diff --git a/devlog/_plan/260905_windows_suite_stabilization/000_plan.md b/devlog/_plan/260905_windows_suite_stabilization/000_plan.md index 6a56e38bfd..306805f50d 100644 --- a/devlog/_plan/260905_windows_suite_stabilization/000_plan.md +++ b/devlog/_plan/260905_windows_suite_stabilization/000_plan.md @@ -58,16 +58,17 @@ prevent a defect that does not exist. ## Research -`001`-`006` are analysis and are not implemented from: +`001`-`007` are analysis and are not implemented from: | doc | what it is | |---|---| | `001_runtime_fault.md` | the 1.3.14-vs-1.4.0 A/B, and the method correction | -| `002_v140_baseline.md` | the corrected baseline and root-cause roll-up | +| `002_v140_baseline.md` | the raw 1.4.0 shard counts — its ACL diagnosis is retracted by `007` | | `003_void_preload_analysis.md` | VOID — a 1.3.14-only mechanism; records a latent hazard at `tests/preload.ts:41` | | `004_void_singles_analysis.md` | VOID — four of six "singles" do not exist on 1.4.0 | | `005_wedge_resolution.md` | RESOLVED — the shard-3 wedge was the runtime; no code target | | `006_void_inventory_1314.md` | VOID — the first inventory, kept as the record of the mistake | +| `007_acl_defect_retracted.md` | RETRACTED — the 22-failure "ACL seam" defect was self-inflicted contamination | ## Acceptance for the unit diff --git a/devlog/_plan/260905_windows_suite_stabilization/002_v140_baseline.md b/devlog/_plan/260905_windows_suite_stabilization/002_v140_baseline.md index f1e09e4213..16687b7ac2 100644 --- a/devlog/_plan/260905_windows_suite_stabilization/002_v140_baseline.md +++ b/devlog/_plan/260905_windows_suite_stabilization/002_v140_baseline.md @@ -1,5 +1,16 @@ # 002 — Corrected baseline on the pinned runtime (`bun 1.4.0`) +> **PARTIALLY SUPERSEDED by `007_acl_defect_retracted.md`.** The shard counts +> below are the raw measurement and stand. The DIAGNOSIS does not: the 22 +> shard-2 failures attributed here to an ACL-seam defect were contamination +> from a killed 1.3.14 run, proven by a probe that stubbed both `icacls` +> runners and logged zero invocations while the failures persisted. On a clean +> tree that file is 22 pass in 1.4s. +> +> Read `007` before using anything in this document. Every "three defects" and +> "defect 2" reference below should be read as **two** defects; phase `010` and +> its follow-up `040` are retracted. + Same box, same checkout, same serial lock. The only change from `000` is the binary: `./node_modules/bun/bin/bun.exe` (1.4.0, the version `package.json:68` pins) instead of the 1.3.14 on `PATH`. @@ -82,7 +93,7 @@ fabric guard failures do not exist on the pinned runtime. ### Where the implementation plans live -This document is research: baseline and root-cause analysis only. One diff-level +This document is research: the raw baseline, plus a root-cause roll-up whose ACL portion is retracted by 007. One diff-level document per surviving phase, each independently landable: | doc | defect | failures | files touched | diff --git a/devlog/_plan/260905_windows_suite_stabilization/007_acl_defect_retracted.md b/devlog/_plan/260905_windows_suite_stabilization/007_acl_defect_retracted.md index 14cd1f41c0..1f15e92147 100644 --- a/devlog/_plan/260905_windows_suite_stabilization/007_acl_defect_retracted.md +++ b/devlog/_plan/260905_windows_suite_stabilization/007_acl_defect_retracted.md @@ -32,9 +32,23 @@ A mechanism that never executes cannot be the cause. Every claim in `010` about `tests/.tmp-oauth-store-multi-test/auth.json`, timestamped **00:44** — from the 1.3.14 baseline, hours earlier. At 01:08 I sent `kill -9` to the wedged shard-3 -process (PID 1382, `001`/`005`). On Windows that leaves the handle held: the -process is gone but its open file keeps the directory undeletable, and every -later `beforeEach` in that fixture hit EPERM. +process (PID 1382, `001`/`005`). + +**Something left by that killed run held the directory**, so every later +`beforeEach` in the fixture hit EPERM until the leftover was removed by hand. + +What the evidence does NOT establish is WHO held it. An earlier draft of this +document said the dead process kept its own handle; that is wrong — Windows +closes a terminated process's handles. The candidates that remain — a surviving +descendant of the killed shard, an indexer or antivirus scanner that opened the +file, or a delete pending on a handle closed later — were not distinguished, +because no handle-owner snapshot was taken before the directory was deleted. +Taking one (`handle.exe`, `openfiles`, or Resource Monitor) is what a future +occurrence should start with. + +What IS established: the killed run is the origin (the debris carries its +timestamp), `icacls` is not the mechanism (0 invocations with both runners +stubbed), and the file is green once the debris is gone. After deleting the leftover: @@ -87,9 +101,10 @@ built on top of it. ## Operational lesson, now a rule for this unit -**A killed suite process contaminates the next run.** `kill -9` on a Bun test -process leaves Windows handles held. Before any measurement that a conclusion -depends on: +**A killed suite run contaminates the next one.** `kill -9` on a Bun test process +leaves debris that something on the box may still hold — the mechanism was not +identified, and the practical rule does not depend on identifying it. Before any +measurement that a conclusion depends on: ```bash cd /c/ocxwin/repo && git status --short # leftover tests/.tmp-* dirs? diff --git a/devlog/_plan/260905_windows_suite_stabilization/008_oauth_lease_residual.md b/devlog/_plan/260905_windows_suite_stabilization/008_oauth_lease_residual.md new file mode 100644 index 0000000000..bde90afce5 --- /dev/null +++ b/devlog/_plan/260905_windows_suite_stabilization/008_oauth_lease_residual.md @@ -0,0 +1,286 @@ +# 008 — Residual: one OAuth-lease case still loses a teardown race + +Found by confirmation run 1, on a clean tree, after the two fixes landed. + +## What happened + +Shard 2 of the confirmation run: **4627 pass / 16 skip / 1 fail**, down from 22. +The survivor is the LAST test in the file: + +``` +error: EPERM: operation not permitted, rm 'C:\ocxwin\repo\tests\.tmp-oauth-store-multi-test' + at removeTreeWithRetry (tests/helpers/remove-tree.ts:28:83) + at tests/oauth-store-multi.test.ts:61 (afterEach) +(fail) multi-account auth store > OAuth 30 second wait timeout releases an + unstarted lease and never enters the chain [2641.81ms] +``` + +The 21 cases before it pass. That distribution is the finding: this is not the +directory being unusable — it is one specific test leaving something behind. + +## Why this is NOT the retracted defect + +`007` retracted a 22-failure "ACL seam" diagnosis because the failures were +contamination and `icacls` was never invoked. This one is different on every +axis that matters: + +| | retracted (`007`) | this | +|---|---|---| +| failures | all 22, from the first `beforeEach` | 1, the last case only | +| tree state | debris from a killed 1.3.14 run | clean, verified before the run | +| reproduces alone | no — 22 pass in 1.4s | not yet established | + +So the ACL analysis stays retracted. What this shows is that removing the +contamination exposed a smaller, real race that the 22 failures had been masking. + +## Hypothesis, explicitly unproven + +`tests/oauth-store-multi.test.ts:372` drives the OAuth mutation queue: a blocking +mutation holds a lease while a second one is rejected by a `waitMs` timeout. Its +`finally` releases the blocker and awaits both promises +(`allSettled([blocker, timedOut])`), so the JS side settles — but the store's own +lock file (`getAuthStoreLockPath()`, `src/oauth/store.ts:61`) and any fd behind it +are not obviously drained by that await. If a handle survives the test body, the +`afterEach` delete races it, and `removeTreeWithRetry` spends 50×50ms before +rethrowing — consistent with the 2641ms duration. + +**That is a hypothesis built from reading, and the last time I did that in this +unit I was wrong** (`007`). It is not a plan until it is measured. + +## Measurement 1: it does not reproduce alone + +Box idle, suite lock held, pinned runtime, five consecutive runs of the file: + +``` +run1 exit=0 fails=0 +run2 exit=0 fails=0 +run3 exit=0 fails=0 +run4 exit=0 fails=0 +run5 exit=0 fails=0 +``` + +0/5. So the hypothesis above — "this test leaves its own lock behind" — is not +supported: if the test's own teardown were the whole story it would fail alone +too. Whatever holds the directory needs the rest of the shard to be present. + +That also means it cannot be fixed by reading the file. The remaining candidates +are load-dependent: another file in the shard touching the same fixture path, +a slower release under 265-file memory pressure that outlasts 50×50ms, or an +external scanner reacting to churn the solo run does not produce. + +Note that after the confirmation run the directory was left behind again and +deleted cleanly by hand — so nothing holds it once the suite exits. The window +is inside the run. + +## Measurement 2: deterministic within the shard + +Shard 2 re-run alone, box idle, lock held: + +``` + 4627 pass · 16 skip · 1 fail · [1034.21s] + (fail) multi-account auth store > OAuth 30 second wait timeout releases an + unstarted lease and never enters the chain +``` + +Byte-identical outcome to the confirmation run. So: + +| context | result | +|---|---| +| the file alone, ×5 | 0 fail | +| the whole shard, ×2 | 1 fail, the same case both times | + +Deterministic given the shard, absent without it. Not a flake, and not the test's +own teardown in isolation. + +## Measurement 3: it is not a path collision + +`rg -l 'tmp-oauth-store-multi-test' tests/` returns exactly one file — the test +itself. No sibling in shard 2 writes that directory, so a second writer is ruled +out. What the shard supplies is load and preceding state, not a competing path. + +The three files immediately before it in shard order are +`oauth-login-cli-live-update`, `oauth-open-browser-choice` and +`oauth-refresh-generic-lock` — all OAuth-store adjacent, and the last one drives +refresh locks. That is a lead, not a conclusion. + +## Measurement 4: a two-file repro + +Bisecting the shard found the minimal pair, which cuts the cycle from 17 minutes +to two: + +``` +bun.exe test --isolate tests/oauth-refresh-generic-lock.test.ts \ + tests/oauth-store-multi.test.ts + → 22 fail (the SAME 22 the contamination used to produce) +``` + +On macOS the identical pair is 28 pass / 0 fail, so it is Windows-specific. + +Note what this changes about the confirmation run: shard 2 showed only ONE +failure because the shard's file ordering put something between the two that +broke the interaction. The pair is the honest reproduction. + +## Measurement 5: the directory is not locked + +A preload `afterEach` that inspects the fixture directory before the test's own +teardown: + +``` + 1 ["auth.json"] -> unlink OK + 5 [] -> unlink OK +``` + +The file deletes cleanly and the directory is left empty. So no handle is held on +`auth.json`, which kills the "something still owns the file" family of +hypotheses — including the one `008` opened with. + +Then the decisive one. The same preload, but calling `rmdirSync` on the now-empty +directory before the test's `removeTreeWithRetry` runs: + +``` +FAILS=0 (from 22) +28 readdir failed: ENOENT ... procs=13 +``` + +**Removing the directory with `rmdirSync` succeeds every time, and the whole +failure disappears.** The directory is not locked by anything. What fails is +`rmSync(path, { recursive: true, force: true })` — the default remover inside +`removeTreeWithRetry` (`tests/helpers/remove-tree.ts:17`) — on this Windows host, +against a directory a plain `rmdirSync` deletes. + +## Measurement 6: `rmSync` is not broken, and the repro is load-dependent + +Both follow-up questions were answered, and both answers were negative. + +A standalone probe on the box exercising the exact removal shapes: + +``` +empty-rmSync: OK +empty-rmdir: OK +file-rmSync: OK +file-unlink-then-rmdir: OK +``` + +So `rmSync(recursive)` is fine here in isolation — measurement 5's conclusion +("the removal call is the cause") was too strong. + +Then the pair itself, on a now-idle box: + +| run | fails | wall | +|---|---|---| +| bare ×3 | 0 | 5.4-5.6s | +| with the leftover directory pre-created | 0 | 5.5s | +| bare ×5 more | 0 | 5.5-5.8s | + +**8 consecutive clean runs.** Meanwhile every run that DID fail took ~119s — +22× longer — and its slowest cases were all ~5.2s, which is exactly +`removeTreeWithRetry`'s 50 × 50 ms budget plus overhead. So in the failing runs +something really did hold the directory for the full retry window; in the passing +runs nothing does. + +What separates them is not the code. Every failing reproduction ran while the box +was busy — during or immediately after a full shard, or while my own +(lock-blocked) probe workers were alive. The passing ones ran on an idle machine. + +## Status: NOT diagnosed + +Honest summary of what is known: + +- Real: it happened twice in full shard-2 runs, deterministically, and 22× + in the two-file pair while the box was loaded. +- Not the file alone (0/5 solo), not a path collision (single writer), not the + retracted ACL mechanism (0 runner invocations), not `rmSync` itself + (isolated probe passes), not the leftover directory (pre-creating it passes). +- The failing signature is a genuine 2.5s+ hold on the directory, seen only under + load. + +That is a load-dependent Windows filesystem hold whose owner has still not been +identified — the same gap `007` had, and I have not closed it here either. The +one measurement that would close it is a handle-owner snapshot taken WHILE the +failure is happening (`handle.exe` / `openfiles` from a second shell during a +loaded run), which requires reproducing under load on purpose. + +## Recommendation + +Do not patch this now. It is one case out of 17807, it does not reproduce on an +idle machine, and the two previous attempts to name its cause from reading were +both wrong. The defensible next step is the handle-owner snapshot under load; the +defensible interim position is to report the suite as **1 failure remaining, +cause unidentified**, rather than to ship a speculative teardown change to a +helper the whole suite shares. + +## Measurement 7: the handle-owner snapshot, and why it failed + +I tried the snapshot anyway: a background watcher polling once a second for the +fixture directory and, when present, listing candidate processes through +`powershell.exe`, while shard 2 ran as the load. + +It destroyed the experiment. Five minutes in, the shard had **72 failures across +ten unrelated suites** — `Codex catalog sync hardening` (25), +`020 coverage completions` (17), `ocx models` (7), and others that have never +failed in any run of this unit. The watcher's own per-second `powershell.exe` +spawns were the new load, and child-process-spawning tests started failing on +`r.status`. The watcher never captured a single sample: the directory exists for +milliseconds at a time, so a 1 Hz poll missed every window, and `watch.log` was +empty when I killed it. + +So the run is discarded — it measured my instrument, not the defect. Worse, it is +the same class of mistake as `007`: I added a process to the box and then read +the resulting failures as if they were properties of the code. + +What this does establish, accidentally but usefully: **these Windows failures are +load-sensitive across the board.** Adding one poll-per-second process was enough +to break 72 cases in ten suites. That is context for the 1 remaining failure — +and a warning that any future "flaky on Windows" claim from this box needs the +box's own load accounted for. + +A correct snapshot needs an instrument that does not compete: an ETW/Sysmon trace +or a `handle.exe` invocation triggered by the failing `afterEach` itself, not a +polling loop. That is a real piece of work and it is not justified by one failing +case out of 17807. + +## Measurement 8: it is deterministic in a shard, on an idle box + +Confirmation run 2, box fully idle, no watcher, no competing process — the same +case failed again, at the same log offset: + +``` +3707:tests\oauth-store-multi.test.ts: +3736:error: EPERM ... rm 'C:\ocxwin\repo\tests\.tmp-oauth-store-multi-test' +``` + +Three shard-2 runs, three identical failures. So "load-dependent" from +measurement 6 was wrong as a cause: the load explains why the two-file PAIR +needed it, not why the SHARD fails. Corrected picture: + +| context | runs | result | +|---|---|---| +| the file alone | 5 | pass | +| the two-file pair, idle | 8 | pass | +| the two-file pair, box loaded | 1 | 22 fail | +| **full shard 2, idle or not** | **3** | **1 fail, always the same case** | + +Something in the other ~263 files of shard 2 is required, and once present the +failure is reliable. That is a much better position to debug from than "flaky +under load" — and it means the eventual bisect target is the shard, not the pair. + +## Final position for this cycle + +**1 failure remaining, cause unidentified, no fix attempted.** The two defects +this unit set out to fix are fixed and verified. This one is documented to the +limit of what was measured, including the two dead ends, the instrument that +contaminated its own experiment, and the corrected load hypothesis above. + +The next person's cheapest path is a binary search over shard 2's file list with +`oauth-store-multi` pinned last — roughly 8 runs of ~2 minutes each to find the +file that arms it, rather than the 17-minute full-shard cycle used here. + +## Process note + +While diagnosing this I started a repeat-run loop on the box **while the +confirmation run still held `/c/ocxwin/.suite.lock`** — the exact parallel +execution this unit is required to avoid. It did no damage (the repo's own +test-run lock blocked my workers: *"bare Bun worker 8876 is waiting for test run +pid 424"*), and the shard-2 failure timestamp precedes my first probe, so the +result stands. The workers were killed and only the confirmation run left +running. Recorded because the guard that saved it was the repository's, not mine. diff --git a/devlog/_plan/260905_windows_suite_stabilization/009_confirmation_run_1.md b/devlog/_plan/260905_windows_suite_stabilization/009_confirmation_run_1.md new file mode 100644 index 0000000000..a3285a2bde --- /dev/null +++ b/devlog/_plan/260905_windows_suite_stabilization/009_confirmation_run_1.md @@ -0,0 +1,50 @@ +# 009 — Confirmation run 1: 25 failures → 1 + +First full four-shard run with both fixes applied. Pinned runtime +(`./node_modules/bun/bin/bun.exe`, 1.4.0), serial under `/c/ocxwin/.suite.lock`, +tree verified clean before starting. + +| shard | pass | skip | fail | wall | baseline was | +|---|---|---|---|---|---| +| 1/4 | 4462 | 39 | **0** | 974s | 2 | +| 2/4 | 4627 | 16 | **1** | 1044s | 22 (contaminated — `007`) | +| 3/4 | 4305 | 12 | **0** | 1272s | 1 | +| 4/4 | 4413 | 12 | **0** | 978s | 0 | +| total | **17807** | 79 | **1** | 4268s | 25 | + +## What the fixes did + +- **Shard 1, 2 → 0.** `tests/multi-agent-keep-native-v1.test.ts` no longer reads + the `cmd.exe` launcher's positional argv. `featureActionOf` parses the two + shapes `commandInvocation` emits. +- **Shard 3, 1 → 0.** `tests/update-notify.test.ts` skips the unlinked-cwd case + on Windows, where the state cannot exist. +- **Shard 2, 22 → 1.** Not a fix — `007`. Twenty-one of those were contamination + from a killed 1.3.14 run. The survivor is a different, real problem: `008`. + +## The one that remains + +`multi-account auth store > OAuth 30 second wait timeout releases an unstarted +lease and never enters the chain` — EPERM on the `afterEach` directory delete, +last case in its file, 21 siblings green. + +It does **not** reproduce alone: 0 failures in 5 consecutive solo runs of that +file on an idle box. So it needs the shard around it, and it cannot be diagnosed +by reading the test. `008` carries the measurement plan; a shard-2 solo re-run is +in flight to establish whether one occurrence is deterministic or a flake. + +## Honest status against the unit's acceptance + +`000_plan.md` asks for **0 fail, twice consecutively**. This is one run with one +failure, so the bar is not met and this unit is not done. What IS established: + +- both planned fixes work, verified on the platform that had the defects; +- no product source changed; +- the three shards that had defects are now green; +- the remaining failure is scoped to one case and one shard. + +## Evidence + +`/c/ocxwin/logs/fix-{1,2,3,4}.log` on the box (601/632/597/645 KB). The 1.3.14 +baseline logs and the corrected 1.4.0 baseline are at `v140-*.log`; retrieved +copies live in `.tmp/win/` (gitignored). diff --git a/devlog/_plan/260905_windows_suite_stabilization/050_ci_residual_retained_root.md b/devlog/_plan/260905_windows_suite_stabilization/050_ci_residual_retained_root.md new file mode 100644 index 0000000000..ba8949a975 --- /dev/null +++ b/devlog/_plan/260905_windows_suite_stabilization/050_ci_residual_retained_root.md @@ -0,0 +1,272 @@ +# 050 — wp3: the CI residual — a three-child test under a 15 s budget + +Implementation phase. Independent of `020`/`030` (disjoint write set). Found by +dispatching the pushed branch to GitHub Actions (run 33920624827, head +`7153f247a`): windows 1/4, 3/4, 4/4 green; 2/4 = 4627 pass / 1 fail. + +## The failure + +``` +tests\codex-retained-root-serialization.test.ts: +killed 2 dangling processes +(fail) startup and CLI sync-cache cannot write models_cache while another process owns K [15536.76ms] + ^ this test timed out after 15000ms. + +# Unhandled error between tests +215 | holder.release(); +ENOENT: no such file or directory, open '...\ocx-retained-cache-3FtvI4\lock-release' +``` + +Not an assertion failure. Bun's per-test timeout fired at 15 s, then the +`finally` ran `holder.release()` against a sandbox `afterEach` had already +torn down — that ENOENT is a consequence of the timeout, not a second defect. + +It does not reproduce on the self-hosted box: three full shard-2 runs there +passed this file every time. It is a hosted-runner-speed failure. + +## What the test does inside 15 s + +``` +:176 holdCatalogLock → Bun.spawn child #1 (holds K, STAYS ALIVE; its marker waited up to 12 s) +:178 runChild → Bun.spawn child #2 (import src/server/index.ts, probe startServer) — unbounded await +:192 Bun.spawnSync → child #3 (bun run src/cli/index.ts sync-cache) — unbounded +``` + +The holder boots first and remains alive while the two contenders run one after +the other, so the boot costs are additive even though the holder is concurrent. +Two of the three import the server or the CLI — the heaviest module graphs in +the repository. The file's own comment at `:99-102` records "a `bun --eval` +child on a loaded windows-latest shard takes 8-11 s just to boot and reach its +marker". Three boots cannot fit in 15 s; the budget was sized from local timing +(448 ms on macOS), the exact mistake `tests/helpers/test-budget.ts` names. + +Sibling accounting, corrected by the audit: the file has six cases with +per-case budgets `15 / unspecified / 20 / 20 / 20 / 30` s. The unspecified one +(`:220`) inherits the lane-wide `--timeout 60000` from `ci.yml:655`. All +five siblings passed on the same runner at 7.1 / 10.5 / 14.0 / 4.1 / 8.2 s. The +15 s case is the only one under the line, and it is the one that failed. + +## The second defect: dangling children and a teardown race + +"killed 2 dangling processes" and the ENOENT are not noise. They are what a +per-test timeout does to this harness today: + +- `runChild` (`:110-127`) awaits `child.exited` with no deadline, and the + `Bun.spawnSync` at `:192` has none either. When Bun's outer timeout fires, + both contenders can still be running — those are the two dangling processes. +- The `finally` at `:214-217` then calls `holder.release()`, which writes a + file inside `sandbox.root` — but `afterEach` (`:163-170`) has already + `removeTreeWithRetry`'d that root. Hence ENOENT. + +A 45 s budget delays that failure; it does not remove it. The next slow runner +produces the same "killed N dangling processes" with a bigger number in the +timestamp. Both halves are fixed here, not just the budget. + +### Ordering that removes the race + +Cleanup has to be idempotent and owned by ONE place that both the test's +`finally` and `afterEach` can call: + +1. release the holder (write `lock-release`, tolerate ENOENT) +2. kill every child spawned for this sandbox that is still running +3. `await` each child's `exited` — reap BEFORE the directory goes away +4. only then `removeTreeWithRetry(sandbox.root)` + +`afterEach` becomes `async` and awaits step 3. That is the change that turns +"killed 2 dangling processes" into a clean exit under any budget. + +## Why this is a budget, not a hang + +`test-budget.ts` sets two conditions for raising a number: + +1. **The wait is intrinsic to the assertion.** Yes: the assertion IS that a + real startup process and a real CLI process both refuse to write + `models_cache.json` while a third real process holds K. The processes are + the proof; there is nothing to delete. +2. **The ablation still fails.** To be verified at B: remove + `withCatalogWriteSerialization` from the sync-cache path and confirm the + case goes red on `existsSync(cachePath)`. If it does not, the budget hides + a vacuous test and the fix is different. + +`SPAWN_BUDGET_MS` (45 s) is the repository's named budget for "real child +process: PowerShell, a CLI smoke test, an external binary" — this case is three +of those. + +## MODIFY `tests/codex-retained-root-serialization.test.ts` + +Three coordinated changes. + +**(a) Track children on the sandbox, and make cleanup one idempotent function.** + +```ts + interface Sandbox { + … ++ readonly children: Set>; ++ readonly releaseMarkers: Set; + } + ++/** Idempotent: safe from a test's finally AND from afterEach, in either order. */ ++async function teardownSandbox(sandbox: Sandbox): Promise { ++ for (const marker of sandbox.releaseMarkers) { ++ try { writeFileSync(marker, "release"); } catch { /* root may already be gone */ } ++ } ++ for (const child of sandbox.children) { ++ if (child.exitCode === null) child.kill(); ++ } ++ await Promise.all([...sandbox.children].map(child => child.exited)); // reap first ++ sandbox.children.clear(); ++} +``` + +`holdCatalogLock` and `runChild` register every spawn in `sandbox.children`; +`holdCatalogLock` registers its release marker. + +**(b) `afterEach` awaits reaping before deleting the tree.** + +```ts +-afterEach(() => { ++afterEach(async () => { + const identity = resolveEffectiveUserIdentity(); + for (const sandbox of sandboxes.splice(0)) { ++ await teardownSandbox(sandbox); + const database = resolveCodexCatalogSerializationDatabasePath(identity, sandbox.codexHome); + for (const suffix of ["", "-journal", "-wal", "-shm"]) rmSync(`${database}${suffix}`, { force: true }); + removeTreeWithRetry(sandbox.root); + } + }); +``` + +**(c) The budget, with the CI run in the comment.** + +```ts ++import { SPAWN_BUDGET_MS } from "./helpers/test-budget"; + … +-}, 15_000); ++// Three real Bun children (lock holder alive throughout; startup probe and CLI ++// sync-cache in series), two importing the server/CLI graphs at 8-11 s each on ++// windows-latest (:99). 15 s timed out on run 33920624827. ++}, SPAWN_BUDGET_MS); +``` + +The `Bun.spawnSync` at `:192` stays synchronous: it cannot be killed mid-flight, +but with (a)/(b) its worst case is now "slow", not "dangling + ENOENT". Converting +it to an async bounded spawn is a reasonable follow-up and is out of scope here +because it changes how the CLI's exit code is captured. + +### Not changed, deliberately + +- `waitForPath(ready, 12_000)` at `:159` stays: it is the helper's own + diagnostic and sits inside the new budget as its comment requires. +- The sibling cases keep 20/20/30 s. They passed with margin; raising numbers + that are not failing is the "making red go away" the helper warns against. + +## Ablation, made constructible + +The first draft said "bypass `withCatalogWriteSerialization`". The audit is +right that this cannot produce the red: `invalidateCodexModelsCacheWithPermit` +demands a live registered permit (`src/codex/catalog/sync.ts:1949`), so +removing the wrapper makes the write REFUSE, which is the same green. + +The mutation that actually disarms K is one token in +`src/codex/catalog-write-serialization.ts:188`: + +```ts +- database.exec("PRAGMA busy_timeout = 0; BEGIN IMMEDIATE"); ++ database.exec("PRAGMA busy_timeout = 0; BEGIN"); // DEFERRED: no write lock taken +``` + +With a deferred transaction the contender opens without contending, receives a +live permit, and writes `models_cache.json` while the holder still "owns" K. +The behavioural assertion `expect(existsSync(cachePath)).toBe(false)` at `:200` +must go red — not the source-text assertions at `:204-213`, which would stay +green under this mutation and are exactly why they are insufficient as the +gate. + +## Acceptance + +1. Ablation at B, on macOS: the one-token mutation above makes the case fail on + `existsSync(cachePath)`. Reverted before commit; the revert is verified by + `git diff --stat` showing only the test file. +2. macOS: the file passes; `afterEach` reaps before deleting (no ENOENT even if + a case is forced to time out by temporarily setting its budget to 1 ms). +3. CI: re-dispatch on the stacked head; windows 2/4 SUCCESS, this case's + recorded duration under `SPAWN_BUDGET_MS` with margin, and no "killed N + dangling processes" line in the job log. + +## Stack position + +Third commit on `codex/260905-windows-suite-stabilization`, after the two +harness fixes. Independent of them, ordered by discovery. + +--- + +## Second CI round: the budget moved the failure one case down the file + +Run 33923803071 (head `7dc9d622f`): windows 1/4, 3/4, 4/4 green; 2/4 red again, +still 4627 pass / 1 fail, still this file — a different case: + +``` +(pass) startup and CLI sync-cache … owns K [18743.00ms] ← was the failure; now passes +(pass) native restore … owns K [5726.56ms] +killed 1 dangling process +(fail) POST /api/sync … newer convergence catalog [20140.28ms] ← timed out at 20 s +(pass) POST /api/sync … newer retained catalog [11876.76ms] +(pass) a persisted runtime selection … [2289.08ms] +(pass) two processes at the post-approval seam … [5623.21ms] +``` + +The first case ran 18.7 s — it would have died under the old 15 s and lived +under 45 s, so the fix did what it claimed. The convergence case is the same +shape (a `Bun.spawn` of the management API, `:342`, plus a publisher child, +`:288`) with a 20 s budget that this runner exceeded by 140 ms. + +Also notable: the shard as a whole was ~2× slower than the previous run (18.7 s +vs 15.5 s on the first case with the SAME fixture), so the hosted runner's speed +varies run to run and the margins in this file are all thin. + +## What I got wrong in the first round + +I budgeted the ONE case that had failed. The audit flagged "raising one case to +45 s while its siblings stay at 20-30 s" and I answered that workload differs per +case. That was true and beside the point: every case in this file boots the same +kind of child on the same runner, and the sibling budgets were sized the same +way the 15 s one was. Fixing the case instead of the class is how the failure +moved rather than stopped. + +## Amendment: budget the class, and bound the children + +### MODIFY `tests/codex-retained-root-serialization.test.ts` — all four +explicit budgets become `SPAWN_BUDGET_MS` + +| line | case | today | after | +|---|---|---|---| +| `:255` | startup + CLI | `SPAWN_BUDGET_MS` (done) | — | +| `:376` | POST /api/sync ×2 (`for` loop) | 20 s | `SPAWN_BUDGET_MS` | +| `:460` | runtime selection moved | 20 s | `SPAWN_BUDGET_MS` | +| `:639` | post-approval seam (3 children) | 30 s | `SPAWN_BUDGET_MS` | + +The unspecified case at `:220` (native restore) inherits the lane's 60 s and +is left alone. + +Every one of these spawns at least one real Bun child that imports the +server, the CLI, or the convergence graph. Under `test-budget.ts` they are the +same category — "real child process" — and the budget name says so. The +ablation from the first round (BEGIN IMMEDIATE → BEGIN) already establishes +that K is real for this file; the sibling cases assert on the same lock. + +### MODIFY — register every spawn with the sandbox + +The teardown from the first round only reaps children that were added to +`sandbox.children`. `runChild` and `holdCatalogLock` register; the four +inline `Bun.spawn` calls at `:342`, `:421`, `:489`, `:551` do not. "killed 1 +dangling process" in this run is one of them. Each gets a +`sandbox.children.add(child)` immediately after the spawn, so a timeout in any +case reaps cleanly. + +### Acceptance, amended + +1. macOS: file passes, `typecheck` clean. +2. Forced 1 ms budget on the convergence case: fails cleanly, no dangling + process, no unhandled ENOENT. +3. CI re-dispatch: windows 2/4 SUCCESS with **no** "killed N dangling processes" + line in the log, and every case in this file under its budget with margin. diff --git a/tests/codex-integration/codex-retained-root-serialization.test.ts b/tests/codex-integration/codex-retained-root-serialization.test.ts index b0c56bffbf..4f15c7852d 100644 --- a/tests/codex-integration/codex-retained-root-serialization.test.ts +++ b/tests/codex-integration/codex-retained-root-serialization.test.ts @@ -19,6 +19,7 @@ import { import { claimOwnedServiceHome, withOwnedServiceHomePreload } from "../helpers/owned-service-home"; import { removeTreeWithRetry } from "../helpers/remove-tree"; import { repoRoot as resolveRepoRoot } from "../helpers/repo-root"; +import { SPAWN_BUDGET_MS } from "../helpers/test-budget"; const repoRoot = resolveRepoRoot(); const sandboxes: Sandbox[] = []; @@ -30,6 +31,10 @@ interface Sandbox { readonly env: Record; readonly serviceManagerEnv: Record; readonly preloadPath?: string; + /** Every child spawned against this sandbox, so teardown can reap before deleting the root. */ + readonly children: Set>; + /** Release markers a lock holder polls for; written (tolerantly) on teardown. */ + readonly releaseMarkers: Set; } function nativeEntry(slug: string, visibility = "list"): Record { @@ -88,15 +93,57 @@ function makeSandbox(prefix: string): Sandbox { }, serviceManagerEnv: serviceHome.env, preloadPath: serviceHome.preloadPath, + children: new Set(), + releaseMarkers: new Set(), }; sandboxes.push(sandbox); return sandbox; } +/** + * Idempotent teardown, safe from a test's `finally` AND from `afterEach` in either + * order. Order matters: release holders, kill anything still running, then AWAIT + * every exit so no child holds a handle inside the sandbox when the root is removed. + * Run 33920624827 (windows 2/4) showed the alternative: a per-test timeout left two + * children dangling and the `finally` then wrote a release marker into a root + * `afterEach` had already deleted (ENOENT). + */ +async function teardownSandbox(sandbox: Sandbox): Promise { + for (const marker of sandbox.releaseMarkers) { + try { writeFileSync(marker, "release"); } catch { /* root may already be gone */ } + } + for (const child of sandbox.children) { + if (child.exitCode === null) child.kill(); + } + await Promise.all([...sandbox.children].map(child => child.exited)); + sandbox.children.clear(); +} + function sandboxChildEnv(sandbox: Sandbox): Record { return { ...sandbox.env, ...sandbox.serviceManagerEnv }; } +/** + * Wait for a child to reach its barrier, failing fast with its output if it exits + * first. The exit branch is a REJECTING promise, so while the race is pending an + * early exit fails the test with the child's output. The subtlety is what happens + * AFTER the barrier wins: that promise stays pending, and if a per-test timeout + * later fires, teardown kills the child (exit 143) and the promise rejects with + * nobody awaiting it — Bun reports it as an "unhandled error between tests" on + * top of the timeout that already explained the failure (run 33923803071). The + * no-op catch attached up front marks that late rejection handled without + * changing what the race sees. + */ +async function raceBarrier(child: ReturnType, barrier: Promise): Promise { + const exitedEarly = child.exited.then(async exitCode => { + const stdout = await new Response(child.stdout).text(); + const stderr = await new Response(child.stderr).text(); + throw new Error(`sync exited before provider barrier (${exitCode})\nstdout=${stdout}\nstderr=${stderr}`); + }); + exitedEarly.catch(() => undefined); + await Promise.race([barrier, exitedEarly]); +} + // A `bun --eval` child on a loaded windows-latest shard takes 8-11 s just to boot and // reach its marker (runs 33590540220 and 33605898170), so a 10 s wait was the coin flip, // not the child. Every caller passes a deadline that sits inside its own test budget so @@ -119,6 +166,7 @@ async function runChild( stdout: "pipe", stderr: "pipe", }); + sandbox.children.add(child); const [exitCode, stdout, stderr] = await Promise.all([ child.exited, new Response(child.stdout).text(), @@ -150,8 +198,13 @@ async function holdCatalogLock(sandbox: Sandbox): Promise<{ stdout: "pipe", stderr: "pipe", }); + sandbox.children.add(child); + sandbox.releaseMarkers.add(release); await waitForPath(ready, 12_000); - return { release: () => writeFileSync(release, "release"), child }; + return { + release: () => { try { writeFileSync(release, "release"); } catch { /* teardown may have released already */ } }, + child, + }; } function seedCatalog(sandbox: Sandbox, bytes = catalogBytes()): string { @@ -161,9 +214,10 @@ function seedCatalog(sandbox: Sandbox, bytes = catalogBytes()): string { return path; } -afterEach(() => { +afterEach(async () => { const identity = resolveEffectiveUserIdentity(); for (const sandbox of sandboxes.splice(0)) { + await teardownSandbox(sandbox); const database = resolveCodexCatalogSerializationDatabasePath(identity, sandbox.codexHome); for (const suffix of ["", "-journal", "-wal", "-shm"]) rmSync(`${database}${suffix}`, { force: true }); removeTreeWithRetry(sandbox.root); @@ -216,7 +270,11 @@ test("startup and CLI sync-cache cannot write models_cache while another process holder.release(); expect(await holder.child.exited).toBe(0); } -}, 15_000); +// Three real Bun children (the lock holder alive throughout; the startup probe and +// the CLI sync-cache in series), two of them importing the server/CLI graphs at +// 8-11 s each on windows-latest (see waitForPath). 15 s timed out on CI run +// 33920624827; the local timing (~450 ms) is not what this number is for. +}, SPAWN_BUDGET_MS); test("native restore cannot read-transform-write the catalog while another process owns K", async () => { const sandbox = makeSandbox("ocx-retained-restore-"); @@ -310,15 +368,9 @@ for (const publisher of ["convergence", "retained"] as const) { const response = await handleManagementAPI(req, new URL(req.url), config); console.log(JSON.stringify({ status: response.status, body: await response.json() })); `], sandbox.preloadPath)], { cwd: repoRoot, env: sandboxChildEnv(sandbox), stdout: "pipe", stderr: "pipe" }); + sandbox.children.add(sync); - await Promise.race([ - waitForPath(requested, 16_000), - sync.exited.then(async exitCode => { - const stdout = await new Response(sync.stdout).text(); - const stderr = await new Response(sync.stderr).text(); - throw new Error(`sync exited before provider barrier (${exitCode})\nstdout=${stdout}\nstderr=${stderr}`); - }), - ]); + await raceBarrier(sync, waitForPath(requested, 16_000)); const published = await runPublisher(sandbox, publisher, config); if (published.exitCode !== 0) { throw new Error(`${publisher} publisher failed\nstdout=${published.stdout}\nstderr=${published.stderr}`); @@ -337,7 +389,7 @@ for (const publisher of ["convergence", "retained"] as const) { } finally { provider.stop(true); } - }, 20_000); + }, SPAWN_BUDGET_MS); } /** @@ -393,15 +445,9 @@ test("a persisted runtime selection moved by another process during the await bl const { syncCatalogModels } = await import("./src/codex/catalog/sync.ts"); console.log(JSON.stringify(await syncCatalogModels(config))); `], sandbox.preloadPath)], { cwd: repoRoot, env: sandboxChildEnv(sandbox), stdout: "pipe", stderr: "pipe" }); + sandbox.children.add(sync); - await Promise.race([ - waitForPath(requested, 16_000), - sync.exited.then(async exitCode => { - const stdout = await new Response(sync.stdout).text(); - const stderr = await new Response(sync.stderr).text(); - throw new Error(`sync exited before provider barrier (${exitCode})\nstdout=${stdout}\nstderr=${stderr}`); - }), - ]); + await raceBarrier(sync, waitForPath(requested, 16_000)); // Another process selects a different Codex runtime. No catalog byte changes. writeFileSync(runtimeStatePath, `${JSON.stringify({ @@ -421,7 +467,7 @@ test("a persisted runtime selection moved by another process during the await bl expect({ exitCode, stderr }).toMatchObject({ exitCode: 0 }); expect(JSON.parse(stdout.trim())).toMatchObject({ catalogWritten: false }); expect(readFileSync(catalogPath, "utf8")).toBe(initial); -}, 20_000); +}, SPAWN_BUDGET_MS); /** * The post-approval seam, raced by two real processes through a real route. @@ -454,6 +500,7 @@ test("two processes at the post-approval management seam serialize instead of in const { withConfigMutationLockSync } = await import("./src/config.ts"); withConfigMutationLockSync(() => undefined); `], { cwd: repoRoot, env: sandbox.env, stdout: "pipe", stderr: "pipe" }); + sandbox.children.add(warm); expect(await warm.exited).toBe(0); const routeScript = (marker: string) => ` @@ -516,6 +563,7 @@ test("two processes at the post-approval management seam serialize instead of in [process.execPath, ...withOwnedServiceHomePreload(["--eval", routeScript(marker)], sandbox.preloadPath)], { cwd: repoRoot, env: sandboxChildEnv(sandbox), stdout: "pipe", stderr: "pipe" }, )); + for (const child of children) sandbox.children.add(child); results = await Promise.all(children.map(async child => { const [exitCode, stdout, stderr] = await Promise.all([ @@ -600,4 +648,4 @@ test("two processes at the post-approval management seam serialize instead of in const fromA = slugs.some(s => s.includes("seam-model-a")); const fromB = slugs.some(s => s.includes("seam-model-b")); expect(fromA && fromB).toBe(false); -}, 30_000); +}, SPAWN_BUDGET_MS); diff --git a/tests/codex-integration/multi-agent-keep-native-v1.test.ts b/tests/codex-integration/multi-agent-keep-native-v1.test.ts index 33c021f68f..e7ae3308b3 100644 --- a/tests/codex-integration/multi-agent-keep-native-v1.test.ts +++ b/tests/codex-integration/multi-agent-keep-native-v1.test.ts @@ -102,8 +102,18 @@ function isolateHomes(): void { * these tests assert the OS launcher's argument grammar instead of the state * transition they exist to check. * - * This THROWS on anything else rather than falling back, so a bypassed or - * malformed invocation fails the test instead of silently matching. + * SCOPE: this extracts the SEMANTIC ARGUMENTS. It deliberately does not check + * WHICH executable is being launched — it never sees `file`, and it accepts any + * `.cmd`/`.bat` target, so `evil.cmd` parses as readily as `codex.cmd`. + * Executable identity belongs to the launcher contract, which is pinned + * independently by `tests/codex-v2-gate.test.ts` (`codexFeaturesInvocation` + * resolving `codex` on POSIX, `.cmd` and `.exe` on win32) and + * `tests/win-exec.test.ts` (PATH×PATHEXT resolution and escaping). Duplicating + * that here would couple these state tests to resolution behaviour again, which + * is the defect this helper exists to remove. + * + * Within that scope it THROWS rather than falling back, so a malformed argv or + * an unrecognized shape fails the test instead of silently matching. */ function featureActionOf(args: readonly string[]): string { const ACTION = /^(?:enable|disable)$/; @@ -219,7 +229,7 @@ describe("keep-native-v1 restamp path", () => { }); describe("ocx v2 keep-native-v1", () => { - test("featureActionOf parses both launcher shapes and rejects everything else", () => { + test("featureActionOf parses both launcher shapes and rejects malformed argv", () => { // The exact strings commandInvocation emits, captured from a real run against // three target shapes: plain path, a path containing a space, and a // node_modules/.bin shim (double-escaped). @@ -235,7 +245,9 @@ describe("ocx v2 keep-native-v1", () => { String.raw`"C:\p\node_modules\.bin\codex.cmd ^^^"features^^^" ^^^"enable^^^" ^^^"multi_agent_v2^^^""`])) .toBe("features enable multi_agent_v2"); - // A bypassed target must not match merely because the phrase is present. + // A non-batch target must not match merely because the phrase is present. + // (A .cmd target that is not codex DOES parse — see the helper's SCOPE note: + // executable identity is the launcher contract's job, not this helper's.) expect(() => featureActionOf(["/d", "/s", "/c", String.raw`"echo ^"features^" ^"disable^" ^"multi_agent_v2^""`])).toThrow(); expect(() => featureActionOf(["features", "disable"])).toThrow();