diff --git a/docs/ops/deploy.md b/docs/ops/deploy.md index d4a828b9e..c87d7926b 100644 --- a/docs/ops/deploy.md +++ b/docs/ops/deploy.md @@ -68,6 +68,11 @@ Database error code: 55P03 HealthLog: migration 0412_measurement_hot_updates timed out waiting for a lock (55P03) and changed nothing; marking it rolled back and retrying in 15s (retry 1 of 5). ``` +A marked migration that loses a deadlock against an app transaction +(`Database error code: 40P01`) is in the same state, its block rolled back +whole, and is handled the same way; the entrypoint's line then says +`was cancelled in a deadlock (40P01)`. + What happens on its own: such a migration is written so that a timed-out attempt changes nothing, and it says so in its file (`-- @retry-on-lock-timeout`). The entrypoint then marks that one migration diff --git a/prisma/migrations/0415_foreign_key_and_prefix_indexes/migration.sql b/prisma/migrations/0415_foreign_key_and_prefix_indexes/migration.sql index 1844f11a7..eb7fb4676 100644 --- a/prisma/migrations/0415_foreign_key_and_prefix_indexes/migration.sql +++ b/prisma/migrations/0415_foreign_key_and_prefix_indexes/migration.sql @@ -20,13 +20,19 @@ -- -- Lock wait. `CREATE INDEX` takes SHARE on its table (reads go on, writes -- wait while it builds; every table here is small, so the build is quick) --- and `DROP INDEX` takes ACCESS EXCLUSIVE for the instant the catalog --- changes. `CREATE INDEX CONCURRENTLY` cannot share a migration file with --- any other statement (0416), so the whole set runs in one `DO` block: one --- statement that commits or rolls back whole, with the lock wait bounded at --- five seconds so a long reader cannot queue the tables' writes behind the --- migration. Every statement is `IF [NOT] EXISTS`, so a lock timeout leaves --- the file safe to apply again, which the marker declares +-- and `DROP INDEX` takes ACCESS EXCLUSIVE. `CREATE INDEX CONCURRENTLY` +-- cannot share a migration file with any other statement, so the whole set +-- runs in one `DO` block: one statement that commits or rolls back whole, +-- with each lock wait bounded at five seconds so a long reader cannot queue +-- the tables' writes behind the migration. Inside the block every lock is +-- held until it commits, not just while its statement runs: the SHARE locks +-- of the builds stay through the drops, and the drops come last so their +-- ACCESS EXCLUSIVE locks are held only for the rest of the block. An app +-- transaction that takes two of these tables in the other order can +-- therefore deadlock with it; Postgres cancels one side, and when that is the +-- migration its block has rolled back whole, as on a lock timeout. Every +-- statement is `IF [NOT] EXISTS`, so either failure leaves the file safe to +-- apply again, which the marker declares and the boot acts on for both -- (docs/ops/deploy.md, "A migration that timed out on a lock"). -- -- @retry-on-lock-timeout diff --git a/scripts/__tests__/migrate-deploy.test.ts b/scripts/__tests__/migrate-deploy.test.ts index 46b7b7915..f1e776340 100644 --- a/scripts/__tests__/migrate-deploy.test.ts +++ b/scripts/__tests__/migrate-deploy.test.ts @@ -47,6 +47,11 @@ const P3018_UNIQUE = P3018_LOCK.replace("55P03", "23505").replace( 'duplicate key value violates unique constraint "x"', ); +const P3018_DEADLOCK = P3018_LOCK.replace("55P03", "40P01").replace( + "canceling statement due to lock timeout", + "deadlock detected", +); + const P3009 = `Error: P3009 migrate found failed migrations in the target database, new migrations will not be applied. Read more about how to resolve migration issues in a production database: https://pris.ly/d/migrate-resolve @@ -78,7 +83,11 @@ describe("which failure is retried", () => { failedRows: null, readMigration: reader(MARKED), }), - ).toEqual({ retry: true, migration: "0412_measurement_hot_updates" }); + ).toEqual({ + retry: true, + migration: "0412_measurement_hot_updates", + code: "55P03", + }); }); it("does not retry a lock timeout of an unmarked migration", () => { @@ -93,6 +102,31 @@ describe("which failure is retried", () => { }); }); + it("retries a deadlock of a marked migration, which rolled back whole", () => { + expect(lockTimeoutInReport(P3018_DEADLOCK)).toBe( + "0412_measurement_hot_updates", + ); + expect( + decideLockRetry({ + output: P3018_DEADLOCK, + failedRows: null, + readMigration: reader(MARKED), + }), + ).toEqual({ + retry: true, + migration: "0412_measurement_hot_updates", + code: "40P01", + }); + // Unmarked, a deadlock stays fatal like a lock timeout. + expect( + decideLockRetry({ + output: P3018_DEADLOCK, + failedRows: null, + readMigration: reader(UNMARKED), + }).retry, + ).toBe(false); + }); + it("does not retry any other database error", () => { expect( decideLockRetry({ @@ -123,7 +157,11 @@ describe("which failure is retried", () => { failedRows, readMigration: reader(MARKED), }), - ).toEqual({ retry: true, migration: "0412_measurement_hot_updates" }); + ).toEqual({ + retry: true, + migration: "0412_measurement_hot_updates", + code: "55P03", + }); // A stored failure of another kind stays fatal. expect( decideLockRetry({ @@ -295,6 +333,24 @@ process.exit(0); expect(result.stdout).toContain("timed out waiting for a lock (55P03)"); }); + it("does the same for a deadlock, and names it", () => { + const { run, calls } = setup( + [ + [1, P3018_DEADLOCK], + [0, "All migrations have been successfully applied."], + ], + MARKED, + ); + const result = run(); + expect(result.status).toBe(0); + expect(calls()).toEqual([ + "migrate deploy --schema x", + "migrate resolve --rolled-back 0412_measurement_hot_updates --schema x", + "migrate deploy --schema x", + ]); + expect(result.stdout).toContain("was cancelled in a deadlock (40P01)"); + }); + it("gives up after the last delay with Prisma's exit code", () => { const { run, calls } = setup( [ diff --git a/scripts/migrate-deploy.mjs b/scripts/migrate-deploy.mjs index 4f06202c2..d6f9f8973 100644 --- a/scripts/migrate-deploy.mjs +++ b/scripts/migrate-deploy.mjs @@ -21,9 +21,15 @@ * back whole. `src/__tests__/migration-lock-timeout-guard.test.ts` holds the * migrations to that. * - * So: on a 55P03 failure of a migration carrying the marker, mark that one - * migration rolled back and run `migrate deploy` again after a backoff (15, - * 30, 60, 120, 240 seconds). Any other failure, a lock timeout of a migration + * A deadlock (40P01) is the same failure seen from the other side: a marked + * migration's `DO` block holds the locks it took until it commits, and an app + * transaction that took two of the same tables in the other order makes + * Postgres cancel one of the two. When the migration is the one cancelled, + * its block rolled back whole, exactly as on a lock timeout. + * + * So: on a 55P03 or 40P01 failure of a migration carrying the marker, mark + * that one migration rolled back and run `migrate deploy` again after a + * backoff (15, 30, 60, 120, 240 seconds). Any other failure, a lock timeout of a migration * without the marker, or a fifth lock timeout in a row, ends the boot with * Prisma's exit code exactly as before. The failure is read from Prisma's * own report (`Migration name:` and `Database error code:`), or, on a boot @@ -58,20 +64,27 @@ const DEFAULT_RETRY_DELAYS_S = [15, 30, 60, 120, 240]; /** The line a migration carries when a lock-timeout retry is safe for it. */ export const RETRY_MARKER = /^--\s*@retry-on-lock-timeout\s*$/m; -const LOCK_TIMEOUT = "55P03"; +/** Lock timeout and deadlock: both leave a marked migration unapplied. */ +const LOCK_FAILURES = new Set(["55P03", "40P01"]); const TIME_ZONE_OPTION = "-c TimeZone=UTC"; const MIGRATION_NAME = /^[A-Za-z0-9_]+$/; +/** The SQLSTATE a P3018 report gives, or null. */ +export function errorCodeInReport(text) { + if (typeof text !== "string") return null; + return /^Database error code: (\S+)\s*$/m.exec(text)?.[1] ?? null; +} + /** - * The migration a P3018 report says failed on a lock timeout, or null. - * Prisma prints `Migration name: ` and `Database error code: ` - * for a migration that failed to apply. + * The migration a P3018 report says failed on a lock (a lock timeout or a + * deadlock), or null. Prisma prints `Migration name: ` and + * `Database error code: ` for a migration that failed to apply. */ export function lockTimeoutInReport(text) { if (typeof text !== "string") return null; const name = /^Migration name: (\S+)\s*$/m.exec(text)?.[1]; - const code = /^Database error code: (\S+)\s*$/m.exec(text)?.[1]; - return name && code === LOCK_TIMEOUT ? name : null; + const code = errorCodeInReport(text); + return name && code !== null && LOCK_FAILURES.has(code) ? name : null; } /** Whether Prisma refused to start because a failed migration is on record. */ @@ -89,14 +102,16 @@ function isFailedMigrationOnRecord(output) { * when they were not read * @param {(name: string) => string | null} input.readMigration * the migration's SQL, or null when the image does not ship it - * @returns {{ retry: true, migration: string } | { retry: false, reason: string }} + * @returns {{ retry: true, migration: string, code: string } | { retry: false, reason: string }} */ export function decideLockRetry({ output, failedRows, readMigration }) { let migration = lockTimeoutInReport(output); + let code = migration ? errorCodeInReport(output) : null; if (!migration && isFailedMigrationOnRecord(output) && failedRows) { // More than one failed row is not a state this boot can reason about. if (failedRows.length === 1) { migration = lockTimeoutInReport(failedRows[0].logs); + code = migration ? errorCodeInReport(failedRows[0].logs) : null; } } if (!migration) { @@ -115,7 +130,7 @@ export function decideLockRetry({ output, failedRows, readMigration }) { reason: `${migration} timed out on a lock but is not marked safe to re-run`, }; } - return { retry: true, migration }; + return { retry: true, migration, code }; } /** The backoff schedule, from the environment or the default. */ @@ -272,9 +287,13 @@ async function main({ return deploy.code; } const delay = delays[attempt]; + const cause = + decision.code === "40P01" + ? "was cancelled in a deadlock (40P01)" + : "timed out waiting for a lock (55P03)"; console.log( - `HealthLog: migration ${decision.migration} timed out waiting for a lock ` + - `(55P03) and changed nothing; marking it rolled back and retrying in ` + + `HealthLog: migration ${decision.migration} ${cause} ` + + `and changed nothing; marking it rolled back and retrying in ` + `${delay}s (retry ${attempt + 1} of ${delays.length}).`, ); const resolve = await runPrisma(cli, [