kayg/infraternal

Watch

Fork 0

J439: load-only test flakes (shim terminal lease, rootless cleanup, text file busy, liveness doubt) #475

New issue

Open

opened 2026-11-09 13:03:56 +00:00 by kayg · 6 comments

kayg commented

2026-11-09 13:03:56 +00:00

Owner

Load-only flakes seen during verify fast on a busy compute01 (J411 evidence: compute01 ~/.cache/codex-scratch/j411/evidence/verify-fast.log):

infraternal-shim login_lifecycle::unauthorized_controller_is_refused_before_terminal_acceptance: "worker retained a released terminal lease". Passed 5/5 alone.
real_binary_rootless_cleanup_survives_sender_disconnect_before_readiness (resource_unavailable)
login_binary::tests::cleanup_preserves_running_images_for_fallback_adoption ("Text file busy")
liveness_doubt...retires_the_link (timing)

Plan: reproduce each in a loop under stress-ng/parallel-build load via build-slot, find the cause (timeout vs real product race vs test isolation), fix (product fix + deterministic test for real races; condition waits with generous bounds for timing), prove 50/50 under load. Branch fix-load-flakes from origin/dev 6df0f5bd5. Estimate: 3-4 h incl. queue (compute01 queue ~13 deep at start).

Load-only flakes seen during `verify fast` on a busy compute01 (J411 evidence: compute01 ~/.cache/codex-scratch/j411/evidence/verify-fast.log): - `infraternal-shim` `login_lifecycle::unauthorized_controller_is_refused_before_terminal_acceptance`: "worker retained a released terminal lease". Passed 5/5 alone. - `real_binary_rootless_cleanup_survives_sender_disconnect_before_readiness` (resource_unavailable) - `login_binary::tests::cleanup_preserves_running_images_for_fallback_adoption` ("Text file busy") - `liveness_doubt...retires_the_link` (timing) Plan: reproduce each in a loop under stress-ng/parallel-build load via build-slot, find the cause (timeout vs real product race vs test isolation), fix (product fix + deterministic test for real races; condition waits with generous bounds for timing), prove 50/50 under load. Branch `fix-load-flakes` from origin/dev 6df0f5bd5. Estimate: 3-4 h incl. queue (compute01 queue ~13 deep at start).

kayg commented

2026-11-09 13:04:01 +00:00

Author

Owner

Start: branch fix-load-flakes, base 6df0f5bd5e (origin/dev). First hypothesis for the shim case: Worker::retired waits 5 s but the worker idles out after a 3 s grace measured from its own start, so a worker starved for ~2 s fails the test. Not yet confirmed; reproducing under load first.

Start: branch `fix-load-flakes`, base 6df0f5bd5e2e5a519e249f729c4ba2dd1b5bd991 (origin/dev). First hypothesis for the shim case: `Worker::retired` waits 5 s but the worker idles out after a 3 s grace measured from its own start, so a worker starved for ~2 s fails the test. Not yet confirmed; reproducing under load first.

kayg commented

2026-11-09 13:08:41 +00:00

Author

Owner

Progress: harness queued on compute01 build-slot (queue ~14 deep, expect a long wait). Script ~/.cache/codex-scratch/j439/run.sh builds the 4 test binaries and loops each 20x under 12 CPU spinners + 2 fsync writers (no stress-ng installed; box already at load avg ~45 on 16 vCPUs). Log: ~/.cache/codex-scratch/j439/run1.log, evidence dir ~/.cache/codex-scratch/j439/evidence/.

Static findings so far (not yet reproduced):

shim: Worker::retired waits 5 s; the worker idles out 3 s after its own startup. Unauthorized connections do not refresh that deadline, so failure needs the worker stalled >5 s past its deadline.
Text file busy: the fork-with-open-writer race is already documented in login_binary.rs tests (source() comment); cleanup_preserves_running_images_for_fallback_adoption still execs old directly after staged() in a multithreaded test process, so another test thread forking during the copy keeps ETXTBSY alive until its child execs.
sibling failure in older logs: real_binary_rootless_person_revocation_stops_existing_shells hit a 1 s child.wait timeout in agent_fixture.py (same class).

Progress: harness queued on compute01 build-slot (queue ~14 deep, expect a long wait). Script `~/.cache/codex-scratch/j439/run.sh` builds the 4 test binaries and loops each 20x under 12 CPU spinners + 2 fsync writers (no stress-ng installed; box already at load avg ~45 on 16 vCPUs). Log: `~/.cache/codex-scratch/j439/run1.log`, evidence dir `~/.cache/codex-scratch/j439/evidence/`. Static findings so far (not yet reproduced): - shim: `Worker::retired` waits 5 s; the worker idles out 3 s after its own startup. Unauthorized connections do not refresh that deadline, so failure needs the worker stalled >5 s past its deadline. - Text file busy: the fork-with-open-writer race is already documented in `login_binary.rs` tests (`source()` comment); `cleanup_preserves_running_images_for_fallback_adoption` still execs `old` directly after `staged()` in a multithreaded test process, so another test thread forking during the copy keeps ETXTBSY alive until its child execs. - sibling failure in older logs: `real_binary_rootless_person_revocation_stops_existing_shells` hit a 1 s `child.wait` timeout in `agent_fixture.py` (same class).

kayg commented

2026-11-09 15:10:32 +00:00

Author

Owner

Findings so far (evidence on compute01 under ~/.cache/codex-scratch/; harness and logs for my runs on dev-02 under ~/.cache/codex-scratch/j439/):

Not reproducible with simple load. On dev-02 (10 cores), 20 serial loops and 24 parallel copies per test with 8-12 CPU spinners passed 100% for the agent, daemon and server tests. (My first shim loop also "passed", but only because the test is compiled behind the host-login feature and --exact matching nothing exits 0. Corrected below.) A whole-suite shim run (3 copies x 8 rounds, 8 spinners, --features host-login) had 0 failures and a worker retire latency of 3023-3027 ms, i.e. just the 3 s idle grace. Heavier run queued.

1. shim unauthorized_controller_is_refused_before_terminal_acceptance, "worker retained a released terminal lease" (j411/evidence/verify-fast.log:6341). The worker retires 3 s after startup (GRACE) and Worker::retired waits only 5 s, so the bound leaves 2 s of margin. Retirement also runs loginctl show-session (a D-Bus round trip) before exit. Every other wait in the file is also a fixed 5 s. No product race found: the worker's retirement logic is sound (no deadline refresh on unauthorised peers). Fix: one WAIT bound of 60 s for all conditions that return as soon as they hold.

2. login_binary::tests::cleanup_preserves_running_images_for_fallback_adoption, "Text file busy". Real mechanism, not a flake of the test's own logic: publish copies the image through a writable descriptor; a sibling test thread that forks during the copy keeps that descriptor (CLOEXEC only acts at exec) until its child execs, and exec of the image fails with ETXTBSY for exactly that window. Same class in anonymous_kernel_image_can_be_published_after_unlink (appwin-launch-idle-146/evidence/verify-fast-text-file-busy.log), agent_sessions::detached_shim_is_discovered... (j60b). Fix: exec_when_not_busy retries only ETXTBSY; deterministic test holds a write descriptor, observes ETXTBSY, releases it inside the attempt. (Note for the orchestrator: production has the same window if the agent forks while publishing and systemd execs the image at that moment. Not changed here; rare, and the fix would live in systemd's exec.)

3. remote_runtime::...liveness_doubt::one_missed_primary_reply_shows_reconnecting_and_only_a_second_retires_the_link. Two failure modes in the logs:

j395/evidence/fast4.log:4789-4793: "the link retired on its first miss: 366ms" (doubt_ms=222). The test measured from its own answer.store(false), but the product counts from the last reply it received; with probes delayed under load the last reply sits well before that instant. 222 ms < the 250 ms floor shows the reference is wrong, not the product.
j51/evidence/verify-fast-ratcheted.log:2670-2673: "unexpected recovery notice Some(Reconnecting)": the test must answer inside a 250 ms window it does not control; when starved past 500 ms the link retires, correctly.
Fix (test only): measure every bound from the fixture's own last-reply stamp (a strict bound on the server's clock) and treat a run in which the fixture was starved past the allowance as not-a-trial, repeating the scenario (max 6). A run that stayed inside the allowances and still misbehaves fails immediately.

4. real_binary_rootless_cleanup_survives_sender_disconnect_before_readiness, resource_unavailable (j332/evidence/a-fast-final.log:1161-1173). The oracle's three real assertions had already passed (cleanup_byte_written, sender_disconnected, owned_shell_stopped all true); the failure is its final cleanup call control(..., 'terminal.login.revoke') returning resource_unavailable, which the agent maps from any non-InvalidInput io error out of logins::revoke (daemon.rs ~l.405-430). Investigating under heavier load to find which io error.

Findings so far (evidence on compute01 under `~/.cache/codex-scratch/`; harness and logs for my runs on dev-02 under `~/.cache/codex-scratch/j439/`): **Not reproducible with simple load.** On dev-02 (10 cores), 20 serial loops and 24 parallel copies per test with 8-12 CPU spinners passed 100% for the agent, daemon and server tests. (My first shim loop also "passed", but only because the test is compiled behind the `host-login` feature and `--exact` matching nothing exits 0. Corrected below.) A whole-suite shim run (3 copies x 8 rounds, 8 spinners, `--features host-login`) had 0 failures and a worker retire latency of 3023-3027 ms, i.e. just the 3 s idle grace. Heavier run queued. **1. shim `unauthorized_controller_is_refused_before_terminal_acceptance`, "worker retained a released terminal lease"** (`j411/evidence/verify-fast.log:6341`). The worker retires 3 s after startup (`GRACE`) and `Worker::retired` waits only 5 s, so the bound leaves 2 s of margin. Retirement also runs `loginctl show-session` (a D-Bus round trip) before exit. Every other wait in the file is also a fixed 5 s. No product race found: the worker's retirement logic is sound (no deadline refresh on unauthorised peers). Fix: one `WAIT` bound of 60 s for all conditions that return as soon as they hold. **2. `login_binary::tests::cleanup_preserves_running_images_for_fallback_adoption`, "Text file busy".** Real mechanism, not a flake of the test's own logic: `publish` copies the image through a writable descriptor; a sibling test thread that forks during the copy keeps that descriptor (CLOEXEC only acts at exec) until its child execs, and exec of the image fails with ETXTBSY for exactly that window. Same class in `anonymous_kernel_image_can_be_published_after_unlink` (`appwin-launch-idle-146/evidence/verify-fast-text-file-busy.log`), `agent_sessions::detached_shim_is_discovered...` (`j60b`). Fix: `exec_when_not_busy` retries only ETXTBSY; deterministic test holds a write descriptor, observes ETXTBSY, releases it inside the attempt. (Note for the orchestrator: production has the same window if the agent forks while publishing and systemd execs the image at that moment. Not changed here; rare, and the fix would live in systemd's exec.) **3. `remote_runtime::...liveness_doubt::one_missed_primary_reply_shows_reconnecting_and_only_a_second_retires_the_link`.** Two failure modes in the logs: - `j395/evidence/fast4.log:4789-4793`: "the link retired on its first miss: 366ms" (doubt_ms=222). The test measured from its own `answer.store(false)`, but the product counts from the last reply it received; with probes delayed under load the last reply sits well before that instant. 222 ms < the 250 ms floor shows the reference is wrong, not the product. - `j51/evidence/verify-fast-ratcheted.log:2670-2673`: "unexpected recovery notice Some(Reconnecting)": the test must answer inside a 250 ms window it does not control; when starved past 500 ms the link retires, correctly. Fix (test only): measure every bound from the fixture's own last-reply stamp (a strict bound on the server's clock) and treat a run in which the fixture was starved past the allowance as not-a-trial, repeating the scenario (max 6). A run that stayed inside the allowances and still misbehaves fails immediately. **4. `real_binary_rootless_cleanup_survives_sender_disconnect_before_readiness`, `resource_unavailable`** (`j332/evidence/a-fast-final.log:1161-1173`). The oracle's three real assertions had already passed (`cleanup_byte_written`, `sender_disconnected`, `owned_shell_stopped` all true); the failure is its final cleanup call `control(..., 'terminal.login.revoke')` returning `resource_unavailable`, which the agent maps from any non-InvalidInput io error out of `logins::revoke` (`daemon.rs` ~l.405-430). Investigating under heavier load to find which io error.

kayg commented

2026-11-09 16:06:40 +00:00

Author

Owner

Update (evidence on dev-02 under ~/.cache/codex-scratch/j439/; harness scripts there: run.sh, par.sh, suite.sh, y.sh, final.sh):

Reproduced: #4 real_binary_rootless_cleanup_survives_sender_disconnect_before_readiness. 40 parallel copies x 4 rounds + 16 CPU spinners: 3 of 160 failed, same message as compute01 (control action result differs: resource_unavailable after all three oracle checks were true). Files: evidence/daemon/FAIL-r1-c7.log, FAIL-r2-c23.log, FAIL-r2-c29.log, summary in y1.log. A temporary VM-only trace (never committed) of the io error behind resource_unavailable printed Custom { kind: ConnectionReset, ... } three times out of three. Cause: the revoke's rootless_sessions::stop connects to the shim's .stop socket while the shim is still retiring from the earlier stop request (sender had disconnected) and the shim hangs up. A real product race: the person stays denied and the owner retries in the background, but the first caller gets a spurious refusal. Fix in product (stop accepts the sealed exit record, which the shim writes before it exits, as proof after an attempt that ended because the shim left; no record = still refused), with two deterministic tests.

Not reproduced (honest):

shim lifecycle suite, 10 copies at once + 24 spinners, --features host-login: 0 failures, worker retire latency max 3117 ms (grace is 3000 ms). It takes a >5 s stall to hit the old bound; I could not produce one. The failure on compute01 is therefore inferred to be a host stall (it was at load ~45 on 16 vCPUs, a host that has OOMed this week). The fix (60 s condition bound) is justified by the 2 s margin, not by a reproduction.
liveness test baseline, 64 copies x 3 rounds + 16 spinners: 0 of 192 failed. The two failures in the compute01 logs were analysed from their messages (see previous comment) and the new test measures from the correct clock.
ETXTBSY test baseline: 0 of 72 at 24 copies. Mechanism analysed and covered by a deterministic test; fork-during-copy needs the sibling tests of the whole module, which the final run includes (login_binary:: module x 40 copies).

Branch head now 64974e5c4 (four atomic commits on current origin/dev). Final validation (new tests once + each flaky test x 120 under the same load) is queued; verify quick / verify fast follow.

Update (evidence on dev-02 under `~/.cache/codex-scratch/j439/`; harness scripts there: `run.sh`, `par.sh`, `suite.sh`, `y.sh`, `final.sh`): **Reproduced: #4 `real_binary_rootless_cleanup_survives_sender_disconnect_before_readiness`.** 40 parallel copies x 4 rounds + 16 CPU spinners: **3 of 160 failed**, same message as compute01 (`control action result differs: resource_unavailable` after all three oracle checks were true). Files: `evidence/daemon/FAIL-r1-c7.log`, `FAIL-r2-c23.log`, `FAIL-r2-c29.log`, summary in `y1.log`. A temporary VM-only trace (never committed) of the io error behind `resource_unavailable` printed `Custom { kind: ConnectionReset, ... }` three times out of three. Cause: the revoke's `rootless_sessions::stop` connects to the shim's `.stop` socket while the shim is still retiring from the earlier stop request (sender had disconnected) and the shim hangs up. A real product race: the person stays denied and the owner retries in the background, but the first caller gets a spurious refusal. Fix in product (`stop` accepts the sealed exit record, which the shim writes before it exits, as proof after an attempt that ended because the shim left; no record = still refused), with two deterministic tests. **Not reproduced (honest):** - shim lifecycle suite, 10 copies at once + 24 spinners, `--features host-login`: 0 failures, worker retire latency max 3117 ms (grace is 3000 ms). It takes a >5 s stall to hit the old bound; I could not produce one. The failure on compute01 is therefore inferred to be a host stall (it was at load ~45 on 16 vCPUs, a host that has OOMed this week). The fix (60 s condition bound) is justified by the 2 s margin, not by a reproduction. - liveness test baseline, 64 copies x 3 rounds + 16 spinners: 0 of 192 failed. The two failures in the compute01 logs were analysed from their messages (see previous comment) and the new test measures from the correct clock. - ETXTBSY test baseline: 0 of 72 at 24 copies. Mechanism analysed and covered by a deterministic test; fork-during-copy needs the sibling tests of the whole module, which the final run includes (`login_binary::` module x 40 copies). Branch head now `64974e5c4` (four atomic commits on current origin/dev). Final validation (new tests once + each flaky test x 120 under the same load) is queued; `verify quick` / `verify fast` follow.

kayg commented

2026-11-09 16:09:07 +00:00

Author

Owner

Evidence for the flake hunt, from J407 (#447). logins::tests::a_linger_request_landing_after_disable_never_survives_revocation:

Failed once in scripts/verify fast on compute01, 2026-11-09 ~15:40 UTC, branch latency-targets-120hz at 174127529. That branch has no Rust changes, so the test binary is dev's at that time. Load average was 34–50 on 16 cores (the workspace cargo test running in parallel next to other jobs):

thread 'logins::tests::a_linger_request_landing_after_disable_never_survives_revocation' (1199672) panicked at crates/infraternal-agent/src/logins.rs:2077:9:
assertion `left == right` failed: "systemctl show --property=LoadState --property=ActiveState --property=ControlGroup --property=MainPID infraternal-login-555b3d8fae2646b3acbfed9526cbbdae-1500.service\nsystemctl stop infraternal-login-555b3d8fae2646b…
  left: 3
 right: 2

Log: compute01:~/.cache/codex-scratch/j407/fast.log around line 2306. That target was deleted afterwards, but the log is kept.

Passed 3/3 straight after, run alone on the same target at load 50: cargo test --locked -q -p infraternal-agent --lib logins::tests::a_linger_request_landing_after_disable_never_survives_revocation gave test result: ok. 1 passed ×3 (0.62–0.67 s).
What it looks like: the test counts systemctl invocations. Under contention, one extra systemctl call happens (3 instead of 2) before the revocation lands, so the race the test describes resolves the other way when the scheduler is slow. Either the assertion assumes an ordering the code doesn't guarantee, or the code issues a redundant call under load. I haven't traced which.

Evidence for the flake hunt, from J407 (#447). `logins::tests::a_linger_request_landing_after_disable_never_survives_revocation`: - **Failed** once in `scripts/verify fast` on compute01, 2026-11-09 ~15:40 UTC, branch `latency-targets-120hz` at `174127529`. That branch has no Rust changes, so the test binary is dev's at that time. Load average was 34–50 on 16 cores (the workspace `cargo test` running in parallel next to other jobs): ``` thread 'logins::tests::a_linger_request_landing_after_disable_never_survives_revocation' (1199672) panicked at crates/infraternal-agent/src/logins.rs:2077:9: assertion `left == right` failed: "systemctl show --property=LoadState --property=ActiveState --property=ControlGroup --property=MainPID infraternal-login-555b3d8fae2646b3acbfed9526cbbdae-1500.service\nsystemctl stop infraternal-login-555b3d8fae2646b… left: 3 right: 2 ``` Log: `compute01:~/.cache/codex-scratch/j407/fast.log` around line 2306. That target was deleted afterwards, but the log is kept. - **Passed** 3/3 straight after, run alone on the same target at load 50: `cargo test --locked -q -p infraternal-agent --lib logins::tests::a_linger_request_landing_after_disable_never_survives_revocation` gave `test result: ok. 1 passed` ×3 (0.62–0.67 s). - What it looks like: the test counts systemctl invocations. Under contention, one extra `systemctl` call happens (3 instead of 2) before the revocation lands, so the race the test describes resolves the other way when the scheduler is slow. Either the assertion assumes an ordering the code doesn't guarantee, or the code issues a redundant call under load. I haven't traced which.

kayg referenced this issue

2026-11-09 17:13:59 +00:00

Latency gate: D375 120 Hz target table in PROCESS §6 and verify latency (J407) #447

kayg commented

2026-11-09 17:34:34 +00:00

Author

Owner

5. breakit2_concurrent_same_destination_issues_only_one_invitation (left: 2, right: 1): a test assumption, not a product race. Reproduced on dev-02 with the unmodified test (origin/dev 5eb968744 test code): 8 copies x 10 rounds + 16 CPU spinners, 13/80 and 9/80 failed (evidence/dest/old-1/FAIL-*.log, old-2/). A VM-only trace of the events (never committed) shows exactly two batches with host_id: Some and step Failed ("Joining the host to this server failed", i.e. each issued an invitation and then hit the fixture's post-invitation refusal) and six refused with "This host is already being added" (host_id: None).

Why that is not a double issue: reserve_attempt checks and inserts under one attempts mutex, so two attempts for one destination cannot be live together. The fixture makes the winner fail immediately; failed() fences its invitation synchronously (retire_failed) and then releases the reservation. A batch that was still in preflight/key preparation when that happened then reserves the freed destination and issues its own invitation, correctly. Guarantee = one live invitation per destination, which the test could not distinguish from one per run; load only widens the skew between batches. I looked for a window where the second reservation could succeed while the first invitation is still live (completion removes the attempt before retirement finishes, bootstrap_remote.rs failed()/completed_record), but the invitation is already fenced by then and the durable check after reservation (existing_host(.., retire=true)) consumes or finds the old setup, so no live pair arises.

Fix (test only, commit 33a15c4c9): the winner's invitation delivery waits on a gate that opens only after the other seven batches have finished with "already being added", so all eight overlap the winner's reservation whatever the scheduler does. Same load: 0/80, 0/80, and 0/120 at 40 copies (evidence/dest/new-*, new-heavy).

**5. `breakit2_concurrent_same_destination_issues_only_one_invitation` (`left: 2, right: 1`): a test assumption, not a product race.** Reproduced on dev-02 with the unmodified test (origin/dev 5eb968744 test code): 8 copies x 10 rounds + 16 CPU spinners, **13/80 and 9/80 failed** (`evidence/dest/old-1/FAIL-*.log`, `old-2/`). A VM-only trace of the events (never committed) shows exactly two batches with `host_id: Some` and step `Failed` ("Joining the host to this server failed", i.e. each issued an invitation and then hit the fixture's post-invitation refusal) and six refused with "This host is already being added" (`host_id: None`). Why that is not a double issue: `reserve_attempt` checks and inserts under one `attempts` mutex, so two attempts for one destination cannot be live together. The fixture makes the winner fail immediately; `failed()` fences its invitation synchronously (`retire_failed`) and then releases the reservation. A batch that was still in preflight/key preparation when that happened then reserves the freed destination and issues its own invitation, correctly. Guarantee = one *live* invitation per destination, which the test could not distinguish from one per run; load only widens the skew between batches. I looked for a window where the second reservation could succeed while the first invitation is still live (completion removes the attempt before retirement finishes, `bootstrap_remote.rs` `failed()`/`completed_record`), but the invitation is already fenced by then and the durable check after reservation (`existing_host(.., retire=true)`) consumes or finds the old setup, so no live pair arises. Fix (test only, commit 33a15c4c9): the winner's invitation delivery waits on a gate that opens only after the other seven batches have finished with "already being added", so all eight overlap the winner's reservation whatever the scheduler does. Same load: **0/80, 0/80, and 0/120 at 40 copies** (`evidence/dest/new-*`, `new-heavy`).

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#475

No description provided.

Rows
Columns