net/http: Transport.CancelRequest not always called if RoundTrip returns promptly when a request times out

[axw]

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

$ go version
go version devel +770a13546e Thu Sep 26 06:48:55 2019 +0000 linux/amd64

Does this issue reproduce with the latest release?

No.

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

go env Output

$ go env
GO111MODULE=""
GOARCH="amd64"
GOBIN=""
GOCACHE="/home/andrew/.cache/go-build"
GOENV="/home/andrew/.config/go/env"
GOEXE=""
GOFLAGS=""
GOHOSTARCH="amd64"
GOHOSTOS="linux"
GONOPROXY=""
GONOSUMDB=""
GOOS="linux"
GOPATH="/home/andrew/go"
GOPRIVATE=""
GOPROXY="https://proxy.golang.org,direct"
GOROOT="/home/andrew/.gimme/versions/go"
GOSUMDB="sum.golang.org"
GOTMPDIR=""
GOTOOLDIR="/home/andrew/.gimme/versions/go/pkg/tool/linux_amd64"
GCCGO="/usr/bin/gccgo"
AR="ar"
CC="gcc"
CXX="g++"
CGO_ENABLED="1"
GOMOD="/home/andrew/go/src/go.elastic.co/apm/module/apmhttp/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-build282289598=/tmp/go-build -gno-record-gcc-switches"

What did you do?

The tests for my project, go.elastic.co/apm, started failing when running against go tip.

I strongly suspect 7fc2625, since it started happening today. The issue can be reproduced with https://play.golang.org/p/MQepDRMdcjL

What did you expect to see?

The program should run and exit cleanly.

What did you see instead?

The program runs for ~10 seconds and panics, due to CancelRequest not being called.

Note that this doesn't happen every time, hence the loop. If I increase the timeout to 50ms it becomes less frequent, but still fails occasionally.

[bcmills]

due to CancelRequest not being called.

Why do you expect CancelRequest to be called?

Per its documentation:

Deprecated: Use Request.WithContext to create a request with a cancelable context instead. CancelRequest cannot cancel HTTP/2 requests.

That seems to also imply that Transport implementations should use req.Context() rather than only relying on CancelRequest.

A version of your test program modified to do so (https://play.golang.org/p/7ZZRvEpy9uJ) seems to confirm that in all cases, either CancelRequest was called, or req.Context().Done() was closed before the end of the RoundTrip call.

[bcmills]

CC @bradfitz to confirm, but I'm pretty sure this is working as designed.

An additional test confirms that CancelRequest is always called if RoundTrip blocks:
https://play.golang.org/p/1UjWdVrhdgh

[bradfitz]

Yup, looks like it's working fine. In the original snippet there was no need for net/http to call CancelRequest because Do had already failed in time.

Thanks for investigating, @bcmills.

[axw]

Why do you expect CancelRequest to be called?

Because the Client.Timeout docs say it will be :)

The Client cancels requests to the underlying Transport
as if the Request's Context ended.

For compatibility, the Client will also use the deprecated
CancelRequest method on Transport if found. New
RoundTripper implementations should use the Request's Context
for cancellation instead of implementing CancelRequest.

@bcmills for context, I'm writing tracing middleware that wraps others' arbitrarily old and crusty code, harking back from from versions of Go that do not support context. I don't have much of a say about whether they use CancelRequest or Context cancellation.

Perhaps the docs ought to be clarified? Then again, we've probably spent enough time in this dusty corner. I'll change my test to accommodate.

Thanks both for looking into it.