feat(telemetry): the readout names rules that were opened and changed nothing (#4213)
CI & Build / Python lint (push) Successful in 5s
CI & Build / Plugin hooks (push) Successful in 12s
CI & Build / TypeScript typecheck (push) Successful in 56s
CI & Build / integration (push) Successful in 1m6s
CI & Build / Python tests (push) Successful in 1m40s
CI & Build / Build & push image (push) Successful in 35s
CI & Build / Python lint (push) Successful in 5s
CI & Build / Plugin hooks (push) Successful in 12s
CI & Build / TypeScript typecheck (push) Successful in 56s
CI & Build / integration (push) Successful in 1m6s
CI & Build / Python tests (push) Successful in 1m40s
CI & Build / Build & push image (push) Successful in 35s
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 <noreply@anthropic.com> Claude-Session: https://claude.ai/code/session_01821k5B3Ysecp9fNYs92Kuy
This commit is contained in:
@@ -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.
|
||||
|
||||
@@ -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
|
||||
|
||||
@@ -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})
|
||||
)
|
||||
|
||||
@@ -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
|
||||
|
||||
Reference in New Issue
Block a user