net/http: 1.17.3 setting http.Client.Timeout returns context cancelled on Body.Close

[andresusanto]

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="/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.17.3"
GCCGO="gccgo"
AR="ar"
CC="gcc"
CXX="g++"
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 -m64 -pthread -fmessage-length=0 -fdebug-prefix-map=/tmp/go-build114244718=/tmp/go-build -gno-record-gcc-switches"

What did you do?

We use "net/http" with timeout specified as following:

// client construction looks like this
        x.client = &http.Client{
            Transport: &http.Transport{
                MaxIdleConnsPerHost: 10,
            },
            Timeout: 1 * time.Second,
        }


// somewhere we use the client like this:
	req, err := http.NewRequest(http.MethodGet, "< some url >" , nil)
        // ...
        // ...
        log.Debug("Sending request")
	resp, err := x.client.Do(req)
	if err != nil {
		return nil, err
	}

	defer func(){
              err := resp.Body.Close()
              if err != nil {
                    	log.WithField("err", err).Error("Error when closing resp Body")
              }
        }()

	if resp.StatusCode != http.StatusOK {
		body := ""
		if b, err := io.ReadAll(resp.Body); err == nil {
			body = string(b)
		}
		return nil, errors.Errorf("xxxx %v, %v", resp.StatusCode, body)
	}

	xxxx := someStruct{}
	err = json.NewDecoder(resp.Body).Decode(&xxxx)
	if err != nil {
		return nil, err
	}

	log.WithField("data", xxxx).Debug("Received tiles response")

	return xxxx, nil

What did you expect to see?

We expected to close the resp.Body with no error regardless whether requests were successful or not.

	defer func(){
              err := resp.Body.Close()
              if err != nil {
                    	log.WithField("err", err).Error("Error when closing resp Body")
              }
        }()

What did you see instead?

We saw an intermittent context canceled error happening when closing resp.Body even when the requests were successful and took far less than the specified timeout duration.

When we downgraded to go1.17.2 the issue disappeared.

I managed to create this small program that behaves differently when being run using go1.17.3 and go.17.2:

package main

import (
	"context"
	"fmt"
	"io"
	"math/rand"
	"net/http"
	"time"
)

func req(client *http.Client, i int) {
	time.Sleep(time.Duration(rand.Int31n(100)) * time.Millisecond)

	req, err := http.NewRequest(http.MethodGet, "https://www.google.com", nil)
	if err != nil {
		fmt.Println("ERROR 0", err)
		return
	}

	ctx, cancel := context.WithCancel(context.Background())
	req = req.WithContext(ctx)

	resp, err := client.Do(req)

	if err != nil {
		fmt.Println("ERROR 1")
		cancel()
		return
	}

	defer func() {
		cancel()
		err := resp.Body.Close()
		if err != nil {
			fmt.Println("ERROR WHEN CLOSING BODY!!", err)
		} else {
			fmt.Println(i, "Closing Body OK")
		}
	}()

	if resp.StatusCode != http.StatusOK {
		body := ""
		if b, err := io.ReadAll(resp.Body); err == nil {
			body = string(b)
		}
		fmt.Println(i, "ERROR STATUS CODE", body)
	}

}

func main() {
	client := &http.Client{
		Transport: &http.Transport{
			MaxIdleConnsPerHost: 10,
		},
	}

	for i := 0; i < 100; i++ {
		go req(client, i)
	}

	time.Sleep(10 * time.Second)
}

running with **go1.17.3**

ERROR WHEN CLOSING BODY!! context canceled
ERROR WHEN CLOSING BODY!! context canceled
42 Closing Body OK
78 Closing Body OK
ERROR WHEN CLOSING BODY!! context canceled
ERROR WHEN CLOSING BODY!! context canceled
ERROR WHEN CLOSING BODY!! context canceled
ERROR WHEN CLOSING BODY!! context canceled
53 Closing Body OK
ERROR WHEN CLOSING BODY!! context canceled
ERROR WHEN CLOSING BODY!! context canceled
ERROR WHEN CLOSING BODY!! context canceled
ERROR WHEN CLOSING BODY!! context canceled
ERROR WHEN CLOSING BODY!! context canceled
96 Closing Body OK
ERROR WHEN CLOSING BODY!! context canceled
ERROR WHEN CLOSING BODY!! context canceled
ERROR WHEN CLOSING BODY!! context canceled
...
...

running with **go1.17.2**: (no `context canceled` at all)

62 Closing Body OK
45 Closing Body OK
51 Closing Body OK
87 Closing Body OK
66 Closing Body OK
29 Closing Body OK
72 Closing Body OK
75 Closing Body OK
57 Closing Body OK
9 Closing Body OK
4 Closing Body OK
8 Closing Body OK
18 Closing Body OK
64 Closing Body OK
5 Closing Body OK
56 Closing Body OK
39 Closing Body OK
41 Closing Body OK
23 Closing Body OK
47 Closing Body OK
16 Closing Body OK
97 Closing Body OK
88 Closing Body OK
53 Closing Body OK
13 Closing Body OK
73 Closing Body OK
74 Closing Body OK
80 Closing Body OK
70 Closing Body OK
83 Closing Body OK
90 Closing Body OK
21 Closing Body OK
76 Closing Body OK
...
...

I guess there are two questions from me:

1. Why did the http client cancel its own context although the requests were successful? (we can see in the logs that we got the response and could read the body perfectly fine)
2. Is that an intended feature or a regression in go1.17.3? I think like we should be able to close the response Body regardless of the deadline, timeout, or context cancelation (as in go1.17.2).

Thanks
Andre

[seankhliao]

cc @neild

[rhysh]

This sounds like #49366 (which has some fixes in progress).

[seankhliao]

Duplicate of #49366