Skip to content

fix(watcher): surface stopped stales once per situation, not per poll or hash tick#735

Open
anxsec wants to merge 8 commits into
kunchenguid:mainfrom
anxsec:fm/watch-pause-done-fix
Open

fix(watcher): surface stopped stales once per situation, not per poll or hash tick#735
anxsec wants to merge 8 commits into
kunchenguid:mainfrom
anxsec:fm/watch-pause-done-fix

Conversation

@anxsec

@anxsec anxsec commented Jul 19, 2026

Copy link
Copy Markdown

Intent

Fix firstmate watcher defect: a finished ship task awaiting PR merge (crew state done) was re-surfaced as stale on every poll and every pane-hash tick; make it surface once per distinct terminal situation while preserving the absorb-only-when-provably-working, paused-recheck, and herdr false-surface contracts, with a reproducing test in tests/

What Changed

  • The watcher now dedups stopped-crew stale wakes on the situation (the task's last status line) instead of the pane hash, so a finished crew awaiting PR merge with a ticking status bar surfaces once rather than on every poll and hash tick; a superseded paused: log line is cached against the status file's signature so it isn't re-read and re-surfaced each poll, and surfacing re-arms only on positive working evidence (busy or streaming pane, active run) or a new status line. Already-surfaced stopped stales are also no longer re-nagged by the wedge timer, and a dead 0x1f hex-send path was removed.
  • crew_absorb_class in bin/fm-classify-lib.sh gained a distinct unreadable verdict for a failed crew-state read, which still surfaces conservatively but is never cached as a negative verdict — so a transient misread cannot disarm a genuine pause's recheck cadence.
  • The herdr bare-prompt regex was rewritten as an anchored alternation (bracket classes misread UTF-8 box-corner bytes under C locales), tests/fm-watch-triage.test.sh gained six regression tests for the once-per-situation behavior plus tmux 3.7 marker/locale fixes, the shellcheck cleanliness test now skips when shellcheck is absent, and the architecture/configuration docs were synced to the new stale-surfacing cadence.

Risk Assessment

✅ Low: The change is confined to the watcher's stale-triage state machine, the captain-directed fix for the failed-read caching hazard is correctly implemented with a dedicated regression test, six new tests reproduce the original per-poll re-surfacing incident and the re-arm contracts, and the remaining round-1 concerns were explicitly adjudicated by the user.

Testing

Ran the watcher-triage suite (40/40 pass, including the six new regression tests) plus the other touched test files on top of the green baseline sweep, then reproduced the original merge-wait incident with a scripted supervisor re-arm loop: the base-commit watcher woke the supervisor on all 7 rounds while the fixed watcher woke it exactly twice — once for the first terminal situation and once for a genuinely new status line — absorbing the five idle status-bar hash ticks in between. No UI surface is involved (bash watcher daemon), so evidence is CLI transcripts.

Evidence: Before: base-commit watcher re-surfaces the finished merge-wait crew on every status-bar tick (7 wakes / 7 rounds)

=== BEFORE (base b2bf95f) === tick 11:52 (status-bar minute) WOKE SUPERVISOR: stale: demo:fm-merge-wait tick 11:53 (status-bar minute) WOKE SUPERVISOR: stale: demo:fm-merge-wait tick 11:54 (status-bar minute) WOKE SUPERVISOR: stale: demo:fm-merge-wait tick 11:55 (status-bar minute) WOKE SUPERVISOR: stale: demo:fm-merge-wait tick 11:56 (status-bar minute) WOKE SUPERVISOR: stale: demo:fm-merge-wait tick 11:57 (status-bar minute) WOKE SUPERVISOR: stale: demo:fm-merge-wait tick 11:58 + NEW status (failed:) WOKE SUPERVISOR: stale: demo:fm-merge-wait result: 7 supervisor wake(s)

=== BEFORE (base b2bf95f) ===
Task merge-wait: done: PR https://github.com/acme/gadget/pull/42 checks green (awaiting captain merge)
Idle agent pane; status-bar clock ticks once per round. Supervisor re-arms watcher after every wake.

  tick 11:52 (status-bar minute)     WOKE SUPERVISOR: stale: demo:fm-merge-wait
  tick 11:53 (status-bar minute)     WOKE SUPERVISOR: stale: demo:fm-merge-wait
  tick 11:54 (status-bar minute)     WOKE SUPERVISOR: stale: demo:fm-merge-wait
  tick 11:55 (status-bar minute)     WOKE SUPERVISOR: stale: demo:fm-merge-wait
  tick 11:56 (status-bar minute)     WOKE SUPERVISOR: stale: demo:fm-merge-wait
  tick 11:57 (status-bar minute)     WOKE SUPERVISOR: stale: demo:fm-merge-wait
  tick 11:58 + NEW status (failed:)  WOKE SUPERVISOR: stale: demo:fm-merge-wait

BEFORE (base b2bf95f) result: 7 supervisor wake(s) across 6 idle status-bar ticks + 1 genuinely new situation
Evidence: After: fixed watcher surfaces once per situation, absorbs hash ticks, re-surfaces on a new status line (2 wakes / 7 rounds)

=== AFTER (fm/watch-pause-done-fix) === tick 11:52 (status-bar minute) WOKE SUPERVISOR: stale: demo:fm-merge-wait tick 11:53 (status-bar minute) watcher stayed quiet (absorbed) tick 11:54 (status-bar minute) watcher stayed quiet (absorbed) tick 11:55 (status-bar minute) watcher stayed quiet (absorbed) tick 11:56 (status-bar minute) watcher stayed quiet (absorbed) tick 11:57 (status-bar minute) watcher stayed quiet (absorbed) tick 11:58 + NEW status (failed:) WOKE SUPERVISOR: stale: demo:fm-merge-wait result: 2 supervisor wake(s) triage log: absorbed stale (terminal situation already surfaced): demo:fm-merge-wait (x5)

=== AFTER (fm/watch-pause-done-fix) ===
Task merge-wait: done: PR https://github.com/acme/gadget/pull/42 checks green (awaiting captain merge)
Idle agent pane; status-bar clock ticks once per round. Supervisor re-arms watcher after every wake.

  tick 11:52 (status-bar minute)     WOKE SUPERVISOR: stale: demo:fm-merge-wait
  tick 11:53 (status-bar minute)     watcher stayed quiet (absorbed)
  tick 11:54 (status-bar minute)     watcher stayed quiet (absorbed)
  tick 11:55 (status-bar minute)     watcher stayed quiet (absorbed)
  tick 11:56 (status-bar minute)     watcher stayed quiet (absorbed)
  tick 11:57 (status-bar minute)     watcher stayed quiet (absorbed)
  tick 11:58 + NEW status (failed:)  WOKE SUPERVISOR: stale: demo:fm-merge-wait

AFTER (fm/watch-pause-done-fix) result: 2 supervisor wake(s) across 6 idle status-bar ticks + 1 genuinely new situation

watcher triage log (AFTER (fm/watch-pause-done-fix)):
  [2026-07-19T18:45:44+0800] absorbed stale (terminal situation already surfaced): demo:fm-merge-wait
  [2026-07-19T18:46:04+0800] absorbed stale (terminal situation already surfaced): demo:fm-merge-wait
  [2026-07-19T18:46:27+0800] absorbed stale (terminal situation already surfaced): demo:fm-merge-wait
  [2026-07-19T18:46:53+0800] absorbed stale (terminal situation already surfaced): demo:fm-merge-wait
  [2026-07-19T18:47:16+0800] absorbed stale (terminal situation already surfaced): demo:fm-merge-wait
Evidence: Reproduction script simulating the 2026-07-11 merge-wait incident (runnable against any fm-watch.sh)
#!/usr/bin/env bash
# End-to-end demo of the merge-wait stale-resurfacing fix (fm/watch-pause-done-fix).
#
# Scenario (mirrors the 2026-07-11 fix-sync-ssh-m4 incident): a ship task's run
# finished — "done: PR ... checks green", authoritative crew state
# "done · run-step" — and the crew's live idle agent sits at its composer while
# its status-bar clock ticks, changing the pane hash every minute. The
# supervisor re-arms the watcher after handling each wake. Pre-fix the watcher
# woke the supervisor with "stale:" on every tick; post-fix it surfaces the
# terminal situation once, absorbs identical ticks, and re-surfaces only on a
# genuinely new status line.
#
# Usage: merge-wait-demo.sh <path-to-fm-watch.sh> <label>
set -u
WATCH=$1
LABEL=$2

DEMO=$(mktemp -d "${TMPDIR:-/tmp}/fm-merge-wait-demo.XXXXXX")
trap 'rm -rf "$DEMO"' EXIT
STATE="$DEMO/state"; FAKEBIN="$DEMO/fakebin"; PANE="$DEMO/pane.txt"
mkdir -p "$STATE" "$FAKEBIN"

# Fake tmux: one window, pane content read from $PANE (same shim the test suite uses).
cat > "$FAKEBIN/tmux" <<'SH'
#!/usr/bin/env bash
set -u
if [ "${1:-}" = "list-windows" ]; then
  [ -n "${FM_FAKE_TMUX_WINDOW:-}" ] && printf '%s\n' "$FM_FAKE_TMUX_WINDOW"
  exit 0
fi
if [ "${1:-}" = "capture-pane" ]; then
  [ -n "${FM_FAKE_TMUX_CAPTURE:-}" ] && cat "$FM_FAKE_TMUX_CAPTURE"
  exit 0
fi
exit 1
SH
chmod +x "$FAKEBIN/tmux"

# Fake fm-crew-state.sh: authoritative current state is done via run-step
# (finished, PR open, awaiting the captain's merge) — NOT provably working.
cat > "$FAKEBIN/fm-crew-state.sh" <<'SH'
#!/usr/bin/env bash
printf 'state: done · source: run-step · checks green, awaiting merge\n'
SH
chmod +x "$FAKEBIN/fm-crew-state.sh"

WINDOW="demo:fm-merge-wait"
printf 'window=%s\nkind=ship\n' "$WINDOW" > "$STATE/merge-wait.meta"
printf 'done: PR https://github.com/acme/gadget/pull/42 checks green\n' > "$STATE/merge-wait.status"
# The done: status was already surfaced to the supervisor (seen marker matches),
# exactly the incident's standing state.
if [ "$(uname)" = Darwin ]; then sig=$(stat -f '%z:%Fm' "$STATE/merge-wait.status"); else sig=$(stat -c '%s:%Y' "$STATE/merge-wait.status"); fi
printf '%s' "$sig" > "$STATE/.seen-merge-wait_status"

wakes=0
arm_and_watch() {  # <round-label>
  local out="$DEMO/watch.out" pid i
  : > "$out"
  PATH="$FAKEBIN:$PATH" FM_FAKE_TMUX_WINDOW="$WINDOW" FM_FAKE_TMUX_CAPTURE="$PANE" \
    FM_STATE_OVERRIDE="$STATE" FM_ROOT_OVERRIDE="$DEMO" FM_CREW_STATE_BIN="$FAKEBIN/fm-crew-state.sh" \
    FM_POLL=1 FM_SIGNAL_GRACE=1 FM_STALE_ESCALATE_SECS=999 FM_CHECK_INTERVAL=999999 FM_HEARTBEAT=999999 \
    "$WATCH" > "$out" 2>"$DEMO/watch.err" &
  pid=$!
  i=0
  while [ "$i" -lt 100 ]; do
    kill -0 "$pid" 2>/dev/null || break
    sleep 0.1; i=$((i + 1))
  done
  if kill -0 "$pid" 2>/dev/null; then
    printf '  %-34s watcher stayed quiet (absorbed)\n' "$1"
    kill "$pid" 2>/dev/null; wait "$pid" 2>/dev/null
  else
    wait "$pid" 2>/dev/null
    wakes=$((wakes + 1))
    printf '  %-34s WOKE SUPERVISOR: %s\n' "$1" "$(cat "$out")"
  fi
}

printf '=== %s ===\n' "$LABEL"
printf 'Task merge-wait: done: PR https://github.com/acme/gadget/pull/42 checks green (awaiting captain merge)\n'
printf 'Idle agent pane; status-bar clock ticks once per round. Supervisor re-arms watcher after every wake.\n\n'
for m in 52 53 54 55 56 57; do
  printf '│ ❯ composer idle                │ 11:%s │' "$m" > "$PANE"
  arm_and_watch "tick 11:$m (status-bar minute)"
done
printf 'failed: merge conflict while rebasing\n' >> "$STATE/merge-wait.status"
if [ "$(uname)" = Darwin ]; then sig=$(stat -f '%z:%Fm' "$STATE/merge-wait.status"); else sig=$(stat -c '%s:%Y' "$STATE/merge-wait.status"); fi
printf '%s' "$sig" > "$STATE/.seen-merge-wait_status"
printf '│ ❯ composer idle                │ 11:58 │' > "$PANE"
arm_and_watch "tick 11:58 + NEW status (failed:)"

printf '\n%s result: %d supervisor wake(s) across 6 idle status-bar ticks + 1 genuinely new situation\n' "$LABEL" "$wakes"
if [ -s "$STATE/.watch-triage.log" ]; then
  printf '\nwatcher triage log (%s):\n' "$LABEL"
  sed 's/^/  /' "$STATE/.watch-triage.log"
fi

Pipeline

Updates from git push no-mistakes

✅ **intent** - passed

✅ No issues found.

✅ **Rebase** - passed

✅ No issues found.

⚠️ **Review** - 1 info
  • ⚠️ bin/fm-watch.sh:415 - The new durable markers state/.stale-surfaced-<key> and state/.paused-none-<key> are window-keyed and never removed at teardown (bin/fm-teardown.sh:1139 removes only $ID.* files) or at spawn. Unlike the old pane-hash suppressors, the situation record is keyed on the last status line, which is likely to repeat across tasks (e.g. 'working: implementing'), so a later task reusing the same id/window can have its first stopped stale silently absorbed by the previous task's leftover record - violating the documented 'first stop of any situation always surfaces' guarantee on the stale path (the turn-end signal path remains as backstop). Clear both markers for the task's window during teardown and/or spawn.
  • ⚠️ bin/fm-watch.sh:1018 - crew_absorb_class returns 'none' when the fm-crew-state read transiently fails, and the paused re-entry branch now caches that verdict in .paused-none-<key> against the status-file signature. For a genuinely paused crew on a fully static pane, one transient read failure permanently disables the FM_PAUSE_RESURFACE_SECS recheck cadence (pf and .paused-rechecked are removed by surface_nonterminal_stale, sitf suppresses further surfacing, and heartbeat ignores paused: lines), so the declared external wait can rot invisibly until the crew writes a new status line or the pane changes. Pre-fix the misread self-corrected on the next poll. Consider distinguishing a read failure from an authoritative 'none' verdict before writing the negative cache.
  • ℹ️ bin/fm-watch.sh:939 - The terminal-stale branch reimplements the situation-record compare/absorb/record pattern inline (compare at line 939, record at line 950, clear at 935) that surface_nonterminal_stale owns for the 'stopped|' prefix. A small shared helper taking the prefix and the per-branch surface actions would keep the two situation-key formats and their clear/record semantics from drifting apart.
  • ℹ️ bin/fm-watch.sh:913 - The afk-mode stale branch still dedups once per pane hash, so a finished merge-wait crew with a ticking status bar continues to enqueue one stale record per hash tick for the away-mode daemon. The daemon batches digests so cost is bounded, and this path is untouched by the change; noting it as a known boundary of the once-per-situation fix.

🔧 Fix: never cache a failed crew-state read as superseded-pause verdict
1 info still open:

  • ℹ️ bin/fm-watch.sh:1055 - On the new-hash paused path, an unreadable crew-state read still falls through *) to clear_pause_tracking, momentarily dropping pause tracking on a transient misread. Unlike the fixed repeat-hash branch, nothing negative is cached: the next stable-stale classification re-reads the crew state and handle_paused_stale re-arms the pause, so the behavior is self-correcting and identical to the pre-change none handling. Noted only as a boundary of the no-cache fix.
✅ **Test** - passed

✅ No issues found.

  • command -v tmux >/dev/null || { echo "tmux is required for e2e tests" >&2; exit 1; }; tmux -V; rc=0; for t in tests/*.test.sh; do echo "== $t =="; bash "$t" || rc=1; done; exit "$rc"
  • bash tests/fm-watch-triage.test.sh — all 40 tests pass, including the 6 new regression tests (terminal stale not resurfaced per hash tick, superseded-pause done crew not resurfaced per poll, transient crew-state misread not cached, surfaced stopped stale not wedge-nagged, busy and streaming panes re-arm surfacing)
  • bash tests/fm-bootstrap.test.sh and bash tests/fm-cd-pretool-check.test.sh — touched test files pass
  • Baseline configured command (full tests/*.test.sh sweep under tmux 3.7) already ran green
  • Manual incident reproduction: merge-wait-demo.sh simulates a done-awaiting-merge crew with a ticking status-bar pane and supervisor re-arm loop, run against the base-commit watcher (7 wakes in 7 rounds — bug reproduced) and the fixed watcher (2 wakes: first surface + new failed: status line; 5 ticks absorbed with triage-log confirmation)
✅ **Document** - passed

✅ No issues found.

✅ **Lint** - passed

✅ No issues found.

✅ **Push** - passed

✅ No issues found.

anxsec added 8 commits July 19, 2026 11:47
… or hash tick

A finished ship task awaiting PR merge (crew state done via run-step) was
re-surfaced as stale: on effectively every poll: the hash-keyed .stale-*
suppressor never held against a live idle agent's ticking status bar, and a
paused: log line superseded by run-step precedence re-entered classification
and surfacing on every poll through the status_is_paused re-entry branch.

- record each SURFACED stale's situation (branch + last status line) in
  .stale-surfaced-<key>; an identical situation is absorbed across polls,
  pane-hash ticks, and watcher restarts
- clear that record only on positive working evidence (busy pane, active
  run), so a crew that resumes and stops again, or writes a new status
  line, still surfaces; the first stop of any situation always surfaces
- cache a superseded paused: verdict against the status file's signature
  (.paused-none-<key>) so the costly crew-state read and the re-surface no
  longer repeat every poll
- keep wedge timing reserved for provably-working absorbs; an
  already-surfaced stopped stale is no longer re-nagged as a possible wedge

Evidence: 2026-07-11 fix-sync-ssh-m4 merge-wait incident (wake records 31-38
in ~7 minutes); reproduced by four new fm-watch-triage tests that fail
against the pre-fix watcher.
@kunchenguid

kunchenguid commented Jul 19, 2026

Copy link
Copy Markdown
Owner

Automated reminder: thanks for the PR! This branch currently has a merge conflict with the base branch.

When you get a chance, please rebase onto (or merge) the latest base branch, resolve the conflict, and push. After that, checks will re-run and the PR will get looked at again.

Noted for firstmate#735 at 6324ca46.

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

Labels

Projects

None yet

Development

Successfully merging this pull request may close these issues.

2 participants