bvandeusenandClaude Opus 5
623464323e
CI & Build / Plugin hooks (push) Successful in 13s
CI & Build / Python lint (push) Successful in 4s
CI & Build / TypeScript typecheck (push) Successful in 46s
CI & Build / integration (push) Successful in 52s
CI & Build / Python tests (push) Successful in 1m21s
CI & Build / Build & push image (push) Successful in 36s
`best_available_score` was added by #3670 so a bar could be judged from what it rejected, and it arrived null on four unrelated causes: the corpus offered nothing, the query was empty, the embedder was down, or the DATABASE QUERY FAILED. Only the first is a measurement. The fourth is the #2663 shape — a swallowed failure rendering as a clean zero — inside the field added to fix an instance of the #2663 shape. Found while trying to explain why reuse_slot returned nothing on 45 of 45 calls, and auto_inject on 153 of 161. That investigation is still open; what it established first is that the readout could not answer it. THE FIX IS NOT A NEW COLUMN. A call that never searched writes no row, so every remaining null means one thing: searched, and nothing came close. That is the convention the pre-tool arm already follows for a blank command — "a row here would report a call that never happened and drag the clear-rate down with phantom declines" — extended from the case a caller can see in advance to the ones only the search knows about. Both searches stamp `report["searched"]` FALSE before anything can return and True only where a real result set exists, so every early return leaves it false. It has to be the first thing done to the dict: a return added above that line would leave the key absent. ABSENT IS A THIRD STATE AND IT DEFAULTS TO TRUE. A caller that passes no report cannot know, and the safe reading there is the old behaviour. Only a real search can report False, so absent means "nobody asked" and never "it failed" — which is also why 66 existing mocked searches across twelve test files keep working unchanged rather than being rewritten to simulate a flag they do not care about. A FAILURE IS NOT MADE INVISIBLE. semantic_search_notes already 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. Three tests, and the middle one is what makes them discriminate — a blanket `return` passes the first and fails the second, because a call that searched and came back empty is the only evidence a threshold is too high (#3497). Co-Authored-By: Claude Opus 5 <noreply@anthropic.com> Claude-Session: https://claude.ai/code/session_011cPyzNnegXHr5iRMzzy5KJ
865 lines
42 KiB
Python
865 lines
42 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
|
|
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
|
|
|
|
|
|
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,
|
|
) -> 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,
|
|
"query": 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)
|
|
),
|
|
"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,
|
|
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,
|
|
)
|
|
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) -> 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
|
|
|
|
# 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,
|
|
# `list_always_on_rules`, 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
|