Featuretests test data race/panic due to Testing.Log called after test finishes

[sunjayBhatia]

See test runs:

• https://github.com/projectcontour/contour/actions/runs/7403392541/job/20143161478
• https://github.com/projectcontour/contour/actions/runs/7400733328/job/20135033752
• https://github.com/projectcontour/contour/actions/runs/7400814171/job/20135279982
• https://github.com/projectcontour/contour/actions/runs/7251025980/job/19752564722
• https://github.com/projectcontour/contour/actions/runs/7425728318/job/20208024297
• https://github.com/projectcontour/contour/actions/runs/7449199586/job/20265372911
• https://github.com/projectcontour/contour/actions/runs/7478586959/job/20353923206

Tests have a data race/panic because Testing.Logf is called after the test ends

The offending call comes from here:

contour/internal/xds/v3/contour.go

Line 88 in 8d63b86

log.Debug("stream terminated")

We set up and wait for teardown of the Contour gRPC server here:

contour/internal/featuretests/v3/featuretests.go

Lines 162 to 211 in 8d63b86

	contour_xds_v3.RegisterServer(contour_xds_v3.NewContourServer(log, xdscache.ResourcesOf(resources)...), srv)
	var wg sync.WaitGroup
	ctx, cancel := context.WithCancel(context.Background())
	wg.Add(1)
	go func() {
	// Returns once GracefulStop() is called by the below goroutine.
	// nolint:errcheck
	srv.Serve(l)
	wg.Done()
	}()
	wg.Add(1)
	go func() {
	// Returns once the context is cancelled by the cleanup func.
	// nolint:errcheck
	eh.Start(ctx)
	// Close the gRPC server and its listener.
	srv.GracefulStop()
	wg.Done()
	}()
	cc, err := grpc.Dial(l.Addr().String(), grpc.WithTransportCredentials(insecure.NewCredentials()))
	require.NoError(t, err)
	rh := &resourceEventHandler{
	EventHandler: eh,
	EndpointsHandler: et,
	Sequence: eh.Sequence(),
	statusUpdateCacher: statusUpdateCacher,
	}
	return rh, &Contour{
	T: t,
	ClientConn: cc,
	statusUpdateCache: statusUpdateCacher,
	}, func() {
	// close client connection
	cc.Close()
	// stop server
	cancel()
	// wait for everything to gracefully stop.
	wg.Wait()
	}
	}

GracefulStop() and Serve should be waiting for all server handler goroutines to exit before returning, the test cleanup function should then be waiting for these to return before letting the test end, e.g.

contour/internal/featuretests/v3/extensionservice_test.go

Lines 427 to 428 in 8d63b86

	rh, c, done := setup(t)
	defer done()

However as can be seen in the tests above, this is not strictly the case, it seems the server is allowed to exit before some of the handlers fully return. Repro by running make check-test-race, modified with -count=50 (we can exacerbate this by adding a sleep to the done function in the contour xDS server).

This issue seems to have popped up post bumping grpc-go to 1.60.0+, I cannot repro it on 1.59.0

Ironically, this was an issue that was supposedly addressed in 1.60.0:

• loopyWriter continuing to run after GracefulStop causing race with t.Log grpc/grpc-go#6485
• grpc: Wait until resources finish cleaning up in Stop() and GracefulStop() grpc/grpc-go#6489

[sunjayBhatia]

Minimal repro here: https://github.com/sunjayBhatia/grpc-go-issue-repro/tree/main/shutdown-cleanup

Tracked the offending commit down to grpc/grpc-go#6489

[sunjayBhatia]

Submitted grpc-go issue here: grpc/grpc-go#6921

[sunjayBhatia]

Going to roll back to v1.59.0 until this is fixed to get CI green