bvandeusenandClaude Opus 5.5
9909cd2450
CI & Build / Python lint (push) Successful in 4s
CI & Build / Plugin hooks (push) Successful in 15s
CI & Build / TypeScript typecheck (push) Successful in 54s
CI & Build / integration (push) Successful in 1m7s
CI & Build / Python tests (push) Successful in 1m55s
CI & Build / Build & push image (push) Successful in 26s
#4798 "The rules corpus's surfaced_never_pulled warning sends the reader to menus_to_review, which can only review auto_inject". #4772 gave the warning one remedy for both corpora: "judge a sample with menus_to_review". That is right for notes, where a line carries its passage. For rules it is a dead end: retrieval_review.REVIEWABLE holds only auto_inject, so the tool refuses every rule arm. - The reading is now per corpus (_NEVER_PULLED_READING). For rules, the text says: - the count includes rules that only arrived in a listing; - a rule can rightly be set aside on its trigger alone; - no judged sample exists for the rule arms; - a rule set aside again and again is a trigger to fix (update_rule when_to_apply, then what_might_apply), not a floor. - The tool docstring says the same. - The guard is tied to REVIEWABLE, so it can fail in both directions: if the rules text names menus_to_review while no rule arm is reviewable, or if a rule arm becomes reviewable and the text still says there is no sample. Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>
1681 lines
83 KiB
Python
1681 lines
83 KiB
Python
"""Retrieval telemetry — one RetrievalLog row per semantic-retrieval call.
|
|
|
|
This is the empirical basis for KB-injection tuning: it records what each query
|
|
asked for, the score distribution of what came back, and the effective params,
|
|
so the similarity threshold and top-k can be tuned from data rather than guessed.
|
|
|
|
Design notes:
|
|
- Fire-and-forget, mirroring upsert_note_embedding: `record_retrieval` extracts
|
|
the primitives it needs SYNCHRONOUSLY (while the caller's Note objects are
|
|
still valid) and schedules the DB insert as a background task, so logging
|
|
never adds latency to — or can break — the search response.
|
|
- Result objects are reduced to {id, score, rank} before scheduling; the
|
|
background writer touches only plain data, never a possibly-detached ORM row.
|
|
- Every failure path is swallowed: telemetry must never take down retrieval.
|
|
"""
|
|
from __future__ import annotations
|
|
|
|
import asyncio
|
|
import logging
|
|
import re
|
|
from typing import Any
|
|
|
|
from datetime import datetime, timedelta, timezone
|
|
|
|
from sqlalchemy import case, func, select
|
|
|
|
from scribe.models import async_session
|
|
from scribe.models.base import iso
|
|
from scribe.models.note import Note
|
|
from scribe.models.note_usage import PULLED, SURFACED, NoteUsageEvent
|
|
from scribe.models.rule_usage import OUTCOMES as RULE_OUTCOMES
|
|
from scribe.models.rule_usage import APPLIED as RULE_APPLIED
|
|
from scribe.models.rule_usage import DEPARTED as RULE_DEPARTED
|
|
from scribe.models.rule_usage import PULLED as RULE_PULLED
|
|
from scribe.models.rule_usage import SURFACED as RULE_SURFACED
|
|
from scribe.models.rule_usage import RuleUsageEvent
|
|
from scribe.models.system import System
|
|
from scribe.models.system_usage import PULLED as SYSTEM_PULLED
|
|
from scribe.models.system_usage import SURFACED as SYSTEM_SURFACED
|
|
from scribe.models.system_usage import SystemUsageEvent
|
|
from scribe.services.rule_usage import is_ambient
|
|
from scribe.models.retrieval_log import RetrievalLog
|
|
from scribe.services.retrieval_review import judged_block
|
|
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.retrieval_tuning import floor_history_gaps, floor_moves_since
|
|
from scribe.services.settings import get_setting
|
|
|
|
logger = logging.getLogger(__name__)
|
|
|
|
# Strong references to in-flight inserts — the loop holds tasks only weakly,
|
|
# and an unreferenced fire-and-forget task can be collected before it runs
|
|
# (same guard as note_usage, found via #2663).
|
|
_pending: set[asyncio.Task] = set()
|
|
|
|
# Whether this process already dropped its one warning about failing writes.
|
|
_reported = False
|
|
|
|
|
|
|
|
# ── secrets never reach the query column (#3925) ───────────────────────
|
|
#
|
|
# `pre_tool_rule` retrieves against the RAW COMMAND TEXT and `write_path_rule`
|
|
# against the code being written, so whatever was on the command line or in the
|
|
# buffer is what gets logged. A command that exports a token therefore stored
|
|
# the token — and worse than stored it: `near_miss_samples` is the readout the
|
|
# threshold docs tell you to open before moving a bar, so the value came back
|
|
# out into an agent's context on the next tuning pass. That is how this was
|
|
# found.
|
|
#
|
|
# SCRUBBED ON WRITE, NOT ON READ. A read-side filter leaves the secret in the
|
|
# table, where a backup, a debug query or a future readout still reaches it.
|
|
# The value must never land.
|
|
#
|
|
# REDACTED VISIBLY, AND THIS IS THE PART THAT KEEPS THE READOUT HONEST. The
|
|
# whole worth of a near-miss sample is reading the query that was actually
|
|
# refused; a scrubber that silently deleted spans would turn the one instrument
|
|
# for tuning a bar into unreadable stubs — the #2663 shape, where a surface
|
|
# looks fine and has quietly stopped saying anything. A `[redacted:<kind>]`
|
|
# marker keeps the sentence readable, keeps its shape and length roughly
|
|
# intact for the ranker's reader, and says plainly that something was removed.
|
|
#
|
|
# DELIBERATELY CONSERVATIVE. These patterns match things that are secrets by
|
|
# CONSTRUCTION — a vendor-prefixed credential, a value assigned to a
|
|
# secret-named variable, an auth header, a PEM header. Anything cleverer
|
|
# (entropy heuristics, long-opaque-string detection) starts eating real
|
|
# queries, and a query is evidence. Missing an exotic secret costs one
|
|
# redaction nobody made; eating a query costs the ability to tune the bar.
|
|
_SECRET_PATTERNS: tuple[tuple[str, "re.Pattern[str]"], ...] = (
|
|
# Vendor-prefixed credentials. The prefix IS the tell, so no entropy
|
|
# guessing is needed — `fmcp_` is Scribe's own API key format.
|
|
("token", re.compile(
|
|
r"\b(?:fmcp_|flt_|ghp_|gho_|ghs_|ghu_|github_pat_|glpat-|gitlab-ci-token:"
|
|
r"|xox[abprs]-|sk-[A-Za-z0-9]*-?|AKIA|ASIA)[A-Za-z0-9_\-]{12,}"
|
|
)),
|
|
# A value handed to a secret-NAMED variable, in shell, env files, YAML,
|
|
# JSON or a query string. The name is what identifies it, so the value can
|
|
# be anything.
|
|
("assigned", re.compile(
|
|
r"(?i)\b([A-Za-z0-9_]*"
|
|
# NO BARE "auth" HERE. It matched `--author=`, so a commit naming an
|
|
# address redacted the address — evidence eaten for a word that only
|
|
# LOOKS credential-shaped. `AUTH_TOKEN` is still caught, by `token`.
|
|
r"(?:token|secret|password|passwd|api[_-]?key|access[_-]?key)"
|
|
r"[A-Za-z0-9_]*)"
|
|
r"(\s*[:=]\s*[\"']?)"
|
|
r"([^\s\"'&]{8,})"
|
|
)),
|
|
("auth-header", re.compile(
|
|
r"(?i)(authorization\s*:\s*(?:bearer|basic|token)\s+)(\S+)"
|
|
)),
|
|
("private-key", re.compile(
|
|
r"-----BEGIN [A-Z ]*PRIVATE KEY-----[\s\S]*?-----END [A-Z ]*PRIVATE KEY-----"
|
|
)),
|
|
)
|
|
|
|
|
|
def scrub_secrets(text: str | None) -> str | None:
|
|
"""Redact credential-shaped spans from a query before it is stored.
|
|
|
|
Pure and synchronous, so it is unit-testable and safe to run inline on the
|
|
write path. Returns the input unchanged when nothing matches, which is the
|
|
overwhelmingly common case and the one the patterns are tuned to protect.
|
|
"""
|
|
if not text:
|
|
return text
|
|
for kind, pattern in _SECRET_PATTERNS:
|
|
if kind == "assigned":
|
|
text = pattern.sub(
|
|
lambda m: f"{m.group(1)}{m.group(2)}[redacted:{kind}]", text)
|
|
elif kind == "auth-header":
|
|
text = pattern.sub(lambda m: f"{m.group(1)}[redacted:{kind}]", text)
|
|
else:
|
|
text = pattern.sub(f"[redacted:{kind}]", text)
|
|
return text
|
|
|
|
|
|
def _build_payload(
|
|
*,
|
|
user_id: int | None,
|
|
source: str,
|
|
query: str | None,
|
|
threshold: float | None,
|
|
limit: int | None,
|
|
project_id: int | None,
|
|
is_task: bool | None,
|
|
results: list[tuple[float, Note]],
|
|
duration_ms: float | None,
|
|
suppressed: int | None = None,
|
|
best_available: float | None = None,
|
|
best_available_id: int | None = None,
|
|
) -> dict:
|
|
"""Reduce a retrieval call to a flat, JSON-safe RetrievalLog payload.
|
|
|
|
Pure and synchronous (no DB, no event loop) so it is unit-testable and safe
|
|
to run inline before scheduling the write. `results` is the
|
|
`(score, Note)` list from semantic_search_notes, already highest-first.
|
|
|
|
`suppressed` is how many scored hits the caller dropped because the session
|
|
had already been shown them, and it stays None for callers that cannot
|
|
know. See the column's comment: None means "not measured here", which is a
|
|
different fact from 0 and must never render as one.
|
|
|
|
`best_available` is the highest score the ranker reached BEFORE the
|
|
threshold, and it carries the same null discipline for a sharper reason: it
|
|
is the only field that still says something on a call that returned
|
|
nothing, so a 0.0 standing in for "not measured" would read as "the corpus
|
|
held nothing remotely relevant" — a claim about the corpus invented out of
|
|
a caller's silence.
|
|
"""
|
|
items = [
|
|
{"id": int(note.id), "score": round(float(score), 5), "rank": rank}
|
|
for rank, (score, note) in enumerate(results)
|
|
]
|
|
scores = [it["score"] for it in items]
|
|
return {
|
|
"user_id": user_id,
|
|
"source": source,
|
|
# Scrubbed HERE rather than at each caller: this is the only path to
|
|
# the column, and a per-caller scrub is three places for one of them
|
|
# to be forgotten by whoever adds the fourth arm.
|
|
"query": scrub_secrets(query),
|
|
"threshold": threshold,
|
|
"limit_n": limit,
|
|
"project_id": project_id,
|
|
"is_task": is_task,
|
|
"result_count": len(items),
|
|
"suppressed_count": (None if suppressed is None else int(suppressed)),
|
|
"top_score": (scores[0] if scores else None),
|
|
"min_score": (scores[-1] if scores else None),
|
|
"best_available_score": (
|
|
None if best_available is None else round(float(best_available), 5)
|
|
),
|
|
# The record that scored it, so a reader can go and look (#3807).
|
|
"best_available_id": (
|
|
None if best_available_id is None else int(best_available_id)
|
|
),
|
|
"result_ids": items,
|
|
"duration_ms": (round(duration_ms, 2) if duration_ms is not None else None),
|
|
}
|
|
|
|
|
|
async def _insert_retrieval_log(payload: dict) -> None:
|
|
"""Persist one RetrievalLog row. Best-effort: failures degrade, visibly.
|
|
|
|
WARNING rather than debug — this table is the empirical basis for threshold
|
|
tuning, and a silent write outage yields a dataset that looks complete while
|
|
covering only part of the traffic (#2663's shape). Once per process is
|
|
enough to be found; per-call would flood the log with what it already said.
|
|
"""
|
|
global _reported
|
|
try:
|
|
async with async_session() as session:
|
|
session.add(RetrievalLog(**payload))
|
|
await session.commit()
|
|
except Exception:
|
|
if not _reported:
|
|
_reported = True
|
|
logger.warning("retrieval telemetry write failed", exc_info=True)
|
|
else:
|
|
logger.debug("retrieval telemetry write skipped", exc_info=True)
|
|
|
|
|
|
def record_retrieval(
|
|
*,
|
|
user_id: int | None,
|
|
source: str,
|
|
query: str | None,
|
|
threshold: float | None,
|
|
limit: int | None,
|
|
project_id: int | None,
|
|
is_task: bool | None,
|
|
results: list[tuple[float, Any]],
|
|
duration_ms: float | None = None,
|
|
suppressed: int | None = None,
|
|
best_available: float | None = None,
|
|
best_available_id: int | None = None,
|
|
searched: bool = True,
|
|
) -> None:
|
|
"""Fire-and-forget: record one retrieval call.
|
|
|
|
`results` needs only `.id` on each record, which is why it is not typed to
|
|
Note: rules are retrieved too (milestone 307) and land here rather than in
|
|
note_usage_events. That table's ids are REMAPPED on a backup restore, so a
|
|
rule id written into it would come back attached to whatever note happened
|
|
to take that number — silent corruption of the very evidence this exists to
|
|
provide. retrieval_logs is not restored at all, so it has no such hazard,
|
|
and `source` already distinguishes the surfaces.
|
|
|
|
`searched=False` WRITES NO ROW, and that is the point rather than an
|
|
optimisation. A semantic search has three ways to return nothing without
|
|
having run — an empty query, an unavailable embedder, and the broad
|
|
`except` around the query itself — and each one currently arrives here
|
|
looking exactly like a ranker that declined. Logging it would report a
|
|
decline nobody made, drag `zero_result_calls` down with phantom evidence
|
|
about a threshold, and leave `best_available_score` null for a reason that
|
|
has nothing to do with the corpus. That last ambiguity is #3765: the field
|
|
added to judge a bar was null on four unrelated causes, one of them a
|
|
swallowed failure, and no reader could tell them apart.
|
|
Dropping the row is what makes the remaining nulls mean ONE thing —
|
|
"searched, and there was nothing".
|
|
|
|
The same convention already governs the pre-tool arm: a blank command costs
|
|
no embedding query, so it writes no row, because "a row here would report a
|
|
call that never happened and drag the clear-rate down with phantom
|
|
declines". This extends it from a case the caller could see in advance to
|
|
the ones only the search knows about.
|
|
|
|
A FAILURE IS NOT MADE INVISIBLE BY THIS. `semantic_search_notes` logs a
|
|
WARNING on a query failure, which is where a broken search belongs — a
|
|
counter cannot say "I am broken" without a reader already trusting it.
|
|
|
|
Builds the payload inline (synchronously) then schedules the insert so the
|
|
caller returns immediately. Never raises — telemetry must not affect search.
|
|
"""
|
|
if not searched:
|
|
return
|
|
|
|
try:
|
|
payload = _build_payload(
|
|
user_id=user_id,
|
|
source=source,
|
|
query=query,
|
|
threshold=threshold,
|
|
limit=limit,
|
|
project_id=project_id,
|
|
is_task=is_task,
|
|
results=results,
|
|
duration_ms=duration_ms,
|
|
suppressed=suppressed,
|
|
best_available=best_available,
|
|
best_available_id=best_available_id,
|
|
)
|
|
except Exception:
|
|
logger.debug("retrieval telemetry payload build failed", exc_info=True)
|
|
return
|
|
|
|
try:
|
|
task = asyncio.get_running_loop().create_task(_insert_retrieval_log(payload))
|
|
except RuntimeError:
|
|
# No running loop (e.g. called from sync context outside the app) —
|
|
# skip rather than block. The app paths always run on the loop.
|
|
logger.debug("retrieval telemetry skipped — no running event loop")
|
|
return
|
|
_pending.add(task)
|
|
task.add_done_callback(_pending.discard)
|
|
|
|
|
|
# --- The read half (#2975) ---------------------------------------------------
|
|
# Until this existed, `retrieval_logs` was WRITE-ONLY: rows accrued and the only
|
|
# `select()` over them in the whole tree lived in a test. That made #1038's gate
|
|
# — "build the reranker once telemetry shows precision is the bottleneck" —
|
|
# unsatisfiable by construction, and it is why the one real tuning decision on
|
|
# record (the 0.68 write-path threshold, #2223) was reached by hand-probing the
|
|
# live instance with eight payloads instead of by reading what was collected.
|
|
|
|
def _bucket(rows: list) -> dict:
|
|
"""A score readout a human can act on, from one aggregate row."""
|
|
(calls, zero, p10, p50, p90, lo, hi, avg_n, dur,
|
|
measured, supp_calls, supp_zero,
|
|
miss_calls, miss_p50, miss_p90, miss_max) = rows
|
|
return {
|
|
"calls": int(calls or 0),
|
|
# A call that returned nothing is not a low-scoring call — it is a
|
|
# different failure (nothing indexed, filter too narrow), and averaging
|
|
# it into the score distribution would hide both.
|
|
"zero_result_calls": int(zero or 0),
|
|
# `cleared_threshold` USED TO LIVE HERE and it was a tautology (#3670).
|
|
# The search applies the bar before returning, so every returned result
|
|
# cleared it by construction and a call with nothing has no score to
|
|
# compare — the condition was true exactly when `result_count > 0`.
|
|
# `zero_result_calls + cleared_threshold == calls` held on all nineteen
|
|
# readings ever taken. It was `calls - zero_result_calls` wearing a name
|
|
# that promised a second opinion, and the docstring built a reading
|
|
# procedure on it that asked the reader to compare a number with itself.
|
|
# Its replacement is `near_misses` below, which the bar cannot fix by
|
|
# construction because it is measured on the calls the bar REJECTED.
|
|
# Of the zeros above, which were the RANKER declining and which were
|
|
# the reader having seen it already? `zero_result_calls` cannot say,
|
|
# and only the first kind is evidence about the threshold.
|
|
#
|
|
# None — not a zeroed dict — when no row in the window reported it. A
|
|
# surface that filters inside the search genuinely does not know, and
|
|
# rendering that as `{"calls": 0}` would state a measurement nobody
|
|
# made. That substitution is the whole of #3311.
|
|
"suppression": (
|
|
None if not int(measured or 0) else {
|
|
"measured_calls": int(measured or 0),
|
|
"calls_with_suppression": int(supp_calls or 0),
|
|
# Subtract from zero_result_calls for the true ranker declines.
|
|
"zero_because_already_shown": int(supp_zero or 0),
|
|
}
|
|
),
|
|
"top_score": {
|
|
"p10": _round(p10), "p50": _round(p50), "p90": _round(p90),
|
|
"min": _round(lo), "max": _round(hi),
|
|
},
|
|
# WHAT THE BAR TURNED AWAY, and the only figure here a threshold can
|
|
# actually be tuned from. Measured over the calls that returned
|
|
# NOTHING, on the best score the ranker reached before the filter.
|
|
#
|
|
# Read `p90` against the threshold in force. A bar at 0.72 rejecting a
|
|
# stream of 0.71s is set too high by a hair and the surface is losing
|
|
# hits it should have had; the same bar rejecting 0.30s is doing its
|
|
# job and the corpus simply had nothing. Both render as a zero-result
|
|
# call, and nothing else in this readout separates them.
|
|
#
|
|
# None — not a zeroed block — when no declining call in the window
|
|
# measured it. Old rows predate the column, and a 0.0 would assert that
|
|
# the corpus held nothing relevant, which is a claim about the corpus
|
|
# invented out of a caller's silence.
|
|
"near_misses": (
|
|
None if not int(miss_calls or 0) else {
|
|
"measured_calls": int(miss_calls or 0),
|
|
"p50": _round(miss_p50),
|
|
"p90": _round(miss_p90),
|
|
"max": _round(miss_max),
|
|
}
|
|
),
|
|
"avg_result_count": _round(avg_n),
|
|
"p90_duration_ms": _round(dur, 1),
|
|
}
|
|
|
|
|
|
# The aggregate row Postgres would have returned for a source with no rows in
|
|
# the window: nothing counted, nothing scored. Positional, matching the SELECT
|
|
# `_bucket` unpacks — calls, zero, p10, p50, p90, min, max, avg_n,
|
|
# dur, measured, supp_calls, supp_zero, miss_calls, miss_p50, miss_p90,
|
|
# miss_max. The counts are 0 because zero calls is a real observation;
|
|
# everything else is None because a distribution nobody sampled has no value,
|
|
# and rendering it as 0.0 would state one.
|
|
_NO_ROWS_IN_WINDOW = [0, 0, None, None, None, None, None, None, None,
|
|
0, 0, 0, 0, None, None, None]
|
|
|
|
|
|
def _round(v, places: int = 4):
|
|
return None if v is None else round(float(v), places)
|
|
|
|
|
|
async def _complete_from(session, model, user_id) -> dict[str, Any]:
|
|
"""When each source in `model` started being recorded, and the instant the
|
|
WHOLE table is complete from. Returns {source: earliest_row, "*": latest}.
|
|
|
|
THE GRAIN IS THE SOURCE, and that is the whole point. `retrieval_logs` has
|
|
rows going back months, so a table-level "earliest row" says months and
|
|
tells a reader their window is fully covered — while a source added last
|
|
week has a week of rows and a counter that silently means something else.
|
|
Per-source is the only grain at which partial coverage is visible.
|
|
|
|
THE AGGREGATE USES THE LATEST, NOT THE EARLIEST. A number that sums several
|
|
sources is complete only once EVERY contributor was recording, so "*" is a
|
|
max over the sources, not a min. Taking the min here would reproduce the
|
|
exact reading this exists to prevent: the oldest source vouching for the
|
|
youngest.
|
|
|
|
All-time, deliberately unfiltered by the window — a query bounded by
|
|
`since` can only ever report something at or after `since`, which answers
|
|
nothing.
|
|
"""
|
|
rows = (
|
|
await session.execute(
|
|
select(model.source, func.min(model.created_at))
|
|
.where(model.user_id == user_id)
|
|
.group_by(model.source)
|
|
)
|
|
).all()
|
|
out: dict[str, Any] = {src: ts for src, ts in rows if ts is not None}
|
|
stamps = list(out.values())
|
|
out["*"] = max(stamps) if stamps else None
|
|
return out
|
|
|
|
|
|
def _coverage(complete_from, since) -> dict:
|
|
"""The two keys every counter block carries, from one timestamp.
|
|
|
|
`covers_window` is None — never False — when nothing was ever recorded.
|
|
"No rows at all" is not "partial coverage", it is no measurement, and the
|
|
null convention #3497 established for `suppression` holds here for the
|
|
same reason: absent must not read as a verdict.
|
|
"""
|
|
return {
|
|
# iso() already returns None for an unset value (#2845) — the guard
|
|
# belongs on covers_window, which is a verdict, not a serialisation.
|
|
"complete_from": iso(complete_from),
|
|
"covers_window": (
|
|
None if complete_from is None else complete_from <= since
|
|
),
|
|
}
|
|
|
|
|
|
# ── 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
|
|
|
|
|
|
# What "surfaced and never opened" can and cannot mean, per corpus, and where
|
|
# to look next. ONE SENTENCE PER CORPUS because the two lines are built
|
|
# differently (#4798): a note line carries its matched passage, so an unopened
|
|
# note may have done its job, and the judged sample is the instrument that can
|
|
# tell. A rule line carries only its trigger and asks to be opened, and no
|
|
# judged sample covers the rule arms (`retrieval_review.REVIEWABLE`), so
|
|
# sending that reader to `menus_to_review` sent them to a refusal.
|
|
_NEVER_PULLED_READING = {
|
|
"notes": (
|
|
"That is not a verdict on them: a line carries its matched passage, "
|
|
"so an unopened record may have been unrelated, enough as shown, or "
|
|
"already in context. Before acting on it — a title, a floor, a "
|
|
"budget — judge a sample with `menus_to_review` and read the "
|
|
"`judged` block."
|
|
),
|
|
"rules": (
|
|
"Not a verdict either, and read differently from notes: the count "
|
|
"includes rules that only arrived in a listing (the project "
|
|
"handshake, a planning read), and a rule line shows its trigger, so a "
|
|
"session can rightly set one aside on the trigger alone. There is no "
|
|
"judged sample for the rule arms. A rule set aside again and again "
|
|
"where it does not apply is a trigger to fix, not a floor to move — "
|
|
"`update_rule(when_to_apply=...)`, then `what_might_apply` with the "
|
|
"moment's own words to see where it ranks."
|
|
),
|
|
}
|
|
|
|
|
|
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,
|
|
floor_moves: dict | None = None,
|
|
floor_gaps: dict | None = None) -> 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.
|
|
#
|
|
# FOUR NOW. A FIXED-QUERY arm is exempt for the same reason one step
|
|
# over (#4232): it scores against one constant, so its decline rate is
|
|
# 0% or 100% and never in between, and which one it is depends only on
|
|
# where the bar sits relative to that single number. "Never returned
|
|
# nothing" is then not evidence about the floor — it is arithmetic —
|
|
# and this warning's own remedy, "check that it applies its floor",
|
|
# cannot be answered from it. Those arms get `fixed_query_never_clears`
|
|
# below, which asks the question that IS answerable for them.
|
|
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
|
|
and not point.fixed_query
|
|
):
|
|
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,
|
|
))
|
|
|
|
# ── A fixed-query arm that never clears its bar ──────────────────
|
|
#
|
|
# The mirror image of `cannot_decline`, and the state that actually
|
|
# threatens these arms. `reply_preferences` names it in its own
|
|
# docstring: "a fixed query makes this arm's score a constant and a
|
|
# floor a hair above it produces a dead arm no amount of traffic will
|
|
# ever reveal."
|
|
#
|
|
# For an arm whose score can vary, a window of all-empty calls is
|
|
# ordinary — it means nothing matched, which is an answer. For one
|
|
# whose score is a constant it means the bar is above that constant,
|
|
# and no volume of further calls will ever produce a different result.
|
|
# The arm is not quiet; it is switched off, and nothing else in this
|
|
# readout would say so.
|
|
#
|
|
# It has happened: `report_preference` logged 69 consecutive declines
|
|
# at 0.0006 under the bar. Note what that incident also proves — the
|
|
# fix is NOT automatically to lower the floor. Reading the refused
|
|
# record showed the refusal was correct, so this warning sends the
|
|
# reader to `near_miss_samples` rather than to the dial.
|
|
if (
|
|
calls >= min_calls
|
|
and point is not None
|
|
and point.fixed_query
|
|
and point.logs_unconditionally
|
|
and (b.get("zero_result_calls") or 0) == calls
|
|
):
|
|
out.append(_warn(
|
|
"fixed_query_never_clears",
|
|
f"{calls} calls, every one of them empty — and this arm always "
|
|
f"searches the same query, so its score is a constant. That "
|
|
f"means the bar sits above it and no amount of further traffic "
|
|
f"will change the result: the arm is off, not quiet. Read the "
|
|
f"record it refused (`near_miss_samples`) before touching the "
|
|
f"floor — the last time this arm sat here, every percentile "
|
|
f"said lower it and the refused record showed the refusal was "
|
|
f"right.",
|
|
source=name, calls=calls, zero_result_calls=calls,
|
|
))
|
|
|
|
# ── 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")
|
|
moved = (floor_moves or {}).get(name)
|
|
gaps = floor_gaps or {}
|
|
if calls >= min_calls and floor is not None and p10 is not None:
|
|
# ── The floor moved inside the window ────────────────────────
|
|
#
|
|
# THE CHECK IS SUSPENDED, NOT SOFTENED, and this is the whole of
|
|
# #4225. `band_hugs_floor` asks whether the scores are piled on
|
|
# the bar. That question needs the scores and the bar to come from
|
|
# the same regime; across a floor change they do not, and the
|
|
# comparison quietly becomes one between two populations.
|
|
#
|
|
# It announced itself when the change was a RAISE: p10 computed
|
|
# over calls made under the old, lower bar came out BELOW today's
|
|
# floor, and the warning reported a band "-0.0216 above" its
|
|
# floor. A negative distance above something is not a number
|
|
# anybody can act on. A LOWERED floor hides better — the gap comes
|
|
# out comfortably positive and reads as a clean bill of health on
|
|
# a sample that half predates the bar being judged.
|
|
#
|
|
# So the honest move is to say the sample cannot answer, and say
|
|
# when it will be able to, rather than print a figure with an
|
|
# asterisk. A reader who is told a number is unavailable goes and
|
|
# gets one; a reader handed a qualified number uses it.
|
|
if moved is not None:
|
|
out.append(_warn(
|
|
"floor_moved_mid_window",
|
|
f"this arm's floor changed at {moved}, inside the window, "
|
|
f"so its calls were made under two different bars and its "
|
|
f"band cannot be compared against the floor now in force "
|
|
f"({floor}). The band check is suspended for this arm "
|
|
f"until the window clears that date — ask again with a "
|
|
f"`days` that starts after it, or wait.",
|
|
source=name, floor=floor, p10=p10, moved_at=moved,
|
|
))
|
|
# ── The ledger does not reach back this far ──────────────────
|
|
#
|
|
# The same suspension, for the case the one above cannot see. The
|
|
# check overhead asks `floor_moves_since` whether this arm's floor
|
|
# moved, and reads an empty answer as "it held steady". That
|
|
# reading is only sound where the ledger was WATCHING; before its
|
|
# first row for this arm, "no move recorded" and "no move" are
|
|
# different statements, and the first was standing in for the
|
|
# second.
|
|
#
|
|
# Not theoretical, and not a one-off: every install passes
|
|
# through it. A window longer than the install is old reaches back
|
|
# past the ledger's first row, and the symptom is the same
|
|
# impossible negative the comment above describes — printed with
|
|
# the suspension silent, because there was nothing on record for
|
|
# it to notice.
|
|
#
|
|
# Deliberately ordered after the known move: when both apply, the
|
|
# arm that has a date to give should give it.
|
|
elif name in gaps:
|
|
known_from = gaps[name]
|
|
out.append(_warn(
|
|
"floor_history_unknown",
|
|
(
|
|
f"this arm's floor has been recorded since "
|
|
f"{known_from}, which is after this window opens, so "
|
|
f"whether it moved earlier in the window is not known "
|
|
f"— and an unrecorded move is exactly what makes a "
|
|
f"band reading meaningless. The band check is "
|
|
f"suspended for this arm until the window starts at "
|
|
f"or after that date: ask again with a smaller `days`, "
|
|
f"or wait."
|
|
if known_from else
|
|
f"this arm has no floor history at all, so there is "
|
|
f"nothing to say whether its floor of {floor} is the "
|
|
f"one its calls were made under. The band check is "
|
|
f"suspended for this arm until a floor is recorded for "
|
|
f"it — moving it once with `tune_retrieval`, or the "
|
|
f"next release baseline, starts the record."
|
|
),
|
|
source=name, floor=floor, p10=p10, known_from=known_from,
|
|
))
|
|
elif p10 - floor < epsilon:
|
|
gap = p10 - floor
|
|
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. It used to say a record shown repeatedly
|
|
# and never opened is "badly titled or genuinely irrelevant" — true when a
|
|
# line was a title, and not since it carries the passage (#4364): the
|
|
# record may have done its job unopened. So it now points at the judged
|
|
# sample rather than at a cause (#4772).
|
|
#
|
|
# 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. {_NEVER_PULLED_READING[label]}",
|
|
source=None, corpus=label,
|
|
surfaced=int(shown), pulled=int(pulled or 0), never_pulled=never,
|
|
))
|
|
|
|
# ── A rule that was read and changed nothing (#4213, milestone 419) ──
|
|
#
|
|
# The failure this milestone was opened on, and the one number that could
|
|
# not previously be computed. `surfaced_never_pulled` above catches a rule
|
|
# nobody opens; this catches the worse case — a rule the agent DID open,
|
|
# deliberately, and then left no trace of having acted on. Until #4212
|
|
# those were arithmetically identical to compliance.
|
|
opened = int(rule_usage.get("distinct_rules_pulled") or 0)
|
|
acted = int(rule_usage.get("distinct_rules_acted") or 0)
|
|
applied = int(rule_usage.get("applied") or 0)
|
|
departed = int(rule_usage.get("departed") or 0)
|
|
|
|
if opened and not (applied or departed):
|
|
# THE HONEST ANSWER WHILE THE INSTRUMENT IS COLD, and the reason this
|
|
# is a separate code rather than a zero fed into the check below.
|
|
# Outcomes only started being recorded in milestone 419; a window
|
|
# containing none cannot tell "every rule was ignored" from "nothing
|
|
# reports outcomes yet". Emitting the ignored-rules warning here would
|
|
# manufacture a finding out of an unwired feature — #3311's mistake
|
|
# exactly, where a statistic that could not vary was read as a fact
|
|
# about the corpus.
|
|
out.append(_warn(
|
|
"outcomes_never_recorded",
|
|
f"{opened} distinct rules were opened in this window and not one "
|
|
f"recorded an outcome. This does NOT mean they were ignored — it "
|
|
f"means nothing is calling `rule_outcome`, so the difference "
|
|
f"between a rule that worked and a rule that was read and "
|
|
f"forgotten is still unmeasured here.",
|
|
source=None, opened=opened, applied=0, departed=0,
|
|
))
|
|
elif opened:
|
|
unacted = opened - acted
|
|
if unacted > 0:
|
|
out.append(_warn(
|
|
"read_and_unacted",
|
|
f"{unacted} of {opened} distinct rules were opened in this "
|
|
f"window and left no outcome, against {acted} that did. A rule "
|
|
f"read and silently unchanged looks exactly like one that "
|
|
f"worked; these are the ones where nobody can tell. Either the "
|
|
f"rule is mis-triggering — it arrives, gets read, and does not "
|
|
f"apply — or it is being ignored, and the two want opposite "
|
|
f"fixes.",
|
|
source=None, opened=opened, acted=acted, unacted=unacted,
|
|
applied=applied, departed=departed,
|
|
))
|
|
|
|
return out
|
|
|
|
|
|
def _silent_surfaces(sources: dict, usage: dict, rule_usage: dict,
|
|
active: bool, system_usage: dict | None = None) -> 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 {}))
|
|
seen |= set(((system_usage or {}).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
|
|
]
|
|
|
|
|
|
# How many Systems `by_system` lists. A readout of which AREAS' rulings are
|
|
# reaching sessions, not an export: an install with more ruled areas than this
|
|
# reads the rest from the per-System counts on the Systems list.
|
|
SYSTEM_USAGE_TOP = 20
|
|
|
|
|
|
async def _system_usage(user_id: int | None, since) -> dict:
|
|
"""The rulings arm's own block (#4769): were an area's rulings shown, and
|
|
was the area then opened.
|
|
|
|
FROM `system_usage_events`, IN ITS OWN SESSION AND ITS OWN GUARD, for the
|
|
reason the rule block is guarded apart: a failure here must not take down
|
|
the readouts beside it, and must say so rather than print zeros (#2663) —
|
|
the keys are kept and `system_usage_failed` is added.
|
|
|
|
NO PULL-THROUGH, and the omission is the design. The note and rule ratios
|
|
ask "was the hint any use" of a line that carries a TITLE, where opening
|
|
the record is how it gets read. A rulings line carries the rulings
|
|
themselves; the agent reads them without opening anything, and
|
|
`get_system` is reached for only when a long list was cut ("+N more").
|
|
A ratio here would read near zero on an arm that is working, and invite
|
|
the dead-weight verdict the per-record badges give — the wrong conclusion,
|
|
built from a true number. The counts are printed side by side instead.
|
|
|
|
`by_system` names the areas, because "rulings were shown 40 times" says
|
|
nothing a reader can act on, and "Billing, 38 of them" does.
|
|
Ordered by surfacings, then by name, so a stable window reads stably.
|
|
"""
|
|
block: dict = {
|
|
"surfaced": 0,
|
|
"pulled": 0,
|
|
"distinct_systems_surfaced": 0,
|
|
"distinct_systems_pulled": 0,
|
|
"by_source": {},
|
|
"by_system": [],
|
|
}
|
|
try:
|
|
async with async_session() as session:
|
|
where = (
|
|
SystemUsageEvent.created_at >= since,
|
|
SystemUsageEvent.user_id == user_id,
|
|
)
|
|
per_source = (
|
|
await session.execute(
|
|
select(
|
|
SystemUsageEvent.event,
|
|
SystemUsageEvent.source,
|
|
func.count().label("n"),
|
|
)
|
|
.where(*where)
|
|
.group_by(SystemUsageEvent.event, SystemUsageEvent.source)
|
|
)
|
|
).all()
|
|
per_system = (
|
|
await session.execute(
|
|
select(
|
|
SystemUsageEvent.system_id,
|
|
System.name,
|
|
SystemUsageEvent.event,
|
|
func.count().label("n"),
|
|
func.max(SystemUsageEvent.created_at).label("last_at"),
|
|
)
|
|
# Outer: telemetry outlives the row it describes, and a
|
|
# deleted System's surfacings still happened.
|
|
.outerjoin(System, System.id == SystemUsageEvent.system_id)
|
|
.where(*where)
|
|
.group_by(
|
|
SystemUsageEvent.system_id, System.name,
|
|
SystemUsageEvent.event,
|
|
)
|
|
)
|
|
).all()
|
|
complete = await _complete_from(session, SystemUsageEvent, user_id)
|
|
except Exception:
|
|
logger.warning("system usage read failed", exc_info=True)
|
|
block["system_usage_failed"] = True
|
|
return block
|
|
|
|
for event, source, n in per_source:
|
|
n = int(n)
|
|
key = "surfaced" if event == SYSTEM_SURFACED else (
|
|
"pulled" if event == SYSTEM_PULLED else None)
|
|
if key is None:
|
|
continue
|
|
block[key] += n
|
|
block["by_source"][source] = block["by_source"].get(source, 0) + n
|
|
|
|
systems: dict[int, dict] = {}
|
|
for system_id, name, event, n, last_at in per_system:
|
|
row = systems.setdefault(int(system_id), {
|
|
"system_id": int(system_id),
|
|
"name": name,
|
|
"surfaced": 0,
|
|
"pulled": 0,
|
|
"last_surfaced_at": None,
|
|
})
|
|
if event == SYSTEM_SURFACED:
|
|
row["surfaced"] += int(n)
|
|
row["last_surfaced_at"] = iso(last_at)
|
|
elif event == SYSTEM_PULLED:
|
|
row["pulled"] += int(n)
|
|
block["distinct_systems_surfaced"] = sum(1 for r in systems.values() if r["surfaced"])
|
|
block["distinct_systems_pulled"] = sum(1 for r in systems.values() if r["pulled"])
|
|
block["by_system"] = sorted(
|
|
(r for r in systems.values() if r["surfaced"]),
|
|
key=lambda r: (-r["surfaced"], r["name"] or ""),
|
|
)[:SYSTEM_USAGE_TOP]
|
|
block.update(_coverage(complete.get("*"), since))
|
|
return block
|
|
|
|
|
|
async def retrieval_summary(
|
|
user_id: int | None, *, days: int = 30, near_miss_samples: int = 0,
|
|
) -> dict:
|
|
"""What the retrieval telemetry says, per surface, over a window.
|
|
|
|
Three aggregates side by side, each read from the table built for it — NOT
|
|
a join. `usage` is notes, `rule_usage` is rules, and they stay apart
|
|
because a few dozen eligible rules blended into thousands of notes is the
|
|
note ratio with noise on it (milestone 333). `NoteUsageEvent`'s own docstring is explicit that the two are
|
|
complements ("RetrievalLog tunes the threshold, this tunes the corpus") and
|
|
that RetrievalLog's JSONB `result_ids` "can't be indexed at" the per-note
|
|
grain. So the score distribution comes from `retrieval_logs` on its indexed
|
|
columns, and surfaced-vs-pulled comes from `note_usage_events` at the grain
|
|
it was built for. Reading each from its own table is both cheaper and more
|
|
honest than correlating them through JSONB.
|
|
|
|
`usage["by_source"]` is the one join, and it stays INSIDE
|
|
`note_usage_events` — surfaced rows against pulled rows on note_id. That
|
|
answers "of the notes this surface chose, how many were opened", which the
|
|
top-level ratio averages away. It does not cross into `retrieval_logs`, so
|
|
the sentence above still holds.
|
|
|
|
Scoped to one user's own telemetry. There is no sharing model for a
|
|
retrieval log — it records what THIS user's agent asked for, including the
|
|
query text — so an owner filter is the whole access rule here rather than a
|
|
shortcut around `services/access.py` (P#78 governs shared record kinds).
|
|
|
|
Never raises: a telemetry readout that can break its caller is worse than
|
|
no readout. It does distinguish "no rows" from "the read failed", because
|
|
#2663 is exactly the bug where those two looked identical for weeks.
|
|
"""
|
|
since = datetime.now(timezone.utc) - timedelta(days=max(1, int(days)))
|
|
out: dict = {
|
|
"window_days": int(days),
|
|
"since": iso(since),
|
|
"sources": {},
|
|
"usage": {},
|
|
"rule_usage": {},
|
|
"system_usage": {},
|
|
"judged": {},
|
|
"read_failed": False,
|
|
}
|
|
|
|
zero = case((RetrievalLog.result_count == 0, 1), else_=0)
|
|
# THE NEAR-MISS POPULATION: calls that returned nothing BECAUSE THE BAR
|
|
# TURNED SOMETHING AWAY, and recorded what it was. Three conditions, and
|
|
# the third was missing for one deploy (#3739).
|
|
#
|
|
# Zero-result only: on a call that returned something,
|
|
# `best_available_score` equals `top_score` and adds nothing.
|
|
#
|
|
# Non-null only: rows written before #3670 genuinely do not know, and must
|
|
# not read as scoreless declines.
|
|
#
|
|
# AND NOT A REPEAT. A zero-result call is two unrelated events — the ranker
|
|
# found nothing above the bar, or it found only what this session had
|
|
# already been shown — and just the first says anything about the bar. That
|
|
# is the whole of #3497, and #3670 reintroduced the conflation one level up:
|
|
# the rule arms filter exclusions in PYTHON, after the search, so a rule
|
|
# that cleared the bar and was dropped as a repeat still reported a high
|
|
# `best_available_score` on a zero-result row. Live proof, first read after
|
|
# deploy: pre_tool_rule's near-miss max was 0.7457 while the lowest score it
|
|
# ever RETURNED was 0.7204 — a "rejection" that outscored acceptances.
|
|
#
|
|
# The NULL arm is principled, not permissive: `suppressed_count IS NULL`
|
|
# means the caller passed its exclusions INTO the search, which is exactly
|
|
# the case where the reported score is already post-exclusion and cannot be
|
|
# contaminated. Note arms stay measured; rule arms get cleaned.
|
|
#
|
|
# Deliberately conservative: a call carrying both a repeat and a lower
|
|
# genuine miss is dropped whole, losing that point. It undercounts; it
|
|
# cannot corrupt — the right way round for a number read against a bar.
|
|
#
|
|
# This also makes `near_misses.max < threshold` true BY CONSTRUCTION. An
|
|
# above-bar candidate that was not excluded would have been returned, so
|
|
# its call is not in this population at all.
|
|
declined = (
|
|
(RetrievalLog.result_count == 0)
|
|
& (RetrievalLog.best_available_score.isnot(None))
|
|
& (
|
|
RetrievalLog.suppressed_count.is_(None)
|
|
| (RetrievalLog.suppressed_count == 0)
|
|
)
|
|
)
|
|
miss = case((declined, 1), else_=0)
|
|
# `best_available_score` only for those rows; NULL elsewhere, and
|
|
# percentile_cont ignores NULLs, so the distribution is over the declines
|
|
# alone without a second pass over the table.
|
|
miss_score = case((declined, RetrievalLog.best_available_score), else_=None)
|
|
# Three sums rather than one, because "not measured" and "measured as zero"
|
|
# are different answers and a single counter cannot hold both.
|
|
measured = case((RetrievalLog.suppressed_count.isnot(None), 1), else_=0)
|
|
supp_calls = case((RetrievalLog.suppressed_count > 0, 1), else_=0)
|
|
supp_zero = case(
|
|
((RetrievalLog.result_count == 0) & (RetrievalLog.suppressed_count > 0), 1),
|
|
else_=0,
|
|
)
|
|
|
|
def pct(p: float):
|
|
return func.percentile_cont(p).within_group(RetrievalLog.top_score.asc())
|
|
|
|
# Assigned inside the try below; named here so the readout can tell
|
|
# "this query failed" from "this window has no rows" (#2663).
|
|
by_source_rows = None
|
|
rule_rows = None
|
|
distinct_rules_surfaced = distinct_rules_pulled = 0
|
|
# None means the coverage read did not happen — distinct from a table with
|
|
# no rows, which is {"*": None}. Same reason `read_failed` exists.
|
|
note_complete = rule_complete = None
|
|
|
|
try:
|
|
async with async_session() as session:
|
|
rows = (
|
|
await session.execute(
|
|
select(
|
|
RetrievalLog.source,
|
|
func.count().label("calls"),
|
|
func.sum(zero).label("zero"),
|
|
pct(0.1), pct(0.5), pct(0.9),
|
|
func.min(RetrievalLog.top_score),
|
|
func.max(RetrievalLog.top_score),
|
|
func.avg(RetrievalLog.result_count),
|
|
func.percentile_cont(0.9).within_group(
|
|
RetrievalLog.duration_ms.asc()
|
|
),
|
|
func.sum(measured).label("measured"),
|
|
func.sum(supp_calls).label("supp_calls"),
|
|
func.sum(supp_zero).label("supp_zero"),
|
|
func.sum(miss).label("miss_calls"),
|
|
func.percentile_cont(0.5).within_group(miss_score.asc()),
|
|
func.percentile_cont(0.9).within_group(miss_score.asc()),
|
|
func.max(miss_score),
|
|
)
|
|
.where(
|
|
RetrievalLog.created_at >= since,
|
|
RetrievalLog.user_id == user_id,
|
|
)
|
|
.group_by(RetrievalLog.source)
|
|
)
|
|
).all()
|
|
log_complete = await _complete_from(session, RetrievalLog, user_id)
|
|
for row in rows:
|
|
source = row[0]
|
|
bucket = _bucket(list(row[1:]))
|
|
# Per SOURCE, not per table: retrieval_logs goes back months
|
|
# while any individual arm may be days old, and the table's
|
|
# age would vouch for an arm that has barely started.
|
|
bucket.update(_coverage(log_complete.get(source), since))
|
|
out["sources"][source] = bucket
|
|
|
|
# A source with rows in the table but NONE in this window would
|
|
# otherwise be absent from the readout — and absent is exactly how
|
|
# a source that never existed renders, so a surface that WAS
|
|
# recording and went silent is unreadable (#3720). That is #2663
|
|
# one level up: the failure that looks like the correct answer.
|
|
#
|
|
# Zero here is a real measurement, not a manufactured one. The
|
|
# all-time query proves the source was recording, and it made no
|
|
# calls across a window it fully covers — which is why no
|
|
# `covers_window` special case is needed: a source whose first row
|
|
# fell after `since` would have that row IN the window and already
|
|
# hold a bucket, so anything reaching here began before it.
|
|
for src, first_row in log_complete.items():
|
|
if src == "*" or first_row is None or src in out["sources"]:
|
|
continue
|
|
quiet = _bucket(list(_NO_ROWS_IN_WINDOW))
|
|
quiet.update(_coverage(first_row, since))
|
|
out["sources"][src] = quiet
|
|
|
|
# WHAT THE BAR REFUSED, by name (#3807). Opt-in, because it is a
|
|
# LISTING and not a statistic: an id cannot be percentiled, and a
|
|
# reader tuning a threshold needs to go and read the records rather
|
|
# than see another number about them. Off by default so the
|
|
# ordinary readout keeps its size.
|
|
#
|
|
# Deliberately NOT a window function. This module's one production
|
|
# outage (#2663) was a grouped query the database rejected, swallowed
|
|
# by the broad except, every counter reading zero while the mocked
|
|
# tests passed — and the lesson recorded then was to group on a raw
|
|
# column and classify in Python rather than push cleverness into the
|
|
# SQL. So: one flat ordered query, overfetched, bucketed here.
|
|
if near_miss_samples > 0:
|
|
want = max(1, min(int(near_miss_samples), 20))
|
|
rows = (
|
|
await session.execute(
|
|
select(
|
|
RetrievalLog.source,
|
|
RetrievalLog.best_available_score,
|
|
RetrievalLog.best_available_id,
|
|
RetrievalLog.query,
|
|
)
|
|
.where(
|
|
declined,
|
|
RetrievalLog.created_at >= since,
|
|
RetrievalLog.user_id == user_id,
|
|
RetrievalLog.best_available_id.isnot(None),
|
|
)
|
|
.order_by(RetrievalLog.best_available_score.desc())
|
|
# Overfetch so every source can fill its own quota even
|
|
# when one of them holds all the highest scores.
|
|
.limit(want * 40)
|
|
)
|
|
).all()
|
|
for src, score, rec_id, q in rows:
|
|
bucket = out["sources"].get(src)
|
|
if bucket is None:
|
|
continue
|
|
samples = bucket.setdefault("near_miss_records", [])
|
|
if len(samples) >= want:
|
|
continue
|
|
samples.append({
|
|
"score": _round(score),
|
|
"record_id": int(rec_id),
|
|
# Enough to recognise the ask, not the whole prompt.
|
|
"query": (q or "")[:120],
|
|
})
|
|
|
|
# The corpus side, at its own grain. `ambient` mirrors
|
|
# note_usage.usage_for_notes: an ambient surfacing was not a scored
|
|
# CHOICE, so folding it into pull-through would understate it.
|
|
# Grouped by RAW source, then classified in Python. The
|
|
# alternative — CASE expressions in the GROUP BY — is the shape
|
|
# that produced #2663: a second case() renders its own expanding
|
|
# bind names, the database sees two different expressions and
|
|
# rejects the query, and the broad except swallows it. One CASE is
|
|
# provably fine (usage_for_notes does it); two is where it broke.
|
|
# `source` has a handful of distinct values, so grouping on it
|
|
# directly is cheap and cannot fail that way at all.
|
|
urows = (
|
|
await session.execute(
|
|
select(
|
|
NoteUsageEvent.event,
|
|
NoteUsageEvent.source,
|
|
func.count().label("n"),
|
|
)
|
|
.where(
|
|
NoteUsageEvent.created_at >= since,
|
|
NoteUsageEvent.user_id == user_id,
|
|
)
|
|
.group_by(NoteUsageEvent.event, NoteUsageEvent.source)
|
|
)
|
|
).all()
|
|
note_complete = await _complete_from(session, NoteUsageEvent, user_id)
|
|
|
|
# Distinct-note counts need their OWN queries, and this is not
|
|
# fussiness: count(distinct note_id) per (event, source) group
|
|
# cannot be summed across groups — a note surfaced by two sources
|
|
# is one distinct note and would be counted twice. A wrong number
|
|
# labelled "distinct" is worse than no number.
|
|
from scribe.services.note_usage import AMBIENT_SOURCES as _AMB
|
|
|
|
distinct_surfaced = (
|
|
await session.execute(
|
|
select(func.count(func.distinct(NoteUsageEvent.note_id))).where(
|
|
NoteUsageEvent.created_at >= since,
|
|
NoteUsageEvent.user_id == user_id,
|
|
NoteUsageEvent.event == SURFACED,
|
|
NoteUsageEvent.source.notin_(_AMB),
|
|
)
|
|
)
|
|
).scalar_one()
|
|
distinct_pulled = (
|
|
await session.execute(
|
|
select(func.count(func.distinct(NoteUsageEvent.note_id))).where(
|
|
NoteUsageEvent.created_at >= since,
|
|
NoteUsageEvent.user_id == user_id,
|
|
NoteUsageEvent.event == PULLED,
|
|
)
|
|
)
|
|
).scalar_one()
|
|
|
|
# Per-source pull-through, at the NOTE grain (#3311).
|
|
#
|
|
# The `urows` query above already groups by source and the loop
|
|
# below then throws the source away, so until now this readout
|
|
# could say what the corpus's overall pull-through was and nothing
|
|
# about WHICH surface earned it. The data was always here; only
|
|
# the aggregation discarded it.
|
|
#
|
|
# It cannot be had by grouping the PULLED rows by source: a pull
|
|
# records the door it came through (`mcp_get_note`), not the
|
|
# surface that put the record in front of the agent. Correlating
|
|
# those within a session is what #2085 ruled out — there is no
|
|
# session identity server-side and inventing one would mean
|
|
# threading a client-supplied token through every read path. The
|
|
# note grain answers the question without one: of the distinct
|
|
# notes surface X chose, how many did an agent open in this window?
|
|
#
|
|
# Guarded separately from the reads above, on #2663's actual
|
|
# lesson. That outage was a NOVEL SQL SHAPE the database rejected
|
|
# inside a broad except. This join is the novel shape here, and a
|
|
# failure in it must not take down two readouts that already work.
|
|
try:
|
|
pulled_ids = (
|
|
select(NoteUsageEvent.note_id)
|
|
.where(
|
|
NoteUsageEvent.created_at >= since,
|
|
NoteUsageEvent.user_id == user_id,
|
|
NoteUsageEvent.event == PULLED,
|
|
# autoescape because `_` is a LIKE wildcard: a bare
|
|
# like("mcp_%") also matches "mcpX…". The Python half
|
|
# of this readout uses str.startswith and has no such
|
|
# hazard; this is the SQL half's version of it.
|
|
NoteUsageEvent.source.startswith("mcp_", autoescape=True),
|
|
)
|
|
.distinct()
|
|
.subquery()
|
|
)
|
|
surfaced_pairs = (
|
|
select(NoteUsageEvent.source, NoteUsageEvent.note_id)
|
|
.where(
|
|
NoteUsageEvent.created_at >= since,
|
|
NoteUsageEvent.user_id == user_id,
|
|
NoteUsageEvent.event == SURFACED,
|
|
)
|
|
.distinct()
|
|
.subquery()
|
|
)
|
|
# DISTINCT on (source, note_id) FIRST, which is what lets the
|
|
# outer aggregate be a plain count(): the pairs are already
|
|
# unique, so the left join cannot multiply them and no
|
|
# count(DISTINCT) is needed to undo damage that never happens.
|
|
by_source_rows = (
|
|
await session.execute(
|
|
select(
|
|
surfaced_pairs.c.source,
|
|
func.count().label("notes_surfaced"),
|
|
func.count(pulled_ids.c.note_id).label("notes_pulled"),
|
|
)
|
|
.select_from(
|
|
surfaced_pairs.outerjoin(
|
|
pulled_ids,
|
|
pulled_ids.c.note_id == surfaced_pairs.c.note_id,
|
|
)
|
|
)
|
|
.group_by(surfaced_pairs.c.source)
|
|
)
|
|
).all()
|
|
except Exception:
|
|
logger.warning("per-source pull-through read failed", exc_info=True)
|
|
by_source_rows = None
|
|
|
|
# Rules, at their own grain and in their own block (milestone 333).
|
|
#
|
|
# Guarded separately from the reads above for the reason `by_source`
|
|
# is: this table is NEW, and an instance running upgraded code
|
|
# against un-migrated schema would otherwise take down two readouts
|
|
# that work perfectly in order to report a third that cannot.
|
|
#
|
|
# The queries themselves are the note block's shapes, not novel
|
|
# ones — a group-by on two indexed columns and two count(distinct).
|
|
# The distinct counts need their own queries for the same reason
|
|
# the note ones do: count(distinct rule_id) per group cannot be
|
|
# summed across groups without double-counting a rule two sources
|
|
# both touched.
|
|
try:
|
|
rule_rows = (
|
|
await session.execute(
|
|
select(
|
|
RuleUsageEvent.event,
|
|
RuleUsageEvent.source,
|
|
func.count().label("n"),
|
|
)
|
|
.where(
|
|
RuleUsageEvent.created_at >= since,
|
|
RuleUsageEvent.user_id == user_id,
|
|
)
|
|
.group_by(RuleUsageEvent.event, RuleUsageEvent.source)
|
|
)
|
|
).all()
|
|
rule_complete = await _complete_from(
|
|
session, RuleUsageEvent, user_id,
|
|
)
|
|
# The rows carry `source`, so the ranked/ambient split is done
|
|
# below rather than in SQL — the bulk surfaces started emitting
|
|
# on 2026-09-03 (#3473), so there IS an ambient class now.
|
|
#
|
|
# `distinct_rules_surfaced` deliberately counts BOTH classes. It
|
|
# answers "how many distinct rules did this install put in front
|
|
# of an agent at all", which is the denominator for dead weight
|
|
# — and a rule delivered by the preload a hundred times and
|
|
# never opened is the most important case that question has.
|
|
distinct_rules_surfaced = (
|
|
await session.execute(
|
|
select(func.count(func.distinct(RuleUsageEvent.rule_id)))
|
|
.where(
|
|
RuleUsageEvent.created_at >= since,
|
|
RuleUsageEvent.user_id == user_id,
|
|
RuleUsageEvent.event == RULE_SURFACED,
|
|
)
|
|
)
|
|
).scalar_one()
|
|
distinct_rules_pulled = (
|
|
await session.execute(
|
|
select(func.count(func.distinct(RuleUsageEvent.rule_id)))
|
|
.where(
|
|
RuleUsageEvent.created_at >= since,
|
|
RuleUsageEvent.user_id == user_id,
|
|
RuleUsageEvent.event == RULE_PULLED,
|
|
)
|
|
)
|
|
).scalar_one()
|
|
# Rules that were OPENED AND THEN ACTED ON (#4212). Its own
|
|
# distinct count for the same reason the two above have one:
|
|
# "how many rules did anything come of" cannot be summed from
|
|
# the per-source group without double-counting a rule that was
|
|
# applied once and departed from once.
|
|
distinct_rules_acted = (
|
|
await session.execute(
|
|
select(func.count(func.distinct(RuleUsageEvent.rule_id)))
|
|
.where(
|
|
RuleUsageEvent.created_at >= since,
|
|
RuleUsageEvent.user_id == user_id,
|
|
RuleUsageEvent.event.in_(RULE_OUTCOMES),
|
|
)
|
|
)
|
|
).scalar_one()
|
|
except Exception:
|
|
logger.warning("rule usage read failed", exc_info=True)
|
|
rule_rows = None
|
|
distinct_rules_surfaced = distinct_rules_pulled = 0
|
|
distinct_rules_acted = 0
|
|
except Exception:
|
|
logger.warning("retrieval summary read failed", exc_info=True)
|
|
out["read_failed"] = True
|
|
return out
|
|
|
|
from scribe.services.note_usage import AMBIENT_SOURCES
|
|
|
|
usage = {
|
|
"surfaced": 0, "ambient": 0,
|
|
"pulled": 0, "pulled_by_agent": 0, "pulled_by_human": 0,
|
|
"distinct_notes_surfaced": int(distinct_surfaced or 0),
|
|
"distinct_notes_pulled": int(distinct_pulled or 0),
|
|
}
|
|
for event, source, n in urows:
|
|
n = int(n)
|
|
if event == SURFACED:
|
|
if source in AMBIENT_SOURCES:
|
|
usage["ambient"] += n
|
|
else:
|
|
usage["surfaced"] += n
|
|
elif event == PULLED:
|
|
usage["pulled"] += n
|
|
# The mcp_/rest_ split is load-bearing (see NoteUsageEvent's own
|
|
# comment, which names #1038 — this readout's whole purpose). "Is
|
|
# this record dead weight?" is answered by ANY pull; "was that
|
|
# injected line useful to the agent?" only by an AGENT pull. So
|
|
# pull-through, which exists to answer the second, counts mcp_*
|
|
# only. Both halves are reported so the first question is still
|
|
# answerable from the same payload.
|
|
if source.startswith("mcp_"):
|
|
usage["pulled_by_agent"] += n
|
|
else:
|
|
usage["pulled_by_human"] += n
|
|
# Ranked surfacings in the denominator, agent pulls in the numerator: the
|
|
# "surfaced often, opened never" reading is only valid where a scored
|
|
# surface CHOSE the record and an agent was the one who declined it.
|
|
usage["pull_through"] = (
|
|
round(usage["pulled_by_agent"] / usage["surfaced"], 4)
|
|
if usage["surfaced"] else None
|
|
)
|
|
|
|
# The same question, per surface — which is the one the top-level ratio
|
|
# cannot answer. A corpus average of 0.05 is compatible with one surface
|
|
# earning its noise and another producing none, and tuning a threshold
|
|
# needs to know which.
|
|
#
|
|
# UPPER BOUND, and say so where it will be read: a pull records the door,
|
|
# not the surface that led to it, so a note surfaced by two surfaces and
|
|
# opened once counts as pulled for both. Attribution would need the session
|
|
# identity #2085 declined to invent. The bound is still decisive in the
|
|
# direction that matters — a surface reading near zero here is not being
|
|
# flattered by the double-count.
|
|
if by_source_rows is None:
|
|
usage["by_source"] = {}
|
|
# Distinct from an empty window, for the same reason `read_failed` is.
|
|
usage["by_source_failed"] = True
|
|
else:
|
|
by_source: dict[str, dict] = {}
|
|
for source, n_surfaced, n_pulled in by_source_rows:
|
|
n_surfaced, n_pulled = int(n_surfaced or 0), int(n_pulled or 0)
|
|
ambient = source in AMBIENT_SOURCES
|
|
by_source[source] = {
|
|
"notes_surfaced": n_surfaced,
|
|
"notes_pulled": n_pulled,
|
|
# None rather than a number on an ambient surface: nothing
|
|
# CHOSE those records, so "surfaced often, opened never" is not
|
|
# a judgment about them. The counts stay visible; the ratio
|
|
# that would be misread does not.
|
|
"pull_through": (
|
|
None if ambient or not n_surfaced
|
|
else round(n_pulled / n_surfaced, 4)
|
|
),
|
|
"ambient": ambient,
|
|
}
|
|
usage["by_source"] = by_source
|
|
|
|
# The SECTION's coverage, from the latest source to start recording — a
|
|
# figure that sums several sources is complete only once every one of them
|
|
# was being written. `_complete_from` computes that as "*".
|
|
usage.update(_coverage((note_complete or {}).get("*"), since))
|
|
out["usage"] = usage
|
|
|
|
# ── Rules, deliberately a SEPARATE block ────────────────────────────
|
|
#
|
|
# Not folded into `usage`, for two reasons and the second is the one that
|
|
# bites. The corpora differ by orders of magnitude — a few dozen eligible
|
|
# rules against thousands of notes — so one blended ratio would be the note
|
|
# ratio with a little noise on it, and the rule arm's own behaviour would
|
|
# be undetectable inside it. And `usage` is what existing callers already
|
|
# read: silently changing what it counts would move a number people have
|
|
# been comparing across windows, without telling them it now measures
|
|
# something else.
|
|
#
|
|
# `ambient` now carries the bulk deliveries — the SessionStart preload,
|
|
# and every `rules_payload` surface (#3473). Before
|
|
# they emitted, this block had no ambient key and said the absence was a
|
|
# fact about the data. It was, and it was also the thing that made the
|
|
# always-on set impossible to judge: the largest rule surface in the
|
|
# product was the one surface its own scoreboard could not see.
|
|
#
|
|
# READ THE TWO SEPARATELY, ALWAYS. `surfaced` is a claim a ranker made and
|
|
# a pull can settle. `ambient` is a delivery nobody chose, so a high count
|
|
# says the set is large and resident, never that it is useful.
|
|
rule_usage = {
|
|
"surfaced": 0, "ambient": 0,
|
|
"pulled": 0, "pulled_by_agent": 0, "pulled_by_human": 0,
|
|
"distinct_rules_surfaced": int(distinct_rules_surfaced or 0),
|
|
"distinct_rules_pulled": int(distinct_rules_pulled or 0),
|
|
# The outcome half (#4212, milestone 419). `pulled` says a rule was
|
|
# opened; these say whether anything came of it. Until this existed, a
|
|
# rule obeyed every time and a rule ignored every time produced
|
|
# identical rows, and the second is the one worth finding.
|
|
"applied": 0,
|
|
"departed": 0,
|
|
"distinct_rules_acted": int(distinct_rules_acted or 0),
|
|
}
|
|
if rule_rows is None:
|
|
# The FLAG is added, the shape is kept — matching `by_source_failed`
|
|
# one block up. A caller that renders this must not have to choose
|
|
# between crashing on a missing key and quietly showing zeros it has no
|
|
# right to: the keys let it render, and the flag tells it the zeros are
|
|
# "we could not find out" rather than "nothing happened" (#2663).
|
|
rule_usage["rule_usage_failed"] = True
|
|
else:
|
|
for event, source, n in rule_rows:
|
|
n = int(n)
|
|
if event == RULE_SURFACED:
|
|
# One definition of ranked-vs-ambient, imported rather than
|
|
# restated — the per-rule badge readout reads the same
|
|
# predicate, and two spellings of "what counts as surfaced" is
|
|
# precisely the uneven wiring #3246 found across this system.
|
|
if is_ambient(source):
|
|
rule_usage["ambient"] += n
|
|
else:
|
|
rule_usage["surfaced"] += n
|
|
elif event == RULE_PULLED:
|
|
rule_usage["pulled"] += n
|
|
# Same split, and it carries MORE weight here than for notes.
|
|
# The arm's whole claim is "this rule may apply to what you are
|
|
# writing", and only an agent opening it says the claim landed.
|
|
# A person browsing the rule list says nothing about the hint.
|
|
if source.startswith("mcp_"):
|
|
rule_usage["pulled_by_agent"] += n
|
|
else:
|
|
rule_usage["pulled_by_human"] += n
|
|
elif event == RULE_APPLIED:
|
|
rule_usage["applied"] += n
|
|
elif event == RULE_DEPARTED:
|
|
# Kept apart from `applied` rather than summed into a single
|
|
# "acted" count. A departure is a rule someone ARGUED with,
|
|
# and an install where every outcome is a departure is telling
|
|
# you something quite different from one where none is —
|
|
# folding them together would hide exactly that.
|
|
rule_usage["departed"] += n
|
|
|
|
# None, not 0.0, when nothing was surfaced — matching the note block. A
|
|
# ratio of zero asserts "we showed rules and none were opened"; with an
|
|
# empty numerator AND denominator that is a claim the data does not
|
|
# support, and it is the reading that would make a brand-new install look
|
|
# like a broken one.
|
|
#
|
|
# RANKED SURFACINGS ONLY in the denominator, and this is the load-bearing
|
|
# line of the whole change. Pull-through asks "was that hint any use", and
|
|
# only a surface that CHOSE what it showed can be judged by it. Folding the
|
|
# preload in would divide the same pulls by a number that grows with every
|
|
# session and every rule added to the resident set — so enlarging the
|
|
# always-on set would DEPRESS the arm's measured precision, and trimming it
|
|
# would flatter it, neither for any reason to do with the arm. The ambient
|
|
# count sits beside it, unaveraged, and is read as size rather than skill.
|
|
rule_usage["pull_through"] = (
|
|
round(rule_usage["pulled_by_agent"] / rule_usage["surfaced"], 4)
|
|
if rule_usage["surfaced"] else None
|
|
)
|
|
rule_usage.update(_coverage((rule_complete or {}).get("*"), since))
|
|
out["rule_usage"] = rule_usage
|
|
out["system_usage"] = await _system_usage(user_id, since)
|
|
|
|
# ── Judged lines (#4772) ─────────────────────────────────────────────
|
|
#
|
|
# The relevance readout the usage blocks cannot be: a reviewer's verdict
|
|
# on each line of a sample of logged menus, by rank. Its own guard, for
|
|
# `_system_usage`'s reason — a failure flags itself rather than printing
|
|
# an empty block, which reads as "nothing judged" (#2663).
|
|
try:
|
|
out["judged"] = await judged_block(user_id, since)
|
|
except Exception:
|
|
logger.warning("judged block read failed", exc_info=True)
|
|
out["judged"] = {"judged_failed": True}
|
|
|
|
# ── 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)
|
|
|
|
# Floors that MOVED inside this window (#4225) — a release's shipped
|
|
# default or the operator's own dial, because the question is about the
|
|
# sample, not about who is answerable for it. Read unconditionally rather
|
|
# than under `if user_id`, unlike `floors` above: a release change belongs
|
|
# to no account, and it is exactly the case that used to go unrecorded.
|
|
floor_moves: dict[str, str] = {}
|
|
try:
|
|
floor_moves = await floor_moves_since(since)
|
|
except Exception: # pragma: no cover - telemetry never raises
|
|
logger.warning("could not read floor changes", exc_info=True)
|
|
|
|
# And the arms whose floor history does not REACH the start of the window.
|
|
# `floor_moves` answers "did it move"; for a window that opens before this
|
|
# arm's first ledger row, that answer is unavailable rather than no — and
|
|
# the band check was reading the two as the same. Read the same way and for
|
|
# the same reason: the ledger belongs to the install, not to an account.
|
|
floor_gaps: dict[str, str | None] = {}
|
|
try:
|
|
floor_gaps = await floor_history_gaps(since)
|
|
except Exception: # pragma: no cover - telemetry never raises
|
|
logger.warning("could not read floor history coverage", exc_info=True)
|
|
|
|
out["warnings"] = _compute_warnings(
|
|
out["sources"], usage, rule_usage, floors, min_calls, epsilon,
|
|
floor_moves, floor_gaps,
|
|
)
|
|
|
|
# "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,
|
|
system_usage=out["system_usage"],
|
|
)
|
|
|
|
return out
|