Skip to content

test(watcher): de-flake and leak-proof the watcher-lock suite - #904

Open
mattwwatson wants to merge 3 commits into
kunchenguid:mainfrom
mattwwatson:up/watcher-lock-deflake
Open

test(watcher): de-flake and leak-proof the watcher-lock suite#904
mattwwatson wants to merge 3 commits into
kunchenguid:mainfrom
mattwwatson:up/watcher-lock-deflake

Conversation

@mattwwatson

Copy link
Copy Markdown

Intent

Upstream contribution from the mattwwatson/firstmate fork: de-flake and leak-proof the watcher-lock test suite at the root. Peer watcher starts are now exec-confirmed with durable-file synchronization instead of sleeps, a self-checking bash peer, and an injectable FM_ARM_CONFIRM_TIMEOUT; tests/lib.sh gains file-backed pid and temp registries with a home-scoped reaper (fm_test_track_pid) so no failure path leaks background processes or holds a temp home's watcher lock, and CONTRIBUTING.md documents the convention (nothing reaped by process-name pattern). The CONTRIBUTING.md paragraph was hand-merged onto the current upstream testing-docs rewrite, keeping upstream's fm-test-run.sh section intact and appending only the two new convention sentences. Suite passes 28/28 locally on the upstream base.

What Changed

  • Replaced sleep-based peer-watcher startup in the watcher-lock suite with exec-confirmed durable-file synchronization: a self-checking bash peer, an injectable FM_ARM_CONFIRM_TIMEOUT, and an fm-watch-arm.sh tweak that surfaces the finished child's stand-down output before the successor-confirmation wait so tests can synchronize on it.
  • Added file-backed pid and temp-dir registries to tests/lib.sh (stored in a private mktemp -d directory) with a home-scoped reaper via fm_test_track_pid, so failing test paths no longer leak background processes or hold a temp home's watcher lock — nothing is reaped by process-name pattern. Suites that install custom EXIT traps now drain these registries in their own cleanup.
  • Documented the process-tracking convention in CONTRIBUTING.md, appending two sentences to the existing fm-test-run.sh testing section. Suite verified 28/28 across three consecutive runs in the pipeline, including its built-in no-leaked-process/no-held-lock audit.

Risk Assessment

✅ Low: The final commit cleanly closes the round-2 registry-dir leak by adding idempotent, exit-status-preserving fm_test_cleanup calls to the exact three non-conforming suites, and the full branch now satisfies every stated intent criterion with no outstanding source findings.

Testing

Ran the watcher-lock suite three times through the canonical runner (28/28 each, no flakes), ran the three other touched suites (pass/clean self-skip), and demonstrated the leak-proofing end-to-end with a fail()-aborted real-arm demo (children reaped, lock released, 5s pipe EOF) against a pre-change contrast that hung the pipe 76s; before/after audits show zero leaked processes or temp dirs and the user's real watcher untouched. No UI surface — this is CLI/test infrastructure, so transcripts are the reviewer-visible evidence.

Evidence: watcher-lock suite run 1 transcript (28/28 ok)
FM_TEST_BEGIN 2026-07-23T09:11:05Z tests/fm-watcher-lock.test.sh family=watcher-wake-lock expected_gate_skip=none
ok - simultaneous watcher starts leave exactly one live process
ok - fm_pid_identity is locale-invariant across LC_ALL/LC_TIME
ok - Linux process identity clock-step regression skipped on non-Linux host
ok - killed watcher stale lock is reclaimed
ok - live watcher lock with stale heartbeat is actionable
ok - guard banner leads when down with pending wakes (repair-after-drain) and stays silent when fresh
ok - concurrent fm_lock_try_acquire yields exactly one winner
ok - dead-pid stale lock is reclaimed by a single acquirer
ok - concurrent stale-lock steal yields exactly one winner
ok - live steal mutex is not reclaimed
ok - live-held lock is not stolen
ok - empty mid-acquire lock keeps a minimum grace
ok - late original claimant cannot claim a recreated lock
ok - paused mid-acquire claimant backs off to active stealer
ok - watch restart refuses to signal a reused pid
ok - watch restart attaches to a verified healthy peer and later surfaces a successor gap
ok - watcher self-evicts when the lock pid no longer names it
ok - arm turns clean self-eviction without a successor into a typed failure
ok - arm attaches to a live fresh watcher and fails loudly when that cycle has no successor
ok - attached arm signals record a classified lifecycle entry
ok - arm starts+confirms a fresh watcher on a clean lock and self-heals a dead-pid lock (never healthy off a dead pid)
ok - arm cleans child watcher and temp output on HUP
ok - arm propagates an immediate watcher wake before confirmation
ok - arm attaches to a peer watcher after child stands down and surfaces a missing successor
watcher: lock held by live pid 46486 but heartbeat is stale for 838152738s (>300s); inspect or stop that watcher before re-arming.
ok - arm reports FAILED and exits non-zero when no fresh watcher can be confirmed
ok - cycle-exit ledger links a verified successor and remains size-capped
ok - SIGSTOP distinguishes live PID from stale beacon and termination records the exit class
ok - every case leaves no background process and no watcher holding a temp home lock
FM_TEST_END 2026-07-23T09:13:06Z tests/fm-watcher-lock.test.sh exit=0 duration_ms=121237 gate_skip=false
FM_TEST_SUMMARY total=1 failed=0 skipped_gate=0 duration_ms=121336
FM_TEST_SUMMARY_FAMILY family=watcher-wake-lock count=1 duration_ms=121237 failed=0
FM_TEST_SLOWEST rank=1 script=tests/fm-watcher-lock.test.sh duration_ms=121237
Evidence: watcher-lock suite run 2 transcript (28/28 ok)
FM_TEST_BEGIN 2026-07-23T09:13:50Z tests/fm-watcher-lock.test.sh family=watcher-wake-lock expected_gate_skip=none
ok - simultaneous watcher starts leave exactly one live process
ok - fm_pid_identity is locale-invariant across LC_ALL/LC_TIME
ok - Linux process identity clock-step regression skipped on non-Linux host
ok - killed watcher stale lock is reclaimed
ok - live watcher lock with stale heartbeat is actionable
ok - guard banner leads when down with pending wakes (repair-after-drain) and stays silent when fresh
ok - concurrent fm_lock_try_acquire yields exactly one winner
ok - dead-pid stale lock is reclaimed by a single acquirer
ok - concurrent stale-lock steal yields exactly one winner
ok - live steal mutex is not reclaimed
ok - live-held lock is not stolen
ok - empty mid-acquire lock keeps a minimum grace
ok - late original claimant cannot claim a recreated lock
ok - paused mid-acquire claimant backs off to active stealer
ok - watch restart refuses to signal a reused pid
ok - watch restart attaches to a verified healthy peer and later surfaces a successor gap
ok - watcher self-evicts when the lock pid no longer names it
ok - arm turns clean self-eviction without a successor into a typed failure
ok - arm attaches to a live fresh watcher and fails loudly when that cycle has no successor
ok - attached arm signals record a classified lifecycle entry
ok - arm starts+confirms a fresh watcher on a clean lock and self-heals a dead-pid lock (never healthy off a dead pid)
ok - arm cleans child watcher and temp output on HUP
ok - arm propagates an immediate watcher wake before confirmation
ok - arm attaches to a peer watcher after child stands down and surfaces a missing successor
watcher: lock held by live pid 65710 but heartbeat is stale for 838152901s (>300s); inspect or stop that watcher before re-arming.
ok - arm reports FAILED and exits non-zero when no fresh watcher can be confirmed
ok - cycle-exit ledger links a verified successor and remains size-capped
ok - SIGSTOP distinguishes live PID from stale beacon and termination records the exit class
ok - every case leaves no background process and no watcher holding a temp home lock
FM_TEST_END 2026-07-23T09:15:49Z tests/fm-watcher-lock.test.sh exit=0 duration_ms=119233 gate_skip=false
FM_TEST_SUMMARY total=1 failed=0 skipped_gate=0 duration_ms=119426
FM_TEST_SUMMARY_FAMILY family=watcher-wake-lock count=1 duration_ms=119233 failed=0
FM_TEST_SLOWEST rank=1 script=tests/fm-watcher-lock.test.sh duration_ms=119233
Evidence: watcher-lock suite run 3 transcript (28/28 ok)
FM_TEST_BEGIN 2026-07-23T09:15:50Z tests/fm-watcher-lock.test.sh family=watcher-wake-lock expected_gate_skip=none
ok - simultaneous watcher starts leave exactly one live process
ok - fm_pid_identity is locale-invariant across LC_ALL/LC_TIME
ok - Linux process identity clock-step regression skipped on non-Linux host
ok - killed watcher stale lock is reclaimed
ok - live watcher lock with stale heartbeat is actionable
ok - guard banner leads when down with pending wakes (repair-after-drain) and stays silent when fresh
ok - concurrent fm_lock_try_acquire yields exactly one winner
ok - dead-pid stale lock is reclaimed by a single acquirer
ok - concurrent stale-lock steal yields exactly one winner
ok - live steal mutex is not reclaimed
ok - live-held lock is not stolen
ok - empty mid-acquire lock keeps a minimum grace
ok - late original claimant cannot claim a recreated lock
ok - paused mid-acquire claimant backs off to active stealer
ok - watch restart refuses to signal a reused pid
ok - watch restart attaches to a verified healthy peer and later surfaces a successor gap
ok - watcher self-evicts when the lock pid no longer names it
ok - arm turns clean self-eviction without a successor into a typed failure
ok - arm attaches to a live fresh watcher and fails loudly when that cycle has no successor
ok - attached arm signals record a classified lifecycle entry
ok - arm starts+confirms a fresh watcher on a clean lock and self-heals a dead-pid lock (never healthy off a dead pid)
ok - arm cleans child watcher and temp output on HUP
ok - arm propagates an immediate watcher wake before confirmation
ok - arm attaches to a peer watcher after child stands down and surfaces a missing successor
watcher: lock held by live pid 95414 but heartbeat is stale for 838153023s (>300s); inspect or stop that watcher before re-arming.
ok - arm reports FAILED and exits non-zero when no fresh watcher can be confirmed
ok - cycle-exit ledger links a verified successor and remains size-capped
ok - SIGSTOP distinguishes live PID from stale beacon and termination records the exit class
ok - every case leaves no background process and no watcher holding a temp home lock
FM_TEST_END 2026-07-23T09:17:52Z tests/fm-watcher-lock.test.sh exit=0 duration_ms=121856 gate_skip=false
FM_TEST_SUMMARY total=1 failed=0 skipped_gate=0 duration_ms=121931
FM_TEST_SUMMARY_FAMILY family=watcher-wake-lock count=1 duration_ms=121856 failed=0
FM_TEST_SLOWEST rank=1 script=tests/fm-watcher-lock.test.sh duration_ms=121856
Evidence: Fail-path leak demo transcript — tracked arm+watcher reaped after mid-case fail(), lock released, 5s pipe EOF

demo exit=1 (expected nonzero: fail() aborted the case) seconds-to-EOF=5 (a leaked child would hold the pipe open and hang this read) arm pid 65278: gone (reaped) watcher grandchild pid 65293: gone (reaped) temp root .../fm-leak-demo.lDnZPj: removed (watcher lock released with it)

== driver: run fail-path demo, reading its output to EOF (the hang symptom) ==
demo exit=1 (expected nonzero: fail() aborted the case)
seconds-to-EOF=5 (a leaked child would hold the pipe open and hang this read)
demo output: not ok - simulated mid-case assertion failure (arm=65278 watcher=65293 still live)

== recorded live pids at moment of failure ==
arm=65278 watcher=65293 tmp_root=/var/folders/mz/9drvc3ms7w9c8vzk0j1gj2vm0000gp/T//fm-leak-demo.lDnZPj

== after exit: are they reaped? ==
  PID COMMAND
arm pid 65278: gone (reaped)
  PID COMMAND
watcher grandchild pid 65293: gone (reaped)
temp root /var/folders/mz/9drvc3ms7w9c8vzk0j1gj2vm0000gp/T//fm-leak-demo.lDnZPj: removed (watcher lock released with it)
Evidence: Pre-change contrast transcript — untracked children held the output pipe 76s past the abort
== driver: run OLD-STYLE demo (no pid registry), reading output to EOF with a 15s cap ==
driver read returned rc=1 after 76s (142=ALRM: the leaked children held the pipe open past the 15s cap)

== recorded pids at moment of failure ==
arm=71892 watcher=71925

== after the case aborted: still running? ==
  PID 
arm gone
  PID 
watcher gone

== driver cleans up the deliberately leaked fixture pids ==
  PID 
leaked fixtures now cleaned up by driver
Evidence: Fail-path demo script (replicates a watcher-lock case with the new registry convention)
#!/usr/bin/env bash
# Demonstrates the leak-proofing this change adds to tests/lib.sh:
# a watcher-lock-style case starts a REAL fm-watch-arm.sh (which forks a real
# fm-watch.sh grandchild that takes the temp home's singleton lock), registers
# the arm with fm_test_track_pid exactly as the suite does, and then aborts
# mid-case via fail() - the exact path that used to leak the arm + watcher
# forever and hold the suite's stdout pipe open.
#
# Usage: fail-path-leak-demo.sh <worktree> <status-file>
# The status file (outside TMP_ROOT, which the reaper deletes) records the pids
# and temp home so the driver can verify everything was reaped after exit.
set -u
WT=$1
STATUS=$2
# shellcheck source=/dev/null
. "$WT/tests/wake-helpers.sh"
WATCH_ARM="$ROOT/bin/fm-watch-arm.sh"
TMP_ROOT=$(fm_test_tmproot fm-leak-demo)

# Same cleanup convention as tests/fm-watcher-lock.test.sh.
watcher_lock_cleanup() {
  fm_test_reap_tracked_pids
  fm_wake_reap_temp_watchers "$TMP_ROOT"
  fm_test_cleanup
}
trap watcher_lock_cleanup EXIT

dir=$(make_case leak-demo)
state="$dir/state"
fakebin="$dir/fakebin"
armout="$dir/arm.out"
printf '%s\n' fm-pr-check-migration-scan-v1 > "$state/.pr-check-migration-scan-v1"
printf '%s\n' fm-pr-check-migration-v1 > "$state/.pr-check-migration-v1"
chmod 0600 "$state/.pr-check-migration-scan-v1" "$state/.pr-check-migration-v1"

PATH="$fakebin:$PATH" FM_HOME="$dir" FM_STATE_OVERRIDE="$state" FM_POLL=5 \
  FM_SIGNAL_GRACE=1 FM_CHECK_INTERVAL=999999 FM_HEARTBEAT=999999 \
  "$WATCH_ARM" > "$armout" &
armpid=$!
fm_test_track_pid "$armpid"

i=0
while [ "$i" -lt 80 ]; do
  grep -qF 'watcher: started pid=' "$armout" 2>/dev/null && break
  sleep 0.1
  i=$((i + 1))
done
grep -qF 'watcher: started pid=' "$armout" || fail "demo arm never started a watcher"
watcher_pid=$(cat "$state/.watch.lock/pid" 2>/dev/null || true)
printf 'arm=%s watcher=%s tmp_root=%s\n' "$armpid" "$watcher_pid" "$TMP_ROOT" > "$STATUS"

# Abort mid-case with a live arm + live watcher grandchild holding the lock -
# the leak scenario. fail() exits 1; the EXIT trap must reap everything.
fail "simulated mid-case assertion failure (arm=$armpid watcher=$watcher_pid still live)"
Evidence: Other touched suites transcript (tmux 4/4 ok; herdr e2e clean opt-in skips)
FM_TEST_BEGIN 2026-07-23T09:17:59Z tests/fm-tmux-submit-busy.test.sh family=pure-contract-unit expected_gate_skip=none
ok - fm_tmux_submit_enter_core: busy pane + pending composer returns empty (message queued)
ok - fm_tmux_submit_enter_core: idle pane + pending composer stays pending (genuine swallow preserved)
ok - fm_tmux_submit_enter_core: busy pane clears composer on first Enter - returns empty
ok - fm_tmux_submit_enter_core: idle pane clears composer on first Enter - returns empty as before
FM_TEST_END 2026-07-23T09:18:01Z tests/fm-tmux-submit-busy.test.sh exit=0 duration_ms=2526 gate_skip=false
FM_TEST_BEGIN 2026-07-23T09:18:01Z tests/fm-afk-pi-herdr-return-e2e.test.sh family=live-harness-optin expected_gate_skip=optin-env
skip: set FM_AFK_PI_HERDR_E2E=1 to run the real Pi/Herdr away-return regression
FM_TEST_END 2026-07-23T09:18:02Z tests/fm-afk-pi-herdr-return-e2e.test.sh exit=0 duration_ms=107 gate_skip=true
FM_TEST_BEGIN 2026-07-23T09:18:02Z tests/fm-send-secondmate-marker-herdr-e2e.test.sh family=live-harness-optin expected_gate_skip=optin-env
skip: set FM_SEND_MARKER_HERDR_E2E=1 to run the real Pi/Herdr secondmate-marker regression
FM_TEST_END 2026-07-23T09:18:02Z tests/fm-send-secondmate-marker-herdr-e2e.test.sh exit=0 duration_ms=83 gate_skip=true
FM_TEST_SUMMARY total=3 failed=0 skipped_gate=2 duration_ms=2922
FM_TEST_SUMMARY_FAMILY family=live-harness-optin count=2 duration_ms=190 failed=0
FM_TEST_SUMMARY_FAMILY family=pure-contract-unit count=1 duration_ms=2526 failed=0
FM_TEST_SLOWEST rank=1 script=tests/fm-tmux-submit-busy.test.sh duration_ms=2526
FM_TEST_SLOWEST rank=2 script=tests/fm-afk-pi-herdr-return-e2e.test.sh duration_ms=107
FM_TEST_SLOWEST rank=3 script=tests/fm-send-secondmate-marker-herdr-e2e.test.sh duration_ms=83
Evidence: Leak audit: TMPDIR fm-* dirs and watcher processes before/after all runs (zero suite leftovers)
fm-test-registry.LSGxKZ
fm-wake-tangle-root.HEPx5S
fm-wedge-rec.tJ6Rr5

Pipeline

Updates from git push no-mistakes

✅ **intent** - passed

✅ No issues found.

✅ **Rebase** - passed

✅ No issues found.

🔧 **Review** - 2 issues found → auto-fixed (2) ✅
  • ⚠️ tests/lib.sh:85 - The file-backed registries use predictable world-tmp paths (${TMPDIR:-/tmp}/fm-test-cleanup.$$ and fm-test-pids.$$), and fm_test_cleanup later rm -rfs every path read back from the cleanup log (guarded only against empty and /). On a multi-user machine another user can pre-create or symlink those names — sticky-bit /tmp even makes the source-time rm -f of a foreign-owned planted file fail silently — letting planted content steer the rm -rf. The in-code rationale for rejecting mktemp (that an assignment would die inside a command-substitution subshell) does not apply at source time: these variables are assigned when lib.sh is sourced in the main shell, where a mktemp'd path would be equally visible to every subshell; the only real trade-off is the documented lazy-creation/no-stray-file property. Consider a mktemp'd per-process registry directory created at source time (fixed filenames inside, created lazily), which keeps laziness for the files while removing name predictability. Flagged ask-user because the current scheme is explicitly documented as deliberate.
  • ℹ️ bin/fm-watch-arm.sh:418 - A commit scoped test(watcher): changes production behavior in bin/fm-watch-arm.sh: the arm now prints its finished child's output (and deletes the temp file) before spending the successor-confirmation window, so the child's stand-down explanation surfaces up to FM_ARM_CONFIRM_TIMEOUT seconds earlier. I verified the change is safe (wait_for_healthy_successor/healthy_watcher never read child/child_out; the signal handler behaves identically since the child is already reaped on this path; relative stdout order and cycle-ledger timing are unchanged) and it is load-bearing for the new durable-file synchronization in test_arm_waits_for_peer_beacon_after_child_stands_down, which greps the arm's own output for the stand-down line before the beacon exists. Only noting that the commit-type label understates a production output-timing change.

🔧 Fix: harden test registries with private mktemp dir
1 info still open:

  • ℹ️ tests/lib.sh:85 - The round-1 hardening makes the registry directory eager: sourcing tests/lib.sh now always runs mktemp -d (tests/lib.sh:85), so any suite that sources lib.sh but overrides the EXIT trap without calling fm_test_cleanup leaks one small empty registry dir per run. Exactly three suites do this: tests/fm-tmux-submit-busy.test.sh (trap 'rm -rf "$TMP_ROOT"' EXIT), tests/fm-afk-pi-herdr-return-e2e.test.sh (custom cleanup that rm -rfs its own TMP_ROOT but never drains the registries — it already leaked the lazy cleanup-log file under the previous commit since it uses fm_test_tmproot), and tests/fm-send-secondmate-marker-herdr-e2e.test.sh. All three violate the trap convention this branch documents in lib.sh and CONTRIBUTING.md, and the leak is bounded to a tiny OS-reaped tmp dir. Making their traps call fm_test_cleanup is a mechanical follow-up, but it would expand this focused upstream-contribution branch to unrelated suites — asking rather than auto-fixing; deferring entirely is also reasonable.

🔧 Fix: drain test registries in suites with custom EXIT traps
✅ Re-checked - no issues remain.

✅ **Test** - passed

✅ No issues found.

  • bin/fm-test-run.sh tests/fm-watcher-lock.test.sh ×3 consecutive runs — 28/28 ok each, exit=0, including the suite's built-in no-leaked-process/no-held-lock audit case
  • bin/fm-test-run.sh tests/fm-tmux-submit-busy.test.sh tests/fm-afk-pi-herdr-return-e2e.test.sh tests/fm-send-secondmate-marker-herdr-e2e.test.sh — tmux suite 4/4 ok; both herdr e2e suites self-skip cleanly behind their opt-in env gates with the new fm_test_cleanup trap line in place
  • Fail-path leak demo: real fm-watch-arm.sh + watcher grandchild registered via fm_test_track_pid, aborted mid-case with fail() — verified both pids reaped, temp home watcher lock released, and suite output pipe reached EOF in 5s
  • Pre-change contrast demo (untracked pid, dirs-only EXIT trap) — reproduced the old symptom: output pipe held 76s past the abort by lingering arm/watcher before driver cleanup
  • Leak audit: diffed TMPDIR fm-* dirs and fm-watch/fm-watch-arm processes before vs after all runs — zero suite leftovers, TMPDIR restored to exact baseline, user's real-home watcher untouched
  • Reviewed CONTRIBUTING.md diff — two convention sentences appended after upstream's intact fm-test-run.sh testing-docs section
✅ **Document** - passed

✅ No issues found.

✅ **Lint** - passed

✅ No issues found.

✅ **Push** - passed

✅ No issues found.

The watcher-lock suite raced its peer processes (peers were assumed
started without confirmation) and leaked background children on failure
exits, which could hang the suite's output pipe and hold a temp home's
watcher lock. De-flake it at the root: exec-confirmed peer starts,
durable-file synchronization instead of sleeps, a self-checking bash
peer, and an injectable FM_ARM_CONFIRM_TIMEOUT. Leak-proof the harness
with file-backed pid and temp registries in tests/lib.sh plus a
home-scoped reaper (fm_test_track_pid), and document the convention in
CONTRIBUTING.md: nothing is ever reaped by process-name pattern.
@mattwwatson
mattwwatson force-pushed the up/watcher-lock-deflake branch from 0a0d42c to de7c31a Compare July 24, 2026 19:32
@kunchenguid

kunchenguid commented Jul 29, 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#904 at de7c31a0.

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