net/http: memory leak due to a large number of items in transport.reqCanceler

[huozby]

net/http: memory leak due to a large number of items in transport.reqCanceler

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

$ go version
go version go1.19.10 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="on"
GOARCH="amd64"
GOBIN="/home/xxx/codes/go/bin"
GOCACHE="/home/xxx/.cache/go-build"
GOENV="/home/xxx/.config/go/env"
GOEXE=""
GOEXPERIMENT=""
GOFLAGS=""
GOHOSTARCH="amd64"
GOHOSTOS="linux"
GOINSECURE=""
GOMODCACHE="/home/xxx/codes/go/pkg/mod"
GONOPROXY=""
GONOSUMDB=""
GOOS="linux"
GOPATH="/home/xxx/codes/go"
GOPRIVATE=""
GOPROXY="https://goproxy.cn,direct"
GOROOT="/usr/local/go"
GOSUMDB="sum.golang.org"
GOTMPDIR=""
GOTOOLDIR="/usr/local/go/pkg/tool/linux_amd64"
GOVCS=""
GOVERSION="go1.19.10"
GCCGO="gccgo"
GOAMD64="v1"
AR="ar"
CC="gcc"
CXX="g++"
CGO_ENABLED="1"
GOMOD="/home/xxx/codes/transport-memory-leak/go.mod"
GOWORK=""
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 -Wl,--no-gc-sections -fmessage-length=0 -fdebug-prefix-map=/tmp/go-build3608446700=/tmp/go-build -gno-record-gcc-switches"

What did you do?

When using http.ReverseProxy to build http ReverseProxy, We found memory leak in http.Transport in certain case.

There is a client , proxy and server as bellow, :

client ----->  proxy -----> server

reproduce condition:

1. client concurrently visit proxy（maybe 200+ concurrency）.
2. server receive request head and return response immediately(server response before receive entired request body).

proxy code:
https://go.dev/play/p/dRzdohisHy5?v=goprev

server code:
https://go.dev/play/p/iyBuNbJWKVi?v=goprev

client code:
https://go.dev/play/p/7gPDzt9vrkw?v=goprev

What did you expect to see?

http.ReverseProxy perform well and has no memory leak.

What did you see instead?

proxy error logs:

2023/08/02 10:37:52 httputil: ReverseProxy read error during body copy: read tcp 127.0.0.1:53946->127.0.0.1:9090: use of closed network connection

PProf file shows that memory leak in transport:

dlv debug info shows the memory leak is caused by reqCanceler. 1900+ items in the reqCanceller map should be gc after we stop client, but after a long time, they are still there.

a sample request(proxy -> server) diagram of tcpdump.

Source code and some files for further debug:
transport-memory-leak.zip

[mauri870]

Issue #51354 also claims leaks in reqCanceler under certain conditions

If you get the chance try to reproduce the issue with this patch, I believe this is the fix the author of the other issue suggested:

diff --git a/src/net/http/transport.go b/src/net/http/transport.go
index c07352b018..d30eb79508 100644
--- a/src/net/http/transport.go
+++ b/src/net/http/transport.go
@@ -2248,7 +2248,7 @@ func (pc *persistConn) readLoop() {
 			}
 		case <-rc.req.Cancel:
 			alive = false
-			pc.t.CancelRequest(rc.req)
+			pc.t.cancelRequest(rc.cancelKey, errRequestCanceled)
 		case <-rc.req.Context().Done():
 			alive = false
 			pc.t.cancelRequest(rc.cancelKey, rc.req.Context().Err())

[AlexanderYastrebov]

I've created #61724 to fix #51354

The test TestCancelRequestWithBodyWithChannel I added with such change

diff --git a/src/net/http/transport.go b/src/net/http/transport.go
index d30eb79508..fb3f9e168d 100644
--- a/src/net/http/transport.go
+++ b/src/net/http/transport.go
@@ -26,6 +26,7 @@ import (
        "net/textproto"
        "net/url"
        "reflect"
+       "runtime"
        "strings"
        "sync"
        "sync/atomic"
@@ -2248,6 +2249,9 @@ func (pc *persistConn) readLoop() {
                        }
                case <-rc.req.Cancel:
                        alive = false
+                       for _, v := range pc.t.reqCanceler {
+                               fmt.Printf(">> %v\n", runtime.FuncForPC(reflect.ValueOf(v).Pointer()).Name())
+                       }
                        pc.t.cancelRequest(rc.cancelKey, errRequestCanceled)
                case <-rc.req.Context().Done():
                        alive = false

outputs >> net/http.(*persistConn).cancelRequest-fm which matches the description so there are chances it will fix this one as well.

[munding]

I encountered the same issue while writing a forward HTTP proxy.
using transport.DisableKeepAlives = true temporarily resolved the memory leak issue.

[huozby]

@mauri870 @AlexanderYastrebov Thanks a lot for your great work. I test the solution you mentioned above, but it doesn't work.
The result shows:

Maybe my case is much more complicated. My team members and I read go net http source code, the memory leak could happen in src/net/http/transport.go:2230.

		// Before looping back to the top of this function and peeking on
		// the bufio.Reader, wait for the caller goroutine to finish
		// reading the response body. (or for cancellation or death)
		select {
		case bodyEOF := <-waitForBodyRead:
			replaced := pc.t.replaceReqCanceler(rc.cancelKey, nil) // before pc might return to idle pool
			alive = alive &&
				bodyEOF &&
				!pc.sawEOF &&
				pc.wroteRequest() &&
				replaced && tryPutIdleConn(trace)
			if bodyEOF {
				eofc <- struct{}{}
			}
		case <-rc.req.Cancel:
			alive = false
			pc.t.CancelRequest(rc.req)
		case <-rc.req.Context().Done():
			alive = false
			pc.t.cancelRequest(rc.cancelKey, rc.req.Context().Err())
		case <-pc.closech:  // memroy may leak here. pc closed, rc.cancelKey would never be removed.
			alive = false
		}

there could be a unexpected case： case bodyEOF := <-waitForBodyRead is still blocked(the caller goroutine is reading the response body.)， pconn is closed by somewhere. Thus, rc.cancelKey would never clean.

pc.closech would be set here: src/net/http/transport.go:2716 which is called by src/net/http/transport.go:2696. There several callers call pc.close, which one could cause the problem?

we guess that in src/net/http/transport.go:2418 calls pc.close(err). In a rare case(or special timings), there is a writeErr(http: invalid Read on closed) , the request body not completely send to server, meanwhile the caller goroutine is reading the response body, pc.close(err) is called(could it be possible?).

			pc.writeErrCh <- err // to the body reader, which might recycle us
			wr.ch <- err         // to the roundTrip function
			if err != nil {
				pc.close(err)
				return
			}

In addition，we found a possible solution to solve this memory leak problem, bu we are not sure the impact(would it impact normal request?). Maybe it is safe to remove rc.cancelKey here, for pconn has already been closed.

		// Before looping back to the top of this function and peeking on
		// the bufio.Reader, wait for the caller goroutine to finish
		// reading the response body. (or for cancellation or death)
		select {
		case bodyEOF := <-waitForBodyRead:
			replaced := pc.t.replaceReqCanceler(rc.cancelKey, nil) // before pc might return to idle pool
			alive = alive &&
				bodyEOF &&
				!pc.sawEOF &&
				pc.wroteRequest() &&
				replaced && tryPutIdleConn(trace)
			if bodyEOF {
				eofc <- struct{}{}
			}
		case <-rc.req.Cancel:
			alive = false
			pc.t.CancelRequest(rc.req)
		case <-rc.req.Context().Done():
			alive = false
			pc.t.cancelRequest(rc.cancelKey, rc.req.Context().Err())
		case <-pc.closech: // memroy may leak here. pc closed, rc.cancelKey would never be removed.
			alive = false
                        pc.t.replaceReqCanceler(rc.cancelKey, nil) // remove rc.cancelKey when pconn has been closed
		}

In out test, this change indeed help to solve the problem, but it is really ok or is there other better solutions?

[huozby]

I encountered the same issue while writing a forward HTTP proxy. using transport.DisableKeepAlives = true temporarily resolved the memory leak issue.

memory leak of transport may has several cause, you could use gcore to get core dump file of the process. And use dlv core <app_binary> core. to analyse the memory problem, to find which objects has great numbers and it is unusual.

In this issues(in my case), I have test the DisableKeepAlives: true, option of http.Transport, the memory still keep growing.

[AlexanderYastrebov]

@hzzzzzb

In a rare case(or special timings), there is a writeErr(http: invalid Read on closed) , the request body not completely send to server, meanwhile the caller goroutine is reading the response body, pc.close(err) is called(could it be possible?).

I think you are right.
I've modified your proxy to print reqCanceler

func getUnexportedFieldLen(field reflect.Value) int {
	return reflect.NewAt(field.Type(), unsafe.Pointer(field.UnsafeAddr())).Elem().Len()
}

func countReqCanceler(t *http.Transport) int {
	return getUnexportedFieldLen(reflect.ValueOf(t).Elem().FieldByName("reqCanceler"))
}

...
	reverseProxy.ErrorLog = log.New(io.Discard, "", 0)
	var requests atomic.Int64

	http.HandleFunc("/", func(w http.ResponseWriter, r *http.Request) {
		reverseProxy.ServeHTTP(w, r)

		n := requests.Add(1)
		if n%1000 == 0 {
			fmt.Println("proxy: reqCanceler:", countReqCanceler(t))
		}
	})
...

and the number grows even with #51354 fix but stops growing with

		case <-pc.closech:
			alive = false
			pc.t.cancelRequest(rc.cancelKey, errRequestCanceled)
                        // pc.t.replaceReqCanceler(rc.cancelKey, nil) // or this

I've added a second channel to send close error, it is indeed ErrBodyReadAfterClose, I correlated it to

go/src/net/http/transport.go

Lines 2422 to 2424 in ed8cbaf

	case wr := <-pc.writech:
	startBytesWritten := pc.nwrite
	err := wr.req.Request.write(pc.bw, pc.isProxy, wr.req.extra, pc.waitForContinue(wr.continueCh))

where it calls pc.close

go/src/net/http/transport.go

Lines 2444 to 2449 in ed8cbaf

	pc.writeErrCh <- err // to the body reader, which might recycle us
	wr.ch <- err // to the roundTrip function
	if err != nil {
	pc.close(err)
	return
	}

I think the problem could be reverseproxy specific due to the way it works similar to #46866

I could not come up with a reproducer test yet that we'd need to make a proper fix.

memory leak of transport may has several cause

Indeed, see e.g. #50798 and #43966

[gopherbot]

Change https://go.dev/cl/515796 mentions this issue: net/http: fix request canceler leak on connection close

[ianlancetaylor]

CC @neild @bradfitz

[WenlongWang]

any update on this ?