Flaky test: Test/RingHash_AggregateClusterFallBackFromRingHashToLogicalDnsAtStartup

[purnesh42H]

--- FAIL: Test (23.36s)
    --- FAIL: Test/RingHash_AggregateClusterFallBackFromRingHashToLogicalDnsAtStartup (10.01s)
        tlogger.go:116: INFO server.go:685 [core] [Server #409]Server created  (t=+276.144µs)
        stubserver.go:288: Started test service backend at "127.0.0.1:44079"
        tlogger.go:116: INFO server.go:881 [core] [Server #409 ListenSocket #410]ListenSocket created  (t=+423.177µs)
        tlogger.go:116: INFO restartable_listener.go:84 [testutils] Stopping restartable listener "127.0.0.1:34327"  (t=+762.212µs)
        ringhash_balancer_test.go:438: Created new snapshot cache...
        tlogger.go:116: INFO server.go:685 [core] [Server #411]Server created  (t=+1.204154ms)
        ringhash_balancer_test.go:438: Registered Aggregated Discovery Service (ADS)...
        ringhash_balancer_test.go:438: xDS management server serving at: 127.0.0.1:35659...
        tlogger.go:116: INFO server.go:881 [core] [Server #411 ListenSocket #412]ListenSocket created  (t=+1.870166ms)
        server.go:[229](https://github.com/grpc/grpc-go/actions/runs/12684369727/job/35352925778?pr=7992#step:8:230): Created new resource snapshot...
        server.go:235: Updated snapshot cache with resource snapshot...
        tlogger.go:116: INFO clientconn.go:1674 [core] original dial target is: "xds:///test.server"  (t=+3.552713ms)
        tlogger.go:116: INFO clientconn.go:314 [core] [Channel #413]Channel created  (t=+3.622452ms)
        tlogger.go:116: INFO clientconn.go:193 [core] [Channel #413]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.73948ms)
        tlogger.go:116: INFO clientconn.go:194 [core] [Channel #413]Channel authority set to "test.server"  (t=+3.798049ms)
        tlogger.go:116: INFO xds_resolver.go:100 [xds] [xds-resolver 0xc000785320] Creating resolver for target: xds:///test.server  (t=+4.049948ms)
        tlogger.go:116: INFO client_refcounted.go:76 [xds] [xds-client 0xc000389a40] Created client with name "xds:///test.server" and bootstrap configuration:
             {
              "xds_servers": [
               {
                "server_uri": "passthrough:///127.0.0.1:35659",
                "channel_creds": [
                 {
                  "type": "insecure"
                 }
                ]
               }
              ],
              "certificate_providers": {
               "client-side-certificate-provider-instance": {
                "plugin_name": "file_watcher",
                "config": {
                 "certificate_file": "/tmp/testClientSideXDS35[230](https://github.com/grpc/grpc-go/actions/runs/12684369727/job/35352925778?pr=7992#step:8:231)94675/cert.pem",
                 "private_key_file": "/tmp/testClientSideXDS3523094675/key.pem",
                 "ca_certificate_file": "/tmp/testClientSideXDS3523094675/ca.pem",
                 "refresh_interval": "600s"
                }
               },
               "server-side-certificate-provider-instance": {
                "plugin_name": "file_watcher",
                "config": {
                 "certificate_file": "/tmp/testServerSideXDS420696777/cert.pem",
                 "private_key_file": "/tmp/testServerSideXDS420696777/key.pem",
                 "ca_certificate_file": "/tmp/testServerSideXDS420696777/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": "9deb4ef4-9391-4307-b8ba-e560cb9cc3ed",
               "locality": {}
              }
             }  (t=+5.461273ms)
        tlogger.go:116: INFO client_refcounted.go:81 [xds] xDS node ID: 9deb4ef4-9391-4307-b8ba-e560cb9cc3ed  (t=+5.576247ms)
        tlogger.go:116: INFO clientconn.go:1674 [core] original dial target is: "passthrough:///127.0.0.1:35659"  (t=+5.729802ms)
        tlogger.go:116: INFO clientconn.go:314 [core] [Channel #414]Channel created  (t=+5.829618ms)
        tlogger.go:116: INFO clientconn.go:193 [core] [Channel #414]parsed dial target is: resolver.Target{URL:url.URL{Scheme:"passthrough", Opaque:"", User:(*url.Userinfo)(nil), Host:"", Path:"/127.0.0.1:35659", RawPath:"", OmitHost:false, ForceQuery:false, RawQuery:"", Fragment:"", RawFragment:""}}  (t=+5.969428ms)
        tlogger.go:116: INFO clientconn.go:194 [core] [Channel #414]Channel authority set to "127.0.0.1:35659"  (t=+6.044247ms)
        tlogger.go:116: INFO resolver_wrapper.go:200 [core] [Channel #414]Resolver state updated: {
              "Addresses": [
                {
                  "Addr": "127.0.0.1:35659",
                  "ServerName": "",
                  "Attributes": null,
                  "BalancerAttributes": null,
                  "Metadata": null
                }
              ],
              "Endpoints": [
                {
                  "Addresses": [
                    {
                      "Addr": "127.0.0.1:35659",
                      "ServerName": "",
                      "Attributes": null,
                      "BalancerAttributes": null,
                      "Metadata": null
                    }
                  ],
                  "Attributes": null
                }
              ],
              "ServiceConfig": null,
              "Attributes": null
            } (resolver returned new addresses)  (t=+6.435836ms)
        tlogger.go:116: INFO balancer_wrapper.go:117 [core] [Channel #414]Channel switches to new LB policy "pick_first"  (t=+6.641057ms)
        tlogger.go:116: INFO clientconn.go:544 [core] [Channel #414]Channel Connectivity change to CONNECTING  (t=+6.738749ms)
        tlogger.go:116: INFO clientconn.go:858 [core] [Channel #414 SubChannel #415]Subchannel created  (t=+6.848183ms)
        tlogger.go:116: INFO clientconn.go:1219 [core] [Channel #414 SubChannel #415]Subchannel Connectivity change to CONNECTING  (t=+6.952096ms)
        tlogger.go:116: INFO clientconn.go:1339 [core] [Channel #414 SubChannel #415]Subchannel picks a new address "127.0.0.1:35659" to connect  (t=+7.016496ms)
        tlogger.go:116: INFO clientconn.go:314 [core] [Channel #414]Channel exiting idle mode  (t=+7.827194ms)
        tlogger.go:116: INFO clientconn.go:314 [core] [Channel #413]Channel exiting idle mode  (t=+8.216047ms)
        tlogger.go:116: INFO clientconn.go:1219 [core] [Channel #414 SubChannel #415]Subchannel Connectivity change to READY  (t=+10.783082ms)
        tlogger.go:116: INFO clientconn.go:544 [core] [Channel #414]Channel Connectivity change to READY  (t=+11.036874ms)
        logging.go:30: nodeID "9deb4ef4-9391-4307-b8ba-e560cb9cc3ed" 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 "9deb4ef4-9391-4307-b8ba-e560cb9cc3ed" 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 "9deb4ef4-9391-4307-b8ba-e560cb9cc3ed", version "1"
        logging.go:30: nodeID "9deb4ef4-9391-4307-b8ba-e560cb9cc3ed" 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 0xc000785320] For Listener resource "test.server" and RouteConfiguration resource "new_route", generated service config: {
              "loadBalancingConfig": [
                {
                  "xds_cluster_manager_experimental": {
                    "children": {
                      "cluster:aggregate_cluster": {
                        "childPolicy": [
                          {
                            "cds_experimental": {
                              "cluster": "aggregate_cluster"
                            }
                          }
                        ]
                      }
                    }
                  }
                }
              ]
            }  (t=+14.317477ms)
        tlogger.go:116: INFO resolver_wrapper.go:200 [core] [Channel #413]Resolver state updated: {
              "Addresses": null,
              "Endpoints": [],
              "ServiceConfig": {
                "Config": {
                  "Config": null,
                  "Methods": {}
                },
                "Err": null
              },
              "Attributes": {
                "\u003c%!p(resolver.csKeyType=grpc.internal.resolver.configSelector)\u003e": "\u003c0xc0006f60a0\u003e",
                "\u003c%!p(xdsclient.clientKeyType=grpc.xds.internal.client.Client)\u003e": "\u003c0xc000739c40\u003e"
              }
            } (service config updated)  (t=+14.696121ms)
        tlogger.go:116: INFO balancer_wrapper.go:117 [core] [Channel #413]Channel switches to new LB policy "xds_cluster_manager_experimental"  (t=+14.779026ms)
        tlogger.go:116: INFO clustermanager.go:59 [xds] [xds-cluster-manager-lb 0xc000160cc0] Created  (t=+14.828808ms)
        tlogger.go:116: INFO balancergroup.go:299 [xds] [xds-cluster-manager-lb 0xc000160cc0] Adding child policy of type "cds_experimental" for child "cluster:aggregate_cluster"  (t=+14.879082ms)
        tlogger.go:116: INFO balancergroup.go:102 [xds] [xds-cluster-manager-lb 0xc000160cc0] Creating child policy of type "cds_experimental" for child "cluster:aggregate_cluster"  (t=+14.918615ms)
        tlogger.go:116: INFO cdsbalancer.go:109 [xds] [cds-lb 0xc000247520] Created  (t=+14.966885ms)
        logging.go:30: nodeID "9deb4ef4-9391-4307-b8ba-e560cb9cc3ed" 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 "9deb4ef4-9391-4307-b8ba-e560cb9cc3ed", version "1"
        tlogger.go:116: INFO cdsbalancer.go:121 [xds] [cds-lb 0xc000247520] xDS credentials in use: false  (t=+15.364675ms)
        tlogger.go:116: INFO cdsbalancer.go:290 [xds] [cds-lb 0xc000247520] Received balancer config update: {
              "LoadBalancingConfig": null,
              "Cluster": "aggregate_cluster"
            }  (t=+15.460233ms)
        tlogger.go:116: INFO balancerstateaggregator.go:191 [xds] [xds-cluster-manager-lb 0xc000160cc0] Child pickers: map[cluster:aggregate_cluster:picker:0xc00077a670,state:CONNECTING,stateToAggregate:CONNECTING]  (t=+15.634617ms)
        tlogger.go:116: INFO clientconn.go:544 [core] [Channel #413]Channel Connectivity change to CONNECTING  (t=+15.713023ms)
        logging.go:30: nodeID "9deb4ef4-9391-4307-b8ba-e560cb9cc3ed" requested type.googleapis.com/envoy.config.cluster.v3.Cluster[aggregate_cluster] and known map[]. Diff [aggregate_cluster]
        logging.go:30: respond type.googleapis.com/envoy.config.cluster.v3.Cluster[aggregate_cluster] version "" with version "1"
        logging.go:30: nodeID "9deb4ef4-9391-4307-b8ba-e560cb9cc3ed" requested type.googleapis.com/envoy.config.cluster.v3.Cluster[aggregate_cluster] and known map[aggregate_cluster:{}]. Diff []
        logging.go:30: open watch 3 for type.googleapis.com/envoy.config.cluster.v3.Cluster[aggregate_cluster] from nodeID "9deb4ef4-9391-4307-b8ba-e560cb9cc3ed", version "1"
        tlogger.go:116: INFO cdsbalancer.go:414 [xds] [cds-lb 0xc000247520] Received Cluster resource: {
              "ClusterType": 2,
              "ClusterName": "aggregate_cluster",
              "EDSServiceName": "",
              "LRSServerConfig": null,
              "SecurityCfg": null,
              "MaxRequests": null,
              "DNSHostName": "",
              "PrioritizedClusterNames": [
                "eds_cluster",
                "logical_dns_cluster"
              ],
              "LBPolicy": [
                {
                  "ring_hash_experimental": {
                    "minRingSize": 1024,
                    "maxRingSize": 8388608
                  }
                }
              ],
              "OutlierDetection": null,
              "Raw": {
                "type_url": "type.googleapis.com/envoy.config.cluster.v3.Cluster",
                "value": "ChFhZ2dyZWdhdGVfY2x1c3RlcjACsgKKAQoYZW52b3kuY2x1c3RlcnMuYWdncmVnYXRlEm4KSHR5cGUuZ29vZ2xlYXBpcy5jb20vZW52b3kuZXh0ZW5zaW9ucy5jbHVzdGVycy5hZ2dyZWdhdGUudjMuQ2x1c3RlckNvbmZpZxIiCgtlZHNfY2x1c3RlcgoTbG9naWNhbF9kbnNfY2x1c3Rlcg=="
              },
              "TelemetryLabels": {
                "csm.service_name": "unknown",
                "csm.service_namespace_name": "unknown"
              }
            }  (t=+16.746595ms)
        logging.go:30: nodeID "9deb4ef4-9391-4307-b8ba-e560cb9cc3ed" requested type.googleapis.com/envoy.config.cluster.v3.Cluster[aggregate_cluster eds_cluster] and known map[aggregate_cluster:{}]. Diff [eds_cluster]
        logging.go:30: respond type.googleapis.com/envoy.config.cluster.v3.Cluster[aggregate_cluster eds_cluster] version "1" with version "1"
        tlogger.go:116: INFO cdsbalancer.go:414 [xds] [cds-lb 0xc000247520] Received Cluster resource: {
              "ClusterType": 0,
              "ClusterName": "eds_cluster",
              "EDSServiceName": "eds_cluster",
              "LRSServerConfig": null,
              "SecurityCfg": null,
              "MaxRequests": null,
              "DNSHostName": "",
              "PrioritizedClusterNames": null,
              "LBPolicy": [
                {
                  "xds_wrr_locality_experimental": {
                    "childPolicy": [
                      {
                        "round_robin": {}
                      }
                    ]
                  }
                }
              ],
              "OutlierDetection": null,
              "Raw": {
                "type_url": "type.googleapis.com/envoy.config.cluster.v3.Cluster",
                "value": "CgtlZHNfY2x1c3RlchoRCgIaABILZWRzX2NsdXN0ZXIQAw=="
              },
              "TelemetryLabels": {
                "csm.service_name": "unknown",
                "csm.service_namespace_name": "unknown"
              }
            }  (t=+18.182486ms)
        logging.go:30: nodeID "9deb4ef4-9391-4307-b8ba-e560cb9cc3ed" requested type.googleapis.com/envoy.config.cluster.v3.Cluster[aggregate_cluster eds_cluster logical_dns_cluster] and known map[aggregate_cluster:{} eds_cluster:{}]. Diff [logical_dns_cluster]
        logging.go:30: respond type.googleapis.com/envoy.config.cluster.v3.Cluster[aggregate_cluster eds_cluster logical_dns_cluster] version "1" with version "1"
        tlogger.go:116: INFO cdsbalancer.go:414 [xds] [cds-lb 0xc000247520] Received Cluster resource: {
              "ClusterType": 1,
              "ClusterName": "logical_dns_cluster",
              "EDSServiceName": "",
              "LRSServerConfig": null,
              "SecurityCfg": null,
              "MaxRequests": null,
              "DNSHostName": "server.example.com:443",
              "PrioritizedClusterNames": null,
              "LBPolicy": [
                {
                  "xds_wrr_locality_experimental": {
                    "childPolicy": [
                      {
                        "round_robin": {}
                      }
                    ]
                  }
                }
              ],
              "OutlierDetection": null,
              "Raw": {
                "type_url": "type.googleapis.com/envoy.config.cluster.v3.Cluster",
                "value": "ChNsb2dpY2FsX2Ruc19jbHVzdGVyigIhEh8SHQobChkKFxISc2VydmVyLmV4YW1wbGUuY29tGLsDEAI="
              },
              "TelemetryLabels": {
                "csm.service_name": "unknown",
                "csm.service_namespace_name": "unknown"
              }
            }  (t=+19.145708ms)
        logging.go:30: nodeID "9deb4ef4-9391-4307-b8ba-e560cb9cc3ed" requested type.googleapis.com/envoy.config.cluster.v3.Cluster[aggregate_cluster eds_cluster logical_dns_cluster] and known map[aggregate_cluster:{} eds_cluster:{} logical_dns_cluster:{}]. Diff []
        logging.go:30: open watch 4 for type.googleapis.com/envoy.config.cluster.v3.Cluster[aggregate_cluster eds_cluster logical_dns_cluster] from nodeID "9deb4ef4-9391-4307-b8ba-e560cb9cc3ed", version "1"
        tlogger.go:116: INFO clusterresolver.go:85 [xds] [xds-cluster-resolver-lb 0xc0008cea80] Created  (t=+19.61966ms)
        tlogger.go:116: INFO cdsbalancer.go:455 [xds] [cds-lb 0xc000247520] Created child policy 0xc0008cea80 of type cluster_resolver_experimental  (t=+19.708395ms)
        ringhash_balancer_test.go:460: rpc EmptyCall() failed: rpc error: code = DeadlineExceeded desc = received context error while waiting for new LB policy update: context deadline exceeded
        tlogger.go:116: INFO clientconn.go:544 [core] [Channel #413]Channel Connectivity change to SHUTDOWN  (t=+10.008614258s)
        tlogger.go:116: INFO resolver_wrapper.go:100 [core] [Channel #413]Closing the name resolver  (t=+10.008656096s)
        tlogger.go:116: INFO balancer_wrapper.go:155 [core] [Channel #413]ccBalancerWrapper: closing  (t=+10.008718722s)
        tlogger.go:116: INFO watch_service.go:56 [xds] [xds-resolver 0xc000785320] Canceling watch on Listener resource "test.server"  (t=+10.008880952s)
        tlogger.go:116: INFO watch_service.go:91 [xds] [xds-resolver 0xc000785320] Canceling watch on RouteConfiguration resource "new_route"  (t=+10.00908305s)
        tlogger.go:116: INFO clusterresolver.go:355 [xds] [xds-cluster-resolver-lb 0xc0008cea80] Shutdown  (t=+10.00918091s)
        tlogger.go:116: WARNING ads_stream.go:514 [xds] [xds-client 0xc000389a40] [xds-channel 0xc00064c120] [ads-stream 0xc0006f0800] ADS stream closed: rpc error: code = Canceled desc = context canceled  (t=+10.009[232](https://github.com/grpc/grpc-go/actions/runs/12684369727/job/35352925778?pr=7992#step:8:233)788s)
        tlogger.go:116: INFO cdsbalancer.go:380 [xds] [cds-lb 0xc000247520] Shutdown  (t=+10.009283252s)
        tlogger.go:116: INFO ads_stream.go:178 [xds] [xds-client 0xc000389a40] [xds-channel 0xc00064c120] [ads-stream 0xc0006f0800] Stopping ADS stream  (t=+10.009327324s)
        logging.go:30: nodeID "9deb4ef4-9391-4307-b8ba-e560cb9cc3ed" requested type.googleapis.com/envoy.config.cluster.v3.Cluster[eds_cluster logical_dns_cluster] and known map[aggregate_cluster:{} eds_cluster:{} logical_dns_cluster:{}]. Diff []
        tlogger.go:116: INFO clientconn.go:544 [core] [Channel #414]Channel Connectivity change to SHUTDOWN  (t=+10.009384731s)
        logging.go:30: open watch 5 for type.googleapis.com/envoy.config.cluster.v3.Cluster[eds_cluster logical_dns_cluster] from nodeID "9deb4ef4-9391-4307-b8ba-e560cb9cc3ed", version "1"
        tlogger.go:116: INFO resolver_wrapper.go:100 [core] [Channel #414]Closing the name resolver  (t=+10.009489346s)
        tlogger.go:116: INFO clustermanager.go:197 [xds] [xds-cluster-manager-lb 0xc000160cc0] Shutdown  (t=+10.009563402s)
        tlogger.go:116: INFO balancer_wrapper.go:155 [core] [Channel #414]ccBalancerWrapper: closing  (t=+10.009610319s)
        tlogger.go:116: INFO clientconn.go:1219 [core] [Channel #414 SubChannel #415]Subchannel Connectivity change to SHUTDOWN  (t=+10.009743041s)
        tlogger.go:116: INFO clientconn.go:1547 [core] [Channel #414 SubChannel #415]Subchannel deleted  (t=+10.009789337s)
        tlogger.go:116: INFO clientconn.go:314 [core] [Channel #414]Channel deleted  (t=+10.010027204s)
        tlogger.go:116: INFO channel.go:145 [xds] [xds-client 0xc000389a40] [xds-channel 0xc00064c120] Shutdown  (t=+10.010089721s)
        tlogger.go:116: INFO clientimpl.go:185 [xds] [xds-client 0xc000389a40] Shutdown  (t=+10.010159192s)
        tlogger.go:116: INFO xds_resolver.go:253 [xds] [xds-resolver 0xc000785320] Shutdown  (t=+10.01019071s)
        tlogger.go:116: INFO clientconn.go:314 [core] [Channel #413]Channel deleted  (t=+10.010[238](https://github.com/grpc/grpc-go/actions/runs/12684369727/job/35352925778?pr=7992#step:8:239)539s)
        tlogger.go:116: INFO server.go:817 [core] [Server #411 ListenSocket #412]ListenSocket deleted  (t=+10.010355049s)
        tlogger.go:116: INFO server.go:817 [core] [Server #409 ListenSocket #410]ListenSocket deleted  (t=+10.010458542s)
FAIL