Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

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

Jump to bottom

Flaky test: Test/ClientSideAffinitySanityCheck #4778

Closed
easwars opened this issue Sep 16, 2021 · 10 comments · Fixed by #4876
Closed

Flaky test: Test/ClientSideAffinitySanityCheck #4778

easwars opened this issue Sep 16, 2021 · 10 comments · Fixed by #4876
Labels
fixit P1 Type: Bug

Comments

@easwars
Copy link
Contributor

easwars commented Sep 16, 2021

https://github.com/grpc/grpc-go/pull/4777/checks?check_run_id=3616120012

--- FAIL: Test (3.38s)
    --- FAIL: Test/ClientSideAffinitySanityCheck (0.12s)
        tlogger.go:101: server.go:89 [xds-e2e] Created new snapshot cache...  (t=+59.701µs)
        tlogger.go:101: server.go:103 [xds-e2e] Registered Aggregated Discovery Service (ADS)...  (t=+564.21µs)
        tlogger.go:101: server.go:107 [xds-e2e] xDS management server serving at: 127.0.0.1:33759...  (t=+653.912µs)
        tlogger.go:101: server.go:157 [xds-e2e] Created new resource snapshot...  (t=+2.451043ms)
        tlogger.go:101: server.go:163 [xds-e2e] Updated snapshot cache with resource snapshot...  (t=+2.503044ms)
        tlogger.go:101: clientconn.go:252 [core] parsed scheme: "xds"  (t=+2.578045ms)
        tlogger.go:101: xds_resolver.go:72 [xds] [xds-resolver 0xc000703300] Creating resolver for target: {Scheme:xds Authority: Endpoint:my-service-client-side-xds}  (t=+2.652847ms)
        tlogger.go:101: bootstrap.go:282 [xds] [xds-bootstrap] Bootstrap config for creating xds-client: {
              "BalancerName": "127.0.0.1:33759",
              "Creds": {},
              "TransportAPI": 1,
              "NodeProto": {
                "id": "54bca118-4cdc-4751-a839-b59c21a88ada",
                "user_agent_name": "gRPC Go",
                "UserAgentVersionType": {
                  "UserAgentVersion": "1.41.0-dev"
                },
                "client_features": [
                  "envoy.lb.does_not_support_overprovisioning"
                ]
              },
              "CertProviderConfigs": {
                "client-side-certificate-provider-instance": {},
                "server-side-certificate-provider-instance": {}
              },
              "ServerListenerResourceNameTemplate": "grpc/server?xds.resource.listening_address=%s"
            }  (t=+8.198843ms)
        tlogger.go:101: clientconn.go:252 [core] parsed scheme: ""  (t=+8.317345ms)
        tlogger.go:101: clientconn.go:258 [core] scheme "" not registered, fallback to default scheme  (t=+8.389946ms)
        tlogger.go:101: resolver_conn_wrapper.go:100 [core] ccResolverWrapper: sending update to cc: {[{127.0.0.1:33759  <nil> 0 <nil>}] <nil> <nil>}  (t=+8.508248ms)
        tlogger.go:101: clientconn.go:728 [core] ClientConn switching balancer to "pick_first"  (t=+8.558049ms)
        tlogger.go:101: clientconn.go:748 [core] Channel switches to new LB policy "pick_first"  (t=+8.659451ms)
        tlogger.go:101: client.go:480 [xds] [xds-client 0xc00014c600] Created ClientConn to xDS management server: 127.0.0.1:33759  (t=+8.860854ms)
        tlogger.go:101: clientconn.go:1142 [core] Subchannel Connectivity change to CONNECTING  (t=+9.020257ms)
        tlogger.go:101: clientconn.go:1253 [core] Subchannel picks a new address "127.0.0.1:33759" to connect  (t=+9.092158ms)
        tlogger.go:101: picker_wrapper.go:161 [core] blockingPicker: the picked transport is not ready, loop back to repick  (t=+9.866372ms)
        tlogger.go:101: clientconn.go:1142 [core] Subchannel Connectivity change to READY  (t=+10.013774ms)
        tlogger.go:101: clientconn.go:436 [core] Channel Connectivity change to CONNECTING  (t=+10.262779ms)
        tlogger.go:101: clientconn.go:436 [core] Channel Connectivity change to READY  (t=+10.34998ms)
        tlogger.go:101: transport_helper.go:208 [xds] [xds-client 0xc00014c600] ADS stream created  (t=+10.482782ms)
        tlogger.go:101: client.go:492 [xds] [xds-client 0xc00014c600] Created  (t=+11.665803ms)
        tlogger.go:101: xds_resolver.go:105 [xds] [xds-resolver 0xc000703300] Watch started on resource name my-service-client-side-xds with xds-client 0xc000462798  (t=+11.781005ms)
        tlogger.go:101: simple.go:361 [xds-e2e] respond type.googleapis.com/envoy.config.listener.v3.Listener[my-service-client-side-xds] version "" with version "1"  (t=+16.68769ms)
        tlogger.go:101: client.go:146 [xds] [xds-client 0xc00014c600] ADS response received, type: type.googleapis.com/envoy.config.listener.v3.Listener  (t=+17.186799ms)
        tlogger.go:101: xds.go:77 [xds] [xds-client 0xc00014c600] Resource with name: my-service-client-side-xds, type: *envoy_config_listener_v3.Listener, contains: {
              "name": "my-service-client-side-xds",
              "filterChains": [
                {
                  "filters": [
                    {
                      "name": "envoy.filters.network.http_connection_manager",
                      "typedConfig": {
                        "@type": "type.googleapis.com/envoy.extensions.filters.network.http_connection_manager.v3.HttpConnectionManager",
                        "rds": {
                          "configSource": {
                            "ads": {
            
                            }
                          },
                          "routeConfigName": "route-my-service-client-side-xds"
                        },
                        "httpFilters": [
                          {
                            "name": "router",
                            "typedConfig": {
                              "@type": "type.googleapis.com/envoy.extensions.filters.http.router.v3.Router"
                            }
                          }
                        ]
                      }
                    }
                  ],
                  "name": "filter-chain-name"
                }
              ],
              "apiListener": {
                "apiListener": {
                  "@type": "type.googleapis.com/envoy.extensions.filters.network.http_connection_manager.v3.HttpConnectionManager",
                  "rds": {
                    "configSource": {
                      "ads": {
            
                      }
                    },
                    "routeConfigName": "route-my-service-client-side-xds"
                  },
                  "httpFilters": [
                    {
                      "name": "router",
                      "typedConfig": {
                        "@type": "type.googleapis.com/envoy.extensions.filters.http.router.v3.Router"
                      }
                    }
                  ]
                }
              }
            }  (t=+19.439738ms)
        tlogger.go:101: transport_helper.go:340 [xds] [xds-client 0xc00014c600] Sending ACK for response type: ListenerResource, version: 1, nonce: 1  (t=+19.978047ms)
        tlogger.go:101: simple.go:313 [xds-e2e] open watch 1 for type.googleapis.com/envoy.config.listener.v3.Listener[my-service-client-side-xds] from nodeID "54bca118-4cdc-4751-a839-b59c21a88ada", version "1"  (t=+20.742661ms)
        tlogger.go:101: watch_service.go:85 [xds] [xds-resolver 0xc000703300] received LDS update: {
              "RouteConfigName": "route-my-service-client-side-xds",
              "InlineRouteConfig": null,
              "MaxStreamDuration": 0,
              "HTTPFilters": [
                {
                  "Name": "router",
                  "Filter": {},
                  "Config": {}
                }
              ],
              "InboundListenerCfg": null,
              "Raw": {
                "type_url": "type.googleapis.com/envoy.config.listener.v3.Listener",
                "value": "ChpteS1zZXJ2aWNlLWNsaWVudC1zaWRlLXhkcxqpAhqTAgotZW52b3kuZmlsdGVycy5uZXR3b3JrLmh0dHBfY29ubmVjdGlvbl9tYW5hZ2VyIuEBCmV0eXBlLmdvb2dsZWFwaXMuY29tL2Vudm95LmV4dGVuc2lvbnMuZmlsdGVycy5uZXR3b3JrLmh0dHBfY29ubmVjdGlvbl9tYW5hZ2VyLnYzLkh0dHBDb25uZWN0aW9uTWFuYWdlchJ4Kk4KBnJvdXRlciJECkJ0eXBlLmdvb2dsZWFwaXMuY29tL2Vudm95LmV4dGVuc2lvbnMuZmlsdGVycy5odHRwLnJvdXRlci52My5Sb3V0ZXIaJgoCGgASIHJvdXRlLW15LXNlcnZpY2UtY2xpZW50LXNpZGUteGRzOhFmaWx0ZXItY2hhaW4tbmFtZZoB5AEK4QEKZXR5cGUuZ29vZ2xlYXBpcy5jb20vZW52b3kuZXh0ZW5zaW9ucy5maWx0ZXJzLm5ldHdvcmsuaHR0cF9jb25uZWN0aW9uX21hbmFnZXIudjMuSHR0cENvbm5lY3Rpb25NYW5hZ2VyEngqTgoGcm91dGVyIkQKQnR5cGUuZ29vZ2xlYXBpcy5jb20vZW52b3kuZXh0ZW5zaW9ucy5maWx0ZXJzLmh0dHAucm91dGVyLnYzLlJvdXRlchomCgIaABIgcm91dGUtbXktc2VydmljZS1jbGllbnQtc2lkZS14ZHM="
              }
            }, err: <nil>  (t=+21.972982ms)
        tlogger.go:101: simple.go:361 [xds-e2e] respond type.googleapis.com/envoy.config.route.v3.RouteConfiguration[route-my-service-client-side-xds] version "" with version "1"  (t=+22.523591ms)
        tlogger.go:101: client.go:146 [xds] [xds-client 0xc00014c600] ADS response received, type: type.googleapis.com/envoy.config.route.v3.RouteConfiguration  (t=+22.9905ms)
        tlogger.go:101: xds.go:313 [xds] [xds-client 0xc00014c600] Resource with name: route-my-service-client-side-xds, type: *envoy_config_route_v3.RouteConfiguration, contains: {
              "name": "route-my-service-client-side-xds",
              "virtualHosts": [
                {
                  "domains": [
                    "my-service-client-side-xds"
                  ],
                  "routes": [
                    {
                      "match": {
                        "prefix": "/"
                      },
                      "route": {
                        "cluster": "cluster-my-service-client-side-xds",
                        "hashPolicy": [
                          {
                            "header": {
                              "headerName": "session_id"
                            },
                            "terminal": true
                          }
                        ]
                      }
                    }
                  ]
                }
              ]
            }.  (t=+25.721247ms)
        tlogger.go:101: transport_helper.go:340 [xds] [xds-client 0xc00014c600] Sending ACK for response type: RouteConfigResource, version: 1, nonce: 2  (t=+26.574462ms)
        tlogger.go:101: watch_service.go:166 [xds] [xds-resolver 0xc000703300] received RDS update: {
              "VirtualHosts": [
                {
                  "Domains": [
                    "my-service-client-side-xds"
                  ],
                  "Routes": [
                    {
                      "Path": null,
                      "Prefix": "/",
                      "Regex": null,
                      "CaseInsensitive": false,
                      "Headers": null,
                      "Fraction": null,
                      "HashPolicies": [
                        {
                          "HashPolicyType": 0,
                          "Terminal": true,
                          "HeaderName": "session_id",
                          "Regex": null,
                          "RegexSubstitution": ""
                        }
                      ],
                      "WeightedClusters": {
                        "cluster-my-service-client-side-xds": {
                          "Weight": 1,
                          "HTTPFilterConfigOverride": null
                        }
                      },
                      "MaxStreamDuration": null,
                      "HTTPFilterConfigOverride": null,
                      "RetryConfig": null,
                      "RouteAction": 1
                    }
                  ],
                  "HTTPFilterConfigOverride": null,
                  "RetryConfig": null
                }
              ],
              "Raw": {
                "type_url": "type.googleapis.com/envoy.config.route.v3.RouteConfiguration",
                "value": "CiByb3V0ZS1teS1zZXJ2aWNlLWNsaWVudC1zaWRlLXhkcxJbEhpteS1zZXJ2aWNlLWNsaWVudC1zaWRlLXhkcxo9CgMKAS8SNnoQIAEKDAoKc2Vzc2lvbl9pZAoiY2x1c3Rlci1teS1zZXJ2aWNlLWNsaWVudC1zaWRlLXhkcw=="
              }
            }, err: <nil>  (t=+29.687616ms)
        tlogger.go:101: xds_resolver.go:182 [xds] [xds-resolver 0xc000703300] Received update on resource my-service-client-side-xds from xds-client 0xc000462798, generated service config: {
              "loadBalancingConfig": [
                {
                  "xds_cluster_manager_experimental": {
                    "children": {
                      "cluster-my-service-client-side-xds": {
                        "childPolicy": [
                          {
                            "cds_experimental": {
                              "cluster": "cluster-my-service-client-side-xds"
                            }
                          }
                        ]
                      }
                    }
                  }
                }
              ]
            }  (t=+30.094423ms)
        tlogger.go:101: resolver_conn_wrapper.go:100 [core] ccResolverWrapper: sending update to cc: {[] 0xc00044ec00 0xc0003f40a8}  (t=+30.453829ms)
        tlogger.go:101: clientconn.go:728 [core] ClientConn switching balancer to "xds_cluster_manager_experimental"  (t=+30.51833ms)
        tlogger.go:101: clientconn.go:748 [core] Channel switches to new LB policy "xds_cluster_manager_experimental"  (t=+30.569231ms)
        tlogger.go:101: clustermanager.go:51 [xds] [xds-cluster-manager-lb 0xc00044f520] Created  (t=+30.666933ms)
        tlogger.go:101: clustermanager.go:119 [xds] [xds-cluster-manager-lb 0xc00044f520] update with config {
              "LoadBalancingConfig": null,
              "Children": {
                "cluster-my-service-client-side-xds": {
                  "ChildPolicy": [
                    {
                      "cds_experimental": {
                        "LoadBalancingConfig": null,
                        "Cluster": "cluster-my-service-client-side-xds"
                      }
                    }
                  ]
                }
              }
            }, resolver state {Addresses:[] ServiceConfig:0xc00044ec00 Attributes:0xc0003f40a8}  (t=+30.879937ms)
        tlogger.go:101: cdsbalancer.go:84 [xds] [cds-lb 0xc0000fc3c0] Created  (t=+30.971138ms)
        tlogger.go:101: cdsbalancer.go:95 [xds] [cds-lb 0xc0000fc3c0] xDS credentials in use: false  (t=+31.011339ms)
        tlogger.go:101: balancergroup.go:100 [xds] [xds-cluster-manager-lb 0xc00044f520] Created child policy 0xc0000fc3c0 of type cds_experimental  (t=+31.09684ms)
        tlogger.go:101: cdsbalancer.go:469 [xds] [cds-lb 0xc0000fc3c0] Received update from resolver, balancer config: {
              "LoadBalancingConfig": null,
              "Cluster": "cluster-my-service-client-side-xds"
            }  (t=+31.181742ms)
        tlogger.go:101: cluster_handler.go:160 [xds] [cds-lb 0xc0000fc3c0] CDS watch started on cluster-my-service-client-side-xds  (t=+31.276943ms)
        tlogger.go:101: simple.go:313 [xds-e2e] open watch 2 for type.googleapis.com/envoy.config.route.v3.RouteConfiguration[route-my-service-client-side-xds] from nodeID "54bca118-4cdc-4751-a839-b59c21a88ada", version "1"  (t=+32.041057ms)
        tlogger.go:101: simple.go:361 [xds-e2e] respond type.googleapis.com/envoy.config.cluster.v3.Cluster[cluster-my-service-client-side-xds] version "" with version "1"  (t=+32.125858ms)
        tlogger.go:101: client.go:146 [xds] [xds-client 0xc00014c600] ADS response received, type: type.googleapis.com/envoy.config.cluster.v3.Cluster  (t=+32.468664ms)
        tlogger.go:101: xds.go:649 [xds] [xds-client 0xc00014c600] Resource with name: cluster-my-service-client-side-xds, type: *envoy_config_cluster_v3.Cluster, contains: {
              "name": "cluster-my-service-client-side-xds",
              "type": "EDS",
              "edsClusterConfig": {
                "edsConfig": {
                  "ads": {
            
                  }
                },
                "serviceName": "endpoints-my-service-client-side-xds"
              },
              "lbPolicy": "RING_HASH"
            }  (t=+33.288978ms)
        tlogger.go:101: transport_helper.go:340 [xds] [xds-client 0xc00014c600] Sending ACK for response type: ClusterResource, version: 1, nonce: 3  (t=+33.688085ms)
        tlogger.go:101: cdsbalancer.go:281 [xds] [cds-lb 0xc0000fc3c0] Watch update from xds-client 0xc000462798, content: [
              {
                "ClusterType": 0,
                "ClusterName": "cluster-my-service-client-side-xds",
                "EDSServiceName": "endpoints-my-service-client-side-xds",
                "EnableLRS": false,
                "SecurityCfg": null,
                "MaxRequests": null,
                "DNSHostName": "",
                "PrioritizedClusterNames": null,
                "LBPolicy": {
                  "MinimumRingSize": 1024,
                  "MaximumRingSize": 8388608
                },
                "Raw": {
                  "type_url": "type.googleapis.com/envoy.config.cluster.v3.Cluster",
                  "value": "CiJjbHVzdGVyLW15LXNlcnZpY2UtY2xpZW50LXNpZGUteGRzGioKAhoAEiRlbmRwb2ludHMtbXktc2VydmljZS1jbGllbnQtc2lkZS14ZHMwAhAD"
                }
              }
            ], security config: null  (t=+34.374997ms)
        tlogger.go:101: clusterresolver.go:80 [xds] [xds-cluster-resolver-lb 0xc0009cad80] Created  (t=+34.473599ms)
        tlogger.go:101: cdsbalancer.go:307 [xds] [cds-lb 0xc0000fc3c0] Created child policy 0xc0009cad80 of type cluster_resolver_experimental  (t=+34.562ms)
        tlogger.go:101: clusterresolver.go:158 [xds] [xds-cluster-resolver-lb 0xc0009cad80] Receive update from resolver, balancer config: {
              "discoveryMechanisms": [
                {
                  "cluster": "cluster-my-service-client-side-xds",
                  "edsServiceName": "endpoints-my-service-client-side-xds"
                }
              ],
              "xdsLbPolicy": [
                {
                  "ring_hash_experimental": {
                    "minRingSize": 1024,
                    "maxRingSize": 8388608
                  }
                }
              ]
            }  (t=+34.796105ms)
        tlogger.go:101: resource_resolver.go:226 [xds] [xds-cluster-resolver-lb 0xc0009cad80] EDS watch started on endpoints-my-service-client-side-xds  (t=+34.858606ms)
        tlogger.go:101: simple.go:313 [xds-e2e] open watch 3 for type.googleapis.com/envoy.config.cluster.v3.Cluster[cluster-my-service-client-side-xds] from nodeID "54bca118-4cdc-4751-a839-b59c21a88ada", version "1"  (t=+35.421615ms)
        tlogger.go:101: simple.go:361 [xds-e2e] respond type.googleapis.com/envoy.config.endpoint.v3.ClusterLoadAssignment[endpoints-my-service-client-side-xds] version "" with version "1"  (t=+35.497017ms)
        tlogger.go:101: client.go:146 [xds] [xds-client 0xc00014c600] ADS response received, type: type.googleapis.com/envoy.config.endpoint.v3.ClusterLoadAssignment  (t=+35.833423ms)
        tlogger.go:101: xds.go:1059 [xds] [xds-client 0xc00014c600] Resource with name: endpoints-my-service-client-side-xds, type: *envoy_config_endpoint_v3.ClusterLoadAssignment, contains: {
              "clusterName": "endpoints-my-service-client-side-xds",
              "endpoints": [
                {
                  "locality": {
                    "subZone": "subzone"
                  },
                  "lbEndpoints": [
                    {
                      "endpoint": {
                        "address": {
                          "socketAddress": {
                            "address": "localhost",
                            "portValue": 32801
                          }
                        }
                      }
                    }
                  ],
                  "loadBalancingWeight": 1
                }
              ]
            }  (t=+45.940598ms)
        tlogger.go:101: transport_helper.go:340 [xds] [xds-client 0xc00014c600] Sending ACK for response type: EndpointsResource, version: 1, nonce: 4  (t=+46.299204ms)
        tlogger.go:101: clusterresolver.go:190 [xds] [xds-cluster-resolver-lb 0xc0009cad80] resource update: [
              {}
            ]  (t=+46.696511ms)
        tlogger.go:101: balancer.go:65 [xds] [priority-lb 0xc0009ffb00] Created  (t=+46.811213ms)
        tlogger.go:101: configbuilder.go:280 [xds] xds lb policy is "ring_hash_experimental", building config with ring_hash  (t=+46.883814ms)
        tlogger.go:101: simple.go:313 [xds-e2e] open watch 4 for type.googleapis.com/envoy.config.endpoint.v3.ClusterLoadAssignment[endpoints-my-service-client-side-xds] from nodeID "54bca118-4cdc-4751-a839-b59c21a88ada", version "1"  (t=+47.296522ms)
        tlogger.go:101: clusterresolver.go:222 [xds] [xds-cluster-resolver-lb 0xc0009cad80] build balancer config: {
              "children": {
                "priority-0-0": {
                  "config": [
                    {
                      "xds_cluster_impl_experimental": {
                        "cluster": "cluster-my-service-client-side-xds",
                        "edsServiceName": "endpoints-my-service-client-side-xds",
                        "childPolicy": [
                          {
                            "ring_hash_experimental": {
                              "minRingSize": 1024,
                              "maxRingSize": 8388608
                            }
                          }
                        ]
                      }
                    }
                  ],
                  "ignoreReresolutionRequests": true
                }
              },
              "priorities": [
                "priority-0-0"
              ]
            }  (t=+49.317757ms)
        tlogger.go:101: balancer.go:112 [xds] [priority-lb 0xc0009ffb00] Received update from resolver, balancer config: {
              "children": {
                "priority-0-0": {
                  "config": [
                    {
                      "xds_cluster_impl_experimental": {
                        "cluster": "cluster-my-service-client-side-xds",
                        "edsServiceName": "endpoints-my-service-client-side-xds",
                        "childPolicy": [
                          {
                            "ring_hash_experimental": {
                              "minRingSize": 1024,
                              "maxRingSize": 8388608
                            }
                          }
                        ]
                      }
                    }
                  ],
                  "ignoreReresolutionRequests": true
                }
              },
              "priorities": [
                "priority-0-0"
              ]
            }  (t=+50.521678ms)
        tlogger.go:101: balancer_priority.go:98 [xds] [priority-lb 0xc0009ffb00] switching to ("priority-0-0", 0) in syncPriority  (t=+50.624579ms)
        tlogger.go:101: clusterimpl.go:72 [xds] [xds-cluster-impl-lb 0xc000933a00] Created  (t=+50.806182ms)
        tlogger.go:101: balancergroup.go:100 [xds] [priority-lb 0xc0009ffb00] Created child policy 0xc000933a00 of type xds_cluster_impl_experimental  (t=+50.852183ms)
        tlogger.go:101: clusterimpl.go:223 [xds] [xds-cluster-impl-lb 0xc000933a00] Received update from resolver, balancer config: {
              "cluster": "cluster-my-service-client-side-xds",
              "edsServiceName": "endpoints-my-service-client-side-xds",
              "childPolicy": [
                {
                  "ring_hash_experimental": {
                    "minRingSize": 1024,
                    "maxRingSize": 8388608
                  }
                }
              ]
            }  (t=+51.024586ms)
        tlogger.go:101: ringhash.go:55 [xds] [ring-hash-lb 0xc0009ffe80] Created  (t=+51.094488ms)
        tlogger.go:101: ringhash.go:253 [xds] [ring-hash-lb 0xc0009ffe80] Received update from resolver, balancer config: {
              "minRingSize": 1024,
              "maxRingSize": 8388608
            }  (t=+51.991303ms)
        tlogger.go:101: balancergroup.go:469 [xds] [priority-lb 0xc0009ffb00] Balancer state update from locality priority-0-0, new state: {ConnectivityState:IDLE Picker:0xc0007677c0}  (t=+55.606866ms)
        tlogger.go:101: balancergroup.go:469 [xds] [xds-cluster-manager-lb 0xc00044f520] Balancer state update from locality cluster-my-service-client-side-xds, new state: {ConnectivityState:IDLE Picker:0xc0007677c0}  (t=+56.314778ms)
        tlogger.go:101: balancerstateaggregator.go:210 [xds] [xds-cluster-manager-lb 0xc00044f520] Child pickers: map[cluster-my-service-client-side-xds:picker:0xc0007677c0,state:IDLE,stateToAggregate:IDLE]  (t=+56.41848ms)
        tlogger.go:101: clientconn.go:1142 [core] Subchannel Connectivity change to CONNECTING  (t=+56.591783ms)
        tlogger.go:101: clientconn.go:1253 [core] Subchannel picks a new address "localhost:32801" to connect  (t=+56.658684ms)
        tlogger.go:101: ringhash.go:318 [xds] [ring-hash-lb 0xc0009ffe80] handle SubConn state change: 0xc0006172e0, CONNECTING  (t=+56.954489ms)
        tlogger.go:101: balancergroup.go:469 [xds] [priority-lb 0xc0009ffb00] Balancer state update from locality priority-0-0, new state: {ConnectivityState:CONNECTING Picker:0xc0009fb6d0}  (t=+57.226394ms)
        tlogger.go:101: clientconn.go:1142 [core] Subchannel Connectivity change to READY  (t=+58.788121ms)
        tlogger.go:101: ringhash.go:318 [xds] [ring-hash-lb 0xc0009ffe80] handle SubConn state change: 0xc0006172e0, READY  (t=+58.899823ms)
        tlogger.go:101: balancergroup.go:469 [xds] [priority-lb 0xc0009ffb00] Balancer state update from locality priority-0-0, new state: {ConnectivityState:READY Picker:0xc0009fbb30}  (t=+58.979524ms)
        tlogger.go:101: clientconn.go:436 [core] Channel Connectivity change to TRANSIENT_FAILURE  (t=+59.113627ms)
        tlogger.go:101: balancergroup.go:469 [xds] [xds-cluster-manager-lb 0xc00044f520] Balancer state update from locality cluster-my-service-client-side-xds, new state: {ConnectivityState:CONNECTING Picker:0xc0009fb6d0}  (t=+59.195028ms)
        tlogger.go:101: balancerstateaggregator.go:210 [xds] [xds-cluster-manager-lb 0xc00044f520] Child pickers: map[cluster-my-service-client-side-xds:picker:0xc0009fb6d0,state:CONNECTING,stateToAggregate:CONNECTING]  (t=+59.268429ms)
        tlogger.go:101: clientconn.go:436 [core] Channel Connectivity change to CONNECTING  (t=+59.361331ms)
        tlogger.go:96: picker_wrapper.go:147 [core] subconn returned from pick is not *acBalancerWrapper  (t=+59.456633ms)
        tlogger.go:101: balancergroup.go:469 [xds] [xds-cluster-manager-lb 0xc00044f520] Balancer state update from locality cluster-my-service-client-side-xds, new state: {ConnectivityState:READY Picker:0xc0009fbb30}  (t=+59.564735ms)
        tlogger.go:101: balancerstateaggregator.go:210 [xds] [xds-cluster-manager-lb 0xc00044f520] Child pickers: map[cluster-my-service-client-side-xds:picker:0xc0009fbb30,state:READY,stateToAggregate:READY]  (t=+59.643736ms)
        tlogger.go:101: clientconn.go:436 [core] Channel Connectivity change to READY  (t=+60.190345ms)
        tlogger.go:101: clientconn.go:436 [core] Channel Connectivity change to SHUTDOWN  (t=+61.531869ms)
        tlogger.go:101: cluster_handler.go:163 [xds] [cds-lb 0xc0000fc3c0] CDS watch canceled on cluster-my-service-client-side-xds  (t=+62.474185ms)
        tlogger.go:101: resource_resolver.go:243 [xds] [xds-cluster-resolver-lb 0xc0009cad80] EDS watch canceled on endpoints-my-service-client-side-xds  (t=+62.588787ms)
        tlogger.go:101: simple.go:313 [xds-e2e] open watch 5 for type.googleapis.com/envoy.config.cluster.v3.Cluster[] from nodeID "54bca118-4cdc-4751-a839-b59c21a88ada", version "1"  (t=+63.3542ms)
        tlogger.go:101: clusterimpl.go:335 [xds] [xds-cluster-impl-lb 0xc000933a00] Shutdown  (t=+63.534103ms)
        tlogger.go:101: clusterresolver.go:310 [xds] [xds-cluster-resolver-lb 0xc0009cad80] Shutdown  (t=+63.589104ms)
        tlogger.go:101: cdsbalancer.go:408 [xds] [cds-lb 0xc0000fc3c0] Shutdown  (t=+63.713207ms)
        tlogger.go:101: clustermanager.go:136 [xds] [xds-cluster-manager-lb 0xc00044f520] Shutdown  (t=+63.786608ms)
        tlogger.go:101: xds_resolver.go:108 [xds] [xds-resolver 0xc000703300] Watch cancel on resource name my-service-client-side-xds with xds-client 0xc000462798  (t=+63.952511ms)
        tlogger.go:101: clientconn.go:436 [core] Channel Connectivity change to SHUTDOWN  (t=+64.014512ms)
        tlogger.go:101: clientconn.go:1142 [core] Subchannel Connectivity change to SHUTDOWN  (t=+64.111213ms)
        tlogger.go:101: client.go:534 [xds] [xds-client 0xc00014c600] Shutdown  (t=+65.09003ms)
        tlogger.go:101: xds_resolver.go:274 [xds] [xds-resolver 0xc000703300] Shutdown  (t=+65.140031ms)
        tlogger.go:101: clientconn.go:1142 [core] Subchannel Connectivity change to SHUTDOWN  (t=+65.188932ms)
        tlogger.go:101: transport_helper.go:315 [xds] [xds-client 0xc00014c600] ADS stream is closed with error: xds: stream.Recv() failed: rpc error: code = Canceled desc = grpc: the client connection is closing  (t=+65.373435ms)
        tlogger.go:101: transport_helper.go:275 [xds] [xds-client 0xc00014c600] ADS request for {target: [], type: EndpointsResource, version: "1", nonce: "4"} failed: xds: stream.Send(version_info:"1"  node:{id:"54bca118-4cdc-4751-a839-b59c21a88ada"  user_agent_name:"gRPC Go"  user_agent_version:"1.41.0-dev"  client_features:"envoy.lb.does_not_support_overprovisioning"}  type_url:"type.googleapis.com/envoy.config.endpoint.v3.ClusterLoadAssignment"  response_nonce:"4") failed: EOF  (t=+67.420771ms)
FAIL
FAIL	google.golang.org/grpc/xds/internal/test	8.998s
@easwars
Copy link
Contributor Author

easwars commented Sep 16, 2021

@menghanl : related to the ring hash lb policy?

@menghanl
Copy link
Contributor

menghanl commented Sep 16, 2021 •
edited

I saw this once, but there's no failure (no log from *_test.go). And I cannot reproduce locally.

I guess this is some error logging. That's why I did #4774

@easwars
Copy link
Contributor Author

easwars commented Sep 20, 2021

Another failure: https://github.com/grpc/grpc-go/pull/4787/checks?check_run_id=3657286788

@menghanl
Copy link
Contributor

https://github.com/grpc/grpc-go/runs/3701482783

Caused by error log
tlogger.go:111: ERROR picker_wrapper.go:147 [core] subconn returned from pick is not *acBalancerWrapper (t=+39.429339ms)

@menghanl menghanl mentioned this issue Sep 24, 2021
Merged
@dfawley
Copy link
Member

dfawley commented Sep 24, 2021

Another: https://github.com/grpc/grpc-go/runs/3704357992#step:8:190

@menghanl
Copy link
Contributor

menghanl commented Oct 6, 2021

https://github.com/grpc/grpc-go/runs/3807544141

tlogger.go:111: ERROR picker_wrapper.go:147 [core] subconn returned from pick is type *clusterimpl.scWrapper, not *acBalancerWrapper (t=+67.031235ms)

@easwars
Copy link
Contributor Author

easwars commented Oct 7, 2021

https://github.com/grpc/grpc-go/pull/4848/checks?check_run_id=3830110752

@easwars
Copy link
Contributor Author

easwars commented Oct 12, 2021

https://github.com/grpc/grpc-go/pull/4858/checks?check_run_id=3862795216

@easwars
Copy link
Contributor Author

easwars commented Oct 14, 2021

https://github.com/grpc/grpc-go/pull/4817/checks?check_run_id=3864858204

@easwars
Copy link
Contributor Author

easwars commented Oct 14, 2021

https://github.com/grpc/grpc-go/pull/4817/checks?check_run_id=3897864171

@menghanl menghanl mentioned this issue Oct 14, 2021
Merged
@github-actions github-actions bot locked as resolved and limited conversation to collaborators Apr 14, 2022
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Assignees
No one assigned
Labels
fixit P1 Type: Bug
Projects
None yet
Milestone
No milestone
Development

Successfully merging a pull request may close this issue.

xds/clusterimpl: fix SubConn wrapper returned by picker during race menghanl/grpc-go
3 participants
@menghanl @easwars @dfawley