From fab760f8fc9e1000b90b0b78440d17610142d5bc Mon Sep 17 00:00:00 2001 From: Claude Date: Thu, 6 Aug 2026 13:49:31 +0000 Subject: [PATCH] =?UTF-8?q?fix(metadata-protocol,objectql):=20loadMetaFrom?= =?UTF-8?q?Db=20=E7=94=A8=E8=BF=94=E5=9B=9E=E5=80=BC=E8=A1=A8=E8=BE=BE?= =?UTF-8?q?=E3=80=8C=E6=B2=A1=E8=AF=BB=E5=88=B0=E5=AD=98=E5=82=A8=E3=80=8D?= =?UTF-8?q?,boot=20=E4=BE=A7=E4=B8=8D=E5=86=8D=E6=8A=8A=20outage=20?= =?UTF-8?q?=E8=AE=B0=E6=88=90=E7=A9=BA=E5=BA=93=20(#5897)?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit `loadMetaFromDb` 的返回值 `{ loaded, errors, invalid }` 没有任何字段能表达 「这次水合根本没读到存储」—— 读不到的数据库与真正的空库都答 `loaded: 0`。 其唯一生产消费方 `ObjectQLPlugin.restoreMetadataFromDb` 因此无从分支:它唯一 的分支只是在两条日志之间做选择,而「什么都没回来」那一侧是 debug 级的 `No persisted metadata found in database`。于是一个一个字都没读到持久化元数据 的 kernel,在 debug 级上宣称「本来就没有」,然后照常报告 ready。 代价写在 plugin.ts Phase 2 注释里:registry 为空时 `registry.getObject` 把 「读不到」答成「没声明」—— unknown-column 查询守卫、hooks、relationships 静默 降级,overlay 对象既不建表也不桥接。这是 ADR-0110 D3(outage ≠ miss)在 boot 侧的落地,继 #5108 / #5089 / #5532 / #5707 之后。 - 生产端:返回值加 `storeUnavailable: boolean`,只在已经打印 `[Protocol] DB hydration skipped` 的那条分支上置位 —— 即 `isMissingTableError` 判为非良性的读失败。未建表的首次启动(#5841)不置位,那里 `loaded: 0` 确是事实。 - 消费端:读该位并打 **error** 级日志,按 AGENTS「Degradation log levels」写清 后果(什么都没恢复、kernel 仍报健康、哪些能力静默降级)与修法(查 sys_metadata 背后的数据源:连接、凭据、表是否存在,然后重启)。可读的空库照旧 debug。 ⛔ 不改控制流:boot 继续降级运行 —— 对着读不到的 overlay 存储拒绝启动,会把一次 瞬时故障变成彻底停机。变的只是「降级」不再被当成「健康」。 对 `ProtocolWithDbRestore` 鸭子类型实现者零破坏:新字段在消费侧声明为 optional (与既有的 `invalid` 同例),旧 shim 照常通过类型检查并被读成「不是 outage」—— 正是它此前唯一能表达的判定。 Co-Authored-By: Claude Fable 5 Claude-Session: https://claude.ai/code/session_019Q7oc7ASjh8yxyS3Yz78We --- .../boot-hydration-outage-diagnostic.md | 62 +++++ ...rotocol.load-meta-hydration-benign.test.ts | 160 +++++++++--- .../src/protocol.stored-conversions.test.ts | 5 +- packages/metadata-protocol/src/protocol.ts | 60 ++++- .../plugin-restore-metadata-outage.test.ts | 242 ++++++++++++++++++ packages/objectql/src/plugin.ts | 61 ++++- 6 files changed, 541 insertions(+), 49 deletions(-) create mode 100644 .changeset/boot-hydration-outage-diagnostic.md create mode 100644 packages/objectql/src/plugin-restore-metadata-outage.test.ts diff --git a/.changeset/boot-hydration-outage-diagnostic.md b/.changeset/boot-hydration-outage-diagnostic.md new file mode 100644 index 0000000000..2fbe3100ed --- /dev/null +++ b/.changeset/boot-hydration-outage-diagnostic.md @@ -0,0 +1,62 @@ +--- +"@objectstack/metadata-protocol": patch +"@objectstack/objectql": patch +--- + +fix(metadata-protocol,objectql): a boot that could not read `sys_metadata` says so at `error`, instead of reporting "no persisted metadata" at debug (#5897) + +`loadMetaFromDb` — the boot step that hydrates `sys_metadata` overlay rows into +the SchemaRegistry — returned `{ loaded, errors, invalid }`, and no field in +that shape could express **"this hydration never read the store"**. An +unreachable database and a genuinely empty one both answered `loaded: 0`. + +Its only production consumer, `ObjectQLPlugin.restoreMetadataFromDb`, therefore +had nothing to branch on: its single branch chose between two log lines, and +the "nothing came back" side was +`logger.debug('No persisted metadata found in database')`. So a kernel that +could not read a word of its persisted metadata stated at **debug** level that +there was none, and went on to report ready. + +What that costs is not hypothetical — it is written into the plugin's own +Phase 2 comment. With the registry empty, `registry.getObject` answers "not +declared" where the truth is "we could not look": unknown-column query guards, +hooks and relationships silently degrade, and overlay objects get neither a +synced table nor a metadata bridge. This is ADR-0110 D3 (an outage is not a +miss) on the boot side, after the same rule landed for `DatabaseLoader` +(#5108), `listForIndex` (#5089) and the overlay reads (#5532 / #5707). + +**What changed** + +- `loadMetaFromDb` returns `storeUnavailable: boolean`, set on exactly the + branch that already prints `[Protocol] DB hydration skipped` — a read that + failed for a reason `isMissingTableError` does *not* call benign. A store + that has merely not been provisioned yet (first boot, before migrations) + keeps `storeUnavailable: false`, because `loaded: 0` genuinely is the truth + there (#5841). +- `restoreMetadataFromDb` reads it and logs at **`error`**, naming the + consequence (nothing was restored, the kernel keeps reporting healthy, and + which capabilities silently degrade) and the fix (check the datasource behind + `sys_metadata` — connection, credentials, table existence — then restart). + Per AGENTS.md "Degradation log levels": persisted state and runtime state + disagreeing while the system still looks healthy is the `error` class. An + empty-but-readable store keeps its quiet debug line, so first boots do not + start emitting durability errors. + +**Not changed**: control flow. Boot still degrades and continues — refusing to +boot on an unreadable overlay store would turn a transient outage into an +outright one. What changes is that the degradation is now distinguishable from +health, and reported as such. + +**Impact on duck-typed `ProtocolWithDbRestore` implementers**: none required. +`ObjectQLPlugin` matches the `protocol` service structurally, and the new field +is declared **optional** on its side of the contract, exactly as `invalid` +already is. A shim that predates the field keeps type-checking and is read as +"not an outage" — the only verdict it was able to express before — so its +behaviour is byte-for-byte what it was. The trade-off is deliberate and worth +naming: an optional field cannot *force* a third-party shim to start reporting +outages, so such a shim stays as silent as it is today. Requiring the field +would have made that impossible to ignore at the cost of breaking every +external implementer for a bit only one in-repo producer sets; the in-repo +producer (`ObjectStackProtocolImplementation`) declares and returns it +**required**, so the path that actually runs in every ObjectStack kernel is +fully covered. diff --git a/packages/metadata-protocol/src/protocol.load-meta-hydration-benign.test.ts b/packages/metadata-protocol/src/protocol.load-meta-hydration-benign.test.ts index 0f79ca4960..cf6b04890b 100644 --- a/packages/metadata-protocol/src/protocol.load-meta-hydration-benign.test.ts +++ b/packages/metadata-protocol/src/protocol.load-meta-hydration-benign.test.ts @@ -32,32 +32,55 @@ // `@objectstack/metadata/errors`. // // --------------------------------------------------------------------------- -// Deliberately NOT covered here — #5841 fact 2 +// #5841 fact 2, now closed — #5897 // --------------------------------------------------------------------------- -// Every non-benign failure is still answered with `console.warn` + a -// `{ loaded: 0, errors: 0, invalid: 0 }` return, so the return value cannot -// distinguish "the store holds no overlay rows" from "the store could not be -// read" (ADR-0110 D3, on the boot side). That is a change to this method's -// return CONTRACT and to its consumer (`ObjectQLPlugin.restoreMetadataFromDb`), -// so it was measured and reported separately rather than bundled in. The -// `records the fact-2 indistinguishability` case below pins the measurement, -// not an endorsement — see its comment. +// The classification above decided which failures are worth a console line. It +// did NOT change the return value: every non-benign failure still answered +// `{ loaded: 0, errors: 0, invalid: 0 }`, the exact shape a healthy empty store +// answers, so nothing a CALLER can read distinguished "the store holds no +// overlay rows" from "the store could not be read" (ADR-0110 D3, on the boot +// side). The sole consumer, `ObjectQLPlugin.restoreMetadataFromDb`, therefore +// logged an unreachable database as `debug` "No persisted metadata found in +// database" and the kernel reported ready. +// +// #5897 adds `storeUnavailable: boolean` to the return, set on exactly the +// branch that prints `DB hydration skipped` — the non-benign one. The +// `outage vs empty store` case below is the SAME measurement as before, turned +// over: it used to assert the two are indistinguishable, and now asserts the +// bit is precisely what tells them apart while every count stays identical. +// +// Not a superset of `errors`: that counter is about rows that arrived and +// failed to hydrate, this bit is about a row set that never arrived. And not a +// control-flow change — boot still degrades and continues. // // --------------------------------------------------------------------------- // Reverse verification, direction predicted BEFORE running // --------------------------------------------------------------------------- -// Restore `if (!/no such table/i.test(e.message ?? ''))` and this file goes -// PARTIALLY red — which is itself the finding, so the split is recorded rather -// than rounded to "it goes red": +// Two limbs, two predictions, both confirmed by running them: +// +// (1) Restore `if (!/no such table/i.test(e.message ?? ''))` (the #5841 fix) +// and this file goes PARTIALLY red — the split is itself the finding, so it +// is recorded rather than rounded to "it goes red": +// +// * RED: every "table not provisioned" case whose driver does not use +// SQLite's wording — the Postgres message, the code-only `42P01`, the +// MySQL `errno`, and the wrapped `cause` — because the regex cannot see +// any of them, so the benign first boot both warns AND (post-#5897) +// mis-sets `storeUnavailable`, mistaking health for an outage. +// * GREEN, unchanged: the SQLite case (the one phrasing the old regex was +// written against), the ECONNREFUSED outage case (already warned, still +// warns), and the working-store control. A suite that went fully red +// here would mean the fix had changed more than the classification. // -// * RED: every "table not provisioned" case whose driver does not use -// SQLite's wording — the Postgres message, the code-only `42P01`, the -// MySQL `errno`, and the wrapped `cause` — because the regex cannot see any -// of them and the benign first boot starts warning. -// * GREEN, unchanged: the SQLite case (the one phrasing the old regex was -// written against), the ECONNREFUSED outage case (already warned, still -// warns), and the working-store control. A suite that went fully red here -// would mean the fix had changed more than the classification. +// (2) Delete `storeUnavailable = true` from that branch (the #5897 fix) and the +// complementary set goes red, all in the same direction — no inversion, no +// count that moves the other way: +// +// * RED: the outage cases (`ECONNREFUSED`, the non-Error rejection, the +// unrecognised-wording case) and `outage vs empty store`, which stops +// being able to tell them apart — i.e. exactly the defect #5897 names. +// * GREEN, unchanged: every benign case and the working-store control, +// because `false` is what they already expected. // // The engine doubles below declare `find` only — `loadMetaFromDb` calls nothing // else on the engine, and a fake with no `delete`/`update` member has no write @@ -158,8 +181,11 @@ describe('loadMetaFromDb — an unprovisioned store is benign, by error TYPE (#5 const res = await protocol.loadMetaFromDb(); - // Benign: there really are no overlay rows yet, so this IS the truth. - expect(res).toEqual({ loaded: 0, errors: 0, invalid: 0 }); + // Benign: there really are no overlay rows yet, so this IS the + // truth — including `storeUnavailable: false` (#5897). An + // un-provisioned store is not an outage, and a bit that fired here + // would turn every first boot into a boot-time `error`. + expect(res).toEqual({ loaded: 0, errors: 0, invalid: 0, storeUnavailable: false }); // …and a healthy first boot owes the operator no warning line. expect( warn.mock.calls.map((c) => String(c[0])), @@ -178,9 +204,14 @@ describe('loadMetaFromDb — an unprovisioned store is benign, by error TYPE (#5 engineThatCannotBeRead(() => new Error('role "app_ro" does not exist')), ); - await protocol.loadMetaFromDb(); + const res = await protocol.loadMetaFromDb(); expect(warn.mock.calls.some((c) => String(c[0]).startsWith(SKIPPED))).toBe(true); + // The console line and the return bit are ONE verdict, read twice — + // a failure loud enough to warn about is one the caller must be able + // to see too (#5897). If these two ever disagree, the boot log and the + // boot's own return value are describing different systems. + expect(res.storeUnavailable).toBe(true); }); }); @@ -193,7 +224,9 @@ describe('loadMetaFromDb — every other read failure stays loud (#5841)', () => const res = await protocol.loadMetaFromDb(); - expect(res).toEqual({ loaded: 0, errors: 0, invalid: 0 }); + // #5897 — the counts are unchanged (nothing was loaded, and truthfully + // so), but the shape now ALSO says why: the read never happened. + expect(res).toEqual({ loaded: 0, errors: 0, invalid: 0, storeUnavailable: true }); const skipped = warn.mock.calls .map((c) => String(c[0])) .filter((m) => m.startsWith(SKIPPED)); @@ -209,7 +242,7 @@ describe('loadMetaFromDb — every other read failure stays loud (#5841)', () => engineThatCannotBeRead(() => 'pool exhausted'), ); - await protocol.loadMetaFromDb(); + const res = await protocol.loadMetaFromDb(); const skipped = warn.mock.calls .map((c) => String(c[0])) @@ -217,18 +250,23 @@ describe('loadMetaFromDb — every other read failure stays loud (#5841)', () => expect(skipped).toHaveLength(1); expect(skipped[0]).toContain('pool exhausted'); expect(skipped[0]).not.toContain('undefined'); + // A driver that rejects with a bare string is still an outage: the bit + // is set from the CLASSIFICATION, never from the thrown value's shape. + expect(res.storeUnavailable).toBe(true); }); - it('records the fact-2 indistinguishability: an outage returns exactly what an empty store returns', async () => { - // NOT an endorsement — this is #5841 fact 2, measured. The console.warn - // above is the only channel that separates these two, and the RETURN - // VALUE (the thing `ObjectQLPlugin.restoreMetadataFromDb` reads) makes - // them identical, so boot logs `No persisted metadata found in database` - // at debug level for an unreachable store. + it('an outage and an empty store agree on every count and are told apart by the bit alone', async () => { + // This case is #5841 fact 2, TURNED OVER (#5897). It used to assert + // `expect(outage).toEqual(emptyStore)` and carried the note "when the + // return contract grows a way to say the store could not be read, this + // assertion is EXPECTED to flip — update it to assert the difference; + // do not delete the case." This is that flip. // - // When the return contract grows a way to say "the store could not be - // read", this assertion is EXPECTED to flip — update it to assert the - // difference; do not delete the case. + // The `console.warn` is no longer the ONLY channel separating the two. + // The return value — the thing `ObjectQLPlugin.restoreMetadataFromDb` + // actually reads — now separates them as well, which is what lets boot + // log an unreachable store at `error` instead of `debug` "No persisted + // metadata found in database". const warn = vi.spyOn(console, 'warn').mockImplementation(() => {}); const outage = await new ObjectStackProtocolImplementation( engineThatCannotBeRead(connectionRefused), @@ -237,7 +275,20 @@ describe('loadMetaFromDb — every other read failure stays loud (#5841)', () => engineWithRows([]).engine, ).loadMetaFromDb(); - expect(outage).toEqual(emptyStore); + // Distinguishable at all — the defect, gone. + expect(outage).not.toEqual(emptyStore); + expect(outage.storeUnavailable).toBe(true); + expect(emptyStore.storeUnavailable).toBe(false); + + // …and distinguishable by the bit ALONE. Asserted rather than implied: + // every count is still identical, so nothing downstream can reconstruct + // the difference from `loaded`/`errors`/`invalid` and quietly grow a + // second, weaker way of asking the same question. + const { storeUnavailable: _o, ...outageCounts } = outage; + const { storeUnavailable: _e, ...emptyCounts } = emptyStore; + expect(outageCounts).toEqual(emptyCounts); + expect(outageCounts).toEqual({ loaded: 0, errors: 0, invalid: 0 }); + expect(warn).toHaveBeenCalled(); }); }); @@ -266,7 +317,46 @@ describe('loadMetaFromDb — a working store is untouched by the classification expect(res.loaded).toBe(1); expect(res.errors).toBe(0); + // #5897 — the control that keeps the bit from becoming decorative: a + // read that SUCCEEDED must report `false`, or every boot is an outage. + expect(res.storeUnavailable).toBe(false); expect(registered).toHaveLength(1); expect(warn.mock.calls.some((c) => String(c[0]).startsWith(SKIPPED))).toBe(false); }); + + it('rows that fail to hydrate are counted in `errors`, NOT reported as an unavailable store', async () => { + // #5897 — the other half of "not a superset of `errors`". Here the read + // succeeded and one row is unparseable: the store was perfectly + // available, the hydration is PARTIAL. Setting the bit here would make + // boot print the durability `error` for a single corrupt row, which is + // the mirror-image failure AGENTS.md "Degradation log levels" warns + // about — it trains everyone to skim `error`. + const warn = vi.spyOn(console, 'warn').mockImplementation(() => {}); + const { engine } = engineWithRows([ + { + id: 'r_ok', + type: 'app', + name: 'crm', + organization_id: null, + state: 'active', + metadata: JSON.stringify({ name: 'crm', label: 'CRM' }), + }, + { + id: 'r_bad', + type: 'app', + name: 'broken', + organization_id: null, + state: 'active', + metadata: 'not-valid-json{{{', + }, + ]); + + const res = await new ObjectStackProtocolImplementation(engine).loadMetaFromDb(); + + expect(res.loaded).toBe(1); + expect(res.errors).toBe(1); + expect(res.storeUnavailable).toBe(false); + expect(warn).toHaveBeenCalled(); // the per-row line, not the skipped one + expect(warn.mock.calls.some((c) => String(c[0]).startsWith(SKIPPED))).toBe(false); + }); }); diff --git a/packages/metadata-protocol/src/protocol.stored-conversions.test.ts b/packages/metadata-protocol/src/protocol.stored-conversions.test.ts index e79e68ad3d..76977599e4 100644 --- a/packages/metadata-protocol/src/protocol.stored-conversions.test.ts +++ b/packages/metadata-protocol/src/protocol.stored-conversions.test.ts @@ -163,7 +163,10 @@ describe('loadMetaFromDb — boot hydration converts, diagnoses, never drops (#3 const { engine, registered } = makeStubEngine([legacyObjectRow, legacyActionRow]); const protocol = new ObjectStackProtocolImplementation(engine); const res = await protocol.loadMetaFromDb(); - expect(res).toEqual({ loaded: 2, errors: 0, invalid: 0 }); + // `storeUnavailable: false` (#5897) — a read that happened. The whole + // return is asserted rather than the three counts, so a future field + // cannot appear here unexamined. + expect(res).toEqual({ loaded: 2, errors: 0, invalid: 0, storeUnavailable: false }); const obj = registered.find((r) => r.kind === 'object')!; expect(obj.body.fields.amount.requiredWhen).toBe("record.status == 'sent'"); diff --git a/packages/metadata-protocol/src/protocol.ts b/packages/metadata-protocol/src/protocol.ts index 1b46f064d2..36a923769c 100644 --- a/packages/metadata-protocol/src/protocol.ts +++ b/packages/metadata-protocol/src/protocol.ts @@ -10395,11 +10395,44 @@ export class ObjectStackProtocolImplementation implements * writes (422), and the read surfaces badge the row via * `_diagnostics`. This is that same read-side verdict, surfaced once * at boot where operators look. + * + * #5897 / ADR-0110 D3 — the return value can now say **"the store was not + * read at all"**. `loaded: 0` alone cannot: it is equally the truth for an + * empty store, an un-provisioned store, and a database this process could + * not reach, and the sole consumer + * (`ObjectQLPlugin.restoreMetadataFromDb`) therefore logged an outage as + * `debug` "No persisted metadata found in database" while the kernel went + * on to report ready. `storeUnavailable` is that missing bit, set on + * exactly the branch that already prints `DB hydration skipped` — i.e. the + * outer read failed for a reason {@link isMissingTableError} does NOT call + * benign. + * + * Three things it deliberately is **not**: + * + * - **Not a superset of `errors`.** Per-row hydration failures already + * have their own counter and the rows around them did land. This bit + * means the row set itself never arrived, so the hydration is not + * partial — it is absent. (Named `storeUnavailable` rather than a bare + * `degraded` for that reason: the narrower word cannot be misread as + * "something, somewhere, went wrong".) + * - **Not set for an un-provisioned store.** A first boot before + * migrations genuinely holds no overlay rows (#5841), so `loaded: 0` IS + * the truth there and the bit stays `false`. + * - **Not a control-flow change.** Boot still degrades and continues; what + * changes is that the degradation can be *told apart* from health and is + * reported at the level AGENTS.md "Degradation log levels" prescribes + * for it — persisted state and runtime state disagreeing while the + * system keeps looking healthy is the `error` class. + * + * It is the boot-side spelling of the same fact `MetadataManager`'s + * `loadDiagnosed` reports as `degraded` for the loader plane. */ - async loadMetaFromDb(): Promise<{ loaded: number; errors: number; invalid: number }> { + async loadMetaFromDb(): Promise<{ loaded: number; errors: number; invalid: number; storeUnavailable: boolean }> { let loaded = 0; let errors = 0; let invalid = 0; + /** #5897 — see the TSDoc: set only on the non-benign outer-catch branch. */ + let storeUnavailable = false; try { // ADR-0005 (revised 2026-05): hydrate only env-wide rows // (organization_id IS NULL). Per-org overlays are loaded on @@ -10492,20 +10525,29 @@ export class ObjectStackProtocolImplementation implements // driver that says "no such table" for a different failure got read as // benign. One driver quirk, taught to the platform once. // - // NOT extended here (#5841 fact 2, deliberately left open): every - // OTHER failure is still answered with `console.warn` + `loaded: 0`, - // so the return shape cannot tell "the store had no overlay rows" from - // "the store could not be read" — ADR-0110 D3's rule, on the boot - // side. Changing that changes this method's return contract and its - // consumer in `ObjectQLPlugin.restoreMetadataFromDb`, so it is - // measured and reported separately rather than smuggled in here. + // #5897 (was #5841 fact 2, closed here): every OTHER failure is a + // read that did not happen, and it now SAYS so in the return value + // instead of only in a console line. Before this, the shape could + // not tell "the store had no overlay rows" from "the store could + // not be read" — ADR-0110 D3's rule, on the boot side — so the one + // consumer (`ObjectQLPlugin.restoreMetadataFromDb`) reported an + // outage as `debug` "No persisted metadata found in database" and + // the kernel went on to report ready. + // + // The two lines this branch and that consumer print are one event + // at two altitudes, not a repetition: this one names the DRIVER + // error (the detail an operator debugs with), the consumer's + // `error` names what the outage COSTS and how to fix it. Keeping + // the technical line here at `warn` is what lets the consumer's + // line stay the single loud statement of consequence. if (!isMissingTableError(e)) { + storeUnavailable = true; console.warn( `[Protocol] DB hydration skipped: ${e instanceof Error ? e.message : String(e)}`, ); } } - return { loaded, errors, invalid }; + return { loaded, errors, invalid, storeUnavailable }; } // ========================================== diff --git a/packages/objectql/src/plugin-restore-metadata-outage.test.ts b/packages/objectql/src/plugin-restore-metadata-outage.test.ts new file mode 100644 index 0000000000..6244e860c3 --- /dev/null +++ b/packages/objectql/src/plugin-restore-metadata-outage.test.ts @@ -0,0 +1,242 @@ +// Copyright (c) 2026 ObjectStack. Licensed under the Apache-2.0 license. + +/** + * [#5897, ADR-0110 D3 — boot side] `restoreMetadataFromDb` must report an + * unreadable `sys_metadata` as an outage, not as an empty store. + * + * --------------------------------------------------------------------------- + * The defect + * --------------------------------------------------------------------------- + * `loadMetaFromDb` answered an unreachable database and a genuinely empty one + * with the same `{ loaded: 0, errors: 0, invalid: 0 }`, so this method — its + * ONLY production consumer — had nothing to branch on. Its single branch chose + * between two log lines, and the "nothing came back" side of it was + * `logger.debug('No persisted metadata found in database')`. A kernel that + * could not read a word of its persisted metadata therefore said, at debug + * level, that there was none, and went on to report ready. + * + * What that costs downstream is written into the plugin's own Phase 2 comment + * and is not hypothetical: `registry.getObject` answers empty, so unknown-column + * query guards, hooks and relationships silently degrade; overlay objects get + * neither a synced table nor a metadata bridge. Every one of those reads + * "the author declared nothing" where the truth is "we could not look". + * + * --------------------------------------------------------------------------- + * What is pinned here + * --------------------------------------------------------------------------- + * The consumer half only — that the diagnostic bit is READ, and that the level + * it is read at is `error` per AGENTS.md "Degradation log levels": persisted + * state and runtime state disagree while the system keeps looking healthy. + * The producer half (which failures set the bit, and that an un-provisioned + * store does not) is pinned next to the classification it belongs to, in + * `@objectstack/metadata-protocol`'s `protocol.load-meta-hydration-benign.test.ts`. + * + * The protocol double here declares `loadMetaFromDb` only — that is the entire + * surface {@link hasLoadMetaFromDb} probes and the entire surface this method + * calls. It declares no engine write verb, so there is no `delete`/`update` + * dispatch for `check:engine-double-contract` to scan and nothing to + * hand-mirror. + * + * --------------------------------------------------------------------------- + * Reverse verification, direction predicted BEFORE running + * --------------------------------------------------------------------------- + * Ordinary direction, no inversion: stop propagating the bit — delete + * `storeUnavailable = true` in the producer, or drop it from the destructure + * here — and the outage case goes RED, because the log falls back to the + * `debug` line it used to emit, which is the defect restated. The empty-store + * and restored cases stay GREEN throughout: they never depended on the bit. + * (Confirmed by running it, not assumed.) + */ + +import { describe, it, expect, vi } from 'vitest'; +import { ObjectQLPlugin } from './plugin.js'; +import type { ObjectQL } from './engine.js'; + +type AnyRecord = Record; + +/** Captures one call to each level so a test can assert WHICH level fired. */ +function makeCtx(protocol: unknown) { + const logger = { + debug: vi.fn(), + info: vi.fn(), + warn: vi.fn(), + error: vi.fn(), + }; + return { + logger, + getService: vi.fn((name: string) => { + if (name === 'protocol') return protocol; + throw new Error(`service '${name}' not registered`); + }), + hook: vi.fn(), + } as AnyRecord; +} + +/** + * A protocol double whose `loadMetaFromDb` answers `result` verbatim. + * + * Deliberately NOT the real `ObjectStackProtocolImplementation`: this file is + * about how the consumer reads the return CONTRACT, so the contract is what it + * feeds in. Which real failures produce which return is the producer's test. + */ +function protocolReturning(result: AnyRecord) { + return { loadMetaFromDb: vi.fn(async () => result) }; +} + +/** The engine is untouched by this path; a bare object satisfies the ctor. */ +function makePlugin() { + return new ObjectQLPlugin({ ql: {} as unknown as ObjectQL }); +} + +/** Every string the logger was handed at `level`, joined for keyword checks. */ +function linesAt(ctx: AnyRecord, level: 'debug' | 'info' | 'warn' | 'error'): string[] { + return ctx.logger[level].mock.calls.map((c: unknown[]) => String(c[0])); +} + +describe('ObjectQLPlugin.restoreMetadataFromDb — an unreadable store is an outage (#5897)', () => { + it('logs at ERROR, not debug, when the protocol reports storeUnavailable', async () => { + const ctx = makeCtx( + protocolReturning({ loaded: 0, errors: 0, invalid: 0, storeUnavailable: true }), + ); + + await (makePlugin() as any).restoreMetadataFromDb(ctx); + + const errors = linesAt(ctx, 'error'); + expect(errors).toHaveLength(1); + + // Pre-fix, THIS is what an unreachable database produced — the assertion + // that fails first if the branch is ever removed. + expect(linesAt(ctx, 'debug')).not.toContain('No persisted metadata found in database'); + expect(linesAt(ctx, 'debug').join('\n')).not.toMatch(/No persisted metadata/); + }); + + it("the error line owes both things AGENTS.md requires: the consequence and the fix", async () => { + const ctx = makeCtx( + protocolReturning({ loaded: 0, errors: 0, invalid: 0, storeUnavailable: true }), + ); + + await (makePlugin() as any).restoreMetadataFromDb(ctx); + + const line = linesAt(ctx, 'error')[0]; + // Names WHAT could not be read… + expect(line).toContain('sys_metadata'); + // …that it was not restored, and that the kernel will still look healthy — + // the half operators cannot infer and the reason this is `error` at all. + expect(line).toMatch(/NOT restored/); + expect(line).toMatch(/healthy/); + // …and the remedy, concretely enough to act on without reading the source. + expect(line).toMatch(/connection|credentials|datasource/); + // …plus the boundary, so the line is not read as covering first boots. + expect(line).toMatch(/provisioned/); + }); + + it('carries the counts as structured metadata rather than burying them in prose', async () => { + const ctx = makeCtx( + protocolReturning({ loaded: 0, errors: 0, invalid: 0, storeUnavailable: true }), + ); + + await (makePlugin() as any).restoreMetadataFromDb(ctx); + + // The `Logger` contract is `error(message, error?: Error, meta?)`, so the + // counts ride the THIRD slot and the error slot stays empty — there is no + // Error to pass: `loadMetaFromDb` swallowed the driver's, having already + // printed it at `warn`. Pinned positionally because the two-argument + // spelling type-checks against `ObjectLogger` (which tolerates meta in the + // error slot) while violating the declared contract every other Logger + // implementation is written to. + expect(ctx.logger.error).toHaveBeenCalledWith( + expect.any(String), + undefined, + { loaded: 0, errors: 0, invalid: 0 }, + ); + }); + + it('outranks the counts: a partial hydration that ALSO lost the store still reports the outage', async () => { + // Defensive on purpose. Today the outer read either throws before any row + // is seen or does not throw at all, so `loaded > 0 && storeUnavailable` is + // not reachable — but the branch ORDER is the thing being pinned, and the + // wrong order (counts first) would degrade silently the day it becomes + // reachable, which is precisely this issue's failure mode one layer up. + const ctx = makeCtx( + protocolReturning({ loaded: 3, errors: 1, invalid: 0, storeUnavailable: true }), + ); + + await (makePlugin() as any).restoreMetadataFromDb(ctx); + + expect(linesAt(ctx, 'error')).toHaveLength(1); + expect(linesAt(ctx, 'info')).toEqual([]); + expect(ctx.logger.error).toHaveBeenCalledWith( + expect.any(String), + undefined, + { loaded: 3, errors: 1, invalid: 0 }, + ); + }); +}); + +describe('ObjectQLPlugin.restoreMetadataFromDb — health is still reported as health (#5897)', () => { + it('an empty but READABLE store keeps the quiet debug line', async () => { + // The over-application guard. Escalating this to `error` is the + // mirror-image failure AGENTS.md names: every first boot in every test and + // every fresh install would print a durability error, and `error` stops + // being readable — which is what made the original `warn` unreadable. + const ctx = makeCtx( + protocolReturning({ loaded: 0, errors: 0, invalid: 0, storeUnavailable: false }), + ); + + await (makePlugin() as any).restoreMetadataFromDb(ctx); + + expect(linesAt(ctx, 'error')).toEqual([]); + expect(linesAt(ctx, 'debug')).toContain('No persisted metadata found in database'); + }); + + it('a successful restore still reports info with loaded/errors/invalid', async () => { + const ctx = makeCtx( + protocolReturning({ loaded: 4, errors: 1, invalid: 2, storeUnavailable: false }), + ); + + await (makePlugin() as any).restoreMetadataFromDb(ctx); + + expect(linesAt(ctx, 'error')).toEqual([]); + expect(ctx.logger.info).toHaveBeenCalledWith( + 'Metadata restored from database to SchemaRegistry', + { loaded: 4, errors: 1, invalid: 2 }, + ); + }); + + it('a protocol shim that predates the field is read as "not an outage", not as undefined', async () => { + // `storeUnavailable` is OPTIONAL on `ProtocolWithDbRestore` because the + // interface is structural — matched against whatever object is registered + // as `protocol`. An older shim omitting it must behave exactly as it did + // before this change, which is the whole basis for calling the field + // non-breaking in the changeset. + const ctx = makeCtx(protocolReturning({ loaded: 0, errors: 0 })); + + await (makePlugin() as any).restoreMetadataFromDb(ctx); + + expect(linesAt(ctx, 'error')).toEqual([]); + expect(linesAt(ctx, 'debug')).toContain('No persisted metadata found in database'); + }); +}); + +describe('ObjectQLPlugin.restoreMetadataFromDb — the pre-existing skip paths are untouched (#5897)', () => { + it('a protocol without loadMetaFromDb still skips at debug', async () => { + const ctx = makeCtx({ notTheRightShape: true }); + + await (makePlugin() as any).restoreMetadataFromDb(ctx); + + expect(linesAt(ctx, 'error')).toEqual([]); + expect(linesAt(ctx, 'debug').join('\n')).toMatch(/does not support loadMetaFromDb/); + }); + + it('no protocol service at all still skips at debug', async () => { + const ctx = makeCtx(undefined); + ctx.getService = vi.fn(() => { + throw new Error('service not registered'); + }); + + await (makePlugin() as any).restoreMetadataFromDb(ctx); + + expect(linesAt(ctx, 'error')).toEqual([]); + expect(linesAt(ctx, 'debug').join('\n')).toMatch(/Protocol service unavailable/); + }); +}); diff --git a/packages/objectql/src/plugin.ts b/packages/objectql/src/plugin.ts index c60c739d87..4e7d214318 100644 --- a/packages/objectql/src/plugin.ts +++ b/packages/objectql/src/plugin.ts @@ -20,7 +20,24 @@ export type { Plugin, PluginContext }; * `@objectstack/spec`, since it is a server-side bootstrap concern only. */ interface ProtocolWithDbRestore { - loadMetaFromDb(): Promise<{ loaded: number; errors: number; invalid?: number }>; + loadMetaFromDb(): Promise<{ + loaded: number; + errors: number; + invalid?: number; + /** + * [#5897, ADR-0110 D3] True when the `sys_metadata` read itself failed for + * a reason that is NOT "the table has not been provisioned yet" — i.e. the + * row set never arrived, so `loaded: 0` is an outage rather than an empty + * store. `restoreMetadataFromDb` branches on it to tell the two apart. + * + * Optional, like `invalid` above and for the same reason: this interface is + * structural, matched by {@link hasLoadMetaFromDb} against whatever object + * happens to be registered as `protocol`. A shim that predates the field + * keeps type-checking and is simply read as "not an outage" — the same + * verdict it could express before. + */ + storeUnavailable?: boolean; + }>; } /** Type guard — checks whether the service exposes `loadMetaFromDb`. */ @@ -1117,6 +1134,20 @@ export class ObjectQLPlugin implements Plugin { * - The protocol service is unavailable (e.g., in-memory-only mode). * - `loadMetaFromDb` is not implemented by the protocol shim. * - The underlying driver/table does not exist yet (first-run scenario). + * + * [#5897, ADR-0110 D3] Degrading is not the same as being fine, and this + * method used to be unable to say which one happened: `loadMetaFromDb` + * answered an unreachable database and an empty one with the same + * `loaded: 0`, so a boot that restored nothing because it could not read + * `sys_metadata` logged `debug` "No persisted metadata found in database" + * and the kernel reported ready. `storeUnavailable` now carries that + * distinction, and the outage branch logs at `error` per AGENTS.md + * "Degradation log levels" — runtime state silently disagreeing with + * persisted state, while the system keeps looking healthy, is exactly the + * class that rule reserves `error` for. Control flow is unchanged: boot + * still continues in the degraded state (refusing to boot on an unreadable + * overlay store would turn a transient outage into an outright outage), + * it just no longer claims that state is health. */ private async restoreMetadataFromDb(ctx: PluginContext): Promise { // Phase 1: Resolve protocol service (separate from DB I/O for clearer diagnostics) @@ -1137,14 +1168,36 @@ export class ObjectQLPlugin implements Plugin { // Phase 2: DB hydration (loads into SchemaRegistry) try { - const { loaded, errors, invalid = 0 } = await protocol.loadMetaFromDb(); - - if (loaded > 0 || errors > 0) { + const { loaded, errors, invalid = 0, storeUnavailable = false } = await protocol.loadMetaFromDb(); + + if (storeUnavailable) { + // #5897 — FIRST branch on purpose: "we could not read the store" out- + // ranks any count taken from a read that did not happen. The line owes + // the two things AGENTS.md requires of a durability `error` — the + // concrete consequence, and the fix. + ctx.logger.error( + 'sys_metadata could NOT be read at boot — persisted metadata was NOT restored, and this kernel will keep reporting healthy. ' + + 'Every overlay object, view, app, permission and hook stored in the database is absent from the SchemaRegistry for the life of this process: ' + + 'registry lookups answer "not declared" rather than "unavailable", so unknown-column query guards, hooks and relationships silently degrade, ' + + 'and overlay objects get neither a synced table nor a metadata bridge. Authoring against this kernel writes on top of state it never loaded. ' + + 'Fix: check the datasource behind sys_metadata — connection, credentials, and that the table exists — then restart. ' + + 'A store that merely has not been provisioned yet is NOT this case; that first-boot path stays quiet.', + // `Logger.error(message, error?: Error, meta?)` — the error slot is + // genuinely empty here: `loadMetaFromDb` swallows the driver error + // and returns only the verdict, having already printed the driver's + // own text at `warn` (`[Protocol] DB hydration skipped: …`). Passing + // the counts in the declared meta slot rather than the error slot, + // per the contract in `@objectstack/spec/contracts`. + undefined, + { loaded, errors, invalid }, + ); + } else if (loaded > 0 || errors > 0) { // `invalid` (#3903): rows registered despite failing the current spec // schema AFTER the stored conversion chain — each already warned with // `[metadata_spec_invalid]` and carries `_diagnostics` on read. ctx.logger.info('Metadata restored from database to SchemaRegistry', { loaded, errors, invalid }); } else { + // Reachable store, nothing in it — the ordinary empty/first-boot case. ctx.logger.debug('No persisted metadata found in database'); } } catch (e: unknown) {