From b7f7e2e64138ad59c5fe154c1fde257836ea59b2 Mon Sep 17 00:00:00 2001 From: Claude Date: Tue, 18 Aug 2026 10:34:19 +0000 Subject: [PATCH] fix(driver-sql): bound the metadata-lock wait on boot schema-sync's MySQL widening ALTER too, keeping boot's swallow (#9542) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit #9354 armed the 120s `lock_wait_timeout` bound only while the deferred-DDL flush was running, so boot schema-sync reached the same widening ALTER through `runWideningAlters`'s early return and inherited MySQL's one-year default. A metadata lock held by another session parked boot there silently, and the widening's own `logger.warn` was unreachable — it is in a `catch`, and the ALTER never returned. The bound is now armed unconditionally; `flushingDeferredDdl` gates only the escape from the swallow. Boot warns and carries on, `os migrate apply` keeps its DATABASE_ERROR/500 refusal. The suite's boot pin is flipped rather than deleted, and the neighbouring flag-hygiene pin swaps to an observable that still discriminates a stuck flag. Co-Authored-By: Claude Opus 5 Claude-Session: https://claude.ai/code/session_017qYPmkKEsfbWY1yVg83p8F --- .changeset/boot-widening-bounded-lock-wait.md | 41 +++++++++ .../sql-driver-deferred-ddl-lock-wait.test.ts | 92 +++++++++++++++++-- packages/drivers/driver-sql/src/sql-driver.ts | 41 +++++++-- 3 files changed, 162 insertions(+), 12 deletions(-) create mode 100644 .changeset/boot-widening-bounded-lock-wait.md diff --git a/.changeset/boot-widening-bounded-lock-wait.md b/.changeset/boot-widening-bounded-lock-wait.md new file mode 100644 index 0000000000..f8a876f721 --- /dev/null +++ b/.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. diff --git a/packages/drivers/driver-sql/src/sql-driver-deferred-ddl-lock-wait.test.ts b/packages/drivers/driver-sql/src/sql-driver-deferred-ddl-lock-wait.test.ts index 8d10ac4ac9..641aa82247 100644 --- a/packages/drivers/driver-sql/src/sql-driver-deferred-ddl-lock-wait.test.ts +++ b/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); }); }); diff --git a/packages/drivers/driver-sql/src/sql-driver.ts b/packages/drivers/driver-sql/src/sql-driver.ts index 2d5603dada..f4b2bb0758 100644 --- a/packages/drivers/driver-sql/src/sql-driver.ts +++ b/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 { - 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;