Files
FabledScribe/tests/test_services_retrieval_telemetry.py
T
bvandeusenandClaude Fable 5 64bfa5725f
CI & Build / Python lint (push) Successful in 3s
CI & Build / Plugin hooks (push) Successful in 7s
CI & Build / integration (push) Successful in 25s
CI & Build / TypeScript typecheck (push) Successful in 33s
CI & Build / Python tests (push) Successful in 1m3s
CI & Build / Build & push image (push) Successful in 20s
feat(telemetry): a read surface over retrieval_logs — the tuning loop had no read half (#2975)
`retrieval_logs` was write-only. `record_retrieval` inserted rows and nothing
in the tree ever selected from them: the only `select()` over RetrievalLog
lived in a test. So #1038's gate — "build the reranker once telemetry shows
precision is the bottleneck" — was unsatisfiable by construction, and the one
real tuning decision on record (the 0.68 write-path threshold, #2223) had to
be reached by hand-probing the live instance with eight payloads. This adds
the half that was missing.

`retrieval_summary(user_id, days=30)` returns two aggregates side by side,
each read from the table built for it — NOT a join. NoteUsageEvent's docstring
is explicit that the two are complements ("RetrievalLog tunes the threshold,
this tunes the corpus") and that RetrievalLog's JSONB `result_ids` cannot be
indexed at the per-note grain, so correlating through it would be both slower
and less honest than reading each source directly. That corrects the approach
sketched on the task.

  - `sources`, per surface: calls, zero_result_calls, cleared_threshold (how
    often the best hit beat the threshold in force for THAT call), the
    top_score spread as p10/p50/p90/min/max, avg_result_count, p90 duration.
    Zero-result calls are counted apart from low-scoring ones — they are a
    different failure and averaging them together would hide both.
  - `usage`, from note_usage_events: ranked surfacings, ambient surfacings,
    and pulls split into `pulled_by_agent` / `pulled_by_human`.

That split is not decoration. NoteUsageEvent's own comment says the mcp_/rest_
prefix is load-bearing and names #1038 while saying so: "is this dead weight?"
is answered by any pull, "was that injected line useful?" only by an agent
pull. `pull_through` exists to answer the second, so it counts agent pulls
over ranked surfacings; both halves ship so the first stays answerable.

Two things the code made me get right rather than guess:

  - Distinct-note counts get their own queries. `count(distinct note_id)` per
    (event, source) group cannot be summed across groups — a note surfaced by
    two sources is one distinct note and would be counted twice. A wrong
    number labelled "distinct" is worse than no number.
  - No CASE in the GROUP BY. #2663 is the bug where a second case() rendered
    its own expanding bind names, Postgres rejected the query, a broad except
    swallowed it, and every counter read zero in production while mocked tests
    passed. Grouping on raw `source` and classifying in Python cannot fail
    that way. For the same reason the readout distinguishes `read_failed` from
    an empty window, and its tests are integration against real Postgres —
    percentile_cont ... WITHIN GROUP only proves it parses against a database.

Exposed as the `retrieval_telemetry` MCP tool, added to `_READ_ONLY_TOOLS`:
it mutates nothing, but its name carries no read prefix, so the completeness
test cannot derive it and it would otherwise have failed closed for read-only
keys in silence — the same reason `enter_project` is spelled out there. Docs
updated to name both exceptions rather than leave the rule looking derivable.

Scoped to the caller's own telemetry: a retrieval log records what one user's
agent asked for, query text included, and is not a shared record kind — the
owner filter is the whole access rule, not a shortcut past access.py.

Co-Authored-By: Claude Fable 5 <noreply@anthropic.com>
2026-08-23 22:48:54 -04:00

225 lines
9.4 KiB
Python

"""Tests for services.retrieval_telemetry.
_build_payload is pure (no DB, no loop) and gets unit coverage. The persistence
path (_insert_retrieval_log + the RetrievalLog model / JSONB roundtrip) is an
integration test against real Postgres.
"""
from types import SimpleNamespace
import pytest
from scribe.services.retrieval_telemetry import (
_build_payload,
record_retrieval,
)
def _note(nid):
"""Minimal stand-in — _build_payload only reads .id."""
return SimpleNamespace(id=nid)
# ─── _build_payload (pure) ───────────────────────────────────────────────────
def test_build_payload_ranks_and_score_bounds():
results = [(0.91, _note(11)), (0.72, _note(22)), (0.55, _note(33))]
p = _build_payload(
user_id=7, source="mcp_search", query="hello", threshold=0.45,
limit=10, project_id=3, is_task=None, results=results, duration_ms=12.345,
)
assert p["result_count"] == 3
assert p["top_score"] == 0.91
assert p["min_score"] == 0.55
assert [it["rank"] for it in p["result_ids"]] == [0, 1, 2]
assert [it["id"] for it in p["result_ids"]] == [11, 22, 33]
assert p["duration_ms"] == 12.35 # rounded to 2dp
assert p["user_id"] == 7 and p["project_id"] == 3 and p["threshold"] == 0.45
def test_build_payload_empty_results():
p = _build_payload(
user_id=1, source="rest_search", query="x", threshold=0.3,
limit=5, project_id=None, is_task=False, results=[], duration_ms=None,
)
assert p["result_count"] == 0
assert p["top_score"] is None and p["min_score"] is None
assert p["result_ids"] == []
assert p["duration_ms"] is None
def test_build_payload_rounds_scores_to_5dp():
p = _build_payload(
user_id=1, source="mcp_search", query="q", threshold=0.45,
limit=1, project_id=None, is_task=None,
results=[(0.123456789, _note(1))], duration_ms=0.0,
)
assert p["result_ids"][0]["score"] == 0.12346
def test_record_retrieval_without_event_loop_is_safe():
"""Called from a sync context (no running loop) it must swallow and return,
never raise — telemetry can't be allowed to break a caller."""
# No event loop running in this plain sync test.
assert record_retrieval(
user_id=1, source="mcp_search", query="q", threshold=0.45,
limit=10, project_id=None, is_task=None,
results=[(0.9, _note(1))],
) is None
# ─── persistence (integration) ───────────────────────────────────────────────
@pytest.mark.integration
@pytest.mark.asyncio
async def test_insert_retrieval_log_roundtrip(_dispose_engine):
from sqlalchemy import delete, select
from scribe.models import async_session
from scribe.models.retrieval_log import RetrievalLog
from scribe.services.retrieval_telemetry import _insert_retrieval_log
payload = _build_payload(
user_id=990001, source="mcp_search", query="pgvector tuning",
threshold=0.45, limit=10, project_id=None, is_task=None,
results=[(0.88, _note(501)), (0.61, _note(502))], duration_ms=9.9,
)
await _insert_retrieval_log(payload)
async with async_session() as s:
row = (
await s.execute(
select(RetrievalLog).where(RetrievalLog.user_id == 990001)
)
).scalars().first()
assert row is not None
assert row.source == "mcp_search"
assert row.result_count == 2
assert row.top_score == 0.88
# JSONB roundtrips as a list of dicts with the expected shape.
assert row.result_ids[0] == {"id": 501, "score": 0.88, "rank": 0}
assert row.created_at is not None # server_default now()
await s.execute(delete(RetrievalLog).where(RetrievalLog.user_id == 990001))
await s.commit()
# ─── the read half: retrieval_summary (integration) ──────────────────────────
# Integration, not mocked, and deliberately so. #2663 is the bug where a
# GROUP BY the database rejected was swallowed by a broad except, so every
# counter read zero in production while the writes landed fine and the mocked
# tests passed. `retrieval_summary` runs a grouped aggregate with
# percentile_cont ... WITHIN GROUP and a two-label CASE — precisely the shape
# that failed then. Only a real Postgres can say it parses.
@pytest.mark.integration
@pytest.mark.asyncio
async def test_retrieval_summary_reads_what_the_writer_wrote(_dispose_engine):
from sqlalchemy import delete
from scribe.models import async_session
from scribe.models.note_usage import NoteUsageEvent
from scribe.models.retrieval_log import RetrievalLog
from scribe.services.retrieval_telemetry import (
_insert_retrieval_log, retrieval_summary,
)
UID = 990002
# Three auto_inject calls at a 0.55 bar: two clear it, one does not.
# Plus one call that returned nothing at all — a different failure from a
# low-scoring one, and the readout must not blend them.
for score in (0.91, 0.72, 0.40):
await _insert_retrieval_log(_build_payload(
user_id=UID, source="auto_inject", query="q", threshold=0.55,
limit=3, project_id=None, is_task=None,
results=[(score, _note(1))], duration_ms=5.0,
))
await _insert_retrieval_log(_build_payload(
user_id=UID, source="auto_inject", query="q", threshold=0.55,
limit=3, project_id=None, is_task=None, results=[], duration_ms=5.0,
))
# A second surface, so the GROUP BY has something to separate.
await _insert_retrieval_log(_build_payload(
user_id=UID, source="mcp_search", query="q", threshold=0.45,
limit=10, project_id=None, is_task=None,
results=[(0.80, _note(2))], duration_ms=11.0,
))
# Corpus side: two ranked surfacings, one ambient, one pull.
async with async_session() as s:
s.add_all([
NoteUsageEvent(user_id=UID, note_id=1, event="surfaced", source="auto_inject"),
NoteUsageEvent(user_id=UID, note_id=2, event="surfaced", source="auto_inject"),
NoteUsageEvent(user_id=UID, note_id=3, event="surfaced", source="enter_project"),
NoteUsageEvent(user_id=UID, note_id=1, event="pulled", source="mcp_get_note"),
])
await s.commit()
try:
out = await retrieval_summary(UID, days=30)
assert out["read_failed"] is False, "the aggregate did not execute"
ai = out["sources"]["auto_inject"]
assert ai["calls"] == 4
assert ai["zero_result_calls"] == 1
assert ai["cleared_threshold"] == 2 # 0.91 and 0.72, not 0.40
# p50 over the three scored calls; the empty one contributes no score.
assert ai["top_score"]["p50"] == pytest.approx(0.72, abs=1e-4)
assert ai["top_score"]["min"] == pytest.approx(0.40, abs=1e-4)
assert ai["top_score"]["max"] == pytest.approx(0.91, abs=1e-4)
assert out["sources"]["mcp_search"]["calls"] == 1
u = out["usage"]
assert u["surfaced"] == 2 and u["ambient"] == 1 and u["pulled"] == 1
assert u["distinct_notes_surfaced"] == 2
# The pull came from `mcp_get_note`, so it counts as an AGENT pull
# and drives pull_through; a human `rest_*` pull would not.
assert u["pulled_by_agent"] == 1 and u["pulled_by_human"] == 0
assert u["pull_through"] == pytest.approx(0.5)
finally:
async with async_session() as s:
await s.execute(delete(RetrievalLog).where(RetrievalLog.user_id == UID))
await s.execute(delete(NoteUsageEvent).where(NoteUsageEvent.user_id == UID))
await s.commit()
@pytest.mark.integration
@pytest.mark.asyncio
async def test_retrieval_summary_is_empty_not_broken_for_a_fresh_install(_dispose_engine):
"""Rule #115: an install with no telemetry gets a coherent zero readout,
and `read_failed` stays False — the distinction #2663 says must exist."""
from scribe.services.retrieval_telemetry import retrieval_summary
out = await retrieval_summary(990003, days=30)
assert out["read_failed"] is False
assert out["sources"] == {}
assert out["usage"]["pull_through"] is None # no division by zero
assert out["usage"]["surfaced"] == 0
@pytest.mark.integration
@pytest.mark.asyncio
async def test_retrieval_summary_sees_only_its_own_users_telemetry(_dispose_engine):
"""A retrieval log records what one user's agent asked for, query text
included. The owner filter is the access rule, so it gets a test."""
from sqlalchemy import delete
from scribe.models import async_session
from scribe.models.retrieval_log import RetrievalLog
from scribe.services.retrieval_telemetry import (
_insert_retrieval_log, retrieval_summary,
)
await _insert_retrieval_log(_build_payload(
user_id=990004, source="auto_inject", query="theirs", threshold=0.55,
limit=3, project_id=None, is_task=None, results=[(0.9, _note(1))],
duration_ms=1.0,
))
try:
assert (await retrieval_summary(990005, days=30))["sources"] == {}
assert (await retrieval_summary(990004, days=30))["sources"]["auto_inject"]["calls"] == 1
finally:
async with async_session() as s:
await s.execute(delete(RetrievalLog).where(RetrievalLog.user_id == 990004))
await s.commit()