Merge pull request 'fix(telemetry): both rule arms logged only their hits, so the clear-rate could only read 100% (#3497)' (#138) from dev into main

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.

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
+on 39%. The rule arm APPEARED never to have returned nothing (#3311), and this
-perfectly tuned surface or a bar it cannot fail to clear, and `retrieval_logs`
+docstring used to put that forward as the puzzle worth measuring: "either a
-cannot tell the two apart: it records what the ranker scored, never whether the
+perfectly tuned surface or a bar it cannot fail to clear".
-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.
+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

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
+    `cfg`, `rule_search` and `retrieval_log` are overridable so a caller can
-    arm ASKED for rather than only what it did with the answer — patching them
+    inspect what the arm ASKED for, and what it told the CALL log, rather than
-    a second time on top would work, but reads as an accident.
+    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"
+    )

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()
+    sources = [c.kwargs["source"] for c in rec.call_args_list]
-    assert rec.call_args.kwargs["source"] == "write_path"
+    assert sources.count("write_path") == 1, sources
-    assert rec.call_args.kwargs["source"] != "auto_inject"
+    assert "auto_inject" not in sources
-    assert rec.call_args.kwargs["project_id"] == 4
+
+    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