net/http: data race in TestTransportResponseHeaderTimeout

[dvyukov]

parent: 19010:d067c6de4ec3 tip, linux/amd64
$ go test -v -race -cpu=16,16,16,16 -run=TestTransportResponseHeaderTimeout net/http

WARNING: DATA RACE
Write by goroutine 51:
  sync.raceWrite()
      src/pkg/sync/race.go:41 +0x35
  sync.(*WaitGroup).Wait()
      src/pkg/sync/waitgroup.go:120 +0x16d
  net/http/httptest.(*Server).Close()
      src/pkg/net/http/httptest/server.go:168 +0x6a
  net/http_test.TestTransportResponseHeaderTimeout()
      src/pkg/net/http/transport_test.go:1254 +0x6de
  testing.tRunner()
      src/pkg/testing/testing.go:398 +0x10f

Previous read by goroutine 366:
  sync.raceRead()
      src/pkg/sync/race.go:37 +0x35
  sync.(*WaitGroup).Add()
      src/pkg/sync/waitgroup.go:60 +0xc1
  net/http/httptest.(*waitGroupHandler).ServeHTTP()
      src/pkg/net/http/httptest/server.go:198 +0x5e
  net/http.serverHandler.ServeHTTP()
      src/pkg/net/http/server.go:1599 +0x1cc
  net/http.(*conn).serve()
      src/pkg/net/http/server.go:1162 +0xc36

Goroutine 51 (running) created at:
  testing.RunTests()
      src/pkg/testing/testing.go:479 +0xbb5
  testing.Main()
      src/pkg/testing/testing.go:411 +0xad
  main.main()
      /tmp/go-build864201384/net/http/_test/_testmain.go:443 +0xdc

Goroutine 366 (running) created at:
  net/http.(*Server).Serve()
      src/pkg/net/http/server.go:1646 +0x2d1


The test sends request to /slow:
    mux.HandleFunc("/slow", func(w ResponseWriter, r *Request) { time.Sleep(2 * time.Second) })
gets timeout error after 500ms and then closes the server with:
    defer ts.Close()

Close waits for all outstanding handlers to finish:
func (s *Server) Close() {
    s.Listener.Close()
    s.wg.Wait()
    ...
}

The wg is +1'ed in the handler:
func (h *waitGroupHandler) ServeHTTP(w http.ResponseWriter, r *http.Request) {
    h.s.wg.Add(1)
    defer h.s.wg.Done() // a defer, in case ServeHTTP below panics
    h.h.ServeHTTP(w, r)
}

So essentially when the test closes the server and waits for all outstanding handlers to
finish, ServeHTTP may not yet have +1'ed wg, so wg.Wait will return early w/o waiting
for the handler.


httptest.NewServer API assumes that tests wait at least for handlers to start executing.
Then Close will wait for handlers to finish.

[bradfitz]

Comment 1:

Sorry, I don't understand this bug report.

[dvyukov]

Comment 2:

We call wg.Wait before the relevant wg.Add has happened.

[bradfitz]

Comment 3:

I don't see where.
Also, you're not even clear about what you think is at fault---  that test or
httptest.Server?
If no HTTP request has been received, there is nothing to wait for in
httptest.Server.Close.
This test makes 3 HTTP requests. How will the wg.Add not be called 3 times?
I also can't reproduce this.

[dvyukov]

Comment 4:

The test makes 3 requests, but it does not know that the servers handler for /slow
request has started. It may not be even received from Listen. Or received from Listen
and the handler goroutine is kicked off, but it has not yet executed wg.Add.
The test is at fault, it must do something along the lines of:
received := make(chan bool)
mux.HandleFunc("/slow", func(w ResponseWriter, r *Request) {
  received <- true
  time.Sleep(2 * time.Second)
})
<-received
// Only NOW we do know that wg.Add has happened!
ts.Close()
-------------------------------------
Essentially what happens here is:
var wg sync.WaitGroup
go func() {  // this is slow handler
  wg.Add(1)
  time.Sleep(2 * time.Second)
  wg.Done()
}()
wg.Wait()

[bradfitz]

Comment 5:

In the general case, I agree that the wg.Add(1) could be earlier in httptest, and I
could imagine scenarios that would exploit that, but you wrote that the test
(TestTransportResponseHeaderTimeout) is at fault and I kinda disagree.
The test makes three synchronous HTTP requests. They're not in goroutines.
How can I reproduce the data race you saw? Did you have local modifications?
Normally it's very easy to repro races, but I can't make this one trigger, and an
eyeball analysis of all the relevant code seems fine too.
I totally understand what you're talking about with wg.Add(1) being done in a goroutine
(and I'll send a CL for httptest to do the wg.Add(1) earlier), but I don't see how this
can happen here, at least in the success paths, unless the test is already failing for
other reasons.
Maybe I could imagine a scenario where the second HTTP request actually connects, but
the machine is so loaded, the Go scheduler doesn't run the http Handler goroutine for
seconds, meanwhile the client code goroutine does run and passes, the func exits, and
then the Handler runs.  Was the builder very overloaded?  I guess I'm never surprised by
how slow the build machines can be.

[bradfitz]

Comment 6:

Sent https://golang.org/cl/70950043

Owner changed to @bradfitz.

Status changed to Started.

[dvyukov]

Comment 7:

I will try to provide more reliable reproducer today.
> Maybe I could imagine a scenario where the second HTTP request actually connects, but
the machine is so loaded, the Go scheduler doesn't run the http Handler goroutine for
seconds, meanwhile the client code goroutine does run and passes, the func exits, and
then the Handler runs.
The race detector does not care about timings, it watches when things are not
synchronized.
> I totally understand what you're talking about with wg.Add(1) being done in a
goroutine (and I'll send a CL for httptest to do the wg.Add(1) earlier)
Just doing wd.Add after Accept won't help. Because if you do http.Get with timeout, then
you don't know that even Accept has returned when timeout fires.

[gopherbot]

Comment 8:

CL https://golang.org/cl/70950043 references this issue.

[bradfitz]

Comment 9:

Assigning to Dmitry to create a repro.

Owner changed to @dvyukov.

Status changed to Accepted.

[bradfitz]

Comment 10:

Labels changed: added testing.

[dvyukov]

Comment 11:

Mailed CL with small and reliable reproducer:
https://golang.org/cl/86770043

Owner changed to @bradfitz.

[gopherbot]

Comment 12:

CL https://golang.org/cl/86770043 mentions this issue.

[gopherbot]

Comment 13:

CL https://golang.org/cl/86770043 mentions this issue.

[gopherbot]

Comment 14:

CL https://golang.org/cl/86770043 mentions this issue.

[dvyukov]

Comment 15:

This issue was updated by revision 388d533.

LGTM=bradfitz
R=golang-codereviews, bradfitz
CC=golang-codereviews
https://golang.org/cl/86770043