From bb8013928fd9022f85df09a0c767bd4974508eff Mon Sep 17 00:00:00 2001 From: Bryan Van Deusen Date: Mon, 21 Sep 2026 00:13:45 -0400 Subject: [PATCH] feat(telemetry): the readout names rules that were opened and changed nothing (#4213) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Milestone 419 step 2. Step 1 made an outcome recordable; this makes it readable. `retrieval_summary`'s rule block gains `applied`, `departed` and `distinct_rules_acted`, and `_compute_warnings` gains two codes. TWO CODES, NOT ONE WITH A ZERO IN IT. `read_and_unacted` reports rules that were opened and left no outcome, against the ones that did. It only fires once outcomes exist anywhere in the window, because a window with none cannot tell "every rule was ignored" from "nothing calls `rule_outcome` yet" — and on every install the day this ships, the truth is the second. Claiming the first there would be #3311's failure exactly: a statistic that could not vary being read as a fact about the corpus. The cold case gets its own code, `outcomes_never_recorded`, whose prose says in as many words that it does NOT mean the rules were ignored. `applied` AND `departed` ARE NOT SUMMED. A departure carries the reason the agent gave and is evidence about the RULE; an application is evidence about the agent. Folded together they would say only "an outcome exists", which is true of both and useful about neither. `distinct_rules_acted` counts either, because for the unacted arithmetic the distinction does not matter. An outcome is not a pull. The fold branches on OUTCOMES first and never routes an outcome through the surfaced/ambient split: `source` on an outcome row names the door the outcome came through, not a ranker, so the ambient distinction has nothing to say about it. An integration test holds that line — if an outcome leaked into the pull counters the silently-unchanged rule would vanish into a compliant-looking total, which is the confusion #4212 was opened to end. Verified by lifting the shipped `_compute_warnings` out of source with `ast` and exercising it against the six populations the new tests assert: cold instrument, warm instrument, departures-only, full compliance, nothing opened, and a failed read. The integration tests for the new counts run against real Postgres in CI — count(distinct) with an IN over an unconstrained column is a SQL shape a mock would agree with whatever it did, which is what #2663 was. Co-Authored-By: Claude Opus 5 Claude-Session: https://claude.ai/code/session_01821k5B3Ysecp9fNYs92Kuy --- src/scribe/mcp/tools/search.py | 27 +++++++ src/scribe/services/retrieval_telemetry.py | 81 +++++++++++++++++++++ tests/test_retrieval_warnings.py | 83 ++++++++++++++++++++++ tests/test_services_retrieval_telemetry.py | 66 +++++++++++++++++ 4 files changed, 257 insertions(+) diff --git a/src/scribe/mcp/tools/search.py b/src/scribe/mcp/tools/search.py index 517b6eb..713b250 100644 --- a/src/scribe/mcp/tools/search.py +++ b/src/scribe/mcp/tools/search.py @@ -336,6 +336,18 @@ It is an UPPER BOUND per surface: a pull records the door it came `pulled_by_human`, the distinct-rule counts, and `pull_through` on the same definition (agent pulls over RANKED surfacings). + `applied`, `departed` AND `distinct_rules_acted` ARE WHAT HAPPENED AFTER + THE RULE WAS OPENED (#4213). A pull says the rule was read; these say it + changed something. `applied` counts rules followed, `departed` rules + deliberately not followed — kept apart rather than summed, because a + departure carries the reason the agent gave and is evidence about the + RULE, while an application is evidence about the agent. There is + deliberately no count of rules read and quietly ignored: that state is what + is left over when a rule was pulled and neither outcome arrived, and + `read_and_unacted` below is where it is reported. Asking an agent to + declare it would be asking it to notice an omission it is defined by not + noticing. + A SEPARATE BLOCK, not folded into `usage`, and reading it as one number with that is the mistake to avoid. The corpora differ by orders of magnitude — a few dozen eligible rules against thousands of notes — so a @@ -418,6 +430,21 @@ It is an UPPER BOUND per surface: a pull records the door it came - `surfaced_never_pulled` — distinct records shown and never opened, per corpus. Read their titles before touching a threshold: a record nobody opens is usually one whose title does not say when it matters. + - `read_and_unacted` — distinct rules OPENED in the window that recorded + no outcome, against the ones that did. The failure milestone 419 was + opened on, and the worse sibling of `surfaced_never_pulled` above: a + rule nobody opens is cheap, while a rule read and silently unchanged is + indistinguishable from one that worked. It does not say which of the two + causes it is — a rule mis-triggering, arriving where it does not apply, + or a rule being ignored — and those want opposite fixes, so read the + rules before moving anything. + - `outcomes_never_recorded` — rules were opened and NOT ONE outcome exists + anywhere in the window. Deliberately a separate code, and not a + `read_and_unacted` with a zero in it: a window with no outcomes at all + cannot tell "every rule was ignored" from "nothing on this install calls + `rule_outcome` yet", and reporting the first would manufacture a finding + out of an unwired feature. Wire the outcome call before reading this as + a fact about the corpus. - `unregistered_source` — rows under a source missing from `retrieval_registry`. Its numbers are real; no verdict could be computed, because nothing says whether it was asked or fired unbidden. diff --git a/src/scribe/services/retrieval_telemetry.py b/src/scribe/services/retrieval_telemetry.py index bcf6233..b849d25 100644 --- a/src/scribe/services/retrieval_telemetry.py +++ b/src/scribe/services/retrieval_telemetry.py @@ -28,6 +28,9 @@ from scribe.models import async_session from scribe.models.base import iso from scribe.models.note import Note from scribe.models.note_usage import PULLED, SURFACED, NoteUsageEvent +from scribe.models.rule_usage import OUTCOMES as RULE_OUTCOMES +from scribe.models.rule_usage import APPLIED as RULE_APPLIED +from scribe.models.rule_usage import DEPARTED as RULE_DEPARTED from scribe.models.rule_usage import PULLED as RULE_PULLED from scribe.models.rule_usage import SURFACED as RULE_SURFACED from scribe.models.rule_usage import RuleUsageEvent @@ -636,6 +639,52 @@ def _compute_warnings(sources: dict, usage: dict, rule_usage: dict, surfaced=int(shown), pulled=int(pulled or 0), never_pulled=never, )) + # ── A rule that was read and changed nothing (#4213, milestone 419) ── + # + # The failure this milestone was opened on, and the one number that could + # not previously be computed. `surfaced_never_pulled` above catches a rule + # nobody opens; this catches the worse case — a rule the agent DID open, + # deliberately, and then left no trace of having acted on. Until #4212 + # those were arithmetically identical to compliance. + opened = int(rule_usage.get("distinct_rules_pulled") or 0) + acted = int(rule_usage.get("distinct_rules_acted") or 0) + applied = int(rule_usage.get("applied") or 0) + departed = int(rule_usage.get("departed") or 0) + + if opened and not (applied or departed): + # THE HONEST ANSWER WHILE THE INSTRUMENT IS COLD, and the reason this + # is a separate code rather than a zero fed into the check below. + # Outcomes only started being recorded in milestone 419; a window + # containing none cannot tell "every rule was ignored" from "nothing + # reports outcomes yet". Emitting the ignored-rules warning here would + # manufacture a finding out of an unwired feature — #3311's mistake + # exactly, where a statistic that could not vary was read as a fact + # about the corpus. + out.append(_warn( + "outcomes_never_recorded", + f"{opened} distinct rules were opened in this window and not one " + f"recorded an outcome. This does NOT mean they were ignored — it " + f"means nothing is calling `rule_outcome`, so the difference " + f"between a rule that worked and a rule that was read and " + f"forgotten is still unmeasured here.", + source=None, opened=opened, applied=0, departed=0, + )) + elif opened: + unacted = opened - acted + if unacted > 0: + out.append(_warn( + "read_and_unacted", + f"{unacted} of {opened} distinct rules were opened in this " + f"window and left no outcome, against {acted} that did. A rule " + f"read and silently unchanged looks exactly like one that " + f"worked; these are the ones where nobody can tell. Either the " + f"rule is mis-triggering — it arrives, gets read, and does not " + f"apply — or it is being ignored, and the two want opposite " + f"fixes.", + source=None, opened=opened, acted=acted, unacted=unacted, + applied=applied, departed=departed, + )) + return out @@ -1063,10 +1112,26 @@ async def retrieval_summary( ) ) ).scalar_one() + # Rules that were OPENED AND THEN ACTED ON (#4212). Its own + # distinct count for the same reason the two above have one: + # "how many rules did anything come of" cannot be summed from + # the per-source group without double-counting a rule that was + # applied once and departed from once. + distinct_rules_acted = ( + await session.execute( + select(func.count(func.distinct(RuleUsageEvent.rule_id))) + .where( + RuleUsageEvent.created_at >= since, + RuleUsageEvent.user_id == user_id, + RuleUsageEvent.event.in_(RULE_OUTCOMES), + ) + ) + ).scalar_one() except Exception: logger.warning("rule usage read failed", exc_info=True) rule_rows = None distinct_rules_surfaced = distinct_rules_pulled = 0 + distinct_rules_acted = 0 except Exception: logger.warning("retrieval summary read failed", exc_info=True) out["read_failed"] = True @@ -1175,6 +1240,13 @@ async def retrieval_summary( "pulled": 0, "pulled_by_agent": 0, "pulled_by_human": 0, "distinct_rules_surfaced": int(distinct_rules_surfaced or 0), "distinct_rules_pulled": int(distinct_rules_pulled or 0), + # The outcome half (#4212, milestone 419). `pulled` says a rule was + # opened; these say whether anything came of it. Until this existed, a + # rule obeyed every time and a rule ignored every time produced + # identical rows, and the second is the one worth finding. + "applied": 0, + "departed": 0, + "distinct_rules_acted": int(distinct_rules_acted or 0), } if rule_rows is None: # The FLAG is added, the shape is kept — matching `by_source_failed` @@ -1205,6 +1277,15 @@ async def retrieval_summary( rule_usage["pulled_by_agent"] += n else: rule_usage["pulled_by_human"] += n + elif event == RULE_APPLIED: + rule_usage["applied"] += n + elif event == RULE_DEPARTED: + # Kept apart from `applied` rather than summed into a single + # "acted" count. A departure is a rule someone ARGUED with, + # and an install where every outcome is a departure is telling + # you something quite different from one where none is — + # folding them together would hide exactly that. + rule_usage["departed"] += n # None, not 0.0, when nothing was surfaced — matching the note block. A # ratio of zero asserts "we showed rules and none were opened"; with an diff --git a/tests/test_retrieval_warnings.py b/tests/test_retrieval_warnings.py index e1d066b..b973757 100644 --- a/tests/test_retrieval_warnings.py +++ b/tests/test_retrieval_warnings.py @@ -266,3 +266,86 @@ def test_a_point_seen_only_in_usage_counts_as_having_emitted() -> None: ]) def test_a_setting_falls_back_rather_than_raising(raw, fallback, want) -> None: assert _num(raw, fallback) == want + + +# ── read_and_unacted / outcomes_never_recorded (#4213, milestone 419) ───── +# +# The pair exists because ZERO OUTCOMES IS AMBIGUOUS, and getting that wrong +# would have been this milestone's own failure mode in miniature: a window +# with no outcome rows cannot tell "every rule was ignored" from "nothing +# reports outcomes yet". Reporting the first when the truth is the second +# manufactures a finding out of an unwired feature — #3311, where a statistic +# that could not vary was read as a fact about the corpus. + +def ru(**kw) -> dict: + base = { + "distinct_rules_surfaced": 0, "distinct_rules_pulled": 0, + "distinct_rules_acted": 0, "applied": 0, "departed": 0, + } + base.update(kw) + return base + + +def test_rules_opened_with_no_outcome_machinery_running_says_so() -> None: + """The cold-instrument case, which is what an install looks like the day + this ships. It must NOT read as "47 rules ignored".""" + ws = warn({}, rule_usage=ru(distinct_rules_pulled=47)) + assert "outcomes_never_recorded" in codes(ws) + assert "read_and_unacted" not in codes(ws) + [w] = [w for w in ws if w["code"] == "outcomes_never_recorded"] + assert w["numbers"]["opened"] == 47 + # The distinction is in the prose, because the prose is what gets read. + assert "does NOT mean they were ignored" in w["detail"] + + +def test_once_outcomes_exist_the_unacted_rules_are_named() -> None: + """The instrument is live — some rules recorded an outcome — so the ones + that did not are a real finding rather than an artefact.""" + ws = warn({}, rule_usage=ru( + distinct_rules_pulled=20, distinct_rules_acted=6, applied=5, departed=2, + )) + assert "read_and_unacted" in codes(ws) + assert "outcomes_never_recorded" not in codes(ws) + [w] = [w for w in ws if w["code"] == "read_and_unacted"] + assert w["numbers"]["unacted"] == 14 + assert w["numbers"]["opened"] == 20 and w["numbers"]["acted"] == 6 + assert w["numbers"]["applied"] == 5 and w["numbers"]["departed"] == 2 + + +def test_a_departure_alone_is_enough_to_warm_the_instrument() -> None: + """Departures count as outcomes. An install whose every recorded outcome + is a departure is saying something loudly, and must not be mistaken for + one that records nothing.""" + ws = warn({}, rule_usage=ru( + distinct_rules_pulled=9, distinct_rules_acted=2, departed=3, + )) + assert "read_and_unacted" in codes(ws) + assert "outcomes_never_recorded" not in codes(ws) + + +def test_every_opened_rule_acted_on_reports_nothing() -> None: + ws = warn({}, rule_usage=ru( + distinct_rules_pulled=4, distinct_rules_acted=4, applied=4, + )) + assert "read_and_unacted" not in codes(ws) + assert "outcomes_never_recorded" not in codes(ws) + + +def test_no_rules_opened_at_all_reports_neither() -> None: + """Silence is not a finding. A window where nothing was opened has nothing + to say about outcomes, and saying it anyway would put a warning on every + fresh install (rule 115).""" + ws = warn({}, rule_usage=ru(distinct_rules_surfaced=12)) + assert "read_and_unacted" not in codes(ws) + assert "outcomes_never_recorded" not in codes(ws) + + +def test_an_absent_rule_usage_block_is_not_a_finding() -> None: + """A failed rule-usage read leaves the keys missing or zero. Neither may + become a warning, because a warning computed over rows that could not be + loaded describes the outage, not the corpus (#2663).""" + assert "read_and_unacted" not in codes(warn({}, rule_usage={})) + assert "outcomes_never_recorded" not in codes(warn({}, rule_usage={})) + assert "outcomes_never_recorded" not in codes( + warn({}, rule_usage={"rule_usage_failed": True}) + ) diff --git a/tests/test_services_retrieval_telemetry.py b/tests/test_services_retrieval_telemetry.py index 8b99422..538879f 100644 --- a/tests/test_services_retrieval_telemetry.py +++ b/tests/test_services_retrieval_telemetry.py @@ -643,6 +643,72 @@ async def test_ambient_alone_reports_no_ratio(_dispose_engine): await cleanup() +@pytest.mark.integration +@pytest.mark.asyncio +async def test_the_outcome_counts_come_back_split(_dispose_engine): + """A pull says the rule was read; an outcome says it changed something + (#4213). Integration rather than a mock because `distinct_rules_acted` is + a count(distinct) with an IN over a column that carries no CHECK — the + kind of SQL shape #2663 was, where a mock agrees with whatever the code + does including nothing. + + `applied` and `departed` stay APART. Summed they would say "an outcome was + recorded", which is true of both and useful about neither: a departure is + evidence about the rule, an application is evidence about the agent. + """ + from scribe.services.retrieval_telemetry import retrieval_summary + + cleanup = await _rule_events(990016, [ + # Opened and followed. + (5301, "surfaced", "write_path_rule"), + (5301, "pulled", "mcp_get_rule"), + (5301, "applied", "mcp_rule_outcome"), + # Opened and deliberately departed from. + (5302, "surfaced", "write_path_rule"), + (5302, "pulled", "mcp_get_rule"), + (5302, "departed", "mcp_rule_outcome"), + # Opened, and nothing after it. The state the milestone exists for, + # and the one that is counted by its ABSENCE. + (5303, "surfaced", "write_path_rule"), + (5303, "pulled", "mcp_get_rule"), + ]) + try: + ru = (await retrieval_summary(990016, days=30))["rule_usage"] + assert ru["applied"] == 1 + assert ru["departed"] == 1 + assert ru["distinct_rules_acted"] == 2 + assert ru["distinct_rules_pulled"] == 3 + + # An outcome is NOT a pull. If `applied` leaked into the pull counters + # the silently-unchanged rule would vanish into a compliant-looking + # total, which is the exact confusion #4212 was opened to end. + assert ru["pulled"] == 3 + finally: + await cleanup() + + +@pytest.mark.integration +@pytest.mark.asyncio +async def test_an_outcome_is_never_split_by_ambient(_dispose_engine): + """`source` on an outcome row names the door the outcome came through, not + a ranker, so the surfaced/ambient split has nothing to say about it. An + outcome recorded from an unranked source must still count.""" + from scribe.services.retrieval_telemetry import retrieval_summary + + cleanup = await _rule_events(990017, [ + (5401, "surfaced", "session_start"), + (5401, "pulled", "mcp_get_rule"), + (5401, "applied", "some_door_nobody_has_ranked"), + ]) + try: + ru = (await retrieval_summary(990017, days=30))["rule_usage"] + assert ru["applied"] == 1 + assert ru["distinct_rules_acted"] == 1 + assert ru["ambient"] == 1, "the surfacing was ambient; the outcome is not" + finally: + await cleanup() + + # ── Window coverage (#3712) ──────────────────────────────────────────── # # A counter added last week, read over a 30-day window, reports a real count