fix(metadata-protocol,objectql): loadMetaFromDb 用返回值表达「没读到存储」,boot 侧不再把 outage 记成空库 (#5897)

.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.

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,26 +242,31 @@ 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]))
             .filter((m) => m.startsWith(SKIPPED));
         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);
+    });
 });

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'");