grpc: Wait until resources finish cleaning up in Stop() and GracefulStop()

[fho]

It was not guaranteed that when Stop() and GracefulStop() returned, the
loopyWriter go-routines terminated.
This can lead to a panic or a testing.(*common).logDepth() race
condition in Go Tests because t.Log is used after or during the testcase
terminates.
This can happen when:

• a GRPC server is started in a Go test,
• the GRPC logs are forwarded to t.Log,
• loopyWriter.run logs an error after server.Stop() and the Test
  method returns.

grpc@v1.57.0/internal/leakcheck is unable to detect that the
loopyWriter go-routine continues to run after server.Stop() because it
waits up to 10s for go-routines to terminate after a test finishes.
The loopyWriter returns much faster after Stop() returns.

To ensure that Stop and GracefulStop only return after the loopyWriter
go-routine terminates:

• rename http2Server.writerDone to loopyWriterDone, the channel was only
  used in test and is closed when loopyWriter returns
• wait in http2Server.HandleStreams() until loopyWriterDone was closed
• wait in Server.Stop() until all connections were removed, this is
  already done in GracefulStop.
  To abort GracefulStop() when Stop() is called a local copy of Server.lis and
  Server.conns was created and both fields were set to nil and then
  s.csv.Broadcast() was called to wake up an eventually sleeping
  GracefulStop() execution. This does not work anymore when we need to
  wait for connections to be removed in Stop() we need to check the
  length of Server.conns.
  Instead GracefulStop now waits until the the procedure completed.

GracefulStop now also stops running stream workers. Shared code between Stop and GracefulStop is moved to helper functions.

This fixes: #6485

RELEASE NOTES:

• grpc: Wait until resources finish cleaning up in Stop() and GracefulStop()

[fho]

I don't know a good way to add a testcase for it because the mentioned issue with leakcheck.
To reproduce the issue consistently it would also be needed to inject into loopyWriter.run to wait a bit longer on shutdown.
To test the PR, I modified leakcheck, inserted a sleep in loopyWriter.run and did not use test.s: fho@f2dce22.

The testcase also detects another running go-routine of the grpc-client:

    leakcheck.go:116: Leaked goroutine: goroutine 13 [runnable]:
        runtime.Gosched()
        	/usr/lib/go/src/runtime/proc.go:321 +0x1a
        google.golang.org/grpc/internal/transport.(*loopyWriter).run(0xc000318930)
        	/home/fho/git/grpc-go/internal/transport/controlbuf.go:590 +0x34b
        google.golang.org/grpc/internal/transport.newHTTP2Client.func6()
        	/home/fho/git/grpc-go/internal/transport/http2_client.go:451 +0x165
        created by google.golang.org/grpc/internal/transport.newHTTP2Client
        	/home/fho/git/grpc-go/internal/transport/http2_client.go:449 +0x39d2
    leakcheck.go:116: Leaked goroutine: goroutine 20 [runnable]:

This looks like analogous to the loopyWriter issue. I only had a brief look, I guess can be fixed by changing readerDone in a similar manner. That is an issue for another PR.

[dfawley]

Thank you for the PR!

That is an issue for another PR.

Yes, this one is known: #2869.

As for the approach here, it unfortunately has the effect of making the close operation sequential. Each transport will be closed one by one, and wait for the previous one to fully shut down before closing the next. This could be noticeable if there are hundreds or thousands of connections. I'm not sure if there are any things that could delay loopy writer from terminating, but if there is anything that could last up to a second (e.g. a slow network write), then that could make Stop() take minutes.

Also, this approach only fixes Stop() and not GracefulStop(). I think we could fix both with a different approach: e.g. we could make sure HandleStreams doesn't return until the writer has shut down. After HandleStreams returns is the point that we delete the connection from the set of connections. In addition to this, Stop would need the same kind of loop that waits for len(s.conns) to reach 0 like we do in GracefulStop.

[fho]

@dfawley thanks for your feedback, I'll try to implement the suggested approach.

Do you maybe have an idea how to add a testcase for the issue that is compatible with the current test code?

[dfawley]

Do you maybe have an idea how to add a testcase for the issue that is compatible with the current test code?

The only thing I could think of that wouldn't be flaky is a version of leakcheck that fails immediately instead of waiting 10 seconds. If you wanted it to be reliable, you'd have to inject some extra code to optionally Sleep as you mention. And that would only help catch the current goroutines, not any added in the future.

But 1. it's OK to not have a test for this behavior, and 2. if there is a test for it, it's fine if it only fails ~10% of the time when the bug is present.

[github-actions]

This PR is labeled as requiring an update from the reporter, and no update has been received after 6 days. If no update is provided in the next 7 days, this issue will be automatically closed.

[fho]

I pushed a new version, were I wait in HandleStreams() for the loopyWriter to terminate and wait in Stop() until all connections are removed. This does not work yet though.
When running the tests, Stop() is hanging forever when waiting for the connections to be removed (see CI Logs.
Does somebody has an idea what is wrong?

[dfawley]

Stop() is hanging forever when waiting for the connections to be removed (see CI Logs.
Does somebody has an idea what is wrong?

I think I see what's happening. HandleStreams is returning, but (*grpc.Server).serveStreams, which calls it, is not returning because the method handlers are still running. Because serveStreams is not returning, even though the connection is fully closed, removeConn is not executed, meaning the grpc.Server (and Stop) still thinks the connection is there.

Since HandleStreams now does not return until it has cleaned up the connection, I wonder if we can remove the waitgroup in serveStreams entirely now? That seems plausible.

[fho]

Since HandleStreams now does not return until it has cleaned up the connection, I wonder if we can remove the waitgroup in serveStreams entirely now? That seems plausible.

The wg in Server.serveStreams() is used to wait is for a go-routine that runs Server.handleStream() as part of the st.HandleStreams() handle func.
I don't see how it would be ensured without the waitGroup that the Server.handleStream() go-routines return before Stop/GracefulStop would return.

[fho]

I'm also wondering why s.stopServerWorkers is only called in Stop() but not in GracefulStop.

[dfawley]

The wg in Server.serveStreams() is used to wait is for a go-routine that runs Server.handleStream() as part of the st.HandleStreams() handle func.

This doesn't sound right.

st.HandleStreams calls the closure that server.go passes it for each RPC. When an RPC starts, the first thing that does is increment the wg, and when it finishes, it calls wg.Done() on it. This means all the server handlers have to return before wg.Wait() will ever unblock.

But you changed st.HandleStreams so that it blocked until the transport was closed. At that point, it seems fine to dereference the st which is what happens when serveStreams returns (ref). We can't rely on the method handlers all returning when the stream ends (these tests that are failing are blocked in the method handlers, which presumably will be cleaned up later), because it's running code that isn't owned by gRPC at that point.

I'm also wondering why s.stopServerWorkers is only called in Stop() but not in GracefulStop.

This just seems to be an oversight.

[fho]

@dfawley that works!
I still don't understand the code sufficiently to judge if my change is correct.
Should I keep the abortGracefulStop atomic.Bool or is there a better way to abort the GracefulStop?

Tests currently fail on go 1.18 because atomic.Bool does not exist in that version.
Because Golang 1.21 was released and the min. required go version will therefore be changed to 1.19 which supports it, I kept it.

[fho]

@dfawley I addressed them. Thanks a lot for you patience and great support and sorry for oversights at the end causing this unnecessary back and forth.

[zasweq]

Code all LGTM. All comments are minor nits with respect to comments/naming.

[zasweq]

For the non inlined functions that are called while holding the server mutex, can you please add the suffix Locked(). Then I will approve and go ahead and merge :).

[fho]

@zasweq yes, it's done! Thanks for your review

[zasweq]

LGTM. Thank you for the contribution.