mirror of
https://github.com/dtzp555-max/ocp.git
synced 2026-07-27 07:55:07 +00:00
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:
+29
-9
@@ -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"),
|
||||||
|
|||||||
Reference in New Issue
Block a user