net/http/httptest: (*Server).Close races with HTTP/2 request handler

[bcmills]

~/go/src$ go version
go version devel +24ea77559f Thu Apr 9 11:09:00 2020 -0400 linux/amd64

~/go/src$ go doc httptest.Server.Close
package httptest // import "net/http/httptest"

func (s *Server) Close()
    Close shuts down the server and blocks until all outstanding requests on
    this server have completed.

While investigating #37669, I saw a reported race that led me to believe that, contrary to its documentation, (*httptest.Server).Close was not blocking for requests to complete.

To check that hypothesis, I added the following test function:

diff --git c/src/net/http/httptest/server_test.go w/src/net/http/httptest/server_test.go
index 0aad15c5ed..8b0e0f137f 100644
--- c/src/net/http/httptest/server_test.go
+++ w/src/net/http/httptest/server_test.go
@@ -6,9 +6,12 @@ package httptest

 import (
    "bufio"
+   "context"
+   "io"
    "io/ioutil"
    "net"
    "net/http"
+   "strings"
    "testing"
 )

@@ -238,3 +241,51 @@ func TestTLSServerWithHTTP2(t *testing.T) {
        })
    }
 }
+
+func TestCloseBlocksUntilRequestsCompleted(t *testing.T) {
+   t.Parallel()
+
+   modes := []string{
+       "http1",
+       "http2",
+   }
+
+   for _, mode := range modes {
+       mode := mode
+       t.Run(mode, func(t *testing.T) {
+           t.Parallel()
+
+           ctx, cancel := context.WithCancel(context.Background())
+           closed := false
+
+           cst := NewUnstartedServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
+               cancel()
+
+               io.Copy(w, r.Body)
+
+               <-r.Context().Done()
+               if closed {
+                   panic("Close did not wait for handler to return")
+               }
+           }))
+
+           switch mode {
+           case "http1":
+               cst.Start()
+           case "http2":
+               cst.EnableHTTP2 = true
+               cst.StartTLS()
+           }
+           defer func() {
+               cst.Close()
+               closed = true
+           }()
+
+           req, _ := http.NewRequestWithContext(ctx, "POST", cst.URL, strings.NewReader("Hello, server!"))
+           resp, err := cst.Client().Do(req)
+           if err == nil {
+               resp.Body.Close()
+           }
+       })
+   }
+}

It reliably fails under the race detector with even a very modest count, indicating that the server is not waiting for the handler to complete when HTTP/2 is enabled:

~/go/src$ go test -race net/http/httptest -run=TestCloseBlocksUntilRequestsCompleted -count=10
==================
WARNING: DATA RACE
Write at 0x00c000202018 by goroutine 10:
  net/http/httptest.TestCloseBlocksUntilRequestsCompleted.func1.2()
      /usr/local/google/home/bcmills/go/src/net/http/httptest/server_test.go:281 +0x46
  net/http/httptest.TestCloseBlocksUntilRequestsCompleted.func1()
      /usr/local/google/home/bcmills/go/src/net/http/httptest/server_test.go:289 +0x508
  testing.tRunner()
      /usr/local/google/home/bcmills/go/src/testing/testing.go:1022 +0x1eb

Previous read at 0x00c000202018 by goroutine 31:
  net/http/httptest.TestCloseBlocksUntilRequestsCompleted.func1.1()
      /usr/local/google/home/bcmills/go/src/net/http/httptest/server_test.go:267 +0x18b
  net/http.HandlerFunc.ServeHTTP()
      /usr/local/google/home/bcmills/go/src/net/http/server.go:2012 +0x51
  net/http.serverHandler.ServeHTTP()
      /usr/local/google/home/bcmills/go/src/net/http/server.go:2808 +0xc4
  net/http.initALPNRequest.ServeHTTP()
      /usr/local/google/home/bcmills/go/src/net/http/server.go:3380 +0xfc
  net/http.(*initALPNRequest).ServeHTTP()
      <autogenerated>:1 +0xa6
  net/http.Handler.ServeHTTP-fm()
      /usr/local/google/home/bcmills/go/src/net/http/server.go:87 +0x64
  net/http.(*http2serverConn).runHandler()
      /usr/local/google/home/bcmills/go/src/net/http/h2_bundle.go:5712 +0xc0

Goroutine 10 (running) created at:
  testing.(*T).Run()
      /usr/local/google/home/bcmills/go/src/testing/testing.go:1073 +0x6a3
  net/http/httptest.TestCloseBlocksUntilRequestsCompleted()
      /usr/local/google/home/bcmills/go/src/net/http/httptest/server_test.go:255 +0x13e
  testing.tRunner()
      /usr/local/google/home/bcmills/go/src/testing/testing.go:1022 +0x1eb

Goroutine 31 (finished) created at:
  net/http.(*http2serverConn).processHeaders()
      /usr/local/google/home/bcmills/go/src/net/http/h2_bundle.go:5446 +0x8fb
  net/http.(*http2serverConn).processFrame()
      /usr/local/google/home/bcmills/go/src/net/http/h2_bundle.go:4975 +0x44a
  net/http.(*http2serverConn).processFrameFromReader()
      /usr/local/google/home/bcmills/go/src/net/http/h2_bundle.go:4933 +0x750
  net/http.(*http2serverConn).serve()
      /usr/local/google/home/bcmills/go/src/net/http/h2_bundle.go:4432 +0x1485
  net/http.(*http2Server).ServeConn()
      /usr/local/google/home/bcmills/go/src/net/http/h2_bundle.go:4033 +0xd88
  net/http.http2ConfigureServer.func1()
      /usr/local/google/home/bcmills/go/src/net/http/h2_bundle.go:3859 +0x117
  net/http.(*conn).serve()
      /usr/local/google/home/bcmills/go/src/net/http/server.go:1805 +0x1c77
==================
--- FAIL: TestCloseBlocksUntilRequestsCompleted (0.00s)
    --- FAIL: TestCloseBlocksUntilRequestsCompleted/http2 (0.02s)
        testing.go:937: race detected during execution of test
2020/04/10 16:35:14 http2: panic serving 127.0.0.1:46044: Close did not wait for handler to return
goroutine 132 [running]:
net/http.(*http2serverConn).runHandler.func1(0xc0000ae068, 0xc00022af4f, 0xc00031a180)
        /usr/local/google/home/bcmills/go/src/net/http/h2_bundle.go:5705 +0x231
panic(0x8b5220, 0x9c14f0)
        /usr/local/google/home/bcmills/go/src/runtime/panic.go:975 +0x3b3
net/http/httptest.TestCloseBlocksUntilRequestsCompleted.func1.1(0x9cd0c0, 0xc0000ae068, 0xc0000ac600)
        /usr/local/google/home/bcmills/go/src/net/http/httptest/server_test.go:268 +0x1e2
net/http.HandlerFunc.ServeHTTP(0xc000096740, 0x9cd0c0, 0xc0000ae068, 0xc0000ac600)
        /usr/local/google/home/bcmills/go/src/net/http/server.go:2012 +0x52
net/http.serverHandler.ServeHTTP(0xc0000a8460, 0x9cd0c0, 0xc0000ae068, 0xc0000ac600)
        /usr/local/google/home/bcmills/go/src/net/http/server.go:2808 +0xc5
net/http.initALPNRequest.ServeHTTP(0x9cd940, 0xc000282b70, 0xc00029a380, 0xc0000a8460, 0x9cd0c0, 0xc0000ae068, 0xc0000ac600)
        /usr/local/google/home/bcmills/go/src/net/http/server.go:3380 +0xfd
net/http.(*http2serverConn).runHandler(0xc00031a180, 0xc0000ae068, 0xc0000ac600, 0xc0000977c0)
        /usr/local/google/home/bcmills/go/src/net/http/h2_bundle.go:5712 +0xc1
created by net/http.(*http2serverConn).processHeaders
        /usr/local/google/home/bcmills/go/src/net/http/h2_bundle.go:5446 +0x8fc
FAIL
FAIL    net/http/httptest       0.202s
FAIL

CC @bradfitz @tombergan @nerd2

[gopherbot]

Change https://golang.org/cl/227924 mentions this issue: net/http/httptest: add a regression test for #38370

[bcmills]

See previously #12262.

[bcmills]

Curiously, I'm not able to get the test to fail without the race detector.

I suspect that httptest may actually be synchronizing itself via the network socket in a way that is hidden from the race detector.

[nwidger]

@bcmills Could this be related to the same issue as #36946? Looks like the httptest server's Close method calls SetKeepAlivesEnabled(false):

https://golang.org/src/net/http/httptest/server.go?s=5496:5520#L190

I believe that might explain why the test server is not waiting for the handler to complete when HTTP/2 is enabled.

[ianlancetaylor]

Too late for 1.15, and not entirely clear that there is a real problem. Moving to Backlog.

[bcmills]

All races observed since the last comment are attributable to either #45237 or #49850 (which may actually be a variant of the same issue). This may have been resolved by some intervening change (to one or more of net/http, the runtime, and/or the race detector).

greplogs --dashboard -md -l -e '^WARNING: DATA RACE\n.+ by goroutine \d+:\n(?: .+\n \s+.+\n)* net/http/httptest' --since=2020-06-26

2021-11-29T02:12:23-d83791d-f6103e9/linux-amd64-race 2021-04-12T21:25:46-afb366f-f12cf76/windows-amd64-race 2021-03-31T16:59:18-cb1fcc7-887c0d8/freebsd-amd64-race 2021-03-23T23:09:33-08027d5-87a3ac5/windows-amd64-race 2021-02-24T04:11:43-9060382-6ba4a30/linux-amd64-race 2020-12-23T17:01:35-986b41b-49d0b23/freebsd-amd64-race 2020-12-21T21:48:47-986b41b-bc7e4d9/freebsd-amd64-race 2020-10-26T18:10:12-146b70c-c5dea8f/freebsd-amd64-race 2020-10-19T12:40:52-7b1cca2-53094ac/windows-amd64-race 2020-09-29T22:49:58-5d4f700-0e85fd7/windows-amd64-race 2020-09-28T22:28:06-5d4f700-1f4d035/freebsd-amd64-race 2020-08-21T23:45:40-3edf25e-f454f70/freebsd-amd64-race 2020-08-12T23:16:53-ab34263-50f63a7/freebsd-amd64-race

[bcmills]

Oh, neat! The regression test in https://go.dev/cl/227924 actually still fails.

[bcmills]

(attn @neild)

[bcmills]

Interesting! The race that is now reported is entirely on the client side. 🤔

``` ================== WARNING: DATA RACE Write at 0x00c0002928e1 by goroutine 191: net/http.(*readTrackingBody).Close() /workdir/go/src/net/http/transport.go:657 +0x2f net/http.(*http2clientStream).closeReqBodyLocked.func1() /workdir/go/src/net/http/h2_bundle.go:7469 +0x5d Previous write at 0x00c0002928e1 by goroutine 168: net/http.(*readTrackingBody).Close() /workdir/go/src/net/http/transport.go:657 +0x2f net/http.(*Request).closeBody() /workdir/go/src/net/http/request.go:1443 +0xf84 net/http.(*Transport).roundTrip() /workdir/go/src/net/http/transport.go:629 +0xf45 net/http.(*Transport).RoundTrip() /workdir/go/src/net/http/roundtrip.go:17 +0x33 net/http.send() /workdir/go/src/net/http/client.go:260 +0x943 net/http.(*Client).send() /workdir/go/src/net/http/client.go:181 +0x14e net/http.(*Client).do() /workdir/go/src/net/http/client.go:724 +0x1153 net/http.(*Client).Do() /workdir/go/src/net/http/client.go:590 +0x52d net/http/httptest.TestCloseBlocksUntilRequestsCompleted.func1() /workdir/go/src/net/http/httptest/server_test.go:341 +0x520 testing.tRunner() /workdir/go/src/testing/testing.go:1595 +0x238 ??() -:0 +0x56edc4 Goroutine 191 (running) created at: net/http.(*http2clientStream).closeReqBodyLocked() /workdir/go/src/net/http/h2_bundle.go:7468 +0x170 net/http.(*http2clientStream).abortStreamLocked() /workdir/go/src/net/http/h2_bundle.go:7443 +0x9e net/http.(*http2ClientConn).RoundTrip.func3() /workdir/go/src/net/http/h2_bundle.go:8293 +0xda net/http.(*http2ClientConn).RoundTrip() /workdir/go/src/net/http/h2_bundle.go:8328 +0xb7b net/http.(*http2Transport).RoundTripOpt() /workdir/go/src/net/http/h2_bundle.go:7582 +0x639 net/http.(*http2Transport).RoundTrip() /workdir/go/src/net/http/h2_bundle.go:7534 +0x35 net/http.(*Transport).roundTrip() /workdir/go/src/net/http/transport.go:602 +0xcee net/http.(*Transport).RoundTrip() /workdir/go/src/net/http/roundtrip.go:17 +0x33 net/http.send() /workdir/go/src/net/http/client.go:260 +0x943 net/http.(*Client).send() /workdir/go/src/net/http/client.go:181 +0x14e net/http.(*Client).do() /workdir/go/src/net/http/client.go:724 +0x1153 net/http.(*Client).Do() /workdir/go/src/net/http/client.go:590 +0x52d net/http/httptest.TestCloseBlocksUntilRequestsCompleted.func1() /workdir/go/src/net/http/httptest/server_test.go:341 +0x520 testing.tRunner() /workdir/go/src/testing/testing.go:1595 +0x238 ??() -:0 +0x56edc4 Goroutine 168 (running) created at: testing.(*T).Run() /workdir/go/src/testing/testing.go:1648 +0x835 net/http/httptest.TestCloseBlocksUntilRequestsCompleted() /workdir/go/src/net/http/httptest/server_test.go:311 +0x7b testing.tRunner() /workdir/go/src/testing/testing.go:1595 +0x238 ??() -:0 +0x56edc4 ================== --- FAIL: TestCloseBlocksUntilRequestsCompleted (0.00s) --- FAIL: TestCloseBlocksUntilRequestsCompleted/http2 (0.03s) testing.go:1465: race detected during execution of test FAIL FAIL net/http/httptest 0.198s ```

[bcmills]

Ah, that race is #60041.

[neild]

httptest doesn't do anything to wait for handlers to exit.

httptest.Server.Close closes the connection listener and waits for http.Server.Serve to return, but Serve doesn't wait for handler goroutines to complete before returning.

In fact, I don't think there's anything in net/http which is documented as waiting for handler goroutines to complete. Server.Shutdown waits "for connections to return to idle", but a handler that's still running for a request on a now-closed connection won't block Shutdown.

httptest.Server.Close "blocks until all outstanding requests on this server have completed", but that's a bit ambiguous on whether it blocks until handlers have returned.

This doesn't look like a race condition; there just isn't anything that waits for handlers to exit. Perhaps there should be.

[bcmills]

Per https://pkg.go.dev/net/http#Handler:

Returning signals that the request is finished

To me, that makes the phrase “blocks until all outstanding requests on this server have completed” completely unambiguous: a (server-side) request is not “completed” until its handler has returned.

[gopherbot]

Change https://go.dev/cl/539436 mentions this issue: net/http: remove arbitrary timeouts in tests of Server.ErrorLog