Follow-ups from #744: parallel driver closes at shutdown, onClose no longer tied to the fd's map removal

[FumingPower3925]

The review of #744 (celeris#735) left these minor findings and nits. The review's blocking finding, a test that could pass without the close lingering, is fixed on the branch (2948301). The items below were left for later, and each says what to do.

1. Shutdown still closes lingering driver sockets one after another, on the worker (nit)

shutdownDrivers closes each registered conn's engine descriptor on the worker goroutine, in a loop (engine/iouring/driver.go at 782f435, the for _, dc := range conns loop: if dc.retire() { _ = unix.Close(dc.opFD) }; dc.fireOnClose(errEngineShutdown)).

• With N lingering sockets, engine stop takes up to N × linger.
• waitDriverCloses then adds the longest linger among the closes that were handed off before shutdown.
• Engine.Shutdown ignores its ctx (engine.go:460), and Listen waits for the workers (engine.go:384), so a stop waits out every linger.

main has the same serial close (retire closed on the worker), so this is not a regression.

To do: hand these closes to closeOpFD-style goroutines and let the existing wait cover them, so they run in parallel. onClose must still fire after its close.

2. onClose is no longer tied to the map removal (nit, a documented hazard for third-party drivers)

Since #744, onClose fires at least one loop iteration after finalizeDriver, because it takes a goroutine and a driver-action round trip. It is no longer tied to the conn leaving driverConns. So a RegisterConn of the same caller fd number can succeed before the old conn's onClose runs.

• engine/provider.go documents this ("fails ... until the conn is finalized, which is at the latest when onClose fires").
• The in-tree drivers keep per-conn closures (driver/redis/conn.go:292, driver/postgres/conn.go:886, driver/memcached/conn.go:211), not fd-keyed state, so nothing in-tree is affected.
• A third-party driver that keys its state by fd and deletes that state in onClose could delete the new conn's entry.

To do: either say so explicitly in the RegisterConn/UnregisterConn docs ("do not key onClose state by fd number"), or pass onClose something that identifies the registration and not only the number.

3. Items the round-2 push dealt with (for the record)

• The body's round-1 diagnosis (minor). There were two causes, not one. CI job 108681501232 failed in 0.12 s because the close did not linger (the shallow rig, fixed by 5f3593c). The local 3.1 s failures were an ordering race (fixed by 1d83906). The PR body now says so.
• Evidence hygiene (nit). Lint is now taken at the head. The combined three-PR merge claim now has a saved script. The mislabelled round-1 log is noted in the lane README.

To do: nothing further.

4. The shutdown test syncs on a 200 ms sleep (minor, CodeRabbit on 2948301)

From the CodeRabbit review of #744 (#744 (comment)). TestDriverShutdownWaitsForAHandedOffClose (engine/iouring/driver_linger_close_linux_test.go, lines 284-289 at 2948301) starts stop() on a goroutine, sleeps 200 ms, then calls drain(). The sleep does not prove the worker reached waitDriverCloses before the close returned.

• If the stop is slower than 200 ms, the close returns first, the worker's loop fires onClose, and waitDriverCloses finds nothing to wait for. The test then passes without exercising the shutdown wait. It cannot fail falsely.
• driversClosed is set before shutdownDrivers returns, so polling it would not prove the wait has started either; an open stopped channel only proves the stop has not finished.
• The M2 control (no waitDriverCloses) was killed 3/3 in m8, so the test does exercise the wait on that shape. The risk is a vacuous pass on a slow runner.

To do: add a test-only hook that fires when waitDriverCloses starts (no production behavior change), wait for it with a deadline before drain(), and rerun the M2 control.

[FumingPower3925]

5. TestDriverLingeringCloseDoesNotStallTheWorker/linger failed once on PR CI: the close did not linger (flake, test only)

This was seen on #746's merged head 859d843 (main f0886ca merged into #746's branch; #746 changes no engine/iouring code, only a doc comment). It was in the CI job "io_uring init-failure regression (./engine/iouring)", step "celeris#691 io_uring driver tests", which is not required: run 36373856404, job 108775568900, attempt 1.

• 1 of the 5 linger runs (-count=5) failed at driver_linger_close_linux_test.go:246: "L's onClose fired while its close still lingered".
• The failing run's log reads LINGER arm=linger linger=3s v_onrecv_ms=0.127 onclose_before_v=true and then onclose_after_finalize_ms=100.5. That is the same 100.5 ms as the no-linger control, so in that run the close did not linger at all. The worker was not blocked (V's byte came in 0.127 ms), so this is not a io_uring: closing a driver socket with SO_LINGER blocks the worker for the whole linger time (retire closes the engine's duplicate on the worker) #735 regression.
• The other 4 linger runs in that attempt read onclose_before_v=false. Attempt 2 (job 108777489505) passed 145/145, with 0 FAIL and 0 SKIP lines, and all 5 linger runs onclose_before_v=false.
• On the push run at main f0886ca (36372296150), the same job passed.

This looks like the rig's ordering race coming back: the caller's close took the last reference, even with the worker parked, so the engine's close returned at once. Either that or the backlog was drained before the close.

To do: find which one it is. Log whether the engine's close or the caller's close did the lingering release, for example by timing each close. Then make the rig force that order, or make the test tell "did not linger" apart from "onClose before the close finished" and fail only on the second. Measure the flake rate under -count=50 in the CI shape first.

[FumingPower3925]

A data point for the #744 rig: TestDriverLingeringCloseDoesNotStallTheWorker/linger failed once in CI, and then passed on identical code.

• Failed: PR fix(iouring): read a worker's clock on every CQE batch, as epoll does, so a live connection is not timed out on a stale stamp (celeris#713) #768 CI run 36373920043, attempt 1, Unit job 108775757837. The merge commit was 777dcea (fix(iouring): read a worker's clock on every CQE batch, as epoll does, so a live connection is not timed out on a stale stamp (celeris#713) #768 at 9fb68fe into main f0886ca). The job logged L's onClose fired while its close still lingered: a driver must see the socket closed before onClose (engine/provider.go). In that run onclose_after_finalize_ms was 100.5 in the linger arm and 100.4 in the no-linger control. So the engine's close did not linger in that run: it behaved as the no-linger control did.
• Passed, the same test:
  • the same run's attempt 2 (job 108777949738);
  • CI run 36373195106, which merged fix(iouring): read a worker's clock on every CQE batch, as epoll does, so a live connection is not timed out on a stale stamp (celeris#713) #768's previous head d3e46c3 into the same f0886ca. d3e46c3..9fb68fe changes one comment in a test file. The linger arm took 3.04 s there.
• fix(iouring): read a worker's clock on every CQE batch, as epoll does, so a live connection is not timed out on a stale stamp (celeris#713) #768 does not touch driver code. Its production change is the io_uring worker reading cachedNow on every CQE batch.

So this looks like a rare flake of the linger rig (1 failure in the 3 CI runs I looked at). It resembles the race that the comment on unregisterAndCloseInOrder describes: the caller's close lingers instead of the engine's. I have not reproduced it locally.

[FumingPower3925]

Item 5 happened again, this time on a push to main. The flake is now 1 failure on main.

• Where. Main bd17725 (fix(iouring): require Linux 5.19; refuse io_uring on a kernel that rejects the IORING_ASYNC_CANCEL flags (celeris#682) #792 squash-merged onto dfd044f), CI run 36383186309, attempt 1. Job "io_uring init-failure regression (./engine/iouring)", step "celeris#691 io_uring driver tests" (not required): https://github.com/goceleris/celeris/actions/runs/36383186309/job/108803003382
• What failed. In -count=5, the second linger run failed at driver_linger_close_linux_test.go:246, "L's onClose fired while its close still lingered". The run logged arm=linger linger=3s v_onrecv_ms=0.058 onclose_before_v=true, then onclose_after_finalize_ms=100.5. That is the same signature as the fix(server): Shutdown runs the OnShutdown hooks, and returns, only after the drain on every engine (#703) #746 and fix(iouring): read a worker's clock on every CQE batch, as epoll does, so a live connection is not timed out on a stale stamp (celeris#713) #768 cases above: the close did not linger, the no-linger control took 100.6 ms, and the worker was not blocked. The other 4 linger runs in the job logged onclose_before_v=false. The first of them took 3017.8 ms.
• What fix(iouring): require Linux 5.19; refuse io_uring on a kernel that rejects the IORING_ASYNC_CANCEL flags (celeris#682) #792 changes. fix(iouring): require Linux 5.19; refuse io_uring on a kernel that rejects the IORING_ASYNC_CANCEL flags (celeris#682) #792 adds the Linux 5.19 floor and changes no driver code. The floor refuses io_uring only where the probe does not find the async-cancel flags accepted. In this job the engine was built: the linger test ran against it, and every other driver test in the step passed. So the floor was not involved.

The failed job is being rerun once, as a known flake.

[FumingPower3925]

Item 5 again on a push to main. That is 2 failures on main now, and 4 in all with #746 and #768.

• Where. Main 67fdb78 (fix(epoll): do not touch a connection's state after a handler that ran inline on an async loop hijacked it (celeris#769) #774 squash-merged onto bd17725), CI run 36386351199, attempt 1. Job "io_uring init-failure regression (./engine/iouring)", step "celeris#691 io_uring driver tests" (not required): https://github.com/goceleris/celeris/actions/runs/36386351199/job/108812436201
• What failed. In -count=5, the fifth linger run failed at driver_linger_close_linux_test.go:246, "L's onClose fired while its close still lingered". The run logged arm=linger linger=3s v_onrecv_ms=0.074 onclose_before_v=true, then onclose_after_finalize_ms=100.6. The no-linger control in that run took 100.4 ms, so the close did not linger, and V's byte arrived in 0.074 ms, so the worker was not blocked. The same signature as before. The other 4 linger runs logged onclose_before_v=false and took 3010.2 to 3056.4 ms.
• What fix(epoll): do not touch a connection's state after a handler that ran inline on an async loop hijacked it (celeris#769) #774 changes. Only engine/epoll/loop.go (the InlineMode reset in drainRead is skipped after ErrHijacked) and two epoll tests. No engine/iouring or driver code.

The failed job is being rerun once, as a known flake.

[FumingPower3925]

The one rerun failed too. Main 67fdb78 stays red on this job, which is not required.

• Attempt 2 of run 36386351199, job 108815122299 (https://github.com/goceleris/celeris/actions/runs/36386351199/job/108815122299): the third of 5 linger runs failed at driver_linger_close_linux_test.go:246 with the same signature, v_onrecv_ms=0.155 onclose_before_v=true and onclose_after_finalize_ms=100.6. The other 4 logged onclose_before_v=false and took 3015.9 to 3037.4 ms. Every other job in the attempt passed.
• Rate on main since fix(iouring): close a driver conn's engine descriptor off the worker, and fire onClose after the close (celeris#735) #744 merged, from the job logs (count of arm=linger lines with onclose_before_v=true):

main	attempt	job id	linger runs	close did not linger	conclusion
f0886ca	1	108770971397	5	0	success
dfd044f	1	108777850439	5	0	success
bd17725	1	108803003382	5	1	failure
bd17725	2	108805316292	5	0	success
67fdb78	1	108812436201	5	1	failure
67fdb78	2	108815122299	5	1	failure

That is 3 of 30 linger runs, and 3 of 6 jobs, because the step runs -count=5 and one miss fails the job. With the #746 and #768 PR cases, it is no longer rare enough for a single rerun to clear it reliably. Each of the 3 failures on main is the same one: the close did not linger (the linger arm took as long as the no-linger control), and the worker was not blocked. None is a #735 regression. Item 5's to-do stands: tell "did not linger" apart from "onClose before the close finished", and fail only on the second.

No further rerun from the merge train.