net/http: requests sometimes sent even when context is already canceled

[hiranya911]

We are observing a intermittent error with the ctxhttp package when calling it with already cancelled contexts.

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

Error has been observed on multiple Go versions (1.6, 1.7, 1.9)

Here's some more details from the golang 1.9 build environment (Travis CI based) where this happened today:

$ go version
go version go1.9.7 linux/amd64
go.env
$ go env
GOARCH="amd64"
GOBIN=""
GOEXE=""
GOHOSTARCH="amd64"
GOHOSTOS="linux"
GOOS="linux"
GOPATH="/home/travis/gopath"
GORACE=""
GOROOT="/home/travis/.gimme/versions/go1.9.7.linux.amd64"
GOTOOLDIR="/home/travis/.gimme/versions/go1.9.7.linux.amd64/pkg/tool/linux_amd64"
GCCGO="gccgo"
CC="gcc"
GOGCCFLAGS="-fPIC -m64 -pthread -fmessage-length=0 -fdebug-prefix-map=/tmp/go-build696930010=/tmp/go-build -gno-record-gcc-switches"
CXX="g++"
CGO_ENABLED="1"
CGO_CFLAGS="-g -O2"
CGO_CPPFLAGS=""
CGO_CXXFLAGS="-g -O2"
CGO_FFLAGS="-g -O2"
CGO_LDFLAGS="-g -O2"
PKG_CONFIG="pkg-config"

What did you do?

I have the following test case:

func TestContext(t *testing.T) {
	handler := http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
		w.Header().Set("Content-Type", "application/json")
		w.Write([]byte("{}"))
	})
	server := httptest.NewServer(handler)
	defer server.Close()

	hc := http.DefaultClient
	doSend := func(ctx context.Context, req *http.Request) error {
		resp, err := ctxhttp.Do(ctx, hc, req)
		if err != nil {
			return err
		}
		defer resp.Body.Close()

		_, err = ioutil.ReadAll(resp.Body)
		if err != nil {
			return err
		}
		return nil
	}

	ctx, cancel := context.WithCancel(context.Background())
	req, err := http.NewRequest("GET", server.URL, nil)
	if err != nil {
		t.Fatal(err)
	}
	if err := doSend(ctx, req); err != nil { // Request 1
		t.Fatal(err)
	}

	cancel()
	req, err = http.NewRequest("GET", server.URL, nil)
	if err != nil {
		t.Fatal(err)
	}
	if err := doSend(ctx, req); err == nil { // Request 2
		t.Fatal("no err raised")
	}
}

What did you expect to see?

I expect Request 2 to fail with an error since the context is explicitly cancelled.

What did you see instead?

Every now and then Request 2 completes successfully (i.e. gets a response from the server), and doesn't return an error.

[meirf]

I wasn't able to reproduce this on go1.10.3 darwin/amd64.
I recommend updating your initial comment to include the output of go env.

---

@hiranya911 can you please help me with my understanding here:

My guess is that the firebase library linked to this issue has the requirement to support go1.6. context was only added to net/http in 1.7 so switching to 1.7+ is not possible in this case.

firebase/firebase-admin-go#144 links to this:

resp, err := client.Do(ctx, &Request{
	Method: http.MethodGet,
	URL:    server.URL,
})

The code pasted by the OP above has:
resp, err := ctxhttp.Do(ctx, hc, req)

These are different libraries: net/http, golang.org/x/net/context/ctxhttp

Your comment:

TestContext() in internal/http_client_test.go is flaky on Golang 1.6: https://github.com/firebase/firebase-admin-go/blob/master/internal/http_client_test.go#L176

I thought context was added to net/http in 1.7 so how could that test be running in go1.6?

[hiranya911]

client.Do() is an internal API of ours that wraps ctxhttp: https://github.com/firebase/firebase-admin-go/blob/master/internal/http_client.go#L43

You're right about us not being able to use ctx+http APIs at the moment, due to us having to support golang 1.6.

[hiranya911]

The issue occurs very occasionally. I haven't observed it in the local development environments. But it happens every now and then on our Travis builds. Here's some env details from the golang 1.9 build environment where this happened today:

$ go version
go version go1.9.7 linux/amd64
go.env
$ go env
GOARCH="amd64"
GOBIN=""
GOEXE=""
GOHOSTARCH="amd64"
GOHOSTOS="linux"
GOOS="linux"
GOPATH="/home/travis/gopath"
GORACE=""
GOROOT="/home/travis/.gimme/versions/go1.9.7.linux.amd64"
GOTOOLDIR="/home/travis/.gimme/versions/go1.9.7.linux.amd64/pkg/tool/linux_amd64"
GCCGO="gccgo"
CC="gcc"
GOGCCFLAGS="-fPIC -m64 -pthread -fmessage-length=0 -fdebug-prefix-map=/tmp/go-build696930010=/tmp/go-build -gno-record-gcc-switches"
CXX="g++"
CGO_ENABLED="1"
CGO_CFLAGS="-g -O2"
CGO_CPPFLAGS=""
CGO_CXXFLAGS="-g -O2"
CGO_FFLAGS="-g -O2"
CGO_LDFLAGS="-g -O2"
PKG_CONFIG="pkg-config"

[meirf]

/cc @broady @bradfitz

[broady]

Very strange. For Go 1.9, ctxhttp is a very light shim:

func Do(ctx context.Context, client *http.Client, req *http.Request) (*http.Response, error) {
	if client == nil {
		client = http.DefaultClient
	}
	resp, err := client.Do(req.WithContext(ctx))
	// If we got an error, and the context has been canceled,
	// the context's error is probably more useful.
	if err != nil {
		select {
		case <-ctx.Done():
			err = ctx.Err()
		default:
		}
	}
	return resp, err
}

so, this might be a bug in net/http. Renaming bug given how unlikely this is a bug in ctxhttp.

[ghost]

I can reproduce it in Go 1.10.3 on linux/amd64 using this modified code without the ctxhttp dependency:

package main

import (
	"context"
	"io/ioutil"
	"log"
	"net/http"
	"net/http/httptest"
)

func Do(ctx context.Context, client *http.Client, req *http.Request) (*http.Response, error) {
	if client == nil {
		client = http.DefaultClient
	}
	resp, err := client.Do(req.WithContext(ctx))
	// If we got an error, and the context has been canceled,
	// the context's error is probably more useful.
	if err != nil {
		select {
		case <-ctx.Done():
			err = ctx.Err()
		default:
		}
	}
	return resp, err
}

func main() {
	handler := http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
		w.Header().Set("Content-Type", "application/json")
		w.Write([]byte("{}"))
	})
	server := httptest.NewServer(handler)
	defer server.Close()

	hc := http.DefaultClient
	doSend := func(ctx context.Context, req *http.Request) error {
		resp, err := Do(ctx, hc, req)
		if err != nil {
			return err
		}
		defer resp.Body.Close()

		_, err = ioutil.ReadAll(resp.Body)
		if err != nil {
			return err
		}
		return nil
	}

	for i := 0; i < 10; i++ {
		go func() {
			for {
				ctx, cancel := context.WithCancel(context.Background())
				req, err := http.NewRequest("GET", server.URL, nil)
				if err != nil {
					log.Fatal(err)
				}
				if err := doSend(ctx, req); err != nil { // Request 1
					log.Fatal(err)
				}

				cancel()
				req, err = http.NewRequest("GET", server.URL, nil)
				if err != nil {
					log.Fatal(err)
				}
				if err := doSend(ctx, req); err == nil { // Request 2
					log.Fatal("no err raised")
				}
			}
		}()
	}
	select {}
}

It takes only 1-10 seconds before there's no err raised. (Sometimes it also exits with another error message: connect: cannot assign requested address)

[minaevmike]

Some my thoughts.
Problem is located in http transport.

• transport want to get connection. but at this step cancel could be missed. Because transport can take an idle connection. https://github.com/golang/go/blob/master/src/net/http/transport.go#L947
• after this transport tries to read response https://github.com/golang/go/blob/master/src/net/http/transport.go#L1927 but here cancel could be missed too if response is ready.

[gopherbot]

Change https://golang.org/cl/118560 mentions this issue: net/http: make Transport.RoundTrip check context.Done earlier

[hiranya911]

Thanks gophers. Do you usually backport this sort of thing to older versions of Go, or is it just going to be included in the next milestone release?