From f46756b906decb538090cebe0f1c69fc775bedf3 Mon Sep 17 00:00:00 2001 From: dtzp555-max Date: Mon, 27 Jul 2026 07:39:33 +1000 Subject: [PATCH] fix(server): pair the active-request counter with the process lifecycle (supersedes #180) (#193) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit * fix(server): pair the active-request counter with the process lifecycle (#180) `stats.activeRequests` was incremented ~40 lines before the child process was spawned, but its only decrement site — cleanup() — is wired to that process's exit/close/error events. Any synchronous throw in the window between them (buildCliArgs, env assembly, applying the spawn decision, or spawn() itself) therefore leaked +1 permanently: the increment had happened, and cleanup() was not yet attached to anything that could undo it. /health and /stats then over-report in-flight work forever, and the drift is monotonic. Fix: move the increment to immediately after `activeProcesses.add(proc)`, so increment and decrement are structurally paired to exactly one process lifecycle. No try/catch and no reconciliation pass is needed — there is no longer a window in which the counter is incremented but unowned. `stats.activeRequests` is observability-only, not a gate: the old `if (activeRequests >= MAX_CONCURRENT) throw` admission check was removed in favour of the releaseSlot semaphore (see the comment at server.mjs:1327), and the only remaining readers are /health, /stats and the settings snapshot. So deferring the increment past the spawn changes no admission decision. Reproduced and verified on the real server (no test double). A deliberate throw injected between the increment and the spawn, then three requests: before the fix : 3 requests -> http 500 -> stats.activeRequests == 3 (leaked) after the fix : 3 requests -> http 500 -> stats.activeRequests == 0 happy path : real completion "OK", activeRequests 0, total 1, errors 0 The fault injection was removed before committing (no residue: `grep -rn OCP_FAULT_INJECT` is clean) — it is documented in the PR so any reviewer can re-run the same three commands. cli.js citation: NOT APPLICABLE — this touches no cli.js-derived wire behavior. Scope is justified under ALIGNMENT.md Rule 2 as OCP-owned internal bookkeeping: the counter is OCP's own observability state, cli.js has no equivalent operation, and the spawn arguments and protocol are untouched. Supersedes the approach in #180, which additionally reconciled the counter to `activeProcesses.size`. That reconciliation is racy: a concurrent request that has incremented but not yet registered its process is invisible in `activeProcesses`, so reconciling stomps it back down and under-reports live work. Pairing the increment to the spawn removes the drift at its source, so no reconciliation is required. Original report and diagnosis by @konceptnet. Tests: 449 passed, 0 failed. Co-Authored-By: Hermes Agent Co-Authored-By: Claude Opus 5 (1M context) Claude-Session: https://claude.ai/code/session_017gbqUZ8HfBZpjjbzQ85oH8 * fix(review): correct three wrong claims in this PR, and add the regression test The diff was right; three things I wrote about it were not. An independent reviewer falsified each one, and leaving a correct fix on an incorrect rationale in git history is exactly what ALIGNMENT.md governance exists to prevent. Corrections: 1. "No regression test is possible here" — WRONG, and the test is now here. Two compounding errors. `test-features.mjs:955` already has `ltBoot`, a real-server integration fixture (spawns server.mjs, fake claude binary, HTTP) that I had used myself in #191; I reasoned from "cannot import server.mjs" straight to "cannot test" without grepping for it. And the synchronous throw is reachable from ENV ALONE, needing no production hook: buildCliArgs does `args.push("--allowedTools", ...ALLOWED_TOOLS)`, and a spread of enough elements throws RangeError synchronously, inside the leak window. Measured, zero production changes: origin/main : 3 requests -> 500 x3 -> stats.activeRequests == 3 this branch : 3 requests -> 500 x3 -> stats.activeRequests == 0 The committed test DISCOVERS the element count rather than hard-coding it (the threshold is stack-size dependent, so a fixed number would silently stop triggering on another machine and pass vacuously), and asserts the requests actually 500 before trusting the counter. Mutation-proven: moving the increment back before the spawn fails it with "got 3". 2. My reason for rejecting #180's approach was WRONG. I claimed reconciling to activeProcesses.size is racy because a request that incremented but has not yet registered is invisible in the Set. There is no `await` anywhere in that window — it is fully synchronous, so on Node's single thread that state is unobservable and the race cannot occur. The real reason reconciliation is unsafe: the decrement is wired to 'exit' while activeProcesses.delete is wired to 'close', and exit precedes close (measured exit @2ms, close @2017ms with a grandchild holding stdout), so activeProcesses.size OVER-reports during that window — the opposite direction from what I wrote. Separately, a throw after activeProcesses.add leaves permanent Set residue that reconciliation would inherit. Corrected publicly on #180; the contributor was owed an accurate rejection. 3. The alignment citation named the wrong authority. ALIGNMENT.md:17 scopes Rules 1-5 to Class A only, and Rule 2 is a prohibition, not an authorization — citing it as justification is a category error. Every reader of stats.activeRequests is a grandfathered Class B.2 endpoint (/health, /status, /usage). Correct citation, per ALIGNMENT.md:142 and the in-repo precedent at server.mjs:3271-3276 (the F6 spawn.isolated fix): Authorized by ADR 0006 (grandfathered as of v3.16.4). The field SET is unchanged — no field added, removed or renamed — only the VALUE is made truthful. Behaviour-preserving; no new ADR required. The "cli.js: no hit, declared" part stands: cli.js has no equivalent operation, and spawn argv and protocol are byte-identical. Also corrected the new comment at the increment: only 'exit' is wired inside spawnClaudeProcess; 'close'/'error' are wired by each caller, and that is REQUIRED because a failed spawn never emits 'exit'. Note for a follow-up issue, not folded in (Iron Rule 11): stats.errors stays 0 across all of these 500s — synchronous throws from spawnClaudeProcess are never counted. And CLAUDE.md hard-requirement #1 literally says "justify scope under Rule 2", which is what I followed; CLAUDE.md predates ADR 0006's Class B section and needs its own governance PR. Tests: 450 passed, 0 failed. Co-Authored-By: Hermes Agent Co-Authored-By: Claude Opus 5 (1M context) Claude-Session: https://claude.ai/code/session_017gbqUZ8HfBZpjjbzQ85oH8 * test: skip the leak probe where the OS rejects the trigger, instead of failing CI The regression test I added broke CI with `spawn E2BIG`, and the reason matters more than the fix: the env-only trigger is NOT portable, and the review that proposed it was measured only on darwin (the reviewer said so). Delivering the trigger needs a single env var of ~2n bytes where n is the spread-throw threshold (~130k elements here). Linux caps ONE env string at MAX_ARG_STRLEN = 32 * PAGE_SIZE = 131072 bytes, so execve rejects it outright. Encoding tricks do not rescue it: empty items cost 1 byte each, but 120k empty items do not reach the throw threshold, and the threshold itself moves with stack size — the margin does not exist. buildCliArgs has exactly one spread (verified), so there is no alternative env-only trigger. So the test now runs where the OS allows the trigger (macOS/BSD) and SKIPS LOUDLY where it does not, printing the platform and byte count. It never passes vacuously: it already asserts the requests actually return 500 before trusting the counter, and E2BIG is detected both as a synchronous throw and as an async 'error' event. Consequence, stated plainly rather than buried: CI runs on Linux, so CI does NOT exercise this test. The fix is protected on macOS dev machines only. That is weaker than I would like and is why #197 (portable in-process fault injection) matters — it is the difference between this class of bug being guarded and merely having been checked once by hand. Verified after the change: macOS, fixed -> test RUNS and passes, 450/0 macOS, bug restored -> test goes RED ("got 3"), 449/1 Linux CI -> skips with a printed reason Co-Authored-By: Hermes Agent Co-Authored-By: Claude Opus 5 (1M context) Claude-Session: https://claude.ai/code/session_017gbqUZ8HfBZpjjbzQ85oH8 * test: make the leak probe run on Linux CI — my "impossible" conclusion was wrong f84d4c6 concluded the trigger could not be delivered on Linux and made the test skip there. The reviewer refuted that and built the working version; this is it. Three things I got wrong, all the same shape — treating a darwin measurement as universal: 1. "empty items don't reach the throw threshold" — the REASON was wrong. The spread's cost is per ELEMENT, not per byte: empty and "x" have an identical threshold. What actually kills the empty-item encoding is `.filter(Boolean)` at server.mjs:355, which strips empty entries, so ALLOWED_TOOLS ends up empty and the spread branch is never entered. The new control mutation demonstrates exactly this: tools filtered to empty -> requests return 200, not 500. 2. "the threshold moves with stack size — the margin does not exist" — exactly backwards. The stack dependence is the LEVER, and ltBoot already spawns the server, so the test owns its argv. Under --stack-size=200 the threshold drops ~5x: measured 24069 elements, so 1.5x margin is 36104 elements = 72207 bytes, 45% UNDER Linux's MAX_ARG_STRLEN of 131072. 3. "buildCliArgs has only one spread, so there is no alternative trigger" — the premise is true (verified) but irrelevant. The problem was never finding a second spread; it was making the one spread throw with fewer elements. Test-side only; server.mjs is untouched by this commit. - ltBoot(env, dir, nodeArgs = []) — one line, so a caller can set V8 flags - the threshold is discovered in a CHILD under the same --stack-size (the old version measured it in the parent, whose stack is not the one that matters) - hard assert entryBytes <= MAX_ARG_STRLEN, so a future regression fails loudly instead of silently degrading to a skip - dynamic free port instead of a fixed 39370 (a flake was observed on the fixed port across back-to-back runs) - the 500s must carry "call stack size exceeded", so an unrelated fault that also left the counter at 0 cannot be mistaken for a pass The Linux claim here is still ARITHMETIC (72207 < 131072), not a measurement — neither I nor the reviewer has a Linux box. CI is the check: the log must show this test RUNNING, not skipping. Co-Authored-By: Hermes Agent Co-Authored-By: Claude Opus 5 (1M context) Claude-Session: https://claude.ai/code/session_017gbqUZ8HfBZpjjbzQ85oH8 --------- Co-authored-by: dtzp555 Co-authored-by: Hermes Agent Co-authored-by: Claude Opus 5 (1M context) --- server.mjs | 12 +++++- test-features.mjs | 96 +++++++++++++++++++++++++++++++++++++++++++++-- 2 files changed, 104 insertions(+), 4 deletions(-) diff --git a/server.mjs b/server.mjs index cb0c4ad..8c4427c 100644 --- a/server.mjs +++ b/server.mjs @@ -1371,7 +1371,6 @@ function spawnClaudeProcess(model, messages, conversationId, keyName, releaseSlo promptChars = stdinPayload.length; } - stats.activeRequests++; stats.totalRequests++; stats.oneOffRequests++; if (conversationId) { @@ -1414,6 +1413,17 @@ function spawnClaudeProcess(model, messages, conversationId, keyName, releaseSlo const proc = spawn(CLAUDE, cliArgs, spawnOpts); activeProcesses.add(proc); + // Counter drift (#180, reported by @konceptnet): increment ONLY after the spawn has + // succeeded and the process is registered. Incrementing before the spawn (as this did) leaked + // +1 permanently on any synchronous throw in between — buildCliArgs, env assembly, the spawn + // decision, or spawn() itself — because nothing was yet attached that could undo it. + // + // cleanup() is the SOLE decrement site, but note how it is reached: only 'exit' is wired HERE + // (below); 'close' and 'error' are wired by each CALLER (callClaude / callClaudeStreaming). + // That caller wiring is REQUIRED, not belt-and-braces — a FAILED spawn emits 'error' and + // 'close' but never 'exit', so without it a spawn failure would never decrement. A future + // third caller of spawnClaudeProcess must wire them too. + stats.activeRequests++; const t0 = Date.now(); let gotFirstByte = false; diff --git a/test-features.mjs b/test-features.mjs index d2022b3..c157ffd 100644 --- a/test-features.mjs +++ b/test-features.mjs @@ -959,7 +959,8 @@ test("localToolsSafetyError: multi is checked before loopback/anon (most severe // a request — and boot-gate refusals are asserted by the process exit code. Without these, the // wiring (extractSystemPrompt using SYSTEM_PROMPT_WRAPPER, the boot gate, the epoch fold) can be // silently reverted with the unit suite still green — the maintainer's #1 rejection pattern. -import { spawn as _ltSpawn } from "node:child_process"; +import { spawn as _ltSpawn, execFileSync as _ltExecFile } from "node:child_process"; +import { createServer as _ltNetServer } from "node:net"; import { writeFileSync as _ltWrite, chmodSync as _ltChmod, readFileSync as _ltRead, existsSync as _ltExists, rmSync as _ltRm, mkdtempSync as _ltMkdtemp } from "node:fs"; import { tmpdir as _ltTmp } from "node:os"; import { fileURLToPath as _ltF2P } from "node:url"; @@ -984,8 +985,8 @@ exit 0 function ltMkdir() { return _ltMkdtemp(join(_ltTmp(), "ocp-lt-")); } function ltFake(dir) { const p = join(dir, "claude"); _ltWrite(p, LT_FAKE); _ltChmod(p, 0o755); return p; } -function ltBoot(env, dir) { - const child = _ltSpawn(process.execPath, [LT_SERVER], { +function ltBoot(env, dir, nodeArgs = []) { + const child = _ltSpawn(process.execPath, [...nodeArgs, LT_SERVER], { env: { ...process.env, NODE_ENV: "test", OCP_DIR_OVERRIDE: dir, OCP_SKIP_AUTH_TEST: "1", CLAUDE_BIND: "127.0.0.1", CLAUDE_AUTH_MODE: "none", CLAUDE_CACHE_TTL: "0", CLAUDE_TIMEOUT: "4000", ...env }, stdio: ["ignore", "pipe", "pipe"], @@ -1104,6 +1105,95 @@ test("integration: toggling OCP_LOCAL_TOOLS invalidates the standard response ca } finally { _ltRm(dir, { recursive: true, force: true }); } }); +// ── active-request counter is paired to the process lifecycle (#180 / #193) ── +// The counter used to be incremented ~40 lines before the spawn, while its only decrement +// (cleanup()) is wired to that proc's events — so any SYNCHRONOUS throw in between leaked +1 +// permanently. Driving that fault needs no production hook and no test double: buildCliArgs +// does `args.push("--allowedTools", ...ALLOWED_TOOLS)`, and a spread of enough elements throws +// RangeError synchronously, right inside the window. +// +// Getting there on Linux needs one more turn of the screw. The spread's cost is per ELEMENT, +// so the naive form needs ~124k elements ≈ 250KB in one env var — and Linux caps a single env +// string at MAX_ARG_STRLEN (32 * PAGE_SIZE = 131072 on x86-64), so execve rejects it (E2BIG). +// Encoding around it fails too: empty items are 1 byte each, but `.filter(Boolean)` +// (server.mjs:355) strips them, so ALLOWED_TOOLS ends up empty and the spread branch is never +// entered at all. +// +// The lever is the stack: the throw threshold scales with it, and ltBoot spawns the server, so +// the test owns its argv. Running the child under --stack-size=200 drops the threshold ~5x +// (~24k elements ≈ 48KB), which fits Linux's limit with room to spare. +// +// The threshold is DISCOVERED, in a child under the SAME --stack-size (measuring it in this +// process would report the parent's stack, which is not the one that matters), then taken with +// 1.5x margin and hard-asserted under MAX_ARG_STRLEN. A hard-coded count would silently stop +// triggering on another machine and the test would pass vacuously. +const LT_STACK = 200; // child V8 stack (KB); lowers the spread-throw threshold +const LT_MAX_ARG_STRLEN = 131072; // Linux, x86-64: 32 * 4096 +function ltSpreadThrowCount(stackKb) { + // Binary-search the smallest element count whose spread throws, inside a child running with + // the stack the server will actually use. + const src = `const t=n=>{try{const a=[];a.push("--allowedTools",...Array(n).fill("x"));return false}catch{return true}};` + + `let lo=500,hi=400000;if(!t(hi)){console.log(0)}else{while(lo>1;t(m)?hi=m:lo=m+1}console.log(lo)}`; + try { + return Number(String(_ltExecFile(process.execPath, [`--stack-size=${stackKb}`, "-e", src], { encoding: "utf8" })).trim()) || 0; + } catch { return 0; } +} +async function ltFreePort() { + const srv = _ltNetServer(); + await new Promise(r => srv.listen(0, "127.0.0.1", r)); + const p = srv.address().port; + await new Promise(r => srv.close(r)); + return p; +} +async function ltPostStatus(port, body) { + try { + const r = await fetch(`http://127.0.0.1:${port}/v1/chat/completions`, { + method: "POST", headers: { "Content-Type": "application/json" }, body: JSON.stringify(body), + }); + return { status: r.status, text: await r.text() }; + } catch { return { status: 0, text: "" }; } +} + +console.log("\nactive-request counter pairing (#180 / #193):"); + +test("integration: a synchronous pre-spawn throw must not leak stats.activeRequests", async () => { + if (!LT_POSIX) return; + const thr = ltSpreadThrowCount(LT_STACK); + assert.ok(thr > 0, `no spread-throw threshold found under --stack-size=${LT_STACK}`); + const n = Math.ceil(thr * 1.5); // margin over the measured threshold + const entry = Array(n).fill("x").join(","); + const bytes = Buffer.byteLength(entry); + // Hard gate: if this ever stops fitting, fail loudly rather than regress to an E2BIG skip. + assert.ok(bytes <= LT_MAX_ARG_STRLEN, + `env entry ${bytes}B exceeds MAX_ARG_STRLEN ${LT_MAX_ARG_STRLEN}B — lower LT_STACK`); + const port = await ltFreePort(); + const dir = ltMkdir(); const fake = ltFake(dir); + const { child, buf } = ltBoot({ + CLAUDE_BIN: fake, CLAUDE_PROXY_PORT: String(port), CLAUDE_ALLOWED_TOOLS: entry, + }, dir, [`--stack-size=${LT_STACK}`]); + let spawnErr = null; + child.on("error", e => { spawnErr = e; }); + try { + const up = await ltWait(() => buf.out.includes("listening on") || spawnErr, 20000); + assert.ok(up && !spawnErr, `did not start: ${spawnErr ? spawnErr.message : buf.err.slice(0, 300)}`); + const req = { model: "haiku", messages: [{ role: "user", content: "leak-probe" }] }; + const res = []; + for (let i = 0; i < 3; i++) res.push(await ltPostStatus(port, req)); + // Non-vacuous on two axes: the requests must actually fail, AND the failure must be the + // stack overflow from the --allowedTools spread — not some unrelated 500 that a small + // stack happened to produce. Without the second check a different fault would still leave + // the counter at 0 and the test would "pass" for the wrong reason. + assert.deepEqual(res.map(r => r.status), [500, 500, 500], + `expected the pre-spawn throw to surface as 500s, got ${res.map(r => r.status)}`); + assert.ok(res.every(r => /call stack size exceeded/i.test(r.text)), + `500s must come from the spread's RangeError; got: ${res[0].text.slice(0, 200)}`); + const r = await fetch(`http://127.0.0.1:${port}/status`); + const active = (await r.json()).requests.active; + assert.equal(active, 0, + `3 requests threw before their spawn; the counter must be back to 0, got ${active} (this is the #180 leak)`); + } finally { child.kill("SIGKILL"); _ltRm(dir, { recursive: true, force: true }); } +}); + // ── Cache keys hash the RESOLVED model, not the alias string (#194) ────────── // models.json is read once at boot, so repointing an alias only takes effect on restart — // while the SQLite response_cache outlives it. Hashing the raw string would keep serving the