From f28db54eda60fedf426d21ae6d3b802007c0bbbe Mon Sep 17 00:00:00 2001 From: Alex Garcia Date: Wed, 2 Sep 2026 12:24:42 -0700 Subject: [PATCH] Add a plugin telemetry kit: public registry API, linked_root_span_kwargs, test helpers, docs A survey of five plugin OTel plans (datasette-paper, -agent, -litestream, -accounts, -cron) found every one hand-copying the same core machinery: the registry classes, the conformance-test harness, the pytest fixtures, the bucket boundaries and the detached-root-with-Link recipe. This makes that machinery importable instead: - The registry classes are documented public API. Attribute gains values= (a closed enum the conformance helpers enforce - what makes an attribute safe as a metric dimension); SpanName gains prefix=True for span families like "chat {model}" whose names share a fixed prefix, matched by span_for() after exact names. span_for()/attribute helpers accept a spans= tuple so plugin registries can use them. - datasette.telemetry.linked_root_span_kwargs(): the root-span-with-Link shape for work a request caused without containing - background jobs, scheduled ticks, block=False writes. Core's own write thread now uses it instead of building the kwargs inline. - datasette.telemetry_testing: the session provider fixtures, otel_spans / otel_metrics, a two-way registry conformance checker (including enum and prefix handling, filtered by instrumentation scope) and an assert_package_never_imports_sdk() guard. Core's conftest now imports these instead of defining them, so the suite consumes the kit exactly as a plugin's would. - New "Telemetry for plugin authors" docs page: scope discipline, registry usage, privacy/cardinality rules, named-callable guidance, request_span(), the background root-with-link convention (one root per tick, always emitted), provider-ordering facts and known caveats. request_span() is now documented public API. Co-Authored-By: Claude Fable 5 Claude-Session: https://claude.ai/code/session_012U7coQfVu8nK2R4q2mCULA --- datasette/database.py | 37 +--- datasette/telemetry.py | 32 ++- datasette/telemetry_registry.py | 74 +++++-- datasette/telemetry_testing.py | 294 ++++++++++++++++++++++++++++ docs/changelog.rst | 2 + docs/index.rst | 1 + docs/internals.rst | 2 + docs/plugin_telemetry.rst | 195 ++++++++++++++++++ docs/telemetry_doc.py | 6 +- tests/conftest.py | 161 +-------------- tests/test_http_span.py | 2 +- tests/test_telemetry_registry.py | 37 +++- tests/test_telemetry_testing_kit.py | 138 +++++++++++++ 13 files changed, 785 insertions(+), 196 deletions(-) create mode 100644 datasette/telemetry_testing.py create mode 100644 docs/plugin_telemetry.rst create mode 100644 tests/test_telemetry_testing_kit.py diff --git a/datasette/database.py b/datasette/database.py index 96d42a21..d3ee3395 100644 --- a/datasette/database.py +++ b/datasette/database.py @@ -14,11 +14,12 @@ from pathlib import Path import sqlite_utils from opentelemetry import context as otel_context_api -from opentelemetry.trace import Link, Status, StatusCode, get_current_span +from opentelemetry.trace import Status, StatusCode from .inspect import inspect_hash from .telemetry import ( callback_name, + linked_root_span_kwargs, record_operation_duration, record_query_interrupted, record_write_queue_wait, @@ -615,39 +616,19 @@ class Database: # warning rather than raising, so this pairing is load-bearing # and easy to get wrong silently. # - block=False: the caller returned already without awaiting, - # so the enqueueing span may already have closed (and - # exported) before this task's spans even start - parenting to - # it would make a child appear to outlive its already-closed - # parent, which OTel allows but which renders badly in most - # trace UIs. The enqueueing request *caused* this write + # so the enqueueing span may have closed before this task's + # spans even start. The enqueueing request *caused* this write # without *containing* it, so nothing is attached here - - # instead each write span is started as its own root (explicit - # empty `context=`, so the write thread's ambient context - # cannot supply a parent either) carrying one `Link` back to - # the enqueueing span's context, built once into - # `write_span_kwargs` and spread into every start_span call - # below. + # linked_root_span_kwargs() makes each write span a root with + # a Link back to the enqueueing span (see its docstring for + # the full rationale), built once into `write_span_kwargs` + # and spread into every start_span call below. token = None write_span_kwargs = {} if task.block: token = otel_context_api.attach(task.otel_context) else: - enqueueing_span_context = get_current_span( - task.otel_context - ).get_span_context() - # No attributes on the link: there is only one kind of link - # here, so naming the relationship would be a constant that - # carries no information a consumer does not already have - # from the link's existence. - links = ( - [Link(enqueueing_span_context)] - if enqueueing_span_context.is_valid - else [] - ) - write_span_kwargs = { - "context": otel_context_api.Context(), - "links": links, - } + write_span_kwargs = linked_root_span_kwargs(task.otel_context) try: exception = None result = None diff --git a/datasette/telemetry.py b/datasette/telemetry.py index 4693e1fb..087f2950 100644 --- a/datasette/telemetry.py +++ b/datasette/telemetry.py @@ -23,11 +23,12 @@ import time import weakref from contextlib import contextmanager +from opentelemetry import context as otel_context_api from opentelemetry import metrics as otel_metrics from opentelemetry import trace as otel_trace from opentelemetry.propagate import extract from opentelemetry.propagators.textmap import Getter -from opentelemetry.trace import SpanKind, Status, StatusCode +from opentelemetry.trace import Link, SpanKind, Status, StatusCode, get_current_span from .telemetry_registry import ( DB_NAMESPACE, @@ -105,6 +106,35 @@ def callback_name(fn) -> str: return getattr(fn, "__qualname__", type(fn).__name__) +def linked_root_span_kwargs(context=None): + """ + Keyword arguments that start a span as a root in its own trace, carrying + a ``Link`` back to whatever span is current - the shape for work that a + request *caused* without *containing*. + + Use it when the causing span will end before the work does (a background + task, a scheduled job, a ``block=False`` write): parenting there would + draw a child outliving its closed parent, which renders badly in most + trace UIs. The explicit empty ``Context()`` also stops the worker + thread's ambient context from supplying an accidental parent. + + Pass ``context`` to link to the span current in a *captured* context + (e.g. one carried across a queue) rather than the caller's. If no valid + span is current there is simply no link. The link carries no attributes: + with only one kind of link, naming the relationship would add nothing. + + Works with any tracer:: + + with my_tracer.start_as_current_span( + "myplugin.job", **linked_root_span_kwargs() + ): + ... + """ + cause = get_current_span(context).get_span_context() + links = [Link(cause)] if cause.is_valid else [] + return {"context": otel_context_api.Context(), "links": links} + + # db.operation.name is the leading keyword of a statement matched against a # fixed allowlist - deliberately not a parse. # diff --git a/datasette/telemetry_registry.py b/datasette/telemetry_registry.py index e4082347..aa9a7b91 100644 --- a/datasette/telemetry_registry.py +++ b/datasette/telemetry_registry.py @@ -30,14 +30,24 @@ class Attribute(str): A span attribute key, carrying its own documentation. Subclasses `str` so it can be handed straight to `set_attribute()`. + + Part of Datasette's public plugin API - plugins declare their own + telemetry registries with these classes. See the "Telemetry for plugin + authors" documentation. """ - __slots__ = ("description", "optional") + __slots__ = ("description", "optional", "values") - def __new__(cls, name, description, optional=False): + def __new__(cls, name, description, optional=False, values=None): self = super().__new__(cls, name) self.description = description self.optional = optional + # A closed enum vocabulary for the attribute's values, or None for + # an open value set. Declaring one does two things: the conformance + # helpers assert every emitted value is a member, and it marks the + # attribute as bounded - safe to use as a metric dimension, where an + # open value set would be a cardinality hazard. + self.values = frozenset(values) if values is not None else None return self def __repr__(self): @@ -45,21 +55,31 @@ class Attribute(str): class SpanName(str): - "A span name, carrying its documentation and the attributes it may set." + """A span name, carrying its documentation and the attributes it may set. - __slots__ = ("attributes", "description", "dynamic", "kind") + Part of Datasette's public plugin API, like `Attribute`. + """ + + __slots__ = ("attributes", "description", "dynamic", "kind", "prefix") def __new__( cls, name, description, attributes=(), + prefix=False, dynamic=False, kind=SpanKind.INTERNAL, ): self = super().__new__(cls, name) self.description = description self.attributes = tuple(attributes) + # True for a span family whose emitted names carry a variable suffix + # after a fixed prefix - e.g. a plugin's `chat {model}` registered as + # SpanName("chat ", ..., prefix=True) - so `span_for()` matches by + # prefix rather than equality. Core registers none itself; the flag + # exists for plugin registries. + self.prefix = prefix # True when the emitted name is composed at runtime and shares no # fixed prefix with the registry entry - the HTTP request span, whose # name is the request method followed by the matched route. There is @@ -405,23 +425,37 @@ SPANS = ( ) -def span_for(emitted_name, kind=None): +def span_for(emitted_name, kind=None, spans=None): """ Resolve an emitted span name to its registry entry, or None. - Handles `dynamic=True` entries, whose emitted names are not knowable in - advance: the name has no fixed part at all, so it is matched on `kind` - instead and the caller has to supply one. Exact entries are tried first, - so a dynamic entry can never shadow a span that does have a registered - name. + Handles the two entry kinds whose emitted names are not knowable in + advance: + + - `prefix=True` - the name carries a variable suffix after a fixed + prefix, matched by prefix. Core registers none; plugin registries use + it for names like ``chat {model}``. + - `dynamic=True` - the name has no fixed part at all, so it is matched + on `kind` instead and the caller has to supply one. + + Exact matches win over prefix matches, and both win over dynamic, so a + looser entry can never shadow a span with a registered name. + + `spans` defaults to core's own registry; the plugin testing kit passes a + plugin's tuple instead. """ - for span in SPANS: + if spans is None: + spans = SPANS + for span in spans: if span.dynamic: continue if emitted_name == span: return span + for span in spans: + if span.prefix and emitted_name.startswith(span): + return span if kind is not None: - for span in SPANS: + for span in spans: if span.dynamic and span.kind == kind: return span return None @@ -434,6 +468,22 @@ def attribute_allowed(span, emitted_key): return emitted_key in span.attributes +def attribute_value_allowed(span, emitted_key, value): + """ + Whether `value` is permitted for `emitted_key` on `span`. + + True for any value when the attribute declares no `values=` enum; when it + does, membership is enforced - that is what makes a declared enum a real + cardinality bound rather than documentation. + """ + if span is None: + return False + for attribute in span.attributes: + if attribute == emitted_key: + return attribute.values is None or value in attribute.values + return False + + # --- Metrics -------------------------------------------------------------- # Every duration histogram here is in seconds, and OpenTelemetry's default diff --git a/datasette/telemetry_testing.py b/datasette/telemetry_testing.py new file mode 100644 index 00000000..3aa3aff7 --- /dev/null +++ b/datasette/telemetry_testing.py @@ -0,0 +1,294 @@ +""" +Pytest helpers for testing OpenTelemetry instrumentation - Datasette's own +and any plugin's. Part of Datasette's public plugin API; see the "Telemetry +for plugin authors" documentation. + +Usage from a plugin's ``conftest.py``:: + + from datasette.telemetry_testing import ( # noqa: F401 + MetricsCollector, + otel_metrics, + otel_meter_provider, + otel_provider, + otel_spans, + ) + +Importing the fixture names into a conftest registers them; ``otel_provider`` +and ``otel_meter_provider`` are session-scoped and autouse, so a real SDK +provider (when the SDK is installed) is in place before any test emits a +signal. Tests then take ``otel_spans`` / ``otel_metrics``. Everything here +imports the OpenTelemetry SDK lazily: with no SDK installed the fixtures +skip rather than fail, and importing this module costs nothing. + +The conformance helpers (`assert_spans_conform`, `assert_registry_covered`) +check a registry of `SpanName` entries against actually-finished spans in +both directions - emitted-but-unregistered and registered-but-never-emitted, +the two drift modes documented in `tests/test_telemetry_registry.py`. +""" + +import subprocess +import sys + +import pytest + +from .telemetry_registry import ( + attribute_allowed, + attribute_value_allowed, + span_for, +) + +_span_exporter = None +_metric_reader = None + + +def install_span_exporter(): + """ + Install a TracerProvider + InMemorySpanExporter once per process and + return the exporter, or None when the SDK is not installed. + + `set_tracer_provider()` is effectively once-per-process (a second call + logs a warning and is ignored), so this must run before anything asserts + on spans. A `SimpleSpanProcessor` exports synchronously on span end - no + background batching thread, so assertions immediately after a request + never race. + """ + global _span_exporter + if _span_exporter is not None: + return _span_exporter + try: + from opentelemetry import trace as otel_trace + from opentelemetry.sdk.trace import TracerProvider + from opentelemetry.sdk.trace.export import SimpleSpanProcessor + from opentelemetry.sdk.trace.export.in_memory_span_exporter import ( + InMemorySpanExporter, + ) + except ImportError: + return None + exporter = InMemorySpanExporter() + provider = TracerProvider() + provider.add_span_processor(SimpleSpanProcessor(exporter)) + otel_trace.set_tracer_provider(provider) + _span_exporter = exporter + return exporter + + +def install_metric_reader(): + """ + Install a MeterProvider + InMemoryMetricReader once per process and + return the reader, or None when the SDK is not installed. + + DELTA temporality for counters and histograms, so each collection + reports only what happened since the previous one - with the SDK default + of CUMULATIVE, every metrics test would see every measurement from every + earlier test in the session. + """ + global _metric_reader + if _metric_reader is not None: + return _metric_reader + try: + from opentelemetry import metrics as otel_metrics_api + from opentelemetry.sdk.metrics import Counter, Histogram, MeterProvider + from opentelemetry.sdk.metrics.export import ( + AggregationTemporality, + InMemoryMetricReader, + ) + except ImportError: + return None + reader = InMemoryMetricReader( + preferred_temporality={ + Counter: AggregationTemporality.DELTA, + Histogram: AggregationTemporality.DELTA, + } + ) + otel_metrics_api.set_meter_provider(MeterProvider(metric_readers=[reader])) + _metric_reader = reader + return reader + + +@pytest.fixture(scope="session", autouse=True) +def otel_provider(): + """ + Session-scoped, autouse: install the span exporter exactly once, before + any span is created. + + `datasette.telemetry.tracer` (and a plugin's own tracer) is a + module-level `ProxyTracer`: once a provider exists, the first span it + starts resolves a concrete tracer and caches it permanently. It does + *not* cache the no-op tracer, so a span started before this fixture runs + is merely lost rather than poisoning the tracer for the process. With no + SDK installed this does nothing and spans stay no-op. + """ + install_span_exporter() + + +@pytest.fixture(scope="session", autouse=True) +def otel_meter_provider(): + """ + Session-scoped, autouse: install the metric reader once per process. + + Unlike the tracer, ordering is not load-bearing - `_ProxyMeter` and its + instruments forward to a provider installed after they were created. + Still autouse for symmetry, and so a single reader collects all run. + """ + install_metric_reader() + + +@pytest.fixture +def otel_spans(): + """ + Function-scoped access to the finished-spans exporter: clears spans left + over from previous tests, then yields the exporter so a test can call + `.get_finished_spans()`. Skips if the OTel SDK is not installed. + """ + pytest.importorskip("opentelemetry.sdk") + exporter = install_span_exporter() + if exporter is None: + pytest.skip("OpenTelemetry SDK provider was not installed") + exporter.clear() + yield exporter + + +class MetricsCollector: + """ + Thin reader over an `InMemoryMetricReader`. + + `collect()` runs a collection cycle - which is what invokes observable + gauge callbacks - and snapshots the result. Queries then run against + that snapshot rather than re-collecting, so a test that inspects + several metrics sees one consistent moment and does not drain delta + state twice. + """ + + def __init__(self, reader): + self.reader = reader + self.snapshot = {} + + def collect(self): + self.snapshot = {} + data = self.reader.get_metrics_data() + if data is None: + return self.snapshot + for resource_metrics in data.resource_metrics: + for scope_metrics in resource_metrics.scope_metrics: + for metric in scope_metrics.metrics: + self.snapshot.setdefault(metric.name, []).extend( + metric.data.data_points + ) + return self.snapshot + + def points(self, name, attributes=None): + "Data points for `name` whose attributes are a superset of `attributes`." + found = [] + for point in self.snapshot.get(name, []): + point_attributes = dict(point.attributes or {}) + if all(point_attributes.get(k) == v for k, v in (attributes or {}).items()): + found.append(point) + return found + + def point(self, name, attributes=None): + "The single matching data point, asserting there is exactly one." + found = self.points(name, attributes) + assert len(found) == 1, ( + f"expected exactly one {name} point matching {attributes}, " + f"got {len(found)}: {found}" + ) + return found[0] + + +@pytest.fixture +def otel_metrics(): + """ + Function-scoped metrics collector. Drains delta state accumulated by + earlier tests before yielding, so counts start from zero. + """ + pytest.importorskip("opentelemetry.sdk") + reader = install_metric_reader() + if reader is None: + pytest.skip("OpenTelemetry SDK meter provider was not installed") + reader.get_metrics_data() + yield MetricsCollector(reader) + + +def _scoped(finished_spans, scope_name): + if scope_name is None: + return list(finished_spans) + return [ + span + for span in finished_spans + if span.instrumentation_scope and span.instrumentation_scope.name == scope_name + ] + + +def assert_spans_conform(registry_spans, finished_spans, scope_name=None): + """ + Every finished span (optionally: only those from `scope_name`, which is + what a plugin should pass - its own tracer's name) resolves to an entry + in `registry_spans`, sets only registered attributes, and respects any + declared `values=` enums. This is the emitted-but-unregistered direction: + instrumentation added without documentation fails here. + """ + problems = [] + for span in _scoped(finished_spans, scope_name): + entry = span_for(str(span.name), kind=span.kind, spans=registry_spans) + if entry is None: + problems.append(f"unregistered span: {span.name!r}") + continue + for key, value in (span.attributes or {}).items(): + if not attribute_allowed(entry, str(key)): + problems.append(f"{span.name}: unregistered attribute {key!r}") + elif not attribute_value_allowed(entry, str(key), value): + problems.append( + f"{span.name}: {key}={value!r} not in the declared enum" + ) + assert not problems, "\n".join(problems) + + +def assert_registry_covered(registry_spans, finished_spans, scope_name=None): + """ + Every entry in `registry_spans` was emitted at least once, and every one + of its registered attributes appeared on it at least once. This is the + registered-but-never-emitted direction - documentation describing a + signal that no longer exists, which is worse than omitting it because a + reader will build a dashboard on it. Run it against a workload broad + enough to exercise everything the registry claims. + """ + spans = _scoped(finished_spans, scope_name) + seen_attributes = {} + for span in spans: + entry = span_for(str(span.name), kind=span.kind, spans=registry_spans) + if entry is not None: + seen = seen_attributes.setdefault(str(entry), set()) + seen.update(str(key) for key in (span.attributes or {})) + problems = [] + for entry in registry_spans: + if str(entry) not in seen_attributes: + problems.append(f"registered span never emitted: {entry!r}") + continue + missing = set(map(str, entry.attributes)) - seen_attributes[str(entry)] + if missing: + problems.append( + f"{entry}: registered attributes never emitted: {sorted(missing)}" + ) + assert not problems, "\n".join(problems) + + +def assert_package_never_imports_sdk(*module_names): + """ + Import the named modules in a fresh interpreter and assert none of them + dragged in `opentelemetry.sdk`. Checked via sys.modules in a subprocess + rather than by grepping, so a lazy `import opentelemetry.sdk` inside a + function body cannot slip past. A plugin should depend on + `opentelemetry-api` only, exactly as Datasette core does. + """ + imports = "; ".join(f"import {name}" for name in module_names) + code = ( + f"import sys; {imports}; " + "print([m for m in sys.modules if m.startswith('opentelemetry.sdk')])" + ) + result = subprocess.run( + [sys.executable, "-c", code], capture_output=True, text=True, check=True + ) + assert result.stdout.strip() == "[]", ( + f"importing {module_names} pulled in the OpenTelemetry SDK: " + f"{result.stdout.strip()}" + ) diff --git a/docs/changelog.rst b/docs/changelog.rst index 7a083d8f..a754402a 100644 --- a/docs/changelog.rst +++ b/docs/changelog.rst @@ -14,6 +14,8 @@ Unreleased - Every HTTP request now gets an OpenTelemetry ``SERVER`` span, named after the request method and matched route, carrying ``http.route``, the response status and W3C trace context extracted from inbound headers - so every database span has a request to belong to, and Datasette joins distributed traces started by a proxy or calling service. The query string is never recorded. See :ref:`internals_telemetry_requests`. (:issue:`1730`) - Datasette core now also emits OpenTelemetry **metrics** covering SQL thread pool saturation, per-database write queue depth, open connections, query latency and time-limit interruptions. These answer operational questions that spans structurally cannot - "am I saturating my :ref:`setting_num_sql_threads` threads?" is a level, not an event - and they survive trace sampling. As with spans, core installs no ``MeterProvider``, so there is no cost unless metrics are collected externally. See :ref:`internals_telemetry`. (:issue:`1730`) +- New :ref:`plugin telemetry kit ` for plugins that emit their own OpenTelemetry signals: the registry classes (``Attribute`` with closed-enum ``values=``, ``SpanName`` with prefix-matched families, ``MetricName``) are now documented public API, ``datasette.telemetry.linked_root_span_kwargs()`` provides the root-span-with-link shape for background work, ``datasette.telemetry.request_span()`` is documented, and ``datasette.telemetry_testing`` ships the pytest fixtures and two-way conformance checks core's own suite uses. (:issue:`1730`) + Nothing is removed by the OpenTelemetry work: the ``?_trace=1`` query string parameter, the ``trace_debug`` setting and the :ref:`internals_tracer` module all continue to work as before. .. _v1_0_a38: diff --git a/docs/index.rst b/docs/index.rst index d494fd17..bf109f68 100644 --- a/docs/index.rst +++ b/docs/index.rst @@ -64,6 +64,7 @@ Contents javascript_plugins plugin_hooks testing_plugins + plugin_telemetry internals events upgrade_guide diff --git a/docs/internals.rst b/docs/internals.rst index b82ebfbc..5f8fb437 100644 --- a/docs/internals.rst +++ b/docs/internals.rst @@ -2329,6 +2329,8 @@ Datasette core depends on `opentelemetry-api `__ its attribute names follow. This is separate from, and does not replace, the built-in :ref:`internals_tracer` mechanism behind ``?_trace=1`` and the :ref:`setting_trace_debug` setting. Both continue to work exactly as before. diff --git a/docs/plugin_telemetry.rst b/docs/plugin_telemetry.rst new file mode 100644 index 00000000..1999da4a --- /dev/null +++ b/docs/plugin_telemetry.rst @@ -0,0 +1,195 @@ +.. _plugin_telemetry: + +Telemetry for plugin authors +============================ + +Datasette core emits OpenTelemetry spans and metrics for the work it does itself - see :ref:`internals_telemetry` for what those are and how an operator turns them on. This page is about the other half: instrumenting the work **your plugin** does, so that a plugin's queries, background jobs and custom operations show up in the same traces and the same metrics pipeline, using the same conventions. + +Everything here follows one rule inherited from core: **depend on** ``opentelemetry-api`` **only, and never install a provider**. With no SDK installed every span and instrument your plugin creates is a free no-op; whoever runs Datasette decides whether telemetry is collected, sampled or exported. A plugin that installs a ``TracerProvider`` or configures an exporter is making an operator's decision for them. + +.. _plugin_telemetry_scope: + +Use your own instrumentation scope +---------------------------------- + +Never emit through core's tracer or meter. Your plugin's scope name is the machine-readable claim about *who emitted a signal*, and consumers filter on it: + +.. code-block:: python + + from opentelemetry import metrics, trace + + from my_plugin import __version__ + + tracer = trace.get_tracer("my-plugin", __version__) + meter = metrics.get_meter("my-plugin", __version__) + +If every attribute you emit follows current semantic conventions you can also pass ``schema_url=``; ``datasette.telemetry.SCHEMA_URL`` is the version core's own spellings track, with a comment explaining how to choose one. When in doubt, omit it - a wrong schema URL is worse than none. + +Name your own signals under a prefix you own (``my_plugin.*``). Reuse core's shared attribute spellings where they mean the same thing - ``db.namespace`` for a database name, ``error.type`` for a failure class - rather than minting parallel ones. + +.. _plugin_telemetry_registry: + +Declare a registry +------------------ + +Core keeps a single source of truth for every signal it emits in ``datasette/telemetry_registry.py``, and the classes it uses are public API. They subclass ``str``, so a registry entry *is* the name you pass to OpenTelemetry - no parallel constants to keep in step: + +.. code-block:: python + + from opentelemetry.trace import SpanKind + + from datasette.telemetry_registry import Attribute, MetricName, SpanName + + OUTCOME = Attribute( + "my_plugin.outcome", + "How the job ended.", + values={"ok", "error", "skipped"}, + ) + JOB_NAME = Attribute("my_plugin.job", "The registered job name.") + + JOB_RUN = SpanName( + "my_plugin.job.run", + "One execution of a scheduled job.", + (OUTCOME, JOB_NAME), + ) + + # A span family with a variable suffix - emitted as "my_plugin.chat gpt-5" + CHAT = SpanName( + "my_plugin.chat ", + "One model call, named ``my_plugin.chat {model}``.", + prefix=True, + ) + + SPANS = (JOB_RUN, CHAT) + + JOB_DURATION = MetricName( + "my_plugin.job.duration", + "Histogram", + "s", + "How long each job took.", + (JOB_NAME, OUTCOME), + buckets=(0.01, 0.1, 1, 10, 60, 600, 3600), + ) + +Three details that matter: + +- ``values=`` declares a **closed enum**. The conformance helpers (below) assert every emitted value is a member, which is what makes an attribute safe to use as a metric dimension - a metric series is keyed by its attribute values, so an open value set on a metric is an unbounded-cardinality hazard. +- ``prefix=True`` registers a span *family* whose emitted names share a fixed prefix; ``datasette.telemetry_registry.span_for()`` matches them by prefix, exact names first. +- Declare explicit histogram ``buckets=`` scaled to *your* domain. Core's SQLite-scale boundaries are importable as ``datasette.telemetry_registry.DURATION_BUCKETS`` (0.0001s to 10s) - use them if you are timing SQLite work so dashboards align, and define your own otherwise (a job scheduler wants buckets out to an hour; the SDK's defaults will put all your measurements in one bucket either way). + +.. _plugin_telemetry_privacy: + +Privacy and cardinality rules +----------------------------- + +Core's instrumentation records **no data users put into Datasette and no identifier that ties a signal to a person** - no parameter values, no query strings, no actor identifiers, no IP addresses. Hold your plugin to the same bar: + +- Attribute values should be closed enums, booleans, counts and durations. Anything echoed from user input - a name, a URL, a token, free text - does not belong on a span, and *especially* not on a metric. +- If you time user-influenced SQL, follow core: record the SQL via ``datasette.telemetry.sql_attribute()`` (truncated, never parameters) on spans only. +- When a value is interesting but unbounded, record a bounded proxy instead: a count, a byte size, a truncation flag, or the enum outcome. + +.. _plugin_telemetry_callbacks: + +Your database work is already traced +------------------------------------ + +Every call your plugin makes through :ref:`db.execute() `, :ref:`db.execute_fn() `, :ref:`db.execute_write() ` and :ref:`db.execute_write_fn() ` already emits core's ``db.query`` spans and is counted in the ``db.client.operation.duration`` histogram. Two consequences: + +- **Pass named callables**, not lambdas: the span for a callback-style call is identified by ``datasette.callback``, the callable's qualified name, and a lambda reports ````. +- If you also wrap those calls in your own span or histogram, you are creating a *second* series in *your* scope - that is fine and sometimes right (yours can carry plugin-level attributes core cannot know), but it is a deliberate two-series design, not a substitute for core's. + +.. _plugin_telemetry_request_span: + +Enriching the request span +-------------------------- + +Inside a view or ASGI middleware, ``datasette.telemetry.request_span(scope)`` returns the recording ``SERVER`` span for the current request, or ``None`` when nothing is recording - which is also your signal to skip any work done only to compute attributes: + +.. code-block:: python + + from datasette.telemetry import request_span + + async def my_view(request): + span = request_span(request.scope) + if span is not None: + span.set_attribute("my_plugin.cache", "hit") + ... + +.. _plugin_telemetry_background: + +Background work: roots with links +--------------------------------- + +A background job, a scheduled task or a queue consumer must **not** parent its spans to the request that caused it - by the time the work runs, that request span has usually ended, and a child outliving its closed parent renders badly in every major trace UI. The correct shape, the one core itself uses for ``execute_write(block=False)``, is a **root span carrying a link** to the causing span: + +.. code-block:: python + + from datasette.telemetry import linked_root_span_kwargs + + # Capture at scheduling time, while the causing span is current: + kwargs = linked_root_span_kwargs() + + # Later, wherever the work actually runs: + with tracer.start_as_current_span("my_plugin.job.run", **kwargs) as span: + span.set_attribute(OUTCOME, "ok") + +For a periodic loop (a health check, a scheduler tick), the convention is one root span **per tick**, always emitted - including no-op ticks, with an outcome attribute saying so - plus a tick counter metric. Suppressing quiet ticks seems tidy but destroys the signal operators actually want: "is the loop still running?". Pair the spans with a gauge for the loop's staleness if the interval is long. + +Two propagation facts worth knowing (details in ``datasette/telemetry.py``): + +- Core's ``tracer`` and yours are proxies. A ``ProxyTracer`` permanently caches the first concrete tracer it resolves *after* a provider exists, so in embedded deployments the provider must be installed before the first span - importing the module is fine, starting spans is not. Meters forward retroactively; tracers do not. +- ``asyncio.create_task`` copies the ambient context, so a long-running task created during a request will silently parent to that request's span - exactly the bug ``linked_root_span_kwargs()`` exists to avoid. + +.. _plugin_telemetry_testing: + +Testing your instrumentation +---------------------------- + +``datasette.telemetry_testing`` ships the same fixtures and checks core's own suite uses. In your ``conftest.py``: + +.. code-block:: python + + from datasette.telemetry_testing import ( # noqa: F401 + otel_metrics, + otel_meter_provider, + otel_provider, + otel_spans, + ) + +``otel_provider`` and ``otel_meter_provider`` are session-scoped and autouse - they install a real SDK provider (in-memory, synchronous export) once per process, and do nothing when the SDK is not installed, so add ``opentelemetry-sdk`` to your test dependencies only. Tests then take ``otel_spans`` (an ``InMemorySpanExporter``) or ``otel_metrics`` (a collector with ``collect()`` / ``point()`` helpers). + +Wire your registry to reality with the conformance helpers - the two directions catch instrumentation added without documentation and documentation describing signals that no longer exist: + +.. code-block:: python + + from datasette.telemetry_testing import ( + assert_package_never_imports_sdk, + assert_registry_covered, + assert_spans_conform, + ) + + from my_plugin.telemetry import SPANS + + + def test_conformance(otel_spans): + run_a_workload_that_exercises_everything() + finished = otel_spans.get_finished_spans() + # Everything emitted is registered (and enum values are legal): + assert_spans_conform(SPANS, finished, scope_name="my-plugin") + # Everything registered was emitted: + assert_registry_covered(SPANS, finished, scope_name="my-plugin") + + + def test_api_only_dependency(): + assert_package_never_imports_sdk("my_plugin") + +Always pass ``scope_name`` - the exporter also holds core's spans, and your registry should only be judged against your own. + +.. _plugin_telemetry_caveats: + +Known caveats +------------- + +- **Streaming responses hold the request span open.** Core's request span ends when the response body finishes, so for an SSE or long-streaming route its duration is the connection lifetime. If you need per-message timing on a stream, emit your own child spans or span events per message, and use gauges for concurrent-stream counts. +- **A plugin timing core's work double-measures by design.** See :ref:`plugin_telemetry_callbacks` above. +- ``datasette.client`` requests made from inside a request currently produce a nested ``SERVER`` span, which can double-count requests in kind-based dashboards. diff --git a/docs/telemetry_doc.py b/docs/telemetry_doc.py index 725cb968..f8aa22dd 100644 --- a/docs/telemetry_doc.py +++ b/docs/telemetry_doc.py @@ -15,7 +15,11 @@ def _attribute_lines(cog, attributes): cog.out(" Attributes:\n\n") for attribute in attributes: suffix = " *(optional)*" if attribute.optional else "" - cog.out(f" - ``{attribute}``{suffix} - {attribute.description}\n") + line = f" - ``{attribute}``{suffix} - {attribute.description}" + if attribute.values is not None: + rendered = ", ".join(f"``{value}``" for value in sorted(attribute.values)) + line += f" One of: {rendered}." + cog.out(line + "\n") cog.out("\n") diff --git a/tests/conftest.py b/tests/conftest.py index ff33da98..d3bbab1b 100644 --- a/tests/conftest.py +++ b/tests/conftest.py @@ -58,158 +58,15 @@ def find_free_port(): return sock.getsockname()[1] -_otel_span_exporter = None - - -@pytest.fixture(scope="session", autouse=True) -def _otel_provider(): - """ - Install a real OTel SDK TracerProvider + InMemorySpanExporter exactly - once, before any span is ever created in this process. - - This has to be session-scoped and autouse because - `opentelemetry.trace.set_tracer_provider()` is effectively - once-per-process: a second call logs a warning and is ignored. So the - install must happen exactly once, before anything asserts on spans. - - `datasette.telemetry.tracer` is a module-level `ProxyTracer`. Once a - provider exists, the first span it starts resolves a concrete tracer - and caches it permanently. It does *not* cache the no-op tracer, so - any span started before this fixture runs is merely lost rather than - poisoning the tracer for the rest of the process. If the SDK isn't - installed, do nothing: core spans stay no-op `NonRecordingSpan`s and - the rest of the suite is unaffected. - """ - global _otel_span_exporter - try: - from opentelemetry import trace as otel_trace - from opentelemetry.sdk.trace import TracerProvider - from opentelemetry.sdk.trace.export import SimpleSpanProcessor - from opentelemetry.sdk.trace.export.in_memory_span_exporter import ( - InMemorySpanExporter, - ) - except ImportError: - return - exporter = InMemorySpanExporter() - provider = TracerProvider() - # SimpleSpanProcessor exports synchronously on span end - no background - # batching thread, so assertions immediately after a request never race. - provider.add_span_processor(SimpleSpanProcessor(exporter)) - otel_trace.set_tracer_provider(provider) - _otel_span_exporter = exporter - - -@pytest.fixture -def otel_spans(): - """ - Function-scoped access to the finished-spans exporter: clears any spans - left over from previous tests, then yields the exporter so a test can - call `.get_finished_spans()` after making requests. Skips (rather than - fails) if the OTel SDK is not installed. - """ - pytest.importorskip("opentelemetry.sdk") - if _otel_span_exporter is None: - pytest.skip("OpenTelemetry SDK provider was not installed") - _otel_span_exporter.clear() - yield _otel_span_exporter - - -_otel_metric_reader = None - - -@pytest.fixture(scope="session", autouse=True) -def _otel_meter_provider(): - """ - Install a real OTel SDK MeterProvider + InMemoryMetricReader once per - process. - - Unlike the tracer, ordering is not load-bearing here - see the metrics - banner in `datasette/telemetry.py` for the `_ProxyMeter`-vs-`ProxyTracer` - difference. This fixture is still session-scoped and autouse for - symmetry, and so that a single reader collects for the whole run. - - DELTA temporality is chosen for counters and histograms so that each - collection reports only what happened since the previous one. With the - SDK default of CUMULATIVE, every metrics test would see every query run - by every earlier test in the session. - """ - global _otel_metric_reader - try: - from opentelemetry import metrics as otel_metrics - from opentelemetry.sdk.metrics import Counter, Histogram, MeterProvider - from opentelemetry.sdk.metrics.export import ( - AggregationTemporality, - InMemoryMetricReader, - ) - except ImportError: - return - reader = InMemoryMetricReader( - preferred_temporality={ - Counter: AggregationTemporality.DELTA, - Histogram: AggregationTemporality.DELTA, - } - ) - otel_metrics.set_meter_provider(MeterProvider(metric_readers=[reader])) - _otel_metric_reader = reader - - -class MetricsCollector: - """ - Thin reader over an `InMemoryMetricReader`. - - `collect()` runs a collection cycle - which is what invokes the observable - gauge callbacks - and snapshots the result. Queries then run against that - snapshot rather than re-collecting, so a test that inspects several - metrics sees one consistent moment and does not drain delta state twice. - """ - - def __init__(self, reader): - self.reader = reader - self.snapshot = {} - - def collect(self): - self.snapshot = {} - data = self.reader.get_metrics_data() - if data is None: - return self.snapshot - for resource_metrics in data.resource_metrics: - for scope_metrics in resource_metrics.scope_metrics: - for metric in scope_metrics.metrics: - self.snapshot.setdefault(metric.name, []).extend( - metric.data.data_points - ) - return self.snapshot - - def points(self, name, attributes=None): - "Data points for `name` whose attributes are a superset of `attributes`." - found = [] - for point in self.snapshot.get(name, []): - point_attributes = dict(point.attributes or {}) - if all(point_attributes.get(k) == v for k, v in (attributes or {}).items()): - found.append(point) - return found - - def point(self, name, attributes=None): - "The single matching data point, asserting there is exactly one." - found = self.points(name, attributes) - assert len(found) == 1, ( - f"expected exactly one {name} point matching {attributes}, " - f"got {len(found)}: {found}" - ) - return found[0] - - -@pytest.fixture -def otel_metrics(): - """ - Function-scoped metrics collector. Drains any delta state accumulated by - earlier tests before yielding, so counts start from zero. - """ - pytest.importorskip("opentelemetry.sdk") - if _otel_metric_reader is None: - pytest.skip("OpenTelemetry SDK meter provider was not installed") - _otel_metric_reader.get_metrics_data() - yield MetricsCollector(_otel_metric_reader) +# The otel fixtures moved to datasette.telemetry_testing, which is public +# plugin API - core's suite consumes it exactly the way a plugin's would. +from datasette.telemetry_testing import ( # noqa: F401, E402 + MetricsCollector, + otel_metrics, + otel_meter_provider, + otel_provider, + otel_spans, +) @pytest.fixture diff --git a/tests/test_http_span.py b/tests/test_http_span.py index ca2239d5..8e74175d 100644 --- a/tests/test_http_span.py +++ b/tests/test_http_span.py @@ -825,7 +825,7 @@ def test_no_provider_takes_the_fast_path(): install should pay essentially nothing for instrumentation it is not using. - This has to run in a subprocess. The suite's `_otel_provider` fixture is + This has to run in a subprocess. The suite's `otel_provider` fixture is session-scoped and autouse, and `set_tracer_provider()` is effectively once-per-process, so in-process every span is recording and the fast path is unreachable. diff --git a/tests/test_telemetry_registry.py b/tests/test_telemetry_registry.py index 418b99ff..b638997b 100644 --- a/tests/test_telemetry_registry.py +++ b/tests/test_telemetry_registry.py @@ -457,7 +457,7 @@ async def emitted_metrics(otel_metrics): plus the raw set of metric names - the metric-side counterpart of the `emitted` span fixture above. - Metrics use DELTA temporality (see `_otel_meter_provider`), and the + Metrics use DELTA temporality (see `otel_meter_provider` in datasette.telemetry_testing), and the function-scoped `otel_metrics` fixture drains any state left by an earlier test before yielding, so this collection is not polluted by other tests in the session - only by other *instances*, which is why the @@ -574,3 +574,38 @@ async def test_every_registered_metric_attribute_is_emitted(emitted_metrics): "these metric attributes are documented but never emitted by the " "test workload: " + ", ".join(sorted(missing)) ) + + +def test_prefix_span_lookup(): + """ + `prefix=True` matching, exercised directly. + + Core registers no prefix spans - the flag exists for plugin registries + (e.g. a `chat {model}` span family) - so without this the branch in + `span_for()` would be untested code the conformance tests never reach. + """ + hook = reg.SpanName("myplugin.hook.", "A hypothetical span family", prefix=True) + spans = reg.SPANS + (hook,) + assert reg.span_for("myplugin.hook.render_cell", spans=spans) is hook + assert reg.span_for("myplugin.hook.anything", spans=spans) is hook + assert reg.span_for("myplugin.hookish", spans=spans) is None + assert reg.span_for("db.query", spans=spans) is reg.DB_QUERY + + +def test_exact_match_wins_over_prefix(): + "A prefix family can never shadow a span with a registered exact name." + family = reg.SpanName("db.", "Greedy prefix", prefix=True) + spans = (family,) + reg.SPANS + assert reg.span_for("db.query", spans=spans) is reg.DB_QUERY + assert reg.span_for("db.anything-else", spans=spans) is family + + +def test_attribute_values_enum_enforced(): + outcome = reg.Attribute("myplugin.outcome", "Enum.", values={"ok", "error"}) + open_attr = reg.Attribute("myplugin.note", "Open value set.") + span = reg.SpanName("myplugin.job", "Test span", (outcome, open_attr)) + assert reg.attribute_value_allowed(span, "myplugin.outcome", "ok") + assert not reg.attribute_value_allowed(span, "myplugin.outcome", "surprise") + assert reg.attribute_value_allowed(span, "myplugin.note", "anything at all") + assert not reg.attribute_value_allowed(span, "not.registered", "x") + assert not reg.attribute_value_allowed(None, "myplugin.outcome", "ok") diff --git a/tests/test_telemetry_testing_kit.py b/tests/test_telemetry_testing_kit.py new file mode 100644 index 00000000..ba2bc435 --- /dev/null +++ b/tests/test_telemetry_testing_kit.py @@ -0,0 +1,138 @@ +""" +The plugin telemetry kit (`datasette.telemetry_testing` plus the public +registry classes), exercised the way a third-party plugin would use it: a +toy plugin registry, a toy tracer scope, and the kit's own fixtures and +conformance helpers. +""" + +import pytest + +pytest.importorskip("opentelemetry.sdk") + +from opentelemetry import trace as otel_trace + +from datasette import telemetry_registry as reg +from datasette.telemetry import linked_root_span_kwargs +from datasette.telemetry_testing import ( + assert_package_never_imports_sdk, + assert_registry_covered, + assert_spans_conform, +) + +SCOPE = "toyplugin" + +OUTCOME = reg.Attribute( + "toyplugin.outcome", "How the job ended.", values={"ok", "error"} +) +JOB_NAME = reg.Attribute("toyplugin.job", "The job's registered name.") +JOB = reg.SpanName("toyplugin.job.run", "One job execution.", (OUTCOME, JOB_NAME)) +CHAT = reg.SpanName( + "toyplugin.chat ", "One model call, named `toyplugin.chat {model}`.", prefix=True +) +TOY_SPANS = (JOB, CHAT) + +toy_tracer = otel_trace.get_tracer(SCOPE, "0.1") + + +def _toy_spans(otel_spans): + return [ + span + for span in otel_spans.get_finished_spans() + if span.instrumentation_scope and span.instrumentation_scope.name == SCOPE + ] + + +def _run_workload(): + with toy_tracer.start_as_current_span(JOB) as span: + span.set_attribute(OUTCOME, "ok") + span.set_attribute(JOB_NAME, "nightly") + with toy_tracer.start_as_current_span("toyplugin.chat gpt-5"): + pass + + +def test_conformance_passes_for_a_conforming_workload(otel_spans): + _run_workload() + finished = otel_spans.get_finished_spans() + assert_spans_conform(TOY_SPANS, finished, scope_name=SCOPE) + # Coverage direction needs prefix families seen too - the chat span + # resolves to the CHAT entry despite its variable suffix. + assert_registry_covered(TOY_SPANS, finished, scope_name=SCOPE) + + +def test_conformance_catches_an_unregistered_span(otel_spans): + with toy_tracer.start_as_current_span("toyplugin.surprise"): + pass + with pytest.raises(AssertionError, match="unregistered span"): + assert_spans_conform( + TOY_SPANS, otel_spans.get_finished_spans(), scope_name=SCOPE + ) + + +def test_conformance_catches_an_unregistered_attribute(otel_spans): + with toy_tracer.start_as_current_span(JOB) as span: + span.set_attribute("toyplugin.stealth", 1) + with pytest.raises(AssertionError, match="unregistered attribute"): + assert_spans_conform( + TOY_SPANS, otel_spans.get_finished_spans(), scope_name=SCOPE + ) + + +def test_conformance_enforces_declared_enums(otel_spans): + with toy_tracer.start_as_current_span(JOB) as span: + span.set_attribute(OUTCOME, "surprise") + with pytest.raises(AssertionError, match="not in the declared enum"): + assert_spans_conform( + TOY_SPANS, otel_spans.get_finished_spans(), scope_name=SCOPE + ) + + +def test_coverage_catches_a_never_emitted_span(otel_spans): + with toy_tracer.start_as_current_span(JOB) as span: + span.set_attribute(OUTCOME, "ok") + span.set_attribute(JOB_NAME, "nightly") + # CHAT never emitted + with pytest.raises(AssertionError, match="never emitted"): + assert_registry_covered( + TOY_SPANS, otel_spans.get_finished_spans(), scope_name=SCOPE + ) + + +def test_scope_filter_ignores_other_scopes(otel_spans): + # Core's own spans are in the exporter too; a plugin's conformance run + # must not fail because of them. + other = otel_trace.get_tracer("someone-else", "1.0") + with other.start_as_current_span("not.in.the.toy.registry"): + pass + _run_workload() + assert_spans_conform(TOY_SPANS, otel_spans.get_finished_spans(), scope_name=SCOPE) + + +def test_linked_root_span_kwargs_links_without_parenting(otel_spans): + with toy_tracer.start_as_current_span("toyplugin.cause") as cause: + cause_context = cause.get_span_context() + kwargs = linked_root_span_kwargs() + with toy_tracer.start_as_current_span("toyplugin.effect", **kwargs): + pass + effect = [ + span for span in _toy_spans(otel_spans) if span.name == "toyplugin.effect" + ][0] + assert effect.parent is None, "must be a root, not a child" + assert effect.context.trace_id != cause_context.trace_id + assert len(effect.links) == 1 + assert effect.links[0].context.span_id == cause_context.span_id + + +def test_linked_root_span_kwargs_with_no_current_span(otel_spans): + kwargs = linked_root_span_kwargs() + assert kwargs["links"] == [] + with toy_tracer.start_as_current_span("toyplugin.orphanless", **kwargs): + pass + span = _toy_spans(otel_spans)[0] + assert span.parent is None + assert span.links == () + + +def test_kit_module_itself_never_imports_the_sdk(): + # The kit imports the SDK lazily, so a plugin importing it at module + # level does not violate the api-only dependency rule. + assert_package_never_imports_sdk("datasette.telemetry_testing")