grpc-go
grpc-go copied to clipboard
Published
17 hours ago
•
grpc
grpc
Flaky test: Test/EDS_OneLocality in xds/internal/balancer/clusterresolver
Data race detected: https://github.com/grpc/grpc-go/pull/4549/checks?check_run_id=2844066083#step:8:175
Test log:
--- FAIL: Test (5.54s)
--- FAIL: Test/EDS_OneLocality (1.08s)
tlogger.go:116: INFO clusterresolver.go:81 [xds] [xds-cluster-resolver-lb 0xc000457a40] Created (t=+82.105µs)
tlogger.go:116: INFO clusterresolver.go:159 [xds] [xds-cluster-resolver-lb 0xc000457a40] Receive update from resolver, balancer config: {
"discoveryMechanisms": [
{
"cluster": "test-cluster-name",
"outlierDetection": {}
}
]
} (t=+312.12µs)
tlogger.go:116: INFO resource_resolver.go:257 [xds] [xds-cluster-resolver-lb 0xc000457a40] EDS watch started on test-cluster-name (t=+378.724µs)
tlogger.go:116: INFO clusterresolver.go:191 [xds] [xds-cluster-resolver-lb 0xc000457a40] resource update: [
{}
] (t=+474.93µs)
tlogger.go:116: INFO balancer.go:66 [xds] [priority-lb 0xc0004468c0] Created (t=+615.539µs)
tlogger.go:116: INFO configbuilder.go:311 [xds] xds lb policy is "round_robin", building config with weighted_target + round_robin (t=+687.144µs)
tlogger.go:116: INFO clusterresolver.go:223 [xds] [xds-cluster-resolver-lb 0xc000457a40] build balancer config: {
"children": {
"priority-0-0": {
"config": [
{
"xds_cluster_impl_experimental": {
"cluster": "test-cluster-name",
"childPolicy": [
{
"weighted_target_experimental": {
"targets": {
"{\"subZone\":\"I\"}": {
"weight": 1,
"childPolicy": [
{
"round_robin": {}
}
]
}
}
}
}
]
}
}
],
"ignoreReresolutionRequests": true
}
},
"priorities": [
"priority-0-0"
]
} (t=+1.780813ms)
tlogger.go:116: INFO balancer.go:108 [xds] [priority-lb 0xc0004468c0] Received update from resolver, balancer config: {
"children": {
"priority-0-0": {
"config": [
{
"xds_cluster_impl_experimental": {
"cluster": "test-cluster-name",
"childPolicy": [
{
"weighted_target_experimental": {
"targets": {
"{\"subZone\":\"I\"}": {
"weight": 1,
"childPolicy": [
{
"round_robin": {}
}
]
}
}
}
}
]
}
}
],
"ignoreReresolutionRequests": true
}
},
"priorities": [
"priority-0-0"
]
} (t=+2.177538ms)
tlogger.go:116: WARNING balancer_priority.go:87 [xds] ciu, cn, cu: , priority-0-0, (t=+2.319747ms)
balancer.go:147: testClientConn: UpdateState({CONNECTING 0xc0004feab0})
tlogger.go:116: INFO balancer_priority.go:92 [xds] [priority-lb 0xc0004468c0] switching to ("priority-0-0", 0) in syncPriority (t=+2.418953ms)
tlogger.go:116: INFO balancergroup.go:100 [xds] [priority-lb 0xc0004468c0] Creating child policy of type xds_cluster_impl_experimental (t=+2.472956ms)
tlogger.go:116: INFO clusterimpl.go:73 [xds] [xds-cluster-impl-lb 0xc00019ab40] Created (t=+2.601064ms)
tlogger.go:116: INFO clusterimpl.go:224 [xds] [xds-cluster-impl-lb 0xc00019ab40] Received update from resolver, balancer config: {
"cluster": "test-cluster-name",
"childPolicy": [
{
"weighted_target_experimental": {
"targets": {
"{\"subZone\":\"I\"}": {
"weight": 1,
"childPolicy": [
{
"round_robin": {}
}
]
}
}
}
}
]
} (t=+2.85488ms)
tlogger.go:116: INFO weightedtarget.go:59 [xds] [weighted-target-lb 0xc000518aa0] Created (t=+2.963[387](https://github.com/grpc/grpc-go/runs/7046249753?check_suite_focus=true#step:8:388)ms)
tlogger.go:116: INFO weightedtarget.go:84 [xds] [weighted-target-lb 0xc000518aa0] Received update from resolver, balancer config: {
"targets": {
"{\"subZone\":\"I\"}": {
"weight": 1,
"childPolicy": [
{
"round_robin": {}
}
]
}
}
} (t=+3.093896ms)
tlogger.go:116: INFO balancergroup.go:100 [xds] [weighted-target-lb 0xc000518aa0] Creating child policy of type round_robin (t=+3.1606ms)
balancer.go:113: testClientConn: NewSubConn([{
"Addr": "0.0.0.0:0",
"ServerName": "",
"Attributes": {},
"BalancerAttributes": {},
"Type": 0,
"Metadata": null
}], {CredsBundle:<nil> HealthCheckEnabled:true}) => sc0
tlogger.go:116: INFO roundrobin.go:50 [roundrobin] roundrobinPicker: Build called with info: {map[]} (t=+3.387614ms)
tlogger.go:116: INFO balancergroup.go:499 [xds] [weighted-target-lb 0xc000518aa0] Balancer state update from locality {"subZone":"I"}, new state: {ConnectivityState:CONNECTING Picker:0xc0004ff110} (t=+3.440417ms)
tlogger.go:116: INFO aggregator.go:201 [xds] [weighted-target-lb 0xc000518aa0] Child pickers with config: map[{"subZone":"I"}:weight:1,picker:0xc0004ff110,state:CONNECTING,stateToAggregate:CONNECTING] (t=+3.511322ms)
tlogger.go:116: INFO balancergroup.go:499 [xds] [priority-lb 0xc0004468c0] Balancer state update from locality priority-0-0, new state: {ConnectivityState:CONNECTING Picker:0xc00003cb90} (t=+3.655031ms)
tlogger.go:116: INFO balancergroup.go:499 [xds] [weighted-target-lb 0xc000518aa0] Balancer state update from locality {"subZone":"I"}, new state: {ConnectivityState:CONNECTING Picker:0xc0004ff110} (t=+3.728936ms)
tlogger.go:116: INFO aggregator.go:201 [xds] [weighted-target-lb 0xc000518aa0] Child pickers with config: map[{"subZone":"I"}:weight:1,picker:0xc0004ff110,state:CONNECTING,stateToAggregate:CONNECTING] (t=+3.79124ms)
tlogger.go:116: INFO balancergroup.go:499 [xds] [priority-lb 0xc0004468c0] Balancer state update from locality priority-0-0, new state: {ConnectivityState:CONNECTING Picker:0xc000100370} (t=+3.946649ms)
tlogger.go:116: WARNING balancer_priority.go:87 [xds] ciu, cn, cu: priority-0-0, priority-0-0, priority-0-0 (t=+4.025554ms)
balancer.go:147: testClientConn: UpdateState({CONNECTING 0xc00003cb90})
tlogger.go:116: INFO balancer_priority.go:92 [xds] [priority-lb 0xc0004468c0] switching to ("priority-0-0", 0) in syncPriority (t=+4.149062ms)
tlogger.go:116: WARNING balancer_priority.go:87 [xds] ciu, cn, cu: priority-0-0, priority-0-0, priority-0-0 (t=+4.249768ms)
balancer.go:147: testClientConn: UpdateState({CONNECTING 0xc000100370})
tlogger.go:116: INFO balancer_priority.go:92 [xds] [priority-lb 0xc0004468c0] switching to ("priority-0-0", 0) in syncPriority (t=+4.338374ms)
tlogger.go:116: INFO roundrobin.go:50 [roundrobin] roundrobinPicker: Build called with info: {map[0xc000518c20:{{
"Addr": "0.0.0.0:0",
"ServerName": "",
"Attributes": null,
"BalancerAttributes": {},
"Type": 0,
"Metadata": null
}}]} (t=+7.016843ms)
tlogger.go:116: INFO balancergroup.go:499 [xds] [weighted-target-lb 0xc000518aa0] Balancer state update from locality {"subZone":"I"}, new state: {ConnectivityState:READY Picker:0xc000591860} (t=+7.111349ms)
tlogger.go:116: INFO aggregator.go:201 [xds] [weighted-target-lb 0xc000518aa0] Child pickers with config: map[{"subZone":"I"}:weight:1,picker:0xc000591860,state:READY,stateToAggregate:READY] (t=+7.187554ms)
tlogger.go:116: INFO balancergroup.go:499 [xds] [priority-lb 0xc0004468c0] Balancer state update from locality priority-0-0, new state: {ConnectivityState:READY Picker:0xc00003ccd0} (t=+7.329263ms)
tlogger.go:116: WARNING balancer_priority.go:87 [xds] ciu, cn, cu: priority-0-0, priority-0-0, priority-0-0 (t=+7.415468ms)
balancer.go:147: testClientConn: UpdateState({READY 0xc00003ccd0})
tlogger.go:116: INFO clusterresolver.go:191 [xds] [xds-cluster-resolver-lb 0xc000457a40] resource update: [
{}
] (t=+7.622781ms)
tlogger.go:116: INFO configbuilder.go:311 [xds] xds lb policy is "round_robin", building config with weighted_target + round_robin (t=+7.683485ms)
tlogger.go:116: INFO clusterresolver.go:223 [xds] [xds-cluster-resolver-lb 0xc000457a40] build balancer config: {
"children": {
"priority-0-0": {
"config": [
{
"xds_cluster_impl_experimental": {
"cluster": "test-cluster-name",
"childPolicy": [
{
"weighted_target_experimental": {
"targets": {
"{\"subZone\":\"I\"}": {
"weight": 1,
"childPolicy": [
{
"round_robin": {}
}
]
}
}
}
}
]
}
}
],
"ignoreReresolutionRequests": true
}
},
"priorities": [
"priority-0-0"
]
} (t=+8.518738ms)
tlogger.go:116: INFO balancer.go:108 [xds] [priority-lb 0xc0004468c0] Received update from resolver, balancer config: {
"children": {
"priority-0-0": {
"config": [
{
"xds_cluster_impl_experimental": {
"cluster": "test-cluster-name",
"childPolicy": [
{
"weighted_target_experimental": {
"targets": {
"{\"subZone\":\"I\"}": {
"weight": 1,
"childPolicy": [
{
"round_robin": {}
}
]
}
}
}
}
]
}
}
],
"ignoreReresolutionRequests": true
}
},
"priorities": [
"priority-0-0"
]
} (t=+8.86726ms)
tlogger.go:116: INFO balancer_priority.go:92 [xds] [priority-lb 0xc0004468c0] switching to ("priority-0-0", 0) in syncPriority (t=+8.978667ms)
tlogger.go:116: INFO clusterimpl.go:224 [xds] [xds-cluster-impl-lb 0xc00019ab40] Received update from resolver, balancer config: {
"cluster": "test-cluster-name",
"childPolicy": [
{
"weighted_target_experimental": {
"targets": {
"{\"subZone\":\"I\"}": {
"weight": 1,
"childPolicy": [
{
"round_robin": {}
}
]
}
}
}
}
]
} (t=+9.222782ms)
tlogger.go:116: INFO weightedtarget.go:84 [xds] [weighted-target-lb 0xc000518aa0] Received update from resolver, balancer config: {
"targets": {
"{\"subZone\":\"I\"}": {
"weight": 1,
"childPolicy": [
{
"round_robin": {}
}
]
}
}
} (t=+9.404394ms)
balancer.go:113: testClientConn: NewSubConn([{
"Addr": "1.1.1.1:1",
"ServerName": "",
"Attributes": {},
"BalancerAttributes": {},
"Type": 0,
"Metadata": null
}], {CredsBundle:<nil> HealthCheckEnabled:true}) => sc1
tlogger.go:116: INFO roundrobin.go:50 [roundrobin] roundrobinPicker: Build called with info: {map[0xc000518c20:{{
"Addr": "0.0.0.0:0",
"ServerName": "",
"Attributes": null,
"BalancerAttributes": {},
"Type": 0,
"Metadata": null
}}]} (t=+9.754116ms)
tlogger.go:116: INFO balancergroup.go:499 [xds] [weighted-target-lb 0xc000518aa0] Balancer state update from locality {"subZone":"I"}, new state: {ConnectivityState:READY Picker:0xc000591c50} (t=+9.82532ms)
tlogger.go:116: INFO aggregator.go:201 [xds] [weighted-target-lb 0xc000518aa0] Child pickers with config: map[{"subZone":"I"}:weight:1,picker:0xc000591c50,state:READY,stateToAggregate:READY] (t=+9.891725ms)
tlogger.go:116: INFO balancergroup.go:499 [xds] [priority-lb 0xc0004468c0] Balancer state update from locality priority-0-0, new state: {ConnectivityState:READY Picker:0xc0006d4d70} (t=+10.158641ms)
tlogger.go:116: INFO balancer_priority.go:92 [xds] [priority-lb 0xc0004468c0] switching to ("priority-0-0", 0) in syncPriority (t=+10.274949ms)
tlogger.go:116: INFO balancergroup.go:499 [xds] [weighted-target-lb 0xc000518aa0] Balancer state update from locality {"subZone":"I"}, new state: {ConnectivityState:READY Picker:0xc000591c50} (t=+10.369155ms)
tlogger.go:116: INFO aggregator.go:201 [xds] [weighted-target-lb 0xc000518aa0] Child pickers with config: map[{"subZone":"I"}:weight:1,picker:0xc000591c50,state:READY,stateToAggregate:READY] (t=+10.436559ms)
tlogger.go:116: INFO roundrobin.go:50 [roundrobin] roundrobinPicker: Build called with info: {map[0xc000518c20:{{
"Addr": "0.0.0.0:0",
"ServerName": "",
"Attributes": null,
"BalancerAttributes": {},
"Type": 0,
"Metadata": null
}} 0xc000519080:{{
"Addr": "1.1.1.1:1",
"ServerName": "",
"Attributes": null,
"BalancerAttributes": {},
"Type": 0,
"Metadata": null
}}]} (t=+10.640972ms)
tlogger.go:116: INFO balancergroup.go:499 [xds] [weighted-target-lb 0xc000518aa0] Balancer state update from locality {"subZone":"I"}, new state: {ConnectivityState:READY Picker:0xc0001fa210} (t=+10.721677ms)
tlogger.go:116: INFO aggregator.go:201 [xds] [weighted-target-lb 0xc000518aa0] Child pickers with config: map[{"subZone":"I"}:weight:1,picker:0xc0001fa210,state:READY,stateToAggregate:READY] (t=+10.781281ms)
tlogger.go:116: INFO balancergroup.go:499 [xds] [priority-lb 0xc0004468c0] Balancer state update from locality priority-0-0, new state: {ConnectivityState:READY Picker:0xc000100690} (t=+10.851885ms)
tlogger.go:116: INFO balancergroup.go:499 [xds] [priority-lb 0xc0004468c0] Balancer state update from locality priority-0-0, new state: {ConnectivityState:READY Picker:0xc0001006e0} (t=+10.92079ms)
tlogger.go:116: WARNING balancer_priority.go:87 [xds] ciu, cn, cu: priority-0-0, priority-0-0, priority-0-0 (t=+11.007495ms)
balancer.go:147: testClientConn: UpdateState({READY 0xc000100690})
tlogger.go:116: INFO balancer_priority.go:92 [xds] [priority-lb 0xc0004468c0] switching to ("priority-0-0", 0) in syncPriority (t=+13.696665ms)
tlogger.go:116: WARNING balancer_priority.go:87 [xds] ciu, cn, cu: priority-0-0, priority-0-0, priority-0-0 (t=+13.767269ms)
balancer.go:147: testClientConn: UpdateState({READY 0xc0001006e0})
tlogger.go:116: INFO clusterresolver.go:191 [xds] [xds-cluster-resolver-lb 0xc000457a40] resource update: [
{}
] (t=+14.004384ms)
tlogger.go:116: INFO configbuilder.go:311 [xds] xds lb policy is "round_robin", building config with weighted_target + round_robin (t=+14.059288ms)
tlogger.go:116: INFO clusterresolver.go:223 [xds] [xds-cluster-resolver-lb 0xc000457a40] build balancer config: {
"children": {
"priority-0-0": {
"config": [
{
"xds_cluster_impl_experimental": {
"cluster": "test-cluster-name",
"childPolicy": [
{
"weighted_target_experimental": {
"targets": {
"{\"subZone\":\"I\"}": {
"weight": 1,
"childPolicy": [
{
"round_robin": {}
}
]
}
}
}
}
]
}
}
],
"ignoreReresolutionRequests": true
}
},
"priorities": [
"priority-0-0"
]
} (t=+14.897541ms)
tlogger.go:116: INFO balancer.go:108 [xds] [priority-lb 0xc0004468c0] Received update from resolver, balancer config: {
"children": {
"priority-0-0": {
"config": [
{
"xds_cluster_impl_experimental": {
"cluster": "test-cluster-name",
"childPolicy": [
{
"weighted_target_experimental": {
"targets": {
"{\"subZone\":\"I\"}": {
"weight": 1,
"childPolicy": [
{
"round_robin": {}
}
]
}
}
}
}
]
}
}
],
"ignoreReresolutionRequests": true
}
},
"priorities": [
"priority-0-0"
]
} (t=+15.224261ms)
tlogger.go:116: INFO balancer_priority.go:92 [xds] [priority-lb 0xc0004468c0] switching to ("priority-0-0", 0) in syncPriority (t=+15.342769ms)
tlogger.go:116: INFO clusterimpl.go:224 [xds] [xds-cluster-impl-lb 0xc00019ab40] Received update from resolver, balancer config: {
"cluster": "test-cluster-name",
"childPolicy": [
{
"weighted_target_experimental": {
"targets": {
"{\"subZone\":\"I\"}": {
"weight": 1,
"childPolicy": [
{
"round_robin": {}
}
]
}
}
}
}
]
} (t=+15.566183ms)
tlogger.go:116: INFO weightedtarget.go:84 [xds] [weighted-target-lb 0xc000518aa0] Received update from resolver, balancer config: {
"targets": {
"{\"subZone\":\"I\"}": {
"weight": 1,
"childPolicy": [
{
"round_robin": {}
}
]
}
}
} (t=+15.753495ms)
balancer.go:129: testClientConn: RemoveSubConn(sc0)
tlogger.go:116: INFO roundrobin.go:50 [roundrobin] roundrobinPicker: Build called with info: {map[0xc000519080:{{
"Addr": "1.1.1.1:1",
"ServerName": "",
"Attributes": null,
"BalancerAttributes": {},
"Type": 0,
"Metadata": null
}}]} (t=+16.745957ms)
tlogger.go:116: INFO balancergroup.go:499 [xds] [weighted-target-lb 0xc000518aa0] Balancer state update from locality {"subZone":"I"}, new state: {ConnectivityState:READY Picker:0xc0000b80f0} (t=+16.830263ms)
tlogger.go:116: INFO aggregator.go:201 [xds] [weighted-target-lb 0xc000518aa0] Child pickers with config: map[{"subZone":"I"}:weight:1,picker:0xc0000b80f0,state:READY,stateToAggregate:READY] (t=+16.908467ms)
tlogger.go:116: INFO balancergroup.go:499 [xds] [priority-lb 0xc0004468c0] Balancer state update from locality priority-0-0, new state: {ConnectivityState:READY Picker:0xc00003d0e0} (t=+20.071967ms)
tlogger.go:116: INFO balancer_priority.go:92 [xds] [priority-lb 0xc0004468c0] switching to ("priority-0-0", 0) in syncPriority (t=+20.128171ms)
tlogger.go:116: WARNING balancer_priority.go:87 [xds] ciu, cn, cu: priority-0-0, priority-0-0, priority-0-0 (t=+20.192275ms)
balancer.go:147: testClientConn: UpdateState({READY 0xc00003d0e0})
tlogger.go:116: INFO balancer_priority.go:92 [xds] [priority-lb 0xc0004468c0] switching to ("priority-0-0", 0) in syncPriority (t=+20.27528ms)
tlogger.go:116: INFO clusterresolver.go:191 [xds] [xds-cluster-resolver-lb 0xc000457a40] resource update: [
{}
] (t=+20.402688ms)
tlogger.go:116: INFO configbuilder.go:311 [xds] xds lb policy is "round_robin", building config with weighted_target + round_robin (t=+20.458192ms)
tlogger.go:116: INFO clusterresolver.go:223 [xds] [xds-cluster-resolver-lb 0xc000457a40] build balancer config: {
"children": {
"priority-0-0": {
"config": [
{
"xds_cluster_impl_experimental": {
"cluster": "test-cluster-name",
"childPolicy": [
{
"weighted_target_experimental": {
"targets": {
"{\"subZone\":\"I\"}": {
"weight": 1,
"childPolicy": [
{
"round_robin": {}
}
]
}
}
}
}
]
}
}
],
"ignoreReresolutionRequests": true
}
},
"priorities": [
"priority-0-0"
]
} (t=+21.191938ms)
tlogger.go:116: INFO balancer.go:108 [xds] [priority-lb 0xc0004468c0] Received update from resolver, balancer config: {
"children": {
"priority-0-0": {
"config": [
{
"xds_cluster_impl_experimental": {
"cluster": "test-cluster-name",
"childPolicy": [
{
"weighted_target_experimental": {
"targets": {
"{\"subZone\":\"I\"}": {
"weight": 1,
"childPolicy": [
{
"round_robin": {}
}
]
}
}
}
}
]
}
}
],
"ignoreReresolutionRequests": true
}
},
"priorities": [
"priority-0-0"
]
} (t=+22.373712ms)
tlogger.go:116: INFO clusterimpl.go:224 [xds] [xds-cluster-impl-lb 0xc00019ab40] Received update from resolver, balancer config: {
"cluster": "test-cluster-name",
"childPolicy": [
{
"weighted_target_experimental": {
"targets": {
"{\"subZone\":\"I\"}": {
"weight": 1,
"childPolicy": [
{
"round_robin": {}
}
]
}
}
}
}
]
} (t=+22.65393ms)
tlogger.go:116: INFO weightedtarget.go:84 [xds] [weighted-target-lb 0xc000518aa0] Received update from resolver, balancer config: {
"targets": {
"{\"subZone\":\"I\"}": {
"weight": 1,
"childPolicy": [
{
"round_robin": {}
}
]
}
}
} (t=+22.821541ms)
balancer.go:113: testClientConn: NewSubConn([{
"Addr": "2.2.2.2:2",
"ServerName": "",
"Attributes": {},
"BalancerAttributes": {},
"Type": 0,
"Metadata": null
}], {CredsBundle:<nil> HealthCheckEnabled:true}) => sc2
balancer.go:129: testClientConn: RemoveSubConn(sc1)
tlogger.go:116: INFO roundrobin.go:50 [roundrobin] roundrobinPicker: Build called with info: {map[]} (t=+23.066556ms)
tlogger.go:116: INFO balancergroup.go:499 [xds] [weighted-target-lb 0xc000518aa0] Balancer state update from locality {"subZone":"I"}, new state: {ConnectivityState:READY Picker:0xc0000c7fb0} (t=+23.12686ms)
tlogger.go:116: INFO aggregator.go:201 [xds] [weighted-target-lb 0xc000518aa0] Child pickers with config: map[{"subZone":"I"}:weight:1,picker:0xc0000c7fb0,state:READY,stateToAggregate:READY] (t=+23.192964ms)
tlogger.go:116: INFO balancer_priority.go:92 [xds] [priority-lb 0xc0004468c0] switching to ("priority-0-0", 0) in syncPriority (t=+24.067519ms)
tlogger.go:116: INFO balancergroup.go:499 [xds] [priority-lb 0xc0004468c0] Balancer state update from locality priority-0-0, new state: {ConnectivityState:READY Picker:0xc0006d4e60} (t=+24.71376ms)
tlogger.go:116: WARNING balancer_priority.go:87 [xds] ciu, cn, cu: priority-0-0, priority-0-0, priority-0-0 (t=+24.809366ms)
balancer.go:147: testClientConn: UpdateState({READY 0xc0006d4e60})
tlogger.go:116: INFO balancer_priority.go:92 [xds] [priority-lb 0xc0004468c0] switching to ("priority-0-0", 0) in syncPriority (t=+24.888271ms)
tlogger.go:116: INFO roundrobin.go:50 [roundrobin] roundrobinPicker: Build called with info: {map[]} (t=+24.997278ms)
tlogger.go:116: INFO balancergroup.go:499 [xds] [weighted-target-lb 0xc000518aa0] Balancer state update from locality {"subZone":"I"}, new state: {ConnectivityState:READY Picker:0xc0001135f0} (t=+25.056082ms)
tlogger.go:116: INFO aggregator.go:201 [xds] [weighted-target-lb 0xc000518aa0] Child pickers with config: map[{"subZone":"I"}:weight:1,picker:0xc0001135f0,state:READY,stateToAggregate:READY] (t=+25.115085ms)
tlogger.go:116: INFO balancergroup.go:499 [xds] [weighted-target-lb 0xc000518aa0] Balancer state update from locality {"subZone":"I"}, new state: {ConnectivityState:READY Picker:0xc0001135f0} (t=+25.18719ms)
tlogger.go:116: INFO aggregator.go:201 [xds] [weighted-target-lb 0xc000518aa0] Child pickers with config: map[{"subZone":"I"}:weight:1,picker:0xc0001135f0,state:READY,stateToAggregate:READY] (t=+25.241793ms)
tlogger.go:116: INFO roundrobin.go:50 [roundrobin] roundrobinPicker: Build called with info: {map[0xc00007f780:{{
"Addr": "2.2.2.2:2",
"ServerName": "",
"Attributes": null,
"BalancerAttributes": {},
"Type": 0,
"Metadata": null
}}]} (t=+25.361001ms)
tlogger.go:116: INFO balancergroup.go:499 [xds] [weighted-target-lb 0xc000518aa0] Balancer state update from locality {"subZone":"I"}, new state: {ConnectivityState:READY Picker:0xc0000b8840} (t=+25.427005ms)
tlogger.go:116: INFO aggregator.go:201 [xds] [weighted-target-lb 0xc000518aa0] Child pickers with config: map[{"subZone":"I"}:weight:1,picker:0xc0000b8840,state:READY,stateToAggregate:READY] (t=+25.482009ms)
tlogger.go:116: INFO roundrobin.go:50 [roundrobin] roundrobinPicker: Build called with info: {map[0xc00007f780:{{
"Addr": "2.2.2.2:2",
"ServerName": "",
"Attributes": null,
"BalancerAttributes": {},
"Type": 0,
"Metadata": null
}}]} (t=+25.599616ms)
tlogger.go:116: INFO balancergroup.go:499 [xds] [weighted-target-lb 0xc000518aa0] Balancer state update from locality {"subZone":"I"}, new state: {ConnectivityState:READY Picker:0xc0000b89f0} (t=+25.675521ms)
tlogger.go:116: INFO aggregator.go:201 [xds] [weighted-target-lb 0xc000518aa0] Child pickers with config: map[{"subZone":"I"}:weight:1,picker:0xc0000b89f0,state:READY,stateToAggregate:READY] (t=+25.81653ms)
tlogger.go:116: INFO balancergroup.go:499 [xds] [priority-lb 0xc0004468c0] Balancer state update from locality priority-0-0, new state: {ConnectivityState:READY Picker:0xc0006d4eb0} (t=+25.912436ms)
tlogger.go:116: INFO balancergroup.go:499 [xds] [priority-lb 0xc0004468c0] Balancer state update from locality priority-0-0, new state: {ConnectivityState:READY Picker:0xc0006d4f00} (t=+26.001341ms)
tlogger.go:116: WARNING balancer_priority.go:87 [xds] ciu, cn, cu: priority-0-0, priority-0-0, priority-0-0 (t=+26.090147ms)
balancer.go:147: testClientConn: UpdateState({READY 0xc0006d4eb0})
tlogger.go:116: INFO balancer_priority.go:92 [xds] [priority-lb 0xc0004468c0] switching to ("priority-0-0", 0) in syncPriority (t=+26.180353ms)
tlogger.go:116: INFO balancergroup.go:499 [xds] [priority-lb 0xc0004468c0] Balancer state update from locality priority-0-0, new state: {ConnectivityState:READY Picker:0xc0006d4f50} (t=+26.306961ms)
tlogger.go:116: WARNING balancer_priority.go:87 [xds] ciu, cn, cu: priority-0-0, priority-0-0, priority-0-0 (t=+26.402867ms)
balancer.go:147: testClientConn: UpdateState({READY 0xc0006d4f00})
tlogger.go:116: INFO balancer_priority.go:92 [xds] [priority-lb 0xc0004468c0] switching to ("priority-0-0", 0) in syncPriority (t=+26.481472ms)
tlogger.go:116: INFO balancergroup.go:499 [xds] [priority-lb 0xc0004468c0] Balancer state update from locality priority-0-0, new state: {ConnectivityState:READY Picker:0xc0006d4fa0} (t=+26.61518ms)
tlogger.go:116: WARNING balancer_priority.go:87 [xds] ciu, cn, cu: priority-0-0, priority-0-0, priority-0-0 (t=+26.897698ms)
balancer.go:147: testClientConn: UpdateState({READY 0xc0006d4f50})
tlogger.go:116: INFO clusterresolver.go:191 [xds] [xds-cluster-resolver-lb 0xc000457a40] resource update: [
{}
] (t=+27.08981ms)
tlogger.go:116: INFO configbuilder.go:311 [xds] xds lb policy is "round_robin", building config with weighted_target + round_robin (t=+27.152314ms)
tlogger.go:116: INFO clusterresolver.go:223 [xds] [xds-cluster-resolver-lb 0xc000457a40] build balancer config: {
"children": {
"priority-0-0": {
"config": [
{
"xds_cluster_impl_experimental": {
"cluster": "test-cluster-name",
"dropCategories": [
{
"Category": "test-drop",
"RequestsPerMillion": 500000
}
],
"childPolicy": [
{
"weighted_target_experimental": {
"targets": {
"{\"subZone\":\"I\"}": {
"weight": 1,
"childPolicy": [
{
"round_robin": {}
}
]
}
}
}
}
]
}
}
],
"ignoreReresolutionRequests": true
}
},
"priorities": [
"priority-0-0"
]
} (t=+28.116075ms)
tlogger.go:116: INFO balancer.go:108 [xds] [priority-lb 0xc0004468c0] Received update from resolver, balancer config: {
"children": {
"priority-0-0": {
"config": [
{
"xds_cluster_impl_experimental": {
"cluster": "test-cluster-name",
"dropCategories": [
{
"Category": "test-drop",
"RequestsPerMillion": 500000
}
],
"childPolicy": [
{
"weighted_target_experimental": {
"targets": {
"{\"subZone\":\"I\"}": {
"weight": 1,
"childPolicy": [
{
"round_robin": {}
}
]
}
}
}
}
]
}
}
],
"ignoreReresolutionRequests": true
}
},
"priorities": [
"priority-0-0"
]
} (t=+28.5109ms)
tlogger.go:116: INFO balancer_priority.go:92 [xds] [priority-lb 0xc0004468c0] switching to ("priority-0-0", 0) in syncPriority (t=+28.635508ms)
tlogger.go:116: INFO clusterimpl.go:224 [xds] [xds-cluster-impl-lb 0xc00019ab40] Received update from resolver, balancer config: {
"cluster": "test-cluster-name",
"dropCategories": [
{
"Category": "test-drop",
"RequestsPerMillion": 500000
}
],
"childPolicy": [
{
"weighted_target_experimental": {
"targets": {
"{\"subZone\":\"I\"}": {
"weight": 1,
"childPolicy": [
{
"round_robin": {}
}
]
}
}
}
}
]
} (t=+28.972429ms)
tlogger.go:116: INFO balancergroup.go:499 [xds] [priority-lb 0xc0004468c0] Balancer state update from locality priority-0-0, new state: {ConnectivityState:READY Picker:0xc00020f130} (t=+29.157741ms)
tlogger.go:116: INFO weightedtarget.go:84 [xds] [weighted-target-lb 0xc000518aa0] Received update from resolver, balancer config: {
"targets": {
"{\"subZone\":\"I\"}": {
"weight": 1,
"childPolicy": [
{
"round_robin": {}
}
]
}
}
} (t=+29.238746ms)
tlogger.go:116: INFO roundrobin.go:50 [roundrobin] roundrobinPicker: Build called with info: {map[0xc00007f780:{{
"Addr": "2.2.2.2:2",
"ServerName": "",
"Attributes": null,
"BalancerAttributes": {},
"Type": 0,
"Metadata": null
}}]} (t=+29.401556ms)
tlogger.go:116: INFO balancergroup.go:499 [xds] [weighted-target-lb 0xc000518aa0] Balancer state update from locality {"subZone":"I"}, new state: {ConnectivityState:READY Picker:0xc0004e5c20} (t=+29.476561ms)
tlogger.go:116: INFO aggregator.go:201 [xds] [weighted-target-lb 0xc000518aa0] Child pickers with config: map[{"subZone":"I"}:weight:1,picker:0xc0004e5c20,state:READY,stateToAggregate:READY] (t=+29.540465ms)
tlogger.go:116: INFO balancergroup.go:499 [xds] [priority-lb 0xc0004468c0] Balancer state update from locality priority-0-0, new state: {ConnectivityState:READY Picker:0xc00020f180} (t=+29.753578ms)
tlogger.go:116: INFO balancer_priority.go:92 [xds] [priority-lb 0xc0004468c0] switching to ("priority-0-0", 0) in syncPriority (t=+30.239909ms)
eds_impl_test.go:186: timeout waiting for picker with expected behavior, error from previous picker: <nil>
tlogger.go:116: INFO resource_resolver.go:274 [xds] [xds-cluster-resolver-lb 0xc000457a40] EDS watch canceled on test-cluster-name (t=+1.027962483s)
balancer.go:129: testClientConn: RemoveSubConn(sc2)
tlogger.go:116: INFO clusterimpl.go:336 [xds] [xds-cluster-impl-lb 0xc00019ab40] Shutdown (t=+1.028129793s)
balancer.go:129: testClientConn: RemoveSubConn(sc2)
tlogger.go:116: INFO clusterresolver.go:311 [xds] [xds-cluster-resolver-lb 0xc000457a40] Shutdown (t=+1.028217999s)
--- FAIL: Test/EDS_TwoLocalities (1.24s)
tlogger.go:116: INFO clusterresolver.go:81 [xds] [xds-cluster-resolver-lb 0xc000457880] Created (t=+98.906µs)
tlogger.go:116: INFO clusterresolver.go:159 [xds] [xds-cluster-resolver-lb 0xc000457880] Receive update from resolver, balancer config: {
"discoveryMechanisms": [
{
"cluster": "test-cluster-name",
"outlierDetection": {}
}
]
} (t=+383.224µs)
tlogger.go:116: INFO resource_resolver.go:257 [xds] [xds-cluster-resolver-lb 0xc000457880] EDS watch started on test-cluster-name (t=+455.729µs)
tlogger.go:116: INFO clusterresolver.go:191 [xds] [xds-cluster-resolver-lb 0xc000457880] resource update: [
{}
] (t=+562.735µs)
tlogger.go:116: INFO balancer.go:66 [xds] [priority-lb 0xc0001f20e0] Created (t=+693.944µs)
tlogger.go:116: INFO configbuilder.go:311 [xds] xds lb policy is "round_robin", building config with weighted_target + round_robin (t=+766.348µs)
tlogger.go:116: INFO clusterresolver.go:223 [xds] [xds-cluster-resolver-lb 0xc000457880] build balancer config: {
"children": {
"priority-0-0": {
"config": [
{
"xds_cluster_impl_experimental": {
"cluster": "test-cluster-name",
"childPolicy": [
{
"weighted_target_experimental": {
"targets": {
"{\"subZone\":\"I\"}": {
"weight": 1,
"childPolicy": [
{
"round_robin": {}
}
]
}
}
}
}
]
}
}
],
"ignoreReresolutionRequests": true
}
},
"priorities": [
"priority-0-0"
]
} (t=+1.775612ms)
tlogger.go:116: INFO balancer.go:108 [xds] [priority-lb 0xc0001f20e0] Received update from resolver, balancer config: {
"children": {
"priority-0-0": {
"config": [
{
"xds_cluster_impl_experimental": {
"cluster": "test-cluster-name",
"childPolicy": [
{
"weighted_target_experimental": {
"targets": {
"{\"subZone\":\"I\"}": {
"weight": 1,
"childPolicy": [
{
"round_robin": {}
}
]
}
}
}
}
]
}
}
],
"ignoreReresolutionRequests": true
}
},
"priorities": [
"priority-0-0"
]
} (t=+2.165237ms)
tlogger.go:116: WARNING balancer_priority.go:87 [xds] ciu, cn, cu: , priority-0-0, (t=+2.334247ms)
balancer.go:147: testClientConn: UpdateState({CONNECTING 0xc00022f670})
tlogger.go:116: INFO balancer_priority.go:92 [xds] [priority-lb 0xc0001f20e0] switching to ("priority-0-0", 0) in syncPriority (t=+2.438254ms)
tlogger.go:116: INFO balancergroup.go:100 [xds] [priority-lb 0xc0001f20e0] Creating child policy of type xds_cluster_impl_experimental (t=+2.492057ms)
tlogger.go:116: INFO clusterimpl.go:73 [xds] [xds-cluster-impl-lb 0xc0000d8900] Created (t=+2.609065ms)
tlogger.go:116: INFO clusterimpl.go:224 [xds] [xds-cluster-impl-lb 0xc0000d8900] Received update from resolver, balancer config: {
"cluster": "test-cluster-name",
"childPolicy": [
{
"weighted_target_experimental": {
"targets": {
"{\"subZone\":\"I\"}": {
"weight": 1,
"childPolicy": [
{
"round_robin": {}
}
]
}
}
}
}
]
} (t=+2.864581ms)
tlogger.go:116: INFO weightedtarget.go:59 [xds] [weighted-target-lb 0xc00007ea40] Created (t=+2.967987ms)
tlogger.go:116: INFO weightedtarget.go:84 [xds] [weighted-target-lb 0xc00007ea40] Received update from resolver, balancer config: {
"targets": {
"{\"subZone\":\"I\"}": {
"weight": 1,
"childPolicy": [
{
"round_robin": {}
}
]
}
}
} (t=+3.087095ms)
tlogger.go:116: INFO balancergroup.go:100 [xds] [weighted-target-lb 0xc00007ea40] Creating child policy of type round_robin (t=+3.150599ms)
balancer.go:113: testClientConn: NewSubConn([{
"Addr": "0.0.0.0:0",
"ServerName": "",
"Attributes": {},
"BalancerAttributes": {},
"Type": 0,
"Metadata": null
}], {CredsBundle:<nil> HealthCheckEnabled:true}) => sc0
tlogger.go:116: INFO roundrobin.go:50 [roundrobin] roundrobinPicker: Build called with info: {map[]} (t=+3.399915ms)
tlogger.go:116: INFO balancergroup.go:499 [xds] [weighted-target-lb 0xc00007ea40] Balancer state update from locality {"subZone":"I"}, new state: {ConnectivityState:CONNECTING Picker:0xc0001c03f0} (t=+3.456018ms)
tlogger.go:116: INFO aggregator.go:201 [xds] [weighted-target-lb 0xc00007ea40] Child pickers with config: map[{"subZone":"I"}:weight:1,picker:0xc0001c03f0,state:CONNECTING,stateToAggregate:CONNECTING] (t=+3.521922ms)
tlogger.go:116: INFO balancergroup.go:499 [xds] [priority-lb 0xc0001f20e0] Balancer state update from locality priority-0-0, new state: {ConnectivityState:CONNECTING Picker:0xc0005ba780} (t=+3.635829ms)
tlogger.go:116: INFO balancergroup.go:499 [xds] [weighted-target-lb 0xc00007ea40] Balancer state update from locality {"subZone":"I"}, new state: {ConnectivityState:CONNECTING Picker:0xc0001c03f0} (t=+3.746736ms)
tlogger.go:116: INFO aggregator.go:201 [xds] [weighted-target-lb 0xc00007ea40] Child pickers with config: map[{"subZone":"I"}:weight:1,picker:0xc0001c03f0,state:CONNECTING,stateToAggregate:CONNECTING] (t=+4.162463ms)
tlogger.go:116: WARNING balancer_priority.go:87 [xds] ciu, cn, cu: priority-0-0, priority-0-0, priority-0-0 (t=+4.218766ms)
balancer.go:147: testClientConn: UpdateState({CONNECTING 0xc0005ba780})
tlogger.go:116: INFO balancer_priority.go:92 [xds] [priority-lb 0xc0001f20e0] switching to ("priority-0-0", 0) in syncPriority (t=+4.313372ms)
tlogger.go:116: INFO balancergroup.go:499 [xds] [priority-lb 0xc0001f20e0] Balancer state update from locality priority-0-0, new state: {ConnectivityState:CONNECTING Picker:0xc00003c050} (t=+4.43398ms)
tlogger.go:116: WARNING balancer_priority.go:87 [xds] ciu, cn, cu: priority-0-0, priority-0-0, priority-0-0 (t=+6.066483ms)
balancer.go:147: testClientConn: UpdateState({CONNECTING 0xc00003c050})
tlogger.go:116: INFO roundrobin.go:50 [roundrobin] roundrobinPicker: Build called with info: {map[0xc00007eca0:{{
"Addr": "0.0.0.0:0",
"ServerName": "",
"Attributes": null,
"BalancerAttributes": {},
"Type": 0,
"Metadata": null
}}]} (t=+6.14[388](https://github.com/grpc/grpc-go/runs/7046249753?check_suite_focus=true#step:8:389)8ms)
tlogger.go:116: INFO balancergroup.go:499 [xds] [weighted-target-lb 0xc00007ea40] Balancer state update from locality {"subZone":"I"}, new state: {ConnectivityState:READY Picker:0xc0000b9b90} (t=+6.246094ms)
tlogger.go:116: INFO aggregator.go:201 [xds] [weighted-target-lb 0xc00007ea40] Child pickers with config: map[{"subZone":"I"}:weight:1,picker:0xc0000b9b90,state:READY,stateToAggregate:READY] (t=+6.319299ms)
tlogger.go:116: INFO clusterresolver.go:191 [xds] [xds-cluster-resolver-lb 0xc000457880] resource update: [
{}
] (t=+6.393903ms)
tlogger.go:116: INFO configbuilder.go:311 [xds] xds lb policy is "round_robin", building config with weighted_target + round_robin (t=+6.457007ms)
tlogger.go:116: INFO clusterresolver.go:223 [xds] [xds-cluster-resolver-lb 0xc000457880] build balancer config: {
"children": {
"priority-0-0": {
"config": [
{
"xds_cluster_impl_experimental": {
"cluster": "test-cluster-name",
"childPolicy": [
{
"weighted_target_experimental": {
"targets": {
"{\"subZone\":\"I\"}": {
"weight": 1,
"childPolicy": [
{
"round_robin": {}
}
]
},
"{\"subZone\":\"II\"}": {
"weight": 1,
"childPolicy": [
{
"round_robin": {}
}
]
}
}
}
}
]
}
}
],
"ignoreReresolutionRequests": true
}
},
"priorities": [
"priority-0-0"
]
} (t=+7.560477ms)
tlogger.go:116: INFO balancer.go:108 [xds] [priority-lb 0xc0001f20e0] Received update from resolver, balancer config: {
"children": {
"priority-0-0": {
"config": [
{
"xds_cluster_impl_experimental": {
"cluster": "test-cluster-name",
"childPolicy": [
{
"weighted_target_experimental": {
"targets": {
"{\"subZone\":\"I\"}": {
"weight": 1,
"childPolicy": [
{
"round_robin": {}
}
]
},
"{\"subZone\":\"II\"}": {
"weight": 1,
"childPolicy": [
{
"round_robin": {}
}
]
}
}
}
}
]
}
}
],
"ignoreReresolutionRequests": true
}
},
"priorities": [
"priority-0-0"
]
} (t=+8.062009ms)
tlogger.go:116: INFO balancergroup.go:499 [xds] [priority-lb 0xc0001f20e0] Balancer state update from locality priority-0-0, new state: {ConnectivityState:READY Picker:0xc0005baaa0} (t=+8.224619ms)
tlogger.go:116: INFO balancer_priority.go:92 [xds] [priority-lb 0xc0001f20e0] switching to ("priority-0-0", 0) in syncPriority (t=+8.281223ms)
tlogger.go:116: WARNING balancer_priority.go:87 [xds] ciu, cn, cu: priority-0-0, priority-0-0, priority-0-0 (t=+8.338526ms)
balancer.go:147: testClientConn: UpdateState({READY 0xc0005baaa0})
tlogger.go:116: INFO balancer_priority.go:92 [xds] [priority-lb 0xc0001f20e0] switching to ("priority-0-0", 0) in syncPriority (t=+8.416531ms)
tlogger.go:116: INFO clusterimpl.go:224 [xds] [xds-cluster-impl-lb 0xc0000d8900] Received update from resolver, balancer config: {
"cluster": "test-cluster-name",
"childPolicy": [
{
"weighted_target_experimental": {
"targets": {
"{\"subZone\":\"I\"}": {
"weight": 1,
"childPolicy": [
{
"round_robin": {}
}
]
},
"{\"subZone\":\"II\"}": {
"weight": 1,
"childPolicy": [
{
"round_robin": {}
}
]
}
}
}
}
]
} (t=+8.690648ms)
tlogger.go:116: INFO weightedtarget.go:84 [xds] [weighted-target-lb 0xc00007ea40] Received update from resolver, balancer config: {
"targets": {
"{\"subZone\":\"I\"}": {
"weight": 1,
"childPolicy": [
{
"round_robin": {}
}
]
},
"{\"subZone\":\"II\"}": {
"weight": 1,
"childPolicy": [
{
"round_robin": {}
}
]
}
}
} (t=+8.928963ms)
tlogger.go:116: INFO roundrobin.go:50 [roundrobin] roundrobinPicker: Build called with info: {map[0xc00007eca0:{{
"Addr": "0.0.0.0:0",
"ServerName": "",
"Attributes": null,
"BalancerAttributes": {},
"Type": 0,
"Metadata": null
}}]} (t=+9.098574ms)
tlogger.go:116: INFO balancergroup.go:499 [xds] [weighted-target-lb 0xc00007ea40] Balancer state update from locality {"subZone":"I"}, new state: {ConnectivityState:READY Picker:0xc000590990} (t=+9.172479ms)
tlogger.go:116: INFO aggregator.go:201 [xds] [weighted-target-lb 0xc00007ea40] Child pickers with config: map[{"subZone":"I"}:weight:1,picker:0xc000590990,state:READY,stateToAggregate:READY] (t=+9.237383ms)
tlogger.go:116: INFO balancergroup.go:100 [xds] [weighted-target-lb 0xc00007ea40] Creating child policy of type round_robin (t=+9.300087ms)
balancer.go:113: testClientConn: NewSubConn([{
"Addr": "1.1.1.1:1",
"ServerName": "",
"Attributes": {},
"BalancerAttributes": {},
"Type": 0,
"Metadata": null
}], {CredsBundle:<nil> HealthCheckEnabled:true}) => sc1
tlogger.go:116: INFO roundrobin.go:50 [roundrobin] roundrobinPicker: Build called with info: {map[]} (t=+9.483999ms)
tlogger.go:116: INFO balancergroup.go:499 [xds] [weighted-target-lb 0xc00007ea40] Balancer state update from locality {"subZone":"II"}, new state: {ConnectivityState:CONNECTING Picker:0xc0001c1790} (t=+9.540902ms)
tlogger.go:116: INFO aggregator.go:201 [xds] [weighted-target-lb 0xc00007ea40] Child pickers with config: map[{"subZone":"I"}:weight:1,picker:0xc000590990,state:READY,stateToAggregate:READY {"subZone":"II"}:weight:1,picker:0xc0001c1790,state:CONNECTING,stateToAggregate:CONNECTING] (t=+9.618307ms)
tlogger.go:116: INFO balancergroup.go:499 [xds] [priority-lb 0xc0001f20e0] Balancer state update from locality priority-0-0, new state: {ConnectivityState:READY Picker:0xc00020e000} (t=+9.744915ms)
tlogger.go:116: INFO balancergroup.go:499 [xds] [priority-lb 0xc0001f20e0] Balancer state update from locality priority-0-0, new state: {ConnectivityState:READY Picker:0xc00020e050} (t=+9.81782ms)
tlogger.go:116: INFO balancer_priority.go:92 [xds] [priority-lb 0xc0001f20e0] switching to ("priority-0-0", 0) in syncPriority (t=+9.905625ms)
tlogger.go:116: WARNING balancer_priority.go:87 [xds] ciu, cn, cu: priority-0-0, priority-0-0, priority-0-0 (t=+9.963129ms)
balancer.go:147: testClientConn: UpdateState({READY 0xc00020e000})
tlogger.go:116: INFO balancer_priority.go:92 [xds] [priority-lb 0xc0001f20e0] switching to ("priority-0-0", 0) in syncPriority (t=+10.041934ms)
tlogger.go:116: WARNING balancer_priority.go:87 [xds] ciu, cn, cu: priority-0-0, priority-0-0, priority-0-0 (t=+10.089337ms)
balancer.go:147: testClientConn: UpdateState({READY 0xc00020e050})
tlogger.go:116: INFO balancer_priority.go:92 [xds] [priority-lb 0xc0001f20e0] switching to ("priority-0-0", 0) in syncPriority (t=+10.197244ms)
tlogger.go:116: INFO balancergroup.go:499 [xds] [weighted-target-lb 0xc00007ea40] Balancer state update from locality {"subZone":"II"}, new state: {ConnectivityState:CONNECTING Picker:0xc0001c1790} (t=+10.270448ms)
tlogger.go:116: INFO aggregator.go:201 [xds] [weighted-target-lb 0xc00007ea40] Child pickers with config: map[{"subZone":"I"}:weight:1,picker:0xc000590990,state:READY,stateToAggregate:READY {"subZone":"II"}:weight:1,picker:0xc0001c1790,state:CONNECTING,stateToAggregate:CONNECTING] (t=+10.355854ms)
tlogger.go:116: INFO roundrobin.go:50 [roundrobin] roundrobinPicker: Build called with info: {map[0xc00007f6a0:{{
"Addr": "1.1.1.1:1",
"ServerName": "",
"Attributes": null,
"BalancerAttributes": {},
"Type": 0,
"Metadata": null
}}]} (t=+10.499363ms)
tlogger.go:116: INFO balancergroup.go:499 [xds] [weighted-target-lb 0xc00007ea40] Balancer state update from locality {"subZone":"II"}, new state: {ConnectivityState:READY Picker:0xc000336540} (t=+10.565867ms)
tlogger.go:116: INFO aggregator.go:201 [xds] [weighted-target-lb 0xc00007ea40] Child pickers with config: map[{"subZone":"I"}:weight:1,picker:0xc000590990,state:READY,stateToAggregate:READY {"subZone":"II"}:weight:1,picker:0xc000336540,state:READY,stateToAggregate:READY] (t=+10.639271ms)
tlogger.go:116: INFO balancergroup.go:499 [xds] [priority-lb 0xc0001f20e0] Balancer state update from locality priority-0-0, new state: {ConnectivityState:READY Picker:0xc00020e230} (t=+10.712376ms)
tlogger.go:116: INFO balancergroup.go:499 [xds] [priority-lb 0xc0001f20e0] Balancer state update from locality priority-0-0, new state: {ConnectivityState:READY Picker:0xc00020e280} (t=+10.77348ms)
tlogger.go:116: WARNING balancer_priority.go:87 [xds] ciu, cn, cu: priority-0-0, priority-0-0, priority-0-0 (t=+10.832684ms)
balancer.go:147: testClientConn: UpdateState({READY 0xc00020e230})
tlogger.go:116: INFO balancer_priority.go:92 [xds] [priority-lb 0xc0001f20e0] switching to ("priority-0-0", 0) in syncPriority (t=+10.907188ms)
tlogger.go:116: WARNING balancer_priority.go:87 [xds] ciu, cn, cu: priority-0-0, priority-0-0, priority-0-0 (t=+10.952791ms)
balancer.go:147: testClientConn: UpdateState({READY 0xc00020e280})
tlogger.go:116: INFO balancer_priority.go:92 [xds] [priority-lb 0xc0001f20e0] switching to ("priority-0-0", 0) in syncPriority (t=+11.023296ms)
tlogger.go:116: INFO clusterresolver.go:191 [xds] [xds-cluster-resolver-lb 0xc000457880] resource update: [
{}
] (t=+11.472924ms)
tlogger.go:116: INFO configbuilder.go:311 [xds] xds lb policy is "round_robin", building config with weighted_target + round_robin (t=+11.5[389](https://github.com/grpc/grpc-go/runs/7046249753?check_suite_focus=true#step:8:390)28ms)
tlogger.go:116: INFO clusterresolver.go:223 [xds] [xds-cluster-resolver-lb 0xc000457880] build balancer config: {
"children": {
"priority-0-0": {
"config": [
{
"xds_cluster_impl_experimental": {
"cluster": "test-cluster-name",
"childPolicy": [
{
"weighted_target_experimental": {
"targets": {
"{\"subZone\":\"I\"}": {
"weight": 1,
"childPolicy": [
{
"round_robin": {}
}
]
},
"{\"subZone\":\"II\"}": {
"weight": 1,
"childPolicy": [
{
"round_robin": {}
}
]
},
"{\"subZone\":\"III\"}": {
"weight": 1,
"childPolicy": [
{
"round_robin": {}
}
]
}
}
}
}
]
}
}
],
"ignoreReresolutionRequests": true
}
},
"priorities": [
"priority-0-0"
]
} (t=+12.74[390](https://github.com/grpc/grpc-go/runs/7046249753?check_suite_focus=true#step:8:391)4ms)
tlogger.go:116: INFO balancer.go:108 [xds] [priority-lb 0xc0001f20e0] Received update from resolver, balancer config: {
"children": {
"priority-0-0": {
"config": [
{
"xds_cluster_impl_experimental": {
"cluster": "test-cluster-name",
"childPolicy": [
{
"weighted_target_experimental": {
"targets": {
"{\"subZone\":\"I\"}": {
"weight": 1,
"childPolicy": [
{
"round_robin": {}
}
]
},
"{\"subZone\":\"II\"}": {
"weight": 1,
"childPolicy": [
{
"round_robin": {}
}
]
},
"{\"subZone\":\"III\"}": {
"weight": 1,
"childPolicy": [
{
"round_robin": {}
}
]
}
}
}
}
]
}
}
],
"ignoreReresolutionRequests": true
}
},
"priorities": [
"priority-0-0"
]
} (t=+13.234435ms)
tlogger.go:116: INFO clusterimpl.go:224 [xds] [xds-cluster-impl-lb 0xc0000d8900] Received update from resolver, balancer config: {
"cluster": "test-cluster-name",
"childPolicy": [
{
"weighted_target_experimental": {
"targets": {
"{\"subZone\":\"I\"}": {
"weight": 1,
"childPolicy": [
{
"round_robin": {}
}
]
},
"{\"subZone\":\"II\"}": {
"weight": 1,
"childPolicy": [
{
"round_robin": {}
}
]
},
"{\"subZone\":\"III\"}": {
"weight": 1,
"childPolicy": [
{
"round_robin": {}
}
]
}
}
}
}
]
} (t=+13.849174ms)
tlogger.go:116: INFO weightedtarget.go:84 [xds] [weighted-target-lb 0xc00007ea40] Received update from resolver, balancer config: {
"targets": {
"{\"subZone\":\"I\"}": {
"weight": 1,
"childPolicy": [
{
"round_robin": {}
}
]
},
"{\"subZone\":\"II\"}": {
"weight": 1,
"childPolicy": [
{
"round_robin": {}
}
]
},
"{\"subZone\":\"III\"}": {
"weight": 1,
"childPolicy": [
{
"round_robin": {}
}
]
}
}
} (t=+14.113891ms)
tlogger.go:116: INFO roundrobin.go:50 [roundrobin] roundrobinPicker: Build called with info: {map[0xc00007eca0:{{
"Addr": "0.0.0.0:0",
"ServerName": "",
"Attributes": null,
"BalancerAttributes": {},
"Type": 0,
"Metadata": null
}}]} (t=+14.289402ms)
tlogger.go:116: INFO balancergroup.go:499 [xds] [weighted-target-lb 0xc00007ea40] Balancer state update from locality {"subZone":"I"}, new state: {ConnectivityState:READY Picker:0xc000337530} (t=+14.361206ms)
tlogger.go:116: INFO aggregator.go:201 [xds] [weighted-target-lb 0xc00007ea40] Child pickers with config: map[{"subZone":"I"}:weight:1,picker:0xc000337530,state:READY,stateToAggregate:READY {"subZone":"II"}:weight:1,picker:0xc000336540,state:READY,stateToAggregate:READY] (t=+14.442011ms)
tlogger.go:116: INFO roundrobin.go:50 [roundrobin] roundrobinPicker: Build called with info: {map[0xc00007f6a0:{{
"Addr": "1.1.1.1:1",
"ServerName": "",
"Attributes": null,
"BalancerAttributes": {},
"Type": 0,
"Metadata": null
}}]} (t=+14.57252ms)
tlogger.go:116: INFO balancergroup.go:499 [xds] [weighted-target-lb 0xc00007ea40] Balancer state update from locality {"subZone":"II"}, new state: {ConnectivityState:READY Picker:0xc000337710} (t=+14.637324ms)
tlogger.go:116: INFO aggregator.go:201 [xds] [weighted-target-lb 0xc00007ea40] Child pickers with config: map[{"subZone":"I"}:weight:1,picker:0xc000337530,state:READY,stateToAggregate:READY {"subZone":"II"}:weight:1,picker:0xc000337710,state:READY,stateToAggregate:READY] (t=+14.712329ms)
tlogger.go:116: INFO balancergroup.go:100 [xds] [weighted-target-lb 0xc00007ea40] Creating child policy of type round_robin (t=+14.765932ms)
balancer.go:113: testClientConn: NewSubConn([{
"Addr": "2.2.2.2:2",
"ServerName": "",
"Attributes": {},
"BalancerAttributes": {},
"Type": 0,
"Metadata": null
}], {CredsBundle:<nil> HealthCheckEnabled:true}) => sc2
tlogger.go:116: INFO roundrobin.go:50 [roundrobin] roundrobinPicker: Build called with info: {map[]} (t=+14.948243ms)
tlogger.go:116: INFO balancergroup.go:499 [xds] [weighted-target-lb 0xc00007ea40] Balancer state update from locality {"subZone":"III"}, new state: {ConnectivityState:CONNECTING Picker:0xc0000551c0} (t=+14.998347ms)
tlogger.go:116: INFO aggregator.go:201 [xds] [weighted-target-lb 0xc00007ea40] Child pickers with config: map[{"subZone":"I"}:weight:1,picker:0xc000337530,state:READY,stateToAggregate:READY {"subZone":"II"}:weight:1,picker:0xc000337710,state:READY,stateToAggregate:READY {"subZone":"III"}:weight:1,picker:0xc0000551c0,state:CONNECTING,stateToAggregate:CONNECTING] (t=+15.085152ms)
tlogger.go:116: INFO balancergroup.go:499 [xds] [priority-lb 0xc0001f20e0] Balancer state update from locality priority-0-0, new state: {ConnectivityState:READY Picker:0xc00003ca50} (t=+15.169657ms)
tlogger.go:116: INFO balancergroup.go:499 [xds] [priority-lb 0xc0001f20e0] Balancer state update from locality priority-0-0, new state: {ConnectivityState:READY Picker:0xc00003caa0} (t=+15.242662ms)
tlogger.go:116: INFO balancergroup.go:499 [xds] [priority-lb 0xc0001f20e0] Balancer state update from locality priority-0-0, new state: {ConnectivityState:READY Picker:0xc00003caf0} (t=+15.300666ms)
tlogger.go:116: INFO balancer_priority.go:92 [xds] [priority-lb 0xc0001f20e0] switching to ("priority-0-0", 0) in syncPriority (t=+15.361169ms)
tlogger.go:116: WARNING balancer_priority.go:87 [xds] ciu, cn, cu: priority-0-0, priority-0-0, priority-0-0 (t=+15.410573ms)
balancer.go:147: testClientConn: UpdateState({READY 0xc00003ca50})
tlogger.go:116: INFO balancer_priority.go:92 [xds] [priority-lb 0xc0001f20e0] switching to ("priority-0-0", 0) in syncPriority (t=+15.484177ms)
tlogger.go:116: WARNING balancer_priority.go:87 [xds] ciu, cn, cu: priority-0-0, priority-0-0, priority-0-0 (t=+15.578583ms)
balancer.go:147: testClientConn: UpdateState({READY 0xc00003caa0})
tlogger.go:116: INFO balancer_priority.go:92 [xds] [priority-lb 0xc0001f20e0] switching to ("priority-0-0", 0) in syncPriority (t=+15.638887ms)
tlogger.go:116: WARNING balancer_priority.go:87 [xds] ciu, cn, cu: priority-0-0, priority-0-0, priority-0-0 (t=+15.67919ms)
balancer.go:147: testClientConn: UpdateState({READY 0xc00003caf0})
tlogger.go:116: INFO balancer_priority.go:92 [xds] [priority-lb 0xc0001f20e0] switching to ("priority-0-0", 0) in syncPriority (t=+15.733693ms)
tlogger.go:116: INFO balancergroup.go:499 [xds] [weighted-target-lb 0xc00007ea40] Balancer state update from locality {"subZone":"III"}, new state: {ConnectivityState:CONNECTING Picker:0xc0000551c0} (t=+16.47194ms)
tlogger.go:116: INFO aggregator.go:201 [xds] [weighted-target-lb 0xc00007ea40] Child pickers with config: map[{"subZone":"I"}:weight:1,picker:0xc000337530,state:READY,stateToAggregate:READY {"subZone":"II"}:weight:1,picker:0xc000337710,state:READY,stateToAggregate:READY {"subZone":"III"}:weight:1,picker:0xc0000551c0,state:CONNECTING,stateToAggregate:CONNECTING] (t=+16.571246ms)
tlogger.go:116: INFO roundrobin.go:50 [roundrobin] roundrobinPicker: Build called with info: {map[0xc0001538c0:{{
"Addr": "2.2.2.2:2",
"ServerName": "",
"Attributes": null,
"BalancerAttributes": {},
"Type": 0,
"Metadata": null
}}]} (t=+16.706354ms)
tlogger.go:116: INFO balancergroup.go:499 [xds] [weighted-target-lb 0xc00007ea40] Balancer state update from locality {"subZone":"III"}, new state: {ConnectivityState:READY Picker:0xc0000b83f0} (t=+16.769058ms)
tlogger.go:116: INFO aggregator.go:201 [xds] [weighted-target-lb 0xc00007ea40] Child pickers with config: map[{"subZone":"I"}:weight:1,picker:0xc000337530,state:READY,stateToAggregate:READY {"subZone":"II"}:weight:1,picker:0xc000337710,state:READY,stateToAggregate:READY {"subZone":"III"}:weight:1,picker:0xc0000b83f0,state:READY,stateToAggregate:READY] (t=+16.852364ms)
tlogger.go:116: INFO balancergroup.go:499 [xds] [priority-lb 0xc0001f20e0] Balancer state update from locality priority-0-0, new state: {ConnectivityState:READY Picker:0xc00003cdc0} (t=+16.920868ms)
tlogger.go:116: INFO balancergroup.go:499 [xds] [priority-lb 0xc0001f20e0] Balancer state update from locality priority-0-0, new state: {ConnectivityState:READY Picker:0xc00003ce10} (t=+16.984672ms)
tlogger.go:116: WARNING balancer_priority.go:87 [xds] ciu, cn, cu: priority-0-0, priority-0-0, priority-0-0 (t=+17.036675ms)
balancer.go:147: testClientConn: UpdateState({READY 0xc00003cdc0})
tlogger.go:116: INFO balancer_priority.go:92 [xds] [priority-lb 0xc0001f20e0] switching to ("priority-0-0", 0) in syncPriority (t=+17.102879ms)
tlogger.go:116: WARNING balancer_priority.go:87 [xds] ciu, cn, cu: priority-0-0, priority-0-0, priority-0-0 (t=+17.141082ms)
balancer.go:147: testClientConn: UpdateState({READY 0xc00003ce10})
tlogger.go:116: INFO balancer_priority.go:92 [xds] [priority-lb 0xc0001f20e0] switching to ("priority-0-0", 0) in syncPriority (t=+17.198085ms)
tlogger.go:116: INFO clusterresolver.go:191 [xds] [xds-cluster-resolver-lb 0xc000457880] resource update: [
{}
] (t=+17.448801ms)
tlogger.go:116: INFO configbuilder.go:311 [xds] xds lb policy is "round_robin", building config with weighted_target + round_robin (t=+17.502705ms)
tlogger.go:116: INFO clusterresolver.go:223 [xds] [xds-cluster-resolver-lb 0xc000457880] build balancer config: {
"children": {
"priority-0-0": {
"config": [
{
"xds_cluster_impl_experimental": {
"cluster": "test-cluster-name",
"childPolicy": [
{
"weighted_target_experimental": {
"targets": {
"{\"subZone\":\"II\"}": {
"weight": 1,
"childPolicy": [
{
"round_robin": {}
}
]
},
"{\"subZone\":\"III\"}": {
"weight": 1,
"childPolicy": [
{
"round_robin": {}
}
]
}
}
}
}
]
}
}
],
"ignoreReresolutionRequests": true
}
},
"priorities": [
"priority-0-0"
]
} (t=+18.453965ms)
tlogger.go:116: INFO balancer.go:108 [xds] [priority-lb 0xc0001f20e0] Received update from resolver, balancer config: {
"children": {
"priority-0-0": {
"config": [
{
"xds_cluster_impl_experimental": {
"cluster": "test-cluster-name",
"childPolicy": [
{
"weighted_target_experimental": {
"targets": {
"{\"subZone\":\"II\"}": {
"weight": 1,
"childPolicy": [
{
"round_robin": {}
}
]
},
"{\"subZone\":\"III\"}": {
"weight": 1,
"childPolicy": [
{
"round_robin": {}
}
]
}
}
}
}
]
}
}
],
"ignoreReresolutionRequests": true
}
},
"priorities": [
"priority-0-0"
]
} (t=+18.86199ms)
tlogger.go:116: INFO clusterimpl.go:224 [xds] [xds-cluster-impl-lb 0xc0000d8900] Received update from resolver, balancer config: {
"cluster": "test-cluster-name",
"childPolicy": [
{
"weighted_target_experimental": {
"targets": {
"{\"subZone\":\"II\"}": {
"weight": 1,
"childPolicy": [
{
"round_robin": {}
}
]
},
"{\"subZone\":\"III\"}": {
"weight": 1,
"childPolicy": [
{
"round_robin": {}
}
]
}
}
}
}
]
} (t=+19.163509ms)
tlogger.go:116: INFO weightedtarget.go:84 [xds] [weighted-target-lb 0xc00007ea40] Received update from resolver, balancer config: {
"targets": {
"{\"subZone\":\"II\"}": {
"weight": 1,
"childPolicy": [
{
"round_robin": {}
}
]
},
"{\"subZone\":\"III\"}": {
"weight": 1,
"childPolicy": [
{
"round_robin": {}
}
]
}
}
} (t=+19.442627ms)
tlogger.go:116: INFO roundrobin.go:50 [roundrobin] roundrobinPicker: Build called with info: {map[0xc00007f6a0:{{
"Addr": "1.1.1.1:1",
"ServerName": "",
"Attributes": null,
"BalancerAttributes": {},
"Type": 0,
"Metadata": null
}}]} (t=+19.624239ms)
tlogger.go:116: INFO balancergroup.go:499 [xds] [weighted-target-lb 0xc00007ea40] Balancer state update from locality {"subZone":"II"}, new state: {ConnectivityState:READY Picker:0xc0001fa780} (t=+19.693743ms)
tlogger.go:116: INFO aggregator.go:201 [xds] [weighted-target-lb 0xc00007ea40] Child pickers with config: map[{"subZone":"II"}:weight:1,picker:0xc0001fa780,state:READY,stateToAggregate:READY {"subZone":"III"}:weight:1,picker:0xc0000b83f0,state:READY,stateToAggregate:READY] (t=+19.795349ms)
tlogger.go:116: INFO roundrobin.go:50 [roundrobin] roundrobinPicker: Build called with info: {map[0xc0001538c0:{{
"Addr": "2.2.2.2:2",
"ServerName": "",
"Attributes": null,
"BalancerAttributes": {},
"Type": 0,
"Metadata": null
}}]} (t=+19.926358ms)
tlogger.go:116: INFO balancergroup.go:499 [xds] [weighted-target-lb 0xc00007ea40] Balancer state update from locality {"subZone":"III"}, new state: {ConnectivityState:READY Picker:0xc0001fa960} (t=+19.985561ms)
tlogger.go:116: INFO aggregator.go:201 [xds] [weighted-target-lb 0xc00007ea40] Child pickers with config: map[{"subZone":"II"}:weight:1,picker:0xc0001fa780,state:READY,stateToAggregate:READY {"subZone":"III"}:weight:1,picker:0xc0001fa960,state:READY,stateToAggregate:READY] (t=+20.053266ms)
tlogger.go:116: INFO aggregator.go:201 [xds] [weighted-target-lb 0xc00007ea40] Child pickers with config: map[{"subZone":"II"}:weight:1,picker:0xc0001fa780,state:READY,stateToAggregate:READY {"subZone":"III"}:weight:1,picker:0xc0001fa960,state:READY,stateToAggregate:READY] (t=+21.032927ms)
tlogger.go:116: INFO balancergroup.go:499 [xds] [priority-lb 0xc0001f20e0] Balancer state update from locality priority-0-0, new state: {ConnectivityState:READY Picker:0xc0005ba000} (t=+21.089431ms)
tlogger.go:116: INFO balancergroup.go:499 [xds] [priority-lb 0xc0001f20e0] Balancer state update from locality priority-0-0, new state: {ConnectivityState:READY Picker:0xc00003d590} (t=+21.744972ms)
tlogger.go:116: INFO balancergroup.go:499 [xds] [priority-lb 0xc0001f20e0] Balancer state update from locality priority-0-0, new state: {ConnectivityState:READY Picker:0xc00003d5e0} (t=+21.809977ms)
tlogger.go:116: INFO balancer_priority.go:92 [xds] [priority-lb 0xc0001f20e0] switching to ("priority-0-0", 0) in syncPriority (t=+21.848479ms)
tlogger.go:116: WARNING balancer_priority.go:87 [xds] ciu, cn, cu: priority-0-0, priority-0-0, priority-0-0 (t=+21.899682ms)
balancer.go:147: testClientConn: UpdateState({READY 0xc0005ba000})
tlogger.go:116: INFO balancer_priority.go:92 [xds] [priority-lb 0xc0001f20e0] switching to ("priority-0-0", 0) in syncPriority (t=+21.969287ms)
tlogger.go:116: WARNING balancer_priority.go:87 [xds] ciu, cn, cu: priority-0-0, priority-0-0, priority-0-0 (t=+22.010789ms)
balancer.go:147: testClientConn: UpdateState({READY 0xc00003d590})
tlogger.go:116: INFO balancer_priority.go:92 [xds] [priority-lb 0xc0001f20e0] switching to ("priority-0-0", 0) in syncPriority (t=+22.070193ms)
tlogger.go:116: WARNING balancer_priority.go:87 [xds] ciu, cn, cu: priority-0-0, priority-0-0, priority-0-0 (t=+22.114196ms)
balancer.go:147: testClientConn: UpdateState({READY 0xc00003d5e0})
tlogger.go:116: INFO balancer_priority.go:92 [xds] [priority-lb 0xc0001f20e0] switching to ("priority-0-0", 0) in syncPriority (t=+22.169999ms)
balancer.go:129: testClientConn: RemoveSubConn(sc0)
tlogger.go:116: INFO clusterresolver.go:191 [xds] [xds-cluster-resolver-lb 0xc000457880] resource update: [
{}
] (t=+120.523607ms)
tlogger.go:116: INFO configbuilder.go:311 [xds] xds lb policy is "round_robin", building config with weighted_target + round_robin (t=+120.609913ms)
tlogger.go:116: INFO clusterresolver.go:223 [xds] [xds-cluster-resolver-lb 0xc000457880] build balancer config: {
"children": {
"priority-0-0": {
"config": [
{
"xds_cluster_impl_experimental": {
"cluster": "test-cluster-name",
"childPolicy": [
{
"weighted_target_experimental": {
"targets": {
"{\"subZone\":\"II\"}": {
"weight": 1,
"childPolicy": [
{
"round_robin": {}
}
]
},
"{\"subZone\":\"III\"}": {
"weight": 1,
"childPolicy": [
{
"round_robin": {}
}
]
}
}
}
}
]
}
}
],
"ignoreReresolutionRequests": true
}
},
"priorities": [
"priority-0-0"
]
} (t=+121.730683ms)
tlogger.go:116: INFO balancer.go:108 [xds] [priority-lb 0xc0001f20e0] Received update from resolver, balancer config: {
"children": {
"priority-0-0": {
"config": [
{
"xds_cluster_impl_experimental": {
"cluster": "test-cluster-name",
"childPolicy": [
{
"weighted_target_experimental": {
"targets": {
"{\"subZone\":\"II\"}": {
"weight": 1,
"childPolicy": [
{
"round_robin": {}
}
]
},
"{\"subZone\":\"III\"}": {
"weight": 1,
"childPolicy": [
{
"round_robin": {}
}
]
}
}
}
}
]
}
}
],
"ignoreReresolutionRequests": true
}
},
"priorities": [
"priority-0-0"
]
} (t=+122.301219ms)
tlogger.go:116: INFO clusterimpl.go:224 [xds] [xds-cluster-impl-lb 0xc0000d8900] Received update from resolver, balancer config: {
"cluster": "test-cluster-name",
"childPolicy": [
{
"weighted_target_experimental": {
"targets": {
"{\"subZone\":\"II\"}": {
"weight": 1,
"childPolicy": [
{
"round_robin": {}
}
]
},
"{\"subZone\":\"III\"}": {
"weight": 1,
"childPolicy": [
{
"round_robin": {}
}
]
}
}
}
}
]
} (t=+122.651041ms)
tlogger.go:116: INFO weightedtarget.go:84 [xds] [weighted-target-lb 0xc00007ea40] Received update from resolver, balancer config: {
"targets": {
"{\"subZone\":\"II\"}": {
"weight": 1,
"childPolicy": [
{
"round_robin": {}
}
]
},
"{\"subZone\":\"III\"}": {
"weight": 1,
"childPolicy": [
{
"round_robin": {}
}
]
}
}
} (t=+122.921158ms)
tlogger.go:116: INFO roundrobin.go:50 [roundrobin] roundrobinPicker: Build called with info: {map[0xc00007f6a0:{{
"Addr": "1.1.1.1:1",
"ServerName": "",
"Attributes": null,
"BalancerAttributes": {},
"Type": 0,
"Metadata": null
}}]} (t=+123.10887ms)
tlogger.go:116: INFO balancergroup.go:499 [xds] [weighted-target-lb 0xc00007ea40] Balancer state update from locality {"subZone":"II"}, new state: {ConnectivityState:READY Picker:0xc000591ce0} (t=+123.184275ms)
tlogger.go:116: INFO aggregator.go:201 [xds] [weighted-target-lb 0xc00007ea40] Child pickers with config: map[{"subZone":"II"}:weight:1,picker:0xc000591ce0,state:READY,stateToAggregate:READY {"subZone":"III"}:weight:1,picker:0xc0001fa960,state:READY,stateToAggregate:READY] (t=+123.27118ms)
balancer.go:113: testClientConn: NewSubConn([{
"Addr": "3.3.3.3:3",
"ServerName": "",
"Attributes": {},
"BalancerAttributes": {},
"Type": 0,
"Metadata": null
}], {CredsBundle:<nil> HealthCheckEnabled:true}) => sc3
tlogger.go:116: INFO roundrobin.go:50 [roundrobin] roundrobinPicker: Build called with info: {map[0xc0001538c0:{{
"Addr": "2.2.2.2:2",
"ServerName": "",
"Attributes": null,
"BalancerAttributes": {},
"Type": 0,
"Metadata": null
}}]} (t=+123.540097ms)
tlogger.go:116: INFO balancergroup.go:499 [xds] [weighted-target-lb 0xc00007ea40] Balancer state update from locality {"subZone":"III"}, new state: {ConnectivityState:READY Picker:0xc000591f50} (t=+123.605502ms)
tlogger.go:116: INFO aggregator.go:201 [xds] [weighted-target-lb 0xc00007ea40] Child pickers with config: map[{"subZone":"II"}:weight:1,picker:0xc000591ce0,state:READY,stateToAggregate:READY {"subZone":"III"}:weight:1,picker:0xc000591f50,state:READY,stateToAggregate:READY] (t=+123.687307ms)
tlogger.go:116: INFO balancer_priority.go:92 [xds] [priority-lb 0xc0001f20e0] switching to ("priority-0-0", 0) in syncPriority (t=+123.849617ms)
tlogger.go:116: INFO balancergroup.go:499 [xds] [weighted-target-lb 0xc00007ea40] Balancer state update from locality {"subZone":"III"}, new state: {ConnectivityState:READY Picker:0xc000591f50} (t=+123.952223ms)
tlogger.go:116: INFO aggregator.go:201 [xds] [weighted-target-lb 0xc00007ea40] Child pickers with config: map[{"subZone":"II"}:weight:1,picker:0xc000591ce0,state:READY,stateToAggregate:READY {"subZone":"III"}:weight:1,picker:0xc000591f50,state:READY,stateToAggregate:READY] (t=+124.036529ms)
tlogger.go:116: INFO roundrobin.go:50 [roundrobin] roundrobinPicker: Build called with info: {map[0xc0001538c0:{{
"Addr": "2.2.2.2:2",
"ServerName": "",
"Attributes": null,
"BalancerAttributes": {},
"Type": 0,
"Metadata": null
}} 0xc00025e540:{{
"Addr": "3.3.3.3:3",
"ServerName": "",
"Attributes": null,
"BalancerAttributes": {},
"Type": 0,
"Metadata": null
}}]} (t=+124.261843ms)
tlogger.go:116: INFO balancergroup.go:499 [xds] [weighted-target-lb 0xc00007ea40] Balancer state update from locality {"subZone":"III"}, new state: {ConnectivityState:READY Picker:0xc0001ec450} (t=+124.345948ms)
tlogger.go:116: INFO aggregator.go:201 [xds] [weighted-target-lb 0xc00007ea40] Child pickers with config: map[{"subZone":"II"}:weight:1,picker:0xc000591ce0,state:READY,stateToAggregate:READY {"subZone":"III"}:weight:1,picker:0xc0001ec450,state:READY,stateToAggregate:READY] (t=+124.422953ms)
tlogger.go:116: INFO balancergroup.go:499 [xds] [priority-lb 0xc0001f20e0] Balancer state update from locality priority-0-0, new state: {ConnectivityState:READY Picker:0xc00020ebe0} (t=+124.509959ms)
tlogger.go:116: INFO balancergroup.go:499 [xds] [priority-lb 0xc0001f20e0] Balancer state update from locality priority-0-0, new state: {ConnectivityState:READY Picker:0xc00020ec30} (t=+124.593164ms)
tlogger.go:116: WARNING balancer_priority.go:87 [xds] ciu, cn, cu: priority-0-0, priority-0-0, priority-0-0 (t=+124.678069ms)
balancer.go:147: testClientConn: UpdateState({READY 0xc00020ebe0})
tlogger.go:116: INFO balancer_priority.go:92 [xds] [priority-lb 0xc0001f20e0] switching to ("priority-0-0", 0) in syncPriority (t=+124.762675ms)
tlogger.go:116: INFO balancergroup.go:499 [xds] [priority-lb 0xc0001f20e0] Balancer state update from locality priority-0-0, new state: {ConnectivityState:READY Picker:0xc00020ec80} (t=+124.943486ms)
tlogger.go:116: WARNING balancer_priority.go:87 [xds] ciu, cn, cu: priority-0-0, priority-0-0, priority-0-0 (t=+125.015891ms)
balancer.go:147: testClientConn: UpdateState({READY 0xc00020ec30})
tlogger.go:116: INFO balancer_priority.go:92 [xds] [priority-lb 0xc0001f20e0] switching to ("priority-0-0", 0) in syncPriority (t=+125.124997ms)
tlogger.go:116: WARNING balancer_priority.go:87 [xds] ciu, cn, cu: priority-0-0, priority-0-0, priority-0-0 (t=+125.183401ms)
balancer.go:147: testClientConn: UpdateState({READY 0xc00020ec80})
tlogger.go:116: INFO balancer_priority.go:92 [xds] [priority-lb 0xc0001f20e0] switching to ("priority-0-0", 0) in syncPriority (t=+125.254706ms)
tlogger.go:116: INFO balancergroup.go:499 [xds] [priority-lb 0xc0001f20e0] Balancer state update from locality priority-0-0, new state: {ConnectivityState:READY Picker:0xc00020ecd0} (t=+125.290808ms)
tlogger.go:116: WARNING balancer_priority.go:87 [xds] ciu, cn, cu: priority-0-0, priority-0-0, priority-0-0 (t=+125.351512ms)
balancer.go:147: testClientConn: UpdateState({READY 0xc00020ecd0})
tlogger.go:116: INFO balancer_priority.go:92 [xds] [priority-lb 0xc0001f20e0] switching to ("priority-0-0", 0) in syncPriority (t=+125.412716ms)
tlogger.go:116: INFO clusterresolver.go:191 [xds] [xds-cluster-resolver-lb 0xc000457880] resource update: [
{}
] (t=+125.736036ms)
tlogger.go:116: INFO configbuilder.go:311 [xds] xds lb policy is "round_robin", building config with weighted_target + round_robin (t=+125.80344ms)
tlogger.go:116: INFO clusterresolver.go:223 [xds] [xds-cluster-resolver-lb 0xc000457880] build balancer config: {
"children": {
"priority-0-0": {
"config": [
{
"xds_cluster_impl_experimental": {
"cluster": "test-cluster-name",
"childPolicy": [
{
"weighted_target_experimental": {
"targets": {
"{\"subZone\":\"II\"}": {
"weight": 2,
"childPolicy": [
{
"round_robin": {}
}
]
},
"{\"subZone\":\"III\"}": {
"weight": 1,
"childPolicy": [
{
"round_robin": {}
}
]
}
}
}
}
]
}
}
],
"ignoreReresolutionRequests": true
}
},
"priorities": [
"priority-0-0"
]
} (t=+126.863707ms)
tlogger.go:116: INFO balancer.go:108 [xds] [priority-lb 0xc0001f20e0] Received update from resolver, balancer config: {
"children": {
"priority-0-0": {
"config": [
{
"xds_cluster_impl_experimental": {
"cluster": "test-cluster-name",
"childPolicy": [
{
"weighted_target_experimental": {
"targets": {
"{\"subZone\":\"II\"}": {
"weight": 2,
"childPolicy": [
{
"round_robin": {}
}
]
},
"{\"subZone\":\"III\"}": {
"weight": 1,
"childPolicy": [
{
"round_robin": {}
}
]
}
}
}
}
]
}
}
],
"ignoreReresolutionRequests": true
}
},
"priorities": [
"priority-0-0"
]
} (t=+127.309235ms)
tlogger.go:116: INFO clusterimpl.go:224 [xds] [xds-cluster-impl-lb 0xc0000d8900] Received update from resolver, balancer config: {
"cluster": "test-cluster-name",
"childPolicy": [
{
"weighted_target_experimental": {
"targets": {
"{\"subZone\":\"II\"}": {
"weight": 2,
"childPolicy": [
{
"round_robin": {}
}
]
},
"{\"subZone\":\"III\"}": {
"weight": 1,
"childPolicy": [
{
"round_robin": {}
}
]
}
}
}
}
]
} (t=+127.648557ms)
tlogger.go:116: INFO weightedtarget.go:84 [xds] [weighted-target-lb 0xc00007ea40] Received update from resolver, balancer config: {
"targets": {
"{\"subZone\":\"II\"}": {
"weight": 2,
"childPolicy": [
{
"round_robin": {}
}
]
},
"{\"subZone\":\"III\"}": {
"weight": 1,
"childPolicy": [
{
"round_robin": {}
}
]
}
}
} (t=+127.899373ms)
tlogger.go:116: INFO roundrobin.go:50 [roundrobin] roundrobinPicker: Build called with info: {map[0xc00007f6a0:{{
"Addr": "1.1.1.1:1",
"ServerName": "",
"Attributes": null,
"BalancerAttributes": {},
"Type": 0,
"Metadata": null
}}]} (t=+128.081184ms)
tlogger.go:116: INFO balancergroup.go:499 [xds] [weighted-target-lb 0xc00007ea40] Balancer state update from locality {"subZone":"II"}, new state: {ConnectivityState:READY Picker:0xc0001b4a50} (t=+128.154389ms)
tlogger.go:116: INFO aggregator.go:201 [xds] [weighted-target-lb 0xc00007ea40] Child pickers with config: map[{"subZone":"II"}:weight:2,picker:0xc0001b4a50,state:READY,stateToAggregate:READY {"subZone":"III"}:weight:1,picker:0xc0001ec450,state:READY,stateToAggregate:READY] (t=+128.242094ms)
tlogger.go:116: INFO roundrobin.go:50 [roundrobin] roundrobinPicker: Build called with info: {map[0xc0001538c0:{{
"Addr": "2.2.2.2:2",
"ServerName": "",
"Attributes": null,
"BalancerAttributes": {},
"Type": 0,
"Metadata": null
}} 0xc00025e540:{{
"Addr": "3.3.3.3:3",
"ServerName": "",
"Attributes": null,
"BalancerAttributes": {},
"Type": 0,
"Metadata": null
}}]} (t=+128.473809ms)
tlogger.go:116: INFO balancergroup.go:499 [xds] [weighted-target-lb 0xc00007ea40] Balancer state update from locality {"subZone":"III"}, new state: {ConnectivityState:READY Picker:0xc0001b4c90} (t=+128.550914ms)
tlogger.go:116: INFO aggregator.go:201 [xds] [weighted-target-lb 0xc00007ea40] Child pickers with config: map[{"subZone":"II"}:weight:2,picker:0xc0001b4a50,state:READY,stateToAggregate:READY {"subZone":"III"}:weight:1,picker:0xc0001b4c90,state:READY,stateToAggregate:READY] (t=+128.756327ms)
tlogger.go:116: INFO aggregator.go:201 [xds] [weighted-target-lb 0xc00007ea40] Child pickers with config: map[{"subZone":"II"}:weight:2,picker:0xc0001b4a50,state:READY,stateToAggregate:READY {"subZone":"III"}:weight:1,picker:0xc0001b4c90,state:READY,stateToAggregate:READY] (t=+128.844632ms)
tlogger.go:116: INFO balancergroup.go:499 [xds] [priority-lb 0xc0001f20e0] Balancer state update from locality priority-0-0, new state: {ConnectivityState:READY Picker:0xc0005bb3b0} (t=+128.932238ms)
tlogger.go:116: INFO balancergroup.go:499 [xds] [priority-lb 0xc0001f20e0] Balancer state update from locality priority-0-0, new state: {ConnectivityState:READY Picker:0xc0005bb400} (t=+129.000542ms)
tlogger.go:116: INFO balancergroup.go:499 [xds] [priority-lb 0xc0001f20e0] Balancer state update from locality priority-0-0, new state: {ConnectivityState:READY Picker:0xc0005bb450} (t=+129.074447ms)
tlogger.go:116: INFO balancer_priority.go:92 [xds] [priority-lb 0xc0001f20e0] switching to ("priority-0-0", 0) in syncPriority (t=+129.141851ms)
tlogger.go:116: WARNING balancer_priority.go:87 [xds] ciu, cn, cu: priority-0-0, priority-0-0, priority-0-0 (t=+129.196854ms)
balancer.go:147: testClientConn: UpdateState({READY 0xc0005bb3b0})
tlogger.go:116: INFO balancer_priority.go:92 [xds] [priority-lb 0xc0001f20e0] switching to ("priority-0-0", 0) in syncPriority (t=+129.274959ms)
tlogger.go:116: WARNING balancer_priority.go:87 [xds] ciu, cn, cu: priority-0-0, priority-0-0, priority-0-0 (t=+129.317662ms)
balancer.go:147: testClientConn: UpdateState({READY 0xc0005bb400})
tlogger.go:116: INFO balancer_priority.go:92 [xds] [priority-lb 0xc0001f20e0] switching to ("priority-0-0", 0) in syncPriority (t=+129.[392](https://github.com/grpc/grpc-go/runs/7046249753?check_suite_focus=true#step:8:393)767ms)
tlogger.go:116: WARNING balancer_priority.go:87 [xds] ciu, cn, cu: priority-0-0, priority-0-0, priority-0-0 (t=+129.43627ms)
balancer.go:147: testClientConn: UpdateState({READY 0xc0005bb450})
tlogger.go:116: INFO balancer_priority.go:92 [xds] [priority-lb 0xc0001f20e0] switching to ("priority-0-0", 0) in syncPriority (t=+129.496173ms)
tlogger.go:116: INFO clusterresolver.go:191 [xds] [xds-cluster-resolver-lb 0xc000457880] resource update: [
{}
] (t=+129.846496ms)
tlogger.go:116: INFO configbuilder.go:311 [xds] xds lb policy is "round_robin", building config with weighted_target + round_robin (t=+129.905799ms)
tlogger.go:116: INFO clusterresolver.go:223 [xds] [xds-cluster-resolver-lb 0xc000457880] build balancer config: {
"children": {
"priority-0-0": {
"config": [
{
"xds_cluster_impl_experimental": {
"cluster": "test-cluster-name",
"childPolicy": [
{
"weighted_target_experimental": {
"targets": {
"{\"subZone\":\"III\"}": {
"weight": 1,
"childPolicy": [
{
"round_robin": {}
}
]
}
}
}
}
]
}
}
],
"ignoreReresolutionRequests": true
}
},
"priorities": [
"priority-0-0"
]
} (t=+130.723651ms)
tlogger.go:116: INFO balancer.go:108 [xds] [priority-lb 0xc0001f20e0] Received update from resolver, balancer config: {
"children": {
"priority-0-0": {
"config": [
{
"xds_cluster_impl_experimental": {
"cluster": "test-cluster-name",
"childPolicy": [
{
"weighted_target_experimental": {
"targets": {
"{\"subZone\":\"III\"}": {
"weight": 1,
"childPolicy": [
{
"round_robin": {}
}
]
}
}
}
}
]
}
}
],
"ignoreReresolutionRequests": true
}
},
"priorities": [
"priority-0-0"
]
} (t=+131.093374ms)
tlogger.go:116: INFO clusterimpl.go:224 [xds] [xds-cluster-impl-lb 0xc0000d8900] Received update from resolver, balancer config: {
"cluster": "test-cluster-name",
"childPolicy": [
{
"weighted_target_experimental": {
"targets": {
"{\"subZone\":\"III\"}": {
"weight": 1,
"childPolicy": [
{
"round_robin": {}
}
]
}
}
}
}
]
} (t=+131.374092ms)
tlogger.go:116: INFO weightedtarget.go:84 [xds] [weighted-target-lb 0xc00007ea40] Received update from resolver, balancer config: {
"targets": {
"{\"subZone\":\"III\"}": {
"weight": 1,
"childPolicy": [
{
"round_robin": {}
}
]
}
}
} (t=+131.532102ms)
tlogger.go:116: INFO roundrobin.go:50 [roundrobin] roundrobinPicker: Build called with info: {map[0xc0001538c0:{{
"Addr": "2.2.2.2:2",
"ServerName": "",
"Attributes": null,
"BalancerAttributes": {},
"Type": 0,
"Metadata": null
}} 0xc00025e540:{{
"Addr": "3.3.3.3:3",
"ServerName": "",
"Attributes": null,
"BalancerAttributes": {},
"Type": 0,
"Metadata": null
}}]} (t=+131.843422ms)
tlogger.go:116: INFO balancergroup.go:499 [xds] [weighted-target-lb 0xc00007ea40] Balancer state update from locality {"subZone":"III"}, new state: {ConnectivityState:READY Picker:0xc000538600} (t=+131.930327ms)
tlogger.go:116: INFO aggregator.go:201 [xds] [weighted-target-lb 0xc00007ea40] Child pickers with config: map[{"subZone":"III"}:weight:1,picker:0xc000538600,state:READY,stateToAggregate:READY] (t=+132.009532ms)
tlogger.go:116: INFO aggregator.go:201 [xds] [weighted-target-lb 0xc00007ea40] Child pickers with config: map[{"subZone":"III"}:weight:1,picker:0xc000538600,state:READY,stateToAggregate:READY] (t=+132.093037ms)
tlogger.go:116: INFO balancergroup.go:499 [xds] [priority-lb 0xc0001f20e0] Balancer state update from locality priority-0-0, new state: {ConnectivityState:READY Picker:0xc00020ed20} (t=+132.206944ms)
tlogger.go:116: INFO balancergroup.go:499 [xds] [priority-lb 0xc0001f20e0] Balancer state update from locality priority-0-0, new state: {ConnectivityState:READY Picker:0xc00003d630} (t=+132.322952ms)
tlogger.go:116: INFO balancer_priority.go:92 [xds] [priority-lb 0xc0001f20e0] switching to ("priority-0-0", 0) in syncPriority (t=+132.[403](https://github.com/grpc/grpc-go/runs/7046249753?check_suite_focus=true#step:8:404)757ms)
balancer.go:129: testClientConn: RemoveSubConn(sc1)
eds_impl_test.go:321: timeout waiting for picker with expected behavior, error from previous picker: non-roundrobin want: [sc2 sc3], result: [sc1]
tlogger.go:116: INFO resource_resolver.go:274 [xds] [xds-cluster-resolver-lb 0xc000[457](https://github.com/grpc/grpc-go/runs/7046249753?check_suite_focus=true#step:8:458)880] EDS watch canceled on test-cluster-name (t=+1.233326344s)
balancer.go:129: testClientConn: RemoveSubConn(sc2)
balancer.go:129: testClientConn: RemoveSubConn(sc3)
balancer.go:129: testClientConn: RemoveSubConn(sc1)
tlogger.go:116: INFO clusterimpl.go:336 [xds] [xds-cluster-impl-lb 0xc0000d8900] Shutdown (t=+1.233527057s)
balancer.go:129: testClientConn: RemoveSubConn(sc3)
balancer.go:129: testClientConn: RemoveSubConn(sc1)
balancer.go:129: testClientConn: RemoveSubConn(sc2)
tlogger.go:116: INFO clusterresolver.go:311 [xds] [xds-cluster-resolver-lb 0xc000457880] Shutdown (t=+1.233633764s)
FAIL
FAIL google.golang.org/grpc/xds/internal/balancer/clusterresolver
Fails 1/10K times in google3, but seems to happen so much more frequently here.
