Flaky test : 5/100k: TestEDS_ClusterResourceUpdates #8920
Description
Failed run : https://github.com/grpc/grpc-go/actions/runs/22218782275/job/64268739382?pr=8907
Failed 5/100k times on forge on master
Logs
--- FAIL: Test (12.85s)
--- FAIL: Test/EDS_ClusterResourceUpdates (5.01s)
eds_impl_test.go:640: Created new snapshot cache...
tlogger.go:133: INFO server.go:717 [core] [Server #656] Server created (t=+172.623µs)
eds_impl_test.go:640: Registered Aggregated Discovery Service (ADS)...
eds_impl_test.go:640: xDS management server serving at: 127.0.0.1:43699...
tlogger.go:133: INFO server.go:913 [core] [Server #656 ListenSocket #657] ListenSocket created (t=+347.207µs)
tlogger.go:133: INFO server.go:717 [core] [Server #658] Server created (t=+1.10893ms)
stubserver.go:300: Started test service backend at "127.0.0.1:39835"
tlogger.go:133: INFO server.go:913 [core] [Server #658 ListenSocket #659] ListenSocket created (t=+1.225965ms)
tlogger.go:133: INFO server.go:717 [core] [Server #660] Server created (t=+1.292002ms)
stubserver.go:300: Started test service backend at "127.0.0.1:36025"
server.go:229: Created new resource snapshot...
logging.go:30: setting snapshot for node 3abec332-5dab-43e1-97c5-a4307d7b83a1
server.go:235: Updated snapshot cache with resource snapshot...
tlogger.go:133: INFO clientconn.go:1799 [core] original dial target is: "xds:///listener-my-service-client-side-xds" (t=+1.413178ms)
tlogger.go:133: INFO clientconn.go:514 [core] [Channel #662] Channel created for target "xds:///listener-my-service-client-side-xds" (t=+1.428317ms)
tlogger.go:133: INFO clientconn.go:245 [core] [Channel #662] parsed dial target is: resolver.Target{URL:url.URL{Scheme:"xds", Opaque:"", User:(*url.Userinfo)(nil), Host:"", Path:"/listener-my-service-client-side-xds", RawPath:"", OmitHost:false, ForceQuery:false, RawQuery:"", Fragment:"", RawFragment:""}} (t=+1.449396ms)
tlogger.go:133: INFO clientconn.go:246 [core] [Channel #662] Channel authority set to "listener-my-service-client-side-xds" (t=+1.458754ms)
tlogger.go:133: INFO clientconn.go:618 [core] [Channel #662] Channel Connectivity change to CONNECTING (t=+1.471888ms)
tlogger.go:133: INFO server.go:913 [core] [Server #660 ListenSocket #661] ListenSocket created (t=+1.482438ms)
tlogger.go:133: INFO pool.go:309 [xds] xDS node ID: 3abec332-5dab-43e1-97c5-a4307d7b83a1 (t=+1.592263ms)
tlogger.go:133: INFO xds_resolver.go:153 [xds] [xds-resolver 0xc00061f0e0] Creating resolver for target: xds:///listener-my-service-client-side-xds (t=+1.604927ms)
tlogger.go:133: INFO clientconn.go:1799 [core] original dial target is: "passthrough:///127.0.0.1:43699" (t=+1.629562ms)
tlogger.go:133: INFO clientconn.go:514 [core] [Channel #663] Channel created for target "passthrough:///127.0.0.1:43699" (t=+1.640212ms)
tlogger.go:133: INFO clientconn.go:245 [core] [Channel #663] parsed dial target is: resolver.Target{URL:url.URL{Scheme:"passthrough", Opaque:"", User:(*url.Userinfo)(nil), Host:"", Path:"/127.0.0.1:43699", RawPath:"", OmitHost:false, ForceQuery:false, RawQuery:"", Fragment:"", RawFragment:""}} (t=+1.650982ms)
tlogger.go:133: INFO clientconn.go:246 [core] [Channel #663] Channel authority set to "127.0.0.1:43699" (t=+1.658988ms)
tlogger.go:133: INFO clientconn.go:419 [core] [Channel #662] Channel exiting idle mode (t=+1.683353ms)
tlogger.go:133: INFO clientconn.go:618 [core] [Channel #663] Channel Connectivity change to CONNECTING (t=+1.709067ms)
tlogger.go:133: INFO resolver_wrapper.go:211 [core] [Channel #663] Resolver state updated: {
"Addresses": [
{
"Addr": "127.0.0.1:43699",
"ServerName": "",
"Attributes": null,
"BalancerAttributes": null,
"Metadata": null
}
],
"Endpoints": [
{
"Addresses": [
{
"Addr": "127.0.0.1:43699",
"ServerName": "",
"Attributes": null,
"BalancerAttributes": null,
"Metadata": null
}
],
"Attributes": null
}
],
"ServiceConfig": null,
"Attributes": null
} (resolver returned new addresses) (t=+1.741988ms)
tlogger.go:133: INFO balancer_wrapper.go:121 [core] [Channel #663] Channel switches to new LB policy "pick_first" (t=+1.768107ms)
tlogger.go:133: INFO clientconn.go:921 [core] [Channel #663 SubChannel #664] Subchannel created (t=+1.791581ms)
tlogger.go:133: INFO clientconn.go:419 [core] [Channel #663] Channel exiting idle mode (t=+1.809604ms)
tlogger.go:133: INFO clientconn.go:1295 [core] [Channel #663 SubChannel #664] Subchannel Connectivity change to CONNECTING (t=+1.833647ms)
tlogger.go:133: INFO clientconn.go:1463 [core] [Channel #663 SubChannel #664] Subchannel picks a new address "127.0.0.1:43699" to connect (t=+1.848204ms)
tlogger.go:133: INFO clientconn.go:1295 [core] [Channel #663 SubChannel #664] Subchannel Connectivity change to READY (t=+2.047912ms)
tlogger.go:133: INFO clientconn.go:618 [core] [Channel #663] Channel Connectivity change to READY (t=+2.083338ms)
logging.go:30: respond type.googleapis.com/envoy.config.listener.v3.Listener (requested [listener-my-service-client-side-xds]) version "" with version "1" and resources [listener-my-service-client-side-xds]
logging.go:30: open watch 1 for type.googleapis.com/envoy.config.listener.v3.Listener map[listener-my-service-client-side-xds:{}] from nodeID "3abec332-5dab-43e1-97c5-a4307d7b83a1", version "1"
logging.go:30: respond type.googleapis.com/envoy.config.route.v3.RouteConfiguration (requested [route-my-service-client-side-xds]) version "" with version "1" and resources [route-my-service-client-side-xds]
logging.go:30: open watch 2 for type.googleapis.com/envoy.config.route.v3.RouteConfiguration map[route-my-service-client-side-xds:{}] from nodeID "3abec332-5dab-43e1-97c5-a4307d7b83a1", version "1"
logging.go:30: respond type.googleapis.com/envoy.config.cluster.v3.Cluster (requested [cluster-my-service-client-side-xds]) version "" with version "1" and resources [cluster-my-service-client-side-xds]
logging.go:30: open watch 3 for type.googleapis.com/envoy.config.cluster.v3.Cluster map[cluster-my-service-client-side-xds:{}] from nodeID "3abec332-5dab-43e1-97c5-a4307d7b83a1", version "1"
logging.go:30: respond type.googleapis.com/envoy.config.endpoint.v3.ClusterLoadAssignment (requested [endpoints-my-service-client-side-xds]) version "" with version "1" and resources [endpoints-my-service-client-side-xds]
tlogger.go:133: INFO resolver_wrapper.go:211 [core] [Channel #662] Resolver state updated: {
"Addresses": null,
"Endpoints": [],
"ServiceConfig": {
"Config": {
"Config": null,
"Methods": {}
},
"Err": null
},
"Attributes": {
"\u003c%!p(resolver.csKeyType=grpc.internal.resolver.configSelector)\u003e": "\u003c0xc00022dce0\u003e",
"\u003c%!p(xdsresource.xdsConfigkey={})\u003e": "\u003c0xc000541000\u003e",
"\u003c%!p(xdsdepmgr.xdsClusterSubscriberKey={})\u003e": "\u003c0xc0007de6c0\u003e",
"\u003c%!p(xdsclient.clientKeyType=grpc.xds.internal.client.Client)\u003e": "\u003c0xc0007ca5a0\u003e"
}
} (service config updated) (t=+3.003536ms)
tlogger.go:133: INFO balancer_wrapper.go:121 [core] [Channel #662] Channel switches to new LB policy "xds_cluster_manager_experimental" (t=+3.029344ms)
tlogger.go:133: INFO clustermanager.go:58 [xds] [xds-cluster-manager-lb 0xc0005411a0] Created (t=+3.043721ms)
tlogger.go:133: INFO balancergroup.go:274 [xds] [xds-cluster-manager-lb 0xc0005411a0] Adding child policy of type "cds_experimental" for child "cluster:cluster-my-service-client-side-xds" (t=+3.052587ms)
tlogger.go:133: INFO balancergroup.go:102 [xds] [xds-cluster-manager-lb 0xc0005411a0] Creating child policy of type "cds_experimental" for child "cluster:cluster-my-service-client-side-xds" (t=+3.059901ms)
tlogger.go:133: INFO cdsbalancer.go:109 [xds] [cds-lb 0xc000616000] Created (t=+3.069008ms)
tlogger.go:133: INFO cdsbalancer.go:121 [xds] [cds-lb 0xc000616000] xDS credentials in use: false (t=+3.076933ms)
tlogger.go:133: INFO cdsbalancer.go:287 [xds] [cds-lb 0xc000616000] Received balancer config update: {
"LoadBalancingConfig": null,
"cluster": "cluster-my-service-client-side-xds",
"isDynamic": false
} (t=+3.087593ms)
tlogger.go:133: INFO balancer.go:75 [xds] [priority-lb 0xc00022ddc0] Created (t=+3.123149ms)
tlogger.go:133: INFO balancergroup.go:510 [xds] [xds-cluster-manager-lb 0xc0005411a0] Balancer state update from child cluster:cluster-my-service-client-side-xds, new state: {ConnectivityState:CONNECTING Picker:0xc00015f520} (t=+3.249335ms)
tlogger.go:133: INFO balancerstateaggregator.go:147 [xds] [xds-cluster-manager-lb 0xc0005411a0] State update from sub-balancer "cluster:cluster-my-service-client-side-xds": {ConnectivityState:CONNECTING Picker:0xc00015f520} (t=+3.259524ms)
tlogger.go:133: INFO balancergroup.go:274 [xds] [priority-lb 0xc00022ddc0] Adding child policy of type "outlier_detection_experimental" for child "priority-0-0" (t=+3.275073ms)
tlogger.go:133: INFO balancergroup.go:102 [xds] [priority-lb 0xc00022ddc0] Creating child policy of type "outlier_detection_experimental" for child "priority-0-0" (t=+3.283078ms)
tlogger.go:133: INFO balancer.go:94 [xds] [outlier-detection-lb 0xc0006204b0] Created (t=+3.292165ms)
tlogger.go:133: INFO clusterimpl.go:79 [xds] [xds-cluster-impl-lb 0xc0001f2600] Created (t=+3.334854ms)
tlogger.go:133: INFO weightedtarget.go:65 [xds] [weighted-target-lb 0xc000541620] Created (t=+3.374368ms)
tlogger.go:133: INFO balancer.go:88 [xds] [wrrlocality-lb 0xc0004a2390] Created (t=+3.383826ms)
tlogger.go:133: INFO balancergroup.go:274 [xds] [weighted-target-lb 0xc000541620] Adding child policy of type "round_robin" for child "{region=\"region-1\", zone=\"zone-1\", sub_zone=\"subzone-1\"}" (t=+3.409554ms)
tlogger.go:133: INFO balancergroup.go:102 [xds] [weighted-target-lb 0xc000541620] Creating child policy of type "round_robin" for child "{region=\"region-1\", zone=\"zone-1\", sub_zone=\"subzone-1\"}" (t=+3.42352ms)
tlogger.go:133: INFO roundrobin.go:56 [roundrobin] [0xc0004a29c0] Created (t=+3.43415ms)
tlogger.go:133: INFO clientconn.go:921 [core] [Channel #662 SubChannel #667] Subchannel created (t=+3.460279ms)
tlogger.go:133: INFO balancergroup.go:510 [xds] [weighted-target-lb 0xc000541620] Balancer state update from child {region="region-1", zone="zone-1", sub_zone="subzone-1"}, new state: {ConnectivityState:CONNECTING Picker:0xc0005d4ec0} (t=+3.490144ms)
tlogger.go:133: INFO aggregator.go:253 [xds] [weighted-target-lb 0xc000541620] Child pickers with config: map[{region="region-1", zone="zone-1", sub_zone="subzone-1"}:weight:1,picker:0xc0005d4ec0,state:CONNECTING,stateToAggregate:CONNECTING] (t=+3.510332ms)
tlogger.go:133: INFO balancergroup.go:510 [xds] [priority-lb 0xc00022ddc0] Balancer state update from child priority-0-0, new state: {ConnectivityState:CONNECTING Picker:0xc000824ee8} (t=+3.527765ms)
tlogger.go:133: INFO balancergroup.go:510 [xds] [xds-cluster-manager-lb 0xc0005411a0] Balancer state update from child cluster:cluster-my-service-client-side-xds, new state: {ConnectivityState:CONNECTING Picker:0xc000824ee8} (t=+3.55758ms)
tlogger.go:133: INFO balancerstateaggregator.go:147 [xds] [xds-cluster-manager-lb 0xc0005411a0] State update from sub-balancer "cluster:cluster-my-service-client-side-xds": {ConnectivityState:CONNECTING Picker:0xc000824ee8} (t=+3.572148ms)
tlogger.go:133: INFO balancerstateaggregator.go:191 [xds] [xds-cluster-manager-lb 0xc0005411a0] Child pickers: map[cluster:cluster-my-service-client-side-xds:picker:0xc000824ee8,state:CONNECTING,stateToAggregate:CONNECTING] (t=+3.587176ms)
tlogger.go:133: INFO clientconn.go:1295 [core] [Channel #662 SubChannel #667] Subchannel Connectivity change to CONNECTING (t=+3.609547ms)
tlogger.go:133: INFO clientconn.go:1463 [core] [Channel #662 SubChannel #667] Subchannel picks a new address "localhost:39835" to connect (t=+3.619095ms)
tlogger.go:133: INFO clientconn.go:1295 [core] [Channel #662 SubChannel #667] Subchannel Connectivity change to READY (t=+3.964421ms)
tlogger.go:133: INFO balancergroup.go:510 [xds] [weighted-target-lb 0xc000541620] Balancer state update from child {region="region-1", zone="zone-1", sub_zone="subzone-1"}, new state: {ConnectivityState:READY Picker:0xc000604cc0} (t=+4.02262ms)
tlogger.go:133: INFO aggregator.go:253 [xds] [weighted-target-lb 0xc000541620] Child pickers with config: map[{region="region-1", zone="zone-1", sub_zone="subzone-1"}:weight:1,picker:0xc000604cc0,state:READY,stateToAggregate:READY] (t=+4.036045ms)
tlogger.go:133: INFO balancergroup.go:510 [xds] [priority-lb 0xc00022ddc0] Balancer state update from child priority-0-0, new state: {ConnectivityState:READY Picker:0xc0006f6ca8} (t=+4.050612ms)
tlogger.go:133: INFO balancergroup.go:510 [xds] [xds-cluster-manager-lb 0xc0005411a0] Balancer state update from child cluster:cluster-my-service-client-side-xds, new state: {ConnectivityState:READY Picker:0xc0006f6ca8} (t=+4.068756ms)
tlogger.go:133: INFO balancerstateaggregator.go:147 [xds] [xds-cluster-manager-lb 0xc0005411a0] State update from sub-balancer "cluster:cluster-my-service-client-side-xds": {ConnectivityState:READY Picker:0xc0006f6ca8} (t=+4.080067ms)
tlogger.go:133: INFO balancerstateaggregator.go:191 [xds] [xds-cluster-manager-lb 0xc0005411a0] Child pickers: map[cluster:cluster-my-service-client-side-xds:picker:0xc0006f6ca8,state:READY,stateToAggregate:READY] (t=+4.088222ms)
tlogger.go:133: INFO clientconn.go:618 [core] [Channel #662] Channel Connectivity change to READY (t=+4.107689ms)
server.go:229: Created new resource snapshot...
logging.go:30: setting snapshot for node 3abec332-5dab-43e1-97c5-a4307d7b83a1
logging.go:30: respond open watch 1 type.googleapis.com/envoy.config.listener.v3.Listener [listener-my-service-client-side-xds] with new version "2"
logging.go:30: respond type.googleapis.com/envoy.config.listener.v3.Listener (requested [listener-my-service-client-side-xds]) version "1" with version "2" and resources [listener-my-service-client-side-xds]
logging.go:30: respond open watch 2 type.googleapis.com/envoy.config.route.v3.RouteConfiguration [route-my-service-client-side-xds] with new version "2"
logging.go:30: respond type.googleapis.com/envoy.config.route.v3.RouteConfiguration (requested [route-my-service-client-side-xds]) version "1" with version "2" and resources [route-my-service-client-side-xds]
logging.go:30: respond open watch 3 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 (requested [cluster-my-service-client-side-xds]) version "1" with version "2" and resources [cluster-my-service-client-side-xds]
server.go:235: Updated snapshot cache with resource snapshot...
logging.go:30: respond type.googleapis.com/envoy.config.endpoint.v3.ClusterLoadAssignment (requested [endpoints-my-service-client-side-xds]) version "1" with version "2" and resources [endpoints-my-service-client-side-xds]
logging.go:30: open watch 4 for type.googleapis.com/envoy.config.route.v3.RouteConfiguration map[route-my-service-client-side-xds:{}] from nodeID "3abec332-5dab-43e1-97c5-a4307d7b83a1", version "2"
tlogger.go:129: WARNING ads_stream.go:535 [xds] [xds-client 0xc00061f050] [xds-channel 0xc0009c3e00] [ads-stream 0xc0007e6a00] ADS stream received a response for resource "endpoints-my-service-client-side-xds", but no state exists for it (t=+4.638949ms)
logging.go:30: open watch 5 for type.googleapis.com/envoy.config.cluster.v3.Cluster map[cluster-my-service-client-side-xds:{}] from nodeID "3abec332-5dab-43e1-97c5-a4307d7b83a1", version "2"
logging.go:30: respond type.googleapis.com/envoy.config.endpoint.v3.ClusterLoadAssignment (requested [cluster-my-service-client-side-xds]) version "2" with version "2" and resources [cluster-my-service-client-side-xds]
logging.go:30: respond type.googleapis.com/envoy.config.endpoint.v3.ClusterLoadAssignment (requested [cluster-my-service-client-side-xds endpoints-my-service-client-side-xds]) version "2" with version "2" and resources [cluster-my-service-client-side-xds endpoints-my-service-client-side-xds]
logging.go:30: respond type.googleapis.com/envoy.config.endpoint.v3.ClusterLoadAssignment (requested [cluster-my-service-client-side-xds]) version "2" with version "2" and resources [cluster-my-service-client-side-xds]
logging.go:30: open watch 6 for type.googleapis.com/envoy.config.listener.v3.Listener map[listener-my-service-client-side-xds:{}] from nodeID "3abec332-5dab-43e1-97c5-a4307d7b83a1", version "2"
logging.go:30: open watch 7 for type.googleapis.com/envoy.config.endpoint.v3.ClusterLoadAssignment map[cluster-my-service-client-side-xds:{}] from nodeID "3abec332-5dab-43e1-97c5-a4307d7b83a1", version "2"
tlogger.go:133: INFO resolver_wrapper.go:211 [core] [Channel #662] Resolver state updated: {
"Addresses": null,
"Endpoints": [],
"ServiceConfig": {
"Config": {
"Config": null,
"Methods": {}
},
"Err": null
},
"Attributes": {
"\u003c%!p(xdsdepmgr.xdsClusterSubscriberKey={})\u003e": "\u003c0xc0007de6c0\u003e",
"\u003c%!p(xdsclient.clientKeyType=grpc.xds.internal.client.Client)\u003e": "\u003c0xc0007ca5a0\u003e",
"\u003c%!p(resolver.csKeyType=grpc.internal.resolver.configSelector)\u003e": "\u003c0xc0008e6850\u003e",
"\u003c%!p(xdsresource.xdsConfigkey={})\u003e": "\u003c0xc0002ff580\u003e"
}
} () (t=+5.000804614s)
tlogger.go:133: INFO cdsbalancer.go:287 [xds] [cds-lb 0xc000616000] Received balancer config update: {
"LoadBalancingConfig": null,
"cluster": "cluster-my-service-client-side-xds",
"isDynamic": false
} (t=+5.000845951s)
tlogger.go:133: INFO balancergroup.go:341 [xds] [priority-lb 0xc00022ddc0] Removing child policy for child "priority-0-0" (t=+5.001010708s)
tlogger.go:133: INFO balancergroup.go:510 [xds] [xds-cluster-manager-lb 0xc0005411a0] Balancer state update from child cluster:cluster-my-service-client-side-xds, new state: {ConnectivityState:CONNECTING Picker:0xc00015f2e0} (t=+5.001041065s)
tlogger.go:133: INFO balancerstateaggregator.go:147 [xds] [xds-cluster-manager-lb 0xc0005411a0] State update from sub-balancer "cluster:cluster-my-service-client-side-xds": {ConnectivityState:CONNECTING Picker:0xc00015f2e0} (t=+5.001053118s)
tlogger.go:133: INFO balancergroup.go:274 [xds] [priority-lb 0xc00022ddc0] Adding child policy of type "outlier_detection_experimental" for child "priority-1-0" (t=+5.001073365s)
tlogger.go:133: INFO balancergroup.go:102 [xds] [priority-lb 0xc00022ddc0] Creating child policy of type "outlier_detection_experimental" for child "priority-1-0" (t=+5.001083915s)
tlogger.go:133: INFO balancer.go:94 [xds] [outlier-detection-lb 0xc0009762d0] Created (t=+5.00109763s)
tlogger.go:133: INFO clusterimpl.go:79 [xds] [xds-cluster-impl-lb 0xc0001f2100] Created (t=+5.001115965s)
tlogger.go:133: INFO weightedtarget.go:65 [xds] [weighted-target-lb 0xc0000742c0] Created (t=+5.001161991s)
tlogger.go:133: INFO balancer.go:88 [xds] [wrrlocality-lb 0xc000868180] Created (t=+5.001174514s)
tlogger.go:133: INFO balancergroup.go:274 [xds] [weighted-target-lb 0xc0000742c0] Adding child policy of type "round_robin" for child "{region=\"region-1\", zone=\"zone-1\", sub_zone=\"subzone-1\"}" (t=+5.001205682s)
tlogger.go:133: INFO balancergroup.go:102 [xds] [weighted-target-lb 0xc0000742c0] Creating child policy of type "round_robin" for child "{region=\"region-1\", zone=\"zone-1\", sub_zone=\"subzone-1\"}" (t=+5.00122592s)
tlogger.go:133: INFO roundrobin.go:56 [roundrobin] [0xc0008684b0] Created (t=+5.001239435s)
tlogger.go:133: INFO clientconn.go:921 [core] [Channel #662 SubChannel #670] Subchannel created (t=+5.001278187s)
tlogger.go:133: INFO balancergroup.go:510 [xds] [weighted-target-lb 0xc0000742c0] Balancer state update from child {region="region-1", zone="zone-1", sub_zone="subzone-1"}, new state: {ConnectivityState:CONNECTING Picker:0xc0006050c0} (t=+5.001349601s)
tlogger.go:133: INFO aggregator.go:253 [xds] [weighted-target-lb 0xc0000742c0] Child pickers with config: map[{region="region-1", zone="zone-1", sub_zone="subzone-1"}:weight:1,picker:0xc0006050c0,state:CONNECTING,stateToAggregate:CONNECTING] (t=+5.001374247s)
tlogger.go:133: INFO balancergroup.go:510 [xds] [priority-lb 0xc00022ddc0] Balancer state update from child priority-1-0, new state: {ConnectivityState:CONNECTING Picker:0xc000e85c38} (t=+5.001399173s)
tlogger.go:133: INFO balancergroup.go:510 [xds] [xds-cluster-manager-lb 0xc0005411a0] Balancer state update from child cluster:cluster-my-service-client-side-xds, new state: {ConnectivityState:CONNECTING Picker:0xc000e85c38} (t=+5.001414151s)
tlogger.go:133: INFO balancerstateaggregator.go:147 [xds] [xds-cluster-manager-lb 0xc0005411a0] State update from sub-balancer "cluster:cluster-my-service-client-side-xds": {ConnectivityState:CONNECTING Picker:0xc000e85c38} (t=+5.001430291s)
tlogger.go:133: INFO balancerstateaggregator.go:191 [xds] [xds-cluster-manager-lb 0xc0005411a0] Child pickers: map[cluster:cluster-my-service-client-side-xds:picker:0xc000e85c38,state:CONNECTING,stateToAggregate:CONNECTING] (t=+5.001447684s)
tlogger.go:133: INFO clientconn.go:618 [core] [Channel #662] Channel Connectivity change to CONNECTING (t=+5.001472781s)
tlogger.go:133: INFO clientconn.go:1295 [core] [Channel #662 SubChannel #670] Subchannel Connectivity change to CONNECTING (t=+5.001484573s)
tlogger.go:133: INFO clientconn.go:1463 [core] [Channel #662 SubChannel #670] Subchannel picks a new address "localhost:36025" to connect (t=+5.001495593s)
tlogger.go:133: INFO clientconn.go:1295 [core] [Channel #662 SubChannel #670] Subchannel Connectivity change to READY (t=+5.002023966s)
tlogger.go:133: INFO balancergroup.go:510 [xds] [weighted-target-lb 0xc0000742c0] Balancer state update from child {region="region-1", zone="zone-1", sub_zone="subzone-1"}, new state: {ConnectivityState:READY Picker:0xc0006052c0} (t=+5.0020906s)
tlogger.go:133: INFO aggregator.go:253 [xds] [weighted-target-lb 0xc0000742c0] Child pickers with config: map[{region="region-1", zone="zone-1", sub_zone="subzone-1"}:weight:1,picker:0xc0006052c0,state:READY,stateToAggregate:READY] (t=+5.002110788s)
tlogger.go:133: INFO balancergroup.go:510 [xds] [priority-lb 0xc00022ddc0] Balancer state update from child priority-1-0, new state: {ConnectivityState:READY Picker:0xc000e85da0} (t=+5.002126177s)
tlogger.go:133: INFO balancergroup.go:510 [xds] [xds-cluster-manager-lb 0xc0005411a0] Balancer state update from child cluster:cluster-my-service-client-side-xds, new state: {ConnectivityState:READY Picker:0xc000e85da0} (t=+5.002147056s)
tlogger.go:133: INFO balancerstateaggregator.go:147 [xds] [xds-cluster-manager-lb 0xc0005411a0] State update from sub-balancer "cluster:cluster-my-service-client-side-xds": {ConnectivityState:READY Picker:0xc000e85da0} (t=+5.002160881s)
tlogger.go:133: INFO balancerstateaggregator.go:191 [xds] [xds-cluster-manager-lb 0xc0005411a0] Child pickers: map[cluster:cluster-my-service-client-side-xds:picker:0xc000e85da0,state:READY,stateToAggregate:READY] (t=+5.002170399s)
tlogger.go:133: INFO clientconn.go:618 [core] [Channel #662] Channel Connectivity change to READY (t=+5.002182492s)
eds_impl_test.go:742: Timeout when waiting for EmptyCall() to be routed to correct backend "127.0.0.1:36025"
tlogger.go:133: INFO clientconn.go:618 [core] [Channel #662] Channel Connectivity change to SHUTDOWN (t=+5.008186381s)
tlogger.go:133: INFO resolver_wrapper.go:112 [core] [Channel #662] Closing the name resolver (t=+5.008200307s)
tlogger.go:133: INFO balancer_wrapper.go:159 [core] [Channel #662] ccBalancerWrapper: closing (t=+5.0082183s)
tlogger.go:133: INFO clusterimpl.go:360 [xds] [xds-cluster-impl-lb 0xc0001f2600] Shutdown (t=+5.008251161s)
tlogger.go:133: INFO clusterimpl.go:360 [xds] [xds-cluster-impl-lb 0xc0001f2100] Shutdown (t=+5.008278953s)
tlogger.go:133: INFO balancergroup.go:341 [xds] [priority-lb 0xc00022ddc0] Removing child policy for child "priority-1-0" (t=+5.008314109s)
tlogger.go:133: INFO cdsbalancer.go:557 [xds] [cds-lb 0xc000616000] Shutdown (t=+5.008330299s)
tlogger.go:133: INFO clustermanager.go:192 [xds] [xds-cluster-manager-lb 0xc0005411a0] Shutdown (t=+5.008344726s)
tlogger.go:129: WARNING ads_stream.go:402 [xds] [xds-client 0xc00061f050] [xds-channel 0xc0009c3e00] [ads-stream 0xc0007e6a00] Sending ADS request for type "type.googleapis.com/envoy.config.endpoint.v3.ClusterLoadAssignment", resources: [], version: "2", nonce: "9" failed: EOF (t=+5.008367659s)
tlogger.go:129: WARNING ads_stream.go:441 [xds] [xds-client 0xc00061f050] [xds-channel 0xc0009c3e00] [ads-stream 0xc0007e6a00] ADS stream closed: rpc error: code = Canceled desc = context canceled (t=+5.008390361s)
tlogger.go:133: INFO ads_stream.go:160 [xds] [xds-client 0xc00061f050] [xds-channel 0xc0009c3e00] [ads-stream 0xc0007e6a00] Shutdown ADS stream (t=+5.00841123s)
tlogger.go:133: INFO clientconn.go:618 [core] [Channel #663] Channel Connectivity change to SHUTDOWN (t=+5.008441056s)
tlogger.go:133: INFO resolver_wrapper.go:112 [core] [Channel #663] Closing the name resolver (t=+5.008451085s)
tlogger.go:133: INFO balancer_wrapper.go:159 [core] [Channel #663] ccBalancerWrapper: closing (t=+5.008468708s)
logging.go:30: open watch 8 for type.googleapis.com/envoy.config.listener.v3.Listener map[] from nodeID "3abec332-5dab-43e1-97c5-a4307d7b83a1", version "2"
tlogger.go:133: INFO clientconn.go:1295 [core] [Channel #663 SubChannel #664] Subchannel Connectivity change to SHUTDOWN (t=+5.008522845s)
tlogger.go:133: INFO clientconn.go:1672 [core] [Channel #663 SubChannel #664] Subchannel deleted (t=+5.008537703s)
tlogger.go:133: INFO clientconn.go:1230 [core] [Channel #663] Channel deleted (t=+5.008644162s)
tlogger.go:133: INFO channel.go:142 [xds] [xds-client 0xc00061f050] [xds-channel 0xc0009c3e00] Shutdown (t=+5.008671222s)
tlogger.go:133: INFO xdsclient.go:200 [xds] [xds-client 0xc00061f050] Shutdown (t=+5.008694345s)
tlogger.go:133: INFO xds_resolver.go:281 [xds] [xds-resolver 0xc00061f0e0] Shutdown (t=+5.008710836s)
tlogger.go:133: INFO clientconn.go:1295 [core] [Channel #662 SubChannel #670] Subchannel Connectivity change to SHUTDOWN (t=+5.008740722s)
tlogger.go:133: INFO clientconn.go:1672 [core] [Channel #662 SubChannel #670] Subchannel deleted (t=+5.008755039s)
tlogger.go:133: INFO clientconn.go:1295 [core] [Channel #662 SubChannel #667] Subchannel Connectivity change to SHUTDOWN (t=+5.008766583s)
tlogger.go:133: INFO clientconn.go:1672 [core] [Channel #662 SubChannel #667] Subchannel deleted (t=+5.008783735s)
tlogger.go:133: INFO clientconn.go:1230 [core] [Channel #662] Channel deleted (t=+5.008847905s)
tlogger.go:133: INFO server.go:849 [core] [Server #658 ListenSocket #659] ListenSocket deleted (t=+5.008902657s)
tlogger.go:133: INFO server.go:849 [core] [Server #660 ListenSocket #661] ListenSocket deleted (t=+5.008943834s)
tlogger.go:133: INFO server.go:849 [core] [Server #656 ListenSocket #657] ListenSocket deleted (t=+5.008988448s)