Files
FabledScribe/src/scribe/services/rule_usage.py
T
bvandeusenandClaude Opus 5 dfcb000719
CI & Build / Python lint (push) Successful in 2s
CI & Build / Plugin hooks (push) Successful in 12s
CI & Build / TypeScript typecheck (push) Successful in 53s
CI & Build / integration (push) Successful in 1m3s
CI & Build / Python tests (push) Failing after 1m6s
CI & Build / Build & push image (push) Skipped
feat(rules): a surfaced rule gets an outcome, not just a read (#4212)
Milestone 419 step 1. `rule_usage_events` could say a rule was SURFACED and
that it was PULLED. It could not say what happened next, so a rule that fires
constantly and is always obeyed and a rule that fires constantly and is never
obeyed left byte-identical telemetry. The second is far the more urgent and
was the one the readout could not name — measured on a session where three of
seven misses were caught by the operator and none by the system.

Two new events, `applied` and `departed`, and a `detail` column carrying the
why of a departure. No CHECK migration: `event` was created in 0094 as plain
Text with no constraint, verified in the migration rather than assumed from
the model, so rule 36 does not bite here — said in both places because the
next person adding a value will reach for it.

THE THIRD STATE IS DERIVED, AND THAT IS THE DESIGN. Read-and-silently-
unchanged is the failure this milestone was opened on, and it cannot be
reported: an agent that knew it was ignoring a rule would not be ignoring it.
So nothing here asks. `applied` and `departed` are reported; the third state
is a rule that was opened and left no trace. An `ignored` enum member would
collect nothing while reading as though it had measured something, which is
#3311's failure — a statistic that could not vary being taken for a finding.

`detail` is a column rather than two more bare event strings because a
departure stripped of its reason reads back as a miss, so the two states this
exists to separate would collapse again one layer down, in the readout, where
nobody would see it happen. Nullable: following a rule needs no argument, and
an expensive event is one that stops being recorded.

`outcome_state` is the single reading of the four states, taking the aggregate
`usage_for_rules` already returns, so the badge, the readout and any later
session summary cannot disagree about what "followed" means — the drift #3246
found across the rules system. A departure outranks an application: a rule
both applied and argued with is a rule someone argued with, and the argument
is the half worth surfacing.

`rule_outcome` is the MCP door, classed as a WRITE. The read-only set
tolerates getters that call record_pulled, but those are reads that leave a
trace; this tool's entire effect is the row, and the row carries prose the
agent authored. A read-scoped key that can put text in the operator's
database is not read-scoped, whatever table it lands in.

Backup carries `detail` on both sides. It is the one field here a fresh
install cannot re-earn — counts come back by being used again, a stated
reason exists once — and #4197 records that the column guard watches the
export side only, so the round-trip test is the thing that would catch a
one-sided add.

Delivery is deliberately not settled here: how an agent gets prompted to
record an outcome is step 3's subject, and the same record serves whichever
answer that step reaches.

Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01821k5B3Ysecp9fNYs92Kuy
2026-09-20 23:56:05 -04:00

437 lines
20 KiB
Python

"""Rule usage telemetry — did a surfaced rule ever get read?
The sibling of `note_usage`, for the one retrieval surface in Scribe that
could not be measured at all.
Two event streams, deliberately independent:
- SURFACED: the write-path standing-rule arm put this rule in front of the
agent, unbidden, during a write.
- PULLED: someone then opened it in full (`get_rule`, or the REST detail
route).
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 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
adds latency to — or can break — the surface it observes. This module does
NOT carry its own copy of the strong-reference dance; `background` is the
one place that gets it right, and a fourth copy is how one of them drifts.
- Failures degrade, but never SILENTLY. `report_telemetry_failure` logs at
WARNING and drops one AppLog row per process per site. #2663 is the record
of this exact subsystem class running at zero for weeks — indistinguishable
from "nobody uses this" — because every failure went to `logger.debug`.
- Reads (`usage_for_rules`) are awaited and aggregated in one round-trip for
a whole page, never per row.
AMBIENT VS RANKED. The note twin splits ranked surfacings from ambient ones
because `enter_project` and the skill sync put records in front of the agent
without choosing them, and counting those as surfacings makes recency read as
popularity (#2477). Rules have exactly that shape: the SessionStart preload,
and every `rules_payload` surface hand over the whole
applicable set at once, chosen by nobody.
Until 2026-09-03 those bulk surfaces emitted nothing, and this module said so —
"an empty `AMBIENT_SOURCES` would be machinery pretending to a distinction the
data does not yet contain". True as far as it went, but it had a consequence
worth naming, because it is the reason the bucket exists now: the always-on
set's token cost was certain and its usefulness was UNFALSIFIABLE, permanently
and by construction. The one surface whose value was actually in question was
the one surface exempt from the scoreboard that judges every other.
They emit now. The split is the readout-level change the old note promised — a
`case()`, no migration, because `event` and `source` are plain Text with no
CHECK constraint. `source` stays granular so a reader can still tell the
preload from `enter_project` from the ranked arm.
WHY THIS NAMES THE RANKED SOURCES AND THE TWIN NAMES THE AMBIENT ONES. A
deliberate divergence, on the failure mode rather than on symmetry. Both shapes
fail silently when someone adds a surface and forgets the list, so the question
is which list changes more often — and here it is emphatically the ambient one:
there are TWO ranked rule sources (the write-path arm and the pre-tool arm)
against the seven bulk ones the preload alone contributes. Ranked sources are
added when somebody builds a ranker, which is rare and deliberate; bulk ones
appear whenever a surface hands rules over, which is most of them. Naming the
rare, slow-moving half means a newly-added bulk surface defaults to
`ambient`, which merely under-counts it, instead of defaulting to `ranked`,
which would quietly pad the pull-through denominator with surfacings nobody
chose and make the arm look imprecise. Same argument #3191 and #3430 make
against hand-kept lists: keep the list that must be remembered as short and as
slow-moving as possible.
"""
from __future__ import annotations
import logging
from sqlalchemy import case, func, select
from scribe.models import async_session
from scribe.models.base import iso
from scribe.models.rule_usage import (
APPLIED, DEPARTED, OUTCOMES, PULLED, SURFACED, RuleUsageEvent,
)
from scribe.services.background import report_telemetry_failure, spawn
logger = logging.getLogger(__name__)
# The surfaces that CHOSE the rules they showed. Everything else is ambient —
# see the module docstring for why the rare half is the half that gets named.
#
# Membership is the whole definition of the pull-through denominator: a ranked
# surfacing is a claim ("this rule may apply to what you are doing") that a pull
# can confirm or refute, while an ambient one is a delivery nobody decided on.
# Add a source here only when a ranker picked it.
RANKED_SOURCES = (
"write_path_rule", "pre_tool_rule", "prompt_rule",
# A reserved slot is a ranker's choice twice over — it ran a query AND
# decided a kind was worth guaranteeing a place. Left out, its line would
# be counted as bulk delivery and drop out of the denominator, so the one
# surface built because a record class kept losing would be the one whose
# hits nobody could confirm.
"preference_slot",
# The completion-report lookup on update_task (milestone 409 step 4). It
# runs its own query and shows only what cleared the bar — a ranker.
"report_preference",
)
def is_ambient(source: str) -> bool:
"""Was this surfacing a bulk delivery rather than a ranked choice?
One definition, read by both the per-rule badge readout and the aggregate
in `retrieval_telemetry` — the two used to be able to disagree about what
"surfaced" counted, which is the class of drift #3246 found across the
rules system.
Sync and pure, per the service canon (#2860), but deliberately PUBLIC where
that canon says such helpers stay `_private`. The departure is the point:
a module-private copy in each caller is exactly the second definition this
exists to prevent.
"""
return source not in RANKED_SOURCES
async def _report_failure(site: str) -> None:
await report_telemetry_failure("rule_usage", site)
async def _insert_events(rows: list[dict]) -> None:
"""Persist usage rows. Best-effort: failures degrade, visibly."""
try:
async with async_session() as session:
session.add_all([RuleUsageEvent(**row) for row in rows])
await session.commit()
except Exception:
await _report_failure("write")
def _schedule(rows: list[dict]) -> None:
if not rows:
return
spawn(_insert_events(rows), site="rule_usage_write")
def record_rule_surfaced(
*, user_id: int | None, rule_ids: list[int] | set[int], source: str
) -> None:
"""Fire-and-forget: record that these rules were shown to the agent.
Takes the whole delivery at once — one insert per surfacing event, not per
rule — because a hint is a single decision and its rows should land
together.
Record what was actually SHOWN, never what was considered. For the ranked
arm that means the post-filter hits: it drops what the session already
holds (`exclude_rule_ids`) before it speaks, and a rule considered and not
shown was not surfaced. Counting those would inflate the denominator with
claims the agent never saw, which reads as a precision problem the arm does
not have.
Bulk surfaces pass their whole delivered set, which is the same rule read
from the other end — everything in a preload IS shown. `source` is what
separates the two afterwards (see `RANKED_SOURCES`); this function does not
care which kind it is recording.
"""
try:
rows = [
{
"user_id": user_id,
"rule_id": int(rid),
"event": SURFACED,
"source": source,
}
for rid in rule_ids
]
except Exception:
logger.debug("rule usage payload build failed", exc_info=True)
return
_schedule(rows)
def record_rule_pulled(*, user_id: int | None, rule_id: int, source: str) -> None:
"""Fire-and-forget: record that a rule was opened in full.
A PULL is somebody choosing to open one record. `enter_project` is NOT a
pull — they are bulk resident loads that hand over
every applicable rule at once, and counting them would swamp the signal
with the very ambient delivery the ratio exists to distinguish from.
"""
try:
rows = [
{
"user_id": user_id,
"rule_id": int(rule_id),
"event": PULLED,
"source": source,
}
]
except Exception:
logger.debug("rule usage payload build failed", exc_info=True)
return
_schedule(rows)
def record_rule_outcome(
*,
user_id: int | None,
rule_id: int,
outcome: str,
source: str,
detail: str = "",
) -> None:
"""Fire-and-forget: record what a rule ACTUALLY CHANGED (#4212).
The third stream, and the one milestone 419 exists for. `surfaced` says
the system offered a rule; `pulled` says somebody opened it. Neither says
whether it made any difference, so a rule that fires constantly and is
always obeyed and a rule that fires constantly and is never obeyed have,
until now, produced identical telemetry. The second is far the more
urgent and is precisely the one the readout could not name.
Two outcomes, because there are only two a judge can honestly report:
APPLIED — the rule changed what was done, or confirmed it. No `detail`
required: following a rule is the unremarkable case and
charging prose for it is how an event stops being recorded.
DEPARTED — read, and deliberately not followed. `detail` is REQUIRED
and is the entire value of the event. A departure without
its reason reads back as a miss, which collapses the two
states this exists to separate.
THERE IS NO THIRD CALL, and the absence is the design. Read-and-silently-
unchanged is real — it is the failure this milestone was opened on — but
it cannot be reported, because an agent that knew it was ignoring a rule
would not be ignoring it. It is derived: a rule pulled, with no outcome
behind it. See `outcome_state`.
Guarded rather than trusting: a bad outcome or a reasonless departure is
dropped and REPORTED, never written. Telemetry that lies is worse than
telemetry that is missing (#2663), and a `departed` row with an empty
reason is a lie the readout cannot detect.
"""
if outcome not in OUTCOMES:
logger.warning("rule outcome rejected: unknown outcome %r", outcome)
spawn(_report_failure("outcome_unknown"), site="rule_usage_outcome")
return
if outcome == DEPARTED and not (detail or "").strip():
logger.warning("rule outcome rejected: departure with no reason")
spawn(_report_failure("outcome_no_reason"), site="rule_usage_outcome")
return
try:
rows = [
{
"user_id": user_id,
"rule_id": int(rule_id),
"event": outcome,
"source": source,
"detail": (detail or "").strip() or None,
}
]
except Exception:
logger.debug("rule usage payload build failed", exc_info=True)
return
_schedule(rows)
# What a rule's usage says happened to it, in one word. The four states are
# ordered by how much the system actually knows, and only the last two are
# new — the point of the milestone is that UNACTED used to be invisible
# inside APPLIED.
UNREAD = "unread" # surfaced, never opened
UNACTED = "unacted" # opened, and nothing recorded after — the blind spot
FOLLOWED = "followed" # opened and applied
DEPARTED_FROM = "departed" # opened and deliberately not followed, with a why
def outcome_state(usage: dict) -> str:
"""The three states milestone 419 asked to be able to tell apart, plus
the one that already existed.
Pure, and reading only the aggregate `usage_for_rules` already returns —
so the readout, the badge and any later session summary all answer this
question the same way. Two callers computing "was this followed" from raw
counts is the drift #3246 found across the rules system, arriving again.
PRECEDENCE, and it is deliberate: a departure outranks an application.
A rule both applied and departed from in the same window is a rule
someone argued with, and the argument is the interesting half — reporting
it as plain compliance would hide the one row a reader most wants.
UNACTED is the derived state and the reason this function exists. It is
not "no data"; it is a rule that was surfaced, deliberately OPENED, and
then left no trace of having mattered. That is a much stronger signal
than never having been opened at all, and it is the signal that was
previously indistinguishable from compliance.
"""
if int(usage.get("departed_count") or 0):
return DEPARTED_FROM
if int(usage.get("applied_count") or 0):
return FOLLOWED
if int(usage.get("pull_count") or 0):
return UNACTED
return UNREAD
def empty_rule_usage() -> dict:
"""The zero readout — what a rule with no recorded events looks like.
Callers render this shape unconditionally, so a rule predating the table
reads as "never surfaced, never pulled" rather than as a missing key. That
distinction matters more here than for notes: every rule in an install
predates this table, so for a while "no events" is the normal state and it
must not look like a broken readout.
`surfaced_count` is RANKED surfacings only; `ambient_count` is the bulk
deliveries (see `RANKED_SOURCES`). The split is what keeps the badge's
"shown often, opened never → dead weight" reading honest: every rule in an
always-on set is delivered every session, so an unsplit counter would rank
the resident set as the most-surfaced rules in the install purely for being
resident.
"""
return {
"surfaced_count": 0,
"ambient_count": 0,
"pull_count": 0,
# The outcome half (#4212). Zero here means "nothing recorded", which
# for a rule that was also never pulled is simply silence — and for
# one that WAS pulled is the blind spot this milestone is named for.
# `outcome_state` is what tells those apart; no caller should be
# reading these counts raw to decide it.
#
# The REASON for a departure is on the row (`detail`), not here. One
# GROUP BY cannot carry the text of the latest departure without a
# DISTINCT ON alongside it, and a key that the aggregate could never
# fill would read as "no reason given" on every rule that has one —
# a permanently-null field that lies. The readout that needs the
# prose reads the rows (#4213).
"applied_count": 0,
"departed_count": 0,
"last_outcome_at": None,
"last_surfaced_at": None,
"last_pulled_at": None,
}
async def usage_for_rules(rule_ids: list[int]) -> dict[int, dict]:
"""Aggregate usage for a set of rules: {rule_id: {counts + timestamps}}.
One GROUP BY for the whole page rather than a query per row — this feeds a
list view, so the per-row shape would be N+1 by construction. Rules with no
events come back with `empty_rule_usage()`, so the caller never has to tell
"no events" from "not in the result".
"""
ids = [int(r) for r in rule_ids]
out: dict[int, dict] = {rid: empty_rule_usage() for rid in ids}
if not ids:
return out
# Classified in SQL so the group stays small: per rule we get at most
# (surfaced-ranked, surfaced-ambient, pulled) rather than a row per distinct
# source. ONE labelled expression, bound to a variable and reused in the
# GROUP BY — a second `case()` instance there renders its own expanding-IN
# bind names under asyncpg, so the database sees two DIFFERENT expressions
# and rejects the query with a GroupingError. The note twin carries the
# same warning for the same reason, and #2663 is what it cost: the
# rejection was swallowed and every counter read zero in production while
# the writes were landing fine.
ambient = case(
(RuleUsageEvent.source.notin_(RANKED_SOURCES), True),
else_=False,
).label("ambient")
try:
async with async_session() as session:
rows = (
await session.execute(
select(
RuleUsageEvent.rule_id,
RuleUsageEvent.event,
func.count().label("n"),
func.max(RuleUsageEvent.created_at).label("last_at"),
ambient,
)
.where(RuleUsageEvent.rule_id.in_(ids))
.group_by(
RuleUsageEvent.rule_id,
RuleUsageEvent.event,
ambient,
)
)
).all()
except Exception:
# A telemetry readout must not be able to break the list it decorates —
# but it must say it failed, or a broken readout is indistinguishable
# from a corpus nobody uses (#2663).
await _report_failure("readout")
return out
for rule_id, event, n, last_at, is_amb in rows:
slot = out.get(int(rule_id))
if slot is None:
continue
# Outcomes first, and never split by ambient. `ambient` asks whether
# a RANKER chose to show the rule; an outcome is reported by a judge
# after the fact and has no ranker behind it, so the flag is noise
# here. Branching on it would silently drop every outcome row into a
# bucket nothing reads.
if event in OUTCOMES:
key = "applied_count" if event == APPLIED else "departed_count"
slot[key] = slot[key] + int(n)
prev = slot["last_outcome_at"]
now = iso(last_at)
if now and (prev is None or now > prev):
slot["last_outcome_at"] = now
elif event == SURFACED and is_amb:
slot["ambient_count"] = int(n)
elif event == SURFACED:
slot["surfaced_count"] = int(n)
slot["last_surfaced_at"] = iso(last_at)
elif event == PULLED:
# Pulls are pulls regardless of what surfaced the rule — "did
# anyone ever open this?" does not depend on how it was found. Both
# halves accumulate, so this ADDS rather than assigns: a rule can
# now be pulled after a ranked hint and after a preload, and the
# split arrives as two rows.
slot["pull_count"] = slot["pull_count"] + int(n)
latest = iso(last_at)
if latest and (slot["last_pulled_at"] or "") < latest:
slot["last_pulled_at"] = latest
return out