From bcc1ba1ace0e5a594eb22ffc2ae58fd1870e18f5 Mon Sep 17 00:00:00 2001 From: Donkie Date: Sun, 27 Sep 2026 08:22:17 +0200 Subject: [PATCH 1/2] Stop a locked database from hanging the server during backup sqlite3's Connection.backup() retries forever while the source is busy, calling progress with 0 of 0 pages each time. The backup ran synchronously on the event loop, so a lock that did not clear froze every request and spammed "Copied 0 of 0 pages." into the log (#1191). Run backups in a worker thread, give up after the source has been locked for 60 seconds, and serialize backups now that they can overlap. Per-page progress drops to debug. --- spoolman/database/database.py | 33 ++++++++++++++++++++++++++++----- tests/test_backup_rotation.py | 17 +++++++++++++++++ 2 files changed, 45 insertions(+), 5 deletions(-) diff --git a/spoolman/database/database.py b/spoolman/database/database.py index 63eefb58..6f9c7559 100644 --- a/spoolman/database/database.py +++ b/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,19 @@ 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 stayed locked for over {BACKUP_LOCK_TIMEOUT_SECONDS} seconds, giving up on the backup.", + ) if self.connection_url.database == target_path: raise ValueError("Cannot backup database to itself.") @@ -191,7 +209,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 +272,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 +281,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: diff --git a/tests/test_backup_rotation.py b/tests/test_backup_rotation.py index 3aa2dc8f..09065c60 100644 --- a/tests/test_backup_rotation.py +++ b/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,19 @@ 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() From 016ca6791eedd7ffffc102eeacd576be3aa5ddfb Mon Sep 17 00:00:00 2001 From: Donkie Date: Sat, 10 Oct 2026 14:36:01 +0200 Subject: [PATCH 2/2] Back up to the target without taking file locks on it Backup folders on network shares often refuse SQLite's file locks (CIFS without nobrl, NFS without lockd). SQLite reports a refused lock as SQLITE_BUSY, so every backup to such a folder retried until the 60 second give-up and blamed a locked database, while the live database was not locked at all (#1246). The target is a scratch .pending file that nothing else opens, so open it with nolock=1. The give-up message now names the live database, since that is the only file a backup can still wait on. --- spoolman/database/database.py | 9 +++++++-- tests/test_backup_rotation.py | 30 ++++++++++++++++++++++++++++++ 2 files changed, 37 insertions(+), 2 deletions(-) diff --git a/spoolman/database/database.py b/spoolman/database/database.py index 6f9c7559..782df215 100644 --- a/spoolman/database/database.py +++ b/spoolman/database/database.py @@ -152,7 +152,9 @@ class Database: busy_since = busy_since or time.monotonic() if time.monotonic() - busy_since > BACKUP_LOCK_TIMEOUT_SECONDS: raise sqlite3.OperationalError( - f"Database stayed locked for over {BACKUP_LOCK_TIMEOUT_SECONDS} seconds, giving up on the backup.", + 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: @@ -164,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) diff --git a/tests/test_backup_rotation.py b/tests/test_backup_rotation.py index 09065c60..d447dd6e 100644 --- a/tests/test_backup_rotation.py +++ b/tests/test_backup_rotation.py @@ -157,3 +157,33 @@ def test_backup_gives_up_on_a_lock_that_never_clears( 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",)]