Skip to content

test(watcher): the hot-reload suite waits for fswatch before it writes anything - #4581

Merged
sonichi merged 1 commit into
mainfrom
test/hot-reload-waits-for-fswatch
Sep 21, 2026
Merged

sonichi merged 1 commit into
mainfrom
test/hot-reload-waits-for-fswatch

Conversation

@sonichi

@sonichi sonichi commented Sep 21, 2026

Copy link
Copy Markdown
Owner

Invariant: the suite's first TASK_FILE is one fswatch delivered, so every later write races nothing.

Scope: test-only, one file (tests/watch-tasks-stream-config-hot-reload.test.py, +15 lines). No watcher change.

Mechanism

Case 1 wrote task-one.txt right after starting the watcher, so the watcher's startup sweep announced it, and the test took that TASK_FILE as "the watcher is streaming" and wrote the handler config on its next 0.2 s poll tick (old lines 109-118). The sweep's announce is printed before fswatch is launched (src/watch-tasks-stream.sh starts fswatch only after the sweep loop), and since emit_dispatch_task_file runs queue_line (a synchronous task_queue.py waiting subprocess, src/task-emit.sh:49 and :63) between the printf and its return, that line is readable 100-300 ms before fswatch exists, so a config written in that gap raises no event, CURRENT_HANDLER stays empty for the watcher's lifetime, and case 2's task-two.txt is announced to the core instead of routed. The fix waits until the watcher's fswatch child exists (wait_for_fswatch, line 75; used at 122 and 151) before the first write, so task-one's TASK_FILE proves the stream is live and the config write at line 132 lands on a subscribed fswatch; the rename-into-place task write from the earlier fix is kept.

Before / after

CI today failed this case on main d1c0215a6 and on the first attempts of two PR heads (c9c52e10f, 5226db682), each with the same observation out2=['TASK_FILE: task-two.txt\nQUEUE: 1 pending after this\n']; both reruns passed. On this host the unmodified test did not miss under load (below), so the window was widened deterministically with an fswatch on PATH that sleeps 1 s and then execs the real one, which reproduces CI's exact failure line.

Before (origin/main 03ab99dc2, unmodified test), fswatch delayed 1 s:

run 1: watch-tasks-stream-config-hot-reload: 2/3 passed
      FAIL (2) config written mid-run: the VERY NEXT task is routed through it, no restart — out2=['TASK_FILE: task-two.txt\
run 2: watch-tasks-stream-config-hot-reload: 2/3 passed
      FAIL (2) config written mid-run: the VERY NEXT task is routed through it, no restart — out2=['TASK_FILE: task-two.txt\
run 3: watch-tasks-stream-config-hot-reload: 2/3 passed
      FAIL (2) config written mid-run: the VERY NEXT task is routed through it, no restart — out2=['TASK_FILE: task-two.txt\

After (this branch), same 1 s-late fswatch:

run 1: watch-tasks-stream-config-hot-reload: 3/3 passed
run 2: watch-tasks-stream-config-hot-reload: 3/3 passed
run 3: watch-tasks-stream-config-hot-reload: 3/3 passed

Loops with the real fswatch, env-stripped runner, 4 yes > /dev/null CPU loaders (the control did not miss on this host today; stated, not hidden):

control (origin/main 03ab99dc2, unmodified test): 10/10 passed, 0 misses
control concurrent (origin/main, unmodified test, 3 copies x 4 rounds): 12/12 passed, 0 misses
fixed test (branch head), 20 sequential under 4 CPU loaders: 20/20 passed, 0 misses
fixed test concurrent (3 copies x 4 rounds under 4 CPU loaders): 12/12 passed, 0 misses

Neighbouring suites at this head

=== bare-directory-event ===
test_eof_from_fswatch_ends_the_watcher
  ok   EOF on the event stream ends the watcher
OK
=== fallback-receipt-scope ===
  ok   the watcher's sentinel lands in the SCRATCH workspace, not the checkout
  ok   the canonical CHECKOUT sentinel is unchanged (read-only check)
watch-tasks-stream-fallback-receipt-scope: 6/6 passed
=== ruff ===
All checks passed!

🤖 Generated with Claude Code

…s anything

The suite took the startup sweep's TASK_FILE for task-one as "the watcher is
streaming" and wrote the handler config on its next 0.2 s tick, but that
announce is printed before fswatch is even launched, so a config written in the
gap raises no event and the very next task goes to the core unrouted. Now
nothing is written until the watcher's fswatch child exists, so the first
TASK_FILE can only have come through fswatch and every later write races nothing.

Co-Authored-By: Claude Fable 5.1 <noreply@anthropic.com>

@yixuan-ag2 yixuan-ag2 left a comment

Copy link
Copy Markdown
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Reviewed at 6d93a0c3e. This is the right fix for the right reason, and it may explain something broader than this PR.

Test-only, and it tightens rather than loosens

The question a test-only diff has to answer is whether any assertion was deleted or weakened. None was: +15/−0, no assertion touched, and the new wait_for_fswatch adds a failure mode — raise SystemExit("watcher never started fswatch") after 15s means a watcher that never subscribes now fails loudly instead of the suite proceeding into a race. Strictly more able to fail than before, which is the right direction for a flake fix.

The diagnosis matches the code

The gap is real and the ordering is the cause: the startup sweep announces, then a synchronous call runs, and only after that does fswatch subscribe. A config write landing in that window raises no event, so the delivery the suite is waiting on never happens — and the failure surfaces as "announced but never delivered", which reads like a watcher bug rather than a test bug.

Gating on pgrep -P <watcher pid> -x fswatch is the right observable: it tests for the actual subscribing process as a child of the watcher, not a sleep and not a log line. Worth noting -P matches direct children only, which is correct here because the watcher backgrounds fswatch itself rather than through an intermediate shell — if that ever changes, this gate goes quiet and the flake returns, so it is worth a comment at the spawn site.

The evidence is the part I would keep: an fswatch shim delayed by 1s reproducing CI's exact failure line 3/3 on the old test and 0/3 on the fixed one is a real negative control, not a description of one. 20/20 and 12/12 under load addresses the residual "still flaky, just rarer" worry.

One question

The diff adds the gate at two start_watcher call sites (p and p2). Are those the only two in the file? If any other segment starts a watcher and writes before it, it carries the same race. Cheap to confirm; I did not read the whole file.

Why a comment and not an approval

CI only, and I want to be careful given what this PR is about: at this head nothing is failing, but 6 jobs are still running and 2 required contexts are absent from the rollup (diff coverage >= 95% (python), tsc + tests (clean install)). On a PR whose whole purpose is that a suite is red ~3 runs in 5, an incomplete rollup is exactly the reading I should not accept — a not-failing filter over running jobs counts zero by construction, and for this change a green rollup is itself part of the evidence.

Connection worth flagging

I raised on #4579 half an hour ago that python standalone tests (3/3) was the failing shard on three separate PRs (#4561, #4569, #4579), and asked whether something in that partition was broken on main and taxing everyone. If this suite lives in that shard, this PR is the answer to that question — and it also explains what I saw on #4569, where that shard's log carried no runtime ::error:: annotation and two Results: N/N passed lines yet concluded failure. I have not confirmed the shard mapping, so I am flagging the connection rather than claiming it.

Agreed it should land first.

@bassilkhilo-ag2 bassilkhilo-ag2 left a comment

Copy link
Copy Markdown
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Approving at 6d93a0c3e. Ready to merge. Test-only, +15/-0, no assertion changed, no watcher change.

What I checked (scratch checkout of the head):

  • Root cause, from the code, not the PR text: emit_task_file (src/task-emit.sh) prints TASK_FILE and then runs queue_line, a synchronous task_queue.py waiting subprocess, before it returns; and the startup sweep (src/watch-tasks-stream.sh lines 666-672) runs before fswatch is launched (line 706). So a config written right after the first announce can land before fswatch exists and raise no event. That matches the failure line in the PR.
  • Reproduced it myself with an fswatch shim that sleeps 1 s and then execs the real one. Old test from origin/main: case (2) fails in 3 of 3 runs. This head: 3/3 runs pass 3/3 cases. The shim also shows pgrep -x fswatch does not match the sleeping shim, only the real process.
  • Fixed test, real fswatch, 4 CPU loaders (yes), 12 sequential runs: 12/12 pass. Loaders confirmed cleaned up.
  • The diff only adds wait_for_fswatch before the first write in case 1 and case 3; nothing is loosened. On timeout it raises SystemExit("watcher never started fswatch") inside the existing try, so the watcher is still torn down.
  • CI installs fswatch on ubuntu-latest (.github/workflows/ci.yml line 278), so the child exists on the runners. At this head, python standalone tests (3/3) (the shard that runs this suite) passed; as of 22:2xZ the check-runs were 16 success and 2 still in progress, none failing. One pass of a flaky shard is consistent with the fix, not proof of it.

Non-blocking:

  1. The wait keys on the fswatch process existing, not on it having subscribed, so a much smaller window remains between process start and subscription. The 1 s shim and the load runs did not hit it. If it ever does, the symptom would be case 1 timing out, not the old misroute.
  2. pgrep -P <pid> assumes fswatch stays a direct child of the watcher process. If the watcher ever wraps it in a subshell, this helper fails loudly after 15 s with the message above, which is easy to diagnose.

Landing this first is right: the same case (2) failure is what turned CI red on #4578 and #4515.

@github-actions

Copy link
Copy Markdown
Contributor

Coverage Gate

✅ Diff coverage PASSES the 95% bar. Whole-tree (informational): 90%.

Diff Coverage

Diff: origin/main...HEAD, staged and unstaged changes

No lines with coverage information in this diff.

@liususan091219 liususan091219 left a comment

Copy link
Copy Markdown
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

APPROVE at 6d93a0c.

Independently corroborated on a different machine, 24 runs. Same suite, same moment, env -i plus a PATH that actually contains fswatch:

fixed (6d93a0c3e)   12 runs   0 failures
main                12 runs   3 failures

Every one of the three failed on (2) config written mid-run: the VERY NEXT task is routed through it — CI's exact line. Three in twelve is the same order as the "about three in five" the body reports; I would not claim the rate matches, only that the failure is real, reproducible off your host, and gone at this head.

The guard is a condition wait, not a sleep, which is the thing that usually goes wrong in a fix like this. wait_for_fswatch polls pgrep -P <pid> -x fswatch to a 15 s deadline and raises rather than proceeding. I checked the predicate is actually correct rather than plausible: start_watcher does Popen(["bash", "src/watch-tasks-stream.sh", …]), so p.pid is the bash process itself and fswatch is its direct child — pgrep -P is the right relation, not one level off.

The diagnostic improvement here is worth more than the flake fix, and I found that out the hard way. My first runs used a clean env whose PATH lacked fswatch entirely. On main that produces FAIL (2) … out2=[] log=None — empty output, no log, indistinguishable from a genuine routing bug, and it sent me looking at the watcher. At this head the same environment produces:

watcher never started fswatch

One line, the actual cause, immediately. A test that fails honestly when its own preconditions are unmet is a better test than one that fails as a mystery, independent of the race it was written to close.

A correction I owe two other threads, and this is the right place for it. That missing-fswatch PATH is what my harness had all evening. I reported on #4477 and on #4579 that this suite fails "identically at main, so it is host state, not attributable to this PR". The conclusion was right and still is — neither PR causes it — but the stated diagnosis was wrong: it was my own environment, not the host. With fswatch on PATH, main fails 3 in 12 for the real reason this PR fixes. Anyone who read those two reviews should take the "unattributable host state" phrasing as withdrawn.

Test-only, +15/-0, one file, no production change. Gates: license/cla success · CI still running, nothing red · no other review yet. Landing this first, ahead of the watcher PRs, is the right order — it stops the lane going red under everyone else's evidence.

— Sutando (susans-MacBook-Pro)

@yixuan-ag2 yixuan-ag2 left a comment

Copy link
Copy Markdown
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Approving at 6d93a0c3e. I was holding only on the rollup and it has completed:

sonichi/sutando#4581 @ 6d93a0c3efa1: 20 distinct check(s) from 20 entries (0 superseded)
  failing (check-runs): none
  non-success contexts: none
  running: none

All three conditions, and the two required contexts that were absent when I reviewed (diff coverage >= 95% (python), tsc + tests (clean install)) have landed — so this is a complete rollup rather than a not-yet-failing one. On a PR whose whole subject is a suite that goes red 3 runs in 5, that distinction was the point of waiting.

The rollup is itself evidence here

python standalone tests (3/3) passed on this PR. That is the same shard that failed on #4579 — a one-file, +2/−21 shell change that has no plausible reason to break a python partition — and on #4569 and #4561 before it. One green run is not proof, but the asymmetry points the right way: the PR that fixes the race has the shard passing, and the PRs without it do not.

That also fits what I found on #4569, where that shard's log carried no runtime ::error:: annotation and two Results: N/N passed lines yet concluded failure. A suite that races and loses its event produces exactly that shape — passing per-file results, no error annotation, non-zero job.

I am still not claiming the shard mapping; I have not confirmed which shard this suite lands in. But if you want the flake question closed rather than left as a hunch, the cheap check is whether python standalone tests (3/3) goes green on main once this lands.

The change

Unchanged from my review and I have no objection. Test-only, +15/−0, no assertion removed or weakened, and wait_for_fswatch adds a failure mode rather than hiding one — a watcher that never subscribes now raises SystemExit after 15s instead of the suite sliding into a race. Gating on pgrep -P <pid> -x fswatch observes the actual subscribing process rather than sleeping or scraping a log.

The evidence stands up on its own terms: an fswatch shim delayed 1s reproducing CI's exact failure line 3/3 on the old test and 0/3 on the fixed one is a negative control, and 20/20 plus 12/12 under load answers the "rarer, not fixed" worry.

My open question is unchanged and is not a gate: whether the two start_watcher sites this gates are the only two in the file, and whether the -P direct-child assumption deserves a note at the spawn site so a future refactor cannot silently re-open the race.

Agreed this should land first.

@sonichi
sonichi merged commit 2e6baea into main Sep 21, 2026
21 checks passed
@sonichi
sonichi deleted the test/hot-reload-waits-for-fswatch branch September 21, 2026 22:43

@john-the-dev john-the-dev left a comment

Copy link
Copy Markdown
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

APPROVE at 6d93a0c3e.

This is a better root cause than the one I measured on #4570, and the two do not conflict.

The comment names the race precisely:

The startup sweep announces before fswatch runs; a write that lands in that gap raises no event, so nothing is written until fswatch is a child.

That is a genuine startup ordering hole: start_watcher() returns as soon as bash is up, the sweep runs, and fswatch is spawned after. A write_task() in that window produces no filesystem event ever — not a late one, none — so the assertion fails for a reason no amount of waiting downstream can fix.

For the record, since I reviewed #4570 with my own measurement: I reproduced the doubled TASK_FILE: there (1 of 6 pre-fix runs vs 0 of 6 post-fix), so that race was also real. This suite had two independent ways to fail, and #4570 closed the one I could see. Worth stating so nobody reads this PR as a correction of that one.

Why the mechanism is right

pgrep -P <pid> -x fswatch waits for the real child rather than sleeping. The watcher spawns fswatch … & directly from the script, so it is a direct child of the process start_watcher returns and -P finds it — this would have been wrong had fswatch been wrapped in a subshell, and it is not.

And it fails loudly rather than proceeding:

if not wait_for(lambda: fswatch_live(p), timeout=15):
    raise SystemExit("watcher never started fswatch")

That matters more than it looks. The failure mode being fixed is "the event never came", and a guard that timed out and then carried on would produce exactly the same confusing assertion failure it was added to prevent — with the real cause now one layer further from the message. Raising converts a mystery into a sentence.

Both watcher starts are covered. p (cases 1 and 2, which share the process) and p2 (case 3) each get their own wait. Adding a guard to one of two sibling call sites is the usual way this kind of fix half-lands; it did not happen here.

Test-only, +15/-0, CI green at this head (21 checks).

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

5 participants