net/http: Requests with already canceled context are passed to Handlers

[artyom]

Please answer these questions before submitting your issue. Thanks!

What did you do?

If possible, provide a recipe for reproducing the error.
A complete runnable program is good.
A link on play.golang.org is best.

Run this server: https://play.golang.org/p/s4dAekw0Tn — it listens 2 sockets and proxies requests from one address to another to ensure final endpoint receives requests via single connection.

This issue likely related to #18447

What did you expect to see?

~ ¶ for i in 1 2 3 ; do curl 'http://localhost:8080/?d=3s' ; done
ok
ok
ok

What did you see instead?

~ ¶ for i in 1 2 3 ; do curl 'http://localhost:8080/?d=3s' ; done
ok
context canceled
context canceled

Does this issue reproduce with the latest release (go1.7.4)?

No

System details

go version go1.8beta2 darwin/amd64
GOARCH="amd64"
GOBIN=""
GOEXE=""
GOHOSTARCH="amd64"
GOHOSTOS="darwin"
GOOS="darwin"
GOPATH="/tmp/go:/Users/artyom/go"
GORACE=""
GOROOT="/Users/artyom/Library/go"
GOTOOLDIR="/Users/artyom/Library/go/pkg/tool/darwin_amd64"
GCCGO="gccgo"
CC="clang"
GOGCCFLAGS="-fPIC -m64 -pthread -fno-caret-diagnostics -Qunused-arguments -fmessage-length=0 -fdebug-prefix-map=/var/folders/lb/3rk8rqs53czgb4v35w_342xc0000gn/T/go-build942175264=/tmp/go-build -gno-record-gcc-switches -fno-common"
CXX="clang++"
CGO_ENABLED="1"
PKG_CONFIG="pkg-config"
CGO_CFLAGS="-g -O2"
CGO_CPPFLAGS=""
CGO_CXXFLAGS="-g -O2"
CGO_FFLAGS="-g -O2"
CGO_LDFLAGS="-g -O2"
GOROOT/bin/go version: go version go1.8beta2 darwin/amd64
GOROOT/bin/go tool compile -V: compile version go1.8beta2 X:framepointer
uname -v: Darwin Kernel Version 16.3.0: Thu Nov 17 20:23:58 PST 2016; root:xnu-3789.31.2~1/RELEASE_X86_64
ProductName:	Mac OS X
ProductVersion:	10.12.2
BuildVersion:	16C67
lldb --version: lldb-360.1.70

[bradfitz]

Is this just a duplicate of #18447, or is this meant to be a bug report about httputil.ReverseProxy?

Please clarify.

[artyom]

It depends on whether #18447 is a regression from 1.7 or it's just a matter of documenting extra cancelation case in Request.Context() docs. If former, this bug is likely a duplicate, if latter, it's probably a separate issue — it seems that Handlers can receive Requests with already canceled context if multiple requests are sent via single http/1.1 keep-alive connection.

I'm able to reproduce this without httputil.ReverseProxy just using netcat against final endpoint (localhost:8081) as well.

[artyom]

Here's a better reproduction: https://play.golang.org/p/Y7MEdQY27J

go 1.7.4:

go1.7.4 ¶ go run repro.go 
2016/12/28 22:54:30 &{{0xc4201000e0}} new
2016/12/28 22:54:30 &{{0xc4201000e0}} active
2016/12/28 22:54:34 ok
2016/12/28 22:54:34 &{{0xc4201000e0}} idle
2016/12/28 22:54:34 &{{0xc4201000e0}} active
2016/12/28 22:54:35 ok
2016/12/28 22:54:35 &{{0xc4201000e0}} idle
2016/12/28 22:54:35 &{{0xc4201000e0}} active
2016/12/28 22:54:36 ok
2016/12/28 22:54:36 &{{0xc4201000e0}} idle

go1.8beta2:

go1.8beta2 ¶ go run repro.go 
2016/12/28 22:56:14 &{{0xc42006a070}} new
2016/12/28 22:56:14 &{{0xc42006a070}} active
2016/12/28 22:56:17 context canceled
2016/12/28 22:56:17 &{{0xc42006a070}} idle
2016/12/28 22:56:17 &{{0xc42006a070}} active
2016/12/28 22:56:17 context canceled
2016/12/28 22:56:17 &{{0xc42006a070}} idle
2016/12/28 22:56:17 &{{0xc42006a070}} active
2016/12/28 22:56:17 context canceled
2016/12/28 22:56:17 &{{0xc42006a070}} idle

[rsc]

Pretty sure #18447 is a behavior bug and those cancellations should not be coming through. In that case, this will be fixed by the same fix. Closing as dup of #18447.