kayg/infraternal

Watch

Fork 0

Gate timing tests flake under VM load (QUIC/TCP race, status_restart, shim backpressure, source_bridge, saved-shell socket) #334

New issue

Open

opened 2026-11-04 03:06:49 +00:00 by kayg · 11 comments

kayg commented

2026-11-04 03:06:49 +00:00

Owner

Job J163. Related: #324 (J157 covers the separate agent_daemon resource_unavailable family; not duplicated here).

Gate runs (scripts/verify fast) fail on a rotating set of timing tests whenever the build VMs are loaded (load 8–20). Each passes alone. Blocks merges across branches.

Seen 2026-11-03/04:

winning_quic_drops_the_unfinished_tls_dial_before_control_dispatch (twice)
unavailable_udp_does_not_add_seconds_before_tcp_admission
status_restart::service_states_are_truthful_in_text_and_json
shim::attached_backpressure_and_detached_progress
desktop plugin source_bridge (3 s timeout)
saved_shell_automation_uses_an_owner_only_socket_directory (15 s timeout)

Logs: ~/j159-fast*.log on compute01 and dev-02, ~/.cache/codex-scratch/{j79d,j80d,J94e} gate logs.

Task: for each test find what it times/waits on, reproduce under controlled load, classify (a) product timing bug → fix product, (b) test asserts a wall-clock bound the contract does not promise → rewrite to assert ordering/causality with condition waits, (c) real contract bound → keep, move measurement to perf VM if PROCESS.md allows. No bare timeout raises. Each fixed test 20/20 under the load that failed it; before/after numbers here. Branch timing-flakes-j163 from origin/dev, one commit per test/cause, scripts/verify fast twice on dev-02. No merge, no deploy.

Job J163. Related: #324 (J157 covers the separate `agent_daemon` `resource_unavailable` family; not duplicated here). Gate runs (`scripts/verify fast`) fail on a rotating set of timing tests whenever the build VMs are loaded (load 8–20). Each passes alone. Blocks merges across branches. Seen 2026-11-03/04: - `winning_quic_drops_the_unfinished_tls_dial_before_control_dispatch` (twice) - `unavailable_udp_does_not_add_seconds_before_tcp_admission` - `status_restart::service_states_are_truthful_in_text_and_json` - `shim::attached_backpressure_and_detached_progress` - desktop plugin `source_bridge` (3 s timeout) - `saved_shell_automation_uses_an_owner_only_socket_directory` (15 s timeout) Logs: `~/j159-fast*.log` on compute01 and dev-02, `~/.cache/codex-scratch/{j79d,j80d,J94e}` gate logs. Task: for each test find what it times/waits on, reproduce under controlled load, classify (a) product timing bug → fix product, (b) test asserts a wall-clock bound the contract does not promise → rewrite to assert ordering/causality with condition waits, (c) real contract bound → keep, move measurement to perf VM if PROCESS.md allows. No bare timeout raises. Each fixed test 20/20 under the load that failed it; before/after numbers here. Branch `timing-flakes-j163` from origin/dev, one commit per test/cause, `scripts/verify fast` twice on dev-02. No merge, no deploy.

kayg commented

2026-11-04 03:12:12 +00:00

Author

Owner

Start: branch timing-flakes-j163, base origin/dev f14e4309a.

Plan (estimate ~6 h):

Build test binaries once on a VM, then reproduce each test under controlled load (stress-ng --cpu N plus parallel test copies) and record fail rate before. ~1.5 h
Per test: find what it waits on, classify (a)/(b)/(c), and make one commit per cause. ~3 h
20/20 under the failing load for each fix, then scripts/verify fast twice on dev-02. ~1.5 h

First reading of the failure signatures (from the gate logs):

test	failure	waits on
`winning_quic_drops_the_unfinished_tls_dial_before_control_dispatch`	`remote_client_tests.rs:205` Elapsed: no TCP accept within 2 s of `spawn(run)`	agent startup before the dial, plus 100 ms TCP grace
`unavailable_udp_does_not_add_seconds_before_tcp_admission`	`fallback_local_admission_us=2001951`: TLS admission not done within 2 s of spawn	the same startup, plus the TLS handshake
`status_restart::service_states_are_truthful_in_text_and_json`	`system/server/activating` reported `service manager query timed out`	the systemctl fixture reply versus the status query deadline
`shim::attached_backpressure_and_detached_progress`	`attached producer never stalled at head 1373 (minimum 1510)` after 10 s	the producer must get 1024 B past the reader's position
`saved_shell_automation_uses_an_owner_only_socket_directory`	`sessions new local --name build` hit the python 15 s subprocess timeout	the CLI create path
desktop `source_bridge::replay_repairs_coalesce_at_the_source_interval`	the logs I found (j93c, j125c) show `source_bridge.rs:15:60` unwrap on `None`: `CARGO_TARGET_DIR` was unset, not a timeout	none

Question: does anyone have the log of the source_bridge 3 s-timeout failure? The only failures on either VM are the CARGO_TARGET_DIR unwrap. My default: I fix that environment dependency (fall back to the target dir that cargo provides), and I try to reproduce a timing failure under load.

Start: branch `timing-flakes-j163`, base origin/dev `f14e4309a`. Plan (estimate ~6 h): 1. Build test binaries once on a VM, then reproduce each test under controlled load (`stress-ng --cpu N` plus parallel test copies) and record fail rate before. ~1.5 h 2. Per test: find what it waits on, classify (a)/(b)/(c), and make one commit per cause. ~3 h 3. 20/20 under the failing load for each fix, then `scripts/verify fast` twice on dev-02. ~1.5 h First reading of the failure signatures (from the gate logs): | test | failure | waits on | |---|---|---| | `winning_quic_drops_the_unfinished_tls_dial_before_control_dispatch` | `remote_client_tests.rs:205` Elapsed: no TCP accept within 2 s of `spawn(run)` | agent startup before the dial, plus 100 ms TCP grace | | `unavailable_udp_does_not_add_seconds_before_tcp_admission` | `fallback_local_admission_us=2001951`: TLS admission not done within 2 s of spawn | the same startup, plus the TLS handshake | | `status_restart::service_states_are_truthful_in_text_and_json` | `system/server/activating` reported `service manager query timed out` | the systemctl fixture reply versus the status query deadline | | `shim::attached_backpressure_and_detached_progress` | `attached producer never stalled at head 1373 (minimum 1510)` after 10 s | the producer must get 1024 B past the reader's position | | `saved_shell_automation_uses_an_owner_only_socket_directory` | `sessions new local --name build` hit the python 15 s subprocess timeout | the CLI create path | | desktop `source_bridge::replay_repairs_coalesce_at_the_source_interval` | the logs I found (j93c, j125c) show `source_bridge.rs:15:60` unwrap on `None`: `CARGO_TARGET_DIR` was unset, not a timeout | none | Question: does anyone have the log of the `source_bridge` 3 s-timeout failure? The only failures on either VM are the `CARGO_TARGET_DIR` unwrap. My default: I fix that environment dependency (fall back to the target dir that cargo provides), and I try to reproduce a timing failure under load.

kayg commented

2026-11-04 03:38:41 +00:00

Author

Owner

Progress 1 (dev-02-std, aarch64, test binaries from base f14e4309a).

Before, isolated copies under CPU load (~/j163-loadrun.sh: 12 nice-0 busy loops, 4 parallel copies of the one test at nice 10, 5 rounds = 20 runs; load 6→20):

test	pass/20
unavailable_udp…tcp_admission	20 (admission p50 200 ms, max 288 ms)
winning_quic…control_dispatch	20
status_restart	20
shim attached_backpressure…	19 (`never stalled at head 1124 (minimum 1443)`, same signature as the gate)
cli_sessions saved_shell…	20
source_bridge replay_repairs…	20

So CPU contention alone reproduces only the shim test. The others fail inside gate-shaped load (whole test binaries running in parallel next to other gates). Next I reproduce with the full workspace test suite as background load.

Findings so far:

source_bridge: each logged failure on both VMs (j93c/workspace-tests.log, j125c/ws-{base,head}.log) is source_bridge.rs:15:60 Option::unwrap() on None, i.e. CARGO_TARGET_DIR unset when the test was run outside scripts/verify. That is an environment dependency, not timing. I found no 3 s-timeout instance (question above).
shim: when the producer is held, the head normally lands 20–65 KB past the reader (31 passing samples). The failures hold it at about 1 KB for 10 s, and in that state the 1 ms probe connections sometimes get no Hello within the 5 s socket timeout. So the shim is not answering at all. That rules out the margin size. I'm now dumping the process-tree state at the timeout.
QUIC/TCP pair: both 2 s budgets start at spawn(run), so they include agent startup (ensure_service, endpoint setup) before any dial. The product contract in dial_preferred is "TCP starts 100 ms after QUIC, never after QUIC's 5 s timeout".

Progress 1 (dev-02-std, aarch64, test binaries from base `f14e4309a`). **Before, isolated copies under CPU load** (`~/j163-loadrun.sh`: 12 nice-0 busy loops, 4 parallel copies of the one test at nice 10, 5 rounds = 20 runs; load 6→20): | test | pass/20 | |---|---| | unavailable_udp…tcp_admission | 20 (admission p50 200 ms, max 288 ms) | | winning_quic…control_dispatch | 20 | | status_restart | 20 | | shim attached_backpressure… | **19** (`never stalled at head 1124 (minimum 1443)`, same signature as the gate) | | cli_sessions saved_shell… | 20 | | source_bridge replay_repairs… | 20 | So CPU contention alone reproduces only the shim test. The others fail inside gate-shaped load (whole test binaries running in parallel next to other gates). Next I reproduce with the full workspace test suite as background load. Findings so far: - **source_bridge**: each logged failure on both VMs (`j93c/workspace-tests.log`, `j125c/ws-{base,head}.log`) is `source_bridge.rs:15:60` `Option::unwrap()` on `None`, i.e. `CARGO_TARGET_DIR` unset when the test was run outside `scripts/verify`. That is an environment dependency, not timing. I found no 3 s-timeout instance (question above). - **shim**: when the producer is held, the head normally lands 20–65 KB past the reader (31 passing samples). The failures hold it at about 1 KB for 10 s, and in that state the 1 ms probe connections sometimes get no `Hello` within the 5 s socket timeout. So the shim is not answering at all. That rules out the margin size. I'm now dumping the process-tree state at the timeout. - **QUIC/TCP pair**: both 2 s budgets start at `spawn(run)`, so they include agent startup (`ensure_service`, endpoint setup) before any dial. The product contract in `dial_preferred` is "TCP starts 100 ms after QUIC, never after QUIC's 5 s timeout".

kayg commented

2026-11-04 04:15:35 +00:00

Author

Owner

Progress 2.

shim attached_backpressure_and_detached_progress: class (b), fixed in a5c95e32a.

In the failing state, a process dump at the 10 s timeout shows seq blocked in the tty write (wait_woken) and the shim idle in poll, with only about 600 bytes past the reader. The shim reads the PTY only while some viewer is caught up (session.rs:829), and it sends one Output frame per PTY read.
AF_UNIX stream capacity on dev-02 is a fixed number of skbs: write_size=5 → 278 writes, 1390 B; 20 → 278, 5560 B; 512 → 167, 85504 B; 8192 → 24, 196608 B. So when the shim keeps pace with a line-buffered seq, the unread socket fills at about 1 KiB of payload, which is below the test's reader + 1024 floor. That is correct backpressure, not a product bug.
The contract stays: an unread viewer stops the producer before completion, and detached progress completes. The test now requires only head > consumed.

status_restart: cause found (cold page cache, not CPU). Same fixture as the failing case (system/server/activating), posix_fadvise(DONTNEED) on target/debug/infraternal (478 MB) before each run, ambient load about 13, no added burners:

cold0: 4703 ms server=system service; last exit status 1
warm0: 5 ms   server=system service; last exit status 1
cold1: 3642 ms server=system service; last exit status 1
warm1: 4 ms   server=system service; last exit status 1
cold2: 9692 ms server=system service; service manager query timed out
warm2: 4 ms   server=system service; last exit status 1

The 500 ms MANAGER_QUERY_BUDGET starts inside the worker, so our own binary's major faults in spawn/poll code use up the window. That matches the gate failure on the first matrix case. Next: measure the same thing on a static release binary to decide between (a) and (b).

Progress 2. **shim `attached_backpressure_and_detached_progress`: class (b), fixed in `a5c95e32a`.** - In the failing state, a process dump at the 10 s timeout shows `seq` blocked in the tty write (`wait_woken`) and the shim idle in poll, with only about 600 bytes past the reader. The shim reads the PTY only while some viewer is caught up (`session.rs:829`), and it sends one Output frame per PTY read. - AF_UNIX stream capacity on dev-02 is a fixed number of skbs: `write_size=5 → 278 writes, 1390 B`; `20 → 278, 5560 B`; `512 → 167, 85504 B`; `8192 → 24, 196608 B`. So when the shim keeps pace with a line-buffered `seq`, the unread socket fills at about 1 KiB of payload, which is below the test's `reader + 1024` floor. That is correct backpressure, not a product bug. - The contract stays: an unread viewer stops the producer before completion, and detached progress completes. The test now requires only `head > consumed`. **status_restart: cause found (cold page cache, not CPU).** Same fixture as the failing case (`system/server/activating`), `posix_fadvise(DONTNEED)` on `target/debug/infraternal` (478 MB) before each run, ambient load about 13, no added burners: ``` cold0: 4703 ms server=system service; last exit status 1 warm0: 5 ms server=system service; last exit status 1 cold1: 3642 ms server=system service; last exit status 1 warm1: 4 ms server=system service; last exit status 1 cold2: 9692 ms server=system service; service manager query timed out warm2: 4 ms server=system service; last exit status 1 ``` The 500 ms `MANAGER_QUERY_BUDGET` starts inside the worker, so our own binary's major faults in spawn/poll code use up the window. That matches the gate failure on the first matrix case. Next: measure the same thing on a static release binary to decide between (a) and (b).

kayg commented

2026-11-04 04:51:04 +00:00

Author

Owner

Progress 3. QUIC/TCP race tests: class (b), fixed in 20b1b03de.

Load window on dev-02 (~/j163-window.sh): two full infraternal-agent lib suites restarting in a loop plus 6 busy loops, load 22–34. Before and after binaries alternate inside the same window, each invocation running the three supervisor tests.

test	before (base `f14e4309a`)	after (`20b1b03de`)
`unavailable_udp_does_not_add_seconds_before_tcp_admission`	6/20 (14× `remote_client_tests.rs:167`)	20/20
`winning_quic_drops_the_unfinished_tls_dial_before_control_dispatch`	6/20 (14× `:205 Elapsed`)	20/20
`server_path_capability_is_advertised_on_native_and_fallback_transports` (same cause, not on the original list)	9/20 (11× `:688 Elapsed`)	20/20

What the old 2 s budgets measured (μs, same window):

fallback_local_admission_us (before) n=22 min=461313 p50=2002997 max=3199207
spawn_to_first_initial_us   (after)  n=20 min=56654  p50=1218400 max=7934928
quic_to_tcp_connect_us      (after)  n=20 min=100514 p50=101779  max=106486

So the product's race is exact: TCP connects 100–106 ms after QUIC's first Initial, which is the 100 ms grace in dial_preferred. All the variance comes from agent startup before the first dial (up to 7.9 s here), and no contract bounds that. The new tests prove ordering instead: the same QUIC attempt (same Initial DCID) is still retransmitting after TCP connected, and the proxy is held until TCP has dialled, so QUIC wins by construction. Supervisor latency stays in the ignored supervisor_300ms_quic_and_blocked_udp_fallback diagnostic, run alone.

Red check (TCP dialled only after QUIC fails, never committed): rerunning it now with the gate's feature set. The first attempt filtered 0 tests because -p infraternal-agent alone builds 145 tests, not 248.

source_bridge: correction to my first table. The 20/20 I listed for it was vacuous, because without --features source the file compiles to 0 tests. With the feature (15 tests) it passed the one mix round it ran. Every logged failure is still the CARGO_TARGET_DIR unwrap.

Progress 3. **QUIC/TCP race tests: class (b), fixed in `20b1b03de`.** Load window on dev-02 (`~/j163-window.sh`): two full `infraternal-agent` lib suites restarting in a loop plus 6 busy loops, load 22–34. Before and after binaries alternate inside the same window, each invocation running the three supervisor tests. | test | before (base `f14e4309a`) | after (`20b1b03de`) | |---|---|---| | `unavailable_udp_does_not_add_seconds_before_tcp_admission` | 6/20 (14× `remote_client_tests.rs:167`) | **20/20** | | `winning_quic_drops_the_unfinished_tls_dial_before_control_dispatch` | 6/20 (14× `:205 Elapsed`) | **20/20** | | `server_path_capability_is_advertised_on_native_and_fallback_transports` (same cause, not on the original list) | 9/20 (11× `:688 Elapsed`) | **20/20** | What the old 2 s budgets measured (μs, same window): ``` fallback_local_admission_us (before) n=22 min=461313 p50=2002997 max=3199207 spawn_to_first_initial_us (after) n=20 min=56654 p50=1218400 max=7934928 quic_to_tcp_connect_us (after) n=20 min=100514 p50=101779 max=106486 ``` So the product's race is exact: TCP connects 100–106 ms after QUIC's first Initial, which is the 100 ms grace in `dial_preferred`. All the variance comes from agent startup before the first dial (up to 7.9 s here), and no contract bounds that. The new tests prove ordering instead: the same QUIC attempt (same Initial DCID) is still retransmitting after TCP connected, and the proxy is held until TCP has dialled, so QUIC wins by construction. Supervisor latency stays in the ignored `supervisor_300ms_quic_and_blocked_udp_fallback` diagnostic, run alone. Red check (TCP dialled only after QUIC fails, never committed): rerunning it now with the gate's feature set. The first attempt filtered 0 tests because `-p infraternal-agent` alone builds 145 tests, not 248. **source_bridge**: correction to my first table. The 20/20 I listed for it was vacuous, because without `--features source` the file compiles to 0 tests. With the feature (15 tests) it passed the one mix round it ran. Every logged failure is still the `CARGO_TARGET_DIR` unwrap.

kayg commented

2026-11-04 04:59:15 +00:00

Author

Owner

Progress 4.

Red check, QUIC/TCP: with a throwaway product patch that dials TCP only after QUIC fails (never committed), the rewritten test fails as intended:

test remote_client::tests::unavailable_udp_does_not_add_seconds_before_tcp_admission ... FAILED
panicked at crates/infraternal-agent/src/remote_client_tests.rs:221:5:
TCP was dialled only after the silent QUIC attempt gave up
test result: FAILED. 0 passed; 1 failed; 0 ignored; 0 measured; 247 filtered out; finished in 30.01s

shim after (a5c95e32a): RESULT tag=shimafter burners=12 copies=4 rounds=10 pass=40 fail=0 (dev-02). Before, the same harness gave 19/20 and 39/40. The failure is rare because it needs the shim to keep pace with seq line by line. The skb measurement explains the mechanism.

status_restart: class (b), production budget unchanged. Cold vs warm infraternal status (binary pages evicted before each cold run; ! = query timed out):

dev-02, during gates, debug binary 478 MB: cold 4703 / 3642 / 9692**!** ms, warm 4–5 ms.
compute01, load about 6, binaries copied to disk:

rel 21 MiB  cold ms: 28 25 46 55 76 136 21 16
rel 21 MiB  warm ms: 6 7 9 11 10 7 8 8
dbg 464 MiB cold ms: 41 39 42 37 39 40 34 34
dbg 464 MiB warm ms: 14 13 13 13 11 14 14 10

The shipped static binary starts cold well inside 500 ms. The gate failure comes from a 470 MB debug binary page-faulting inside the window on a contended build disk, which a real install does not hit. The budget-expiry path keeps its unit tests (an_unanswering_manager_only_makes_its_own_unit_unknown, manager_completion_handles_an_already_exited_child_and_a_deadline). The fix, in progress:

add a debug-only INFRATERNAL_TEST_MANAGER_QUERY_BUDGET_MS, the same pattern as the existing debug-only INFRATERNAL_TEST_SYSTEMD_SYSTEM_UNIT_DIR; release always uses the constant;
run the role/scope/output matrix under a 30 s budget;
add one warm end-of-test case that keeps the budget's structure: a 4 s budget, an immediate first observation and a 2.5 s second one. It must read running; a per-observation split would cut it. This red-checks at a 2 s budget.

cli_sessions: no repro yet. In both gate failures (j79d dev-02, j94e compute01), the first sessions new local inside the saved shell got no reply in 15 s. The infraternal agent caps its handling at 4 s (automation.rs:198), and the CLI waits for the reply start with no timer (plugin_control.rs:834). Under 6 busy loops, warm and with the binary's pages evicted before each run: 20/20 pass. Every CLI call took 2–171 ms, because the running agent fixture maps the same binary, so eviction does not make the CLI cold. Next: heavier gate-shaped load with per-call durations recorded.

Progress 4. **Red check, QUIC/TCP**: with a throwaway product patch that dials TCP only after QUIC fails (never committed), the rewritten test fails as intended: ``` test remote_client::tests::unavailable_udp_does_not_add_seconds_before_tcp_admission ... FAILED panicked at crates/infraternal-agent/src/remote_client_tests.rs:221:5: TCP was dialled only after the silent QUIC attempt gave up test result: FAILED. 0 passed; 1 failed; 0 ignored; 0 measured; 247 filtered out; finished in 30.01s ``` **shim after (`a5c95e32a`)**: `RESULT tag=shimafter burners=12 copies=4 rounds=10 pass=40 fail=0` (dev-02). Before, the same harness gave 19/20 and 39/40. The failure is rare because it needs the shim to keep pace with `seq` line by line. The skb measurement explains the mechanism. **status_restart: class (b), production budget unchanged.** Cold vs warm `infraternal status` (binary pages evicted before each cold run; `!` = query timed out): - dev-02, during gates, debug binary 478 MB: cold 4703 / 3642 / 9692**!** ms, warm 4–5 ms. - compute01, load about 6, binaries copied to disk: ``` rel 21 MiB cold ms: 28 25 46 55 76 136 21 16 rel 21 MiB warm ms: 6 7 9 11 10 7 8 8 dbg 464 MiB cold ms: 41 39 42 37 39 40 34 34 dbg 464 MiB warm ms: 14 13 13 13 11 14 14 10 ``` The shipped static binary starts cold well inside 500 ms. The gate failure comes from a 470 MB debug binary page-faulting inside the window on a contended build disk, which a real install does not hit. The budget-expiry path keeps its unit tests (`an_unanswering_manager_only_makes_its_own_unit_unknown`, `manager_completion_handles_an_already_exited_child_and_a_deadline`). The fix, in progress: - add a debug-only `INFRATERNAL_TEST_MANAGER_QUERY_BUDGET_MS`, the same pattern as the existing debug-only `INFRATERNAL_TEST_SYSTEMD_SYSTEM_UNIT_DIR`; release always uses the constant; - run the role/scope/output matrix under a 30 s budget; - add one warm end-of-test case that keeps the budget's structure: a 4 s budget, an immediate first observation and a 2.5 s second one. It must read `running`; a per-observation split would cut it. This red-checks at a 2 s budget. **cli_sessions: no repro yet.** In both gate failures (j79d dev-02, j94e compute01), the first `sessions new local` inside the saved shell got no reply in 15 s. The infraternal agent caps its handling at 4 s (`automation.rs:198`), and the CLI waits for the reply start with no timer (`plugin_control.rs:834`). Under 6 busy loops, warm and with the binary's pages evicted before each run: 20/20 pass. Every CLI call took 2–171 ms, because the running agent fixture maps the same binary, so eviction does not make the CLI cold. Next: heavier gate-shaped load with per-call durations recorded.

kayg commented

2026-11-04 05:41:42 +00:00

Author

Owner

Progress 5.

status_restart after e0809a0d9: not good enough. Same window (2 agent suites + 6 busy loops, binary pages evicted before every run): before 17/20, after 18/20. The after failures show two more wall-clock dependencies:

user/server/active read "Running" instead of "Restarting repeatedly". The product counts a start as recent only within 10 s (Observation::recent), and the fixture stamped its start when it was written. One cold status run took longer than 10 s, so the start aged out.
My new shared_deadline case failed its 1.5 s margin (unknown … query timed out at a 4 s budget). A margin is still a stopwatch.

Revision (building now, to be a follow-up commit):

Fixtures that must look freshly started report ExecMainStartTimestampMonotonic as one second before the moment they are queried, so the age is independent of status startup.
The structural check ("one deadline spans both observations; a split would cut a 2.5 s second answer at a 4 s budget") moves to a unit test in the small infraternal-status binary. It uses a cfg(test) thread-local manager-program override and calls manager_activity_before directly. Red check: the second observation on its own 2 s deadline.

cli_sessions: class (a), a product timing bug. Fix written, being verified. create publishes the session name with save(): write, sync_all, rename, then sync_all of the directory. That is synchronous code inside the tokio::time::timeout(4 s) in automation::execute, running on the infraternal agent's current-thread reactor (run_embedded → new_current_thread; the local control listener is a task on it). On ext4 with dirty_ratio=20 (about 6 GB of dirty pages on dev-02, 12 GB on compute01), fsync can block for many seconds during parallel builds. During that time:

the 4 s action deadline cannot fire (no await point);
every terminal and the server link on that host freeze, because they share the reactor;
the CLI waits for the reply start with no timer, so the test's 15 s subprocess guard expires.

new local is the first call in the oracle that reaches save(), which matches both gate failures. A loaded real host with a busy disk hits the same stall.

Fix: a publish() task runs save on the blocking pool and owns the existing failure cleanup (close an unnamed session), so a deadline firing mid-publish cannot skip it. The existing timeout reply already says "the operation may have started; list sessions before retrying". Regression test (causal): a test-only gate holds save as an fsync that never completes. The test then requires that the same current-thread reactor keeps running other work and releases the gate itself; a 30 s watchdog only bounds the hang. Red check: save back on the reactor.

Before/after evidence (in progress): cli_sessions under sustained dd writeback on the state disk, plus fsync latency samples of the exact publication pattern.

Uncommitted files are staged in dev-02:~/j163-stage/. Next: commit once the build and red checks pass.

Progress 5. **status_restart after `e0809a0d9`: not good enough.** Same window (2 agent suites + 6 busy loops, binary pages evicted before every run): before **17/20**, after **18/20**. The after failures show two more wall-clock dependencies: 1. `user/server/active` read "Running" instead of "Restarting repeatedly". The product counts a start as recent only within 10 s (`Observation::recent`), and the fixture stamped its start when it was written. One cold status run took longer than 10 s, so the start aged out. 2. My new `shared_deadline` case failed its 1.5 s margin (`unknown … query timed out` at a 4 s budget). A margin is still a stopwatch. Revision (building now, to be a follow-up commit): - Fixtures that must look freshly started report `ExecMainStartTimestampMonotonic` as one second before the moment they are queried, so the age is independent of status startup. - The structural check ("one deadline spans both observations; a split would cut a 2.5 s second answer at a 4 s budget") moves to a unit test in the small `infraternal-status` binary. It uses a `cfg(test)` thread-local manager-program override and calls `manager_activity_before` directly. Red check: the second observation on its own 2 s deadline. **cli_sessions: class (a), a product timing bug. Fix written, being verified.** `create` publishes the session name with `save()`: write, `sync_all`, rename, then `sync_all` of the directory. That is synchronous code inside the `tokio::time::timeout(4 s)` in `automation::execute`, running on the infraternal agent's current-thread reactor (`run_embedded` → `new_current_thread`; the local control listener is a task on it). On ext4 with `dirty_ratio=20` (about 6 GB of dirty pages on dev-02, 12 GB on compute01), fsync can block for many seconds during parallel builds. During that time: - the 4 s action deadline cannot fire (no await point); - **every terminal and the server link on that host freeze**, because they share the reactor; - the CLI waits for the reply start with no timer, so the test's 15 s subprocess guard expires. `new local` is the first call in the oracle that reaches `save()`, which matches both gate failures. A loaded real host with a busy disk hits the same stall. Fix: a `publish()` task runs `save` on the blocking pool and owns the existing failure cleanup (close an unnamed session), so a deadline firing mid-publish cannot skip it. The existing timeout reply already says "the operation may have started; list sessions before retrying". Regression test (causal): a test-only gate holds `save` as an fsync that never completes. The test then requires that the same current-thread reactor keeps running other work and releases the gate itself; a 30 s watchdog only bounds the hang. Red check: `save` back on the reactor. Before/after evidence (in progress): `cli_sessions` under sustained `dd` writeback on the state disk, plus fsync latency samples of the exact publication pattern. Uncommitted files are staged in `dev-02:~/j163-stage/`. Next: commit once the build and red checks pass.

kayg commented

2026-11-04 06:32:19 +00:00

Author

Owner

Progress 6. Commits: 6984ff653 (status follow-up), ad2c6b9eb (product fix: session names published off the shared reactor).

fsync stall measured (dev-02, ext4, dirty_ratio=20). The exact save() pattern (write, fsync, rename, directory fsync), sampled every 0.5 s while a sustained dd stream writes to the same disk:

publish_fsync_s n=28 p50=1.748 p90=14.347 max=32.118

On the old code, a 32 s stall blocks the infraternal agent's only reactor thread, so every terminal on the host freezes and sessions new misses the oracle's 15 s guard.

Earlier heavy-mix repro on the unchanged test (2 agent suites + shim suite + 8 busy loops, load 34–35), 15/20 pass. Failure modes:

new local --name build → TimeoutExpired(…, 15) (the call took 15.077 s; the exact gate signature);
new → code 5 "The session did not reply in time; the operation may have started." (the 4 s action deadline);
new … -- /bin/sh -c … → code 1 "The session operation failed." (the 2 s shim readiness handshake), plus one more 15 s timeout;
"close left the saved shell running behind its foreground job" (the oracle's own 3 s deadline).

Red checks (throwaway patches, never committed):

a_held_name_publication_leaves_the_reactor_serving_other_work ... FAILED
the name publication held the reactor until the watchdog released it        (save() back on the reactor)
one_deadline_spans_both_observations_of_a_fresh_start ... FAILED            (second observation on its own 2 s deadline)

Both pass on the fixes (agent automation::operations::tests 4/4, infraternal-status 24 passed).

Side finding (not fixed; out of scope, for kayg): when the 2 s shim-readiness handshake in launch_configured times out, the launcher returns an error, but nothing stops the --detach shim it already spawned. On a slow host the caller hears "operation failed", yet an unnamed detached session appears later. This deserves its own issue if you agree.

Running now: the status before/after window (20+20), then cli_sessions after the fix under sustained writeback (20 runs), with the oracle's own waits made condition waits.

Progress 6. Commits: `6984ff653` (status follow-up), `ad2c6b9eb` (**product fix**: session names published off the shared reactor). **fsync stall measured** (dev-02, ext4, `dirty_ratio=20`). The exact `save()` pattern (write, fsync, rename, directory fsync), sampled every 0.5 s while a sustained `dd` stream writes to the same disk: ``` publish_fsync_s n=28 p50=1.748 p90=14.347 max=32.118 ``` On the old code, a 32 s stall blocks the infraternal agent's only reactor thread, so every terminal on the host freezes and `sessions new` misses the oracle's 15 s guard. Earlier heavy-mix repro on the unchanged test (2 agent suites + shim suite + 8 busy loops, load 34–35), 15/20 pass. Failure modes: - `new local --name build` → `TimeoutExpired(…, 15)` (the call took 15.077 s; the exact gate signature); - `new` → code 5 "The session did not reply in time; the operation may have started." (the 4 s action deadline); - `new … -- /bin/sh -c …` → code 1 "The session operation failed." (the 2 s shim readiness handshake), plus one more 15 s timeout; - "close left the saved shell running behind its foreground job" (the oracle's own 3 s deadline). **Red checks** (throwaway patches, never committed): ``` a_held_name_publication_leaves_the_reactor_serving_other_work ... FAILED the name publication held the reactor until the watchdog released it (save() back on the reactor) one_deadline_spans_both_observations_of_a_fresh_start ... FAILED (second observation on its own 2 s deadline) ``` Both pass on the fixes (agent `automation::operations::tests` 4/4, `infraternal-status` 24 passed). **Side finding (not fixed; out of scope, for kayg):** when the 2 s shim-readiness handshake in `launch_configured` times out, the launcher returns an error, but nothing stops the `--detach` shim it already spawned. On a slow host the caller hears "operation failed", yet an unnamed detached session appears later. This deserves its own issue if you agree. Running now: the status before/after window (20+20), then `cli_sessions` after the fix under sustained writeback (20 runs), with the oracle's own waits made condition waits.

kayg commented

2026-11-04 07:09:43 +00:00

Author

Owner

Progress 7.

status_restart, before/after 6984ff653 (dev-02, 2 agent suites + 6 busy loops, binary pages evicted before every run, load 22–27): before 14/20 (6× status_restart.rs:170 "query timed out" / unknown), after 19/20. The single after failure was the first run of the window: system/agent/activating timed out with the 30 s override, so one cold query spent more than 30 s faulting the binary back in. No matrix case waits for the budget to expire, so b9646fd05 makes it 120 s. Confirmation run (20 after-runs) is queued.

cli_sessions after ad2c6b9eb: the reactor is free, but the test got worse. Changed the semantics and rerunning.
Under sustained writeback (publish_fsync_s n=35 p50=3.085 p90=9.077 max=12.433), the unchanged oracle went from 10/10 before to 11/20 after. Every failure is new answering at exactly 4.0 s with code 5 "may have started", because the 4 s action deadline can now fire while the publication waits on fsync. Before the fix, the frozen reactor finished save() and replied success late; that is why the old code passed here while freezing every terminal.

Decision (D314 does not specify the 4 s bound, and I'm not changing the contract): execute now awaits the name publication outside the 4 s deadline, still off the reactor. A successful sessions new still means the name is saved. A disk busy with writeback delays only that reply, not other terminals, and AI tools don't get a spurious "may have started" to retry. The deadline keeps bounding discovery and launch, which can stall on unresponsive shims. Implementation: operations::run hands the spawned publication back via pending, and execute awaits it after the timeout.

cli oracle (scripts/test-cli-sessions.py), class (b): the oracle's own waits become condition waits under one documented HANG = 120 s: the 15 s per-call guard, the 40 s receipt wait, 10 s output polls, 3 s close → shell exit, and a sleep(0.1) before reading the ended session's output. A broken close still fails, because the saved shell outlives its 20 s foreground job.

Queued on dev-02: build, red check, 20 status after-runs, 20 cli after-runs under sustained writeback.

Progress 7. **status_restart, before/after `6984ff653`** (dev-02, 2 agent suites + 6 busy loops, binary pages evicted before every run, load 22–27): before **14/20** (6× `status_restart.rs:170` "query timed out" / unknown), after **19/20**. The single after failure was the first run of the window: `system/agent/activating` timed out with the 30 s override, so one cold query spent more than 30 s faulting the binary back in. No matrix case waits for the budget to expire, so `b9646fd05` makes it 120 s. Confirmation run (20 after-runs) is queued. **cli_sessions after `ad2c6b9eb`: the reactor is free, but the test got worse. Changed the semantics and rerunning.** Under sustained writeback (`publish_fsync_s n=35 p50=3.085 p90=9.077 max=12.433`), the unchanged oracle went from 10/10 before to **11/20** after. Every failure is `new` answering at exactly 4.0 s with code 5 "may have started", because the 4 s action deadline can now fire while the publication waits on fsync. Before the fix, the frozen reactor finished `save()` and replied success late; that is why the old code passed here while freezing every terminal. Decision (D314 does not specify the 4 s bound, and I'm not changing the contract): `execute` now awaits the name publication **outside** the 4 s deadline, still off the reactor. A successful `sessions new` still means the name is saved. A disk busy with writeback delays only that reply, not other terminals, and AI tools don't get a spurious "may have started" to retry. The deadline keeps bounding discovery and launch, which can stall on unresponsive shims. Implementation: `operations::run` hands the spawned publication back via `pending`, and `execute` awaits it after the timeout. **cli oracle (`scripts/test-cli-sessions.py`), class (b):** the oracle's own waits become condition waits under one documented `HANG = 120` s: the 15 s per-call guard, the 40 s receipt wait, 10 s output polls, 3 s close → shell exit, and a `sleep(0.1)` before reading the ended session's output. A broken `close` still fails, because the saved shell outlives its 20 s foreground job. Queued on dev-02: build, red check, 20 status after-runs, 20 `cli` after-runs under sustained writeback.

kayg commented

2026-11-04 07:54:38 +00:00

Author

Owner

Progress 8. All fixes are on the branch, head e7d902ffa. verify quick plus verify fast ×2 are queued on dev-02.

test	class	load that failed it (dev-02)	before	after
`unavailable_udp_does_not_add_seconds_before_tcp_admission`	(b)	2 full agent suites + 6 busy loops, load 22–34	6/20	20/20 (`20b1b03de`)
`winning_quic_drops_the_unfinished_tls_dial_before_control_dispatch`	(b)	same	6/20	20/20
`server_path_capability_is_advertised_on_native_and_fallback_transports` (same cause)	(b)	same	9/20	20/20
`shim::attached_backpressure_and_detached_progress`	(b)	12 busy loops + 4 parallel copies	19/20, 39/40	40/40 (`a5c95e32a`)
`status_restart::service_states_are_truthful_in_text_and_json`	(b)	binary pages evicted before every run + 2 agent suites + 6 busy loops, load 22–33	14/20, 17/20	20/20 (`e0809a0d9`, `6984ff653`, `b9646fd05`)
`saved_shell_automation_uses_an_owner_only_socket_directory`	(a) product + (b) oracle	sustained `dd` writeback on the state disk	15/20 under the heavy mix; 11/20 with only `ad2c6b9eb`	20/20 (`ad2c6b9eb`, `c7cde1f0a`, `e7d902ffa`)
desktop `source_bridge::replay_repairs_coalesce_at_the_source_interval`	env, not timing	`CARGO_TARGET_DIR` unset	unwrap panic	fixed (`5e2ead65b`)

cli after-run, publication fsync in that window: n=57 p50=1.247 p90=2.436 max=5.264. new calls took up to 4.3 s and all succeeded. The heavy CPU mix was not rerun after the fix; its failures were the fsync stall and the oracle's own deadlines, both covered above.

Red checks (all fail as intended, never committed): sequenced QUIC→TCP fallback; save() back on the reactor; second status observation on its own 2 s deadline.

None of these is class (c), so nothing moves to the perf VM. The only latency measurement involved, supervisor first-Hello time, already lives in the ignored supervisor_300ms_quic_and_blocked_udp_fallback diagnostic.

Progress 8. All fixes are on the branch, head `e7d902ffa`. `verify quick` plus `verify fast` ×2 are queued on dev-02. | test | class | load that failed it (dev-02) | before | after | |---|---|---|---|---| | `unavailable_udp_does_not_add_seconds_before_tcp_admission` | (b) | 2 full agent suites + 6 busy loops, load 22–34 | 6/20 | **20/20** (`20b1b03de`) | | `winning_quic_drops_the_unfinished_tls_dial_before_control_dispatch` | (b) | same | 6/20 | **20/20** | | `server_path_capability_is_advertised_on_native_and_fallback_transports` (same cause) | (b) | same | 9/20 | **20/20** | | `shim::attached_backpressure_and_detached_progress` | (b) | 12 busy loops + 4 parallel copies | 19/20, 39/40 | **40/40** (`a5c95e32a`) | | `status_restart::service_states_are_truthful_in_text_and_json` | (b) | binary pages evicted before every run + 2 agent suites + 6 busy loops, load 22–33 | 14/20, 17/20 | **20/20** (`e0809a0d9`, `6984ff653`, `b9646fd05`) | | `saved_shell_automation_uses_an_owner_only_socket_directory` | **(a)** product + (b) oracle | sustained `dd` writeback on the state disk | 15/20 under the heavy mix; 11/20 with only `ad2c6b9eb` | **20/20** (`ad2c6b9eb`, `c7cde1f0a`, `e7d902ffa`) | | desktop `source_bridge::replay_repairs_coalesce_at_the_source_interval` | env, not timing | `CARGO_TARGET_DIR` unset | unwrap panic | fixed (`5e2ead65b`) | cli after-run, publication fsync in that window: `n=57 p50=1.247 p90=2.436 max=5.264`. `new` calls took up to 4.3 s and all succeeded. The heavy CPU mix was not rerun after the fix; its failures were the fsync stall and the oracle's own deadlines, both covered above. Red checks (all fail as intended, never committed): sequenced QUIC→TCP fallback; `save()` back on the reactor; second status observation on its own 2 s deadline. None of these is class (c), so nothing moves to the perf VM. The only latency measurement involved, supervisor first-Hello time, already lives in the ignored `supervisor_300ms_quic_and_blocked_udp_fallback` diagnostic.

kayg commented

2026-11-04 09:24:27 +00:00

Author

Owner

Finish. Branch timing-flakes-j163, head e7d902ffa93aad5aadd88d87c5ab60331bdc4666, base origin/dev f14e4309a. Not merged, not deployed.

scripts/verify quick (pre-check, not the gate): QUICK_EXIT=0, "QUICK pre-check passed."

scripts/verify fast twice in a row on dev-02 at that head (run 1 started 08:27 UTC at load 8.97, run 2 at 09:01 UTC at load 3.43). Verbatim:

HEAD e7d902ffa93aad5aadd88d87c5ab60331bdc4666
QUICK_EXIT=0
== fast run 1 start 08:27 load=8.97
VERIFY_EXIT_1=0
== fast run 2 start 09:01 load=3.43
VERIFY_EXIT_2=1
######## fast run 1
+---------------------------+--------------+
| Rust gate                 | Result       |
+---------------------------+--------------+
| fmt                       | PASS         |
| VT native fmt             | PASS         |
| CLI plugin compile-out    | PASS         |
| clippy                    | PASS         |
| SSH runtime test helper   | PASS         |
| real-binary fixture paths | PASS         |
| Traefik component manifest | PASS         |
| release component publication | PASS         |
| test                      | PASS         |
| SSH inode reuse fixture   | PASS         |
| shim process-per-user     | PASS         |
| cargo-deny                | PASS         |
| gate architecture         | PASS         |
| static builds             | PASS         |
######## fast run 2
+---------------------------+--------------+
| Rust gate                 | Result       |
+---------------------------+--------------+
| fmt                       | PASS         |
| VT native fmt             | PASS         |
| CLI plugin compile-out    | PASS         |
| clippy                    | PASS         |
| SSH runtime test helper   | PASS         |
| real-binary fixture paths | PASS         |
| Traefik component manifest | PASS         |
| release component publication | PASS         |
| test                      | FAIL (101)   |
| SSH inode reuse fixture   | PASS         |
| shim process-per-user     | PASS         |
| cargo-deny                | PASS         |
| gate architecture         | PASS         |
| static builds             | PASS         |

Run 2 test failure: pre-existing flake, not from this branch. session_exit_events::idle_daemon_discovers_unattached_and_adopted_shim_exit_without_requests failed in scripts/verify-session-exit-events.py:51 → client.open() → agent_fixture.py:264 read → TimeoutError: timed out. The infraternal agent fixture did not answer terminal.open within the fixture's socket timeout. This branch changes nothing on that path; it changes only the sessions automation publication. The identical failure, at the same call site, is in older gate logs of three unrelated branches on dev-02: appwin-launch-idle-146/verify-fast-c51226569.log (11-01), j16-appwin/fast-final-home-roots.log (10-31), j62b/verify-fast-c.log (11-03). It belongs with the agent_daemon/fixture readiness family on #324 (J157). Run 1 passed it. I started a 10× isolated rerun but stopped it: each run had to queue for a build slot separately.

Static builds: the static builds row passes in both runs (D243 caps removed). I did not separately extract the x86/arm size delta; the only product change is a few lines in automation/operations plus one debug-only status env read (compiled out of release).

Cleanup: target dir, copied binaries and temp state on dev-02 deleted. Logs kept: ~/j163-*.log, ~/j163-runs/.

Open questions for kayg (recommendation first):

Session-name durability semantic (c7cde1f0a): sessions new now awaits the fsynced name outside the 4 s action deadline, off the reactor. A slow disk delays only that reply. Alternative: keep it inside the deadline and answer code 5 "may have started". Recommend keeping it as committed.
Orphaned detached shim on a 2 s handshake timeout (launch_configured): the caller gets "operation failed" while an unnamed session appears later. Recommend a separate issue.
The 3 s source_bridge timeout in the original report could not be found in any log on either VM.

Finish. Branch `timing-flakes-j163`, head **`e7d902ffa93aad5aadd88d87c5ab60331bdc4666`**, base origin/dev `f14e4309a`. Not merged, not deployed. `scripts/verify quick` (pre-check, not the gate): `QUICK_EXIT=0`, "QUICK pre-check passed." `scripts/verify fast` twice in a row on dev-02 at that head (run 1 started 08:27 UTC at load 8.97, run 2 at 09:01 UTC at load 3.43). Verbatim: ``` HEAD e7d902ffa93aad5aadd88d87c5ab60331bdc4666 QUICK_EXIT=0 == fast run 1 start 08:27 load=8.97 VERIFY_EXIT_1=0 == fast run 2 start 09:01 load=3.43 VERIFY_EXIT_2=1 ######## fast run 1 +---------------------------+--------------+ | Rust gate | Result | +---------------------------+--------------+ | fmt | PASS | | VT native fmt | PASS | | CLI plugin compile-out | PASS | | clippy | PASS | | SSH runtime test helper | PASS | | real-binary fixture paths | PASS | | Traefik component manifest | PASS | | release component publication | PASS | | test | PASS | | SSH inode reuse fixture | PASS | | shim process-per-user | PASS | | cargo-deny | PASS | | gate architecture | PASS | | static builds | PASS | ######## fast run 2 +---------------------------+--------------+ | Rust gate | Result | +---------------------------+--------------+ | fmt | PASS | | VT native fmt | PASS | | CLI plugin compile-out | PASS | | clippy | PASS | | SSH runtime test helper | PASS | | real-binary fixture paths | PASS | | Traefik component manifest | PASS | | release component publication | PASS | | test | FAIL (101) | | SSH inode reuse fixture | PASS | | shim process-per-user | PASS | | cargo-deny | PASS | | gate architecture | PASS | | static builds | PASS | ``` **Run 2 `test` failure: pre-existing flake, not from this branch.** `session_exit_events::idle_daemon_discovers_unattached_and_adopted_shim_exit_without_requests` failed in `scripts/verify-session-exit-events.py:51` → `client.open()` → `agent_fixture.py:264 read` → `TimeoutError: timed out`. The infraternal agent fixture did not answer `terminal.open` within the fixture's socket timeout. This branch changes nothing on that path; it changes only the `sessions` automation publication. The identical failure, at the same call site, is in older gate logs of three unrelated branches on dev-02: `appwin-launch-idle-146/verify-fast-c51226569.log` (11-01), `j16-appwin/fast-final-home-roots.log` (10-31), `j62b/verify-fast-c.log` (11-03). It belongs with the `agent_daemon`/fixture readiness family on #324 (J157). Run 1 passed it. I started a 10× isolated rerun but stopped it: each run had to queue for a build slot separately. Static builds: the `static builds` row passes in both runs (D243 caps removed). I did not separately extract the x86/arm size delta; the only product change is a few lines in `automation`/`operations` plus one debug-only status env read (compiled out of release). Cleanup: target dir, copied binaries and temp state on dev-02 deleted. Logs kept: `~/j163-*.log`, `~/j163-runs/`. Open questions for kayg (recommendation first): 1. **Session-name durability semantic** (`c7cde1f0a`): `sessions new` now awaits the fsynced name outside the 4 s action deadline, off the reactor. A slow disk delays only that reply. Alternative: keep it inside the deadline and answer code 5 "may have started". Recommend keeping it as committed. 2. **Orphaned detached shim** on a 2 s handshake timeout (`launch_configured`): the caller gets "operation failed" while an unnamed session appears later. Recommend a separate issue. 3. The 3 s `source_bridge` timeout in the original report could not be found in any log on either VM.

kayg referenced this issue

2026-11-04 10:03:41 +00:00

Engineering practices proposal #344

kayg referenced this issue

2026-11-04 10:08:45 +00:00

Engineering practices proposal #344

kayg referenced this issue

2026-11-04 10:22:03 +00:00

Engineering practices proposal #344

kayg commented

2026-11-04 10:47:44 +00:00

Author

Owner

J176 review: `timing-flakes-j163` @ `e7d902ffa9` (base `f14e4309a`): APPROVE

No P1 or P2 findings. One P3 (non-blocking).

`c7cde1f0a` / `ad2c6b9eb` (session-name save moved off the event loop)

Ordering: OK. Only sessions new writes session-names.json. close doesn't write it, and there is no rename verb. The local automation socket serves one connection at a time (plugin_control.rs:677, serve(...).await in the accept loop), and execute awaits the save before it replies. So no later request can overtake the save or overwrite it.
Queue and threads: bounded. Because of the one-at-a-time accept loop, at most one save is in flight. A flood of new requests waits in the socket backlog and adds no threads or tasks. Trade-off: a slow disk delays other sessions.* calls queued behind the save (it did before too), but it no longer blocks terminals.
Crash consistency: kept. The save still fsyncs the file, renames it, fsyncs the directory, and only then replies. strace of the real debug binary during scripts/test-cli-sessions.py on dev-02 (excerpt; thread 2432813 is a blocking-pool thread, 2431980 is the event loop):
```
2432813 10:46:57.423434 write(17, ..., 68) = 68
2432813 10:46:57.423557 fsync(17)       = 0
2432813 10:46:57.435187 renameat(...)   = 0
2432813 10:46:57.435550 fsync(18)       = 0
2431980 10:46:57.444171 sendto(15, ..., 156, MSG_NOSIGNAL, NULL, 0) = 156
```
All 6 fsyncs in the run were on the blocking-pool thread. None ran on the event-loop thread.
Error path: OK. If the save fails, the task closes the unnamed session, and the published.is_ok() guard turns the reply into code 1. A JoinError is mapped to an io error and also gives code 1.
Other fsyncs on the event loop: none in the automation path. save() is its only fsync.

Tests and the budget override

INFRATERNAL_TEST_MANAGER_QUERY_BUDGET_MS sits behind #[cfg(debug_assertions)], and [profile.release] doesn't enable debug assertions. Proven with a build on dev-02: the release libinfraternal_status rlib has 0 hits for the env var name, and the debug rlib has 1. The production deadline stays 500 ms.
status_restart: the matrix never tested an expiring deadline. Expiry is still covered by manager_completion_handles_an_already_exited_child_and_a_deadline. The shared-deadline rule moved to the new unit test one_deadline_spans_both_observations_of_a_fresh_start. Fresh starts are now stamped when the manager is queried, which fixes a fixture that went stale on slow runs. It does not loosen the 10 s window.
shim: the threshold change from seq+1024 to seq+1 only affects when the wait starts. The proof is still stalled < 1_000_000, which stays intact.
QUIC/TCP: unavailable_udp... now proves TCP connected while the same QUIC attempt (same DCID) was still retransmitting. That is a causal ordering proof, and the biased select stops early Initials from counting as later evidence. In winning_quic... the proxy starts only after the TCP ClientHello, so QUIC wins by construction. The 1 s EOF check stays below the 5 s Hello timeout. The other 2-3 s bounds became 30 s hang guards. None of them were production deadlines.
test-cli-sessions.py: fixed sleeps and deadlines became condition waits with a 120 s hang bound. The close check still tells a working close from a broken one, because the shell's foreground job runs 20 s.

Runs (dev-02, worktree ~/worktrees/j176 at `e7d902ffa`, through build-slot)

cargo test -p infraternal-agent --lib automation   -> ok. 8 passed; 0 failed (incl. a_held_name_publication_leaves_the_reactor_serving_other_work)
cargo test -p infraternal-status --lib             -> ok. 24 passed; 0 failed; 1 ignored
release rlib hits: 0 / debug rlib hits: 1
scripts/test-cli-sessions.py (under strace)        -> {"ok": true, ...} CLI_EXIT=0

P3: shutdown during a save can skip the cleanup (from reading the code, not reproduced)

The infraternal agent shuts down by returning from runtime.block_on (infraternal-agent/src/lib.rs:74), which drops the runtime. Tokio lets a running spawn_blocking save finish but cancels the async publish task. If that save fails, the unnamed session's CloseSession cleanup never runs. The client gets EOF, never "saved", so nobody is told the name was durable when it wasn't, and the file is atomic (old or new, never torn). Before this branch the save ran on the event loop and couldn't be interrupted this way. Suggestion for later: have shutdown await the pending publication, or run the close inside the blocking closure. Not a merge blocker.

## J176 review: `timing-flakes-j163` @ e7d902ffa93aad5aadd88d87c5ab60331bdc4666 (base f14e4309a): **APPROVE** No P1 or P2 findings. One P3 (non-blocking). ### c7cde1f0a / ad2c6b9eb (session-name save moved off the event loop) - **Ordering:** OK. Only `sessions new` writes `session-names.json`. `close` doesn't write it, and there is no rename verb. The local automation socket serves one connection at a time (`plugin_control.rs:677`, `serve(...).await` in the accept loop), and `execute` awaits the save before it replies. So no later request can overtake the save or overwrite it. - **Queue and threads:** bounded. Because of the one-at-a-time accept loop, at most one save is in flight. A flood of `new` requests waits in the socket backlog and adds no threads or tasks. Trade-off: a slow disk delays other `sessions.*` calls queued behind the save (it did before too), but it no longer blocks terminals. - **Crash consistency:** kept. The save still fsyncs the file, renames it, fsyncs the directory, and only then replies. strace of the real debug binary during `scripts/test-cli-sessions.py` on dev-02 (excerpt; thread 2432813 is a blocking-pool thread, 2431980 is the event loop): ``` 2432813 10:46:57.423434 write(17, ..., 68) = 68 2432813 10:46:57.423557 fsync(17) = 0 2432813 10:46:57.435187 renameat(...) = 0 2432813 10:46:57.435550 fsync(18) = 0 2431980 10:46:57.444171 sendto(15, ..., 156, MSG_NOSIGNAL, NULL, 0) = 156 ``` All 6 fsyncs in the run were on the blocking-pool thread. None ran on the event-loop thread. - **Error path:** OK. If the save fails, the task closes the unnamed session, and the `published.is_ok()` guard turns the reply into code 1. A JoinError is mapped to an io error and also gives code 1. - **Other fsyncs on the event loop:** none in the automation path. `save()` is its only fsync. ### Tests and the budget override - `INFRATERNAL_TEST_MANAGER_QUERY_BUDGET_MS` sits behind `#[cfg(debug_assertions)]`, and `[profile.release]` doesn't enable debug assertions. Proven with a build on dev-02: the release `libinfraternal_status` rlib has **0** hits for the env var name, and the debug rlib has **1**. The production deadline stays 500 ms. - status_restart: the matrix never tested an expiring deadline. Expiry is still covered by `manager_completion_handles_an_already_exited_child_and_a_deadline`. The shared-deadline rule moved to the new unit test `one_deadline_spans_both_observations_of_a_fresh_start`. Fresh starts are now stamped when the manager is queried, which fixes a fixture that went stale on slow runs. It does not loosen the 10 s window. - shim: the threshold change from `seq+1024` to `seq+1` only affects when the wait starts. The proof is still `stalled < 1_000_000`, which stays intact. - QUIC/TCP: `unavailable_udp...` now proves TCP connected while the same QUIC attempt (same DCID) was still retransmitting. That is a causal ordering proof, and the biased select stops early Initials from counting as later evidence. In `winning_quic...` the proxy starts only after the TCP ClientHello, so QUIC wins by construction. The 1 s EOF check stays below the 5 s Hello timeout. The other 2-3 s bounds became 30 s hang guards. None of them were production deadlines. - test-cli-sessions.py: fixed sleeps and deadlines became condition waits with a 120 s hang bound. The close check still tells a working close from a broken one, because the shell's foreground job runs 20 s. ### Runs (dev-02, worktree ~/worktrees/j176 at e7d902ffa, through build-slot) ``` cargo test -p infraternal-agent --lib automation -> ok. 8 passed; 0 failed (incl. a_held_name_publication_leaves_the_reactor_serving_other_work) cargo test -p infraternal-status --lib -> ok. 24 passed; 0 failed; 1 ignored release rlib hits: 0 / debug rlib hits: 1 scripts/test-cli-sessions.py (under strace) -> {"ok": true, ...} CLI_EXIT=0 ``` ### P3: shutdown during a save can skip the cleanup (from reading the code, not reproduced) The infraternal agent shuts down by returning from `runtime.block_on` (`infraternal-agent/src/lib.rs:74`), which drops the runtime. Tokio lets a running `spawn_blocking` save finish but cancels the async `publish` task. If that save fails, the unnamed session's `CloseSession` cleanup never runs. The client gets EOF, never "saved", so nobody is told the name was durable when it wasn't, and the file is atomic (old or new, never torn). Before this branch the save ran on the event loop and couldn't be interrupted this way. Suggestion for later: have shutdown await the pending publication, or run the close inside the blocking closure. Not a merge blocker.

kayg referenced this issue from a commit

2026-11-04 11:50:53 +00:00

agent: a failed launch keeps closing a slow detached shim until it answers (#324, #334)

kayg referenced this issue

2026-11-04 14:13:36 +00:00

agent_daemon tests flake under load (resource_unavailable on readiness open, lazy-manager accept timeout) #324

kayg referenced this issue

2026-11-04 16:15:29 +00:00

Agent: durable writes off the event loop (follow-up to #334, #344) #347

kayg referenced this issue

2026-11-04 16:17:10 +00:00

agent_daemon tests flake under load (resource_unavailable on readiness open, lazy-manager accept timeout) #324