From 75ac3e45796fc43f132f452a5d6d0f05b90f5689 Mon Sep 17 00:00:00 2001 From: dtzp555 Date: Mon, 27 Jul 2026 12:20:26 +1000 Subject: [PATCH] test: land the comment fix that didn't, and size ltDiag's window to the banner MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit 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) Claude-Session: https://claude.ai/code/session_017gbqUZ8HfBZpjjbzQ85oH8 --- test-features.mjs | 38 +++++++++++++++++++++++++++++--------- 1 file changed, 29 insertions(+), 9 deletions(-) diff --git a/test-features.mjs b/test-features.mjs index b7be82b..c7caed8 100644 --- a/test-features.mjs +++ b/test-features.mjs @@ -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 }, 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.stderr.on("data", d => { buf.err += d; }); // '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 // an empty buffer. 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 // whole runner instead of failing one test. 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 // `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. +// 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) { - 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}` : "") + - ` | stderr(${buf.err.length}B)=${JSON.stringify(buf.err.slice(0, 200))}` + - ` | stdout(${buf.out.length}B)=${JSON.stringify(buf.out.slice(-200))}`; + ` | stderr(${buf.err.length}B)=${JSON.stringify(buf.err.slice(0, 240))}` + + ` | stdout(${buf.out.length}B)=${JSON.stringify(ltHeadTail(buf.out))}`; } async function ltWait(cond, ms = 9000) { 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 { child, buf } = ltBoot({ OCP_LOCAL_TOOLS: "1", CLAUDE_BIN: fake, CLAUDE_PROXY_PORT: String(port) }, dir); // loopback + none try { - // Same race as #199, one line over: "Local tools: ON" is written 14 console.log calls AFTER - // "listening on", so gating on the boot marker and then asserting the announcement can read a - // buffer holding only the first chunk. Wait for the line actually under assertion. Measured by - // review at 9/200 before this change and 0/200 after — it was the suite's top flake. + // Same race as #199, one line over: "Local tools: ON" (server.mjs:3640) is written 12 + // console.log calls after "listening on" (:3627) — 10 of them in this env, since the + // SYSTEM_PROMPT and MCP_CONFIG lines are conditional and unset here. Gating on the boot + // 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), `startup must announce local tools when active — ${ltDiag(buf)}`); assert.ok(buf.out.includes("Local tools: ON"),