feat(telemetry): retrieval_telemetry reports rule pull-through where it reported nothing (#3317)

Milestone 333 step 3, the read half. Steps 1 and 2 built the table and filled
it; until now nothing read it, and `usage` — sourced entirely from
note_usage_events — described notes only while `sources` happily listed a
write_path_rule row above it. A reader takes the aggregate as covering
everything named above it. It did not.

A SEPARATE `rule_usage` BLOCK, not folded into `usage`. Two reasons, and the
second is the one that bites: the corpora differ by orders of magnitude, so a
blended ratio would be the note ratio with noise on it and the rule arm would
stay invisible inside it; and `usage` is what existing callers already read and
compare across windows, so silently changing what it counts would move a number
nobody was told had changed meaning. There is a test asserting rule events stay
out of the note block.

No `ambient` key, unlike the twin. Nothing surfaces a rule un-ranked —
list_always_on_rules and enter_project hand rules over wholesale but emit no
event — so there is no ambient class to subtract. The absence is a fact about
the data, not an oversight, and it returns when a bulk loader starts emitting.

Guarded separately, like `by_source`. This table did not exist a commit ago,
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. On failure the FLAG is added and the SHAPE is kept — a caller must
not have to choose between crashing on a missing key and quietly rendering
zeros it has no right to.

`pull_through` is None rather than 0.0 on an empty window, matching the note
block. A ratio of zero asserts "rules were shown and none 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.

Also fixed, from #3311: the rule arm never timed its search, so it was the one
source in the readout reporting a null p90_duration_ms — a gap that reads as
"this surface is somehow not measurable" rather than "nobody passed the
number".

Both docstrings updated in the same change. The tool's is the agent-facing
contract (rule 119) and it explicitly said rule surfacings were absent and had
"no usage counter at all". Leaving that would have had a reader conclude the
arm has zero pull-through rather than a separate one.

Tests are integration for the reason the block above them is: real GROUP BYs
and count(distinct) against a table a commit old, in a module whose one
production outage was a SQL shape the database rejected inside a broad except.
A mock would agree with whatever the code does, including nothing.

Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01TcCs1CcQ1ormdnzSshKqvN

src/scribe/mcp/tools/search.py

@@ -158,7 +158,7 @@ async def retrieval_telemetry(days: int = 30) -> dict:
     hand-probing the live instance, which is how the last such decision had to
     be made.
 
-    Two readouts, from the two tables built for them:
+    Three readouts, from the three tables built for them:
 
     `sources` — per retrieval surface (`auto_inject`, `write_path`,
     `mcp_search`, …), from `retrieval_logs`: `calls`, `zero_result_calls`,
@@ -168,7 +168,7 @@ async def retrieval_telemetry(days: int = 30) -> dict:
     against `calls`, with the spread beside it: a surface that clears its bar
     on nearly every call is either well-tuned or too loose, and p10 says which.
 
-    `usage` — from `note_usage_events`, at the per-note grain
+    `usage` — NOTES ONLY, from `note_usage_events`, at the per-note grain
     `retrieval_logs` cannot be indexed at: `surfaced` (ranked surfacings — a
     scored surface CHOSE the record), `ambient` (the rest), `pulled` split into
     `pulled_by_agent` / `pulled_by_human`, the distinct-note counts, and
@@ -190,14 +190,34 @@ async def retrieval_telemetry(days: int = 30) -> dict:
     about a record nothing chose). Read it as: of the distinct notes THIS
     surface put in front of the agent, how many did the agent then open?
 
-    Two limits on it, both deliberate. It is an UPPER BOUND per surface: a pull
-    records the door it came through, not the surface that led there, so a note
-    surfaced by two surfaces and opened once counts for both — attribution
-    would need the session identity #2085 declined to invent. And RULE
-    surfacings are absent: `write_path_rule` appears in `sources` with its
-    scores but has no usage counter at all, so it has no row here (#3311).
-    `by_source_failed: true` means that one query failed while the rest of the
-    readout stood.
+It is an UPPER BOUND per surface: a pull records the door it came
+    through, not the surface that led there, so a note surfaced by two surfaces
+    and opened once counts for both — attribution would need the session
+    identity #2085 declined to invent. `by_source_failed: true` means that one
+    query failed while the rest of the readout stood.
+
+    `rule_usage` — the same question for RULES, from `rule_usage_events`:
+    `surfaced`, `pulled` split into `pulled_by_agent` / `pulled_by_human`, the
+    distinct-rule counts, and `pull_through` on the same definition (agent
+    pulls over surfacings).
+
+    A SEPARATE BLOCK, not folded into `usage`, and reading it as one number
+    with that is the mistake to avoid. The corpora differ by orders of
+    magnitude — a few dozen eligible rules against thousands of notes — so a
+    blended ratio would be the note ratio with noise on it and would hide the
+    rule arm entirely. It also has no `ambient` key, because nothing surfaces a
+    rule un-ranked: `list_always_on_rules` and `enter_project` hand over rules
+    wholesale but emit no event, so there is no ambient class to separate.
+
+    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.
+
+    `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
+    not report a pull-through from a block carrying that flag.
 
     Scoped to your own telemetry — a retrieval log records what your agent
     asked for, query text included, and is not a shared record kind.

src/scribe/services/plugin_context.py

@@ -1126,10 +1126,16 @@ async def build_write_path_hint(
     rule_ids: list[int] = []
     try:
         already = set(exclude_rule_ids or [])
+        # Timed like the notes arm above. Without this the rule row was the one
+        # source in the whole readout reporting a null p90_duration_ms (#3311)
+        # — a gap that reads as "this surface is somehow not measurable" rather
+        # than "nobody passed the number".
+        rule_t0 = time.perf_counter()
         hits = await semantic_search_rules(
             user_id, code or path, limit=2,
             threshold=cfg["threshold"], tier="conditional",
         )
+        rule_ms = (time.perf_counter() - rule_t0) * 1000.0
         fresh = [(score, rule) for score, rule in hits if rule.id not in already]
         for _score, rule in fresh:
             trigger = (rule.when_to_apply or "").strip()
@@ -1155,7 +1161,7 @@ async def build_write_path_hint(
             record_retrieval(
                 user_id=user_id, source="write_path_rule", query=code or path,
                 threshold=cfg["threshold"], limit=2, project_id=project_id,
-                is_task=None, results=fresh,
+                is_task=None, results=fresh, duration_ms=rule_ms,
             )
             # `rule_ids` is `fresh`, i.e. AFTER exclude_rule_ids. A rule the
             # session already holds was considered and not shown, and counting

src/scribe/services/retrieval_telemetry.py

@@ -27,6 +27,9 @@ 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.models.retrieval_log import RetrievalLog
 
 logger = logging.getLogger(__name__)
@@ -190,8 +193,10 @@ def _round(v, places: int = 4):
 async def retrieval_summary(user_id: int | None, *, days: int = 30) -> dict:
     """What the retrieval telemetry says, per surface, over a window.
 
-    Two aggregates side by side, each read from the table built for it — NOT a
-    join. `NoteUsageEvent`'s own docstring is explicit that the two are
+    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
@@ -220,6 +225,7 @@ async def retrieval_summary(user_id: int | None, *, days: int = 30) -> dict:
         "since": iso(since),
         "sources": {},
         "usage": {},
+        "rule_usage": {},
         "read_failed": False,
     }
 
@@ -240,6 +246,8 @@ async def retrieval_summary(user_id: int | None, *, days: int = 30) -> dict:
     # 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
 
     try:
         async with async_session() as session:
@@ -391,6 +399,63 @@ async def retrieval_summary(user_id: int | None, *, days: int = 30) -> dict:
             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()
+                # No AMBIENT exclusion here, unlike the note twin: nothing
+                # surfaces a rule un-ranked yet. `list_always_on_rules` and
+                # `enter_project` deliver rules wholesale but emit no event, so
+                # there is no ambient class to subtract (milestone 333 step 1).
+                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
@@ -468,4 +533,59 @@ async def retrieval_summary(user_id: int | None, *, days: int = 30) -> dict:
         usage["by_source"] = by_source
 
     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.
+    #
+    # No `ambient` key, unlike its twin. Nothing surfaces a rule un-ranked yet;
+    # the absence is a fact about the data rather than an oversight, and it
+    # returns the moment a bulk loader starts emitting.
+    rule_usage = {
+        "surfaced": 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:
+                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.
+    rule_usage["pull_through"] = (
+        round(rule_usage["pulled_by_agent"] / rule_usage["surfaced"], 4)
+        if rule_usage["surfaced"] else None
+    )
+    out["rule_usage"] = rule_usage
+
     return out

tests/test_services_retrieval_telemetry.py

@@ -359,3 +359,155 @@ async def test_the_agent_pull_filter_does_not_treat_its_underscore_as_a_wildcard
         async with async_session() as s:
             await s.execute(delete(NoteUsageEvent).where(NoteUsageEvent.user_id == UID))
             await s.commit()
+
+
+# ─── rule usage (milestone 333 step 3) ───────────────────────────────────────
+# Integration, for the same reason the block above is: these are real GROUP BYs
+# and count(distinct) against a table that did not exist a commit ago, in a
+# module whose one production outage (#2663) was a SQL shape the database
+# rejected inside a broad except. A mock would agree with whatever the code
+# does, including nothing.
+
+
+async def _rule_events(uid, rows):
+    """Write (event, source) pairs for one rule and hand back a cleanup."""
+    from sqlalchemy import delete
+
+    from scribe.models import async_session
+    from scribe.models.rule_usage import RuleUsageEvent
+
+    async with async_session() as s:
+        s.add_all([
+            RuleUsageEvent(user_id=uid, rule_id=rid, event=ev, source=src)
+            for rid, ev, src in rows
+        ])
+        await s.commit()
+
+    async def cleanup():
+        async with async_session() as s:
+            await s.execute(
+                delete(RuleUsageEvent).where(RuleUsageEvent.user_id == uid)
+            )
+            await s.commit()
+
+    return cleanup
+
+
+@pytest.mark.integration
+@pytest.mark.asyncio
+async def test_rule_usage_is_a_coherent_zero_on_a_fresh_install(_dispose_engine):
+    """Every rule in an existing install predates this table, so "no events" is
+    the normal state for a while. It must read as zero, not as a missing key
+    and not as a failure — the same "no rows" / "read broke" distinction the
+    rest of this readout keeps (#2663).
+
+    `pull_through` is None rather than 0.0, matching the note block: a ratio of
+    zero asserts "rules were shown and none opened", which with an empty
+    numerator AND denominator is a claim the data does not support.
+    """
+    from scribe.services.retrieval_telemetry import retrieval_summary
+
+    out = await retrieval_summary(990010, days=30)
+    assert out["read_failed"] is False
+    assert "rule_usage_failed" not in out["rule_usage"]
+    assert out["rule_usage"]["surfaced"] == 0
+    assert out["rule_usage"]["pulled"] == 0
+    assert out["rule_usage"]["distinct_rules_surfaced"] == 0
+    assert out["rule_usage"]["pull_through"] is None
+
+
+@pytest.mark.integration
+@pytest.mark.asyncio
+async def test_an_agent_reading_a_surfaced_rule_is_what_moves_the_ratio(_dispose_engine):
+    """The whole point of the milestone: the arm can now be told apart from a
+    bar it cannot fail to clear."""
+    from scribe.services.retrieval_telemetry import retrieval_summary
+
+    cleanup = await _rule_events(990011, [
+        (5001, "surfaced", "write_path_rule"),
+        (5002, "surfaced", "write_path_rule"),
+        (5001, "pulled", "mcp_get_rule"),
+    ])
+    try:
+        ru = (await retrieval_summary(990011, days=30))["rule_usage"]
+        assert ru["surfaced"] == 2
+        assert ru["pulled"] == 1
+        assert ru["pulled_by_agent"] == 1
+        assert ru["pulled_by_human"] == 0
+        assert ru["distinct_rules_surfaced"] == 2
+        assert ru["distinct_rules_pulled"] == 1
+        assert ru["pull_through"] == 0.5
+    finally:
+        await cleanup()
+
+
+@pytest.mark.integration
+@pytest.mark.asyncio
+async def test_a_person_browsing_the_rule_list_does_not_move_the_ratio(_dispose_engine):
+    """The mcp_/rest_ split, and it carries more weight here than for notes.
+
+    The arm's claim is "this rule may apply to what you are writing". Only an
+    agent opening it says that claim landed; a person clicking through the rule
+    list in the web UI says nothing about the hint. Both are still counted in
+    `pulled`, so "is this rule dead weight?" stays answerable.
+    """
+    from scribe.services.retrieval_telemetry import retrieval_summary
+
+    cleanup = await _rule_events(990012, [
+        (5003, "surfaced", "write_path_rule"),
+        (5003, "pulled", "rest_rule"),
+    ])
+    try:
+        ru = (await retrieval_summary(990012, days=30))["rule_usage"]
+        assert ru["pulled"] == 1
+        assert ru["pulled_by_human"] == 1
+        assert ru["pulled_by_agent"] == 0
+        # Surfaced once, opened by nobody who matters to this question.
+        assert ru["pull_through"] == 0.0
+    finally:
+        await cleanup()
+
+
+@pytest.mark.integration
+@pytest.mark.asyncio
+async def test_rule_events_stay_out_of_the_note_block(_dispose_engine):
+    """The separation, asserted rather than assumed.
+
+    `usage` is what existing callers already read and compare across windows.
+    If rule events leaked into it, that number would move for a reason nobody
+    was told about — and the rule arm would still be invisible, because a few
+    dozen rules against thousands of notes is noise on the note ratio.
+    """
+    from scribe.services.retrieval_telemetry import retrieval_summary
+
+    cleanup = await _rule_events(990013, [
+        (5004, "surfaced", "write_path_rule"),
+        (5004, "pulled", "mcp_get_rule"),
+    ])
+    try:
+        out = await retrieval_summary(990013, days=30)
+        assert out["rule_usage"]["surfaced"] == 1
+        # The note block saw none of it.
+        assert out["usage"]["surfaced"] == 0
+        assert out["usage"]["pulled"] == 0
+        assert out["usage"]["pull_through"] is None
+    finally:
+        await cleanup()
+
+
+@pytest.mark.integration
+@pytest.mark.asyncio
+async def test_rule_usage_sees_only_its_own_users_events(_dispose_engine):
+    """Same access rule as the rest of the readout — the owner filter IS the
+    rule for telemetry, which is not a shared record kind."""
+    from scribe.services.retrieval_telemetry import retrieval_summary
+
+    cleanup = await _rule_events(990014, [
+        (5005, "surfaced", "write_path_rule"),
+        (5005, "pulled", "mcp_get_rule"),
+    ])
+    try:
+        assert (await retrieval_summary(990015, days=30))["rule_usage"]["surfaced"] == 0
+        assert (await retrieval_summary(990014, days=30))["rule_usage"]["surfaced"] == 1
+    finally:
+        await cleanup()