From 154a5de13e4da02d02f4dcdfa0b36c958711030e Mon Sep 17 00:00:00 2001 From: Bryan Van Deusen Date: Thu, 3 Sep 2026 06:57:13 -0400 Subject: [PATCH 1/2] fix(telemetry): both rule arms logged only their hits, so the clear-rate could only read 100% (#3497) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit `write_path_rule` reported `zero_result_calls: 0` and `cleared_threshold: 133/133` — a perfect record no other surface comes near (`write_path` 421 zeroes of 613, `reuse_slot` 124/199, `auto_inject` 114/326). #3311 read that as a measurement and milestone 333 was scoped on it. It was an artifact. Both arms called `record_retrieval` inside a guard on having results — the write-path arm behind `if fresh:`, the pre-tool arm below `if not fresh: return out` — so a call that found nothing wrote no row. The statistic was a fact about the shape of the code, true at any threshold whatsoever. The call log moves out of the guard in both arms. The surfacing log stays in it: nothing was shown, so no surfacing occurred. `results=fresh` is kept deliberately — the note arms pass exclusions into `semantic_search_notes`, so what they log is already post-exclusion, and logging `hits` here would make this row mean something other than every other row in the same readout. The defect bites hardest on the pre-tool arm, which fires on every Bash call: with no rows at all, a ranker that declined is indistinguishable from a hook that never fired — the silent failure the arm exists to stop. Tests cover both arms behaviourally (found nothing; found only what the session already held; searched nothing at all, which must stay silent) plus a structural guard, because this was one level of indentation and it appeared independently in two places. #3311 and the `rule_usage` docstring corrected rather than quietly rewritten. Co-Authored-By: Claude Opus 5 (1M context) Claude-Session: https://claude.ai/code/session_011cPyzNnegXHr5iRMzzy5KJ --- src/scribe/services/plugin_context.py | 74 +++++++++---- src/scribe/services/rule_usage.py | 22 +++- tests/test_rule_usage_wiring.py | 147 ++++++++++++++++++++++++-- 3 files changed, 204 insertions(+), 39 deletions(-) diff --git a/src/scribe/services/plugin_context.py b/src/scribe/services/plugin_context.py index 18bee4e..589d166 100644 --- a/src/scribe/services/plugin_context.py +++ b/src/scribe/services/plugin_context.py @@ -1218,24 +1218,43 @@ async def build_write_path_hint( "does not apply; it is not in this session's loaded set." ) rule_ids.append(rule.id) + # 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. + # + # THE CALL LOG IS UNCONDITIONAL; THE SURFACING LOG IS NOT, and the + # asymmetry is the correction #3497 exists to make. Both used to sit + # inside an `if fresh:`, which is how this arm came to report + # `zero_result_calls: 0` and `cleared_threshold: 133/133` — not a + # perfectly tuned surface but one structurally unable to record its + # own misses. #3311 read that artifact as a measurement and a whole + # milestone was scoped on it. A call that found nothing is the ONLY + # evidence a threshold is set too high, and it is the row every note + # surface has always written (write_path: 421 zeroes of 613 calls; + # auto_inject: 114 of 326). A SURFACING is different in kind: nothing + # was shown, so no such event occurred, and its log stays guarded. + # + # `results=fresh`, not `hits`: the note arms pass their exclusions + # INTO semantic_search_notes, so what they log is already + # post-exclusion. semantic_search_rules takes no such parameter and + # this filter is where the equivalent happens — logging `hits` would + # quietly make this row mean something other than every other row in + # the same readout. + record_retrieval( + user_id=user_id, source="write_path_rule", query=code or path, + threshold=cfg["rule_threshold"], limit=RULEHINT_LIMIT, + project_id=project_id, + is_task=None, results=fresh, duration_ms=rule_ms, + ) if fresh: - # 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["rule_threshold"], limit=RULEHINT_LIMIT, - project_id=project_id, - 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 # it would inflate the denominator with claims the agent never saw @@ -1319,6 +1338,21 @@ async def build_tool_rule_hint( already = set(exclude_rule_ids or []) fresh = [(score, rule) for score, rule in hits if rule.id not in already] + + # Logged BEFORE the early return, for the reason spelled out at length + # on the write-path arm above: a call that found nothing is the only + # evidence a threshold is too high, and an arm that logs only the calls + # it liked reports a flawless clear-rate however badly it is tuned. + # This arm shipped with the same defect inherited from its sibling, and + # it mattered more here — a surface with no rows at all cannot be told + # apart from a hook that never fired, which is precisely the silent + # failure the arm was built to stop. + record_retrieval( + user_id=user_id, source="pre_tool_rule", query=query, + threshold=cfg["rule_threshold"], limit=RULEHINT_LIMIT, + project_id=project_id, + is_task=None, results=fresh, duration_ms=duration_ms, + ) if not fresh: return out @@ -1335,12 +1369,6 @@ async def build_tool_rule_hint( ) rule_ids.append(rule.id) - record_retrieval( - user_id=user_id, source="pre_tool_rule", query=query, - threshold=cfg["rule_threshold"], limit=RULEHINT_LIMIT, - project_id=project_id, - is_task=None, results=fresh, duration_ms=duration_ms, - ) # RANKED, not ambient: this arm chose what it showed, so a pull can # settle whether the choice was any good. `rule_usage.RANKED_SOURCES` # carries the same name. diff --git a/src/scribe/services/rule_usage.py b/src/scribe/services/rule_usage.py index b30402d..e053be1 100644 --- a/src/scribe/services/rule_usage.py +++ b/src/scribe/services/rule_usage.py @@ -12,11 +12,23 @@ Two event streams, deliberately independent: WHY THIS ARM AND NOT ANOTHER. Every other surface declines most of the time — `write_path` returns nothing on 78% of calls, `reuse_slot` on 79%, auto-inject -on 39%. The rule arm has never once returned nothing (#3311). That is either a -perfectly tuned surface or a bar it cannot fail to clear, and `retrieval_logs` -cannot tell the two apart: it records what the ranker scored, never whether the -hint was any use. The ratio these two streams produce is the missing half, and -without it any threshold change is a number picked off a histogram. +on 39%. The rule arm APPEARED never to have returned nothing (#3311), and this +docstring used to put that forward as the puzzle worth measuring: "either a +perfectly tuned surface or a bar it cannot fail to clear". + +It was neither, and the correction belongs here rather than being quietly +deleted. The arm wrote its `retrieval_logs` row only on calls that FOUND +something (#3497), so `zero_result_calls` sat at 0 and `cleared_threshold` at +`calls` because of the shape of the code — at any threshold whatsoever. A +statistic that could not vary was read as a finding about the corpus. It is the +#2663 failure mode one level up: there the broken readout was a zero, here it +was a hundred percent, which is far better camouflage. + +The reason to measure this arm survives the correction, and is stronger for it. +`retrieval_logs` records what the ranker scored, never whether the hint was any +use, so even an honest clear-rate would not settle the question. The ratio these +two streams produce is the missing half, and without it any threshold change is +a number picked off a histogram. Design notes, mirroring `note_usage`: - Writes are fire-and-forget through `background.spawn`, so telemetry never diff --git a/tests/test_rule_usage_wiring.py b/tests/test_rule_usage_wiring.py index a012b8c..e63cede 100644 --- a/tests/test_rule_usage_wiring.py +++ b/tests/test_rule_usage_wiring.py @@ -47,12 +47,14 @@ _PRIOR_ART = [(0.72, fake_note(id=9, title="debounce helper", user_id=1, note_type="snippet"))] -def _arm_patches(pc, hits, recorder, prior_art=None, cfg=None, rule_search=None): +def _arm_patches(pc, hits, recorder, prior_art=None, cfg=None, rule_search=None, + retrieval_log=None): """The minimum stubbing that lets the rule arm run and nothing else. - `cfg` and `rule_search` are overridable so a caller can inspect what the - arm ASKED for rather than only what it did with the answer — patching them - a second time on top would work, but reads as an accident. + `cfg`, `rule_search` and `retrieval_log` are overridable so a caller can + inspect what the arm ASKED for, and what it told the CALL log, rather than + only what it did with the answer — patching them a second time on top would + work, but reads as an accident. """ return ( patch.object(pc, "get_writepath_config", @@ -66,7 +68,7 @@ def _arm_patches(pc, hits, recorder, prior_art=None, cfg=None, rule_search=None) else prior_art)), patch.object(pc, "semantic_search_rules", rule_search or AsyncMock(return_value=hits)), - patch.object(pc, "record_retrieval", MagicMock()), + patch.object(pc, "record_retrieval", retrieval_log or MagicMock()), patch.object(pc, "record_surfaced", MagicMock()), patch.object(pc, "record_rule_surfaced", recorder), patch.object(pc, "owner_names_for", AsyncMock(return_value={})), @@ -74,10 +76,11 @@ def _arm_patches(pc, hits, recorder, prior_art=None, cfg=None, rule_search=None) ) -async def _run_arm(hits, recorder, prior_art=None, **kwargs): +async def _run_arm(hits, recorder, prior_art=None, retrieval_log=None, **kwargs): from scribe.services import plugin_context as pc with ExitStack() as stack: - for ctx in _arm_patches(pc, hits, recorder, prior_art): + for ctx in _arm_patches(pc, hits, recorder, prior_art, + retrieval_log=retrieval_log): stack.enter_context(ctx) return await pc.build_write_path_hint( 1, "frontend/src/api/client.ts", code="x" * 400, **kwargs @@ -410,7 +413,7 @@ def test_the_marker_paths_stay_silent(): # is why they all had to be resident. These cover the surface that changes it. -def _tool_patches(pc, hits, recorder, cfg=None): +def _tool_patches(pc, hits, recorder, cfg=None, retrieval_log=None): return ( patch.object(pc, "get_writepath_config", AsyncMock(return_value=cfg or { @@ -418,16 +421,16 @@ def _tool_patches(pc, hits, recorder, cfg=None): "top_k": 3, "rule_threshold": 0.6, })), patch.object(pc, "semantic_search_rules", AsyncMock(return_value=hits)), - patch.object(pc, "record_retrieval", MagicMock()), + patch.object(pc, "record_retrieval", retrieval_log or MagicMock()), patch.object(pc, "record_rule_surfaced", recorder), ) async def _run_tool_arm(hits, recorder, command="curl -s https://git.example/api/v1/runs", - tool="Bash", **kwargs): + tool="Bash", retrieval_log=None, **kwargs): from scribe.services import plugin_context as pc with ExitStack() as stack: - for ctx in _tool_patches(pc, hits, recorder): + for ctx in _tool_patches(pc, hits, recorder, retrieval_log=retrieval_log): stack.enter_context(ctx) return await pc.build_tool_rule_hint(1, tool, command, **kwargs) @@ -577,3 +580,125 @@ def test_the_hook_and_the_route_agree_on_every_parameter_name(): assert f'request.args.get("{arg}")' in handler, ( f"the hook sends {arg!r} and the route never reads it" ) + + +# ── The CALL log is unconditional; the SURFACING log is not (#3497) ──── +# +# Both arms used to write their retrieval_logs row inside a guard on having +# results, so `zero_result_calls` was pinned at 0 and `cleared_threshold` at +# `calls` by the shape of the code — at any threshold whatsoever. #3311 read +# that as a measurement of the corpus and a milestone was scoped on it. +# +# The distinction these tests hold: a CALL happened whether or not it found +# anything, and the calls that found nothing are the only evidence a threshold +# is set too high. A SURFACING did not happen when nothing was shown. + + +@pytest.mark.asyncio +async def test_the_write_path_arm_logs_the_call_that_found_nothing(): + log, rec = MagicMock(), MagicMock() + await _run_arm([], rec, retrieval_log=log) + + rule_calls = [c for c in log.call_args_list + if c.kwargs.get("source") == "write_path_rule"] + assert len(rule_calls) == 1, ( + "a rule call that found nothing wrote no row — `zero_result_calls` can " + "then only ever read 0, however badly the threshold is tuned" + ) + assert rule_calls[0].kwargs["results"] == [] + rec.assert_not_called() + + +@pytest.mark.asyncio +async def test_the_write_path_arm_logs_a_call_whose_only_hit_was_already_shown(): + """The subtler half. The ranker DID find something; the session had already + been told. That is a decline from the reader's side and must be logged as + one — the note arms get this for free by passing exclusions into the search, + so their zero-result rows already include this case.""" + log, rec = MagicMock(), MagicMock() + hits = [(0.71, fake_rule(id=156, title="A wait with no deadline is a bug"))] + await _run_arm(hits, rec, retrieval_log=log, exclude_rule_ids=[156]) + + rule_calls = [c for c in log.call_args_list + if c.kwargs.get("source") == "write_path_rule"] + assert len(rule_calls) == 1 + assert rule_calls[0].kwargs["results"] == [], ( + "the row must record what the arm could SHOW, so this row is comparable " + "with an auto_inject row, whose exclusions are applied by the search" + ) + rec.assert_not_called() + + +@pytest.mark.asyncio +async def test_the_tool_arm_logs_the_call_that_found_nothing(): + """It matters more here than on the sibling. This arm fires on every Bash + call, so an empty `sources` row is the normal outcome — and with no row at + all, "the ranker declined" is indistinguishable from "the hook never fired", + which is exactly the silent failure the arm was built to stop (#3476).""" + log, rec = MagicMock(), MagicMock() + out = await _run_tool_arm([], rec, retrieval_log=log) + + assert out == {"context": "", "rule_ids": []} + assert log.call_count == 1 + assert log.call_args.kwargs["source"] == "pre_tool_rule" + assert log.call_args.kwargs["results"] == [] + assert log.call_args.kwargs["query"] == "curl -s https://git.example/api/v1/runs", ( + "the query is the point of the row: it is what a threshold is tuned against" + ) + rec.assert_not_called() + + +@pytest.mark.asyncio +async def test_the_tool_arm_logs_a_call_whose_only_hit_was_already_shown(): + log, rec = MagicMock(), MagicMock() + hits = [(0.71, fake_rule(id=161, title="Reach the forge through its MCP tools"))] + out = await _run_tool_arm(hits, rec, retrieval_log=log, exclude_rule_ids=[161]) + + assert out["rule_ids"] == [] + assert log.call_count == 1 + assert log.call_args.kwargs["results"] == [] + rec.assert_not_called() + + +@pytest.mark.asyncio +async def test_a_command_the_arm_never_searched_writes_no_row_at_all(): + """The one case that must stay silent, and the boundary of the rule above. + + A blank command costs no embedding query, so there was no retrieval to log. + A row here would report a call that never happened and drag the clear-rate + down with phantom declines — the mirror of the defect, from the other side. + """ + from scribe.services import plugin_context as pc + + log = MagicMock() + with ExitStack() as stack: + for ctx in _tool_patches(pc, [], MagicMock(), retrieval_log=log): + stack.enter_context(ctx) + await pc.build_tool_rule_hint(1, "Bash", " ") + + log.assert_not_called() + + +def test_neither_rule_arm_logs_its_call_behind_a_results_guard(): + """Structural, on top of the behavioural pair above, because the defect was + one level of indentation and it appeared INDEPENDENTLY in two places — the + pre-tool arm inherited it by being modelled on its sibling. The third arm + modelled on either of them is the one this catches. + """ + pc_src = Path("src/scribe/services/plugin_context.py").read_text() + + # Write-path arm: what remains inside `if fresh:` is the SURFACING log only. + guarded = pc_src.split('source="write_path_rule", query=code or path')[1] + guarded = guarded.split("if fresh:")[1].split("except Exception:")[0] + assert "record_rule_surfaced" in guarded, "the surfacing log must stay guarded" + assert "record_retrieval" not in guarded, ( + "the call log is back inside the results guard — a call that found " + "nothing is the only evidence a threshold is set too high" + ) + + # Pre-tool arm: the call log comes BEFORE the early return. + body = pc_src.split("async def build_tool_rule_hint")[1] + assert body.index('source="pre_tool_rule"') < body.index("if not fresh:"), ( + "the pre-tool arm returns before logging its call — a surface with no " + "rows at all cannot be told apart from a hook that never fired" + ) From 48804c437d574b3a7b75fbdce716e934312c0863 Mon Sep 17 00:00:00 2001 From: Bryan Van Deusen Date: Thu, 3 Sep 2026 06:59:52 -0400 Subject: [PATCH 2/2] fix(tests): the write-path telemetry test asserted the defect, not the split (#3497) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit `assert_called_once` held only because the rule arm skipped its retrieval_logs row when it found nothing. With the arm logging every call, the test now asserts what it was always about — exactly one `write_path` row, no `auto_inject`, and the rule arm keeping its own separate source. Co-Authored-By: Claude Opus 5 (1M context) Claude-Session: https://claude.ai/code/session_011cPyzNnegXHr5iRMzzy5KJ --- tests/test_write_path_trigger.py | 16 ++++++++++++---- 1 file changed, 12 insertions(+), 4 deletions(-) diff --git a/tests/test_write_path_trigger.py b/tests/test_write_path_trigger.py index ef1c3c0..72ad0d6 100644 --- a/tests/test_write_path_trigger.py +++ b/tests/test_write_path_trigger.py @@ -360,10 +360,18 @@ async def test_telemetry_uses_its_own_source(): patch.object(pc, "record_retrieval", rec), \ patch.object(pc, "owner_names_for", AsyncMock(return_value={})): await pc.build_write_path_hint(1, "src/x.py", code=REAL_CODE, project_id=4) - rec.assert_called_once() - assert rec.call_args.kwargs["source"] == "write_path" - assert rec.call_args.kwargs["source"] != "auto_inject" - assert rec.call_args.kwargs["project_id"] == 4 + sources = [c.kwargs["source"] for c in rec.call_args_list] + assert sources.count("write_path") == 1, sources + assert "auto_inject" not in sources + + note_arm = next(c for c in rec.call_args_list if c.kwargs["source"] == "write_path") + assert note_arm.kwargs["project_id"] == 4 + + # The rule arm rides along on the same hint and logs its own call even when + # it finds nothing (#3497). This assertion used to be `assert_called_once`, + # which passed only because that row was never written — the test encoded + # the defect. The second row is the point of having two sources. + assert "write_path_rule" in sources, sources @pytest.mark.asyncio