Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

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

Closed
jmhodges opened this issue Aug 21, 2015 · 8 comments
Closed

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

jmhodges opened this issue Aug 21, 2015 · 8 comments
Labels
FrozenDueToAge
Milestone
Go1.6

Comments

@jmhodges
Copy link
Contributor

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
Copy link
Contributor Author

(This is in Go 1.5)

@jmhodges jmhodges mentioned this issue Aug 21, 2015
Merged
@ianlancetaylor ianlancetaylor added this to the Go1.6 milestone Aug 21, 2015
@ianlancetaylor
Copy link
Contributor

CC @bradfitz

@jmhodges jmhodges mentioned this issue Aug 25, 2015
Closed
@mvdan mvdan mentioned this issue Aug 26, 2015
Merged
powerman added a commit to powerman/rpc-codec that referenced this issue Sep 5, 2015
@powerman
work around golang/go#12262
65bac2c
@mvdan mvdan mentioned this issue Sep 21, 2015
Merged
@phemmer
Copy link

phemmer commented Sep 28, 2015

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
Copy link
Contributor

bradfitz commented Dec 4, 2015

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
Copy link
Contributor

bradfitz commented Dec 4, 2015

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.

@bradfitz bradfitz closed this as completed Dec 4, 2015
@mikedanese mikedanese mentioned this issue Dec 5, 2015
Merged
@xiang90 xiang90 mentioned this issue Dec 30, 2015
Closed
@mikedanese mikedanese mentioned this issue Jan 7, 2016
Closed
@roberthbailey
Copy link

@bradfitz - Was this also fixed in Go 1.5.2 by any chance?

@bradfitz
Copy link
Contributor

bradfitz commented Jan 7, 2016

No. Point releases are only for critical crashes or security things.

@roberthbailey
Copy link

Thanks.

@krousey krousey mentioned this issue Jan 7, 2016
Closed
davidopp pushed a commit to davidopp/kubernetes that referenced this issue Jan 12, 2016
Comment out calls to httptest.Server.Close() to work around
8ac4847 
golang/go#12262 . See kubernetes#19254 for
more details. This change should be reverted when we upgrade
to Go 1.6.
brendandburns added a commit to brendandburns/kubernetes that referenced this issue Jan 25, 2016
@brendandburns
Disable closing of the httptest Server due to golang/go#12262
b8b074f
dchen1107 added a commit to kubernetes/kubernetes that referenced this issue Jan 26, 2016
@dchen1107
Merge pull request #20123 from brendandburns/flake3
19ef077 
Disable closing of the httptest Server due to golang/go#12262
@dcbw dcbw mentioned this issue Feb 5, 2016
Closed
@dcbw dcbw mentioned this issue Feb 5, 2016
Merged
soltysh added a commit to soltysh/kubernetes that referenced this issue Feb 11, 2016
@soltysh
Comment out calls to httptest.Server.Close() to work around
72654d3 
golang/go#12262 . See kubernetes#19254 for
more details. This change should be reverted when we upgrade
to Go 1.6.
dcbw added a commit to dcbw/kubernetes that referenced this issue Feb 12, 2016
@dcbw
Fix another instance of golang kubernetes#12262
905dfd9 
Reliably reproducible on two up-to-date Fedora 23 machines using
go 1.5.3, both one Core i7-4770R and a Core i7-4790.

golang/go#12262
@wojtek-t wojtek-t mentioned this issue Feb 15, 2016
Closed
@lavalamp lavalamp mentioned this issue Apr 20, 2016
Closed
This was referenced Jun 28, 2016
Closed
Closed
deads2k pushed a commit to kubernetes-retired/kube-mesos-framework that referenced this issue Sep 29, 2016
Comment out calls to httptest.Server.Close() to work around
0e56ecc 
golang/go#12262 . See #19254 for
more details. This change should be reverted when we upgrade
to Go 1.6.
@golang golang locked and limited conversation to collaborators Jan 7, 2017
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Assignees
No one assigned
Labels
FrozenDueToAge
Projects
None yet
Milestone
Go1.6
Development

No branches or pull requests
6 participants
@jmhodges @bradfitz @phemmer @ianlancetaylor @roberthbailey @gopherbot