From 7eeb2230ea86a00c21a1b2add31cff3af68421f3 Mon Sep 17 00:00:00 2001 From: dtzp555 Date: Mon, 27 Jul 2026 08:43:42 +1000 Subject: [PATCH] test: harden and instrument the ltBoot integration tests (#203, #199) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit I could NOT reproduce either flake, and this commit does not claim to have root-caused them. Stating that plainly up front, because a "fix" for an unreproduced fault is a placebo unless you say what it actually is. What I tried, all negative: - 150 targeted runs of the #203 boot-gate scenario in isolation (25 rounds x 3 cases, with and without 8 CPU hogs) -> 0 failures - 6 consecutive full-suite runs -> 0 failures - a direct test of the exit-before-stdio-drain hypothesis (40 spawns writing a stderr burst then exiting) -> 0 races - a direct test of the port-clash hypothesis: with the port already held, the boot gate still fires FIRST and stderr still carries the FATAL, so a clash cannot produce the observed empty-stderr signature So instead of guessing a cause, this removes the mechanisms that were individually defensible anyway, and makes the next occurrence self-diagnosing. 1. Wait for 'close', not 'exit', wherever a test reads buf.err/buf.out after the child terminates. 'exit' fires on process termination while its stdio pipes may still hold unread data; 'close' is the event that guarantees both are drained. I could not get this to race locally, but the ordering is simply correct and costs nothing — and it exactly matches #203's signature (non-zero exit, EMPTY stderr). 2. Stop gating on a proxy signal. The #199 test waited for "listening on" and then asserted a DIFFERENT line ("ignored in TUI mode") that is written independently — a race by construction. It now waits for the line actually under assertion, still bounded by the same timeout, with the boot markers kept in the predicate so a failed boot ends the wait immediately. 3. Every fixed port is gone. All 10 ltBoot sites and their 8 matching ltPost calls now use ltFreePort(). #193 already hit a fixed-port variant of this, and 39330+i in particular was shared across a 3-iteration loop. 4. ltBoot now tracks signal/closed/spawnErr, and an 'error' listener is attached — without one, a spawn error is re-thrown as an uncaught exception and takes down the whole runner instead of failing one test. 5. New ltDiag(buf) is used in every assertion message. The historical failure text was `expected a local-tools FATAL, got: ` — an empty string, which distinguishes nothing. Both mutations below now produce an immediately readable cause: gate neutered -> "[non-loopback] process never closed — exit=undefined signal=undefined closed=false | stderr(92B)=... | stdout(1147B)=..." (it booted; the gate is gone) warning renamed -> "no inert-flag warning appeared — ... stderr(295B)= \"⚠ OCP_LOCAL_TOOLS=1 is SILENCED-FOR-MUTATION ...\"" (the text changed, and you can see the new text) Both target tests remain mutation-proven: neutering the non-loopback branch of localToolsSafetyError fails the boot-gate test, and renaming the TUI inert warning fails the inert test. Stability after the change: 4 sequential + 3 concurrent full-suite runs, all 457/0. That shows no regression was introduced; it does NOT show the flakes are gone, since I never reproduced them. #203 and #199 should stay open until a run passes through this instrumentation and reports what it saw. Tests: 457 passed, 0 failed. No production code touched. Co-Authored-By: Claude Opus 5 (1M context) Claude-Session: https://claude.ai/code/session_017gbqUZ8HfBZpjjbzQ85oH8 --- test-features.mjs | 94 ++++++++++++++++++++++++++++++++--------------- 1 file changed, 65 insertions(+), 29 deletions(-) diff --git a/test-features.mjs b/test-features.mjs index c157ffd..e6bfd64 100644 --- a/test-features.mjs +++ b/test-features.mjs @@ -991,12 +991,29 @@ function ltBoot(env, dir, nodeArgs = []) { CLAUDE_BIND: "127.0.0.1", CLAUDE_AUTH_MODE: "none", CLAUDE_CACHE_TTL: "0", CLAUDE_TIMEOUT: "4000", ...env }, stdio: ["ignore", "pipe", "pipe"], }); - const buf = { out: "", err: "", exit: undefined }; + const buf = { out: "", err: "", exit: undefined, signal: undefined, closed: false, spawnErr: null }; child.stdout.on("data", d => { buf.out += d; }); child.stderr.on("data", d => { buf.err += d; }); - child.on("exit", code => { buf.exit = code; }); + // 'exit' fires when the process terminates, but its stdio pipes may still hold unread data — + // 'close' is the one that guarantees both are drained. A test that terminates the child and + // then asserts on buf.err/buf.out must wait for `closed`, not `exit != null`, or it can read + // an empty buffer. See ltAssertBoot below. + child.on("exit", (code, signal) => { buf.exit = code; buf.signal = signal; }); + child.on("close", () => { buf.closed = true; }); + // Without a listener, a spawn 'error' is re-thrown as an uncaught exception and takes down the + // whole runner instead of failing one test. + child.on("error", e => { buf.spawnErr = e; }); return { child, buf }; } +// Every ltBoot assertion failure should be self-diagnosing. The historical failure text was +// `expected a local-tools FATAL, got: ` — an empty string, which says nothing about whether the +// child never wrote, wrote to the other stream, died on a signal, or was never spawned. +function ltDiag(buf) { + return `exit=${buf.exit} signal=${buf.signal} closed=${buf.closed}` + + (buf.spawnErr ? ` spawnErr=${buf.spawnErr.code || buf.spawnErr.message}` : "") + + ` | stderr(${buf.err.length}B)=${JSON.stringify(buf.err.slice(0, 200))}` + + ` | stdout(${buf.out.length}B)=${JSON.stringify(buf.out.slice(-200))}`; +} async function ltWait(cond, ms = 9000) { const start = Date.now(); while (Date.now() - start < ms) { if (cond()) return true; await new Promise(r => setTimeout(r, 40)); } @@ -1015,10 +1032,11 @@ console.log("\nOCP_LOCAL_TOOLS integration (boot server.mjs):"); test("integration: OCP_LOCAL_TOOLS=1 → the -p spawn receives the POSITIVE wrapper (kills the no-op mutation)", async () => { if (!LT_POSIX) return; // sh fake — skip on Windows CI const dir = ltMkdir(); const cap = join(dir, "sp.txt"); const fake = ltFake(dir); - const { child, buf } = ltBoot({ OCP_LOCAL_TOOLS: "1", CLAUDE_BIN: fake, CLAUDE_PROXY_PORT: "39321", SP_CAPTURE: cap }, dir); + const port = await ltFreePort(); + const { child, buf } = ltBoot({ OCP_LOCAL_TOOLS: "1", CLAUDE_BIN: fake, CLAUDE_PROXY_PORT: String(port), SP_CAPTURE: cap }, dir); try { assert.ok(await ltWait(() => buf.out.includes("listening on") || buf.exit != null), `server did not start: ${buf.err.slice(0,200)}`); - await ltPost(39321, { model: "sonnet", messages: [{ role: "user", content: "hi" }] }); + await ltPost(port, { model: "sonnet", messages: [{ role: "user", content: "hi" }] }); assert.ok(await ltWait(() => _ltExists(cap)), "fake claude was spawned and captured --system-prompt"); const sp = _ltRead(cap, "utf8"); assert.ok(sp.includes(LT_POS_MARK), `expected POSITIVE wrapper in --system-prompt, got: ${sp.slice(0,90)}`); @@ -1029,10 +1047,11 @@ test("integration: OCP_LOCAL_TOOLS=1 → the -p spawn receives the POSITIVE wrap test("integration: flag OFF → the -p spawn receives the EXACT negative wrapper (default path byte-for-byte)", async () => { if (!LT_POSIX) return; const dir = ltMkdir(); const cap = join(dir, "sp.txt"); const fake = ltFake(dir); - const { child, buf } = ltBoot({ CLAUDE_BIN: fake, CLAUDE_PROXY_PORT: "39322", SP_CAPTURE: cap }, dir); // OCP_LOCAL_TOOLS unset + const port = await ltFreePort(); + const { child, buf } = ltBoot({ CLAUDE_BIN: fake, CLAUDE_PROXY_PORT: String(port), SP_CAPTURE: cap }, dir); // OCP_LOCAL_TOOLS unset try { assert.ok(await ltWait(() => buf.out.includes("listening on") || buf.exit != null), `server did not start: ${buf.err.slice(0,200)}`); - await ltPost(39322, { model: "sonnet", messages: [{ role: "user", content: "hi" }] }); + await ltPost(port, { model: "sonnet", messages: [{ role: "user", content: "hi" }] }); assert.ok(await ltWait(() => _ltExists(cap)), "fake claude captured --system-prompt"); const sp = _ltRead(cap, "utf8"); // No system messages + no CLAUDE_SYSTEM_PROMPT → the wrapper is passed verbatim. @@ -1049,12 +1068,15 @@ test("integration: boot gate REFUSES each unsafe config (multi / non-loopback / { label: "anon", env: { PROXY_ANONYMOUS_KEY: "pub" } }, ]; try { - for (const [i, c] of cases.entries()) { - const { child, buf } = ltBoot({ OCP_LOCAL_TOOLS: "1", CLAUDE_BIN: fake, CLAUDE_PROXY_PORT: String(39330 + i), ...c.env }, dir); + for (const c of cases) { + const port = await ltFreePort(); + const { child, buf } = ltBoot({ OCP_LOCAL_TOOLS: "1", CLAUDE_BIN: fake, CLAUDE_PROXY_PORT: String(port), ...c.env }, dir); try { - assert.ok(await ltWait(() => buf.exit != null), `[${c.label}] expected the process to exit`); - assert.notEqual(buf.exit, 0, `[${c.label}] must exit non-zero`); - assert.ok(/FATAL[\s\S]*OCP_LOCAL_TOOLS/.test(buf.err), `[${c.label}] expected a local-tools FATAL, got: ${buf.err.slice(0,160)}`); + // Wait for `closed`, not `exit`: the assertion below reads buf.err, and stderr is only + // guaranteed drained at 'close'. This is the ordering #203 was filed for. + assert.ok(await ltWait(() => buf.closed), `[${c.label}] process never closed — ${ltDiag(buf)}`); + assert.notEqual(buf.exit, 0, `[${c.label}] must exit non-zero — ${ltDiag(buf)}`); + assert.ok(/FATAL[\s\S]*OCP_LOCAL_TOOLS/.test(buf.err), `[${c.label}] expected a local-tools FATAL — ${ltDiag(buf)}`); } finally { child.kill("SIGKILL"); } } } finally { _ltRm(dir, { recursive: true, force: true }); } @@ -1063,7 +1085,8 @@ test("integration: boot gate REFUSES each unsafe config (multi / non-loopback / test("integration: safe single-user config BOOTS past the gate and announces local tools", async () => { if (!LT_POSIX) return; const dir = ltMkdir(); const fake = ltFake(dir); - const { child, buf } = ltBoot({ OCP_LOCAL_TOOLS: "1", CLAUDE_BIN: fake, CLAUDE_PROXY_PORT: "39340" }, dir); // loopback + none + const port = await ltFreePort(); + const { child, buf } = ltBoot({ OCP_LOCAL_TOOLS: "1", CLAUDE_BIN: fake, CLAUDE_PROXY_PORT: String(port) }, dir); // loopback + none try { assert.ok(await ltWait(() => buf.out.includes("listening on")), `safe config must boot, got: ${buf.err.slice(0,200)}`); assert.ok(buf.out.includes("Local tools: ON"), "startup must announce local tools when active"); @@ -1075,11 +1098,21 @@ test("integration: TUI mode → flag is announced INERT (not 'ON'), boot not ref const dir = ltMkdir(); const fake = ltFake(dir); // Non-loopback would normally trip the local-tools gate; under TUI the flag is inert so the // gate must NOT fire on its behalf. Use loopback here to isolate TUI's own guards from ours. - const { child, buf } = ltBoot({ OCP_LOCAL_TOOLS: "1", CLAUDE_TUI_MODE: "true", CLAUDE_BIN: fake, CLAUDE_PROXY_PORT: "39341" }, dir); + const port = await ltFreePort(); + const { child, buf } = ltBoot({ OCP_LOCAL_TOOLS: "1", CLAUDE_TUI_MODE: "true", CLAUDE_BIN: fake, CLAUDE_PROXY_PORT: String(port) }, dir); try { - assert.ok(await ltWait(() => buf.out.includes("listening on") || buf.exit != null), `did not start: ${buf.err.slice(0,200)}`); - assert.ok(!buf.out.includes("Local tools: ON"), "must NOT claim local tools are ON in TUI mode (the wrapper is unused there)"); - assert.ok(/ignored in TUI mode/.test(buf.out + buf.err), "must warn that OCP_LOCAL_TOOLS is inert under TUI"); + // Wait for the line actually under assertion, not for a proxy signal. "listening on" and the + // inert-flag warning are written independently, so gating on the former and then asserting + // the latter is a race — the flake #199 was filed for. Still bounded by the same timeout, and + // the boot markers are kept in the predicate so a failed boot ends the wait immediately + // rather than burning it. + const ready = await ltWait(() => /ignored in TUI mode/.test(buf.out + buf.err) + || buf.closed || buf.spawnErr); + assert.ok(ready, `no inert-flag warning appeared — ${ltDiag(buf)}`); + assert.ok(/ignored in TUI mode/.test(buf.out + buf.err), + `must warn that OCP_LOCAL_TOOLS is inert under TUI — ${ltDiag(buf)}`); + assert.ok(!buf.out.includes("Local tools: ON"), + `must NOT claim local tools are ON in TUI mode (the wrapper is unused there) — ${ltDiag(buf)}`); } finally { child.kill("SIGKILL"); _ltRm(dir, { recursive: true, force: true }); } }); @@ -1098,8 +1131,8 @@ test("integration: toggling OCP_LOCAL_TOOLS invalidates the standard response ca } finally { child.kill("SIGKILL"); } }; try { - const off = await bootOnce({}, 39350); // caches "OK" under epoch(negative) - const on = await bootOnce({ OCP_LOCAL_TOOLS: "1" }, 39351); // same DB, epoch(positive) → must MISS → re-spawn + const off = await bootOnce({}, await ltFreePort()); // caches "OK" under epoch(negative) + const on = await bootOnce({ OCP_LOCAL_TOOLS: "1" }, await ltFreePort()); // same DB, epoch(positive) → must MISS → re-spawn assert.equal(off, 1, "first request (cache empty) must spawn claude"); assert.equal(on, 1, "after toggling the flag the identical request must NOT be served from the old cache (epoch differs → re-spawn)"); } finally { _ltRm(dir, { recursive: true, force: true }); } @@ -1219,14 +1252,15 @@ console.log("\nCache key resolves the model alias (#194):"); test("integration: an alias and its canonical target share ONE cache slot (normal path)", async () => { if (!LT_POSIX) return; const dir = ltMkdir(); const fake = ltFake(dir); const counter = join(dir, "spawns.txt"); - const { child, buf } = ltBoot({ CLAUDE_BIN: fake, CLAUDE_PROXY_PORT: "39360", CLAUDE_CACHE_TTL: "60000", SP_COUNTER: counter }, dir); + const port = await ltFreePort(); + const { child, buf } = ltBoot({ CLAUDE_BIN: fake, CLAUDE_PROXY_PORT: String(port), CLAUDE_CACHE_TTL: "60000", SP_COUNTER: counter }, dir); try { assert.ok(await ltWait(() => buf.out.includes("listening on")), `did not start: ${buf.err.slice(0, 200)}`); _ltWrite(counter, "0"); const msgs = [{ role: "user", content: "alias-resolution-probe" }]; - await ltPost(39360, { model: "sonnet", messages: msgs }); // miss → spawn + await ltPost(port, { model: "sonnet", messages: msgs }); // miss → spawn await ltWait(() => (Number(_ltRead(counter, "utf8")) || 0) >= 1, 3000); - await ltPost(39360, { model: "claude-sonnet-5", messages: msgs }); // same resolved model → HIT + await ltPost(port, { model: "claude-sonnet-5", messages: msgs }); // same resolved model → HIT await new Promise(r => setTimeout(r, 600)); assert.equal(Number(_ltRead(counter, "utf8")) || 0, 1, "the canonical id must hit the slot the alias populated — a 2nd spawn means the key still hashes the raw alias"); @@ -1236,15 +1270,16 @@ test("integration: an alias and its canonical target share ONE cache slot (norma test("integration: an alias and its canonical target share ONE cache slot (STRUCTURED path)", async () => { if (!LT_POSIX) return; const dir = ltMkdir(); const fake = ltFakeJson(dir); const counter = join(dir, "spawns.txt"); - const { child, buf } = ltBoot({ CLAUDE_BIN: fake, CLAUDE_PROXY_PORT: "39361", CLAUDE_CACHE_TTL: "60000", SP_COUNTER: counter }, dir); + const port = await ltFreePort(); + const { child, buf } = ltBoot({ CLAUDE_BIN: fake, CLAUDE_PROXY_PORT: String(port), CLAUDE_CACHE_TTL: "60000", SP_COUNTER: counter }, dir); try { assert.ok(await ltWait(() => buf.out.includes("listening on")), `did not start: ${buf.err.slice(0, 200)}`); _ltWrite(counter, "0"); const rf = { type: "json_schema", json_schema: { name: "probe", schema: LT_SCHEMA } }; const msgs = [{ role: "user", content: "structured-alias-probe" }]; - await ltPost(39361, { model: "sonnet", messages: msgs, response_format: rf }); + await ltPost(port, { model: "sonnet", messages: msgs, response_format: rf }); await ltWait(() => (Number(_ltRead(counter, "utf8")) || 0) >= 1, 4000); - await ltPost(39361, { model: "claude-sonnet-5", messages: msgs, response_format: rf }); + await ltPost(port, { model: "claude-sonnet-5", messages: msgs, response_format: rf }); await new Promise(r => setTimeout(r, 600)); assert.equal(Number(_ltRead(counter, "utf8")) || 0, 1, "structured cache key must resolve the alias too — this is the path the epoch-only fix missed"); @@ -1257,14 +1292,15 @@ test("integration: an alias and its canonical target share ONE cache slot (STRUC test("integration: a legacyAlias shares ONE cache slot with its canonical target", async () => { if (!LT_POSIX) return; const dir = ltMkdir(); const fake = ltFake(dir); const counter = join(dir, "spawns.txt"); - const { child, buf } = ltBoot({ CLAUDE_BIN: fake, CLAUDE_PROXY_PORT: "39364", CLAUDE_CACHE_TTL: "60000", SP_COUNTER: counter }, dir); + const port = await ltFreePort(); + const { child, buf } = ltBoot({ CLAUDE_BIN: fake, CLAUDE_PROXY_PORT: String(port), CLAUDE_CACHE_TTL: "60000", SP_COUNTER: counter }, dir); try { assert.ok(await ltWait(() => buf.out.includes("listening on")), `did not start: ${buf.err.slice(0, 200)}`); _ltWrite(counter, "0"); const msgs = [{ role: "user", content: "legacy-alias-probe" }]; - await ltPost(39364, { model: "claude-haiku-4-5", messages: msgs }); // legacyAlias + await ltPost(port, { model: "claude-haiku-4-5", messages: msgs }); // legacyAlias await ltWait(() => (Number(_ltRead(counter, "utf8")) || 0) >= 1, 3000); - await ltPost(39364, { model: "claude-haiku-4-5-20251001", messages: msgs }); // canonical + await ltPost(port, { model: "claude-haiku-4-5-20251001", messages: msgs }); // canonical await new Promise(r => setTimeout(r, 600)); assert.equal(Number(_ltRead(counter, "utf8")) || 0, 1, "legacyAliases live in MODEL_MAP too — resolving must collapse them onto the canonical slot"); @@ -1287,8 +1323,8 @@ test("integration: a config change invalidates the STRUCTURED cache too (closes } finally { child.kill("SIGKILL"); } }; try { - const off = await bootOnce({}, 39362); // caches under epoch(negative wrapper) - const on = await bootOnce({ OCP_LOCAL_TOOLS: "1" }, 39363); // same DB, epoch differs → must re-spawn + const off = await bootOnce({}, await ltFreePort()); // caches under epoch(negative wrapper) + const on = await bootOnce({ OCP_LOCAL_TOOLS: "1" }, await ltFreePort()); // same DB, epoch differs → must re-spawn assert.equal(off, 1, "first structured request (cache empty) must spawn claude"); assert.equal(on, 1, "structured cache must honor CONFIG_EPOCH — before #194 it omitted the epoch entirely and served the stale answer"); } finally { _ltRm(dir, { recursive: true, force: true }); }