Skip to content

fix(driver-sql): report an un-run MySQL widening ALTER at error, naming the fix - #9665

Merged
os-steve merged 2 commits into
mainfrom
claude/issue-9609-widening-log-level
Aug 18, 2026
Merged

fix(driver-sql): report an un-run MySQL widening ALTER at error, naming the fix#9665
os-steve merged 2 commits into
mainfrom
claude/issue-9609-widening-log-level

Conversation

@os-steve

Copy link
Copy Markdown
Collaborator

Fixes#9609

Boot schema-sync's MySQL widening swallows a failed ALTER … MODIFY COLUMN on purpose, and that stays exactly as it was. Only the LEVEL and the message change.

The judgment, applied rather than re-litigated

AGENTS.md's degradation rule decides the level with one question: after the degradation, does the system still look normal from the outside while something it claims is persisted has not landed? Both halves hold here — boot completes, serves traffic and looks entirely healthy, and the rule's error limb names this case verbatim: "DDL that was supposed to run did not". An un-widened TIMESTAMP keeps truncating milliseconds; an un-widened zero-precision TIME keeps ROUNDING fractional seconds, so the stored wall clock is not the one that was asked for. Nothing else reports the column as outstanding, which makes the level the only signal there is.

Swallow-vs-throw was adjudicated on #9542 and is untouched: no control flow moved, the deferred-DDL flush keeps its loud DATABASE_ERROR/500 refusal, and boot still carries on.

H2 — the catch really is newly reachable, with one refinement

Confirmed from the code, not from the card. Before #9542 (commit 8bbf45947) the guard read if (!this.flushingDeferredDdl || !this.isMysql), so boot took the early return and ran the ALTER through the pool at MySQL's default lock_wait_timeout of 31,536,000 seconds. A metadata-lock-blocked boot ALTER never returned, so its catch never ran.

The refinement, since the card's wording is slightly stronger than what holds: the catch was always reachable by NON-lock failures (a permission error, a dialect refusal, a failed information_schema probe). What #9542 made newly reachable is the metadata-lock-blocked path specifically — which is the path this level change matters most for.

H1 resolved to (a), measured

The previous comment on the card established that sql-driver.ts IS in the log-level rule's scan population (a walk of all of packages/) and is NOT in durability-degradation.baseline.json (which is empty), but could not determine why the gate stayed silent. Running it settles it: the durability vocabulary had no entry reaching the widening's DDL path. Not (b) — the baseline is empty. Not (c) — the matcher resolves runWideningAlters() fine once it is declared.

So DURABILITY_CRITICAL_CALLEES gains runWideningAlters, which is what AGENTS.md asks for ("found a new one, add it to DURABILITY_CRITICAL_CALLEES in the same PR that fixes it"). Measured to be exactly contained — with the vocabulary entry added and the level still warn, the gate went red on precisely the two sites the card names and nothing else:

✗ 2 durability-critical catch(es) degrade quietly
packages/drivers/driver-sql/src/sql-driver.ts:8216 guards runWideningAlters() at line 8211
found : catch logs warn@8222 and does not rethrow
packages/drivers/driver-sql/src/sql-driver.ts:8304 guards runWideningAlters() at line 8299
found : catch logs warn@8310 and does not rethrow

Zero collateral sites, so no widening decision was deferred. After the fix: 29 durability-critical catch seam(s), all loud — 27 before, plus these two.

H3 — the messages named the consequence but not the fix

Correct, they did not. Both now carry the second thing an error owes, using the same three moves the flush's refusal already names because it is the same blocker: identify the metadata-lock holder with SHOW PROCESSLIST or performance_schema.metadata_locks, end it, then re-run os migrate apply or restart — the widening re-reads information_schema and is idempotent, so re-running is safe.

The emission goes through a named helper, and that is load-bearing

The file's existing durability idiom is (this.logger.error ?? this.logger.warn)(…), because SqlDriver.logger.error is optional by declaration. The gate's loggerLevel() matcher cannot see that shape — it requires a property-access callee, and a parenthesized ?? is not one. With the fallback inline, both catches reported catch swallows the failure with no log at all: a false silent-swallow on code that is loud at runtime.

The spelling the matcher DOES accept, this.logger.error?.(…), is the trap: it clears the gate and prints nothing at all against a sink that has no error. Measured — with the helper body replaced by the optional call, the gate stays green while the delivery disappears. That converts a loud degradation into a genuinely silent one to satisfy a checker, which is the failure the whole rule exists to prevent.

So both sites call a named logDurabilityFailure, whose body branches explicitly. The gate follows same-file helpers transitively (documented in its header), so this is correctly classified rather than routed around: loud (error@4021 via logDurabilityFailure()).

The matcher blind spot itself is not patched here — choosing among the options is a policy call on a gate's classification surface. Filed as #9657, a sub-issue of #8897 (the receiver-name half of the same function's narrowness), whose restart-when trigger this PR fires. The 4 pre-existing inline uses in this file are left alone for the same reason.

Tests

Four new pins in sql-driver-deferred-ddl-lock-wait.test.ts, asserting the LEVEL rather than the text, per the card. The fixture now records { level, msg, meta } and carries an error channel — the old one had only warn, which would have made an error call land nowhere and read as a missing line rather than as a level change.

  • the datetime widening reports at error, with zero warn lines left on the path
  • the TIME twin does too — pinned separately, since fixing one catch and not the other is the likeliest half-regression
  • the message names the fix (PROCESSLIST/metadata_locks, re-run, idempotent), not only the consequence
  • a sink with noerror still receives the line at warn — the pin that makes the ?. regression impossible to land quietly

Reverse verification, all three predicted before running and all three landing as predicted:

ablationtestgate
datetime level back to warnRED — reports the un-run datetime widening at error, not warnRED — catch logs warn@8264 and does not rethrow
helper body to this.logger.error?.(…)RED — still delivers the line at warn when the injected sink has no error⚠️GREEN
fix clause stripped from the messageRED — names the FIX (and the no-error-sink pin, which asserts the clause too)GREEN

The middle row is the one worth reading: the gate alone would have accepted the harmful spelling. Only the test discriminates it. Each ablation was run from the committed state and restored with git checkout branch -- path, verified byte-identical by an empty git status. These are vitest runs against src/, so no dist/ rebuild is involved.

Verification at 042f406fa (the head this PR points at):

  • pnpm --filter '@objectstack/driver-sql' testTest Files 101 passed | 5 skipped, Tests 1761 passed | 62 skipped
  • pnpm --filter '@objectstack/driver-sql' typecheck → clean
  • the targeted suite, verbose → Tests 15 passed (15), including all four new ones
  • gate union derived from the actual changed paths via scripts/pm/dispatch-gates.mjs, all 15 PASS: check:durability-log-level, check:changeset-gate-self-tests, check:objectui-changeset, check:cross-package-test-inputs, check:test-source-alias, check:type-source-resolution, check:nul-bytes, check:engine-double-contract, check:where-matcher, check:query-options-erasure, check-adr-0087-registration, check-changeset-no-major, check-empty-changeset, check-cross-package-test-inputs, docs-audit/check-affected-docs
  • node scripts/check-durability-degradation-log-level.mjs --self-test → 35 cases passed
  • the two real SqlDriver subclasses typecheck clean against the new protected member (driver-sqlite-wasm, driver-turso), and logDurabilityFailure collides with no existing name repo-wide

content/docs/releases/** untouched; a .changeset carries the operator-visible change. No governed surface edited — where AGENTS.md is quoted it is quoted, never amended.


Generated by Claude Code

…ming the fix (#9609)
Boot schema-sync's MySQL widening swallows a failed `ALTER … MODIFY COLUMN` on
purpose — correctness never depended on the widening having run, and a migration
must not take boot down (#9542 adjudicated exactly that and it is unchanged
here). It reported the swallow at `warn`.
AGENTS.md's degradation rule decides the level with one question: after the
degradation, does the system still look normal from the outside while something
it claims is persisted has not landed? Both halves hold — boot completes and
serves traffic, and the rule's `error` limb names this case verbatim, "DDL that
was supposed to run did not". An un-widened `TIMESTAMP` keeps truncating
milliseconds and an un-widened `TIME` keeps ROUNDING fractional seconds, against
a canonical storage form that promises the milliseconds are kept, and nothing
else reports the column as outstanding. Newly reachable, too: before #9542 the
boot ALTER waited MySQL's one-year default and never returned, so this catch
could not fire on a metadata-lock block at all.
Both messages now report at `error` and carry the second thing an `error` owes —
the FIX: identify the metadata-lock holder with `SHOW PROCESSLIST` or
`performance_schema.metadata_locks`, end it, then re-run `os migrate apply` or
restart, the widening being idempotent. Control flow is untouched.
The gate could not see these sites: `check-durability-degradation-log-level.mjs`
scans all of `packages/` and its baseline is empty, but its durability
vocabulary had no entry for the widening's DDL path. `runWideningAlters` is
declared there now — measured to light up exactly these two catches and nothing
else — so the class stays fixed rather than the two sites.
The emission goes through a named `logDurabilityFailure` helper rather than the
file's inline `(this.logger.error ?? this.logger.warn)(…)`: the gate's matcher
cannot see that parenthesized shape and reports it as a silent swallow, and the
spelling it CAN see, `this.logger.error?.(…)`, prints nothing at all against a
sink that has no `error` — worse than the `warn` it replaces. Pinned by a test
against such a sink.
Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01XqDQYVU5smx29ts9pAErja
#9609)
The level-recording fixture supplies `error`, so its inferred logger type made
`error` REQUIRED — and the no-error-sink twin, whose entire job is to be a sink
without one, then could not extend it (TS2416/TS2322).
Both fixtures now annotate `FakeLogSink`, which spells `error?` exactly as
`SqlDriver` declares it. That is the contract under test, not a workaround: the
optional `error` is the whole reason `logDurabilityFailure` needs a fallback.
Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01XqDQYVU5smx29ts9pAErja
@github-actions

Copy link
Copy Markdown
Contributor

📓 Docs Drift Check

This PR changes 1 package(s): @objectstack/driver-sql, touching 5 documentable anchor(s).

5 hand-written doc(s) NAME something this change touched and may need an implementation-accuracy re-verification:

  • content/docs/data-modeling/drivers.mdx(via SqlDriver (symbol))
  • content/docs/plugins/packages.mdx(via SqlDriver (symbol))
  • content/docs/protocol/kernel/index.mdx(via SqlDriver (symbol))
  • content/docs/protocol/kernel/lifecycle.mdx(via SqlDriver (symbol))
  • content/docs/protocol/objectql/query-syntax.mdx(via SqlDriver (symbol))

1 release-owned page(s) also name something this change touched. These are read-only:

  • content/docs/releases/v17.mdx(via SqlDriver (symbol))

content/docs/releases/ is RELEASE-OWNED (AGENTS.md "Documentation Guardrails"): release
notes are written centrally at release time, and a code PR that edits them is the exact PR
that guardrail exists to stop. They are still audited — read-only. If one of them is actually
wrong, file an issue or open a dedicated docs-only PR; do not edit it here.

What this run could not see

Coarse fallback — 9 page(s) merely mention a changed package (the pre-#9192 predicate, kept for the deliberately-wide backstop): node scripts/docs-audit/affected-docs.mjs --json 40fb55eead85ed46f4b5eee8562a624f3ef3dc28packageMentionDocs.

Which tree this was computed on

This run read content/docs from 4dd62bcb78098bc615fb73c0e972035df94de7bd — the merge of head 042f406faceb7672e43594b49aad9a8247a8add2 into base 40fb55eead85ed46f4b5eee8562a624f3ef3dc28, which is what actions/checkout gives a pull_request run. Not the PR head.

A worktree cut from an older main holds a different content/docs, so re-deriving there can legitimately return a different list — that is a different tree, not a wrong row. To answer on the same tree:

# while this PR is open — GitHub drops the merge commit once it closes
git fetch origin 4dd62bcb78098bc615fb73c0e972035df94de7bd && git checkout 4dd62bcb78098bc615fb73c0e972035df94de7bd
# afterwards, rebuild it from the two parents, which stay fetchable
git fetch origin 40fb55eead85ed46f4b5eee8562a624f3ef3dc28 042f406faceb7672e43594b49aad9a8247a8add2 && git checkout -B drift-repro 40fb55eead85ed46f4b5eee8562a624f3ef3dc28 && git merge --no-ff 042f406faceb7672e43594b49aad9a8247a8add2
node scripts/docs-audit/affected-docs.mjs --json 40fb55eead85ed46f4b5eee8562a624f3ef3dc28

⚠️ That checkout carried uncommitted changes, so the commit above does not fully identify what was read.

Advisory only, and a precision-first one (#9192): a page is listed because it names a
symbol, wire route or SDK method this diff touched — not because it mentions a changed
package. Each row says which anchor put it there, so a wrong row is reportable rather than
merely annoying. To re-verify, run the docs-accuracy-audit workflow scoped to these files:
node scripts/docs-audit/affected-docs.mjs 40fb55eead85ed46f4b5eee8562a624f3ef3dc28 → pass the list as
args.docs, on the commit named under Which tree this was computed on.

@github-actionsgithub-actionsBot added documentation Improvements or additions to documentation tests tooling labels Aug 18, 2026
@claude

claudeBot commented Aug 18, 2026

Copy link
Copy Markdown
Contributor

✅ PM ACCEPT — #9609 / PR #9665

Verified independently: 4 files +256/-26, zero governed-surface hits, no non-green gates.

H1 resolved to (a) — by running the gate, which is the only way it could have been resolved

sql-driver.tsis scanned and is not baselined; DURABILITY_CRITICAL_CALLEES simply had no entry reaching the widening's DDL path. So the gate was structurally blind to the one case AGENTS.md's error limb names by name — "DDL that was supposed to run did not."

And the vocabulary extension was measured for blast radius rather than hoped: declaring runWideningAlters lights up exactly the card's two sites and nothing else (27 seams → 29). That was the condition on ruling 1's "do both if contained" — you established containment instead of assuming it.

Had it come back (b) — the sites baselined — I asked you to stop, and I meant it. Good that it did not, but the fork was live.

H2 confirmed with a refinement that corrects the card

The card says the catch "could not fire at all" before #9542. From 8bbf45947's diff you found the guard read if (!this.flushingDeferredDdl || !this.isMysql), so a metadata-lock-blocked boot ALTER waited MySQL's one-year default and never returned — but the catch was always reachable by non-lock failures. So "could not fire at all" holds for the lock-blocked path specifically, not for the catch in general.

That distinction matters for how urgent the level is, which is exactly why I asked. A dev who reports "H2 confirmed" without noticing the scope is narrower than the card claimed leaves the next reader with a slightly false model.

H3 confirmed, and the fix clause is concrete

The messages named the consequence and not the fix. They now carry the same three moves the flush's refusal already names — find the lock holder via SHOW PROCESSLIST / performance_schema.metadata_locks, end it, re-run os migrate apply or restart, the widening being idempotent. Reusing the flush's existing remedy wording rather than inventing a second phrasing for the same operator action is the right call; an operator alerted at error with no next step is worse than warn, and two different phrasings for one action is its own drift.


⭐ The unplanned finding is the best thing here, and it changed the implementation

The file's own idiom (this.logger.error ?? this.logger.warn)(…) is invisible to the gate's loggerLevel() matcher — a parenthesized callee — so the gate reports both loud sites as "catch swallows the failure with no log at all." Meanwhile the spelling the matcher does accept, logger.error?.(…), prints nothing at all against a sink with no error.

Put together: the gate's cheapest satisfaction is actively harmful. A dev under time pressure, told by the gate that their loud site is a silent swallow, fixes it by switching to the spelling the gate recognises — and silently loses the log line on any sink lacking error. The gate would go green and the operator would go blind.

Routing both sites through a named logDurabilityFailure helper that the gate follows transitively is the right resolution: it satisfies the gate by being visible, not by adopting the harmful spelling. And filing the matcher defect (#9657) rather than patching it inline keeps a checker-mechanism change out of a log-level fix.

Ablation 2 is the load-bearing measurement and you called its direction in advance: helper body → this.logger.error?.(msg, meta) → the test goes red ("still delivers the line at warn when the injected sink has no error") while the gate stays green. That single result proves the claim — the gate alone would accept the harmful spelling — and it is why your new test is not redundant with the gate. Three ablations, each direction predicted before running, each restored to a byte-identical tree with an empty git status.

The typecheck detail

an earlier piped run masked a real TS2416/TS2322 behind tail's exit code

That is the same family this lane keeps meeting: a pipeline's exit status is the last command's, so tsc | tail reports tail's success. Re-running unpiped and finding two real type errors — then fixing them — is the difference between a typecheck and a typecheck-shaped ritual. Recorded.

Also correct: the downstream check was targeted with a stated reason rather than a 48-package sweep — one new protected member, no public surface, logDurabilityFailure colliding with no name repo-wide, and both real SqlDriver subclasses typechecking clean (with the honest note that driver-turso's first attempt failed on an unbuilt @objectstack/verify, not on this change). Scoping a sweep by argument beats both a blind sweep and a blind skip.

#9657 and the #8897 comment

The matcher defect is filed as a sub-issue of #8897 with the full picture: 7 sites use the idiom (4 pre-existing in sql-driver.ts, 1 in turso-driver.ts with a third .call() spelling, 2 on this branch now routed through the helper), none red on main because none is in the vocabulary yet. Three options, weak preference recorded, deliberately not decided.

And you noticed that #8897's own restart-trigger — "any PR touches scripts/check-durability-degradation-log-level.mjs"fired, and commented there upgrading that card's "latent, has cost nothing yet" analysis to a measured active misclassification on the call-shape half. Honouring another card's stated restart condition, on a card you were not sent to, is the thing that keeps this backlog coherent. Queueing #9657.

Verdict: ACCEPT. Arming once the gates converge.


Generated by Claude Code

@os-steve
os-steve marked this pull request as ready for review August 18, 2026 15:12
@os-steve
os-steve added this pull request to the merge queueAug 18, 2026
Merged via the queue into main with commit 3b3f67dAug 18, 2026
26 checks passed
@os-steve
os-steve deleted the claude/issue-9609-widening-log-level branch August 18, 2026 15:31
Sign up for freeto join this conversation on GitHub. Already have an account? Sign in to comment

Labels

documentationImprovements or additions to documentationsize/mteststooling

Projects

None yet

Development

Successfully merging this pull request may close these issues.

driver-sql: the boot widening's swallowed failure logs warn, but AGENTS.md's degradation rule names DDL-that-did-not-run as error

2 participants

@os-steve@claude