feat(telemetry): rule_usage_events — the table, the service, and a restore that maps rule ids through the rule map (#3315)
CI & Build / Python lint (push) Failing after 3s
CI & Build / Plugin hooks (push) Successful in 8s
CI & Build / integration (push) Successful in 30s
CI & Build / TypeScript typecheck (push) Successful in 33s
CI & Build / Python tests (push) Successful in 1m5s
CI & Build / Build & push image (push) Skipped
CI & Build / Python lint (push) Failing after 3s
CI & Build / Plugin hooks (push) Successful in 8s
CI & Build / integration (push) Successful in 30s
CI & Build / TypeScript typecheck (push) Successful in 33s
CI & Build / Python tests (push) Successful in 1m5s
CI & Build / Build & push image (push) Skipped
Milestone 333 step 1. The write-path standing-rule arm is the only retrieval surface in Scribe whose usefulness cannot be observed — and, not coincidentally, the only one that has never declined to fire. 296 calls, zero zero-result, 100% clearing its threshold, while every other surface declines most of the time (#3311, and re-measured in note #3430). `retrieval_logs` gives it scores; scores say what the ranker thought, never whether the hint landed. WHY A SIBLING TABLE AND NOT A COLUMN ON note_usage_events. The row carries no note-specific field and the readout is the same shape, which is the strongest case for sharing that note #3163 admits. What decides against it is identity at RESTORE: the note importer maps note_id through note_id_map, so a rule id parked in that column comes back attached to whatever note holds that number in the target database. Not dropped — reattached. The restore reports success, the counters are populated, and every one is about the wrong record, with no other field to disagree with. rule_versions made the same call for the same reason; this is the third rule-side sibling and it reads like the first two. FK-free on rule_id and user_id, matching note_usage_events / retrieval_logs / app_logs, and deliberately unlike rule_versions. A version belongs to a rule's history and dies with it; telemetry outlives what it describes. Deleting a rule must not erase the evidence that it was surfaced forty times and opened never, because that evidence is the case for having deleted it. The service uses `background.spawn` rather than a third copy of the strong-reference dance — that module's own docstring says new callers should, and a fourth copy is how one of them drifts. The AppLog canary #2663 demands is kept, and since `rule_usage` needed exactly `note_usage`'s semantics, that canary moved into `background.report_telemetry_failure` and note_usage now calls it. `retrieval_telemetry` deliberately keeps its own: its canary is a different shape (one process-wide flag, no AppLog row), so repointing it would change behaviour rather than consolidate it. No ambient bucket, and that is a decision. The note twin splits ranked from ambient surfacings because enter_project and the skill sync deliver records without choosing them (#2477). Rules have the same problem waiting — list_always_on_rules loads them wholesale — but nothing emits here yet, so an empty AMBIENT_SOURCES would be machinery pretending to a distinction the data does not contain. `source` stays granular, so the split stays a readout-level change needing no migration. Backup carries it (v14). The round-trip test seeds a NOTE alongside the rule so the target database has a note id to collide with — without that decoy, a restore running rule ids through the wrong map would merely drop them and the test would pass by absence, rather than failing on the populated-and-wrong result that is the actual hazard. Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com> Claude-Session: https://claude.ai/code/session_01TcCs1CcQ1ormdnzSshKqvN
This commit is contained in:
@@ -0,0 +1,193 @@
|
||||
"""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 has never once returned nothing (#3311). That is either a
|
||||
perfectly tuned surface or a bar it cannot fail to clear, and `retrieval_logs`
|
||||
cannot tell the two apart: it records what the ranker scored, never whether the
|
||||
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.
|
||||
|
||||
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.
|
||||
|
||||
NO AMBIENT BUCKET, YET — and that is a decision, not an omission. 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 the same shape of problem waiting: `list_always_on_rules` and
|
||||
`enter_project` load rules wholesale on every session. They do not emit here
|
||||
today, so there is nothing to bucket, and an empty `AMBIENT_SOURCES` would be
|
||||
machinery pretending to a distinction the data does not yet contain. When a
|
||||
bulk surface starts emitting, the split is a readout-level change — a tuple and
|
||||
a `case()`, exactly as in the twin — and needs no migration. Keep it that way:
|
||||
`source` stays granular so the choice remains available.
|
||||
"""
|
||||
from __future__ import annotations
|
||||
|
||||
import logging
|
||||
|
||||
from sqlalchemy import func, select
|
||||
|
||||
from scribe.models import async_session
|
||||
from scribe.models.base import iso
|
||||
from scribe.models.rule_usage import PULLED, SURFACED, RuleUsageEvent
|
||||
from scribe.services.background import report_telemetry_failure, spawn
|
||||
|
||||
logger = logging.getLogger(__name__)
|
||||
|
||||
|
||||
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 hint at once — one insert per surfacing event, not per rule
|
||||
— because a hint is a single decision and its rows should land together.
|
||||
|
||||
Record the RANKED hits only. The arm filters candidates before it speaks
|
||||
(`exclude_rule_ids` drops what the session already holds), and a rule that
|
||||
was 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.
|
||||
"""
|
||||
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. `list_always_on_rules` and
|
||||
`enter_project` are NOT pulls — 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 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.
|
||||
"""
|
||||
return {
|
||||
"surfaced_count": 0,
|
||||
"pull_count": 0,
|
||||
"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
|
||||
|
||||
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"),
|
||||
)
|
||||
.where(RuleUsageEvent.rule_id.in_(ids))
|
||||
.group_by(RuleUsageEvent.rule_id, RuleUsageEvent.event)
|
||||
)
|
||||
).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 in rows:
|
||||
slot = out.get(int(rule_id))
|
||||
if slot is None:
|
||||
continue
|
||||
if event == SURFACED:
|
||||
slot["surfaced_count"] = int(n)
|
||||
slot["last_surfaced_at"] = iso(last_at)
|
||||
elif event == PULLED:
|
||||
slot["pull_count"] = int(n)
|
||||
slot["last_pulled_at"] = iso(last_at)
|
||||
return out
|
||||
Reference in New Issue
Block a user