test(budget): restore the 45s spawn signal and stop hardening a disposable port

tests/codex-integration/codex-sync-api.test.ts

@@ -10,21 +10,30 @@ 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");
 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 {

tests/codex-integration/native-profile-startup.test.ts

@@ -54,21 +54,28 @@ 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;
 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<typeof Bun.spawn>;
 const childOutputs = new WeakMap<StartupChild, {
   stdout: Promise<string>;
   stderr: Promise<string>;
   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<number> {
+async function waitForPort(path: string, child: StartupChild, timeoutMs = readinessBudgetMs(child)): Promise<number> {
   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<typeof childPaths>): 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);

tests/helpers/native-profile-startup-child.ts

@@ -1,16 +1,47 @@
-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,
 } from "../../src/codex/native-profile-startup";
 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,29 +106,26 @@ 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);
 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),
   }));
 });

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;