Skip to content

Commit 7ac1995

Browse files
authored
fix(cli): serve's boot-quiet window buffers plugin log lines instead of discarding them (#4012) (#4084)
`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 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, inverting the flag's own promise (the default is `warn` precisely "so flow/hook execution failures surface", ADR-0032). The window becomes a buffer rather than a drain: - `BootLogCapture` is a line-oriented, bounded sink that classifies each intercepted 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. - Retained records replay under the banner, and on the two exits that never reach it: OS_MIGRATE_AND_EXIT and serve's error path. - `--verbose` / `--log-level debug|info` no longer open the window at all. On examples/app-todo, `os serve` went from 25 lines with zero WARN to surfacing five boot warnings including the `[action-governance]` line naming all eight unbound actions. Same on `os dev`. 13 unit cases drive a real ObjectLogger through the real interception; 2 e2e cases boot a real stack through bin/run-dev.js and read its stdout. Both e2e cases fail against the pre-fix command. Closes #4012
1 parent 2af1988 commit 7ac1995

6 files changed

Lines changed: 787 additions & 19 deletions

File tree

Lines changed: 38 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,38 @@
1+
---
2+
'@objectstack/cli': patch
3+
---
4+
5+
**`os dev` / `os serve` stop swallowing every plugin boot-phase log line — the
6+
boot-quiet window buffers instead of discarding (#4012).**
7+
8+
`serve` blanks stdout while the kernel boots so the startup banner is readable,
9+
and dropped what it intercepted. `ObjectLogger` routes `debug`/`info`/`warn` to
10+
**stdout** — only `error`/`fatal` go to stderr — so that one line swallowed
11+
every boot-phase `logger.warn` any plugin emits: the ADR-0110 D5
12+
`[action-governance]` inventory, the automation engine's binding warnings,
13+
every degraded-boot notice. `os dev` spawns `serve` with inherited stdio, so a
14+
single drain blinded both entrypoints at every log level, and it inverted the
15+
flag's own promise — the default is `warn` precisely "so flow/hook execution
16+
failures surface (ADR-0032)". Data-phase logging was unaffected, which is why
17+
the hole survived: `--log-level debug` printed thousands of lines with none
18+
from boot.
19+
20+
- The intercepted bytes now land in a line-oriented, bounded `BootLogCapture`
21+
that classifies each line against `ObjectLogger`'s pretty/text/json
22+
renderings and retains only records at `warn` or above, so buffer size tracks
23+
a boot's warnings rather than its chattiness. The startup chatter the window
24+
exists to hide is still dropped.
25+
- Retained records replay under the banner, beside the automation and seed
26+
summaries that exist for exactly this reason — and on the two exits that
27+
never reach the banner: `OS_MIGRATE_AND_EXIT` (a deploy pipeline must not
28+
lose a degraded-boot warning) and serve's error path, where a boot that died
29+
is when its warnings matter most.
30+
- `--verbose` / `--log-level debug|info` no longer open the window at all.
31+
Buffering a stream the operator explicitly asked to watch would be the flag
32+
defeating itself.
33+
34+
On `examples/app-todo`, `os serve` went from 25 lines with zero WARN among them
35+
to surfacing five boot warnings, including the `[action-governance]` line
36+
naming all eight unbound actions. This closes the loop the D5 inventory
37+
changeset left open: the inventory was already emitted correctly and is now
38+
visible on the platform's own dev loop.

packages/cli/src/commands/serve.ts

Lines changed: 69 additions & 19 deletions
Original file line numberDiff line numberDiff line change
@@ -15,6 +15,7 @@ import { PLATFORM_CAPABILITY_TOKENS } from '@objectstack/spec/kernel';
1515
import { missingProviderMessage } from '../utils/capability-preflight.js';
1616
import { resolveObjectStackHome } from '@objectstack/runtime';
1717
import { LOG_LEVELS, resolveLogLevel, readLogLevelEnv } from '../utils/log-level.js';
18+
import { BootLogCapture, isVerboseBootLevel } from '../utils/boot-log-capture.js';
1819
import { redactConnectionUrl, describeDriverConnection } from '../utils/connection-display.js';
1920
import {
2021
printHeader,
@@ -24,6 +25,7 @@ import {
2425
printStep,
2526
printInfo,
2627
printServerReady,
28+
printBootDiagnostics,
2729
type AutomationReadySummary,
2830
type SeedSourceSummary,
2931
} from '../utils/format.js';
@@ -176,7 +178,7 @@ export default class Serve extends Command {
176178
options: ['minimal', 'default', 'full'],
177179
}),
178180
'log-level': Flags.string({
179-
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.',
181+
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.',
180182
options: [...LOG_LEVELS],
181183
}),
182184
verbose: Flags.boolean({ char: 'v', description: 'Verbose output — shortcut for --log-level debug.' }),
@@ -554,11 +556,35 @@ export default class Serve extends Command {
554556
let resolvedDriverLabel: string | undefined;
555557
let resolvedDatabaseUrl: string | undefined;
556558

559+
// Resolve the kernel logger level up front. It decides more than the
560+
// logger's own threshold: it decides whether the boot-quiet window below
561+
// runs at all, so it has to be known BEFORE the window opens rather than
562+
// at the `new Runtime(...)` call further down.
563+
const bootLogLevel = resolveLogLevel({
564+
verbose: flags.verbose,
565+
flag: flags['log-level'],
566+
envLevel: readLogLevelEnv(),
567+
});
568+
// `--verbose` / `--log-level debug|info` asks to watch the boot happen.
569+
// Blanking stdout through it would be the flag defeating itself, so at
570+
// those levels the window never opens and boot output streams live — the
571+
// banner just prints at the end of it (#4012).
572+
const verboseBoot = isVerboseBootLevel(bootLogLevel);
573+
557574
// Save original console/stdout methods — we'll suppress noise during boot
558575
const originalConsoleLog = console.log;
559576
const originalConsoleDebug = console.debug;
560577
const origStdoutWrite = process.stdout.write.bind(process.stdout);
561578
let bootQuiet = false;
579+
// Everything the quiet window intercepts lands here instead of being
580+
// dropped on the floor, so boot-phase `logger.warn` survives to be
581+
// replayed under the banner (#4012).
582+
const bootLogs = new BootLogCapture();
583+
/** Diagnostics to replay, or `undefined` when the boot had nothing to say. */
584+
const collectBootDiagnostics = () => {
585+
const lines = bootLogs.diagnostics();
586+
return lines.length > 0 ? { lines, dropped: bootLogs.droppedCount } : undefined;
587+
};
562588

563589
const restoreOutput = () => {
564590
bootQuiet = false;
@@ -568,19 +594,34 @@ export default class Serve extends Command {
568594
};
569595

570596
try {
571-
// ── Suppress ALL runtime noise during boot ────────────────────
597+
// ── Hold back runtime noise during boot ───────────────────────
572598
// Multiple sources write to stdout during startup:
573599
// • Pino-pretty (direct process.stdout.write)
574600
// • ObjectLogger browser fallback (console.log)
575601
// • SchemaRegistry (console.log)
576-
// We capture stdout entirely, then restore after runtime.start().
577-
bootQuiet = true;
578-
process.stdout.write = (chunk: any, ...rest: any[]) => {
579-
if (bootQuiet) return true; // swallow
580-
return (origStdoutWrite as any)(chunk, ...rest);
581-
};
582-
console.log = (...args: any[]) => { if (!bootQuiet) originalConsoleLog(...args); };
583-
console.debug = (...args: any[]) => { if (!bootQuiet) originalConsoleDebug(...args); };
602+
// We intercept stdout entirely, then restore after runtime.start().
603+
//
604+
// Intercepted is not discarded (#4012): `ObjectLogger` routes `warn` to
605+
// stdout — only `error`/`fatal` go to stderr — so dropping these bytes
606+
// dropped every boot-phase warning a plugin logged, on both `os serve`
607+
// and `os dev` (which inherits this child's stdio), at every log level.
608+
// The chatter still never reaches the banner; the kernel-logger records
609+
// among it are buffered and replayed once the banner has printed.
610+
bootQuiet = !verboseBoot;
611+
if (!verboseBoot) {
612+
process.stdout.write = (chunk: any, ...rest: any[]) => {
613+
if (bootQuiet) {
614+
bootLogs.write(chunk, typeof rest[0] === 'string' ? rest[0] : undefined);
615+
// Honor the write callback so a caller awaiting drain still resumes.
616+
const cb = rest.find((a) => typeof a === 'function');
617+
if (cb) cb();
618+
return true;
619+
}
620+
return (origStdoutWrite as any)(chunk, ...rest);
621+
};
622+
console.log = (...args: any[]) => { if (!bootQuiet) originalConsoleLog(...args); };
623+
console.debug = (...args: any[]) => { if (!bootQuiet) originalConsoleDebug(...args); };
624+
}
584625

585626
// Load configuration
586627
// --prebuilt: load as native ESM (no esbuild, no bundle-require) —
@@ -784,18 +825,13 @@ export default class Serve extends Command {
784825
// Import ObjectStack runtime
785826
const { Runtime } = await import('@objectstack/runtime');
786827

787-
// Resolve the kernel logger level. Honors --verbose / --log-level and
828+
// The kernel logger level. Honors --verbose / --log-level and
788829
// $OS_LOG_LEVEL / $LOG_LEVEL, defaulting to `warn` so flow/hook
789830
// execution failures surface even when the CLI manages its own output
790831
// (ADR-0032 "fail loudly"; see #1533). `--log-level silent` restores the
791-
// old fully-quiet behavior.
792-
const loggerConfig = {
793-
level: resolveLogLevel({
794-
verbose: flags.verbose,
795-
flag: flags['log-level'],
796-
envLevel: readLogLevelEnv(),
797-
}),
798-
};
832+
// fully-quiet behavior. Resolved above the boot-quiet window, which
833+
// keys off it too (#4012).
834+
const loggerConfig = { level: bootLogLevel };
799835

800836
// Cluster wiring: env-driven driver selection (mirrors OS_DATABASE_URL).
801837
// The remote driver self-registers on import; import it dynamically so it
@@ -2391,6 +2427,11 @@ export default class Serve extends Command {
23912427
// never accept a request — shutdown immediately so the deploy
23922428
// pipeline can move on.
23932429
if (process.env.OS_MIGRATE_AND_EXIT === '1') {
2430+
// This path exits before the banner, so it has to replay the boot
2431+
// diagnostics itself — a deploy pipeline is precisely where a
2432+
// degraded-boot warning must not vanish (#4012).
2433+
const migrateDiagnostics = collectBootDiagnostics();
2434+
if (migrateDiagnostics) printBootDiagnostics(migrateDiagnostics);
23942435
console.log(chalk.green(`✓ Migration complete (${loadedPlugins.length} plugins started against ${resolvedDatabaseUrl ? redactConnectionUrl(resolvedDatabaseUrl) : 'configured DB'})`));
23952436
try {
23962437
await kernel.shutdown();
@@ -2469,6 +2510,11 @@ export default class Serve extends Command {
24692510
seededAdmin,
24702511
automation: automationSummary,
24712512
seeds: seedSummary,
2513+
// #4012 — every boot-phase `logger.warn` the quiet window intercepted,
2514+
// replayed here. Without this the window is a drain: the ADR-0110 D5
2515+
// `[action-governance]` inventory, degraded-boot notices and flow
2516+
// binding failures all reached stdout and none reached a terminal.
2517+
bootDiagnostics: collectBootDiagnostics(),
24722518
// #3167 — surface the default-on MCP endpoint in the dev loop, where an
24732519
// AI client can connect to operate the running app. Same decision point
24742520
// that auto-loads the plugin + gates the route, so the banner never
@@ -2512,6 +2558,10 @@ export default class Serve extends Command {
25122558
restoreOutput();
25132559
console.log('');
25142560
printError(error.message || String(error));
2561+
// A boot that died is when its warnings matter most, and the banner that
2562+
// would normally carry them never printed (#4012).
2563+
const diagnostics = collectBootDiagnostics();
2564+
if (diagnostics) printBootDiagnostics(diagnostics);
25152565
if (process.env.DEBUG) console.error(chalk.dim(error.stack));
25162566
this.exit(1);
25172567
}

0 commit comments

Comments
 (0)