search

grpc / grpc-go

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

Flaky test: Transport_RetriesAfterBrokenStream #5896

Open easwars opened 1 year ago

easwars commented 1 year ago 
--- FAIL: Test (6.45s)
    --- FAIL: Test/Transport_RetriesAfterBrokenStream (5.00s)
        tlogger.go:116: INFO server.go:113 [xds-e2e] Created new snapshot cache...  (t=+318.32µs)
        tlogger.go:116: INFO server.go:631 [core] [Server #155] Server created  (t=+417.926µs)
        tlogger.go:116: INFO server.go:139 [xds-e2e] Registered Aggregated Discovery Service (ADS)...  (t=+471.73µs)
        tlogger.go:116: INFO server.go:143 [xds-e2e] xDS management server serving at: 127.0.0.1:34819...  (t=+516.332µs)
        transport_backoff_test.go:234: Started xDS management server on 127.0.0.1:34819
        tlogger.go:116: INFO server.go:819 [core] [Server #155 ListenSocket #156] ListenSocket created  (t=+786.749µs)
        tlogger.go:116: INFO server.go:193 [xds-e2e] Created new resource snapshot...  (t=+885.755µs)
        tlogger.go:116: INFO server.go:199 [xds-e2e] Updated snapshot cache with resource snapshot...  (t=+924.058µs)
        tlogger.go:116: INFO clientconn.go:105 [core] [Channel #157] Channel created  (t=+982.961µs)
        tlogger.go:116: INFO clientconn.go:1556 [core] [Channel #157] original dial target is: "127.0.0.1:34819"  (t=+1.020864ms)
        tlogger.go:116: INFO clientconn.go:1561 [core] [Channel #157] dial target "127.0.0.1:34819" parse failed: parse "127.0.0.1:34819": first path segment in URL cannot contain colon  (t=+1.067967ms)
        tlogger.go:116: INFO clientconn.go:1576 [core] [Channel #157] fallback to scheme "passthrough"  (t=+1.111869ms)
        tlogger.go:116: INFO clientconn.go:1584 [core] [Channel #157] parsed dial target is: {Scheme:passthrough Authority: Endpoint:127.0.0.1:34819 URL:{Scheme:passthrough Opaque: User: Host: Path:/127.0.0.1:34819 RawPath: OmitHost:false ForceQuery:false RawQuery: Fragment: RawFragment:}}  (t=+1.170373ms)
        tlogger.go:116: INFO clientconn.go:263 [core] [Channel #157] Channel authority set to "127.0.0.1:34819"  (t=+1.202375ms)
        tlogger.go:116: INFO resolver_conn_wrapper.go:175 [core] [Channel #157] Resolver state updated: {
              "Addresses": [
                {
                  "Addr": "127.0.0.1:34819",
                  "ServerName": "",
                  "Attributes": null,
                  "BalancerAttributes": null,
                  "Type": 0,
                  "Metadata": null
                }
              ],
              "ServiceConfig": null,
              "Attributes": null
            } (resolver returned new addresses)  (t=+1.377986ms)
        tlogger.go:116: INFO balancer_conn_wrappers.go:274 [core] [Channel #157] Channel switches to new LB policy "pick_first"  (t=+1.492693ms)
        tlogger.go:116: INFO clientconn.go:725 [core] [Channel #157 SubChannel #158] Subchannel created  (t=+1.6088ms)
        tlogger.go:116: INFO clientconn.go:418 [core] [Channel #157] Channel Connectivity change to CONNECTING  (t=+1.657203ms)
        tlogger.go:116: INFO clientconn.go:1106 [core] [Channel #157 SubChannel #158] Subchannel Connectivity change to CONNECTING  (t=+1.711507ms)
        tlogger.go:116: INFO clientconn.go:1217 [core] [Channel #157 SubChannel #158] Subchannel picks a new address "127.0.0.1:34819" to connect  (t=+1.77121ms)
        tlogger.go:116: INFO clientconn.go:1106 [core] [Channel #157 SubChannel #158] Subchannel Connectivity change to READY  (t=+2.664166ms)
        tlogger.go:116: INFO clientconn.go:418 [core] [Channel #157] Channel Connectivity change to READY  (t=+2.73577ms)
        tlogger.go:116: INFO transport.go:217 Created transport to server "127.0.0.1:34819"  (t=+2.881279ms)
        tlogger.go:116: INFO transport.go:316 ADS stream created  (t=+3.457315ms)
        tlogger.go:116: INFO simple.go:354 [xds-e2e] nodeID "7fefd658-d817-4375-98f2-6b0c20774abb" requested type.googleapis.com/envoy.config.listener.v3.Listener[resource name 1 resource name 2] and known map[]. Diff [resource name 1 resource name 2]  (t=+3.999949ms)
        tlogger.go:116: INFO simple.go:421 [xds-e2e] respond type.googleapis.com/envoy.config.listener.v3.Listener[resource name 1 resource name 2] version "" with version "1"  (t=+4.058152ms)
        tlogger.go:116: INFO transport.go:281 ADS response received, type: type.googleapis.com/envoy.config.listener.v3.Listener  (t=+4.431675ms)
        tlogger.go:116: INFO transport.go:469 Sending ACK for resource type: type.googleapis.com/envoy.config.listener.v3.Listener, version: 1, nonce: 1  (t=+5.451039ms)
        tlogger.go:116: INFO simple.go:354 [xds-e2e] nodeID "7fefd658-d817-4375-98f2-6b0c20774abb" requested type.googleapis.com/envoy.config.listener.v3.Listener[resource name 2 resource name 1] and known map[resource name 1:{} resource name 2:{}]. Diff []  (t=+7.705679ms)
        tlogger.go:116: INFO simple.go:374 [xds-e2e] open watch 1 for type.googleapis.com/envoy.config.listener.v3.Listener[resource name 2 resource name 1] from nodeID "7fefd658-d817-4375-98f2-6b0c20774abb", version "1"  (t=+7.778083ms)
        transport_backoff_test.go:334: Timeout waiting for the discovery request ACK on the stream
        tlogger.go:116: WARNING transport.go:433 ADS stream is closed with error: failed to read ADS response: rpc error: code = Canceled desc = context canceled  (t=+5.001414443s)
        tlogger.go:116: INFO clientconn.go:418 [core] [Channel #157] Channel Connectivity change to SHUTDOWN  (t=+5.00153115s)
        tlogger.go:116: INFO clientconn.go:1106 [core] [Channel #157 SubChannel #158] Subchannel Connectivity change to SHUTDOWN  (t=+5.001655858s)
        tlogger.go:116: INFO clientconn.go:1434 [core] [Channel #157 SubChannel #158] Subchannel deleted  (t=+5.001778[266](https://github.com/grpc/grpc-go/actions/runs/3744800183/jobs/6358567003#step:8:267)s)
        tlogger.go:116: INFO clientconn.go:1061 [core] [Channel #157] Channel deleted  (t=+5.00184127s)
        tlogger.go:116: INFO server.go:770 [core] [Server #155 ListenSocket #156] ListenSocket deleted  (t=+5.002020681s)
FAIL
FAIL    google.golang.org/grpc/xds/internal/xdsclient/transport 8.326s
arvindbr8 commented 1 year ago

Ran the test 4x 10K times and doesnt flake. Seems to be flaking more in github than in forge.

easwars commented 1 year ago

https://github.com/grpc/grpc-go/actions/runs/4379004388/jobs/7664752692

easwars commented 1 year ago

https://github.com/grpc/grpc-go/actions/runs/6201261029/job/16837607045?pr=6635

easwars commented 2 months ago

https://github.com/grpc/grpc-go/actions/runs/9769128208/job/26968005130?pr=7378