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(). https://github.com/grpc/grpc-go/blob/724f450f77a09bade8174e5052625977069aaf81/test/xds/xds_security_config_nack_test.go#L43

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 https://github.com/grpc/grpc-go/blob/724f450f77a09bade8174e5052625977069aaf81/internal/grpctest/grpctest.go#L104-L125 https://github.com/grpc/grpc-go/blob/724f450f77a09bade8174e5052625977069aaf81/internal/grpctest/grpctest.go#L53-L61

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.

[hugehoo]

@dfawley @arjan-bal hi, is this issue already fixed? i tried to reproduce the issue, but it seems like there's no duplicate parent test name currently.