1004 lines
48 KiB
Python
1004 lines
48 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 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
|
|
|
|
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
|
|
),
|
|
}
|
|
|
|
|
|
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()
|
|
except Exception:
|
|
logger.warning("rule usage read failed", exc_info=True)
|
|
rule_rows = None
|
|
distinct_rules_surfaced = distinct_rules_pulled = 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),
|
|
}
|
|
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
|
|
|
|
# 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
|
|
|
|
return out
|