HealthLog/scripts/migrate-deploy.mjs

/**
 * `prisma migrate deploy` for the container boot, with one narrow retry: a
 * migration that gave up waiting for a lock.
 *
 * Run by `docker-entrypoint.sh` as `node scripts/migrate-deploy.mjs`.
 *
 * A migration that bounds its lock wait (`lock_timeout`) fails with SQLSTATE
 * 55P03 when something holds the table longer, typically an autovacuum that
 * is preventing wraparound and does not step aside. Prisma then records the
 * attempt as failed, and every later `migrate deploy` stops at P3009 until an
 * operator runs `prisma migrate resolve --rolled-back`: under a restart
 * policy that is a container that never comes up.
 *
 * `migrate deploy` does not wrap a migration file in a transaction, so a
 * failed file is not necessarily rolled back: statements before the one that
 * failed stay applied. Marking such an attempt rolled back and running it
 * again is only safe when the file was written for it. A migration declares
 * that with a `-- @retry-on-lock-timeout` line, which its author adds only
 * when every statement before the lock-taking one is harmless to repeat and
 * the lock-taking statements form one statement (a `DO` block) that rolls
 * back whole. `src/__tests__/migration-lock-timeout-guard.test.ts` holds the
 * migrations to that.
 *
 * 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
 * after a failed one (P3009), from the `logs` Prisma stored on the failed
 * row in `_prisma_migrations`.
 *
 * Every Prisma call runs with its session pinned to UTC, the way the app's
 * own connections are (`src/lib/db-session.ts`). Almost every `DateTime`
 * column is `timestamp` without a time zone and holds UTC, and Postgres
 * converts between that and `timestamptz` / `now()` through the session time
 * zone. A migration that mixes the two (0372 does) therefore wrote hours-off
 * values on a database whose default zone is not UTC. Prisma ignores `PGTZ`,
 * so the pin rides the connection URL as the libpq `options` parameter, which
 * Prisma passes to the server. `DATABASE_SESSION_OPTIONS_DISABLED` (a pooler
 * that refuses `options`) turns it off, as it does for the app.
 *
 * Environment:
 *   HEALTHLOG_PRISMA_CLI      Prisma's CLI entry (default: the image's copy)
 *   HEALTHLOG_MIGRATIONS_DIR  where the migration files are (default:
 *                             prisma/migrations under the working directory)
 *   HEALTHLOG_MIGRATE_LOCK_RETRY_DELAYS
 *                             comma-separated backoff in seconds
 * Arguments are passed through to every Prisma call (`--schema …`).
 */
import { spawn } from "node:child_process";
import { readFileSync } from "node:fs";
import { join } from "node:path";
import { pathToFileURL } from "node:url";

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;

/** 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 (a lock timeout or a
 * deadlock), or null. Prisma prints `Migration name: <name>` and
 * `Database error code: <state>` 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 = errorCodeInReport(text);
  return name && code !== null && LOCK_FAILURES.has(code) ? name : null;
}

/** Whether Prisma refused to start because a failed migration is on record. */
function isFailedMigrationOnRecord(output) {
  return /\bP3009\b/.test(output);
}

/**
 * Decide whether a failed `migrate deploy` is the one failure retried here.
 *
 * @param {object} input
 * @param {string} input.output    everything Prisma printed
 * @param {Array<{migration_name: string, logs: string | null}> | null} input.failedRows
 *   the unfinished, not-rolled-back rows of `_prisma_migrations`, or null
 *   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, 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) {
    return { retry: false, reason: "not a lock timeout" };
  }
  if (!MIGRATION_NAME.test(migration)) {
    return { retry: false, reason: `unexpected migration name ${migration}` };
  }
  const sql = readMigration(migration);
  if (sql === null) {
    return { retry: false, reason: `${migration} is not in this image` };
  }
  if (!RETRY_MARKER.test(sql)) {
    return {
      retry: false,
      reason: `${migration} timed out on a lock but is not marked safe to re-run`,
    };
  }
  return { retry: true, migration, code };
}

/** The backoff schedule, from the environment or the default. */
export function retryDelays(raw) {
  if (!raw) return DEFAULT_RETRY_DELAYS_S;
  const delays = raw.split(",").map((part) => Number(part.trim()));
  return delays.every((d) => Number.isFinite(d) && d >= 0)
    ? delays
    : DEFAULT_RETRY_DELAYS_S;
}

/**
 * `DATABASE_URL` with the session time zone pinned to UTC, for Prisma.
 *
 * Appends to an `options` value the operator set rather than replacing it;
 * a later `-c` wins, so an operator's own `TimeZone` gives way to UTC. A URL
 * that does not parse, or a host that disabled the startup options, is
 * returned unchanged.
 *
 * @param {string | undefined} raw
 * @param {{ optionsDisabled?: boolean }} [opts]
 * @returns {string | undefined}
 */
export function utcSessionUrl(raw, { optionsDisabled = false } = {}) {
  if (!raw || optionsDisabled) return raw;
  let url;
  try {
    url = new URL(raw);
  } catch {
    return raw;
  }
  const existing = url.searchParams.get("options")?.trim();
  if (existing && existing.endsWith(TIME_ZONE_OPTION)) return raw;
  url.searchParams.set(
    "options",
    existing ? `${existing} ${TIME_ZONE_OPTION}` : TIME_ZONE_OPTION,
  );
  return url.toString();
}

/** The same switch the app reads in `src/lib/db-session.ts`. */
function sessionOptionsDisabled(env) {
  const raw = env.DATABASE_SESSION_OPTIONS_DISABLED?.trim();
  return raw !== undefined && /^(1|true|yes)$/i.test(raw);
}

/** The environment every Prisma call runs in. */
export function prismaEnv(env = process.env) {
  const url = utcSessionUrl(env.DATABASE_URL, {
    optionsDisabled: sessionOptionsDisabled(env),
  });
  return url === undefined ? { ...env } : { ...env, DATABASE_URL: url };
}

function runPrisma(cli, args) {
  return new Promise((resolve) => {
    const child = spawn(process.execPath, [cli, ...args], {
      stdio: ["ignore", "pipe", "pipe"],
      env: prismaEnv(),
    });
    let output = "";
    child.stdout.on("data", (chunk) => {
      output += chunk;
      process.stdout.write(chunk);
    });
    child.stderr.on("data", (chunk) => {
      output += chunk;
      process.stderr.write(chunk);
    });
    child.on("error", (error) => {
      output += String(error);
      resolve({ code: 1, output });
    });
    child.on("close", (code) => resolve({ code: code ?? 1, output }));
  });
}

/** The failed rows of `_prisma_migrations`, or null when they cannot be read. */
async function readFailedRows(connectionString) {
  if (!connectionString) return null;
  try {
    const { default: pg } = await import("pg");
    const url = new URL(connectionString);
    const schema = url.searchParams.get("schema") || "public";
    url.searchParams.delete("schema");
    const client = new pg.Client({
      connectionString: url.toString(),
      connectionTimeoutMillis: 5_000,
      statement_timeout: 5_000,
    });
    await client.connect();
    try {
      const { rows } = await client.query(
        `SELECT migration_name, logs FROM ${client.escapeIdentifier(schema)}._prisma_migrations
         WHERE finished_at IS NULL AND rolled_back_at IS NULL`,
      );
      return rows;
    } finally {
      await client.end().catch(() => {});
    }
  } catch {
    return null;
  }
}

function migrationReader(dir) {
  return (name) => {
    try {
      return readFileSync(join(dir, name, "migration.sql"), "utf8");
    } catch {
      return null;
    }
  };
}

const sleep = (ms) => new Promise((resolve) => setTimeout(resolve, ms));

async function main({
  cli = process.env.HEALTHLOG_PRISMA_CLI ||
    "/opt/prisma-cli/node_modules/prisma/build/index.js",
  migrationsDir = process.env.HEALTHLOG_MIGRATIONS_DIR ||
    join(process.cwd(), "prisma", "migrations"),
  delays = retryDelays(process.env.HEALTHLOG_MIGRATE_LOCK_RETRY_DELAYS),
  extraArgs = process.argv.slice(2),
} = {}) {
  const readMigration = migrationReader(migrationsDir);
  for (let attempt = 0; ; attempt++) {
    const deploy = await runPrisma(cli, ["migrate", "deploy", ...extraArgs]);
    if (deploy.code === 0) return 0;

    const failedRows = isFailedMigrationOnRecord(deploy.output)
      ? await readFailedRows(process.env.DATABASE_URL)
      : null;
    const decision = decideLockRetry({
      output: deploy.output,
      failedRows,
      readMigration,
    });
    if (!decision.retry) {
      if (decision.reason !== "not a lock timeout") {
        console.error(
          `HealthLog: not retrying the migration: ${decision.reason}.`,
        );
      }
      return deploy.code;
    }
    if (attempt >= delays.length) {
      console.error(
        `HealthLog: ERROR — migration ${decision.migration} timed out on a lock ` +
          `${attempt + 1} times in a row; giving up. Something holds the table ` +
          "for minutes: see docs/ops/deploy.md, " +
          '"A migration that timed out on a lock".',
      );
      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} ${cause} ` +
        `and changed nothing; marking it rolled back and retrying in ` +
        `${delay}s (retry ${attempt + 1} of ${delays.length}).`,
    );
    const resolve = await runPrisma(cli, [
      "migrate",
      "resolve",
      "--rolled-back",
      decision.migration,
      ...extraArgs,
    ]);
    if (resolve.code !== 0) return resolve.code;
    await sleep(delay * 1000);
  }
}

if (import.meta.url === pathToFileURL(process.argv[1] ?? "").href) {
  process.exitCode = await main();
}