From 8826be7a916dbca84945549ec2f0d7ea6eb2f5ae Mon Sep 17 00:00:00 2001 From: Bryan Van Deusen Date: Wed, 2 Sep 2026 16:55:22 -0400 Subject: [PATCH] =?UTF-8?q?feat(telemetry):=20rule=5Fusage=5Fevents=20?= =?UTF-8?q?=E2=80=94=20the=20table,=20the=20service,=20and=20a=20restore?= =?UTF-8?q?=20that=20maps=20rule=20ids=20through=20the=20rule=20map=20(#33?= =?UTF-8?q?15)?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit 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) Claude-Session: https://claude.ai/code/session_01TcCs1CcQ1ormdnzSshKqvN --- alembic/versions/0094_rule_usage_events.py | 86 +++++ src/scribe/models/__init__.py | 1 + src/scribe/models/rule_usage.py | 95 ++++++ src/scribe/services/background.py | 49 ++- src/scribe/services/backup.py | 60 +++- src/scribe/services/note_usage.py | 38 +-- src/scribe/services/rule_usage.py | 193 ++++++++++++ ...integration_backup_rule_usage_roundtrip.py | 294 ++++++++++++++++++ tests/test_services_backup.py | 4 +- tests/test_services_rule_usage.py | 118 +++++++ 10 files changed, 904 insertions(+), 34 deletions(-) create mode 100644 alembic/versions/0094_rule_usage_events.py create mode 100644 src/scribe/models/rule_usage.py create mode 100644 src/scribe/services/rule_usage.py create mode 100644 tests/test_integration_backup_rule_usage_roundtrip.py create mode 100644 tests/test_services_rule_usage.py diff --git a/alembic/versions/0094_rule_usage_events.py b/alembic/versions/0094_rule_usage_events.py new file mode 100644 index 0000000..365650d --- /dev/null +++ b/alembic/versions/0094_rule_usage_events.py @@ -0,0 +1,86 @@ +"""add rule_usage_events — was a surfaced rule ever read? (milestone 333 step 1) + +Revision ID: 0094 +Revises: 0093 +Create Date: 2026-09-02 + +The sibling `note_usage_events` has had since 0071, and the third rule-side +table to arrive after `rule_embeddings` and `rule_versions` — each one added +because the rule side kept inheriting machinery built for notes and getting +the weaker version of it. + +WHAT IT MEASURES. 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. Over 30 days it took 296 calls, +returned something on every one, and cleared its threshold 100% of the time, +while every other surface declines most of the time (#3311). That is either a +perfectly tuned surface or a bar it cannot fail to clear, and `retrieval_logs` +cannot tell them apart: it records what the ranker scored, never whether the +hint was any use. + +WHY NOT A rule_id COLUMN ON note_usage_events. The row shares no note-specific +fields and the aggregate readout is the same shape, which is the strongest case +for sharing that note #3163 admits. What decides against it is identity at +RESTORE: `note_usage_events`'s importer maps `note_id` through `note_id_map` +and drops what does not resolve. A rule id parked in that column would come +back from a backup silently reattached to whatever note took that number — +telemetry not merely lost but wrong, and wrong in a way nothing downstream +could detect. `rule_versions` made the same call for the same reason. + +FK-free on `rule_id` and `user_id`, matching note_usage_events, retrieval_logs +and app_logs — and deliberately unlike `rule_versions`, which does carry FKs. +The difference is what the row is for: a version belongs to a rule's history +and dies with it; telemetry outlives the row it describes. Deleting a rule must +not erase the evidence that it was surfaced forty times and opened never, since +that evidence is exactly the case for having deleted it. + +No CHECK on `event`, matching the note twin. Rule 36 governs adding a value to +a column that is already gated; it does not require gating one that never was, +and a two-member enum whose members are written by two functions in one module +is not where that discipline earns its cost. + +Downgrade drops the table outright. The data is purely observational — nothing +reads it for correctness, so losing it costs history and no behaviour. +""" +from alembic import op +import sqlalchemy as sa + + +revision = "0094" +down_revision = "0093" +branch_labels = None +depends_on = None + + +def upgrade() -> None: + op.create_table( + "rule_usage_events", + # BigInteger throughout where the note twin uses Integer: rules.id is + # BigInteger, so rule_id must be, and a high-churn append-only table is + # a poor place to discover an id ceiling. + sa.Column("id", sa.BigInteger(), primary_key=True), + sa.Column( + "created_at", + sa.DateTime(timezone=True), + nullable=False, + server_default=sa.text("now()"), + ), + sa.Column("user_id", sa.BigInteger(), nullable=True), + sa.Column("rule_id", sa.BigInteger(), nullable=False), + sa.Column("event", sa.Text(), nullable=False), + sa.Column("source", sa.Text(), nullable=False), + ) + # Every readout is "these rule ids, split by event", so the composite is the + # one that actually gets used; the others serve pruning and per-user views. + op.create_index( + "ix_rule_usage_rule_event", "rule_usage_events", ["rule_id", "event"] + ) + op.create_index("ix_rule_usage_created_at", "rule_usage_events", ["created_at"]) + op.create_index("ix_rule_usage_user_id", "rule_usage_events", ["user_id"]) + + +def downgrade() -> None: + op.drop_index("ix_rule_usage_user_id", table_name="rule_usage_events") + op.drop_index("ix_rule_usage_created_at", table_name="rule_usage_events") + op.drop_index("ix_rule_usage_rule_event", table_name="rule_usage_events") + op.drop_table("rule_usage_events") diff --git a/src/scribe/models/__init__.py b/src/scribe/models/__init__.py index 203d962..0b95999 100644 --- a/src/scribe/models/__init__.py +++ b/src/scribe/models/__init__.py @@ -28,6 +28,7 @@ from scribe.models.invitation import InvitationToken # noqa: E402, F401 from scribe.models.embedding import NoteEmbedding, RuleEmbedding # noqa: E402, F401 from scribe.models.retrieval_log import RetrievalLog # noqa: E402, F401 from scribe.models.note_usage import NoteUsageEvent # noqa: E402, F401 +from scribe.models.rule_usage import RuleUsageEvent # noqa: E402, F401 from scribe.models.project import Project # noqa: E402, F401 from scribe.models.milestone import Milestone # noqa: E402, F401 from scribe.models.task_log import TaskLog # noqa: E402, F401 diff --git a/src/scribe/models/rule_usage.py b/src/scribe/models/rule_usage.py new file mode 100644 index 0000000..ea53c96 --- /dev/null +++ b/src/scribe/models/rule_usage.py @@ -0,0 +1,95 @@ +from sqlalchemy import BigInteger, Index, Text +from sqlalchemy.orm import Mapped, mapped_column + +from scribe.models import Base +from scribe.models.base import CreatedAtMixin, iso + +SURFACED = "surfaced" +PULLED = "pulled" + + +class RuleUsageEvent(Base, CreatedAtMixin): + """One row per time a rule was SURFACED to the agent, or PULLED in full. + + The sibling `note_usage_events` has had since 2026-07, third in the line + after `rule_embeddings` and `rule_versions` — and, like those, it exists + because the rule side kept inheriting machinery built for notes and + quietly getting the weaker version of it. + + WHY RULES NEED THEIR OWN AND CANNOT SHARE THE NOTE TABLE. Not squeamishness + about a polymorphic column — the row shares no note-specific fields and the + aggregate readout is the same shape, which is the strongest case for + sharing that note #3163 admits. What decides it is IDENTITY AT RESTORE. A + note id and a rule id are different namespaces resolved through different + maps, and `note_usage_events`'s importer maps `note_id` through + `note_id_map` and drops what does not resolve. A rule id parked in that + column would come back from a backup silently reattached to whatever note + happened to take that number — telemetry that is not merely lost but wrong, + and wrong in a way nothing downstream could detect. + + WHAT THIS MEASURES, AND WHY IT DID NOT EXIST. 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 (#3311: 296 calls, zero zero-result, 100% clearing its threshold). + `retrieval_logs` gives it scores; scores say what the ranker thought, never + whether the hint landed. Without a pull counter no install can tune the arm + from evidence, only from the shape of a histogram. + + Deliberately FK-FREE on `rule_id` and `user_id`, matching `note_usage_events`, + `retrieval_logs` and `app_logs` — and diverging from `rule_versions`, which + does carry FKs. The difference is what the row is FOR: a version is part of + a rule's history and dies with it, while telemetry outlives the row it + describes. Deleting a rule must not erase the evidence that it was surfaced + forty times and opened never, because that evidence is precisely the case + for having deleted it. + + Cells left deliberately empty (note #3163's step 3): no share ACL — rules + have none of their own; no soft delete — nothing restores a telemetry row, + and the table is append-only; no embedding — an event is not a document. + """ + + __tablename__ = "rule_usage_events" + + # BigInteger throughout, where the note twin uses Integer. `rule_id` has to + # be, since `rules.id` is BigInteger — and once one column is, matching the + # rest costs nothing and keeps the row uniform. A high-churn append-only + # telemetry table is a poor place to discover an id ceiling. + id: Mapped[int] = mapped_column(BigInteger, primary_key=True) + user_id: Mapped[int | None] = mapped_column(BigInteger, nullable=True) + rule_id: Mapped[int] = mapped_column(BigInteger, nullable=False) + + # 'surfaced' | 'pulled' + event: Mapped[str] = mapped_column(Text, nullable=False) + + # Which surface produced it. A CONVENTION, not a fixed vocabulary, and the + # note twin's comment explains why this one deliberately does not enumerate + # its members: the previous such list went stale, naming a source nothing + # wrote while omitting ones that existed, and a half-true enumeration reads + # as authoritative in exactly the way that misleads (#2476). + # `grep -rn record_rule_pulled\|record_rule_surfaced src/` is the + # authoritative list, and unlike a comment it cannot drift. + # + # The mcp_/rest_ prefix split is load-bearing here for the same reason it is + # for notes, and more so: "is this rule dead weight?" is served by any pull, + # but "did that injected hint land?" — the question this arm exists to + # answer — is served by AGENT pulls only. Never aggregate across the prefix + # without saying why. + source: Mapped[str] = mapped_column(Text, nullable=False) + + __table_args__ = ( + # Every readout is "these rule ids, split by event" — a covering + # composite beats separate single-column indexes for it. + Index("ix_rule_usage_rule_event", "rule_id", "event"), + Index("ix_rule_usage_created_at", "created_at"), + Index("ix_rule_usage_user_id", "user_id"), + ) + + def to_dict(self) -> dict: + return { + "id": self.id, + "created_at": iso(self.created_at), + "user_id": self.user_id, + "rule_id": self.rule_id, + "event": self.event, + "source": self.source, + } diff --git a/src/scribe/services/background.py b/src/scribe/services/background.py index a81fa5d..eb80c28 100644 --- a/src/scribe/services/background.py +++ b/src/scribe/services/background.py @@ -6,20 +6,63 @@ write that never errors and never lands (the #2663 GC footgun). This module is the one place that gets the pattern right: strong references in ``_pending``, discarded on completion, with failures logged at WARNING instead of vanishing. -``note_usage`` and ``retrieval_telemetry`` predate this module and carry their -own copies with bespoke canary semantics; new fire-and-forget callers use this -instead of writing a fourth copy. +``retrieval_telemetry`` predates this module and keeps its own copy, because +its canary is a genuinely different shape — one process-wide flag and no +AppLog row. ``note_usage`` and ``rule_usage`` share ``report_telemetry_failure`` +below. New fire-and-forget callers use ``spawn`` rather than writing another +copy of the strong-reference dance. """ from __future__ import annotations import asyncio import logging +import traceback from collections.abc import Coroutine logger = logging.getLogger(__name__) _pending: set[asyncio.Task] = set() +# Sites that have already dropped their once-per-process AppLog row, keyed +# ":". A readout can run on every list render — without this, +# a broken table turns the error log into a firehose that buries the finding it +# exists to surface. +_reported: set[str] = set() + + +async def report_telemetry_failure(subsystem: str, site: str) -> None: + """Make a swallowed telemetry failure visible. Call from an except block. + + WARNING to the process log every time; one AppLog error row per process per + (subsystem, site) so the admin UI shows the outage without host access. + + THIS IS NOT DECORATION. #2663 is the record of a telemetry subsystem running + at zero for weeks — every counter reading empty, indistinguishable from + "nobody uses this" — because every failure went to ``logger.debug``. A + subsystem whose failures are all invisible cannot report its own death. + + The AppLog write is itself guarded: when the database is down it fails too, + and that is fine. The WARNING already said so, and a canary must never take + down the surface it watches. + """ + logger.warning("%s telemetry %s failed", subsystem, site, exc_info=True) + key = f"{subsystem}:{site}" + if key in _reported: + return + _reported.add(key) + try: + from scribe.services.logging import log_error + + await log_error( + endpoint=subsystem, + error_type=f"{subsystem}_{site}_failed", + error_message=f"{subsystem} telemetry {site} is failing; " + "usage counters will read zero until this is fixed", + traceback=traceback.format_exc(), + ) + except Exception: + logger.debug("%s canary write failed", subsystem, exc_info=True) + def spawn(coro: Coroutine, *, site: str) -> None: """Schedule ``coro`` fire-and-forget; ``site`` names it in failure logs. diff --git a/src/scribe/services/backup.py b/src/scribe/services/backup.py index a791824..6491975 100644 --- a/src/scribe/services/backup.py +++ b/src/scribe/services/backup.py @@ -12,6 +12,7 @@ from scribe.models.note_version import NoteVersion from scribe.models.rule_version import RuleVersion from scribe.models.design_system import DesignSystem, DesignToken from scribe.models.note_usage import NoteUsageEvent +from scribe.models.rule_usage import RuleUsageEvent from scribe.models.canonical_system import CanonicalSystem from scribe.models.rulebook import RuleRelation, rule_systems as rule_systems_t from scribe.models.code_shape import CodeShape, CodeShapeEvent, CodeShapeUse @@ -62,8 +63,12 @@ logger = logging.getLogger(__name__) # _COLUMN_EXCLUSIONS and its guard landed with it, so the next such column # fails the build instead. # v13 (2026-08) added rule_versions — a rule's edit history (milestone 323). +# v14 (2026-09) added rule_usage_events — the rule twin of note_usage_events +# (milestone 333). Carrying it is the WHOLE REASON the table is separate: the +# note importer maps note_id through note_id_map, so a rule id parked there +# would restore attached to whatever note took that number. # Bump when the serialized schema changes. -BACKUP_VERSION = 13 +BACKUP_VERSION = 14 # Every table this backup carries, by its REAL name. Paired with _NOT_INCLUDED # below, these two lists must together account for the entire schema — which is @@ -92,6 +97,11 @@ _BACKED_UP = [ # v13 (2026-08): a rule's edit history (milestone 323). note_versions has # always travelled; its sibling has no excuse not to. "rule_versions", + # v14 (2026-09): rule usage telemetry (milestone 333). Same argument + # note_usage_events makes for itself — pull-through is only ever + # accumulated, so a restore that dropped it would silently reset the + # measurement to zero while everything still looked fine. + "rule_usage_events", ] # Tables intentionally NOT in the backup, surfaced in the payload so the gap is @@ -178,6 +188,8 @@ _COLUMN_EXCLUSIONS: dict[str, set[str]] = { "note_supersessions": {"id", "created_at"}, "rule_relations": {"id", "created_at"}, "note_usage_events": {"id"}, + # Same as the note twin: the surrogate key is re-issued on insert. + "rule_usage_events": {"id"}, "design_systems": {"deleted_at", "deleted_batch_id", "created_at", "updated_at"}, "design_tokens": {"deleted_at", "deleted_batch_id", "created_at", "updated_at"}, "repo_bindings": {"id", "created_at", "updated_at"}, @@ -321,6 +333,17 @@ def _usage_event_rows(rows) -> list[dict]: ] +def _rule_usage_event_rows(rows) -> list[dict]: + return [ + { + "user_id": r.user_id, "rule_id": r.rule_id, "event": r.event, + "source": r.source, + "created_at": r.created_at.isoformat() if r.created_at else None, + } + for r in rows + ] + + def _code_shape_rows(rows) -> list[dict]: return [r.to_dict() for r in rows] @@ -606,6 +629,9 @@ async def export_full_backup() -> dict: )).scalars().all() design_tokens = (await session.execute(select(DesignToken))).scalars().all() usage_events = (await session.execute(select(NoteUsageEvent))).scalars().all() + rule_usage_events = ( + await session.execute(select(RuleUsageEvent)) + ).scalars().all() repo_bindings = (await session.execute(select(RepoBinding))).scalars().all() code_shapes = (await session.execute(select(CodeShape))).scalars().all() code_shape_events = (await session.execute( @@ -665,6 +691,7 @@ async def export_full_backup() -> dict: "design_systems": _design_system_rows(design_systems), "design_tokens": _design_token_rows(design_tokens), "note_usage_events": _usage_event_rows(usage_events), + "rule_usage_events": _rule_usage_event_rows(rule_usage_events), "repo_bindings": _repo_binding_rows(repo_bindings), "note_supersessions": _note_supersession_rows(supersessions), "code_shapes": _code_shape_rows(code_shapes), @@ -740,6 +767,14 @@ async def export_user_backup(user_id: int) -> dict: usage_events = (await session.execute( select(NoteUsageEvent).where(NoteUsageEvent.note_id.in_(note_ids)) )).scalars().all() if note_ids else [] + # Scoped through the RULE, not the event's user_id — the same call + # rule_versions makes one block up. user_id here is whoever the arm + # fired for, so filtering on it would carry this user's surfacings of + # someone ELSE's rule and drop the ones fired for someone else on + # theirs: the opposite of a per-user export. + rule_usage_events = (await session.execute( + select(RuleUsageEvent).where(RuleUsageEvent.rule_id.in_(_rule_ids)) + )).scalars().all() if _rule_ids else [] repo_bindings = (await session.execute( select(RepoBinding).where(RepoBinding.user_id == user_id) )).scalars().all() @@ -858,6 +893,7 @@ async def export_user_backup(user_id: int) -> dict: "design_systems": _design_system_rows(design_systems), "design_tokens": _design_token_rows(design_tokens), "note_usage_events": _usage_event_rows(usage_events), + "rule_usage_events": _rule_usage_event_rows(rule_usage_events), "repo_bindings": _repo_binding_rows(repo_bindings), "note_supersessions": _note_supersession_rows(supersessions), "code_shapes": _code_shape_rows(code_shapes), @@ -994,7 +1030,8 @@ async def _restore_v2(data: dict) -> dict: "rulebook_subscriptions": 0, "rule_suppressions": 0, "topic_suppressions": 0, "rulebook_exclusions": 0, "systems": 0, "record_systems": 0, "design_systems": 0, - "design_tokens": 0, "note_usage_events": 0, "repo_bindings": 0, + "design_tokens": 0, "note_usage_events": 0, "rule_usage_events": 0, + "repo_bindings": 0, "note_supersessions": 0, "code_shapes": 0, "code_shape_events": 0, "code_shape_uses": 0, "canonical_systems": 0, "rule_systems": 0, "rule_relations": 0, "rule_versions": 0, @@ -1496,6 +1533,25 @@ async def _restore_v2(data: dict) -> dict: )) stats["note_usage_events"] += 1 + # The rule twin — and the reason it is a separate table at all. + # Resolved through rule_id_map, NOT note_id_map. A rule id run through + # the note map would either drop (best case) or land on whatever note + # took that number, producing telemetry that is wrong rather than + # missing and that nothing downstream could detect (milestone 333). + # Must come after the rules themselves; rule_id_map is populated there. + for ev in data.get("rule_usage_events", []): + mapped_rid = rule_id_map.get(ev.get("rule_id", 0)) + if mapped_rid is None: + continue + session.add(RuleUsageEvent( + user_id=user_id_map.get(ev.get("user_id") or 0), + rule_id=mapped_rid, + event=ev.get("event", ""), + source=ev.get("source", ""), + created_at=_dt(ev.get("created_at")), + )) + stats["rule_usage_events"] += 1 + # 20. Repo bindings — small, but losing them means every bound repo # quietly stops loading its project at session start. for rb_data in data.get("repo_bindings", []): diff --git a/src/scribe/services/note_usage.py b/src/scribe/services/note_usage.py index cf67d5c..21c3596 100644 --- a/src/scribe/services/note_usage.py +++ b/src/scribe/services/note_usage.py @@ -30,13 +30,13 @@ from __future__ import annotations import asyncio import logging -import traceback from sqlalchemy import case, func, select from scribe.models import async_session from scribe.models.note_usage import PULLED, SURFACED, NoteUsageEvent from scribe.models.base import iso +from scribe.services.background import report_telemetry_failure logger = logging.getLogger(__name__) @@ -46,37 +46,19 @@ logger = logging.getLogger(__name__) # never lands. The done-callback discard keeps the set from growing. _pending: set[asyncio.Task] = set() -# Sites that already dropped their once-per-process AppLog row. The readout -# runs on every snippet list render — without this, a broken table would turn -# the error log into a firehose that buries the finding it exists to surface. -_reported: set[str] = set() - async def _report_failure(site: str) -> None: - """Make a swallowed telemetry failure visible. Called from an except block. + """This subsystem's canary, now the shared one. - WARNING to the process log every time; one AppLog error row per process per - site so the admin UI shows the outage without host access. The AppLog write - is itself guarded — when the whole database is down it fails too, and that - is fine: the WARNING already said so, and a canary must never take down the - surface it watches. + The per-site dedup, the WARNING and the single AppLog row all moved to + `background.report_telemetry_failure` unchanged when `rule_usage` needed + the identical behaviour — two hand-kept copies of a thing whose whole job + is to be reliable is the wrong number. `retrieval_telemetry` deliberately + still has 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. """ - logger.warning("note usage telemetry %s failed", site, exc_info=True) - if site in _reported: - return - _reported.add(site) - try: - from scribe.services.logging import log_error - - await log_error( - endpoint="note_usage", - error_type=f"note_usage_{site}_failed", - error_message=f"note usage telemetry {site} is failing; " - "usage counters will read zero until this is fixed", - traceback=traceback.format_exc(), - ) - except Exception: - logger.debug("note usage canary write failed", exc_info=True) + await report_telemetry_failure("note_usage", site) async def _insert_events(rows: list[dict]) -> None: diff --git a/src/scribe/services/rule_usage.py b/src/scribe/services/rule_usage.py new file mode 100644 index 0000000..061005b --- /dev/null +++ b/src/scribe/services/rule_usage.py @@ -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 diff --git a/tests/test_integration_backup_rule_usage_roundtrip.py b/tests/test_integration_backup_rule_usage_roundtrip.py new file mode 100644 index 0000000..10f2dc9 --- /dev/null +++ b/tests/test_integration_backup_rule_usage_roundtrip.py @@ -0,0 +1,294 @@ +"""Real-Postgres round trip for rule_usage_events (milestone 333 step 1). + +**This file is the reason the table exists.** `rule_usage_events` could have +been a `rule_id` 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 decided against it is identity at +restore, and that is a claim only a real round trip can support. + +The failure it guards is the quiet kind. `note_usage_events`'s importer maps +`note_id` through `note_id_map`; a rule id parked in that column comes back +attached to whatever note happens to hold that number in the target database. +Not dropped — REATTACHED. The restore reports success, the counters are +populated, and every one of them is about the wrong record. Nothing downstream +can detect it, because a usage row has no other field to disagree with. + +So the assertions below are about WHICH MAP resolved the id, and they are +written to fail if the answer ever becomes "the note one" or "neither". + +Same shape as `test_integration_backup_rule_version_roundtrip.py`, which guards +`rule_versions` against #3182's `arose_from_id` trap on the same seam. +""" +import pytest +import pytest_asyncio +from sqlalchemy import select + +from scribe.models import async_session +from scribe.models.note import Note +from scribe.models.rule_usage import PULLED, SURFACED, RuleUsageEvent +from scribe.models.rulebook import Rule, Rulebook, RulebookTopic +from scribe.models.user import User +from scribe.services import backup +from tests.helpers import ensure_user + +pytestmark = [pytest.mark.integration, pytest.mark.usefixtures("_dispose_engine")] + +OWNER_USERNAME = "rule_usage_roundtrip_owner" +RESTORED_USERNAME = "rule_usage_roundtrip_restored" + + +async def _purge_books(username: str) -> None: + """user -> rulebook -> topic -> rule is ON DELETE CASCADE the whole way, + so dropping the books clears the rules this file made. + + `rule_usage_events` is deliberately FK-FREE, so its rows do NOT cascade — + that is the property under test elsewhere (telemetry outlives what it + describes). They are cleared explicitly below. + """ + async with async_session() as s: + users = (await s.execute( + select(User).where(User.username == username) + )).scalars().all() + for user in users: + books = (await s.execute( + select(Rulebook).where(Rulebook.owner_user_id == user.id) + )).scalars().all() + for book in books: + await s.delete(book) + for note in (await s.execute( + select(Note).where(Note.user_id == user.id) + )).scalars().all(): + await s.delete(note) + await s.commit() + + +async def _purge_usage(rule_ids: set[int]) -> None: + if not rule_ids: + return + async with async_session() as s: + for ev in (await s.execute( + select(RuleUsageEvent).where(RuleUsageEvent.rule_id.in_(rule_ids)) + )).scalars().all(): + await s.delete(ev) + await s.commit() + + +async def _purge_restored() -> None: + await _purge_books(RESTORED_USERNAME) + async with async_session() as s: + for user in (await s.execute( + select(User).where(User.username == RESTORED_USERNAME) + )).scalars().all(): + await s.delete(user) + await s.commit() + + +@pytest_asyncio.fixture(autouse=True) +async def _no_leftovers(): + """SETUP ONLY — see the sibling file for why a database call after a + `yield` here orphans a pooled connection and breaks unrelated tests.""" + await _purge_restored() + await _purge_books(OWNER_USERNAME) + + +@pytest_asyncio.fixture +async def source(): + """One rule with a surfaced/pulled pair — plus a NOTE that will hold the + rule's id in the restored database. + + That note is the whole trick. Without it, a restore that ran rule ids + through `note_id_map` would simply drop them and the test would read as a + pass-by-absence. With it, the wrong map produces a plausible, populated, + entirely wrong result — which is the failure actually being guarded. + """ + async with async_session() as s: + owner = await ensure_user(s, OWNER_USERNAME) + uid = owner.id + await s.commit() + + async with async_session() as s: + book = Rulebook(owner_user_id=uid, title="Environment facts") + s.add(book) + await s.flush() + topic = RulebookTopic(rulebook_id=book.id, title="ci") + s.add(topic) + await s.flush() + rule = Rule( + topic_id=topic.id, + title="A wait with no deadline is a bug", + statement="Every wait on something that can fail to answer carries one.", + ) + s.add(rule) + # A note in the same export, so the target database has a note id to + # collide with. Its own id is irrelevant; what matters is that the + # note map is populated and would resolve to something. + note = Note(user_id=uid, title="a note that must not receive rule telemetry", + body="decoy") + s.add(note) + await s.flush() + s.add_all([ + RuleUsageEvent( + user_id=uid, rule_id=rule.id, + event=SURFACED, source="write_path_rule", + ), + RuleUsageEvent( + user_id=uid, rule_id=rule.id, + event=PULLED, source="mcp_get_rule", + ), + # No actor. The arm can fire for an unauthenticated hook call, and + # a user who later leaves must not take the evidence with them. + RuleUsageEvent( + user_id=None, rule_id=rule.id, + event=SURFACED, source="write_path_rule", + ), + ]) + await s.commit() + book_id, rule_id, note_id = book.id, rule.id, note.id + + async with async_session() as s: + user_rows = backup._user_rows( + [(await s.execute(select(User).where(User.id == uid))).scalars().one()] + ) + book_rows = backup._rulebook_rows( + [(await s.execute(select(Rulebook).where(Rulebook.id == book_id))) + .scalars().one()] + ) + topic_rows = backup._topic_rows( + (await s.execute( + select(RulebookTopic).where(RulebookTopic.rulebook_id == book_id) + )).scalars().all() + ) + rule_rows = backup._rule_rows( + [(await s.execute(select(Rule).where(Rule.id == rule_id))).scalars().one()] + ) + note_rows = backup._note_rows( + [(await s.execute(select(Note).where(Note.id == note_id))).scalars().one()] + ) + usage_rows = backup._rule_usage_event_rows( + (await s.execute( + select(RuleUsageEvent).where(RuleUsageEvent.rule_id == rule_id) + .order_by(RuleUsageEvent.id) + )).scalars().all() + ) + user_rows[0]["username"] = RESTORED_USERNAME + + yield { + "payload": { + "version": backup.BACKUP_VERSION, + "users": user_rows, + "rulebooks": book_rows, + "rulebook_topics": topic_rows, + "rules": rule_rows, + "notes": note_rows, + "rule_usage_events": usage_rows, + }, + "source_rule_id": rule_id, + "source_user_id": uid, + } + + await _purge_usage({rule_id}) + async with async_session() as s: + book = await s.get(Rulebook, book_id) + if book is not None: + await s.delete(book) + note = await s.get(Note, note_id) + if note is not None: + await s.delete(note) + await s.commit() + + +@pytest_asyncio.fixture +async def restored(source): + await backup.restore_full_backup(source["payload"]) + async with async_session() as s: + user = (await s.execute( + select(User).where(User.username == RESTORED_USERNAME) + )).scalars().first() + assert user is not None, "the payload's user was not restored" + book = (await s.execute( + select(Rulebook).where(Rulebook.owner_user_id == user.id) + )).scalars().one() + topic = (await s.execute( + select(RulebookTopic).where(RulebookTopic.rulebook_id == book.id) + )).scalars().one() + rule = (await s.execute( + select(Rule).where(Rule.topic_id == topic.id) + )).scalars().one() + note = (await s.execute( + select(Note).where(Note.user_id == user.id) + )).scalars().one() + events = (await s.execute( + select(RuleUsageEvent).where(RuleUsageEvent.rule_id == rule.id) + .order_by(RuleUsageEvent.id) + )).scalars().all() + yield { + "user": user, "rule": rule, "note": note, + "events": events, "source": source, + } + + await _purge_usage({rule.id}) + await _purge_restored() + + +async def test_every_event_comes_back(restored): + """The count first: every shape assertion below reads the same on an empty + list, so without this a restore that dropped all three would pass them.""" + assert len(restored["events"]) == 3 + + +async def test_the_events_attach_to_the_RESTORED_rule(restored): + """The remap, on the column that matters.""" + new_rule_id = restored["rule"].id + source_rule_id = restored["source"]["source_rule_id"] + assert new_rule_id != source_rule_id, ( + "the restore reused the source id, so this test cannot tell a remap " + "from a copy — the fixture is not proving what it claims" + ) + assert {e.rule_id for e in restored["events"]} == {new_rule_id} + + +async def test_no_event_landed_on_the_note_id(restored): + """THE ONE THIS TABLE EXISTS FOR. + + If `rule_id` were ever resolved through `note_id_map` — the shape it would + have had as a column on `note_usage_events` — these rows would come back + pointing at the restored NOTE's id. Populated, plausible, and describing a + record that was never surfaced. + """ + note_id = restored["note"].id + landed_on_note = [e for e in restored["events"] if e.rule_id == note_id] + assert not landed_on_note, ( + f"{len(landed_on_note)} usage event(s) resolved to the note's id " + f"({note_id}) instead of the rule's. The rule id went through the " + "note map — telemetry that is wrong rather than missing, and that " + "nothing downstream can detect." + ) + + +async def test_the_actor_is_remapped_and_a_missing_one_survives(restored): + """`user_id` is an id in the source database too — the same trap one + column over. And the actorless row must not be dropped: the arm can fire + for an unauthenticated hook call, so requiring an actor would discard the + surfacings of exactly the surface being measured.""" + attributed = [e for e in restored["events"] if e.user_id is not None] + orphaned = [e for e in restored["events"] if e.user_id is None] + assert len(attributed) == 2 + assert len(orphaned) == 1, ( + "the event with no actor did not come back. Telemetry outlives the " + "account it was recorded for; dropping it silently lowers the " + "surfaced count that the pull-through ratio divides by." + ) + assert {e.user_id for e in attributed} == {restored["user"].id} + assert restored["user"].id != restored["source"]["source_user_id"] + + +async def test_the_event_and_source_survive(restored): + """The two fields the ratio is computed from. A restore that kept the rows + and lost these would preserve a count of nothing in particular.""" + pairs = {(e.event, e.source) for e in restored["events"]} + assert pairs == { + (SURFACED, "write_path_rule"), + (PULLED, "mcp_get_rule"), + } + assert sum(1 for e in restored["events"] if e.event == SURFACED) == 2 + assert sum(1 for e in restored["events"] if e.event == PULLED) == 1 diff --git a/tests/test_services_backup.py b/tests/test_services_backup.py index 274fde3..d85681d 100644 --- a/tests/test_services_backup.py +++ b/tests/test_services_backup.py @@ -23,7 +23,7 @@ def test_backup_version_is_current(): (Named for the number it asserted until v10, which is exactly the drift a name-carrying-a-value invites; it now says what it checks.)""" - assert backup.BACKUP_VERSION == 13 + assert backup.BACKUP_VERSION == 14 def _exportable_note(**over): @@ -133,6 +133,7 @@ def _column_guard_targets(): from scribe.models.note_draft import NoteDraft from scribe.models.note_supersession import NoteSupersession from scribe.models.note_usage import NoteUsageEvent + from scribe.models.rule_usage import RuleUsageEvent from scribe.models.note_version import NoteVersion from scribe.models.rule_version import RuleVersion from scribe.models.project import Project @@ -162,6 +163,7 @@ def _column_guard_targets(): "note_supersessions": (NoteSupersession, backup._note_supersession_rows), "rule_relations": (RuleRelation, backup._rule_relation_rows), "note_usage_events": (NoteUsageEvent, backup._usage_event_rows), + "rule_usage_events": (RuleUsageEvent, backup._rule_usage_event_rows), "design_systems": (DesignSystem, backup._design_system_rows), "design_tokens": (DesignToken, backup._design_token_rows), "repo_bindings": (RepoBinding, backup._repo_binding_rows), diff --git a/tests/test_services_rule_usage.py b/tests/test_services_rule_usage.py new file mode 100644 index 0000000..3356390 --- /dev/null +++ b/tests/test_services_rule_usage.py @@ -0,0 +1,118 @@ +"""Rule usage telemetry — the parts that need no database (milestone 333 step 1). + +The round trip lives in `test_integration_backup_rule_usage_roundtrip.py`. +What is here is the payload building and the zero shape: cheap, and the half +where a mistake is silent rather than loud. +""" +import pytest + +from scribe.models.rule_usage import PULLED, SURFACED, RuleUsageEvent +from scribe.services import rule_usage + + +@pytest.fixture +def captured(monkeypatch): + """Intercept the scheduler so the payload can be read without a loop. + + Patching `_schedule` rather than `background.spawn` keeps the test on this + module's own seam: what is under test is which rows get built, not whether + the shared fire-and-forget machinery works — that has its own home. + """ + rows: list[list[dict]] = [] + monkeypatch.setattr(rule_usage, "_schedule", rows.append) + return rows + + +def test_a_surfacing_records_one_row_per_rule(captured): + """The arm shows a hint containing several rules at once; each needs its + own row, because the readout is per rule.""" + rule_usage.record_rule_surfaced( + user_id=7, rule_ids=[156, 157], source="write_path_rule" + ) + [batch] = captured + assert batch == [ + {"user_id": 7, "rule_id": 156, "event": SURFACED, "source": "write_path_rule"}, + {"user_id": 7, "rule_id": 157, "event": SURFACED, "source": "write_path_rule"}, + ] + + +def test_the_whole_hint_lands_as_one_batch(captured): + """One scheduled insert for the hint, not one per rule. A hint is a single + decision and its rows should land together — a partial batch would read as + a hint that surfaced fewer rules than it did.""" + rule_usage.record_rule_surfaced( + user_id=7, rule_ids=[1, 2, 3], source="write_path_rule" + ) + assert len(captured) == 1 + assert len(captured[0]) == 3 + + +def test_a_pull_records_one_row(captured): + rule_usage.record_rule_pulled(user_id=7, rule_id=156, source="mcp_get_rule") + assert captured == [ + [{"user_id": 7, "rule_id": 156, "event": PULLED, "source": "mcp_get_rule"}] + ] + + +def test_an_actorless_event_is_still_recorded(captured): + """The arm fires from a hook that may carry no authenticated user. Dropping + those would silently shrink the denominator the ratio divides by — the + surfacings would vanish while any later pull still counted.""" + rule_usage.record_rule_surfaced( + user_id=None, rule_ids=[156], source="write_path_rule" + ) + assert captured[0][0]["user_id"] is None + + +def test_an_empty_surfacing_builds_no_rows(captured): + """The arm can rank everything out — `exclude_rule_ids` drops what the + session already holds. That is not a surfacing, and the empty batch is + where `_schedule` returns early rather than opening a session to insert + nothing.""" + rule_usage.record_rule_surfaced(user_id=7, rule_ids=[], source="write_path_rule") + assert captured == [[]] + + +def test_the_real_scheduler_returns_early_on_an_empty_batch(): + """The guard itself, against the REAL `_schedule` the stub above replaces. + + There is no running loop in a unit test, so `spawn` would be harmless + anyway — but it would build a coroutine only to close it, and the point is + that an empty batch never gets that far. + """ + rule_usage._schedule([]) # must not raise + + +def test_a_bad_rule_id_is_dropped_not_raised(captured): + """Telemetry must never break the surface it observes. An unconvertible id + is a bug somewhere upstream, and the right response is to lose the row and + log it — not to take down the write-path hint.""" + rule_usage.record_rule_pulled( + user_id=7, rule_id="not-an-int", source="mcp_get_rule" # type: ignore[arg-type] + ) + assert captured == [] + + +def test_the_zero_readout_names_every_key(): + """Callers render this shape unconditionally. Every rule in an existing + install predates the table, so for a while "no events" is the NORMAL state + — a missing key here would read as a broken readout on almost every row.""" + assert rule_usage.empty_rule_usage() == { + "surfaced_count": 0, + "pull_count": 0, + "last_surfaced_at": None, + "last_pulled_at": None, + } + + +def test_the_model_serialises_the_fields_the_ratio_needs(): + ev = RuleUsageEvent( + user_id=7, rule_id=156, event=SURFACED, source="write_path_rule" + ) + row = ev.to_dict() + assert row["rule_id"] == 156 + assert row["event"] == SURFACED + assert row["source"] == "write_path_rule" + # created_at is server-defaulted, so it is None until the row is flushed — + # `iso()` must tolerate that rather than raising on a fresh instance. + assert row["created_at"] is None