Flaky test : ClientSideXDS_WithValidAndInvalidSecurityConfigurationSPIFFE

[mbissa]

Test is flaking on PR, passing on local: https://github.com/grpc/grpc-go/actions/runs/23533223183/job/68501882514?pr=9005

Logs:
? google.golang.org/grpc/test/codec_perf [no test files]
--- FAIL: Test (10.81s)
--- FAIL: Test/ClientSideXDS_WithValidAndInvalidSecurityConfigurationSPIFFE (1.16s)
setup.go:69: Created new snapshot cache...
tlogger.go:133: INFO server.go:721 [core] [Server #999] Server created (t=+279.741µs)
setup.go:69: Registered Aggregated Discovery Service (ADS)...
setup.go:69: xDS management server serving at: 127.0.0.1:39155...
tlogger.go:133: INFO server.go:917 [core] [Server #999 ListenSocket #1000] ListenSocket created (t=+383.231µs)
tlogger.go:133: INFO server.go:721 [core] [Server #1001] Server created (t=+2.259239ms)
stubserver.go:300: Started test service backend at "127.0.0.1:34625"
tlogger.go:133: INFO server.go:917 [core] [Server #1001 ListenSocket #1002] ListenSocket created (t=+2.416299ms)
tlogger.go:133: INFO server.go:721 [core] [Server #1003] Server created (t=+3.323533ms)
stubserver.go:300: Started test service backend at "127.0.0.1:44759"
tlogger.go:133: INFO server.go:917 [core] [Server #1003 ListenSocket #1004] ListenSocket created (t=+3.416553ms)
tlogger.go:133: INFO server.go:721 [core] [Server #1005] Server created (t=+3.543192ms)
stubserver.go:300: Started test service backend at "127.0.0.1:46125"
server.go:229: Created new resource snapshot...
logging.go:30: setting snapshot for node 26a76e6f-ba73-4d1e-9d3d-6cb662c4f872
server.go:235: Updated snapshot cache with resource snapshot...
tlogger.go:133: INFO clientconn.go:1799 [core] original dial target is: "xds:///my-service-client-side-xds" (t=+3.651624ms)
tlogger.go:133: INFO clientconn.go:514 [core] [Channel #1006] Channel created for target "xds:///my-service-client-side-xds" (t=+3.673304ms)
tlogger.go:133: INFO clientconn.go:245 [core] [Channel #1006] parsed dial target is: resolver.Target{URL:url.URL{Scheme:"xds", Opaque:"", User:(*url.Userinfo)(nil), Host:"", Path:"/my-service-client-side-xds", Fragment:"", RawQuery:"", RawPath:"", RawFragment:"", ForceQuery:false, OmitHost:false}} (t=+3.694874ms)
tlogger.go:133: INFO server.go:917 [core] [Server #1005 ListenSocket #1007] ListenSocket created (t=+3.707956ms)
tlogger.go:133: INFO clientconn.go:246 [core] [Channel #1006] Channel authority set to "my-service-client-side-xds" (t=+3.750308ms)
tlogger.go:133: INFO clientconn.go:618 [core] [Channel #1006] Channel Connectivity change to CONNECTING (t=+3.791024ms)
tlogger.go:133: INFO pool.go:309 [xds] xDS node ID: 26a76e6f-ba73-4d1e-9d3d-6cb662c4f872 (t=+3.936675ms)
tlogger.go:133: INFO xds_resolver.go:157 [xds] [xds-resolver 0xd4ae820] Creating resolver for target: xds:///my-service-client-side-xds (t=+3.953957ms)
tlogger.go:133: INFO clientconn.go:1799 [core] original dial target is: "passthrough:///127.0.0.1:39155" (t=+3.981268ms)
tlogger.go:133: INFO clientconn.go:514 [core] [Channel #1008] Channel created for target "passthrough:///127.0.0.1:39155" (t=+3.995204ms)
tlogger.go:133: INFO clientconn.go:245 [core] [Channel #1008] parsed dial target is: resolver.Target{URL:url.URL{Scheme:"passthrough", Opaque:"", User:(*url.Userinfo)(nil), Host:"", Path:"/127.0.0.1:39155", Fragment:"", RawQuery:"", RawPath:"", RawFragment:"", ForceQuery:false, OmitHost:false}} (t=+4.011274ms)
tlogger.go:133: INFO clientconn.go:246 [core] [Channel #1008] Channel authority set to "127.0.0.1:39155" (t=+4.021703ms)
tlogger.go:133: INFO clientconn.go:419 [core] [Channel #1006] Channel exiting idle mode (t=+4.047241ms)
tlogger.go:133: INFO clientconn.go:618 [core] [Channel #1008] Channel Connectivity change to CONNECTING (t=+4.105009ms)
tlogger.go:133: INFO resolver_wrapper.go:211 [core] [Channel #1008] Resolver state updated: {
"Addresses": [
{
"Addr": "127.0.0.1:39155",
"ServerName": "",
"Attributes": null,
"BalancerAttributes": null,
"Metadata": null
}
tlogger.go:133: INFO ads_stream.go:160 [xds] [xds-client 0xd4ae7d0] [xds-channel 0xd4b2ed0] [ads-stream 0xcf73080] Shutdown ADS stream (t=+1.151957376s)
tlogger.go:133: INFO clientconn.go:618 [core] [Channel #1008] Channel Connectivity change to SHUTDOWN (t=+1.151990448s)
tlogger.go:133: INFO resolver_wrapper.go:112 [core] [Channel #1008] Closing the name resolver (t=+1.152012309s)
tlogger.go:133: INFO balancer_wrapper.go:159 [core] [Channel #1008] ccBalancerWrapper: closing (t=+1.15205595s)
tlogger.go:133: INFO clientconn.go:1295 [core] [Channel #1008 SubChannel #1009] Subchannel Connectivity change to SHUTDOWN (t=+1.152128124s)
tlogger.go:133: INFO clientconn.go:1672 [core] [Channel #1008 SubChannel #1009] Subchannel deleted (t=+1.152146639s)
tlogger.go:133: INFO clientconn.go:1230 [core] [Channel #1008] Channel deleted (t=+1.15232436s)
tlogger.go:133: INFO channel.go:143 [xds] [xds-client 0xd4ae7d0] [xds-channel 0xd4b2ed0] Shutdown (t=+1.152350128s)
tlogger.go:133: INFO xdsclient.go:200 [xds] [xds-client 0xd4ae7d0] Shutdown (t=+1.152391485s)
tlogger.go:133: INFO xds_resolver.go:295 [xds] [xds-resolver 0xd4ae820] Shutdown (t=+1.152410801s)
tlogger.go:133: INFO clientconn.go:1295 [core] [Channel #1006 SubChannel #1013] Subchannel Connectivity change to SHUTDOWN (t=+1.152460874s)
tlogger.go:133: INFO clientconn.go:1672 [core] [Channel #1006 SubChannel #1013] Subchannel deleted (t=+1.152484268s)
tlogger.go:133: INFO clientconn.go:1295 [core] [Channel #1006 SubChannel #1012] Subchannel Connectivity change to SHUTDOWN (t=+1.152679412s)
tlogger.go:133: INFO clientconn.go:1672 [core] [Channel #1006 SubChannel #1012] Subchannel deleted (t=+1.152700872s)
tlogger.go:133: INFO clientconn.go:1230 [core] [Channel #1006] Channel deleted (t=+1.152880877s)
tlogger.go:133: INFO server.go:853 [core] [Server #1005 ListenSocket #1007] ListenSocket deleted (t=+1.152966146s)
tlogger.go:133: INFO server.go:853 [core] [Server #1003 ListenSocket #1004] ListenSocket deleted (t=+1.153036146s)
tlogger.go:133: INFO server.go:853 [core] [Server #1001 ListenSocket #1002] ListenSocket deleted (t=+1.153145099s)
tlogger.go:133: INFO server.go:853 [core] [Server #999 ListenSocket #1000] ListenSocket deleted (t=+1.153233143s)
grpctest.go:40: WARNING 1 allocated buffers never freed:
google.golang.org/grpc/internal/leakcheck.(*swappableBufferPool).Get
/home/runner/work/grpc-go/grpc-go/internal/leakcheck/leakcheck.go:65
google.golang.org/grpc/internal/transport.(*framer).readDataFrame
/home/runner/work/grpc-go/grpc-go/internal/transport/http_util.go:527
google.golang.org/grpc/internal/transport.(*framer).readFrame
/home/runner/work/grpc-go/grpc-go/internal/transport/http_util.go:488
google.golang.org/grpc/internal/transport.(*http2Client).reader
/home/runner/work/grpc-go/grpc-go/internal/transport/http2_client.go:1666
grpctest.go:40: 0.0001996007984031936% of buffers never freed

[mbissa]

Is not flaking on master - closing for now, will reopen if this reoccurs.

[arjan-bal]

http://github.com/grpc/grpc-go/actions/runs/23894736197/job/69676542492?pr=9034

[Pranjali-2501]

Hey @gtcooke94 , could you please take a look at this flaky test.

[arjan-bal]

https://github.com/grpc/grpc-go/actions/runs/24469520250/job/71505714012?pr=9055

[gtcooke94]

Looks like the underlying issue is, looking further

Err: connection error: desc = "transport: authentication handshake failed: xds: fetching trusted roots from CertificateProvider failed: provider instance is closed"

[gtcooke94]

This test uses a lot of underlying XDS test infra that I'm not as familiar with - is there any chance something could've changed in that causing this flake, or someone who could look at that?

It looks like something is closing the root provider before the connection actually happens.