From 8901c904a91fa28ab4f7e469c39d94670b8fb5bc Mon Sep 17 00:00:00 2001 From: Bryan Van Deusen Date: Wed, 2 Sep 2026 17:25:11 -0400 Subject: [PATCH] feat(telemetry): retrieval_telemetry reports rule pull-through where it reported nothing (#3317) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit 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) Claude-Session: https://claude.ai/code/session_01TcCs1CcQ1ormdnzSshKqvN --- src/scribe/mcp/tools/search.py | 40 ++++-- src/scribe/services/plugin_context.py | 8 +- src/scribe/services/retrieval_telemetry.py | 124 ++++++++++++++++- tests/test_services_retrieval_telemetry.py | 152 +++++++++++++++++++++ 4 files changed, 311 insertions(+), 13 deletions(-) diff --git a/src/scribe/mcp/tools/search.py b/src/scribe/mcp/tools/search.py index 410c308..e00730f 100644 --- a/src/scribe/mcp/tools/search.py +++ b/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. diff --git a/src/scribe/services/plugin_context.py b/src/scribe/services/plugin_context.py index dcd2120..9122417 100644 --- a/src/scribe/services/plugin_context.py +++ b/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 diff --git a/src/scribe/services/retrieval_telemetry.py b/src/scribe/services/retrieval_telemetry.py index 1377ecd..af27dda 100644 --- a/src/scribe/services/retrieval_telemetry.py +++ b/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 diff --git a/tests/test_services_retrieval_telemetry.py b/tests/test_services_retrieval_telemetry.py index df6ef87..e5b529b 100644 --- a/tests/test_services_retrieval_telemetry.py +++ b/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()