Repository navigation
fix(cli): with the stdio MCP transport on, a host plugin's console output while serving a call reaches stderr - #33159
Conversation
…rt claims stdout A stdio MCP client writes initialize at spawn and its first tools/call as soon as that is answered, so the calls are served inside serve's boot-quiet window. Whatever a host plugin wrote to the console from them was dropped as boot chatter and reached neither stream. protocolStdout() now marks process.stdout when the transport claims it, and the window stops holding back console and stdout bytes from that moment; they go to the stderr forwarder, never to stdout. An HTTP-only boot never claims, so its window is unchanged. Co-Authored-By: Claude <noreply@anthropic.com> Claude-Session: https://claude.ai/code/session_01L9qibwitFuZejYP8o8ZdXC
…et window Co-Authored-By: Claude <noreply@anthropic.com> Claude-Session: https://claude.ai/code/session_01L9qibwitFuZejYP8o8ZdXC
Co-Authored-By: Claude <noreply@anthropic.com> Claude-Session: https://claude.ai/code/session_01L9qibwitFuZejYP8o8ZdXC
📓 Docs Drift Check3 anchor(s) derived from 2 changed package(s); no hand-written page names any of them, so this run has nothing to list — not a clean bill of health. This check sees only pages that NAME a derived anchor: one that documents this change in prose, or enumerates it in an authoring dialect, names none and stays invisible to it on every run. What this run could not see
Coarse fallback — 47 page(s) merely mention a changed package (the pre-#9192 predicate, kept for the deliberately-wide backstop): Which tree this was computed onThis run read A worktree cut from an older # while this PR is open — GitHub drops the merge commit once it closes
git fetch origin 1c1ccf13605314eef7ce0c46f48e6e2c62a25f3c && git checkout 1c1ccf13605314eef7ce0c46f48e6e2c62a25f3c
# afterwards, rebuild it from the two parents, which stay fetchable
git fetch origin 47f6c939f132df9185e1259740e2cbe4156802e1 f4bbd64872cd5597a69d84b7e5b3c2f0ca063248 && git checkout -B drift-repro 47f6c939f132df9185e1259740e2cbe4156802e1 && git merge --no-ff f4bbd64872cd5597a69d84b7e5b3c2f0ca063248
node scripts/docs-audit/affected-docs.mjs --json 47f6c939f132df9185e1259740e2cbe4156802e1 |
|
domain:server#7 · os-tesla · session_01L9qibzuZJBQY4wUQFJbkfx 维护者速读 · PR #33159 @
|
Requested by Tesla · project thread
Fixes #32942
Clause-②: no
Metadata-protocol: none
维护者速读
console.log/console.info/console.debug/process.stdout.write现在都会出现在 stderr;stdout 仍然只有 JSON-RPC 帧。initialize,收到答复立刻发tools/call,这些调用在serve的“启动静默窗口”还没关闭时就被处理了,窗口把它们的日志当成启动噪音直接丢掉,两个流都看不到(拦截器审计日志因此在 stdio 部署上全部丢失)。[Registry])也会直接打到 stderr。回滚 = revert 本 PR,不涉及数据。packages/cli/src/commands/serve.ts的quietHolds与isProtocolStdoutClaimed;packages/mcp/src/protocol-stdout.ts的PROTOCOL_STDOUT_CLAIM标记;packages/cli/test/serve-stdio-stdout-purity.e2e.test.ts新增的#32942一组。OS_TEST_TIERS=nightly pnpm --filter @objectstack/cli exec vitest run test/serve-stdio-stdout-purity.e2e.test.ts(先 build cli),预期 3/3 通过。What changes
The mechanism, measured at
origin/main(b22be279). It is not the stdout redirect and not the transport's stdout claim. It isserve's boot-quiet window. A stdio client writesinitializeat spawn and its firsttools/callas soon as that is answered. The transport attaches insideruntime.start(), and the window closes about 100 ms afterruntime.start()returns. So the first calls are served while the window is still open. During the windowconsole.logandconsole.debugare replaced by no-ops, andprocess.stdout.writeis filtered down to kernel-logger records for the post-banner replay. A host interceptor's line is not one of those records, so it was dropped and reached neither stream.console.warnandconsole.errorgo to stderr directly and were never affected, which is why the card saw the MCP WARN but not the interceptor line.@objectstack/mcp,protocol-stdout.ts:protocolStdout()now sets a mark onprocess.stdout(PROTOCOL_STDOUT_CLAIM, aSymbol.forkey) when the stdio transport claims the stream. The mark is set beforeconnect()attaches stdin, so no call can be served before it exists.mcp-server-runtime.tsis not edited.@objectstack/cli,serve.ts: the window's stdout and console wrappers askquietHolds()(the window is open AND stdout is not claimed) per write, instead ofbootQuiet. From the claim on, bytes go toorigStdoutWrite, which is the stderr forwarderredirectStdoutToStderr()installed, never to the real stdout.isProtocolStdoutClaimed()reads the mark by key soservedoes not import the MCP package to ask.init()and the starts ahead of the MCP plugin are still held back under stdio); the whole window on a boot without the stdio transport;printDiagnostic(serve's own lines) stays suppressed whilebootQuietis set.Each channel after the fix, under stdio, from a call served inside the window (all measured by the pin):
console.log,console.info,console.debugandprocess.stdout.writereach stderr through the forwarder;console.warnandconsole.errorreach stderr as before. None reaches stdout. From a timer after the banner every channel already reached stderr atmain, and still does.Tests
packages/mcp/src/protocol-stdout.test.ts(+1):protocolStdout()sets the mark onprocess.stdoutunderSymbol.for('@objectstack/mcp:protocol-stdout-claimed'), and the mark is absent before the call.packages/cli/test/serve-stdio-stdout-purity.e2e.test.ts, the existing child-process harness for this seam (builtbin/run.js, a real mintedosk_key), new top-leveldescribewith two cases. The sharedbeforeAll/afterAllmoved from inside theos servewrites its banner and kernel logs to the stdout the stdio MCP transport owns #7915describeto file level, unchanged, so both describes use one minting boot. The fixture config gains a host plugin whose tool-call interceptor writes through all six channels. WithFX_HOLD_FOR_CALL=1it holdskernel:readyuntil a call is served (cap 30 s), so the call lands inside the window deterministically instead of racing it. Theos servewrites its banner and kernel logs to the stdout the stdio MCP transport owns #7915 case makes no tool call, so the plugin is inert there.initializeat spawn,tools/call list_objectsthe moment its answer is read. Every channel's[fx-call] CHANNEL stdio:list_objectsline is on stderr AND beforeServer is ready. Every stdout line parses as a JSON-RPC frame.[fx-boot-chatter]frominit()is on neither stream.POST /api/v1/mcpafter boot: every channel's line on stderr, stdout empty,[fx-boot-chatter]still held back.OS_LOG_LEVEL=warn. Theos servewrites its banner and kernel logs to the stdout the stdio MCP transport owns #7915 case runs atinfo, a verbose level at whichservenever opens the window, so the defect cannot be reached there.Acceptance notes
ruling|Ruling-ref|maintainer|⛔) on the touched surface:serve.tshas 65 hits, none in the redirect or window region (L2160 to L2850 before the edit, the closest are L2158 "never a second copy", L2328, L2342, L2387 on the port flags).protocol-stdout.tsand its test have 0. The e2e file has 3, all in the existingos servewrites its banner and kernel logs to the stdout the stdio MCP transport owns #7915 harness text.mcp-server-runtime.ts(13 hits) is not edited.[Registry]console.loglines and oneWARNthat now print on stderr before the banner instead of being dropped (theWARNwas replayed under the banner before). The stream cannot tell a call's line from the rest of the boot. Holding them would mean marking request context in the MCP runtime's dispatch, outside this card's surface. Nothing reaches stdout either way..e2efile, so it runs on the nightly tier, the same tier as theos servewrites its banner and kernel logs to the stdout the stdio MCP transport owns #7915 purity pin it sits beside. The file is now about 19 s of local wall (four boots) and declares notest-budgetline, as before this PR. Flagged for the seat: whether it needs one now.os start;startspawnsservewith inherited stdio, so the fix is inserve. Both doors were measured before and after.Verification
Readings at head
f4bbd648(fix commits onb22be279;origin/mainmerged once before opening, no overlap with this diff).Measured at origin/main first (the premise holds, with a sharper mechanism)
A scratch app with the card's interceptor plugin plus a timer that writes through every channel 4 to 8 s after boot, a minted key,
OS_MCP_STDIO_ENABLED=true:[qa-interceptor]line and every timer line on stderr, under bothos serve --devandos start --no-ui. Not reproduced.initializeat spawn,tools/callon its answer, before the banner):os serveandos startboth answeredlist_objectsand denieddelete_record(PERMISSION_DENIED from the interceptor), stdout carried 3 frames and nothing else, and the interceptor'sconsole.logline was on NEITHER stream. Aprocess.stderr.writeline from the same interceptor was on stderr. Reproduced on both doors.After the fix, same harness: the
[qa-interceptor]lines on stderr on both doors, stdout 3 frames only.Package tests, typecheck, lint, derived gates
pnpm --filter @objectstack/mcp test: Test Files 64 passed (64), Tests 1138 passed (1138)pnpm --filter @objectstack/mcp typecheck,pnpm --filter @objectstack/cli typecheck: exit 0pnpm --filter @objectstack/cli exec vitest run --project unit --maxWorkers=2: Test Files 416 passed (416), Tests 5934 passed (5934)OS_TEST_TIERS=nightly … vitest run test/serve-stdio-stdout-purity.e2e.test.ts: Tests 3 passed (3)pnpm lint: exit 0node scripts/pm/dispatch-gates.mjs --commands: 72 families derived; 70 exit 0, 2 NOT MEASURED (exit 3, PREREQUISITE NOT MET:check:dual-build-cjs-loadsneedsdist/for packages outside this closure,check:i18n-coveragea partial lint round).check-plugin-teardown-shape --self-testfirst exited 3 on the shallow clone, and passed (48 cases) after fetching its pinned fixture commit.--ranreconciliation: 72 derived, 70 run, 2 NOT-MEASURED, 0 UNRUN.integrationtier ofpackages/cliis declared to CI.Ablations (both red, both restored)
The e2e spawns the built CLI, which loads both packages from
dist/, so each leg was rebuilt and checked withscripts/ablation-dist-preflight.mjs.scripts/ablation-replace.mjsonserve.ts, anchorconst quietHolds = () => bootQuiet && !isProtocolStdoutClaimed();(x1 to x0) replaced byconst quietHolds = () => bootQuiet;. Rebuilt; preflight: marker absent from all 952 built files. Result: 1 failed, 2 passed: the stdio case,the console.log line of the stdio call is missing from stderr; theos servewrites its banner and kernel logs to the stdout the stdio MCP transport owns #7915 case and the HTTP CONTROL stayed green. Restored: blob == HEAD (5d4e3372),git diff HEADempty, rebuilt, preflight marker present.PROTOCOL_STDOUT_CLAIMtotrueon the stream deleted (x1 to x0). mcp unit: 1 failed, 2 passed (the new mark case). mcp rebuilt, preflight absent from all 12 built files; e2e: 1 failed, 2 passed, the stdio case with the same message, which pins the key both packages spell. Restored: blob == HEAD (5cc99b80),git diff HEADempty, rebuilt, preflight marker present indist/index.jsanddist/index.cjs.Generated by Claude Code