From 21a583147924d491b4d5346802e7f997c71843b8 Mon Sep 17 00:00:00 2001 From: Bryan Van Deusen Date: Tue, 8 Sep 2026 10:29:02 -0400 Subject: [PATCH 1/4] feat(telemetry): every counter says when it started being recorded (#3712) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit 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 Claude-Session: https://claude.ai/code/session_011cPyzNnegXHr5iRMzzy5KJ --- src/scribe/mcp/tools/search.py | 28 +++- src/scribe/services/retrieval_telemetry.py | 72 +++++++++- tests/test_services_retrieval_telemetry.py | 145 +++++++++++++++++++++ 3 files changed, 240 insertions(+), 5 deletions(-) diff --git a/src/scribe/mcp/tools/search.py b/src/scribe/mcp/tools/search.py index 0bbed96..f84ce78 100644 --- a/src/scribe/mcp/tools/search.py +++ b/src/scribe/mcp/tools/search.py @@ -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 diff --git a/src/scribe/services/retrieval_telemetry.py b/src/scribe/services/retrieval_telemetry.py index 126fe40..2d88211 100644 --- a/src/scribe/services/retrieval_telemetry.py +++ b/src/scribe/services/retrieval_telemetry.py @@ -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 diff --git a/tests/test_services_retrieval_telemetry.py b/tests/test_services_retrieval_telemetry.py index 7cc869c..709840f 100644 --- a/tests/test_services_retrieval_telemetry.py +++ b/tests/test_services_retrieval_telemetry.py @@ -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() From 950c93c5d42bbfca40b05605ffef93caa09dedeb Mon Sep 17 00:00:00 2001 From: Bryan Van Deusen Date: Tue, 8 Sep 2026 10:34:57 -0400 Subject: [PATCH 2/4] fix(telemetry): the coverage helpers were defined inside the function they serve (#3712) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit `_complete_from` and `_coverage` landed between `retrieval_summary`'s docstring and its body. Python does not object to that the way it looks like it should: blank lines do not close a block, so the whole remaining body — indented four spaces, sitting after `_coverage`'s `return` — became unreachable code INSIDE `_coverage`, and `retrieval_summary` became a function that is nothing but a docstring. The error surfaced three ways at once, none of which named the cause: fourteen F821s for `days` and `user_id` (real: those are `retrieval_summary`'s parameters, and the body no longer lived there), a SyntaxError on `async with` (real: `_coverage` is sync), and every test module that imports this file failing to collect. Moved both helpers above `retrieval_summary`, beside `_bucket` and `_round`, where the file's other helpers already are. No behaviour change — this is the code that was meant to be there. Co-Authored-By: Claude Opus 5 Claude-Session: https://claude.ai/code/session_011cPyzNnegXHr5iRMzzy5KJ --- src/scribe/services/retrieval_telemetry.py | 58 +++++++++++----------- 1 file changed, 29 insertions(+), 29 deletions(-) diff --git a/src/scribe/services/retrieval_telemetry.py b/src/scribe/services/retrieval_telemetry.py index 2d88211..2a75c26 100644 --- a/src/scribe/services/retrieval_telemetry.py +++ b/src/scribe/services/retrieval_telemetry.py @@ -217,35 +217,6 @@ def _round(v, places: int = 4): return None if v is None else round(float(v), places) -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. - """ 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}. @@ -297,6 +268,35 @@ def _coverage(complete_from, since) -> dict: } +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), From 0808e8259ab74a1de8569003fe149b7c30ed962f Mon Sep 17 00:00:00 2001 From: Bryan Van Deusen Date: Tue, 8 Sep 2026 10:39:42 -0400 Subject: [PATCH 3/4] test(telemetry): the old surface needs a row in the window to have a bucket at all (#3712) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit The per-source grain test gave `auto_inject` a single row 90 days back and `pre_tool_rule` one 2 days back, then asserted on both buckets. Only the young arm got a bucket: `out["sources"]` is built from the WINDOWED query, so a source with no rows inside the window is absent entirely, and the assertion died on KeyError before it could test anything. `complete_from` and the bucket come from different queries — all-time for the first, windowed for the second — and the fixture only satisfied one of them. Gave `auto_inject` a second row inside the window, which is also the shape being described: an old surface that is STILL recording. The 90-day row still sets its `complete_from`. Still discriminating: auto_inject reads True and pre_tool_rule False, and a per-table `_complete_from` would make both 90 days and fail the second assertion — the regression this test is for. Co-Authored-By: Claude Opus 5 Claude-Session: https://claude.ai/code/session_011cPyzNnegXHr5iRMzzy5KJ --- tests/test_services_retrieval_telemetry.py | 10 +++++++++- 1 file changed, 9 insertions(+), 1 deletion(-) diff --git a/tests/test_services_retrieval_telemetry.py b/tests/test_services_retrieval_telemetry.py index 709840f..8605e39 100644 --- a/tests/test_services_retrieval_telemetry.py +++ b/tests/test_services_retrieval_telemetry.py @@ -706,11 +706,19 @@ async def test_coverage_is_per_source_because_the_table_is_older_than_its_arms( 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. + # An old surface, recording since well before any window we ask for, + # AND still recording inside it. Both rows are needed: `complete_from` + # comes from the all-time query, but a source only gets a bucket at all + # if it has rows in the window, so the 90-day row alone would leave + # nothing to assert on. s.add(RetrievalLog( user_id=UID, source="auto_inject", result_count=1, created_at=now - timedelta(days=90), )) + s.add(RetrievalLog( + user_id=UID, source="auto_inject", result_count=1, + created_at=now - timedelta(days=1), + )) # A young arm, first written INSIDE the window below. s.add(RetrievalLog( user_id=UID, source="pre_tool_rule", result_count=1, From 7a2aff7bc12eecfb0f0460289d96a04a7aadcc55 Mon Sep 17 00:00:00 2001 From: Bryan Van Deusen Date: Tue, 8 Sep 2026 11:07:21 -0400 Subject: [PATCH 4/4] fix(telemetry): a surface that stopped recording is not one that never ran (#3720) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit `out["sources"]` was built only from the windowed aggregate, so a source with rows in `retrieval_logs` but none inside the window got no bucket at all. Absent is exactly how a source that never existed renders, so a surface that WAS recording and went silent became unreadable — #2663 one level up, the failure that looks like the correct answer. Two queries at different scopes, and only one shaped the output. `_complete_from` reads all-time and knows every source the table has ever held; the windowed loop dropped whatever it did not return. Every such source now gets a zero bucket. Zero is a real measurement here rather than a manufactured one: the all-time query proves the source was recording, and it made no calls across a window it fully covers. No `covers_window` special case is needed either — a source whose first row fell after `since` would have that row IN the window and already hold a bucket, so anything reaching this branch began before it. The counts are 0 and everything else is null. A sampled distribution is not the same claim as a call count, and rendering p50 as 0.0 for a source nobody sampled would assert a measurement — #3311's mistake, in the readout built to prevent it. Found while fixing #3712's fixture, which failed with KeyError for this exact reason. Co-Authored-By: Claude Opus 5 Claude-Session: https://claude.ai/code/session_011cPyzNnegXHr5iRMzzy5KJ --- src/scribe/mcp/tools/search.py | 7 +++ src/scribe/services/retrieval_telemetry.py | 28 +++++++++++ tests/test_services_retrieval_telemetry.py | 56 ++++++++++++++++++++++ 3 files changed, 91 insertions(+) diff --git a/src/scribe/mcp/tools/search.py b/src/scribe/mcp/tools/search.py index f84ce78..e31ab17 100644 --- a/src/scribe/mcp/tools/search.py +++ b/src/scribe/mcp/tools/search.py @@ -262,6 +262,13 @@ It is an UPPER BOUND per surface: a pull records the door it came "no measurement" is not "partial measurement", the same distinction `suppression`'s null carries a few paragraphs up. + A SOURCE SHOWING `calls: 0` WAS RECORDING AND MADE NO CALLS. `sources` + lists every source the table has ever held, not only those active in the + window, so a surface that stopped firing stays visible rather than + disappearing — being absent is reserved for a source that has never + recorded at all. Its score fields are null, not zero: the calls are a + real observation, the distribution is not one. + `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 they are zeros meaning "could not find out", not "nothing happened" — do diff --git a/src/scribe/services/retrieval_telemetry.py b/src/scribe/services/retrieval_telemetry.py index 2a75c26..fe5908d 100644 --- a/src/scribe/services/retrieval_telemetry.py +++ b/src/scribe/services/retrieval_telemetry.py @@ -213,6 +213,15 @@ def _bucket(rows: list) -> dict: } +# 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, cleared, p10, p50, p90, min, max, avg_n, +# dur, measured, supp_calls, supp_zero. The three 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, 0, None, None, None, None, None, None, None, 0, 0, 0] + + def _round(v, places: int = 4): return None if v is None else round(float(v), places) @@ -375,6 +384,25 @@ async def retrieval_summary(user_id: int | None, *, days: int = 30) -> dict: 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. diff --git a/tests/test_services_retrieval_telemetry.py b/tests/test_services_retrieval_telemetry.py index 8605e39..c0eca30 100644 --- a/tests/test_services_retrieval_telemetry.py +++ b/tests/test_services_retrieval_telemetry.py @@ -740,6 +740,62 @@ async def test_coverage_is_per_source_because_the_table_is_older_than_its_arms( await s.commit() +@pytest.mark.integration +@pytest.mark.asyncio +async def test_a_surface_that_went_silent_is_not_the_same_as_one_that_never_ran( + _dispose_engine, +): + """#3720 — absent is how "never existed" renders, so it cannot also be how + "stopped recording" renders. + + A surface losing its recorder is one of the failures this milestone exists + to make visible, and dropping it from the readout is the most complete way + to hide it. Zero here is a real measurement: the table proves the source + was recording, and it made no calls across a window it fully covers. + """ + 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 = 990078 + now = datetime.now(timezone.utc) + async with async_session() as s: + # Recorded once, well before the window, and never since. + s.add(RetrievalLog( + user_id=UID, source="auto_inject", result_count=3, top_score=0.81, + created_at=now - timedelta(days=60), + )) + await s.commit() + + try: + out = await retrieval_summary(UID, days=7) + + assert "auto_inject" in out["sources"], ( + "a source with rows in the table but none in the window was " + "dropped from the readout — a surface that stopped recording now " + "reads exactly like one that never existed" + ) + quiet = out["sources"]["auto_inject"] + assert quiet["calls"] == 0 + # The window IS covered; what was observed across it is nothing. + assert quiet["covers_window"] is True + # ...but nothing was sampled, so no distribution may be claimed. A + # zeroed score would assert a measurement, which is #3311's mistake. + assert quiet["top_score"] == { + "p10": None, "p50": None, "p90": None, "min": None, "max": None, + } + assert quiet["suppression"] is None + assert quiet["avg_result_count"] is None + 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(