feat(telemetry): tell a ranker decline from a repeat before the observation window opens (#3497)
CI & Build / Python lint (push) Successful in 3s
CI & Build / Plugin hooks (push) Successful in 8s
CI & Build / integration (push) Successful in 31s
CI & Build / TypeScript typecheck (push) Successful in 37s
CI & Build / Python tests (push) Successful in 1m4s
CI & Build / Build & push image (push) Successful in 28s

Making the rule arms log every call exposed a second ambiguity in the same
row. `result_count == 0` is two unrelated events wearing one number:

  - the ranker found nothing above the bar — the only evidence a threshold is
    set too high; and
  - the ranker found only what this session had already been shown — which
    says nothing whatever about the bar.

A long session excludes its way into the second, so the arm reads worse the
longer it runs correctly. Rows written now carry the ambiguity permanently,
which is why this lands before any watch period rather than after.

`retrieval_logs.suppressed_count` (0095, nullable) holds what the caller
dropped as already-shown. Both rule arms report it; they filter in Python and
always know. The note arms pass exclusions INTO semantic_search_notes and
never see what was dropped, so they store NULL.

THE NULL IS LOAD-BEARING. It means "not measured here", and the readout
renders it as `suppression: null` rather than a zeroed dict. Defaulting to 0
would let an unmeasured surface read as a perfectly clean one — the same
substitution of an artifact for a measurement that #3311 made. No backfill,
for the same reason: existing rows genuinely do not know.

`retrieval_telemetry`'s `sources` gains `suppression` with `measured_calls`,
`calls_with_suppression` and `zero_because_already_shown`; subtract the last
from `zero_result_calls` for the true ranker declines. The MCP tool docstring
says to read the two together and warns against reading the null as a zero.

Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_011cPyzNnegXHr5iRMzzy5KJ
This commit is contained in:
2026-09-03 21:12:38 -04:00
co-authored by Claude Opus 5
parent 48804c437d
commit 8be555d6dd
7 changed files with 248 additions and 1 deletions
+62
View File
@@ -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
@@ -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."""