search

grpc / grpc-go

The Go language implementation of gRPC. HTTP/2 based RPC
https://grpc.io
Apache License 2.0
20.9k stars 4.34k forks source link

Flaky Test: 1/10k: Test/RetryStats in grpc/test #5881

Open dfawley opened 1 year ago

dfawley commented 1 year ago

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
arvindbr8 commented 1 year ago

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
arvindbr8 commented 1 year ago

flaked again https://github.com/grpc/grpc-go/actions/runs/3852686030/jobs/6565023613

zasweq commented 11 months ago

https://github.com/grpc/grpc-go/actions/runs/6592530881/job/17913339519?pr=6716

arvindbr8 commented 11 months ago

https://github.com/grpc/grpc-go/actions/runs/6632864246/job/18019443106?pr=6746