search

grpc / grpc-go

The Go language implementation of gRPC. HTTP/2 based RPC
https://grpc.io
Apache License 2.0
21.06k stars 4.37k forks source link

Flaky test: 145/10k: OutlierDetectionXDSDefaultOn #6599

Open easwars opened 1 year ago

easwars commented 1 year ago

https://github.com/grpc/grpc-go/actions/runs/6017419635/job/16323557911?pr=6595

--- FAIL: Test (24.46s)
    --- FAIL: Test/OutlierDetectionXDSDefaultOn (10.07s)
        tlogger.go:116: INFO server.go:132 [xds-e2e] Created new snapshot cache...  (t=+104.105µs)
        tlogger.go:116: INFO server.go:667 [core] [Server #841] Server created  (t=+810.243µs)
        tlogger.go:116: INFO server.go:158 [xds-e2e] Registered Aggregated Discovery Service (ADS)...  (t=+1.027254ms)
        tlogger.go:116: INFO server.go:177 [xds-e2e] xDS management server serving at: 127.0.0.1:43269...  (t=+1.14126ms)
        tlogger.go:116: INFO server.go:855 [core] [Server #841 ListenSocket #842] ListenSocket created  (t=+2.788148ms)
        tlogger.go:116: INFO server.go:667 [core] [Server #843] Server created  (t=+3.897406ms)
        stubserver.go:230: Started test service backend at "127.0.0.1:39293"
        tlogger.go:116: INFO server.go:855 [core] [Server #843 ListenSocket #844] ListenSocket created  (t=+4.194522ms)
        tlogger.go:116: INFO server.go:667 [core] [Server #845] Server created  (t=+5.200876ms)
        stubserver.go:230: Started test service backend at "127.0.0.1:46753"
        tlogger.go:116: INFO server.go:855 [core] [Server #845 ListenSocket #846] ListenSocket created  (t=+5.47429ms)
        tlogger.go:116: INFO server.go:667 [core] [Server #847] Server created  (t=+6.260632ms)
        stubserver.go:230: Started test service backend at "127.0.0.1:45485"
        tlogger.go:116: INFO server.go:855 [core] [Server #847 ListenSocket #848] ListenSocket created  (t=+6.551547ms)
        tlogger.go:116: INFO server.go:220 [xds-e2e] Created new resource snapshot...  (t=+7.248684ms)
        tlogger.go:116: INFO server.go:226 [xds-e2e] Updated snapshot cache with resource snapshot...  (t=+7.35349ms)
        tlogger.go:116: INFO clientconn.go:318 [core] [Channel #849] Channel created  (t=+7.466996ms)
        tlogger.go:116: INFO clientconn.go:1825 [core] [Channel #849] original dial target is: "xds:///my-service-client-side-xds"  (t=+8.071128ms)
        tlogger.go:116: INFO clientconn.go:1832 [core] [Channel #849] parsed dial target is: {URL:{Scheme:xds Opaque: User: Host: Path:/my-service-client-side-xds RawPath: OmitHost:false ForceQuery:false RawQuery: Fragment: RawFragment:}}  (t=+8.232836ms)
        tlogger.go:116: INFO clientconn.go:1987 [core] [Channel #849] Channel authority set to "my-service-client-side-xds"  (t=+8.336542ms)
        tlogger.go:116: INFO xds_resolver.go:83 [xds] [xds-resolver 0x4000244620] Creating resolver for target: {URL:{Scheme:xds Opaque: User: Host: Path:/my-service-client-side-xds RawPath: OmitHost:false ForceQuery:false RawQuery: Fragment: RawFragment:}}  (t=+8.67086ms)
        tlogger.go:116: INFO client_new.go:80 [xds] [xds-client 0x4000881950] Created client to xDS management server: 127.0.0.1:43269-insecure-xds_v3  (t=+10.772171ms)
        tlogger.go:116: INFO clientconn.go:318 [core] [Channel #850] Channel created  (t=+10.981582ms)
        tlogger.go:116: INFO clientconn.go:1825 [core] [Channel #850] original dial target is: "127.0.0.1:43269"  (t=+11.187993ms)
        tlogger.go:116: INFO clientconn.go:1830 [core] [Channel #850] dial target "127.0.0.1:43269" parse failed: parse "127.0.0.1:43269": first path segment in URL cannot contain colon  (t=+11.408905ms)
        tlogger.go:116: INFO clientconn.go:1846 [core] [Channel #850] fallback to scheme "passthrough"  (t=+11.51651ms)
        tlogger.go:116: INFO clientconn.go:1854 [core] [Channel #850] parsed dial target is: {URL:{Scheme:passthrough Opaque: User: Host: Path:/127.0.0.1:43269 RawPath: OmitHost:false ForceQuery:false RawQuery: Fragment: RawFragment:}}  (t=+11.663218ms)
        tlogger.go:116: INFO clientconn.go:1987 [core] [Channel #850] Channel authority set to "127.0.0.1:43269"  (t=+12.057439ms)
        tlogger.go:116: INFO resolver_conn_wrapper.go:246 [core] [Channel #850] Resolver state updated: {
              "Addresses": [
                {
                  "Addr": "127.0.0.1:43269",
                  "ServerName": "",
                  "Attributes": null,
                  "BalancerAttributes": null,
                  "Metadata": null
                }
              ],
              "Endpoints": [
                {
                  "Addresses": [
                    {
                      "Addr": "127.0.0.1:43269",
                      "ServerName": "",
                      "Attributes": null,
                      "BalancerAttributes": null,
                      "Metadata": null
                    }
                  ],
                  "Attributes": null
                }
              ],
              "ServiceConfig": null,
              "Attributes": null
            } (resolver returned new addresses)  (t=+12.44866ms)
        tlogger.go:116: INFO balancer_conn_wrappers.go:180 [core] [Channel #850] Channel switches to new LB policy "pick_first"  (t=+12.794978ms)
        tlogger.go:116: INFO clientconn.go:956 [core] [Channel #850 SubChannel #851] Subchannel created  (t=+13.120595ms)
        tlogger.go:116: INFO clientconn.go:592 [core] [Channel #850] Channel Connectivity change to CONNECTING  (t=+13.299705ms)
        tlogger.go:116: INFO clientconn.go:1338 [core] [Channel #850 SubChannel #851] Subchannel Connectivity change to CONNECTING  (t=+13.570019ms)
        tlogger.go:116: INFO clientconn.go:1453 [core] [Channel #850 SubChannel #851] Subchannel picks a new address "127.0.0.1:43269" to connect  (t=+13.724527ms)
        tlogger.go:116: INFO clientconn.go:1338 [core] [Channel #850 SubChannel #851] Subchannel Connectivity change to READY  (t=+15.244908ms)
        tlogger.go:116: INFO clientconn.go:592 [core] [Channel #850] Channel Connectivity change to READY  (t=+15.396616ms)
        tlogger.go:116: INFO transport.go:238 [xds] [xds-client 0x4000881950] [127.0.0.1:43269] Created transport to server "127.0.0.1:43269"  (t=+16.566578ms)
        tlogger.go:116: INFO transport.go:347 [xds] [xds-client 0x4000881950] [127.0.0.1:43269] ADS stream created  (t=+16.79159ms)
        tlogger.go:116: INFO xds_resolver.go:143 [xds] [xds-resolver 0x4000244620] Watch started on resource name my-service-client-side-xds with xds-client 0x40005f3a90  (t=+17.661536ms)
        tlogger.go:116: INFO simple.go:359 [xds-e2e] nodeID "f9c0941c-5126-453b-af33-d5bdcc6e5b14" requested type.googleapis.com/envoy.config.listener.v3.Listener[my-service-client-side-xds] and known map[]. Diff [my-service-client-side-xds]  (t=+17.877648ms)
        tlogger.go:116: INFO simple.go:428 [xds-e2e] respond type.googleapis.com/envoy.config.listener.v3.Listener[my-service-client-side-xds] version "" with version "1"  (t=+18.024755ms)
        tlogger.go:116: INFO watch_service.go:94 [xds] [xds-resolver 0x4000244620] received LDS update: {
              "RouteConfigName": "route-my-service-client-side-xds",
              "InlineRouteConfig": null,
              "MaxStreamDuration": 0,
              "HTTPFilters": [
                {
                  "Name": "router",
                  "Filter": {},
                  "Config": {
                    "FilterConfig": null
                  }
                }
              ],
              "InboundListenerCfg": null,
              "Raw": {
                "type_url": "type.googleapis.com/envoy.config.listener.v3.Listener",
                "value": "ChpteS1zZXJ2aWNlLWNsaWVudC1zaWRlLXhkcxqpAhqTAgotZW52b3kuZmlsdGVycy5uZXR3b3JrLmh0dHBfY29ubmVjdGlvbl9tYW5hZ2VyIuEBCmV0eXBlLmdvb2dsZWFwaXMuY29tL2Vudm95LmV4dGVuc2lvbnMuZmlsdGVycy5uZXR3b3JrLmh0dHBfY29ubmVjdGlvbl9tYW5hZ2VyLnYzLkh0dHBDb25uZWN0aW9uTWFuYWdlchJ4Kk4KBnJvdXRlciJECkJ0eXBlLmdvb2dsZWFwaXMuY29tL2Vudm95LmV4dGVuc2lvbnMuZmlsdGVycy5odHRwLnJvdXRlci52My5Sb3V0ZXIaJgoCGgASIHJvdXRlLW15LXNlcnZpY2UtY2xpZW50LXNpZGUteGRzOhFmaWx0ZXItY2hhaW4tbmFtZZoB5AEK4QEKZXR5cGUuZ29vZ2xlYXBpcy5jb20vZW52b3kuZXh0ZW5zaW9ucy5maWx0ZXJzLm5ldHdvcmsuaHR0cF9jb25uZWN0aW9uX21hbmFnZXIudjMuSHR0cENvbm5lY3Rpb25NYW5hZ2VyEngqTgoGcm91dGVyIkQKQnR5cGUuZ29vZ2xlYXBpcy5jb20vZW52b3kuZXh0ZW5zaW9ucy5maWx0ZXJzLmh0dHAucm91dGVyLnYzLlJvdXRlchomCgIaABIgcm91dGUtbXktc2VydmljZS1jbGllbnQtc2lkZS14ZHM="
              }
            }, err: <nil>  (t=+19.520035ms)
        tlogger.go:116: INFO simple.go:359 [xds-e2e] nodeID "f9c0941c-5126-453b-af33-d5bdcc6e5b14" requested type.googleapis.com/envoy.config.listener.v3.Listener[my-service-client-side-xds] and known map[my-service-client-side-xds:{}]. Diff []  (t=+20.344478ms)
        tlogger.go:116: INFO simple.go:380 [xds-e2e] open watch 1 for type.googleapis.com/envoy.config.listener.v3.Listener[my-service-client-side-xds] from nodeID "f9c0941c-5126-453b-af33-d5bdcc6e5b14", version "1"  (t=+20.469085ms)
        tlogger.go:116: INFO simple.go:359 [xds-e2e] nodeID "f9c0941c-5126-453b-af33-d5bdcc6e5b14" 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]  (t=+20.676596ms)
        tlogger.go:116: INFO simple.go:428 [xds-e2e] respond type.googleapis.com/envoy.config.route.v3.RouteConfiguration[route-my-service-client-side-xds] version "" with version "1"  (t=+20.783502ms)
        tlogger.go:116: INFO watch_service.go:176 [xds] [xds-resolver 0x4000244620] received RDS update: {
              "VirtualHosts": [
                {
                  "Domains": [
                    "my-service-client-side-xds"
                  ],
                  "Routes": [
                    {
                      "Path": null,
                      "Prefix": "/",
                      "Regex": null,
                      "CaseInsensitive": false,
                      "Headers": null,
                      "Fraction": null,
                      "HashPolicies": null,
                      "MaxStreamDuration": null,
                      "HTTPFilterConfigOverride": null,
                      "RetryConfig": null,
                      "ActionType": 1,
                      "WeightedClusters": {
                        "cluster-my-service-client-side-xds": {
                          "Weight": 100,
                          "HTTPFilterConfigOverride": null
                        }
                      },
                      "ClusterSpecifierPlugin": ""
                    }
                  ],
                  "HTTPFilterConfigOverride": null,
                  "RetryConfig": null
                }
              ],
              "ClusterSpecifierPlugins": {},
              "Raw": {
                "type_url": "type.googleapis.com/envoy.config.route.v3.RouteConfiguration",
                "value": "CiByb3V0ZS1teS1zZXJ2aWNlLWNsaWVudC1zaWRlLXhkcxJREhpteS1zZXJ2aWNlLWNsaWVudC1zaWRlLXhkcxozCgMKAS8SLBoqCigKImNsdXN0ZXItbXktc2VydmljZS1jbGllbnQtc2lkZS14ZHMSAghk"
              }
            }, err: <nil>  (t=+21.862159ms)
        tlogger.go:116: INFO simple.go:359 [xds-e2e] nodeID "f9c0941c-5126-453b-af33-d5bdcc6e5b14" 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 []  (t=+22.26808ms)
        tlogger.go:116: INFO simple.go:380 [xds-e2e] open watch 2 for type.googleapis.com/envoy.config.route.v3.RouteConfiguration[route-my-service-client-side-xds] from nodeID "f9c0941c-5126-453b-af33-d5bdcc6e5b14", version "1"  (t=+23.444343ms)
        tlogger.go:116: INFO xds_resolver.go:223 [xds] [xds-resolver 0x4000244620] Received update on resource my-service-client-side-xds from xds-client 0x40005f3a90, generated service config: {
              "loadBalancingConfig": [
                {
                  "xds_cluster_manager_experimental": {
                    "children": {
                      "cluster:cluster-my-service-client-side-xds": {
                        "childPolicy": [
                          {
                            "cds_experimental": {
                              "cluster": "cluster-my-service-client-side-xds"
                            }
                          }
                        ]
                      }
                    }
                  }
                }
              ]
            }  (t=+23.667355ms)
        tlogger.go:116: INFO resolver_conn_wrapper.go:246 [core] [Channel #849] Resolver state updated: {
              "Addresses": null,
              "Endpoints": [],
              "ServiceConfig": {
                "Config": {
                  "Config": null,
                  "LB": null,
                  "Methods": {}
                },
                "Err": null
              },
              "Attributes": {
                "\u003c%!p(resolver.csKeyType=grpc.internal.resolver.configSelector)\u003e": "\u003c0x40006ce8c0\u003e",
                "\u003c%!p(xdsclient.clientKeyType=grpc.xds.internal.client.Client)\u003e": "\u003c0x40005f3a90\u003e"
              }
            } (service config updated)  (t=+24.764113ms)
        tlogger.go:116: INFO balancer_conn_wrappers.go:180 [core] [Channel #849] Channel switches to new LB policy "xds_cluster_manager_experimental"  (t=+24.982024ms)
        tlogger.go:116: INFO clustermanager.go:58 [xds] [xds-cluster-manager-lb 0x40005d05c0] Created  (t=+25.130732ms)
        tlogger.go:116: INFO clustermanager.go:131 [xds] [xds-cluster-manager-lb 0x40005d05c0] update with config {
              "LoadBalancingConfig": null,
              "Children": {
                "cluster:cluster-my-service-client-side-xds": {
                  "ChildPolicy": [
                    {
                      "cds_experimental": {
                        "LoadBalancingConfig": null,
                        "Cluster": "cluster-my-service-client-side-xds"
                      }
                    }
                  ]
                }
              }
            }, resolver state {Addresses:[] Endpoints:[] ServiceConfig:0x40005d04a0 Attributes:{"<%!p(resolver.csKeyType=grpc.internal.resolver.configSelector)>": "<0x40006ce8c0>" , "<%!p(xdsclient.clientKeyType=grpc.xds.internal.client.Client)>": "<0x40005f3a90>" }}  (t=+25.83627ms)
        tlogger.go:116: INFO balancergroup.go:316 [xds] [xds-cluster-manager-lb 0x40005d05c0] Adding child policy of type "cds_experimental" for locality "cluster:cluster-my-service-client-side-xds"  (t=+27.16504ms)
        tlogger.go:116: INFO balancergroup.go:100 [xds] [xds-cluster-manager-lb 0x40005d05c0] Creating child policy of type "cds_experimental" for locality "cluster:cluster-my-service-client-side-xds"  (t=+27.270846ms)
        tlogger.go:116: INFO cdsbalancer.go:99 [xds] [cds-lb 0x40008bac00] Created  (t=+27.376951ms)
        tlogger.go:116: INFO cdsbalancer.go:110 [xds] [cds-lb 0x40008bac00] xDS credentials in use: false  (t=+27.72787ms)
        tlogger.go:116: INFO cdsbalancer.go:499 [xds] [cds-lb 0x40008bac00] Received balancer config update: {
              "LoadBalancingConfig": null,
              "Cluster": "cluster-my-service-client-side-xds"
            }  (t=+27.91298ms)
        tlogger.go:116: INFO cluster_handler.go:190 [xds] [cds-lb 0x40008bac00] CDS watch started on cluster-my-service-client-side-xds  (t=+28.2974ms)
        tlogger.go:116: INFO simple.go:359 [xds-e2e] nodeID "f9c0941c-5126-453b-af33-d5bdcc6e5b14" 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]  (t=+28.911433ms)
        tlogger.go:116: INFO simple.go:428 [xds-e2e] respond type.googleapis.com/envoy.config.cluster.v3.Cluster[cluster-my-service-client-side-xds] version "" with version "1"  (t=+29.065641ms)
        tlogger.go:116: INFO cdsbalancer.go:290 [xds] [cds-lb 0x40008bac00] Received Cluster resource contains content: [
              {
                "ClusterType": 0,
                "ClusterName": "cluster-my-service-client-side-xds",
                "EDSServiceName": "endpoints-my-service-client-side-xds",
                "LRSServerConfig": 0,
                "SecurityCfg": null,
                "MaxRequests": null,
                "DNSHostName": "",
                "PrioritizedClusterNames": null,
                "LBPolicy": [
                  {
                    "xds_wrr_locality_experimental": {
                      "childPolicy": [
                        {
                          "round_robin": {}
                        }
                      ]
                    }
                  }
                ],
                "OutlierDetection": {
                  "interval": "0.050s",
                  "successRateEjection": {
                    "stdevFactor": 1,
                    "minimumHosts": 1,
                    "requestVolume": 8
                  }
                },
                "Raw": {
                  "type_url": "type.googleapis.com/envoy.config.cluster.v3.Cluster",
                  "value": "CiJjbHVzdGVyLW15LXNlcnZpY2UtY2xpZW50LXNpZGUteGRzGioKAhoAEiRlbmRwb2ludHMtbXktc2VydmljZS1jbGllbnQtc2lkZS14ZHOaARMSBRCA4esXOgIIAUICCAhKAggBEAM="
                }
              }
            ], security config: null  (t=+29.910186ms)
        tlogger.go:116: INFO clusterresolver.go:86 [xds] [xds-cluster-resolver-lb 0x400045a4e0] Created  (t=+30.053593ms)
        tlogger.go:116: INFO cdsbalancer.go:316 [xds] [cds-lb 0x40008bac00] Created child policy 0x400045a4e0 of type cluster_resolver_experimental  (t=+30.160099ms)
        tlogger.go:116: INFO clusterresolver.go:190 [xds] [xds-cluster-resolver-lb 0x400045a4e0] Received new balancer config: {
              "discoveryMechanisms": [
                {
                  "cluster": "cluster-my-service-client-side-xds",
                  "edsServiceName": "endpoints-my-service-client-side-xds",
                  "outlierDetection": {
                    "interval": "0.050s",
                    "successRateEjection": {
                      "stdevFactor": 1,
                      "minimumHosts": 1,
                      "requestVolume": 8
                    }
                  }
                }
              ],
              "xdsLbPolicy": [
                {
                  "xds_wrr_locality_experimental": {
                    "childPolicy": [
                      {
                        "round_robin": {}
                      }
                    ]
                  }
                }
              ]
            }  (t=+30.805533ms)
        tlogger.go:116: INFO simple.go:359 [xds-e2e] nodeID "f9c0941c-5126-453b-af33-d5bdcc6e5b14" 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 []  (t=+31.602275ms)
        tlogger.go:116: INFO simple.go:380 [xds-e2e] open watch 3 for type.googleapis.com/envoy.config.cluster.v3.Cluster[cluster-my-service-client-side-xds] from nodeID "f9c0941c-5126-453b-af33-d5bdcc6e5b14", version "1"  (t=+31.719882ms)
        tlogger.go:116: INFO simple.go:359 [xds-e2e] nodeID "f9c0941c-5126-453b-af33-d5bdcc6e5b14" requested type.googleapis.com/envoy.config.endpoint.v3.ClusterLoadAssignment[endpoints-my-service-client-side-xds] and known map[]. Diff [endpoints-my-service-client-side-xds]  (t=+31.865189ms)
        tlogger.go:116: INFO simple.go:428 [xds-e2e] respond type.googleapis.com/envoy.config.endpoint.v3.ClusterLoadAssignment[endpoints-my-service-client-side-xds] version "" with version "1"  (t=+31.964894ms)
        tlogger.go:116: INFO balancer.go:76 [xds] [priority-lb 0x40003d35e0] Created  (t=+33.333467ms)
        tlogger.go:116: INFO simple.go:359 [xds-e2e] nodeID "f9c0941c-5126-453b-af33-d5bdcc6e5b14" requested type.googleapis.com/envoy.config.endpoint.v3.ClusterLoadAssignment[endpoints-my-service-client-side-xds] and known map[endpoints-my-service-client-side-xds:{}]. Diff []  (t=+33.905997ms)
        tlogger.go:116: INFO simple.go:380 [xds-e2e] open watch 4 for type.googleapis.com/envoy.config.endpoint.v3.ClusterLoadAssignment[endpoints-my-service-client-side-xds] from nodeID "f9c0941c-5126-453b-af33-d5bdcc6e5b14", version "1"  (t=+36.809651ms)
        tlogger.go:116: INFO clusterresolver.go:248 [xds] [xds-cluster-resolver-lb 0x400045a4e0] Built child policy config: {
              "children": {
                "priority-0-0": {
                  "config": [
                    {
                      "outlier_detection_experimental": {
                        "interval": "0.050s",
                        "baseEjectionTime": "30s",
                        "maxEjectionTime": "300s",
                        "maxEjectionPercent": 10,
                        "successRateEjection": {
                          "stdevFactor": 1,
                          "enforcementPercentage": 100,
                          "minimumHosts": 1,
                          "requestVolume": 8
                        },
                        "childPolicy": [
                          {
                            "xds_cluster_impl_experimental": {
                              "cluster": "cluster-my-service-client-side-xds",
                              "edsServiceName": "endpoints-my-service-client-side-xds",
                              "childPolicy": [
                                {
                                  "xds_wrr_locality_experimental": {
                                    "childPolicy": [
                                      {
                                        "round_robin": {}
                                      }
                                    ]
                                  }
                                }
                              ]
                            }
                          }
                        ]
                      }
                    }
                  ],
                  "ignoreReresolutionRequests": true
                }
              },
              "priorities": [
                "priority-0-0"
              ]
            }  (t=+37.089066ms)
        tlogger.go:116: INFO balancergroup.go:559 [xds] [xds-cluster-manager-lb 0x40005d05c0] Balancer state update from locality cluster:cluster-my-service-client-side-xds, new state: {ConnectivityState:CONNECTING Picker:0x40009c6fc0}  (t=+37.798104ms)
        tlogger.go:116: INFO balancerstateaggregator.go:255 [xds] [xds-cluster-manager-lb 0x40005d05c0] Child pickers: map[cluster:cluster-my-service-client-side-xds:picker:0x40009c6fc0,state:CONNECTING,stateToAggregate:CONNECTING]  (t=+37.959812ms)
        tlogger.go:116: INFO clientconn.go:592 [core] [Channel #849] Channel Connectivity change to CONNECTING  (t=+38.082219ms)
        tlogger.go:116: INFO balancergroup.go:316 [xds] [priority-lb 0x40003d35e0] Adding child policy of type "outlier_detection_experimental" for locality "priority-0-0"  (t=+38.188724ms)
        tlogger.go:116: INFO balancergroup.go:100 [xds] [priority-lb 0x40003d35e0] Creating child policy of type "outlier_detection_experimental" for locality "priority-0-0"  (t=+38.3[234](https://github.com/grpc/grpc-go/actions/runs/6017419635/job/16323557911?pr=6595#step:8:235)32ms)
        tlogger.go:116: INFO balancer.go:77 [xds] [outlier-detection-lb 0x4000136600] Created  (t=+38.444038ms)
        tlogger.go:116: INFO clusterimpl.go:74 [xds] [xds-cluster-impl-lb 0x400067ea00] Created  (t=+38.638748ms)
        tlogger.go:116: INFO clusterimpl.go:213 [xds] [xds-cluster-impl-lb 0x400067ea00] Received update from resolver, balancer config: {
              "cluster": "cluster-my-service-client-side-xds",
              "edsServiceName": "endpoints-my-service-client-side-xds",
              "childPolicy": [
                {
                  "xds_wrr_locality_experimental": {
                    "childPolicy": [
                      {
                        "round_robin": {}
                      }
                    ]
                  }
                }
              ]
            }  (t=+38.879161ms)
        tlogger.go:116: INFO weightedtarget.go:66 [xds] [weighted-target-lb 0x40005d1200] Created  (t=+48.252258ms)
        tlogger.go:116: INFO balancer.go:88 [xds] [wrrlocality-lb 0x4000460570] Created  (t=+49.718536ms)
        tlogger.go:116: INFO weightedtarget.go:91 [xds] [weighted-target-lb 0x40005d1200] Received update from resolver, balancer config: {
              "targets": {
                "{\"region\":\"region-1\",\"zone\":\"zone-1\",\"subZone\":\"subzone-1\"}": {
                  "weight": 1,
                  "childPolicy": [
                    {
                      "round_robin": {}
                    }
                  ]
                }
              }
            }  (t=+50.275565ms)
        tlogger.go:116: INFO balancergroup.go:316 [xds] [weighted-target-lb 0x40005d1200] Adding child policy of type "round_robin" for locality "{\"region\":\"region-1\",\"zone\":\"zone-1\",\"subZone\":\"subzone-1\"}"  (t=+50.512378ms)
        tlogger.go:116: INFO balancergroup.go:100 [xds] [weighted-target-lb 0x40005d1200] Creating child policy of type "round_robin" for locality "{\"region\":\"region-1\",\"zone\":\"zone-1\",\"subZone\":\"subzone-1\"}"  (t=+50.632284ms)
        tlogger.go:116: INFO clientconn.go:956 [core] [Channel #849 SubChannel #854] Subchannel created  (t=+50.900098ms)
        tlogger.go:116: INFO clientconn.go:956 [core] [Channel #849 SubChannel #855] Subchannel created  (t=+51.[235](https://github.com/grpc/grpc-go/actions/runs/6017419635/job/16323557911?pr=6595#step:8:236)216ms)
        tlogger.go:116: INFO clientconn.go:956 [core] [Channel #849 SubChannel #856] Subchannel created  (t=+51.48973ms)
        tlogger.go:116: INFO roundrobin.go:50 [roundrobin] roundrobinPicker: Build called with info: {map[]}  (t=+51.724342ms)
        tlogger.go:116: INFO balancergroup.go:559 [xds] [weighted-target-lb 0x40005d1200] Balancer state update from locality {"region":"region-1","zone":"zone-1","subZone":"subzone-1"}, new state: {ConnectivityState:CONNECTING Picker:0x40009c7e30}  (t=+51.849749ms)
        tlogger.go:116: INFO aggregator.go:252 [xds] [weighted-target-lb 0x40005d1200] Child pickers with config: map[{"region":"region-1","zone":"zone-1","subZone":"subzone-1"}:weight:1,picker:0x40009c7e30,state:CONNECTING,stateToAggregate:CONNECTING]  (t=+52.0[236](https://github.com/grpc/grpc-go/actions/runs/6017419635/job/16323557911?pr=6595#step:8:237)58ms)
        tlogger.go:116: INFO balancergroup.go:559 [xds] [priority-lb 0x40003d35e0] Balancer state update from locality priority-0-0, new state: {ConnectivityState:CONNECTING Picker:0x40008fc0a8}  (t=+52.355976ms)
        tlogger.go:116: INFO balancergroup.go:559 [xds] [xds-cluster-manager-lb 0x40005d05c0] Balancer state update from locality cluster:cluster-my-service-client-side-xds, new state: {ConnectivityState:CONNECTING Picker:0x40008fc0a8}  (t=+52.504683ms)
        tlogger.go:116: INFO balancerstateaggregator.go:255 [xds] [xds-cluster-manager-lb 0x40005d05c0] Child pickers: map[cluster:cluster-my-service-client-side-xds:picker:0x40008fc0a8,state:CONNECTING,stateToAggregate:CONNECTING]  (t=+52.615589ms)
        tlogger.go:116: INFO clientconn.go:1338 [core] [Channel #849 SubChannel #854] Subchannel Connectivity change to CONNECTING  (t=+52.8191ms)
        tlogger.go:116: INFO clientconn.go:1453 [core] [Channel #849 SubChannel #854] Subchannel picks a new address "localhost:39293" to connect  (t=+53.329027ms)
        tlogger.go:116: INFO balancergroup.go:559 [xds] [weighted-target-lb 0x40005d1200] Balancer state update from locality {"region":"region-1","zone":"zone-1","subZone":"subzone-1"}, new state: {ConnectivityState:CONNECTING Picker:0x40009c7e30}  (t=+53.594941ms)
        tlogger.go:116: INFO aggregator.go:252 [xds] [weighted-target-lb 0x40005d1200] Child pickers with config: map[{"region":"region-1","zone":"zone-1","subZone":"subzone-1"}:weight:1,picker:0x40009c7e30,state:CONNECTING,stateToAggregate:CONNECTING]  (t=+53.985862ms)
        tlogger.go:116: INFO clientconn.go:1338 [core] [Channel #849 SubChannel #856] Subchannel Connectivity change to CONNECTING  (t=+54.591194ms)
        tlogger.go:116: INFO clientconn.go:1453 [core] [Channel #849 SubChannel #856] Subchannel picks a new address "localhost:45485" to connect  (t=+59.736267ms)
        tlogger.go:116: INFO clientconn.go:1338 [core] [Channel #849 SubChannel #855] Subchannel Connectivity change to CONNECTING  (t=+59.870374ms)
        tlogger.go:116: INFO balancergroup.go:559 [xds] [priority-lb 0x40003d35e0] Balancer state update from locality priority-0-0, new state: {ConnectivityState:CONNECTING Picker:0x40008fc198}  (t=+61.747473ms)
        tlogger.go:116: INFO clientconn.go:1338 [core] [Channel #849 SubChannel #854] Subchannel Connectivity change to READY  (t=+61.922983ms)
        tlogger.go:116: INFO clientconn.go:1338 [core] [Channel #849 SubChannel #856] Subchannel Connectivity change to READY  (t=+62.195797ms)
        tlogger.go:116: INFO clientconn.go:1453 [core] [Channel #849 SubChannel #855] Subchannel picks a new address "localhost:46753" to connect  (t=+62.399208ms)
        tlogger.go:116: INFO balancergroup.go:559 [xds] [weighted-target-lb 0x40005d1200] Balancer state update from locality {"region":"region-1","zone":"zone-1","subZone":"subzone-1"}, new state: {ConnectivityState:CONNECTING Picker:0x40009c7e30}  (t=+62.566417ms)
        tlogger.go:116: INFO aggregator.go:252 [xds] [weighted-target-lb 0x40005d1200] Child pickers with config: map[{"region":"region-1","zone":"zone-1","subZone":"subzone-1"}:weight:1,picker:0x40009c7e30,state:CONNECTING,stateToAggregate:CONNECTING]  (t=+62.718625ms)
        tlogger.go:116: INFO balancergroup.go:559 [xds] [weighted-target-lb 0x40005d1200] Balancer state update from locality {"region":"region-1","zone":"zone-1","subZone":"subzone-1"}, new state: {ConnectivityState:CONNECTING Picker:0x40009c7e30}  (t=+62.847932ms)
        tlogger.go:116: INFO aggregator.go:252 [xds] [weighted-target-lb 0x40005d1200] Child pickers with config: map[{"region":"region-1","zone":"zone-1","subZone":"subzone-1"}:weight:1,picker:0x40009c7e30,state:CONNECTING,stateToAggregate:CONNECTING]  (t=+62.947537ms)
        tlogger.go:116: INFO balancergroup.go:559 [xds] [priority-lb 0x40003d35e0] Balancer state update from locality priority-0-0, new state: {ConnectivityState:CONNECTING Picker:0x40006ae1c8}  (t=+63.106546ms)
        tlogger.go:116: INFO balancergroup.go:559 [xds] [priority-lb 0x40003d35e0] Balancer state update from locality priority-0-0, new state: {ConnectivityState:CONNECTING Picker:0x40006ae1f8}  (t=+63.19205ms)
        tlogger.go:116: INFO balancergroup.go:559 [xds] [xds-cluster-manager-lb 0x40005d05c0] Balancer state update from locality cluster:cluster-my-service-client-side-xds, new state: {ConnectivityState:CONNECTING Picker:0x40008fc198}  (t=+63.264654ms)
        tlogger.go:116: INFO balancerstateaggregator.go:255 [xds] [xds-cluster-manager-lb 0x40005d05c0] Child pickers: map[cluster:cluster-my-service-client-side-xds:picker:0x40008fc198,state:CONNECTING,stateToAggregate:CONNECTING]  (t=+63.403561ms)
        tlogger.go:116: INFO balancergroup.go:559 [xds] [xds-cluster-manager-lb 0x40005d05c0] Balancer state update from locality cluster:cluster-my-service-client-side-xds, new state: {ConnectivityState:CONNECTING Picker:0x40006ae1c8}  (t=+63.522768ms)
        tlogger.go:116: INFO balancerstateaggregator.go:255 [xds] [xds-cluster-manager-lb 0x40005d05c0] Child pickers: map[cluster:cluster-my-service-client-side-xds:picker:0x40006ae1c8,state:CONNECTING,stateToAggregate:CONNECTING]  (t=+63.609372ms)
        tlogger.go:116: INFO roundrobin.go:50 [roundrobin] roundrobinPicker: Build called with info: {map[0x40005d16e0:{{Addr: "localhost:39293", ServerName: "", BalancerAttributes: {"<%!p(weightedroundrobin.attributeKey={})>": "Weight: 1" , "<%!p(hierarchy.pathKeyType=grpc.internal.address.hierarchical_path)>": "<0x4000ac6bd0>" , "<%!p(internal.localityKeyType=grpc.xds.internal.address.locality)>": "<%!p(internal.LocalityID={region-1 zone-1 subzone-1})>" , "<%!p(wrrlocality.attributeKey={})>": "Locality Weight: 1" }}}]}  (t=+64.013194ms)
        tlogger.go:116: INFO balancergroup.go:559 [xds] [weighted-target-lb 0x40005d1200] Balancer state update from locality {"region":"region-1","zone":"zone-1","subZone":"subzone-1"}, new state: {ConnectivityState:READY Picker:0x40005d26a0}  (t=+64.1259ms)
        tlogger.go:116: INFO aggregator.go:252 [xds] [weighted-target-lb 0x40005d1200] Child pickers with config: map[{"region":"region-1","zone":"zone-1","subZone":"subzone-1"}:weight:1,picker:0x40005d26a0,state:READY,stateToAggregate:READY]  (t=+64.227805ms)
        tlogger.go:116: INFO roundrobin.go:50 [roundrobin] roundrobinPicker: Build called with info: {map[0x40005d16e0:{{Addr: "localhost:39293", ServerName: "", BalancerAttributes: {"<%!p(hierarchy.pathKeyType=grpc.internal.address.hierarchical_path)>": "<0x4000ac6bd0>" , "<%!p(internal.localityKeyType=grpc.xds.internal.address.locality)>": "<%!p(internal.LocalityID={region-1 zone-1 subzone-1})>" , "<%!p(wrrlocality.attributeKey={})>": "Locality Weight: 1" , "<%!p(weightedroundrobin.attributeKey={})>": "Weight: 1" }}} 0x40005d1b20:{{Addr: "localhost:45485", 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(weightedroundrobin.attributeKey={})>": "Weight: 1" , "<%!p(hierarchy.pathKeyType=grpc.internal.address.hierarchical_path)>": "<0x4000ac6c10>" }}}]}  (t=+64.562123ms)
        tlogger.go:116: INFO balancergroup.go:559 [xds] [weighted-target-lb 0x40005d1200] Balancer state update from locality {"region":"region-1","zone":"zone-1","subZone":"subzone-1"}, new state: {ConnectivityState:READY Picker:0x40005d28a0}  (t=+64.667328ms)
        tlogger.go:116: INFO aggregator.go:252 [xds] [weighted-target-lb 0x40005d1200] Child pickers with config: map[{"region":"region-1","zone":"zone-1","subZone":"subzone-1"}:weight:1,picker:0x40005d28a0,state:READY,stateToAggregate:READY]  (t=+64.770434ms)
        tlogger.go:116: INFO balancergroup.go:559 [xds] [priority-lb 0x40003d35e0] Balancer state update from locality priority-0-0, new state: {ConnectivityState:READY Picker:0x40006ae480}  (t=+64.899441ms)
        tlogger.go:116: INFO balancergroup.go:559 [xds] [priority-lb 0x40003d35e0] Balancer state update from locality priority-0-0, new state: {ConnectivityState:READY Picker:0x40006ae4b0}  (t=+64.980345ms)
        tlogger.go:116: INFO balancergroup.go:559 [xds] [xds-cluster-manager-lb 0x40005d05c0] Balancer state update from locality cluster:cluster-my-service-client-side-xds, new state: {ConnectivityState:CONNECTING Picker:0x40006ae1f8}  (t=+65.08405ms)
        tlogger.go:116: INFO balancerstateaggregator.go:255 [xds] [xds-cluster-manager-lb 0x40005d05c0] Child pickers: map[cluster:cluster-my-service-client-side-xds:picker:0x40006ae1f8,state:CONNECTING,stateToAggregate:CONNECTING]  (t=+65.177955ms)
        tlogger.go:116: INFO balancergroup.go:559 [xds] [xds-cluster-manager-lb 0x40005d05c0] Balancer state update from locality cluster:cluster-my-service-client-side-xds, new state: {ConnectivityState:READY Picker:0x40006ae480}  (t=+65.279261ms)
        tlogger.go:116: INFO balancerstateaggregator.go:255 [xds] [xds-cluster-manager-lb 0x40005d05c0] Child pickers: map[cluster:cluster-my-service-client-side-xds:picker:0x40006ae480,state:READY,stateToAggregate:READY]  (t=+65.363165ms)
        tlogger.go:116: INFO clientconn.go:592 [core] [Channel #849] Channel Connectivity change to READY  (t=+65.44947ms)
        tlogger.go:116: INFO balancergroup.go:559 [xds] [xds-cluster-manager-lb 0x40005d05c0] Balancer state update from locality cluster:cluster-my-service-client-side-xds, new state: {ConnectivityState:READY Picker:0x40006ae4b0}  (t=+65.542875ms)
        tlogger.go:116: INFO balancerstateaggregator.go:255 [xds] [xds-cluster-manager-lb 0x40005d05c0] Child pickers: map[cluster:cluster-my-service-client-side-xds:picker:0x40006ae4b0,state:READY,stateToAggregate:READY]  (t=+65.626779ms)
        tlogger.go:116: INFO balancer.go:843 [xds] [Channel #849] SuccessRate algorithm detected outlier: [[{Addr: "localhost:45485", ServerName: "", Attributes: {"<%!p(internal.handshakeClusterNameKey={})>": "cluster-my-service-client-side-xds" }, BalancerAttributes: {"<%!p(hierarchy.pathKeyType=grpc.internal.address.hierarchical_path)>": "<0x4000ac6c10>" , "<%!p(internal.localityKeyType=grpc.xds.internal.address.locality)>": "<%!p(internal.LocalityID={region-1 zone-1 subzone-1})>" , "<%!p(wrrlocality.attributeKey={})>": "Locality Weight: 1" , "<%!p(weightedroundrobin.attributeKey={})>": "Weight: 1" }}]]. Parameters: successRate=0.000000, mean=0.500000, stddev=0.500000, requiredSuccessRate=0.499500  (t=+89.231231ms)
        tlogger.go:116: INFO balancer.go:885 [xds] [Channel #849] Subchannel ejected: [{Addr: "localhost:45485", ServerName: "", Attributes: {"<%!p(internal.handshakeClusterNameKey={})>": "cluster-my-service-client-side-xds" }, BalancerAttributes: {"<%!p(weightedroundrobin.attributeKey={})>": "Weight: 1" , "<%!p(hierarchy.pathKeyType=grpc.internal.address.hierarchical_path)>": "<0x4000ac6c10>" , "<%!p(internal.localityKeyType=grpc.xds.internal.address.locality)>": "<%!p(internal.LocalityID={region-1 zone-1 subzone-1})>" , "<%!p(wrrlocality.attributeKey={})>": "Locality Weight: 1" }}]  (t=+89.491544ms)
        tlogger.go:116: INFO roundrobin.go:50 [roundrobin] roundrobinPicker: Build called with info: {map[0x40005d16e0:{{Addr: "localhost:39293", ServerName: "", BalancerAttributes: {"<%!p(wrrlocality.attributeKey={})>": "Locality Weight: 1" , "<%!p(weightedroundrobin.attributeKey={})>": "Weight: 1" , "<%!p(hierarchy.pathKeyType=grpc.internal.address.hierarchical_path)>": "<0x4000ac6bd0>" , "<%!p(internal.localityKeyType=grpc.xds.internal.address.locality)>": "<%!p(internal.LocalityID={region-1 zone-1 subzone-1})>" }}}]}  (t=+89.79086ms)
        tlogger.go:116: INFO balancergroup.go:559 [xds] [weighted-target-lb 0x40005d1200] Balancer state update from locality {"region":"region-1","zone":"zone-1","subZone":"subzone-1"}, new state: {ConnectivityState:READY Picker:0x4000ac69a0}  (t=+89.919167ms)
        tlogger.go:116: INFO aggregator.go:252 [xds] [weighted-target-lb 0x40005d1200] Child pickers with config: map[{"region":"region-1","zone":"zone-1","subZone":"subzone-1"}:weight:1,picker:0x4000ac69a0,state:READY,stateToAggregate:READY]  (t=+90.032973ms)
        tlogger.go:116: INFO balancergroup.go:559 [xds] [priority-lb 0x40003d35e0] Balancer state update from locality priority-0-0, new state: {ConnectivityState:READY Picker:0x40004d1f80}  (t=+90.421394ms)
        tlogger.go:116: INFO balancergroup.go:559 [xds] [xds-cluster-manager-lb 0x40005d05c0] Balancer state update from locality cluster:cluster-my-service-client-side-xds, new state: {ConnectivityState:READY Picker:0x40004d1f80}  (t=+90.550801ms)
        tlogger.go:116: INFO balancerstateaggregator.go:255 [xds] [xds-cluster-manager-lb 0x40005d05c0] Child pickers: map[cluster:cluster-my-service-client-side-xds:picker:0x40004d1f80,state:READY,stateToAggregate:READY]  (t=+90.653606ms)
        tlogger.go:116: INFO clientconn.go:1338 [core] [Channel #849 SubChannel #855] Subchannel Connectivity change to READY  (t=+91.946775ms)
        tlogger.go:116: INFO roundrobin.go:50 [roundrobin] roundrobinPicker: Build called with info: {map[0x40005d16e0:{{Addr: "localhost:39293", ServerName: "", BalancerAttributes: {"<%!p(hierarchy.pathKeyType=grpc.internal.address.hierarchical_path)>": "<0x4000ac6bd0>" , "<%!p(internal.localityKeyType=grpc.xds.internal.address.locality)>": "<%!p(internal.LocalityID={region-1 zone-1 subzone-1})>" , "<%!p(wrrlocality.attributeKey={})>": "Locality Weight: 1" , "<%!p(weightedroundrobin.attributeKey={})>": "Weight: 1" }}} 0x40005d1940:{{Addr: "localhost:46753", ServerName: "", BalancerAttributes: {"<%!p(hierarchy.pathKeyType=grpc.internal.address.hierarchical_path)>": "<0x4000ac6bf0>" , "<%!p(internal.localityKeyType=grpc.xds.internal.address.locality)>": "<%!p(internal.LocalityID={region-1 zone-1 subzone-1})>" , "<%!p(wrrlocality.attributeKey={})>": "Locality Weight: 1" , "<%!p(weightedroundrobin.attributeKey={})>": "Weight: 1" }}}]}  (t=+92.405699ms)
        tlogger.go:116: INFO balancergroup.go:559 [xds] [weighted-target-lb 0x40005d1200] Balancer state update from locality {"region":"region-1","zone":"zone-1","subZone":"subzone-1"}, new state: {ConnectivityState:READY Picker:0x400077e960}  (t=+92.53[240](https://github.com/grpc/grpc-go/actions/runs/6017419635/job/16323557911?pr=6595#step:8:241)6ms)
        tlogger.go:116: INFO aggregator.go:252 [xds] [weighted-target-lb 0x40005d1200] Child pickers with config: map[{"region":"region-1","zone":"zone-1","subZone":"subzone-1"}:weight:1,picker:0x400077e960,state:READY,stateToAggregate:READY]  (t=+92.644111ms)
        tlogger.go:116: INFO balancergroup.go:559 [xds] [priority-lb 0x40003d35e0] Balancer state update from locality priority-0-0, new state: {ConnectivityState:READY Picker:0x40007b3a28}  (t=+92.793419ms)
        tlogger.go:116: INFO balancergroup.go:559 [xds] [xds-cluster-manager-lb 0x40005d05c0] Balancer state update from locality cluster:cluster-my-service-client-side-xds, new state: {ConnectivityState:READY Picker:0x40007b3a28}  (t=+92.895625ms)
        tlogger.go:116: INFO balancerstateaggregator.go:255 [xds] [xds-cluster-manager-lb 0x40005d05c0] Child pickers: map[cluster:cluster-my-service-client-side-xds:picker:0x40007b3a28,state:READY,stateToAggregate:READY]  (t=+92.99183ms)
        xds_client_outlier_detection_test.go:310: error in expected round robin: timeout when waiting for roundrobin distribution of RPCs across addresses: [{Addr: "127.0.0.1:39293", ServerName: "", } {Addr: "127.0.0.1:46753", ServerName: "", } {Addr: "127.0.0.1:45485", ServerName: "", }]
        tlogger.go:116: INFO clientconn.go:592 [core] [Channel #849] Channel Connectivity change to SHUTDOWN  (t=+10.010498222s)
        tlogger.go:116: INFO balancer_conn_wrappers.go:191 [core] [Channel #849] ccBalancerWrapper: closing  (t=+10.01066713s)
        tlogger.go:116: INFO cluster_handler.go:193 [xds] [cds-lb 0x40008bac00] CDS watch canceled on cluster-my-service-client-side-xds  (t=+10.010899142s)
        tlogger.go:116: INFO clusterimpl.go:304 [xds] [xds-cluster-impl-lb 0x400067ea00] Shutdown  (t=+10.011272761s)
        tlogger.go:116: INFO balancergroup.go:400 [xds] [priority-lb 0x40003d35e0] Removing child policy for locality "priority-0-0"  (t=+10.01145117s)
        tlogger.go:116: INFO clusterresolver.go:337 [xds] [xds-cluster-resolver-lb 0x400045a4e0] Shutdown  (t=+10.011530074s)
        tlogger.go:116: INFO simple.go:359 [xds-e2e] nodeID "f9c0941c-5126-453b-af33-d5bdcc6e5b14" requested type.googleapis.com/envoy.config.cluster.v3.Cluster[] and known map[cluster-my-service-client-side-xds:{}]. Diff []  (t=+10.011634879s)
        tlogger.go:116: INFO simple.go:380 [xds-e2e] open watch 5 for type.googleapis.com/envoy.config.cluster.v3.Cluster[] from nodeID "f9c0941c-5126-453b-af33-d5bdcc6e5b14", version "1"  (t=+10.011791687s)
        tlogger.go:116: INFO cdsbalancer.go:439 [xds] [cds-lb 0x40008bac00] Shutdown  (t=+10.011960596s)
        tlogger.go:116: INFO simple.go:359 [xds-e2e] nodeID "f9c0941c-5126-453b-af33-d5bdcc6e5b14" requested type.googleapis.com/envoy.config.endpoint.v3.ClusterLoadAssignment[] and known map[endpoints-my-service-client-side-xds:{}]. Diff []  (t=+10.012145305s)
        tlogger.go:116: INFO simple.go:380 [xds-e2e] open watch 6 for type.googleapis.com/envoy.config.endpoint.v3.ClusterLoadAssignment[] from nodeID "f9c0941c-5126-453b-af33-d5bdcc6e5b14", version "1"  (t=+10.012293112s)
        tlogger.go:116: INFO clustermanager.go:150 [xds] [xds-cluster-manager-lb 0x40005d05c0] Shutdown  (t=+10.01[242](https://github.com/grpc/grpc-go/actions/runs/6017419635/job/16323557911?pr=6595#step:8:243)5419s)
        tlogger.go:116: INFO resolver_conn_wrapper.go:126 [core] [Channel #849] Closing the name resolver  (t=+10.012543025s)
        tlogger.go:116: INFO clientconn.go:1338 [core] [Channel #849 SubChannel #855] Subchannel Connectivity change to SHUTDOWN  (t=+10.012692232s)
        tlogger.go:116: INFO clientconn.go:1693 [core] [Channel #849 SubChannel #855] Subchannel deleted  (t=+10.012807638s)
        tlogger.go:116: INFO clientconn.go:1338 [core] [Channel #849 SubChannel #856] Subchannel Connectivity change to SHUTDOWN  (t=+10.012897743s)
        tlogger.go:116: INFO clientconn.go:1693 [core] [Channel #849 SubChannel #856] Subchannel deleted  (t=+10.012996348s)
        tlogger.go:116: INFO clientconn.go:1338 [core] [Channel #849 SubChannel #854] Subchannel Connectivity change to SHUTDOWN  (t=+10.013091953s)
        tlogger.go:116: INFO xds_resolver.go:146 [xds] [xds-resolver 0x4000[244](https://github.com/grpc/grpc-go/actions/runs/6017419635/job/16323557911?pr=6595#step:8:245)620] Watch cancel on resource name my-service-client-side-xds with xds-client 0x40005f3a90  (t=+10.013188557s)
        tlogger.go:116: INFO clientconn.go:1693 [core] [Channel #849 SubChannel #854] Subchannel deleted  (t=+10.013382167s)
        tlogger.go:116: WARNING authority.go:417 [xds] [xds-client 0x4000881950] [127.0.0.1:43269] Watchers not notified since ADS stream failed after having received at least one response: rpc error: code = Canceled desc = context canceled  (t=+10.01363408s)
        tlogger.go:116: WARNING transport.go:497 [xds] [xds-client 0x4000881950] [127.0.0.1:43269] ADS stream closed: rpc error: code = Canceled desc = context canceled  (t=+10.013754786s)
        tlogger.go:116: INFO simple.go:359 [xds-e2e] nodeID "f9c0941c-5126-453b-af33-d5bdcc6e5b14" requested type.googleapis.com/envoy.config.listener.v3.Listener[] and known map[my-service-client-side-xds:{}]. Diff []  (t=+10.013848691s)
        tlogger.go:116: INFO simple.go:380 [xds-e2e] open watch 7 for type.googleapis.com/envoy.config.listener.v3.Listener[] from nodeID "f9c0941c-5126-453b-af33-d5bdcc6e5b14", version "1"  (t=+10.013993498s)
        tlogger.go:116: INFO clientconn.go:592 [core] [Channel #850] Channel Connectivity change to SHUTDOWN  (t=+10.014198808s)
        tlogger.go:116: INFO balancer_conn_wrappers.go:191 [core] [Channel #850] ccBalancerWrapper: closing  (t=+10.014307414s)
        tlogger.go:116: INFO resolver_conn_wrapper.go:126 [core] [Channel #850] Closing the name resolver  (t=+10.0144[252](https://github.com/grpc/grpc-go/actions/runs/6017419635/job/16323557911?pr=6595#step:8:253)2s)
        tlogger.go:116: INFO clientconn.go:318 [core] [Channel #849] Channel deleted  (t=+10.014550226s)
        tlogger.go:116: INFO server.go:806 [core] [Server #847 ListenSocket #848] ListenSocket deleted  (t=+10.015009649s)
        tlogger.go:116: INFO server.go:806 [core] [Server #845 ListenSocket #846] ListenSocket deleted  (t=+10.015[256](https://github.com/grpc/grpc-go/actions/runs/6017419635/job/16323557911?pr=6595#step:8:257)862s)
        tlogger.go:116: INFO clientconn.go:1338 [core] [Channel #850 SubChannel #851] Subchannel Connectivity change to SHUTDOWN  (t=+10.015467172s)
        tlogger.go:116: INFO clientconn.go:1693 [core] [Channel #850 SubChannel #851] Subchannel deleted  (t=+10.015609079s)
        tlogger.go:116: INFO server.go:806 [core] [Server #843 ListenSocket #844] ListenSocket deleted  (t=+10.015701884s)
        tlogger.go:116: INFO server.go:806 [core] [Server #841 ListenSocket #842] ListenSocket deleted  (t=+10.015864592s)
        tlogger.go:116: INFO clientconn.go:318 [core] [Channel #850] Channel deleted  (t=+10.016177608s)
        tlogger.go:116: INFO clientimpl.go:88 [xds] [xds-client 0x4000881950] Shutdown  (t=+10.016[296](https://github.com/grpc/grpc-go/actions/runs/6017419635/job/16323557911?pr=6595#step:8:297)114s)
        tlogger.go:116: INFO xds_resolver.go:[322](https://github.com/grpc/grpc-go/actions/runs/6017419635/job/16323557911?pr=6595#step:8:323) [xds] [xds-resolver 0x4000244620] Shutdown  (t=+10.016[395](https://github.com/grpc/grpc-go/actions/runs/6017419635/job/16323557911?pr=6595#step:8:396)119s)
FAIL
FAIL    google.golang.org/grpc/test/xds 42.104s
easwars commented 1 year ago

Removing the P2 label since this fails quite often in blaze: http://sponge2/9755b204-9e27-46f7-bd0c-d12e720dd86d

zasweq commented 1 year ago

Yikes. Will try and get to this this week then.

arvindbr8 commented 9 months ago

https://github.com/grpc/grpc-go/actions/runs/7733517345/job/21085764301?pr=6953

easwars commented 3 months ago

https://github.com/grpc/grpc-go/actions/runs/10063211882/job/27817491867?pr=7432

easwars commented 2 months ago

https://github.com/grpc/grpc-go/actions/runs/10308428524/job/28535815523?pr=7458