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: non-deterministic timeout error with custom transport #51385

Open
KlotzAndrew opened this issue Feb 27, 2022 · 1 comment
Open

net/http: non-deterministic timeout error with custom transport #51385

KlotzAndrew opened this issue Feb 27, 2022 · 1 comment
Labels
NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one.
Milestone

Comments

@KlotzAndrew
Copy link

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

$ go version
go version go1.17.7 darwin/amd64

Does this issue reproduce with the latest release?

Currently using the latest

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

go env Output
$ go env
GO111MODULE=""
GOARCH="amd64"
GOBIN=""
GOCACHE="/Users/scout/Library/Caches/go-build"
GOENV="/Users/scout/Library/Application Support/go/env"
GOEXE=""
GOEXPERIMENT=""
GOFLAGS=""
GOHOSTARCH="amd64"
GOHOSTOS="darwin"
GOINSECURE=""
GOMODCACHE="/Users/scout/code/go/pkg/mod"
GONOPROXY=""
GONOSUMDB=""
GOOS="darwin"
GOPATH="/Users/scout/code/go"
GOPRIVATE=""
GOPROXY="https://proxy.golang.org,direct"
GOROOT="/usr/local/go"
GOSUMDB="sum.golang.org"
GOTMPDIR=""
GOTOOLDIR="/usr/local/go/pkg/tool/darwin_amd64"
GOVCS=""
GOVERSION="go1.17.7"
GCCGO="gccgo"
AR="ar"
CC="clang"
CXX="clang++"
CGO_ENABLED="1"
GOMOD="/Users/scout/code/go/github.com/http-simple-server/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 -arch x86_64 -m64 -pthread -fno-caret-diagnostics -Qunused-arguments -fmessage-length=0 -fdebug-prefix-map=/var/folders/bh/l9q9jgzd06377mbts0h3wgtc0000gn/T/go-build1394708782=/tmp/go-build -gno-record-gcc-switches -fno-common"

What did you do?

On a client with a timeout, added a custom transport and RoundTrip function. The custom transport causes the timeout error to be non-deterministic, even though it only passes the request through to the default transport.

With the default transport, the error is context deadline exceeded. With a custom transport, we randomly get context deadline exceeded or net/http: request canceled.

$ go test -v ./...
=== RUN   TestClientCustomTransport
    main_test.go:46: got two different errors:
        Get "http://127.0.0.1:59114": context deadline exceeded (Client.Timeout exceeded while awaiting headers)
        Get "http://127.0.0.1:59114": net/http: request canceled (Client.Timeout exceeded while awaiting headers)
--- FAIL: TestClientCustomTransport (0.01s)
=== RUN   TestClientDefaultTransport
error from default transport: Get "http://127.0.0.1:59122": context deadline exceeded (Client.Timeout exceeded while awaiting headers)
--- PASS: TestClientDefaultTransport (0.68s)
FAIL
FAIL	http-simple-server	0.848s
FAIL

Test code to reproduce

// main_test.go
package main_test

import (
	"fmt"
	"net/http"
	"net/http/httptest"
	"testing"
	"time"
)

type CustomTransport struct {
	baseTransport http.RoundTripper
}

func newTransport() *CustomTransport {
	return &CustomTransport{
		baseTransport: &http.Transport{},
	}
}

func (transport *CustomTransport) RoundTrip(r *http.Request) (*http.Response, error) {
	return transport.baseTransport.RoundTrip(r)
}

func TestClientCustomTransport(t *testing.T) {
	ts := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
		time.Sleep(5 * time.Millisecond)
	}))
	defer ts.Close()

	client := &http.Client{
		Timeout:   1 * time.Millisecond,
		Transport: newTransport(),
	}

	var lastError error
	for i := 0; i < 500; i++ {
		_, err := client.Get(ts.URL)
		if lastError == nil {
			lastError = err
			continue
		}

		if err.Error() != lastError.Error() {
			t.Errorf("got two different errors: \n%v \n%v", err, lastError)
			break
		}
	}
}

func TestClientDefaultTransport(t *testing.T) {
	ts := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
		time.Sleep(5 * time.Millisecond)
	}))
	defer ts.Close()

	client := &http.Client{
		Timeout: 1 * time.Millisecond,
		// Transport: newTransport(),
	}

	var lastError error
	for i := 0; i < 500; i++ {
		_, err := client.Get(ts.URL)
		if lastError == nil {
			lastError = err
			continue
		}

		if err.Error() != lastError.Error() {
			t.Errorf("got two different errors: \n%v \n%v", err, lastError)
			break
		}
	}
	fmt.Printf("error from default transport: %v\n", lastError)
}

What did you expect to see?

Expected to deterministically see a context deadline exceeded, the same as returned without a custom transport.

What did you see instead?

Randomly see either context deadline exceeded or net/http: request canceled timeout errors.

@seankhliao seankhliao changed the title affected/package: net/http, non-deterministic timeout error with custom transport net/http, non-deterministic timeout error with custom transport Feb 27, 2022
@seankhliao seankhliao added the NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one. label Feb 27, 2022
@seankhliao
Copy link
Member

I think this is just the extra call taking more time so the cancellation happens at different parts of the request lifecycle

cc @neild

@seankhliao seankhliao changed the title net/http, non-deterministic timeout error with custom transport net/http: non-deterministic timeout error with custom transport Feb 27, 2022
@seankhliao seankhliao added this to the Unplanned milestone Aug 20, 2022
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one.
Projects
None yet
Development

No branches or pull requests

2 participants