net/http: TestServerKeepAlivesEnabled_h2 test flake

[bradfitz]

linux-amd64-race at 789e14c1aa487f83d6e99f369b22c4fa60bf6f4c

https://storage.googleapis.com/go-build-log/789e14c1/linux-amd64-race_7fc53188.log

2016/11/28 20:31:42 http: TLS handshake error from 127.0.0.1:42614: read tcp 127.0.0.1:35582->127.0.0.1:42614: use of closed network connection
--- FAIL: TestServerKeepAlivesEnabled_h2 (0.09s)
	clientserver_test.go:50: Get https://127.0.0.1:34653: http2: server sent GOAWAY and closed the connection; LastStreamID=1, ErrCode=NO_ERROR, debug=""
FAIL
FAIL	net/http	4.922s
```

/cc @tombergan (if you're bored)

[tombergan]

Wild guess:

The server becomes "idle" before it sends the GOAWAY:
https://github.com/golang/net/blob/1c5acb2c2d1df0409de556978dd628d90aee5cb3/http2/server.go#L1275

The test sends the second request after the server has transitioned to "idle":

go/src/net/http/serve_test.go

Line 5030 in 409a667

if !waitCondition(2*time.Second, 10*time.Millisecond, srv.ExportAllConnsIdle) {

The test can make the second getURL call before receiving the GOAWAY. However, the h2 transport doesn't retry a request when the following code executes before GOAWAY is actually received:
https://github.com/golang/net/blob/1c5acb2c2d1df0409de556978dd628d90aee5cb3/http2/transport.go#L679

There is a race: if the client sends a new request on stream n+2, then shortly afterwards receives GOAWAY(lastStream=n), the client won't auto-retry that request on a new connection. Auto-retry happens only if RoundTrip gets to line 679 after the GOAWAY is received.

There is arguably a second bug, though this isn't the root cause of the test flake: the server transitions to idle at the line below even though there may still be response frames queued in the write scheduler. (Is it really correct to consider the server "idle" at this point?)
https://github.com/golang/net/blob/1c5acb2c2d1df0409de556978dd628d90aee5cb3/http2/server.go#L1275

Finally, I noticed a third bug: the following code should check curClientStreams+curPushedStreams==0 rather than curClientStreams==0:
https://github.com/golang/net/blob/1c5acb2c2d1df0409de556978dd628d90aee5cb3/http2/server.go#L756

[gopherbot]

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

[gopherbot]

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

[tombergan]

There is arguably a second bug, though this isn't the root cause of the test flake: the server transitions to idle at the line below even though there may still be response frames queued in the write scheduler. (Is it really correct to consider the server "idle" at this point?)
https://github.com/golang/net/blob/1c5acb2c2d1df0409de556978dd628d90aee5cb3/http2/server.go#L1275

This is not a problem. At the end of sc.closeStream, the call to writeSched.CloseStream will discard any frames queued for that stream.

Finally, I noticed a third bug: the following code should check curClientStreams+curPushedStreams==0 rather than curClientStreams==0:
https://github.com/golang/net/blob/1c5acb2c2d1df0409de556978dd628d90aee5cb3/http2/server.go#L756

This is a bug. Sending a CL.

[gopherbot]

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

[gopherbot]

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