We read every piece of feedback, and take your input very seriously.
To see all available qualifiers, see our documentation.
Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.
By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.
Already on GitHub? Sign in to your account
--- FAIL: Test (28.17s) --- FAIL: Test/RLSinxDS (10.07s) tlogger.go:116: INFO server.go:685 [core] [Server #1392]Server created (t=+1.475067ms) tlogger.go:116: INFO server.go:881 [core] [Server #1392 ListenSocket #1393]ListenSocket created (t=+11.037977ms) tlogger.go:116: INFO server.go:685 [core] [Server #1394]Server created (t=+12.535477ms) tlogger.go:116: INFO server.go:881 [core] [Server #1394 ListenSocket #1395]ListenSocket created (t=+12.990055ms) tlogger.go:116: INFO server.go:685 [core] [Server #1396]Server created (t=+13.179521ms) tlogger.go:116: INFO server.go:881 [core] [Server #1396 ListenSocket #1397]ListenSocket created (t=+13.567755ms) tlogger.go:116: INFO clientconn.go:1654 [core] original dial target is: "xds:///my-service-client-side-xds" (t=+13.885731ms) tlogger.go:116: INFO clientconn.go:314 [core] [Channel #1398]Channel created (t=+13.979326ms) tlogger.go:116: INFO clientconn.go:193 [core] [Channel #1398]parsed dial target is: resolver.Target{URL:url.URL{Scheme:"xds", Opaque:"", User:(*url.Userinfo)(nil), Host:"", Path:"/my-service-client-side-xds", RawPath:"", OmitHost:false, ForceQuery:false, RawQuery:"", Fragment:"", RawFragment:""}} (t=+14.119428ms) tlogger.go:116: INFO clientconn.go:194 [core] [Channel #1398]Channel authority set to "my-service-client-side-xds" (t=+14.185983ms) tlogger.go:116: INFO xds_resolver.go:100 [xds] [xds-resolver 0x4000874120] Creating resolver for target: xds:///my-service-client-side-xds (t=+14.402457ms) tlogger.go:116: INFO client_refcounted.go:76 [xds] [xds-client 0x40008289a0] Created client with name "xds:///my-service-client-side-xds" and bootstrap configuration: { "xds_servers": [ { "server_uri": "passthrough:///127.0.0.1:32855", "channel_creds": [ { "type": "insecure" } ] } ], "certificate_providers": { "client-side-certificate-provider-instance": { "plugin_name": "file_watcher", "config": { "certificate_file": "/tmp/testClientSideXDS2749346559/cert.pem", "private_key_file": "/tmp/testClientSideXDS2749346559/key.pem", "ca_certificate_file": "/tmp/testClientSideXDS2749346559/ca.pem", "refresh_interval": "600s" } }, "server-side-certificate-provider-instance": { "plugin_name": "file_watcher", "config": { "certificate_file": "/tmp/testServerSideXDS3340599431/cert.pem", "private_key_file": "/tmp/testServerSideXDS3340599431/key.pem", "ca_certificate_file": "/tmp/testServerSideXDS3340599431/ca.pem", "refresh_interval": "600s" } } }, "server_listener_resource_name_template": "grpc/server?xds.resource.listening_address=%s", "client_default_listener_resource_name_template": "%s", "node": { "id": "75af46f0-4044-4315-8046-89599531c2cc", "locality": {} } } (t=+15.289856ms) tlogger.go:116: INFO client_refcounted.go:81 [xds] xDS node ID: 75af46f0-4044-4315-8046-89599531c2cc (t=+15.403459ms) tlogger.go:116: INFO clientconn.go:1654 [core] original dial target is: "passthrough:///127.0.0.1:32855" (t=+15.584818ms) tlogger.go:116: INFO clientconn.go:314 [core] [Channel #1399]Channel created (t=+15.672922ms) tlogger.go:116: INFO clientconn.go:193 [core] [Channel #1399]parsed dial target is: resolver.Target{URL:url.URL{Scheme:"passthrough", Opaque:"", User:(*url.Userinfo)(nil), Host:"", Path:"/127.0.0.1:32855", RawPath:"", OmitHost:false, ForceQuery:false, RawQuery:"", Fragment:"", RawFragment:""}} (t=+15.771406ms) tlogger.go:116: INFO clientconn.go:194 [core] [Channel #1399]Channel authority set to "127.0.0.1:32855" (t=+15.838492ms) tlogger.go:116: INFO resolver_wrapper.go:200 [core] [Channel #1399]Resolver state updated: { "Addresses": [ { "Addr": "127.0.0.1:32855", "ServerName": "", "Attributes": null, "BalancerAttributes": null, "Metadata": null } ], "Endpoints": [ { "Addresses": [ { "Addr": "127.0.0.1:32855", "ServerName": "", "Attributes": null, "BalancerAttributes": null, "Metadata": null } ], "Attributes": null } ], "ServiceConfig": null, "Attributes": null } (resolver returned new addresses) (t=+16.124166ms) tlogger.go:116: INFO balancer_wrapper.go:117 [core] [Channel #1399]Channel switches to new LB policy "pick_first" (t=+16.266632ms) tlogger.go:116: INFO clientconn.go:838 [core] [Channel #1399 SubChannel #1400]Subchannel created (t=+16.407445ms) tlogger.go:116: INFO clientconn.go:544 [core] [Channel #1399]Channel Connectivity change to CONNECTING (t=+16.490901ms) tlogger.go:116: INFO clientconn.go:314 [core] [Channel #1399]Channel exiting idle mode (t=+16.632646ms) tlogger.go:116: INFO clientconn.go:1199 [core] [Channel #1399 SubChannel #1400]Subchannel Connectivity change to CONNECTING (t=+16.784529ms) tlogger.go:116: INFO clientconn.go:1319 [core] [Channel #1399 SubChannel #1400]Subchannel picks a new address "127.0.0.1:32855" to connect (t=+16.950469ms) tlogger.go:116: INFO clientconn.go:314 [core] [Channel #1398]Channel exiting idle mode (t=+17.36279ms) tlogger.go:116: INFO clientconn.go:1199 [core] [Channel #1399 SubChannel #1400]Subchannel Connectivity change to READY (t=+18.840713ms) tlogger.go:116: INFO clientconn.go:544 [core] [Channel #1399]Channel Connectivity change to READY (t=+19.046688ms) tlogger.go:116: INFO config.go:237 [rls] rls: stale_age 0s is not less than max_age 0s, ignoring it (t=+23.890826ms) tlogger.go:116: INFO config.go:241 [rls] rls: max_age in route lookup config is 0s, using 5m0s (t=+23.976286ms) tlogger.go:116: INFO xds_resolver.go:284 [xds] [xds-resolver 0x4000874120] For Listener resource "my-service-client-side-xds" and RouteConfiguration resource "route-my-service-client-side-xds", generated service config: { "loadBalancingConfig": [ { "xds_cluster_manager_experimental": { "children": { "cluster_specifier_plugin:rls-csp": { "childPolicy": [ { "rls_experimental": { "routeLookupConfig": { "grpcKeybuilders": [ { "names": [ { "service": "grpc.testing.TestService" } ] } ], "lookupService": "127.0.0.1:33241", "lookupServiceTimeout": "10s", "cacheSizeBytes": "1024" }, "childPolicy": [ { "cds_experimental": {} } ], "childPolicyConfigTargetFieldName": "cluster" } } ] } } } } ] } (t=+24.880113ms) tlogger.go:116: INFO config.go:237 [rls] rls: stale_age 0s is not less than max_age 0s, ignoring it (t=+25.458995ms) tlogger.go:116: INFO config.go:241 [rls] rls: max_age in route lookup config is 0s, using 5m0s (t=+25.559013ms) tlogger.go:116: INFO resolver_wrapper.go:200 [core] [Channel #1398]Resolver state updated: { "Addresses": null, "Endpoints": [], "ServiceConfig": { "Config": { "Config": null, "Methods": {} }, "Err": null }, "Attributes": { "\u003c%!p(resolver.csKeyType=grpc.internal.resolver.configSelector)\u003e": "\u003c0x40005d8140\u003e", "\u003c%!p(xdsclient.clientKeyType=grpc.xds.internal.client.Client)\u003e": "\u003c0x4000932a90\u003e" } } (service config updated) (t=+25.833586ms) tlogger.go:116: INFO balancer_wrapper.go:117 [core] [Channel #1398]Channel switches to new LB policy "xds_cluster_manager_experimental" (t=+25.998304ms) tlogger.go:116: INFO clustermanager.go:59 [xds] [xds-cluster-manager-lb 0x40005f2520] Created (t=+26.126323ms) tlogger.go:116: INFO balancergroup.go:299 [xds] [xds-cluster-manager-lb 0x40005f2520] Adding child policy of type "rls_experimental" for child "cluster_specifier_plugin:rls-csp" (t=+26.204219ms) tlogger.go:116: INFO balancergroup.go:102 [xds] [xds-cluster-manager-lb 0x40005f2520] Creating child policy of type "rls_experimental" for child "cluster_specifier_plugin:rls-csp" (t=+26.275252ms) tlogger.go:116: INFO balancer.go:306 [rls] [rls-experimental-lb 0x40004021e0] Delaying picker updates until config is propagated to and processed by child policies (t=+26.431925ms) tlogger.go:116: INFO balancer.go:359 [rls] [rls-experimental-lb 0x40004021e0] Creating control channel to RLS server at: 127.0.0.1:33241 (t=+26.550216ms) tlogger.go:116: INFO clientconn.go:1654 [core] original dial target is: "127.0.0.1:33241" (t=+26.68641ms) tlogger.go:116: INFO clientconn.go:314 [core] [Channel #1403]Channel created (t=+26.834377ms) tlogger.go:116: INFO clientconn.go:193 [core] [Channel #1403]parsed dial target is: resolver.Target{URL:url.URL{Scheme:"passthrough", Opaque:"", User:(*url.Userinfo)(nil), Host:"", Path:"/127.0.0.1:33241", RawPath:"", OmitHost:false, ForceQuery:false, RawQuery:"", Fragment:"", RawFragment:""}} (t=+26.941307ms) tlogger.go:116: INFO clientconn.go:194 [core] [Channel #1403]Channel authority set to "my-service-client-side-xds" (t=+27.020395ms) tlogger.go:116: INFO resolver_wrapper.go:200 [core] [Channel #1403]Resolver state updated: { "Addresses": [ { "Addr": "127.0.0.1:33241", "ServerName": "", "Attributes": null, "BalancerAttributes": null, "Metadata": null } ], "Endpoints": [ { "Addresses": [ { "Addr": "127.0.0.1:33241", "ServerName": "", "Attributes": null, "BalancerAttributes": null, "Metadata": null } ], "Attributes": null } ], "ServiceConfig": null, "Attributes": null } (resolver returned new addresses) (t=+27.31767ms) tlogger.go:116: INFO balancer_wrapper.go:117 [core] [Channel #1403]Channel switches to new LB policy "pick_first" (t=+27.463323ms) tlogger.go:116: INFO clientconn.go:838 [core] [Channel #1403 SubChannel #1404]Subchannel created (t=+27.626087ms) tlogger.go:116: INFO clientconn.go:544 [core] [Channel #1403]Channel Connectivity change to CONNECTING (t=+27.711326ms) tlogger.go:116: INFO clientconn.go:314 [core] [Channel #1403]Channel exiting idle mode (t=+27.848222ms) tlogger.go:116: INFO control_channel.go:83 [rls] [rls-control-channel 0x40004f50c0] Control channel created to RLS server at: 127.0.0.1:33241 (t=+27.990989ms) tlogger.go:116: INFO balancer.go:384 [rls] [rls-experimental-lb 0x40004021e0] Child policy changed to "cds_experimental" (t=+28.156959ms) tlogger.go:116: INFO balancer.go:253 [rls] [rls-experimental-lb 0x40004021e0] Resuming picker updates after config propagation to child policies (t=+28.316718ms) tlogger.go:116: INFO balancer.go:551 [rls] [rls-experimental-lb 0x40004021e0] New balancer.State: {ConnectivityState:IDLE Picker:0x40006b8ab0} (t=+28.513757ms) tlogger.go:116: INFO balancergroup.go:538 [xds] [xds-cluster-manager-lb 0x40005f2520] Balancer state update from child cluster_specifier_plugin:rls-csp, new state: {ConnectivityState:IDLE Picker:0x40006b8ab0} (t=+28.623772ms) tlogger.go:116: INFO balancerstateaggregator.go:147 [xds] [xds-cluster-manager-lb 0x40005f2520] State update from sub-balancer "cluster_specifier_plugin:rls-csp": {ConnectivityState:IDLE Picker:0x40006b8ab0} (t=+28.781266ms) tlogger.go:116: INFO balancerstateaggregator.go:191 [xds] [xds-cluster-manager-lb 0x40005f2520] Child pickers: map[cluster_specifier_plugin:rls-csp:picker:0x40006b8ab0,state:IDLE,stateToAggregate:IDLE] (t=+28.934573ms) tlogger.go:116: INFO clientconn.go:1199 [core] [Channel #1403 SubChannel #1404]Subchannel Connectivity change to CONNECTING (t=+29.073443ms) tlogger.go:116: INFO control_channel.go:135 [rls] [rls-control-channel 0x40004f50c0] Starting connectivity state monitoring goroutine (t=+29.231969ms) tlogger.go:116: INFO clientconn.go:1319 [core] [Channel #1403 SubChannel #1404]Subchannel picks a new address "127.0.0.1:33241" to connect (t=+29.406095ms) tlogger.go:116: INFO clientconn.go:1199 [core] [Channel #1403 SubChannel #1404]Subchannel Connectivity change to READY (t=+30.290779ms) tlogger.go:116: INFO clientconn.go:544 [core] [Channel #1403]Channel Connectivity change to READY (t=+30.446319ms) tlogger.go:116: INFO control_channel.go:170 [rls] [rls-control-channel 0x40004f50c0] Connectivity state is READY (t=+30.565723ms) tlogger.go:116: INFO picker.go:273 [rls] [rls-picker 0x40006b8ab0] Received RLS response for key {path:/grpc.testing.TestService/EmptyCall keys:} with targets [cluster-my-service-client-side-xds], headerData "", err: <nil> (t=+31.799681ms) tlogger.go:116: INFO child_policy.go:84 [rls] [rls-child-policy-wrapper cluster-my-service-client-side-xds 0x4000714360] Created (t=+31.958008ms) tlogger.go:116: INFO balancergroup.go:299 [rls] [rls-experimental-lb 0x40004021e0] Adding child policy of type "cds_experimental" for child "cluster-my-service-client-side-xds" (t=+32.024963ms) tlogger.go:116: INFO balancergroup.go:102 [rls] [rls-experimental-lb 0x40004021e0] Creating child policy of type "cds_experimental" for child "cluster-my-service-client-side-xds" (t=+32.115262ms) tlogger.go:116: INFO cdsbalancer.go:109 [xds] [cds-lb 0x40006a0ea0] Created (t=+32.230036ms) tlogger.go:116: INFO cdsbalancer.go:121 [xds] [cds-lb 0x40006a0ea0] xDS credentials in use: false (t=+32.345652ms) tlogger.go:116: INFO balancer.go:681 [rls] [rls-experimental-lb 0x40004021e0] Child policy "cluster-my-service-client-side-xds" added to BalancerGroup (t=+32.424289ms) tlogger.go:116: INFO balancer.go:470 [rls] [rls-experimental-lb 0x40004021e0] Pushing new state to child policy "cluster-my-service-client-side-xds": {ResolverState:{Addresses:[] Endpoints:[] ServiceConfig:0x40005f2440 Attributes:{"<%!p(xdsclient.clientKeyType=grpc.xds.internal.client.Client)>": "<0x4000932a90>" , "<%!p(resolver.csKeyType=grpc.internal.resolver.configSelector)>": "<0x40005d8140>" }} BalancerConfig:0x4000842a60} (t=+32.593646ms) tlogger.go:116: INFO cdsbalancer.go:290 [xds] [cds-lb 0x40006a0ea0] Received balancer config update: { "LoadBalancingConfig": null, "Cluster": "cluster-my-service-client-side-xds" } (t=+32.685918ms) tlogger.go:116: INFO picker.go:279 [rls] [rls-picker 0x40006b8ab0] Removing pending request entry for key {path:/grpc.testing.TestService/EmptyCall keys:} (t=+32.98098ms) tlogger.go:116: INFO balancer.go:551 [rls] [rls-experimental-lb 0x40004021e0] New balancer.State: {ConnectivityState:CONNECTING Picker:0x4000600000} (t=+33.188798ms) tlogger.go:116: INFO balancergroup.go:538 [xds] [xds-cluster-manager-lb 0x40005f2520] Balancer state update from child cluster_specifier_plugin:rls-csp, new state: {ConnectivityState:CONNECTING Picker:0x4000600000} (t=+33.35019ms) tlogger.go:116: INFO balancerstateaggregator.go:147 [xds] [xds-cluster-manager-lb 0x40005f2520] State update from sub-balancer "cluster_specifier_plugin:rls-csp": {ConnectivityState:CONNECTING Picker:0x4000600000} (t=+33.513876ms) tlogger.go:116: INFO balancerstateaggregator.go:191 [xds] [xds-cluster-manager-lb 0x40005f2520] Child pickers: map[cluster_specifier_plugin:rls-csp:picker:0x4000600000,state:CONNECTING,stateToAggregate:CONNECTING] (t=+33.685046ms) tlogger.go:116: INFO clientconn.go:544 [core] [Channel #1398]Channel Connectivity change to CONNECTING (t=+33.857729ms) tlogger.go:116: INFO cdsbalancer.go:414 [xds] [cds-lb 0x40006a0ea0] Received Cluster resource: { "ClusterType": 0, "ClusterName": "cluster-my-service-client-side-xds", "EDSServiceName": "endpoints-my-service-client-side-xds", "LRSServerConfig": null, "SecurityCfg": null, "MaxRequests": null, "DNSHostName": "", "PrioritizedClusterNames": null, "LBPolicy": [ { "xds_wrr_locality_experimental": { "childPolicy": [ { "round_robin": {} } ] } } ], "OutlierDetection": null, "Raw": { "type_url": "type.googleapis.com/envoy.config.cluster.v3.Cluster", "value": "CiJjbHVzdGVyLW15LXNlcnZpY2UtY2xpZW50LXNpZGUteGRzGioKAhoAEiRlbmRwb2ludHMtbXktc2VydmljZS1jbGllbnQtc2lkZS14ZHMQAw==" }, "TelemetryLabels": { "csm.service_name": "unknown", "csm.service_namespace_name": "unknown" } } (t=+34.587844ms) tlogger.go:116: INFO clusterresolver.go:85 [xds] [xds-cluster-resolver-lb 0x400068d880] Created (t=+34.782758ms) tlogger.go:116: INFO cdsbalancer.go:455 [xds] [cds-lb 0x40006a0ea0] Created child policy 0x400068d880 of type cluster_resolver_experimental (t=+34.975759ms) tlogger.go:116: INFO balancer.go:76 [xds] [priority-lb 0x400074b3b0] Created (t=+36.840934ms) tlogger.go:116: INFO balancergroup.go:538 [rls] [rls-experimental-lb 0x40004021e0] Balancer state update from child cluster-my-service-client-side-xds, new state: {ConnectivityState:CONNECTING Picker:0x4000119490} (t=+37.970666ms) tlogger.go:116: INFO balancergroup.go:299 [xds] [priority-lb 0x400074b3b0] Adding child policy of type "outlier_detection_experimental" for child "priority-0-0" (t=+38.095951ms) tlogger.go:116: INFO balancer.go:656 [rls] [rls-experimental-lb 0x40004021e0] Child policy "cluster-my-service-client-side-xds" has new state {ConnectivityState:CONNECTING Picker:0x4000119490} (t=+38.240142ms) tlogger.go:116: INFO balancer.go:551 [rls] [rls-experimental-lb 0x40004021e0] New balancer.State: {ConnectivityState:CONNECTING Picker:0x4000728000} (t=+38.382027ms) tlogger.go:116: INFO balancergroup.go:538 [xds] [xds-cluster-manager-lb 0x40005f2520] Balancer state update from child cluster_specifier_plugin:rls-csp, new state: {ConnectivityState:CONNECTING Picker:0x4000728000} (t=+38.524824ms) tlogger.go:116: INFO balancerstateaggregator.go:147 [xds] [xds-cluster-manager-lb 0x40005f2520] State update from sub-balancer "cluster_specifier_plugin:rls-csp": {ConnectivityState:CONNECTING Picker:0x4000728000} (t=+38.658003ms) tlogger.go:116: INFO balancerstateaggregator.go:191 [xds] [xds-cluster-manager-lb 0x40005f2520] Child pickers: map[cluster_specifier_plugin:rls-csp:picker:0x4000728000,state:CONNECTING,stateToAggregate:CONNECTING] (t=+38.802453ms) tlogger.go:116: INFO balancergroup.go:102 [xds] [priority-lb 0x400074b3b0] Creating child policy of type "outlier_detection_experimental" for child "priority-0-0" (t=+39.006024ms) tlogger.go:116: INFO balancer.go:74 [xds] [outlier-detection-lb 0x400069e270] Created (t=+39.115028ms) tlogger.go:116: INFO clusterimpl.go:76 [xds] [xds-cluster-impl-lb 0x4000888000] Created (t=+39.239911ms) tlogger.go:116: INFO weightedtarget.go:66 [xds] [weighted-target-lb 0x400006ea60] Created (t=+39.509585ms) tlogger.go:116: INFO balancer.go:88 [xds] [wrrlocality-lb 0x40006a6cf0] Created (t=+39.649908ms) tlogger.go:116: INFO balancergroup.go:299 [xds] [weighted-target-lb 0x400006ea60] Adding child policy of type "round_robin" for child "{\"region\":\"region-1\",\"zone\":\"zone-1\",\"subZone\":\"subzone-1\"}" (t=+39.874608ms) tlogger.go:116: INFO balancergroup.go:102 [xds] [weighted-target-lb 0x400006ea60] Creating child policy of type "round_robin" for child "{\"region\":\"region-1\",\"zone\":\"zone-1\",\"subZone\":\"subzone-1\"}" (t=+39.957412ms) tlogger.go:116: INFO clientconn.go:838 [core] [Channel #1398 SubChannel #1407]Subchannel created (t=+40.171643ms) tlogger.go:116: INFO roundrobin.go:50 [roundrobin] roundrobinPicker: Build called with info: {map[]} (t=+40.375033ms) tlogger.go:116: INFO balancergroup.go:538 [xds] [weighted-target-lb 0x400006ea60] Balancer state update from child {"region":"region-1","zone":"zone-1","subZone":"subzone-1"}, new state: {ConnectivityState:CONNECTING Picker:0x4000013660} (t=+40.543398ms) tlogger.go:116: INFO aggregator.go:252 [xds] [weighted-target-lb 0x400006ea60] Child pickers with config: map[{"region":"region-1","zone":"zone-1","subZone":"subzone-1"}:weight:1,picker:0x4000013660,state:CONNECTING,stateToAggregate:CONNECTING] (t=+40.707886ms) tlogger.go:116: INFO clientconn.go:1199 [core] [Channel #1398 SubChannel #1407]Subchannel Connectivity change to CONNECTING (t=+40.971707ms) tlogger.go:116: INFO balancergroup.go:538 [xds] [priority-lb 0x400074b3b0] Balancer state update from child priority-0-0, new state: {ConnectivityState:CONNECTING Picker:0x4000940348} (t=+41.153438ms) tlogger.go:116: INFO balancergroup.go:538 [rls] [rls-experimental-lb 0x40004021e0] Balancer state update from child cluster-my-service-client-side-xds, new state: {ConnectivityState:CONNECTING Picker:0x4000940348} (t=+41.406772ms) tlogger.go:116: INFO balancergroup.go:538 [xds] [weighted-target-lb 0x400006ea60] Balancer state update from child {"region":"region-1","zone":"zone-1","subZone":"subzone-1"}, new state: {ConnectivityState:CONNECTING Picker:0x4000013660} (t=+41.543626ms) tlogger.go:116: INFO aggregator.go:252 [xds] [weighted-target-lb 0x400006ea60] Child pickers with config: map[{"region":"region-1","zone":"zone-1","subZone":"subzone-1"}:weight:1,picker:0x4000013660,state:CONNECTING,stateToAggregate:CONNECTING] (t=+41.719354ms) tlogger.go:116: INFO balancergroup.go:538 [xds] [priority-lb 0x400074b3b0] Balancer state update from child priority-0-0, new state: {ConnectivityState:CONNECTING Picker:0x4000b069f0} (t=+41.885816ms) tlogger.go:116: INFO balancer.go:656 [rls] [rls-experimental-lb 0x40004021e0] Child policy "cluster-my-service-client-side-xds" has new state {ConnectivityState:CONNECTING Picker:0x4000940348} (t=+42.08513ms) tlogger.go:116: INFO balancer.go:551 [rls] [rls-experimental-lb 0x40004021e0] New balancer.State: {ConnectivityState:CONNECTING Picker:0x4000a2d050} (t=+42.198181ms) tlogger.go:116: INFO clientconn.go:1319 [core] [Channel #1398 SubChannel #1407]Subchannel picks a new address "localhost:34183" to connect (t=+42.323355ms) tlogger.go:116: INFO balancergroup.go:538 [rls] [rls-experimental-lb 0x40004021e0] Balancer state update from child cluster-my-service-client-side-xds, new state: {ConnectivityState:CONNECTING Picker:0x4000b069f0} (t=+42.437439ms) tlogger.go:116: INFO balancergroup.go:538 [xds] [xds-cluster-manager-lb 0x40005f2520] Balancer state update from child cluster_specifier_plugin:rls-csp, new state: {ConnectivityState:CONNECTING Picker:0x4000a2d050} (t=+42.564627ms) tlogger.go:116: INFO balancerstateaggregator.go:147 [xds] [xds-cluster-manager-lb 0x40005f2520] State update from sub-balancer "cluster_specifier_plugin:rls-csp": {ConnectivityState:CONNECTING Picker:0x4000a2d050} (t=+42.706241ms) tlogger.go:116: INFO balancerstateaggregator.go:191 [xds] [xds-cluster-manager-lb 0x40005f2520] Child pickers: map[cluster_specifier_plugin:rls-csp:picker:0x4000a2d050,state:CONNECTING,stateToAggregate:CONNECTING] (t=+42.859348ms) tlogger.go:116: INFO balancer.go:656 [rls] [rls-experimental-lb 0x40004021e0] Child policy "cluster-my-service-client-side-xds" has new state {ConnectivityState:CONNECTING Picker:0x4000b069f0} (t=+43.052789ms) tlogger.go:116: INFO balancer.go:551 [rls] [rls-experimental-lb 0x40004021e0] New balancer.State: {ConnectivityState:CONNECTING Picker:0x4000a2d0e0} (t=+43.357379ms) tlogger.go:116: INFO balancergroup.go:538 [xds] [xds-cluster-manager-lb 0x40005f2520] Balancer state update from child cluster_specifier_plugin:rls-csp, new state: {ConnectivityState:CONNECTING Picker:0x4000a2d0e0} (t=+43.9582ms) tlogger.go:116: INFO clientconn.go:1199 [core] [Channel #1398 SubChannel #1407]Subchannel Connectivity change to READY (t=+44.327432ms) tlogger.go:116: INFO balancerstateaggregator.go:147 [xds] [xds-cluster-manager-lb 0x40005f2520] State update from sub-balancer "cluster_specifier_plugin:rls-csp": {ConnectivityState:CONNECTING Picker:0x4000a2d0e0} (t=+44.504161ms) tlogger.go:116: INFO balancerstateaggregator.go:191 [xds] [xds-cluster-manager-lb 0x40005f2520] Child pickers: map[cluster_specifier_plugin:rls-csp:picker:0x4000a2d0e0,state:CONNECTING,stateToAggregate:CONNECTING] (t=+44.603817ms) tlogger.go:116: INFO roundrobin.go:50 [roundrobin] roundrobinPicker: Build called with info: {map[0x400006ed00:{{Addr: "localhost:34183", ServerName: "", BalancerAttributes: {"<%!p(internal.localityKeyType=grpc.xds.internal.address.locality)>": "<%!p(internal.LocalityID={region-1 zone-1 subzone-1})>" , "<%!p(wrrlocality.attributeKey={})>": "Locality Weight: 1" , "<%!p(hierarchy.pathKeyType=grpc.internal.address.hierarchical_path)>": "<0x40005f35f0>" , "<%!p(weightedroundrobin.attributeKey={})>": "Weight: 1" }}}]} (t=+44.965634ms) tlogger.go:116: INFO balancergroup.go:538 [xds] [weighted-target-lb 0x400006ea60] Balancer state update from child {"region":"region-1","zone":"zone-1","subZone":"subzone-1"}, new state: {ConnectivityState:READY Picker:0x400006f420} (t=+45.083193ms) tlogger.go:116: INFO aggregator.go:252 [xds] [weighted-target-lb 0x400006ea60] Child pickers with config: map[{"region":"region-1","zone":"zone-1","subZone":"subzone-1"}:weight:1,picker:0x400006f420,state:READY,stateToAggregate:READY] (t=+45.166449ms) tlogger.go:116: INFO balancergroup.go:538 [xds] [priority-lb 0x400074b3b0] Balancer state update from child priority-0-0, new state: {ConnectivityState:READY Picker:0x40009404b0} (t=+45.271686ms) tlogger.go:116: INFO balancergroup.go:538 [rls] [rls-experimental-lb 0x40004021e0] Balancer state update from child cluster-my-service-client-side-xds, new state: {ConnectivityState:READY Picker:0x40009404b0} (t=+45.379247ms) tlogger.go:116: INFO balancer.go:656 [rls] [rls-experimental-lb 0x40004021e0] Child policy "cluster-my-service-client-side-xds" has new state {ConnectivityState:READY Picker:0x40009404b0} (t=+45.489403ms) tlogger.go:116: INFO balancer.go:551 [rls] [rls-experimental-lb 0x40004021e0] New balancer.State: {ConnectivityState:READY Picker:0x4000728360} (t=+45.559965ms) tlogger.go:116: INFO balancergroup.go:538 [xds] [xds-cluster-manager-lb 0x40005f2520] Balancer state update from child cluster_specifier_plugin:rls-csp, new state: {ConnectivityState:READY Picker:0x4000728360} (t=+45.614316ms) tlogger.go:116: INFO balancerstateaggregator.go:147 [xds] [xds-cluster-manager-lb 0x40005f2520] State update from sub-balancer "cluster_specifier_plugin:rls-csp": {ConnectivityState:READY Picker:0x4000728360} (t=+45.676292ms) tlogger.go:116: INFO balancerstateaggregator.go:191 [xds] [xds-cluster-manager-lb 0x40005f2520] Child pickers: map[cluster_specifier_plugin:rls-csp:picker:0x4000728360,state:READY,stateToAggregate:READY] (t=+45.743538ms) tlogger.go:116: INFO clientconn.go:544 [core] [Channel #1398]Channel Connectivity change to READY (t=+45.848484ms) tlogger.go:116: INFO clientconn.go:544 [core] [Channel #1398]Channel Connectivity change to SHUTDOWN (t=+47.04459ms) tlogger.go:116: INFO resolver_wrapper.go:100 [core] [Channel #1398]Closing the name resolver (t=+47.225047ms) tlogger.go:116: INFO balancer_wrapper.go:155 [core] [Channel #1398]ccBalancerWrapper: closing (t=+47.357435ms) tlogger.go:116: INFO control_channel.go:188 [rls] [rls-control-channel 0x40004f50c0] Closing control channel (t=+47.541739ms) tlogger.go:116: INFO clientconn.go:544 [core] [Channel #1403]Channel Connectivity change to SHUTDOWN (t=+47.798832ms) tlogger.go:116: INFO resolver_wrapper.go:100 [core] [Channel #1403]Closing the name resolver (t=+47.965323ms) tlogger.go:116: INFO balancer_wrapper.go:155 [core] [Channel #1403]ccBalancerWrapper: closing (t=+48.145059ms) tlogger.go:116: INFO watch_service.go:56 [xds] [xds-resolver 0x4000874120] Canceling watch on Listener resource "my-service-client-side-xds" (t=+48.327691ms) tlogger.go:116: INFO watch_service.go:91 [xds] [xds-resolver 0x4000874120] Canceling watch on RouteConfiguration resource "route-my-service-client-side-xds" (t=+48.521032ms) tlogger.go:116: INFO clientconn.go:1199 [core] [Channel #1403 SubChannel #1404]Subchannel Connectivity change to SHUTDOWN (t=+48.629343ms) tlogger.go:116: INFO clientconn.go:1527 [core] [Channel #1403 SubChannel #1404]Subchannel deleted (t=+48.783461ms) tlogger.go:116: WARNING ads_stream.go:471 [xds] [xds-client 0x40008289a0] [xds-channel 0x4000b84ea0] [ads-stream 0x4000924700] Sending ADS request for type "type.googleapis.com/envoy.config.route.v3.RouteConfiguration", resources: [], version: "1", nonce: "2" failed: EOF (t=+48.960404ms) tlogger.go:116: WARNING ads_stream.go:514 [xds] [xds-client 0x40008289a0] [xds-channel 0x4000b84ea0] [ads-stream 0x4000924700] ADS stream closed: rpc error: code = Canceled desc = context canceled (t=+49.182699ms) tlogger.go:116: INFO ads_stream.go:178 [xds] [xds-client 0x40008289a0] [xds-channel 0x4000b84ea0] [ads-stream 0x4000924700] Stopping ADS stream (t=+49.356504ms) tlogger.go:116: INFO clientconn.go:544 [core] [Channel #1399]Channel Connectivity change to SHUTDOWN (t=+49.53074ms) tlogger.go:116: INFO resolver_wrapper.go:100 [core] [Channel #1399]Closing the name resolver (t=+49.687242ms) tlogger.go:116: INFO clientconn.go:314 [core] [Channel #1403]Channel deleted (t=+49.835999ms) tlogger.go:116: INFO balancer_wrapper.go:155 [core] [Channel #1399]ccBalancerWrapper: closing (t=+49.993775ms) tlogger.go:116: INFO clusterimpl.go:350 [xds] [xds-cluster-impl-lb 0x4000888000] Shutdown (t=+50.139897ms) tlogger.go:116: INFO clientconn.go:1199 [core] [Channel #1399 SubChannel #1400]Subchannel Connectivity change to SHUTDOWN (t=+50.327329ms) tlogger.go:116: INFO clientconn.go:1527 [core] [Channel #1399 SubChannel #1400]Subchannel deleted (t=+50.476678ms) tlogger.go:116: INFO balancergroup.go:369 [xds] [priority-lb 0x400074b3b0] Removing child policy for child "priority-0-0" (t=+50.861556ms) tlogger.go:116: INFO clusterresolver.go:355 [xds] [xds-cluster-resolver-lb 0x400068d880] Shutdown (t=+50.973375ms) tlogger.go:116: INFO clientconn.go:314 [core] [Channel #1399]Channel deleted (t=+51.147703ms) tlogger.go:116: INFO cdsbalancer.go:380 [xds] [cds-lb 0x40006a0ea0] Shutdown (t=+51.2971ms) tlogger.go:116: INFO channel.go:145 [xds] [xds-client 0x40008289a0] [xds-channel 0x4000b84ea0] Shutdown (t=+51.410103ms) tlogger.go:116: INFO clustermanager.go:197 [xds] [xds-cluster-manager-lb 0x40005f2520] Shutdown (t=+51.55903ms) tlogger.go:116: INFO clientimpl.go:185 [xds] [xds-client 0x40008289a0] Shutdown (t=+51.661892ms) tlogger.go:116: INFO xds_resolver.go:253 [xds] [xds-resolver 0x4000874120] Shutdown (t=+51.743415ms) tlogger.go:116: INFO clientconn.go:1199 [core] [Channel #1398 SubChannel #1407]Subchannel Connectivity change to SHUTDOWN (t=+51.920946ms) tlogger.go:116: INFO clientconn.go:1527 [core] [Channel #1398 SubChannel #1407]Subchannel deleted (t=+51.996788ms) tlogger.go:116: INFO clientconn.go:314 [core] [Channel #1398]Channel deleted (t=+52.350349ms) tlogger.go:116: INFO server.go:817 [core] [Server #1394 ListenSocket #1395]ListenSocket deleted (t=+52.533972ms) tlogger.go:116: INFO server.go:817 [core] [Server #1396 ListenSocket #1397]ListenSocket deleted (t=+52.772939ms) tlogger.go:116: INFO server.go:817 [core] [Server #1392 ListenSocket #1393]ListenSocket deleted (t=+52.979656ms) tlogger.go:116: INFO server.go:685 [core] [Server #1410]Server created (t=+53.780894ms) tlogger.go:116: INFO server.go:881 [core] [Server #1410 ListenSocket #1411]ListenSocket created (t=+54.196964ms) tlogger.go:116: INFO server.go:685 [core] [Server #1412]Server created (t=+55.709439ms) tlogger.go:116: INFO server.go:881 [core] [Server #1412 ListenSocket #1413]ListenSocket created (t=+56.114518ms) tlogger.go:116: INFO server.go:685 [core] [Server #1414]Server created (t=+56.299833ms) tlogger.go:116: INFO server.go:881 [core] [Server #1414 ListenSocket #1415]ListenSocket created (t=+56.641574ms) tlogger.go:116: INFO clientconn.go:1654 [core] original dial target is: "xds:///my-service-client-side-xds" (t=+56.970186ms) tlogger.go:116: INFO clientconn.go:314 [core] [Channel #1416]Channel created (t=+57.07945ms) tlogger.go:116: INFO clientconn.go:193 [core] [Channel #1416]parsed dial target is: resolver.Target{URL:url.URL{Scheme:"xds", Opaque:"", User:(*url.Userinfo)(nil), Host:"", Path:"/my-service-client-side-xds", RawPath:"", OmitHost:false, ForceQuery:false, RawQuery:"", Fragment:"", RawFragment:""}} (t=+57.173977ms) tlogger.go:116: INFO clientconn.go:194 [core] [Channel #1416]Channel authority set to "my-service-client-side-xds" (t=+57.236474ms) tlogger.go:116: INFO xds_resolver.go:100 [xds] [xds-resolver 0x40002b38c0] Creating resolver for target: xds:///my-service-client-side-xds (t=+57.466264ms) tlogger.go:116: INFO client_refcounted.go:76 [xds] [xds-client 0x4000a715e0] Created client with name "xds:///my-service-client-side-xds" and bootstrap configuration: { "xds_servers": [ { "server_uri": "passthrough:///127.0.0.1:36257", "channel_creds": [ { "type": "insecure" } ] } ], "certificate_providers": { "client-side-certificate-provider-instance": { "plugin_name": "file_watcher", "config": { "certificate_file": "/tmp/testClientSideXDS2565592037/cert.pem", "private_key_file": "/tmp/testClientSideXDS2565592037/key.pem", "ca_certificate_file": "/tmp/testClientSideXDS2565592037/ca.pem", "refresh_interval": "600s" } }, "server-side-certificate-provider-instance": { "plugin_name": "file_watcher", "config": { "certificate_file": "/tmp/testServerSideXDS179257062/cert.pem", "private_key_file": "/tmp/testServerSideXDS179257062/key.pem", "ca_certificate_file": "/tmp/testServerSideXDS179257062/ca.pem", "refresh_interval": "600s" } } }, "server_listener_resource_name_template": "grpc/server?xds.resource.listening_address=%s", "client_default_listener_resource_name_template": "%s", "node": { "id": "2d64ef82-d914-49c1-b466-c551c69ab2b4", "locality": {} } } (t=+58.289022ms) tlogger.go:116: INFO client_refcounted.go:81 [xds] xDS node ID: 2d64ef82-d914-49c1-b466-c551c69ab2b4 (t=+58.395851ms) tlogger.go:116: INFO clientconn.go:1654 [core] original dial target is: "passthrough:///127.0.0.1:36257" (t=+58.573383ms) tlogger.go:116: INFO clientconn.go:314 [core] [Channel #1417]Channel created (t=+58.653303ms) tlogger.go:116: INFO clientconn.go:193 [core] [Channel #1417]parsed dial target is: resolver.Target{URL:url.URL{Scheme:"passthrough", Opaque:"", User:(*url.Userinfo)(nil), Host:"", Path:"/127.0.0.1:36257", RawPath:"", OmitHost:false, ForceQuery:false, RawQuery:"", Fragment:"", RawFragment:""}} (t=+58.742279ms) tlogger.go:116: INFO clientconn.go:194 [core] [Channel #1417]Channel authority set to "127.0.0.1:36257" (t=+58.814204ms) tlogger.go:116: INFO resolver_wrapper.go:200 [core] [Channel #1417]Resolver state updated: { "Addresses": [ { "Addr": "127.0.0.1:36257", "ServerName": "", "Attributes": null, "BalancerAttributes": null, "Metadata": null } ], "Endpoints": [ { "Addresses": [ { "Addr": "127.0.0.1:36257", "ServerName": "", "Attributes": null, "BalancerAttributes": null, "Metadata": null } ], "Attributes": null } ], "ServiceConfig": null, "Attributes": null } (resolver returned new addresses) (t=+59.115276ms) tlogger.go:116: INFO balancer_wrapper.go:117 [core] [Channel #1417]Channel switches to new LB policy "pick_first" (t=+59.268894ms) tlogger.go:116: INFO clientconn.go:838 [core] [Channel #1417 SubChannel #1418]Subchannel created (t=+59.391693ms) tlogger.go:116: INFO clientconn.go:544 [core] [Channel #1417]Channel Connectivity change to CONNECTING (t=+59.472474ms) tlogger.go:116: INFO clientconn.go:314 [core] [Channel #1417]Channel exiting idle mode (t=+59.623787ms) tlogger.go:116: INFO clientconn.go:1199 [core] [Channel #1417 SubChannel #1418]Subchannel Connectivity change to CONNECTING (t=+59.84884ms) tlogger.go:116: INFO clientconn.go:1319 [core] [Channel #1417 SubChannel #1418]Subchannel picks a new address "127.0.0.1:36257" to connect (t=+60.016283ms) tlogger.go:116: INFO clientconn.go:314 [core] [Channel #1416]Channel exiting idle mode (t=+60.307556ms) tlogger.go:116: INFO clientconn.go:1199 [core] [Channel #1417 SubChannel #1418]Subchannel Connectivity change to READY (t=+60.919531ms) tlogger.go:116: INFO clientconn.go:544 [core] [Channel #1417]Channel Connectivity change to READY (t=+61.154521ms) tlogger.go:116: INFO config.go:237 [rls] rls: stale_age 0s is not less than max_age 0s, ignoring it (t=+64.590414ms) tlogger.go:116: INFO config.go:241 [rls] rls: max_age in route lookup config is 0s, using 5m0s (t=+64.672047ms) tlogger.go:116: INFO xds_resolver.go:284 [xds] [xds-resolver 0x40002b38c0] For Listener resource "my-service-client-side-xds" and RouteConfiguration resource "route-my-service-client-side-xds", generated service config: { "loadBalancingConfig": [ { "xds_cluster_manager_experimental": { "children": { "cluster_specifier_plugin:rls-csp": { "childPolicy": [ { "rls_experimental": { "routeLookupConfig": { "grpcKeybuilders": [ { "names": [ { "service": "grpc.testing.TestService" } ] } ], "lookupService": "127.0.0.1:34301", "lookupServiceTimeout": "10s", "cacheSizeBytes": "1024" }, "childPolicy": [ { "cds_experimental": {} } ], "childPolicyConfigTargetFieldName": "cluster" } } ] } } } } ] } (t=+65.474495ms) tlogger.go:116: INFO config.go:237 [rls] rls: stale_age 0s is not less than max_age 0s, ignoring it (t=+65.993295ms) tlogger.go:116: INFO config.go:241 [rls] rls: max_age in route lookup config is 0s, using 5m0s (t=+66.114892ms) tlogger.go:116: INFO resolver_wrapper.go:200 [core] [Channel #1416]Resolver state updated: { "Addresses": null, "Endpoints": [], "ServiceConfig": { "Config": { "Config": null, "Methods": {} }, "Err": null }, "Attributes": { "\u003c%!p(resolver.csKeyType=grpc.internal.resolver.configSelector)\u003e": "\u003c0x400082a5a0\u003e", "\u003c%!p(xdsclient.clientKeyType=grpc.xds.internal.client.Client)\u003e": "\u003c0x4000790210\u003e" } } (service config updated) (t=+66.415334ms) tlogger.go:116: INFO balancer_wrapper.go:117 [core] [Channel #1416]Channel switches to new LB policy "xds_cluster_manager_experimental" (t=+66.567158ms) tlogger.go:116: INFO clustermanager.go:59 [xds] [xds-cluster-manager-lb 0x4000733f20] Created (t=+66.668608ms) tlogger.go:116: INFO balancergroup.go:299 [xds] [xds-cluster-manager-lb 0x4000733f20] Adding child policy of type "rls_experimental" for child "cluster_specifier_plugin:rls-csp" (t=+66.747004ms) tlogger.go:116: INFO balancergroup.go:102 [xds] [xds-cluster-manager-lb 0x4000733f20] Creating child policy of type "rls_experimental" for child "cluster_specifier_plugin:rls-csp" (t=+66.824449ms) tlogger.go:116: INFO balancer.go:306 [rls] [rls-experimental-lb 0x40003e3a40] Delaying picker updates until config is propagated to and processed by child policies (t=+66.974349ms) tlogger.go:116: INFO balancer.go:359 [rls] [rls-experimental-lb 0x40003e3a40] Creating control channel to RLS server at: 127.0.0.1:34301 (t=+67.102178ms) tlogger.go:116: INFO clientconn.go:1654 [core] original dial target is: "127.0.0.1:34301" (t=+67.191435ms) tlogger.go:116: INFO clientconn.go:314 [core] [Channel #1421]Channel created (t=+67.33312ms) tlogger.go:116: INFO clientconn.go:193 [core] [Channel #1421]parsed dial target is: resolver.Target{URL:url.URL{Scheme:"passthrough", Opaque:"", User:(*url.Userinfo)(nil), Host:"", Path:"/127.0.0.1:34301", RawPath:"", OmitHost:false, ForceQuery:false, RawQuery:"", Fragment:"", RawFragment:""}} (t=+67.432195ms) tlogger.go:116: INFO clientconn.go:194 [core] [Channel #1421]Channel authority set to "my-service-client-side-xds" (t=+67.504179ms) tlogger.go:116: INFO resolver_wrapper.go:200 [core] [Channel #1421]Resolver state updated: { "Addresses": [ { "Addr": "127.0.0.1:34301", "ServerName": "", "Attributes": null, "BalancerAttributes": null, "Metadata": null } ], "Endpoints": [ { "Addresses": [ { "Addr": "127.0.0.1:34301", "ServerName": "", "Attributes": null, "BalancerAttributes": null, "Metadata": null } ], "Attributes": null } ], "ServiceConfig": null, "Attributes": null } (resolver returned new addresses) (t=+67.785325ms) tlogger.go:116: INFO balancer_wrapper.go:117 [core] [Channel #1421]Channel switches to new LB policy "pick_first" (t=+67.928433ms) tlogger.go:116: INFO clientconn.go:838 [core] [Channel #1421 SubChannel #1422]Subchannel created (t=+68.038649ms) tlogger.go:116: INFO clientconn.go:544 [core] [Channel #1421]Channel Connectivity change to CONNECTING (t=+68.139638ms) tlogger.go:116: INFO clientconn.go:314 [core] [Channel #1421]Channel exiting idle mode (t=+68.278377ms) tlogger.go:116: INFO control_channel.go:83 [rls] [rls-control-channel 0x40005f1700] Control channel created to RLS server at: 127.0.0.1:34301 (t=+68.431974ms) tlogger.go:116: INFO balancer.go:384 [rls] [rls-experimental-lb 0x40003e3a40] Child policy changed to "cds_experimental" (t=+68.578688ms) tlogger.go:116: INFO balancer.go:253 [rls] [rls-experimental-lb 0x40003e3a40] Resuming picker updates after config propagation to child policies (t=+68.749528ms) tlogger.go:116: INFO balancer.go:551 [rls] [rls-experimental-lb 0x40003e3a40] New balancer.State: {ConnectivityState:IDLE Picker:0x4000a2db00} (t=+68.963989ms) tlogger.go:116: INFO balancergroup.go:538 [xds] [xds-cluster-manager-lb 0x4000733f20] Balancer state update from child cluster_specifier_plugin:rls-csp, new state: {ConnectivityState:IDLE Picker:0x4000a2db00} (t=+69.121062ms) tlogger.go:116: INFO balancerstateaggregator.go:147 [xds] [xds-cluster-manager-lb 0x4000733f20] State update from sub-balancer "cluster_specifier_plugin:rls-csp": {ConnectivityState:IDLE Picker:0x4000a2db00} (t=+69.222702ms) tlogger.go:116: INFO balancerstateaggregator.go:191 [xds] [xds-cluster-manager-lb 0x4000733f20] Child pickers: map[cluster_specifier_plugin:rls-csp:picker:0x4000a2db00,state:IDLE,stateToAggregate:IDLE] (t=+69.356122ms) tlogger.go:116: INFO clientconn.go:1199 [core] [Channel #1421 SubChannel #1422]Subchannel Connectivity change to CONNECTING (t=+69.483901ms) tlogger.go:116: INFO control_channel.go:135 [rls] [rls-control-channel 0x40005f1700] Starting connectivity state monitoring goroutine (t=+69.63[205](https://github.com/grpc/grpc-go/actions/runs/12402614473/job/34624476229?pr=7949#step:8:206)8ms) tlogger.go:116: INFO clientconn.go:1319 [core] [Channel #1421 SubChannel #1422]Subchannel picks a new address "127.0.0.1:34301" to connect (t=+69.79911ms) tlogger.go:116: INFO clientconn.go:1199 [core] [Channel #1421 SubChannel #1422]Subchannel Connectivity change to READY (t=+71.287352ms) tlogger.go:116: INFO clientconn.go:544 [core] [Channel #1421]Channel Connectivity change to READY (t=+71.481946ms) tlogger.go:116: INFO control_channel.go:170 [rls] [rls-control-channel 0x40005f1700] Connectivity state is READY (t=+71.64462ms) tlogger.go:116: INFO picker.go:273 [rls] [rls-picker 0x4000a2db00] Received RLS response for key {path:/grpc.testing.TestService/EmptyCall keys:} with targets [cluster-my-service-client-side-xds], headerData "", err: <nil> (t=+73.468039ms) tlogger.go:116: INFO child_policy.go:84 [rls] [rls-child-policy-wrapper cluster-my-service-client-side-xds 0x400073e3c0] Created (t=+73.664136ms) tlogger.go:116: INFO balancergroup.go:299 [rls] [rls-experimental-lb 0x40003e3a40] Adding child policy of type "cds_experimental" for child "cluster-my-service-client-side-xds" (t=+73.810529ms) tlogger.go:116: INFO balancergroup.go:102 [rls] [rls-experimental-lb 0x40003e3a40] Creating child policy of type "cds_experimental" for child "cluster-my-service-client-side-xds" (t=+73.961612ms) tlogger.go:116: INFO cdsbalancer.go:109 [xds] [cds-lb 0x4000755040] Created (t=+74.18518ms) tlogger.go:116: INFO cdsbalancer.go:121 [xds] [cds-lb 0x4000755040] xDS credentials in use: false (t=+74.369514ms) tlogger.go:116: INFO balancer.go:681 [rls] [rls-experimental-lb 0x40003e3a40] Child policy "cluster-my-service-client-side-xds" added to BalancerGroup (t=+74.529093ms) tlogger.go:116: INFO balancer.go:470 [rls] [rls-experimental-lb 0x40003e3a40] Pushing new state to child policy "cluster-my-service-client-side-xds": {ResolverState:{Addresses:[] Endpoints:[] ServiceConfig:0x4000733e40 Attributes:{"<%!p(resolver.csKeyType=grpc.internal.resolver.configSelector)>": "<0x400082a5a0>" , "<%!p(xdsclient.clientKeyType=grpc.xds.internal.client.Client)>": "<0x4000790210>" }} BalancerConfig:0x400077afc0} (t=+74.889807ms) tlogger.go:116: INFO cdsbalancer.go:290 [xds] [cds-lb 0x4000755040] Received balancer config update: { "LoadBalancingConfig": null, "Cluster": "cluster-my-service-client-side-xds" } (t=+75.102254ms) tlogger.go:116: INFO picker.go:279 [rls] [rls-picker 0x4000a2db00] Removing pending request entry for key {path:/grpc.testing.TestService/EmptyCall keys:} (t=+75.553698ms) tlogger.go:116: INFO balancer.go:551 [rls] [rls-experimental-lb 0x40003e3a40] New balancer.State: {ConnectivityState:CONNECTING Picker:0x4000a2ddd0} (t=+75.831267ms) tlogger.go:116: INFO balancergroup.go:538 [xds] [xds-cluster-manager-lb 0x4000733f20] Balancer state update from child cluster_specifier_plugin:rls-csp, new state: {ConnectivityState:CONNECTING Picker:0x4000a2ddd0} (t=+75.970558ms) tlogger.go:116: INFO balancerstateaggregator.go:147 [xds] [xds-cluster-manager-lb 0x4000733f20] State update from sub-balancer "cluster_specifier_plugin:rls-csp": {ConnectivityState:CONNECTING Picker:0x4000a2ddd0} (t=+76.129324ms) tlogger.go:116: INFO balancerstateaggregator.go:191 [xds] [xds-cluster-manager-lb 0x4000733f20] Child pickers: map[cluster_specifier_plugin:rls-csp:picker:0x4000a2ddd0,state:CONNECTING,stateToAggregate:CONNECTING] (t=+76.275898ms) tlogger.go:116: INFO clientconn.go:544 [core] [Channel #1416]Channel Connectivity change to CONNECTING (t=+76.461956ms) tlogger.go:116: INFO cdsbalancer.go:414 [xds] [cds-lb 0x4000755040] Received Cluster resource: { "ClusterType": 0, "ClusterName": "cluster-my-service-client-side-xds", "EDSServiceName": "endpoints-my-service-client-side-xds", "LRSServerConfig": null, "SecurityCfg": null, "MaxRequests": null, "DNSHostName": "", "PrioritizedClusterNames": null, "LBPolicy": [ { "ring_hash_experimental": { "minRingSize": 1024, "maxRingSize": 8388608 } } ], "OutlierDetection": null, "Raw": { "type_url": "type.googleapis.com/envoy.config.cluster.v3.Cluster", "value": "CiJjbHVzdGVyLW15LXNlcnZpY2UtY2xpZW50LXNpZGUteGRzGioKAhoAEiRlbmRwb2ludHMtbXktc2VydmljZS1jbGllbnQtc2lkZS14ZHMwAhAD" }, "TelemetryLabels": { "csm.service_name": "unknown", "csm.service_namespace_name": "unknown" } } (t=+77.2277ms) tlogger.go:116: INFO clusterresolver.go:85 [xds] [xds-cluster-resolver-lb 0x40008961c0] Created (t=+77.454965ms) tlogger.go:116: INFO cdsbalancer.go:455 [xds] [cds-lb 0x4000755040] Created child policy 0x40008961c0 of type cluster_resolver_experimental (t=+77.599004ms) tlogger.go:116: INFO clientconn.go:544 [core] [Channel #1416]Channel Connectivity change to SHUTDOWN (t=+10.058723543s) tlogger.go:116: INFO resolver_wrapper.go:100 [core] [Channel #1416]Closing the name resolver (t=+10.058936511s) tlogger.go:116: INFO balancer_wrapper.go:155 [core] [Channel #1416]ccBalancerWrapper: closing (t=+10.059148728s) tlogger.go:116: INFO control_channel.go:188 [rls] [rls-control-channel 0x40005f1700] Closing control channel (t=+10.059354192s) tlogger.go:116: INFO clientconn.go:544 [core] [Channel #1421]Channel Connectivity change to SHUTDOWN (t=+10.059614639s) tlogger.go:116: INFO resolver_wrapper.go:100 [core] [Channel #1421]Closing the name resolver (t=+10.059783835s) tlogger.go:116: INFO balancer_wrapper.go:155 [core] [Channel #1421]ccBalancerWrapper: closing (t=+10.059919799s) tlogger.go:116: INFO watch_service.go:56 [xds] [xds-resolver 0x40002b38c0] Canceling watch on Listener resource "my-service-client-side-xds" (t=+10.060087092s) tlogger.go:116: INFO watch_service.go:91 [xds] [xds-resolver 0x40002b38c0] Canceling watch on RouteConfiguration resource "route-my-service-client-side-xds" (t=+10.060256669s) tlogger.go:116: INFO clientconn.go:1199 [core] [Channel #1421 SubChannel #1422]Subchannel Connectivity change to SHUTDOWN (t=+10.060667467s) tlogger.go:116: INFO clientconn.go:1527 [core] [Channel #1421 SubChannel #1422]Subchannel deleted (t=+10.060800355s) tlogger.go:116: WARNING ads_stream.go:471 [xds] [xds-client 0x4000a715e0] [xds-channel 0x400011f440] [ads-stream 0x4000a24b00] Sending ADS request for type "type.googleapis.com/envoy.config.route.v3.RouteConfiguration", resources: [], version: "1", nonce: "2" failed: EOF (t=+10.061023197s) tlogger.go:116: WARNING ads_stream.go:514 [xds] [xds-client 0x4000a715e0] [xds-channel 0x400011f440] [ads-stream 0x4000a24b00] ADS stream closed: rpc error: code = Canceled desc = context canceled (t=+10.06128685s) tlogger.go:116: INFO ads_stream.go:178 [xds] [xds-client 0x4000a715e0] [xds-channel 0x400011f440] [ads-stream 0x4000a24b00] Stopping ADS stream (t=+10.061472187s) tlogger.go:116: INFO clientconn.go:544 [core] [Channel #1417]Channel Connectivity change to SHUTDOWN (t=+10.061677921s) tlogger.go:116: INFO resolver_wrapper.go:100 [core] [Channel #1417]Closing the name resolver (t=+10.061868979s) tlogger.go:116: INFO clientconn.go:314 [core] [Channel #1421]Channel deleted (t=+10.06[209](https://github.com/grpc/grpc-go/actions/runs/12402614473/job/34624476229?pr=7949#step:8:210)4775s) tlogger.go:116: INFO balancer_wrapper.go:155 [core] [Channel #1417]ccBalancerWrapper: closing (t=+10.06230312s) tlogger.go:116: INFO clientconn.go:1199 [core] [Channel #1417 SubChannel #1418]Subchannel Connectivity change to SHUTDOWN (t=+10.062701204s) tlogger.go:116: INFO clientconn.go:1527 [core] [Channel #1417 SubChannel #1418]Subchannel deleted (t=+10.062883716s) tlogger.go:116: INFO clusterresolver.go:355 [xds] [xds-cluster-resolver-lb 0x40008961c0] Shutdown (t=+10.063090497s) tlogger.go:116: INFO cdsbalancer.go:380 [xds] [cds-lb 0x4000755040] Shutdown (t=+10.063197627s) tlogger.go:116: INFO clustermanager.go:197 [xds] [xds-cluster-manager-lb 0x4000733f20] Shutdown (t=+10.063335465s) tlogger.go:116: INFO clientconn.go:314 [core] [Channel #1417]Channel deleted (t=+10.063430362s) tlogger.go:116: INFO channel.go:145 [xds] [xds-client 0x4000a715e0] [xds-channel 0x400011f440] Shutdown (t=+10.06354686s) tlogger.go:116: INFO clientimpl.go:185 [xds] [xds-client 0x4000a715e0] Shutdown (t=+10.063685379s) tlogger.go:116: INFO xds_resolver.go:253 [xds] [xds-resolver 0x40002b38c0] Shutdown (t=+10.063794153s) tlogger.go:116: INFO clientconn.go:314 [core] [Channel #1416]Channel deleted (t=+10.063934715s) tlogger.go:116: INFO server.go:817 [core] [Server #1412 ListenSocket #1413]ListenSocket deleted (t=+10.064239896s) tlogger.go:116: INFO server.go:817 [core] [Server #1414 ListenSocket #1415]ListenSocket deleted (t=+10.064564954s) tlogger.go:116: INFO server.go:817 [core] [Server #1410 ListenSocket #1411]ListenSocket deleted (t=+10.0648[214](https://github.com/grpc/grpc-go/actions/runs/12402614473/job/34624476229?pr=7949#step:8:215)63s) --- FAIL: Test/RLSinxDS/ringhash (10.01s) setup.go:45: Created new snapshot cache... setup.go:45: Registered Aggregated Discovery Service (ADS)... setup.go:45: xDS management server serving at: 127.0.0.1:36257... stubserver.go:288: Started test service backend at "127.0.0.1:44577" fake_rls_server.go:53: Started fake RLS server at "127.0.0.1:34301" server.go:229: Created new resource snapshot... server.go:235: Updated snapshot cache with resource snapshot... logging.go:30: nodeID "2d64ef82-d914-49c1-b466-c551c69ab2b4" requested type.googleapis.com/envoy.config.listener.v3.Listener[my-service-client-side-xds] and known map[]. Diff [my-service-client-side-xds] logging.go:30: respond type.googleapis.com/envoy.config.listener.v3.Listener[my-service-client-side-xds] version "" with version "1" logging.go:30: nodeID "2d64ef82-d914-49c1-b466-c551c69ab2b4" requested type.googleapis.com/envoy.config.listener.v3.Listener[my-service-client-side-xds] and known map[my-service-client-side-xds:{}]. Diff [] logging.go:30: open watch 1 for type.googleapis.com/envoy.config.listener.v3.Listener[my-service-client-side-xds] from nodeID "2d64ef82-d914-49c1-b466-c551c69ab2b4", version "1" logging.go:30: nodeID "2d64ef82-d914-49c1-b466-c551c69ab2b4" requested type.googleapis.com/envoy.config.route.v3.RouteConfiguration[route-my-service-client-side-xds] and known map[]. Diff [route-my-service-client-side-xds] logging.go:30: respond type.googleapis.com/envoy.config.route.v3.RouteConfiguration[route-my-service-client-side-xds] version "" with version "1" logging.go:30: nodeID "2d64ef82-d914-49c1-b466-c551c69ab2b4" requested type.googleapis.com/envoy.config.route.v3.RouteConfiguration[route-my-service-client-side-xds] and known map[route-my-service-client-side-xds:{}]. Diff [] logging.go:30: open watch 2 for type.googleapis.com/envoy.config.route.v3.RouteConfiguration[route-my-service-client-side-xds] from nodeID "2d64ef82-d914-49c1-b466-c551c69ab2b4", version "1" logging.go:30: nodeID "2d64ef82-d914-49c1-b466-c551c69ab2b4" requested type.googleapis.com/envoy.config.cluster.v3.Cluster[cluster-my-service-client-side-xds] and known map[]. Diff [cluster-my-service-client-side-xds] logging.go:30: respond type.googleapis.com/envoy.config.cluster.v3.Cluster[cluster-my-service-client-side-xds] version "" with version "1" logging.go:30: nodeID "2d64ef82-d914-49c1-b466-c551c69ab2b4" requested type.googleapis.com/envoy.config.cluster.v3.Cluster[cluster-my-service-client-side-xds] and known map[cluster-my-service-client-side-xds:{}]. Diff [] logging.go:30: open watch 3 for type.googleapis.com/envoy.config.cluster.v3.Cluster[cluster-my-service-client-side-xds] from nodeID "2d64ef82-d914-49c1-b466-c551c69ab2b4", version "1" xds_rls_clusterspecifier_plugin_test.go:155: rpc EmptyCall() failed: rpc error: code = DeadlineExceeded desc = received context error while waiting for new LB policy update: context deadline exceeded logging.go:30: nodeID "2d64ef82-d914-49c1-b466-c551c69ab2b4" requested type.googleapis.com/envoy.config.listener.v3.Listener[] and known map[my-service-client-side-xds:{}]. Diff [] logging.go:30: open watch 4 for type.googleapis.com/envoy.config.listener.v3.Listener[] from nodeID "2d64ef82-d914-49c1-b466-c551c69ab2b4", version "1" FAIL FAIL google.golang.org/grpc/test/xds 46.535s
The text was updated successfully, but these errors were encountered:
https://github.com/grpc/grpc-go/actions/runs/12402614473/job/34624476229?pr=7949
Sorry, something went wrong.
No branches or pull requests
The text was updated successfully, but these errors were encountered: