Flaky test: TimerAndWatchStateOnSendCallback

easwars commented 1 year ago

--- FAIL: Test (5.52s)
    --- FAIL: Test/TimerAndWatchStateOnSendCallback (5.00s)
        tlogger.go:116: INFO server.go:113 [xds-e2e] Created new snapshot cache...  (t=+26.4µs)
        tlogger.go:116: INFO server.go:632 [core] [Server #43] Server created  (t=+242.902µs)
        tlogger.go:116: INFO server.go:139 [xds-e2e] Registered Aggregated Discovery Service (ADS)...  (t=+270.403µs)
        tlogger.go:116: INFO server.go:143 [xds-e2e] xDS management server serving at: 127.0.0.1:39785...  (t=+288.103µs)
        tlogger.go:116: INFO clientconn.go:105 [core] [Channel #44] Channel created  (t=+326.403µs)
        tlogger.go:116: INFO clientconn.go:1565 [core] [Channel #44] original dial target is: "127.0.0.1:39785"  (t=+340.004µs)
        tlogger.go:116: INFO clientconn.go:1570 [core] [Channel #44] dial target "127.0.0.1:39785" parse failed: parse "127.0.0.1:39785": first path segment in URL cannot contain colon  (t=+358.404µs)
        tlogger.go:116: INFO clientconn.go:1585 [core] [Channel #44] fallback to scheme "passthrough"  (t=+371.504µs)
        tlogger.go:116: INFO clientconn.go:1593 [core] [Channel #44] parsed dial target is: {Scheme:passthrough Authority: URL:{Scheme:passthrough Opaque: User: Host: Path:/127.0.0.1:39785 RawPath: ForceQuery:false RawQuery: Fragment: RawFragment:}}  (t=+396.304µs)
        tlogger.go:116: INFO clientconn.go:273 [core] [Channel #44] Channel authority set to "127.0.0.1:39785"  (t=+415.704µs)
        tlogger.go:116: INFO resolver_conn_wrapper.go:175 [core] [Channel #44] Resolver state updated: {
              "Addresses": [
                {
                  "Addr": "127.0.0.1:39785",
                  "ServerName": "",
                  "Attributes": null,
                  "BalancerAttributes": null,
                  "Type": 0,
                  "Metadata": null
                }
              ],
              "ServiceConfig": null,
              "Attributes": null
            } (resolver returned new addresses)  (t=+445.805µs)
        tlogger.go:116: INFO balancer_conn_wrappers.go:274 [core] [Channel #44] Channel switches to new LB policy "pick_first"  (t=+475.605µs)
        tlogger.go:116: INFO clientconn.go:735 [core] [Channel #44 SubChannel #45] Subchannel created  (t=+491.805µs)
        tlogger.go:116: INFO clientconn.go:428 [core] [Channel #44] Channel Connectivity change to CONNECTING  (t=+514.706µs)
        tlogger.go:116: INFO transport.go:238 Created transport to server "127.0.0.1:39785"  (t=+530.506µs)
        tlogger.go:116: INFO server.go:820 [core] [Server #43 ListenSocket #46] ListenSocket created  (t=+586.906µs)
        tlogger.go:116: INFO clientconn.go:1116 [core] [Channel #44 SubChannel #45] Subchannel Connectivity change to CONNECTING  (t=+616.207µs)
        tlogger.go:116: INFO clientconn.go:1227 [core] [Channel #44 SubChannel #45] Subchannel picks a new address "127.0.0.1:39785" to connect  (t=+628.507µs)
        tlogger.go:116: INFO clientconn.go:1116 [core] [Channel #44 SubChannel #45] Subchannel Connectivity change to READY  (t=+1.354015ms)
        tlogger.go:116: INFO clientconn.go:428 [core] [Channel #44] Channel Connectivity change to READY  (t=+1.376116ms)
        tlogger.go:116: INFO transport.go:345 ADS stream created  (t=+1.508[217](https://github.com/grpc/grpc-go/actions/runs/4316641977/jobs/7532681830#step:8:218)ms)
        tlogger.go:116: INFO simple.go:374 [xds-e2e] open watch 1 for type.googleapis.com/envoy.config.listener.v3.Listener[xdsclient-test-lds-resource] from nodeID "55028a4a-d931-40e0-948a-e5b526dc3616", version ""  (t=+1.859521ms)
        tlogger.go:116: INFO server.go:193 [xds-e2e] Created new resource snapshot...  (t=+1.958522ms)
        tlogger.go:116: INFO simple.go:234 [xds-e2e] respond open watch 1 type.googleapis.com/envoy.config.listener.v3.Listener[xdsclient-test-lds-resource] with new version "1"  (t=+1.975823ms)
        tlogger.go:116: INFO simple.go:421 [xds-e2e] respond type.googleapis.com/envoy.config.listener.v3.Listener[xdsclient-test-lds-resource] version "" with version "1"  (t=+1.990423ms)
        tlogger.go:116: INFO server.go:199 [xds-e2e] Updated snapshot cache with resource snapshot...  (t=+2.009823ms)
        tlogger.go:116: INFO simple.go:354 [xds-e2e] nodeID "55028a4a-d931-40e0-948a-e5b526dc3616" requested type.googleapis.com/envoy.config.listener.v3.Listener[xdsclient-test-lds-resource] and known map[xdsclient-test-lds-resource:{}]. Diff []  (t=+2.257426ms)
        tlogger.go:116: INFO simple.go:374 [xds-e2e] open watch 2 for type.googleapis.com/envoy.config.listener.v3.Listener[xdsclient-test-lds-resource] from nodeID "55028a4a-d931-40e0-948a-e5b526dc3616", version "1"  (t=+2.276926ms)
        authority_test.go:157: Test timed out before watcher received an update from server.
        tlogger.go:116: WARNING authority.go:375 Watchers not notified since ADS stream failed after having received at least one response: rpc error: code = Canceled desc = context canceled  (t=+5.000347085s)
        tlogger.go:116: WARNING transport.go:471 ADS stream closed: rpc error: code = Canceled desc = context canceled  (t=+5.000381785s)
        tlogger.go:116: INFO clientconn.go:428 [core] [Channel #44] Channel Connectivity change to SHUTDOWN  (t=+5.000421086s)
        tlogger.go:116: INFO clientconn.go:1116 [core] [Channel #44 SubChannel #45] Subchannel Connectivity change to SHUTDOWN  (t=+5.000464686s)
        tlogger.go:116: WARNING transport.go:412 Sending ADS request for resources: [], url: "type.googleapis.com/envoy.config.listener.v3.Listener", version: "1", nonce: "1" failed: EOF  (t=+5.000493886s)
        tlogger.go:116: INFO clientconn.go:1440 [core] [Channel #44 SubChannel #45] Subchannel deleted  (t=+5.0005[230](https://github.com/grpc/grpc-go/actions/runs/4316641977/jobs/7532681830#step:8:231)87s)
        tlogger.go:116: INFO clientconn.go:1071 [core] [Channel #44] Channel deleted  (t=+5.000553587s)
        tlogger.go:116: INFO server.go:771 [core] [Server #43 ListenSocket #46] ListenSocket deleted  (t=+5.000614988s)
FAIL
FAIL    google.golang.org/grpc/xds/internal/xdsclient   6.289s

https://github.com/grpc/grpc-go/actions/runs/4316641977/jobs/7532681830

easwars commented 1 year ago

Looks like the test can also timeout. https://github.com/grpc/grpc-go/actions/runs/4324090128/jobs/7548480827