Milestone 379 closes: the readout can now say what it did not measure #144

Merged
bvandeusen merged 3 commits from dev into main 2026-09-08 16:06:15 -04:00
2 changed files with 96 additions and 2 deletions
Showing only changes of commit 5e19a1b028 - Show all commits
+2 -2
View File
@@ -1300,7 +1300,7 @@ async def build_write_path_hint(
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,
is_task=None, results=hits, duration_ms=rule_ms,
# What the ranker found and this session had already been told.
# Without it a zero row cannot say whether the bar was too high or
# the reader was simply ahead of it — and only the first is a
@@ -1404,7 +1404,7 @@ async def build_tool_rule_hint(
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,
is_task=None, results=hits, duration_ms=duration_ms,
# See the sibling arm. It matters more here: this arm fires on every
# Bash call, so a long session excludes its way to an all-zero row
# and the threshold looks wrong when nothing about it is.
+94
View File
@@ -772,3 +772,97 @@ async def test_a_shown_hit_is_not_counted_as_suppressed():
assert out["rule_ids"] == [161]
assert log.call_args.kwargs["suppressed"] == 1
assert len(log.call_args.kwargs["results"]) == 1
# ── The identity that falsified this milestone (#3668) ─────────────────
#
# `rule_usage.surfaced` == `pre_tool_rule.cleared` + `write_path_rule.cleared`.
# Milestone #379 was scoped on a reconstruction that put ~64% of ranked rule
# surfacings as never reaching `rule_usage_events`. Five steps were planned
# against it. One read of this identity — 17 = 17, then 39 = 39 on a second
# window — falsified the whole thing: the gap was two counters that started
# recording on different days, not a write path dropping rows.
#
# So the identity is not a nice-to-have. It is the cheapest true statement
# available about this pair of tables, and its absence is what let a magnitude
# that merely LOOKED wrong survive a code review and a five-step plan. An
# identity that must hold exactly beats a magnitude that looks wrong.
#
# WHY THE ARM IS THE RIGHT PLACE TO PIN IT, and the readout is not. Inside an
# arm, one `fresh` list feeds both recorders in one function, so the counts
# cannot legitimately differ — at any limit. The readout-level form is weaker
# than it looks: `cleared_threshold` counts CALLS that beat the bar while
# `surfaced` counts RULES, and those coincide only while `RULEHINT_LIMIT` is 1.
# Raise the limit and the readout identity breaks while nothing is wrong.
# `RULEHINT_LIMIT` has already moved once (2 → 1, `2385100`), and that move is
# half of why the original reconstruction misread its own numbers.
#
# Hence three hits below, where production currently returns at most one. The
# test is deliberately in a state the limit does not permit today, because what
# is being pinned is that the two recorders read the same list — not that the
# list happens to be short.
_THREE_HITS = [
(0.81, fake_rule(id=156, title="A wait with no deadline is a bug")),
(0.77, fake_rule(id=157, title="A loop re-arms in a finally")),
(0.74, fake_rule(id=161, title="Reach the forge through its MCP tools")),
]
_ARMS = [("write_path_rule", _run_arm), ("pre_tool_rule", _run_tool_arm)]
def _both_ends(log, rec, source):
"""What the two recorders said about one call, at the same grain.
Ids rather than counts. Equal counts drawn from different lists is a real
way for this to break — an off-by-one slice, or one recorder reading `hits`
where the other reads `fresh` in a window where the exclusion happened to
remove as many as it added — and a count comparison would call that agreement.
"""
rows = [c for c in log.call_args_list if c.kwargs.get("source") == source]
assert len(rows) == 1, (
f"expected exactly one {source} call row, got {len(rows)} — the "
f"identity is per call and cannot be read across several"
)
logged = [rule.id for _score, rule in rows[0].kwargs["results"]]
surfaced = [
rid
for c in rec.call_args_list if c.kwargs.get("source") == source
for rid in c.kwargs["rule_ids"]
]
return logged, surfaced
@pytest.mark.parametrize(("source", "run"), _ARMS, ids=["write_path", "pre_tool"])
@pytest.mark.parametrize(
("excluded", "expected"),
[([], 3), ([157], 2), ([156, 157, 161], 0)],
ids=["nothing-held", "one-already-held", "all-already-held"],
)
@pytest.mark.asyncio
async def test_both_recorders_report_the_same_rules_for_one_call(
source, run, excluded, expected
):
"""One list, two tables, no room to disagree.
The middle case is the one that discriminates. With nothing excluded both
recorders see the same three rules however wrongly they are wired, so an
arm logging `hits` to the call log and `fresh` to the surfacing log passes
that case and fails this one — and logging `hits` is exactly the divergence
that would manufacture an apparent write loss out of a correct system.
"""
log, rec = MagicMock(), MagicMock()
await run(list(_THREE_HITS), rec, retrieval_log=log, exclude_rule_ids=excluded)
logged, surfaced = _both_ends(log, rec, source)
assert surfaced == logged, (
f"{source} told its two tables different stories about one call: the "
f"call log recorded {logged} and the surfacing log recorded {surfaced}. "
f"Both come from `fresh`, in one function, so any difference is a bug "
f"in the wiring — and it is the shape that reads as a lost write when "
f"the two tables are later compared in aggregate (#3668)."
)
assert len(logged) == expected, (
"the fixture stopped exercising what it claims to; check the exclusion "
"filter still runs before both recorders"
)