Flaky test: TestServerSideXDS_WithValidAndInvalidSecurityConfiguration #6913
Description
logs:
--- FAIL: Test (21.28s)
--- FAIL: Test/ServerSideXDS_WithValidAndInvalidSecurityConfiguration (10.00s)
tlogger.go:116: INFO server.go:132 [xds-e2e] Created new snapshot cache... (t=+41.587µs)
tlogger.go:116: INFO server.go:667 [core] [Server #1251] Server created (t=+245.248µs)
tlogger.go:116: INFO server.go:158 [xds-e2e] Registered Aggregated Discovery Service (ADS)... (t=+279.021µs)
tlogger.go:116: INFO server.go:177 [xds-e2e] xDS management server serving at: 127.0.0.1:43987... (t=+314.547µs)
tlogger.go:116: INFO server.go:867 [core] [Server #1251 ListenSocket #1252] ListenSocket created (t=+419.854µs)
tlogger.go:116: INFO server.go:667 [core] [Server #1253] Server created (t=+1.415082ms)
tlogger.go:116: INFO client_new.go:80 [xds] [xds-client 0xc0009f71d0] Created client to xDS management server: 127.0.0.1:43987-insecure-xds_v3 (t=+2.381787ms)
tlogger.go:116: INFO server.go:126 [xds] [xds-server 0xc0005c6a80] Created xds.GRPCServer (t=+2.435117ms)
tlogger.go:116: INFO server.go:185 [xds] [xds-server 0xc0005c6a80] Serve() passed a net.Listener on 127.0.0.1:41227 (t=+2.537438ms)
tlogger.go:116: INFO server.go:185 [xds] [xds-server 0xc0005c6a80] Serve() passed a net.Listener on 127.0.0.1:38643 (t=+2.621775ms)
tlogger.go:116: INFO clientconn.go:304 [core] [Channel #1254] Channel created (t=+2.736189ms)
tlogger.go:116: INFO clientconn.go:1724 [core] [Channel #1254] original dial target is: "127.0.0.1:43987" (t=+2.778338ms)
tlogger.go:116: INFO clientconn.go:1729 [core] [Channel #1254] dial target "127.0.0.1:43987" parse failed: parse "127.0.0.1:43987": first path segment in URL cannot contain colon (t=+2.829784ms)
tlogger.go:116: INFO clientconn.go:1745 [core] [Channel #1254] fallback to scheme "passthrough" (t=+2.866112ms)
tlogger.go:116: INFO clientconn.go:1753 [core] [Channel #1254] parsed dial target is: passthrough:///127.0.0.1:43987 (t=+2.904303ms)
tlogger.go:116: INFO clientconn.go:1874 [core] [Channel #1254] Channel authority set to "127.0.0.1:43987" (t=+2.971528ms)
tlogger.go:116: INFO server.go:220 [xds-e2e] Created new resource snapshot... (t=+3.034055ms)
tlogger.go:116: INFO server.go:226 [xds-e2e] Updated snapshot cache with resource snapshot... (t=+3.076164ms)
tlogger.go:116: INFO resolver_wrapper.go:196 [core] [Channel #1254] Resolver state updated: {
"Addresses": [
{
"Addr": "127.0.0.1:43987",
"ServerName": "",
"Attributes": null,
"BalancerAttributes": null,
"Metadata": null
}
],
"Endpoints": [
{
"Addresses": [
{
"Addr": "127.0.0.1:43987",
"ServerName": "",
"Attributes": null,
"BalancerAttributes": null,
"Metadata": null
}
],
"Attributes": null
}
],
"ServiceConfig": null,
"Attributes": null
} (resolver returned new addresses) (t=+3.167144ms)
tlogger.go:116: INFO balancer_wrapper.go:161 [core] [Channel #1254] Channel switches to new LB policy "pick_first" (t=+3.252914ms)
tlogger.go:116: INFO clientconn.go:848 [core] [Channel #1254 SubChannel #1255] Subchannel created (t=+3.318426ms)
tlogger.go:116: INFO clientconn.go:532 [core] [Channel #1254] Channel Connectivity change to CONNECTING (t=+3.360906ms)
tlogger.go:116: INFO clientconn.go:1223 [core] [Channel #1254 SubChannel #1255] Subchannel Connectivity change to CONNECTING (t=+3.4[205](https://github.com/grpc/grpc-go/actions/runs/7451893903/job/20273977821?pr=6908#step:8:206)47ms)
tlogger.go:116: INFO clientconn.go:1338 [core] [Channel #1254 SubChannel #1255] Subchannel picks a new address "127.0.0.1:43987" to connect (t=+3.45982ms)
tlogger.go:116: INFO clientconn.go:304 [core] [Channel #1254] Channel exiting idle mode (t=+3.628375ms)
tlogger.go:116: INFO transport.go:238 [xds] [xds-client 0xc0009f71d0] [127.0.0.1:43987] Created transport to server "127.0.0.1:43987" (t=+3.696141ms)
tlogger.go:116: INFO clientconn.go:1223 [core] [Channel #1254 SubChannel #1255] Subchannel Connectivity change to READY (t=+4.201796ms)
tlogger.go:116: INFO clientconn.go:532 [core] [Channel #1254] Channel Connectivity change to READY (t=+4.280633ms)
tlogger.go:116: INFO transport.go:337 [xds] [xds-client 0xc0009f71d0] [127.0.0.1:43987] ADS stream created (t=+4.342027ms)
tlogger.go:116: INFO simple.go:359 [xds-e2e] nodeID "9cff038f-7f39-4e20-8f06-5d24ae9015a6" requested type.googleapis.com/envoy.config.listener.v3.Listener[grpc/server?xds.resource.listening_address=127.0.0.1:38643] and known map[]. Diff [grpc/server?xds.resource.listening_address=127.0.0.1:38643] (t=+4.781458ms)
tlogger.go:116: INFO simple.go:428 [xds-e2e] respond type.googleapis.com/envoy.config.listener.v3.Listener[grpc/server?xds.resource.listening_address=127.0.0.1:38643] version "" with version "1" (t=+4.828286ms)
tlogger.go:116: WARNING transport.go:510 [xds] [xds-client 0xc0009f71d0] [127.0.0.1:43987] Sending NACK for resource type: "type.googleapis.com/envoy.config.listener.v3.Listener", version: "1", nonce: "1", reason: error parsing "ListenerResource" response: resource "grpc/server?xds.resource.listening_address=127.0.0.1:38643": identitiy certificate provider instance name "non-existent-certificate-provider" missing in bootstrap configuration (t=+5.56475ms)
tlogger.go:116: INFO simple.go:359 [xds-e2e] nodeID "9cff038f-7f39-4e20-8f06-5d24ae9015a6" requested type.googleapis.com/envoy.config.listener.v3.Listener[grpc/server?xds.resource.listening_address=127.0.0.1:38643] and known map[grpc/server?xds.resource.listening_address=127.0.0.1:38643:{}]. Diff [] (t=+5.823313ms)
tlogger.go:116: INFO simple.go:428 [xds-e2e] respond type.googleapis.com/envoy.config.listener.v3.Listener[grpc/server?xds.resource.listening_address=127.0.0.1:38643] version "" with version "1" (t=+5.868668ms)
tlogger.go:116: WARNING transport.go:510 [xds] [xds-client 0xc0009f71d0] [127.0.0.1:43987] Sending NACK for resource type: "type.googleapis.com/envoy.config.listener.v3.Listener", version: "1", nonce: "2", reason: error parsing "ListenerResource" response: resource "grpc/server?xds.resource.listening_address=127.0.0.1:38643": identitiy certificate provider instance name "non-existent-certificate-provider" missing in bootstrap configuration (t=+6.677769ms)
tlogger.go:116: INFO clientconn.go:304 [core] [Channel #1258] Channel created (t=+27.559578ms)
tlogger.go:116: INFO clientconn.go:1724 [core] [Channel #1258] original dial target is: "127.0.0.1:41227" (t=+27.612306ms)
tlogger.go:116: INFO clientconn.go:1729 [core] [Channel #1258] dial target "127.0.0.1:41227" parse failed: parse "127.0.0.1:41227": first path segment in URL cannot contain colon (t=+27.66296ms)
tlogger.go:116: INFO clientconn.go:1745 [core] [Channel #1258] fallback to scheme "passthrough" (t=+27.700731ms)
tlogger.go:116: INFO clientconn.go:1753 [core] [Channel #1258] parsed dial target is: passthrough:///127.0.0.1:41227 (t=+27.747849ms)
tlogger.go:116: INFO clientconn.go:1874 [core] [Channel #1258] Channel authority set to "x.test.example.com" (t=+27.776282ms)
tlogger.go:116: INFO resolver_wrapper.go:196 [core] [Channel #1258] Resolver state updated: {
"Addresses": [
{
"Addr": "127.0.0.1:41227",
"ServerName": "",
"Attributes": null,
"BalancerAttributes": null,
"Metadata": null
}
],
"Endpoints": [
{
"Addresses": [
{
"Addr": "127.0.0.1:41227",
"ServerName": "",
"Attributes": null,
"BalancerAttributes": null,
"Metadata": null
}
],
"Attributes": null
}
],
"ServiceConfig": null,
"Attributes": null
} (resolver returned new addresses) (t=+27.967289ms)
tlogger.go:116: INFO balancer_wrapper.go:161 [core] [Channel #1258] Channel switches to new LB policy "pick_first" (t=+28.061745ms)
tlogger.go:116: INFO clientconn.go:848 [core] [Channel #1258 SubChannel #1259] Subchannel created (t=+28.134371ms)
tlogger.go:116: INFO clientconn.go:532 [core] [Channel #1258] Channel Connectivity change to CONNECTING (t=+28.178373ms)
tlogger.go:116: INFO clientconn.go:304 [core] [Channel #1258] Channel exiting idle mode (t=+28.234798ms)
tlogger.go:116: INFO clientconn.go:1223 [core] [Channel #1258 SubChannel #1259] Subchannel Connectivity change to CONNECTING (t=+28.29451ms)
tlogger.go:116: INFO clientconn.go:1338 [core] [Channel #1258 SubChannel #1259] Subchannel picks a new address "127.0.0.1:41227" to connect (t=+28.332801ms)
xds_server_certificate_providers_test.go:461: EmptyCall() failed: rpc error: code = DeadlineExceeded desc = context deadline exceeded
tlogger.go:116: INFO simple.go:359 [xds-e2e] nodeID "9cff038f-7f39-4e20-8f06-5d24ae9015a6" requested type.googleapis.com/envoy.config.listener.v3.Listener[grpc/server?xds.resource.listening_address=127.0.0.1:38643] and known map[grpc/server?xds.resource.listening_address=127.0.0.1:38643:{}]. Diff [] (t=+10.003127377s)
tlogger.go:116: INFO simple.go:428 [xds-e2e] respond type.googleapis.com/envoy.config.listener.v3.Listener[grpc/server?xds.resource.listening_address=127.0.0.1:38643] version "" with version "1" (t=+10.003200533s)
tlogger.go:116: INFO simple.go:359 [xds-e2e] nodeID "9cff038f-7f39-4e20-8f06-5d24ae9015a6" requested type.googleapis.com/envoy.config.listener.v3.Listener[grpc/server?xds.resource.listening_address=127.0.0.1:38643 grpc/server?xds.resource.listening_address=127.0.0.1:41227] and known map[grpc/server?xds.resource.listening_address=127.0.0.1:38643:{}]. Diff [grpc/server?xds.resource.listening_address=127.0.0.1:41227] (t=+10.003330336s)
tlogger.go:116: INFO simple.go:428 [xds-e2e] respond type.googleapis.com/envoy.config.listener.v3.Listener[grpc/server?xds.resource.listening_address=127.0.0.1:38643 grpc/server?xds.resource.listening_address=127.0.0.1:41227] version "" with version "1" (t=+10.003386631s)
tlogger.go:116: INFO clientconn.go:532 [core] [Channel #1258] Channel Connectivity change to SHUTDOWN (t=+10.003451192s)
tlogger.go:116: INFO resolver_wrapper.go:99 [core] [Channel #1258] Closing the name resolver (t=+10.003506815s)
tlogger.go:116: INFO balancer_wrapper.go:178 [core] [Channel #1258] ccBalancerWrapper: closing (t=+10.00357869s)
tlogger.go:116: INFO clientconn.go:1223 [core] [Channel #1258 SubChannel #1259] Subchannel Connectivity change to SHUTDOWN (t=+10.003676512s)
tlogger.go:116: INFO clientconn.go:1569 [core] [Channel #1258 SubChannel #1259] Subchannel deleted (t=+10.003751512s)
tlogger.go:116: INFO clientconn.go:304 [core] [Channel #1258] Channel deleted (t=+10.003807076s)
tlogger.go:116: WARNING authority.go:417 [xds] [xds-client 0xc0009f71d0] [127.0.0.1:43987] Watchers not notified since ADS stream failed after having received at least one response: rpc error: code = Canceled desc = context canceled (t=+10.003973908s)
tlogger.go:116: WARNING transport.go:483 [xds] [xds-client 0xc0009f71d0] [127.0.0.1:43987] ADS stream closed: rpc error: code = Canceled desc = context canceled (t=+10.004026376s)
tlogger.go:116: WARNING clientconn.go:1400 [core] [Channel #1258 SubChannel #1259] grpc: addrConn.createTransport failed to connect to {Addr: "127.0.0.1:41227", ServerName: "x.test.example.com", }. Err: connection error: desc = "transport: authentication handshake failed: context canceled" (t=+10.004094252s)
tlogger.go:116: INFO clientconn.go:532 [core] [Channel #1254] Channel Connectivity change to SHUTDOWN (t=+10.004162129s)
tlogger.go:116: INFO resolver_wrapper.go:99 [core] [Channel #1254] Closing the name resolver (t=+10.004[207](https://github.com/grpc/grpc-go/actions/runs/7451893903/job/20273977821?pr=6908#step:8:208)744s)
tlogger.go:116: INFO balancer_wrapper.go:178 [core] [Channel #1254] ccBalancerWrapper: closing (t=+10.004274419s)
tlogger.go:116: INFO clientconn.go:1[223](https://github.com/grpc/grpc-go/actions/runs/7451893903/job/20273977821?pr=6908#step:8:224) [core] [Channel #1254 SubChannel #1255] Subchannel Connectivity change to SHUTDOWN (t=+10.004340332s)
tlogger.go:116: INFO clientconn.go:1569 [core] [Channel #1254 SubChannel #1255] Subchannel deleted (t=+10.004379124s)
tlogger.go:116: INFO clientconn.go:304 [core] [Channel #1254] Channel deleted (t=+10.004491855s)
tlogger.go:116: INFO clientimpl.go:100 [xds] [xds-client 0xc0009f71d0] Shutdown (t=+10.004536558s)
tlogger.go:116: INFO server.go:806 [core] [Server #1[251](https://github.com/grpc/grpc-go/actions/runs/7451893903/job/20273977821?pr=6908#step:8:252) ListenSocket #1[252](https://github.com/grpc/grpc-go/actions/runs/7451893903/job/20273977821?pr=6908#step:8:253)] ListenSocket deleted (t=+10.004600718s)
FAIL
https://github.com/grpc/grpc-go/actions/runs/7451893903/job/20273977821?pr=6908