retrieval_telemetry says what is wrong (#3431) #172

Merged
bvandeusen merged 1 commits from dev into main 2026-09-20 21:03:53 -04:00
5 changed files with 1003 additions and 0 deletions
+47
View File
@@ -396,6 +396,53 @@ It is an UPPER BOUND per surface: a pull records the door it came
they are zeros meaning "could not find out", not "nothing happened" — do
not report a pull-through from a block carrying that flag.
`warnings` IS THE PART TO READ FIRST (#3431). Everything above is a
distribution; this is a verdict, and it exists because the same four
checks were being redone by hand on every reading and were easy to
forget. An EMPTY LIST means checked and clean — it is always present, so
its emptiness is an answer rather than a gap. Each entry carries the
numbers that triggered it, so you can disagree with the rule instead of
having to redo the arithmetic:
- `cannot_decline` — an arm that fires unasked answered every one of its
calls. It cannot say nothing, which means it is not applying a floor.
Only ever raised for unbidden arms known to log unconditionally: a
search returning a list every time is doing its job, and an arm whose
zeros were never written would flag a LOGGING bug while pointing you at
a threshold, which is #3497 exactly.
- `band_hugs_floor` — the weakest tenth of what an arm returns sits on
its floor. The bar is doing the selecting and the score is not, so
moving that floor changes how MUCH you get, not how good it is.
- `no_duration` — rows written without timings. A logging gap, not a slow
arm, and it devalues every other number from that source.
- `surfaced_never_pulled` — distinct records shown and never opened, per
corpus. Read their titles before touching a threshold: a record nobody
opens is usually one whose title does not say when it matters.
- `unregistered_source` — rows under a source missing from
`retrieval_registry`. Its numbers are real; no verdict could be
computed, because nothing says whether it was asked or fired unbidden.
`silent_surfaces` IS THE HALF THE ROWS CANNOT SHOW YOU. Every check above
reads rows, so an arm that produced none is invisible to all of them and
looks exactly like an arm that does not exist. This list is driven by the
declared registry instead: points expected to emit that emitted nothing.
Points that are legitimately quiet — the web-UI-only sources on an install
driven through MCP — are excluded by declaration rather than by silence,
so a justified quiet never reads as a gap. The list stays EMPTY on a
window with little traffic: on a fresh install every point is silent, and
reporting all of them would be describing the emptiness.
WARNINGS ARE COMPUTED OVER THE BLOCKS ABOVE, not over a second query, so
one can never disagree with the numbers printed beside it. A window whose
read failed produces none at all — a verdict over rows that did not load
would describe the outage while appearing to describe the system.
Two thresholds govern them, both settings so an install driven harder can
say so: `retrieval_warn_min_calls` (default 30) is how much traffic a
source needs before its silence means anything, and
`retrieval_warn_floor_epsilon` (default 0.02) is how close to the bar
counts as piled on it.
Scoped to your own telemetry — a retrieval log records what your agent
asked for, query text included, and is not a shared record kind.
+223
View File
@@ -0,0 +1,223 @@
"""Every point that retrieves or surfaces a record, declared (#3431, #3432).
WHY A DECLARED LIST WHEN THE ROWS ALREADY NAME THEIR SOURCE. Because the rows
can only describe arms that FIRED. A surface that emits nothing writes no row,
so it is indistinguishable from a surface that does not exist — and the two
call for opposite responses. `retrieval_telemetry` could report perfect health
for a window in which half the arms never ran. #3430 hit exactly this: its
"silent surface" finding could only be made by a human who happened to know
which arms were supposed to be there.
This module is that knowledge, written down. It carries the two facts the rows
structurally cannot:
* **asked or unbidden.** `mcp_search` returning nothing is a search with no
matches, which is its job. `auto_inject` returning nothing on every call
for a week is an arm that has lost the ability to speak. Same row shape,
opposite meanings, and only the caller's intent separates them.
* **expected to emit, or deliberately quiet with a reason.** A justified
silence must not read as a gap (#2475). `rest_*` sources fire only when a
person opens the web UI; on an install driven entirely through MCP their
absence is correct and permanent, and reporting it every window would
train the reader to ignore the list that also carries the real ones.
NOT `retrieval_surfaces.SURFACES`, and the distinction is deliberate rather
than duplication. That registry answers "what can be TUNED" — it carries a
floor key, a budget key and the measurement stamp behind their defaults, and
it deliberately EXCLUDES the reserved slots (`preference_slot`, `reuse_slot`,
`lesson_slot`) because a budget of 1 is their feature and exposing it would
invite setting it to 0. This registry answers "what can be MEASURED", and the
reserved slots belong in it precisely because they are judgeable without being
tunable. One is a control panel; the other is an inventory. A test asserts
every tunable surface also appears here, so the two cannot drift apart.
ADDING AN ARM MEANS ADDING A ROW HERE. `tests/test_retrieval_registry.py`
walks the call sites with the ast module and fails on a source it cannot find
below — deliberately not a grep, because two of the sources in this file
(`wide_net`, `report_preference`) reach their recorder as `source=SOURCE`
through a module constant and a grep for `source="` misses both. That is the
narrowing #3191 warns about, caught here in the act.
"""
from __future__ import annotations
from dataclasses import dataclass
# ── How a point is reached ────────────────────────────────────────────────
#
# UNBIDDEN: fires on its own, against a query the agent did not write — a
# prompt, a file being written, a command about to run. It interrupts, so it
# must be able to stay quiet, and a stream of empty calls is a real signal.
#
# ASKED: someone called a search and wants a ranked list. Returning nothing is
# an answer, not a failure, so "cannot decline" must never fire on these.
#
# AMBIENT: records travel with a reply that was going to be sent anyway (a
# project handshake, a planning read). Nothing was ranked and nothing was
# chosen, so score-shaped warnings do not apply.
#
# PULL: a reader opened a record. The terminal event of the whole system, and
# the numerator of pull-through.
UNBIDDEN = "unbidden"
ASKED = "asked"
AMBIENT = "ambient"
PULL = "pull"
@dataclass(frozen=True)
class Point:
"""One place a record reaches a reader."""
source: str
"""The telemetry `source` value. MUST equal the string the call site passes."""
kind: str
"""UNBIDDEN / ASKED / AMBIENT / PULL — see above."""
what: str
"""One line, for an agent reading a warning that names this source."""
expects_traffic: bool = True
"""Whether silence over an active window is worth reporting.
False means "this can be quiet forever and that is correct" — and then
`quiet_because` must say why, so a reader meets a decision rather than a
hole (#2475).
"""
quiet_because: str = ""
logs_unconditionally: bool = True
"""Whether this arm writes a row even when it returns NOTHING.
THE #3497 GUARD, and the reason this field is not merely documentation.
Both rule arms once logged only their hits, so their zero-result count was
structurally 0 — and a "cannot decline" warning computed over that would
have fired on a LOGGING BUG while reporting a ranking problem, sending the
reader to move a floor that was never involved. An arm whose logging has
not been confirmed unconditional is not eligible for that warning; it is
excluded from the check rather than trusted.
"""
def _p(source, kind, what, **kw) -> tuple[str, Point]:
return source, Point(source=source, kind=kind, what=what, **kw)
POINTS: dict[str, Point] = dict([
# ── Unbidden push arms ───────────────────────────────────────────────
_p("auto_inject", UNBIDDEN, "the notes menu offered at the prompt boundary"),
_p("write_path", UNBIDDEN, "prior art offered when a file is about to be written"),
_p("write_path_rule", UNBIDDEN, "rules that may govern the file being written"),
_p("pre_tool_rule", UNBIDDEN, "rules that may govern a command about to run"),
_p("prompt_rule", UNBIDDEN, "rules that may govern what the operator just asked"),
_p("preference_slot", UNBIDDEN,
"the one line reserved for a preference at the prompt boundary"),
_p("reuse_slot", UNBIDDEN, "the one line reserved for a reusable snippet"),
_p("lesson_slot", UNBIDDEN, "the one line reserved for a lesson"),
_p("report_preference", UNBIDDEN,
"the fixed question asked when a task finishes: how should this report read"),
# ── Asked: a caller wanted a ranked list ─────────────────────────────
_p("mcp_search", ASKED, "an agent called search"),
_p("wide_net", ASKED, "an agent asked what might apply, with no bar"),
_p("rest_search", ASKED, "the web UI searched", expects_traffic=False,
quiet_because="only fires when a person uses the web UI; an install "
"driven entirely through MCP is correctly silent here"),
_p("browse_search", ASKED, "the browse listing searched", expects_traffic=False,
quiet_because="same as rest_search — a human-only entry point"),
# ── Ambient: carried along with a reply already being sent ───────────
_p("enter_project", AMBIENT, "the project handshake"),
_p("process_skill_sync", AMBIENT, "stored Processes synced into skills"),
_p("start_planning", AMBIENT, "the rules listed when a plan is opened"),
_p("get_task", AMBIENT, "the rules listed beside a task"),
_p("get_project", AMBIENT, "the rules listed beside a project"),
_p("get_milestone", AMBIENT, "the rules listed beside a milestone"),
# ── The write-path menu's own arms ───────────────────────────────────
#
# These are NOT in retrieval_logs. The place arm carries no score and so
# has no row there at all (#2085) — before it was split out, the arm
# firing on the strongest possible claim, "there is already a canonical
# helper in this exact file", was the one arm nobody could measure.
_p("write_path_place", AMBIENT, "a snippet already placed in this very file"),
_p("write_path_semantic", AMBIENT, "prior art matched by meaning"),
_p("write_path_sync", AMBIENT,
"records that should be updated alongside this edit"),
# ── Pull: a reader opened the record ─────────────────────────────────
_p("mcp_get_note", PULL, "an agent opened a note"),
_p("mcp_get_task", PULL, "an agent opened a task"),
_p("mcp_get_snippet", PULL, "an agent opened a snippet"),
_p("mcp_get_process", PULL, "an agent opened a process"),
_p("mcp_get_lesson", PULL, "an agent opened a lesson"),
_p("mcp_get_rule", PULL, "an agent opened a rule"),
_p("rest_note", PULL, "a person opened a note", expects_traffic=False,
quiet_because="web UI only"),
_p("rest_task", PULL, "a person opened a task", expects_traffic=False,
quiet_because="web UI only"),
_p("rest_snippet", PULL, "a person opened a snippet", expects_traffic=False,
quiet_because="web UI only"),
_p("rest_lesson", PULL, "a person opened a lesson", expects_traffic=False,
quiet_because="web UI only"),
_p("rest_rule", PULL, "a person opened a rule", expects_traffic=False,
quiet_because="web UI only"),
])
# Call sites that pass `source` as a VARIABLE, and what they can pass.
#
# WHY THESE ARE DECLARED RATHER THAN RESOLVED. The registry test reads the
# call sites with `ast`, which settles a literal and a module constant but not
# a value that arrives through a parameter or a dict key. Rather than let
# those sites go unchecked — the silent half of a guard that appears to cover
# everything — they are named here, and the test FAILS if it meets an
# unresolved site that is not in this list.
#
# THE HONEST LIMIT, stated so nobody over-trusts this: the test pins the SITE,
# not the values. Adding a fourth arm inside `plugin_context`'s `by_arm` fan
# out would not fail here. What catches that is `assert_registered`, which the
# recorders call as the row is written.
# Keyed by the EXACT string the extractor produces, matched by equality rather
# than by prefix. A prefix match was the first spelling and it silently matched
# nothing, because the paths are relative to `src/` and so begin `scribe/` —
# every site sailed through a check that looked like it was running.
FAN_OUT_SITES: dict[str, tuple[str, ...]] = {
"scribe/services/plugin_context.py::record_surfaced(source=arm)": (
"write_path_place", "write_path_semantic", "write_path_sync",
),
"scribe/services/rulebooks.py::record_rule_surfaced(source=source)": (
"enter_project", "start_planning", "get_task", "get_project",
"get_milestone",
),
}
def get_point(source: str) -> Point | None:
"""The registered point for a source, or None if it is not declared."""
return POINTS.get(source)
def sources_expected_to_emit() -> list[str]:
"""Every point whose silence over an ACTIVE window is worth reporting."""
return [s for s, p in POINTS.items() if p.expects_traffic]
def is_registered(source: str) -> bool:
"""Is this source declared?
Read by the TELEMETRY READOUT, not by the recorders, and that placement is
the design rather than an accident of where it was easy. Validating at
write time would put a dict lookup on every retrieval to catch a mistake
that is only ever made once, when an arm is added — and it could not
raise anyway, because telemetry that breaks its caller is the worse bug
(`record_retrieval` is fire-and-forget for exactly that reason). So the
check sits where the cost is already paid and the reader is already
looking: a source that appears in the rows and not in this file comes back
as an `unregistered_source` warning.
That is what covers FAN_OUT_SITES above. The static test pins those sites
but not the values they can pass, so a fourth arm added inside one would
slip past it — and then show up here the first time it fires.
"""
return source in POINTS
+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
+181
View File
@@ -0,0 +1,181 @@
"""Every retrieval point is declared, derived from the CALL SITES (#3431).
WHY AST AND NOT GREP, demonstrated rather than asserted. Two of the sources in
this system reach their recorder as `source=SOURCE` through a module-level
constant — `wide_net` and `report_preference` — so a grep for `source="` finds
neither. A registry test built on that grep would pass while being blind to
two arms, which is the narrowing #3191 warns about: a check that looks
thorough and quietly covers less than it claims.
So the extractor below parses each module, resolves module-level string
constants, and reports anything it still cannot settle rather than dropping
it. `test_the_extractor_resolves_the_constant_sources` pins the specific case,
so that if someone later "simplifies" this to a text scan the suite says which
capability was lost instead of merely going red.
WHAT THIS CANNOT DO, stated because a guard trusted past its reach is worse
than none. Three call sites pass `source` as a variable — a loop variable over
a dict of write-path arms, and a forwarded parameter in `rules_payload`. The
values are not statically knowable without real dataflow analysis, so those
sites are DECLARED in `FAN_OUT_SITES` and this test pins the sites, not the
values. A fourth arm added inside one of them passes here. What catches that
is the `unregistered_source` warning, which fires the first time the arm
actually records anything.
"""
from __future__ import annotations
import ast
from pathlib import Path
from scribe.services.retrieval_registry import (
ASKED, FAN_OUT_SITES, POINTS, UNBIDDEN,
)
from scribe.services.retrieval_surfaces import SURFACES
SRC = Path(__file__).resolve().parents[1] / "src"
# The recorders, plus the one FORWARDER. `rules_payload` takes a `source` and
# passes it to `record_rule_surfaced` on its caller's behalf (snippet #2858),
# so its callers are the real declaration site and a scan of recorders alone
# would miss every ambient rule surfacing.
RECORDERS = {
"record_retrieval", "record_surfaced", "record_pulled",
"record_rule_surfaced", "record_rule_pulled", "rules_payload",
}
def _module_constants(tree: ast.Module) -> dict[str, str]:
"""Module-level NAME = "literal", so `source=SOURCE` resolves."""
out: dict[str, str] = {}
for node in tree.body:
if isinstance(node, ast.Assign) and isinstance(node.value, ast.Constant) \
and isinstance(node.value.value, str):
for t in node.targets:
if isinstance(t, ast.Name):
out[t.id] = node.value.value
return out
def call_sites() -> tuple[dict[str, set[str]], list[str]]:
"""Every `source=` reaching a recorder: resolved, and what could not be."""
found: dict[str, set[str]] = {}
unresolved: list[str] = []
for path in sorted(SRC.rglob("*.py")):
tree = ast.parse(path.read_text(encoding="utf-8"), filename=str(path))
consts = _module_constants(tree)
rel = path.relative_to(SRC).as_posix()
for node in ast.walk(tree):
if not isinstance(node, ast.Call):
continue
fn = node.func
name = fn.attr if isinstance(fn, ast.Attribute) else getattr(fn, "id", None)
if name not in RECORDERS:
continue
kw = next((k for k in node.keywords if k.arg == "source"), None)
if kw is None:
continue # a recorder called without one is a different bug
v = kw.value
if isinstance(v, ast.Constant) and isinstance(v.value, str):
found.setdefault(v.value, set()).add(rel)
elif isinstance(v, ast.Name) and v.id in consts:
found.setdefault(consts[v.id], set()).add(rel)
elif isinstance(v, ast.Name):
unresolved.append(f"{rel}::{name}(source={v.id})")
else:
unresolved.append(f"{rel}::{name}(source=<expression>)")
return found, unresolved
def test_the_extractor_finds_something() -> None:
"""The guard has to be able to fail (rule 167).
An extractor that silently matched nothing would make every assertion
below vacuously true — a green suite proving the opposite of what it
claims.
"""
found, _ = call_sites()
assert len(found) >= 20, f"suspiciously few call sites found: {sorted(found)}"
def test_the_extractor_resolves_the_constant_sources() -> None:
"""The specific capability a grep would lose. See the module docstring."""
found, _ = call_sites()
for via_constant in ("wide_net", "report_preference"):
assert via_constant in found, (
f"{via_constant} reaches its recorder through a module constant; "
f"an extractor that cannot resolve one is blind to it"
)
def test_every_call_site_source_is_registered() -> None:
"""The point of the file: adding an arm means declaring it."""
found, _ = call_sites()
missing = {s: sorted(found[s]) for s in found if s not in POINTS}
assert not missing, (
"these sources record telemetry but are not in "
f"retrieval_registry.POINTS: {missing}"
)
def test_every_unresolved_call_site_is_declared() -> None:
"""A site passing a variable must be named, not silently skipped."""
_, unresolved = call_sites()
# EQUALITY, not prefix. The first spelling of this compared against a
# prefix that could never match — the paths begin `scribe/` — so the check
# passed by matching nothing, which is the failure mode a guard is most
# likely to have and least likely to show (rule 167).
undeclared = sorted({u for u in unresolved if u not in FAN_OUT_SITES})
assert not undeclared, (
"these call sites pass `source` as a value this test cannot resolve, "
"and are not declared in FAN_OUT_SITES: " + repr(undeclared)
)
def test_the_declared_fan_out_values_are_registered() -> None:
"""The sites are unresolvable; the values they claim to pass are not."""
for site, sources in FAN_OUT_SITES.items():
for s in sources:
assert s in POINTS, f"{site} claims to emit {s!r}, which is not registered"
def test_every_tunable_surface_is_also_a_registered_point() -> None:
"""The two registries answer different questions and must not drift.
`SURFACES` is what can be TUNED, `POINTS` is what can be MEASURED. A
surface with a floor dial and no entry here would be adjustable and
unjudgeable at the same time.
"""
missing = [s for s in SURFACES if s not in POINTS]
assert not missing, f"tunable but unregistered: {missing}"
def test_a_quiet_point_says_why() -> None:
"""A justified silence must carry its justification (#2475).
Without the reason the reader cannot tell a decision from an oversight,
which is the whole difference this field exists to record.
"""
silent_without_reason = [
s for s, p in POINTS.items() if not p.expects_traffic and not p.quiet_because
]
assert not silent_without_reason, silent_without_reason
def test_every_point_declares_a_known_kind() -> None:
from scribe.services.retrieval_registry import AMBIENT, PULL
for s, p in POINTS.items():
assert p.kind in {UNBIDDEN, ASKED, AMBIENT, PULL}, (s, p.kind)
def test_the_reserved_slots_are_measurable_even_though_they_are_not_tunable() -> None:
"""The case that motivated a second registry rather than reusing SURFACES.
A budget of 1 is the reserved slots' feature, so they are deliberately
absent from the tuning registry — but "never places a hit" is exactly the
kind of thing this readout exists to notice.
"""
for slot in ("preference_slot", "reuse_slot", "lesson_slot"):
assert slot not in SURFACES, f"{slot} became tunable; re-read the decision"
assert slot in POINTS
assert POINTS[slot].kind == UNBIDDEN
+268
View File
@@ -0,0 +1,268 @@
"""`retrieval_telemetry` says what is wrong, rather than implying it (#3431).
WHY THIS IS TESTED AS ARITHMETIC AND NOT THROUGH THE DATABASE. The warnings
are a pure function of the blocks the readout already built — that is the
design, so a verdict can never disagree with the numbers printed beside it —
and the risk in them is not whether rows load. It is whether a rule fires on
the wrong shape. Every case below is a shape that once produced, or would
produce, a wrong reading:
* an arm that never declines, which is either a missing floor or a missing
LOG (#3497 — the rule arms recorded only their hits, so their decline
count was structurally zero and the obvious warning would have sent a
reader to move a threshold that was never involved);
* a search that never declines, which is a search working correctly;
* a quiet window, where firing every check would describe an empty database
rather than a broken one (rule 115);
* a floor the band is sitting on, which is the case where tuning changes
volume while looking like it changes quality.
The ε and N boundaries are tested from BOTH sides. A threshold asserted only
where it fires is half-tested: the expensive failure here is a false positive,
because a readout that cries wolf is one nobody reads.
"""
from __future__ import annotations
import pytest
from scribe.services.retrieval_telemetry import (
WARN_FLOOR_EPSILON_DEFAULT, WARN_MIN_CALLS_DEFAULT,
_compute_warnings, _num, _silent_surfaces,
)
N = WARN_MIN_CALLS_DEFAULT
EPS = WARN_FLOOR_EPSILON_DEFAULT
def src(**kw) -> dict:
"""One source block, shaped like the readout builds it."""
b = {
"calls": kw.pop("calls", 0),
"zero_result_calls": kw.pop("zero_result_calls", 0),
"top_score": {"p10": kw.pop("p10", None), "p50": None, "p90": None,
"min": None, "max": None},
"avg_result_count": None,
"p90_duration_ms": kw.pop("p90_duration_ms", 12.0),
}
b.update(kw)
return b
def warn(sources, usage=None, rule_usage=None, floors=None,
min_calls=N, epsilon=EPS) -> list[dict]:
return _compute_warnings(
sources, usage or {}, rule_usage or {}, floors or {}, min_calls, epsilon,
)
def codes(ws, source=None) -> set[str]:
return {w["code"] for w in ws if source is None or w["source"] == source}
# ── cannot_decline ────────────────────────────────────────────────────────
def test_an_unbidden_arm_that_never_declines_is_flagged() -> None:
ws = warn({"auto_inject": src(calls=300, zero_result_calls=0)})
assert "cannot_decline" in codes(ws, "auto_inject")
def test_the_warning_carries_the_numbers_that_produced_it() -> None:
"""Not "check auto_inject" — that is an instruction to redo the analysis."""
w = next(w for w in warn({"auto_inject": src(calls=300)})
if w["code"] == "cannot_decline")
assert w["numbers"] == {"calls": 300, "zero_result_calls": 0}
assert "300" in w["detail"]
def test_a_quiet_window_flags_nothing() -> None:
"""Three calls returning nothing is an afternoon, not a defect (rule 115)."""
assert codes(warn({"auto_inject": src(calls=3, zero_result_calls=0)})) == set()
def test_the_call_count_boundary_holds_on_both_sides() -> None:
assert "cannot_decline" not in codes(warn({"auto_inject": src(calls=N - 1)}))
assert "cannot_decline" in codes(warn({"auto_inject": src(calls=N)}))
def test_an_asked_surface_is_never_flagged_for_not_declining() -> None:
"""A search returning a list every time is a search doing its job."""
for asked in ("mcp_search", "wide_net", "rest_search", "browse_search"):
assert "cannot_decline" not in codes(
warn({asked: src(calls=500, zero_result_calls=0)}), asked)
def test_an_arm_that_does_decline_is_not_flagged() -> None:
ws = warn({"auto_inject": src(calls=300, zero_result_calls=1)})
assert "cannot_decline" not in codes(ws)
def test_an_arm_not_known_to_log_unconditionally_is_exempt(monkeypatch) -> None:
"""#3497: a structurally-zero decline count is a logging bug, not a floor.
Flagging it would report a ranking problem and send the reader to a
threshold that was never involved.
"""
from dataclasses import replace
from scribe.services import retrieval_registry as reg
patched = dict(reg.POINTS)
patched["auto_inject"] = replace(patched["auto_inject"],
logs_unconditionally=False)
monkeypatch.setattr(reg, "POINTS", patched)
assert "cannot_decline" not in codes(
warn({"auto_inject": src(calls=300, zero_result_calls=0)}))
# ── band_hugs_floor ───────────────────────────────────────────────────────
def test_a_band_sitting_on_its_floor_is_flagged() -> None:
ws = warn({"auto_inject": src(calls=100, zero_result_calls=5, p10=0.705)},
floors={"auto_inject": 0.70})
assert "band_hugs_floor" in codes(ws, "auto_inject")
def test_a_band_clear_of_its_floor_is_not() -> None:
ws = warn({"auto_inject": src(calls=100, zero_result_calls=5, p10=0.80)},
floors={"auto_inject": 0.70})
assert "band_hugs_floor" not in codes(ws)
@pytest.mark.parametrize("gap,flagged", [
(EPS / 2, True), # inside
(EPS, False), # exactly at the boundary is NOT "hugging"
(EPS * 2, False), # clear
])
def test_the_epsilon_boundary_holds_on_both_sides(gap, flagged) -> None:
ws = warn({"auto_inject": src(calls=100, zero_result_calls=5,
p10=round(0.70 + gap, 6))},
floors={"auto_inject": 0.70})
assert ("band_hugs_floor" in codes(ws)) is flagged
def test_an_arm_with_no_readable_floor_is_not_guessed_at() -> None:
"""Reserved slots borrow a parent's floor; naming it here would attribute
the parent's setting to a child that has no dial of its own."""
ws = warn({"preference_slot": src(calls=100, zero_result_calls=5, p10=0.7001)},
floors={})
assert "band_hugs_floor" not in codes(ws)
# ── no_duration ───────────────────────────────────────────────────────────
def test_rows_without_timings_are_a_logging_gap() -> None:
ws = warn({"auto_inject": src(calls=1, zero_result_calls=1,
p90_duration_ms=None)})
assert "no_duration" in codes(ws)
def test_one_untimed_call_is_already_the_defect() -> None:
"""No minimum on this one — unlike the others, it is not about volume."""
ws = warn({"auto_inject": src(calls=1, p90_duration_ms=None)})
assert "no_duration" in codes(ws)
assert "cannot_decline" not in codes(ws), "volume rules still need volume"
def test_a_source_with_no_calls_reports_no_timing_gap() -> None:
assert "no_duration" not in codes(warn({"auto_inject": src(calls=0)}))
# ── surfaced_never_pulled ─────────────────────────────────────────────────
def test_records_shown_and_never_opened_are_reported_per_corpus() -> None:
ws = warn(
{},
usage={"distinct_notes_surfaced": 171, "distinct_notes_pulled": 40},
rule_usage={"distinct_rules_surfaced": 69, "distinct_rules_pulled": 11},
)
found = {w["numbers"]["corpus"]: w["numbers"]
for w in ws if w["code"] == "surfaced_never_pulled"}
assert found["notes"]["never_pulled"] == 131
assert found["rules"]["never_pulled"] == 58
def test_everything_opened_reports_nothing() -> None:
ws = warn({}, usage={"distinct_notes_surfaced": 5, "distinct_notes_pulled": 5})
assert "surfaced_never_pulled" not in codes(ws)
def test_an_empty_corpus_reports_nothing_rather_than_zero() -> None:
ws = warn({}, usage={"distinct_notes_surfaced": 0, "distinct_notes_pulled": 0})
assert "surfaced_never_pulled" not in codes(ws)
# ── unregistered_source ───────────────────────────────────────────────────
def test_a_source_missing_from_the_registry_is_reported() -> None:
"""The check that covers what the static test cannot reach — a source
arriving through a parameter or a dict key."""
ws = warn({"a_fourth_write_path_arm": src(calls=50)})
assert codes(ws, "a_fourth_write_path_arm") == {"unregistered_source"}
def test_an_unregistered_source_gets_no_other_verdict() -> None:
"""Its numbers are real, but nothing says whether it was asked."""
ws = warn({"mystery": src(calls=500, zero_result_calls=0)})
assert "cannot_decline" not in codes(ws)
def test_every_registered_source_stays_quiet_when_healthy() -> None:
"""The negative control for the whole suite (rule 167).
A guard that cannot pass cleanly is not a guard — if a healthy window
produced warnings, every assertion above would be meaningless.
"""
from scribe.services.retrieval_registry import POINTS
healthy = {s: src(calls=100, zero_result_calls=40, p10=0.90)
for s in POINTS}
assert warn(healthy, floors={s: 0.70 for s in POINTS}) == []
# ── silent surfaces ───────────────────────────────────────────────────────
def test_a_registered_point_with_no_rows_is_reported() -> None:
quiet = _silent_surfaces({"auto_inject": src(calls=100)}, {}, {}, active=True)
assert "prompt_rule" in {p["source"] for p in quiet}
def test_a_point_that_emitted_is_not_reported() -> None:
quiet = _silent_surfaces({"auto_inject": src(calls=100)}, {}, {}, active=True)
assert "auto_inject" not in {p["source"] for p in quiet}
def test_a_deliberately_quiet_point_is_never_reported() -> None:
"""A justified silence must not read as a gap (#2475)."""
quiet = {p["source"] for p in _silent_surfaces({}, {}, {}, active=True)}
for web_only in ("rest_search", "browse_search", "rest_note", "rest_rule"):
assert web_only not in quiet
def test_an_inactive_window_reports_no_silence_at_all() -> None:
"""On a fresh install every point is silent; the list would be the
registry printed back (rule 115)."""
assert _silent_surfaces({}, {}, {}, active=False) == []
def test_a_point_seen_only_in_usage_counts_as_having_emitted() -> None:
"""The write-path arms and the pull sources never reach `sources` — they
live in note_usage_events — so reading only retrieval_logs would report
every one of them as silent."""
quiet = {p["source"] for p in _silent_surfaces(
{}, {"by_source": {"write_path_place": {}}},
{"by_source": {"enter_project": {}}}, active=True)}
assert "write_path_place" not in quiet
assert "enter_project" not in quiet
# ── settings parsing ──────────────────────────────────────────────────────
@pytest.mark.parametrize("raw,fallback,want", [
("50", 30, 50),
("0.05", 0.02, 0.05),
("", 30, 30),
("banana", 30, 30), # a malformed setting must not take the readout down
(None, 0.02, 0.02),
])
def test_a_setting_falls_back_rather_than_raising(raw, fallback, want) -> None:
assert _num(raw, fallback) == want