AudioDB worker: stop infinite loop on direct-ID lookup failure (#553)

Track enrichment was stuck in a constant retry loop. Logs showed
nothing but `Read timed out. (read timeout=10)` from
`lookup_track_by_id` repeating against the same track ID. AudioDB
itself was being hammered nonstop with no progress.

Cause: when an entity already has `audiodb_id` populated (from a
manual match or earlier scan) but `audiodb_match_status` is still
NULL — an inconsistent state some import paths can leave behind —
the worker tries a direct ID lookup. If that lookup fails (returns
None on timeout, which AudioDB's `track.php` endpoint hits
frequently because it's slow), the prior code logged "preserving
manual match" and returned WITHOUT marking status. Row stayed NULL
→ queue's NULL-status filter picked it up next tick → tried direct
lookup → timed out → returned → infinite loop.

The "preserve manual match" intent was correct: don't fall through
to the name-search path because that could overwrite a manually-set
`audiodb_id` with a wrong guess. Bug was the missing `_mark_status`
call before the early return.

Fix:

* `_process_item` direct-lookup-failure branch now calls
  `_mark_status(item_type, item_id, 'error')` before returning. The
  existing `audiodb_id` is preserved (column not touched). Queue's
  NULL-status filter no longer re-picks the row.

* `_get_next_item` retry-cutoff queue priorities (4/5/6) extended
  from `audiodb_match_status = 'not_found'` to
  `audiodb_match_status IN ('not_found', 'error')`. Same `retry_days`
  window. Transient AudioDB outages still recover automatically;
  permanently-broken IDs eventually get re-attempted once a month
  rather than staying errored forever.

5 new tests in `tests/test_audiodb_worker_stuck_track.py` use a real
SQLite DB (not mocks) so the SQL queries are actually exercised:

  - lookup-returns-None marks status='error' (no infinite loop)
  - lookup-raises-exception marks status='error' (defensive)
  - lookup-success preserves the existing match-success path
  - error-status row past retry-cutoff gets picked up again
  - error-status row within cutoff stays skipped (loop prevention
    works)

Only triggers for entities in the inconsistent `audiodb_id` set +
`match_status` NULL state. Happy path and already-matched /
already-not-found rows unchanged. Full pytest 2698 passed.

Closes #553.
This commit is contained in:
Broque Thomas 2026-05-11 14:18:55 -07:00
parent 655c185026
commit fc573a5f19
3 changed files with 330 additions and 12 deletions

View file

@ -200,42 +200,45 @@ class AudioDBWorker:
if row:
return {'type': 'track', 'id': row[0], 'name': row[1], 'artist': row[2], 'artist_audiodb_id': row[3]}
# Priority 4: Retry 'not_found' artists after retry_days
not_found_cutoff = datetime.now() - timedelta(days=self.retry_days)
# Priority 4: Retry 'not_found' OR 'error' artists after retry_days.
# 'error' status covers transient AudioDB outages (timeouts, 500s)
# that the issue-#553 fix marks rather than leaving NULL — without
# this retry path those rows would stay errored forever.
retry_cutoff = datetime.now() - timedelta(days=self.retry_days)
cursor.execute("""
SELECT id, name
FROM artists
WHERE audiodb_match_status = 'not_found' AND audiodb_last_attempted < ?
WHERE audiodb_match_status IN ('not_found', 'error') AND audiodb_last_attempted < ?
ORDER BY audiodb_last_attempted ASC
LIMIT 1
""", (not_found_cutoff,))
""", (retry_cutoff,))
row = cursor.fetchone()
if row:
logger.info(f"Retrying artist '{row[1]}' (last attempted before cutoff)")
return {'type': 'artist', 'id': row[0], 'name': row[1]}
# Priority 5: Retry 'not_found' albums
# Priority 5: Retry 'not_found' OR 'error' albums
cursor.execute("""
SELECT a.id, a.title, ar.name AS artist_name, ar.audiodb_id AS artist_audiodb_id
FROM albums a
JOIN artists ar ON a.artist_id = ar.id
WHERE a.audiodb_match_status = 'not_found' AND a.audiodb_last_attempted < ?
WHERE a.audiodb_match_status IN ('not_found', 'error') AND a.audiodb_last_attempted < ?
ORDER BY a.audiodb_last_attempted ASC
LIMIT 1
""", (not_found_cutoff,))
""", (retry_cutoff,))
row = cursor.fetchone()
if row:
return {'type': 'album', 'id': row[0], 'name': row[1], 'artist': row[2], 'artist_audiodb_id': row[3]}
# Priority 6: Retry 'not_found' tracks
# Priority 6: Retry 'not_found' OR 'error' tracks
cursor.execute("""
SELECT t.id, t.title, ar.name AS artist_name, ar.audiodb_id AS artist_audiodb_id
FROM tracks t
JOIN artists ar ON t.artist_id = ar.id
WHERE t.audiodb_match_status = 'not_found' AND t.audiodb_last_attempted < ?
WHERE t.audiodb_match_status IN ('not_found', 'error') AND t.audiodb_last_attempted < ?
ORDER BY t.audiodb_last_attempted ASC
LIMIT 1
""", (not_found_cutoff,))
""", (retry_cutoff,))
row = cursor.fetchone()
if row:
return {'type': 'track', 'id': row[0], 'name': row[1], 'artist': row[2], 'artist_audiodb_id': row[3]}
@ -374,8 +377,22 @@ class AudioDBWorker:
return
except Exception as e:
logger.warning(f"Direct lookup failed for existing AudioDB ID {existing_id}: {e}")
# Direct lookup failed — don't overwrite manual match
logger.debug(f"Preserving manual match for {item_type} '{item_name}' (AudioDB ID: {existing_id})")
# Direct lookup returned no metadata (None) or raised — don't
# fall through to the name-search path below, which could
# overwrite a manually-matched audiodb_id with a wrong guess.
# Mark status='error' so the queue's NULL-status filter stops
# re-picking this row on every tick (issue #553: AudioDB
# `track.php` timeouts caused infinite enrichment loops as
# the row was repeatedly picked + re-attempted because it
# never left the NULL state). The error-retry priority block
# in `_get_next_item` re-attempts after `retry_days` so
# transient AudioDB outages still recover automatically.
self._mark_status(item_type, item_id, 'error')
self.stats['errors'] += 1
logger.debug(
f"Preserving manual match for {item_type} '{item_name}' "
f"(AudioDB ID: {existing_id}); marked error pending retry"
)
return
if item_type == 'artist':

View file

@ -0,0 +1,300 @@
"""Pin AudioDB worker doesn't infinite-loop on direct-ID-lookup
failures.
Issue #553: when an entity already has `audiodb_id` populated
(from manual match or earlier scan) but `audiodb_match_status` is
NULL, the worker tries a direct ID lookup. If that lookup fails
(returns None on timeout AudioDB's `track.php` endpoint is slow
and 10s timeouts are common), the prior code returned WITHOUT
marking status. Result: row stayed in NULL state, queue picked it
up next tick, retried, timed out, returned again infinite loop.
User saw constant requests with no progress.
The fix:
- Mark status='error' so the queue's NULL-status filter stops
picking the row on every tick
- Add 'error' to the retry-after-cutoff queries (priorities 4-6)
so transient AudioDB outages still recover automatically after
`retry_days`
- Preserve the existing `audiodb_id` (don't overwrite it via
name-search fallback original "preserve manual match" intent)
These tests pin:
- Direct-lookup-returns-None marks status='error' (no infinite loop)
- Direct-lookup-raises-exception marks status='error'
- Direct-lookup-success preserves existing match-success path
- 'error' status is included in retry-cutoff queue so eventual
recovery happens
"""
from __future__ import annotations
import sqlite3
from datetime import datetime, timedelta
from types import SimpleNamespace
from unittest.mock import MagicMock
import pytest
from core.audiodb_worker import AudioDBWorker
def _make_real_db_with_audiodb_columns(tmp_path):
"""Build a minimal SQLite DB with the artist/album/track schema
the worker needs. Real SQLite (not mocks) so the SQL queries
actually exercise the column names + retry-cutoff logic."""
db_path = tmp_path / "audiodb_test.db"
conn = sqlite3.connect(str(db_path))
conn.executescript("""
CREATE TABLE artists (
id INTEGER PRIMARY KEY,
name TEXT,
audiodb_id TEXT,
audiodb_match_status TEXT,
audiodb_last_attempted DATETIME,
updated_at DATETIME
);
CREATE TABLE albums (
id INTEGER PRIMARY KEY,
title TEXT,
artist_id INTEGER,
audiodb_id TEXT,
audiodb_match_status TEXT,
audiodb_last_attempted DATETIME,
updated_at DATETIME
);
CREATE TABLE tracks (
id INTEGER PRIMARY KEY,
title TEXT,
artist_id INTEGER,
audiodb_id TEXT,
audiodb_match_status TEXT,
audiodb_last_attempted DATETIME,
updated_at DATETIME
);
""")
conn.commit()
conn.close()
class _RealDB:
def _get_connection(self):
return sqlite3.connect(str(db_path))
return _RealDB(), db_path
def _make_worker(db, fake_client):
"""Build a worker with a real DB + mocked AudioDB client.
Skip __init__ side effects (config load, thread start)."""
worker = AudioDBWorker.__new__(AudioDBWorker)
worker.db = db
worker.client = fake_client
worker.retry_days = 30
worker.stats = {'matched': 0, 'not_found': 0, 'errors': 0, 'pending': 0}
worker.current_item = None
worker.running = False
worker.paused = False
worker.thread = None
return worker
# ---------------------------------------------------------------------------
# Issue #553 — direct-ID lookup failure no longer infinite-loops
# ---------------------------------------------------------------------------
class TestDirectLookupFailureMarksError:
def test_lookup_returns_none_marks_status_error(self, tmp_path):
"""Reporter's exact scenario: track has audiodb_id set,
match_status is NULL. AudioDB times out lookup returns None.
Pre-fix: return without marking infinite loop next tick.
Post-fix: mark status='error' queue stops re-picking."""
db, db_path = _make_real_db_with_audiodb_columns(tmp_path)
# Seed a track with audiodb_id populated, status NULL
with sqlite3.connect(str(db_path)) as seed_conn:
seed_conn.execute(
"INSERT INTO artists (id, name) VALUES (?, ?)",
(1, 'Test Artist'),
)
seed_conn.execute(
"INSERT INTO tracks (id, title, artist_id, audiodb_id, audiodb_match_status) "
"VALUES (?, ?, ?, ?, ?)",
(32743988, 'Sweet Talk', 1, '12345', None),
)
seed_conn.commit()
# AudioDB client returns None on timeout (matches lookup_track_by_id behavior)
fake_client = SimpleNamespace(
lookup_artist_by_id=MagicMock(return_value=None),
lookup_album_by_id=MagicMock(return_value=None),
lookup_track_by_id=MagicMock(return_value=None),
)
worker = _make_worker(db, fake_client)
item = {
'type': 'track',
'id': 32743988,
'name': 'Sweet Talk',
'artist': 'Test Artist',
'artist_audiodb_id': None,
}
worker._process_item(item)
# Verify status was marked (no longer NULL → queue won't re-pick)
with sqlite3.connect(str(db_path)) as verify:
row = verify.execute(
"SELECT audiodb_match_status, audiodb_id, audiodb_last_attempted "
"FROM tracks WHERE id = ?",
(32743988,),
).fetchone()
assert row[0] == 'error', f"Expected status='error' to break loop; got {row[0]!r}"
# audiodb_id preserved (manual match not overwritten)
assert row[1] == '12345', f"audiodb_id must NOT be cleared; got {row[1]!r}"
# last_attempted set so retry-cutoff logic can re-pick later
assert row[2] is not None, "audiodb_last_attempted must be set for retry logic"
# Stats updated
assert worker.stats['errors'] == 1
def test_lookup_raises_exception_marks_status_error(self, tmp_path):
"""Defensive: if the AudioDB client itself raises (not just
returns None) the same loop-protection must apply. Some
client paths re-raise on certain error classes."""
db, db_path = _make_real_db_with_audiodb_columns(tmp_path)
with sqlite3.connect(str(db_path)) as seed_conn:
seed_conn.execute(
"INSERT INTO artists (id, name) VALUES (?, ?)",
(1, 'X'),
)
seed_conn.execute(
"INSERT INTO tracks (id, title, artist_id, audiodb_id, audiodb_match_status) "
"VALUES (?, ?, ?, ?, ?)",
(99, 'Y', 1, '67890', None),
)
seed_conn.commit()
fake_client = SimpleNamespace(
lookup_artist_by_id=MagicMock(side_effect=RuntimeError("boom")),
lookup_album_by_id=MagicMock(side_effect=RuntimeError("boom")),
lookup_track_by_id=MagicMock(side_effect=RuntimeError("read timeout")),
)
worker = _make_worker(db, fake_client)
item = {'type': 'track', 'id': 99, 'name': 'Y', 'artist': 'X',
'artist_audiodb_id': None}
worker._process_item(item)
with sqlite3.connect(str(db_path)) as verify:
row = verify.execute(
"SELECT audiodb_match_status FROM tracks WHERE id = ?",
(99,),
).fetchone()
assert row[0] == 'error'
def test_lookup_success_preserves_existing_path(self, tmp_path):
"""Sanity: when direct lookup SUCCEEDS, the existing match-
success path runs (update + stats['matched'] += 1). Don't
regress the happy path."""
db, db_path = _make_real_db_with_audiodb_columns(tmp_path)
with sqlite3.connect(str(db_path)) as seed_conn:
seed_conn.execute("INSERT INTO artists (id, name) VALUES (?, ?)", (1, 'A'))
seed_conn.execute(
"INSERT INTO tracks (id, title, artist_id, audiodb_id) "
"VALUES (?, ?, ?, ?)",
(50, 'T', 1, '111'),
)
seed_conn.commit()
fake_client = SimpleNamespace(
lookup_artist_by_id=MagicMock(),
lookup_album_by_id=MagicMock(),
lookup_track_by_id=MagicMock(return_value={
'idTrack': '111',
'strTrack': 'T',
'idArtist': '999',
}),
)
worker = _make_worker(db, fake_client)
# Stub the per-entity update method so we don't need every column
worker._update_track = MagicMock()
worker._verify_artist_id = MagicMock(return_value=True)
item = {'type': 'track', 'id': 50, 'name': 'T', 'artist': 'A',
'artist_audiodb_id': None}
worker._process_item(item)
worker._update_track.assert_called_once()
assert worker.stats['matched'] == 1
assert worker.stats['errors'] == 0
# ---------------------------------------------------------------------------
# Retry queue includes 'error' status — transient outages eventually recover
# ---------------------------------------------------------------------------
class TestErrorRetryAfterCutoff:
def test_error_track_picked_up_after_cutoff(self, tmp_path):
"""After fix #553, rows marked 'error' get a 30-day retry
cutoff same treatment as 'not_found'. Without this they'd
stay errored forever after a transient AudioDB outage."""
db, db_path = _make_real_db_with_audiodb_columns(tmp_path)
# Seed a track marked 'error' with last_attempted older than retry_days.
# Artist must be marked 'matched' too — otherwise priority 1 (NULL-status
# artists) wins over priority 6 (error/not_found track retry).
old_attempt = datetime.now() - timedelta(days=31)
with sqlite3.connect(str(db_path)) as seed_conn:
seed_conn.execute(
"INSERT INTO artists (id, name, audiodb_match_status) VALUES (?, ?, ?)",
(1, 'A', 'matched'),
)
seed_conn.execute(
"INSERT INTO tracks (id, title, artist_id, audiodb_match_status, audiodb_last_attempted) "
"VALUES (?, ?, ?, ?, ?)",
(10, 'OldErrored', 1, 'error', old_attempt),
)
seed_conn.commit()
fake_client = SimpleNamespace() # not called for queue check
worker = _make_worker(db, fake_client)
item = worker._get_next_item()
assert item is not None, "Expected error-status track past retry cutoff to be picked up"
assert item['type'] == 'track'
assert item['id'] == 10
def test_error_track_NOT_picked_within_cutoff(self, tmp_path):
"""Sanity: rows marked 'error' but recently-attempted should
NOT be picked. Otherwise the retry-cutoff doesn't actually
rate-limit retries and we're back to the loop."""
db, db_path = _make_real_db_with_audiodb_columns(tmp_path)
# Just-attempted (within cutoff). Artist marked matched
# so priority 1 doesn't intercept the queue check.
recent_attempt = datetime.now() - timedelta(days=1)
with sqlite3.connect(str(db_path)) as seed_conn:
seed_conn.execute(
"INSERT INTO artists (id, name, audiodb_match_status) VALUES (?, ?, ?)",
(1, 'A', 'matched'),
)
seed_conn.execute(
"INSERT INTO tracks (id, title, artist_id, audiodb_match_status, audiodb_last_attempted) "
"VALUES (?, ?, ?, ?, ?)",
(20, 'RecentErrored', 1, 'error', recent_attempt),
)
seed_conn.commit()
worker = _make_worker(db, SimpleNamespace())
item = worker._get_next_item()
assert item is None, (
"Recently-attempted error rows must NOT be picked up — that's "
"the loop-prevention mechanism"
)

View file

@ -3416,6 +3416,7 @@ const WHATS_NEW = {
'2.5.1': [
// --- post-release patch work on the 2.5.1 line — entries hidden by _getLatestWhatsNewVersion until the build version bumps ---
{ date: 'Unreleased — 2.5.1 patch work' },
{ title: 'AudioDB Enrichment: Track Worker No Longer Stuck In Infinite Retry Loop', desc: 'github issue #553: audiodb track enrichment "stuck" — constant requests, no progress, only error log was a 10s read-timeout from `lookup_track_by_id` repeating against the same track. trace: when an entity already has `audiodb_id` populated (from manual match or earlier scan) but `audiodb_match_status` is NULL, the worker tries a direct ID lookup. if it fails (returns None on timeout — audiodb\'s `track.php` endpoint is slow, 10s timeouts common), the prior code logged "preserving manual match" and returned WITHOUT marking status. row stayed NULL → queue picked it up next tick → tried direct lookup → timed out → returned → infinite loop. fix: (1) when direct lookup fails (None or exception), mark `audiodb_match_status="error"` so the queue\'s NULL-status filter stops re-picking the row on every tick. preserves the existing `audiodb_id` (no fallback to name-search guess that would overwrite a manual match). (2) extended the retry-after-cutoff queue priorities (4/5/6) to include `\'error\'` rows alongside `\'not_found\'` — same `retry_days=30` window. transient audiodb outages still recover automatically; permanently-broken IDs eventually get re-attempted once a month. only triggered for entities in the inconsistent state of `audiodb_id` set + `match_status` NULL — happy path and already-matched/already-not-found rows unchanged. 5 new tests pin: lookup-returns-none marks error (no infinite loop), lookup-raises-exception marks error, lookup-success preserves happy path, error-row-past-cutoff gets re-picked, error-row-within-cutoff stays skipped.', page: 'tools' },
{ title: 'Docker: Container No Longer Restart-Loops On Bind-Mounted Staging Folder', desc: 'after pulling latest, the container refused to start. logs showed `mkdir: cannot create directory \'/app/Staging\': Permission denied`. cause traced back to the 2026-05-08 image-bloat fix (commit 70e1750) which changed the Dockerfile from `chown -R /app` to a scoped chown on specific subdirs (the recursive chown was duplicating the whole /app tree into a new layer and ballooning image size). side effect: `/app` itself went from soulsync:soulsync to root:root (Docker WORKDIR default), AND `/app/Staging` was left out of both the Dockerfile mkdir + chown list and only created at runtime by the entrypoint script. on rootless Docker / Podman where in-container "root" maps to a host UID, the entrypoint mkdir on `/app/Staging` could fail with EACCES depending on the bind-mount path\'s host ownership — `set -e` then aborted the script and the container restart-looped. fix: (1) Dockerfile now pre-bakes `/app/Staging` into the image alongside the other runtime mount points (mkdir + scoped chown) so the entrypoint mkdir is a guaranteed no-op even when bind-mount perms are weird. (2) entrypoint mkdir + chown both have `|| true` now so any future bind-mount permission quirk surfaces as a log line, not a restart loop. (3) new writability audit at the end of entrypoint setup — `gosu soulsync test -w` on every bind-mountable dir, logs a loud warning with the exact `chown` command to run on the host if perms mismatch the configured PUID/PGID. catches the underlying bind-mount perm issue that the restart-loop fix would otherwise mask (container starts, but auto-import / downloads write into unwritable dirs and fail silently). zero behavior change for users whose containers were already starting fine; defensive against the rootless/podman config that broke after the image-bloat refactor.', page: 'tools' },
{ title: 'Your Albums: Download Missing Now Opens Selectable Modal + Tidal Resolution', desc: 'two-part fix to the your albums "download missing" flow on discover. (1) replaced the broken per-album direct-download loop with a selectable-grid modal mirroring the library page\'s download discography flow. clicking the download button now opens a checkbox grid showing every missing album (cover, title, artist, year, track count, source) with select all / deselect all controls. user picks what they actually want, hits "add to wishlist", each album\'s tracks get resolved + queued through the existing wishlist auto-download processor. matches the discography flow\'s per-album ndjson progress stream so users see ✓/✗ per album as it processes. previous loop fired direct downloads via `openDownloadMissingModalForYouTube` which the user reported as silently failing — "queuing 2/2" toast with no actual transfer activity. wishlist is the right destination for batch missing-album adds since it already handles retry, source fallback, dedup, and rate limiting. (2) added tidal source resolution. backend `/api/discover/album/<source>/<album_id>` got a new `tidal` source branch that calls a NEW `tidal_client.get_album_tracks(album_id)` method — two-phase fetch (cursor-walk `/v2/albums/<id>/relationships/items?include=items` for track refs + position metadata, batch-hydrate via existing `_get_tracks_batch` for artist/album names). track refs carry `meta.trackNumber` + `meta.volumeNumber` so multi-disc compilations render in album order. inline `?include=coverArt` lookup pulls the album cover too. single-album click flow (`openYourAlbumDownload`) gets `tidal_album_id` added to `trySources`. virtual-id generation includes tidal_album_id for stable identifiers. backend reuses the existing `/api/artist/<id>/download-discography` endpoint — its url artist_id param is functionally unused (per-album payload carries everything), so the modal posts with placeholder `your-albums` and gets multi-artist resolution for free. 10 new tests pin the tidal album-tracks method: single-page walk + hydration, multi-page cursor chain, multi-disc sort order, limit short-circuit, no-token short-circuit, http error returns empty, 429 propagates to rate_limited decorator, forward-compat type filter, partial-batch failure containment, empty-album short-circuit.', page: 'discover' },
{ title: 'AcoustID Scanner: File-Tag Fallback For Legacy Compilation Tracks', desc: 'follow-up to the compilation-album scanner fix. previous patch made the scanner read `tracks.track_artist` (per-track artist column) via COALESCE so compilation tracks would compare against the right value. but tracks downloaded BEFORE that column existed have track_artist=NULL — COALESCE falls back to album artist (the curator) and we\'re back to the wrong-comparison case. fix: explicit 3-tier resolution in `_scan_file` — (1) `tracks.track_artist` from DB if populated → trust it (respects manual edits from the enhanced library view), (2) audio file\'s ARTIST tag via mutagen if present → use it (tidal/spotify/deezer all write the per-track artist into the file at download time, so it\'s ground truth even when DB is stale), (3) album artist → final fallback for files without proper ARTIST tags AND no DB track_artist. file open is essentially free since acoustid is opening it for fingerprinting anyway. critical guard: when DB track_artist is populated (curated value), it always wins over file tag — protects users who edited DB but didn\'t re-tag the file from getting false-positive flags. closes the legacy-data gap without requiring a one-time DB backfill or a re-download. 5 new tests pin: file-tag-resolves-skowl-case (legacy NULL track_artist → file tag wins → no flag), tag-missing-falls-back-to-album-artist (preserves existing genuine-mismatch contract), mutagen-exception-swallowed (debug log, fall-through), tag-matches-DB no behavioral change, and the false-positive guard (DB populated → trumps stale file tag).', page: 'tools' },