From 90696c2b541c44fca5203e8bc39abcd15279b986 Mon Sep 17 00:00:00 2001 From: GeneAI Date: Mon, 24 Aug 2026 15:20:23 -0400 Subject: [PATCH 1/3] =?UTF-8?q?feat(telemetry):=20per-stage=20form=20event?= =?UTF-8?q?s=20joinable=20on=20a=20deterministic=20form=5Fid=20=E2=80=94?= =?UTF-8?q?=200.8.0?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Chair-approved 2026-08-24 (route "measure first"): the log had only form_surface and a bare form_submitted, so per-stage latency was not computable. This adds the lifecycle: - FormSchema.form_id: explicit "form_id" definition key wins (validated token), else a deterministic content hash — render and collect re-parse the same dict, so both land on the same id with nothing threaded through the agent. - form_build (source: dict|template: — the V7 adoption signal), form_rendered (duration_ms, html_bytes), form_submitted(form_id), and form_id on form_surface records. - stage_latency(): per-stage p50/p95 read-back (render cost + first-render→first-submission wait per form_id) with the same skip-don't-raise read contract as surface_mix. - Shared _append write path; log_submission stays zero-arg-compatible for pre-0.8 callers (attune-ai <= 14.1.0). Version 0.8.0 across pyproject + plugin + marketplace manifests. Co-Authored-By: Claude Fable 5 --- .claude-plugin/marketplace.json | 4 +- CHANGELOG.md | 37 ++++ plugin/.claude-plugin/plugin.json | 2 +- pyproject.toml | 2 +- src/attune_forms/bridge.py | 54 +++++- src/attune_forms/form_events.py | 240 ++++++++++++++++++++++---- src/attune_forms/mcp_server.py | 2 +- src/attune_forms/models.py | 7 + src/attune_forms/template_store.py | 2 +- src/attune_forms/widget.py | 13 +- tests/test_form_events.py | 262 +++++++++++++++++++++++++++++ 11 files changed, 580 insertions(+), 45 deletions(-) diff --git a/.claude-plugin/marketplace.json b/.claude-plugin/marketplace.json index 7bd4ec3..32daaa1 100644 --- a/.claude-plugin/marketplace.json +++ b/.claude-plugin/marketplace.json @@ -7,14 +7,14 @@ }, "metadata": { "description": "Structured agent-user communication: validated forms, decision cards with recommendations, structured pushback, and progress reports \u2014 batch questions instead of asking one at a time.", - "version": "0.7.0" + "version": "0.8.0" }, "plugins": [ { "name": "attune-forms", "description": "The communication grammar for AI agents: batch independent questions into ONE validated form; offer recommendations as decision cards with rationales and per-option tradeoffs; disagree constructively via pushback cards; report multi-step progress with a blocked-item picker. Renders rich HTML where the host supports widgets and degrades cleanly to plain questions everywhere else. Powered by the attune-forms PyPI package via a bundled MCP server.", "source": "./plugin", - "version": "0.7.0", + "version": "0.8.0", "author": { "name": "Smart AI Memory", "email": "admin@smartaimemory.com" diff --git a/CHANGELOG.md b/CHANGELOG.md index 723bd6f..74188cb 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -6,6 +6,43 @@ follow [SemVer](https://semver.org/). ## [Unreleased] +## [0.8.0] — 2026-08-24 + +Per-stage form telemetry: the lifecycle is now measurable end to end +(chair-approved 2026-08-24, route "measure first" — the prior log had +only `form_surface` and a bare `form_submitted`, so per-stage latency +was not computable). + +### Added +- **`FormSchema.form_id`** — a telemetry join key on every parsed + form. An explicit top-level `"form_id"` in the definition wins + (short `[A-Za-z0-9._-]` token, validated); otherwise + `form_from_dict` derives a deterministic content hash, so the + render call and the collect call — which each re-parse the same + dict — land on the same id without the agent threading anything. +- **Stage events** in `~/.attune/telemetry/form_events.jsonl` (same + append-only JSONL, consent gates, and 5 MB rotation): + - `form_build` (`form_id`, `source`: `"dict"` or + `"template:"` — the V7 template-adoption signal, + `question_count`) — emitted by `form_from_dict` / + `form_from_template` on every successful cast. + - `form_rendered` (`form_id`, `duration_ms`, `html_bytes`) — + emitted by `form_to_widget_html`. + - `form_submitted` now carries `form_id` (the MCP collect handler + passes it; the zero-arg form stays valid for older callers). + - `form_surface` records also carry `form_id`. +- **`stage_latency()`** — reads the log back as per-stage p50/p95: + render cost from each `form_rendered`'s own `duration_ms`, and the + user-facing wait as first `form_rendered` → first `form_submitted` + per `form_id`; plus build/render/submission counts and the + cast-source mix. +- `log_form_build` / `log_form_rendered` log helpers (same + never-raises contract), shared `_append` write path. + +### Changed +- `form_from_dict` accepts a keyword-only `source` (default + `"dict"`); `form_from_template` passes `template:`. + ## [0.7.0] — 2026-08-20 The output of a four-stage library review (checkpoint-1 sweep, a diff --git a/plugin/.claude-plugin/plugin.json b/plugin/.claude-plugin/plugin.json index 654e77f..68072d9 100644 --- a/plugin/.claude-plugin/plugin.json +++ b/plugin/.claude-plugin/plugin.json @@ -1,6 +1,6 @@ { "name": "attune-forms", - "version": "0.7.0", + "version": "0.8.0", "description": "Structured agent-user communication \u2014 validated forms, decision cards, pushback, progress reports, deliberation, triage boards, confirm gates, rankings, and assumption reviews via the attune-forms MCP server.", "author": { "name": "Smart AI Memory", diff --git a/pyproject.toml b/pyproject.toml index 272bf0d..8918489 100644 --- a/pyproject.toml +++ b/pyproject.toml @@ -4,7 +4,7 @@ build-backend = "setuptools.build_meta" [project] name = "attune-forms" -version = "0.7.0" +version = "0.8.0" description = "Dynamic forms library: declarative FormSchema, multi-surface renderers (widget HTML, AskUserQuestion, MCP elicitation), and template-driven intake generation" readme = "README.md" requires-python = ">=3.10" diff --git a/src/attune_forms/bridge.py b/src/attune_forms/bridge.py index 94d71fc..ddf8384 100644 --- a/src/attune_forms/bridge.py +++ b/src/attune_forms/bridge.py @@ -12,15 +12,17 @@ from __future__ import annotations +import hashlib import json import math import os +import re from collections.abc import Callable from datetime import datetime from pathlib import Path from typing import Any -from attune_forms.form_events import log_surface_decision +from attune_forms.form_events import log_form_build, log_surface_decision from attune_forms.models import ( ASSUMPTION_RULINGS, ASSUMPTION_TEXT_SUFFIX, @@ -802,7 +804,30 @@ def _parse_list_style( # the bound is never built and collect(99999) validates clean). These # sets must track exactly what form_from_dict and its _parse_* helpers # read; the parity test against the MCP _field_schema ratchets that. -_DEFINITION_TOP_KEYS = frozenset({"title", "description", "fields", "questions"}) +_DEFINITION_TOP_KEYS = frozenset({"title", "description", "fields", "questions", "form_id"}) + +#: An explicit definition ``form_id``: short, filesystem/log-safe token. +_FORM_ID_RE = re.compile(r"^[A-Za-z0-9][A-Za-z0-9._-]{0,63}$") + + +def _derived_form_id(data: dict[str, Any]) -> str: + """Deterministic id from the definition content. + + The render call and the collect call each re-parse the same dict, + so hashing the canonical JSON gives both the SAME id — lifecycle + stages join in telemetry without the agent threading anything. + Content-addressed, not unique-per-cast: two casts of an identical + definition share an id, which is exactly what the stage-latency + join wants (first render → first submission). + """ + try: + canonical = json.dumps(data, sort_keys=True, separators=(",", ":"), default=str) + except (TypeError, ValueError): + return "" + digest = hashlib.sha1(canonical.encode("utf-8", "replace"), usedforsecurity=False) + return digest.hexdigest()[:12] + + _DEFINITION_FIELD_KEYS = frozenset( { "id", @@ -835,7 +860,7 @@ def _parse_list_style( ) -def form_from_dict(data: dict[str, Any]) -> FormSchema: +def form_from_dict(data: dict[str, Any], *, source: str = "dict") -> FormSchema: """Build a :class:`FormSchema` from plain serializable data (D3). The declarative artifact a skill / future designer / data source @@ -851,6 +876,12 @@ def form_from_dict(data: dict[str, Any]) -> FormSchema: "options"?: list[str], "default"?: str, "help_text"?: str, "required"?: bool}``. ``"label"`` is accepted as an alias for ``"text"``; ``"questions"`` as an alias for ``"fields"``. + An optional top-level ``"form_id"`` (short + ``[A-Za-z0-9._-]`` token) names the telemetry lifecycle id + explicitly; omitted, a deterministic content hash is used. + source: Where the definition came from, recorded on the + ``form_build`` telemetry event — ``"dict"`` (default) or + ``"template:"`` (set by ``form_from_template``). Returns: A validated :class:`FormSchema`. @@ -873,6 +904,17 @@ def form_from_dict(data: dict[str, Any]) -> FormSchema: problems.append("form must have a non-empty 'fields' list") raw_fields = [] + form_id = "" + raw_form_id = data.get("form_id") + if raw_form_id is not None: + if isinstance(raw_form_id, str) and _FORM_ID_RE.match(raw_form_id): + form_id = raw_form_id + else: + problems.append( + "form 'form_id' must be a 1-64 char [A-Za-z0-9._-] string" + " starting with a letter or digit" + ) + for key in data: if key not in _DEFINITION_TOP_KEYS: problems.append(f"form has unknown definition key {key!r}") @@ -1048,11 +1090,14 @@ def form_from_dict(data: dict[str, Any]) -> FormSchema: if problems: raise FormValidationError(problems) - return FormSchema( + schema = FormSchema( title=title, description=data.get("description", "") or "", questions=questions, + form_id=form_id or _derived_form_id(data), ) + log_form_build(schema.form_id, source=source, question_count=len(questions)) + return schema #: Question types that lose fidelity on ``AskUserQuestion`` — either @@ -1267,6 +1312,7 @@ def select_form_surface( log_surface_decision( surface, reason=reason, + form_id=form.form_id, question_count=len(form.questions), chosen=chosen, agreed=None if chosen is None else chosen == surface, diff --git a/src/attune_forms/form_events.py b/src/attune_forms/form_events.py index 27af39a..da772e9 100644 --- a/src/attune_forms/form_events.py +++ b/src/attune_forms/form_events.py @@ -9,6 +9,23 @@ One event = one JSON line: ``v`` / ``ts`` / ``event`` / ``surface`` plus optional routing context. +**Stage events.** Beyond the routing decision, the pipeline emits one +event per lifecycle stage, joinable on ``form_id`` (derived +deterministically from the definition by +:func:`~attune_forms.bridge.form_from_dict`, so the render call and the +collect call — which each re-parse the same dict — land on the same id +without the agent threading anything): + +- ``form_build`` — a definition was cast into a validated + ``FormSchema`` (``source`` says how: ``"dict"`` or + ``"template:"``). +- ``form_rendered`` — the widget HTML was produced (``duration_ms``, + ``html_bytes``). +- ``form_submitted`` — answers validated; carries ``form_id`` when the + caller has one. + +:func:`stage_latency` reads them back as per-stage p50/p95. + **What this can and cannot measure.** The live call site is the pair of MCP elicitation handlers, where the tool the agent invoked *is* its choice — so each record carries the router's recommendation (``surface`` @@ -35,6 +52,7 @@ from __future__ import annotations import json +import math import os from collections import Counter from datetime import datetime, timezone @@ -112,28 +130,15 @@ def _rotate_if_huge(path: Path) -> None: pass # rotation is a nicety; the append below still works -def log_surface_decision(surface: str, **fields: object) -> None: - """Append one surface-routing decision. Best-effort, never raises. +def _append(record: dict[str, object]) -> None: + """Append one record to the live log. Best-effort, never raises. - Args: - surface: The chosen surface — ``"widget"`` or ``"ask"``. - **fields: Routing context (e.g. ``reason``, ``question_count``). + The single write path every logger below shares: consent gate, + directory creation, size rotation, compact one-line JSON. """ try: if not _enabled(): return - record: dict[str, object] = { - "v": "1.0", - "ts": datetime.now(timezone.utc).strftime("%Y-%m-%dT%H:%M:%S.%fZ"), - "event": "form_surface", - "surface": str(surface)[:32], - } - # Reserved keys always win: a caller kwarg named v/ts/event/ - # surface would forge records every reader keys on (e.g. a fake - # "form_submitted" advancing the keyboard-hint counter) — - # confirmation pass 1, 2026-08-20. - record.update({k: v for k, v in fields.items() if k not in record}) - path = _events_path() path.parent.mkdir(parents=True, exist_ok=True, mode=0o700) _rotate_if_huge(path) @@ -141,14 +146,82 @@ def log_surface_decision(surface: str, **fields: object) -> None: json.dump(record, fh, separators=(",", ":"), default=str) fh.write("\n") except Exception: - # Telemetry is best-effort and this runs on the live routing - # path: "never raises" must hold for MORE than OSError — + # Telemetry is best-effort and this runs on live pipeline + # paths: "never raises" must hold for MORE than OSError — # json.dump raises ValueError on a circular context and # ``default=str`` re-raises whatever a value's __str__ raises # (confirmation pass 1, 2026-08-20). pass +def _base_record(event: str) -> dict[str, object]: + """Version + UTC timestamp + event kind — every record's spine.""" + return { + "v": "1.0", + "ts": datetime.now(timezone.utc).strftime("%Y-%m-%dT%H:%M:%S.%fZ"), + "event": event, + } + + +def log_surface_decision(surface: str, **fields: object) -> None: + """Append one surface-routing decision. Best-effort, never raises. + + Args: + surface: The chosen surface — ``"widget"`` or ``"ask"``. + **fields: Routing context (e.g. ``reason``, ``question_count``). + """ + try: + record = _base_record("form_surface") + record["surface"] = str(surface)[:32] + # Reserved keys always win: a caller kwarg named v/ts/event/ + # surface would forge records every reader keys on (e.g. a fake + # "form_submitted" advancing the keyboard-hint counter) — + # confirmation pass 1, 2026-08-20. + record.update({k: v for k, v in fields.items() if k not in record}) + _append(record) + except Exception: + pass # str(surface) runs caller __str__; same contract as _append + + +def log_form_build(form_id: str, *, source: str = "dict", question_count: int = 0) -> None: + """Record that a definition was cast into a validated form. + + Args: + form_id: The lifecycle join key (see ``form_from_dict``). + source: How the cast happened — ``"dict"`` for a hand-built + definition, ``"template:"`` for a template cast. The + V7 adoption signal: the mix of the two is the receipt that + the template library is (or is not) actually used. + question_count: Number of fields in the validated form. + """ + try: + record = _base_record("form_build") + record["form_id"] = str(form_id)[:64] + record["source"] = str(source)[:64] + record["question_count"] = int(question_count) + _append(record) + except Exception: + pass # never-raises contract; coercions run caller code + + +def log_form_rendered(form_id: str, *, duration_ms: float, html_bytes: int) -> None: + """Record that widget HTML was produced for a form. + + Args: + form_id: The lifecycle join key. + duration_ms: Wall-clock render time in milliseconds. + html_bytes: Size of the rendered HTML in bytes. + """ + try: + record = _base_record("form_rendered") + record["form_id"] = str(form_id)[:64] + record["duration_ms"] = round(float(duration_ms), 3) + record["html_bytes"] = int(html_bytes) + _append(record) + except Exception: + pass # never-raises contract; coercions run caller code + + #: Form submissions before the one-time keyboard-mode hint fires. D17 #: ratified usage-triggered discovery ("after N form submissions"), not a #: calendar timer — someone who never feels the friction never sees it. @@ -163,22 +236,20 @@ def log_surface_decision(surface: str, **fields: object) -> None: ) -def log_submission() -> None: - """Record that a user submitted a form. Best-effort, never raises.""" +def log_submission(form_id: str | None = None) -> None: + """Record that a user submitted a form. Best-effort, never raises. + + Args: + form_id: The lifecycle join key, when the caller has one. + Optional so pre-0.8 call sites (zero-arg) keep working; + without it the submission still counts toward the keyboard + hint but cannot join its ``form_rendered`` event. + """ try: - if not _enabled(): - return - path = _events_path() - path.parent.mkdir(parents=True, exist_ok=True, mode=0o700) - _rotate_if_huge(path) - record = { - "v": "1.0", - "ts": datetime.now(timezone.utc).strftime("%Y-%m-%dT%H:%M:%S.%fZ"), - "event": "form_submitted", - } - with path.open("a", encoding="utf-8") as fh: - json.dump(record, fh, separators=(",", ":")) - fh.write("\n") + record = _base_record("form_submitted") + if form_id: + record["form_id"] = str(form_id)[:64] + _append(record) except Exception: pass # same never-raises contract as log_surface_decision @@ -341,3 +412,104 @@ def surface_mix(home: Path | None = None) -> dict[str, int]: except OSError: return {} return dict(counts) + + +def _parse_ts(raw: object) -> datetime | None: + """Parse a record's ``ts`` back to an aware datetime, or ``None``.""" + try: + return datetime.strptime(str(raw), "%Y-%m-%dT%H:%M:%S.%fZ").replace(tzinfo=timezone.utc) + except (TypeError, ValueError): + return None + + +def _percentiles(values: list[float]) -> dict[str, float | int] | None: + """Nearest-rank p50/p95 (plus ``n``) of ``values``, or ``None`` if empty.""" + if not values: + return None + ordered = sorted(values) + + def rank(q: float) -> float: + return ordered[min(len(ordered) - 1, max(0, math.ceil(q * len(ordered)) - 1))] + + return {"p50": round(rank(0.50), 3), "p95": round(rank(0.95), 3), "n": len(ordered)} + + +def stage_latency(home: Path | None = None) -> dict[str, object]: + """Per-stage latency read-back once stage events accrue. + + Joins ``form_rendered`` → ``form_submitted`` on ``form_id`` (first + render, first submission at-or-after it) — the user-facing wait. + Render cost comes straight from each ``form_rendered`` record's own + ``duration_ms``, no join needed. Malformed lines, missing ids, and + a submission with no matching render are skipped, never raised on — + same read contract as :func:`surface_mix`. + + Args: + home: Optional attune-home base to read from; defaults to the + process's own (ATTUNE_HOME or ``~/.attune``). + + Returns: + ``builds`` / ``renders`` / ``submissions`` (event counts), + ``build_sources`` (cast-source mix — the V7 template-adoption + signal), ``joined`` (render→submit pairs found), ``render_ms`` + and ``submit_seconds`` (each ``{"p50", "p95", "n"}`` or ``None`` + when no data). + """ + builds = renders = submissions = 0 + sources: Counter[str] = Counter() + render_ms: list[float] = [] + first_render: dict[str, datetime] = {} + first_submit: dict[str, datetime] = {} + try: + with _events_path(home).open(encoding="utf-8") as fh: + for line in fh: + try: + record = json.loads(line) + except ValueError: + continue + if not isinstance(record, dict): + continue + event = record.get("event") + form_id = record.get("form_id") + keyed = isinstance(form_id, str) and bool(form_id) + stamp = _parse_ts(record.get("ts")) + if event == "form_build": + builds += 1 + sources[str(record.get("source", "(unknown)"))] += 1 + elif event == "form_rendered": + renders += 1 + raw = record.get("duration_ms") + if isinstance(raw, (int, float)) and not isinstance(raw, bool) and raw >= 0: + render_ms.append(float(raw)) + if ( + keyed + and stamp + and stamp + < first_render.get(form_id, datetime.max.replace(tzinfo=timezone.utc)) + ): + first_render[form_id] = stamp + elif event == "form_submitted": + submissions += 1 + if ( + keyed + and stamp + and stamp + < first_submit.get(form_id, datetime.max.replace(tzinfo=timezone.utc)) + ): + first_submit[form_id] = stamp + except OSError: + pass # empty read below — zeros, not an error + waits = [ + (first_submit[form_id] - rendered).total_seconds() + for form_id, rendered in first_render.items() + if form_id in first_submit and first_submit[form_id] >= rendered + ] + return { + "builds": builds, + "renders": renders, + "submissions": submissions, + "build_sources": dict(sources), + "joined": len(waits), + "render_ms": _percentiles(render_ms), + "submit_seconds": _percentiles(waits), + } diff --git a/src/attune_forms/mcp_server.py b/src/attune_forms/mcp_server.py index 3f7fe91..2f56d61 100644 --- a/src/attune_forms/mcp_server.py +++ b/src/attune_forms/mcp_server.py @@ -334,7 +334,7 @@ async def handle_collect_response(args: dict[str, Any]) -> dict[str, Any]: "response_id": response.response_id, } try: - log_submission() + log_submission(form_id=form.form_id) hint = maybe_keyboard_hint(keyboard_mode=keyboard_mode_enabled()) except (OSError, ValueError) as exc: logger.debug("keyboard-mode hint skipped: %s", exc) diff --git a/src/attune_forms/models.py b/src/attune_forms/models.py index 915eb64..8b43c63 100644 --- a/src/attune_forms/models.py +++ b/src/attune_forms/models.py @@ -631,12 +631,19 @@ class FormSchema: title: Form title description: Form description questions: List of questions to ask + form_id: Telemetry join key for the form's lifecycle events + (``form_build`` → ``form_rendered`` → ``form_submitted``). + ``form_from_dict`` fills it — an explicit top-level + ``"form_id"`` in the definition wins, otherwise a + deterministic content hash so every re-parse of the same + dict lands on the same id. Empty on hand-built schemas. """ title: str description: str questions: list[FormQuestion] = field(default_factory=list) + form_id: str = "" def get_question_batches(self, batch_size: int = 4) -> list[list[FormQuestion]]: """Batch questions for asking (AskUserQuestion supports max 4 at once). diff --git a/src/attune_forms/template_store.py b/src/attune_forms/template_store.py index ea6be0f..e0c2028 100644 --- a/src/attune_forms/template_store.py +++ b/src/attune_forms/template_store.py @@ -101,7 +101,7 @@ def form_from_template(name: str, slots: dict[str, Any] | None = None) -> FormSc problems = _slot_problems(name, declared, values, data) if problems: raise FormValidationError(problems) - return form_from_dict(_substitute(data, values)) + return form_from_dict(_substitute(data, values), source=f"template:{name}") def _slot_problems( diff --git a/src/attune_forms/widget.py b/src/attune_forms/widget.py index ee3d1c1..47e0da9 100644 --- a/src/attune_forms/widget.py +++ b/src/attune_forms/widget.py @@ -21,11 +21,13 @@ from __future__ import annotations +import time import uuid from collections.abc import Callable from html import escape from attune_forms.bridge import is_fully_inferred +from attune_forms.form_events import log_form_rendered from attune_forms.models import ( ASSUMPTION_RULINGS, BOOLEAN_OPTIONS, @@ -727,6 +729,7 @@ def form_to_widget_html( An HTML string ready to pass straight to ``mcp__visualize__show_widget``. """ + start = time.perf_counter() sfx = "".join(c for c in (instance_id or "") if c.isalnum()) or uuid.uuid4().hex[:8] form_id = f"attune-elicit-form-{sfx}" intro = f'

{_esc(message)}

' if message else "" @@ -748,7 +751,7 @@ def form_to_widget_html( ) submit_label = "Confirm" if confirm else "Submit" - return f"""

{_esc(form.title)} — interactive form

+ html = f"""

{_esc(form.title)} — interactive form

@@ -927,3 +930,11 @@ def form_to_widget_html( }})();
""" + # form.form_id, not the DOM id above: the DOM suffix is fresh per + # render, while the telemetry id must match what collect re-derives. + log_form_rendered( + form.form_id, + duration_ms=(time.perf_counter() - start) * 1000.0, + html_bytes=len(html.encode("utf-8")), + ) + return html diff --git a/tests/test_form_events.py b/tests/test_form_events.py index 1bd7625..b5774ab 100644 --- a/tests/test_form_events.py +++ b/tests/test_form_events.py @@ -21,9 +21,12 @@ _MAX_BYTES, _rotate_if_huge, inference_rate, + log_form_build, + log_form_rendered, log_submission, log_surface_decision, maybe_keyboard_hint, + stage_latency, submission_count, surface_mix, ) @@ -343,3 +346,262 @@ def test_inferred_exceeding_fields_skipped(self, _isolated_home: Path) -> None: assert stats["fields"] == 4 assert stats["fields_inferred"] == 2 assert 0.0 <= stats["inferred_share"] <= 1.0 + + +class TestStageLoggers: + """The three lifecycle loggers write joinable, well-formed records.""" + + def test_log_form_build_record(self, _isolated_home: Path) -> None: + log_form_build("abc123", source="template:session-contract", question_count=4) + (line,) = _events_file(_isolated_home).read_text(encoding="utf-8").splitlines() + record = json.loads(line) + assert record["event"] == "form_build" + assert record["form_id"] == "abc123" + assert record["source"] == "template:session-contract" + assert record["question_count"] == 4 + assert record["v"] == "1.0" and "ts" in record + + def test_log_form_rendered_record(self, _isolated_home: Path) -> None: + log_form_rendered("abc123", duration_ms=1.23456, html_bytes=2048) + record = json.loads(_events_file(_isolated_home).read_text(encoding="utf-8")) + assert record["event"] == "form_rendered" + assert record["form_id"] == "abc123" + assert record["duration_ms"] == 1.235 + assert record["html_bytes"] == 2048 + + def test_log_submission_carries_form_id(self, _isolated_home: Path) -> None: + log_submission(form_id="abc123") + record = json.loads(_events_file(_isolated_home).read_text(encoding="utf-8")) + assert record["event"] == "form_submitted" + assert record["form_id"] == "abc123" + + def test_log_submission_zero_arg_still_works(self, _isolated_home: Path) -> None: + """Pre-0.8 call sites (attune-ai <= 14.1.0) pass no form_id.""" + log_submission() + record = json.loads(_events_file(_isolated_home).read_text(encoding="utf-8")) + assert record["event"] == "form_submitted" + assert "form_id" not in record + assert submission_count() == 1 + + def test_stage_loggers_honor_consent( + self, _isolated_home: Path, monkeypatch: pytest.MonkeyPatch + ) -> None: + monkeypatch.setenv("ATTUNE_FORMS_TELEMETRY", "0") + log_form_build("x", source="dict", question_count=1) + log_form_rendered("x", duration_ms=1.0, html_bytes=1) + log_submission(form_id="x") + assert not _events_file(_isolated_home).exists() + + def test_form_id_truncated_to_64(self, _isolated_home: Path) -> None: + log_submission(form_id="z" * 200) + record = json.loads(_events_file(_isolated_home).read_text(encoding="utf-8")) + assert record["form_id"] == "z" * 64 + + +class TestFormIdLifecycle: + """form_id joins the pipeline stages without the agent threading it.""" + + FORM = { + "title": "Scope", + "fields": [ + {"id": "goal", "text": "Goal?", "type": "text_input"}, + ], + } + + def test_same_dict_same_id_different_dict_different_id(self) -> None: + from attune_forms.bridge import form_from_dict + + first = form_from_dict(dict(self.FORM)) + second = form_from_dict(dict(self.FORM)) + other = form_from_dict({**self.FORM, "title": "Other"}) + assert first.form_id and first.form_id == second.form_id + assert other.form_id != first.form_id + + def test_explicit_form_id_wins(self) -> None: + from attune_forms.bridge import form_from_dict + + form = form_from_dict({**self.FORM, "form_id": "my-form.v1"}) + assert form.form_id == "my-form.v1" + + def test_invalid_form_id_is_a_definition_problem(self) -> None: + from attune_forms.bridge import FormValidationError, form_from_dict + + with pytest.raises(FormValidationError) as exc: + form_from_dict({**self.FORM, "form_id": "../escape"}) + assert any("form_id" in p for p in exc.value.problems) + + def test_build_event_logged_with_source_dict(self, _isolated_home: Path) -> None: + from attune_forms.bridge import form_from_dict + + form = form_from_dict(dict(self.FORM)) + records = [ + json.loads(line) + for line in _events_file(_isolated_home).read_text(encoding="utf-8").splitlines() + ] + builds = [r for r in records if r["event"] == "form_build"] + assert builds and builds[0]["form_id"] == form.form_id + assert builds[0]["source"] == "dict" + assert builds[0]["question_count"] == 1 + + def test_template_cast_logs_template_source(self, _isolated_home: Path) -> None: + from attune_forms.template_store import form_from_template + + form = form_from_template("session-contract", {"project": "attune-ai"}) + records = [ + json.loads(line) + for line in _events_file(_isolated_home).read_text(encoding="utf-8").splitlines() + ] + builds = [r for r in records if r["event"] == "form_build"] + assert builds and builds[-1]["source"] == "template:session-contract" + assert builds[-1]["form_id"] == form.form_id + + def test_surface_decision_carries_form_id(self, _isolated_home: Path) -> None: + from attune_forms.bridge import form_from_dict, select_form_surface + + form = form_from_dict(dict(self.FORM)) + select_form_surface(form, widget_capable=True, keyboard_mode=False) + records = [ + json.loads(line) + for line in _events_file(_isolated_home).read_text(encoding="utf-8").splitlines() + ] + surfaces = [r for r in records if r["event"] == "form_surface"] + assert surfaces and surfaces[-1]["form_id"] == form.form_id + + def test_render_and_collect_join_on_one_form_id(self, _isolated_home: Path) -> None: + """The pipeline receipt: dict → widget → collect, one form_id.""" + import asyncio + + from attune_forms.bridge import form_from_dict + from attune_forms.mcp_server import handle_collect_response + from attune_forms.widget import form_to_widget_html + + form = form_from_dict(dict(self.FORM)) + html = form_to_widget_html(form) + result = asyncio.run( + handle_collect_response({"form": dict(self.FORM), "answers": {"goal": "ship"}}) + ) + assert result["success"] is True + + records = [ + json.loads(line) + for line in _events_file(_isolated_home).read_text(encoding="utf-8").splitlines() + ] + rendered = [r for r in records if r["event"] == "form_rendered"] + submitted = [r for r in records if r["event"] == "form_submitted"] + assert rendered[-1]["form_id"] == form.form_id + assert rendered[-1]["html_bytes"] == len(html.encode("utf-8")) + assert rendered[-1]["duration_ms"] >= 0 + assert submitted[-1]["form_id"] == form.form_id + + +class TestStageLatency: + def _write(self, home: Path, records: list[dict]) -> None: + path = _events_file(home) + path.parent.mkdir(parents=True, exist_ok=True) + path.write_text( + "".join(json.dumps(r) + "\n" for r in records), encoding="utf-8" + ) + + def test_empty_store_returns_zeros(self) -> None: + stats = stage_latency() + assert stats["builds"] == stats["renders"] == stats["submissions"] == 0 + assert stats["joined"] == 0 + assert stats["render_ms"] is None and stats["submit_seconds"] is None + + def test_joins_and_percentiles(self, _isolated_home: Path) -> None: + self._write( + _isolated_home, + [ + {"event": "form_build", "form_id": "a", "source": "dict"}, + {"event": "form_build", "form_id": "b", "source": "template:x"}, + { + "event": "form_rendered", + "form_id": "a", + "ts": "2026-08-24T10:00:00.000000Z", + "duration_ms": 2.0, + }, + { + "event": "form_rendered", + "form_id": "b", + "ts": "2026-08-24T10:01:00.000000Z", + "duration_ms": 4.0, + }, + { + "event": "form_submitted", + "form_id": "a", + "ts": "2026-08-24T10:00:10.000000Z", + }, + { + "event": "form_submitted", + "form_id": "b", + "ts": "2026-08-24T10:01:30.000000Z", + }, + # No render for this one — counted, never joined. + { + "event": "form_submitted", + "form_id": "orphan", + "ts": "2026-08-24T10:02:00.000000Z", + }, + ], + ) + stats = stage_latency() + assert stats["builds"] == 2 + assert stats["build_sources"] == {"dict": 1, "template:x": 1} + assert stats["renders"] == 2 and stats["submissions"] == 3 + assert stats["joined"] == 2 + assert stats["render_ms"] == {"p50": 2.0, "p95": 4.0, "n": 2} + assert stats["submit_seconds"] == {"p50": 10.0, "p95": 30.0, "n": 2} + + def test_submission_before_render_not_joined(self, _isolated_home: Path) -> None: + self._write( + _isolated_home, + [ + { + "event": "form_rendered", + "form_id": "a", + "ts": "2026-08-24T10:00:00.000000Z", + "duration_ms": 1.0, + }, + # Stale submission from an earlier run of the same + # content-addressed form — must not produce a negative wait. + { + "event": "form_submitted", + "form_id": "a", + "ts": "2026-08-24T09:59:00.000000Z", + }, + ], + ) + stats = stage_latency() + assert stats["joined"] == 0 + assert stats["submit_seconds"] is None + + def test_malformed_lines_and_values_skipped(self, _isolated_home: Path) -> None: + path = _events_file(_isolated_home) + path.parent.mkdir(parents=True, exist_ok=True) + path.write_text( + "not json\n" + + json.dumps(["not", "a", "dict"]) + + "\n" + + json.dumps( + { + "event": "form_rendered", + "form_id": "a", + "ts": "garbage", + "duration_ms": "fast", + } + ) + + "\n" + + json.dumps({"event": "form_rendered", "form_id": 42, "duration_ms": -1}) + + "\n", + encoding="utf-8", + ) + stats = stage_latency() + assert stats["renders"] == 2 + assert stats["render_ms"] is None # no valid duration among them + assert stats["joined"] == 0 + + def test_reads_configured_home(self, tmp_path: Path, _isolated_home: Path) -> None: + other = tmp_path / "dashboard-home" + self._write(other, [{"event": "form_build", "form_id": "a", "source": "dict"}]) + assert stage_latency()["builds"] == 0 + assert stage_latency(home=other)["builds"] == 1 From 35dc2531cdfb9fbc448e886522ef64cbb72a57b0 Mon Sep 17 00:00:00 2001 From: GeneAI Date: Mon, 24 Aug 2026 15:32:12 -0400 Subject: [PATCH 2/3] =?UTF-8?q?style:=20UP038=20=E2=80=94=20isinstance=20u?= =?UTF-8?q?nion=20syntax=20in=20stage=5Flatency=20(CI=20lint)?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit --- src/attune_forms/form_events.py | 2 +- tests/test_form_events.py | 4 +--- 2 files changed, 2 insertions(+), 4 deletions(-) diff --git a/src/attune_forms/form_events.py b/src/attune_forms/form_events.py index da772e9..3126a06 100644 --- a/src/attune_forms/form_events.py +++ b/src/attune_forms/form_events.py @@ -479,7 +479,7 @@ def stage_latency(home: Path | None = None) -> dict[str, object]: elif event == "form_rendered": renders += 1 raw = record.get("duration_ms") - if isinstance(raw, (int, float)) and not isinstance(raw, bool) and raw >= 0: + if isinstance(raw, int | float) and not isinstance(raw, bool) and raw >= 0: render_ms.append(float(raw)) if ( keyed diff --git a/tests/test_form_events.py b/tests/test_form_events.py index b5774ab..83c8023 100644 --- a/tests/test_form_events.py +++ b/tests/test_form_events.py @@ -498,9 +498,7 @@ class TestStageLatency: def _write(self, home: Path, records: list[dict]) -> None: path = _events_file(home) path.parent.mkdir(parents=True, exist_ok=True) - path.write_text( - "".join(json.dumps(r) + "\n" for r in records), encoding="utf-8" - ) + path.write_text("".join(json.dumps(r) + "\n" for r in records), encoding="utf-8") def test_empty_store_returns_zeros(self) -> None: stats = stage_latency() From b0c705293cf23489e9cb318887d76025fd279690 Mon Sep 17 00:00:00 2001 From: GeneAI Date: Mon, 24 Aug 2026 15:43:52 -0400 Subject: [PATCH 3/3] fix(telemetry): sequential render-submit pairing + never-raise id derivation (codex cross-review findings 1-3) --- src/attune_forms/bridge.py | 6 ++- src/attune_forms/form_events.py | 46 ++++++++-------- tests/test_form_events.py | 93 +++++++++++++++++++++++++++++++++ 3 files changed, 121 insertions(+), 24 deletions(-) diff --git a/src/attune_forms/bridge.py b/src/attune_forms/bridge.py index ddf8384..6bf2222 100644 --- a/src/attune_forms/bridge.py +++ b/src/attune_forms/bridge.py @@ -822,7 +822,11 @@ def _derived_form_id(data: dict[str, Any]) -> str: """ try: canonical = json.dumps(data, sort_keys=True, separators=(",", ":"), default=str) - except (TypeError, ValueError): + except Exception: # noqa: BLE001 + # ``default=str`` re-raises whatever a value's __str__ raises, so + # TypeError/ValueError alone is not enough — a telemetry id must + # never make a valid definition fail to parse (codex cross-review + # finding 3, 2026-08-24). return "" digest = hashlib.sha1(canonical.encode("utf-8", "replace"), usedforsecurity=False) return digest.hexdigest()[:12] diff --git a/src/attune_forms/form_events.py b/src/attune_forms/form_events.py index 3126a06..d2b1b53 100644 --- a/src/attune_forms/form_events.py +++ b/src/attune_forms/form_events.py @@ -437,8 +437,14 @@ def rank(q: float) -> float: def stage_latency(home: Path | None = None) -> dict[str, object]: """Per-stage latency read-back once stage events accrue. - Joins ``form_rendered`` → ``form_submitted`` on ``form_id`` (first - render, first submission at-or-after it) — the user-facing wait. + Joins ``form_rendered`` → ``form_submitted`` on ``form_id``, + pairing sequentially in log order: each submission consumes the + latest not-yet-matched render at-or-before it, so a form rendered + and answered N times yields N wait samples — the user-facing wait + per cycle. (``form_id`` is content-derived, so repeated casts of + one definition share an id; pairing per cycle rather than taking + lifetime firsts is what keeps repeat forms — e.g. a template cast + every session — measurable. Codex cross-review finding, 2026-08-24.) Render cost comes straight from each ``form_rendered`` record's own ``duration_ms``, no join needed. Malformed lines, missing ids, and a submission with no matching render are skipped, never raised on — @@ -458,8 +464,8 @@ def stage_latency(home: Path | None = None) -> dict[str, object]: builds = renders = submissions = 0 sources: Counter[str] = Counter() render_ms: list[float] = [] - first_render: dict[str, datetime] = {} - first_submit: dict[str, datetime] = {} + pending: dict[str, list[datetime]] = {} + waits: list[float] = [] try: with _events_path(home).open(encoding="utf-8") as fh: for line in fh: @@ -481,29 +487,23 @@ def stage_latency(home: Path | None = None) -> dict[str, object]: raw = record.get("duration_ms") if isinstance(raw, int | float) and not isinstance(raw, bool) and raw >= 0: render_ms.append(float(raw)) - if ( - keyed - and stamp - and stamp - < first_render.get(form_id, datetime.max.replace(tzinfo=timezone.utc)) - ): - first_render[form_id] = stamp + if keyed and stamp: + pending.setdefault(form_id, []).append(stamp) elif event == "form_submitted": submissions += 1 - if ( - keyed - and stamp - and stamp - < first_submit.get(form_id, datetime.max.replace(tzinfo=timezone.utc)) - ): - first_submit[form_id] = stamp + if keyed and stamp: + # Consume the LATEST unmatched render at-or-before + # this submission. A stale submission (before every + # pending render) matches nothing and never blocks a + # later valid pair (codex finding 2, 2026-08-24). + stack = pending.get(form_id, []) + candidates = [ts for ts in stack if ts <= stamp] + if candidates: + matched = max(candidates) + stack.remove(matched) + waits.append((stamp - matched).total_seconds()) except OSError: pass # empty read below — zeros, not an error - waits = [ - (first_submit[form_id] - rendered).total_seconds() - for form_id, rendered in first_render.items() - if form_id in first_submit and first_submit[form_id] >= rendered - ] return { "builds": builds, "renders": renders, diff --git a/tests/test_form_events.py b/tests/test_form_events.py index 83c8023..b226bc2 100644 --- a/tests/test_form_events.py +++ b/tests/test_form_events.py @@ -603,3 +603,96 @@ def test_reads_configured_home(self, tmp_path: Path, _isolated_home: Path) -> No self._write(other, [{"event": "form_build", "form_id": "a", "source": "dict"}]) assert stage_latency()["builds"] == 0 assert stage_latency(home=other)["builds"] == 1 + + def test_repeated_form_yields_one_pair_per_cycle(self, _isolated_home: Path) -> None: + """Codex finding 1 (2026-08-24): form_id is content-derived, so a + template cast every session shares one id — lifetime-first joining + measured only the first cycle ever. Sequential pairing yields one + wait sample per render→submit cycle.""" + self._write( + _isolated_home, + [ + { + "event": "form_rendered", + "form_id": "a", + "ts": "2026-08-23T10:00:00.000000Z", + "duration_ms": 1.0, + }, + { + "event": "form_submitted", + "form_id": "a", + "ts": "2026-08-23T10:00:05.000000Z", + }, + { + "event": "form_rendered", + "form_id": "a", + "ts": "2026-08-24T09:00:00.000000Z", + "duration_ms": 1.0, + }, + { + "event": "form_submitted", + "form_id": "a", + "ts": "2026-08-24T09:00:15.000000Z", + }, + ], + ) + stats = stage_latency() + assert stats["joined"] == 2 + assert stats["submit_seconds"] == {"p50": 5.0, "p95": 15.0, "n": 2} + + def test_stale_submission_does_not_block_later_valid_pair(self, _isolated_home: Path) -> None: + """Codex finding 2 (2026-08-24): a submission predating every render + (same content hash from an earlier run) must not consume or block the + join — the later render→submit cycle still pairs.""" + self._write( + _isolated_home, + [ + # Stale submission from before this run's render. + { + "event": "form_submitted", + "form_id": "a", + "ts": "2026-08-24T09:00:00.000000Z", + }, + { + "event": "form_rendered", + "form_id": "a", + "ts": "2026-08-24T10:00:00.000000Z", + "duration_ms": 1.0, + }, + { + "event": "form_submitted", + "form_id": "a", + "ts": "2026-08-24T10:00:20.000000Z", + }, + ], + ) + stats = stage_latency() + assert stats["joined"] == 1 + assert stats["submit_seconds"] == {"p50": 20.0, "p95": 20.0, "n": 1} + + +class TestDerivedFormIdNeverRaises: + def test_hostile_str_value_degrades_to_empty_id(self) -> None: + """Codex finding 3 (2026-08-24): json.dumps(default=str) re-raises + whatever a value's __str__ raises — the telemetry id must degrade to + empty, never make a valid definition fail to parse.""" + from attune_forms.bridge import form_from_dict + + class Hostile: + def __str__(self) -> str: + raise RuntimeError("boom") + + form = form_from_dict( + { + "title": "T", + "fields": [ + { + "id": "q", + "text": "Q?", + "type": "text_input", + "help_text": Hostile(), + } + ], + } + ) + assert form.form_id == ""