From e2c3a5c2b58167b588f1c9e200d82d797e3dd2fc Mon Sep 17 00:00:00 2001 From: Bryan Van Deusen Date: Sun, 20 Sep 2026 20:24:56 -0400 Subject: [PATCH] feat(telemetry): retrieval_telemetry says what is wrong (#3431) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit 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 Claude-Session: https://claude.ai/code/session_01821k5B3Ysecp9fNYs92Kuy --- src/scribe/mcp/tools/search.py | 47 ++++ src/scribe/services/retrieval_registry.py | 223 ++++++++++++++++ src/scribe/services/retrieval_telemetry.py | 284 +++++++++++++++++++++ tests/test_retrieval_registry.py | 181 +++++++++++++ tests/test_retrieval_warnings.py | 268 +++++++++++++++++++ 5 files changed, 1003 insertions(+) create mode 100644 src/scribe/services/retrieval_registry.py create mode 100644 tests/test_retrieval_registry.py create mode 100644 tests/test_retrieval_warnings.py diff --git a/src/scribe/mcp/tools/search.py b/src/scribe/mcp/tools/search.py index 1078637..517b6eb 100644 --- a/src/scribe/mcp/tools/search.py +++ b/src/scribe/mcp/tools/search.py @@ -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. diff --git a/src/scribe/services/retrieval_registry.py b/src/scribe/services/retrieval_registry.py new file mode 100644 index 0000000..5da53d7 --- /dev/null +++ b/src/scribe/services/retrieval_registry.py @@ -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 diff --git a/src/scribe/services/retrieval_telemetry.py b/src/scribe/services/retrieval_telemetry.py index f942329..bcf6233 100644 --- a/src/scribe/services/retrieval_telemetry.py +++ b/src/scribe/services/retrieval_telemetry.py @@ -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 diff --git a/tests/test_retrieval_registry.py b/tests/test_retrieval_registry.py new file mode 100644 index 0000000..9da0a80 --- /dev/null +++ b/tests/test_retrieval_registry.py @@ -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=)") + 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 diff --git a/tests/test_retrieval_warnings.py b/tests/test_retrieval_warnings.py new file mode 100644 index 0000000..e1d066b --- /dev/null +++ b/tests/test_retrieval_warnings.py @@ -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 -- 2.54.0