fix(telemetry): a search that never ran is not a decline (#3765)
CI & Build / Plugin hooks (push) Successful in 13s
CI & Build / Python lint (push) Successful in 4s
CI & Build / TypeScript typecheck (push) Successful in 46s
CI & Build / integration (push) Successful in 52s
CI & Build / Python tests (push) Successful in 1m21s
CI & Build / Build & push image (push) Successful in 36s

`best_available_score` was added by #3670 so a bar could be judged from
what it rejected, and it arrived null on four unrelated causes: the corpus
offered nothing, the query was empty, the embedder was down, or the
DATABASE QUERY FAILED. Only the first is a measurement. The fourth is the
#2663 shape — a swallowed failure rendering as a clean zero — inside the
field added to fix an instance of the #2663 shape.

Found while trying to explain why reuse_slot returned nothing on 45 of 45
calls, and auto_inject on 153 of 161. That investigation is still open;
what it established first is that the readout could not answer it.

THE FIX IS NOT A NEW COLUMN. A call that never searched writes no row, so
every remaining null means one thing: searched, and nothing came close.
That is the convention the pre-tool arm already follows for a blank
command — "a row here would report a call that never happened and drag the
clear-rate down with phantom declines" — extended from the case a caller
can see in advance to the ones only the search knows about.

Both searches stamp `report["searched"]` FALSE before anything can return
and True only where a real result set exists, so every early return leaves
it false. It has to be the first thing done to the dict: a return added
above that line would leave the key absent.

ABSENT IS A THIRD STATE AND IT DEFAULTS TO TRUE. A caller that passes no
report cannot know, and the safe reading there is the old behaviour. Only
a real search can report False, so absent means "nobody asked" and never
"it failed" — which is also why 66 existing mocked searches across twelve
test files keep working unchanged rather than being rewritten to simulate
a flag they do not care about.

A FAILURE IS NOT MADE INVISIBLE. semantic_search_notes already logs a
WARNING on a query failure, which is where a broken search belongs: a
counter cannot say "I am broken" without a reader already trusting it.

Three tests, and the middle one is what makes them discriminate — a
blanket `return` passes the first and fails the second, because a call
that searched and came back empty is the only evidence a threshold is too
high (#3497).

Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_011cPyzNnegXHr5iRMzzy5KJ
This commit is contained in:
2026-09-09 12:47:46 -04:00
co-authored by Claude Opus 5
parent 277f5df515
commit 623464323e
6 changed files with 159 additions and 0 deletions
+11
View File
@@ -128,6 +128,7 @@ async def search(
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"),
searched=bool(report.get("searched", True)),
)
owners = await owner_names_for(
{int(note.user_id) for _s, note in raw if note.user_id != uid}
@@ -185,6 +186,16 @@ async def retrieval_telemetry(days: int = 30) -> dict:
"nothing came close"; a 0.0 there would be a claim about the corpus
invented out of a caller's silence.
A NULL HERE NOW MEANS ONE THING, which it did not at first. A semantic
search returns nothing three ways WITHOUT having run — an empty query, an
unavailable embedder, and a failed database query — and each used to write
a row indistinguishable from a ranker that declined (#3765). Those calls no
longer write a row at all, on the same reasoning that already keeps a blank
command out of the log: a row there reports a call that never happened and
drags the clear rate down with phantom declines. So a null is "searched,
and nothing came close", and a broken search shows up as a WARNING in the
application log rather than as a quiet zero in here.
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
+1
View File
@@ -58,6 +58,7 @@ async def search_route():
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"),
searched=bool(report.get("searched", True)),
)
owners = await owner_names_for(
{int(note.user_id) for _s, note in results if note.user_id != uid}
+35
View File
@@ -492,6 +492,14 @@ async def semantic_search_notes(
the only figure that survives a call returning nothing, and therefore the
only one a bar can be judged from (#3670).
It also sets `report["searched"]`: False before anything can return, True
only where a real result set exists. So an empty query, an unavailable
embedder and a failed database query all leave it FALSE, and a caller can
tell a search that found nothing from one that never ran. A caller logging
telemetry must check it — recording a failed search as a zero-result call
reports a decline the ranker never made (#3765). ABSENT means no search
touched the dict at all, which is a stand-in in a test, not a real call.
`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.
@@ -526,6 +534,13 @@ async def semantic_search_notes(
Returns an empty list if the embedder is unavailable or on any error.
"""
# Stamped FALSE before anything can return, flipped True only where a real
# result set exists (#3765). Every early return below leaves it false, so a
# caller can tell a search that found nothing from one that never ran. It
# has to be the first thing done to `report`: a return added above this
# line would leave the key ABSENT, which reads as "no caller asked".
if report is not None:
report["searched"] = False
if not query or not query.strip():
return []
try:
@@ -636,6 +651,13 @@ async def semantic_search_notes(
# 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:
# `searched` is what stops a null score meaning four things (#3765).
# Every early return above — empty query, embedder down, and the broad
# `except` around the query itself — leaves this key ABSENT, so a
# caller can tell "I looked and there was nothing" from "I never
# looked" and from "the query failed". Set here, at the one point past
# which a real result set exists.
report["searched"] = True
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:
@@ -801,6 +823,14 @@ async def semantic_search_rules(
the only figure that survives a call returning nothing, and therefore the
only one a bar can be judged from (#3670).
It also sets `report["searched"]`: False before anything can return, True
only where a real result set exists. So an empty query, an unavailable
embedder and a failed database query all leave it FALSE, and a caller can
tell a search that found nothing from one that never ran. A caller logging
telemetry must check it — recording a failed search as a zero-result call
reports a decline the ranker never made (#3765). ABSENT means no search
touched the dict at all, which is a stand-in in a test, not a real call.
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
@@ -828,6 +858,9 @@ async def semantic_search_rules(
from scribe.models.project import Project
from scribe.models.rulebook import Rule, Rulebook, RulebookTopic
# See the sibling search: stamped before anything can return (#3765).
if report is not None:
report["searched"] = False
if not query or not query.strip():
return []
try:
@@ -874,6 +907,8 @@ async def semantic_search_rules(
best[rule.id] = (score, rule)
ranked = sorted(best.values(), key=lambda pair: pair[0], reverse=True)
if report is not None:
# See the sibling search: absent means the search never ran (#3765).
report["searched"] = True
report["best_available_score"] = ranked[0][0] if ranked else None
return [pair for pair in ranked if pair[0] >= threshold][:limit]
+5
View File
@@ -484,6 +484,7 @@ async def _reserve_slot_for_reuse(
threshold=cfg["threshold"], limit=1, project_id=project_id,
is_task=None, results=reuse,
best_available=_rep.get("best_available_score"),
searched=bool(_rep.get("searched", True)),
duration_ms=(time.perf_counter() - _t0) * 1000.0,
)
# Verify the kind rather than trusting the query that asked for it, and
@@ -552,6 +553,7 @@ async def build_autoinject_hint(
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"),
searched=bool(_rep_ai.get("searched", True)),
duration_ms=(time.perf_counter() - t0) * 1000.0,
)
if not hits:
@@ -1046,6 +1048,7 @@ async def build_write_path_hint(
best_available=(
None if withheld_here else _rep_wp.get("best_available_score")
),
searched=bool(_rep_wp.get("searched", True)),
duration_ms=(time.perf_counter() - t0) * 1000.0,
)
if hits:
@@ -1342,6 +1345,7 @@ async def build_write_path_hint(
project_id=project_id,
is_task=None, results=fresh, duration_ms=rule_ms,
best_available=_rep_wpr.get("best_available_score"),
searched=bool(_rep_wpr.get("searched", True)),
# 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
@@ -1449,6 +1453,7 @@ async def build_tool_rule_hint(
project_id=project_id,
is_task=None, results=fresh, duration_ms=duration_ms,
best_available=_rep_ptr.get("best_available_score"),
searched=bool(_rep_ptr.get("searched", True)),
# 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.
@@ -135,6 +135,7 @@ def record_retrieval(
duration_ms: float | None = None,
suppressed: int | None = None,
best_available: float | None = None,
searched: bool = True,
) -> None:
"""Fire-and-forget: record one retrieval call.
@@ -146,9 +147,35 @@ def record_retrieval(
provide. retrieval_logs is not restored at all, so it has no such hazard,
and `source` already distinguishes the surfaces.
`searched=False` WRITES NO ROW, and that is the point rather than an
optimisation. A semantic search has three ways to return nothing without
having run — an empty query, an unavailable embedder, and the broad
`except` around the query itself — and each one currently arrives here
looking exactly like a ranker that declined. Logging it would report a
decline nobody made, drag `zero_result_calls` down with phantom evidence
about a threshold, and leave `best_available_score` null for a reason that
has nothing to do with the corpus. That last ambiguity is #3765: the field
added to judge a bar was null on four unrelated causes, one of them a
swallowed failure, and no reader could tell them apart.
Dropping the row is what makes the remaining nulls mean ONE thing —
"searched, and there was nothing".
The same convention already governs the pre-tool arm: a blank command costs
no embedding query, so it writes no row, because "a row here would report a
call that never happened and drag the clear-rate down with phantom
declines". This extends it from a case the caller could see in advance to
the ones only the search knows about.
A FAILURE IS NOT MADE INVISIBLE BY THIS. `semantic_search_notes` logs a
WARNING on a query failure, which is where a broken search belongs — a
counter cannot say "I am broken" without a reader already trusting it.
Builds the payload inline (synchronously) then schedules the insert so the
caller returns immediately. Never raises — telemetry must not affect search.
"""
if not searched:
return
try:
payload = _build_payload(
user_id=user_id,
@@ -1040,3 +1040,83 @@ async def test_the_near_miss_distribution_is_a_query_postgres_accepts(_dispose_e
async with async_session() as s:
await s.execute(delete(RetrievalLog).where(RetrievalLog.user_id == UID))
await s.commit()
# ─── a search that never ran is not a decline (#3765) ────────────────────────
#
# `best_available_score` was added by #3670 so a bar could be judged from what
# it rejected, and it arrived null on four unrelated causes: the corpus offered
# nothing, the query was empty, the embedder was down, or the DATABASE QUERY
# FAILED. Only the first is a measurement. The fourth is the #2663 shape — a
# swallowed failure rendering as a clean zero — inside the field added to fix
# an instance of the #2663 shape.
#
# The fix is not a new column. A call that never searched writes no row, so
# every remaining null means one thing. That is the convention the pre-tool arm
# already follows for a blank command, extended from the case a caller can see
# in advance to the ones only the search knows about.
def test_a_search_that_never_ran_writes_no_row():
"""The whole fix, at the one place it is enforced.
`record_retrieval` is fire-and-forget and returns None either way, so the
observable is the payload never being built — asserted through the builder
rather than the scheduler, which needs a running loop.
"""
from unittest.mock import patch
import scribe.services.retrieval_telemetry as rt
with patch.object(rt, "_build_payload") as build:
rt.record_retrieval(
user_id=1, source="auto_inject", query="q", threshold=0.6,
limit=3, project_id=None, is_task=None, results=[],
searched=False,
)
assert not build.called, (
"a search that never ran was recorded as a retrieval. It would "
"read as a ranker decline — evidence about a threshold, from a "
"call where no threshold was ever applied (#3765)"
)
def test_a_search_that_ran_and_found_nothing_still_writes_its_row():
"""The half that stops the fix from being 'log less'.
A call that searched and came back empty is the ONLY evidence a threshold
is too high (#3497). Dropping it too would trade one silent distortion for
another, and this assertion is what makes the pair discriminate: a blanket
`return` passes the test above and fails this one.
"""
from unittest.mock import patch
import scribe.services.retrieval_telemetry as rt
with patch.object(rt, "_build_payload") as build:
rt.record_retrieval(
user_id=1, source="auto_inject", query="q", threshold=0.6,
limit=3, project_id=None, is_task=None, results=[],
searched=True,
)
assert build.called, "a genuine zero-result call must still be recorded"
def test_a_caller_that_never_asked_is_assumed_to_have_searched():
"""`searched` defaults True, and the default is load-bearing.
A caller that passes no `report` cannot know, and the safe reading there is
the old behaviour — log it. Only a REAL search can report False, because it
stamps the key before anything can return. An absent key therefore means
"nobody asked", never "it failed".
"""
from unittest.mock import patch
import scribe.services.retrieval_telemetry as rt
with patch.object(rt, "_build_payload") as build:
rt.record_retrieval(
user_id=1, source="mcp_search", query="q", threshold=0.45,
limit=10, project_id=None, is_task=None, results=[],
)
assert build.called