net/http: Unrecoverable client panic crashes my program

[dustin]

devel go (tried a few versions):

changeset:   14493:2a8dfbc7b566
tag:         tip
user:        Robert Griesemer <gri@golang.org>
date:        Wed Oct 03 13:46:37 2012 -0700
summary:     go spec: conversion types starting with "func" must be
parenthesized

I have a fairly simple program that copies the body of a GET request into the body of a
PUT request for a bunch of URLs in a loop.  It runs fine for a few or ten thousand, but
consistently crashes as shown at the bottom of this report.

The code I'm running is https://gist.github.com/3822449 -- it uses some data I've got
publicly available and a server I wrote in go that's not entirely trivial to get running
(pretty close to it), but I suspect that's not an important detail.  For this code path,
it's basically http PUT and an io.Copy to the filesystem.


The really nasty part here, as far as I can tell, is that I can't seem to do anything
about it.  I tried adding a recover around where I use the http client, but it's not
"from" my code, so I couldn't trap it.  This is rather catastrophic for my app
(though I remain hopeful it's a dumb bug in my code).


2012/10/03 14:19:10 Unsolicited response received on idle HTTP channel starting 
with "H"; err=<nil>
panic: http: unexpected bodyEOFSignal Read after Close; see issue #1725

goroutine 60 [running]:
net/http.(*bodyEOFSignal).Read(0xf8401c08a0, 0xf840340000, 0x800000008000, 0x389
0, 0x0, ...)
        /Users/dustin/prog/eprojects/go/src/pkg/net/http/transport.go:826 +0xbb
io.(*multiReader).Read(0xf8406548d0, 0xf840340000, 0x800000008000, 0xf8000005a8,
 0x0, ...)
        /Users/dustin/prog/eprojects/go/src/pkg/io/multi.go:13 +0x85
io.Copy(0xf8400d11e0, 0xf840654910, 0xf8400d1180, 0xf8406548d0, 0x485a46, ...)
        /Users/dustin/prog/eprojects/go/src/pkg/io/io.go:360 +0x1a8
net/http.(*transferWriter).WriteBody(0xf840129600, 0xf8400cd000, 0xf84006ea40, 0
x0, 0x0, ...)
        /Users/dustin/prog/eprojects/go/src/pkg/net/http/transfer.go:194 +0x1a1
net/http.(*Request).write(0xf840233000, 0xf8400cd000, 0xf84006ea40, 0x0, 0xf8404
936c0, ...)
        /Users/dustin/prog/eprojects/go/src/pkg/net/http/request.go:371 +0x820
net/http.(*persistConn).writeLoop(0xf840154b80, 0x0)
        /Users/dustin/prog/eprojects/go/src/pkg/net/http/transport.go:660 +0x1b6
created by net/http.(*Transport).getConn
        /Users/dustin/prog/eprojects/go/src/pkg/net/http/transport.go:408 +0x5d6

[dustin]

Comment 1:

I pasted the wrong gist into the email.  Apologies:  https://gist.github.com/3831133

[bradfitz]

Comment 2:

Labels changed: removed priority-triage.

Owner changed to @bradfitz.

Status changed to Accepted.

[dustin]

Comment 3:

I've been having a lot of trouble trying to reproduce this in isolation.  I thought it
could be because of the socket timeouts (though I have no evidence that this is
occurring), but if I write a test that does tons of HTTP requests in tight loops that
are all timing out, it seems to do the right thing.
I thought it might be something related to fetching the data from wikipedia itself, but
I ran a test doing just that for hours yesterday and never saw as much as the
unsolicited response warning (which I get occasionally even without a corresponding
crash).
In the meantime, I've disabled the timeout handling on my client that's got it. 
Sometimes my process crashes within fifteen minutes, and sometimes it runs for three or
four hours.  It'll be a while before I have confidence that that makes a difference.
However, if it does, the way I was using it was very specific.  I had a type that holds
the underlying connection to an http server and sets the read timeout forward on every
read.  As far as I can tell, that had a pretty constant stream of data on that one
connection, and it's code I've been running continuously for months.
The rest of the connections are using an unmodified default client as seen in the gist. 
I can't tell what the clients that are leading to the panic were connected to.

[bradfitz]

Comment 4:

If you get me a self-contained client & server repro I will prioritize fixing this, but
it's not even obvious what the problem is.
Using a custom dialer and custom net.Conns that mess with read timeouts at least gives
me an excuse to point the blame finger at you, but I'm perfectly willing to believe it's
my fault too, but I'm not sure exactly what to look for.  I have enough free time at the
moment to fix something, but not to investigate.

[dustin]

Comment 5:

If it's the timeout that's causing the issue, then it's related to issue #3362 in that it
may be happening as an attempt to work around this.  I do wish it to be my fault, but
I'm not sure how else I can do this.
func (tc *timeoutClient) Read(p []byte) (n int, err error) {
    if tc.readTimeout > 0 {
        tc.socket.SetReadDeadline(time.Now().Add(tc.readTimeout))
    }
    return tc.body.Read(p)
}
At 0, I don't see any evidence that things are going wrong (again, it would run for
hours, though).
I've been trying pretty hard to abuse this.  My latest attempt crashed OS X and deleted
my source (need to stop writing things in /tmp).
I'll continue to work towards a repro assuming it's related to the above.

[dustin]

Comment 6:

I'm fairly certain the problem here is that I'm closing the body when the connection
times out.  This is definitely wrong and would explain why I haven't been able to
reproduce this in isolation.
Let's just call this my fault until I prove otherwise.
I do wish I had another star to offer issue #3362, though.  :)

[bradfitz]

Comment 7:

It's still a bug that the transport should never panic the whole program.  That needs to
be fixed regardless.
Even if you find it to be "your fault", please help me repro this.  If it's your timeout
code + closing before timeout, please replicate that combination in a nice little
bradsucks.go file and I'll fix the panic at least, even if the code isn't what one
should do.

[rsc]

Comment 8:

Labels changed: added go1.1.

[bradfitz]

Comment 9:

Related race:
http://build.golang.org/log/61e43a328fb220801d3d5c88cd91916cfc5dc43c

[davecheney]

Comment 10:

https://golang.org/cl/6640057/

[dustin]

Comment 11:

I just crashed my mac a second time trying to do a clean repro of this.  This does sound
like the kind of thing I was doing, though.  Pretty sure I was reading from a socket
that had timed out while I was blocked on something else.

[dustin]

Comment 12:

I updated to tip (after seeing that new change come in) and got this today:
changeset:   14611:57736947de5a
tag:         tip
user:        Dave Cheney <dave@cheney.net>
date:        Fri Oct 12 09:17:56 2012 +1100
summary:     net/http: fix data race on countReader.n
  This is on FreeBSD (the previous one was Mac).   Same program, but 
goroutine 501870 [running]:
net/http.(*bodyEOFSignal).Read(0xf8406d45a0, 0xf8406df000, 0x8000, 0x8000, 0x5a8
, ...)
        /Users/dustin/prog/eprojects/go/src/pkg/net/http/transport.go:827 +0xcc
io.(*multiReader).Read(0xf840118380, 0xf8406df000, 0x8000, 0x8000, 0x5a8, ...)
        /Users/dustin/prog/eprojects/go/src/pkg/io/multi.go:13 +0x92
io.Copy(0xf840145480, 0xf840573d60, 0xf8401450f0, 0xf840118380, 0xe92878, ...)
        /Users/dustin/prog/eprojects/go/src/pkg/io/io.go:360 +0x1a9
net/http.(*transferWriter).WriteBody(0xf8402dc9a0, 0xf8400cac00, 0xf8405c7c80, 0
x0, 0x0, ...)
        /Users/dustin/prog/eprojects/go/src/pkg/net/http/transfer.go:194 +0x1c6
net/http.(*Request).write(0xf8405d9820, 0xf8400cac00, 0xf8405c7c80, 0x0, 0xf8401
18680, ...)
        /Users/dustin/prog/eprojects/go/src/pkg/net/http/request.go:371 +0x833
net/http.(*persistConn).writeLoop(0xf840162f00, 0x0)
        /Users/dustin/prog/eprojects/go/src/pkg/net/http/transport.go:661 +0x1b8
created by net/http.(*Transport).getConn
        /Users/dustin/prog/eprojects/go/src/pkg/net/http/transport.go:409 +0x5cd
The problem does go away if I disable my timeout, but I've still not reproduced it
outside of this thing without crashing a machine.  Part of that is likely in trying to
make it happen too fast.
...which is odd, because the timeout is straightforward.  Socket has a deadline on read.
 I am most likely not reading from the body soon enough (due to processing of stuff
coming off of it) and when I go back to read from it, it breaks.  This happened after
about 800,000 articles and who knows how many images I pulled from them today.  It was
several hours.

[dustin]

Comment 13:

Sorry, again not a repro, but I did capture the full stack this time and wanted to get
it included in the report just in case there's something useful here.
Note that I'm still running the build from the previous changeset and I've disabled part
of my timeout logic (the one I was suspect of).  This means the remaining timeouts are
on the GET side and the PUT side of an individual request.  I'd be most suspicious at
this point of the read timeout on a PUT request.  I will start going down this path for
repro now (notice this one happened almost exactly 24 hours into a run).
[comment is too long...  http://pastebin.com/djEpGLpR ]

[dustin]

Comment 14:

OK, using that last bit of info, I have a repro:  http://play.golang.org/p/VNx9D1u4tX
This breaks in a really weird way.  It does the right thing twice, hangs consuming lots
of CPU for a while and then panics:
2012/10/13 12:39:28 Error doing the thing: read tcp 127.0.0.1:62331: i/o timeout
2012/10/13 12:39:28 put: copied 8036337 bytes before http: suspiciously long trailer
after chunked body
2012/10/13 12:39:30 Error doing the thing: read tcp 127.0.0.1:62331: i/o timeout
2012/10/13 12:39:30 put: copied 8355840 bytes before http: suspiciously long trailer
after chunked body
2012/10/13 12:41:57 Error doing the thing: read tcp 127.0.0.1:62331: i/o timeout
panic: http: unexpected bodyEOFSignal Read after Close; see issue #1725
goroutine 28 [running]:
net/http.(*bodyEOFSignal).Read(0xf8400ca120, 0xf8401a0000, 0x8000, 0x8000, 0x7008, ...)
    /Users/dustin/prog/eprojects/go/src/pkg/net/http/transport.go:827 +0xcc
io.(*multiReader).Read(0xf840076a40, 0xf8401a0000, 0x8000, 0x8000, 0xff8, ...)
    /Users/dustin/prog/eprojects/go/src/pkg/io/multi.go:13 +0x92
io.Copy(0xf8400cad50, 0xf8401859f0, 0xf8400cacc0, 0xf840076a40, 0x838ff8, ...)
    /Users/dustin/prog/eprojects/go/src/pkg/io/io.go:360 +0x1a9
net/http.(*transferWriter).WriteBody(0xf840125460, 0xf8400ca0f0, 0xf840186bc0, 0x0, 0x0,
...)
    /Users/dustin/prog/eprojects/go/src/pkg/net/http/transfer.go:194 +0x1c6
net/http.(*Request).write(0xf8400d7ea0, 0xf8400ca0f0, 0xf840186bc0, 0x0, 0xf8400f2420,
...)
    /Users/dustin/prog/eprojects/go/src/pkg/net/http/request.go:371 +0x833
net/http.(*persistConn).writeLoop(0xf840126400, 0x0)
    /Users/dustin/prog/eprojects/go/src/pkg/net/http/transport.go:661 +0x1b8
created by net/http.(*Transport).getConn
    /Users/dustin/prog/eprojects/go/src/pkg/net/http/transport.go:409 +0x5cd

[dustin]

Comment 15:

(quick note, disabling keepalive doesn't have an effect -- I'm going to go off and do
something else now and stop annoying those watching this bug)