x/net/http2: data race in onSameConn test helper

[bcmills]

https://build.golang.org/log/0d66aaa201ea31f6aa29c94ff8d6b76f67789071

==================
WARNING: DATA RACE
Read at 0x00c00015c163 by goroutine 315:
  testing.(*common).logDepth()
      /tmp/workdir/go/src/testing/testing.go:669 +0xa1
  testing.(*common).log()
      /tmp/workdir/go/src/testing/testing.go:662 +0x8f
  testing.(*common).Logf()
      /tmp/workdir/go/src/testing/testing.go:701 +0x21
  golang.org/x/net/http2.onSameConn.func2()
      /tmp/workdir/gopath/src/golang.org/x/net/http2/transport_test.go:196 +0x101
  net/http/httptest.(*Server).wrap.func1()
      /tmp/workdir/go/src/net/http/httptest/server.go:357 +0x121
  net/http.(*conn).setState()
      /tmp/workdir/go/src/net/http/server.go:1725 +0x155
  net/http.(*conn).serve.func1()
      /tmp/workdir/go/src/net/http/server.go:1777 +0xf8
  net/http.(*conn).serve()
      /tmp/workdir/go/src/net/http/server.go:1807 +0x1c10

Previous write at 0x00c00015c163 by goroutine 195:
  testing.tRunner.func1()
      /tmp/workdir/go/src/testing/testing.go:978 +0x467
  testing.tRunner()
      /tmp/workdir/go/src/testing/testing.go:996 +0x20d

Goroutine 315 (running) created at:
  net/http.(*Server).Serve()
      /tmp/workdir/go/src/net/http/server.go:2933 +0x5b6
  net/http/httptest.(*Server).goServe.func1()
      /tmp/workdir/go/src/net/http/httptest/server.go:308 +0xd3

Goroutine 195 (running) created at:
  testing.(*T).Run()
      /tmp/workdir/go/src/testing/testing.go:1043 +0x660
  testing.runTests.func1()
      /tmp/workdir/go/src/testing/testing.go:1300 +0xa6
  testing.tRunner()
      /tmp/workdir/go/src/testing/testing.go:992 +0x1eb
  testing.runTests()
      /tmp/workdir/go/src/testing/testing.go:1298 +0x57f
  testing.(*M).Run()
      /tmp/workdir/go/src/testing/testing.go:1210 +0x353
  main.main()
      _testmain.go:668 +0x223
==================
FAIL
FAIL	golang.org/x/net/http2	17.754s

The racing write is here:

go/src/testing/testing.go

Lines 976 to 978 in 7bb3317

	// Do not lock t.done to allow race detector to detect race in case
	// the user does not appropriately synchronizes a goroutine.
	t.done = true

That comment suggests that the bug lies in the test itself:
https://github.com/golang/net/blob/0de0cce0169b09b364e001f108dc0399ea8630b3/http2/transport_test.go#L193-L198

	st := newServerTester(t, func(w http.ResponseWriter, r *http.Request) {
		io.WriteString(w, r.RemoteAddr)
	}, optOnlyServer, func(c net.Conn, st http.ConnState) {
		t.Logf("conn %v is now state %v", c.RemoteAddr(), st)
	})
	defer st.Close()

That, in turn, suggests that the serverTester is continuing to execute one of its callbacks after its Close method has already returned.

The callback is registered via the httptest.Server's Config.ConnState field:
https://github.com/golang/net/blob/0de0cce0169b09b364e001f108dc0399ea8630b3/http2/server_test.go#L118-L119

The (*serverTester).Close method explicitly closes its httptest.Server and its net.Conn.
https://github.com/golang/net/blob/0de0cce0169b09b364e001f108dc0399ea8630b3/http2/server_test.go#L256-L259

The documentation for (*httptest.Server).Close says that it “blocks until all outstanding requests on this server have completed.” However, it does not specify whether it blocks until the corresponding connections have been closed.

I would argue that (*httptest.Server).Close should block until the outstanding connections are completely closed, including any ConnState callbacks. However, there may be a shorter-term workaround we can apply in the x/net/http2 test in the interim. (I will file a separate issue for httptest.Server.)

CC @bradfitz @rsc @tombergan

[bcmills]

2020-10-16T16:51:38-7b1cca2/windows-amd64-race
2020-09-27T03:25:02-5d4f700/freebsd-amd64-race
2020-09-27T03:25:02-5d4f700/windows-amd64-race
2020-08-13T13:45:08-3edf25e/freebsd-amd64-race
2020-07-07T03:43:11-ab34263/freebsd-amd64-race
2020-05-28T22:51:25-3c3fba1/windows-amd64-race
2020-05-20T18:23:14-0ba52f6/windows-amd64-race
2020-05-13T18:57:01-a91f071/windows-amd64-race
2020-04-25T23:01:54-ff2c4b7/freebsd-amd64-race
2020-03-24T14:37:07-d3edc99/freebsd-amd64-race
2020-03-19T23:41:17-63522db/freebsd-amd64-race
2020-02-22T12:55:58-5a598a2/windows-amd64-race
2020-02-19T18:36:55-4628272/freebsd-amd64-race
2020-01-14T15:54:13-6afb519/freebsd-amd64-race
2019-12-09T16:08:50-c0dbc17/windows-amd64-race

[bcmills]

2020-12-16T05:46:12-986b41b/freebsd-amd64-race
2020-10-26T09:15:29-146b70c/freebsd-amd64-race

[gopherbot]

Change https://golang.org/cl/304829 mentions this issue: net/http/httptest: wait for user ConnState hooks

[gopherbot]

Change https://golang.org/cl/367516 mentions this issue: [release-branch.go1.16] net/http/httptest: wait for user ConnState hooks