From 275b137ab08c94bb53383e4dbef70080184af9f6 Mon Sep 17 00:00:00 2001 From: Alex Garcia Date: Thu, 30 Jul 2026 19:33:04 -0700 Subject: [PATCH 1/2] Give every span a request to belong to Nothing in Datasette created a span for the HTTP request itself, so every span the database layer emits was a root span. Measured on this branch: one faceted table page produces 70 spans in 36 separate traces, none of which carries a URL. A trace UI shows that as dozens of unrelated single-span traces per page, interleaved across concurrent requests - worse than ?_trace=1 at the exact job people reach for tracing to do. With the request span it is 71 spans in 1 trace. `opentelemetry-instrument` does not fix this on its own: auto-instrumentation only picks up frameworks that ship an instrumentor entry point, and Datasette's raw ASGI app is not one. TelemetryMiddleware is mounted outermost in Datasette.app(), after the asgi_wrapper() plugin loop, so plugin middleware and the CSRF layer run *inside* the span. Putting it in DatasetteRouter instead would leave a span created by an instrumented plugin as an orphan root - reintroducing the problem for exactly the code most likely to be instrumented. It stays at ~90 lines, against roughly 700 for opentelemetry-instrumentation-asgi, because Datasette's app does not return before its body is sent: route_path awaits response.asgi_send(send), and a streaming CSV export runs its generator inline inside AsgiStream.asgi_send. So a plain `finally` covers the response body and no deferred-end machinery is needed. Two decisions worth flagging for review: - Inbound W3C traceparent and baggage are extracted, using the *global* propagator. That is the ecosystem norm (Flask, Django, FastAPI, the ASGI instrumentation), and going through the global propagator leaves the operator in control with no Datasette setting to invent: OTEL_PROPAGATORS=none disables it entirely. A public instance that does not want client-influenced traces should strip those headers at the proxy. - url.query is not recorded, anywhere. Datasette query strings carry user-supplied SQL in ?sql= and canned query parameters. client.address is not recorded either. The status code is sniffed from the ASGI http.response.start message rather than read off a Response, because asgi_static, the favicon route, AsgiStream and AsgiFileDownload all send that message themselves and never build one. Only a >= 500 sets an error status - per semantic conventions a 4xx is the client's mistake, and Datasette 404s are routine enough that treating them as errors would bury a real 500. The registry gains a `dynamic` flag, because this span's name is composed at runtime and so can never equal a fixed registry string. Dynamic entries resolve by span kind instead, and only after exact and prefix matching has failed, so they cannot shadow a span that does have a registered name. Co-Authored-By: Claude Opus 5 --- datasette/app.py | 23 ++- datasette/telemetry.py | 194 +++++++++++++++++ datasette/telemetry_registry.py | 110 +++++++++- docs/internals.rst | 21 +- tests/test_http_span.py | 344 +++++++++++++++++++++++++++++++ tests/test_telemetry_registry.py | 172 ++++++++++++---- 6 files changed, 813 insertions(+), 51 deletions(-) create mode 100644 tests/test_http_span.py diff --git a/datasette/app.py b/datasette/app.py index 68ef62391f..be864413bb 100644 --- a/datasette/app.py +++ b/datasette/app.py @@ -49,7 +49,7 @@ from .plugins import DEFAULT_PLUGINS, get_plugins, pm from .renderer import json_renderer from .resources import DatabaseResource, TableResource -from .telemetry import tracer +from .telemetry import TelemetryMiddleware, tracer from .telemetry_registry import STARTUP from .tokens import TokenInvalid from .tracer import AsgiTracer @@ -777,12 +777,16 @@ async def invoke_startup(self): # This must be called for Datasette to be in a usable state if self._startup_invoked: return - # invoke_startup() runs before any request exists, so every span its - # children create - the register_* hook dispatches, the internal - # catalog's db.query/db.write spans, and the prepare_connection - # warm-up of the read connections those touch - would otherwise be - # its own orphan root trace: around twenty of them on a fresh - # instance. Bracketing the whole thing gives them somewhere to belong. + # `datasette serve` calls invoke_startup() before uvicorn starts, so + # on the CLI path every span its children create - the register_* + # hook dispatches, the internal catalog's db.query/db.write spans, + # and the prepare_connection warm-up of the read connections those + # touch - would otherwise be its own orphan root trace: around twenty + # of them on a fresh instance. Bracketing the whole thing gives them + # somewhere to belong. An ASGI-hosted or programmatic deployment + # reaches here instead through AsgiRunOnFirstRequest, in which case + # this span nests under the first request's own span - honest enough, + # since it genuinely is that request's latency. # A connection warmed lazily later, by a request touching a new # database for the first time, nests under that request instead: # this span has already ended by then. @@ -2837,6 +2841,11 @@ async def _close_on_shutdown(): asgi = AsgiRunOnFirstRequest(asgi, on_startup=[setup_db, self.invoke_startup]) for wrapper in pm.hook.asgi_wrapper(datasette=self): asgi = wrapper(asgi) + # Outermost, deliberately: plugin asgi_wrapper() middleware and the + # CSRF layer run *inside* this span, so a span created by an + # instrumented plugin parents to the request instead of becoming its + # own orphan root trace. + asgi = TelemetryMiddleware(asgi) return asgi diff --git a/datasette/telemetry.py b/datasette/telemetry.py index 3a205cee1d..31541a476d 100644 --- a/datasette/telemetry.py +++ b/datasette/telemetry.py @@ -18,7 +18,19 @@ import re 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 .telemetry_registry import ( + ERROR_TYPE, + HTTP_REQUEST_METHOD, + HTTP_RESPONSE_STATUS_CODE, + SERVER_ADDRESS, + URL_PATH, + URL_SCHEME, + USER_AGENT_ORIGINAL, +) from .version import __version__ # The semantic-convention version whose spellings this instrumentation @@ -115,3 +127,185 @@ def sql_operation_name(sql: str) -> str | None: if keyword in DB_OPERATION_ALLOWLIST: return keyword return None + + +# --- The HTTP request span ------------------------------------------------ + + +class _ScopeHeadersGetter(Getter): + """ + Read W3C trace context out of an ASGI scope's headers. + + `scope["headers"]` is a list of `(bytes, bytes)` pairs, lowercased by the + server per the ASGI spec - but `.lower()` is applied again here because + that is a spec promise about servers, not something this process + controls. Header bytes are latin-1 by RFC 9110. + """ + + def get(self, carrier, key): + wanted = key.lower().encode("latin-1") + values = [v.decode("latin-1") for k, v in carrier if k.lower() == wanted] + return values or None + + def keys(self, carrier): + return [k.decode("latin-1") for k, _ in carrier] + + +_HEADERS_GETTER = _ScopeHeadersGetter() + + +# An unclamped method is an unbounded dimension a client controls: anyone can +# send `FOO / HTTP/1.1`. Semantic conventions say map anything unrecognised to +# `_OTHER`. These nine are the methods of RFC 9110 plus PATCH (RFC 5789). +_KNOWN_METHODS = frozenset( + {"GET", "HEAD", "POST", "PUT", "DELETE", "CONNECT", "OPTIONS", "TRACE", "PATCH"} +) + + +def clamp_http_method(method): + "The request method if it is one we recognise, else ``_OTHER``." + method = (method or "").upper() + return method if method in _KNOWN_METHODS else "_OTHER" + + +def _first_header(headers, name): + "The first value of a header, decoded, or None." + for key, value in headers: + if key.lower() == name: + return value.decode("latin-1") + return None + + +def _url_path(scope): + """ + The request path, with any query string removed. + + `raw_path` is preferred because it is the bytes the client sent, before + percent-decoding - Datasette routes on database and table names that can + contain encoded slashes, which `scope["path"]` has already collapsed. + + The split on "?" is not decoration. The ASGI spec's `raw_path` excludes + the query string, and uvicorn honours that, but the name is used the + other way round elsewhere in this same dependency tree: httpx's + `URL.raw_path` is documented as "raw bytes of both the path and query". + A server that followed that reading would hand us `?sql=...` here, and + Datasette's query strings carry user-supplied SQL, which core never + records. A literal "?" cannot appear unencoded in a path, so the split + costs nothing when the server is well behaved. + """ + raw_path = scope.get("raw_path") + if raw_path: + if isinstance(raw_path, bytes): + raw_path = raw_path.decode("latin-1") + return raw_path.split("?", 1)[0] + return scope.get("path", "") + + +class TelemetryMiddleware: + """ + One `SpanKind.SERVER` span per HTTP request. + + Mounted outermost in `Datasette.app()`, so every other span raised while + serving a request - database queries, plugin middleware, startup work on + a cold ASGI-hosted deployment - has somewhere to belong instead of + becoming its own root trace. + + Deliberately much smaller than `opentelemetry-instrumentation-asgi`, + which needs several hundred lines of deferred-end machinery for + applications that return before their body is sent. Datasette does not: + `DatasetteRouter.route_path` awaits `response.asgi_send(send)`, and for a + streaming CSV export `AsgiStream.asgi_send` runs the generator inline. + All of it happens inside the single `await self.app(...)` below, so + ending the span in a `finally` covers the response body too. + """ + + def __init__(self, app): + self.app = app + + async def __call__(self, scope, receive, send): + # First, before anything else: `AsgiLifespan` is *inside* this + # middleware, so lifespan startup and shutdown have to pass through + # untouched or the server never starts. Same for websockets. + if scope["type"] != "http": + await self.app(scope, receive, send) + return + headers = scope.get("headers") or [] + # The *global* propagator, deliberately: it leaves the operator in + # control with no Datasette-specific setting - OTEL_PROPAGATORS=none + # disables extraction entirely, OTEL_PROPAGATORS=tracecontext drops + # baggage - and core configuring propagation itself would be the same + # mistake as core configuring sampling. + context = extract(headers, getter=_HEADERS_GETTER) + method = clamp_http_method(scope.get("method", "")) + # The method, not the URL: a span name has to be low cardinality, and + # the method is what is known out here at the edge, before any routing + # has happened. + with tracer.start_as_current_span( + method, context=context, kind=SpanKind.SERVER + ) as span: + if not span.is_recording(): + # No provider installed, or a sampler dropped this trace. + # Everything below would be discarded, so skip building the + # `send` wrapper and let a default install pay almost + # nothing. Note this cannot be `get_span_context().is_valid`: + # with no provider but an inbound `traceparent`, the API's + # NoOpTracer returns a NonRecordingSpan carrying the *remote* + # context, which is perfectly valid and still records nothing. + await self.app(scope, receive, send) + return + span.set_attribute(HTTP_REQUEST_METHOD, method) + span.set_attribute(URL_PATH, _url_path(scope)) + scheme = scope.get("scheme") + if scheme: + span.set_attribute(URL_SCHEME, scheme) + host = _first_header(headers, b"host") + if host: + span.set_attribute(SERVER_ADDRESS, host) + user_agent = _first_header(headers, b"user-agent") + if user_agent: + span.set_attribute(USER_AGENT_ORIGINAL, user_agent) + + # The status cannot be read off a Response object: `asgi_static`, + # the favicon route, `AsgiStream` and `AsgiFileDownload` all call + # `send` directly and never build one. Wrapping `send` is the only + # thing that sees every response, including the 404 and 500 + # handlers. + status_holder = {} + + async def wrapped_send(message): + if ( + message["type"] == "http.response.start" + and "status" not in status_holder + ): + status_holder["status"] = message["status"] + await send(message) + + escaped = False + try: + # Positional (scope, receive, send) throughout this codebase - + # `wrapped_send` is the third argument. `receive` is passed + # through unwrapped. + await self.app(scope, receive, wrapped_send) + except BaseException as exception: + # BaseException, not Exception: `route_path` turns almost + # everything into a 500 itself, but `asyncio.CancelledError` + # on client disconnect is a BaseException its `except + # Exception` deliberately does not catch. + escaped = True + span.set_attribute(ERROR_TYPE, type(exception).__name__) + span.set_status(Status(StatusCode.ERROR, str(exception))) + raise + finally: + status = status_holder.get("status") + if status is not None: + span.set_attribute(HTTP_RESPONSE_STATUS_CODE, status) + # 4xx is NOT an error for a SERVER span per semantic + # conventions - the client made the mistake, not us. + # + # `not escaped` because this block still runs when an + # exception is on its way out, and a response can have + # started before it: the exception's class name is more + # use than the string "500", so it wins. + if status >= 500 and not escaped: + span.set_status(Status(StatusCode.ERROR)) + span.set_attribute(ERROR_TYPE, str(status)) diff --git a/datasette/telemetry_registry.py b/datasette/telemetry_registry.py index 2d0692a817..ddecbc5bb4 100644 --- a/datasette/telemetry_registry.py +++ b/datasette/telemetry_registry.py @@ -47,10 +47,16 @@ def __repr__(self): class SpanName(str): "A span name, carrying its documentation and the attributes it may set." - __slots__ = ("attributes", "description", "kind", "prefix") + __slots__ = ("attributes", "description", "dynamic", "kind", "prefix") def __new__( - cls, name, description, attributes=(), prefix=False, kind=SpanKind.INTERNAL + cls, + name, + description, + attributes=(), + prefix=False, + dynamic=False, + kind=SpanKind.INTERNAL, ): self = super().__new__(cls, name) self.description = description @@ -59,6 +65,13 @@ def __new__( # so the conformance test matches by prefix rather than equality. # Nothing sets it yet. 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. There is no substring of the entry that + # could be matched against the wire, so `span_for()` resolves these by + # span kind instead, and the entry's own string is a template written + # for a human reading the generated reference. + self.dynamic = dynamic # SpanKind.INTERNAL by default - every span Datasette emits describes # its own internal work. db.query is the one exception: it is a real # database call, so semantic conventions (and trace UIs, which key @@ -75,6 +88,53 @@ def __repr__(self): # Shared attributes are defined once and referenced by every span that sets # them, so "which spans carry db.namespace?" is answerable by grep. +HTTP_REQUEST_METHOD = Attribute( + "http.request.method", + "The HTTP method, clamped to the nine methods RFC 9110 and RFC 5789 " + "define. Anything else is reported as ``_OTHER``: the method is a " + "client-controlled string, so echoing it back unbounded would be a " + "cardinality hazard.", +) +HTTP_RESPONSE_STATUS_CODE = Attribute( + "http.response.status_code", + "The status of the response, read from the ASGI ``http.response.start`` " + "message rather than from a :ref:`internals_response` object - several " + "views, including static files, file downloads and streaming CSV, send " + "that message themselves and never build one. Omitted if the connection " + "closed before anything was sent.", + optional=True, +) +URL_PATH = Attribute( + "url.path", + "The path portion of the URL. The query string is deliberately **not** " + "recorded, on this or any other span: Datasette puts user-supplied SQL in " + "``?sql=`` and canned query parameters in the query string, so exporting " + "it by default would export exactly the data the rest of this " + "instrumentation is careful with.", +) +URL_SCHEME = Attribute("url.scheme", "``http`` or ``https``.") +SERVER_ADDRESS = Attribute( + "server.address", + "The ``Host`` header. Client-controlled, so treat it as untrusted input " + "rather than as the identity of the server.", + optional=True, +) +USER_AGENT_ORIGINAL = Attribute( + "user_agent.original", + "The ``User-Agent`` header, verbatim. Omitted if the client sent none. " + "The client's IP address is deliberately not recorded: core records no " + "identifier that would tie a span to a person.", + optional=True, +) +ERROR_TYPE = Attribute( + "error.type", + "Set when the request failed: the exception class name if one escaped the " + "application, otherwise the status code as a string for a 5xx response. " + "A 4xx does **not** set this and does not set an error status - per " + "semantic conventions a client error is not a server span's failure.", + optional=True, +) + DB_SYSTEM = Attribute("db.system", "Always ``sqlite``.") DB_NAMESPACE = Attribute("db.namespace", "Name of the database being queried.") DB_QUERY_TEXT = Attribute( @@ -175,6 +235,30 @@ def __repr__(self): # --- Spans ---------------------------------------------------------------- +HTTP_REQUEST = SpanName( + "{http.request.method}", + "One span per HTTP request, created by the outermost layer of the ASGI " + "stack - so plugin ``asgi_wrapper()`` middleware, CSRF protection and " + "every database span raised while serving the request all nest inside " + "it. Without it each of those would be its own root trace. The span name " + "is not a fixed string: it is the value of ``http.request.method``. " + "W3C ``traceparent`` and ``baggage`` headers are extracted using the " + "global propagator, so a request arriving from an already-traced caller " + "continues that trace; set ``OTEL_PROPAGATORS=none`` to turn that off, " + "and strip those headers at your proxy if your instance is public.", + ( + HTTP_REQUEST_METHOD, + URL_PATH, + URL_SCHEME, + SERVER_ADDRESS, + USER_AGENT_ORIGINAL, + HTTP_RESPONSE_STATUS_CODE, + ERROR_TYPE, + ), + dynamic=True, + kind=SpanKind.SERVER, +) + DB_QUERY = SpanName( "db.query", "A SQL operation issued by Datasette, covering the full round trip " @@ -240,6 +324,7 @@ def __repr__(self): ) SPANS = ( + HTTP_REQUEST, DB_QUERY, DB_QUERY_EXECUTE, DB_WRITE_QUEUE_WAIT, @@ -248,21 +333,32 @@ def __repr__(self): ) -def span_for(emitted_name): +def span_for(emitted_name, kind=None): """ Resolve an emitted span name to its registry entry, or None. - Handles span families whose emitted names carry a suffix that is not - knowable in advance - `prefix=True` entries. Phase 1 has none, but the - lookup is what the conformance test calls, so it lives here rather than - in the test. + Handles the two entry kinds whose emitted names are not knowable in + advance: + + - `prefix=True` - the name carries a variable suffix, matched by prefix. + Phase 1 registers none. + - `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 and prefix + entries are tried first, so a dynamic entry can never shadow a span + that does have a registered name. """ for span in SPANS: + if span.dynamic: + continue if span.prefix: if emitted_name.startswith(span): return span elif emitted_name == span: return span + if kind is not None: + for span in SPANS: + if span.dynamic and span.kind == kind: + return span return None diff --git a/docs/internals.rst b/docs/internals.rst index 31666e0e6c..ec50716f8f 100644 --- a/docs/internals.rst +++ b/docs/internals.rst @@ -2361,17 +2361,34 @@ Setting ``OTEL_METRICS_EXPORTER=none`` and ``OTEL_LOGS_EXPORTER=none`` is worth Span reference -------------- -Datasette emits five spans. Four of them describe the database layer - one per query, one for the work that query does inside a SQL worker thread, and two more for the write queue - and the fifth covers startup. Attribute names use the ``datasette.*`` prefix for Datasette-specific data, alongside standard OpenTelemetry attributes such as ``db.system``. +Datasette emits six spans. One covers the HTTP request, and is the root everything else raised while serving that request hangs from. Four describe the database layer - one per query, one for the work that query does inside a SQL worker thread, and two more for the write queue. The sixth covers startup. Attribute names use the ``datasette.*`` prefix for Datasette-specific data, alongside standard OpenTelemetry attributes such as ``db.system``. This reference is generated from ``datasette/telemetry_registry.py``, the single source of truth for every span and attribute Datasette emits. A conformance test makes real requests and compares what is actually emitted against that registry in both directions, so nothing here is hand-maintained and nothing can silently drift out of date. -Spans are ``SpanKind.INTERNAL`` unless a kind is listed below. Only ``db.query`` is ``CLIENT``: it is the one span that represents a call to a database rather than Datasette's own work, and trace UIs use the kind to decide whether to render a span as a database call. Its children stay ``INTERNAL`` because they are Datasette's decomposition of that one query - marking them ``CLIENT`` too would make a single query look like several database calls to anything counting by kind. +Spans are ``SpanKind.INTERNAL`` unless a kind is listed below. Two are not: the request span is ``SERVER``, and ``db.query`` is ``CLIENT`` because it is the one span that represents a call to a database rather than Datasette's own work. Trace UIs use the kind to decide whether to render a span as an inbound request or as a database call. ``db.query``'s children stay ``INTERNAL`` because they are Datasette's decomposition of that one query - marking them ``CLIENT`` too would make a single query look like several database calls to anything counting by kind. + +The request span's name is the only one that is not a fixed string - it is composed from the request, so the heading below shows the template rather than a literal you will see in a trace. .. [[[cog from telemetry_doc import spans spans(cog) .. ]]] +``{http.request.method}`` + One span per HTTP request, created by the outermost layer of the ASGI stack - so plugin ``asgi_wrapper()`` middleware, CSRF protection and every database span raised while serving the request all nest inside it. Without it each of those would be its own root trace. The span name is not a fixed string: it is the value of ``http.request.method``. W3C ``traceparent`` and ``baggage`` headers are extracted using the global propagator, so a request arriving from an already-traced caller continues that trace; set ``OTEL_PROPAGATORS=none`` to turn that off, and strip those headers at your proxy if your instance is public. + + Kind: ``SERVER``. + + Attributes: + + - ``http.request.method`` - The HTTP method, clamped to the nine methods RFC 9110 and RFC 5789 define. Anything else is reported as ``_OTHER``: the method is a client-controlled string, so echoing it back unbounded would be a cardinality hazard. + - ``url.path`` - The path portion of the URL. The query string is deliberately **not** recorded, on this or any other span: Datasette puts user-supplied SQL in ``?sql=`` and canned query parameters in the query string, so exporting it by default would export exactly the data the rest of this instrumentation is careful with. + - ``url.scheme`` - ``http`` or ``https``. + - ``server.address`` *(optional)* - The ``Host`` header. Client-controlled, so treat it as untrusted input rather than as the identity of the server. + - ``user_agent.original`` *(optional)* - The ``User-Agent`` header, verbatim. Omitted if the client sent none. The client's IP address is deliberately not recorded: core records no identifier that would tie a span to a person. + - ``http.response.status_code`` *(optional)* - The status of the response, read from the ASGI ``http.response.start`` message rather than from a :ref:`internals_response` object - several views, including static files, file downloads and streaming CSV, send that message themselves and never build one. Omitted if the connection closed before anything was sent. + - ``error.type`` *(optional)* - Set when the request failed: the exception class name if one escaped the application, otherwise the status code as a string for a 5xx response. A 4xx does **not** set this and does not set an error status - per semantic conventions a client error is not a server span's failure. + ``db.query`` A SQL operation issued by Datasette, covering the full round trip including any time spent queued for a thread. diff --git a/tests/test_http_span.py b/tests/test_http_span.py new file mode 100644 index 0000000000..740d437df8 --- /dev/null +++ b/tests/test_http_span.py @@ -0,0 +1,344 @@ +""" +The HTTP request span. + +`tests/test_telemetry_registry.py` already pins the span's name shape, kind +and attribute keys against literals, so this file deliberately does not +repeat that. What it covers is the three properties of the middleware that +the registry conformance test structurally cannot see: + +- **where the middleware sits.** Outermost is the entire point - moving it + inside the plugin `asgi_wrapper()` loop leaves plugin middleware creating + orphan root traces, which is the problem this span exists to fix, and every + attribute assertion still passes. +- **method clamping**, which a workload of ordinary GETs can never exercise. +- **the query string never being recorded**, which only fails if a request + actually carries one. +""" + +import asyncio +import itertools + +import pytest +import pytest_asyncio + +pytest.importorskip("opentelemetry.sdk") + +from opentelemetry.trace import SpanKind, StatusCode + +from datasette import hookimpl +from datasette.app import Datasette +from datasette.telemetry import TelemetryMiddleware, tracer + +# Named in-memory databases are shared-cache: two Datasette instances given +# the same name share one SQLite database and the second `create table` +# fails. +_names = itertools.count() + + +PLUGIN_MIDDLEWARE_SPAN = "test.plugin.middleware" + + +class _MiddlewarePlugin: + "A plugin asgi_wrapper() that creates a span, standing in for a real one." + + __name__ = "HttpSpanMiddlewarePlugin" + + @hookimpl + def asgi_wrapper(self, datasette): + def wrap(app): + async def wrapped(scope, receive, send): + with tracer.start_as_current_span(PLUGIN_MIDDLEWARE_SPAN): + await app(scope, receive, send) + + return wrapped + + return wrap + + +class _RaisingMiddlewarePlugin: + """ + A plugin asgi_wrapper() that raises. + + `route_path` converts almost every exception into a 500 itself, so an + exception escaping into the request span is only reachable from *outside* + the router - a plugin wrapper, or a failure inside the 500 handler. + """ + + __name__ = "HttpSpanRaisingMiddlewarePlugin" + + def __init__(self, call_app_first): + self.call_app_first = call_app_first + + @hookimpl + def asgi_wrapper(self, datasette): + call_app_first = self.call_app_first + + def wrap(app): + async def wrapped(scope, receive, send): + if call_app_first: + await app(scope, receive, send) + raise RuntimeError("wrapper exploded") + + return wrapped + + return wrap + + +class _BoomPlugin: + "A route that raises, which route_path turns into a 500." + + __name__ = "HttpSpanBoomPlugin" + + @hookimpl + def register_routes(self): + return [(r"^/-/http-span-boom$", lambda: 1 / 0)] + + +@pytest_asyncio.fixture +async def ds(): + name = f"httpspan{next(_names)}" + instance = Datasette(memory=True) + instance.add_memory_database(name) + await instance.invoke_startup() + await instance.get_database(name).execute_write( + "create table t (id integer primary key, v text)" + ) + instance.db_name = name + try: + yield instance + finally: + instance.close() + + +def _server_spans(otel_spans): + return [ + span for span in otel_spans.get_finished_spans() if span.kind is SpanKind.SERVER + ] + + +@pytest.mark.asyncio +async def test_plugin_asgi_wrapper_middleware_runs_inside_the_request_span( + ds, otel_spans +): + """ + The placement check. + + A span created by a plugin `asgi_wrapper()` must be a *child* of the + request span. If the middleware is mounted anywhere inside the plugin + loop the two swap places - the plugin's span becomes the root and the + request span its child - which is exactly the orphaning this is meant to + prevent, and which no attribute assertion notices. + """ + ds.pm.register(_MiddlewarePlugin(), name="httpspan-middleware") + try: + otel_spans.clear() + response = await ds.client.get(f"/{ds.db_name}/t") + assert response.status_code == 200 + finally: + ds.pm.unregister(name="httpspan-middleware") + + spans = otel_spans.get_finished_spans() + server = [span for span in spans if span.kind is SpanKind.SERVER] + assert len(server) == 1, "expected exactly one SERVER span per request" + request_span = server[0] + assert request_span.parent is None, "the request span should be the trace root" + + plugin_spans = [span for span in spans if span.name == PLUGIN_MIDDLEWARE_SPAN] + assert len(plugin_spans) == 1 + assert plugin_spans[0].parent is not None + assert plugin_spans[0].parent.span_id == request_span.context.span_id + assert plugin_spans[0].context.trace_id == request_span.context.trace_id + + # And the database work is in the same trace, not off on its own. + queries = [span for span in spans if span.name == "db.query"] + assert queries, "a table page should have issued at least one query" + for query in queries: + assert query.context.trace_id == request_span.context.trace_id + + +@pytest.mark.asyncio +async def test_unrecognised_method_is_clamped(ds, otel_spans): + """ + Anyone can send `FROB / HTTP/1.1`. An unclamped method is an unbounded + dimension a client controls, so semantic conventions map anything off the + known list to `_OTHER` - and the span name is the method, so an unclamped + one would put attacker-supplied text in the span name too. + """ + otel_spans.clear() + await ds.client.request("FROB", f"/{ds.db_name}/t") + server = _server_spans(otel_spans) + assert len(server) == 1 + assert server[0].name == "_OTHER" + assert server[0].attributes["http.request.method"] == "_OTHER" + + +@pytest.mark.asyncio +async def test_known_method_is_not_clamped(ds, otel_spans): + "The other half of clamping: a real method must survive it verbatim." + otel_spans.clear() + await ds.client.get(f"/{ds.db_name}/t") + server = _server_spans(otel_spans) + assert len(server) == 1 + assert server[0].name == "GET" + assert server[0].attributes["http.request.method"] == "GET" + + +@pytest.mark.asyncio +async def test_the_query_string_is_never_recorded(ds, otel_spans): + """ + Datasette puts user-supplied SQL in `?sql=` and canned query parameters in + the query string, so no span may carry it. Asserting on the absence of a + `url.query` key alone would not catch it arriving under some other name, + so this searches every attribute value of every span for the marker. + """ + marker = "canary-9f2b1c" + otel_spans.clear() + await ds.client.get(f"/{ds.db_name}/t?_facet=v&_nosuch={marker}") + spans = otel_spans.get_finished_spans() + assert _server_spans(otel_spans), "no request span was emitted" + leaked = [ + f"{span.name} -> {key}={value!r}" + for span in spans + for key, value in (span.attributes or {}).items() + if marker in str(value) or key == "url.query" + ] + assert not leaked, "the query string reached a span attribute: " + ", ".join(leaked) + + +@pytest.mark.asyncio +async def test_url_path_is_recorded_without_the_query_string(ds, otel_spans): + otel_spans.clear() + await ds.client.get(f"/{ds.db_name}/t?_facet=v") + server = _server_spans(otel_spans) + assert len(server) == 1 + assert server[0].attributes["url.path"] == f"/{ds.db_name}/t" + + +@pytest.mark.asyncio +async def test_escaping_exception_sets_error_type_and_reraises(ds, otel_spans): + """ + An exception that gets past `route_path` must be recorded, not swallowed. + + No response ever started, so there is no status code to record either. + """ + ds.pm.register( + _RaisingMiddlewarePlugin(call_app_first=False), name="httpspan-raiser" + ) + try: + otel_spans.clear() + with pytest.raises(RuntimeError): + await ds.client.get(f"/{ds.db_name}/t") + finally: + ds.pm.unregister(name="httpspan-raiser") + server = _server_spans(otel_spans) + assert len(server) == 1 + assert server[0].attributes["error.type"] == "RuntimeError" + assert "http.response.status_code" not in server[0].attributes + assert server[0].status.status_code is StatusCode.ERROR + + +@pytest.mark.asyncio +async def test_an_escaping_exception_beats_the_status_code_for_error_type( + ds, otel_spans +): + """ + Both paths can fire on one request: a 500 response is sent and *then* + something raises on the way out. The `finally` block runs while the + exception is propagating, so without the guard it would overwrite the + exception's class name with the string "500" - strictly less information + about what actually went wrong. + """ + ds.pm.register(_BoomPlugin(), name="httpspan-boom") + ds.pm.register( + _RaisingMiddlewarePlugin(call_app_first=True), name="httpspan-raiser" + ) + try: + otel_spans.clear() + with pytest.raises(RuntimeError): + await ds.client.get("/-/http-span-boom") + finally: + ds.pm.unregister(name="httpspan-raiser") + ds.pm.unregister(name="httpspan-boom") + server = _server_spans(otel_spans) + assert len(server) == 1 + # The 500 really was sent, so the status is still recorded ... + assert server[0].attributes["http.response.status_code"] == 500 + # ... but error.type names the exception, not the status. + assert server[0].attributes["error.type"] == "RuntimeError" + + +@pytest.mark.asyncio +async def test_a_404_is_not_an_error(ds, otel_spans): + """ + Per semantic conventions a 4xx is the client's mistake, not the server's, + so a SERVER span must record the status and leave both its own status and + `error.type` alone. Datasette 404s are routine - every missing table, and + every bot probing for /wp-login.php - so treating them as errors would + drown a real 500 in noise. + """ + otel_spans.clear() + response = await ds.client.get("/no-such-database-at-all") + assert response.status_code == 404 + server = _server_spans(otel_spans) + assert len(server) == 1 + assert server[0].attributes["http.response.status_code"] == 404 + assert "error.type" not in server[0].attributes + assert server[0].status.status_code is StatusCode.UNSET + + +@pytest.mark.asyncio +async def test_only_the_first_http_response_start_is_recorded(otel_spans): + """ + The `send` wrapper keeps the first status it sees. + + Nothing in Datasette sends two `http.response.start` messages, so this + drives the middleware directly rather than pretending a request could + reach it. Without the guard a misbehaving plugin's second start message + would silently replace the status the client actually received. + """ + + async def two_starts(scope, receive, send): + await send({"type": "http.response.start", "status": 200, "headers": []}) + await send({"type": "http.response.start", "status": 503, "headers": []}) + await send({"type": "http.response.body", "body": b""}) + + middleware = TelemetryMiddleware(two_starts) + scope = { + "type": "http", + "method": "GET", + "path": "/twice", + "raw_path": b"/twice", + "scheme": "http", + "headers": [], + } + otel_spans.clear() + await middleware(scope, None, lambda message: asyncio.sleep(0)) + server = _server_spans(otel_spans) + assert len(server) == 1 + assert server[0].attributes["http.response.status_code"] == 200 + assert "error.type" not in server[0].attributes + + +@pytest.mark.asyncio +async def test_lifespan_scope_passes_through_unspanned(otel_spans): + """ + `AsgiLifespan` sits *inside* this middleware, so the scope-type check has + to come first or startup and shutdown events never reach it. A SERVER + span for a lifespan scope is the symptom of that check being missing or + late. + """ + instance = Datasette(memory=True) + app = instance.app() + events = iter([{"type": "lifespan.startup"}, {"type": "lifespan.shutdown"}]) + sent = [] + + async def receive(): + return next(events) + + async def send(message): + sent.append(message["type"]) + + otel_spans.clear() + await app({"type": "lifespan"}, receive, send) + assert sent == ["lifespan.startup.complete", "lifespan.shutdown.complete"] + assert not _server_spans(otel_spans) diff --git a/tests/test_telemetry_registry.py b/tests/test_telemetry_registry.py index 335eb94628..96b2a7c555 100644 --- a/tests/test_telemetry_registry.py +++ b/tests/test_telemetry_registry.py @@ -30,6 +30,9 @@ pytest.importorskip("opentelemetry.sdk") +from opentelemetry.trace import SpanKind + +from datasette import hookimpl from datasette import telemetry_registry as reg from datasette.app import Datasette from datasette.database import QueryInterrupted @@ -66,6 +69,31 @@ } EXPECTED_SPANS = set(EXPECTED_ATTRIBUTES) +# The HTTP request span is handled separately because its name is composed at +# runtime - it is the request method - so there is no fixed string to pin it +# to. What can still be pinned, and is what a dashboard depends on, is the +# shape of the name and the attribute keys. The workload below only issues +# GETs, so a change that stopped clamping the method, or that started naming +# the span after the path, fails here. +EXPECTED_HTTP_SPAN_NAME = "{http.request.method}" +EXPECTED_HTTP_SPAN_NAMES = {"GET"} +EXPECTED_HTTP_ATTRIBUTES = { + "http.request.method", + "url.path", + "url.scheme", + "server.address", + "user_agent.original", + "http.response.status_code", + "error.type", +} + +# The registry's own name for the request span is that template, not anything +# that appears on the wire. +EXPECTED_REGISTRY_ATTRIBUTES = dict( + EXPECTED_ATTRIBUTES, **{EXPECTED_HTTP_SPAN_NAME: EXPECTED_HTTP_ATTRIBUTES} +) +EXPECTED_REGISTRY_NAMES = set(EXPECTED_REGISTRY_ATTRIBUTES) + # Named in-memory databases are shared-cache, so two Datasette instances using # the same name share one SQLite database - and the second `create table` # fails. Every workload below therefore gets its own name. @@ -76,6 +104,23 @@ def _unique(prefix): return f"{prefix}{next(_names)}" +class _BoomPlugin: + """ + A route that raises. + + `error.type` on the request span is only ever set by a 5xx, and nothing + in Datasette returns one on a healthy instance - `route_path` converts + exceptions into a 500 itself, so the workload has to supply the + exception. + """ + + __name__ = "TelemetryRegistryBoomPlugin" + + @hookimpl + def register_routes(self): + return [(r"^/-/telemetry-registry-boom$", lambda: 1 / 0)] + + async def exercise(): """ Drive enough of Datasette to emit every span and attribute the registry @@ -128,37 +173,62 @@ async def exercise(): custom_time_limit=1, ) - # db.collection.name - set only by views that already know their table + # db.collection.name - set only by views that already know their table. + # These requests are also what produces the HTTP request span and its + # http.request.method / url.path / url.scheme / server.address / + # user_agent.original / http.response.status_code attributes. assert (await ds.client.get(f"/{name}/t?_facet=v")).status_code == 200 assert (await ds.client.get(f"/{name}/t/1.json")).status_code == 200 + + # error.type on the request span, which only a 5xx sets + ds.pm.register(_BoomPlugin(), name="telemetry-registry-boom") + try: + response = await ds.client.get("/-/telemetry-registry-boom") + assert response.status_code == 500 + finally: + ds.pm.unregister(name="telemetry-registry-boom") return ds @pytest_asyncio.fixture async def emitted(otel_spans): - "Every span name and (span name, attribute key) pair a broad workload emits." + """ + Every (span name, span kind, attribute keys) triple a broad workload emits. + + The kind is carried because the request span's name is composed at + runtime, so `span_for()` resolves it by kind instead. + """ # otel_spans has already cleared the exporter, and nothing is cleared # after this point: the workload's own startup emits datasette.startup. ds = await exercise() spans = otel_spans.get_finished_spans() assert spans, "no spans captured - the fixture is not exercising anything" - names = set() - pairs = set() - for span in spans: - # str() because span.name is the registry's SpanName instance, and a - # set of those would compare equal to literals but read confusingly - # in a failure message. - names.add(str(span.name)) - for key in span.attributes or {}: - pairs.add((str(span.name), str(key))) + # str() because span.name is the registry's SpanName instance, and a set + # of those would compare equal to literals but read confusingly in a + # failure message. + collected = tuple( + ( + str(span.name), + span.kind, + frozenset(str(key) for key in span.attributes or {}), + ) + for span in spans + ) ds.close() - return {"names": names, "pairs": pairs} + return collected -def _keys_by_span(pairs): +def _partition(emitted): + "The statically named spans, and the dynamically named request spans." + static = [record for record in emitted if record[1] is not SpanKind.SERVER] + server = [record for record in emitted if record[1] is SpanKind.SERVER] + return static, server + + +def _keys_by_span(records): by_span = {} - for span_name, key in pairs: - by_span.setdefault(span_name, set()).add(key) + for name, _kind, keys in records: + by_span.setdefault(name, set()).update(keys) return by_span @@ -170,27 +240,34 @@ async def test_workload_emits_exactly_the_expected_names(emitted): Not derived from the registry, so this is what catches a rename that the registry and the call sites make together. """ - assert emitted["names"] == EXPECTED_SPANS - by_span = _keys_by_span(emitted["pairs"]) - assert {name: by_span.get(name, set()) for name in emitted["names"]} == ( - EXPECTED_ATTRIBUTES - ) + static, server = _partition(emitted) + by_span = _keys_by_span(static) + assert set(by_span) == EXPECTED_SPANS + assert by_span == EXPECTED_ATTRIBUTES + + assert server, "the workload made HTTP requests but no SERVER span was emitted" + server_keys = _keys_by_span(server) + assert set(server_keys) == EXPECTED_HTTP_SPAN_NAMES + union = set() + for keys in server_keys.values(): + union |= keys + assert union == EXPECTED_HTTP_ATTRIBUTES def test_registry_matches_the_expected_names(): "The other half of the rename check: the registry against the same literals." - assert {str(span) for span in reg.SPANS} == EXPECTED_SPANS + assert {str(span) for span in reg.SPANS} == EXPECTED_REGISTRY_NAMES for span in reg.SPANS: - assert {str(attribute) for attribute in span.attributes} == EXPECTED_ATTRIBUTES[ - str(span) - ], f"{span} attributes have drifted" + assert { + str(attribute) for attribute in span.attributes + } == EXPECTED_REGISTRY_ATTRIBUTES[str(span)], f"{span} attributes have drifted" @pytest.mark.asyncio async def test_every_emitted_span_is_registered(emitted): "A span added without a registry entry would be missing from the docs." unregistered = sorted( - name for name in emitted["names"] if reg.span_for(name) is None + {name for name, kind, _ in emitted if reg.span_for(name, kind) is None} ) assert ( not unregistered @@ -201,9 +278,12 @@ async def test_every_emitted_span_is_registered(emitted): async def test_every_emitted_attribute_is_registered(emitted): "An attribute added without a registry entry would be missing from the docs." unregistered = sorted( - f"{span_name} -> {key}" - for span_name, key in emitted["pairs"] - if not reg.attribute_allowed(reg.span_for(span_name), key) + { + f"{name} -> {key}" + for name, kind, keys in emitted + for key in keys + if not reg.attribute_allowed(reg.span_for(name, kind), key) + } ) assert ( not unregistered @@ -218,11 +298,10 @@ async def test_every_registered_span_is_emitted(emitted): The direction nothing else catches: the docs must not describe a span that no longer exists. """ - missing = sorted( - str(span) - for span in reg.SPANS - if not any(reg.span_for(name) is span for name in emitted["names"]) - ) + # By identity, not by name: a dynamic entry's own string never appears on + # the wire, so comparing strings would be comparing the wrong things. + resolved = {id(reg.span_for(name, kind)) for name, kind, _ in emitted} + missing = sorted(str(span) for span in reg.SPANS if id(span) not in resolved) assert not missing, ( f"these spans are documented but never emitted by the workload: {missing}. " "Either the instrumentation was removed, or exercise() no longer reaches it." @@ -241,10 +320,14 @@ async def test_every_registered_attribute_is_emitted(emitted): new attribute only appears in some rare case, extend exercise() to reach that case. """ - by_span = _keys_by_span(emitted["pairs"]) + by_entry = {} + for name, kind, keys in emitted: + entry = reg.span_for(name, kind) + if entry is not None: + by_entry.setdefault(id(entry), set()).update(keys) missing = [] for span in reg.SPANS: - emitted_keys = by_span.get(str(span), set()) + emitted_keys = by_entry.get(id(span), set()) for attribute in span.attributes: if attribute not in emitted_keys: missing.append(f"{span} -> {attribute}") @@ -279,6 +362,25 @@ def test_registry_entries_are_usable_as_plain_strings(): assert f"{reg.DB_QUERY}.execute" == "db.query.execute" +def test_dynamic_span_lookup(): + """ + `dynamic=True` matching, which is how the request span resolves. + + The last two assertions are the ones worth having: a dynamic entry must + not swallow a span that does have a registered name, and must not match at + all when the caller supplies no kind - otherwise every unregistered span + in the suite would silently resolve to the request span and the + emitted-but-not-registered direction would stop catching anything. + """ + assert reg.span_for("GET", SpanKind.SERVER) is reg.HTTP_REQUEST + assert reg.span_for("POST /^/(?P[^/]+)$", SpanKind.SERVER) is ( + reg.HTTP_REQUEST + ) + assert reg.span_for("GET") is None + assert reg.span_for("anything at all", SpanKind.INTERNAL) is None + assert reg.span_for("db.query", SpanKind.SERVER) is reg.DB_QUERY + + def test_span_and_attribute_lookup(): assert reg.span_for("db.query") is reg.DB_QUERY assert reg.span_for("datasette.startup") is reg.STARTUP From fec260e1a585aca378651b6788a03b7d61c72439 Mon Sep 17 00:00:00 2001 From: Alex Garcia Date: Thu, 30 Jul 2026 19:52:12 -0700 Subject: [PATCH 2/2] Name the request span after the route it matched The request span was created at the ASGI edge, before anything knew which route would match, so it carried nothing but the method: every request in a trace UI showed up as "GET", and the only URL on it was url.path, which is unbounded on a public instance and useless as a grouping key. Routing resolves in DatasetteRouter, so that is where the span gets http.route and its semconv `{method} {route}` name. http.route is the compiled route pattern, not a prettified /{database}/{table} template. Datasette routes with compiled regexes and the route table is fixed when the app is built, so the pattern is exact, bounded and needs no parsing; the transform into something prettier accretes edge cases, and Django's instrumentation ships regex-flavoured routes for the same reason. A request that matches no route gets no http.route and keeps its bare method name, which is what semantic conventions ask for. Two things the obvious implementation gets wrong, both found by testing it: - The router must not read `get_current_span()`. A plugin asgi_wrapper() runs *inside* the request middleware, so an instrumented plugin makes its own span current for the whole request - and the route then lands on that plugin's INTERNAL span, renaming it, while the actual request span never gets the one attribute a trace UI groups by. It reproduces with a five-line plugin. The span is passed through the ASGI scope instead, falling back to the current span so an externally-created SERVER span is still enriched. - The method has to be clamped again here. The middleware clamps it for the attribute, but the name is rebuilt from request.method, which is the raw client string - so an unclamped rename put `FROB /(?P...` back into the span name that the middleware had just kept it out of. Both guards are `is_recording()`, not `get_span_context().is_valid`: with no provider but an inbound traceparent the API returns a NonRecordingSpan carrying the remote context, which is valid and records nothing, so an is_valid guard would do the work on every request from a traced caller. Tests cover the route and name, the unrouted 404 fallback, the full attribute set, db.query spans reaching the request span by parent walk, a 500, an inbound traceparent becoming a remote parent, ?sql= never reaching a span attribute, and - in a subprocess, because the suite's provider fixture is session-scoped and unavoidable - the no-provider fast path handing the app the original `send`. The streaming test uses a table larger than one page so the export genuinely issues queries during the body send; without that it passes however early the span ends. Measured on this branch against fixtures.db: a faceted table page went from 112 spans in 56 traces to 113 spans in 1. Co-Authored-By: Claude Opus 5 --- datasette/app.py | 27 +- datasette/telemetry.py | 36 +++ datasette/telemetry_registry.py | 31 +- docs/internals.rst | 38 ++- tests/conftest.py | 1 + tests/test_http_span.py | 537 ++++++++++++++++++++++++++++++- tests/test_telemetry_registry.py | 52 ++- 7 files changed, 681 insertions(+), 41 deletions(-) diff --git a/datasette/app.py b/datasette/app.py index be864413bb..9fafd9402b 100644 --- a/datasette/app.py +++ b/datasette/app.py @@ -49,8 +49,13 @@ from .plugins import DEFAULT_PLUGINS, get_plugins, pm from .renderer import json_renderer from .resources import DatabaseResource, TableResource -from .telemetry import TelemetryMiddleware, tracer -from .telemetry_registry import STARTUP +from .telemetry import ( + TelemetryMiddleware, + clamp_http_method, + request_span, + tracer, +) +from .telemetry_registry import HTTP_ROUTE, STARTUP from .tokens import TokenInvalid from .tracer import AsgiTracer from .url_builder import Urls @@ -2926,8 +2931,26 @@ async def route_path(self, scope, receive, send, path): match, view = resolve_routes(self.routes, path) if match is None: + # No route matched, so the span keeps the bare method name it was + # given at the edge and gets no http.route. That is what semantic + # conventions ask for when the route is unknown. return await self.handle_404(request, send) + # The request span was started at the ASGI edge, before routing, so it + # carries only the method as a name. Now that the route is known, give + # it the `{method} {route}` shape semantic conventions want, and the + # http.route attribute - the low-cardinality counterpart to url.path, + # and so the one to group by. + span = request_span(scope) + if span is not None: + route = match.re.pattern + span.set_attribute(HTTP_ROUTE, route) + # Clamped, for the same reason the middleware clamps it: the method + # is a client-controlled string, and an unclamped one here would + # put attacker-supplied text back into the span name that the + # middleware just kept out of it. + span.update_name(f"{clamp_http_method(request.method)} {route}") + new_scope = dict(scope, url_route={"kwargs": match.groupdict()}) request.scope = new_scope try: diff --git a/datasette/telemetry.py b/datasette/telemetry.py index 31541a476d..311d661f97 100644 --- a/datasette/telemetry.py +++ b/datasette/telemetry.py @@ -201,6 +201,38 @@ def _url_path(scope): return scope.get("path", "") +# The request span is handed to `DatasetteRouter.route_path` through the ASGI +# scope rather than through `get_current_span()`, because by the time routing +# happens the current span may well be something else: a plugin +# `asgi_wrapper()` runs *inside* this middleware, and an instrumented one makes +# its own span current for the whole request. Reading the current span there +# would set `http.route` on that plugin's span - and rename it - while leaving +# the actual request span without the one attribute a trace UI groups by. Not +# hypothetical: an ordinary tracing plugin triggers it. +# +# Namespaced per the ASGI spec's rules for extension keys. Absent when the span +# is not recording, which is exactly when the router should skip the work too. +REQUEST_SPAN_SCOPE_KEY = "datasette.telemetry.request_span" + + +def request_span(scope): + """ + The recording request span for an ASGI scope, or None. + + Falls back to the current span so that a `DatasetteRouter` running under + some other instrumentation - one that started a SERVER span but of course + knows nothing about this scope key - still gets enriched. + """ + span = scope.get(REQUEST_SPAN_SCOPE_KEY) + if span is None: + span = otel_trace.get_current_span() + # is_recording(), not `get_span_context().is_valid`: with no provider but + # an inbound `traceparent`, the API's NoOpTracer hands back a + # NonRecordingSpan carrying the *remote* context, which is perfectly valid + # and still records nothing. + return span if span.is_recording() else None + + class TelemetryMiddleware: """ One `SpanKind.SERVER` span per HTTP request. @@ -265,6 +297,10 @@ async def __call__(self, scope, receive, send): if user_agent: span.set_attribute(USER_AGENT_ORIGINAL, user_agent) + # A copy, not a mutation: the scope belongs to the server, and + # every other layer in Datasette extends it the same way. + scope = dict(scope, **{REQUEST_SPAN_SCOPE_KEY: span}) + # The status cannot be read off a Response object: `asgi_static`, # the favicon route, `AsgiStream` and `AsgiFileDownload` all call # `send` directly and never build one. Wrapping `send` is the only diff --git a/datasette/telemetry_registry.py b/datasette/telemetry_registry.py index ddecbc5bb4..4e750605d2 100644 --- a/datasette/telemetry_registry.py +++ b/datasette/telemetry_registry.py @@ -67,10 +67,11 @@ def __new__( 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. There is no substring of the entry that - # could be matched against the wire, so `span_for()` resolves these by - # span kind instead, and the entry's own string is a template written - # for a human reading the generated reference. + # name is the request method followed by the matched route. There is + # no substring of the entry that could be matched against the wire, so + # `span_for()` resolves these by span kind instead, and the entry's own + # string is a template written for a human reading the generated + # reference. self.dynamic = dynamic # SpanKind.INTERNAL by default - every span Datasette emits describes # its own internal work. db.query is the one exception: it is a real @@ -104,6 +105,20 @@ def __repr__(self): "closed before anything was sent.", optional=True, ) +HTTP_ROUTE = Attribute( + "http.route", + "The route the request matched, as the compiled regular expression " + "pattern Datasette routes with - for example " + "``/(?P[^\\/\\.]+)/(?P[^\\/\\.]+)(\\.(?P\\w+))?$`` " + "for a table page. It is deliberately the pattern rather than a prettified " + "``/{database}/{table}`` template: the route table is fixed when the app " + "is built, so the pattern is exact, bounded and needs no parsing, whereas " + "the transform into something prettier accretes edge cases. Unlike " + "``url.path`` this is low cardinality, so it is the attribute to group by. " + "Omitted when no route matched - a 404 - which is also when the span name " + "falls back to the bare method.", + optional=True, +) URL_PATH = Attribute( "url.path", "The path portion of the URL. The query string is deliberately **not** " @@ -236,18 +251,22 @@ def __repr__(self): # --- Spans ---------------------------------------------------------------- HTTP_REQUEST = SpanName( - "{http.request.method}", + "{http.request.method} {http.route}", "One span per HTTP request, created by the outermost layer of the ASGI " "stack - so plugin ``asgi_wrapper()`` middleware, CSRF protection and " "every database span raised while serving the request all nest inside " "it. Without it each of those would be its own root trace. The span name " - "is not a fixed string: it is the value of ``http.request.method``. " + "is not a fixed string: it is the method followed by the matched route, " + "and just the method for a request that matched no route. The span starts " + "at the ASGI edge, before routing has happened, so it is named for the " + "method there and renamed once the route is known. " "W3C ``traceparent`` and ``baggage`` headers are extracted using the " "global propagator, so a request arriving from an already-traced caller " "continues that trace; set ``OTEL_PROPAGATORS=none`` to turn that off, " "and strip those headers at your proxy if your instance is public.", ( HTTP_REQUEST_METHOD, + HTTP_ROUTE, URL_PATH, URL_SCHEME, SERVER_ADDRESS, diff --git a/docs/internals.rst b/docs/internals.rst index ec50716f8f..da99e557f4 100644 --- a/docs/internals.rst +++ b/docs/internals.rst @@ -2367,21 +2367,26 @@ This reference is generated from ``datasette/telemetry_registry.py``, the single Spans are ``SpanKind.INTERNAL`` unless a kind is listed below. Two are not: the request span is ``SERVER``, and ``db.query`` is ``CLIENT`` because it is the one span that represents a call to a database rather than Datasette's own work. Trace UIs use the kind to decide whether to render a span as an inbound request or as a database call. ``db.query``'s children stay ``INTERNAL`` because they are Datasette's decomposition of that one query - marking them ``CLIENT`` too would make a single query look like several database calls to anything counting by kind. -The request span's name is the only one that is not a fixed string - it is composed from the request, so the heading below shows the template rather than a literal you will see in a trace. +The request span's name is the only one that is not a fixed string - it is composed from the request, so the heading below shows the template rather than a literal you will see in a trace. A request to a table page produces a span named, in full:: + + GET /(?P[^\/\.]+)/(?P
[^\/\.]+)(\.(?P\w+))?$ + +That is the route's compiled regular expression, not a prettified ``/{database}/{table}`` template. It is deliberate: Datasette routes with compiled patterns and the route table is fixed when the app is built, so the pattern is exact, bounded and needs no parsing, while transforming it into something prettier accretes edge cases. Django's own instrumentation ships regex-flavoured routes for the same reason. .. [[[cog from telemetry_doc import spans spans(cog) .. ]]] -``{http.request.method}`` - One span per HTTP request, created by the outermost layer of the ASGI stack - so plugin ``asgi_wrapper()`` middleware, CSRF protection and every database span raised while serving the request all nest inside it. Without it each of those would be its own root trace. The span name is not a fixed string: it is the value of ``http.request.method``. W3C ``traceparent`` and ``baggage`` headers are extracted using the global propagator, so a request arriving from an already-traced caller continues that trace; set ``OTEL_PROPAGATORS=none`` to turn that off, and strip those headers at your proxy if your instance is public. +``{http.request.method} {http.route}`` + One span per HTTP request, created by the outermost layer of the ASGI stack - so plugin ``asgi_wrapper()`` middleware, CSRF protection and every database span raised while serving the request all nest inside it. Without it each of those would be its own root trace. The span name is not a fixed string: it is the method followed by the matched route, and just the method for a request that matched no route. The span starts at the ASGI edge, before routing has happened, so it is named for the method there and renamed once the route is known. W3C ``traceparent`` and ``baggage`` headers are extracted using the global propagator, so a request arriving from an already-traced caller continues that trace; set ``OTEL_PROPAGATORS=none`` to turn that off, and strip those headers at your proxy if your instance is public. Kind: ``SERVER``. Attributes: - ``http.request.method`` - The HTTP method, clamped to the nine methods RFC 9110 and RFC 5789 define. Anything else is reported as ``_OTHER``: the method is a client-controlled string, so echoing it back unbounded would be a cardinality hazard. + - ``http.route`` *(optional)* - The route the request matched, as the compiled regular expression pattern Datasette routes with - for example ``/(?P[^\/\.]+)/(?P
[^\/\.]+)(\.(?P\w+))?$`` for a table page. It is deliberately the pattern rather than a prettified ``/{database}/{table}`` template: the route table is fixed when the app is built, so the pattern is exact, bounded and needs no parsing, whereas the transform into something prettier accretes edge cases. Unlike ``url.path`` this is low cardinality, so it is the attribute to group by. Omitted when no route matched - a 404 - which is also when the span name falls back to the bare method. - ``url.path`` - The path portion of the URL. The query string is deliberately **not** recorded, on this or any other span: Datasette puts user-supplied SQL in ``?sql=`` and canned query parameters in the query string, so exporting it by default would export exactly the data the rest of this instrumentation is careful with. - ``url.scheme`` - ``http`` or ``https``. - ``server.address`` *(optional)* - The ``Host`` header. Client-controlled, so treat it as untrusted input rather than as the identity of the server. @@ -2436,6 +2441,29 @@ The request span's name is the only one that is not a fixed string - it is compo .. [[[end]]] +.. _internals_telemetry_requests: + +Requests and inbound trace context +---------------------------------- + +Datasette creates the request span itself, at the outermost layer of the ASGI stack, so a trace is complete out of the box with no plugin and no extra instrumentation package. Everything raised while serving the request - plugin ``asgi_wrapper()`` middleware, CSRF protection, every database query - nests inside it. + +**Inbound trace context is trusted by default.** W3C ``traceparent`` and ``baggage`` headers are extracted from every request using the global propagator, so a request arriving from an already-traced caller continues that trace instead of starting a new one. That is what every other framework instrumentation does - Flask, Django, FastAPI and ``opentelemetry-instrumentation-asgi`` all extract unconditionally - but on an instance open to the internet it means an arbitrary client can influence your traces: + +- **Trace-ID pollution.** The client chooses the trace ID its request is filed under. +- **Sampling control.** The SDK's default sampler is ``parentbased_always_on``, so under any parent-based sampler a client's sampled flag can force recording - a telemetry-cost denial of service - or suppress it. +- **Baggage injection**, through the default composite propagator. + +Because extraction goes through the *global* propagator there is no Datasette setting to configure, and the remedies are the standard OpenTelemetry ones: + +- Strip ``traceparent``, ``tracestate`` and ``baggage`` at your reverse proxy, which is the right answer for a public instance fronted by one. +- Set ``OTEL_PROPAGATORS=none`` to disable extraction entirely, or ``OTEL_PROPAGATORS=tracecontext`` to keep trace continuation and drop baggage. +- Use a sampler that is not parent-based, which neutralises the sampling concern on its own. + +**Installing an ASGI instrumentation as well is harmless.** If you wire up ``opentelemetry-instrumentation-asgi`` through an ``asgi_wrapper()`` plugin, its middleware lands *inside* Datasette's own, so its span becomes a redundant child ``SERVER`` span in the same trace. Nothing is re-orphaned. There is no setting to turn Datasette's request span off, because "turn it off" is already covered by installing no provider, or by ``OTEL_SDK_DISABLED=true``. + +**Where** ``datasette.startup`` **lands depends on how you run Datasette.** ``datasette serve`` calls ``invoke_startup()`` before the server starts accepting connections, so the startup span is its own trace. An ASGI-hosted or programmatic deployment reaches startup lazily, on the first request, so there the startup span nests under that first request - which is honest, since it genuinely is that request's latency. + .. _internals_telemetry_privacy: Privacy and safety @@ -2447,6 +2475,7 @@ Spans leave your infrastructure whenever you configure an exporter, so what goes - **SQL parameter values are never recorded.** Only ``datasette.param_count``, a count. Parameter values are the part of a query most likely to hold something sensitive, and separating them from the SQL is the reason bound parameters exist. - **No actor identifiers are recorded.** No actor ID, no actor JSON, no client IP address. Nothing on a span identifies who made the request. - **Table names come only from an explicit** ``table=`` **argument.** ``db.collection.name`` is set by callers that already know which table they are working with, and is never derived from the SQL. Deriving it would mean parsing, and on an instance where visitors can create tables the set of possible values has no ceiling. +- **The query string is never recorded.** There is no ``url.query`` attribute on the request span or on any other span. Datasette puts user-supplied SQL in ``?sql=`` and canned query parameters in the query string, so recording it by default would export exactly the class of data the rules above are careful with. Only ``url.path`` and ``http.route`` are recorded. The SQL itself, though, *is* recorded, and on a public instance that means anything a visitor types into the query editor or passes as ``?sql=`` will be exported along with the span. That is the trade-off tracing a query engine makes. @@ -2455,7 +2484,8 @@ The SQL itself, though, *is* recorded, and on a public instance that means anyth Known limitations ----------------- -- **Datasette does not create a span for the HTTP request itself.** Every span listed above is therefore a root span unless something above Datasette - an ASGI instrumentation layer, or the web framework embedding it - has already started one for the request, in which case Datasette's spans nest underneath it correctly. +- ``http.route`` **is a compiled regular expression, not a pretty route template.** See :ref:`internals_telemetry_requests` above for why. +- **Inbound trace context is trusted by default**, which on a public instance means a client can influence your trace IDs, your sampling and your baggage. :ref:`internals_telemetry_requests` lists the remedies. - **Two plugin hooks run outside the** ``datasette.startup`` **span.** ``register_output_renderer`` is dispatched from ``Datasette.__init__()`` and ``asgi_wrapper`` from ``Datasette.app()``, both of which happen before ``invoke_startup()``. Datasette itself queries no database in either, so a default install emits nothing there - but a plugin that does will produce a root trace. Covering these would mean holding a span open across object construction, which is worse than the orphan. - ``db.operation.name`` **reports** ``WITH`` **for a statement that opens with a common table expression**, rather than the operation inside it, and a substantial share of Datasette's own reads take that form. The attribute is a leading-keyword match against a fixed allowlist, deliberately not a parse. - **Spans emitted before a provider is installed are not recorded.** If you are embedding Datasette in a host application, install your ``TracerProvider`` before serving traffic. This is ordinary OpenTelemetry behaviour rather than anything Datasette controls; nothing is permanently affected, those particular spans are simply dropped. diff --git a/tests/conftest.py b/tests/conftest.py index 3065f9e1b3..6e6b0ee70b 100644 --- a/tests/conftest.py +++ b/tests/conftest.py @@ -215,6 +215,7 @@ def pytest_collection_modifyitems(config, items): # (SIGSEGV/SIGBUS inside _execute_child). Reproduces with any subprocess # call placed there, on an unmodified tree - running it first avoids it. move_to_front(items, "test_datasette_package_never_imports_the_sdk") + move_to_front(items, "test_no_provider_takes_the_fast_path") def move_to_front(items, test_name): diff --git a/tests/test_http_span.py b/tests/test_http_span.py index 740d437df8..ff7924892d 100644 --- a/tests/test_http_span.py +++ b/tests/test_http_span.py @@ -3,31 +3,53 @@ `tests/test_telemetry_registry.py` already pins the span's name shape, kind and attribute keys against literals, so this file deliberately does not -repeat that. What it covers is the three properties of the middleware that -the registry conformance test structurally cannot see: +repeat that. What it covers is the properties of the middleware and of the +router's `http.route` enrichment that the registry conformance test +structurally cannot see: - **where the middleware sits.** Outermost is the entire point - moving it inside the plugin `asgi_wrapper()` loop leaves plugin middleware creating orphan root traces, which is the problem this span exists to fix, and every attribute assertion still passes. +- **which span the route lands on**, which only diverges once something else + has made a span current. - **method clamping**, which a workload of ordinary GETs can never exercise. - **the query string never being recorded**, which only fails if a request actually carries one. +- **the span outliving a streamed response body**, which only a paging export + can distinguish from ending far too early. """ import asyncio import itertools +import json +import subprocess +import sys +import textwrap +import time import pytest import pytest_asyncio pytest.importorskip("opentelemetry.sdk") -from opentelemetry.trace import SpanKind, StatusCode +from opentelemetry.trace import ( + NonRecordingSpan, + SpanContext, + SpanKind, + StatusCode, + TraceFlags, +) from datasette import hookimpl from datasette.app import Datasette -from datasette.telemetry import TelemetryMiddleware, tracer +from datasette.telemetry import ( + REQUEST_SPAN_SCOPE_KEY, + TelemetryMiddleware, + request_span, + tracer, +) +from datasette.utils import resolve_routes # Named in-memory databases are shared-cache: two Datasette instances given # the same name share one SQLite database and the second `create table` @@ -110,12 +132,51 @@ async def ds(): instance.close() +@pytest_asyncio.fixture +async def ds_paging(): + """ + An instance whose table is bigger than `max_returned_rows`. + + That is what makes `?_stream=1` genuinely page: `stream_csv` loops calling + `fetch_data` for each page *inside* the response body send, so the trace + contains `db.query` spans that start after the response has begun. On a + table that fits in one page every query finishes before the body starts + and the span-covers-the-body assertion cannot fail. + """ + name = f"httpspanpaging{next(_names)}" + # Both settings matter. `?_stream=1` forces `_size=max`, which is + # `max_returned_rows` - so lowering only that gives one page of five rows + # and no `next` token, and the export never loops. + instance = Datasette( + memory=True, settings={"max_returned_rows": 5, "default_page_size": 3} + ) + instance.add_memory_database(name) + await instance.invoke_startup() + db = instance.get_database(name) + await db.execute_write("create table t (id integer primary key, v text)") + await db.execute_write_many( + "insert into t (id, v) values (?, ?)", [[i, f"v{i}"] for i in range(40)] + ) + instance.db_name = name + try: + yield instance + finally: + instance.close() + + def _server_spans(otel_spans): return [ span for span in otel_spans.get_finished_spans() if span.kind is SpanKind.SERVER ] +def _route_for(ds, path): + "The compiled pattern Datasette's own router resolves `path` to." + match, _view = resolve_routes(ds._routes(), path) + assert match is not None, f"{path} matches no route" + return match.re.pattern + + @pytest.mark.asyncio async def test_plugin_asgi_wrapper_middleware_runs_inside_the_request_span( ds, otel_spans @@ -140,20 +201,20 @@ async def test_plugin_asgi_wrapper_middleware_runs_inside_the_request_span( spans = otel_spans.get_finished_spans() server = [span for span in spans if span.kind is SpanKind.SERVER] assert len(server) == 1, "expected exactly one SERVER span per request" - request_span = server[0] - assert request_span.parent is None, "the request span should be the trace root" + server_span = server[0] + assert server_span.parent is None, "the request span should be the trace root" plugin_spans = [span for span in spans if span.name == PLUGIN_MIDDLEWARE_SPAN] assert len(plugin_spans) == 1 assert plugin_spans[0].parent is not None - assert plugin_spans[0].parent.span_id == request_span.context.span_id - assert plugin_spans[0].context.trace_id == request_span.context.trace_id + assert plugin_spans[0].parent.span_id == server_span.context.span_id + assert plugin_spans[0].context.trace_id == server_span.context.trace_id # And the database work is in the same trace, not off on its own. queries = [span for span in spans if span.name == "db.query"] assert queries, "a table page should have issued at least one query" for query in queries: - assert query.context.trace_id == request_span.context.trace_id + assert query.context.trace_id == server_span.context.trace_id @pytest.mark.asyncio @@ -161,15 +222,20 @@ async def test_unrecognised_method_is_clamped(ds, otel_spans): """ Anyone can send `FROB / HTTP/1.1`. An unclamped method is an unbounded dimension a client controls, so semantic conventions map anything off the - known list to `_OTHER` - and the span name is the method, so an unclamped - one would put attacker-supplied text in the span name too. + known list to `_OTHER`. + + The span name is checked too, and it is the reason the router clamps the + method a second time when it renames the span: the middleware's clamping + protects the attribute, but the name is rebuilt from `request.method` in + `route_path`, which is the raw client string. An unclamped rename would + put attacker-supplied text straight back into the span name. """ otel_spans.clear() await ds.client.request("FROB", f"/{ds.db_name}/t") server = _server_spans(otel_spans) assert len(server) == 1 - assert server[0].name == "_OTHER" assert server[0].attributes["http.request.method"] == "_OTHER" + assert server[0].name == f"_OTHER {server[0].attributes['http.route']}" @pytest.mark.asyncio @@ -179,8 +245,8 @@ async def test_known_method_is_not_clamped(ds, otel_spans): await ds.client.get(f"/{ds.db_name}/t") server = _server_spans(otel_spans) assert len(server) == 1 - assert server[0].name == "GET" assert server[0].attributes["http.request.method"] == "GET" + assert server[0].name == f"GET {server[0].attributes['http.route']}" @pytest.mark.asyncio @@ -275,6 +341,10 @@ async def test_a_404_is_not_an_error(ds, otel_spans): `error.type` alone. Datasette 404s are routine - every missing table, and every bot probing for /wp-login.php - so treating them as errors would drown a real 500 in noise. + + Note this 404 *does* match a route: `/no-such-database-at-all` matches the + database pattern and the view then raises `NotFound`. Most Datasette 404s + are that shape rather than the unrouted one below. """ otel_spans.clear() response = await ds.client.get("/no-such-database-at-all") @@ -286,6 +356,29 @@ async def test_a_404_is_not_an_error(ds, otel_spans): assert server[0].status.status_code is StatusCode.UNSET +@pytest.mark.asyncio +async def test_an_unrouted_404_has_no_route_and_a_bare_method_name(ds, otel_spans): + """ + When no route matches there is nothing to set `http.route` to, so the span + keeps the bare method name it was given at the edge - which is exactly the + fallback semantic conventions specify for an unknown route. + + `/a/b/c/d/e` is used rather than a plausible-looking missing name because + Datasette's route table is greedy: `/no-such-database-at-all` matches the + database pattern, and `/-/nope/deeper` matches the row pattern. Only a + path deeper than any route matches nothing at all. + """ + otel_spans.clear() + response = await ds.client.get("/a/b/c/d/e") + assert response.status_code == 404 + server = _server_spans(otel_spans) + assert len(server) == 1 + assert server[0].name == "GET" + assert "http.route" not in server[0].attributes + assert server[0].attributes["http.response.status_code"] == 404 + assert server[0].status.status_code is StatusCode.UNSET + + @pytest.mark.asyncio async def test_only_the_first_http_response_start_is_recorded(otel_spans): """ @@ -342,3 +435,421 @@ async def send(message): await app({"type": "lifespan"}, receive, send) assert sent == ["lifespan.startup.complete", "lifespan.shutdown.complete"] assert not _server_spans(otel_spans) + + +@pytest.mark.asyncio +async def test_http_route_is_the_compiled_pattern(ds, otel_spans): + """ + `http.route` is the route's compiled regex, not a prettified template. + + Asserted against what Datasette's own router resolves rather than against + a copied literal, so this pins the *relationship* - the attribute is the + matched route - and does not break when a core pattern is edited. + """ + path = f"/{ds.db_name}/t" + expected = _route_for(ds, path) + otel_spans.clear() + assert (await ds.client.get(path)).status_code == 200 + server = _server_spans(otel_spans) + assert len(server) == 1 + assert server[0].attributes["http.route"] == expected + assert server[0].name == f"GET {expected}" + # The pattern really is the ugly one, and that is deliberate - if someone + # adds a prettifier this is the assertion that should make them argue for + # it rather than slip it in. + assert "(?P" in expected + + +@pytest.mark.asyncio +async def test_the_route_lands_on_the_request_span_not_a_plugins_current_span( + ds, otel_spans +): + """ + The route is set on the span the middleware started, found through the + ASGI scope - not on whatever span happens to be current when routing + resolves. + + Those are the same span only until a plugin `asgi_wrapper()` starts one of + its own. A plugin wrapper runs *inside* this middleware, so an instrumented + plugin makes its span current for the whole request: reading the current + span in `route_path` renames that plugin's INTERNAL span to + `GET ` and hangs `http.route` off it, while the actual request span + keeps a bare method name and never gets the one attribute a trace UI + groups requests by. Verified by reproducing it, not by reasoning about it. + """ + ds.pm.register(_MiddlewarePlugin(), name="httpspan-middleware") + try: + otel_spans.clear() + path = f"/{ds.db_name}/t" + expected = _route_for(ds, path) + assert (await ds.client.get(path)).status_code == 200 + finally: + ds.pm.unregister(name="httpspan-middleware") + + spans = otel_spans.get_finished_spans() + server = _server_spans(otel_spans) + assert len(server) == 1 + assert server[0].attributes["http.route"] == expected + assert server[0].name == f"GET {expected}" + # And the plugin's span is untouched: same name, no route attribute. + plugin_spans = [span for span in spans if span.name == PLUGIN_MIDDLEWARE_SPAN] + assert len(plugin_spans) == 1 + assert "http.route" not in (plugin_spans[0].attributes or {}) + + +@pytest.mark.asyncio +async def test_request_span_attributes(ds, otel_spans): + "The whole attribute set on one ordinary request." + path = f"/{ds.db_name}/t" + otel_spans.clear() + assert (await ds.client.get(path)).status_code == 200 + server = _server_spans(otel_spans) + assert len(server) == 1 + attributes = server[0].attributes + assert attributes["http.request.method"] == "GET" + assert attributes["url.path"] == path + assert attributes["url.scheme"] == "http" + assert attributes["http.response.status_code"] == 200 + assert attributes["http.route"] == _route_for(ds, path) + assert server[0].status.status_code is StatusCode.UNSET + # Never, on any span: an IP is borderline PII and the query string carries + # user-supplied SQL. + assert "client.address" not in attributes + assert "url.query" not in attributes + + +@pytest.mark.asyncio +async def test_db_query_spans_are_children_of_the_request_span(ds, otel_spans): + """ + The point of the whole PR. + + Not just "same trace ID" - every `db.query` span must reach the request + span by walking parents, and the request span must be the only root. A + stray root would show up in a trace UI as its own single-span trace, which + is the state this replaces. + """ + otel_spans.clear() + assert (await ds.client.get(f"/{ds.db_name}/t?_facet=v")).status_code == 200 + spans = otel_spans.get_finished_spans() + server = _server_spans(otel_spans) + assert len(server) == 1 + server_span = server[0] + assert server_span.parent is None + + by_span_id = {span.context.span_id: span for span in spans} + roots = [span for span in spans if span.parent is None] + assert [span.name for span in roots] == [server_span.name], ( + "every span from a request should hang off the request span, but these " + f"are roots: {sorted(span.name for span in roots)}" + ) + + queries = [span for span in spans if span.name == "db.query"] + assert queries, "a faceted table page should have issued queries" + for query in queries: + assert query.context.trace_id == server_span.context.trace_id + # Walk up to the root, which must be the request span. + current = query + seen = 0 + while current.parent is not None: + current = by_span_id[current.parent.span_id] + seen += 1 + assert seen < 20, "parent chain did not terminate" + assert current is server_span + + +@pytest.mark.asyncio +async def test_500_sets_error_status_and_error_type(ds, otel_spans): + """ + A plain 500 - no exception escaping the app, because `route_path` converts + it into a response itself. The status is the only signal the middleware + gets, so `error.type` is the status as a string. + """ + ds.pm.register(_BoomPlugin(), name="httpspan-boom") + try: + otel_spans.clear() + response = await ds.client.get("/-/http-span-boom") + assert response.status_code == 500 + finally: + ds.pm.unregister(name="httpspan-boom") + server = _server_spans(otel_spans) + assert len(server) == 1 + assert server[0].attributes["http.response.status_code"] == 500 + assert server[0].attributes["error.type"] == "500" + assert server[0].status.status_code is StatusCode.ERROR + + +@pytest.mark.asyncio +async def test_csv_stream_span_covers_the_body_send(ds_paging, otel_spans): + """ + The span must not end when the handler returns - it has to cover the + response body. + + `stream_csv` runs its generator inline inside `AsgiStream.asgi_send`, and + that call happens inside the single `await self.app(...)` the middleware + makes, so a plain `finally` is enough and no deferred-end machinery is + needed. This is the assertion that holds that claim up: a `db.query` that + starts during the body send must still finish before the request span + does. + + Only meaningful on an export that actually pages, hence `ds_paging` - on a + single-page table every query is over before the body begins and this + passes however early the span ends. The middle assertion below, that some + query *started* after `http.response.start` went out, is what keeps the + test honest about that; it is why the app is driven as raw ASGI rather + than through `ds.client`, which cannot timestamp the response start. + + `time.time_ns()` is the same clock the SDK stamps spans with, so the two + are directly comparable. + """ + app = ds_paging.app() + body = [] + response_started_at = None + + async def receive(): + return {"type": "http.request", "body": b"", "more_body": False} + + async def send(message): + nonlocal response_started_at + if message["type"] == "http.response.start": + assert message["status"] == 200 + response_started_at = time.time_ns() + else: + body.append(message.get("body") or b"") + + otel_spans.clear() + await app( + { + "type": "http", + "http_version": "1.1", + "method": "GET", + "path": f"/{ds_paging.db_name}/t.csv", + "raw_path": f"/{ds_paging.db_name}/t.csv".encode("latin-1"), + "query_string": b"_stream=1", + "scheme": "http", + "headers": [(b"host", b"localhost")], + }, + receive, + send, + ) + # 40 rows plus a header - the export really did read past one page + assert len(b"".join(body).decode("utf-8").strip().splitlines()) == 41 + assert response_started_at is not None + + spans = otel_spans.get_finished_spans() + server = _server_spans(otel_spans) + assert len(server) == 1 + server_span = server[0] + queries = [span for span in spans if span.name == "db.query"] + assert len(queries) > 1 + during_body = [span for span in queries if span.start_time > response_started_at] + assert during_body, ( + "no query ran after the response started, so this workload cannot " + "distinguish a span that covers the body send from one that ends when " + "the handler returns - the export is not paging" + ) + last_query_end = max(span.end_time for span in queries) + assert server_span.end_time > last_query_end, ( + "the request span ended before the last query of a streaming export - " + "it is not covering the response body" + ) + for query in queries: + assert query.context.trace_id == server_span.context.trace_id + + +@pytest.mark.asyncio +async def test_inbound_traceparent_becomes_the_parent(ds, otel_spans): + """ + W3C trace context is extracted with the global propagator, so a request + from an already-traced caller continues that trace. + + The sampled flag has to be set: the SDK's default sampler is + parentbased_always_on, so a `-00` flag would drop the span and the test + would fail for a reason that has nothing to do with propagation. + """ + trace_id = "4bf92f3577b34da6a3ce929d0e0e4736" + parent_span_id = "00f067aa0ba902b7" + otel_spans.clear() + response = await ds.client.get( + f"/{ds.db_name}/t", + headers={"traceparent": f"00-{trace_id}-{parent_span_id}-01"}, + ) + assert response.status_code == 200 + server = _server_spans(otel_spans) + assert len(server) == 1 + server_span = server[0] + assert f"{server_span.context.trace_id:032x}" == trace_id + assert server_span.parent is not None + assert f"{server_span.parent.span_id:016x}" == parent_span_id + assert server_span.parent.is_remote + # And the database spans joined the caller's trace too, not a new one. + queries = [ + span for span in otel_spans.get_finished_spans() if span.name == "db.query" + ] + assert queries + for query in queries: + assert f"{query.context.trace_id:032x}" == trace_id + + +@pytest.mark.asyncio +async def test_user_supplied_sql_in_the_query_string_is_never_recorded(ds, otel_spans): + """ + The `?sql=` case specifically, which is the one that matters: this is the + request where the query string *is* user-supplied SQL, and it reaches a + view that runs it. The marker is searched for across every attribute of + every span in the trace, not just for a `url.query` key, so recording it + under some other name fails too. + + `db.query.text` legitimately contains the SQL - that is documented and + deliberate - so the marker is checked against the request span's own + attributes, and against `url.*` and `http.*` keys everywhere. + """ + marker = "secret_marker_5b1f" + otel_spans.clear() + # `/{db}?sql=` 302s to the query view, so go straight there - a redirect + # would leave the SQL only on a span for a request that never ran it. + response = await ds.client.get(f"/{ds.db_name}/-/query?sql=select+'{marker}'") + assert response.status_code == 200 + spans = otel_spans.get_finished_spans() + server = _server_spans(otel_spans) + assert len(server) == 1 + leaked = [ + f"{span.name} -> {key}={value!r}" + for span in spans + for key, value in (span.attributes or {}).items() + if (span is server[0] or str(key).startswith(("url.", "http."))) + and (marker in str(value) or str(key) == "url.query") + ] + assert not leaked, "the query string reached a span attribute: " + ", ".join(leaked) + # The request really did carry the marker, so the search above had + # something to find. + assert marker in response.text + + +def test_request_span_skips_a_valid_but_non_recording_span(): + """ + `request_span()` is guarded on `is_recording()`, not on + `get_span_context().is_valid`, and this is the case that separates them. + + With no provider installed but an inbound `traceparent`, the API's + NoOpTracer hands back a `NonRecordingSpan` carrying the *remote* span + context - valid, sampled, and recording nothing. An `is_valid` guard would + wave that through and the router would build the name string and call + `set_attribute`/`update_name` on a span that discards both. + + Tested at this level deliberately: through a real request the two guards + are indistinguishable, because every call the router makes on a + NonRecordingSpan is already a no-op. The only difference is the work done + to get there, so the guard itself is what has to be asserted on. + """ + remote = SpanContext( + trace_id=0x4BF92F3577B34DA6A3CE929D0E0E4736, + span_id=0x00F067AA0BA902B7, + is_remote=True, + trace_flags=TraceFlags(TraceFlags.SAMPLED), + ) + assert remote.is_valid + non_recording = NonRecordingSpan(remote) + assert non_recording.is_recording() is False + assert request_span({REQUEST_SPAN_SCOPE_KEY: non_recording}) is None + # Nothing current, nothing in the scope: the INVALID_SPAN fallback. + assert request_span({}) is None + # And the case it must not skip. + with tracer.start_as_current_span("test.request_span.recording") as span: + assert request_span({REQUEST_SPAN_SCOPE_KEY: span}) is span + # Falling back to the current span is how an externally installed + # SERVER span still gets enriched. + assert request_span({}) is span + + +NO_PROVIDER_PROGRAM = textwrap.dedent(""" + import asyncio, json, sys + + from datasette.telemetry import TelemetryMiddleware + + seen = {} + + + async def inner(scope, receive, send): + seen.setdefault("sends", []).append(send) + seen.setdefault("scopes", []).append(scope) + await send({"type": "http.response.start", "status": 200, "headers": []}) + await send({"type": "http.response.body", "body": b""}) + + + async def real_send(message): + pass + + + async def main(): + middleware = TelemetryMiddleware(inner) + for headers in ([], [(b"traceparent", b"00-" + b"a" * 32 + b"-" + b"b" * 16 + b"-01")]): + await middleware( + { + "type": "http", + "method": "GET", + "path": "/", + "raw_path": b"/", + "scheme": "http", + "headers": headers, + }, + None, + real_send, + ) + print( + json.dumps( + { + "unwrapped": [send is real_send for send in seen["sends"]], + "scope_keys": [ + "datasette.telemetry.request_span" in scope + for scope in seen["scopes"] + ], + "sdk_imported": any( + name.startswith("opentelemetry.sdk") for name in sys.modules + ), + } + ) + ) + + + asyncio.run(main()) + """) + + +def test_no_provider_takes_the_fast_path(): + """ + With no `TracerProvider` installed the middleware must hand the + application the *original* `send`, not a wrapper - a default Datasette + 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 + 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. + + The second case, with an inbound `traceparent`, is the one that pins the + check itself. With no provider the API's NoOpTracer returns a + NonRecordingSpan carrying the *remote* span context: its + `get_span_context().is_valid` is True while `is_recording()` is False. A + fast path guarded on `is_valid` would therefore silently stop working for + exactly the requests that arrive from an already-traced caller - which on + a real deployment behind an instrumented proxy is all of them. + + conftest.py's pytest_collection_modifyitems() moves this test to the front + of the run by name - if you rename it, rename it there too. + """ + result = subprocess.run( + [sys.executable, "-c", NO_PROVIDER_PROGRAM], + capture_output=True, + text=True, + check=True, + ) + report = json.loads(result.stdout) + assert report["sdk_imported"] is False, "the SDK loaded in a fresh interpreter" + assert report["unwrapped"] == [True, True], ( + "the middleware wrapped `send` with no provider installed; the second " + "entry is the inbound-traceparent case, which fails if the fast path " + "is guarded on is_valid instead of is_recording()" + ) + # Same fast path, other observable: nothing is stashed in the scope either. + assert report["scope_keys"] == [False, False] diff --git a/tests/test_telemetry_registry.py b/tests/test_telemetry_registry.py index 96b2a7c555..398f72aab9 100644 --- a/tests/test_telemetry_registry.py +++ b/tests/test_telemetry_registry.py @@ -70,15 +70,22 @@ EXPECTED_SPANS = set(EXPECTED_ATTRIBUTES) # The HTTP request span is handled separately because its name is composed at -# runtime - it is the request method - so there is no fixed string to pin it -# to. What can still be pinned, and is what a dashboard depends on, is the -# shape of the name and the attribute keys. The workload below only issues -# GETs, so a change that stopped clamping the method, or that started naming -# the span after the path, fails here. -EXPECTED_HTTP_SPAN_NAME = "{http.request.method}" -EXPECTED_HTTP_SPAN_NAMES = {"GET"} +# runtime - the request method, then the route it matched - so there is no +# fixed string to pin it to. What can still be pinned, and is what a dashboard +# depends on, is the shape of that name and the attribute keys. +# +# The route half is deliberately not spelled out as a literal: it is a core +# route regex, and pinning those here would make an unrelated routing change +# fail the telemetry conformance test. What is pinned instead is that the name +# is exactly the method, a space, and the span's own `http.route` value - the +# `{method} {route}` shape semantic conventions specify. The workload below +# only issues GETs, so a change that stopped clamping the method, or that +# started naming the span after the path, fails here. +EXPECTED_HTTP_SPAN_NAME = "{http.request.method} {http.route}" +EXPECTED_HTTP_METHOD_NAMES = {"GET"} EXPECTED_HTTP_ATTRIBUTES = { "http.request.method", + "http.route", "url.path", "url.scheme", "server.address", @@ -193,10 +200,12 @@ async def exercise(): @pytest_asyncio.fixture async def emitted(otel_spans): """ - Every (span name, span kind, attribute keys) triple a broad workload emits. + Every (span name, span kind, attributes) triple a broad workload emits. The kind is carried because the request span's name is composed at - runtime, so `span_for()` resolves it by kind instead. + runtime, so `span_for()` resolves it by kind instead. The attributes are + carried as a mapping rather than a set of keys because the request span's + name has to be checked against its own `http.route` value. """ # otel_spans has already cleared the exporter, and nothing is cleared # after this point: the workload's own startup emits datasette.startup. @@ -210,7 +219,7 @@ async def emitted(otel_spans): ( str(span.name), span.kind, - frozenset(str(key) for key in span.attributes or {}), + {str(key): value for key, value in (span.attributes or {}).items()}, ) for span in spans ) @@ -227,8 +236,8 @@ def _partition(emitted): def _keys_by_span(records): by_span = {} - for name, _kind, keys in records: - by_span.setdefault(name, set()).update(keys) + for name, _kind, attributes in records: + by_span.setdefault(name, set()).update(attributes) return by_span @@ -246,11 +255,22 @@ async def test_workload_emits_exactly_the_expected_names(emitted): assert by_span == EXPECTED_ATTRIBUTES assert server, "the workload made HTTP requests but no SERVER span was emitted" - server_keys = _keys_by_span(server) - assert set(server_keys) == EXPECTED_HTTP_SPAN_NAMES union = set() - for keys in server_keys.values(): - union |= keys + methods = set() + for name, _kind, attributes in server: + union |= set(attributes) + route = attributes.get("http.route") + # Every request in the workload matches a route, so every one of these + # names must be `{method} {route}`. A 404 would be a bare method - the + # http_route tests cover that case with a real request. + assert route, f"the request span {name!r} carries no http.route" + method, _, name_route = name.partition(" ") + assert name_route == route, ( + f"the request span is named {name!r}, which is not the " + f"`{{method}} {{route}}` of {method!r} and {route!r}" + ) + methods.add(method) + assert methods == EXPECTED_HTTP_METHOD_NAMES assert union == EXPECTED_HTTP_ATTRIBUTES