From d309d52655f1069ef46d15524bf820b5f209079c Mon Sep 17 00:00:00 2001 From: JUN Date: Thu, 17 Sep 2026 04:30:10 +0900 Subject: [PATCH] test(budget): restore the 45s spawn signal and stop hardening a disposable port PR #4830 raised SPAWN_BUDGET_MS on win32 from 45s to 90s to fix one test case. 31 test files read that constant and nine hand it to setDefaultTimeout, so the edit reached 339 Windows cases: 315 went 45s to 90s, 22 more that multiply it went 90s to 180s, and one derivation chain in codex-sync-api reached 265s. The detectors that now report twice as late are the contention ones -- codex-write-lock, the cross-process history-lock exclusions, the shim process cases -- and several of the affected files never spawn anything. The measurement behind #4830 was also contaminated. The child published its port through atomicWriteFile, the production SECRET writer, which on Windows runs hardenSecretPath(..., required: true) twice, each able to spawn PowerShell for SID resolution and several 30s-budgeted icacls passes. That ACL ceremony ran inside the window the parent measures as "time to reach a port" -- on a disposable port number. - SPAWN_BUDGET_MS returns to 45s on every platform. - COLD_SPAWN_BUDGET_MS (90s, win32 only) is consumed exactly once, by the readiness wait of the first proxy child in native-profile-startup. - The child publishes its port and settled markers with a plain temp-file rename, preserving the #1061 no-partial-read contract without the ACL ceremony. - The child logs child-entry, start-server-begin, start-server-end and port-published, so the next slow run names its own phase. - codex-sync-api owns its bounds instead of deriving them, which returns that case to 130s and makes it immune to the next edit of a shared constant. It also reports its measured preparation window on green runs. Co-authored-by: lidge-jun --- .../codex-integration/codex-sync-api.test.ts | 30 ++++++++--- .../native-profile-startup.test.ts | 30 +++++++++-- tests/helpers/native-profile-startup-child.ts | 51 +++++++++++++++---- tests/helpers/test-budget.ts | 50 +++++++++++++----- 4 files changed, 126 insertions(+), 35 deletions(-) diff --git a/tests/codex-integration/codex-sync-api.test.ts b/tests/codex-integration/codex-sync-api.test.ts index ff53a7e92ca..ded465e0d90 100644 --- a/tests/codex-integration/codex-sync-api.test.ts +++ b/tests/codex-integration/codex-sync-api.test.ts @@ -10,7 +10,6 @@ import type { OrcaCodexHomeDiagnostic } from "../../src/codex/home"; 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 TEST_DIR = join(import.meta.dir, ".tmp-codex-sync-api"); const TEST_CODEX_HOME = join(TEST_DIR, "codex"); @@ -18,13 +17,23 @@ const TEST_OCX_HOME = join(TEST_DIR, "ocx"); const TEST_HOME = join(TEST_DIR, "home"); const repoRoot = resolveRepoRoot(); const COMPETING_OFF_REAP_MS = 5_000; -const COMPETING_OFF_BOOT_MS = SPAWN_BUDGET_MS - COMPETING_OFF_REAP_MS; -// Windows preparation performs real identity/admission preflight before discovery. -// Reserve that work separately: CI observed 52.7s before the flip could even start. -// The second process still keeps its original boot and reap limits. -const COMPETING_OFF_PREPARATION_MS = process.platform === "win32" - ? 2 * COMPETING_OFF_BOOT_MS - : COMPETING_OFF_BOOT_MS; +/** + * This case owns its numbers instead of deriving them from `SPAWN_BUDGET_MS`. + * + * It used to derive them, and three derivations multiplied a single edit: when that shared + * constant moved 45s -> 90s the outer bound here went 130s -> 265s, which nobody chose and no + * measurement asked for. A 265s case on a Windows shard that already runs 25 minutes leaves an + * unsafe margin against the 30-minute job timeout, so one hang would have been reported as a + * cancelled job rather than as a named Bun timeout. + * + * What the case costs in practice: five Windows shard logs put it at 3.7s, 3.8s, 4.1s, 7.6s + * and 9.4s. What the numbers below are for is the cold-start outlier the reserve was written + * against — 52.7s of real identity/admission preflight before the flip could even start. They + * are headroom for that, not a duration, and the child now reports its own preparation time on + * every green run so the next revision of these bounds can be measured rather than argued. + */ +const COMPETING_OFF_BOOT_MS = 40_000; +const COMPETING_OFF_PREPARATION_MS = process.platform === "win32" ? 80_000 : COMPETING_OFF_BOOT_MS; const COMPETING_OFF_CHILD_MS = COMPETING_OFF_PREPARATION_MS + COMPETING_OFF_BOOT_MS + COMPETING_OFF_REAP_MS; const COMPETING_OFF_TEST_MS = COMPETING_OFF_CHILD_MS + COMPETING_OFF_REAP_MS; let prevCodexHome: string | undefined; @@ -470,6 +479,7 @@ describe("GUI/CLI Codex sync backend", () => { ' const flipEnv = { ...process.env }; delete flipEnv.OCX_TEST_SERVICE_HOME_PROBE;', ` const flipBudgetMs = ${COMPETING_OFF_BOOT_MS};`, ' const remainingMs = Number(process.env.OCX_TEST_COMPETING_OFF_DEADLINE) - Date.now();', + ` console.log("[sync-race] preparation elapsedMs=" + (${COMPETING_OFF_CHILD_MS} - remainingMs));`, ` if (!Number.isFinite(remainingMs) || remainingMs < flipBudgetMs + ${COMPETING_OFF_REAP_MS}) {`, ' flipFailure = new Error("competing OFF flip not started: insufficient remaining budget " + remainingMs);', ' throw flipFailure;', @@ -512,6 +522,10 @@ describe("GUI/CLI Codex sync backend", () => { } const line = child.stdout.trim().split("\n").filter(Boolean).pop() ?? "{}"; expect(JSON.parse(line)).toMatchObject({ status: "skipped", skippedReason: "desired_disabled", ok: true }); + // Surface the measured preparation window on green runs too: the Windows reserve above is + // sized on one 52.7s observation, and this is what makes the next sizing an observation. + const prepared = child.stdout.split("\n").find(entry => entry.includes("[sync-race] preparation")); + if (prepared) console.info(prepared.trim()); // The stale ON snapshot wrote nothing: the fixture config is untouched. expect(readFileSync(join(raceCodexHome, "config.toml"), "utf8")).toBe(before); } finally { diff --git a/tests/codex-integration/native-profile-startup.test.ts b/tests/codex-integration/native-profile-startup.test.ts index 192a31259a0..89e871c0bbf 100644 --- a/tests/codex-integration/native-profile-startup.test.ts +++ b/tests/codex-integration/native-profile-startup.test.ts @@ -54,7 +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, SPAWN_BUDGET_MS } from "../helpers/test-budget"; +import { COLD_SPAWN_BUDGET_MS, INTERNAL_DEADLINE_MS, SPAWN_BUDGET_MS } from "../helpers/test-budget"; const roots: string[] = []; const previousOpencodexHome = process.env.OPENCODEX_HOME; @@ -62,13 +62,20 @@ const previousCodexHome = process.env.CODEX_HOME; const OWNERSHIP_REPROBE_TEST_HOME = "ownership-reprobe-test-home"; // One process boot, recovery observation, requests and bounded child teardown. const CHILD_CASE_BUDGET_MS = 2 * SPAWN_BUDGET_MS; +// The same, for the one case whose child pays this process's cold start. Only its readiness +// wait is longer; everything inside the case keeps the deadlines every other case has, so the +// wider outer bound cannot slow a real failure down — `waitForPort` still reports first. +const FIRST_CHILD_CASE_BUDGET_MS = COLD_SPAWN_BUDGET_MS + SPAWN_BUDGET_MS; type StartupChild = ReturnType; const childOutputs = new WeakMap; stderr: Promise; startedAt: number; ready: boolean; + cold: boolean; }>(); +/** Only the first child spawned in this process pays a cold start; the rest are warm. */ +let coldSpawnPending = true; function restoreEnv(name: "OPENCODEX_HOME" | "CODEX_HOME", value: string | undefined): void { if (value === undefined) delete process.env[name]; @@ -252,7 +259,7 @@ async function waitForPath(path: string, timeoutMs = INTERNAL_DEADLINE_MS): Prom // A spawned proxy child needs 10-18 s to reach its port file on a loaded windows-latest shard // (runs 33601508392 and 33610501053). A 15 s generic deadline therefore rejects healthy // children. Use the intrinsic spawn budget; each scenario has its own larger case bound. -async function waitForPort(path: string, child: StartupChild, timeoutMs = SPAWN_BUDGET_MS): Promise { +async function waitForPort(path: string, child: StartupChild, timeoutMs = readinessBudgetMs(child)): Promise { const deadline = Date.now() + timeoutMs; for (;;) { if (child.exitCode !== null) { @@ -268,12 +275,24 @@ async function waitForPort(path: string, child: StartupChild, timeoutMs = SPAWN_ } } if (Date.now() >= deadline) { - throw new Error(`Timed out waiting for a real port in ${path}; childExit=${child.exitCode}; elapsedMs=${Date.now() - childOutputs.get(child)!.startedAt}`); + const output = childOutputs.get(child)!; + throw new Error(`Timed out waiting for a real port in ${path}; childExit=${child.exitCode}; cold=${output.cold}; budgetMs=${timeoutMs}; elapsedMs=${Date.now() - output.startedAt}`); } await Bun.sleep(10); } } +/** + * Windows gives the first child in a file more room and nothing else: run 35118018849 saw the + * first proxy child publish at 50.7s while the very next one was ready in 1.8s. Spending that + * allowance on every child would halve the reporting speed of the contention detectors in this + * file for a cost only one child pays. The child now logs `child-entry`, `start-server-begin`, + * `start-server-end` and `port-published`, so a future breach names its own phase. + */ +function readinessBudgetMs(child: StartupChild): number { + return childOutputs.get(child)!.cold ? COLD_SPAWN_BUDGET_MS : SPAWN_BUDGET_MS; +} + function childPaths(f: Fixture) { return { port: join(f.root, "port"), @@ -312,7 +331,9 @@ function spawnChild(f: Fixture, paths: ReturnType): StartupCh stderr: new Response(child.stderr).text(), startedAt, ready: false, + cold: coldSpawnPending, }); + coldSpawnPending = false; return child; } @@ -662,7 +683,8 @@ describe("native-main startup journal gate", () => { const active = (await f.manager.list()).activeProfileId; expect(active).toBe(scenario.active === "target" ? f.targetProfileId : f.sourceProfileId); }); - }, CHILD_CASE_BUDGET_MS); + // First spawning case in file order, so its first scenario is the cold one. + }, FIRST_CHILD_CASE_BUDGET_MS); test.each(["unreadable", "third"] as const)("manual observation %s keeps main closed while health and explicit recovery remain available", async (observation) => { const f = await fixture("prepared", observation); diff --git a/tests/helpers/native-profile-startup-child.ts b/tests/helpers/native-profile-startup-child.ts index a5a939d8982..90c3dfd9113 100644 --- a/tests/helpers/native-profile-startup-child.ts +++ b/tests/helpers/native-profile-startup-child.ts @@ -1,9 +1,9 @@ -import { appendFileSync, existsSync } from "node:fs"; +import { appendFileSync, existsSync, renameSync, writeFileSync } from "node:fs"; import { NativeProfileManager } from "../../src/codex/native-profile-manager"; import { isCodexAccountUsable } from "../../src/codex/account-usability"; import { isMainAccountTokenLive, MAIN_CODEX_ACCOUNT_ID } from "../../src/codex/main-account"; -import { atomicWriteFile, loadConfig } from "../../src/config"; +import { loadConfig } from "../../src/config"; import { nativeMainStartupGateSnapshot, waitForNativeMainStartupGate, @@ -11,6 +11,37 @@ import { import type { NativeProfileKey, NativeProfileKeyProvider } from "../../src/codex/native-profile-types"; import { startServer } from "../../src/server"; +const launchedAt = Number(process.env.NATIVE_STARTUP_LAUNCHED_AT ?? Date.now()); + +/** + * When this child is slow, the parent only learns that it was slow. Name each phase so the + * next slow run says WHERE — module load, `startServer`, or publication — instead of costing + * another forensic round. Run 35118018849 reported a single elapsedMs=50728 with no way to + * tell which of the three it was. + */ +const phase = (name: string): void => { + console.info(`[native-startup] ${name} elapsedMs=${Date.now() - launchedAt}`); +}; + +phase("child-entry"); + +/** + * A disposable port number is not a secret, so it must not travel through the production + * secret writer. On Windows `atomicWriteFile` runs `hardenSecretPath(..., required: true)` + * twice (`src/config/atomic-write.ts`), each of which can spawn PowerShell for SID resolution + * and several `icacls` passes budgeted at 30s apiece — an ACL ceremony performed inside the + * window the parent measures as "time to reach a port". + * + * The parent's actual contract is narrower (#1061): it treats existence as readiness and parses + * immediately, so it must never observe the file between create and write. A rename within the + * same directory gives exactly that — a reader sees either nothing or the whole document. + */ +function publishFixtureFile(path: string, content: string): void { + const tmp = `${path}.${process.pid}.tmp`; + writeFileSync(tmp, content, "utf8"); + renameSync(tmp, path); +} + const required = (name: string): string => { const value = process.env[name]; if (!value) throw new Error(`missing ${name}`); @@ -61,6 +92,7 @@ if (process.env.OCX_TEST_NATIVE_STARTUP_FAIL_BEFORE_LISTEN === "1") { throw new Error("injected native startup failure before listen"); } +phase("start-server-begin"); const server = startServer(0, { inspectNativeCodexOwnership: () => ({ ownership: "owned", @@ -74,9 +106,8 @@ const server = startServer(0, { }, managementApi: { nativeProfileApi: { manager } }, }); +phase("start-server-end"); -// The parent treats existence as readiness and parses the port immediately. Publish -// through a rename so it can never observe the file between create and write. // Test-only causal probe, normally disabled: a healthy process can publish later // than the old generic deadline without changing recovery/admission behavior. const portDelayMs = Number(process.env.OCX_TEST_NATIVE_STARTUP_DELAY_PORT_MS ?? 0); @@ -84,19 +115,17 @@ if (!Number.isFinite(portDelayMs) || portDelayMs < 0 || portDelayMs > 60_000) { throw new Error("invalid native startup port delay fault"); } if (portDelayMs > 0) await Bun.sleep(portDelayMs); -atomicWriteFile(portPath, String(server.port)); -console.info(`[native-startup] port-published elapsedMs=${Date.now() - Number(process.env.NATIVE_STARTUP_LAUNCHED_AT ?? Date.now())}`); -// #1061: the parent parses this file as soon as it exists, so a partial write -// surfaces as `Unexpected EOF`. atomicWriteFile publishes through a rename, so a -// reader sees either nothing or the whole document. +phase("port-publish-begin"); +publishFixtureFile(portPath, String(server.port)); +phase("port-published"); void waitForNativeMainStartupGate().then(() => { - atomicWriteFile(settledPath, JSON.stringify({ + publishFixtureFile(settledPath, JSON.stringify({ gate: nativeMainStartupGateSnapshot(), mainTokenLive: isMainAccountTokenLive(), mainUsable: isCodexAccountUsable(loadConfig(), MAIN_CODEX_ACCOUNT_ID), })); }).catch((error: unknown) => { - atomicWriteFile(settledPath, JSON.stringify({ + publishFixtureFile(settledPath, JSON.stringify({ error: error instanceof Error ? `${error.message}\n${error.stack ?? ""}` : String(error), })); }); diff --git a/tests/helpers/test-budget.ts b/tests/helpers/test-budget.ts index d319f71d112..b41ccac9a3a 100644 --- a/tests/helpers/test-budget.ts +++ b/tests/helpers/test-budget.ts @@ -31,23 +31,49 @@ */ /** Real child process: PowerShell, a CLI smoke test, an external binary. */ -export const SPAWN_BUDGET_MS = spawnBudgetMs(); +export const SPAWN_BUDGET_MS = 45_000; /** - * Windows needs a higher ceiling for the same reason `BULK_DURABLE_IO_BUDGET_MS` does: the leg - * runs four Bun pools on one runner, and the first child spawned in a file pays a cold start the - * later ones do not. Run 35118018849 (job 104895935554) measured the first proxy child in + * The cold start of the FIRST child in a process, on Windows only. + * + * This exists because raising `SPAWN_BUDGET_MS` itself does not. 31 test files read that + * constant and nine hand it straight to `setDefaultTimeout`, so moving it from 45s to 90s + * halved the reporting speed of 339 Windows cases — codex-write-lock contention, the + * cross-process history-lock exclusions, the shim process cases — in order to fix one. Several + * of those files never spawn anything. Four more multiply it, and one chain of derivations + * reached 265s: long enough that a single hang on a Windows shard, which already runs about 25 + * minutes, approaches the 30-minute job timeout and returns an opaque cancellation instead of a + * readable Bun timeout. + * + * ## Why the number + * + * Run 35118018849 (job 104895935554) measured the first proxy child in * `tests/codex-integration/native-profile-startup.test.ts` publishing its port at - * elapsedMs=50728 against this 45s budget, while the very next spawn in the same file was ready - * in 1759ms and every other case passed. The wait is intrinsic — the spawned proxy IS the - * assertion — so 45s was measuring runner contention rather than a hang. + * elapsedMs=50728, while the next spawn in the same file was ready in 1759ms. Most of that + * window was the test's own doing: the child published a disposable port number through the + * production secret writer, which on Windows runs two `hardenSecretPath(..., required: true)` + * passes, each able to spawn PowerShell for SID resolution and several 30s-budgeted `icacls` + * calls. That publication is now a plain temp-file rename, so the ceremony is out of the + * measured window entirely. Across 30 Windows shard logs the surviving readiness waits are + * 2.0s to 19.7s. 45s covers them; this ceiling covers the possibility that some part of the + * 50.7s was cold process start rather than ACL work, which the new phase timestamps in + * `tests/helpers/native-profile-startup-child.ts` will settle on the next slow run. * - * 90s stays a bound rather than an absence of one, and it is gated on Windows so no other lane - * loses the shorter signal. + * ## Ablation + * + * The wait is intrinsic: the case that consumes this budget proves that a FRESH process gates + * native-main admission, so a real second process reaching a real port is the assertion, not + * setup for it. And the budget cannot hide a vacuous test, because none of the assertions + * depend on it. Ablate the behaviour under test — let `waitForNativeMainStartupGate` open + * admission before journal recovery settles — and the first `mainRequest` returns 200 where the + * case demands >= 400. That failure lands within milliseconds of readiness at any budget, 45s + * or 90s. A child that dies instead of listening is reported by `waitForPort` on + * `child.exitCode` without spending the budget at all. + * + * Consume it exactly once, for the readiness wait of a file's first child. A second consumer + * means the cold start is not what is being waited on. */ -function spawnBudgetMs(): number { - return process.platform === "win32" ? 90_000 : 45_000; -} +export const COLD_SPAWN_BUDGET_MS = process.platform === "win32" ? 90_000 : SPAWN_BUDGET_MS; /** Binds a real server or opens a real socket, including restart-and-reconnect flows. */ export const SERVER_BUDGET_MS = 30_000;