net/http: apparent deadlock in TestServerWriteTimeout on plan9-amd64-0intro

[bcmills]

#!watchflakes
post <- builder ~ `^plan9` && pkg == "net/http" && test == "TestServerWriteTimeout"

As of CL 449935, the plan9-amd64-0intro builder went from failing something like 25% of the time to failing nearly 100% of the time.

The vast majority of the current failures are test timeouts running net/http, and they all seem to involve goroutines parked in net/http.(*http2ClientConn).RoundTrip via net/http_test.testServerWriteTimeout.

I think this is probably because the plan9 netpoll implementation does not support (or does not fully support?) SetDeadline.

(attn @golang/plan9; CC @neild)

[0intro]

Deadlines should be supported. What is not supported is half closing of TCP connections (closeWrite, closeRead, see issue #17906), but I don't believe it's related here.

I'm not sure why this issue is happening on the amd64 builder only and not on the 386 and arm builders. I'll investigate.

[bcmills]

I'm not sure why this issue is happening on the amd64 builder only and not on the 386 and arm builders. I'll investigate.

Turns out that it does occasionally happen on the plan9-arm builder too:
https://build.golang.org/log/c3901bbe3d4681c4026a08664447fe2629aeebbd

[gopherbot]

Found new dashboard test flakes for:

#!watchflakes
post <- builder ~ `^plan9` && pkg == "net/http" && test == "TestServerWriteTimeout"

2023-01-20 18:12 plan9-arm go@2507e789 net/http.TestServerWriteTimeout (log)

http.test 35687: warning: process exceeds 100 file descriptors
--- FAIL: TestServerWriteTimeout (0.00s)
    --- FAIL: TestServerWriteTimeout/h1 (0.83s)
        clientserver_test.go:210: server log: http: TLS handshake error from 127.0.0.1:55647: write tcp 127.0.0.1:53294->127.0.0.1:55647: i/o timeout
        serve_test.go:784: Get error, retrying: Get "https://127.0.0.1:53294": EOF
        clientserver_test.go:210: server log: http: TLS handshake error from 127.0.0.1:35055: write tcp 127.0.0.1:45038->127.0.0.1:35055: i/o timeout
        serve_test.go:784: Get error, retrying: Get "https://127.0.0.1:45038": EOF
        clientserver_test.go:210: server log: http: TLS handshake error from 127.0.0.1:34693: write tcp 127.0.0.1:58685->127.0.0.1:34693: i/o timeout
        serve_test.go:784: Get error, retrying: Get "https://127.0.0.1:58685": EOF
        clientserver_test.go:210: server log: http: TLS handshake error from 127.0.0.1:54889: write tcp 127.0.0.1:47544->127.0.0.1:54889: i/o timeout
        serve_test.go:784: Get error, retrying: Get "https://127.0.0.1:47544": EOF
        serve_test.go:797: server timed out writing request body: got err client disconnected; want os.ErrDeadlineExceeded

— watchflakes

[millerresearch]

The deadlock occurs when the server hits a write deadline while trying to write the response headers. The client's Get() never returns because it's waiting to read the headers. The server never exits because it's waiting for the client to close the connection.

A workaround is to break the deadlock by inserting

cst.c.Transport.(*Transport).ResponseHeaderTimeout = 3 * time.Second

just before the call to Get in testServerWriteTimeout.

Strictly speaking this is not specifically a Plan 9 issue, since the deadlock could occur on any platform given the right timing. I've simulated this on linux by hacking a deadline in the past after the server reads the client's request. That results in the same deadlock.

However in the wild this is very unlikely to happen because the many-millisecond timeout used in the test should give plenty of time for the server to invoke the handler and start writing headers. Why are we seeing it on Plan 9? Because it turns out there is a race condition in the Plan 9 implementation of internal/poll.FD, when an I/O deadline timer fires at the same time as the deadline is being reset to zero. The race can be triggered in this test if the write deadline for the TLS handshake hits just after the handshake completes and the deadline is being reset. The consequence is that the connection remains marked as "timed out", so the server's subsequent write of the headers will fail.

I think I have a fix for the poll.FD race, which I'm testing now. Looking at history, I see some other races were fixed in 2020 by https://golang.org/cl/235820 but I didn't spot this one!

@bcmills should I submit the ResponseHeaderTimeout workaround for this test, or just rely on the poll.FD fix to prevent it from happening?

[bcmills]

Strictly speaking this is not specifically a Plan 9 issue, since the deadlock could occur on any platform given the right timing. I've simulated this on linux by hacking a deadline in the past after the server reads the client's request. That results in the same deadlock.
…
should I submit the ResponseHeaderTimeout workaround for this test, or just rely on the poll.FD fix to prevent it from happening?

Could you file a separate issue for the cross-platform bug? I don't think that setting a client-side ResponseHeaderTimeout should be necessary.

If a write timeout occurs before (or while) writing headers, I would expect the server to close the connection immediately instead of waiting for the client to close it.

[millerresearch]

If a write timeout occurs before (or while) writing headers, I would expect the server to close the connection immediately instead of waiting for the client to close it.

Is that the right thing to do with respect to http2 persistent connections? Or should the client be able to time out and send another request on the same connection? I don't know what the http spec says.

[bcmills]

I'm not sure! That's part of why I think it merits a separate issue for discussion. 😅

[millerresearch]

Could you file a separate issue for the cross-platform bug? I don't think that setting a client-side ResponseHeaderTimeout should be necessary.

If a write timeout occurs before (or while) writing headers, I would expect the server to close the connection immediately instead of waiting for the client to close it.

Sorry, I was mistaken: my simulation wasn't realistic. In http2 deadlines (after the TLS handshake) are set by an explicit time.AfterFunc, not by setting a deadline on the underlying connection. So this is just a Plan 9 issue.

[gopherbot]

Change https://go.dev/cl/470215 mentions this issue: internal/poll: avoid race between SetDeadline and timer expiry in Plan 9