grpctest: Parent testing.T used for logging when running subtests with t.Run

[arjan-bal]

What version of gRPC are you using?

1.69

What version of Go are you using (go version)?

N/A

What operating system (Linux, Windows, …) and version?

N/A

What did you do?

Run a test that follows table driven style, similar to TestUnmarshalListener_WithUpdateValidatorFunc which has multiple subtests run using t.Run().

grpc-go/test/xds/xds_security_config_nack_test.go

Line 43 in 724f450

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

What did you expect to see?

In the test logs, ordering of events should be as follows:

1. Name of parent test
2. Setup logs
3. Name of subtest 1
4. Subtest 1 logs
5. Name of subtest 2
6. Subtest 2 logs

Example:

$ go test ./test/xds/ -failfast -count 1 -v -run "Test/UnmarshalListener_WithUpdateValidatorFunc/both_identity_and_root_providers_are_
not_present_in_bootstrap"
=== RUN   Test
=== RUN   Test/UnmarshalListener_WithUpdateValidatorFunc
=== RUN   Test/UnmarshalListener_WithUpdateValidatorFunc/both_identity_and_root_providers_are_not_present_in_bootstrap
    setup.go:45: Created new snapshot cache...
    tlogger.go:116: INFO server.go:685 [core] [Server #1]Server created  (t=+651.435µs)
    setup.go:45: Registered Aggregated Discovery Service (ADS)...
    setup.go:45: xDS management server serving at: 127.0.0.1:46695...
    tlogger.go:116: INFO server.go:881 [core] [Server #1 ListenSocket #2]ListenSocket created  (t=+960.269µs)
    tlogger.go:116: INFO server.go:685 [core] [Server #3]Server created  (t=+1.292673ms)

What did you see instead?

The parent test name is interleaved in subtest logs.

=== RUN   Test
=== RUN   Test/UnmarshalListener_WithUpdateValidatorFunc
=== RUN   Test/UnmarshalListener_WithUpdateValidatorFunc/both_identity_and_root_providers_are_not_present_in_bootstrap
    setup.go:45: Created new snapshot cache...
=== NAME  Test/UnmarshalListener_WithUpdateValidatorFunc
    tlogger.go:116: INFO server.go:685 [core] [Server #1]Server created  (t=+1.162218ms)
=== NAME  Test/UnmarshalListener_WithUpdateValidatorFunc/both_identity_and_root_providers_are_not_present_in_bootstrap
    setup.go:45: Registered Aggregated Discovery Service (ADS)...
    setup.go:45: xDS management server serving at: 127.0.0.1:38723...
=== NAME  Test/UnmarshalListener_WithUpdateValidatorFunc
    tlogger.go:116: INFO server.go:881 [core] [Server #1 ListenSocket #2]ListenSocket created  (t=+1.458969ms)
    tlogger.go:116: INFO server.go:685 [core] [Server #3]Server created  (t=+1.846345ms)
    tlogger.go:116: INFO client_refcounted.go:76 [xds] [xds-client 0xc00036e460] Created client with name "#server" and bootstrap configuration: (t=+2.014449ms)  
    tlogger.go:116: INFO client_refcounted.go:81 [xds] xDS node ID: 030e1a26-0e7c-4935-968d-0a948b03cd0f  (t=+2.045277ms)
    tlogger.go:116: INFO server.go:123 [xds] [xds-server 0xc00022da40] Created xds.GRPCServer  (t=+2.056109ms)
=== NAME  Test/UnmarshalListener_WithUpdateValidatorFunc/both_identity_and_root_providers_are_not_present_in_bootstrap
    stubserver.go:288: Started test service backend at "127.0.0.1:33307"
=== NAME  Test/UnmarshalListener_WithUpdateValidatorFunc

Root Cause

This issue is seen because the parent function's *testing.T is used to log for all substests

grpc-go/internal/grpctest/grpctest.go

Lines 104 to 125 in 724f450

	func RunSubTests(t *testing.T, x Interface) {
	xt := reflect.TypeOf(x)
	xv := reflect.ValueOf(x)
	for i := 0; i < xt.NumMethod(); i++ {
	methodName := xt.Method(i).Name
	if !strings.HasPrefix(methodName, "Test") {
	continue
	}
	tfunc := getTestFunc(t, xv, methodName)
	t.Run(strings.TrimPrefix(methodName, "Test"), func(t *testing.T) {
	// Run leakcheck in t.Cleanup() to guarantee it is run even if tfunc
	// or setup uses t.Fatal().
	//
	// Note that a defer would run before t.Cleanup, so if a goroutine
	// is closed by a test's t.Cleanup, a deferred leakcheck would fail.
	t.Cleanup(func() { x.Teardown(t) })
	x.Setup(t)
	tfunc(t)
	})
	}
	}

grpc-go/internal/grpctest/grpctest.go

Lines 53 to 61 in 724f450

	// Setup updates the tlogger.
	func (Tester) Setup(t *testing.T) {
	TLogger.Update(t)
	// TODO: There is one final leak around closing connections without completely
	// draining the recvBuffer that has yet to be resolved. All other leaks have been
	// completely addressed, and this can be turned back on as soon as this issue is
	// fixed.
	leakcheck.SetTrackingBufferPool(logger{t: t})
	}

A manual fix would be to call grpctest.Tester.Setup(t) at the beginning of each subtest. I tried finding a way of giving a setup hook to testing.T (similar to the t.Cleanup functions that run after tests), but there isn't a public API to do this. Since testing.T is a struct and not an interface, wrapping it to intercept call to t.Run isn't an option too.

[dfawley]

Options:

1. Forbid the use of t.Run and require a grpctest.Run() that does what we need instead.
2. Replace *testing.T in the function signature with *grpctest.T and embed a *testing.T with an overridden Run method.
3. Completely redo the way grpctest works and require a call to Setup(t) (or just defer leakcheck). Find a way to require this.
4. Do leakcheck after all tests run via a TestMain in each package. If a leak is found, it's hard to narrow down what's causing it, but maybe that's actually not all that bad?

An argument against 3 would be that we also want to add leak checking for buffer reuse -- if we fail to free a buffer, we want to know about it now, too. That becomes much harder to add universally with 3, but is easy in today's world, which 1 & 2 both maintain.

Edit: the argument against 3 does not apply to 4, so deleted "& 4".

[dfawley]

I think I like (2) the most of these options. I don't think it would be hard to implement, and changing all the existing tests isn't too hard with a script.