Repository navigation
test: stop leaked supervision-host cycles per case and widen the remote-reply recapture wait - #27
Merged
cloud-practitioner merged 1 commit intoOct 1, 2026
Conversation
…te-reply recapture wait Both failures are test-side timing assumptions that a busy host exposes. They are not product bugs, and they do not come from missing tools: tmux and ruby are absent here but neither suite needs them (supervision-host stubs tmux), and the live e2e variants are opt-in and gate-skip unless FM_SUPERVISION_HOST_LIVE_E2E / FM_SUPERVISION_HOST_ATTENDED_LIVE_E2E is set. Upstream CI at f593060 passes both suites (supervision-host 683s, remote-reply 184s) on uncontended runners. tests/fm-supervision-host.test.sh Most cases end with their host parked (default park bound 27000s) or with a pass-through's successor watcher still running at FM_POLL=1. Before this change only the EXIT trap stopped them, so they piled up across the 65 cases. An instrumented run on a quiet 4-core host counted 17 live watchers and 8 live hosts by the last case. Load average rose from 1.5 to 25.8, per-case time roughly tripled (latch case 35s -> 131s, attended latch 37s -> 159s), and the suite took 1558s, past any 900s per-command cap. When concurrent lanes added load, the pile-up pushed closes past the suite's fixed 15-25s wait_until budgets, with failures that varied between runs: "latch: the later failed probe did not hand the wake back" (fork main fc795e5, 1482s), "away grok: the wake was not handled on the engine" (upstream-merge branch), and "the watcher's downtime resurface did not reach main". run_case now stops every home a case made after the case returns. With that change no watchers leak between cases, load stayed at 2-9, and the suite passed in 558s under the same conditions. It also passed in 659s under concurrent load from fm-test-run, and in 731s on the upstream f593060 tree with the same change applied. tests/fm-remote-reply.test.sh After a cursor loss, the whole-log recapture fetches again every document that the whole log offers, one remote job at a time: one delta read and 13 document fetches. Upstream kunchenguid#6255 (549e07f) made each sequential remote job slower. It cut the dispatcher burst from 20 passes to 4 before the 1s quiet scan, raised active/result sampling from 0.05s to 0.25s, and raised delta polling from 0.2s to 0.5s. Paired runs under the same load measured that step at 36s on f593060 (about 2.5s per fetch). With 549e07f's bin changes reverted it took 20s (about 1.1s per fetch). Either way it has to fit inside await_reply_result's 40s budget (800 x 0.05s polls). The failures ("the replay-identity whole-log recapture was not captured") appeared only on trees that include kunchenguid#6255. Fork main without it passes, but the same step already used 30s of the 40s under load. The bound is now 2400 polls (120s). A healthy wait still returns as soon as the capture is applied. Upstream: both changes belong upstream too. The leak and the post-kunchenguid#6255 budget exist the same way on upstream main, and upstream CI passes only because its runners are uncontended. When upstream is merged into the fork, the call-list hunk conflicts trivially with upstream's added test_park_exit_probe_uses_half_second_child_sleeps line. Resolve it by prefixing that line with run_case.
This was referenced Oct 2, 2026
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 the test failures in tests/fm-remote-reply.test.sh and the supervision-host tests (tests/fm-supervision-host.test.sh and, if they also fail, tests/fm-supervision-host-live-e2e.test.sh and tests/fm-supervision-host-attended-live-e2e.test.sh) in the fork https://github.com/cloud-practitioner/firstmate. Context: while validating the upstream-merge branch, these tests failed both on the fork's unmerged main and on upstream https://github.com/kunchenguid/firstmate main in this environment, so they are pre-existing failures rather than merge breakage; one supervision-host run hit its 900-second timeout. A standing rule says test failures found along the way get fixed. Establish the cause first, fix it in the fork, and note whether the fix belongs upstream as well.
What Changed
tests/fm-supervision-host.test.sh: adds arun_casewrapper that runs each test function and then callsstop_home_processesfor every home that case added to$HOMES_FILE. All 65 cases now run through it. Before this, a case that finished with its host parked or a successor watcher still running left thatFM_POLL=1cycle alive until the suite's EXIT trap. Those cycles piled up from case to case and pushed later cases past their fixedwait_untilbudgets. In an instrumented run the suite took 1558s, well past the 900s cap.tests/fm-remote-reply.test.sh: raises theawait_reply_resultpolling bound from 800 to 2400 iterations, so the 40s budget becomes 120s. This makes room for the cursor-loss whole-log recapture, which re-fetches every document one remote job at a time and runs slower since upstream fix: reduce remote-job and supervision polling churn kunchenguid/firstmate#6255. A healthy wait still returns as soon as the capture is applied. A new comment records why the bound is this size.bin/are untouched. Both fixes also apply upstream. When upstream is merged in, the call-list hunk will conflict with upstream's addedtest_park_exit_probe_uses_half_second_child_sleepsline. Resolve it by prefixing that line withrun_case.🤖 Generated with Claude Code
Causes and evidence
Both failures come from timing assumptions in the tests that a busy host exposes.
Neither is a product bug in
bin/or a missing tool: tmux and ruby are absent here, but neither suite uses them, and both live e2e variants are opt-in and skip without their opt-in variables.Upstream CI at f593060 passes both suites (supervision-host 683s, remote-reply 184s) on runners with no other work.
Supervision-host: leaked hosts and watchers.
Most cases end with their host parked (the default park bound is 27000s) or with a successor watcher still polling at
FM_POLL=1, and only the EXIT trap stopped them.An instrumented run of the unfixed suite counted 17 live watchers and 8 live hosts by the last case.
Over the run, load average rose from 1.5 to 25.8 on this 4-core host, cases ran about 3x slower (latch 35s -> 131s, attended latch 37s -> 159s), and the suite took 1558s, past the 900s cap.
When other lanes added load, closes ran past the fixed 15-25s
wait_untilbudgets.Observed failures were "latch: the later failed probe did not hand the wake back" (fork main fc795e5, 1482s), "away grok: the wake was not handled on the engine" (upstream-merge branch), and "the watcher's downtime resurface did not reach main".
With
run_caseand the same conditions, no watchers leaked between cases, load stayed between 2 and 9, and the suite passed in 558s.It also passed in 659s through
bin/fm-test-run.shon fork main with other tests running, and in 731s on the upstream f593060 tree with the same change.Remote-reply: the recapture wait after upstream kunchenguid#6255.
After a cursor loss, the whole-log recapture reads the log once and then fetches 13 documents, one remote job at a time.
Upstream kunchenguid#6255 (549e07f) made each sequential remote job slower to be picked up and sampled:
Two runs side by side under the same load timed that step at 36s on f593060 (about 2.5s per fetch).
With 549e07f's
bin/changes reverted, it took 20s (about 1.1s per fetch).The old
await_reply_resultbudget was 40s."The replay-identity whole-log recapture was not captured" failed only on trees that include kunchenguid#6255.
Fork main, which does not have kunchenguid#6255 yet, still passes, but that step already took 30s of its 40s under load.
Upstream: both fixes belong upstream as well.
Upstream main has the same leaked processes and the same 40s budget after kunchenguid#6255, and its CI passes only because nothing else runs on its runners.
Risk Assessment
✅ Low: The change only touches test code. It adds a per-case cleanup wrapper that reuses the existing idempotent stop_home_processes over just the homes each case registered, and it widens one success-only polling bound. No product code changed, no caller of await_reply_result expects a timeout, and no case depends on processes left running by an earlier case.
Testing
I ran the changed suites directly on this 4-core host while other work was also using it. The supervision-host suite passed 65/65 in 599s with at most 3 hosts and 1 watcher alive at once. Base fc795e5 reproduced the pile-up: after 450s it had finished only 36 cases, with 11 hosts, 12 watchers and load average 17.5. The remote-reply suite passed 33/33 in 166s, and an instrumented copy showed the two whole-log recapture waits took 19.6s and 21.9s against the new 120s bound. Both live e2e suites skip cleanly without their opt-in variables. Separately, I found an existing product temp-directory leak, which is reported as a finding. There is no UI surface, so I captured no screenshots. The evidence is CLI logs and per-10s process-count tables.
Evidence: Evidence summary (HEAD vs base table, recapture timings)
Source: Evidence summary (HEAD vs base table, recapture timings)
Evidence: supervision-host HEAD full run transcript (65 ok, rc=0, 599s)
Source: supervision-host HEAD full run transcript (65 ok, rc=0, 599s)
Evidence: HEAD per-10s live fixture hosts/watchers/load
Source: HEAD per-10s live fixture hosts/watchers/load
Evidence: base fc795e5 partial run transcript (36 cases in 450s)
Source: base fc795e5 partial run transcript (36 cases in 450s)
Evidence: base per-10s live fixture hosts/watchers/load (peaks 11/12/17.5)
Source: base per-10s live fixture hosts/watchers/load (peaks 11/12/17.5)
Evidence: remote-reply HEAD timestamped transcript (ALL TESTS PASSED, 166s)
Source: remote-reply HEAD timestamped transcript (ALL TESTS PASSED, 166s)
Evidence: remote-reply await_reply_result per-call durations
Source: remote-reply await_reply_result per-call durations
Evidence: live e2e suites skip without their opt-in variables
Source: live e2e suites skip without their opt-in variables
Evidence: Process monitor used for the samples
Source: Process monitor used for the samples
Evidence: HEAD vs base supervision-host comparison
Pipeline
Updates from git push no-mistakes
✅ **intent** - passed
✅ No issues found.
✅ **Rebase** - passed
✅ No issues found.
✅ **Review** - passed
✅ No issues found.
bin/fm-procevent-remote-reply.sh:557- Existing product leak, unrelated to this change. cmd_ingest's continuity-broken branch doesreturn 3without removing its staging directory (created at line 508). The cleanup is an EXIT trap (trap 'rm -rf -- "$tmp"' EXIT), buttmpis local to cmd_ingest, so by the time the script exits the variable is out of scope and nothing is removed. Every tests/fm-remote-reply.test.sh run leaves 4 /tmp/fm-remote-reply-ingest.* directories, each holding an empty payload and normalized-payload. Dozens of these from earlier runs are on this host. The fix would betrap - EXIT; rm -rf -- "$tmp"beforereturn 3, mirroring the success path at lines 636-637. I did not change it because product code is out of scope for this test phase. It likely affects upstream too.bash tests/fm-supervision-host.test.shat HEAD, with a 10s monitor counting live fixture hosts and watchers (FM_HOME under the fm-supervision-host.* fixture root) and load averagegit show fc795e5:tests/fm-supervision-host.test.shrun from a temporary copy in tests/ for 450s with the same monitor, then stopped (before/after comparison of the leak)bash tests/fm-remote-reply.test.shat HEAD, with each output line timestampedTemporary instrumented copy of tests/fm-remote-reply.test.sh that wraps await_reply_result to log each call's durationbash tests/fm-supervision-host-live-e2e.test.shandbash tests/fm-supervision-host-attended-live-e2e.test.shwith the opt-in variables unset (checks that both skip)Cleanup check: confirmed no leftover fixture processes after the runs, removed the temporary test copies and my /tmp ingest leftovers, and confirmed the worktree is clean✅ **Document** - passed
✅ No issues found.
✅ **Lint** - passed
✅ No issues found.
✅ **Push** - passed
✅ No issues found.