bvandeusenandClaude Opus 5
512d0326a0
CI & Build / Python lint (push) Successful in 3s
CI & Build / Plugin hooks (push) Successful in 16s
CI & Build / integration (push) Successful in 55s
CI & Build / TypeScript typecheck (push) Successful in 1m0s
CI & Build / Python tests (push) Successful in 1m34s
CI & Build / Build & push image (push) Successful in 33s
`retrieval_telemetry(days=30)` reported, for write_path_rule:
"the weakest tenth of what this arm returns scores 0.6984, only -0.0216
above its floor of 0.72"
A negative distance above something. The tenth percentile of what an arm
RETURNED cannot sit below the floor that gates what it may return — not
inside one population.
MEASURED CAUSE. write_path_rule's floor was 0.68 until 2026-09-02, when
2385100 (#3318) raised the shipped default to 0.72. The window opened
2026-08-22, so six days of it are calls made under the old bar; top_score.min
for the surface is exactly 0.68, the old bar still in the sample.
AND THE CHANGE LEFT NO TRACE THE READOUT COULD SEE. retrieval_tuning_events
records dial turns — a person or a model choosing a number. It was silent
about the other way a floor moves: somebody edits floor_default and ships it.
retrieval_tuning_history returned {"events": []} and retrieval_surfaces said
last_change: {}, source: "shipped". All true, and all of it silent about a
floor that had in fact moved.
THE RAISE ANNOUNCED ITSELF. A LOWERED FLOOR WOULD NOT: the gap comes out
comfortably positive and reads as a clean bill of health on a sample that
half predates the bar being judged. Both directions are now pinned.
So the check is SUSPENDED, not softened. band_hugs_floor asks whether the
scores are piled on the bar; that needs the scores and the bar to come from
the same regime. Where they do not, the honest answer is that this sample
cannot say, plus the date after which one can — floor_moved_mid_window
replaces band_hugs_floor for that arm and never accompanies it. A reader told
a number is unavailable goes and gets one; a reader handed a qualified number
uses it.
NO MIGRATION. `actor` is Text with no CHECK precisely so a new kind of actor
is not one — the model's own comment says so, and this is the case it
anticipated. "release" joins "model" and "human". user_id is already
nullable, which is right: no user did this, a release acts on every account
that has not overridden the dial, and a row per user would both multiply and
misattribute it. Both readers now take the newest of (this user's change, the
release's).
THE FIRST SIGHTING IS A BASELINE, written with old_value NULL. Nothing moved;
the row exists so the next release has a predecessor. That null is
load-bearing: floor_moves_since asks for old_value IS NOT NULL, so a fresh
install's baseline does not silently retire the check on every new install.
UI: the tuning history rendered actor as `human ? 'you' : 'Claude'`, so a
release row would have told the operator that Claude moved a floor it never
touched — the one failure the actor column exists to prevent. Three-way now,
with an unknown value printing itself rather than guessing.
Recorded at startup, inline and awaited. What #4181 cost three hours was
concurrency — a background task racing the hook for the same pool. Sequential
creates no contention, and this is twelve single-row reads. It must finish
before serving because a readout served before the change was recorded is the
exact answer this exists to stop giving.
Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01821k5B3Ysecp9fNYs92Kuy
1415 lines
69 KiB
Python
1415 lines
69 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.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.retrieval_tuning import 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
|
|
|
|
|
|
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) -> 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")
|
|
moved = (floor_moves or {}).get(name)
|
|
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,
|
|
))
|
|
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. 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,
|
|
))
|
|
|
|
# ── 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) -> 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:
|
|
"""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": {},
|
|
"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
|
|
|
|
# ── 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)
|
|
|
|
out["warnings"] = _compute_warnings(
|
|
out["sources"], usage, rule_usage, floors, min_calls, epsilon,
|
|
floor_moves,
|
|
)
|
|
|
|
# "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
|