Merge pull request #447 from Nezreka/fix/config-db-locking

Fix config DB lock spam on slow disks (#434)

config/settings.py

@@ -2,6 +2,7 @@ import copy
 import json
 import os
 import sqlite3
+import time
 from typing import Dict, Any, Optional
 from cryptography.fernet import Fernet, InvalidToken
 from pathlib import Path
@@ -220,7 +221,7 @@ class ConfigManager:
         """Re-save config to encrypt any plaintext sensitive values still in the DB."""
         try:
             # Read raw DB content to check if any sensitive value is still plaintext
-            conn = sqlite3.connect(str(self.database_path))
+            conn = self._connect_db()
             cursor = conn.cursor()
             cursor.execute("SELECT value FROM metadata WHERE key = 'app_config'")
             row = cursor.fetchone()
@@ -257,6 +258,19 @@ class ConfigManager:
         except Exception as e:
             logger.warning(f"Could not migrate encryption: {e}")
 
+    def _connect_db(self) -> sqlite3.Connection:
+        """Open a configured SQLite connection for the config DB.
+
+        Centralizes pragma setup so every connection gets WAL mode,
+        a 30s busy timeout, and synchronous=NORMAL (the safe pairing
+        with WAL that avoids unnecessary fsyncs on slow disks).
+        """
+        conn = sqlite3.connect(str(self.database_path), timeout=30.0)
+        conn.execute("PRAGMA journal_mode=WAL")
+        conn.execute("PRAGMA busy_timeout=30000")
+        conn.execute("PRAGMA synchronous=NORMAL")
+        return conn
+
     def _ensure_database_exists(self):
         """Ensure database file and metadata table exist"""
         try:
@@ -264,8 +278,7 @@ class ConfigManager:
             self.database_path.parent.mkdir(parents=True, exist_ok=True)
 
             # Connect to database (creates file if it doesn't exist)
-            conn = sqlite3.connect(str(self.database_path), timeout=30.0)
+            conn = self._connect_db()
-            conn.execute("PRAGMA journal_mode=WAL")
             cursor = conn.cursor()
 
             # Create metadata table if it doesn't exist
@@ -287,8 +300,7 @@ class ConfigManager:
         try:
             self._ensure_database_exists()
 
-            conn = sqlite3.connect(str(self.database_path), timeout=30.0)
+            conn = self._connect_db()
-            conn.execute("PRAGMA journal_mode=WAL")
             cursor = conn.cursor()
             cursor.execute("SELECT value FROM metadata WHERE key = 'app_config'")
             row = cursor.fetchone()
@@ -314,8 +326,7 @@ class ConfigManager:
         conn = None
         try:
             self._ensure_database_exists()
-            conn = sqlite3.connect(str(self.database_path), timeout=30.0)
+            conn = self._connect_db()
-            conn.execute("PRAGMA journal_mode=WAL")
             cursor = conn.cursor()
             cursor.execute("SELECT value FROM metadata WHERE key = 'log_level'")
             row = cursor.fetchone()
@@ -362,7 +373,13 @@ class ConfigManager:
         return config_data
 
     def _save_to_database(self, config_data: Dict[str, Any]) -> bool:
-        """Save configuration to database, encrypting sensitive values."""
+        """Save configuration to database, encrypting sensitive values.
+
+        Returns ``True`` on success. Transient ``database is locked``
+        failures are logged at DEBUG so the caller's retry loop owns the
+        user-visible error message — otherwise every retry would spam
+        ERROR-level logs even when the next attempt succeeds.
+        """
         conn = None
         try:
             self._ensure_database_exists()
@@ -370,9 +387,7 @@ class ConfigManager:
             # Encrypt sensitive values before writing (original dict is untouched)
             encrypted_data = self._encrypt_sensitive(config_data)
 
-            # Use longer timeout (30s) to handle contention from enrichment workers
+            conn = self._connect_db()
-            conn = sqlite3.connect(str(self.database_path), timeout=30.0)
-            conn.execute("PRAGMA journal_mode=WAL")
             cursor = conn.cursor()
 
             config_json = json.dumps(encrypted_data, indent=2)
@@ -384,6 +399,16 @@ class ConfigManager:
             conn.commit()
             return True
 
+        except sqlite3.OperationalError as e:
+            # SQLite raises OperationalError("database is locked") when the
+            # busy_timeout expires while another writer holds the lock.
+            # Log at DEBUG so the caller can decide whether the final
+            # outcome warrants an ERROR-level message.
+            if "locked" in str(e).lower():
+                logger.debug(f"Config DB locked, will retry: {e}")
+            else:
+                logger.error(f"Could not save config to database: {e}")
+            return False
         except Exception as e:
             logger.error(f"Could not save config to database: {e}")
             return False
@@ -607,25 +632,38 @@ class ConfigManager:
         self.config_data = self._apply_log_level_overrides(config_data)
 
     def _save_config(self):
-        """Save configuration to database with retry on lock."""
+        """Save configuration to database with exponential-backoff retry on lock.
-        success = self._save_to_database(self.config_data)
 
-        if not success:
+        Spread retries over ~7 seconds so a long-held writer (enrichment
-            # Retry once after a brief wait (handles transient lock contention)
+        worker batch insert, library scan commit, etc.) on a slow disk
-            import time
+        has time to release the lock before we fall back to the JSON
-            time.sleep(1)
+        file. The single 1s retry that used to live here gave up too
-            success = self._save_to_database(self.config_data)
+        early on HDD-backed Docker volumes.
+        """
+        # Cumulative delay across attempts: 0.2 + 0.5 + 1.0 + 2.0 + 4.0 = 7.7s
+        # plus the 30s busy_timeout that already runs inside each attempt.
+        retry_delays = [0.2, 0.5, 1.0, 2.0, 4.0]
+        if self._save_to_database(self.config_data):
+            return
 
-        if not success:
+        for delay in retry_delays:
-            # Fallback: Try to save to config.json if database fails
+            time.sleep(delay)
-            logger.warning("Database save failed - attempting file fallback")
+            if self._save_to_database(self.config_data):
-            try:
+                return
-                self.config_path.parent.mkdir(parents=True, exist_ok=True)
+
-                with open(self.config_path, 'w') as f:
+        # All retries exhausted — fall back to config.json so the user
-                    json.dump(self.config_data, f, indent=2)
+        # doesn't lose their settings, then log a single error.
-                logger.info("Configuration saved to config.json as fallback")
+        logger.error(
-            except Exception as e:
+            f"Config DB save failed after {len(retry_delays) + 1} attempts (database is locked) — "
-                logger.error(f"Failed to save configuration: {e}")
+            "falling back to config.json"
+        )
+        try:
+            self.config_path.parent.mkdir(parents=True, exist_ok=True)
+            with open(self.config_path, 'w') as f:
+                json.dump(self.config_data, f, indent=2)
+            logger.warning("Configuration saved to config.json as fallback")
+        except Exception as e:
+            logger.error(f"Failed to save configuration: {e}")
 
     def get(self, key: str, default: Any = None) -> Any:
         keys = key.split('.')

tests/test_config_save_retry.py

@@ -0,0 +1,174 @@
+"""Regression tests for ConfigManager._save_config retry behaviour.
+
+The DB-locking spam reported in #434 was caused by an aggressive retry
+loop that gave up after one second and logged each transient lock as
+ERROR. These tests pin the new behaviour:
+
+- Lock errors during retries log at DEBUG, not ERROR (no spam).
+- Six attempts with exponential backoff before giving up.
+- Successful retry after a few transient locks emits zero ERROR logs.
+- Genuine exhaustion logs a single ERROR and falls back to config.json.
+- Non-lock OperationalErrors don't trigger the lock-specific quiet path.
+"""
+
+import json
+import logging
+import sqlite3
+from pathlib import Path
+from unittest.mock import patch
+
+import pytest
+
+from config.settings import ConfigManager
+
+
+@pytest.fixture
+def manager(tmp_path: Path, monkeypatch: pytest.MonkeyPatch) -> ConfigManager:
+    """Build a ConfigManager rooted at a tmp dir so every test starts clean."""
+    config_path = tmp_path / "config.json"
+    db_path = tmp_path / "database" / "music_library.db"
+    monkeypatch.setenv("SOULSYNC_CONFIG_PATH", str(config_path))
+    monkeypatch.setenv("SOULSYNC_DB_PATH", str(db_path))
+    mgr = ConfigManager(str(config_path))
+    # Replace whatever was loaded with a known payload so we can assert on it
+    mgr.config_data = {"plex": {"base_url": "http://example.test"}}
+    return mgr
+
+
+# ---------------------------------------------------------------------------
+# Helpers
+# ---------------------------------------------------------------------------
+
+
+def _fail_n_times_then_succeed(n: int, manager: ConfigManager):
+    """Patch ``_save_to_database`` so the first ``n`` calls fail (lock),
+    then subsequent calls succeed."""
+    state = {"calls": 0}
+    real_save = manager._save_to_database
+
+    def stub(config_data):
+        state["calls"] += 1
+        if state["calls"] <= n:
+            return False
+        return real_save(config_data)
+
+    return stub, state
+
+
+# ---------------------------------------------------------------------------
+# Tests
+# ---------------------------------------------------------------------------
+
+
+def test_save_succeeds_on_first_attempt_emits_no_error_logs(
+    manager: ConfigManager, caplog: pytest.LogCaptureFixture
+) -> None:
+    """Happy path: a successful save should not log at ERROR."""
+    caplog.set_level(logging.DEBUG, logger="soulsync.config")
+    with patch("config.settings.time.sleep") as sleep_mock:
+        with patch.object(manager, "_save_to_database", return_value=True) as save_mock:
+            manager._save_config()
+    assert save_mock.call_count == 1
+    sleep_mock.assert_not_called()
+    error_logs = [r for r in caplog.records if r.levelno >= logging.ERROR]
+    assert error_logs == []
+
+
+def test_lock_errors_during_retries_log_at_debug_not_error(
+    manager: ConfigManager, caplog: pytest.LogCaptureFixture
+) -> None:
+    """Three transient locks then success should produce DEBUG noise only."""
+    caplog.set_level(logging.DEBUG, logger="soulsync.config")
+    stub, state = _fail_n_times_then_succeed(3, manager)
+    with patch("config.settings.time.sleep") as sleep_mock:
+        with patch.object(manager, "_save_to_database", side_effect=stub):
+            with patch.object(manager, "_ensure_database_exists"):
+                manager._save_config()
+    assert state["calls"] == 4
+    assert sleep_mock.call_count == 3
+    error_logs = [r for r in caplog.records if r.levelno >= logging.ERROR]
+    assert error_logs == [], "transient locks should not log ERROR"
+
+
+def test_save_uses_six_attempts_with_exponential_backoff(
+    manager: ConfigManager,
+) -> None:
+    """All six attempts must run, with the documented backoff schedule."""
+    with patch("config.settings.time.sleep") as sleep_mock:
+        with patch.object(manager, "_save_to_database", return_value=False) as save_mock:
+            with patch("builtins.open"):  # silence the json fallback's filesystem write
+                with patch.object(Path, "mkdir"):
+                    manager._save_config()
+    assert save_mock.call_count == 6
+    expected_delays = [0.2, 0.5, 1.0, 2.0, 4.0]
+    actual_delays = [c.args[0] for c in sleep_mock.call_args_list]
+    assert actual_delays == expected_delays
+
+
+def test_all_retries_exhausted_logs_single_error_and_falls_back_to_json(
+    manager: ConfigManager, caplog: pytest.LogCaptureFixture, tmp_path: Path
+) -> None:
+    """Exhausting retries should produce one ERROR log + one fallback file."""
+    caplog.set_level(logging.DEBUG, logger="soulsync.config")
+    manager.config_path = tmp_path / "config.json"
+    with patch("config.settings.time.sleep"):
+        with patch.object(manager, "_save_to_database", return_value=False):
+            manager._save_config()
+    error_logs = [r for r in caplog.records if r.levelno == logging.ERROR]
+    assert len(error_logs) == 1
+    assert "falling back to config.json" in error_logs[0].getMessage()
+    assert manager.config_path.exists()
+    payload = json.loads(manager.config_path.read_text())
+    assert payload["plex"]["base_url"] == "http://example.test"
+
+
+def test_save_to_database_lock_error_logs_at_debug(
+    manager: ConfigManager, caplog: pytest.LogCaptureFixture
+) -> None:
+    """sqlite3.OperationalError("...locked...") must surface as DEBUG only."""
+    caplog.set_level(logging.DEBUG, logger="soulsync.config")
+    with patch.object(manager, "_ensure_database_exists"):
+        with patch("config.settings.sqlite3.connect") as connect_mock:
+            connect_mock.return_value.execute.side_effect = sqlite3.OperationalError(
+                "database is locked"
+            )
+            ok = manager._save_to_database({"x": 1})
+    assert ok is False
+    error_logs = [r for r in caplog.records if r.levelno >= logging.ERROR]
+    assert error_logs == []
+    debug_logs = [
+        r for r in caplog.records
+        if r.levelno == logging.DEBUG and "locked" in r.getMessage().lower()
+    ]
+    assert len(debug_logs) == 1
+
+
+def test_save_to_database_non_lock_operational_error_logs_at_error(
+    manager: ConfigManager, caplog: pytest.LogCaptureFixture
+) -> None:
+    """A non-lock OperationalError is a real failure and must log ERROR."""
+    caplog.set_level(logging.DEBUG, logger="soulsync.config")
+    with patch.object(manager, "_ensure_database_exists"):
+        with patch("config.settings.sqlite3.connect") as connect_mock:
+            connect_mock.return_value.execute.side_effect = sqlite3.OperationalError(
+                "no such table: metadata"
+            )
+            ok = manager._save_to_database({"x": 1})
+    assert ok is False
+    error_logs = [r for r in caplog.records if r.levelno >= logging.ERROR]
+    assert len(error_logs) == 1
+
+
+def test_connect_db_sets_required_pragmas(manager: ConfigManager) -> None:
+    """All four pragmas must be applied on every config-DB connection."""
+    conn = manager._connect_db()
+    try:
+        journal_mode = conn.execute("PRAGMA journal_mode").fetchone()[0]
+        busy_timeout = conn.execute("PRAGMA busy_timeout").fetchone()[0]
+        synchronous = conn.execute("PRAGMA synchronous").fetchone()[0]
+    finally:
+        conn.close()
+    assert journal_mode.lower() == "wal"
+    assert busy_timeout == 30000
+    # synchronous returns 0=OFF, 1=NORMAL, 2=FULL, 3=EXTRA
+    assert synchronous == 1