Timing-sensitive tests fail under VM load #31
Loading…
Reference in a new issue
No description provided.
Delete branch "%!s()"
Deleting a branch is permanent. Although the deleted branch may continue to exist for a short time before it actually gets removed, it CANNOT be undone in most cases. Continue?
With about 10 parallel jobs (load5 around 15 to 18), tests that pass on a quiet machine fail:
crates/engine/tests/integration.rs:481stalled_pty_stdin_cannot_hold_exec_termination:session.close()exceeded its 4 s timeout on Podman. At low load it passed 3 of 3, reaping in 389 to 400 ms on Docker and 502 to 732 ms on Podman.packages/streamVitest case expected close code4108and receivedundefined(seen in theui-apisfast gate). It passed at low load.Fix: make these tests robust to scheduling delay without hiding real regressions. Use deterministic synchronization (wait on events, not wall-clock sleeps). Where a wall-clock bound is the product guarantee, measure it from the right start point and give it a stated tolerance for a loaded CI host, or move the timing assertion to
bench. Also consider ascripts/verifyguard that warns when load5 is above the core count.Starting work on
flaky-testsfrom basef1bedf994ce5399cf4b53ff0ca693ff0db4cfb9d.Scope: test code and the load warning in
scripts/verify. I am mapping existing timing-sensitive cases before establishing quiet and deliberate-load baselines.Starting work on
flaky-testsfrom basef1bedf994ce5399cf4b53ff0ca693ff0db4cfb9d.Scope: test code and the load warning in
scripts/verify. I am mapping existing timing-sensitive cases before establishing quiet and deliberate-load baselines.Baseline setup evidence: launching
fastandintegrationsimultaneously caused bothinfraternal_ensure_js_dependenciescalls to runbun installagainst this checkout's sharednode_modules; they failed withEEXISTwhile linking packages before any tests ran. I am sequencing the gates under one continuousstress-ng --cpu 8run. The separate debug build also exited because embedded web assets had not yet been built.Loaded baseline evidence: under
stress-ng --cpu 8 --cpu-load 100,scripts/verify fastpassed the Cargo workspace tests, web and UI Vitest, and typechecks, then stream Vitest failedclient_protocol_failures.test.ts→closes 1008 when the peer exceeds the 400-control-frame burst: it expected 1008 and gotundefined(line 302). The test sends 401 PING frames while the implementation's 200/s token bucket uses realperformance.now(); this run's test body took 22 ms, enough for tokens to refill during the synchronous loop. The adjacent browser-policy case expects 4108 from the same burst path and has the same timing assumption.The two stream burst tests now pin
performance.now()at 0 while delivering their 401 PING frames, so scheduler delays cannot refill the burst bucket during the modeled same-instant input. The focused test file passed under the same stress workers:Test Files 1 passed (1); Tests 49 passed (49). I also added a non-failingscripts/verifywarning when/proc/loadavgload5 exceeds the online CPU count; it prints both values.The first loaded
integrationrun completed every integration step successfully, including Docker/Podman engine adapters, stream regressions, CLI/MCP, and real sshd. The script then exited 1 in the new warning helper withload5: unbound variableunderset -u. I initialized both local values explicitly and am rerunning the helper and gate.Loaded integration run 1 found another test timing assumption in
crates/server/tests/stream_regressions.rs::every_grant_shrink_closes_logs_and_persistent_exec_on_both_engines. At load5 13.99, Docker's transient grant shrink observed 4 log DATA frames before CLOSE; Podman's observed 0 and failed the assertion that every run must have a log frame arrive after the SQLite commit. The product behavior assertion still passed for Podman: both CLOSE frames arrived in 66.7 ms, below the 1 s contract. I am changing the test to wait for an actual log DATA event before mutating grants and to keep the 1 s close and DATA-before-CLOSE assertions.The first focused rerun of the grant-shrink test after adding the log-event wait passed all Docker causes and Podman's first two causes, then panicked because
shrink_open_replysaw the WebSocket end while waiting for an OPEN reply (Option::unwrap()at the helper). It did not capture a CLOSE code or payload. I am improving the test's failure diagnostic and repeating before deciding whether this is a product bug or another harness race.The next focused run under eight stress workers passed Docker and the first seven Podman grant-shrink causes. It then failed starting the final Podman
token_expiredcase: the WebSocket closed with 4003token expired or revokedbefore the logs OPEN reply. Several preceding Podman process-reap checks took 1.5–3.7 s under this load. I am checking whether the test's shared token lifetime expires naturally before that final case.Follow-up on the intermittent 4003:
SqliteStorage::issue_test_tokensets a 15-minute expiry; the focused matrix completes in under 2 minutes, so natural expiry does not explain the early close. The next focused run, with runtime/cause context, passed both engines through the finaltoken_expiredcase (68 ms CLOSE). I have not confirmed a product bug; the full integration repetitions will exercise this again.Loaded integration repetition 1 reached the real server stream regressions but failed
authorization_loss_terminates_stalled_stdin_on_both_engines: Podman emitted CLOSE-forbidden at 47.624097 ms, then the test failedpodman termination completion was not auditedatcrates/server/tests/stream_regressions.rs:833. The newly adjusted grant-shrink matrix passed on Docker and Podman in the same run; its transient stream saw 3 Docker and 10 Podman DATA frames after commit. Investigating whether the audit assertion races asynchronous completion or indicates a product bug; no product changes made.The focused rerun of
authorization_loss_terminates_stalled_stdin_on_both_enginespassed once under continued host load:cargo test: 1 passed, 15 filtered out (1 suite, 20.77s). This does not establish whether the first Podman audit miss was a delayed completion or a product failure; the test now prints all termination audit rows if it recurs.After adding audit-row diagnostics (keeping the assertion intact), the first post-diagnostic loaded
scripts/verify integrationrepetition passed every step. It emittedWARN load5=8.78 exceeds online CPU count=8; timing-sensitive checks may be delayed; the stream regression suite passed on Docker and Podman, including the stalled-stdin audit case. The earlier single Podman audit miss has not reproduced in three focused repetitions or this full run. Log:/tmp/flaky-tests-20260924-loaded-integration-final-1.log.Finished job #31 on branch
flaky-tests, based onf1bedf994ce5399cf4b53ff0ca693ff0db4cfb9d.Head:
5c0c0dd2861c895531489ace82780dbbd01147e8(not pushed).Changes:
performance.now()during the burst, so the token bucket cannot refill while the test loop runs.scripts/verifywarning when load5 exceeds online CPU count.Verification:
scripts/verify fastpassed three consecutive times under the samestress-ng --cpu 8 --cpu-load 10run. Gate-start load5 warnings were 10.87, 9.25, and 10.55 on 8 CPUs. Logs:/tmp/flaky-tests-20260924-loaded-fast-final-{1,2,3}.log.scripts/verify integrationpassed three consecutive times under the same stress profile. Logs:/tmp/flaky-tests-20260924-loaded-integration-final-{1,2,3}.log.scripts/verify fastandscripts/verify integrationalso passed after stress-ng stopped and other builds cleared. Logs:/tmp/flaky-tests-20260924-quiet-fast.logand/tmp/flaky-tests-20260924-quiet-integration.log.authorization_loss_terminates_stalled_stdin_on_both_enginespassed three consecutive loaded repetitions: 20.77 s, 15.74 s, and 14.56 s.One earlier loaded full integration attempt failed because Podman sent forbidden CLOSE in 47.6 ms and the test then did not observe an accepted/forbidden termination audit within 2 seconds. I added audit-row diagnostics without weakening that assertion. It passed in the three focused repetitions, all three later loaded integration gates, and the quiet integration gate. I found no confirmed product bug and changed no product code. The earlier isolated WebSocket CLOSE 4003 before OPEN also did not recur in the later matrix runs.
Representative loaded gate output, verbatim:
Quiet gate output, verbatim:
Starting independent review on branch
flaky-tests, head5c0c0dd2861c895531489ace82780dbbd01147e8, against requested basef1bedf9. I’m reviewing the test-strength changes and verify warning, then will run the changed tests and scratch fault checks as requested.Independent review — branch
flaky-tests, head5c0c0dd2861c895531489ace82780dbbd01147e8, basef1bedf9.Findings:
every_grant_shrink_closes_logs_and_persistent_exec_on_both_engines, thequeued_logs_after_commit > 0assertion is removed. The new event wait proves an actual logsDATAreached the client before the transient shrink. The test still requiresforbiddenCLOSE on both channels, the one-second deadline measured from the shrinking commit, no same-channel DATA after CLOSE, and no same-channel frames during the 100 ms post-CLOSE drain. This removes a scheduling-dependent workload observation and leaves less direct evidence that a log frame was in flight at the commit boundary. Consider deterministic queue-barrier coverage later if that race needs explicit integration coverage. The §2.3 close/fence checks and §3.101008/4108checks remain asserted.No blocks-merge findings.
Test review:
freezeControlClock()fixesperformance.now()for the two 401-frame tests; their4108and1008expectations are unchanged. No timeout, sleep, skip, or retry change was added in Vitest.shrink_open_replyremains at 5 seconds. No new conditional skip or retry was added.bash -euo pipefail. Its normal branch returned 0; exercising the overload branch with load 99 / 8 CPUs printed the warning and returned 0; a failedawklookup also returned 0.scripts/verify fastpassed.Verification:
authorization_loss_terminates_stalled_stdin_on_both_enginespassed;every_grant_shrink_closes_logs_and_persistent_exec_on_both_enginespassed against Docker and rootless Podman (48.30 s).docker role_change CLOSE exceeded one second(2.43 s). After restoring the Rust and TypeScript test files fromf1bedf9, the old grant-shrink assertion set failed at the same one-second CLOSE deadline (2.21 s); the old stream Vitest file passed 49 tests.scripts/verify fastoutput:Another load-sensitive flake:
steady_state_framing_does_not_allocate_per_chunkfailed inverify fastat load5 6.23 during verify-11c. The direct rerun passed. Label: later.Starting fix-scroll-wait on branch
ws-close-reply, base head2fae616b9f06ceed40d8cd270b58a6a3402799ec. Scope: make the production browser smoke wait for the filtered container row to be fully visible after DataTable scrolling, then reproduce under CPU load and run the requestedfastgate.The supplied gate log records
WARN load5=11.43 exceeds online CPU count=8; the production browser smoke then fails infindContainerRowwithcontainer row did not scroll into view. The existing geometry poll has a 200 ms timeout and 20 ms interval. I am preparing the requested stress-ng reproduction; the shared VM is still above the documented load threshold for starting a release build.Implementation decision: retain the existing scroll adjustment and full-row containment predicate, and change only the polling window from 200 ms / 20 ms to 5 s / 50 ms. This gives the virtualized layout time to settle under VM load without accepting a partially visible row. The original script is saved outside the worktree so the before-change reproduction can run later against the matching release binary.
The source change is ready, but verification is temporarily blocked by shared-host admission:
/proc/loadavghas remained around 35–40 and a separatecargo build --release -p infraternalis active ininstall-timeline-ui. The worktree job rules require waiting for load below 10 before starting a heavy build. I will resume the baseline, five post-change smoke runs andfastwhen the host clears.Follow-up admission snapshot: both external release builds have ended, but
/proc/loadavgis now42.80 34.88 30.90; Rust builds and browser processes remain active. No smoke suite has been started from this worktree. I am continuing to wait for load below 10 and browser-suite serialization.To avoid another release compile on the loaded host, I will run the browser smoke against the cached release binary built at
1dd62b854fbdedadd9611c07b5bf19cd067cf9ae. The source diff from the task base is limited tocrates/server/src/stream.rsand its regression test; the container route, DataTable and browser-check source are unchanged. The smoke checks stream/channel retirement but does not assert the WebSocket close-reply frame itself. I will include this binary head in the result.Before-change reproduction:
nix run nixpkgs#stress-ng -- --cpu 16started stress-ng 0.22.00 with 16 CPU workers. Browser smoke runfix-scroll-before-1against the cached release binary failed infindContainerRowat line 2528 withcontainer row did not scroll into view; the assertion still had{ timeout: 200, interval: 20 }. The failure occurred after the auth and sidebar persistence flows passed. The test's source was restored to the committed version afterward.After-change reproduction: while the same
nix run nixpkgs#stress-ng -- --cpu 16process ran for 16 minutes, the updated browser smoke passed five sequential runs (fix-scroll-after-1throughfix-scroll-after-5). Each ended withPOST_CHANGE_SMOKE_PASS; each reachedSIDEBAR_CONTAINERS repetition=1/1 GET /api/v1/containers status=200. Stress-ng reported 16 CPU workers passed, 0 failed. The browser script requires full-row containment and now polls for 5 s at 50 ms intervals. These runs used the cached release binary at base1dd62b854fbdedadd9611c07b5bf19cd067cf9aeas recorded above. The requested fast gate remains pending shared-host load admission.Finished
fix-scroll-wait.ws-close-reply2fae616b9f06ceed40d8cd270b58a6a3402799ece10cb37d52e1980cd82a3b0b2a8bd8ae931dd532nix run nixpkgs#stress-ng -- --cpu 16,fix-scroll-before-1failed atfindContainerRowwithcontainer row did not scroll into view.fix-scroll-after-1throughfix-scroll-after-5) passed under 16 CPU workers. Stress-ng reported 16 passed, 0 failed.1dd62b854fbdedadd9611c07b5bf19cd067cf9ae, whose only source difference from the task base is server WebSocket close-reply handling. Container UI, DataTable, API and browser-check code are identical.Fast gate output:
The pre-existing
THIRD_PARTY_NOTICES.mdworktree modification remains unstaged and unchanged.Architecture-review evidence (2026-10-04; source report reviewed
d1eefa9, current checkout is0b4fc37):scripts/browser-check.mjs(24.8% of all recent commits), with 208 changing only that file. This is churn, not a measured failure rate.crates/server/tests/stream_regressions.rs:597,978,1149.steady_state_framing_does_not_allocate_per_chunkfailing under load and passing on retry. Keep the allocation bound; isolate its measurement phase/thread instead of loosening it.These are audit findings, not new reproductions. Source: arch-review 2026-10-04; /mnt/hdd/infraternal/jobs/arch-review/report.md.
One more timing-sensitive class from the architecture review (historical evidence only; not reproduced by this review):
The report groups commits
7d4a71d,665407c,7014255and1a8755dunder runtime starvation from probes/subprocesses. Its recommendation is to keep blocking work off the async executor and wait for observed process state. This belongs with the existing loaded-VM timing issue: use controlled readiness/state evidence, keep deadlines for detecting a hung fixture, and retain real integration gates.Source: arch-review 2026-10-04; /mnt/hdd/infraternal/jobs/arch-review/report.md.