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/httputil: data race in ReverseProxy #29321

Closed
inksink opened this issue Dec 18, 2018 · 11 comments
Closed

net/http/httputil: data race in ReverseProxy #29321

inksink opened this issue Dec 18, 2018 · 11 comments
Labels
FrozenDueToAge WaitingForInfo Issue is not actionable because of missing required information, which needs to be provided.

Comments

@inksink
Copy link

inksink commented Dec 18, 2018

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

$ go version
go version go1.11.2 darwin/amd64

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
GOARCH="amd64"
GOBIN=""
GOCACHE="/Users/megvii/Library/Caches/go-build"
GOEXE=""
GOFLAGS=""
GOHOSTARCH="amd64"
GOHOSTOS="darwin"
GOOS="darwin"
GOPATH="/Users/megvii/go"
GOPROXY=""
GORACE=""
GOROOT="/usr/local/Cellar/go/1.11.2/libexec"
GOTMPDIR=""
GOTOOLDIR="/usr/local/Cellar/go/1.11.2/libexec/pkg/tool/darwin_amd64"
GCCGO="gccgo"
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/d_/17dg6drs2ss4yttxylv9bv3r0000gn/T/go-build139806013=/tmp/go-build -gno-record-gcc-switches -fno-common"

What did you do?

What did you expect to see?

all going well

What did you see instead?

WARNING: DATA RACE
Read at 0x00c420706ae8 by goroutine 147:
bufio.(*Writer).WriteString()
GOROOT/src/bufio/bufio.go:590 +0xd2
net/http.writeStatusLine()
GOROOT/src/net/http/server.go:1440 +0x75
net/http.(*chunkWriter).writeHeader()
GOROOT/src/net/http/server.go:1410 +0xd5c
net/http.(*chunkWriter).Write()
GOROOT/src/net/http/server.go:359 +0x66a
bufio.(*Writer).Flush()
GOROOT/src/bufio/bufio.go:573 +0x138
net/http.(*response).finishRequest()
GOROOT/src/net/http/server.go:1542 +0x8c
net/http.(*conn).serve()
GOROOT/src/net/http/server.go:1835 +0x831

Previous write at 0x00c420706ae8 by goroutine 188:
bufio.(*Writer).Flush()
GOROOT/src/bufio/bufio.go:585 +0x3c5
net/http.(*expectContinueReader).Read()
GOROOT/src/net/http/server.go:868 +0x2b5
 … // omit some private wrappers for Read()
net/http.transferBodyReader.Read()
GOROOT/src/net/http/transfer.go:60 +0x75
io.(*LimitedReader).Read()
GOROOT/src/io/io.go:446 +0xca
bufio.(*Writer).ReadFrom()
GOROOT/src/bufio/bufio.go:703 +0x13b
io.copyBuffer()
GOROOT/src/io/io.go:386 +0x417
io.Copy()
GOROOT/src/io/io.go:362 +0x74
net/http.(*transferWriter).WriteBody()
GOROOT/src/net/http/transfer.go:337 +0x98a
net/http.(*Request).write()
GOROOT/src/net/http/request.go:622 +0x797
net/http.(*persistConn).writeLoop()
GOROOT/src/net/http/transport.go:1825 +0x2e0

Goroutine 147 (running) created at:
net/http.(*Server).Serve()
GOROOT/src/net/http/server.go:2795 +0x364
net/http.(*Server).ListenAndServe()
GOROOT/src/net/http/server.go:2711 +0xc4
main.main()
service/ossproxy/main.go:64 +0x3ac

Goroutine 188 (running) created at:
net/http.(*Transport).dialConn()
GOROOT/src/net/http/transport.go:1238 +0xb4a
net/http.(*Transport).getConn.func4()
GOROOT/src/net/http/transport.go:957 +0x9f

I found that in serveHTTP() reverse proxy start a default standard transport.RoundTrip() .
After RoundTrip() there is also a running goroutine writeloop() . This is by design:

From net/http/client.go type RoundTripper interface :
RoundTrip must always close the body, including on errors,
but depending on the implementation may do so in a separate
goroutine even after RoundTrip returns. This means that
callers wanting to reuse the body for subsequent requests
must arrange to wait for the Close call before doing so.

But this goroutine may write to conn.bufw, which will make race condition with net/http.(*Server).Serve().

Sometimes it leads to panic. In net/http.(*Server).Serve() conn is closed, but write loop wants to write something to conn.bufw .

It is hard to reproduce this issue. It appears about every several hours in my service.

I am trying to find a simple way to reproduce it.

@bradfitz
Copy link
Contributor

What's your code look like?

The ReverseProxy code has to run synchronously in your ServeHTTP Handler. You can't start it in a new goroutine and then return from your ServeHTTP.

@bradfitz bradfitz added the WaitingForInfo Issue is not actionable because of missing required information, which needs to be provided. label Dec 18, 2018
@bradfitz bradfitz changed the title net/http: data race in httputil.reverseproxy net/http/httputil: data race in ReverseProxy? Dec 18, 2018
@inksink
Copy link
Author

inksink commented Dec 19, 2018

@bradfitz There is no synchronous code in my ServerHTTP.
I means ReverseProxy.ServeHttp() run transport.RoundTrip(), and transport.RoundTrip() run a "writeloop()" synchronously, which may lead to race condition.

I've simplified my code:

package main

import (
        "net/http/httputil"

        "github.com/aws/aws-sdk-go/aws/signer/v4"
 
        "..."
)

type proxy struct {
	p            *httputil.ReverseProxy
    	signer       *v4.Signer
}

func (p *proxy) getDirector(target *url.URL) func(req *http.Request) {
	return func(req *http.Request) {
		req.URL.Scheme = target.Scheme
		req.URL.Host = target.Host

		// Req.Host should be "" or req.URL.Host. Because v4.Signer will prefer req.host to req.URL.host.
		req.Host = target.Host
		if _, ok := req.Header["User-Agent"]; !ok {
			req.Header.Set("User-Agent", "")
		}

		if req.Header.Get("Content-Length") == "0" {
			req.Header.Del("Content-Length")
		}

		_, err := p.signer.Sign(req, nil, "s3", "", time.Now())
		if err != nil {
			log.Errorln(err)
		}
	}
}

func newProxy() (p *proxy, err error) {
	p = &proxy{}

	// httputil.ReverseProxy
	target, err := url.Parse(*flagRgw)
	if err != nil {
		return nil, err
	}
	p.p = &httputil.ReverseProxy{Director: p.getDirector(target)}
}

func (p *proxy) ServeHTTP(w http.ResponseWriter, r *http.Request) {
        // omit some unimportant codes

        p.p.ServeHTTP(w,r)
}

func main() {
        server := &http.Server{
	        Addr:    80,
        	Handler: p,
        }
        server.ListenAndServe()
}

@inksink inksink changed the title net/http/httputil: data race in ReverseProxy? net/http/httputil: data race in ReverseProxy Dec 20, 2018
@sleepymole
Copy link

@bradfitz I reproduce the data race or panic in ReverseProxy.

I construct a broken server. The server will always send 100-continue and an incorrect header to proxy. In ReverseProxy,transport.RoundTrip(outreq) will receive an error and don't keep the connection to client. After the connection is closed, (*conn).finalFlush will assign (*conn).bufw = nil. At the same time, writeLoop probably doesn't exit and may writeBody. The body here is an *expectContinueReader. When writeLoop first reads it, it writes 100-continue to client. But (*expectContinueReader).resp.conn.bufw == nil, so it leads to panic. If writeBody happens before assign,it leads to data race.

Here is my code:

package main

import (
	"io"
	"io/ioutil"
	"log"
	"net/http"
	"net/http/httputil"
	"net/url"
	"time"
)

type zeroReader struct{}

func (zeroReader) Read(p []byte) (int, error) { return len(p), nil }

var infinite io.Reader = &zeroReader{}

func brokenBackend() {
	http.HandleFunc("/", func(w http.ResponseWriter, r *http.Request) {
		conn, bfw, err := w.(http.Hijacker).Hijack()
		if err != nil {
			log.Fatalf("hijack failed: %v", err)
		}
		// Tell client net/http.(*persistConn).writeLoop() to continue writeBody.
		bfw.WriteString("HTTP/1.1 100 Continue\r\n\r\n")

		// Send client a wrong format header to make client net/http.(*persistConn).readLoop() readResponse failed.
		// Then client net/http.(*persistConn).roundTrip() will return an error and probably doesn't wait
		// net/http.(*persistConn).writeLoop() to exit.
		bfw.WriteString("BROKEN-HEADER\r\n\r\n")
		bfw.Flush()

		// Keep this connection for 1s so that the client doesn't think the connection is down immediately.
		<-time.AfterFunc(time.Second, func() { conn.Close() }).C
	})
	http.ListenAndServe("localhost:8081", nil)
}

// Proxy just forwards requests to the broken backend.
func proxy() {
	target, err := url.Parse("http://localhost:8081")
	if err != nil {
		log.Fatalf("parse target url failed: %v", err)
	}
	p := httputil.NewSingleHostReverseProxy(target)
	p.ErrorLog = log.New(ioutil.Discard, "", 0)
	http.ListenAndServe("localhost:8080", p)
}

func main() {
	go brokenBackend()
	go proxy()
	// Wait backend and proxy server to start
	time.Sleep(time.Second)

	for range time.Tick(time.Millisecond * 100) {
		req, err := http.NewRequest("PUT", "http://localhost:8080", io.LimitReader(infinite, 65536))
		if err != nil {
			log.Fatalf("create request failed: %v", err)
		}
		req.Header.Set("Expect", "100-continue")
		_, err = http.DefaultClient.Do(req)
		if err != nil {
			log.Fatalf("do request failed: %v", err)
		}
	}
}

Run the code with race detector. After a few seconds, data race is occurred. In very few cases,it leads to panic.

@inksink
Copy link
Author

inksink commented Jul 15, 2020

Go 1.14.5 has fixed a similar bug to this issue, but it doesn't work for @gozssky 's reproducible code.
Has any work been done on this? Is there a work around that I can use?

@davecheney
Copy link
Contributor

@inksink as the original issue is over a year old now would you be able to include the output from the data race detector when running Go 1.14.5 or 1.15.beta1. Thanks

@sleepymole
Copy link

@davecheney I run the same code as mentioned above. Here is the output:

[root@centos7 ~]# go/bin/go version
go version go1.14.5 linux/amd64
[root@centos7 ~]# go/bin/go run -race main.go 
==================
WARNING: DATA RACE
Read at 0x00c000cae828 by goroutine 63:
  bufio.(*Writer).Available()
      /root/go/src/bufio/bufio.go:608 +0xd4
  bufio.(*Writer).WriteString()
      /root/go/src/bufio/bufio.go:689 +0x2f
  net/http.writeStatusLine()
      /root/go/src/net/http/server.go:1505 +0x75
  net/http.(*chunkWriter).writeHeader()
      /root/go/src/net/http/server.go:1475 +0xd49
  net/http.(*chunkWriter).close()
      /root/go/src/net/http/server.go:402 +0x176
  net/http.(*response).finishRequest()
      /root/go/src/net/http/server.go:1621 +0xc4
  net/http.(*conn).serve()
      /root/go/src/net/http/server.go:1929 +0x88a

Previous write at 0x00c000cae828 by goroutine 511:
  bufio.(*Writer).Flush()
      /root/go/src/bufio/bufio.go:603 +0x3d4
  net/http.(*expectContinueReader).Read()
      /root/go/src/net/http/server.go:904 +0x2b6
  io.copyBuffer()
      /root/go/src/io/io.go:405 +0x143
  io.Copy()
      /root/go/src/io/io.go:364 +0x78
  net/http.(*transferWriter).doBodyCopy()
      /root/go/src/net/http/transfer.go:400 +0x2f
  net/http.(*transferWriter).writeBody()
      /root/go/src/net/http/transfer.go:348 +0x753
  net/http.(*Request).write()
      /root/go/src/net/http/request.go:685 +0x859
  net/http.(*persistConn).writeLoop()
      /root/go/src/net/http/transport.go:2280 +0x331

Goroutine 63 (running) created at:
  net/http.(*Server).Serve()
      /root/go/src/net/http/server.go:2962 +0x5b6
  net/http.(*Server).ListenAndServe()
      /root/go/src/net/http/server.go:2859 +0x102
  net/http.ListenAndServe()
      /root/go/src/net/http/server.go:3115 +0x2d1
  main.proxy()
      /root/main.go:48 +0x20d

Goroutine 511 (running) created at:
  net/http.(*Transport).dialConn()
      /root/go/src/net/http/transport.go:1648 +0xc33
  net/http.(*Transport).dialConnFor()
      /root/go/src/net/http/transport.go:1365 +0x14f
==================
==================
WARNING: DATA RACE
Write at 0x00c000e11000 by goroutine 63:
  runtime.slicestringcopy()
      /root/go/src/runtime/slice.go:232 +0x0
  bufio.(*Writer).WriteString()
      /root/go/src/bufio/bufio.go:699 +0x2ad
  net/http.writeStatusLine()
      /root/go/src/net/http/server.go:1505 +0x75
  net/http.(*chunkWriter).writeHeader()
      /root/go/src/net/http/server.go:1475 +0xd49
  net/http.(*chunkWriter).close()
      /root/go/src/net/http/server.go:402 +0x176
  net/http.(*response).finishRequest()
      /root/go/src/net/http/server.go:1621 +0xc4
  net/http.(*conn).serve()
      /root/go/src/net/http/server.go:1929 +0x88a

Previous write at 0x00c000e11000 by goroutine 511:
  runtime.slicestringcopy()
      /root/go/src/runtime/slice.go:232 +0x0
  bufio.(*Writer).WriteString()
      /root/go/src/bufio/bufio.go:699 +0x2ad
  net/http.(*expectContinueReader).Read()
      /root/go/src/net/http/server.go:903 +0x27a
  io.copyBuffer()
      /root/go/src/io/io.go:405 +0x143
  io.Copy()
      /root/go/src/io/io.go:364 +0x78
  net/http.(*transferWriter).doBodyCopy()
      /root/go/src/net/http/transfer.go:400 +0x2f
  net/http.(*transferWriter).writeBody()
      /root/go/src/net/http/transfer.go:348 +0x753
  net/http.(*Request).write()
      /root/go/src/net/http/request.go:685 +0x859
  net/http.(*persistConn).writeLoop()
      /root/go/src/net/http/transport.go:2280 +0x331

Goroutine 63 (running) created at:
  net/http.(*Server).Serve()
      /root/go/src/net/http/server.go:2962 +0x5b6
  net/http.(*Server).ListenAndServe()
      /root/go/src/net/http/server.go:2859 +0x102
  net/http.ListenAndServe()
      /root/go/src/net/http/server.go:3115 +0x2d1
  main.proxy()
      /root/main.go:48 +0x20d

Goroutine 511 (running) created at:
  net/http.(*Transport).dialConn()
      /root/go/src/net/http/transport.go:1648 +0xc33
  net/http.(*Transport).dialConnFor()
      /root/go/src/net/http/transport.go:1365 +0x14f
==================
==================
WARNING: DATA RACE
Write at 0x00c000e11018 by goroutine 63:
  runtime.slicestringcopy()
      /root/go/src/runtime/slice.go:232 +0x0
  bufio.(*Writer).WriteString()
      /root/go/src/bufio/bufio.go:699 +0x2ad
  net/http.writeStatusLine()
      /root/go/src/net/http/server.go:1513 +0x1be
  net/http.(*chunkWriter).writeHeader()
      /root/go/src/net/http/server.go:1475 +0xd49
  net/http.(*chunkWriter).close()
      /root/go/src/net/http/server.go:402 +0x176
  net/http.(*response).finishRequest()
      /root/go/src/net/http/server.go:1621 +0xc4
  net/http.(*conn).serve()
      /root/go/src/net/http/server.go:1929 +0x88a

Previous write at 0x00c000e11018 by goroutine 511:
  runtime.slicestringcopy()
      /root/go/src/runtime/slice.go:232 +0x0
  bufio.(*Writer).WriteString()
      /root/go/src/bufio/bufio.go:699 +0x2ad
  net/http.(*expectContinueReader).Read()
      /root/go/src/net/http/server.go:903 +0x27a
  io.copyBuffer()
      /root/go/src/io/io.go:405 +0x143
  io.Copy()
      /root/go/src/io/io.go:364 +0x78
  net/http.(*transferWriter).doBodyCopy()
      /root/go/src/net/http/transfer.go:400 +0x2f
  net/http.(*transferWriter).writeBody()
      /root/go/src/net/http/transfer.go:348 +0x753
  net/http.(*Request).write()
      /root/go/src/net/http/request.go:685 +0x859
  net/http.(*persistConn).writeLoop()
      /root/go/src/net/http/transport.go:2280 +0x331

Goroutine 63 (running) created at:
  net/http.(*Server).Serve()
      /root/go/src/net/http/server.go:2962 +0x5b6
  net/http.(*Server).ListenAndServe()
      /root/go/src/net/http/server.go:2859 +0x102
  net/http.ListenAndServe()
      /root/go/src/net/http/server.go:3115 +0x2d1
  main.proxy()
      /root/main.go:48 +0x20d

Goroutine 511 (finished) created at:
  net/http.(*Transport).dialConn()
      /root/go/src/net/http/transport.go:1648 +0xc33
  net/http.(*Transport).dialConnFor()
      /root/go/src/net/http/transport.go:1365 +0x14f
==================

@sleepymole
Copy link

@davecheney Is there any progress on this issue?

@davecheney
Copy link
Contributor

davecheney commented Jul 20, 2020

Not yet, it is still labeled waiting for info as it has yet to be reproduced independently.

If you are able to provide a self contained method that someone may use to reproduce the issue I’m sure that will be of great assistance.

@sleepymole
Copy link

sleepymole commented Jul 20, 2020

@bradfitz I reproduce the data race or panic in ReverseProxy.

I construct a broken server. The server will always send 100-continue and an incorrect header to proxy. In ReverseProxy,transport.RoundTrip(outreq) will receive an error and don't keep the connection to client. After the connection is closed, (*conn).finalFlush will assign (*conn).bufw = nil. At the same time, writeLoop probably doesn't exit and may writeBody. The body here is an *expectContinueReader. When writeLoop first reads it, it writes 100-continue to client. But (*expectContinueReader).resp.conn.bufw == nil, so it leads to panic. If writeBody happens before assign,it leads to data race.

Here is my code:

package main

import (
	"io"
	"io/ioutil"
	"log"
	"net/http"
	"net/http/httputil"
	"net/url"
	"time"
)

type zeroReader struct{}

func (zeroReader) Read(p []byte) (int, error) { return len(p), nil }

var infinite io.Reader = &zeroReader{}

func brokenBackend() {
	http.HandleFunc("/", func(w http.ResponseWriter, r *http.Request) {
		conn, bfw, err := w.(http.Hijacker).Hijack()
		if err != nil {
			log.Fatalf("hijack failed: %v", err)
		}
		// Tell client net/http.(*persistConn).writeLoop() to continue writeBody.
		bfw.WriteString("HTTP/1.1 100 Continue\r\n\r\n")

		// Send client a wrong format header to make client net/http.(*persistConn).readLoop() readResponse failed.
		// Then client net/http.(*persistConn).roundTrip() will return an error and probably doesn't wait
		// net/http.(*persistConn).writeLoop() to exit.
		bfw.WriteString("BROKEN-HEADER\r\n\r\n")
		bfw.Flush()

		// Keep this connection for 1s so that the client doesn't think the connection is down immediately.
		<-time.AfterFunc(time.Second, func() { conn.Close() }).C
	})
	http.ListenAndServe("localhost:8081", nil)
}

// Proxy just forwards requests to the broken backend.
func proxy() {
	target, err := url.Parse("http://localhost:8081")
	if err != nil {
		log.Fatalf("parse target url failed: %v", err)
	}
	p := httputil.NewSingleHostReverseProxy(target)
	p.ErrorLog = log.New(ioutil.Discard, "", 0)
	http.ListenAndServe("localhost:8080", p)
}

func main() {
	go brokenBackend()
	go proxy()
	// Wait backend and proxy server to start
	time.Sleep(time.Second)

	for range time.Tick(time.Millisecond * 100) {
		req, err := http.NewRequest("PUT", "http://localhost:8080", io.LimitReader(infinite, 65536))
		if err != nil {
			log.Fatalf("create request failed: %v", err)
		}
		req.Header.Set("Expect", "100-continue")
		_, err = http.DefaultClient.Do(req)
		if err != nil {
			log.Fatalf("do request failed: %v", err)
		}
	}
}

Run the code with race detector. After a few seconds, data race is occurred. In very few cases,it leads to panic.

@davecheney Here is the code. It doesn't contain any dependency. I run this code with Go 1.14.5, data race still exists.

@davecheney
Copy link
Contributor

Slightly smaller reproduction

package main

import (
	"io"
	"io/ioutil"
	"log"
	"net/http"
	"net/http/httputil"
	"net/url"
	"time"
)

type zeroReader struct{}

func (zeroReader) Read(p []byte) (int, error) { return len(p), nil }

var infinite io.Reader = &zeroReader{}

func brokenBackend() {
	http.HandleFunc("/", func(w http.ResponseWriter, r *http.Request) {
		conn, bfw, err := w.(http.Hijacker).Hijack()
		if err != nil {
			log.Fatalf("hijack failed: %v", err)
		}
		// Tell client net/http.(*persistConn).writeLoop() to continue writeBody.
		bfw.WriteString("HTTP/1.1 100 Continue\r\n\r\n")
		bfw.Flush()

		conn.Close()
	})
	http.ListenAndServe("localhost:8081", nil)
}

// Proxy just forwards requests to the broken backend.
func proxy() {
	target, err := url.Parse("http://localhost:8081")
	if err != nil {
		log.Fatalf("parse target url failed: %v", err)
	}
	p := httputil.NewSingleHostReverseProxy(target)
	p.ErrorLog = log.New(ioutil.Discard, "", 0)
	http.ListenAndServe("localhost:8080", p)
}

func main() {
	go brokenBackend()
	go proxy()
	// Wait backend and proxy server to start
	time.Sleep(time.Second)

	for {
		req, err := http.NewRequest("PUT", "http://localhost:8080", io.LimitReader(infinite, 65536))
		if err != nil {
			log.Fatalf("create request failed: %v", err)
		}
		req.Header.Set("Expect", "100-continue")
		_, err = http.DefaultClient.Do(req)
		if err != nil {
			log.Fatalf("do request failed: %v", err)
		}
	}
}

@neild
Copy link
Contributor

neild commented May 21, 2021

The data race in #29321 (comment) was fixed (so far as I can tell) by CL 251858

@neild neild closed this as completed May 22, 2021
@golang golang locked and limited conversation to collaborators May 22, 2022
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Labels
FrozenDueToAge WaitingForInfo Issue is not actionable because of missing required information, which needs to be provided.
Projects
None yet
Development

No branches or pull requests

6 participants