search

grpc / grpc-go

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

Flaky Test: TestResolverRemovedResource #5986

Closed arvindbr8 closed 1 year ago

arvindbr8 commented 1 year ago

https://github.com/grpc/grpc-go/actions/runs/4018261656/jobs/6903664506

tlogger.go:116: INFO server.go:113 [xds-e2e] Created new snapshot cache...  (t=+38.3µs)
        tlogger.go:116: INFO server.go:631 [core] [Server #127] Server created  (t=+540.209µs)
        tlogger.go:116: INFO server.go:139 [xds-e2e] Registered Aggregated Discovery Service (ADS)...  (t=+613.51µs)
        tlogger.go:116: INFO server.go:143 [xds-e2e] xDS management server serving at: 127.0.0.1:41363...  (t=+659.511µs)
        tlogger.go:116: INFO bootstrap.go:95 [internal/xds] Created bootstrap file at "/tmp/test_xds_bootstrap_1772734321" with contents: {
              "xds_servers": [
                {
                  "server_uri": "127.0.0.1:41363",
                  "channel_creds": [
                    {
                      "type": "insecure"
                    }
                  ],
                  "server_features": [
                    "xds_v3"
                  ]
                }
              ],
              "node": {
                "id": "5a25cfce-d929-48ba-8998-0a54ef2ccff9"
              }
            }
              (t=+1.007117ms)
        tlogger.go:116: INFO xds_resolver.go:83 [xds] [xds-resolver 0xc000336000] Creating resolver for target: {Scheme: Authority: URL:{Scheme:xds Opaque: User: Host: Path:/my-service-client-side-xds RawPath: OmitHost:false ForceQuery:false RawQuery: Fragment: RawFragment:}}  (t=+1.132219ms)
        tlogger.go:116: INFO server.go:819 [core] [Server #127 ListenSocket #128] ListenSocket created  (t=+1.595927ms)
        tlogger.go:116: INFO bootstrap.go:480 [xds] [xds-bootstrap] Bootstrap config for creating xds-client: {
              "XDSServer": {
                "server_uri": "127.0.0.1:41363",
                "channel_creds": [
                  {
                    "type": "insecure"
                  }
                ],
                "server_features": [
                  "xds_v3"
                ]
              },
              "CertProviderConfigs": null,
              "ServerListenerResourceNameTemplate": "",
              "ClientDefaultListenerResourceNameTemplate": "%s",
              "Authorities": null
            }  (t=+1.890332ms)
        tlogger.go:116: INFO client_new.go:80 [xds] [xds-client 0xc0005509b0] Created client to xDS management server: 127.0.0.1:41363-insecure-xDSv3  (t=+2.002534ms)
        tlogger.go:116: INFO singleton.go:101 [xds] xDS node ID: 5a25cfce-d929-48ba-8998-0a54ef2ccff9  (t=+2.081535ms)
        tlogger.go:116: INFO clientconn.go:105 [core] [Channel #129] Channel created  (t=+2.168037ms)
        tlogger.go:116: INFO clientconn.go:1552 [core] [Channel #129] original dial target is: "127.0.0.1:41363"  (t=+2.222038ms)
        tlogger.go:116: INFO clientconn.go:1557 [core] [Channel #129] dial target "127.0.0.1:41363" parse failed: parse "127.0.0.1:41363": first path segment in URL cannot contain colon  (t=+2.317839ms)
        tlogger.go:116: INFO clientconn.go:1572 [core] [Channel #129] fallback to scheme "passthrough"  (t=+2.36314ms)
        tlogger.go:116: INFO clientconn.go:1580 [core] [Channel #129] parsed dial target is: {Scheme:passthrough Authority: URL:{Scheme:passthrough Opaque: User: Host: Path:/127.0.0.1:41363 RawPath: OmitHost:false ForceQuery:false RawQuery: Fragment: RawFragment:}}  (t=+2.438741ms)
        tlogger.go:116: INFO clientconn.go:263 [core] [Channel #129] Channel authority set to "127.0.0.1:41363"  (t=+2.493242ms)
        tlogger.go:116: INFO resolver_conn_wrapper.go:175 [core] [Channel #129] Resolver state updated: {
              "Addresses": [
                {
                  "Addr": "127.0.0.1:41363",
                  "ServerName": "",
                  "Attributes": null,
                  "BalancerAttributes": null,
                  "Type": 0,
                  "Metadata": null
                }
              ],
              "ServiceConfig": null,
              "Attributes": null
            } (resolver returned new addresses)  (t=+2.647245ms)
        tlogger.go:116: INFO balancer_conn_wrappers.go:274 [core] [Channel #129] Channel switches to new LB policy "pick_first"  (t=+8.506145ms)
        tlogger.go:116: INFO clientconn.go:725 [core] [Channel #129 SubChannel #130] Subchannel created  (t=+8.620347ms)
        tlogger.go:116: INFO clientconn.go:418 [core] [Channel #129] Channel Connectivity change to CONNECTING  (t=+8.670547ms)
        tlogger.go:116: INFO clientconn.go:1106 [core] [Channel #129 SubChannel #130] Subchannel Connectivity change to CONNECTING  (t=+8.732949ms)
        tlogger.go:116: INFO clientconn.go:1217 [core] [Channel #129 SubChannel #130] Subchannel picks a new address "127.0.0.1:41363" to connect  (t=+8.79475ms)
        tlogger.go:116: INFO transport.go:[216](https://github.com/grpc/grpc-go/actions/runs/4018261656/jobs/6903664506#step:8:217) [xds] [xds-client 0xc0005509b0] Created transport to server "127.0.0.1:41363"  (t=+9.032754ms)
        tlogger.go:116: INFO xds_resolver.go:143 [xds] [xds-resolver 0xc000336000] Watch started on resource name my-service-client-side-xds with xds-client 0xc0005710b0  (t=+9.105155ms)
        tlogger.go:116: INFO server.go:193 [xds-e2e] Created new resource snapshot...  (t=+9.285358ms)
        tlogger.go:116: INFO server.go:199 [xds-e2e] Updated snapshot cache with resource snapshot...  (t=+9.320859ms)
        tlogger.go:116: INFO clientconn.go:1106 [core] [Channel #129 SubChannel #130] Subchannel Connectivity change to READY  (t=+12.431512ms)
        tlogger.go:116: INFO clientconn.go:418 [core] [Channel #129] Channel Connectivity change to READY  (t=+12.505513ms)
        tlogger.go:116: INFO transport.go:315 [xds] [xds-client 0xc0005509b0] ADS stream created  (t=+12.596314ms)
        tlogger.go:116: INFO simple.go:354 [xds-e2e] nodeID "5a25cfce-d929-48ba-8998-0a54ef2ccff9" requested type.googleapis.com/envoy.config.listener.v3.Listener[my-service-client-side-xds] and known map[]. Diff [my-service-client-side-xds]  (t=+13.415928ms)
        tlogger.go:116: INFO simple.go:421 [xds-e2e] respond type.googleapis.com/envoy.config.listener.v3.Listener[my-service-client-side-xds] version "" with version "1"  (t=+13.49153ms)
        tlogger.go:116: INFO transport.go:280 [xds] [xds-client 0xc0005509b0] ADS response received, type: type.googleapis.com/envoy.config.listener.v3.Listener  (t=+13.968938ms)
        tlogger.go:116: INFO unmarshal_lds.go:54 [xds] [xds-client 0xc0005509b0] Resource with name: my-service-client-side-xds, type: *listenerv3.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=+22.116076ms)
        tlogger.go:116: INFO watch_service.go:94 [xds] [xds-resolver 0xc000336000] 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=+22.956991ms)
        tlogger.go:116: INFO simple.go:354 [xds-e2e] nodeID "5a25cfce-d929-48ba-8998-0a54ef2ccff9" 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=+23.906807ms)
        tlogger.go:116: INFO simple.go:421 [xds-e2e] respond type.googleapis.com/envoy.config.route.v3.RouteConfiguration[route-my-service-client-side-xds] version "" with version "1"  (t=+24.030909ms)
        tlogger.go:116: INFO transport.go:468 [xds] [xds-client 0xc0005509b0] Sending ACK for resource type: type.googleapis.com/envoy.config.listener.v3.Listener, version: 1, nonce: 1  (t=+27.277564ms)
        tlogger.go:116: INFO transport.go:280 [xds] [xds-client 0xc0005509b0] ADS response received, type: type.googleapis.com/envoy.config.route.v3.RouteConfiguration  (t=+27.374666ms)
        tlogger.go:116: INFO simple.go:354 [xds-e2e] nodeID "5a25cfce-d929-48ba-8998-0a54ef2ccff9" requested type.googleapis.com/envoy.config.listener.v3.Listener[my-service-client-side-xds] and known map[my-service-client-side-xds:{}]. Diff []  (t=+28.730589ms)
        tlogger.go:116: INFO simple.go:374 [xds-e2e] open watch 1 for type.googleapis.com/envoy.config.listener.v3.Listener[my-service-client-side-xds] from nodeID "5a25cfce-d929-48ba-8998-0a54ef2ccff9", version "1"  (t=+28.79549ms)
        tlogger.go:116: INFO unmarshal_rds.go:51 [xds] [xds-client 0xc0005509b0] Resource with name: route-my-service-client-side-xds, type: *routev3.RouteConfiguration, contains: {
              "name": "route-my-service-client-side-xds",
              "virtualHosts": [
                {
                  "domains": [
                    "my-service-client-side-xds"
                  ],
                  "routes": [
                    {
                      "match": {
                        "prefix": "/"
                      },
                      "route": {
                        "weightedClusters": {
                          "clusters": [
                            {
                              "name": "test-cluster-1",
                              "weight": 100
                            }
                          ]
                        }
                      }
                    }
                  ]
                }
              ]
            }.  (t=+33.789875ms)
        tlogger.go:116: INFO transport.go:468 [xds] [xds-client 0xc0005509b0] Sending ACK for resource type: type.googleapis.com/envoy.config.route.v3.RouteConfiguration, version: 1, nonce: 2  (t=+34.195282ms)
        tlogger.go:116: INFO watch_service.go:176 [xds] [xds-resolver 0xc000336000] 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": {
                        "test-cluster-1": {
                          "Weight": 100,
                          "HTTPFilterConfigOverride": null
                        }
                      },
                      "ClusterSpecifierPlugin": ""
                    }
                  ],
                  "HTTPFilterConfigOverride": null,
                  "RetryConfig": null
                }
              ],
              "ClusterSpecifierPlugins": {},
              "Raw": {
                "type_url": "type.googleapis.com/envoy.config.route.v3.RouteConfiguration",
                "value": "CiByb3V0ZS1teS1zZXJ2aWNlLWNsaWVudC1zaWRlLXhkcxI9EhpteS1zZXJ2aWNlLWNsaWVudC1zaWRlLXhkcxofCgMKAS8SGBoWChQKDnRlc3QtY2x1c3Rlci0xEgIIZA=="
              }
            }, err: <nil>  (t=+34.66829ms)
        tlogger.go:116: INFO xds_resolver.go:223 [xds] [xds-resolver 0xc000336000] Received update on resource my-service-client-side-xds from xds-client 0xc0005710b0, generated service config: {
              "loadBalancingConfig": [
                {
                  "xds_cluster_manager_experimental": {
                    "children": {
                      "cluster:test-cluster-1": {
                        "childPolicy": [
                          {
                            "cds_experimental": {
                              "cluster": "test-cluster-1"
                            }
                          }
                        ]
                      }
                    }
                  }
                }
              ]
            }  (t=+35.864111ms)
        tlogger.go:116: INFO simple.go:354 [xds-e2e] nodeID "5a25cfce-d929-48ba-8998-0a54ef2ccff9" 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=+36.558322ms)
        tlogger.go:116: INFO simple.go:374 [xds-e2e] open watch 2 for type.googleapis.com/envoy.config.route.v3.RouteConfiguration[route-my-service-client-side-xds] from nodeID "5a25cfce-d929-48ba-8998-0a54ef2ccff9", version "1"  (t=+36.631024ms)
        tlogger.go:116: INFO server.go:193 [xds-e2e] Created new resource snapshot...  (t=+36.914628ms)
        tlogger.go:116: INFO simple.go:234 [xds-e2e] respond open watch 1 type.googleapis.com/envoy.config.listener.v3.Listener[my-service-client-side-xds] with new version "2"  (t=+36.971629ms)
        tlogger.go:116: INFO simple.go:421 [xds-e2e] respond type.googleapis.com/envoy.config.listener.v3.Listener[my-service-client-side-xds] version "1" with version "2"  (t=+37.01163ms)
        tlogger.go:116: INFO transport.go:280 [xds] [xds-client 0xc0005509b0] ADS response received, type: type.googleapis.com/envoy.config.listener.v3.Listener  (t=+37.199833ms)
        tlogger.go:116: INFO transport.go:468 [xds] [xds-client 0xc0005509b0] Sending ACK for resource type: type.googleapis.com/envoy.config.listener.v3.Listener, version: 2, nonce: 3  (t=+37.330136ms)
        tlogger.go:116: INFO watch_service.go:94 [xds] [xds-resolver 0xc000336000] received LDS update: {
              "RouteConfigName": "",
              "InlineRouteConfig": null,
              "MaxStreamDuration": 0,
              "HTTPFilters": null,
              "InboundListenerCfg": null,
              "Raw": null
            }, err: resource name "my-service-client-side-xds" of type Listener not found in received response  (t=+37.776543ms)
        tlogger.go:116: WARNING xds_resolver.go:242 [xds] [xds-resolver 0xc000336000] Watch error on resource my-service-client-side-xds from xds-client 0xc0005710b0, resource name "my-service-client-side-xds" of type Listener not found in received response  (t=+37.854344ms)
        tlogger.go:116: INFO xds_resolver.go:223 [xds] [xds-resolver 0xc000336000] Received update on resource my-service-client-side-xds from xds-client 0xc0005710b0, generated service config: {
              "loadBalancingConfig": [
                {
                  "xds_cluster_manager_experimental": {
                    "children": {
                      "cluster:test-cluster-1": {
                        "childPolicy": [
                          {
                            "cds_experimental": {
                              "cluster": "test-cluster-1"
                            }
                          }
                        ]
                      }
                    }
                  }
                }
              ]
            }  (t=+37.993947ms)
        tlogger.go:116: INFO simple.go:234 [xds-e2e] respond open watch 2 type.googleapis.com/envoy.config.route.v3.RouteConfiguration[route-my-service-client-side-xds] with new version "2"  (t=+40.589291ms)
        tlogger.go:116: INFO simple.go:421 [xds-e2e] respond type.googleapis.com/envoy.config.route.v3.RouteConfiguration[route-my-service-client-side-xds] version "1" with version "2"  (t=+40.646792ms)
        tlogger.go:116: INFO server.go:199 [xds-e2e] Updated snapshot cache with resource snapshot...  (t=+40.706893ms)
        tlogger.go:116: INFO simple.go:354 [xds-e2e] nodeID "5a25cfce-d929-48ba-8998-0a54ef2ccff9" requested type.googleapis.com/envoy.config.listener.v3.Listener[my-service-client-side-xds] and known map[my-service-client-side-xds:{}]. Diff []  (t=+40.798195ms)
        tlogger.go:116: INFO simple.go:374 [xds-e2e] open watch 3 for type.googleapis.com/envoy.config.listener.v3.Listener[my-service-client-side-xds] from nodeID "5a25cfce-d929-48ba-8998-0a54ef2ccff9", version "2"  (t=+40.856596ms)
        tlogger.go:116: INFO simple.go:354 [xds-e2e] nodeID "5a25cfce-d929-48ba-8998-0a54ef2ccff9" requested type.googleapis.com/envoy.config.route.v3.RouteConfiguration[] and known map[route-my-service-client-side-xds:{}]. Diff []  (t=+40.926997ms)
        tlogger.go:116: INFO simple.go:421 [xds-e2e] respond type.googleapis.com/envoy.config.route.v3.RouteConfiguration[] version "1" with version "2"  (t=+40.970498ms)
        tlogger.go:116: INFO transport.go:280 [xds] [xds-client 0xc0005509b0] ADS response received, type: type.googleapis.com/envoy.config.route.v3.RouteConfiguration  (t=+41.272903ms)
        tlogger.go:116: INFO transport.go:468 [xds] [xds-client 0xc0005509b0] Sending ACK for resource type: type.googleapis.com/envoy.config.route.v3.RouteConfiguration, version: 2, nonce: 4  (t=+41.400505ms)
        xds_resolver_test.go:1269: Got service config:
              any(
            +   &grpc.ServiceConfig{Methods: map[string]serviceconfig.MethodConfig{}, rawJSONString: "{}"},
              )

            Want service config:
              any(
            +   &grpc.ServiceConfig{
            +       lbConfig: &grpc.lbConfig{
            +           name: "xds_cluster_manager_experimental",
            +           cfg:  &clustermanager.lbConfig{Children: map[string]clustermanager.childConfig{...}},
            +       },
            +       Methods:       map[string]serviceconfig.MethodConfig{},
            +       rawJSONString: "\n{\n\t\"loadBalancingConfig\": [\n\t\t{\n\t\t  \"xds_cluster_manager_experimental\": {\n\t\t\t\"children\": {\n\t\t\t  \"cluster:test-cluster-1\": {\n\t\t\t"...,
            +   },
              )
        tlogger.go:116: INFO xds_resolver.go:146 [xds] [xds-resolver 0xc000336000] Watch cancel on resource name my-service-client-side-xds with xds-client 0xc0005710b0  (t=+42.141717ms)
        tlogger.go:116: INFO simple.go:354 [xds-e2e] nodeID "5a25cfce-d929-48ba-8998-0a54ef2ccff9" requested type.googleapis.com/envoy.config.listener.v3.Listener[] and known map[my-service-client-side-xds:{}]. Diff []  (t=+46.176886ms)
        tlogger.go:116: INFO simple.go:374 [xds-e2e] open watch 4 for type.googleapis.com/envoy.config.listener.v3.Listener[] from nodeID "5a25cfce-d929-48ba-8998-0a54ef2ccff9", version "2"  (t=+46.243587ms)
        tlogger.go:116: WARNING transport.go:432 [xds] [xds-client 0xc0005509b0] ADS stream is closed with error: failed to read ADS response: rpc error: code = Canceled desc = context canceled  (t=+46.439491ms)
        tlogger.go:116: INFO clientconn.go:418 [core] [Channel #129] Channel Connectivity change to SHUTDOWN  (t=+46.505492ms)
        tlogger.go:116: INFO clientconn.go:1106 [core] [Channel #129 SubChannel #130] Subchannel Connectivity change to SHUTDOWN  (t=+46.582993ms)
        tlogger.go:116: INFO clientconn.go:1430 [core] [Channel #129 SubChannel #130] Subchannel deleted  (t=+46.640594ms)
        tlogger.go:116: INFO clientconn.go:1061 [core] [Channel #129] Channel deleted  (t=+46.675595ms)
        tlogger.go:116: INFO clientimpl.go:88 [xds] [xds-client 0xc0005509b0] Shutdown  (t=+46.7[220](https://github.com/grpc/grpc-go/actions/runs/4018261656/jobs/6903664506#step:8:221)95ms)
        tlogger.go:116: INFO xds_resolver.go:[322](https://github.com/grpc/grpc-go/actions/runs/4018261656/jobs/6903664506#step:8:323) [xds] [xds-resolver 0xc000[336](https://github.com/grpc/grpc-go/actions/runs/4018261656/jobs/6903664506#step:8:337)000] Shutdown  (t=+46.757996ms)
        tlogger.go:116: INFO server.go:770 [core] [Server #127 ListenSocket #128] ListenSocket deleted  (t=+46.9696ms)
FAIL
zasweq commented 1 year ago

https://github.com/grpc/grpc-go/actions/runs/4128043731/jobs/7132004238

arvindbr8 commented 1 year ago

grpc/grpc-go/actions/runs/4177364308/jobs/7234833594

arvindbr8 commented 1 year ago

Not able to reproduce in forge. 0/100k flakes;

easwars commented 1 year ago

If we don't see it for another week, maybe we should close it?