fix(telemetry): usage counters get canaries, task references, and the missing integration tests (#2663)

The deployed instance ran with every usage counter at zero while surfacing
demonstrably fired. Every unit test was green because every unit test mocked
either _schedule or the session — the two functions that touch the database
ran against real Postgres nowhere. Both telemetry writers also held no
reference to their fire-and-forget tasks (the loop keeps only weak ones), and
swallowed every failure into logger.debug, so a total outage was
indistinguishable from an unused corpus.

- note_usage + retrieval_telemetry keep strong task references until done
- failures log at WARNING; note_usage additionally drops one AppLog error row
  per process per site, so the admin UI shows the outage without host access
- integration tests cover _insert_events -> usage_for_notes and the full
  record_pulled chain on a running loop, splitting the write and read halves
  so a failure names its side

Co-Authored-By: Claude Fable 5 <noreply@anthropic.com>
This commit is contained in:
2026-08-14 21:45:32 -04:00
co-authored by Claude Fable 5
parent 5cb7cfe706
commit 77acee9239
3 changed files with 157 additions and 10 deletions
+25 -3
View File
@@ -24,6 +24,14 @@ from scribe.models.retrieval_log import RetrievalLog
logger = logging.getLogger(__name__)
# Strong references to in-flight inserts — the loop holds tasks only weakly,
# and an unreferenced fire-and-forget task can be collected before it runs
# (same guard as note_usage, found via #2663).
_pending: set[asyncio.Task] = set()
# Whether this process already dropped its one warning about failing writes.
_reported = False
def _build_payload(
*,
@@ -65,13 +73,24 @@ def _build_payload(
async def _insert_retrieval_log(payload: dict) -> None:
"""Persist one RetrievalLog row. Best-effort: all errors are swallowed."""
"""Persist one RetrievalLog row. Best-effort: failures degrade, visibly.
WARNING rather than debug — this table is the empirical basis for threshold
tuning, and a silent write outage yields a dataset that looks complete while
covering only part of the traffic (#2663's shape). Once per process is
enough to be found; per-call would flood the log with what it already said.
"""
global _reported
try:
async with async_session() as session:
session.add(RetrievalLog(**payload))
await session.commit()
except Exception:
logger.debug("retrieval telemetry write skipped", exc_info=True)
if not _reported:
_reported = True
logger.warning("retrieval telemetry write failed", exc_info=True)
else:
logger.debug("retrieval telemetry write skipped", exc_info=True)
def record_retrieval(
@@ -108,8 +127,11 @@ def record_retrieval(
return
try:
asyncio.get_running_loop().create_task(_insert_retrieval_log(payload))
task = asyncio.get_running_loop().create_task(_insert_retrieval_log(payload))
except RuntimeError:
# No running loop (e.g. called from sync context outside the app) —
# skip rather than block. The app paths always run on the loop.
logger.debug("retrieval telemetry skipped — no running event loop")
return
_pending.add(task)
task.add_done_callback(_pending.discard)