net/http: segfault in bufio

[randall77]

Happens only a few percent of the time.  Looks like the b.rd field is nil.

env GOARCH=386 ./make.bash
env GOARCH=386 ../bin/go test -c net/http
cd pkg/net/http
env GOMAXPROCS=4 ../../../http.test -test.short

panic: runtime error: invalid memory address or nil pointer dereference
[signal 0xb code=0x1 addr=0x1 pc=0x8168594]

goroutine 748 [running]:
runtime.panic(0x82e0d20, 0x86c2c28)
    /usr/local/google/home/khr/sandbox/go-issue7083/src/pkg/runtime/panic.c:264 +0xac
bufio.(*Reader).Read(0x18cd1510, 0x18b0e000, 0x1000, 0x1000, 0x1000, ...)
    /usr/local/google/home/khr/sandbox/go-issue7083/src/pkg/bufio/bufio.go:152 +0xc4
net/http.(*chunkedReader).Read(0x18bce9c0, 0x18b0e000, 0x1000, 0x1000, 0x18af6808, ...)
    /usr/local/google/home/khr/sandbox/go-issue7083/src/pkg/net/http/chunked.go:73 +0x10f
net/http.(*body).readLocked(0x18c38930, 0x18b0e000, 0x1000, 0x1000, 0x0, ...)
    /usr/local/google/home/khr/sandbox/go-issue7083/src/pkg/net/http/transfer.go:544 +0x58
net/http.(*body).Read(0x18c38930, 0x18b0e000, 0x1000, 0x1000, 0x0, ...)
    /usr/local/google/home/khr/sandbox/go-issue7083/src/pkg/net/http/transfer.go:539 +0xcb
io.(*LimitedReader).Read(0x18b57fb0, 0x18b0e000, 0x1000, 0x1000, 0xf8c, ...)
    /usr/local/google/home/khr/sandbox/go-issue7083/src/pkg/io/io.go:398 +0xc4
bufio.(*Writer).ReadFrom(0x18bcecc0, 0xf779c698, 0x18b57fb0, 0x84f85, 0x0, ...)
    /usr/local/google/home/khr/sandbox/go-issue7083/src/pkg/bufio/bufio.go:622 +0x139
io.Copy(0xf779de20, 0x18bcecc0, 0xf779c698, 0x18b57fb0, 0x0, ...)
    /usr/local/google/home/khr/sandbox/go-issue7083/src/pkg/io/io.go:348 +0xe7
net/http.(*transferWriter).WriteBody(0x18ca09c0, 0xf779de20, 0x18bcecc0, 0x0, 0x0)
    /usr/local/google/home/khr/sandbox/go-issue7083/src/pkg/net/http/transfer.go:197 +0x50d
net/http.(*Request).write(0x18a5c2a0, 0xf779de20, 0x18bcecc0, 0x18a6f900, 0x18c2cf60,
...)
    /usr/local/google/home/khr/sandbox/go-issue7083/src/pkg/net/http/request.go:401 +0x697
net/http.(*persistConn).writeLoop(0x18c2d6e0)
    /usr/local/google/home/khr/sandbox/go-issue7083/src/pkg/net/http/transport.go:797 +0x163
created by net/http.(*Transport).dialConn
    /usr/local/google/home/khr/sandbox/go-issue7083/src/pkg/net/http/transport.go:529 +0x553

I suspect net/http/server.go:putBufioReader, it's the only one that clears the rd field.
 If I comment out the body of this function, the bug goes away.

Perhaps someone is still using the bufio.Reader when it is put in the pool?  Ah, the
dangers of manual memory management...

Seems to happen only in 32 bit and with GOMAXPROCS>1.  Why?  I have no idea.

[bradfitz]

Comment 1:

This code is not new, though. I'm pretty confident in it.
If it only happens in 32 bit and not 64 bit, that suggests something
runtime/compiler-related, no?

[dvyukov]

Comment 2:

Note that the address is not nil, it's addr=0x1
Keith, please disassemble the binary and check what exactly is accessed at pc=0x8168594
There is another issue about random episodic 386 builder crashes...

[randall77]

Comment 3:

But it isn't 1, it's actually nil.  That is, you can patch src/pkg/bufio/bufio.go and
add before line 152 the code
  if b.rd == nil {
    panic("b.rd is nil!")
  }
it will trigger.
I don't know how the runtime comes up with addr=0x1.  The actual instruction that faults
is:
  mov 0x14(%ecx),%ebx
where %ecx is loaded from the itab slot of the nil b.rd.  So addr should be 0x14.

[randall77]

Comment 4:

It gets the right address on arm...
panic: runtime error: invalid memory address or nil pointer dereference
[signal 0xb code=0x1 addr=0x14 pc=0x1683d0]
goroutine 749 [running]:
runtime.panic(0x2e8920, 0x6ab3b0)
    /tmp/gobuilder/linux-arm-luitvd-9d797d0b899b/go/src/pkg/runtime/panic.c:264 +0x134
bufio.(*Reader).Read(0x11062270, 0x10a8b000, 0x1000, 0x1000, 0x1000, ...)
    /tmp/gobuilder/linux-arm-luitvd-9d797d0b899b/go/src/pkg/bufio/bufio.go:152 +0x12c
net/http.(*chunkedReader).Read(0x10ca9c60, 0x10a8b000, 0x1000, 0x1000, 0x4, ...)
    /tmp/gobuilder/linux-arm-luitvd-9d797d0b899b/go/src/pkg/net/http/chunked.go:73 +0x16c
net/http.(*body).readLocked(0x11062660, 0x10a8b000, 0x1000, 0x1000, 0x0, ...)
    /tmp/gobuilder/linux-arm-luitvd-9d797d0b899b/go/src/pkg/net/http/transfer.go:544 +0x74
net/http.(*body).Read(0x11062660, 0x10a8b000, 0x1000, 0x1000, 0x0, ...)
    /tmp/gobuilder/linux-arm-luitvd-9d797d0b899b/go/src/pkg/net/http/transfer.go:539 +0x10c
io.(*LimitedReader).Read(0x10f33590, 0x10a8b000, 0x1000, 0x1000, 0xf84, ...)
    /tmp/gobuilder/linux-arm-luitvd-9d797d0b899b/go/src/pkg/io/io.go:398 +0x130
bufio.(*Writer).ReadFrom(0x10c9ce20, 0xb6def6a0, 0x10f33590, 0x80f85, 0x0, ...)
    /tmp/gobuilder/linux-arm-luitvd-9d797d0b899b/go/src/pkg/bufio/bufio.go:622 +0x1a0
io.Copy(0xb6df0ea8, 0x10c9ce20, 0xb6def6a0, 0x10f33590, 0x0, ...)
    /tmp/gobuilder/linux-arm-luitvd-9d797d0b899b/go/src/pkg/io/io.go:348 +0x120
net/http.(*transferWriter).WriteBody(0x10ab5940, 0xb6df0ea8, 0x10c9ce20, 0x0, 0x0)
    /tmp/gobuilder/linux-arm-luitvd-9d797d0b899b/go/src/pkg/net/http/transfer.go:197 +0x63c
net/http.(*Request).write(0x10b85460, 0xb6df0ea8, 0x10c9ce20, 0x0, 0x10c9ce80, ...)
    /tmp/gobuilder/linux-arm-luitvd-9d797d0b899b/go/src/pkg/net/http/request.go:401 +0x730
net/http.(*persistConn).writeLoop(0x10b90c80)
    /tmp/gobuilder/linux-arm-luitvd-9d797d0b899b/go/src/pkg/net/http/transport.go:797 +0x194
created by net/http.(*Transport).dialConn
    /tmp/gobuilder/linux-arm-luitvd-9d797d0b899b/go/src/pkg/net/http/transport.go:529 +0x604

[randall77]

Comment 5:

I think this is a bug in net/http.  CL 50760043 triggers every few runs for me.  Someone
is using the bufio.Reader after putBufioReader is called.
I did get it to fail on 64 bit.  Seems to happen less often for some reason.
panic: bufio.Read from trashed Reader
goroutine 749 [running]:
runtime.panic(0x8283540, 0x18fb8ed0)
    /usr/local/google/home/khr/sandbox/go-issue7092/src/pkg/runtime/panic.c:264 +0xac
bufio.(*Reader).Read(0x18b12ed0, 0x18b8e000, 0x1000, 0x1000, 0x18b2a73c, ...)
    /usr/local/google/home/khr/sandbox/go-issue7092/src/pkg/bufio/bufio.go:143 +0x78
net/http.(*chunkedReader).Read(0x18af7760, 0x18b8e000, 0x1000, 0x1000, 0x18a90008, ...)
    /usr/local/google/home/khr/sandbox/go-issue7092/src/pkg/net/http/chunked.go:73 +0x10f
net/http.(*body).readLocked(0x18b2a720, 0x18b8e000, 0x1000, 0x1000, 0x0, ...)
    /usr/local/google/home/khr/sandbox/go-issue7092/src/pkg/net/http/transfer.go:544 +0x58
net/http.(*body).Read(0x18b2a720, 0x18b8e000, 0x1000, 0x1000, 0x0, ...)
    /usr/local/google/home/khr/sandbox/go-issue7092/src/pkg/net/http/transfer.go:539 +0xcb
io.(*LimitedReader).Read(0x19008550, 0x18b8e000, 0x1000, 0x1000, 0xf8c, ...)
    /usr/local/google/home/khr/sandbox/go-issue7092/src/pkg/io/io.go:398 +0xc4
bufio.(*Writer).ReadFrom(0x1910e340, 0xf77cb6f8, 0x19008550, 0x83f85, 0x0, ...)
    /usr/local/google/home/khr/sandbox/go-issue7092/src/pkg/bufio/bufio.go:626 +0x139
io.Copy(0xf77cce90, 0x1910e340, 0xf77cb6f8, 0x19008550, 0x0, ...)
    /usr/local/google/home/khr/sandbox/go-issue7092/src/pkg/io/io.go:348 +0xe7
net/http.(*transferWriter).WriteBody(0x18c1bc00, 0xf77cce90, 0x1910e340, 0x0, 0x0)
    /usr/local/google/home/khr/sandbox/go-issue7092/src/pkg/net/http/transfer.go:197 +0x50d
net/http.(*Request).write(0x18bd00e0, 0xf77cce90, 0x1910e340, 0x808a200, 0x18af7b00, ...)
    /usr/local/google/home/khr/sandbox/go-issue7092/src/pkg/net/http/request.go:401 +0x697
net/http.(*persistConn).writeLoop(0x18bd79b0)
    /usr/local/google/home/khr/sandbox/go-issue7092/src/pkg/net/http/transport.go:797 +0x163
created by net/http.(*Transport).dialConn
    /usr/local/google/home/khr/sandbox/go-issue7092/src/pkg/net/http/transport.go:529 +0x553
panic: bufio.Read from trashed Reader
goroutine 749 [running]:
runtime.panic(0x6c51c0, 0xc210632380)
    /usr/local/google/home/khr/sandbox/go-issue7092/src/pkg/runtime/panic.c:264 +0xb6
bufio.(*Reader).Read(0xc21030f360, 0xc210f85000, 0x1000, 0x1000, 0xc21091fbf0, ...)
    /usr/local/google/home/khr/sandbox/go-issue7092/src/pkg/bufio/bufio.go:143 +0xa8
net/http.(*chunkedReader).Read(0xc2107b3720, 0xc210f85000, 0x1000, 0x1000, 0xc2101d9010,
...)
    /usr/local/google/home/khr/sandbox/go-issue7092/src/pkg/net/http/chunked.go:73 +0x168
net/http.(*body).readLocked(0xc21091fbc0, 0xc210f85000, 0x1000, 0x1000, 0x0, ...)
    /usr/local/google/home/khr/sandbox/go-issue7092/src/pkg/net/http/transfer.go:544 +0x64
net/http.(*body).Read(0xc21091fbc0, 0xc210f85000, 0x1000, 0x1000, 0x0, ...)
    /usr/local/google/home/khr/sandbox/go-issue7092/src/pkg/net/http/transfer.go:539 +0xe7
io.(*LimitedReader).Read(0xc210920c40, 0xc210f85000, 0x1000, 0x1000, 0x8e, ...)
    /usr/local/google/home/khr/sandbox/go-issue7092/src/pkg/io/io.go:398 +0xc6
bufio.(*Writer).ReadFrom(0xc21091f040, 0x7fd849e8cbe8, 0xc210920c40, 0x82f85, 0x0, ...)
    /usr/local/google/home/khr/sandbox/go-issue7092/src/pkg/bufio/bufio.go:626 +0x16e
io.Copy(0x7fd849e8ea48, 0xc21091f040, 0x7fd849e8cbe8, 0xc210920c40, 0x0, ...)
    /usr/local/google/home/khr/sandbox/go-issue7092/src/pkg/io/io.go:348 +0x124
net/http.(*transferWriter).WriteBody(0xc21052e620, 0x7fd849e8ea48, 0xc21091f040, 0x0,
0x0)
    /usr/local/google/home/khr/sandbox/go-issue7092/src/pkg/net/http/transfer.go:197 +0x60e
net/http.(*Request).write(0xc210048270, 0x7fd849e8ea48, 0xc21091f040, 0x405c00,
0xc2107e59c0, ...)
    /usr/local/google/home/khr/sandbox/go-issue7092/src/pkg/net/http/request.go:401 +0x88d
net/http.(*persistConn).writeLoop(0xc2107a7f80)
    /usr/local/google/home/khr/sandbox/go-issue7092/src/pkg/net/http/transport.go:797 +0x1c7
created by net/http.(*Transport).dialConn
    /usr/local/google/home/khr/sandbox/go-issue7092/src/pkg/net/http/transport.go:529 +0x6ad

[bradfitz]

Comment 6:

Quick repro, even in Linux/amd64 any GOMAXPROCS...
$ while ./http.test -test.v  -test.short -test.cpu=8,8,8,8
-test.run=TestTransportAndServerSharedBodyRace; do true; done
The TestTransportAndServerSharedBodyRace test was added last week and tests the case of
a server passing off its Request.Body to the HTTP client.
That new test is exposing yet another bug in this same area. The assumption that the
server owned the Request.Body exclusively was wrong.
Will fix.

Status changed to Accepted.

[bradfitz]

Comment 7:

Sent https://golang.org/cl/51700043/

Status changed to Started.

[bradfitz]

Comment 8:

*** Submitted as https://code.google.com/p/go/source/detail?r=51a204237ba5 ***

Status changed to Fixed.