fix(driver-sql): report an un-run MySQL widening ALTER at error, naming 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

Author: claude

.changeset/olive-donkeys-brake.md

@@ -0,0 +1,27 @@
+---
+'@objectstack/driver-sql': patch
+---
+
+Report an un-run MySQL widening ALTER at `error`, naming the fix
+
+Boot schema-sync widens legacy MySQL `TIMESTAMP` columns to `DATETIME(3)` and
+zero-precision `TIME` columns to `TIME(3)`. When that DDL cannot run — most
+often another session holding the table's metadata lock — the failure is
+swallowed on purpose so a migration never takes boot down. It was reported at
+`warn`.
+
+That is the case AGENTS.md's degradation rule names for `error` by name: after
+the swallow the platform boots, serves traffic and looks entirely normal, while
+the DDL that was supposed to run did not. An un-widened `TIMESTAMP` keeps
+truncating milliseconds and an un-widened `TIME` keeps rounding fractional
+seconds to whole ones, against a canonical storage form that promises the
+milliseconds are kept, and nothing else reports the column as outstanding.
+
+Both lines now report at `error` and say what to do about it — identify the
+metadata-lock holder, end it, then re-run `os migrate apply` or restart, the
+widening being idempotent. Control flow is unchanged: the swallow stays, and
+the deferred-DDL flush keeps its loud refusal.
+
+`scripts/check-durability-degradation-log-level.mjs` gains `runWideningAlters`
+in its durability vocabulary, so the class stays fixed rather than these two
+sites.

packages/drivers/driver-sql/src/sql-driver-deferred-ddl-lock-wait.test.ts

@@ -94,17 +94,27 @@ class FakeMysqlDriver extends SqlDriver {
 
   issued: Issued[] = [];
   /**
-   * [#9542] Every `logger.warn` the driver emitted.
+   * [#9542/#9609] Every log line the driver emitted, **with its level**.
    *
    * On the boot path this is the ONLY output a blocked widening produces — the
    * swallow eats the error itself — so "the bound fires and the operator is
    * told" and "the bound fires and nothing at all is printed" are the same
    * green suite without a sink to assert on.
+   *
+   * ⭐ #9609: the LEVEL is recorded, not just the text. The pins below assert
+   * `error`, because that is the observable that regresses: a future edit that
+   * puts this line back on `warn` keeps every message assertion green while
+   * removing it from the operator's alerting, which is the only signal there
+   * is. Recording the text alone cannot tell those two apart. The sink
+   * therefore also HAS an `error` channel — the previous fixture had only
+   * `warn`, which would have made an `error` call land nowhere and read as a
+   * missing line rather than as a level change.
    */
-  warnings: Array<{ msg: string; meta?: any }> = [];
+  logs: Array<{ level: 'warn' | 'error'; msg: string; meta?: any }> = [];
 
   protected override logger = {
-    warn: (msg: string, meta?: any) => { this.warnings.push({ msg, meta }); },
+    warn: (msg: string, meta?: any) => { this.logs.push({ level: 'warn', msg, meta }); },
+    error: (msg: string, meta?: any) => { this.logs.push({ level: 'error', msg, meta }); },
     info: () => {},
   };
 
@@ -174,6 +184,32 @@ function makeDriver(): FakeMysqlDriver {
   });
 }
 
+/**
+ * [#9609] The same driver behind a sink that has NO `error` channel.
+ *
+ * `SqlDriver.logger.error` is optional by declaration, and a host that injects
+ * `{ warn }` is a supported composition. This twin exists so the fallback in
+ * `logDurabilityFailure` is pinned by a test rather than by a comment: the
+ * obvious way to make the durability gate see this call site is
+ * `this.logger.error?.(…)`, which against THIS sink prints nothing at all —
+ * strictly worse than the `warn` it replaced, and invisible to every assertion
+ * that only looks at the driver with a full sink.
+ */
+class NoErrorSinkDriver extends FakeMysqlDriver {
+  protected override logger = {
+    warn: (msg: string, meta?: any) => { this.logs.push({ level: 'warn' as const, msg, meta }); },
+    info: () => {},
+  };
+}
+
+function makeNoErrorSinkDriver(): NoErrorSinkDriver {
+  return new NoErrorSinkDriver({
+    client: 'better-sqlite3',
+    connection: { filename: ':memory:' },
+    useNullAsDefault: true,
+  });
+}
+
 /** Create the table, then arm the deferral over the same metadata. */
 async function armedFlush(driver: FakeMysqlDriver): Promise<void> {
   await driver.initObjects([WIDGET]);   // table now EXISTS — widening applies
@@ -361,27 +397,109 @@ describe('[#9354/#9542] a blocked widening ALTER — bounded on both paths, refu
     // boot, and correctness never depended on the widening having run.
   });
 
-  it('finally reaches the boot `logger.warn` — a bound that printed nothing would deliver nothing', async () => {
+  it('finally reaches the boot durability log — a bound that printed nothing would deliver nothing', async () => {
     driver = makeDriver();
     await driver.initObjects([WIDGET]);
     driver.issued.length = 0;
-    driver.warnings.length = 0;
+    driver.logs.length = 0;
 
     await expect(driver.initObjects([WIDGET])).resolves.toBeUndefined();
 
-    // ⭐ The card's whole claim. This warn was already written and was
+    // ⭐ The card's whole claim. This line was already written and was
     // UNREACHABLE in this scenario: the unbounded ALTER never returned, so the
     // catch that logs it never ran. A bound whose only effect is a quieter hang
     // delivers nothing and looks identical in a green suite, so the delivery is
     // asserted on the sink rather than inferred from the bound being armed.
-    const warn = driver.warnings.find((w) => /could not widen MySQL datetime columns/.test(w.msg));
-    expect(warn).toBeDefined();
-    expect(warn!.msg).toContain(WIDGET.name);
+    const line = driver.logs.find((w) => /widen MySQL datetime columns/.test(w.msg));
+    expect(line).toBeDefined();
+    expect(line!.msg).toContain(WIDGET.name);
     // Carrying the server's own diagnosis, not a swallowed blank.
-    expect(String(warn!.meta?.error)).toMatch(/Lock wait timeout exceeded/);
+    expect(String(line!.meta?.error)).toMatch(/Lock wait timeout exceeded/);
     // And it is the SERVER error that was swallowed, not the ADR-0112 refusal:
     // that envelope stays flush-only, so its operator sentence is absent here.
-    expect(String(warn!.meta?.error)).not.toMatch(/PROCESSLIST|No schema change was made/);
+    expect(String(line!.meta?.error)).not.toMatch(/PROCESSLIST|No schema change was made/);
+  });
+
+  // ───────────────────────────────────────────────────────────────
+  // #9609 — the LEVEL of that line, which is a separate question
+  // ───────────────────────────────────────────────────────────────
+
+  it('reports the un-run datetime widening at `error`, not `warn`', async () => {
+    driver = makeDriver();
+    await driver.initObjects([WIDGET]);
+    driver.logs.length = 0;
+
+    await expect(driver.initObjects([WIDGET])).resolves.toBeUndefined();
+
+    // AGENTS.md → "Degradation log levels" decides this with one question:
+    // after the degradation, does the system still look normal from the outside
+    // while something it claims is persisted has not landed? Here: yes. Boot
+    // completed, traffic is served, and the `error` limb names this exact case
+    // — "DDL that was supposed to run did not". The swallow is unchanged and
+    // deliberately so (#9542); only the level moved.
+    const line = driver.logs.find((w) => /widen MySQL datetime columns/.test(w.msg));
+    expect(line?.level).toBe('error');
+    // ⭐ Asserted as an ABSENCE too, because `find` above would happily return
+    // an `error` line while a second `warn` copy of the same degradation kept
+    // being emitted somewhere else on the path.
+    expect(driver.logs.filter((w) => w.level === 'warn')).toHaveLength(0);
+  });
+
+  it('reports the un-run TIME widening at `error` too — the twins do not diverge', async () => {
+    driver = makeDriver();
+    driver.legacyDatetimeColumns = [];
+    driver.legacyTimeColumns = [{ name: 'at', nullable: true }];
+    await driver.initObjects([WIDGET]);
+    driver.logs.length = 0;
+
+    await expect(driver.initObjects([WIDGET])).resolves.toBeUndefined();
+
+    // The `Field.time` twin loses fractional seconds by ROUNDING, which changes
+    // the wall clock that was asked for — if anything the louder of the two. It
+    // is pinned separately because the two catches are separate code: fixing one
+    // and not the other is the likeliest way this half-regresses.
+    const line = driver.logs.find((w) => /widen MySQL time columns/.test(w.msg));
+    expect(line?.level).toBe('error');
+    expect(line!.msg).toContain(WIDGET.name);
+  });
+
+  it('names the FIX, not only the consequence — the second thing an `error` owes', async () => {
+    driver = makeDriver();
+    await driver.initObjects([WIDGET]);
+    driver.logs.length = 0;
+
+    await expect(driver.initObjects([WIDGET])).resolves.toBeUndefined();
+
+    const line = driver.logs.find((w) => /widen MySQL datetime columns/.test(w.msg));
+    // AGENTS.md: an `error` owes BOTH the consequence and the fix, in the first
+    // line it prints. An operator woken at `error` with no next step is a worse
+    // outcome than the `warn` this replaced, so the actionable half is pinned as
+    // hard as the level. Same three moves the flush's refusal names, because it
+    // is the same blocker: find the lock holder, end it, re-run.
+    expect(line!.msg).toMatch(/PROCESSLIST|metadata_locks/);
+    expect(line!.msg).toMatch(/os migrate apply|restart/);
+    expect(line!.msg).toMatch(/idempotent/);
+    // And the consequence stays concrete rather than becoming "degraded".
+    expect(line!.msg).toMatch(/millisecond/i);
+  });
+
+  it('still delivers the line at `warn` when the injected sink has no `error`', async () => {
+    const noErrorSink = makeNoErrorSinkDriver();
+    driver = noErrorSink;
+    await noErrorSink.initObjects([WIDGET]);
+    noErrorSink.logs.length = 0;
+
+    await expect(noErrorSink.initObjects([WIDGET])).resolves.toBeUndefined();
+
+    // ⛔ The regression this guards is `this.logger.error?.(…)`: it satisfies the
+    // durability gate's matcher and prints NOTHING against this sink, converting
+    // a loud degradation into a silent one to please a checker. `SqlDriver`
+    // declares `logger.error` optional, so this composition is supported and the
+    // fallback is part of the contract, not a nicety.
+    const line = noErrorSink.logs.find((w) => /widen MySQL datetime columns/.test(w.msg));
+    expect(line).toBeDefined();
+    expect(line!.level).toBe('warn');
+    expect(line!.msg).toMatch(/PROCESSLIST|metadata_locks/);
   });
 
   it('clears the flush flag after a refusal, so a later boot sync is unaffected', async () => {

packages/drivers/driver-sql/src/sql-driver.ts

@@ -887,7 +887,8 @@ function backendStatementFaultError(object: string, cause: unknown): Error {
  * one. Everything above is reasoning about how long a legitimate metadata-lock
  * holder can plausibly hold it — a property of the lock, not of who is waiting
  * on it. Boot's difference from the flush is what happens when the bound fires
- * (boot warns and carries on; the flush refuses), never how long it waits.
+ * (boot reports at `error` and carries on; the flush refuses), never how long
+ * it waits.
  *
  * ⛔ Deliberately NOT configurable, and deliberately NOT retried — the 2026-08-17
  * ruling's explicit minimality. Both wait for measured demand. A knob added now
@@ -3983,6 +3984,45 @@ export class SqlDriver implements IDataDriver {
     error: (msg, meta) => console.error(msg, meta ?? ''),
   };
 
+  /**
+   * [#9609] Emit on the durability-degradation channel: `error` when the
+   * injected sink has one, `warn` when it does not.
+   *
+   * # Why a named method and not the inline `(this.logger.error ?? this.logger.warn)(…)`
+   *
+   * Two reasons, and the second is the load-bearing one.
+   *
+   * ① It names the AGENTS.md channel at the call site, so the level is read as
+   * a classification ("this is durability, not functionality") rather than as
+   * an adjective someone picked. The `error?` field above already documents
+   * that channel; this is its verb.
+   *
+   * ② `check-durability-degradation-log-level.mjs` cannot SEE the inline
+   * fallback. Its `loggerLevel()` matches the shape `<logger|log|console>.<level>(…)`
+   * — a call whose expression is a property access. `(a ?? b)(…)` is a call on
+   * a PARENTHESIZED expression, so the matcher returns nothing and the catch is
+   * reported as `catch swallows the failure with no log at all` — a false
+   * silent-swallow on code that is loud at runtime. Measured, not inferred:
+   * with `runWideningAlters` in the vocabulary, both widening catches reported
+   * exactly that while calling the fallback inline.
+   *
+   * ⛔ Deliberately NOT `this.logger.error?.(…)`, which the gate DOES recognise.
+   * That spelling drops the message entirely for a sink that has no `error` —
+   * turning a durability-critical failure into true silence in order to
+   * satisfy a matcher, which is the failure this whole rule exists to prevent. The gate follows
+   * same-file helpers transitively (its header says so, and the audit reports
+   * sites as `loud (error@… via <helper>())`), so routing through this method
+   * keeps the fallback AND is correctly classified.
+   *
+   * The pre-existing inline uses in this file (the ADR-0120 D4 index sites) are
+   * left alone on purpose — they are a separate change with a separate blast
+   * radius, and the matcher blind spot itself is filed rather than patched here.
+   */
+  protected logDurabilityFailure(msg: string, meta?: any): void {
+    if (this.logger.error) this.logger.error(msg, meta);
+    else this.logger.warn(msg, meta);
+  }
+
   /** Whether the underlying database is a SQLite variant (sqlite3 or better-sqlite3). */
   protected get isSqlite(): boolean {
     const c = (this.config as any).client;
@@ -8113,9 +8153,11 @@ export class SqlDriver implements IDataDriver {
    * better for boot than it is for an operator: a boot blocked on another
    * session's metadata lock waits 31,536,000 seconds having printed nothing,
    * and boot is the path nobody can retry from a prompt. Bounding it turns
-   * that into a bounded wait plus the widening's own `logger.warn` — which,
+   * that into a bounded wait plus the widening's own durability log — which,
    * until the bound reached here, could never fire at all: the ALTER never
-   * returned, so its catch never ran.
+   * returned, so its catch never ran. #9609 raised that line from `warn` to
+   * `error`; the level is the operator's only signal, and the swallow below is
+   * exactly what makes an un-run ALTER invisible without it.
    *
    * What stays gated on {@link flushDeferredSchemaDdl} is the REFUSAL, and
    * only it. Boot still swallows: correctness never depends on the widening
@@ -8150,8 +8192,8 @@ export class SqlDriver implements IDataDriver {
           } catch (err) {
             // #9542: the bound is armed on both callers, the ESCAPE is not.
             // Off the flush this rethrows the server's own error, which the
-            // widening's catch logs and swallows — boot's policy unchanged,
-            // now reached by a wait that ends.
+            // widening's catch reports and swallows — boot's policy
+            // unchanged, now reached by a wait that ends.
             if (this.flushingDeferredDdl && isMysqlLockWaitTimeout(err)) {
               throw deferredDdlLockWaitError(table, DEFERRED_DDL_LOCK_WAIT_TIMEOUT_SECONDS, err);
             }
@@ -8219,9 +8261,14 @@ export class SqlDriver implements IDataDriver {
       // lock wait that the flush bounded is the operator's answer to a command
       // they ran, and dropping it would report success for work not done.
       if (isDeferredDdlLockWaitRefusal(err)) throw err;
-      this.logger.warn(
-        `[sql-driver] could not widen MySQL datetime columns on ${table}; ` +
-        `writes stay correct, but the 2038 ceiling and millisecond truncation remain`,
+      this.logDurabilityFailure(
+        `[sql-driver] FAILED to widen MySQL datetime columns on ${table} — the DDL did not run and boot ` +
+        `continued: the columns are still legacy TIMESTAMP, so every write to them keeps truncating ` +
+        `milliseconds and keeps the 2038 ceiling, while reads return exactly what was stored and nothing ` +
+        `else reports the table as un-widened. Fix: identify the metadata-lock holder with ` +
+        '`SHOW PROCESSLIST` or `performance_schema.metadata_locks` (or resolve the error in this ' +
+        'record\'s meta), end it, then re-run `os migrate apply` or restart — the widening is ' +
+        're-detected from `information_schema` and is idempotent, so re-running is safe.',
         { error: err instanceof Error ? err.message : String(err) },
       );
     }
@@ -8269,9 +8316,21 @@ export class SqlDriver implements IDataDriver {
    * keeps the milliseconds instead, matching the canonical form's resolution
    * and the `DATETIME(3)` precedent (#3942).
    *
-   * Failures are logged and swallowed for the usual reason; the only cost of a
-   * `TIME(0)` column that could not be widened is second-rounding of fractional
-   * writes — which is today's behaviour.
+   * Failures are swallowed for the usual reason; the only cost of a `TIME(0)`
+   * column that could not be widened is second-rounding of fractional writes —
+   * which is today's behaviour.
+   *
+   * # The level is `error`, and that is a separate question from the swallow (#9609)
+   *
+   * Swallow-vs-throw was adjudicated (#9542) and is unchanged: boot must not go
+   * down over a migration. `warn`-vs-`error` was never separately decided, and
+   * AGENTS.md → "Degradation log levels" decides it 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 its `error` limb names this case by name
+   * ("DDL that was supposed to run did not"). Nothing else reports the column
+   * as un-widened, so the level IS the signal. Same reasoning, same level, on
+   * {@link migrateMysqlDatetimeColumns}.
    */
   protected async migrateMysqlTimeColumns(
     table: string,
@@ -8307,9 +8366,15 @@ export class SqlDriver implements IDataDriver {
       // lock wait that the flush bounded is the operator's answer to a command
       // they ran, and dropping it would report success for work not done.
       if (isDeferredDdlLockWaitRefusal(err)) throw err;
-      this.logger.warn(
-        `[sql-driver] could not widen MySQL time columns on ${table}; ` +
-        `fractional-second writes keep rounding to whole seconds`,
+      this.logDurabilityFailure(
+        `[sql-driver] FAILED to widen MySQL time columns on ${table} — the DDL did not run and boot ` +
+        `continued: the columns are still zero-precision TIME, so every fractional-second write to them ` +
+        `keeps being ROUNDED to whole seconds — the stored wall clock is not the one that was asked for — ` +
+        `while reads return exactly what was stored and nothing else reports the table as un-widened. ` +
+        'Fix: identify the metadata-lock holder with `SHOW PROCESSLIST` or ' +
+        '`performance_schema.metadata_locks` (or resolve the error in this record\'s meta), end it, then ' +
+        're-run `os migrate apply` or restart — the widening is re-detected from `information_schema` ' +
+        'and is idempotent, so re-running is safe.',
         { error: err instanceof Error ? err.message : String(err) },
       );
     }