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>

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:

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)

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)