Fix: deep-scan / DB-update automation falsely errors on large libraries (stall-based timeout)
The DB-update + deep-scan automation monitor used a hard 2-hour TOTAL cap
(while elapsed < 7200). It tracked progress but only used it to print a stall
warning — the only thing that actually timed out was wall-clock. So a large
library that scans for >2h while progressing fine (reported: 4781 artists) trips
the cap and the automation card flips to 'error: timed out after 2 hours' even
though the scan thread is healthy and still running (the timeout never cancels
it, which is why it keeps progressing in the logs after the 'error').
Time out on STALL, not total runtime:
- 30 min with NO progress -> error ('stalled'); catches a genuinely hung scan.
- 10 min idle -> warning (repeats); unchanged heads-up.
- 24h absolute backstop, purely a runaway-loop guard.
- An actively-progressing scan keeps resetting the idle clock, so it never
times out no matter how many hours the whole library takes.
- Progress is judged on (processed, progress, current_item) so a slow stretch
where the rounded % holds steady (but the artist keeps changing) isn't a
false stall.
The decision is extracted into a pure, testable scan_wait_action(); both the
deep-scan and full-refresh handlers share the monitor loop, so both are fixed.
Tests: tests/test_scan_wait_action.py (9) — headline regression (5h/12h total
but progressing -> 'continue', not timeout), finished/stall-warn/stall-timeout/
abs-cap thresholds, and ordering. 280 automation tests still pass.
This commit is contained in:
parent
c8c3789cb9
commit
de20897f83
2 changed files with 162 additions and 17 deletions
|
|
@ -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',
|
||||
|
|
|
|||
84
tests/test_scan_wait_action.py
Normal file
84
tests/test_scan_wait_action.py
Normal file
|
|
@ -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
|
||||
Loading…
Reference in a new issue