net/http: panic when reading request body

[gopherbot]

by dimitrij.denissenko@blacksquaremedia.com:

What does 'go version' print?

go version go1.2 linux/amd64

What happened?

In my http server, I am trying to read the http.Request.Body via
ioutil.ReadAll(req.Body). Rarely, it causes an unexpected panic:

panic: runtime error: invalid memory address or nil pointer dereference [recovered]
    panic: runtime error: invalid memory address or nil pointer dereference
[signal 0xb code=0x1 addr=0x20 pc=0x5e65ca]
goroutine 1918503 [running]:
runtime.panic(0x7c3560, 0xd59d88)
  /home/user/.gvm/gos/go1.2/src/pkg/runtime/panic.c:266 +0xb6
io/ioutil.func·001()
  /home/user/.gvm/gos/go1.2/src/pkg/io/ioutil/ioutil.go:29 +0xf0
runtime.panic(0x7c3560, 0xd59d88)
  /home/user/.gvm/gos/go1.2/src/pkg/runtime/panic.c:248 +0x106
bufio.(*Reader).fill(0xc2101b1c00)
  /home/user/.gvm/gos/go1.2/src/pkg/bufio/bufio.go:91 +0x10a
bufio.(*Reader).Read(0xc2101b1c00, 0xc2119bde00, 0x1e5, 0x200, 0x1e5, ...)
  /home/user/.gvm/gos/go1.2/src/pkg/bufio/bufio.go:159 +0x1a4
io.(*LimitedReader).Read(0xc2107532e0, 0xc2119bde00, 0x200, 0x200, 0xc2119bde00, ...)
  /home/user/.gvm/gos/go1.2/src/pkg/io/io.go:398 +0xbb
net/http.(*body).Read(0xc2109ee4e0, 0xc2119bde00, 0x200, 0x200, 0x1, ...)
  /home/user/.gvm/gos/go1.2/src/pkg/net/http/transfer.go:534 +0x96
bytes.(*Buffer).ReadFrom(0xc21344b1c0, 0x7fe124670ee0, 0xc2109ee4e0, 0x0, 0x0, ...)
  /home/user/.gvm/gos/go1.2/src/pkg/bytes/buffer.go:169 +0x1f7
io/ioutil.readAll(0x7fe124670ee0, 0xc2109ee4e0, 0x200, 0x0, 0x0, ...)
  /home/user/.gvm/gos/go1.2/src/pkg/io/ioutil/ioutil.go:32 +0x156
io/ioutil.ReadAll(0x7fe124670ee0, 0xc2109ee4e0, 0x5320e1b2, 0x2a5129fd, 0x48349e, ...)
  /home/user/.gvm/gos/go1.2/src/pkg/io/ioutil/ioutil.go:41 +0x3f

What should have happened instead?

The documentation http://golang.org/src/pkg/net/http/request.go?#L114 suggests that a
server body must never be nil.

[davecheney]

Comment 1:

Can you please provide a code sample which demonstrates this issue.
Could you also attach the entire panic message from the issue report above.

Status changed to WaitingForReply.

[gopherbot]

Comment 2 by dimitrij.denissenko@blacksquaremedia.com:

Unfortunately there are limitations to what I can expose as it is a proprietary client
app, but please see a different panic message from the same app. There are dozens of
goroutines, so I have copied the first few as all the others are in a runnable state.
Here is the code which causes this is:
// proprietary.com/client/app/protocol.ParseRequest
func ParseRequest(reader io.Reader) ... {
  dec := json.NewDecoder(reader)
  if err = dec.Decode(&req); err != nil {
    return nil, err
  }
  ...
}
// proprietary.com/client/app.(*Parser).Parse
func (p *Parser) Parse(rd io.Reader) .... {
  req, err := protocol.ParseRequest(rd)
  ...
}
// proprietary.com/client/app.(*Mux).Handle
func (m *Mux) Handle(w http.ResponseWriter, req *http.Request) {
  data, err := DefaultParser.Parse(req.Body)
  ...
}
The panic message:
panic: runtime error: invalid memory address or nil pointer dereference
[signal 0xb code=0x1 addr=0x20 pc=0x5e65ca]
goroutine 8761184 [running]:
runtime.panic(0x7c3560, 0xd59d88)
        /home/user/.gvm/gos/go1.2/src/pkg/runtime/panic.c:266 +0xb6
bufio.(*Reader).fill(0xc211a1c000)
        /home/user/.gvm/gos/go1.2/src/pkg/bufio/bufio.go:91 +0x10a
bufio.(*Reader).Read(0xc211a1c000, 0xc210a86000, 0x200, 0x200, 0x200, ...)
        /home/user/.gvm/gos/go1.2/src/pkg/bufio/bufio.go:159 +0x1a4
io.(*LimitedReader).Read(0xc2144bdae0, 0xc210a86000, 0x200, 0x200, 0x200, ...)
        /home/user/.gvm/gos/go1.2/src/pkg/io/io.go:398 +0xbb
net/http.(*body).Read(0xc210ab4a80, 0xc210a86000, 0x200, 0x200, 0x0, ...)
        /home/user/.gvm/gos/go1.2/src/pkg/net/http/transfer.go:534 +0x96
encoding/json.(*Decoder).readValue(0xc215022c40, 0x8, 0xc21196d900, 0xba)
        /home/user/.gvm/gos/go1.2/src/pkg/encoding/json/stream.go:124 +0x4af
encoding/json.(*Decoder).Decode(0xc215022c40, 0x6d6760, 0xc210261628, 0x14e6413c,
0x42723e)
        /home/user/.gvm/gos/go1.2/src/pkg/encoding/json/stream.go:44 +0x57
proprietary.com/client/app/protocol.ParseRequest(0x7ff17152a0e0, 0xc210ab4a80,
0xc200000000, 0x0, 0x0)
        /home/user/app/releases/20140312144700/_vendor/src/proprietary.com/client/app/protocol/request.go:34 +0xb0
proprietary.com/client/app.(*Parser).Parse(0xd580e0, 0x7ff17152a0e0, 0xc210ab4a80,
0xc2102606c0, 0x0, ...)
        /home/user/app/releases/20140312144700/src/proprietary.com/client/app/parser.go:133 +0xc2
proprietary.com/client/app.(*Mux).Handle(0xc210000ab0, 0x7ff179ba4e50, 0xc2144bdb00,
0xc2155a1c30, 0x7ff179b9d758, ...)
        /home/user/app/releases/20140312144700/src/proprietary.com/client/app/mux.go:128 +0x270
proprietary.com/client/app.func·008(0x7ff179ba4e50, 0xc2144bdb00, 0xc2155a1c30)
        /home/user/app/releases/20140312144700/src/proprietary.com/client/app/mux.go:792 +0x54
net/http.HandlerFunc.ServeHTTP(0xc2100956e0, 0x7ff179ba4e50, 0xc2144bdb00, 0xc2155a1c30)
        /home/user/.gvm/gos/go1.2/src/pkg/net/http/server.go:1220 +0x40
proprietary.com/client/app/utils.func·002()
        /home/user/app/releases/20140312144700/src/proprietary.com/client/app/utils/timeout.go:27 +0x86
created by proprietary.com/client/app/utils.(*timeoutHandler).ServeHTTP
        /home/user/app/releases/20140312144700/src/proprietary.com/client/app/utils/timeout.go:29 +0x134
goroutine 1 [IO wait]:
net.runtime_pollWait(0x7ff179b9e780, 0x72, 0x0)
        /home/user/.gvm/gos/go1.2/src/pkg/runtime/netpoll.goc:116 +0x6a
net.(*pollDesc).Wait(0xc210097c30, 0x72, 0x7ff179b9d180, 0xb)
        /home/user/.gvm/gos/go1.2/src/pkg/net/fd_poll_runtime.go:81 +0x34
net.(*pollDesc).WaitRead(0xc210097c30, 0xb, 0x7ff179b9d180)
        /home/user/.gvm/gos/go1.2/src/pkg/net/fd_poll_runtime.go:86 +0x30
net.(*netFD).accept(0xc210097bd0, 0x938758, 0x0, 0x7ff179b9d180, 0xb)
        /home/user/.gvm/gos/go1.2/src/pkg/net/fd_unix.go:382 +0x2c2
net.(*UnixListener).AcceptUnix(0xc21010e7a0, 0x4d284b, 0x7ff1799fdcf0, 0x4d284b)
        /home/user/.gvm/gos/go1.2/src/pkg/net/unixsock_posix.go:283 +0x4b
net.(*UnixListener).Accept(0xc21010e7a0, 0x0, 0x0, 0x0, 0x0)
        /home/user/.gvm/gos/go1.2/src/pkg/net/unixsock_posix.go:294 +0x4b
net/http.(*Server).Serve(0xc210099780, 0x7ff179ba43f0, 0xc21010e7a0, 0x0, 0x0)
        /home/user/.gvm/gos/go1.2/src/pkg/net/http/server.go:1622 +0x91
proprietary.com/client/app.(*Mux).ListenAndServe(0xc210000ab0, 0xc210000940, 0x4,
0x7fff18194e9c, 0x15, ...)
        /home/user/app/releases/20140312144700/src/proprietary.com/client/app/mux.go:108 +0x2bb
proprietary.com/client/app.(*app).Run(0xd5fcc0, 0x7fff18194e9c, 0x15, 0x7fff18194e7f,
0x16)
        /home/user/app/releases/20140312144700/src/proprietary.com/client/app/app.go:85 +0x767
main.main()
        /home/user/app/releases/20140312144700/worker/worker.go:17 +0x63
goroutine 3 [syscall]:
os/signal.loop()
        /home/user/.gvm/gos/go1.2/src/pkg/os/signal/signal_unix.go:21 +0x1e
created by os/signal.init·1
        /home/user/.gvm/gos/go1.2/src/pkg/os/signal/signal_unix.go:27 +0x31
goroutine 4 [chan receive]:
github.com/golang/glog.(*loggingT).flushDaemon(0xd5fe00)
        /home/user/app/releases/20140312144700/_vendor/src/github.com/golang/glog/glog.go:839 +0x50
created by github.com/golang/glog.init·1
        /home/user/app/releases/20140312144700/_vendor/src/github.com/golang/glog/glog.go:406 +0x276
goroutine 5 [syscall]:
runtime.goexit()
        /home/user/.gvm/gos/go1.2/src/pkg/runtime/proc.c:1394
goroutine 9 [chan receive]:
database/sql.(*DB).connectionOpener(0xc21004bb00)
        /home/user/.gvm/gos/go1.2/src/pkg/database/sql/sql.go:574 +0x3e
created by database/sql.Open
        /home/user/.gvm/gos/go1.2/src/pkg/database/sql/sql.go:436 +0x24d
goroutine 11 [finalizer wait]:
runtime.park(0x40aa00, 0xd5dc18, 0xd5b8c8)
        /home/user/.gvm/gos/go1.2/src/pkg/runtime/proc.c:1342 +0x66
runfinq()
        /home/user/.gvm/gos/go1.2/src/pkg/runtime/mgc0.c:2276 +0x84
runtime.goexit()
        /home/user/.gvm/gos/go1.2/src/pkg/runtime/proc.c:1394

[gopherbot]

Comment 3 by dimitrij.denissenko@blacksquaremedia.com:

Unfortunately there are limitations to what I can expose as it is a proprietary client
app, but please see a different panic message from the same app. There are dozens of
goroutines, so I have copied the first few as all the others are in a runnable state.
Here is the code which causes this is:
// proprietary.com/client/app.(*Mux).Handle
func (m *Mux) Handle(w http.ResponseWriter, req *http.Request) {
  data, err := DefaultParser.Parse(req.Body)
  ...
}
// proprietary.com/client/app.(*Parser).Parse
func (p *Parser) Parse(rd io.Reader) .... {
  req, err := protocol.ParseRequest(rd)
  ...
}
// proprietary.com/client/app/protocol.ParseRequest
func ParseRequest(reader io.Reader) ... {
  dec := json.NewDecoder(reader)
  if err = dec.Decode(&req); err != nil { // -> PANIC (see below)
    return nil, err
  }
  ...
}
The panic message:
panic: runtime error: invalid memory address or nil pointer dereference
[signal 0xb code=0x1 addr=0x20 pc=0x5e65ca]
goroutine 8761184 [running]:
runtime.panic(0x7c3560, 0xd59d88)
        /home/user/.gvm/gos/go1.2/src/pkg/runtime/panic.c:266 +0xb6
bufio.(*Reader).fill(0xc211a1c000)
        /home/user/.gvm/gos/go1.2/src/pkg/bufio/bufio.go:91 +0x10a
bufio.(*Reader).Read(0xc211a1c000, 0xc210a86000, 0x200, 0x200, 0x200, ...)
        /home/user/.gvm/gos/go1.2/src/pkg/bufio/bufio.go:159 +0x1a4
io.(*LimitedReader).Read(0xc2144bdae0, 0xc210a86000, 0x200, 0x200, 0x200, ...)
        /home/user/.gvm/gos/go1.2/src/pkg/io/io.go:398 +0xbb
net/http.(*body).Read(0xc210ab4a80, 0xc210a86000, 0x200, 0x200, 0x0, ...)
        /home/user/.gvm/gos/go1.2/src/pkg/net/http/transfer.go:534 +0x96
encoding/json.(*Decoder).readValue(0xc215022c40, 0x8, 0xc21196d900, 0xba)
        /home/user/.gvm/gos/go1.2/src/pkg/encoding/json/stream.go:124 +0x4af
encoding/json.(*Decoder).Decode(0xc215022c40, 0x6d6760, 0xc210261628, 0x14e6413c,
0x42723e)
        /home/user/.gvm/gos/go1.2/src/pkg/encoding/json/stream.go:44 +0x57
proprietary.com/client/app/protocol.ParseRequest(0x7ff17152a0e0, 0xc210ab4a80,
0xc200000000, 0x0, 0x0)
        /home/user/app/releases/20140312144700/_vendor/src/proprietary.com/client/app/protocol/request.go:34 +0xb0
proprietary.com/client/app.(*Parser).Parse(0xd580e0, 0x7ff17152a0e0, 0xc210ab4a80,
0xc2102606c0, 0x0, ...)
        /home/user/app/releases/20140312144700/src/proprietary.com/client/app/parser.go:133 +0xc2
proprietary.com/client/app.(*Mux).Handle(0xc210000ab0, 0x7ff179ba4e50, 0xc2144bdb00,
0xc2155a1c30, 0x7ff179b9d758, ...)
        /home/user/app/releases/20140312144700/src/proprietary.com/client/app/mux.go:128 +0x270
proprietary.com/client/app.func·008(0x7ff179ba4e50, 0xc2144bdb00, 0xc2155a1c30)
        /home/user/app/releases/20140312144700/src/proprietary.com/client/app/mux.go:792 +0x54
net/http.HandlerFunc.ServeHTTP(0xc2100956e0, 0x7ff179ba4e50, 0xc2144bdb00, 0xc2155a1c30)
        /home/user/.gvm/gos/go1.2/src/pkg/net/http/server.go:1220 +0x40
proprietary.com/client/app/utils.func·002()
        /home/user/app/releases/20140312144700/src/proprietary.com/client/app/utils/timeout.go:27 +0x86
created by proprietary.com/client/app/utils.(*timeoutHandler).ServeHTTP
        /home/user/app/releases/20140312144700/src/proprietary.com/client/app/utils/timeout.go:29 +0x134
goroutine 1 [IO wait]:
net.runtime_pollWait(0x7ff179b9e780, 0x72, 0x0)
        /home/user/.gvm/gos/go1.2/src/pkg/runtime/netpoll.goc:116 +0x6a
net.(*pollDesc).Wait(0xc210097c30, 0x72, 0x7ff179b9d180, 0xb)
        /home/user/.gvm/gos/go1.2/src/pkg/net/fd_poll_runtime.go:81 +0x34
net.(*pollDesc).WaitRead(0xc210097c30, 0xb, 0x7ff179b9d180)
        /home/user/.gvm/gos/go1.2/src/pkg/net/fd_poll_runtime.go:86 +0x30
net.(*netFD).accept(0xc210097bd0, 0x938758, 0x0, 0x7ff179b9d180, 0xb)
        /home/user/.gvm/gos/go1.2/src/pkg/net/fd_unix.go:382 +0x2c2
net.(*UnixListener).AcceptUnix(0xc21010e7a0, 0x4d284b, 0x7ff1799fdcf0, 0x4d284b)
        /home/user/.gvm/gos/go1.2/src/pkg/net/unixsock_posix.go:283 +0x4b
net.(*UnixListener).Accept(0xc21010e7a0, 0x0, 0x0, 0x0, 0x0)
        /home/user/.gvm/gos/go1.2/src/pkg/net/unixsock_posix.go:294 +0x4b
net/http.(*Server).Serve(0xc210099780, 0x7ff179ba43f0, 0xc21010e7a0, 0x0, 0x0)
        /home/user/.gvm/gos/go1.2/src/pkg/net/http/server.go:1622 +0x91
proprietary.com/client/app.(*Mux).ListenAndServe(0xc210000ab0, 0xc210000940, 0x4,
0x7fff18194e9c, 0x15, ...)
        /home/user/app/releases/20140312144700/src/proprietary.com/client/app/mux.go:108 +0x2bb
proprietary.com/client/app.(*app).Run(0xd5fcc0, 0x7fff18194e9c, 0x15, 0x7fff18194e7f,
0x16)
        /home/user/app/releases/20140312144700/src/proprietary.com/client/app/app.go:85 +0x767
main.main()
        /home/user/app/releases/20140312144700/worker/worker.go:17 +0x63
goroutine 3 [syscall]:
os/signal.loop()
        /home/user/.gvm/gos/go1.2/src/pkg/os/signal/signal_unix.go:21 +0x1e
created by os/signal.init·1
        /home/user/.gvm/gos/go1.2/src/pkg/os/signal/signal_unix.go:27 +0x31
goroutine 4 [chan receive]:
github.com/golang/glog.(*loggingT).flushDaemon(0xd5fe00)
        /home/user/app/releases/20140312144700/_vendor/src/github.com/golang/glog/glog.go:839 +0x50
created by github.com/golang/glog.init·1
        /home/user/app/releases/20140312144700/_vendor/src/github.com/golang/glog/glog.go:406 +0x276
goroutine 5 [syscall]:
runtime.goexit()
        /home/user/.gvm/gos/go1.2/src/pkg/runtime/proc.c:1394
goroutine 9 [chan receive]:
database/sql.(*DB).connectionOpener(0xc21004bb00)
        /home/user/.gvm/gos/go1.2/src/pkg/database/sql/sql.go:574 +0x3e
created by database/sql.Open
        /home/user/.gvm/gos/go1.2/src/pkg/database/sql/sql.go:436 +0x24d
goroutine 11 [finalizer wait]:
runtime.park(0x40aa00, 0xd5dc18, 0xd5b8c8)
        /home/user/.gvm/gos/go1.2/src/pkg/runtime/proc.c:1342 +0x66
runfinq()
        /home/user/.gvm/gos/go1.2/src/pkg/runtime/mgc0.c:2276 +0x84
runtime.goexit()
        /home/user/.gvm/gos/go1.2/src/pkg/runtime/proc.c:1394

[gopherbot]

Comment 4 by dimitrij.denissenko@blacksquaremedia.com:

Any comments/suggestions? Do you need more information or was that sufficient?

[bradfitz]

Comment 5:

My first guess is that you have a data race.  Have you run your code under the race
detector?
Without a minimal repro that crashes at tip, I'm inclined to say that it's a bug in your
code, but I would love to be proven wrong.

[olov]

Comment 6:

I just filed issue #7848 with a minimal test case. This issue is most likely related to
it.

[rsc]

Comment 7:

Status changed to Duplicate.

Merged into issue #7848.