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

Jump to bottom

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

Closed
mike1808 opened this issue Oct 14, 2019 · 10 comments
Closed

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

mike1808 opened this issue Oct 14, 2019 · 10 comments
Labels
FrozenDueToAge NeedsFix The path to resolution is known, but the work has not been done.
Milestone
Go1.15

Comments

@mike1808
Copy link

mike1808 commented Oct 14, 2019 •
edited

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
Copy link
Author

Related issues:
#30580
fabiolb/fabio#659
#6995
#26253

@smasher164
Copy link
Member

smasher164 commented Oct 14, 2019 •
edited

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

@smasher164 smasher164 added the NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one. label Oct 14, 2019
@odeke-em
Copy link
Member

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 odeke-em added NeedsFix The path to resolution is known, but the work has not been done. and removed NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one. labels Oct 14, 2019
@odeke-em
Copy link
Member

@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
Copy link
Author

mike1808 commented Oct 15, 2019 •
edited

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()

@ameowlia
Copy link
Contributor

ameowlia commented Jan 9, 2020

I am also running into this issue. Has any work been done on this? Is there a work around that I can use?

@KauzClay
Copy link

KauzClay commented Jan 9, 2020

Hi @odeke-em

It has been a few months and we were wondering how things were going on your side with this?

Thanks!

@akutz
Copy link

akutz commented Jun 12, 2020 •
edited

UPDATE
Please see my next comment as it includes updated information.

Hi @mike1808 and @odeke-em,

I have been taking a look at this issue, and I think I have a patch, albeit not one we probably want. The gist has the following:

  • The patch...ish
  • A wrapper for bufio.Writer to ensure concurrent access to the buffer
  • The test log for net/http to show the changes do not break the existing tests

With the above changes, I have not been able to reproduce the issue with the above example.

Basically:

  • server.go now uses an interface bufferedWriter instead of directly using bufio.Writer
  • This enables the introduction of the struct safeWriter, which is nothing more than a wrapper around bufio.Writer, but with a mutex guarding access to the writer's exported functions
  • A mutex has also been introduced around expectContinueReader.sawEOF as it would also race

There has to be a cleaner way of patching this, but ultimately it would require a lot more refactoring of server.go due to the fact that a race is happening with the connection's buffered writer. The number of places that is accessed meant a nuclear solution of creating a thread-safe wrapper around the writer was the path of least resistance. Again, not the most optimal path, just one to verify the problem and a solution.

UPDATE
I also executed the packages’ (net/http and net/http/httputil) built-in benchmarks, and there is not a noticeable difference when the safeWriter is and is not used. However, perhaps over time or at scale there may be. It is worth considering.

akutz added a commit to akutz/go that referenced this issue Jun 13, 2020
@akutz
Patch for race on HTTP-100 expected continue
10fcb95 
This patch is a first-pass attempt to fix the issue described by
golang#34902, where the use of 100-continue in HTTP headers received
by a net/http/Server can lead to a data race involving the connection's
buffered writer and the expectContinueReader.sawEOF field.

This patch is not activated unless the process's environment variables
include NET_HTTP_SERVER_SYNC_BUFIO_WRITER=1.

This patch also includes a test to validate the race condition no longer
occurs. To execute the test to validate the existence of the race
condition please use:

        GORACE="halt_on_error=1" go test -race \
          -v -run TestExpectedContinueRace net/http

To execute the test to validate the race condition no longer exists once
the patch is applied, please use:

        NET_HTTP_SERVER_SYNC_BUFIO_WRITER=1 \
          GORACE="halt_on_error=1" go test -race \
          -v -run TestExpectedContinueRace net/http

The test allows five minutes for the race to occur, after which the
absence of the race is deemed as evidence it no longer occurs.
@akutz
Copy link

akutz commented Jun 13, 2020 •
edited

Hi @mike1808 and @odeke-em,

I spent a little more time on this and decided to create a proper branch with the changes - https://github.com/akutz/go/tree/bugfix/http-100-race. The branch:

  • Is based on go1.14.4
  • Collapses all of the changes into server.go
  • Still uses a thread-safe wrapper around bufio.Writer
  • Only activates the patch if run with NET_HTTP_SERVER_SYNC_BUFIO_WRITER=1
  • Includes a proper Go test to validate the race condition and the patch

Also, @odeke-em, I updated your example from above and put it into server_race_test.go. I updated things so that the test program will exit after a specified amount of time if no race has been encountered instead of running ad infinitum. There is also occasional output to indicate things are still running.

Notes on how to test the patch are included in the commit message from the aforementioned branch. Please let me know if you have any questions!

Here is an example test run:

$ NET_HTTP_SERVER_SYNC_BUFIO_WRITER=1 \
  GORACE="halt_on_error=1" \
  go test -race -v -run TestExpectedContinueRace net/http
=== RUN   TestExpectedContinueRace
    TestExpectedContinueRace: server_race_test.go:92: 5.699330035s	1000	success
    TestExpectedContinueRace: server_race_test.go:92: 16.813722224s	2000	success
    TestExpectedContinueRace: server_race_test.go:92: 19.802324322s	3000	success
    TestExpectedContinueRace: server_race_test.go:92: 22.710844385s	4000	success
    TestExpectedContinueRace: server_race_test.go:92: 25.481533886s	5000	success
    TestExpectedContinueRace: server_race_test.go:92: 29.564832153s	6000	success
    TestExpectedContinueRace: server_race_test.go:92: 35.332867897s	7000	success
    TestExpectedContinueRace: server_race_test.go:92: 45.020530799s	8000	success
    TestExpectedContinueRace: server_race_test.go:92: 51.195042719s	9000	success
    TestExpectedContinueRace: server_race_test.go:92: 1m4.3442834s	10000	success
    TestExpectedContinueRace: server_race_test.go:92: 1m8.402871653s	11000	success
    TestExpectedContinueRace: server_race_test.go:92: 1m12.205081197s	12000	success
    TestExpectedContinueRace: server_race_test.go:92: 1m16.075249366s	13000	success
    TestExpectedContinueRace: server_race_test.go:92: 1m22.236953565s	14000	success
    TestExpectedContinueRace: server_race_test.go:92: 1m28.688912654s	15000	success
    TestExpectedContinueRace: server_race_test.go:92: 1m34.566695544s	16000	success
    TestExpectedContinueRace: server_race_test.go:92: 1m40.022079595s	17000	success
    TestExpectedContinueRace: server_race_test.go:92: 1m52.399052446s	18000	success
    TestExpectedContinueRace: server_race_test.go:92: 1m57.05937919s	19000	success
    TestExpectedContinueRace: server_race_test.go:92: 2m3.562737723s	20000	success
    TestExpectedContinueRace: server_race_test.go:92: 2m11.163692754s	21000	success
    TestExpectedContinueRace: server_race_test.go:92: 2m17.346798591s	22000	success
    TestExpectedContinueRace: server_race_test.go:92: 2m22.476667311s	23000	success
    TestExpectedContinueRace: server_race_test.go:92: 2m28.068210052s	24000	success
    TestExpectedContinueRace: server_race_test.go:92: 2m34.712127145s	25000	success
    TestExpectedContinueRace: server_race_test.go:92: 2m40.791093059s	26000	success
    TestExpectedContinueRace: server_race_test.go:92: 2m46.169517952s	27000	success
    TestExpectedContinueRace: server_race_test.go:92: 2m52.91424554s	28000	success
    TestExpectedContinueRace: server_race_test.go:92: 2m59.817914966s	29000	success
    TestExpectedContinueRace: server_race_test.go:92: 3m8.208221571s	30000	success
    TestExpectedContinueRace: server_race_test.go:92: 3m13.744794678s	31000	success
    TestExpectedContinueRace: server_race_test.go:92: 3m19.769425135s	32000	success
    TestExpectedContinueRace: server_race_test.go:92: 3m25.326477017s	33000	success
    TestExpectedContinueRace: server_race_test.go:92: 3m31.396548575s	34000	success
    TestExpectedContinueRace: server_race_test.go:92: 3m37.00717295s	35000	success
    TestExpectedContinueRace: server_race_test.go:92: 3m43.945229576s	36000	success
    TestExpectedContinueRace: server_race_test.go:92: 3m50.259696643s	37000	success
    TestExpectedContinueRace: server_race_test.go:92: 3m59.069321526s	38000	success
    TestExpectedContinueRace: server_race_test.go:92: 4m3.175832261s	39000	success
    TestExpectedContinueRace: server_race_test.go:92: 4m9.572133776s	40000	success
    TestExpectedContinueRace: server_race_test.go:92: 4m15.254040969s	41000	success
    TestExpectedContinueRace: server_race_test.go:92: 4m19.762444825s	42000	success
    TestExpectedContinueRace: server_race_test.go:92: 4m26.044543354s	43000	success
    TestExpectedContinueRace: server_race_test.go:92: 4m31.823938742s	44000	success
    TestExpectedContinueRace: server_race_test.go:92: 4m39.386460542s	45000	success
    TestExpectedContinueRace: server_race_test.go:92: 4m45.12414952s	46000	success
    TestExpectedContinueRace: server_race_test.go:92: 4m51.59784742s	47000	success
    TestExpectedContinueRace: server_race_test.go:92: 4m56.840072847s	48000	success
--- PASS: TestExpectedContinueRace (300.03s)
PASS
ok  	net/http	300.582s

You can use the same test to verify the data race exists; just omit the environment variable that activates the synchronous writer:

$ GORACE="halt_on_error=1" \
  go test -race -v -run TestExpectedContinueRace net/http
=== RUN   TestExpectedContinueRace
    TestExpectedContinueRace: server_race_test.go:92: 1.068806428s	1000	success
    TestExpectedContinueRace: server_race_test.go:92: 2.605504358s	2000	success
    TestExpectedContinueRace: server_race_test.go:92: 4.741652746s	3000	success
    TestExpectedContinueRace: server_race_test.go:92: 8.23426989s	4000	success
    TestExpectedContinueRace: server_race_test.go:92: 11.989015435s	5000	success
    TestExpectedContinueRace: server_race_test.go:92: 15.902393666s	6000	success
    TestExpectedContinueRace: server_race_test.go:92: 21.48671671s	7000	success
    TestExpectedContinueRace: server_race_test.go:92: 27.951748535s	8000	success
    TestExpectedContinueRace: server_race_test.go:92: 52.880008996s	9000	success
    TestExpectedContinueRace: server_race_test.go:92: 55.472999714s	10000	success
    TestExpectedContinueRace: server_race_test.go:92: 58.218712305s	11000	success
    TestExpectedContinueRace: server_race_test.go:92: 1m1.389870424s	12000	success
    TestExpectedContinueRace: server_race_test.go:92: 1m4.838242096s	13000	success
    TestExpectedContinueRace: server_race_test.go:92: 1m8.803293442s	14000	success
    TestExpectedContinueRace: server_race_test.go:92: 1m13.807306472s	15000	success
    TestExpectedContinueRace: server_race_test.go:92: 1m18.683510907s	16000	success
    TestExpectedContinueRace: server_race_test.go:92: 1m24.653467879s	17000	success
    TestExpectedContinueRace: server_race_test.go:92: 1m41.401806704s	18000	success
==================
WARNING: DATA RACE
Read at 0x00c00043a2a8 by goroutine 149:
  bufio.(*Writer).Available()
      /Users/akutz/Projects/golang/src/bufio/bufio.go:608 +0xd4
  bufio.(*Writer).WriteString()
      /Users/akutz/Projects/golang/src/bufio/bufio.go:689 +0x2f
  net/http.writeStatusLine()
      /Users/akutz/Projects/golang/src/net/http/server.go:1602 +0x7e
  net/http.(*chunkWriter).writeHeader()
      /Users/akutz/Projects/golang/src/net/http/server.go:1572 +0xd52
  net/http.(*chunkWriter).Write()
      /Users/akutz/Projects/golang/src/net/http/server.go:370 +0x755
  bufio.(*Writer).Flush()
      /Users/akutz/Projects/golang/src/bufio/bufio.go:591 +0x136
  net/http.(*response).finishRequest()
      /Users/akutz/Projects/golang/src/net/http/server.go:1705 +0x97
  net/http.(*conn).serve()
      /Users/akutz/Projects/golang/src/net/http/server.go:2018 +0x89b

Previous write at 0x00c00043a2a8 by goroutine 63:
  bufio.(*Writer).Flush()
      /Users/akutz/Projects/golang/src/bufio/bufio.go:603 +0x3d4
  net/http.(*expectContinueReader).Read()
      /Users/akutz/Projects/golang/src/net/http/server.go:1004 +0x2de
  io.(*LimitedReader).Read()
      /Users/akutz/Projects/golang/src/io/io.go:451 +0xc7
  io.copyBuffer()
      /Users/akutz/Projects/golang/src/io/io.go:405 +0x143
  io.Copy()
      /Users/akutz/Projects/golang/src/io/io.go:364 +0xb0
  net.genericReadFrom()
      /Users/akutz/Projects/golang/src/net/net.go:626 +0x32
  net.(*TCPConn).readFrom()
      /Users/akutz/Projects/golang/src/net/tcpsock_posix.go:54 +0x7a
  net.(*TCPConn).ReadFrom()
      /Users/akutz/Projects/golang/src/net/tcpsock.go:103 +0x79
  io.copyBuffer()
      /Users/akutz/Projects/golang/src/io/io.go:391 +0x3fa
  io.Copy()
      /Users/akutz/Projects/golang/src/io/io.go:364 +0xb5
  net/http.persistConnWriter.ReadFrom()
      /Users/akutz/Projects/golang/src/net/http/transport.go:1672 +0x32
  bufio.(*Writer).ReadFrom()
      /Users/akutz/Projects/golang/src/bufio/bufio.go:714 +0x52c
  io.copyBuffer()
      /Users/akutz/Projects/golang/src/io/io.go:391 +0x3fa
  io.Copy()
      /Users/akutz/Projects/golang/src/io/io.go:364 +0x78
  net/http.(*transferWriter).doBodyCopy()
      /Users/akutz/Projects/golang/src/net/http/transfer.go:400 +0x2f
  net/http.(*transferWriter).writeBody()
      /Users/akutz/Projects/golang/src/net/http/transfer.go:359 +0xc11
  net/http.(*Request).write()
      /Users/akutz/Projects/golang/src/net/http/request.go:685 +0x859
  net/http.(*persistConn).writeLoop()
      /Users/akutz/Projects/golang/src/net/http/transport.go:2280 +0x331

Goroutine 149 (running) created at:
  net/http.(*Server).Serve()
      /Users/akutz/Projects/golang/src/net/http/server.go:3051 +0x5b3
  net/http.Serve()
      /Users/akutz/Projects/golang/src/net/http/server.go:2586 +0xe1
  net/http_test.TestExpectedContinueRace.func2()
      /Users/akutz/Projects/golang/src/net/http/server_race_test.go:78 +0xf6

Goroutine 63 (running) created at:
  net/http.(*Transport).dialConn()
      /Users/akutz/Projects/golang/src/net/http/transport.go:1648 +0xc33
  net/http.(*Transport).dialConnFor()
      /Users/akutz/Projects/golang/src/net/http/transport.go:1365 +0x14f
==================
FAIL	net/http	103.619s
FAIL

akutz added a commit to akutz/go that referenced this issue Jun 13, 2020
@akutz
Patch for race on HTTP-100 expected continue
2d07e6f 
This patch is a first-pass attempt to fix the issue described by
golang#34902, where the use of 100-continue in HTTP headers received
by a net/http/Server can lead to a data race involving the connection's
buffered writer and the expectContinueReader.sawEOF field.

This patch is not activated unless the process's environment variables
include NET_HTTP_SERVER_SYNC_BUFIO_WRITER=1.

This patch also includes a test to validate the race condition no longer
occurs. To execute the test to validate the existence of the race
condition please use:

        GORACE="halt_on_error=1" go test -race \
          -v -run TestExpectedContinueRace net/http

To execute the test to validate the race condition no longer exists once
the patch is applied, please use:

        NET_HTTP_SERVER_SYNC_BUFIO_WRITER=1 \
          GORACE="halt_on_error=1" go test -race \
          -v -run TestExpectedContinueRace net/http

The test allows five minutes for the race to occur, after which the
absence of the race is deemed as evidence it no longer occurs.
akutz added a commit to akutz/go that referenced this issue Jun 15, 2020
@akutz
Patch for race on HTTP-100 expected continue
f08f60a 
This patch is a first-pass attempt to fix the issue described by
golang#34902, where the use of 100-continue in HTTP headers received
by a net/http/Server can lead to a data race involving the connection's
buffered writer and the expectContinueReader.sawEOF field.

This patch is not activated unless the process's environment variables
include NET_HTTP_SERVER_SYNC_BUFIO_WRITER=1.

This patch also includes a test to validate the race condition no longer
occurs. To execute the test to validate the existence of the race
condition please use:

        GORACE="halt_on_error=1" go test -race \
          -v -run TestExpectedContinueRace net/http

To execute the test to validate the race condition no longer exists once
the patch is applied, please use:

        NET_HTTP_SERVER_SYNC_BUFIO_WRITER=1 \
          GORACE="halt_on_error=1" go test -race \
          -v -run TestExpectedContinueRace net/http

The test allows five minutes for the race to occur, after which the
absence of the race is deemed as evidence it no longer occurs.
This was referenced Jul 14, 2020
Closed
Closed
@gopherbot
Copy link

Change https://golang.org/cl/242598 mentions this issue: net/http: synchronize "100 Continue" write and Handler writes

@dmitshur dmitshur added this to the Go1.15 milestone Jul 14, 2020
gopherbot pushed a commit that referenced this issue Jul 14, 2020
@rsc @katiehockman
[release-branch.go1.13-security] net/http: synchronize "100 Continue"…
e434185 
… write and Handler writes

The expectContinueReader writes to the connection on the first
Request.Body read. Since a Handler might be doing a read in parallel or
before a write, expectContinueReader needs to synchronize with the
ResponseWriter, and abort if a response already went out.

The tests will land in a separate CL.

Fixes #34902
Fixes CVE-2020-15586

Change-Id: Icdd8dd539f45e8863762bd378194bb4741e875fc
Reviewed-on: https://team-review.git.corp.google.com/c/golang/go-private/+/793350
Reviewed-by: Filippo Valsorda <valsorda@google.com>
(cherry picked from commit b5e504f4a07c572744b228fa1b10e3989c4c44f3)
Reviewed-on: https://team-review.git.corp.google.com/c/golang/go-private/+/793499
gopherbot pushed a commit that referenced this issue Jul 14, 2020
@rsc @katiehockman
[release-branch.go1.14-security] net/http: synchronize "100 Continue"…
f3529ca 
… write and Handler writes

The expectContinueReader writes to the connection on the first
Request.Body read. Since a Handler might be doing a read in parallel or
before a write, expectContinueReader needs to synchronize with the
ResponseWriter, and abort if a response already went out.

The tests will land in a separate CL.

Fixes #34902
Fixes CVE-2020-15586

Change-Id: Icdd8dd539f45e8863762bd378194bb4741e875fc
Reviewed-on: https://team-review.git.corp.google.com/c/golang/go-private/+/793350
Reviewed-by: Filippo Valsorda <valsorda@google.com>
(cherry picked from commit b5e504f4a07c572744b228fa1b10e3989c4c44f3)
Reviewed-on: https://team-review.git.corp.google.com/c/golang/go-private/+/793500
kph pushed a commit to platinasystems/golang-1.14 that referenced this issue Sep 9, 2020
@toddy15 @kph
Import Debian changes 1.14.6-1
dccdab4 
golang-1.14 (1.14.6-1) unstable; urgency=medium

  * New upstream version 1.14.6
    - Refresh patches
    - net/http: Expect 100-continue panics in httputil.ReverseProxy.
      See golang/go#34902, fixes CVE-2020-15586
kph pushed a commit to platinasystems/golang-1.15 that referenced this issue Sep 30, 2020
@toddy15
Import Debian changes 1.15~rc1-1
f837f90 
golang-1.15 (1.15~rc1-1) unstable; urgency=medium

  [ Shengjing Zhu ]
  * Backport patches to fix the FPU ABI problems for mips32
    https://go-review.googlesource.com/c/go/+/237058/

  [ Dr. Tobias Quathamer ]
  * New upstream version 1.15~rc1
    - Refresh patches
    - net/http: Expect 100-continue panics in httputil.ReverseProxy.
      See golang/go#34902, fixes CVE-2020-15586
@empijei empijei mentioned this issue Dec 16, 2020
Closed
@bcmills bcmills mentioned this issue Jan 19, 2021
Closed
@FiloSottile FiloSottile mentioned this issue Mar 10, 2021
Closed
@golang golang locked and limited conversation to collaborators Jul 14, 2021
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Assignees
No one assigned
Labels
FrozenDueToAge NeedsFix The path to resolution is known, but the work has not been done.
Projects
None yet
Milestone
Go1.15
Development

No branches or pull requests
9 participants
@bradfitz @akutz @dmitshur @mike1808 @odeke-em @ameowlia @gopherbot @smasher164 @KauzClay