Flaky test Test/ResourceUpdateMetrics (new xDS client)

[arjan-bal]

This is the test added for the new xDS client, a similar test exists for the existing client:

grpc-go/xds/internal/clients/xdsclient/test/metrics_test.go

Line 42 in aaabd60

func (s) TestResourceUpdateMetrics(t *testing.T) {

Failure: https://github.com/grpc/grpc-go/actions/runs/15130001679/job/42528973595?pr=8306

The test timed out.

panic: test timed out after 7m0s
	running tests:
		Test (6m46s)
		Test/ResourceUpdateMetrics (6m35s)

goroutine 3013 [running]:
testing.(*M).startAlarm.func1()
	/opt/hostedtoolcache/go/1.24.3/x64/src/testing/testing.go:2484 +0x308
created by time.goFunc
	/opt/hostedtoolcache/go/1.24.3/x64/src/time/sleep.go:215 +0x38

goroutine 1 [chan receive, 6 minutes]:
testing.(*T).Run(0x400055a8c0, {0xc9b8fd?, 0x40002f3b38?}, 0xcecd50)
	/opt/hostedtoolcache/go/1.24.3/x64/src/testing/testing.go:1859 +0x388
testing.runTests.func1(0x400055a8c0)
	/opt/hostedtoolcache/go/1.24.3/x64/src/testing/testing.go:2279 +0x40
testing.tRunner(0x400055a8c0, 0x40002f3c68)
	/opt/hostedtoolcache/go/1.24.3/x64/src/testing/testing.go:1792 +0xe4
testing.runTests(0x40004a21c8, {0x171bbc0, 0x2, 0x2}, {0x400005c160?, 0x7?, 0x173a6a0?})
	/opt/hostedtoolcache/go/1.24.3/x64/src/testing/testing.go:2277 +0x3ec
testing.(*M).Run(0x4000298aa0)
	/opt/hostedtoolcache/go/1.24.3/x64/src/testing/testing.go:2142 +0x588
main.main()
	_testmain.go:47 +0x90

goroutine 1625 [chan receive, 6 minutes]:
testing.(*T).Run(0x400055aa80, {0x9dee1d?, 0x1762020?}, 0x40004fc160)
	/opt/hostedtoolcache/go/1.24.3/x64/src/testing/testing.go:1859 +0x388
google.golang.org/grpc/internal/grpctest.RunSubTests(0x400055aa80, {0xdff4c0, 0x1762020})
	/home/runner/work/grpc-go/grpc-go/internal/grpctest/grpctest.go:119 +0x284
google.golang.org/grpc/xds/internal/clients/xdsclient/test_test.Test(0x400055aa80?)
	/home/runner/work/grpc-go/grpc-go/xds/internal/clients/xdsclient/test/helpers_test.go:48 +0x2c
testing.tRunner(0x400055aa80, 0xcecd50)
	/opt/hostedtoolcache/go/1.24.3/x64/src/testing/testing.go:1792 +0xe4
created by testing.(*T).Run in goroutine 1
	/opt/hostedtoolcache/go/1.24.3/x64/src/testing/testing.go:1851 +0x374

goroutine 2984 [select, 6 minutes]:
reflect.rselect({0x40002ed720, 0x3, 0x40005104e0?})
	/opt/hostedtoolcache/go/1.24.3/x64/src/runtime/select.go:616 +0x278
reflect.Select({0x400066e0e0?, 0x3, 0x400026a180?})
	/opt/hostedtoolcache/go/1.24.3/x64/src/reflect/value.go:2875 +0x494
github.com/envoyproxy/go-control-plane/pkg/server/sotw/v3.(*server).process(0x4000882300, {0x5547d580c0, 0x40003ee140}, 0x40005060e0, {0x0, 0x0})
	/home/runner/go/pkg/mod/github.com/envoyproxy/go-control-plane@v0.13.4/pkg/server/sotw/v3/xds.go:53 +0x2e4
github.com/envoyproxy/go-control-plane/pkg/server/sotw/v3.(*server).StreamHandler(0x4000882300, {0x5547d580c0, 0x40003ee140}, {0x0, 0x0})
	/home/runner/go/pkg/mod/github.com/envoyproxy/go-control-plane@v0.13.4/pkg/server/sotw/v3/server.go:168 +0xc4
github.com/envoyproxy/go-control-plane/pkg/server/v3.(*server).StreamHandler(...)
	/home/runner/go/pkg/mod/github.com/envoyproxy/go-control-plane@v0.13.4/pkg/server/v3/server.go:186
github.com/envoyproxy/go-control-plane/pkg/server/v3.(*server).StreamAggregatedResources(0x16ff700?, {0xe08af8?, 0x40003ee140?})
	/home/runner/go/pkg/mod/github.com/envoyproxy/go-control-plane@v0.13.4/pkg/server/v3/server.go:190 +0x58
github.com/envoyproxy/go-control-plane/envoy/service/discovery/v3._AggregatedDiscoveryService_StreamAggregatedResources_Handler({0xc83080?, 0x40009ccb10}, {0xe06db8, 0x400066e000})
	/home/runner/go/pkg/mod/github.com/envoyproxy/go-control-plane/envoy@v1.32.4/service/discovery/v3/ads_grpc.pb.go:137 +0xdc
google.golang.org/grpc.(*Server).processStreamingRPC(0x40005c4200, {0xe03be0, 0x40005102d0}, 0x400054c840, 0x40009ccc90, 0x1721340, 0x0)
	/home/runner/work/grpc-go/grpc-go/server.go:1695 +0xebc
google.golang.org/grpc.(*Server).handleStream(0x40005c4200, {0xe03fd0, 0x4000608000}, 0x400054c840)
	/home/runner/work/grpc-go/grpc-go/server.go:1819 +0x8d4
google.golang.org/grpc.(*Server).serveStreams.func2.1()
	/home/runner/work/grpc-go/grpc-go/server.go:1035 +0x84
created by google.golang.org/grpc.(*Server).serveStreams.func2 in goroutine 3010
	/home/runner/work/grpc-go/grpc-go/server.go:1046 +0x138

goroutine 3009 [select, 6 minutes]:
google.golang.org/grpc/internal/transport.(*http2Server).keepalive(0x4000608000)
	/home/runner/work/grpc-go/grpc-go/internal/transport/http2_server.go:1198 +0x164
created by google.golang.org/grpc/internal/transport.NewServerTransport in goroutine 2959
	/opt/hostedtoolcache/go/1.24.3/x64/src/internal/poll/fd_poll_runtime.go:89
internal/poll.(*FD).Read(0x40004c6100, {0x4000276000, 0x8000, 0x8000})
	/opt/hostedtoolcache/go/1.24.3/x64/src/internal/poll/fd_unix.go:165 +0x1fc
net.(*netFD).Read(0x40004c6100, {0x4000276000?, 0x40002e5c48?, 0x26e54?})
	/opt/hostedtoolcache/go/1.24.3/x64/src/net/fd_posix.go:55 +0x28
net.(*conn).Read(0x40000b2070, {0x4000276000?, 0x18010100000000?, 0x5547bf40e8?})
	/opt/hostedtoolcache/go/1.24.3/x64/src/net/net.go:194 +0x34
bufio.(*Reader).Read(0x4000652000, {0x40000be040, 0x9, 0x4000672468?})
	/opt/hostedtoolcache/go/1.24.3/x64/src/bufio/bufio.go:245 +0x1b0
io.ReadAtLeast({0xdebf20, 0x4000652000}, {0x40000be040, 0x9, 0x9}, 0x9)
	/opt/hostedtoolcache/go/1.24.3/x64/src/io/io.go:335 +0xa0
io.ReadFull(...)
	/opt/hostedtoolcache/go/1.24.3/x64/src/io/io.go:354
golang.org/x/net/http2.readFrameHeader({0x40000be040, 0x9, 0x40000d2060?}, {0xdebf20?, 0x4000652000?})
	/home/runner/go/pkg/mod/golang.org/x/net@v0.38.0/http2/frame.go:242 +0x58
golang.org/x/net/http2.(*Framer).ReadFrame(0x40000be000)
	/home/runner/go/pkg/mod/golang.org/x/net@v0.38.0/http2/frame.go:506 +0x78
google.golang.org/grpc/internal/transport.(*http2Client).reader(0x4000[236](https://github.com/grpc/grpc-go/actions/runs/15130001679/job/42528973595?pr=8306#step:8:237)b48, 0x40001bc150)
	/home/runner/work/grpc-go/grpc-go/internal/transport/http2_client.go:1662 +0x158
created by google.golang.org/grpc/internal/transport.NewHTTP2Client in goroutine 2974
	/home/runner/work/grpc-go/grpc-go/internal/transport/http2_client.go:414 +0x16a8

goroutine 3005 [select, 6 minutes]:
google.golang.org/grpc/xds/internal/clients/xdsclient.(*adsStreamImpl).send(0x4000024400, {0xe03c18, 0x40004f49b0})
	/home/runner/work/grpc-go/grpc-go/xds/internal/clients/xdsclient/ads_stream.go:275 +0xb8
created by google.golang.org/grpc/xds/internal/clients/xdsclient.(*adsStreamImpl).runner in goroutine 3004
	/home/runner/work/grpc-go/grpc-go/xds/internal/clients/xdsclient/ads_stream.go:229 +0xa8

goroutine 2957 [select, 2 minutes]:
google.golang.org/grpc/internal/transport.(*http2Client).keepalive(0x4000236b48)
	/home/runner/work/grpc-go/grpc-go/internal/transport/http2_client.go:1735 +0x134
created by google.golang.org/grpc/internal/transport.NewHTTP2Client in goroutine 2974
	/home/runner/work/grpc-go/grpc-go/internal/transport/http2_client.go:404 +0x1644

goroutine 3002 [select, 6 minutes]:
google.golang.org/grpc/internal/grpcsync.(*CallbackSerializer).run(0x40003ef170, {0xe03c18, 0x40004f48c0})
	/home/runner/work/grpc-go/grpc-go/internal/grpcsync/callback_serializer.go:88 +0xc4
created by google.golang.org/grpc/internal/grpcsync.NewCallbackSerializer in goroutine 3000
	/home/runner/work/grpc-go/grpc-go/internal/grpcsync/callback_serializer.go:52 +0x118

goroutine 3001 [select, 6 minutes]:
google.golang.org/grpc/internal/grpcsync.(*CallbackSerializer).run(0x40003ef140, {0xe03c18, 0x40004f4870})
	/home/runner/work/grpc-go/grpc-go/internal/grpcsync/callback_serializer.go:88 +0xc4
created by google.golang.org/grpc/internal/grpcsync.NewCallbackSerializer in goroutine 3000
	/home/runner/work/grpc-go/grpc-go/internal/grpcsync/callback_serializer.go:52 +0x118

goroutine 3012 [select, 6 minutes]:
google.golang.org/grpc.newClientStreamWithParams.func4()
	/home/runner/work/grpc-go/grpc-go/stream.go:398 +0x8c
created by google.golang.org/grpc.newClientStreamWithParams in goroutine 3004
	/home/runner/work/grpc-go/grpc-go/stream.go:397 +0xb40

goroutine 2952 [chan receive, 6 minutes]:
google.golang.org/grpc/xds/internal/clients/xdsclient.(*authority).close(0x40000[242](https://github.com/grpc/grpc-go/actions/runs/15130001679/job/42528973595?pr=8306#step:8:243)00)
	/home/runner/work/grpc-go/grpc-go/xds/internal/clients/xdsclient/authority.go:871 +0x3c
google.golang.org/grpc/xds/internal/clients/xdsclient.(*XDSClient).Close(0x400053e000)
	/home/runner/work/grpc-go/grpc-go/xds/internal/clients/xdsclient/xdsclient.go:183 +0x48
google.golang.org/grpc/xds/internal/clients/xdsclient/test_test.s.TestResourceUpdateMetrics({{}}, 0x40003ec000)
	/home/runner/work/grpc-go/grpc-go/xds/internal/clients/xdsclient/test/metrics_test.go:121 +0xa74
google.golang.org/grpc/internal/grpctest.RunSubTests.func1(0x40003ec000)
	/home/runner/work/grpc-go/grpc-go/internal/grpctest/grpctest.go:127 +0xbc
testing.tRunner(0x40003ec000, 0x40004fc160)
	/opt/hostedtoolcache/go/1.24.3/x64/src/testing/testing.go:1792 +0xe4
created by testing.(*T).Run in goroutine 1625

[purnesh42H]

https://github.com/grpc/grpc-go/actions/runs/15182563202/job/42695217533?pr=8348

[arjan-bal]

https://github.com/grpc/grpc-go/actions/runs/15256392001/job/42904944546?pr=8347

[purnesh42H]

The test uses testMetricsReporter for xdsclient to report metrics which calls metricsReporter.ReportMetric() to report invalid and valid xds resource updates. This flakiness is due to timeout in r.metricsCh.Send(m) because the metricsCh in testMetricsReporter is a testutils.Channel initialized with a size of 1. A Send operation on this channel will block if the channel is full.

In a rare case scenario of NACKs, the xDS client can emit metrics in quick succession due to the interaction sequence between the xDS client (in grpc-go) and the test management server (using go-control-plane) after the initial invalid update:

• The test code calls mgmtServer.Update(ctx, resources) once with the listener resource where resources.Listeners.ApiListener = nil. This action updates the management server's internal state (e.g., its SnapshotCache) to hold this invalid listener as the current version for the specified nodeID.
• The grpc-go xDS client, which is watching for this listener resource, receives this update from the server.
• Upon processing, the client identifies the listener as invalid (due to ApiListener being nil).
• The client then sends a NACK back to the management server. Crucially, a NACK is a form of DiscoveryRequest where the error_detail field is populated, and the version_info typically reflects the last known good version (or the version of the NACKed resource).
• The go-control-plane based management server receives this NACK (which is a DiscoveryRequest).
• A common behavior for go-control-plane's SnapshotCache is to respond to a DiscoveryRequest by sending the current version of the requested resources it holds for that client node.  
• Since the server's current snapshot for this listener was set to the invalid one by the test's single mgmtServer.Update() call, the server, in response to the client's NACK/DiscoveryRequest, resends the same invalid listener configuration.
• The client receives the resent invalid listener.
• It again finds it invalid and sends another NACK.
• The server again responds with the same invalid listener from its cache.
• This cycle of NACK -> Resend (of same invalid data) -> NACK can repeat. Each time the client attempts to process the resent invalid resource, it would generate an "invalid resource update" metric. If this cycle happens rapidly, it leads to a burst of metric reports to metricsCh.

Similar issue has been raised in go-control-plane envoyproxy/go-control-plane#46

[purnesh42H]

Using metricsCh.Replace(m) instead of metricsCh.Send(m) addresses this flakiness effectively for this test.

Replace ensures that the send operation doesn't block if the channel is full. It atomically removes the existing item and sends the new one.

The TestResourceUpdateMetrics test is primarily concerned with verifying the occurrence and sequence of specific metric types (ResourceUpdateValid, ResourceUpdateInvalid). If two identical ResourceUpdateInvalid metrics are emitted in rapid succession due to the NACK/resend cycle, and the first is overwritten by the second before consumption, the test still correctly observes a ResourceUpdateInvalid metric, satisfying its core assertion. The loss of an intermediate, identical metric is not critical for this test's validation goals.

[eshitachandwani]

https://github.com/grpc/grpc-go/actions/runs/15465582976/job/43536786370?pr=8323
Got another instance.

[arjan-bal]

@eshitachandwani the failure in the above comment is on the 1.73 branch which doesn't have the fix cherry-picked (#8363) since the fix was merged in master after the 1.73 branch cut. Since we know it's a bug in the test code, and we won't be cherry-picking into 1.73 frequently, it's not necessary to cherry-pick the fix in v1.73.x.