feat(telemetry): every counter says when it started being recorded (#3712)
CI & Build / Python lint (push) Failing after 3s
CI & Build / Plugin hooks (push) Successful in 8s
CI & Build / integration (push) Failing after 17s
CI & Build / Python tests (push) Failing after 26s
CI & Build / TypeScript typecheck (push) Successful in 34s
CI & Build / Build & push image (push) Skipped
CI & Build / Python lint (push) Failing after 3s
CI & Build / Plugin hooks (push) Successful in 8s
CI & Build / integration (push) Failing after 17s
CI & Build / Python tests (push) Failing after 26s
CI & Build / TypeScript typecheck (push) Successful in 34s
CI & Build / Build & push image (push) Skipped
A window that opens before a counter existed reports that counter as though it had been measured throughout. The reader cannot tell "zero because nothing happened" from "zero because nobody was counting yet", and — worse — cannot tell a partial count from a complete one. That middle case yields a plausible FRACTION rather than an obvious zero, which is what makes it dangerous. It is not hypothetical. A 7-day window opened while the ranked rule surfacing recorders were four days old produced an apparent 64% write loss, which survived a code review, four ruled-out alternative causes and a five-step milestone before an identity check falsified it in one read. Every counter block now carries `complete_from` and `covers_window`. THE GRAIN IS THE SOURCE. retrieval_logs accumulates for months, so a per-table earliest row says months for every source it holds — including an arm added days ago whose counter means something else entirely. The old source would vouch for the young one, which is the exact reading this prevents. A SECTION TAKES ITS LATEST CONTRIBUTOR, NOT ITS EARLIEST. A figure summing several sources is complete only once every one of them was being written, so "*" is a max. Using min would reproduce the original error in miniature. `covers_window` is null, never false, when nothing was ever recorded: "no measurement" is not "partial measurement" — the null convention #3497 established for `suppression`, one level up. Also corrects a stale claim in the tool docstring: it still taught readers that write_path_rule "has never once declined to fire" (#3311). That was the arm writing its retrieval_logs row only on calls that found something; #3497 fixed it, and the arm declines the large majority of its calls. _complete_from takes the caller's session rather than opening its own, departing from the services canon (#2860) because it runs inside an existing block; to be recorded against the ledger once it ingests. Co-Authored-By: Claude Opus 5 <noreply@anthropic.com> Claude-Session: https://claude.ai/code/session_011cPyzNnegXHr5iRMzzy5KJ
This commit is contained in:
@@ -237,10 +237,30 @@ It is an UPPER BOUND per surface: a pull records the door it came
|
||||
those same rules over time: a resident set surfaced thousands of times and
|
||||
opened never is the dead-weight signal, one tier up.
|
||||
|
||||
Read it against `sources["write_path_rule"]`. That surface has never once
|
||||
declined to fire, and until this block existed there was no way to tell a
|
||||
well-tuned arm from a bar it cannot fail to clear (#3311). `pull_through`
|
||||
is the number that tells them apart.
|
||||
Read it against `sources["write_path_rule"]`. That arm was once believed
|
||||
never to decline — the reading that scoped #3311 — but it was the arm's
|
||||
`retrieval_logs` row being written only on calls that FOUND something, so
|
||||
the zeros were missing rather than absent (#3497). Measured since, it
|
||||
declines the large majority of its calls like any other surface.
|
||||
|
||||
EVERY COUNTER BLOCK CARRIES ITS OWN COVERAGE — `complete_from` and
|
||||
`covers_window`. `complete_from` is when the number became trustworthy:
|
||||
for one source, its first recorded row; for a section that sums several,
|
||||
the LATEST of theirs, because a total is complete only once every
|
||||
contributor was being written. `covers_window: false` means the window
|
||||
reaches back further than the recording does, so the count is a fraction
|
||||
of the period it appears to describe.
|
||||
|
||||
READ IT BEFORE COMPARING TWO NUMBERS, and especially before comparing
|
||||
across a deploy. A counter added last week, read over a 30-day window,
|
||||
reports a real count against an imagined denominator — and the result is
|
||||
a plausible fraction rather than an obvious zero, which is what makes it
|
||||
dangerous. That reading cost milestone #379 five steps aimed at a defect
|
||||
that did not exist.
|
||||
|
||||
`covers_window` is null, never false, when nothing was ever recorded:
|
||||
"no measurement" is not "partial measurement", the same distinction
|
||||
`suppression`'s null carries a few paragraphs up.
|
||||
|
||||
`rule_usage_failed: true` means that read failed while the rest of the
|
||||
readout stood. The counts are still present so a caller can render, but
|
||||
|
||||
@@ -246,6 +246,57 @@ async def retrieval_summary(user_id: int | None, *, days: int = 30) -> dict:
|
||||
no readout. It does distinguish "no rows" from "the read failed", because
|
||||
#2663 is exactly the bug where those two looked identical for weeks.
|
||||
"""
|
||||
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
|
||||
),
|
||||
}
|
||||
|
||||
|
||||
since = datetime.now(timezone.utc) - timedelta(days=max(1, int(days)))
|
||||
out: dict = {
|
||||
"window_days": int(days),
|
||||
@@ -283,6 +334,9 @@ async def retrieval_summary(user_id: int | None, *, days: int = 30) -> dict:
|
||||
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:
|
||||
@@ -311,8 +365,15 @@ async def retrieval_summary(user_id: int | None, *, days: int = 30) -> dict:
|
||||
.group_by(RetrievalLog.source)
|
||||
)
|
||||
).all()
|
||||
log_complete = await _complete_from(session, RetrievalLog, user_id)
|
||||
for row in rows:
|
||||
out["sources"][row[0]] = _bucket(list(row[1:]))
|
||||
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
|
||||
|
||||
# The corpus side, at its own grain. `ambient` mirrors
|
||||
# note_usage.usage_for_notes: an ambient surfacing was not a scored
|
||||
@@ -339,6 +400,7 @@ async def retrieval_summary(user_id: int | None, *, days: int = 30) -> dict:
|
||||
.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
|
||||
@@ -466,6 +528,9 @@ async def retrieval_summary(user_id: int | None, *, days: int = 30) -> dict:
|
||||
.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.
|
||||
@@ -575,6 +640,10 @@ async def retrieval_summary(user_id: int | None, *, days: int = 30) -> dict:
|
||||
}
|
||||
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 ────────────────────────────
|
||||
@@ -652,6 +721,7 @@ async def retrieval_summary(user_id: int | None, *, days: int = 30) -> dict:
|
||||
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
|
||||
|
||||
@@ -638,3 +638,148 @@ async def test_ambient_alone_reports_no_ratio(_dispose_engine):
|
||||
assert ru["pull_through"] is None
|
||||
finally:
|
||||
await cleanup()
|
||||
|
||||
|
||||
# ── Window coverage (#3712) ────────────────────────────────────────────
|
||||
#
|
||||
# A counter added last week, read over a 30-day window, reports a real count
|
||||
# against an imagined denominator. The result is a plausible FRACTION rather
|
||||
# than an obvious zero, which is what makes it dangerous — #379 spent five
|
||||
# planned steps on a defect that turned out to be a window opening before the
|
||||
# recording it was measuring existed.
|
||||
|
||||
|
||||
def test_coverage_says_nothing_rather_than_false_when_nothing_was_recorded():
|
||||
"""Null, never False. "No measurement" is not "partial measurement".
|
||||
|
||||
The same distinction `suppression`'s null carries (#3497): absent must not
|
||||
read as a verdict. A False here would assert the window is under-covered,
|
||||
which is a claim nobody is in a position to make.
|
||||
"""
|
||||
from datetime import datetime, timezone
|
||||
|
||||
from scribe.services.retrieval_telemetry import _coverage
|
||||
|
||||
since = datetime(2026, 9, 1, tzinfo=timezone.utc)
|
||||
assert _coverage(None, since) == {
|
||||
"complete_from": None, "covers_window": None,
|
||||
}
|
||||
|
||||
|
||||
def test_coverage_reads_a_start_before_the_window_as_covered():
|
||||
from datetime import datetime, timezone
|
||||
|
||||
from scribe.services.retrieval_telemetry import _coverage
|
||||
|
||||
since = datetime(2026, 9, 1, tzinfo=timezone.utc)
|
||||
older = datetime(2026, 8, 1, tzinfo=timezone.utc)
|
||||
newer = datetime(2026, 9, 5, tzinfo=timezone.utc)
|
||||
|
||||
assert _coverage(older, since)["covers_window"] is True
|
||||
assert _coverage(newer, since)["covers_window"] is False, (
|
||||
"a counter that started inside the window covers only part of it"
|
||||
)
|
||||
assert _coverage(newer, since)["complete_from"] == newer.isoformat()
|
||||
|
||||
|
||||
@pytest.mark.integration
|
||||
@pytest.mark.asyncio
|
||||
async def test_coverage_is_per_source_because_the_table_is_older_than_its_arms(
|
||||
_dispose_engine,
|
||||
):
|
||||
"""THE grain question, and the reason a per-table answer is useless.
|
||||
|
||||
`retrieval_logs` accumulates for months. A table-level "earliest row"
|
||||
therefore says months for every source it holds — including one added
|
||||
days ago whose counter means something quite different. The old source
|
||||
would vouch for the young one, which is exactly the reading this exists
|
||||
to prevent.
|
||||
"""
|
||||
from datetime import datetime, timedelta, timezone
|
||||
|
||||
from sqlalchemy import delete
|
||||
|
||||
from scribe.models import async_session
|
||||
from scribe.models.retrieval_log import RetrievalLog
|
||||
from scribe.services.retrieval_telemetry import retrieval_summary
|
||||
|
||||
UID = 990077
|
||||
now = datetime.now(timezone.utc)
|
||||
async with async_session() as s:
|
||||
# An old surface, recording since well before any window we ask for.
|
||||
s.add(RetrievalLog(
|
||||
user_id=UID, source="auto_inject", result_count=1,
|
||||
created_at=now - timedelta(days=90),
|
||||
))
|
||||
# A young arm, first written INSIDE the window below.
|
||||
s.add(RetrievalLog(
|
||||
user_id=UID, source="pre_tool_rule", result_count=1,
|
||||
created_at=now - timedelta(days=2),
|
||||
))
|
||||
await s.commit()
|
||||
|
||||
try:
|
||||
out = await retrieval_summary(UID, days=30)
|
||||
|
||||
assert out["sources"]["auto_inject"]["covers_window"] is True
|
||||
assert out["sources"]["pre_tool_rule"]["covers_window"] is False, (
|
||||
"the young arm was reported as covering a 30-day window — the "
|
||||
"table's age has been allowed to vouch for one of its sources"
|
||||
)
|
||||
finally:
|
||||
async with async_session() as s:
|
||||
await s.execute(delete(RetrievalLog).where(RetrievalLog.user_id == UID))
|
||||
await s.commit()
|
||||
|
||||
|
||||
@pytest.mark.integration
|
||||
@pytest.mark.asyncio
|
||||
async def test_a_section_is_complete_only_from_its_latest_contributor(
|
||||
_dispose_engine,
|
||||
):
|
||||
"""A sum is complete once EVERY contributor was being written — so the
|
||||
section takes the LATEST first-row, not the earliest.
|
||||
|
||||
Taking the earliest would be worse than reporting nothing: it would pick
|
||||
the oldest source in the table and use it to certify a total that a
|
||||
newer source is still only partly contributing to. That is the original
|
||||
error in miniature.
|
||||
"""
|
||||
from datetime import datetime, timedelta, timezone
|
||||
|
||||
from sqlalchemy import delete
|
||||
|
||||
from scribe.models import async_session
|
||||
from scribe.models.rule_usage import RuleUsageEvent
|
||||
from scribe.services.retrieval_telemetry import retrieval_summary
|
||||
|
||||
UID = 990078
|
||||
now = datetime.now(timezone.utc)
|
||||
old = now - timedelta(days=90)
|
||||
young = now - timedelta(days=2)
|
||||
async with async_session() as s:
|
||||
s.add_all([
|
||||
RuleUsageEvent(
|
||||
user_id=UID, rule_id=1, event="surfaced",
|
||||
source="list_always_on_rules", created_at=old,
|
||||
),
|
||||
RuleUsageEvent(
|
||||
user_id=UID, rule_id=2, event="surfaced",
|
||||
source="pre_tool_rule", created_at=young,
|
||||
),
|
||||
])
|
||||
await s.commit()
|
||||
|
||||
try:
|
||||
out = await retrieval_summary(UID, days=30)
|
||||
ru = out["rule_usage"]
|
||||
|
||||
assert ru["complete_from"] == young.isoformat(), (
|
||||
"the section reported completeness from its OLDEST source; a "
|
||||
"total is only as complete as its newest contributor"
|
||||
)
|
||||
assert ru["covers_window"] is False
|
||||
finally:
|
||||
async with async_session() as s:
|
||||
await s.execute(delete(RuleUsageEvent).where(RuleUsageEvent.user_id == UID))
|
||||
await s.commit()
|
||||
|
||||
Reference in New Issue
Block a user