net/http: TestRetryRequestsOnError is flaky

[bradfitz]

From https://storage.googleapis.com/go-build-log/c7862f5a/linux-amd64-race_4ed6f3c3.log

--- FAIL: TestRetryRequestsOnError (0.02s)
    --- FAIL: TestRetryRequestsOnError/NothingWrittenGetBody (0.00s)
        transport_test.go:3116: i=1: Do = Post http://fake.golang: read tcp 127.0.0.1:52650->127.0.0.1:42017: use of closed network connection; log:
            Dial
            Write("POST / HTTP/1.1\r\nHost: fake.golang\r\nUser-Agent: Go-http-client/1.1\r\nContent-Length: 4\r\nAccept-Encoding: gzip\r\n\r\nfoo\n")
            Handler
            intentional write failure
2019/03/19 21:17:09 http: TLS handshake error from 127.0.0.1:38418: write tcp 127.0.0.1:43483->127.0.0.1:38418: use of closed network connection

[cuonglm]

@bradfitz is there a way to reliably reproduce this?

I tried:

for _ in {1..100}; do go-tip test -count=1 -race .;done

with no error.

[bradfitz]

I haven't tried.

[bradfitz]

Another:
https://storage.googleapis.com/go-build-log/8b56461e/linux-amd64-race_ed25b175.log

[bcmills]

https://storage.googleapis.com/go-build-log/de0346c9/linux-amd64-race_86344abc.log

--- FAIL: TestRetryRequestsOnError (0.02s)
    --- FAIL: TestRetryRequestsOnError/NothingWrittenNoBody (0.00s)
        transport_test.go:3217: i=1: Do = Delete http://fake.golang: read tcp 127.0.0.1:56096->127.0.0.1:40507: use of closed network connection; log:
            Dial
            Write("DELETE / HTTP/1.1\r\nHost: fake.golang\r\nUser-Agent: Go-http-client/1.1\r\nAccept-Encoding: gzip\r\n\r\n")
            Handler
            intentional write failure
2019/05/16 17:31:29 http: TLS handshake error from 127.0.0.1:49704: read tcp 127.0.0.1:33311->127.0.0.1:49704: use of closed network connection
2019/05/16 17:31:29 http: TLS handshake error from 127.0.0.1:49712: write tcp 127.0.0.1:33311->127.0.0.1:49712: use of closed network connection
2019/05/16 17:31:29 http: TLS handshake error from 127.0.0.1:49710: read tcp 127.0.0.1:33311->127.0.0.1:49710: use of closed network connection
2019/05/16 17:31:29 http: TLS handshake error from 127.0.0.1:49716: read tcp 127.0.0.1:33311->127.0.0.1:49716: use of closed network connection
2019/05/16 17:31:29 http: TLS handshake error from 127.0.0.1:49706: read tcp 127.0.0.1:33311->127.0.0.1:49706: use of closed network connection
2019/05/16 17:31:29 http: TLS handshake error from 127.0.0.1:49708: write tcp 127.0.0.1:33311->127.0.0.1:49708: use of closed network connection
2019/05/16 17:31:29 http: TLS handshake error from 127.0.0.1:49714: write tcp 127.0.0.1:33311->127.0.0.1:49714: use of closed network connection
2019/05/16 17:31:29 http: TLS handshake error from 127.0.0.1:49720: read tcp 127.0.0.1:33311->127.0.0.1:49720: use of closed network connection
2019/05/16 17:31:29 http: TLS handshake error from 127.0.0.1:49734: write tcp 127.0.0.1:33311->127.0.0.1:49734: use of closed network connection
2019/05/16 17:31:29 http: TLS handshake error from 127.0.0.1:49722: read tcp 127.0.0.1:33311->127.0.0.1:49722: use of closed network connection
2019/05/16 17:31:29 http: TLS handshake error from 127.0.0.1:49718: read tcp 127.0.0.1:33311->127.0.0.1:49718: use of closed network connection
2019/05/16 17:31:29 http: TLS handshake error from 127.0.0.1:49726: read tcp 127.0.0.1:33311->127.0.0.1:49726: use of closed network connection
2019/05/16 17:31:29 http: TLS handshake error from 127.0.0.1:49728: read tcp 127.0.0.1:33311->127.0.0.1:49728: use of closed network connection
2019/05/16 17:31:29 http: TLS handshake error from 127.0.0.1:49724: read tcp 127.0.0.1:33311->127.0.0.1:49724: use of closed network connection
2019/05/16 17:31:29 http: TLS handshake error from 127.0.0.1:49732: read tcp 127.0.0.1:33311->127.0.0.1:49732: use of closed network connection
2019/05/16 17:31:29 http: TLS handshake error from 127.0.0.1:49730: read tcp 127.0.0.1:33311->127.0.0.1:49730: use of closed network connection
FAIL

[cuonglm]

Another https://storage.googleapis.com/go-build-log/ff7e60ef/android-amd64-emu_19080ded.log

[bcmills]

https://storage.googleapis.com/go-build-log/868e4d85/android-amd64-emu_10321f7f.log

[bcmills]

darwin-386-10_14: https://build.golang.org/log/4742b5e51eebf76feb5249e2650939eaebb16793

See previously #25366.

[bcmills]

android-amd64-emu (https://build.golang.org/log/92ec6ce5e426c6e197dc01557d726a680dc5134a):

--- FAIL: TestRetryRequestsOnError (0.03s)
    --- FAIL: TestRetryRequestsOnError/NothingWrittenNoBody (0.00s)
        transport_test.go:3224: i=1: Do = Delete http://fake.golang: read tcp 127.0.0.1:36280->127.0.0.1:41698: use of closed network connection; log:
            Dial
            Write("DELETE / HTTP/1.1\r\nHost: fake.golang\r\nUser-Agent: Go-http-client/1.1\r\nAccept-Encoding: gzip\r\n\r\n")
            Handler
            intentional write failure
FAIL
exitcode=1FAIL	net/http	9.085s

[jtarchie]

We may be experiencing this error, too.
We have a test that is testing retry logic when a connection (in <=go1.12) would receive a io.EOF when the server closed the client connection.
When we upgraded to go1.13, we no longer receive io.EOF on the closed connection. We receive tls.errClosed.
With retry logic, we were able to compare the type of io.EOF, but with tls.errClosed, we now have to inspect the error string (Error()). This doesn't feel right to do.
We don't have a reproducible simple test case at the moment, but hopefully I've provided enough information from our current test case.

[jtarchie]

It appears that tls.errClosed may not be the only culprit.
We are experiencing also a bunch of write: broken pipe in CI.
🤔

[jtarchie]

We've reverted back to go1.12.

[bcmills]

linux-s390x-ibm: https://build.golang.org/log/7b2dcb45b72837f2cb08401d2083f7a857443d7b

(same failure mode as in #30938 (comment))

[bcmills]

windows-amd64-2016: https://build.golang.org/log/bef07597bea372590c2de133c9ad1afeddd7a42f

Same failure, mode, but no TLS handshake error (consistent with @jtarchie's observation).

[jtarchie]

I might be able to figure out a reproducible (flakey) test, but I don't know if that actually hunts down the issue.
I'm not sure what changed in the go 1.12 to 1.13 source for TLS. I've looked at the diffs via git.
The fact that the error types changed (io.EOF to tls.errClosed | write: broken pipe) is probably where to start.

This could also be due to changes in httptest TLS Server.

[bcmills]

dragonfly-amd64: https://build.golang.org/log/782c3e02489de8e3203dcd50f037538956bab465
...at least we know it's not platform-dependent?

Actually, there is a pattern here: the only two cases that seem to flake are NothingWrittenNoBody and NothingWrittenGetBody. The Idempotent cases have not yet been implicated.

[bcmills]

This note in the test may provide a clue:

go/src/net/http/transport_test.go

Lines 3263 to 3266 in 06ac262

	// NOTE: we resend a request only if:
	// - we reused a keep-alive connection
	// - we haven't yet received any header data
	// - either we wrote no bytes to the server, or the request is idempotent

I think the TLS handshake error is a red herring: it isn't necessarily even coming from the same test function.

[bcmills]

2019-11-19T22:42:59-ce7829f/linux-amd64-longtest
2019-11-14T01:57:00-3f21c23/darwin-arm-mg912baios
2019-10-28T22:10:06-59a6847/darwin-arm64-mn4m2zdaios
2019-10-04T13:47:53-8c74bfb/windows-amd64-2016
2019-09-17T16:25:15-38543c2/android-amd64-emu
2019-09-16T11:53:57-d9b8ffa/linux-s390x-ibm
2019-09-02T21:44:50-fb7b50c/freebsd-386-11_2
2019-08-20T19:26:11-53c088f/android-amd64-emu
2019-07-30T20:49:54-1ad64fa/darwin-386-10_14
2019-07-15T16:28:58-4b36588/android-amd64-emu
2019-04-18T21:49:02-c8aaec2/linux-amd64-race
2019-03-17T19:13:01-bedb6a1/netbsd-arm-bsiegert
2019-03-05T14:19:59-94cbfc2/android-386-emu
2019-03-01T18:26:37-820ad17/android-amd64-emu
2019-03-01T16:27:27-4e10ce4/android-386-emu

[bradfitz]

I can reproduce this if I burn a bunch of CPU (https://gist.github.com/bradfitz/233894f4aec11b221cb06abd8489d2e4) and run

$ go test  -run=TestRetryRequestsOnError/NothingWrittenGetBody -race -count=500
--- FAIL: TestRetryRequestsOnError (0.02s) 
    --- FAIL: TestRetryRequestsOnError/NothingWrittenGetBody (0.02s)
        transport_test.go:3395: i=1: Do = Post "http://fake.golang": read tcp 127.0.0.1:50552->127.0.0.1:46615: use of closed network connection; log:
            Dial 
            Write("POST / HTTP/1.1\r\nHost: fake.golang\r\nUser-Agent: Go-http-client/1.1\r\nContent-Length: 4\r\nAccept-Encoding: gzip\r\n\r\nfoo\n")
            Handler
            intentional write failure      
--- FAIL: TestRetryRequestsOnError (0.01s) 
    --- FAIL: TestRetryRequestsOnError/NothingWrittenGetBody (0.00s)
        transport_test.go:3395: i=1: Do = Post "http://fake.golang": read tcp 127.0.0.1:42122->127.0.0.1:38355: use of closed network connection; log:
            Dial
            Write("POST / HTTP/1.1\r\nHost: fake.golang\r\nUser-Agent: Go-http-client/1.1\r\nContent-Length: 4\r\nAccept-Encoding: gzip\r\n\r\nfoo\n")
            Handler
            intentional write failure
FAIL
exit status 1   
FAIL    net/http        55.811s

This check involving checking for a failure under 25 milliseconds scares me:

if time.Since(t0) < MaxWriteWaitBeforeConnReuse/2 {

... because all test code involving time scares me.