grpc-go
grpc-go copied to clipboard
Published
2 weeks ago
•
grpc
grpc
Flaky Test: 1/10k: Test/RetryStats in grpc/test
https://github.com/grpc/grpc-go/actions/runs/3735324618/jobs/6338431713
--- FAIL: Test/RetryStats (0.02s)
tlogger.go:116: INFO clientconn.go:105 [core] [Channel #152] Channel created (t=+314.905µs)
tlogger.go:116: INFO clientconn.go:1556 [core] [Channel #152] original dial target is: "127.0.0.1:44421" (t=+473.607µs)
tlogger.go:116: INFO clientconn.go:1561 [core] [Channel #152] dial target "127.0.0.1:44421" parse failed: parse "127.0.0.1:44421": first path segment in URL cannot contain colon (t=+525.808µs)
tlogger.go:116: INFO clientconn.go:1576 [core] [Channel #152] fallback to scheme "passthrough" (t=+559.709µs)
tlogger.go:116: INFO clientconn.go:1584 [core] [Channel #152] parsed dial target is: {Scheme:passthrough Authority: Endpoint:127.0.0.1:44421 URL:{Scheme:passthrough Opaque: User: Host: Path:/127.0.0.1:44421 RawPath: OmitHost:false ForceQuery:false RawQuery: Fragment: RawFragment:}} (t=+622.009µs)
tlogger.go:116: INFO clientconn.go:263 [core] [Channel #152] Channel authority set to "127.0.0.1:44421" (t=+660.61µs)
tlogger.go:116: INFO resolver_conn_wrapper.go:175 [core] [Channel #152] Resolver state updated: {
"Addresses": [
{
"Addr": "127.0.0.1:44421",
"ServerName": "",
"Attributes": null,
"BalancerAttributes": null,
"Type": 0,
"Metadata": null
}
],
"ServiceConfig": null,
"Attributes": null
} (resolver returned new addresses) (t=+760.611µs)
tlogger.go:116: INFO balancer_conn_wrappers.go:274 [core] [Channel #152] Channel switches to new LB policy "pick_first" (t=+852.413µs)
tlogger.go:116: INFO clientconn.go:725 [core] [Channel #152 SubChannel #153] Subchannel created (t=+923.414µs)
tlogger.go:116: INFO clientconn.go:418 [core] [Channel #152] Channel Connectivity change to CONNECTING (t=+988.315µs)
tlogger.go:116: INFO clientconn.go:1106 [core] [Channel #152 SubChannel #153] Subchannel Connectivity change to CONNECTING (t=+1.043316ms)
tlogger.go:116: INFO clientconn.go:1217 [core] [Channel #152 SubChannel #153] Subchannel picks a new address "127.0.0.1:44421" to connect (t=+1.098316ms)
tlogger.go:116: INFO clientconn.go:1106 [core] [Channel #152 SubChannel #153] Subchannel Connectivity change to READY (t=+1.734126ms)
tlogger.go:116: INFO clientconn.go:418 [core] [Channel #152] Channel Connectivity change to READY (t=+1.830627ms)
retry_test.go:569: Handler received frames:
*stats.Begin - &{true 2022-12-19 21:33:53.123973626 +0000 UTC m=+215.367275504 true false false false}
*stats.OutHeader - &{true map[user-agent:[grpc-go/1.53.0-dev]] /grpc.testing.TestService/EmptyCall 127.0.0.1:44421 127.0.0.1:60346}
*stats.OutPayload - &{true [] 0 5 2022-12-19 21:33:53.124837938 +0000 UTC m=+215.368139916}
*stats.End - &{true 2022-12-19 21:33:53.123973626 +0000 UTC m=+215.367275504 2022-12-19 21:33:53.124865639 +0000 UTC m=+215.368167617 map[] rpc error: code = Unavailable desc = stream terminated by RST_STREAM with error code: REFUSED_STREAM}
*stats.Begin - &{true 2022-12-19 21:33:53.124871039 +0000 UTC m=+215.368172917 true false false true}
*stats.OutHeader - &{true map[user-agent:[grpc-go/1.53.0-dev]] /grpc.testing.TestService/EmptyCall 127.0.0.1:44421 127.0.0.1:60346}
*stats.InTrailer - &{true 73 map[content-type:[application/grpc] grpc-retry-pushback-ms:[10]]}
*stats.OutPayload - &{true [] 0 5 2022-12-19 21:33:53.125162043 +0000 UTC m=+215.368463921}
*stats.End - &{true 2022-12-19 21:33:53.124871039 +0000 UTC m=+215.368172917 2022-12-19 21:33:53.125180943 +0000 UTC m=+215.368482821 map[content-type:[application/grpc] grpc-retry-pushback-ms:[10]] rpc error: code = Unavailable desc = unavailable retry}
*stats.Begin - &{true 2022-12-19 21:33:53.135365493 +0000 UTC m=+215.378667471 true false false false}
*stats.OutHeader - &{true map[user-agent:[grpc-go/1.53.0-dev]] /grpc.testing.TestService/EmptyCall 127.0.0.1:44421 127.0.0.1:60346}
*stats.OutPayload - &{true [] 0 5 2022-12-19 21:33:53.135433094 +0000 UTC m=+215.378735072}
*stats.InHeader - &{true 14 map[content-type:[application/grpc]] <nil> <nil>}
*stats.InTrailer - &{true 12 map[]}
*stats.InPayload - &{true [] 0 5 2022-12-19 21:33:53.135780499 +0000 UTC m=+215.379082377}
*stats.End - &{true 2022-12-19 21:33:53.135365493 +0000 UTC m=+215.378667471 2022-12-19 21:33:53.135797499 +0000 UTC m=+215.379099477 map[] <nil>}
---
want:
*stats.Begin - &{false 0001-01-01 00:00:00 +0000 UTC false false false false}
*stats.OutHeader - &{false map[] /grpc.testing.TestService/EmptyCall <nil> <nil>}
*stats.OutPayload - &{false <nil> [] 0 5 0001-01-01 00:00:00 +0000 UTC}
*stats.End - &{false 0001-01-01 00:00:00 +0000 UTC 0001-01-01 00:00:00 +0000 UTC map[] <nil>}
*stats.Begin - &{false 0001-01-01 00:00:00 +0000 UTC false false false true}
*stats.OutHeader - &{false map[] /grpc.testing.TestService/EmptyCall <nil> <nil>}
*stats.OutPayload - &{false <nil> [] 0 5 0001-01-01 00:00:00 +0000 UTC}
*stats.InTrailer - &{false 0 map[content-type:[application/grpc] grpc-retry-pushback-ms:[10]]}
*stats.End - &{false 0001-01-01 00:00:00 +0000 UTC 0001-01-01 00:00:00 +0000 UTC map[] <nil>}
*stats.Begin - &{false 0001-01-01 00:00:00 +0000 UTC false false false false}
*stats.OutHeader - &{false map[] /grpc.testing.TestService/EmptyCall <nil> <nil>}
*stats.OutPayload - &{false <nil> [] 0 5 0001-01-01 00:00:00 +0000 UTC}
*stats.InHeader - &{false 0 map[] <nil> <nil>}
*stats.InPayload - &{false <nil> [] 0 5 0001-01-01 00:00:00 +0000 UTC}
*stats.InTrailer - &{false 0 map[]}
*stats.End - &{false 0001-01-01 00:00:00 +0000 UTC 0001-01-01 00:00:00 +0000 UTC map[] <nil>}
retry_test.go:592: at position 6: got *stats.InTrailer; want *stats.OutPayload
tlogger.go:116: INFO clientconn.go:418 [core] [Channel #152] Channel Connectivity change to SHUTDOWN (t=+14.105907ms)
tlogger.go:116: INFO clientconn.go:1106 [core] [Channel #152 SubChannel #153] Subchannel Connectivity change to SHUTDOWN (t=+15.407626ms)
tlogger.go:116: INFO clientconn.go:1434 [core] [Channel #152 SubChannel #153] Subchannel deleted (t=+15.517028ms)
tlogger.go:116: INFO clientconn.go:1061 [core] [Channel #152] Channel deleted (t=+15.565329ms)
tlogger.go:116: INFO types.go:68 [channelz] attempt to delete child with id 153 from a parent (id=152) that doesn't currently exist (t=+17.273154ms)
tlogger.go:116: INFO types.go:68 [channelz] attempt to delete child with id 153 from a parent (id=152) that doesn't currently exist (t=+17.336455ms)
FAIL
FAIL google.golang.org/grpc/test 227.623s
Failed 1 in 10K runs on forge
logs:
=== RUN Test
=== RUN Test/RetryStats
[third_party/golang/grpc/internal/grpctest/tlogger.go:116](https://cs.corp.google.com/piper///depot/google3/third_party/golang/grpc/internal/grpctest/tlogger.go?l=116&ws=arvindbright/32&snapshot=6): INFO clientconn.go:105 [core] [Channel #1] Channel created (t=+1.006509ms)
[third_party/golang/grpc/internal/grpctest/tlogger.go:116](https://cs.corp.google.com/piper///depot/google3/third_party/golang/grpc/internal/grpctest/tlogger.go?l=116&ws=arvindbright/32&snapshot=6): INFO clientconn.go:1556 [core] [Channel #1] original dial target is: "[::1]:38585" (t=+1.34618ms)
[third_party/golang/grpc/internal/grpctest/tlogger.go:116](https://cs.corp.google.com/piper///depot/google3/third_party/golang/grpc/internal/grpctest/tlogger.go?l=116&ws=arvindbright/32&snapshot=6): INFO clientconn.go:1561 [core] [Channel #1] dial target "[::1]:38585" parse failed: parse "[::1]:38585": first path segment in URL cannot contain colon (t=+1.445229ms)
[third_party/golang/grpc/internal/grpctest/tlogger.go:116](https://cs.corp.google.com/piper///depot/google3/third_party/golang/grpc/internal/grpctest/tlogger.go?l=116&ws=arvindbright/32&snapshot=6): INFO clientconn.go:1576 [core] [Channel #1] fallback to scheme "passthrough" (t=+1.5021ms)
[third_party/golang/grpc/internal/grpctest/tlogger.go:116](https://cs.corp.google.com/piper///depot/google3/third_party/golang/grpc/internal/grpctest/tlogger.go?l=116&ws=arvindbright/32&snapshot=6): INFO clientconn.go:1584 [core] [Channel #1] parsed dial target is: {Scheme:passthrough Authority: Endpoint:[::1]:38585 URL:{Scheme:passthrough Opaque: User: Host: Path:/[::1]:38585 RawPath:/[::1]:38585 OmitHost:false ForceQuery:false RawQuery: Fragment: RawFragment:}} (t=+1.616489ms)
[third_party/golang/grpc/internal/grpctest/tlogger.go:116](https://cs.corp.google.com/piper///depot/google3/third_party/golang/grpc/internal/grpctest/tlogger.go?l=116&ws=arvindbright/32&snapshot=6): INFO clientconn.go:263 [core] [Channel #1] Channel authority set to "[::1]:38585" (t=+1.68262ms)
[third_party/golang/grpc/internal/grpctest/tlogger.go:116](https://cs.corp.google.com/piper///depot/google3/third_party/golang/grpc/internal/grpctest/tlogger.go?l=116&ws=arvindbright/32&snapshot=6): INFO resolver_conn_wrapper.go:175 [core] [Channel #1] Resolver state updated: {
"Addresses": [
{
"Addr": "[::1]:38585",
"ServerName": "",
"Attributes": null,
"BalancerAttributes": null,
"Type": 0,
"Metadata": null
}
],
"ServiceConfig": null,
"Attributes": null
} (resolver returned new addresses) (t=+2.201899ms)
[third_party/golang/grpc/internal/grpctest/tlogger.go:116](https://cs.corp.google.com/piper///depot/google3/third_party/golang/grpc/internal/grpctest/tlogger.go?l=116&ws=arvindbright/32&snapshot=6): INFO balancer_conn_wrappers.go:274 [core] [Channel #1] Channel switches to new LB policy "pick_first" (t=+2.345869ms)
[third_party/golang/grpc/internal/grpctest/tlogger.go:116](https://cs.corp.google.com/piper///depot/google3/third_party/golang/grpc/internal/grpctest/tlogger.go?l=116&ws=arvindbright/32&snapshot=6): INFO clientconn.go:725 [core] [Channel #1 SubChannel #2] Subchannel created (t=+2.478969ms)
[third_party/golang/grpc/internal/grpctest/tlogger.go:116](https://cs.corp.google.com/piper///depot/google3/third_party/golang/grpc/internal/grpctest/tlogger.go?l=116&ws=arvindbright/32&snapshot=6): INFO clientconn.go:418 [core] [Channel #1] Channel Connectivity change to CONNECTING (t=+2.578899ms)
[third_party/golang/grpc/internal/grpctest/tlogger.go:116](https://cs.corp.google.com/piper///depot/google3/third_party/golang/grpc/internal/grpctest/tlogger.go?l=116&ws=arvindbright/32&snapshot=6): INFO clientconn.go:1106 [core] [Channel #1 SubChannel #2] Subchannel Connectivity change to CONNECTING (t=+2.810739ms)
[third_party/golang/grpc/internal/grpctest/tlogger.go:116](https://cs.corp.google.com/piper///depot/google3/third_party/golang/grpc/internal/grpctest/tlogger.go?l=116&ws=arvindbright/32&snapshot=6): INFO clientconn.go:1217 [core] [Channel #1 SubChannel #2] Subchannel picks a new address "[::1]:38585" to connect (t=+2.873619ms)
[third_party/golang/grpc/internal/grpctest/tlogger.go:116](https://cs.corp.google.com/piper///depot/google3/third_party/golang/grpc/internal/grpctest/tlogger.go?l=116&ws=arvindbright/32&snapshot=6): INFO pickfirst.go:114 [core] pickfirstBalancer: UpdateSubConnState: 0xc000012af8, {CONNECTING <nil>} (t=+3.015959ms)
[third_party/golang/grpc/internal/grpctest/tlogger.go:116](https://cs.corp.google.com/piper///depot/google3/third_party/golang/grpc/internal/grpctest/tlogger.go?l=116&ws=arvindbright/32&snapshot=6): INFO clientconn.go:1106 [core] [Channel #1 SubChannel #2] Subchannel Connectivity change to READY (t=+3.722559ms)
[third_party/golang/grpc/internal/grpctest/tlogger.go:116](https://cs.corp.google.com/piper///depot/google3/third_party/golang/grpc/internal/grpctest/tlogger.go?l=116&ws=arvindbright/32&snapshot=6): INFO pickfirst.go:114 [core] pickfirstBalancer: UpdateSubConnState: 0xc000012af8, {READY <nil>} (t=+3.811539ms)
[third_party/golang/grpc/internal/grpctest/tlogger.go:116](https://cs.corp.google.com/piper///depot/google3/third_party/golang/grpc/internal/grpctest/tlogger.go?l=116&ws=arvindbright/32&snapshot=6): INFO clientconn.go:418 [core] [Channel #1] Channel Connectivity change to READY (t=+3.883469ms)
[third_party/golang/grpc/test/retry_test.go:569](https://cs.corp.google.com/piper///depot/google3/third_party/golang/grpc/test/retry_test.go?l=569&ws=arvindbright/32&snapshot=6): Handler received frames:
*stats.Begin - &{true 2023-01-04 07:45:05.347530658 -0800 PST m=+0.146722730 true false false false}
*stats.OutHeader - &{true map[user-agent:[grpc-[go/1.52.0-dev](http://goto.google.com/1.52.0-dev)]] /grpc.testing.TestService/EmptyCall [::1]:38585 [::1]:53554}
*stats.OutPayload - &{true [] 0 5 2023-01-04 07:45:05.350147238 -0800 PST m=+0.149339350}
*stats.End - &{true 2023-01-04 07:45:05.347530658 -0800 PST m=+0.146722730 2023-01-04 07:45:05.350502667 -0800 PST m=+0.149694729 map[] rpc error: code = Unavailable desc = stream terminated by RST_STREAM with error code: REFUSED_STREAM}
*stats.Begin - &{true 2023-01-04 07:45:05.350508707 -0800 PST m=+0.149700969 true false false true}
*stats.OutHeader - &{true map[user-agent:[grpc-[go/1.52.0-dev](http://goto.google.com/1.52.0-dev)]] /grpc.testing.TestService/EmptyCall [::1]:38585 [::1]:53554}
*stats.OutPayload - &{true [] 0 5 2023-01-04 07:45:05.350549947 -0800 PST m=+0.149742009}
*stats.InTrailer - &{true 73 map[content-type:[application/grpc] grpc-retry-pushback-ms:[10]]}
*stats.End - &{true 2023-01-04 07:45:05.350508707 -0800 PST m=+0.149700969 2023-01-04 07:45:05.352114217 -0800 PST m=+0.151306319 map[content-type:[application/grpc] grpc-retry-pushback-ms:[10]] rpc error: code = Unavailable desc = unavailable retry}
*stats.Begin - &{true 2023-01-04 07:45:05.410671665 -0800 PST m=+0.209863737 true false false false}
*stats.OutHeader - &{true map[user-agent:[grpc-[go/1.52.0-dev](http://goto.google.com/1.52.0-dev)]] /grpc.testing.TestService/EmptyCall [::1]:38585 [::1]:53554}
*stats.OutPayload - &{true [] 0 5 2023-01-04 07:45:05.410783285 -0800 PST m=+0.209975407}
*stats.InHeader - &{true 14 map[content-type:[application/grpc]] <nil> <nil>}
*stats.InTrailer - &{true 12 map[]}
*stats.InPayload - &{true [] 0 5 2023-01-04 07:45:05.411262095 -0800 PST m=+0.210454187}
*stats.End - &{true 2023-01-04 07:45:05.410671665 -0800 PST m=+0.209863737 2023-01-04 07:45:05.411289305 -0800 PST m=+0.210481396 map[] <nil>}
---
want:
*stats.Begin - &{false 0001-01-01 00:00:00 +0000 UTC false false false false}
*stats.OutHeader - &{false map[] /grpc.testing.TestService/EmptyCall <nil> <nil>}
*stats.OutPayload - &{false <nil> [] 0 5 0001-01-01 00:00:00 +0000 UTC}
*stats.End - &{false 0001-01-01 00:00:00 +0000 UTC 0001-01-01 00:00:00 +0000 UTC map[] <nil>}
*stats.Begin - &{false 0001-01-01 00:00:00 +0000 UTC false false false true}
*stats.OutHeader - &{false map[] /grpc.testing.TestService/EmptyCall <nil> <nil>}
*stats.OutPayload - &{false <nil> [] 0 5 0001-01-01 00:00:00 +0000 UTC}
*stats.InTrailer - &{false 0 map[content-type:[application/grpc] grpc-retry-pushback-ms:[10]]}
*stats.End - &{false 0001-01-01 00:00:00 +0000 UTC 0001-01-01 00:00:00 +0000 UTC map[] <nil>}
*stats.Begin - &{false 0001-01-01 00:00:00 +0000 UTC false false false false}
*stats.OutHeader - &{false map[] /grpc.testing.TestService/EmptyCall <nil> <nil>}
*stats.OutPayload - &{false <nil> [] 0 5 0001-01-01 00:00:00 +0000 UTC}
*stats.InHeader - &{false 0 map[] <nil> <nil>}
*stats.InPayload - &{false <nil> [] 0 5 0001-01-01 00:00:00 +0000 UTC}
*stats.InTrailer - &{false 0 map[]}
*stats.End - &{false 0001-01-01 00:00:00 +0000 UTC 0001-01-01 00:00:00 +0000 UTC map[] <nil>}
[third_party/golang/grpc/test/retry_test.go:625](https://cs.corp.google.com/piper///depot/google3/third_party/golang/grpc/test/retry_test.go?l=625&ws=arvindbright/32&snapshot=6): pushback time before final attempt = 58.557418ms; want ~10ms
[third_party/golang/grpc/internal/grpctest/tlogger.go:116](https://cs.corp.google.com/piper///depot/google3/third_party/golang/grpc/internal/grpctest/tlogger.go?l=116&ws=arvindbright/32&snapshot=6): INFO clientconn.go:418 [core] [Channel #1] Channel Connectivity change to SHUTDOWN (t=+68.872215ms)
[third_party/golang/grpc/internal/grpctest/tlogger.go:116](https://cs.corp.google.com/piper///depot/google3/third_party/golang/grpc/internal/grpctest/tlogger.go?l=116&ws=arvindbright/32&snapshot=6): INFO clientconn.go:1106 [core] [Channel #1 SubChannel #2] Subchannel Connectivity change to SHUTDOWN (t=+69.043425ms)
[third_party/golang/grpc/internal/grpctest/tlogger.go:116](https://cs.corp.google.com/piper///depot/google3/third_party/golang/grpc/internal/grpctest/tlogger.go?l=116&ws=arvindbright/32&snapshot=6): INFO clientconn.go:1434 [core] [Channel #1 SubChannel #2] Subchannel deleted (t=+69.179155ms)
[third_party/golang/grpc/internal/grpctest/tlogger.go:116](https://cs.corp.google.com/piper///depot/google3/third_party/golang/grpc/internal/grpctest/tlogger.go?l=116&ws=arvindbright/32&snapshot=6): INFO clientconn.go:1061 [core] [Channel #1] Channel deleted (t=+69.276945ms)
[third_party/golang/grpc/internal/grpctest/tlogger.go:116](https://cs.corp.google.com/piper///depot/google3/third_party/golang/grpc/internal/grpctest/tlogger.go?l=116&ws=arvindbright/32&snapshot=6): INFO http2_client.go:452 [transport] transport: loopyWriter exited. Closing connection. Err: transport closed by client (t=+76.572913ms)
[third_party/golang/grpc/internal/grpctest/tlogger.go:116](https://cs.corp.google.com/piper///depot/google3/third_party/golang/grpc/internal/grpctest/tlogger.go?l=116&ws=arvindbright/32&snapshot=6): INFO http2_client.go:956 [transport] transport: closing: connection error: desc = "error reading from server: read tcp [::1]:53554->[::1]:38585: use of closed network connection" (t=+77.749073ms)
[third_party/golang/grpc/internal/grpctest/tlogger.go:116](https://cs.corp.google.com/piper///depot/google3/third_party/golang/grpc/internal/grpctest/tlogger.go?l=116&ws=arvindbright/32&snapshot=6): INFO types.go:68 [channelz] attempt to delete child with id 2 from a parent (id=1) that doesn't currently exist (t=+77.877023ms)
[third_party/golang/grpc/internal/grpctest/tlogger.go:116](https://cs.corp.google.com/piper///depot/google3/third_party/golang/grpc/internal/grpctest/tlogger.go?l=116&ws=arvindbright/32&snapshot=6): INFO types.go:68 [channelz] attempt to delete child with id 2 from a parent (id=1) that doesn't currently exist (t=+77.965623ms)
--- FAIL: Test (0.17s)
--- FAIL: Test/RetryStats (0.13s)
FAIL
exit status 1
flaked again https://github.com/grpc/grpc-go/actions/runs/3852686030/jobs/6565023613
https://github.com/grpc/grpc-go/actions/runs/6592530881/job/17913339519?pr=6716
https://github.com/grpc/grpc-go/actions/runs/6632864246/job/18019443106?pr=6746