Repository: go
Issue: x/net,net/http/httputil: ReverseProxy attempts to log each http2 stream cancellation, causing concurrent streams to grow unbounded due to logger buildup
Labels: NeedsInvestigation

**Summary: ReverseProxy backed up on mutex in go logger while cleaning up cancelled HTTP2 streams.**

<!--
Please answer these questions before submitting your issue. Thanks!
-->

### What version of Go are you using (`go version`)?

<pre>
$ go version

go version go1.17.7 darwin/amd64

</pre>

### Does this issue reproduce with the latest release?

Yes - We weren't able to try this, but the httputil code in question has not changed.

### What operating system and processor architecture are you using (`go env`)?

<details><summary><code>go env</code> Output</summary><br><pre>
$ go env

GO111MODULE=""
GOARCH="amd64"
GOBIN=""
GOCACHE="/Users/amandachow/Library/Caches/go-build"
GOENV="/Users/amandachow/Library/Application Support/go/env"
GOEXE=""
GOEXPERIMENT=""
GOFLAGS=""
GOHOSTARCH="amd64"
GOHOSTOS="darwin"
GOINSECURE=""
GOMODCACHE="/Users/amandachow/go/pkg/mod"
GOOS="darwin"
GOPATH="/Users/amandachow/go"
GOPROXY="https://proxy.golang.org,direct"
GOROOT="/usr/local/go"
GOSUMDB="sum.golang.org"
GOTMPDIR=""
GOTOOLDIR="/usr/local/go/pkg/tool/darwin_amd64"
GOVCS=""
GOVERSION="go1.17.7"
GCCGO="gccgo"
AR="ar"
CC="clang"
CXX="clang++"
CGO_ENABLED="1"
GOMOD="/dev/null"
CGO_CFLAGS="-g -O2"
CGO_CPPFLAGS=""
CGO_CXXFLAGS="-g -O2"
CGO_FFLAGS="-g -O2"
CGO_LDFLAGS="-g -O2"
PKG_CONFIG="pkg-config"
GOGCCFLAGS="-fPIC -arch x86_64 -m64 -pthread -fno-caret-diagnostics -Qunused-arguments -fmessage-length=0 -fdebug-prefix-map=/var/folders/_f/1tl8g2w95wx34b7zp53y0kqc0000gp/T/go-build69516959=/tmp/go-build -gno-record-gcc-switches -fno-common"

</pre></details>

### What did you do?

I have a service that uses the httputil ReverseProxy as a load balancer, proxying requests to upstream services. My service averages ~10k requests per second, nearly all of which are streams. The streams are short lived - The P95 stream duration (the duration of time that a finished stream was alive) is 400ms.

I upgraded the x/net version from `v0.0.0-20210929193557-e81a3d93ecf6` to `v0.0.0-20220531201128-c960675eff93`. I confirmed that the change directly after the old version, [http2: refactor request write flow](https://github.com/golang/net/commit/cedda3a722ddc29587099e7176bb992c7c072a60), is the first version that introduces the following symptoms.

### What did you expect to see?

No noticeable behavior change to my service.

### What did you see instead?

My service's number of currently open streams began growing unbounded. When healthy, my service has ~60 concurrent streams - With the upgrade, within 3 minutes it had reached 300k open streams and was continuing to grow. 

I took a goroutine dump and it showed nearly all goroutines were waiting on the [go logger's mutex](https://github.com/golang/go/blob/release-branch.go1.17/src/log/log.go#L165) to [log the stream cancellation](https://github.com/golang/go/blob/release-branch.go1.17/src/net/http/httputil/reverseproxy.go#L461-L464). Example log: (Message is always identical, except for the stream ID)

```
2022/06/03 01:37:59 httputil: ReverseProxy read error during body copy: stream error: stream ID 1403; CANCEL
```

From the pprof:
![Screen Shot 2022-06-03 at 7 27 10 PM](https://ghe.anduril.dev/storage/user/283/files/971987ba-70c8-4d8b-bc56-b64d6b36f430)

I do not set a custom ReverseProxy ErrorLogger. My theory is that due to the [cleanupWriteRequest](https://github.com/golang/net/commit/cedda3a722ddc29587099e7176bb992c7c072a60?diff=unified#diff-e9bd9b4a514c2960ad85405e4a827d83c2decaaac70e9e0158a59db2d05807a7R1274) introduced in the transport.go change, a [`CANCEL`ed](https://github.com/golang/net/blob/c960675eff93b7ce235fa4b1578d83fa48ea129c/http2/errors.go#L24) stream will now cause http2's Transport to return an error in RoundTrip, which is then [consumed by ReverseProxy](https://github.com/golang/go/blob/release-branch.go1.17/src/net/http/httputil/reverseproxy.go#L298). ReverseProxy attempts to log each instance of this. Since the service has a high workload (rate of stream requests proxied), the logger falls behind and causes the buildup of concurrent streams.

It looks like ReverseProxy [attempts to filter out other request cancellation errors](https://github.com/golang/go/blob/release-branch.go1.17/src/net/http/httputil/reverseproxy.go#L462-L464) - io.EOF and context.Canceled - and not log in those cases. It seems like it should also filter out http2 stream cancellation?

To test this theory, I set the ReverseProxy ErrorLogger to a custom go Logger with a no-op io.Writer:

```
type noOpWriter struct {}

func (noOpWriter) Write(_ []byte) (n int, err error) {return 0, nil}
[...]
&httputil.ReverseProxy{
		ErrorLog: log.New(noOpWriter{}, "", 0),
		[...]
}
```

With this change, using x/net `v0.0.0-20220531201128-c960675eff93`, the service performed as expected - The concurrent streams no longer grew unbounded.