From f5787764d41c53b4fb7c3902884c60d30ef1e2e5 Mon Sep 17 00:00:00 2001 From: BoulderBadgeDad Date: Fri, 12 Jun 2026 19:38:30 -0700 Subject: [PATCH] #859: DB-update stall watchdog + UI self-heal (no more wedged 'Starting...' / frozen bar) --- core/database_update_health.py | 82 +++++++++++++++++++++++++ tests/test_database_update_health.py | 92 ++++++++++++++++++++++++++++ web_server.py | 56 ++++++++++++++++- webui/static/sync-services.js | 17 +++-- webui/static/wishlist-tools.js | 35 +++++++++++ 5 files changed, 275 insertions(+), 7 deletions(-) create mode 100644 core/database_update_health.py create mode 100644 tests/test_database_update_health.py diff --git a/core/database_update_health.py b/core/database_update_health.py new file mode 100644 index 00000000..83b4fffb --- /dev/null +++ b/core/database_update_health.py @@ -0,0 +1,82 @@ +"""Stall detection for the database-update job. + +The DB updater keeps a single in-memory state dict whose ``status`` is set to +``running`` at start and only flipped to ``finished``/``error`` by the worker's +completion/error callbacks. If the worker thread hangs — e.g. a media-server API +call with no timeout, a DB lock — those callbacks never fire, so ``status`` stays +``running`` forever and the UI shows a frozen progress bar with no way to recover +(GitHub #859). + +This module is the single, *pure* decision for "is a running job stalled?". It +takes the state dict plus the current wall-clock time and a timeout, and answers +yes/no — no DB, no globals, no clock of its own. That keeps it unit-testable and +lets the watchdog wiring in web_server.py stay a thin call. The job carries a +``last_progress_at`` epoch timestamp that the start path and every progress/phase +callback bump; staleness is simply "running, and that timestamp is older than the +timeout". +""" + +from __future__ import annotations + +from typing import Any, Mapping + +# 5 minutes with zero forward progress = presumed hung. A healthy scan ticks +# progress (per-artist) far more often than this even for large libraries, so +# the timeout won't false-positive a slow-but-working run. +DEFAULT_STALL_TIMEOUT_SECONDS = 300 + + +def is_db_update_stalled( + state: Mapping[str, Any], + now: float, + timeout_seconds: float = DEFAULT_STALL_TIMEOUT_SECONDS, +) -> bool: + """Return True when the job is ``running`` but has made no progress within + ``timeout_seconds``. + + Conservative by design — it only ever reports a stall it can prove: + - Only a ``running`` job can stall (idle/finished/error never do). + - With no usable ``last_progress_at`` timestamp we cannot judge, so we return + False rather than risk killing a job we have no clock for. + - A non-positive timeout is treated as "disabled" (never stalls). + """ + if not isinstance(state, Mapping): + return False + if state.get("status") != "running": + return False + if timeout_seconds is None or timeout_seconds <= 0: + return False + last = state.get("last_progress_at") + if not last: + return False + try: + elapsed = float(now) - float(last) + except (TypeError, ValueError): + return False + return elapsed >= float(timeout_seconds) + + +def stalled_error_message(state: Mapping[str, Any], now: float) -> str: + """Build a clear, human-facing message for a stalled job, including how long + it has been silent and the phase it died in.""" + last = state.get("last_progress_at") if isinstance(state, Mapping) else None + phase = state.get("phase") if isinstance(state, Mapping) else None + try: + secs = int(float(now) - float(last)) if last else 0 + except (TypeError, ValueError): + secs = 0 + msg = "Update appears stuck — no progress" + if secs > 0: + msg += f" for {secs}s" + if phase: + msg += f" (last phase: {phase})" + msg += (". The worker may be hung on the media server. Start a new update " + "to try again, or restart SoulSync if it keeps stalling.") + return msg + + +__all__ = [ + "DEFAULT_STALL_TIMEOUT_SECONDS", + "is_db_update_stalled", + "stalled_error_message", +] diff --git a/tests/test_database_update_health.py b/tests/test_database_update_health.py new file mode 100644 index 00000000..770a34a7 --- /dev/null +++ b/tests/test_database_update_health.py @@ -0,0 +1,92 @@ +"""Seam tests for the database-update stall watchdog (GitHub #859). + +A DB-update job can hang (media-server call with no timeout, DB lock) and sit at +status='running' forever because the worker's finished/error callbacks never +fire. `is_db_update_stalled` is the pure decision that lets the watchdog flip +such a job to 'error' so the UI recovers. These tests pin that decision — +including the conservative cases where it must NOT false-positive. +""" + +from __future__ import annotations + +from core.database_update_health import ( + DEFAULT_STALL_TIMEOUT_SECONDS, + is_db_update_stalled, + stalled_error_message, +) + + +def _state(**over): + base = {"status": "running", "phase": "Incremental: scanning", + "processed": 2, "total": 3, "progress": 66.7, "last_progress_at": 1000.0} + base.update(over) + return base + + +def test_running_and_heartbeat_stale_is_stalled(): + # last tick at t=1000, now=1000+timeout → exactly at the boundary counts. + now = 1000.0 + DEFAULT_STALL_TIMEOUT_SECONDS + assert is_db_update_stalled(_state(), now) is True + + +def test_running_and_heartbeat_fresh_is_not_stalled(): + now = 1000.0 + 5 # ticked 5s ago, well within timeout + assert is_db_update_stalled(_state(), now) is False + + +def test_just_under_timeout_is_not_stalled(): + now = 1000.0 + DEFAULT_STALL_TIMEOUT_SECONDS - 0.001 + assert is_db_update_stalled(_state(), now) is False + + +def test_non_running_statuses_never_stall(): + now = 1000.0 + 10_000 # very stale heartbeat + for status in ("idle", "finished", "error"): + assert is_db_update_stalled(_state(status=status), now) is False, status + + +def test_missing_heartbeat_cannot_judge(): + # No usable timestamp → we refuse to kill a job we have no clock for. + now = 1_000_000.0 + assert is_db_update_stalled(_state(last_progress_at=0), now) is False + assert is_db_update_stalled(_state(last_progress_at=None), now) is False + s = _state() + del s["last_progress_at"] + assert is_db_update_stalled(s, now) is False + + +def test_non_positive_timeout_disables_watchdog(): + now = 1000.0 + 10_000 + assert is_db_update_stalled(_state(), now, timeout_seconds=0) is False + assert is_db_update_stalled(_state(), now, timeout_seconds=-1) is False + + +def test_bad_inputs_are_safe(): + assert is_db_update_stalled(None, 123.0) is False + assert is_db_update_stalled("not a dict", 123.0) is False + assert is_db_update_stalled(_state(last_progress_at="oops"), 1_000_000.0) is False + + +def test_custom_timeout_respected(): + now = 1000.0 + 120 + assert is_db_update_stalled(_state(), now, timeout_seconds=60) is True + assert is_db_update_stalled(_state(), now, timeout_seconds=180) is False + + +def test_stalled_message_is_informative(): + now = 1000.0 + 360 + msg = stalled_error_message(_state(phase="Incremental: scanning"), now) + assert "stuck" in msg.lower() + assert "360s" in msg + assert "Incremental: scanning" in msg + + +def test_issue_859_frozen_running_job_is_caught(): + """Regression: the reported state — running, frozen at 2/3 (66.7%), heartbeat + long stale — is detected as stalled so the card can self-heal.""" + state = _state(status="running", processed=2, total=3, progress=66.7, + last_progress_at=1000.0) + now = 1000.0 + DEFAULT_STALL_TIMEOUT_SECONDS + 30 + assert is_db_update_stalled(state, now) is True + # And a healthy job that's actively ticking is left alone. + assert is_db_update_stalled(_state(last_progress_at=now - 2), now) is False diff --git a/web_server.py b/web_server.py index 6963ee2c..3d1c010d 100644 --- a/web_server.py +++ b/web_server.py @@ -973,6 +973,10 @@ db_update_state = { "removed_artists": 0, "removed_albums": 0, "removed_tracks": 0, + # Heartbeat epoch (seconds): bumped at start and on every progress/phase + # callback. The stall watchdog (core.database_update_health) flips a job to + # 'error' when this goes stale while status is still 'running' (#859). + "last_progress_at": 0, } _db_update_automation_id = None # Set when automation triggers DB update, used by callbacks db_update_lock = threading.Lock() @@ -8099,7 +8103,8 @@ def request_incremental_database_update(): with db_update_lock: db_update_state.update({ "status": "running", "phase": "Initializing...", - "progress": 0, "current_item": "", "processed": 0, "total": 0, "error_message": "" + "progress": 0, "current_item": "", "processed": 0, "total": 0, "error_message": "", + "last_progress_at": time.time(), # seed heartbeat for the stall watchdog }) db_update_executor.submit(_run_db_update_task, False, active_server) @@ -15723,7 +15728,8 @@ def _db_update_progress_callback(current_item, processed, total, percentage): "current_item": current_item, "processed": processed, "total": total, - "progress": percentage + "progress": percentage, + "last_progress_at": time.time(), # heartbeat for the stall watchdog }) _update_automation_progress(_db_update_automation_id, progress=percentage, processed=processed, total=total, @@ -15733,6 +15739,7 @@ def _db_update_phase_callback(phase): logger.info(f"[DB Phase] {phase}") with db_update_lock: db_update_state["phase"] = phase + db_update_state["last_progress_at"] = time.time() # heartbeat for the stall watchdog _update_automation_progress(_db_update_automation_id, phase=phase) def _db_update_artist_callback(artist_name, success, details, album_count, track_count): @@ -15853,6 +15860,44 @@ def _db_update_error_callback(error_message): # Add activity for database update error add_activity_item("", "Database Update Failed", error_message, "Now") + +def _check_db_update_stall(): + """Watchdog: flip a hung 'running' DB-update job to 'error' so the UI can + recover (#859). A worker that blocks indefinitely (media-server call with no + timeout, DB lock) never fires its finished/error callback, so the job would + otherwise sit at 'running' forever with a frozen progress bar. + + Idempotent — only acts on the running→stalled transition (after the flip, + status != 'running' so the pure check returns False and we don't re-fire). + Safe to call from the status endpoint and the 1s broadcast loop. Returns True + only on the transition.""" + from core.database_update_health import ( + DEFAULT_STALL_TIMEOUT_SECONDS, + is_db_update_stalled, + stalled_error_message, + ) + try: + timeout = config_manager.get('database.update_stall_timeout_seconds', + DEFAULT_STALL_TIMEOUT_SECONDS) + except Exception: + timeout = DEFAULT_STALL_TIMEOUT_SECONDS + now = time.time() + with db_update_lock: + if not is_db_update_stalled(db_update_state, now, timeout): + return False + msg = stalled_error_message(db_update_state, now) + db_update_state["status"] = "error" + db_update_state["error_message"] = msg + db_update_state["phase"] = "Stalled" + logger.error(f"[DB Update Watchdog] {msg}") + # The hung worker paused enrichment/maintenance workers and won't resume them + # itself — resume here so a stall doesn't leave them parked indefinitely. + try: + _resume_workers_after_scan() + except Exception as e: + logger.debug(f"[DB Update Watchdog] resume workers failed: {e}") + return True + _workers_paused_by_scan = set() # Track which workers WE paused (don't resume manually-paused ones) def _pause_workers_for_scan(): @@ -16719,7 +16764,10 @@ def start_database_update(): db_update_state.update({ "status": "running", "phase": f"{scan_type}: Initializing...", - "progress": 0, "current_item": "", "processed": 0, "total": 0, "error_message": "" + "progress": 0, "current_item": "", "processed": 0, "total": 0, "error_message": "", + # Seed the heartbeat now so a worker that hangs during init (before the + # first progress/phase callback) is still caught by the stall watchdog. + "last_progress_at": time.time(), }) # Add activity for database update start @@ -16737,6 +16785,7 @@ def start_database_update(): @app.route('/api/database/update/status', methods=['GET']) def get_database_update_status(): """Endpoint to poll for the current update status.""" + _check_db_update_stall() # self-heal a hung job before reporting (#859) with db_update_lock: # Debug: Log current state occasionally if db_update_state["status"] == "running": @@ -37158,6 +37207,7 @@ def _emit_tool_progress_loop(): logger.debug(f"Error emitting duplicate cleaner status: {e}") # DB Update try: + _check_db_update_stall() # self-heal a hung job, then broadcast (#859) with db_update_lock: socketio.emit('tool:db-update', dict(db_update_state)) except Exception as e: diff --git a/webui/static/sync-services.js b/webui/static/sync-services.js index f375bdd3..de14d351 100644 --- a/webui/static/sync-services.js +++ b/webui/static/sync-services.js @@ -4063,7 +4063,11 @@ async function handleDbUpdateButtonClick() { } try { - button.disabled = true; + // Leave the button ENABLED while "Starting..." so it doubles as a + // cancel affordance — a wedged start (#859) must stay clickable. A + // second click reads "Starting..." and falls through to the stop + // branch below, so there's no double-start risk. + button.disabled = false; button.textContent = 'Starting...'; const response = await fetch('/api/database/update', { method: 'POST', @@ -4072,14 +4076,19 @@ async function handleDbUpdateButtonClick() { // scan takes precedence server-side, so send only its flag. body: JSON.stringify(isDeepScan ? { deep_scan: true } : { full_refresh: isFullRefresh }) }); + const data = await response.json().catch(() => ({})); - if (response.ok) { + // Check BOTH the HTTP status and the body's success flag — a 200 with + // success:false must not be mistaken for a started job (#859). + if (response.ok && data.success !== false) { showToast('Database update started!', 'success'); // Start polling immediately to get live status checkAndUpdateDbProgress(); + // Socket-independent safety net: recovers the card from + // "Starting..." even if the WebSocket goes quiet/half-open (#859). + armDbUpdateSafetyPoll(); } else { - const errorData = await response.json(); - showToast(`Error: ${errorData.error}`, 'error'); + showToast(`Error: ${data.error || 'Failed to start update.'}`, 'error'); button.disabled = false; button.textContent = 'Update Database'; } diff --git a/webui/static/wishlist-tools.js b/webui/static/wishlist-tools.js index e47fd5d6..9cfed00f 100644 --- a/webui/static/wishlist-tools.js +++ b/webui/static/wishlist-tools.js @@ -8280,6 +8280,30 @@ function updateDbProgressFromData(data) { updateDbProgressUI(data); } +// Socket-independent safety net for the DB-updater card. The 1s WebSocket +// broadcast normally drives the card, but if the socket goes quiet/half-open the +// card can wedge on "Starting..." with a frozen bar and no recovery (#859). This +// polls /status directly, applies the same idempotent UI update, and stops itself +// once the job is no longer running. +let _dbUpdateSafetyPoll = null; +function armDbUpdateSafetyPoll() { + if (_dbUpdateSafetyPoll) { clearInterval(_dbUpdateSafetyPoll); _dbUpdateSafetyPoll = null; } + const tick = async () => { + try { + const r = await fetch('/api/database/update/status'); + if (!r.ok) return; + const state = await r.json(); + updateDbProgressUI(state); + if (state.status !== 'running') { + clearInterval(_dbUpdateSafetyPoll); + _dbUpdateSafetyPoll = null; + } + } catch (e) { /* transient — keep the safety net armed */ } + }; + tick(); // immediate: flip off "Starting..." as soon as the server confirms state + _dbUpdateSafetyPoll = setInterval(tick, 5000); +} + function updateDbProgressUI(state) { const button = document.getElementById('db-update-button'); const phaseLabel = document.getElementById('db-phase-label'); @@ -8311,6 +8335,17 @@ function updateDbProgressUI(state) { progressBar.style.backgroundColor = 'rgb(var(--accent-rgb))'; // Green for normal } + // Reset the bar/label so a finished/idle/error card doesn't keep showing a + // frozen partial bar from the previous run (e.g. "2/3 artists 66.7%" left + // over after completion) — the #859 confusion. Finished → full bar; any + // other terminal state → cleared bar. The phase label carries the summary. + if (state.status === 'finished') { + progressBar.style.width = '100%'; + } else { + progressBar.style.width = '0%'; + } + progressLabel.textContent = ''; + if (state.status === 'finished' || state.status === 'error') { // Final stats refresh after completion/error setTimeout(fetchAndUpdateDbStats, 500);