diff --git a/.changeset/deferred-ddl-bounded-lock-wait.md b/.changeset/deferred-ddl-bounded-lock-wait.md new file mode 100644 index 0000000000..b173e4438e --- /dev/null +++ b/.changeset/deferred-ddl-bounded-lock-wait.md @@ -0,0 +1,49 @@ +--- +"@objectstack/driver-sql": patch +--- + +fix(driver-sql): a blocked `os migrate` now refuses in 120s instead of hanging for a year on a MySQL metadata lock (#9354) + +The deferred-DDL flush widens legacy MySQL `TIMESTAMP` columns to `DATETIME(3)` +and `TIME` to `TIME(3)` with `ALTER TABLE … MODIFY COLUMN`, which needs an +**exclusive metadata lock** on the table. That ALTER ran on a session inheriting +MySQL's default `lock_wait_timeout` — **31,536,000 seconds, one year**. A single +other session holding a lock on the table (a long-running transaction, an open +uncommitted session, a stuck report query) parked the ALTER in +`Waiting for table metadata lock` for that long, and nothing printed. + +An operator running `os migrate apply` against a busy production table met this +as a command that simply hangs — indistinguishable from a crash, with no output +to diagnose from. It was first measured as a CI stall: a sub-second test blew a +5000ms budget with **no error at all**, because the ALTER just sat in a lock wait +until vitest killed the process. + +Two things were wrong, and a bound alone would have fixed neither: + +- **Nothing bounded the wait.** `lock_wait_timeout` had zero occurrences + anywhere in `packages/`. +- **The widening swallows its failures.** That policy is right on boot — a + migration must never take boot down, and correctness never depended on the + widening having run — but on the flush it means `os migrate apply` reports + success for work it did not do. + +The flush now runs its widening ALTERs on **one pinned connection**, bounds +`lock_wait_timeout` to **120 seconds** on that same session, and lets exactly one +condition escape the swallow: a metadata-lock timeout is re-thrown as an ADR-0112 +envelope — `DATABASE_ERROR` / 500, from the existing closed vocabulary — whose +message names the lock wait, the table, the bound it hit, and how to find the +holder. `os migrate apply` prints that message and exits 1. + +The connection pinning is the load-bearing half: `lock_wait_timeout` is a SESSION +variable, so a `SET SESSION` issued through the pool lands on a connection the +ALTER never uses — a no-op that looks exactly like a fix. + +**120 seconds** is chosen as a diagnosis deadline, not a capacity knob: three +orders of magnitude above the milliseconds a normal OLTP transaction holds a +metadata lock (so an ordinary busy table never trips it), and still inside the +window where the operator is watching the command. The widening is idempotent, +so the cost of firing too eagerly is one re-run. + +Unchanged, deliberately: boot schema-sync still runs unbounded and still +swallows; every non-lock-wait failure during the flush keeps the swallow it had. +No retry logic and no configurability — both wait for measured demand. 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 new file mode 100644 index 0000000000..8d10ac4ac9 --- /dev/null +++ b/packages/drivers/driver-sql/src/sql-driver-deferred-ddl-lock-wait.test.ts @@ -0,0 +1,325 @@ +// Copyright (c) 2026 ObjectStack. Licensed under the Apache-2.0 license. + +/** + * #9354 — a blocked `os migrate` must FAIL, not hang. + * + * The deferred-DDL flush widens legacy MySQL `TIMESTAMP`/`TIME` columns with + * `ALTER TABLE … MODIFY COLUMN`, which needs an exclusive metadata lock. The + * session inherited MySQL's default `lock_wait_timeout` — **31,536,000 seconds, + * one year** — so one other transaction holding a lock on the table parked the + * ALTER silently for that long. Measured once as a CI stall (a sub-second test + * blowing a 5000ms budget with no error at all); an operator meets it as + * `os migrate apply` printing nothing, forever, indistinguishable from a crash. + * + * Maintainer ruling, 2026-08-17 (verbatim 「同意」): bound the wait on the + * session performing the widening, and fail loudly with an ADR-0112 envelope + * whose code comes from the closed vocabulary and names the lock wait. No retry + * logic, no configurability. + * + * # What this suite pins, and why it is pinned THIS way + * + * ⭐ The observable is the **refusal**, never "a `SET SESSION` string was + * emitted". A suite asserting only that the statement went out passes in full + * while the operator still hangs — the bound could land on the wrong connection, + * or the error could still be swallowed by the widening's catch, and every such + * assertion stays green. So the assertions below are the caller-visible ones: + * the flush REJECTS, with `code` and `status`, and the message names the wait. + * + * The fakes are deliberately shallow. Only two things are replaced — the + * connection (`withPinnedSession`) and the `information_schema` probe that would + * need a real MySQL — so the bounding, the 1205 recognition, the envelope and + * the escape from the swallowing catch all execute for real. `isMysql` is true + * only INSIDE the widening call, so the rest of the flush runs as the genuine + * SQLite path it is: a real table, really created, really flushed. + */ + +import { describe, it, expect, afterEach } from 'vitest'; +import { SqlDriver } from './sql-driver.js'; + +const WIDGET = { + name: 'widgets_9354', + fields: { sku: { type: 'text' }, at: { type: 'datetime' } }, +}; + +/** One statement, tagged with the pinned session it was issued on. */ +interface Issued { session: number; sql: string; bindings: unknown[] } + +/** + * 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 + * goes blind here, and blind means back to the year-long hang. + */ +function lockWaitTimeoutError(): Error { + const driverErr = Object.assign( + new Error('Lock wait timeout exceeded; try restarting transaction'), + { errno: 1205, code: 'ER_LOCK_WAIT_TIMEOUT', sqlState: 'HY000' }, + ); + const wrapped = new Error( + 'alter table `widgets_9354` modify column … - Lock wait timeout exceeded', + ); + // Attached by hand rather than through `new Error(msg, { cause })`: that + // overload needs the ES2022 lib and this package targets ES2020, so the + // constructor form does not type-check here. `defineProperty` is the shape the + // driver's own refusals in `sql-driver.ts` use, and it reproduces what the + // constructor produces at runtime exactly — including NON-enumerability, which + // an `Object.assign` spelling would silently get wrong and make this fixture a + // weaker stand-in for the real knex re-throw than it looks. + Object.defineProperty(wrapped, 'cause', { + value: driverErr, + enumerable: false, + writable: true, + configurable: true, + }); + return wrapped; +} + +/** The server's default, so the restore has a prior value to put back. */ +const MYSQL_DEFAULT_LOCK_WAIT = 31_536_000; + +class FakeMysqlDriver extends SqlDriver { + /** True only while a widening call is in flight — see the file header. */ + private pretendMysql = false; + private sessions = 0; + + issued: Issued[] = []; + /** What the ALTER should do; `undefined` = succeed. */ + alterFails: (() => Error) | undefined = lockWaitTimeoutError; + legacyDatetimeColumns: Array<{ name: string; nullable: boolean }> = [ + { name: 'at', nullable: true }, + ]; + legacyTimeColumns: Array<{ name: string; nullable: boolean }> = []; + + protected override get isMysql(): boolean { + return this.pretendMysql; + } + + private async asMysql(fn: () => Promise): Promise { + this.pretendMysql = true; + try { return await fn(); } finally { this.pretendMysql = false; } + } + + protected override async migrateMysqlDatetimeColumns( + table: string, fields: Record, + ): Promise { + return this.asMysql(() => super.migrateMysqlDatetimeColumns(table, fields)); + } + + protected override async migrateMysqlTimeColumns( + table: string, fields: Record, + ): Promise { + return this.asMysql(() => super.migrateMysqlTimeColumns(table, fields)); + } + + /** The `information_schema` lookups, which need a real MySQL. */ + protected override async legacyMysqlTimestampColumns(): Promise> { + return this.legacyDatetimeColumns; + } + + protected override async legacyMysqlTimeColumns(): Promise> { + return this.legacyTimeColumns; + } + + /** + * A pinned connection, faked. Every statement records the session number it + * rode on, which is the ONLY way to prove the `SET SESSION` and the ALTER + * share a connection — the defect a pooled `knex.raw` would reintroduce + * invisibly. + */ + protected override async withPinnedSession( + fn: (run: (sql: string, bindings?: unknown[]) => Promise) => Promise, + ): Promise { + const session = ++this.sessions; + return await fn(async (sql, bindings) => { + this.issued.push({ session, sql, bindings: bindings ?? [] }); + if (/^select @@session\.lock_wait_timeout/i.test(sql)) { + return [[{ v: MYSQL_DEFAULT_LOCK_WAIT }]]; + } + if (/^alter table/i.test(sql) && this.alterFails) throw this.alterFails(); + return []; + }); + } +} + +function makeDriver(): FakeMysqlDriver { + return new FakeMysqlDriver({ + 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 { + await driver.initObjects([WIDGET]); // table now EXISTS — widening applies + driver.issued.length = 0; // drop anything the create path issued + driver.setDeferredDdl(true); + await driver.initObjects([WIDGET]); +} + +async function caught(run: () => Promise): Promise { + try { + await run(); + } catch (err) { + return err; + } + return expect.fail('expected the flush to refuse, but it resolved'); +} + +const setStatements = (d: FakeMysqlDriver) => + d.issued.filter((s) => /^set session lock_wait_timeout/i.test(s.sql)); +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', () => { + let driver: FakeMysqlDriver; + + afterEach(async () => { + await driver.disconnect(); + }); + + // ─────────────────────────────────────────────────────────────── + // THE RULING — the refusal itself, as the operator meets it + // ─────────────────────────────────────────────────────────────── + + it('rejects with the ADR-0112 envelope instead of hanging', async () => { + driver = makeDriver(); + await armedFlush(driver); + + const err = await caught(() => driver.flushDeferredSchemaDdl()); + + // The closed-vocabulary pair. `toThrow()` alone would be no pin at all here: + // the pre-fix driver swallowed this error entirely, and a driver that threw + // a bare `Error` would satisfy a throw-only assertion while telling the + // operator, and every programmatic consumer, nothing. + expect(err.code).toBe('DATABASE_ERROR'); + expect(err.status).toBe(500); + }); + + it("names the lock wait, the table and the bound — `os migrate` prints only the message", async () => { + driver = makeDriver(); + await armedFlush(driver); + + const err = await caught(() => driver.flushDeferredSchemaDdl()); + + // `migrate/apply.ts` prints `error.message` and exits 1; `code`/`status` + // never reach the terminal. So the diagnosis has to live in this sentence. + expect(err.message).toMatch(/lock_wait_timeout/); + expect(err.message).toMatch(/metadata lock/i); + expect(err.message).toContain(WIDGET.name); + expect(err.message).toContain('120s'); + // It must also say what to DO — the ruling's whole point is an actionable + // refusal rather than a diagnosable-in-principle one. + expect(err.message).toMatch(/PROCESSLIST|metadata_locks/); + // And that nothing was half-applied, so a re-run is obviously safe. + expect(err.message).toMatch(/No schema change was made/i); + }); + + it('keeps the server error as `cause`, without putting it on the wire', async () => { + driver = makeDriver(); + await armedFlush(driver); + + const err = await caught(() => driver.flushDeferredSchemaDdl()); + + expect((err.cause as any)?.cause?.errno).toBe(1205); + // Non-enumerable, like every sibling refusal in this file: readable by + // cause-following predicates, invisible to `JSON.stringify(err)`. + expect(Object.keys(err)).not.toContain('cause'); + }); + + // ─────────────────────────────────────────────────────────────── + // THE BOUND — armed, minutes-scale, and on the ALTER's OWN session + // ─────────────────────────────────────────────────────────────── + + it('arms the bound on the SAME pinned session as the ALTER', async () => { + driver = makeDriver(); + await armedFlush(driver); + await caught(() => driver.flushDeferredSchemaDdl()); + + const set = setStatements(driver); + const alter = alterStatements(driver); + expect(set.length).toBeGreaterThan(0); + expect(alter).toHaveLength(1); + + // ⭐ The assertion the whole seam exists for. `SET SESSION` is per-connection: + // issued through the pool it lands on a connection the ALTER never uses, and + // the migration hangs exactly as before while every other pin here still + // passes. Same session id, and the bound set BEFORE the ALTER. + expect(set[0].session).toBe(alter[0].session); + expect(driver.issued.indexOf(set[0])).toBeLessThan(driver.issued.indexOf(alter[0])); + }); + + it('bounds the wait at 120 seconds, not MySQL\'s one-year default', async () => { + driver = makeDriver(); + await armedFlush(driver); + await caught(() => driver.flushDeferredSchemaDdl()); + + expect(setStatements(driver)[0].bindings).toEqual([120]); + expect(setStatements(driver)[0].bindings).not.toEqual([MYSQL_DEFAULT_LOCK_WAIT]); + }); + + it('restores the prior bound, so the pooled connection carries nothing away', async () => { + driver = makeDriver(); + driver.alterFails = undefined; // the ALTER succeeds this time + await armedFlush(driver); + await driver.flushDeferredSchemaDdl(); + + const set = setStatements(driver); + expect(set).toHaveLength(2); + expect(set[1].bindings).toEqual([MYSQL_DEFAULT_LOCK_WAIT]); + // Restored on the same session it was set on — a restore elsewhere would + // leave the bound live on the connection going back to the pool. + expect(set[1].session).toBe(set[0].session); + }); + + it('refuses the `Field.time` widening the same way — it takes the same lock', async () => { + driver = makeDriver(); + driver.legacyDatetimeColumns = []; + driver.legacyTimeColumns = [{ name: 'at', nullable: true }]; + await armedFlush(driver); + + const err = await caught(() => driver.flushDeferredSchemaDdl()); + + expect(err.code).toBe('DATABASE_ERROR'); + expect(err.status).toBe(500); + expect(alterStatements(driver)[0].sql).toMatch(/time\(3\)/); + }); + + // ─────────────────────────────────────────────────────────────── + // THE BLAST RADIUS — everything else keeps the behaviour it had + // ─────────────────────────────────────────────────────────────── + + it('still swallows a NON-lock-wait failure during the flush', async () => { + driver = makeDriver(); + driver.alterFails = () => Object.assign(new Error('Unknown column'), { errno: 1054 }); + await armedFlush(driver); + + // The swallow is deliberate and documented: correctness never depended on + // the widening having run. This ruling escapes exactly ONE condition, and a + // change that let every failure through would be a different decision. + await expect(driver.flushDeferredSchemaDdl()).resolves.toBeDefined(); + }); + + it('leaves BOOT sync unbounded and swallowing — it 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. + await expect(driver.initObjects([WIDGET])).resolves.toBeUndefined(); + expect(setStatements(driver)).toHaveLength(0); + }); + + it('clears the flush flag after a refusal, so a later boot sync is unaffected', async () => { + driver = makeDriver(); + await armedFlush(driver); + await caught(() => driver.flushDeferredSchemaDdl()); + driver.issued.length = 0; + + // `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); + }); +}); diff --git a/packages/drivers/driver-sql/src/sql-driver.ts b/packages/drivers/driver-sql/src/sql-driver.ts index 61493c3919..2d5603dada 100644 --- a/packages/drivers/driver-sql/src/sql-driver.ts +++ b/packages/drivers/driver-sql/src/sql-driver.ts @@ -843,6 +843,138 @@ function backendStatementFaultError(object: string, cause: unknown): Error { return err; } +/** + * [#9354] How long the deferred-DDL flush waits for a metadata lock, in seconds. + * + * 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 + * table, so a single long-running transaction elsewhere (an open REPEATABLE + * READ snapshot, a forgotten `BEGIN` in a psql-style shell, a stuck report + * query) parks the ALTER in `Waiting for table metadata lock` for that long. + * Nothing prints. `os migrate apply` looks like it hung, and no operator can + * tell that from a crash — which is the condition this bound exists to end. + * + * # Why 120 seconds + * + * The bound is a diagnosis deadline, not a capacity knob: its job is to end the + * silence, not to decide how patient a migration may be. So it is chosen as the + * shortest wait that still clears the legitimate blockers, and no longer. + * + * - **Above the noise.** Normal OLTP transactions on a table being migrated + * hold their metadata lock for milliseconds. Two minutes is three orders of + * magnitude above that, so an ordinary busy table never trips it — the bound + * does not convert a working migration into a failing one. + * - **Below an operator's patience.** A command that has printed nothing for + * two minutes is still within the window where the operator is watching it. + * At ten minutes they have already reached for `SHOW PROCESSLIST` or killed + * it, so a bound that fires later than that arrives after the diagnosis it + * was supposed to provide. + * - **Minutes-scale, per the ruling**, and deliberately at the low end of it: + * failing fast is cheap here. `os migrate apply` is re-runnable and the + * widening is idempotent (`migrateMysqlDatetimeColumns` re-reads + * `information_schema` and does nothing when the column is already + * `DATETIME(3)`), so the cost of a bound that fires too eagerly is one + * re-run once the blocker is gone — against an unbounded hang as the cost of + * one that never fires. + * + * ⛔ 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. + */ +const DEFERRED_DDL_LOCK_WAIT_TIMEOUT_SECONDS = 120; + +/** + * [#9354] MySQL's lock-wait timeout, as it arrives through mysql2 and knex. + * + * `ER_LOCK_WAIT_TIMEOUT` (**errno 1205**) is what BOTH lock waits raise — the + * InnoDB row-lock timeout (`innodb_lock_wait_timeout`) and the metadata-lock + * timeout (`lock_wait_timeout`) this bound arms. The ALTER path can only be + * blocked by the second, so on this seam 1205 means the metadata lock. + * + * Both spellings are checked because the two layers carry different ones: + * mysql2 sets a string `code` (`'ER_LOCK_WAIT_TIMEOUT'`) alongside the numeric + * `errno`, and a wrapper that rebuilds the error commonly keeps one and drops + * the other. `cause` is followed because knex re-throws the driver error with + * the original attached — the same cause-chaining + * {@link backendStatementFaultError} relies on, and the reason a recognizer + * that inspected only the top-level error would go quietly blind. + * + * ⛔ Message text is NOT sniffed. MySQL and MariaDB word this differently and + * both translate it, so a prose match is a recognizer that fails in another + * locale — silently, back to the year-long hang. + */ +function isMysqlLockWaitTimeout(err: unknown, depth = 0): boolean { + if (!err || typeof err !== 'object' || depth > 4) return false; + const e = err as { errno?: unknown; code?: unknown; cause?: unknown }; + if (Number(e.errno) === 1205) return true; + if (e.code === 'ER_LOCK_WAIT_TIMEOUT') return true; + return isMysqlLockWaitTimeout(e.cause, depth + 1); +} + +/** [#9354] Marks the enveloped refusal below, so the flush's own catch can tell + * it from every other failure without re-running the recognizer on a wrapper. */ +const LOCK_WAIT_REFUSAL = Symbol.for('objectstack.driver-sql.deferredDdlLockWaitRefusal'); + +/** [#9354] True only for the refusal {@link deferredDdlLockWaitError} built. */ +function isDeferredDdlLockWaitRefusal(err: unknown): boolean { + return Boolean(err && typeof err === 'object' && (err as Record)[LOCK_WAIT_REFUSAL]); +} + +/** + * [#9354] The refusal a blocked deferred-DDL widening ALTER fails with. + * + * # Why this is thrown at all, when every sibling here is swallowed + * + * {@link SqlDriver.migrateMysqlDatetimeColumns} logs and swallows its failures + * on purpose: correctness never depends on the widening having run, and a + * migration must not take boot down. That policy is right for boot and wrong + * for the flush. `os migrate apply` is a command an operator RAN, whose whole + * contract is to report what it did; a swallowed lock wait there prints + * "Applied 0 change(s)" and reports success while the widening silently did not + * happen. So the escape is scoped exactly to this condition on exactly that + * path — every other failure keeps the swallow it has today. + * + * # `DATABASE_ERROR` / 500 + * + * The 2026-08-17 ruling requires a code from the CLOSED standard vocabulary + * (ADR-0112), from the `DATABASE_ERROR` family, naming the lock wait. That is + * the catalog's own "database operation failed", and it is the same pair + * {@link backendStatementFaultError} answers with one refusal over — so this + * mints nothing and adds no code to the catalog. 500 rather than 4xx: nothing + * about the operator's request is at fault. The blocker is another session. + * + * # The message carries the diagnosis, because it is the only thing shown + * + * `os migrate apply` prints `error.message` and exits 1 — `code` and `status` + * reach programmatic consumers, but the operator reads this sentence and + * nothing else. So it names the lock wait, the table, the bound it hit, and the + * one thing that resolves it. The table name is the operator's own schema + * (the line beside it already logs it), so naming it discloses nothing new — + * and unlike the query-refusal envelope there is no caller-bound literal here + * to leak: the statement's only bindings are the table and column. + */ +function deferredDdlLockWaitError(table: string, seconds: number, cause: unknown): Error { + const err = new Error( + `Migration of table '${table}' timed out after ${seconds}s waiting for a MySQL metadata ` + + 'lock (lock_wait_timeout). Another session is holding a lock on the table — a long-running ' + + 'transaction or an open, uncommitted session. No schema change was made. Identify the ' + + "holder with `SHOW PROCESSLIST` or by querying `performance_schema.metadata_locks`, end " + + 'it, then re-run `os migrate apply` — the widening is idempotent, so re-running is safe.', + ) as Error & { code?: string; status?: number }; + err.code = StandardErrorCode.enum.DATABASE_ERROR; + err.status = 500; + Object.defineProperty(err, LOCK_WAIT_REFUSAL, { value: true, enumerable: false }); + // Non-enumerable, like every sibling refusal in this file: the carrier must be + // readable by cause-following predicates and invisible to `JSON.stringify`. + Object.defineProperty(err, 'cause', { + value: cause, + enumerable: false, + writable: true, + configurable: true, + }); + return err; +} + /** * [#7929] The full, operand-naming text of a refusal whose caller-visible * message was redacted — carried on the Error under a SYMBOL key. @@ -4006,6 +4138,19 @@ export class SqlDriver implements IDataDriver { /** Object defs `initObjects` registered but did not physically sync while {@link deferredDdl}. */ protected deferredSchemaObjects = new Map }>(); + /** + * [#9354] True only while {@link flushDeferredSchemaDdl} is performing the + * deferred work — the operator-initiated `os migrate apply` path. + * + * The MySQL widening ALTERs are reached from BOTH boot schema-sync and the + * flush, through the same `initObjects` line, and the two want opposite + * failure policies: boot must never be taken down by a migration, while a + * command the operator ran must never report success for work it did not do. + * This flag is what tells them apart at the point the policy is applied, so + * neither path needs its own copy of the widening. + */ + private flushingDeferredDdl = false; + /** Backing field for {@link sqliteOpenedEmptyInMemory} (#6743). */ private openedEmptyInMemory = false; @@ -7926,6 +8071,91 @@ export class SqlDriver implements IDataDriver { * keeps the range and precision limits. Correctness must not depend on a * migration having run, and a migration must never take boot down. */ + /** + * [#9354] Run the deferred flush's MySQL widening ALTERs under a bounded + * metadata-lock wait, on ONE pinned connection. + * + * # Why the connection has to be pinned + * + * `lock_wait_timeout` is a SESSION variable, and `this.knex.raw` takes + * whatever connection the pool hands it. Issuing `SET SESSION …` through the + * pool and the ALTER through the pool sets the bound on one connection and + * runs the ALTER on another — a no-op that looks exactly like a fix, and that + * a test can pass against by asserting the `SET` was merely emitted. A knex + * transaction is this file's existing single-connection seam (it is how every + * multi-statement unit here already holds one connection), so both statements + * provably ride the same session. MySQL implicitly commits on DDL, which + * costs nothing here: the transaction is being used for connection affinity, + * not atomicity — an ALTER was never rollback-able on MySQL to begin with. + * + * # The prior value is restored + * + * The connection goes back to the pool afterwards and would otherwise carry + * this bound into every later statement on it — a migration quietly changing + * 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. + */ + protected async runWideningAlters( + table: string, + statements: ReadonlyArray<{ sql: string; bindings: unknown[] }>, + ): Promise { + if (!this.flushingDeferredDdl || !this.isMysql) { + for (const s of statements) await this.knex.raw(s.sql, s.bindings as any); + return; + } + await this.withPinnedSession(async (run) => { + let prior: unknown; + try { + const res: any = await run('select @@session.lock_wait_timeout as v'); + const rows = Array.isArray(res?.[0]) ? res[0] : (res?.rows ?? res ?? []); + prior = (rows?.[0] as any)?.v; + } catch { + // Unreadable prior value only costs the restore below; it must not stop + // the bound from being armed, which is the point of the whole seam. + } + await run('set session lock_wait_timeout = ?', [DEFERRED_DDL_LOCK_WAIT_TIMEOUT_SECONDS]); + try { + for (const s of statements) { + try { + await run(s.sql, s.bindings); + } catch (err) { + if (isMysqlLockWaitTimeout(err)) { + throw deferredDdlLockWaitError(table, DEFERRED_DDL_LOCK_WAIT_TIMEOUT_SECONDS, err); + } + throw err; + } + } + } finally { + if (prior !== undefined && prior !== null) { + try { + await run('set session lock_wait_timeout = ?', [Number(prior)]); + } catch { + // Best-effort: never mask the refusal being thrown past this block. + } + } + } + }); + } + + /** + * [#9354] Hold one connection for the duration of `fn`, and give it a runner + * that provably issues every statement on that connection. + * + * Its own method so the connection acquisition can be replaced in a test + * without stubbing any of the bounding, recognition or refusal logic above — + * the parts that must be exercised for real. + */ + protected async withPinnedSession( + fn: (run: (sql: string, bindings?: unknown[]) => Promise) => Promise, + ): Promise { + return await this.knex.transaction(async (trx) => + fn((sql, bindings) => trx.raw(sql, (bindings ?? []) as any))); + } + protected async migrateMysqlDatetimeColumns( table: string, fields: Record, @@ -7935,23 +8165,31 @@ export class SqlDriver implements IDataDriver { const legacy = await this.legacyMysqlTimestampColumns(table, fields); if (legacy.length === 0) return; - for (const col of legacy) { + // #9354: built as a list, then run as one unit, so the whole widening of a + // table shares the ONE pinned session the bounded lock wait needs. + const statements = legacy.map((col) => { // The default is re-stated because MySQL drops a column's DEFAULT when // MODIFY does not repeat it, and an audit column without // `CURRENT_TIMESTAMP(3)` would start inserting NULL. const isAudit = (AUDIT_TIMESTAMP_COLUMNS as readonly string[]).includes(col.name); const nullClause = col.nullable ? 'null' : 'not null'; const defaultClause = isAudit ? ' default current_timestamp(3)' : ''; - await this.knex.raw( - `alter table ?? modify column ?? datetime(3) ${nullClause}${defaultClause}`, - [table, col.name], - ); - } + return { + sql: `alter table ?? modify column ?? datetime(3) ${nullClause}${defaultClause}`, + bindings: [table, col.name] as unknown[], + }; + }); + await this.runWideningAlters(table, statements); this.logger.info?.( `[sql-driver] widened MySQL TIMESTAMP → DATETIME(3) (#3942) on ${table}`, { columns: legacy.map((c) => c.name) }, ); } catch (err) { + // #9354: the ONE failure that must not be swallowed. Everything else on + // this path keeps the policy the doc comment above describes; a metadata + // 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`, @@ -8015,23 +8253,31 @@ export class SqlDriver implements IDataDriver { const legacy = await this.legacyMysqlTimeColumns(table, fields); if (legacy.length === 0) return; - for (const col of legacy) { + // #9354: the datetime twin's seam, for the same reason — this ALTER takes + // the same exclusive metadata lock and blocks on the same holder. + const statements = legacy.map((col) => { // MODIFY drops a default it does not restate. A `defaultValue: 'NOW()'` // column gets the canonical UTC expression default (`nowColumnDefault`); // its legacy `current_timestamp()` default read the SESSION's zone, so // dropping-and-replacing it is a fix, not collateral. const isNowDefault = isNowDefaultValue(fields[col.name]?.defaultValue); const defaultClause = isNowDefault ? ' default (cast(utc_timestamp(3) as time(3)))' : ''; - await this.knex.raw( - `alter table ?? modify column ?? time(3) ${col.nullable ? 'null' : 'not null'}${defaultClause}`, - [table, col.name], - ); - } + return { + sql: `alter table ?? modify column ?? time(3) ${col.nullable ? 'null' : 'not null'}${defaultClause}`, + bindings: [table, col.name] as unknown[], + }; + }); + await this.runWideningAlters(table, statements); this.logger.info?.( `[sql-driver] widened MySQL TIME → TIME(3) (#3994) on ${table}`, { columns: legacy.map((c) => c.name) }, ); } catch (err) { + // #9354: the ONE failure that must not be swallowed. Everything else on + // this path keeps the policy the doc comment above describes; a metadata + // 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`, @@ -8248,7 +8494,17 @@ export class SqlDriver implements IDataDriver { // Re-entering initObjects re-registers the same metadata (idempotent) and // this time takes the DDL path, so create/alter/index/rotation handling // stays in exactly one place. - await this.initObjects(pending); + // + // #9354: armed across that re-entry, and cleared in a `finally` so a refusal + // thrown out of the widening cannot leave the flag set on a driver the + // caller goes on using (`os migrate apply` keeps the stack alive to shut it + // down). It is the only thing distinguishing this path from boot sync. + this.flushingDeferredDdl = true; + try { + await this.initObjects(pending); + } finally { + this.flushingDeferredDdl = false; + } return performed; }