diff --git a/config/settings.py b/config/settings.py index 19b24e6c..94105426 100644 --- a/config/settings.py +++ b/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.execute("PRAGMA journal_mode=WAL") + conn = self._connect_db() 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.execute("PRAGMA journal_mode=WAL") + conn = self._connect_db() 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.execute("PRAGMA journal_mode=WAL") + conn = self._connect_db() 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 = sqlite3.connect(str(self.database_path), timeout=30.0) - conn.execute("PRAGMA journal_mode=WAL") + conn = self._connect_db() 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.""" - success = self._save_to_database(self.config_data) + """Save configuration to database with exponential-backoff retry on lock. - if not success: - # Retry once after a brief wait (handles transient lock contention) - import time - time.sleep(1) - success = self._save_to_database(self.config_data) + Spread retries over ~7 seconds so a long-held writer (enrichment + worker batch insert, library scan commit, etc.) on a slow disk + has time to release the lock before we fall back to the JSON + file. The single 1s retry that used to live here gave up too + 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: - # Fallback: Try to save to config.json if database fails - logger.warning("Database save failed - attempting file fallback") - 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.info("Configuration saved to config.json as fallback") - except Exception as e: - logger.error(f"Failed to save configuration: {e}") + for delay in retry_delays: + time.sleep(delay) + if self._save_to_database(self.config_data): + return + + # All retries exhausted — fall back to config.json so the user + # doesn't lose their settings, then log a single error. + logger.error( + f"Config DB save failed after {len(retry_delays) + 1} attempts (database is locked) — " + "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('.') diff --git a/tests/test_config_save_retry.py b/tests/test_config_save_retry.py new file mode 100644 index 00000000..7214849e --- /dev/null +++ b/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