Merge pull request 'feat(telemetry): tell a ranker decline from a repeat before the observation window opens (#3497)' (#139) from dev into main

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")

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

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,

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

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,

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

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."""