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

bcmills · 2020-04-10T20:38:48Z

~/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

The text was updated successfully, but these errors were encountered:

gopherbot · 2020-04-10T20:41:39Z

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

bcmills · 2020-04-10T20:47:49Z

See previously #12262.

bcmills · 2020-04-10T21:00:43Z

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 · 2020-05-27T20:09:11Z

@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 · 2020-06-26T00:02:50Z

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

bcmills · 2021-11-29T17:21:30Z

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 · 2023-05-17T13:25:42Z

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

bcmills · 2023-05-17T13:26:28Z

(attn @neild)

bcmills · 2023-05-17T13:48:33Z

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 · 2023-05-17T13:49:20Z

Ah, that race is #60041.

neild · 2023-05-19T21:33:03Z

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 · 2023-05-20T03:42:26Z

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 · 2023-11-20T19:58:00Z

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

This also allows us to remove the chanWriter helper from the test, using a simpler strings.Builder instead, relying on clientServerTest.close for synchronization. (I don't think this runs afoul of golang#38370, because the handler functions themselves in these tests should never be executed, let alone result in an asynchronous write to the error log.) Fixes golang#57599. Change-Id: I45c6cefca0bb218f6f9a9659de6bde454547f704 Reviewed-on: https://go-review.googlesource.com/c/go/+/539436 Run-TryBot: Bryan Mills <bcmills@google.com> TryBot-Result: Gopher Robot <gobot@golang.org> Auto-Submit: Bryan Mills <bcmills@google.com> Reviewed-by: Damien Neil <dneil@google.com> LUCI-TryBot-Result: Go LUCI <golang-scoped@luci-project-accounts.iam.gserviceaccount.com>

…ndServerSharedBodyRace This race was reported in https://build.golang.org/log/6f043170946b665edb85b50804a62db68348c52f. As best as I can tell, it is another instance of golang#38370. The deferred call to backend.close() ought to be enough to ensure that the t.Logf happens before the end of the test, but in practice it is not, and with enough scheduling delay we can manage to trip the race detector on a call to Logf after the test function has returned. Updates golang#38370. Change-Id: I5ee45df45c6bfad3239d665df65a138f1c4573a3 Reviewed-on: https://go-review.googlesource.com/c/go/+/531195 LUCI-TryBot-Result: Go LUCI <golang-scoped@luci-project-accounts.iam.gserviceaccount.com> Auto-Submit: Bryan Mills <bcmills@google.com> Reviewed-by: Damien Neil <dneil@google.com>

bcmills added the NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one. label Apr 10, 2020

bcmills added this to the Go1.15 milestone Apr 10, 2020

bcmills changed the title ~~net/http/httptest: (*Server).Close fails to block until outstanding HTTP/2 requests have completed~~ net/http/httptest: (*Server).Close races with HTTP/2 request handler Apr 10, 2020

bcmills added the RaceDetector label Apr 10, 2020

ianlancetaylor modified the milestones: Go1.15, Backlog Jun 26, 2020

bcmills mentioned this issue Jan 29, 2021

net/http: test failed on freebsd-12.2-STABLE #43984

Closed

bcmills mentioned this issue Mar 25, 2021

x/net/http2: data race in test from logging in onSameConn callback #45237

Closed

bcmills mentioned this issue Nov 29, 2021

x/net/http2: data race in TestTransportReusesConns #49850

Closed

bcmills closed this as completed Nov 29, 2021

golang locked and limited conversation to collaborators Nov 29, 2022

gopherbot added the FrozenDueToAge label Nov 29, 2022

bcmills reopened this May 17, 2023

bcmills removed the FrozenDueToAge label May 17, 2023

bcmills removed the RaceDetector label May 17, 2023

bcmills mentioned this issue Sep 28, 2023

net/http: data race in testTransportAndServerSharedBodyRace via t.Logf #63269

Closed

golang unlocked this conversation Nov 20, 2023

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

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

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

bcmills commented Apr 10, 2020

gopherbot commented Apr 10, 2020

bcmills commented Apr 10, 2020

bcmills commented Apr 10, 2020

nwidger commented May 27, 2020

ianlancetaylor commented Jun 26, 2020

bcmills commented Nov 29, 2021

bcmills commented May 17, 2023

bcmills commented May 17, 2023

bcmills commented May 17, 2023

bcmills commented May 17, 2023

neild commented May 19, 2023

bcmills commented May 20, 2023

gopherbot commented Nov 20, 2023

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

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

Comments

bcmills commented Apr 10, 2020

gopherbot commented Apr 10, 2020

bcmills commented Apr 10, 2020

bcmills commented Apr 10, 2020

nwidger commented May 27, 2020

ianlancetaylor commented Jun 26, 2020

bcmills commented Nov 29, 2021

bcmills commented May 17, 2023

bcmills commented May 17, 2023

bcmills commented May 17, 2023

bcmills commented May 17, 2023

neild commented May 19, 2023

bcmills commented May 20, 2023

gopherbot commented Nov 20, 2023