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

* 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

* test(driver-sql): type the fixture log sinks so `error` stays OPTIONAL (#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

---------

Co-authored-by: Claude <noreply@anthropic.com>

Author: os-steve

.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

@@ -55,6 +55,22 @@ const WIDGET = {
 /** One statement, tagged with the pinned session it was issued on. */
 interface Issued { session: number; sql: string; bindings: unknown[] }
 
+/**
+ * [#9609] The driver's logger shape, with `error` OPTIONAL exactly as
+ * `SqlDriver` declares it.
+ *
+ * Spelled out rather than inferred from each fixture's object literal: an
+ * inferred type makes `error` REQUIRED on whichever fixture happens to supply
+ * it, and then the no-error-sink twin below cannot extend it — which reads as a
+ * TypeScript puzzle when it is really the contract under test. `error?` is the
+ * whole reason `logDurabilityFailure` needs a fallback.
+ */
+type FakeLogSink = {
+  warn: (msg: string, meta?: any) => void;
+  info?: (msg: string, meta?: any) => void;
+  error?: (msg: string, meta?: any) => void;
+};
+
 /**
  * MySQL's lock-wait timeout as mysql2 raises it, wrapped the way knex re-throws
  * it — the wrapper is the point: a recognizer reading only the top-level error
@@ -94,17 +110,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 }); },
+  protected override logger: FakeLogSink = {
+    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 +200,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: FakeLogSink = {
+    warn: (msg: string, meta?: any) => { this.logs.push({ level: 'warn', 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 +413,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 () => {