Skip to content
New issue

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

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Flaky test: Test/ServerSideXDS_RedundantUpdateSuppression #4974

Closed
menghanl opened this issue Nov 11, 2021 · 9 comments · Fixed by #5463
Closed

Flaky test: Test/ServerSideXDS_RedundantUpdateSuppression #4974

menghanl opened this issue Nov 11, 2021 · 9 comments · Fixed by #5463
Assignees
@easwars
Labels
P2 Type: Testing

Comments

@menghanl
Copy link
Contributor

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

Log

--- FAIL: Test (7.10s)
    --- FAIL: Test/ServerSideXDS_RedundantUpdateSuppression (0.13s)
        tlogger.go:116: INFO server.go:89 [xds-e2e] Created new snapshot cache...  (t=+66.7µs)
        tlogger.go:116: INFO server.go:103 [xds-e2e] Registered Aggregated Discovery Service (ADS)...  (t=+588.2µs)
        tlogger.go:116: INFO server.go:107 [xds-e2e] xDS management server serving at: 127.0.0.1:44819...  (t=+726.5µs)
        tlogger.go:116: INFO server.go:111 [xds] [xds-server 0xc000714190] Created xds.GRPCServer  (t=+2.714499ms)
        tlogger.go:116: INFO server.go:125 [xds] [xds-server 0xc000714190] xDS credentials in use: true  (t=+2.774999ms)
        tlogger.go:116: INFO server.go:157 [xds-e2e] Created new resource snapshot...  (t=+3.102599ms)
        tlogger.go:116: INFO server.go:163 [xds-e2e] Updated snapshot cache with resource snapshot...  (t=+3.173899ms)
        tlogger.go:116: INFO server.go:186 [xds] [xds-server 0xc000714190] Serve() passed a net.Listener on 127.0.0.1:38493  (t=+3.320899ms)
        tlogger.go:116: INFO bootstrap.go:397 [xds] [xds-bootstrap] Bootstrap config for creating xds-client: {
              "XDSServer": {
                "ServerURI": "127.0.0.1:44819",
                "Creds": {},
                "TransportAPI": 1,
                "NodeProto": {
                  "id": "aeb8c193-3940-4069-b5c6-9f3f9ce0f4a0",
                  "user_agent_name": "gRPC Go",
                  "UserAgentVersionType": {
                    "UserAgentVersion": "1.43.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",
              "ClientDefaultListenerResourceNameTemplate": "%s",
              "Authorities": null
            }  (t=+5.096398ms)
        tlogger.go:116: INFO client.go:65 [xds] [xds-client 0xc000640870] Created ClientConn to xDS management server: &{127.0.0.1:44819 %!s(*grpc.funcDialOption=&{0xe43620}) insecure %!s(version.TransportAPI=1) id:"aeb8c193-3940-4069-b5c6-9f3f9ce0f4a0"  user_agent_name:"gRPC Go"  user_agent_version:"1.43.0-dev"  client_features:"envoy.lb.does_not_support_overprovisioning"}  (t=+5.294598ms)
        tlogger.go:116: INFO clientconn.go:1623 [core] original dial target is: "127.0.0.1:44819"  (t=+5.527598ms)
        tlogger.go:116: INFO clientconn.go:1628 [core] dial target "127.0.0.1:44819" parse failed: parse "127.0.0.1:44819": first path segment in URL cannot contain colon  (t=+5.603698ms)
        tlogger.go:116: INFO clientconn.go:1643 [core] fallback to scheme "passthrough"  (t=+5.645798ms)
        tlogger.go:116: INFO clientconn.go:1651 [core] parsed dial target is: {Scheme:passthrough Authority: Endpoint:127.0.0.1:44819 URL:{Scheme:passthrough Opaque: User: Host: Path:/127.0.0.1:44819 RawPath: ForceQuery:false RawQuery: Fragment: RawFragment:}}  (t=+5.715098ms)
        tlogger.go:116: INFO clientconn.go:262 [core] Channel authority set to "127.0.0.1:44819"  (t=+5.762098ms)
        tlogger.go:116: INFO resolver_conn_wrapper.go:100 [core] ccResolverWrapper: sending update to cc: {[{127.0.0.1:44819  <nil> <nil> 0 <nil>}] <nil> <nil>}  (t=+5.863098ms)
        tlogger.go:116: INFO clientconn.go:712 [core] ClientConn switching balancer to "pick_first"  (t=+5.924798ms)
        tlogger.go:116: INFO clientconn.go:732 [core] Channel switches to new LB policy "pick_first"  (t=+5.980098ms)
        tlogger.go:116: INFO client.go:75 [xds] [xds-client 0xc000640870] Created  (t=+6.217998ms)
        tlogger.go:116: INFO server.go:174 [xds] [xds-server 0xc000714190] Created an xdsClient  (t=+6.265598ms)
        tlogger.go:116: INFO clientconn.go:1143 [core] Subchannel Connectivity change to CONNECTING  (t=+6.403798ms)
        tlogger.go:116: INFO clientconn.go:1254 [core] Subchannel picks a new address "127.0.0.1:44819" to connect  (t=+6.585898ms)
        tlogger.go:116: INFO clientconn.go:417 [core] Channel Connectivity change to CONNECTING  (t=+6.709898ms)
        tlogger.go:116: INFO picker_wrapper.go:161 [core] blockingPicker: the picked transport is not ready, loop back to repick  (t=+6.776998ms)
        tlogger.go:116: INFO listener_wrapper.go:129 [xds] [xds-server-listener 0xc0006aa700] Watch started on resource name grpc/server?xds.resource.listening_address=127.0.0.1:38493  (t=+8.122597ms)
        tlogger.go:116: INFO clientconn.go:1143 [core] Subchannel Connectivity change to READY  (t=+8.228397ms)
        tlogger.go:116: INFO clientconn.go:417 [core] Channel Connectivity change to READY  (t=+8.347597ms)
        tlogger.go:116: INFO transport.go:87 ADS stream created  (t=+8.538197ms)
        tlogger.go:116: INFO simple.go:361 [xds-e2e] respond type.googleapis.com/envoy.config.listener.v3.Listener[grpc/server?xds.resource.listening_address=127.0.0.1:38493] version "" with version "1"  (t=+9.665697ms)
        tlogger.go:116: INFO client.go:124 [xds] [xds-client 0xc000640870] ADS response received, type: type.googleapis.com/envoy.config.listener.v3.Listener  (t=+10.386297ms)
        tlogger.go:116: INFO unmarshal_lds.go:58 Resource with name: grpc/server?xds.resource.listening_address=127.0.0.1:38493, type: *envoy_config_listener_v3.Listener, contains: {
              "name": "grpc/server?xds.resource.listening_address=127.0.0.1:38493",
              "address": {
                "socketAddress": {
                  "address": "127.0.0.1",
                  "portValue": 38493
                }
              },
              "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": [
                                "*"
                              ],
                              "routes": [
                                {
                                  "match": {
                                    "prefix": "/"
                                  },
                                  "nonForwardingAction": {
            
                                  }
                                }
                              ]
                            }
                          ]
                        },
                        "httpFilters": [
                          {
                            "name": "router",
                            "typedConfig": {
                              "@type": "type.googleapis.com/envoy.extensions.filters.http.router.v3.Router"
                            }
                          }
                        ]
                      }
                    }
                  ],
                  "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": [
                                "*"
                              ],
                              "routes": [
                                {
                                  "match": {
                                    "prefix": "/"
                                  },
                                  "nonForwardingAction": {
            
                                  }
                                }
                              ]
                            }
                          ]
                        },
                        "httpFilters": [
                          {
                            "name": "router",
                            "typedConfig": {
                              "@type": "type.googleapis.com/envoy.extensions.filters.http.router.v3.Router"
                            }
                          }
                        ]
                      }
                    }
                  ],
                  "name": "v6-wildcard"
                }
              ]
            }  (t=+17.248995ms)
        tlogger.go:116: INFO simple.go:313 [xds-e2e] open watch 1 for type.googleapis.com/envoy.config.listener.v3.Listener[grpc/server?xds.resource.listening_address=127.0.0.1:38493] from nodeID "aeb8c193-3940-4069-b5c6-9f3f9ce0f4a0", version "1"  (t=+20.163994ms)
        tlogger.go:116: INFO transport.go:222 Sending ACK for response type: ListenerResource, version: 1, nonce: 1  (t=+20.380694ms)
        tlogger.go:116: INFO listener_wrapper.go:390 [xds] [xds-server-listener 0xc0006aa700] Received update for resource "grpc/server?xds.resource.listening_address=127.0.0.1:38493": {RouteConfigName: InlineRouteConfig:<nil> MaxStreamDuration:0s HTTPFilters:[] InboundListenerCfg:0xc00073ccc0 Raw:[type.googleapis.com/envoy.config.listener.v3.Listener]:{name:"grpc/server?xds.resource.listening_address=127.0.0.1:38493"  address:{socket_address:{address:"127.0.0.1"  port_value:38493}}  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:"*"  routes:{match:{prefix:"/"}  non_forwarding_action:{}}}}  http_filters:{name:"router"  typed_config:{[type.googleapis.com/envoy.extensions.filters.http.router.v3.Router]:{}}}}}}  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:"*"  routes:{match:{prefix:"/"}  non_forwarding_action:{}}}}  http_filters:{name:"router"  typed_config:{[type.googleapis.com/envoy.extensions.filters.http.router.v3.Router]:{}}}}}}  name:"v6-wildcard"}}}  (t=+21.446794ms)
        tlogger.go:116: WARNING listener_wrapper.go:441 [xds] [xds-server-listener 0xc0006aa700] Listener "127.0.0.1:38493" entering mode: "SERVING" due to error: <nil>  (t=+21.565194ms)
        xds_server_serving_mode_test.go:66: serving mode for listener "127.0.0.1:38493" changed to "SERVING", err: <nil>
        tlogger.go:116: INFO clientconn.go:1623 [core] original dial target is: "127.0.0.1:38493"  (t=+21.731394ms)
        tlogger.go:116: INFO clientconn.go:1628 [core] dial target "127.0.0.1:38493" parse failed: parse "127.0.0.1:38493": first path segment in URL cannot contain colon  (t=+21.804694ms)
        tlogger.go:116: INFO clientconn.go:1643 [core] fallback to scheme "passthrough"  (t=+21.848994ms)
        tlogger.go:116: INFO clientconn.go:1651 [core] parsed dial target is: {Scheme:passthrough Authority: Endpoint:127.0.0.1:38493 URL:{Scheme:passthrough Opaque: User: Host: Path:/127.0.0.1:38493 RawPath: ForceQuery:false RawQuery: Fragment: RawFragment:}}  (t=+21.929594ms)
        tlogger.go:116: INFO clientconn.go:262 [core] Channel authority set to "127.0.0.1:38493"  (t=+21.984994ms)
        tlogger.go:116: INFO resolver_conn_wrapper.go:100 [core] ccResolverWrapper: sending update to cc: {[{127.0.0.1:38493  <nil> <nil> 0 <nil>}] <nil> <nil>}  (t=+22.072594ms)
        tlogger.go:116: INFO clientconn.go:712 [core] ClientConn switching balancer to "pick_first"  (t=+22.145794ms)
        tlogger.go:116: INFO clientconn.go:732 [core] Channel switches to new LB policy "pick_first"  (t=+22.189893ms)
        tlogger.go:116: INFO picker_wrapper.go:161 [core] blockingPicker: the picked transport is not ready, loop back to repick  (t=+22.405593ms)
        tlogger.go:116: INFO clientconn.go:1143 [core] Subchannel Connectivity change to CONNECTING  (t=+22.457493ms)
        tlogger.go:116: INFO clientconn.go:1254 [core] Subchannel picks a new address "127.0.0.1:38493" to connect  (t=+22.562493ms)
        tlogger.go:116: INFO clientconn.go:1143 [core] Subchannel Connectivity change to READY  (t=+23.829993ms)
        tlogger.go:116: INFO clientconn.go:417 [core] Channel Connectivity change to CONNECTING  (t=+24.092193ms)
        tlogger.go:116: INFO server.go:157 [xds-e2e] Created new resource snapshot...  (t=+25.339993ms)
        tlogger.go:116: INFO simple.go:202 [xds-e2e] respond open watch 1[grpc/server?xds.resource.listening_address=127.0.0.1:38493] with new version "2"  (t=+25.447393ms)
        tlogger.go:116: INFO simple.go:361 [xds-e2e] respond type.googleapis.com/envoy.config.listener.v3.Listener[grpc/server?xds.resource.listening_address=127.0.0.1:38493] version "1" with version "2"  (t=+25.526893ms)
        tlogger.go:116: INFO server.go:163 [xds-e2e] Updated snapshot cache with resource snapshot...  (t=+25.618193ms)
        tlogger.go:116: INFO client.go:124 [xds] [xds-client 0xc000640870] ADS response received, type: type.googleapis.com/envoy.config.listener.v3.Listener  (t=+26.121692ms)
        tlogger.go:116: INFO clientconn.go:417 [core] Channel Connectivity change to READY  (t=+29.226592ms)
        tlogger.go:116: INFO unmarshal_lds.go:58 Resource with name: grpc/server?xds.resource.listening_address=127.0.0.1:38493, type: *envoy_config_listener_v3.Listener, contains: {
              "name": "grpc/server?xds.resource.listening_address=127.0.0.1:38493",
              "address": {
                "socketAddress": {
                  "address": "127.0.0.1",
                  "portValue": 38493
                }
              },
              "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": [
                                "*"
                              ],
                              "routes": [
                                {
                                  "match": {
                                    "prefix": "/"
                                  },
                                  "nonForwardingAction": {
            
                                  }
                                }
                              ]
                            }
                          ]
                        },
                        "httpFilters": [
                          {
                            "name": "router",
                            "typedConfig": {
                              "@type": "type.googleapis.com/envoy.extensions.filters.http.router.v3.Router"
                            }
                          }
                        ]
                      }
                    }
                  ],
                  "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": [
                                "*"
                              ],
                              "routes": [
                                {
                                  "match": {
                                    "prefix": "/"
                                  },
                                  "nonForwardingAction": {
            
                                  }
                                }
                              ]
                            }
                          ]
                        },
                        "httpFilters": [
                          {
                            "name": "router",
                            "typedConfig": {
                              "@type": "type.googleapis.com/envoy.extensions.filters.http.router.v3.Router"
                            }
                          }
                        ]
                      }
                    }
                  ],
                  "name": "v6-wildcard"
                }
              ]
            }  (t=+30.111991ms)
        tlogger.go:116: INFO transport.go:222 Sending ACK for response type: ListenerResource, version: 2, nonce: 2  (t=+30.955391ms)
        tlogger.go:116: INFO simple.go:313 [xds-e2e] open watch 2 for type.googleapis.com/envoy.config.listener.v3.Listener[grpc/server?xds.resource.listening_address=127.0.0.1:38493] from nodeID "aeb8c193-3940-4069-b5c6-9f3f9ce0f4a0", version "2"  (t=+31.603891ms)
        xds_server_serving_mode_test.go:152: unexpected connectivity state change {READY --> CONNECTING} on the client connection
        tlogger.go:116: INFO clientconn.go:417 [core] Channel Connectivity change to SHUTDOWN  (t=+127.421864ms)
        tlogger.go:116: INFO clientconn.go:1143 [core] Subchannel Connectivity change to SHUTDOWN  (t=+127.645764ms)
        tlogger.go:116: INFO listener_wrapper.go:132 [xds] [xds-server-listener 0xc0006aa700] Watch cancelled on resource name grpc/server?xds.resource.listening_address=127.0.0.1:38493  (t=+127.881164ms)
        tlogger.go:116: INFO clientconn.go:417 [core] Channel Connectivity change to SHUTDOWN  (t=+128.096664ms)
        tlogger.go:116: WARNING transport.go:154 ADS request for {target: [], type: ListenerResource, version: "2", nonce: "2"} failed: xds: stream.Send(version_info:"2"  node:{id:"aeb8c193-3940-4069-b5c6-9f3f9ce0f4a0"  user_agent_name:"gRPC Go"  user_agent_version:"1.43.0-dev"  client_features:"envoy.lb.does_not_support_overprovisioning"}  type_url:"type.googleapis.com/envoy.config.listener.v3.Listener"  response_nonce:"2") failed: EOF  (t=+128.577163ms)
        tlogger.go:116: WARNING transport.go:195 ADS stream is closed with error: xds: stream.Recv() failed: rpc error: code = Canceled desc = context canceled  (t=+128.712063ms)
        tlogger.go:116: INFO clientconn.go:1143 [core] Subchannel Connectivity change to SHUTDOWN  (t=+128.822463ms)
        tlogger.go:116: INFO client.go:103 [xds] [xds-client 0xc000640870] Shutdown  (t=+128.912963ms)
FAIL
FAIL	google.golang.org/grpc/xds/internal/test	15.193s

@easwars easwars self-assigned this Nov 17, 2021
@easwars
Copy link
Contributor

easwars commented Jan 19, 2022

One more: https://github.com/grpc/grpc-go/runs/4872246852?check_suite_focus=true

Log

--- FAIL: Test (7.10s)
    --- FAIL: Test/ServerSideXDS_RedundantUpdateSuppression (0.18s)
        tlogger.go:116: INFO server.go:89 [xds-e2e] Created new snapshot cache...  (t=+93.701µs)
        tlogger.go:116: INFO server.go:103 [xds-e2e] Registered Aggregated Discovery Service (ADS)...  (t=+611.204µs)
        tlogger.go:116: INFO server.go:107 [xds-e2e] xDS management server serving at: 127.0.0.1:41525...  (t=+721.605µs)
        tlogger.go:116: INFO server.go:111 [xds] [xds-server 0xc000a34320] Created xds.GRPCServer  (t=+2.208615ms)
        tlogger.go:116: INFO server.go:125 [xds] [xds-server 0xc000a34320] xDS credentials in use: true  (t=+2.259515ms)
        tlogger.go:116: INFO server.go:157 [xds-e2e] Created new resource snapshot...  (t=+2.552117ms)
        tlogger.go:116: INFO server.go:163 [xds-e2e] Updated snapshot cache with resource snapshot...  (t=+2.596618ms)
        tlogger.go:116: INFO server.go:186 [xds] [xds-server 0xc000a34320] Serve() passed a net.Listener on 127.0.0.1:42829  (t=+2.777719ms)
        tlogger.go:116: INFO bootstrap.go:417 [xds] [xds-bootstrap] Bootstrap config for creating xds-client: {
              "XDSServer": {
                "ServerURI": "127.0.0.1:41525",
                "Creds": {},
                "CredsType": "insecure",
                "TransportAPI": 1,
                "NodeProto": {
                  "id": "f6d40ac8-ba10-4b3f-876f-d10727cc77cb",
                  "user_agent_name": "gRPC Go",
                  "UserAgentVersionType": {
                    "UserAgentVersion": "1.45.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",
              "ClientDefaultListenerResourceNameTemplate": "%s",
              "Authorities": null
            }  (t=+4.32003ms)
        tlogger.go:116: INFO client.go:81 [xds] [xds-client 0xc00044d200] Created ClientConn to xDS management server: 127.0.0.1:41525-insecure-xDSv3  (t=+4.40983ms)
        tlogger.go:116: INFO client.go:82 [xds] [xds-client 0xc00044d200] Created  (t=+4.445531ms)
        tlogger.go:116: INFO server.go:174 [xds] [xds-server 0xc000a34320] Created an xdsClient  (t=+4.483931ms)
        tlogger.go:116: INFO clientconn.go:1623 [core] original dial target is: "127.0.0.1:41525"  (t=+4.695632ms)
        tlogger.go:116: INFO clientconn.go:1628 [core] dial target "127.0.0.1:41525" parse failed: parse "127.0.0.1:41525": first path segment in URL cannot contain colon  (t=+4.756533ms)
        tlogger.go:116: INFO clientconn.go:1643 [core] fallback to scheme "passthrough"  (t=+4.790933ms)
        tlogger.go:116: INFO clientconn.go:1651 [core] parsed dial target is: {Scheme:passthrough Authority: Endpoint:127.0.0.1:41525 URL:{Scheme:passthrough Opaque: User: Host: Path:/127.0.0.1:41525 RawPath: ForceQuery:false RawQuery: Fragment: RawFragment:}}  (t=+4.864733ms)
        tlogger.go:116: INFO clientconn.go:262 [core] Channel authority set to "127.0.0.1:41525"  (t=+4.904434ms)
        tlogger.go:116: INFO resolver_conn_wrapper.go:100 [core] ccResolverWrapper: sending update to cc: {[{127.0.0.1:41525  <nil> <nil> 0 <nil>}] <nil> <nil>}  (t=+4.964134ms)
        tlogger.go:116: INFO clientconn.go:712 [core] ClientConn switching balancer to "pick_first"  (t=+5.004434ms)
        tlogger.go:116: INFO clientconn.go:732 [core] Channel switches to new LB policy "pick_first"  (t=+5.037835ms)
        tlogger.go:116: INFO listener_wrapper.go:129 [xds] [xds-server-listener 0xc0004e6ee0] Watch started on resource name grpc/server?xds.resource.listening_address=127.0.0.1:42829  (t=+5.319137ms)
        tlogger.go:116: INFO clientconn.go:1143 [core] Subchannel Connectivity change to CONNECTING  (t=+5.433237ms)
        tlogger.go:116: INFO clientconn.go:1254 [core] Subchannel picks a new address "127.0.0.1:41525" to connect  (t=+5.505338ms)
        tlogger.go:116: INFO picker_wrapper.go:161 [core] blockingPicker: the picked transport is not ready, loop back to repick  (t=+5.87814ms)
        tlogger.go:116: INFO clientconn.go:417 [core] Channel Connectivity change to CONNECTING  (t=+5.966841ms)
        tlogger.go:116: INFO clientconn.go:1143 [core] Subchannel Connectivity change to READY  (t=+7.041648ms)
        tlogger.go:116: INFO clientconn.go:417 [core] Channel Connectivity change to READY  (t=+7.146249ms)
        tlogger.go:116: INFO transport.go:88 ADS stream created  (t=+7.27765ms)
        tlogger.go:116: INFO simple.go:361 [xds-e2e] respond type.googleapis.com/envoy.config.listener.v3.Listener[grpc/server?xds.resource.listening_address=127.0.0.1:42829] version "" with version "1"  (t=+8.452458ms)
        tlogger.go:116: INFO client.go:124 [xds] [xds-client 0xc00044d200] ADS response received, type: type.googleapis.com/envoy.config.listener.v3.Listener  (t=+8.924461ms)
        tlogger.go:116: INFO unmarshal_lds.go:58 Resource with name: grpc/server?xds.resource.listening_address=127.0.0.1:42829, type: *envoy_config_listener_v3.Listener, contains: {
              "name": "grpc/server?xds.resource.listening_address=127.0.0.1:42829",
              "address": {
                "socketAddress": {
                  "address": "127.0.0.1",
                  "portValue": 42829
                }
              },
              "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": [
                                "*"
                              ],
                              "routes": [
                                {
                                  "match": {
                                    "prefix": "/"
                                  },
                                  "nonForwardingAction": {
            
                                  }
                                }
                              ]
                            }
                          ]
                        },
                        "httpFilters": [
                          {
                            "name": "router",
                            "typedConfig": {
                              "@type": "type.googleapis.com/envoy.extensions.filters.http.router.v3.Router"
                            }
                          }
                        ]
                      }
                    }
                  ],
                  "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": [
                                "*"
                              ],
                              "routes": [
                                {
                                  "match": {
                                    "prefix": "/"
                                  },
                                  "nonForwardingAction": {
            
                                  }
                                }
                              ]
                            }
                          ]
                        },
                        "httpFilters": [
                          {
                            "name": "router",
                            "typedConfig": {
                              "@type": "type.googleapis.com/envoy.extensions.filters.http.router.v3.Router"
                            }
                          }
                        ]
                      }
                    }
                  ],
                  "name": "v6-wildcard"
                }
              ]
            }  (t=+13.01459ms)
        tlogger.go:116: INFO listener_wrapper.go:390 [xds] [xds-server-listener 0xc0004e6ee0] Received update for resource "grpc/server?xds.resource.listening_address=127.0.0.1:42829": {RouteConfigName: InlineRouteConfig:<nil> MaxStreamDuration:0s HTTPFilters:[] InboundListenerCfg:0xc000a0d140 Raw:[type.googleapis.com/envoy.config.listener.v3.Listener]:{name:"grpc/server?xds.resource.listening_address=127.0.0.1:42829" address:{socket_address:{address:"127.0.0.1" port_value:42829}} 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:"*" routes:{match:{prefix:"/"} non_forwarding_action:{}}}} http_filters:{name:"router" typed_config:{[type.googleapis.com/envoy.extensions.filters.http.router.v3.Router]:{}}}}}} 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:"*" routes:{match:{prefix:"/"} non_forwarding_action:{}}}} http_filters:{name:"router" typed_config:{[type.googleapis.com/envoy.extensions.filters.http.router.v3.Router]:{}}}}}} name:"v6-wildcard"}}}  (t=+16.068711ms)
        tlogger.go:116: WARNING listener_wrapper.go:441 [xds] [xds-server-listener 0xc0004e6ee0] Listener "127.0.0.1:42829" entering mode: "SERVING" due to error: <nil>  (t=+16.214912ms)
        xds_server_serving_mode_test.go:66: serving mode for listener "127.0.0.1:42829" changed to "SERVING", err: <nil>
        tlogger.go:116: INFO clientconn.go:1623 [core] original dial target is: "127.0.0.1:42829"  (t=+16.439913ms)
        tlogger.go:116: INFO clientconn.go:1628 [core] dial target "127.0.0.1:42829" parse failed: parse "127.0.0.1:42829": first path segment in URL cannot contain colon  (t=+16.511814ms)
        tlogger.go:116: INFO clientconn.go:1643 [core] fallback to scheme "passthrough"  (t=+16.552614ms)
        tlogger.go:116: INFO clientconn.go:1651 [core] parsed dial target is: {Scheme:passthrough Authority: Endpoint:127.0.0.1:42829 URL:{Scheme:passthrough Opaque: User: Host: Path:/127.0.0.1:42829 RawPath: ForceQuery:false RawQuery: Fragment: RawFragment:}}  (t=+16.623915ms)
        tlogger.go:116: INFO clientconn.go:262 [core] Channel authority set to "127.0.0.1:42829"  (t=+16.677815ms)
        tlogger.go:116: INFO resolver_conn_wrapper.go:100 [core] ccResolverWrapper: sending update to cc: {[{127.0.0.1:42829  <nil> <nil> 0 <nil>}] <nil> <nil>}  (t=+16.738015ms)
        tlogger.go:116: INFO clientconn.go:712 [core] ClientConn switching balancer to "pick_first"  (t=+16.806816ms)
        tlogger.go:116: INFO clientconn.go:732 [core] Channel switches to new LB policy "pick_first"  (t=+16.849216ms)
        tlogger.go:116: INFO clientconn.go:1143 [core] Subchannel Connectivity change to CONNECTING  (t=+17.103918ms)
        tlogger.go:116: INFO clientconn.go:1254 [core] Subchannel picks a new address "127.0.0.1:42829" to connect  (t=+17.217519ms)
        tlogger.go:116: INFO clientconn.go:1143 [core] Subchannel Connectivity change to READY  (t=+18.687329ms)
        tlogger.go:116: INFO clientconn.go:417 [core] Channel Connectivity change to CONNECTING  (t=+19.026131ms)
        tlogger.go:116: INFO server.go:157 [xds-e2e] Created new resource snapshot...  (t=+19.996838ms)
        tlogger.go:116: INFO server.go:163 [xds-e2e] Updated snapshot cache with resource snapshot...  (t=+20.049538ms)
        tlogger.go:116: INFO clientconn.go:417 [core] Channel Connectivity change to READY  (t=+20.33574ms)
        tlogger.go:116: INFO transport.go:223 Sending ACK for response type: ListenerResource, version: 1, nonce: 1  (t=+20.408041ms)
        tlogger.go:116: INFO simple.go:361 [xds-e2e] respond type.googleapis.com/envoy.config.listener.v3.Listener[grpc/server?xds.resource.listening_address=127.0.0.1:42829] version "1" with version "2"  (t=+20.935144ms)
        tlogger.go:116: INFO client.go:124 [xds] [xds-client 0xc00044d200] ADS response received, type: type.googleapis.com/envoy.config.listener.v3.Listener  (t=+21.380447ms)
        tlogger.go:116: INFO unmarshal_lds.go:58 Resource with name: grpc/server?xds.resource.listening_address=127.0.0.1:42829, type: *envoy_config_listener_v3.Listener, contains: {
              "name": "grpc/server?xds.resource.listening_address=127.0.0.1:42829",
              "address": {
                "socketAddress": {
                  "address": "127.0.0.1",
                  "portValue": 42829
                }
              },
              "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": [
                                "*"
                              ],
                              "routes": [
                                {
                                  "match": {
                                    "prefix": "/"
                                  },
                                  "nonForwardingAction": {
            
                                  }
                                }
                              ]
                            }
                          ]
                        },
                        "httpFilters": [
                          {
                            "name": "router",
                            "typedConfig": {
                              "@type": "type.googleapis.com/envoy.extensions.filters.http.router.v3.Router"
                            }
                          }
                        ]
                      }
                    }
                  ],
                  "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": [
                                "*"
                              ],
                              "routes": [
                                {
                                  "match": {
                                    "prefix": "/"
                                  },
                                  "nonForwardingAction": {
            
                                  }
                                }
                              ]
                            }
                          ]
                        },
                        "httpFilters": [
                          {
                            "name": "router",
                            "typedConfig": {
                              "@type": "type.googleapis.com/envoy.extensions.filters.http.router.v3.Router"
                            }
                          }
                        ]
                      }
                    }
                  ],
                  "name": "v6-wildcard"
                }
              ]
            }  (t=+24.525469ms)
        tlogger.go:116: INFO transport.go:223 Sending ACK for response type: ListenerResource, version: 2, nonce: 2  (t=+25.247774ms)
        tlogger.go:116: INFO simple.go:313 [xds-e2e] open watch 1 for type.googleapis.com/envoy.config.listener.v3.Listener[grpc/server?xds.resource.listening_address=127.0.0.1:42829] from nodeID "f6d40ac8-ba10-4b3f-876f-d10727cc77cb", version "2"  (t=+25.855178ms)
        xds_server_serving_mode_test.go:152: unexpected connectivity state change {READY --> CONNECTING} on the client connection
        tlogger.go:116: INFO clientconn.go:417 [core] Channel Connectivity change to SHUTDOWN  (t=+121.86864ms)
        tlogger.go:116: INFO clientconn.go:1143 [core] Subchannel Connectivity change to SHUTDOWN  (t=+121.957741ms)
        tlogger.go:116: INFO listener_wrapper.go:132 [xds] [xds-server-listener 0xc0004e6ee0] Watch cancelled on resource name grpc/server?xds.resource.listening_address=127.0.0.1:42829  (t=+122.125542ms)
        tlogger.go:116: INFO clientconn.go:417 [core] Channel Connectivity change to SHUTDOWN  (t=+122.642346ms)
        tlogger.go:116: WARNING transport.go:196 ADS stream is closed with error: xds: stream.Recv() failed: rpc error: code = Canceled desc = context canceled  (t=+122.868047ms)
        tlogger.go:116: INFO clientconn.go:1143 [core] Subchannel Connectivity change to SHUTDOWN  (t=+122.953548ms)
        tlogger.go:116: INFO client.go:112 [xds] [xds-client 0xc00044d200] Shutdown  (t=+123.017348ms)
FAIL
FAIL	google.golang.org/grpc/xds/internal/test	15.634s

@easwars
Copy link
Contributor

easwars commented Jan 31, 2022

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

@easwars
Copy link
Contributor

easwars commented Mar 1, 2022

Closing this since we haven't seen a failure in quite a while now.

@easwars easwars closed this as completed Mar 1, 2022
@easwars
Copy link
Contributor

easwars commented Mar 22, 2022

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

@easwars easwars reopened this Mar 22, 2022
@easwars
Copy link
Contributor

easwars commented Mar 25, 2022

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

@easwars
Copy link
Contributor

easwars commented Mar 25, 2022

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

@easwars
Copy link
Contributor

easwars commented Apr 1, 2022

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

@zasweq
Copy link
Contributor

zasweq commented May 9, 2022

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

@easwars easwars mentioned this issue May 16, 2022
Closed
@easwars
Copy link
Contributor

easwars commented Jun 22, 2022

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

@easwars easwars mentioned this issue Jun 23, 2022
Merged
@github-actions github-actions bot locked as resolved and limited conversation to collaborators Dec 22, 2022
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Assignees

@easwars easwars

Labels
P2 Type: Testing
Projects
None yet
Milestone
No milestone
Development

Successfully merging a pull request may close this issue.

test/xds: fail only when state changes to something other than READY and IDLE easwars/grpc-go
3 participants
@menghanl @easwars @zasweq