fix(objectql): pick the find failure log level from the cause — "the table is not provisioned yet" is not "the read failed" (#13273)

.changeset/migrate-plan-missing-table-log-level.md

@@ -0,0 +1,58 @@
+---
+"@objectstack/objectql": patch
+---
+
+fix(objectql): stop reporting "the table does not exist yet" as an ERROR with a stack trace (#13273)
+
+`ObjectQL.find` logged every read failure identically: `ERROR Find operation
+failed`, carrying the driver's fault as a stack. That merged two different
+facts — **"this table has not been created yet"** and **"this read failed"** —
+onto one channel, at the level reserved for the second.
+
+Measured on `os migrate plan --database-url file:<an unmigrated database>`,
+which is the ordinary first run and exactly the run the command exists to
+describe: **five** ERROR records with full stack traces, out of a command that
+exits 0 and prints a correct plan. Every one of them is a boot-path probe whose
+caller already treats a missing table as a normal answer and says so in its own
+code — `readMigrationFlagVerified` (`sys_migration`),
+`ObjectStoreActionActivationStore.probe` (`sys_metadata_activation`),
+`readAuthoredTranslationLayer` and `ObjectQLPlugin`'s authored-hook /
+authored-action re-syncs (`sys_metadata`, which report `authoredRows: 0` and
+carry on). An `error` channel that fires on a routine state is what trains
+operators to skim `error`.
+
+**What changed:** the read path now picks the level from the CAUSE. A failure
+that positively identifies as "relation does not exist" — asked through the
+shared `isMissingTableError` predicate (`@objectstack/metadata/errors`), never a
+hand-rolled code test — is logged at `debug` with a
+`reason: 'table-not-provisioned'` meta and no stack. Everything else is
+unchanged: `error`, with the Error and its stack.
+
+**⛔ What did not change**, and is pinned:
+
+- **The throw.** Both branches rethrow the driver's envelope byte-identically,
+  so no caller's control flow, `catch` or error envelope moves. This is a log
+  level and nothing else.
+- **Every genuinely failed read.** A connection drop, a timeout, a permission
+  denial, an unclassified fault — and, through the predicate's `excludes`,
+  Postgres' `column "x" of relation "y" does not exist`, which contains a legal
+  missing-table phrase but is a column fault on a table that exists — all stay
+  loud. Measured end to end on the same command: against a database whose
+  `sys_metadata` exists but lacks the column being filtered on, three ERROR
+  records with stacks remain in the same run in which the two still-absent
+  tables stay quiet; against a file that is not a database at all
+  (`SQLITE_NOTADB`), all five stay loud and the command exits 1.
+- **The driver's own refusal envelope.** `[sql-driver] DATABASE_ERROR — the
+  backend refused a read on '<table>' … no such table: <table>` still goes to
+  `warn` on every one of these reads. It is deliberately the surviving loud
+  half: the class remains visible to an operator, without a duplicate and
+  without a stack.
+- **The write verbs.** `insert` / `update` / `delete` keep their unconditional
+  `error` — a write to a table that does not exist is not a normal answer for
+  any caller, and nothing landed.
+
+User-visible: `os migrate plan` (and any first boot against an unprovisioned
+database) no longer prints these stack traces. Fixtures that captured this frame
+on the `error` channel should read `debug` as well; the shared
+`expected-read-refusal-noise` helper in `@objectstack/runtime`'s test tree
+already does.

packages/objectql/src/engine-file-hydrate-outage.test.ts

@@ -13,12 +13,15 @@
  *
  * ONE CORRECTION to the issue body, measured rather than assumed: the catch is
  * zero-output, but the PATH is not literally silent. The generic read handler
- * one frame up already logs `error: 'Find operation failed' { object:
- * 'sys_file' }` before rethrowing into this catch. That line is untouched here,
- * and `the pre-existing generic line cannot tell the two apart` below pins why
- * it does not satisfy the acceptance: it is byte-identical for the benign and
- * the non-benign failure, and it describes the sub-read only — never the parent
- * object, the fields left un-hydrated, or the consequence.
+ * one frame up already logs `'Find operation failed' { object: 'sys_file' }`
+ * before rethrowing into this catch. That line is untouched here, and the
+ * `the generic line separates the two causes but still cannot name the loss`
+ * block below pins why it does not satisfy the acceptance: it describes the
+ * sub-read only — never the parent object, the fields left un-hydrated, or the
+ * consequence. ⚠️ [#13273] That block was rewritten when the generic frame
+ * stopped being `error` for every cause: it is `debug` for the benign
+ * "table was never provisioned" class now, and `error` for everything else.
+ * The consequence gap this file exists to close is unchanged either way.
  *
  * The pass-through itself is correct and is NOT what this fixes. A file-metadata
  * read that fails must not take down the record read that asked for it, so
@@ -279,16 +282,26 @@ describe('sys_file hydrate read fault — distinguishable from "no file" (#6116)
    * #6116's body says the seam logs nothing. Measured on `origin/main` that is
    * true of the CATCH, but not of the whole path: the generic read handler one
    * frame up (`engine.ts`, `'Find operation failed'`) already reports the
-   * failed `sys_file` sub-read at `error` before rethrowing into this catch.
-   * That line is real and this fix neither removes nor duplicates it.
+   * failed `sys_file` sub-read before rethrowing into this catch. That line is
+   * real and this fix neither removes nor duplicates it.
    *
-   * It cannot be the discriminator the acceptance asks for, for two reasons
-   * pinned below: it is emitted IDENTICALLY for the benign and the non-benign
-   * failure, and it describes the sub-read only — never the parent object,
-   * the fields left un-hydrated, or the consequence that those bare ids will
-   * read downstream as "this record has no file".
+   * ⚠️ [#13273] What HAS moved since #6116, and why this block was rewritten
+   * rather than deleted. That generic frame used to be `error` for every cause
+   * — which is what made it useless as a discriminator, and is the sentence
+   * this block used to pin. `engine.ts` now asks `isMissingTableError` and puts
+   * the benign class on `debug`, so the two causes no longer produce the same
+   * line. The re-pinned facts below are therefore:
+   *
+   *   1. the generic frame DOES now separate the two causes by channel — the
+   *      benign read leaves the `error` channel empty (#13273's own acceptance,
+   *      re-measured from this file's fake driver);
+   *   2. and it STILL does not satisfy #6116's acceptance, because on the
+   *      outage branch it describes the sub-read only — never the parent
+   *      object, the fields left un-hydrated, or the consequence that those
+   *      bare ids will read downstream as "this record has no file". That gap
+   *      is what the seam's own `warn` closes, and it is unchanged.
    */
-  describe('the pre-existing generic line cannot tell the two apart', () => {
+  describe('the generic line separates the two causes but still cannot name the loss', () => {
     async function errorCensus(make: () => unknown) {
       await boot(async () => {
         throw make();
@@ -297,17 +310,45 @@ describe('sys_file hydrate read fault — distinguishable from "no file" (#6116)
       return logger.lines.error.map((l: any) => l.msg);
     }
 
-    it('reports the same `error` for a benign and a non-benign failure', async () => {
+    /**
+     * The `debug` channel carries the engine's ordinary read tracing too, so
+     * this census is narrowed to the one frame under test. ⛔ Narrowed by an
+     * EXACT message match, not a substring: a filter that also admitted
+     * `'Find operation starting'` would report a frame this block did not
+     * measure.
+     */
+    async function debugCensus(make: () => unknown) {
+      await boot(async () => {
+        throw make();
+      });
+      await engine.find('doc');
+      return logger.lines.debug.filter((l: any) => l.msg === 'Find operation failed');
+    }
+
+    it('[#13273] the benign cause no longer reaches `error` — it reaches `debug`', async () => {
       const benign = await errorCensus(() => new Error('no such table: sys_file'));
       const outage = await errorCensus(() =>
         Object.assign(new Error('connect ECONNREFUSED 127.0.0.1:5432'), { code: 'ECONNREFUSED' }));
 
-      // Identical — so an operator reading only this line learns that a read
-      // failed, never whether the answer they received can be trusted.
-      expect(benign).toEqual(['Find operation failed']);
+      // "The table was never provisioned" is a routine state, not a failure to
+      // report — and every caller on that path treats it as a normal answer.
+      expect(benign).toEqual([]);
+      // ⭐ The positive control on that zero: the SAME read, one cause over,
+      // still reaches `error`. So the empty census above measures the
+      // classification and not a broken fixture.
       expect(outage).toEqual(['Find operation failed']);
     });
 
+    it('[#13273] the benign frame is still recorded, one channel down', async () => {
+      // ⛔ Demoted, not muted: the frame is still emitted, still names the
+      // object, and now carries its own classification instead of a stack.
+      const benign = await debugCensus(() => new Error('no such table: sys_file'));
+      expect(benign.map((l: any) => l.msg)).toEqual(['Find operation failed']);
+
+      const [meta] = benign[0].args;
+      expect(meta).toMatchObject({ object: 'sys_file', reason: 'table-not-provisioned' });
+    });
+
     it('names only the sub-read, not the degradation it caused', async () => {
       await boot(async () => {
         throw Object.assign(new Error('connect ECONNREFUSED 127.0.0.1:5432'), { code: 'ECONNREFUSED' });