grpc-go icon indicating copy to clipboard operation
grpc-go copied to clipboard

Flaky Test: xds/ServerSideXDS_RedundantUpdateSuppression

Open arjan-bal opened this issue 1 year ago • 4 comments

Example failure: https://github.com/grpc/grpc-go/actions/runs/11253051356/job/31287507377?pr=7498

Logs

--- FAIL: Test/ServerSideXDS_RedundantUpdateSuppression (0.08s)
        setup.go:45: Created new snapshot cache...
        tlogger.go:116: INFO server.go:684 [core] [Server #1427]Server created  (t=+390.751µs)
        setup.go:45: Registered Aggregated Discovery Service (ADS)...
        setup.go:45: xDS management server serving at: 127.0.0.1:36507...
        tlogger.go:116: INFO server.go:880 [core] [Server #1427 ListenSocket #1428]ListenSocket created  (t=+1.994634ms)
        tlogger.go:116: INFO server.go:684 [core] [Server #1429]Server created  (t=+2.279998ms)
        tlogger.go:116: INFO client_refcounted.go:84 [xds] [xds-client 0xc0008f6540] Created client with name "#server" and bootstrap configuration:
             {
              "xds_servers": [
               {
                "server_uri": "passthrough:///127.0.0.1:36507",
                "channel_creds": [
                 {
                  "type": "insecure"
                 }
                ]
               }
              ],
              "certificate_providers": {
               "client-side-certificate-provider-instance": {
                "plugin_name": "file_watcher",
                "config": {
                 "certificate_file": "/tmp/testClientSideXDS361233951/cert.pem",
                 "private_key_file": "/tmp/testClientSideXDS361233951/key.pem",
                 "ca_certificate_file": "/tmp/testClientSideXDS361233951/ca.pem",
                 "refresh_interval": "600s"
                }
               },
               "server-side-certificate-provider-instance": {
                "plugin_name": "file_watcher",
                "config": {
                 "certificate_file": "/tmp/testServerSideXDS1443769593/cert.pem",
                 "private_key_file": "/tmp/testServerSideXDS1443769593/key.pem",
                 "ca_certificate_file": "/tmp/testServerSideXDS1443769593/ca.pem",
                 "refresh_interval": "600s"
                }
               }
              },
              "server_listener_resource_name_template": "grpc/server?xds.resource.listening_address=%s",
              "client_default_listener_resource_name_template": "%s",
              "node": {
               "id": "d67efc3f-f3a5-4ebb-8bc2-fb0689613c70",
               "locality": {}
              }
             }  (t=+3.20514ms)
        tlogger.go:116: INFO client_refcounted.go:89 [xds] xDS node ID: d67efc3f-f3a5-4ebb-8bc2-fb0689613c70  (t=+3.627211ms)
        tlogger.go:116: INFO server.go:123 [xds] [xds-server 0xc000507340] Created xds.GRPCServer  (t=+3.67492ms)
        server.go:229: Created new resource snapshot...
        server.go:235: Updated snapshot cache with resource snapshot...
        tlogger.go:116: INFO server.go:182 [xds] [xds-server 0xc000507340] Serve() passed a net.Listener on 127.0.0.1:42403  (t=+4.211264ms)
        tlogger.go:116: INFO clientconn.go:1652 [core] original dial target is: "passthrough:///127.0.0.1:36507"  (t=+4.335546ms)
        tlogger.go:116: INFO clientconn.go:314 [core] [Channel #1430]Channel created  (t=+4.395709ms)
        tlogger.go:116: INFO clientconn.go:193 [core] [Channel #1430]parsed dial target is: resolver.Target{URL:url.URL{Scheme:"passthrough", Opaque:"", User:(*url.Userinfo)(nil), Host:"", Path:"/127.0.0.1:36507", RawPath:"", OmitHost:false, ForceQuery:false, RawQuery:"", Fragment:"", RawFragment:""}}  (t=+4.475839ms)
        tlogger.go:116: INFO clientconn.go:194 [core] [Channel #1430]Channel authority set to "127.0.0.1:36507"  (t=+4.524651ms)
                  "Attributes": null,
                  "BalancerAttributes": null,
                  "Metadata": null
                }
              ],
              "Endpoints": [
                {
                  "Addresses": [
                    {
                      "Addr": "127.0.0.1:42403",
                      "ServerName": "",
                      "Attributes": null,
                      "BalancerAttributes": null,
                      "Metadata": null
                    }
                  ],
                  "Attributes": null
                }
              ],
              "ServiceConfig": null,
              "Attributes": null
            } (resolver returned new addresses)  (t=+11.659879ms)
        tlogger.go:116: INFO balancer_wrapper.go:109 [core] [Channel #1435]Channel switches to new LB policy "pick_first"  (t=+11.760578ms)
        tlogger.go:116: INFO clientconn.go:841 [core] [Channel #1435 SubChannel #1436]Subchannel created  (t=+11.831671ms)
        tlogger.go:116: INFO clientconn.go:544 [core] [Channel #1435]Channel Connectivity change to CONNECTING  (t=+11.885091ms)
        logging.go:30: nodeID "d67efc3f-f3a5-4ebb-8bc2-fb0689613c70" requested type.googleapis.com/envoy.config.listener.v3.Listener[grpc/server?xds.resource.listening_address=127.0.0.1:42403] and known map[grpc/server?xds.resource.listening_address=127.0.0.1:42403:{}]. Diff []
        logging.go:30: open watch 1 for type.googleapis.com/envoy.config.listener.v3.Listener[grpc/server?xds.resource.listening_address=127.0.0.1:42403] from nodeID "d67efc3f-f3a5-4ebb-8bc2-fb0689613c70", version "1"
        tlogger.go:116: INFO clientconn.go:314 [core] [Channel #1435]Channel exiting idle mode  (t=+12.321588ms)
        tlogger.go:116: INFO clientconn.go:1[197](https://github.com/grpc/grpc-go/actions/runs/11253051356/job/31287507377?pr=7498#step:8:198) [core] [Channel #1435 SubChannel #1436]Subchannel Connectivity change to CONNECTING  (t=+18.041147ms)
        tlogger.go:116: INFO clientconn.go:1317 [core] [Channel #1435 SubChannel #1436]Subchannel picks a new address "127.0.0.1:42403" to connect  (t=+18.126386ms)
        tlogger.go:116: INFO clientconn.go:1197 [core] [Channel #1435 SubChannel #1436]Subchannel Connectivity change to READY  (t=+18.586358ms)
        server.go:229: Created new resource snapshot...
        logging.go:30: respond open watch 1 type.googleapis.com/envoy.config.listener.v3.Listener[grpc/server?xds.resource.listening_address=127.0.0.1:42403] with new version "2"
        logging.go:30: respond type.googleapis.com/envoy.config.listener.v3.Listener[grpc/server?xds.resource.listening_address=127.0.0.1:42403] version "1" with version "2"
        server.go:235: Updated snapshot cache with resource snapshot...
        logging.go:30: nodeID "d67efc3f-f3a5-4ebb-8bc2-fb0689613c70" requested type.googleapis.com/envoy.config.listener.v3.Listener[grpc/server?xds.resource.listening_address=127.0.0.1:42403] and known map[grpc/server?xds.resource.listening_address=127.0.0.1:42403:{}]. Diff []
        logging.go:30: open watch 2 for type.googleapis.com/envoy.config.listener.v3.Listener[grpc/server?xds.resource.listening_address=127.0.0.1:42403] from nodeID "d67efc3f-f3a5-4ebb-8bc2-fb0689613c70", version "2"
        tlogger.go:116: INFO clientconn.go:544 [core] [Channel #1435]Channel Connectivity change to READY  (t=+20.673245ms)
        xds_server_serving_mode_test.go:161: unexpected connectivity state change {READY --> CONNECTING} on the client connection
        tlogger.go:116: INFO clientconn.go:544 [core] [Channel #1435]Channel Connectivity change to SHUTDOWN  (t=+30.60551ms)
        tlogger.go:116: INFO resolver_wrapper.go:100 [core] [Channel #1435]Closing the name resolver  (t=+30.669921ms)
        tlogger.go:116: INFO balancer_wrapper.go:147 [core] [Channel #1435]ccBalancerWrapper: closing  (t=+30.747536ms)
        tlogger.go:116: INFO clientconn.go:1197 [core] [Channel #1435 SubChannel #1436]Subchannel Connectivity change to SHUTDOWN  (t=+30.921221ms)
        tlogger.go:116: INFO clientconn.go:1525 [core] [Channel #1435 SubChannel #1436]Subchannel deleted  (t=+31.026829ms)
        tlogger.go:116: INFO clientconn.go:314 [core] [Channel #1435]Channel deleted  (t=+31.367[206](https://github.com/grpc/grpc-go/actions/runs/11253051356/job/31287507377?pr=7498#step:8:207)ms)
        logging.go:30: nodeID "d67efc3f-f3a5-4ebb-8bc2-fb0689613c70" requested type.googleapis.com/envoy.config.listener.v3.Listener[] and known map[grpc/server?xds.resource.listening_address=127.0.0.1:42403:{}]. Diff []
        logging.go:30: open watch 3 for type.googleapis.com/envoy.config.listener.v3.Listener[] from nodeID "d67efc3f-f3a5-4ebb-8bc2-fb0689613c70", version "2"
        tlogger.go:116: INFO server.go:816 [core] [Server #1429 ListenSocket #1432]ListenSocket deleted  (t=+31.983119ms)
        tlogger.go:116: WARNING authority.go:457 [xds] [xds-client 0xc0008f6540] [passthrough:///127.0.0.1:36507] Watchers not notified since ADS stream failed after having received at least one response: rpc error: code = Canceled desc = context canceled  (t=+32.307066ms)
        tlogger.go:116: WARNING transport.go:498 [xds] [xds-client 0xc0008f6540] [passthrough:///127.0.0.1:36507] ADS stream closed: rpc error: code = Canceled desc = context canceled  (t=+32.356358ms)
        tlogger.go:116: INFO clientconn.go:544 [core] [Channel #1430]Channel Connectivity change to SHUTDOWN  (t=+32.458098ms)
        tlogger.go:116: INFO resolver_wrapper.go:100 [core] [Channel #1430]Closing the name resolver  (t=+32.513472ms)
        tlogger.go:116: INFO balancer_wrapper.go:147 [core] [Channel #1430]ccBalancerWrapper: closing  (t=+32.573595ms)
        tlogger.go:116: INFO clientconn.go:1197 [core] [Channel #1430 SubChannel #1431]Subchannel Connectivity change to SHUTDOWN  (t=+32.654076ms)
        tlogger.go:116: INFO clientconn.go:1525 [core] [Channel #1430 SubChannel #1431]Subchannel deleted  (t=+32.738163ms)
        tlogger.go:116: INFO clientconn.go:314 [core] [Channel #1430]Channel deleted  (t=+32.89694ms)
        tlogger.go:116: INFO clientimpl.go:101 [xds] [xds-client 0xc0008f6540] Shutdown  (t=+32.979805ms)
        tlogger.go:116: INFO server.go:816 [core] [Server #1427 ListenSocket #1428]ListenSocket deleted  (t=+33.076907ms)

arjan-bal avatar Oct 09 '24 10:10 arjan-bal