net/http: panic "slice bounds out of range" while reading chunked response body

[benburkert]

Please answer these questions before submitting your issue. Thanks!

What version of Go are you using (go version)?

go version go1.8.3 linux/amd64

Does this issue reproduce with the latest release?

unknown

What operating system and processor architecture are you using (go env)?

GOARCH="amd64"
GOHOSTARCH="amd64"
GOHOSTOS="linux"
GOOS="linux"

What did you do?

A HTTP service proxies it's request to an upstream HTTP service. The upstream sends back a chunked encoded response.

What did you expect to see?

The service is expected to proxy the response from the upstream back to the downstream client.

What did you see instead?

The process sporadically panics with a runtime error: slice bounds out of range message in the bufio.(*Reader).ReadSlice.

panic: runtime error: slice bounds out of range

goroutine 134054 [running]:
bufio.(*Reader).ReadSlice(0xc4204e17a0, 0xa, 0x92e7e8, 0xc4206dd940, 0xc4206dd930, 0xc420718680, 0xc420b2a850)
    /usr/local/go/src/bufio/bufio.go:316 +0x258
bufio.(*Reader).ReadLine(0xc4204e17a0, 0xc4201185a0, 0x90, 0x90, 0x8fc0e0, 0xc420b2a8b8, 0xc4206dda08)
    /usr/local/go/src/bufio/bufio.go:367 +0x37
net/textproto.(*Reader).readLineSlice(0xc4206ddaf8, 0x0, 0xc4206dda30, 0x40fdb8, 0x90, 0x8fc0e0)
    /usr/local/go/src/net/textproto/reader.go:55 +0x5f
net/textproto.(*Reader).ReadLine(0xc4206ddaf8, 0xc4201185a0, 0xc4207a3520, 0x0, 0x0)
    /usr/local/go/src/net/textproto/reader.go:36 +0x2f
net/http.ReadResponse(0xc4204e17a0, 0xc4200bcb00, 0xc4206ddb80, 0x5f916d, 0xc420314440)
    /usr/local/go/src/net/http/response.go:148 +0xca
net/http.(*persistConn).readResponse(0xc420554a20, 0xc4200bcb00, 0xc420a38300, 0x0, 0x0, 0xc420a381e0, 0xc420b2a150, 0xc420686870, 0x0, 0x0)
    /usr/local/go/src/net/http/transport.go:1649 +0x57
net/http.(*persistConn).readLoop(0xc420554a20)
    /usr/local/go/src/net/http/transport.go:1489 +0x12c0
created by net/http.(*Transport).dialConn
/usr/local/go/src/net/http/transport.go:1117 +0xa35

Running the service with the race detector enabled shows a data race between net/http.(*body).readLocked()/bufio.(*Reader).ReadSlice() and net/http.(*persistConn).readLoop()/bufio.(*Reader).Peek() that is likely related:

==================
WARNING: DATA RACE
Read at 0x00c42088e508 by goroutine 169:
  bufio.(*Reader).ReadSlice()
      /usr/local/go/src/bufio/bufio.go:316 +0x5f
  net/http/internal.readChunkLine()
      /usr/local/go/src/net/http/internal/chunked.go:122 +0x4a
  net/http/internal.(*chunkedReader).beginChunk()
      /usr/local/go/src/net/http/internal/chunked.go:48 +0x5c
  net/http/internal.(*chunkedReader).Read()
      /usr/local/go/src/net/http/internal/chunked.go:93 +0x229
  net/http.(*body).readLocked()
      /usr/local/go/src/net/http/transfer.go:761 +0xbf
  net/http.(*body).Read()
      /usr/local/go/src/net/http/transfer.go:753 +0x131
  io.copyBuffer()
      /usr/local/go/src/io/io.go:390 +0x116
  io.CopyBuffer()
      /usr/local/go/src/io/io.go:371 +0xa5
  REDACTED http handler
  net/http.serverHandler.ServeHTTP()
      /usr/local/go/src/net/http/server.go:2568 +0xbc
  net/http.(*conn).serve()
      /usr/local/go/src/net/http/server.go:1825 +0x71a

Previous write at 0x00c42088e508 by goroutine 8:
  bufio.(*Reader).fill()
      /usr/local/go/src/bufio/bufio.go:88 +0x561
  bufio.(*Reader).Peek()
      /usr/local/go/src/bufio/bufio.go:129 +0x131
  net/http.(*persistConn).readLoop()
      /usr/local/go/src/net/http/transport.go:1474 +0x2b5

Goroutine 169 (running) created at:
  net/http.(*Server).Serve()
      /usr/local/go/src/net/http/server.go:2668 +0x35f
  REDACTED main func

Goroutine 8 (running) created at:
  net/http.(*Transport).dialConn()
      /usr/local/go/src/net/http/transport.go:1117 +0xc07
  net/http.(*Transport).getConn.func4()
      /usr/local/go/src/net/http/transport.go:908 +0xa2
==================

[benburkert]

A short investigation points to a data race between the Peek call by readLoop on the connection's bufio.Reader and the chunked body reader. It appears that the EOF signal, forwarded by the bodyEOFSignal reader, is forwarded once the body reader returns an EOF but not necessarily before all body data has been read from the bufio.Reader. The Peek(1) call does not grab the persistConn's lock, and bufio.Peek may call bufio.fill, which can rearrange the backing slice. My guess is that this only seems to show up with chunked responses because small reads (smaller than the buffer size) are performed when the chunk size is small.

[dsnet]

Thank you for the report. Do you have a minimal reproduction that we can run?

[benburkert]

@dsnet not yet, i'm still working on one but it's proving to be quite tricky to trigger. I'll update the ticket as soon as I have a reproduction.

[dsnet]

\cc @tombergan

[tombergan]

Can you say more about "REDACTED http handler", specifically, what the copy is copying?

[tombergan]

Does the error occur with 1.9?

[benburkert]

The handler is running a modified version of httputil.ReverseProxy, and the io.CopyBuffer comes from the ReverseProxy.copyResponse method, which still calls io.CopyBuffered directly.

I'm only able to trigger the panic & data race in a production environment where running 1.9/tip is not an option. If I'm able to reproduce it locally I will be sure to test with go1.9 and tip.

[benburkert]

This program reproduces the data race: https://play.golang.org/p/QztsfgNHNr

It looks like the data race is triggered by a 304 response that has a chunked encoded empty body. go1.9 and tip also hit the data race.

[bradfitz]

I'm not really following this thread (still on leave), but of note: a 304 response never has a body.

https://tools.ietf.org/html/rfc7230#section-3.3.3 says:

1. Any response to a HEAD request and any response with a 1xx
   (Informational), 204 (No Content), or 304 (Not Modified) status
   code is always terminated by the first empty line after the
   header fields, regardless of the header fields present in the
   message, and thus cannot contain a message body.

If Go is processing a server saying:

"HTTP/1.1 304 NOT MODIFIED\r\nConnection: keep-alive\r\nTransfer-Encoding: chunked\r\n\r\n0\r\n\r\n"

It would stop after the first \r\n\r\n and start reading 0\r\n\r\n as the next response, which may not be ready yet.

Any server sending such a response is buggy, but I agree that Go shouldn't have a data race when handling an invalid response, if that's indeed what's happening here. (I haven't looked.)

[gopherbot]

Change https://golang.org/cl/71910 mentions this issue: net/http: ignore response body when forbidden by status code

[bradfitz]

@benburkert, I realize now you said the exact same thing. I had looked at your play.golang.org snippet, came back to comment, and never read your very next sentence. Sorry.

[benburkert]

@bradfitz no worries, thanks for digging up the relevant section of the RFC so quickly!