Closed as duplicate of#7713
Description
--- FAIL: Test (7.02s)
--- FAIL: Test/Server_RedundantUpdateSuppression (0.10s)
server_resource_ext_test.go:169: Created new snapshot cache...
tlogger.go:116: INFO server.go:715 [core] [Server #1501]Server created (t=+415.818µs)
server_resource_ext_test.go:169: Registered Aggregated Discovery Service (ADS)...
server_resource_ext_test.go:169: xDS management server serving at: 127.0.0.1:38667...
tlogger.go:116: INFO server.go:911 [core] [Server #1501 ListenSocket #1502]ListenSocket created (t=+1.863739ms)
server.go:229: Created new resource snapshot...
server.go:235: Updated snapshot cache with resource snapshot...
tlogger.go:116: INFO server.go:715 [core] [Server #1503]Server created (t=+4.036747ms)
tlogger.go:116: INFO pool.go:283 [xds] xDS node ID: ce6e42be-21c0-48a0-b6a7-1bbc796f1304 (t=+4.16691ms)
tlogger.go:116: INFO server.go:124 [xds] [xds-server 0xc000502500] Created xds.GRPCServer (t=+4.2[207](https://github.com/grpc/grpc-go/actions/runs/15576804040/job/43863167655?pr=8391#step:8:208)21ms)
stubserver.go:300: Started test service backend at "127.0.0.1:36397"
tlogger.go:116: INFO server.go:183 [xds] [xds-server 0xc000502500] Serve() passed a net.Listener on 127.0.0.1:36397 (t=+4.397492ms)
tlogger.go:116: INFO clientconn.go:1687 [core] original dial target is: "passthrough:///127.0.0.1:38667" (t=+4.60461ms)
tlogger.go:116: INFO clientconn.go:333 [core] [Channel #1504]Channel created (t=+4.720156ms)
tlogger.go:116: INFO clientconn.go:207 [core] [Channel #1504]parsed dial target is: resolver.Target{URL:url.URL{Scheme:"passthrough", Opaque:"", User:(*url.Userinfo)(nil), Host:"", Path:"/127.0.0.1:38667", RawPath:"", OmitHost:false, ForceQuery:false, RawQuery:"", Fragment:"", RawFragment:""}} (t=+4.876318ms)
tlogger.go:116: INFO clientconn.go:[208](https://github.com/grpc/grpc-go/actions/runs/15576804040/job/43863167655?pr=8391#step:8:209) [core] [Channel #1504]Channel authority set to "127.0.0.1:38667" (t=+5.577892ms)
tlogger.go:116: INFO server.go:911 [core] [Server #1503 ListenSocket #1505]ListenSocket created (t=+5.738041ms)
tlogger.go:116: INFO resolver_wrapper.go:[210](https://github.com/grpc/grpc-go/actions/runs/15576804040/job/43863167655?pr=8391#step:8:211) [core] [Channel #1504]Resolver state updated: {
"Addresses": [
{
"Addr": "127.0.0.1:38667",
"ServerName": "",
"Attributes": null,
"BalancerAttributes": null,
"Metadata": null
}
],
"Endpoints": [
{
"Addresses": [
{
"Addr": "127.0.0.1:38667",
"ServerName": "",
"Attributes": null,
"BalancerAttributes": null,
"Metadata": null
}
],
"Attributes": null
}
],
"ServiceConfig": null,
"Attributes": null
} (resolver returned new addresses) (t=+5.990484ms)
tlogger.go:116: INFO balancer_wrapper.go:122 [core] [Channel #1504]Channel switches to new LB policy "pick_first" (t=+6.080953ms)
tlogger.go:116: INFO clientconn.go:866 [core] [Channel #1504 SubChannel #1506]Subchannel created (t=+6.178125ms)
tlogger.go:116: INFO clientconn.go:563 [core] [Channel #1504]Channel Connectivity change to CONNECTING (t=+6.251302ms)
tlogger.go:116: INFO clientconn.go:1233 [core] [Channel #1504 SubChannel #1506]Subchannel Connectivity change to CONNECTING (t=+6.331302ms)
tlogger.go:116: INFO clientconn.go:1352 [core] [Channel #1504 SubChannel #1506]Subchannel picks a new address "127.0.0.1:38667" to connect (t=+6.38396ms)
tlogger.go:116: INFO clientconn.go:333 [core] [Channel #1504]Channel exiting idle mode (t=+6.600596ms)
tlogger.go:116: INFO clientconn.go:1233 [core] [Channel #1504 SubChannel #1506]Subchannel Connectivity change to READY (t=+8.782851ms)
tlogger.go:116: INFO clientconn.go:563 [core] [Channel #1504]Channel Connectivity change to READY (t=+8.867369ms)
logging.go:30: nodeID "ce6e42be-21c0-48a0-b6a7-1bbc796f1304" requested type.googleapis.com/envoy.config.listener.v3.Listener[grpc/server?xds.resource.listening_address=127.0.0.1:36397] and known map[]. Diff [grpc/server?xds.resource.listening_address=127.0.0.1:36397]
logging.go:30: respond type.googleapis.com/envoy.config.listener.v3.Listener[grpc/server?xds.resource.listening_address=127.0.0.1:36397] version "" with version "1"
server_ext_test.go:115: Serving mode for listener "127.0.0.1:36397" changed to "SERVING", err: <nil>
tlogger.go:116: INFO clientconn.go:1687 [core] original dial target is: "127.0.0.1:36397" (t=+10.491499ms)
tlogger.go:116: INFO clientconn.go:333 [core] [Channel #1509]Channel created (t=+10.555289ms)
tlogger.go:116: INFO clientconn.go:207 [core] [Channel #1509]parsed dial target is: resolver.Target{URL:url.URL{Scheme:"dns", Opaque:"", User:(*url.Userinfo)(nil), Host:"", Path:"/127.0.0.1:36397", RawPath:"", OmitHost:false, ForceQuery:false, RawQuery:"", Fragment:"", RawFragment:""}} (t=+10.640759ms)
tlogger.go:116: INFO clientconn.go:208 [core] [Channel #1509]Channel authority set to "127.0.0.1:36397" (t=+10.689891ms)
logging.go:30: nodeID "ce6e42be-21c0-48a0-b6a7-1bbc796f1304" requested type.googleapis.com/envoy.config.listener.v3.Listener[grpc/server?xds.resource.listening_address=127.0.0.1:36397] and known map[grpc/server?xds.resource.listening_address=127.0.0.1:36397:{}]. 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:36397] from nodeID "ce6e42be-21c0-48a0-b6a7-1bbc796f1304", version "1"
tlogger.go:116: INFO resolver_wrapper.go:210 [core] [Channel #1509]Resolver state updated: {
"Addresses": [
{
"Addr": "127.0.0.1:36397",
"ServerName": "",
"Attributes": null,
"BalancerAttributes": null,
"Metadata": null
}
],
"Endpoints": [
{
"Addresses": [
{
"Addr": "127.0.0.1:36397",
"ServerName": "",
"Attributes": null,
"BalancerAttributes": null,
"Metadata": null
}
],
"Attributes": null
}
],
"ServiceConfig": null,
"Attributes": null
} (resolver returned new addresses) (t=+21.45889ms)
tlogger.go:116: INFO balancer_wrapper.go:122 [core] [Channel #1509]Channel switches to new LB policy "pick_first" (t=+21.555351ms)
tlogger.go:116: INFO clientconn.go:866 [core] [Channel #1509 SubChannel #1510]Subchannel created (t=+21.637344ms)
tlogger.go:116: INFO clientconn.go:563 [core] [Channel #1509]Channel Connectivity change to CONNECTING (t=+21.696405ms)
tlogger.go:116: INFO clientconn.go:1233 [core] [Channel #1509 SubChannel #1510]Subchannel Connectivity change to CONNECTING (t=+21.772808ms)
tlogger.go:116: INFO clientconn.go:1352 [core] [Channel #1509 SubChannel #1510]Subchannel picks a new address "127.0.0.1:36397" to connect (t=+21.828973ms)
tlogger.go:116: INFO clientconn.go:333 [core] [Channel #1509]Channel exiting idle mode (t=+22.037924ms)
tlogger.go:116: INFO clientconn.go:1233 [core] [Channel #1509 SubChannel #1510]Subchannel Connectivity change to READY (t=+22.934673ms)
server.go:[229](https://github.com/grpc/grpc-go/actions/runs/15576804040/job/43863167655?pr=8391#step:8:230): 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:36397] 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:36397] version "1" with version "2"
server.go:235: Updated snapshot cache with resource snapshot...
logging.go:30: nodeID "ce6e42be-21c0-48a0-b6a7-1bbc796f1304" requested type.googleapis.com/envoy.config.listener.v3.Listener[grpc/server?xds.resource.listening_address=127.0.0.1:36397] and known map[grpc/server?xds.resource.listening_address=127.0.0.1:36397:{}]. 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:36397] from nodeID "ce6e42be-21c0-48a0-b6a7-1bbc796f1304", version "2"
tlogger.go:116: INFO clientconn.go:563 [core] [Channel #1509]Channel Connectivity change to READY (t=+25.119903ms)
server_resource_ext_test.go:268: unexpected connectivity state change {READY --> CONNECTING} on the client connection
tlogger.go:116: INFO clientconn.go:563 [core] [Channel #1509]Channel Connectivity change to SHUTDOWN (t=+45.442943ms)
tlogger.go:116: INFO resolver_wrapper.go:111 [core] [Channel #1509]Closing the name resolver (t=+45.499689ms)
tlogger.go:116: INFO balancer_wrapper.go:160 [core] [Channel #1509]ccBalancerWrapper: closing (t=+45.566273ms)
tlogger.go:116: INFO clientconn.go:1[233](https://github.com/grpc/grpc-go/actions/runs/15576804040/job/43863167655?pr=8391#step:8:234) [core] [Channel #1509 SubChannel #1510]Subchannel Connectivity change to SHUTDOWN (t=+45.706045ms)
tlogger.go:116: INFO clientconn.go:1560 [core] [Channel #1509 SubChannel #1510]Subchannel deleted (t=+45.774263ms)
tlogger.go:116: INFO clientconn.go:333 [core] [Channel #1509]Channel deleted (t=+45.944331ms)
tlogger.go:116: WARNING ads_stream.go:496 [xds] [xds-client 0xc00049e[240](https://github.com/grpc/grpc-go/actions/runs/15576804040/job/43863167655?pr=8391#step:8:241)] [xds-channel 0xc0013400a0] [ads-stream 0xc001ac4080] ADS stream closed: rpc error: code = Canceled desc = context canceled (t=+46.188138ms)
tlogger.go:116: INFO ads_stream.go:155 [xds] [xds-client 0xc00049e240] [xds-channel 0xc0013400a0] [ads-stream 0xc001ac4080] Shutdown ADS stream (t=+46.289913ms)
tlogger.go:116: INFO clientconn.go:563 [core] [Channel #1504]Channel Connectivity change to SHUTDOWN (t=+46.376064ms)
tlogger.go:116: INFO resolver_wrapper.go:111 [core] [Channel #1504]Closing the name resolver (t=+46.429024ms)
logging.go:30: nodeID "ce6e42be-21c0-48a0-b6a7-1bbc796f1304" requested type.googleapis.com/envoy.config.listener.v3.Listener[] and known map[grpc/server?xds.resource.listening_address=127.0.0.1:36397:{}]. Diff []
logging.go:30: open watch 3 for type.googleapis.com/envoy.config.listener.v3.Listener[] from nodeID "ce6e42be-21c0-48a0-b6a7-1bbc796f1304", version "2"
tlogger.go:116: INFO balancer_wrapper.go:160 [core] [Channel #1504]ccBalancerWrapper: closing (t=+46.49134ms)
tlogger.go:116: INFO clientconn.go:1233 [core] [Channel #1504 SubChannel #1506]Subchannel Connectivity change to SHUTDOWN (t=+46.890347ms)
tlogger.go:116: INFO clientconn.go:1560 [core] [Channel #1504 SubChannel #1506]Subchannel deleted (t=+46.971399ms)
tlogger.go:116: INFO clientconn.go:333 [core] [Channel #1504]Channel deleted (t=+47.178096ms)
tlogger.go:116: INFO channel.go:142 [xds] [xds-client 0xc00049e240] [xds-channel 0xc0013400a0] Shutdown (t=+47.26588ms)
tlogger.go:116: INFO server.go:847 [core] [Server #1503 ListenSocket #1505]ListenSocket deleted (t=+47.342694ms)
tlogger.go:116: INFO xdsclient.go:207 [xds] [xds-client 0xc00049e240] Shutdown (t=+47.438343ms)
tlogger.go:116: INFO server.go:847 [core] [Server #1501 ListenSocket #1502]ListenSocket deleted (t=+47.533872ms)
FAIL