Flaky test: Test/RingHash_IdleToReady

[purnesh42H]

https://github.com/grpc/grpc-go/actions/runs/11569197131/job/32202453928?pr=7789

[purnesh42H]

--- FAIL: Test (13.19s)
    --- FAIL: Test/RingHash_IdleToReady (0.02s)
        tlogger.go:116: INFO server.go:684 [core] [Server #587]Server created  (t=+340.659µs)
        stubserver.go:288: Started test service backend at "127.0.0.1:38299"
        ringhash_balancer_test.go:1362: Created new snapshot cache...
        tlogger.go:116: INFO server.go:880 [core] [Server #587 ListenSocket #588]ListenSocket created  (t=+989.035µs)
        tlogger.go:116: INFO server.go:684 [core] [Server #589]Server created  (t=+1.325547ms)
        ringhash_balancer_test.go:1362: Registered Aggregated Discovery Service (ADS)...
        ringhash_balancer_test.go:1362: xDS management server serving at: 127.0.0.1:46377...
        tlogger.go:116: INFO server.go:880 [core] [Server #589 ListenSocket #590]ListenSocket created  (t=+2.280227ms)
        server.go:229: Created new resource snapshot...
        server.go:235: Updated snapshot cache with resource snapshot...
        tlogger.go:116: INFO clientconn.go:1654 [core] original dial target is: "xds:///test.server"  (t=+3.770453ms)
        tlogger.go:116: INFO clientconn.go:314 [core] [Channel #591]Channel created  (t=+3.830846ms)
        tlogger.go:116: INFO clientconn.go:193 [core] [Channel #591]parsed dial target is: resolver.Target{URL:url.URL{Scheme:"xds", Opaque:"", User:(*url.Userinfo)(nil), Host:"", Path:"/test.server", RawPath:"", OmitHost:false, ForceQuery:false, RawQuery:"", Fragment:"", RawFragment:""}}  (t=+3.908973ms)
        tlogger.go:116: INFO clientconn.go:194 [core] [Channel #591]Channel authority set to "test.server"  (t=+3.958666ms)
        tlogger.go:116: INFO xds_resolver.go:100 [xds] [xds-resolver 0xc000c3e120] Creating resolver for target: xds:///test.server  (t=+4.073632ms)
        tlogger.go:116: INFO client_refcounted.go:84 [xds] [xds-client 0xc000d942a0] Created client with name "xds:///test.server" and bootstrap configuration:
             {
              "xds_servers": [
               {
                "server_uri": "passthrough:///127.0.0.1:46377",
                "channel_creds": [
                 {
                  "type": "insecure"
                 }
                ]
               }
              ],
              "certificate_providers": {
               "client-side-certificate-provider-instance": {
                "plugin_name": "file_watcher",
                "config": {
                 "certificate_file": "/tmp/testClientSideXDS3785984441/cert.pem",
                 "private_key_file": "/tmp/testClientSideXDS3785984441/key.pem",
                 "ca_certificate_file": "/tmp/testClientSideXDS3785984441/ca.pem",
                 "refresh_interval": "600s"
                }
               },
               "server-side-certificate-provider-instance": {
                "plugin_name": "file_watcher",
                "config": {
                 "certificate_file": "/tmp/testServerSideXDS857184589/cert.pem",
                 "private_key_file": "/tmp/testServerSideXDS857184589/key.pem",
                 "ca_certificate_file": "/tmp/testServerSideXDS857184589/ca.pem",
                 "refresh_interval": "600s"
                }
               }
              },
              "server_listener_resource_name_template": "grpc/server?xds.resource.listening_address=%s",
              "client_default_listener_resource_name_template": "%s",
              "node": {
               "id": "8df6bf1b-88c4-4b1a-9f3e-8b1c876595bc",
               "locality": {}
              }
             }  (t=+4.939476ms)
        tlogger.go:116: INFO client_refcounted.go:89 [xds] xDS node ID: 8df6bf1b-88c4-4b1a-9f3e-8b1c876595bc  (t=+5.019236ms)
        tlogger.go:116: INFO clientconn.go:1654 [core] original dial target is: "passthrough:///127.0.0.1:46377"  (t=+5.098935ms)
        tlogger.go:116: INFO clientconn.go:314 [core] [Channel #592]Channel created  (t=+5.152967ms)
        tlogger.go:116: INFO clientconn.go:193 [core] [Channel #592]parsed dial target is: resolver.Target{URL:url.URL{Scheme:"passthrough", Opaque:"", User:(*url.Userinfo)(nil), Host:"", Path:"/127.0.0.1:46377", RawPath:"", OmitHost:false, ForceQuery:false, RawQuery:"", Fragment:"", RawFragment:""}}  (t=+5.227977ms)
        tlogger.go:116: INFO clientconn.go:194 [core] [Channel #592]Channel authority set to "127.0.0.1:46377"  (t=+5.27207ms)
        tlogger.go:116: INFO resolver_wrapper.go:200 [core] [Channel #592]Resolver state updated: {
              "Addresses": [
                {
                  "Addr": "127.0.0.1:46377",
                  "ServerName": "",
                  "Attributes": null,
                  "BalancerAttributes": null,
                  "Metadata": null
                }
              ],
              "Endpoints": [
                {
                  "Addresses": [
                    {
                      "Addr": "127.0.0.1:46377",
                      "ServerName": "",
                      "Attributes": null,
                      "BalancerAttributes": null,
                      "Metadata": null
                    }
                  ],
                  "Attributes": null
                }
              ],
              "ServiceConfig": null,
              "Attributes": null
            } (resolver returned new addresses)  (t=+5.499747ms)
        tlogger.go:116: INFO balancer_wrapper.go:109 [core] [Channel #592]Channel switches to new LB policy "pick_first"  (t=+5.621425ms)
        tlogger.go:116: INFO clientconn.go:544 [core] [Channel #592]Channel Connectivity change to CONNECTING  (t=+5.720431ms)
        tlogger.go:116: INFO clientconn.go:838 [core] [Channel #592 SubChannel #593]Subchannel created  (t=+5.803647ms)
        tlogger.go:116: INFO clientconn.go:314 [core] [Channel #592]Channel exiting idle mode  (t=+5.904296ms)
        tlogger.go:116: INFO transport.go:243 [xds] [xds-client 0xc000d942a0] [passthrough:///127.0.0.1:46377] Created transport to server "passthrough:///127.0.0.1:46377"  (t=+5.980719ms)
        tlogger.go:116: INFO clientconn.go:314 [core] [Channel #591]Channel exiting idle mode  (t=+6.051422ms)
        tlogger.go:116: INFO clientconn.go:1199 [core] [Channel #592 SubChannel #593]Subchannel Connectivity change to CONNECTING  (t=+6.106886ms)
        tlogger.go:116: INFO clientconn.go:1319 [core] [Channel #592 SubChannel #593]Subchannel picks a new address "127.0.0.1:46377" to connect  (t=+6.191465ms)
        tlogger.go:116: INFO clientconn.go:1199 [core] [Channel #592 SubChannel #593]Subchannel Connectivity change to READY  (t=+6.76473ms)
        tlogger.go:116: INFO clientconn.go:544 [core] [Channel #592]Channel Connectivity change to READY  (t=+6.851804ms)
        tlogger.go:116: INFO transport.go:339 [xds] [xds-client 0xc000d942a0] [passthrough:///127.0.0.1:46377] ADS stream created  (t=+6.942734ms)
        logging.go:30: nodeID "8df6bf1b-88c4-4b1a-9f3e-8b1c876595bc" requested type.googleapis.com/envoy.config.listener.v3.Listener[test.server] and known map[]. Diff [test.server]
        logging.go:30: respond type.googleapis.com/envoy.config.listener.v3.Listener[test.server] version "" with version "1"
        logging.go:30: nodeID "8df6bf1b-88c4-4b1a-9f3e-8b1c876595bc" requested type.googleapis.com/envoy.config.listener.v3.Listener[test.server] and known map[test.server:{}]. Diff []
        logging.go:30: open watch 1 for type.googleapis.com/envoy.config.listener.v3.Listener[test.server] from nodeID "8df6bf1b-88c4-4b1a-9f3e-8b1c876595bc", version "1"
        logging.go:30: nodeID "8df6bf1b-88c4-4b1a-9f3e-8b1c876595bc" requested type.googleapis.com/envoy.config.route.v3.RouteConfiguration[new_route] and known map[]. Diff [new_route]
        logging.go:30: respond type.googleapis.com/envoy.config.route.v3.RouteConfiguration[new_route] version "" with version "1"
        tlogger.go:116: INFO xds_resolver.go:284 [xds] [xds-resolver 0xc000c3e120] For Listener resource "test.server" and RouteConfiguration resource "new_route", generated service config: {
              "loadBalancingConfig": [
                {
                  "xds_cluster_manager_experimental": {
                    "children": {
                      "cluster:cluster": {
                        "childPolicy": [
                          {
                            "cds_experimental": {
                              "cluster": "cluster"
                            }
                          }
                        ]
                      }
                    }
                  }
                }
              ]
            }  (t=+9.124267ms)
        tlogger.go:116: INFO resolver_wrapper.go:200 [core] [Channel #591]Resolver state updated: {
              "Addresses": null,
              "Endpoints": [],
              "ServiceConfig": {
                "Config": {
                  "Config": null,
                  "Methods": {}
                },
                "Err": null
              },
              "Attributes": {
                "\u003c%!p(xdsclient.clientKeyType=grpc.xds.internal.client.Client)\u003e": "\u003c0xc000fb6780\u003e",
                "\u003c%!p(resolver.csKeyType=grpc.internal.resolver.configSelector)\u003e": "\u003c0xc00071a780\u003e"
              }
            } (service config updated)  (t=+9.494912ms)
        tlogger.go:116: INFO balancer_wrapper.go:109 [core] [Channel #591]Channel switches to new LB policy "xds_cluster_manager_experimental"  (t=+9.580603ms)
        tlogger.go:116: INFO clustermanager.go:59 [xds] [xds-cluster-manager-lb 0xc0005f2d80] Created  (t=+9.631368ms)
        tlogger.go:116: INFO balancergroup.go:299 [xds] [xds-cluster-manager-lb 0xc0005f2d80] Adding child policy of type "cds_experimental" for child "cluster:cluster"  (t=+9.68603ms)
        tlogger.go:116: INFO balancergroup.go:102 [xds] [xds-cluster-manager-lb 0xc0005f2d80] Creating child policy of type "cds_experimental" for child "cluster:cluster"  (t=+9.726857ms)
        tlogger.go:116: INFO cdsbalancer.go:109 [xds] [cds-lb 0xc0004144e0] Created  (t=+9.775007ms)
        tlogger.go:116: INFO cdsbalancer.go:121 [xds] [cds-lb 0xc0004144e0] xDS credentials in use: false  (t=+9.831814ms)
        tlogger.go:116: INFO cdsbalancer.go:290 [xds] [cds-lb 0xc0004144e0] Received balancer config update: {
              "LoadBalancingConfig": null,
              "Cluster": "cluster"
            }  (t=+9.889562ms)
        tlogger.go:116: INFO balancerstateaggregator.go:191 [xds] [xds-cluster-manager-lb 0xc0005f2d80] Child pickers: map[cluster:cluster:picker:0xc000fb7560,state:CONNECTING,stateToAggregate:CONNECTING]  (t=+10.006571ms)
        tlogger.go:116: INFO clientconn.go:544 [core] [Channel #591]Channel Connectivity change to CONNECTING  (t=+10.061845ms)
        logging.go:30: nodeID "8df6bf1b-88c4-4b1a-9f3e-8b1c876595bc" requested type.googleapis.com/envoy.config.route.v3.RouteConfiguration[new_route] and known map[new_route:{}]. Diff []
        logging.go:30: open watch 2 for type.googleapis.com/envoy.config.route.v3.RouteConfiguration[new_route] from nodeID "8df6bf1b-88c4-4b1a-9f3e-8b1c876595bc", version "1"
        logging.go:30: nodeID "8df6bf1b-88c4-4b1a-9f3e-8b1c876595bc" requested type.googleapis.com/envoy.config.cluster.v3.Cluster[cluster] and known map[]. Diff [cluster]
        logging.go:30: respond type.googleapis.com/envoy.config.cluster.v3.Cluster[cluster] version "" with version "1"
        tlogger.go:116: INFO cdsbalancer.go:414 [xds] [cds-lb 0xc0004144e0] Received Cluster resource: {
              "ClusterType": 0,
              "ClusterName": "cluster",
              "EDSServiceName": "cluster",
              "LRSServerConfig": null,
              "SecurityCfg": null,
              "MaxRequests": null,
              "DNSHostName": "",
              "PrioritizedClusterNames": null,
              "LBPolicy": [
                {
                  "ring_hash_experimental": {
                    "minRingSize": 1024,
                    "maxRingSize": 8388608
                  }
                }
              ],
              "OutlierDetection": null,
              "Raw": {
                "type_url": "type.googleapis.com/envoy.config.cluster.v3.Cluster",
                "value": "CgdjbHVzdGVyGg0KAhoAEgdjbHVzdGVyMAIQAw=="
              },
              "TelemetryLabels": {
                "csm.service_name": "unknown",
                "csm.service_namespace_name": "unknown"
              }
            }  (t=+10.969027ms)
        tlogger.go:116: INFO clusterresolver.go:85 [xds] [xds-cluster-resolver-lb 0xc000509880] Created  (t=+11.041232ms)
        tlogger.go:116: INFO cdsbalancer.go:455 [xds] [cds-lb 0xc0004144e0] Created child policy 0xc000509880 of type cluster_resolver_experimental  (t=+11.100183ms)
        logging.go:30: nodeID "8df6bf1b-88c4-4b1a-9f3e-8b1c876595bc" requested type.googleapis.com/envoy.config.cluster.v3.Cluster[cluster] and known map[cluster:{}]. Diff []
        logging.go:30: open watch 3 for type.googleapis.com/envoy.config.cluster.v3.Cluster[cluster] from nodeID "8df6bf1b-88c4-4b1a-9f3e-8b1c876595bc", version "1"
        logging.go:30: nodeID "8df6bf1b-88c4-4b1a-9f3e-8b1c876595bc" requested type.googleapis.com/envoy.config.endpoint.v3.ClusterLoadAssignment[cluster] and known map[]. Diff [cluster]
        logging.go:30: respond type.googleapis.com/envoy.config.endpoint.v3.ClusterLoadAssignment[cluster] version "" with version "1"
        tlogger.go:116: INFO balancer.go:76 [xds] [priority-lb 0xc000c58850] Created  (t=+12.055876ms)
        tlogger.go:116: INFO balancergroup.go:538 [xds] [xds-cluster-manager-lb 0xc0005f2d80] Balancer state update from child cluster:cluster, new state: {ConnectivityState:CONNECTING Picker:0xc000c32de0}  (t=+12.895682ms)
        tlogger.go:116: INFO balancerstateaggregator.go:147 [xds] [xds-cluster-manager-lb 0xc0005f2d80] State update from sub-balancer "cluster:cluster": {ConnectivityState:CONNECTING Picker:0xc000c32de0}  (t=+12.947488ms)
        tlogger.go:116: INFO balancerstateaggregator.go:191 [xds] [xds-cluster-manager-lb 0xc0005f2d80] Child pickers: map[cluster:cluster:picker:0xc000c32de0,state:CONNECTING,stateToAggregate:CONNECTING]  (t=+13.004996ms)
        logging.go:30: nodeID "8df6bf1b-88c4-4b1a-9f3e-8b1c876595bc" requested type.googleapis.com/envoy.config.endpoint.v3.ClusterLoadAssignment[cluster] and known map[cluster:{}]. Diff []
        logging.go:30: open watch 4 for type.googleapis.com/envoy.config.endpoint.v3.ClusterLoadAssignment[cluster] from nodeID "8df6bf1b-88c4-4b1a-9f3e-8b1c876595bc", version "1"
        tlogger.go:116: INFO balancergroup.go:299 [xds] [priority-lb 0xc000c58850] Adding child policy of type "outlier_detection_experimental" for child "priority-0-0"  (t=+13.056453ms)
        tlogger.go:116: INFO balancergroup.go:102 [xds] [priority-lb 0xc000c58850] Creating child policy of type "outlier_detection_experimental" for child "priority-0-0"  (t=+13.158414ms)
        tlogger.go:116: INFO balancer.go:74 [xds] [outlier-detection-lb 0xc000fef6c0] Created  (t=+13.212836ms)
        tlogger.go:116: INFO clusterimpl.go:79 [xds] [xds-cluster-impl-lb 0xc0000e1400] Created  (t=+13.286705ms)
        tlogger.go:116: INFO ringhash.go:56 [xds] [ring-hash-lb 0xc000718b40] Created  (t=+13.488624ms)
        tlogger.go:116: INFO clientconn.go:838 [core] [Channel #591 SubChannel #596]Subchannel created  (t=+13.612105ms)
        tlogger.go:116: INFO balancergroup.go:538 [xds] [priority-lb 0xc000c58850] Balancer state update from child priority-0-0, new state: {ConnectivityState:IDLE Picker:0xc00052a780}  (t=+15.746289ms)
        tlogger.go:116: INFO balancergroup.go:538 [xds] [xds-cluster-manager-lb 0xc0005f2d80] Balancer state update from child cluster:cluster, new state: {ConnectivityState:IDLE Picker:0xc00052a780}  (t=+15.833443ms)
        tlogger.go:116: INFO balancerstateaggregator.go:147 [xds] [xds-cluster-manager-lb 0xc0005f2d80] State update from sub-balancer "cluster:cluster": {ConnectivityState:IDLE Picker:0xc00052a780}  (t=+15.892954ms)
        tlogger.go:116: INFO balancerstateaggregator.go:191 [xds] [xds-cluster-manager-lb 0xc0005f2d80] Child pickers: map[cluster:cluster:picker:0xc00052a780,state:IDLE,stateToAggregate:IDLE]  (t=+15.957014ms)
        tlogger.go:116: INFO clientconn.go:544 [core] [Channel #591]Channel Connectivity change to IDLE  (t=+16.031053ms)
        tlogger.go:116: INFO ringhash.go:167 [xds] [ring-hash-lb 0xc000718b40] [subConn 0xc0010c2ea0] Executing a queued connect for subConn in state: IDLE  (t=+16.089824ms)
        tlogger.go:116: INFO clientconn.go:1199 [core] [Channel #591 SubChannel #596]Subchannel Connectivity change to CONNECTING  (t=+16.192025ms)
        tlogger.go:116: INFO clientconn.go:1319 [core] [Channel #591 SubChannel #596]Subchannel picks a new address "127.0.0.1:38299" to connect  (t=+16.258029ms)
        tlogger.go:116: INFO ringhash.go:377 [xds] [ring-hash-lb 0xc000718b40] SubConn's effective old state was: IDLE, new state is CONNECTING  (t=+16.612835ms)
        tlogger.go:116: INFO ringhash.go:396 [xds] [ring-hash-lb 0xc000718b40] Pushing new state CONNECTING and picker 0xc00052a810  (t=+17.228931ms)
        tlogger.go:116: INFO balancergroup.go:538 [xds] [priority-lb 0xc000c58850] Balancer state update from child priority-0-0, new state: {ConnectivityState:CONNECTING Picker:0xc00052a840}  (t=+17.299062ms)
        tlogger.go:116: INFO balancergroup.go:538 [xds] [xds-cluster-manager-lb 0xc0005f2d80] Balancer state update from child cluster:cluster, new state: {ConnectivityState:CONNECTING Picker:0xc00052a840}  (t=+17.370747ms)
        tlogger.go:116: INFO balancerstateaggregator.go:147 [xds] [xds-cluster-manager-lb 0xc0005f2d80] State update from sub-balancer "cluster:cluster": {ConnectivityState:CONNECTING Picker:0xc00052a840}  (t=+17.414599ms)
        tlogger.go:116: INFO balancerstateaggregator.go:191 [xds] [xds-cluster-manager-lb 0xc0005f2d80] Child pickers: map[cluster:cluster:picker:0xc00052a840,state:CONNECTING,stateToAggregate:CONNECTING]  (t=+17.47388ms)
        tlogger.go:116: INFO clientconn.go:544 [core] [Channel #591]Channel Connectivity change to CONNECTING  (t=+17.529334ms)
        tlogger.go:116: INFO clientconn.go:1199 [core] [Channel #591 SubChannel #596]Subchannel Connectivity change to READY  (t=+18.06036ms)
        tlogger.go:116: INFO ringhash.go:377 [xds] [ring-hash-lb 0xc000718b40] SubConn's effective old state was: CONNECTING, new state is READY  (t=+18.175657ms)
        tlogger.go:116: INFO ringhash.go:396 [xds] [ring-hash-lb 0xc000718b40] Pushing new state READY and picker 0xc000768348  (t=+18.790069ms)
        tlogger.go:116: INFO balancergroup.go:538 [xds] [priority-lb 0xc000c58850] Balancer state update from child priority-0-0, new state: {ConnectivityState:READY Picker:0xc000768378}  (t=+18.873526ms)
        tlogger.go:116: INFO balancergroup.go:538 [xds] [xds-cluster-manager-lb 0xc0005f2d80] Balancer state update from child cluster:cluster, new state: {ConnectivityState:READY Picker:0xc000768378}  (t=+18.957053ms)
        tlogger.go:116: INFO balancerstateaggregator.go:147 [xds] [xds-cluster-manager-lb 0xc0005f2d80] State update from sub-balancer "cluster:cluster": {ConnectivityState:READY Picker:0xc000768378}  (t=+19.018448ms)
        tlogger.go:116: INFO balancerstateaggregator.go:191 [xds] [xds-cluster-manager-lb 0xc0005f2d80] Child pickers: map[cluster:cluster:picker:0xc000768378,state:READY,stateToAggregate:READY]  (t=+19.072169ms)
        ringhash_balancer_test.go:1381: conn.GetState(): got CONNECTING, want READY
        tlogger.go:116: INFO clientconn.go:544 [core] [Channel #591]Channel Connectivity change to READY  (t=+19.97946ms)
        tlogger.go:116: INFO clientconn.go:544 [core] [Channel #591]Channel Connectivity change to SHUTDOWN  (t=+20.057597ms)
        tlogger.go:116: INFO resolver_wrapper.go:100 [core] [Channel #591]Closing the name resolver  (t=+20.121657ms)
        tlogger.go:116: INFO balancer_wrapper.go:147 [core] [Channel #591]ccBalancerWrapper: closing  (t=+20.199463ms)
        tlogger.go:116: INFO watch_service.go:56 [xds] [xds-resolver 0xc000c3e120] Canceling watch on Listener resource "test.server"  (t=+20.313687ms)
        logging.go:30: nodeID "8df6bf1b-88c4-4b1a-9f3e-8b1c876595bc" requested type.googleapis.com/envoy.config.cluster.v3.Cluster[] and known map[cluster:{}]. Diff []
        logging.go:30: open watch 5 for type.googleapis.com/envoy.config.cluster.v3.Cluster[] from nodeID "8df6bf1b-88c4-4b1a-9f3e-8b1c876595bc", version "1"
        logging.go:30: nodeID "8df6bf1b-88c4-4b1a-9f3e-8b1c876595bc" requested type.googleapis.com/envoy.config.listener.v3.Listener[] and known map[test.server:{}]. Diff []
        logging.go:30: open watch 6 for type.googleapis.com/envoy.config.listener.v3.Listener[] from nodeID "8df6bf1b-88c4-4b1a-9f3e-8b1c876595bc", version "1"
        logging.go:30: nodeID "8df6bf1b-88c4-4b1a-9f3e-8b1c876595bc" requested type.googleapis.com/envoy.config.endpoint.v3.ClusterLoadAssignment[] and known map[cluster:{}]. Diff []
        logging.go:30: open watch 7 for type.googleapis.com/envoy.config.endpoint.v3.ClusterLoadAssignment[] from nodeID "8df6bf1b-88c4-4b1a-9f3e-8b1c876595bc", version "1"
        tlogger.go:116: INFO ringhash.go:453 [xds] [ring-hash-lb 0xc000718b40] Shutdown  (t=+21.053936ms)
        tlogger.go:116: INFO clusterimpl.go:313 [xds] [xds-cluster-impl-lb 0xc0000e1400] Shutdown  (t=+21.096436ms)
        tlogger.go:116: INFO balancergroup.go:369 [xds] [priority-lb 0xc000c58850] Removing child policy for child "priority-0-0"  (t=+21.16805ms)
        tlogger.go:116: INFO clusterresolver.go:338 [xds] [xds-cluster-resolver-lb 0xc000509880] Shutdown  (t=+21.212513ms)
        tlogger.go:116: INFO cdsbalancer.go:380 [xds] [cds-lb 0xc0004144e0] Shutdown  (t=+21.255334ms)
        tlogger.go:116: INFO clustermanager.go:195 [xds] [xds-cluster-manager-lb 0xc0005f2d80] Shutdown  (t=+21.301611ms)
        tlogger.go:116: INFO watch_service.go:91 [xds] [xds-resolver 0xc000c3e120] Canceling watch on RouteConfiguration resource "new_route"  (t=+21.385298ms)
        logging.go:30: nodeID "8df6bf1b-88c4-4b1a-9f3e-8b1c876595bc" requested type.googleapis.com/envoy.config.route.v3.RouteConfiguration[] and known map[new_route:{}]. Diff []
        logging.go:30: open watch 8 for type.googleapis.com/envoy.config.route.v3.RouteConfiguration[] from nodeID "8df6bf1b-88c4-4b1a-9f3e-8b1c876595bc", version "1"
        tlogger.go:116: WARNING authority.go:457 [xds] [xds-client 0xc000d942a0] [passthrough:///127.0.0.1:46377] Watchers not notified since ADS stream failed after having received at least one response: rpc error: code = Canceled desc = context canceled  (t=+21.86111ms)
        tlogger.go:116: WARNING transport.go:493 [xds] [xds-client 0xc000d942a0] [passthrough:///127.0.0.1:46377] ADS stream closed: rpc error: code = Canceled desc = context canceled  (t=+21.915813ms)
        tlogger.go:116: INFO clientconn.go:544 [core] [Channel #592]Channel Connectivity change to SHUTDOWN  (t=+22.006102ms)
        tlogger.go:116: INFO resolver_wrapper.go:100 [core] [Channel #592]Closing the name resolver  (t=+22.05854ms)
        tlogger.go:116: INFO balancer_wrapper.go:147 [core] [Channel #592]ccBalancerWrapper: closing  (t=+22.116199ms)
        tlogger.go:116: INFO clientconn.go:1199 [core] [Channel #592 SubChannel #593]Subchannel Connectivity change to SHUTDOWN  (t=+22.[224](https://github.com/grpc/grpc-go/actions/runs/11569197131/job/32202453928?pr=7789#step:8:225)111ms)
        tlogger.go:116: INFO clientconn.go:1527 [core] [Channel #592 SubChannel #593]Subchannel deleted  (t=+22.283182ms)
        tlogger.go:116: INFO clientconn.go:314 [core] [Channel #592]Channel deleted  (t=+22.457569ms)
        tlogger.go:116: INFO clientimpl.go:101 [xds] [xds-client 0xc000d942a0] Shutdown  (t=+22.527741ms)
        tlogger.go:116: INFO xds_resolver.go:253 [xds] [xds-resolver 0xc000c3e120] Shutdown  (t=+22.566614ms)
        tlogger.go:116: INFO clientconn.go:1199 [core] [Channel #591 SubChannel #596]Subchannel Connectivity change to SHUTDOWN  (t=+22.646083ms)
        tlogger.go:116: INFO clientconn.go:1527 [core] [Channel #591 SubChannel #596]Subchannel deleted  (t=+22.701377ms)
        tlogger.go:116: INFO clientconn.go:314 [core] [Channel #591]Channel deleted  (t=+22.869562ms)
        tlogger.go:116: INFO server.go:816 [core] [Server #589 ListenSocket #590]ListenSocket deleted  (t=+22.993865ms)
        tlogger.go:116: INFO server.go:816 [core] [Server #587 ListenSocket #588]ListenSocket deleted  (t=+23.116705ms)
FAIL