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: data race in net/http.(*expectContinueReader) #43769

Closed
sleepymole opened this issue Jan 19, 2021 · 7 comments
Closed

net/http: data race in net/http.(*expectContinueReader) #43769

sleepymole opened this issue Jan 19, 2021 · 7 comments
Labels
FrozenDueToAge NeedsFix The path to resolution is known, but the work has not been done.
Milestone

Comments

@sleepymole
Copy link

sleepymole commented Jan 19, 2021

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

$ go version
go version go1.15.6 linux/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
GO111MODULE=""
GOARCH="amd64"
GOBIN=""
GOCACHE="/home/xyj/.cache/go-build"
GOENV="/home/xyj/.config/go/env"
GOEXE=""
GOFLAGS=""
GOHOSTARCH="amd64"
GOHOSTOS="linux"
GOINSECURE=""
GOMODCACHE="/home/xyj/go/pkg/mod"
GONOPROXY=""
GONOSUMDB=""
GOOS="linux"
GOPATH="/home/xyj/go"
GOPRIVATE=""
GOPROXY="https://proxy.golang.org,direct"
GOROOT="/usr/lib/go"
GOSUMDB="sum.golang.org"
GOTMPDIR=""
GOTOOLDIR="/usr/lib/go/pkg/tool/linux_amd64"
GCCGO="gccgo"
AR="ar"
CC="gcc"
CXX="g++"
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 -fmessage-length=0 -fdebug-prefix-map=/tmp/go-build120895179=/tmp/go-build -gno-record-gcc-switches"

What did you do?

There are two background loops for each connection. readLoop reads responses from server and writeLoop writes reqeusts to server.

In a ReverseProxy, request.Body that writeLoop used may be a net/http.(*expectContinueReader). It means we must send "100 Continue" to client if we want to read data from the body. It may lead to concurrent writes to a same connection from readLoop and writeLoop.

What's worse, the connection is probably closed without waiting writeLoop to exit. After connection is closed, (*conn).bufw will be set to nil. See https://github.com/golang/go/blob/go1.15.6/src/net/http/server.go#L1690 . If writeLoop continues writing data to the connection, a panic will occur. Something like "Invalid memory address or nil pointer dereference".

This bug is mentioned in #29321. But that issue hasn't been updated for a long time, probably because of the label WaitingForInfo.

Reproduce code is https://play.golang.org/p/6i3dUmUgOjK. You need to run with race detector.

What did you expect to see?

There is no data race or panic.

What did you see instead?

Data race occurred. In very rare case, this caused panic.

Data Race Output
==================
WARNING: DATA RACE
Read at 0x00c00022c068 by goroutine 23:
  bufio.(*Writer).Available()
      /usr/lib/go/src/bufio/bufio.go:624 +0xce
  bufio.(*Writer).WriteString()
      /usr/lib/go/src/bufio/bufio.go:705 +0x2f
  net/http.writeStatusLine()
      /usr/lib/go/src/net/http/server.go:1506 +0x7a
  net/http.(*chunkWriter).writeHeader()
      /usr/lib/go/src/net/http/server.go:1476 +0xd77
  net/http.(*chunkWriter).close()
      /usr/lib/go/src/net/http/server.go:402 +0x188
  net/http.(*response).finishRequest()
      /usr/lib/go/src/net/http/server.go:1622 +0xc9
  net/http.(*conn).serve()
      /usr/lib/go/src/net/http/server.go:1930 +0x8a4
Previous write at 0x00c00022c068 by goroutine 39: bufio.(*Writer).Flush() /usr/lib/go/src/bufio/bufio.go:619 +0x3c4 net/http.(*expectContinueReader).Read() /usr/lib/go/src/net/http/server.go:905 +0x2c7 io.(*LimitedReader).Read() /usr/lib/go/src/io/io.go:455 +0xc7 io.copyBuffer() /usr/lib/go/src/io/io.go:409 +0x14b io.Copy() /usr/lib/go/src/io/io.go:368 +0xb0 net.genericReadFrom() /usr/lib/go/src/net/net.go:643 +0x32 net.(*TCPConn).readFrom() /usr/lib/go/src/net/tcpsock_posix.go:54 +0x17c net.(*TCPConn).ReadFrom() /usr/lib/go/src/net/tcpsock.go:103 +0x79 io.copyBuffer() /usr/lib/go/src/io/io.go:395 +0x3fe io.Copy() /usr/lib/go/src/io/io.go:368 +0xb5 net/http.persistConnWriter.ReadFrom() /usr/lib/go/src/net/http/transport.go:1733 +0x32 bufio.(*Writer).ReadFrom() /usr/lib/go/src/bufio/bufio.go:730 +0x554 io.copyBuffer() /usr/lib/go/src/io/io.go:395 +0x3fe io.Copy() /usr/lib/go/src/io/io.go:368 +0x78 net/http.(*transferWriter).doBodyCopy() /usr/lib/go/src/net/http/transfer.go:400 +0x2f net/http.(*transferWriter).writeBody() /usr/lib/go/src/net/http/transfer.go:359 +0xc31 net/http.(*Request).write() /usr/lib/go/src/net/http/request.go:682 +0x887 net/http.(*persistConn).writeLoop() /usr/lib/go/src/net/http/transport.go:2343 +0x349
Goroutine 23 (running) created at: net/http.(*Server).Serve() /usr/lib/go/src/net/http/server.go:2969 +0x5d3 net/http.Serve() /usr/lib/go/src/net/http/server.go:2498 +0xe4
Goroutine 39 (running) created at: net/http.(*Transport).dialConn() /usr/lib/go/src/net/http/transport.go:1709 +0xc30 net/http.(*Transport).dialConnFor() /usr/lib/go/src/net/http/transport.go:1421 +0x151 ================== ================== WARNING: DATA RACE Write at 0x00c000237000 by goroutine 23: runtime.slicestringcopy() /usr/lib/go/src/runtime/slice.go:281 +0x0 bufio.(*Writer).WriteString() /usr/lib/go/src/bufio/bufio.go:715 +0x289 net/http.writeStatusLine() /usr/lib/go/src/net/http/server.go:1506 +0x7a net/http.(*chunkWriter).writeHeader() /usr/lib/go/src/net/http/server.go:1476 +0xd77 net/http.(*chunkWriter).close() /usr/lib/go/src/net/http/server.go:402 +0x188 net/http.(*response).finishRequest() /usr/lib/go/src/net/http/server.go:1622 +0xc9 net/http.(*conn).serve() /usr/lib/go/src/net/http/server.go:1930 +0x8a4
Previous write at 0x00c000237000 by goroutine 39: runtime.slicestringcopy() /usr/lib/go/src/runtime/slice.go:281 +0x0 bufio.(*Writer).WriteString() /usr/lib/go/src/bufio/bufio.go:715 +0x289 net/http.(*expectContinueReader).Read() /usr/lib/go/src/net/http/server.go:904 +0x28b io.(*LimitedReader).Read() /usr/lib/go/src/io/io.go:455 +0xc7 io.copyBuffer() /usr/lib/go/src/io/io.go:409 +0x14b io.Copy() /usr/lib/go/src/io/io.go:368 +0xb0 net.genericReadFrom() /usr/lib/go/src/net/net.go:643 +0x32 net.(*TCPConn).readFrom() /usr/lib/go/src/net/tcpsock_posix.go:54 +0x17c net.(*TCPConn).ReadFrom() /usr/lib/go/src/net/tcpsock.go:103 +0x79 io.copyBuffer() /usr/lib/go/src/io/io.go:395 +0x3fe io.Copy() /usr/lib/go/src/io/io.go:368 +0xb5 net/http.persistConnWriter.ReadFrom() /usr/lib/go/src/net/http/transport.go:1733 +0x32 bufio.(*Writer).ReadFrom() /usr/lib/go/src/bufio/bufio.go:730 +0x554 io.copyBuffer() /usr/lib/go/src/io/io.go:395 +0x3fe io.Copy() /usr/lib/go/src/io/io.go:368 +0x78 net/http.(*transferWriter).doBodyCopy() /usr/lib/go/src/net/http/transfer.go:400 +0x2f net/http.(*transferWriter).writeBody() /usr/lib/go/src/net/http/transfer.go:359 +0xc31 net/http.(*Request).write() /usr/lib/go/src/net/http/request.go:682 +0x887 net/http.(*persistConn).writeLoop() /usr/lib/go/src/net/http/transport.go:2343 +0x349
Goroutine 23 (running) created at: net/http.(*Server).Serve() /usr/lib/go/src/net/http/server.go:2969 +0x5d3 net/http.Serve() /usr/lib/go/src/net/http/server.go:2498 +0xe4
Goroutine 39 (running) created at: net/http.(*Transport).dialConn() /usr/lib/go/src/net/http/transport.go:1709 +0xc30 net/http.(*Transport).dialConnFor() /usr/lib/go/src/net/http/transport.go:1421 +0x151 ==================
@bcmills
Copy link
Contributor

bcmills commented Jan 19, 2021

Duplicate of #34902

@bcmills bcmills marked this as a duplicate of #34902 Jan 19, 2021
@bcmills bcmills closed this as completed Jan 19, 2021
@bcmills bcmills reopened this Jan 19, 2021
@bcmills
Copy link
Contributor

bcmills commented Jan 19, 2021

Well, hrm. The same data race was reported on #34902 (in #34902 (comment)), but your report here is for go1.15.6 which should have included the fix.

@bcmills
Copy link
Contributor

bcmills commented Jan 19, 2021

CC @katiehockman @FiloSottile @rolandshoemaker (via CL 242598, which was intended to fix #34902)

@bcmills bcmills added the NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one. label Jan 19, 2021
@bcmills bcmills added this to the Backlog milestone Jan 19, 2021
@sleepymole
Copy link
Author

Well, hrm. The same data race was reported on #34902 (in #34902 (comment)), but your report here is for go1.15.6 which should have included the fix.

That fix doesn't work for this issue. The root cause is probably the concurrent writes to the same connection in ReverseProxy.

@neild
Copy link
Contributor

neild commented May 21, 2021

This was fixed by CL 251858, which was backported to go1.16 but not go1.15.

@neild
Copy link
Contributor

neild commented May 21, 2021

Sorry, misread the history: The fix was originally made in go1.16. It was never backported to go1.15.

@dmitshur
Copy link
Contributor

In that case, I think we can close this issue and update its milestone to Go1.16, since that's the Go release it was fixed in.

@dmitshur dmitshur 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 May 22, 2021
@dmitshur dmitshur modified the milestones: Backlog, Go1.16 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 NeedsFix The path to resolution is known, but the work has not been done.
Projects
None yet
Development

No branches or pull requests

5 participants