net/http: TimeoutHandler panics with concurrent requests

[gopherbot]

by vzdravevski:

When I make concurrent requests (~200 concurrent users, 100 requests each) to this code,
POST-ing ~70kb worth of form data in each request, I get the following panic ...

http://play.golang.org/p/LYLFT4l2qp

My guess based on reading the source code is that timeout causes a write to the response
before reading the request might be completely done. Seems like a race condition because
the reading of req/resp isn't synchronized and with the current API can't be
synchronized. Race detector also doesn't seem to detect this issue.

The "timeoutWriter" does have a mutex, but it only protects the response, but
not the request in the handler.

NOTE: This was tested on linux/amd64
Go1.2.2 and 1.3.rc2

Panic:
---------
runtime error: slice bounds out of range
goroutine 302 [running]:
net/http.func·009()
    /usr/local/go/src/pkg/net/http/server.go:1093 +0xae
runtime.panic(0x5f6060, 0x87388a)
    /usr/local/go/src/pkg/runtime/panic.c:248 +0x106
bufio.(*Reader).Read(0xc210396480, 0xc210b1c000, 0x2000, 0x2000, 0xffffffffffffffec, ...)
    /usr/local/go/src/pkg/bufio/bufio.go:168 +0x2e7
io.(*LimitedReader).Read(0xc210459120, 0xc210b1c000, 0x2000, 0x2000, 0x14, ...)
    /usr/local/go/src/pkg/io/io.go:398 +0xbb
net/http.(*body).Read(0xc21042d750, 0xc210b1c000, 0x2000, 0x2000, 0x14, ...)
    /usr/local/go/src/pkg/net/http/transfer.go:534 +0x96
io.(*LimitedReader).Read(0xc2101fb800, 0xc210b1c000, 0x2000, 0x2000, 0x14, ...)
    /usr/local/go/src/pkg/io/io.go:398 +0xbb
io/ioutil.devNull.ReadFrom(0x0, 0x7fe33e84f4a8, 0xc2101fb800, 0x544, 0x0, ...)
    /usr/local/go/src/pkg/io/ioutil/ioutil.go:144 +0xb0
io.Copy(0x7fe33e84dfe8, 0x0, 0x7fe33e84f4a8, 0xc2101fb800, 0x0, ...)
    /usr/local/go/src/pkg/io/io.go:348 +0x124
io.CopyN(0x7fe33e84dfe8, 0x0, 0x7fe33e855590, 0xc21042d750, 0x40001, ...)
    /usr/local/go/src/pkg/io/io.go:317 +0xbe
net/http.(*chunkWriter).writeHeader(0xc210260a20, 0xc210246800, 0x1a, 0x800)
    /usr/local/go/src/pkg/net/http/server.go:787 +0x117d
net/http.(*chunkWriter).Write(0xc210260a20, 0xc210246800, 0x1a, 0x800, 0x0, ...)
    /usr/local/go/src/pkg/net/http/server.go:246 +0x87
bufio.(*Writer).flush(0xc210058bc0, 0xc2104561d8, 0x7fe3ffffffff)
    /usr/local/go/src/pkg/bufio/bufio.go:494 +0xa1
bufio.(*Writer).Flush(0xc210058bc0, 0x7fe33c664e28, 0x1025b038)
    /usr/local/go/src/pkg/bufio/bufio.go:483 +0x27
net/http.(*response).finishRequest(0xc210260a00)
    /usr/local/go/src/pkg/net/http/server.go:999 +0x57
net/http.(*conn).serve(0xc210456180)
    /usr/local/go/src/pkg/net/http/server.go:1171 +0x7e8
created by net/http.(*Server).Serve
    /usr/local/go/src/pkg/net/http/server.go:1644 +0x28b

[ianlancetaylor]

Comment 1:

Labels changed: added repo-main, release-go1.4.

[gopherbot]

Comment 2 by [email protected]:

I've created a gist that can reproduce the issue without high concurrency.
https://gist.github.com/partkyle/404b3d305e69ea11172e

[bradfitz]

Comment 3:

Owner changed to @bradfitz.

Status changed to Accepted.

[gopherbot]

Comment 4:

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

[bradfitz]

Comment 5:

This issue was closed by revision e38fa91.

Status changed to Fixed.

[wongak]

Comment 6:

Hi, I'm sorry, I replied to the code review :P
The TimeoutHandler will still suffer from a race if the guarded handler modifies the
Header.
Created a slight modification to the test:
diff -r 493ad916c3b1 src/net/http/serve_test.go
--- a/src/net/http/serve_test.go    Sun Nov 23 15:13:48 2014 -0500
+++ b/src/net/http/serve_test.go    Mon Nov 24 15:50:11 2014 +0100
@@ -1171,6 +1171,7 @@
    sendHi := make(chan bool, 1)
    writeErrors := make(chan error, 1)
    sayHi := HandlerFunc(func(w ResponseWriter, r *Request) {
+       w.Header().Set("Content-Type", "text/plain")
        <-sendHi
        _, werr := w.Write([]byte("hi"))
        writeErrors <- werr
Assuming a handler modifies the header before timing out. This will lead to a
data race.