Repository navigation
fix(bin): stop the watcher from missing status signals written during or between cycles - #85
Merged
Merged
Conversation
A lane's done, needs-decision, or blocked line reaches firstmate only through the watcher's signal scan, and that scan was the last step of a long cycle. On 2026-10-08 two done lines and three keyed lane decisions sat unsignaled for up to 77 minutes. The lines were never lost: the seen markers never advanced, and the first watcher that reached the scan surfaced all 20 pending files at once. Of the six watchers between 14:35 and 15:57, five exited on a wake raised by an earlier step (three ledger wakes, one rearm-resurface, one secondmate stall) and only one reached the scan, after about 9.5 minutes. Each such wake also cost one firstmate round trip before the next watcher could scan. The steps ahead of the scan are O(state) in bash 3.2 (the pending-reply tick alone reads 2282 retained records, 12-30 s per cycle unloaded; the scan itself took 5 s unloaded and 47 s in the loaded watcher) and a prior step can block for the whole cycle. The signal scan now runs first. To keep the other work (ledger wake, reconcile and liveness ticks, process-event and inactive scans, due checks) from starving under a fleet that signals every cycle, the order is bounded: after FM_PRELUDE_MAX_DEFER (default 3) consecutive signal wakes that skipped it, the next cycle runs it first. The count is persisted in state/.prelude-deferred; an unreadable count reads as owed, which is the previous order. FM_PRELUDE_MAX_DEFER=0 always selects the previous order. Alternatives, by counted factors: - Previous order: write-to-wake latency is the full prelude (minutes under load) plus one round trip per earlier wake; 8 wake-capable steps ahead of the scan; 5 of 6 observed cycles never reached it. - Signals first, unconditionally: latency is the scan alone, but the other work never runs while every cycle signals (every watcher from 14:03 to 14:31 exited on a signal), so liveness and relaunch ticks would starve. - Signals first with a bounded deferral (chosen): latency is the scan alone in all but one cycle in four under a constantly chatty fleet, and the other work is delayed by at most three signal wakes. One scan per cycle, no new process, one persisted integer. - Detach the other work as helpers: removes the blocking, but those steps wake through wake() and exit the cycle, so each needs a new result channel. - Speed up the slow steps only: leaves the pre-emption and any new slow step. Tests: the shape tests (done written between cycles and during one, keyed needs-decision and blocked) pass before and after, which rules out a baseline race and a classifier skip. The blocked-check, overdue-ledger, and bounded-deferral tests fail before and pass after. The poll-cycle test's ordering assertion is updated to the new contract. Not covered, filed as follow-up: one cycle on 2026-10-08 spent about 33 minutes in a step between the ledger capture and the secondmate stall tick that the available records do not identify, and signals written during such a stall still wait for it to end.
A lane's done, needs-decision, or blocked line reaches firstmate only through the watcher's signal scan, and that scan was the last step of a long cycle. On 2026-10-08 two done lines and three keyed lane decisions sat unsignaled for up to 77 minutes. The lines were never lost: the seen markers never advanced, and the first watcher that reached the scan surfaced all 20 pending files at once. Of the six watchers between 14:35 and 15:57, five exited on a wake raised by an earlier step (three ledger wakes, one rearm-resurface, one secondmate stall) and only one reached the scan, after about 9.5 minutes. Each such wake also cost one firstmate round trip before the next watcher could scan. The steps ahead of the scan are O(state) in bash 3.2 (the pending-reply tick alone reads 2282 retained records, 12-30 s per cycle unloaded; the scan itself took 5 s unloaded and 47 s in the loaded watcher) and a prior step can block for the whole cycle. The signal scan now runs first. To keep the other work (ledger wake, reconcile and liveness ticks, process-event and inactive scans, due checks) from starving under a fleet that signals every cycle, the order is bounded: after FM_PRELUDE_MAX_DEFER (default 3) consecutive signal wakes that skipped it, the next cycle runs it first. The count is persisted in state/.prelude-deferred; an unreadable count reads as owed, which is the previous order. FM_PRELUDE_MAX_DEFER=0 always selects the previous order. Alternatives, by counted factors: - Previous order: write-to-wake latency is the full prelude (minutes under load) plus one round trip per earlier wake; 8 wake-capable steps ahead of the scan; 5 of 6 observed cycles never reached it. - Signals first, unconditionally: latency is the scan alone, but the other work never runs while every cycle signals (every watcher from 14:03 to 14:31 exited on a signal), so liveness and relaunch ticks would starve. - Signals first with a bounded deferral (chosen): latency is the scan alone in all but one cycle in four under a constantly chatty fleet, and the other work is delayed by at most three signal wakes. One scan per cycle, no new process, one persisted integer. - Detach the other work as helpers: removes the blocking, but those steps wake through wake() and exit the cycle, so each needs a new result channel. - Speed up the slow steps only: leaves the pre-emption and any new slow step. Tests: the shape tests (done written between cycles and during one, keyed needs-decision and blocked) pass before and after, which rules out a baseline race and a classifier skip. The blocked-check, overdue-ledger, and bounded-deferral tests fail before and pass after. The poll-cycle test's ordering assertion is updated to the new contract. Not covered, filed as follow-up: one cycle on 2026-10-08 spent about 33 minutes in a step between the ledger capture and the secondmate stall tick that the available records do not identify, and signals written during such a stall still wait for it to end.
…hrough delivery failures
…to fm/fm-watch-missed-done-signal # Conflicts: # bin/fm-watch.sh # docs/configuration.md # tests/fm-watch-triage.test.sh
…m/fm-watch-missed-done-signal
…files only. They are not committed. **Cause** This PR makes the watcher report unread signals before it runs checks. Two older test files left an unread signal file in their setup. The watcher reported that signal and stopped, so the check that each test expected never ran. The watcher behavior is the intended one. The tests were wrong. **Rule that was broken** A test that expects a check wake must not leave an unread signal in its setup. **All places with this problem (3)** 1. `tests/fm-inactive-reconcile.test.sh`, `test_watcher_hook_and_idle_secondmate_exemption`. This is the shard 4 failure. An unread `child.turn-ended` file was reported first. 2. `tests/fm-inactive-reconcile.test.sh`, `test_watcher_poll_delivers_child_ledger_line_to_parent`. CI did not reach this test, because the file stops at the first failure. It had the same problem and would have failed next. 3. `tests/fm-pr-check-security.test.sh`, `test_persistent_secondmate_retirement_is_poll_only`. This is the shard 9 failure. An unread `domain.status` file was reported first. **Fix** 1. `prime_seen` in `tests/fm-inactive-reconcile.test.sh` now also marks a `.turn-ended` file as read. 2. Tests 1 and 2 mark `child.turn-ended` as read before the watcher starts. 3. Test 3 marks `domain.status` as read before the watcher starts. 4. No product code changed. No assertion was removed or made weaker. **Results** 1. `bash tests/fm-inactive-reconcile.test.sh`: pass, 37 ok, exit 0. 2. `FM_LAUNCH_AGENTS_DIR=/nonexistent-fm-launch-agents bash tests/fm-pr-check-security.test.sh`: pass, 45 ok, exit 0. 3. `bin/fm-lint.sh`: clean, exit 0. **One thing to know** Without that `FM_LAUNCH_AGENTS_DIR` setting, `tests/fm-pr-check-security.test.sh` fails on this Mac at line 822. The message is "safe lifecycle-compatible task ID could not be torn down". The refusal comes from the launch-agent check in `bin/fm-teardown.sh`, which only runs when `~/Library/LaunchAgents` exists. This PR does not touch that file. CI passed that line on Linux. It also passed once on this Mac and then failed three times. I did not find why it changes, and I did not change it
MrGTV-love
added a commit
that referenced
this pull request
Oct 10, 2026
… red-CI test races (#98) * fix(tests): start every wake-queue watcher leg from a clean cycle PR #85 made an interrupted watcher cycle resumable through state/.prelude-progress. The drain-ring idle-capture case and the ios-queue rounds stop a watcher mid-cycle and launch another against the same state, so the next watcher resumed past the stall step and exited on a recovery wake (check: rearm-resurface) instead of reading the pane. Add clear_watcher_cycle and stop_watcher_and_clear_cycle to the shared wake helpers, clearing .prelude-progress, .prelude-deferred and .watcher-down, and use them at the start, restart and stop of every stall watch leg and in the foreign-stall leg. The tick mode no longer accepts a recovery wake as proof that the stall tick ran. The drain-ring case and the ios rounds seed a progress marker of 7 and still reach the pane read. The suite also switches off the open-loop and home-summary cadence for every watcher it launches. Under the fake clock on stock macOS bash 3.2 every file looked 999999 s old, so the open-loop stale wake fired before the step under test. * fix(tests): wait on the event in the captain-hold cleanup barriers wait_for_test_file gave up after a fixed 500 polls, which a loaded host exhausts: cleanup now takes 8 to 12 s to reach the locked worktree return. Wait on the file or the process exit with one ceiling in seconds, matching the 120 s the fake treehouse barrier holds for, so the ceiling only bounds a hang. Install fm_fake_docker in the shared fixture so cleanup never reaches the host's real Docker, and assert the stand-in saw a small number of calls. * fix(bin): name the backend send that ended a spawn A failed backend send under set -e ended fm-spawn.sh with exit 1 and no text. Run the pre-launch exports, the launch command and its Enter, and treehouse get through spawn_send_or_abort, which prints one line naming the backend, the task and the failed send, then exits non-zero. Key the fake Orca of the spawn cases by subcommand instead of a global call number. Spawn starts a detached home-summary refresh that probes Orca beside its own sends, so a send could read call number 1 and get the scripted repo-show failure. Add regressions for a probe loop running through the whole spawn and for a scripted terminal-send failure. * no-mistakes(review): Trim test knobs, docker bound, and redundant test guards * no-mistakes(review): Clean Orca spawn test temp dirs after each run * no-mistakes(document): Correct spawn send-abort comment about cleanup
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
Add this suggestion to a batch that can be applied as a single commit.This suggestion is invalid because no changes were made to the code.Suggestions cannot be applied while the pull request is closed.Suggestions cannot be applied while viewing a subset of changes.Only one suggestion per line can be applied in a batch.Add this suggestion to a batch that can be applied as a single commit.Applying suggestions on deleted lines is not supported.You must change the existing code in this line in order to create a valid suggestion.Outdated suggestions cannot be applied.This suggestion has been applied or marked resolved.Suggestions cannot be applied from pending reviews.Suggestions cannot be applied on multi-line comments.Suggestions cannot be applied while the pull request is queued to merge.Suggestion cannot be applied right now. Please check back later.
Intent
I would like all bugs to be fixed so tomorrow can be focused entirely to Vernant and not problems preventning Vernant from getting built.
A recommended architecture should come with proof.
Context (the backlog record for this bug, as filed):
Watcher did not signal a scout's done event written while it was running (repo: firstmate) (kind: ship) (priority: 1) (since 2026-10-08)
Evidence 2026-10-08: fm-backlog-triage-20261008 (scout) appended 'done [at=1791490597]' (15:16:37 CDT) to state/fm-backlog-triage-20261008.status while watcher pid 15556 ran 14:49:57-15:23:41 (state/.watch-cycle-exits.log reason=actionable-check, delivered 'check: rearm-resurface'); state/.watch-deliveries.log has no signal for it, and the next drain (seq 23944) showed no wake annotation or unread status for it. Same for fm-nm-agent-pipe-buffer 'done [at=1791488399]' (14:39:59, during a Main handling turn between watchers 46565 and 15556). Main learned of both only by polling crew state ~15:30. Diagnose (diagnostic-reasoning): baseline-at-start race for events written between cycles, and/or the in-cycle classifier skipping these done lines; fix the root and add a behavioral test for both shapes. mode=no-mistakes yolo=off.
More evidence (same day): vernant-d2-custody 'needs-decision [key=main996-preservation-diagnosis] [at=1791488659]' (14:44), plus d2 key main992-gre2023-cleanup and d3 key analytics-gre1948-native-validation blocked lines, reached Main only through the open-loop ledger at ~15:38, never as signal wakes. So keyed needs-decision and blocked lines are also missed, not only done lines. Raise priority: Main is blind to lane decisions while this persists.
What Changed
bin/fm-watch.shnow scans status signals (done, keyedneeds-decision,blocked) at the start of each cycle, before the maintenance work. The maintenance work (ledger, reconcile, replies, liveness, relaunch, stall, process-event, recovery, inactive-outcome, due checks) moves into a checkpointedprelude_phase.state/.prelude-progressrecords the next step. After three signal wakes in a row put maintenance off, the next cycle runs maintenance first. Due checks and secondmate stall rows no longer exit on the first actionable result. The watcher queues each result and wakes once with the first reason.state/.watch-late-signals. The next cycle sends them as their ownsignal:wake, but only if their rows are still queued. If the marker cannot be saved, the signal wake goes out at once.wake()inbin/fm-push-transition-lib.shgets before-output and after-output hooks for this. The grace sleep is skipped while the watcher holds the wake-queue lock.docs/configuration.md,docs/architecture.md, and thefm-merge-outcome-lib.shheader now describe the new scheduling and delivery order.tests/fm-watch-triage.test.shadds regression tests for these cases: done and keyed lines written between and during cycles, a signal stuck behind a blocked check, routing of late signals, heartbeat scope, filtering of drained rows, output-failure retries, marker failure before process events, no grace sleep under the queue lock, an overdue ledger, the deferral limit, and a bad deferral marker.Risk Assessment
✅ Low: The round-1 lock fix is two small lines that match the user's instruction, the grace sleep no longer runs under the queue lock on either race shape, the new test is behavioral and fails without the fix, and the only new finding is a test-coverage shift.
Testing
I drove six live lab scenarios with the real watcher and the real Main drain. Each one ran in its own disposable FM_HOME lab. They prove the fix for the reported bug. Done lines, keyed needs-decision lines, and blocked lines now reach Main as signal wakes, whether they are written between watcher cycles or during a cycle. A process-event wake no longer holds the wake-queue lock during the signal grace. A concurrent real queue writer waited at most 627ms against a 6000ms grace, and the late signal reached Main on the next arm. The new deterministic lock test passed 10 of 10 isolated runs under heavy host load (load average 46-71). It fails on the pre-F1 code and on a half fix, so it checks both parts of F1. The 10 targeted late-signal regression tests all passed. The test-determinism scenario (T1) is a test-suite property, not a live product run, so it is recorded as untested for live validation. The run produced no UI change, so there are no screenshots. The evidence is CLI transcripts. All labs and temporary trees were removed, and the worktree is clean.
Evidence: Deterministic lock test 10/10 under load on target
Source: Deterministic lock test 10/10 under load on target
Evidence: Lock test fails on pre-F1 code
Source: Lock test fails on pre-F1 code
Evidence: Lock test fails on half fix (grace under held lock)
Source: Lock test fails on half fix (grace under held lock)
Evidence: Live: done line written between cycles reaches Main
Source: Live: done line written between cycles reaches Main
Evidence: Live: keyed needs-decision and blocked lines reach Main
Source: Live: keyed needs-decision and blocked lines reach Main
Evidence: Live: done during quiet slow check reaches Main
Source: Live: done during quiet slow check reaches Main
Evidence: Live: done during actionable slow check reaches Main with the check result
Source: Live: done during actionable slow check reaches Main with the check result
Evidence: Live: chatty fleet with loud check every round still gets signal wakes
Source: Live: chatty fleet with loud check every round still gets signal wakes
Evidence: Live: process-event wake does not block queue writers on grace; signal delivered next arm
Source: Live: process-event wake does not block queue writers on grace; signal delivered next arm
Evidence: Targeted late-signal regression tests on target
Source: Targeted late-signal regression tests on target
Evidence: Live driver script
Source: Live driver script
Pipeline
Updates from git push no-mistakes
✅ **intent** - passed
✅ No issues found.
✅ **Rebase** - passed
✅ No issues found.
bin/fm-watch.sh:2133- The new pre-output signal flush runs while procevent_surface_queued still holds FM_WAKE_QUEUE_LOCK. Sequence: a process-event row is queued, and a status line is appended between the first signal scan and prelude step 7. procevent_surface_queued takes the queue lock at :2102 and calls wake at :2133. watch_before_wake (:2943-2947) runs signal_phase_flush, so signal_phase finds the pending file and sleeps SIGNAL_GRACE (:3226, default 30s). It then runs signal classification (crew-state lookup, bounded no-mistakes call, pane capture), all with the queue lock still held. Before this change the process-event wake printed and released the lock at once. Effects: (1) a concurrent presentation drain gives up after FM_STATUS_PRESENTATION_LOCK_TIMEOUT (default 10s) with 'WAKE DRAIN SKIPPED' (bin/fm-wake-drain.sh:837-843). Under Pi this overlap is real, because the successor is armed before the predecessor's wake is delivered and drained (.pi/extensions/fm-primary-pi-watch.ts:1007-1008). (2) Acknowledgement drains (fm-wake-drain.sh:836) and every other queue writer stall for the whole grace period plus classification: fm-inbox.sh:347, fm-mail.sh:378, fm-wake-grant.sh, fm-session-launch-policy-lib.sh:53, fm-contributions.sh:331. The existing fixture (tests/fm-watch-triage.test.sh:2585-2611) checks only that the lock is released afterwards, not how long it is held. Remedy: in procevent_surface_queued, run signal_phase_flush before the lock is taken at :2102. Also skip the grace sleep when the flush runs under the held queue lock (signal_append=fm_wake_append_locked at :3215-3218), so only the small race window is scanned while locked. No other wake site in the changed code calls wake while holding the queue lock.🔧 Fix applied.
1 info still open:
tests/fm-watch-triage.test.sh:2548- The round-1 F1 fix moved this test off its target path. test_late_signal_marker_failure_before_procevent appends the done line immediately after prelude step 6 commits. The new pre-lock flush at bin/fm-watch.sh:2102 now finds that line before the queue lock is taken. The marker failure then exits through signal_phase_note_queued with FM_WAKE_POST_OUTPUT_ACTION empty. The under-lock failure branch at bin/fm-watch.sh:2933-2936 (which calls procevent_surface_after_output 1 to release the lock) no longer runs in any test. The assertion at tests/fm-watch-triage.test.sh:2595 ('signal fallback retained the process-event queue lock') now passes trivially, because the lock is never taken. The branch is still reachable: a status line can land between the pre-lock flush and the flush inside wake. Remedy: add an under-lock injection shape to this test. Use the same ln hook on .wake-queue.lock that test_procevent_wake_never_lingers_under_the_queue_lock uses at tests/fm-watch-triage.test.sh:2632-2651. Keep the existing assertions. No production code change is needed.🔧 **Test** - 1 issue found → auto-fixed ✅
tests/fm-watch-triage.test.sh:2675- test_procevent_wake_never_lingers_under_the_queue_lock is timing-flaky under heavy host load. It failed 2 of 9 isolated runs ('before-lock queue writer waited 5s on the 6s signal grace') at host load average 43-75 and passed the other 7. Six live lab repeats with lock-holder sampling showed concurrent writers acquiring the lock between the watcher's short critical sections. The watcher never held the lock continuously for the grace period. The worst writer wait was 4.4s and the typical wait was about 1s, so the cause is process-spawn latency under load, not grace-under-lock. The <3s bound with whole-second date measurement is close to that latency on a saturated runner. If CI fails it, rerun on a less loaded runner before suspecting the product. Evidence: lock-test-reruns.log, targeted-regression-tests.log, live-lockgrace-repeat.log.FM_TEST_ONLY=<name> bash tests/fm-watch-triage.test.shfor each of the 11 new regressions (test_done_and_keyed_lines_surface_between_and_during_cycles, test_signal_not_held_behind_a_blocked_check, test_flushed_signals_preserve_main_owned_routing, test_heartbeat_late_signal_retains_fleet_scope, test_late_signal_follow_up_filters_drained_rows, test_late_signal_output_failure_retries, test_late_signal_marker_failure_before_procevent, test_procevent_wake_never_lingers_under_the_queue_lock, test_signal_not_preempted_by_an_overdue_ledger, test_cycle_work_runs_after_bounded_signal_deferrals, test_invalid_prelude_deferral_marker_restores_the_previous_order)FM_TEST_ONLY=test_procevent_wake_never_lingers_under_the_queue_lock bash tests/fm-watch-triage.test.shrepeated 8 more times to diagnose flakinessLive lab driver (live-driver.sh <code> between) on the target and on agit archive 924f479cbase export: real bin/fm-watch-arm.sh plus bin/fm-wake-drain.sh against abin/fm-lab-home.sh createhomeLivelive-driver.sh <code> keyedon target and base: keyed needs-decision and blocked lines between watchersLivelive-driver.sh <code> incycle-quietandincycle-loudon target and base: done appended during a registered slow custom check (bin/fm-check-register.sh)Livelive-driver.sh <code> chattyon target and base: 6 rounds of status lines with a check that reports every roundLivelive-driver.sh <target> lockgracerun 7 times: process-event row plus a status line in the step-6/7 race window, a concurrent fm_wake_append writer measuring lock wait, and lock-holder sampling🔧 Fix applied.
✅ Re-checked - no issues remain.
FM_TEST_ONLY=test_procevent_wake_never_lingers_under_the_queue_lock bash tests/fm-watch-triage.test.shx10 on fab06b96 (load avg 46-71): 10/10 okSame test on pre-F1 product code (git archive 51774c6b + current test file) x3: 3/3 not ok (before-lock slept grace under lock)Same test on half fix (flush moved before lock, grace sleep under held lock restored): not ok (under-lock slept grace under lock)bash live-driver.sh <worktree> between(real arm + drain, disposable FM_HOME lab)bash live-driver.sh <worktree> keyedbash live-driver.sh <worktree> incycle-quietbash live-driver.sh <worktree> incycle-loudbash live-driver.sh <worktree> chattybash live-driver.sh <worktree> lockgrace(concurrent real queue writer + lock-holder sampling)FM_TEST_ONLY targeted runs: test_done_and_keyed_lines_surface_between_and_during_cycles, test_signal_not_held_behind_a_blocked_check, test_flushed_signals_preserve_main_owned_routing, test_heartbeat_late_signal_retains_fleet_scope, test_late_signal_follow_up_filters_drained_rows, test_late_signal_output_failure_retries, test_late_signal_marker_failure_before_procevent, test_signal_not_preempted_by_an_overdue_ledger, test_cycle_work_runs_after_bounded_signal_deferrals, test_invalid_prelude_deferral_marker_restores_the_previous_order✅ **Document** - passed
✅ No issues found.
🔧 **Lint** - 1 issue found → auto-fixed ✅
🔧 Fix applied.
✅ Re-checked - no issues remain.
✅ **Push** - passed
✅ No issues found.