From d32970a5fe5d73243802db97f8a6935ea9406b23 Mon Sep 17 00:00:00 2001 From: Alex Garcia Date: Mon, 28 Sep 2026 12:38:05 -0700 Subject: [PATCH 1/5] Telemetry scaffolding: registry, helpers, test fixtures Declares every span, metric and attribute in telemetry_registry.py using Datasette 1.0a41's plugin telemetry kit. No instrumentation yet. Co-Authored-By: Claude Opus 5.5 (1M context) --- datasette_apps/telemetry.py | 243 ++++++++++++++++++++++++ datasette_apps/telemetry_registry.py | 264 +++++++++++++++++++++++++++ pyproject.toml | 2 + tests/conftest.py | 21 +++ tests/test_telemetry.py | 13 ++ tests/test_telemetry_registry.py | 102 +++++++++++ 6 files changed, 645 insertions(+) create mode 100644 datasette_apps/telemetry.py create mode 100644 datasette_apps/telemetry_registry.py create mode 100644 tests/conftest.py create mode 100644 tests/test_telemetry.py create mode 100644 tests/test_telemetry_registry.py diff --git a/datasette_apps/telemetry.py b/datasette_apps/telemetry.py new file mode 100644 index 0000000..d3a61c1 --- /dev/null +++ b/datasette_apps/telemetry.py @@ -0,0 +1,243 @@ +"""OpenTelemetry helpers for datasette-apps. + +Depends on ``opentelemetry-api`` only, like Datasette core: this module +never creates a ``TracerProvider`` or ``MeterProvider``, never configures an +exporter, and must never import ``opentelemetry.sdk`` (a test imports the +package in a fresh subprocess and checks). With no provider installed every +span is a ``NonRecordingSpan`` and every instrument is a no-op - turning +telemetry on is the operator's move (``opentelemetry-instrument datasette +...``), exactly as with core. + +The tracer and meter live under their own ``datasette_apps`` +instrumentation scope, never core's ``datasette`` scope. Context +propagation is via contextvars, so this plugin's spans nest inside core's +request span, and core's spans nest inside ours. + +Every wire name comes from ``telemetry_registry``. Instruments are +module-level: OpenTelemetry's proxy meter forwards to a provider installed +later, and the test harness installs its tracer provider in a +session-scoped autouse fixture before any span is created. +""" + +import time +from contextlib import contextmanager +from importlib.metadata import PackageNotFoundError, version + +from datasette.telemetry import request_span +from opentelemetry import metrics as otel_metrics +from opentelemetry import trace as otel_trace +from opentelemetry.trace import Status, StatusCode + +from . import telemetry_registry as reg + + +def _version(): + try: + return version("datasette-apps") + except PackageNotFoundError: + return None + + +# No schema_url: our attributes are plugin-specific apart from db.namespace +# and error.type; see the plugin telemetry docs ("Omit schema_url if you are +# unsure which version applies"). +tracer = otel_trace.get_tracer("datasette_apps", _version()) +meter = otel_metrics.get_meter("datasette_apps", _version()) + + +# --- Instruments ---------------------------------------------------------- +# +# Each instrument passes the SDK a short plain-text description; the +# registry entry carries the longer documentation. Unit and buckets always +# come off the registry entry so the create_*() call cannot drift from it. + + +def _histogram(entry, description): + return meter.create_histogram( + entry, + unit=entry.unit, + description=description, + explicit_bucket_boundaries_advisory=entry.buckets, + ) + + +def _counter(entry, description): + return meter.create_counter(entry, unit=entry.unit, description=description) + + +queries = _counter(reg.M_QUERIES, "App queries handled, by source and outcome") +query_duration = _histogram( + reg.M_QUERY_DURATION, "Time to handle one app query, by source and outcome" +) +changes = _counter(reg.M_CHANGES, "App changes, by operation and origin") +debug_runs = _counter(reg.M_DEBUG_RUNS, "Terminal app_debug runs, by outcome") +debug_run_duration = _histogram( + reg.M_DEBUG_RUN_DURATION, "Wall-clock time of an app_debug run, by outcome" +) +debug_script_duration = _histogram( + reg.M_DEBUG_SCRIPT_DURATION, + "Browser-reported debug script duration, by outcome", +) +debug_jobs_expired = _counter( + reg.M_DEBUG_JOBS_EXPIRED, "Pending debug jobs lazily marked expired" +) + + +# --- Helpers -------------------------------------------------------------- + + +def clamp(value, allowed, default): + """Clamp an attribute value to its registry enum. + + Enum attributes declare a closed ``values=`` set in the registry and the + conformance helpers enforce membership; this is the call-site half of + that promise - anything unexpected becomes ``default`` instead of + minting a new metric series. + """ + return value if value in allowed else default + + +def error_type(exc): + "The exception's class name for ``error.type`` - never its message." + return type(exc).__qualname__ + + +def _without_none(mapping): + return {key: value for key, value in mapping.items() if value is not None} + + +def set_attributes(span, mapping): + "Set attributes on ``span`` if it is recording, skipping ``None`` values." + if span is None or not span.is_recording(): + return + for key, value in mapping.items(): + if value is not None: + span.set_attribute(key, value) + + +def annotate_request(request, mapping): + "Add attributes to core's recording request span for this request, if any." + set_attributes(request_span(request.scope), mapping) + + +def annotate_current_span(mapping): + "Add attributes to the current span (e.g. datasette-agent's tool span)." + set_attributes(otel_trace.get_current_span(), mapping) + + +def record_change(operation, via): + """Count one app change. Call only after the write succeeded. + + Unrecognised values are dropped rather than guessed at. + """ + changes.add( + 1, + _without_none( + { + reg.CHANGE_OPERATION: clamp( + operation, reg.CHANGE_OPERATION.values, None + ), + reg.CHANGE_VIA: clamp(via, reg.CHANGE_VIA.values, None), + } + ), + ) + + +def record_debug_run(outcome, run_seconds=None, script_seconds=None): + """Count one terminal ``app_debug`` run and record its durations. + + Durations that are ``None`` or negative are skipped. An unrecognised + outcome is dropped rather than guessed at. + """ + attributes = _without_none( + {reg.DEBUG_OUTCOME: clamp(outcome, reg.DEBUG_OUTCOME.values, None)} + ) + debug_runs.add(1, attributes) + if run_seconds is not None and run_seconds >= 0: + debug_run_duration.record(run_seconds, attributes) + if script_seconds is not None and script_seconds >= 0: + debug_script_duration.record(script_seconds, attributes) + + +def record_debug_job_expired(): + "Count one pending debug job flipped to expired." + debug_jobs_expired.add(1) + + +class QueryRecorder: + """What the body of ``query_span`` learns about one app query. + + ``kind`` (``sql``/``stored``), ``write`` (bool, stored queries only), + ``database`` (set only after the allowlist check passed), ``outcome`` + (see ``apps.query.outcome``) and ``rows`` (``ok`` read queries only). + """ + + __slots__ = ("kind", "write", "database", "outcome", "rows") + + def __init__(self): + self.kind = None + self.write = None + self.database = None + self.outcome = None + self.rows = None + + +@contextmanager +def query_span(source, app_id, job_id=None): + """Wrap one app query in an ``apps.query`` span and record its metrics. + + Yields a ``QueryRecorder`` for the body to fill in. On exit the outcome + is clamped to the registry enum (``error`` when an exception escaped or + no valid outcome was set), and only ``error`` sets span status + ``ERROR``. Exceptions are never recorded on the span - their messages + can quote SQL or data - only their class name as ``error.type``. + ``apps.queries`` and ``apps.query.duration`` are recorded whether or not + the span is recording (instruments are no-ops without a provider). + """ + source = clamp(source, reg.QUERY_SOURCE.values, None) + recorder = QueryRecorder() + started = time.perf_counter() + escaped = None + with tracer.start_as_current_span( + reg.QUERY, record_exception=False, set_status_on_exception=False + ) as span: + try: + yield recorder + except BaseException as exc: + escaped = exc + raise + finally: + duration = time.perf_counter() - started + if escaped is not None: + outcome = "error" + else: + outcome = clamp(recorder.outcome, reg.QUERY_OUTCOME.values, "error") + kind = clamp(recorder.kind, reg.QUERY_KIND.values, None) + write = recorder.write if isinstance(recorder.write, bool) else None + if span.is_recording(): + rows = recorder.rows if isinstance(recorder.rows, int) else None + set_attributes( + span, + { + reg.APP_ID: app_id, + reg.QUERY_SOURCE: source, + reg.QUERY_OUTCOME: outcome, + reg.QUERY_KIND: kind, + reg.QUERY_WRITE: write, + reg.DB_NAMESPACE: recorder.database, + reg.QUERY_ROWS: rows, + reg.DEBUG_JOB_ID: job_id, + reg.ERROR_TYPE: ( + error_type(escaped) if escaped is not None else None + ), + }, + ) + if outcome == "error": + span.set_status(Status(StatusCode.ERROR)) + base = {reg.QUERY_SOURCE: source, reg.QUERY_OUTCOME: outcome} + queries.add( + 1, _without_none({**base, reg.QUERY_KIND: kind, reg.QUERY_WRITE: write}) + ) + query_duration.record( + duration, _without_none({**base, reg.QUERY_KIND: kind}) + ) diff --git a/datasette_apps/telemetry_registry.py b/datasette_apps/telemetry_registry.py new file mode 100644 index 0000000..c627eea --- /dev/null +++ b/datasette_apps/telemetry_registry.py @@ -0,0 +1,264 @@ +""" +Every span, metric and attribute datasette-apps emits. + +Instrumentation scope: ``datasette_apps``. Prefix: ``apps.*`` (``datasette.*`` +is reserved for Datasette core). Shared names reused from core: +``db.namespace`` and ``error.type``. + +Built on Datasette's plugin telemetry kit (``datasette.telemetry_registry``): +``Attribute`` / ``SpanName`` / ``MetricName`` subclass ``str``, so a registry +entry *is* the name handed to OpenTelemetry. Call sites import these +constants; no wire name is written anywhere else. + +Privacy: nothing here records app HTML, names or descriptions, SQL text or +parameter values, stored query names, debug scripts or their results, CSP +origins, actor or conversation IDs, tokens, or exception messages. +``apps.app_id``, ``apps.debug.job_id`` and ``db.namespace`` ride on spans +only, never on a metric. +""" + +from datasette.telemetry_registry import ( + COUNTER, + DB_NAMESPACE, + DURATION_BUCKETS, + ERROR_TYPE, + HISTOGRAM, + Attribute, + MetricName, + SpanName, +) + +__all__ = [ + "ATTRIBUTES", + "DEBUG_RUN_BUCKETS", + "DEBUG_SCRIPT_BUCKETS", + "DURATION_BUCKETS", + "METRICS", + "SPANS", +] + +# --- Histogram bucket boundaries ------------------------------------------ + +# A debug run is wall-clock from job creation to the resumed tool call +# recording its envelope: it includes the browser claiming the task, so it +# can far exceed the script's own timeout (max 60s, debug.py MAX_TIMEOUT_MS), +# up to the 15 minute job window (debug.py JOB_EXPIRY_SECONDS). +DEBUG_RUN_BUCKETS = (0.5, 1, 2.5, 5, 10, 15, 30, 60, 120, 300, 900) +# The browser-reported duration_ms of the script itself, capped by +# MAX_TIMEOUT_MS = 60000. +DEBUG_SCRIPT_BUCKETS = (0.01, 0.05, 0.1, 0.25, 0.5, 1, 2.5, 5, 10, 15, 30, 60) + + +# --- Attributes ----------------------------------------------------------- + +APP_ID = Attribute( + "apps.app_id", + "The app's ID: a ULID for stored apps, or a plugin-supplied ID for " + "external apps. Unbounded, so it rides on spans only - **never on a " + "metric**.", +) +DEBUG_JOB_ID = Attribute( + "apps.debug.job_id", + "The ``_app_debug_jobs.id`` (a ULID) of an ``app_debug`` run. Spans " + "only - **never on a metric**. Present on ``apps.query`` only for " + "queries made by a debug run.", + optional=True, +) +QUERY_SOURCE = Attribute( + "apps.query.source", + "Which endpoint the app's query arrived on: ``app`` " + "(``/-/apps/{id}/query``, a running app) or ``debug`` " + "(``/-/apps/debug/{job}/query``, an ``app_debug`` run).", + values={"app", "debug"}, +) +QUERY_KIND = Attribute( + "apps.query.kind", + "``sql`` for ``datasette.query()``, ``stored`` for " + "``datasette.storedQuery()``. Absent when the request body could not be " + "parsed.", + optional=True, + values={"sql", "stored"}, +) +QUERY_WRITE = Attribute( + "apps.query.write", + "True for a stored query declared ``is_write``. Only known once the " + "stored query has been resolved, so absent otherwise.", + optional=True, + values={True, False}, +) +QUERY_OUTCOME = Attribute( + "apps.query.outcome", + "How the app query ended. ``ok``: the query ran and returned a result. " + "``invalid``: the request body or parameters were malformed. " + "``not_allowed``: the database or stored query is not on the app's " + "allowlist. ``not_found``: the database or stored query doesn't exist. " + "``denied``: Datasette's permission checks refused the actor. " + "``failed``: Datasette rejected or failed the query (SQL error, time " + "limit, write denied by a read-only query). ``error``: an unexpected " + "exception escaped - the only outcome that sets span status ``ERROR``. " + "Clamped at the call site: anything unrecognised becomes ``error``.", + values={"ok", "invalid", "not_allowed", "not_found", "denied", "failed", "error"}, +) +QUERY_ROWS = Attribute( + "apps.query.rows", + "Number of rows returned. Only on ``ok`` read queries.", + optional=True, +) +CHANGE_OPERATION = Attribute( + "apps.change.operation", + "What changed: an app was created, edited, deleted, pinned or unpinned.", + values={"create", "edit", "delete", "pin", "unpin"}, +) +CHANGE_VIA = Attribute( + "apps.change.via", + "Where the change came from: ``web`` (the plugin's HTML forms) or " + "``agent`` (datasette-agent tools).", + values={"web", "agent"}, +) +TOOL_RESULT = Attribute( + "apps.tool.result", + "How one of this plugin's agent tools ended: ``ok``, ``error`` or " + "``denied`` (the actor lacked permission). Set on the current tool span " + "(datasette-agent's ``execute_tool`` span), not on a span of our own.", + values={"ok", "error", "denied"}, +) +DEBUG_OUTCOME = Attribute( + "apps.debug.outcome", + "How an ``app_debug`` run ended. ``ok``: the script ran and the envelope " + "reported success. ``script_error``: the script threw, or the harness " + "reported an error. ``timed_out``: the script hit its timeout. " + "``task_expired`` / ``task_cancelled``: the browser task expired or was " + "cancelled before a result came back. ``denied``: the actor may not edit " + "the app. ``invalid``: the debug request was rejected (e.g. a bad " + "viewport). ``unsupported``: the agent host does not support browser " + "tasks.", + values={ + "ok", + "script_error", + "timed_out", + "task_expired", + "task_cancelled", + "denied", + "invalid", + "unsupported", + }, +) + + +# --- Spans ---------------------------------------------------------------- + +QUERY = SpanName( + "apps.query", + "One query from a running app (or an ``app_debug`` run) through the " + "plugin's query endpoint: body parsing, the allowlist check and the " + "internal ``datasette.client`` call to Datasette's JSON API, which nests " + "inside as a SERVER span tagged ``datasette.internal_client``. Only an " + "unexpected exception (outcome ``error``) sets status ``ERROR``; " + "exception messages are never recorded. ``db.namespace`` is set only " + "once the database has passed the app's allowlist.", + attributes=( + APP_ID, + QUERY_SOURCE, + QUERY_OUTCOME, + QUERY_KIND, + QUERY_WRITE, + DB_NAMESPACE, + QUERY_ROWS, + DEBUG_JOB_ID, + ERROR_TYPE, + ), +) + + +# --- Metrics -------------------------------------------------------------- + +M_QUERIES = MetricName( + "apps.queries", + COUNTER, + "{query}", + "App queries handled, by source, outcome, kind and whether a stored " + "query was a write.", + attributes=(QUERY_SOURCE, QUERY_OUTCOME, QUERY_KIND, QUERY_WRITE), +) +M_QUERY_DURATION = MetricName( + "apps.query.duration", + HISTOGRAM, + "s", + "Time to handle one app query end to end, as the app sees it. Uses " + "core's duration buckets so it lines up with " + "``db.client.operation.duration``.", + attributes=(QUERY_SOURCE, QUERY_OUTCOME, QUERY_KIND), + buckets=DURATION_BUCKETS, +) +M_CHANGES = MetricName( + "apps.changes", + COUNTER, + "{change}", + "App changes (create, edit, delete, pin, unpin), by operation and " + "whether they came from the web UI or the agent.", + attributes=(CHANGE_OPERATION, CHANGE_VIA), +) +M_DEBUG_RUNS = MetricName( + "apps.debug.runs", + COUNTER, + "{run}", + "Terminal ``app_debug`` tool executions, by outcome. The first " + "execution that suspends waiting for the browser is not counted.", + attributes=(DEBUG_OUTCOME,), +) +M_DEBUG_RUN_DURATION = MetricName( + "apps.debug.run.duration", + HISTOGRAM, + "s", + "Wall-clock time from debug job creation to the resumed tool call " + "recording its result, including the browser claiming the task. Only " + "for outcomes that came back from the browser.", + attributes=(DEBUG_OUTCOME,), + buckets=DEBUG_RUN_BUCKETS, +) +M_DEBUG_SCRIPT_DURATION = MetricName( + "apps.debug.script.duration", + HISTOGRAM, + "s", + "The debug script's own run time as reported by the browser " + "(``duration_ms``), capped by the 60s maximum script timeout.", + attributes=(DEBUG_OUTCOME,), + buckets=DEBUG_SCRIPT_BUCKETS, +) +M_DEBUG_JOBS_EXPIRED = MetricName( + "apps.debug.jobs.expired", + COUNTER, + "{job}", + "Pending debug jobs flipped to ``expired`` because a ``/frame`` or " + "``/query`` request arrived after the 15 minute job window. Counted " + "only when a row actually changed.", +) + + +SPANS = (QUERY,) + +METRICS = ( + M_QUERIES, + M_QUERY_DURATION, + M_CHANGES, + M_DEBUG_RUNS, + M_DEBUG_RUN_DURATION, + M_DEBUG_SCRIPT_DURATION, + M_DEBUG_JOBS_EXPIRED, +) + +ATTRIBUTES = ( + APP_ID, + DEBUG_JOB_ID, + QUERY_SOURCE, + QUERY_KIND, + QUERY_WRITE, + QUERY_OUTCOME, + QUERY_ROWS, + CHANGE_OPERATION, + CHANGE_VIA, + TOOL_RESULT, + DEBUG_OUTCOME, + DB_NAMESPACE, + ERROR_TYPE, +) diff --git a/pyproject.toml b/pyproject.toml index f31da78..2e4dfbe 100644 --- a/pyproject.toml +++ b/pyproject.toml @@ -12,11 +12,13 @@ requires-python = ">=3.10" dependencies = [ "datasette>=1.0a41", "datasette-agent-edit>=0.1a0", + "opentelemetry-api>=1.37", ] [dependency-groups] dev = [ "datasette-agent>=0.4a0", + "opentelemetry-sdk>=1.37", "playwright>=1.60.0", "pytest", "pytest-asyncio", diff --git a/tests/conftest.py b/tests/conftest.py new file mode 100644 index 0000000..66b3a7f --- /dev/null +++ b/tests/conftest.py @@ -0,0 +1,21 @@ +# Importing the fixture names registers them: session-scoped autouse +# tracer/meter providers with in-memory export (skipped when the SDK is not +# installed), and a per-test reset. Tests take otel_spans / otel_metrics. +from datasette.telemetry_testing import ( # noqa: F401 + MetricsCollector, + otel_metrics, + otel_meter_provider, + otel_provider, + otel_reset, + otel_spans, +) + + +def pytest_collection_modifyitems(items): + # assert_package_never_imports_sdk shells out to a fresh interpreter; its + # docstring documents a macOS/CPython 3.13 crash when subprocess-spawning + # tests run late in a thread-heavy process, so run it first. + front_names = {"test_package_never_imports_the_sdk"} + front = [item for item in items if item.name in front_names] + rest = [item for item in items if item.name not in front_names] + items[:] = front + rest diff --git a/tests/test_telemetry.py b/tests/test_telemetry.py new file mode 100644 index 0000000..2deefa6 --- /dev/null +++ b/tests/test_telemetry.py @@ -0,0 +1,13 @@ +import pytest + +pytest.importorskip("opentelemetry.sdk") + +from datasette.telemetry_testing import assert_package_never_imports_sdk + + +def test_package_never_imports_the_sdk(): + assert_package_never_imports_sdk( + "datasette_apps", + "datasette_apps.telemetry", + "datasette_apps.telemetry_registry", + ) diff --git a/tests/test_telemetry_registry.py b/tests/test_telemetry_registry.py new file mode 100644 index 0000000..34dc1c2 --- /dev/null +++ b/tests/test_telemetry_registry.py @@ -0,0 +1,102 @@ +"""Static checks on datasette-apps' telemetry registry (no SDK needed).""" + +from datasette_apps.telemetry_registry import ( + APP_ID, + ATTRIBUTES, + DB_NAMESPACE, + DEBUG_JOB_ID, + HISTOGRAM, + METRICS, + SPANS, +) + +# Core's semantic-convention names, deliberately reused rather than shadowed. +CORE_ATTRIBUTES = {"db.namespace", "error.type"} + +# --- Wire names pinned as literals ---------------------------------------- +# +# A rename is a dashboard-breaking decision to take here, deliberately. If +# one of these fails, either revert the rename or update the literal in the +# same commit. + +EXPECTED_SPANS = {"apps.query"} + +EXPECTED_METRICS = { + "apps.queries", + "apps.query.duration", + "apps.changes", + "apps.debug.runs", + "apps.debug.run.duration", + "apps.debug.script.duration", + "apps.debug.jobs.expired", +} + +EXPECTED_ATTRIBUTES = { + "apps.app_id", + "apps.debug.job_id", + "apps.query.source", + "apps.query.kind", + "apps.query.write", + "apps.query.outcome", + "apps.query.rows", + "apps.change.operation", + "apps.change.via", + "apps.tool.result", + "apps.debug.outcome", + "db.namespace", + "error.type", +} + + +def test_wire_names_are_pinned(): + assert {str(s) for s in SPANS} == EXPECTED_SPANS + assert {str(m) for m in METRICS} == EXPECTED_METRICS + assert {str(a) for a in ATTRIBUTES} == EXPECTED_ATTRIBUTES + + +def test_registry_has_no_duplicate_names(): + for group in (SPANS, METRICS, ATTRIBUTES): + names = [str(entry) for entry in group] + assert len(names) == len(set(names)), f"duplicates in {names}" + + +def test_registry_entries_are_documented(): + for entry in (*SPANS, *METRICS, *ATTRIBUTES): + assert entry.description and entry.description.strip(), entry + + +def test_every_name_is_prefixed(): + for entry in (*SPANS, *METRICS): + assert str(entry).startswith("apps."), entry + for attribute in ATTRIBUTES: + name = str(attribute) + assert name.startswith("apps.") or name in CORE_ATTRIBUTES, attribute + + +def test_span_and_metric_attributes_are_registered(): + registered = set(ATTRIBUTES) + for entry in (*SPANS, *METRICS): + for attribute in entry.attributes: + assert attribute in registered, f"{entry!r} uses unlisted {attribute!r}" + + +def test_metric_dimensions_are_bounded(): + # Per-app, per-job and per-database dimensions ride on spans only. + unbounded = {str(APP_ID), str(DEBUG_JOB_ID), str(DB_NAMESPACE)} + for metric in METRICS: + for attribute in metric.attributes: + assert str(attribute) not in unbounded, f"{metric}: {attribute}" + assert ( + attribute.values is not None + ), f"{metric}: {attribute} declares no values= enum" + + +def test_only_histograms_have_increasing_buckets(): + for metric in METRICS: + if metric.kind == HISTOGRAM: + assert metric.buckets, f"{metric!r} declares no buckets" + assert all( + a < b for a, b in zip(metric.buckets, metric.buckets[1:]) + ), f"{metric!r} buckets are not strictly increasing" + else: + assert metric.buckets is None, f"{metric!r} is not a histogram" From 915bca1a679290b1f54cf0a0425b79e4629c53d6 Mon Sep 17 00:00:00 2001 From: Alex Garcia Date: Mon, 28 Sep 2026 12:46:28 -0700 Subject: [PATCH 2/5] Trace app data queries Adds an apps.query span plus apps.queries / apps.query.duration metrics around datasette.query() and datasette.storedQuery() calls, and tags request spans on app routes with apps.app_id. Co-Authored-By: Claude Opus 5.5 (1M context) --- datasette_apps/data_access.py | 85 ++++-- datasette_apps/telemetry.py | 19 ++ datasette_apps/views.py | 117 ++++---- tests/test_telemetry_queries.py | 503 ++++++++++++++++++++++++++++++++ 4 files changed, 653 insertions(+), 71 deletions(-) create mode 100644 tests/test_telemetry_queries.py diff --git a/datasette_apps/data_access.py b/datasette_apps/data_access.py index c7dcaf9..d9f8c68 100644 --- a/datasette_apps/data_access.py +++ b/datasette_apps/data_access.py @@ -4,20 +4,44 @@ from datasette.utils import tilde_encode +from . import telemetry from .registry import Registry class AppQueryError(Exception): - pass + """A query the app asked for that was refused or failed. + ``outcome`` classifies it for telemetry (``apps.query.outcome``): one of + ``invalid``, ``not_allowed``, ``not_found``, ``denied`` or ``failed``. + The message is shown to the app but never recorded in telemetry - for + ``failed`` it is Datasette's SQL error text, which can quote SQL. + """ -async def run_app_query(datasette, app, actor, database_name, sql, params=None): + def __init__(self, message, *, outcome="failed"): + super().__init__(message) + self.outcome = outcome + + +async def run_app_query( + datasette, app, actor, database_name, sql, params=None, recorder=None +): + """Run ``sql`` against ``database_name`` as ``actor``. + + ``recorder`` is an optional ``telemetry.QueryRecorder``; ``database`` is + set on it only once the database has passed the app's allowlist. + """ allowed_databases = await Registry(datasette).get_sql_databases(app["id"]) if database_name not in allowed_databases: - raise AppQueryError("This app is not allowed to query that database") + raise AppQueryError( + "This app is not allowed to query that database", outcome="not_allowed" + ) + if recorder is not None: + recorder.database = database_name if params is not None and not isinstance(params, dict): - raise AppQueryError("Query parameters must be an object of named values") + raise AppQueryError( + "Query parameters must be an object of named values", outcome="invalid" + ) query_args = { "sql": sql, @@ -30,19 +54,23 @@ async def run_app_query(datasette, app, actor, database_name, sql, params=None): try: database_path = datasette.urls.database(database_name) except KeyError as e: - raise AppQueryError("Database not found") from e + raise AppQueryError("Database not found", outcome="not_found") from e path = f"{database_path}/-/query.json?" + urlencode(query_args, doseq=True) - response = await datasette.client.get(path, actor=actor) + response = await datasette.client.get( + path, actor=actor, headers=telemetry.trace_headers() + ) try: data = response.json() except ValueError as e: if response.status_code in (401, 403): - raise AppQueryError("Permission denied by Datasette") from e - raise AppQueryError("Query failed") from e + raise AppQueryError( + "Permission denied by Datasette", outcome="denied" + ) from e + raise AppQueryError("Query failed", outcome="failed") from e if response.status_code in (401, 403): - raise AppQueryError("Permission denied by Datasette") + raise AppQueryError("Permission denied by Datasette", outcome="denied") if response.status_code != 200 or not data.get("ok"): - raise AppQueryError(data.get("error") or "Query failed") + raise AppQueryError(data.get("error") or "Query failed", outcome="failed") return { "columns": data.get("columns") or [], "rows": data.get("rows") or [], @@ -50,29 +78,44 @@ async def run_app_query(datasette, app, actor, database_name, sql, params=None): async def run_app_stored_query( - datasette, app, actor, database_name, query_name, params=None + datasette, app, actor, database_name, query_name, params=None, recorder=None ): + """Run the stored query ``database_name/query_name`` as ``actor``. + + ``recorder`` is an optional ``telemetry.QueryRecorder``: ``database`` is + set on it once the stored query has passed the app's allowlist, and + ``write`` once the stored query has been resolved. + """ allowed_queries = await Registry(datasette).get_stored_queries(app["id"]) if f"{database_name}/{query_name}" not in allowed_queries: - raise AppQueryError("This app is not allowed to run that stored query") + raise AppQueryError( + "This app is not allowed to run that stored query", outcome="not_allowed" + ) + if recorder is not None: + recorder.database = database_name if params is not None and not isinstance(params, dict): - raise AppQueryError("Query parameters must be an object of named values") + raise AppQueryError( + "Query parameters must be an object of named values", outcome="invalid" + ) stored_query = await datasette.get_query(database_name, query_name) if stored_query is None: - raise AppQueryError("Stored query not found") + raise AppQueryError("Stored query not found", outcome="not_found") + if recorder is not None: + recorder.write = bool(stored_query.is_write) try: database_path = datasette.urls.database(database_name) except KeyError as e: - raise AppQueryError("Database not found") from e + raise AppQueryError("Database not found", outcome="not_found") from e query_path = f"{database_path}/{tilde_encode(query_name)}" if stored_query.is_write: response = await datasette.client.post( query_path + "?_json=1", actor=actor, + headers=telemetry.trace_headers(), json={ key: "" if value is None else value for key, value in (params or {}).items() @@ -89,6 +132,7 @@ async def run_app_stored_query( response = await datasette.client.get( f"{query_path}.json?" + urlencode(query_args, doseq=True), actor=actor, + headers=telemetry.trace_headers(), ) data = _json_response_or_error(response) return { @@ -102,12 +146,15 @@ def _json_response_or_error(response): data = response.json() except ValueError as e: if response.status_code in (401, 403): - raise AppQueryError("Permission denied by Datasette") from e - raise AppQueryError("Stored query failed") from e + raise AppQueryError( + "Permission denied by Datasette", outcome="denied" + ) from e + raise AppQueryError("Stored query failed", outcome="failed") from e if response.status_code in (401, 403): - raise AppQueryError("Permission denied by Datasette") + raise AppQueryError("Permission denied by Datasette", outcome="denied") if response.status_code != 200 or data.get("ok") is False: raise AppQueryError( - data.get("error") or data.get("message") or "Stored query failed" + data.get("error") or data.get("message") or "Stored query failed", + outcome="failed", ) return data diff --git a/datasette_apps/telemetry.py b/datasette_apps/telemetry.py index d3a61c1..dc819cb 100644 --- a/datasette_apps/telemetry.py +++ b/datasette_apps/telemetry.py @@ -26,6 +26,7 @@ from datasette.telemetry import request_span from opentelemetry import metrics as otel_metrics from opentelemetry import trace as otel_trace +from opentelemetry.propagate import inject from opentelemetry.trace import Status, StatusCode from . import telemetry_registry as reg @@ -164,6 +165,24 @@ def record_debug_job_expired(): debug_jobs_expired.add(1) +def trace_headers(): + """W3C trace context headers for the current span, for ``datasette.client``. + + Core's ``TelemetryMiddleware`` starts every request's SERVER span from + ``extract(headers)``, which falls back to an empty context rather than + the current one, so without these headers an internal + ``datasette.client`` request lands in a separate trace instead of + nesting under the span that made it. Workaround for + https://github.com/simonw/datasette/issues/2969 - remove once the + minimum Datasette version propagates context itself. Uses the global + propagator, so ``OTEL_PROPAGATORS=none`` turns it off; with no provider + installed it returns ``{}``. + """ + headers = {} + inject(headers) + return headers + + class QueryRecorder: """What the body of ``query_span`` learns about one app query. diff --git a/datasette_apps/views.py b/datasette_apps/views.py index cf6b6a9..e97ac77 100644 --- a/datasette_apps/views.py +++ b/datasette_apps/views.py @@ -17,6 +17,7 @@ configured_csp_allowlist, resolve_csp_origins, ) +from . import telemetry from .data_access import AppQueryError, run_app_query, run_app_stored_query from .debug import ( debug_job_is_expired, @@ -27,6 +28,7 @@ from .prompt import build_llm_prompt_data, stored_query_options from .rendering import build_app_srcdoc, iframe_bridge_script, parent_bridge_script from .registry import Registry +from .telemetry_registry import APP_ID from .utils import sort_names_with_underscores_last @@ -437,6 +439,7 @@ async def view_app(datasette, request): app = await registry.get_app(app_id) if app is None or app["external"]: raise NotFound("App not found") + telemetry.annotate_request(request, {APP_ID: app_id}) await _ensure_app_permission(datasette, actor, "view-app", app_id) version = await registry.get_current_version(app_id) state = None @@ -480,6 +483,7 @@ async def edit_app(datasette, request): app = await registry.get_app(app_id) if app is None or app["external"]: raise NotFound("App not found") + telemetry.annotate_request(request, {APP_ID: app_id}) await _ensure_app_permission(datasette, actor, "edit-app", app_id) if request.method == "GET": version = await registry.get_current_version(app_id) @@ -563,6 +567,7 @@ async def delete_app(datasette, request): app = await registry.get_app(app_id) if app is None or app["external"]: raise NotFound("App not found") + telemetry.annotate_request(request, {APP_ID: app_id}) await _ensure_app_permission(datasette, actor, "delete-app", app_id) if request.method == "GET": return Response.html( @@ -590,6 +595,7 @@ async def app_revision(datasette, request): app = await registry.get_app(app_id) if app is None or app["external"]: raise NotFound("App not found") + telemetry.annotate_request(request, {APP_ID: app_id}) await _ensure_app_permission(datasette, actor, "edit-app", app_id) version = await registry.get_version(app_id, revision_number) if version is None: @@ -626,6 +632,7 @@ async def app_json(datasette, request): app = await registry.get_app(app_id) if app is None or app["external"]: raise NotFound("App not found") + telemetry.annotate_request(request, {APP_ID: app_id}) await _ensure_app_permission(datasette, actor, "view-app", app_id) version = await registry.get_current_version(app_id) return Response.json({"app": app, "version": version}) @@ -637,6 +644,7 @@ async def pin_app(datasette, request): registry = Registry(datasette) if await registry.get_app(app_id) is None: raise NotFound("App not found") + telemetry.annotate_request(request, {APP_ID: app_id}) await _ensure_app_permission(datasette, actor, "view-app", app_id) await registry.set_pinned(_actor_id(actor), app_id, True) return await _redirect_after_pin(request) @@ -648,6 +656,7 @@ async def unpin_app(datasette, request): registry = Registry(datasette) if await registry.get_app(app_id) is None: raise NotFound("App not found") + telemetry.annotate_request(request, {APP_ID: app_id}) await _ensure_app_permission(datasette, actor, "view-app", app_id) await registry.set_pinned(_actor_id(actor), app_id, False) return await _redirect_after_pin(request) @@ -660,34 +669,59 @@ async def app_query(datasette, request): app = await registry.get_app(app_id) if app is None or app["external"]: raise NotFound("App not found") + telemetry.annotate_request(request, {APP_ID: app_id}) await _ensure_app_permission(datasette, actor, "view-app", app_id) - try: - body = json.loads((await request.post_body()).decode("utf-8") or "{}") - if "query" in body: - # Keep stored query execution server-side so permission revocations - # apply immediately to app pages that are already loaded in browsers. - result = await run_app_stored_query( - datasette, - app, - actor, - body["database"], - body["query"], - body.get("params"), - ) - else: - result = await run_app_query( - datasette, - app, - actor, - body["database"], - body["sql"], - body.get("params"), - ) - return Response.json({"ok": True, "result": result}) - except (KeyError, json.JSONDecodeError) as e: - return Response.json({"ok": False, "error": f"Invalid request: {e}"}) - except AppQueryError as e: - return Response.json({"ok": False, "error": str(e)}) + return await _run_query_request(datasette, request, app, source="app") + + +async def _run_query_request(datasette, request, app, *, source, job_id=None): + """Parse an app's query request body and run it as the request's actor. + + Shared by ``app_query`` and ``debug_query``, and wrapped in one + ``apps.query`` span. Rejections return HTTP 200 with ``ok: false``; only + unexpected exceptions escape (and are recorded as outcome ``error``). + """ + with telemetry.query_span(source=source, app_id=app["id"], job_id=job_id) as q: + try: + body = json.loads((await request.post_body()).decode("utf-8") or "{}") + # No body.get() before dispatch: a non-dict body must keep + # raising exactly what it raised before. + if "query" in body: + q.kind = "stored" + # Keep stored query execution server-side so permission + # revocations apply immediately to app pages that are already + # loaded in browsers. + result = await run_app_stored_query( + datasette, + app, + request.actor, + body["database"], + body["query"], + body.get("params"), + recorder=q, + ) + else: + q.kind = "sql" + result = await run_app_query( + datasette, + app, + request.actor, + body["database"], + body["sql"], + body.get("params"), + recorder=q, + ) + q.outcome = "ok" + if not q.write: + # Stored write queries return Datasette's raw JSON, not rows. + q.rows = len(result.get("rows") or []) + return Response.json({"ok": True, "result": result}) + except (KeyError, json.JSONDecodeError) as e: + q.outcome = "invalid" + return Response.json({"ok": False, "error": f"Invalid request: {e}"}) + except AppQueryError as e: + q.outcome = e.outcome + return Response.json({"ok": False, "error": str(e)}) async def _debug_job_or_404(datasette, request): @@ -754,31 +788,9 @@ async def debug_query(datasette, request): app = await Registry(datasette).get_app(job["app_id"]) if app is None: raise NotFound("App not found") - try: - body = json.loads((await request.post_body()).decode("utf-8") or "{}") - if "query" in body: - result = await run_app_stored_query( - datasette, - app, - request.actor, - body["database"], - body["query"], - body.get("params"), - ) - else: - result = await run_app_query( - datasette, - app, - request.actor, - body["database"], - body["sql"], - body.get("params"), - ) - return Response.json({"ok": True, "result": result}) - except (KeyError, json.JSONDecodeError) as e: - return Response.json({"ok": False, "error": f"Invalid request: {e}"}) - except AppQueryError as e: - return Response.json({"ok": False, "error": str(e)}) + return await _run_query_request( + datasette, request, app, source="debug", job_id=job["id"] + ) async def launch_app(datasette, request): @@ -788,6 +800,7 @@ async def launch_app(datasette, request): app = await registry.get_app(app_id) if app is None: raise NotFound("App not found") + telemetry.annotate_request(request, {APP_ID: app_id}) await _ensure_app_permission(datasette, actor, "view-app", app_id) if not app["external"]: return Response.redirect(app["path"]) diff --git a/tests/test_telemetry_queries.py b/tests/test_telemetry_queries.py new file mode 100644 index 0000000..fd79c45 --- /dev/null +++ b/tests/test_telemetry_queries.py @@ -0,0 +1,503 @@ +"""Telemetry for app data queries: the apps.query span, the apps.queries and +apps.query.duration metrics, and apps.app_id on app routes' request spans.""" + +import json +import sqlite3 + +import pytest + +pytest.importorskip("opentelemetry.sdk") + +from datasette.app import Datasette +from datasette.telemetry_testing import assert_metrics_conform, assert_spans_conform +from opentelemetry.trace import SpanKind, StatusCode + +from datasette_apps import Registry, telemetry_registry +from datasette_apps.debug import create_debug_job + +ACTOR = {"id": "alice"} + + +def create_database(tmp_path): + db_path = tmp_path / "content.db" + conn = sqlite3.connect(db_path) + conn.executescript(""" + create table news (id integer primary key, title text); + insert into news (title) values ('First'), ('Second'); + """) + conn.close() + return db_path + + +async def _make_app(datasette, *, sql_databases=("content",), stored_queries=()): + return await Registry(datasette).create_stored_app( + actor_id="alice", + name="News app", + description="", + html="

News

", + sql_databases=list(sql_databases), + stored_queries=list(stored_queries), + ) + + +async def _datasette(tmp_path, **kwargs): + datasette = Datasette([str(create_database(tmp_path))], **kwargs) + await datasette.invoke_startup() + return datasette + + +async def _post_query(datasette, app, body): + return await datasette.client.post( + f"/-/apps/{app['id']}/query", + actor=ACTOR, + content=body if isinstance(body, str) else json.dumps(body), + ) + + +def _query_span(otel_spans): + spans = [ + span + for span in otel_spans.get_finished_spans() + if span.name == telemetry_registry.QUERY + ] + assert len(spans) == 1, spans + return spans[0] + + +def _children(otel_spans, parent): + return [ + span + for span in otel_spans.get_finished_spans() + if span.parent is not None and span.parent.span_id == parent.context.span_id + ] + + +def _assert_conforms(otel_spans, otel_metrics): + assert_spans_conform( + telemetry_registry.SPANS, + otel_spans.get_finished_spans(), + scope_name="datasette_apps", + ) + assert_metrics_conform( + telemetry_registry.METRICS, otel_metrics, scope_name="datasette_apps" + ) + + +def _assert_one_query_metric(otel_metrics, **attributes): + otel_metrics.collect() + counted = otel_metrics.point("apps.queries", attributes) + assert counted.value == 1 + assert dict(counted.attributes) == attributes + duration = otel_metrics.point("apps.query.duration") + assert duration.count == 1 + for key in ("apps.app_id", "db.namespace", "apps.debug.job_id"): + assert key not in duration.attributes + return counted + + +@pytest.mark.asyncio +async def test_ok_sql_query(tmp_path, otel_spans, otel_metrics): + datasette = await _datasette(tmp_path) + app = await _make_app(datasette) + + response = await _post_query( + datasette, app, {"database": "content", "sql": "select title from news"} + ) + assert response.json()["ok"] is True + + span = _query_span(otel_spans) + assert dict(span.attributes) == { + "apps.app_id": app["id"], + "apps.query.source": "app", + "apps.query.outcome": "ok", + "apps.query.kind": "sql", + "db.namespace": "content", + "apps.query.rows": 2, + } + assert span.status.status_code == StatusCode.UNSET + _assert_one_query_metric( + otel_metrics, + **{ + "apps.query.source": "app", + "apps.query.outcome": "ok", + "apps.query.kind": "sql", + }, + ) + _assert_conforms(otel_spans, otel_metrics) + + +@pytest.mark.asyncio +async def test_internal_client_span_nests_under_apps_query(tmp_path, otel_spans): + datasette = await _datasette(tmp_path) + app = await _make_app(datasette) + + await _post_query( + datasette, app, {"database": "content", "sql": "select title from news"} + ) + + span = _query_span(otel_spans) + nested = [ + child + for child in _children(otel_spans, span) + if child.kind == SpanKind.SERVER + and child.attributes.get("datasette.internal_client") is True + ] + assert len(nested) == 1 + assert nested[0].context.trace_id == span.context.trace_id + assert nested[0].attributes["url.path"].endswith("/content/-/query.json") + + +@pytest.mark.asyncio +async def test_not_allowed_database(tmp_path, otel_spans, otel_metrics): + datasette = await _datasette(tmp_path, memory=True) + app = await _make_app(datasette) + + response = await _post_query( + datasette, app, {"database": "_memory", "sql": "select 1"} + ) + assert "not allowed" in response.json()["error"] + + span = _query_span(otel_spans) + assert span.attributes["apps.query.outcome"] == "not_allowed" + assert span.attributes["apps.query.kind"] == "sql" + # The requested database name is unvetted input until it passes the + # allowlist, so it is never recorded. + assert "db.namespace" not in span.attributes + assert "apps.query.rows" not in span.attributes + assert span.status.status_code == StatusCode.UNSET + assert not [ + child for child in _children(otel_spans, span) if child.kind == SpanKind.SERVER + ] + _assert_one_query_metric( + otel_metrics, + **{ + "apps.query.source": "app", + "apps.query.outcome": "not_allowed", + "apps.query.kind": "sql", + }, + ) + _assert_conforms(otel_spans, otel_metrics) + + +@pytest.mark.asyncio +async def test_denied_by_actor_permissions(tmp_path, otel_spans, otel_metrics): + datasette = await _datasette(tmp_path, default_deny=True) + app = await _make_app(datasette) + + response = await _post_query( + datasette, app, {"database": "content", "sql": "select title from news"} + ) + assert "Permission denied" in response.json()["error"] + + span = _query_span(otel_spans) + assert span.attributes["apps.query.outcome"] == "denied" + assert span.attributes["db.namespace"] == "content" + assert span.status.status_code == StatusCode.UNSET + _assert_one_query_metric( + otel_metrics, + **{ + "apps.query.source": "app", + "apps.query.outcome": "denied", + "apps.query.kind": "sql", + }, + ) + + +@pytest.mark.asyncio +async def test_failed_sql_records_no_error_text(tmp_path, otel_spans, otel_metrics): + datasette = await _datasette(tmp_path) + app = await _make_app(datasette) + + response = await _post_query( + datasette, app, {"database": "content", "sql": "select * from nope"} + ) + error = response.json()["error"] + assert "nope" in error + + span = _query_span(otel_spans) + assert span.attributes["apps.query.outcome"] == "failed" + assert span.status.status_code == StatusCode.UNSET + assert "error.type" not in span.attributes + assert not span.events + for value in span.attributes.values(): + assert "nope" not in str(value) + _assert_one_query_metric( + otel_metrics, + **{ + "apps.query.source": "app", + "apps.query.outcome": "failed", + "apps.query.kind": "sql", + }, + ) + + +@pytest.mark.asyncio +@pytest.mark.parametrize( + "body,kind", + [ + ({"database": "content"}, "sql"), # missing "sql": KeyError + ({"database": "content", "sql": "select 1", "params": [1]}, "sql"), + ("not json", None), + ], +) +async def test_invalid_requests(tmp_path, otel_spans, otel_metrics, body, kind): + datasette = await _datasette(tmp_path) + app = await _make_app(datasette) + + response = await _post_query(datasette, app, body) + assert response.status_code == 200 + assert response.json()["ok"] is False + + span = _query_span(otel_spans) + assert span.attributes["apps.query.outcome"] == "invalid" + assert span.attributes.get("apps.query.kind") == kind + assert span.status.status_code == StatusCode.UNSET + expected = {"apps.query.source": "app", "apps.query.outcome": "invalid"} + if kind: + expected["apps.query.kind"] = kind + _assert_one_query_metric(otel_metrics, **expected) + _assert_conforms(otel_spans, otel_metrics) + + +@pytest.mark.asyncio +async def test_non_object_body_is_recorded_as_error(tmp_path, otel_spans, otel_metrics): + # Pre-existing bug, deliberately left alone here: a JSON body that is not + # an object raises TypeError, which is not caught and becomes a 500. + # Telemetry records it as an unexpected error, not as "invalid". + datasette = await _datasette(tmp_path) + app = await _make_app(datasette) + + response = await _post_query(datasette, app, "[]") + assert response.status_code == 500 + + span = _query_span(otel_spans) + assert span.attributes["apps.query.outcome"] == "error" + assert span.attributes["error.type"] == "TypeError" + assert span.status.status_code == StatusCode.ERROR + assert not span.events # the exception itself is never recorded + otel_metrics.collect() + assert ( + otel_metrics.point( + "apps.queries", {"apps.query.source": "app", "apps.query.outcome": "error"} + ).value + == 1 + ) + _assert_conforms(otel_spans, otel_metrics) + + +@pytest.mark.asyncio +async def test_stored_query_not_found(tmp_path, otel_spans, otel_metrics): + datasette = await _datasette(tmp_path) + # Allow-listed, but never created + app = await _make_app(datasette, stored_queries=["content/missing"]) + + response = await _post_query( + datasette, app, {"database": "content", "query": "missing"} + ) + assert response.json() == {"ok": False, "error": "Stored query not found"} + + span = _query_span(otel_spans) + assert span.attributes["apps.query.outcome"] == "not_found" + assert span.attributes["apps.query.kind"] == "stored" + assert "apps.query.write" not in span.attributes + _assert_one_query_metric( + otel_metrics, + **{ + "apps.query.source": "app", + "apps.query.outcome": "not_found", + "apps.query.kind": "stored", + }, + ) + for value in span.attributes.values(): + assert "missing" not in str(value) + + +@pytest.mark.asyncio +async def test_stored_query_not_allowed(tmp_path, otel_spans): + datasette = await _datasette(tmp_path) + app = await _make_app(datasette) + + await _post_query(datasette, app, {"database": "content", "query": "anything"}) + + span = _query_span(otel_spans) + assert span.attributes["apps.query.outcome"] == "not_allowed" + assert "db.namespace" not in span.attributes + + +@pytest.mark.asyncio +async def test_stored_read_query(tmp_path, otel_spans, otel_metrics): + datasette = await _datasette(tmp_path) + await datasette.add_query( + "content", + "news_by_id", + "select title from news where id = :id", + source="user", + owner_id="alice", + ) + app = await _make_app(datasette, stored_queries=["content/news_by_id"]) + + response = await _post_query( + datasette, + app, + {"database": "content", "query": "news_by_id", "params": {"id": 2}}, + ) + assert response.json()["result"]["rows"] == [{"title": "Second"}] + + span = _query_span(otel_spans) + assert dict(span.attributes) == { + "apps.app_id": app["id"], + "apps.query.source": "app", + "apps.query.outcome": "ok", + "apps.query.kind": "stored", + "apps.query.write": False, + "db.namespace": "content", + "apps.query.rows": 1, + } + _assert_one_query_metric( + otel_metrics, + **{ + "apps.query.source": "app", + "apps.query.outcome": "ok", + "apps.query.kind": "stored", + "apps.query.write": False, + }, + ) + _assert_conforms(otel_spans, otel_metrics) + + +@pytest.mark.asyncio +async def test_stored_write_query(tmp_path, otel_spans, otel_metrics): + datasette = await _datasette(tmp_path) + await datasette.add_query( + "content", + "add_news", + "insert into news (title) values (:title)", + is_write=True, + # Trusted, so it runs without the actor needing execute-write-sql + is_trusted=True, + source="user", + owner_id="alice", + ) + app = await _make_app(datasette, stored_queries=["content/add_news"]) + + response = await _post_query( + datasette, + app, + {"database": "content", "query": "add_news", "params": {"title": "Third"}}, + ) + assert response.json()["ok"] is True, response.json() + + span = _query_span(otel_spans) + assert span.attributes["apps.query.outcome"] == "ok" + assert span.attributes["apps.query.kind"] == "stored" + assert span.attributes["apps.query.write"] is True + assert "apps.query.rows" not in span.attributes + _assert_one_query_metric( + otel_metrics, + **{ + "apps.query.source": "app", + "apps.query.outcome": "ok", + "apps.query.kind": "stored", + "apps.query.write": True, + }, + ) + _assert_conforms(otel_spans, otel_metrics) + + +@pytest.mark.asyncio +async def test_debug_query_source_and_job_id(tmp_path, otel_spans, otel_metrics): + datasette = await _datasette(tmp_path) + app = await _make_app(datasette) + job = await create_debug_job( + datasette, app_id=app["id"], actor_id="alice", javascript="return 1;" + ) + + response = await datasette.client.post( + f"/-/apps/debug/{job['id']}/query", + actor=ACTOR, + json={"database": "content", "sql": "select title from news"}, + ) + assert response.json()["ok"] is True + + span = _query_span(otel_spans) + assert span.attributes["apps.query.source"] == "debug" + assert span.attributes["apps.debug.job_id"] == job["id"] + assert span.attributes["apps.app_id"] == app["id"] + _assert_one_query_metric( + otel_metrics, + **{ + "apps.query.source": "debug", + "apps.query.outcome": "ok", + "apps.query.kind": "sql", + }, + ) + _assert_conforms(otel_spans, otel_metrics) + + +# --- apps.app_id on core's request spans ---------------------------------- + + +def _request_span(otel_spans): + # Tests drive the app through datasette.client, so the outer request + # span is itself flagged datasette.internal_client; it is the root + # SERVER span. (In production it would not carry the flag.) + spans = [ + span + for span in otel_spans.get_finished_spans() + if span.kind == SpanKind.SERVER and span.parent is None + ] + assert len(spans) == 1, spans + return spans[0] + + +@pytest.mark.asyncio +@pytest.mark.parametrize( + "method,path_template,kwargs,status", + [ + ("GET", "/-/apps/{id}", {}, 200), + ("GET", "/-/apps/{id}.json", {}, 200), + ("GET", "/-/apps/{id}/edit", {}, 200), + ("GET", "/-/apps/{id}/delete", {}, 200), + ("GET", "/-/apps/{id}/revisions/1", {}, 200), + ("GET", "/-/apps/{id}/launch", {}, 302), + ( + "POST", + "/-/apps/{id}/query", + {"json": {"database": "content", "sql": "select 1"}}, + 200, + ), + ], +) +async def test_app_routes_tag_request_span_with_app_id( + tmp_path, otel_spans, method, path_template, kwargs, status +): + datasette = await _datasette(tmp_path) + app = await _make_app(datasette) + + response = await datasette.client.request( + method, path_template.format(id=app["id"]), actor=ACTOR, **kwargs + ) + assert response.status_code == status + + assert _request_span(otel_spans).attributes["apps.app_id"] == app["id"] + + +@pytest.mark.asyncio +@pytest.mark.parametrize("action", ["pin", "unpin"]) +async def test_pin_routes_tag_request_span_with_app_id(tmp_path, otel_spans, action): + datasette = await _datasette(tmp_path) + app = await _make_app(datasette) + response = await datasette.client.post(f"/-/apps/{app['id']}/{action}", actor=ACTOR) + assert response.status_code == 302 + + assert _request_span(otel_spans).attributes["apps.app_id"] == app["id"] + + +@pytest.mark.asyncio +async def test_unknown_app_id_is_not_recorded(tmp_path, otel_spans): + datasette = await _datasette(tmp_path) + + response = await datasette.client.get("/-/apps/nope", actor=ACTOR) + assert response.status_code == 404 + + assert "apps.app_id" not in _request_span(otel_spans).attributes From 5b9912c07a088cbfdfb31aa7d29e5853dacb2a76 Mon Sep 17 00:00:00 2001 From: Alex Garcia Date: Mon, 28 Sep 2026 12:53:23 -0700 Subject: [PATCH 3/5] Count app changes and tag agent tool spans apps.changes counts creates, edits, deletes and pins by channel (web or agent). Agent tools set apps.app_id and apps.tool.result on the current span, which is datasette-agent's execute_tool span when it has telemetry. Co-Authored-By: Claude Opus 5.5 (1M context) --- datasette_apps/agent_tools.py | 110 ++++-- datasette_apps/telemetry_registry.py | 18 +- datasette_apps/views.py | 5 + tests/test_telemetry_changes.py | 477 +++++++++++++++++++++++++++ 4 files changed, 586 insertions(+), 24 deletions(-) create mode 100644 tests/test_telemetry_changes.py diff --git a/datasette_apps/agent_tools.py b/datasette_apps/agent_tools.py index 338e141..818c5bf 100644 --- a/datasette_apps/agent_tools.py +++ b/datasette_apps/agent_tools.py @@ -5,6 +5,7 @@ from datasette_agent_edit import EditError, EditToolset, Editable, NotFound +from . import telemetry from .csp import configured_csp_allowlist, resolve_csp_origins from .debug import ( BROWSER_TASK_SLACK_MS, @@ -18,6 +19,7 @@ ) from .permissions import AppResource, AppsResource from .registry import Registry, _fts_query +from .telemetry_registry import APP_ID, TOOL_RESULT APP_RUNTIME_API_GUIDANCE = ( " Apps run in a sandboxed iframe. For data access, use " @@ -153,6 +155,9 @@ async def edit(self, ref, transform): raise NotFound(ref) from e if version is None: raise NotFound(ref) + # One call is one saved edit, however many operations app_edit + # batched into it; a failed transform raised above and never counts. + telemetry.record_change("edit", "agent") app = await self.registry.get_app(ref) return Editable( ref=ref, @@ -226,6 +231,40 @@ def _error(message, app_id=None): return json.dumps(payload) +def _tool_result(result): + """Classify a tool's returned JSON string as ``ok``/``error``/``denied``. + + Our tools (and datasette-agent-edit's ``EditToolset``) report failures + as a returned ``{"error": ...}`` object rather than raising. The message + is only matched on its prefix, never recorded. + """ + if not isinstance(result, str) or '"error"' not in result: + return "ok" + try: + payload = json.loads(result) + except ValueError: + return "ok" + if not isinstance(payload, dict) or "error" not in payload: + return "ok" + message = payload["error"] + if isinstance(message, str) and message.startswith("Permission denied"): + return "denied" + return "error" + + +def _annotate_tool(result, app_id=None): + """Tag the current span - datasette-agent's ``execute_tool`` span when it + has telemetry - with the app ID and how the tool ended. Returns + ``result`` unchanged.""" + telemetry.annotate_current_span( + { + APP_ID: app_id if isinstance(app_id, str) and app_id else None, + TOOL_RESULT: _tool_result(result), + } + ) + return result + + async def _app_create( datasette, actor, @@ -238,7 +277,7 @@ async def _app_create( csp_origins=None, ): if not await _can_create_app(datasette, actor): - return _error("Permission denied: create-app") + return _annotate_tool(_error("Permission denied: create-app")) try: csp_origins = await resolve_csp_origins(datasette, actor, csp_origins or []) app = await Registry(datasette).create_stored_app( @@ -252,8 +291,9 @@ async def _app_create( csp_origins=csp_origins or [], ) except ValueError as e: - return _error(str(e)) - return json.dumps( + return _annotate_tool(_error(str(e))) + telemetry.record_change("create", "agent") + result = json.dumps( { "app_id": app["id"], "name": app["name"], @@ -269,15 +309,16 @@ async def _app_create( ), } ) + return _annotate_tool(result, app["id"]) async def _app_list(datasette, actor, query=None, limit=10): try: limit = int(limit) except (TypeError, ValueError): - return _error("limit must be an integer between 1 and 20") + return _annotate_tool(_error("limit must be an integer between 1 and 20")) if limit < 1 or limit > 20: - return _error("limit must be an integer between 1 and 20") + return _annotate_tool(_error("limit must be an integer between 1 and 20")) await Registry(datasette).ensure_tables() allowed_sql, allowed_params = await datasette.allowed_resources_sql( @@ -299,13 +340,15 @@ async def _app_list(datasette, actor, query=None, limit=10): if query: fts_query = _fts_query(query) if not fts_query: - return json.dumps( - { - "query": query, - "apps": [], - "returned_count": 0, - "has_more": False, - } + return _annotate_tool( + json.dumps( + { + "query": query, + "apps": [], + "returned_count": 0, + "has_more": False, + } + ) ) join_search = "JOIN apps_fts ON apps.rowid = apps_fts.rowid" search_filter = "AND apps_fts MATCH :fts_query" @@ -383,20 +426,45 @@ async def _app_list(datasette, actor, query=None, limit=10): } for row in rows[:limit] ] - return json.dumps( - { - "query": query, - "apps": apps, - "returned_count": len(apps), - "has_more": has_more, - } + return _annotate_tool( + json.dumps( + { + "query": query, + "apps": apps, + "returned_count": len(apps), + "has_more": has_more, + } + ) ) +async def _existing_stored_app_id(datasette, app_id): + """``app_id`` if it names an existing, non-deleted stored app, else None. + + ``app_id`` is model-supplied text, so it is only recorded on a span once + it is known to be a real app - the same rule as the app routes, which + tag the request span only after their 404 check. + """ + if not isinstance(app_id, str) or not app_id: + return None + app = await Registry(datasette).get_app(app_id) + if app is None or app["external"]: + return None + return app_id + + async def _with_app_edit_permission(datasette, actor, app_id, callback): if not await _can_edit_app(datasette, actor, app_id): - return _error("Permission denied: edit-app", app_id=app_id) - return await callback() + result = _error("Permission denied: edit-app", app_id=app_id) + else: + result = await callback() + # EditToolset only succeeds after reading or editing the stored app, so + # an ok result proves the ID; anything else needs a lookup. + if _tool_result(result) == "ok": + known_app_id = app_id + else: + known_app_id = await _existing_stored_app_id(datasette, app_id) + return _annotate_tool(result, known_app_id) def _csp_origins_schema_description(datasette=None): diff --git a/datasette_apps/telemetry_registry.py b/datasette_apps/telemetry_registry.py index c627eea..cac65e3 100644 --- a/datasette_apps/telemetry_registry.py +++ b/datasette_apps/telemetry_registry.py @@ -55,7 +55,10 @@ "apps.app_id", "The app's ID: a ULID for stored apps, or a plugin-supplied ID for " "external apps. Unbounded, so it rides on spans only - **never on a " - "metric**.", + "metric**. Also set on the current span inside this plugin's agent " + "tools, which with datasette-agent's telemetry is its ``execute_tool`` " + "span - an attribute from this plugin on a span in the " + "``datasette_agent`` scope.", ) DEBUG_JOB_ID = Attribute( "apps.debug.job_id", @@ -119,7 +122,11 @@ "apps.tool.result", "How one of this plugin's agent tools ended: ``ok``, ``error`` or " "``denied`` (the actor lacked permission). Set on the current tool span " - "(datasette-agent's ``execute_tool`` span), not on a span of our own.", + "(datasette-agent's ``execute_tool`` span), not on a span of our own, " + "so it sits in the ``datasette_agent`` scope; with a datasette-agent " + "that has no telemetry it lands on whatever span is current, or " + "nowhere. Set only when the tool returns: an exception escaping the " + "tool leaves it unset.", values={"ok", "error", "denied"}, ) DEBUG_OUTCOME = Attribute( @@ -195,7 +202,12 @@ COUNTER, "{change}", "App changes (create, edit, delete, pin, unpin), by operation and " - "whether they came from the web UI or the agent.", + "whether they came from the web UI or the agent. Counted only after the " + "write succeeded. An edit is one submitted and saved edit form or agent " + "edit call (an ``app_edit`` batch counts once), even when nothing " + "changed and no revision was written. Apps registered by other plugins " + "through the ``Registry`` API (``add_app``/``add_apps``) are not " + "counted.", attributes=(CHANGE_OPERATION, CHANGE_VIA), ) M_DEBUG_RUNS = MetricName( diff --git a/datasette_apps/views.py b/datasette_apps/views.py index e97ac77..eb592ee 100644 --- a/datasette_apps/views.py +++ b/datasette_apps/views.py @@ -429,6 +429,7 @@ async def create_app(datasette, request): stored_queries=stored_queries, csp_origins=csp_origins, ) + telemetry.record_change("create", "web") return Response.redirect(app["path"]) @@ -557,6 +558,7 @@ async def edit_app(datasette, request): actor_id=actor_id, **update_kwargs, ) + telemetry.record_change("edit", "web") return Response.redirect(f"/-/apps/{app_id}") @@ -584,6 +586,7 @@ async def delete_app(datasette, request): await registry.delete_stored_app(app_id, actor_id=_actor_id(actor)) except (KeyError, ValueError) as e: raise NotFound("App not found") from e + telemetry.record_change("delete", "web") return Response.redirect("/-/apps") @@ -647,6 +650,7 @@ async def pin_app(datasette, request): telemetry.annotate_request(request, {APP_ID: app_id}) await _ensure_app_permission(datasette, actor, "view-app", app_id) await registry.set_pinned(_actor_id(actor), app_id, True) + telemetry.record_change("pin", "web") return await _redirect_after_pin(request) @@ -659,6 +663,7 @@ async def unpin_app(datasette, request): telemetry.annotate_request(request, {APP_ID: app_id}) await _ensure_app_permission(datasette, actor, "view-app", app_id) await registry.set_pinned(_actor_id(actor), app_id, False) + telemetry.record_change("unpin", "web") return await _redirect_after_pin(request) diff --git a/tests/test_telemetry_changes.py b/tests/test_telemetry_changes.py new file mode 100644 index 0000000..2ad24c1 --- /dev/null +++ b/tests/test_telemetry_changes.py @@ -0,0 +1,477 @@ +"""Telemetry for app changes and agent tools: the apps.changes counter and +apps.app_id / apps.tool.result on the current (tool) span.""" + +from dataclasses import dataclass +import json + +import pytest + +pytest.importorskip("opentelemetry.sdk") + +from datasette.app import Datasette +from datasette.telemetry_testing import assert_metrics_conform +from opentelemetry import trace + +from datasette_apps import Registry, agent_tools, telemetry_registry +from datasette_apps.agent_tools import get_app_edit_tools + + +@dataclass +class FakeAgentTool: + name: str + description: str + input_schema: dict + fn: object + required_permission: str | None = None + + +ALICE = {"id": "alice"} +BOB = {"id": "bob"} + + +def _tools_by_name(): + return {tool.name: tool for tool in get_app_edit_tools(FakeAgentTool)} + + +async def _datasette(**kwargs): + datasette = Datasette(memory=True, **kwargs) + await datasette.invoke_startup() + return datasette + + +async def _make_app(datasette, html="

Hello

\n

World

\n"): + return await Registry(datasette).create_stored_app( + actor_id="alice", name="Target app", description="", html=html + ) + + +def _changes(otel_metrics): + otel_metrics.collect() + return { + ( + point.attributes["apps.change.operation"], + point.attributes["apps.change.via"], + ): point.value + for point in otel_metrics.points("apps.changes") + } + + +def _assert_metrics_conform(otel_metrics): + assert_metrics_conform( + telemetry_registry.METRICS, otel_metrics, scope_name="datasette_apps" + ) + for point in otel_metrics.points("apps.changes"): + assert set(point.attributes) == {"apps.change.operation", "apps.change.via"} + + +async def _call_in_tool_span(otel_spans, tool, **kwargs): + """Run a tool inside a test-owned span standing in for datasette-agent's + execute_tool span; return (result, that span's attributes).""" + name = f"execute_tool {tool.name}" + with trace.get_tracer("test").start_as_current_span(name): + result = await tool.fn(**kwargs) + spans = [s for s in otel_spans.get_finished_spans() if s.name == name] + assert len(spans) == 1, spans + return result, dict(spans[0].attributes) + + +# --- Web -------------------------------------------------------------------- + + +@pytest.mark.asyncio +async def test_web_changes_are_counted(otel_metrics): + datasette = await _datasette( + config={"permissions": {"create-app": {"id": "alice"}}} + ) + + create = await datasette.client.post( + "/-/apps/create", actor=ALICE, data={"name": "Web app", "html": "

Hi

"} + ) + assert create.status_code == 302 + app_id = create.headers["location"].rsplit("/", 1)[-1] + + edit = await datasette.client.post( + f"/-/apps/{app_id}/edit", + actor=ALICE, + data={"name": "Web app", "html": "

Updated

"}, + ) + assert edit.status_code == 302 + for action in ("pin", "unpin"): + response = await datasette.client.post( + f"/-/apps/{app_id}/{action}", actor=ALICE + ) + assert response.status_code == 302 + deleted = await datasette.client.post(f"/-/apps/{app_id}/delete", actor=ALICE) + assert deleted.status_code == 302 + + assert _changes(otel_metrics) == { + ("create", "web"): 1, + ("edit", "web"): 1, + ("pin", "web"): 1, + ("unpin", "web"): 1, + ("delete", "web"): 1, + } + _assert_metrics_conform(otel_metrics) + + +@pytest.mark.asyncio +async def test_web_edit_without_changes_still_counts(otel_metrics): + # The metric is "edit submitted and saved": a no-op POST writes no + # revision but still counts. + datasette = await _datasette() + app = await _make_app(datasette, html="

Same

") + + response = await datasette.client.post( + f"/-/apps/{app['id']}/edit", + actor=ALICE, + data={"name": "Target app", "html": "

Same

"}, + ) + assert response.status_code == 302 + assert len(await Registry(datasette).list_versions(app["id"])) == 1 + assert _changes(otel_metrics) == {("edit", "web"): 1} + + +@pytest.mark.asyncio +async def test_forbidden_web_changes_are_not_counted(otel_metrics): + datasette = await _datasette() + app = await _make_app(datasette) + + for path in ("delete", "edit"): + response = await datasette.client.post( + f"/-/apps/{app['id']}/{path}", actor=BOB, data={"html": "

x

"} + ) + assert response.status_code == 403 + create = await datasette.client.post( + "/-/apps/create", actor=BOB, data={"name": "Nope", "html": "

x

"} + ) + assert create.status_code == 403 + missing = await datasette.client.post("/-/apps/nope/delete", actor=ALICE) + assert missing.status_code == 404 + + assert _changes(otel_metrics) == {} + + +@pytest.mark.asyncio +async def test_plugin_registered_apps_are_not_counted(otel_metrics): + datasette = await _datasette() + await Registry(datasette).add_app( + id="plugin:one", name="Plugin One", description="", path="/plugin-one" + ) + assert _changes(otel_metrics) == {} + + +# --- Agent ------------------------------------------------------------------ + + +@pytest.mark.asyncio +async def test_agent_create_counts_and_tags_span(otel_spans, otel_metrics): + datasette = await _datasette( + config={"permissions": {"create-app": {"id": "alice"}}} + ) + tools = _tools_by_name() + + result, attributes = await _call_in_tool_span( + otel_spans, + tools["app_create"], + datasette=datasette, + actor=ALICE, + name="Agent app", + html="

Secret HTML

", + ) + app_id = json.loads(result)["app_id"] + assert attributes["apps.app_id"] == app_id + assert attributes["apps.tool.result"] == "ok" + assert _changes(otel_metrics) == {("create", "agent"): 1} + _assert_metrics_conform(otel_metrics) + + +@pytest.mark.asyncio +async def test_agent_create_denied(otel_spans, otel_metrics): + datasette = await _datasette() + result, attributes = await _call_in_tool_span( + otel_spans, + _tools_by_name()["app_create"], + datasette=datasette, + actor=ALICE, + name="Denied app", + html="

x

", + ) + assert json.loads(result)["error"].startswith("Permission denied") + assert attributes["apps.tool.result"] == "denied" + assert "apps.app_id" not in attributes + assert _changes(otel_metrics) == {} + + +@pytest.mark.asyncio +async def test_agent_create_error(otel_spans, otel_metrics): + datasette = await _datasette( + config={"permissions": {"create-app": {"id": "alice"}}} + ) + result, attributes = await _call_in_tool_span( + otel_spans, + _tools_by_name()["app_create"], + datasette=datasette, + actor=ALICE, + name="Bad CSP", + html="

x

", + csp_origins=["not an origin"], + ) + assert "error" in json.loads(result) + assert attributes["apps.tool.result"] == "error" + assert "apps.app_id" not in attributes + assert _changes(otel_metrics) == {} + + +@pytest.mark.asyncio +async def test_agent_edit_batch_counts_once(otel_spans, otel_metrics): + datasette = await _datasette() + app = await _make_app(datasette) + + result, attributes = await _call_in_tool_span( + otel_spans, + _tools_by_name()["app_edit"], + datasette=datasette, + actor=ALICE, + app_id=app["id"], + edits=[ + {"operation": "str_replace", "old_str": "Hello", "new_str": "Goodbye"}, + {"operation": "insert", "insert_line": 2, "insert_text": "
\n"}, + ], + ) + assert json.loads(result)["edits_applied"] == 2 + assert attributes["apps.app_id"] == app["id"] + assert attributes["apps.tool.result"] == "ok" + assert _changes(otel_metrics) == {("edit", "agent"): 1} + _assert_metrics_conform(otel_metrics) + + +@pytest.mark.asyncio +async def test_agent_edit_partial_failure_is_not_counted(otel_spans, otel_metrics): + datasette = await _datasette() + app = await _make_app(datasette) + + result, attributes = await _call_in_tool_span( + otel_spans, + _tools_by_name()["app_edit"], + datasette=datasette, + actor=ALICE, + app_id=app["id"], + edits=[ + {"operation": "str_replace", "old_str": "Hello", "new_str": "Goodbye"}, + {"operation": "str_replace", "old_str": "Missing", "new_str": "Nope"}, + ], + ) + assert "Edit #2 failed" in json.loads(result)["error"] + assert attributes["apps.app_id"] == app["id"] + assert attributes["apps.tool.result"] == "error" + assert _changes(otel_metrics) == {} + + +@pytest.mark.asyncio +async def test_agent_edit_denied_is_not_counted(otel_spans, otel_metrics): + datasette = await _datasette() + app = await _make_app(datasette) + + result, attributes = await _call_in_tool_span( + otel_spans, + _tools_by_name()["app_edit"], + datasette=datasette, + actor=BOB, + app_id=app["id"], + edits=[{"operation": "str_replace", "old_str": "Hello", "new_str": "Hi"}], + ) + assert json.loads(result)["error"] == "Permission denied: edit-app" + assert attributes["apps.app_id"] == app["id"] + assert attributes["apps.tool.result"] == "denied" + assert _changes(otel_metrics) == {} + + +@pytest.mark.asyncio +@pytest.mark.parametrize( + "tool_name,kwargs,counted", + [ + ("app_view", {}, False), + ("app_view", {"view_range": "1,1"}, False), + ("app_str_replace", {"old_str": "Hello", "new_str": "Hi"}, True), + ("app_insert", {"insert_line": 0, "insert_text": "
\n"}, True), + ("app_render", {}, False), + ], +) +async def test_other_edit_tools_tag_span( + otel_spans, otel_metrics, tool_name, kwargs, counted +): + datasette = await _datasette() + app = await _make_app(datasette) + + result, attributes = await _call_in_tool_span( + otel_spans, + _tools_by_name()[tool_name], + datasette=datasette, + actor=ALICE, + app_id=app["id"], + **kwargs, + ) + assert "error" not in json.loads(result) + assert attributes["apps.app_id"] == app["id"] + assert attributes["apps.tool.result"] == "ok" + assert _changes(otel_metrics) == ({("edit", "agent"): 1} if counted else {}) + + +@pytest.mark.asyncio +async def test_edit_tool_error_for_missing_text(otel_spans, otel_metrics): + datasette = await _datasette() + app = await _make_app(datasette) + + result, attributes = await _call_in_tool_span( + otel_spans, + _tools_by_name()["app_str_replace"], + datasette=datasette, + actor=ALICE, + app_id=app["id"], + old_str="Missing", + new_str="x", + ) + assert "error" in json.loads(result) + assert attributes["apps.tool.result"] == "error" + assert _changes(otel_metrics) == {} + + +@pytest.mark.asyncio +@pytest.mark.parametrize( + "tool_name,kwargs", + [ + ("app_view", {}), + ( + "app_edit", + {"edits": [{"operation": "insert", "insert_line": 0, "insert_text": "x"}]}, + ), + ], +) +@pytest.mark.parametrize("allowed", [True, False]) +async def test_unknown_app_id_is_never_recorded( + otel_spans, otel_metrics, monkeypatch, tool_name, kwargs, allowed +): + # The model-supplied app_id is only recorded once it names a real app. + # Datasette's edit-app check always refuses an ID with no stored app row, + # so EditToolset's "Content not found" path is only reachable if the app + # vanishes after the check; force the check open to exercise it. + datasette = await _datasette() + await _make_app(datasette) + if allowed: + + async def allow(datasette, actor, app_id): + return True + + monkeypatch.setattr(agent_tools, "_can_edit_app", allow) + actor = ALICE + expected = "error" if allowed else "denied" + + result, attributes = await _call_in_tool_span( + otel_spans, + _tools_by_name()[tool_name], + datasette=datasette, + actor=actor, + app_id="SENTINEL not an app", + **kwargs, + ) + assert "error" in json.loads(result) + assert attributes["apps.tool.result"] == expected + assert "apps.app_id" not in attributes + assert not any("SENTINEL" in str(value) for value in attributes.values()) + assert _changes(otel_metrics) == {} + + +@pytest.mark.asyncio +async def test_denied_call_on_real_app_is_tagged(otel_spans): + # Consistent with the app routes, which tag apps.app_id after the 404 + # check but before the permission check. + datasette = await _datasette() + app = await _make_app(datasette) + + _, attributes = await _call_in_tool_span( + otel_spans, + _tools_by_name()["app_view"], + datasette=datasette, + actor=BOB, + app_id=app["id"], + ) + assert attributes == {"apps.app_id": app["id"], "apps.tool.result": "denied"} + + +@pytest.mark.asyncio +async def test_app_list_tags_result_without_app_id(otel_spans): + datasette = await _datasette() + await _make_app(datasette) + tools = _tools_by_name() + + result, attributes = await _call_in_tool_span( + otel_spans, tools["app_list"], datasette=datasette, actor=ALICE + ) + assert json.loads(result)["returned_count"] == 1 + assert attributes["apps.tool.result"] == "ok" + assert "apps.app_id" not in attributes + + otel_spans.clear() + result, attributes = await _call_in_tool_span( + otel_spans, tools["app_list"], datasette=datasette, actor=ALICE, limit=99 + ) + assert "error" in json.loads(result) + assert attributes["apps.tool.result"] == "error" + + +@pytest.mark.asyncio +async def test_tool_span_carries_no_tool_arguments(otel_spans): + datasette = await _datasette( + config={"permissions": {"create-app": {"id": "alice"}}} + ) + _, attributes = await _call_in_tool_span( + otel_spans, + _tools_by_name()["app_create"], + datasette=datasette, + actor=ALICE, + name="SENTINEL_NAME", + description="SENTINEL_DESCRIPTION", + html="

SENTINEL_HTML

", + ) + assert set(attributes) == {"apps.app_id", "apps.tool.result"} + assert not any("SENTINEL" in str(value) for value in attributes.values()) + + +def test_tool_signatures_unchanged(): + # datasette-agent passes datasette/actor/context by keyword and only + # passes context when "context" is a named parameter of fn. + import inspect + + tools = _tools_by_name() + for name in ( + "app_list", + "app_create", + "app_view", + "app_str_replace", + "app_insert", + "app_edit", + "app_render", + ): + parameters = inspect.signature(tools[name].fn).parameters + assert list(parameters)[:2] == ["datasette", "actor"], name + assert "context" not in parameters, name + assert "context" in inspect.signature(tools["app_debug"].fn).parameters + + +@pytest.mark.asyncio +async def test_real_datasette_agent_tool_span(otel_spans): + """Only once the datasette-agent dev dependency ships telemetry.""" + pytest.importorskip("datasette_agent.telemetry") + from datasette_agent.tools import AgentTool, execute_agent_tool + + datasette = await _datasette() + app = await _make_app(datasette) + tool = {t.name: t for t in get_app_edit_tools(AgentTool)}["app_view"] + + await execute_agent_tool(tool, datasette, ALICE, arguments={"app_id": app["id"]}) + spans = [ + s for s in otel_spans.get_finished_spans() if s.name == "execute_tool app_view" + ] + assert len(spans) == 1 + assert spans[0].attributes["apps.app_id"] == app["id"] + assert spans[0].attributes["apps.tool.result"] == "ok" From cfb0a656423128e7672d10efe828d5e32ac171c3 Mon Sep 17 00:00:00 2001 From: Alex Garcia Date: Mon, 28 Sep 2026 13:03:16 -0700 Subject: [PATCH 4/5] Telemetry for app_debug runs apps.debug.runs counts terminal debug runs by outcome, with wall-clock and browser-reported script durations. Lazily expired jobs are counted separately, and the debug frame and query routes tag their request spans with the job and app IDs. Co-Authored-By: Claude Opus 5.5 (1M context) --- datasette_apps/agent_tools.py | 107 ++++++- datasette_apps/debug.py | 5 +- datasette_apps/views.py | 16 +- tests/test_telemetry_debug.py | 556 ++++++++++++++++++++++++++++++++++ 4 files changed, 674 insertions(+), 10 deletions(-) create mode 100644 tests/test_telemetry_debug.py diff --git a/datasette_apps/agent_tools.py b/datasette_apps/agent_tools.py index 818c5bf..fd7a17f 100644 --- a/datasette_apps/agent_tools.py +++ b/datasette_apps/agent_tools.py @@ -2,6 +2,7 @@ import html import json +from datetime import datetime, timezone from datasette_agent_edit import EditError, EditToolset, Editable, NotFound @@ -19,7 +20,7 @@ ) from .permissions import AppResource, AppsResource from .registry import Registry, _fts_query -from .telemetry_registry import APP_ID, TOOL_RESULT +from .telemetry_registry import APP_ID, DEBUG_JOB_ID, DEBUG_OUTCOME, TOOL_RESULT APP_RUNTIME_API_GUIDANCE = ( " Apps run in a sandboxed iframe. For data access, use " @@ -490,11 +491,81 @@ def _csp_origins_schema_description(datasette=None): ) +# apps.tool.result for each apps.debug.outcome: the debug machinery did its +# job for ok, script_error and timed_out, even if the script itself failed. +_DEBUG_TOOL_RESULTS = { + "ok": "ok", + "script_error": "ok", + "timed_out": "ok", + "denied": "denied", +} + + +def _debug_outcome(outcome, envelope): + """Classify a terminal app_debug run for ``apps.debug.outcome``. + + Order matters: the harness's timeout envelope sets both ``ok: false`` + and ``timed_out: true``, so ``timed_out`` is checked before ``ok``. + """ + task_outcome = outcome.get("outcome") + if task_outcome == "expired": + return "task_expired" + if task_outcome == "cancelled": + return "task_cancelled" + if envelope["timed_out"]: + return "timed_out" + if envelope["ok"]: + return "ok" + return "script_error" + + +def _seconds_since(iso_timestamp): + try: + started = datetime.fromisoformat(iso_timestamp) + except (TypeError, ValueError): + return None + return (datetime.now(timezone.utc) - started).total_seconds() + + +async def _finish_debug( + datasette, + result, + outcome, + *, + app_id, + job=None, + run_seconds=None, + script_seconds=None, +): + """Record one terminal app_debug execution and tag the current (tool) + span. Never called on the suspending first execution: that one exits + through the BrowserTaskPending raise. Returns ``result`` unchanged.""" + telemetry.record_debug_run(outcome, run_seconds, script_seconds) + if job is not None: + known_app_id = job["app_id"] + else: + known_app_id = await _existing_stored_app_id(datasette, app_id) + telemetry.annotate_current_span( + { + APP_ID: known_app_id, + DEBUG_JOB_ID: job["id"] if job is not None else None, + DEBUG_OUTCOME: outcome, + TOOL_RESULT: _DEBUG_TOOL_RESULTS.get(outcome, "error"), + } + ) + return result + + async def _app_debug( datasette, actor, context, app_id, javascript, viewport=None, timeout_ms=None ): if not await _can_edit_app(datasette, actor, app_id): - return _error("Permission denied: edit-app", app_id=app_id) + return await _finish_debug( + datasette, + _error("Permission denied: edit-app", app_id=app_id), + "denied", + app_id=app_id, + ) conversation_id = getattr(context, "conversation_id", None) call_key = getattr(context, "call_key", None) # Re-executing a suspended call (after its browser task finishes) @@ -519,7 +590,9 @@ async def _app_debug( call_key=call_key, ) except ValueError as e: - return _error(str(e), app_id=app_id) + return await _finish_debug( + datasette, _error(str(e), app_id=app_id), "invalid", app_id=app_id + ) app = await Registry(datasette).get_app(app_id) try: outcome = await context.browser_task( @@ -534,10 +607,16 @@ async def _app_debug( # Matched by name so datasette-agent stays an optional dependency; # BrowserTaskPending (an llm.PauseChain) must keep propagating. if e.__class__.__name__ == "BrowserTasksNotSupported": - return _error( - "app_debug requires an interactive conversation with the " - "chat open in a browser; it is not available here", + return await _finish_debug( + datasette, + _error( + "app_debug requires an interactive conversation with the " + "chat open in a browser; it is not available here", + app_id=app_id, + ), + "unsupported", app_id=app_id, + job=job, ) raise if not isinstance(outcome, dict): @@ -545,6 +624,12 @@ async def _app_debug( envelope = normalize_envelope(outcome) # The audit record: what ran and what came back await complete_debug_job(datasette, job["id"], envelope) + # Wall-clock time the user waited, including the browser claiming the + # task; the script's own duration is browser-reported (normalize_envelope + # has coerced it to int or None). + run_seconds = _seconds_since(job["created_at"]) + duration_ms = envelope["duration_ms"] + script_seconds = duration_ms / 1000 if duration_ms is not None else None payload = { "app_id": app_id, "version": job["version"], @@ -553,7 +638,15 @@ async def _app_debug( payload.update(cap_envelope(envelope)) if payload.get("error") is None: payload.pop("error", None) - return json.dumps(payload) + return await _finish_debug( + datasette, + json.dumps(payload), + _debug_outcome(outcome, envelope), + app_id=app_id, + job=job, + run_seconds=run_seconds, + script_seconds=script_seconds, + ) def get_app_edit_tools(AgentTool, datasette=None): diff --git a/datasette_apps/debug.py b/datasette_apps/debug.py index d230d46..a03e70c 100644 --- a/datasette_apps/debug.py +++ b/datasette_apps/debug.py @@ -191,11 +191,14 @@ def debug_job_is_expired(job): async def expire_debug_job(datasette, job_id): - await datasette.get_internal_database().execute_write( + """Mark a pending job expired. Returns True only if this call flipped + the row - a concurrent request may already have expired it.""" + result = await datasette.get_internal_database().execute_write( "UPDATE _app_debug_jobs SET status = 'expired' " "WHERE id = ? AND status = 'pending'", [job_id], ) + return result.rowcount > 0 def debug_task_payload(datasette, job): diff --git a/datasette_apps/views.py b/datasette_apps/views.py index eb592ee..a8ac7e6 100644 --- a/datasette_apps/views.py +++ b/datasette_apps/views.py @@ -28,7 +28,7 @@ from .prompt import build_llm_prompt_data, stored_query_options from .rendering import build_app_srcdoc, iframe_bridge_script, parent_bridge_script from .registry import Registry -from .telemetry_registry import APP_ID +from .telemetry_registry import APP_ID, DEBUG_JOB_ID from .utils import sort_names_with_underscores_last @@ -747,13 +747,23 @@ async def _running_debug_job_or_403(datasette, request): query endpoints stop serving.""" job = await _debug_job_or_404(datasette, request) if job["status"] == "pending" and debug_job_is_expired(job): - await expire_debug_job(datasette, job["id"]) + if await expire_debug_job(datasette, job["id"]): + telemetry.record_debug_job_expired() job = await get_debug_job(datasette, job["id"]) if job["status"] != "pending": raise Forbidden("Debug job is not running") return job +def _annotate_debug_request(request, job): + """Tag the request span with the job and its app. Only called once the + job is known to exist, is running and belongs to the actor, so a probe + with a made-up job ID records nothing.""" + telemetry.annotate_request( + request, {DEBUG_JOB_ID: job["id"], APP_ID: job["app_id"]} + ) + + async def debug_frame(datasette, request): """Returns the debug run's app document as JSON, never as text/html: the untrusted app HTML must only ever execute inside the harness's @@ -761,6 +771,7 @@ async def debug_frame(datasette, request): browser would render on direct navigation.""" job = await _running_debug_job_or_403(datasette, request) _require_debug_job_actor(request, job) + _annotate_debug_request(request, job) token = request.args.get("token") or "" # The harness fetches this same-origin with credentials, so the # actor check above is the primary gate; the token (handed out only @@ -790,6 +801,7 @@ async def debug_frame(datasette, request): async def debug_query(datasette, request): job = await _running_debug_job_or_403(datasette, request) _require_debug_job_actor(request, job) + _annotate_debug_request(request, job) app = await Registry(datasette).get_app(job["app_id"]) if app is None: raise NotFound("App not found") diff --git a/tests/test_telemetry_debug.py b/tests/test_telemetry_debug.py new file mode 100644 index 0000000..454e231 --- /dev/null +++ b/tests/test_telemetry_debug.py @@ -0,0 +1,556 @@ +"""Telemetry for app_debug runs: apps.debug.runs by outcome, run and script +durations, apps.debug.jobs.expired, and job/app IDs on the debug routes' +request spans.""" + +import json + +import pytest + +pytest.importorskip("opentelemetry.sdk") + +from datasette.app import Datasette +from datasette.telemetry_testing import assert_metrics_conform +from opentelemetry import trace +from opentelemetry.trace import SpanKind + +from datasette_apps import agent_tools, telemetry_registry +from datasette_apps.debug import ( + JOB_EXPIRY_SECONDS, + create_debug_job, + debug_task_payload, + expire_debug_job, + get_debug_job, + get_debug_job_for_call, +) +from test_debug_agent_tool import ( + COMPLETED_OUTCOME, + FakeBrowserTaskPending, + FakeContext, + _make_app, + _tools_by_name, +) +from test_debug_jobs import _backdate_job + +ALICE = {"id": "alice"} +TOOL_SPAN = "execute_tool app_debug" + + +async def _datasette(): + datasette = Datasette(memory=True) + await datasette.invoke_startup() + return datasette + + +async def _call_debug(otel_spans, context, **kwargs): + """Call app_debug inside a test-owned span standing in for + datasette-agent's execute_tool span; return (result, span attributes). + """ + tool = _tools_by_name()["app_debug"] + kwargs.setdefault("javascript", "return 1;") + with trace.get_tracer("test").start_as_current_span(TOOL_SPAN): + result = await tool.fn( + datasette=kwargs.pop("datasette"), + actor=kwargs.pop("actor", ALICE), + context=context, + **kwargs, + ) + spans = [s for s in otel_spans.get_finished_spans() if s.name == TOOL_SPAN] + attributes = dict(spans[-1].attributes) + otel_spans.clear() + return result, attributes + + +# The collector's reader uses delta temporality: collect() once per check, +# then read every metric from that snapshot. + + +def _runs(otel_metrics): + otel_metrics.collect() + return { + point.attributes["apps.debug.outcome"]: point.value + for point in otel_metrics.points("apps.debug.runs") + } + + +def _histogram_points(otel_metrics, name): + "Points from the snapshot taken by the preceding _runs() call." + return list(otel_metrics.points(name)) + + +def _assert_metrics_conform(otel_metrics): + assert_metrics_conform( + telemetry_registry.METRICS, otel_metrics, scope_name="datasette_apps" + ) + + +# --- Outcomes --------------------------------------------------------------- + + +@pytest.mark.asyncio +@pytest.mark.parametrize( + "outcome,expected,tool_result", + [ + (dict(COMPLETED_OUTCOME), "ok", "ok"), + ( + { + "ok": False, + "error": {"message": "boom"}, + "duration_ms": 12, + "outcome": "completed", + }, + "script_error", + "ok", + ), + ( + # The harness's timeout envelope sets ok: false AND timed_out + { + "ok": False, + "error": {"message": "Debug run timed out after 15000ms"}, + "timed_out": True, + "outcome": "completed", + }, + "timed_out", + "ok", + ), + ( + { + "ok": False, + "error": {"message": "Browser task timed out before completing"}, + "outcome": "expired", + }, + "task_expired", + "error", + ), + ( + { + "ok": False, + "error": {"message": "Cancelled by the user"}, + "outcome": "cancelled", + }, + "task_cancelled", + "error", + ), + ], +) +async def test_browser_outcomes( + otel_spans, otel_metrics, outcome, expected, tool_result +): + datasette = await _datasette() + app = await _make_app(datasette) + + result, attributes = await _call_debug( + otel_spans, FakeContext(outcome=outcome), datasette=datasette, app_id=app["id"] + ) + job = await get_debug_job_for_call(datasette, "conv-1", "call-1") + + assert _runs(otel_metrics) == {expected: 1} + run_points = _histogram_points(otel_metrics, "apps.debug.run.duration") + assert len(run_points) == 1 + assert run_points[0].attributes == {"apps.debug.outcome": expected} + assert run_points[0].sum >= 0 + assert attributes == { + "apps.app_id": app["id"], + "apps.debug.job_id": job["id"], + "apps.debug.outcome": expected, + "apps.tool.result": tool_result, + } + # The tool's result is unchanged by instrumentation + assert json.loads(result)["app_id"] == app["id"] + _assert_metrics_conform(otel_metrics) + + +@pytest.mark.asyncio +async def test_denied(otel_spans, otel_metrics): + datasette = await _datasette() + app = await _make_app(datasette) + + result, attributes = await _call_debug( + otel_spans, + FakeContext(), + datasette=datasette, + actor={"id": "bob"}, + app_id=app["id"], + ) + assert json.loads(result)["error"] == "Permission denied: edit-app" + assert _runs(otel_metrics) == {"denied": 1} + assert _histogram_points(otel_metrics, "apps.debug.run.duration") == [] + # A denied call on a real app is tagged with it, as in ticket 04 + assert attributes == { + "apps.app_id": app["id"], + "apps.debug.outcome": "denied", + "apps.tool.result": "denied", + } + + +@pytest.mark.asyncio +async def test_invalid_viewport(otel_spans, otel_metrics): + datasette = await _datasette() + app = await _make_app(datasette) + + result, attributes = await _call_debug( + otel_spans, + FakeContext(), + datasette=datasette, + app_id=app["id"], + viewport={"width": 10, "height": 10}, + ) + assert "viewport" in json.loads(result)["error"] + assert _runs(otel_metrics) == {"invalid": 1} + assert _histogram_points(otel_metrics, "apps.debug.run.duration") == [] + assert attributes == { + "apps.app_id": app["id"], + "apps.debug.outcome": "invalid", + "apps.tool.result": "error", + } + + +@pytest.mark.asyncio +async def test_invalid_unknown_app_id_is_never_recorded( + otel_spans, otel_metrics, monkeypatch +): + # Datasette's edit-app check refuses an ID with no stored app row, so + # force it open to reach create_debug_job's "App not found". + async def allow(datasette, actor, app_id): + return True + + monkeypatch.setattr(agent_tools, "_can_edit_app", allow) + datasette = await _datasette() + + result, attributes = await _call_debug( + otel_spans, + FakeContext(), + datasette=datasette, + app_id="SENTINEL not an app", + ) + assert json.loads(result)["error"] == "App not found" + assert _runs(otel_metrics) == {"invalid": 1} + assert attributes == { + "apps.debug.outcome": "invalid", + "apps.tool.result": "error", + } + + +@pytest.mark.asyncio +async def test_unsupported(otel_spans, otel_metrics): + datasette = await _datasette() + app = await _make_app(datasette) + + result, attributes = await _call_debug( + otel_spans, + FakeContext(supports_browser_tasks=False), + datasette=datasette, + app_id=app["id"], + ) + assert "interactive" in json.loads(result)["error"] + job = await get_debug_job_for_call(datasette, "conv-1", "call-1") + assert _runs(otel_metrics) == {"unsupported": 1} + assert _histogram_points(otel_metrics, "apps.debug.run.duration") == [] + assert attributes == { + "apps.app_id": app["id"], + "apps.debug.job_id": job["id"], + "apps.debug.outcome": "unsupported", + "apps.tool.result": "error", + } + + +# --- Suspend, then resume --------------------------------------------------- + + +@pytest.mark.asyncio +async def test_suspend_then_resume_records_exactly_once(otel_spans, otel_metrics): + datasette = await _datasette() + app = await _make_app(datasette) + tool = _tools_by_name()["app_debug"] + + # First execution: suspends waiting for the browser, records nothing + with trace.get_tracer("test").start_as_current_span(TOOL_SPAN): + with pytest.raises(FakeBrowserTaskPending): + await tool.fn( + datasette=datasette, + actor=ALICE, + context=FakeContext(), + app_id=app["id"], + javascript="return 1;", + ) + (suspended,) = [s for s in otel_spans.get_finished_spans() if s.name == TOOL_SPAN] + assert not { + "apps.debug.outcome", + "apps.tool.result", + "apps.debug.job_id", + } & set(suspended.attributes) + otel_spans.clear() + job = await get_debug_job_for_call(datasette, "conv-1", "call-1") + await _backdate_job(datasette, job["id"], 3) + + # Second execution: the resumed call records the run. Metrics are + # collected only now, so the snapshot covers both executions. + _, attributes = await _call_debug( + otel_spans, + FakeContext(outcome=dict(COMPLETED_OUTCOME)), + datasette=datasette, + app_id=app["id"], + ) + assert (await get_debug_job(datasette, job["id"]))["status"] == "completed" + assert _runs(otel_metrics) == {"ok": 1} + (runs_point,) = otel_metrics.points("apps.debug.runs") + assert runs_point.value == 1 + (run_point,) = _histogram_points(otel_metrics, "apps.debug.run.duration") + assert run_point.count == 1 + (script_point,) = _histogram_points(otel_metrics, "apps.debug.script.duration") + assert script_point.count == 1 + # Wall-clock from job creation, not from the resumed call + assert run_point.sum >= 3 + assert attributes["apps.debug.job_id"] == job["id"] + assert attributes["apps.debug.outcome"] == "ok" + _assert_metrics_conform(otel_metrics) + + +# --- Script duration -------------------------------------------------------- + + +@pytest.mark.asyncio +async def test_script_duration_recorded_from_envelope(otel_spans, otel_metrics): + datasette = await _datasette() + app = await _make_app(datasette) + outcome = dict(COMPLETED_OUTCOME, duration_ms=1234) + + await _call_debug( + otel_spans, FakeContext(outcome=outcome), datasette=datasette, app_id=app["id"] + ) + assert _runs(otel_metrics) == {"ok": 1} + (point,) = _histogram_points(otel_metrics, "apps.debug.script.duration") + assert point.attributes == {"apps.debug.outcome": "ok"} + assert point.count == 1 + assert point.sum == pytest.approx(1.234) + # Lands in the (1, 2.5] bucket + bounds = list(point.explicit_bounds) + bucket = bounds.index(2.5) + assert bounds[bucket - 1] == 1 + assert point.bucket_counts[bucket] == 1 + assert sum(point.bucket_counts) == 1 + + +@pytest.mark.asyncio +@pytest.mark.parametrize("duration_ms", [None, -5]) +async def test_no_script_duration_without_a_usable_duration_ms( + otel_spans, otel_metrics, duration_ms +): + datasette = await _datasette() + app = await _make_app(datasette) + outcome = dict(COMPLETED_OUTCOME) + if duration_ms is None: + outcome.pop("duration_ms") + else: + outcome["duration_ms"] = duration_ms + + await _call_debug( + otel_spans, FakeContext(outcome=outcome), datasette=datasette, app_id=app["id"] + ) + assert _runs(otel_metrics) == {"ok": 1} + assert _histogram_points(otel_metrics, "apps.debug.script.duration") == [] + + +# --- Lazy expiry ------------------------------------------------------------ + + +def _expired(otel_metrics): + otel_metrics.collect() + return sum(point.value for point in otel_metrics.points("apps.debug.jobs.expired")) + + +@pytest.mark.asyncio +async def test_lazy_expiry_counts_only_flipped_rows(otel_metrics): + datasette = await _datasette() + app = await _make_app(datasette) + job = await create_debug_job( + datasette, app_id=app["id"], actor_id="alice", javascript="return 1;" + ) + await _backdate_job(datasette, job["id"], JOB_EXPIRY_SECONDS + 60) + frame_url = debug_task_payload(datasette, job)["frame_url"] + + assert (await datasette.client.get(frame_url, actor=ALICE)).status_code == 403 + assert _expired(otel_metrics) == 1 + _assert_metrics_conform(otel_metrics) + # Already expired: still 403, adds nothing (delta since the last collect) + assert (await datasette.client.get(frame_url, actor=ALICE)).status_code == 403 + query = await datasette.client.post( + f"/-/apps/debug/{job['id']}/query", + actor=ALICE, + json={"database": "_memory", "sql": "select 1"}, + ) + assert query.status_code == 403 + assert _expired(otel_metrics) == 0 + + +# --- Debug route request spans ---------------------------------------------- + + +def _request_span(otel_spans): + # The test client's own request is the root SERVER span (see + # test_telemetry_queries._request_span). + spans = [ + span + for span in otel_spans.get_finished_spans() + if span.kind == SpanKind.SERVER and span.parent is None + ] + assert len(spans) == 1, spans + return spans[0] + + +async def _job(datasette): + app = await _make_app(datasette, sql_databases=["_memory"]) + job = await create_debug_job( + datasette, app_id=app["id"], actor_id="alice", javascript="return 1;" + ) + return app, job + + +@pytest.mark.asyncio +async def test_frame_request_span_carries_job_and_app(otel_spans): + datasette = await _datasette() + app, job = await _job(datasette) + + response = await datasette.client.get( + debug_task_payload(datasette, job)["frame_url"], actor=ALICE + ) + assert response.status_code == 200 + attributes = _request_span(otel_spans).attributes + assert attributes["apps.debug.job_id"] == job["id"] + assert attributes["apps.app_id"] == app["id"] + # The frame token rides in the query string, which core never records + token = job["config"]["frame_token"] + for span in otel_spans.get_finished_spans(): + assert token not in json.dumps(dict(span.attributes), default=str) + + +@pytest.mark.asyncio +async def test_query_request_span_carries_job_and_app(otel_spans): + datasette = await _datasette() + app, job = await _job(datasette) + + response = await datasette.client.post( + f"/-/apps/debug/{job['id']}/query", + actor=ALICE, + json={"database": "_memory", "sql": "select 1"}, + ) + assert response.json()["ok"] is True + attributes = _request_span(otel_spans).attributes + assert attributes["apps.debug.job_id"] == job["id"] + assert attributes["apps.app_id"] == app["id"] + (query_span,) = [ + s for s in otel_spans.get_finished_spans() if s.name == "apps.query" + ] + assert query_span.attributes["apps.query.source"] == "debug" + assert query_span.attributes["apps.debug.job_id"] == job["id"] + + +@pytest.mark.asyncio +@pytest.mark.parametrize( + "path,method,kwargs", + [ + ("frame", "GET", {}), + ("query", "POST", {"json": {"database": "_memory", "sql": "select 1"}}), + ], +) +async def test_forbidden_debug_requests_are_not_tagged( + otel_spans, path, method, kwargs +): + datasette = await _datasette() + _, job = await _job(datasette) + url = f"/-/apps/debug/{job['id']}/{path}" + if path == "frame": + url = debug_task_payload(datasette, job)["frame_url"] + + response = await datasette.client.request( + method, url, actor={"id": "mallory"}, **kwargs + ) + assert response.status_code == 403 + attributes = _request_span(otel_spans).attributes + assert "apps.debug.job_id" not in attributes + assert "apps.app_id" not in attributes + + +@pytest.mark.asyncio +async def test_unknown_job_id_is_not_tagged(otel_spans): + datasette = await _datasette() + + response = await datasette.client.get( + "/-/apps/debug/made-up-job/frame?token=x", actor=ALICE + ) + assert response.status_code == 404 + attributes = _request_span(otel_spans).attributes + assert "apps.debug.job_id" not in attributes + assert "apps.app_id" not in attributes + + +@pytest.mark.asyncio +async def test_expire_debug_job_reports_whether_it_flipped_the_row(): + datasette = await _datasette() + app = await _make_app(datasette) + job = await create_debug_job( + datasette, app_id=app["id"], actor_id="alice", javascript="return 1;" + ) + assert await expire_debug_job(datasette, job["id"]) is True + # A second (e.g. concurrent) request finds nothing left to flip + assert await expire_debug_job(datasette, job["id"]) is False + + +# --- Real datasette-agent runtime ------------------------------------------- + + +@pytest.mark.asyncio +async def test_real_datasette_agent_suspend_and_resume_records_once( + tmp_path, otel_metrics +): + """Both executions of one logical run through the real browser-task + runtime record exactly one apps.debug.runs point.""" + pytest.importorskip("datasette_agent") + from datasette_agent.browser_tasks import ( + BrowserTaskPending, + claim_task, + complete_task, + ) + from datasette_agent.schema import ensure_tables + from datasette_agent.tools import ToolContext + + datasette = Datasette(memory=True, internal=str(tmp_path / "internal.db")) + await datasette.invoke_startup() + await ensure_tables(datasette.get_internal_database()) + app = await _make_app(datasette) + tool = _tools_by_name()["app_debug"] + + async def run(): + return await tool.fn( + datasette=datasette, + actor=ALICE, + context=ToolContext( + datasette=datasette, + actor=ALICE, + conversation_id="01CONVERSATION00000000TEST", + tool_name="app_debug", + arguments={"app_id": app["id"], "javascript": "return 1;"}, + tool_call_id="call_1", + supports_browser_tasks=True, + ), + app_id=app["id"], + javascript="return 1;", + ) + + with pytest.raises(BrowserTaskPending) as excinfo: + await run() + task = excinfo.value.task + db = datasette.get_internal_database() + await claim_task(db, task["id"], "alice") + await complete_task( + db, + task["id"], + {"ok": False, "error": {"message": "x"}, "duration_ms": 10}, + "alice", + ) + assert json.loads(await run())["ok"] is False + + assert _runs(otel_metrics) == {"script_error": 1} + (point,) = otel_metrics.points("apps.debug.runs") + assert point.value == 1 + (script_point,) = _histogram_points(otel_metrics, "apps.debug.script.duration") + assert script_point.sum == pytest.approx(0.01) From f5606dbf746d0e89616e40520b31a0e0fcaeb7d9 Mon Sep 17 00:00:00 2001 From: Alex Garcia Date: Mon, 28 Sep 2026 13:17:43 -0700 Subject: [PATCH 5/5] Telemetry conformance, privacy tests and README reference Checks that everything emitted is registered and everything registered is emitted, plants sentinel values to prove app HTML, SQL parameters, debug scripts and tokens never reach telemetry, and generates the README's telemetry reference from the registry. Co-Authored-By: Claude Opus 5.5 (1M context) --- README.md | 104 +++++ datasette_apps/agent_tools.py | 1 + datasette_apps/telemetry.py | 6 +- datasette_apps/telemetry_registry.py | 53 ++- scripts/telemetry-doc.py | 144 +++++++ tests/test_telemetry_conformance.py | 610 +++++++++++++++++++++++++++ tests/test_telemetry_registry.py | 36 ++ 7 files changed, 940 insertions(+), 14 deletions(-) create mode 100644 scripts/telemetry-doc.py create mode 100644 tests/test_telemetry_conformance.py diff --git a/README.md b/README.md index af8747c..45ae49d 100644 --- a/README.md +++ b/README.md @@ -145,6 +145,98 @@ Here's how to remove a single external app from the catalog by ID: await Registry(datasette).remove_app("myplugin:example") ``` +## Telemetry + +datasette-apps emits [OpenTelemetry](https://opentelemetry.io/) spans and metrics under the instrumentation scope `datasette_apps`, using Datasette's plugin telemetry kit (requires Datasette 1.0a41+). It depends on `opentelemetry-api` only and never installs a provider or an exporter: nothing is recorded unless an OpenTelemetry SDK is configured. See Datasette's telemetry documentation for running under `opentelemetry-instrument`, or use [datasette-otel-viewer](https://github.com/datasette/datasette-otel-viewer) to browse this instance's own telemetry at `/-/otel`. + +The plugin adds one span of its own, `apps.query`, and otherwise adds attributes to spans Datasette core (or datasette-agent) already creates. A running app calling `datasette.query()` produces this tree (core's spans marked): + +``` +POST /-/apps/{id}/query SERVER (core, apps.app_id) +├── db.query (app lookup, permissions) CLIENT (core) +└── apps.query INTERNAL + ├── db.query (allowlist) CLIENT (core) + └── GET /{database}/-/query.json SERVER (core, datasette.internal_client) + └── db.query select ... CLIENT (core) +``` + +Request span names are abbreviated here: core names them `{method} {http.route}`, using Datasette's route pattern (for example `POST ^/-/apps/(?P[^/]+)/query$`). + +The nested `GET` is Datasette's JSON API called through `datasette.client`, marked `datasette.internal_client: true` - filter on that to keep request counts honest. It nests under `apps.query` because this plugin injects W3C trace context headers into that internal request, a workaround for [datasette#2969](https://github.com/simonw/datasette/issues/2969). + +`apps.debug.runs` counts each terminal `app_debug` tool execution. For a run that reaches the browser, that is the resumed call that records the result; the first execution, which suspends waiting for the browser, records nothing. The debug run's `/frame` and `/query` requests carry `apps.debug.job_id` and `apps.app_id` on core's request spans. + +Agent tools don't open spans of their own. They add `apps.app_id` and `apps.tool.result` (plus `apps.debug.job_id` and `apps.debug.outcome` for `app_debug`) to the current span - datasette-agent's `execute_tool` span when the installed datasette-agent has telemetry. These attributes are set when a tool returns; an exception escaping a tool leaves them unset and records no `apps.debug.runs` (a datasette-agent version with telemetry records it on its own span as `error.type`). + +**What is never recorded:** app HTML, names or descriptions; SQL text (core's `db.query` spans record SQL, and the internal request's `url.path` includes a stored query's name - this plugin does not add either again); SQL parameter values; debug scripts and their results, logs and errors; CSP origins; actor or conversation IDs; the frame, channel and bridge tokens; exception messages. App IDs, debug job IDs and database names appear on spans only, never as metric dimensions. `tests/test_telemetry_conformance.py` plants sentinel values for these in a broad workload: app HTML, names, descriptions, parameter values, debug scripts and results, CSP origins, actor and conversation IDs, and tokens are checked against every span and metric, core's included. SQL text and stored query names are checked against this plugin's scope only, because core records them by design. + +Every span, metric and attribute below is declared in `datasette_apps/telemetry_registry.py`; the conformance test holds the code to this reference in both directions, and `uv run scripts/telemetry-doc.py` regenerates it. + + + +#### Spans + +**`apps.query`** - One query from a running app (or an `app_debug` run) through the plugin's query endpoint: body parsing, the allowlist check and the internal `datasette.client` call to Datasette's JSON API, which nests inside as a SERVER span tagged `datasette.internal_client`. Only an unexpected exception (outcome `error`) sets status `ERROR`; exception messages are never recorded. `db.namespace` reuses core's attribute, which is declared as always present, but here it is set only once the database has passed the app's allowlist - so it is absent for `invalid` and `not_allowed` queries, and the requested database name is never recorded unvetted. The internal request nests under this span because the plugin injects W3C trace context headers into it with the global propagator, a workaround for https://github.com/simonw/datasette/issues/2969: with the default propagator core would otherwise start it as a new trace. With `OTEL_PROPAGATORS=none` nothing is injected, but core extracts nothing either, so it still nests. + +Attributes: `apps.app_id`, `apps.query.source`, `apps.query.outcome`, `apps.query.kind` *(optional)*, `apps.query.write` *(optional)*, `db.namespace`, `apps.query.rows` *(optional)*, `apps.debug.job_id` *(optional)*, `error.type` *(optional)*. + +#### Attributes on spans this plugin does not own + +- On core's HTTP request spans (scope `datasette`): `apps.app_id`, `apps.debug.job_id` *(optional)*. +- On the agent tool span (datasette-agent's `execute_tool {tool}`, scope `datasette_agent`, when it has telemetry): `apps.app_id`, `apps.debug.job_id` *(optional)*, `apps.tool.result`, `apps.debug.outcome`. + +#### Metrics + +**`apps.queries`** *(Counter, unit `{query}`)* - App queries handled, by source, outcome, kind and whether a stored query was a write. + +Attributes: `apps.query.source`, `apps.query.outcome`, `apps.query.kind` *(optional)*, `apps.query.write` *(optional)*. + +**`apps.query.duration`** *(Histogram, unit `s`)* - Time to handle one app query end to end, as the app sees it. Uses core's duration buckets so it lines up with `db.client.operation.duration`. + +Attributes: `apps.query.source`, `apps.query.outcome`, `apps.query.kind` *(optional)*. + +Bucket boundaries: 0.0001, 0.0005, 0.001, 0.005, 0.01, 0.05, 0.1, 0.5, 1, 5, 10. + +**`apps.changes`** *(Counter, unit `{change}`)* - App changes (create, edit, delete, pin, unpin), by operation and whether they came from the web UI or the agent. Counted only after the write succeeded. An edit is one submitted and saved edit form or agent edit call (an `app_edit` batch counts once), even when nothing changed and no revision was written. Apps registered by other plugins through the `Registry` API (`add_app`/`add_apps`) are not counted. + +Attributes: `apps.change.operation`, `apps.change.via`. + +**`apps.debug.runs`** *(Counter, unit `{run}`)* - Terminal `app_debug` tool executions, by outcome. The first execution that suspends waiting for the browser is not counted, and neither is an execution that ends in an escaped exception (there is no `error` outcome). + +Attributes: `apps.debug.outcome`. + +**`apps.debug.run.duration`** *(Histogram, unit `s`)* - Wall-clock time from debug job creation to the resumed tool call recording its result, including the browser claiming the task. Only for outcomes that came back from the browser. + +Attributes: `apps.debug.outcome`. + +Bucket boundaries: 0.5, 1, 2.5, 5, 10, 15, 30, 60, 120, 300, 900. + +**`apps.debug.script.duration`** *(Histogram, unit `s`)* - The debug script's own run time as reported by the browser (`duration_ms`), capped by the 60s maximum script timeout. + +Attributes: `apps.debug.outcome`. + +Bucket boundaries: 0.01, 0.05, 0.1, 0.25, 0.5, 1, 2.5, 5, 10, 15, 30, 60. + +**`apps.debug.jobs.expired`** *(Counter, unit `{job}`)* - Pending debug jobs flipped to `expired` because a `/frame` or `/query` request arrived after the 15 minute job window. Counted only when a row actually changed. + +#### Attributes + +- `apps.app_id` - The app's ID: a ULID for stored apps, or a plugin-supplied ID for external apps. Unbounded, so it rides on spans only - **never on a metric**. Besides `apps.query`, it is added to spans this plugin does not own: core's HTTP request span for the app's routes (view, JSON, edit, delete, revision, pin, unpin, launch, query, and the `app_debug` frame and query routes), and the current span inside this plugin's agent tools, which with datasette-agent's telemetry is its `execute_tool` span in the `datasette_agent` scope. Only recorded once the ID is known to name a real app, so a made-up ID in a URL or a tool argument is never recorded. Used on: `apps.query`, core's HTTP request spans, the agent tool span. +- `apps.debug.job_id` *(optional)* - The `_app_debug_jobs.id` (a ULID) of an `app_debug` run. Spans only - **never on a metric**. Present on `apps.query` only for queries made by a debug run. Also added to core's HTTP request span for the debug run's `/frame` and `/query` routes (once the job is known to be running and to belong to the actor) and to the `app_debug` tool span. Used on: `apps.query`, core's HTTP request spans, the agent tool span. +- `apps.query.source` - Which endpoint the app's query arrived on: `app` (`/-/apps/{id}/query`, a running app) or `debug` (`/-/apps/debug/{job}/query`, an `app_debug` run). One of: `app`, `debug`. Used on: `apps.query`, `apps.queries`, `apps.query.duration`. +- `apps.query.kind` *(optional)* - `sql` for `datasette.query()`, `stored` for `datasette.storedQuery()`. Absent when the request body is not valid JSON. One of: `sql`, `stored`. Used on: `apps.query`, `apps.queries`, `apps.query.duration`. +- `apps.query.write` *(optional)* - True for a stored query declared `is_write`. Only known once the stored query has been resolved, so absent otherwise. One of: `false`, `true`. Used on: `apps.query`, `apps.queries`. +- `apps.query.outcome` - How the app query ended. `ok`: the query ran and returned a result. `invalid`: the request body or parameters were malformed. `not_allowed`: the database or stored query is not on the app's allowlist. `not_found`: the database or stored query doesn't exist. `denied`: Datasette's permission checks refused the actor. `failed`: Datasette rejected or failed the query (SQL error, time limit, write denied by a read-only query). `error`: an unexpected exception escaped - the only outcome that sets span status `ERROR`. Clamped at the call site: anything unrecognised becomes `error`. One of: `denied`, `error`, `failed`, `invalid`, `not_allowed`, `not_found`, `ok`. Used on: `apps.query`, `apps.queries`, `apps.query.duration`. +- `apps.query.rows` *(optional)* - Number of rows returned. Only on `ok` read queries. Used on: `apps.query`. +- `apps.change.operation` - What changed: an app was created, edited, deleted, pinned or unpinned. One of: `create`, `delete`, `edit`, `pin`, `unpin`. Used on: `apps.changes`. +- `apps.change.via` - Where the change came from: `web` (the plugin's HTML forms) or `agent` (datasette-agent tools). One of: `agent`, `web`. Used on: `apps.changes`. +- `apps.tool.result` - How one of this plugin's agent tools ended: `ok`, `error` or `denied` (the actor lacked permission). Set on the current tool span (datasette-agent's `execute_tool` span), not on a span of our own, so it sits in the `datasette_agent` scope; with a datasette-agent that has no telemetry it lands on whatever span is current, or nowhere. Set only when the tool returns: an exception escaping the tool leaves it unset (a datasette-agent version with telemetry records `error.type` on its own span). One of: `denied`, `error`, `ok`. Used on: the agent tool span. +- `apps.debug.outcome` - How an `app_debug` run ended. `ok`: the script ran and the envelope reported success. `script_error`: the script threw, or the harness reported an error. `timed_out`: the script hit its timeout. `task_expired` / `task_cancelled`: the browser task expired or was cancelled before a result came back. `denied`: the actor may not edit the app. `invalid`: the debug request was rejected (e.g. a bad viewport). `unsupported`: the agent host does not support browser tasks. Also set on the `app_debug` tool span alongside `apps.tool.result`. There is no `error` outcome: an exception escaping the tool records nothing. One of: `denied`, `invalid`, `ok`, `script_error`, `task_cancelled`, `task_expired`, `timed_out`, `unsupported`. Used on: `apps.debug.runs`, `apps.debug.run.duration`, `apps.debug.script.duration`, the agent tool span. +- `db.namespace` - Name of the database being queried. Used on: `apps.query`. +- `error.type` *(optional)* - The exception class name for a failed operation. On HTTP spans, also set to the status code as a string for 5xx responses. A 4xx response alone does not set this attribute or an error status. Used on: `apps.query`. + + + ## Development To set up this plugin locally, first checkout the code. You can confirm it is available like this: @@ -158,3 +250,15 @@ To run the tests: ```bash uv run pytest ``` + +After changing `datasette_apps/telemetry_registry.py`, regenerate the telemetry reference above (a test checks it is fresh): +```bash +uv run scripts/telemetry-doc.py +``` + +### Viewing telemetry locally + +With a checkout of [datasette-otel-viewer](https://github.com/datasette/datasette-otel-viewer) next to this one, run Datasette with it installed, sign in with the `--root` link and open `/-/otel` to see the spans and metrics this plugin emits: +```bash +uv run --with ../datasette-otel-viewer datasette data.db --root +``` diff --git a/datasette_apps/agent_tools.py b/datasette_apps/agent_tools.py index fd7a17f..368e984 100644 --- a/datasette_apps/agent_tools.py +++ b/datasette_apps/agent_tools.py @@ -540,6 +540,7 @@ async def _finish_debug( """Record one terminal app_debug execution and tag the current (tool) span. Never called on the suspending first execution: that one exits through the BrowserTaskPending raise. Returns ``result`` unchanged.""" + outcome = telemetry.clamp(outcome, DEBUG_OUTCOME.values, None) telemetry.record_debug_run(outcome, run_seconds, script_seconds) if job is not None: known_app_id = job["app_id"] diff --git a/datasette_apps/telemetry.py b/datasette_apps/telemetry.py index dc819cb..d284622 100644 --- a/datasette_apps/telemetry.py +++ b/datasette_apps/telemetry.py @@ -175,8 +175,10 @@ def trace_headers(): nesting under the span that made it. Workaround for https://github.com/simonw/datasette/issues/2969 - remove once the minimum Datasette version propagates context itself. Uses the global - propagator, so ``OTEL_PROPAGATORS=none`` turns it off; with no provider - installed it returns ``{}``. + propagator: with ``OTEL_PROPAGATORS=none`` it injects nothing, but core + then extracts nothing either (the empty composite propagator returns no + context), so the internal request still nests under the current span. + With no provider installed it returns ``{}``. """ headers = {} inject(headers) diff --git a/datasette_apps/telemetry_registry.py b/datasette_apps/telemetry_registry.py index cac65e3..e06669a 100644 --- a/datasette_apps/telemetry_registry.py +++ b/datasette_apps/telemetry_registry.py @@ -34,7 +34,9 @@ "DEBUG_SCRIPT_BUCKETS", "DURATION_BUCKETS", "METRICS", + "REQUEST_SPAN_ATTRIBUTES", "SPANS", + "TOOL_SPAN_ATTRIBUTES", ] # --- Histogram bucket boundaries ------------------------------------------ @@ -55,16 +57,23 @@ "apps.app_id", "The app's ID: a ULID for stored apps, or a plugin-supplied ID for " "external apps. Unbounded, so it rides on spans only - **never on a " - "metric**. Also set on the current span inside this plugin's agent " - "tools, which with datasette-agent's telemetry is its ``execute_tool`` " - "span - an attribute from this plugin on a span in the " - "``datasette_agent`` scope.", + "metric**. Besides ``apps.query``, it is added to spans this plugin " + "does not own: core's HTTP request span for the app's routes (view, " + "JSON, edit, delete, revision, pin, unpin, launch, query, and the " + "``app_debug`` frame and query routes), and the current span inside " + "this plugin's agent tools, which with datasette-agent's telemetry is " + "its ``execute_tool`` span in the ``datasette_agent`` scope. Only " + "recorded once the ID is known to name a real app, so a made-up ID in " + "a URL or a tool argument is never recorded.", ) DEBUG_JOB_ID = Attribute( "apps.debug.job_id", "The ``_app_debug_jobs.id`` (a ULID) of an ``app_debug`` run. Spans " "only - **never on a metric**. Present on ``apps.query`` only for " - "queries made by a debug run.", + "queries made by a debug run. Also added to core's HTTP request span " + "for the debug run's ``/frame`` and ``/query`` routes (once the job is " + "known to be running and to belong to the actor) and to the " + "``app_debug`` tool span.", optional=True, ) QUERY_SOURCE = Attribute( @@ -77,8 +86,8 @@ QUERY_KIND = Attribute( "apps.query.kind", "``sql`` for ``datasette.query()``, ``stored`` for " - "``datasette.storedQuery()``. Absent when the request body could not be " - "parsed.", + "``datasette.storedQuery()``. Absent when the request body is not valid " + "JSON.", optional=True, values={"sql", "stored"}, ) @@ -126,7 +135,8 @@ "so it sits in the ``datasette_agent`` scope; with a datasette-agent " "that has no telemetry it lands on whatever span is current, or " "nowhere. Set only when the tool returns: an exception escaping the " - "tool leaves it unset.", + "tool leaves it unset (a datasette-agent version with telemetry " + "records ``error.type`` on its own span).", values={"ok", "error", "denied"}, ) DEBUG_OUTCOME = Attribute( @@ -138,7 +148,9 @@ "cancelled before a result came back. ``denied``: the actor may not edit " "the app. ``invalid``: the debug request was rejected (e.g. a bad " "viewport). ``unsupported``: the agent host does not support browser " - "tasks.", + "tasks. Also set on the ``app_debug`` tool span alongside " + "``apps.tool.result``. There is no ``error`` outcome: an exception " + "escaping the tool records nothing.", values={ "ok", "script_error", @@ -161,8 +173,17 @@ "internal ``datasette.client`` call to Datasette's JSON API, which nests " "inside as a SERVER span tagged ``datasette.internal_client``. Only an " "unexpected exception (outcome ``error``) sets status ``ERROR``; " - "exception messages are never recorded. ``db.namespace`` is set only " - "once the database has passed the app's allowlist.", + "exception messages are never recorded. ``db.namespace`` reuses core's " + "attribute, which is declared as always present, but here it is set " + "only once the database has passed the app's allowlist - so it is " + "absent for ``invalid`` and ``not_allowed`` queries, and the requested " + "database name is never recorded unvetted. The internal request nests " + "under this span because the plugin injects W3C trace context headers " + "into it with the global propagator, a workaround for " + "https://github.com/simonw/datasette/issues/2969: with the default " + "propagator core would otherwise start it as a new trace. With " + "``OTEL_PROPAGATORS=none`` nothing is injected, but core extracts " + "nothing either, so it still nests.", attributes=( APP_ID, QUERY_SOURCE, @@ -215,7 +236,9 @@ COUNTER, "{run}", "Terminal ``app_debug`` tool executions, by outcome. The first " - "execution that suspends waiting for the browser is not counted.", + "execution that suspends waiting for the browser is not counted, and " + "neither is an execution that ends in an escaped exception (there is " + "no ``error`` outcome).", attributes=(DEBUG_OUTCOME,), ) M_DEBUG_RUN_DURATION = MetricName( @@ -247,6 +270,12 @@ ) +# Attributes this plugin adds to spans it does not own. The scoped +# conformance helpers never see them, so the conformance test and the +# generated README reference list them from here. +REQUEST_SPAN_ATTRIBUTES = (APP_ID, DEBUG_JOB_ID) +TOOL_SPAN_ATTRIBUTES = (APP_ID, DEBUG_JOB_ID, TOOL_RESULT, DEBUG_OUTCOME) + SPANS = (QUERY,) METRICS = ( diff --git a/scripts/telemetry-doc.py b/scripts/telemetry-doc.py new file mode 100644 index 0000000..2427ac4 --- /dev/null +++ b/scripts/telemetry-doc.py @@ -0,0 +1,144 @@ +#!/usr/bin/env python3 +"""Render README.md's OpenTelemetry reference from the telemetry registry. + +Rewrites the block between the telemetry-reference markers so the docs +cannot drift from the code; `--check` exits non-zero if the file would +change. `tests/test_telemetry_registry.py` imports `rendered_readme()` and +compares its output with the README, so the existing pytest run enforces +freshness. + +Usage: uv run scripts/telemetry-doc.py [--check] +""" + +from __future__ import annotations + +import sys +from pathlib import Path + +ROOT = Path(__file__).resolve().parent.parent +sys.path.insert(0, str(ROOT)) + +from datasette_apps import telemetry_registry as reg # noqa: E402 + +README = ROOT / "README.md" +START = "" +END = "" + +REQUEST_SPANS = "core's HTTP request spans" +TOOL_SPANS = "the agent tool span" + + +def _md(text: str) -> str: + "Registry descriptions use RST double-backtick literals; fold to Markdown." + return " ".join(text.replace("``", "`").split()) + + +def _attribute_names(attributes) -> str: + return ", ".join( + f"`{attribute}`" + (" *(optional)*" if attribute.optional else "") + for attribute in attributes + ) + + +def _used_on(attribute) -> list[str]: + places = [f"`{span}`" for span in reg.SPANS if attribute in span.attributes] + places += [ + f"`{metric}`" for metric in reg.METRICS if attribute in metric.attributes + ] + if attribute in reg.REQUEST_SPAN_ATTRIBUTES: + places.append(REQUEST_SPANS) + if attribute in reg.TOOL_SPAN_ATTRIBUTES: + places.append(TOOL_SPANS) + return places + + +def render() -> str: + lines: list[str] = [] + add = lines.append + add("#### Spans") + add("") + for span in reg.SPANS: + kind = f" *({span.kind.name})*" if span.kind.name != "INTERNAL" else "" + add(f"**`{span}`**{kind} - {_md(span.description)}") + add("") + add(f"Attributes: {_attribute_names(span.attributes)}.") + add("") + add("#### Attributes on spans this plugin does not own") + add("") + add( + f"- On {REQUEST_SPANS} (scope `datasette`): " + f"{_attribute_names(reg.REQUEST_SPAN_ATTRIBUTES)}." + ) + add( + f"- On {TOOL_SPANS} (datasette-agent's `execute_tool {{tool}}`, scope " + f"`datasette_agent`, when it has telemetry): " + f"{_attribute_names(reg.TOOL_SPAN_ATTRIBUTES)}." + ) + add("") + add("#### Metrics") + add("") + for metric in reg.METRICS: + add( + f"**`{metric}`** *({metric.kind}, unit `{metric.unit}`)* - " + f"{_md(metric.description)}" + ) + add("") + if metric.attributes: + add(f"Attributes: {_attribute_names(metric.attributes)}.") + add("") + if metric.buckets is not None: + buckets = ", ".join(str(boundary) for boundary in metric.buckets) + add(f"Bucket boundaries: {buckets}.") + add("") + add("#### Attributes") + add("") + for attribute in reg.ATTRIBUTES: + parts = [f"- `{attribute}`"] + if attribute.optional: + parts.append("*(optional)*") + parts.append("-") + parts.append(_md(attribute.description)) + if attribute.values is not None: + values = ", ".join( + f"`{str(value).lower() if isinstance(value, bool) else value}`" + for value in sorted(attribute.values, key=str) + ) + parts.append(f"One of: {values}.") + parts.append(f"Used on: {', '.join(_used_on(attribute))}.") + add(" ".join(parts)) + return "\n".join(lines).rstrip() + "\n" + + +def rendered_readme(text: str) -> str: + "`text` with the block between the markers replaced by `render()`." + if START not in text or END not in text: + raise ValueError(f"README.md is missing the {START} / {END} markers") + head, rest = text.split(START, 1) + _, tail = rest.split(END, 1) + return f"{head}{START}\n\n{render()}\n{END}{tail}" + + +def main() -> int: + check = "--check" in sys.argv + text = README.read_text() + try: + updated = rendered_readme(text) + except ValueError as e: + print(e, file=sys.stderr) + return 1 + if updated == text: + return 0 + if check: + print( + "README.md telemetry reference is stale; run " + "`uv run scripts/telemetry-doc.py`", + file=sys.stderr, + ) + return 1 + README.write_text(updated) + print("Rewrote README.md telemetry reference") + return 0 + + +if __name__ == "__main__": + raise SystemExit(main()) diff --git a/tests/test_telemetry_conformance.py b/tests/test_telemetry_conformance.py new file mode 100644 index 0000000..0bd6036 --- /dev/null +++ b/tests/test_telemetry_conformance.py @@ -0,0 +1,610 @@ +"""Registry <-> reality conformance and the sentinel privacy walk. + +One broad workload (``exercise``) emits every registered span, metric and +attribute, then a single ``collect()`` feeds the kit's four conformance +assertions (always scoped to ``datasette_apps``: the fixtures also capture +core's spans and any other installed plugin's). Attributes this plugin sets +on *other* scopes' spans - core's request spans and the agent tool span - +are not seen by the scoped helpers, so they are checked explicitly. + +The workload is driven with sentinel values in every private input. Two +privacy passes follow: an unscoped one (core's telemetry included) for +everything except SQL, and a scoped one for SQL text and stored query +names, which core records by design (``db.query`` spans carry SQL text; +the internal ``datasette.client`` request's ``url.path`` carries a stored +query's name). The sentinels therefore never appear inside SQL literals, +apart from the one scoped SQL sentinel. +""" + +import json +import secrets +import sqlite3 + +import pytest + +pytest.importorskip("opentelemetry.sdk") + +from datasette.app import Datasette +from datasette.telemetry_testing import ( + assert_metrics_conform, + assert_metrics_covered, + assert_no_forbidden_values, + assert_spans_conform, + assert_spans_covered, +) +from opentelemetry import trace +from opentelemetry.trace import SpanKind + +from datasette_apps import Registry, views +from datasette_apps.debug import ( + JOB_EXPIRY_SECONDS, + debug_task_payload, + get_debug_job_for_call, +) +from datasette_apps.telemetry_registry import ( + APP_ID, + ATTRIBUTES, + DEBUG_JOB_ID, + DEBUG_OUTCOME, + M_DEBUG_RUN_DURATION, + M_DEBUG_SCRIPT_DURATION, + METRICS, + QUERY, + REQUEST_SPAN_ATTRIBUTES, + SPANS, + TOOL_RESULT, + TOOL_SPAN_ATTRIBUTES, +) +from test_debug_agent_tool import ( + FakeBrowserTaskPending, + FakeContext, + _tools_by_name, +) +from test_debug_jobs import _backdate_job + +SCOPE = "datasette_apps" + +# --- Sentinels ---------------------------------------------------------------- +# +# Planted in every private input. None of these may appear in any signal, in +# any scope. They are bound parameters, form fields, JSON bodies and tool +# arguments - never SQL text - so core's db.query spans (which record SQL +# text, but never parameter values) cannot produce false positives. + +SENTINELS = { + "actor": "sentinel-actor-3f9c", + "other_actor": "sentinel-actor-other-6a12", + "app_name": "Sentinel App Name 7d21", + "app_description": "sentinel-description-b0e4", + "app_html": "sentinel-html-51aa", + "param_value": "sentinel-param-c77e", + "stored_write_value": "sentinel-write-9a0d", + "csp_origin": "https://sentinel-origin-2b.example", + "debug_js": "sentinel-js-e61f", + "debug_result": "sentinel-result-8c3b", + "debug_error": "sentinel-error-40fa", + "agent_edit_text": "sentinel-edit-1d9e", + "app_list_query": "sentinel-search-77c0", + "conversation_id": "sentinel-conversation-4b8e", +} + +# Checked against this plugin's scope only. The SQL sentinel is a table name, +# so Datasette's "no such table" error - the AppQueryError message the app +# sees - quotes it; core's db.query span records the SQL (and that error) by +# design. A stored query's name is in the internal request's url.path. +SQL_SENTINEL = "sentinel_sql_5e3d" +STORED_QUERY_SENTINEL = "sentinel_stored_query_0f7b" +# Allowlisted but never created: not_found, no internal request +MISSING_QUERY_SENTINEL = "sentinel_missing_query_93d1" +# Created but not on the app's allowlist: not_allowed +UNLISTED_QUERY_SENTINEL = "sentinel_unlisted_query_c24a" +SCOPED_SENTINELS = { + SQL_SENTINEL, + STORED_QUERY_SENTINEL, + MISSING_QUERY_SENTINEL, + UNLISTED_QUERY_SENTINEL, +} + +ACTOR = {"id": SENTINELS["actor"]} +OTHER_ACTOR = {"id": SENTINELS["other_actor"]} +HTML = f"

{SENTINELS['app_html']}

\n" +DEBUG_JS = f"/* {SENTINELS['debug_js']} */ return 1;" + + +def _envelope(**overrides): + envelope = { + "ok": True, + "result": {"text": SENTINELS["debug_result"]}, + "events": { + "errors": [{"kind": "console-error", "message": SENTINELS["debug_result"]}], + "logs": [{"kind": "console-log", "message": SENTINELS["debug_result"]}], + }, + "duration_ms": 321, + "timed_out": False, + "outcome": "completed", + } + envelope.update(overrides) + return envelope + + +ERROR = {"message": SENTINELS["debug_error"], "stack": SENTINELS["debug_error"]} +DEBUG_OUTCOMES = { + "ok": _envelope(), + "script_error": _envelope(ok=False, error=ERROR, duration_ms=12), + "timed_out": _envelope(ok=False, error=ERROR, timed_out=True, duration_ms=None), + "task_expired": {"ok": False, "error": ERROR, "outcome": "expired"}, + "task_cancelled": {"ok": False, "error": ERROR, "outcome": "cancelled"}, +} + + +class _Boom(Exception): + "Escapes the query body once, to exercise outcome error / error.type." + + +# --- Workload ----------------------------------------------------------------- + + +def _databases(tmp_path): + content = tmp_path / "content.db" + conn = sqlite3.connect(content) + conn.executescript(""" + create table news (id integer primary key, title text); + insert into news (title) values ('First'), ('Second'); + """) + conn.close() + secret = tmp_path / "secret.db" + sqlite3.connect(secret).execute("create table t (id integer)").connection.close() + return [str(content), str(secret)] + + +def _context(call_key, **kwargs): + return FakeContext( + conversation_id=SENTINELS["conversation_id"], call_key=call_key, **kwargs + ) + + +class Workload: + def __init__(self, datasette): + self.datasette = datasette + self.tools = _tools_by_name() + self.tool_span_ids = set() + self.calls = 0 + + async def tool(self, tool_name, actor=ACTOR, **kwargs): + """Call an agent tool inside a stand-in for datasette-agent's + execute_tool span. Exceptions (BrowserTaskPending) are not recorded + on it: their message is the task label, which names the app.""" + with trace.get_tracer("test").start_as_current_span( + f"execute_tool {tool_name}", + record_exception=False, + set_status_on_exception=False, + ) as span: + self.tool_span_ids.add(span.get_span_context().span_id) + return await self.tools[tool_name].fn( + datasette=self.datasette, actor=actor, **kwargs + ) + + async def debug(self, app_id, outcome=None, call_key=None, **kwargs): + if call_key is None: + self.calls += 1 + call_key = f"call-{self.calls}" + kwargs.setdefault("javascript", DEBUG_JS) + kwargs.setdefault("context", _context(call_key, outcome=outcome)) + return await self.tool("app_debug", app_id=app_id, **kwargs) + + async def suspend(self, app_id): + "First execution of app_debug: leaves a pending job, records nothing." + self.calls += 1 + call_key = f"call-{self.calls}" + with pytest.raises(FakeBrowserTaskPending): + await self.debug(app_id, call_key=call_key) + job = await get_debug_job_for_call( + self.datasette, SENTINELS["conversation_id"], call_key + ) + return call_key, job + + async def query(self, app, body, path=None): + return await self.datasette.client.post( + path or f"/-/apps/{app['id']}/query", + actor=ACTOR, + content=body if isinstance(body, str) else json.dumps(body), + ) + + +async def exercise(tmp_path, monkeypatch): + # Every per-run secret (frame, channel and view bridge tokens) comes + # from secrets.token_urlsafe: capture them all as forbidden values. + tokens = [] + real_token_urlsafe = secrets.token_urlsafe + + def capturing_token_urlsafe(*args, **kwargs): + token = real_token_urlsafe(*args, **kwargs) + tokens.append(token) + return token + + monkeypatch.setattr(secrets, "token_urlsafe", capturing_token_urlsafe) + + datasette = Datasette( + _databases(tmp_path), + memory=True, + config={ + "permissions": { + "create-app": {"id": ACTOR["id"]}, + "apps-set-csp": {"id": ACTOR["id"]}, + }, + # Visible to nobody, so an allowed query against it is denied + "databases": {"secret": {"allow": {"id": "nobody"}}}, + }, + ) + await datasette.invoke_startup() + work = Workload(datasette) + registry = Registry(datasette) + + # --- App queries: every outcome, both kinds, both sources --------------- + await datasette.add_query( + "content", + STORED_QUERY_SENTINEL, + "select title from news where title != :title", + source="user", + owner_id=ACTOR["id"], + ) + await datasette.add_query( + "content", + UNLISTED_QUERY_SENTINEL, + "select 1", + source="user", + owner_id=ACTOR["id"], + ) + await datasette.add_query( + "content", + "add_news", + "insert into news (title) values (:title)", + is_write=True, + # Trusted, so it runs without the actor needing execute-write-sql + is_trusted=True, + source="user", + owner_id=ACTOR["id"], + ) + app = await registry.create_stored_app( + actor_id=ACTOR["id"], + name=SENTINELS["app_name"], + description=SENTINELS["app_description"], + html=HTML, + sql_databases=["content", "secret", "missing"], + stored_queries=[ + f"content/{STORED_QUERY_SENTINEL}", + "content/add_news", + f"content/{MISSING_QUERY_SENTINEL}", + ], + csp_origins=[SENTINELS["csp_origin"]], + ) + param = SENTINELS["param_value"] + results = { + "ok": await work.query( + app, + {"database": "content", "sql": "select :v as v", "params": {"v": param}}, + ), + "not_allowed": await work.query( + app, {"database": "_memory", "sql": "select 1"} + ), + "denied": await work.query(app, {"database": "secret", "sql": "select 1"}), + "failed": await work.query( + app, {"database": "content", "sql": f"select * from {SQL_SENTINEL}"} + ), + "invalid_json": await work.query(app, "not json"), + "invalid_params": await work.query( + app, {"database": "content", "sql": "select 1", "params": [param]} + ), + "not_found_db": await work.query( + app, {"database": "missing", "sql": "select 1"} + ), + "not_found_query": await work.query( + app, {"database": "content", "query": MISSING_QUERY_SENTINEL} + ), + "not_allowed_query": await work.query( + app, {"database": "content", "query": UNLISTED_QUERY_SENTINEL} + ), + "stored_read": await work.query( + app, + { + "database": "content", + "query": STORED_QUERY_SENTINEL, + "params": {"title": param}, + }, + ), + "stored_write": await work.query( + app, + { + "database": "content", + "query": "add_news", + "params": {"title": SENTINELS["stored_write_value"]}, + }, + ), + } + + async def boom(*args, **kwargs): + raise _Boom() + + with monkeypatch.context() as patch: + patch.setattr(views, "run_app_query", boom) + results["error"] = await work.query( + app, {"database": "content", "sql": "select 1"} + ) + + assert results["ok"].json()["result"]["rows"] == [{"v": param}] + assert results["stored_read"].json()["result"]["rows"] + assert results["stored_write"].json()["ok"] is True + assert results["error"].status_code == 500 + # The AppQueryError message the app sees quotes the SQL sentinel + assert SQL_SENTINEL in results["failed"].json()["error"] + assert "not allowed" in results["not_allowed_query"].json()["error"] + assert results["not_found_query"].json()["error"] == "Stored query not found" + for name in ("not_allowed", "denied", "invalid_json", "not_found_query"): + assert results[name].json()["ok"] is False, name + + # --- Web changes -------------------------------------------------------- + create = await datasette.client.post( + "/-/apps/create", + actor=ACTOR, + data={ + "name": SENTINELS["app_name"], + "description": SENTINELS["app_description"], + "html": HTML, + "csp_origins": SENTINELS["csp_origin"], + }, + ) + assert create.status_code == 302 + web_app_id = create.headers["location"].rsplit("/", 1)[-1] + assert (await registry.get_csp_origins(web_app_id)) == [SENTINELS["csp_origin"]] + view = await datasette.client.get(f"/-/apps/{web_app_id}", actor=ACTOR) + assert view.status_code == 200 + edit = await datasette.client.post( + f"/-/apps/{web_app_id}/edit", + actor=ACTOR, + data={ + "name": SENTINELS["app_name"], + "description": SENTINELS["app_description"], + "html": f"

{SENTINELS['agent_edit_text']}

", + }, + ) + assert edit.status_code == 302 + for action in ("pin", "unpin", "delete"): + response = await datasette.client.post( + f"/-/apps/{web_app_id}/{action}", actor=ACTOR + ) + assert response.status_code == 302, action + + # --- Agent tools: every apps.tool.result -------------------------------- + created = json.loads( + await work.tool( + "app_create", + name=SENTINELS["app_name"], + description=SENTINELS["app_description"], + html=HTML, + csp_origins=[SENTINELS["csp_origin"]], + ) + ) + agent_app_id = created["app_id"] + edited = json.loads( + await work.tool( + "app_edit", + app_id=agent_app_id, + edits=[ + { + "operation": "str_replace", + "old_str": SENTINELS["app_html"], + "new_str": SENTINELS["agent_edit_text"], + } + ], + ) + ) + assert edited["edits_applied"] == 1 + assert "error" in json.loads( + await work.tool( + "app_create", name=SENTINELS["app_name"], html=HTML, actor=OTHER_ACTOR + ) + ) + assert "error" in json.loads( + await work.tool( + "app_str_replace", + app_id=agent_app_id, + old_str=SENTINELS["debug_error"], + new_str=SENTINELS["agent_edit_text"], + ) + ) + await work.tool("app_list", query=SENTINELS["app_list_query"]) + + # --- app_debug: the browser flow, then every other outcome -------------- + call_key, job = await work.suspend(app["id"]) + frame_url = debug_task_payload(datasette, job)["frame_url"] + assert job["config"]["frame_token"] in frame_url + frame = await datasette.client.get(frame_url, actor=ACTOR) + assert frame.status_code == 200 + debug_query = await work.query( + app, + {"database": "content", "sql": "select :v as v", "params": {"v": param}}, + path=f"/-/apps/debug/{job['id']}/query", + ) + assert debug_query.json()["ok"] is True + await work.debug(app["id"], outcome=DEBUG_OUTCOMES["ok"], call_key=call_key) + for name in ("script_error", "timed_out", "task_expired", "task_cancelled"): + await work.debug(app["id"], outcome=DEBUG_OUTCOMES[name]) + await work.debug(app["id"], actor=OTHER_ACTOR) # denied + await work.debug(app["id"], viewport={"width": 1, "height": 1}) # invalid + await work.debug( # unsupported + app["id"], + context=_context("call-unsupported", supports_browser_tasks=False), + ) + + # A pending job hit after its window: lazily expired and counted + _, stale = await work.suspend(app["id"]) + await _backdate_job(datasette, stale["id"], JOB_EXPIRY_SECONDS + 60) + stale_frame = debug_task_payload(datasette, stale)["frame_url"] + assert (await datasette.client.get(stale_frame, actor=ACTOR)).status_code == 403 + + assert job["config"]["frame_token"] in tokens + assert job["config"]["channel_token"] in tokens + # The view bridge token was minted and handed to the page + assert any(token in view.text for token in tokens) + return { + "tokens": tokens, + # Apps reached through HTTP routes; the agent-created one only ever + # through tools. The stale job's frame request was refused before + # its request span could be tagged. + "route_app_ids": {app["id"], web_app_id}, + "route_job_ids": {job["id"]}, + "tool_app_ids": {app["id"], agent_app_id}, + "tool_job_ids": {job["id"]}, + "tool_span_ids": work.tool_span_ids, + } + + +# --- The test ------------------------------------------------------------------- + + +def _is_ours(span): + return span.instrumentation_scope is not None and ( + span.instrumentation_scope.name == SCOPE + ) + + +@pytest.mark.asyncio +async def test_conformance_and_privacy(tmp_path, otel_spans, otel_metrics, monkeypatch): + seen = await exercise(tmp_path, monkeypatch) + finished = otel_spans.get_finished_spans() + # Exactly one collect(): the reader is delta-temporality, so anything an + # earlier collect() drained would be invisible to the coverage checks. + otel_metrics.collect() + + # --- Conformance, in both directions ------------------------------------ + assert_spans_conform(SPANS, finished, scope_name=SCOPE) + assert_spans_covered(SPANS, finished, scope_name=SCOPE) + assert_metrics_conform(METRICS, otel_metrics, scope_name=SCOPE) + assert_metrics_covered(METRICS, otel_metrics, scope_name=SCOPE) + + ours = [span for span in finished if _is_ours(span)] + foreign = [span for span in finished if not _is_ours(span)] + + # --- Privacy ------------------------------------------------------------ + forbidden = set(SENTINELS.values()) | set(seen["tokens"]) + # 1. Unscoped: core's telemetry included. Covers the frame token in + # ?token= (core records url.path without the query string) and the + # parameter values sent as query string args to /-/query.json. + assert_no_forbidden_values( + forbidden, finished_spans=finished, collector=otel_metrics + ) + # 2. Scoped: SQL text and stored query names. Core records both by + # design, so first prove the sentinels really reached telemetry. The + # SQL sentinel is also the text of an AppQueryError message (the + # "failed" query's "no such table" error), so this proves exception + # messages stay off apps.query too... + core_text = json.dumps( + [dict(span.attributes or {}) for span in foreign] + + [span.status.description for span in foreign], + default=str, + ) + assert SQL_SENTINEL in core_text + assert STORED_QUERY_SENTINEL in core_text + # ...then that this plugin never adds them again. + assert_no_forbidden_values( + SCOPED_SENTINELS, + finished_spans=finished, + collector=otel_metrics, + scope_name=SCOPE, + ) + # The kit checks status descriptions for sentinels, not their absence: + # this plugin never sets one, and never records an exception event. + for span in ours: + assert not span.status.description, span.name + assert not span.events, span.name + + query_spans = [span for span in ours if span.name == QUERY] + # assert_spans_covered skips optional attributes: every one must still + # have been exercised. + for attribute in QUERY.attributes: + assert any( + attribute in span.attributes for span in query_spans + ), f"{attribute} never set on {QUERY}" + for attribute in QUERY.attributes: + if attribute.values is not None: + assert { + span.attributes[attribute] + for span in query_spans + if attribute in span.attributes + } == set(attribute.values), attribute + for metric in METRICS: + for attribute in metric.attributes: + assert any( + attribute in point.attributes for point in otel_metrics.points(metric) + ), f"{metric}: {attribute} never collected" + # Every declared enum value was collected, so no dimension is dead. The + # debug duration histograms are recorded only for runs that came back + # from the browser (and the script duration only when it reported + # duration_ms), by design. + browser = {"ok", "script_error", "timed_out", "task_expired", "task_cancelled"} + expected_values = { + (M_DEBUG_RUN_DURATION, DEBUG_OUTCOME): browser, + (M_DEBUG_SCRIPT_DURATION, DEBUG_OUTCOME): {"ok", "script_error"}, + } + for metric in METRICS: + for attribute in metric.attributes: + if attribute.values is not None: + assert { + point.attributes[attribute] + for point in otel_metrics.points(metric) + if attribute in point.attributes + } == expected_values.get( + (metric, attribute), set(attribute.values) + ), f"{metric}: {attribute}" + + # --- Attributes on other scopes' spans ---------------------------------- + registered = {str(attribute): attribute for attribute in ATTRIBUTES} + for span in finished: + for key, value in (span.attributes or {}).items(): + if key.startswith("apps."): + assert key in registered, f"{span.name}: unregistered {key}" + allowed = registered[key].values + assert allowed is None or value in allowed, f"{span.name}: {key}" + request_spans = [ + span + for span in foreign + if span.kind == SpanKind.SERVER + and span.instrumentation_scope.name == "datasette" + ] + tool_spans = [ + span + for span in foreign + if span.get_span_context().span_id in seen["tool_span_ids"] + ] + for span in request_spans: + ours_on_it = {key for key in span.attributes if key.startswith("apps.")} + assert ours_on_it <= set(REQUEST_SPAN_ATTRIBUTES), span.name + for attribute in REQUEST_SPAN_ATTRIBUTES: + assert any( + attribute in span.attributes for span in request_spans + ), f"{attribute} never set on a request span" + assert {s.attributes.get(APP_ID) for s in request_spans} - {None} == seen[ + "route_app_ids" + ] + assert {s.attributes.get(DEBUG_JOB_ID) for s in request_spans} - {None} == seen[ + "route_job_ids" + ] + + for span in tool_spans: + assert set(span.attributes) <= set(TOOL_SPAN_ATTRIBUTES), span.name + for attribute in TOOL_SPAN_ATTRIBUTES: + assert any( + attribute in span.attributes for span in tool_spans + ), f"{attribute} never set on a tool span" + assert { + s.attributes[TOOL_RESULT] for s in tool_spans if TOOL_RESULT in s.attributes + } == set(TOOL_RESULT.values) + assert { + s.attributes[DEBUG_OUTCOME] for s in tool_spans if DEBUG_OUTCOME in s.attributes + } == set(DEBUG_OUTCOME.values) + assert {s.attributes.get(APP_ID) for s in tool_spans} - {None} == seen[ + "tool_app_ids" + ] + assert {s.attributes.get(DEBUG_JOB_ID) for s in tool_spans} - {None} >= seen[ + "tool_job_ids" + ] diff --git a/tests/test_telemetry_registry.py b/tests/test_telemetry_registry.py index 34dc1c2..d7c6ea9 100644 --- a/tests/test_telemetry_registry.py +++ b/tests/test_telemetry_registry.py @@ -1,5 +1,8 @@ """Static checks on datasette-apps' telemetry registry (no SDK needed).""" +import importlib.util +from pathlib import Path + from datasette_apps.telemetry_registry import ( APP_ID, ATTRIBUTES, @@ -7,9 +10,13 @@ DEBUG_JOB_ID, HISTOGRAM, METRICS, + REQUEST_SPAN_ATTRIBUTES, SPANS, + TOOL_SPAN_ATTRIBUTES, ) +ROOT = Path(__file__).resolve().parent.parent + # Core's semantic-convention names, deliberately reused rather than shadowed. CORE_ATTRIBUTES = {"db.namespace", "error.type"} @@ -100,3 +107,32 @@ def test_only_histograms_have_increasing_buckets(): ), f"{metric!r} buckets are not strictly increasing" else: assert metric.buckets is None, f"{metric!r} is not a histogram" + + +def test_every_attribute_is_used(): + # Declared-but-dead attributes are documentation for a signal that does + # not exist. Attributes set only on spans this plugin does not own + # (core's request spans, the agent tool span) count via their tuples. + used = set(REQUEST_SPAN_ATTRIBUTES) | set(TOOL_SPAN_ATTRIBUTES) + for entry in (*SPANS, *METRICS): + used.update(entry.attributes) + unused = [str(attribute) for attribute in ATTRIBUTES if attribute not in used] + assert not unused, f"registered but never used: {unused}" + registered = set(ATTRIBUTES) + for attribute in (*REQUEST_SPAN_ATTRIBUTES, *TOOL_SPAN_ATTRIBUTES): + assert attribute in registered, attribute + + +def test_generated_docs_are_fresh(): + # In-process rather than a subprocess: the same renderer as + # `uv run scripts/telemetry-doc.py --check`. + spec = importlib.util.spec_from_file_location( + "telemetry_doc", ROOT / "scripts" / "telemetry-doc.py" + ) + telemetry_doc = importlib.util.module_from_spec(spec) + spec.loader.exec_module(telemetry_doc) + readme = (ROOT / "README.md").read_text() + assert telemetry_doc.rendered_readme(readme) == readme, ( + "README.md telemetry reference is stale; run " + "`uv run scripts/telemetry-doc.py`" + )