diff --git a/.changeset/serve-diagnostics-to-stderr.md b/.changeset/serve-diagnostics-to-stderr.md new file mode 100644 index 0000000000..5e7a3dae12 --- /dev/null +++ b/.changeset/serve-diagnostics-to-stderr.md @@ -0,0 +1,49 @@ +--- +"@objectstack/cli": patch +"@objectstack/mcp": patch +--- + +fix(cli): `os serve` writes its banner, boot progress and kernel logs to stderr, so the stdio MCP channel carries only protocol (#7915) + +With `OS_MCP_STDIO_ENABLED=true`, `objectstack serve` used `process.stdout` as +the MCP JSON-RPC channel **and** as its ordinary human/log output. MCP stdio +framing is newline-delimited JSON — a conforming client `JSON.parse`s every line +it reads off the server's stdout — so every banner line and every `INFO`/`WARN` +record reached the client as a transport error. Measured on the card's repro: +the `initialize` result arrived on **line 517**, behind 516 lines of +non-protocol text. It reads as "the transport is broken", which is also why it +stayed invisible until #7645 (PR #7914) made the transport answer at all. + +**`serve`'s stdout is now the protocol's, and nothing else's.** Banners, boot +progress and kernel logs are diagnostics, not program output, and stderr is +where a CLI puts diagnostics — so they go there whether or not a stdio +transport is mounted. Two halves: + +- every human line `serve` prints is written to stderr explicitly, the startup + banner (`✓ Server is ready`, the plugin table, `Press Ctrl+C to stop`) and the + boot-diagnostics replay included; +- everything else the process would write to stdout — `ObjectLogger`'s + `debug`/`info`/`warn` records, and the stray `console.log`s several packages + emit during boot — is forwarded to stderr for the life of the process, the + same route `--json` already takes (#6217). `LoggerConfig` has a level but no + destination knob, so the stream itself is the only seam that covers writers + the CLI does not own. + +**Unconditional, deliberately.** "Redirect when the stdio transport is active" +needs a reliable signal at the moment each line prints — before the config is +read, before the plugin is loaded — and fails silently and in the worse +direction when that signal is wrong or late: a frame-corrupting line that shows +up only in some boots is far harder to find than one that always does. In a +terminal the move costs nothing, since both streams render. + +**Nothing is silenced.** Every line still appears, on stderr — including the +boot-phase warnings #4012 rescued from the quiet window. A shell that captured +both streams (`> log 2>&1`) sees exactly what it saw before; one that captured +stdout alone now finds `serve`'s output on stderr. + +`@objectstack/mcp`: the stdio transport now holds its own channel to the real +stdout instead of writing through `process.stdout` — a host that intercepts +`process.stdout.write` to move its diagnostics (which is what `serve` does) +would otherwise swallow the protocol frames along with them. It claims that +channel in every host and on every construction path, so a transport's frames +never depend on who booted the plugin. diff --git a/packages/cli/src/commands/serve-tenancy-posture-gate.test.ts b/packages/cli/src/commands/serve-tenancy-posture-gate.test.ts index 808bdb9ae6..735fa83421 100644 --- a/packages/cli/src/commands/serve-tenancy-posture-gate.test.ts +++ b/packages/cli/src/commands/serve-tenancy-posture-gate.test.ts @@ -193,8 +193,14 @@ describe('the gate runs before serve does ANY boot work', () => { * posture got as far as `Loading objectstack.config.ts…`, the whole plugin * slate, a persisted dev crypto key and a degraded kernel bootstrap before * anything refused. After it, `run()` reaches the gate and stops: the FATAL - * is the only thing written, and `console.log` — which is where every - * subsequent boot step reports — is never touched at all. + * is the only thing written, and the diagnostic stream — where every + * subsequent boot step reports — carries nothing else. + * + * That stream is **stderr** since #7915 (`serve` keeps stdout clear for the + * MCP stdio transport), so the capture below watches `process.stderr.write` + * rather than `console.log`. Watching `console.log` here would now be a + * phantom check: no boot step writes there any more, so the assertion could + * never fail, whatever the gate did. * * Note what is deliberately NOT asserted: "the port never listened". That was * true before the fix too (the escaping throw aborted kernel Phase 1, while @@ -207,13 +213,19 @@ describe('the gate runs before serve does ANY boot work', () => { process.env.OS_TENANCY_POSTURE = 'bogus'; const errors: string[] = []; - const logs: string[] = []; + const diagnostics: string[] = []; const errSpy = vi.spyOn(console, 'error').mockImplementation((...a: unknown[]) => { errors.push(a.join(' ')); }); - const logSpy = vi.spyOn(console, 'log').mockImplementation((...a: unknown[]) => { - logs.push(a.join(' ')); - }); + // Everything `serve` prints, at the stream: its own `printDiagnostic` lines + // AND anything the redirect installed at the top of `run()` forwards there. + const stdoutWrite = process.stdout.write; + const stderrSpy = vi + .spyOn(process.stderr, 'write') + .mockImplementation(((chunk: unknown) => { + diagnostics.push(String(chunk)); + return true; + }) as typeof process.stderr.write); // The gate exits the PROCESS on purpose (a throw is what the broad // AuthPlugin catch used to swallow). Convert it to something catchable so // the test runner survives, and assert it was reached. @@ -230,8 +242,12 @@ describe('the gate runs before serve does ANY boot work', () => { raised = err; } finally { errSpy.mockRestore(); - logSpy.mockRestore(); + stderrSpy.mockRestore(); exitSpy.mockRestore(); + // `run()` reserves stdout for the process's lifetime (#7915). Harmless in + // the real one-shot CLI; in a vitest worker it would outlive this case, + // so put the stream back. + process.stdout.write = stdoutWrite; if (savedNodeEnv === undefined) delete process.env.NODE_ENV; else process.env.NODE_ENV = savedNodeEnv; } @@ -244,12 +260,14 @@ describe('the gate runs before serve does ANY boot work', () => { expect(stderr).toContain('OS_TENANCY_POSTURE="bogus"'); // ── The ordering facts ──────────────────────────────────────────────── - // serve announces the config load on stdout as its first boot step. It is - // absent, so the gate preceded it — and therefore preceded every plugin - // load, the kernel bootstrap and the listening socket that follow it. - expect(logs.join('\n')).not.toContain('Loading'); - // Nothing at all reached stdout, in fact: the refusal is the whole output. - expect(logs).toEqual([]); + // serve announces the config load as its first boot step. It is absent, so + // the gate preceded it — and therefore preceded every plugin load, the + // kernel bootstrap and the listening socket that follow it. + expect(plain(diagnostics.join('\n'))).not.toContain('Loading'); + // Nothing at all was printed by a boot step, in fact: the FATAL — written + // with `console.error`, which the spy above takes before it reaches the + // stream — is the whole output. + expect(diagnostics).toEqual([]); // The misattribution that made this issue expensive to diagnose is gone: // no warning blames a plugin for an environment-variable typo. diff --git a/packages/cli/src/commands/serve.ts b/packages/cli/src/commands/serve.ts index b9adada7fa..a9c5e6adf4 100644 --- a/packages/cli/src/commands/serve.ts +++ b/packages/cli/src/commands/serve.ts @@ -4,7 +4,7 @@ import { Args, Command, Flags } from '@oclif/core'; import path from 'path'; import fs from 'fs'; import net from 'net'; -import chalk from 'chalk'; +import chalk, { chalkStderr } from 'chalk'; import { bundleRequire } from 'bundle-require'; import { loadConfig, BUNDLE_REQUIRE_EXTERNALS } from '../utils/config.js'; import { mergeBootConfig } from '../utils/merge-boot-config.js'; @@ -67,6 +67,7 @@ import { type AutomationReadySummary, type SeedSourceSummary, } from '../utils/format.js'; +import { redirectStdoutToStderr } from '../utils/json-stdout.js'; import { CONSOLE_PATH, resolveConsolePath, @@ -544,6 +545,76 @@ export default class Serve extends Command { async run(): Promise { const { args, flags } = await this.parse(Serve); + // ── stdout belongs to the protocol, never to diagnostics (#7915) ── + // Everything `serve` and the kernel it boots would write to stdout is + // forwarded to stderr, for the whole life of the process. Held, never + // released: this is not a window, it is the process's output policy. + // + // WHY, and why UNCONDITIONALLY. With `OS_MCP_STDIO_ENABLED=true` the MCP + // stdio transport owns stdout, and that protocol is newline-delimited JSON: + // a conforming client `JSON.parse`s every line it reads, so each banner or + // log line reaches it as a transport error. Measured on the #7915 repro + // (#7645 had to be fixed first for the channel to carry anything at all): + // the `initialize` result arrived on line 517, behind 516 lines of banner + // and kernel log — which reads as "the transport is broken". + // + // The tempting fix is "redirect when the stdio transport is active". It is + // the wrong one: a conditional needs a reliable signal at the moment each + // line prints — before the config is read, before the plugin is loaded — + // and it fails SILENTLY and in the worse direction when that signal is + // wrong or late. A frame-corrupting line that appears only in some boots is + // far harder to find than one that always does. Banners, boot progress and + // kernel logs are diagnostics, not program output; stderr is where a CLI + // puts diagnostics, mounted transport or not, and in a terminal it costs + // nothing because both streams render. + // + // Covers writers this file does not own — `ObjectLogger` routes + // debug/info/warn to `process.stdout` directly (packages/core), and stray + // `console.log`s live in several packages the boot touches (the + // `[StandaloneStack] no compiled artifact …` line is one). That is why the + // redirection is on the STREAM: `LoggerConfig` has a level but no + // destination knob, so there is nothing else to point at stderr. Same route + // `--json` takes for the same reason (#6217, `utils/json-stdout.ts`). + // + // The MCP transport is the one writer that must still reach the real + // stdout, and it holds its own channel to it (`packages/mcp`, + // protocol-stdout.ts) rather than depending on who booted it. + redirectStdoutToStderr(); + + // Colour follows the stream the text actually lands on. `chalk`'s default + // level is decided from stdout, so with the lines above moved to stderr a + // `serve > log` in a terminal would print an uncoloured banner to a TTY, + // and a `serve 2> log` would write ANSI escapes into the file. Both are + // cosmetic, both are wrong, and one assignment fixes them: every writer in + // this process shares the same chalk instance. + chalk.level = chalkStderr.level; + + /** + * Whether the boot-quiet window (further down) is currently open. + * + * Declared here rather than beside the window because {@link printDiagnostic} + * reads it, and this command's first human line prints long before the + * window opens. + */ + let bootQuiet = false; + + /** + * One human line from `serve`, written straight to **stderr** (#7915). + * + * Every `console.log` in this command was one of these: a banner line, a + * boot-progress note, an error explanation — diagnostics, all of them. They + * are written explicitly rather than left to the redirect above so the + * stream choice is visible at the call site; the redirect stays because it + * also covers the writers this file does not own. + * + * Suppressed while the boot-quiet window is open, exactly as `console.log` + * was: that window exists to keep the banner readable, and moving the + * stream must not turn a quiet boot into a noisy one. + */ + const printDiagnostic = (text = '') => { + if (!bootQuiet) process.stderr.write(text + '\n'); + }; + // When --dev is passed, set NODE_ENV early so any runtime modules // imported below (and any deps that branch on NODE_ENV at import // time) see development mode. We deliberately do NOT inherit @@ -579,7 +650,7 @@ export default class Serve extends Command { // shape — this one is fixed by construction (the e2e that measured the // truncation drives the other exit; reaching this one needs a busy port in // production mode). - console.log( + printDiagnostic( '\n' + chalk.red(` ✗ Port ${requestedPort} is already in use.\n`) + chalk.dim(' ObjectStack does not auto-select a different port in production mode:\n') @@ -685,7 +756,7 @@ export default class Serve extends Command { // lines survived a pipe.) An error whose tail can vanish is the #4012 // shape all over again; assembling it into a single write keeps it // inside one pipe-buffer flush. - console.log( + printDiagnostic( chalk.red(' ✗ Nothing to serve — no config and no compiled artifact.') + '\n' + chalk.dim(` Looked for a config at: ${absolutePath}\n`) + chalk.dim(` Looked for an artifact at: ${path.resolve(process.cwd(), 'dist/objectstack.json')}\n`) @@ -703,13 +774,13 @@ export default class Serve extends Command { } // Quiet loading — only show a single spinner line - console.log(''); + printDiagnostic(); if (useEmptyBoot) { - console.log(chalk.dim(' No objectstack.config.ts or artifact found — booting empty kernel...')); + printDiagnostic(chalk.dim(' No objectstack.config.ts or artifact found — booting empty kernel...')); } else if (useArtifactFallback) { - console.log(chalk.dim(' No objectstack.config.ts found — booting from artifact (default host)...')); + printDiagnostic(chalk.dim(' No objectstack.config.ts found — booting from artifact (default host)...')); } else { - console.log(chalk.dim(` Loading ${relativeConfig}...`)); + printDiagnostic(chalk.dim(` Loading ${relativeConfig}...`)); } // Track loaded plugins for summary @@ -747,11 +818,13 @@ export default class Serve extends Command { // banner just prints at the end of it (#4012). const verboseBoot = isVerboseBootLevel(bootLogLevel); - // Save original console/stdout methods — we'll suppress noise during boot + // Save original console/stdout methods — we'll suppress noise during boot. + // `origStdoutWrite` is the redirected write installed at the top of `run()`, + // NOT the real stdout: restoring it hands the stream back to the stderr + // forwarder, which is where every diagnostic belongs (#7915). const originalConsoleLog = console.log; const originalConsoleDebug = console.debug; const origStdoutWrite = process.stdout.write.bind(process.stdout); - let bootQuiet = false; // Everything the quiet window intercepts lands here instead of being // dropped on the floor, so boot-phase `logger.warn` survives to be // replayed under the banner (#4012). @@ -1172,7 +1245,7 @@ export default class Serve extends Command { Object.defineProperty(telemetry.driver, 'name', { value: 'telemetry' }); await kernel.use(new DriverPlugin(telemetry.driver)); trackPlugin('TelemetryDatasource'); - console.log(chalk.dim(` telemetry datasource: ${telemetryPath} (lifecycle-classed system data; OS_TELEMETRY_DB=0 to disable)`)); + printDiagnostic(chalk.dim(` telemetry datasource: ${telemetryPath} (lifecycle-classed system data; OS_TELEMETRY_DB=0 to disable)`)); } } catch { // Best-effort: a failed telemetry provision must never block @@ -2667,7 +2740,7 @@ export default class Serve extends Command { trackPlugin('DatasourceAdminRoutes'); if (isDev) { - console.log( + printDiagnostic( chalk.dim(' ↪ datasource admin: runtime UI lifecycle wired (/api/v1/datasources)'), ); } @@ -2765,7 +2838,7 @@ export default class Serve extends Command { } dataEngine.setCryptoProvider(sharedCryptoProvider); if (isDev) { - console.log( + printDiagnostic( chalk.dim( ' ↪ secret fields: LocalCryptoProvider wired (dev) — set OS_SECRET_KEY and swap for KMS/Vault in production', ), @@ -2803,7 +2876,7 @@ export default class Serve extends Command { // degraded-boot warning must not vanish (#4012). const migrateDiagnostics = collectBootDiagnostics(); if (migrateDiagnostics) printBootDiagnostics(migrateDiagnostics); - console.log(chalk.green(`✓ Migration complete (${loadedPlugins.length} plugins started against ${resolvedDatabaseUrl ? redactConnectionUrl(resolvedDatabaseUrl) : 'configured DB'})`)); + printDiagnostic(chalk.green(`✓ Migration complete (${loadedPlugins.length} plugins started against ${resolvedDatabaseUrl ? redactConnectionUrl(resolvedDatabaseUrl) : 'configured DB'})`)); try { await kernel.shutdown(); } catch (err: any) { @@ -2941,7 +3014,7 @@ export default class Serve extends Command { } catch (error: any) { restoreOutput(); - console.log(''); + printDiagnostic(); printError(error.message || String(error)); // A boot that died is when its warnings matter most, and the banner that // would normally carry them never printed (#4012). diff --git a/packages/cli/src/commands/start.ts b/packages/cli/src/commands/start.ts index 15c31c402b..1f6317febe 100644 --- a/packages/cli/src/commands/start.ts +++ b/packages/cli/src/commands/start.ts @@ -1,7 +1,7 @@ // Copyright (c) 2025 ObjectStack. Licensed under the Apache-2.0 license. import { Command, Flags } from '@oclif/core'; -import chalk from 'chalk'; +import chalk, { chalkStderr } from 'chalk'; import { spawn, spawnSync } from 'child_process'; import crypto from 'crypto'; import dotenvFlow from 'dotenv-flow'; @@ -9,6 +9,7 @@ import fs from 'fs'; import os from 'os'; import path from 'path'; import { printHeader, printKV, printStep, printError } from '../utils/format.js'; +import { redirectStdoutToStderr } from '../utils/json-stdout.js'; import { redactConnectionUrl } from '../utils/connection-display.js'; import { databaseDriverFlag } from '../utils/database-driver-flag.js'; import { readEnvWithDeprecation } from '@objectstack/types'; @@ -127,6 +128,19 @@ export default class Start extends Command { async run(): Promise { const { flags } = await this.parse(Start); + // ── stdout belongs to the protocol, never to diagnostics (#7915) ── + // `start` is a supervisor: it prints a header, a few resolved values and a + // progress line, then spawns `serve` with INHERITED stdio. So its own + // stdout is the same fd the child's stdio MCP transport writes JSON-RPC + // frames to — and this is the invocation the stdio docs name + // (`OS_MCP_STDIO_ENABLED=true OS_MCP_STDIO_API_KEY=osk_… os start`). + // Everything on that fd from this process is a diagnostic, so it goes to + // stderr, unconditionally, for the same reasons spelled out at the top of + // `serve.run()`. The child installs the same policy for itself. + redirectStdoutToStderr(); + // Colour follows the destination stream — see the same line in `serve`. + chalk.level = chalkStderr.level; + // Load .env files following Vite/Next.js convention (mirrors `serve`). // Loaded BEFORE any env lookups so OS_DATABASE_URL/OS_HOME/AUTH_SECRET // from `.env`, `.env.production`, `.env.local`, etc. are picked up. diff --git a/packages/cli/src/utils/format.seed-summary.test.ts b/packages/cli/src/utils/format.seed-summary.test.ts index 44b004d224..74e3a5f90e 100644 --- a/packages/cli/src/utils/format.seed-summary.test.ts +++ b/packages/cli/src/utils/format.seed-summary.test.ts @@ -24,7 +24,9 @@ describe('printServerReady seed summary (#3415/#3430)', () => { beforeEach(() => { lines = []; - spy = vi.spyOn(console, 'log').mockImplementation((...args: unknown[]) => { + // stderr, not stdout (#7915): the whole banner is a diagnostic, and + // `serve` keeps stdout clear for the MCP stdio transport. + spy = vi.spyOn(console, 'error').mockImplementation((...args: unknown[]) => { lines.push(args.join(' ')); }); }); diff --git a/packages/cli/src/utils/format.tenancy.test.ts b/packages/cli/src/utils/format.tenancy.test.ts index 3bc7508394..3e8ca8f0a8 100644 --- a/packages/cli/src/utils/format.tenancy.test.ts +++ b/packages/cli/src/utils/format.tenancy.test.ts @@ -40,7 +40,9 @@ describe('printServerReady Tenancy row (#4801, ADR-0105 D1)', () => { beforeEach(() => { lines = []; - spy = vi.spyOn(console, 'log').mockImplementation((...args: unknown[]) => { + // stderr, not stdout (#7915): the whole banner is a diagnostic, and + // `serve` keeps stdout clear for the MCP stdio transport. + spy = vi.spyOn(console, 'error').mockImplementation((...args: unknown[]) => { // Strip SGR escapes so assertions hold whether or not chalk colors. lines.push(args.join(' ').replace(/\u001b\[[0-9;]*m/g, '')); }); diff --git a/packages/cli/src/utils/format.ts b/packages/cli/src/utils/format.ts index ac1f87ee61..99db27629f 100644 --- a/packages/cli/src/utils/format.ts +++ b/packages/cli/src/utils/format.ts @@ -527,49 +527,72 @@ export interface AutomationReadySummary { draftCount: number; } +/** + * `os serve`'s startup banner — on **stderr** (#7915). + * + * Everything below writes with `console.error`, and that is the whole point of + * this comment: the banner is a DIAGNOSTIC, not program output. `os serve`'s + * stdout belongs to the MCP stdio transport when one is mounted + * (`OS_MCP_STDIO_ENABLED=true`), and that protocol is newline-delimited JSON — + * a conforming client `JSON.parse`s every line it reads, so one banner line + * reaches it as a transport error. Measured on the #7915 repro: the + * `initialize` result arrived on line 517, behind 516 lines of banner and + * kernel log. + * + * Unconditional on purpose. "stderr when the stdio transport is mounted" needs + * a reliable signal at the moment each line prints, and fails silently and in + * the worse direction when that signal is wrong or late. Diagnostics belong on + * stderr whether or not anything is listening on stdout, and in a terminal it + * costs nothing — both streams render. + * + * `printBootDiagnostics`, `printAutomationSummary` and `printSeedSummary` are + * part of this same banner and follow the same rule. The general helpers above + * (`printSuccess`, `printKV`, `printMetadataStats`, …) deliberately do NOT: + * they serve every command, some of whose stdout IS the program's output. + */ export function printServerReady(opts: ServerReadyOptions) { const base = `http://localhost:${opts.port}`; - console.log(''); - console.log(chalk.bold.green(' ✓ Server is ready')); - console.log(''); - console.log(chalk.cyan(' ➜') + chalk.bold(' API: ') + chalk.cyan(base + '/')); + console.error(''); + console.error(chalk.bold.green(' ✓ Server is ready')); + console.error(''); + console.error(chalk.cyan(' ➜') + chalk.bold(' API: ') + chalk.cyan(base + '/')); if (opts.uiEnabled && opts.consolePath) { - console.log(chalk.cyan(' ➜') + chalk.bold(' Console: ') + chalk.cyan(base + opts.consolePath + '/')); + console.error(chalk.cyan(' ➜') + chalk.bold(' Console: ') + chalk.cyan(base + opts.consolePath + '/')); } if (opts.mcpEnabled) { - console.log(chalk.cyan(' ➜') + chalk.bold(' MCP: ') + chalk.cyan(base + '/api/v1/mcp')); - console.log(chalk.dim(` connect an AI client (Claude Code, Cursor, …) · skill: ${base}/api/v1/mcp/skill`)); + console.error(chalk.cyan(' ➜') + chalk.bold(' MCP: ') + chalk.cyan(base + '/api/v1/mcp')); + console.error(chalk.dim(` connect an AI client (Claude Code, Cursor, …) · skill: ${base}/api/v1/mcp/skill`)); } if (opts.seededAdmin) { - console.log(''); - console.log( + console.error(''); + console.error( chalk.green(' 🔑') + chalk.bold(' Dev admin: ') + chalk.bold.green(`${opts.seededAdmin.email} / ${opts.seededAdmin.password}`), ); - console.log(chalk.dim(' seeded on empty DB · dev only — do not use in production')); + console.error(chalk.dim(' seeded on empty DB · dev only — do not use in production')); } - console.log(''); - console.log(chalk.dim(` Config: ${opts.configFile}`)); - console.log(chalk.dim(` Mode: ${opts.isDev ? 'development' : 'production'}`)); + console.error(''); + console.error(chalk.dim(` Config: ${opts.configFile}`)); + console.error(chalk.dim(` Mode: ${opts.isDev ? 'development' : 'production'}`)); if (opts.driverLabel) { const dbInfo = opts.databaseUrl ? `${opts.driverLabel} ${chalk.dim('→')} ${opts.databaseUrl}` : opts.driverLabel; - console.log(chalk.dim(` Driver: ${dbInfo}`)); + console.error(chalk.dim(` Driver: ${dbInfo}`)); } // [ADR-0105 D1] Print the posture verbatim — see `tenancyPosture` above for // why this is not a boolean and why it must be the resolver's answer. if (opts.tenancyPosture !== undefined) { - console.log(chalk.dim(` Tenancy: ${opts.tenancyPosture}`)); + console.error(chalk.dim(` Tenancy: ${opts.tenancyPosture}`)); } - console.log(chalk.dim(` Plugins: ${opts.pluginCount} loaded`)); + console.error(chalk.dim(` Plugins: ${opts.pluginCount} loaded`)); if (opts.pluginNames && opts.pluginNames.length > 0) { - console.log(chalk.dim(` ${opts.pluginNames.join(', ')}`)); + console.error(chalk.dim(` ${opts.pluginNames.join(', ')}`)); } if (opts.automation) printAutomationSummary(opts.automation); if (opts.seeds) printSeedSummary(opts.seeds); if (opts.bootDiagnostics) printBootDiagnostics(opts.bootDiagnostics); - console.log(''); - console.log(chalk.dim(' Press Ctrl+C to stop')); - console.log(''); + console.error(''); + console.error(chalk.dim(' Press Ctrl+C to stop')); + console.error(''); } /** Boot-phase logger records held back by the boot-quiet window (#4012). */ @@ -592,22 +615,25 @@ export interface BootDiagnostics { * Quiet when a boot had nothing to say. Printed from the banner on a healthy * boot and directly from serve's error path on a failed one — a boot that dies * is exactly when its warnings matter most. + * + * Replayed to **stderr** (#7915) — these are the kernel's own diagnostics, held + * back and re-emitted, so they land where every other `serve` diagnostic does. */ export function printBootDiagnostics(diagnostics: BootDiagnostics) { const { lines, dropped = 0 } = diagnostics; if (lines.length === 0) return; - console.log(''); - console.log( + console.error(''); + console.error( chalk.yellow( ` ⚠ Boot diagnostics — ${lines.length} warning${lines.length === 1 ? '' : 's'} logged during startup:`, ), ); - for (const line of lines) console.log(chalk.dim(` ${line}`)); + for (const line of lines) console.error(chalk.dim(` ${line}`)); if (dropped > 0) { - console.log(chalk.dim(` …and ${dropped} more (capture buffer full)`)); + console.error(chalk.dim(` …and ${dropped} more (capture buffer full)`)); } - console.log(chalk.dim(' run with --log-level debug to watch the boot stream live')); + console.error(chalk.dim(' run with --log-level debug to watch the boot stream live')); } /** @@ -618,7 +644,7 @@ export function printBootDiagnostics(diagnostics: BootDiagnostics) { function printAutomationSummary(a: AutomationReadySummary) { if (!a.enabled) { if (a.declaredFlowCount > 0) { - console.log( + console.error( chalk.yellow( ` ⚠ Flows: ${a.declaredFlowCount} flow(s) declared but the automation engine is not enabled — ` + `they will never run. Add requires: ['automation', 'triggers'] to objectstack.config.ts`, @@ -632,15 +658,15 @@ function printAutomationSummary(a: AutomationReadySummary) { const parts = [`${a.flowCount} flow(s)`, `${a.boundCount} bound to triggers`]; if (a.triggerTypes.length > 0) parts.push(`(${a.triggerTypes.join(', ')})`); if (a.draftCount > 0) parts.push(`· ${a.draftCount} draft`); - console.log(chalk.dim(` Flows: ${parts.join(' ')}`)); + console.error(chalk.dim(` Flows: ${parts.join(' ')}`)); for (const u of a.unbound) { - console.log( + console.error( chalk.yellow(` ⚠ flow '${u.flowName}' declares a '${u.triggerType}' trigger but is NOT bound — ${u.reason}`), ); } for (const u of a.unknownObject) { - console.log( + console.error( chalk.yellow( ` ⚠ flow '${u.flowName}' targets unknown object '${u.object}' — bound, but it will never fire ` + `(object names match exactly; check the start node's config.objectName)`, @@ -691,11 +717,11 @@ function printSeedSummary(sources: SeedSourceSummary[]) { const line = shown.map(fragment).join(' · '); if (anyProblem) { - console.log(chalk.yellow(` ⚠ Seeds: ${line}`)); - console.log(chalk.dim(' run with OS_LOG_LEVEL=info to see each dropped record')); + console.error(chalk.yellow(` ⚠ Seeds: ${line}`)); + console.error(chalk.dim(' run with OS_LOG_LEVEL=info to see each dropped record')); return; } - console.log(chalk.dim(` Seeds: ${line}`)); + console.error(chalk.dim(` Seeds: ${line}`)); } export function printMetadataStats(stats: MetadataStats) { diff --git a/packages/cli/src/utils/json-stdout.ts b/packages/cli/src/utils/json-stdout.ts index 6a2c5f9866..2a18f72acb 100644 --- a/packages/cli/src/utils/json-stdout.ts +++ b/packages/cli/src/utils/json-stdout.ts @@ -1,7 +1,8 @@ // Copyright (c) 2026 ObjectStack. Licensed under the Apache-2.0 license. /** - * `--json` stdout reservation (#6217). + * stdout reservation — `--json` payloads (#6217) and `os serve`'s protocol + * channel (#7915). * * ## The invariant * @@ -10,6 +11,13 @@ * heuristic extraction. Anything else is a `--json` flag that isn't * machine-readable. * + * `os serve` has the same invariant for a different reason (#7915): with + * `OS_MCP_STDIO_ENABLED=true` the MCP stdio transport owns stdout, and that + * protocol is newline-delimited JSON — a conforming client `JSON.parse`s every + * line it reads, so one banner line is a transport error. `serve` therefore + * reserves stdout too, for the whole life of the process and **unconditionally** + * (see {@link redirectStdoutToStderr}). + * * It was not true for the commands that boot a kernel. `ObjectLogger` routes * `debug`/`info`/`warn` to **stdout** and only `error`/`fatal` to stderr * (`packages/core/src/logger.ts`), so `os migrate recorded-by --json` emitted @@ -99,6 +107,30 @@ export function isStdoutReserved(): boolean { * payload. */ export function reserveStdoutForJson(): () => void { + return redirectStdoutToStderr(); +} + +/** + * The same reservation, named for the case that has no `--json` payload: + * **every** byte written to `process.stdout` is forwarded to stderr, and + * nothing is expected to come back the other way. + * + * This is what `os serve` installs, once, for the life of the process (#7915). + * Banners, boot progress and kernel logs are diagnostics, not program output, + * so they belong on stderr whether or not anything is listening on stdout — + * which is also why `serve` installs it UNCONDITIONALLY rather than "when the + * stdio MCP transport is mounted". A conditional needs a reliable signal at the + * moment each line prints, and it fails silently and in the worse direction + * when that signal is wrong or late: a frame-corrupting line that appears only + * in some boots is far harder to find than one that always does. + * + * The one writer that must still reach the real stdout is whoever the stream is + * reserved FOR — `--json`'s payload writer goes through + * {@link writeStdoutDirect}; the MCP stdio transport holds its own channel to + * the real stream (`packages/mcp/src/protocol-stdout.ts`), for the same reason + * and by the same rule: nothing else may reach stdout. + */ +export function redirectStdoutToStderr(): () => void { if (realStdoutWrite) return () => { /* an inner reservation owns nothing */ }; const original = process.stdout.write.bind(process.stdout) as StreamWrite; diff --git a/packages/cli/test/helpers/serve-process.ts b/packages/cli/test/helpers/serve-process.ts index 1909dc93ae..3c9dffa506 100644 --- a/packages/cli/test/helpers/serve-process.ts +++ b/packages/cli/test/helpers/serve-process.ts @@ -36,6 +36,13 @@ export interface ServeRun { * * A boot that DIES still has to have said why, so an early exit resolves rather * than rejects — the caller's assertions read what it printed on the way down. + * + * `waitFor` is matched against **stdout and stderr together** (#7915). `serve` + * writes every human line — banner, boot progress, kernel logs — to stderr now, + * because its stdout belongs to the MCP stdio transport when one is mounted; + * matching stdout alone would wait for a stream that stays empty for the whole + * boot. Both streams are still returned separately, which is what lets + * `serve-stdio-stdout-purity.e2e.test.ts` assert stdout carries NOTHING else. */ export function runServe( cwd: string, @@ -90,10 +97,11 @@ export function runServe( child.stdout.on('data', (d) => { stdout += String(d); - if (opts.waitFor.test(stdout)) finish(); + if (opts.waitFor.test(stdout + stderr)) finish(); }); child.stderr.on('data', (d) => { stderr += String(d); + if (opts.waitFor.test(stdout + stderr)) finish(); }); child.on('error', (err) => finish(err)); child.on('exit', () => finish()); diff --git a/packages/cli/test/json-stdout-purity.e2e.test.ts b/packages/cli/test/json-stdout-purity.e2e.test.ts index 2a6e87e8d4..88ab115034 100644 --- a/packages/cli/test/json-stdout-purity.e2e.test.ts +++ b/packages/cli/test/json-stdout-purity.e2e.test.ts @@ -45,6 +45,15 @@ * warnings included, on the floor. Every case therefore asserts the same lines * are present on **stderr**, so a regression toward silencing goes red here * too. + * + * ## The other member of this family + * + * `os serve` has no `--json` and boots no `bootSchemaStack`, so it is correctly + * outside the FAMILY below — but it holds the same invariant for a different + * consumer: its stdout is the MCP stdio transport's JSON-RPC channel (#7915). + * It reserves the stream through this same module and is pinned by + * `serve-stdio-stdout-purity.e2e.test.ts`, which asserts the same two halves — + * nothing unparseable on stdout, every diagnostic still on stderr. */ import { describe, it, expect, beforeAll, afterAll } from 'vitest'; diff --git a/packages/cli/test/serve-app-runtime-hooks.e2e.test.ts b/packages/cli/test/serve-app-runtime-hooks.e2e.test.ts index 0155919f70..5d43f7fda8 100644 --- a/packages/cli/test/serve-app-runtime-hooks.e2e.test.ts +++ b/packages/cli/test/serve-app-runtime-hooks.e2e.test.ts @@ -99,18 +99,18 @@ describe('os serve — an app booted from its artifact keeps its module code (#4 // Sanity: the boot has to have got far enough for the inventory to run at // all, or "no warning" would be vacuously true. - expect(stdout, `serve never reached its banner${seen}`).toMatch(/Server is ready/); + expect(stderr, `serve never reached its banner${seen}`).toMatch(/Server is ready/); // The load-bearing assertion. Pre-fix this reported // `{"count":1,"actions":["hookfix_task:do_thing"]}` — declared, no handler. - expect(stdout, `the action's handler went unregistered${seen}`).not.toContain( + expect(stderr, `the action's handler went unregistered${seen}`).not.toContain( '[action-governance]', ); - expect(stdout).not.toContain('hookfix_task:do_thing'); + expect(stderr).not.toContain('hookfix_task:do_thing'); // And the config's code was not merely tolerated in silence: nothing should - // report it as orphaned either. - expect(stdout).not.toContain('no app bundle claimed'); - expect(stderr).not.toContain('no app bundle claimed'); + // report it as orphaned either. One stream covers both since #7915 — every + // human line `serve` prints goes to stderr. + expect(stdout + stderr).not.toContain('no app bundle claimed'); }, 240_000); }); diff --git a/packages/cli/test/serve-boot-diagnostics.e2e.test.ts b/packages/cli/test/serve-boot-diagnostics.e2e.test.ts index 47d4160576..95301cf0d5 100644 --- a/packages/cli/test/serve-boot-diagnostics.e2e.test.ts +++ b/packages/cli/test/serve-boot-diagnostics.e2e.test.ts @@ -10,8 +10,13 @@ * blinded both). Nothing above the CLI could see it: the kernel logged * correctly, the sink was live, and every data-phase line streamed fine. * + * The replay stream moved in #7915: `serve` now forwards everything it and the + * kernel would write to stdout onto **stderr**, unconditionally, because its + * stdout belongs to the MCP stdio transport. What #4012 pinned is unchanged — + * the records must reach a terminal — so the assertions below read stderr. + * * Only a test that drives the actual command can catch that, so this one boots - * a real stack through `bin/run-dev.js` and reads its stdout. The positive + * a real stack through `bin/run-dev.js` and reads its output. The positive * control is a config-only guarantee that a boot WARN gets emitted: a declared * `script` action with no `body` and no registered handler, which the ADR-0110 * D5 inventory reports as an `unboundDeclarations` finding through @@ -89,12 +94,12 @@ describe('os serve — boot-phase logger output (#4012)', () => { // The load-bearing assertion. Before the fix this was absent at EVERY // log level while thousands of data-phase lines streamed past. - expect(stdout, `[action-governance] missing from stdout${seen}`).toContain( + expect(stderr, `[action-governance] missing from stderr${seen}`).toContain( '[action-governance]', ); // …and it names the offender, so the line is actionable rather than just // present. - expect(stdout).toContain('bootdiag_task:orphan_action'); + expect(stderr).toContain('bootdiag_task:orphan_action'); }, 240_000, ); @@ -112,8 +117,8 @@ describe('os serve — boot-phase logger output (#4012)', () => { }); const seen = `\n--- stdout ---\n${stdout.slice(-4000)}\n--- stderr ---\n${stderr.slice(-2000)}`; - expect(stdout, `boot-phase kernel traces missing${seen}`).toContain('Bootstrap complete'); - expect(stdout, `boot WARN missing at debug level${seen}`).toContain('[action-governance]'); + expect(stderr, `boot-phase kernel traces missing${seen}`).toContain('Bootstrap complete'); + expect(stderr, `boot WARN missing at debug level${seen}`).toContain('[action-governance]'); }, 240_000, ); diff --git a/packages/cli/test/serve-mcp-capability-collision.e2e.test.ts b/packages/cli/test/serve-mcp-capability-collision.e2e.test.ts index 829bce98b1..017b87609f 100644 --- a/packages/cli/test/serve-mcp-capability-collision.e2e.test.ts +++ b/packages/cli/test/serve-mcp-capability-collision.e2e.test.ts @@ -96,7 +96,12 @@ let dir: string; let port: string; let base: string; let apiKey: string; -let bootStdout = ''; +/** + * The boot's human output. Read from **stderr** since #7915 — `serve` keeps its + * stdout clear for the MCP stdio transport, so every banner and log line the + * assertions below look for arrives on stderr. + */ +let bootOutput = ''; const children: ChildProcessWithoutNullStreams[] = []; function boot(env: Record, waitFor: RegExp): Promise { @@ -127,17 +132,22 @@ function boot(env: Record, waitFor: RegExp): Promise rejectBoot(new Error(`serve never printed ${waitFor}\n--- stdout ---\n${out.slice(-4000)}\n--- stderr ---\n${err.slice(-4000)}`)); }, 150_000); - child.stdout.on('data', (d) => { - out += String(d); - bootStdout = out; - if (!settled && waitFor.test(out)) { + const onOutput = () => { + bootOutput = err; + if (!settled && waitFor.test(out + err)) { settled = true; clearTimeout(timer); resolveBoot(child); } + }; + + child.stdout.on('data', (d) => { + out += String(d); + onOutput(); }); child.stderr.on('data', (d) => { err += String(d); + onOutput(); }); child.on('exit', (code) => { if (settled) return; @@ -247,10 +257,10 @@ describe('#7652: an app loading the MCP client connector still gets the MCP serv // The banner lists the app's own plugins. If the fixture ever stops loading // the connector, the rest of this file would pass for the wrong reason. expect( - bootStdout, - `the fixture's ${CONSUMER_CLASS_NAME} is not in the boot output:\n${bootStdout.slice(-3000)}`, + bootOutput, + `the fixture's ${CONSUMER_CLASS_NAME} is not in the boot output:\n${bootOutput.slice(-3000)}`, ).toMatch(/mcpcollision|Server is ready/); - expect(bootStdout).not.toMatch(/Capability "mcp".*not installed/); + expect(bootOutput).not.toMatch(/Capability "mcp".*not installed/); }); it('GET /api/v1/mcp/skill answers 200 — the card\'s repro', async () => { diff --git a/packages/cli/test/serve-mcp-stdio-answers.e2e.test.ts b/packages/cli/test/serve-mcp-stdio-answers.e2e.test.ts index e471eb9fcf..7d3de7ff75 100644 --- a/packages/cli/test/serve-mcp-stdio-answers.e2e.test.ts +++ b/packages/cli/test/serve-mcp-stdio-answers.e2e.test.ts @@ -84,9 +84,15 @@ interface Booted { } /** - * Spawn `os serve` and resolve once `waitFor` matches its stdout, leaving the - * child RUNNING — the shared `runServe` helper kills on match, and this file - * has to keep talking to the process afterwards. + * Spawn `os serve` and resolve once `waitFor` matches its output — stdout and + * stderr together — leaving the child RUNNING; the shared `runServe` helper + * kills on match, and this file has to keep talking to the process afterwards. + * + * Both streams, because since #7915 `serve` writes every human line (banner, + * boot progress, kernel logs — including the `[MCP] Server started` record this + * file waits for) to stderr, and keeps stdout clear for the protocol. Matching + * stdout alone would wait on a stream that carries nothing until a client + * speaks. * * NOTE: no positional config path is passed. That is deliberate and load-bearing: * supplying one makes oclif skip `tryStdin` entirely, so stdin is never paused @@ -124,16 +130,21 @@ function boot(env: Record, waitFor: RegExp): Promise ); }, 150_000); - child.stdout.on('data', (d) => { - out += String(d); - if (!settled && waitFor.test(out)) { + const onOutput = () => { + if (!settled && waitFor.test(out + err)) { settled = true; clearTimeout(timer); resolveBoot({ child, stdout: () => out, stderr: () => err }); } + }; + + child.stdout.on('data', (d) => { + out += String(d); + onOutput(); }); child.stderr.on('data', (d) => { err += String(d); + onOutput(); }); child.on('exit', (code) => { if (settled) return; diff --git a/packages/cli/test/serve-no-artifact.e2e.test.ts b/packages/cli/test/serve-no-artifact.e2e.test.ts index 97597e2f42..44f4dd4a31 100644 --- a/packages/cli/test/serve-no-artifact.e2e.test.ts +++ b/packages/cli/test/serve-no-artifact.e2e.test.ts @@ -168,7 +168,7 @@ describe('os serve — boots without a compiled artifact (#4085)', () => { // No artifact was built — the whole point. expect(existsSync(join(appDir, 'dist/objectstack.json'))).toBe(false); - expect(stdout, `serve never reported ready${seen}`).toContain('Server is ready'); + expect(stderr, `serve never reported ready${seen}`).toContain('Server is ready'); // The exact Phase-1 death this issue filed, in either of its spellings // (the misleading "is async" one and the truthful "not found" the kernel // now reports). @@ -181,7 +181,7 @@ describe('os serve — boots without a compiled artifact (#4085)', () => { // through a connected datasource. A failure in either aborts boot before // the banner, so reaching this line with the app listed is the real // guarantee. - expect(stdout, `app plugin missing from the boot banner${seen}`).toMatch( + expect(stderr, `app plugin missing from the boot banner${seen}`).toMatch( /Plugins:[\s\S]*noartifact/, ); @@ -205,7 +205,7 @@ describe('os serve — boots without a compiled artifact (#4085)', () => { // Same premise as every boot in this file: nothing was ever compiled. expect(existsSync(join(defineStackDir, 'dist/objectstack.json'))).toBe(false); - expect(stdout, `serve never reported ready${seen}`).toContain('Server is ready'); + expect(stderr, `serve never reported ready${seen}`).toContain('Server is ready'); // The crash #3887 reported, and the truthful message the kernel replaced // it with — neither may return through the authored path either. expect(out).not.toMatch(/Service 'manifest' (is async|not found)/); @@ -217,7 +217,7 @@ describe('os serve — boots without a compiled artifact (#4085)', () => { // fails HERE rather than degrading into a green run against nothing: the // app is named in the started plugin set, which it can only reach by // having been parsed, registered, and started. - expect(stdout, `app plugin missing from the boot banner${seen}`).toMatch( + expect(stderr, `app plugin missing from the boot banner${seen}`).toMatch( /Plugins:[\s\S]*cfgload/, ); @@ -226,7 +226,7 @@ describe('os serve — boots without a compiled artifact (#4085)', () => { // app's start had to find a connected driver behind that name. The banner // reports which one resolved, so assert it rather than leave the claim // resting on "boot did not throw". - expect(stdout, `no driver resolved for the stamped datasource${seen}`).toMatch( + expect(stderr, `no driver resolved for the stamped datasource${seen}`).toMatch( /Driver:\s+\S+/, ); }, @@ -242,7 +242,7 @@ describe('os serve — boots without a compiled artifact (#4085)', () => { }); const seen = `\n--- stdout ---\n${stdout}\n--- stderr ---\n${stderr}`; - expect(stdout, `bare platform never reported ready${seen}`).toContain('Server is ready'); + expect(stderr, `bare platform never reported ready${seen}`).toContain('Server is ready'); expect(stdout + stderr).not.toContain('rollback complete'); // MetadataPlugin's own fatal on the absent `dist/objectstack.json`. expect(stdout + stderr).not.toContain('Cannot read artifact file'); @@ -303,7 +303,7 @@ describe('os serve — boots without a compiled artifact (#4085)', () => { const out = stdout + stderr; // A rejected app must not take the platform down… - expect(stdout, `platform died on an unregisterable app${seen}`).toContain('Server is ready'); + expect(stderr, `platform died on an unregisterable app${seen}`).toContain('Server is ready'); // …and must not be swallowed either: the operator has to learn that their // objects are NOT being served, and why. expect(out, `no warning about the skipped app${seen}`).toContain('Skipped registering the app'); diff --git a/packages/cli/test/serve-organizations-host-resolution.e2e.test.ts b/packages/cli/test/serve-organizations-host-resolution.e2e.test.ts index 782fda1c31..6fec9b75da 100644 --- a/packages/cli/test/serve-organizations-host-resolution.e2e.test.ts +++ b/packages/cli/test/serve-organizations-host-resolution.e2e.test.ts @@ -167,10 +167,10 @@ describe('os serve — enterprise organizations resolution (cloud#1013)', () => // reaching the banner at all. expect(stderr, `the D5 fail-fast fired — the app-installed package was not found${seen}`) .not.toMatch(/could not be loaded/); - expect(stdout, `serve never reached its banner${seen}`).toContain('Press Ctrl+C to stop'); + expect(stderr, `serve never reached its banner${seen}`).toContain('Press Ctrl+C to stop'); // …and it is the APP's package that got mounted: `Organizations` is // tracked only on the path that actually registered the plugin. - expect(stdout, `OrganizationsPlugin was not registered${seen}`).toContain('Organizations'); + expect(stderr, `OrganizationsPlugin was not registered${seen}`).toContain('Organizations'); }, 300_000, ); @@ -195,7 +195,7 @@ describe('os serve — enterprise organizations resolution (cloud#1013)', () => ); // The remedy names the app, because that is where the package has to go. expect(stderr).toMatch(/to THIS APP/); - expect(stdout, `serve served traffic without the wall${seen}`).not.toContain( + expect(stderr, `serve served traffic without the wall${seen}`).not.toContain( 'Press Ctrl+C to stop', ); }, @@ -226,10 +226,10 @@ describe('os serve — enterprise organizations resolution (cloud#1013)', () => // …and the remedy is the declaration one, naming why reachability lost. expect(stderr).toMatch(/to THIS APP/); expect(stderr).toMatch(/NODE_PATH/); - expect(stdout, `serve served traffic without the wall${seen}`).not.toContain( + expect(stderr, `serve served traffic without the wall${seen}`).not.toContain( 'Press Ctrl+C to stop', ); - expect(stdout, `the hoisted package was mounted anyway${seen}`).not.toContain( + expect(stderr, `the hoisted package was mounted anyway${seen}`).not.toContain( 'Organizations', ); }, diff --git a/packages/cli/test/serve-organizations-mount-failure.e2e.test.ts b/packages/cli/test/serve-organizations-mount-failure.e2e.test.ts index f199e27b9e..3722b6b715 100644 --- a/packages/cli/test/serve-organizations-mount-failure.e2e.test.ts +++ b/packages/cli/test/serve-organizations-mount-failure.e2e.test.ts @@ -164,7 +164,7 @@ describe('os serve — organizations import stage vs mount stage (#4818)', () => expect(stderr, `the absent-package diagnosis was lost${seen}`).toMatch(/could not be loaded/); // …and the escape hatch is still offered on the path it belongs to. expect(stderr).toMatch(/set OS_ALLOW_DEGRADED_TENANCY=1 to boot/); - expect(stdout, `serve served traffic without the wall${seen}`).not.toContain(BANNER); + expect(stderr, `serve served traffic without the wall${seen}`).not.toContain(BANNER); }, 300_000, ); @@ -183,7 +183,7 @@ describe('os serve — organizations import stage vs mount stage (#4818)', () => }); const seen = seenOf(stdout, stderr); - expect(stdout, `serve never reached its banner${seen}`).toContain(BANNER); + expect(stderr, `serve never reached its banner${seen}`).toContain(BANNER); expect(stderr, `the degraded boot was not branded${seen}`).toMatch(/DEGRADED TENANCY/); expect(stderr, `the degraded opt-in still fired the fail-fast${seen}`).not.toMatch(/✖ FATAL/); }, @@ -205,7 +205,7 @@ describe('os serve — organizations import stage vs mount stage (#4818)', () => // D5's posture is unchanged: isolation was requested and cannot be // delivered, so the boot still dies. - expect(stdout, `serve served traffic without the wall${seen}`).not.toContain(BANNER); + expect(stderr, `serve served traffic without the wall${seen}`).not.toContain(BANNER); expect(stderr, `no fail-fast fired for a refusing plugin${seen}`).toMatch(/✖ FATAL/); // The crux: the operator is told the package IS there, and reads the @@ -242,7 +242,7 @@ describe('os serve — organizations import stage vs mount stage (#4818)', () => const seen = seenOf(stdout, stderr); expect( - stdout, + stderr, `OS_ALLOW_DEGRADED_TENANCY swallowed a plugin refusal and served traffic${seen}`, ).not.toContain(BANNER); expect(stderr, `the refusal did not fail fast under the escape hatch${seen}`).toMatch(/✖ FATAL/); diff --git a/packages/cli/test/serve-stdio-stdout-purity.e2e.test.ts b/packages/cli/test/serve-stdio-stdout-purity.e2e.test.ts new file mode 100644 index 0000000000..183935def1 --- /dev/null +++ b/packages/cli/test/serve-stdio-stdout-purity.e2e.test.ts @@ -0,0 +1,338 @@ +// Copyright (c) 2026 ObjectStack. Licensed under the Apache-2.0 license. + +/** + * #7915 — with the stdio MCP transport mounted, `os serve` puts NOTHING but + * protocol frames on stdout. + * + * The defect: `OS_MCP_STDIO_ENABLED=true` makes `process.stdout` the JSON-RPC + * channel, while the same fd carried the CLI's banner and the kernel's + * `INFO`/`WARN` records. MCP stdio framing is newline-delimited JSON — a + * conforming client `JSON.parse`s every line it reads — so each of those lines + * reaches the client as a transport error. Measured on the card's repro: the + * `initialize` result arrived on line 517, behind 516 lines of non-protocol + * text. It reads as "the transport is broken", which is why it only became + * visible once #7645 (PR #7914) made the transport answer at all. + * + * ## Why this asserts on the STREAM, not on "the client parsed OK" + * + * A test that only writes `initialize` and checks the reply passes today for + * the wrong reason: the harness reads the child's pipe as one accumulating + * buffer and picks the frame out of it, so a short banner never bothers it. + * Only "every byte on stdout belongs to the protocol" fails when one line + * comes back — which is the invariant a real client actually depends on. + * + * ## The negative half + * + * Purity is trivially satisfiable by silence, and silence would be a worse bug + * than the noise: the operator loses the banner, the boot warnings and the + * kernel log. So the same run asserts the banner and the kernel's records are + * present on **stderr**. Moved, not deleted. + * + * ## Fixture cost + * + * stdio auto-start is fail-closed (ADR-0101): without an `OS_MCP_STDIO_API_KEY` + * that resolves to a real identity the plugin refuses to start, so there is no + * transport to measure. The first boot mints a key through the product route + * against a file-backed DB, exactly as `serve-mcp-stdio-answers.e2e.test.ts` + * (this file's sibling — that one pins that the transport ANSWERS, this one + * pins what else the channel carries). + */ + +import { describe, it, expect, beforeAll, afterAll } from 'vitest'; +import { spawn, type ChildProcessWithoutNullStreams } from 'node:child_process'; +import { mkdtempSync, rmSync, writeFileSync } from 'node:fs'; +import { tmpdir } from 'node:os'; +import { join, resolve } from 'node:path'; +import { fileURLToPath } from 'node:url'; +import { randomPort } from './helpers/serve-process.js'; + +const HERE = resolve(fileURLToPath(import.meta.url), '..'); +/** `bin/run.js` — the SHIPPED entrypoint, i.e. the one the card's repro names. */ +const CLI = resolve(HERE, '../bin/run.js'); + +const CONFIG = ` +export default { + manifest: { + id: 'com.example.stdoutpurity', + namespace: 'stdoutpurity', + version: '1.0.0', + type: 'app', + name: 'MCP stdout purity probe', + }, + objects: [{ + name: 'stdoutpurity_task', + label: 'Task', + sharingModel: 'public', + fields: { title: { type: 'text', label: 'Title' } }, + }], +}; +`; + +let dir: string; +let port: string; +let apiKey: string; +const children: ChildProcessWithoutNullStreams[] = []; + +interface Booted { + child: ChildProcessWithoutNullStreams; + stdout: () => string; + stderr: () => string; +} + +/** + * Spawn `os serve` and resolve once `waitFor` matches its output, leaving the + * child RUNNING. + * + * `waitFor` is matched against stdout and stderr TOGETHER. That is not a + * convenience: this file's whole subject is that the boot says nothing on + * stdout, so a stdout-only wait would time out on a healthy process. + * + * No positional config path, deliberately — `os serve --dev` is the form the + * card's repro and every user types (and the one whose oclif stdin handling + * #7645 had to fix). + */ +function boot(env: Record, waitFor: RegExp): Promise { + return new Promise((resolveBoot, rejectBoot) => { + const child = spawn(process.execPath, [CLI, 'serve', '-p', port, '--dev'], { + cwd: dir, + stdio: ['pipe', 'pipe', 'pipe'], + env: { + ...process.env, + NO_COLOR: '1', + // The card's own capture level. `warn` (the default) still puts the + // banner and the WARN records on the channel, so `info` is the same + // defect with more of it — the strictest setting this pin can run at. + OS_LOG_LEVEL: 'info', + OS_DISABLE_CONSOLE: '1', + // Explicit, not inherited: the dev-admin seed the mint signs in as is + // hard-gated on `NODE_ENV === 'development'`, and vitest exports `test`. + NODE_ENV: 'development', + ...env, + }, + }) as ChildProcessWithoutNullStreams; + children.push(child); + + let out = ''; + let err = ''; + let settled = false; + + const timer = setTimeout(() => { + if (settled) return; + settled = true; + rejectBoot( + new Error( + `serve never printed ${waitFor}\n--- stdout ---\n${out.slice(-4000)}\n--- stderr ---\n${err.slice(-4000)}`, + ), + ); + }, 150_000); + + const onOutput = () => { + if (settled || !waitFor.test(out + err)) return; + settled = true; + clearTimeout(timer); + resolveBoot({ child, stdout: () => out, stderr: () => err }); + }; + + child.stdout.on('data', (d) => { + out += String(d); + onOutput(); + }); + child.stderr.on('data', (d) => { + err += String(d); + onOutput(); + }); + child.on('exit', (code) => { + if (settled) return; + settled = true; + clearTimeout(timer); + rejectBoot( + new Error( + `serve exited ${code} before ${waitFor}\n--- stdout ---\n${out.slice(-4000)}\n--- stderr ---\n${err.slice(-4000)}`, + ), + ); + }); + }); +} + +async function stop(child: ChildProcessWithoutNullStreams): Promise { + if (child.exitCode !== null || child.signalCode !== null) return; + await new Promise((done) => { + const give = setTimeout(() => { + try { + child.kill('SIGKILL'); + } catch { + /* already gone */ + } + done(); + }, 10_000); + child.once('exit', () => { + clearTimeout(give); + done(); + }); + try { + child.kill('SIGTERM'); + } catch { + clearTimeout(give); + done(); + } + }); +} + +/** One line of the child's stdout, as a client's `ReadBuffer` would read it. */ +function parseFrame(line: string): Record | undefined { + try { + const msg = JSON.parse(line) as Record; + return msg && typeof msg === 'object' && msg.jsonrpc === '2.0' ? msg : undefined; + } catch { + return undefined; + } +} + +describe('#7915: a stdio MCP boot writes nothing but protocol frames to stdout', () => { + beforeAll(async () => { + dir = mkdtempSync(join(tmpdir(), 'mcp-stdout-purity-e2e-')); + writeFileSync(join(dir, 'objectstack.config.ts'), CONFIG, 'utf8'); + writeFileSync( + join(dir, 'package.json'), + JSON.stringify({ name: 'mcp-stdout-purity-e2e-fixture', private: true, type: 'module' }, null, 2), + 'utf8', + ); + port = randomPort(); + + // Boot 1 — mint a real key through the product route, against a FILE db so + // boot 2 sees the same row (`:memory:` would not survive the restart). + const first = await boot({ OS_DATABASE_URL: join(dir, 'probe.db') }, /Server is ready/); + const base = `http://localhost:${port}/api/v1`; + const signIn = await fetch(`${base}/auth/sign-in/email`, { + method: 'POST', + headers: { 'content-type': 'application/json' }, + body: JSON.stringify({ email: 'admin@objectos.ai', password: 'admin123' }), + }); + expect(signIn.status).toBe(200); + const token = ((await signIn.json()) as { token?: string }).token; + expect(token).toBeTruthy(); + + const minted = await fetch(`${base}/keys`, { + method: 'POST', + headers: { 'content-type': 'application/json', authorization: `Bearer ${token}` }, + body: JSON.stringify({ name: 'mcp-stdout-purity-e2e' }), + }); + expect(minted.status).toBe(201); + apiKey = String(((await minted.json()) as { data: { key: string } }).data.key); + expect(apiKey.startsWith('osk_')).toBe(true); + + await stop(first.child); + }, 240_000); + + afterAll(async () => { + for (const child of children) await stop(child); + if (dir) rmSync(dir, { recursive: true, force: true }); + }, 60_000); + + it('keeps stdout free of every non-frame byte, and keeps the diagnostics on stderr', async () => { + // Wait for the banner's LAST line, not for `[MCP] Server started`. The + // transport attaches inside `runtime.start()`, which the banner follows — + // so this waits for both facts, where the MCP line alone would let the + // assertions read a boot that had not printed its banner yet (measured: + // that is exactly what happened on the first run of this file). + const booted = await boot( + { + OS_DATABASE_URL: join(dir, 'probe.db'), + OS_MCP_STDIO_ENABLED: 'true', + OS_MCP_STDIO_API_KEY: apiKey, + }, + /Press Ctrl\+C to stop/, + ); + + // Speak the protocol, so the channel is exercised rather than merely quiet: + // an empty stdout would satisfy "no non-frame bytes" while the transport is + // broken, and that is the failure this file must NOT pass. + const reply = await new Promise((resolveReply) => { + let buf = ''; + const onData = (d: Buffer | string) => { + buf += String(d); + if (/"jsonrpc"\s*:\s*"2\.0"/.test(buf) && /"id"\s*:\s*1\b/.test(buf)) { + clearTimeout(giveUp); + booted.child.stdout.off('data', onData); + resolveReply(buf); + } + }; + booted.child.stdout.on('data', onData); + + const giveUp = setTimeout(() => { + booted.child.stdout.off('data', onData); + resolveReply(null); + }, 45_000); + + booted.child.stdin.write( + `${JSON.stringify({ + jsonrpc: '2.0', + id: 1, + method: 'initialize', + params: { + protocolVersion: '2024-11-05', + capabilities: {}, + clientInfo: { name: 'objectstack-e2e', version: '0.0.0' }, + }, + })}\n`, + ); + }); + + // Let the stream settle: the reply is detected on a regex, which can match + // before the frame's trailing newline has been delivered. + await new Promise((r) => setTimeout(r, 750)); + + const stdout = booted.stdout(); + const stderr = booted.stderr(); + const seen = `\n--- stdout ---\n${stdout.slice(0, 4000)}\n--- stderr (tail) ---\n${stderr.slice(-2000)}`; + + // ── The pin ──────────────────────────────────────────────────────── + // Every line the child has written to stdout since it was spawned — + // banner, boot progress and kernel log included, had any of them gone + // there — read exactly as a client's ReadBuffer reads them. + // + // The last element of the split is dropped either way: it is the empty + // string after a trailing newline, or a line the pipe has not finished + // delivering. A chunk boundary is not evidence of anything, and every line + // that matters is followed by another. + const nonFrameLines = stdout + .split('\n') + .slice(0, -1) + .filter((line) => line.length > 0) + .filter((line) => parseFrame(line) === undefined); + expect( + nonFrameLines, + `stdout carries ${nonFrameLines.length} line(s) a JSON-RPC client would fail to parse (#7915)${seen}`, + ).toEqual([]); + + // The transport really did answer on that clean channel (#7645's pin, kept + // here so purity can never be reached by breaking the channel). + expect(reply, `the stdio transport never answered \`initialize\`${seen}`).not.toBeNull(); + const frame = (reply as string) + .split('\n') + .map((line) => line.trim()) + .filter((line) => line.length > 0) + .map(parseFrame) + .find((msg) => msg?.id === 1); + expect(frame, `no parseable JSON-RPC frame for id 1${seen}`).toBeTruthy(); + expect(frame!.error).toBeUndefined(); + + // ── The negative half: moved, not silenced ───────────────────────── + // Purity is trivially satisfiable by silence; these say the output is on + // the other stream rather than gone. (`Press Ctrl+C to stop` is what the + // boot waited for above, so it is a tautology here — kept anyway, because + // it is the assertion that would have to be deleted, not merely relaxed, + // for the banner to disappear.) + expect(stderr, `the startup banner vanished instead of moving to stderr${seen}`).toContain( + 'Server is ready', + ); + expect(stderr, `the banner's tail is missing from stderr${seen}`).toContain('Press Ctrl+C to stop'); + // The kernel's own records — the second, independent source the card names. + // `[MCP] Server started` is one the boot always emits at INFO. + expect(stderr, `kernel log records are not reaching stderr${seen}`).toMatch( + /INFO .*\[MCP\] Server started \(transport: stdio/, + ); + + await stop(booted.child); + }, 240_000); +}); diff --git a/packages/mcp/src/mcp-server-runtime.ts b/packages/mcp/src/mcp-server-runtime.ts index 2930c69954..edb1918b8c 100644 --- a/packages/mcp/src/mcp-server-runtime.ts +++ b/packages/mcp/src/mcp-server-runtime.ts @@ -13,6 +13,7 @@ import type { RegisterObjectToolsOptions, RegisterActionToolsOptions, } from './mcp-http-tools.js'; +import { protocolStdout } from './protocol-stdout.js'; import { renderSkillMarkdown, type RenderSkillOptions } from './skill-md.js'; import { listSkillPrompts, @@ -1020,7 +1021,14 @@ export class MCPServerRuntime { const logger = this.config.logger; if (this.config.transport === 'stdio') { - this.transport = new StdioServerTransport(); + // [#7915] stdin as usual, stdout through the transport's OWN channel to + // the real stream. A host that boots this plugin must keep its banners + // and kernel logs off stdout (the framing is newline-delimited JSON), and + // the only way to move every writer at once is to intercept + // `process.stdout.write` — which would swallow these frames too. See + // protocol-stdout.ts for why the transport claims the channel itself + // rather than being handed one. + this.transport = new StdioServerTransport(process.stdin, protocolStdout()); await this.mcpServer.connect(this.transport); // [#7645] The transport now OWNS this process's stdin — so make sure it // is actually flowing. `StdioServerTransport.start()` only attaches a diff --git a/packages/mcp/src/protocol-stdout.test.ts b/packages/mcp/src/protocol-stdout.test.ts new file mode 100644 index 0000000000..d0a9f9b87d --- /dev/null +++ b/packages/mcp/src/protocol-stdout.test.ts @@ -0,0 +1,89 @@ +// Copyright (c) 2026 ObjectStack. Licensed under the Apache-2.0 license. + +/** + * #7915 — the stdio transport's channel survives a host that redirects stdout. + * + * `os serve` forwards everything written to `process.stdout` to stderr, for the + * whole life of the process, so its banner and the kernel's logs cannot corrupt + * the newline-delimited JSON the stdio transport speaks. That interception is + * an own property on `process.stdout`, and `StdioServerTransport.send()` + * resolves `this._stdout.write` per frame — so a transport left on the default + * `process.stdout` loses every frame to stderr. + * + * These cases are the two halves of that: frames reach the real stream even + * while an interception is installed, and the interception still catches + * everything else. + */ + +import { describe, it, expect, afterEach } from 'vitest'; +import { protocolStdout } from './protocol-stdout.js'; + +type StreamWrite = (chunk: string | Uint8Array, ...rest: unknown[]) => boolean; + +const originalWrite = process.stdout.write; + +afterEach(() => { + process.stdout.write = originalWrite; +}); + +describe('protocolStdout (#7915)', () => { + it('writes past an instance-level `process.stdout.write` interception', () => { + const swallowed: string[] = []; + const real: string[] = []; + + // Stand in for the real stream underneath, so the assertion does not depend + // on this test process's actual fd 1. + const proto = Object.getPrototypeOf(process.stdout) as { write: StreamWrite }; + const protoWrite = proto.write; + proto.write = function patchedProto(this: unknown, chunk: string | Uint8Array) { + real.push(String(chunk)); + return true; + } as StreamWrite; + + // The host's redirect: an OWN property, exactly as `redirectStdoutToStderr` + // installs it. + process.stdout.write = ((chunk: string | Uint8Array) => { + swallowed.push(String(chunk)); + return true; + }) as typeof process.stdout.write; + + try { + const channel = protocolStdout(); + channel.write('{"jsonrpc":"2.0","id":1,"result":{}}\n'); + + // The frame went to the real stream… + expect(real).toEqual(['{"jsonrpc":"2.0","id":1,"result":{}}\n']); + // …and NOT into the host's diagnostics forwarder. + expect(swallowed).toEqual([]); + + // The interception is still in force for everyone else — the channel is a + // hole for the protocol, not a release of the redirect. + process.stdout.write('a banner line\n'); + expect(swallowed).toEqual(['a banner line\n']); + } finally { + proto.write = protoWrite; + } + }); + + it('reports the real stream\'s backpressure and delegates `drain`', () => { + const proto = Object.getPrototypeOf(process.stdout) as { write: StreamWrite }; + const protoWrite = proto.write; + proto.write = (() => false) as StreamWrite; + + try { + const channel = protocolStdout(); + // `false` is what makes the SDK transport wait for `drain` instead of + // resolving — swallowing it would turn backpressure into lost frames. + expect(channel.write('{"jsonrpc":"2.0"}\n')).toBe(false); + + let drained = false; + channel.once('drain', () => { + drained = true; + }); + process.stdout.emit('drain'); + expect(drained).toBe(true); + } finally { + proto.write = protoWrite; + } + }); +}); diff --git a/packages/mcp/src/protocol-stdout.ts b/packages/mcp/src/protocol-stdout.ts new file mode 100644 index 0000000000..16b6dae0d3 --- /dev/null +++ b/packages/mcp/src/protocol-stdout.ts @@ -0,0 +1,71 @@ +// Copyright (c) 2026 ObjectStack. Licensed under the Apache-2.0 license. + +import type { Writable } from 'node:stream'; + +/** + * The stdout channel the **stdio MCP transport** writes its JSON-RPC frames to + * (#7915). + * + * ## Why this is not just `process.stdout` + * + * A stdio MCP session multiplexes nothing: stdout carries the protocol and + * NOTHING else, because the framing is newline-delimited JSON and a conforming + * client `JSON.parse`s every line it reads. A host that boots this plugin + * therefore has to put its own banners, boot progress and kernel logs somewhere + * else — and the only way to move `ObjectLogger` and every stray `console.log` + * in one place is to intercept `process.stdout.write` itself (`LoggerConfig` + * has a level but no destination knob). `os serve` does exactly that, + * unconditionally, for the whole life of the process + * (`packages/cli/src/utils/json-stdout.ts`). + * + * That interception is an OWN property on the `process.stdout` instance, and + * `StdioServerTransport.send()` resolves `this._stdout.write` per frame — so a + * transport constructed with the default `process.stdout` would have its frames + * forwarded to stderr along with the diagnostics, and the session would go + * silent in a way that reads exactly like #7645 (started, never answers). + * + * So the protocol channel is taken from the stream's PROTOTYPE: the same + * `write` implementation `process.stdout.write` normally resolves to, reached + * past any instance-level interception, with the real stream as `this` — real + * fd, real backpressure, no reimplementation of Node's stdout. + * + * ## Why the transport claims it unconditionally + * + * The alternative is for the host to hand its transport a channel ("the CLI + * knows it redirected stdout, so it passes the real one in"). That makes the + * protocol work or not work depending on WHO constructed the plugin — a + * user-authored `plugins: [new MCPServerPlugin()]` under the same `os serve` + * would be swallowed, silently. The transport owns stdout in every host by + * contract, so it holds the channel in every host too. + * + * ## Backpressure + * + * `write()` returns the real stream's boolean and `once('drain', …)` is + * delegated to the real stream, which is the whole surface the SDK transport + * uses (`if (this._stdout.write(json)) resolve(); else this._stdout.once('drain', resolve)`). + */ +export function protocolStdout(): Writable { + const stdout = process.stdout as unknown as { + write: (chunk: string | Uint8Array, ...rest: unknown[]) => boolean; + once: (event: string, listener: (...args: unknown[]) => void) => unknown; + }; + + // The prototype's `write`, i.e. the one an instance-level interception + // replaced. Falls back to the instance property when there is no prototype + // implementation to reach (never true for Node's stdout — TTY, pipe and file + // all inherit `write` — but a fallback beats a throw in an exotic runtime). + const proto = Object.getPrototypeOf(stdout) as { write?: typeof stdout.write } | null; + const directWrite = typeof proto?.write === 'function' ? proto.write : stdout.write; + + const channel = { + write(chunk: string | Uint8Array, ...rest: unknown[]): boolean { + return directWrite.call(stdout, chunk, ...rest); + }, + once(event: string, listener: (...args: unknown[]) => void) { + stdout.once(event, listener); + return channel; + }, + }; + + return channel as unknown as Writable; +}