diff --git a/src/scribe/mcp/tools/search.py b/src/scribe/mcp/tools/search.py index c6db75d..410c308 100644 --- a/src/scribe/mcp/tools/search.py +++ b/src/scribe/mcp/tools/search.py @@ -182,6 +182,23 @@ async def retrieval_telemetry(days: int = 30) -> dict: tuned against — only by a pull the agent made. Aggregating across the mcp_/rest_ prefix would silently answer the wrong one. + `usage["by_source"]` — THE number to tune a threshold against, because the + top-level `pull_through` is a corpus average and averages the surfaces + together. Per surface: `notes_surfaced`, `notes_pulled`, `pull_through`, + and `ambient: true` on surfaces whose surfacings were not scored choices + (their ratio is null — "surfaced often, opened never" is not a judgment + about a record nothing chose). Read it as: of the distinct notes THIS + surface put in front of the agent, how many did the agent then open? + + Two limits on it, both deliberate. It is an UPPER BOUND per surface: a pull + records the door it came through, not the surface that led there, so a note + surfaced by two surfaces and opened once counts for both — attribution + would need the session identity #2085 declined to invent. And RULE + surfacings are absent: `write_path_rule` appears in `sources` with its + scores but has no usage counter at all, so it has no row here (#3311). + `by_source_failed: true` means that one query failed while the rest of the + readout stood. + Scoped to your own telemetry — a retrieval log records what your agent asked for, query text included, and is not a shared record kind. diff --git a/src/scribe/services/retrieval_telemetry.py b/src/scribe/services/retrieval_telemetry.py index 1fd747f..1377ecd 100644 --- a/src/scribe/services/retrieval_telemetry.py +++ b/src/scribe/services/retrieval_telemetry.py @@ -199,6 +199,12 @@ async def retrieval_summary(user_id: int | None, *, days: int = 30) -> dict: it was built for. Reading each from its own table is both cheaper and more honest than correlating them through JSONB. + `usage["by_source"]` is the one join, and it stays INSIDE + `note_usage_events` — surfaced rows against pulled rows on note_id. That + answers "of the notes this surface chose, how many were opened", which the + top-level ratio averages away. It does not cross into `retrieval_logs`, so + the sentence above still holds. + 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 @@ -231,6 +237,10 @@ async def retrieval_summary(user_id: int | None, *, days: int = 30) -> dict: def pct(p: float): return func.percentile_cont(p).within_group(RetrievalLog.top_score.asc()) + # Assigned inside the try below; named here so the readout can tell + # "this query failed" from "this window has no rows" (#2663). + by_source_rows = None + try: async with async_session() as session: rows = ( @@ -310,6 +320,77 @@ async def retrieval_summary(user_id: int | None, *, days: int = 30) -> dict: ) ) ).scalar_one() + + # Per-source pull-through, at the NOTE grain (#3311). + # + # The `urows` query above already groups by source and the loop + # below then throws the source away, so until now this readout + # could say what the corpus's overall pull-through was and nothing + # about WHICH surface earned it. The data was always here; only + # the aggregation discarded it. + # + # It cannot be had by grouping the PULLED rows by source: a pull + # records the door it came through (`mcp_get_note`), not the + # surface that put the record in front of the agent. Correlating + # those within a session is what #2085 ruled out — there is no + # session identity server-side and inventing one would mean + # threading a client-supplied token through every read path. The + # note grain answers the question without one: of the distinct + # notes surface X chose, how many did an agent open in this window? + # + # Guarded separately from the reads above, on #2663's actual + # lesson. That outage was a NOVEL SQL SHAPE the database rejected + # inside a broad except. This join is the novel shape here, and a + # failure in it must not take down two readouts that already work. + try: + pulled_ids = ( + select(NoteUsageEvent.note_id) + .where( + NoteUsageEvent.created_at >= since, + NoteUsageEvent.user_id == user_id, + NoteUsageEvent.event == PULLED, + # autoescape because `_` is a LIKE wildcard: a bare + # like("mcp_%") also matches "mcpX…". The Python half + # of this readout uses str.startswith and has no such + # hazard; this is the SQL half's version of it. + NoteUsageEvent.source.startswith("mcp_", autoescape=True), + ) + .distinct() + .subquery() + ) + surfaced_pairs = ( + select(NoteUsageEvent.source, NoteUsageEvent.note_id) + .where( + NoteUsageEvent.created_at >= since, + NoteUsageEvent.user_id == user_id, + NoteUsageEvent.event == SURFACED, + ) + .distinct() + .subquery() + ) + # DISTINCT on (source, note_id) FIRST, which is what lets the + # outer aggregate be a plain count(): the pairs are already + # unique, so the left join cannot multiply them and no + # count(DISTINCT) is needed to undo damage that never happens. + by_source_rows = ( + await session.execute( + select( + surfaced_pairs.c.source, + func.count().label("notes_surfaced"), + func.count(pulled_ids.c.note_id).label("notes_pulled"), + ) + .select_from( + surfaced_pairs.outerjoin( + pulled_ids, + pulled_ids.c.note_id == surfaced_pairs.c.note_id, + ) + ) + .group_by(surfaced_pairs.c.source) + ) + ).all() + except Exception: + logger.warning("per-source pull-through read failed", exc_info=True) + by_source_rows = None except Exception: logger.warning("retrieval summary read failed", exc_info=True) out["read_failed"] = True @@ -350,5 +431,41 @@ async def retrieval_summary(user_id: int | None, *, days: int = 30) -> dict: round(usage["pulled_by_agent"] / usage["surfaced"], 4) if usage["surfaced"] else None ) + + # The same question, per surface — which is the one the top-level ratio + # cannot answer. A corpus average of 0.05 is compatible with one surface + # earning its noise and another producing none, and tuning a threshold + # needs to know which. + # + # UPPER BOUND, and say so where it will be read: a pull records the door, + # not the surface that led to it, so a note surfaced by two surfaces and + # opened once counts as pulled for both. Attribution would need the session + # identity #2085 declined to invent. The bound is still decisive in the + # direction that matters — a surface reading near zero here is not being + # flattered by the double-count. + if by_source_rows is None: + usage["by_source"] = {} + # Distinct from an empty window, for the same reason `read_failed` is. + usage["by_source_failed"] = True + else: + by_source: dict[str, dict] = {} + for source, n_surfaced, n_pulled in by_source_rows: + n_surfaced, n_pulled = int(n_surfaced or 0), int(n_pulled or 0) + ambient = source in AMBIENT_SOURCES + by_source[source] = { + "notes_surfaced": n_surfaced, + "notes_pulled": n_pulled, + # None rather than a number on an ambient surface: nothing + # CHOSE those records, so "surfaced often, opened never" is not + # a judgment about them. The counts stay visible; the ratio + # that would be misread does not. + "pull_through": ( + None if ambient or not n_surfaced + else round(n_pulled / n_surfaced, 4) + ), + "ambient": ambient, + } + usage["by_source"] = by_source + out["usage"] = usage return out diff --git a/tests/test_services_retrieval_telemetry.py b/tests/test_services_retrieval_telemetry.py index bd69dd7..df6ef87 100644 --- a/tests/test_services_retrieval_telemetry.py +++ b/tests/test_services_retrieval_telemetry.py @@ -195,6 +195,10 @@ async def test_retrieval_summary_is_empty_not_broken_for_a_fresh_install(_dispos assert out["sources"] == {} assert out["usage"]["pull_through"] is None # no division by zero assert out["usage"]["surfaced"] == 0 + # An empty dict, not a missing key and not a failure flag — the same + # "no rows" / "read broke" distinction the rest of this readout keeps. + assert out["usage"]["by_source"] == {} + assert "by_source_failed" not in out["usage"] @pytest.mark.integration @@ -222,3 +226,136 @@ async def test_retrieval_summary_sees_only_its_own_users_telemetry(_dispose_engi async with async_session() as s: await s.execute(delete(RetrievalLog).where(RetrievalLog.user_id == 990004)) await s.commit() + + +# ─── per-source pull-through (#3311) ───────────────────────────────────────── +# Integration for the same reason the block above is: this is a self-join with +# two DISTINCT subqueries and a LIKE escape, which is a new SQL shape in a +# module whose one production outage (#2663) was a new SQL shape the database +# rejected inside a broad except. A mock would pass on a query Postgres refuses. + + +@pytest.mark.integration +@pytest.mark.asyncio +async def test_by_source_separates_a_surface_that_earns_its_noise_from_one_that_does_not( + _dispose_engine, +): + """The whole point: the corpus average cannot say WHICH surface is working. + + Two ranked surfaces, identical volume, opposite outcomes — and a top-level + ratio that describes neither of them. + """ + from sqlalchemy import delete + + from scribe.models import async_session + from scribe.models.note_usage import NoteUsageEvent + from scribe.services.retrieval_telemetry import retrieval_summary + + UID = 990010 + async with async_session() as s: + s.add_all([ + # auto_inject chose note 1 three times and note 2 once. Three + # surfacings of one note is ONE note surfaced — the DISTINCT that + # keeps the join from multiplying rows is what this pins. + NoteUsageEvent(user_id=UID, note_id=1, event="surfaced", source="auto_inject"), + NoteUsageEvent(user_id=UID, note_id=1, event="surfaced", source="auto_inject"), + NoteUsageEvent(user_id=UID, note_id=1, event="surfaced", source="auto_inject"), + NoteUsageEvent(user_id=UID, note_id=2, event="surfaced", source="auto_inject"), + # write_path_semantic chose two notes and got nothing opened. + NoteUsageEvent(user_id=UID, note_id=3, event="surfaced", source="write_path_semantic"), + NoteUsageEvent(user_id=UID, note_id=4, event="surfaced", source="write_path_semantic"), + # One agent pull, of a note only auto_inject surfaced. + 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 + by_source = out["usage"]["by_source"] + assert "by_source_failed" not in out["usage"], "the join did not execute" + + ai = by_source["auto_inject"] + assert ai["notes_surfaced"] == 2, "three surfacings of note 1 are one note" + assert ai["notes_pulled"] == 1 + assert ai["pull_through"] == pytest.approx(0.5) + + wp = by_source["write_path_semantic"] + assert wp["notes_surfaced"] == 2 + assert wp["notes_pulled"] == 0 + # 0.0, NOT None. "This surface produced nothing" is a finding; None is + # what a surface with no data reads as, and they must not look alike. + assert wp["pull_through"] == 0.0 + + # And the number that exists today, which is true of neither surface: + # one agent pull over six ranked surfacings. + assert out["usage"]["pull_through"] == pytest.approx(1 / 6, abs=1e-4) + finally: + async with async_session() as s: + await s.execute(delete(NoteUsageEvent).where(NoteUsageEvent.user_id == UID)) + await s.commit() + + +@pytest.mark.integration +@pytest.mark.asyncio +async def test_an_ambient_surface_reports_its_counts_but_no_ratio(_dispose_engine): + """`enter_project` bulk-loads records; nothing CHOSE them. "Surfaced often, + opened never" is not a judgment about a record that was never picked, so the + counts stay visible and the ratio that would be misread is null.""" + from sqlalchemy import delete + + from scribe.models import async_session + from scribe.models.note_usage import NoteUsageEvent + from scribe.services.retrieval_telemetry import retrieval_summary + + UID = 990011 + async with async_session() as s: + s.add_all([ + NoteUsageEvent(user_id=UID, note_id=1, event="surfaced", source="enter_project"), + NoteUsageEvent(user_id=UID, note_id=2, event="surfaced", source="enter_project"), + ]) + await s.commit() + + try: + row = (await retrieval_summary(UID, days=30))["usage"]["by_source"]["enter_project"] + assert row["ambient"] is True + assert row["notes_surfaced"] == 2 + assert row["pull_through"] is None + finally: + async with async_session() as s: + await s.execute(delete(NoteUsageEvent).where(NoteUsageEvent.user_id == UID)) + await s.commit() + + +@pytest.mark.integration +@pytest.mark.asyncio +async def test_the_agent_pull_filter_does_not_treat_its_underscore_as_a_wildcard( + _dispose_engine, +): + """`_` is a LIKE wildcard, so an unescaped `LIKE 'mcp_%'` also matches + `mcpXsomething`. The Python half of this readout uses str.startswith and + cannot have the bug; the SQL half needs autoescape to match it, and nothing + else in the payload would reveal the difference.""" + from sqlalchemy import delete + + from scribe.models import async_session + from scribe.models.note_usage import NoteUsageEvent + from scribe.services.retrieval_telemetry import retrieval_summary + + UID = 990012 + async with async_session() as s: + s.add_all([ + NoteUsageEvent(user_id=UID, note_id=1, event="surfaced", source="auto_inject"), + # Not an agent pull: the door is `mcpXget_note`, not `mcp_get_note`. + NoteUsageEvent(user_id=UID, note_id=1, event="pulled", source="mcpXget_note"), + ]) + await s.commit() + + try: + row = (await retrieval_summary(UID, days=30))["usage"]["by_source"]["auto_inject"] + assert row["notes_pulled"] == 0, "a wildcard match counted a non-agent pull" + assert row["pull_through"] == 0.0 + finally: + async with async_session() as s: + await s.execute(delete(NoteUsageEvent).where(NoteUsageEvent.user_id == UID)) + await s.commit()