Flaky test: Test/ServerSideXDS_ServingModeChanges #4403

easwars · 2021-05-07T22:22:54Z

See: https://github.com/grpc/grpc-go/pull/4398/checks?check_run_id=2531253416#step:8:189

dfawley · 2021-05-07T22:35:59Z

Seen also here: https://github.com/grpc/grpc-go/pull/4401/checks?check_run_id=2531447517#step:8:189

easwars · 2021-05-07T22:36:00Z

Currently in the xds_server_serving_mode_test.go, we create the xDS enabled gRPC server and start serving. Only after that do we push the server side resources to the management server. And in this failed run, I see that our xDS enabled gRPC server never receives those listener resources.

I see the following initially:

        tlogger.go:99: listener_wrapper.go:138 [xds] [xds-server-listener 0xc0001a2f20] Watch started on resource name grpc/server?xds.resource.listening_address=127.0.0.1:37007  (t=+861.157µs)
        ....
        tlogger.go:99: server.go:48 [xds-e2e] ADS mode: not responding to request: "my-service-security-config-change" not listed  (t=+1.496798ms)

I'm going to send a PR which moves the resource creation on the management server to happen before the xDS enabled gRPC server starts serving.

dfawley · 2021-05-07T22:37:40Z

Shouldn't the xDS+gRPC server get the data after it is added, however? This log is printed after only 1ms of test execution.

easwars · 2021-05-07T22:43:35Z

Technically it should. But we don't see it here. Maybe some bug in the go-control-plane.

dfawley · 2021-05-08T00:44:40Z

Then #4406 is more of a workaround than a fix. If we don't know what's actually going on here, we should leave this open to investigate, or file a new issue.

easwars · 2021-05-10T17:30:02Z

Keeping this open as #4406 is more of a workaround.

easwars · 2021-05-17T20:51:57Z

Another failed run:
https://github.com/grpc/grpc-go/pull/4443/checks?check_run_id=2604062853

easwars · 2021-05-17T21:31:34Z

Complete paste of the failing test's log to avoid the extra step of retrieving it from GA.

--- FAIL: Test (12.37s)
    --- FAIL: Test/ServerSideXDS_ServingModeChanges (10.07s)
        tlogger.go:99: server.go:111 [xds] [xds-server 0x40005140a0] Created xds.GRPCServer  (t=+215.3µs)
        tlogger.go:99: server.go:125 [xds] [xds-server 0x40005140a0] xDS credentials in use: true  (t=+326.7µs)
        tlogger.go:99: server.go:134 [xds-e2e] Created new resource snapshot...  (t=+1.7526ms)
        tlogger.go:99: server.go:140 [xds-e2e] Updated snapshot cache with resource snapshot...  (t=+1.8528ms)
        tlogger.go:99: server.go:174 [xds] [xds-server 0x40005140a0] Serve() passed a net.Listener on 127.0.0.1:33323  (t=+1.9955ms)
        tlogger.go:99: server.go:174 [xds] [xds-server 0x40005140a0] Serve() passed a net.Listener on 127.0.0.1:38695  (t=+2.0341ms)
        tlogger.go:99: bootstrap.go:274 [xds] [xds-bootstrap] Bootstrap config for creating xds-client: {
              "BalancerName": "127.0.0.1:36249",
              "Creds": {},
              "TransportAPI": 1,
              "NodeProto": {
                "id": "c82b953d-5ac5-4936-b7ed-146a320857c8",
                "user_agent_name": "gRPC Go",
                "UserAgentVersionType": {
                  "UserAgentVersion": "1.39.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=+6.1735ms)
        tlogger.go:99: clientconn.go:252 [core] parsed scheme: ""  (t=+6.3293ms)
        tlogger.go:99: clientconn.go:258 [core] scheme "" not registered, fallback to default scheme  (t=+6.4122ms)
        tlogger.go:99: resolver_conn_wrapper.go:96 [core] ccResolverWrapper: sending update to cc: {[{127.0.0.1:36249  <nil> 0 <nil>}] <nil> <nil>}  (t=+6.523701ms)
        tlogger.go:99: clientconn.go:708 [core] ClientConn switching balancer to "pick_first"  (t=+6.611101ms)
        tlogger.go:99: clientconn.go:723 [core] Channel switches to new LB policy "pick_first"  (t=+6.755701ms)
        tlogger.go:99: clientconn.go:1114 [core] Subchannel Connectivity change to CONNECTING  (t=+6.898201ms)
        tlogger.go:99: client.go:560 [xds] [xds-client 0x4000110200] Created ClientConn to xDS management server: 127.0.0.1:36249  (t=+7.021801ms)
        tlogger.go:99: client.go:572 [xds] [xds-client 0x4000110200] Created  (t=+7.133901ms)
        tlogger.go:99: server.go:162 [xds] [xds-server 0x40005140a0] Created an xdsClient  (t=+7.207201ms)
        tlogger.go:99: clientconn.go:1251 [core] Subchannel picks a new address "127.0.0.1:36249" to connect  (t=+7.222901ms)
        tlogger.go:99: listener_wrapper.go:138 [xds] [xds-server-listener 0x400047f340] Watch started on resource name grpc/server?xds.resource.listening_address=127.0.0.1:33323  (t=+7.345401ms)
        tlogger.go:99: clientconn.go:435 [core] Channel Connectivity change to CONNECTING  (t=+7.143101ms)
        tlogger.go:99: listener_wrapper.go:138 [xds] [xds-server-listener 0x4000275810] Watch started on resource name grpc/server?xds.resource.listening_address=127.0.0.1:38695  (t=+7.681001ms)
        tlogger.go:99: clientconn.go:1114 [core] Subchannel Connectivity change to READY  (t=+8.602801ms)
        tlogger.go:99: clientconn.go:435 [core] Channel Connectivity change to READY  (t=+8.697001ms)
        tlogger.go:99: transport_helper.go:208 [xds] [xds-client 0x4000110200] ADS stream created  (t=+8.872001ms)
        tlogger.go:99: server.go:48 [xds-e2e] respond type.googleapis.com/envoy.config.listener.v3.Listener[grpc/server?xds.resource.listening_address=127.0.0.1:33323 grpc/server?xds.resource.listening_address=127.0.0.1:38695] version "" with version "17"  (t=+10.030301ms)
        tlogger.go:99: client.go:146 [xds] [xds-client 0x4000110200] ADS response received, type: type.googleapis.com/envoy.config.listener.v3.Listener  (t=+10.571501ms)
        tlogger.go:99: xds.go:76 [xds] [xds-client 0x4000110200] Resource with name: grpc/server?xds.resource.listening_address=127.0.0.1:38695, type: *envoy_config_listener_v3.Listener, contains: {
              "name": "grpc/server?xds.resource.listening_address=127.0.0.1:38695",
              "address": {
                "socketAddress": {
                  "address": "127.0.0.1",
                  "portValue": 38695
                }
              },
              "filterChains": [
                {
                  "filterChainMatch": {
                    "prefixRanges": [
                      {
                        "addressPrefix": "0.0.0.0",
                        "prefixLen": 0
                      }
                    ],
                    "sourceType": "SAME_IP_OR_LOOPBACK",
                    "sourcePrefixRanges": [
                      {
                        "addressPrefix": "0.0.0.0",
                        "prefixLen": 0
                      }
                    ]
                  },
                  "filters": [
                    {
                      "name": "filter-1",
                      "typedConfig": {
                        "@type": "type.googleapis.com/envoy.extensions.filters.network.http_connection_manager.v3.HttpConnectionManager"
                      }
                    }
                  ],
                  "name": "v4-wildcard"
                },
                {
                  "filterChainMatch": {
                    "prefixRanges": [
                      {
                        "addressPrefix": "::",
                        "prefixLen": 0
                      }
                    ],
                    "sourceType": "SAME_IP_OR_LOOPBACK",
                    "sourcePrefixRanges": [
                      {
                        "addressPrefix": "::",
                        "prefixLen": 0
                      }
                    ]
                  },
                  "filters": [
                    {
                      "name": "filter-1",
                      "typedConfig": {
                        "@type": "type.googleapis.com/envoy.extensions.filters.network.http_connection_manager.v3.HttpConnectionManager"
                      }
                    }
                  ],
                  "name": "v6-wildcard"
                }
              ]
            }  (t=+13.376901ms)
        tlogger.go:99: xds.go:76 [xds] [xds-client 0x4000110200] Resource with name: grpc/server?xds.resource.listening_address=127.0.0.1:33323, type: *envoy_config_listener_v3.Listener, contains: {
              "name": "grpc/server?xds.resource.listening_address=127.0.0.1:33323",
              "address": {
                "socketAddress": {
                  "address": "127.0.0.1",
                  "portValue": 33323
                }
              },
              "filterChains": [
                {
                  "filterChainMatch": {
                    "prefixRanges": [
                      {
                        "addressPrefix": "0.0.0.0",
                        "prefixLen": 0
                      }
                    ],
                    "sourceType": "SAME_IP_OR_LOOPBACK",
                    "sourcePrefixRanges": [
                      {
                        "addressPrefix": "0.0.0.0",
                        "prefixLen": 0
                      }
                    ]
                  },
                  "filters": [
                    {
                      "name": "filter-1",
                      "typedConfig": {
                        "@type": "type.googleapis.com/envoy.extensions.filters.network.http_connection_manager.v3.HttpConnectionManager"
                      }
                    }
                  ],
                  "name": "v4-wildcard"
                },
                {
                  "filterChainMatch": {
                    "prefixRanges": [
                      {
                        "addressPrefix": "::",
                        "prefixLen": 0
                      }
                    ],
                    "sourceType": "SAME_IP_OR_LOOPBACK",
                    "sourcePrefixRanges": [
                      {
                        "addressPrefix": "::",
                        "prefixLen": 0
                      }
                    ]
                  },
                  "filters": [
                    {
                      "name": "filter-1",
                      "typedConfig": {
                        "@type": "type.googleapis.com/envoy.extensions.filters.network.http_connection_manager.v3.HttpConnectionManager"
                      }
                    }
                  ],
                  "name": "v6-wildcard"
                }
              ]
            }  (t=+14.498901ms)
        tlogger.go:99: transport_helper.go:340 [xds] [xds-client 0x4000110200] Sending ACK for response type: ListenerResource, version: 17, nonce: 1  (t=+15.243201ms)
        tlogger.go:99: listener_wrapper.go:298 [xds] [xds-server-listener 0x4000275810] Received update for resource "grpc/server?xds.resource.listening_address=127.0.0.1:38695": {RouteConfigName: InlineRouteConfig:<nil> MaxStreamDuration:0s HTTPFilters:[] InboundListenerCfg:0x400013b530 Raw:[type.googleapis.com/envoy.config.listener.v3.Listener]:{name:"grpc/server?xds.resource.listening_address=127.0.0.1:38695" address:{socket_address:{address:"127.0.0.1" port_value:38695}} filter_chains:{filter_chain_match:{prefix_ranges:{address_prefix:"0.0.0.0" prefix_len:{}} source_type:SAME_IP_OR_LOOPBACK source_prefix_ranges:{address_prefix:"0.0.0.0" prefix_len:{}}} filters:{name:"filter-1" typed_config:{[type.googleapis.com/envoy.extensions.filters.network.http_connection_manager.v3.HttpConnectionManager]:{}}} name:"v4-wildcard"} filter_chains:{filter_chain_match:{prefix_ranges:{address_prefix:"::" prefix_len:{}} source_type:SAME_IP_OR_LOOPBACK source_prefix_ranges:{address_prefix:"::" prefix_len:{}}} filters:{name:"filter-1" typed_config:{[type.googleapis.com/envoy.extensions.filters.network.http_connection_manager.v3.HttpConnectionManager]:{}}} name:"v6-wildcard"}}}  (t=+16.503301ms)
        tlogger.go:99: listener_wrapper.go:331 [xds] [xds-server-listener 0x4000275810] Listener "127.0.0.1:38695" entering mode: "serving" due to error: <nil>  (t=+16.608201ms)
        tlogger.go:99: listener_wrapper.go:298 [xds] [xds-server-listener 0x400047f340] Received update for resource "grpc/server?xds.resource.listening_address=127.0.0.1:33323": {RouteConfigName: InlineRouteConfig:<nil> MaxStreamDuration:0s HTTPFilters:[] InboundListenerCfg:0x40007dc2a0 Raw:[type.googleapis.com/envoy.config.listener.v3.Listener]:{name:"grpc/server?xds.resource.listening_address=127.0.0.1:33323" address:{socket_address:{address:"127.0.0.1" port_value:33323}} filter_chains:{filter_chain_match:{prefix_ranges:{address_prefix:"0.0.0.0" prefix_len:{}} source_type:SAME_IP_OR_LOOPBACK source_prefix_ranges:{address_prefix:"0.0.0.0" prefix_len:{}}} filters:{name:"filter-1" typed_config:{[type.googleapis.com/envoy.extensions.filters.network.http_connection_manager.v3.HttpConnectionManager]:{}}} name:"v4-wildcard"} filter_chains:{filter_chain_match:{prefix_ranges:{address_prefix:"::" prefix_len:{}} source_type:SAME_IP_OR_LOOPBACK source_prefix_ranges:{address_prefix:"::" prefix_len:{}}} filters:{name:"filter-1" typed_config:{[type.googleapis.com/envoy.extensions.filters.network.http_connection_manager.v3.HttpConnectionManager]:{}}} name:"v6-wildcard"}}}  (t=+17.355301ms)
        tlogger.go:99: listener_wrapper.go:331 [xds] [xds-server-listener 0x400047f340] Listener "127.0.0.1:33323" entering mode: "serving" due to error: <nil>  (t=+17.483601ms)
        xds_server_serving_mode_test.go:103: serving mode for listener "127.0.0.1:38695" changed to "serving", err: <nil>
        xds_server_serving_mode_test.go:103: serving mode for listener "127.0.0.1:33323" changed to "serving", err: <nil>
        tlogger.go:99: clientconn.go:252 [core] parsed scheme: ""  (t=+17.906501ms)
        tlogger.go:99: clientconn.go:258 [core] scheme "" not registered, fallback to default scheme  (t=+18.004301ms)
        tlogger.go:99: resolver_conn_wrapper.go:96 [core] ccResolverWrapper: sending update to cc: {[{127.0.0.1:38695  <nil> 0 <nil>}] <nil> <nil>}  (t=+18.174201ms)
        tlogger.go:99: clientconn.go:708 [core] ClientConn switching balancer to "pick_first"  (t=+18.250301ms)
        tlogger.go:99: clientconn.go:723 [core] Channel switches to new LB policy "pick_first"  (t=+18.319301ms)
        tlogger.go:99: clientconn.go:1114 [core] Subchannel Connectivity change to CONNECTING  (t=+18.432101ms)
        tlogger.go:99: picker_wrapper.go:161 [core] blockingPicker: the picked transport is not ready, loop back to repick  (t=+18.609701ms)
        tlogger.go:99: clientconn.go:1251 [core] Subchannel picks a new address "127.0.0.1:38695" to connect  (t=+23.171702ms)
        tlogger.go:99: clientconn.go:435 [core] Channel Connectivity change to CONNECTING  (t=+18.832801ms)
        tlogger.go:99: server.go:48 [xds-e2e] open watch 64 for type.googleapis.com/envoy.config.listener.v3.Listener[grpc/server?xds.resource.listening_address=127.0.0.1:33323 grpc/server?xds.resource.listening_address=127.0.0.1:38695] from nodeID "c82b953d-5ac5-4936-b7ed-146a320857c8", version "17"  (t=+18.925701ms)
        tlogger.go:99: clientconn.go:1114 [core] Subchannel Connectivity change to READY  (t=+27.261102ms)
        tlogger.go:99: clientconn.go:435 [core] Channel Connectivity change to READY  (t=+27.354102ms)
        tlogger.go:99: clientconn.go:252 [core] parsed scheme: ""  (t=+29.020702ms)
        tlogger.go:99: clientconn.go:258 [core] scheme "" not registered, fallback to default scheme  (t=+29.125902ms)
        tlogger.go:99: resolver_conn_wrapper.go:96 [core] ccResolverWrapper: sending update to cc: {[{127.0.0.1:33323  <nil> 0 <nil>}] <nil> <nil>}  (t=+29.268802ms)
        tlogger.go:99: clientconn.go:708 [core] ClientConn switching balancer to "pick_first"  (t=+29.392302ms)
        tlogger.go:99: clientconn.go:723 [core] Channel switches to new LB policy "pick_first"  (t=+29.471002ms)
        tlogger.go:99: clientconn.go:1114 [core] Subchannel Connectivity change to CONNECTING  (t=+29.639602ms)
        tlogger.go:99: clientconn.go:435 [core] Channel Connectivity change to CONNECTING  (t=+29.848202ms)
        tlogger.go:99: clientconn.go:1251 [core] Subchannel picks a new address "127.0.0.1:33323" to connect  (t=+29.922902ms)
        tlogger.go:99: clientconn.go:1114 [core] Subchannel Connectivity change to READY  (t=+31.160902ms)
        tlogger.go:99: clientconn.go:435 [core] Channel Connectivity change to READY  (t=+31.324602ms)
        tlogger.go:99: server.go:134 [xds-e2e] Created new resource snapshot...  (t=+32.307802ms)
        tlogger.go:99: server.go:48 [xds-e2e] respond open watch 64[grpc/server?xds.resource.listening_address=127.0.0.1:33323 grpc/server?xds.resource.listening_address=127.0.0.1:38695] with new version "18"  (t=+32.474402ms)
        tlogger.go:99: server.go:48 [xds-e2e] respond type.googleapis.com/envoy.config.listener.v3.Listener[grpc/server?xds.resource.listening_address=127.0.0.1:33323 grpc/server?xds.resource.listening_address=127.0.0.1:38695] version "17" with version "18"  (t=+32.591702ms)
        tlogger.go:99: server.go:140 [xds-e2e] Updated snapshot cache with resource snapshot...  (t=+32.713902ms)
        tlogger.go:99: client.go:146 [xds] [xds-client 0x4000110200] ADS response received, type: type.googleapis.com/envoy.config.listener.v3.Listener  (t=+33.130902ms)
        tlogger.go:99: xds.go:76 [xds] [xds-client 0x4000110200] Resource with name: grpc/server?xds.resource.listening_address=127.0.0.1:38695, type: *envoy_config_listener_v3.Listener, contains: {
              "name": "grpc/server?xds.resource.listening_address=127.0.0.1:38695",
              "address": {
                "socketAddress": {
                  "address": "127.0.0.1",
                  "portValue": 38695
                }
              },
              "filterChains": [
                {
                  "filterChainMatch": {
                    "prefixRanges": [
                      {
                        "addressPrefix": "0.0.0.0",
                        "prefixLen": 0
                      }
                    ],
                    "sourceType": "SAME_IP_OR_LOOPBACK",
                    "sourcePrefixRanges": [
                      {
                        "addressPrefix": "0.0.0.0",
                        "prefixLen": 0
                      }
                    ]
                  },
                  "filters": [
                    {
                      "name": "filter-1",
                      "typedConfig": {
                        "@type": "type.googleapis.com/envoy.extensions.filters.network.http_connection_manager.v3.HttpConnectionManager"
                      }
                    }
                  ],
                  "name": "v4-wildcard"
                },
                {
                  "filterChainMatch": {
                    "prefixRanges": [
                      {
                        "addressPrefix": "::",
                        "prefixLen": 0
                      }
                    ],
                    "sourceType": "SAME_IP_OR_LOOPBACK",
                    "sourcePrefixRanges": [
                      {
                        "addressPrefix": "::",
                        "prefixLen": 0
                      }
                    ]
                  },
                  "filters": [
                    {
                      "name": "filter-1",
                      "typedConfig": {
                        "@type": "type.googleapis.com/envoy.extensions.filters.network.http_connection_manager.v3.HttpConnectionManager"
                      }
                    }
                  ],
                  "name": "v6-wildcard"
                }
              ]
            }  (t=+35.325502ms)
        tlogger.go:99: transport_helper.go:340 [xds] [xds-client 0x4000110200] Sending ACK for response type: ListenerResource, version: 18, nonce: 2  (t=+35.819502ms)
        tlogger.go:99: listener_wrapper.go:298 [xds] [xds-server-listener 0x4000275810] Received update for resource "grpc/server?xds.resource.listening_address=127.0.0.1:38695": {RouteConfigName: InlineRouteConfig:<nil> MaxStreamDuration:0s HTTPFilters:[] InboundListenerCfg:0x400033cc90 Raw:[type.googleapis.com/envoy.config.listener.v3.Listener]:{name:"grpc/server?xds.resource.listening_address=127.0.0.1:38695" address:{socket_address:{address:"127.0.0.1" port_value:38695}} filter_chains:{filter_chain_match:{prefix_ranges:{address_prefix:"0.0.0.0" prefix_len:{}} source_type:SAME_IP_OR_LOOPBACK source_prefix_ranges:{address_prefix:"0.0.0.0" prefix_len:{}}} filters:{name:"filter-1" typed_config:{[type.googleapis.com/envoy.extensions.filters.network.http_connection_manager.v3.HttpConnectionManager]:{}}} name:"v4-wildcard"} filter_chains:{filter_chain_match:{prefix_ranges:{address_prefix:"::" prefix_len:{}} source_type:SAME_IP_OR_LOOPBACK source_prefix_ranges:{address_prefix:"::" prefix_len:{}}} filters:{name:"filter-1" typed_config:{[type.googleapis.com/envoy.extensions.filters.network.http_connection_manager.v3.HttpConnectionManager]:{}}} name:"v6-wildcard"}}}  (t=+36.855302ms)
        tlogger.go:99: listener_wrapper.go:331 [xds] [xds-server-listener 0x4000275810] Listener "127.0.0.1:38695" entering mode: "serving" due to error: <nil>  (t=+36.959202ms)
        tlogger.go:99: listener_wrapper.go:290 [xds] [xds-server-listener 0x400047f340] Received error for resource "grpc/server?xds.resource.listening_address=127.0.0.1:33323": xds: ListenerResource target grpc/server?xds.resource.listening_address=127.0.0.1:33323 not found in received response  (t=+37.084602ms)
        tlogger.go:99: listener_wrapper.go:331 [xds] [xds-server-listener 0x400047f340] Listener "127.0.0.1:33323" entering mode: "not-serving" due to error: xds: ListenerResource target grpc/server?xds.resource.listening_address=127.0.0.1:33323 not found in received response  (t=+37.165602ms)
        xds_server_serving_mode_test.go:103: serving mode for listener "127.0.0.1:38695" changed to "serving", err: <nil>
        tlogger.go:99: server.go:48 [xds-e2e] open watch 65 for type.googleapis.com/envoy.config.listener.v3.Listener[grpc/server?xds.resource.listening_address=127.0.0.1:33323 grpc/server?xds.resource.listening_address=127.0.0.1:38695] from nodeID "c82b953d-5ac5-4936-b7ed-146a320857c8", version "18"  (t=+37.008602ms)
        xds_server_serving_mode_test.go:103: serving mode for listener "127.0.0.1:33323" changed to "not-serving", err: xds: ListenerResource target grpc/server?xds.resource.listening_address=127.0.0.1:33323 not found in received response
        tlogger.go:99: clientconn.go:1114 [core] Subchannel Connectivity change to CONNECTING  (t=+37.593102ms)
        tlogger.go:99: clientconn.go:1251 [core] Subchannel picks a new address "127.0.0.1:33323" to connect  (t=+37.899802ms)
        tlogger.go:99: clientconn.go:435 [core] Channel Connectivity change to CONNECTING  (t=+38.004802ms)
        tlogger.go:99: clientconn.go:1326 [core] grpc: addrConn.createTransport failed to connect to {127.0.0.1:33323 127.0.0.1:33323 <nil> 0 <nil>}. Err: write tcp 127.0.0.1:33456->127.0.0.1:33323: write: broken pipe. Reconnecting...  (t=+38.499502ms)
        tlogger.go:99: clientconn.go:1114 [core] Subchannel Connectivity change to TRANSIENT_FAILURE  (t=+38.581702ms)
        tlogger.go:99: clientconn.go:435 [core] Channel Connectivity change to TRANSIENT_FAILURE  (t=+38.676602ms)
        tlogger.go:99: server.go:134 [xds-e2e] Created new resource snapshot...  (t=+42.784903ms)
        tlogger.go:99: server.go:48 [xds-e2e] respond open watch 65[grpc/server?xds.resource.listening_address=127.0.0.1:33323 grpc/server?xds.resource.listening_address=127.0.0.1:38695] with new version "19"  (t=+42.883703ms)
        tlogger.go:99: server.go:48 [xds-e2e] respond type.googleapis.com/envoy.config.listener.v3.Listener[grpc/server?xds.resource.listening_address=127.0.0.1:33323 grpc/server?xds.resource.listening_address=127.0.0.1:38695] version "18" with version "19"  (t=+42.992303ms)
        tlogger.go:99: server.go:140 [xds-e2e] Updated snapshot cache with resource snapshot...  (t=+43.079303ms)
        tlogger.go:99: client.go:146 [xds] [xds-client 0x4000110200] ADS response received, type: type.googleapis.com/envoy.config.listener.v3.Listener  (t=+43.384903ms)
        tlogger.go:99: transport_helper.go:340 [xds] [xds-client 0x4000110200] Sending ACK for response type: ListenerResource, version: 19, nonce: 3  (t=+43.575203ms)
        tlogger.go:99: listener_wrapper.go:290 [xds] [xds-server-listener 0x4000275810] Received error for resource "grpc/server?xds.resource.listening_address=127.0.0.1:38695": xds: ListenerResource target grpc/server?xds.resource.listening_address=127.0.0.1:38695 not found in received response  (t=+43.915503ms)
        tlogger.go:99: listener_wrapper.go:331 [xds] [xds-server-listener 0x4000275810] Listener "127.0.0.1:38695" entering mode: "not-serving" due to error: xds: ListenerResource target grpc/server?xds.resource.listening_address=127.0.0.1:38695 not found in received response  (t=+43.998703ms)
        tlogger.go:99: server.go:48 [xds-e2e] open watch 66 for type.googleapis.com/envoy.config.listener.v3.Listener[grpc/server?xds.resource.listening_address=127.0.0.1:33323 grpc/server?xds.resource.listening_address=127.0.0.1:38695] from nodeID "c82b953d-5ac5-4936-b7ed-146a320857c8", version "19"  (t=+44.269303ms)
        xds_server_serving_mode_test.go:103: serving mode for listener "127.0.0.1:38695" changed to "not-serving", err: xds: ListenerResource target grpc/server?xds.resource.listening_address=127.0.0.1:38695 not found in received response
        tlogger.go:99: clientconn.go:1114 [core] Subchannel Connectivity change to CONNECTING  (t=+45.074203ms)
        tlogger.go:99: clientconn.go:1251 [core] Subchannel picks a new address "127.0.0.1:38695" to connect  (t=+45.373403ms)
        tlogger.go:99: clientconn.go:435 [core] Channel Connectivity change to CONNECTING  (t=+45.650903ms)
        tlogger.go:99: clientconn.go:1114 [core] Subchannel Connectivity change to TRANSIENT_FAILURE  (t=+46.248703ms)
        tlogger.go:99: clientconn.go:435 [core] Channel Connectivity change to TRANSIENT_FAILURE  (t=+46.345303ms)
        tlogger.go:99: clientconn.go:1114 [core] Subchannel Connectivity change to CONNECTING  (t=+1.039881963s)
        tlogger.go:99: clientconn.go:1251 [core] Subchannel picks a new address "127.0.0.1:33323" to connect  (t=+1.040003163s)
        tlogger.go:99: clientconn.go:435 [core] Channel Connectivity change to CONNECTING  (t=+1.040370163s)
        tlogger.go:99: clientconn.go:1114 [core] Subchannel Connectivity change to TRANSIENT_FAILURE  (t=+1.041088063s)
        tlogger.go:99: clientconn.go:435 [core] Channel Connectivity change to TRANSIENT_FAILURE  (t=+1.041178563s)
        tlogger.go:99: clientconn.go:1114 [core] Subchannel Connectivity change to CONNECTING  (t=+1.046390263s)
        tlogger.go:99: clientconn.go:1251 [core] Subchannel picks a new address "127.0.0.1:38695" to connect  (t=+1.046475863s)
        tlogger.go:99: clientconn.go:435 [core] Channel Connectivity change to CONNECTING  (t=+1.046722563s)
        tlogger.go:99: clientconn.go:1114 [core] Subchannel Connectivity change to TRANSIENT_FAILURE  (t=+1.047200663s)
        tlogger.go:99: clientconn.go:435 [core] Channel Connectivity change to TRANSIENT_FAILURE  (t=+1.047290463s)
        tlogger.go:99: clientconn.go:1114 [core] Subchannel Connectivity change to CONNECTING  (t=+2.538524843s)
        tlogger.go:99: clientconn.go:1251 [core] Subchannel picks a new address "127.0.0.1:33323" to connect  (t=+2.538711252s)
        tlogger.go:99: clientconn.go:435 [core] Channel Connectivity change to CONNECTING  (t=+2.539067669s)
        tlogger.go:99: clientconn.go:1114 [core] Subchannel Connectivity change to TRANSIENT_FAILURE  (t=+2.539730302s)
        tlogger.go:99: clientconn.go:435 [core] Channel Connectivity change to TRANSIENT_FAILURE  (t=+2.539821706s)
        tlogger.go:99: clientconn.go:1114 [core] Subchannel Connectivity change to CONNECTING  (t=+2.557093656s)
        tlogger.go:99: clientconn.go:1251 [core] Subchannel picks a new address "127.0.0.1:38695" to connect  (t=+2.55717926s)
        tlogger.go:99: clientconn.go:435 [core] Channel Connectivity change to CONNECTING  (t=+2.55738637s)
        tlogger.go:99: clientconn.go:1114 [core] Subchannel Connectivity change to TRANSIENT_FAILURE  (t=+2.557851493s)
        tlogger.go:99: clientconn.go:435 [core] Channel Connectivity change to TRANSIENT_FAILURE  (t=+2.557939497s)
        tlogger.go:99: clientconn.go:1114 [core] Subchannel Connectivity change to CONNECTING  (t=+5.240972134s)
        tlogger.go:99: clientconn.go:1251 [core] Subchannel picks a new address "127.0.0.1:33323" to connect  (t=+5.24110244s)
        tlogger.go:99: clientconn.go:435 [core] Channel Connectivity change to CONNECTING  (t=+5.24150996s)
        tlogger.go:99: clientconn.go:1114 [core] Subchannel Connectivity change to TRANSIENT_FAILURE  (t=+5.242200594s)
        tlogger.go:99: clientconn.go:435 [core] Channel Connectivity change to TRANSIENT_FAILURE  (t=+5.2423109s)
        tlogger.go:99: clientconn.go:1114 [core] Subchannel Connectivity change to CONNECTING  (t=+5.481928683s)
        tlogger.go:99: clientconn.go:1251 [core] Subchannel picks a new address "127.0.0.1:38695" to connect  (t=+5.482051389s)
        tlogger.go:99: clientconn.go:435 [core] Channel Connectivity change to CONNECTING  (t=+5.482399706s)
        tlogger.go:99: clientconn.go:1326 [core] grpc: addrConn.createTransport failed to connect to {127.0.0.1:38695 127.0.0.1:38695 <nil> 0 <nil>}. Err: write tcp 127.0.0.1:54144->127.0.0.1:38695: write: broken pipe. Reconnecting...  (t=+5.482937932s)
        tlogger.go:99: clientconn.go:1114 [core] Subchannel Connectivity change to TRANSIENT_FAILURE  (t=+5.483149643s)
        tlogger.go:99: clientconn.go:435 [core] Channel Connectivity change to TRANSIENT_FAILURE  (t=+5.483279149s)
        tlogger.go:99: clientconn.go:1114 [core] Subchannel Connectivity change to CONNECTING  (t=+9.207429111s)
        tlogger.go:99: clientconn.go:1251 [core] Subchannel picks a new address "127.0.0.1:33323" to connect  (t=+9.207557911s)
        tlogger.go:99: clientconn.go:435 [core] Channel Connectivity change to CONNECTING  (t=+9.207786911s)
        tlogger.go:99: clientconn.go:1114 [core] Subchannel Connectivity change to TRANSIENT_FAILURE  (t=+9.20848651s)
        tlogger.go:99: clientconn.go:435 [core] Channel Connectivity change to TRANSIENT_FAILURE  (t=+9.20874721s)
        tlogger.go:99: clientconn.go:1114 [core] Subchannel Connectivity change to CONNECTING  (t=+9.397776503s)
        tlogger.go:99: clientconn.go:1251 [core] Subchannel picks a new address "127.0.0.1:38695" to connect  (t=+9.397937103s)
        tlogger.go:99: clientconn.go:435 [core] Channel Connectivity change to CONNECTING  (t=+9.398252403s)
        tlogger.go:99: clientconn.go:1114 [core] Subchannel Connectivity change to TRANSIENT_FAILURE  (t=+9.398898903s)
        tlogger.go:99: clientconn.go:435 [core] Channel Connectivity change to TRANSIENT_FAILURE  (t=+9.398995703s)
        tlogger.go:99: clientconn.go:252 [core] parsed scheme: ""  (t=+10.000984274s)
        tlogger.go:99: clientconn.go:258 [core] scheme "" not registered, fallback to default scheme  (t=+10.001102276s)
        tlogger.go:99: resolver_conn_wrapper.go:96 [core] ccResolverWrapper: sending update to cc: {[{127.0.0.1:38695  <nil> 0 <nil>}] <nil> <nil>}  (t=+10.001217878s)
        tlogger.go:99: clientconn.go:708 [core] ClientConn switching balancer to "pick_first"  (t=+10.001295379s)
        tlogger.go:99: clientconn.go:723 [core] Channel switches to new LB policy "pick_first"  (t=+10.001397081s)
        tlogger.go:99: clientconn.go:1114 [core] Subchannel Connectivity change to CONNECTING  (t=+10.001516983s)
        tlogger.go:99: clientconn.go:435 [core] Channel Connectivity change to SHUTDOWN  (t=+10.001642485s)
        tlogger.go:99: clientconn.go:1114 [core] Subchannel Connectivity change to SHUTDOWN  (t=+10.001718886s)
        tlogger.go:99: server.go:134 [xds-e2e] Created new resource snapshot...  (t=+10.001871888s)
        tlogger.go:99: server.go:48 [xds-e2e] respond open watch 66[grpc/server?xds.resource.listening_address=127.0.0.1:33323 grpc/server?xds.resource.listening_address=127.0.0.1:38695] with new version "20"  (t=+10.002016591s)
        tlogger.go:99: server.go:48 [xds-e2e] respond type.googleapis.com/envoy.config.listener.v3.Listener[grpc/server?xds.resource.listening_address=127.0.0.1:33323 grpc/server?xds.resource.listening_address=127.0.0.1:38695] version "19" with version "20"  (t=+10.002174793s)
        tlogger.go:99: server.go:140 [xds-e2e] Updated snapshot cache with resource snapshot...  (t=+10.002291795s)
        xds_server_serving_mode_test.go:258: error when waiting for a mode change update: context deadline exceeded
        tlogger.go:99: clientconn.go:435 [core] Channel Connectivity change to SHUTDOWN  (t=+10.002978006s)
        tlogger.go:99: client.go:146 [xds] [xds-client 0x4000110200] ADS response received, type: type.googleapis.com/envoy.config.listener.v3.Listener  (t=+10.004308627s)
        tlogger.go:99: clientconn.go:1114 [core] Subchannel Connectivity change to SHUTDOWN  (t=+10.007304675s)
        tlogger.go:99: clientconn.go:435 [core] Channel Connectivity change to SHUTDOWN  (t=+10.007540478s)
        tlogger.go:99: clientconn.go:1114 [core] Subchannel Connectivity change to SHUTDOWN  (t=+10.00764478s)
        tlogger.go:99: xds.go:76 [xds] [xds-client 0x4000110200] Resource with name: grpc/server?xds.resource.listening_address=127.0.0.1:38695, type: *envoy_config_listener_v3.Listener, contains: {
              "name": "grpc/server?xds.resource.listening_address=127.0.0.1:38695",
              "address": {
                "socketAddress": {
                  "address": "127.0.0.1",
                  "portValue": 38695
                }
              },
              "filterChains": [
                {
                  "filterChainMatch": {
                    "prefixRanges": [
                      {
                        "addressPrefix": "0.0.0.0",
                        "prefixLen": 0
                      }
                    ],
                    "sourceType": "SAME_IP_OR_LOOPBACK",
                    "sourcePrefixRanges": [
                      {
                        "addressPrefix": "0.0.0.0",
                        "prefixLen": 0
                      }
                    ]
                  },
                  "filters": [
                    {
                      "name": "filter-1",
                      "typedConfig": {
                        "@type": "type.googleapis.com/envoy.extensions.filters.network.http_connection_manager.v3.HttpConnectionManager"
                      }
                    }
                  ],
                  "name": "v4-wildcard"
                },
                {
                  "filterChainMatch": {
                    "prefixRanges": [
                      {
                        "addressPrefix": "::",
                        "prefixLen": 0
                      }
                    ],
                    "sourceType": "SAME_IP_OR_LOOPBACK",
                    "sourcePrefixRanges": [
                      {
                        "addressPrefix": "::",
                        "prefixLen": 0
                      }
                    ]
                  },
                  "filters": [
                    {
                      "name": "filter-1",
                      "typedConfig": {
                        "@type": "type.googleapis.com/envoy.extensions.filters.network.http_connection_manager.v3.HttpConnectionManager"
                      }
                    }
                  ],
                  "name": "v6-wildcard"
                }
              ]
            }  (t=+10.008039986s)
        tlogger.go:99: xds.go:76 [xds] [xds-client 0x4000110200] Resource with name: grpc/server?xds.resource.listening_address=127.0.0.1:33323, type: *envoy_config_listener_v3.Listener, contains: {
              "name": "grpc/server?xds.resource.listening_address=127.0.0.1:33323",
              "address": {
                "socketAddress": {
                  "address": "127.0.0.1",
                  "portValue": 33323
                }
              },
              "filterChains": [
                {
                  "filterChainMatch": {
                    "prefixRanges": [
                      {
                        "addressPrefix": "0.0.0.0",
                        "prefixLen": 0
                      }
                    ],
                    "sourceType": "SAME_IP_OR_LOOPBACK",
                    "sourcePrefixRanges": [
                      {
                        "addressPrefix": "0.0.0.0",
                        "prefixLen": 0
                      }
                    ]
                  },
                  "filters": [
                    {
                      "name": "filter-1",
                      "typedConfig": {
                        "@type": "type.googleapis.com/envoy.extensions.filters.network.http_connection_manager.v3.HttpConnectionManager"
                      }
                    }
                  ],
                  "name": "v4-wildcard"
                },
                {
                  "filterChainMatch": {
                    "prefixRanges": [
                      {
                        "addressPrefix": "::",
                        "prefixLen": 0
                      }
                    ],
                    "sourceType": "SAME_IP_OR_LOOPBACK",
                    "sourcePrefixRanges": [
                      {
                        "addressPrefix": "::",
                        "prefixLen": 0
                      }
                    ]
                  },
                  "filters": [
                    {
                      "name": "filter-1",
                      "typedConfig": {
                        "@type": "type.googleapis.com/envoy.extensions.filters.network.http_connection_manager.v3.HttpConnectionManager"
                      }
                    }
                  ],
                  "name": "v6-wildcard"
                }
              ]
            }  (t=+10.009039402s)
        tlogger.go:99: transport_helper.go:340 [xds] [xds-client 0x4000110200] Sending ACK for response type: ListenerResource, version: 20, nonce: 4  (t=+10.009724113s)
        tlogger.go:99: listener_wrapper.go:141 [xds] [xds-server-listener 0x4000275810] Watch cancelled on resource name grpc/server?xds.resource.listening_address=127.0.0.1:38695  (t=+10.010125619s)
        tlogger.go:99: server.go:48 [xds-e2e] open watch 67 for type.googleapis.com/envoy.config.listener.v3.Listener[grpc/server?xds.resource.listening_address=127.0.0.1:33323 grpc/server?xds.resource.listening_address=127.0.0.1:38695] from nodeID "c82b953d-5ac5-4936-b7ed-146a320857c8", version "20"  (t=+10.010855831s)
        tlogger.go:99: listener_wrapper.go:298 [xds] [xds-server-listener 0x400047f340] Received update for resource "grpc/server?xds.resource.listening_address=127.0.0.1:33323": {RouteConfigName: InlineRouteConfig:<nil> MaxStreamDuration:0s HTTPFilters:[] InboundListenerCfg:0x4000031ef0 Raw:[type.googleapis.com/envoy.config.listener.v3.Listener]:{name:"grpc/server?xds.resource.listening_address=127.0.0.1:33323" address:{socket_address:{address:"127.0.0.1" port_value:33323}} filter_chains:{filter_chain_match:{prefix_ranges:{address_prefix:"0.0.0.0" prefix_len:{}} source_type:SAME_IP_OR_LOOPBACK source_prefix_ranges:{address_prefix:"0.0.0.0" prefix_len:{}}} filters:{name:"filter-1" typed_config:{[type.googleapis.com/envoy.extensions.filters.network.http_connection_manager.v3.HttpConnectionManager]:{}}} name:"v4-wildcard"} filter_chains:{filter_chain_match:{prefix_ranges:{address_prefix:"::" prefix_len:{}} source_type:SAME_IP_OR_LOOPBACK source_prefix_ranges:{address_prefix:"::" prefix_len:{}}} filters:{name:"filter-1" typed_config:{[type.googleapis.com/envoy.extensions.filters.network.http_connection_manager.v3.HttpConnectionManager]:{}}} name:"v6-wildcard"}}}  (t=+10.011196736s)
        tlogger.go:99: listener_wrapper.go:331 [xds] [xds-server-listener 0x400047f340] Listener "127.0.0.1:33323" entering mode: "serving" due to error: <nil>  (t=+10.011941648s)
        tlogger.go:99: server.go:48 [xds-e2e] open watch 68 for type.googleapis.com/envoy.config.listener.v3.Listener[grpc/server?xds.resource.listening_address=127.0.0.1:33323] from nodeID "c82b953d-5ac5-4936-b7ed-146a320857c8", version "20"  (t=+10.01203835s)
        tlogger.go:99: listener_wrapper.go:141 [xds] [xds-server-listener 0x400047f340] Watch cancelled on resource name grpc/server?xds.resource.listening_address=127.0.0.1:33323  (t=+10.012243753s)
        tlogger.go:99: clientconn.go:435 [core] Channel Connectivity change to SHUTDOWN  (t=+10.012352055s)
        tlogger.go:99: clientconn.go:1114 [core] Subchannel Connectivity change to SHUTDOWN  (t=+10.012432656s)
        tlogger.go:99: client.go:614 [xds] [xds-client 0x4000110200] Shutdown  (t=+10.012515857s)
        tlogger.go:99: transport_helper.go:315 [xds] [xds-client 0x4000110200] ADS stream is closed with error: xds: stream.Recv() failed: rpc error: code = Canceled desc = grpc: the client connection is closing  (t=+10.030736947s)
        tlogger.go:99: transport_helper.go:275 [xds] [xds-client 0x4000110200] ADS request for {target: [], type: ListenerResource, version: "20", nonce: "4"} failed: xds: stream.Send(version_info:"20" node:{id:"c82b953d-5ac5-4936-b7ed-146a320857c8" user_agent_name:"gRPC Go" user_agent_version:"1.39.0-dev" client_features:"envoy.lb.does_not_support_overprovisioning"} type_url:"type.googleapis.com/envoy.config.listener.v3.Listener" response_nonce:"4") failed: EOF  (t=+10.031271055s)

easwars · 2021-05-17T21:55:55Z

The above also seems to be a result of envoyproxy/go-control-plane#431.

It is a little unclear to me though as to why we eventually see those resources from the server after the test times out (after 10s).

dfawley · 2021-06-03T22:57:36Z

Saw again in #4511

menghanl · 2021-06-16T23:21:44Z

https://github.com/grpc/grpc-go/pull/4533/checks?check_run_id=2797734099

easwars · 2021-07-07T23:20:04Z

One more: https://github.com/grpc/grpc-go/pull/4582/checks?check_run_id=3011929638

easwars · 2021-08-20T00:26:20Z

I think the problem could be as follows:

Two listener resources are added to the management server, update is received by the gRPC server, both listeners move to serving mode.

xds_server_serving_mode_test.go:103: serving mode for listener "127.0.0.1:38695" changed to "serving", err: <nil>
xds_server_serving_mode_test.go:103: serving mode for listener "127.0.0.1:33323" changed to "serving", err: <nil>

The test makes couple of calls to waitForModeChange and things are good for now.

Then, we remove one of the listener resources. gRPC server gets the update, and one of the listener moves to not-serving while the other stays in serving. But since the version number on the resource gets bumped by the management server, we still see the mode-change-callback invoked for both listeners.

xds_server_serving_mode_test.go:103: serving mode for listener "127.0.0.1:38695" changed to "serving", err: <nil>
xds_server_serving_mode_test.go:103: serving mode for listener "127.0.0.1:33323" changed to "not-serving", err: xds: ListenerResource target grpc/server?xds.resource.listening_address=127.0.0.1:33323 not found in received response

At this point, the test make only one call to waitForModeChange: lines 193-195

	if err := waitForModeChange(ctx, modeTracker, lis2.Addr(), xds.ServingModeNotServing); err != nil {
		t.Fatal(err)
	}

this means that the modeTracker implementation would have pushed a value on its updateCh which is not being read by the test.

Then, the test removes the second listener resource as well, and this update is also received by the gRPC server, but when the modeTracker implementation attempts to push this mode change on its updateCh, the SendContext() calls gets blocked.

This means that the test while waiting for the second listener to also move to not-serving also gets blocked here: lines 223-225

	if err := waitForModeChange(ctx, modeTracker, lis1.Addr(), xds.ServingModeNotServing); err != nil {
		t.Fatal(err)
	}

But, at this point, I don't understand why this only happens sometimes and not all the time.

dfawley · 2021-08-20T17:06:20Z

See analysis in #4689. I believe this is an actual bug, not a test mistake.

Okay, I think I see what's happening. When we send this update here:

grpc-go/xds/internal/test/xds_server_serving_mode_test.go

Lines 187 to 190 in 8ab16ef

    
           if err := managementServer.Update(e2e.UpdateOptions{ 
        
           	NodeID:    xdsClientNodeID, 
        
           	Listeners: []*v3listenerpb.Listener{listener1}, 
        
           }); err != nil {

Even though the listener resource is not modified, an update comes to the xds client and to the first xds.GRPCServer. This causes the server to kill all its incoming connections. This seems like a bug to me - if the listener in question doesn't change, we don't want to make all connections cycle.

You can make this failure happen reliably by adding a 2 second sleep after sending the update that removes the second listener. I also locally deleted the second listener entirely from this test case, which may help with debugging (and unless there is a strong reason to have both intermingled in the same test, we may want to separate these test cases in the future).

easwars · 2021-08-24T18:09:28Z

Should be fixed by #4689.

dfawley · 2021-08-26T18:02:56Z

Saw this fail on 1.17:

--- FAIL: Test (11.96s)
    --- FAIL: Test/ServerSideXDS_ServingModeChanges (10.09s)
        tlogger.go:99: server.go:103 [xds] [xds-server 0x40009c00a0] Created xds.GRPCServer  (t=+150.202µs)
        tlogger.go:99: server.go:117 [xds] [xds-server 0x40009c00a0] xDS credentials in use: true  (t=+239.403µs)
        tlogger.go:99: server.go:146 [xds-e2e] Created new resource snapshot...  (t=+1.552014ms)
        tlogger.go:99: server.go:152 [xds-e2e] Updated snapshot cache with resource snapshot...  (t=+1.640115ms)
        tlogger.go:99: server.go:178 [xds] [xds-server 0x40009c00a0] Serve() passed a net.Listener on 127.0.0.1:44787  (t=+1.768516ms)
        tlogger.go:99: server.go:178 [xds] [xds-server 0x40009c00a0] Serve() passed a net.Listener on 127.0.0.1:39839  (t=+1.858717ms)
        tlogger.go:99: bootstrap.go:282 [xds] [xds-bootstrap] Bootstrap config for creating xds-client: {
              "BalancerName": "127.0.0.1:44899",
              "Creds": {},
              "TransportAPI": 1,
              "NodeProto": {
                "id": "fefb1662-dea6-4c2a-98c9-cb03eaac322b",
                "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=+3.192628ms)
        tlogger.go:99: clientconn.go:252 [core] parsed scheme: ""  (t=+3.38253ms)
        tlogger.go:99: clientconn.go:258 [core] scheme "" not registered, fallback to default scheme  (t=+3.455831ms)
        tlogger.go:99: resolver_conn_wrapper.go:100 [core] ccResolverWrapper: sending update to cc: {[{127.0.0.1:44899  <nil> 0 <nil>}] <nil> <nil>}  (t=+3.562532ms)
        tlogger.go:99: clientconn.go:728 [core] ClientConn switching balancer to "pick_first"  (t=+3.697933ms)
        tlogger.go:99: clientconn.go:748 [core] Channel switches to new LB policy "pick_first"  (t=+3.766333ms)
        tlogger.go:99: client.go:627 [xds] [xds-client 0x40000bc000] Created ClientConn to xDS management server: 127.0.0.1:44899  (t=+4.028236ms)
        tlogger.go:99: clientconn.go:1142 [core] Subchannel Connectivity change to CONNECTING  (t=+4.131637ms)
        tlogger.go:99: clientconn.go:1253 [core] Subchannel picks a new address "127.0.0.1:44899" to connect  (t=+4.282838ms)
        tlogger.go:99: client.go:639 [xds] [xds-client 0x40000bc000] Created  (t=+4.139237ms)
        tlogger.go:99: server.go:166 [xds] [xds-server 0x40009c00a0] Created an xdsClient  (t=+4.51864ms)
        tlogger.go:99: clientconn.go:436 [core] Channel Connectivity change to CONNECTING  (t=+4.637541ms)
        tlogger.go:99: listener_wrapper.go:154 [xds] [xds-server-listener 0x40005eafc0] Watch started on resource name grpc/server?xds.resource.listening_address=127.0.0.1:44787  (t=+4.747342ms)
        tlogger.go:99: picker_wrapper.go:161 [core] blockingPicker: the picked transport is not ready, loop back to repick  (t=+4.352239ms)
        tlogger.go:99: listener_wrapper.go:154 [xds] [xds-server-listener 0x40000222a0] Watch started on resource name grpc/server?xds.resource.listening_address=127.0.0.1:39839  (t=+4.968544ms)
        tlogger.go:99: clientconn.go:1142 [core] Subchannel Connectivity change to READY  (t=+6.039753ms)
        tlogger.go:99: clientconn.go:436 [core] Channel Connectivity change to READY  (t=+6.426257ms)
        tlogger.go:99: transport_helper.go:208 [xds] [xds-client 0x40000bc000] ADS stream created  (t=+6.655859ms)
        tlogger.go:99: simple.go:360 [xds-e2e] respond type.googleapis.com/envoy.config.listener.v3.Listener[grpc/server?xds.resource.listening_address=127.0.0.1:44787 grpc/server?xds.resource.listening_address=127.0.0.1:39839] version "" with version "17"  (t=+7.91497ms)
        tlogger.go:99: client.go:146 [xds] [xds-client 0x40000bc000] ADS response received, type: type.googleapis.com/envoy.config.listener.v3.Listener  (t=+8.486875ms)
        tlogger.go:99: xds.go:76 [xds] [xds-client 0x40000bc000] Resource with name: grpc/server?xds.resource.listening_address=127.0.0.1:39839, type: *envoy_config_listener_v3.Listener, contains: {
              "name": "grpc/server?xds.resource.listening_address=127.0.0.1:39839",
              "address": {
                "socketAddress": {
                  "address": "127.0.0.1",
                  "portValue": 39839
                }
              },
              "filterChains": [
                {
                  "filterChainMatch": {
                    "prefixRanges": [
                      {
                        "addressPrefix": "0.0.0.0",
                        "prefixLen": 0
                      }
                    ],
                    "sourceType": "SAME_IP_OR_LOOPBACK",
                    "sourcePrefixRanges": [
                      {
                        "addressPrefix": "0.0.0.0",
                        "prefixLen": 0
                      }
                    ]
                  },
                  "filters": [
                    {
                      "name": "filter-1",
                      "typedConfig": {
                        "@type": "type.googleapis.com/envoy.extensions.filters.network.http_connection_manager.v3.HttpConnectionManager",
                        "routeConfig": {
                          "name": "routeName",
                          "virtualHosts": [
                            {
                              "domains": [
                                "lds.target.good:3333"
                              ],
                              "routes": [
                                {
                                  "match": {
                                    "prefix": "/"
                                  },
                                  "nonForwardingAction": {
            
                                  }
                                }
                              ]
                            }
                          ]
                        }
                      }
                    }
                  ],
                  "name": "v4-wildcard"
                },
                {
                  "filterChainMatch": {
                    "prefixRanges": [
                      {
                        "addressPrefix": "::",
                        "prefixLen": 0
                      }
                    ],
                    "sourceType": "SAME_IP_OR_LOOPBACK",
                    "sourcePrefixRanges": [
                      {
                        "addressPrefix": "::",
                        "prefixLen": 0
                      }
                    ]
                  },
                  "filters": [
                    {
                      "name": "filter-1",
                      "typedConfig": {
                        "@type": "type.googleapis.com/envoy.extensions.filters.network.http_connection_manager.v3.HttpConnectionManager",
                        "routeConfig": {
                          "name": "routeName",
                          "virtualHosts": [
                            {
                              "domains": [
                                "lds.target.good:3333"
                              ],
                              "routes": [
                                {
                                  "match": {
                                    "prefix": "/"
                                  },
                                  "nonForwardingAction": {
            
                                  }
                                }
                              ]
                            }
                          ]
                        }
                      }
                    }
                  ],
                  "name": "v6-wildcard"
                }
              ]
            }  (t=+12.974514ms)
        tlogger.go:99: xds.go:76 [xds] [xds-client 0x40000bc000] Resource with name: grpc/server?xds.resource.listening_address=127.0.0.1:44787, type: *envoy_config_listener_v3.Listener, contains: {
              "name": "grpc/server?xds.resource.listening_address=127.0.0.1:44787",
              "address": {
                "socketAddress": {
                  "address": "127.0.0.1",
                  "portValue": 44787
                }
              },
              "filterChains": [
                {
                  "filterChainMatch": {
                    "prefixRanges": [
                      {
                        "addressPrefix": "0.0.0.0",
                        "prefixLen": 0
                      }
                    ],
                    "sourceType": "SAME_IP_OR_LOOPBACK",
                    "sourcePrefixRanges": [
                      {
                        "addressPrefix": "0.0.0.0",
                        "prefixLen": 0
                      }
                    ]
                  },
                  "filters": [
                    {
                      "name": "filter-1",
                      "typedConfig": {
                        "@type": "type.googleapis.com/envoy.extensions.filters.network.http_connection_manager.v3.HttpConnectionManager",
                        "routeConfig": {
                          "name": "routeName",
                          "virtualHosts": [
                            {
                              "domains": [
                                "lds.target.good:3333"
                              ],
                              "routes": [
                                {
                                  "match": {
                                    "prefix": "/"
                                  },
                                  "nonForwardingAction": {
            
                                  }
                                }
                              ]
                            }
                          ]
                        }
                      }
                    }
                  ],
                  "name": "v4-wildcard"
                },
                {
                  "filterChainMatch": {
                    "prefixRanges": [
                      {
                        "addressPrefix": "::",
                        "prefixLen": 0
                      }
                    ],
                    "sourceType": "SAME_IP_OR_LOOPBACK",
                    "sourcePrefixRanges": [
                      {
                        "addressPrefix": "::",
                        "prefixLen": 0
                      }
                    ]
                  },
                  "filters": [
                    {
                      "name": "filter-1",
                      "typedConfig": {
                        "@type": "type.googleapis.com/envoy.extensions.filters.network.http_connection_manager.v3.HttpConnectionManager",
                        "routeConfig": {
                          "name": "routeName",
                          "virtualHosts": [
                            {
                              "domains": [
                                "lds.target.good:3333"
                              ],
                              "routes": [
                                {
                                  "match": {
                                    "prefix": "/"
                                  },
                                  "nonForwardingAction": {
            
                                  }
                                }
                              ]
                            }
                          ]
                        }
                      }
                    }
                  ],
                  "name": "v6-wildcard"
                }
              ]
            }  (t=+14.75773ms)
        tlogger.go:99: transport_helper.go:340 [xds] [xds-client 0x40000bc000] Sending ACK for response type: ListenerResource, version: 17, nonce: 1  (t=+15.535836ms)
        tlogger.go:99: listener_wrapper.go:386 [xds] [xds-server-listener 0x40005eafc0] Received update for resource "grpc/server?xds.resource.listening_address=127.0.0.1:44787": {RouteConfigName: InlineRouteConfig:<nil> MaxStreamDuration:0s HTTPFilters:[] InboundListenerCfg:0x4000a2dda0 Raw:[type.googleapis.com/envoy.config.listener.v3.Listener]:{name:"grpc/server?xds.resource.listening_address=127.0.0.1:44787" address:{socket_address:{address:"127.0.0.1" port_value:44787}} filter_chains:{filter_chain_match:{prefix_ranges:{address_prefix:"0.0.0.0" prefix_len:{}} source_type:SAME_IP_OR_LOOPBACK source_prefix_ranges:{address_prefix:"0.0.0.0" prefix_len:{}}} filters:{name:"filter-1" typed_config:{[type.googleapis.com/envoy.extensions.filters.network.http_connection_manager.v3.HttpConnectionManager]:{route_config:{name:"routeName" virtual_hosts:{domains:"lds.target.good:3333" routes:{match:{prefix:"/"} non_forwarding_action:{}}}}}}} name:"v4-wildcard"} filter_chains:{filter_chain_match:{prefix_ranges:{address_prefix:"::" prefix_len:{}} source_type:SAME_IP_OR_LOOPBACK source_prefix_ranges:{address_prefix:"::" prefix_len:{}}} filters:{name:"filter-1" typed_config:{[type.googleapis.com/envoy.extensions.filters.network.http_connection_manager.v3.HttpConnectionManager]:{route_config:{name:"routeName" virtual_hosts:{domains:"lds.target.good:3333" routes:{match:{prefix:"/"} non_forwarding_action:{}}}}}}} name:"v6-wildcard"}}}  (t=+17.09835ms)
        tlogger.go:99: simple.go:312 [xds-e2e] open watch 65 for type.googleapis.com/envoy.config.listener.v3.Listener[grpc/server?xds.resource.listening_address=127.0.0.1:44787 grpc/server?xds.resource.listening_address=127.0.0.1:39839] from nodeID "fefb1662-dea6-4c2a-98c9-cb03eaac322b", version "17"  (t=+17.298152ms)
        tlogger.go:99: listener_wrapper.go:435 [xds] [xds-server-listener 0x40005eafc0] Listener "127.0.0.1:44787" entering mode: "serving" due to error: <nil>  (t=+17.361652ms)
        xds_server_serving_mode_test.go:102: serving mode for listener "127.0.0.1:44787" changed to "serving", err: <nil>
        tlogger.go:99: listener_wrapper.go:386 [xds] [xds-server-listener 0x40000222a0] Received update for resource "grpc/server?xds.resource.listening_address=127.0.0.1:39839": {RouteConfigName: InlineRouteConfig:<nil> MaxStreamDuration:0s HTTPFilters:[] InboundListenerCfg:0x4000a2ccf0 Raw:[type.googleapis.com/envoy.config.listener.v3.Listener]:{name:"grpc/server?xds.resource.listening_address=127.0.0.1:39839" address:{socket_address:{address:"127.0.0.1" port_value:39839}} filter_chains:{filter_chain_match:{prefix_ranges:{address_prefix:"0.0.0.0" prefix_len:{}} source_type:SAME_IP_OR_LOOPBACK source_prefix_ranges:{address_prefix:"0.0.0.0" prefix_len:{}}} filters:{name:"filter-1" typed_config:{[type.googleapis.com/envoy.extensions.filters.network.http_connection_manager.v3.HttpConnectionManager]:{route_config:{name:"routeName" virtual_hosts:{domains:"lds.target.good:3333" routes:{match:{prefix:"/"} non_forwarding_action:{}}}}}}} name:"v4-wildcard"} filter_chains:{filter_chain_match:{prefix_ranges:{address_prefix:"::" prefix_len:{}} source_type:SAME_IP_OR_LOOPBACK source_prefix_ranges:{address_prefix:"::" prefix_len:{}}} filters:{name:"filter-1" typed_config:{[type.googleapis.com/envoy.extensions.filters.network.http_connection_manager.v3.HttpConnectionManager]:{route_config:{name:"routeName" virtual_hosts:{domains:"lds.target.good:3333" routes:{match:{prefix:"/"} non_forwarding_action:{}}}}}}} name:"v6-wildcard"}}}  (t=+18.645964ms)
        tlogger.go:99: listener_wrapper.go:435 [xds] [xds-server-listener 0x40000222a0] Listener "127.0.0.1:39839" entering mode: "serving" due to error: <nil>  (t=+18.804265ms)
        xds_server_serving_mode_test.go:102: serving mode for listener "127.0.0.1:39839" changed to "serving", err: <nil>
        tlogger.go:99: clientconn.go:252 [core] parsed scheme: ""  (t=+19.039567ms)
        tlogger.go:99: clientconn.go:258 [core] scheme "" not registered, fallback to default scheme  (t=+19.115568ms)
        tlogger.go:99: resolver_conn_wrapper.go:100 [core] ccResolverWrapper: sending update to cc: {[{127.0.0.1:39839  <nil> 0 <nil>}] <nil> <nil>}  (t=+19.300369ms)
        tlogger.go:99: clientconn.go:728 [core] ClientConn switching balancer to "pick_first"  (t=+19.37947ms)
        tlogger.go:99: clientconn.go:748 [core] Channel switches to new LB policy "pick_first"  (t=+19.455071ms)
        tlogger.go:99: picker_wrapper.go:161 [core] blockingPicker: the picked transport is not ready, loop back to repick  (t=+19.618772ms)
        tlogger.go:99: clientconn.go:1142 [core] Subchannel Connectivity change to CONNECTING  (t=+19.742373ms)
        tlogger.go:99: clientconn.go:1253 [core] Subchannel picks a new address "127.0.0.1:39839" to connect  (t=+19.816074ms)
        tlogger.go:99: clientconn.go:436 [core] Channel Connectivity change to CONNECTING  (t=+20.050076ms)
        tlogger.go:99: clientconn.go:1142 [core] Subchannel Connectivity change to READY  (t=+20.55878ms)
        tlogger.go:99: clientconn.go:436 [core] Channel Connectivity change to READY  (t=+20.761182ms)
        tlogger.go:99: clientconn.go:252 [core] parsed scheme: ""  (t=+21.770291ms)
        tlogger.go:99: clientconn.go:258 [core] scheme "" not registered, fallback to default scheme  (t=+21.865692ms)
        tlogger.go:99: resolver_conn_wrapper.go:100 [core] ccResolverWrapper: sending update to cc: {[{127.0.0.1:44787  <nil> 0 <nil>}] <nil> <nil>}  (t=+21.959493ms)
        tlogger.go:99: clientconn.go:728 [core] ClientConn switching balancer to "pick_first"  (t=+22.031393ms)
        tlogger.go:99: clientconn.go:748 [core] Channel switches to new LB policy "pick_first"  (t=+22.112394ms)
        tlogger.go:99: picker_wrapper.go:161 [core] blockingPicker: the picked transport is not ready, loop back to repick  (t=+22.265595ms)
        tlogger.go:99: clientconn.go:1142 [core] Subchannel Connectivity change to CONNECTING  (t=+22.374696ms)
        tlogger.go:99: clientconn.go:1253 [core] Subchannel picks a new address "127.0.0.1:44787" to connect  (t=+22.443697ms)
        tlogger.go:99: clientconn.go:436 [core] Channel Connectivity change to CONNECTING  (t=+22.705799ms)
        tlogger.go:99: clientconn.go:1142 [core] Subchannel Connectivity change to READY  (t=+23.158003ms)
        tlogger.go:99: clientconn.go:436 [core] Channel Connectivity change to READY  (t=+23.261104ms)
        tlogger.go:99: server.go:146 [xds-e2e] Created new resource snapshot...  (t=+24.122412ms)
        tlogger.go:99: simple.go:205 [xds-e2e] respond open watch 65[grpc/server?xds.resource.listening_address=127.0.0.1:44787 grpc/server?xds.resource.listening_address=127.0.0.1:39839] with new version "18"  (t=+24.244613ms)
        tlogger.go:99: simple.go:360 [xds-e2e] respond type.googleapis.com/envoy.config.listener.v3.Listener[grpc/server?xds.resource.listening_address=127.0.0.1:44787 grpc/server?xds.resource.listening_address=127.0.0.1:39839] version "17" with version "18"  (t=+24.396814ms)
        tlogger.go:99: server.go:152 [xds-e2e] Updated snapshot cache with resource snapshot...  (t=+24.537515ms)
        tlogger.go:99: client.go:146 [xds] [xds-client 0x40000bc000] ADS response received, type: type.googleapis.com/envoy.config.listener.v3.Listener  (t=+25.007119ms)
        tlogger.go:99: xds.go:76 [xds] [xds-client 0x40000bc000] Resource with name: grpc/server?xds.resource.listening_address=127.0.0.1:39839, type: *envoy_config_listener_v3.Listener, contains: {
              "name": "grpc/server?xds.resource.listening_address=127.0.0.1:39839",
              "address": {
                "socketAddress": {
                  "address": "127.0.0.1",
                  "portValue": 39839
                }
              },
              "filterChains": [
                {
                  "filterChainMatch": {
                    "prefixRanges": [
                      {
                        "addressPrefix": "0.0.0.0",
                        "prefixLen": 0
                      }
                    ],
                    "sourceType": "SAME_IP_OR_LOOPBACK",
                    "sourcePrefixRanges": [
                      {
                        "addressPrefix": "0.0.0.0",
                        "prefixLen": 0
                      }
                    ]
                  },
                  "filters": [
                    {
                      "name": "filter-1",
                      "typedConfig": {
                        "@type": "type.googleapis.com/envoy.extensions.filters.network.http_connection_manager.v3.HttpConnectionManager",
                        "routeConfig": {
                          "name": "routeName",
                          "virtualHosts": [
                            {
                              "domains": [
                                "lds.target.good:3333"
                              ],
                              "routes": [
                                {
                                  "match": {
                                    "prefix": "/"
                                  },
                                  "nonForwardingAction": {
            
                                  }
                                }
                              ]
                            }
                          ]
                        }
                      }
                    }
                  ],
                  "name": "v4-wildcard"
                },
                {
                  "filterChainMatch": {
                    "prefixRanges": [
                      {
                        "addressPrefix": "::",
                        "prefixLen": 0
                      }
                    ],
                    "sourceType": "SAME_IP_OR_LOOPBACK",
                    "sourcePrefixRanges": [
                      {
                        "addressPrefix": "::",
                        "prefixLen": 0
                      }
                    ]
                  },
                  "filters": [
                    {
                      "name": "filter-1",
                      "typedConfig": {
                        "@type": "type.googleapis.com/envoy.extensions.filters.network.http_connection_manager.v3.HttpConnectionManager",
                        "routeConfig": {
                          "name": "routeName",
                          "virtualHosts": [
                            {
                              "domains": [
                                "lds.target.good:3333"
                              ],
                              "routes": [
                                {
                                  "match": {
                                    "prefix": "/"
                                  },
                                  "nonForwardingAction": {
            
                                  }
                                }
                              ]
                            }
                          ]
                        }
                      }
                    }
                  ],
                  "name": "v6-wildcard"
                }
              ]
            }  (t=+28.269448ms)
        tlogger.go:99: transport_helper.go:340 [xds] [xds-client 0x40000bc000] Sending ACK for response type: ListenerResource, version: 18, nonce: 2  (t=+29.041255ms)
        tlogger.go:99: listener_wrapper.go:378 [xds] [xds-server-listener 0x40005eafc0] Received error for resource "grpc/server?xds.resource.listening_address=127.0.0.1:44787": xds: ListenerResource target grpc/server?xds.resource.listening_address=127.0.0.1:44787 not found in received response  (t=+29.578659ms)
        tlogger.go:99: listener_wrapper.go:435 [xds] [xds-server-listener 0x40005eafc0] Listener "127.0.0.1:44787" entering mode: "not-serving" due to error: xds: ListenerResource target grpc/server?xds.resource.listening_address=127.0.0.1:44787 not found in received response  (t=+29.66706ms)
        xds_server_serving_mode_test.go:102: serving mode for listener "127.0.0.1:44787" changed to "not-serving", err: xds: ListenerResource target grpc/server?xds.resource.listening_address=127.0.0.1:44787 not found in received response
        tlogger.go:99: clientconn.go:1142 [core] Subchannel Connectivity change to IDLE  (t=+30.201665ms)
        tlogger.go:99: clientconn.go:436 [core] Channel Connectivity change to IDLE  (t=+30.76257ms)
        tlogger.go:99: simple.go:312 [xds-e2e] open watch 66 for type.googleapis.com/envoy.config.listener.v3.Listener[grpc/server?xds.resource.listening_address=127.0.0.1:44787 grpc/server?xds.resource.listening_address=127.0.0.1:39839] from nodeID "fefb1662-dea6-4c2a-98c9-cb03eaac322b", version "18"  (t=+30.924671ms)
        tlogger.go:99: listener_wrapper.go:386 [xds] [xds-server-listener 0x40000222a0] Received update for resource "grpc/server?xds.resource.listening_address=127.0.0.1:39839": {RouteConfigName: InlineRouteConfig:<nil> MaxStreamDuration:0s HTTPFilters:[] InboundListenerCfg:0x4000a98c90 Raw:[type.googleapis.com/envoy.config.listener.v3.Listener]:{name:"grpc/server?xds.resource.listening_address=127.0.0.1:39839" address:{socket_address:{address:"127.0.0.1" port_value:39839}} filter_chains:{filter_chain_match:{prefix_ranges:{address_prefix:"0.0.0.0" prefix_len:{}} source_type:SAME_IP_OR_LOOPBACK source_prefix_ranges:{address_prefix:"0.0.0.0" prefix_len:{}}} filters:{name:"filter-1" typed_config:{[type.googleapis.com/envoy.extensions.filters.network.http_connection_manager.v3.HttpConnectionManager]:{route_config:{name:"routeName" virtual_hosts:{domains:"lds.target.good:3333" routes:{match:{prefix:"/"} non_forwarding_action:{}}}}}}} name:"v4-wildcard"} filter_chains:{filter_chain_match:{prefix_ranges:{address_prefix:"::" prefix_len:{}} source_type:SAME_IP_OR_LOOPBACK source_prefix_ranges:{address_prefix:"::" prefix_len:{}}} filters:{name:"filter-1" typed_config:{[type.googleapis.com/envoy.extensions.filters.network.http_connection_manager.v3.HttpConnectionManager]:{route_config:{name:"routeName" virtual_hosts:{domains:"lds.target.good:3333" routes:{match:{prefix:"/"} non_forwarding_action:{}}}}}}} name:"v6-wildcard"}}}  (t=+31.366775ms)
        xds_server_serving_mode_test.go:102: serving mode for listener "127.0.0.1:39839" changed to "serving", err: <nil>
        tlogger.go:99: listener_wrapper.go:435 [xds] [xds-server-listener 0x40000222a0] Listener "127.0.0.1:39839" entering mode: "serving" due to error: <nil>  (t=+31.858379ms)
        tlogger.go:99: clientconn.go:1142 [core] Subchannel Connectivity change to IDLE  (t=+31.805879ms)
        tlogger.go:99: clientconn.go:436 [core] Channel Connectivity change to IDLE  (t=+32.365084ms)
        tlogger.go:99: clientconn.go:1142 [core] Subchannel Connectivity change to CONNECTING  (t=+42.177769ms)
        tlogger.go:99: clientconn.go:1253 [core] Subchannel picks a new address "127.0.0.1:44787" to connect  (t=+42.28367ms)
        tlogger.go:99: clientconn.go:436 [core] Channel Connectivity change to CONNECTING  (t=+42.603573ms)
        tlogger.go:99: clientconn.go:1320 [core] grpc: addrConn.createTransport failed to connect to {127.0.0.1:44787 127.0.0.1:44787 <nil> 0 <nil>}. Err: write tcp 127.0.0.1:39980->127.0.0.1:44787: use of closed network connection  (t=+43.673183ms)
        tlogger.go:99: clientconn.go:1142 [core] Subchannel Connectivity change to TRANSIENT_FAILURE  (t=+43.798584ms)
        tlogger.go:99: clientconn.go:436 [core] Channel Connectivity change to TRANSIENT_FAILURE  (t=+43.906385ms)
        tlogger.go:99: server.go:146 [xds-e2e] Created new resource snapshot...  (t=+44.100186ms)
        tlogger.go:99: simple.go:205 [xds-e2e] respond open watch 66[grpc/server?xds.resource.listening_address=127.0.0.1:44787 grpc/server?xds.resource.listening_address=127.0.0.1:39839] with new version "19"  (t=+44.387889ms)
        tlogger.go:99: simple.go:360 [xds-e2e] respond type.googleapis.com/envoy.config.listener.v3.Listener[grpc/server?xds.resource.listening_address=127.0.0.1:44787 grpc/server?xds.resource.listening_address=127.0.0.1:39839] version "18" with version "19"  (t=+44.50369ms)
        tlogger.go:99: client.go:146 [xds] [xds-client 0x40000bc000] ADS response received, type: type.googleapis.com/envoy.config.listener.v3.Listener  (t=+44.959694ms)
        tlogger.go:99: transport_helper.go:340 [xds] [xds-client 0x40000bc000] Sending ACK for response type: ListenerResource, version: 19, nonce: 3  (t=+45.209496ms)
        tlogger.go:99: listener_wrapper.go:378 [xds] [xds-server-listener 0x40000222a0] Received error for resource "grpc/server?xds.resource.listening_address=127.0.0.1:39839": xds: ListenerResource target grpc/server?xds.resource.listening_address=127.0.0.1:39839 not found in received response  (t=+45.609499ms)
        tlogger.go:99: listener_wrapper.go:435 [xds] [xds-server-listener 0x40000222a0] Listener "127.0.0.1:39839" entering mode: "not-serving" due to error: xds: ListenerResource target grpc/server?xds.resource.listening_address=127.0.0.1:39839 not found in received response  (t=+45.6963ms)
        xds_server_serving_mode_test.go:102: serving mode for listener "127.0.0.1:39839" changed to "not-serving", err: xds: ListenerResource target grpc/server?xds.resource.listening_address=127.0.0.1:39839 not found in received response
        tlogger.go:99: simple.go:312 [xds-e2e] open watch 67 for type.googleapis.com/envoy.config.listener.v3.Listener[grpc/server?xds.resource.listening_address=127.0.0.1:44787 grpc/server?xds.resource.listening_address=127.0.0.1:39839] from nodeID "fefb1662-dea6-4c2a-98c9-cb03eaac322b", version "19"  (t=+46.004503ms)
        tlogger.go:99: server.go:152 [xds-e2e] Updated snapshot cache with resource snapshot...  (t=+44.632291ms)
        tlogger.go:99: clientconn.go:1142 [core] Subchannel Connectivity change to IDLE  (t=+1.045070543s)
        tlogger.go:99: clientconn.go:436 [core] Channel Connectivity change to IDLE  (t=+1.045238144s)
        xds_server_serving_mode_test.go:206: failure when waiting for RPCs to fail: context deadline exceeded
        tlogger.go:99: clientconn.go:436 [core] Channel Connectivity change to SHUTDOWN  (t=+10.010242297s)
        tlogger.go:99: clientconn.go:1142 [core] Subchannel Connectivity change to SHUTDOWN  (t=+10.010824702s)
        tlogger.go:99: clientconn.go:436 [core] Channel Connectivity change to SHUTDOWN  (t=+10.011135605s)
        tlogger.go:99: clientconn.go:1142 [core] Subchannel Connectivity change to SHUTDOWN  (t=+10.011346207s)
        tlogger.go:99: simple.go:312 [xds-e2e] open watch 68 for type.googleapis.com/envoy.config.listener.v3.Listener[grpc/server?xds.resource.listening_address=127.0.0.1:39839] from nodeID "fefb1662-dea6-4c2a-98c9-cb03eaac322b", version "19"  (t=+10.012655118s)
        tlogger.go:99: listener_wrapper.go:157 [xds] [xds-server-listener 0x40005eafc0] Watch cancelled on resource name grpc/server?xds.resource.listening_address=127.0.0.1:44787  (t=+10.013315924s)
        tlogger.go:99: listener_wrapper.go:157 [xds] [xds-server-listener 0x40000222a0] Watch cancelled on resource name grpc/server?xds.resource.listening_address=127.0.0.1:39839  (t=+10.014331133s)
        tlogger.go:99: clientconn.go:436 [core] Channel Connectivity change to SHUTDOWN  (t=+10.014651836s)
        tlogger.go:99: clientconn.go:1142 [core] Subchannel Connectivity change to SHUTDOWN  (t=+10.014817537s)
        tlogger.go:99: client.go:681 [xds] [xds-client 0x40000bc000] Shutdown  (t=+10.014981939s)
        tlogger.go:99: transport_helper.go:315 [xds] [xds-client 0x40000bc000] ADS stream is closed with error: xds: stream.Recv() failed: rpc error: code = Canceled desc = grpc: the client connection is closing  (t=+10.019826381s)
FAIL
FAIL	google.golang.org/grpc/xds/internal/test	15.837s

easwars · 2021-08-31T02:10:01Z

Another: https://github.com/grpc/grpc-go/pull/4718/checks?check_run_id=3468030691

dfawley · 2021-09-02T18:52:41Z

https://github.com/grpc/grpc-go/pull/4713/checks?check_run_id=3499056082

easwars · 2021-09-03T18:00:23Z

Should be fixed by #4712.

easwars · 2022-06-14T21:34:18Z

Seeing more of this still: https://github.com/grpc/grpc-go/runs/6531255144?check_suite_focus=true

zasweq · 2022-06-17T07:18:04Z

https://github.com/grpc/grpc-go/runs/6931294217?check_suite_focus=true

easwars · 2022-06-29T00:58:31Z

https://github.com/grpc/grpc-go/runs/7103567996?check_suite_focus=true

easwars · 2022-11-16T18:38:46Z

Hasn't flaked in a long time.

easwars added the Type: Bug label May 7, 2021

easwars mentioned this issue May 7, 2021

xds: register resources at the mgmt server before requesting them #4406

Merged

easwars closed this as completed in #4406 May 10, 2021

easwars reopened this May 10, 2021

dfawley linked a pull request May 11, 2021 that will close this issue

xds: temporary workaround for go-control-plane bug to deflake xds e2e tests #4413

Merged

dfawley mentioned this issue May 12, 2021

Flaky test Test/ServerSideXDS_FileWatcherCerts #4402

Closed

easwars self-assigned this May 17, 2021

easwars mentioned this issue May 17, 2021

use depth logging from the e2e package #4448

Merged

menghanl mentioned this issue Aug 13, 2021

Flaky test: Test/ServerSideXDS_ServingModeChanges #4674

Closed

easwars closed this as completed Aug 24, 2021

dfawley reopened this Aug 26, 2021

easwars mentioned this issue Aug 31, 2021

xds: use separate update channels for listeners in test #4712

Merged

easwars closed this as completed Sep 3, 2021

github-actions bot locked as resolved and limited conversation to collaborators Mar 3, 2022

easwars reopened this Jun 14, 2022

dfawley added the P2 label Jun 28, 2022

easwars added the Type: Testing label Jul 22, 2022

easwars closed this as completed Nov 16, 2022

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Flaky test: Test/ServerSideXDS_ServingModeChanges #4403

Flaky test: Test/ServerSideXDS_ServingModeChanges #4403

easwars commented May 7, 2021

dfawley commented May 7, 2021

easwars commented May 7, 2021

dfawley commented May 7, 2021

easwars commented May 7, 2021

dfawley commented May 8, 2021

easwars commented May 10, 2021 •

edited

Loading

easwars commented May 17, 2021

easwars commented May 17, 2021 •

edited

Loading

easwars commented May 17, 2021

dfawley commented Jun 3, 2021

menghanl commented Jun 16, 2021

easwars commented Jul 7, 2021

easwars commented Aug 20, 2021

dfawley commented Aug 20, 2021

easwars commented Aug 24, 2021

dfawley commented Aug 26, 2021 •

edited by easwars

Loading

easwars commented Aug 31, 2021

dfawley commented Sep 2, 2021

easwars commented Sep 3, 2021

easwars commented Jun 14, 2022

zasweq commented Jun 17, 2022

easwars commented Jun 29, 2022

easwars commented Nov 16, 2022

Flaky test: Test/ServerSideXDS_ServingModeChanges #4403

Flaky test: Test/ServerSideXDS_ServingModeChanges #4403

Comments

easwars commented May 7, 2021

dfawley commented May 7, 2021

easwars commented May 7, 2021

dfawley commented May 7, 2021

easwars commented May 7, 2021

dfawley commented May 8, 2021

easwars commented May 10, 2021 • edited Loading

easwars commented May 17, 2021

easwars commented May 17, 2021 • edited Loading

easwars commented May 17, 2021

dfawley commented Jun 3, 2021

menghanl commented Jun 16, 2021

easwars commented Jul 7, 2021

easwars commented Aug 20, 2021

dfawley commented Aug 20, 2021

easwars commented Aug 24, 2021

dfawley commented Aug 26, 2021 • edited by easwars Loading

easwars commented Aug 31, 2021

dfawley commented Sep 2, 2021

easwars commented Sep 3, 2021

easwars commented Jun 14, 2022

zasweq commented Jun 17, 2022

easwars commented Jun 29, 2022

easwars commented Nov 16, 2022

easwars commented May 10, 2021 •

edited

Loading

easwars commented May 17, 2021 •

edited

Loading

dfawley commented Aug 26, 2021 •

edited by easwars

Loading