From bf14336542a88d59a29cd6252f84c44ff374b8f5 Mon Sep 17 00:00:00 2001 From: NewAiCoder Date: Sat, 26 Sep 2026 22:22:06 -0400 Subject: [PATCH 1/2] fix(watch): stop the wedge timer once a crew's run is gone A stale pane absorbed as provably working starts a wedge timer. When the run later vanished (crew state unknown, latest status done:), the timer kept escalating 'possible wedge' every STALE_ESCALATE_SECS, and the repair path restarted it after each escalation. Re-confirm provable work where the idle-pane paths use the timer: at the threshold, a crew no longer working drops the timer and hash suppressor so the ordinary first-sight handling surfaces it once; when the timer is missing, a crew no longer working gets no new timer and the hash is marked settled. Busy-turn bound callers and genuinely working runs are unchanged. --- bin/fm-watch.sh | 42 +++++++++++++---- tests/fm-watch-triage.test.sh | 87 ++++++++++++++++++++++++++++++++++- 2 files changed, 118 insertions(+), 11 deletions(-) diff --git a/bin/fm-watch.sh b/bin/fm-watch.sh index ae34b107fd5..e5a049dfceb 100755 --- a/bin/fm-watch.sh +++ b/bin/fm-watch.sh @@ -411,7 +411,7 @@ window_label() { # The ONE derivation of a window's per-window marker key: `:`, `/` and `.` become # `_` so a window name is usable as a filename suffix. Every per-window file the -# watcher keeps is named by it (.hash-, .count-, .stale-, .stale-since-, +# watcher keeps is named by it (.hash-, .count-, .stale-, .stale-since-, .stale-settled-, # .wedge-escalations-, .paused-*, .writing-*), and live homes hold those markers on # disk under the current format, so the format lives here alone: a second copy is # how a future change to it silently orphans a window's markers instead of clearing @@ -948,11 +948,25 @@ clear_write_tracking() { # # The worktree write probe runs ONLY here, inside the at-threshold branch that is # about to escalate: at most one bounded walk per window per STALE_ESCALATE_SECS, # never per poll. -wedge_timer_check() { # - local win=$1 since_file=$2 label=$3 escalation_file=$4 task=$5 since age n reason +wedge_timer_check() { # [reverify] + local win=$1 since_file=$2 label=$3 escalation_file=$4 task=$5 reverify=${6:-} since age n reason key settled + key=$(window_key "$win") + settled="$STATE/.stale-settled-$key" + # A stale hash already found no longer provably working stays quiet: no timer, + # no crew-state read per poll (see wedge_timer_gone_quiet). + if [ -n "$reverify" ] && [ -e "$settled" ] && [ "$(cat "$settled" 2>/dev/null || true)" = "$(cat "$STATE/.stale-$key" 2>/dev/null || true)" ]; then + return 0 + fi since=$(cat "$since_file" 2>/dev/null || true) case "$since" in ''|*[!0-9]*) + if [ -n "$reverify" ] && ! crew_is_provably_working "$task"; then + # No timer to repair: the run that justified one is gone, so starting a + # fresh one would wedge-escalate a finished crew forever. + cp "$STATE/.stale-$key" "$settled" 2>/dev/null || : > "$settled" + triage_log "absorbed $label (crew no longer provably working, no wedge timer started): $win" + return 0 + fi # Publish the repaired timer only after its old write-deferral chain is # gone, so observers cannot mistake a new idle window for the old chain. clear_write_tracking "$(window_key "$win")" @@ -962,6 +976,16 @@ wedge_timer_check() { # key=$(window_key "$win") printf '%s' "$h" > "$STATE/.stale-$key" : > "$STATE/.paused-$key" - rm -f "$STATE/.stale-since-$key" "$STATE/.wedge-escalations-$key" + rm -f "$STATE/.stale-since-$key" "$STATE/.wedge-escalations-$key" "$STATE/.stale-settled-$key" clear_write_tracking "$key" statusf="$STATE/$task.status" mtime=$(stat_mtime "$statusf") @@ -1148,7 +1172,7 @@ clear_pause_state() { # clear_stale_hash_tracking() { # local key=$1 clear_write_tracking "$key" - rm -f "$STATE/.stale-$key" "$STATE/.stale-since-$key" "$STATE/.wedge-escalations-$key" + rm -f "$STATE/.stale-$key" "$STATE/.stale-since-$key" "$STATE/.wedge-escalations-$key" "$STATE/.stale-settled-$key" } clear_pause_tracking() { # @@ -2455,7 +2479,7 @@ EOF # wedge timer is running for it) - keep treating it that way # without re-reading the crew state every poll, and without # letting the still-captain-relevant log line re-surface it. - wedge_timer_check "$w" "$ssf" "stale (overridden terminal status)" "$ewf" "$task" + wedge_timer_check "$w" "$ssf" "stale (overridden terminal status)" "$ewf" "$task" reverify fi # else: already surfaced as genuinely terminal on a prior poll of # this same hash - nothing left to do (matches the original, @@ -2507,7 +2531,7 @@ EOF *) handle_paused_stale "$w" "$task" "$h" ;; esac else - wedge_timer_check "$w" "$ssf" "non-terminal stale" "$ewf" "$task" + wedge_timer_check "$w" "$ssf" "non-terminal stale" "$ewf" "$task" reverify fi fi fi @@ -2520,7 +2544,7 @@ EOF if [ "$busy_now" -eq 0 ] && busy_turn_over_age "$task"; then busy_turn_bound_check "$w" "$task" "$h" "$ssf" "$ewf" && paused_bound=0 else - rm -f "$ssf" "$ewf" + rm -f "$ssf" "$ewf" "$STATE/.stale-settled-$key" clear_write_tracking "$key" fi # A busy pane normally means real work resumed, so stale pause bookkeeping @@ -2538,7 +2562,7 @@ EOF if [ "$busy_now" -eq 0 ] && busy_turn_over_age "$task"; then busy_turn_bound_check "$w" "$task" "$h" "$ssf" "$ewf" && paused_bound=0 else - rm -f "$ssf" "$ewf" + rm -f "$ssf" "$ewf" "$STATE/.stale-settled-$key" clear_write_tracking "$key" fi task=$(window_to_task "$w" "$STATE") diff --git a/tests/fm-watch-triage.test.sh b/tests/fm-watch-triage.test.sh index bfdc5a2e927..8587e38ecc0 100755 --- a/tests/fm-watch-triage.test.sh +++ b/tests/fm-watch-triage.test.sh @@ -2067,6 +2067,75 @@ test_nonterminal_stale_provably_working_absorbed_then_escalated() { pass "provably-working non-terminal stale is absorbed on first sight, then wedge-escalated past the threshold" } +# --- a finished crew whose run is gone: the wedge timer stops, never repeats --- +# The live 2026-09 case: a crew reported done and only waits on an outside merge. +# While its run monitored CI the pane was provably working, which started the +# wedge timer; once the run vanished (fm-crew-state reads unknown) that timer kept +# escalating "possible wedge" every STALE_ESCALATE_SECS forever. Both status shapes +# reach the timer through a different branch, so each is driven through the same +# three phases: working absorb (timer starts), run gone at the threshold (no wedge +# wake, at most the ordinary surface), then the same hash stays quiet. +run_working_then_gone_case() { # + local name=$1 task=$2 status_line=$3 dir state fakebin out capture_file window key pane_hash sig pid + dir=$(make_case "$name"); state="$dir/state"; fakebin="$dir/fakebin" + out="$dir/watch.out"; capture_file="$dir/pane.txt" + window="test:fm-$task" + printf 'idle after monitoring ci' > "$capture_file" + printf 'window=%s\nkind=ship\n' "$window" > "$state/$task.meta" + printf '%s\n' "$status_line" > "$state/$task.status" + sig=$(seen_sig "$state/$task.status"); printf '%s' "$sig" > "$state/.seen-${task}_status" + key=$(printf '%s' "$window" | tr ':/.' '___') + pane_hash=$(hash_text "idle after monitoring ci") + printf '%s' "$pane_hash" > "$state/.hash-$key" + printf '1\n' > "$state/.count-$key" + + # Phase A: the run is monitoring CI, so the static pane is absorbed and timed. + export FM_FAKE_CREW_STATE='state: working · source: run-step · ci running' + watch_bg "$state" "$fakebin" "$out" FM_FAKE_TMUX_WINDOW="$window" FM_FAKE_TMUX_CAPTURE="$capture_file" FM_STALE_ESCALATE_SECS=240 + pid=$! + wait_poll_cycle "$state" "$pid" || { reap "$pid"; fail "$name: watcher exited while absorbing a working run: $(cat "$out")"; } + [ -s "$state/.stale-since-$key" ] || { reap "$pid"; fail "$name: the working absorb did not start the wedge timer"; } + reap "$pid" + ack_stopped_cycle "$state" || fail "$name: could not acknowledge the phase-A stop" + + # Phase B: the run is gone (unknown) and the timer is past the threshold. The + # old code escalated "possible wedge" here. + export FM_FAKE_CREW_STATE='state: unknown · source: none' + echo $(( $(date +%s) - 500 )) > "$state/.stale-since-$key" + : > "$out" + watch_bg "$state" "$fakebin" "$out" FM_FAKE_TMUX_WINDOW="$window" FM_FAKE_TMUX_CAPTURE="$capture_file" FM_STALE_ESCALATE_SECS=240 + pid=$! + # The ordinary one-time surface ends this watcher; a wedge wake would too. + wait_for_exit "$pid" 100 || { reap "$pid"; fail "$name: a crew whose run is gone was never surfaced through the ordinary path"; } + grep -F "stale: $window" "$out" >/dev/null || fail "$name: the ordinary surface did not print a stale wake: $(cat "$out")" + grep -F "possible wedge" "$out" "$state/.wake-queue" >/dev/null 2>&1 \ + && fail "$name: a crew whose run is gone was wedge-escalated: $(cat "$out" "$state/.wake-queue" 2>/dev/null)" + [ ! -e "$state/.stale-since-$key" ] || fail "$name: the wedge timer survived the run going away" + [ ! -e "$state/.wedge-escalations-$key" ] || fail "$name: a wedge-escalation count was recorded for a finished crew" + ack_stopped_cycle "$state" || fail "$name: could not acknowledge the phase-B surface" + + # Phase C: the same hash later stays quiet - no timer, no wake, however long. + : > "$out"; rm -f "$state/.wake-queue" + watch_bg "$state" "$fakebin" "$out" FM_FAKE_TMUX_WINDOW="$window" FM_FAKE_TMUX_CAPTURE="$capture_file" FM_STALE_ESCALATE_SECS=1 + pid=$! + sleep 4 + kill -0 "$pid" 2>/dev/null || { wait "$pid" 2>/dev/null || true; fail "$name: the finished crew woke firstmate again: $(cat "$out" "$state/.wake-queue" 2>/dev/null)"; } + [ ! -e "$state/.stale-since-$key" ] || { reap "$pid"; fail "$name: a finished crew restarted the wedge timer"; } + [ ! -s "$state/.wake-queue" ] || { reap "$pid"; fail "$name: a finished crew re-enqueued a wake: $(cat "$state/.wake-queue")"; } + reap "$pid" + unset FM_FAKE_CREW_STATE +} + +test_terminal_done_crew_whose_run_is_gone_stops_wedge_escalating() { + run_working_then_gone_case done-run-gone donegone 'done: PR https://example.invalid/pr/1 checks green' + pass "a done: crew whose run is gone stops wedge-escalating after the ordinary surface" +} + +test_nonterminal_crew_whose_run_is_gone_stops_wedge_escalating() { + run_working_then_gone_case quiet-run-gone quietgone 'working: waiting on the outside merge' + pass "a quiet crew whose run is gone stops wedge-escalating and never restarts the timer" +} + # --- non-terminal stale, crew NOT provably working: surfaced immediately ------ # The key requirement: a crew with no running pipeline that has gone quiet (and is # not busy) has stopped - it may be done via interactive menus, waiting, or wedged. @@ -3876,9 +3945,11 @@ test_nonterminal_stale_repairs_missing_or_corrupt_timer() { printf '%s' "$pane_hash" > "$state/.hash-$key" printf '1\n' > "$state/.count-$key" printf '%s' "$pane_hash" > "$state/.stale-$key" + # The timer is only repaired for a crew that is still provably working. + export FM_FAKE_CREW_STATE='state: working · source: run-step · ci running' PATH="$fakebin:$PATH" FM_FAKE_TMUX_WINDOW="$window" FM_FAKE_TMUX_CAPTURE="$capture_file" \ - FM_STATE_OVERRIDE="$state" FM_STALE_ESCALATE_SECS=999 FM_POLL=1 FM_SIGNAL_GRACE=1 \ + FM_STATE_OVERRIDE="$state" FM_CREW_STATE_BIN="$fakebin/fm-crew-state.sh" FM_STALE_ESCALATE_SECS=999 FM_POLL=1 FM_SIGNAL_GRACE=1 \ FM_CHECK_INTERVAL=999999 FM_HEARTBEAT=999999 "$WATCH" > "$out" & pid=$! wait_numeric_file "$state/.stale-since-$key" 30 || { reap "$pid"; fail "matching stale suppressor with missing timer did not initialize stale-since"; } @@ -3893,7 +3964,7 @@ test_nonterminal_stale_repairs_missing_or_corrupt_timer() { printf 'corrupt\n' > "$state/.stale-since-$key" : > "$out" PATH="$fakebin:$PATH" FM_FAKE_TMUX_WINDOW="$window" FM_FAKE_TMUX_CAPTURE="$capture_file" \ - FM_STATE_OVERRIDE="$state" FM_STALE_ESCALATE_SECS=999 FM_POLL=1 FM_SIGNAL_GRACE=1 \ + FM_STATE_OVERRIDE="$state" FM_CREW_STATE_BIN="$fakebin/fm-crew-state.sh" FM_STALE_ESCALATE_SECS=999 FM_POLL=1 FM_SIGNAL_GRACE=1 \ FM_CHECK_INTERVAL=999999 FM_HEARTBEAT=999999 "$WATCH" > "$out" & pid=$! wait_numeric_file "$state/.stale-since-$key" 30 || { reap "$pid"; fail "matching stale suppressor with corrupt timer did not repair stale-since"; } @@ -3901,6 +3972,7 @@ test_nonterminal_stale_repairs_missing_or_corrupt_timer() { [ "$since" != "corrupt" ] || { reap "$pid"; fail "corrupt stale-since value was left in place"; } [ ! -s "$state/.wake-queue" ] || { reap "$pid"; fail "corrupt stale-since repair enqueued a wake"; } reap "$pid" + unset FM_FAKE_CREW_STATE pass "matching non-terminal stale suppressors repair missing or corrupt stale-since timers" } @@ -3920,6 +3992,8 @@ test_nonterminal_stale_repairs_missing_or_corrupt_timer() { test_wedge_escalation_deferred_while_worktree_is_written() { local dir state fakebin out drain_out capture_file window key pane_hash sig pid wt back dir=$(make_case wedge-worktree-writes); state="$dir/state"; fakebin="$dir/fakebin" + # The at-threshold wedge branch re-confirms the crew is still provably working. + export FM_FAKE_CREW_STATE='state: working · source: run-step · ci running' out="$dir/watch.out"; drain_out="$dir/drain.out"; capture_file="$dir/pane.txt" window="test:fm-writing"; wt="$dir/wt" mkdir -p "$wt/src" @@ -3978,6 +4052,7 @@ test_wedge_escalation_deferred_while_worktree_is_written() { [ ! -e "$state/.writing-since-$key" ] || fail "the write-deferral chain outlived a real escalation" FM_STATE_OVERRIDE="$state" "$DRAIN" > "$drain_out" 2>/dev/null || fail "drain after the stalled-crew escalation failed" grep "$(printf '\tstale\t')" "$drain_out" | grep -F "$window" >/dev/null || fail "the stalled-crew escalation was not queued" + unset FM_FAKE_CREW_STATE pass "a quiet pane writing its own worktree is deferred, while one writing nothing still wedge-escalates on the unchanged schedule" } @@ -3988,6 +4063,8 @@ test_wedge_escalation_deferred_while_worktree_is_written() { test_write_deferral_resurfaces_on_the_bounded_cadence() { local dir state fakebin out drain_out capture_file window key pane_hash sig pid wt back dir=$(make_case wedge-worktree-resurface); state="$dir/state"; fakebin="$dir/fakebin" + # The at-threshold wedge branch re-confirms the crew is still provably working. + export FM_FAKE_CREW_STATE='state: working · source: run-step · ci running' out="$dir/watch.out"; drain_out="$dir/drain.out"; capture_file="$dir/pane.txt" window="test:fm-churn"; wt="$dir/wt" mkdir -p "$wt/src" @@ -4021,6 +4098,7 @@ test_write_deferral_resurfaces_on_the_bounded_cadence() { [ ! -e "$state/.wedge-escalations-$key" ] || fail "a write-deferral recheck advanced the wedge escalation counter" FM_STATE_OVERRIDE="$state" "$DRAIN" > "$drain_out" 2>/dev/null || fail "drain after the write-deferral recheck failed" grep "$(printf '\tstale\t')" "$drain_out" | grep -F "$window" >/dev/null || fail "the write-deferral recheck was not queued" + unset FM_FAKE_CREW_STATE pass "a write deferral re-surfaces once on the bounded pause cadence, so a churning worktree cannot stay invisible" } @@ -4083,6 +4161,8 @@ test_secondmate_home_supervision_churn_is_not_write_evidence() { test_timer_repair_drops_a_finished_write_deferral_chain() { local dir state fakebin out capture_file window key pane_hash sig pid wt back dir=$(make_case wedge-write-chain-timer-repair); state="$dir/state"; fakebin="$dir/fakebin" + # The at-threshold wedge branch re-confirms the crew is still provably working. + export FM_FAKE_CREW_STATE='state: working · source: run-step · ci running' out="$dir/watch.out"; capture_file="$dir/pane.txt" window="test:fm-chain-repair"; wt="$dir/wt" mkdir -p "$wt/src" @@ -4143,6 +4223,7 @@ test_timer_repair_drops_a_finished_write_deferral_chain() { [ ! -e "$state/.writing-resurfaced-$key" ] \ || { reap "$pid"; fail "a fresh write deferral spent its bounded re-surface on the first poll"; } reap "$pid" + unset FM_FAKE_CREW_STATE pass "an idle-window timer repair drops a finished write-deferral chain, so the next deferral gets a fresh re-surface window" } @@ -5170,6 +5251,8 @@ test_permission_recovery_surfaces_preserved_status test_terminal_stale_surfaced test_stale_terminal_status_overridden_by_active_run test_nonterminal_stale_provably_working_absorbed_then_escalated +test_terminal_done_crew_whose_run_is_gone_stops_wedge_escalating +test_nonterminal_crew_whose_run_is_gone_stops_wedge_escalating test_wedge_escalation_marks_demand_deep_inspection_after_threshold test_wedge_escalation_resets_when_pane_becomes_active test_busy_pane_below_turn_age_bound_is_absorbed From a89bcc007706d6e7d022fd82ccd16da6b01448c5 Mon Sep 17 00:00:00 2001 From: NewAiCoder Date: Sat, 26 Sep 2026 22:28:39 -0400 Subject: [PATCH 2/2] no-mistakes(document): Document watcher wedge-timer re-verification --- docs/architecture.md | 1 + 1 file changed, 1 insertion(+) diff --git a/docs/architecture.md b/docs/architecture.md index 94f85c70bea..9a7b97ab5aa 100644 --- a/docs/architecture.md +++ b/docs/architecture.md @@ -57,6 +57,7 @@ A secondmate's endpoint liveness is still never read at all; a mate is admitted A `paused:` line specifically claiming a no-mistakes run is the one declared wait not taken on faith for that whole cadence: both the watcher and the away-mode daemon revalidate it against crew state, and an unconfirmed claim (no run, failed, or parked at a gate) is escalated on the stale cadence instead of re-absorbed (`status_pause_claims_nm_run` in [`bin/fm-classify-lib.sh`](../bin/fm-classify-lib.sh); [configuration.md](configuration.md) "Pipeline-state watch" owns the mechanics). Its initial normal-mode status signal still surfaces through the no-verb path, while a daemon-backed away posture self-handles that routine signal and owns later external-wait rechecks. Fresh stale panes use the same current-state read before trusting the status log, so an active run or a proven busy worker outranks an old captain-relevant status-log line left behind before validation. +The same read gates the wedge timer of a stale pane: when the run that justified the timer is gone, the timer is dropped rather than escalated, and a finished crew (latest status `done:`, crew state unknown) surfaces at most once through the ordinary stale path and then stays quiet, while a crew that is still provably working and frozen escalates as before (`wedge_timer_check` in [`bin/fm-watch.sh`](../bin/fm-watch.sh); pinned in `tests/fm-watch-triage.test.sh`). No-change heartbeats are also benign. Separately from heartbeat backoff and wedge handling, the watcher poll runs `bin/fm-inactive-reconcile.sh` on its own bounded cadence, while locked session start sends the same bounded local scan through `bin/fm-startup-network.sh`'s deferred worker so current-state reads never block the digest. In each home the scan considers only that home's long-inactive direct ordinary crewmates, excludes captain-held work, and accepts only `done` or `failed` from `bin/fm-crew-state.sh`.