diff --git a/.changeset/lucky-pears-arrive.md b/.changeset/lucky-pears-arrive.md new file mode 100644 index 0000000000..67de3b75d4 --- /dev/null +++ b/.changeset/lucky-pears-arrive.md @@ -0,0 +1,25 @@ +--- +'@objectstack/cli': patch +--- + +fix(cli): `--json` now owns stdout — kernel boot logs move to stderr (#6217) + +Every `os migrate` / `os meta` subcommand that boots a kernel wrote its +machine-readable payload into a stream it shared with ~60 INFO lines. The +kernel logger routes `debug`/`info`/`warn` to stdout and only `error`/`fatal` +to stderr, so `os migrate recorded-by --json | jq .` failed with `parse error: +Invalid numeric literal` while stderr sat completely empty — a `--json` flag +whose only audience is a program, handing that program something it cannot +parse. + +With this change, a `--json` run reserves stdout for its payload: everything +the kernel and its plugins write goes to **stderr** instead, including the +`[StandaloneStack] no compiled artifact …` notice that never went through the +logger at all. `JSON.parse()` now succeeds with no heuristic +extraction, and no diagnostic is lost — every line an operator used to see is +still printed, on the stream diagnostics belong on. + +Covers the whole family that shares the boot seam: `os migrate plan` / `apply` +/ `resume` / `recorded-by` / `summary-nulls` / `value-shapes` / +`files-to-references`, `os migrate meta --stored`, and `os meta resync`. +Human-mode runs are unchanged. diff --git a/packages/cli/src/commands/meta/resync.ts b/packages/cli/src/commands/meta/resync.ts index f648fcc77f..82708c77e8 100644 --- a/packages/cli/src/commands/meta/resync.ts +++ b/packages/cli/src/commands/meta/resync.ts @@ -83,7 +83,7 @@ export default class MetaResync extends Command { let stack; try { - stack = await bootSchemaStack({ databaseUrl: flags['database-url'] }); + stack = await bootSchemaStack({ jsonOutput: flags.json, databaseUrl: flags['database-url'] }); } catch (error: any) { if (flags.json) await emitJson({ error: error.message }, 0, { compact: true }); else printError(error.message || String(error)); diff --git a/packages/cli/src/commands/migrate/apply.ts b/packages/cli/src/commands/migrate/apply.ts index acbb32caae..220e98e78a 100644 --- a/packages/cli/src/commands/migrate/apply.ts +++ b/packages/cli/src/commands/migrate/apply.ts @@ -126,7 +126,7 @@ export default class MigrateApply extends Command { try { // `deferSchemaDdl` is what makes the prompt below meaningful: without it // the boot has already created tables and added columns by this point. - stack = await bootSchemaStack({ databaseUrl: flags['database-url'], deferSchemaDdl: true }); + stack = await bootSchemaStack({ jsonOutput: flags.json, databaseUrl: flags['database-url'], deferSchemaDdl: true }); } catch (error: any) { if (flags.json) { await emitJson({ error: error.message }, 0, { compact: true }); this.exit(1); } printError(error.message || String(error)); diff --git a/packages/cli/src/commands/migrate/files-to-references.ts b/packages/cli/src/commands/migrate/files-to-references.ts index a48cfa58b9..35ebb9a763 100644 --- a/packages/cli/src/commands/migrate/files-to-references.ts +++ b/packages/cli/src/commands/migrate/files-to-references.ts @@ -161,6 +161,7 @@ export default class MigrateFilesToReferences extends Command { let stack; try { stack = await bootSchemaStack({ + jsonOutput: flags.json, databaseUrl: flags['database-url'], extraPlugins: await buildDataMigrationPlugins({ storage: true }), }); diff --git a/packages/cli/src/commands/migrate/meta.stored-flow-resolution.integration.test.ts b/packages/cli/src/commands/migrate/meta.stored-flow-resolution.integration.test.ts index 43d8e02dee..9dcaa8da8f 100644 --- a/packages/cli/src/commands/migrate/meta.stored-flow-resolution.integration.test.ts +++ b/packages/cli/src/commands/migrate/meta.stored-flow-resolution.integration.test.ts @@ -94,6 +94,7 @@ describe('os migrate meta --stored — the protocol resolves the engine itself ( it('rewrites a pre-17 flow row with NO canonicalizeFlow passed by the command', async () => { const stack = await bootSchemaStack({ + jsonOutput: false, databaseUrl: `file:${dbFile}`, projectRoot: dir, extraPlugins: await buildDataMigrationPlugins({ automation: true }), @@ -163,6 +164,7 @@ describe('os migrate meta --stored — the protocol resolves the engine itself ( // verbatim and leave the row `pending` forever; `saveMetaItem` now // canonicalizes flow bodies before its schema gate. const stack = await bootSchemaStack({ + jsonOutput: false, databaseUrl: `file:${dbFile}`, projectRoot: dir, extraPlugins: await buildDataMigrationPlugins({ automation: true }), @@ -223,6 +225,7 @@ describe('os migrate meta --stored — the protocol resolves the engine itself ( // The honest negative: the coverage comes from the engine being present, // not from the report defaulting to optimistic. const stack = await bootSchemaStack({ + jsonOutput: false, databaseUrl: `file:${dbFile}`, projectRoot: dir, extraPlugins: await buildDataMigrationPlugins(), diff --git a/packages/cli/src/commands/migrate/meta.ts b/packages/cli/src/commands/migrate/meta.ts index d5b9a8dae8..ef0e52d384 100644 --- a/packages/cli/src/commands/migrate/meta.ts +++ b/packages/cli/src/commands/migrate/meta.ts @@ -518,6 +518,7 @@ export default class MigrateMeta extends Command { // nothing. No storage adapter: unlike the file migration, nothing here // reads bytes. stack = await bootSchemaStack({ + jsonOutput: flags.json, ...(flags['database-url'] ? { databaseUrl: flags['database-url'] } : {}), extraPlugins: await buildDataMigrationPlugins({ automation: true }), }); diff --git a/packages/cli/src/commands/migrate/plan.ts b/packages/cli/src/commands/migrate/plan.ts index 9f9f5ea0ec..5b87b9dd23 100644 --- a/packages/cli/src/commands/migrate/plan.ts +++ b/packages/cli/src/commands/migrate/plan.ts @@ -77,7 +77,7 @@ export default class MigratePlan extends Command { let stack; try { - stack = await bootSchemaStack({ databaseUrl: flags['database-url'], deferSchemaDdl: true }); + stack = await bootSchemaStack({ jsonOutput: flags.json, databaseUrl: flags['database-url'], deferSchemaDdl: true }); } catch (error: any) { if (flags.json) { await emitJson({ error: error.message }, 0, { compact: true }); this.exit(1); } printError(error.message || String(error)); diff --git a/packages/cli/src/commands/migrate/recorded-by.ts b/packages/cli/src/commands/migrate/recorded-by.ts index 793f059b92..cef253c566 100644 --- a/packages/cli/src/commands/migrate/recorded-by.ts +++ b/packages/cli/src/commands/migrate/recorded-by.ts @@ -95,6 +95,7 @@ export default class MigrateRecordedBy extends Command { let stack; try { stack = await bootSchemaStack({ + jsonOutput: flags.json, databaseUrl: flags['database-url'], extraPlugins: await buildDataMigrationPlugins(), }); diff --git a/packages/cli/src/commands/migrate/resume.ts b/packages/cli/src/commands/migrate/resume.ts index 1c16b1c006..4e55742f44 100644 --- a/packages/cli/src/commands/migrate/resume.ts +++ b/packages/cli/src/commands/migrate/resume.ts @@ -105,6 +105,7 @@ export default class MigrateResume extends Command { let stack; try { stack = await bootSchemaStack({ + jsonOutput: flags.json, databaseUrl: flags['database-url'], extraPlugins: await buildDataMigrationPlugins(), }); diff --git a/packages/cli/src/commands/migrate/summary-nulls.ts b/packages/cli/src/commands/migrate/summary-nulls.ts index d9177d30cf..693fc5ccc1 100644 --- a/packages/cli/src/commands/migrate/summary-nulls.ts +++ b/packages/cli/src/commands/migrate/summary-nulls.ts @@ -167,6 +167,7 @@ export default class MigrateSummaryNulls extends Command { let stack; try { stack = await bootSchemaStack({ + jsonOutput: flags.json, databaseUrl: flags['database-url'], extraPlugins: await buildDataMigrationPlugins(), }); diff --git a/packages/cli/src/commands/migrate/value-shapes.ts b/packages/cli/src/commands/migrate/value-shapes.ts index 18c3d9af43..6f0e01fd96 100644 --- a/packages/cli/src/commands/migrate/value-shapes.ts +++ b/packages/cli/src/commands/migrate/value-shapes.ts @@ -134,6 +134,7 @@ export default class MigrateValueShapes extends Command { let stack; try { stack = await bootSchemaStack({ + jsonOutput: flags.json, databaseUrl: flags['database-url'], extraPlugins: await buildDataMigrationPlugins(), }); diff --git a/packages/cli/src/utils/format.ts b/packages/cli/src/utils/format.ts index a22b6cd0db..9e50466a01 100644 --- a/packages/cli/src/utils/format.ts +++ b/packages/cli/src/utils/format.ts @@ -4,6 +4,7 @@ import chalk from 'chalk'; import type { ZodError } from 'zod'; import { formatZodIssue } from '@objectstack/spec'; import type { TenancyPosture } from '@objectstack/spec/security'; +import { writeStdoutDirect } from './json-stdout.js'; // ─── Constants ────────────────────────────────────────────────────── export const CLI_NAME = 'objectstack'; @@ -129,9 +130,11 @@ export function isExitSignal(error: unknown): boolean { * applies here too. */ export async function emitText(text: string, exitCode: CliExitCode = 0): Promise { - await new Promise((resolve, reject) => { - process.stdout.write(text + '\n', (err) => (err ? reject(err) : resolve())); - }); + // `writeStdoutDirect`, not `process.stdout.write`: a `--json` command that + // boots a kernel reserves stdout so the kernel's INFO stream goes to stderr + // (#6217), and the payload is the one thing that must still reach the real + // stdout. Outside a reservation this is `process.stdout.write` verbatim. + await writeStdoutDirect(text + '\n'); if (exitCode !== 0) process.exitCode = exitCode; } diff --git a/packages/cli/src/utils/json-stdout.test.ts b/packages/cli/src/utils/json-stdout.test.ts new file mode 100644 index 0000000000..bc923872e2 --- /dev/null +++ b/packages/cli/src/utils/json-stdout.test.ts @@ -0,0 +1,161 @@ +// Copyright (c) 2026 ObjectStack. Licensed under the Apache-2.0 license. + +/** + * The stdout reservation `--json` is built on (#6217), at the unit level. + * + * `packages/cli/test/json-stdout-purity.e2e.test.ts` pins the contract this + * serves — every `--json` command in the `bootSchemaStack` family emitting one + * parseable JSON document — over real child processes. This file pins the + * mechanism underneath it, including the two properties that make the contract + * hold rather than merely look held: + * + * 1. a reservation catches EVERY stdout writer, not just `ObjectLogger` + * (`console.log` is how `[StandaloneStack] no compiled artifact …` + * reaches stdout, and it never passes through the kernel logger at all); + * 2. the payload writer still reaches the REAL stdout while a reservation is + * in force — a reservation that also swallowed the payload would produce + * an empty stdout, which `JSON.parse` rejects just as loudly. + */ + +import { describe, it, expect, afterEach, vi } from 'vitest'; +import { Console } from 'node:console'; +import { isStdoutReserved, reserveStdoutForJson, writeStdoutDirect } from './json-stdout.js'; + +/** + * A `console` bound to the process streams, because the GLOBAL one is not + * usable as evidence here: vitest replaces `globalThis.console` with its own + * reporter sink, so a `console.log` inside a worker never reaches + * `process.stdout.write` at all and would prove nothing either way. + * + * This is the same mechanism Node's own global console uses — hold the stream, + * call `stream.write(...)` per record — so it exercises exactly the property + * the reservation replaces. The end-to-end proof that the REAL global console + * is covered is `packages/cli/test/json-stdout-purity.e2e.test.ts`, which runs + * the CLI as a child process and pins `[StandaloneStack] no compiled artifact` + * (a bare `console.log` in `@objectstack/runtime`) onto stderr. + */ +const streamConsole = new Console(process.stdout, process.stderr); + +/** + * Spy on both streams and hand back what each received. + * + * The stdout spy is installed BEFORE the reservation on purpose: a reservation + * captures whatever `process.stdout.write` is at that moment, so the spy is + * what {@link writeStdoutDirect} ends up calling, and "reached the real stdout" + * becomes an assertion instead of an inference. + */ +function spyStreams() { + const stdout = vi.spyOn(process.stdout, 'write').mockImplementation(((chunk: any, ...rest: any[]) => { + const cb = rest.find((a) => typeof a === 'function'); + if (cb) cb(); + return true; + }) as typeof process.stdout.write); + const stderr = vi.spyOn(process.stderr, 'write').mockImplementation(((chunk: any, ...rest: any[]) => { + const cb = rest.find((a) => typeof a === 'function'); + if (cb) cb(); + return true; + }) as typeof process.stderr.write); + const text = (spy: typeof stdout) => spy.mock.calls.map((c) => String(c[0])).join(''); + return { stdout, stderr, stdoutText: () => text(stdout), stderrText: () => text(stderr) }; +} + +afterEach(() => { + vi.restoreAllMocks(); +}); + +describe('reserveStdoutForJson — stdout goes to stderr, nothing is destroyed', () => { + it('forwards direct writes AND console.log/info/debug to stderr', () => { + const streams = spyStreams(); + const release = reserveStdoutForJson(); + try { + process.stdout.write('direct write\n'); + // The three console methods Node binds to stdout. `console.log` is the + // one that matters most here: `loadArtifactBundle` announces a missing + // compiled artifact through it, so a fix that only reached the kernel + // logger would still leave that line on stdout. + streamConsole.log('console.log'); + streamConsole.info('console.info'); + streamConsole.debug('console.debug'); + } finally { + release(); + } + + const onStderr = streams.stderrText(); + for (const line of ['direct write', 'console.log', 'console.info', 'console.debug']) { + expect(onStderr).toContain(line); + expect(streams.stdoutText()).not.toContain(line); + } + }); + + it('keeps the drain callback, so a caller awaiting the write still resumes', async () => { + spyStreams(); + const release = reserveStdoutForJson(); + try { + await new Promise((resolve, reject) => { + process.stdout.write('needs a callback\n', (err) => (err ? reject(err) : resolve())); + }); + } finally { + release(); + } + // Reaching here at all is the assertion: `emitJson` awaits exactly this + // callback, and a forwarder that dropped it would hang the CLI forever + // rather than print a wrong byte. + expect(true).toBe(true); + }); + + it('lets the payload through to the real stdout while the reservation holds', async () => { + const streams = spyStreams(); + const release = reserveStdoutForJson(); + try { + streamConsole.log('boot chatter'); + await writeStdoutDirect('{"payload":true}\n'); + } finally { + release(); + } + + expect(streams.stdoutText()).toBe('{"payload":true}\n'); + expect(streams.stderrText()).toContain('boot chatter'); + // The whole point, restated as the consumer sees it. + expect(JSON.parse(streams.stdoutText())).toEqual({ payload: true }); + }); + + it('releases back to the exact write it took', () => { + const before = process.stdout.write; + expect(isStdoutReserved()).toBe(false); + const release = reserveStdoutForJson(); + expect(isStdoutReserved()).toBe(true); + expect(process.stdout.write).not.toBe(before); + release(); + expect(isStdoutReserved()).toBe(false); + // `.bind()` makes a new function object, so identity cannot be asserted; + // behaviour can — the stream is stdout's again. + const streams = spyStreams(); + process.stdout.write('after release\n'); + expect(streams.stdoutText()).toContain('after release'); + expect(streams.stderrText()).not.toContain('after release'); + }); + + it('an inner reservation releases nothing — the outer one owns the stream', () => { + const streams = spyStreams(); + const outer = reserveStdoutForJson(); + const inner = reserveStdoutForJson(); + try { + inner(); // must be a no-op: the outer reservation is still in force + process.stdout.write('still reserved\n'); + expect(streams.stderrText()).toContain('still reserved'); + expect(streams.stdoutText()).not.toContain('still reserved'); + } finally { + outer(); + } + expect(isStdoutReserved()).toBe(false); + }); +}); + +describe('writeStdoutDirect — outside a reservation it is plain stdout', () => { + it('writes to stdout when nothing is reserved', async () => { + const streams = spyStreams(); + await writeStdoutDirect('unreserved\n'); + expect(streams.stdoutText()).toContain('unreserved'); + expect(streams.stderrText()).toBe(''); + }); +}); diff --git a/packages/cli/src/utils/json-stdout.ts b/packages/cli/src/utils/json-stdout.ts new file mode 100644 index 0000000000..6a2c5f9866 --- /dev/null +++ b/packages/cli/src/utils/json-stdout.ts @@ -0,0 +1,139 @@ +// Copyright (c) 2026 ObjectStack. Licensed under the Apache-2.0 license. + +/** + * `--json` stdout reservation (#6217). + * + * ## The invariant + * + * `--json` has exactly one audience: a program. So the whole of a `--json` + * run's **stdout must be one JSON document** — `JSON.parse(stdout)` with no + * heuristic extraction. Anything else is a `--json` flag that isn't + * machine-readable. + * + * It was not true for the commands that boot a kernel. `ObjectLogger` routes + * `debug`/`info`/`warn` to **stdout** and only `error`/`fatal` to stderr + * (`packages/core/src/logger.ts`), so `os migrate recorded-by --json` emitted + * ~60 INFO lines above the payload and two more below it, with stderr + * completely empty: + * + * ``` + * [StandaloneStack] no compiled artifact at '…' — booting without one + * 2026-08-08T02:14:38.330Z INFO Registered metadata loader: filesystem (file:) + * … + * { "planId": "metadata.recorded-by-sentinel-to-null", … } + * 2026-08-08T02:14:38.833Z INFO ✅ Graceful shutdown complete + * ``` + * + * A consumer then has to write a "find the last lone `{` and its matching `}`" + * extractor — #4873 was forced to write one to assert its own payload — and + * that heuristic silently picks the wrong text the moment a log line looks + * like JSON. + * + * ## Why this shape + * + * Three routes were on the table (issue #6217): + * + * 1. redirect the kernel's output to **stderr** for the duration of a `--json` + * run — this module; + * 2. drop the kernel logger to `silent` under `--json` — throws the operator's + * diagnostics away, warnings included, and would still leave the + * `console.log` lines that never went through the logger at all (the + * `[StandaloneStack] no compiled artifact …` line above is one); + * 3. make the logger default to stderr repo-wide — a `packages/core` change + * that moves `os serve` / `os dev` output for every existing user and every + * log-scraping deployment, so a maintainer call, and out of scope here. + * + * Route 1 is the only one that keeps every diagnostic *and* gives the payload a + * clean channel, and it is reachable from the CLI with no `packages/core` + * change: `LoggerConfig` has a `level` but no destination/stream knob, so the + * redirection has to happen on the stream itself. `os serve` already does + * exactly this to keep its startup banner readable — it swaps + * `process.stdout.write` for the boot window and buffers what it intercepts + * (`boot-log-capture.ts`, #4012). This is that same seam, pointed at stderr + * instead of at a buffer. + * + * Patching `process.stdout.write` covers every writer, not just the logger: + * Node's global `console.log` / `console.info` / `console.debug` resolve + * `process.stdout` and call `.write` on it per call, and `ObjectLogger.write()` + * reads `process.stdout` per record too. Measured, all of them route through + * one patched property. + * + * ## The payload's way out + * + * With stdout reserved, the payload needs a channel the reservation cannot + * capture — that is {@link writeStdoutDirect}, which holds the real write and + * is what `emitJson`/`emitText` are built on. It is the ONLY thing that may + * reach stdout during a reservation, which is what makes "exactly one JSON + * document" structural rather than aspirational. + */ + +/** `process.stdout.write`, as a callable with the varargs Node accepts. */ +type StreamWrite = (chunk: any, ...rest: any[]) => boolean; + +/** + * The real `process.stdout.write` while a reservation is in force, `null` + * otherwise. Captured at reservation time rather than at module load, so a + * reservation composes with any other stdout interception in the process + * (`os serve`'s boot-quiet window) instead of tearing it out from underneath. + */ +let realStdoutWrite: StreamWrite | null = null; + +/** Whether stdout is currently reserved for a machine-readable payload. */ +export function isStdoutReserved(): boolean { + return realStdoutWrite !== null; +} + +/** + * Reserve stdout for a `--json` payload: everything written to + * `process.stdout` from here on is forwarded to **stderr**. + * + * Nothing is discarded — the operator keeps every boot line, every warning and + * every degraded-boot notice, on the stream diagnostics belong on. Returns the + * release, which restores the previous `process.stdout.write`; a second + * reservation while one is in force is a no-op that releases nothing (the + * outer reservation owns the stream). + * + * Callers in a one-shot CLI process are not obliged to release: see + * `bootSchemaStack`, which deliberately holds the reservation past a failed + * boot so a stray log from a half-started kernel cannot land next to the error + * payload. + */ +export function reserveStdoutForJson(): () => void { + if (realStdoutWrite) return () => { /* an inner reservation owns nothing */ }; + + const original = process.stdout.write.bind(process.stdout) as StreamWrite; + realStdoutWrite = original; + + // A property call on `process.stderr`, so `this` is the stderr stream and the + // varargs (`encoding`, the drain callback) keep their native meaning — a + // caller awaiting the write still resumes. + const forward = ((chunk: any, ...rest: any[]): boolean => + (process.stderr as unknown as { write: StreamWrite }).write(chunk, ...rest)) as StreamWrite; + + process.stdout.write = forward as typeof process.stdout.write; + + return () => { + if (realStdoutWrite !== original) return; + realStdoutWrite = null; + // Only take the stream back if it is still ours — another interception + // layered on top has to unwind first. + if ((process.stdout.write as unknown as StreamWrite) === forward) { + process.stdout.write = original as typeof process.stdout.write; + } + }; +} + +/** + * Write to the REAL stdout, bypassing any reservation, and resolve once the + * bytes are handed off. + * + * The drain is not decoration: `console.log(big)` followed by an exit is cut + * off at one 64 KiB pipe buffer, which is why `emitJson` exists at all — see + * its doc comment in `format.ts`. + */ +export function writeStdoutDirect(text: string): Promise { + const write = realStdoutWrite ?? (process.stdout.write.bind(process.stdout) as StreamWrite); + return new Promise((resolve, reject) => { + write(text, (err?: Error | null) => (err ? reject(err) : resolve())); + }); +} diff --git a/packages/cli/src/utils/schema-migrate.deferred-ddl.integration.test.ts b/packages/cli/src/utils/schema-migrate.deferred-ddl.integration.test.ts index 404534112f..549a447df0 100644 --- a/packages/cli/src/utils/schema-migrate.deferred-ddl.integration.test.ts +++ b/packages/cli/src/utils/schema-migrate.deferred-ddl.integration.test.ts @@ -100,7 +100,7 @@ describe('bootSchemaStack({ deferSchemaDdl }) — the boot writes nothing (#3917 expect(before.tables).toEqual(['defer_widget']); expect(before.widgetColumns).toEqual(['created_at', 'id', 'name', 'updated_at']); - const stack = await bootSchemaStack({ databaseUrl: `file:${dbFile}`, deferSchemaDdl: true, projectRoot: dir }); + const stack = await bootSchemaStack({ jsonOutput: false, databaseUrl: `file:${dbFile}`, deferSchemaDdl: true, projectRoot: dir }); try { const after = await inspect(); // The core assertion: boot created no table, added no column, wrote no @@ -128,7 +128,7 @@ describe('bootSchemaStack({ deferSchemaDdl }) — the boot writes nothing (#3917 }, 60_000); it('flushSchemaDdl performs exactly the work that was reported', async () => { - const stack = await bootSchemaStack({ databaseUrl: `file:${dbFile}`, deferSchemaDdl: true, projectRoot: dir }); + const stack = await bootSchemaStack({ jsonOutput: false, databaseUrl: `file:${dbFile}`, deferSchemaDdl: true, projectRoot: dir }); try { const pending = stack.pendingSchemaWork; const performed = await stack.flushSchemaDdl(); @@ -142,7 +142,7 @@ describe('bootSchemaStack({ deferSchemaDdl }) — the boot writes nothing (#3917 // A second boot finds nothing left to do. await stack.shutdown(); - const again = await bootSchemaStack({ databaseUrl: `file:${dbFile}`, deferSchemaDdl: true, projectRoot: dir }); + const again = await bootSchemaStack({ jsonOutput: false, databaseUrl: `file:${dbFile}`, deferSchemaDdl: true, projectRoot: dir }); try { expect(again.pendingSchemaWork).toEqual([]); } finally { @@ -155,7 +155,7 @@ describe('bootSchemaStack({ deferSchemaDdl }) — the boot writes nothing (#3917 }, 60_000); it('without the flag, the boot syncs as it always did', async () => { - const stack = await bootSchemaStack({ databaseUrl: `file:${dbFile}`, projectRoot: dir }); + const stack = await bootSchemaStack({ jsonOutput: false, databaseUrl: `file:${dbFile}`, projectRoot: dir }); try { expect(stack.pendingSchemaWork).toEqual([]); const after = await inspect(); diff --git a/packages/cli/src/utils/schema-migrate.integration.test.ts b/packages/cli/src/utils/schema-migrate.integration.test.ts index 8873fa61d9..ed5addccfb 100644 --- a/packages/cli/src/utils/schema-migrate.integration.test.ts +++ b/packages/cli/src/utils/schema-migrate.integration.test.ts @@ -78,7 +78,7 @@ describe('bootSchemaStack + migrate engine (integration)', () => { }); it('detects the NOT NULL + legacy-unique drift, applies both, and self-verifies in-sync', async () => { - const stack = await bootSchemaStack({ databaseUrl: `file:${dbFile}`, projectRoot: dir }); + const stack = await bootSchemaStack({ jsonOutput: false, databaseUrl: `file:${dbFile}`, projectRoot: dir }); try { expect(stack.driver).toBeTruthy(); expect(stack.managedTableCount).toBeGreaterThan(0); @@ -198,7 +198,7 @@ describe('bootSchemaStack — dev-provisioned __search companions are not orphan }); it('the migrate boot provisions the companion in metadata, so plan reports no __search drift', async () => { - const stack = await bootSchemaStack({ databaseUrl: `file:${dbFile}`, projectRoot: dir }); + const stack = await bootSchemaStack({ jsonOutput: false, databaseUrl: `file:${dbFile}`, projectRoot: dir }); try { expect(stack.driver).toBeTruthy(); diff --git a/packages/cli/src/utils/schema-migrate.teardown.integration.test.ts b/packages/cli/src/utils/schema-migrate.teardown.integration.test.ts index 86178b84fb..aaa0fe03b1 100644 --- a/packages/cli/src/utils/schema-migrate.teardown.integration.test.ts +++ b/packages/cli/src/utils/schema-migrate.teardown.integration.test.ts @@ -78,7 +78,7 @@ describe('[#4747] bootSchemaStack teardown disarms the ADR-0057 sweep', () => { }); it('audits while the engine is live, and reads nothing once the stack is down', async () => { - const stack = await bootSchemaStack({ databaseUrl: `file:${dbFile}`, projectRoot: dir }); + const stack = await bootSchemaStack({ jsonOutput: false, databaseUrl: `file:${dbFile}`, projectRoot: dir }); // Resolved BEFORE teardown — the point is what this same instance does // afterwards, and service resolution post-shutdown is not the subject. const lifecycle = stack.kernel.getService('lifecycle') as LifecycleServiceLike; diff --git a/packages/cli/src/utils/schema-migrate.ts b/packages/cli/src/utils/schema-migrate.ts index 403ed60e00..eaa894682e 100644 --- a/packages/cli/src/utils/schema-migrate.ts +++ b/packages/cli/src/utils/schema-migrate.ts @@ -16,6 +16,7 @@ import chalk from 'chalk'; import type { ManagedDriftEntry, DriftCategory, PendingSchemaWork } from '@objectstack/driver-sql'; import type { IObjectQLEngine } from '@objectstack/spec/contracts'; import { describeDriverConnection } from './connection-display.js'; +import { reserveStdoutForJson } from './json-stdout.js'; export type { PendingSchemaWork }; @@ -139,6 +140,30 @@ function describeDb(driver: SqlDriverLike | null): string { /** Boot the schema stack. Caller MUST call `shutdown()` when done. */ export async function bootSchemaStack( opts: { + /** + * `true` when this run's stdout belongs to a machine-readable payload + * (`--json`) — the boot then sends everything the kernel and its plugins + * write to **stderr** so `JSON.parse(stdout)` succeeds on the whole + * stream, with no heuristic extraction (#6217). + * + * REQUIRED, and required on purpose. Every command in this family declares + * a `--json` flag, and each of them re-introduced the same defect + * independently: `os migrate plan` / `apply` / `resume` / `recorded-by` / + * `summary-nulls` / `value-shapes` / `files-to-references`, `os migrate + * meta --stored` and `os meta resync` all emitted ~60 INFO lines around + * their payload. Booting the stack is what makes a command a member of + * this family, so this is the one place a new member cannot avoid — and + * with no default, a new member has to *decide* rather than inherit the + * bug. Pass `false` from anything that owns stdout itself (every + * human-mode run, and every test). + * + * The reservation is NOT lifted when the boot fails: a half-started kernel + * can still log, and the command's next act on that path is to emit its + * error payload. Lifting it would put those two on the same stream, which + * is the defect. `shutdown()` lifts it on the success path, once the kernel + * is down and nothing is left to write. See `./json-stdout.ts`. + */ + jsonOutput: boolean; databaseUrl?: string; /** * Service plugins to register after the data stack (driver/metadata/ @@ -176,8 +201,14 @@ export async function bootSchemaStack( * whatever directory the test runner happens to be standing in (#4065). */ projectRoot?: string; - } = {}, + }, ): Promise { + // Taken BEFORE the first line the boot can print. `createStandaloneStack` + // announces a missing compiled artifact on `console.log` before any plugin + // is constructed, so a reservation installed one statement later already + // arrives too late to keep stdout a single JSON document (#6217). + const releaseStdout = opts.jsonOutput ? reserveStdoutForJson() : () => { /* stdout is the caller's */ }; + const { createStandaloneStack, Runtime } = await import('@objectstack/runtime'); const defer = opts.deferSchemaDdl === true; @@ -262,6 +293,12 @@ export async function bootSchemaStack( shutdown: async () => { try { await kernel.shutdown(); } catch { /* teardown is best-effort */ } try { await driver?.disconnect?.(); } catch { /* ignore */ } + // Only now — `kernel.shutdown()` is itself two INFO lines ("Graceful + // shutdown started" / "complete"), and under `--json` those printed + // BELOW the payload, which is half of what made stdout unparseable + // (#6217). Released after the kernel is down, when nothing is left to + // write; a failed boot never reaches here on purpose. + releaseStdout(); }, }; } diff --git a/packages/cli/test/json-stdout-purity.e2e.test.ts b/packages/cli/test/json-stdout-purity.e2e.test.ts new file mode 100644 index 0000000000..2a6e87e8d4 --- /dev/null +++ b/packages/cli/test/json-stdout-purity.e2e.test.ts @@ -0,0 +1,225 @@ +// Copyright (c) 2026 ObjectStack. Licensed under the Apache-2.0 license. + +/** + * `--json` ⇒ stdout is EXACTLY ONE JSON DOCUMENT, for the whole + * `bootSchemaStack` family (#6217). + * + * `--json` has one audience — a program — and the commands that boot a kernel + * were handing that program a stream it could not parse. `ObjectLogger` routes + * `debug`/`info`/`warn` to **stdout** and only `error`/`fatal` to stderr, so + * `os migrate recorded-by --json` shipped ~60 INFO lines above the payload and + * the two shutdown lines below it, with stderr completely empty. The consumer's + * only recourse was a "find the last lone `{` and its matching `}`" extractor — + * #4873 was forced to write one to assert its own payload — and that heuristic + * silently picks the wrong text as soon as a log line looks like JSON. + * + * ## Why the whole family, from one expectation + * + * The contract has one implementation face per command, and there are nine of + * them. A file that pinned `migrate recorded-by` alone would go green while the + * other eight stayed broken, and would say nothing at all about the tenth. So + * the family is DISCOVERED from the source tree — every command that calls + * `bootSchemaStack` and declares a `--json` flag — and the discovered set is + * reconciled against {@link FAMILY} below. Add a member and this file goes red + * until it is listed here and passes; drop one and it goes red until it is + * removed. The seam itself (`bootSchemaStack`'s required `jsonOutput` option) + * makes the mistake a compile error first; this is the runtime proof that the + * seam actually delivers the invariant. + * + * ## Deliberately an UNCOMPILED fixture + * + * No `os compile` runs here, so the project has no `dist/objectstack.json` and + * the boot announces that through `console.log`: + * + * [StandaloneStack] no compiled artifact at '…' — booting without one + * + * That line never passes through the kernel logger, so it is the second, + * independent pollution source — a fix that only quieted `ObjectLogger` would + * still leave it on stdout. Compiling the fixture would make the richer command + * payloads possible and delete that coverage; the invariant matters more. + * + * ## Diagnostics are MOVED, never destroyed + * + * Route 2 of the issue (drop the kernel to `logLevel: 'silent'` under `--json`) + * would also make stdout parse — by throwing the operator's boot diagnostics, + * warnings included, on the floor. Every case therefore asserts the same lines + * are present on **stderr**, so a regression toward silencing goes red here + * too. + */ + +import { describe, it, expect, beforeAll, afterAll } from 'vitest'; +import { execFile } from 'node:child_process'; +import { mkdtempSync, rmSync, writeFileSync, readFileSync, readdirSync, statSync } from 'node:fs'; +import { tmpdir } from 'node:os'; +import { join, resolve, relative, sep } from 'node:path'; +import { fileURLToPath } from 'node:url'; + +const HERE = resolve(fileURLToPath(import.meta.url), '..'); +const CLI = resolve(HERE, '../bin/run-dev.js'); +const TSX = resolve(HERE, '../../../node_modules/.bin/tsx'); +const COMMANDS_DIR = resolve(HERE, '../src/commands'); + +/** + * The family, and how to drive each member into a boot. + * + * The value is the EXTRA argv a member needs beyond `--json`; `[]` means the + * bare form already boots. Only one member needs anything: `os migrate meta` + * migrates an authored config in memory and boots a kernel solely under + * `--stored`, which is why the issue's own list names it as `migrate meta + * --stored` rather than `migrate meta`. + */ +const FAMILY: Record = { + 'meta resync': [], + 'migrate apply': [], + 'migrate files-to-references': [], + 'migrate meta': ['--stored'], + 'migrate plan': [], + 'migrate recorded-by': [], + 'migrate resume': [], + 'migrate summary-nulls': [], + 'migrate value-shapes': [], +}; + +/** Boot lines every member emits — the diagnostics that must survive on stderr. */ +const BOOT_DIAGNOSTICS = [ + // `console.log`, not the kernel logger — see the header. + '[StandaloneStack] no compiled artifact', + 'Bootstrap complete', + 'Graceful shutdown complete', +]; + +/** Every `.ts` under `src/commands`, excluding tests. */ +function commandFiles(dir: string): string[] { + const out: string[] = []; + for (const entry of readdirSync(dir)) { + const abs = join(dir, entry); + if (statSync(abs).isDirectory()) { + out.push(...commandFiles(abs)); + continue; + } + if (!entry.endsWith('.ts') || entry.endsWith('.test.ts')) continue; + out.push(abs); + } + return out; +} + +/** + * The family, read off the source rather than remembered: a command belongs iff + * it boots the shared stack AND offers a machine-readable mode. Both halves are + * needed — `os serve` boots a kernel with no `--json`, and `os lint --json` + * emits JSON without booting one. + */ +function discoverFamily(): string[] { + const ids: string[] = []; + for (const abs of commandFiles(COMMANDS_DIR)) { + const src = readFileSync(abs, 'utf-8'); + if (!src.includes('bootSchemaStack(')) continue; + if (!/\bjson:\s*Flags\.boolean\(/.test(src)) continue; + const rel = relative(COMMANDS_DIR, abs).replace(/\.ts$/, ''); + const parts = rel.split(sep).filter((p) => p !== 'index'); + ids.push(parts.join(' ')); + } + return ids.sort(); +} + +interface Run { + id: string; + code: number; + stdout: string; + stderr: string; +} + +function runCli(argv: string[], cwd: string, env: Record): Promise> { + return new Promise((resolvePromise) => { + execFile( + TSX, + [CLI, ...argv], + { cwd, maxBuffer: 32 * 1024 * 1024, env: { ...process.env, NO_COLOR: '1', ...env } }, + (err, stdout, stderr) => { + resolvePromise({ + code: err ? (typeof (err as { code?: unknown }).code === 'number' ? (err as unknown as { code: number }).code : 1) : 0, + stdout: String(stdout), + stderr: String(stderr), + }); + }, + ); + }); +} + +/** Minimal project — every member boots the same stack, none of them needs more. */ +const CONFIG = ` +export default { + name: 'json_purity_e2e', + label: 'JSON Purity E2E', + objects: [{ + name: 'jp_ticket', + label: 'Ticket', + sharingModel: 'private', + fields: { title: { type: 'text', label: 'Title' } }, + }], +}; +`; + +let dir: string; +let runs: Run[]; + +beforeAll(async () => { + dir = mkdtempSync(join(tmpdir(), 'os-json-purity-e2e-')); + writeFileSync(join(dir, 'objectstack.config.ts'), CONFIG); + + // Sequential, each on its own database file: several members create tables, + // and a shared SQLite file would make one member's run depend on the order + // the others happened to run in. Sequential also keeps peak memory at one + // booted kernel rather than nine. + runs = []; + for (const [id, extra] of Object.entries(FAMILY)) { + const slug = id.replace(/[^a-z0-9]+/gi, '-'); + const { code, stdout, stderr } = await runCli( + [...id.split(' '), '--json', ...extra], + dir, + { OS_DATABASE_URL: `file:${join(dir, `${slug}.db`)}` }, + ); + runs.push({ id, code, stdout, stderr }); + } +}, 900_000); + +afterAll(() => { + try { rmSync(dir, { recursive: true, force: true }); } catch { /* ignore */ } +}); + +describe('the family this contract has to hold across', () => { + it('is exactly the set listed here — a new member goes red until it is driven too', () => { + expect(discoverFamily()).toEqual(Object.keys(FAMILY).sort()); + }); +}); + +describe.each(Object.keys(FAMILY))('os %s --json', (id) => { + const runOf = () => { + const run = runs.find((r) => r.id === id); + if (!run) throw new Error(`no run captured for '${id}'`); + return run; + }; + + it('emits ONE JSON document on stdout — a bare JSON.parse, no extraction', () => { + const run = runOf(); + // `JSON.parse(run.stdout)` directly, not a payload-hunting helper. Under + // the defect this threw `Unexpected token 'S', "[Standalone"...`. + const payload = JSON.parse(run.stdout); + expect(payload).toBeTypeOf('object'); + expect(payload).not.toBeNull(); + }); + + it('leaves no kernel-logger record on stdout', () => { + const run = runOf(); + // The rendering `ObjectLogger` emits at `pretty` (the CLI's format): + // ` INFO …`. Asserted separately from the parse so a regression + // names its cause rather than only `Unexpected token`. + expect(run.stdout).not.toMatch(/^\d{4}-\d{2}-\d{2}T[\d:.]+Z\s+(DEBUG|INFO|WARN)\b/m); + expect(run.stdout).not.toContain('[StandaloneStack]'); + }); + + it('still shows the operator every boot diagnostic — on stderr', () => { + const run = runOf(); + for (const line of BOOT_DIAGNOSTICS) expect(run.stderr).toContain(line); + }); +}); diff --git a/packages/cli/test/migrate-exit-code.e2e.test.ts b/packages/cli/test/migrate-exit-code.e2e.test.ts index 52e01ce886..64fab3293c 100644 --- a/packages/cli/test/migrate-exit-code.e2e.test.ts +++ b/packages/cli/test/migrate-exit-code.e2e.test.ts @@ -11,6 +11,11 @@ * Only the one thing no author looks at, and the only thing a CI step, a * `set -e` script, a Makefile or a container entrypoint looks at. * + * Two of those observations have since changed, and deliberately: #6217 gave + * `--json` its stdout back, so the boot log and the shutdown receipt now arrive + * on **stderr** and stdout is one JSON document. That is what let this file + * drop the payload-hunting extractor it had to carry — see {@link jsonPayload}. + * * The cause was `emitJson(payload, timer.elapsed())` — a DURATION handed to the * parameter that means `exitCode`, so the process exited with its own runtime * in milliseconds, truncated to 8 bits. `packages/cli/src/utils/format.exit-code.test.ts` @@ -92,33 +97,24 @@ function runCli(args: string[], cwd: string, env: Record = {}): } /** - * The `--json` payload, dug out of stdout. + * The `--json` payload: the WHOLE of stdout, parsed as one document. * - * This command boots a kernel and the kernel's INFO logger writes to STDOUT, so - * the machine payload arrives with human log lines above AND below it — the - * whole stdout is not valid JSON. That is its own defect for the same audience - * and is filed as #6217; it is not this test's subject, and working around it - * here is exactly what a consumer has to do today. + * This used to be a heuristic extractor — scan backwards for a lone `}` at + * column 0, then back to its matching lone `{` — written under duress because + * the kernel's INFO logger wrote to stdout, so the payload arrived with ~60 log + * lines above it and two below and the whole stream was not valid JSON. That + * was its own defect for the same audience (#6217); it is fixed, `--json` now + * reserves stdout for the payload and the kernel's output goes to stderr, and + * the extractor is gone. * - * Structural rather than a regex over the buffer: `emitJson` pretty-prints, so - * the payload is a lone `{` through a lone `}` at column 0; `{ compact: true }` - * puts one object on one line. A log line that merely looks like JSON fails - * `JSON.parse` and the scan continues. + * Keeping this a bare `JSON.parse` is deliberate: the heuristic could silently + * pick the wrong text the moment a log line looked like an object, so removing + * it removes a way for THIS pin to pass on the wrong bytes. The invariant it + * now leans on is pinned across the whole `bootSchemaStack` family in + * `json-stdout-purity.e2e.test.ts`. */ function jsonPayload(stdout: string): Record { - const lines = stdout.split('\n'); - for (let i = lines.length - 1; i >= 0; i--) { - const line = lines[i]; - if (line === '}') { - for (let j = i; j >= 0; j--) { - if (lines[j] === '{') return JSON.parse(lines.slice(j, i + 1).join('\n')); - } - } - if (line.startsWith('{') && line.endsWith('}')) { - try { return JSON.parse(line); } catch { /* a log line shaped like an object */ } - } - } - throw new Error(`no --json payload on stdout:\n${stdout}`); + return JSON.parse(stdout) as Record; } const RUNS = 3; @@ -166,8 +162,11 @@ describe('os migrate recorded-by --json — a successful run exits 0 (#4873)', ( pending: 0, applied: false, }); - expect(run.stdout).toContain('Graceful shutdown complete'); - expect(run.stderr).toBe(''); + // The receipt moved streams with #6217 and is still a receipt: the + // kernel really came up and really came down, it just says so on stderr + // now so stdout can be the payload and nothing else. + expect(run.stderr).toContain('Graceful shutdown complete'); + expect(run.stdout).not.toContain('Graceful shutdown complete'); } });