objectql: engine.insert logs `Insert operation failed` at ERROR inside a catch that rethrows — the case AGENTS.md names as "not a degradation at all"

[os-bill]

packages/objectql/src/engine.ts logs a failure it is about to hand back to its caller, at ERROR. AGENTS.md names that exact case and forbids it.

⛔ Filed by the seat that hit it while repairing the publish-smoke boot gate (see the acceptance notes on PR #17051). It is out of that card's file surface and it reverses nothing recorded, so it is a card rather than a rider. domain:* and priority:* are triage's to set — deliberately not set here.

The site

insert's catch, packages/objectql/src/engine.ts (the line that emits Insert operation failed):

const logged = e instanceof DuplicateRecordError ? e.cause : e;
this.logger.error('Insert operation failed', redactBoundStatement(logged) as Error, { object });
throw e;

The rethrow is the next statement. Update operation failed in the sibling verb has the same shape, and packages/objectql/src/engine-strict-readonly-warning-truthful.test.ts pins the level (l.level === 'error'), so the class is at least two sites and is pinned.

The contract it violates

AGENTS.md, Degradation log levels — warn vs error, verbatim:

And a failure handed to the CALLER is not a degradation at all — the third legal answer: a catch that answers errorFromThrown(e, 400), or a batch whose contract IS a per-item outcome report, does not look normal from the outside — the requester was told. Do not bolt a logger.error onto such a site; declare how it delivers instead — FAILURE_PROPAGATION_CALLEES (repo-wide names) or the function-scoped FAILURE_PROPAGATION_SITES in the checker, which then proves structurally that every path out of the catch delivers.

The requester was told: e is rethrown one line down, and since #14095 the door hands the caller a DuplicateRecordError envelope. pnpm check:durability-log-level does not catch it because its log-level rule fires on a catch that logs below error without rethrowing — the opposite direction.

What it cost, measured

A caller that catches the exception makes the ERROR line a false alarm that nothing downstream can distinguish from a real one.

@better-auth/oauth-provider@1.7.2 seeds sys_oauth_resource in insertOnly mode and documents the identifier UNIQUE constraint as its race-safety mechanism — "one wins, the other catches the constraint error and treats it as a no-op" (dist/introspect-C6P1zrTr.mjs, the docblock over seedResources, read from the installed tarball). Its catch tests the message for unique|duplicate|UNIQUE, logs the collision at debug, and continues. Our line is emitted before that catch ever runs, so a completely healthy first boot of every fresh create-objectstack project prints:

ISO_TIMESTAMP ERROR Insert operation failed {"object":"sys_oauth_resource","error":{"message":
  "UNIQUE constraint failed: sys_oauth_resource.identifier [statement and bound values redacted]", ...}}

That line is what red-lit publish-smoke / packed-tarballs on main for six consecutive runs and blocked a release (#17027) — on a candidate whose auth and CRUD probes were, once allowed to run, all green. The gate has been repaired to judge the boot by predicate rather than by level (PR #17051), so this card is no longer release-blocking; the misleading line is still emitted on every fresh boot.

What this card does NOT decide

⛔ It does not prescribe the level, because the diagnosis the line carries is load-bearing and was deliberately shaped twice:

• Undeclared fields still reach the driver: beforeInsert hooks run and an auto-number is consumed before the request is refused, and the whole INSERT with its values is logged at ERROR (17.0.0 GA) #8682 cut the inlined statement and its bound values from both message and stack, keeping what the database itself said;
• An application told to rely on a unique index cannot recognise the violation: ObjectQL rethrows the raw driver error and isUniqueViolationError is not reachable from an app #14095 kept the log on the cause rather than the envelope, because the platform logger serialises only message and stack, so logging the envelope would drop the failing column, MySQL's index name and the driver's own frames.

Neither decided the level. The three shapes worth weighing:

1. Declare the propagation — add the site to FAILURE_PROPAGATION_SITES / FAILURE_PROPAGATION_CALLEES and drop the level to warn or debug, which is what the contract text prescribes. The diagnosis survives at a level a healthy run may legitimately emit.
2. Keep ERROR and narrow it — log at ERROR only where the caller cannot be told, e.g. only when the throw is swallowed upstream. Needs a way to know that, which the site does not have today.
3. Keep ERROR as-is and record the decision in an ADR, so the next seat that reads AGENTS.md's rule against this exact shape finds the exemption instead of re-filing this card.

Not measured here

• ⛔ How many other rethrowing catches in packages/objectql log at ERROR. Only insert and update were established; the class was not swept.
• ⛔ Whether any consumer greps for the ERROR level of these two lines. The pinned test asserts the level, but no downstream reader was surveyed.

---

Generated by Claude Code

[os-bill]

Claim: PM loop, maintainer direct dispatch
Session: session_019wtfW1ZxGnP1XKGc9uZVms
Branch: claude/issue-17052-insert-failure-log-level
Worktree: objectstack-issue-17052
Domain: domain:engine (packages/objectql, per the anchoring table)
File surface: packages/objectql/src/engine.ts (the insert and update catches), the failure-propagation declaration the checker reads, and engine-strict-readonly-warning-truthful.test.ts which pins the level — stop on breach
Container & model: M, mode:subagent, model: opus
Clause-②: no — this narrows what the platform claims at ERROR; no accept set widens and no public surface grows. ⚠️ Re-declare from the delivered diff: if the repair ends up adding a name to a repo-wide list (FAILURE_PROPAGATION_CALLEES), say so — a repo-wide list entry is worth naming even though it is still not a widening.
Thread-read: none (no comments on the card)
Serial constraints cleared: ⚠️ NOT measured against open PRs this round — the maintainer is near a usage wall and asked to sequence, so this is recorded as unmeasured rather than claimed clean. ⛔ packages/objectql/src/engine.ts is a hot file; the dev merges origin/main immediately before opening the PR.

Maintainer ruling — sequencing

Verbatim, this PM session's chat, 2026-09-09T08:0xZ (⛔ 照抄不译): 「让 #17052 落地,再放 #17051」

⇒ Option C of the three put on #17027. This card now leads; PR #17051 stays a parked draft until it lands. publish-smoke / packed-tarballs stays red on main in the meantime — accepted cost of the ordering, and the reason this card is now on the critical path rather than a follow-up.

Seat ruling on the level — premised, and falsifiable

The card deliberately declines to pick among its three shapes. This seat directs shape 1 — declare the propagation and drop the level — and the authority is not seat judgement, it is the governing text this card already quotes:

Do not bolt a logger.error onto such a site; declare how it delivers instead — FAILURE_PROPAGATION_CALLEES … or the function-scoped FAILURE_PROPAGATION_SITES in the checker, which then proves structurally that every path out of the catch delivers.

AGENTS.md names the mechanism by name for exactly this shape. Under 「协议为基准:spec 与代码不一致默认改代码对齐」 the default is to move the code onto the contract; shape 3 (keep ERROR, write an ADR exemption) is changing the contract and would be a maintainer decision, not this seat's. Shape 2 needs knowledge the site does not have. So this is 恢复不变量的修复 — a named non-escalation class — not a design pick.

⛔ The ruling is hung on a premise the dev must verify FIRST: that the propagation checker can structurally prove every path out of these catches delivers. If it cannot — if some path exits without telling the caller — stop and report the fork. ⛔ Do not silently fall back to shape 3, and ⛔ do not weaken the checker to make shape 1 fit.

⚠️ Two things this card marks NOT MEASURED are part of the work: sweep packages/objectql for other rethrowing catches logging at ERROR (only insert/update were established), and check whether any consumer depends on the ERROR level of these two lines before moving it.

---

Generated by Claude Code

[os-bill]

os-dev-report

{
  "issue": 17052,
  "status": "done",
  "branch": "claude/issue-17052-insert-failure-log-level",
  "pr": "https://github.com/objectstack-ai/objectstack/pull/17211",
  "premise_still_valid": true,
  "premise_evidence": {
    "zone2_question": "Can the propagation checker structurally prove EVERY path out of these catches delivers to the caller?",
    "answer": "YES for the substance, NO for the named mechanism. The stop condition ('some path exits without telling the caller') did NOT occur, so shape 1 landed.",
    "every_path_delivers": "Each catch body's only exit is the unconditional `throw e` — no branch, no early return, no loop. The checker's own model agrees: catchDeliversFailure()/analyzeStmt returns {delivered:true, terminates:true} for a ThrowStatement, commented 'A rethrow IS delivery — the loudest kind.'",
    "mechanism_unavailable_measured": "Adding `packages/objectql/src/engine.ts::insert` to FAILURE_PROPAGATION_SITES makes `pnpm check:durability-log-level` exit 1: '1 stale entr(ies) in FAILURE_PROPAGATION_SITES — the declaration excuses nothing, so delete it'. Probe mutation proven on disk (marker count 1), restore verified by git hash-object against the HEAD blob (87a4b617834257a4cc9a84068d44d23299f0801f == 87a4b617834257a4cc9a84068d44d23299f0801f).",
    "why_it_cannot_attach": [
      "analyzeSourceFile step 1 (collectGuardedCalls) returns empty: the raw ObjectQL verbs are deliberately absent from DURABILITY_CRITICAL_CALLEES (#12981, the checker's own header). Confirmed by --list: of the log-level rule's 29 seams the only engine.ts entry is syncSchema()@14484.",
      "Even as a seam it would not attach: catchDeliversFailure() requires `evidence` (a declared propagation CALL). A bare `throw e` leaves evidence undefined, so the site is excused by the rethrow limb (propagatesAlways), never by a declaration."
    ],
    "checker_weakened": false,
    "shape_3_used": false
  },
  "summary": "Dropped the level of `Insert operation failed`, `Update operation failed` and `Delete operation failed` from `error` to `warn` in packages/objectql/src/engine.ts — each catch's next statement is `throw e`, which is AGENTS.md's third legal answer. The `Logger` contract gives an `Error` slot to error/fatal only, and Error.message/stack are non-enumerable, so a naive level change would have serialised `{}` and destroyed the diagnosis #8682 and #14095 preserved; a module-local `writeFailureLogMeta()` instead rebuilds the `{...meta, error:{message,stack}}` bag `ObjectLogger.write()` builds from the slot. Measured against the real platform logger: the rendered line is byte-identical apart from the level word. Four level pins moved (not deleted); three gained an assertion that nothing is emitted at `error` any more. Verified on the delivered tree: the full objectql suite is 4865/4865 green and typecheck is OK; running the whole package rather than the message-matched files is what caught a fifth level-dependent consumer that no grep of the three messages could reach.",
  "tests": {
    "package_suite": "pnpm --filter @objectstack/objectql test — 289/289 files, 4865/4865 tests PASSING (exit 0). Run under the shared lock; VERDICT command-exit 0, held 209s.",
    "typecheck": "pnpm --filter @objectstack/objectql typecheck — OK (exit 0). check:test-typecheck confirms the TEST LAYER compiles, so the assertions moved here are inside the checked program, not excluded from it.",
    "build": "pnpm --filter '@objectstack/objectql...' build — exit 0 (required first: with no dist/, all five targeted files failed to RESOLVE @objectstack/core and reported 'no tests', which is NOT MEASURED rather than red).",
    "logger_equivalence": "npx tsx against packages/core/src/logger.ts with the real createLogger({level:'info',format:'pretty'}) — BEFORE (logger.error(msg, Error, {object})) vs AFTER (logger.warn(msg, {object, error:{message,stack}})): REMAINDER IDENTICAL with the level word stripped = true. NEGATIVE CONTROL, the naive move: handing the Error to warn as meta renders '\"error\":{}', spreading it flat drops it entirely (diagnosis present = false). EXIT=0.",
    "premise_probe": "see premise_evidence.mechanism_unavailable_measured — gate exit 1 under the injected entry; mutation proven on disk, restore byte-verified against the HEAD blob.",
    "what_the_full_run_caught": "Running the WHOLE package rather than only the message-matched files turned up 3 failures the targeted set could not: one real consumer (engine-delete-restricted-locale.test.ts, invisible to a message grep — see consumers_surveyed.method_correction) and two defects in my own new rig (the delete door driven with an unrecognised `id` option, so the engine refused before the driver and the door logged nothing; and the strict-readonly suite's `warns` accessor counting the door's entry). All three fixed in 998d98779; the suite is green on the delivered tree."
  },
  "gates": {
    "derivation": "node scripts/pm/dispatch-gates.mjs --commands --repo objectstack-ai/objectstack (re-derived after the changeset landed and again after the origin/main merge — identical list both times)",
    "reconciliation": "dispatch-gates --ran: 62 derived famil(ies) accounted for — 62 run, 0 NOT-MEASURED",
    "total": 62,
    "green": 60,
    "red": 0,
    "not_measured_exit3": [
      "pnpm check:dual-build-cjs-loads — needs a WHOLE-TREE build (47 further packages unbuilt)",
      "pnpm check:type-check-debt — its --re-measure half needs 17 further dependency closures built; the gate refuses to measure a different world rather than record a wrong number"
    ],
    "recovered_after_the_build": "check:dts-closure (78/78 declaration files across 15 built packages), check:lean-entry-closure, check:sourcemap-no-sources-content — all three exit 3 before the build and GREEN after it",
    "durability_log_level": "GREEN on the delivered tree — '29 durability-critical catch seam(s), all loud, rethrowing or propagating to the caller (4 propagating, declared)', plus 63 log-level and 57 read-seam self-test cases. Its rule was never the one firing here: it fires on a catch logging BELOW error WITHOUT rethrowing, the opposite direction, exactly as the card measured.",
    "exit_codes": "captured to disk before any pipe (scratchpad/issue-17052/g/NNN.log + summary.tsv); verdict lines read from the gates' own output, never a bare $?"
  },
  "files_changed": [
    "packages/objectql/src/engine.ts (+94/-10) — 3 log sites moved to warn; module-local writeFailureLogMeta(); reportFindFailure's docblock sentence about the write verbs corrected",
    "packages/objectql/src/driver-fault-redaction.ts (+12/-5) — #8682 docblock: specimen line now reads WARN; the ⛔ 'not to lower the level' sentence narrowed to what it was actually about (not dropping the entry)",
    "packages/objectql/src/engine-write-failure-log-level.test.ts (+199) — NEW, the card's regression pin",
    "packages/objectql/src/driver-fault-redaction.test.ts (+30/-14) — level pin moved; reads meta.error",
    "packages/objectql/src/engine-update-duplicate-record.test.ts (+40/-12) — #14095's suite; recorder moved to warn",
    "packages/objectql/src/engine-strict-readonly-warning-truthful.test.ts (+14/-4) — the pin the dispatch named",
    "packages/objectql/src/engine-find-missing-table-log-level.test.ts (+12/-4) — write-verb pin; its not-at-debug assertion is untouched and still passes",
    ".changeset/engine-write-failure-log-level-warn.md (+37) — @objectstack/objectql patch"
  ],
  "sweep": {
    "scan_root": "packages/objectql/src — 145 files carrying a `catch`",
    "matcher": "AST; follows same-file helper calls one frame (the visibility collectLoggedLevels() has) and requires the ERROR log to be on the SAME path as the rethrow",
    "other_rethrowing_error_sites": 4,
    "sites": [
      "engine.ts:11010 Insert operation failed (established by the card)",
      "engine.ts:12382 Update operation failed (established by the card)",
      "engine.ts:13832 Delete operation failed (NOT previously established)",
      "engine.ts:9710 Find operation failed, via reportFindFailure one frame down (NOT previously established)"
    ],
    "positive_control": "the matcher finds `Insert operation failed` at engine.ts:11010 and `Update operation failed` at engine.ts:12382 — the two sites the card had already established, by name",
    "negative_control": "hook-wrappers.ts:418 is a real ERROR-and-rethrow in one catch and is DISCRIMINATED OUT — it logs at error only on the onError:'log' branch that suppresses and returns, and logs nothing on its rethrow branch. So the path limb is exercised, not vacuous, and that site is correct as it stands.",
    "repaired": "3 of 4 — insert, update, delete. Scoped out: find (filed as #17212).",
    "scope_note": "find's level was set by a separate recent ruling (the missing-table demotion) whose docblock weighs the driver's own surviving warn against a second line — a read-path noise budget the write doors do not have. Overturning it is a decision, not a repair.",
    "not_swept": "outside packages/objectql — the dispatch scoped the sweep to that package; the matcher is general and the scan root is a one-line change"
  },
  "consumers_surveyed": {
    "method": "git grep of all three messages repo-wide, then each hit read rather than pattern-matched — 29 hits across 18 files",
    "depend_on_the_level": 5,
    "level_dependent_sites": [
      "scripts/publish-smoke.sh — SMOKE_ERROR_LOG_PATTERN fails a boot on any error-level line. This is the consumer that made the card a release problem, and its own header rules the direction: '⛔ The severity is NOT the predicate. Widening the error scan to WARN is the obvious repair and it is the wrong one: warn is where this repo deliberately puts functional degradation … so a healthy boot HAS warn lines.' No gate change owed.",
      "packages/objectql/src/engine-strict-readonly-warning-truthful.test.ts — moved",
      "packages/objectql/src/engine-find-missing-table-log-level.test.ts — moved",
      "packages/objectql/src/driver-fault-redaction.test.ts — moved",
      "packages/objectql/src/engine-update-duplicate-record.test.ts — moved",
      "packages/objectql/src/engine-delete-restricted-locale.test.ts — #7307's server-log pin, found by the suite and not by the grep; moved"
    ],
    "positive_control": "engine-strict-readonly-warning-truthful.test.ts:204 (`l.level === 'error' && l.msg === 'Update operation failed'`) — the pin the dispatch named; the survey finds it",
    "do_not_depend_on_the_level": "7 runtime prose references (plugin-security x4: bootstrap-system-capabilities, per-organization-catalog x2, permission-set-drift, permission-set-overlay-discard; cli/src/utils/schema-migration-plugins.ts; plus 2 test comments) all point operators at 'the query engine's \"Insert operation failed\" / \"Update operation failed\" entries logged just before this one'. They name the MESSAGE, never the level, so they stay true — verified by reading each string.",
    "outside_the_repo": "not surveyable; the changeset states the FROM to TO for anyone grepping or alerting on these lines",
    "method_correction": "⚠ The message-grep method MISSED one, and the full-suite run is what found it. packages/objectql/src/engine-delete-restricted-locale.test.ts pins #7307 (the delete door's `developerMessage` reaches the SERVER LOG). It monkey-patches the logger METHOD and reads the meta BY ARGUMENT POSITION, so it never names `Delete operation failed` and no grep for the three messages could reach it. `warn(message, meta)` has no Error slot, so the meta moved from the third argument to the second. Moved, not deleted: it now captures both levels and takes meta from the right position for each. ⇒ the honest count of level-dependent consumers is 5, not the 4 the grep found."
  },
  "deviations": [
    "SHAPE 1's DECLARATION HALF NOT LANDED, and this is the Zone 2 answer: no FAILURE_PROPAGATION_SITES / FAILURE_PROPAGATION_CALLEES entry was added, because the checker rejects one here as stale (measured, exit 1). The ruling's substance (drop the level) landed; the mechanism it named is unavailable at this shape, which the checker itself treats as already-proven via its rethrow limb. ⛔ The checker was not weakened and shape 3 was not used.",
    "FILE SURFACE INCREMENT beyond the claim's declared surface: the claim named engine.ts's insert/update catches + engine-strict-readonly-warning-truthful.test.ts. Delivered additionally — the delete catch (same class, same file), FOUR further level pins of the same lines (driver-fault-redaction.test.ts, engine-update-duplicate-record.test.ts, engine-find-missing-table-log-level.test.ts, engine-delete-restricted-locale.test.ts), one new test file, and two prose rulings in source docblocks that this change would otherwise have left contradicting the code (reportFindFailure's docblock, driver-fault-redaction.ts's #8682 header).",
    "LOCK CONTENTION, resolved not skipped: the shared heavy-verify lock was held continuously by another seat's run (scratchpad/issue-8772/final.sh, pid 5749) for ~37 minutes across FOUR acquisition windows, each returning 'VERDICT queue-timeout (exit 99) · never acquired'. Place kept via OS_VERIFY_LOCK_SLOT=issue-17052; nothing was recorded as red on an unacquired lock. The lock freed and every owed measurement was then taken, so nothing is outstanding on this account.",
    "CHANNEL SWITCH declared: REST /search/* is 403 by proxy design, so the pre-filing duplicate check used ONE targeted MCP search_issues call. It returned six semantically adjacent cards (durability-checker and publish-smoke log-scan cards) and no duplicate — a live read, not an empty one.",
    "Clause-② re-declared from the delivered diff: still NO. Nothing widens an accept set, no public surface grows; writeFailureLogMeta is module-local and not exported, and no name was added to any repo-wide list (the FAILURE_PROPAGATION_CALLEES entry the claim asked me to flag if it appeared was measured to be unavailable, so none exists)."
  ],
  "mcp_calls": "1 — a single targeted search_issues for the pre-filing duplicate check. Everything else went over repo-scoped REST or git.",
  "open_questions": [
    {
      "question": "warn or debug for the three write doors? The card allowed either and the ruling did not choose.",
      "options": [
        "warn — kept on by default (platform default level is info), off the channel publish-smoke reads",
        "debug — quieter still, but invisible in production"
      ],
      "recommendation": "warn, and it is what landed. Two measured reasons: engine-find-missing-table-log-level.test.ts already pinned that this line must NOT land at debug (that assertion is untouched by this PR and still holds), and at debug the diagnosis #8682 and #14095 fought to keep would be invisible under the default level — which Zone 1 rule 4 forbids."
    }
  ],
  "out_of_scope_findings": [
    "filed as #17212: engine.find logs `Find operation failed` at ERROR inside a catch that rethrows — the fourth member of this card's class, scoped out because its level was set by a separate recent ruling",
    "noted, not filed: `Logger.warn(message, meta?)` has no Error slot while error/fatal do, so every future demotion off `error` in this repo silently destroys an Error payload unless the call site rebuilds {message, stack} by hand — measured here: the naive move renders '\"error\":{}'. Successor: whoever fixes #17212, which is the next such move and hits this first.",
    "noted, not filed: a log-level consumer can be INVISIBLE to a message grep when it patches the logger method and reads meta by argument position (engine-delete-restricted-locale.test.ts was exactly that, and only the full package suite found it). Any future level move needs the whole package run, not the message-matched files. Successor: whoever fixes #17212 — same package, same class of pin."
  ]
}

---

Generated by Claude Code

[github-actions]

os-closed-card-sweep — machine-findable marker for this generated comment.

Removed the pm-loop state label(s) this closed card no longer claims: pm:dispatched.

• Closing pull request: fix(objectql): report a refused write at warn, not error — the caller was already told #17211, merged.
• Closing commit 0780e88481, merged into main.
• Left untouched: bug, domain:engine — ownership, priority and outcome are not state claims.
• The label set was read back after the write and matched.

A state label claims work is in flight. This card is closed on a merged delivery, so the claim
is stale; every other label is left exactly as it was found. Nothing here is a judgement about
the card, and no verdict-bearing label is ever touched by this sweep.

posted by half-state-patrol run 34427120721 · trigger schedule

Generated by Claude Code