diff --git a/devlog/_plan/260905_windows_suite_stabilization/080_run_variance_residuals.md b/devlog/_plan/260905_windows_suite_stabilization/080_run_variance_residuals.md new file mode 100644 index 0000000000..a6c6f22ee1 --- /dev/null +++ b/devlog/_plan/260905_windows_suite_stabilization/080_run_variance_residuals.md @@ -0,0 +1,267 @@ +# 080 — wp5 (research): two more hosted-runner timing residuals surface on the 5th run + +Run 33930757649 (head `fd786be83`, PR #3555): windows 1/4 and 3/4 SUCCESS. +**The change under test passed** — `anthropic-quorum-cache` 7/7 on 2/4. But 2/4 +and 4/4 each failed on ONE case that had passed on every one of the four +previous runs of this stack: + +| shard | case | wall | what timed out | +|---|---|---|---| +| 2/4 | `codex-write-lock > two real processes contend for one lock > one OS user and one home take ONE lock, case 0` | 10.67 s | `waitFor(holdMarker)` — default 10 s (`codex-write-lock.test.ts:314`) waiting for a spawned holder child to write its marker | +| 4/4 | `codex-composed-acceptance > B-reduced: a held local provider cannot commit after the HTTP route persists OFF` | 57.7 s | a `fx.request(..., SERVER_BUDGET_MS)` (30 s) `AbortSignal.timeout` — `TimeoutError: The operation timed out` | + +## Same class, already named + +Both are `test-budget-sized-from-local-timing` (corpus, added this unit) with a +twist: neither is a per-test budget. They are **internal waits** whose bound is +shorter than a Windows child boot or a Windows server round-trip under load. + +- `waitFor(holdMarker)` has the same shape as the 8-11 s child boot that + `retained-root-serialization` documented at its `:99` comment. The file's own + comment at `:430` already knows this ("process boot took >4 s on + windows-latest in run 33603770447") and raised `holdMs` to 20 s for it — but + left `waitFor`'s default at 10 s. On this run the holder took longer than + that to boot. +- The composed-acceptance case already carries one Windows fix in its + comments (`idleTimeout: 255` because Bun's 10 s default cancelled the held + request on a loaded shard). This time the client-side `SERVER_BUDGET_MS` + abort fired first. Its siblings on the same run took 47.9 s and 57.8 s and + passed, so 30 s for one round-trip is inside the runner's noise band. + +## What this run says about the runner + +Five dispatches of this stack on `windows-latest`, same job class: + +| run | 1/4 | 2/4 | 3/4 | 4/4 | +|---|---|---|---|---| +| 33920624827 | ✓ | K-owner 15 s timeout | ✓ | ✓ | +| 33923803071 | ✓ | K-owner 20 s timeout (next case) | ✓ | ✓ | +| 33926041666 | ✓ | ✓ | ✓ | ✓ | +| 33928082123 | ✓ | quorum-cache ×3 (dev drift) | ✓ | ✓ | +| 33930757649 | ✓ | write-lock `waitFor` 10 s | ✓ | composed-acceptance 30 s abort | + +Every red cell is a bound that a slower-than-usual run crossed; no red cell +is an assertion about behaviour. The runner is not getting worse — the +quorum-cache file (fixed here) and the K-owner file (fixed in #3550) are both +green on this run — it is that each run samples a different slow child, and +the suite has more sub-10 s waits than the four we have fixed. + +## Honest reading of the acceptance bar + +`c-1` asks for 0 fail twice consecutively. Run 3 was the first; run 4 broke on +dev drift (fixed, #3555); run 5 broke on two more waits of the same class. +"Twice consecutively" is not going to be reached by fixing the residual each +run exposes and re-dispatching, because each 25-minute run samples one or two +new ones out of a population we have not enumerated. + +The faster path is to enumerate the population once: grep the suite for every +internal wait shorter than the hosted-runner floor and budget them as a +class, the way `retained-root-serialization` was fixed in `050` after +budgeting one case moved the failure. That is the next work-phase. + +## Next work-phase (wp5) + +1. Inventory: every `waitFor`/`waitForPath`/`AbortSignal.timeout`/ + `Bun.sleep`-poll deadline under `tests/` with a literal below 30 s that + gates on a spawned child or a real server round-trip. `rg` for the + patterns, then read each hit for what it waits on. +2. Classify each: intrinsic child/server wait → `SPAWN_BUDGET_MS` / + `SERVER_BUDGET_MS` / `isolationBudgetMs()`; pure-logic wait → leave alone. +3. One PR (stack 5) with the class change and a comment per site naming the + run that motivated it, then two consecutive dispatches. + +Fixing only `waitFor`'s default and the one `SERVER_BUDGET_MS` call would be +the same mistake `050` recorded: it moves the failure to the next site. + +--- + +## Inventory (wp5 step 1, done) + +`rg` over `tests/` for literal deadlines that gate on something external — +`waitFor*(…, N)`, `deadline = Date.now() + N`, `AbortSignal.timeout(N)`, +helper defaults `timeoutMs = N` — excluding sites already on a named budget. +58 hits. Classified by what the wait actually gates on, after reading each: + +### A. Gates on a spawned Bun child reaching a marker — MUST budget + +These are the `retained-root` shape: a real `bun --eval` boot that costs 8-19 s +on `windows-latest`, behind a literal under 20 s. + +| site | literal | gates on | +|---|---|---| +| `codex-integration/codex-write-lock.test.ts:314` | `waitFor` default 10 s | holder child writes marker (**failed run 5**) | +| `codex-integration/codex-history-lock.test.ts:59` | `waitForPath` default 10 s | child marker | +| `codex-integration/native-profile-startup.test.ts:229` | `waitForPath` default 10 s | child marker | +| `codex-integration/native-profile-startup.test.ts:243` | `waitForPort` default 18 s | child binds a port | +| `codex-integration/native-profile-manager.test.ts:199` | 12 s | child ready marker | +| `codex-integration/codex-history-worker.test.ts:346` | 10 s | worker child | +| `codex-integration/codex-inject-write-lock.test.ts:343` | 10 s | child marker | +| `oauth/oauth-refresh-lock-multiprocess.test.ts:95` | 15 s | child | +| `codex-integration/codex-retained-root-serialization.test.ts:203,373,450` | 12 s / 16 s | child marker — the file `050` budgeted at the CASE level; its internal waits are still literal | +| `codex-integration/codex-retained-root-serialization.test.ts:514` | 8 s | two children | + +### B. Gates on a real server / HTTP round-trip — MUST budget + +| site | literal | gates on | +|---|---|---| +| `codex-integration/codex-composed-acceptance.test.ts:494,503` | `SERVER_BUDGET_MS` 30 s | already named, still lost on run 5 at 57 s wall; the CASE budget is 150 s on CI, so the per-request bound is the one that fires. See note. | +| `server/server-background-lifecycle.test.ts:221,243` | 5 s / 10 s | live server + storage worker | +| `storage/storage-policy-job-responsive.test.ts:140` | 10 s | server under a blocked worker | +| `storage/storage-worker-lifecycle.test.ts:70,80`, `storage-worker-teardown-isolate.test.ts:95` | 10-20 s | Worker thread lifecycle (Windows OS-thread join is the slow half; `worker-lifecycle.ts` already keeps a 1.5 s settle) | + +### C. Deliberately short — LEAVE ALONE + +Bounds that exist to prove something is fast or absent; raising them would +weaken the assertion: + +- `AbortSignal.timeout(500/800)` on `/healthz` polls (`composed-acceptance:251`, + `cli-start-journal-order:135`, `ocx-launcher-runtime:57`, `shutdown-launcher:63`, + `local-management-direct-transport` ×4) — each is inside its own retry loop + whose OUTER bound is already a budget; the 500 ms is per-probe. +- `issue-914-transport-attribution:163` — `fetch("http://127.0.0.1:1/")` is + asserting a refused connection, 5 s is generous. +- `terminal-guard:235` (25 ms), `web-search-progress-stream:15` (100 ms), + `translator-budget:17` (2 s) — in-process logic, no child, no socket. +- `windows-secret-acl:1680,1714,1831` (5 s) — stubbed runners, in-process. +- `deepseek-*`, `responses-reasoning-summary-passthrough`, `cli-account:397` + (`AbortSignal.timeout(5_000)` on adapter calls against an in-process mock + server) — no child, loopback only, 5 s is not the floor these hit. + +### D. Ambiguous — read at B, decide per site + +`oauth-status-privacy:365,427`, `oauth-manual-code:226`, `codex-account-store:1302`, +`codex-shim:1704`, `codex-prompt-*:35,74`, `native-main-claim:202`, +`native-profile-drain-server:189`, `server-live:1221,1309`, +`storage-policy-config-race:135`, `cursor-http1-transport:289`, +`package-tree-integrity:192`, `user-cost-overlay-*` — 2-5 s deadlines whose +subject I have not read yet. Rule for B: if the loop body spawns or awaits a +real listener, it is A/B; if it polls in-process state, it is C. + +### Note on the composed-acceptance case + +Its per-request bound is already `SERVER_BUDGET_MS` and it still lost. The +siblings on the same run took 47.9 s and 57.8 s and PASSED, so this case's +total (57.7 s) is inside the file's normal band; what fired was one +`fx.request` at the 30 s mark while the server was mid-startup under four +shards. The honest fix is not "raise 30 to 60" but to give the held-request +pattern its own named bound: the request is deliberately held open by the +fixture until `release()`, so its ceiling is "a startup plus a held gather", +not "a request". That is a design note for B, not a number. + +## Plan for B (wp5) + +One PR. For every A/B site: replace the literal with the matching named budget +(`SPAWN_BUDGET_MS` for a child boot, `SERVER_BUDGET_MS` for a round-trip, +`isolationBudgetMs()` where the file already scales by lane), and leave a +one-line comment naming the run that motivated the class (33930757649). For +each helper with a default (`waitFor`, `waitForPath`, `waitForPort`), change +the DEFAULT so every caller inherits it. C sites untouched. D sites resolved +by reading, listed in the commit message either way. + +Verifier: macOS focused run of every touched file, `typecheck`, then two +consecutive CI dispatches. The ablation rule from `test-budget.ts` applies per +file: at least one case per touched file is driven red by disabling the thing +it waits for, so a budget cannot hide a vacuous wait. + +--- + +## Review of 3b431b413: FAIL (6 blockers) — the composition invariant + +The implementation reviewer found the shape of the first attempt wrong, and the +argument is structural, not a nit. + +`watchdogMs()` returns **45 s on Windows CI**. I applied it to INTERNAL waits +inside tests whose OWN budgets are 15, 20 or 30 s. So on the platform this fix +targets, the internal deadline is now LONGER than the test — Bun's per-test +timeout fires first, and the wait's diagnostic ("timed out waiting for +``") never prints. That is the exact inversion `test-budget.ts:64` +warns about: "keep these at least a few times under the surrounding budget". +It also destroys the one thing the diagnostic was for — naming WHICH child was +slow — and replaces it with a bare timeout, which is where this unit started. + +| file | internal wait now | enclosing budget | result on Windows CI | +|---|---|---|---| +| `native-profile-manager` | 45 s | **15 s** ×4 cases | bare timeout, no diagnostic | +| `codex-history-lock` | 45 s | 30 s | bare timeout | +| `codex-write-lock` | 45 s | 30 s ×4 | bare timeout | +| `oauth-refresh-lock-multiprocess` | 45 s | 30 s | bare timeout | +| `codex-history-worker` | 45 s | 30 s | bare timeout | +| `codex-retained-root`, `codex-inject-write-lock` | 45 s | 45 s | tie — diagnostic races Bun | + +### Corrected shape + +Two knobs, moved together, the way `test-budget.ts` and `ci-watchdog.ts` say: + +1. **Internal waits that gate on a spawned child or a live server use + `INTERNAL_DEADLINE_MS` (15 s)** — the repository's named constant for + exactly this ("a deadline inside a test, for an await that would otherwise + hang forever"). It is already what `windows-tray`, `cli-models` and + `oauth-store-multi` use. Not `watchdogMs`, which is for the OUTER + watchdog and is sized to sit under the lane's 60 s. +2. **Every enclosing case whose body spawns a child or binds a server gets + `SPAWN_BUDGET_MS` (45 s) or `SERVER_BUDGET_MS` (30 s)** — a few times the + internal deadline, as the invariant requires, and under the 60 s lane ceiling. + +On the failing runs the child took 8-19 s: 15 s internal still loses on the +slow tail. That is acceptable ONLY because the diagnostic then fires and names +the marker, which is the signal we want — and it is why (2) matters: the case +must outlive the diagnostic so the diagnostic is what gets reported. If 15 s +proves too tight in practice, the right move is to raise `INTERNAL_DEADLINE_MS` +once, in the helper, with the run number — not to reach for `watchdogMs`. + +### The other five blockers, dispositions + +- **b2** `retained-root:515` (8 s two-child barrier) and `:555` (20 s child + deadline) were in my own class-A inventory and not changed. Change both. +- **b3** Ten more A/B sites the reviewer's re-run of the grep found that mine + missed (`codex-shim:1704`, `codex-prompt-route:73`, `codex-prompt-text-probe:34`, + `native-profile-drain-server:189`, `server-live:1221,1309`, + `helpers/storage-policy-api:61`, `storage-mutation-race:127`, + `api-storage-policy-put-race:55`, `helpers/windows-power-shell-fixture:22`). + My inventory regex excluded helper files and missed `deadline = Date.now() + + N` where N was a variable. Read each; budget the ones that gate externally. +- **b4** `storage-policy-job-responsive:143` — the loop falls through on + expiry with no throw and no final assertion, so it is vacuous today + regardless of the bound. Add `expect(status).toBe("idle")` after the loop. + This is a real find independent of Windows. +- **b5** `composed-acceptance` — `SERVER_BUDGET_MS * 2` was arithmetic, and my + "two serialized legs" model is wrong: `fx.start()` completes BEFORE the held + request begins, and the held request and the OFF round-trip overlap. Name + it: `HELD_REQUEST_BUDGET_MS = SERVER_BUDGET_MS` with a comment that the bound + covers "a gather held open until `release()` plus one overlapping mutation", + and derive nothing from `* 2`. Since the case budget is 150 s on CI and the + request was aborted at 30 s while the case sat at 57 s total, the real + question is whether 30 s is enough for a gather under startup load; the + siblings say yes at 47-58 s total. Keep 30 s named, do not double it. +- **b6** Ablation evidence — blocked by another session holding the user + test lock at the time; must be run before this lands. Two files selected: + `codex-history-lock` (disable the holder's `writeFileSync(ready)` → the + helper's "timed out waiting for" must print, not Bun's timeout) and + `storage-policy-job-responsive` (after b4, block the job → the new + `expect` must fail). + +### Reading of what I did wrong + +I reached for the helper whose name matched ("watchdog") without reading the +two paragraphs above it that say what it is for and what it must stay under. +The reviewer read them. Same failure as `007` in a smaller key: pattern-matched +the fix instead of measuring it against the constraint. + +### Blocker-3 sites, read and dispositioned + +| site | what the loop gates on | disposition | +|---|---|---| +| `codex-shim:1704` | spawned holder child's ready marker | **A → INTERNAL_DEADLINE_MS** | +| `codex-prompt-route:73` | `waitUntil` used only for spawned probe child pid/start markers (5 callers) | **A → INTERNAL_DEADLINE_MS** | +| `codex-prompt-text-probe:34` | same shape, child pid marker / child exit | **A → INTERNAL_DEADLINE_MS** | +| `helpers/storage-policy-api:61` `waitForJobIdle` | live server, worker-backed job settling | **B → INTERNAL_DEADLINE_MS** (helper default; every caller inherits) | +| `storage-mutation-race:127` `waitForPolicyJob` | same as above, local copy | **B → INTERNAL_DEADLINE_MS** | +| `native-profile-drain-server:189` | in-process `Bun.serve` counters (`upstreamCloses`), no child | **C — leave** | +| `server-live:1221` | in-process WS frame arrival on a loopback server already up | **C — leave** (2 s asserts latency of an established socket) | +| `server-live:1309` | frame-log file written by the same process | **C — leave** | +| `api-storage-policy-put-race:55` | `sawRunning` peek loop — the assertion is that the job is STILL running during the edit window; a longer bound would wait for it to finish and invert the test | **C — leave, deliberately** | +| `helpers/windows-power-shell-fixture:22` `probeWindowsPowerShellFixture` | spawns a real PowerShell — but it is a PREFLIGHT whose `ok:false` result skips the dependent cases with a reason; 5 s is the "is PowerShell usable at all" bound and lengthening it only delays a skip | **C — leave** | + +Five budgeted, five left with a reason each. The inventory regex missed +`tests/helpers/*.ts` and `deadline = Date.now() + `; both are +now in the grep. diff --git a/tests/codex-integration/codex-composed-acceptance.test.ts b/tests/codex-integration/codex-composed-acceptance.test.ts index 4dac153f14..20d4943912 100644 --- a/tests/codex-integration/codex-composed-acceptance.test.ts +++ b/tests/codex-integration/codex-composed-acceptance.test.ts @@ -41,9 +41,19 @@ import { resolveEffectiveUserIdentity, } from "../../src/codex/user-identity"; import { claimOwnedServiceHome, withOwnedServiceHomePreload } from "../helpers/owned-service-home"; -import { SERVER_BUDGET_MS } from "../helpers/test-budget"; +import { INTERNAL_DEADLINE_MS, SERVER_BUDGET_MS } from "../helpers/test-budget"; import { repoRoot as resolveRepoRoot } from "../helpers/repo-root"; +/** + * Bound for a request the fixture deliberately HOLDS open: the provider's /models response + * blocks until the test calls release(), so this request's ceiling is "a gather held + * across one overlapping mutation", not a single round-trip. On run 33930757649 the plain + * SERVER_BUDGET_MS abort fired at 30 s while the case sat at 57.7 s total and its siblings + * passed at 47.9 s and 57.8 s — the case was inside its band, the per-request bound was + * not. Named rather than multiplied so the next reader sees WHAT is being bounded. + */ +const HELD_REQUEST_BUDGET_MS = SERVER_BUDGET_MS + INTERNAL_DEADLINE_MS; + const repoRoot = resolveRepoRoot(); const cliPath = resolve(repoRoot, "src/cli/index.ts"); const lockChildPath = resolve(repoRoot, "tests/helpers/codex-write-lock-child.ts"); @@ -490,8 +500,8 @@ describe("WP13 composed toggle acceptance", () => { } }, defaultProvider: "fixture", clientIntegrations: { codex: true } }); hold = true; // This request is intentionally held open while a second real HTTP - // mutation crosses the Windows process-backed identity path. - const stale = fx.request(server.runtime, "/api/sync", { method: "POST" }, SERVER_BUDGET_MS); + // mutation crosses the Windows process-backed identity path; see HELD_REQUEST_BUDGET_MS. + const stale = fx.request(server.runtime, "/api/sync", { method: "POST" }, HELD_REQUEST_BUDGET_MS); await Promise.race([ enteredGather, stale.then(result => Promise.reject(new Error( diff --git a/tests/codex-integration/codex-history-lock.test.ts b/tests/codex-integration/codex-history-lock.test.ts index b752b60e53..fb72d9c96e 100644 --- a/tests/codex-integration/codex-history-lock.test.ts +++ b/tests/codex-integration/codex-history-lock.test.ts @@ -11,6 +11,7 @@ import { } from "../../src/codex/history-lock"; import { removeTreeWithRetry } from "../helpers/remove-tree"; import { repoRoot as resolveRepoRoot } from "../helpers/repo-root"; +import { INTERNAL_DEADLINE_MS, SPAWN_BUDGET_MS } from "../helpers/test-budget"; const repoRoot = resolveRepoRoot(); const sandboxes: string[] = []; @@ -56,7 +57,9 @@ afterEach(() => { for (const root of sandboxes.splice(0)) removeTreeWithRetry(root); }); -async function waitForPath(path: string, timeoutMs = 10_000): Promise { +// Same shape as codex-write-lock: gates on a spawned child reaching its marker, which +// costs 8-19 s on windows-latest (run 33930757649). Local stays at 10 s. +async function waitForPath(path: string, timeoutMs = INTERNAL_DEADLINE_MS): Promise { const deadline = Date.now() + timeoutMs; while (!existsSync(path)) { if (Date.now() > deadline) throw new Error(`timed out waiting for ${path}`); @@ -107,7 +110,7 @@ test("H excludes a second process across the whole history unit", async () => { // Once the holder is gone the lock is available again. const after = withHistoryWriteSerialization(sandbox.codexHome, sandbox.stateDb, () => "ok"); expect(after).toEqual({ kind: "completed", value: "ok" }); -}, 30_000); +}, SPAWN_BUDGET_MS); test("a permit is refused once its acquisition released, and for a foreign state database", () => { const sandbox = makeSandbox("ocx-history-permit-"); diff --git a/tests/codex-integration/codex-history-worker.test.ts b/tests/codex-integration/codex-history-worker.test.ts index 454efa72e5..90a0a04caf 100644 --- a/tests/codex-integration/codex-history-worker.test.ts +++ b/tests/codex-integration/codex-history-worker.test.ts @@ -13,6 +13,7 @@ import { } from "../../src/codex/history-worker"; import { removeTreeWithRetry } from "../helpers/remove-tree"; import { repoRoot as resolveRepoRoot } from "../helpers/repo-root"; +import { INTERNAL_DEADLINE_MS, SPAWN_BUDGET_MS } from "../helpers/test-budget"; // A held write lock otherwise costs the full production 5s busy timeout per // attempt, tripping bun's 5s default per-test timeout. @@ -343,7 +344,8 @@ test("a second holder of H makes the unit report blocked rather than wait", asyn `], { cwd: repoRoot, env: fixture.env, stdout: "pipe", stderr: "pipe" }); try { - const deadline = Date.now() + 10_000; + // The holder is a spawned child; 8-19 s to boot on windows-latest (run 33930757649). + const deadline = Date.now() + INTERNAL_DEADLINE_MS; while (!existsSync(ready)) { if (Date.now() > deadline) throw new Error("holder never acquired H"); await Bun.sleep(5); @@ -366,7 +368,7 @@ test("a second holder of H makes the unit report blocked rather than wait", asyn writeFileSync(release, "release"); expect(await holder.exited).toBe(0); } -}, 30_000); +}, SPAWN_BUDGET_MS); /** * The reason the parent can tell a false "app holds the DB" from a real one: diff --git a/tests/codex-integration/codex-inject-write-lock.test.ts b/tests/codex-integration/codex-inject-write-lock.test.ts index 824e75f21f..5633a8dced 100644 --- a/tests/codex-integration/codex-inject-write-lock.test.ts +++ b/tests/codex-integration/codex-inject-write-lock.test.ts @@ -24,6 +24,7 @@ import { import { SPAWN_BUDGET_MS } from "../helpers/test-budget"; import { removeTreeWithRetry } from "../helpers/remove-tree"; import { repoRoot as resolveRepoRoot } from "../helpers/repo-root"; +import { INTERNAL_DEADLINE_MS } from "../helpers/test-budget"; const repoRoot = resolveRepoRoot(); const CHILD = join(repoRoot, "tests", "helpers", "codex-inject-race-child.ts"); @@ -340,7 +341,9 @@ describe("the lock is on the production path", () => { let cleanupFailed = false; let cleanupError: unknown; try { - const deadline = Date.now() + 10_000; + // Each poll iteration spawns a real child; the hold marker comes from another one. + // 8-19 s per boot on windows-latest (run 33930757649). + const deadline = Date.now() + INTERNAL_DEADLINE_MS; while (!existsSync(holdMarker) && Date.now() < deadline) { requireChildSuccess(runChild(["--eval", "Bun.sleepSync(20)"], process.env), "hold-marker wait child"); } diff --git a/tests/codex-integration/codex-prompt-route.test.ts b/tests/codex-integration/codex-prompt-route.test.ts index f69dd8ea2d..ef862f58e2 100644 --- a/tests/codex-integration/codex-prompt-route.test.ts +++ b/tests/codex-integration/codex-prompt-route.test.ts @@ -20,6 +20,7 @@ import { import type { ManagementPrincipal } from "../../src/server/management-auth"; import type { OcxConfig } from "../../src/types"; import { removeTreeWithRetry } from "../helpers/remove-tree"; +import { INTERNAL_DEADLINE_MS } from "../helpers/test-budget"; const MARKER = "# Auto-injected by opencodex"; const config = { port: 10100, defaultProvider: "openai", providers: {} } as OcxConfig; @@ -71,7 +72,10 @@ function read(path: string): string | null { } async function waitUntil(predicate: () => boolean, detail: string): Promise { - const deadline = Date.now() + 5_000; + // Every caller gates on a spawned probe child writing a pid/start marker: 8-19 s to boot + // on windows-latest (run 33930757649). The diagnostic below names the marker, so the + // bound must stay under the enclosing case budget for it to be what gets reported. + const deadline = Date.now() + INTERNAL_DEADLINE_MS; while (!predicate()) { if (Date.now() >= deadline) throw new Error(`timed out waiting for ${detail}`); await Bun.sleep(10); diff --git a/tests/codex-integration/codex-prompt-text-probe.test.ts b/tests/codex-integration/codex-prompt-text-probe.test.ts index f9c70e1729..363bcc4798 100644 --- a/tests/codex-integration/codex-prompt-text-probe.test.ts +++ b/tests/codex-integration/codex-prompt-text-probe.test.ts @@ -19,6 +19,7 @@ import { setPromptTextProbeCommandForTests, } from "../../src/codex/prompt-text-probe"; import { removeTreeWithRetry } from "../helpers/remove-tree"; +import { INTERNAL_DEADLINE_MS } from "../helpers/test-budget"; const lifecycleRoots: string[] = []; const VALID_PROBE_OUTPUT = JSON.stringify([{ @@ -32,7 +33,8 @@ function message(text: string): string { } async function waitUntil(predicate: () => boolean, detail: string): Promise { - const deadline = Date.now() + 5_000; + // Gates on a spawned child writing its pid marker or exiting: 8-19 s on windows-latest. + const deadline = Date.now() + INTERNAL_DEADLINE_MS; while (!predicate()) { if (Date.now() >= deadline) throw new Error(`timed out waiting for ${detail}`); await Bun.sleep(10); diff --git a/tests/codex-integration/codex-retained-root-serialization.test.ts b/tests/codex-integration/codex-retained-root-serialization.test.ts index 4f15c7852d..07f6446582 100644 --- a/tests/codex-integration/codex-retained-root-serialization.test.ts +++ b/tests/codex-integration/codex-retained-root-serialization.test.ts @@ -20,6 +20,7 @@ import { claimOwnedServiceHome, withOwnedServiceHomePreload } from "../helpers/o import { removeTreeWithRetry } from "../helpers/remove-tree"; import { repoRoot as resolveRepoRoot } from "../helpers/repo-root"; import { SPAWN_BUDGET_MS } from "../helpers/test-budget"; +import { INTERNAL_DEADLINE_MS } from "../helpers/test-budget"; const repoRoot = resolveRepoRoot(); const sandboxes: Sandbox[] = []; @@ -200,7 +201,7 @@ async function holdCatalogLock(sandbox: Sandbox): Promise<{ }); sandbox.children.add(child); sandbox.releaseMarkers.add(release); - await waitForPath(ready, 12_000); + await waitForPath(ready, INTERNAL_DEADLINE_MS); return { release: () => { try { writeFileSync(release, "release"); } catch { /* teardown may have released already */ } }, child, @@ -370,7 +371,7 @@ for (const publisher of ["convergence", "retained"] as const) { `], sandbox.preloadPath)], { cwd: repoRoot, env: sandboxChildEnv(sandbox), stdout: "pipe", stderr: "pipe" }); sandbox.children.add(sync); - await raceBarrier(sync, waitForPath(requested, 16_000)); + await raceBarrier(sync, waitForPath(requested, INTERNAL_DEADLINE_MS)); const published = await runPublisher(sandbox, publisher, config); if (published.exitCode !== 0) { throw new Error(`${publisher} publisher failed\nstdout=${published.stdout}\nstderr=${published.stderr}`); @@ -447,7 +448,7 @@ test("a persisted runtime selection moved by another process during the await bl `], sandbox.preloadPath)], { cwd: repoRoot, env: sandboxChildEnv(sandbox), stdout: "pipe", stderr: "pipe" }); sandbox.children.add(sync); - await raceBarrier(sync, waitForPath(requested, 16_000)); + await raceBarrier(sync, waitForPath(requested, INTERNAL_DEADLINE_MS)); // Another process selects a different Codex runtime. No catalog byte changes. writeFileSync(runtimeStatePath, `${JSON.stringify({ @@ -511,7 +512,8 @@ test("two processes at the post-approval management seam serialize instead of in // looked exactly like a production defect until the encoder said so. globalThis.fetch = async () => { writeFileSync(${JSON.stringify(barrier)} + "-" + ${JSON.stringify(marker)}, "here"); - const deadline = Date.now() + 8000; + // Two children rendezvous on markers; either may take 8-19 s to boot on windows-latest. + const deadline = Date.now() + ${INTERNAL_DEADLINE_MS}; while (Date.now() < deadline) { if (existsSync(${JSON.stringify(barrier)} + "-a") && existsSync(${JSON.stringify(barrier)} + "-b")) break; await Bun.sleep(5); @@ -551,7 +553,8 @@ test("two processes at the post-approval management seam serialize instead of in // On macOS CI both children can still lose the config lock before approval even // after the warm-up — that proves nothing about catalog serialization. Retry // vacuous runs until at least one process reaches the post-approval seam. - const attemptDeadline = Date.now() + 20_000; + // Each attempt boots two real children; bound the retry loop by the spawn budget, not a literal. + const attemptDeadline = Date.now() + SPAWN_BUDGET_MS; let results: Array<{ exitCode: number; stdout: string; stderr: string }> | undefined; while (Date.now() < attemptDeadline) { for (const marker of ["a", "b"] as const) { diff --git a/tests/codex-integration/codex-shim.test.ts b/tests/codex-integration/codex-shim.test.ts index fc36d7c8b0..7094eb3748 100644 --- a/tests/codex-integration/codex-shim.test.ts +++ b/tests/codex-integration/codex-shim.test.ts @@ -6,6 +6,7 @@ import { tmpdir } from "node:os"; import { autoRestoreCodexShim, buildUnixCodexShim, buildWindowsCodexShim, buildWindowsPowerShellCodexShim, diagnoseCodexShim, findCodexOnPath, inspectCodexShimBackingForCommand, installCodexShim, isLocalAbsoluteInspectionPath, isVersionManagerOwnedCodexPath, isWindowsInteropDir, lastCodexDiscoveryError, setCodexShimFreshWriteHookForTests, setCodexShimGuardedWriteHookForTests, setCodexShimProbeHookForTests, setCodexShimProbeObservationMsForTests, setCodexShimProbeShellForTests, setCodexShimRollbackRestoreHookForTests, uninstallCodexShim } from "../../src/codex/shim"; import { removeTreeWithRetry } from "../helpers/remove-tree"; import { repoPath, repoRoot } from "../helpers/repo-root"; +import { INTERNAL_DEADLINE_MS } from "../helpers/test-budget"; const SHIM_MARKER = "opencodex codex autostart shim"; const UNIX_SHIM_REVISION_MARKER = "opencodex unix codex shim revision 2"; @@ -1701,7 +1702,8 @@ exit 127 stdout: "pipe", stderr: "pipe", }); - const deadline = Date.now() + 5_000; + // Spawned holder child writing its ready marker: 8-19 s on windows-latest. + const deadline = Date.now() + INTERNAL_DEADLINE_MS; while (!existsSync(readyPath) && Date.now() < deadline) await Bun.sleep(5); expect(existsSync(readyPath)).toBe(true); diff --git a/tests/codex-integration/codex-write-lock.test.ts b/tests/codex-integration/codex-write-lock.test.ts index e33163361d..b3becfad47 100644 --- a/tests/codex-integration/codex-write-lock.test.ts +++ b/tests/codex-integration/codex-write-lock.test.ts @@ -25,6 +25,7 @@ import { import type { AdmissionSnapshot } from "../../src/codex/convergence-types"; import { removeTreeWithRetry } from "../helpers/remove-tree"; import { helperPath } from "../helpers/repo-root"; +import { INTERNAL_DEADLINE_MS, SPAWN_BUDGET_MS } from "../helpers/test-budget"; let root = ""; let codexHome = ""; @@ -311,7 +312,11 @@ describe("two real processes contend for one lock", () => { return JSON.parse(line) as { status: string; reason?: string; value?: string; lockId?: string }; } - async function waitFor(path: string, timeoutMs = 10_000): Promise { + // A spawned holder child boots in 8-19 s on a loaded windows-latest shard; the 10 s + // literal expired first on run 33930757649 ("case 0", 10.67 s). INTERNAL_DEADLINE_MS is + // the named bound for an in-test wait and stays under the enclosing SPAWN_BUDGET_MS so + // this helper's "timed out waiting for" diagnostic is what gets reported, not Bun's. + async function waitFor(path: string, timeoutMs = INTERNAL_DEADLINE_MS): Promise { const deadline = Date.now() + timeoutMs; while (Date.now() < deadline) { if (Bun.file(path).size > 0) return; @@ -340,14 +345,14 @@ describe("two real processes contend for one lock", () => { // was contention rather than a permanent refusal wearing its label. const after = await withCodexWriteLock(options({ timeoutMs: 5_000 }), publishing("parent")); expect(after.status).toBe("acquired"); - }, 30_000); + }, SPAWN_BUDGET_MS); test("both processes resolve the same lock id for one home", async () => { const first = await childResult(spawnChild({ timeoutMs: 5_000 })); expect(first.status).toBe("acquired"); const local = canonicalizeCodexHome(codexHome); expect(local.ok && first.lockId).toBe(local.ok ? local.home.lockId : "x"); - }, 30_000); + }, SPAWN_BUDGET_MS); /** * A waiting contender must actually wait rather than fail fast — and must @@ -368,7 +373,7 @@ describe("two real processes contend for one lock", () => { expect(holderResult.status).toBe("acquired"); expect(waited.status).toBe("acquired"); expect(waited.status === "acquired" && waited.waitedMs).toBeGreaterThan(0); - }, 30_000); + }, SPAWN_BUDGET_MS); /** * C7/C18 — the namespace keys on the OS user, not on any home accessor. @@ -451,6 +456,6 @@ describe("two real processes contend for one lock", () => { ); expect(after.status).toBe("acquired"); expect(after.lockId).toBe(held.lockId); - }, 30_000); + }, SPAWN_BUDGET_MS); } }); diff --git a/tests/codex-integration/native-profile-manager.test.ts b/tests/codex-integration/native-profile-manager.test.ts index 5d7a29509f..425f0a6c08 100644 --- a/tests/codex-integration/native-profile-manager.test.ts +++ b/tests/codex-integration/native-profile-manager.test.ts @@ -17,6 +17,7 @@ import { NativeProfileError, type NativeProfileKey, type NativeProfileKeyProvide import { codexCredentialMutationEpoch } from "../../src/codex/credential-mutation-epoch"; import { removeTreeWithRetry } from "../helpers/remove-tree"; import { helperPath, repoRoot } from "../helpers/repo-root"; +import { INTERNAL_DEADLINE_MS, SPAWN_BUDGET_MS } from "../helpers/test-budget"; const roots: string[] = []; @@ -137,7 +138,8 @@ async function leavePendingJournal(f: Awaited * sized inside its 15 s test budget. On timeout the child's stderr is part of the error so * a real crash is not mistaken for a slow start. */ -async function waitForPath(path: string, child?: ReturnType, waitMs = 5_000): Promise { +// Gates on a spawned child reaching its marker: 8-19 s on windows-latest (run 33930757649). +async function waitForPath(path: string, child?: ReturnType, waitMs = INTERNAL_DEADLINE_MS): Promise { const deadline = Date.now() + waitMs; while (!existsSync(path) && Date.now() < deadline) await Bun.sleep(10); if (existsSync(path)) return; @@ -196,12 +198,12 @@ describe("native main profile transactions", () => { const f = fixture(); const readyPath = join(f.root, "crash-ready"); const child = spawnLockHolder(f, readyPath, join(f.root, "unused-release"), { crash: true }); - await waitForPath(readyPath, child, 12_000); + await waitForPath(readyPath, child, INTERNAL_DEADLINE_MS); expect(await child.exited).toBe(87); const successor = new NativeProfileManager({ ...f.options, lockWaitMs: 250 }); expect((await successor.recover(false)).recovered).toBe(false); - }, 15_000); + }, SPAWN_BUDGET_MS); test("a losing same-process contender cannot release another transaction's POSIX lock", async () => { if (process.platform === "win32") return; @@ -252,7 +254,7 @@ describe("native main profile transactions", () => { ...(acquiredProbe ? [acquiredProbe.exited] : []), ]); } - }, 15_000); + }, SPAWN_BUDGET_MS); test("two processes exclude each other and predecessor release cannot delete a successor lock", async () => { const f = fixture(); @@ -291,7 +293,7 @@ describe("native main profile transactions", () => { await first.exited; if (second) await second.exited; } - }, 15_000); + }, SPAWN_BUDGET_MS); test("the same canonical CODEX_HOME serializes different OpenCodex config roots", async () => { const f = fixture(); @@ -318,7 +320,7 @@ describe("native main profile transactions", () => { writeFileSync(release, "release"); await first.exited; } - }, 15_000); + }, SPAWN_BUDGET_MS); test("shares one vault while preventing another OPENCODEX_HOME from finishing or cancelling a stage", async () => { const f = fixture(); diff --git a/tests/codex-integration/native-profile-startup.test.ts b/tests/codex-integration/native-profile-startup.test.ts index ed0a622769..9e3aa656e1 100644 --- a/tests/codex-integration/native-profile-startup.test.ts +++ b/tests/codex-integration/native-profile-startup.test.ts @@ -54,6 +54,7 @@ import { import { startServer } from "../../src/server"; import { removeTreeWithRetry } from "../helpers/remove-tree"; import { helperPath, repoRoot } from "../helpers/repo-root"; +import { INTERNAL_DEADLINE_MS } from "../helpers/test-budget"; const roots: string[] = []; const previousOpencodexHome = process.env.OPENCODEX_HOME; @@ -226,7 +227,8 @@ async function fixture( return { root, codexHome, configDir, key, manager, target, sourceProfileId: sourceRecord.id, targetProfileId: targetRecord.id }; } -async function waitForPath(path: string, timeoutMs = 10_000): Promise { +// Gates on a spawned child reaching its marker: 8-19 s on windows-latest (run 33930757649). +async function waitForPath(path: string, timeoutMs = INTERNAL_DEADLINE_MS): Promise { const deadline = Date.now() + timeoutMs; while (!existsSync(path) && Date.now() < deadline) await Bun.sleep(10); if (!existsSync(path)) throw new Error(`Timed out waiting for ${path}`); @@ -239,8 +241,9 @@ async function waitForPath(path: string, timeoutMs = 10_000): Promise { * Wait for a port that is actually a port. */ // A spawned proxy child needs 10-18 s to reach its port file on a loaded windows-latest shard -// (runs 33601508392 and 33610501053); every caller here has a 20 s+ budget. -async function waitForPort(path: string, timeoutMs = 18_000): Promise { +// (runs 33601508392 and 33610501053), and run 33930757649 showed 19 s boots elsewhere in the +// suite. INTERNAL_DEADLINE_MS is the named in-test bound; callers carry a larger case budget. +async function waitForPort(path: string, timeoutMs = INTERNAL_DEADLINE_MS): Promise { const deadline = Date.now() + timeoutMs; for (;;) { if (existsSync(path)) { diff --git a/tests/helpers/storage-policy-api.ts b/tests/helpers/storage-policy-api.ts index 70ef03f15b..0451132f4b 100644 --- a/tests/helpers/storage-policy-api.ts +++ b/tests/helpers/storage-policy-api.ts @@ -24,6 +24,7 @@ import { import { stopStorageCleanupScheduler } from "../../src/storage/policy-scheduler"; import { drainStorageWorkers } from "../../src/storage/worker-lifecycle"; import { removeTreeWithRetry } from "./remove-tree"; +import { INTERNAL_DEADLINE_MS } from "./test-budget"; export function baseConfig(): OcxConfig { return { @@ -58,7 +59,9 @@ export function seedArchived(codexHome: string): void { export async function waitForJobIdle( serverUrl: URL, startedAt: number, - timeoutMs = 15_000, + // Polls a live server for a worker-backed job to settle; the worker's OS-thread join is + // the slow half on Windows. Named so every caller inherits the same bound. + timeoutMs = INTERNAL_DEADLINE_MS, ): Promise<{ enabled: boolean; lastRun?: { removed: number }; diff --git a/tests/oauth/oauth-refresh-lock-multiprocess.test.ts b/tests/oauth/oauth-refresh-lock-multiprocess.test.ts index 524c9397b4..7114120c94 100644 --- a/tests/oauth/oauth-refresh-lock-multiprocess.test.ts +++ b/tests/oauth/oauth-refresh-lock-multiprocess.test.ts @@ -15,6 +15,7 @@ import { saveCredential, } from "../../src/oauth/store"; import { removeTreeWithRetry } from "../helpers/remove-tree"; +import { INTERNAL_DEADLINE_MS, SPAWN_BUDGET_MS } from "../helpers/test-budget"; const repoRoot = dirname(fileURLToPath(new URL("../../package.json", import.meta.url))); const origHome = process.env.HOME; @@ -92,7 +93,8 @@ describe("slow multi-process OAuth refresh lock", () => { stderr: "pipe", }); - const deadline = Date.now() + 15_000; + // Spawned child reaching its ready marker: 8-19 s on windows-latest (run 33930757649). + const deadline = Date.now() + INTERNAL_DEADLINE_MS; while (!existsSync(readyPath) && Date.now() < deadline) { await Bun.sleep(25); } @@ -127,5 +129,5 @@ describe("slow multi-process OAuth refresh lock", () => { expect(writerExit).toBe(0); const writerOut = await new Response(writer.stdout).text(); expect(writerOut).toContain("writer-done"); - }, 30_000); + }, SPAWN_BUDGET_MS); }); diff --git a/tests/server/server-background-lifecycle.test.ts b/tests/server/server-background-lifecycle.test.ts index faa0f9949c..530ead83ca 100644 --- a/tests/server/server-background-lifecycle.test.ts +++ b/tests/server/server-background-lifecycle.test.ts @@ -40,6 +40,7 @@ import { type IsolatedCodexHome, } from "../helpers/isolated-codex-home"; import { removeTreeWithRetry } from "../helpers/remove-tree"; +import { INTERNAL_DEADLINE_MS } from "../helpers/test-budget"; type StartedServer = ReturnType; type IntervalTimer = ReturnType; @@ -240,7 +241,8 @@ function seedArchived(codexHome: string): void { db.close(); } -async function waitForLiveStorageWorker(timeoutMs = 10_000): Promise { +// Worker spawn behind a live server on a loaded windows-latest shard; platform floor. +async function waitForLiveStorageWorker(timeoutMs = INTERNAL_DEADLINE_MS): Promise { const deadline = Date.now() + timeoutMs; while (Date.now() < deadline) { if (liveStorageWorkerCount() > 0) return; diff --git a/tests/storage/storage-mutation-race.test.ts b/tests/storage/storage-mutation-race.test.ts index d4a85925d5..fb89dd9215 100644 --- a/tests/storage/storage-mutation-race.test.ts +++ b/tests/storage/storage-mutation-race.test.ts @@ -43,6 +43,7 @@ import { drainStorageWorkers, } from "../../src/storage/worker-lifecycle"; import { installIsolatedCodexHome, type IsolatedCodexHome } from "../helpers/isolated-codex-home"; +import { INTERNAL_DEADLINE_MS } from "../helpers/test-budget"; let testDir = ""; let previousHome: string | undefined; @@ -124,7 +125,8 @@ async function enablePolicyAndRun(serverUrl: string): Promise<{ startedAt: numbe async function waitForPolicyJob( serverUrl: string, startedAt: number, - timeoutMs = 20_000, + // Same wait as helpers/storage-policy-api waitForJobIdle: live server, worker-backed job. + timeoutMs = INTERNAL_DEADLINE_MS, ): Promise<{ job: { lastOutcome?: { ok?: boolean; error?: string; removed?: number } } }> { const deadline = Date.now() + timeoutMs; while (Date.now() < deadline) { diff --git a/tests/storage/storage-policy-job-responsive.test.ts b/tests/storage/storage-policy-job-responsive.test.ts index b93552a9d0..ad3a0d57e9 100644 --- a/tests/storage/storage-policy-job-responsive.test.ts +++ b/tests/storage/storage-policy-job-responsive.test.ts @@ -20,6 +20,7 @@ import { import { stopStorageCleanupScheduler } from "../../src/storage/policy-scheduler"; import { drainStorageWorkers } from "../../src/storage/worker-lifecycle"; import { removeTreeWithRetry } from "../helpers/remove-tree"; +import { INTERNAL_DEADLINE_MS } from "../helpers/test-budget"; let testDir = ""; let previousHome: string | undefined; @@ -137,13 +138,18 @@ describe("storage cleanup policy job responsiveness", () => { expect(sample).toBeLessThan(maxHealthMs); } - const deadline = Date.now() + 10_000; + // Polls a live server whose worker is deliberately blocked. Review of 3b431b413 found + // this loop fell through on expiry with no assertion, so a job that never returned to + // idle still passed; the expect below is what makes the wait mean something. + const deadline = Date.now() + INTERNAL_DEADLINE_MS; + let settled = false; while (Date.now() < deadline) { const got = await fetch(new URL("/api/storage/cleanup-policy", server.url)); const body = await got.json() as { job: { status: string; startedAt?: number } }; - if (body.job.status === "idle" && body.job.startedAt === runBody.job?.startedAt) break; + if (body.job.status === "idle" && body.job.startedAt === runBody.job?.startedAt) { settled = true; break; } await Bun.sleep(50); } + expect(settled).toBe(true); } finally { await drainAndShutdown(server, 5_000); await resetStorageCleanupPolicyJobForTestsAsync(); diff --git a/tests/storage/storage-worker-lifecycle.test.ts b/tests/storage/storage-worker-lifecycle.test.ts index 9f92227678..3e3a415ed3 100644 --- a/tests/storage/storage-worker-lifecycle.test.ts +++ b/tests/storage/storage-worker-lifecycle.test.ts @@ -34,6 +34,7 @@ import { } from "../../src/storage/worker-lifecycle"; import { installIsolatedCodexHome, type IsolatedCodexHome } from "../helpers/isolated-codex-home"; import { removeTreeWithRetry } from "../helpers/remove-tree"; +import { INTERNAL_DEADLINE_MS } from "../helpers/test-budget"; let isolatedCodexHome: IsolatedCodexHome | null = null; let testDir = ""; @@ -67,7 +68,9 @@ afterEach(async () => { testDir = ""; }); -async function waitForIdle(timeoutMs = 20_000): Promise { +// Worker-thread lifecycle: Windows OS-thread join is the slow half (see +// src/storage/worker-lifecycle.ts), so the bound follows the platform floor. +async function waitForIdle(timeoutMs = INTERNAL_DEADLINE_MS): Promise { const deadline = Date.now() + timeoutMs; while (Date.now() < deadline) { if (getStorageCleanupPolicyJobState().status === "idle") return; @@ -77,7 +80,7 @@ async function waitForIdle(timeoutMs = 20_000): Promise { } /** Guards against a vacuous pass: assert we really did spawn a worker. */ -async function waitForLiveWorker(timeoutMs = 10_000): Promise { +async function waitForLiveWorker(timeoutMs = INTERNAL_DEADLINE_MS): Promise { const deadline = Date.now() + timeoutMs; while (Date.now() < deadline) { if (liveStorageWorkerCount() > 0) return; diff --git a/tests/storage/storage-worker-teardown-isolate.test.ts b/tests/storage/storage-worker-teardown-isolate.test.ts index fa8c244a7d..f5b6309cf1 100644 --- a/tests/storage/storage-worker-teardown-isolate.test.ts +++ b/tests/storage/storage-worker-teardown-isolate.test.ts @@ -36,6 +36,7 @@ import { } from "../../src/storage/worker-lifecycle"; import { installIsolatedCodexHome, type IsolatedCodexHome } from "../helpers/isolated-codex-home"; import { removeTreeWithRetry } from "../helpers/remove-tree"; +import { INTERNAL_DEADLINE_MS } from "../helpers/test-budget"; let isolatedCodexHome: IsolatedCodexHome | null = null; let testDir = ""; @@ -92,7 +93,8 @@ afterAll(async () => { await drainStorageWorkers(); }); -async function waitForLiveWorker(timeoutMs = 10_000): Promise { +// Worker spawn on a loaded windows-latest shard; bound follows the platform floor. +async function waitForLiveWorker(timeoutMs = INTERNAL_DEADLINE_MS): Promise { const deadline = Date.now() + timeoutMs; while (Date.now() < deadline) { if (liveStorageWorkerCount() > 0) return;