Flaky Test : TestAggregatedClusterSuccess_SwitchBetweenLeafAndAggregate #8989
Description
This test flaked for me a couple of times.
Below are the captured logs:
--- FAIL: Test (6.27s)
--- FAIL: Test/AggregatedClusterSuccess_SwitchBetweenLeafAndAggregate (5.06s)
aggregate_cluster_test.go:334: Created new snapshot cache...
tlogger.go:133: INFO server.go:721 [core] [Server #59] Server created (t=+305.424µs)
aggregate_cluster_test.go:334: Registered Aggregated Discovery Service (ADS)...
aggregate_cluster_test.go:334: xDS management server serving at: 127.0.0.1:38339...
tlogger.go:133: INFO clientconn.go:1834 [core] original dial target is: "xds:///test.service" (t=+966.956µs)
tlogger.go:133: INFO clientconn.go:518 [core] [Channel #60] Channel created for target "xds:///test.service" (t=+994.437µs)
tlogger.go:133: INFO clientconn.go:249 [core] [Channel #60] parsed dial target is: resolver.Target{URL:url.URL{Scheme:"xds", Opaque:"", User:(*url.Userinfo)(nil), Host:"", Path:"/test.service", RawPath:"", OmitHost:false, ForceQuery:false, RawQuery:"", Fragment:"", RawFragment:""}} (t=+1.066083ms)
tlogger.go:133: INFO clientconn.go:250 [core] [Channel #60] Channel authority set to "test.service" (t=+1.078862ms)
tlogger.go:133: INFO clientconn.go:622 [core] [Channel #60] Channel Connectivity change to CONNECTING (t=+1.104059ms)
tlogger.go:133: INFO server.go:917 [core] [Server #59 ListenSocket #61] ListenSocket created (t=+1.568789ms)
tlogger.go:133: INFO pool.go:309 [xds] xDS node ID: 78e5fdcb-22b1-49fa-a3ce-52b704fcec69 (t=+1.711331ms)
tlogger.go:133: INFO xds_resolver.go:157 [xds] [xds-resolver 0xc000473050] Creating resolver for target: xds:///test.service (t=+1.726774ms)
tlogger.go:133: INFO clientconn.go:1834 [core] original dial target is: "passthrough:///127.0.0.1:38339" (t=+1.884568ms)
tlogger.go:133: INFO clientconn.go:518 [core] [Channel #62] Channel created for target "passthrough:///127.0.0.1:38339" (t=+1.902375ms)
tlogger.go:133: INFO clientconn.go:249 [core] [Channel #62] parsed dial target is: resolver.Target{URL:url.URL{Scheme:"passthrough", Opaque:"", User:(*url.Userinfo)(nil), Host:"", Path:"/127.0.0.1:38339", RawPath:"", OmitHost:false, ForceQuery:false, RawQuery:"", Fragment:"", RawFragment:""}} (t=+1.917898ms)
tlogger.go:133: INFO clientconn.go:250 [core] [Channel #62] Channel authority set to "127.0.0.1:38339" (t=+1.929044ms)
tlogger.go:133: INFO clientconn.go:423 [core] [Channel #60] Channel exiting idle mode (t=+1.95979ms)
server.go:229: Created new resource snapshot...
logging.go:30: setting snapshot for node 78e5fdcb-22b1-49fa-a3ce-52b704fcec69
server.go:235: Updated snapshot cache with resource snapshot...
tlogger.go:133: INFO clientconn.go:622 [core] [Channel #62] Channel Connectivity change to CONNECTING (t=+2.482997ms)
tlogger.go:133: INFO resolver_wrapper.go:211 [core] [Channel #62] Resolver state updated: {
"Addresses": [
{
"Addr": "127.0.0.1:38339",
"ServerName": "",
"Attributes": null,
"BalancerAttributes": null,
"Metadata": null
}
],
"Endpoints": [
{
"Addresses": [
{
"Addr": "127.0.0.1:38339",
"ServerName": "",
"Attributes": null,
"BalancerAttributes": null,
"Metadata": null
}
],
"Attributes": null
}
],
tlogger.go:133: INFO balancergroup.go:510 [xds] [weighted-target-lb 0xc0006089e0] Balancer state update from child {region="region-1", zone="zone-1", sub_zone="subzone-1"}, new state: {ConnectivityState:TRANSIENT_FAILURE Picker:0xc0004f24c0} (t=+1.006983266s)
tlogger.go:133: INFO aggregator.go:253 [xds] [weighted-target-lb 0xc0006089e0] Child pickers with config: map[{region="region-1", zone="zone-1", sub_zone="subzone-1"}:weight:1,picker:0xc0004f24c0,state:TRANSIENT_FAILURE,stateToAggregate:TRANSIENT_FAILURE] (t=+1.007023075s)
tlogger.go:133: INFO balancergroup.go:510 [xds] [priority-lb 0xc00025cb60] Balancer state update from child priority-0-0, new state: {ConnectivityState:TRANSIENT_FAILURE Picker:0xc0006488b8} (t=+1.007050967s)
tlogger.go:133: INFO balancergroup.go:510 [xds] [xds-cluster-manager-lb 0xc000608420] Balancer state update from child cluster:cluster1, new state: {ConnectivityState:TRANSIENT_FAILURE Picker:0xc0006488b8} (t=+1.007069334s)
tlogger.go:133: INFO balancerstateaggregator.go:147 [xds] [xds-cluster-manager-lb 0xc000608420] State update from sub-balancer "cluster:cluster1": {ConnectivityState:TRANSIENT_FAILURE Picker:0xc0006488b8} (t=+1.007081592s)
tlogger.go:133: INFO balancerstateaggregator.go:191 [xds] [xds-cluster-manager-lb 0xc000608420] Child pickers: map[cluster:cluster1:picker:0xc0006488b8,state:TRANSIENT_FAILURE,stateToAggregate:TRANSIENT_FAILURE] (t=+1.007093139s)
tlogger.go:133: INFO clientconn.go:1307 [core] [Channel #60 SubChannel #66] Subchannel Connectivity change to IDLE, last error: connection error: desc = "transport: Error while dialing: dial tcp [::1]:8080: connect: connection refused" (t=+2.857052693s)
tlogger.go:133: INFO clientconn.go:1305 [core] [Channel #60 SubChannel #66] Subchannel Connectivity change to CONNECTING (t=+2.857123689s)
tlogger.go:133: INFO clientconn.go:1473 [core] [Channel #60 SubChannel #66] Subchannel picks a new address "localhost:8080" to connect (t=+2.857139272s)
tlogger.go:129: WARNING clientconn.go:1536 [core] [Channel #60 SubChannel #66] grpc: addrConn.createTransport failed to connect to {Addr: "localhost:8080", ServerName: "test.service", Attributes: {"<%!p(xds.handshakeAttrKey={})>": "<0xc0004ec2f0>" , "<%!p(xds.handshakeClusterNameKey={})>": "cluster1" }, BalancerAttributes: {"<%!p(weight.attributeKey={})>": "Weight: 2147483648" , "<%!p(wrrlocality.attributeKey={})>": "Locality Weight: 1" , "<%!p(xds.localityKeyType=grpc.xds.internal.address.locality)>": "<%!p(clients.Locality={region-1 zone-1 subzone-1})>" , "<%!p(hierarchy.pathKeyType=grpc.internal.address.hierarchical_path)>": "<0xc0006085c0>" }}. Err: connection error: desc = "transport: Error while dialing: dial tcp [::1]:8080: connect: connection refused" (t=+2.857519366s)
tlogger.go:133: INFO clientconn.go:1307 [core] [Channel #60 SubChannel #66] Subchannel Connectivity change to TRANSIENT_FAILURE, last error: connection error: desc = "transport: Error while dialing: dial tcp [::1]:8080: connect: connection refused" (t=+2.857539636s)
tlogger.go:133: INFO balancergroup.go:510 [xds] [weighted-target-lb 0xc0006089e0] Balancer state update from child {region="region-1", zone="zone-1", sub_zone="subzone-1"}, new state: {ConnectivityState:TRANSIENT_FAILURE Picker:0xc0004f2640} (t=+2.857564683s)
tlogger.go:133: INFO aggregator.go:253 [xds] [weighted-target-lb 0xc0006089e0] Child pickers with config: map[{region="region-1", zone="zone-1", sub_zone="subzone-1"}:weight:1,picker:0xc0004f2640,state:TRANSIENT_FAILURE,stateToAggregate:TRANSIENT_FAILURE] (t=+2.85760263s)
tlogger.go:133: INFO balancergroup.go:510 [xds] [priority-lb 0xc00025cb60] Balancer state update from child priority-0-0, new state: {ConnectivityState:TRANSIENT_FAILURE Picker:0xc0006489c0} (t=+2.857620626s)
tlogger.go:133: INFO balancergroup.go:510 [xds] [xds-cluster-manager-lb 0xc000608420] Balancer state update from child cluster:cluster1, new state: {ConnectivityState:TRANSIENT_FAILURE Picker:0xc0006489c0} (t=+2.857631803s)
tlogger.go:133: INFO balancerstateaggregator.go:147 [xds] [xds-cluster-manager-lb 0xc000608420] State update from sub-balancer "cluster:cluster1": {ConnectivityState:TRANSIENT_FAILURE Picker:0xc0006489c0} (t=+2.85764326s)
tlogger.go:133: INFO balancerstateaggregator.go:191 [xds] [xds-cluster-manager-lb 0xc000608420] Child pickers: map[cluster:cluster1:picker:0xc0006489c0,state:TRANSIENT_FAILURE,stateToAggregate:TRANSIENT_FAILURE] (t=+2.857652474s)
aggregate_cluster_test.go:389: timeout when waiting for child policy to receive its configuration
tlogger.go:133: INFO clientconn.go:622 [core] [Channel #60] Channel Connectivity change to SHUTDOWN (t=+5.003518269s)
tlogger.go:133: INFO resolver_wrapper.go:112 [core] [Channel #60] Closing the name resolver (t=+5.003542275s)
tlogger.go:133: INFO balancer_wrapper.go:159 [core] [Channel #60] ccBalancerWrapper: closing (t=+5.003569215s)
tlogger.go:133: INFO clusterimpl.go:498 [xds] [xds-cluster-impl-lb 0xc0004ec280] Shutdown (t=+5.003686198s)
tlogger.go:133: INFO balancergroup.go:341 [xds] [priority-lb 0xc00025cb60] Removing child policy for child "priority-0-0" (t=+5.00371448s)
tlogger.go:133: INFO cdsbalancer.go:416 [xds] [cds-lb 0xc0005ec700] Shutdown (t=+5.003732186s)
tlogger.go:133: INFO clustermanager.go:192 [xds] [xds-cluster-manager-lb 0xc000608420] Shutdown (t=+5.003746307s)
tlogger.go:129: WARNING ads_stream.go:402 [xds] [xds-client 0xc000472fc0] [xds-channel 0xc000ca06e0] [ads-stream 0xc0001ffa40] Sending ADS request for type "type.googleapis.com/envoy.config.listener.v3.Listener", resources: [], version: "2", nonce: "5" failed: EOF (t=+5.003776723s)
tlogger.go:129: WARNING ads_stream.go:441 [xds] [xds-client 0xc000472fc0] [xds-channel 0xc000ca06e0] [ads-stream 0xc0001ffa40] ADS stream closed: rpc error: code = Canceled desc = context canceled (t=+5.00380209s)
tlogger.go:133: INFO ads_stream.go:160 [xds] [xds-client 0xc000472fc0] [xds-channel 0xc000ca06e0] [ads-stream 0xc0001ffa40] Shutdown ADS stream (t=+5.003820828s)
tlogger.go:133: INFO clientconn.go:622 [core] [Channel #62] Channel Connectivity change to SHUTDOWN (t=+5.003837352s)
tlogger.go:133: INFO resolver_wrapper.go:112 [core] [Channel #62] Closing the name resolver (t=+5.003846536s)
tlogger.go:133: INFO balancer_wrapper.go:159 [core] [Channel #62] ccBalancerWrapper: closing (t=+5.003858404s)
tlogger.go:133: INFO clientconn.go:1305 [core] [Channel #62 SubChannel #63] Subchannel Connectivity change to SHUTDOWN (t=+5.003906024s)
tlogger.go:133: INFO clientconn.go:1707 [core] [Channel #62 SubChannel #63] Subchannel deleted (t=+5.003917552s)
tlogger.go:133: INFO clientconn.go:1234 [core] [Channel #62] Channel deleted (t=+5.004018331s)
tlogger.go:133: INFO channel.go:143 [xds] [xds-client 0xc000472fc0] [xds-channel 0xc000ca06e0] Shutdown (t=+5.004031921s)
tlogger.go:133: INFO dns_resolver.go:288 [dns] dns: A record lookup error: lookup dns_host on 127.0.0.53:53: dial udp 127.0.0.53:53: operation was canceled (t=+5.007313502s)
tlogger.go:133: INFO xdsclient.go:200 [xds] [xds-client 0xc000472fc0] Shutdown (t=+5.007339871s)
tlogger.go:133: INFO xds_resolver.go:295 [xds] [xds-resolver 0xc000473050] Shutdown (t=+5.007353471s)
tlogger.go:133: INFO clientconn.go:1305 [core] [Channel #60 SubChannel #66] Subchannel Connectivity change to SHUTDOWN (t=+5.007374092s)
tlogger.go:133: INFO clientconn.go:1707 [core] [Channel #60 SubChannel #66] Subchannel deleted (t=+5.007384948s)
tlogger.go:133: INFO clientconn.go:1234 [core] [Channel #60] Channel deleted (t=+5.007392579s)
tlogger.go:133: INFO server.go:853 [core] [Server #59 ListenSocket #61] ListenSocket deleted (t=+5.007436044s)
FAIL