diff --git a/.changeset/degraded-boot-stderr-premise.md b/.changeset/degraded-boot-stderr-premise.md new file mode 100644 index 0000000000..5f3d43db6d --- /dev/null +++ b/.changeset/degraded-boot-stderr-premise.md @@ -0,0 +1,46 @@ +--- +'@objectstack/types': patch +'@objectstack/objectql': patch +'@objectstack/runtime': patch +'@objectstack/cli': patch +--- + +**Correct the stale premise left behind by #4012: the degraded-boot stderr copy +survives the operator's LOG LEVEL, not `os serve`'s boot-quiet window.** + +`emitDegradedBootBanner` writes the `OS_ALLOW_DRIVER_CONNECT_FAILURE` banner to +stderr in addition to `logger.warn`, and every comment and test name explaining +why cited the same reason: `os serve` swallowed all of stdout while the kernel +booted, and `Logger` routes `warn` to stdout. #4012 fixed that — the boot window +now buffers and replays `warn`-and-above — which retires the *stated* +justification for a duplicate that is nonetheless still load-bearing: + +`Logger.write()` returns before touching a stream when the record is below +`config.level`, so at `--log-level error`, `fatal` or `silent` the banner's +`logger.warn` reaches **no** stream at all. A production host at `error` is +exactly the deployment this escape hatch exists for, and exactly where a +logger-only banner would vanish. Removing the stderr copy on the strength of +#4012 would therefore have been a regression — so this documents the reason that +is still true, in the places someone would read before deleting it: +`degraded-boot.ts`, the engine's emit site, and all three parity tests +(objectql, runtime, service-datasource), which are renamed off "which `os serve` +boot-quiet cannot swallow" to "which the operator log level cannot filter away". + +The objectql parity test now proves the claim instead of asserting around it: it +drives a **real** `ObjectLogger` at `level: 'error'` and requires the banner on +stderr *and* nothing on stdout. Set the level to `warn` and it fails — so the +test is pinned to the level filter rather than passing for any reason. + +Also corrected in the same sweep, all comment-only, all previously overstating +what #4012 had not yet fixed: + +- the automation wiring summary (`format.ts`, `serve.ts`, its test) claimed the + boot window swallowed the engine's binding warnings. Its real justification is + stronger and unchanged: a flow that silently fails to arm emits **no** log line + at any level, so binding state has to be read off the live engine — absence of + a warning was never evidence of a bound flow. +- the seed summary (`seed-summary.ts`, `format.ts`, its test) and `AppPlugin`'s + seed-outcome note attributed the silence to the boot window; the operative + gate is that `SeedLoader`'s result logs are `info`, under the default `warn`. + +No behavior changes. diff --git a/packages/cli/src/commands/serve-automation-summary.test.ts b/packages/cli/src/commands/serve-automation-summary.test.ts index 4dbe450e79..750a9a1df7 100644 --- a/packages/cli/src/commands/serve-automation-summary.test.ts +++ b/packages/cli/src/commands/serve-automation-summary.test.ts @@ -2,13 +2,14 @@ // // Startup-banner automation summary (2026-07-17 third-party eval). // -// Flow registration and trigger binding happen entirely inside serve's -// boot-quiet stdout window, so the automation engine's own logs never reach -// the terminal — a project whose flows silently failed to arm looked exactly -// like one whose flows armed fine. `collectAutomationSummary` gathers the -// live binding facts after stdout is restored so the banner can answer -// "did my flows actually arm?" — including the three silent author mistakes: -// engine not enabled, trigger not registered, and objectName mismatch. +// A project whose flows silently failed to arm looks exactly like one whose +// flows armed fine: the failure modes below emit no log line to go looking for, +// and the engine's own binding narration is `info`, under the default `warn` +// level. So the banner reads live binding STATE off the engine rather than +// scraping output. `collectAutomationSummary` gathers those facts after +// runtime.start() so the banner can answer "did my flows actually arm?" — +// including the three silent author mistakes: engine not enabled, trigger not +// registered, and objectName mismatch. import { describe, it, expect } from 'vitest'; import { collectAutomationSummary } from './serve.js'; diff --git a/packages/cli/src/commands/serve.ts b/packages/cli/src/commands/serve.ts index 3a9ec08b81..d210d4e6ff 100644 --- a/packages/cli/src/commands/serve.ts +++ b/packages/cli/src/commands/serve.ts @@ -2471,21 +2471,22 @@ export default class Serve extends Command { } catch { /* auth service not present — nothing to show */ } // ── Automation wiring summary (2026-07-17 third-party eval) ───── - // Flow registration + trigger binding happen entirely inside the - // boot-quiet stdout window above, so the engine's own info/warn logs - // never reach the terminal. Collect the live binding state here (after - // restore) and surface it in the banner: declared-but-engine-missing, - // unbound triggered flows, and bound-but-dead (unknown object) flows. + // A flow that silently failed to arm logs nothing at all, so no amount of + // log plumbing answers "did my flows arm?" — the binding STATE has to be + // read off the live engine. Collect it here (after restore) and surface it + // in the banner: declared-but-engine-missing, unbound triggered flows, and + // bound-but-dead (unknown object) flows. const automationSummary = collectAutomationSummary( kernel, Array.isArray((config as any)?.flows) ? (config as any).flows.length : 0, ); // ── Seed outcome summary (#3415/#3430) ───────────────────────── - // Seeds run inside the boot-quiet window too, and SeedLoader's own - // logs sit under the default warn level — a fixture could lose 90% - // of its rows, or a marketplace package rehydrate onto a fresh DB - // with zero rows, all with zero terminal signal. AppPlugin and the + // SeedLoader's own result logs are `info`, under the default warn + // level — a fixture could lose 90% of its rows, or a marketplace + // package rehydrate onto a fresh DB with zero rows, all with zero + // terminal signal. (The boot-quiet window hid them at every level on + // top of that until #4012.) AppPlugin and the // marketplace rehydrate/heal path stash a per-source entry on the // kernel; print them here, loudly when rows dropped or an install // came up empty. @@ -2624,8 +2625,8 @@ export function describeRegisteredDriver(kernel: any): { label: string; url: str /** * Collect the automation wiring facts for the startup banner (2026-07-17 - * third-party eval: flow registration/binding logs fall inside the boot-quiet - * stdout window, so the banner is the one channel a developer reliably sees). + * third-party eval: a flow that failed to arm emits no log line to find, so the + * banner reads the binding state off the engine instead). * * Every probe is feature-detected so an older `@objectstack/service-automation` * (without `getTriggerBindingAudit` / extended runtime states) degrades to the diff --git a/packages/cli/src/utils/format.seed-summary.test.ts b/packages/cli/src/utils/format.seed-summary.test.ts index 9b47fd54e0..44b004d224 100644 --- a/packages/cli/src/utils/format.seed-summary.test.ts +++ b/packages/cli/src/utils/format.seed-summary.test.ts @@ -5,8 +5,10 @@ import { printServerReady, type ServerReadyOptions, type SeedSourceSummary } fro /** * #3415/#3430 — the boot banner is the ONE place a developer reliably sees seed - * outcomes (SeedLoader's own logs are level-filtered and swallowed by the serve - * boot-quiet window). Assert the Seeds line prints per source, screams on + * outcomes: SeedLoader's own result logs are `info`, under the default `warn` + * level. (They were additionally swallowed by the serve boot-quiet window at + * every level until framework#4012; the level gate is what still hides them.) + * Assert the Seeds line prints per source, screams on * rejections AND empty marketplace installs, marks fresh-DB heals, and stays * silent when nothing was seeded. */ diff --git a/packages/cli/src/utils/format.ts b/packages/cli/src/utils/format.ts index b9b7b1acf8..86fb656f97 100644 --- a/packages/cli/src/utils/format.ts +++ b/packages/cli/src/utils/format.ts @@ -294,18 +294,21 @@ export interface ServerReadyOptions { */ seededAdmin?: { email: string; password: string }; /** - * Automation wiring summary (2026-07-17 third-party eval). The boot-quiet - * stdout window swallows every info/warn the automation engine logs while - * binding flows to triggers, so the banner is the ONE reliable place a - * developer can see whether their record-change / schedule flows actually - * armed. Collected from the live engine after runtime.start(). + * Automation wiring summary (2026-07-17 third-party eval). The engine's own + * `info` narration while binding flows to triggers sits under the default + * `warn` level and never prints, and a flow that armed logs nothing either + * way — so a log line is the wrong instrument here regardless. This reports + * live binding STATE, read off the engine after runtime.start(), which is + * what "did my flows actually arm?" actually asks. (Boot-phase warnings the + * engine does emit now reach the terminal too — see {@link BootDiagnostics}, + * #4012 — but absence of a warning was never evidence of a bound flow.) */ automation?: AutomationReadySummary; /** - * Per-source seed outcomes for this boot (#3415/#3430). Seeds run inside the - * boot-quiet stdout window and SeedLoader's own logs sit under the default - * warn level, so without this line a fixture can silently lose most of its - * rows (the showcase shipped 1 of 5 projects for weeks) and a marketplace + * Per-source seed outcomes for this boot (#3415/#3430). SeedLoader's own + * logs sit under the default warn level (and the boot-quiet window hid them + * at every level until #4012), so without this line a fixture can silently + * lose most of its rows (the showcase shipped 1 of 5 projects for weeks) and a marketplace * package can rehydrate onto a fresh DB with zero rows. Each config app and * each rehydrated/healed marketplace package contributes one entry; * rejections and empty installs are loud, a clean seed prints one dim line. diff --git a/packages/objectql/src/engine-driver-connect-failfast.test.ts b/packages/objectql/src/engine-driver-connect-failfast.test.ts index 9012bc71d2..d801888a9d 100644 --- a/packages/objectql/src/engine-driver-connect-failfast.test.ts +++ b/packages/objectql/src/engine-driver-connect-failfast.test.ts @@ -8,6 +8,7 @@ // OS_ALLOW_DRIVER_CONNECT_FAILURE. import { describe, it, expect, beforeEach, afterEach } from 'vitest'; +import { ObjectLogger } from '@objectstack/core'; import { ObjectQL } from './engine.js'; import { DriverConnectError } from './driver-connect-errors.js'; @@ -138,28 +139,46 @@ describe('ObjectQL.init() — driver connect fail-fast (framework#3741)', () => expect(warned).toContain('sql'); }); - it('repeats the degraded banner on stderr, which `os serve` boot-quiet cannot swallow', async () => { - // `os serve` replaces process.stdout.write for the whole boot, and Logger - // sends `warn` to stdout — so a logger-only banner is invisible in exactly - // the deployment this flag exists for. + it('repeats the degraded banner on stderr, which the operator log level cannot filter away', async () => { + // The banner's `logger.warn` is dropped OUTRIGHT at `error`/`fatal`/`silent` + // — `Logger.write()` returns before touching a stream — and a production + // host at `error` is exactly the deployment this flag exists for. The stderr + // copy is what survives that. + // + // This used to be justified by `os serve`'s boot-quiet stdout capture + // instead; that swallowed the banner at EVERY level until framework#4012 + // fixed it. Pinning the level filter keeps the test tied to the reason that + // is still true. process.env[ENV] = '1'; const written: string[] = []; - const realWrite = process.stderr.write; + const onStdout: string[] = []; + const realErrWrite = process.stderr.write; + const realOutWrite = process.stdout.write; (process.stderr as { write: unknown }).write = (chunk: any) => { written.push(String(chunk)); return true; }; + (process.stdout as { write: unknown }).write = (chunk: any) => { + onStdout.push(String(chunk)); + return true; + }; try { const engine = new ObjectQL({ - logger: { debug() {}, info() {}, warn() {}, error() {} }, + // A REAL logger, silenced the way a production host silences it. + logger: new ObjectLogger({ level: 'error' }), } as any); engine.registerDriver(fails('sql', 'down'), true); await engine.init(); } finally { - (process.stderr as { write: unknown }).write = realWrite; + (process.stderr as { write: unknown }).write = realErrWrite; + (process.stdout as { write: unknown }).write = realOutWrite; } expect(written.join('')).toContain('DEGRADED BOOT'); + // The half that makes this a real pin: at `error` the logger emitted + // NOTHING, so stderr is the only channel that carried the banner. Drop the + // helper and this deployment goes silent. + expect(onStdout.join('')).not.toContain('DEGRADED BOOT'); }); it('treats a falsy opt-in value as off — still fail-fast', async () => { diff --git a/packages/objectql/src/engine.ts b/packages/objectql/src/engine.ts index f7a0544252..b38809688c 100644 --- a/packages/objectql/src/engine.ts +++ b/packages/objectql/src/engine.ts @@ -2050,8 +2050,11 @@ export class ObjectQL implements IDataEngine { `the DDL, so those objects may have no tables even after the database comes back. Unset ` + `OS_ALLOW_DRIVER_CONNECT_FAILURE to restore fail-fast boot.`; this.logger.warn(banner, { failedDrivers }); - // …and again on a channel the host cannot silence — see the helper's note - // on `os serve`'s boot-quiet stdout capture. + // …and again on a channel the operator's log level cannot filter away: the + // line above is dropped outright at `error`/`fatal`/`silent`, which is a + // normal production setting and precisely where this flag gets used. See + // the helper's note — the duplication is deliberate, and it is NOT about + // `os serve`'s boot-quiet window (that swallowed it too until #4012). emitDegradedBootBanner(banner); } diff --git a/packages/runtime/src/app-plugin.ts b/packages/runtime/src/app-plugin.ts index 1f76cdeef5..1016096d8d 100644 --- a/packages/runtime/src/app-plugin.ts +++ b/packages/runtime/src/app-plugin.ts @@ -932,10 +932,13 @@ export class AppPlugin implements Plugin { const totalRefsDropped = result.summary.totalReferencesDropped ?? 0; // #3415/#3430: stash a per-source outcome on the kernel so // the CLI boot banner can print a Seeds line. The logs below - // never reach `os dev` output — info is under the default - // warn level, and the serve boot-quiet window swallows stdout - // — so without this a fixture can lose most of its rows with - // no signal at all. One labelled entry per config app. + // are `info`, which sits under the default `warn` level, so + // they never reach `os dev` output — without this a fixture + // can lose most of its rows with no signal at all. (The + // serve boot-quiet window used to swallow them on top of + // that, at every level; framework#4012 fixed that half, but + // the level gate below is what still hides these.) One + // labelled entry per config app. recordSeedOutcome(ctx, { source: String(appId), inserted: totalInserted, diff --git a/packages/runtime/src/degraded-boot-parity.test.ts b/packages/runtime/src/degraded-boot-parity.test.ts index 666de812d6..da47d48621 100644 --- a/packages/runtime/src/degraded-boot-parity.test.ts +++ b/packages/runtime/src/degraded-boot-parity.test.ts @@ -135,7 +135,12 @@ describe('degraded-boot parity between the two connect paths (framework#3826)', }); } - it('announces the degraded state on stderr, which `os serve` boot-quiet cannot swallow', async () => { + // Parity with the engine-side pin in + // `objectql/src/engine-driver-connect-failfast.test.ts`: the stderr copy + // survives the operator's LOG LEVEL (`warn` is dropped outright at + // `error`/`fatal`/`silent`), not `os serve`'s boot-quiet window — that + // swallowed the banner at every level until framework#4012 fixed it. + it('announces the degraded state on stderr, which the operator log level cannot filter away', async () => { process.env[ENV] = '1'; const written: string[] = []; const realWrite = process.stderr.write; diff --git a/packages/runtime/src/seed-summary.ts b/packages/runtime/src/seed-summary.ts index 8ed8a9772c..c073f58609 100644 --- a/packages/runtime/src/seed-summary.ts +++ b/packages/runtime/src/seed-summary.ts @@ -3,11 +3,12 @@ /** * Boot-time seed outcome accumulator (#3415, extended #3430). * - * Seeds run inside the CLI's boot-quiet stdout window and SeedLoader's own - * result logs sit under the default `warn` level, so `os dev` shows NOTHING - * about how seeding actually went — a fixture can silently lose most of its - * rows, a marketplace package can rehydrate onto a fresh DB with zero rows, - * and a partial row-level failure leaves no signal at all. + * SeedLoader's own result logs sit under the default `warn` level, so `os dev` + * shows NOTHING about how seeding actually went — a fixture can silently lose + * most of its rows, a marketplace package can rehydrate onto a fresh DB with + * zero rows, and a partial row-level failure leaves no signal at all. (Seeds + * also run inside the CLI's boot-quiet window, which hid them at every level + * until framework#4012; the level gate is what still hides them.) * * Every seeding producer (AppPlugin's inline config-app seed, the * marketplace rehydrate/heal path) records a per-source outcome on the diff --git a/packages/services/service-datasource/src/__tests__/datasource-connection-service.test.ts b/packages/services/service-datasource/src/__tests__/datasource-connection-service.test.ts index d7f8d484e7..f6a43a4be3 100644 --- a/packages/services/service-datasource/src/__tests__/datasource-connection-service.test.ts +++ b/packages/services/service-datasource/src/__tests__/datasource-connection-service.test.ts @@ -321,7 +321,11 @@ describe('DatasourceConnectionService.connect', () => { expect(warned).toContain('visit'); }); - it('repeats the degraded banner on stderr, which `os serve` boot-quiet cannot swallow', async () => { + // The stderr copy survives the operator's LOG LEVEL — `warn` is dropped + // outright at `error`/`fatal`/`silent` — not `os serve`'s boot-quiet + // window, which swallowed it at every level until framework#4012 fixed + // that. Same pin as the engine-side and runtime-side parity tests. + it('repeats the degraded banner on stderr, which the operator log level cannot filter away', async () => { process.env[ENV] = '1'; const written: string[] = []; const realWrite = process.stderr.write; diff --git a/packages/types/src/degraded-boot.ts b/packages/types/src/degraded-boot.ts index c08f2b6ca6..7977a394f1 100644 --- a/packages/types/src/degraded-boot.ts +++ b/packages/types/src/degraded-boot.ts @@ -22,12 +22,21 @@ * silence. * * `OS_ALLOW_DRIVER_CONNECT_FAILURE` only justifies itself if the state it opts - * into is impossible to miss — and a logger-only banner is missable: `os serve` - * swallows ALL of stdout while the kernel boots (its "boot-quiet" capture), and - * `Logger` routes `warn` to stdout, so the one message that matters would be - * invisible in exactly the situation it exists for. Writing to stderr as well - * is the same belt-and-braces the kernel already uses for plugin startup - * failures. + * into is impossible to miss — and a logger-only banner is missable, because + * the logger answers to a level the operator sets. `Logger.write()` returns + * before emitting anything when the record is below `config.level`, so at + * `--log-level error`, `fatal`, or `silent` this `warn` never reaches ANY + * stream. A production host running at `error` is exactly the deployment this + * flag exists for, and is exactly where the banner would vanish. Writing to + * stderr as well is the same belt-and-braces the kernel already uses for + * plugin startup failures. + * + * A second reason used to be load-bearing and no longer is: `os serve` blanked + * ALL of stdout while the kernel booted, and `Logger` routes `warn` to stdout, + * so a boot-phase banner was swallowed at every level. That was framework#4012 + * and is fixed — the boot window buffers and replays `warn`-and-above instead + * of discarding it. Do not re-derive this helper's necessity from the + * boot-quiet capture; the level filter is what keeps it alive. * * Best-effort and never throws: falls back to `console.error`, then to silence * on runtimes that have neither (the logger still carries the structured