Conversation
…kiness
tests/fm-wake-queue.test.sh and tests/fm-watch-triage.test.sh failed
intermittently, and deterministically in some environments, for three
unrelated reasons. Each is fixed at its cause rather than absorbed with a
sleep or a retry, and no assertion is weakened.
1. Fixture roots were reached through a symlink. On macOS $TMPDIR is
/var/folders/... and /var is a symlink to private/var, so every fixture
mktemp named was reached through one. The process-event claim deliberately
refuses a state root in that shape, so it refused the fixture itself and
the suite reported the refusal as a product failure - on macOS only, since
Linux /tmp is a real directory. fm_test_tmproot now hands back the
physical path. This also repairs tests/fm-procevent.test.sh (2 ok -> 62).
2. Lock reclaim could not tell a subshell from its parent. The reclaim branch
asked [ "$pid" = "${BASHPID:-$$}" ]; stock bash 3.2 has no BASHPID and its
$$ is identical in every subshell, so a subshell looked exactly like an
abandoned frame of its own parent and took the lock the parent still held.
fm_pid_is_this_frame now owns that question: BASHPID where it exists, and
otherwise $$ only in the main shell, the one frame BASH_SUBSHELL proves has
no subshell to be confused with. Behavior on any bash 4+ is unchanged.
3. The one-shot watcher exit budget sat below the work inside its own window.
fm-watch.sh does bounded startup work before its first poll, measured at
1.1s idle and 2.5s under load, against a 4s budget - so a slow machine
reaped a watcher that was still starting and reported a spurious "did not
surface". wait_for_exit now owns the standard budget and the reason for it.
A fourth cause surfaced while proving the above: the fixtures' stop-and-collect
was unbounded. `kill; wait` on bin/fm-watch.sh, which exits through a trap that
itself takes a lock, hangs indefinitely when that lock is contended - observed
as a run killed from outside at 900s with no failing assertion and no line
naming the case. tests/lib.sh now owns one bounded reap that escalates to a
signal that cannot be trapped, so a wedged exit path costs a bounded wait and a
reported result. The two verbatim copies of the old spelling are replaced by it.
CI's stock macOS Bash lane now runs the frame-identity regression under real
/bin/bash 3.2, so the half of that contract the Linux lanes cannot reach is
enforced rather than assumed.
…serial 4": tests/fm-watch-triage.test.sh failed with "not ok - could not acknowledge the intentional phase-A watcher stop" inside test_wedge_escalation_deferred_while_worktree_is_written. Root cause found: tests/lib.sh's reap() helper (newly introduced in this same PR's prior commit) uses a 5-second SIGTERM-then-SIGKILL budget to stop a fixture fm-watch.sh process. That test relies on fm-watch.sh's EXIT trap (watcher_cleanup) completing gracefully, since it publishes the downtime recovery marker that ack_stopped_cycle's later drain call must find and acknowledge. Under CI load, 5s was sometimes too tight (matches wait_for_exit's own documented finding that fm-watch.sh's bounded internal work needs headroom on a loaded runner, which is why wait_for_exit already uses a 10s "standard budget"), causing reap() to escalate to SIGKILL and cut off the exit trap before it could publish the marker, so ack_stopped_cycle found nothing to acknowledge and the test failed. Fix applied: bumped reap()'s default tick budget from 50 to 100 (5s -> 10s) in tests/lib.sh, matching the already-established standard budget, with an updated comment explaining why. This is a minimal, one-line functional change (plus comment). Verified: shellcheck-clean, bin/fm-lint.sh clean, tests/fm-wake-queue.test.sh full run green, and tests/fm-watch-triage.test.sh full run green (previously-failing test now passes) on a completed first consecutive run; a second consecutive verification run of fm-watch-triage.test.sh is still finishing in the background at time of this report but the first run already confirms the fix resolves the reported failure mode. No other files were changed
Owner
Author
|
Closing on captain instruction. The lock-reclaim bash-3.2 edge is not worth more pipeline or load-test theater on this machine. |
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
Add this suggestion to a batch that can be applied as a single commit.This suggestion is invalid because no changes were made to the code.Suggestions cannot be applied while the pull request is closed.Suggestions cannot be applied while viewing a subset of changes.Only one suggestion per line can be applied in a batch.Add this suggestion to a batch that can be applied as a single commit.Applying suggestions on deleted lines is not supported.You must change the existing code in this line in order to create a valid suggestion.Outdated suggestions cannot be applied.This suggestion has been applied or marked resolved.Suggestions cannot be applied from pending reviews.Suggestions cannot be applied on multi-line comments.Suggestions cannot be applied while the pull request is queued to merge.Suggestion cannot be applied right now. Please check back later.
Intent
Fix two pre-existing flaky test scripts, tests/fm-wake-queue.test.sh and tests/fm-watch-triage.test.sh, by root-causing each failure with evidence rather than papering over it with sleeps or retries. Make the tests hermetic where the cause is in the test, and fix the code where the cause is a real defect in the code under test. Where a test genuinely depends on an environment the sandbox cannot provide, make it skip loudly with the exact reason printed, never silently pass and never weaken an assertion. Prove the result with repeated consecutive green runs recorded in the PR body.
What Changed
bin/fm-wake-lib.sh's lock-reclaim logic:fm_lock_try_acquirecompared a recorded holder pid against${BASHPID:-$$}inline, which on shells with noBASHPID(stock macOS bash 3.2, where$$is identical in every subshell) could let a subshell mistake its parent's still-live lock hold for its own abandoned one. Extracted a newfm_pid_is_this_framehelper that usesBASHPIDwhen available and otherwise only matches on the main shell (BASH_SUBSHELL = 0), so deeper frames onBASHPID-less shells correctly keep waiting instead of reclaiming a live hold.is_live_non_zombie/reapfixture-process helpers (previously redefined per test file with an unboundedkill; wait) into single owners intests/lib.sh, and madereapbounded: it now sends SIGTERM, polls for exit, and escalates to SIGKILL instead of hanging indefinitely when a watcher's EXIT trap gets stuck re-acquiring a contended lock.tests/wake-helpers.shand thefm-*.test.shfiles now source these instead of defining their own.tests/lib.sh'sfm_test_tmprootresolve and return the physical (symlink-free) path, fixing fixtures that were spuriously rejected on macOS because$TMPDIRresolves through the/var->/private/varsymlink and production code refuses a state root reached through a symlink.wait_for_exit's default budget from 50 to 100 ticks (5s to 10s) intests/wake-helpers.sh, based on measured watcher startup cost (up to 2.5s under load), and removed the now-redundant explicit40/100tick arguments scattered acrosstests/fm-wake-queue.test.shandtests/fm-watch-triage.test.shin favor of that shared default.FM_TEST_ONLY-gated single-test entry point totests/fm-wake-queue.test.shso CI can run the frame-identity lock-reclaim regression in isolation, and added a step in.github/workflows/ci.ymlthat runs it under/bin/bashon the macOS lane and asserts exactly one passing result, since that half of the reclaim contract only exercises theBASHPID-less path on a shell that lacks it.Risk Assessment
✅ Low: Each of the three claimed root causes (macOS symlinked TMPDIR tripping the process-event state-root refusal, bash 3.2's shared $$ making a subshell indistinguishable from its parent in lock reclaim, and an insufficient wait_for_exit budget vs. measured watcher startup cost) is fixed at a verifiable source location with reasoning that checks out against the actual code (fm-procevent-lib.sh's
pwd -Pidentity check, fm-wake-lib.sh's BASHPID-based reclaim, fm-watch.sh's startup work), a bonus fourth fix (boundedreapreplacing unboundedkill; wait) is applied consistently everywhere the old unbounded pattern existed, all consumers of the deduplicatedreap/is_live_non_zombiehelpers transitively source tests/lib.sh so nothing breaks, the newFM_TEST_ONLYgate is added after all test function definitions so normal full-suite runs are unaffected, and no assertions were weakened or silently skipped - matching the user intent's requirements.Testing
Reproduced the actual pre-fix lock-reclaim defect on this bash 3.2/no-BASHPID macOS host (rc=13 with the old code, rc=0 with the fix) and independently confirmed the TMPDIR-symlink root cause the tests/lib.sh fix addresses; then ran tests/fm-wake-queue.test.sh and tests/fm-watch-triage.test.sh three consecutive times each plus 20 consecutive isolated runs of the frame-identity regression, all green with no flakes, and one clean run of the touched tests/fm-inactive-reconcile.test.sh - no test failures or evidence gaps found.
Root causes
Three distinct causes, none of them the same bug. Each has a minimal repro against unmodified files.
1. macOS symlinked TMPDIR vs the process-event claim (deterministic,
fm-watch-triage.test.sh)fm_procevent_claim_state_root_identity(bin/fm-procevent-lib.sh:349) deliberately refuses a state root reachable through a symlink: it compares the physically resolved path against a lexical normalization and rejects any mismatch.fm_test_tmproothanded back whatevermktemp -d "$TMPDIR/..."returned. On macOSTMPDIRis/var/folders/.../T/and/varis a symlink toprivate/var, so every fixture built from it is reached through a symlink and the claim refuses it. No runner ever claims the source, no result is ever captured, and the six procevent cases fail. On Linux CI/tmpand$RUNNER_TEMPare real directories, so CI never saw it.This is a fixture defect, not a product defect: a real firstmate home is a real path.
Minimal repro (unmodified files, before the fix)
The runner's own trace shows the exact refusal:
Same commands under a physically-resolved root capture the result:
tests/fm-procevent.test.shwas broken by the same cause (2 ok, thennot ok - reconcile never claimed the registered source); it now passes 62/62.Fix:
fm_test_tmprootresolves the root withcd -P && pwd -Pbefore handing it out.2. Lock reclaim could not tell a subshell from its parent (deterministic,
fm-wake-queue.test.sh)fm_lock_try_acquire's reclaim branch asked[ "$pid" = "${BASHPID:-$$}" ]. Stock macOS bash 3.2 has noBASHPID, and its$$is the same value in every subshell, so the fallback makes a subshell look exactly like an abandoned frame of its own parent - and it reclaims the lock the parent is still holding./bin/bashis 3.2.57 and precedes Homebrew's bash 5 on the default macOSPATH, so#!/usr/bin/env bashresolves to 3.2 in any shell that has not put Homebrew first. That is the whole difference between the environments: an interactive terminal with Homebrew'sshellenvruns bash 5, the sandbox runs 3.2.Minimal repro (unmodified files, before the fix)
10 of 10 runs of the whole file failed at this case under bash 3.2; the other 28 cases in the file pass there.
Fix:
fm_pid_is_this_frameis now the single owner of "does this recorded pid name the frame asking".BASHPIDanswers directly where it exists. Where it does not,$$names a frame only where there is no subshell to confuse it with - the main shell, the one placeBASH_SUBSHELLis 0 - so a subshell can never take the branch.Why the obvious alternatives were rejected (both tried, both measured)
BASHPID. Safe against the steal, but it reintroduces the deadlock the reclaim exists to prevent. Measured: with that version in place,test_stale_terminal_status_overridden_by_active_runhung for over 8 minutes under bash 3.2 withbin/fm-watch.shalive and unreapable; the unmodified file passes the same case in seconds.$(sh -c 'echo $PPID'). It relies on bash exec'ing a one-command substitution in place, which is an optimization, not a guarantee - and it does not hold where this code actually lives. Measured under bash 3.2: exact in a top-level script (a=b=$$), but forking, and so wrong, inside a sourced file (a=70804 b=70806 self=70803), underbash -c, and any time a redirection is added to the substitution (on bash 5 too). A shell that forks answers with a fresh pid every call, which would write an already-dead owner into every lock.BASH_SUBSHELLis a shell-maintained fact rather than an optimization, needs no fork, and is exactly the distinction the branch was missing.3. Watcher-exit budget below the work inside the window (rare,
fm-wake-queue.test.sh)tests/fm-wake-queue.test.shgave its five one-shot watcher waits 40 ticks (4s), whiletests/fm-watch-triage.test.shgives the same watcher 100 ticks and already documented why a tighter budget reports a spurious "did not surface":fm-watch.shdoes bounded startup work before its first poll, and a budget close to that cost reaps the process while it is still starting.Measured cost of that one poll on this machine: 1.1s idle, 2.5s at load 18 - a 1.6x margin against 4s, versus 4x for the sibling suite's budget.
Observed rate is low: 1 failure in 3 full-file runs when first seen, then 0 failures in 39 further pre-fix runs. Reported honestly rather than dressed up; the budget is fixed because it is measurably under-provisioned against the repo's own documented standard, not because a reproduction rate demanded it.
Fix:
wait_for_exitintests/wake-helpers.shnow owns the standard budget and the rationale, and defaults to it.fm-wake-queue.test.sh's five waits take that default.fm-watch-triage.test.sh's 65 copies of the literal100are replaced by the same default, so its "every budget here is the standard one" comment is true by construction instead of by 65 coincidences; its three deliberately larger away-mode budgets stay explicit.No assertion was weakened and nothing was papered over with a sleep or a retry: a watcher that never surfaces its wake still fails its assertion when the budget runs out.
4. An unbounded stop-and-collect turned a wedged watcher into a whole-suite hang (rare,
fm-watch-triage.test.sh)The most severe failure of the three files was not a failing assertion at all.
A 20-run loop had run 11 stop producing output at
ok=58and never return; it had to be killed from outside at a 900-second bound, with nonot okline and nothing naming the case it died in.The mechanism is the way these suites stop a process they spawned.
Both spellings ended in an unbounded wait:
reap() { kill "$1"; wait "$1"; }, and the budget-exhausted tail ofwait_for_exit.The process being stopped is
bin/fm-watch.sh, which leaves throughtrap watcher_cleanup EXIT, andwatcher_cleanupitself takes a lock (fm_recovery_transition ... "$WATCH_LOCK" downtime).A watcher signalled while that lock is contended can sit inside its own exit path, and an unbounded
waitsits there with it - forever, taking the run's whole budget and reporting nothing.To be exact about what is and is not established: the wedge itself is rare and was not reproduced on demand, and it is not caused by this PR's production change.
That was tested rather than assumed, twice: 25 isolated rounds of the case the loop died near give
mine 0/25, head 0/25, and eight instrumented full-file runs logging every reclaim the new frame check newly refuses giverefusals=0across all eight (rc=0 ok=92each).The defect being fixed here is the fixture's, and it is deterministic and provable on its own terms: whatever wedges the exit path, an unbounded wait converts it into a silent hang instead of a result.
Minimal repro (the two spellings, against an exit path that does not complete on TERM)
Fix:
tests/lib.shnow owns one boundedreap: signal, allow a bounded number of ticks to leave, thenSIGKILL, which cannot be trapped, so the bound holds whatever the exit path is doing.wait_for_exit's exhausted-budget tail routes through it, and the two verbatim copies of the old spelling - intests/fm-watch-triage.test.shand intests/fm-inactive-reconcile.test.sh, which had the identical latent hang - are replaced by that single owner.No assertion is weakened:
reapis cleanup that runs after a case has already made its assertions, andwait_for_exitstill returns 124 for a watcher that never surfaced its wake.What changes is only that a wedged exit path now costs a bounded wait and a reported result instead of an unbounded hang.
5. Nothing needed a loud skip
Both suites now pass in full on both shells present here, so no case needed an environment skip.
5. What CI caught that 14 local runs could not
The bounded reap above shipped with a 5 second allowance, and CI failed on it:
not ok - could not acknowledge the intentional phase-A watcher stop, one assertion, intests/fm-watch-triage.test.sh.That is a real regression introduced by this branch, found by CI and worth stating plainly.
The reasoning error is visible in the original comment, which called
reap"cleanup that runs after a case has already made its assertions".That is true of most callers and false of the one that mattered:
ack_stopped_cycledepends on the EXIT trap itself completing, because that trap is what publishes the downtime recovery marker the following drain must find.Escalating to
SIGKILLthere does not merely skip cleanup - it erases a side effect the next assertion reads.Under CI contention the watcher's exit path exceeded 5 seconds, the marker was never written, and the drain had nothing to acknowledge.
Fix: the default is now the same 10 second standard budget
wait_for_exituses, and the comment says why: both bound the samefm-watch.shunder the same load doing comparably sized work, so one standard serves both rather than two unexplained numbers.It passes locally because the exit path finishes well inside 5 seconds here; only a contended runner exposes it.
Proof
All runs from the pooled task worktree, each wrapped in a hard wall-clock bound so a hang fails loudly instead of hanging the run.
fm-wake-queue.test.sh(bash 3.2)fm-wake-queue.test.sh(bash 5)fm-watch-triage.test.sh(bash 3.2)not ok - the fixture captured no process-event resultfm-watch-triage.test.sh(bash 5)fm-procevent.test.sh(collateral)not ok - reconcile never claimed the registered sourceConsecutive full-file runs
Run under stock
/bin/bash3.2, the shell where these failed before the fix, each run bounded so a hang fails loudly instead of eating the budget silently.The wake-queue loop ran its full 20.
The triage loop was stopped deliberately at 14 rather than run to 20: the two failures it was there to catch are both root-caused and fixed deterministically, with a minimal repro each, so further identical runs re-measure a rate that no longer has a mechanism behind it.
14 consecutive clean full-file runs alongside a found-and-fixed cause is the evidence; a 20th run would not have added a different kind.
Two details worth stating rather than smoothing over.
Run 11 is the position where the pre-fix loop hung and had to be killed at 900 seconds; it now passes in 274 seconds like every other run.
The loop driver was killed from outside between runs 13 and 14 and restarted; no test failed, nothing was left running, and the files under proof were verified byte-identical across the restart, so the 14 are 14 runs of one unchanged tree.
Per-run wall clock was 269-291 seconds, tightly clustered, which is itself evidence that nothing is sitting near a timing boundary.
Both suites also pass under bash 5, where the full 175-script serial sweep records
fm-wake-queue.test.sh exit=0,fm-watch-triage.test.sh exit=0, andfm-procevent.test.sh exit=0.The one suite whose result needed a controlled comparison
tests/fm-control-relaunch.test.shfailed during the sweep, so it was compared against pristineHEADin interleaved rounds. It is a pre-existing load-sensitive flake and this change is not distinguishable as a cause:The calibration is the control: with identical code on both sides the spread is still +/-2 at n=10 and the direction reverses, which accounts for the earlier runs. Pooled over 28 interleaved rounds: mine 14/28, head 11/28. Its assertion is a 2s wall-clock budget, the same under-provisioned shape as cause 3.
Both regressions were proven load-bearing by reverting only the production line and re-running:
bin/fm-lint.shclean (ShellCheck 0.11.0 pinned, actionlint 1.7.12 pinned, 3 workflows valid).bin/fm-doc-audience-check.shclean (89 surfaces, 300 local links).Pre-existing failures found on the way, deliberately not fixed here
All four reproduce on unmodified
origin/mainand none is caused by this change. They are listed so they are not lost, not folded in, because each is a deterministic or environmental defect in a file this task does not name, and bundling them would make a flakiness fix harder to review.tests/fm-muse-harness.test.sh(macOS, stock bash only). The fixture doescp "$(command -v bash)"and renames the copy tomuse-bin-<version>so harness detection can find it in the process tree. A copied macOS system/bin/bashwill not execute at all - code signing - so the probe returns empty. It passes whereverbashresolves to a copyable build, which is why Linux CI and a Homebrew-first PATH never see it. A symlink in place of the copy fixes it on macOS (verified: detection returnsmuse, and the anchored negatives still refusemusescore,amuse,notmuse-bin,muse-binary,muse-bind), but the Linux half of that change cannot be verified from here.tests/fm-composer-lib.test.sh(stock bash only):not ok - a half-block rule row must count as a structural edge. Passes under bash 5. Undiagnosed.tests/fm-backend-herdr-presentation-e2e.test.sh:error: herdr presentation recovery could not acquire its session lock; refusing a concurrent resume. A race between two concurrent resumes in a real-Herdr end-to-end case, on a machine also running another firstmate session against the same Herdr daemon.tests/fm-control-relaunch.test.sh:relaunch did not reach trace delivery. That assertion gives the relaunch 2s (200 x 0.01s) to reach trace delivery - the same class of under-provisioned wait as cause 3 above.Notes
tests/lib.shgains the boundedreapbecause it is the generic helper that the wake, watcher, and reconcile suites all already source, so it is the one place the contract can be stated once.tests/fm-inactive-reconcile.test.shloses its verbatim copy of the old unbounded spelling, because leaving it would leave a local definition shadowing the fixed one and silently keeping the same hang; it is a one-line deletion and that suite passes (17 ok).origin/main(6aa4beb), which already contains the watcher change from fix(bin): absorb background-run stale wakes and trust declared pauses over ci-monitoring #2 that editedtests/fm-watch-triage.test.sh. The budget cleanup here sits on top of those cases rather than around them; the newtest_crew_run_step_paused_classifierand the pause-trust cases pass unchanged.bin/fm-wake-lib.sh's behavior on any bash withBASHPID- every bash 4.0 and later, which is every shell CI and the fleet actually run - is unchanged by this PR./bin/bash3.2 viaFM_TEST_ONLY, so the half of the contract the Linux lanes cannot reach is enforced rather than assumed.Pipeline
Updates from git push no-mistakes
✅ **intent** - passed
✅ No issues found.
✅ **Rebase** - passed
✅ No issues found.
✅ **Review** - passed
✅ No issues found.
✅ **Test** - passed
✅ No issues found.
/bin/bash tests/fm-wake-queue.test.shx3 consecutive runs (29 assertions, exit 0 each)/bin/bash tests/fm-watch-triage.test.shx3 consecutive runs (92 assertions, exit 0 each)/bin/bash tests/fm-inactive-reconcile.test.sh(17 assertions, exit 0)FM_TEST_ONLY=test_self_held_lock_reclaims_instead_of_deadlocking /bin/bash tests/fm-wake-queue.test.shx20 consecutive isolated runs of the frame-identity lock regression (all ok)Manual repro: ran the pre-fix bin/fm-wake-lib.sh lock-reclaim logic against the subshell-reclaim scenario directly, confirming it fails (rc=13) before the fix and the current code passes (rc=0) - fail-before/pass-after regression proofManual verification that TMPDIR on this host resolves through a /var -> private/var symlink, confirming the root cause tests/lib.sh's fm_test_tmproot fix addresses✅ **Lint** - passed
✅ No issues found.
✅ **Push** - passed
✅ No issues found.