loopyWriter continuing to run after GracefulStop causing race with t.Log

[fho]

Hello,

we are starting a grpc-server in a Go testserver.
On test finish we call Server.GracefulStop() via t.Cleanup().

We forward all log messages from the grpc packages to the test logger, by setting grpclog.SetLoggerV2 to a t.Log wrapper.

When we run the tests with the -race parameter, it happens from now and then that a race is detected because loopyWriter logs a message to t.Log() after the test finish.
As I understand Server.GracefulStop() does not wait until the loopyWriter go-routine has terminated.

The message that is logged after test termination from loopyWriter happens here:

grpc-go/internal/transport/controlbuf.go

Line 543 in b8d36ca

l.logger.Infof("loopyWriter exiting with error: %v", err)

) maybe there are also other log calls that can happen after GracefulStop.

Is there a way to wait in a testcase until loopyWriter terminated that I'm missing?
If not, shouldn't it be possible to do a termination that ensures no go-routines are running afterwards?
This would also e.g. work well together with https://github.com/uber-go/goleak, that checks if any go-routines are leaked in a testcase.

grpc-go version: 1.57

[dfawley]

We forward all log messages from the grpc packages to the test logger, by setting grpclog.SetLoggerV2 to a t.Log wrapper.

We do the same thing in our tests. 😄

It looks like GracefulStop isn't waiting for all the resources to go away - it's just waiting for the in-flight streams to end.

Stop is really what you should be using instead for this purpose. GracefulStop makes sure pending streams have a chance to end gracefully, but in a test, you shouldn't have streams running when you think your test is done. If you do actually need the behavior of GracefulStop, you can always do both: t.Cleanup(func() { s.GracefulStop(); s.Stop() }) But as a cleanup, you really only want the hard-shutdown behavior, because if a test has hung, Stop will quickly terminate things, whereas GracefulStop will just hang forever.

GracefulStop should probably be updated to ensure the transports are fully shut down as well, but this would be a minor issue that we probably wouldn't be able to prioritize for some time.

[fho]

@dfawley thanks a lot for your help.

Yes, s.Stop() is also sufficient in the testcases, all clients are shutdown before anyways.

Why should using s.Stop() help? It also does not wait for the loopyWriter go-routine.
I reproduced this by using goleak.VerifyNone() and by adding a time.Sleep() to the defer func() of loopyWriter.run().
goleak complains that the loopyWriter is still running, when goleaks runs after s.Stop() returned.
(I could provide a testcase to reproduce it next week, if wanted.)

Does t.Stop() maybe prevent that an error happens that the loopyWriter go-routine will log?

[dfawley]

I reproduced this by using goleak.VerifyNone() and by adding a time.Sleep() to the defer func() of loopyWriter.run().

Interesting.. I was thinking st.Close() (called from here:

grpc-go/server.go

Line 1862 in b8d36ca

st.Close(errors.New("Server.Stop called"))

) would block until loopy exited because of

grpc-go/internal/transport/http2_server.go

Line 1238 in b8d36ca

t.controlBuf.finish()

, but it looks like it doesn't. Maybe we can add something in there that waits for loopy to exit and that would take care of both paths?

[dfawley]

Also our tests may not run into this because we also always use:

https://pkg.go.dev/google.golang.org/grpc@v1.57.0/internal/leakcheck

[fho]

grpc-go/internal/transport/http2_server.go

Line 1238 in b8d36ca

t.controlBuf.finish()

, but it looks like it doesn't. Maybe we can add something in there that waits for loopy to exit and that would take care of both paths?

I'll give it a try and create a PR if it works out.

Update: PR is out: #6489

[fho]

Also our tests may not run into this because we also always use:

https://pkg.go.dev/google.golang.org/grpc@v1.57.0/internal/leakcheck

Yes, leakcheck does not detect it because it only complains if a go-routine is still running after 10s after the test terminated.
Condition like that the LoopyWriter routine terminates shortly after Stop() returned it can not detect.