feat(telemetry): retrieval_telemetry says what is wrong (#3431)
CI & Build / Python lint (push) Successful in 3s
CI & Build / Plugin hooks (push) Successful in 8s
CI & Build / integration (push) Successful in 48s
CI & Build / TypeScript typecheck (push) Successful in 52s
CI & Build / Python tests (push) Successful in 1m30s
CI & Build / Build & push image (push) Successful in 23s

The tool returned distributions and left the reading to the caller, so every
readout was the same four checks done by hand — #3430's baseline, #3835's rule
near-misses, the #1038 rerank gate. Mechanical, and therefore forgettable.

Tonight's acceptance pass on #3898 was the case for doing this. Reading it by
hand meant catching that two surfaces had `covers_window: false`, that
`prompt_rule`'s floor had moved three times inside the window (which made the
readout self-contradictory: deliveries at 0.622 beside refusals at 0.7199),
and that 15 of 20 near-misses were one record against text no operator wrote.
Miss any of those and the obvious conclusion was "the bar is too tight" — a
floor change that would have injected one preference into every notification.

`warnings` is always present and empty when clean, so its emptiness is an
answer rather than a gap. Each entry carries the numbers that produced it:
"345 calls, 0 declined" is the analysis, "check write_path_rule" is an
instruction to redo it. Five codes — cannot_decline, band_hugs_floor,
no_duration, surfaced_never_pulled, unregistered_source.

cannot_decline has three guards, each a bug it would otherwise cause. Asked
surfaces are exempt (a search returning a list every time is working). An arm
not known to log unconditionally is exempt — that is #3497 exactly, where both
rule arms recorded only their hits, so a decline count of zero was a LOGGING
defect and this warning would have sent the reader to a threshold that was
never involved. Unregistered sources get numbers but no verdict.

`silent_surfaces` is the half the rows cannot show: an arm that emitted
nothing is invisible to every row-based check and looks exactly like an arm
that does not exist. It is driven by a new declared registry,
`retrieval_registry.POINTS` — deliberately NOT `retrieval_surfaces.SURFACES`,
which answers "what can be tuned" and excludes the reserved slots because a
budget of 1 is their feature. This answers "what can be measured", and the
reserved slots belong in it precisely because they are judgeable without being
tunable. A test asserts the two cannot drift apart.

The registry test derives sources from the call sites with `ast`, not grep,
and the difference is not theoretical: `wide_net` and `report_preference`
reach their recorder as `source=SOURCE` through a module constant, so a grep
for `source="` is blind to both — the narrowing #3191 warns about. Three sites
pass `source` as a variable and are declared in FAN_OUT_SITES; the test pins
those sites but not the values they can pass, which is why the
`unregistered_source` warning exists to catch the rest at first fire.

Thresholds are settings (rule 25) defaulted so a fresh install with almost no
data produces no warnings at all (rule 115) — a new user's first readout
naming five broken things would be describing the emptiness.

Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01821k5B3Ysecp9fNYs92Kuy
This commit is contained in:
2026-09-20 20:24:56 -04:00
co-authored by Claude Opus 5
parent 1f7ff7b215
commit e2c3a5c2b5
5 changed files with 1003 additions and 0 deletions
+284
View File
@@ -33,6 +33,11 @@ from scribe.models.rule_usage import SURFACED as RULE_SURFACED
from scribe.models.rule_usage import RuleUsageEvent
from scribe.services.rule_usage import is_ambient
from scribe.models.retrieval_log import RetrievalLog
from scribe.services.retrieval_registry import (
POINTS, UNBIDDEN, get_point, is_registered, sources_expected_to_emit,
)
from scribe.services.retrieval_surfaces import SURFACES, floor_for
from scribe.services.settings import get_setting
logger = logging.getLogger(__name__)
@@ -436,6 +441,228 @@ def _coverage(complete_from, since) -> dict:
}
# ── What is wrong, computed rather than re-derived by hand (#3431) ────────
#
# Every reading of this tool used to be a hand analysis — #3430's baseline,
# #3835's rule near-misses, the #1038 rerank gate — and the analysis was the
# same four checks each time. Worse than tedious: it was UNRELIABLE, because
# the reader had to remember them. The checks are mechanical, so they belong
# in the tool, phrased for an agent reading the output rather than a page.
# HOW MUCH TRAFFIC BEFORE A SILENCE MEANS ANYTHING. Three calls returning
# nothing is a quiet afternoon; three hundred is an arm that has lost its
# voice, and only the count separates them. Settings-backed because the right
# number depends on how hard an install is driven (rule 25), and defaulted
# high enough that a FRESH INSTALL WITH ALMOST NO DATA PRODUCES NO WARNINGS AT
# ALL (rule 115) — a new user's first readout saying five things are broken
# would be describing the emptiness, not the system.
WARN_MIN_CALLS_KEY = "retrieval_warn_min_calls"
WARN_MIN_CALLS_DEFAULT = 30
# HOW CLOSE TO THE BAR COUNTS AS PILED ON IT. If the WEAKEST tenth of what an
# arm returns still sits within a hair of the floor, the score is not sorting
# anything — everything it admits is borderline, and the bar is doing the
# whole job the ranking was supposed to do. 0.02 is roughly the spread this
# corpus shows between a genuine match and an incidental one (#2485 measured
# the top-to-second gap at 0.010-0.023 for everything but snippets), so a
# band tighter than that is indistinguishable from noise.
WARN_FLOOR_EPSILON_KEY = "retrieval_warn_floor_epsilon"
WARN_FLOOR_EPSILON_DEFAULT = 0.02
def _num(raw: str, fallback):
"""A setting read as a number, falling back rather than raising.
A malformed setting must not take the readout down with it — same posture
as the rest of this module, where a telemetry failure that breaks its
caller is the worse bug (#2663).
"""
try:
return type(fallback)(raw)
except (TypeError, ValueError):
return fallback
def _warn(code, detail, source=None, **numbers) -> dict:
"""One finding, carrying the numbers that produced it.
THE NUMBERS ARE NOT DECORATION. "Check write_path_rule" is an instruction
to redo the analysis; "345 calls, 0 declined" is the analysis. A reader
who disagrees with the rule can only say so if the inputs travel with the
verdict.
"""
return {"code": code, "source": source, "detail": detail, "numbers": numbers}
def _compute_warnings(sources: dict, usage: dict, rule_usage: dict,
floors: dict, min_calls: int, epsilon: float) -> list[dict]:
"""The four checks, over whatever sources the window actually contains.
DELIBERATELY NOT KEYED ON A HARD-CODED SOURCE LIST. An arm added next
month is judged the day it first fires, without anyone remembering to add
it here — which is the opposite failure from the registry's, and why both
exist.
"""
out: list[dict] = []
for name, b in sorted(sources.items()):
calls = b.get("calls") or 0
point = get_point(name)
# ── An arm nobody declared ───────────────────────────────────────
#
# THE CHECK THAT COVERS WHAT THE STATIC TEST CANNOT. The registry test
# reads the call sites with `ast`, which settles a literal and a
# module constant but not a source arriving through a parameter or a
# dict key — `plugin_context` fans out to three arms that way. Adding
# a fourth would pass that test and then land here, the first time it
# fires, instead of going unnoticed.
#
# It is a warning rather than an omission: an unregistered arm still
# gets its numbers printed above, because the row is real. What it
# does not get is a verdict, since every check below needs to know
# whether the arm was ASKED or fired unbidden, and that fact lives
# only in the registry.
if not is_registered(name):
out.append(_warn(
"unregistered_source",
f"{calls} calls logged under a source that is not in "
f"`retrieval_registry.POINTS`. Its numbers are above and are "
f"real; no warning below could be computed for it, because "
f"nothing says whether it was asked or fired unbidden. Add "
f"it to the registry.",
source=name, calls=calls,
))
# ── Cannot decline ───────────────────────────────────────────────
#
# An arm that interrupts unasked must be able to stay quiet. One that
# has answered every single call over real traffic is not confident,
# it is stuck — either its bar is beneath everything or it is not
# applying one.
#
# THREE GUARDS BEFORE TRUSTING THIS, and each is a bug it already
# caused. Asked surfaces are exempt: a search returning a list every
# time is a search doing its job, and flagging `mcp_search` would
# teach the reader to skip the list. An UNREGISTERED source is exempt
# because nothing says which kind it is, and guessing from the name is
# the narrowing #3191 warns about. And an arm not known to log
# unconditionally is exempt because that was #3497 exactly: both rule
# arms once recorded only their hits, so their decline count was
# structurally zero and this warning would have fired on a LOGGING
# defect while pointing the reader at the threshold.
if (
calls >= min_calls
and (b.get("zero_result_calls") or 0) == 0
and point is not None
and point.kind == UNBIDDEN
and point.logs_unconditionally
):
out.append(_warn(
"cannot_decline",
f"{calls} calls, 0 of them returned nothing. An arm that fires "
f"unasked has to be able to say nothing; this one never has. "
f"Check that it applies its floor at all before reading any "
f"score below as evidence.",
source=name, calls=calls, zero_result_calls=0,
))
# ── Band hugs its floor ──────────────────────────────────────────
#
# Read on p10, the WEAKEST tenth of what the arm returned. If even
# that sits on the bar, the bar is selecting and the score is not.
#
# Only for arms whose floor is knowable. The reserved slots borrow
# their parent arm's floor rather than owning one, so naming a number
# for them here would attribute the parent's setting to the child and
# invite tuning a dial that does not exist.
floor = floors.get(name)
p10 = (b.get("top_score") or {}).get("p10")
if calls >= min_calls and floor is not None and p10 is not None:
gap = p10 - floor
if gap < epsilon:
out.append(_warn(
"band_hugs_floor",
f"the weakest tenth of what this arm returns scores "
f"{p10}, only {round(gap, 4)} above its floor of {floor}. "
f"Scores piled on the bar mean the bar is choosing, not "
f"the ranking — a floor change here moves volume, not "
f"quality.",
source=name, p10=p10, floor=floor,
gap=round(gap, 4), epsilon=epsilon,
))
# ── No duration recorded ─────────────────────────────────────────
#
# Not a performance warning — a LOGGING one. A source writing rows
# without timings means a call path that skipped the instrumentation,
# and every other number it reports is worth less until that is
# explained. No minimum: one untimed call is already the defect.
if calls > 0 and b.get("p90_duration_ms") is None:
out.append(_warn(
"no_duration",
f"{calls} calls logged and not one recorded a duration. This "
f"is a logging gap rather than a slow arm — some call path "
f"reaches the recorder without timing itself.",
source=name, calls=calls,
))
# ── Surfaced and never pulled, for each corpus ───────────────────────
#
# The one corpus-level check, and the only number here that judges the
# RECORDS rather than the arms. A record shown repeatedly and never opened
# is either badly titled or genuinely irrelevant, and both are actionable
# in a way "pull-through is 0.15" is not.
#
# Distinct records, not events: a note surfaced forty times and never
# opened is one problem, not forty.
for label, block in (("notes", usage), ("rules", rule_usage)):
shown = block.get("distinct_notes_surfaced")
pulled = block.get("distinct_notes_pulled")
if shown is None:
shown = block.get("distinct_rules_surfaced")
pulled = block.get("distinct_rules_pulled")
if not shown:
continue
never = int(shown) - int(pulled or 0)
if never > 0:
out.append(_warn(
"surfaced_never_pulled",
f"{never} of {shown} distinct {label} were surfaced in this "
f"window and never opened. Read the titles before the "
f"threshold: a record nobody opens is usually one whose title "
f"does not say when it matters.",
source=None, corpus=label,
surfaced=int(shown), pulled=int(pulled or 0), never_pulled=never,
))
return out
def _silent_surfaces(sources: dict, usage: dict, rule_usage: dict,
active: bool) -> list[dict]:
"""Registered points that emitted nothing at all in the window.
THE HALF THE ROWS CANNOT SEE. Every check above reads rows, so an arm that
produced none is invisible to all of them — it looks identical to an arm
that does not exist. #3430 found one of these, and only because a human
happened to know the arm was supposed to be there.
ONLY WHEN THE INSTALL IS OTHERWISE ACTIVE. On a quiet window every point
is silent and the list would be the registry, printed back. Rule 115: a
fresh install must not be told that thirty things are broken when the
truth is that nobody has used it yet.
"""
if not active:
return []
seen = set(sources) | set((usage.get("by_source") or {}))
seen |= set((rule_usage.get("by_source") or {}))
return [
{"source": s, "kind": POINTS[s].kind, "what": POINTS[s].what}
for s in sources_expected_to_emit() if s not in seen
]
async def retrieval_summary(
user_id: int | None, *, days: int = 30, near_miss_samples: int = 0,
) -> dict:
@@ -1000,4 +1227,61 @@ async def retrieval_summary(
rule_usage.update(_coverage((rule_complete or {}).get("*"), since))
out["rule_usage"] = rule_usage
# ── What is wrong (#3431) ────────────────────────────────────────────
#
# Computed LAST, over the blocks above rather than over the database, so
# a warning can never disagree with the numbers printed beside it. Read
# the same rows the caller reads.
#
# ALWAYS PRESENT, EMPTY WHEN NOTHING IS WRONG — never omitted. A missing
# key and an empty list are the same shape to a careless reader and
# opposite facts: one says "checked, clean", the other says "did not
# check". The whole point of the key is that its emptiness is an answer.
out["warnings"] = []
out["silent_surfaces"] = []
# A FAILED READ JUDGES NOTHING. Warnings computed over rows that could not
# be loaded would read as findings about the system rather than about the
# outage, which is the #2663 confusion arriving one level up.
if out["read_failed"]:
return out
min_calls = _num(
await get_setting(user_id, WARN_MIN_CALLS_KEY, "") if user_id else "",
WARN_MIN_CALLS_DEFAULT,
)
epsilon = _num(
await get_setting(user_id, WARN_FLOOR_EPSILON_KEY, "") if user_id else "",
WARN_FLOOR_EPSILON_DEFAULT,
)
# The floor each arm was actually judged against, read per surface rather
# than assumed. Only the TUNABLE surfaces have one to read; the reserved
# slots borrow their parent's and are left out on purpose, because naming
# the parent's number against the child would invite tuning a dial the
# child does not have.
floors: dict[str, float] = {}
if user_id:
for name in out["sources"]:
if name in SURFACES:
try:
floors[name] = await floor_for(user_id, name)
except Exception: # pragma: no cover - telemetry never raises
logger.warning("could not read floor for %s", name, exc_info=True)
out["warnings"] = _compute_warnings(
out["sources"], usage, rule_usage, floors, min_calls, epsilon,
)
# "Active" means this window saw real traffic SOMEWHERE. Without that
# test, an install nobody has used reports every registered point as
# silent — thirty warnings describing an empty database (rule 115).
active = (
sum((b.get("calls") or 0) for b in out["sources"].values()) >= min_calls
or (usage.get("surfaced") or 0) > 0
)
out["silent_surfaces"] = _silent_surfaces(
out["sources"], usage, rule_usage, active,
)
return out