net/http/httptest: race on Server.Close and long-running requests

[jmhodges]

httptest.Server races between requests coming into its mux, and Server.Close. Normal usage doesn't typically trigger the race detector, but when a test client timeouts (we do this intentionally in letsencrypt/boulder to test how boulder fails) and moves on to teardown the test with Close, a race is found easily.

This code has a client that always times out when making a request to the server and reliably has a race detected: https://play.golang.org/p/aC0YTPBYGn

This is its output when run with the race detector:

GET error: Get http://127.0.0.1:61653: net/http: request canceled (Client.Timeout exceeded while awaiting headers)
==================
WARNING: DATA RACE
Write by main goroutine:
  sync.raceWrite()
      /Users/jmhodges/projects/go/src/sync/race.go:41 +0x2e
  sync.(*WaitGroup).Wait()
      /Users/jmhodges/projects/go/src/sync/waitgroup.go:124 +0xf9
  net/http/httptest.(*Server).Close()
      /Users/jmhodges/projects/go/src/net/http/httptest/server.go:168 +0x80
  main.main()
      /Users/jmhodges/projects/foo.go:35 +0x1fb

Previous read by goroutine 10:
  sync.raceRead()
      /Users/jmhodges/projects/go/src/sync/race.go:37 +0x2e
  sync.(*WaitGroup).Add()
      /Users/jmhodges/projects/go/src/sync/waitgroup.go:66 +0xfa
  net/http/httptest.(*waitGroupHandler).ServeHTTP()
      /Users/jmhodges/projects/go/src/net/http/httptest/server.go:198 +0x5c
  net/http.serverHandler.ServeHTTP()
      /Users/jmhodges/projects/go/src/net/http/server.go:1862 +0x206
  net/http.(*conn).serve()
      /Users/jmhodges/projects/go/src/net/http/server.go:1361 +0x117c

Goroutine 10 (running) created at:
  net/http.(*Server).Serve()
      /Users/jmhodges/projects/go/src/net/http/server.go:1910 +0x464
==================
Found 1 data race(s)

It seems the race detector is saying that between Server.Close closing the listener and Server.Close calling WaitGroup.Wait, a new Request could be pulled off the listener, but that the new Request could then only get to waitGroupHandler.ServeHTTP's WaitGroup.Add after the Wait is called.

[jmhodges]

(This is in Go 1.5)

[ianlancetaylor]

CC @bradfitz

[phemmer]

Also seeing this in 1.4.2 and 1.5.1

Edit: this code seems to reproduce it fairly reliably on my system:

package main

import (
    "net/http"
    "net/http/httptest"
    "testing"
    "time"
)

func TestRace(t *testing.T) {
    s := httptest.NewServer(http.HandlerFunc(func(_ http.ResponseWriter, _ *http.Request) { time.Sleep(time.Second * 2) }))
    go http.Get(s.URL)
    time.Sleep(time.Second)
    s.Close()
}

[bradfitz]

Can somebody who was able to reproduce this reliably before (@jmhodges, @phemmer?) try it again with Go tip.

I think this might've been fixed by:

commit a3156aaa121446c4136927f8c2139fefe05ba82c
Author: Brad Fitzpatrick <bradfitz@golang.org>
Date:   Tue Sep 29 14:26:48 2015 -0700

    net/http/httptest: change Server to use http.Server.ConnState for accounting

    With this CL, httptest.Server now uses connection-level accounting of
    outstanding requests instead of ServeHTTP-level accounting. This is
    more robust and results in a non-racy shutdown.

    This is much easier now that net/http.Server has the ConnState hook.

    Fixes #12789
    Fixes #12781

    Change-Id: I098cf334a6494316acb66cd07df90766df41764b
    Reviewed-on: https://go-review.googlesource.com/15151
    Reviewed-by: Andrew Gerrand <adg@golang.org>
    Run-TryBot: Brad Fitzpatrick <bradfitz@golang.org>
    TryBot-Result: Gobot Gobot <gobot@golang.org>

[bradfitz]

I can't get a race with either example with tip, but I do with Go 1.5. So yeah, looks like this was fixed.