From 8f7f447fda5d2da181a604d18481ec93c7302065 Mon Sep 17 00:00:00 2001 From: Bryan Van Deusen Date: Wed, 2 Sep 2026 17:15:03 -0400 Subject: [PATCH] feat(telemetry): the rule arm records what it showed, and get_rule records the read (#3316) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit 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) Claude-Session: https://claude.ai/code/session_01TcCs1CcQ1ormdnzSshKqvN --- src/scribe/mcp/tools/rulebooks.py | 6 + src/scribe/routes/rulebooks.py | 6 + src/scribe/services/plugin_context.py | 23 ++- tests/test_rule_usage_wiring.py | 204 ++++++++++++++++++++++++++ 4 files changed, 235 insertions(+), 4 deletions(-) create mode 100644 tests/test_rule_usage_wiring.py diff --git a/src/scribe/mcp/tools/rulebooks.py b/src/scribe/mcp/tools/rulebooks.py index ca6a8c3..178cbbe 100644 --- a/src/scribe/mcp/tools/rulebooks.py +++ b/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) diff --git a/src/scribe/routes/rulebooks.py b/src/scribe/routes/rulebooks.py index 629ba1c..17ab59c 100644 --- a/src/scribe/routes/rulebooks.py +++ b/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)) diff --git a/src/scribe/services/plugin_context.py b/src/scribe/services/plugin_context.py index f6a5066..dcd2120 100644 --- a/src/scribe/services/plugin_context.py +++ b/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 - # remapped on a backup restore, so a rule id there would return - # attached to whatever note took that number. This one is never - # restored, and `source` already separates the surfaces. + # 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, + # 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) diff --git a/tests/test_rule_usage_wiring.py b/tests/test_rule_usage_wiring.py new file mode 100644 index 0000000..5efbcd2 --- /dev/null +++ b/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." + )