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;