Merge pull request 'Telemetry coverage, and the rule arms stop filtering to one tier' (#143) from dev into main

src/scribe/mcp/tools/search.py

@@ -237,10 +237,37 @@ 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.
+
+    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

src/scribe/services/retrieval_telemetry.py

@@ -213,10 +213,70 @@ 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)
 
 
+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.
 
@@ -283,6 +343,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 +374,34 @@ 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
+
+            # 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
@@ -339,6 +428,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 +556,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 +668,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 +749,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

tests/test_services_retrieval_telemetry.py

@@ -638,3 +638,212 @@ 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,
+        # 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,
+            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_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(
+    _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()