net/http: setting Timeout in http.Client produces unexpected "context canceled" on body.Close

[tim-oster]

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

$ go version
go version go1.17.3 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/user/.cache/go-build"
GOENV="/home/user/.config/go/env"
GOEXE=""
GOEXPERIMENT=""
GOFLAGS=""
GOHOSTARCH="amd64"
GOHOSTOS="linux"
GOINSECURE=""
GOMODCACHE="/home/user/go/pkg/mod"
GONOPROXY=""
GONOSUMDB=""
GOOS="linux"
GOPATH="/home/user/go"
GOPRIVATE=""
GOPROXY="https://proxy.golang.org,direct"
GOROOT="/home/user/go/go1.17.3"
GOSUMDB="sum.golang.org"
GOTMPDIR=""
GOTOOLDIR="/home/user/go/go1.17.3/pkg/tool/linux_amd64"
GOVCS=""
GOVERSION="go1.17.3"
GCCGO="/usr/bin/gccgo"
AR="ar"
CC="gcc"
CXX="g++"
CGO_ENABLED="1"
GOMOD="/home/user/dev/testing/go.mod"
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-build3690665818=/tmp/go-build -gno-record-gcc-switches"

What did you do?

In our production code, we set the Timeout propery on our http.Client to limit the maximum request duration. These operations started to fail after upgrading to go1.17.3. The example code returns the expected result when executed using go1.17.2.

package main

import (
	"fmt"
	"io"
	"net/http"
	"time"
)

func main() {
	fmt.Println("these partially fail in go 1.17.3:")
	tryClient(&http.Client{Timeout: time.Hour}, 10)

	fmt.Println()

	fmt.Println("these always work:")
	tryClient(&http.Client{}, 10)
}

func tryClient(client *http.Client, n int) {
	for i := 0; i < n; i++ {
		body, err := makeRequest(client)
		if err != nil {
			fmt.Println(err)
			continue
		}
		fmt.Println("body received", len(body))
	}
}

func makeRequest(client *http.Client) ([]byte, error) {
	req, err := http.NewRequest(http.MethodGet, "https://golang.org", nil)
	if err != nil {
		return nil, fmt.Errorf("http.NewRequest: %w", err)
	}
	resp, err := client.Do(req)
	if err != nil {
		return nil, fmt.Errorf("client.Do: %w", err)
	}
	body, err := io.ReadAll(resp.Body)
	if err != nil {
		return nil, fmt.Errorf("io.ReadAll: %w", err)
	}
	err = resp.Body.Close()
	if err != nil {
		return nil, fmt.Errorf("resp.Body.Close: %w", err)
	}
	return body, nil
}

What did you expect to see?

The expected result is that all requests bodies can be closed successfully as the timeout of 1 hour should not have been reached.

these partially fail in go 1.17.3:
body received 9964
body received 9964
body received 9964
...

these always work:
body received 9964
body received 9964
body received 9964
...

What did you see instead?

Instead, when executing using go1.17.3, some requests work while others return a context canceled when the body is closed.

these partially fail in go 1.17.3:
body received 9964
body received 9964
resp.Body.Close: context canceled
resp.Body.Close: context canceled
resp.Body.Close: context canceled
body received 9964
body received 9964
body received 9964
resp.Body.Close: context canceled
resp.Body.Close: context canceled

these always work:
body received 9964
body received 9964
body received 9964
body received 9964
body received 9964
body received 9964
body received 9964

[seankhliao]

Duplicate of #49517