Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

net/http: Expect 100-continue panics in httputil.ReverseProxy #34902

Open
mike1808 opened this issue Oct 14, 2019 · 5 comments
Assignees
Labels

Comments

@mike1808
Copy link

@mike1808 mike1808 commented Oct 14, 2019

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

$ go version
go version go1.13.1 darwin/amd64

Also, it happens on go1.12, 1.11, 1.10, 1.9

Does this issue reproduce with the latest release?

Yes.

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

go env Output
$ go env
GO111MODULE=""
GOARCH="amd64"
GOBIN=""
GOCACHE="/Users/user/Library/Caches/go-build"
GOENV="/Users/user/Library/Application Support/go/env"
GOEXE=""
GOFLAGS=""
GOHOSTARCH="amd64"
GOHOSTOS="darwin"
GONOPROXY=""
GONOSUMDB=""
GOOS="darwin"
GOPATH="/Users/user/go"
GOPRIVATE=""
GOPROXY="https://proxy.golang.org,direct"
GOROOT="/usr/local/Cellar/go/1.13.1/libexec"
GOSUMDB="sum.golang.org"
GOTMPDIR=""
GOTOOLDIR="/usr/local/Cellar/go/1.13.1/libexec/pkg/tool/darwin_amd64"
GCCGO="gccgo"
AR="ar"
CC="clang"
CXX="clang++"
CGO_ENABLED="1"
GOMOD=""
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 -fno-caret-diagnostics -Qunused-arguments -fmessage-length=0 -fdebug-prefix-map=/var/folders/5h/vw88yy8s6s19dtf39trffmv40000gn/T/go-build076404496=/tmp/go-build -gno-record-gcc-switches -fno-common"

It also is reproducible on the Linux machine.

What did you do?

We created a simple client, reverse proxy, and server.
We make a simple POST request using the Expect: 100-continue header to the reverse proxy, which forwards onto the server
We make many of these requests at once to simulate load. At about 10 requests at a time, it fails quickly with a panic.

We have uploaded a minimal reproduction to a gist

When we run the reverse proxy with the race detector enabled we see several race messages leading up to and immediately before the panic.

We have found that this panic occurs more reliably when the http.Transport has an ExpectContinueTimeout value set to 0.
Though under very high load with cURL we were able to see the same behavior with the http.DefaultTransport.
The mean time to occur was at least an order of magnitude greater so we have set the value in our test to 0.
The stack trace for the events is the same in either case.

What did you expect to see?

The reverse proxy does not panic.

What did you see instead?

We see two different kinds of panics:

panic: runtime error: slice bounds out of range [:-25]

goroutine 28515 [running]:
bufio.(*Writer).Flush(0xc000112dc0, 0x147d1ef, 0x19)
        /usr/local/Cellar/go/1.13.1/libexec/src/bufio/bufio.go:599 +0x4cb
net/http.(*expectContinueReader).Read(0xc0002407a0, 0xc0005bc000, 0x401, 0x401, 0x0, 0x0, 0xc0003f7600)
        /usr/local/Cellar/go/1.13.1/libexec/src/net/http/server.go:889 +0x29a
io.(*LimitedReader).Read(0xc00015a800, 0xc0005bc000, 0x401, 0x401, 0x0, 0xc0003f7700, 0x10)
        /usr/local/Cellar/go/1.13.1/libexec/src/io/io.go:448 +0xc8
io.copyBuffer(0x14f2380, 0xc0000b12c0, 0x14f1900, 0xc00015a800, 0xc0005bc000, 0x401, 0x401, 0x40, 0x1461e00, 0xc0002bf101)
        /usr/local/Cellar/go/1.13.1/libexec/src/io/io.go:402 +0x144
io.Copy(...)
        /usr/local/Cellar/go/1.13.1/libexec/src/io/io.go:364
net.genericReadFrom(0x14f19c0, 0xc000290050, 0x14f1900, 0xc00015a800, 0xc0003a5380, 0xc0003f7788, 0x106e0e0)
        /usr/local/Cellar/go/1.13.1/libexec/src/net/net.go:625 +0xb1
net.(*TCPConn).readFrom(0xc000290050, 0x14f1900, 0xc00015a800, 0x1465b20, 0x65040c8, 0x1090800)
        /usr/local/Cellar/go/1.13.1/libexec/src/net/tcpsock_posix.go:54 +0x7b
net.(*TCPConn).ReadFrom(0xc000290050, 0x14f1900, 0xc00015a800, 0x65040c8, 0xc000290050, 0x1465b01)
        /usr/local/Cellar/go/1.13.1/libexec/src/net/tcpsock.go:103 +0x7a
io.copyBuffer(0x14f19c0, 0xc000290050, 0x14f1900, 0xc00015a800, 0x0, 0x0, 0x0, 0xc000103200, 0x0, 0xc0003f7928)
        /usr/local/Cellar/go/1.13.1/libexec/src/io/io.go:388 +0x3fb
io.Copy(...)
        /usr/local/Cellar/go/1.13.1/libexec/src/io/io.go:364
net/http.persistConnWriter.ReadFrom(0xc0002fe6c0, 0x14f1900, 0xc00015a800, 0x65040a8, 0xc0002fe6c0, 0x1423501)
        /usr/local/Cellar/go/1.13.1/libexec/src/net/http/transport.go:1591 +0xb6
bufio.(*Writer).ReadFrom(0xc00015cd40, 0x14f1900, 0xc00015a800, 0x6504088, 0xc00015cd40, 0x1043d01)
        /usr/local/Cellar/go/1.13.1/libexec/src/bufio/bufio.go:713 +0x50d
io.copyBuffer(0x14f1780, 0xc00015cd40, 0x14f1900, 0xc00015a800, 0x0, 0x0, 0x0, 0xc0003f7ad8, 0x1044678, 0x20)
        /usr/local/Cellar/go/1.13.1/libexec/src/io/io.go:388 +0x3fb
io.Copy(...)
        /usr/local/Cellar/go/1.13.1/libexec/src/io/io.go:364
net/http.(*transferWriter).doBodyCopy(0xc0001326e0, 0x14f1780, 0xc00015cd40, 0x14f1900, 0xc00015a800, 0xc00023c820, 0xc0002fe700, 0x3)
        /usr/local/Cellar/go/1.13.1/libexec/src/net/http/transfer.go:400 +0x79
net/http.(*transferWriter).writeBody(0xc0001326e0, 0x14f1780, 0xc00015cd40, 0x2, 0x2)
        /usr/local/Cellar/go/1.13.1/libexec/src/net/http/transfer.go:359 +0xc15
net/http.(*Request).write(0xc0001a5600, 0x14f1780, 0xc00015cd40, 0x0, 0x0, 0xc00015a7c0, 0x0, 0x0)
        /usr/local/Cellar/go/1.13.1/libexec/src/net/http/request.go:682 +0x85a
net/http.(*persistConn).writeLoop(0xc0002fe6c0)
        /usr/local/Cellar/go/1.13.1/libexec/src/net/http/transport.go:2199 +0x332
created by net/http.(*Transport).dialConn
        /usr/local/Cellar/go/1.13.1/libexec/src/net/http/transport.go:1567 +0xc07

and

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

goroutine 76196 [running]:
bufio.(*Writer).Available(...)
        /usr/local/Cellar/go/1.13.1/libexec/src/bufio/bufio.go:610
bufio.(*Writer).WriteString(0x0, 0x147d1ef, 0x19, 0xc000174630, 0x10, 0x100000000000200)
        /usr/local/Cellar/go/1.13.1/libexec/src/bufio/bufio.go:691 +0x9e
net/http.(*expectContinueReader).Read(0xc00000e880, 0xc000174630, 0xa, 0xa, 0x0, 0x0, 0xc000057600)
        /usr/local/Cellar/go/1.13.1/libexec/src/net/http/server.go:888 +0x246
io.(*LimitedReader).Read(0xc0001609e0, 0xc000174630, 0xa, 0xa, 0x0, 0xc000057700, 0x10)
        /usr/local/Cellar/go/1.13.1/libexec/src/io/io.go:448 +0xc8
io.copyBuffer(0x14f2380, 0xc000012bf0, 0x14f1900, 0xc0001609e0, 0xc000174630, 0xa, 0xa, 0x40, 0x1461e00, 0xc0000b0b01)
        /usr/local/Cellar/go/1.13.1/libexec/src/io/io.go:402 +0x144
io.Copy(...)
        /usr/local/Cellar/go/1.13.1/libexec/src/io/io.go:364
net.genericReadFrom(0x14f19c0, 0xc0000a6078, 0x14f1900, 0xc0001609e0, 0x2b, 0xc000057788, 0x106e02d)
        /usr/local/Cellar/go/1.13.1/libexec/src/net/net.go:625 +0xb1
net.(*TCPConn).readFrom(0xc0000a6078, 0x14f1900, 0xc0001609e0, 0x1465b20, 0x6b6a1b8, 0x1090800)
        /usr/local/Cellar/go/1.13.1/libexec/src/net/tcpsock_posix.go:54 +0x7b
net.(*TCPConn).ReadFrom(0xc0000a6078, 0x14f1900, 0xc0001609e0, 0x6b6a1b8, 0xc0000a6078, 0x1465b01)
        /usr/local/Cellar/go/1.13.1/libexec/src/net/tcpsock.go:103 +0x7a
io.copyBuffer(0x14f19c0, 0xc0000a6078, 0x14f1900, 0xc0001609e0, 0x0, 0x0, 0x0, 0xc000120f00, 0x0, 0xc000057928)
        /usr/local/Cellar/go/1.13.1/libexec/src/io/io.go:388 +0x3fb
io.Copy(...)
        /usr/local/Cellar/go/1.13.1/libexec/src/io/io.go:364
net/http.persistConnWriter.ReadFrom(0xc0003a87e0, 0x14f1900, 0xc0001609e0, 0x6b6a198, 0xc0003a87e0, 0x1423501)
        /usr/local/Cellar/go/1.13.1/libexec/src/net/http/transport.go:1591 +0xb6
bufio.(*Writer).ReadFrom(0xc000196ac0, 0x14f1900, 0xc0001609e0, 0x6b6a178, 0xc000196ac0, 0x1043d01)
        /usr/local/Cellar/go/1.13.1/libexec/src/bufio/bufio.go:713 +0x50d
io.copyBuffer(0x14f1780, 0xc000196ac0, 0x14f1900, 0xc0001609e0, 0x0, 0x0, 0x0, 0xc000057ad8, 0x1044678, 0x20)
        /usr/local/Cellar/go/1.13.1/libexec/src/io/io.go:388 +0x3fb
io.Copy(...)
        /usr/local/Cellar/go/1.13.1/libexec/src/io/io.go:364
net/http.(*transferWriter).doBodyCopy(0xc0002c25a0, 0x14f1780, 0xc000196ac0, 0x14f1900, 0xc0001609e0, 0xc0000f2a00, 0xc0003a8800, 0x3)
        /usr/local/Cellar/go/1.13.1/libexec/src/net/http/transfer.go:400 +0x79
net/http.(*transferWriter).writeBody(0xc0002c25a0, 0x14f1780, 0xc000196ac0, 0x2, 0x2)
        /usr/local/Cellar/go/1.13.1/libexec/src/net/http/transfer.go:359 +0xc15
net/http.(*Request).write(0xc0001b5400, 0x14f1780, 0xc000196ac0, 0x0, 0x0, 0xc0000a0740, 0x0, 0x0)
        /usr/local/Cellar/go/1.13.1/libexec/src/net/http/request.go:682 +0x85a
net/http.(*persistConn).writeLoop(0xc0003a87e0)
        /usr/local/Cellar/go/1.13.1/libexec/src/net/http/transport.go:2199 +0x332
created by net/http.(*Transport).dialConn
        /usr/local/Cellar/go/1.13.1/libexec/src/net/http/transport.go:1567 +0xc07
exit status 2

cc @KauzClay @adobley

@mike1808

This comment has been minimized.

Copy link
Author

@mike1808 mike1808 commented Oct 14, 2019

@smasher164

This comment has been minimized.

Copy link
Member

@smasher164 smasher164 commented Oct 14, 2019

This is not a recent regression since the reverse proxy also segfaults on 1.11 and 1.12 (after commenting out ForceAttemptHTTP2: true). Also reproduces on tip (19e0799).
/cc @bradfitz @fraenkel

@odeke-em

This comment has been minimized.

Copy link
Member

@odeke-em odeke-em commented Oct 14, 2019

Thank you for this report @mike1808 and welcome to the Go project!
Thank you @smasher164 for the triage!

@mike1808 here is a simplified all in one repro that can be run without 3 different programs being run and it reproduces on my Darwin machine, please see https://play.golang.org/p/dvv7HaB8t-Y or inlined below:

package main

import (
	"bytes"
	"fmt"
	"log"
	"net"
	"net/http"
	"net/http/httptest"
	"net/http/httputil"
	"net/url"
	"strings"
	"sync"
)

func main() {
	cst := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
		fmt.Fprintln(w, "this call was relayed by the reverse proxy")
	}))
	defer cst.Close()

	ln, err := net.Listen("tcp", ":0")
	if err != nil {
		log.Fatalf("Failed to find available port: %v", err)
	}
	defer ln.Close()

	backendURL, _ := url.Parse(cst.URL)
	rpxy := httputil.NewSingleHostReverseProxy(backendURL)
	addr := ln.Addr().String()

	var wg sync.WaitGroup
	defer wg.Wait()

	wg.Add(1)
	go func() {
		if err := http.Serve(ln, rpxy); err != nil {
			log.Fatalf("Reverse proxy serve error: %v", err)
		}
	}()

	runClients(10, addr, &wg)
}

func runClients(n int, addr string, wg *sync.WaitGroup) {
	fullURL := "http://" + addr

	// Request needs a larger body to see the error happen more quickly
	// It is reproducable with smaller body sizes, but it takes longer to fail
	bodyString := strings.Repeat("a", 2048)
	client := &http.Client{}

	for i := 0; i < n; i++ {
		wg.Add(1)
		go func() {
			defer wg.Done()
			for {
				buf := bytes.NewBufferString(bodyString)
				req, _ := http.NewRequest("POST", fullURL, buf)
				req.Header.Add("Expect", "100-continue")

				resp, err := client.Do(req)
				if err != nil {
					fmt.Printf("Request Failed: %s\n", err.Error())
				} else {
					resp.Body.Close()
				}
			}
		}()
	}
}

and when ran as

$ go run -race all.go 
==================
WARNING: DATA RACE
Read at 0x00c00012c159 by goroutine 149:
  net/http.(*chunkWriter).writeHeader()
      /Users/emmanuelodeke/go/src/go.googlesource.com/go/src/net/http/server.go:1312 +0x1ce4
  net/http.(*chunkWriter).Write()
      /Users/emmanuelodeke/go/src/go.googlesource.com/go/src/net/http/server.go:369 +0x726
  bufio.(*Writer).Flush()
      /Users/emmanuelodeke/go/src/go.googlesource.com/go/src/bufio/bufio.go:591 +0x136
  net/http.(*response).finishRequest()
      /Users/emmanuelodeke/go/src/go.googlesource.com/go/src/net/http/server.go:1590 +0x92
  net/http.(*conn).serve()
      /Users/emmanuelodeke/go/src/go.googlesource.com/go/src/net/http/server.go:1900 +0x88a

Previous write at 0x00c00012c159 by goroutine 111:
  net/http.(*expectContinueReader).Read()
      /Users/emmanuelodeke/go/src/go.googlesource.com/go/src/net/http/server.go:893 +0x19b
  io/ioutil.devNull.ReadFrom()
      /Users/emmanuelodeke/go/src/go.googlesource.com/go/src/io/ioutil/ioutil.go:144 +0xb9
  io/ioutil.(*devNull).ReadFrom()
      <autogenerated>:1 +0x7c
  io.copyBuffer()
      /Users/emmanuelodeke/go/src/go.googlesource.com/go/src/io/io.go:388 +0x3fa
  io.Copy()
      /Users/emmanuelodeke/go/src/go.googlesource.com/go/src/io/io.go:364 +0x78
  net/http.(*transferWriter).writeBody()
      /Users/emmanuelodeke/go/src/go.googlesource.com/go/src/net/http/transfer.go:364 +0xc7a
  net/http.(*Request).write()
      /Users/emmanuelodeke/go/src/go.googlesource.com/go/src/net/http/request.go:684 +0x859
  net/http.(*persistConn).writeLoop()
      /Users/emmanuelodeke/go/src/go.googlesource.com/go/src/net/http/transport.go:2178 +0x331

Goroutine 149 (running) created at:
  net/http.(*Server).Serve()
      /Users/emmanuelodeke/go/src/go.googlesource.com/go/src/net/http/server.go:2937 +0x5bf
  net/http.Serve()
      /Users/emmanuelodeke/go/src/go.googlesource.com/go/src/net/http/server.go:2473 +0xe1

Goroutine 111 (running) created at:
  net/http.(*Transport).dialConn()
      /Users/emmanuelodeke/go/src/go.googlesource.com/go/src/net/http/transport.go:1546 +0xbf9
  net/http.(*Transport).dialConnFor()
      /Users/emmanuelodeke/go/src/go.googlesource.com/go/src/net/http/transport.go:1292 +0x14f
==================

we can see the data race adjusted for new updates given that am on Go tip aka future Go1.14.

We are going to jump onto this and investigate and fix it.

@odeke-em

This comment has been minimized.

Copy link
Member

@odeke-em odeke-em commented Oct 15, 2019

@cuonglm since you proposed the mutex addition to expectBody in a related issue, you might be interested in this one too and the repro that I posted above. Thanks!

@mike1808

This comment has been minimized.

Copy link
Author

@mike1808 mike1808 commented Oct 15, 2019

Thanks for picking this up!
The first thing which we tried was to put mutex on .closed flag here

go/src/net/http/server.go

Lines 883 to 885 in 11d7775

if ecr.closed {
return 0, ErrBodyReadAfterClose
}

However, the problem was that during the panic the expectContinueReader#Close method was not called

go/src/net/http/server.go

Lines 898 to 901 in 11d7775

func (ecr *expectContinueReader) Close() error {
ecr.closed = true
return ecr.readCloser.Close()
}

But the underlying ecr.resp.conn.bufw buffer was nil as the connection was already closed. So putting mutex on closed flag didn't help.

go/src/net/http/server.go

Lines 886 to 889 in 11d7775

if !ecr.resp.wroteContinue && !ecr.resp.conn.hijacked() {
ecr.resp.wroteContinue = true
ecr.resp.conn.bufw.WriteString("HTTP/1.1 100 Continue\r\n\r\n")
ecr.resp.conn.bufw.Flush()

So, my theory was that due to some race condition the body is still being read while req.Body is already discarded, so it is not possible to call req.Body.Close() but the expectContinueReader#Read tries to write to response buffer. Maybe putting a check here that buffer is not empty will fix the issue.

go/src/net/http/server.go

Lines 888 to 889 in 11d7775

ecr.resp.conn.bufw.WriteString("HTTP/1.1 100 Continue\r\n\r\n")
ecr.resp.conn.bufw.Flush()

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
4 participants
You can’t perform that action at this time.