fix(cli): serve diagnostics to stderr so the stdio MCP channel carries only protocol (#7915)

.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.

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.

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<void> {
  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).

packages/cli/src/commands/start.ts

@@ -1,14 +1,15 @@
 // 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';
 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<void> {
  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.

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(' '));
  });
  });