From ac297afc7c00ec812739174c3c2c53e433be236a Mon Sep 17 00:00:00 2001 From: Claude Date: Thu, 30 Jul 2026 09:55:49 +0000 Subject: [PATCH] docs(types,objectql,runtime,cli): repoint the degraded-boot stderr copy at the reason that survived #4012 MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit `emitDegradedBootBanner` writes the OS_ALLOW_DRIVER_CONNECT_FAILURE banner to stderr on top of `logger.warn`, and every comment and test name explaining why cited one reason: `os serve` swallowed all of stdout while the kernel booted, and Logger routes `warn` to stdout. #4012 fixed that, which retires the stated justification for a duplicate that is still load-bearing for a different one: `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. A production host at `error` is exactly the deployment this escape hatch exists for, and exactly where a logger-only banner vanishes. Deleting the stderr copy on the strength of #4012 would have been a regression — so this documents the surviving reason where someone would read it before deleting it: `degraded-boot.ts`, the engine emit site, and all three parity tests (objectql, runtime, service-datasource), 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 rather than asserting around it: it drives a real ObjectLogger at level 'error' and requires the banner on stderr AND nothing on stdout. Setting the level to 'warn' makes it fail, so it is pinned to the level filter instead of passing for any reason. Same sweep, same class of stale premise, all comment-only: - 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 must 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. Verified: objectql 1180, runtime 913 (one pre-existing failure unrelated to this diff, filed as #4102), types 48, cli 877, service-datasource 154; eslint clean on every touched file. Refs #4012 Co-Authored-By: Claude Opus 5 Claude-Session: https://claude.ai/code/session_01HrRNgrWaRtggzmrHpbomyh --- .changeset/degraded-boot-stderr-premise.md | 46 +++++++++++++++++++ .../commands/serve-automation-summary.test.ts | 15 +++--- packages/cli/src/commands/serve.ts | 23 +++++----- .../cli/src/utils/format.seed-summary.test.ts | 6 ++- packages/cli/src/utils/format.ts | 21 +++++---- .../engine-driver-connect-failfast.test.ts | 33 ++++++++++--- packages/objectql/src/engine.ts | 7 ++- packages/runtime/src/app-plugin.ts | 11 +++-- .../runtime/src/degraded-boot-parity.test.ts | 7 ++- packages/runtime/src/seed-summary.ts | 11 +++-- .../datasource-connection-service.test.ts | 6 ++- packages/types/src/degraded-boot.ts | 21 ++++++--- 12 files changed, 152 insertions(+), 55 deletions(-) create mode 100644 .changeset/degraded-boot-stderr-premise.md 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