Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

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

Closed
hiranya911 opened this issue Jun 12, 2018 · 9 comments
Closed
Labels
FrozenDueToAge NeedsFix The path to resolution is known, but the work has not been done.
Milestone

Comments

@hiranya911
Copy link

hiranya911 commented Jun 12, 2018

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
Copy link
Contributor

meirf commented Jun 13, 2018

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
Copy link
Author

hiranya911 commented Jun 13, 2018

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
Copy link
Author

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
Copy link
Contributor

meirf commented Jun 13, 2018

/cc @broady @bradfitz

@broady
Copy link
Member

broady commented Jun 13, 2018

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.

@broady broady changed the title Intermittent problem when using ctxhttp package net/http: requests sometimes sent even when context is already canceled Jun 13, 2018
@ghost
Copy link

ghost commented Jun 13, 2018

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
Copy link
Contributor

Some my thoughts.
Problem is located in http transport.

@bradfitz bradfitz added the NeedsFix The path to resolution is known, but the work has not been done. label Jun 13, 2018
@bradfitz bradfitz self-assigned this Jun 13, 2018
@bradfitz bradfitz added this to the Go1.11 milestone Jun 13, 2018
@gopherbot
Copy link

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

@hiranya911
Copy link
Author

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?

dna2github pushed a commit to dna2fork/go that referenced this issue Jun 14, 2018
Fixes golang#25852

Change-Id: I35c630367c8f1934dcffc0b0e08891d55a903518
Reviewed-on: https://go-review.googlesource.com/118560
Run-TryBot: Brad Fitzpatrick <bradfitz@golang.org>
TryBot-Result: Gobot Gobot <gobot@golang.org>
Reviewed-by: Andrew Bonventre <andybons@golang.org>
@golang golang locked and limited conversation to collaborators Jun 13, 2019
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Labels
FrozenDueToAge NeedsFix The path to resolution is known, but the work has not been done.
Projects
None yet
Development

No branches or pull requests

6 participants