Merge pull request #1256 from Donkie/fix/1246-backup-lock

Fix nightly backups failing on network shares, and the backup hang

spoolman/database/database.py

@@ -1,10 +1,12 @@
 """SQLAlchemy database setup."""
 
+import asyncio
 import datetime
 import filecmp
 import logging
 import shutil
 import sqlite3
+import threading
 import time
 from collections.abc import AsyncGenerator
 from contextlib import closing
@@ -30,6 +32,10 @@ MIN_SECONDS_BETWEEN_ROTATIONS = 5 * 60
 # Name of the newest backup. Older ones get a .1 ... .N suffix.
 BACKUP_NAME = "spoolman.db"
 
+# sqlite3's backup() retries forever while the source is locked. Give up after this long, so a lock
+# that never clears fails the backup loudly instead of hanging it (#1191).
+BACKUP_LOCK_TIMEOUT_SECONDS = 60
+
 
 def _unicode_lower(value: str | None) -> str | None:
     """Lowercase SQLite text using Python's Unicode support."""
@@ -97,6 +103,7 @@ class Database:
         # Monotonic timestamp of the last rotation, for the rate limit. Process-local, which is
         # fine: Spoolman is single-instance, and a restart erring towards one extra backup is safe.
         self._last_rotation: float | None = None
+        self._backup_lock = threading.Lock()
 
     def is_file_based_sqlite(self) -> bool:
         """Return True if the database is file based."""
@@ -134,8 +141,21 @@ class Database:
 
         logger.info("Backing up SQLite database to %s", target_path)
 
-        def progress(_: int, remaining: int, total: int) -> None:
-            logger.info("Copied %d of %d pages.", total - remaining, total)
+        busy_since: float | None = None
+
+        def progress(status: int, remaining: int, total: int) -> None:
+            nonlocal busy_since
+            if status not in (sqlite3.SQLITE_BUSY, sqlite3.SQLITE_LOCKED):
+                busy_since = None
+                logger.debug("Copied %d of %d pages.", total - remaining, total)
+                return
+            busy_since = busy_since or time.monotonic()
+            if time.monotonic() - busy_since > BACKUP_LOCK_TIMEOUT_SECONDS:
+                raise sqlite3.OperationalError(
+                    f"Database {self.connection_url.database} stayed locked for over "
+                    f"{BACKUP_LOCK_TIMEOUT_SECONDS} seconds, giving up on the backup. "
+                    "Is another program holding it open?",
+                )
 
         if self.connection_url.database == target_path:
             raise ValueError("Cannot backup database to itself.")
@@ -146,9 +166,12 @@ class Database:
         # transaction manager that commits on exit, it does not close the connection. Leaving the
         # handles open leaks them on every backup, and on Windows it makes the caller's unlink/move
         # of the file we just wrote fail with "used by another process" (POSIX unlink hides this).
+        # nolock=1: the target is a scratch file nothing else opens, so it needs no file locks. Backup
+        # folders on network shares often refuse SQLite's locks (CIFS without nobrl, NFS without
+        # lockd), which failed every backup with a "locked" database that was not locked at all (#1246).
         with (
             closing(sqlite3.connect(self.connection_url.database)) as src,
-            closing(sqlite3.connect(target_path)) as dst,
+            closing(sqlite3.connect(f"{Path(target_path).absolute().as_uri()}?nolock=1", uri=True)) as dst,
         ):
             src.backup(dst, pages=1, progress=progress)
 
@@ -191,7 +214,11 @@ class Database:
             logger.info("Skipping backup as the database is not SQLite.")
             return BackupResult(None, created=False)
 
-        backup_folder = Path(backup_folder)
+        # Backups run in worker threads, so a manual one can overlap the scheduled one.
+        with self._backup_lock:
+            return self._backup_and_rotate(Path(backup_folder), num_backups)
+
+    def _backup_and_rotate(self, backup_folder: Path, num_backups: int) -> BackupResult:
         backup_folder.mkdir(parents=True, exist_ok=True)
         newest = backup_folder.joinpath(BACKUP_NAME)
 
@@ -250,7 +277,8 @@ async def backup_global_db(num_backups: int = 5) -> BackupResult:
     """
     if __db is None:
         raise RuntimeError("DB is not setup.")
-    return __db.backup_and_rotate(env.get_backups_dir(), num_backups=num_backups)
+    # Off the event loop: the copy is blocking, and can wait on a lock held by our own connection.
+    return await asyncio.to_thread(__db.backup_and_rotate, env.get_backups_dir(), num_backups=num_backups)
 
 
 async def _backup_task() -> BackupResult:
@@ -258,7 +286,7 @@ async def _backup_task() -> BackupResult:
     logger.info("Performing scheduled database backup.")
     if __db is None:
         raise RuntimeError("DB is not setup.")
-    return __db.backup_and_rotate(env.get_backups_dir(), num_backups=5)
+    return await asyncio.to_thread(__db.backup_and_rotate, env.get_backups_dir(), num_backups=5)
 
 
 async def _metrics() -> None:

tests/test_backup_rotation.py

@@ -7,6 +7,7 @@ cross-origin form post.
 """
 
 import sqlite3
+from contextlib import closing
 from pathlib import Path
 
 import pytest
@@ -140,3 +141,49 @@ def test_non_sqlite_database_is_skipped(backups: Path):
     result = db.backup_and_rotate(backups)
 
     assert result == database.BackupResult(None, created=False)
+
+
+def test_backup_gives_up_on_a_lock_that_never_clears(
+    db: Database,
+    db_path: Path,
+    backups: Path,
+    monkeypatch: pytest.MonkeyPatch,
+):
+    """sqlite3's backup() retries a locked source forever, which hung the server (#1191)."""
+    monkeypatch.setattr(database, "BACKUP_LOCK_TIMEOUT_SECONDS", 0.5)
+    with closing(sqlite3.connect(db_path, isolation_level=None)) as holder:
+        holder.execute("BEGIN EXCLUSIVE")
+        with pytest.raises(sqlite3.OperationalError, match="locked"):
+            db.backup_and_rotate(backups)
+        holder.execute("ROLLBACK")
+    assert not (backups / f"{BACKUP_NAME}.pending").exists()
+
+
+def test_backup_needs_no_lock_on_the_target(db: Database, backups: Path, monkeypatch: pytest.MonkeyPatch):
+    """Backup folders on network shares often refuse file locks, which failed every backup (#1246).
+
+    Simulate that by holding an exclusive lock on the target from the moment it is created.
+    """
+    monkeypatch.setattr(database, "BACKUP_LOCK_TIMEOUT_SECONDS", 0.5)
+    pending = backups / f"{BACKUP_NAME}.pending"
+    real_connect = sqlite3.connect
+    holders: list[sqlite3.Connection] = []
+
+    def connect(*args: object, **kwargs: object) -> sqlite3.Connection:
+        conn = real_connect(*args, **kwargs)
+        if pending.exists() and not holders:
+            holders.append(real_connect(pending, isolation_level=None))
+            holders[0].execute("BEGIN EXCLUSIVE")
+        return conn
+
+    monkeypatch.setattr(sqlite3, "connect", connect)
+    try:
+        result = db.backup_and_rotate(backups)
+    finally:
+        for holder in holders:
+            holder.close()
+
+    assert holders, "the target was never locked, so this test proves nothing"
+    assert result.created is True
+    with closing(real_connect(backups / BACKUP_NAME)) as conn:
+        assert conn.execute("SELECT note FROM spool").fetchall() == [("original",)]