From 77acee92391961bce165c72e31e168930baae2c1 Mon Sep 17 00:00:00 2001 From: Bryan Van Deusen Date: Fri, 14 Aug 2026 21:45:32 -0400 Subject: [PATCH] fix(telemetry): usage counters get canaries, task references, and the missing integration tests (#2663) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit 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 --- src/scribe/services/note_usage.py | 63 ++++++++++++++++-- src/scribe/services/retrieval_telemetry.py | 28 +++++++- tests/test_note_usage.py | 76 ++++++++++++++++++++++ 3 files changed, 157 insertions(+), 10 deletions(-) diff --git a/src/scribe/services/note_usage.py b/src/scribe/services/note_usage.py index 041b42a..3cff648 100644 --- a/src/scribe/services/note_usage.py +++ b/src/scribe/services/note_usage.py @@ -15,8 +15,13 @@ Design notes (mirrors retrieval_telemetry, for the same reasons): - Writes are fire-and-forget. `record_surfaced` / `record_pulled` extract plain ints synchronously and schedule the insert as a background task, so telemetry never adds latency to — or can break — the surface it observes. - - Every failure path is swallowed. Losing a usage row costs a data point; - raising would cost the operator their retrieval. + - Failures degrade, but they must not degrade SILENTLY. The original version + swallowed everything into logger.debug, and the deployed instance ran with + every counter at zero for weeks while surfacing demonstrably fired — a + total outage indistinguishable from "nobody uses this" (#2663). A + subsystem whose every failure mode is invisible cannot report its own + death, so failures now log at WARNING and drop one AppLog error row per + process per site, where the admin UI shows it. - Reads (`usage_for_notes`) are NOT fire-and-forget — a readout the caller awaits, aggregated in one round-trip for a whole page of snippets rather than per row. @@ -25,6 +30,7 @@ from __future__ import annotations import asyncio import logging +import traceback from sqlalchemy import case, func, select @@ -33,26 +39,67 @@ from scribe.models.note_usage import PULLED, SURFACED, NoteUsageEvent logger = logging.getLogger(__name__) +# Strong references to in-flight inserts. The event loop keeps only a WEAK +# reference to a task, so a fire-and-forget create_task with no other holder +# can be garbage-collected before it completes — a write that never errors and +# never lands. The done-callback discard keeps the set from growing. +_pending: set[asyncio.Task] = set() + +# Sites that already dropped their once-per-process AppLog row. The readout +# runs on every snippet list render — without this, a broken table would turn +# the error log into a firehose that buries the finding it exists to surface. +_reported: set[str] = set() + + +async def _report_failure(site: str) -> None: + """Make a swallowed telemetry failure visible. Called from an except block. + + WARNING to the process log every time; one AppLog error row per process per + site so the admin UI shows the outage without host access. The AppLog write + is itself guarded — when the whole database is down it fails too, and that + is fine: the WARNING already said so, and a canary must never take down the + surface it watches. + """ + logger.warning("note usage telemetry %s failed", site, exc_info=True) + if site in _reported: + return + _reported.add(site) + try: + from scribe.services.logging import log_error + + await log_error( + endpoint="note_usage", + error_type=f"note_usage_{site}_failed", + error_message=f"note usage telemetry {site} is failing; " + "usage counters will read zero until this is fixed", + traceback=traceback.format_exc(), + ) + except Exception: + logger.debug("note usage canary write failed", exc_info=True) + async def _insert_events(rows: list[dict]) -> None: - """Persist usage rows. Best-effort: all errors are swallowed.""" + """Persist usage rows. Best-effort: failures degrade, visibly.""" try: async with async_session() as session: session.add_all([NoteUsageEvent(**row) for row in rows]) await session.commit() except Exception: - logger.debug("note usage telemetry write skipped", exc_info=True) + await _report_failure("write") def _schedule(rows: list[dict]) -> None: if not rows: return try: - asyncio.get_running_loop().create_task(_insert_events(rows)) + task = asyncio.get_running_loop().create_task(_insert_events(rows)) except RuntimeError: # No running loop (sync context outside the app) — skip rather than # block. Every app path runs on the loop. logger.debug("note usage telemetry skipped — no running event loop") + return + _pending.add(task) + task.add_done_callback(_pending.discard) def record_surfaced( @@ -168,8 +215,10 @@ async def usage_for_notes(note_ids: list[int]) -> dict[int, dict]: ) ).all() except Exception: - # A telemetry readout must not be able to break the list it decorates. - logger.debug("note usage readout failed", exc_info=True) + # A telemetry readout must not be able to break the list it decorates — + # but it must say it failed, or a broken readout is indistinguishable + # from a corpus nobody uses (#2663). + await _report_failure("readout") return out for note_id, event, n, last_at, ambient in rows: diff --git a/src/scribe/services/retrieval_telemetry.py b/src/scribe/services/retrieval_telemetry.py index 7ab8d8a..b8fb21f 100644 --- a/src/scribe/services/retrieval_telemetry.py +++ b/src/scribe/services/retrieval_telemetry.py @@ -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) diff --git a/tests/test_note_usage.py b/tests/test_note_usage.py index 11c6e62..6a81942 100644 --- a/tests/test_note_usage.py +++ b/tests/test_note_usage.py @@ -8,6 +8,7 @@ before this it surfaced snippets while leaving no trace anywhere. from unittest.mock import AsyncMock, MagicMock, patch import pytest +import pytest_asyncio @pytest.fixture(autouse=True) @@ -249,3 +250,78 @@ def test_every_getter_that_can_be_surfaced_also_records_a_pull(): f"{name} can be surfaced in an auto-inject menu but records no pull — " "its pull-through rate will read as zero regardless of real usage" ) + + +# --- persistence (integration) -------------------------------------------- +# Everything above mocks _schedule or the session — deliberately, for the hot +# path. But that left the two functions that actually touch the database +# (_insert_events and usage_for_notes' real SQL) running against real Postgres +# nowhere, which is how the deployed instance reported zero for every counter +# while surfacing demonstrably fired (#2663): all-green mocked units over a +# dead real path, the #2109 shape. These two run in the CI integration lane +# and split the chain so a failure names its half. + + +@pytest_asyncio.fixture +async def _dispose_engine(): + from scribe.models import engine + yield + await engine.dispose() + + +async def _purge(note_id: int) -> None: + from sqlalchemy import delete + + from scribe.models import async_session + from scribe.models.note_usage import NoteUsageEvent + + async with async_session() as s: + await s.execute( + delete(NoteUsageEvent).where(NoteUsageEvent.note_id == note_id) + ) + await s.commit() + + +@pytest.mark.integration +async def test_insert_and_readout_roundtrip_on_real_postgres(_dispose_engine): + """WRITE half + READ half against the real table, one assertion per counter.""" + from scribe.services.note_usage import _insert_events + + nid = 990101 + try: + await _insert_events([ + {"user_id": 7, "note_id": nid, "event": "surfaced", + "source": "write_path_place"}, + {"user_id": 7, "note_id": nid, "event": "surfaced", + "source": "enter_project"}, + {"user_id": 7, "note_id": nid, "event": "pulled", + "source": "mcp_get_snippet"}, + ]) + out = await usage_for_notes([nid]) + # write_path_place is a ranked choice; enter_project is ambient (#2477). + assert out[nid]["surfaced_count"] == 1 + assert out[nid]["ambient_count"] == 1 + assert out[nid]["pull_count"] == 1 + assert out[nid]["last_surfaced_at"] is not None + assert out[nid]["last_pulled_at"] is not None + finally: + await _purge(nid) + + +@pytest.mark.integration +async def test_record_pulled_lands_end_to_end_from_a_running_loop(_dispose_engine): + """The exact chain the deployed instance runs: record_pulled schedules a + fire-and-forget task on the running loop, and the row must land. The + _pending set (which exists to keep the loop's weak-ref'd tasks alive) is + also what lets this test await a write that is fire-and-forget by design.""" + import asyncio + + nid = 990102 + try: + record_pulled(user_id=7, note_id=nid, source="mcp_get_snippet") + assert note_usage._pending, "record_pulled scheduled no task" + await asyncio.gather(*note_usage._pending) + out = await usage_for_notes([nid]) + assert out[nid]["pull_count"] == 1 + finally: + await _purge(nid)