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.

Sign up for GitHub

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

http.TimeoutHandler breaks with GOMAXPROCS n > 1 #8414

Closed
gopherbot opened this issue Jul 23, 2014 · 5 comments
Closed

http.TimeoutHandler breaks with GOMAXPROCS n > 1 #8414

gopherbot opened this issue Jul 23, 2014 · 5 comments
Labels
FrozenDueToAge
Milestone
Go1.4

Comments

@gopherbot
Copy link

by steinar@plainvanillagames.com:

*What does 'go version' print?*

go version go1.3 darwin/amd64

*What steps reproduce the problem?*

Running the following code (also attached) with 2 or more processes:
http://play.golang.org/p/eDtbVWdoMw
Since play.golang.org allows only one process per execution, the error cannot be
reproduced there.

1. Create a TimeoutHandler
2. Make it timeout while handler is writing to the ResponseWriter buffer

What happened?

Panic.

1. Handler starts writing to the ResponseWriter
2. Timeout occurs and ServeHTTP returns.  Meanwhile the original handler is still
running in a  go routine.
3. Bufio panics because buffer is dereferenced 

What should have happened instead?

Either of the following would have been expected:

* ResponseWriter is locked while being written to
  * Timeout trigger should have waited for the ongoing Write to complete
* Timeout should not occur if write has started

Please provide any additional information below.

The following is a stack trace of *timeout.go* running on a Macbook Pro.

{{{
2014/07/23 11:13:57 http: multiple response.WriteHeader calls
panic: runtime error: slice bounds out of range

goroutine 8692 [running]:
runtime.panic(0x269820, 0x40666f)
    /usr/local/Cellar/go/1.3/libexec/src/pkg/runtime/panic.c:279 +0xf5
bufio.(*Writer).flush(0xc208038080, 0x0, 0x0)
    /usr/local/Cellar/go/1.3/libexec/src/pkg/bufio/bufio.go:530 +0x256
bufio.(*Writer).Write(0xc208038080, 0xc20810e700, 0x1770, 0x1b00, 0x0, 0x0, 0x0)
    /usr/local/Cellar/go/1.3/libexec/src/pkg/bufio/bufio.go:566 +0x203
net/http.(*chunkWriter).Write(0xc2081dc7a0, 0xc20810e700, 0x1770, 0x1b00, 0x0, 0x0, 0x0)
    /usr/local/Cellar/go/1.3/libexec/src/pkg/net/http/server.go:261 +0x2a0
bufio.(*Writer).Write(0xc208038100, 0xc20810e700, 0x1770, 0x1b00, 0x0, 0x0, 0x0)
    /usr/local/Cellar/go/1.3/libexec/src/pkg/bufio/bufio.go:562 +0xd9
net/http.(*response).write(0xc2081dc780, 0x1770, 0xc20810e700, 0x1770, 0x1b00, 0x2983d0,
0x0, 0x100000000, 0x0, 0x0)
    /usr/local/Cellar/go/1.3/libexec/src/pkg/net/http/server.go:987 +0x1de
net/http.(*response).Write(0xc2081dc780, 0xc20810e700, 0x1770, 0x1b00, 0x3ff408, 0x0,
0x0)
    /usr/local/Cellar/go/1.3/libexec/src/pkg/net/http/server.go:959 +0x7b
net/http.(*timeoutWriter).Write(0xc2080c12c0, 0xc20810e700, 0x1770, 0x1b00, 0x0, 0x0,
0x0)
    /usr/local/Cellar/go/1.3/libexec/src/pkg/net/http/server.go:1924 +0xf5
main.handlerFn(0x4afad0, 0xc2080c12c0, 0xc20809f860)
    /Users/steinar/projects/quizup/quizup-presence/src/examples/timeout.go:36 +0x289
net/http.HandlerFunc.ServeHTTP(0x31b6d0, 0x4afad0, 0xc2080c12c0, 0xc20809f860)
    /usr/local/Cellar/go/1.3/libexec/src/pkg/net/http/server.go:1235 +0x40
net/http.func·014()
    /usr/local/Cellar/go/1.3/libexec/src/pkg/net/http/server.go:1888 +0xa4
created by net/http.(*timeoutHandler).ServeHTTP
    /usr/local/Cellar/go/1.3/libexec/src/pkg/net/http/server.go:1890 +0x142

goroutine 16 [chan receive]:
main.main()
    /Users/steinar/projects/quizup/quizup-presence/src/examples/timeout.go:62 +0x12a

goroutine 19 [finalizer wait]:
runtime.park(0x147d0, 0x40a200, 0x408d09)
    /usr/local/Cellar/go/1.3/libexec/src/pkg/runtime/proc.c:1369 +0x89
runtime.parkunlock(0x40a200, 0x408d09)
    /usr/local/Cellar/go/1.3/libexec/src/pkg/runtime/proc.c:1385 +0x3b
runfinq()
    /usr/local/Cellar/go/1.3/libexec/src/pkg/runtime/mgc0.c:2644 +0xcf
runtime.goexit()
    /usr/local/Cellar/go/1.3/libexec/src/pkg/runtime/proc.c:1445

goroutine 20 [IO wait]:
net.runtime_pollWait(0x4af730, 0x72, 0x0)
    /usr/local/Cellar/go/1.3/libexec/src/pkg/runtime/netpoll.goc:146 +0x66
net.(*pollDesc).Wait(0xc20802a140, 0x72, 0x0, 0x0)
    /usr/local/Cellar/go/1.3/libexec/src/pkg/net/fd_poll_runtime.go:84 +0x46
net.(*pollDesc).WaitRead(0xc20802a140, 0x0, 0x0)
    /usr/local/Cellar/go/1.3/libexec/src/pkg/net/fd_poll_runtime.go:89 +0x42
net.(*netFD).accept(0xc20802a0e0, 0x31b7e8, 0x0, 0x4ae290, 0x23)
    /usr/local/Cellar/go/1.3/libexec/src/pkg/net/fd_unix.go:409 +0x343
net.(*TCPListener).AcceptTCP(0xc20803a028, 0x3bf18, 0x0, 0x0)
    /usr/local/Cellar/go/1.3/libexec/src/pkg/net/tcpsock_posix.go:234 +0x5d
net.(*TCPListener).Accept(0xc20803a028, 0x0, 0x0, 0x0, 0x0)
    /usr/local/Cellar/go/1.3/libexec/src/pkg/net/tcpsock_posix.go:244 +0x4b
net/http/httptest.(*historyListener).Accept(0xc208022a80, 0x0, 0x0, 0x0, 0x0)
    /usr/local/Cellar/go/1.3/libexec/src/pkg/net/http/httptest/server.go:48 +0x7e
net/http.(*Server).Serve(0xc2080041e0, 0x4af7e0, 0xc208022a80, 0x0, 0x0)
    /usr/local/Cellar/go/1.3/libexec/src/pkg/net/http/server.go:1698 +0x91
created by net/http/httptest.(*Server).Start
    /usr/local/Cellar/go/1.3/libexec/src/pkg/net/http/httptest/server.go:109 +0x2a3

goroutine 21 [select]:
net/http.(*persistConn).roundTrip(0xc20821e420, 0xc208000fa0, 0x0, 0x0, 0x0)
    /usr/local/Cellar/go/1.3/libexec/src/pkg/net/http/transport.go:1015 +0x6db
net/http.(*Transport).RoundTrip(0xc208046100, 0xc20809f790, 0xc20818dd10, 0x0, 0x0)
    /usr/local/Cellar/go/1.3/libexec/src/pkg/net/http/transport.go:208 +0x49a
net/http.send(0xc20809f790, 0x4ae5c0, 0xc208046100, 0xc2081acaa4, 0x0, 0x0)
    /usr/local/Cellar/go/1.3/libexec/src/pkg/net/http/client.go:195 +0x43d
net/http.(*Client).send(0x40b4a0, 0xc20809f790, 0x23, 0x0, 0x0)
    /usr/local/Cellar/go/1.3/libexec/src/pkg/net/http/client.go:118 +0x15b
net/http.(*Client).doFollowingRedirects(0x40b4a0, 0xc20809f790, 0x31b858, 0x0, 0x0, 0x0)
    /usr/local/Cellar/go/1.3/libexec/src/pkg/net/http/client.go:343 +0x97f
net/http.(*Client).Do(0x40b4a0, 0xc20809f790, 0xc20818dd10, 0x0, 0x0)
    /usr/local/Cellar/go/1.3/libexec/src/pkg/net/http/client.go:150 +0xa3
main.func·001()
    /Users/steinar/projects/quizup/quizup-presence/src/examples/timeout.go:50 +0xf0
created by main.main
    /Users/steinar/projects/quizup/quizup-presence/src/examples/timeout.go:59 +0xf2

goroutine 8671 [select]:
net/http.(*persistConn).writeLoop(0xc20821e420)
    /usr/local/Cellar/go/1.3/libexec/src/pkg/net/http/transport.go:885 +0x38f
created by net/http.(*Transport).dialConn
    /usr/local/Cellar/go/1.3/libexec/src/pkg/net/http/transport.go:601 +0x957

goroutine 8691 [runnable]:
net.(*pollDesc).PrepareWrite(0xc2081bc6f0, 0x0, 0x0)
    /usr/local/Cellar/go/1.3/libexec/src/pkg/net/fd_poll_runtime.go:79
net.(*netFD).Write(0xc2081bc690, 0xc208096000, 0x93, 0x1000, 0x0, 0x0, 0x0)
    /usr/local/Cellar/go/1.3/libexec/src/pkg/net/fd_unix.go:312 +0x108
net.(*conn).Write(0xc208093ee8, 0xc208096000, 0x93, 0x1000, 0x0, 0x0, 0x0)
    /usr/local/Cellar/go/1.3/libexec/src/pkg/net/net.go:130 +0xe7
bufio.(*Writer).flush(0xc208038080, 0x0, 0x0)
    /usr/local/Cellar/go/1.3/libexec/src/pkg/bufio/bufio.go:530 +0xe2
bufio.(*Writer).Flush(0xc208038080, 0x0, 0x0)
    /usr/local/Cellar/go/1.3/libexec/src/pkg/bufio/bufio.go:519 +0x39
net/http.(*response).finishRequest(0xc2081dc780)
    /usr/local/Cellar/go/1.3/libexec/src/pkg/net/http/server.go:1003 +0xa0
net/http.(*conn).serve(0xc2080e0400)
    /usr/local/Cellar/go/1.3/libexec/src/pkg/net/http/server.go:1178 +0xab9
created by net/http.(*Server).Serve
    /usr/local/Cellar/go/1.3/libexec/src/pkg/net/http/server.go:1721 +0x313

goroutine 8670 [IO wait]:
net.runtime_pollWait(0x4af680, 0x72, 0x0)
    /usr/local/Cellar/go/1.3/libexec/src/pkg/runtime/netpoll.goc:146 +0x66
net.(*pollDesc).Wait(0xc2081bc530, 0x72, 0x0, 0x0)
    /usr/local/Cellar/go/1.3/libexec/src/pkg/net/fd_poll_runtime.go:84 +0x46
net.(*pollDesc).WaitRead(0xc2081bc530, 0x0, 0x0)
    /usr/local/Cellar/go/1.3/libexec/src/pkg/net/fd_poll_runtime.go:89 +0x42
net.(*netFD).Read(0xc2081bc4d0, 0xc20809b000, 0x1000, 0x1000, 0x0, 0x4ae290, 0x23)
    /usr/local/Cellar/go/1.3/libexec/src/pkg/net/fd_unix.go:232 +0x34c
net.(*conn).Read(0xc20803bb68, 0xc20809b000, 0x1000, 0x1000, 0x0, 0x0, 0x0)
    /usr/local/Cellar/go/1.3/libexec/src/pkg/net/net.go:122 +0xe7
net/http.noteEOFReader.Read(0x4af8a0, 0xc20803bb68, 0xc20821e478, 0xc20809b000, 0x1000,
0x1000, 0x31d001, 0x0, 0x0)
    /usr/local/Cellar/go/1.3/libexec/src/pkg/net/http/transport.go:1203 +0x72
net/http.(*noteEOFReader).Read(0xc2080f9e00, 0xc20809b000, 0x1000, 0x1000, 0x40, 0x0,
0x0)
    <autogenerated>:124 +0xca
bufio.(*Reader).fill(0xc2080a8b40)
    /usr/local/Cellar/go/1.3/libexec/src/pkg/bufio/bufio.go:97 +0x1b3
bufio.(*Reader).Peek(0xc2080a8b40, 0x1, 0x0, 0x0, 0x0, 0x0, 0x0)
    /usr/local/Cellar/go/1.3/libexec/src/pkg/bufio/bufio.go:132 +0x101
net/http.(*persistConn).readLoop(0xc20821e420)
    /usr/local/Cellar/go/1.3/libexec/src/pkg/net/http/transport.go:782 +0x95
created by net/http.(*Transport).dialConn
    /usr/local/Cellar/go/1.3/libexec/src/pkg/net/http/transport.go:600 +0x93f
exit status 2
}}}

Attachments:

  1. timeout.go (1491 bytes)
  2. output.txt (23179 bytes)
@gopherbot
Copy link
Author

Comment 1 by steinar@plainvanillagames.com:

Related to issue #8209 and issue #6410.

@ianlancetaylor
Copy link
Contributor

Comment 2:

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

@bradfitz
Copy link
Contributor

Comment 3:

Owner changed to @bradfitz.

Status changed to Accepted.

@gopherbot
Copy link
Author

Comment 4:

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

@bradfitz
Copy link
Contributor

Comment 5:

This issue was closed by revision e38fa91.

Status changed to Fixed.

@rsc rsc added this to the Go1.4 milestone Apr 14, 2015
@rsc rsc removed the release-go1.4 label Apr 14, 2015
@golang golang locked and limited conversation to collaborators Jun 25, 2016
wheatman pushed a commit to wheatman/go-akaros that referenced this issue Jun 25, 2018
@bradfitz @wheatman
net/http: fix TimeoutHandler data races; hold lock longer
3a77fd0 
The existing lock needed to be held longer. If a timeout occured
while writing (but after the guarded timeout check), the writes
would clobber a future connection's buffer.

Also remove a harmless warning by making Write also set the
flag that headers were sent (implicitly), so we don't try to
write headers later (a no-op + warning) on timeout after we've
started writing.

Fixes golang#8414
Fixes golang#8209

LGTM=ruiu, adg
R=adg, ruiu
CC=golang-codereviews
https://golang.org/cl/123610043
wheatman pushed a commit to wheatman/go-akaros that referenced this issue Jul 9, 2018
@bradfitz @wheatman
net/http: fix TimeoutHandler data races; hold lock longer
29ab802 
The existing lock needed to be held longer. If a timeout occured
while writing (but after the guarded timeout check), the writes
would clobber a future connection's buffer.

Also remove a harmless warning by making Write also set the
flag that headers were sent (implicitly), so we don't try to
write headers later (a no-op + warning) on timeout after we've
started writing.

Fixes golang#8414
Fixes golang#8209

LGTM=ruiu, adg
R=adg, ruiu
CC=golang-codereviews
https://golang.org/cl/123610043
This issue was closed.
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.4
Development

No branches or pull requests
4 participants
@bradfitz @rsc @ianlancetaylor @gopherbot