[FumingPower3925]

Lane L19 H2-TIMEOUTS of v1.6.0, the second defect that PR #1134 found. Refs #889.

Draft. Nothing in the trackers is ticked or edited. It is independent of #1134 (that PR changes the Read and Idle arm of the same checkTimeouts sweep, this one the send path; no shared lines, so no conflict is expected, and git merge-tree of the two heads is clean).

The defect

On io_uring the sweep's dirty/sending arm closes a conn when elapsed > WriteTimeout, where elapsed = now - cs.lastActivity and lastActivity is the last read or completed send. Nothing stamps it when a send starts. For a stream that is quiet for longer than WriteTimeout between two chunks the clock is as old as the gap, so when a sweep (every 50 to 100 ms) finds the next chunk's SEND in flight, the conn is closed, mid-stream, with that chunk. epoll and adaptive have their own write clock (writeSince) and are not affected.

Found by #1134's own test: its io_uring write arm of a quiet stream (WriteTimeout 1 s, a chunk every 2 s) failed in CI, "cut after 4.001s: EOF (3 DATA frames, the last at 4.001s)" (https://github.com/goceleris/celeris/actions/runs/40464118254). Measured with a probe (WriteTimeout 100 ms, a chunk every 250 ms): io_uring was cut at 3.75 s, 6.26 s and 10.75 s in three runs, each time at a chunk, about one chunk in 16 to 44; the Opus reviewer of #1134 got 1.756 s; epoll and adaptive stayed open for 20 s (80 chunks).

At the defaults (WriteTimeout 60 s) it needs a quiet gap of 60 s; a server that sets WriteTimeout below its SSE heartbeat interval gets it.

The fix

flushSend, in the branch where the conn goes from idle (nothing in flight, nothing left over) to having output, stamps cs.lastActivity = w.cachedNow: the write clock starts when the send starts. cachedNow is the clock the iteration already read (a recv, the wake of a handler goroutine's write, or the sweep refreshed it before); this is one store, no clock read, no branch beyond the existing ones. A completed send already restamped the same clock, so what ReadTimeout and IdleTimeout mean on io_uring is unchanged. flushSendLink (the HTTP/1 request/response chain) is not touched: a read has just stamped the clock there.

Tests and evidence

test/server/iouring_write_clock_quiet_889_linux_test.go (its own helpers, wtq-prefixed, so it does not collide with #1134's h2raw889; it uses engines761 and startServerConfig761; no skip):

• TestQuietH2StreamIsNotCutByWriteTimeout889: 16 h2c streams on one server, a chunk every 250 ms (ticks 13 ms apart so that they do not share a phase of the sweep), WriteTimeout 100 ms, ReadTimeout and IdleTimeout off, clients that read and send nothing; every stream open after 6 s on the three native engines. Red on main on io_uring in 7 of 7 runs: 8, 9, 5 of 16 streams cut in the last three (logs/wt-red-main.log; 7, 7, 9 and 4 of 16 in four runs before them). An earlier version with all 16 ticks on the same phase cut none in one run of three: the spread is the sweep's phase, not the defect. Green with the fix, 0 of 16 on all three engines (logs/wt-fix-green.log; 4 of 4 runs of the quiet test).
• TestNonReadingH2ClientIsStillCutByWriteTimeout889 (control, green on main and with the fix): a client that requests a 48 MiB response with windows of 2^31-1 and reads nothing is cut on epoll, adaptive and io_uring; the client sees the end of the conn after 2.5 MiB, having read nothing for 12 s. On io_uring the cut is WriteTimeout 1 s plus the 5 s the close waits for the queued SEND, so the client's first read at 6 s still gets the whole response if it reads then (measured: delivered whole at 6.09 s); at 12 s it is cut. Mutant: the WriteTimeout closeConn of the arm disabled: this test fails on io_uring (logs/wt-mutant-no-writetimeout.log). The mutant of the fix is main.
• Not covered by a test: a SEND in flight for longer than WriteTimeout on a conn whose peer takes nothing is closed, by design (a stall).

Benchmark note

The change is on the send path, a per-request path: one 8-byte store per idle-to-sending transition, of a value already in a register. BenchmarkAsyncDispatchKeepAlive (an H1 keep-alive client against an async route, loopback, docker --cpus 2, 10 rounds interleaved main, branch and an A/A twin of main) does not resolve it: the twin differs from main by -23% in the median (-22% minimum) and the branch by -6.8% (minimum -49.8%): that bench is a ping-pong on two vCPUs shared with the client and the Mac. Not claimed: no regression, or a speedup; the argument is the diff (logs/bench4/).

Local results

New tests green (logs/wt-fix-green.log) and under -race (37 s); go test -race ./internal/engine/iouring/... ok, 489 s (logs/race2-wtwt.log); golangci-lint clean on the new code (three errcheck hits in files this PR does not touch). git merge-tree of this branch with #1134 is clean.

For the reviewer to attack

• cachedNow as the stamp: how stale can it be where flushSend runs without a CQE-bearing iteration (the dirty-list retry after an SQ-full)? A stamp that is older than the send start makes the clock more aggressive by that much, bounded by one loop iteration.
• A stamp at the start also moves the Read and Idle clock of a conn forward by the send's age, for a peer that then takes nothing: it is cut by the WriteTimeout arm first (the control test).
• Whether flushSendLink and the remainder branch need the same (the first has a read just before; the second is a SEND already in flight).

Also changes (stated after review, Opus r2 G1)

flushSend is the send path of every handler goroutine's write and of the buffer-ring default branch, not only HTTP/2. For an HTTP/1 async handler that runs longer than WriteTimeout, main measured the in-flight SEND from the request's read (a cut only if a sweep happened to catch the SEND in flight); now WriteTimeout is measured from the send's start, which is the same rule epoll applies (writeSince). ReadTimeout and IdleTimeout are unchanged.

Findings, not fixed here

• The stamp is made before the SQE is taken; on an SQ-full retry of a dirty conn each retry re-stamps, so WriteTimeout cannot fire while the SQ stays full (server overload, not peer-controlled). if !cs.dirty would make the first attempt the start (nit).
• The remainder branch (partial SEND) does not restamp and completeSend restamps only on a whole send, so a peer that takes a big send slowly but steadily is still measured from the send's start (unchanged by this PR; epoll's rule is progress-based, see epoll: the write timeout of a parked response is a minimum rate on acknowledged bytes, no ceiling, inbound bytes are not progress (v1.6.0, Refs #885) #1119).

[coderabbitai]

Caution

Review failed

The pull request is closed.

• Autofix · Keep fixing CodeRabbit findings and required CI, and resolving merge conflicts

Thanks for using CodeRabbit! It's free for OSS, and your support helps us grow. If you like it, consider giving us a shout-out.

❤️ Share

• X
• Mastodon
• Reddit
• LinkedIn

_{Comment @coderabbitai help to get the list of available commands.}

[codecov]

Codecov Report

✅ All modified and coverable lines are covered by tests.

📢 Thoughts on this report? Let us know!