net/http/httptrace: add retry hook

[benburkert]

Please answer these questions before submitting your issue. Thanks!

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

go version go1.7.4 darwin/amd64

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

GOARCH="amd64"
GOBIN=""
GOEXE=""
GOHOSTARCH="amd64"
GOHOSTOS="darwin"
GOOS="darwin"
GOPATH="/Users/benburkert"
GORACE=""
GOROOT="/usr/local/Cellar/go/1.7.4/libexec"
GOTOOLDIR="/usr/local/Cellar/go/1.7.4/libexec/pkg/tool/darwin_amd64"
CC="clang"
GOGCCFLAGS="-fPIC -m64 -pthread -fno-caret-diagnostics -Qunused-arguments -fmessage-length=0 -fdebug-prefix-map=/var/folders/qs/qkt9twmx4qg379d6f8kxl1vm0000gn/T/go-build714318584=/tmp/go-build -gno-record-gcc-switches -fno-common"
CXX="clang++"
CGO_ENABLED="1"

What did you do?

https://play.golang.org/p/odjH-4qcwa

What did you expect to see?

The WroteRequest hook is called only once for the second request, as it is with the first request, and the program exits normally.

What did you see instead?

The WroteRequest hook is called twice because the transport attempts to write the request to a dead connection then retries with a new connection. Both attempts call the hook. This causes the program to panic because of the send on the already closed channel during the second call.

panic: send on closed channel

goroutine 12 [running]:
panic(0x3167c0, 0x1070a648)
	/usr/local/go/src/runtime/panic.go:500 +0x720
main.request.func1(0x0, 0x0)
	/tmp/sandbox194689056/main.go:41 +0x40
net/http.(*Request).write.func1(0x10736780, 0x10716f18)
	/usr/local/go/src/net/http/request.go:452 +0x80
net/http.(*Request).write(0x10740880, 0x440890, 0x10733100, 0x0, 0x10733120, 0x0, 0x0, 0x0)
	/usr/local/go/src/net/http/request.go:573 +0x10fb
net/http.(*persistConn).writeLoop(0x10746870, 0x0)
	/usr/local/go/src/net/http/transport.go:1644 +0x200
created by net/http.(*Transport).dialConn
	/usr/local/go/src/net/http/transport.go:1058 +0x13a0

[bradfitz]

Okay, we can document that it may be called multiple times.

[benburkert]

thanks @bradfitz. I was also surprised to see that the WroteRequestInfo argument to the hook has a nil error for every call, even when the request write (supposedly) failed.

https://play.golang.org/p/HvqrsSN48F

[bradfitz]

Who says the request write failed? It looks like the write was successful, but then the server hung up, so it retried because it was safe to do so.

[tombergan]

Should we also add a hook for retries to help the user make sense of multiple WroteRequest/GetConn callbacks? I'm also reminded of #17152.

[bradfitz]

Perhaps. But that is Go 1.9.

We can re-use this bug. I won't close this one.

[gopherbot]

CL https://golang.org/cl/34386 mentions this issue.

[benburkert]

Yes, that would be a successful write, my mistake.

It looks like the GetConn and GotConn hooks can also be called multiple times. I did not check any others but there may be more.

[odeke-em]

@benburkert interested in documenting your findings?