From 1882eef6f6b1a29da94d87e0095b2c7813067ab1 Mon Sep 17 00:00:00 2001 From: Claude Date: Thu, 30 Jul 2026 09:09:01 +0000 Subject: [PATCH 1/2] fix(cli): serve's boot-quiet window buffers plugin log lines instead of discarding them (#4012) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit `serve` blanks stdout while the kernel boots so the startup banner is readable. That window dropped what it intercepted: process.stdout.write = (chunk, ...rest) => { if (bootQuiet) return true; // swallow ... }; `ObjectLogger` routes debug/info/warn to **stdout** and only error/fatal to stderr, so that one line swallowed every boot-phase `logger.warn` any plugin emits — the ADR-0110 D5 `[action-governance]` inventory, the automation engine's binding warnings, every degraded-boot notice. `os dev` spawns `serve` with inherited stdio, so one drain blinded both entrypoints, at every log level. Nothing above the CLI could see it: the kernel logged correctly and data-phase lines streamed fine, which is why `--log-level debug` could print 2,360 lines with zero boot-phase ones among them. It also inverted the flag's own promise — the default is `warn` precisely "so flow/hook execution failures surface (ADR-0032)". The window is worth keeping, so it becomes a buffer rather than a drain: - `BootLogCapture` (new) is a line-oriented, bounded sink for the intercepted bytes. It classifies each line against `ObjectLogger`'s three renderings (pretty/text/json, ANSI-stripped) and retains only records at warn or above, so buffer size tracks a boot's warnings rather than its chattiness. Chunks that split mid-line are carried, and a trailing unterminated record still flushes — that is the shape the last warning before a crash arrives in. - The retained records replay under the banner, beside the automation and seed summaries that already exist for exactly this reason. The startup chatter the window exists to hide is still dropped. - Three exits carry them, not just the healthy one: the banner, OS_MIGRATE_AND_EXIT (a deploy pipeline must not lose a degraded-boot warning), and serve's error path — a boot that died is when its warnings matter most, and it never reaches the banner. - At `--verbose` / `--log-level debug|info` the window no longer opens at all. Buffering a stream the operator explicitly asked to watch would be the flag defeating itself. Verified on `examples/app-todo`: before, `os serve` printed 25 lines with zero WARN among them; after, it surfaces 5 boot warnings including the `[action-governance]` line naming all 8 unbound actions. Same on `os dev`. Tests: 13 unit cases pin the classifier and the buffer, driving a REAL `ObjectLogger` through the real interception so a change to its line format fails here rather than silently reopening the hole. Two end-to-end cases boot a real stack through `bin/run-dev.js` and read its stdout, using a config-only positive control (a declared `script` action with no handler, which the D5 inventory always warns about). Both fail against the pre-fix command. Closes #4012 Co-Authored-By: Claude Opus 5 Claude-Session: https://claude.ai/code/session_01HrRNgrWaRtggzmrHpbomyh --- packages/cli/src/commands/serve.ts | 88 +++++-- .../cli/src/utils/boot-log-capture.test.ts | 230 ++++++++++++++++++ packages/cli/src/utils/boot-log-capture.ts | 198 +++++++++++++++ packages/cli/src/utils/format.ts | 49 ++++ .../test/serve-boot-diagnostics.e2e.test.ts | 203 ++++++++++++++++ 5 files changed, 749 insertions(+), 19 deletions(-) create mode 100644 packages/cli/src/utils/boot-log-capture.test.ts create mode 100644 packages/cli/src/utils/boot-log-capture.ts create mode 100644 packages/cli/test/serve-boot-diagnostics.e2e.test.ts diff --git a/packages/cli/src/commands/serve.ts b/packages/cli/src/commands/serve.ts index 58db52e3eb..3a9ec08b81 100644 --- a/packages/cli/src/commands/serve.ts +++ b/packages/cli/src/commands/serve.ts @@ -15,6 +15,7 @@ import { PLATFORM_CAPABILITY_TOKENS } from '@objectstack/spec/kernel'; import { missingProviderMessage } from '../utils/capability-preflight.js'; import { resolveObjectStackHome } from '@objectstack/runtime'; import { LOG_LEVELS, resolveLogLevel, readLogLevelEnv } from '../utils/log-level.js'; +import { BootLogCapture, isVerboseBootLevel } from '../utils/boot-log-capture.js'; import { redactConnectionUrl, describeDriverConnection } from '../utils/connection-display.js'; import { printHeader, @@ -24,6 +25,7 @@ import { printStep, printInfo, printServerReady, + printBootDiagnostics, type AutomationReadySummary, type SeedSourceSummary, } from '../utils/format.js'; @@ -176,7 +178,7 @@ export default class Serve extends Command { options: ['minimal', 'default', 'full'], }), 'log-level': Flags.string({ - description: 'Kernel logger level. Defaults to $OS_LOG_LEVEL / $LOG_LEVEL, else `warn` so flow/hook execution failures surface (ADR-0032). Use `silent` to fully quiet the runtime.', + description: 'Kernel logger level. Defaults to $OS_LOG_LEVEL / $LOG_LEVEL, else `warn` so flow/hook execution failures surface (ADR-0032). Boot-phase warnings are replayed under the startup banner; `debug`/`info` stream the whole boot live instead. Use `silent` to fully quiet the runtime.', options: [...LOG_LEVELS], }), verbose: Flags.boolean({ char: 'v', description: 'Verbose output — shortcut for --log-level debug.' }), @@ -554,11 +556,35 @@ export default class Serve extends Command { let resolvedDriverLabel: string | undefined; let resolvedDatabaseUrl: string | undefined; + // Resolve the kernel logger level up front. It decides more than the + // logger's own threshold: it decides whether the boot-quiet window below + // runs at all, so it has to be known BEFORE the window opens rather than + // at the `new Runtime(...)` call further down. + const bootLogLevel = resolveLogLevel({ + verbose: flags.verbose, + flag: flags['log-level'], + envLevel: readLogLevelEnv(), + }); + // `--verbose` / `--log-level debug|info` asks to watch the boot happen. + // Blanking stdout through it would be the flag defeating itself, so at + // those levels the window never opens and boot output streams live — the + // banner just prints at the end of it (#4012). + const verboseBoot = isVerboseBootLevel(bootLogLevel); + // Save original console/stdout methods — we'll suppress noise during boot 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). + const bootLogs = new BootLogCapture(); + /** Diagnostics to replay, or `undefined` when the boot had nothing to say. */ + const collectBootDiagnostics = () => { + const lines = bootLogs.diagnostics(); + return lines.length > 0 ? { lines, dropped: bootLogs.droppedCount } : undefined; + }; const restoreOutput = () => { bootQuiet = false; @@ -568,19 +594,34 @@ export default class Serve extends Command { }; try { - // ── Suppress ALL runtime noise during boot ──────────────────── + // ── Hold back runtime noise during boot ─────────────────────── // Multiple sources write to stdout during startup: // • Pino-pretty (direct process.stdout.write) // • ObjectLogger browser fallback (console.log) // • SchemaRegistry (console.log) - // We capture stdout entirely, then restore after runtime.start(). - bootQuiet = true; - process.stdout.write = (chunk: any, ...rest: any[]) => { - if (bootQuiet) return true; // swallow - return (origStdoutWrite as any)(chunk, ...rest); - }; - console.log = (...args: any[]) => { if (!bootQuiet) originalConsoleLog(...args); }; - console.debug = (...args: any[]) => { if (!bootQuiet) originalConsoleDebug(...args); }; + // We intercept stdout entirely, then restore after runtime.start(). + // + // Intercepted is not discarded (#4012): `ObjectLogger` routes `warn` to + // stdout — only `error`/`fatal` go to stderr — so dropping these bytes + // dropped every boot-phase warning a plugin logged, on both `os serve` + // and `os dev` (which inherits this child's stdio), at every log level. + // The chatter still never reaches the banner; the kernel-logger records + // among it are buffered and replayed once the banner has printed. + bootQuiet = !verboseBoot; + if (!verboseBoot) { + process.stdout.write = (chunk: any, ...rest: any[]) => { + if (bootQuiet) { + bootLogs.write(chunk, typeof rest[0] === 'string' ? rest[0] : undefined); + // Honor the write callback so a caller awaiting drain still resumes. + const cb = rest.find((a) => typeof a === 'function'); + if (cb) cb(); + return true; + } + return (origStdoutWrite as any)(chunk, ...rest); + }; + console.log = (...args: any[]) => { if (!bootQuiet) originalConsoleLog(...args); }; + console.debug = (...args: any[]) => { if (!bootQuiet) originalConsoleDebug(...args); }; + } // Load configuration // --prebuilt: load as native ESM (no esbuild, no bundle-require) — @@ -784,18 +825,13 @@ export default class Serve extends Command { // Import ObjectStack runtime const { Runtime } = await import('@objectstack/runtime'); - // Resolve the kernel logger level. Honors --verbose / --log-level and + // The kernel logger level. Honors --verbose / --log-level and // $OS_LOG_LEVEL / $LOG_LEVEL, defaulting to `warn` so flow/hook // execution failures surface even when the CLI manages its own output // (ADR-0032 "fail loudly"; see #1533). `--log-level silent` restores the - // old fully-quiet behavior. - const loggerConfig = { - level: resolveLogLevel({ - verbose: flags.verbose, - flag: flags['log-level'], - envLevel: readLogLevelEnv(), - }), - }; + // fully-quiet behavior. Resolved above the boot-quiet window, which + // keys off it too (#4012). + const loggerConfig = { level: bootLogLevel }; // Cluster wiring: env-driven driver selection (mirrors OS_DATABASE_URL). // The remote driver self-registers on import; import it dynamically so it @@ -2391,6 +2427,11 @@ export default class Serve extends Command { // never accept a request — shutdown immediately so the deploy // pipeline can move on. if (process.env.OS_MIGRATE_AND_EXIT === '1') { + // This path exits before the banner, so it has to replay the boot + // diagnostics itself — a deploy pipeline is precisely where a + // 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'})`)); try { await kernel.shutdown(); @@ -2469,6 +2510,11 @@ export default class Serve extends Command { seededAdmin, automation: automationSummary, seeds: seedSummary, + // #4012 — every boot-phase `logger.warn` the quiet window intercepted, + // replayed here. Without this the window is a drain: the ADR-0110 D5 + // `[action-governance]` inventory, degraded-boot notices and flow + // binding failures all reached stdout and none reached a terminal. + bootDiagnostics: collectBootDiagnostics(), // #3167 — surface the default-on MCP endpoint in the dev loop, where an // AI client can connect to operate the running app. Same decision point // that auto-loads the plugin + gates the route, so the banner never @@ -2512,6 +2558,10 @@ export default class Serve extends Command { restoreOutput(); console.log(''); 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). + const diagnostics = collectBootDiagnostics(); + if (diagnostics) printBootDiagnostics(diagnostics); if (process.env.DEBUG) console.error(chalk.dim(error.stack)); this.exit(1); } diff --git a/packages/cli/src/utils/boot-log-capture.test.ts b/packages/cli/src/utils/boot-log-capture.test.ts new file mode 100644 index 0000000000..60cfad8a22 --- /dev/null +++ b/packages/cli/src/utils/boot-log-capture.test.ts @@ -0,0 +1,230 @@ +// Copyright (c) 2026 ObjectStack. Licensed under the Apache-2.0 license. + +/** + * framework#4012 — `os dev` / `os serve` swallowed every plugin boot-phase log line. + * + * `serve` blanks stdout while the kernel boots so the startup banner is + * readable. `ObjectLogger` routes `debug`/`info`/`warn` to **stdout** (only + * `error`/`fatal` go to stderr), so for as long as that window discarded its + * bytes outright, no plugin's boot-phase `logger.warn` could reach a terminal — + * on either entrypoint, at any `--log-level`. `os dev` inherits the `serve` + * child's stdio, so one drain blinded both. Data-phase logging (after the + * window closes) streamed normally, which is exactly why the hole survived: + * `--log-level debug` printed thousands of lines and not one of them was from + * boot. + * + * The window is worth keeping, so it became a buffer: kernel-logger records are + * retained and replayed under the banner, and the rest of the startup chatter is + * still dropped. These tests pin both halves of that split — including against a + * REAL `ObjectLogger`, so a change to its line format fails here rather than + * silently re-opening the hole. + */ + +import { describe, it, expect } from 'vitest'; +import { ObjectLogger } from '@objectstack/core'; +import { + BootLogCapture, + classifyBootLogLine, + isBootDiagnostic, + isVerboseBootLevel, + stripAnsi, +} from './boot-log-capture.js'; + +/** ObjectLogger's `pretty` head, uncolored: ` `. */ +const pretty = (level: string, rest: string) => `2026-07-30T02:41:53.123Z ${level} ${rest}`; + +/** + * Reinstall the interception `serve` puts on stdout during boot, and hand the + * bytes to `capture` exactly as the command does. Restores on the way out. + */ +function underBootQuietWindow(capture: BootLogCapture, run: () => void): void { + const original = process.stdout.write.bind(process.stdout); + process.stdout.write = ((chunk: any, ...rest: any[]) => { + capture.write(chunk, typeof rest[0] === 'string' ? rest[0] : undefined); + const cb = rest.find((a) => typeof a === 'function'); + if (cb) cb(); + return true; + }) as typeof process.stdout.write; + try { + run(); + } finally { + process.stdout.write = original; + } +} + +describe('classifyBootLogLine', () => { + it('reads the level off every format ObjectLogger renders', () => { + expect(classifyBootLogLine(pretty('WARN', '[kernel] something degraded'))).toBe('warn'); + expect(classifyBootLogLine(pretty('DEBUG', 'Triggering kernel:ready hook'))).toBe('debug'); + expect(classifyBootLogLine(pretty('INFO', '✅ Bootstrap complete'))).toBe('info'); + // text: ` | LEVEL | message` + expect(classifyBootLogLine('2026-07-30T02:41:53.123Z | WARN | degraded')).toBe('warn'); + // json + expect( + classifyBootLogLine('{"time":"2026-07-30T02:41:53.123Z","level":"warn","msg":"degraded"}'), + ).toBe('warn'); + }); + + it('sees through the color ObjectLogger wraps the head in', () => { + // `${LEVEL_COLORS[level]}${ts} ${LEVEL}${RESET}${tail}` — the real shape + // when stdout is a TTY, which is the case that matters on a dev machine. + const colored = `\u001B[33m2026-07-30T02:41:53.123Z WARN\u001B[0m [action-governance] undeclared handler`; + expect(classifyBootLogLine(colored)).toBe('warn'); + expect(stripAnsi(colored)).toBe( + '2026-07-30T02:41:53.123Z WARN [action-governance] undeclared handler', + ); + }); + + it('does not mistake startup chatter for a logger record', () => { + // Everything the quiet window exists to hide must stay hidden, or the fix + // trades a silent boot for an unreadable banner. + for (const noise of [ + '', + ' ', + ' Loading objectstack.config.ts...', + '⠋ building', + 'ObjectStack v17.0.0', + '{ not json', + '{"msg":"no level or time"}', + '2026-07-30 02:41:53 WARN not-an-iso-timestamp', + 'WARN: leading level, no timestamp', + ]) { + expect(classifyBootLogLine(noise), noise).toBeNull(); + } + }); +}); + +describe('isBootDiagnostic', () => { + it('keeps warn and above, drops the info/debug chatter', () => { + expect(isBootDiagnostic(pretty('WARN', 'x'))).toBe(true); + expect(isBootDiagnostic(pretty('ERROR', 'x'))).toBe(true); + expect(isBootDiagnostic(pretty('FATAL', 'x'))).toBe(true); + expect(isBootDiagnostic(pretty('INFO', 'x'))).toBe(false); + expect(isBootDiagnostic(pretty('DEBUG', 'x'))).toBe(false); + expect(isBootDiagnostic(' Loading config...')).toBe(false); + }); +}); + +describe('isVerboseBootLevel', () => { + it('is the levels that ask to watch the boot happen', () => { + // At these the window never opens at all — buffering a stream the operator + // explicitly asked for would be the flag defeating itself. + expect(isVerboseBootLevel('debug')).toBe(true); + expect(isVerboseBootLevel('info')).toBe(true); + expect(isVerboseBootLevel('warn')).toBe(false); + expect(isVerboseBootLevel('error')).toBe(false); + expect(isVerboseBootLevel('fatal')).toBe(false); + expect(isVerboseBootLevel('silent')).toBe(false); + }); +}); + +describe('BootLogCapture', () => { + it('survives a record split across write chunks', () => { + // pino-pretty and ObjectLogger both write whole lines, but stdout chunking + // is not a guarantee — a fragment classified on its own is unparseable and + // would be dropped as noise. + const capture = new BootLogCapture(); + capture.write('2026-07-30T02:41:53.123Z WA'); + capture.write('RN [action-governance] undeclared handler\n'); + expect(capture.diagnostics()).toEqual([ + '2026-07-30T02:41:53.123Z WARN [action-governance] undeclared handler', + ]); + }); + + it('flushes a trailing record that never got its newline', () => { + // The last warning before a boot dies is exactly the one that arrives + // unterminated. + const capture = new BootLogCapture(); + capture.write(pretty('WARN', 'datasource unreachable — DEGRADED BOOT')); + expect(capture.diagnostics()).toEqual([ + '2026-07-30T02:41:53.123Z WARN datasource unreachable — DEGRADED BOOT', + ]); + }); + + it('keeps order, strips \\r, and drops the noise between records', () => { + const capture = new BootLogCapture(); + capture.write( + [ + ' Loading objectstack.config.ts...', + pretty('INFO', 'Phase 1: Init plugins'), + `${pretty('WARN', 'first')}\r`, + 'SchemaRegistry: 42 objects', + pretty('WARN', 'second'), + '', + ].join('\n'), + ); + expect(capture.diagnostics()).toEqual([ + '2026-07-30T02:41:53.123Z WARN first', + '2026-07-30T02:41:53.123Z WARN second', + ]); + }); + + it('is bounded — a boot that warns forever cannot grow the buffer forever', () => { + const capture = new BootLogCapture(120); + for (let i = 0; i < 50; i++) capture.write(`${pretty('WARN', `warning ${i}`)}\n`); + const kept = capture.diagnostics(); + expect(kept.length).toBeGreaterThan(0); + expect(kept.length).toBeLessThan(50); + expect(capture.droppedCount).toBe(50 - kept.length); + // The ones it did keep are the earliest — a boot's first warning is + // usually the cause and the rest the consequences. + expect(kept[0]).toContain('warning 0'); + }); + + it('holds nothing when a boot logged nothing', () => { + const capture = new BootLogCapture(); + capture.write(' Loading objectstack.config.ts...\n'); + expect(capture.diagnostics()).toEqual([]); + expect(capture.droppedCount).toBe(0); + }); +}); + +describe('the #4012 regression — a real ObjectLogger under the boot-quiet window', () => { + it('retains a boot-phase logger.warn that the window used to swallow', () => { + // The positive control from the issue: the ADR-0110 D5 inventory warns + // through `logger.warn`, lands on stdout, and vanished. Drive the REAL + // logger through the REAL interception and require it to come back out. + const capture = new BootLogCapture(); + const logger = new ObjectLogger({ level: 'warn' }); + + underBootQuietWindow(capture, () => { + logger.warn( + '[action-governance] registered handlers with NO declaration — these are REFUSED at dispatch', + { count: 1, handlers: ['todo:archive'] }, + ); + }); + + const diagnostics = capture.diagnostics(); + expect(diagnostics).toHaveLength(1); + expect(diagnostics[0]).toContain('[action-governance]'); + expect(diagnostics[0]).toContain('todo:archive'); + }); + + it('still keeps the banner clean when a host runs a chattier kernel level', () => { + // The window's whole purpose. A host that configures `info` gets its + // warnings replayed and its startup narration dropped. + const capture = new BootLogCapture(); + const logger = new ObjectLogger({ level: 'info' }); + + underBootQuietWindow(capture, () => { + logger.info('Phase 1: Init plugins'); + logger.info('Plugin registered: com.objectstack.todo@1.0.0'); + logger.warn('Service not provided — using in-memory fallback', { service: 'queue' }); + logger.info('✅ Bootstrap complete'); + }); + + const diagnostics = capture.diagnostics(); + expect(diagnostics).toHaveLength(1); + expect(diagnostics[0]).toContain('using in-memory fallback'); + expect(diagnostics.join('\n')).not.toContain('Bootstrap complete'); + }); + + it('captures error/fatal too, for the hosts that route them to stdout', () => { + // ObjectLogger sends these to stderr, which the window never touched — but + // the filter must not be the reason they would go missing if it did. + const capture = new BootLogCapture(); + capture.write(`${pretty('ERROR', 'Plugin startup failed: com.objectstack.todo')}\n`); + capture.write(`${pretty('FATAL', 'kernel unrecoverable')}\n`); + expect(capture.diagnostics()).toHaveLength(2); + }); +}); diff --git a/packages/cli/src/utils/boot-log-capture.ts b/packages/cli/src/utils/boot-log-capture.ts new file mode 100644 index 0000000000..d2545d2e71 --- /dev/null +++ b/packages/cli/src/utils/boot-log-capture.ts @@ -0,0 +1,198 @@ +// Copyright (c) 2026 ObjectStack. Licensed under the Apache-2.0 license. + +import type { CliLogLevel } from './log-level.js'; + +// --------------------------------------------------------------------------- +// Boot-phase log capture (#4012). +// +// `serve` blanks stdout while the kernel boots so the startup banner is not +// buried under startup chatter (pino-pretty, SchemaRegistry, plugin +// `console.log`). That window used to *discard* the bytes outright: +// +// process.stdout.write = (chunk, ...rest) => { +// if (bootQuiet) return true; // swallow +// ... +// }; +// +// `ObjectLogger` writes `debug`/`info`/`warn` to **stdout** and only +// `error`/`fatal` to stderr, so that one line swallowed every boot-phase +// `logger.warn` any plugin emits — the ADR-0110 D5 `[action-governance]` +// inventory, the automation engine's binding warnings, every degraded-boot +// notice — while data-phase logging (after the window closes) streamed fine. +// The CLI's `--log-level` help promises the opposite: it defaults to `warn` +// precisely "so flow/hook execution failures surface (ADR-0032)". +// +// The window itself is worth keeping, so the fix is to make it a *buffer* +// rather than a drain: retain the kernel-logger records that carry +// diagnostics and replay them once the banner has printed. Everything else in +// the window is the chatter the window exists to hide, and is still dropped. +// +// Capture is line-oriented and filters as it goes, so a long boot cannot grow +// the buffer past the diagnostics themselves. +// --------------------------------------------------------------------------- + +/** Levels `ObjectLogger` stamps onto a record, in severity order. */ +const LEVEL_ORDER = { + debug: 0, + info: 1, + warn: 2, + error: 3, + fatal: 4, +} as const; + +export type BootLogLevel = keyof typeof LEVEL_ORDER; + +/** + * Severity at or above which a boot-phase record is a *diagnostic* — something + * the operator needs to see even though the banner owns the screen. + * + * `warn` matches the CLI's own default kernel level: at that level the logger + * only emits `warn` (stdout) and `error`/`fatal` (stderr), so in practice every + * record that reaches this filter is already one an operator asked for. The + * floor still earns its keep when a *host* configures a chattier kernel level + * than the CLI flag — the banner stays clean instead of absorbing its info log. + */ +export const BOOT_DIAGNOSTIC_FLOOR: BootLogLevel = 'warn'; + +/** Default cap on retained diagnostics, in characters. */ +export const BOOT_LOG_CAPTURE_LIMIT = 256 * 1024; + +/** SGR color sequences — the head `ObjectLogger` wraps when stdout is a TTY. */ +const ANSI_SGR = /\u001B\[[0-9;]*m/g; + +/** + * `ObjectLogger`'s three renderings of one record, as emitted by + * `logger.write()`: + * + * pretty `2026-07-30T02:41:53.123Z WARN [name] message {"ctx":1}` + * text `2026-07-30T02:41:53.123Z | WARN | message | {"ctx":1}` + * json `{"time":"2026-07-30T02:41:53.123Z","level":"warn","msg":"…"}` + * + * `pretty` (the CLI's format — the kernel constructs the logger from a bare + * `{ level }`, so `ObjectLogger`'s own `'pretty'` default applies) colors the + * ` ` head, hence the ANSI strip before matching. + */ +const PRETTY_OR_TEXT = + /^\d{4}-\d{2}-\d{2}T\d{2}:\d{2}:\d{2}\.\d{3}Z(?: \|)? (DEBUG|INFO|WARN|ERROR|FATAL)\b/; + +/** Strip SGR color so a colored record classifies the same as a plain one. */ +export function stripAnsi(text: string): string { + return text.replace(ANSI_SGR, ''); +} + +/** + * Read the level off one raw stdout line, or `null` when the line is not a + * kernel-logger record (spinner frames, third-party banners, bare + * `console.log` — the noise the boot-quiet window exists to hide). + */ +export function classifyBootLogLine(raw: string): BootLogLevel | null { + const line = stripAnsi(raw).trim(); + if (!line) return null; + + if (line.startsWith('{')) { + let record: unknown; + try { + record = JSON.parse(line); + } catch { + return null; + } + const rec = record as { level?: unknown; time?: unknown } | null; + if (!rec || typeof rec.time !== 'string' || typeof rec.level !== 'string') return null; + const level = rec.level.toLowerCase(); + return level in LEVEL_ORDER ? (level as BootLogLevel) : null; + } + + const match = PRETTY_OR_TEXT.exec(line); + return match ? (match[1].toLowerCase() as BootLogLevel) : null; +} + +/** + * Whether a raw stdout line is a boot diagnostic worth replaying after the + * banner — a kernel-logger record at or above {@link BOOT_DIAGNOSTIC_FLOOR}. + */ +export function isBootDiagnostic(raw: string, floor: BootLogLevel = BOOT_DIAGNOSTIC_FLOOR): boolean { + const level = classifyBootLogLine(raw); + return level !== null && LEVEL_ORDER[level] >= LEVEL_ORDER[floor]; +} + +/** + * Whether the operator asked for a verbose kernel level. + * + * At `debug`/`info` the boot-quiet window is self-defeating: they opted into + * the stream, so `serve` skips quieting entirely and boot output goes live + * rather than being buffered and replayed. A clean banner is not worth a + * silent boot when the whole point of the flag is to watch one. + */ +export function isVerboseBootLevel(level: CliLogLevel): boolean { + return level === 'debug' || level === 'info'; +} + +/** + * Line-oriented, bounded sink for the bytes `serve`'s boot-quiet window would + * otherwise discard. Retains only diagnostics, so buffer size tracks the + * warnings a boot emits and not how chatty the boot was. + */ +export class BootLogCapture { + private carry = ''; + private retained: string[] = []; + private retainedChars = 0; + private dropped = 0; + + constructor( + private readonly limit: number = BOOT_LOG_CAPTURE_LIMIT, + private readonly floor: BootLogLevel = BOOT_DIAGNOSTIC_FLOOR, + ) {} + + /** + * Feed one `process.stdout.write` chunk. Chunks split mid-line, so the + * trailing fragment is carried into the next call rather than classified as + * its own (unparseable, therefore dropped) line. + */ + write(chunk: string | Uint8Array, encoding?: string): void { + const text = + typeof chunk === 'string' + ? chunk + : Buffer.from(chunk).toString( + // `encoding` arrives off `process.stdout.write`'s untyped varargs, + // so it is validated rather than trusted. + encoding && Buffer.isEncoding(encoding) ? encoding : 'utf8', + ); + + this.carry += text; + let newline = this.carry.indexOf('\n'); + while (newline !== -1) { + this.offer(this.carry.slice(0, newline)); + this.carry = this.carry.slice(newline + 1); + newline = this.carry.indexOf('\n'); + } + } + + private offer(line: string): void { + const trimmed = line.replace(/\r$/, ''); + if (!isBootDiagnostic(trimmed, this.floor)) return; + if (this.retainedChars + trimmed.length > this.limit) { + this.dropped += 1; + return; + } + this.retained.push(trimmed); + this.retainedChars += trimmed.length; + } + + /** + * The diagnostics to replay, in emission order. Flushes any trailing + * fragment that never got its newline — the last warning before a boot + * crash is exactly the one that tends to arrive unterminated. + */ + diagnostics(): string[] { + if (this.carry) { + this.offer(this.carry); + this.carry = ''; + } + return this.retained; + } + + /** Diagnostics discarded because the buffer was full. */ + get droppedCount(): number { + return this.dropped; + } +} diff --git a/packages/cli/src/utils/format.ts b/packages/cli/src/utils/format.ts index 56dd7564a0..b9b7b1acf8 100644 --- a/packages/cli/src/utils/format.ts +++ b/packages/cli/src/utils/format.ts @@ -311,6 +311,16 @@ export interface ServerReadyOptions { * rejections and empty installs are loud, a clean seed prints one dim line. */ seeds?: SeedSourceSummary[]; + /** + * Boot-phase kernel-logger diagnostics replayed from the boot-quiet stdout + * window (#4012). `ObjectLogger` writes `warn` to stdout, so that window + * used to discard every warning a plugin emitted while booting — the + * ADR-0110 D5 `[action-governance]` inventory, degraded-boot notices, flow + * binding failures — even though the CLI defaults the kernel to `warn` + * expressly so they surface (ADR-0032). `serve` now buffers them and hands + * them here, so they land under the banner instead of nowhere. + */ + bootDiagnostics?: BootDiagnostics; /** * Whether the MCP server surface (`/api/v1/mcp`) is on (#3167). Default-on * core capability, but nothing in the dev loop surfaces it — an AI client @@ -405,11 +415,50 @@ export function printServerReady(opts: ServerReadyOptions) { } 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(''); } +/** Boot-phase logger records held back by the boot-quiet window (#4012). */ +export interface BootDiagnostics { + /** Retained records, in emission order, exactly as the logger rendered them. */ + lines: string[]; + /** Records dropped because the capture buffer filled. */ + dropped?: number; +} + +/** + * Replay what the boot-quiet stdout window held back (#4012). + * + * `serve` blanks stdout while the kernel boots so the banner is readable, and + * `ObjectLogger` sends `warn` to stdout — so for as long as that window simply + * discarded its bytes, no plugin's boot-phase warning could reach a terminal on + * either `os dev` or `os serve`, at any `--log-level`. Data-phase logging was + * unaffected, which is why the hole stayed invisible: the stream looked alive. + * + * 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. + */ +export function printBootDiagnostics(diagnostics: BootDiagnostics) { + const { lines, dropped = 0 } = diagnostics; + if (lines.length === 0) return; + + console.log(''); + console.log( + chalk.yellow( + ` ⚠ Boot diagnostics — ${lines.length} warning${lines.length === 1 ? '' : 's'} logged during startup:`, + ), + ); + for (const line of lines) console.log(chalk.dim(` ${line}`)); + if (dropped > 0) { + console.log(chalk.dim(` …and ${dropped} more (capture buffer full)`)); + } + console.log(chalk.dim(' run with --log-level debug to watch the boot stream live')); +} + /** * One-glance answer to "did my flows actually arm?" — the question the * boot-quiet stdout window otherwise makes unanswerable (the engine's own diff --git a/packages/cli/test/serve-boot-diagnostics.e2e.test.ts b/packages/cli/test/serve-boot-diagnostics.e2e.test.ts new file mode 100644 index 0000000000..3e15871ae7 --- /dev/null +++ b/packages/cli/test/serve-boot-diagnostics.e2e.test.ts @@ -0,0 +1,203 @@ +// Copyright (c) 2026 ObjectStack. Licensed under the Apache-2.0 license. + +/** + * framework#4012 — boot-phase logger output over the REAL `os serve` process. + * + * `serve` blanks stdout while the kernel boots so the banner is readable, and + * `ObjectLogger` routes `warn` to stdout — so while that window discarded its + * bytes, no plugin's boot-phase warning reached a terminal on either CLI + * entrypoint (`os dev` spawns `serve` with inherited stdio, so one drain + * blinded both). Nothing above the CLI could see it: the kernel logged + * correctly, the sink was live, and every data-phase line streamed fine. + * + * 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 + * 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 + * `ctx.logger.warn`. + * + * That single assertion covers the whole class — it fails whenever boot-phase + * WARNs are swallowed, whatever re-introduces the swallowing. + */ + +import { describe, it, expect, beforeAll, afterAll } from 'vitest'; +import { execFile, spawn } from 'node:child_process'; +import { promisify } from 'node:util'; +import { mkdtempSync, rmSync, writeFileSync } from 'node:fs'; +import { tmpdir } from 'node:os'; +import { join, resolve } from 'node:path'; +import { fileURLToPath } from 'node:url'; + +const execFileP = promisify(execFile); + +const HERE = resolve(fileURLToPath(import.meta.url), '..'); +const CLI = resolve(HERE, '../bin/run-dev.js'); +const TSX = resolve(HERE, '../../../node_modules/.bin/tsx'); + +/** + * A stack whose only interesting property is that booting it MUST log a + * warning: `orphan_action` is a `script` action with no `body`, and nothing + * registers a handler under `neverRegistered` — ADR-0078's "button wired to + * nothing", which the D5 inventory warns about at `kernel:ready`. + */ +const CONFIG = ` +export default { + manifest: { + id: 'com.example.bootdiag', + namespace: 'bootdiag', + version: '1.0.0', + type: 'app', + name: 'Boot Diagnostics Fixture', + }, + objects: [{ + name: 'bootdiag_task', + label: 'Task', + sharingModel: 'private', + fields: { + title: { type: 'text', label: 'Title' }, + }, + actions: [{ + name: 'orphan_action', + label: 'Orphan', + type: 'script', + target: 'neverRegistered', + }], + }], +}; +`; + +interface ServeRun { + stdout: string; + stderr: string; +} + +/** + * Boot `os serve` in `cwd`, collect its output until the banner prints (or + * `waitFor` matches), then stop it. Never leaves the child running. + */ +function runServe( + cwd: string, + args: string[], + opts: { waitFor: RegExp; timeoutMs?: number }, +): Promise { + return new Promise((resolveRun, rejectRun) => { + const child = spawn(TSX, [CLI, 'serve', 'objectstack.config.ts', ...args], { + cwd, + env: { + ...process.env, + NO_COLOR: '1', + // Keep the fixture self-contained: no file written, no port conflict + // with another agent's dev server, no inherited log level. + OS_DATABASE_URL: ':memory:', + OS_LOG_LEVEL: '', + OS_DISABLE_CONSOLE: '1', + }, + }); + + let stdout = ''; + let stderr = ''; + let settled = false; + + const finish = (err?: Error) => { + if (settled) return; + settled = true; + clearTimeout(timer); + try { + child.kill('SIGTERM'); + } catch { + /* already gone */ + } + if (err) rejectRun(err); + else resolveRun({ stdout, stderr }); + }; + + const timer = setTimeout( + () => + finish( + new Error( + `serve did not reach ${opts.waitFor} in time.\n--- stdout ---\n${stdout}\n--- stderr ---\n${stderr}`, + ), + ), + opts.timeoutMs ?? 180_000, + ); + + child.stdout.on('data', (d) => { + stdout += String(d); + if (opts.waitFor.test(stdout)) finish(); + }); + child.stderr.on('data', (d) => { + stderr += String(d); + }); + child.on('error', (err) => finish(err)); + // A boot that dies still has to have said why — resolve rather than reject + // so the assertions can read what it printed on the way down. + child.on('exit', () => finish()); + }); +} + +let dir: string; + +beforeAll(async () => { + dir = mkdtempSync(join(tmpdir(), 'os-boot-diagnostics-e2e-')); + writeFileSync(join(dir, 'objectstack.config.ts'), CONFIG, 'utf8'); + // `serve` needs the compiled artifact beside the config: booting from the + // config alone currently dies in `AppPlugin` with "Service 'manifest' is + // async - use await" (reproducible on `examples/app-todo` too, by moving its + // `dist/objectstack.json` aside) — a separate, pre-existing defect, filed + // rather than worked around here. + await execFileP(TSX, [CLI, 'compile'], { + cwd: dir, + maxBuffer: 16 * 1024 * 1024, + env: { ...process.env, NO_COLOR: '1' }, + }); +}, 240_000); + +afterAll(() => { + if (dir) rmSync(dir, { recursive: true, force: true }); +}); + +describe('os serve — boot-phase logger output (#4012)', () => { + it( + 'prints the boot WARN a plugin logged while the banner was being assembled', + async () => { + // Random high port: never contend with a dev server this machine is + // already running (AGENTS.md multi-agent discipline §8). + const port = String(40000 + Math.floor(Math.random() * 20000)); + const { stdout, stderr } = await runServe(dir, ['--port', port], { + waitFor: /Press Ctrl\+C to stop/, + }); + + const seen = `\n--- stdout ---\n${stdout}\n--- stderr ---\n${stderr}`; + + // 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( + '[action-governance]', + ); + // …and it names the offender, so the line is actionable rather than just + // present. + expect(stdout).toContain('bootdiag_task:orphan_action'); + }, + 240_000, + ); + + it( + 'streams boot output live at --log-level debug instead of hiding it', + async () => { + // The issue's damning evidence: `--log-level debug` emitted 2,360 lines, + // none of them from boot — not even the kernel's own plain + // `logger.debug('Triggering kernel:ready hook')`. At a verbose level the + // quiet window no longer opens at all. + const port = String(40000 + Math.floor(Math.random() * 20000)); + const { stdout, stderr } = await runServe(dir, ['--port', port, '--log-level', 'debug'], { + waitFor: /Press Ctrl\+C to stop/, + }); + + 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]'); + }, + 240_000, + ); +}); From 3f43c36fd3ca3572860c0d997e466c35606af339 Mon Sep 17 00:00:00 2001 From: Claude Date: Thu, 30 Jul 2026 09:11:01 +0000 Subject: [PATCH 2/2] chore(changeset): add changeset for the serve boot-log visibility fix (#4012) Co-Authored-By: Claude Opus 5 Claude-Session: https://claude.ai/code/session_01HrRNgrWaRtggzmrHpbomyh --- .changeset/serve-boot-log-visibility.md | 38 +++++++++++++++++++++++++ 1 file changed, 38 insertions(+) create mode 100644 .changeset/serve-boot-log-visibility.md diff --git a/.changeset/serve-boot-log-visibility.md b/.changeset/serve-boot-log-visibility.md new file mode 100644 index 0000000000..28874031f4 --- /dev/null +++ b/.changeset/serve-boot-log-visibility.md @@ -0,0 +1,38 @@ +--- +'@objectstack/cli': patch +--- + +**`os dev` / `os serve` stop swallowing every plugin boot-phase log line — the +boot-quiet window buffers instead of discarding (#4012).** + +`serve` blanks stdout while the kernel boots so the startup banner is readable, +and dropped what it intercepted. `ObjectLogger` routes `debug`/`info`/`warn` to +**stdout** — only `error`/`fatal` go to stderr — so that one line swallowed +every boot-phase `logger.warn` any plugin emits: the ADR-0110 D5 +`[action-governance]` inventory, the automation engine's binding warnings, +every degraded-boot notice. `os dev` spawns `serve` with inherited stdio, so a +single drain blinded both entrypoints at every log level, and it inverted the +flag's own promise — the default is `warn` precisely "so flow/hook execution +failures surface (ADR-0032)". Data-phase logging was unaffected, which is why +the hole survived: `--log-level debug` printed thousands of lines with none +from boot. + +- The intercepted bytes now land in a line-oriented, bounded `BootLogCapture` + that classifies each line against `ObjectLogger`'s pretty/text/json + renderings and retains only records at `warn` or above, so buffer size tracks + a boot's warnings rather than its chattiness. The startup chatter the window + exists to hide is still dropped. +- Retained records replay under the banner, beside the automation and seed + summaries that exist for exactly this reason — and on the two exits that + never reach the banner: `OS_MIGRATE_AND_EXIT` (a deploy pipeline must not + lose a degraded-boot warning) and serve's error path, where a boot that died + is when its warnings matter most. +- `--verbose` / `--log-level debug|info` no longer open the window at all. + Buffering a stream the operator explicitly asked to watch would be the flag + defeating itself. + +On `examples/app-todo`, `os serve` went from 25 lines with zero WARN among them +to surfacing five boot warnings, including the `[action-governance]` line +naming all eight unbound actions. This closes the loop the D5 inventory +changeset left open: the inventory was already emitted correctly and is now +visible on the platform's own dev loop.