Test: motion-audit spec is flaky under load #65

Closed
opened 2026-10-07 08:40:47 +00:00 by kayg · 18 comments
Owner

The motion-audit spec (apps/tracer/test/motion-audit.spec.ts) is flaky under CPU load: it timed out waiting for #copy-recovery data-done, and earlier runs failed other auth timing assertions. Make it deterministic: wait on state, not wall-clock assumptions; run it with the CPU-priority scope in the gate; and keep its real budgets.

The motion-audit spec (apps/tracer/test/motion-audit.spec.ts) is flaky under CPU load: it timed out waiting for #copy-recovery data-done, and earlier runs failed other auth timing assertions. Make it deterministic: wait on state, not wall-clock assumptions; run it with the CPU-priority scope in the gate; and keep its real budgets.
Author
Owner

Start: branch fix-socket from dev ac03b1913b. I am addressing the four deadline/synchronization flakes requested by the orchestrator before the separate #51 socket fix; measuring baseline repetitions under host load and a CPUWeight scope.

Start: branch fix-socket from dev ac03b1913bfb6dd9b978477fc23ee5c88e276f67. I am addressing the four deadline/synchronization flakes requested by the orchestrator before the separate #51 socket fix; measuring baseline repetitions under host load and a CPUWeight scope.
Author
Owner

Finding: on infraternal-dev (x86_64, 8 cores; starting load 9.84/14.92/19.07), baseline review3_backend_reply_has_a_deadline failed on repetition 8 after 32,960 ms; repetitions 1–7 passed at about 60.5 s each. The test waits 61 s against the production 60 s terminal-open deadline. The remaining baseline repetitions are running.

Finding: on infraternal-dev (x86_64, 8 cores; starting load 9.84/14.92/19.07), baseline review3_backend_reply_has_a_deadline failed on repetition 8 after 32,960 ms; repetitions 1–7 passed at about 60.5 s each. The test waits 61 s against the production 60 s terminal-open deadline. The remaining baseline repetitions are running.
Author
Owner

Baseline finding on infraternal-dev (x86_64, 8 cores; load started 9.84/14.92/19.07 and ended 22.53/25.11/20.67): review3_backend_reply_has_a_deadline failed 10/20, review3_busy_expiry failed 13/20, and attached_backpressure_and_detached_progress failed 20/20 before reaching its assertion because the shim child reported ENOENT and its socket did not appear within 10 s. The initial review4 filter matched zero tests; those rows are discarded and I am rerunning with the exact module path.

Baseline finding on infraternal-dev (x86_64, 8 cores; load started 9.84/14.92/19.07 and ended 22.53/25.11/20.67): review3_backend_reply_has_a_deadline failed 10/20, review3_busy_expiry failed 13/20, and attached_backpressure_and_detached_progress failed 20/20 before reaching its assertion because the shim child reported ENOENT and its socket did not appear within 10 s. The initial review4 filter matched zero tests; those rows are discarded and I am rerunning with the exact module path.
Author
Owner

Corrected review4 baseline (exact filter auth::tests::review3_tests::review4_ten_second_open_preserves_authority): 5/20 passed and 15/20 failed on infraternal-dev; every failure ended with 'server closed websocket unexpectedly'. Test elapsed 2.47–43.88 s (median 15.11 s), including two real 10 s waits in passing runs; load ended 38.28/32.71/25.38. The earlier zero-test rows are excluded.

Corrected review4 baseline (exact filter auth::tests::review3_tests::review4_ten_second_open_preserves_authority): 5/20 passed and 15/20 failed on infraternal-dev; every failure ended with 'server closed websocket unexpectedly'. Test elapsed 2.47–43.88 s (median 15.11 s), including two real 10 s waits in passing runs; load ended 38.28/32.71/25.38. The earlier zero-test rows are excluded.
Author
Owner

Correction: the first direct shim-binary repetition used the worktree root as CWD, but crates/infraternal/tests/shim.rs resolves its fixture path from the package root. Its 20/20 ENOENT rows are invalid and must be ignored; I stopped that run and will repeat from crates/infraternal. The server-test baseline rows are unaffected.

Correction: the first direct shim-binary repetition used the worktree root as CWD, but crates/infraternal/tests/shim.rs resolves its fixture path from the package root. Its 20/20 ENOENT rows are invalid and must be ignored; I stopped that run and will repeat from crates/infraternal. The server-test baseline rows are unaffected.
Author
Owner

Valid base measurements complete (infraternal-dev x86_64, 8 cores; load varied about 10–38): under load, backend deadline passed 10/20 (median 46.70 s; 10 failures), busy expiry 7/20 (13 failures), review4 ten-second open 5/20 (15 failures; median 15.11 s), and detached producer 7/20 (13 failures; failures hit the fixed 2 s output assertion). Under systemd-run --user --scope -p CPUWeight=10000: backend 19/20, busy expiry 20/20, review4 19/20 (median 22.00 s), detached producer 20/20 (median 2.53 s). All shim runs now used crates/infraternal as CWD; invalid wrong-CWD rows are discarded.

Valid base measurements complete (infraternal-dev x86_64, 8 cores; load varied about 10–38): under load, backend deadline passed 10/20 (median 46.70 s; 10 failures), busy expiry 7/20 (13 failures), review4 ten-second open 5/20 (15 failures; median 15.11 s), and detached producer 7/20 (13 failures; failures hit the fixed 2 s output assertion). Under systemd-run --user --scope -p CPUWeight=10000: backend 19/20, busy expiry 20/20, review4 19/20 (median 22.00 s), detached producer 20/20 (median 2.53 s). All shim runs now used crates/infraternal as CWD; invalid wrong-CWD rows are discarded.
Author
Owner

Finding: the PTY login shell changes cwd to /home/kayg, so the relative completion marker was never created; the output still reached sequence 1,490,028 (observed from the live shim socket). The test marker will use an absolute path under its session state.

Finding: the PTY login shell changes cwd to /home/kayg, so the relative completion marker was never created; the output still reached sequence 1,490,028 (observed from the live shim socket). The test marker will use an absolute path under its session state.
Author
Owner

Additional finding from the fast gate: review3_revoked_resume_must_not_welcome also has a 100ms close assertion. Before changing it, it passed 19/20 under ambient load and 5/20 under systemd-run --user --scope -p CPUWeight=10000 (8-core infraternal-dev; close event still arrives later). I am adding it to this determinism repair.

Additional finding from the fast gate: review3_revoked_resume_must_not_welcome also has a 100ms close assertion. Before changing it, it passed 19/20 under ambient load and 5/20 under systemd-run --user --scope -p CPUWeight=10000 (8-core infraternal-dev; close event still arrives later). I am adding it to this determinism repair.
Author
Owner

Determinism repair committed as c5af3d1. On the 8-core x86_64 host, all five cases now pass 20/20 under ambient load and 20/20 under systemd-run CPUWeight=10000: backend deadline, busy expiry, review4 open/revocation, detached shim, and revoked Resume. Post medians under load: 3.016s, 0.994s, 2.217s, 2.295s, 0.525s; CPUWeight: 2.864s, 0.766s, 1.434s, 0.790s, 0.555s. Before counts and failure evidence are in the preceding comments and commit body.

The successful combined-worktree gate ran as systemd-run --user --scope --quiet --property=CPUWeight=10000 -- scripts/verify fast. Verbatim summary output:

METRIC name=network_rtt_selftest configured_rtt_ms=300 jitter_ms=30 loss=unsupported transport=tcp-stream n=3 p50_ms=303.56 p99_ms=306.60 result=PASS
| fmt                       | PASS         |
| VT native fmt             | PASS         |
| clippy                    | PASS         |
| test                      | PASS         |
| cargo-deny                | PASS         |
| static builds             | PASS         |
JavaScript transfer: identity=800596 gzip=243302/307200 brotli=199731/256000 bytes
stream differential: 134 streams, 11439 schedules, zero divergences
7 pass
0 fail
Determinism repair committed as c5af3d1. On the 8-core x86_64 host, all five cases now pass 20/20 under ambient load and 20/20 under systemd-run CPUWeight=10000: backend deadline, busy expiry, review4 open/revocation, detached shim, and revoked Resume. Post medians under load: 3.016s, 0.994s, 2.217s, 2.295s, 0.525s; CPUWeight: 2.864s, 0.766s, 1.434s, 0.790s, 0.555s. Before counts and failure evidence are in the preceding comments and commit body. The successful combined-worktree gate ran as `systemd-run --user --scope --quiet --property=CPUWeight=10000 -- scripts/verify fast`. Verbatim summary output: ```text METRIC name=network_rtt_selftest configured_rtt_ms=300 jitter_ms=30 loss=unsupported transport=tcp-stream n=3 p50_ms=303.56 p99_ms=306.60 result=PASS | fmt | PASS | | VT native fmt | PASS | | clippy | PASS | | test | PASS | | cargo-deny | PASS | | static builds | PASS | JavaScript transfer: identity=800596 gzip=243302/307200 brotli=199731/256000 bytes stream differential: 134 streams, 11439 schedules, zero divergences 7 pass 0 fail ```
Author
Owner

Final lane head is fbe257906a; #65 changes are isolated in c5af3d1, followed by the requested #51 fix. All five flake cases pass 20/20 under ambient load and 20/20 under CPUWeight=10000; before/after counts and medians are recorded in the prior comment and c5af3d1.

Final combined-tree gate command: systemd-run --user --scope --quiet --property=CPUWeight=10000 -- scripts/verify fast (exit 0). Verbatim summary:

METRIC name=network_rtt_selftest configured_rtt_ms=300 jitter_ms=30 loss=unsupported transport=tcp-stream n=3 p50_ms=303.56 p99_ms=306.60 result=PASS
+---------------------------+--------------+
| Rust gate                 | Result       |
+---------------------------+--------------+
| fmt                       | PASS         |
| VT native fmt             | PASS         |
| clippy                    | PASS         |
| test                      | PASS         |
| cargo-deny                | PASS         |
| static builds             | PASS         |
+---------------------------+--------------+
JavaScript transfer: identity=800596 gzip=243302/307200 brotli=199731/256000 bytes
stream differential: 134 streams, 11439 schedules, zero divergences
7 pass
0 fail
Final lane head is fbe257906a75b5013ba932e86a14bb4905332aac; #65 changes are isolated in c5af3d1, followed by the requested #51 fix. All five flake cases pass 20/20 under ambient load and 20/20 under CPUWeight=10000; before/after counts and medians are recorded in the prior comment and c5af3d1. Final combined-tree gate command: `systemd-run --user --scope --quiet --property=CPUWeight=10000 -- scripts/verify fast` (exit 0). Verbatim summary: ```text METRIC name=network_rtt_selftest configured_rtt_ms=300 jitter_ms=30 loss=unsupported transport=tcp-stream n=3 p50_ms=303.56 p99_ms=306.60 result=PASS +---------------------------+--------------+ | Rust gate | Result | +---------------------------+--------------+ | fmt | PASS | | VT native fmt | PASS | | clippy | PASS | | test | PASS | | cargo-deny | PASS | | static builds | PASS | +---------------------------+--------------+ JavaScript transfer: identity=800596 gzip=243302/307200 brotli=199731/256000 bytes stream differential: 134 streams, 11439 schedules, zero divergences 7 pass 0 fail ```
Author
Owner

Self-review complete: every changed deadline override is behind cfg(test); release code still uses the original handshake, authority-read, terminal-open and embedded-agent values. The shim synchronization is confined to the real-process test fixture.

Self-review complete: every changed deadline override is behind cfg(test); release code still uses the original handshake, authority-read, terminal-open and embedded-agent values. The shim synchronization is confined to the real-process test fixture.
Author
Owner

Start: branch fix-reviewer-clock from dev 907e89e2cb. I read the #65 and #45 histories. I will make both expired-finish tests control expiry deterministically around writer contention, preserve production expiry behavior, and verify both tests under ambient and CPUWeight=10000 load plus a commit-time-check removal mutation.

Start: branch fix-reviewer-clock from dev 907e89e2cb63ec4bbaa4901302e9f86f1316fb85. I read the #65 and #45 histories. I will make both expired-finish tests control expiry deterministically around writer contention, preserve production expiry behavior, and verify both tests under ambient and CPUWeight=10000 load plus a commit-time-check removal mutation.
Author
Owner

Finding: reviewer_tests.rs:184-197 samples SystemTime, then sets recovery expiry to now+1s before recovery-ready. HTTP uses the live global clock (http.rs:206-213), so scheduling/storage delay can correctly yield 401 before the test reaches its writer-wait assertion. #45 records this exact setup failure (recovery-ready expected 200, got 401); this host's load varied 22.53 to 15.70 on the 1-minute average. A baseline capability run passed 1/1 in 4.51s, confirming the failure window is intermittent. I will use a cfg(test) HTTP clock override while retaining the production clock and commit-time SQL predicates.

Finding: reviewer_tests.rs:184-197 samples SystemTime, then sets recovery expiry to now+1s before recovery-ready. HTTP uses the live global clock (http.rs:206-213), so scheduling/storage delay can correctly yield 401 before the test reaches its writer-wait assertion. #45 records this exact setup failure (recovery-ready expected 200, got 401); this host's load varied 22.53 to 15.70 on the 1-minute average. A baseline capability run passed 1/1 in 4.51s, confirming the failure window is intermittent. I will use a cfg(test) HTTP clock override while retaining the production clock and commit-time SQL predicates.
Author
Owner

Mutation proof: temporarily removed expires>MAX(?,unixepoch()) from recovery::complete in crates/infraternal-server/src/auth/recovery.rs, leaving the rest unchanged. reviewer_http_expired_capability_cannot_complete_after_writer_wait then returned HTTP 200 (expected 401) and failed at reviewer_tests.rs:257 (0/1 passed, 3.30s; expiry-mutation.log). The pre-mutation recovery.rs is saved in job scratch and is being restored now.

Mutation proof: temporarily removed `expires>MAX(?,unixepoch())` from recovery::complete in crates/infraternal-server/src/auth/recovery.rs, leaving the rest unchanged. reviewer_http_expired_capability_cannot_complete_after_writer_wait then returned HTTP 200 (expected 401) and failed at reviewer_tests.rs:257 (0/1 passed, 3.30s; expiry-mutation.log). The pre-mutation recovery.rs is saved in job scratch and is being restored now.
Author
Owner

Step complete (uncommitted diff on head 907e89e2cb): added a cfg(test)-only shared HTTP clock and advanced expiry only after the existing writer wait. Both tests passed 20/20 under ambient load and 20/20 under systemd-run --user --scope -p CPUWeight=10000 (80/80 total). Ambient host infraternal-dev, 8 cores, load average start/end 2.30/8.35/12.61 and 4.04/7.72/11.72; CPUWeight scope start/end 3.27/7.24/11.46 and 1.49/5.20/10.12. Removing the statement-time recovery-expiry predicate makes the capability test return 200 and fail its expected-401 assertion (0/1). Running scripts/verify fast next.

Step complete (uncommitted diff on head 907e89e2cb63ec4bbaa4901302e9f86f1316fb85): added a cfg(test)-only shared HTTP clock and advanced expiry only after the existing writer wait. Both tests passed 20/20 under ambient load and 20/20 under `systemd-run --user --scope -p CPUWeight=10000` (80/80 total). Ambient host infraternal-dev, 8 cores, load average start/end 2.30/8.35/12.61 and 4.04/7.72/11.72; CPUWeight scope start/end 3.27/7.24/11.46 and 1.49/5.20/10.12. Removing the statement-time recovery-expiry predicate makes the capability test return 200 and fail its expected-401 assertion (0/1). Running scripts/verify fast next.
Author
Owner

Fast-gate environment finding: the first scoped run exited 1 because the agent attach-credit fixture could not create relative target/ac1206527 (FileNotFoundError at scripts/verify-agent-attach-credit.py:54), and the musl wrappers could not find target/auth-tools/zig/zig while CARGO_TARGET_DIR pointed to scratch (verify-fast.log). This is the known target-path assumption recorded on #45; no source test failed in the recovery code. I will make the ignored worktree target an alias to the job scratch target and rerun.

Fast-gate environment finding: the first scoped run exited 1 because the agent attach-credit fixture could not create relative `target/ac1206527` (FileNotFoundError at scripts/verify-agent-attach-credit.py:54), and the musl wrappers could not find `target/auth-tools/zig/zig` while CARGO_TARGET_DIR pointed to scratch (verify-fast.log). This is the known target-path assumption recorded on #45; no source test failed in the recovery code. I will make the ignored worktree `target` an alias to the job scratch target and rerun.
Author
Owner

Finished: head 9e99820ff5 (test: control recovery reviewer HTTP expiry clock (#65 #45)). The cfg(test) clock is opt-in and shared by cloned HTTP routers. The test keeps time before expiry while the writer is held, then advances it; production time, expiry checks and constants are unchanged. Auth self-review checklist B1/S1/S2/N1 is complete.

Repetitions on infraternal-dev (8 cores): each test passed 20/20 under ambient load and 20/20 in systemd-run --user --scope -p CPUWeight=10000 (80/80 total). Ambient load average start/end: 2.30/8.35/12.61 and 4.04/7.72/11.72. CPUWeight scope start/end: 3.27/7.24/11.46 and 1.49/5.20/10.12.

Mutation proof: removing expires>MAX(?,unixepoch()) from recovery::complete made reviewer_http_expired_capability_cannot_complete_after_writer_wait return HTTP 200 instead of 401; 0 passed / 1 failed. Mutation reverted.

scripts/verify fast command: systemd-run --user --scope -p CPUWeight=10000 env CARGO_TARGET_DIR=$HOME/.cache/codex-scratch/fix-reviewer-clock/verify-target RUST_TEST_THREADS=1 TRACER_TEST_PORT=4865 scripts/verify fast — exit 0.

Verbatim gate summary:

METRIC name=network_rtt_selftest configured_rtt_ms=300 jitter_ms=30 loss=unsupported transport=tcp-stream n=3 p50_ms=308.51 p99_ms=318.03 result=PASS

test result: ok. 100 passed; 0 failed; 9 ignored; 0 measured; 0 filtered out; finished in 150.71s

PT_INTERP: absent; size: 15965392 bytes (baseline 16142672 + allowance 262144 = max 16404816)
PT_INTERP: absent; size: 13426064 bytes (baseline 13555672 + allowance 262144 = max 13817816)

+---------------------------+--------------+
| Rust gate                 | Result       |
+---------------------------+--------------+
| fmt                       | PASS         |
| VT native fmt             | PASS         |
| clippy                    | PASS         |
| test                      | PASS         |
| cargo-deny                | PASS         |
| static builds             | PASS         |
+---------------------------+--------------+

 20 pass
 0 fail
 376 expect() calls
Ran 20 tests across 6 files. [187.00ms]
JavaScript transfer: identity=821193 gzip=250827/307200 brotli=206392/256000 bytes
stream differential: 134 streams, 11439 schedules, zero divergences
 7 pass
 0 fail
 34390 expect() calls
Ran 7 tests across 2 files. [2.75s]
Finished: head 9e99820ff58910fa7bb96b65ad0a7f0d005ef9b8 (`test: control recovery reviewer HTTP expiry clock (#65 #45)`). The cfg(test) clock is opt-in and shared by cloned HTTP routers. The test keeps time before expiry while the writer is held, then advances it; production time, expiry checks and constants are unchanged. Auth self-review checklist B1/S1/S2/N1 is complete. Repetitions on infraternal-dev (8 cores): each test passed 20/20 under ambient load and 20/20 in `systemd-run --user --scope -p CPUWeight=10000` (80/80 total). Ambient load average start/end: 2.30/8.35/12.61 and 4.04/7.72/11.72. CPUWeight scope start/end: 3.27/7.24/11.46 and 1.49/5.20/10.12. Mutation proof: removing `expires>MAX(?,unixepoch())` from `recovery::complete` made `reviewer_http_expired_capability_cannot_complete_after_writer_wait` return HTTP 200 instead of 401; 0 passed / 1 failed. Mutation reverted. `scripts/verify fast` command: `systemd-run --user --scope -p CPUWeight=10000 env CARGO_TARGET_DIR=$HOME/.cache/codex-scratch/fix-reviewer-clock/verify-target RUST_TEST_THREADS=1 TRACER_TEST_PORT=4865 scripts/verify fast` — exit 0. Verbatim gate summary: ```text METRIC name=network_rtt_selftest configured_rtt_ms=300 jitter_ms=30 loss=unsupported transport=tcp-stream n=3 p50_ms=308.51 p99_ms=318.03 result=PASS test result: ok. 100 passed; 0 failed; 9 ignored; 0 measured; 0 filtered out; finished in 150.71s PT_INTERP: absent; size: 15965392 bytes (baseline 16142672 + allowance 262144 = max 16404816) PT_INTERP: absent; size: 13426064 bytes (baseline 13555672 + allowance 262144 = max 13817816) +---------------------------+--------------+ | Rust gate | Result | +---------------------------+--------------+ | fmt | PASS | | VT native fmt | PASS | | clippy | PASS | | test | PASS | | cargo-deny | PASS | | static builds | PASS | +---------------------------+--------------+ 20 pass 0 fail 376 expect() calls Ran 20 tests across 6 files. [187.00ms] JavaScript transfer: identity=821193 gzip=250827/307200 brotli=206392/256000 bytes stream differential: 134 streams, 11439 schedules, zero divergences 7 pass 0 fail 34390 expect() calls Ran 7 tests across 2 files. [2.75s] ```
Author
Owner

Closed by the orchestrator during the 2026-11-09 night housekeeping (owner order: "close stale prs/issues"). The work has landed on dev, and the latest note here is a finish or merge note (J387 inventory on #436). Reopen if anything is still missing.

Closed by the orchestrator during the 2026-11-09 night housekeeping (owner order: "close stale prs/issues"). The work has landed on dev, and the latest note here is a finish or merge note (J387 inventory on #436). Reopen if anything is still missing.
kayg closed this issue 2026-11-08 19:04:31 +00:00
Sign in to join this conversation.
No labels
launch-qa
No milestone
No project
No assignees
1 participant
Notifications
Due date
The due date is invalid or out of range. Please use the format "yyyy-mm-dd".

No due date set.

Dependencies

No dependencies set

Reference
kayg/infraternal#65
No description provided.