diff --git a/docs/api-keys-and-mcp.md b/docs/api-keys-and-mcp.md index f6ebe4c..d950d4b 100644 --- a/docs/api-keys-and-mcp.md +++ b/docs/api-keys-and-mcp.md @@ -43,8 +43,10 @@ client straight to the URL with a Bearer token. Authenticate with an API key generated from **Settings → API Keys** (see above), sent as `Authorization: Bearer fmcp_`. A `read`-scoped key may call only the -read tools (`get_*`, `list_*`, `search`, `enter_project`); any write/delete tool -is rejected with `403`. A `write`-scoped key may call everything. +read tools (`get_*`, `list_*`, `search`, `enter_project`, `retrieval_telemetry`); +any write/delete tool is rejected with `403`. The allow-list is explicit rather +than derived from the name — see `_READ_ONLY_TOOLS`, which is why the two reads +without a read-shaped name are spelled out here. A `write`-scoped key may call everything. ### Claude Code (Project-scoped) @@ -85,7 +87,7 @@ table here. The tools are grouped by family: | Notes | `create_note`, `get_note`, `update_note`, `delete_note`, `list_notes` | Free-form knowledge | | Tasks | `create_task`, `update_task`, `add_task_log`, `start_planning` | Actionable work + plans | | Projects / Milestones | `enter_project`, `get_project`, `create_milestone`, … | Containers and outcomes | -| Search / Recall | `search`, `get_recent`, `list_tags` | Semantic + structured recall | +| Search / Recall | `search`, `get_recent`, `list_tags`, `retrieval_telemetry` | Semantic + structured recall, and the readout its thresholds are tuned from | | Systems | `create_system`, `list_systems`, `list_system_records` | Reusable per-project subsystems/areas | | Rulebooks | `list_always_on_rules`, `list_rules`, `create_rule`, `create_project_rule`, `subscribe_project_to_rulebook`, … | Engineering/workflow rules | | Processes | `list_processes`, `get_process`, `create_process` | Saved prompts/workflows | diff --git a/src/scribe/mcp/server.py b/src/scribe/mcp/server.py index 4ccc7a0..5f0a8d5 100644 --- a/src/scribe/mcp/server.py +++ b/src/scribe/mcp/server.py @@ -112,6 +112,11 @@ _READ_ONLY_TOOLS = frozenset({ # The shape ledger's todo query (#2789). Reads only — classify_shapes is # the write, and it is deliberately NOT here. "list_shapes", "shape_history", + # The retrieval telemetry readout (#2975). Aggregates two log tables and + # writes nothing. Listed explicitly because its name carries no read + # prefix, so the completeness test below cannot derive it — the same + # reason `enter_project` is spelled out above. + "retrieval_telemetry", }) # Read-SHAPED tools that must NOT be reachable with a read key — a getter that diff --git a/src/scribe/mcp/tools/search.py b/src/scribe/mcp/tools/search.py index dbe2f28..b1e5775 100644 --- a/src/scribe/mcp/tools/search.py +++ b/src/scribe/mcp/tools/search.py @@ -12,7 +12,7 @@ import time from scribe.mcp._context import current_user_id from scribe.services.access import owner_names_for from scribe.services.embeddings import DEFAULT_SIMILARITY_THRESHOLD, semantic_search_notes -from scribe.services.retrieval_telemetry import record_retrieval +from scribe.services.retrieval_telemetry import record_retrieval, retrieval_summary async def search( @@ -95,5 +95,52 @@ async def search( } +async def retrieval_telemetry(days: int = 30) -> dict: + """What the retrieval telemetry says about YOUR surfaces, over a window. + + The read half of the loop the ranker's thresholds are meant to be tuned + from (#2975). Reach for it before changing a similarity threshold, a top-k, + or deciding whether a reranker is worth building — the alternative is + hand-probing the live instance, which is how the last such decision had to + be made. + + Two readouts, from the two tables built for them: + + `sources` — per retrieval surface (`auto_inject`, `write_path`, + `mcp_search`, …), from `retrieval_logs`: `calls`, `zero_result_calls`, + `cleared_threshold` (how often the best hit beat the threshold in force for + that call), the `top_score` spread (p10/p50/p90/min/max), `avg_result_count` + and `p90_duration_ms`. THE number to read first is `cleared_threshold` + against `calls`, with the spread beside it: a surface that clears its bar + on nearly every call is either well-tuned or too loose, and p10 says which. + + `usage` — from `note_usage_events`, at the per-note grain + `retrieval_logs` cannot be indexed at: `surfaced` (ranked surfacings — a + scored surface CHOSE the record), `ambient` (the rest), `pulled` split into + `pulled_by_agent` / `pulled_by_human`, the distinct-note counts, and + `pull_through`. That ratio is the corpus-side precision signal: records + surfaced often and opened never are dead weight competing for the injection + budget every turn. + + `pull_through` is AGENT pulls over RANKED surfacings, and both halves of + that matter. "Is this record dead weight?" is answered by any pull; "was + that injected line useful?" — the question a threshold or a reranker is + tuned against — only by a pull the agent made. Aggregating across the + mcp_/rest_ prefix would silently answer the wrong one. + + Scoped to your own telemetry — a retrieval log records what your agent + asked for, query text included, and is not a shared record kind. + + `read_failed: true` means the query itself failed — deliberately distinct + from an empty window, because those two looked identical for weeks once + (#2663) and every counter silently read zero. + + Args: + days: window size, default 30. Clamped to at least 1. + """ + return await retrieval_summary(current_user_id(), days=days) + + def register(mcp) -> None: mcp.tool(name="search")(search) + mcp.tool(name="retrieval_telemetry")(retrieval_telemetry) diff --git a/src/scribe/services/retrieval_telemetry.py b/src/scribe/services/retrieval_telemetry.py index b8fb21f..65b6cbc 100644 --- a/src/scribe/services/retrieval_telemetry.py +++ b/src/scribe/services/retrieval_telemetry.py @@ -18,8 +18,14 @@ from __future__ import annotations import asyncio import logging +from datetime import datetime, timedelta, timezone + +from sqlalchemy import case, func, select + from scribe.models import async_session +from scribe.models.base import iso from scribe.models.note import Note +from scribe.models.note_usage import PULLED, SURFACED, NoteUsageEvent from scribe.models.retrieval_log import RetrievalLog logger = logging.getLogger(__name__) @@ -135,3 +141,205 @@ def record_retrieval( return _pending.add(task) task.add_done_callback(_pending.discard) + + +# --- The read half (#2975) --------------------------------------------------- +# Until this existed, `retrieval_logs` was WRITE-ONLY: rows accrued and the only +# `select()` over them in the whole tree lived in a test. That made #1038's gate +# — "build the reranker once telemetry shows precision is the bottleneck" — +# unsatisfiable by construction, and it is why the one real tuning decision on +# record (the 0.68 write-path threshold, #2223) was reached by hand-probing the +# live instance with eight payloads instead of by reading what was collected. + +def _bucket(rows: list) -> dict: + """A score readout a human can act on, from one aggregate row.""" + calls, zero, cleared, p10, p50, p90, lo, hi, avg_n, dur = rows + return { + "calls": int(calls or 0), + # A call that returned nothing is not a low-scoring call — it is a + # different failure (nothing indexed, filter too narrow), and averaging + # it into the score distribution would hide both. + "zero_result_calls": int(zero or 0), + # How often the best hit actually cleared the threshold in force for + # that call. THE precision-adjacent number: a surface that clears its + # bar on almost every call is either well-tuned or too loose, and the + # score spread below says which. + "cleared_threshold": int(cleared or 0), + "top_score": { + "p10": _round(p10), "p50": _round(p50), "p90": _round(p90), + "min": _round(lo), "max": _round(hi), + }, + "avg_result_count": _round(avg_n), + "p90_duration_ms": _round(dur, 1), + } + + +def _round(v, places: int = 4): + return None if v is None else round(float(v), places) + + +async def retrieval_summary(user_id: int | None, *, days: int = 30) -> dict: + """What the retrieval telemetry says, per surface, over a window. + + Two aggregates side by side, each read from the table built for it — NOT a + join. `NoteUsageEvent`'s own docstring is explicit that the two are + complements ("RetrievalLog tunes the threshold, this tunes the corpus") and + that RetrievalLog's JSONB `result_ids` "can't be indexed at" the per-note + grain. So the score distribution comes from `retrieval_logs` on its indexed + columns, and surfaced-vs-pulled comes from `note_usage_events` at the grain + it was built for. Reading each from its own table is both cheaper and more + honest than correlating them through JSONB. + + Scoped to one user's own telemetry. There is no sharing model for a + retrieval log — it records what THIS user's agent asked for, including the + query text — so an owner filter is the whole access rule here rather than a + shortcut around `services/access.py` (P#78 governs shared record kinds). + + Never raises: a telemetry readout that can break its caller is worse than + no readout. It does distinguish "no rows" from "the read failed", because + #2663 is exactly the bug where those two looked identical for weeks. + """ + since = datetime.now(timezone.utc) - timedelta(days=max(1, int(days))) + out: dict = { + "window_days": int(days), + "since": iso(since), + "sources": {}, + "usage": {}, + "read_failed": False, + } + + cleared = case( + ( + (RetrievalLog.threshold.isnot(None)) + & (RetrievalLog.top_score.isnot(None)) + & (RetrievalLog.top_score >= RetrievalLog.threshold), + 1, + ), + else_=0, + ) + zero = case((RetrievalLog.result_count == 0, 1), else_=0) + + def pct(p: float): + return func.percentile_cont(p).within_group(RetrievalLog.top_score.asc()) + + try: + async with async_session() as session: + rows = ( + await session.execute( + select( + RetrievalLog.source, + func.count().label("calls"), + func.sum(zero).label("zero"), + func.sum(cleared).label("cleared"), + pct(0.1), pct(0.5), pct(0.9), + func.min(RetrievalLog.top_score), + func.max(RetrievalLog.top_score), + func.avg(RetrievalLog.result_count), + func.percentile_cont(0.9).within_group( + RetrievalLog.duration_ms.asc() + ), + ) + .where( + RetrievalLog.created_at >= since, + RetrievalLog.user_id == user_id, + ) + .group_by(RetrievalLog.source) + ) + ).all() + for row in rows: + out["sources"][row[0]] = _bucket(list(row[1:])) + + # The corpus side, at its own grain. `ambient` mirrors + # note_usage.usage_for_notes: an ambient surfacing was not a scored + # CHOICE, so folding it into pull-through would understate it. + # Grouped by RAW source, then classified in Python. The + # alternative — CASE expressions in the GROUP BY — is the shape + # that produced #2663: a second case() renders its own expanding + # bind names, the database sees two different expressions and + # rejects the query, and the broad except swallows it. One CASE is + # provably fine (usage_for_notes does it); two is where it broke. + # `source` has a handful of distinct values, so grouping on it + # directly is cheap and cannot fail that way at all. + urows = ( + await session.execute( + select( + NoteUsageEvent.event, + NoteUsageEvent.source, + func.count().label("n"), + ) + .where( + NoteUsageEvent.created_at >= since, + NoteUsageEvent.user_id == user_id, + ) + .group_by(NoteUsageEvent.event, NoteUsageEvent.source) + ) + ).all() + + # Distinct-note counts need their OWN queries, and this is not + # fussiness: 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. + from scribe.services.note_usage import AMBIENT_SOURCES as _AMB + + distinct_surfaced = ( + await session.execute( + select(func.count(func.distinct(NoteUsageEvent.note_id))).where( + NoteUsageEvent.created_at >= since, + NoteUsageEvent.user_id == user_id, + NoteUsageEvent.event == SURFACED, + NoteUsageEvent.source.notin_(_AMB), + ) + ) + ).scalar_one() + distinct_pulled = ( + await session.execute( + select(func.count(func.distinct(NoteUsageEvent.note_id))).where( + NoteUsageEvent.created_at >= since, + NoteUsageEvent.user_id == user_id, + NoteUsageEvent.event == PULLED, + ) + ) + ).scalar_one() + except Exception: + logger.warning("retrieval summary read failed", exc_info=True) + out["read_failed"] = True + return out + + from scribe.services.note_usage import AMBIENT_SOURCES + + usage = { + "surfaced": 0, "ambient": 0, + "pulled": 0, "pulled_by_agent": 0, "pulled_by_human": 0, + "distinct_notes_surfaced": int(distinct_surfaced or 0), + "distinct_notes_pulled": int(distinct_pulled or 0), + } + for event, source, n in urows: + n = int(n) + if event == SURFACED: + if source in AMBIENT_SOURCES: + usage["ambient"] += n + else: + usage["surfaced"] += n + elif event == PULLED: + usage["pulled"] += n + # The mcp_/rest_ split is load-bearing (see NoteUsageEvent's own + # comment, which names #1038 — this readout's whole purpose). "Is + # this record dead weight?" is answered by ANY pull; "was that + # injected line useful to the agent?" only by an AGENT pull. So + # pull-through, which exists to answer the second, counts mcp_* + # only. Both halves are reported so the first question is still + # answerable from the same payload. + if source.startswith("mcp_"): + usage["pulled_by_agent"] += n + else: + usage["pulled_by_human"] += n + # Ranked surfacings in the denominator, agent pulls in the numerator: the + # "surfaced often, opened never" reading is only valid where a scored + # surface CHOSE the record and an agent was the one who declined it. + usage["pull_through"] = ( + round(usage["pulled_by_agent"] / usage["surfaced"], 4) + if usage["surfaced"] else None + ) + out["usage"] = usage + return out diff --git a/tests/test_services_retrieval_telemetry.py b/tests/test_services_retrieval_telemetry.py index 67a5d01..bd69dd7 100644 --- a/tests/test_services_retrieval_telemetry.py +++ b/tests/test_services_retrieval_telemetry.py @@ -102,3 +102,123 @@ async def test_insert_retrieval_log_roundtrip(_dispose_engine): 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()