test: show which shutdown step a slow-to-exit test daemon was waiting on

Merged
BO
2d ago
+51-2

When the disconnect test's daemon misses its 8 s exit deadline, the failure now shows which shutdown step it was waiting on, and whether it exited in the next 20 s.

The test "a disconnect before client hello leaves no phantom session and the idle reaper exits" fails now and then on the Windows CI runner because the daemon doesn't exit in time. That stall didn't reproduce in 60 local Windows runs or in 20 repeats inside one Windows CI job (#539, closed unmerged). So this keeps the timing marks from #539 in the test's preload, and the next natural failure will carry them.

  • __tests__/fixtures/daemon-disconnect-order.cjs: once Daemon.stop starts, logs a begin and end line with elapsed ms and active handles for server.close, engine.stop, queryPool.destroy, toolHandler.closeAll, endFreshnessMeasurements, initPromise and defaultLease.release, plus a line every 500 ms (unref'd) and one at process exit. Each begin line prints before the step runs, so a synchronous stall is blamed on the right step. The lines go to daemon.log, which the failure message already includes.
  • __tests__/mcp-daemon.test.ts: after an 8 s miss, waits 20 s more and reports whether the daemon exited, so a slow exit can be told apart from a hang. The test limit goes from 45 s to 70 s to fit (worst case 3 × 10 s startup waits + 8 s + 20 s = 58 s). A passing run takes no longer.

Example of the logged lines on a passing Linux run:

[disconnect-test] +0ms server.close begin
[disconnect-test] +0ms engine.stop begin
[disconnect-test] +0ms queryPool.destroy begin
...
[disconnect-test] +7ms engine.stop end
[disconnect-test] +7ms exit 0

Validation at e857de0f: npx vitest run __tests__/mcp-daemon.test.ts passed 24/24 on Linux. I printed the daemon log from a passing run to check the marks appear in step order.

README: test-only change; checked the "About this fork" tables, and no row is affected.

Summary by cubic

Adds shutdown step timing to the disconnect test so a daemon that misses its 8 s exit deadline reports which shutdown step it was waiting on and whether it exited in the next 20 s.

The test fails intermittently on the Windows CI runner because the daemon doesn't exit in time, and the stall has not reproduced locally. Each shutdown step now logs a begin and end line with elapsed ms and active handles to daemon.log, plus a line every 500 ms and one at process exit; begin lines print before the step runs, so a synchronous stall is blamed on the right step. After an 8 s miss, the test waits 20 s more to tell a slow exit from a hang, so the test limit goes from 45 s to 70 s — a passing run takes no longer.