diff --git a/core/automation/handlers/database_update.py b/core/automation/handlers/database_update.py index a9d51036..d123be24 100644 --- a/core/automation/handlers/database_update.py +++ b/core/automation/handlers/database_update.py @@ -21,12 +21,49 @@ from typing import Any, Dict from core.automation.deps import AutomationDeps -_TIMEOUT_SECONDS = 7200 # 2 hours — covers the worst large-library case -_STALL_WARNING_SECONDS = 600 # 10 minutes without progress = stall +# Time out on STALL (no progress), not total runtime: a large library can scan +# for many hours while progressing fine — a hard total cap would falsely mark a +# healthy scan 'error' (the scan thread keeps running uncancelled). We only give +# up when progress hasn't moved for a long stretch, with a generous absolute +# backstop against a truly stuck monitor loop. +_STALL_WARNING_SECONDS = 600 # warn after 10 min with no progress (repeats) +_STALL_TIMEOUT_SECONDS = 1800 # 30 min with no progress at all = genuinely stalled +_ABSOLUTE_CAP_SECONDS = 86400 # 24h hard backstop (runaway-loop guard only) _POLL_INTERVAL_SECONDS = 3 _INITIAL_DELAY_SECONDS = 1 +def scan_wait_action( + *, + status: str, + idle_seconds: float, + total_seconds: float, + stall_timeout_s: float = _STALL_TIMEOUT_SECONDS, + stall_warn_s: float = _STALL_WARNING_SECONDS, + abs_cap_s: float = _ABSOLUTE_CAP_SECONDS, +) -> str: + """Decide what the monitor loop should do on a poll tick (pure/testable). + + ``idle_seconds`` is time since progress last changed; ``total_seconds`` is + time since the wait began. Returns one of: + ``'finished'`` (task no longer running), ``'stall_timeout'`` (no progress for + too long → give up), ``'abs_timeout'`` (absolute backstop), ``'warn'`` + (stalled long enough to warn but not give up), or ``'continue'``. + + Crucially, an actively-progressing scan keeps resetting ``idle_seconds``, so + it never hits ``stall_timeout`` no matter how long the whole scan takes. + """ + if status != 'running': + return 'finished' + if total_seconds >= abs_cap_s: + return 'abs_timeout' + if idle_seconds >= stall_timeout_s: + return 'stall_timeout' + if idle_seconds >= stall_warn_s: + return 'warn' + return 'continue' + + def auto_start_database_update(config: Dict[str, Any], deps: AutomationDeps) -> Dict[str, Any]: """Run a full or incremental DB update via ``run_db_update_task``.""" return _run_with_progress( @@ -36,7 +73,7 @@ def auto_start_database_update(config: Dict[str, Any], deps: AutomationDeps) -> initial_phase='Initializing...', stall_label='Database update', finished_extras=lambda: {'full_refresh': str(config.get('full_refresh', False))}, - timeout_label='Database update timed out after 2 hours', + timeout_label='Database update timed out after 24 hours', ) @@ -49,7 +86,7 @@ def auto_deep_scan_library(config: Dict[str, Any], deps: AutomationDeps) -> Dict initial_phase='Deep scan: Initializing...', stall_label='Deep scan', finished_extras=lambda: {}, - timeout_label='Deep scan timed out after 2 hours', + timeout_label='Deep scan timed out after 24 hours', ) @@ -83,30 +120,54 @@ def _run_with_progress( deps.db_update_executor.submit(task, *task_args) # Monitor progress (callbacks handle card updates, we just block until done). + # We time out on STALL, not total runtime: ``processed`` advances on every + # artist, so an actively-progressing scan keeps resetting the idle clock and + # is never falsely failed no matter how long the whole library takes. time.sleep(_INITIAL_DELAY_SECONDS) poll_start = time.time() last_progress_time = time.time() - last_progress_val = 0 - while time.time() - poll_start < _TIMEOUT_SECONDS: + # Any of these advancing means the scan is alive. current_item (the artist + # being processed) changes every artist even when the rounded progress % + # holds steady, so it guards against a false stall during slow stretches. + last_progress_val = (0, 0, '') + last_warn_time = 0.0 + outcome = 'finished' + while True: time.sleep(_POLL_INTERVAL_SECONDS) + now = time.time() with deps.db_update_lock: current_status = state.get('status', 'idle') - current_progress = state.get('progress', 0) - if current_status != 'running': + current_val = (state.get('processed', 0), state.get('progress', 0), + state.get('current_item', '')) + if current_val != last_progress_val: + last_progress_val = current_val + last_progress_time = now + + action = scan_wait_action( + status=current_status, + idle_seconds=now - last_progress_time, + total_seconds=now - poll_start, + ) + if action in ('finished', 'stall_timeout', 'abs_timeout'): + outcome = action break - # Stall detection — if no progress change in 10 minutes, warn. - if current_progress != last_progress_val: - last_progress_val = current_progress - last_progress_time = time.time() - elif time.time() - last_progress_time > _STALL_WARNING_SECONDS: + if action == 'warn' and (now - last_warn_time) > _STALL_WARNING_SECONDS: + idle_min = int((now - last_progress_time) / 60) deps.update_progress( automation_id, - log_line=f'{stall_label} appears stalled — waiting...', + log_line=f'{stall_label} — no progress for {idle_min} min, still waiting...', log_type='warning', ) - last_progress_time = time.time() # Reset so warning repeats every 10 min. - else: - # 2-hour timeout reached. + last_warn_time = now + + if outcome == 'stall_timeout': + deps.update_progress( + automation_id, status='error', phase='Stalled', + log_line=f'{stall_label} made no progress for {_STALL_TIMEOUT_SECONDS // 60} minutes — giving up', + log_type='error', + ) + return {'status': 'error', 'reason': 'Stalled (no progress)', '_manages_own_progress': True} + if outcome == 'abs_timeout': deps.update_progress( automation_id, status='error', phase='Timed out', log_line=timeout_label, log_type='error', diff --git a/tests/test_scan_wait_action.py b/tests/test_scan_wait_action.py new file mode 100644 index 00000000..1f3ac004 --- /dev/null +++ b/tests/test_scan_wait_action.py @@ -0,0 +1,84 @@ +"""Tests for the DB-update / deep-scan monitor decision (stall-based timeout). + +Regression: a large library can deep-scan for many hours while progressing +fine. The old monitor used a hard 2-hour TOTAL cap, so it falsely marked a +healthy, still-running scan 'error' (the scan thread kept going uncancelled). +The decision now keys off STALL (no progress), so an actively-progressing scan +never times out no matter how long the whole library takes. +""" + +from __future__ import annotations + +from core.automation.handlers.database_update import ( + scan_wait_action, + _STALL_WARNING_SECONDS, + _STALL_TIMEOUT_SECONDS, + _ABSOLUTE_CAP_SECONDS, +) + + +# --- the headline regression ------------------------------------------------- + + +def test_long_but_progressing_scan_never_times_out(): + # 5 hours elapsed total, but progress moved 5s ago -> keep waiting, NOT error. + assert scan_wait_action( + status='running', idle_seconds=5, total_seconds=5 * 3600, + ) == 'continue' + + +def test_very_long_progressing_scan_still_continues(): + # 12h total, just progressed — old code would have failed at 2h. + assert scan_wait_action( + status='running', idle_seconds=2, total_seconds=12 * 3600, + ) == 'continue' + + +# --- finished / not-running -------------------------------------------------- + + +def test_finished_when_not_running(): + for st in ('completed', 'error', 'idle', 'finished'): + assert scan_wait_action(status=st, idle_seconds=0, total_seconds=0) == 'finished' + + +def test_finished_takes_precedence_even_if_stalled(): + # Task already ended — don't report a stall. + assert scan_wait_action( + status='completed', idle_seconds=_STALL_TIMEOUT_SECONDS + 1, total_seconds=10, + ) == 'finished' + + +# --- stall warning vs stall timeout ------------------------------------------ + + +def test_warns_after_stall_warning_threshold(): + assert scan_wait_action( + status='running', idle_seconds=_STALL_WARNING_SECONDS + 1, total_seconds=1000, + ) == 'warn' + + +def test_stall_timeout_after_no_progress(): + assert scan_wait_action( + status='running', idle_seconds=_STALL_TIMEOUT_SECONDS + 1, total_seconds=2000, + ) == 'stall_timeout' + + +def test_just_below_warning_keeps_going(): + assert scan_wait_action( + status='running', idle_seconds=_STALL_WARNING_SECONDS - 1, total_seconds=1000, + ) == 'continue' + + +# --- absolute backstop ------------------------------------------------------- + + +def test_absolute_cap_is_last_resort(): + # Even if somehow progressing, a 24h+ wait trips the runaway-loop backstop. + assert scan_wait_action( + status='running', idle_seconds=1, total_seconds=_ABSOLUTE_CAP_SECONDS + 1, + ) == 'abs_timeout' + + +def test_thresholds_are_ordered_sensibly(): + assert _STALL_WARNING_SECONDS < _STALL_TIMEOUT_SECONDS < _ABSOLUTE_CAP_SECONDS