Flaky Test: EDS_ResourceRemoved

[arjan-bal]

Please see the FAQ in our main README.md before submitting your issue.

--- FAIL: Test (8.99s)
    --- FAIL: Test/EDS_ResourceRemoved (1.08s)
        eds_impl_test.go:625: Created new snapshot cache...
        tlogger.go:116: INFO server.go:690 [core] [Server #798]Server created  (t=+1.268213ms)
        eds_impl_test.go:625: Registered Aggregated Discovery Service (ADS)...
        eds_impl_test.go:625: xDS management server serving at: 127.0.0.1:42583...
        tlogger.go:116: INFO server.go:886 [core] [Server #798 ListenSocket #799]ListenSocket created  (t=+2.93925ms)
        tlogger.go:116: INFO server.go:690 [core] [Server #800]Server created  (t=+9.940513ms)
        stubserver.go:300: Started test service backend at "127.0.0.1:42415"
        server.go:229: Created new resource snapshot...
        server.go:235: Updated snapshot cache with resource snapshot...
        tlogger.go:116: INFO server.go:886 [core] [Server #800 ListenSocket #801]ListenSocket created  (t=+10.880402ms)
        tlogger.go:116: INFO pool.go:242 [xds] xDS node ID: 295acf50-1b56-45b4-9a16-71bd850cb659  (t=+14.[240](https://github.com/grpc/grpc-go/actions/runs/13393122559/job/37405347291?pr=7967#step:8:241)12ms)
        tlogger.go:116: INFO clientconn.go:1679 [core] original dial target is: "whatever:///test.service"  (t=+14.578884ms)
        tlogger.go:116: INFO clientconn.go:333 [core] [Channel #802]Channel created  (t=+14.780902ms)
        logging.go:30: nodeID "295acf50-1b56-45b4-9a16-71bd850cb659" requested type.googleapis.com/envoy.config.endpoint.v3.ClusterLoadAssignment[endpoints-my-service-client-side-xds] and known map[]. Diff [endpoints-my-service-client-side-xds]
        logging.go:30: respond type.googleapis.com/envoy.config.endpoint.v3.ClusterLoadAssignment[endpoints-my-service-client-side-xds] version "" with version "1"
        tlogger.go:116: INFO balancer.go:76 [xds] [priority-lb 0x400042c690] Created  (t=+33.856051ms)
        tlogger.go:116: INFO clientconn.go:563 [core] [Channel #802]Channel Connectivity change to CONNECTING  (t=+35.835425ms)
        tlogger.go:116: INFO balancergroup.go:299 [xds] [priority-lb 0x400042c690] Adding child policy of type "outlier_detection_experimental" for child "priority-0-0"  (t=+36.074483ms)
        tlogger.go:116: INFO balancergroup.go:102 [xds] [priority-lb 0x400042c690] Creating child policy of type "outlier_detection_experimental" for child "priority-0-0"  (t=+36.252286ms)
        tlogger.go:116: INFO balancer.go:74 [xds] [outlier-detection-lb 0x40004ff1e0] Created  (t=+36.427333ms)
        logging.go:30: nodeID "295acf50-1b56-45b4-9a16-71bd850cb659" requested type.googleapis.com/envoy.config.endpoint.v3.ClusterLoadAssignment[endpoints-my-service-client-side-xds] and known map[endpoints-my-service-client-side-xds:{}]. Diff []
        logging.go:30: open watch 2 for type.googleapis.com/envoy.config.endpoint.v3.ClusterLoadAssignment[endpoints-my-service-client-side-xds] from nodeID "295acf50-1b56-45b4-9a16-71bd850cb659", version "1"
        tlogger.go:116: INFO clusterimpl.go:76 [xds] [xds-cluster-impl-lb 0x400024ca00] Created  (t=+37.929424ms)
        tlogger.go:116: INFO weightedtarget.go:66 [xds] [weighted-target-lb 0x40001b9680] Created  (t=+38.622351ms)
        tlogger.go:116: INFO balancer.go:88 [xds] [wrrlocality-lb 0x40007e9620] Created  (t=+38.825642ms)
        tlogger.go:116: INFO balancergroup.go:299 [xds] [weighted-target-lb 0x40001b9680] Adding child policy of type "round_robin" for child "{\"region\":\"region-1\",\"zone\":\"zone-1\",\"subZone\":\"subzone-1\"}"  (t=+39.317863ms)
        tlogger.go:116: INFO balancergroup.go:102 [xds] [weighted-target-lb 0x40001b9680] Creating child policy of type "round_robin" for child "{\"region\":\"region-1\",\"zone\":\"zone-1\",\"subZone\":\"subzone-1\"}"  (t=+39.566097ms)
        tlogger.go:116: INFO roundrobin.go:56 [roundrobin] [0x40007e9950] Created  (t=+39.775549ms)
        tlogger.go:116: INFO clientconn.go:857 [core] [Channel #802 SubChannel #807]Subchannel created  (t=+40.272279ms)
        tlogger.go:116: INFO clientconn.go:1224 [core] [Channel #802 SubChannel #807]Subchannel Connectivity change to CONNECTING  (t=+40.877531ms)
        tlogger.go:116: INFO clientconn.go:1344 [core] [Channel #802 SubChannel #807]Subchannel picks a new address "localhost:4[241](https://github.com/grpc/grpc-go/actions/runs/13393122559/job/37405347291?pr=7967#step:8:242)5" to connect  (t=+41.070152ms)
        tlogger.go:116: INFO balancergroup.go:538 [xds] [weighted-target-lb 0x40001b9680] Balancer state update from child {"region":"region-1","zone":"zone-1","subZone":"subzone-1"}, new state: {ConnectivityState:CONNECTING Picker:0x400061a7c0}  (t=+42.646562ms)
        tlogger.go:116: INFO aggregator.go:253 [xds] [weighted-target-lb 0x40001b9680] Child pickers with config: map[{"region":"region-1","zone":"zone-1","subZone":"subzone-1"}:weight:1,picker:0x400061a7c0,state:CONNECTING,stateToAggregate:CONNECTING]  (t=+43.768051ms)
        tlogger.go:116: INFO balancergroup.go:538 [xds] [priority-lb 0x400042c690] Balancer state update from child priority-0-0, new state: {ConnectivityState:CONNECTING Picker:0x400012e750}  (t=+44.171496ms)
        tlogger.go:116: INFO clientconn.go:1224 [core] [Channel #802 SubChannel #807]Subchannel Connectivity change to READY  (t=+45.553332ms)
        tlogger.go:116: INFO balancergroup.go:538 [xds] [weighted-target-lb 0x40001b9680] Balancer state update from child {"region":"region-1","zone":"zone-1","subZone":"subzone-1"}, new state: {ConnectivityState:READY Picker:0x400061a800}  (t=+46.392823ms)
        tlogger.go:116: INFO aggregator.go:253 [xds] [weighted-target-lb 0x40001b9680] Child pickers with config: map[{"region":"region-1","zone":"zone-1","subZone":"subzone-1"}:weight:1,picker:0x400061a800,state:READY,stateToAggregate:READY]  (t=+46.579743ms)
        tlogger.go:116: INFO balancergroup.go:538 [xds] [priority-lb 0x400042c690] Balancer state update from child priority-0-0, new state: {ConnectivityState:READY Picker:0x400012e7e0}  (t=+46.766272ms)
        tlogger.go:116: INFO clientconn.go:563 [core] [Channel #802]Channel Connectivity change to READY  (t=+46.93057ms)
        server.go:229: Created new resource snapshot...
        logging.go:30: respond open watch 1 type.googleapis.com/envoy.config.cluster.v3.Cluster[cluster-my-service-client-side-xds] with new version "2"
        logging.go:30: respond type.googleapis.com/envoy.config.cluster.v3.Cluster[cluster-my-service-client-side-xds] version "1" with version "2"
        logging.go:30: respond open watch 2 type.googleapis.com/envoy.config.endpoint.v3.ClusterLoadAssignment[endpoints-my-service-client-side-xds] with new version "2"
        logging.go:30: respond type.googleapis.com/envoy.config.endpoint.v3.ClusterLoadAssignment[endpoints-my-service-client-side-xds] version "1" with version "2"
        server.go:235: Updated snapshot cache with resource snapshot...
        logging.go:30: nodeID "295acf50-1b56-45b4-9a16-71bd850cb659" requested type.googleapis.com/envoy.config.cluster.v3.Cluster[cluster-my-service-client-side-xds] and known map[cluster-my-service-client-side-xds:{}]. Diff []
        logging.go:30: open watch 3 for type.googleapis.com/envoy.config.cluster.v3.Cluster[cluster-my-service-client-side-xds] from nodeID "295acf50-1b56-45b4-9a16-71bd850cb659", version "2"
        logging.go:30: nodeID "295acf50-1b56-45b4-9a16-71bd850cb659" requested type.googleapis.com/envoy.config.endpoint.v3.ClusterLoadAssignment[endpoints-my-service-client-side-xds] and known map[endpoints-my-service-client-side-xds:{}]. Diff []
        logging.go:30: open watch 4 for type.googleapis.com/envoy.config.endpoint.v3.ClusterLoadAssignment[endpoints-my-service-client-side-xds] from nodeID "295acf50-1b56-45b4-9a16-71bd850cb659", version "2"
        tlogger.go:116: WARNING ads_stream.go:514 [xds] [xds-client 0x40008f43f0] [xds-channel 0x400077ecc0] [ads-stream 0x40006a8b00] ADS stream closed: rpc error: code = Canceled desc = context canceled  (t=+1.060711194s)
        tlogger.go:116: INFO ads_stream.go:178 [xds] [xds-client 0x40008f43f0] [xds-channel 0x400077ecc0] [ads-stream 0x40006a8b00] Stopping ADS stream  (t=+1.061028017s)
        tlogger.go:116: INFO clientconn.go:563 [core] [Channel #803]Channel Connectivity change to SHUTDOWN  (t=+1.061235095s)
        tlogger.go:116: INFO resolver_wrapper.go:111 [core] [Channel #803]Closing the name resolver  (t=+1.061394143s)
        tlogger.go:116: INFO balancer_wrapper.go:160 [core] [Channel #803]ccBalancerWrapper: closing  (t=+1.06176169s)
        tlogger.go:116: INFO clientconn.go:1224 [core] [Channel #803 SubChannel #804]Subchannel Connectivity change to SHUTDOWN  (t=+1.06210867s)
        tlogger.go:116: INFO clientconn.go:1552 [core] [Channel #803 SubChannel #804]Subchannel deleted  (t=+1.062[245](https://github.com/grpc/grpc-go/actions/runs/13393122559/job/37405347291?pr=7967#step:8:246)295s)
        tlogger.go:116: INFO clientconn.go:333 [core] [Channel #803]Channel deleted  (t=+1.062748467s)
        tlogger.go:116: INFO channel.go:145 [xds] [xds-client 0x40008f43f0] [xds-channel 0x400077ecc0] Shutdown  (t=+1.062913226s)
        tlogger.go:116: INFO clientimpl.go:228 [xds] [xds-client 0x40008f43f0] Shutdown  (t=+1.063062946s)
        tlogger.go:116: INFO clientconn.go:563 [core] [Channel #802]Channel Connectivity change to SHUTDOWN  (t=+1.063231411s)
        tlogger.go:116: INFO resolver_wrapper.go:111 [core] [Channel #802]Closing the name resolver  (t=+1.06335372s)
        tlogger.go:116: INFO balancer_wrapper.go:160 [core] [Channel #802]ccBalancerWrapper: closing  (t=+1.063490245s)
        tlogger.go:116: INFO clusterimpl.go:350 [xds] [xds-cluster-impl-lb 0x400024ca00] Shutdown  (t=+1.064349904s)
        tlogger.go:116: INFO balancergroup.go:369 [xds] [priority-lb 0x400042c690] Removing child policy for child "priority-0-0"  (t=+1.064536403s)
        tlogger.go:116: INFO clusterresolver.go:355 [xds] [xds-cluster-resolver-lb 0x40001609c0] Shutdown  (t=+1.064654454s)
        tlogger.go:116: INFO cdsbalancer.go:391 [xds] [cds-lb 0x400053a600] Shutdown  (t=+1.064757347s)
        tlogger.go:116: INFO clientconn.go:1224 [core] [Channel #802 SubChannel #807]Subchannel Connectivity change to SHUTDOWN  (t=+1.06501541s)
        tlogger.go:116: INFO clientconn.go:1552 [core] [Channel #802 SubChannel #807]Subchannel deleted  (t=+1.065150162s)
        tlogger.go:116: INFO clientconn.go:333 [core] [Channel #802]Channel deleted  (t=+1.065895827s)
        tlogger.go:116: INFO server.go:822 [core] [Server #800 ListenSocket #801]ListenSocket deleted  (t=+1.06633[249](https://github.com/grpc/grpc-go/actions/runs/13393122559/job/37405347291?pr=7967#step:8:250)4s)
        tlogger.go:116: INFO server.go:822 [core] [Server #798 ListenSocket #799]ListenSocket deleted  (t=+1.066660047s)

The error log causing the failure:

tlogger.go:111: ERROR clusterresolver.go:330 [xds] [xds-cluster-resolver-lb 0x40001609c0] xds: received ExitIdle with no child balancer (t=+31.247038ms)

Failing run: https://github.com/grpc/grpc-go/actions/runs/13393122559/job/37405347291?pr=7967