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

Open
inksink opened this issue Dec 18, 2018 · 3 comments

Comments

@inksink
Copy link

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

This comment has been minimized.

Copy link
Member

commented Dec 18, 2018

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 changed the title net/http: data race in httputil.reverseproxy net/http/httputil: data race in ReverseProxy? Dec 18, 2018

@inksink

This comment has been minimized.

Copy link
Author

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

@gozssky

This comment has been minimized.

Copy link

commented Sep 2, 2019

@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.

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