fix(objectql): report a refused write at warn, not error (#17052)

`insert`, `update` and `delete` each end their catch with `throw e` and logged
the failure at ERROR one statement earlier. AGENTS.md → Degradation log levels
names that shape: "a failure handed to the CALLER is not a degradation at all
… Do not bolt a `logger.error` onto such a site."

The diagnosis two earlier rulings shaped survives the move. `warn(message,
meta?)` has no `Error` slot, and `Error.message`/`stack` are non-enumerable, so
handing the error over as meta would have serialised `{}`. The doors instead
build the `{ error: { message, stack } }` bag `ObjectLogger.write()` builds from
the slot, keeping #8682's redaction and #14095's choice of the driver error over
the envelope. The rendered line is byte-identical apart from the level word.

Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_019wtfW1ZxGnP1XKGc9uZVms

Author: claude

.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-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,11 +125,18 @@ 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.
  */
 function stripLineLevels(o: Observed): string[] {
   return o.lines
@@ -201,7 +208,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 +257,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 () => {

packages/objectql/src/engine-update-duplicate-record.test.ts

@@ -194,17 +194,32 @@ function makeDriver(opts: DriverOpts = {}) {
   return driver as IDataDriver & { update: any; updateMany: any };
 }
 
-/** A logger that records what the door's `Update operation failed` line carried. */
+/**
+ * A logger that records what the door's `Update operation failed` line carried.
+ *
+ * [#17052] The line is emitted at `warn` now (the catch rethrows — the caller
+ * was told), so the recorder listens there. `warn` has no `Error` slot, so the
+ * driver's error arrives as `meta.error = { message, stack }`; `err` below is
+ * lifted back out of it, which keeps every assertion in section (7) reading the
+ * same two fields #14095 pinned. `errors` also captures anything still emitted
+ * at `error`, so a regression that puts the line back would be visible rather
+ * than silently unmatched.
+ */
 function recordingLogger() {
-  const errors: Array<{ msg: string; err: unknown; meta: unknown }> = [];
+  const errors: Array<{ msg: string; err: unknown; meta: unknown; level: string }> = [];
+  const record = (level: string) => (msg: string, a?: unknown, b?: unknown) => {
+    const meta = (level === 'warn' ? a : b) as Record<string, any> | undefined;
+    const err = level === 'warn'
+      ? (meta?.error as unknown)
+      : a;
+    errors.push({ msg, err, meta, level });
+  };
   const logger = {
     info: vi.fn(),
     debug: vi.fn(),
-    warn: vi.fn(),
+    warn: vi.fn(record('warn')),
     trace: vi.fn(),
-    error: vi.fn((msg: string, err?: unknown, meta?: unknown) => {
-      errors.push({ msg, err, meta });
-    }),
+    error: vi.fn(record('error')),
   };
   return { logger, errors };
 }
@@ -603,14 +618,19 @@ describe('engine.update — a driver unique violation is a DUPLICATE_RECORD enve
 
       const line = errors.find((e) => e.msg === 'Update operation failed');
       expect(line).toBeDefined();
-      const logged = line!.err as Error;
-      expect(logged).toBeInstanceOf(Error);
+      // [#17052] …at `warn`: the catch rethrows, so the caller was told and
+      // this entry is the operator's copy, not a degradation report.
+      expect(line!.level).toBe('warn');
+      const logged = line!.err as { message: string; stack: string };
       expect(logged.message).toContain('UNIQUE constraint failed: doc.email');
       expect(logged.message).not.toContain('Duplicate record refused');
       // …and the redaction still holds: no statement, no bound value.
       expect(logged.message).not.toMatch(/update `doc` set/i);
       expect(logged.message).not.toContain('a@b.example');
-      expect(line!.meta).toEqual({ object: 'doc' });
+      // The `cause` reached the log with its FRAMES, which is the other half of
+      // what the platform logger serializes.
+      expect(typeof logged.stack).toBe('string');
+      expect(line!.meta).toEqual({ object: 'doc', error: logged });
     });
 
     it('logs the same way on the predicate door', async () => {
@@ -622,8 +642,9 @@ describe('engine.update — a driver unique violation is a DUPLICATE_RECORD enve
 
       const line = errors.find((e) => e.msg === 'Update operation failed');
       expect(line).toBeDefined();
-      expect((line!.err as Error).message).toContain('violates unique constraint');
-      expect((line!.err as Error).message).not.toContain('Duplicate record refused');
+      expect(line!.level).toBe('warn');
+      expect((line!.err as { message: string }).message).toContain('violates unique constraint');
+      expect((line!.err as { message: string }).message).not.toContain('Duplicate record refused');
     });
 
     it('a non-enveloped failure is logged exactly as before — the driver error itself', async () => {
@@ -635,7 +656,14 @@ describe('engine.update — a driver unique violation is a DUPLICATE_RECORD enve
 
       const line = errors.find((e) => e.msg === 'Update operation failed');
       expect(line).toBeDefined();
-      expect(line!.err).toBe(raw);
+      // [#17052] The identity check this used to make (`err === raw`) was a
+      // check on the SLOT, which `warn` does not have. What it was there to
+      // prove — nothing rewrites a failure that is not a duplicate envelope —
+      // is asserted on the two fields the platform logger has ever serialized,
+      // byte for byte against the driver's own error.
+      expect(line!.err).toEqual({ message: raw.message, stack: raw.stack });
+      // …and the caller still receives that very object, unwrapped.
+      expect(line!.level).toBe('warn');
     });
   });
 });