diff --git a/alembic/versions/0095_retrieval_log_suppressed_count.py b/alembic/versions/0095_retrieval_log_suppressed_count.py new file mode 100644 index 0000000..87fe5aa --- /dev/null +++ b/alembic/versions/0095_retrieval_log_suppressed_count.py @@ -0,0 +1,52 @@ +"""add retrieval_logs.suppressed_count — tell a ranker decline from a repeat (#3497) + +Revision ID: 0095 +Revises: 0094 +Create Date: 2026-09-03 + +`result_count == 0` has always meant "this surface said nothing", which is the +right number for "was the hint any use" and the wrong one for tuning a +threshold. It folds together two unrelated events: + + - the ranker found nothing above the bar — the ONLY evidence a threshold is + set too high; and + - the ranker found something the session had already been shown — a decline + that says nothing whatever about the bar. + +The rule arms filter in Python after the search, so they can count the second +kind exactly. The note arms pass `exclude_ids` INTO semantic_search_notes, so +the dropped rows never come back and there is nothing to count. + +NULLABLE, AND THE NULL IS THE POINT. A surface that does not measure +suppression stores NULL, not 0, and the readout renders it as "not measured" +rather than "none". Defaulting to 0 would make an unmeasured surface look like +a perfectly clean one — the exact substitution of an artifact for a +measurement that #3311 made and that #3497 exists to correct. Doing it again, +in the migration that fixes it, would be its own small joke. + +No backfill for the same reason: existing rows genuinely do not know, and +saying so is the honest state. `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 = "0095" +down_revision = "0094" +branch_labels = None +depends_on = None + + +def upgrade() -> None: + op.add_column( + "retrieval_logs", + sa.Column("suppressed_count", sa.Integer(), nullable=True), + ) + + +def downgrade() -> None: + op.drop_column("retrieval_logs", "suppressed_count") diff --git a/src/scribe/mcp/tools/search.py b/src/scribe/mcp/tools/search.py index a686a1c..0bbed96 100644 --- a/src/scribe/mcp/tools/search.py +++ b/src/scribe/mcp/tools/search.py @@ -168,6 +168,20 @@ async def retrieval_telemetry(days: int = 30) -> dict: 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. + 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 + `zero_result_calls` to leave the true ranker declines. + + `suppression` is `null` when NO row in the window reported it, and that is + "not measured here", NOT "none suppressed". Surfaces that pass their + exclusions into the search never see what was dropped, so they cannot say. + Do not read a null as a zero: reading an artifact as a measurement is how + this surface got mis-scoped once already (#3311, #3497). + `usage` — NOTES ONLY, from `note_usage_events`, at the per-note grain `retrieval_logs` cannot be indexed at: `surfaced` (ranked surfacings — a scored surface CHOSE the record), `ambient` (the rest), `pulled` split into diff --git a/src/scribe/models/retrieval_log.py b/src/scribe/models/retrieval_log.py index ba49df4..fc85a84 100644 --- a/src/scribe/models/retrieval_log.py +++ b/src/scribe/models/retrieval_log.py @@ -42,6 +42,16 @@ class RetrievalLog(Base): # False=notes, NULL=any. is_task: Mapped[bool | None] = mapped_column(Boolean, nullable=True) result_count: Mapped[int] = mapped_column(Integer, nullable=False, default=0) + # How many scored hits this call DROPPED because the session had already + # been shown them. NULLABLE, and the null is load-bearing: it means "this + # surface does not report suppression", which must not read as "nothing was + # suppressed". `result_count == 0` alone conflates two different events — + # the ranker found nothing above threshold, and the ranker found something + # the reader already had — and only the first says a threshold is too high. + # Reading a zero as a ranker decline is how #3311 mis-scoped a milestone; + # an unmeasured value that renders as 0 is the same mistake with a nicer + # face, so surfaces that filter INSIDE the search leave this null. + 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) # [{"id": int, "score": float, "rank": int}, ...], highest-first. @@ -67,6 +77,7 @@ class RetrievalLog(Base): "project_id": self.project_id, "is_task": self.is_task, "result_count": self.result_count, + "suppressed_count": self.suppressed_count, "top_score": self.top_score, "min_score": self.min_score, "result_ids": self.result_ids, diff --git a/src/scribe/services/plugin_context.py b/src/scribe/services/plugin_context.py index 589d166..2b45615 100644 --- a/src/scribe/services/plugin_context.py +++ b/src/scribe/services/plugin_context.py @@ -1253,6 +1253,11 @@ 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, + # 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 + # reason to move the threshold. + suppressed=len(hits) - len(fresh), ) if fresh: # `rule_ids` is `fresh`, i.e. AFTER exclude_rule_ids. A rule the @@ -1352,6 +1357,10 @@ 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, + # 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. + suppressed=len(hits) - len(fresh), ) if not fresh: return out diff --git a/src/scribe/services/retrieval_telemetry.py b/src/scribe/services/retrieval_telemetry.py index e21629a..126fe40 100644 --- a/src/scribe/services/retrieval_telemetry.py +++ b/src/scribe/services/retrieval_telemetry.py @@ -55,12 +55,18 @@ def _build_payload( is_task: bool | None, results: list[tuple[float, Note]], duration_ms: float | None, + suppressed: int | None = None, ) -> dict: """Reduce a retrieval call to a flat, JSON-safe RetrievalLog payload. Pure and synchronous (no DB, no event loop) so it is unit-testable and safe to run inline before scheduling the write. `results` is the `(score, Note)` list from semantic_search_notes, already highest-first. + + `suppressed` is how many scored hits the caller dropped because the session + 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. """ items = [ {"id": int(note.id), "score": round(float(score), 5), "rank": rank} @@ -76,6 +82,7 @@ def _build_payload( "project_id": project_id, "is_task": is_task, "result_count": len(items), + "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), "result_ids": items, @@ -115,6 +122,7 @@ def record_retrieval( is_task: bool | None, results: list[tuple[float, Any]], duration_ms: float | None = None, + suppressed: int | None = None, ) -> None: """Fire-and-forget: record one retrieval call. @@ -140,6 +148,7 @@ def record_retrieval( is_task=is_task, results=results, duration_ms=duration_ms, + suppressed=suppressed, ) except Exception: logger.debug("retrieval telemetry payload build failed", exc_info=True) @@ -166,7 +175,8 @@ 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 = rows + (calls, zero, cleared, p10, p50, p90, lo, hi, avg_n, dur, + measured, supp_calls, supp_zero) = rows return { "calls": int(calls or 0), # A call that returned nothing is not a low-scoring call — it is a @@ -178,6 +188,22 @@ def _bucket(rows: list) -> dict: # 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), + # 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. + # + # None — not a zeroed dict — when no row in the window reported it. A + # surface that filters inside the search genuinely does not know, and + # rendering that as `{"calls": 0}` would state a measurement nobody + # made. That substitution is the whole of #3311. + "suppression": ( + None if not int(measured or 0) else { + "measured_calls": int(measured or 0), + "calls_with_suppression": int(supp_calls or 0), + # Subtract from zero_result_calls for the true ranker declines. + "zero_because_already_shown": int(supp_zero or 0), + } + ), "top_score": { "p10": _round(p10), "p50": _round(p50), "p90": _round(p90), "min": _round(lo), "max": _round(hi), @@ -240,6 +266,14 @@ async def retrieval_summary(user_id: int | None, *, days: int = 30) -> dict: else_=0, ) zero = case((RetrievalLog.result_count == 0, 1), else_=0) + # 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) + supp_calls = case((RetrievalLog.suppressed_count > 0, 1), else_=0) + supp_zero = case( + ((RetrievalLog.result_count == 0) & (RetrievalLog.suppressed_count > 0), 1), + else_=0, + ) def pct(p: float): return func.percentile_cont(p).within_group(RetrievalLog.top_score.asc()) @@ -266,6 +300,9 @@ async def retrieval_summary(user_id: int | None, *, days: int = 30) -> dict: func.percentile_cont(0.9).within_group( RetrievalLog.duration_ms.asc() ), + func.sum(measured).label("measured"), + func.sum(supp_calls).label("supp_calls"), + func.sum(supp_zero).label("supp_zero"), ) .where( RetrievalLog.created_at >= since, diff --git a/tests/test_rule_usage_wiring.py b/tests/test_rule_usage_wiring.py index e63cede..bb76683 100644 --- a/tests/test_rule_usage_wiring.py +++ b/tests/test_rule_usage_wiring.py @@ -702,3 +702,65 @@ def test_neither_rule_arm_logs_its_call_behind_a_results_guard(): "the pre-tool arm returns before logging its call — a surface with no " "rows at all cannot be told apart from a hook that never fired" ) + + +# ── Suppression: which zeros were the ranker, which were repeats (#3497) ── +# +# Making the call log unconditional exposed a second ambiguity in the same row. +# A zero-result rule call is two unrelated events: the ranker found nothing +# above the bar, or it found only what this session already held. Only the +# first says anything about the threshold, and a long session excludes its way +# into the second — so without the split, the arm looks worse the longer it +# runs correctly. + + +@pytest.mark.asyncio +async def test_the_write_path_arm_reports_what_the_session_already_held(): + log, rec = MagicMock(), MagicMock() + hits = [(0.71, fake_rule(id=156, title="A wait with no deadline is a bug")), + (0.70, fake_rule(id=157, title="A loop re-arms in a finally"))] + await _run_arm(hits, rec, retrieval_log=log, exclude_rule_ids=[156, 157]) + + row = next(c for c in log.call_args_list + if c.kwargs.get("source") == "write_path_rule") + assert row.kwargs["results"] == [] + assert row.kwargs["suppressed"] == 2, ( + "both hits were repeats, so this zero is not evidence about the bar" + ) + + +@pytest.mark.asyncio +async def test_a_genuine_ranker_decline_reports_zero_suppression(): + """Zero, not None. The arm filters in Python, so it always knows — and + 'measured none' has to stay distinguishable from 'cannot measure'.""" + log, rec = MagicMock(), MagicMock() + await _run_arm([], rec, retrieval_log=log) + + row = next(c for c in log.call_args_list + if c.kwargs.get("source") == "write_path_rule") + assert row.kwargs["suppressed"] == 0 + assert row.kwargs["suppressed"] is not None + + +@pytest.mark.asyncio +async def test_the_tool_arm_reports_suppression_too(): + log, rec = MagicMock(), MagicMock() + hits = [(0.75, fake_rule(id=161, title="Reach the forge through its MCP tools"))] + await _run_tool_arm(hits, rec, retrieval_log=log, exclude_rule_ids=[161]) + + assert log.call_args.kwargs["results"] == [] + assert log.call_args.kwargs["suppressed"] == 1 + + +@pytest.mark.asyncio +async def test_a_shown_hit_is_not_counted_as_suppressed(): + """The obvious inverse, worth pinning: `suppressed` counts what was DROPPED, + not what came back. Off by one here and every zero row reads as a repeat.""" + log, rec = MagicMock(), MagicMock() + hits = [(0.75, fake_rule(id=161, title="Reach the forge through its MCP tools")), + (0.70, fake_rule(id=12, title="Don't run a local stack unless asked"))] + out = await _run_tool_arm(hits, rec, retrieval_log=log, exclude_rule_ids=[12]) + + assert out["rule_ids"] == [161] + assert log.call_args.kwargs["suppressed"] == 1 + assert len(log.call_args.kwargs["results"]) == 1 diff --git a/tests/test_services_retrieval_telemetry.py b/tests/test_services_retrieval_telemetry.py index 1bea2ca..7cc869c 100644 --- a/tests/test_services_retrieval_telemetry.py +++ b/tests/test_services_retrieval_telemetry.py @@ -57,6 +57,68 @@ def test_build_payload_rounds_scores_to_5dp(): assert p["result_ids"][0]["score"] == 0.12346 +# ─── suppression: "not measured" is not "none" (#3497) ─────────────────────── + + +def test_a_caller_that_cannot_measure_suppression_stores_null(): + """The distinction the whole column exists for. + + A surface that passes its exclusions into the search never sees what was + dropped. Storing 0 would assert a clean run nobody observed — reading an + artifact as a measurement, which is exactly #3311's mistake. + """ + 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["suppressed_count"] is None, "unmeasured must not render as zero" + + +def test_a_caller_that_measured_no_suppression_stores_zero(): + """The other side of it. Zero is a real observation and must survive.""" + p = _build_payload( + user_id=1, source="pre_tool_rule", query="git status", threshold=0.6, + limit=1, project_id=None, is_task=None, results=[], duration_ms=None, + suppressed=0, + ) + assert p["suppressed_count"] == 0 + + +def test_the_count_of_hits_the_reader_already_held_is_carried(): + p = _build_payload( + user_id=1, source="write_path_rule", query="code", threshold=0.6, + limit=2, project_id=None, is_task=None, results=[], duration_ms=None, + suppressed=2, + ) + assert p["result_count"] == 0 + assert p["suppressed_count"] == 2, ( + "a zero row that was really two repeats must be distinguishable from " + "a zero row where the ranker found nothing" + ) + + +def test_the_readout_reports_unmeasured_suppression_as_none(): + """`_bucket` renders the aggregate. No row reporting it → null, never a + 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]) + 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]) + assert measured["suppression"] == { + "measured_calls": 35, + "calls_with_suppression": 9, + "zero_because_already_shown": 9, + } + # The number the threshold is actually tuned from. + assert measured["zero_result_calls"] - 9 == 25 + + def test_record_retrieval_without_event_loop_is_safe(): """Called from a sync context (no running loop) it must swallow and return, never raise — telemetry can't be allowed to break a caller."""