diff --git a/alembic/versions/0096_retrieval_log_best_available_score.py b/alembic/versions/0096_retrieval_log_best_available_score.py new file mode 100644 index 0000000..4772572 --- /dev/null +++ b/alembic/versions/0096_retrieval_log_best_available_score.py @@ -0,0 +1,62 @@ +"""add retrieval_logs.best_available_score — the score the bar rejected (#3670) + +Revision ID: 0096 +Revises: 0095 +Create Date: 2026-09-08 + +`cleared_threshold` was documented as the number to read FIRST — "a surface +that clears its bar on nearly every call is either well-tuned or too loose, +and p10 says which". It was never a measurement. The search applies the +threshold before returning, so every returned result cleared the bar by +construction and a call with no results has no `top_score` to compare: +the condition is true exactly when `result_count > 0`. + +`zero_result_calls + cleared_threshold == calls` held on all nineteen +source/window readings ever taken. It was `calls - zero_result_calls` +wearing a name that promised a second opinion, and a reading procedure was +built on top of it that asked the reader to compare a number against itself. + +THE MISSING NUMBER, and the reason this is a column rather than a deletion. +The question the table exists to answer is "is the bar in the right place", +and that question is only answerable from the calls that returned NOTHING: +how close did the best rejected candidate come? A bar at 0.72 turning away +a stream of 0.71s is set too high by a hair. A bar turning away 0.30s is +doing its job. Those two are indistinguishable today — both render as a +zero-result call — and no arrangement of the existing columns separates +them, because the losing score is discarded inside the search. + +So the searches now rank without the bar and apply it in Python, which +costs nothing (the rows were already ordered by distance, and the qualifying +set is provably identical — above-threshold rows sort first), and the best +score seen becomes observable. + +NULLABLE, AND UNBACKFILLED, for the reason 0095 spells out: a row written +before this shipped genuinely does not know what its best rejected candidate +scored, and saying so is the honest state. A 0.0 default would read as "the +corpus had nothing remotely relevant" — an artifact standing in for a +measurement, which is the whole defect this milestone corrects. + +`retrieval_logs` is not restored from backup, so no importer changes. + +Downgrade drops the column. Purely observational — nothing reads it for +correctness. +""" +from alembic import op +import sqlalchemy as sa + + +revision = "0096" +down_revision = "0095" +branch_labels = None +depends_on = None + + +def upgrade() -> None: + op.add_column( + "retrieval_logs", + sa.Column("best_available_score", sa.Float(), nullable=True), + ) + + +def downgrade() -> None: + op.drop_column("retrieval_logs", "best_available_score") diff --git a/src/scribe/mcp/tools/search.py b/src/scribe/mcp/tools/search.py index e31ab17..20cd999 100644 --- a/src/scribe/mcp/tools/search.py +++ b/src/scribe/mcp/tools/search.py @@ -112,6 +112,7 @@ async def search( return await _search_rules(uid, q, limit) is_task = {"note": False, "task": True}.get(content_type) # None => any t0 = time.perf_counter() + report: dict = {} raw = await semantic_search_notes( uid, q, limit=limit, is_task=is_task, project_id=project_id or None, @@ -119,12 +120,14 @@ async def search( # An explicit search reaches everything the operator may read, including # records shared with them one-to-one. scope="read", + report=report, ) record_retrieval( user_id=uid, source="mcp_search", query=q, threshold=DEFAULT_SIMILARITY_THRESHOLD, limit=limit, 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"), ) owners = await owner_names_for( {int(note.user_id) for _s, note in raw if note.user_id != uid} @@ -162,18 +165,39 @@ async def retrieval_telemetry(days: int = 30) -> dict: `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. + `near_misses`, the `top_score` spread (p10/p50/p90/min/max), + `avg_result_count` and `p90_duration_ms`. - READ `cleared_threshold` AND `zero_result_calls` TOGETHER, and check - `suppression` before concluding anything from either. A zero-result call is - two different events wearing one number: the ranker found nothing above the - bar, or it found only what this session had already been shown. Just the - first is evidence the bar is too high. `suppression` splits them where the - surface can tell — `zero_because_already_shown` comes off + THE NUMBER TO READ FIRST IS `near_misses.p90`, AGAINST THE THRESHOLD IN + FORCE FOR THAT SURFACE. It is measured only on the calls that returned + NOTHING, on the best score the ranker reached before the bar rejected it — + so it is the one figure here that says something the bar cannot make true + by construction. A bar at 0.72 turning away a stream of 0.71s is set too + high by a hair and the surface is losing hits it should have had. The same + bar turning away 0.30s is working, and the corpus simply had nothing. Both + render as a zero-result call, and nothing else in this readout tells them + apart. + + `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 + invented out of a caller's silence. + + THERE IS NO `cleared_threshold` ANY MORE, and if you remember one, that + memory is of a tautology (#3670). The search applies the bar before + returning, so every returned result cleared it by construction and a call + with no results has no score to compare: the field was true exactly when + `result_count > 0`, i.e. it was `calls - zero_result_calls` under a name + that promised a second opinion. `zero_result_calls + cleared_threshold == + calls` held on all nineteen readings ever taken. The reading procedure + built on it — "clears its bar on nearly every call" — asked you to compare + a number with itself. + + CHECK `suppression` BEFORE CONCLUDING ANYTHING FROM `zero_result_calls`. A + zero-result call is two different events wearing one number: the ranker + found nothing above the bar, or it found only what this session had already + been shown. Just the first is evidence about the bar. `suppression` splits + them where the surface can tell — `zero_because_already_shown` comes off `zero_result_calls` to leave the true ranker declines. `suppression` is `null` when NO row in the window reported it, and that is diff --git a/src/scribe/models/retrieval_log.py b/src/scribe/models/retrieval_log.py index fc85a84..9b12bc1 100644 --- a/src/scribe/models/retrieval_log.py +++ b/src/scribe/models/retrieval_log.py @@ -54,6 +54,14 @@ class RetrievalLog(Base): suppressed_count: Mapped[int | None] = mapped_column(Integer, nullable=True) top_score: Mapped[float | None] = mapped_column(Float, nullable=True) min_score: Mapped[float | None] = mapped_column(Float, nullable=True) + # The best score the ranker COULD have offered, before the threshold — as + # against `top_score`, which is the best it DID offer. They are equal on + # any call that returned something, and only this one exists on a call + # that returned nothing, which is the only place a bar can be judged from + # (#3670). Null means the caller did not measure it, never "nothing was + # 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) # [{"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 2cc891c..efba71b 100644 --- a/src/scribe/routes/search.py +++ b/src/scribe/routes/search.py @@ -44,17 +44,20 @@ async def search_route(): project_id = request.args.get("project_id", type=int) t0 = time.perf_counter() + report: dict = {} results = await semantic_search_notes( uid, q, limit=limit, is_task=is_task, threshold=_REST_SEARCH_THRESHOLD, project_id=project_id, system_id=system_id, # The user typed this, so it reaches everything they may read. scope="read", + report=report, ) record_retrieval( user_id=uid, source="rest_search", query=q, threshold=_REST_SEARCH_THRESHOLD, limit=limit, 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"), ) owners = await owner_names_for( {int(note.user_id) for _s, note in results if note.user_id != uid} diff --git a/src/scribe/services/embeddings.py b/src/scribe/services/embeddings.py index e5923c4..cba7fdd 100644 --- a/src/scribe/services/embeddings.py +++ b/src/scribe/services/embeddings.py @@ -448,6 +448,23 @@ async def upsert_note_embedding( logger.warning("Failed to persist embedding for note %d", note_id, exc_info=True) +# Both searches rank WITHOUT the threshold and apply it in Python, so the best +# rejected score stays observable (#3670). The qualifying set is provably +# unchanged: rows arrive ordered by distance ascending, so every above-bar row +# sorts ahead of every below-bar one, and an over-fetch that used to return N +# above-bar rows returns the same N plus some losers. What changes is only that +# the losers are now visible instead of discarded inside the query. +# +# That visibility is the entire point. A bar can only be judged from the calls +# it TURNED AWAY — a 0.72 bar rejecting a stream of 0.71s is set too high by a +# hair, one rejecting 0.30s is working — and those two are indistinguishable +# from any arrangement of the columns that survive the filter. +# +# `report` is how the score gets out without changing what a search RETURNS. +# Eight of the eleven call sites want hits and nothing else; the three that +# write telemetry pass a dict and read `best_available_score` back out of it. + + async def semantic_search_notes( user_id: int, query: str, @@ -462,12 +479,19 @@ async def semantic_search_notes( scope: str = "own", demote_superseded: bool = True, system_id: int | None = None, + report: dict | None = None, ) -> list[tuple[float, Note]]: """Return up to *limit* (score, note) pairs most relevant to *query*. Scores are cosine similarities in [-1, 1]; only notes at or above *threshold* are returned, sorted highest-first. + Pass `report` (an empty dict) to learn what the threshold turned away: + the function sets `report["best_available_score"]` to the highest score + anything reached, or None when the corpus offered nothing at all. It is + the only figure that survives a call returning nothing, and therefore the + only one a bar can be judged from (#3670). + `note_type` narrows to a record kind, or several (e.g. "snippet", or ("snippet", "note")), for callers that want prior art rather than everything embedded. @@ -513,7 +537,6 @@ async def semantic_search_notes( # Distance ceiling equivalent to the similarity floor. Clamp to the valid # cosine-distance range [0, 2] so a threshold of, say, -1 doesn't produce a # nonsensical ceiling. - max_distance = min(2.0, max(0.0, 1.0 - threshold)) distance = NoteEmbedding.embedding.cosine_distance(query_vec) try: @@ -588,11 +611,10 @@ async def semantic_search_notes( fetch = limit * _CHUNK_OVERFETCH * ( _SUPERSESSION_OVERFETCH if demote_superseded else 1 ) - stmt = ( - stmt.where(distance <= max_distance) - .order_by(distance.asc()) - .limit(fetch) - ) + # NO threshold predicate — see the note above this function. The + # bar is applied after the collapse, where the rejected scores can + # still be seen. + stmt = stmt.order_by(distance.asc()).limit(fetch) rows = list((await session.execute(stmt)).all()) except Exception: logger.warning("Failed to query note embeddings", exc_info=True) @@ -611,6 +633,11 @@ async def semantic_search_notes( continue seen.add(int(note.id)) scored.append((1.0 - float(dist), note)) + # The best score anything reached, bar or no bar. Recorded BEFORE the + # filter because a call that returns nothing is exactly when it matters. + if report is not None: + report["best_available_score"] = scored[0][0] if scored else None + scored = [pair for pair in scored if pair[0] >= threshold] if not demote_superseded: return scored[:limit] return await _apply_supersession_penalty(scored, limit) @@ -764,9 +791,16 @@ async def semantic_search_rules( limit: int = 5, threshold: float = _SIMILARITY_THRESHOLD, tier: str | None = None, + report: dict | None = None, ) -> list[tuple[float, "Rule"]]: """Return up to *limit* (score, rule) pairs most relevant to *query*. + Pass `report` (an empty dict) to learn what the threshold turned away: + the function sets `report["best_available_score"]` to the highest score + anything reached, or None when the corpus offered nothing at all. It is + the only figure that survives a call returning nothing, and therefore the + only one a bar can be judged from (#3670). + Scoped by OWNERSHIP — a rule is the caller's if they own its rulebook or its project. Deliberately not filtered to what currently BINDS a given project: this answers "is there a rule about this", which a person asking @@ -802,7 +836,6 @@ async def semantic_search_rules( logger.debug("Rule search skipped — embedder unavailable") return [] - max_distance = min(2.0, max(0.0, 1.0 - threshold)) distance = RuleEmbedding.embedding.cosine_distance(query_vec) try: @@ -816,7 +849,8 @@ async def semantic_search_rules( .outerjoin(Project, Rule.project_id == Project.id) .where( Rule.deleted_at.is_(None), - distance <= max_distance, + # No threshold predicate — see the note above + # semantic_search_notes. Applied below, after the collapse. # topic_id XOR project_id, so exactly one arm can match. or_( Rulebook.owner_user_id == user_id, @@ -839,7 +873,9 @@ async def semantic_search_rules( if rule.id not in best or score > best[rule.id][0]: best[rule.id] = (score, rule) ranked = sorted(best.values(), key=lambda pair: pair[0], reverse=True) - return ranked[:limit] + if report is not None: + report["best_available_score"] = ranked[0][0] if ranked else None + return [pair for pair in ranked if pair[0] >= threshold][:limit] async def backfill_rule_embeddings() -> None: diff --git a/src/scribe/services/plugin_context.py b/src/scribe/services/plugin_context.py index 3ce4dda..9c873c7 100644 --- a/src/scribe/services/plugin_context.py +++ b/src/scribe/services/plugin_context.py @@ -463,6 +463,7 @@ async def _reserve_slot_for_reuse( top_k = cfg["top_k"] _t0 = time.perf_counter() + _rep: dict = {} reuse = await semantic_search_notes( user_id, query, limit=1, @@ -471,6 +472,7 @@ async def _reserve_slot_for_reuse( exclude_ids=exclude_ids | {int(n.id) for _s, n in kept}, note_type=_REUSE_KINDS, scope="browse", + report=_rep, ) # A real semantic query competing for a menu slot — logged like the scored # arm it displaces. Before this, the hit it PUSHED OUT was in @@ -481,6 +483,7 @@ async def _reserve_slot_for_reuse( user_id=user_id, source="reuse_slot", query=query, threshold=cfg["threshold"], limit=1, project_id=project_id, is_task=None, results=reuse, + best_available=_rep.get("best_available_score"), duration_ms=(time.perf_counter() - _t0) * 1000.0, ) # Verify the kind rather than trusting the query that asked for it, and @@ -530,6 +533,7 @@ async def build_autoinject_hint( return empty t0 = time.perf_counter() + _rep_ai: dict = {} hits = await semantic_search_notes( user_id, q, limit=cfg["top_k"], @@ -541,11 +545,13 @@ async def build_autoinject_hint( # still appear is a collaborator's note inside a shared project — legible # only because the line below names its owner. scope="browse", + report=_rep_ai, ) record_retrieval( user_id=user_id, source="auto_inject", query=q, 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"), duration_ms=(time.perf_counter() - t0) * 1000.0, ) if not hits: @@ -972,6 +978,7 @@ async def build_write_path_hint( # Pulled-and-seen ids stay in the query (as evidence) but never in # the menu — the dedup contract holds, the resemblance still lands. pulled_seen = seen & set(pulled) + _rep_wp: dict = {} hits = await semantic_search_notes( user_id, query, limit=remaining + len(pulled_seen), @@ -995,6 +1002,7 @@ async def build_write_path_hint( # Same reasoning as auto-inject: nobody asked for this, so it takes # the browse scope and never surfaces a one-to-one direct share. scope="browse", + report=_rep_wp, ) resembles = { int(note.id): float(score) for score, note in hits @@ -1008,6 +1016,7 @@ async def build_write_path_hint( # recording it as a notes-only retrieval would misdescribe the # candidate set the threshold is being tuned against. project_id=scope_project, is_task=None, results=hits, + best_available=_rep_wp.get("best_available_score"), duration_ms=(time.perf_counter() - t0) * 1000.0, ) if hits: @@ -1251,9 +1260,11 @@ async def build_write_path_hint( # — a gap that reads as "this surface is somehow not measurable" rather # than "nobody passed the number". rule_t0 = time.perf_counter() + _rep_wpr: dict = {} hits = await semantic_search_rules( user_id, code or path, limit=RULEHINT_LIMIT, threshold=cfg["rule_threshold"], + report=_rep_wpr, ) rule_ms = (time.perf_counter() - rule_t0) * 1000.0 fresh = [(score, rule) for score, rule in hits if rule.id not in already] @@ -1301,6 +1312,7 @@ async def build_write_path_hint( threshold=cfg["rule_threshold"], limit=RULEHINT_LIMIT, project_id=project_id, is_task=None, results=fresh, duration_ms=rule_ms, + best_available=_rep_wpr.get("best_available_score"), # 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 # the reader was simply ahead of it — and only the first is a @@ -1383,9 +1395,11 @@ async def build_tool_rule_hint( query = command[:_TOOL_QUERY_CHARS] t0 = time.perf_counter() + _rep_ptr: dict = {} hits = await semantic_search_rules( user_id, query, limit=RULEHINT_LIMIT, threshold=cfg["rule_threshold"], + report=_rep_ptr, ) duration_ms = (time.perf_counter() - t0) * 1000.0 @@ -1405,6 +1419,7 @@ async def build_tool_rule_hint( threshold=cfg["rule_threshold"], limit=RULEHINT_LIMIT, project_id=project_id, is_task=None, results=fresh, duration_ms=duration_ms, + best_available=_rep_ptr.get("best_available_score"), # 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 # and the threshold looks wrong when nothing about it is. diff --git a/src/scribe/services/retrieval_telemetry.py b/src/scribe/services/retrieval_telemetry.py index fe5908d..18e94df 100644 --- a/src/scribe/services/retrieval_telemetry.py +++ b/src/scribe/services/retrieval_telemetry.py @@ -56,6 +56,7 @@ def _build_payload( results: list[tuple[float, Note]], duration_ms: float | None, suppressed: int | None = None, + best_available: float | None = None, ) -> dict: """Reduce a retrieval call to a flat, JSON-safe RetrievalLog payload. @@ -67,6 +68,13 @@ def _build_payload( had already been shown them, and it stays None for callers that cannot know. See the column's comment: None means "not measured here", which is a different fact from 0 and must never render as one. + + `best_available` is the highest score the ranker reached BEFORE the + threshold, and it carries the same null discipline for a sharper reason: it + is the only field that still says something on a call that returned + nothing, so a 0.0 standing in for "not measured" would read as "the corpus + held nothing remotely relevant" — a claim about the corpus invented out of + a caller's silence. """ items = [ {"id": int(note.id), "score": round(float(score), 5), "rank": rank} @@ -85,6 +93,9 @@ def _build_payload( "suppressed_count": (None if suppressed is None else int(suppressed)), "top_score": (scores[0] if scores else None), "min_score": (scores[-1] if scores else None), + "best_available_score": ( + None if best_available is None else round(float(best_available), 5) + ), "result_ids": items, "duration_ms": (round(duration_ms, 2) if duration_ms is not None else None), } @@ -123,6 +134,7 @@ def record_retrieval( results: list[tuple[float, Any]], duration_ms: float | None = None, suppressed: int | None = None, + best_available: float | None = None, ) -> None: """Fire-and-forget: record one retrieval call. @@ -149,6 +161,7 @@ def record_retrieval( results=results, duration_ms=duration_ms, suppressed=suppressed, + best_available=best_available, ) except Exception: logger.debug("retrieval telemetry payload build failed", exc_info=True) @@ -175,19 +188,25 @@ def record_retrieval( 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, - measured, supp_calls, supp_zero) = rows + (calls, zero, p10, p50, p90, lo, hi, avg_n, dur, + measured, supp_calls, supp_zero, + miss_calls, miss_p50, miss_p90, miss_max) = 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), + # `cleared_threshold` USED TO LIVE HERE and it was a tautology (#3670). + # The search applies the bar before returning, so every returned result + # cleared it by construction and a call with nothing has no score to + # compare — the condition was true exactly when `result_count > 0`. + # `zero_result_calls + cleared_threshold == calls` held on all nineteen + # readings ever taken. It was `calls - zero_result_calls` wearing a name + # that promised a second opinion, and the docstring built a reading + # procedure on it that asked the reader to compare a number with itself. + # Its replacement is `near_misses` below, which the bar cannot fix by + # construction because it is measured on the calls the bar REJECTED. # Of the zeros above, which were the RANKER declining and which were # the reader having seen it already? `zero_result_calls` cannot say, # and only the first kind is evidence about the threshold. @@ -208,6 +227,28 @@ def _bucket(rows: list) -> dict: "p10": _round(p10), "p50": _round(p50), "p90": _round(p90), "min": _round(lo), "max": _round(hi), }, + # WHAT THE BAR TURNED AWAY, and the only figure here a threshold can + # actually be tuned from. Measured over the calls that returned + # NOTHING, on the best score the ranker reached before the filter. + # + # Read `p90` against the threshold in force. A bar at 0.72 rejecting a + # stream of 0.71s is set too high by a hair and the surface is losing + # hits it should have had; the same bar rejecting 0.30s is doing its + # job and the corpus simply had nothing. Both render as a zero-result + # call, and nothing else in this readout separates them. + # + # None — not a zeroed block — when no declining call in the window + # measured it. Old rows predate the column, and a 0.0 would assert that + # the corpus held nothing relevant, which is a claim about the corpus + # invented out of a caller's silence. + "near_misses": ( + None if not int(miss_calls or 0) else { + "measured_calls": int(miss_calls or 0), + "p50": _round(miss_p50), + "p90": _round(miss_p90), + "max": _round(miss_max), + } + ), "avg_result_count": _round(avg_n), "p90_duration_ms": _round(dur, 1), } @@ -215,11 +256,13 @@ def _bucket(rows: list) -> dict: # The aggregate row Postgres would have returned for a source with no rows in # the window: nothing counted, nothing scored. Positional, matching the SELECT -# `_bucket` unpacks — calls, zero, cleared, p10, p50, p90, min, max, avg_n, -# dur, measured, supp_calls, supp_zero. The three counts are 0 because zero -# calls is a real observation; everything else is None because a distribution -# nobody sampled has no value, and rendering it as 0.0 would state one. -_NO_ROWS_IN_WINDOW = [0, 0, 0, None, None, None, None, None, None, None, 0, 0, 0] +# `_bucket` unpacks — calls, zero, p10, p50, p90, min, max, avg_n, +# dur, measured, supp_calls, supp_zero, miss_calls, miss_p50, miss_p90, +# miss_max. The counts are 0 because zero calls is a real observation; +# everything else is None because a distribution nobody sampled has no value, +# and rendering it as 0.0 would state one. +_NO_ROWS_IN_WINDOW = [0, 0, None, None, None, None, None, None, None, + 0, 0, 0, 0, None, None, None] def _round(v, places: int = 4): @@ -316,16 +359,22 @@ async def retrieval_summary(user_id: int | None, *, days: int = 30) -> dict: "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) + # THE NEAR-MISS POPULATION: calls that returned nothing AND recorded what + # the bar turned away. Both conditions matter. Restricting to zero-result + # calls is what makes the number say something the bar cannot fix by + # construction — on a call that returned something, `best_available_score` + # equals `top_score` and adds nothing. Requiring the column to be non-null + # keeps rows written before #3670 out of the sample rather than letting + # them read as scoreless declines. + declined = (RetrievalLog.result_count == 0) & ( + RetrievalLog.best_available_score.isnot(None) + ) + miss = case((declined, 1), else_=0) + # `best_available_score` only for those rows; NULL elsewhere, and + # percentile_cont ignores NULLs, so the distribution is over the declines + # alone without a second pass over the table. + miss_score = case((declined, RetrievalLog.best_available_score), else_=None) # Three sums rather than one, because "not measured" and "measured as zero" # are different answers and a single counter cannot hold both. measured = case((RetrievalLog.suppressed_count.isnot(None), 1), else_=0) @@ -355,7 +404,6 @@ async def retrieval_summary(user_id: int | None, *, days: int = 30) -> dict: 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), @@ -366,6 +414,10 @@ async def retrieval_summary(user_id: int | None, *, days: int = 30) -> dict: func.sum(measured).label("measured"), func.sum(supp_calls).label("supp_calls"), func.sum(supp_zero).label("supp_zero"), + func.sum(miss).label("miss_calls"), + func.percentile_cont(0.5).within_group(miss_score.asc()), + func.percentile_cont(0.9).within_group(miss_score.asc()), + func.max(miss_score), ) .where( RetrievalLog.created_at >= since, diff --git a/tests/test_rule_usage_wiring.py b/tests/test_rule_usage_wiring.py index f985bae..050ca89 100644 --- a/tests/test_rule_usage_wiring.py +++ b/tests/test_rule_usage_wiring.py @@ -772,3 +772,97 @@ async def test_a_shown_hit_is_not_counted_as_suppressed(): assert out["rule_ids"] == [161] assert log.call_args.kwargs["suppressed"] == 1 assert len(log.call_args.kwargs["results"]) == 1 + + +# ── The identity that falsified this milestone (#3668) ───────────────── +# +# `rule_usage.surfaced` == `pre_tool_rule.cleared` + `write_path_rule.cleared`. +# Milestone #379 was scoped on a reconstruction that put ~64% of ranked rule +# surfacings as never reaching `rule_usage_events`. Five steps were planned +# against it. One read of this identity — 17 = 17, then 39 = 39 on a second +# window — falsified the whole thing: the gap was two counters that started +# recording on different days, not a write path dropping rows. +# +# So the identity is not a nice-to-have. It is the cheapest true statement +# available about this pair of tables, and its absence is what let a magnitude +# that merely LOOKED wrong survive a code review and a five-step plan. An +# identity that must hold exactly beats a magnitude that looks wrong. +# +# WHY THE ARM IS THE RIGHT PLACE TO PIN IT, and the readout is not. Inside an +# arm, one `fresh` list feeds both recorders in one function, so the counts +# cannot legitimately differ — at any limit. The readout-level form is weaker +# than it looks: `cleared_threshold` counts CALLS that beat the bar while +# `surfaced` counts RULES, and those coincide only while `RULEHINT_LIMIT` is 1. +# Raise the limit and the readout identity breaks while nothing is wrong. +# `RULEHINT_LIMIT` has already moved once (2 → 1, `2385100`), and that move is +# half of why the original reconstruction misread its own numbers. +# +# Hence three hits below, where production currently returns at most one. The +# test is deliberately in a state the limit does not permit today, because what +# is being pinned is that the two recorders read the same list — not that the +# list happens to be short. + +_THREE_HITS = [ + (0.81, fake_rule(id=156, title="A wait with no deadline is a bug")), + (0.77, fake_rule(id=157, title="A loop re-arms in a finally")), + (0.74, fake_rule(id=161, title="Reach the forge through its MCP tools")), +] + +_ARMS = [("write_path_rule", _run_arm), ("pre_tool_rule", _run_tool_arm)] + + +def _both_ends(log, rec, source): + """What the two recorders said about one call, at the same grain. + + Ids rather than counts. Equal counts drawn from different lists is a real + way for this to break — an off-by-one slice, or one recorder reading `hits` + where the other reads `fresh` in a window where the exclusion happened to + remove as many as it added — and a count comparison would call that agreement. + """ + rows = [c for c in log.call_args_list if c.kwargs.get("source") == source] + assert len(rows) == 1, ( + f"expected exactly one {source} call row, got {len(rows)} — the " + f"identity is per call and cannot be read across several" + ) + logged = [rule.id for _score, rule in rows[0].kwargs["results"]] + surfaced = [ + rid + for c in rec.call_args_list if c.kwargs.get("source") == source + for rid in c.kwargs["rule_ids"] + ] + return logged, surfaced + + +@pytest.mark.parametrize(("source", "run"), _ARMS, ids=["write_path", "pre_tool"]) +@pytest.mark.parametrize( + ("excluded", "expected"), + [([], 3), ([157], 2), ([156, 157, 161], 0)], + ids=["nothing-held", "one-already-held", "all-already-held"], +) +@pytest.mark.asyncio +async def test_both_recorders_report_the_same_rules_for_one_call( + source, run, excluded, expected +): + """One list, two tables, no room to disagree. + + The middle case is the one that discriminates. With nothing excluded both + recorders see the same three rules however wrongly they are wired, so an + arm logging `hits` to the call log and `fresh` to the surfacing log passes + that case and fails this one — and logging `hits` is exactly the divergence + that would manufacture an apparent write loss out of a correct system. + """ + log, rec = MagicMock(), MagicMock() + await run(list(_THREE_HITS), rec, retrieval_log=log, exclude_rule_ids=excluded) + + logged, surfaced = _both_ends(log, rec, source) + assert surfaced == logged, ( + f"{source} told its two tables different stories about one call: the " + f"call log recorded {logged} and the surfacing log recorded {surfaced}. " + f"Both come from `fresh`, in one function, so any difference is a bug " + f"in the wiring — and it is the shape that reads as a lost write when " + f"the two tables are later compared in aggregate (#3668)." + ) + assert len(logged) == expected, ( + "the fixture stopped exercising what it claims to; check the exclusion " + "filter still runs before both recorders" + ) diff --git a/tests/test_services_retrieval_telemetry.py b/tests/test_services_retrieval_telemetry.py index c0eca30..ff5b8fd 100644 --- a/tests/test_services_retrieval_telemetry.py +++ b/tests/test_services_retrieval_telemetry.py @@ -102,14 +102,14 @@ def test_the_readout_reports_unmeasured_suppression_as_none(): zeroed dict: a zeroed dict states a measurement nobody made.""" from scribe.services.retrieval_telemetry import _bucket - # calls, zero, cleared, p10, p50, p90, min, max, avg_n, dur, - # measured, supp_calls, supp_zero - unmeasured = _bucket([326, 114, 212, 0.6, 0.68, 0.77, 0.55, 0.85, 1.7, 130.9, - 0, 0, 0]) + # calls, zero, p10, p50, p90, min, max, avg_n, dur, + # measured, supp_calls, supp_zero, miss_calls, miss_p50, miss_p90, miss_max + unmeasured = _bucket([326, 114, 0.6, 0.68, 0.77, 0.55, 0.85, 1.7, 130.9, + 0, 0, 0, 0, None, None, None]) assert unmeasured["suppression"] is None - measured = _bucket([35, 34, 1, 0.75, 0.75, 0.75, 0.75, 0.75, 0.03, 51.9, - 35, 9, 9]) + measured = _bucket([35, 34, 0.75, 0.75, 0.75, 0.75, 0.75, 0.03, 51.9, + 35, 9, 9, 0, None, None, None]) assert measured["suppression"] == { "measured_calls": 35, "calls_with_suppression": 9, @@ -224,7 +224,10 @@ async def test_retrieval_summary_reads_what_the_writer_wrote(_dispose_engine): 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 + assert "cleared_threshold" not in ai, ( + "the tautology is back: it was true exactly when result_count > 0, " + "so it reported nothing zero_result_calls did not (#3670)" + ) # 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) @@ -847,3 +850,176 @@ async def test_a_section_is_complete_only_from_its_latest_contributor( async with async_session() as s: await s.execute(delete(RuleUsageEvent).where(RuleUsageEvent.user_id == UID)) await s.commit() + + +# ─── the bar can only be judged from what it rejected (#3670) ──────────────── +# +# `cleared_threshold` was the number the docstring told a reader to look at +# first. It was `calls - zero_result_calls` under another name: the search +# applies the bar before returning, so every returned result cleared it by +# construction and a call with nothing has no score to compare. +# `zero_result_calls + cleared_threshold == calls` held on all nineteen +# source/window readings ever taken — no near-misses, no exceptions. +# +# What replaced it cannot go the same way, and the reason is structural rather +# than careful naming: `near_misses` is measured on the calls the bar TURNED +# AWAY, using a score the bar never saw. No arrangement of `calls`, +# `zero_result_calls` and `result_count` derives it. + + +def test_a_call_that_returned_nothing_still_records_what_it_nearly_showed(): + """The whole point, at the payload grain. + + This is the row a threshold is tuned from and the one that used to carry no + score at all: `top_score` and `min_score` are both null here, correctly, and + a reader was left unable to tell a bar rejecting 0.71s from one rejecting + 0.30s. Both render as a zero-result call. + """ + 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, + ) + assert p["result_count"] == 0 + assert p["top_score"] is None, "nothing was shown, so nothing has a top score" + assert p["best_available_score"] == 0.7104, ( + "the losing score was discarded — the only figure that survives a call " + "returning nothing, and the only one a bar can be judged from" + ) + + +def test_a_caller_that_did_not_measure_the_near_miss_stores_null(): + """Null, never 0.0. A zero here reads as "the corpus held nothing remotely + relevant" — a claim about the corpus invented out of a caller's silence, + which is #3311's substitution in a new field.""" + 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 + + +def test_the_readout_reports_unmeasured_near_misses_as_none(): + """`_bucket`'s half of the same discipline, and the reason it is a block + rather than three loose keys: old rows predate the column, so a window can + legitimately contain declines nobody measured.""" + from scribe.services.retrieval_telemetry import _bucket + + # calls, zero, p10, p50, p90, min, max, avg_n, dur, + # measured, supp_calls, supp_zero, miss_calls, miss_p50, miss_p90, miss_max + none_measured = _bucket([326, 114, 0.6, 0.68, 0.77, 0.55, 0.85, 1.7, 130.9, + 0, 0, 0, 0, None, None, None]) + assert none_measured["near_misses"] is None + + measured = _bucket([326, 114, 0.6, 0.68, 0.77, 0.55, 0.85, 1.7, 130.9, + 0, 0, 0, 114, 0.61, 0.7104, 0.7189]) + assert measured["near_misses"] == { + "measured_calls": 114, + "p50": 0.61, + "p90": 0.7104, + "max": 0.7189, + } + + +def test_the_readout_carries_no_field_derivable_from_its_neighbours(): + """The guard that would have caught #3670 on the day it shipped. + + `cleared_threshold` survived because it had its own name and its own + docstring paragraph, and nobody added the two numbers beside it. This + asserts the identity that held on every reading ever taken — and if a + future field reintroduces it under a new name, the sum below is where it + shows up. + """ + from scribe.services.retrieval_telemetry import _bucket + + b = _bucket([326, 114, 0.6, 0.68, 0.77, 0.55, 0.85, 1.7, 130.9, + 0, 0, 0, 114, 0.61, 0.71, 0.72]) + derivable = { + k for k, v in b.items() + if isinstance(v, int) and not isinstance(v, bool) + and k not in ("calls", "zero_result_calls") + and v == b["calls"] - b["zero_result_calls"] + } + assert not derivable, ( + f"{sorted(derivable)} equals calls - zero_result_calls on this row. " + f"That is how `cleared_threshold` read for its whole life (#3670): a " + f"figure presented as an independent measurement that a reader can " + f"compute from the two numbers next to it. Either it is a tautology, " + f"or this fixture happens to make it look like one — check which " + f"before adding an exemption." + ) + + +@pytest.mark.integration +@pytest.mark.asyncio +async def test_the_near_miss_distribution_is_a_query_postgres_accepts(_dispose_engine): + """Integration, and NOT belt-and-braces on the unit tests above. + + `near_misses` is a `percentile_cont(...) WITHIN GROUP` over a CASE + expression, inside the same grouped aggregate that already carries four + other CASEs. That is within one step of the shape that produced #2663 — a + query the database rejected, swallowed by this module's broad `except`, so + every counter read zero in production while the writes landed fine and the + mocked tests passed. Only a real Postgres can say this parses, and if it + does not, the symptom is silence rather than an error. + + The numbers are chosen so a bar at 0.72 is visibly the wrong bar: three + declines at 0.70, 0.71 and 0.7189, none of which a reader could see before. + """ + 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 = 990079 + for best in (0.70, 0.71, 0.7189): + await _insert_retrieval_log(_build_payload( + user_id=UID, source="pre_tool_rule", query="git push", threshold=0.72, + limit=1, project_id=None, is_task=None, results=[], + duration_ms=4.0, best_available=best, + )) + # A call that DID show something. Its best-available equals its top score, + # so including it would drag the distribution toward the scores the bar + # already accepts — the population has to be the declines alone. + await _insert_retrieval_log(_build_payload( + user_id=UID, source="pre_tool_rule", query="curl", threshold=0.72, + limit=1, project_id=None, is_task=None, + results=[(0.88, _note(7))], duration_ms=4.0, best_available=0.88, + )) + # An unmeasured decline, standing in for every row written before #3670. + await _insert_retrieval_log(_build_payload( + user_id=UID, source="pre_tool_rule", query="ls", threshold=0.72, + limit=1, project_id=None, is_task=None, results=[], duration_ms=4.0, + )) + + try: + out = await retrieval_summary(UID, days=30) + assert out["read_failed"] is False, ( + "the aggregate did not execute — a rejected query here reads as " + "zeros everywhere, which is #2663 exactly" + ) + src = out["sources"]["pre_tool_rule"] + assert src["calls"] == 5 + assert src["zero_result_calls"] == 4 + + nm = src["near_misses"] + assert nm is not None, "the near-miss block did not survive the query" + assert nm["measured_calls"] == 3, ( + "the population is declines that RECORDED a score: three measured, " + "one unmeasured (excluded, not counted as a scoreless decline), and " + "one call that showed something (excluded — its best-available is " + "just its top score and says nothing about the bar)" + ) + assert nm["max"] == pytest.approx(0.7189, abs=1e-4), ( + "the closest thing the bar turned away — 0.7189 against a 0.72 " + "threshold, which is the reading the whole field exists to give" + ) + assert nm["max"] < 0.72, "a near miss that cleared the bar is not a miss" + assert 0.70 <= nm["p50"] <= 0.7189 + finally: + async with async_session() as s: + await s.execute(delete(RetrievalLog).where(RetrievalLog.user_id == UID)) + await s.commit()