diff --git a/.github/workflows/ci.yml b/.github/workflows/ci.yml index d89c5723935..c466c461ab0 100644 --- a/.github/workflows/ci.yml +++ b/.github/workflows/ci.yml @@ -390,6 +390,18 @@ jobs: exit 1 } + # The wake lock's reclaim rests on naming the running frame, and this + # is the only shell here with no BASHPID to name it with, so the + # portable Linux lanes cannot exercise that half of the contract. + lock_output=$(FM_TEST_ONLY=test_self_held_lock_reclaims_instead_of_deadlocking \ + /bin/bash tests/fm-wake-queue.test.sh) + printf '%s\n' "$lock_output" + lock_count=$(printf '%s\n' "$lock_output" | grep -c '^ok - ') + [ "$lock_count" -eq 1 ] || { + echo "::error::expected 1 wake-lock frame-identity regression, got $lock_count" + exit 1 + } + command -v npm >/dev/null || { echo "::error::npm is required to install tasks-axi"; exit 1; } npm install -g tasks-axi@0.2.5 >/dev/null PATH="$(npm prefix -g)/bin:$PATH" diff --git a/bin/fm-wake-lib.sh b/bin/fm-wake-lib.sh index e7b530d63ac..3bb3846c99e 100755 --- a/bin/fm-wake-lib.sh +++ b/bin/fm-wake-lib.sh @@ -36,6 +36,29 @@ fm_pid_alive() { kill -0 "$pid" 2>/dev/null } +# fm_pid_is_this_frame +# True when a pid recorded in a lock names the exact frame asking. Lock reclaim +# turns on this and nothing else, and the case it has to get right is a subshell +# looking at a lock its parent still holds: the parent is alive, so reading that +# lock as "mine, abandoned" would hand the subshell a live hold. +# +# BASHPID names the frame directly and must be read inline - a command +# substitution would answer for its own subshell, and $(this function) would +# too, so CALL it. Stock macOS bash 3.2 has no BASHPID at all, and its $$ is the +# same value in every subshell, so there $$ names a frame only where there is no +# subshell to confuse it with: the main shell, the one place BASH_SUBSHELL is 0. +# Deeper frames on that shell get no reclaim and keep waiting, which is what the +# lock did before reclaim existed. +fm_pid_is_this_frame() { + local recorded=$1 + [ -n "$recorded" ] || return 1 + if [ -n "${BASHPID:-}" ]; then + [ "$recorded" = "$BASHPID" ] + return + fi + [ "${BASH_SUBSHELL:-0}" = 0 ] && [ "$recorded" = "$$" ] +} + fm_pid_identity() { local pid=$1 out proc_root stat_line starttime cmdline_hex identity_key local -a stat_fields @@ -801,11 +824,10 @@ fm_lock_try_acquire() { return 0 fi - # Compare against ${BASHPID:-$$} inline, never via a command substitution: - # $() forks a subshell whose BASHPID is not this frame's pid. + # fm_pid_is_this_frame owns what counts as "this frame" on each shell. pid=$(cat "$lockdir/pid" 2>/dev/null || true) - if [ -n "$pid" ] && [ "$pid" = "${BASHPID:-$$}" ]; then - # The recorded holder is THIS very process. Single-threaded bash can only + if fm_pid_is_this_frame "$pid"; then + # The recorded holder is THIS very frame. Single-threaded bash can only # observe that when an interrupting trap abandoned the frame that held the # lock mid-critical-section (e.g. TERM inside a recovery-marker section, # with the EXIT path then re-acquiring the same lock), and every diff --git a/tests/fm-inactive-reconcile.test.sh b/tests/fm-inactive-reconcile.test.sh index 2b6386cca13..5c3e55f1656 100755 --- a/tests/fm-inactive-reconcile.test.sh +++ b/tests/fm-inactive-reconcile.test.sh @@ -119,7 +119,8 @@ prime_seen() { # ' _ "$ROOT/bin/fm-wake-lib.sh" "$1" "$2" } -reap() { kill "$1" 2>/dev/null || true; wait "$1" 2>/dev/null || true; } +# reap comes from tests/lib.sh, which owns the bounded stop-and-collect these +# watcher fixtures need; a local `kill; wait` here could hang the whole suite. # The main retains a terminal presentation receipt until the corresponding wake # is handled and acknowledged. diff --git a/tests/fm-wake-queue.test.sh b/tests/fm-wake-queue.test.sh index 2d9b571ed83..c3dacb39300 100755 --- a/tests/fm-wake-queue.test.sh +++ b/tests/fm-wake-queue.test.sh @@ -68,7 +68,7 @@ test_signal_catchup_without_running_watcher() { # tested. printf 'blocked: first\n' > "$status_file" PATH="$fakebin:$PATH" FM_STATE_OVERRIDE="$state" FM_POLL=1 FM_SIGNAL_GRACE=1 FM_CHECK_INTERVAL=999999 FM_HEARTBEAT=999999 "$WATCH" > "$out" & - wait_for_exit "$!" 40 || fail "watcher did not exit for first signal" + wait_for_exit "$!" || fail "watcher did not exit for first signal" grep -F "signal: $status_file" "$out" >/dev/null || fail "watcher did not print first signal" FM_STATE_OVERRIDE="$state" "$DRAIN" > "$drain_out" 2> "$drain_err" || fail "drain after first signal failed" grep "$(printf '\tsignal\t')" "$drain_out" | grep -F "$status_file" >/dev/null || fail "first signal was not queued" @@ -80,7 +80,7 @@ test_signal_catchup_without_running_watcher() { printf 'done: second\n' >> "$status_file" : > "$out" PATH="$fakebin:$PATH" FM_STATE_OVERRIDE="$state" FM_POLL=1 FM_SIGNAL_GRACE=1 FM_CHECK_INTERVAL=999999 FM_HEARTBEAT=999999 "$WATCH" > "$out" & - wait_for_exit "$!" 40 || fail "watcher did not exit for second signal" + wait_for_exit "$!" || fail "watcher did not exit for second signal" grep -F "signal: $status_file" "$out" >/dev/null || fail "signal written with no watcher was not caught" pass "signal written while no watcher runs is caught on next run" } @@ -107,7 +107,7 @@ test_stale_enqueue_before_suppressor() { printf '%s' "$pane_hash" > "$state/.hash-$key" printf '1\n' > "$state/.count-$key" PATH="$fakebin:$PATH" FM_FAKE_TMUX_WINDOW="$window" FM_FAKE_TMUX_CAPTURE="$capture_file" FM_STATE_OVERRIDE="$state" FM_POLL=1 FM_SIGNAL_GRACE=1 FM_CHECK_INTERVAL=999999 FM_HEARTBEAT=999999 "$WATCH" > "$out" & - wait_for_exit "$!" 40 || fail "watcher did not exit for stale pane" + wait_for_exit "$!" || fail "watcher did not exit for stale pane" grep -Fx "stale: $window" "$out" >/dev/null || fail "watcher did not print stale wake" FM_STATE_OVERRIDE="$state" "$DRAIN" > "$drain_out" || fail "drain after stale wake failed" grep "$(printf '\tstale\t')" "$drain_out" | grep -F "$window" >/dev/null || fail "stale wake was not queued" @@ -144,7 +144,7 @@ test_not_working_stale_enqueue_before_suppressor() { PATH="$fakebin:$PATH" FM_FAKE_TMUX_WINDOW="$window" FM_FAKE_TMUX_CAPTURE="$capture_file" \ 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" & - wait_for_exit "$!" 40 || fail "watcher did not surface a not-provably-working stale" + wait_for_exit "$!" || fail "watcher did not surface a not-provably-working stale" grep -Fx "stale: $window" "$out" >/dev/null || fail "watcher did not print the immediate stale wake" FM_STATE_OVERRIDE="$state" "$DRAIN" > "$drain_out" || fail "drain after the immediate stale wake failed" grep "$(printf '\tstale\t')" "$drain_out" | grep -F "$window" >/dev/null || fail "immediate stale wake was not queued" @@ -169,7 +169,7 @@ SH FM_STATE_OVERRIDE="$state" "$ROOT/bin/fm-check-register.sh" task >/dev/null \ || fail "could not register queue custom check" PATH="$fakebin:$PATH" FM_STATE_OVERRIDE="$state" FM_POLL=1 FM_SIGNAL_GRACE=1 FM_CHECK_INTERVAL=0 FM_HEARTBEAT=999999 "$WATCH" > "$out" & - wait_for_exit "$!" 40 || fail "watcher did not exit for check output" + wait_for_exit "$!" || fail "watcher did not exit for check output" grep -F "check: $check_file: merged: https://example.test/pr/1" "$out" >/dev/null || fail "watcher did not print check wake" FM_STATE_OVERRIDE="$state" "$DRAIN" > "$drain_out" || fail "drain after check wake failed" grep "$(printf '\tcheck\t')" "$drain_out" | grep -F "$check_file" | grep -F 'merged: https://example.test/pr/1' >/dev/null || fail "check wake was not queued" @@ -1115,9 +1115,16 @@ test_self_announced_append_guards() { # A trap that fires inside a lock's critical section abandons the holding # frame, and the exit path then re-acquires the same lock (a TERM inside a # recovery-marker section is the reproduced case: the watcher's reap wedged -# forever spinning against its own pid). The same-process re-acquire must -# reclaim the abandoned hold, while a SUBSHELL still waits on its parent's -# live hold exactly as before. +# forever spinning against its own pid). The same-frame re-acquire must reclaim +# the abandoned hold, while a SUBSHELL still waits on its parent's live hold +# exactly as before. +# +# Both halves turn on naming the running frame, and a shell whose $$ is shared +# with every subshell can only do that where there is no subshell to confuse it +# with (fm_pid_is_this_frame owns why). Stock macOS bash 3.2 is such a shell and +# read the subshell below as its own parent before that distinction existed, so +# both halves are asserted on whatever shell runs this file rather than on an +# assumed one. test_self_held_lock_reclaims_instead_of_deadlocking() { local dir state rc dir=$(make_case self-held-lock) @@ -1131,7 +1138,8 @@ test_self_held_lock_reclaims_instead_of_deadlocking() { fm_lock_release "$lock" [ ! -e "$lock" ] && [ ! -L "$lock" ] || exit 12 ' _ "$ROOT/bin/fm-wake-lib.sh" "$state" || rc=$? - [ "$rc" -eq 0 ] || fail "self-held lock was not reclaimed cleanly (rc=$rc)" + [ "$rc" -eq 0 ] \ + || fail "self-held lock was not reclaimed cleanly (rc=$rc, bash $BASH_VERSION)" rc=0 FM_STATE_OVERRIDE="$state" bash -c ' . "$1" @@ -1140,8 +1148,8 @@ test_self_held_lock_reclaims_instead_of_deadlocking() { ( fm_lock_try_acquire "$lock" && exit 13; exit 0 ) || exit 13 fm_lock_release "$lock" ' _ "$ROOT/bin/fm-wake-lib.sh" "$state" || rc=$? - [ "$rc" -eq 0 ] || fail "a subshell reclaimed its parent's live hold (rc=$rc)" - pass "an abandoned same-process lock hold is reclaimed; a parent's live hold is not" + [ "$rc" -eq 0 ] || fail "a subshell reclaimed its parent's live hold (rc=$rc, bash $BASH_VERSION)" + pass "an abandoned same-frame lock hold is reclaimed; a parent's live hold never is" } # Drain-time historical annotation staleness: a turn-ended-only wake row must @@ -1193,6 +1201,14 @@ test_historical_annotation_skips_announced_status() { pass "historical annotations replay nothing already announced and keep everything new" } +# CI's stock macOS Bash lane sets FM_TEST_ONLY to run just the frame-identity +# lock regression, whose contract differs on a shell with no BASHPID. Every +# other case here is shell-agnostic and is covered by the portable lanes. +if [ -n "${FM_TEST_ONLY:-}" ]; then + "$FM_TEST_ONLY" + exit 0 +fi + test_self_held_lock_reclaims_instead_of_deadlocking test_secondmate_foreign_queue_stall_is_one_shot_and_read_only test_secondmate_stall_marker_rejects_symlink diff --git a/tests/fm-watch-triage.test.sh b/tests/fm-watch-triage.test.sh index c527771e2dc..6e2b731bdf6 100755 --- a/tests/fm-watch-triage.test.sh +++ b/tests/fm-watch-triage.test.sh @@ -98,12 +98,10 @@ wait_poll_cycle() { # [limit-ticks] return 1 } -# Every wait_for_exit budget in this file is 100 ticks (10s), not because any -# watcher takes that long to decide, but because fm-watch.sh does bounded -# startup work before its first poll: a tighter budget reaps the process while -# it is still starting and reports a spurious "did not surface" failure. A -# generous budget can only remove that false negative - a watcher that never -# exits still fails the assertion when the budget runs out. +# wait_for_exit calls here take the standard budget; wait_for_exit in +# tests/wake-helpers.sh owns what that budget is and why a tighter one reports +# spurious failures. The few away-mode cases that need a larger one pass it +# explicitly. wait_numeric_file() { local file=$1 limit=${2:-30} i=0 value while [ "$i" -lt "$limit" ]; do @@ -174,7 +172,8 @@ record_pi_busy() { # --source pi-ext --event agent-start } -reap() { kill "$1" 2>/dev/null || true; wait "$1" 2>/dev/null || true; } +# reap comes from tests/lib.sh, which owns the bounded stop-and-collect these +# watcher fixtures need; a local `kill; wait` here could hang the whole suite. # --- pure classifier predicates (fm-classify-lib.sh) ------------------------ @@ -767,7 +766,7 @@ test_turn_ended_not_working_surfaced() { export FM_FAKE_CREW_STATE='state: unknown · source: none · no current-state source available' watch_bg "$state" "$fakebin" "$out" pid=$! - wait_for_exit "$pid" 100 || fail "watcher did not surface a turn-end whose crew is not provably working" + wait_for_exit "$pid" || fail "watcher did not surface a turn-end whose crew is not provably working" grep -F "signal: $state/task.turn-ended" "$out" >/dev/null || fail "watcher did not print the surfaced turn-end signal" FM_STATE_OVERRIDE="$state" "$DRAIN" > "$drain_out" 2>/dev/null || fail "drain after the surfaced turn-end failed" grep "$(printf '\tsignal\t')" "$drain_out" | grep -F "$state/task.turn-ended" >/dev/null || fail "surfaced turn-end was not queued" @@ -880,7 +879,7 @@ test_turn_ended_churn_resets_prior_stale_classification() { # This is a new quiet interval, so it must surface through ordinary staleness # instead of inheriting the earlier interval's wedge timer. printf 'idle prompt from an earlier turn' > "$capture_file" - wait_for_exit "$pid" 100 \ + wait_for_exit "$pid" \ || { reap "$pid"; fail "a stopped pane matching an earlier stale render waited for the wedge timeout"; } grep -Fx "stale: $window" "$out" >/dev/null \ || fail "the returned stale render did not surface through ordinary staleness" @@ -941,7 +940,7 @@ test_turn_ended_still_pane_surfaced() { FM_STATE_OVERRIDE="$state" FM_CREW_STATE_BIN="$fakebin/fm-crew-state.sh" FM_POLL=3 FM_SIGNAL_GRACE=1 \ FM_CHECK_INTERVAL=999999 FM_HEARTBEAT=999999 "$WATCH" > "$out" & pid=$! - wait_for_exit "$pid" 100 || fail "watcher did not surface a bare turn-end from an unchanged pane" + wait_for_exit "$pid" || fail "watcher did not surface a bare turn-end from an unchanged pane" grep -F "signal: $state/codexstopped.turn-ended" "$out" >/dev/null \ || fail "watcher did not print the surfaced still-pane turn-end signal" FM_STATE_OVERRIDE="$state" "$DRAIN" > "$drain_out" 2>/dev/null || fail "drain after the still-pane turn-end failed" @@ -968,7 +967,7 @@ test_turn_ended_malformed_prior_hash_surfaced() { FM_STATE_OVERRIDE="$state" FM_CREW_STATE_BIN="$fakebin/fm-crew-state.sh" FM_POLL=3 FM_SIGNAL_GRACE=1 \ FM_CHECK_INTERVAL=999999 FM_HEARTBEAT=999999 "$WATCH" > "$out" & pid=$! - wait_for_exit "$pid" 100 || fail "watcher absorbed a turn-end backed by a malformed prior hash" + wait_for_exit "$pid" || fail "watcher absorbed a turn-end backed by a malformed prior hash" grep -F "signal: $state/codexmalformed.turn-ended" "$out" >/dev/null \ || fail "watcher did not print the surfaced malformed-hash turn-end" FM_STATE_OVERRIDE="$state" "$DRAIN" > "$drain_out" 2>/dev/null \ @@ -996,7 +995,7 @@ test_turn_ended_trailing_newline_prior_hash_surfaced() { FM_STATE_OVERRIDE="$state" FM_CREW_STATE_BIN="$fakebin/fm-crew-state.sh" FM_POLL=3 FM_SIGNAL_GRACE=1 \ FM_CHECK_INTERVAL=999999 FM_HEARTBEAT=999999 "$WATCH" > "$out" & pid=$! - wait_for_exit "$pid" 100 || fail "watcher absorbed a turn-end backed by a newline-terminated prior hash" + wait_for_exit "$pid" || fail "watcher absorbed a turn-end backed by a newline-terminated prior hash" grep -F "signal: $state/codexnewline.turn-ended" "$out" >/dev/null \ || fail "watcher did not print the surfaced newline-hash turn-end" FM_STATE_OVERRIDE="$state" "$DRAIN" > "$drain_out" 2>/dev/null \ @@ -1026,7 +1025,7 @@ test_secondmate_turn_ended_churning_pane_surfaced() { FM_STATE_OVERRIDE="$state" FM_CREW_STATE_BIN="$fakebin/fm-crew-state.sh" FM_POLL=3 FM_SIGNAL_GRACE=1 \ FM_CHECK_INTERVAL=999999 FM_HEARTBEAT=999999 "$WATCH" > "$out" & pid=$! - wait_for_exit "$pid" 100 || fail "watcher did not surface a churning secondmate turn-end" + wait_for_exit "$pid" || fail "watcher did not surface a churning secondmate turn-end" grep -F "signal: $state/mate.turn-ended" "$out" >/dev/null \ || fail "watcher did not print the surfaced churning secondmate turn-end" FM_STATE_OVERRIDE="$state" "$DRAIN" > "$drain_out" 2>/dev/null \ @@ -1055,7 +1054,7 @@ test_turn_ended_colliding_window_key_surfaced() { FM_STATE_OVERRIDE="$state" FM_CREW_STATE_BIN="$fakebin/fm-crew-state.sh" FM_POLL=3 FM_SIGNAL_GRACE=1 \ FM_CHECK_INTERVAL=999999 FM_HEARTBEAT=999999 "$WATCH" > "$out" & pid=$! - wait_for_exit "$pid" 100 || fail "watcher did not surface a turn-end with an ambiguous pane marker" + wait_for_exit "$pid" || fail "watcher did not surface a turn-end with an ambiguous pane marker" grep -F "signal: $state/a.b.turn-ended" "$out" >/dev/null \ || fail "watcher did not print the surfaced ambiguous-marker turn-end" FM_STATE_OVERRIDE="$state" "$DRAIN" > "$drain_out" 2>/dev/null \ @@ -1084,7 +1083,7 @@ test_turn_ended_duplicate_endpoint_records_surfaced() { FM_STATE_OVERRIDE="$state" FM_CREW_STATE_BIN="$fakebin/fm-crew-state.sh" FM_POLL=3 FM_SIGNAL_GRACE=1 \ FM_CHECK_INTERVAL=999999 FM_HEARTBEAT=999999 "$WATCH" > "$out" & pid=$! - wait_for_exit "$pid" 100 || fail "watcher absorbed a turn-end shared by two endpoint records" + wait_for_exit "$pid" || fail "watcher absorbed a turn-end shared by two endpoint records" grep -F "signal: $state/first.turn-ended" "$out" >/dev/null \ || fail "watcher did not print the surfaced duplicate-endpoint turn-end" FM_STATE_OVERRIDE="$state" "$DRAIN" > "$drain_out" 2>/dev/null \ @@ -1157,7 +1156,7 @@ test_turn_ended_mixed_positive_evidence_batch_default_off() { FM_STATE_OVERRIDE="$state" FM_CREW_STATE_BIN="$fakebin/fm-crew-state.sh" FM_POLL=3 FM_SIGNAL_GRACE=1 \ FM_CHECK_INTERVAL=999999 FM_HEARTBEAT=999999 "$WATCH" > "$out" & pid=$! - wait_for_exit "$pid" 100 || fail "watcher absorbed a mixed-evidence batch without the opt-in flag" + wait_for_exit "$pid" || fail "watcher absorbed a mixed-evidence batch without the opt-in flag" grep -F "$state/firstoff.turn-ended" "$out" >/dev/null \ || fail "watcher did not print the first default-off turn-end" grep -F "$state/secondoff.turn-ended" "$out" >/dev/null \ @@ -1194,7 +1193,7 @@ test_status_and_turn_end_batch_never_uses_churn_evidence() { FM_STATE_OVERRIDE="$state" FM_CREW_STATE_BIN="$fakebin/fm-crew-state.sh" FM_POLL=3 FM_SIGNAL_GRACE=1 \ FM_CHECK_INTERVAL=999999 FM_HEARTBEAT=999999 "$WATCH" > "$out" & pid=$! - wait_for_exit "$pid" 100 || fail "watcher absorbed a status-and-turn-end batch on churn evidence" + wait_for_exit "$pid" || fail "watcher absorbed a status-and-turn-end batch on churn evidence" grep -F "$state/firststatus.status" "$out" >/dev/null \ || fail "watcher did not print the status file from the surfaced mixed batch" grep -F "$state/secondturn.turn-ended" "$out" >/dev/null \ @@ -1232,7 +1231,7 @@ test_turn_ended_churn_absorb_off_by_default() { FM_STATE_OVERRIDE="$state" FM_CREW_STATE_BIN="$fakebin/fm-crew-state.sh" FM_POLL=3 FM_SIGNAL_GRACE=1 \ FM_CHECK_INTERVAL=999999 FM_HEARTBEAT=999999 "$WATCH" > "$out" & pid=$! - wait_for_exit "$pid" 100 || fail "watcher absorbed a churning turn-end without the opt-in flag" + wait_for_exit "$pid" || fail "watcher absorbed a churning turn-end without the opt-in flag" grep -F "signal: $state/codexdefault.turn-ended" "$out" >/dev/null \ || fail "watcher did not print the surfaced default-off churning turn-end" FM_STATE_OVERRIDE="$state" "$DRAIN" > "$drain_out" 2>/dev/null \ @@ -1270,7 +1269,7 @@ test_turn_ended_churn_absorb_bounded() { FM_STATE_OVERRIDE="$state" FM_CREW_STATE_BIN="$fakebin/fm-crew-state.sh" FM_POLL=3 FM_SIGNAL_GRACE=1 \ FM_CHECK_INTERVAL=999999 FM_HEARTBEAT=999999 "$WATCH" > "$out" & pid=$! - wait_for_exit "$pid" 100 \ + wait_for_exit "$pid" \ || fail "a perpetually churning pane deferred its turn-end past the absorb bound" grep -F "signal: $state/codexclock.turn-ended" "$out" >/dev/null \ || fail "watcher did not print the turn-end surfaced by the exhausted absorb bound" @@ -1302,7 +1301,7 @@ test_turn_ended_churn_timer_write_failure_surfaced() { FM_STATE_OVERRIDE="$state" FM_CREW_STATE_BIN="$fakebin/fm-crew-state.sh" FM_POLL=3 FM_SIGNAL_GRACE=1 \ FM_CHECK_INTERVAL=999999 FM_HEARTBEAT=999999 "$WATCH" > "$out" 2>/dev/null & pid=$! - wait_for_exit "$pid" 100 || fail "watcher absorbed a churning turn-end without recording its deadline" + wait_for_exit "$pid" || fail "watcher absorbed a churning turn-end without recording its deadline" grep -F "signal: $state/codextimer.turn-ended" "$out" >/dev/null \ || fail "watcher did not print the turn-end whose churn deadline could not be recorded" FM_STATE_OVERRIDE="$state" "$DRAIN" > "$drain_out" 2>/dev/null \ @@ -1330,7 +1329,7 @@ test_turn_ended_invalid_churn_bound_surfaced() { FM_STATE_OVERRIDE="$state" FM_CREW_STATE_BIN="$fakebin/fm-crew-state.sh" FM_POLL=3 FM_SIGNAL_GRACE=1 \ FM_CHECK_INTERVAL=999999 FM_HEARTBEAT=999999 "$WATCH" > "$out" 2>/dev/null & pid=$! - wait_for_exit "$pid" 100 || fail "watcher did not surface a turn-end with an invalid churn bound" + wait_for_exit "$pid" || fail "watcher did not surface a turn-end with an invalid churn bound" grep -F "signal: $state/codexbound.turn-ended" "$out" >/dev/null \ || fail "watcher terminated before printing the invalid-bound turn-end" FM_STATE_OVERRIDE="$state" "$DRAIN" > "$drain_out" 2>/dev/null \ @@ -1360,7 +1359,7 @@ test_turn_ended_oversized_churn_bound_surfaced() { FM_STATE_OVERRIDE="$state" FM_CREW_STATE_BIN="$fakebin/fm-crew-state.sh" FM_POLL=3 FM_SIGNAL_GRACE=1 \ FM_CHECK_INTERVAL=999999 FM_HEARTBEAT=999999 "$WATCH" > "$out" 2>/dev/null & pid=$! - wait_for_exit "$pid" 100 || fail "watcher did not surface a turn-end with an oversized churn bound" + wait_for_exit "$pid" || fail "watcher did not surface a turn-end with an oversized churn bound" grep -F "signal: $state/codexoversized.turn-ended" "$out" >/dev/null \ || fail "watcher terminated before printing the oversized-bound turn-end" FM_STATE_OVERRIDE="$state" "$DRAIN" > "$drain_out" 2>/dev/null \ @@ -1401,7 +1400,7 @@ test_turn_ended_invalid_churn_deadline_surfaced() { FM_STATE_OVERRIDE="$state" FM_CREW_STATE_BIN="$fakebin/fm-crew-state.sh" FM_POLL=3 FM_SIGNAL_GRACE=1 \ FM_CHECK_INTERVAL=999999 FM_HEARTBEAT=999999 "$WATCH" > "$out" 2>/dev/null & pid=$! - wait_for_exit "$pid" 100 || fail "watcher did not surface a turn-end with a $variant churn deadline" + wait_for_exit "$pid" || fail "watcher did not surface a turn-end with a $variant churn deadline" grep -F "signal: $state/codexdeadline.turn-ended" "$out" >/dev/null \ || fail "watcher terminated before printing the $variant-deadline turn-end" FM_STATE_OVERRIDE="$state" "$DRAIN" > "$drain_out" 2>/dev/null \ @@ -1438,7 +1437,7 @@ test_turn_ended_surfaced_batch_opens_no_partial_deadline() { FM_STATE_OVERRIDE="$state" FM_CREW_STATE_BIN="$fakebin/fm-crew-state.sh" FM_POLL=3 FM_SIGNAL_GRACE=1 \ FM_CHECK_INTERVAL=999999 FM_HEARTBEAT=999999 "$WATCH" > "$out" 2>/dev/null & pid=$! - wait_for_exit "$pid" 100 || fail "watcher absorbed a batch containing an invalid churn deadline" + wait_for_exit "$pid" || fail "watcher absorbed a batch containing an invalid churn deadline" grep -F "$state/first.turn-ended" "$out" >/dev/null \ || fail "watcher did not print the first turn-end from the surfaced batch" grep -F "$state/second.turn-ended" "$out" >/dev/null \ @@ -1469,7 +1468,7 @@ test_working_note_not_working_surfaced() { export FM_FAKE_CREW_STATE='state: working · source: status-log · working: compiling step 2' watch_bg "$state" "$fakebin" "$out" pid=$! - wait_for_exit "$pid" 100 || fail "watcher did not surface a working: note whose crew has no running pipeline and an idle pane" + wait_for_exit "$pid" || fail "watcher did not surface a working: note whose crew has no running pipeline and an idle pane" grep -F "signal: $status_file" "$out" >/dev/null || fail "watcher did not print the surfaced working: signal" FM_STATE_OVERRIDE="$state" "$DRAIN" > "$drain_out" 2>/dev/null || fail "drain after the surfaced working: note failed" grep "$(printf '\tsignal\t')" "$drain_out" | grep -F "$status_file" >/dev/null || fail "surfaced working: note was not queued" @@ -1488,7 +1487,7 @@ test_secondmate_status_note_surfaced_despite_busy_agent() { export FM_FAKE_CREW_STATE='state: working · source: run-step · running' FM_CONFIG_OVERRIDE="$(churn_config "$dir")" watch_bg "$state" "$fakebin" "$out" pid=$! - wait_for_exit "$pid" 100 || fail "watcher absorbed a busy secondmate's routed status note" + wait_for_exit "$pid" || fail "watcher absorbed a busy secondmate's routed status note" grep -F "signal: $state/mate.status" "$out" >/dev/null \ || fail "watcher did not print the surfaced secondmate note" FM_STATE_OVERRIDE="$state" "$DRAIN" > "$drain_out" 2>/dev/null || fail "drain after the surfaced note failed" @@ -1522,7 +1521,7 @@ test_self_announced_close_does_not_rewake_but_next_note_does() { # A later, different note on the SAME task still wakes: dedup is keyed on the # exact announced bytes, never on task identity. printf 'needs-decision [key=k2]: a genuinely new decision\n' >> "$status_file" - wait_for_exit "$pid" 100 || fail "a later different note after a self-announced close was swallowed" + wait_for_exit "$pid" || fail "a later different note after a self-announced close was swallowed" grep -F "signal: $status_file" "$out" >/dev/null \ || fail "the later note did not surface as a signal" pass "a self-announced close never wakes its own home, and the next real note still does" @@ -1538,7 +1537,7 @@ test_actionable_signal_surfaced() { printf 'working: setup\nneeds-decision: pick A or B\n' > "$status_file" watch_bg "$state" "$fakebin" "$out" pid=$! - wait_for_exit "$pid" 100 || fail "watcher did not exit for an actionable needs-decision signal" + wait_for_exit "$pid" || fail "watcher did not exit for an actionable needs-decision signal" grep -F "signal: $status_file" "$out" >/dev/null || fail "watcher did not print the actionable signal reason" FM_STATE_OVERRIDE="$state" "$DRAIN" > "$drain_out" 2>/dev/null || fail "drain after the actionable signal failed" grep "$(printf '\tsignal\t')" "$drain_out" | grep -F "$status_file" >/dev/null || fail "actionable signal was not queued" @@ -1568,7 +1567,7 @@ test_actionable_signal_survives_a_later_routine_append() { export FM_FAKE_CREW_STATE='state: working · source: run-step · validating (running)' watch_bg "$state" "$fakebin" "$out" pid=$! - wait_for_exit "$pid" 100 \ + wait_for_exit "$pid" \ || { reap "$pid"; fail "watcher absorbed a needs-decision hidden behind a later working: line"; } grep -F "signal: $status_file" "$out" >/dev/null || fail "watcher did not print the actionable signal reason" FM_STATE_OVERRIDE="$state" "$DRAIN" > "$drain_out" 2>/dev/null || fail "drain after the masked signal failed" @@ -1590,7 +1589,7 @@ test_release_completion_survives_a_later_routine_append() { export FM_FAKE_CREW_STATE='state: working · source: pane · harness busy' watch_bg "$state" "$fakebin" "$out" pid=$! - wait_for_exit "$pid" 100 \ + wait_for_exit "$pid" \ || { reap "$pid"; fail "watcher absorbed a release/install completion hidden behind later cleanup chatter"; } FM_STATE_OVERRIDE="$state" "$DRAIN" > "$drain_out" 2>/dev/null || fail "drain after the masked completion failed" grep "$(printf '\tsignal\t')" "$drain_out" | grep -F "$status_file" >/dev/null \ @@ -1631,7 +1630,7 @@ test_unreadable_status_reports_once_per_file_state() { watch_bg "$state" "$fakebin" "$out" pid=$! - wait_for_exit "$pid" 100 || { reap "$pid"; fail "a dangling status symlink was not reported"; } + wait_for_exit "$pid" || { reap "$pid"; fail "a dangling status symlink was not reported"; } grep -Fx "signal: $status_file" "$out" >/dev/null \ || fail "a dangling status symlink did not use the immediate signal path: $(cat "$out")" sig=$(status_observed_signature "$status_file") @@ -1653,7 +1652,7 @@ test_unreadable_status_reports_once_per_file_state() { target="$dir/status-target-two-longer" watch_bg "$state" "$fakebin" "$out" pid=$! - wait_for_exit "$pid" 100 || { reap "$pid"; fail "a changed unreadable status did not report again"; } + wait_for_exit "$pid" || { reap "$pid"; fail "a changed unreadable status did not report again"; } [ "$(status_presentation_marker_offset "$marker" "$status_file")" = 0 ] \ || fail "a changed unreadable status advanced its classification position" ack_stopped_cycle "$state" || fail "could not acknowledge the changed unreadable-status wake" @@ -1662,7 +1661,7 @@ test_unreadable_status_reports_once_per_file_state() { cp "$target" "$status_file" watch_bg "$state" "$fakebin" "$out" pid=$! - wait_for_exit "$pid" 100 || { reap "$pid"; fail "a readable replacement did not surface preserved content"; } + wait_for_exit "$pid" || { reap "$pid"; fail "a readable replacement did not surface preserved content"; } [ "$(status_presentation_marker_offset "$marker" "$status_file")" = "$(size_of "$status_file")" ] \ || fail "readable recovery did not classify content written before the failure" pass "unreadable status reports are bounded without advancing classification" @@ -1683,7 +1682,7 @@ test_permission_recovery_surfaces_preserved_status() { watch_bg "$state" "$fakebin" "$out" pid=$! - wait_for_exit "$pid" 100 || { reap "$pid"; chmod 600 "$status_file"; fail "an unreadable regular status was not reported"; } + wait_for_exit "$pid" || { reap "$pid"; chmod 600 "$status_file"; fail "an unreadable regular status was not reported"; } [ "$(status_presentation_marker_offset "$marker" "$status_file")" = 0 ] \ || { chmod 600 "$status_file"; fail "an unreadable regular status advanced its classification position"; } ack_stopped_cycle "$state" || { chmod 600 "$status_file"; fail "could not acknowledge the unreadable regular-status wake"; } @@ -1697,7 +1696,7 @@ test_permission_recovery_surfaces_preserved_status() { chmod 600 "$status_file" after_ident=$(_fm_open_decisions_file_ident "$status_file") [ "$after_ident" = "$before_ident" ] || { reap "$pid"; fail "the permission-only recovery changed file identity"; } - wait_for_exit "$pid" 100 || { reap "$pid"; fail "readability recovery did not surface preserved content"; } + wait_for_exit "$pid" || { reap "$pid"; fail "readability recovery did not surface preserved content"; } grep -Fx "signal: $status_file" "$out" >/dev/null \ || fail "readability recovery did not use the actionable signal path: $(cat "$out")" [ "$(status_presentation_marker_offset "$marker" "$status_file")" = "$(size_of "$status_file")" ] \ @@ -1721,7 +1720,7 @@ test_terminal_stale_surfaced() { PATH="$fakebin:$PATH" FM_FAKE_TMUX_WINDOW="$window" FM_FAKE_TMUX_CAPTURE="$capture_file" \ FM_STATE_OVERRIDE="$state" FM_POLL=1 FM_SIGNAL_GRACE=1 FM_CHECK_INTERVAL=999999 FM_HEARTBEAT=999999 "$WATCH" > "$out" & pid=$! - wait_for_exit "$pid" 100 || fail "watcher did not exit for a stale pane on a terminal status" + wait_for_exit "$pid" || fail "watcher did not exit for a stale pane on a terminal status" grep -Fx "stale: $window" "$out" >/dev/null || fail "watcher did not print the terminal stale wake" FM_STATE_OVERRIDE="$state" "$DRAIN" > "$drain_out" 2>/dev/null || fail "drain after the terminal stale failed" grep "$(printf '\tstale\t')" "$drain_out" | grep -F "$window" >/dev/null || fail "terminal stale was not queued" @@ -1812,7 +1811,7 @@ test_stale_terminal_status_overridden_by_active_run() { FM_STATE_OVERRIDE="$state" FM_CREW_STATE_BIN="$fakebin/fm-crew-state.sh" FM_STALE_ESCALATE_SECS=240 FM_POLL=1 FM_SIGNAL_GRACE=1 \ FM_CHECK_INTERVAL=999999 FM_HEARTBEAT=999999 "$WATCH" > "$out" & pid=$! - wait_for_exit "$pid" 100 || fail "watcher did not escalate once the run-step stopped reporting working" + wait_for_exit "$pid" || fail "watcher did not escalate once the run-step stopped reporting working" grep -F "stale: $window" "$out" >/dev/null || fail "escalation did not print a stale wake" grep -F "possible wedge" "$out" >/dev/null || fail "escalation did not flag a possible wedge" unset FM_FAKE_CREW_STATE @@ -1890,7 +1889,7 @@ test_nonterminal_stale_provably_working_absorbed_then_escalated() { FM_STATE_OVERRIDE="$state" FM_CREW_STATE_BIN="$fakebin/fm-crew-state.sh" FM_STALE_ESCALATE_SECS=240 FM_POLL=1 FM_SIGNAL_GRACE=1 \ FM_CHECK_INTERVAL=999999 FM_HEARTBEAT=999999 "$WATCH" > "$out" & pid=$! - wait_for_exit "$pid" 100 || fail "watcher did not escalate once the run-step stopped reporting working" + wait_for_exit "$pid" || fail "watcher did not escalate once the run-step stopped reporting working" grep -F "stale: $window" "$out" >/dev/null || fail "escalation did not print a stale wake" grep -F "possible wedge" "$out" >/dev/null || fail "escalation did not flag a possible wedge" [ ! -e "$state/.stale-since-$key" ] || fail "stale-since timer was not cleared after escalation" @@ -1929,7 +1928,7 @@ test_nonterminal_stale_not_working_surfaced() { 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_for_exit "$pid" 100 || fail "watcher did not surface a not-provably-working non-terminal stale at once" + wait_for_exit "$pid" || fail "watcher did not surface a not-provably-working non-terminal stale at once" grep -Fx "stale: $window" "$out" >/dev/null || fail "watcher did not print the immediate stale wake" grep -F "possible wedge" "$out" >/dev/null && fail "an immediate stopped-crew stale was mislabeled a wedge" [ "$(cat "$state/.stale-$key" 2>/dev/null || true)" = "$pane_hash" ] || fail "stale suppressor was not advanced on surface" @@ -1998,7 +1997,7 @@ test_nonterminal_stale_paused_absorbed_then_resurfaced() { FM_STATE_OVERRIDE="$state" FM_CREW_STATE_BIN="$fakebin/fm-crew-state.sh" FM_PAUSE_RESURFACE_SECS=240 FM_POLL=1 FM_SIGNAL_GRACE=1 \ FM_CHECK_INTERVAL=999999 FM_HEARTBEAT=999999 "$WATCH" > "$out" & pid=$! - wait_for_exit "$pid" 100 || fail "watcher did not re-surface a declared pause past the threshold" + wait_for_exit "$pid" || fail "watcher did not re-surface a declared pause past the threshold" grep -F "stale: $window" "$out" >/dev/null || fail "re-surface did not print a stale wake" grep -F "awaiting external" "$out" >/dev/null || fail "re-surface was not labeled a paused/awaiting-external recheck" grep -F "possible wedge" "$out" >/dev/null && fail "a declared pause was mislabeled a possible wedge" @@ -2083,7 +2082,7 @@ test_exited_declared_pause_is_bounded_but_live_gate_surfaces() { FM_STATE_OVERRIDE="$state" FM_CREW_STATE_BIN="$fakebin/fm-crew-state.sh" FM_PAUSE_RESURFACE_SECS=240 FM_POLL=1 FM_SIGNAL_GRACE=1 \ FM_CHECK_INTERVAL=999999 FM_HEARTBEAT=999999 "$WATCH" > "$out" & pid=$! - wait_for_exit "$pid" 100 || fail "captain-held dead-agent pane did not re-surface on the bounded cadence" + wait_for_exit "$pid" || fail "captain-held dead-agent pane did not re-surface on the bounded cadence" grep -F "awaiting the captain" "$state/.wake-queue" >/dev/null \ || fail "captain-held dead-agent pane surfaced as a stopped crew instead of a captain-owned recheck: $(cat "$state/.wake-queue")" grep -F "awaiting external" "$state/.wake-queue" >/dev/null \ @@ -2108,7 +2107,7 @@ test_exited_declared_pause_is_bounded_but_live_gate_surfaces() { FM_STATE_OVERRIDE="$state" FM_CREW_STATE_BIN="$fakebin/fm-crew-state.sh" FM_PAUSE_RESURFACE_SECS=999 FM_POLL=1 FM_SIGNAL_GRACE=1 \ FM_CHECK_INTERVAL=999999 FM_HEARTBEAT=999999 "$WATCH" >> "$out" & pid=$! - wait_for_exit "$pid" 100 || fail "live external-decision gate did not surface immediately" + wait_for_exit "$pid" || fail "live external-decision gate did not surface immediately" ack_stopped_cycle "$state" || fail "could not acknowledge the immediate external-decision surface" # Re-arm with the stale timer already beyond the wedge threshold. This is the @@ -2193,7 +2192,7 @@ test_secondmate_paused_resurfaces_in_normal_mode() { FM_STATE_OVERRIDE="$state" FM_CREW_STATE_BIN="$fakebin/fm-crew-state.sh" FM_PAUSE_RESURFACE_SECS=240 FM_POLL=1 FM_SIGNAL_GRACE=1 \ FM_CHECK_INTERVAL=999999 FM_HEARTBEAT=999999 "$WATCH" > "$out" & pid=$! - wait_for_exit "$pid" 100 || fail "watcher did not re-surface a paused secondmate" + wait_for_exit "$pid" || fail "watcher did not re-surface a paused secondmate" grep -F "stale: $window" "$out" >/dev/null || fail "paused secondmate did not emit a stale recheck" grep -F "awaiting external" "$out" >/dev/null || fail "paused secondmate recheck omitted its external-wait reason" grep -F "awaiting the captain" "$out" >/dev/null && fail "paused secondmate recheck named the captain instead of its external dependency" @@ -2227,7 +2226,7 @@ test_secondmate_captain_held_resurfaces_in_normal_mode() { FM_STATE_OVERRIDE="$state" FM_CREW_STATE_BIN="$fakebin/fm-crew-state.sh" FM_PAUSE_RESURFACE_SECS=240 FM_POLL=1 FM_SIGNAL_GRACE=1 \ FM_CHECK_INTERVAL=999999 FM_HEARTBEAT=999999 "$WATCH" > "$out" & pid=$! - wait_for_exit "$pid" 100 || fail "watcher did not re-surface a captain-held secondmate" + wait_for_exit "$pid" || fail "watcher did not re-surface a captain-held secondmate" grep -F "stale: $window" "$out" >/dev/null || fail "captain-held secondmate did not emit a stale recheck" grep -F "awaiting the captain" "$out" >/dev/null || fail "captain-held secondmate recheck did not name the captain as the blocker: $(cat "$out")" grep -F "awaiting external" "$out" >/dev/null && fail "captain-held secondmate recheck claimed an external wait" @@ -2434,7 +2433,7 @@ test_paused_authoritative_working_preserves_wedge_timer() { FM_STATE_OVERRIDE="$state" FM_CREW_STATE_BIN="$fakebin/fm-crew-state.sh" FM_STALE_ESCALATE_SECS=240 FM_POLL=1 FM_SIGNAL_GRACE=1 \ FM_CHECK_INTERVAL=999999 FM_HEARTBEAT=999999 "$WATCH" > "$out" & pid=$! - wait_for_exit "$pid" 100 || fail "authoritative working state did not wedge-escalate once it stopped reporting working" + wait_for_exit "$pid" || fail "authoritative working state did not wedge-escalate once it stopped reporting working" grep -F "possible wedge" "$out" >/dev/null || fail "authoritative working wedge escalation omitted its reason" [ ! -e "$state/.stale-since-$key" ] || fail "wedge timer remained after authoritative working escalation" unset FM_FAKE_CREW_STATE @@ -2497,7 +2496,7 @@ test_wedge_escalation_marks_demand_deep_inspection_after_threshold() { FM_STATE_OVERRIDE="$state" FM_CREW_STATE_BIN="$fakebin/fm-crew-state.sh" FM_STALE_ESCALATE_SECS=240 FM_POLL=1 FM_SIGNAL_GRACE=1 \ FM_CHECK_INTERVAL=999999 FM_HEARTBEAT=999999 "$WATCH" > "$out" & pid=$! - wait_for_exit "$pid" 100 || fail "watcher did not escalate on consecutive wedge round $n: $(cat "$out")" + wait_for_exit "$pid" || fail "watcher did not escalate on consecutive wedge round $n: $(cat "$out")" grep -F "escalation $n" "$out" >/dev/null || fail "round $n did not report escalation count $n: $(cat "$out")" if [ "$n" -lt 3 ]; then grep -F "demand-deep-inspection" "$out" >/dev/null && fail "round $n escalated to demand-deep-inspection before the threshold: $(cat "$out")" @@ -2620,7 +2619,7 @@ test_busy_pane_stable_hash_escalates_past_turn_age_bound() { FM_STATE_OVERRIDE="$state" FM_BUSY_TURN_MAX_SECS=1 FM_STALE_ESCALATE_SECS=240 FM_POLL=1 FM_SIGNAL_GRACE=1 \ FM_CHECK_INTERVAL=999999 FM_HEARTBEAT=999999 "$WATCH" > "$out" & pid=$! - wait_for_exit "$pid" 100 || fail "a stable-hash busy pane did not wedge-escalate past the turn-age bound" + wait_for_exit "$pid" || fail "a stable-hash busy pane did not wedge-escalate past the turn-age bound" grep -F "stale: $window" "$out" >/dev/null || fail "busy turn-age escalation did not print the stale wake" grep -F "possible wedge" "$out" >/dev/null || fail "busy turn-age escalation did not flag a possible wedge" pass "a busy worker with a stable pane hash still escalates once its completed-turn age reaches the bound" @@ -2665,7 +2664,7 @@ test_busy_pane_changing_hash_escalates_past_turn_age_bound() { FM_STATE_OVERRIDE="$state" FM_BUSY_TURN_MAX_SECS=1 FM_STALE_ESCALATE_SECS=240 FM_POLL=1 FM_SIGNAL_GRACE=1 \ FM_CHECK_INTERVAL=999999 FM_HEARTBEAT=999999 "$WATCH" > "$out" & pid=$! - wait_for_exit "$pid" 100 || fail "a changing-hash busy pane did not wedge-escalate past the turn-age bound" + wait_for_exit "$pid" || fail "a changing-hash busy pane did not wedge-escalate past the turn-age bound" grep -F "stale: $window" "$out" >/dev/null || fail "busy turn-age escalation (changing hash) did not print the stale wake" grep -F "possible wedge" "$out" >/dev/null || fail "busy turn-age escalation (changing hash) did not flag a possible wedge" pass "a busy worker whose pane hash changes every poll still escalates once its completed-turn age reaches the bound" @@ -2741,7 +2740,7 @@ test_busy_pane_repeated_escalation_reaches_demand_deep_inspection() { FM_STATE_OVERRIDE="$state" FM_BUSY_TURN_MAX_SECS=1 FM_STALE_ESCALATE_SECS=240 FM_POLL=1 FM_SIGNAL_GRACE=1 \ FM_CHECK_INTERVAL=999999 FM_HEARTBEAT=999999 "$WATCH" > "$out" & pid=$! - wait_for_exit "$pid" 100 || fail "busy turn-age escalation round $n did not escalate: $(cat "$out")" + wait_for_exit "$pid" || fail "busy turn-age escalation round $n did not escalate: $(cat "$out")" grep -F "escalation $n" "$out" >/dev/null || fail "busy turn-age round $n did not report escalation count $n: $(cat "$out")" if [ "$n" -lt 3 ]; then grep -F "demand-deep-inspection" "$out" >/dev/null && fail "busy turn-age round $n escalated to demand-deep-inspection before the threshold: $(cat "$out")" @@ -2816,7 +2815,7 @@ test_busy_declared_pause_is_rechecked_not_wedge_escalated() { FM_POLL=1 FM_SIGNAL_GRACE=1 \ FM_CHECK_INTERVAL=999999 FM_HEARTBEAT=999999 "$WATCH" > "$out" & pid=$! - wait_for_exit "$pid" 100 || { reap "$pid"; fail "a declared pause past the long cadence was never rechecked"; } + wait_for_exit "$pid" || { reap "$pid"; fail "a declared pause past the long cadence was never rechecked"; } grep -F "awaiting external" "$out" >/dev/null || fail "the recheck was not labeled a declared-pause recheck: $(cat "$out")" grep -F "possible wedge" "$out" >/dev/null && fail "a declared pause on a busy pane was mislabeled a possible wedge: $(cat "$out")" [ -e "$state/.paused-resurfaced-$key" ] || fail "the declared-pause re-surface throttle was cleared by the busy-turn bound" @@ -2851,7 +2850,7 @@ test_busy_declared_pause_is_rechecked_not_wedge_escalated() { FM_POLL=1 FM_SIGNAL_GRACE=1 \ FM_CHECK_INTERVAL=999999 FM_HEARTBEAT=999999 "$WATCH" > "$out" & pid=$! - wait_for_exit "$pid" 100 || { reap "$pid"; fail "a lifted pause on an over-age busy pane no longer wedge-escalates"; } + wait_for_exit "$pid" || { reap "$pid"; fail "a lifted pause on an over-age busy pane no longer wedge-escalates"; } grep -F "possible wedge" "$out" >/dev/null || fail "the restored busy-turn escalation did not flag a possible wedge: $(cat "$out")" pass "a busy pane under a declared pause is rechecked on the long cadence, and lifting the pause restores the wedge escalation" } @@ -3155,10 +3154,11 @@ test_nonterminal_stale_repairs_missing_or_corrupt_timer() { # point is that only the worktree evidence differs: writing defers, silent # escalates on the unchanged schedule. # Every wait below is the file's standard one (wait_poll_cycle for an absorbing -# watcher, a 100-tick wait_for_exit for an escalating one), because the poll these -# tests assert on is the ONE poll that spawns the bounded worktree walk: on a -# loaded runner it outlives a fixed liveness budget, and a round reaped before it -# finished reports a lost deferral instead of the deferral under test. +# watcher, the default wait_for_exit budget for an escalating one), because the +# poll these tests assert on is the ONE poll that spawns the bounded worktree +# walk: on a loaded runner it outlives a fixed liveness budget, and a round +# reaped before it finished reports a lost deferral instead of the deferral +# under test. 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" @@ -3212,7 +3212,7 @@ test_wedge_escalation_deferred_while_worktree_is_written() { FM_PAUSE_RESURFACE_SECS=999 FM_POLL=1 FM_SIGNAL_GRACE=1 \ FM_CHECK_INTERVAL=999999 FM_HEARTBEAT=999999 "$WATCH" > "$out" & pid=$! - wait_for_exit "$pid" 100 || fail "a stalled crew that wrote nothing did not wedge-escalate on the existing schedule" + wait_for_exit "$pid" || fail "a stalled crew that wrote nothing did not wedge-escalate on the existing schedule" grep -F "stale: $window" "$out" >/dev/null || fail "the stalled-crew escalation did not print a stale wake" grep -F "possible wedge" "$out" >/dev/null || fail "the stalled-crew escalation did not flag a possible wedge" [ "$(cat "$state/.wedge-escalations-$key" 2>/dev/null || true)" = 1 ] || fail "the stalled-crew escalation was not counted" @@ -3255,7 +3255,7 @@ test_write_deferral_resurfaces_on_the_bounded_cadence() { FM_PAUSE_RESURFACE_SECS=240 FM_POLL=1 FM_SIGNAL_GRACE=1 \ FM_CHECK_INTERVAL=999999 FM_HEARTBEAT=999999 "$WATCH" > "$out" & pid=$! - wait_for_exit "$pid" 100 || fail "a long-running write deferral never re-surfaced on the bounded cadence" + wait_for_exit "$pid" || fail "a long-running write deferral never re-surfaced on the bounded cadence" grep -F "stale: $window" "$out" >/dev/null || fail "the write-deferral recheck did not print a stale wake" grep -F "writing its worktree" "$out" >/dev/null || fail "the write-deferral recheck was not labeled as such" grep -F "possible wedge" "$out" >/dev/null && fail "a write-deferral recheck was mislabeled a possible wedge" @@ -3305,7 +3305,7 @@ test_secondmate_home_supervision_churn_is_not_write_evidence() { FM_STALE_ESCALATE_SECS=240 FM_BUSY_TURN_MAX_SECS=1 FM_PAUSE_RESURFACE_SECS=999 \ FM_POLL=1 FM_SIGNAL_GRACE=1 FM_CHECK_INTERVAL=999999 FM_HEARTBEAT=999999 "$WATCH" > "$out" & pid=$! - wait_for_exit "$pid" 100 || fail "a mate home's own supervision churn deferred an escalation it must not defer" + wait_for_exit "$pid" || fail "a mate home's own supervision churn deferred an escalation it must not defer" grep -F "stale: $window" "$out" >/dev/null || fail "the mate-home escalation did not print a stale wake" grep -F "possible wedge" "$out" >/dev/null || fail "the mate-home escalation did not flag a possible wedge" [ ! -e "$state/.writing-since-$key" ] || fail "a mate's provisioned home was probed as if it were a code tree" @@ -3441,7 +3441,7 @@ test_terminal_first_sight_drops_a_finished_write_deferral_chain() { FM_STALE_ESCALATE_SECS=999 FM_PAUSE_RESURFACE_SECS=240 FM_POLL=1 FM_SIGNAL_GRACE=1 \ FM_CHECK_INTERVAL=999999 FM_HEARTBEAT=999999 "$WATCH" > "$out" & pid=$! - wait_for_exit "$pid" 100 || fail "a first-sight captain-relevant status was not surfaced" + wait_for_exit "$pid" || fail "a first-sight captain-relevant status was not surfaced" grep -F "stale: $window" "$out" >/dev/null || fail "the first-sight surface did not print a stale wake" [ ! -e "$state/.writing-since-$key" ] \ || fail "the first-sight surface kept a finished write-deferral chain" @@ -3546,7 +3546,7 @@ test_procevent_captured_result_surfaces_proactively() { procevent_watch_bg "$dir" "$out" pid=$! - wait_for_exit "$pid" 100 \ + wait_for_exit "$pid" \ || fail "a healthy watcher never surfaced a durably captured process-event result: $(cat "$out")" grep -F "check:" "$out" >/dev/null \ || fail "the process-event wake was not reported as an actionable check: $(cat "$out")" @@ -3570,7 +3570,7 @@ test_procevent_unacknowledged_result_redrains_until_handled() { procevent_watch_bg "$dir" "$out" pid=$! - wait_for_exit "$pid" 100 || fail "the first proactive wake never happened: $(cat "$out")" + wait_for_exit "$pid" || fail "the first proactive wake never happened: $(cat "$out")" FM_STATE_OVERRIDE="$state" "$DRAIN" >/dev/null 2>&1 || fail "drain after the first process-event wake failed" # An interrupted handler leaves the captured result durable. The successor @@ -3578,7 +3578,7 @@ test_procevent_unacknowledged_result_redrains_until_handled() { : > "$out" procevent_watch_bg "$dir" "$out" pid=$! - wait_for_exit "$pid" 100 \ + wait_for_exit "$pid" \ || fail "an unacknowledged process-event result was not re-surfaced on re-arm: $(cat "$out")" grep -F 'check: rearm-resurface' "$out" >/dev/null \ || fail "the successor did not report recovery for the unacknowledged result: $(cat "$out")" @@ -3616,7 +3616,7 @@ test_procevent_marker_keys_are_injective() { append_wake "$state" check "procevent:a_b:1" "check: procevent fixture a_b 1" procevent_watch_bg "$dir" "$out" pid=$! - wait_for_exit "$pid" 100 || fail "colliding-looking process-event keys were not surfaced" + wait_for_exit "$pid" || fail "colliding-looking process-event keys were not surfaced" grep -F "procevent:a.b:1" "$out" >/dev/null || fail "the dotted queue key was suppressed" grep -F "procevent:a_b:1" "$out" >/dev/null || fail "the underscored queue key was suppressed" marker_count=$(find "$state" -maxdepth 1 -name '.seen-procevent-*' -type f | awk 'END { print NR + 0 }') @@ -3683,34 +3683,34 @@ test_procevent_surface_crash_boundaries() { FM_CHECK_INTERVAL=999999 FM_HEARTBEAT=999999 "$WATCH" > "$fifo" & pid=$! wait "$reader" || true - wait_for_exit "$pid" 100 + wait_for_exit "$pid" exit_status=$? [ "$exit_status" -ne 124 ] || fail "the watcher survived a failed actionable output write" marker=$(find "$state" -maxdepth 1 -name '.seen-procevent-*' -type f | head -1) [ -z "$marker" ] || fail "failed output committed a suppression marker" [ -s "$state/.wake-queue" ] || fail "failed output consumed the durable queue record" procevent_watch_bg "$dir" "$out"; pid=$! - wait_for_exit "$pid" 100 || fail "the record was not replayable after output failure" + wait_for_exit "$pid" || fail "the record was not replayable after output failure" grep -F "procevent:output-fail:1" "$out" >/dev/null || fail "output failure lost proactive replay" dir=$(make_case procevent-before-marker); state="$dir/state"; out="$dir/watch.out" append_wake "$state" check "procevent:before-marker:1" "check: procevent fixture before-marker 1" install_marker_mv_fault "$dir" FM_MARKER_MV_MODE=kill-before procevent_watch_bg "$dir" "$out"; pid=$! - wait_for_exit "$pid" 100 + wait_for_exit "$pid" exit_status=$? [ "$exit_status" -ne 124 ] || fail "the watcher survived the injected pre-marker crash" grep -F "procevent:before-marker:1" "$out" >/dev/null || fail "the pre-marker crash happened before output" marker=$(find "$state" -maxdepth 1 -name '.seen-procevent-*' -type f | head -1) [ -z "$marker" ] || fail "a pre-marker crash committed suppression" procevent_watch_bg "$dir" "$out.replay"; pid=$! - wait_for_exit "$pid" 100 || fail "a pre-marker crash was not replayable" + wait_for_exit "$pid" || fail "a pre-marker crash was not replayable" dir=$(make_case procevent-after-marker); state="$dir/state"; out="$dir/watch.out" append_wake "$state" check "procevent:after-marker:1" "check: procevent fixture after-marker 1" install_marker_mv_fault "$dir" FM_MARKER_MV_MODE=kill-after procevent_watch_bg "$dir" "$out"; pid=$! - wait_for_exit "$pid" 100 + wait_for_exit "$pid" exit_status=$? [ "$exit_status" -ne 124 ] || fail "the watcher survived the injected post-marker crash" grep -F "procevent:after-marker:1" "$out" >/dev/null || fail "the post-marker crash lost actionable output" @@ -3718,7 +3718,7 @@ test_procevent_surface_crash_boundaries() { [ -n "$marker" ] || fail "the post-marker crash did not reach marker commit" : > "$out.replay" procevent_watch_bg "$dir" "$out.replay"; pid=$! - wait_for_exit "$pid" 100 \ + wait_for_exit "$pid" \ || fail "an unacknowledged delivered record was not re-surfaced on re-arm: $(cat "$out.replay")" grep -F 'check: rearm-resurface' "$out.replay" >/dev/null \ || fail "the successor did not recover the delivered-but-unacknowledged record: $(cat "$out.replay")" @@ -3744,7 +3744,7 @@ test_procevent_marker_failure_exits_and_replays() { install_marker_mv_fault "$dir" FM_MARKER_MV_MODE=fail procevent_watch_bg "$dir" "$out" pid=$! - wait_for_exit "$pid" 100 || fail "marker failure did not end the actionable watcher cycle successfully" + wait_for_exit "$pid" || fail "marker failure did not end the actionable watcher cycle successfully" output_count=$(grep -Fc "procevent:marker-failure:1" "$out" || true) [ "$output_count" = 1 ] || fail "marker failure printed the actionable reason $output_count times" marker=$(find "$state" -maxdepth 1 -name '.seen-procevent-*' -type f | head -1) @@ -3753,7 +3753,7 @@ test_procevent_marker_failure_exits_and_replays() { || fail "marker failure left the queue lock held" procevent_watch_bg "$dir" "$out.replay" pid=$! - wait_for_exit "$pid" 100 || fail "marker failure did not leave the durable record replayable" + wait_for_exit "$pid" || fail "marker failure did not leave the durable record replayable" grep -F "procevent:marker-failure:1" "$out.replay" >/dev/null \ || fail "marker failure lost the later proactive replay" FM_STATE_OVERRIDE="$state" "$DRAIN" >/dev/null 2>&1 || fail "marker-failure fixture drain failed" @@ -3806,7 +3806,7 @@ test_heartbeat_backstop_surfaces_a_masked_status() { PATH="$fakebin:$PATH" FM_STATE_OVERRIDE="$state" FM_POLL=1 FM_SIGNAL_GRACE=1 \ FM_CHECK_INTERVAL=999999 FM_HEARTBEAT=1 "$WATCH" > "$out" & pid=$! - wait_for_exit "$pid" 100 \ + wait_for_exit "$pid" \ || fail "heartbeat backstop missed a decision hidden behind a later working: line" grep -Fx "heartbeat" "$out" >/dev/null || fail "backstop did not exit with a heartbeat wake" [ "$(status_presentation_marker_offset "$state/.hb-surfaced-miss" "$state/miss.status")" = \ @@ -3828,7 +3828,7 @@ test_heartbeat_backstop_surfaces_unsurfaced_status() { PATH="$fakebin:$PATH" FM_STATE_OVERRIDE="$state" FM_POLL=1 FM_SIGNAL_GRACE=1 \ FM_CHECK_INTERVAL=999999 FM_HEARTBEAT=1 "$WATCH" > "$out" & pid=$! - wait_for_exit "$pid" 100 || fail "heartbeat backstop did not surface an unsurfaced captain-relevant status" + wait_for_exit "$pid" || fail "heartbeat backstop did not surface an unsurfaced captain-relevant status" grep -Fx "heartbeat" "$out" >/dev/null || fail "backstop did not exit with a heartbeat wake" [ "$(status_presentation_marker_offset "$state/.hb-surfaced-miss" "$state/miss.status")" = \ "$(size_of "$state/miss.status")" ] \ @@ -3882,7 +3882,7 @@ test_afk_signal_records_heartbeat_endpoint() { export FM_FAKE_CREW_STATE='state: working · source: run-step · validating (running)' watch_bg "$state" "$fakebin" "$out" pid=$! - wait_for_exit "$pid" 100 || fail "afk watcher did not hand the actionable signal to the daemon" + wait_for_exit "$pid" || fail "afk watcher did not hand the actionable signal to the daemon" [ "$(status_presentation_marker_offset "$state/.hb-surfaced-task" "$status_file")" = \ "$(size_of "$status_file")" ] \ || fail "afk signal did not record the endpoint handed to the daemon" @@ -3903,7 +3903,7 @@ test_afk_present_reverts_watcher_to_one_shot() { export FM_FAKE_CREW_STATE='state: working · source: run-step · validating (running)' watch_bg "$state" "$fakebin" "$out" pid=$! - wait_for_exit "$pid" 100 || fail "with .afk present the watcher did not exit one-shot for a benign signal" + wait_for_exit "$pid" || fail "with .afk present the watcher did not exit one-shot for a benign signal" grep -F "signal: $status_file" "$out" >/dev/null || fail "afk-mode watcher did not surface the signal for the daemon" FM_STATE_OVERRIDE="$state" "$DRAIN" > "$drain_out" 2>/dev/null || fail "drain after the afk-mode signal failed" grep "$(printf '\tsignal\t')" "$drain_out" | grep -F "$status_file" >/dev/null \ @@ -3937,7 +3937,7 @@ test_afk_paused_changed_pane_hands_off_plain_stale() { FM_STATE_OVERRIDE="$state" FM_CREW_STATE_BIN="$fakebin/fm-crew-state.sh" FM_PAUSE_RESURFACE_SECS=240 FM_POLL=0.2 FM_SIGNAL_GRACE=1 \ FM_CHECK_INTERVAL=999999 FM_HEARTBEAT=999999 "$WATCH" > "$out" & pid=$! - wait_for_exit "$pid" 100 || fail "AFK paused changed pane did not hand off a stale wake" + wait_for_exit "$pid" || fail "AFK paused changed pane did not hand off a stale wake" grep -Fx "stale: $window" "$out" >/dev/null || fail "AFK paused stale did not preserve its plain window identity: $(cat "$out")" grep -F "awaiting external" "$out" >/dev/null && fail "AFK watcher decorated a stale identity instead of handing it to the daemon" [ ! -e "$state/.paused-$key" ] || fail "AFK watcher recorded normal-mode pause tracking instead of handing off" diff --git a/tests/lib.sh b/tests/lib.sh index 1f3ce7d1262..878dfbc9bdd 100644 --- a/tests/lib.sh +++ b/tests/lib.sh @@ -99,6 +99,14 @@ fm_test_cleanup() { fm_test_tmproot() { local prefix=${1:-fm-test} root root=$(mktemp -d "${TMPDIR:-/tmp}/${prefix}.XXXXXX") || return 1 + # Hand back the PHYSICAL path. On macOS $TMPDIR is /var/folders/... and /var + # is a symlink to private/var, so every fixture built under the name mktemp + # returns is reached through a symlink - which a real firstmate home never is. + # Production code that refuses a state root reachable through a symlink (the + # process-event claim's state-root identity in bin/fm-procevent-lib.sh) then + # rejects the fixture itself, and the suite reports the refusal as a product + # failure on macOS while passing on Linux, where /tmp is a real directory. + root=$(cd -P -- "$root" && pwd -P) || return 1 if ! printf '%s\n%s\n' "$$" "$FM_TEST_OWNER_IDENTITY" > "$root/.fm-test-fixture" || ! printf '%s\n' "$root" >> "$FM_TEST_CLEANUP_REGISTRY"; then rm -rf "$root" @@ -313,3 +321,56 @@ assert_absent() { assert_present() { [ -e "$1" ] || fail "$2" } + +# --- fixture process helpers ------------------------------------------------ + +# is_live_non_zombie : true while is a running process, false once it +# is gone or has already exited and is only waiting to be collected. `kill -0` +# alone cannot tell those apart - a zombie still answers it - so a bounded wait +# built on `kill -0` would spend its whole budget on a process that is already +# finished. +is_live_non_zombie() { + local pid=$1 stat + kill -0 "$pid" 2>/dev/null || return 1 + stat=$(ps -p "$pid" -o stat= 2>/dev/null || true) + case "$stat" in + Z*) return 1 ;; + esac + return 0 +} + +# reap [ticks]: stop a fixture process and collect it, within a bound. +# This is the single owner of how these suites stop a process they spawned. +# +# `kill; wait` is the obvious spelling and it is unbounded, which matters here +# because the process being stopped is usually bin/fm-watch.sh, and a watcher +# leaves through an EXIT trap that itself takes a lock. Signal one while that +# lock is contended and it can sit in its own exit path indefinitely; the `wait` +# then hangs with it, taking the whole suite down with no failing assertion and +# no output naming the case it stopped in. That was observed once as a run that +# had to be killed from outside after 900 seconds. +# +# So: ask, allow tenth-seconds to leave, then insist. SIGKILL cannot be +# trapped, so the bound holds whatever the exit path is doing. Most callers only +# need this as cleanup that runs after a case has already made its assertions, +# but some (fm-watch-triage.test.sh's ack_stopped_cycle) rely on the EXIT trap +# itself completing - it is what publishes the downtime recovery marker a later +# drain must acknowledge - so an escalation to SIGKILL there does not just skip +# cleanup, it erases real trap-side effects the next assertion depends on. The +# default is therefore the same 10s standard budget wait_for_exit uses (see its +# comment for the measurement): both bound the same fm-watch.sh, under the same +# CI load, doing comparably-sized bounded work (recovery-marker snapshot and +# lock acquisition on the way in, the same marker's transition on the way out). +# A tighter bound here would reap a watcher still finishing its exit trap and +# report a spurious downstream failure instead of a real one. +reap() { + local pid=$1 limit=${2:-100} i=0 + kill "$pid" 2>/dev/null || true + while [ "$i" -lt "$limit" ]; do + is_live_non_zombie "$pid" || break + sleep 0.1 + i=$((i + 1)) + done + kill -9 "$pid" 2>/dev/null || true + wait "$pid" 2>/dev/null || true +} diff --git a/tests/wake-helpers.sh b/tests/wake-helpers.sh index da83bb3dc91..0fa895def26 100644 --- a/tests/wake-helpers.sh +++ b/tests/wake-helpers.sh @@ -296,8 +296,20 @@ SH printf '%s\n' "$dir" } +# wait_for_exit [ticks]: wait up to tenth-seconds for a one-shot +# watcher to exit, returning its exit status, or 124 after reaping it. +# +# The standard budget is 100 ticks (10s), and this is the single owner of why: +# not because any watcher takes that long to decide, but because fm-watch.sh +# does bounded startup work before its first poll, and one poll of that work +# was measured at 1.1s idle and 2.5s on a machine at load 18. A budget close to +# that cost reaps the process while it is still starting and reports a spurious +# "did not surface" failure. A generous budget can only remove that false +# negative - a watcher that never surfaces its wake still fails its assertion +# when the budget runs out - so a case needs a reason to go below the standard, +# never a reason to reach it. wait_for_exit() { - local pid=$1 limit=${2:-50} i=0 + local pid=$1 limit=${2:-100} i=0 while [ "$i" -lt "$limit" ]; do if ! is_live_non_zombie "$pid"; then wait "$pid" @@ -306,21 +318,13 @@ wait_for_exit() { sleep 0.1 i=$((i + 1)) done - kill "$pid" 2>/dev/null || true - wait "$pid" 2>/dev/null || true + # Out of budget: stop it through the bounded reaper in tests/lib.sh rather + # than an unbounded wait, so a watcher stuck in its own exit path reports 124 + # here instead of hanging the suite. + reap "$pid" return 124 } -is_live_non_zombie() { - local pid=$1 stat - kill -0 "$pid" 2>/dev/null || return 1 - stat=$(ps -p "$pid" -o stat= 2>/dev/null || true) - case "$stat" in - Z*) return 1 ;; - esac - return 0 -} - hash_text() { if command -v md5 >/dev/null 2>&1; then printf '%s' "$1" | md5 -q