test: land the comment fix that didn't, and size ltDiag's window to the banner

Two things, both caught by review of the previous commit.

1. The comment fix I claimed to have made never landed.

800800e's message said it corrected the console.log gap "14 -> 13". The diff has two
hunks (ltAssertBoot removal, LT_DEBUG catch) and never touches that line, so the
comment still read 14 — and 13 was wrong too, in units. Ground truth:

    server.mjs:3627  console.log(`... listening on ...`)
    server.mjs:3640  if (LOCAL_TOOLS_ACTIVE) console.log(`Local tools: ON ...`)
    strictly between: 12 console.log calls, of which :3635 (SYSTEM_PROMPT) and
    :3636 (MCP_CONFIG) are conditional and unset in this env -> 10 actually fire.

Now 12, with the conditional note. Also corrected 9/200 -> 8/200 on the same comment:
the control-arm table says 8, and the two disagreed.

2. ltDiag sampled stdout tail-only, which is the wrong end.

Review reversed its own earlier "leave it" with direct evidence: the mutation
diagnostic printed 1147B of tail and did NOT contain "Local tools: ON" — the single
most decisive string for "it booted instead of refusing". Fixed as head+tail.

Sizing is measured, not picked round. On this tree stdout is 1118B with the string at
byte 581, so:

    head=120  -> string lands in the elided middle. VERIFIED INSUFFICIENT.
    head=900  -> clears it with ~5 banner lines of margin.

900 is robust rather than merely bigger: the banner is emitted first and is bounded, so
however much request noise follows, byte 581 stays in the head. Demonstrated under the
gate mutation:

    stdout(1133B)="... Local tools: ON (OCP_LOCAL_TOOLS=1) — model told it may use
    local tools; single-user/loopback only ..."

Also folded in the two cheap #203 levers review listed, since the next step on that
issue is a Linux + Node 24 run:

- closeMs (stamped at 'close', not read at assertion time) separates "died before
  reaching the gate" from "ran, then gated" — exit=1 with empty stderr is equally
  consistent with both today. Prints "(still open)" when close never fired.
- node=${process.version} — exactly what would have flagged the Node 22 SQLite
  ExperimentalWarning before it cost 50 contaminated Oracle runs.

Mutation restored from a file backup, not `git checkout` — that command destroyed
uncommitted work earlier in this series.

server.mjs: unchanged (test-only; ALIGNMENT.md requires no cli.js citation).
Suite: 461 passed, 0 failed.

Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_017gbqUZ8HfBZpjjbzQ85oH8
This commit is contained in:
2026-07-27 12:20:26 +10:00
co-authored by Claude Opus 5
parent e08cb94faf
commit 75ac3e4579
+29 -9
View File
@@ -991,7 +991,7 @@ function ltBoot(env, dir, nodeArgs = []) {
CLAUDE_BIND: "127.0.0.1", CLAUDE_AUTH_MODE: "none", CLAUDE_CACHE_TTL: "0", CLAUDE_TIMEOUT: "4000", ...env }, CLAUDE_BIND: "127.0.0.1", CLAUDE_AUTH_MODE: "none", CLAUDE_CACHE_TTL: "0", CLAUDE_TIMEOUT: "4000", ...env },
stdio: ["ignore", "pipe", "pipe"], stdio: ["ignore", "pipe", "pipe"],
}); });
const buf = { out: "", err: "", exit: undefined, signal: undefined, closed: false, spawnErr: null }; const buf = { out: "", err: "", exit: undefined, signal: undefined, closed: false, spawnErr: null, t0: Date.now() };
child.stdout.on("data", d => { buf.out += d; }); child.stdout.on("data", d => { buf.out += d; });
child.stderr.on("data", d => { buf.err += d; }); child.stderr.on("data", d => { buf.err += d; });
// 'exit' fires when the process terminates, but its stdio pipes may still hold unread data — // 'exit' fires when the process terminates, but its stdio pipes may still hold unread data —
@@ -999,7 +999,7 @@ function ltBoot(env, dir, nodeArgs = []) {
// then asserts on buf.err/buf.out must wait for `closed`, not `exit != null`, or it can read // then asserts on buf.err/buf.out must wait for `closed`, not `exit != null`, or it can read
// an empty buffer. // an empty buffer.
child.on("exit", (code, signal) => { buf.exit = code; buf.signal = signal; }); child.on("exit", (code, signal) => { buf.exit = code; buf.signal = signal; });
child.on("close", () => { buf.closed = true; }); child.on("close", () => { buf.closed = true; buf.closeMs = Date.now() - buf.t0; });
// Without a listener, a spawn 'error' is re-thrown as an uncaught exception and takes down the // Without a listener, a spawn 'error' is re-thrown as an uncaught exception and takes down the
// whole runner instead of failing one test. // whole runner instead of failing one test.
child.on("error", e => { buf.spawnErr = e; }); child.on("error", e => { buf.spawnErr = e; });
@@ -1019,11 +1019,29 @@ function _ltRmRetry(dir) {
// Every ltBoot assertion failure should be self-diagnosing. The historical failure text was // 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 // `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. // child never wrote, wrote to the other stream, died on a signal, or was never spawned.
// stdout is sampled HEAD+TAIL, not tail-only. The decisive string for "it booted instead of
// refusing" is "Local tools: ON", and it lives in the boot banner — a tail-only sample answered
// the wrong question for exactly the tests this exists to diagnose.
//
// The head is sized to the BANNER, not picked round: measured on this tree, the banner runs 1118B
// with "Local tools: ON" at byte 581, so 900 clears it with ~5 banner lines of margin. That sizing
// is what makes it robust — the banner is emitted first and is bounded, so however much request
// noise follows, byte 581 stays in the head. A head of 120 does NOT reach it (verified: the string
// landed in the elided middle), which is why this is not the obvious small window.
// stderr stays head-only: a fatal is the first thing it writes.
function ltHeadTail(s, head = 900, tail = 160) {
return s.length <= head + tail ? s : `${s.slice(0, head)}…[${s.length - head - tail}B]…${s.slice(-tail)}`;
}
function ltDiag(buf) { function ltDiag(buf) {
return `exit=${buf.exit} signal=${buf.signal} closed=${buf.closed}` + // closeMs disambiguates "died before reaching the gate" from "ran, then gated" — an exit=1
// with empty stderr is equally consistent with both, and they have unrelated root causes.
// node= is here because a Node-version-specific stderr warning (22's SQLite ExperimentalWarning)
// once masqueraded as "server did not start" for ~23 of 50 runs on a Linux box.
const ms = buf.closeMs !== undefined ? `${buf.closeMs}ms` : (buf.t0 ? `${Date.now() - buf.t0}ms(still open)` : "?");
return `exit=${buf.exit} signal=${buf.signal} closed=${buf.closed} closeMs=${ms} node=${process.version}` +
(buf.spawnErr ? ` spawnErr=${buf.spawnErr.code || buf.spawnErr.message}` : "") + (buf.spawnErr ? ` spawnErr=${buf.spawnErr.code || buf.spawnErr.message}` : "") +
` | stderr(${buf.err.length}B)=${JSON.stringify(buf.err.slice(0, 200))}` + ` | stderr(${buf.err.length}B)=${JSON.stringify(buf.err.slice(0, 240))}` +
` | stdout(${buf.out.length}B)=${JSON.stringify(buf.out.slice(-200))}`; ` | stdout(${buf.out.length}B)=${JSON.stringify(ltHeadTail(buf.out))}`;
} }
async function ltWait(cond, ms = 9000) { async function ltWait(cond, ms = 9000) {
const start = Date.now(); const start = Date.now();
@@ -1106,10 +1124,12 @@ test("integration: safe single-user config BOOTS past the gate and announces loc
const port = await ltFreePort(); const port = await ltFreePort();
const { child, buf } = ltBoot({ OCP_LOCAL_TOOLS: "1", CLAUDE_BIN: fake, CLAUDE_PROXY_PORT: String(port) }, dir); // loopback + none const { child, buf } = ltBoot({ OCP_LOCAL_TOOLS: "1", CLAUDE_BIN: fake, CLAUDE_PROXY_PORT: String(port) }, dir); // loopback + none
try { try {
// Same race as #199, one line over: "Local tools: ON" is written 14 console.log calls AFTER // Same race as #199, one line over: "Local tools: ON" (server.mjs:3640) is written 12
// "listening on", so gating on the boot marker and then asserting the announcement can read a // console.log calls after "listening on" (:3627) — 10 of them in this env, since the
// buffer holding only the first chunk. Wait for the line actually under assertion. Measured by // SYSTEM_PROMPT and MCP_CONFIG lines are conditional and unset here. Gating on the boot
// review at 9/200 before this change and 0/200 after — it was the suite's top flake. // marker and then asserting the announcement can therefore read a buffer holding only the
// first chunk. Wait for the line actually under assertion. Measured by review at 8/200
// before this change and 0/200 after — it was the suite's top flake.
assert.ok(await ltWait(() => buf.out.includes("Local tools: ON") || buf.closed || buf.spawnErr), assert.ok(await ltWait(() => buf.out.includes("Local tools: ON") || buf.closed || buf.spawnErr),
`startup must announce local tools when active — ${ltDiag(buf)}`); `startup must announce local tools when active — ${ltDiag(buf)}`);
assert.ok(buf.out.includes("Local tools: ON"), assert.ok(buf.out.includes("Local tools: ON"),