// site-sync apply lock (lib/siteLock.js): one apply or rollback per site at a // time across PROCESSES, and recovery of the plans a stopped process left in // flight. In-process checks of the lock itself, then real worker processes: they // race different plans at once, and one is SIGKILLed mid-apply. // // ./test/run.sh applyLock.js (SQLite) // ./test/runPg.sh applyLock.js (Postgres, plus the per-tenant check) // // SS_LOCK_LIB may point the lib modules at a pre-lock copy to prove the process // checks fail there; only those run then (the in-process checks need the lock). const childProcess = require("child_process"); const path = require("path"); const { getState } = require("@saltcorn/data/db/state"); const Plugin = require("@saltcorn/data/models/plugin"); const { db, ok, section, step, summary, installPlugin, bootstrapPlugin, mkRes, mkAdminReq, routeOf } = require("./harness"); const PROOF = !!process.env.SS_LOCK_LIB; const LIB = process.env.SS_LOCK_LIB || path.resolve(__dirname, "..", "lib"); const capture = require(path.join(LIB, "capture")); const planLib = require(path.join(LIB, "plan")); const applyLib = require(path.join(LIB, "apply")); const rollback = require(path.join(LIB, "rollback")); const ops = require(path.join(LIB, "operations")); const env = require(path.join(LIB, "env")); const siteLock = PROOF ? null : require(path.join(LIB, "siteLock")); const routes = PROOF ? null : require(path.join(LIB, "routes")); const { physicalColumns } = require(path.join(LIB, "common", "registeredTable")); const { APPLY_LOCK_TABLE } = require(path.resolve(__dirname, "..", "lib", "constants")); const WORKER_FLAG = "--worker"; const WORKERS = 4; // Every worker has booted by then, so all start together. const START_DELAY_MS = 8000; // How long a worker's install_pack is held up: the window the others race into. const SLOW_MS = 2000; // A lease short enough to outlive several times within a check. const SHORT_LEASE_MS = 400; // How far this process's clock is put ahead to show it is not the lease clock. const CLOCK_SKEW_MS = 60 * 60 * 1000; const STALLED = "STALLED"; const RESULT = "RESULT "; // A refusal by the lock: naming the holder, or (SQLite under load) the database // staying busy while the holder writes. Either way nothing was changed. const BUSY = /is running on this site|the site database is busy/; const BASE_SITE_NAME = "apply-lock-base"; const TENANT = "locktenant"; const sleep = (ms) => { return new Promise((resolve) => setTimeout(resolve, ms)); }; const outcome = async (fn) => { try { return { value: await fn() }; } catch (e) { return { error: e }; } }; const plansRef = () => `${db.getTenantSchemaPrefix()}_ss_plans`; // What LEASE_MS passing does to a lock whose holder stopped renewing it. const ageLease = async () => { await db.query(`UPDATE ${db.getTenantSchemaPrefix()}${APPLY_LOCK_TABLE} SET expires_ms = 0`); }; const planStatus = async (planId) => { return (await planLib.loadPlan(planId)).status; }; const setStatus = async (planId, status, claimedFrom) => { await db.query(`UPDATE ${plansRef()} SET status = $1, claimed_from = $2 WHERE plan_id = $3`, [status, claimedFrom, planId]); }; const dropPlans = async (ids) => { for (const id of ids) { await db.query(`DELETE FROM ${plansRef()} WHERE plan_id = $1`, [id]); } }; // A plan, previewed against this site as it is now, that only renames the site. const variantPlan = async (siteName) => { const desired = JSON.parse(JSON.stringify((await capture.buildDesiredState()).pack)); desired.config.site_name = siteName; const built = await planLib.buildPlan({ peerRow: null, env: await env.getEnv(), desired, desiredHash: capture.hashPack(desired), sourceEnvId: "src", sourceRows: {} }); return built.plan_id; }; // ---------------- worker processes ---------------- // A worker: boot like a server process, hold up (or, for "stall", never finish) // install_pack, then at startAt run one apply or rollback through the admin // operations and print its outcome. const worker = async () => { const [task, planId, startAt, slowMs] = process.argv.slice(process.argv.indexOf(WORKER_FLAG) + 1); await Plugin.loadAllPlugins(); const packMod = require("@saltcorn/admin-models/models/pack"); const realInstall = packMod.install_pack; packMod.install_pack = async (...args) => { if (task === "stall") { process.stdout.write(STALLED + "\n"); return await new Promise(() => {}); } await sleep(Number(slowMs)); return await realInstall(...args); }; await sleep(Math.max(0, Number(startAt) - Date.now())); const r = await outcome(() => (task === "rollback" ? ops.rollbackPlan(planId, {}) : ops.applyPlan(planId, {}))); process.stdout.write(RESULT + JSON.stringify(r.error ? { ok: false, error: r.error.message } : { ok: true, warnings: r.value.warnings }) + "\n"); process.exit(0); }; // Start a worker: { child, done (resolves { code, signal, out }), waitFor(text) }. // waitFor rejects if the worker exits without printing text. const startWorker = (args) => { let out = ""; let exited = null; const waiters = []; const child = childProcess.spawn(process.execPath, [__filename, WORKER_FLAG].concat(args), { env: process.env, stdio: ["ignore", "pipe", "inherit"] }); child.stdout.on("data", (d) => { out += d; for (const w of waiters.filter((x) => out.includes(x.text))) { w.resolve(); } }); const done = new Promise((resolve) => { child.on("exit", (code, signal) => { exited = { code, signal, out }; for (const w of waiters) { w.reject(new Error(`worker exited (${code} ${signal || ""}) without printing ${w.text}: ${out.trim()}`)); } resolve(exited); }); }); const waitFor = (text) => new Promise((resolve, reject) => { if (out.includes(text)) { resolve(); } else if (exited) { reject(new Error(`worker exited without printing ${text}: ${out.trim()}`)); } else { waiters.push({ text, resolve, reject }); } }); return { child, done, waitFor }; }; const resultOf = (run) => { const line = run.out.split("\n").find((l) => l.startsWith(RESULT)); return line ? JSON.parse(line.slice(RESULT.length)) : { ok: false, error: `no result (exit ${run.code} ${run.signal || ""})` }; }; // Reload this process's cached Saltcorn state after workers changed the database. const resync = async () => { await getState().refresh(true); }; // WORKERS workers each run `task` at the same moment, worker i on planIds[i]. const raceWorkers = async (task, planIds) => { const startAt = Date.now() + START_DELAY_MS; const runs = await Promise.all(planIds.map((id) => startWorker([task, id, String(startAt), String(SLOW_MS)]).done)); await resync(); return runs.map(resultOf); }; const outcomesText = (results) => JSON.stringify(results.map((r) => (r.ok ? "ok" : r.error))); // ---------------- in-process checks ---------------- const schemaChecks = async () => { section("schema"); await step("the lock table and _ss_plans.claimed_from exist", async () => { const cols = await physicalColumns(APPLY_LOCK_TABLE); ok("lock table columns", ["lock_name", "holder", "operation", "plan_id", "acquired_at", "expires_ms"].every((c) => cols.has(c)), [...cols].join(",")); ok("_ss_plans.claimed_from", (await physicalColumns("_ss_plans")).has("claimed_from")); }); await step("upgrade: a pre-0.0.4 _ss_plans gains claimed_from, even with workers booting together", async () => { await db.query(`ALTER TABLE ${plansRef()} DROP COLUMN claimed_from`); ok("column dropped (as created by 0.0.3)", !(await physicalColumns("_ss_plans")).has("claimed_from")); const { createAllTables } = require(path.join(LIB, "schema")); const r = await outcome(() => Promise.all([createAllTables(), createAllTables()])); ok("two concurrent onLoad schema passes both succeed", !r.error, r.error && r.error.message); ok("claimed_from added back", (await physicalColumns("_ss_plans")).has("claimed_from")); }); }; const lockChecks = async () => { section("the lock"); await step("acquire, refuse a second holder, release", async () => { const a = await siteLock.acquire({ operation: "apply", planId: "plan-a" }); const st = await siteLock.lockState(); ok("held: live, naming the operation and plan", !!st && st.live && st.operation === "apply" && st.plan_id === "plan-a"); const b = await outcome(() => siteLock.acquire({ operation: "rollback", planId: "plan-b" })); ok("a second acquire is refused with LockBusyError", b.error instanceof siteLock.LockBusyError, b.error && b.error.message); ok("the refusal names what is running", !!b.error && /another apply is running on this site \(plan plan-a,/.test(b.error.message), b.error && b.error.message); await a.release(); ok("released: free", (await siteLock.lockState()) === null); const c = await siteLock.acquire({ operation: "apply", planId: "plan-c" }); ok("acquirable again", (await siteLock.lockState()).plan_id === "plan-c"); await c.release(); }); await step("a held lease is renewed: it outlives its length several times", async () => { const a = await siteLock.acquire({ operation: "apply", planId: "renewed", leaseMs: SHORT_LEASE_MS }); await sleep(SHORT_LEASE_MS * 3); const b = await outcome(() => siteLock.acquire({ operation: "apply", planId: "thief" })); ok("still held after three lease lengths", b.error instanceof siteLock.LockBusyError); ok("the holder still holds it", await a.renew()); await a.release(); }); await step("a lapsed lease is taken over, and its old holder finds out", async () => { const a = await siteLock.acquire({ operation: "apply", planId: "stalled" }); await ageLease(); ok("lapsed: no longer live", (await siteLock.lockState()).live === false); const b = await siteLock.acquire({ operation: "rollback", planId: "taker" }); ok("taken over", (await siteLock.lockState()).plan_id === "taker"); const lost = await outcome(() => a.assertHeld()); ok("the old holder's checkpoint throws LockLostError", lost.error instanceof siteLock.LockLostError); ok("and it does not renew any more", (await a.renew()) === false); await a.release(); ok("its release leaves the new holder's lock alone", (await siteLock.lockState()).plan_id === "taker"); await b.release(); }); await step("lease times come from the database clock, not this server's", async () => { const a = await siteLock.acquire({ operation: "apply", planId: "clock-holder" }); const realNow = Date.now; Date.now = () => realNow() + CLOCK_SKEW_MS; try { ok("a server whose clock runs an hour fast still sees the lease live", (await siteLock.lockState()).live === true); const b = await outcome(() => siteLock.acquire({ operation: "apply", planId: "fast-clock" })); ok("and cannot take it over", b.error instanceof siteLock.LockBusyError); } finally { Date.now = realNow; } await a.release(); }); await step("withSiteLock: a nested step reuses the lease; released on success and failure", async () => { await siteLock.withSiteLock({ operation: "apply", planId: "outer" }, async (lease) => { const nested = await siteLock.withSiteLock({ operation: "apply", planId: "inner", lease }, async (inner) => ({ holder: (await siteLock.lockState()).plan_id, recovered: inner.recovered.length })); ok("a nested step runs under the outer lease", nested.holder === "outer" && nested.recovered === 0); }); ok("released after success", (await siteLock.lockState()) === null); const r = await outcome(() => siteLock.withSiteLock({ operation: "apply", planId: "boom" }, async () => { throw new Error("boom"); })); ok("the failure propagates", !!r.error && r.error.message === "boom"); ok("released after a failure", (await siteLock.lockState()) === null); }); }; const recoveryChecks = async () => { section("recovery of plans a stopped holder left in flight"); await step("claimPlanStatus records the status it claimed from", async () => { const id = await variantPlan("claim"); await planLib.claimPlanStatus(id, ["pending"], "applying"); const p = await planLib.loadPlan(id); ok("applying, claimed_from pending", p.status === "applying" && p.claimed_from === "pending"); await dropPlans([id]); }); await step("acquiring the lock returns each in-flight plan to the status it was claimed from", async () => { const ids = []; for (const tag of ["a", "b", "c", "d"]) { ids.push(await variantPlan(`recover-${tag}`)); } await setStatus(ids[0], "applying", "rolled_back"); await setStatus(ids[1], "rolling_back", "pending"); await setStatus(ids[2], "applying", null); await setStatus(ids[3], "rolling_back", null); const lease = await siteLock.acquire({ operation: "apply", planId: "recoverer" }); ok("all four recovered", lease.recovered.length === 4 && ids.every((id) => lease.recovered.some((r) => r.plan_id === id)), JSON.stringify(lease.recovered)); ok("an apply claimed from rolled_back is rolled_back again", (await planStatus(ids[0])) === "rolled_back"); ok("a rollback claimed from pending is pending again", (await planStatus(ids[1])) === "pending"); ok("a 0.0.3 apply (no claimed_from) is pending again", (await planStatus(ids[2])) === "pending"); ok("a 0.0.3 rollback (no claimed_from) is applied again", (await planStatus(ids[3])) === "applied"); const warnings = siteLock.recoveryWarnings(lease); ok("one warning per recovered plan, naming it", warnings.length === 4 && ids.every((id) => warnings.some((w) => w.includes(id))), warnings.join(" | ")); await lease.release(); await dropPlans(ids); }); }; const standingChecks = async () => { section("a plan left in flight is reported (read-only)"); await step("running while its lease is live, interrupted once nobody holds the lock", async () => { const id = await variantPlan("standing"); const lease = await siteLock.acquire({ operation: "apply", planId: id }); await planLib.claimPlanStatus(id, ["pending"], "applying"); const running = await ops.status(); ok("status: running, naming the plan", running.applyLock.state === "running" && running.applyLock.holder.plan_id === id); ok("get_plan: in flight, not interrupted", (await ops.inspectPlan(id)).standing.interrupted === false); await lease.release(); const st = await ops.status(); ok("status: interrupted, listing the plan", st.applyLock.state === "interrupted" && st.applyLock.plans.some((p) => p.plan_id === id && p.status === "applying")); const standing = (await ops.inspectPlan(id)).standing; ok("get_plan: interrupted, and appliable once recovered (pending, site unchanged)", standing.interrupted === true && standing.can_apply === true && standing.stale === false, JSON.stringify(standing)); const listed = (await ops.listPlans({})).find((p) => p.plan_id === id); ok("list_plans agrees", !!listed && listed.interrupted === true && listed.status === "applying"); const res = mkRes(); await routeOf(routes.routes, "get", "/admin/site-sync/")(mkAdminReq(), res); const html = JSON.stringify(res._wrap || {}); ok("the dashboard shows an interrupted card naming the plan", html.includes("Interrupted apply or rollback") && html.includes(id)); ok("reading changed nothing", (await planStatus(id)) === "applying"); const recoverer = await siteLock.acquire({ operation: "apply", planId: "recoverer" }); ok("the next acquire recovers it", recoverer.recovered.some((r) => r.plan_id === id) && (await planStatus(id)) === "pending"); await recoverer.release(); ok("status: idle", (await ops.status()).applyLock.state === "idle"); await dropPlans([id]); }); }; const lostLeaseChecks = async () => { section("a holder that loses the lock stops, leaving the plan to the new holder"); await step("lock taken over during install_pack: the apply stops at its next checkpoint", async () => { const id = await variantPlan("lost"); const packMod = require("@saltcorn/admin-models/models/pack"); const realInstall = packMod.install_pack; let thief = null; packMod.install_pack = async (...args) => { packMod.install_pack = realInstall; await ageLease(); thief = await siteLock.acquire({ operation: "apply", planId: "thief" }); return await realInstall(...args); }; let r; try { r = await outcome(() => applyLib.applyPlan(id, {})); } finally { packMod.install_pack = realInstall; } ok("the apply stopped with LockLostError", r.error instanceof siteLock.LockLostError, r.error ? r.error.message : "it finished"); ok("the error names the plan", !!r.error && r.error.planId === id); ok("the new holder recovered the plan", !!thief && thief.recovered.some((x) => x.plan_id === id)); ok("its status is what the new holder made it (not overwritten)", (await planStatus(id)) === "pending"); ok("the new holder still holds the lock", (await siteLock.lockState()).plan_id === "thief"); await thief.release(); const rb = await rollback.rollbackApply(id, {}); ok("the half-applied plan rolls back from its restore point", rb.rolledBack === true && getState().getConfig("site_name") === BASE_SITE_NAME); }); }; const opsChecks = async () => { section("the admin operations while the lock is held"); await step("apply and rollback are refused cleanly, then work once it is free", async () => { const id = await variantPlan("ops"); const lease = await siteLock.acquire({ operation: "rollback", planId: "busy-holder" }); const a = await outcome(() => ops.applyPlan(id, {})); ok("apply: OpError naming the running rollback", a.error instanceof ops.OpError && /another rollback is running on this site \(plan busy-holder,/.test(a.error.message), a.error && a.error.message); ok("no restore-point offer (nothing changed)", !!a.error && a.error.extra === undefined); const b = await outcome(() => ops.rollbackPlan(id, {})); ok("rollback: refused the same way", b.error instanceof ops.OpError && BUSY.test(b.error.message)); ok("the plan was not touched", (await planStatus(id)) === "pending"); await lease.release(); const c = await ops.applyPlan(id, {}); ok("applies once the lock is free", c.applied === true && getState().getConfig("site_name") === "ops"); await ops.rollbackPlan(id, {}); ok("and rolls back", getState().getConfig("site_name") === BASE_SITE_NAME); }); }; // ---------------- process checks ---------------- const raceChecks = async () => { section(`${WORKERS} processes apply ${WORKERS} different plans at the same moment`); await step("exactly one runs; the others are refused before changing anything", async () => { const ids = []; for (let i = 0; i < WORKERS; i++) { ids.push(await variantPlan(`race-${i}`)); } const results = await raceWorkers("apply", ids); ok("one apply ran", results.filter((r) => r.ok).length === 1, outcomesText(results)); ok("every other one was refused by the lock", results.filter((r) => !r.ok && BUSY.test(r.error)).length === WORKERS - 1, outcomesText(results)); const statuses = []; for (const id of ids) { statuses.push(await planStatus(id)); } ok("one plan applied, the rest still pending", statuses.filter((s) => s === "applied").length === 1 && statuses.filter((s) => s === "pending").length === WORKERS - 1, statuses.join(",")); if (!PROOF) { ok("the lock is free again", (await siteLock.lockState()) === null); } for (const id of ids.filter((x, i) => statuses[i] === "applied")) { await rollback.rollbackApply(id, {}); } await dropPlans(ids); }); }; const crashChecks = async () => { section("a process killed mid-apply"); await step("its plan is recovered once its lease lapses, by exactly one of several racing rollbacks", async () => { const before = (await capture.buildDesiredState()).hash; const x = await variantPlan("crash-x"); const y = await variantPlan("crash-y"); const w = startWorker(["stall", x, "0", "0"]); await w.waitFor(STALLED); w.child.kill("SIGKILL"); const killed = await w.done; ok("the worker was killed inside install_pack", killed.signal === "SIGKILL"); ok("its plan is left applying", (await planStatus(x)) === "applying"); if (!PROOF) { const st = await siteLock.lockState(); ok("its lock is still held under a live lease", !!st && st.live && st.plan_id === x); const busy = await outcome(() => ops.applyPlan(y, {})); ok("until the lease lapses other applies are refused, naming it", !!busy.error && busy.error.message.includes(`another apply is running on this site (plan ${x},`), busy.error && busy.error.message); ok("the dashboard cannot tell yet: running", (await ops.status()).applyLock.state === "running"); await ageLease(); const lapsed = await ops.status(); ok("lease lapsed: the dashboard reports it interrupted, with its restore point", lapsed.applyLock.state === "interrupted" && lapsed.applyLock.plans.some((p) => p.plan_id === x && p.has_restore_point)); const standing = (await ops.inspectPlan(x)).standing; ok("get_plan: interrupted, can roll back", standing.interrupted === true && standing.can_rollback === true, JSON.stringify(standing)); } const results = await raceWorkers("rollback", Array(WORKERS).fill(x)); ok("exactly one rollback ran", results.filter((r) => r.ok).length === 1, outcomesText(results)); ok("the others were refused by the lock", results.filter((r) => !r.ok && BUSY.test(r.error)).length === WORKERS - 1, outcomesText(results)); const winner = results.find((r) => r.ok); ok("the rollback reports the recovery", !!winner && winner.warnings.some((m) => m.includes(x) && /left applying by a process that stopped/.test(m)), winner && JSON.stringify(winner.warnings)); ok("the plan is rolled back", (await planStatus(x)) === "rolled_back"); ok("this site is as it was before the killed apply", (await capture.buildDesiredState()).hash === before); if (!PROOF) { ok("nothing in flight, lock free", (await ops.status()).applyLock.state === "idle" && (await siteLock.lockState()) === null); } const applied = await outcome(() => ops.applyPlan(y, {})); ok("the plan the kill blocked now applies", !applied.error && applied.value.applied === true, applied.error && applied.error.message); if (!applied.error) { await ops.rollbackPlan(y, {}); } await dropPlans([x, y]); }); }; // ---------------- tenants (Postgres) ---------------- const tenantChecks = async () => { if (db.isSQLite) { return; } section("tenants have their own locks (Postgres)"); const { add_tenant } = require("@saltcorn/data/db/state"); const { create_tenant, switchToTenant, insertTenant } = require("@saltcorn/admin-models/models/tenant"); await step("a held root lock does not block a tenant; the tenant's lease renews in its own schema", async () => { add_tenant(TENANT); await switchToTenant(await insertTenant(TENANT, `admin@${TENANT}.local`, "apply lock tenant check"), `http://${TENANT}.example.com/`); await create_tenant({ t: TENANT, loadAndSaveNewPlugin() {}, plugin_loader() {} }); const rootLease = await siteLock.acquire({ operation: "apply", planId: "root-holder" }); await db.runWithTenant(TENANT, async () => { await Plugin.loadAllPlugins(); await db.runWithTenant(db.connectObj.default_schema, () => getState().setConfig("tenants_unsafe_plugins", true)); await installPlugin(); ok("running in the tenant schema", db.getTenantSchema() === TENANT); ok("the tenant's lock is free", (await siteLock.lockState()) === null); const id = await variantPlan("tenant-plan"); const r = await ops.applyPlan(id, {}); ok("the tenant applies while the root lock is held", r.applied === true); const tenantLease = await siteLock.acquire({ operation: "apply", planId: "tenant-holder", leaseMs: SHORT_LEASE_MS }); await sleep(SHORT_LEASE_MS * 3); const st = await siteLock.lockState(); ok("the tenant's short lease was renewed in the tenant schema", !!st && st.live && st.plan_id === "tenant-holder"); await db.runWithTenant(db.connectObj.default_schema, async () => { ok("the root sees only its own holder", (await siteLock.lockState()).plan_id === "root-holder"); }); await tenantLease.release(); }); await rootLease.release(); }); }; const main = async () => { const where = db.isSQLite ? `sqlite ${process.env.SQLITE_FILEPATH}` : `postgres ${db.connectObj.database} schema ${db.getTenantSchema()}`; console.log(`DB = ${where} LIB = ${LIB}${PROOF ? " (proof mode: process checks only)" : ""}`); await bootstrapPlugin(); await getState().setConfig("site_name", BASE_SITE_NAME); if (!PROOF) { await schemaChecks(); await lockChecks(); await recoveryChecks(); await standingChecks(); await lostLeaseChecks(); await opsChecks(); } await raceChecks(); await crashChecks(); if (!PROOF) { await tenantChecks(); } process.exit(summary() === 0 ? 0 : 1); }; if (process.argv.includes(WORKER_FLAG)) { worker(); } else { // main() ends with process.exit; an event loop that drains first means a check // waited on something that can no longer happen -- a failure, never a pass. process.on("beforeExit", () => { console.log("\nFAILURES: the run ended before finishing its checks"); process.exitCode = 1; }); main(); }