fix(objectql): report a refused write at warn, not error — the caller was already told

.changeset/engine-write-failure-log-level-warn.md

@@ -0,0 +1,37 @@
+---
+"@objectstack/objectql": patch
+---
+
+fix(objectql): a refused write reports at `warn`, not `error` — the caller was already told (#17052)
+
+`insert`, `update` and `delete` each end their `catch` with `throw e`, then
+logged the failure at ERROR one statement earlier. AGENTS.md → *Degradation log
+levels* names that exact shape and forbids it: "a failure handed to the CALLER
+is not a degradation at all … Do not bolt a `logger.error` onto such a site."
+
+**This moves published behaviour**, which is why it is a changeset rather than a
+`skip-changeset`: the level is what an operator greps, and at least one consumer
+reads it structurally. `scripts/publish-smoke.sh` fails a boot on any
+error-level line (`SMOKE_ERROR_LOG_PATTERN`), and that is how the defect was
+found — `@better-auth/oauth-provider` seeds `sys_oauth_resource` in `insertOnly`
+mode and documents its `identifier` UNIQUE constraint AS its race-safety
+mechanism, catching the collision and continuing at `debug`. Our line was
+emitted before that catch ever ran, so a healthy first boot of every fresh
+`create-objectstack` project printed `ERROR Insert operation failed` and red-lit
+`publish-smoke / packed-tarballs` for six consecutive runs on a candidate whose
+auth and CRUD probes were all green.
+
+**Nothing else about the entry moved.** Same message, same `object` meta, same
+redaction (#8682: the bound statement and its values stay cut from `message`
+and `stack`), same subject (#14095: the entry carries the driver's own error —
+a `DuplicateRecordError`'s `cause` — never the envelope, so the failing column,
+MySQL's index name and the driver's frames survive). The `Logger` contract gives
+an `Error` slot to `error`/`fatal` only, so the engine now builds the
+`{ error: { message, stack } }` bag that slot used to build; handing the Error
+to `warn` as meta would have serialised `{}`, because those two fields are
+non-enumerable. The rendered line is byte-identical apart from the level word,
+and that equivalence is pinned rather than asserted.
+
+If you grep your logs for these three messages, keep the message and drop the
+level from the pattern. If you alert on error-level lines from `@objectstack/objectql`,
+a refused write no longer raises one — the write's exception still does.

packages/objectql/src/driver-fault-redaction.test.ts

@@ -751,7 +751,9 @@ describe('#8682 half B — the write-path loggers', () => {
       lines,
       trace() {}, fatal() {},
       debug() {}, info() {},
-      warn(msg: string) { lines.push({ level: 'warn', msg: String(msg) }); },
+      // [#17052] `warn` grew a meta capture: the write doors report there now,
+      // and the redaction this suite pins travels in `meta.error`.
+      warn(msg: string, meta?: any) { lines.push({ level: 'warn', msg: String(msg), meta }); },
       error(msg: string, err?: any, meta?: any) { lines.push({ level: 'error', msg: String(msg), err, meta }); },
       child() { return logger; },
     };
@@ -814,28 +816,37 @@ describe('#8682 half B — the write-path loggers', () => {
       } as any);
     } catch (e) { thrown = e; }
     const line = logger.lines.find((l: any) => l.msg === 'Insert operation failed');
-    return { line, thrown };
+    return { line, thrown, logger };
   }
 
-  it('the entry survives — same level, same message, same object', async () => {
-    const { line } = await insertAgainstADriftedColumn();
+  it('the entry survives — one line, `warn` since #17052, same message, same object', async () => {
+    const { line, logger } = await insertAgainstADriftedColumn();
 
     expect(line).toBeDefined();
-    expect(line!.level).toBe('error');
-    expect(line!.meta).toEqual({ object: 'crm_account' });
+    // [#17052] Was `error` until the door was read against AGENTS.md's third
+    // legal answer: this catch rethrows, so the caller was told. What this
+    // suite pins is the REDACTION, and it is unchanged by the level — the
+    // assertions below read the same two fields they always did.
+    expect(line!.level).toBe('warn');
+    expect(line!.meta).toEqual({
+      object: 'crm_account',
+      error: { message: expect.any(String), stack: expect.any(String) },
+    });
+    // …and the entry did not merely move: nothing is emitted at `error` now.
+    expect(logger.lines.filter((l: any) => l.level === 'error')).toHaveLength(0);
   });
 
   it('the failing column is still named — the fault stays debuggable', async () => {
     const { line } = await insertAgainstADriftedColumn();
 
-    expect(String(line!.err?.message)).toContain('has no column named secret_note');
-    expect(String(line!.err?.stack)).toContain('at Database.prepare');
+    expect(String(line!.meta?.error?.message)).toContain('has no column named secret_note');
+    expect(String(line!.meta?.error?.stack)).toContain('at Database.prepare');
   });
 
   it('neither `message` nor `stack` carries a caller value', async () => {
     const { line } = await insertAgainstADriftedColumn();
 
-    for (const field of [String(line!.err?.message), String(line!.err?.stack)]) {
+    for (const field of [String(line!.meta?.error?.message), String(line!.meta?.error?.stack)]) {
       expect(field).not.toContain(SECRET);
       expect(field).not.toContain(DESCRIPTION);
       expect(field).not.toContain('insert into');
@@ -872,17 +883,22 @@ describe('#8682 half B — the write-path loggers', () => {
     const { line } = await insertAgainstADriftedColumn(MYSQL_DUPLICATE_ENTRY);
 
     expect(line).toBeDefined();
-    expect(line!.level).toBe('error');
-    expect(line!.meta).toEqual({ object: 'crm_account' });
+    // [#17052] The level moved to `warn`; #14095's property is what this case
+    // exists for, and it is asserted below on the same two fields. They travel
+    // in `meta.error` now because `warn` has no `Error` slot — the engine
+    // rebuilds the very `{ message, stack }` bag the slot used to build, so
+    // the index name still arrives.
+    expect(line!.level).toBe('warn');
+    expect(line!.meta?.object).toBe('crm_account');
     // The operator's answer to "which constraint?" is kept whole.
-    expect(String(line!.err?.message)).toContain("for key 'crm_account.secret_note'");
-    expect(String(line!.err?.stack)).toContain('at Database.prepare');
+    expect(String(line!.meta?.error?.message)).toContain("for key 'crm_account.secret_note'");
+    expect(String(line!.meta?.error?.stack)).toContain('at Database.prepare');
   });
 
   it('MySQL duplicate entry — neither `message` nor `stack` carries the value', async () => {
     const { line } = await insertAgainstADriftedColumn(MYSQL_DUPLICATE_ENTRY);
 
-    for (const field of [String(line!.err?.message), String(line!.err?.stack)]) {
+    for (const field of [String(line!.meta?.error?.message), String(line!.meta?.error?.stack)]) {
       expect(field).not.toContain(SECRET);
       expect(field).not.toContain(DESCRIPTION);
       expect(field).not.toContain('insert into');

packages/objectql/src/driver-fault-redaction.ts

@@ -14,7 +14,7 @@
  * to disk at ERROR level, twice:
  *
  * ```
- * ERROR Insert operation failed {"object":"crm_account","error":{"message":
+ * WARN Insert operation failed {"object":"crm_account","error":{"message":
  *   "insert into `crm_account` (`account_number`, …, `zzz_nonexistent_field`)
  *    values ('ACC-000011', …, 'SENSITIVE-CANARY-9f3a2b') returning *
  *    - table crm_account has no column named zzz_nonexistent_field", "stack":
@@ -32,10 +32,17 @@
  * column and the condition (`table crm_account has no column named
  * zzz_nonexistent_field`, `NOT NULL constraint failed: sys_team.name`). It is
  * kept, and the log site keeps the `object` it already carried. ⛔ The
- * remedy for this exposure is NOT to lower the level or drop the entry: a
- * driver-level fault that logs nothing is a fault nobody can debug, which is
- * strictly worse than one logged too loudly. This narrows WHAT is written; the
- * level, the message and the entry are untouched.
+ * remedy for this exposure is NOT to drop the entry: a driver-level fault that
+ * logs nothing is a fault nobody can debug, which is strictly worse than one
+ * logged too loudly. This narrows WHAT is written; the message and the entry
+ * are untouched.
+ *
+ * [#17052] The LEVEL has since moved to `warn` on the three write doors — not
+ * as a remedy for THIS exposure, which it would not have fixed, but because
+ * those catches rethrow and AGENTS.md rules a failure handed to the caller is
+ * not a degradation report. The specimen above therefore reads `WARN` today.
+ * Nothing else about it moved: the same redacted `message`/`stack` reach the
+ * same `error` key of the same meta bag (`ObjectQL.writeFailureLogMeta`).
  *
  * ## [#8823] …but "the tail names identifiers" is not true of every dialect
  *

packages/objectql/src/engine-delete-restricted-locale.test.ts

@@ -220,14 +220,28 @@ describe('#7307 DELETE_RESTRICTED — user copy vs developer guidance', () => {
         });
 
         it('reaches the SERVER LOG, so a zh-CN deployment does not log its operator half in Chinese', async () => {
+            // [#17052] The delete door reports at `warn` now — its catch ends in
+            // `throw e`, so the caller was told and the entry is not a
+            // degradation report. What #7307 holds is unchanged and is what is
+            // asserted below: the operator half reaches the server log, in
+            // English, in the entry's meta. Only the channel moved, and with it
+            // the meta's ARGUMENT POSITION — `warn(message, meta)` has no
+            // `Error` slot in front of it, so meta is the second argument.
+            // Both levels are captured, so this stays a statement about the log
+            // rather than about one method: if the entry ever moves again, or
+            // is emitted twice, this still sees it.
             const logged: Array<Record<string, unknown>> = [];
-            const original = (engine as any).logger.error.bind((engine as any).logger);
-            (engine as any).logger.error = (msg: string, err: unknown, meta: Record<string, unknown>) => {
-                logged.push(meta ?? {});
-                return original(msg, err, meta);
+            const capture = (level: 'warn' | 'error') => {
+                const original = (engine as any).logger[level].bind((engine as any).logger);
+                (engine as any).logger[level] = (...args: unknown[]) => {
+                    logged.push((level === 'warn' ? args[1] : args[2]) as Record<string, unknown> ?? {});
+                    return original(...args);
+                };
             };
+            capture('warn');
+            capture('error');
             await refuseDelete(engine, 'zh-CN');
-            expect(logged.some((m) => typeof m.developerMessage === 'string'
+            expect(logged.some((m) => typeof m?.developerMessage === 'string'
                 && (m.developerMessage as string).includes("deleteBehavior:'cascade'"))).toBe(true);
         });
     });

packages/objectql/src/engine-find-missing-table-log-level.test.ts

@@ -323,18 +323,26 @@ describe('engine `find` failure log level is chosen by CAUSE (#13273)', () => {
       );
     });
 
-    it('a WRITE to a table that does not exist is still `error`', async () => {
-      // Nothing landed, and the row the caller believes it stored is gone —
-      // never a normal answer, whatever the cause.
+    it('a WRITE to a table that does not exist reports ONCE, and not at `debug`', async () => {
+      // [#17052] This case is unchanged in the two things it was written to
+      // hold — the write door reports, and it does not join the read door's
+      // `debug` demotion — and changed in the one it also happened to state:
+      // the level is `warn`, because the write catch rethrows and the caller
+      // was told. The demotion this suite governs is still READS ONLY: a
+      // missing table earns no quieter treatment on a write than any other
+      // driver fault does, and `warn` is what every write fault takes now.
       await boot(() => envelope(new Error(`no such table: ${OBJECT}`)));
 
       await expect(engine.insert(OBJECT, { label: 'x' } as any)).rejects.toThrow();
 
-      const insertFrames = logger.lines.error.filter(
+      const insertFrames = logger.lines.warn.filter(
         (l: any) => l.msg === 'Insert operation failed',
       );
       expect(insertFrames).toHaveLength(1);
       expect(logger.lines.debug.filter((l: any) => l.msg === 'Insert operation failed')).toHaveLength(0);
+      // ⭐ The read door's classification did NOT leak onto the write door:
+      // there is no second, quieter entry and no `error` entry either.
+      expect(logger.lines.error.filter((l: any) => l.msg === 'Insert operation failed')).toHaveLength(0);
     });
   });
 });

packages/objectql/src/engine-strict-readonly-warning-truthful.test.ts

@@ -125,16 +125,24 @@ interface Observed {
 
 /**
  * The level of the STRIP's own line, isolated from the engine's pre-existing
- * `'Update operation failed'` / `'Insert operation failed'` ERROR — which a
+ * `'Update operation failed'` / `'Insert operation failed'` entry — which a
  * strict refusal legitimately emits, because the caller really was handed a
  * failure. The two lines are different facts and this suite must not conflate
  * them: the strip's line stays at `warn` (its docblock argues that level), and
- * the operation-level error is nobody's business here.
+ * the operation-level entry is nobody's business here.
+ *
+ * [#17052] That operation-level entry moved from `error` to `warn`, which makes
+ * the isolation this helper performs load-bearing rather than merely tidy: the
+ * two lines now share a level, so only the MESSAGE tells them apart. The filter
+ * was already keyed on the message, so it needed no change — but the two
+ * assertions below that named `error` did, and they now assert the level the
+ * door actually takes rather than the one it used to.
  */
+const isOperationFailedLine = (msg: string): boolean =>
+  /^(Update|Insert) operation failed$/.test(msg);
+
 function stripLineLevels(o: Observed): string[] {
-  return o.lines
-    .filter((l) => !/^(Update|Insert) operation failed$/.test(l.msg))
-    .map((l) => l.level);
+  return o.lines.filter((l) => !isOperationFailedLine(l.msg)).map((l) => l.level);
 }
 
 async function observeUpdate(data: unknown, options: Record<string, unknown>): Promise<Observed> {
@@ -148,7 +156,14 @@ async function observeUpdate(data: unknown, options: Record<string, unknown>): P
   return {
     refusedCode,
     driverWrites: writes.length,
-    warns: logger.lines.filter((l: any) => l.level === 'warn').map((l: any) => l.msg),
+    // [#17052] The operation-level entry is at `warn` now too, so the message
+    // isolation this suite has always performed has to hold HERE as well —
+    // `warns` is the accessor every strip assertion counts, and a second warn
+    // line that is not the strip's would make every `toHaveLength(1)` a
+    // statement about the engine's door instead of about the strip.
+    warns: logger.lines
+      .filter((l: any) => l.level === 'warn' && !isOperationFailedLine(l.msg))
+      .map((l: any) => l.msg),
     lines: logger.lines.filter((l: any) => l.level !== 'debug' && l.level !== 'info'),
   };
 }
@@ -164,7 +179,9 @@ async function observeInsert(data: unknown, options: Record<string, unknown> = {
   return {
     refusedCode,
     driverWrites: writes.filter((w) => w.fn === 'create').length,
-    warns: logger.lines.filter((l: any) => l.level === 'warn').map((l: any) => l.msg),
+    warns: logger.lines
+      .filter((l: any) => l.level === 'warn' && !isOperationFailedLine(l.msg))
+      .map((l: any) => l.msg),
     lines: logger.lines.filter((l: any) => l.level !== 'debug' && l.level !== 'info'),
   };
 }
@@ -201,7 +218,9 @@ describe('#8214 — a strict refusal is not reported as a commit (UPDATE)', () =
     expect(stripLineLevels(o)).toEqual(['warn']); // the level its docblock argues
     // …and the refusal itself is reported separately, at `error`, by the
     // engine — two lines, two facts, neither pretending to be the other.
-    expect(o.lines.some((l) => l.level === 'error' && l.msg === 'Update operation failed')).toBe(true);
+    expect(o.lines.some((l) => l.level === 'warn' && l.msg === 'Update operation failed')).toBe(true);
+    // …and it is no longer ALSO at `error` — the move is a move, not a copy.
+    expect(o.lines.some((l) => l.level === 'error')).toBe(false);
     expect(o.warns[0]).toContain("Field 'locked_note'");  // the field, named
     expect(o.warns[0]).toContain('{ context: { isSystem: true } }'); // a remedy
   });
@@ -248,7 +267,8 @@ describe('#8214 — the INSERT side carries the identical defect (the card marke
       }),
     );
     expect(stripLineLevels(o)).toEqual(['warn']);
-    expect(o.lines.some((l) => l.level === 'error' && l.msg === 'Insert operation failed')).toBe(true);
+    expect(o.lines.some((l) => l.level === 'warn' && l.msg === 'Insert operation failed')).toBe(true);
+    expect(o.lines.some((l) => l.level === 'error')).toBe(false);
   });
 
   it('the DEFAULT insert strip still says COMMITTED WITHOUT IT — and the row really does commit', async () => {