taodeng/ocp
1
0
Fork 0
mirror of https://github.com/dtzp555-max/ocp.git synced 2026-07-27 07:55:07 +00:00
Code Issues Packages Projects Releases Wiki Activity

test: harden and instrument the ltBoot integration tests (#203, #199)

Browse Source 
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) <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_017gbqUZ8HfBZpjjbzQ85oH8
This commit is contained in:
taodeng
2026-07-27 12:18:11 +10:00
co-authored by Claude Opus 5
parent c180987376
commit 969f772834
1 changed files with 65 additions and 29 deletions
Download Patch File Download Diff File Expand all files Collapse all files
test-features.mjs
+65 -29
View File
@@ -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 }); }