Skip to content

Commit b673bac

Browse files
fix(insights): stop rarity-scores 500s and blind data-completeness timeouts (#375)
Production insights logs showed two recurring scheduler failures: 1. `release_rarity` failed every run with a 500 from `GET /api/internal/insights/rarity-scores`. The API logs traced it to a Neo4j `TransientError: MemoryPoolOutOfMemoryError` — `fetch_all_rarity_signals` fired eight full-graph Cypher scans concurrently via `asyncio.gather`, summing their working sets past `dbms.memory.transaction.total.max` (16 GiB). Two of the scans also used `size([(r)-[]-() | 1])`, which materialises a list element per relationship for every Release. Fix: run the eight queries sequentially (caps peak transaction memory at one query; fine for a daily background job) and replace the list-comprehension degree with `COUNT { }`. The endpoint now also catches `TransientError` and returns 503 instead of a bare 500, so the caller logs a meaningful, retryable failure. 2. `data_completeness` failed intermittently with `error=""` — an empty, undiagnosable log line. The cause was an `httpx.ReadTimeout` (whose `str()` is empty) at the 600s client timeout; the underlying full-table scan varies from ~230s to >600s. Fix: a `_describe_error` helper that always includes the exception type (applied to both the data-completeness and rarity handlers), and a larger timeout (1200s) giving the cold-cache scan headroom. The rarity client timeout is likewise raised, since its scans now run sequentially. Co-authored-by: Claude Opus 4.8 (1M context) <noreply@anthropic.com>
1 parent 54ffac1 commit b673bac

6 files changed

Lines changed: 91 additions & 35 deletions

File tree

api/queries/rarity_queries.py

Lines changed: 21 additions & 23 deletions
Original file line numberDiff line numberDiff line change
@@ -11,7 +11,6 @@
1111
(Release)-[:DERIVED_FROM]->(Master)
1212
"""
1313

14-
import asyncio
1514
import bisect
1615
from datetime import UTC, datetime
1716
from typing import Any
@@ -218,18 +217,22 @@ async def fetch_all_rarity_signals(driver: Any, pool: Any = None) -> list[dict[s
218217
RETURN release_id, year, latest_sibling_year
219218
"""
220219

221-
# 5. Graph degree per release
220+
# 5. Graph degree per release.
221+
# Use COUNT {} rather than size([(r)-[]-() | 1]): the list comprehension
222+
# materialises a list element per relationship for every Release, which over
223+
# the full graph exhausts the Neo4j transaction memory pool. COUNT {} counts
224+
# without building the intermediate list.
222225
degree_query = """
223226
MATCH (r:Release)
224-
WITH r, size([(r)-[]-() | 1]) AS degree
227+
WITH r, COUNT { (r)--() } AS degree
225228
RETURN r.id AS release_id, degree
226229
"""
227230

228231
# Quality signals for hidden gem scoring
229232
# 6. Max artist degree per release
230233
artist_degree_query = """
231234
MATCH (r:Release)-[:BY]->(a:Artist)
232-
WITH r.id AS release_id, max(size([(a)-[]-() | 1])) AS artist_max_degree
235+
WITH r.id AS release_id, max(COUNT { (a)--() }) AS artist_max_degree
233236
RETURN release_id, artist_max_degree
234237
"""
235238

@@ -249,25 +252,20 @@ async def fetch_all_rarity_signals(driver: Any, pool: Any = None) -> list[dict[s
249252

250253
logger.info("🔍 Fetching rarity signals from Neo4j...")
251254

252-
(
253-
pressing_rows,
254-
label_rows,
255-
format_rows,
256-
temporal_rows,
257-
degree_rows,
258-
artist_degree_rows,
259-
label_size_rows,
260-
genre_count_rows,
261-
) = await asyncio.gather(
262-
run_query(driver, pressing_query, database="neo4j"),
263-
run_query(driver, label_query, database="neo4j"),
264-
run_query(driver, format_query, database="neo4j"),
265-
run_query(driver, temporal_query, database="neo4j"),
266-
run_query(driver, degree_query, database="neo4j"),
267-
run_query(driver, artist_degree_query, database="neo4j"),
268-
run_query(driver, label_size_query, database="neo4j"),
269-
run_query(driver, genre_count_query, database="neo4j"),
270-
)
255+
# Run sequentially, not via asyncio.gather: each of these is a full-graph
256+
# scan, and running all eight concurrently sums their working sets against
257+
# the single dbms.memory.transaction.total.max pool — which tips it into a
258+
# TransientError MemoryPoolOutOfMemoryError. Sequential execution caps peak
259+
# transaction memory at one query at a time. This runs in a daily background
260+
# computation, so the extra wall-clock time is acceptable.
261+
pressing_rows = await run_query(driver, pressing_query, database="neo4j")
262+
label_rows = await run_query(driver, label_query, database="neo4j")
263+
format_rows = await run_query(driver, format_query, database="neo4j")
264+
temporal_rows = await run_query(driver, temporal_query, database="neo4j")
265+
degree_rows = await run_query(driver, degree_query, database="neo4j")
266+
artist_degree_rows = await run_query(driver, artist_degree_query, database="neo4j")
267+
label_size_rows = await run_query(driver, label_size_query, database="neo4j")
268+
genre_count_rows = await run_query(driver, genre_count_query, database="neo4j")
271269

272270
logger.info(
273271
"📊 Rarity signal data fetched",

api/routers/insights_compute.py

Lines changed: 12 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -11,6 +11,7 @@
1111
from fastapi import APIRouter, Query, Request
1212
from fastapi.responses import JSONResponse
1313
import httpx
14+
from neo4j.exceptions import TransientError
1415
from psycopg.rows import dict_row
1516
import structlog
1617

@@ -139,7 +140,17 @@ async def rarity_scores(request: Request) -> JSONResponse: # noqa: ARG001
139140
"""Return computed rarity scores for all releases from Neo4j."""
140141
if not _neo4j:
141142
return JSONResponse(content={"error": "Service not ready"}, status_code=503)
142-
results = await fetch_all_rarity_signals(_neo4j, _pool)
143+
try:
144+
results = await fetch_all_rarity_signals(_neo4j, _pool)
145+
except TransientError:
146+
# e.g. MemoryPoolOutOfMemoryError under DB pressure — transient, not a
147+
# server bug. Return 503 so the caller logs a meaningful, retryable
148+
# failure instead of a bare 500.
149+
logger.warning("⚠️ Rarity computation hit a transient Neo4j error", exc_info=True)
150+
return JSONResponse(
151+
content={"error": "Neo4j temporarily unavailable (transient error)"},
152+
status_code=503,
153+
)
143154
return JSONResponse(content={"items": results})
144155

145156

insights/computations.py

Lines changed: 26 additions & 10 deletions
Original file line numberDiff line numberDiff line change
@@ -63,6 +63,18 @@ async def _fetch_from_api(
6363
return items
6464

6565

66+
def _describe_error(exc: Exception) -> str:
67+
"""Return a non-empty, diagnosable description of *exc*.
68+
69+
``str(exc)`` is empty for several exceptions raised here — notably
70+
``httpx.ReadTimeout`` — which previously produced blank ``error=""`` log
71+
lines that were impossible to triage. Always prefix the exception type so
72+
the failure mode is identifiable even when the message is empty.
73+
"""
74+
detail = str(exc)
75+
return f"{type(exc).__name__}: {detail}" if detail else type(exc).__name__
76+
77+
6678
async def compute_and_store_artist_centrality(client: httpx.AsyncClient, pool: Any, limit: int = 100) -> int:
6779
"""Compute artist centrality and store results."""
6880
started_at = datetime.now(UTC)
@@ -260,9 +272,11 @@ async def compute_and_store_data_completeness(client: httpx.AsyncClient, pool: A
260272
"""Compute data completeness and store results."""
261273
started_at = datetime.now(UTC)
262274
try:
263-
# Data completeness does full sequential scans (~400s for releases table alone);
264-
# use a longer timeout than the client default to avoid ReadTimeout errors.
265-
results = await _fetch_from_api(client, "/api/internal/insights/data-completeness", timeout=600.0)
275+
# Data completeness does full sequential scans whose duration varies widely
276+
# (observed ~230s on a warm day, but exceeding 600s on others). The endpoint
277+
# caches results in Redis for 6h, so only the cold path is slow; give the
278+
# cold path generous headroom to avoid spurious ReadTimeouts.
279+
results = await _fetch_from_api(client, "/api/internal/insights/data-completeness", timeout=1200.0)
266280
if not results:
267281
await _log_computation(pool, "data_completeness", "completed", started_at, 0)
268282
return 0
@@ -294,11 +308,11 @@ async def compute_and_store_data_completeness(client: httpx.AsyncClient, pool: A
294308
await _log_computation(pool, "data_completeness", "completed", started_at, len(results))
295309
return len(results)
296310
except Exception as e:
297-
logger.error("❌ Data completeness computation failed", error=str(e))
311+
logger.error("❌ Data completeness computation failed", error=_describe_error(e))
298312
try:
299-
await _log_computation(pool, "data_completeness", "failed", started_at, error_message=str(e))
313+
await _log_computation(pool, "data_completeness", "failed", started_at, error_message=_describe_error(e))
300314
except Exception as log_err:
301-
logger.warning("⚠️ Failed to log computation error", error=str(log_err))
315+
logger.warning("⚠️ Failed to log computation error", error=_describe_error(log_err))
302316
raise
303317

304318

@@ -326,7 +340,9 @@ async def compute_and_store_rarity(client: httpx.AsyncClient, pool: Any) -> int:
326340
"""Compute release rarity scores and store results."""
327341
started_at = datetime.now(UTC)
328342
try:
329-
results = await _fetch_from_api(client, "/api/internal/insights/rarity-scores", timeout=600.0)
343+
# The API runs eight full-graph Neo4j scans sequentially (to cap transaction
344+
# memory), so allow generous headroom over the client default.
345+
results = await _fetch_from_api(client, "/api/internal/insights/rarity-scores", timeout=1200.0)
330346
if not results:
331347
logger.info("📊 No rarity score results to store")
332348
await _log_computation(pool, "release_rarity", "completed", started_at, 0)
@@ -367,11 +383,11 @@ async def compute_and_store_rarity(client: httpx.AsyncClient, pool: Any) -> int:
367383
await _log_computation(pool, "release_rarity", "completed", started_at, len(results))
368384
return len(results)
369385
except Exception as e:
370-
logger.error("❌ Release rarity computation failed", error=str(e))
386+
logger.error("❌ Release rarity computation failed", error=_describe_error(e))
371387
try:
372-
await _log_computation(pool, "release_rarity", "failed", started_at, error_message=str(e))
388+
await _log_computation(pool, "release_rarity", "failed", started_at, error_message=_describe_error(e))
373389
except Exception as log_err:
374-
logger.warning("⚠️ Failed to log computation error", error=str(log_err))
390+
logger.warning("⚠️ Failed to log computation error", error=_describe_error(log_err))
375391
raise
376392

377393

tests/api/test_insights_compute.py

Lines changed: 13 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -245,6 +245,19 @@ def test_503_when_not_ready(self, test_client: TestClient) -> None:
245245
finally:
246246
ic_router._neo4j = original
247247

248+
def test_503_on_transient_neo4j_error(self, test_client: TestClient) -> None:
249+
"""A transient Neo4j error (e.g. out-of-memory) returns 503, not 500."""
250+
from neo4j.exceptions import TransientError
251+
252+
err = TransientError("MemoryPoolOutOfMemoryError")
253+
with patch(
254+
"api.routers.insights_compute.fetch_all_rarity_signals",
255+
new=AsyncMock(side_effect=err),
256+
):
257+
response = test_client.get("/api/internal/insights/rarity-scores")
258+
assert response.status_code == 503
259+
assert "error" in response.json()
260+
248261

249262
class TestAnniversariesValidation:
250263
"""Tests for milestones query parameter validation (lines 82-83)."""

tests/insights/test_computations.py

Lines changed: 18 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -119,6 +119,24 @@ async def test_returns_empty_list_when_no_items_key(self) -> None:
119119
assert result == []
120120

121121

122+
class TestDescribeError:
123+
"""Tests for _describe_error — guards against blank error log lines."""
124+
125+
def test_includes_type_when_message_empty(self) -> None:
126+
"""An exception with an empty str() (e.g. httpx.ReadTimeout) still names its type."""
127+
import httpx
128+
129+
from insights.computations import _describe_error
130+
131+
# httpx.ReadTimeout("") has an empty str(), which previously logged as error="".
132+
assert _describe_error(httpx.ReadTimeout("")) == "ReadTimeout"
133+
134+
def test_includes_type_and_message_when_present(self) -> None:
135+
from insights.computations import _describe_error
136+
137+
assert _describe_error(ValueError("boom")) == "ValueError: boom"
138+
139+
122140
class TestComputeAndStoreArtistCentrality:
123141
@pytest.mark.asyncio
124142
async def test_fetches_from_api_and_stores_results(self) -> None:

tests/insights/test_rarity_computation.py

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -61,7 +61,7 @@ async def test_fetches_and_stores(self) -> None:
6161
mock_fetch.assert_called_once_with(
6262
mock_client,
6363
"/api/internal/insights/rarity-scores",
64-
timeout=600.0,
64+
timeout=1200.0,
6565
)
6666

6767
@pytest.mark.asyncio

0 commit comments

Comments
 (0)