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

go version go1.20.3 linux/amd6

Does this issue reproduce with the latest release?

Yes

What operating system and processor architecture are you using (go env)?

$ go env
GO111MODULE=""

GOARCH="amd64"

GOBIN=""

GOCACHE="/root/.cache/go-build"

GOENV="/root/.config/go/env"

GOEXE=""

GOEXPERIMENT=""

GOFLAGS=""

GOHOSTARCH="amd64"

GOHOSTOS="linux"

GOINSECURE=""

GOMODCACHE="/go/pkg/mod"

GONOPROXY=""

GONOSUMDB=""

GOOS="linux"

GOPATH="/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"

GOVCS=""

GOVERSION="go1.20.3"

GCCGO="gccgo"

GOAMD64="v1"

AR="ar"

CC="gcc"

CXX="g++"

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 -m64 -pthread -Wl,--no-gc-sections -fmessage-length=0 -fdebug-prefix-map=/tmp/go-build2968508177=/tmp/go-build -gno-record-gcc-switches"

What did you do?

A connection is established to a remote server (using HTTP/2 where available) and requests are sent periodically over this connection - it's essentially a write pipeline working through a queue sequentially.

This being the internet, sometimes bad things happen to individual connections and packets go awry.

If a timeout occurs, the connection will (well, should) be closed:

resp, err := client.Do(req.WithContext(ctx))
if err != nil {
            // Attempt to tear down the connection
            fmt.Println("Timed out")
            client.CloseIdleConnections()
        }

(that CloseIdleConnections() call is sourced from #36026)

What did you expect to see?

On the next request (generally a retry), a new connection should be established (if possible) and writes should resume.

What did you see instead?

The underlying TCP connection does not get closed - the kernel sits retransmitting the most recent packets (until net.ipv4.tcp_retries2 is reached about 17mins later).

Subsequent requests all attempt to use the dead connection and so time out.

Repro

The following can be used to help repro the behaviour

package main

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

func main() {

    // The url to place requests to
    url := "https://www.bentasker.co.uk/"

    // Create an empty context
    ctx := context.Background()

    // Create an io.Reader from a string to act as the request body
    bodystring := "foo\nbar\nsed"
    myReader := strings.NewReader(bodystring)

    // build client and request
    client := http.Client{
        Timeout: 5 * time.Second,
    }

    // Set up an infinite loop to place requests from
    for {
        req, err := http.NewRequest("POST", url, myReader)
        if err != nil {
            fmt.Println("boo")
        }
        req.Header.Set("Content-Type", "text/plain; charset=utf-8")

        resp, err := client.Do(req.WithContext(ctx))

        if err != nil {
            // Attempt to tear down the connection
            fmt.Println("Timed out")
            client.CloseIdleConnections()
        } else {
            fmt.Println(resp.StatusCode)
        }

        time.Sleep(time.Second)
    }
}

If you build and run that, you should see 403 printed on a new line every second or so (it being 403 isn't pertinent here, it's just easy/convenient to generate)

Check which source port is being used

root@ratchett:/home/ben/tmp/go_repro# netstat -anp | grep main
tcp        0   2185 192.168.3.217:50446     143.244.38.137:443      ESTABLISHED 2389361/./main   

and then block it in iptables to break the return path

iptables -I INPUT -p tcp --dport 50446 -j DROP

The script should stop printing 403s and after around 5s will print Timed out.

Although the code calls CloseIdleConnections(), it'll silently fail to do anything to the connection (more below)

Subsequent attempts will also print Time out and re-running netstat will show that same connection still in an ESTABLISHED state. If you take a packet capture it'll show re-transmission of whatever packet we interrupted by adding the rule.

If you remove the iptables rule once the remote server starts sending resets, the kernel will tear down the connection and requests will go back to behaving as they should.

Hacking it out

It is actually possible to work around this at the caller's level, although it's not exactly pleasant to look at.

        if err != nil {
            // Attempt to tear down the connection
            fmt.Println("Timed out")

            // prompt the handler into marking the connection as not
           // being reusable
            req.Header.Set("Connection", "close")
            client.Do(req.WithContext(ctx))

            // this is no longer required
            // client.CloseIdleConnections()
        } else {
            fmt.Println(resp.StatusCode)
        }

This works because net/http2 specifically checks for a Connection: close header before placing a request, and set's doNotReuse on the ClientConn, so when the next request comes around, the connection won't be used even if it is otherwise considered still active.

Underlying Issue

The underlying seems to be that there's some raciness between normal stream closure and closeIdleConnections().

The crucial check is here

	if len(cc.streams) > 0 || cc.streamsReserved > 0 {
		cc.mu.Unlock()
		return
	}

If the map cc.streams contains any entries, the connection isn't considered idle and therefore can't be closed.

Dropping some prints in as a quick test shows it's this conditional we're failing at

@@ -7984,6 +7990,8 @@ func (cc *http2ClientConn) forceCloseConn() {
 func (cc *http2ClientConn) closeIfIdle() {
        cc.mu.Lock()
        if len(cc.streams) > 0 || cc.streamsReserved > 0 {
+                fmt.Println("Refusing to close - streams:", len(cc.streams), " reserved:", cc.streamsReserved)
+
                cc.mu.Unlock()
                return
        }

Gives

Refusing to close - streams: 1  reserved: 0

net/http2 does actually try to tidy up the streams, doRequest calls cleanupWriteRequest which ultimately drops the broken stream.

Adding some more prints though, shows that this only tends to happen after the caller has had opportunity to call closeIdleConnections():

Refusing to close - streams: 1  reserved: 0
Doing cleanup context deadline exceeded
Cleanup stream 5 got err context deadline exceeded
Must close body:  false
Got err Sent headers
Writing reset
Forgetting ID  5
werr  <nil>
closing

The string Forgetting ID was added here.

Raciness

Timings definitely seem to be important here - if the time.Sleep call in the repro is adjusted to wait 5 seconds, you'll sometimes see a string of timeouts followed by writes recovering.

That's not the only raciness though.

Stream closures/timeouts etc are handled by a select statement here

	for {
		select {
		case <-cs.peerClosed:
			return nil
		case <-respHeaderTimer:
			return errTimeout
		case <-respHeaderRecv:
			respHeaderRecv = nil
			respHeaderTimer = nil // keep waiting for END_STREAM
		case <-cs.abort:
			return cs.abortErr
		case <-ctx.Done():
			return ctx.Err()
		case <-cs.reqCancel:
			return errRequestCanceled
		}
	}

Sometimes this is triggered by cs.abort and sometimes by ctx.Done(). This appears to be as a result of an attempt to abort the stream when the context hits deadline - so there's an element of potluck in terms of which gets through (I've not dug into this in too much depth though).

TL:DR

CloseIdleConnections() relies on closeIfIdle() which will close a connection only if there are no active streams on that connection.

However, when a timeout occurs, there may be a delay before the stream is closed (leaving it visible to closeIfIdle()).

By the time the stream closure occurs, the timeout has already been bubbled up to the caller, who may then choose to call CloseIdleConnections() knowing that the connection has failed.

Because the dead connection does not get closed by this call, it remains available for use by the next request.

The result is that requests will fail until the kernel itself gives up on the connection, or a RST or FIN makes it through from the remote end.