net/http: nil pointer dereference panic for httputil.ReverseProxy users

[szuecs]

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

$ go version
go1.18.3

Does this issue reproduce with the latest release?

I don't no it's a single occurrence in a system running about 500 instances every day 24x7.

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

go env Output

$ go env
GO111MODULE="on"
GOARCH="amd64"
GOEXE=""
GOEXPERIMENT=""
GOFLAGS=""
GOHOSTARCH="amd64"
GOHOSTOS="linux"
GOINSECURE=""
GONOPROXY=""
GONOSUMDB=""
GOOS="linux"
GOPRIVATE=""
GOPROXY="https://proxy.golang.org,direct"
GOROOT="/usr/share/go"
GOSUMDB="sum.golang.org"
GOTMPDIR=""
GOTOOLDIR="/usr/share/go/pkg/tool/linux_amd64"
GOVCS=""
GOVERSION="go1.18.3"
GCCGO="gccgo"
GOAMD64="v1"
AR="ar"
CC="gcc"
CXX="g++"
CGO_ENABLED="1"
GOWORK=""
CGO_CFLAGS="-g -O2"
CGO_CPPFLAGS=""
CGO_CXXFLAGS="-g -O2"
CGO_FFLAGS="-g -O2"
CGO_LDFLAGS="-g -O2"
PKG_CONFIG="pkg-config"
GOGCCFLAGS="-fPIC -m64 -pthread -fmessage-length=0 -fdebug-prefix-map=/tmp/go-build813518630=/tmp/go-build -gno-record-gcc-switches"

What did you do?

Run the binary in a container and this was a single occurrence after months of running different versions of the binary (we regularly update it ~weekly).

panic: runtime error: invalid memory address or nil pointer dereference
[signal SIGSEGV: segmentation violation code=0x1 addr=0x18 pc=0x52160a]
container=skipper-ingress version=v0.13.220 container_id=22847bac9b2e73e49c21b85e150d93c67919bfa4e306ba2442d9d2ee48e1d6f6 pod=skipper-ingress-7d7bc75576-5nzn9 stream=stderr component=ingress application=skipper-ingress namespace=kube-system
goroutine 31240317 [running]:
bufio.(*Writer).Available(...)
/usr/local/go/src/bufio/bufio.go:645
bufio.(*Writer).WriteString(0x0, {0x1118d77?, 0x7fdacf6cf0f8?})
/usr/local/go/src/bufio/bufio.go:735 +0x6a
net/http.(*expectContinueReader).Read(0xc009fd4560, {0xc002833980, 0x5c, 0x5c})
/usr/local/go/src/net/http/server.go:908 +0xfd
io.(*LimitedReader).Read(0xc009fbee28, {0xc002833980?, 0xc0056d3580?, 0xc005368930?})
/usr/local/go/src/io/io.go:476 +0x45
io.copyBuffer({0x129a7a0, 0xc0056d3580}, {0x1298f00, 0xc009fbee28}, {0x0, 0x0, 0x0})
/usr/local/go/src/io/io.go:426 +0x1b2
io.Copy(...)
/usr/local/go/src/io/io.go:385
net.genericReadFrom({0x1299120?, 0xc009f91e00?}, {0x1298f00, 0xc009fbee28})
/usr/local/go/src/net/net.go:662 +0x6a
net.(*TCPConn).readFrom(0xc009f91e00, {0x1298f00, 0xc009fbee28})
/usr/local/go/src/net/tcpsock_posix.go:54 +0x78
net.(*TCPConn).ReadFrom(0xc009f91e00, {0x1298f00?, 0xc009fbee28?})
/usr/local/go/src/net/tcpsock.go:130 +0x36
io.copyBuffer({0x1299120, 0xc009f91e00}, {0x1298f00, 0xc009fbee28}, {0x0, 0x0, 0x0})
/usr/local/go/src/io/io.go:412 +0x14b
io.Copy(...)
/usr/local/go/src/io/io.go:385
net/http.persistConnWriter.ReadFrom({0x438f3c?}, {0x1298f00?, 0xc009fbee28?})
/usr/local/go/src/net/http/transport.go:1775 +0x5b
bufio.(*Writer).ReadFrom(0xc0051a1d40, {0x1298f00, 0xc009fbee28})
/usr/local/go/src/bufio/bufio.go:768 +0x1ab
io.copyBuffer({0x1296cc0, 0xc0051a1d40}, {0x1298f00, 0xc009fbee28}, {0x0, 0x0, 0x0})
/usr/local/go/src/io/io.go:412 +0x14b
io.Copy(...)
/usr/local/go/src/io/io.go:385
net/http.(*transferWriter).doBodyCopy(0xc000d999a0, {0x1296cc0?, 0xc0051a1d40?}, {0x1298f00?, 0xc009fbee28?})
/usr/local/go/src/net/http/transfer.go:411 +0x4d
net/http.(*transferWriter).writeBody(0xc000d999a0, {0x1296cc0, 0xc0051a1d40})
/usr/local/go/src/net/http/transfer.go:369 +0x3d5
net/http.(*Request).write(0xc009880a00, {0x1296cc0, 0xc0051a1d40}, 0x0, 0x0, 0xc009fbede0)
/usr/local/go/src/net/http/request.go:698 +0xb46
net/http.(*persistConn).writeLoop(0xc003a07e60)
/usr/local/go/src/net/http/transport.go:2395 +0x185
created by net/http.(*Transport).dialConn
/usr/local/go/src/net/http/transport.go:1751 +0x1791

What did you expect to see?

no panic withing the stdlib

What did you see instead?

A panic

[mvdan]

It looks like your program may have a data race causing memory corruption. Please try running your program with -race: https://go.dev/doc/articles/race_detector

[szuecs]

@mvdan Where do you see a data race?
@mdlayher are you sure it's a nil ptr dereference in bufio?
I would assume that address would show 0x0 and the message says ".. or nil ptr dereference"

[mvdan]

A segmentation violation means you tried to dereference a bad pointer. Unless your code uses unsafe, that is most likely caused by memory corruption, often caused by data races.

[dominikh]

I feel the need to clarify @mvdan's statement. An ordinary nil pointer dereference also causes a segmentation violation, and that of course doesn't only happen due to unsafe or data races. But as @szuecs points out, in this instance, the bad pointer has address 0x18, not 0, which would indeed point towards memory corruption of some sort.

The access that panics is in

func (b *Writer) Available() int { return len(b.buf) - b.n }

and I don't see any safe way in which b could be 0x18.

Edit: both @mvdan and I need to freshen up on what nil pointer dereferences can look like. 0x18 is of course the offset of the field being accessed.

[AlexanderYastrebov]

The cause looks to be body read after connection close which nullifies bufw on final flush

go/src/net/http/server.go

Line 1698 in 4068be5

c.bufw = nil

The read then fails on attempt to write

go/src/net/http/server.go

Line 908 in 4068be5

w.conn.bufw.WriteString("HTTP/1.1 100 Continue\r\n\r\n")

Could be reproduced via:

package main

import (
	"log"
	"net/http"
	"time"
)

func main() {
	s := &http.Server{
		Addr: ":8888",
		Handler: http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
			go func() {
				time.Sleep(1000 * time.Millisecond)
				r.Body.Read(make([]byte, 1))
			}()
		}),
	}
	log.Fatal(s.ListenAndServe())
}

# trigger use of expectContinueReader
curl -v -H "Expect: 100-continue" -d"test" localhost:8888

panic: runtime error: invalid memory address or nil pointer dereference
[signal SIGSEGV: segmentation violation code=0x1 addr=0x18 pc=0x4fb40a]

goroutine 5 [running]:
bufio.(*Writer).Available(...)
        /usr/lib/go-1.18/src/bufio/bufio.go:645
bufio.(*Writer).WriteString(0x0, {0x666d76?, 0x0?})
        /usr/lib/go-1.18/src/bufio/bufio.go:735 +0x6a
net/http.(*expectContinueReader).Read(0xc00006a040, {0xc00012c27b, 0x1, 0x1})
        /usr/lib/go-1.18/src/net/http/server.go:908 +0xfd
main.main.func1.1()

[szuecs]

@AlexanderYastrebov thanks. I also tested with 1.18.4 same panic triggered.

[seankhliao]

does it trigger with a race detector?

[szuecs]

[sszuecs@sandor-lab:~/tmp/go/issue-53808-panic-expect-continue]% go run -race main.go                                                      suess-new
==================
WARNING: DATA RACE
Read at 0x00c000094a58 by goroutine 8:
  net/http.(*expectContinueReader).Read()
      /usr/share/go/src/net/http/server.go:908 +0x12e
  main.main.func1.1()
      /home/sszuecs/tmp/go/issue-53808-panic-expect-continue/main.go:15 +0x87

Previous write at 0x00c000094a58 by goroutine 7:
  net/http.(*conn).finalFlush()
      /usr/share/go/src/net/http/server.go:1698 +0xee
  net/http.(*conn).close()
      /usr/share/go/src/net/http/server.go:1704 +0x2e
  net/http.(*conn).serve.func1()
      /usr/share/go/src/net/http/server.go:1836 +0x2d1
  runtime.deferreturn()
      /usr/share/go/src/runtime/panic.go:436 +0x32
  net/http.(*Server).Serve.func3()
      /usr/share/go/src/net/http/server.go:3071 +0x58

Goroutine 8 (running) created at:
  main.main.func1()
      /home/sszuecs/tmp/go/issue-53808-panic-expect-continue/main.go:13 +0x8e
  net/http.HandlerFunc.ServeHTTP()
      /usr/share/go/src/net/http/server.go:2084 +0x4d
  net/http.serverHandler.ServeHTTP()
      /usr/share/go/src/net/http/server.go:2916 +0x896
  net/http.(*conn).serve()
      /usr/share/go/src/net/http/server.go:1966 +0xbaa
  net/http.(*Server).Serve.func3()
      /usr/share/go/src/net/http/server.go:3071 +0x58

Goroutine 7 (finished) created at:
  net/http.(*Server).Serve()
      /usr/share/go/src/net/http/server.go:3071 +0x80c
  net/http.(*Server).ListenAndServe()
      /usr/share/go/src/net/http/server.go:2968 +0xbc
  main.main()
      /home/sszuecs/tmp/go/issue-53808-panic-expect-continue/main.go:19 +0x104
==================
panic: runtime error: invalid memory address or nil pointer dereference
[signal SIGSEGV: segmentation violation code=0x1 addr=0x0 pc=0x57d99c]

goroutine 18 [running]:
panic({0x7516a0, 0x997010})
        /usr/share/go/src/runtime/panic.go:941 +0x397 fp=0xc00004ce58 sp=0xc00004cd98 pc=0x4668d7
runtime.panicmem(...)
        /usr/share/go/src/runtime/panic.go:220
runtime.sigpanic()
        /usr/share/go/src/runtime/signal_unix.go:818 +0x336 fp=0xc00004cea8 sp=0xc00004ce58 pc=0x47d976
bufio.(*Writer).Available(...)
        /usr/share/go/src/bufio/bufio.go:645
bufio.(*Writer).WriteString(0x0?, {0x79490f?, 0x19?})
        /usr/share/go/src/bufio/bufio.go:735 +0x9c fp=0xc00004cf28 sp=0xc00004cea8 pc=0x57d99c
net/http.(*expectContinueReader).Read(0xc000110020, {0xc0001000af, 0x1, 0x1})
        /usr/share/go/src/net/http/server.go:908 +0x149 fp=0xc00004cfa0 sp=0xc00004cf28 pc=0x709369
main.main.func1.1()
        /home/sszuecs/tmp/go/issue-53808-panic-expect-continue/main.go:15 +0x88 fp=0xc00004cfe0 sp=0xc00004cfa0 pc=0x72c5a8
runtime.goexit()
        /usr/share/go/src/runtime/asm_amd64.s:1571 +0x1 fp=0xc00004cfe8 sp=0xc00004cfe0 pc=0x497141
created by main.main.func1
        /home/sszuecs/tmp/go/issue-53808-panic-expect-continue/main.go:13 +0x8f

yes

[seankhliao]

To me that example looks like #30580, which right now doesn't really look like the reported issue

[AlexanderYastrebov]

The example #53808 (comment) is clearly wrong as it reuses body after leaving Handler.

The subject software (Skipper) is an HTTP proxy and passes incoming request to the http.Transport RoundTrip.
E.g. in #29321 the problem was that transport goroutine (in ReverseProxy) still used the request body after RoundTrip returned.
I am wondering if there is still a similar edge case in the transport.

[szuecs]

I can't easily reproduce the problem with skipper build with -race. I also don't see where we would have a goroutine similar to your example @AlexanderYastrebov in the request/response handling.