diff --git a/.changeset/global-backup-lock-lows.md b/.changeset/global-backup-lock-lows.md new file mode 100644 index 0000000000..31d3197378 --- /dev/null +++ b/.changeset/global-backup-lock-lows.md @@ -0,0 +1,22 @@ +--- +id: global-backup-lock-lows +tasks: [T13299, T13293] +kind: fix +summary: "Global backup lock: stale clock starts at acquisition; a lost lock is abandoned, never removed; orphaned copies swept" +--- + +Three follow-ups to the single-flight session-end global backup (#1948 review): + +- The stale-window clock starts when the lock is taken, so a slow `db-heavy` + admission counts against it. A lock held past the window still discards + the copy instead of publishing it. +- A lock that was lost, or held past its stale window, is abandoned rather + than released. proper-lockfile's release and its exit hook remove the lock + directory without checking who owns it, which could delete the lock of the + process that took it over. The new `acquireAbandonableLock` routes the + lock's file operations through a guarded fs, so after `abandon()` neither + path touches the directory. A directory that was still ours is already + stale, and the next taker reclaims it. +- `cleo.db..tmp` copies (and their SQLite sidecars) left by a backup + killed mid-copy are swept from the global backup directory, under the lock, + once they are older than the stale window. diff --git a/.changeset/t13293-global-backup-lock-stale.md b/.changeset/t13293-global-backup-lock-stale.md new file mode 100644 index 0000000000..d47a40bebd --- /dev/null +++ b/.changeset/t13293-global-backup-lock-stale.md @@ -0,0 +1,24 @@ +--- +id: t13293-global-backup-lock-stale +tasks: [T13293, T13286] +kind: fix +summary: the session-end global backup lock outlasts a blocking VACUUM INTO, so a long copy is never taken over by a second one +--- + +The single-flight lock around the session-end global backup (T13286) was stale after 60 s. Its +`VACUUM INTO` is synchronous: while it runs, the event loop is blocked and proper-lockfile cannot +refresh the lock. A copy longer than 60 s could therefore have its lock taken as stale by another +session end, which then started a second full copy. + +**Timings.** Measured on a Mac mini (Mac17,16, Apple M5 Pro, internal APFS SSD) with synthetic +stores: 70 MB copies in 0.29 s and 1 GB in 2.4 s. A slow or FUSE-mounted disk can be 20–50 times +slower. + +**Fix.** The threshold is now `GLOBAL_BACKUP_LOCK_STALE_MS`: 10 minutes, at least three times the +worst case, matching `EXODUS_LOCK_STALE_MS`. + +**Discard on compromise.** A lock reported compromised is recorded instead of thrown, and the copy +made under it is discarded. So is a copy that outlasted the stale window: the copy blocks the event +loop, so a compromise could surface only after it. The copy is written under a temporary name and +published by a rename only if neither happened. A discarded copy is deleted with nothing renamed, +listed or rotated, and a warning is logged. diff --git a/packages/core/src/store/__tests__/backup-store-roundtrip.test.ts b/packages/core/src/store/__tests__/backup-store-roundtrip.test.ts index 17bef286d7..017e5eb988 100644 --- a/packages/core/src/store/__tests__/backup-store-roundtrip.test.ts +++ b/packages/core/src/store/__tests__/backup-store-roundtrip.test.ts @@ -18,16 +18,18 @@ import { mkdirSync, readdirSync, readFileSync, + utimesSync, writeFileSync, } from 'node:fs'; import { dirname, join } from 'node:path'; import { DatabaseSync } from 'node:sqlite'; -import { afterEach, beforeEach, describe, expect, it } from 'vitest'; +import { afterEach, beforeEach, describe, expect, it, vi } from 'vitest'; import { AUTO_GLOBAL_BACKUP_INTERVAL_MS, autoGlobalBackup, createBackup, createGlobalBackup, + GLOBAL_BACKUP_LOCK_STALE_MS, listGlobalBackups, listSystemBackups, restoreBackupById, @@ -252,6 +254,8 @@ describe('backups restore onto the live cleo.db (T13245)', () => { }); describe('the global store backs up and restores (T13245)', () => { + /** A stand-in held lock whose release and abandon are recorded. */ + const heldLock = () => ({ release: vi.fn(async () => {}), abandon: vi.fn(async () => {}) }); /** Row counts and checksums of the global brain and the nexus registry. */ function globalFingerprint(file: string): Record { const db = new DatabaseSync(file, { readOnly: true }); @@ -414,6 +418,96 @@ describe('the global store backs up and restores (T13245)', () => { } }); + it('a lock whose holder is blocked in a long copy (no refresh for 90 s) is not stolen (T13293)', async () => { + const { path: gpath } = await globalDb(); + const gdir = join(dirname(gpath), 'backups', 'sqlite'); + mkdirSync(gdir, { recursive: true }); + // A holder blocked in a synchronous VACUUM INTO cannot refresh the + // lock's mtime: the lock looks 90 s old. + mkdirSync(`${gdir}.lock`); + const old = new Date(Date.now() - 90_000); + utimesSync(`${gdir}.lock`, old, old); + expect(GLOBAL_BACKUP_LOCK_STALE_MS).toBeGreaterThanOrEqual(600_000); + const id = await autoGlobalBackup(new Date(), { + admit: async () => ({ release: async () => {} }), + }); + expect(id).toBeNull(); + expect(readdirSync(gdir).filter((f) => f.startsWith('cleo.db.auto-'))).toEqual([]); + }); + + it('a lock lost during the copy discards it: nothing published, listed or rotated (T13293)', async () => { + const { path: gpath } = await globalDb(); + const gdir = join(dirname(gpath), 'backups', 'sqlite'); + mkdirSync(gdir, { recursive: true }); + const before = readdirSync(gdir).sort(); + const held = heldLock(); + const id = await autoGlobalBackup(new Date(), { + admit: async () => ({ release: async () => {} }), + // The lock is reported compromised while held (as proper-lockfile does + // when its refresh finds the lock taken). + lock: async (onCompromised) => { + onCompromised(new Error('lock taken as stale by another process')); + return held; + }, + }); + expect(id).toBeNull(); + expect(readdirSync(gdir).sort()).toEqual(before); + expect(listGlobalBackups().filter((b) => b.type === 'auto')).toEqual([]); + // The lost lock may be another process's: abandoned, never removed (T13299). + expect(held.abandon).toHaveBeenCalledOnce(); + expect(held.release).not.toHaveBeenCalled(); + }); + + it('the admission wait counts against the stale window: a lock held past it discards the copy (T13299)', async () => { + const { path: gpath } = await globalDb(); + const gdir = join(dirname(gpath), 'backups', 'sqlite'); + mkdirSync(gdir, { recursive: true }); + const held = heldLock(); + const realNow = Date.now.bind(Date); + const id = await autoGlobalBackup(new Date(), { + lock: async () => held, + // The admission returns only after the whole stale window has passed. + admit: async () => { + vi.spyOn(Date, 'now').mockImplementation(() => realNow() + GLOBAL_BACKUP_LOCK_STALE_MS); + return { release: async () => {} }; + }, + }); + vi.restoreAllMocks(); + expect(id).toBeNull(); + expect(readdirSync(gdir).filter((f) => f.startsWith('cleo.db.auto-'))).toEqual([]); + expect(held.abandon).toHaveBeenCalledOnce(); + expect(held.release).not.toHaveBeenCalled(); + }); + + it('a backup that kept its lock releases it, removing the lock directory (T13299)', async () => { + const { path: gpath } = await globalDb(); + const gdir = join(dirname(gpath), 'backups', 'sqlite'); + const id = await autoGlobalBackup(new Date(), { + admit: async () => ({ release: async () => {} }), + }); + expect(id).not.toBeNull(); + expect(existsSync(`${gdir}.lock`)).toBe(false); + }); + + it('copies a killed backup left behind are swept under the lock once stale; a live one is kept (T13299)', async () => { + const { path: gpath } = await globalDb(); + const gdir = join(dirname(gpath), 'backups', 'sqlite'); + mkdirSync(gdir, { recursive: true }); + const old = new Date(Date.now() - GLOBAL_BACKUP_LOCK_STALE_MS - 60_000); + for (const name of ['cleo.db.auto-old.tmp', 'cleo.db.auto-old.tmp-journal', 'other.tmp']) { + writeFileSync(join(gdir, name), 'x'); + utimesSync(join(gdir, name), old, old); + } + writeFileSync(join(gdir, 'cleo.db.auto-live.tmp'), 'x'); + // A deferred admission copies nothing; the sweep already ran under the lock. + expect(await autoGlobalBackup(new Date(), { admit: async () => null })).toBeNull(); + const left = readdirSync(gdir); + expect(left).not.toContain('cleo.db.auto-old.tmp'); + expect(left).not.toContain('cleo.db.auto-old.tmp-journal'); + expect(left).toContain('cleo.db.auto-live.tmp'); + expect(left).toContain('other.tmp'); + }); + it('a deferred db-heavy admission takes no global backup', async () => { const { path: gpath } = await globalDb(); expect(await autoGlobalBackup(new Date(), { admit: async () => null })).toBeNull(); diff --git a/packages/core/src/store/__tests__/lock-abandon.test.ts b/packages/core/src/store/__tests__/lock-abandon.test.ts new file mode 100644 index 0000000000..3ff1f2f660 --- /dev/null +++ b/packages/core/src/store/__tests__/lock-abandon.test.ts @@ -0,0 +1,50 @@ +/** + * T13299 — an abandoned lock never removes its directory: proper-lockfile's + * release removes `.lock` without checking who owns it, so a lock lost + * to another process must be let go of, not released. + * + * @task T13299 + */ + +import { existsSync, mkdirSync, mkdtempSync, rmdirSync, rmSync, writeFileSync } from 'node:fs'; +import { tmpdir } from 'node:os'; +import { join } from 'node:path'; +import { afterEach, beforeEach, describe, expect, it } from 'vitest'; +import { acquireAbandonableLock } from '../lock.js'; + +let dir: string; +let file: string; + +beforeEach(() => { + dir = mkdtempSync(join(tmpdir(), 'cleo-t13299-lock-')); + file = join(dir, 'target'); + writeFileSync(file, ''); +}); + +afterEach(() => { + rmSync(dir, { recursive: true, force: true }); +}); + +describe('acquireAbandonableLock (T13299)', () => { + it('release removes the lock directory', async () => { + const held = await acquireAbandonableLock(file, { retries: 0 }); + expect(existsSync(`${file}.lock`)).toBe(true); + await held.release(); + expect(existsSync(`${file}.lock`)).toBe(false); + }); + + it('abandon leaves a lock another process took meanwhile in place, and frees ours for re-acquisition', async () => { + const held = await acquireAbandonableLock(file, { retries: 0, onCompromised: () => {} }); + // Another process took the lock as stale: removed ours, made its own. + rmdirSync(`${file}.lock`); + mkdirSync(`${file}.lock`); + await held.abandon(); + expect(existsSync(`${file}.lock`)).toBe(true); + // Abandoning a second time (already released) never throws. + await held.abandon(); + // This process no longer holds it: once the other holder lets go, it can be taken again. + rmdirSync(`${file}.lock`); + const again = await acquireAbandonableLock(file, { retries: 0 }); + await again.release(); + }); +}); diff --git a/packages/core/src/store/lock.ts b/packages/core/src/store/lock.ts index f99d399232..3b420c3a88 100644 --- a/packages/core/src/store/lock.ts +++ b/packages/core/src/store/lock.ts @@ -5,6 +5,7 @@ * @task T4457 */ +import * as fs from 'node:fs'; import { ExitCode } from '@cleocode/contracts/exit-codes.js'; import lockfile from 'proper-lockfile'; import { CleoError } from '../errors.js'; @@ -53,6 +54,84 @@ export async function acquireLock( } } +/** + * A held lock that can be released, or abandoned when it may no longer be + * ours (T13299). + */ +export interface AbandonableLock { + /** Release the lock: stop refreshing it and remove its directory. */ + release: ReleaseFn; + /** + * Stop holding the lock WITHOUT removing its directory: for a lock that was + * lost or outlasted its stale window, which another process may have taken + * since. proper-lockfile's release and its exit hook remove the directory + * without checking who owns it; after `abandon` neither touches it. A + * directory that was still ours is already stale, so the next taker + * reclaims it. Never throws. + */ + abandon: ReleaseFn; +} + +/** + * {@link acquireLock}, returning a lock that can also be abandoned (see + * {@link AbandonableLock}). The lock's file operations go through node's fs, + * with the directory removal skipped once the lock is abandoned. + * + * @param filePath - The file to lock (the lock is `.lock`). + * @param options - As for {@link acquireLock}. + * @returns The held lock. + * @throws CleoError (LOCK_TIMEOUT) when the lock cannot be acquired. + * @task T13299 + */ +export async function acquireAbandonableLock( + filePath: string, + options?: { stale?: number; retries?: number; onCompromised?: (err: Error) => void }, +): Promise { + let abandoned = false; + const guardedFs = { + ...fs, + rmdir(target: fs.PathLike, cb: (err: NodeJS.ErrnoException | null) => void): void { + if (abandoned) { + cb(null); + return; + } + fs.rmdir(target, cb); + }, + rmdirSync(target: fs.PathLike): void { + if (!abandoned) fs.rmdirSync(target); + }, + }; + let release: ReleaseFn; + try { + release = await lockfile.lock(filePath, { + ...DEFAULT_LOCK_OPTIONS, + fs: guardedFs, + ...(options?.stale !== undefined && { stale: options.stale }), + ...(options?.onCompromised !== undefined && { onCompromised: options.onCompromised }), + ...(options?.retries !== undefined && { + retries: { ...DEFAULT_LOCK_OPTIONS.retries, retries: options.retries }, + }), + }); + } catch (err) { + // @sync-invariant none:local-only a file lock held by another local process; never replicated + throw new CleoError(ExitCode.LOCK_TIMEOUT, `Failed to acquire lock: ${filePath}`, { + fix: `Another process may be writing to this file. Wait and retry.`, + cause: err, + }); + } + return { + release, + abandon: async () => { + abandoned = true; + try { + await release(); + } catch { + // already released as compromised: nothing is held + } + }, + }; +} + /** * Check if a file is currently locked. * diff --git a/packages/core/src/system/backup.ts b/packages/core/src/system/backup.ts index aa5c409881..49ef55dc3f 100644 --- a/packages/core/src/system/backup.ts +++ b/packages/core/src/system/backup.ts @@ -54,6 +54,7 @@ import { readFileSync, renameSync, rmSync, + statSync, unlinkSync, writeFileSync, } from 'node:fs'; @@ -61,8 +62,10 @@ import { dirname, join } from 'node:path'; import type { StoreRestoreResult } from '@cleocode/contracts'; import { ExitCode } from '@cleocode/contracts/exit-codes.js'; import { CleoError } from '../errors.js'; +import { getLogger } from '../logger.js'; import { formatBackupTimestamp, rotateBackupDir } from '../store/backup-sidecar.js'; import { resolveDualScopeDbPath } from '../store/dual-scope-db.js'; +import type { AbandonableLock } from '../store/lock.js'; import { getNativeDb } from '../store/sqlite.js'; import { assertRestoreTargetConfirmed } from '../store/worktree-isolation-guard.js'; @@ -175,6 +178,8 @@ export interface BackupResult { type: string; /** Files that were successfully captured into this backup. */ files: string[]; + /** Why the copy was discarded instead of published (T13293), when it was. */ + skipped?: string; } /** Result shape returned by {@link restoreBackup}. */ @@ -503,6 +508,18 @@ export function listGlobalBackups(): BackupEntry[] { .sort((a, b) => b.timestamp.localeCompare(a.timestamp)); } +/** + * Stale threshold of the automatic global backup lock (T13293). `VACUUM INTO` + * is synchronous: while it runs, the event loop is blocked and + * proper-lockfile cannot refresh the lock's mtime, so a copy longer than the + * threshold would let another process take the lock as stale and start a + * second copy. Measured on an SSD (2026-10-06): 70 MB in 0.29 s, 1 GB in + * 2.4 s; a slow or FUSE-mounted disk can be 20-50x slower, so 1 GB may take + * ~2 min. The threshold is 3x that worst case with a 10-minute floor, like + * `EXODUS_LOCK_STALE_MS`. + */ +export const GLOBAL_BACKUP_LOCK_STALE_MS = 600_000; + /** Minimum age of the newest automatic global backup before another is taken. */ export const AUTO_GLOBAL_BACKUP_INTERVAL_MS = 60 * 60 * 1000; @@ -521,7 +538,11 @@ export const AUTO_GLOBAL_BACKUP_INTERVAL_MS = 60 * 60 * 1000; */ export async function autoGlobalBackup( now: Date = new Date(), - opts: { admit?: () => Promise<{ release: () => Promise } | null> } = {}, + opts: { + admit?: () => Promise<{ release: () => Promise } | null>; + /** The single-flight lock (tests): takes the compromise callback, returns the held lock. */ + lock?: (onCompromised: (err: Error) => void) => Promise; + } = {}, ): Promise { const due = (): boolean => { const newest = listGlobalBackups().find((b) => b.type === 'auto'); @@ -536,33 +557,88 @@ export async function autoGlobalBackup( // taken without waiting) and the age is re-checked under it. const dir = globalBackupDir(); mkdirSync(dir, { recursive: true }); - const { acquireLock } = await import('../store/lock.js'); - let unlock: (() => Promise) | null = null; + // A lost lock (its refresh failed past the threshold) is recorded, never + // thrown; the copy made under it is then discarded, not published (T13293). + let compromised: string | null = null; + const onCompromised = (err: Error): void => { + compromised = err.message; + getLogger('backup').warn( + { dir, err: err.message }, + 'global backup lock compromised; the copy in flight will be discarded', + ); + }; + const takeLock = + opts.lock ?? + (async (cb: (err: Error) => void) => { + const { acquireAbandonableLock } = await import('../store/lock.js'); + return acquireAbandonableLock(dir, { + retries: 0, + stale: GLOBAL_BACKUP_LOCK_STALE_MS, + onCompromised: cb, + }); + }); + let held: AbandonableLock; try { - unlock = await acquireLock(dir, { retries: 0, stale: 60_000 }); + held = await takeLock(onCompromised); } catch { return null; } + // The stale window runs from when the lock was taken, not from when the + // copy starts: the admission wait counts against it too (T13299). + const lockedAt = Date.now(); + // The copy blocks the event loop, so a compromise may only surface after + // it: a lock held past the stale window is treated as lost. + const lockLost = (): string | null => + compromised !== null + ? `lock compromised: ${compromised}` + : Date.now() - lockedAt >= GLOBAL_BACKUP_LOCK_STALE_MS + ? 'the copy outlasted the lock stale window' + : null; try { + sweepOrphanedGlobalCopies(dir, Date.now()); if (!due()) return null; // A full VACUUM INTO of the largest shared store is db-heavy work: // admitted by the governor, skipped (not queued) under pressure. const admission = await (opts.admit ?? admitDbHeavy)(); if (admission === null) return null; try { - const r = await createGlobalBackup({ type: 'auto' }); + const r = await createGlobalBackup({ type: 'auto', discardIf: lockLost }); return r.files.length > 0 ? r.backupId : null; } finally { await admission.release(); } } finally { - await unlock(); + // A lost or outlasted lock may be another process's by now: let go of + // it without removing its directory (T13299). + await (lockLost() !== null ? held.abandon() : held.release()); } } catch { return null; } } +/** + * Remove the `cleo.db..tmp` copies (and their SQLite sidecars) that a + * global backup killed mid-copy left behind, once older than the lock stale + * window: a live copy is younger, since `VACUUM INTO` keeps writing it. + * Called under the global backup lock (T13299). + * + * @param dir - The global backup directory. + * @param now - Clock in ms. + */ +function sweepOrphanedGlobalCopies(dir: string, now: number): void { + for (const name of readdirSync(dir)) { + if (!/^cleo\.db\..+\.tmp(-journal|-wal|-shm)?$/.test(name)) continue; + const file = join(dir, name); + try { + if (now - statSync(file).mtimeMs >= GLOBAL_BACKUP_LOCK_STALE_MS) + rmSync(file, { force: true }); + } catch { + // removed meanwhile + } + } +} + /** A non-blocking `db-heavy` admission; `null` when deferred. A governor failure admits (fail open, as the store opens do). */ async function admitDbHeavy(): Promise<{ release: () => Promise } | null> { try { @@ -589,6 +665,12 @@ export async function createGlobalBackup(opts?: { type?: string; note?: string; maxSnapshots?: number; + /** + * Checked after the copy and before it is published: a reason to discard + * it (the caller's lock was lost during the copy, T13293), or `null`. A + * discarded copy is deleted; nothing is renamed, listed or rotated. + */ + discardIf?: () => string | null; }): Promise { const btype = opts?.type || 'snapshot'; const now = new Date(); @@ -600,7 +682,20 @@ export async function createGlobalBackup(opts?: { try { const { openDualScopeDb, getDualScopeNativeDb } = await import('../store/dual-scope-db.js'); const db = getDualScopeNativeDb(await openDualScopeDb('global')); - if (safeSqliteSnapshot(db, join(backupDir, `cleo.db.${backupId}`))) backedUp.push('cleo.db'); + // The copy lands under a temporary name and is published by a rename + // only if nothing invalidated it meanwhile. + const final = join(backupDir, `cleo.db.${backupId}`); + const staged = `${final}.tmp`; + if (safeSqliteSnapshot(db, staged)) { + const why = opts?.discardIf?.() ?? null; + if (why !== null) { + rmSync(staged, { force: true }); + getLogger('backup').warn({ backupId, why }, 'global backup discarded, not published'); + return { backupId, path: backupDir, timestamp, type: btype, files: [], skipped: why }; + } + renameSync(staged, final); + backedUp.push('cleo.db'); + } } catch { // the global store could not be opened: nothing to back up }