From d5ac8408f61a0e5225858532d806891d6d1753dc Mon Sep 17 00:00:00 2001 From: Bryan Van Deusen Date: Wed, 9 Sep 2026 21:24:32 -0400 Subject: [PATCH] feat(telemetry): record WHAT the bar turned away, not only how close it came (#3807) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit #3670 added `best_available_score` so a threshold could be judged from its rejections. It records how CLOSE the bar came to firing and not WHAT it refused, and that is the half a decision actually needs. Live, pre_tool_rule sits at a ~0.72 bar with a near-miss p90 of 0.7071 — about 117 declines a day within 0.013 of firing. Dropping to 0.707 would take that arm from 22 hits a day to roughly 139: six-fold, on a surface that runs before every Bash call. The percentile says the mass is there. Nothing said whether it was worth showing. NEITHER OBVIOUS INSTRUMENT ANSWERS IT. Pull-through cannot: the injected rule line already carries title and trigger, so a session can comply without ever calling get_rule, and rule pull-through understates usefulness by construction. Reading the rejected records can — and `result_ids` holds only what was RETURNED, so on a zero-result call the near-missed record had no name at all. So the id, from the SAME ranked candidate as the score. Both searches unpack `best` once and read both fields off it, because splitting that into two expressions is exactly how a later edit pairs a score with its neighbour's id — and a score attached to the wrong record is worse than no id, since it invites judging the wrong one and concluding the bar is fine. write_path withholds the id on the same condition it withholds the score (#3739): a surviving id beside a null score names a record without saying what it scored, the pair disagreeing in the other direction. THE READ PATH IS A LISTING, NOT A STATISTIC — an id cannot be percentiled, and a reader tuning a bar needs to go and read the records. Opt-in via `near_miss_samples` (0-20, default 0) so the ordinary readout keeps its size, and deliberately NOT a window function: this module's one production outage was a grouped query Postgres rejected, swallowed by the broad except, every counter reading zero while the mocked tests passed (#2663). One flat ordered query, overfetched, bucketed in Python — the shape that lesson prescribes. Migration 0097, nullable and unbackfilled. Not a foreign key: the table spans record types and `source` says which, exactly as result_ids works. The integration guard pins the listing as PER SOURCE. A global LIMIT would let a noisy source eat the whole quota and leave the surface being tuned showing nothing — which reads as "nothing was close", the misreading this milestone has spent itself correcting. Co-Authored-By: Claude Opus 5 Claude-Session: https://claude.ai/code/session_011cPyzNnegXHr5iRMzzy5KJ --- .../0097_retrieval_log_best_available_id.py | 60 ++++++++++ src/scribe/mcp/tools/search.py | 32 ++++- src/scribe/models/retrieval_log.py | 9 ++ src/scribe/routes/search.py | 1 + src/scribe/services/embeddings.py | 12 +- src/scribe/services/plugin_context.py | 10 ++ src/scribe/services/retrieval_telemetry.py | 59 +++++++++- tests/test_services_retrieval_telemetry.py | 109 ++++++++++++++++++ 8 files changed, 287 insertions(+), 5 deletions(-) create mode 100644 alembic/versions/0097_retrieval_log_best_available_id.py diff --git a/alembic/versions/0097_retrieval_log_best_available_id.py b/alembic/versions/0097_retrieval_log_best_available_id.py new file mode 100644 index 0000000..6edc8c6 --- /dev/null +++ b/alembic/versions/0097_retrieval_log_best_available_id.py @@ -0,0 +1,60 @@ +"""add retrieval_logs.best_available_id — WHICH record the bar refused (#3807) + +Revision ID: 0097 +Revises: 0096 +Create Date: 2026-09-09 + +0096 added `best_available_score` so a threshold could be judged from what it +rejected. It records how CLOSE the bar came to firing and not WHAT it turned +away, and that turns out to be the half a decision actually needs. + +Live, `pre_tool_rule` shows a bar of ~0.72 with a near-miss p90 of 0.7071 — +about 117 declines a day sitting within 0.013 of firing. Dropping the bar to +0.707 would take that arm from 22 hits a day to roughly 139, a six-fold change +on a surface that runs before every Bash call. The percentile says the mass is +there. Nothing says whether it is worth showing. + +AND THE TWO OBVIOUS INSTRUMENTS DO NOT ANSWER IT. Pull-through cannot: the +injected rule line already carries title and trigger, so a session can comply +without ever calling `get_rule`, and rule pull-through therefore understates +usefulness by construction. Reading the rejected records can — and `result_ids` +holds only what was RETURNED, so on a zero-result call it is empty and the +near-missed record has no name. + +So: the id, beside the score, from the SAME ranked candidate. The two must +never be able to describe different records — a score paired with its +neighbour's id would be worse than no id at all, because it invites a reader to +judge the wrong record and conclude the bar is fine. + +NULLABLE AND UNBACKFILLED, for the reason 0095 and 0096 both spell out: a row +written before this genuinely does not know, and inventing a value would put an +artifact where a measurement belongs. Null here means "not measured", never +"nothing was close". + +NOT A FOREIGN KEY, deliberately. `retrieval_logs` spans record types — the +rules arms store rule ids, the note arms store note ids — and `source` is what +says which table an id belongs to, exactly as `result_ids` has always worked. +A constraint would have to point at one table and would be wrong for the other. + +Downgrade drops the column. Purely observational — nothing reads it for +correctness. +""" +from alembic import op +import sqlalchemy as sa + + +revision = "0097" +down_revision = "0096" +branch_labels = None +depends_on = None + + +def upgrade() -> None: + op.add_column( + "retrieval_logs", + sa.Column("best_available_id", sa.Integer(), nullable=True), + ) + + +def downgrade() -> None: + op.drop_column("retrieval_logs", "best_available_id") diff --git a/src/scribe/mcp/tools/search.py b/src/scribe/mcp/tools/search.py index e104d4a..612f4ca 100644 --- a/src/scribe/mcp/tools/search.py +++ b/src/scribe/mcp/tools/search.py @@ -128,6 +128,7 @@ async def search( project_id=project_id or None, is_task=is_task, results=raw, duration_ms=(time.perf_counter() - t0) * 1000.0, best_available=report.get("best_available_score"), + best_available_id=report.get("best_available_id"), searched=bool(report.get("searched", True)), ) owners = await owner_names_for( @@ -153,7 +154,9 @@ async def search( } -async def retrieval_telemetry(days: int = 30) -> dict: +async def retrieval_telemetry( + days: int = 30, near_miss_samples: int = 0, +) -> 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 @@ -181,6 +184,24 @@ async def retrieval_telemetry(days: int = 30) -> dict: render as a zero-result call, and nothing else in this readout tells them apart. + `near_miss_samples` (0-20, default 0) TURNS THE PERCENTILES INTO RECORDS + YOU CAN READ. Each source then carries `near_miss_records`: its highest + scoring declines, each with the `record_id` the bar refused and the `query` + that asked. Reach for it whenever you are about to move a threshold. + + THE PERCENTILE CANNOT SETTLE A BAR ON ITS OWN, and this is the whole reason + the parameter exists. `near_misses.p90` says mass is sitting just under the + line; it says nothing about whether that mass is RELEVANT, and those are + different questions. Lowering a bar to where the mass is, without reading + what is there, is choosing a firing rate rather than a quality. Pull-through + cannot referee it either — the injected rule line already carries title and + trigger, so a session can comply without ever calling `get_rule`, which + makes rule pull-through understate usefulness by construction. Reading the + rejected records is the method that actually answers it. + + Off by default because it is a LISTING, not a statistic: it is for the + moment you are making a decision, not for every readout. + `near_misses` is `null` when no declining call in the window measured it — rows written before #3670 shipped cannot know. That is "not measured", not "nothing came close"; a 0.0 there would be a claim about the corpus @@ -320,8 +341,15 @@ It is an UPPER BOUND per surface: a pull records the door it came Args: days: window size, default 30. Clamped to at least 1. + near_miss_samples: 0-20, default 0. How many of each source's highest + scoring DECLINES to list by record, with the query that asked. + Pass it when you are about to move a threshold; leave it off + otherwise. See the near-miss section above for why a percentile + alone cannot settle a bar. """ - return await retrieval_summary(current_user_id(), days=days) + return await retrieval_summary( + current_user_id(), days=days, near_miss_samples=near_miss_samples, + ) def register(mcp) -> None: diff --git a/src/scribe/models/retrieval_log.py b/src/scribe/models/retrieval_log.py index 9b12bc1..2eb08f9 100644 --- a/src/scribe/models/retrieval_log.py +++ b/src/scribe/models/retrieval_log.py @@ -62,6 +62,15 @@ class RetrievalLog(Base): # close": a 0.0 there would read as a corpus with no relevant records at # all, which is an artifact standing in for a measurement. best_available_score: Mapped[float | None] = mapped_column(Float, nullable=True) + # WHICH record scored that, so a reader can judge what the bar refused + # rather than only how close it came (#3807). Written from the same ranked + # candidate as the score above — the two describing different records would + # be worse than no id at all, because it invites judging the wrong one. + # + # Not a foreign key on purpose: this table spans record types (the rule arms + # store rule ids, the note arms store note ids) and `source` is what says + # which, exactly as `result_ids` has always worked. + best_available_id: Mapped[int | None] = mapped_column(Integer, nullable=True) # [{"id": int, "score": float, "rank": int}, ...], highest-first. result_ids: Mapped[list] = mapped_column(JSONB, nullable=False, default=list) duration_ms: Mapped[float | None] = mapped_column(Float, nullable=True) diff --git a/src/scribe/routes/search.py b/src/scribe/routes/search.py index 28e66ed..b4303f5 100644 --- a/src/scribe/routes/search.py +++ b/src/scribe/routes/search.py @@ -58,6 +58,7 @@ async def search_route(): project_id=project_id, is_task=is_task, results=results, duration_ms=(time.perf_counter() - t0) * 1000.0, best_available=report.get("best_available_score"), + best_available_id=report.get("best_available_id"), searched=bool(report.get("searched", True)), ) owners = await owner_names_for( diff --git a/src/scribe/services/embeddings.py b/src/scribe/services/embeddings.py index a45395a..aa9e55f 100644 --- a/src/scribe/services/embeddings.py +++ b/src/scribe/services/embeddings.py @@ -658,7 +658,12 @@ async def semantic_search_notes( # looked" and from "the query failed". Set here, at the one point past # which a real result set exists. report["searched"] = True - report["best_available_score"] = scored[0][0] if scored else None + # ONE unpack, so the score and the id cannot describe different records + # (#3807). Splitting these into two expressions is how a later edit + # pairs a score with its neighbour's id. + best = scored[0] if scored else None + report["best_available_score"] = best[0] if best else None + report["best_available_id"] = int(best[1].id) if best else None scored = [pair for pair in scored if pair[0] >= threshold] if not demote_superseded: return scored[:limit] @@ -909,7 +914,10 @@ async def semantic_search_rules( if report is not None: # See the sibling search: absent means the search never ran (#3765). report["searched"] = True - report["best_available_score"] = ranked[0][0] if ranked else None + # One unpack — see the sibling search (#3807). + best = ranked[0] if ranked else None + report["best_available_score"] = best[0] if best else None + report["best_available_id"] = int(best[1].id) if best else None return [pair for pair in ranked if pair[0] >= threshold][:limit] diff --git a/src/scribe/services/plugin_context.py b/src/scribe/services/plugin_context.py index df6e1eb..3a21d4c 100644 --- a/src/scribe/services/plugin_context.py +++ b/src/scribe/services/plugin_context.py @@ -484,6 +484,7 @@ async def _reserve_slot_for_reuse( threshold=cfg["threshold"], limit=1, project_id=project_id, is_task=None, results=reuse, best_available=_rep.get("best_available_score"), + best_available_id=_rep.get("best_available_id"), searched=bool(_rep.get("searched", True)), duration_ms=(time.perf_counter() - _t0) * 1000.0, ) @@ -553,6 +554,7 @@ async def build_autoinject_hint( threshold=cfg["threshold"], limit=cfg["top_k"], project_id=(project_id or None), is_task=None, results=hits, best_available=_rep_ai.get("best_available_score"), + best_available_id=_rep_ai.get("best_available_id"), searched=bool(_rep_ai.get("searched", True)), duration_ms=(time.perf_counter() - t0) * 1000.0, ) @@ -1048,6 +1050,12 @@ async def build_write_path_hint( best_available=( None if withheld_here else _rep_wp.get("best_available_score") ), + # Withheld on the SAME condition as the score. A surviving id + # beside a null score would name a record without saying what it + # scored, which is the pair disagreeing in the other direction. + best_available_id=( + None if withheld_here else _rep_wp.get("best_available_id") + ), searched=bool(_rep_wp.get("searched", True)), duration_ms=(time.perf_counter() - t0) * 1000.0, ) @@ -1345,6 +1353,7 @@ async def build_write_path_hint( project_id=project_id, is_task=None, results=fresh, duration_ms=rule_ms, best_available=_rep_wpr.get("best_available_score"), + best_available_id=_rep_wpr.get("best_available_id"), searched=bool(_rep_wpr.get("searched", True)), # What the ranker found and this session had already been told. # Without it a zero row cannot say whether the bar was too high or @@ -1453,6 +1462,7 @@ async def build_tool_rule_hint( project_id=project_id, is_task=None, results=fresh, duration_ms=duration_ms, best_available=_rep_ptr.get("best_available_score"), + best_available_id=_rep_ptr.get("best_available_id"), searched=bool(_rep_ptr.get("searched", True)), # See the sibling arm. It matters more here: this arm fires on every # Bash call, so a long session excludes its way to an all-zero row diff --git a/src/scribe/services/retrieval_telemetry.py b/src/scribe/services/retrieval_telemetry.py index 81d2197..f44fa44 100644 --- a/src/scribe/services/retrieval_telemetry.py +++ b/src/scribe/services/retrieval_telemetry.py @@ -57,6 +57,7 @@ def _build_payload( duration_ms: float | None, suppressed: int | None = None, best_available: float | None = None, + best_available_id: int | None = None, ) -> dict: """Reduce a retrieval call to a flat, JSON-safe RetrievalLog payload. @@ -96,6 +97,10 @@ def _build_payload( "best_available_score": ( None if best_available is None else round(float(best_available), 5) ), + # The record that scored it, so a reader can go and look (#3807). + "best_available_id": ( + None if best_available_id is None else int(best_available_id) + ), "result_ids": items, "duration_ms": (round(duration_ms, 2) if duration_ms is not None else None), } @@ -135,6 +140,7 @@ def record_retrieval( duration_ms: float | None = None, suppressed: int | None = None, best_available: float | None = None, + best_available_id: int | None = None, searched: bool = True, ) -> None: """Fire-and-forget: record one retrieval call. @@ -189,6 +195,7 @@ def record_retrieval( duration_ms=duration_ms, suppressed=suppressed, best_available=best_available, + best_available_id=best_available_id, ) except Exception: logger.debug("retrieval telemetry payload build failed", exc_info=True) @@ -347,7 +354,9 @@ def _coverage(complete_from, since) -> dict: } -async def retrieval_summary(user_id: int | None, *, days: int = 30) -> dict: +async def retrieval_summary( + user_id: int | None, *, days: int = 30, near_miss_samples: int = 0, +) -> dict: """What the retrieval telemetry says, per surface, over a window. Three aggregates side by side, each read from the table built for it — NOT @@ -512,6 +521,54 @@ async def retrieval_summary(user_id: int | None, *, days: int = 30) -> dict: quiet.update(_coverage(first_row, since)) out["sources"][src] = quiet + # WHAT THE BAR REFUSED, by name (#3807). Opt-in, because it is a + # LISTING and not a statistic: an id cannot be percentiled, and a + # reader tuning a threshold needs to go and read the records rather + # than see another number about them. Off by default so the + # ordinary readout keeps its size. + # + # Deliberately NOT a window function. This module's one production + # outage (#2663) was a grouped query the database rejected, swallowed + # by the broad except, every counter reading zero while the mocked + # tests passed — and the lesson recorded then was to group on a raw + # column and classify in Python rather than push cleverness into the + # SQL. So: one flat ordered query, overfetched, bucketed here. + if near_miss_samples > 0: + want = max(1, min(int(near_miss_samples), 20)) + rows = ( + await session.execute( + select( + RetrievalLog.source, + RetrievalLog.best_available_score, + RetrievalLog.best_available_id, + RetrievalLog.query, + ) + .where( + declined, + RetrievalLog.created_at >= since, + RetrievalLog.user_id == user_id, + RetrievalLog.best_available_id.isnot(None), + ) + .order_by(RetrievalLog.best_available_score.desc()) + # Overfetch so every source can fill its own quota even + # when one of them holds all the highest scores. + .limit(want * 40) + ) + ).all() + for src, score, rec_id, q in rows: + bucket = out["sources"].get(src) + if bucket is None: + continue + samples = bucket.setdefault("near_miss_records", []) + if len(samples) >= want: + continue + samples.append({ + "score": _round(score), + "record_id": int(rec_id), + # Enough to recognise the ask, not the whole prompt. + "query": (q or "")[:120], + }) + # 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. diff --git a/tests/test_services_retrieval_telemetry.py b/tests/test_services_retrieval_telemetry.py index 2bb823c..8b99422 100644 --- a/tests/test_services_retrieval_telemetry.py +++ b/tests/test_services_retrieval_telemetry.py @@ -1120,3 +1120,112 @@ def test_a_caller_that_never_asked_is_assumed_to_have_searched(): limit=10, project_id=None, is_task=None, results=[], ) assert build.called + + +# ─── the bar's refusals have names now (#3807) ─────────────────────────────── +# +# #3670 recorded how CLOSE the bar came to firing. That is the half a decision +# does not need: live, pre_tool_rule sits at a ~0.72 bar with a near-miss p90 of +# 0.7071, so dropping to 0.707 would take it from 22 hits a day to roughly 139. +# The percentile says the mass is there and says nothing about whether it is +# worth showing, and pull-through cannot referee it because the injected rule +# line already carries title and trigger — a session can comply without ever +# calling get_rule. +# +# Reading the rejected records is the method that answers it, and until now +# `result_ids` held only what was RETURNED, so on a zero-result call the +# near-missed record had no name. + + +def test_the_rejected_record_is_named_beside_the_score_it_scored(): + """Both halves, from one payload, because either alone is unusable. + + A score with no id says a bar nearly fired and not what it nearly fired + ABOUT. An id with no score names a record without saying how close it came. + """ + p = _build_payload( + user_id=1, source="pre_tool_rule", query="git push --force", + threshold=0.72, limit=1, project_id=None, is_task=None, + results=[], duration_ms=None, best_available=0.7104, + best_available_id=168, + ) + assert p["result_count"] == 0 + assert p["best_available_score"] == 0.7104 + assert p["best_available_id"] == 168 + + +def test_an_unmeasured_near_miss_names_nothing(): + """Null, on both halves, and for the reason its sibling is null: a row that + did not measure must not invent a record any more than it invents a score.""" + p = _build_payload( + user_id=1, source="auto_inject", query="q", threshold=0.6, + limit=3, project_id=None, is_task=None, results=[], duration_ms=None, + ) + assert p["best_available_score"] is None + assert p["best_available_id"] is None + + +@pytest.mark.integration +@pytest.mark.asyncio +async def test_the_listing_names_the_highest_declines_per_source(_dispose_engine): + """Integration, because the listing is a second query against real Postgres + and this module's one outage was a query the database rejected in silence. + + Also pins that the listing is PER SOURCE. One flat `ORDER BY score DESC` + with a global limit would let a noisy source consume the whole quota and + leave the surface you are actually tuning unrepresented — which reads as + "nothing was close" for that source, the exact misreading this milestone + has spent itself correcting. + """ + 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, + ) + + UID = 990080 + # A source whose declines score HIGH, and one whose declines score low. + for score, rid in ((0.71, 501), (0.70, 502), (0.69, 503)): + await _insert_retrieval_log(_build_payload( + user_id=UID, source="pre_tool_rule", query=f"cmd {rid}", + threshold=0.72, limit=1, project_id=None, is_task=None, + results=[], duration_ms=1.0, + best_available=score, best_available_id=rid, + )) + await _insert_retrieval_log(_build_payload( + user_id=UID, source="auto_inject", query="a quieter ask", + threshold=0.6, limit=3, project_id=None, is_task=None, + results=[], duration_ms=1.0, + best_available=0.31, best_available_id=901, + )) + + try: + out = await retrieval_summary(UID, days=30, near_miss_samples=2) + assert out["read_failed"] is False, ( + "the listing query did not execute — a rejected query here reads " + "as an absent listing, which is #2663 again" + ) + + top = out["sources"]["pre_tool_rule"]["near_miss_records"] + assert [r["record_id"] for r in top] == [501, 502], ( + "the listing must be the HIGHEST declines, in order, capped at the " + "requested count" + ) + assert top[0]["score"] == pytest.approx(0.71, abs=1e-4) + assert top[0]["query"] == "cmd 501", "the ask is what makes a hit judgeable" + + # The low-scoring source keeps its own slot rather than being crowded + # out by the high scorer — this is what a global LIMIT would break. + quiet = out["sources"]["auto_inject"]["near_miss_records"] + assert [r["record_id"] for r in quiet] == [901] + + off = await retrieval_summary(UID, days=30) + assert "near_miss_records" not in off["sources"]["pre_tool_rule"], ( + "the listing is opt-in; the ordinary readout must not grow" + ) + finally: + async with async_session() as s: + await s.execute(delete(RetrievalLog).where(RetrievalLog.user_id == UID)) + await s.commit() -- 2.54.0