feat(telemetry): the rule arm records what it showed, and get_rule records the read (#3316)

Milestone 333 step 2. Step 1 built the table; a counter nobody calls reads zero
and looks exactly like a surface nobody uses, which is #2663's shape.

SURFACED — the standing-rule arm in build_write_path_hint, beside the
record_retrieval it already made. Two tables, and the split is not arbitrary:
retrieval_logs is one row per CALL keyed on the score distribution a threshold
is tuned from; rule_usage_events is one row per RULE per event, the grain "was
this hint ever acted on" needs and the grain a JSONB result_ids array cannot be
indexed at.

The comment there said rule ids had nowhere to go — that note_usage_events
remaps ids on restore, so a rule id would return attached to whatever note took
that number. Still true of the NOTE table, and precisely why step 1 built its
own. Rewritten to say the gap is closed rather than leaving a stale rationale
that would have someone re-derive the same dead end.

Records `fresh`, i.e. AFTER exclude_rule_ids. A rule the session already holds
was considered and not shown; counting it would inflate the denominator with
claims the agent never saw, and the ratio would then fall for a reason that has
nothing to do with whether hints land.

PULLED — two doors, both after their access check so a refused read is not a
pull. mcp_get_rule is the one that matters: the arm's own message ends "Read it
with get_rule(N)", so that call is the exact action a landed hint produces.
rest_rule carries the other prefix, and the prefix is load-bearing — "is this
rule dead weight?" is served by any pull, "did that injected hint land?" by
agent pulls only.

NOT a pull: rule_history. It loads the rule for its title and its own output
says "The current wording is on the rule itself — get_rule(N)", so counting it
would credit a read of the history as a read of the rule and double-count
anyone who then follows that pointer. list_always_on_rules and enter_project
are likewise bulk resident loads, not somebody choosing to open one record.

tests/test_rule_usage_wiring.py is cross-cutting on purpose: the surfaced end
is in plugin_context, the pull end in two other modules, and "both ends meet"
is a property no module-shaped file asserts. It covers the exclusion boundary,
that a failing recorder cannot break the write, that a refused read records
nothing, and two completeness guards — every door records, and the bulk loaders
still do not.

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

src/scribe/mcp/tools/rulebooks.py

@@ -18,6 +18,7 @@ from scribe.mcp._context import current_user_id
 from scribe.services import dedup as dedup_svc
 from scribe.services import rulebooks as rulebooks_svc
 from scribe.services import trash as trash_svc
+from scribe.services.rule_usage import record_rule_pulled
 
 
 # ── Rulebook CRUD ───────────────────────────────────────────────────────
@@ -288,6 +289,11 @@ async def get_rule(rule_id: int) -> dict:
     rule = await rulebooks_svc.get_rule(rule_id, uid)
     if rule is None:
         raise ValueError(f"rule {rule_id} not found")
+    # THE pull that matters. The write-path rule arm's own message ends "Read
+    # it with get_rule(N)", so this is the exact action the hint asks for and
+    # the only evidence that one landed. Recorded after the access check, so a
+    # refused read is not counted as a pull.
+    record_rule_pulled(user_id=uid, rule_id=int(rule.id), source="mcp_get_rule")
     return await rulebooks_svc.rule_detail(uid, rule)
 
 

src/scribe/routes/rulebooks.py

@@ -10,6 +10,7 @@ from quart import Blueprint, jsonify, request
 from scribe.auth import get_current_user_id, login_required
 import scribe.services.rulebooks as rulebooks_svc
 from scribe.services.trash import delete as trash_delete
+from scribe.services.rule_usage import record_rule_pulled
 
 rulebooks_bp = Blueprint("rulebooks", __name__, url_prefix="/api")
 
@@ -182,6 +183,11 @@ async def get_rule(rule_id: int):
     rule = await rulebooks_svc.get_rule(rule_id, uid)
     if rule is None:
         return jsonify({"error": "rule not found"}), 404
+    # `rest_` rather than `mcp_`, and the prefix is load-bearing: "is this rule
+    # dead weight?" is served by any pull, but "did that injected hint land?"
+    # — the question this arm exists to answer — is served by AGENT pulls only.
+    # A person clicking through the rule list says nothing about the hint.
+    record_rule_pulled(user_id=uid, rule_id=int(rule.id), source="rest_rule")
     return jsonify(await rulebooks_svc.rule_detail(uid, rule))
 
 

src/scribe/services/plugin_context.py

@@ -32,6 +32,7 @@ from scribe.services import snippets as snippets_svc
 from scribe.services.access import label_shared_items, owner_names_for
 from scribe.services.embeddings import semantic_search_notes, semantic_search_rules
 from scribe.services.note_usage import record_surfaced
+from scribe.services.rule_usage import record_rule_surfaced
 from scribe.services.supersession import superseded_ids
 from scribe.services.retrieval_telemetry import record_retrieval
 from scribe.services.settings import get_setting
@@ -1140,15 +1141,29 @@ async def build_write_path_hint(
             )
             rule_ids.append(rule.id)
         if fresh:
-            # retrieval_logs, NOT note_usage_events: that table's ids are
+            # TWO tables, and the split is not arbitrary. retrieval_logs is one
-            # remapped on a backup restore, so a rule id there would return
+            # row per CALL, keyed on the score distribution a threshold is
-            # attached to whatever note took that number. This one is never
+            # tuned from. rule_usage_events is one row per RULE per event,
-            # restored, and `source` already separates the surfaces.
+            # which is the grain "was this hint ever acted on" needs and the
+            # grain a JSONB result_ids array cannot be indexed at.
+            #
+            # This comment used to say rule ids had nowhere to go — that
+            # note_usage_events remaps ids on restore, so a rule id there would
+            # return attached to whatever note took that number. That is still
+            # true of the NOTE table, and it is exactly why rule_usage_events
+            # is its own (milestone 333 step 1). The gap it described is closed.
             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,
             )
+            # `rule_ids` is `fresh`, i.e. AFTER exclude_rule_ids. A rule the
+            # session already holds was considered and not shown, and counting
+            # it would inflate the denominator with claims the agent never saw
+            # — which reads as a precision problem this arm does not have.
+            record_rule_surfaced(
+                user_id=user_id, rule_ids=rule_ids, source="write_path_rule",
+            )
     except Exception:
         logger.debug("write-path rule arm failed", exc_info=True)
 

tests/test_rule_usage_wiring.py

@@ -0,0 +1,204 @@
+"""Both ends of the rule-usage loop are actually wired (milestone 333 step 2).
+
+Step 1 built the table and the service. A counter nobody calls reads zero and
+looks exactly like a surface nobody uses — which is #2663's shape and the whole
+reason this milestone exists. So this file is about the CALL SITES, not the
+storage.
+
+Cross-cutting on purpose: the surfaced end lives in `plugin_context`, the pull
+end in two different doors, and the property under test is that they meet. Split
+across three module-shaped files, "both ends are wired" is a thing no single
+test asserts.
+"""
+from contextlib import ExitStack
+from pathlib import Path
+from unittest.mock import AsyncMock, MagicMock, patch
+
+import pytest
+
+from tests.helpers import fake_rule
+
+# The MCP tool layer reads its caller from a ContextVar the HTTP transport sets
+# per request; a unit test has no request, so it binds the caller itself. The
+# arm tests do not need it — build_write_path_hint takes user_id directly — but
+# the module-level mark is how every tool-layer test file in this repo opts in.
+pytestmark = pytest.mark.usefixtures("_bind_user")
+
+
+# ── The surfaced end ───────────────────────────────────────────────────
+#
+# conftest's autouse `_no_rule_arm` stubs `semantic_search_rules` so unrelated
+# plugin-context tests don't pull a real embedding model through this arm. Its
+# docstring says a test that wants the arm live can re-patch it — that is what
+# each of these does.
+
+
+def _arm_patches(pc, hits, recorder):
+    """The minimum stubbing that lets the rule arm run and nothing else."""
+    return (
+        patch.object(pc, "get_writepath_config",
+                     AsyncMock(return_value={"enabled": True, "threshold": 0.6,
+                                             "top_k": 3})),
+        patch.object(pc.snippets_svc, "list_snippets", AsyncMock(return_value=([], 0))),
+        patch.object(pc, "semantic_search_notes", AsyncMock(return_value=[])),
+        patch.object(pc, "semantic_search_rules", AsyncMock(return_value=hits)),
+        patch.object(pc, "record_retrieval", MagicMock()),
+        patch.object(pc, "record_surfaced", MagicMock()),
+        patch.object(pc, "record_rule_surfaced", recorder),
+        patch.object(pc, "owner_names_for", AsyncMock(return_value={})),
+        patch.object(pc, "concept_query", MagicMock(return_value="a deadline on a fetch")),
+    )
+
+
+async def _run_arm(hits, recorder, **kwargs):
+    from scribe.services import plugin_context as pc
+    with ExitStack() as stack:
+        for ctx in _arm_patches(pc, hits, recorder):
+            stack.enter_context(ctx)
+        return await pc.build_write_path_hint(
+            1, "frontend/src/api/client.ts", code="x" * 400, **kwargs
+        )
+
+
+@pytest.mark.asyncio
+async def test_the_arm_records_what_it_showed():
+    """The claim being measured. Without this call the arm keeps producing
+    scores in retrieval_logs and no evidence that any hint was ever read."""
+    rec = MagicMock()
+    hits = [(0.71, fake_rule(id=156, title="A wait with no deadline is a bug"))]
+    await _run_arm(hits, rec)
+
+    assert rec.call_count == 1
+    kw = rec.call_args.kwargs
+    assert kw["rule_ids"] == [156]
+    assert kw["source"] == "write_path_rule"
+
+
+@pytest.mark.asyncio
+async def test_a_rule_the_session_already_holds_is_not_counted_as_surfaced():
+    """`exclude_rule_ids` drops what the session already has, and the recorded
+    set must be what was SHOWN, not what was considered.
+
+    Counting the excluded ones would inflate the denominator with claims the
+    agent never saw — the ratio would fall for a reason that has nothing to do
+    with whether the hints landed, which is precisely the misreading this
+    milestone exists to prevent.
+    """
+    rec = MagicMock()
+    hits = [
+        (0.71, fake_rule(id=156, title="A wait with no deadline is a bug")),
+        (0.70, fake_rule(id=157, title="A loop re-arms in a finally")),
+    ]
+    await _run_arm(hits, rec, exclude_rule_ids=[157])
+
+    assert rec.call_args.kwargs["rule_ids"] == [156]
+
+
+@pytest.mark.asyncio
+async def test_nothing_is_recorded_when_every_hit_was_already_held():
+    """No surfacing happened, so no surfacing is recorded. A zero-row batch
+    would still be a call, and a call that says "we showed nothing" pollutes
+    the count of times the arm spoke."""
+    rec = MagicMock()
+    hits = [(0.71, fake_rule(id=156, title="A wait with no deadline is a bug"))]
+    await _run_arm(hits, rec, exclude_rule_ids=[156])
+
+    assert rec.call_count == 0
+
+
+@pytest.mark.asyncio
+async def test_a_failing_recorder_does_not_break_the_write():
+    """Telemetry must never take down the surface it observes. The arm is
+    already wrapped in a fail-open try/except; this pins that the new call is
+    INSIDE it rather than after."""
+    rec = MagicMock(side_effect=RuntimeError("telemetry is down"))
+    hits = [(0.71, fake_rule(id=156, title="A wait with no deadline is a bug"))]
+    out = await _run_arm(hits, rec)
+
+    assert "context" in out
+
+
+# ── The pull end ───────────────────────────────────────────────────────
+
+
+@pytest.mark.asyncio
+async def test_mcp_get_rule_records_an_agent_pull():
+    """THE pull that matters: the arm's own message ends "Read it with
+    get_rule(N)", so this is the exact action a landed hint produces."""
+    rec = MagicMock()
+    rule = fake_rule(id=156, title="A wait with no deadline is a bug")
+    with patch("scribe.mcp.tools.rulebooks.rulebooks_svc.get_rule",
+               AsyncMock(return_value=rule)), \
+         patch("scribe.mcp.tools.rulebooks.rulebooks_svc.rule_detail",
+               AsyncMock(return_value={"id": 156})), \
+         patch("scribe.mcp.tools.rulebooks.record_rule_pulled", rec):
+        from scribe.mcp.tools.rulebooks import get_rule
+        await get_rule(rule_id=156)
+
+    assert rec.call_args.kwargs["rule_id"] == 156
+    assert rec.call_args.kwargs["source"] == "mcp_get_rule"
+
+
+@pytest.mark.asyncio
+async def test_a_rule_that_cannot_be_read_is_not_a_pull():
+    """Recorded after the access check. A refused read is not a pull, and
+    counting it would credit the arm for a hint nobody could open."""
+    rec = MagicMock()
+    with patch("scribe.mcp.tools.rulebooks.rulebooks_svc.get_rule",
+               AsyncMock(return_value=None)), \
+         patch("scribe.mcp.tools.rulebooks.record_rule_pulled", rec):
+        from scribe.mcp.tools.rulebooks import get_rule
+        with pytest.raises(ValueError):
+            await get_rule(rule_id=156)
+
+    assert rec.call_count == 0
+
+
+# ── Completeness: every door, and only the doors ───────────────────────
+
+
+def _source_of(module_path: str) -> str:
+    return (Path(__file__).resolve().parents[1] / module_path).read_text()
+
+
+def test_every_rule_detail_door_records_a_pull():
+    """The task's own warning, made mechanical: miss a door and the ratio
+    reads low for a reason that is not about the rules.
+
+    Source inspection rather than behaviour, because the REST door has no
+    live-HTTP harness in the unit lane (see test_routes_rulebooks.py's own
+    note). What it can still prove is that the handler names the recorder —
+    which is the thing that gets forgotten when a door is added.
+    """
+    rest = _source_of("src/scribe/routes/rulebooks.py")
+    mcp = _source_of("src/scribe/mcp/tools/rulebooks.py")
+    assert 'source="rest_rule"' in rest, (
+        "the REST rule-detail route does not record a pull"
+    )
+    assert 'source="mcp_get_rule"' in mcp, (
+        "the MCP get_rule tool does not record a pull"
+    )
+
+
+def test_the_bulk_loaders_are_not_counted_as_pulls():
+    """`list_always_on_rules` and `enter_project` hand over every applicable
+    rule at once. That is delivery, not somebody choosing to open one record,
+    and counting it would swamp the signal with exactly the ambient surfacing
+    the ratio exists to distinguish from.
+
+    Stated as a test because it is the tempting addition: both put rules in
+    front of an agent, so "surely those are pulls too" is the reading someone
+    arrives at without the argument.
+    """
+    for path in ("src/scribe/mcp/tools/rulebooks.py",
+                 "src/scribe/mcp/tools/projects.py"):
+        src = _source_of(path)
+        for door in ("list_always_on_rules", "enter_project"):
+            if f"async def {door}" not in src:
+                continue
+            body = src.split(f"async def {door}", 1)[1].split("\nasync def ", 1)[0]
+            assert "record_rule_pulled" not in body, (
+                f"{door} records a pull. It is a bulk resident load — every "
+                "applicable rule at once — so counting it would drown the "
+                "surfaced:pulled ratio in ambient delivery."
+            )