net/http: context cancellation can leave HTTP client with deadlocked HTTP/1.1 connections in Go1.22

[tibbes]

Go version

go version go1.22.0 darwin/arm64

Output of go env in your module/workspace:

GO111MODULE=''
GOARCH='arm64'
GOBIN=''
GOCACHE='/Users/tibbes/Library/Caches/go-build'
GOENV='/Users/tibbes/Library/Application Support/go/env'
GOEXE=''
GOEXPERIMENT=''
GOFLAGS=''
GOHOSTARCH='arm64'
GOHOSTOS='darwin'
GOINSECURE=''
GOMODCACHE='/Users/tibbes/go/pkg/mod'
GONOPROXY=''
GONOSUMDB=''
GOOS='darwin'
GOPATH='/Users/tibbes/go'
GOPRIVATE=''
GOPROXY='https://proxy.golang.org,direct'
GOROOT='/usr/local/go'
GOSUMDB='sum.golang.org'
GOTMPDIR=''
GOTOOLCHAIN='auto'
GOTOOLDIR='/usr/local/go/pkg/tool/darwin_arm64'
GOVCS=''
GOVERSION='go1.22.0'
GCCGO='gccgo'
AR='ar'
CC='clang'
CXX='clang++'
CGO_ENABLED='1'
GOMOD='/dev/null'
GOWORK=''
CGO_CFLAGS='-O2 -g'
CGO_CPPFLAGS=''
CGO_CXXFLAGS='-O2 -g'
CGO_FFLAGS='-O2 -g'
CGO_LDFLAGS='-O2 -g'
PKG_CONFIG='pkg-config'
GOGCCFLAGS='-fPIC -arch arm64 -pthread -fno-caret-diagnostics -Qunused-arguments -fmessage-length=0 -ffile-prefix-map=/var/folders/18/_76dkntd3f76rb3fql9q5jrw0000gn/T/go-build1573940289=/tmp/go-build -gno-record-gcc-switches -fno-common'

What did you do?

There seems to be a bug in go 1.22.0 (not present in earlier versions), that can leave an HTTP client deadlocked when MaxConnsPerHost is used.

The following program reproduces the problem. It:

• starts a local HTTP server
• creates an HTTP client with MaxConnsPerHost, MaxIdleConns, and MaxIdleConnsPerHost all set to 1
• sends 3 requests (with a 1s context timeout) to show the client is working normally
• stresses the HTTP client by sending 10 requests sequentially with a 1 microsecond context timeout
• attempts to send 3 requests (with a 1s context timeout)

package main

import (
	"bytes"
	"context"
	"fmt"
	"net/http"
	"time"
)

func main() {
	go serve()
	client := createHTTPClient()

	fmt.Println("=== Before ===")
	fmt.Println(download(client, 1*time.Second))
	fmt.Println(download(client, 1*time.Second))
	fmt.Println(download(client, 1*time.Second))

	// Try and put the connection in a bad state
	for i := 0; i < 10; i++ {
		download(client, time.Microsecond)
	}
	fmt.Println()

	fmt.Println("=== After ===")
	fmt.Println(download(client, 1*time.Second))
	fmt.Println(download(client, 1*time.Second))
	fmt.Println(download(client, 1*time.Second))
}

func download(client *http.Client, timeout time.Duration) (string, error) {
	ctx, cancel := context.WithTimeout(context.Background(), timeout)
	defer cancel()
	req, err := http.NewRequestWithContext(ctx, http.MethodGet, "http://127.0.0.1:8888", nil)
	if err != nil {
		return "", err
	}

	resp, err := client.Do(req)
	if err != nil {
		return "", err
	}
	defer resp.Body.Close()

	buf := bytes.Buffer{}
	_, err = buf.ReadFrom(resp.Body)
	if err != nil {
		return "", err
	}
	return buf.String(), nil
}

func createHTTPClient() *http.Client {
	// Make sure that the same connection is reused.
	transport := &http.Transport{
		MaxIdleConns:        1,
		MaxIdleConnsPerHost: 1,
		MaxConnsPerHost:     1,
	}
	return &http.Client{Transport: transport}
}

func serve() {
	http.ListenAndServe("127.0.0.1:8888", http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
		fmt.Println("Server received a request")
		w.Write([]byte("Hello, world!"))
	}))
}

What did you see happen?

With go 1.22.0, the HTTP client is not usable after stressing it with short timeouts:

=== Before ===
Server received a request
Hello, world! <nil>
Server received a request
Hello, world! <nil>
Server received a request
Hello, world! <nil>
Server received a request

=== After ===
 Get "http://127.0.0.1:8888": context deadline exceeded
 Get "http://127.0.0.1:8888": context deadline exceeded
 Get "http://127.0.0.1:8888": context deadline exceeded

What did you expect to see?

I would expect to see the same behaviour as go 1.21.7:

=== Before ===
Server received a request
Hello, world! <nil>
Server received a request
Hello, world! <nil>
Server received a request
Hello, world! <nil>

=== After ===
Server received a request
Server received a request
Hello, world! <nil>
Server received a request
Hello, world! <nil>
Server received a request
Hello, world! <nil>

[tibbes]

Digging into this further, it looks like an accounting bug triggered by 38a0c5b.

In particular, the early return in Transport.dialConnFor (if ctx == nil) does not call t.decConnsPerHost(w.key):

	ctx := w.getCtxForDial()
	if ctx == nil {
		return
	}

However, there is a decrement lower down, which seems to indicate that the contract of this function was supposed to be to call t.decConnsPerHost(w.key) if a connection is not successfully created.

        if err != nil {
                t.decConnsPerHost(w.key)
        }

Certainly, the following patch seems to solve the problem:

diff --git a/src/net/http/transport.go b/src/net/http/transport.go
index 2a549a9576..411f6b2912 100644
--- a/src/net/http/transport.go
+++ b/src/net/http/transport.go
@@ -1478,6 +1478,7 @@ func (t *Transport) dialConnFor(w *wantConn) {
        defer w.afterDial()
        ctx := w.getCtxForDial()
        if ctx == nil {
+               t.decConnsPerHost(w.key)
                return
        }

/cc @AlexanderYastrebov, @neild, @bradfitz

[tibbes]

I've added a unit-test that triggers this problem, along with the patch I mentioned in my previous comment, and opened https://go-review.googlesource.com/c/go/+/564036

[gopherbot]

Change https://go.dev/cl/564036 mentions this issue: net/http: add missing call to decConnsPerHost

[bcmills]

(attn @neild)

[neild]

Thanks for the nice analysis (and the fix!).

@gopherbot please open backport issue for go1.21. This is significant regression with no workaround.

[gopherbot]

Backport issue(s) opened: #65759 (for 1.21).

Remember to create the cherry-pick CL(s) as soon as the patch is submitted to master, according to https://go.dev/wiki/MinorReleases.

[tibbes]

Thanks @neild, but I think you mean backport for 1.22!