net/http/httputil: DumpRequestOut can lock up when request cancelled

[nerd2]

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

$ go version
go version go1.14.1 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/sam/.cache/go-build"
GOENV="/home/sam/.config/go/env"
GOEXE=""
GOFLAGS=""
GOHOSTARCH="amd64"
GOHOSTOS="linux"
GOINSECURE=""
GONOPROXY=""
GONOSUMDB=""
GOOS="linux"
GOPATH="/home/sam/go/"
GOPRIVATE=""
GOPROXY="https://proxy.golang.org,direct"
GOROOT="/usr/local/go"
GOSUMDB="sum.golang.org"
GOTMPDIR=""
GOTOOLDIR="/usr/local/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-build016439400=/tmp/go-build -gno-record-gcc-switches"

What did you do?

If a request is cancelled during net/http httputil.DumpRequestOut, the function can sometimes fail to return

https://play.golang.org/p/-tRCoKCk6XB

What did you expect to see?

The program terminate

What did you see instead?

The program hangs.

Running in dlv, I can two problems. In the locked up case:

  Goroutine 82 - User: /usr/local/go/src/net/http/httputil/dump.go:150 net/http/httputil.DumpRequestOut (0x77ede4)
	Labels: "it":"75"

In this case, the quitReadCh go function has finished (sent on the reader chan) but the roundtrip has still errored so the dump has locked up

We also have leaked quit goroutines

  Goroutine 627 - User: /usr/local/go/src/net/http/httputil/dump.go:177 net/http/httputil.(*delegateReader).Read (0x77f34b)
	Labels: "it":"38"

[gopherbot]

Change https://golang.org/cl/227857 mentions this issue: net/http: httputil: reverse quit logic in DumpRequestOut to fix lockup

[andybons]

@bcmills @bradfitz

[fraenkel]

@nerd2 There is a data race in the sample program you provided.

I believe that using DumpRequestOut while executing the Request is invalid although not documented. once RoundTrip is underway, the request.Body may be altered to handle retries as well as reading the actual body. DumpRequestOut is also manipulating the req.Body which causes the data race mentioned.

[nerd2]

As in #37669, the lock up is internal to DumpRequestOut due to a race between the main thread and the quit and is nothing to do with external body manipulation.

I have updated the example to remove the actual request and put it here:
https://github.com/nerd2/bugs/blob/master/38352/dumplock.go

If you have a chance to look at the PR in https://github.com/golang/go/pull/38353/files perhaps you can see the issue?

[fraenkel]

I can't seem to reproduce the hang. Both your examples always execute and complete.

[nerd2]

Try adding a 1 second sleep on line 2277 of net/http/transport.go, before the select

[fraenkel]

With the 1 second delay, I get a race:

==================
WARNING: DATA RACE
Read at 0x00c0002b6340 by goroutine 78:
  net/http.newTransferWriter()
      net/http/transfer.go:83 +0x1582
  net/http.(*Request).write()
      net/http/request.go:631 +0x614
  net/http.(*persistConn).writeLoop()
      net/http/transport.go:2283 +0x33e

Previous write at 0x00c0002b6340 by goroutine 12:
  net/http/httputil.DumpRequestOut()
      net/http/httputil/dump.go:147 +0x7cb
  main.testDumpRoundTripRace()
      command-line-arguments/issue38352.go:61 +0x6a0
  main.main.func1.1()
      command-line-arguments/issue38352.go:30 +0x5b
  runtime/pprof.Do()
      runtime/pprof/runtime.go:40 +0x11c
  main.main.func1()
      command-line-arguments/issue38352.go:29 +0x134

[fraenkel]

Or

==================
WARNING: DATA RACE
Read at 0x00c0003a2940 by goroutine 145:
  net/http.newTransferWriter()
      net/http/transfer.go:83 +0x1582
  net/http.(*Request).write()
      net/http/request.go:631 +0x614
  net/http.(*persistConn).writeLoop()
      net/http/transport.go:2283 +0x33e

Previous write at 0x00c0003a2940 by goroutine 136:
  ??()
      -:0 +0xffffffffffffffff
  encoding/base64.(*Encoding).EncodeToString()
      encoding/base64/base64.go:179 +0xf6
  main.randomBase64EncodedString()
      command-line-arguments/issue38352.go:75 +0x113
  main.testDumpRoundTripRace()
      command-line-arguments/issue38352.go:51 +0x160
  main.main.func1.1()
      command-line-arguments/issue38352.go:30 +0x5b
  runtime/pprof.Do()
      runtime/pprof/runtime.go:40 +0x11c
  main.main.func1()
      command-line-arguments/issue38352.go:29 +0x134

[nerd2]

With the 1 second delay, I get a race:

==================
WARNING: DATA RACE
Read at 0x00c0002b6340 by goroutine 78:
  net/http.newTransferWriter()
      net/http/transfer.go:83 +0x1582
  net/http.(*Request).write()
      net/http/request.go:631 +0x614
  net/http.(*persistConn).writeLoop()
      net/http/transport.go:2283 +0x33e

Previous write at 0x00c0002b6340 by goroutine 12:
  net/http/httputil.DumpRequestOut()
      net/http/httputil/dump.go:147 +0x7cb
  main.testDumpRoundTripRace()
      command-line-arguments/issue38352.go:61 +0x6a0
  main.main.func1.1()
      command-line-arguments/issue38352.go:30 +0x5b
  runtime/pprof.Do()
      runtime/pprof/runtime.go:40 +0x11c
  main.main.func1()
      command-line-arguments/issue38352.go:29 +0x134

#37669

[gopherbot]

Change https://golang.org/cl/232798 mentions this issue: net/http/httputil: Fix deadlock in DumpRequestOut

[stevenh]

We have request debugging in our app which uses httputil.DumpRequestOut and this deadlock took the entire app down. Given the original PR has been sat with changes pending for a while I had a look separately.

The test case added also triggered the above data race, for which I have a two part fix https://golang.org/cl/232798 and https://golang.org/cl/232799