From 69ce7afc4518945b8fd04f545549f038eb29bac1 Mon Sep 17 00:00:00 2001 From: Bryan Van Deusen Date: Mon, 31 Aug 2026 00:45:22 -0400 Subject: [PATCH 01/19] fix(ci): /api/version reported the channel where the build belongs (rule 149) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit CI set BUILD_VERSION to the CHANNEL — literally "dev", "main", or the tag — so a running instance answered "which build are you?" with the name of a branch: {"version":"main"}. The cost was concrete rather than theoretical. During #3244's live acceptance a deploy was behaving as though it held older code, and the one endpoint whose job is to settle that could not. Rule 149's three values, now three fields: version the NAME, YYYY.MM.DD.HHMM from COMMIT time — "is this the same code?", so two lanes carrying one commit report one string build the ORDERING KEY, minutes since 2020-01-01 from BUILD time — "may this be installed over that?", and the only value anything may compare channel its own field. Never a suffix, never a segment of the name Plus `commit`, so the artifact's claim about itself can be checked against the : it was published under (rule 145) — which is exactly the question that could not be answered tonight. THE TWO CLOCKS ARE DELIBERATE and look like an inconsistency. The name comes from the commit so two lanes building one source agree; the key comes from the build so it cannot go backwards when an older commit is rebuilt. A test pins both derivations against being "tidied" into one. ABSENT RATHER THAN EMPTY when unknown. A local build has no ordering key and no channel; emitting "" or a placeholder would let it claim a position in an update order it is not part of. A malformed key is dropped rather than passed through — a reader that cannot order is correct, one that orders on garbage is not. The key is an int, because a string ordering key is how a comparison silently becomes lexicographic ("9" > "10"). The payload builder is extracted from the route so it can be tested as a dict rather than through app startup and a request context. Tests pin the SHAPE the lanes emit, not the values, including the midnight leading-zero case rule 149 names specifically — and assert CI never stamps a branch name as the version again. Co-Authored-By: Claude Opus 5 --- .forgejo/workflows/ci.yml | 48 ++++++++- Dockerfile | 23 ++++- src/scribe/routes/api.py | 57 ++++++++++- tests/test_version_endpoint.py | 182 +++++++++++++++++++++++++++++++++ 4 files changed, 302 insertions(+), 8 deletions(-) create mode 100644 tests/test_version_endpoint.py diff --git a/.forgejo/workflows/ci.yml b/.forgejo/workflows/ci.yml index 2acbc37..7f0e7b8 100644 --- a/.forgejo/workflows/ci.yml +++ b/.forgejo/workflows/ci.yml @@ -327,6 +327,14 @@ jobs: packages: write steps: - uses: actions/checkout@v6 + with: + # Rule 149 asks for this on any job deriving the version NAME. The + # name here comes from HEAD's commit TIME, which a depth-1 clone + # already has — but the rule states it unconditionally because the + # failure it guards is silent (a too-low value, every lane green), + # and a later change to how the name is derived would inherit the + # landmine rather than the guard. + fetch-depth: 0 - name: Generate image tags and version id: tags @@ -339,7 +347,27 @@ jobs: # the runner log on commit 2a374d9. run: | TAGS="${{ env.IMAGE }}:${{ github.sha }}" - BUILD_VERSION="dev" + + # THREE VALUES, NEVER FOLDED TOGETHER (rule 149). Until 2026-08-31 + # BUILD_VERSION was the CHANNEL — "dev" / "main" / the tag — so the + # image self-reported {"version":"main"}, a channel name where a + # build identifier belongs. That cost a debugging session: with the + # deploy misbehaving, nothing on the running instance could say + # which commit was serving it. + + # 1. ORDERING KEY — BUILD time, monotonic by construction. Minutes + # since 2020-01-01. Never a commit count (not monotonic across + # branches) and never commit time (goes DOWN when an older + # commit is rebuilt). + BUILD_KEY=$(( ( $(date -u +%s) - 1577836800 ) / 60 )) + + # 2. NAME — COMMIT time, so the same source reports the same string + # on every lane and the channel is the only thing that differs. + COMMIT_TS=$(git log --format=%ct -1 HEAD) + BUILD_NAME=$(date -u -d "@$COMMIT_TS" +%Y.%m.%d.%H%M) + + # 3. CHANNEL — its own value. Never a suffix, never a segment. + CHANNEL="dev" case "${{ github.ref }}" in refs/heads/dev) TAGS="$TAGS,${{ env.IMAGE }}:dev" @@ -348,15 +376,17 @@ jobs: # main IS the production line: publish :latest (plus the : # set above). No separate :main tag. TAGS="$TAGS,${{ env.IMAGE }}:latest" - BUILD_VERSION="main" + CHANNEL="stable" ;; refs/tags/*) TAGS="$TAGS,${{ env.IMAGE }}:latest,${{ env.IMAGE }}:${{ github.ref_name }}" - BUILD_VERSION="${{ github.ref_name }}" + CHANNEL="stable" ;; esac echo "value=$TAGS" >> $GITHUB_OUTPUT - echo "build_version=$BUILD_VERSION" >> $GITHUB_OUTPUT + echo "build_name=$BUILD_NAME" >> $GITHUB_OUTPUT + echo "build_key=$BUILD_KEY" >> $GITHUB_OUTPUT + echo "channel=$CHANNEL" >> $GITHUB_OUTPUT - name: Free disk space # Self-hosted runner housekeeping. Two-step cleanup: @@ -386,7 +416,15 @@ jobs: push: true provenance: false tags: ${{ steps.tags.outputs.value }} - build-args: BUILD_VERSION=${{ steps.tags.outputs.build_version }} + # All three, plus the commit — rule 145: the registry's identity for + # a build (:) and the artifact's identity for itself must + # agree, and they can only be checked against each other if the + # artifact says which commit it is. + build-args: | + BUILD_VERSION=${{ steps.tags.outputs.build_name }} + BUILD_KEY=${{ steps.tags.outputs.build_key }} + BUILD_CHANNEL=${{ steps.tags.outputs.channel }} + BUILD_COMMIT=${{ github.sha }} # Registry-backed layer cache. Pull from :cache to prime # BuildKit, push updated layers back to :cache so the next # build starts warm even if the runner's local cache was diff --git a/Dockerfile b/Dockerfile index ffe1e79..c94d385 100644 --- a/Dockerfile +++ b/Dockerfile @@ -41,10 +41,29 @@ COPY alembic/ alembic/ # Ensure Python finds the source tree (where static files live) before site-packages ENV PYTHONPATH=/app/src -# Version is injected at build time via --build-arg BUILD_VERSION=YY.MM.DD.N -# Falls back to "dev" for local / untagged builds +# THREE VALUES, NEVER FOLDED TOGETHER (rule 149), plus the commit. +# +# BUILD_VERSION is the NAME (YYYY.MM.DD.HHMM, from COMMIT time) — the same +# string on every lane for the same source, so it answers "is this the same +# code?" rather than "which lane built it?". +# BUILD_KEY is the ORDERING KEY (minutes since 2020-01-01, from BUILD time) — +# the only value anything may compare to decide what is newer. +# BUILD_CHANNEL is its own field. Never a suffix, never a segment of the name. +# BUILD_COMMIT lets the artifact's self-report be checked against the : +# it was published under (rule 145). +# +# Each defaults to empty rather than to a placeholder, EXCEPT the name: a +# local build genuinely has no ordering key or channel, and the endpoint says +# so by omitting them. Inventing values would make a local image claim a +# position in an update order it is not part of. ARG BUILD_VERSION=dev +ARG BUILD_KEY= +ARG BUILD_CHANNEL= +ARG BUILD_COMMIT= ENV APP_VERSION=$BUILD_VERSION +ENV APP_BUILD_KEY=$BUILD_KEY +ENV APP_CHANNEL=$BUILD_CHANNEL +ENV APP_COMMIT=$BUILD_COMMIT EXPOSE 5000 CMD ["sh", "-c", "alembic upgrade head && hypercorn 'scribe.app:create_app()' --bind 0.0.0.0:5000 --keep-alive 600"] diff --git a/src/scribe/routes/api.py b/src/scribe/routes/api.py index a15fd84..7cf9477 100644 --- a/src/scribe/routes/api.py +++ b/src/scribe/routes/api.py @@ -10,6 +10,61 @@ async def health(): return jsonify({"status": "ok"}) +def build_version_payload() -> dict: + """What build is this, separated into the values that answer different + questions (rule 149). + + UNTIL 2026-08-31 THIS RETURNED THE CHANNEL. `BUILD_VERSION` in CI was + literally "dev" / "main" / the tag, so a running instance reported + `{"version": "main"}` — a channel name sitting where a build identifier + belongs. The cost was concrete: with a deploy misbehaving, nothing on the + instance could say which commit was serving it, and the one endpoint whose + job that is answered with the name of a branch. + + The three values, and why they are three: + + - `version` — the NAME, `YYYY.MM.DD.HHMM` from COMMIT time. Answers "is + this the same code?", so two channels carrying one commit report the + same string. + - `build` — the ORDERING KEY, minutes since 2020-01-01 from BUILD time. + Answers "may this be installed over that?". The ONLY value anything may + compare; it is monotonic by construction, which neither a commit count + (branches diverge) nor a commit time (rebuilds go backwards) is. + - `channel` — its own field, never folded into the name. + + Plus `commit`, so the artifact's claim about itself can be checked against + the `:` it was published under (rule 145). + + ABSENT RATHER THAN EMPTY when unknown. A local build has no ordering key + and no channel, and saying so is honest; emitting `""` or a placeholder + would let it claim a position in an update order it is not part of. A + reader must treat a missing `build` as "cannot be ordered", not as zero. + """ + payload: dict = {"version": os.environ.get("APP_VERSION", "dev")} + + # Reported verbatim, never validated against an enum — a build claiming + # something unexpected is better shown than dropped (rule 149). + for key, env in (("channel", "APP_CHANNEL"), ("commit", "APP_COMMIT")): + value = (os.environ.get(env) or "").strip() + if value: + payload[key] = value + + raw_key = (os.environ.get("APP_BUILD_KEY") or "").strip() + if raw_key: + try: + # An INTEGER, not a string. A string ordering key is how a + # comparison silently becomes lexicographic — "9" > "10" — which + # is the same class of fault as folding the channel in: it reads + # fine and orders wrong. + payload["build"] = int(raw_key) + except ValueError: + # A malformed key is omitted rather than passed through: a reader + # that cannot order is correct, one that orders on garbage is not. + pass + + return payload + + @api.route("/version") async def version(): - return jsonify({"version": os.environ.get("APP_VERSION", "dev")}) + return jsonify(build_version_payload()) diff --git a/tests/test_version_endpoint.py b/tests/test_version_endpoint.py new file mode 100644 index 0000000..ebe01e7 --- /dev/null +++ b/tests/test_version_endpoint.py @@ -0,0 +1,182 @@ +"""`/api/version` reports three values, and never folds them together. + +WHAT THIS IS ABOUT (rule 149). Until 2026-08-31 the endpoint returned +`{"version": "main"}` — CI set `BUILD_VERSION` to the CHANNEL, so a running +instance answered the question "which build are you?" with the name of a +branch. The cost was concrete rather than theoretical: during #3244's live +acceptance a deploy was behaving as though it held older code, and the one +endpoint whose job is to settle that could not. + +The three values answer different questions and so cannot be one value: + + version the NAME, from COMMIT time — "is this the same code?" + build the ORDERING KEY, BUILD time — "may this be installed over that?" + channel its own field — "which line is this?" + +These pin the SHAPE the lanes emit, not the values — a test asserting today's +timestamp would fail tomorrow, and one asserting the format catches the thing +that actually breaks: a channel creeping back into the name, or an ordering +key that is not orderable. +""" +import os +import pathlib +import re +from datetime import datetime, timezone +from unittest.mock import patch + +import pytest + +CI = pathlib.Path(__file__).resolve().parents[1] / ".forgejo/workflows/ci.yml" + +# The NAME's shape: four dot-separated numeric fields, zero-padded, and +# nothing else. A channel token anywhere in here is the bug this file exists +# to prevent. +NAME_RE = re.compile(r"^\d{4}\.\d{2}\.\d{2}\.\d{4}$") + + +_ENV_KEYS = ("APP_VERSION", "APP_BUILD_KEY", "APP_CHANNEL", "APP_COMMIT") + + +def _version_payload(env: dict) -> dict: + """The real payload builder, under a controlled environment. + + Calls `build_version_payload` rather than the route: the payload is the + behaviour, and reaching it through an app and a request context would + make these tests depend on app startup to assert a dict. The route is a + one-line `jsonify` wrapper over this. + """ + from scribe.routes.api import build_version_payload + + with patch.dict(os.environ, env, clear=False): + # patch.dict cannot REMOVE, and "absent" is exactly what several of + # these assert — so anything the caller left out is cleared. + for key in _ENV_KEYS: + if key not in env: + os.environ.pop(key, None) + return build_version_payload() + + +def test_the_three_values_are_three_fields(): + """The headline. One field cannot answer three questions, and the failure + mode of trying is silent: the string looks plausible and orders wrong.""" + out = _version_payload({ + "APP_VERSION": "2026.08.31.0403", + "APP_BUILD_KEY": "3505443", + "APP_CHANNEL": "stable", + "APP_COMMIT": "b267037", + }) + assert out["version"] == "2026.08.31.0403" + assert out["build"] == 3505443 + assert out["channel"] == "stable" + assert out["commit"] == "b267037" + + +def test_the_channel_is_never_inside_the_name(): + """The regression itself. `{"version": "main"}` is what this catches.""" + out = _version_payload({ + "APP_VERSION": "2026.08.31.0403", "APP_CHANNEL": "stable", + }) + assert NAME_RE.match(out["version"]), ( + f"the version name is {out['version']!r} — not YYYY.MM.DD.HHMM. A " + f"channel or branch name here is the 2026-08-31 bug returning." + ) + assert "stable" not in out["version"] + + +def test_the_ordering_key_is_an_INTEGER(): + """A string ordering key is how a comparison silently becomes + lexicographic — "9" > "10" — which reads fine and orders wrong.""" + out = _version_payload({"APP_VERSION": "x", "APP_BUILD_KEY": "3505443"}) + assert isinstance(out["build"], int) + assert not isinstance(out["build"], bool) + + +def test_unknown_values_are_ABSENT_not_empty(): + """A local build genuinely has no ordering key and no channel. Emitting + `""` or a placeholder would let it claim a position in an update order it + is not part of; a reader must see "cannot be ordered", not zero.""" + out = _version_payload({"APP_VERSION": "dev"}) + assert out == {"version": "dev"} + assert "build" not in out and "channel" not in out and "commit" not in out + + +def test_an_empty_env_var_counts_as_absent(): + """Docker sets an ARG with no default to the empty string, so "unset" and + "set to nothing" both reach the handler as ''.""" + out = _version_payload({ + "APP_VERSION": "dev", "APP_CHANNEL": "", "APP_BUILD_KEY": "", + "APP_COMMIT": " ", + }) + assert out == {"version": "dev"} + + +def test_a_malformed_ordering_key_is_dropped_not_passed_through(): + """A reader that cannot order is correct; one that orders on garbage is + not. Dropping it degrades to "unorderable", which is a state the caller + already has to handle.""" + out = _version_payload({"APP_VERSION": "dev", "APP_BUILD_KEY": "main"}) + assert "build" not in out + + +def test_the_channel_is_reported_verbatim(): + """Never validated against an enum — a build claiming something + unexpected is better shown than dropped (rule 149).""" + out = _version_payload({"APP_VERSION": "dev", "APP_CHANNEL": "canary"}) + assert out["channel"] == "canary" + + +# ── The lane, as CI actually writes it ───────────────────────────────── + +def test_ci_does_not_stamp_the_channel_as_the_version(): + """The bug lived in the workflow, not the handler. A correct handler fed + `BUILD_VERSION=main` still reports a branch name.""" + text = CI.read_text() + assert "BUILD_VERSION=${{ steps.tags.outputs.build_name }}" in text, ( + "CI no longer passes the derived NAME as BUILD_VERSION. If it is " + "passing a branch or channel again, /api/version is lying." + ) + for wrong in ('BUILD_VERSION="main"', 'BUILD_VERSION="dev"'): + assert wrong not in text, ( + f"CI sets {wrong} — that is the channel in the version field, " + f"which is the 2026-08-31 regression." + ) + + +def test_ci_derives_the_name_from_COMMIT_time_and_the_key_from_BUILD_time(): + """The two clocks are deliberate and easy to "tidy" into one. + + The name must come from the commit so two lanes building one source agree; + the key must come from the build so it cannot go backwards when an older + commit is rebuilt. Collapsing them breaks whichever question loses. + """ + text = CI.read_text() + assert "git log --format=%ct -1 HEAD" in text, ( + "the version NAME is no longer derived from commit time — two lanes " + "building the same commit will now report different strings" + ) + assert "$(date -u +%s) - 1577836800" in text, ( + "the ORDERING KEY is no longer minutes-since-2020 from build time; " + "if it now comes from the commit it can go backwards on a rebuild" + ) + + +def test_ci_passes_all_three_plus_the_commit(): + text = CI.read_text() + for arg in ("BUILD_KEY=", "BUILD_CHANNEL=", "BUILD_COMMIT="): + assert arg in text, f"CI no longer passes {arg} to the image build" + + +@pytest.mark.parametrize("commit_epoch,expected", [ + # Midnight, where a naive formatter drops the leading zeros and yields + # "2026.01.05.0" — rule 149 names this case specifically. + (datetime(2026, 1, 5, 0, 0, tzinfo=timezone.utc), "2026.01.05.0000"), + (datetime(2026, 1, 5, 0, 7, tzinfo=timezone.utc), "2026.01.05.0007"), + (datetime(2026, 12, 31, 23, 59, tzinfo=timezone.utc), "2026.12.31.2359"), + (datetime(2026, 8, 31, 4, 3, tzinfo=timezone.utc), "2026.08.31.0403"), +]) +def test_the_name_format_zero_pads_every_field(commit_epoch, expected): + """`date -u +%Y.%m.%d.%H%M` is what CI runs; this pins what that must + produce, so a reformat that loses zero-padding fails here rather than in + a comparison months later.""" + assert commit_epoch.strftime("%Y.%m.%d.%H%M") == expected + assert NAME_RE.match(expected) From 7827b4ce639ea5d1948ef4cad851ef018213438a Mon Sep 17 00:00:00 2001 From: Bryan Van Deusen Date: Mon, 31 Aug 2026 08:09:09 -0400 Subject: [PATCH 02/19] fix(embeddings): the index refresh loses the race it used to deadlock (#3262) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit An embedding refresh replaces a record's vectors as delete-then-insert, which takes the chunk rows first and the parent row second (via the insert's foreign key). A cascading delete of the parent takes exactly those two locks in the other order. Postgres calls the cycle a deadlock and kills one side: sometimes the detached embedder, silently, and sometimes the user's delete, as a 500 on an operation that should have worked. Both upserts now claim the parent row with FOR KEY SHARE NOWAIT before touching any chunk row. That removes the cycle instead of narrowing it — either the embedder is first and the delete queues behind it, or the delete already holds the row and the embedder loses at once, which is the side designed to lose. FOR KEY SHARE is the lock the insert would take anyway, so an ordinary edit is unaffected. The note twin, recorded as unverified on the issue, has the same shape and the same fix; a trash purge is the hard delete that reaches it. Unit tests pin the ORDER and the lock mode by compiling the statement; the integration pair holds a real delete open in one transaction and proves the embedder returns having written nothing, with a deadline so a regression fails instead of hanging. --- src/scribe/services/embeddings.py | 49 +++++ src/scribe/services/notes.py | 4 + src/scribe/services/rulebooks.py | 4 + tests/helpers.py | 8 +- tests/test_embedding_yields_to_a_delete.py | 118 ++++++++++++ ..._integration_embedding_yields_to_delete.py | 173 ++++++++++++++++++ 6 files changed, 354 insertions(+), 2 deletions(-) create mode 100644 tests/test_embedding_yields_to_a_delete.py create mode 100644 tests/test_integration_embedding_yields_to_delete.py diff --git a/src/scribe/services/embeddings.py b/src/scribe/services/embeddings.py index fb8badd..a905b1e 100644 --- a/src/scribe/services/embeddings.py +++ b/src/scribe/services/embeddings.py @@ -344,6 +344,49 @@ def chunk_document(title: str | None, body: str | None) -> list[str]: return chunks +async def _claim_parent_row(session, id_column, row_id: int, label: str) -> bool: + """Lock the record a vector belongs to BEFORE rewriting that vector (#3262). + + An embedding write and a cascading delete of the same record take the same + two row locks in OPPOSITE orders. The embedder deletes the old chunk rows + and then, on INSERT, needs the foreign key's lock on the parent; a delete + of the parent — or of the rulebook, topic or project above it — locks the + parent first and cascades down into the chunk rows. That is a cycle, and + Postgres breaks it by killing one side at random: sometimes the embedding + write, which is swallowed and invisible, and sometimes the operator's + delete, which surfaces as a 500 on an operation that should have worked. + + Claiming the parent first REMOVES the cycle rather than narrowing it. + Either the embedder arrives first and the delete waits its turn behind it, + or the delete already holds the row and NOWAIT makes the embedder lose at + once. The embedder is the side that should lose: a skipped refresh costs a + stale vector until the next write or the startup backfill, and the other + outcome costs a person their request. + + FOR KEY SHARE, not FOR UPDATE — it is precisely the lock the INSERT's + foreign key would take anyway, so it conflicts with a delete of the parent + and with nothing else. An ordinary edit of the same record, or a second + refresh racing this one, is unaffected. + + Returns False when the row is locked or already gone; the caller skips. + """ + try: + held = (await session.execute( + select(id_column) + .where(id_column == row_id) + .with_for_update(key_share=True, nowait=True) + )).scalar_one_or_none() + except Exception: + # LockNotAvailable: this record is being deleted right now. Not an + # error — the delete wins by design. + logger.debug("Skipping embedding for %s %d — row is being deleted", label, row_id) + return False + if held is None: + logger.debug("Skipping embedding for %s %d — row is gone", label, row_id) + return False + return True + + async def upsert_note_embedding( note_id: int, user_id: int, title: str | None, body: str | None ) -> None: @@ -380,6 +423,8 @@ async def upsert_note_embedding( try: async with async_session() as session: + if not await _claim_parent_row(session, Note.id, note_id, "note"): + return await session.execute( delete(NoteEmbedding).where(NoteEmbedding.note_id == note_id) ) @@ -666,6 +711,8 @@ async def upsert_rule_embedding( replacement is atomic per rule so a concurrent read sees the old chunk set or the new one, never a mixture. """ + from scribe.models.rulebook import Rule # runtime import: see TYPE_CHECKING above + doc_title, doc_body = rule_document(title, statement, when_to_apply) chunks = chunk_document(doc_title, doc_body) try: @@ -688,6 +735,8 @@ async def upsert_rule_embedding( try: async with async_session() as session: + if not await _claim_parent_row(session, Rule.id, rule_id, "rule"): + return await session.execute( delete(RuleEmbedding).where(RuleEmbedding.rule_id == rule_id) ) diff --git a/src/scribe/services/notes.py b/src/scribe/services/notes.py index db8d61d..4deee9c 100644 --- a/src/scribe/services/notes.py +++ b/src/scribe/services/notes.py @@ -76,6 +76,10 @@ def embed_note(note) -> None: exceptions are swallowed because a record that saved must not fail on its index refresh. No running loop (unit tests, scripts) is an ordinary case, not an error. + + Detaching also means this task races anything that deletes the note out + from under it. That is not handled here: `upsert_note_embedding` claims + the note's row before touching its vectors, and loses if it can't (#3262). """ try: import asyncio diff --git a/src/scribe/services/rulebooks.py b/src/scribe/services/rulebooks.py index d2378c1..ba11b69 100644 --- a/src/scribe/services/rulebooks.py +++ b/src/scribe/services/rulebooks.py @@ -379,6 +379,10 @@ def _refresh_rule_embedding(rule: Rule) -> None: swallowed because a rule that SAVED must not fail on its index refresh — a stale vector costs a missed search hit, a raised exception costs the write. No running loop (unit tests, scripts) is ordinary, not an error. + + Detaching also means this task races anything that deletes the rule out + from under it. That is not handled here: `upsert_rule_embedding` claims + the rule's row before touching its vectors, and loses if it can't (#3262). """ try: import asyncio diff --git a/tests/helpers.py b/tests/helpers.py index 45ac4a0..c23516c 100644 --- a/tests/helpers.py +++ b/tests/helpers.py @@ -59,14 +59,18 @@ def tool_doc(module: str, name: str) -> str: return _re.sub(r"\s+", " ", fn.__doc__) -def compiled_sql(element) -> str: +def compiled_sql(element, dialect=None) -> str: """A SQLAlchemy clause or statement rendered as literal SQL text. For asserting on the shape of a predicate without a database — which is how the visibility clauses and the knowledge facets are both tested. Was a private copy in each of those modules before #3128 needed a third. + + Pass `dialect` when the assertion is about something only one backend + renders — a Postgres row-lock mode, say. The generic dialect is enough for + a predicate's shape and would quietly drop the rest. """ - return str(element.compile(compile_kwargs={"literal_binds": True})) + return str(element.compile(dialect=dialect, compile_kwargs={"literal_binds": True})) def make_mock_session() -> AsyncMock: diff --git a/tests/test_embedding_yields_to_a_delete.py b/tests/test_embedding_yields_to_a_delete.py new file mode 100644 index 0000000..ba50388 --- /dev/null +++ b/tests/test_embedding_yields_to_a_delete.py @@ -0,0 +1,118 @@ +"""The embedding refresh must LOSE to a delete, not race it (#3262). + +Both upserts replace a record's vectors as delete-then-insert. That takes two +row locks — the chunk rows, then the parent row via the insert's foreign key — +in the exact reverse of the order a cascading delete of the parent takes them. +Postgres calls that a deadlock and kills one side at random, which sometimes +means killing the user's delete. + +These pin the ORDER, not the outcome: the claim on the parent goes first, and +when the claim fails nothing else in the transaction runs. Compiling the +statement is the only way to assert on a lock mode without a database — the +integration twin (test_integration_embedding_yields_to_delete.py) proves the +behaviour against a real one. +""" +from unittest.mock import AsyncMock, MagicMock, patch + +from sqlalchemy.dialects import postgresql +from sqlalchemy.exc import OperationalError + +from scribe.services import embeddings as emb +from tests.helpers import compiled_sql + +ONE_VECTOR = [[0.0] * 384] + +# The lock mode is a Postgres extension — the generic dialect renders a plain +# FOR UPDATE and would pass an assertion that proves nothing. +PG = postgresql.dialect() + + +def _mock_session(lock_result: object = 7, execute_side_effect=None): + """A session stand-in whose first execute answers the parent-row claim.""" + session = MagicMock() + claimed = MagicMock() + claimed.scalar_one_or_none.return_value = lock_result + if execute_side_effect is not None: + session.execute = AsyncMock(side_effect=execute_side_effect) + else: + session.execute = AsyncMock(return_value=claimed) + session.commit = AsyncMock() + session.add = MagicMock() + ctx = MagicMock() + ctx.__aenter__ = AsyncMock(return_value=session) + ctx.__aexit__ = AsyncMock(return_value=False) + return session, ctx + + +def _lock_unavailable() -> OperationalError: + """What asyncpg raises through SQLAlchemy when NOWAIT can't take the row.""" + return OperationalError("SELECT ...", {}, Exception("lock not available")) + + +async def test_a_note_refresh_claims_the_row_before_rewriting_its_vectors(): + """The claim is FIRST, and it is FOR KEY SHARE NOWAIT. + + FOR KEY SHARE because that is exactly the lock the insert's foreign key + takes anyway — it conflicts with a delete of the note and with nothing + else, so an ordinary edit is unaffected. NOWAIT because the whole point is + to lose immediately rather than queue up behind the delete and hold the + chunk rows while doing it. + """ + session, ctx = _mock_session() + with ( + patch.object(emb, "async_session", return_value=ctx), + patch.object(emb, "get_embeddings", AsyncMock(return_value=ONE_VECTOR)), + ): + await emb.upsert_note_embedding(7, 42, "T", "a short body") + + claim, replace = [c.args[0] for c in session.execute.call_args_list][:2] + assert compiled_sql(claim, dialect=PG).startswith("SELECT notes.id") + assert "FOR KEY SHARE NOWAIT" in compiled_sql(claim, dialect=PG) + assert compiled_sql(replace, dialect=PG).startswith("DELETE FROM note_embeddings") + session.add.assert_called() + + +async def test_a_rule_refresh_claims_the_row_before_rewriting_its_vectors(): + """The rule twin — the path the reported deadlock actually took.""" + session, ctx = _mock_session() + with ( + patch.object(emb, "async_session", return_value=ctx), + patch.object(emb, "get_embeddings", AsyncMock(return_value=ONE_VECTOR)), + ): + await emb.upsert_rule_embedding(9, "T", "a short statement", "on write") + + claim, replace = [c.args[0] for c in session.execute.call_args_list][:2] + assert compiled_sql(claim, dialect=PG).startswith("SELECT rules.id") + assert "FOR KEY SHARE NOWAIT" in compiled_sql(claim, dialect=PG) + assert compiled_sql(replace, dialect=PG).startswith("DELETE FROM rule_embeddings") + session.add.assert_called() + + +async def test_a_record_being_deleted_is_left_alone_rather_than_raced(): + """The claim failing ends the write — it does not fall through to the + delete-and-insert that would take the locks in the losing order.""" + session, ctx = _mock_session(execute_side_effect=_lock_unavailable()) + with ( + patch.object(emb, "async_session", return_value=ctx), + patch.object(emb, "get_embeddings", AsyncMock(return_value=ONE_VECTOR)), + ): + await emb.upsert_rule_embedding(9, "T", "a short statement", "on write") + + assert session.execute.await_count == 1, "it stopped at the claim" + session.add.assert_not_called() + session.commit.assert_not_awaited() + + +async def test_a_record_already_gone_is_not_re_embedded(): + """A vector inserted for a row that no longer exists is either a foreign + key violation or, worse, a resurrected chunk. Nothing to refresh.""" + session, ctx = _mock_session(lock_result=None) + with ( + patch.object(emb, "async_session", return_value=ctx), + patch.object(emb, "get_embeddings", AsyncMock(return_value=ONE_VECTOR)), + ): + await emb.upsert_note_embedding(7, 42, "T", "a short body") + + assert session.execute.await_count == 1 + session.add.assert_not_called() + session.commit.assert_not_awaited() diff --git a/tests/test_integration_embedding_yields_to_delete.py b/tests/test_integration_embedding_yields_to_delete.py new file mode 100644 index 0000000..be17d73 --- /dev/null +++ b/tests/test_integration_embedding_yields_to_delete.py @@ -0,0 +1,173 @@ +"""#3262 against a real Postgres: the embedder loses the race, it doesn't run it. + +The reported failure was a deadlock — `DELETE FROM rulebooks` killed by the +server while a detached `upsert_rule_embedding` held the other half of the +cycle. It cannot be reproduced with mocks, because there is nothing to +deadlock: the whole bug lives in the ORDER two transactions take two row +locks, which only a lock manager can adjudicate. + +So each test here holds a real delete open in one transaction and calls the +embedder in another. What is being pinned is that the embedder RETURNS — +promptly, having written nothing. Before the fix it would sit on the chunk +rows waiting for a delete that is itself waiting on the insert's foreign key, +and the test would hang rather than fail, which is why every call carries a +deadline (rule 156). +""" +import asyncio +from unittest.mock import AsyncMock, patch + +import pytest +import pytest_asyncio +from sqlalchemy import delete, select + +from scribe.models import async_session +from scribe.models.embedding import NoteEmbedding, RuleEmbedding +from scribe.models.note import Note +from scribe.models.rulebook import Rulebook +from scribe.services import embeddings as emb +from scribe.services import rulebooks as rulebooks_svc +from tests.helpers import ensure_user + +pytestmark = [pytest.mark.integration, pytest.mark.usefixtures("_dispose_engine")] + +OWNER_USERNAME = "embed_lock_owner" + +# Generous, because the assertion is "it did not block indefinitely", not "it +# was fast". A machine under load must not turn this into a flake; a genuinely +# blocked embedder never returns at all, so no honest run comes near this. +YIELD_DEADLINE_SECONDS = 20 + +# What the embedder would write if it wrongly went ahead. Distinct from the +# text the fixture's own create_* wrote, so the assertion cannot be satisfied +# by rows that were already there. +SENTINEL = "sentinelvector" + +ONE_VECTOR = [[0.0] * 384] + +# The fixture's own embedding task runs the REAL embedder, which either loads a +# model or gives up; both are bounded well inside this. +SETTLE_DEADLINE_SECONDS = 30 + + +@pytest_asyncio.fixture +async def seeded(): + """A rule and a note to race against. + + CLEANED AT SETUP, NOT TEARDOWN — the same constraint #3241 hit and the + reason this file exists. `create_rule` fires its own detached embedding + task; a teardown that deleted the rulebook would be racing exactly the + thing under test, on a loop that is closing. + """ + async with async_session() as s: + owner = await ensure_user(s, OWNER_USERNAME) + uid = owner.id + await s.commit() + for book in (await s.execute( + select(Rulebook).where(Rulebook.owner_user_id == uid) + )).scalars().all(): + await s.delete(book) + for note in (await s.execute( + select(Note).where(Note.user_id == uid) + )).scalars().all(): + await s.delete(note) + await s.commit() + + book = await rulebooks_svc.create_rulebook(uid, "Lock fixtures") + topic = await rulebooks_svc.create_topic(book.id, uid, "locks") + rule = await rulebooks_svc.create_rule( + topic.id, uid, "A rule with vectors", + "Something for the embedder to index.", + ) + async with async_session() as s: + note = Note(user_id=uid, title="A note with vectors", body="Body text.") + s.add(note) + await s.commit() + note_id = note.id + + await _settle_detached_writes() + return {"uid": uid, "book_id": book.id, "rule_id": rule.id, "note_id": note_id} + + +async def _settle_detached_writes() -> None: + """Let `create_rule`'s own fire-and-forget embedding task finish. + + It is the same detached write these tests are about, aimed at the same + rule, and left in flight it would land in the middle of an assertion about + that rule's rows. Bounded, and a timeout is not a failure — the tests below + carry their own deadlines, and this is only tidying the start line. + """ + pending = [t for t in asyncio.all_tasks() if t is not asyncio.current_task()] + if pending: + await asyncio.wait(pending, timeout=SETTLE_DEADLINE_SECONDS) + + +async def _rule_chunks(rule_id: int) -> list[str]: + async with async_session() as s: + return list((await s.execute( + select(RuleEmbedding.chunk_text).where(RuleEmbedding.rule_id == rule_id) + )).scalars().all()) + + +async def _note_chunks(note_id: int) -> list[str]: + async with async_session() as s: + return list((await s.execute( + select(NoteEmbedding.chunk_text).where(NoteEmbedding.note_id == note_id) + )).scalars().all()) + + +async def test_a_rule_refresh_yields_to_a_delete_cascading_from_its_rulebook(seeded): + """The reported case, exactly: the delete lands on the RULEBOOK and reaches + the rule through two cascades, which is why nothing on the rule's own write + path could have seen it coming.""" + async with async_session() as blocker: + # Uncommitted on purpose — the cascade's locks are held for as long as + # this transaction stays open, which is the state the embedder must + # decline to fight over. + await blocker.execute(delete(Rulebook).where(Rulebook.id == seeded["book_id"])) + try: + with patch.object(emb, "get_embeddings", AsyncMock(return_value=ONE_VECTOR)): + await asyncio.wait_for( + emb.upsert_rule_embedding( + seeded["rule_id"], SENTINEL, f"{SENTINEL} statement", + ), + timeout=YIELD_DEADLINE_SECONDS, + ) + finally: + await blocker.rollback() + + assert not any(SENTINEL in text for text in await _rule_chunks(seeded["rule_id"])), \ + "the embedder wrote into a rule that was being deleted" + + +async def test_a_note_refresh_yields_to_a_delete_of_the_note(seeded): + """The note twin, which #3262 recorded as unverified. Notes are soft-deleted + day to day, so the hard delete a trash purge issues is the one that can put + a lock on the row while a refresh is in flight.""" + async with async_session() as blocker: + await blocker.execute(delete(Note).where(Note.id == seeded["note_id"])) + try: + with patch.object(emb, "get_embeddings", AsyncMock(return_value=ONE_VECTOR)): + await asyncio.wait_for( + emb.upsert_note_embedding( + seeded["note_id"], seeded["uid"], SENTINEL, f"{SENTINEL} body", + ), + timeout=YIELD_DEADLINE_SECONDS, + ) + finally: + await blocker.rollback() + + assert not any(SENTINEL in text for text in await _note_chunks(seeded["note_id"])), \ + "the embedder wrote into a note that was being deleted" + + +async def test_an_uncontended_refresh_still_writes(seeded): + """The guard against the cheapest possible false pass: a claim that never + succeeds would satisfy both tests above while quietly ending semantic + search.""" + with patch.object(emb, "get_embeddings", AsyncMock(return_value=ONE_VECTOR)): + await emb.upsert_rule_embedding( + seeded["rule_id"], SENTINEL, f"{SENTINEL} statement", + ) + + assert any(SENTINEL in text for text in await _rule_chunks(seeded["rule_id"])), \ + "an unlocked rule was not embedded" From 9d8104f7a5a3eb0d2b45506b8c0471bf6d6be278 Mon Sep 17 00:00:00 2001 From: Bryan Van Deusen Date: Mon, 31 Aug 2026 08:13:29 -0400 Subject: [PATCH 03/19] fix(embeddings): key_share alone is FOR NO KEY UPDATE, not FOR KEY SHARE (#3262) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit SQLAlchemy spells Postgres's four row locks as a read/key_share pair, so `with_for_update(key_share=True)` renders FOR NO KEY UPDATE — an exclusive lock that two refreshes of the same record would fight over, and that an ordinary concurrent edit would block. The claim needs `read=True` as well to be the FOR KEY SHARE the docstring describes. Caught by the unit test that compiles the statement, which is the whole reason it asserts on the rendered lock mode rather than on behaviour that looks identical either way. --- src/scribe/services/embeddings.py | 5 ++++- 1 file changed, 4 insertions(+), 1 deletion(-) diff --git a/src/scribe/services/embeddings.py b/src/scribe/services/embeddings.py index a905b1e..bf66e49 100644 --- a/src/scribe/services/embeddings.py +++ b/src/scribe/services/embeddings.py @@ -374,7 +374,10 @@ async def _claim_parent_row(session, id_column, row_id: int, label: str) -> bool held = (await session.execute( select(id_column) .where(id_column == row_id) - .with_for_update(key_share=True, nowait=True) + # BOTH flags: SQLAlchemy spells the four Postgres row locks as a + # read/key_share pair, and key_share alone is FOR NO KEY UPDATE — + # which would make two refreshes of one record fight each other. + .with_for_update(read=True, key_share=True, nowait=True) )).scalar_one_or_none() except Exception: # LockNotAvailable: this record is being deleted right now. Not an From 70d84fbfd7ba96b5319b5370bb496df3fb0413c5 Mon Sep 17 00:00:00 2001 From: Bryan Van Deusen Date: Mon, 31 Aug 2026 08:20:11 -0400 Subject: [PATCH 04/19] ci(integration): print the runner facts that rules 79 and 81 assert (#3237) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Three conditional rules state facts about this act_runner — services are not reachable by hostname (79), the service container's name is derived from the job's truncated display name (80), and `run:` steps execute under a shell without bash features (81). None had ever been verified, because each check reads "add a step to a live CI job and read the log" and nobody wants to arrange a throwaway run to do it. So the step is not throwaway. Two lines on every integration run turn the next sweep of these rules into a log read. Rule 80 needs nothing new: the container listing the suite step already prints for the name filter is its evidence, and run 5055's log already answers it. Every command is guarded with a fallback. This observes the lane; it must not be able to break it. --- .forgejo/workflows/ci.yml | 15 +++++++++++++++ 1 file changed, 15 insertions(+) diff --git a/.forgejo/workflows/ci.yml b/.forgejo/workflows/ci.yml index 7f0e7b8..6ca1627 100644 --- a/.forgejo/workflows/ci.yml +++ b/.forgejo/workflows/ci.yml @@ -279,6 +279,21 @@ jobs: env: UV_PROJECT_ENVIRONMENT: /opt/venv run: uv sync --locked --extra dev + # Standing answers to the checks carried by rules 81 and 79 — two facts + # about THIS runner that conditional rules assert as fact, and that + # otherwise need a throwaway job to confirm (#3237). Printing them on + # every integration run makes the next rulebook sweep a log read. + # Rule 80's evidence is the container listing the next step already + # prints. Every command is guarded: a diagnostic that can break the lane + # it observes is worse than no diagnostic. + - name: Runner facts (rules 79 and 81) + run: | + echo "--- rule 81: which shell runs a run: step ---" + readlink -f /bin/sh || echo "/bin/sh: not a symlink" + ps -p $$ -o comm= || true + echo "--- rule 79: is a service reachable by its hostname yet? ---" + getent hosts postgres \ + || echo "no — 'postgres' does not resolve; the bridge-IP lookup is still required" - name: Integration suite (resolve service IP, migrate, test) run: | set -eux From 05da26eb242f8d58da5cc5a81c52148d500da0d1 Mon Sep 17 00:00:00 2001 From: Bryan Van Deusen Date: Mon, 31 Aug 2026 08:24:14 -0400 Subject: [PATCH 05/19] ci(integration): the run: shell is dash, not busybox (#3237) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit The runner-facts step answered rule 81's check on its first run, and the answer is the one the check itself warned about: `/bin/sh` resolves to `/usr/bin/dash`, because ci-python is Debian-based. The constraint the rule exists for is unchanged — dash has no /dev/tcp, no arrays, no `[[ ]]` — but the shell has never been busybox, and this comment was repeating the wrong name at the one place a reader would trust it. Rule 81's own statement still says busybox; correcting it is a rulebook edit and goes through propose -> approve -> apply. --- .forgejo/workflows/ci.yml | 5 +++-- 1 file changed, 3 insertions(+), 2 deletions(-) diff --git a/.forgejo/workflows/ci.yml b/.forgejo/workflows/ci.yml index 6ca1627..267a6e7 100644 --- a/.forgejo/workflows/ci.yml +++ b/.forgejo/workflows/ci.yml @@ -304,8 +304,9 @@ jobs: PG_IP=$(docker inspect -f '{{range .NetworkSettings.Networks}}{{.IPAddress}}{{end}}' "$PG") test -n "$PG_IP" export DATABASE_URL="postgresql+asyncpg://scribe:ci_integration@${PG_IP}:5432/scribe_test" - # Wait for Postgres to accept connections (busybox sh — the runner - # default — has no bash /dev/tcp, so use Python). + # Wait for Postgres to accept connections. The run: shell is dash + # (/bin/sh -> /usr/bin/dash on this Debian-based image, confirmed by + # the step above) — no bash /dev/tcp, so use Python. /opt/venv/bin/python - "$PG_IP" <<'PY' import socket, sys, time for _ in range(30): From 0d4b1556997208b099a9469b6d7231b074401479 Mon Sep 17 00:00:00 2001 From: Bryan Van Deusen Date: Mon, 31 Aug 2026 15:52:17 -0400 Subject: [PATCH 06/19] feat(telemetry): pull-through per surface, not just per corpus (#3311) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit The readout already grouped usage by source — `group_by(event, source)` — and the loop directly below it threw the source away, collapsing every surface into one corpus-wide ratio. So the question a threshold is actually tuned against, "is THIS surface worth its noise", could not be asked of any surface, while the data to answer it sat in the table. `usage.by_source` reports notes_surfaced / notes_pulled / pull_through per surface. The grain is the note, not the call: a pull records the door it came through, not the surface that led there, so grouping the pulled rows by source would answer a different question. Joining surfaced rows to pulled rows on note_id answers this one without the session identity #2085 declined to invent — at the cost of being an upper bound per surface, which the docstring says where it is read. Ambient surfaces report counts and a null ratio: nothing chose those records, so "surfaced often, opened never" is not a judgment about them. A surface that genuinely produced nothing reports 0.0, which must not look like the null. The join is guarded separately from the two reads above it. #2663 was a novel SQL shape the database rejected inside a broad except; this is the novel shape here, and it must not take down two readouts that work. Tests are integration for that same reason — a mock passes on a query Postgres refuses. They pin the distinct-first property (three surfacings of one note are one note), the ambient null, and the LIKE escape, since an unescaped `mcp_%` also matches `mcpXget_note` and nothing else in the payload would show the difference. --- src/scribe/mcp/tools/search.py | 17 +++ src/scribe/services/retrieval_telemetry.py | 117 ++++++++++++++++++ tests/test_services_retrieval_telemetry.py | 137 +++++++++++++++++++++ 3 files changed, 271 insertions(+) diff --git a/src/scribe/mcp/tools/search.py b/src/scribe/mcp/tools/search.py index c6db75d..410c308 100644 --- a/src/scribe/mcp/tools/search.py +++ b/src/scribe/mcp/tools/search.py @@ -182,6 +182,23 @@ async def retrieval_telemetry(days: int = 30) -> dict: tuned against — only by a pull the agent made. Aggregating across the mcp_/rest_ prefix would silently answer the wrong one. + `usage["by_source"]` — THE number to tune a threshold against, because the + top-level `pull_through` is a corpus average and averages the surfaces + together. Per surface: `notes_surfaced`, `notes_pulled`, `pull_through`, + and `ambient: true` on surfaces whose surfacings were not scored choices + (their ratio is null — "surfaced often, opened never" is not a judgment + about a record nothing chose). Read it as: of the distinct notes THIS + surface put in front of the agent, how many did the agent then open? + + Two limits on it, both deliberate. It is an UPPER BOUND per surface: a pull + records the door it came through, not the surface that led there, so a note + surfaced by two surfaces and opened once counts for both — attribution + would need the session identity #2085 declined to invent. And RULE + surfacings are absent: `write_path_rule` appears in `sources` with its + scores but has no usage counter at all, so it has no row here (#3311). + `by_source_failed: true` means that one query failed while the rest of the + readout stood. + Scoped to your own telemetry — a retrieval log records what your agent asked for, query text included, and is not a shared record kind. diff --git a/src/scribe/services/retrieval_telemetry.py b/src/scribe/services/retrieval_telemetry.py index 1fd747f..1377ecd 100644 --- a/src/scribe/services/retrieval_telemetry.py +++ b/src/scribe/services/retrieval_telemetry.py @@ -199,6 +199,12 @@ async def retrieval_summary(user_id: int | None, *, days: int = 30) -> dict: it was built for. Reading each from its own table is both cheaper and more honest than correlating them through JSONB. + `usage["by_source"]` is the one join, and it stays INSIDE + `note_usage_events` — surfaced rows against pulled rows on note_id. That + answers "of the notes this surface chose, how many were opened", which the + top-level ratio averages away. It does not cross into `retrieval_logs`, so + the sentence above still holds. + Scoped to one user's own telemetry. There is no sharing model for a retrieval log — it records what THIS user's agent asked for, including the query text — so an owner filter is the whole access rule here rather than a @@ -231,6 +237,10 @@ async def retrieval_summary(user_id: int | None, *, days: int = 30) -> dict: def pct(p: float): return func.percentile_cont(p).within_group(RetrievalLog.top_score.asc()) + # Assigned inside the try below; named here so the readout can tell + # "this query failed" from "this window has no rows" (#2663). + by_source_rows = None + try: async with async_session() as session: rows = ( @@ -310,6 +320,77 @@ async def retrieval_summary(user_id: int | None, *, days: int = 30) -> dict: ) ) ).scalar_one() + + # Per-source pull-through, at the NOTE grain (#3311). + # + # The `urows` query above already groups by source and the loop + # below then throws the source away, so until now this readout + # could say what the corpus's overall pull-through was and nothing + # about WHICH surface earned it. The data was always here; only + # the aggregation discarded it. + # + # It cannot be had by grouping the PULLED rows by source: a pull + # records the door it came through (`mcp_get_note`), not the + # surface that put the record in front of the agent. Correlating + # those within a session is what #2085 ruled out — there is no + # session identity server-side and inventing one would mean + # threading a client-supplied token through every read path. The + # note grain answers the question without one: of the distinct + # notes surface X chose, how many did an agent open in this window? + # + # Guarded separately from the reads above, on #2663's actual + # lesson. That outage was a NOVEL SQL SHAPE the database rejected + # inside a broad except. This join is the novel shape here, and a + # failure in it must not take down two readouts that already work. + try: + pulled_ids = ( + select(NoteUsageEvent.note_id) + .where( + NoteUsageEvent.created_at >= since, + NoteUsageEvent.user_id == user_id, + NoteUsageEvent.event == PULLED, + # autoescape because `_` is a LIKE wildcard: a bare + # like("mcp_%") also matches "mcpX…". The Python half + # of this readout uses str.startswith and has no such + # hazard; this is the SQL half's version of it. + NoteUsageEvent.source.startswith("mcp_", autoescape=True), + ) + .distinct() + .subquery() + ) + surfaced_pairs = ( + select(NoteUsageEvent.source, NoteUsageEvent.note_id) + .where( + NoteUsageEvent.created_at >= since, + NoteUsageEvent.user_id == user_id, + NoteUsageEvent.event == SURFACED, + ) + .distinct() + .subquery() + ) + # DISTINCT on (source, note_id) FIRST, which is what lets the + # outer aggregate be a plain count(): the pairs are already + # unique, so the left join cannot multiply them and no + # count(DISTINCT) is needed to undo damage that never happens. + by_source_rows = ( + await session.execute( + select( + surfaced_pairs.c.source, + func.count().label("notes_surfaced"), + func.count(pulled_ids.c.note_id).label("notes_pulled"), + ) + .select_from( + surfaced_pairs.outerjoin( + pulled_ids, + pulled_ids.c.note_id == surfaced_pairs.c.note_id, + ) + ) + .group_by(surfaced_pairs.c.source) + ) + ).all() + except Exception: + logger.warning("per-source pull-through read failed", exc_info=True) + by_source_rows = None except Exception: logger.warning("retrieval summary read failed", exc_info=True) out["read_failed"] = True @@ -350,5 +431,41 @@ async def retrieval_summary(user_id: int | None, *, days: int = 30) -> dict: round(usage["pulled_by_agent"] / usage["surfaced"], 4) if usage["surfaced"] else None ) + + # The same question, per surface — which is the one the top-level ratio + # cannot answer. A corpus average of 0.05 is compatible with one surface + # earning its noise and another producing none, and tuning a threshold + # needs to know which. + # + # UPPER BOUND, and say so where it will be read: a pull records the door, + # not the surface that led to it, so a note surfaced by two surfaces and + # opened once counts as pulled for both. Attribution would need the session + # identity #2085 declined to invent. The bound is still decisive in the + # direction that matters — a surface reading near zero here is not being + # flattered by the double-count. + if by_source_rows is None: + usage["by_source"] = {} + # Distinct from an empty window, for the same reason `read_failed` is. + usage["by_source_failed"] = True + else: + by_source: dict[str, dict] = {} + for source, n_surfaced, n_pulled in by_source_rows: + n_surfaced, n_pulled = int(n_surfaced or 0), int(n_pulled or 0) + ambient = source in AMBIENT_SOURCES + by_source[source] = { + "notes_surfaced": n_surfaced, + "notes_pulled": n_pulled, + # None rather than a number on an ambient surface: nothing + # CHOSE those records, so "surfaced often, opened never" is not + # a judgment about them. The counts stay visible; the ratio + # that would be misread does not. + "pull_through": ( + None if ambient or not n_surfaced + else round(n_pulled / n_surfaced, 4) + ), + "ambient": ambient, + } + usage["by_source"] = by_source + out["usage"] = usage return out diff --git a/tests/test_services_retrieval_telemetry.py b/tests/test_services_retrieval_telemetry.py index bd69dd7..df6ef87 100644 --- a/tests/test_services_retrieval_telemetry.py +++ b/tests/test_services_retrieval_telemetry.py @@ -195,6 +195,10 @@ async def test_retrieval_summary_is_empty_not_broken_for_a_fresh_install(_dispos assert out["sources"] == {} assert out["usage"]["pull_through"] is None # no division by zero assert out["usage"]["surfaced"] == 0 + # An empty dict, not a missing key and not a failure flag — the same + # "no rows" / "read broke" distinction the rest of this readout keeps. + assert out["usage"]["by_source"] == {} + assert "by_source_failed" not in out["usage"] @pytest.mark.integration @@ -222,3 +226,136 @@ async def test_retrieval_summary_sees_only_its_own_users_telemetry(_dispose_engi async with async_session() as s: await s.execute(delete(RetrievalLog).where(RetrievalLog.user_id == 990004)) await s.commit() + + +# ─── per-source pull-through (#3311) ───────────────────────────────────────── +# Integration for the same reason the block above is: this is a self-join with +# two DISTINCT subqueries and a LIKE escape, which is a new SQL shape in a +# module whose one production outage (#2663) was a new SQL shape the database +# rejected inside a broad except. A mock would pass on a query Postgres refuses. + + +@pytest.mark.integration +@pytest.mark.asyncio +async def test_by_source_separates_a_surface_that_earns_its_noise_from_one_that_does_not( + _dispose_engine, +): + """The whole point: the corpus average cannot say WHICH surface is working. + + Two ranked surfaces, identical volume, opposite outcomes — and a top-level + ratio that describes neither of them. + """ + from sqlalchemy import delete + + from scribe.models import async_session + from scribe.models.note_usage import NoteUsageEvent + from scribe.services.retrieval_telemetry import retrieval_summary + + UID = 990010 + async with async_session() as s: + s.add_all([ + # auto_inject chose note 1 three times and note 2 once. Three + # surfacings of one note is ONE note surfaced — the DISTINCT that + # keeps the join from multiplying rows is what this pins. + NoteUsageEvent(user_id=UID, note_id=1, event="surfaced", source="auto_inject"), + NoteUsageEvent(user_id=UID, note_id=1, event="surfaced", source="auto_inject"), + NoteUsageEvent(user_id=UID, note_id=1, event="surfaced", source="auto_inject"), + NoteUsageEvent(user_id=UID, note_id=2, event="surfaced", source="auto_inject"), + # write_path_semantic chose two notes and got nothing opened. + NoteUsageEvent(user_id=UID, note_id=3, event="surfaced", source="write_path_semantic"), + NoteUsageEvent(user_id=UID, note_id=4, event="surfaced", source="write_path_semantic"), + # One agent pull, of a note only auto_inject surfaced. + NoteUsageEvent(user_id=UID, note_id=1, event="pulled", source="mcp_get_note"), + ]) + await s.commit() + + try: + out = await retrieval_summary(UID, days=30) + assert out["read_failed"] is False + by_source = out["usage"]["by_source"] + assert "by_source_failed" not in out["usage"], "the join did not execute" + + ai = by_source["auto_inject"] + assert ai["notes_surfaced"] == 2, "three surfacings of note 1 are one note" + assert ai["notes_pulled"] == 1 + assert ai["pull_through"] == pytest.approx(0.5) + + wp = by_source["write_path_semantic"] + assert wp["notes_surfaced"] == 2 + assert wp["notes_pulled"] == 0 + # 0.0, NOT None. "This surface produced nothing" is a finding; None is + # what a surface with no data reads as, and they must not look alike. + assert wp["pull_through"] == 0.0 + + # And the number that exists today, which is true of neither surface: + # one agent pull over six ranked surfacings. + assert out["usage"]["pull_through"] == pytest.approx(1 / 6, abs=1e-4) + finally: + async with async_session() as s: + await s.execute(delete(NoteUsageEvent).where(NoteUsageEvent.user_id == UID)) + await s.commit() + + +@pytest.mark.integration +@pytest.mark.asyncio +async def test_an_ambient_surface_reports_its_counts_but_no_ratio(_dispose_engine): + """`enter_project` bulk-loads records; nothing CHOSE them. "Surfaced often, + opened never" is not a judgment about a record that was never picked, so the + counts stay visible and the ratio that would be misread is null.""" + from sqlalchemy import delete + + from scribe.models import async_session + from scribe.models.note_usage import NoteUsageEvent + from scribe.services.retrieval_telemetry import retrieval_summary + + UID = 990011 + async with async_session() as s: + s.add_all([ + NoteUsageEvent(user_id=UID, note_id=1, event="surfaced", source="enter_project"), + NoteUsageEvent(user_id=UID, note_id=2, event="surfaced", source="enter_project"), + ]) + await s.commit() + + try: + row = (await retrieval_summary(UID, days=30))["usage"]["by_source"]["enter_project"] + assert row["ambient"] is True + assert row["notes_surfaced"] == 2 + assert row["pull_through"] is None + finally: + async with async_session() as s: + await s.execute(delete(NoteUsageEvent).where(NoteUsageEvent.user_id == UID)) + await s.commit() + + +@pytest.mark.integration +@pytest.mark.asyncio +async def test_the_agent_pull_filter_does_not_treat_its_underscore_as_a_wildcard( + _dispose_engine, +): + """`_` is a LIKE wildcard, so an unescaped `LIKE 'mcp_%'` also matches + `mcpXsomething`. The Python half of this readout uses str.startswith and + cannot have the bug; the SQL half needs autoescape to match it, and nothing + else in the payload would reveal the difference.""" + from sqlalchemy import delete + + from scribe.models import async_session + from scribe.models.note_usage import NoteUsageEvent + from scribe.services.retrieval_telemetry import retrieval_summary + + UID = 990012 + async with async_session() as s: + s.add_all([ + NoteUsageEvent(user_id=UID, note_id=1, event="surfaced", source="auto_inject"), + # Not an agent pull: the door is `mcpXget_note`, not `mcp_get_note`. + NoteUsageEvent(user_id=UID, note_id=1, event="pulled", source="mcpXget_note"), + ]) + await s.commit() + + try: + row = (await retrieval_summary(UID, days=30))["usage"]["by_source"]["auto_inject"] + assert row["notes_pulled"] == 0, "a wildcard match counted a non-agent pull" + assert row["pull_through"] == 0.0 + finally: + async with async_session() as s: + await s.execute(delete(NoteUsageEvent).where(NoteUsageEvent.user_id == UID)) + await s.commit() From ea972ac3f7f3675c52c89a4deef7f3492986b2f6 Mon Sep 17 00:00:00 2001 From: Bryan Van Deusen Date: Tue, 1 Sep 2026 18:28:26 -0400 Subject: [PATCH 07/19] refactor(plugin): one definition of what ships, and the exclusion that makes the version check mean something (#3326) Milestone 334 step 2. The set of files that reach a plugin install lived in two hand-kept copies -- SHIPPED in check_plugin.py and the workflow's paths: filter -- with a comment asking a human to keep them in step. That is the shape #3127 section 3 warns about, and both copies had drifted. The load-bearing change is the exclusion. The version check reads "did shipped content change against the base?", and plugin.json lives INSIDE plugin/ -- so bumping the version is itself a change to the set, which then reads as the change that justifies the bump. Every bump passed, no bump could ever fail, and the check proved nothing while looking green. manifest_differs_beyond_version compares parsed objects with `version` dropped from both sides. One field, never the whole file: plugin.json also carries description, mcpServers and userConfig, all of which reach an install, and excluding the file wholesale would let a userConfig-only edit compute an unchanged version and never refresh -- #2209 again with a narrower trigger. Unreadable input answers "changed", because a spurious bump costs one cache refresh while a missed one is the fix reaching the repo and stopping there. shipped_content_changed returns None, not False, when the diff fails. #2663 is why: a read that failed inside a broad except reported the same zero as an empty window, and every counter read zero for weeks. Two dead trigger paths removed, both found by writing the guard rather than by review. fable-mcp/** outlived its directory by three months (deleted in 91bafb6, 2026-05-27) and assets/** named a path that never existed at all. A paths: entry matching nothing never fires, so neither ever failed anything. Their two orphaned bump scripts go with them -- a third manual-bump mechanism, wired into no settings file. DERIVERS is section 3's (deriver -> artifacts whose identity it decides) table. The membership test is "can changing this file change what the artifact says about itself?", not "is it copied in" -- a deriver is never in the COPY list. A checker is not a deriver, which is why check_plugin.py is absent from it; step 3's mint script adds its own row. The workflow's paths: filter is YAML and cannot import Python, so "one definition" is held by drift tests rather than an import. Said plainly in the test module, because it is the honest shape rather than the ideal one. Co-Authored-By: Claude Opus 5 Claude-Session: https://claude.ai/code/session_01DN4zBVFWhBST9YqjCfQmPb --- .forgejo/workflows/ci.yml | 2 - scripts/bump_fable_mcp_version.sh | 17 -- scripts/check_plugin.py | 141 +++++++++++++++-- scripts/pre_commit_fable_mcp.sh | 39 ----- tests/test_plugin_shipped_set.py | 250 ++++++++++++++++++++++++++++++ 5 files changed, 377 insertions(+), 72 deletions(-) delete mode 100755 scripts/bump_fable_mcp_version.sh delete mode 100755 scripts/pre_commit_fable_mcp.sh create mode 100644 tests/test_plugin_shipped_set.py diff --git a/.forgejo/workflows/ci.yml b/.forgejo/workflows/ci.yml index 267a6e7..3d11996 100644 --- a/.forgejo/workflows/ci.yml +++ b/.forgejo/workflows/ci.yml @@ -46,8 +46,6 @@ on: - "alembic/**" - "alembic.ini" - "Dockerfile" - - "assets/**" - - "fable-mcp/**" # The plugin ships straight from this repo — installs fetch it via # .claude-plugin/marketplace.json, NOT from the image. So a push here is # the release, with no build step in between. Omitting these paths meant diff --git a/scripts/bump_fable_mcp_version.sh b/scripts/bump_fable_mcp_version.sh deleted file mode 100755 index 16b658c..0000000 --- a/scripts/bump_fable_mcp_version.sh +++ /dev/null @@ -1,17 +0,0 @@ -#!/usr/bin/env bash -# Bump the patch segment of fable-mcp/pyproject.toml version and stage the file. -# Usage: called automatically by the Claude Code pre-commit hook, or manually. -set -euo pipefail - -REPO_ROOT="$(cd "$(dirname "${BASH_SOURCE[0]}")/.." && pwd)" -FILE="$REPO_ROOT/fable-mcp/pyproject.toml" - -current=$(grep '^version = ' "$FILE" | sed 's/version = "\(.*\)"/\1/') -major=$(echo "$current" | cut -d. -f1) -minor=$(echo "$current" | cut -d. -f2) -patch=$(echo "$current" | cut -d. -f3) -new_version="$major.$minor.$((patch + 1))" - -sed -i "s/^version = \"$current\"/version = \"$new_version\"/" "$FILE" -git -C "$REPO_ROOT" add "$FILE" -echo "fable-mcp: $current → $new_version" diff --git a/scripts/check_plugin.py b/scripts/check_plugin.py index 159eaa2..dceaf70 100755 --- a/scripts/check_plugin.py +++ b/scripts/check_plugin.py @@ -50,9 +50,45 @@ PLUGIN_DIR = ROOT / "plugin" HOOKS_DIR = PLUGIN_DIR / "hooks" MANIFEST = PLUGIN_DIR / ".claude-plugin" / "plugin.json" -# Paths whose contents reach an install. Keep in step with the workflow's -# `paths:` filter — a path that ships but isn't checked here is the gap again. -SHIPPED = ("plugin", ".claude-plugin") +# ── What ships, and what decides what it says about itself ───────────────── +# +# ONE definition (#3127 §3, milestone 334 step 2). It has TWO consumers that +# need different granularities, and conflating them is the bug: +# +# the workflow's `paths:` trigger whole paths should CI run at all? +# the version check paths MINUS should the version +# the manifest have moved? +# `version` +# +# The second one is why this is not just a tuple of paths. `plugin.json` lives +# INSIDE `plugin/`, so a version bump is itself a change to the shipped set — +# and a check that reads the set naively then treats the bump as its own +# justification. Any bump passes, no bump fails, and it has proved nothing. +# `shipped_content_changed` below is the exclusion-aware reader. +# +# The exclusion is that ONE FIELD, never the whole file: `plugin.json` also +# carries description, mcpServers and userConfig, all of which reach an +# install and all of which matter. Excluding the file wholesale would mean a +# userConfig-only edit computes an unchanged version and never refreshes — +# #2209 again with a narrower trigger. +SHIPPED_PATHS = ("plugin", ".claude-plugin") + +# Files that decide what a published artifact SAYS ABOUT ITSELF — kept as a +# table so the next artifact is a one-line addition rather than a third +# bespoke guard (#3127 §3). The membership test is NOT "is this copied into +# the artifact?" but "can changing this file change the published bytes, or +# what the artifact says about itself?" — FC learned that twice in four days +# (#3156, #3202), and a deriver is never in the COPY list. +# +# Note what is absent: a CHECKER does not belong here. Whatever validates a +# version decides whether the lane goes red, not what any artifact reports, +# so `check_plugin.py` itself is not a deriver — the plugin's mint script +# (milestone 334 step 3) will be, and adds its own row. +DERIVERS: dict[str, tuple[str, ...]] = { + # The "Generate image tags and version" step computes the server image's + # name, ordering key and channel (#3298). + ".forgejo/workflows/ci.yml": ("server-image",), +} failures: list[str] = [] @@ -391,23 +427,95 @@ def _git(*args: str) -> tuple[int, str]: return proc.returncode, (proc.stdout or proc.stderr).strip() -def manifest_version(ref: str | None = None) -> str | None: - """The manifest version at `ref`, or in the working tree when ref is None.""" +def manifest_text(ref: str | None = None) -> str | None: + """The manifest's RAW TEXT at `ref`, or in the working tree when ref is None. + + Split out from `manifest_version` because the exclusion below needs every + field except one, not the one field. + """ if ref is None: try: - return json.loads(MANIFEST.read_text()).get("version") - except Exception: + return MANIFEST.read_text() + except OSError: return None rel = MANIFEST.relative_to(ROOT).as_posix() code, out = _git("show", f"{ref}:{rel}") - if code != 0: + return out if code == 0 else None + + +def manifest_version(ref: str | None = None) -> str | None: + """The manifest version at `ref`, or in the working tree when ref is None.""" + text = manifest_text(ref) + if text is None: return None try: - return json.loads(out).get("version") + return json.loads(text).get("version") except Exception: return None +# Distinct from None, which is a legitimate "this manifest does not exist". +_UNREADABLE = object() + + +def manifest_differs_beyond_version(a: str | None, b: str | None) -> bool: + """Do two `plugin.json` texts differ in anything OTHER than `version`? + + THE exclusion, and it is kept pure — no git, no filesystem — because this + is the half worth testing hard and it needs no repository to exercise. + + Compares PARSED objects rather than text, so reformatting, key reordering + and whitespace do not read as content changes. `version` is dropped from + both sides; everything else counts, which is what keeps a userConfig-only + or mcpServers-only edit demanding a new version. + + Unreadable input answers True. The conservative direction is "demand a new + version": a spurious bump costs one cache refresh, while a missed one is + #2209 — the fix reaches the repo and stops there. + """ + def without_version(text: str | None): + if text is None: + return None + try: + data = json.loads(text) + except Exception: + return _UNREADABLE + if not isinstance(data, dict): + return _UNREADABLE + return {k: v for k, v in data.items() if k != "version"} + + left, right = without_version(a), without_version(b) + if left is _UNREADABLE or right is _UNREADABLE: + return True + return left != right + + +def shipped_content_changed(base: str) -> tuple[bool | None, list[str]]: + """Has anything that REACHES AN INSTALL changed against `base`? + + Returns `(changed, paths)`. `changed` is **None** when the question could + not be answered — a caller must never read that as "no", which is the + distinction #2663 cost weeks of zeroed telemetry to learn. + + The manifest is special-cased, not excluded: if it is the ONLY thing that + moved and the only difference is `version`, nothing that reaches an + install has changed. Any other manifest field, or any other file, counts. + """ + code, out = _git("diff", "--name-only", base, "--", *SHIPPED_PATHS) + if code != 0: + return None, [] + paths = [p for p in out.splitlines() if p.strip()] + if not paths: + return False, [] + + rel_manifest = MANIFEST.relative_to(ROOT).as_posix() + if paths == [rel_manifest]: + return manifest_differs_beyond_version( + manifest_text(), manifest_text(base) + ), paths + return True, paths + + def check_version_bump(base: str = "origin/main") -> None: """If shipped plugin content differs from `base`, the version must too. @@ -416,6 +524,11 @@ def check_version_bump(base: str = "origin/main") -> None: actually matters is that whatever reaches an install carries a version the installer can tell apart from the one already cached. One bump per batch, which is also how a human would do it. + + Reads the set through `shipped_content_changed`, so a commit whose ONLY + change is the version field does not count as content moving. Without that + the check is circular — the bump edits a file inside `plugin/`, which then + reads as the change that justifies the bump. """ code, _ = _git("rev-parse", "--verify", base) if code != 0: @@ -429,11 +542,11 @@ def check_version_bump(base: str = "origin/main") -> None: ) return - code, changed = _git("diff", "--name-only", base, "--", *SHIPPED) - if code != 0: - fail(f"git diff against {base} failed: {changed}") + changed, paths = shipped_content_changed(base) + if changed is None: + fail(f"git diff against {base} failed, so the version check could not run") return - if not changed.strip(): + if not changed: ok(f"no shipped plugin changes against {base} — version bump not required") return @@ -445,7 +558,7 @@ def check_version_bump(base: str = "origin/main") -> None: ok(f"no manifest on {base} — treating as a new plugin (version {here})") return if here == there: - files = "\n ".join(changed.splitlines()) + files = "\n ".join(paths) fail( f"plugin content changed but the manifest version is still {here}.\n" f" The installer compares versions to decide whether to refresh " diff --git a/scripts/pre_commit_fable_mcp.sh b/scripts/pre_commit_fable_mcp.sh deleted file mode 100755 index 8dbd54c..0000000 --- a/scripts/pre_commit_fable_mcp.sh +++ /dev/null @@ -1,39 +0,0 @@ -#!/usr/bin/env bash -# Claude Code PreToolUse hook for Bash. -# Reads the tool input JSON from stdin; if the command is a git commit -# and fable-mcp files (other than pyproject.toml) are staged, bumps -# the fable-mcp patch version before the commit proceeds. -# -# Exits 0 always so it never blocks the commit. - -set -euo pipefail - -REPO_ROOT="$(cd "$(dirname "${BASH_SOURCE[0]}")/.." && pwd)" - -input=$(cat) -command=$(echo "$input" | python3 -c " -import sys, json -data = json.load(sys.stdin) -# Claude Code sends {tool_input: {command: ...}} -ti = data.get('tool_input', data) -print(ti.get('command', '')) -" 2>/dev/null || echo "") - -# Only act on git commit commands -if ! echo "$command" | grep -qE "git commit"; then - exit 0 -fi - -cd "$REPO_ROOT" - -# Check if fable-mcp files other than pyproject.toml are staged -fable_staged=$(git diff --cached --name-only 2>/dev/null \ - | grep "^fable-mcp/" \ - | grep -v "^fable-mcp/pyproject.toml$" \ - || true) - -if [ -n "$fable_staged" ]; then - bash "$REPO_ROOT/scripts/bump_fable_mcp_version.sh" -fi - -exit 0 diff --git a/tests/test_plugin_shipped_set.py b/tests/test_plugin_shipped_set.py new file mode 100644 index 0000000..0a8f46e --- /dev/null +++ b/tests/test_plugin_shipped_set.py @@ -0,0 +1,250 @@ +"""One definition of what SHIPS in the plugin, and the drift guards on it. + +WHAT THIS IS ABOUT (#3127 §3, milestone 334 step 2). Scribe publishes two +artifacts. `plugin/` is not in the Docker image — installs fetch it from this +repo through `.claude-plugin/marketplace.json`, so **a push IS the release**, +with no build step in between. That makes "which files reach an install?" a +question with real consequences, and it has been answered wrong twice: + + - #2198 — `plugin/**` was in no `paths:` filter, so four broken hooks + reached live installs having triggered no CI at all. + - #2209 — the fix for that shipped and still could not reach an install, + because the manifest version had not moved. + +The set lives in `scripts/check_plugin.py`. Its second consumer is the +workflow's `paths:` trigger, which is YAML and cannot import Python — so the +"one definition" is held together by the drift tests here rather than by an +import. That is the honest shape, and it is why these tests exist at all. + +The exclusion tests are the load-bearing half. Without the manifest-`version` +exclusion the version check is CIRCULAR: bumping the version edits a file +inside `plugin/`, which then reads as the content change that justifies the +bump. Every bump passes, no bump ever fails, and the check has proved nothing +while looking green. +""" +import json +import pathlib +import re + +import pytest + +from scripts.check_plugin import ( + DERIVERS, + SHIPPED_PATHS, + manifest_differs_beyond_version, +) + +ROOT = pathlib.Path(__file__).resolve().parents[1] +CI = ROOT / ".forgejo/workflows/ci.yml" + + +def trigger_paths() -> list[str]: + """The `paths:` list under the workflow's push trigger. + + Parsed with a regex rather than a YAML library, matching what + test_version_endpoint.py already does with this file — the alternative is + adding PyYAML as a dependency for one assertion. Raises rather than + returning empty: a silent no-op here would defeat the point of the file. + """ + text = CI.read_text() + block = re.search(r"^ paths:\n((?:(?: [-#].*)?\n)+)", text, re.M) + if block is None: + raise AssertionError("could not find the push trigger's `paths:` block") + found = re.findall(r'^ - "([^"]+)"', block.group(1), re.M) + if not found: + raise AssertionError("the `paths:` block parsed to zero entries") + return found + + +# ── The set itself ───────────────────────────────────────────────────────── + + +def test_every_shipped_path_exists(): + """A set naming something that isn't there is not a definition of anything.""" + for path in SHIPPED_PATHS: + assert (ROOT / path).exists(), f"SHIPPED_PATHS names {path}, which does not exist" + + +def test_every_shipped_path_triggers_ci(): + """#2198's exact hole, stated as an assertion. + + Directional on purpose: the trigger is a superset (it also fires on + `src/**`, `tests/**` and friends). What must never happen is a path that + reaches an install and fires no lane. + """ + triggers = trigger_paths() + for path in SHIPPED_PATHS: + covered = any(t == path or t.startswith(f"{path}/") for t in triggers) + assert covered, ( + f"{path} ships to installs but no `paths:` entry covers it — " + f"changes there would reach a live install having run no CI (#2198)" + ) + + +def test_the_checker_itself_triggers_ci(): + """Changing the checks must re-run them. + + Not a member of the shipped set — a checker decides whether the lane goes + red, not what any artifact reports — but a change to it that runs no lane + is the same silence by a different route. + """ + assert "scripts/check_plugin.py" in trigger_paths() + + +def test_no_trigger_path_names_something_that_does_not_exist(): + """The guard that catches scaffolding outliving its subsystem. + + `fable-mcp/**` sat in this list for three months after the directory was + deleted (commit 91bafb6, 2026-05-27), and `assets/**` named a path that + never existed at all. Neither ever failed anything — a `paths:` entry + matching nothing simply never fires — which is precisely why a list kept + by hand drifts and nobody finds out. + """ + missing = [ + entry for entry in trigger_paths() + if not (ROOT / re.sub(r"/\*\*$", "", entry)).exists() + ] + assert not missing, ( + f"`paths:` names {missing}, which do not exist in the repo. A trigger " + f"that matches nothing is silent, so it survives every review." + ) + + +def test_every_deriver_exists(): + """§3's table, kept honest. + + The point of the table is that the next artifact is a one-line addition + (milestone 334 step 3 adds the plugin's mint script). A row pointing at a + file that has moved would make the table read as complete when it is not. + """ + for path, artifacts in DERIVERS.items(): + assert (ROOT / path).exists(), f"DERIVERS names {path}, which does not exist" + assert artifacts, f"DERIVERS[{path}] names no artifact" + + +# ── The exclusion — the half that makes the version check mean anything ──── + + +def manifest(**fields) -> str: + base = { + "name": "scribe", + "description": "d", + "version": "0.1.48", + "mcpServers": {"scribe": {"type": "http", "url": "${user_config.api_endpoint}/mcp"}}, + "userConfig": {"api_endpoint": {"type": "string"}}, + } + base.update(fields) + return json.dumps(base) + + +def test_a_version_only_change_is_NOT_a_content_change(): + """THE assertion. Without it the version check is self-satisfying: the + bump edits `plugin.json`, which lives inside `plugin/`, so the bump is its + own justification and every bump passes.""" + assert manifest_differs_beyond_version( + manifest(version="2026.09.01.0512"), manifest(version="0.1.48") + ) is False + + +def test_an_identical_manifest_is_not_a_change(): + assert manifest_differs_beyond_version(manifest(), manifest()) is False + + +@pytest.mark.parametrize("field,value", [ + ("userConfig", {"api_endpoint": {"type": "string", "title": "changed"}}), + ("mcpServers", {"scribe": {"type": "http", "url": "elsewhere"}}), + ("description", "a different description"), + ("name", "renamed"), +]) +def test_every_OTHER_manifest_field_still_demands_a_new_version(field, value): + """Why the exclusion is one FIELD and never the whole file. + + `plugin.json` carries description, mcpServers and userConfig alongside the + version, and all of them reach an install. Excluding the file wholesale + would mean a userConfig-only edit computes an unchanged version and never + refreshes — #2209 again, with a narrower trigger and the same silence. + """ + assert manifest_differs_beyond_version(manifest(**{field: value}), manifest()) is True + + +def test_reformatting_is_not_a_content_change(): + """Parsed objects, not text. Whitespace and key order are not content, and + a check that treated them as such would demand a version for a re-indent.""" + data = json.loads(manifest()) + reordered = {k: data[k] for k in reversed(list(data))} + assert manifest_differs_beyond_version( + json.dumps(reordered, indent=4), json.dumps(data, separators=(",", ":")) + ) is False + + +@pytest.mark.parametrize("bad", ["", "{not json", "[]", '"a string"', "null"]) +def test_unreadable_input_demands_a_new_version(bad): + """The conservative direction, chosen deliberately. + + A spurious bump costs one cache refresh. A missed one is #2209 — the fix + reaches the repo and stops there, and the only detector is a human saying + "I don't think it updated." + """ + assert manifest_differs_beyond_version(bad, manifest()) is True + assert manifest_differs_beyond_version(manifest(), bad) is True + + +def test_a_manifest_appearing_or_vanishing_is_a_change(): + """None means the file is absent at that ref — a real difference, and not + the same thing as unreadable.""" + assert manifest_differs_beyond_version(None, manifest()) is True + assert manifest_differs_beyond_version(manifest(), None) is True + + +# ── The reader that joins the exclusion to git ───────────────────────────── + + +def test_shipped_content_changed_reports_a_version_only_commit_as_unchanged(monkeypatch): + """End to end through the git seam, with git stubbed. + + The unit above proves the comparison; this proves it is actually WIRED to + the path that `check_version_bump` reads. A correct helper nobody calls + would leave the circular check exactly as it was. + """ + from scripts import check_plugin + + monkeypatch.setattr( + check_plugin, "_git", + lambda *a: (0, "plugin/.claude-plugin/plugin.json"), + ) + monkeypatch.setattr( + check_plugin, "manifest_text", + lambda ref=None: manifest(version="2026.09.01.0512" if ref is None else "0.1.48"), + ) + changed, paths = check_plugin.shipped_content_changed("origin/main") + assert changed is False + assert paths == ["plugin/.claude-plugin/plugin.json"] + + +def test_shipped_content_changed_reports_a_hook_edit_as_changed(monkeypatch): + """The guard against an exclusion that swallowed everything — a check that + can never fire is indistinguishable from one that is broken.""" + from scripts import check_plugin + + monkeypatch.setattr( + check_plugin, "_git", + lambda *a: (0, "plugin/hooks/scribe_session_context.sh"), + ) + changed, paths = check_plugin.shipped_content_changed("origin/main") + assert changed is True + assert paths == ["plugin/hooks/scribe_session_context.sh"] + + +def test_a_failed_diff_is_None_and_never_False(monkeypatch): + """Could-not-tell and nothing-changed must not collapse into one value. + + #2663 is the precedent: a read that failed inside a broad except reported + the same zero as a genuinely empty window, and every counter read zero for + weeks with nothing to distinguish the two. + """ + from scripts import check_plugin + + monkeypatch.setattr(check_plugin, "_git", lambda *a: (128, "fatal: bad revision")) + changed, paths = check_plugin.shipped_content_changed("origin/main") + assert changed is None + assert paths == [] From f1896bfe9d47e754d28ce0fee6e89567a01d155f Mon Sep 17 00:00:00 2001 From: Bryan Van Deusen Date: Tue, 1 Sep 2026 18:54:55 -0400 Subject: [PATCH 08/19] feat(plugin): mint the version, and make CI the control that it moved (#3327) Milestone 334 step 3. 0.1.48 was the last of 48 numbers a person typed by hand; forgetting to type the 49th is #2209, #1040 and #2220, three separate times a shipped fix reached the repo and stopped there. WHY A SCRIPT AND NOT A BUILD STEP. plugin/ is not in the image -- installs fetch it from this repo via marketplace.json, so the push IS the release and there is no moment at which CI could stamp a version in. Every other artifact in the family derives during a build (#3127 section 2). This one has no build to derive during, so the value is minted before the commit and CI's job is to prove it moved when it had to. MINT TIME, a fourth clock section 2 does not name. It prescribes commit time so two lanes building one source report one string; the plugin has one lane and no build, so that reason does not reach it. What is given up is reproducibility-from-history -- you cannot recompute the value, only verify it moved. That is acceptable ONLY because #3325 read the installer's code and found the refresh test is `P.version === H`, plain equality, with zero ordering comparisons anywhere. Where a comparator orders, an unreproducible version would be unverifiable too. Two artifacts in one repo now derive from different clocks on purpose, one directory apart. "Let's make these consistent" is the obvious tidy-up and breaks whichever loses, so the divergence is pinned in tests rather than only explained in a comment -- including an AST assertion that the mint script never imports subprocess, since a mint that can read history is a commit-time deriver wearing the wrong name. check_version_bump becomes check_version_is_minted. It gains the shape gate and a future-value gate, and it keeps deliberately NOT failing when the version moved without content changing: a needless re-mint costs one cache refresh, and failing the lane over a harmless act is how a check earns a --no-version in somebody's muscle memory and stops running at all. The implication that matters is one-directional. The mint script joins the version-relevant set, which is step 2's DERIVERS table finally being read by something. Section 3's asymmetry is why it is not optional: change the format string, change nothing else, and a diff over the shipped paths alone says "no content change" while the manifest keeps a value in the old format forever. Its own introduction demonstrates this -- adding the deriver is itself the version-relevant change that forced this mint. fetch-depth: 0 was NOT added, against this step's own brief. The plugin job carries a comment refusing it, backed by an observed act_runner failure (any `with:` block made checkout fail to extract, run 3027), and the reasoning holds: the check diffs two trees and the workflow already fetches main at depth 1. Checklist 6 is about jobs that derive; this one checks. Verified live before pushing: the session-context marker reports v2026.09.01.2252 keylessly, and both failure arms were probed by hand rather than assumed. The shape gate fires first on a reverted 0.1.48, so the stale arm is covered by unit test rather than by that probe. Co-Authored-By: Claude Opus 5 Claude-Session: https://claude.ai/code/session_01DN4zBVFWhBST9YqjCfQmPb --- Makefile | 11 +- plugin/.claude-plugin/plugin.json | 2 +- scripts/check_plugin.py | 159 +++++++++++++---- scripts/mint_plugin_version.py | 134 ++++++++++++++ tests/test_plugin_version_mint.py | 279 ++++++++++++++++++++++++++++++ 5 files changed, 550 insertions(+), 35 deletions(-) create mode 100644 scripts/mint_plugin_version.py create mode 100644 tests/test_plugin_version_mint.py diff --git a/Makefile b/Makefile index f9d672c..231f991 100644 --- a/Makefile +++ b/Makefile @@ -1,4 +1,4 @@ -.PHONY: build up down logs health migrate lint typecheck test fmt +.PHONY: build up down logs health migrate lint typecheck test fmt mint-plugin # --- Docker --- @@ -36,3 +36,12 @@ test: # Run all checks in one shot (mirrors what CI does) check: lint typecheck test + +# --- Plugin --- + +# Run this after changing anything under plugin/ or .claude-plugin/, BEFORE +# committing. The plugin ships straight from git with no build step, so its +# version is minted here rather than stamped by CI; the lane fails if you +# forget, but this is what makes remembering cheap. +mint-plugin: + python3 scripts/mint_plugin_version.py diff --git a/plugin/.claude-plugin/plugin.json b/plugin/.claude-plugin/plugin.json index eafde1b..4e078a1 100644 --- a/plugin/.claude-plugin/plugin.json +++ b/plugin/.claude-plugin/plugin.json @@ -1,7 +1,7 @@ { "name": "scribe", "description": "Scribe system-of-record for Claude Code: MCP tools over your notes/tasks/projects/rules, a session-start push channel that surfaces your always-on rules + active-project context, process-skills (writing-plans, systematic-debugging, verification, brainstorming, reusing-code), and your saved Scribe Processes auto-surfaced as skills (/scribe:sync). Replaces superpowers + file-memory with one app-backed plugin.", - "version": "0.1.48", + "version": "2026.09.01.2252", "author": { "name": "Bryan Van Deusen" }, diff --git a/scripts/check_plugin.py b/scripts/check_plugin.py index dceaf70..150e72c 100755 --- a/scripts/check_plugin.py +++ b/scripts/check_plugin.py @@ -32,7 +32,7 @@ whole file exists to prevent. Usage: python3 scripts/check_plugin.py # all checks - python3 scripts/check_plugin.py --no-version # skip the bump check + python3 scripts/check_plugin.py --no-version # skip the version check """ from __future__ import annotations @@ -43,9 +43,19 @@ import re import shutil import subprocess import sys +from datetime import datetime, timedelta, timezone from pathlib import Path ROOT = Path(__file__).resolve().parents[1] + +# The shape contract is ONE definition, shared with the script that mints it — +# a checker carrying its own copy of the format would drift from the minter +# and pass values the minter can no longer produce. Explicit path insert +# because this file runs both as `python3 scripts/check_plugin.py` (which puts +# `scripts/` on the path, not the root) and as an import from the test suite. +sys.path.insert(0, str(ROOT)) +from scripts.mint_plugin_version import VERSION_RE # noqa: E402 + PLUGIN_DIR = ROOT / "plugin" HOOKS_DIR = PLUGIN_DIR / "hooks" MANIFEST = PLUGIN_DIR / ".claude-plugin" / "plugin.json" @@ -82,14 +92,42 @@ SHIPPED_PATHS = ("plugin", ".claude-plugin") # # Note what is absent: a CHECKER does not belong here. Whatever validates a # version decides whether the lane goes red, not what any artifact reports, -# so `check_plugin.py` itself is not a deriver — the plugin's mint script -# (milestone 334 step 3) will be, and adds its own row. +# so `check_plugin.py` itself is not a deriver, while the script that mints +# the plugin version is. DERIVERS: dict[str, tuple[str, ...]] = { # The "Generate image tags and version" step computes the server image's # name, ordering key and channel (#3298). ".forgejo/workflows/ci.yml": ("server-image",), + # Decides the plugin's version FORMAT, so it decides what every future + # manifest says about itself (milestone 334 step 3). + "scripts/mint_plugin_version.py": ("plugin",), } + +def version_relevant_paths() -> tuple[str, ...]: + """Everything a change to which must produce a NEW plugin version. + + Wider than `SHIPPED_PATHS`, and #3127 §3's asymmetry is why it has to be: + + A change to how the VERSION is computed is compared against nothing at + all. Left out, the published artifact goes on reporting the OLD value + indefinitely. + + Concretely — change the mint script's format string, change nothing else, + and a diff over the shipped paths alone reports "no content change, the + version need not move". The manifest then keeps a value in the old format + forever and nothing ever says so. The mint script reaches no install and + belongs here anyway; that is #3156's exact shape. + + A CHECKER is deliberately not here. Whatever validates the version decides + whether the lane goes red, not what any artifact reports — so this file is + absent from its own set, and that is not an oversight. + """ + return SHIPPED_PATHS + tuple( + path for path, artifacts in DERIVERS.items() if "plugin" in artifacts + ) + + failures: list[str] = [] @@ -500,8 +538,11 @@ def shipped_content_changed(base: str) -> tuple[bool | None, list[str]]: The manifest is special-cased, not excluded: if it is the ONLY thing that moved and the only difference is `version`, nothing that reaches an install has changed. Any other manifest field, or any other file, counts. + + Reads `version_relevant_paths`, which is the shipped set PLUS the files + that decide the version — see there for why the deriver has to be in it. """ - code, out = _git("diff", "--name-only", base, "--", *SHIPPED_PATHS) + code, out = _git("diff", "--name-only", base, "--", *version_relevant_paths()) if code != 0: return None, [] paths = [p for p in out.splitlines() if p.strip()] @@ -516,19 +557,39 @@ def shipped_content_changed(base: str) -> tuple[bool | None, list[str]]: return True, paths -def check_version_bump(base: str = "origin/main") -> None: - """If shipped plugin content differs from `base`, the version must too. +def check_version_is_minted(base: str = "origin/main") -> None: + """THE control (#3127 checklist 4), replacing "somebody remembers". - Stated against the BASE BRANCH rather than the last commit on purpose. A - per-commit rule would demand a bump from every commit in a batch; what - actually matters is that whatever reaches an install carries a version the - installer can tell apart from the one already cached. One bump per batch, - which is also how a human would do it. + The checklist asks, of any hand-set component: *say what happens the + release somebody forgets it.* This is the answer — the lane goes red, + deterministically, because CI can compute whether the value should have + moved. Its predecessor could only ask "did the number move at all", which + any bump satisfied and which therefore proved nothing. - Reads the set through `shipped_content_changed`, so a commit whose ONLY - change is the version field does not count as content moving. Without that - the check is circular — the bump edits a file inside `plugin/`, which then - reads as the change that justifies the bump. + Four verdicts: + + content changed, version did not FAIL — this is #2209, exactly + version not in canonical shape FAIL — see below + version implausibly in the future FAIL — a bad clock or a hand-edit + version moved, content did not pass, and say so + + THE LAST ROW IS NOT A FAILURE, DELIBERATELY. A needless re-mint costs one + cache refresh and nothing else. Failing the lane over a harmless act is how + a check earns a `--no-version` in somebody's muscle memory and stops + running at all — which is the failure mode this whole file exists to + prevent. The implication that matters is one-directional: content changed + IMPLIES version moved. + + A malformed version is worth failing on even though the installer would + accept it. `K4` returns the manifest string verbatim, and `H == "unknown"` + sets `forceOverwrite`, so a broken value either sorts as a normal string + or reinstalls the plugin every single session (#3325). Neither is loud. + + Stated against the BASE BRANCH rather than the last commit, as its + predecessor was: a per-commit rule would demand a fresh mint from every + commit in a batch, when what matters is that whatever reaches an install + differs from what is cached. One mint per batch, which is also how a person + would do it. """ code, _ = _git("rev-parse", "--verify", base) if code != 0: @@ -542,42 +603,74 @@ def check_version_bump(base: str = "origin/main") -> None: ) return + here = manifest_version() + if here is None: + fail(f"could not read a version from {MANIFEST.relative_to(ROOT)}") + return + if not VERSION_RE.match(here): + fail( + f"the manifest version is {here!r}, which is not YYYY.MM.DD.HHMM.\n" + f" One shape for every version in the family (#3127 checklist " + f"10), zero-padded so the midnight case renders 2026.01.05.0000.\n" + f" Run `make mint-plugin`." + ) + return + + minted = datetime.strptime(here, "%Y.%m.%d.%H%M").replace(tzinfo=timezone.utc) + # A day of slack: the mint happens on a workstation and the lane runs + # later, so a *small* skew is ordinary. A value further out than that is + # a wrong clock or a typed year, and it makes the version lie about when + # it was minted. + if minted > datetime.now(timezone.utc) + timedelta(days=1): + fail( + f"the manifest version {here} is in the future. Either the clock " + f"that minted it is wrong, or it was typed by hand." + ) + return + changed, paths = shipped_content_changed(base) if changed is None: fail(f"git diff against {base} failed, so the version check could not run") return - if not changed: - ok(f"no shipped plugin changes against {base} — version bump not required") - return - here, there = manifest_version(), manifest_version(base) - if here is None: - fail(f"could not read a version from {MANIFEST.relative_to(ROOT)}") - return + there = manifest_version(base) if there is None: ok(f"no manifest on {base} — treating as a new plugin (version {here})") return - if here == there: + + if changed and here == there: files = "\n ".join(paths) fail( - f"plugin content changed but the manifest version is still {here}.\n" - f" The installer compares versions to decide whether to refresh " - f"its cache, so an unchanged version means these edits reach the repo " - f"and stop there — the marketplace clone updates, the cache that " - f"actually executes does not (issue #2209).\n" - f" Bump `version` in {MANIFEST.relative_to(ROOT)}.\n" + f"plugin content changed but the version is still {here}.\n" + f" The installer decides whether to refresh its cache by " + f"comparing this string, so an unchanged version means these edits " + f"reach the repo and stop there — the marketplace clone updates, the " + f"cache that actually executes does not (#2209, #1040, #2220).\n" + f" Run `make mint-plugin`.\n" f" Changed:\n {files}" ) + elif changed: + ok(f"plugin content changed and the version was minted {there} -> {here}") + elif here != there: + # Not a failure — see the docstring. Named rather than silent, because + # the uninteresting cause (minted twice) and the interesting one (the + # version-relevant set is too narrow to see what actually changed) + # produce the same line, and only a person can tell them apart. + ok( + f"the version moved {there} -> {here} with no version-relevant " + f"change — harmless, unless something DID change that the set " + f"cannot see" + ) else: - ok(f"plugin content changed and version moved {there} -> {here}") + ok(f"nothing version-relevant changed against {base} — no mint required") def main() -> int: parser = argparse.ArgumentParser(description=__doc__) parser.add_argument("--no-version", action="store_true", - help="skip the manifest version-bump check") + help="skip the minted-version check") parser.add_argument("--base", default="origin/main", - help="branch the version bump is measured against") + help="branch the version is measured against") args = parser.parse_args() if not HOOKS_DIR.is_dir(): @@ -591,7 +684,7 @@ def main() -> int: check_local_prior_art_needs_no_instance() check_session_context_reports_its_version() if not args.no_version: - check_version_bump(args.base) + check_version_is_minted(args.base) print() if failures: diff --git a/scripts/mint_plugin_version.py b/scripts/mint_plugin_version.py new file mode 100644 index 0000000..2d45d77 --- /dev/null +++ b/scripts/mint_plugin_version.py @@ -0,0 +1,134 @@ +#!/usr/bin/env python3 +"""Mint the plugin's version — `YYYY.MM.DD.HHMM`, UTC, zero-padded. + +Run this whenever you change something under `plugin/` or `.claude-plugin/`, +before you commit: + + make mint-plugin # or: python3 scripts/mint_plugin_version.py + +WHY A SCRIPT AND NOT A BUILD STEP. `plugin/` is not in the Docker image. +Installs fetch it straight from this git repo via `.claude-plugin/ +marketplace.json`, so **a push IS the release** — there is no build between +you committing and a user fetching, and therefore no moment at which CI could +stamp a version in. Every other artifact in the family derives its version +during a build (note #3127 §2). This one has no build to derive during. + +WHICH CLOCK, AND WHY IT DIFFERS FROM THE SERVER IMAGE — the divergence is +deliberate, and it lives one directory away from its opposite, so it is +exactly what a later "let's make these consistent" change would collapse: + + server image name from COMMIT time, ordering key from BUILD time + (two lanes building one source must report one string; + a rebuild of an older commit must not go backwards) + plugin one value, from MINT time + +§2's reason for commit time is that two lanes build one source. The plugin has +one lane and no build, so that reason does not reach it and paying its cost +buys nothing. What is given up is reproducibility-from-history: you cannot +recompute this value later, only verify that it moved when it had to. + +That trade is acceptable ONLY because of what #3325 established by reading the +installer's code: the refresh test is `P.version === H`, plain string +equality, with no ordering comparison anywhere. Where a comparator ORDERS, an +unreproducible version is dangerous — nothing can check it is right. Where it +only tests equality, "did it change when it should have" is the entire +specification, and `check_plugin.py` checks that completely. + +The manifest is rewritten with a surgical replacement of the `version` line +rather than `json.dump`, because its formatting and key order are not this +script's to decide and a whole-file reformat would make every mint an +unreadable diff. +""" +from __future__ import annotations + +import argparse +import json +import re +import sys +from datetime import datetime, timezone +from pathlib import Path + +ROOT = Path(__file__).resolve().parents[1] +MANIFEST = ROOT / "plugin" / ".claude-plugin" / "plugin.json" + +# Four dot-separated numeric fields, zero-padded, and nothing else — one shape +# for every human-readable version in the family (#3127 checklist 10). The +# padding is load-bearing for the midnight case the checklist names by hand: +# 2026.01.05.0000, which an unpadded `%-H%M` would render as `0` and silently +# shorten. Harmless while nothing orders these, wrong the moment anything does. +VERSION_RE = re.compile(r"^\d{4}\.\d{2}\.\d{2}\.\d{4}$") +VERSION_FORMAT = "%Y.%m.%d.%H%M" + +# The `version` line, captured so its surroundings survive byte-for-byte. +VERSION_LINE_RE = re.compile(r'^(\s*"version"\s*:\s*")([^"]*)(".*)$', re.M) + + +def mint(now: datetime | None = None) -> str: + """The version for this moment. UTC, always — a local-time mint would make + the value depend on who ran it.""" + return (now or datetime.now(timezone.utc)).strftime(VERSION_FORMAT) + + +def rewrite(text: str, version: str) -> str: + """`text` with its `version` value replaced, and everything else untouched. + + Raises rather than falling back to a JSON round-trip: a manifest this + cannot match is one whose shape changed, and quietly reformatting the file + to cope would be a much larger edit than the caller asked for. + """ + # Counted BEFORE substituting, not via subn's return: a capped `subn` + # reports the replacements it made, so a manifest with two `version` lines + # would look like a clean single match while the second one — the real one, + # perhaps — kept its old value. + matches = VERSION_LINE_RE.findall(text) + if len(matches) != 1: + raise ValueError( + f"expected exactly one `version` line in the manifest, found {len(matches)}" + ) + return VERSION_LINE_RE.sub( + lambda m: f"{m.group(1)}{version}{m.group(3)}", text, count=1 + ) + + +def main() -> int: + parser = argparse.ArgumentParser(description="Mint the plugin's version.") + parser.add_argument( + "--check", action="store_true", + help="print the version that WOULD be minted and change nothing", + ) + args = parser.parse_args() + + version = mint() + if args.check: + print(version) + return 0 + + try: + text = MANIFEST.read_text() + except OSError as exc: + print(f"cannot read {MANIFEST.relative_to(ROOT)}: {exc}", file=sys.stderr) + return 1 + + try: + previous = json.loads(text).get("version") + except Exception: + previous = None + + if previous == version: + # Same minute. Not an error — the value is already correct for now, and + # failing here would turn "I ran it twice" into a problem to solve. + print(f"plugin version already {version} (same minute) — unchanged") + return 0 + + try: + MANIFEST.write_text(rewrite(text, version)) + except ValueError as exc: + print(f"{MANIFEST.relative_to(ROOT)}: {exc}", file=sys.stderr) + return 1 + + print(f"plugin version {previous} -> {version}") + return 0 + + +if __name__ == "__main__": + raise SystemExit(main()) diff --git a/tests/test_plugin_version_mint.py b/tests/test_plugin_version_mint.py new file mode 100644 index 0000000..8943e5f --- /dev/null +++ b/tests/test_plugin_version_mint.py @@ -0,0 +1,279 @@ +"""The plugin's version is MINTED, and CI is the control that it moved. + +WHAT THIS IS ABOUT (milestone 334 step 3). `plugin/` ships straight from this +git repo — no build step, so no moment at which CI could stamp a version in. +The value is therefore minted by a script before the commit, and CI's job is +not to produce it but to prove it moved when it had to. + +THE DIVERGENCE THESE GUARD. Two artifacts in one repo derive their versions +from different clocks, on purpose: + + server image name from COMMIT time, ordering key from BUILD time + plugin one value, from MINT time + +#3127 §2 prescribes commit time so two lanes building one source report one +string. The plugin has one lane and no build, so that reason does not reach +it. "Let's make these consistent" is the obvious tidy-up and it breaks +whichever artifact loses — which is why the difference is pinned here rather +than only explained in a comment. + +The trade mint time makes — you cannot recompute the value from history, only +verify it moved — is acceptable ONLY because #3325 established that the +installer's refresh test is `===` with no ordering anywhere. Where a +comparator orders, an unreproducible version would be unverifiable too. +""" +import ast +import json +import pathlib +import re +from datetime import datetime, timedelta, timezone + +import pytest + +from scripts import check_plugin +from scripts.mint_plugin_version import VERSION_RE, mint, rewrite + +MINT_SRC = pathlib.Path(check_plugin.ROOT) / "scripts" / "mint_plugin_version.py" + + +@pytest.fixture(autouse=True) +def _reset_failures(): + """`check_plugin.fail` appends to a module global; without this a failing + assertion in one test would be visible from the next.""" + check_plugin.failures.clear() + yield + check_plugin.failures.clear() + + +def fake_manifest(version: str = "2026.09.01.2252") -> str: + return json.dumps( + {"name": "scribe", "description": "d", "version": version, + "userConfig": {"api_endpoint": {"type": "string"}}}, + indent=2, + ) + + +# ── The mint ─────────────────────────────────────────────────────────────── + + +@pytest.mark.parametrize("when,expected", [ + # THE midnight case, which #3127 checklist 10 names by hand. An unpadded + # `%-H%M` renders this hour as `0` and silently shortens the string. + (datetime(2026, 1, 5, 0, 0, tzinfo=timezone.utc), "2026.01.05.0000"), + (datetime(2026, 1, 5, 0, 9, tzinfo=timezone.utc), "2026.01.05.0009"), + (datetime(2026, 12, 31, 23, 59, tzinfo=timezone.utc), "2026.12.31.2359"), + (datetime(2026, 9, 1, 22, 52, tzinfo=timezone.utc), "2026.09.01.2252"), +]) +def test_the_mint_zero_pads_every_field(when, expected): + assert mint(when) == expected + assert VERSION_RE.match(mint(when)) + + +def test_the_mint_is_UTC_not_local(): + """A local-time mint would make the value depend on who ran it — two people + minting the same minute would disagree, and the string is the artifact's + identity.""" + utc = datetime(2026, 9, 1, 22, 52, tzinfo=timezone.utc) + east = utc.astimezone(timezone(timedelta(hours=9))) + assert mint(east) == mint(utc) == "2026.09.01.2252" + + +def test_the_mint_reads_a_CLOCK_and_never_git(): + """The clock divergence from the server image, asserted structurally. + + Mint time is only meaningful if nothing consults history — the moment this + script shells out to git it has quietly become a commit-time deriver, and + the two artifacts' clocks have been "made consistent" without anyone + deciding to. That change would pass every other test in this file. + + Asserted over the AST rather than the text, because the module docstring + discusses git at length explaining why it is absent. This looks for USE, + not mention. + """ + tree = ast.parse(MINT_SRC.read_text()) + + imported = set() + for node in ast.walk(tree): + if isinstance(node, ast.Import): + imported |= {a.name.split(".")[0] for a in node.names} + elif isinstance(node, ast.ImportFrom) and node.module: + imported.add(node.module.split(".")[0]) + assert "subprocess" not in imported, ( + "the mint script imports subprocess — a mint that can read history is " + "a commit-time deriver wearing the wrong name" + ) + + called = {ast.unparse(n.func) for n in ast.walk(tree) if isinstance(n, ast.Call)} + assert "datetime.now" in called, "the mint script no longer reads a clock" + + +# ── The rewrite ──────────────────────────────────────────────────────────── + + +def test_the_rewrite_touches_exactly_one_line(): + """Surgical, not a JSON round-trip. The manifest's formatting and key order + are not this script's to decide, and a whole-file reformat would make every + mint an unreadable diff.""" + before = fake_manifest("0.1.48") + after = rewrite(before, "2026.09.01.2252") + + b, a = before.splitlines(), after.splitlines() + assert len(b) == len(a) + differing = [i for i, (x, y) in enumerate(zip(b, a)) if x != y] + assert len(differing) == 1 + assert '"version": "2026.09.01.2252"' in a[differing[0]] + + +def test_the_rewrite_preserves_indentation_and_key_order(): + weird = '{\n\t"name": "scribe",\n\t"version": "0.1.48",\n\t"z": 1\n}\n' + out = rewrite(weird, "2026.09.01.2252") + assert out == '{\n\t"name": "scribe",\n\t"version": "2026.09.01.2252",\n\t"z": 1\n}\n' + + +def test_the_rewrite_refuses_a_manifest_it_cannot_match(): + """Raises rather than falling back to a JSON round-trip: a manifest this + cannot match is one whose shape changed, and quietly reformatting the file + to cope would be a far larger edit than the caller asked for.""" + with pytest.raises(ValueError): + rewrite('{"name": "scribe"}', "2026.09.01.2252") + + +def test_the_rewrite_refuses_TWO_version_lines(): + """A capped `subn` would report one replacement and look clean while the + second `version` — possibly the real one — kept its old value.""" + two = '{\n "version": "0.1.48",\n "nested": {\n "version": "9.9.9"\n }\n}\n' + with pytest.raises(ValueError): + rewrite(two, "2026.09.01.2252") + + +# ── The version-relevant set includes its own deriver ────────────────────── + + +def test_the_mint_script_is_version_relevant(): + """#3127 §3's asymmetry. A change to how the version is COMPUTED is + compared against nothing — leave the deriver out of the set and a format + change never forces a re-mint, so the manifest keeps a value in the old + format indefinitely and nothing says so.""" + paths = check_plugin.version_relevant_paths() + assert "scripts/mint_plugin_version.py" in paths + for shipped in check_plugin.SHIPPED_PATHS: + assert shipped in paths + + +def test_the_checker_is_NOT_version_relevant(): + """The inverse, and it is the easy mistake. A checker decides whether the + lane goes red, not what the artifact reports — so its absence here is a + decision, not an oversight.""" + assert "scripts/check_plugin.py" not in check_plugin.version_relevant_paths() + + +# ── The check ────────────────────────────────────────────────────────────── + + +def run_check(here: str, there: str | None, changed_paths: list[str], monkeypatch): + """Drive `check_version_is_minted` with git stubbed. Returns the failures.""" + monkeypatch.setattr( + check_plugin, "_git", + lambda *a: (0, "\n".join(changed_paths)) if a[0] == "diff" else (0, ""), + ) + monkeypatch.setattr( + check_plugin, "manifest_version", + lambda ref=None: here if ref is None else there, + ) + monkeypatch.setattr( + check_plugin, "manifest_text", + lambda ref=None: fake_manifest(here if ref is None else (there or "0.0.0.0000")), + ) + check_plugin.check_version_is_minted("origin/main") + return list(check_plugin.failures) + + +def test_content_changed_and_the_version_did_not_FAILS(monkeypatch): + """#2209, exactly. The headline, and the only reason the check exists.""" + failures = run_check( + "2026.09.01.2252", "2026.09.01.2252", + ["plugin/hooks/scribe_session_context.sh"], monkeypatch, + ) + assert len(failures) == 1 + assert "still 2026.09.01.2252" in failures[0] + assert "scribe_session_context.sh" in failures[0] + + +def test_content_changed_and_the_version_moved_PASSES(monkeypatch): + assert run_check( + "2026.09.01.2252", "2026.08.30.1200", + ["plugin/hooks/scribe_session_context.sh"], monkeypatch, + ) == [] + + +def test_a_version_that_is_not_the_canonical_shape_FAILS(monkeypatch): + """`K4` returns the manifest string verbatim, so a malformed value is not + rejected by the installer — it either sorts as an ordinary string or, when + unreadable, forces a reinstall every session. Neither is loud (#3325).""" + failures = run_check("0.1.48", "0.1.47", [], monkeypatch) + assert len(failures) == 1 + assert "not YYYY.MM.DD.HHMM" in failures[0] + + +@pytest.mark.parametrize("bad", ["2026.9.1.2252", "2026.09.01.252", "2026.09.01"]) +def test_an_UNPADDED_or_short_version_FAILS(bad, monkeypatch): + """The padding is the contract, not cosmetics — one shape for every version + in the family (#3127 checklist 10).""" + assert run_check(bad, "2026.08.30.1200", [], monkeypatch) != [] + + +def test_a_version_in_the_future_FAILS(monkeypatch): + ahead = (datetime.now(timezone.utc) + timedelta(days=400)).strftime("%Y.%m.%d.%H%M") + failures = run_check(ahead, "2026.08.30.1200", [], monkeypatch) + assert len(failures) == 1 + assert "in the future" in failures[0] + + +def test_a_version_minted_minutes_ago_is_NOT_in_the_future(monkeypatch): + """The guard has to tolerate ordinary skew: the mint happens on a + workstation and the lane runs later, on another machine's clock.""" + now = datetime.now(timezone.utc).strftime("%Y.%m.%d.%H%M") + assert run_check(now, "2026.08.30.1200", [], monkeypatch) == [] + + +def test_nothing_changed_and_nothing_minted_PASSES(monkeypatch): + assert run_check("2026.09.01.2252", "2026.09.01.2252", [], monkeypatch) == [] + + +def test_a_version_that_moved_with_no_content_change_is_NOT_a_failure(monkeypatch): + """Deliberately a pass. A needless re-mint costs one cache refresh; failing + the lane over a harmless act is how a check earns a `--no-version` in + somebody's muscle memory and stops running at all. The implication that + matters is one-directional: content changed IMPLIES version moved.""" + assert run_check("2026.09.01.2252", "2026.08.30.1200", [], monkeypatch) == [] + + +def test_a_failed_diff_FAILS_rather_than_passing_quietly(monkeypatch): + """A check that cannot run must not report the same thing as a check that + passed — #2663's lesson, and the reason this whole file's siblings exist.""" + monkeypatch.setattr(check_plugin, "_git", lambda *a: (128, "fatal")) + monkeypatch.setattr(check_plugin, "manifest_version", + lambda ref=None: "2026.09.01.2252") + check_plugin.check_version_is_minted("origin/main") + assert len(check_plugin.failures) == 1 + assert "could not run" in check_plugin.failures[0] + + +# ── The real manifest ────────────────────────────────────────────────────── + + +def test_the_shipped_manifest_carries_a_minted_version(): + """The end of the hand-bumped scheme, asserted on the real file. `0.1.48` + was the last of 48 numbers a person typed.""" + version = json.loads(check_plugin.MANIFEST.read_text())["version"] + assert VERSION_RE.match(version), ( + f"the shipped manifest says {version!r}, which is not a minted version" + ) + + +def test_the_session_context_hook_still_reads_the_version_field(): + """The marker #2220 asked for. The value's SHAPE changed, not the field or + its reader — if this had to move, the derivation went somewhere it should + not have.""" + hook = (check_plugin.HOOKS_DIR / "scribe_session_context.sh").read_text() + assert re.search(r"jq\s+-r\s+'\.version", hook) From 64cb719a125f5fb992d7fc1114baffa1ea802c8c Mon Sep 17 00:00:00 2001 From: Bryan Van Deusen Date: Wed, 2 Sep 2026 00:15:45 -0400 Subject: [PATCH 09/19] fix(plugin): mint() rendered whatever offset it was handed, not UTC (#3327) Run 5175 red on the Python tests lane. The failing assertion was test_the_mint_is_UTC_not_local, and it was right: `strftime` renders the offset the datetime carries, so mint() only produced UTC because its DEFAULT argument happens to be datetime.now(timezone.utc). Hand it an aware datetime in any other zone and it formats that zone's wall clock -- 22:52Z and its +09:00 twin, the same instant, minted as 2026.09.01.2252 and 2026.09.02.0752. The docstring already claimed "UTC, always", so this was a contract the code did not hold rather than a test asking for something new. Two people minting the same instant would disagree, and the string IS the artifact's identity. Now converts explicitly. A naive datetime is read as UTC rather than as the machine's zone: that is this function's stated contract, and guessing the host's offset is how the same bug returns by another route. Two things found while walking the rest of the module by hand: - test_a_failed_diff_FAILS_rather_than_passing_quietly stubbed EVERY git call to fail, so it tripped the base-branch guard first and passed while proving nothing about the diff arm. rev-parse now succeeds and only the diff fails, and the assertion names the diff message instead of the substring both messages happen to share. - the base-branch failure still said "version-bump check", a name that went away with check_version_bump. The mint script is in the version-relevant set, so fixing it is itself a version-relevant change and forced a fresh mint -- 2026.09.02.0415. That is the asymmetry in #3127 section 3 working as intended rather than a quirk: a format change that did not re-mint would leave the manifest reporting a value the current deriver can no longer produce. Co-Authored-By: Claude Opus 5 Claude-Session: https://claude.ai/code/session_01DN4zBVFWhBST9YqjCfQmPb --- plugin/.claude-plugin/plugin.json | 2 +- scripts/check_plugin.py | 2 +- scripts/mint_plugin_version.py | 16 +++++++++++++--- tests/test_plugin_version_mint.py | 14 +++++++++++--- 4 files changed, 26 insertions(+), 8 deletions(-) diff --git a/plugin/.claude-plugin/plugin.json b/plugin/.claude-plugin/plugin.json index 4e078a1..ae00a4f 100644 --- a/plugin/.claude-plugin/plugin.json +++ b/plugin/.claude-plugin/plugin.json @@ -1,7 +1,7 @@ { "name": "scribe", "description": "Scribe system-of-record for Claude Code: MCP tools over your notes/tasks/projects/rules, a session-start push channel that surfaces your always-on rules + active-project context, process-skills (writing-plans, systematic-debugging, verification, brainstorming, reusing-code), and your saved Scribe Processes auto-surfaced as skills (/scribe:sync). Replaces superpowers + file-memory with one app-backed plugin.", - "version": "2026.09.01.2252", + "version": "2026.09.02.0415", "author": { "name": "Bryan Van Deusen" }, diff --git a/scripts/check_plugin.py b/scripts/check_plugin.py index 150e72c..9066a7a 100755 --- a/scripts/check_plugin.py +++ b/scripts/check_plugin.py @@ -596,7 +596,7 @@ def check_version_is_minted(base: str = "origin/main") -> None: # Do NOT pass silently — a check that quietly no-ops is how this class # of bug survives in the first place. fail( - f"cannot resolve {base}, so the version-bump check could not run. " + f"cannot resolve {base}, so the minted-version check could not run. " f"Fetch it first — `git fetch --depth=1 origin main:refs/remotes/" f"origin/main` is enough, since this diffs two trees and needs no " f"common ancestor — or pass --no-version deliberately." diff --git a/scripts/mint_plugin_version.py b/scripts/mint_plugin_version.py index 2d45d77..c37df47 100644 --- a/scripts/mint_plugin_version.py +++ b/scripts/mint_plugin_version.py @@ -64,9 +64,19 @@ VERSION_LINE_RE = re.compile(r'^(\s*"version"\s*:\s*")([^"]*)(".*)$', re.M) def mint(now: datetime | None = None) -> str: - """The version for this moment. UTC, always — a local-time mint would make - the value depend on who ran it.""" - return (now or datetime.now(timezone.utc)).strftime(VERSION_FORMAT) + """The version for this moment. UTC, always. + + The conversion is not decoration: `strftime` renders whatever offset the + datetime carries, so without it two people minting the same instant in + different zones produce different strings — and the string IS the + artifact's identity. A naive datetime is read as UTC rather than as the + machine's zone, because that is this function's stated contract and + guessing the host's offset is how the bug comes back by another route. + """ + moment = now or datetime.now(timezone.utc) + if moment.tzinfo is None: + moment = moment.replace(tzinfo=timezone.utc) + return moment.astimezone(timezone.utc).strftime(VERSION_FORMAT) def rewrite(text: str, version: str) -> str: diff --git a/tests/test_plugin_version_mint.py b/tests/test_plugin_version_mint.py index 8943e5f..4b2d33c 100644 --- a/tests/test_plugin_version_mint.py +++ b/tests/test_plugin_version_mint.py @@ -250,13 +250,21 @@ def test_a_version_that_moved_with_no_content_change_is_NOT_a_failure(monkeypatc def test_a_failed_diff_FAILS_rather_than_passing_quietly(monkeypatch): """A check that cannot run must not report the same thing as a check that - passed — #2663's lesson, and the reason this whole file's siblings exist.""" - monkeypatch.setattr(check_plugin, "_git", lambda *a: (128, "fatal")) + passed — #2663's lesson, and the reason this file's siblings exist. + + `rev-parse` is stubbed to SUCCEED so only the diff fails. Failing every git + call would trip the base-branch guard first and this would pass while + proving nothing about the diff arm. + """ + monkeypatch.setattr( + check_plugin, "_git", + lambda *a: (128, "fatal: bad object") if a[0] == "diff" else (0, ""), + ) monkeypatch.setattr(check_plugin, "manifest_version", lambda ref=None: "2026.09.01.2252") check_plugin.check_version_is_minted("origin/main") assert len(check_plugin.failures) == 1 - assert "could not run" in check_plugin.failures[0] + assert "git diff" in check_plugin.failures[0] # ── The real manifest ────────────────────────────────────────────────────── From f5a3643da896fd29dc7b0fc4b272346962802a35 Mon Sep 17 00:00:00 2001 From: Bryan Van Deusen Date: Wed, 2 Sep 2026 00:38:50 -0400 Subject: [PATCH 10/19] =?UTF-8?q?refactor(plugin):=20retire=20what=20the?= =?UTF-8?q?=20hand-bump=20scheme=20left=20behind=20=E2=80=94=20the=20READM?= =?UTF-8?q?E=20that=20taught=20it,=20the=20floor=20test,=20the=20stale=20r?= =?UTF-8?q?ationale=20(#3328)?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit #3127 checklist 19. The step's own deletion list turned out to be largely spent: `check_version_bump()` came out with #3327, and the machinery the step expected to delete alongside it is load-bearing for its replacement. `manifest_version(ref=…)`, `--base`, `--no-version` and the `origin/main` resolve path all STAY. Derivation makes the value right; it does not make the comparison unnecessary. `check_version_is_minted` still has to ask "did the version move when the shipped content did?", and that is a base-branch question no matter who chose the number. The step was planned before #3327 landed, when the assumption was that these died with the guard. What was actually still standing, all of it teaching or asserting the retired scheme: - `plugin/README.md` told the reader to "set a `version` bump per release." A shipped file, instructing the exact act the mint replaced — this is how a deleted control gets re-added by someone following the docs. Now says not to hand-edit the field, names `make mint-plugin`, and says what a forgotten mint costs. (`make` is not installed on every workstation, so the direct script invocation is given too.) - `test_plugin_version_bumped_with_the_hook` asserted `version >= (0,1,31)` as a tuple of ints. Under a minted value it passes vacuously — every date clears a floor of 0.1.31 — and `int("0415")` silently eats the padding the format exists to keep. Superseded by `test_the_shipped_manifest_carries_a_minted_version`, which asserts the canonical shape instead of an ordering the comparator does not perform. Removed whole (rule 22). - The module preamble still ended on "a written rule that depends on being remembered is not a control; this is" — true of the bump guard, and read as a stronger claim than the mint can support. Replaced with what the change did and did not remove: choosing a number is gone, running the mint is not, and the difference is that forgetting is now loud rather than silent. - An orphaned `# --- the version bump ---` section header with nothing under it, and a test docstring still naming `check_version_bump`. `--no-version` keeps its one legitimate case — on `main` the version is measured against itself — and now says so in both the usage block and its `--help`, so it does not read as an escape hatch. `check_session_context_ reports_its_version` stays untouched: a different check with a different job, and the only thing that makes step 6 readable from a transcript (#2220). Version minted 2026.09.02.0415 -> 2026.09.02.0438 for the README change. Co-Authored-By: Claude Opus 5 (1M context) Claude-Session: https://claude.ai/code/session_01TcCs1CcQ1ormdnzSshKqvN --- plugin/.claude-plugin/plugin.json | 2 +- plugin/README.md | 9 +++++++-- scripts/check_plugin.py | 33 +++++++++++++++++++++++-------- tests/test_plugin_shipped_set.py | 2 +- tests/test_write_path_trigger.py | 8 -------- 5 files changed, 34 insertions(+), 20 deletions(-) diff --git a/plugin/.claude-plugin/plugin.json b/plugin/.claude-plugin/plugin.json index ae00a4f..c462aa9 100644 --- a/plugin/.claude-plugin/plugin.json +++ b/plugin/.claude-plugin/plugin.json @@ -1,7 +1,7 @@ { "name": "scribe", "description": "Scribe system-of-record for Claude Code: MCP tools over your notes/tasks/projects/rules, a session-start push channel that surfaces your always-on rules + active-project context, process-skills (writing-plans, systematic-debugging, verification, brainstorming, reusing-code), and your saved Scribe Processes auto-surfaced as skills (/scribe:sync). Replaces superpowers + file-memory with one app-backed plugin.", - "version": "2026.09.02.0415", + "version": "2026.09.02.0438", "author": { "name": "Bryan Van Deusen" }, diff --git a/plugin/README.md b/plugin/README.md index 14a1fdc..adbd6b6 100644 --- a/plugin/README.md +++ b/plugin/README.md @@ -78,8 +78,13 @@ On install you'll be asked for: ## Notes -- Set a `version` bump in `.claude-plugin/plugin.json` per release so clients - pick up changes. +- **Do not hand-edit `version` in `.claude-plugin/plugin.json`.** It is minted + from the clock — run `make mint-plugin` (or `python3 + scripts/mint_plugin_version.py`) after changing anything under `plugin/`, and + commit the result. The installer decides whether to refresh the cache it + executes from by comparing that string, so content that ships without a new + version reaches the repo and stops there (#2209). CI fails the lane if you + forget. - The session-start, auto-inject and prior-art hooks need only a **read**-scoped key; the MCP tools need **write** scope to create/update. Every hook is a GET for that reason — a read key cannot POST. diff --git a/scripts/check_plugin.py b/scripts/check_plugin.py index 9066a7a..dd381ba 100755 --- a/scripts/check_plugin.py +++ b/scripts/check_plugin.py @@ -13,9 +13,20 @@ separate defects have reached a live install through that path: install, because `plugin.json`'s version wasn't bumped and the installer compares versions to decide whether to refresh its cache. -The rule for the second one was already written down and was still missed. A -written rule that depends on being remembered during a long session is not a -control; this is. +Both were fixed. The second was fixed TWICE — once by bumping the number, and +then properly, by removing the class it came from: `plugin.json`'s version is +no longer a value anybody chooses. `scripts/mint_plugin_version.py` derives it +from the clock (`make mint-plugin`), and `check_version_is_minted` below fails +the lane when shipped content moved and the version did not. + +State exactly what that did and did not remove, because a rationale that +overstates its own control is how the control gets trusted past its limit, and +because the paragraph this replaces was itself read that way. Gone: having to +remember which NUMBER to write, and the whole question of whether a chosen +number was the right one. Not gone: the mint still has to be RUN, and +forgetting to run it is still possible. What changed is that forgetting is now +LOUD — a red lane on the batch that forgot, instead of a silent no-op found +weeks later when somebody says "I don't think it updated" (#2220). shellcheck and jq are NOT in `ci-python` (verified against CI-runner's Dockerfile and scripts/install-common.sh, not from memory — rule #37). CI installs both @@ -31,8 +42,15 @@ itself loudly, because a check that quietly no-ops is the failure mode this whole file exists to prevent. Usage: - python3 scripts/check_plugin.py # all checks - python3 scripts/check_plugin.py --no-version # skip the version check + python3 scripts/check_plugin.py # all checks + python3 scripts/check_plugin.py --no-version # on `main` only — see below + +`--no-version` exists for ONE case. The version is measured against +`origin/main`, so on `main` itself the comparison is against itself and answers +nothing; the syntax, pattern and marker checks are the only ones that mean +anything there. It is NOT a way past a red lane — see +`check_version_is_minted`, whose whole design is shaped by keeping this flag +out of anyone's muscle memory. """ from __future__ import annotations @@ -217,8 +235,6 @@ def check_patterns() -> None: ok(f"{rel}: no known-bad patterns") -# --- the version bump ------------------------------------------------------ - # --- shellcheck ------------------------------------------------------------ def check_shellcheck() -> None: @@ -668,7 +684,8 @@ def check_version_is_minted(base: str = "origin/main") -> None: def main() -> int: parser = argparse.ArgumentParser(description=__doc__) parser.add_argument("--no-version", action="store_true", - help="skip the minted-version check") + help="skip the minted-version check; for `main`, where " + "it would be measured against itself") parser.add_argument("--base", default="origin/main", help="branch the version is measured against") args = parser.parse_args() diff --git a/tests/test_plugin_shipped_set.py b/tests/test_plugin_shipped_set.py index 0a8f46e..2587f6e 100644 --- a/tests/test_plugin_shipped_set.py +++ b/tests/test_plugin_shipped_set.py @@ -203,7 +203,7 @@ def test_shipped_content_changed_reports_a_version_only_commit_as_unchanged(monk """End to end through the git seam, with git stubbed. The unit above proves the comparison; this proves it is actually WIRED to - the path that `check_version_bump` reads. A correct helper nobody calls + the path that `check_version_is_minted` reads. A correct helper nobody calls would leave the circular check exactly as it was. """ from scripts import check_plugin diff --git a/tests/test_write_path_trigger.py b/tests/test_write_path_trigger.py index f84b2cd..c2c47c1 100644 --- a/tests/test_write_path_trigger.py +++ b/tests/test_write_path_trigger.py @@ -867,14 +867,6 @@ def test_hook_skips_prose_and_data_files(): assert '/scribe_defs.sh"' in src # sourced, not copied -def test_plugin_version_bumped_with_the_hook(): - """The #1040 lesson: a plugin change clients can't see is a change that didn't - ship.""" - manifest = json.loads((PLUGIN / ".claude-plugin" / "plugin.json").read_text()) - version = tuple(int(p) for p in manifest["version"].split(".")) - assert version >= (0, 1, 31) - - def test_hook_keeps_sync_and_reuse_dedup_apart(): """#2708's dedup audit, pinned: the hook holds TWO per-session id files and feeds each its own class — sync ids (snippets recording the edited file) to From 9bb59b73ba4f4623aedd412008eaff02587e2e73 Mon Sep 17 00:00:00 2001 From: Bryan Van Deusen Date: Wed, 2 Sep 2026 11:23:43 -0400 Subject: [PATCH 11/19] feat(frontend): the app says what it is running, and says so honestly when it cannot find out (#3329) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit #3127 checklist 12, plus rule 27 — a capability with no surface the operator can touch is not shipped. The step was planned on the premise that nothing read `/api/version`. Two things did, and the state was worse than nothing: - `App.vue` fetched it, wrote `version` into a ref initialised to the literal `"dev"`, and swallowed the error. An instance that could not answer rendered EXACTLY what a healthy local build renders. That is checklist 12's named failure — a blank standing in for `unknown` — in the one readout whose whole job is to say what is running, and it would have made #3298's debugging session no cheaper. - `SettingsView.vue` fetched the same endpoint again on every mount and wrote the result into a local ref no template ever read. A duplicate request whose answer was discarded. So this is not "add a readout"; it is "make the existing one honest, and give it the three fields nobody could see." The readout — Settings → Config, first section, beside the other "what is this instance doing" facts. Three states kept apart, because collapsing any two of them is the defect: not asked yet (tab unopened) nothing answered the values, each ABSENT field as "unknown" the fetch itself failed its own message, with a retry `version` and `channel` prominent, `commit` in full with a copy button so it can be pasted into a `:sha` lookup (rule 145 — the registry's identity and the artifact's own must be checkable against each other), `build` kept because its ABSENCE is the diagnostic part: no ordering key means this build is not in any update order, which is what a local or hand-built image looks like. Absence, not falsiness. The payload omits what it does not know rather than sending `""` or `0` (see `build_version_payload`), so the renderer uses `??` throughout — `build` is a number and `0` is a legitimate ordering key, which `||` would report as unknown. `tests/test_version_readout.py` pins that operator specifically, along with the "no plausible default" property, because `||` is the form a person reaches for by habit. Rule 156 — the fetch carries a deadline. This readout is consulted when an instance is misbehaving, which is exactly when it may never answer; without one the surface sits on "still loading" forever, which is the same blank arrived at from the other direction. `apiGet` gains an OPT-IN `timeoutMs` rather than a default, so no existing call site's behaviour moves. Every other call in the client still has no deadline — reported separately, not fixed here. No frontend test runner exists, so verification is the typecheck lane plus four source-inspection guards in the unit lane, each pinning one property. Also folded in: `plugin/README.md` now leads with the mint script and offers `make` second, since `make` is not installed on every workstation. Co-Authored-By: Claude Opus 5 (1M context) Claude-Session: https://claude.ai/code/session_01TcCs1CcQ1ormdnzSshKqvN --- frontend/src/App.vue | 25 ++++-- frontend/src/api/client.ts | 21 ++++- frontend/src/api/version.ts | 42 ++++++++++ frontend/src/views/SettingsView.vue | 119 ++++++++++++++++++++++++++-- plugin/README.md | 6 +- tests/test_version_readout.py | 86 ++++++++++++++++++++ 6 files changed, 283 insertions(+), 16 deletions(-) create mode 100644 frontend/src/api/version.ts create mode 100644 tests/test_version_readout.py diff --git a/frontend/src/App.vue b/frontend/src/App.vue index 2efab18..278b2f4 100644 --- a/frontend/src/App.vue +++ b/frontend/src/App.vue @@ -7,12 +7,20 @@ import { useTheme } from "@/composables/useTheme"; import { useShortcuts } from "@/composables/useShortcuts"; import { useAuthStore } from "@/stores/auth"; import { useSettingsStore } from "@/stores/settings"; -import { apiGet, apiPut } from "@/api/client"; +import { apiPut } from "@/api/client"; +import { fetchVersion } from "@/api/version"; useTheme(); const router = useRouter(); -const appVersion = ref("dev"); +// THREE states, not two (#3127 checklist 12). `null` is "not answered yet" and +// renders nothing; a string renders; `appVersionFailed` renders its own thing. +// This used to default to the literal "dev" and swallow the error, which meant +// an instance that could not answer was indistinguishable from a local build +// that genuinely reports "dev" — a blank standing in for `unknown`, in the one +// readout whose whole job is to say what is running. +const appVersion = ref(null); +const appVersionFailed = ref(false); const authStore = useAuthStore(); const settingsStore = useSettingsStore(); const { showShortcuts, toggleShortcuts, closeShortcuts } = useShortcuts(); @@ -119,10 +127,12 @@ onMounted(async () => { startAppServices(); } try { - const data = await apiGet<{ version: string }>("/api/version"); - appVersion.value = data.version; + appVersion.value = (await fetchVersion()).version; } catch { - // silent — version display is non-critical + // Not silent any more: the footer says it could not find out, rather than + // showing a version it never received. The full readout (version, channel, + // commit, build) lives in Settings → Config. + appVersionFailed.value = true; } }); @@ -151,7 +161,10 @@ onUnmounted(() => {
-
v{{ appVersion }}
+
+ v{{ appVersion }} + version unknown +
diff --git a/frontend/src/api/client.ts b/frontend/src/api/client.ts index 286d247..ad91d7a 100644 --- a/frontend/src/api/client.ts +++ b/frontend/src/api/client.ts @@ -52,8 +52,25 @@ export function apiErrorMessage(e: unknown, fallback: string): string { return fallback; } -export async function apiGet(path: string): Promise { - const res = await fetch(path); +/** + * A GET, optionally with a deadline. + * + * `timeoutMs` is OPT-IN rather than defaulted, deliberately. Every existing + * caller was written against a `fetch` that waits as long as the browser will, + * and handing them all a deadline in one change would alter behaviour at every + * call site at once, including ones nobody has looked at. New callers should + * pass one. + * + * Why a caller should want it: a wait with no deadline cannot report that it + * failed. It can only stay pending — which is indistinguishable, to anything + * rendering it, from "still loading". A surface that has to tell those two + * apart needs the request to give up on its own. + */ +export async function apiGet(path: string, opts?: { timeoutMs?: number }): Promise { + const res = await fetch( + path, + opts?.timeoutMs ? { signal: AbortSignal.timeout(opts.timeoutMs) } : undefined, + ); return handleResponse(res, path); } diff --git a/frontend/src/api/version.ts b/frontend/src/api/version.ts new file mode 100644 index 0000000..1d239c0 --- /dev/null +++ b/frontend/src/api/version.ts @@ -0,0 +1,42 @@ +import { apiGet } from "./client"; + +/** + * What `/api/version` answers — the client's half of `build_version_payload` + * (`src/scribe/routes/api.py`), which is where the reasoning for the shape is + * written down. + * + * EVERY FIELD BUT `version` IS OPTIONAL, and an absent one means "this build + * does not know", not "empty". A local build has no ordering key and no + * channel, and the server says so by omitting the keys rather than sending + * `""` — emitting a placeholder would let it claim a position in an update + * order it is not part of. + * + * So a renderer must read ABSENCE, never falsiness. `build` is a number and + * `0` is a legitimate ordering key, so `v.build || "unknown"` would report a + * real value as unknown; `v.build ?? "unknown"` is the correct form. + */ +export interface VersionPayload { + /** The NAME — `YYYY.MM.DD.HHMM` from commit time. Answers "is this the same code?" */ + version: string; + /** The ORDERING KEY — minutes since 2020-01-01, from build time. Absent on a local build. */ + build?: number; + /** `dev` / `main` / a tag. Its own field, never folded into the name. */ + channel?: string; + /** The commit the artifact was published under, so its claim can be checked against the registry. */ + commit?: string; +} + +/** + * The readout exists to answer "what is running?" during an incident, which is + * exactly when the server may be the thing that is unwell. Without a deadline + * a failing instance leaves the request pending forever and the surface sits + * on "still loading" — a blank standing in for `unknown`, which is the failure + * mode #3127 checklist 12 names by hand. Eight seconds is long enough for a + * slow-but-alive instance and short enough that a person watching it learns + * something. + */ +const VERSION_TIMEOUT_MS = 8000; + +export function fetchVersion(): Promise { + return apiGet("/api/version", { timeoutMs: VERSION_TIMEOUT_MS }); +} diff --git a/frontend/src/views/SettingsView.vue b/frontend/src/views/SettingsView.vue index 360447a..1a7e7cc 100644 --- a/frontend/src/views/SettingsView.vue +++ b/frontend/src/views/SettingsView.vue @@ -9,6 +9,7 @@ import type { User } from "@/types/auth"; import PaginationBar from "@/components/PaginationBar.vue"; import TagInput from "@/components/TagInput.vue"; import { fmtDate, fmtLogStamp } from "@/utils/dateFormat"; +import { fetchVersion, type VersionPayload } from "@/api/version"; const store = useSettingsStore(); const authStore = useAuthStore(); @@ -187,7 +188,37 @@ const changingPassword = ref(false); const invalidatingSessions = ref(false); const exporting = ref(false); const restoring = ref(false); -const appVersion = ref('dev'); +// ── What's running (#3127 checklist 12) ───────────────────────────────── +// Three states kept apart, because collapsing any two of them is the defect +// this readout exists to remove: `null` + no error = not asked yet (the Config +// tab has not been opened); a payload = answered, with each ABSENT field shown +// as "unknown"; `versionError` = the fetch itself failed, which is its own +// thing and must never render as a blank or as a plausible-looking value. +const versionInfo = ref(null); +const versionLoading = ref(false); +const versionError = ref(""); +const commitCopied = ref(false); + +async function loadVersionPanel() { + if (versionLoading.value) return; + versionLoading.value = true; + versionError.value = ""; + try { + versionInfo.value = await fetchVersion(); + } catch (e) { + versionInfo.value = null; + versionError.value = apiErrorMessage(e, "Could not reach the instance to ask what it is running."); + } finally { + versionLoading.value = false; + } +} + +async function copyCommit() { + if (!versionInfo.value?.commit) return; + await copyToClipboard(versionInfo.value.commit); + commitCopied.value = true; + setTimeout(() => { commitCopied.value = false; }, 2000); +} const restoreFileInput = ref(null); // Migrate stored "admin" → "config"; unknown tabs fall back to "general" @@ -201,6 +232,7 @@ function _loadTabContent(tab: string) { else if (tab === "logs") loadLogsPanel(); else if (tab === "groups") loadGroupsPanel(); else if (tab === "areas") canonStore.fetchCatalog(true); + else if (tab === "config" && !versionInfo.value) loadVersionPanel(); } if (tab === "apikeys") { fetchApiKeys(); } } @@ -554,10 +586,6 @@ function toggleProfileWorkDay(day: string) { function emptyTagsFetch(): Promise { return Promise.resolve([]) } onMounted(async () => { - try { - const v = await apiGet<{ version: string }>('/api/version') - appVersion.value = v.version - } catch { /* non-critical */ } await store.fetchSettings(); newEmail.value = authStore.user?.email ?? ""; @@ -2109,6 +2137,48 @@ async function deleteUser(userId: number) {
+
+

What's running

+

+ The build serving this page. Paste the commit into a :sha image + lookup to check the registry and the app agree about what was published. +

+ +
Reading the ledger…
+
+ {{ versionError }} + +
+
+
Version
+
{{ versionInfo.version }}
+ +
Channel
+
+ {{ versionInfo.channel ?? "unknown" }} +
+ +
Commit
+
+ {{ versionInfo.commit }} + +
+
unknown
+ +
Build
+ +
+ {{ versionInfo.build ?? "unknown" }} +
+
+
Nothing asked yet.
+
+

Application URL

@@ -2768,6 +2838,45 @@ async function deleteUser(userId: number) { letter-spacing: 0.07em; color: var(--fs-text-tertiary); } +/* What's running — a definition list of instance facts. Spacing/geometry only; + colour and type come from the tokens. */ +.version-grid { + display: grid; + grid-template-columns: max-content 1fr; + gap: 0.4rem 1rem; + margin: 0; + align-items: baseline; +} +.version-grid dt { + font-size: 0.8rem; + color: var(--fs-text-secondary); +} +.version-grid dd { + margin: 0; + font-size: 0.875rem; + font-family: var(--fs-font-mono); + color: var(--fs-text-primary); +} +/* An absent field reads as absent — never as a blank, and never styled to look + like a value it does not have (#3127 checklist 12). */ +.version-grid dd.version-unknown { + font-family: inherit; + font-style: italic; + color: var(--fs-text-tertiary); +} +.version-commit { + display: flex; + align-items: center; + gap: 0.5rem; + flex-wrap: wrap; +} +.version-sha { + overflow-wrap: anywhere; +} +.version-retry { + margin-left: 0.5rem; +} + .section-desc { margin: 0 0 1rem; font-size: 0.875rem; diff --git a/plugin/README.md b/plugin/README.md index adbd6b6..f7e9a1a 100644 --- a/plugin/README.md +++ b/plugin/README.md @@ -79,9 +79,9 @@ On install you'll be asked for: ## Notes - **Do not hand-edit `version` in `.claude-plugin/plugin.json`.** It is minted - from the clock — run `make mint-plugin` (or `python3 - scripts/mint_plugin_version.py`) after changing anything under `plugin/`, and - commit the result. The installer decides whether to refresh the cache it + from the clock — run `python3 scripts/mint_plugin_version.py` (or `make + mint-plugin`, where `make` is installed) after changing anything under + `plugin/`, and commit the result. The installer decides whether to refresh the cache it executes from by comparing that string, so content that ships without a new version reaches the repo and stops there (#2209). CI fails the lane if you forget. diff --git a/tests/test_version_readout.py b/tests/test_version_readout.py new file mode 100644 index 0000000..3d4d867 --- /dev/null +++ b/tests/test_version_readout.py @@ -0,0 +1,86 @@ +"""The app must SAY what it is running, and must not lie when it cannot find out. + +There is no frontend test runner in this repo, so these are source-inspection +guards in the unit lane — the same idiom `check_plugin.py` uses on the hook +shells. They are deliberately few and deliberately about ONE property each, +because a grep-shaped test that asserts a whole file's contents fails on every +refactor and gets deleted. + +WHY THIS FILE EXISTS. #3298: with a deploy misbehaving, nothing on the instance +could say which commit was serving it, and the one endpoint whose job that is +answered with the name of a branch. The value was fixed then. This is the other +half — the value reaching a person — and #3127 checklist 12 is specific about +the way it goes wrong: *never let a blank stand in for `unknown`*. A readout +that renders a plausible value it never received is worse than one that renders +nothing, because it ends the investigation instead of starting it. +""" +from __future__ import annotations + +import re +from pathlib import Path + +FRONTEND = Path(__file__).resolve().parents[1] / "frontend" / "src" + + +def test_something_actually_reads_the_version_endpoint(): + """The endpoint is not enough; something must ask it. + + `/api/version` answered correctly for weeks with no caller — an endpoint + reachable only by someone who already knew to curl it. Rule 27: a + capability with no surface the operator can touch is not shipped. + """ + hits = [p for p in FRONTEND.rglob("*.ts") if "/api/version" in p.read_text()] + assert hits, "nothing under frontend/src fetches /api/version" + + +def test_the_footer_does_not_default_to_a_plausible_version(): + """The regression this readout was built to remove. + + `appVersion` used to start life as the literal `"dev"` and the fetch + swallowed its own failure, so an instance that could not answer rendered + exactly what a healthy local build renders. Two very different states, one + string, and no way to tell them apart from the page. + + Pinned as "the ref does not start at a version-shaped literal" rather than + as an exact initialiser, so a later refactor can change how the state is + held without failing here — what must not come back is the plausible + default. + """ + app = (FRONTEND / "App.vue").read_text() + match = re.search(r"const appVersion = ref[^;]*;", app) + assert match, "App.vue no longer declares appVersion — update this guard" + decl = match.group(0) + assert '"dev"' not in decl and "'dev'" not in decl, ( + f"appVersion defaults to a version-shaped literal: {decl}\n" + "A failed fetch would render as a real-looking version (#3127 " + "checklist 12). Start from a not-answered-yet value instead." + ) + + +def test_optional_version_fields_are_read_by_absence_not_falsiness(): + """`build` is a number and 0 is a legitimate ordering key. + + The payload omits what it does not know rather than sending `""` or `0`, so + the renderer's job is to distinguish ABSENT from present. `||` cannot: it + would report a real `build` of 0 as unknown, and it is the form a person + reaches for by habit. `??` is the correct one, which is why this pins the + operator rather than the rendered output. + """ + view = (FRONTEND / "views" / "SettingsView.vue").read_text() + for field in ("channel", "build"): + assert f'versionInfo.{field} ?? "unknown"' in view, ( + f"the {field} readout must use `?? \"unknown\"`, never `|| \"unknown\"` — " + "an absent field and a falsy one are different answers" + ) + + +def test_the_version_request_carries_a_deadline(): + """Rule 156. A wait with no deadline cannot report that it failed. + + This readout is consulted when an instance is misbehaving, which is exactly + when it may never answer. Without a deadline the surface sits on "still + loading" forever — the blank standing in for `unknown` again, arrived at + from the other direction. + """ + src = (FRONTEND / "api" / "version.ts").read_text() + assert "timeoutMs" in src, "the version fetch must pass a deadline" From e029a7db6442ad16488e4a2150662bd0e6d3054c Mon Sep 17 00:00:00 2001 From: Bryan Van Deusen Date: Wed, 2 Sep 2026 14:59:41 -0400 Subject: [PATCH 12/19] fix(frontend): every request carries a deadline, and expiry arrives as an error callers already handle (#3412) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Rule 156, across the whole client. `apiGet`, `apiPost`, `apiPut`, `apiPatch` and `apiDelete` each called bare `fetch`, whose default is to wait as long as the browser will — not a long timeout but the absence of one. The only AbortController in the frontend belonged to the SSE stream and was for cancellation. So every request in the app could hang forever, and there is no state a surface can render for "pending forever" that is not a lie: the spinner that never resolves looks exactly like work still in progress. Found while building the version readout (#3329), which had to tell "the fetch failed" apart from "still loading" and could not. ONE REQUEST PATH. The five verbs were near-identical bodies; they now delegate to a single `request()` that owns the deadline, so a sixth verb cannot be added without one. 30s by default — long enough to clear a cold embedding call and a list view under pool contention (#2384), so tripping it means something is wrong rather than merely busy. Overridable per call via `timeoutMs`. EXPIRY IS AN ApiError, which is the half of rule 156 that is easy to skip. A raw `DOMException: TimeoutError` reaches `apiErrorMessage(e, fallback)` as an object with no `body`, so all ~330 existing catch sites would have printed their generic fallback and the timeout would have been invisible in exactly the situation it exists to expose. Rethrown as `ApiError` with a 408 — a status no Scribe route returns, so it unambiguously means the client gave up — every one of those call sites now reports it correctly, untouched. Only TimeoutError is converted. A deliberate cancellation aborts with AbortError and passes through: a caller that cancelled its own request does not want that surfaced as a server failure. Pinned by a test, because collapsing the two is the obvious "simplification". STREAMS RELOCATE THE DEADLINE RATHER THAN ESCAPING IT. A wall-clock timeout would kill a long-lived SSE connection mid-flight, but two different waits are involved and only one of them is the stream: the CONNECT can fail to answer and now carries a 15s deadline, cleared the moment headers arrive; the BODY stays unbounded on purpose, since its failure mode is going quiet, which a timeout cannot distinguish from being idle — that is what reconnection and Last-Event-ID are for. Reading the connect as exempt because "the stream is long-lived" leaves an unreachable server looking like a quiet one. BULK TRANSFERS get their own value, not the default. Backup, notes export and admin restore walk the whole store and 30s would cut them off mid-work; they carry 10 minutes. Bounded, not unbounded — rule 156 asks for a deadline, not a short one, and no ceiling at all is what leaves a restore that died server-side spinning forever. Four source-inspection guards in the unit lane (no frontend test runner): no bare fetch anywhere; the default is actually applied — pinning the specific regression, since #3329's opt-in shape would pass every other check while leaving 330 callers unbounded; expiry converts to ApiError; and cancellation does not. Co-Authored-By: Claude Opus 5 (1M context) Claude-Session: https://claude.ai/code/session_01TcCs1CcQ1ormdnzSshKqvN --- frontend/src/api/client.ts | 166 +++++++++++++++++------ frontend/src/api/version.ts | 16 ++- frontend/src/views/SettingsView.vue | 15 +- tests/test_frontend_request_deadlines.py | 128 +++++++++++++++++ 4 files changed, 272 insertions(+), 53 deletions(-) create mode 100644 tests/test_frontend_request_deadlines.py diff --git a/frontend/src/api/client.ts b/frontend/src/api/client.ts index ad91d7a..2f4c110 100644 --- a/frontend/src/api/client.ts +++ b/frontend/src/api/client.ts @@ -53,57 +53,120 @@ export function apiErrorMessage(e: unknown, fallback: string): string { } /** - * A GET, optionally with a deadline. + * How long an ordinary JSON call may wait before it is declared failed. * - * `timeoutMs` is OPT-IN rather than defaulted, deliberately. Every existing - * caller was written against a `fetch` that waits as long as the browser will, - * and handing them all a deadline in one change would alter behaviour at every - * call site at once, including ones nobody has looked at. New callers should - * pass one. + * Rule 156: a wait with no deadline is a bug. `fetch`'s own default is to wait + * as long as the browser will, which is not a deadline — it is the absence of + * one, and it renders as a spinner that never resolves. There is no state a + * surface can show for "pending forever" that is not a lie. * - * Why a caller should want it: a wait with no deadline cannot report that it - * failed. It can only stay pending — which is indistinguishable, to anything - * rendering it, from "still loading". A surface that has to tell those two - * apart needs the request to give up on its own. + * 30s is chosen to be longer than anything healthy: it has to clear a cold + * embedding call and a list view under connection-pool contention (#2384 had + * /api/projects fanning 25 concurrent sessions at a 15-connection pool), so + * tripping it means something is genuinely wrong rather than merely busy. Slow + * BY DESIGN is a different case and passes its own value — see the callers in + * SettingsView that do. */ -export async function apiGet(path: string, opts?: { timeoutMs?: number }): Promise { - const res = await fetch( - path, - opts?.timeoutMs ? { signal: AbortSignal.timeout(opts.timeoutMs) } : undefined, +const DEFAULT_TIMEOUT_MS = 30_000; + +/** HTTP 408. Not a status any Scribe route returns, so it unambiguously means + * "the client gave up" rather than anything the server said. */ +const CLIENT_TIMEOUT_STATUS = 408; + +/** + * How long a STREAM may take to answer with its headers. + * + * Streams are the one case a wall-clock deadline would break: a long-lived SSE + * connection is *supposed* to stay open, and `AbortSignal.timeout` would kill + * it mid-flight along with the body. But that does not exempt them from rule + * 156 — it relocates the deadline. Two different waits are involved: + * + * connect — the server answering with headers. CAN fail to answer, so it + * carries this deadline, cleared the moment headers arrive. + * stream — the body, open indefinitely on purpose. Its failure mode is + * going quiet, which a timeout cannot tell from being idle; that + * is what reconnection and Last-Event-ID are for, not this. + * + * Reading the connect as exempt because "the stream is long-lived" is the easy + * mistake here, and it leaves an unreachable server looking like a quiet one. + */ +const STREAM_CONNECT_TIMEOUT_MS = 15_000; + +/** + * A signal that aborts if headers do not arrive in time, plus the `settle` to + * call once they do. After `settle()` the returned signal never fires, so the + * stream body runs unbounded — which is the intent. + */ +function connectDeadline(base: AbortSignal): { signal: AbortSignal; settle: () => void } { + const gate = new AbortController(); + const timer = setTimeout( + () => gate.abort(new DOMException("stream did not connect in time", "TimeoutError")), + STREAM_CONNECT_TIMEOUT_MS, ); + return { + signal: AbortSignal.any([base, gate.signal]), + settle: () => clearTimeout(timer), + }; +} + +export interface RequestOpts { + /** Override the deadline. Pass one when the call is slow BY DESIGN. */ + timeoutMs?: number; +} + +/** + * The one place a request is actually made — every verb below goes through + * here, so the deadline cannot be forgotten by adding a sixth. + * + * EXPIRY SURFACES AS AN `ApiError`, which is rule 156's second half: the + * failure has to arrive in the shape the caller already handles. A bare + * `DOMException: TimeoutError` would reach `apiErrorMessage(e, fallback)` as + * an object with no `body`, so every catch site in the app would report its + * generic fallback and the timeout would be invisible in the very situation it + * exists to expose. Rethrowing as `ApiError` means ~330 existing call sites + * report it correctly without being touched. + * + * Only a TIMEOUT is converted. A deliberate cancellation aborts with + * `AbortError` and is left alone — a caller that cancelled its own request + * does not want it reported as a server failure. + */ +async function request(path: string, init: RequestInit, opts?: RequestOpts): Promise { + const timeoutMs = opts?.timeoutMs ?? DEFAULT_TIMEOUT_MS; + let res: Response; + try { + res = await fetch(path, { ...init, signal: AbortSignal.timeout(timeoutMs) }); + } catch (e) { + if (e instanceof DOMException && e.name === "TimeoutError") { + throw new ApiError(CLIENT_TIMEOUT_STATUS, { + error: `The server did not answer within ${Math.round(timeoutMs / 1000)}s.`, + }); + } + throw e; + } return handleResponse(res, path); } -export async function apiPost(path: string, body: unknown): Promise { - const res = await fetch(path, { - method: "POST", - headers: { "Content-Type": "application/json" }, - body: JSON.stringify(body), - }); - return handleResponse(res, path); +/** JSON body headers — the three write verbs sent an identical literal each. */ +const JSON_HEADERS = { "Content-Type": "application/json" }; + +export function apiGet(path: string, opts?: RequestOpts): Promise { + return request(path, {}, opts); } -export async function apiPut(path: string, body: unknown): Promise { - const res = await fetch(path, { - method: "PUT", - headers: { "Content-Type": "application/json" }, - body: JSON.stringify(body), - }); - return handleResponse(res, path); +export function apiPost(path: string, body: unknown, opts?: RequestOpts): Promise { + return request(path, { method: "POST", headers: JSON_HEADERS, body: JSON.stringify(body) }, opts); } -export async function apiPatch(path: string, body: unknown): Promise { - const res = await fetch(path, { - method: "PATCH", - headers: { "Content-Type": "application/json" }, - body: JSON.stringify(body), - }); - return handleResponse(res, path); +export function apiPut(path: string, body: unknown, opts?: RequestOpts): Promise { + return request(path, { method: "PUT", headers: JSON_HEADERS, body: JSON.stringify(body) }, opts); } -export async function apiDelete(path: string): Promise { - const res = await fetch(path, { method: "DELETE" }); - return handleResponse(res, path); +export function apiPatch(path: string, body: unknown, opts?: RequestOpts): Promise { + return request(path, { method: "PATCH", headers: JSON_HEADERS, body: JSON.stringify(body) }, opts); +} + +export function apiDelete(path: string, opts?: RequestOpts): Promise { + return request(path, { method: "DELETE" }, opts); } // --------------------------------------------------------------------------- @@ -238,7 +301,14 @@ export function apiSSEStream( } const done = (async () => { - const res = await fetch(path, { headers, signal: combinedSignal }); + // Bounded connect, unbounded stream — see STREAM_CONNECT_TIMEOUT_MS. + const connect = connectDeadline(combinedSignal); + let res: Response; + try { + res = await fetch(path, { headers, signal: connect.signal }); + } finally { + connect.settle(); + } if (!res.ok) { let body: Record = {}; try { @@ -335,11 +405,19 @@ export async function apiStreamPost( body: unknown, onChunk: (data: Record) => void ): Promise { - const res = await fetch(path, { - method: "POST", - headers: { "Content-Type": "application/json" }, - body: JSON.stringify(body), - }); + // Bounded connect, unbounded stream — see STREAM_CONNECT_TIMEOUT_MS. + const connect = connectDeadline(new AbortController().signal); + let res: Response; + try { + res = await fetch(path, { + method: "POST", + headers: JSON_HEADERS, + body: JSON.stringify(body), + signal: connect.signal, + }); + } finally { + connect.settle(); + } if (!res.ok) { let errBody: Record = {}; try { diff --git a/frontend/src/api/version.ts b/frontend/src/api/version.ts index 1d239c0..79e89f0 100644 --- a/frontend/src/api/version.ts +++ b/frontend/src/api/version.ts @@ -27,13 +27,15 @@ export interface VersionPayload { } /** - * The readout exists to answer "what is running?" during an incident, which is - * exactly when the server may be the thing that is unwell. Without a deadline - * a failing instance leaves the request pending forever and the surface sits - * on "still loading" — a blank standing in for `unknown`, which is the failure - * mode #3127 checklist 12 names by hand. Eight seconds is long enough for a - * slow-but-alive instance and short enough that a person watching it learns - * something. + * SHORTER than the client's 30s default, deliberately. + * + * This readout answers "what is running?" during an incident, which is exactly + * when the server may be the thing that is unwell — and it is one static field + * off a route that does no work, so a healthy instance answers it immediately. + * Waiting the full default before saying so would leave a person staring at + * "still loading" for half a minute in the moment they are trying to find out + * whether the instance is alive at all. Eight seconds clears a slow-but-alive + * instance and tells them something quickly when it is not. */ const VERSION_TIMEOUT_MS = 8000; diff --git a/frontend/src/views/SettingsView.vue b/frontend/src/views/SettingsView.vue index 1a7e7cc..715c222 100644 --- a/frontend/src/views/SettingsView.vue +++ b/frontend/src/views/SettingsView.vue @@ -188,6 +188,16 @@ const changingPassword = ref(false); const invalidatingSessions = ref(false); const exporting = ref(false); const restoring = ref(false); +// Backup, export and restore walk the whole store, so they are slow BY DESIGN +// and the client's ordinary 30s default would cut them off mid-work. They are +// still bounded: rule 156 asks for a deadline, not a short one, and "no ceiling +// at all" is what leaves a restore that died server-side spinning forever. +const BULK_TRANSFER_TIMEOUT_MS = 10 * 60 * 1000; + +function bulkDeadline(): AbortSignal { + return AbortSignal.timeout(BULK_TRANSFER_TIMEOUT_MS); +} + // ── What's running (#3127 checklist 12) ───────────────────────────────── // Three states kept apart, because collapsing any two of them is the defect // this readout exists to remove: `null` + no error = not asked yet (the Config @@ -755,7 +765,7 @@ async function exportData(scope: "user" | "full") { exporting.value = true; try { const url = scope === "full" ? "/api/admin/backup" : "/api/admin/backup?scope=user"; - const res = await fetch(url); + const res = await fetch(url, { signal: bulkDeadline() }); if (!res.ok) { const body = await res.json().catch(() => ({ error: `Error ${res.status}` })); throw new Error((body as Record).error || `Error ${res.status}`); @@ -780,7 +790,7 @@ const exportingNotes = ref(false); async function exportNotes(format: "markdown" | "json") { exportingNotes.value = true; try { - const res = await fetch(`/api/export?format=${format}`); + const res = await fetch(`/api/export?format=${format}`, { signal: bulkDeadline() }); if (!res.ok) throw new Error(`Error ${res.status}`); const blob = await res.blob(); const ext = format === "json" ? "json" : "zip"; @@ -1009,6 +1019,7 @@ async function handleRestoreFile(event: Event) { method: "POST", headers: { "Content-Type": "application/json" }, body: JSON.stringify(data), + signal: bulkDeadline(), }); if (!res.ok) { const body = await res.json().catch(() => ({ error: `Error ${res.status}` })); diff --git a/tests/test_frontend_request_deadlines.py b/tests/test_frontend_request_deadlines.py new file mode 100644 index 0000000..65abd0d --- /dev/null +++ b/tests/test_frontend_request_deadlines.py @@ -0,0 +1,128 @@ +"""Every request the web UI makes has a deadline (rule 156). + +A source-inspection guard in the unit lane — there is no frontend test runner, +and this is a property of the source rather than of a rendered result, so +reading the source is the honest way to check it. + +WHY. `fetch`'s default is to wait as long as the browser will. That is not a +long timeout, it is the absence of one, and there is no state a surface can +render for "pending forever" that is not a lie — the spinner that never +resolves is indistinguishable from work still in progress. Rule 156 names +`fetch` specifically: + + When a library's default is "wait indefinitely" — `fetch`, most HTTP + clients, a bare `await` on a stream — supplying the deadline is part of + using it, not a hardening pass for later. + +Before this guard, no request in the app carried one. +""" +from __future__ import annotations + +import re +from pathlib import Path + +FRONTEND = Path(__file__).resolve().parents[1] / "frontend" / "src" +CLIENT = FRONTEND / "api" / "client.ts" + + +def _call_text(src: str, start: int) -> str: + """The source of one `fetch(...)` call, from its open paren to its close. + + Naive paren balancing. Adequate because every call site here passes an + object literal, and a construct complex enough to defeat it is one worth + looking at by hand anyway. + """ + depth = 0 + for i in range(start, len(src)): + if src[i] == "(": + depth += 1 + elif src[i] == ")": + depth -= 1 + if depth == 0: + return src[start:i + 1] + return src[start:] + + +def _fetch_calls() -> list[tuple[Path, str]]: + calls: list[tuple[Path, str]] = [] + for path in list(FRONTEND.rglob("*.ts")) + list(FRONTEND.rglob("*.vue")): + src = path.read_text() + for m in re.finditer(r"\bfetch\(", src): + calls.append((path, _call_text(src, m.end() - 1))) + return calls + + +def test_every_fetch_passes_a_signal(): + """No bare `fetch` anywhere in the frontend. + + Stated on the SIGNAL rather than on a timeout value, because the two + legitimate shapes here produce different values and only share this: an + ordinary call takes the client's default, a stream bounds its CONNECT and + then deliberately runs unbounded, and a bulk transfer passes minutes. What + they must all do is pass something. + """ + naked = [ + f"{path.relative_to(FRONTEND)}: {call[:70]}" + for path, call in _fetch_calls() + if "signal:" not in call + ] + assert not naked, ( + "these fetch calls carry no AbortSignal, so they wait forever " + "(rule 156):\n " + "\n ".join(naked) + ) + + +def test_the_client_applies_its_deadline_by_default(): + """The specific regression that would silently undo this. + + An earlier pass (#3329) made `timeoutMs` OPT-IN and used it at exactly one + call site, which left ~330 others waiting forever while the mechanism + looked present. Reverting to that shape would not fail the guard above — + every call would still reach `fetch` through `request()` — so the default + is pinned here separately. + + `??` is the operative character: `opts?.timeoutMs || DEFAULT` would treat + an explicit 0 as "use the default", and `opts?.timeoutMs` alone would + reinstate the opt-in bug. + """ + src = CLIENT.read_text() + assert "opts?.timeoutMs ?? DEFAULT_TIMEOUT_MS" in src, ( + "request() must fall back to DEFAULT_TIMEOUT_MS — without it the " + "deadline is opt-in again and almost nothing opts in" + ) + + +def test_a_timeout_arrives_as_the_error_shape_callers_already_handle(): + """Rule 156's second half: expiry surfaces as a NAMED failure. + + A raw `DOMException: TimeoutError` reaches `apiErrorMessage(e, fallback)` + as an object with no `body`, so every catch site in the app would print its + generic fallback and the timeout would be invisible in exactly the + situation it exists to expose. Rethrowing as `ApiError` is what makes the + other ~330 call sites report it without being edited. + """ + src = CLIENT.read_text() + assert 'e.name === "TimeoutError"' in src, ( + "request() must recognise a timeout specifically" + ) + assert "new ApiError(CLIENT_TIMEOUT_STATUS" in src, ( + "a timeout must be rethrown as ApiError so apiErrorMessage can read it" + ) + + +def test_a_deliberate_cancellation_is_not_reported_as_a_timeout(): + """Only `TimeoutError` is converted, never `AbortError`. + + A caller that cancelled its own request — a superseded search, a closed + stream — must not have that surfaced to the user as a server failure. The + guard is that the conversion is gated on the name, which the assertion + above already pins; this states the intent so the gate is not "simplified" + into catching every abort. + """ + src = CLIENT.read_text() + convert = src[src.index("async function request<"):] + convert = convert[:convert.index("\n}")] + assert "AbortError" not in convert, ( + "request() must not convert AbortError — a deliberate cancellation is " + "not a timeout" + ) From 8826be7a916dbca84945549ec2f0d7ea6eb2f5ae Mon Sep 17 00:00:00 2001 From: Bryan Van Deusen Date: Wed, 2 Sep 2026 16:55:22 -0400 Subject: [PATCH 13/19] =?UTF-8?q?feat(telemetry):=20rule=5Fusage=5Fevents?= =?UTF-8?q?=20=E2=80=94=20the=20table,=20the=20service,=20and=20a=20restor?= =?UTF-8?q?e=20that=20maps=20rule=20ids=20through=20the=20rule=20map=20(#3?= =?UTF-8?q?315)?= 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 From 111eef7e30d51c27bd7ebf04fff796c5a63f939b Mon Sep 17 00:00:00 2001 From: Bryan Van Deusen Date: Wed, 2 Sep 2026 16:56:54 -0400 Subject: [PATCH 14/19] fix(telemetry): the user-scoped rule_usage export read _rule_ids before it existed (#3315) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Ruff F821, twice, on the same two lines. The query was placed next to its note-usage counterpart — which reads `note_ids`, defined much earlier — while `_rule_ids` is not built until forty lines further down, beside the rules themselves. Moved to sit directly after the `rule_versions` query, which is the other consumer of that variable and the block whose scoping argument this one restates. Worth noting what did NOT catch this. The integration round-trip passed on the same commit: it drives `restore_full_backup` against a hand-built payload, so it exercises the import side and the full export, and never calls `export_user_backup` at all. A per-user export of any account owning a rule would have raised NameError at runtime. The lint lane found it because a static check does not need the path to be reachable by a test. The comment moved with it and got sharper, since the hazard is that the plausible column is the wrong one: `user_id` on a usage row is whoever the arm fired FOR, not who owns the rule, so scoping a per-user export by it would carry this user's surfacings of someone else's rule and drop the ones fired for someone else on theirs. Co-Authored-By: Claude Opus 5 (1M context) Claude-Session: https://claude.ai/code/session_01TcCs1CcQ1ormdnzSshKqvN --- src/scribe/services/backup.py | 16 ++++++++-------- 1 file changed, 8 insertions(+), 8 deletions(-) diff --git a/src/scribe/services/backup.py b/src/scribe/services/backup.py index 6491975..50e9f82 100644 --- a/src/scribe/services/backup.py +++ b/src/scribe/services/backup.py @@ -767,14 +767,6 @@ 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() @@ -826,6 +818,14 @@ async def export_user_backup(user_id: int) -> dict: select(RuleVersion).where(RuleVersion.rule_id.in_(_rule_ids)) .order_by(RuleVersion.rule_id, RuleVersion.id) )).scalars().all() if _rule_ids else [] + # Scoped through the RULE for the same reason the versions above are, + # and it is worth restating because the column that looks right is + # wrong: `user_id` here is whoever the arm fired FOR, not who owns the + # rule. Filtering on it would carry this user's surfacings of someone + # ELSE's rule and drop the ones fired for someone else on theirs. + rule_usage_events = (await session.execute( + select(RuleUsageEvent).where(RuleUsageEvent.rule_id.in_(_rule_ids)) + )).scalars().all() if _rule_ids else [] rule_relations = (await session.execute( select(RuleRelation).where( RuleRelation.from_rule_id.in_(_rule_ids), From 8f7f447fda5d2da181a604d18481ec93c7302065 Mon Sep 17 00:00:00 2001 From: Bryan Van Deusen Date: Wed, 2 Sep 2026 17:15:03 -0400 Subject: [PATCH 15/19] feat(telemetry): the rule arm records what it showed, and get_rule records the read (#3316) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Milestone 333 step 2. Step 1 built the table; a counter nobody calls reads zero and looks exactly like a surface nobody uses, which is #2663's shape. SURFACED — the standing-rule arm in build_write_path_hint, beside the record_retrieval it already made. Two tables, and the split is not arbitrary: retrieval_logs is one row per CALL keyed on the score distribution a threshold is tuned from; rule_usage_events is one row per RULE per event, the grain "was this hint ever acted on" needs and the grain a JSONB result_ids array cannot be indexed at. The comment there said rule ids had nowhere to go — that note_usage_events remaps ids on restore, so a rule id would return attached to whatever note took that number. Still true of the NOTE table, and precisely why step 1 built its own. Rewritten to say the gap is closed rather than leaving a stale rationale that would have someone re-derive the same dead end. Records `fresh`, i.e. AFTER exclude_rule_ids. A rule the session already holds was considered and not shown; counting it would inflate the denominator with claims the agent never saw, and the ratio would then fall for a reason that has nothing to do with whether hints land. PULLED — two doors, both after their access check so a refused read is not a pull. mcp_get_rule is the one that matters: the arm's own message ends "Read it with get_rule(N)", so that call is the exact action a landed hint produces. rest_rule carries the other prefix, and the prefix is load-bearing — "is this rule dead weight?" is served by any pull, "did that injected hint land?" by agent pulls only. NOT a pull: rule_history. It loads the rule for its title and its own output says "The current wording is on the rule itself — get_rule(N)", so counting it would credit a read of the history as a read of the rule and double-count anyone who then follows that pointer. list_always_on_rules and enter_project are likewise bulk resident loads, not somebody choosing to open one record. tests/test_rule_usage_wiring.py is cross-cutting on purpose: the surfaced end is in plugin_context, the pull end in two other modules, and "both ends meet" is a property no module-shaped file asserts. It covers the exclusion boundary, that a failing recorder cannot break the write, that a refused read records nothing, and two completeness guards — every door records, and the bulk loaders still do not. Co-Authored-By: Claude Opus 5 (1M context) Claude-Session: https://claude.ai/code/session_01TcCs1CcQ1ormdnzSshKqvN --- src/scribe/mcp/tools/rulebooks.py | 6 + src/scribe/routes/rulebooks.py | 6 + src/scribe/services/plugin_context.py | 23 ++- tests/test_rule_usage_wiring.py | 204 ++++++++++++++++++++++++++ 4 files changed, 235 insertions(+), 4 deletions(-) create mode 100644 tests/test_rule_usage_wiring.py diff --git a/src/scribe/mcp/tools/rulebooks.py b/src/scribe/mcp/tools/rulebooks.py index ca6a8c3..178cbbe 100644 --- a/src/scribe/mcp/tools/rulebooks.py +++ b/src/scribe/mcp/tools/rulebooks.py @@ -18,6 +18,7 @@ from scribe.mcp._context import current_user_id from scribe.services import dedup as dedup_svc from scribe.services import rulebooks as rulebooks_svc from scribe.services import trash as trash_svc +from scribe.services.rule_usage import record_rule_pulled # ── Rulebook CRUD ─────────────────────────────────────────────────────── @@ -288,6 +289,11 @@ async def get_rule(rule_id: int) -> dict: rule = await rulebooks_svc.get_rule(rule_id, uid) if rule is None: raise ValueError(f"rule {rule_id} not found") + # THE pull that matters. The write-path rule arm's own message ends "Read + # it with get_rule(N)", so this is the exact action the hint asks for and + # the only evidence that one landed. Recorded after the access check, so a + # refused read is not counted as a pull. + record_rule_pulled(user_id=uid, rule_id=int(rule.id), source="mcp_get_rule") return await rulebooks_svc.rule_detail(uid, rule) diff --git a/src/scribe/routes/rulebooks.py b/src/scribe/routes/rulebooks.py index 629ba1c..17ab59c 100644 --- a/src/scribe/routes/rulebooks.py +++ b/src/scribe/routes/rulebooks.py @@ -10,6 +10,7 @@ from quart import Blueprint, jsonify, request from scribe.auth import get_current_user_id, login_required import scribe.services.rulebooks as rulebooks_svc from scribe.services.trash import delete as trash_delete +from scribe.services.rule_usage import record_rule_pulled rulebooks_bp = Blueprint("rulebooks", __name__, url_prefix="/api") @@ -182,6 +183,11 @@ async def get_rule(rule_id: int): rule = await rulebooks_svc.get_rule(rule_id, uid) if rule is None: return jsonify({"error": "rule not found"}), 404 + # `rest_` rather than `mcp_`, and the prefix is load-bearing: "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. + # A person clicking through the rule list says nothing about the hint. + record_rule_pulled(user_id=uid, rule_id=int(rule.id), source="rest_rule") return jsonify(await rulebooks_svc.rule_detail(uid, rule)) diff --git a/src/scribe/services/plugin_context.py b/src/scribe/services/plugin_context.py index f6a5066..dcd2120 100644 --- a/src/scribe/services/plugin_context.py +++ b/src/scribe/services/plugin_context.py @@ -32,6 +32,7 @@ from scribe.services import snippets as snippets_svc from scribe.services.access import label_shared_items, owner_names_for from scribe.services.embeddings import semantic_search_notes, semantic_search_rules from scribe.services.note_usage import record_surfaced +from scribe.services.rule_usage import record_rule_surfaced from scribe.services.supersession import superseded_ids from scribe.services.retrieval_telemetry import record_retrieval from scribe.services.settings import get_setting @@ -1140,15 +1141,29 @@ async def build_write_path_hint( ) rule_ids.append(rule.id) if fresh: - # retrieval_logs, NOT note_usage_events: that table's ids are - # remapped on a backup restore, so a rule id there would return - # attached to whatever note took that number. This one is never - # restored, and `source` already separates the surfaces. + # TWO tables, and the split is not arbitrary. retrieval_logs is one + # row per CALL, keyed on the score distribution a threshold is + # tuned from. rule_usage_events is one row per RULE per event, + # which is the grain "was this hint ever acted on" needs and the + # grain a JSONB result_ids array cannot be indexed at. + # + # This comment used to say rule ids had nowhere to go — that + # note_usage_events remaps ids on restore, so a rule id there would + # return attached to whatever note took that number. That is still + # true of the NOTE table, and it is exactly why rule_usage_events + # is its own (milestone 333 step 1). The gap it described is closed. record_retrieval( user_id=user_id, source="write_path_rule", query=code or path, threshold=cfg["threshold"], limit=2, project_id=project_id, is_task=None, results=fresh, ) + # `rule_ids` is `fresh`, i.e. AFTER exclude_rule_ids. A rule the + # session already holds was considered and not shown, and counting + # it would inflate the denominator with claims the agent never saw + # — which reads as a precision problem this arm does not have. + record_rule_surfaced( + user_id=user_id, rule_ids=rule_ids, source="write_path_rule", + ) except Exception: logger.debug("write-path rule arm failed", exc_info=True) diff --git a/tests/test_rule_usage_wiring.py b/tests/test_rule_usage_wiring.py new file mode 100644 index 0000000..5efbcd2 --- /dev/null +++ b/tests/test_rule_usage_wiring.py @@ -0,0 +1,204 @@ +"""Both ends of the rule-usage loop are actually wired (milestone 333 step 2). + +Step 1 built the table and the service. A counter nobody calls reads zero and +looks exactly like a surface nobody uses — which is #2663's shape and the whole +reason this milestone exists. So this file is about the CALL SITES, not the +storage. + +Cross-cutting on purpose: the surfaced end lives in `plugin_context`, the pull +end in two different doors, and the property under test is that they meet. Split +across three module-shaped files, "both ends are wired" is a thing no single +test asserts. +""" +from contextlib import ExitStack +from pathlib import Path +from unittest.mock import AsyncMock, MagicMock, patch + +import pytest + +from tests.helpers import fake_rule + +# The MCP tool layer reads its caller from a ContextVar the HTTP transport sets +# per request; a unit test has no request, so it binds the caller itself. The +# arm tests do not need it — build_write_path_hint takes user_id directly — but +# the module-level mark is how every tool-layer test file in this repo opts in. +pytestmark = pytest.mark.usefixtures("_bind_user") + + +# ── The surfaced end ─────────────────────────────────────────────────── +# +# conftest's autouse `_no_rule_arm` stubs `semantic_search_rules` so unrelated +# plugin-context tests don't pull a real embedding model through this arm. Its +# docstring says a test that wants the arm live can re-patch it — that is what +# each of these does. + + +def _arm_patches(pc, hits, recorder): + """The minimum stubbing that lets the rule arm run and nothing else.""" + return ( + patch.object(pc, "get_writepath_config", + AsyncMock(return_value={"enabled": True, "threshold": 0.6, + "top_k": 3})), + patch.object(pc.snippets_svc, "list_snippets", AsyncMock(return_value=([], 0))), + patch.object(pc, "semantic_search_notes", AsyncMock(return_value=[])), + patch.object(pc, "semantic_search_rules", AsyncMock(return_value=hits)), + patch.object(pc, "record_retrieval", MagicMock()), + patch.object(pc, "record_surfaced", MagicMock()), + patch.object(pc, "record_rule_surfaced", recorder), + patch.object(pc, "owner_names_for", AsyncMock(return_value={})), + patch.object(pc, "concept_query", MagicMock(return_value="a deadline on a fetch")), + ) + + +async def _run_arm(hits, recorder, **kwargs): + from scribe.services import plugin_context as pc + with ExitStack() as stack: + for ctx in _arm_patches(pc, hits, recorder): + stack.enter_context(ctx) + return await pc.build_write_path_hint( + 1, "frontend/src/api/client.ts", code="x" * 400, **kwargs + ) + + +@pytest.mark.asyncio +async def test_the_arm_records_what_it_showed(): + """The claim being measured. Without this call the arm keeps producing + scores in retrieval_logs and no evidence that any hint was ever read.""" + rec = MagicMock() + hits = [(0.71, fake_rule(id=156, title="A wait with no deadline is a bug"))] + await _run_arm(hits, rec) + + assert rec.call_count == 1 + kw = rec.call_args.kwargs + assert kw["rule_ids"] == [156] + assert kw["source"] == "write_path_rule" + + +@pytest.mark.asyncio +async def test_a_rule_the_session_already_holds_is_not_counted_as_surfaced(): + """`exclude_rule_ids` drops what the session already has, and the recorded + set must be what was SHOWN, not what was considered. + + Counting the excluded ones would inflate the denominator with claims the + agent never saw — the ratio would fall for a reason that has nothing to do + with whether the hints landed, which is precisely the misreading this + milestone exists to prevent. + """ + rec = MagicMock() + hits = [ + (0.71, fake_rule(id=156, title="A wait with no deadline is a bug")), + (0.70, fake_rule(id=157, title="A loop re-arms in a finally")), + ] + await _run_arm(hits, rec, exclude_rule_ids=[157]) + + assert rec.call_args.kwargs["rule_ids"] == [156] + + +@pytest.mark.asyncio +async def test_nothing_is_recorded_when_every_hit_was_already_held(): + """No surfacing happened, so no surfacing is recorded. A zero-row batch + would still be a call, and a call that says "we showed nothing" pollutes + the count of times the arm spoke.""" + rec = MagicMock() + hits = [(0.71, fake_rule(id=156, title="A wait with no deadline is a bug"))] + await _run_arm(hits, rec, exclude_rule_ids=[156]) + + assert rec.call_count == 0 + + +@pytest.mark.asyncio +async def test_a_failing_recorder_does_not_break_the_write(): + """Telemetry must never take down the surface it observes. The arm is + already wrapped in a fail-open try/except; this pins that the new call is + INSIDE it rather than after.""" + rec = MagicMock(side_effect=RuntimeError("telemetry is down")) + hits = [(0.71, fake_rule(id=156, title="A wait with no deadline is a bug"))] + out = await _run_arm(hits, rec) + + assert "context" in out + + +# ── The pull end ─────────────────────────────────────────────────────── + + +@pytest.mark.asyncio +async def test_mcp_get_rule_records_an_agent_pull(): + """THE pull that matters: the arm's own message ends "Read it with + get_rule(N)", so this is the exact action a landed hint produces.""" + rec = MagicMock() + rule = fake_rule(id=156, title="A wait with no deadline is a bug") + with patch("scribe.mcp.tools.rulebooks.rulebooks_svc.get_rule", + AsyncMock(return_value=rule)), \ + patch("scribe.mcp.tools.rulebooks.rulebooks_svc.rule_detail", + AsyncMock(return_value={"id": 156})), \ + patch("scribe.mcp.tools.rulebooks.record_rule_pulled", rec): + from scribe.mcp.tools.rulebooks import get_rule + await get_rule(rule_id=156) + + assert rec.call_args.kwargs["rule_id"] == 156 + assert rec.call_args.kwargs["source"] == "mcp_get_rule" + + +@pytest.mark.asyncio +async def test_a_rule_that_cannot_be_read_is_not_a_pull(): + """Recorded after the access check. A refused read is not a pull, and + counting it would credit the arm for a hint nobody could open.""" + rec = MagicMock() + with patch("scribe.mcp.tools.rulebooks.rulebooks_svc.get_rule", + AsyncMock(return_value=None)), \ + patch("scribe.mcp.tools.rulebooks.record_rule_pulled", rec): + from scribe.mcp.tools.rulebooks import get_rule + with pytest.raises(ValueError): + await get_rule(rule_id=156) + + assert rec.call_count == 0 + + +# ── Completeness: every door, and only the doors ─────────────────────── + + +def _source_of(module_path: str) -> str: + return (Path(__file__).resolve().parents[1] / module_path).read_text() + + +def test_every_rule_detail_door_records_a_pull(): + """The task's own warning, made mechanical: miss a door and the ratio + reads low for a reason that is not about the rules. + + Source inspection rather than behaviour, because the REST door has no + live-HTTP harness in the unit lane (see test_routes_rulebooks.py's own + note). What it can still prove is that the handler names the recorder — + which is the thing that gets forgotten when a door is added. + """ + rest = _source_of("src/scribe/routes/rulebooks.py") + mcp = _source_of("src/scribe/mcp/tools/rulebooks.py") + assert 'source="rest_rule"' in rest, ( + "the REST rule-detail route does not record a pull" + ) + assert 'source="mcp_get_rule"' in mcp, ( + "the MCP get_rule tool does not record a pull" + ) + + +def test_the_bulk_loaders_are_not_counted_as_pulls(): + """`list_always_on_rules` and `enter_project` hand over every applicable + rule at once. That is delivery, not somebody choosing to open one record, + and counting it would swamp the signal with exactly the ambient surfacing + the ratio exists to distinguish from. + + Stated as a test because it is the tempting addition: both put rules in + front of an agent, so "surely those are pulls too" is the reading someone + arrives at without the argument. + """ + for path in ("src/scribe/mcp/tools/rulebooks.py", + "src/scribe/mcp/tools/projects.py"): + src = _source_of(path) + for door in ("list_always_on_rules", "enter_project"): + if f"async def {door}" not in src: + continue + body = src.split(f"async def {door}", 1)[1].split("\nasync def ", 1)[0] + assert "record_rule_pulled" not in body, ( + f"{door} records a pull. It is a bulk resident load — every " + "applicable rule at once — so counting it would drown the " + "surfaced:pulled ratio in ambient delivery." + ) From 70761b16d9af6858f8a078d5f32f3b9dbe6d062d Mon Sep 17 00:00:00 2001 From: Bryan Van Deusen Date: Wed, 2 Sep 2026 17:17:59 -0400 Subject: [PATCH 16/19] =?UTF-8?q?test(telemetry):=20the=20rule-arm=20fixtu?= =?UTF-8?q?re=20never=20reached=20the=20arm=20=E2=80=94=20it=20returned=20?= =?UTF-8?q?at=20the=20guard=20(#3316)?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit The product code was right; the test was wrong, and wrong in a way that made two assertions fail and two others pass vacuously. `build_write_path_hint` returns early when a write matched nothing at all — no staleness, no synced record, no prior-art menu, no shape signal. The rule arm sits deliberately on the FAR side of that guard, because it runs a semantic search and hoisting it would mean an embedding query on every write in the session. My fixture stubbed every other arm to empty, so it hit the early return and the rule arm never ran: `record_rule_surfaced` was called zero times, and "the recorder was not called" is also what two of the four tests were asserting for their own reasons. The fixture now supplies one prior-art hit — 0.72 against a 0.6 threshold, so it clears the band and the top_k slice — with a comment saying the hit is the arm's precondition rather than scenery. And the gate got its own test, because the fixture now depends on it: a write matching nothing must NOT reach the arm. Without that, a future change to the guard would make every assertion in this file pass without exercising anything. #3311 is explicit that the gate stays until the arm's precision is fixed, so the test says to go read that issue rather than update the assertion. Co-Authored-By: Claude Opus 5 (1M context) Claude-Session: https://claude.ai/code/session_01TcCs1CcQ1ormdnzSshKqvN --- tests/test_rule_usage_wiring.py | 44 +++++++++++++++++++++++++++++---- 1 file changed, 39 insertions(+), 5 deletions(-) diff --git a/tests/test_rule_usage_wiring.py b/tests/test_rule_usage_wiring.py index 5efbcd2..c304565 100644 --- a/tests/test_rule_usage_wiring.py +++ b/tests/test_rule_usage_wiring.py @@ -16,7 +16,7 @@ from unittest.mock import AsyncMock, MagicMock, patch import pytest -from tests.helpers import fake_rule +from tests.helpers import fake_note, fake_rule # The MCP tool layer reads its caller from a ContextVar the HTTP transport sets # per request; a unit test has no request, so it binds the caller itself. The @@ -33,14 +33,30 @@ pytestmark = pytest.mark.usefixtures("_bind_user") # each of these does. -def _arm_patches(pc, hits, recorder): +# The write-path hint returns early when a write matched nothing at all — no +# staleness, no synced record, no prior-art menu, no shape signal. The rule arm +# sits deliberately on the FAR side of that guard, because it runs a semantic +# search and moving it above would mean an embedding query on every write in +# the session (#3311's closing note, and the reason its gating is a separate +# question from precision). +# +# So a fixture that stubs every other arm to empty never reaches the rule arm +# at all — which is what the first run of this file did. The note hit below is +# not decoration: it is the condition the arm requires in order to fire. +_PRIOR_ART = [(0.72, fake_note(id=9, title="debounce helper", user_id=1, + note_type="snippet"))] + + +def _arm_patches(pc, hits, recorder, prior_art=None): """The minimum stubbing that lets the rule arm run and nothing else.""" return ( patch.object(pc, "get_writepath_config", AsyncMock(return_value={"enabled": True, "threshold": 0.6, "top_k": 3})), patch.object(pc.snippets_svc, "list_snippets", AsyncMock(return_value=([], 0))), - patch.object(pc, "semantic_search_notes", AsyncMock(return_value=[])), + patch.object(pc, "semantic_search_notes", + AsyncMock(return_value=_PRIOR_ART if prior_art is None + else prior_art)), patch.object(pc, "semantic_search_rules", AsyncMock(return_value=hits)), patch.object(pc, "record_retrieval", MagicMock()), patch.object(pc, "record_surfaced", MagicMock()), @@ -50,10 +66,10 @@ def _arm_patches(pc, hits, recorder): ) -async def _run_arm(hits, recorder, **kwargs): +async def _run_arm(hits, recorder, prior_art=None, **kwargs): from scribe.services import plugin_context as pc with ExitStack() as stack: - for ctx in _arm_patches(pc, hits, recorder): + for ctx in _arm_patches(pc, hits, recorder, prior_art): stack.enter_context(ctx) return await pc.build_write_path_hint( 1, "frontend/src/api/client.ts", code="x" * 400, **kwargs @@ -106,6 +122,24 @@ async def test_nothing_is_recorded_when_every_hit_was_already_held(): assert rec.call_count == 0 +@pytest.mark.asyncio +async def test_the_arm_does_not_fire_on_a_write_that_matched_nothing(): + """The gate, pinned — because the fixture above now depends on it and a + silent change would make every other test here pass vacuously. + + A write matching no prior art returns before the rule arm runs. That is + deliberate: the arm is a semantic search, and ungating it means an + embedding query on every write in the session. #3311 is explicit that the + gate stays until the arm's precision is fixed, so this failing is a signal + to go read that issue rather than to update the assertion. + """ + rec = MagicMock() + hits = [(0.71, fake_rule(id=156, title="A wait with no deadline is a bug"))] + await _run_arm(hits, rec, prior_art=[]) + + assert rec.call_count == 0 + + @pytest.mark.asyncio async def test_a_failing_recorder_does_not_break_the_write(): """Telemetry must never take down the surface it observes. The arm is From 8901c904a91fa28ab4f7e469c39d94670b8fb5bc Mon Sep 17 00:00:00 2001 From: Bryan Van Deusen Date: Wed, 2 Sep 2026 17:25:11 -0400 Subject: [PATCH 17/19] feat(telemetry): retrieval_telemetry reports rule pull-through where it reported nothing (#3317) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Milestone 333 step 3, the read half. Steps 1 and 2 built the table and filled it; until now nothing read it, and `usage` — sourced entirely from note_usage_events — described notes only while `sources` happily listed a write_path_rule row above it. A reader takes the aggregate as covering everything named above it. It did not. A SEPARATE `rule_usage` BLOCK, not folded into `usage`. Two reasons, and the second is the one that bites: the corpora differ by orders of magnitude, so a blended ratio would be the note ratio with noise on it and the rule arm would stay invisible inside it; and `usage` is what existing callers already read and compare across windows, so silently changing what it counts would move a number nobody was told had changed meaning. There is a test asserting rule events stay out of the note block. No `ambient` key, unlike the twin. Nothing surfaces a rule un-ranked — list_always_on_rules and enter_project hand rules over wholesale but emit no event — so there is no ambient class to subtract. The absence is a fact about the data, not an oversight, and it returns when a bulk loader starts emitting. Guarded separately, like `by_source`. This table did not exist a commit ago, and an instance running upgraded code against un-migrated schema would otherwise take down two readouts that work perfectly in order to report a third that cannot. On failure the FLAG is added and the SHAPE is kept — a caller must not have to choose between crashing on a missing key and quietly rendering zeros it has no right to. `pull_through` is None rather than 0.0 on an empty window, matching the note block. A ratio of zero asserts "rules were shown and none opened"; with an empty numerator and denominator that is a claim the data does not support, and it is the reading that would make a brand-new install look like a broken one. Also fixed, from #3311: the rule arm never timed its search, so it was the one source in the readout reporting a null p90_duration_ms — a gap that reads as "this surface is somehow not measurable" rather than "nobody passed the number". Both docstrings updated in the same change. The tool's is the agent-facing contract (rule 119) and it explicitly said rule surfacings were absent and had "no usage counter at all". Leaving that would have had a reader conclude the arm has zero pull-through rather than a separate one. Tests are integration for the reason the block above them is: real GROUP BYs and count(distinct) against a table a commit old, in a module whose one production outage was a SQL shape the database rejected inside a broad except. A mock would agree with whatever the code does, including nothing. Co-Authored-By: Claude Opus 5 (1M context) Claude-Session: https://claude.ai/code/session_01TcCs1CcQ1ormdnzSshKqvN --- src/scribe/mcp/tools/search.py | 40 ++++-- src/scribe/services/plugin_context.py | 8 +- src/scribe/services/retrieval_telemetry.py | 124 ++++++++++++++++- tests/test_services_retrieval_telemetry.py | 152 +++++++++++++++++++++ 4 files changed, 311 insertions(+), 13 deletions(-) diff --git a/src/scribe/mcp/tools/search.py b/src/scribe/mcp/tools/search.py index 410c308..e00730f 100644 --- a/src/scribe/mcp/tools/search.py +++ b/src/scribe/mcp/tools/search.py @@ -158,7 +158,7 @@ async def retrieval_telemetry(days: int = 30) -> dict: hand-probing the live instance, which is how the last such decision had to be made. - Two readouts, from the two tables built for them: + Three readouts, from the three tables built for them: `sources` — per retrieval surface (`auto_inject`, `write_path`, `mcp_search`, …), from `retrieval_logs`: `calls`, `zero_result_calls`, @@ -168,7 +168,7 @@ async def retrieval_telemetry(days: int = 30) -> dict: against `calls`, with the spread beside it: a surface that clears its bar on nearly every call is either well-tuned or too loose, and p10 says which. - `usage` — from `note_usage_events`, at the per-note grain + `usage` — NOTES ONLY, from `note_usage_events`, at the per-note grain `retrieval_logs` cannot be indexed at: `surfaced` (ranked surfacings — a scored surface CHOSE the record), `ambient` (the rest), `pulled` split into `pulled_by_agent` / `pulled_by_human`, the distinct-note counts, and @@ -190,14 +190,34 @@ async def retrieval_telemetry(days: int = 30) -> dict: about a record nothing chose). Read it as: of the distinct notes THIS surface put in front of the agent, how many did the agent then open? - Two limits on it, both deliberate. It is an UPPER BOUND per surface: a pull - records the door it came through, not the surface that led there, so a note - surfaced by two surfaces and opened once counts for both — attribution - would need the session identity #2085 declined to invent. And RULE - surfacings are absent: `write_path_rule` appears in `sources` with its - scores but has no usage counter at all, so it has no row here (#3311). - `by_source_failed: true` means that one query failed while the rest of the - readout stood. +It is an UPPER BOUND per surface: a pull records the door it came + through, not the surface that led there, so a note surfaced by two surfaces + and opened once counts for both — attribution would need the session + identity #2085 declined to invent. `by_source_failed: true` means that one + query failed while the rest of the readout stood. + + `rule_usage` — the same question for RULES, from `rule_usage_events`: + `surfaced`, `pulled` split into `pulled_by_agent` / `pulled_by_human`, the + distinct-rule counts, and `pull_through` on the same definition (agent + pulls over surfacings). + + 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 + blended ratio would be the note ratio with noise on it and would hide the + rule arm entirely. It also has no `ambient` key, because nothing surfaces a + rule un-ranked: `list_always_on_rules` and `enter_project` hand over rules + wholesale but emit no event, so there is no ambient class to separate. + + Read it against `sources["write_path_rule"]`. That surface has never once + declined to fire, and until this block existed there was no way to tell a + well-tuned arm from a bar it cannot fail to clear (#3311). `pull_through` + is the number that tells them apart. + + `rule_usage_failed: true` means that read failed while the rest of the + readout stood. The counts are still present so a caller can render, but + they are zeros meaning "could not find out", not "nothing happened" — do + not report a pull-through from a block carrying that flag. Scoped to your own telemetry — a retrieval log records what your agent asked for, query text included, and is not a shared record kind. diff --git a/src/scribe/services/plugin_context.py b/src/scribe/services/plugin_context.py index dcd2120..9122417 100644 --- a/src/scribe/services/plugin_context.py +++ b/src/scribe/services/plugin_context.py @@ -1126,10 +1126,16 @@ async def build_write_path_hint( rule_ids: list[int] = [] try: already = set(exclude_rule_ids or []) + # Timed like the notes arm above. Without this the rule row was the one + # source in the whole readout reporting a null p90_duration_ms (#3311) + # — a gap that reads as "this surface is somehow not measurable" rather + # than "nobody passed the number". + rule_t0 = time.perf_counter() hits = await semantic_search_rules( user_id, code or path, limit=2, threshold=cfg["threshold"], tier="conditional", ) + rule_ms = (time.perf_counter() - rule_t0) * 1000.0 fresh = [(score, rule) for score, rule in hits if rule.id not in already] for _score, rule in fresh: trigger = (rule.when_to_apply or "").strip() @@ -1155,7 +1161,7 @@ async def build_write_path_hint( record_retrieval( user_id=user_id, source="write_path_rule", query=code or path, threshold=cfg["threshold"], limit=2, project_id=project_id, - is_task=None, results=fresh, + is_task=None, results=fresh, duration_ms=rule_ms, ) # `rule_ids` is `fresh`, i.e. AFTER exclude_rule_ids. A rule the # session already holds was considered and not shown, and counting diff --git a/src/scribe/services/retrieval_telemetry.py b/src/scribe/services/retrieval_telemetry.py index 1377ecd..af27dda 100644 --- a/src/scribe/services/retrieval_telemetry.py +++ b/src/scribe/services/retrieval_telemetry.py @@ -27,6 +27,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 PULLED as RULE_PULLED +from scribe.models.rule_usage import SURFACED as RULE_SURFACED +from scribe.models.rule_usage import RuleUsageEvent from scribe.models.retrieval_log import RetrievalLog logger = logging.getLogger(__name__) @@ -190,8 +193,10 @@ def _round(v, places: int = 4): async def retrieval_summary(user_id: int | None, *, days: int = 30) -> dict: """What the retrieval telemetry says, per surface, over a window. - Two aggregates side by side, each read from the table built for it — NOT a - join. `NoteUsageEvent`'s own docstring is explicit that the two are + Three aggregates side by side, each read from the table built for it — NOT + a join. `usage` is notes, `rule_usage` is rules, and they stay apart + because a few dozen eligible rules blended into thousands of notes is the + note ratio with noise on it (milestone 333). `NoteUsageEvent`'s own docstring is explicit that the two are complements ("RetrievalLog tunes the threshold, this tunes the corpus") and that RetrievalLog's JSONB `result_ids` "can't be indexed at" the per-note grain. So the score distribution comes from `retrieval_logs` on its indexed @@ -220,6 +225,7 @@ async def retrieval_summary(user_id: int | None, *, days: int = 30) -> dict: "since": iso(since), "sources": {}, "usage": {}, + "rule_usage": {}, "read_failed": False, } @@ -240,6 +246,8 @@ async def retrieval_summary(user_id: int | None, *, days: int = 30) -> dict: # Assigned inside the try below; named here so the readout can tell # "this query failed" from "this window has no rows" (#2663). by_source_rows = None + rule_rows = None + distinct_rules_surfaced = distinct_rules_pulled = 0 try: async with async_session() as session: @@ -391,6 +399,63 @@ async def retrieval_summary(user_id: int | None, *, days: int = 30) -> dict: except Exception: logger.warning("per-source pull-through read failed", exc_info=True) by_source_rows = None + + # Rules, at their own grain and in their own block (milestone 333). + # + # Guarded separately from the reads above for the reason `by_source` + # is: this table is NEW, and an instance running upgraded code + # against un-migrated schema would otherwise take down two readouts + # that work perfectly in order to report a third that cannot. + # + # The queries themselves are the note block's shapes, not novel + # ones — a group-by on two indexed columns and two count(distinct). + # The distinct counts need their own queries for the same reason + # the note ones do: count(distinct rule_id) per group cannot be + # summed across groups without double-counting a rule two sources + # both touched. + try: + rule_rows = ( + await session.execute( + select( + RuleUsageEvent.event, + RuleUsageEvent.source, + func.count().label("n"), + ) + .where( + RuleUsageEvent.created_at >= since, + RuleUsageEvent.user_id == user_id, + ) + .group_by(RuleUsageEvent.event, RuleUsageEvent.source) + ) + ).all() + # No AMBIENT exclusion here, unlike the note twin: nothing + # surfaces a rule un-ranked yet. `list_always_on_rules` and + # `enter_project` deliver rules wholesale but emit no event, so + # there is no ambient class to subtract (milestone 333 step 1). + distinct_rules_surfaced = ( + await session.execute( + select(func.count(func.distinct(RuleUsageEvent.rule_id))) + .where( + RuleUsageEvent.created_at >= since, + RuleUsageEvent.user_id == user_id, + RuleUsageEvent.event == RULE_SURFACED, + ) + ) + ).scalar_one() + distinct_rules_pulled = ( + await session.execute( + select(func.count(func.distinct(RuleUsageEvent.rule_id))) + .where( + RuleUsageEvent.created_at >= since, + RuleUsageEvent.user_id == user_id, + RuleUsageEvent.event == RULE_PULLED, + ) + ) + ).scalar_one() + except Exception: + logger.warning("rule usage read failed", exc_info=True) + rule_rows = None + distinct_rules_surfaced = distinct_rules_pulled = 0 except Exception: logger.warning("retrieval summary read failed", exc_info=True) out["read_failed"] = True @@ -468,4 +533,59 @@ async def retrieval_summary(user_id: int | None, *, days: int = 30) -> dict: usage["by_source"] = by_source out["usage"] = usage + + # ── Rules, deliberately a SEPARATE block ──────────────────────────── + # + # Not folded into `usage`, for two reasons and the second is the one that + # bites. The corpora differ by orders of magnitude — a few dozen eligible + # rules against thousands of notes — so one blended ratio would be the note + # ratio with a little noise on it, and the rule arm's own behaviour would + # be undetectable inside it. And `usage` is what existing callers already + # read: silently changing what it counts would move a number people have + # been comparing across windows, without telling them it now measures + # something else. + # + # No `ambient` key, unlike its twin. Nothing surfaces a rule un-ranked yet; + # the absence is a fact about the data rather than an oversight, and it + # returns the moment a bulk loader starts emitting. + rule_usage = { + "surfaced": 0, + "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), + } + if rule_rows is None: + # The FLAG is added, the shape is kept — matching `by_source_failed` + # one block up. A caller that renders this must not have to choose + # between crashing on a missing key and quietly showing zeros it has no + # right to: the keys let it render, and the flag tells it the zeros are + # "we could not find out" rather than "nothing happened" (#2663). + rule_usage["rule_usage_failed"] = True + else: + for event, source, n in rule_rows: + n = int(n) + if event == RULE_SURFACED: + rule_usage["surfaced"] += n + elif event == RULE_PULLED: + rule_usage["pulled"] += n + # Same split, and it carries MORE weight here than for notes. + # The arm's whole claim is "this rule may apply to what you are + # writing", and only an agent opening it says the claim landed. + # A person browsing the rule list says nothing about the hint. + if source.startswith("mcp_"): + rule_usage["pulled_by_agent"] += n + else: + rule_usage["pulled_by_human"] += 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 + # empty numerator AND denominator that is a claim the data does not + # support, and it is the reading that would make a brand-new install look + # like a broken one. + rule_usage["pull_through"] = ( + round(rule_usage["pulled_by_agent"] / rule_usage["surfaced"], 4) + if rule_usage["surfaced"] else None + ) + out["rule_usage"] = rule_usage + return out diff --git a/tests/test_services_retrieval_telemetry.py b/tests/test_services_retrieval_telemetry.py index df6ef87..e5b529b 100644 --- a/tests/test_services_retrieval_telemetry.py +++ b/tests/test_services_retrieval_telemetry.py @@ -359,3 +359,155 @@ async def test_the_agent_pull_filter_does_not_treat_its_underscore_as_a_wildcard async with async_session() as s: await s.execute(delete(NoteUsageEvent).where(NoteUsageEvent.user_id == UID)) await s.commit() + + +# ─── rule usage (milestone 333 step 3) ─────────────────────────────────────── +# Integration, for the same reason the block above is: these are real GROUP BYs +# and count(distinct) against a table that did not exist a commit ago, in a +# module whose one production outage (#2663) was a SQL shape the database +# rejected inside a broad except. A mock would agree with whatever the code +# does, including nothing. + + +async def _rule_events(uid, rows): + """Write (event, source) pairs for one rule and hand back a cleanup.""" + from sqlalchemy import delete + + from scribe.models import async_session + from scribe.models.rule_usage import RuleUsageEvent + + async with async_session() as s: + s.add_all([ + RuleUsageEvent(user_id=uid, rule_id=rid, event=ev, source=src) + for rid, ev, src in rows + ]) + await s.commit() + + async def cleanup(): + async with async_session() as s: + await s.execute( + delete(RuleUsageEvent).where(RuleUsageEvent.user_id == uid) + ) + await s.commit() + + return cleanup + + +@pytest.mark.integration +@pytest.mark.asyncio +async def test_rule_usage_is_a_coherent_zero_on_a_fresh_install(_dispose_engine): + """Every rule in an existing install predates this table, so "no events" is + the normal state for a while. It must read as zero, not as a missing key + and not as a failure — the same "no rows" / "read broke" distinction the + rest of this readout keeps (#2663). + + `pull_through` is None rather than 0.0, matching the note block: a ratio of + zero asserts "rules were shown and none opened", which with an empty + numerator AND denominator is a claim the data does not support. + """ + from scribe.services.retrieval_telemetry import retrieval_summary + + out = await retrieval_summary(990010, days=30) + assert out["read_failed"] is False + assert "rule_usage_failed" not in out["rule_usage"] + assert out["rule_usage"]["surfaced"] == 0 + assert out["rule_usage"]["pulled"] == 0 + assert out["rule_usage"]["distinct_rules_surfaced"] == 0 + assert out["rule_usage"]["pull_through"] is None + + +@pytest.mark.integration +@pytest.mark.asyncio +async def test_an_agent_reading_a_surfaced_rule_is_what_moves_the_ratio(_dispose_engine): + """The whole point of the milestone: the arm can now be told apart from a + bar it cannot fail to clear.""" + from scribe.services.retrieval_telemetry import retrieval_summary + + cleanup = await _rule_events(990011, [ + (5001, "surfaced", "write_path_rule"), + (5002, "surfaced", "write_path_rule"), + (5001, "pulled", "mcp_get_rule"), + ]) + try: + ru = (await retrieval_summary(990011, days=30))["rule_usage"] + assert ru["surfaced"] == 2 + assert ru["pulled"] == 1 + assert ru["pulled_by_agent"] == 1 + assert ru["pulled_by_human"] == 0 + assert ru["distinct_rules_surfaced"] == 2 + assert ru["distinct_rules_pulled"] == 1 + assert ru["pull_through"] == 0.5 + finally: + await cleanup() + + +@pytest.mark.integration +@pytest.mark.asyncio +async def test_a_person_browsing_the_rule_list_does_not_move_the_ratio(_dispose_engine): + """The mcp_/rest_ split, and it carries more weight here than for notes. + + The arm's claim is "this rule may apply to what you are writing". Only an + agent opening it says that claim landed; a person clicking through the rule + list in the web UI says nothing about the hint. Both are still counted in + `pulled`, so "is this rule dead weight?" stays answerable. + """ + from scribe.services.retrieval_telemetry import retrieval_summary + + cleanup = await _rule_events(990012, [ + (5003, "surfaced", "write_path_rule"), + (5003, "pulled", "rest_rule"), + ]) + try: + ru = (await retrieval_summary(990012, days=30))["rule_usage"] + assert ru["pulled"] == 1 + assert ru["pulled_by_human"] == 1 + assert ru["pulled_by_agent"] == 0 + # Surfaced once, opened by nobody who matters to this question. + assert ru["pull_through"] == 0.0 + finally: + await cleanup() + + +@pytest.mark.integration +@pytest.mark.asyncio +async def test_rule_events_stay_out_of_the_note_block(_dispose_engine): + """The separation, asserted rather than assumed. + + `usage` is what existing callers already read and compare across windows. + If rule events leaked into it, that number would move for a reason nobody + was told about — and the rule arm would still be invisible, because a few + dozen rules against thousands of notes is noise on the note ratio. + """ + from scribe.services.retrieval_telemetry import retrieval_summary + + cleanup = await _rule_events(990013, [ + (5004, "surfaced", "write_path_rule"), + (5004, "pulled", "mcp_get_rule"), + ]) + try: + out = await retrieval_summary(990013, days=30) + assert out["rule_usage"]["surfaced"] == 1 + # The note block saw none of it. + assert out["usage"]["surfaced"] == 0 + assert out["usage"]["pulled"] == 0 + assert out["usage"]["pull_through"] is None + finally: + await cleanup() + + +@pytest.mark.integration +@pytest.mark.asyncio +async def test_rule_usage_sees_only_its_own_users_events(_dispose_engine): + """Same access rule as the rest of the readout — the owner filter IS the + rule for telemetry, which is not a shared record kind.""" + from scribe.services.retrieval_telemetry import retrieval_summary + + cleanup = await _rule_events(990014, [ + (5005, "surfaced", "write_path_rule"), + (5005, "pulled", "mcp_get_rule"), + ]) + try: + assert (await retrieval_summary(990015, days=30))["rule_usage"]["surfaced"] == 0 + assert (await retrieval_summary(990014, days=30))["rule_usage"]["surfaced"] == 1 + finally: + await cleanup() From 238510080ea89ee3c0172bfafcda980ad6c856fc Mon Sep 17 00:00:00 2001 From: Bryan Van Deusen Date: Wed, 2 Sep 2026 18:05:00 -0400 Subject: [PATCH 18/19] feat(retrieval): the standing-rule arm gets its own bar, and asks for one rule not two (#3318) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Milestone 333 step 4 — the split #2223 made one surface down, now made for the third corpus. The arm inherited WRITEPATH_DEFAULT_THRESHOLD = 0.68, a number measured against code-vs-note-PROSE and never re-derived for code-vs-RULE-TEXT. THE DEFAULT IS ARGUED STRUCTURALLY, NOT READ OFF A HISTOGRAM (rule 115). Two facts hold on any install, including one with six rules and no telemetry: - The eligible corpus is tiny — conditional rules only, a handful to a few dozen against thousands of notes. A top-k over forty candidates always returns something, so "the best match cleared the bar" stops meaning "a good match exists". A bar calibrated for best-of-thousands is cleared by best-of-forty as arithmetic, not relevance. - Rules are short imperative technical English, far more homogeneous than note prose. #2223 put the code-vs-prose floor at 0.55-0.63 and set 0.68 above it; a more homogeneous corpus has a HIGHER floor, so 0.68 is not merely inherited, it sits below where this corpus's noise lives. 0.72 errs deliberately toward silence on an asymmetry that is also structural: this hint fires on EVERY write. A missed rule is recoverable — it is still in Scribe and the agent can search it. A hint that cries wolf is not: it teaches the reader to skip the whole block, and the true positives go with it. The arm's own comment already said "noise on a hint that fires on every write is how a hint gets ignored". Pinned as an INEQUALITY, not a value: test_the_rule_bar_defaults_above_the_code_bar asserts RULEHINT > WRITEPATH, so tuning the number stays free while inverting the relationship — which would silently reinstate #3311 — does not. RULEHINT_LIMIT = 1, and deliberately not a knob. With a corpus this small, k=2 means the second line is almost always the second-best noise wearing the same confident framing as the first; halving k halves that regardless of the bar. It stays a constant because it is a decision about how loud one hint may be, not a per-install tuning question — and a knob nobody turns only adds a way to misconfigure the surface. Reachable from Settings, no restart (rule 25), with copy that says which way to move it and points at retrieval_telemetry's rule pull-through — which step 3 made readable — to tell "arriving unread" from "never arrived". Every config stand-in in the suite gained the key, not just the one that noticed. The arm reads `rule_threshold` while BUILDING its search arguments, so a missing key raises inside its fail-open except and turns the arm into a silent no-op — indistinguishable from it running and finding nothing. That is the same vacuous-pass shape that bit step 2, one layer down (rule 33). Co-Authored-By: Claude Opus 5 (1M context) Claude-Session: https://claude.ai/code/session_01TcCs1CcQ1ormdnzSshKqvN --- frontend/src/views/SettingsView.vue | 36 +++++++++++++ src/scribe/services/plugin_context.py | 70 ++++++++++++++++++++++-- tests/test_note_usage.py | 3 +- tests/test_rule_usage_wiring.py | 48 +++++++++++++++-- tests/test_services_plugin_context.py | 6 ++- tests/test_write_path_trigger.py | 76 ++++++++++++++++++++++++++- 6 files changed, 227 insertions(+), 12 deletions(-) diff --git a/frontend/src/views/SettingsView.vue b/frontend/src/views/SettingsView.vue index 715c222..60b94d4 100644 --- a/frontend/src/views/SettingsView.vue +++ b/frontend/src/views/SettingsView.vue @@ -86,6 +86,7 @@ const kbWritePathEnabled = ref(true); // code embeddings sit on a much higher similarity floor than prose, so 0.55 let // unrelated code through (#2223). Shares top-k, not the threshold. const kbWritePathThreshold = ref("0.68"); +const kbRuleHintThreshold = ref("0.72"); // Near-duplicate report floors, one per record kind (services/dedup.py). // Snippets are single-chunk, so their floor sits below the 0.90 write-time // gate and catches what it lets through. Notes/tasks are scored at chunk @@ -148,12 +149,17 @@ async function saveKbInject() { // Same `|| default` reasoning: falling back to 0 would surface every // snippet in the corpus on every edit, which is the failure this knob fixes. const wpT = Math.min(1, Math.max(0, Number(kbWritePathThreshold.value) || 0.68)); + // Same `|| default` reasoning again, and it bites harder here: a rule hint + // fires on every write, so a fallback of 0 would attach a standing rule to + // every edit in the session. + const rhT = Math.min(1, Math.max(0, Number(kbRuleHintThreshold.value) || 0.72)); kbInjectThreshold.value = String(t); kbInjectTopK.value = String(k); kbDupThresholdSnippet.value = String(dupSnip); kbDupThresholdNote.value = String(dupNote); kbDupThresholdTask.value = String(dupTask); kbWritePathThreshold.value = String(wpT); + kbRuleHintThreshold.value = String(rhT); savingKbInject.value = true; kbInjectSaved.value = false; try { @@ -166,6 +172,10 @@ async function saveKbInject() { // measurements that split them. kb_writepath_enabled: kbWritePathEnabled.value ? 'true' : 'false', kb_writepath_threshold: String(wpT), + // A THIRD corpus with a third bar — see RULEHINT_DEFAULT_THRESHOLD + // in services/plugin_context.py for why rules cannot share the + // code threshold any more than code could share the prose one. + kb_rulehint_threshold: String(rhT), kb_duplicate_threshold_snippet: String(dupSnip), kb_duplicate_threshold_note: String(dupNote), kb_duplicate_threshold_task: String(dupTask), @@ -611,6 +621,9 @@ onMounted(async () => { kbInjectTopK.value = allSettings.kb_autoinject_top_k; } kbWritePathEnabled.value = allSettings.kb_writepath_enabled !== "false"; + if (allSettings.kb_rulehint_threshold !== undefined) { + kbRuleHintThreshold.value = allSettings.kb_rulehint_threshold; + } if (allSettings.kb_writepath_threshold !== undefined) { kbWritePathThreshold.value = allSettings.kb_writepath_threshold; } @@ -1456,6 +1469,29 @@ async function deleteUser(userId: number) { location, not by resemblance.

+
+ + +

+ The same hint can mention a standing rule whose trigger resembles what's + being written — only rules marked conditional, since always-on + ones are already loaded. Stricter again than the threshold above, because + there are far fewer rules than snippets: with a small set, something + always ranks first, so the bar has to carry more of the judgement. + Raise it if rules keep arriving unread; lower it if a rule you needed + never showed up. Settings → check the pull-through in + retrieval_telemetry to see which is happening. +

+
diff --git a/frontend/src/components/rules/RuleListPane.vue b/frontend/src/components/rules/RuleListPane.vue index 6c2a662..32d08f7 100644 --- a/frontend/src/components/rules/RuleListPane.vue +++ b/frontend/src/components/rules/RuleListPane.vue @@ -1,5 +1,16 @@