Similar Artists worker: surface WHY fetches error (observability before tuning)

The kettui move: 38/79 fetches errored on the first live run, but they were
logged at DEBUG only — invisible in app.log, so the cause (rate-limit vs
no-providers vs bug) is unprovable. process_artist now returns a (status, count,
detail) triple carrying the error reason (status code + message / exception),
and the worker logs the first 15 errors per session at WARNING (rest DEBUG) +
keeps _last_error. No blind pacing tweak — let it run, read the real reason, then
fix the proven cause. Seam tests updated + assert the reason is captured.

core/similar_artists_worker.py

@@ -78,26 +78,29 @@ def process_artist(
 
     ``fetch_similars(name, limit)`` returns the ``get_musicmap_similar_artists``
     payload; ``store_similar(**kwargs)`` is ``add_or_update_similar_artist``.
-    Returns ``(status, stored_count)`` where status is one of:
+    Returns ``(status, stored_count, detail)`` where status is one of:
       - ``'matched'``   — stored ≥1 similar artist
       - ``'not_found'`` — MusicMap had no entry / nothing matched a source
       - ``'error'``     — MusicMap/source failure (transient; eligible for retry)
+    ``detail`` is a short human-readable reason (status code + message, or
+    ``'no matches'`` / ``''``) so the worker can surface WHY a fetch failed
+    instead of swallowing it — needed to diagnose error rates.
     """
     try:
         result = fetch_similars(artist_name, limit) or {}
     except Exception as exc:
-        logger.debug("MusicMap fetch raised for %s: %s", artist_name, exc)
+        return ('error', 0, f'exception: {exc}')
-        return ('error', 0)
 
     if not result.get('success'):
         # 404/400 = genuinely no MusicMap entry → 'not_found' (don't keep retrying);
         # anything else (timeout, 5xx, no providers) = transient → 'error' (retry).
         code = result.get('status_code')
-        return ('not_found' if code in (400, 404) else 'error', 0)
+        detail = f"{code}: {result.get('error') or 'unknown'}"
+        return ('not_found' if code in (400, 404) else 'error', 0, detail)
 
     sims = result.get('similar_artists') or []
     if not sims:
-        return ('not_found', 0)
+        return ('not_found', 0, 'no matches')
 
     stored = 0
     for rank, s in enumerate(sims, 1):
@@ -121,7 +124,7 @@ def process_artist(
         except Exception as exc:
             logger.debug("store similar failed for %s: %s", name, exc)
 
-    return ('matched' if stored else 'not_found', stored)
+    return ('matched' if stored else 'not_found', stored, '')
 
 
 class SimilarArtistsWorker:
@@ -138,6 +141,8 @@ class SimilarArtistsWorker:
         self.stats = {'matched': 0, 'not_found': 0, 'pending': 0, 'errors': 0}
         self.retry_days = 30
         self.limit = 25
+        self._err_logged = 0          # how many fetch errors we've logged at WARNING this session
+        self._last_error = None       # most recent fetch-error reason (for diagnosis)
         # similar_artists rows are profile-scoped; the library is shared. v1 keys
         # under the default profile (matches single-profile setups, which is the
         # common case). Multi-profile per-source-chain population is future work.
@@ -220,7 +225,7 @@ class SimilarArtistsWorker:
                     continue
 
                 self.current_item = artist.get('name')
-                status, count = process_artist(
+                status, count, detail = process_artist(
                     sid, artist['name'],
                     get_musicmap_similar_artists,
                     self.db.add_or_update_similar_artist,
@@ -234,6 +239,15 @@ class SimilarArtistsWorker:
                     self.stats['not_found'] += 1
                 else:
                     self.stats['errors'] += 1
+                    # Surface WHY fetches error — the first handful at WARNING (so
+                    # the cause is visible in app.log without spamming a 4000-artist
+                    # run), the rest at DEBUG. Keep the most recent reason for stats.
+                    self._last_error = detail
+                    if self._err_logged < 15:
+                        self._err_logged += 1
+                        logger.warning("Similar artists fetch error for '%s' — %s", artist['name'], detail)
+                    else:
+                        logger.debug("Similar artists fetch error for '%s' — %s", artist['name'], detail)
 
                 # Pace MusicMap (name search per candidate is heavy + rate-limited).
                 interruptible_sleep(self._stop_event, 3)

tests/test_similar_artists_worker.py

@@ -72,8 +72,8 @@ def test_process_artist_matched_stores_with_keying():
             {'name': 'C', 'id': 'it_c', 'source': 'itunes', 'image_url': 'http://x'},
         ],
     }
-    status, count = w.process_artist('SRC1', 'A', lambda n, l: payload, store, limit=25, profile_id=1)
+    status, count, detail = w.process_artist('SRC1', 'A', lambda n, l: payload, store, limit=25, profile_id=1)
-    assert status == 'matched' and count == 2
+    assert status == 'matched' and count == 2 and detail == ''
     # All similars keyed by the SOURCE artist id we passed (not the library PK).
     assert all(c['source_artist_id'] == 'SRC1' for c in calls)
     assert all(c['profile_id'] == 1 for c in calls)
@@ -85,31 +85,34 @@ def test_process_artist_matched_stores_with_keying():
 
 def test_process_artist_not_found_when_no_matches():
     store, calls = _capture_store()
-    status, count = w.process_artist('S', 'A', lambda n, l: {'success': True, 'similar_artists': []}, store)
+    status, count, detail = w.process_artist('S', 'A', lambda n, l: {'success': True, 'similar_artists': []}, store)
-    assert status == 'not_found' and count == 0 and calls == []
+    assert status == 'not_found' and count == 0 and calls == [] and detail == 'no matches'
 
 
 def test_process_artist_not_found_on_404():
     # Genuinely no MusicMap entry — shouldn't be retried as an error.
     store, _ = _capture_store()
-    status, _ = w.process_artist('S', 'A', lambda n, l: {'success': False, 'status_code': 404}, store)
+    status, _, _ = w.process_artist('S', 'A', lambda n, l: {'success': False, 'status_code': 404}, store)
     assert status == 'not_found'
 
 
-def test_process_artist_error_on_outage_is_retriable():
+def test_process_artist_error_on_outage_is_retriable_and_explains_why():
-    # 5xx / no providers → transient error (worker retries after retry_days).
+    # 5xx / no providers → transient error (retried after retry_days), and the
+    # reason is surfaced (code + message) so the cause is diagnosable, not silent.
     store, _ = _capture_store()
-    status, _ = w.process_artist('S', 'A', lambda n, l: {'success': False, 'status_code': 502}, store)
+    status, _, detail = w.process_artist(
+        'S', 'A', lambda n, l: {'success': False, 'status_code': 502, 'error': 'Failed to fetch from MusicMap'}, store)
     assert status == 'error'
+    assert '502' in detail and 'MusicMap' in detail
 
 
-def test_process_artist_error_when_fetch_raises():
+def test_process_artist_error_when_fetch_raises_carries_detail():
     store, _ = _capture_store()
 
     def boom(n, l):
         raise RuntimeError('musicmap down')
-    status, count = w.process_artist('S', 'A', boom, store)
+    status, count, detail = w.process_artist('S', 'A', boom, store)
-    assert status == 'error' and count == 0
+    assert status == 'error' and count == 0 and 'musicmap down' in detail
 
 
 def test_process_artist_skips_unstorable_but_counts_real():
@@ -123,5 +126,5 @@ def test_process_artist_skips_unstorable_but_counts_real():
         {'name': 'B', 'id': '1', 'source': 'spotify'},
         {'name': 'C', 'id': '2', 'source': 'spotify'},
     ]}
-    status, count = w.process_artist('S', 'A', lambda n, l: payload, store)
+    status, count, _ = w.process_artist('S', 'A', lambda n, l: payload, store)
     assert status == 'matched' and count == 1 and len(calls) == 2