fix(driver-sql): bound the metadata-lock wait on boot schema-sync's MySQL widening ALTER too, keeping boot's swallow (#9542)

.changeset/boot-widening-bounded-lock-wait.md

@@ -0,0 +1,41 @@
+---
+"@objectstack/driver-sql": patch
+---
+
+fix(driver-sql): boot schema-sync's MySQL widening ALTER bounds its metadata-lock wait too — a blocked boot warns and carries on instead of hanging for a year (#9542)
+
+#9354 bounded `lock_wait_timeout` to 120s on the widening `ALTER TABLE … MODIFY
+COLUMN` and made a blocked `os migrate apply` refuse loudly — but only while
+`flushDeferredSchemaDdl` was running. The same two widenings
+(`migrateMysqlDatetimeColumns` / `migrateMysqlTimeColumns`, #3942 / #3994) are
+reached from **boot schema-sync** through the same `initObjects` lines, and on
+that path the `runWideningAlters` seam returned early: the ALTER ran through the
+pool inheriting MySQL's own default `lock_wait_timeout` of **31,536,000 seconds
+— one year**.
+
+So a single other session holding a metadata lock on the table parked boot at
+schema-sync for that long, printing nothing — indistinguishable from a crash.
+The widening's own `logger.warn` could not help, because it lives in a `catch`
+and an ALTER that never returns is never caught.
+
+The bound is now armed **unconditionally** in that seam. What stays gated on the
+flush is the **refusal**, and only it: boot still swallows. Correctness never
+depends on the widening having run and a migration must never take boot down, so
+throwing there would trade a silent hang for a failed boot — a different answer,
+not the same one.
+
+**What changes for a deployment.** On MySQL, a boot whose widening ALTER is
+blocked on a metadata lock now waits at most 120s, then logs
+`[sql-driver] could not widen MySQL datetime columns on …` (or its `TIME(3)`
+twin) naming the table, with the server's own `Lock wait timeout exceeded` as
+the `error` field — and boot carries on. The widening is idempotent, so the
+first boot after the blocker is gone completes it. Nothing changes on any other
+dialect, on an ALTER that is not blocked, or for `os migrate apply`, which keeps
+#9354's `DATABASE_ERROR` / 500 refusal.
+
+120s is #9354's number, kept for boot deliberately rather than lengthened: the
+reasoning behind it is about how long a legitimate metadata-lock holder can
+plausibly hold the lock, which is a property of the lock and not of who is
+waiting on it. Boot's difference from the flush is what happens when the bound
+fires, never how long it waits. No retry logic and no configurability — the
+2026-08-17 ruling's minimality, unchanged.

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

@@ -16,6 +16,17 @@
  * whose code comes from the closed vocabulary and names the lock wait. No retry
  * logic, no configurability.
  *
+ * # #9542 — the same bound on boot, deliberately without the refusal
+ *
+ * The seam above separates "bound the wait" from "escape the swallow", and
+ * #9354 armed only the flush, leaving boot schema-sync on the one-year default
+ * (pinned here as intended behaviour, which is how it stayed a recorded gap
+ * rather than an unnoticed one). Triage's 2026-08-18 auto-adjudication took the
+ * card's Option 1: arm the bound unconditionally, keep the REFUSAL gated on the
+ * flush, keep boot's SWALLOW. So this suite now pins two different answers on
+ * one code path — the flush refuses, boot warns — and every pin below says by
+ * name which of the two it is guarding.
+ *
  * # What this suite pins, and why it is pinned THIS way
  *
  * ⭐ The observable is the **refusal**, never "a `SET SESSION` string was
@@ -82,6 +93,21 @@ class FakeMysqlDriver extends SqlDriver {
  private sessions = 0;
 
  issued: Issued[] = [];
+ /**
+ * [#9542] Every `logger.warn` the driver emitted.
+ *
+ * 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.
+ */
+ warnings: Array<{ msg: string; meta?: any }> = [];
+
+ protected override logger = {
+ warn: (msg: string, meta?: any) => { this.warnings.push({ msg, meta }); },
+ info: () => {},
+ };
+
  /** What the ALTER should do; `undefined` = succeed. */
  alterFails: (() => Error) | undefined = lockWaitTimeoutError;
  legacyDatetimeColumns: Array<{ name: string; nullable: boolean }> = [
@@ -170,7 +196,7 @@ const setStatements = (d: FakeMysqlDriver) =>
 const alterStatements = (d: FakeMysqlDriver) =>
  d.issued.filter((s) => /^alter table/i.test(s.sql));
 
-describe('[#9354] deferred-DDL flush — a blocked widening ALTER refuses, loudly', () => {
+describe('[#9354/#9542] a blocked widening ALTER — bounded on both paths, refusing on one', () => {
  let driver: FakeMysqlDriver;
 
  afterEach(async () => {
@@ -299,16 +325,63 @@ describe('[#9354] deferred-DDL flush — a blocked widening ALTER refuses, loudl
  await expect(driver.flushDeferredSchemaDdl()).resolves.toBeDefined();
  });
 
- it('leaves BOOT sync unbounded and swallowing — it is not the flush', async () => {
+ // ───────────────────────────────────────────────────────────────
+ // BOOT (#9542) — the same bound, the opposite answer when it fires
+ // ───────────────────────────────────────────────────────────────
+
+ it('bounds BOOT sync too, and still swallows — boot is not the flush', async () => {
  driver = makeDriver();
  await driver.initObjects([WIDGET]);
  driver.issued.length = 0;
 
  // A second boot-time sync over the existing table reaches the same widening,
- // but off the deferred path. Boot must never be taken down by a migration,
- // and nobody is waiting at a prompt to read a refusal.
+ // but off the deferred path. This pin used to read the other way round:
+ // boot ran the ALTER through the pool at MySQL's one-year default, so a boot
+ // behind another session's metadata lock stopped at schema-sync, printed
+ // nothing, and could not be told from a crash. #9542 arms the bound here.
+ await expect(driver.initObjects([WIDGET])).resolves.toBeUndefined();
+
+ const set = setStatements(driver);
+ const alter = alterStatements(driver);
+ expect(alter).toHaveLength(1);
+ expect(set[0].bindings).toEqual([120]);
+ // On the ALTER's OWN session, for the reason the flush needs it: through the
+ // pool the bound lands on a connection the ALTER never uses, and the boot
+ // hangs exactly as before with this pin still green.
+ expect(set[0].session).toBe(alter[0].session);
+ expect(driver.issued.indexOf(set[0])).toBeLessThan(driver.issued.indexOf(alter[0]));
+ // And the prior value goes back — a boot must not hand the pool a
+ // connection carrying a migration's lock bound into unrelated runtime work.
+ expect(set).toHaveLength(2);
+ expect(set[1].bindings).toEqual([MYSQL_DEFAULT_LOCK_WAIT]);
+
+ // ⭐ What stays boot-only is the SWALLOW: `resolves` above is the assertion,
+ // and it is the half of the old pin that does NOT invert. Bounding boot was
+ // never a licence to throw here — that trades a silent hang for a failed
+ // 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 () => {
+ driver = makeDriver();
+ await driver.initObjects([WIDGET]);
+ driver.issued.length = 0;
+ driver.warnings.length = 0;
+
  await expect(driver.initObjects([WIDGET])).resolves.toBeUndefined();
- expect(setStatements(driver)).toHaveLength(0);
+
+ // ⭐ The card's whole claim. This warn 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);
+ // Carrying the server's own diagnosis, not a swallowed blank.
+ expect(String(warn!.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/);
  });
 
  it('clears the flush flag after a refusal, so a later boot sync is unaffected', async () => {
@@ -320,6 +393,13 @@ describe('[#9354] deferred-DDL flush — a blocked widening ALTER refuses, loudl
  // `os migrate apply` keeps the stack alive to shut it down; a flag left set
  // by the throw would turn every later widening on this driver into a refusal.
  await expect(driver.initObjects([WIDGET])).resolves.toBeUndefined();
- expect(setStatements(driver)).toHaveLength(0);
+ // ⚠️ This pin guards FLAG HYGIENE, not boot policy — it only ever shared an
+ // assertion with the pin above. It used to read `setStatements → 0`, which
+ // since #9542 says nothing about the flag: a clean boot arms the bound too,
+ // so that count is 2 either way. The observable that still discriminates is
+ // the swallow on the line above (a stuck flag makes this same lock wait
+ // escape `initObjects` as a refusal), and this line keeps it from passing
+ // vacuously by pinning that the widening genuinely ran and genuinely hit it.
+ expect(alterStatements(driver)).toHaveLength(1);
  });
 });

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

@@ -844,7 +844,11 @@ function backendStatementFaultError(object: string, cause: unknown): Error {
 }
 
 /**
- * [#9354] How long the deferred-DDL flush waits for a metadata lock, in seconds.
+ * [#9354] How long a widening ALTER waits for a metadata lock, in seconds.
+ *
+ * Named for the seam it arrived on; since #9542 it governs BOTH callers of
+ * {@link SqlDriver.runWideningAlters} — the deferred-DDL flush and boot
+ * schema-sync.
  *
  * MySQL's own default for `lock_wait_timeout` is **31,536,000 — one year**. A
  * widening `ALTER … MODIFY COLUMN` needs an exclusive metadata lock on the
@@ -877,6 +881,14 @@ function backendStatementFaultError(object: string, cause: unknown): Error {
  * re-run once the blocker is gone — against an unbounded hang as the cost of
  * one that never fires.
  *
+ * # The same number on boot (#9542)
+ *
+ * Boot schema-sync arms this bound too, at the same value rather than a longer
+ * 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.
+ *
  * ⛔ Deliberately NOT configurable, and deliberately NOT retried — the 2026-08-17
  * ruling's explicit minimality. Both wait for measured demand. A knob added now
  * would have to be supported forever on the evidence of one CI stall.
@@ -8095,15 +8107,28 @@ export class SqlDriver implements IDataDriver {
  * the lock behaviour of unrelated runtime work. The restore is best-effort:
  * it must never mask the refusal it runs alongside.
  *
- * Only armed for the flush. On boot this runs the statements exactly as
- * before, through the pool and unbounded, because {@link setDeferredDdl} was
- * never armed and there is no operator waiting on a prompt.
+ * # Armed on BOTH callers; only the flush escapes the swallow (#9542)
+ *
+ * The bound is armed unconditionally, because the year-long default is no
+ * 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,
+ * until the bound reached here, could never fire at all: the ALTER never
+ * returned, so its catch never ran.
+ *
+ * What stays gated on {@link flushDeferredSchemaDdl} is the REFUSAL, and
+ * only it. Boot still swallows: correctness never depends on the widening
+ * having run, and a migration must never take boot down, so throwing here
+ * would trade a silent hang for a failed boot — a worse answer, not the
+ * same one. `this.isMysql` is therefore the only early return left; no other
+ * dialect takes this lock, and `lock_wait_timeout` is MySQL's variable.
  */
  protected async runWideningAlters(
  table: string,
  statements: ReadonlyArray<{ sql: string; bindings: unknown[] }>,
  ): Promise<void> {
- if (!this.flushingDeferredDdl || !this.isMysql) {
+ if (!this.isMysql) {
  for (const s of statements) await this.knex.raw(s.sql, s.bindings as any);
  return;
  }
@@ -8123,7 +8148,11 @@ export class SqlDriver implements IDataDriver {
  try {
  await run(s.sql, s.bindings);
  } catch (err) {
- if (isMysqlLockWaitTimeout(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.
+ if (this.flushingDeferredDdl && isMysqlLockWaitTimeout(err)) {
  throw deferredDdlLockWaitError(table, DEFERRED_DDL_LOCK_WAIT_TIMEOUT_SECONDS, err);
  }
  throw err;