Repository navigation
fix(test): handler-terminal-rc waits on what the watcher writes, not on a window - #5007
Conversation
…on a window The suite polled a fixed 25s window per scenario. Two of the four scenarios (rc 4, rc 0) have no stdout line to wait for, so they always ran the full window and the file cost 55s; the control scenario (rc 1) waited for the TASK_FILE line but could not tell a watcher that stalled from one that had exited, and a FAIL printed only the watcher's stderr. In CI (run 36873678067, a PR touching no watcher file) the control scenario failed that way: the claim still held at the kill, no handler verdict line, nothing to say where the watcher stopped. Every scenario now ends on something the watcher itself writes: the TASK_FILE line, the published result, or the `after-done` transition plus the claim's release (through the documented SUTANDO_WATCHER_TRANSITION_HOOK seam); the restart witness waits for the first watcher's sentinel instead of sleeping 2s. A claim released after `after-handler` ends any scenario at once, so a wrong outcome is diagnosed immediately rather than at the bound; a watcher that exits ends its wait at once; and a FAIL prints the transitions reached, the exit status, the claim and result state and the stderr. The bound (40s) is a stall ceiling, not the expected cost. Watcher code is untouched. Before: 20/20 PASS in 55s each under 10x CPU load (the CI failure did not reproduce on macOS/bash 5.3). After: 20/20 PASS, 17-44s each under the same load on a host at load average 30-50, 7s quiet. Stand: Echo Act IV Pro Co-Authored-By: Claude Fable 5.1 <noreply@anthropic.com>
Coverage Gate✅ Diff coverage PASSES the 95% bar. Whole-tree (informational): 91%. Diff CoverageDiff: origin/main...HEAD, staged and unstaged changesNo lines with coverage information in this diff. |
john-the-dev
left a comment
There was a problem hiding this comment.
Approving at exact head 425c417e3d539bf246a66fc8c748a2c4fbc9cff1, with one non-blocking gap that should be named.
Scope:
- One file,
tests/watch-tasks-stream-handler-terminal-rc.test.py(+197/−124). The watcher is unchanged. - No scenario dropped: rc=4, the rc=1 control, the rc=0 control and the restart witness all remain. The fixed
sleep 2.0before the restart is now an asserted "first watcher came up". - Five runs at head took 3–5 s, against 54 s for the old file. Every wait is bounded (40 s main, 10 s claim, 10 + 5 s stop).
Mutation results (watcher mutated, both test versions run, watcher restored):
| mutation | new test | old test |
|---|---|---|
| rc 4 no longer outranks the stored disposition | FAIL | FAIL |
| every non-zero rc treated as must-handle | FAIL (rc=1 control) | FAIL |
| success path emits TASK_FILE right after releasing the claim | FAIL (rc=0 control) | FAIL |
| rc=4 path publishes a failure and emits | FAIL | FAIL |
| success path emits 2 s later, in the background | PASS (survives) | FAIL |
The gap (nit, not blocking):
- The absence checks — rc=4 "not emitted" (~241-243), rc=0 "emits nothing" (~256-258), restart "not handed to core" (~232-233) — now stop watching once the claim is released.
run_handler_nowdecides, emits or publishes, and then releases its claim (src/watch-tasks-stream.sh~732-777). So a synchronous wrong emit is caught, and so is anything printed during shutdown, sincestop()drains stdout.- An emit that happens after the release is not caught. The old 25 s window caught the delayed-emit mutation only incidentally, and no current watcher path emits asynchronously. Still, "nothing weakened" is slightly too strong.
- A ~2 s read-only tail after settling, in those three cases, would kill that mutation and keep the suite fast.
Two more small ones:
run()discardswait_until's return (~201). For the rc=0 control, assert thatafter-donewas reached. Otherwise a watcher that dies early makes "emits nothing" pass vacuously. The old file had the same gap.- The restart wait (~232) has no
over()early exit, so a failing run spends the full 40 s there. Passing runs are unaffected.
Not verified: that this resolves the CI stall in #4862 (not reproducible locally), and Linux/CI behaviour under load.
keweichen
left a comment
There was a problem hiding this comment.
Changes requested at exact head 425c417e3d539bf246a66fc8c748a2c4fbc9cff1.
Blocker — the refactor weakens the must-handle non-emission regression test.
run() now stops as soon as the result/claim-release observation completes (tests/watch-tasks-stream-handler-terminal-rc.test.py:189-205). Watcher.stop() then sends TERM to the whole watcher process group (:150-160), and only afterward does the assertion inspect captured stdout (:241-243). That can make the test suppress the very bad output it is meant to detect.
I verified this with an uncommitted production mutation placed immediately after the rc=4 claim release at src/watch-tasks-stream.sh:775:
if [ "$handler_rc" -eq 4 ]; then
( sleep 2; emit_fallback_task_file "$announce" ) &
fiThe watcher is otherwise byte-identical at the parent and HEAD. Results:
HEAD 425c417e3: PASS (6.6s)
ok a must-handle result is NOT emitted to the live core
parent 1be758ba5: FAIL
FAIL a must-handle result is NOT emitted to the live core
— the task reached the unrestricted core despite the handler refusing it
In a real continuously running watcher, that delayed TASK_FILE leaks the required-handler task to the unrestricted core. HEAD passes because the harness kills the delayed emitter immediately after release; the parent's observation window catches it. This is a direct mutation of the security-boundary behavior, so the PR's claim that the four assertions are unchanged is not preserved.
There is a second false-green in the same synchronization logic: both wait_until() results at lines 201 and 204 are discarded. An uncommitted mutation that exits successfully immediately after after-handler but before record_worker_done / after-done leaves the entire HEAD suite green, including the rc=0 control that says it reached after-done.
Required fix: preserve a short bounded read-only drain/quiescence tail for every negative-emission scenario (rc=4, rc=0, and restart), and require the expected settle observations instead of discarding their return values. Please rerun both mutations as controls. A small tail retains most of the measured runtime improvement (clean HEAD is about 6s versus about 55s at the parent).
Other evidence: the exact-head suite passes unmutated; git diff ... | bash scripts/review-checks.sh passes; current CI and SHA-bound CLA are green. No live-service restart is required for this test-only diff. Worst case as written is a false-green test while a must-handle task is handed to the unrestricted core.
Verdict: changes requested; the negative assertions must keep observing long enough to discriminate post-release output, and the expected settle event must be asserted.
Review follow-up, test only; the watcher is untouched. - The absence checks (rc 4 not emitted, rc 0 emits nothing, restart not handed to the core) keep reading stdout for 2.5s after the claim is released, so an emit that lands after the release is caught again. - The rc 0 control asserts `after-done` was reached and the claim released, so a watcher that dies early cannot pass "emits nothing" vacuously. - The restart wait ends early once the claim is released after `after-handler`, like the other scenarios. - The three scenarios and the restart witness's first watcher start together, so the tails overlap instead of adding to the suite time. Stand: Echo Act IV Pro Co-Authored-By: Claude Opus 5.5 (1M context) <noreply@anthropic.com>
|
Follow-up to @john-the-dev's review, at What changed
Mutations (watcher mutated in a scratch worktree, test run,
For mutation 5, the trace shows that the tail caught it after the claim was released. The transitions show Under load: 10 runs, one after another, with 10 × Suite time: 12.7–13.3s without the synthetic load. The host itself was at load average 19–30, so I couldn't get a quiet measurement. For comparison,
Stand: Echo Act IV Pro |
…point Review follow-up, test only; the watcher is untouched. The rc 4 case and the restart witness now assert that the handler ran and the claim was released before their "not emitted" checks count, as the rc 0 control already does. A watcher that dies before settling a task fails instead of passing the absence check vacuously. Stand: Echo Act IV Pro Co-Authored-By: Claude Opus 5.5 (1M context) <noreply@anthropic.com>
|
Follow-up to @keweichen's CHANGES_REQUESTED at What changed for her two blockers:
Her two controls, run exactly as described. In each run the watcher was mutated in my worktree, the test file was run, and then the watcher was restored with
The remaining watcher mutations from @john-the-dev's table, all at
Under load. 10 sequential runs at Suite time: 12 s for the unmutated run in the table above. The host was not quiet.
Stand: Echo Act IV Pro |
john-the-dev
left a comment
There was a problem hiding this comment.
Re-approving at head e36c5d2d4a6dcea539ddf77298a5243c71f2cdc2. The change is test-only: the PR touches only tests/watch-tasks-stream-handler-terminal-rc.test.py, and src/watch-tasks-stream.sh is unchanged.
The gap I flagged at 425c417e3 is closed. Each mutation was made in the watcher and restored by byte comparison. "Old test" is the test file from 425c417e3 run against the same mutated watcher.
| Mutant | New test | Old test |
|---|---|---|
| emit ~2 s after release, rc 4 path | fails | passes |
| emit ~2 s after release, rc 0 path | fails | passes |
exit 0 before after-done |
fails ("success path did not complete") | passes (vacuous) |
| watcher exits at start | fails | fails |
| rc 4 ignored (the original bug) | fails | fails |
| emit ~3 s after release | passes | passes |
The last row is the expected bound: anything later than TAIL_S=2.5 goes unseen. The tail only sleeps and reads stdout, and touches no task, claim or result files.
Timing: 3 solo runs took 9.9 to 13.0 s. 12 runs at once all passed in 23 s. In CI it runs in the "python standalone (3/5)" leg, taking 11 s. All checks on head pass, and Windows was skipped.
Earlier head cecaced00, run 36896586187:
- Shard 3/5 failed this test's new success control. The rc 0 watcher had exited 0 mid-handler:
before-claimwas the only transition, the claim was still held, and stderr said "task handler in flight … at shutdown". - e36c5d2 doesn't change the success path, so this can still happen at head. The new control turns what used to be a silent pass into a visible failure. I couldn't reproduce it (12/12 concurrent passes) or find what signalled the watcher, so it's worth one sentence in the body, and a re-run if it shows up again.
- Shard 1/5's
sparrow-result-guard.test.pyfailure is unrelated: it passed 3/3 locally.
Nits:
- The test never removes its
mkdtempworkspaces. My runs left 118term-rc-*directories in$TMPDIR. - The tail starts when the release is observed, not when it happens, so the window is about 2.5 s plus one poll. The docstring could say so.
review-checks.sh passes on gh pr diff 5007. Kewei's CR at 425c417e3 still needs Kewei's re-review.
Not verified: Linux runner behaviour (all my runs were on macOS) and Kewei's exact mutant bodies.
Review nit: every Workspace registers its mkdtemp tree for removal at interpreter exit, so pass or fail leaves nothing in $TMPDIR. The diagnosis a FAIL prints is captured before exit. Stand: Echo Act IV Pro Co-Authored-By: Claude Opus 5.5 (1M context) <noreply@anthropic.com>
keweichen
left a comment
There was a problem hiding this comment.
Re-reviewed current exact head de2a75cce7193bb3d230e08e7086a29f31161cb2; this replaces my CHANGES_REQUESTED at 425c417e3.
Both blockers are fixed. Every negative-emission path now keeps reading stdout for a bounded 2.5-second tail after its settle observation, before teardown: rc 4, rc 0, and the restart witness. The rc 4 and restart cases assert that the handler ran and the claim was released; rc 0 additionally requires after-done, so an early watcher exit cannot make an absence claim pass vacuously. The restart wait also exits immediately on the wrong settled outcome rather than consuming the 40-second bound.
Independent controls at this head discriminate the failures that the old test missed:
- a delayed rc 4
TASK_FILEemit after release makes both negative-emission assertions fail here, while425c417e3passed; - exiting the success path after
after-handlerbut beforerecord_worker_done/after-donefails the new completion assertion here, while425c417e3passed; - the restart wrong-outcome control ends through its early-exit path instead of waiting out the deadline.
The unmutated exact-head test passed locally in 11.3 seconds, and the cumulative review scan passed. The final e36c5d2d4..de2a75cce delta only registers each scratch workspace for atexit cleanup; it does not change synchronization or assertions. Current hosted CI and SHA-bound CLA are green.
The 2.5-second tail is intentionally bounded from settle observation, not a proof against arbitrarily delayed output; a 3-second delayed mutation passes. That is non-blocking here: production watcher code is unchanged and has no asynchronous emit path. The cecaced00 shard failure is also not hidden by this test: the new settle assertion exposed a watcher that exited 0 before being signalled, with only before-claim and a held claim. The root cause remains unproven and is tracked separately in #5012.
Worst-case disruption from this test-only PR is CI behavior, not installed runtime behavior: a real mid-handler watcher exit now fails with a useful trace, while an emission later than the explicit tail remains outside the regression bound.
Verdict: APPROVE — no blocker remains at this head. Ready from my review; the full merge gate still needs a current second maintainer approval because the existing approval predates the final cleanup commit.
john-the-dev
left a comment
There was a problem hiding this comment.
Re-approving at head de2a75cce7193bb3d230e08e7086a29f31161cb2. The only change since my approval at e36c5d2d4 is +3 lines in tests/watch-tasks-stream-handler-terminal-rc.test.py: atexit.register(shutil.rmtree, self.tmp, True) in Workspace.__init__. That cleans up the term-rc-* workspaces I flagged, and ignore_errors=True keeps a still-running watcher from turning cleanup into a failure. The test logic is unchanged and the watcher is untouched. CI: 26 pass, 1 skipping. The cecaced shard-3 death is now tracked as #5012, and the 2.5 s bound is stated in the body.
qingyun-wu
left a comment
There was a problem hiding this comment.
Code-owner approval, decided by Qingyun on the [PA] decision page (Pending actions for owners). Posted by Qingyun's Sutando at de2a75c.
|
@cla-assistant check |
What changed, and why
tests/watch-tasks-stream-handler-terminal-rc.test.pyfailed on #4994 (run 36873678067, job 110408347985,python standalone tests (3/5), 2026-10-01 ~14:08Z) — a PR that touches no watcher file — and passed on rerun. The failing check:The test polled a fixed 25s window per scenario, and the suite ran 79s where it normally runs ~55s: the control scenario (handler probes 0, exits 1, so the task must be handed to the core) used its whole window. What the stderr says: the claim was still held at the kill (the "in flight" line) and no handler verdict line was ever printed (
optional task handler failed ... falling back to live corefor rc 1, orhandler timed out/required Team handler failedfor the other branches). So the watcher got pastacquire_task_claimand never reached the verdict insiderun_handler_now— the synchronous handler run and its watchdog subshell — for at least 24s. The test could not say more: its loop could not tell a stalled watcher from one that had exited, two of the four scenarios had no stdout line to wait for and always ran the full 25s, and a FAIL printed only stderr.This PR changes only the test. Every scenario now ends on something the watcher itself writes, with a bound a stall reaches rather than a window the normal case waits out:
TASK_FILEline on stdout.after-donetransition (through the documentedSUTANDO_WATCHER_TRANSITION_HOOKseam, the same onewatch-tasks-stream-shutdown-leaves-inflight-claim.test.pyuses) plus the claim's release.time.sleep(2.0).after-handler— the watcher is done with the task whatever it decided — so a wrong outcome is diagnosed immediately, not at the bound.p.poll()), and a FAIL prints the transitions reached, the exit status, the claim and result state, stdout and stderr.Watcher code is untouched. The root cause of the stall itself is not established: it did not reproduce locally (macOS, bash 5.3; see below), so this PR makes the test end on observables and leaves a diagnosable trace for the next occurrence rather than widening a window that a stall would not respect anyway. Suite cost drops from 55s to ~7s quiet (17–44s on a host at load average 30–50), which is the lever #4862 names for this family.
Update after review (
cecaced00,e36c5d2d4,de2a75cce)What the test now does on top of the description above (test only;
git diff origin/main -- src/is empty):after-done.The mutation tables are in the PR comments: 5/5 of rui's mutations and both of @keweichen's controls fail at the new head.
The shard 3 failure at
cecaced00is a watcher finding, not a harness race. Filed as #5012. That job (110485063284) failed on the new rc 0 success control:What this shows:
before-claim, and it was still holding the claim.cleanup(). In a subshell,cleanup()uses the parent's$$, so it wouldkill -TERM 0the watcher's whole group, and the watcher then exits 0 through its own trap. Which subshell runs the inherited trap, and why, is not established; it did not reproduce on macOS.So the original flake this PR set out to fix is most likely #5012, a watcher bug. This PR does not fix it. What it changes is the test: that failure now shows up with its exit status, last transition and claim state, instead of as a 25 s timeout.
The other two failures at
cecaced00are unrelated to this file:python standalone tests (1/5)failed intests/sparrow-result-guard.test.py; I did not read thetscjob's log. All checks one36c5d2d4passed.Files to look at first
tests/watch-tasks-stream-handler-terminal-rc.test.py—Workspace(fixture + hook),Watcher.wait_until(observable / exited / timeout),run()(per-scenariosettledpredicate plus the claim-released end),restart_witness()(sentinel wait).What this proves
The four assertions are unchanged (must-handle not emitted + failure published; rc 1 still falls back; rc 0 emits nothing; restart witness publishes, does not emit). One assertion is added to the restart witness — the first watcher stamped its sentinel before it was stopped — which the old
sleep(2.0)only assumed.Feature/documentation consistency
N/A — test-only change; no user-visible behaviour or document changes.
Before/after evidence
Parent commit (
1be758ba5, =origin/main), the test as it was — passes locally but costs 55s because two scenarios wait out the window:Reproduction attempt under load, parent commit (20 sequential runs, 10 ×
yes > /dev/nullon a 10-core host, SUTANDO_ scrubbed viatests/fixtures/clean_watcher_env.py's set):*The CI failure did not reproduce: 0/20 full-suite runs, and 0/80 runs of the control scenario alone (12s deadline) under the same load. A direct stress of the watchdog subshell pattern (
( trap ... TERM; sleep & wait ) &thenkill -TERM; wait) ran 1800 iterations under 60 busy loops with no lost signal and no slow wait on bash 5.3. The stall is Linux-only so far (ubuntu-latest, bash 5.2, four suites per 4-vCPU runner under coverage) and observed once.HEAD (
425c417e3), quiet host:HEAD, 20 × under the same load (run twice; the second on the exact pushed commit):
The diagnosis path, checked by mutation (not committed). Control handler changed to exit 4 — the FAIL now arrives when the claim is released (4.3s), not at the bound, and says where the watcher went:
fswatch stub changed to exit 1 — the watcher's early exit ends the wait in 1.0s instead of 40s:
Had the CI run carried this trace, the stderr above would have been accompanied by the last transition reached (
before-claimwith noafter-handler= stalled in the handler run / watchdog wait) and the watcher's exit status.Tests run
Adjacent watcher suites at HEAD, scrubbed env (
tests/watch-tasks-stream*.test.{py,sh},tests/watcher*.test.{py,sh}, 34 files): 33 PASS.tests/watch-tasks-stream-bare-directory-event.test.pyFAILs one check on this host (a second EOF past the relaunch budget ends the watcher, status 1 — rc=None), in the chain run and standalone at load average 11; it is a file this PR does not touch, on a watcher this PR does not touch, and it is in #4862's list — reported here, not fixed here.Live path: N/A (test only). Stacked PR: N/A. Hardcoded paths: none added (fixtures use
tempfile.mkdtemp).tests/python-suite-costs.txtstill lists this file at 25s (measured in CI); left for the next regeneration from a job log rather than hand-edited.Refs #5012 (the watcher exiting mid-handler, seen in this test at
cecaced00and on #4994), #4862 (this file is one of the suites it lists; the others are not changed here), #4750, #4967. Not a duplicate of #5000, which isolates these suites on their own CI leg; this PR changes what the test waits on, which that lane change does not.🤖 Generated with Claude Code