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. 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, + ); +});