4.1 KiB
Row 292 gate r2: the old-test red (read-only notes, no node)
Untracked until the results commit, so the round 1 digest 2fa7ae17 stays (sage-3185). Written for sage-3188.
The red
Gate r2 on 0d0021454, cli suite stage, 04:54:03Z 10-23: 910 tests, 909 pass, 1 fail.
compactions-launch.test.mjs:206, row 270's store-unreadable test, fails at :229
deepEqual(ends[0], ends[1]). The first run ended ['session-invalid', 22, null], and the second
ended ['stopped', 0, null]. Every assertion before :229 passed. Log: gizmo-292-out/r2/suite/cli.log:1023-1045.
Where exit 22 comes from (read from the code, not run)
- packages/harness/src/runner.mjs:43
EXIT.sessionis 22. :55SESSION_GONEis unauthenticated, not-holder and run-ended. The runner exits 22 when a broker call gets one of those: message.receive at :529, state at :550, the reply at :580, and the landing state at :505. - packages/seat/src/session.mjs:340 maps 22 to "session-invalid" for the end event.
- The test's runs end by idle. The fixture sets
launch.threadIdleSeconds = 1(compactions-launch.test.mjs:72). - The idle stop is in packages/cli/src/launcher.mjs:703-717. It calls the broker op
threadIdlefirst. packages/bus/src/broker.mjs:1044-1058 releases the claim in that call (#claimEnd(..., 'release')at :1055). After the op returns, the launcher recordsthread-idleand only then sends SIGTERM (:716). The order is deliberate. Row 121 round 2, Dewey's F3 (broker.mjs:1040-1043), wants a message sent after the snapshot to wait for the next holder. - The window: the claim is already released, but the runner's SIGTERM handler hasn't set
stoppingyet. A message.receive poll that the broker answers in that window getsnot-holder. Polls come everypollInterval, which defaults to 2000 ms (runner.mjs:57). The catch at :526-531 setscode = EXIT.sessionwithout looking atstopping. A call already in flight when the release lands ends the same way, even if SIGTERM arrives before its answer. Either way the run ends session-invalid/22 instead of stopped/0.
Reading
This is a race in the product's idle stop (launcher, broker and runner ordering), not in row 292,
and not in row 270's collection code. Row 270's test exposes it because :229 asserts that both runs'
ends are equal, which in practice means both are idle stops ending stopped. Row 292's diff
(stack-release.sh, stack-release.test.mjs, TOOLS.md, packets) doesn't reach any of these files.
I haven't confirmed this. The 10-run diagnostic Sage proposed to Mos (sage-3186) measures how often it happens. Two fixes are possible if it reproduces, and both go to a separate row, as Sage ruled:
- Product: in the runner, treat
not-holderas stopped when it comes after a SIGTERM. That doesn't close the window where the poll lands before SIGTERM, so a cleaner fix is for the launcher to record that it is the one stopping the run, and map the end to stopped. - Test: compare only the reason classes the test cares about at :229. That loosens an assertion, which needs Mos under mos-1272.
Mos's ruling and the diagnostic (mos-1411, sage-3190, CLEAR sage-3193)
Mos ruled that :229 stays as written and that the race gets its own row (owner Gizmoduck, reviewer Dewey, Vikunja 588). 292's gate counts after one whole, unedited cli suite rerun, provided that rerun is green.
Diagnostic, 05:01:01Z to 05:03:31Z 10-23, on 0d0021454: compactions-launch.test.mjs whole and unedited,
10 isolated runs, each with its own TMPDIR. All ten exited rc=0 with 5/5 pass and no red, so ends[0]
was stopped/0 every time. A side loop copied each runner.log every 100 ms before the test removed its
root. 72 logs end runner: exiting 0. 27 were deleted before their last line was copied. One ends
runner: session stopped working: not-holder and then runner: exiting 22: run 2, launch
r846b8d083502, in the clear test (:305). That test doesn't compare ends, so it passed anyway. So the
race happens, roughly once in a hundred idle stops, and the code is not-holder, which matches the
reading above. Output: gizmo-292-out/diag.out and diag/run2/logs/r846b8d083502/runner.log.