Record WHAT the bar turned away, not only how close it came (#3807) #148

Merged
bvandeusen merged 1 commits from dev into main 2026-09-09 21:34:57 -04:00
8 changed files with 287 additions and 5 deletions
@@ -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")
+30 -2
View File
@@ -128,6 +128,7 @@ async def search(
project_id=project_id or None, is_task=is_task, results=raw, project_id=project_id or None, is_task=is_task, results=raw,
duration_ms=(time.perf_counter() - t0) * 1000.0, duration_ms=(time.perf_counter() - t0) * 1000.0,
best_available=report.get("best_available_score"), best_available=report.get("best_available_score"),
best_available_id=report.get("best_available_id"),
searched=bool(report.get("searched", True)), searched=bool(report.get("searched", True)),
) )
owners = await owner_names_for( 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. """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 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 render as a zero-result call, and nothing else in this readout tells them
apart. 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 — `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 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 "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: Args:
days: window size, default 30. Clamped to at least 1. 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: def register(mcp) -> None:
+9
View File
@@ -62,6 +62,15 @@ class RetrievalLog(Base):
# close": a 0.0 there would read as a corpus with no relevant records at # 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. # all, which is an artifact standing in for a measurement.
best_available_score: Mapped[float | None] = mapped_column(Float, nullable=True) 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. # [{"id": int, "score": float, "rank": int}, ...], highest-first.
result_ids: Mapped[list] = mapped_column(JSONB, nullable=False, default=list) result_ids: Mapped[list] = mapped_column(JSONB, nullable=False, default=list)
duration_ms: Mapped[float | None] = mapped_column(Float, nullable=True) duration_ms: Mapped[float | None] = mapped_column(Float, nullable=True)
+1
View File
@@ -58,6 +58,7 @@ async def search_route():
project_id=project_id, is_task=is_task, results=results, project_id=project_id, is_task=is_task, results=results,
duration_ms=(time.perf_counter() - t0) * 1000.0, duration_ms=(time.perf_counter() - t0) * 1000.0,
best_available=report.get("best_available_score"), best_available=report.get("best_available_score"),
best_available_id=report.get("best_available_id"),
searched=bool(report.get("searched", True)), searched=bool(report.get("searched", True)),
) )
owners = await owner_names_for( owners = await owner_names_for(
+10 -2
View File
@@ -658,7 +658,12 @@ async def semantic_search_notes(
# looked" and from "the query failed". Set here, at the one point past # looked" and from "the query failed". Set here, at the one point past
# which a real result set exists. # which a real result set exists.
report["searched"] = True 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] scored = [pair for pair in scored if pair[0] >= threshold]
if not demote_superseded: if not demote_superseded:
return scored[:limit] return scored[:limit]
@@ -909,7 +914,10 @@ async def semantic_search_rules(
if report is not None: if report is not None:
# See the sibling search: absent means the search never ran (#3765). # See the sibling search: absent means the search never ran (#3765).
report["searched"] = True 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] return [pair for pair in ranked if pair[0] >= threshold][:limit]
+10
View File
@@ -484,6 +484,7 @@ async def _reserve_slot_for_reuse(
threshold=cfg["threshold"], limit=1, project_id=project_id, threshold=cfg["threshold"], limit=1, project_id=project_id,
is_task=None, results=reuse, is_task=None, results=reuse,
best_available=_rep.get("best_available_score"), best_available=_rep.get("best_available_score"),
best_available_id=_rep.get("best_available_id"),
searched=bool(_rep.get("searched", True)), searched=bool(_rep.get("searched", True)),
duration_ms=(time.perf_counter() - _t0) * 1000.0, duration_ms=(time.perf_counter() - _t0) * 1000.0,
) )
@@ -553,6 +554,7 @@ async def build_autoinject_hint(
threshold=cfg["threshold"], limit=cfg["top_k"], threshold=cfg["threshold"], limit=cfg["top_k"],
project_id=(project_id or None), is_task=None, results=hits, project_id=(project_id or None), is_task=None, results=hits,
best_available=_rep_ai.get("best_available_score"), best_available=_rep_ai.get("best_available_score"),
best_available_id=_rep_ai.get("best_available_id"),
searched=bool(_rep_ai.get("searched", True)), searched=bool(_rep_ai.get("searched", True)),
duration_ms=(time.perf_counter() - t0) * 1000.0, duration_ms=(time.perf_counter() - t0) * 1000.0,
) )
@@ -1048,6 +1050,12 @@ async def build_write_path_hint(
best_available=( best_available=(
None if withheld_here else _rep_wp.get("best_available_score") 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)), searched=bool(_rep_wp.get("searched", True)),
duration_ms=(time.perf_counter() - t0) * 1000.0, duration_ms=(time.perf_counter() - t0) * 1000.0,
) )
@@ -1345,6 +1353,7 @@ async def build_write_path_hint(
project_id=project_id, project_id=project_id,
is_task=None, results=fresh, duration_ms=rule_ms, is_task=None, results=fresh, duration_ms=rule_ms,
best_available=_rep_wpr.get("best_available_score"), best_available=_rep_wpr.get("best_available_score"),
best_available_id=_rep_wpr.get("best_available_id"),
searched=bool(_rep_wpr.get("searched", True)), searched=bool(_rep_wpr.get("searched", True)),
# What the ranker found and this session had already been told. # 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 # 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, project_id=project_id,
is_task=None, results=fresh, duration_ms=duration_ms, is_task=None, results=fresh, duration_ms=duration_ms,
best_available=_rep_ptr.get("best_available_score"), best_available=_rep_ptr.get("best_available_score"),
best_available_id=_rep_ptr.get("best_available_id"),
searched=bool(_rep_ptr.get("searched", True)), searched=bool(_rep_ptr.get("searched", True)),
# See the sibling arm. It matters more here: this arm fires on every # 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 # Bash call, so a long session excludes its way to an all-zero row
+58 -1
View File
@@ -57,6 +57,7 @@ def _build_payload(
duration_ms: float | None, duration_ms: float | None,
suppressed: int | None = None, suppressed: int | None = None,
best_available: float | None = None, best_available: float | None = None,
best_available_id: int | None = None,
) -> dict: ) -> dict:
"""Reduce a retrieval call to a flat, JSON-safe RetrievalLog payload. """Reduce a retrieval call to a flat, JSON-safe RetrievalLog payload.
@@ -96,6 +97,10 @@ def _build_payload(
"best_available_score": ( "best_available_score": (
None if best_available is None else round(float(best_available), 5) 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, "result_ids": items,
"duration_ms": (round(duration_ms, 2) if duration_ms is not None else None), "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, duration_ms: float | None = None,
suppressed: int | None = None, suppressed: int | None = None,
best_available: float | None = None, best_available: float | None = None,
best_available_id: int | None = None,
searched: bool = True, searched: bool = True,
) -> None: ) -> None:
"""Fire-and-forget: record one retrieval call. """Fire-and-forget: record one retrieval call.
@@ -189,6 +195,7 @@ def record_retrieval(
duration_ms=duration_ms, duration_ms=duration_ms,
suppressed=suppressed, suppressed=suppressed,
best_available=best_available, best_available=best_available,
best_available_id=best_available_id,
) )
except Exception: except Exception:
logger.debug("retrieval telemetry payload build failed", exc_info=True) 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. """What the retrieval telemetry says, per surface, over a window.
Three aggregates side by side, each read from the table built for it — NOT 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)) quiet.update(_coverage(first_row, since))
out["sources"][src] = quiet 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 # The corpus side, at its own grain. `ambient` mirrors
# note_usage.usage_for_notes: an ambient surfacing was not a scored # note_usage.usage_for_notes: an ambient surfacing was not a scored
# CHOICE, so folding it into pull-through would understate it. # CHOICE, so folding it into pull-through would understate it.
+109
View File
@@ -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=[], limit=10, project_id=None, is_task=None, results=[],
) )
assert build.called 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()