From b3c6563adebc3d3bb197d350680e70cc813f9faf Mon Sep 17 00:00:00 2001 From: JUN Date: Thu, 17 Sep 2026 20:53:25 +0900 Subject: [PATCH 1/2] test(windows): size the first-child readiness wait for cold start, and report dead children Two Windows shards failed on two different files during heavy queue contention, and both are the same defect: an in-test deadline that has to cover a Windows cold first child start, sized for an idle runner. run 35211904734 windows 3/9 failed at waitFor(holdMarker), not at the contention assertion -- that line was never reached, and holdMs was never approached. run 35210400258 windows 7/9 failed at the first wait of its case, for "listening", with no events at all. dev at 6d19a07369 passed all nine Windows shards on an idle queue (run 35215552842), so neither is a defect in the code under test. This is not a number raised to make red go away. The deadlines were smaller than the range this repository has already measured for the wait they bound. COLD_SPAWN_BUDGET_MS records a first child publishing at 50.7s while the next spawn in the same file was ready in 1.76s, with surviving readiness waits from 2.0s to 19.7s; codex-write-lock.test.ts says in its own comment that a holder child boots in 8-19s on a loaded shard, and bounded that wait at 15s. A case the file calls normal is slower than the deadline it has to meet. Each file now spends that named ceiling exactly once, on its first child, as the constant's own contract requires; every later wait keeps the ordinary bound. The second defect is that neither wait observed the child. A child that died and one that was merely slow produced the same message, so CI could not tell them apart, and the two want opposite fixes. Both waits now race the exit and report the code and stderr immediately. That is also what makes the native-main evidence readable: its stderr promise resolves at EOF, so an empty stderr in that message means the child had already exited silently rather than that it was still booting. The timeout branch in the owner harness also awaited that same EOF promise while claiming the child was still running, which could never settle. It is bounded now. Closes #4901 --- .../codex-write-lock.test.ts | 55 ++++++++++++++++--- .../native-main-owner-lifetime.test.ts | 45 ++++++++++++++- 2 files changed, 91 insertions(+), 9 deletions(-) diff --git a/tests/codex-integration/codex-write-lock.test.ts b/tests/codex-integration/codex-write-lock.test.ts index 71d0631f53..7809dcbaef 100644 --- a/tests/codex-integration/codex-write-lock.test.ts +++ b/tests/codex-integration/codex-write-lock.test.ts @@ -25,7 +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"; +import { COLD_SPAWN_BUDGET_MS, INTERNAL_DEADLINE_MS, SPAWN_BUDGET_MS } from "../helpers/test-budget"; let root = ""; let codexHome = ""; @@ -327,17 +327,58 @@ describe("two real processes contend for one lock", () => { }; } + /** + * Consumed once, by the readiness wait of this file's first child, per the contract on + * {@link COLD_SPAWN_BUDGET_MS}. Every later spawn in the process is warm -- the constant + * records a first child publishing at 50.7 s against 1.76 s for the next one in the same + * file -- so a second consumer here would be waiting on something other than cold start. + */ + let coldStartUnspent = true; + + /** + * 15 s was smaller than the range this file itself documents for the wait it bounds, which is + * a sizing error rather than thin headroom: a case that takes 19 s is described here as + * normal. The first child pays Windows cold start and gets the ceiling named for it; every + * later one is warm and keeps the ordinary in-test deadline. + */ + function spendColdStartAllowance(): number { + if (!coldStartUnspent) return INTERNAL_DEADLINE_MS; + coldStartUnspent = false; + return COLD_SPAWN_BUDGET_MS; + } + // 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 { + // + // The CHILD is watched here, not only the file. Until it was, a child that died before + // publishing produced the same "timed out waiting for" line as one that was merely slow on a + // loaded shard, so nothing in CI could tell those apart -- and the two want opposite fixes. + // Racing the exit reports the dead child immediately, with its code and stderr, instead of + // spending the rest of the deadline to say nothing (run 35211904734, windows 3/9). + async function waitFor( + path: string, + child: ReturnType, + timeoutMs = spendColdStartAllowance(), + ): Promise { const deadline = Date.now() + timeoutMs; while (Date.now() < deadline) { if (Bun.file(path).size > 0) return; + if (child.exitCode !== null || child.signalCode !== null) { + // The marker write and the exit can land in the same 10 ms gap, so look once more + // before calling it a death: a holder that published and then exited is not a failure. + if (Bun.file(path).size > 0) return; + throw new Error( + `child exited (code=${child.exitCode}, signal=${child.signalCode}) before publishing ` + + `${path}; stderr=${await new Response(child.stderr).text()}`, + ); + } await Bun.sleep(10); } - throw new Error(`timed out waiting for ${path}`); + // Still running, so this one really is a slow boot rather than a crash. Say which, because + // the previous message was true of both. + throw new Error(`timed out waiting for ${path} after ${timeoutMs}ms; the child is still running`); } test("a second process is excluded while the first holds, and succeeds after it releases", async () => { @@ -345,7 +386,7 @@ describe("two real processes contend for one lock", () => { const releaseMarker = join(root, "release"); const holder = spawnChild({ holdMarker, releaseMarker, timeoutMs: 0, holdMs: 20_000 }); - await waitFor(holdMarker); + await waitFor(holdMarker, holder); // The lock is genuinely held by another process right now. const blocked = await withCodexWriteLock(options({ timeoutMs: 0 }), publishing("parent")); @@ -379,13 +420,13 @@ describe("two real processes contend for one lock", () => { const releaseMarker = join(root, "release-2"); const waitMarker = join(root, "waiting-2"); const holder = spawnChild({ holdMarker, releaseMarker, timeoutMs: 0, holdMs: 20_000 }); - await waitFor(holdMarker); + await waitFor(holdMarker, holder); const waiter = spawnChild({ timeoutMs: 5_000, waitMarker }); // The waiter writes this only after withCodexWriteLock has returned its // pending promise. Because the holder is still held, that means the waiter // has attempted N and reached the retry wait rather than failing fast. - await waitFor(waitMarker); + await waitFor(waitMarker, waiter); writeFileSync(releaseMarker, "go"); const [waited, holderResult] = await Promise.all([childResult(waiter), childResult(holder)]); @@ -456,7 +497,7 @@ describe("two real processes contend for one lock", () => { // to outlast the contender's process boot, which took >4 s on windows-latest in run // 33603770447 and made the default 3 s hold expire first (read as 'acquired'). const holder = spawnChildWithEnv({ holdMarker, releaseMarker, timeoutMs: 0, holdMs: 20_000 }, { ...a }); - await waitFor(holdMarker); + await waitFor(holdMarker, holder); // Fail-fast: if the two environments produced different lock files this // would acquire instead of reporting contention. diff --git a/tests/codex-integration/native-main-owner-lifetime.test.ts b/tests/codex-integration/native-main-owner-lifetime.test.ts index 49d42dcae6..cade269ab1 100644 --- a/tests/codex-integration/native-main-owner-lifetime.test.ts +++ b/tests/codex-integration/native-main-owner-lifetime.test.ts @@ -12,6 +12,7 @@ import { import { tmpdir } from "node:os"; import { join, resolve } from "node:path"; import { watchdogMs } from "../helpers/ci-watchdog"; +import { COLD_SPAWN_BUDGET_MS } from "../helpers/test-budget"; import { saveConfig } from "../../src/config"; import { saveCodexAccountCredential } from "../../src/codex/account-store"; @@ -146,6 +147,25 @@ const OWNER_EVENT_WAIT_MS = watchdogMs(10_000); // drift apart again. const OWNER_LEASE_BUDGET_MS = Math.max(30_000, OWNER_EVENT_WAIT_MS * 4); +/** + * Windows cold start of this file's FIRST child, spent once, per the contract on + * {@link COLD_SPAWN_BUDGET_MS}. + * + * `watchdogMs(10_000)` sizes every wait in this file for a child that is already able to + * answer. The first one is not: it boots Bun, imports the server graph, and binds a port, and + * the constant records that first child taking 50.7 s where the next spawn in the same file was + * ready in 1.76 s. On run 35210400258 (windows 7/9) the very first wait of a case -- for + * `listening` -- expired with no events at all. Every later wait keeps the watchdog bound, + * because by then the cold start has already been paid and a slow answer means something else. + */ +let ownerColdStartUnspent = true; + +function spendOwnerColdStartAllowance(): number { + if (!ownerColdStartUnspent) return OWNER_EVENT_WAIT_MS; + ownerColdStartUnspent = false; + return Math.max(OWNER_EVENT_WAIT_MS, COLD_SPAWN_BUDGET_MS); +} + async function waitUntil(probe: () => T | null, timeoutMs = OWNER_EVENT_WAIT_MS): Promise { const deadline = Date.now() + timeoutMs; while (Date.now() < deadline) { @@ -206,13 +226,34 @@ class ChildHarness { })(); } - async waitFor(predicate: (event: Event) => boolean, timeoutMs = OWNER_EVENT_WAIT_MS): Promise { + async waitFor(predicate: (event: Event) => boolean, timeoutMs = spendOwnerColdStartAllowance()): Promise { const deadline = Date.now() + timeoutMs; for (;;) { const found = this.events.find(predicate); if (found) return found; + // A dead child and a slow one used to report identically. On run 35210400258 + // (windows 7/9) the first wait of a case failed with `events=[] stderr=` -- and because + // that stderr promise only resolves at EOF, its emptiness proves the child had already + // exited, silently, rather than that it was still booting. The message never said so. + // Report the exit the moment it happens, with the code, instead of spending the deadline. + if (this.child.exitCode !== null || this.child.signalCode !== null) { + // The event and the exit can land in the same wake, so re-check before blaming death. + const settled = this.events.find(predicate); + if (settled) return settled; + throw new Error( + `child exited (code=${this.child.exitCode}, signal=${this.child.signalCode}) before the ` + + `awaited event; events=${JSON.stringify(this.events)} stderr=${await this.stderr}`, + ); + } if (Date.now() >= deadline) { - throw new Error(`child event timeout; events=${JSON.stringify(this.events)} stderr=${await this.stderr}`); + // Do NOT await `this.stderr` unguarded here. It resolves at EOF, so for the case this + // branch now describes -- a child still running -- it would never settle, and the + // timeout would hang until the enclosing budget killed the test with a worse message. + const stderr = await Promise.race([this.stderr, Bun.sleep(1_000).then(() => "")]); + throw new Error( + `child event timeout after ${timeoutMs}ms; the child is still running; ` + + `events=${JSON.stringify(this.events)} stderr=${stderr}`, + ); } await Promise.race([ new Promise(resolve => this.waiters.add(resolve)), From ff13543668df416d77b61a4ba654dec5e3bc6e78 Mon Sep 17 00:00:00 2001 From: JUN Date: Thu, 17 Sep 2026 21:31:36 +0900 Subject: [PATCH 2/2] test(windows): drop the readiness-budget change, keep the child-death diagnostics The evidence this PR's budget argument rested on turned out to be an artifact of how it was produced. Both evidence branches were dispatched from refs whose merge-base predates #4876, and workflow_dispatch reads the workflow from the dispatched ref, so those runs used a ci.yml without OCX_TEST_NO_QUEUE and reproduced exactly the batch-serialization bug #4876 had already fixed. The batch-4 log shows it directly: one line saying a bare Bun worker is waiting for another test run to release the user lock, then eight minutes with no (pass) at all. Confirmed on the branches: OCX_TEST_NO_QUEUE appears 0 times in codex/ci-evidence-4875's ci.yml and once in dev's. So whether these deadlines are actually too small is undetermined again, and the COLD_SPAWN_BUDGET_MS use is withdrawn. Both files keep their original bounds. What does not depend on that evidence stays. Neither wait observed its child, so a child that died and one that was merely slow produced the same message; both now race the exit and report the code and stderr immediately, re-checking the awaited signal first so a child that signalled and then exited is not misreported. And the owner harness's timeout branch awaited a promise that only resolves at EOF while describing a child that is still running, which could never settle; it is bounded now. Those are diagnostic defects on their own terms, and they are what would have made the original evidence readable in the first place. --- .../codex-write-lock.test.ts | 24 ++----------------- .../native-main-owner-lifetime.test.ts | 22 +---------------- 2 files changed, 3 insertions(+), 43 deletions(-) diff --git a/tests/codex-integration/codex-write-lock.test.ts b/tests/codex-integration/codex-write-lock.test.ts index 7809dcbaef..8fcd2c034d 100644 --- a/tests/codex-integration/codex-write-lock.test.ts +++ b/tests/codex-integration/codex-write-lock.test.ts @@ -25,7 +25,7 @@ import { import type { AdmissionSnapshot } from "../../src/codex/convergence-types"; import { removeTreeWithRetry } from "../helpers/remove-tree"; import { helperPath } from "../helpers/repo-root"; -import { COLD_SPAWN_BUDGET_MS, INTERNAL_DEADLINE_MS, SPAWN_BUDGET_MS } from "../helpers/test-budget"; +import { INTERNAL_DEADLINE_MS, SPAWN_BUDGET_MS } from "../helpers/test-budget"; let root = ""; let codexHome = ""; @@ -327,26 +327,6 @@ describe("two real processes contend for one lock", () => { }; } - /** - * Consumed once, by the readiness wait of this file's first child, per the contract on - * {@link COLD_SPAWN_BUDGET_MS}. Every later spawn in the process is warm -- the constant - * records a first child publishing at 50.7 s against 1.76 s for the next one in the same - * file -- so a second consumer here would be waiting on something other than cold start. - */ - let coldStartUnspent = true; - - /** - * 15 s was smaller than the range this file itself documents for the wait it bounds, which is - * a sizing error rather than thin headroom: a case that takes 19 s is described here as - * normal. The first child pays Windows cold start and gets the ceiling named for it; every - * later one is warm and keeps the ordinary in-test deadline. - */ - function spendColdStartAllowance(): number { - if (!coldStartUnspent) return INTERNAL_DEADLINE_MS; - coldStartUnspent = false; - return COLD_SPAWN_BUDGET_MS; - } - // 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 @@ -360,7 +340,7 @@ describe("two real processes contend for one lock", () => { async function waitFor( path: string, child: ReturnType, - timeoutMs = spendColdStartAllowance(), + timeoutMs = INTERNAL_DEADLINE_MS, ): Promise { const deadline = Date.now() + timeoutMs; while (Date.now() < deadline) { diff --git a/tests/codex-integration/native-main-owner-lifetime.test.ts b/tests/codex-integration/native-main-owner-lifetime.test.ts index cade269ab1..1bca364f8b 100644 --- a/tests/codex-integration/native-main-owner-lifetime.test.ts +++ b/tests/codex-integration/native-main-owner-lifetime.test.ts @@ -12,7 +12,6 @@ import { import { tmpdir } from "node:os"; import { join, resolve } from "node:path"; import { watchdogMs } from "../helpers/ci-watchdog"; -import { COLD_SPAWN_BUDGET_MS } from "../helpers/test-budget"; import { saveConfig } from "../../src/config"; import { saveCodexAccountCredential } from "../../src/codex/account-store"; @@ -147,25 +146,6 @@ const OWNER_EVENT_WAIT_MS = watchdogMs(10_000); // drift apart again. const OWNER_LEASE_BUDGET_MS = Math.max(30_000, OWNER_EVENT_WAIT_MS * 4); -/** - * Windows cold start of this file's FIRST child, spent once, per the contract on - * {@link COLD_SPAWN_BUDGET_MS}. - * - * `watchdogMs(10_000)` sizes every wait in this file for a child that is already able to - * answer. The first one is not: it boots Bun, imports the server graph, and binds a port, and - * the constant records that first child taking 50.7 s where the next spawn in the same file was - * ready in 1.76 s. On run 35210400258 (windows 7/9) the very first wait of a case -- for - * `listening` -- expired with no events at all. Every later wait keeps the watchdog bound, - * because by then the cold start has already been paid and a slow answer means something else. - */ -let ownerColdStartUnspent = true; - -function spendOwnerColdStartAllowance(): number { - if (!ownerColdStartUnspent) return OWNER_EVENT_WAIT_MS; - ownerColdStartUnspent = false; - return Math.max(OWNER_EVENT_WAIT_MS, COLD_SPAWN_BUDGET_MS); -} - async function waitUntil(probe: () => T | null, timeoutMs = OWNER_EVENT_WAIT_MS): Promise { const deadline = Date.now() + timeoutMs; while (Date.now() < deadline) { @@ -226,7 +206,7 @@ class ChildHarness { })(); } - async waitFor(predicate: (event: Event) => boolean, timeoutMs = spendOwnerColdStartAllowance()): Promise { + async waitFor(predicate: (event: Event) => boolean, timeoutMs = OWNER_EVENT_WAIT_MS): Promise { const deadline = Date.now() + timeoutMs; for (;;) { const found = this.events.find(predicate);