remote/datasette
1
0
Fork 0
mirror of https://github.com/simonw/datasette.git synced 2026-09-06 00:24:07 +02:00
Code Issues Projects Releases Packages Wiki Activity

Give every span a request to belong to

Browse source 
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 <noreply@anthropic.com>
This commit is contained in:
Alex Garcia 2026-07-30 19:33:04 -07:00
commit ad9da9959f
6 changed files with 812 additions and 50 deletions
Download patch file Download diff file Expand all files Collapse all files

24
datasette/app.py
View file

@ -49,7 +49,7 @@ from .events import Event
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
@ -780,12 +780,16 @@ class Datasette:
# 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.
@ -2868,6 +2872,12 @@ class Datasette:
asgi = AsgiRunOnFirstRequest(asgi, on_startup=[self._startup_sequence])
for wrapper in pm.hook.asgi_wrapper(datasette=self):
asgi = wrapper(asgi)
# Outermost, deliberately: plugin asgi_wrapper() middleware, the
# CSRF layer and the first-request startup fallback all run *inside*
# this span, so a span created by an instrumented plugin - or by
# startup work triggered by the first request - parents to the
# request instead of becoming its own orphan root trace.
asgi = TelemetryMiddleware(asgi)
return asgi

194
datasette/telemetry.py
View file

@ -17,7 +17,19 @@ something measurable.
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
@ -124,3 +136,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))

105
datasette/telemetry_registry.py
View file

@ -47,12 +47,26 @@ class Attribute(str):
class SpanName(str):
"A span name, carrying its documentation and the attributes it may set."
__slots__ = ("attributes", "description", "kind")
__slots__ = ("attributes", "description", "dynamic", "kind")
def __new__(cls, name, description, attributes=(), kind=SpanKind.INTERNAL):
def __new__(
cls,
name,
description,
attributes=(),
dynamic=False,
kind=SpanKind.INTERNAL,
):
self = super().__new__(cls, name)
self.description = description
self.attributes = tuple(attributes)
# 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
@ -69,6 +83,53 @@ class SpanName(str):
# 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(
@ -184,6 +245,30 @@ TRANSACTION = Attribute(
# --- 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 "
@ -253,6 +338,7 @@ STARTUP = SpanName(
)
SPANS = (
HTTP_REQUEST,
DB_QUERY,
DB_QUERY_EXECUTE,
DB_WRITE_QUEUE_WAIT,
@ -261,16 +347,25 @@ SPANS = (
)
def span_for(emitted_name):
def span_for(emitted_name, kind=None):
"""
Resolve an emitted span name to its registry entry, or None.
The lookup is what the conformance test calls, so it lives here rather
than in the test.
Handles `dynamic=True` entries, whose emitted names are not knowable in
advance: the name has no fixed part at all, so it is matched on `kind`
instead and the caller has to supply one. Exact entries are tried first,
so a dynamic entry can never shadow a span that does have a registered
name.
"""
for span in SPANS:
if span.dynamic:
continue
if 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

21
docs/internals.rst
View file

@ -2365,17 +2365,34 @@ A few things catch people out the first time:
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. Callback-style calls - ``execute_fn()``, ``execute_write_fn()`` and ``execute_isolated_fn()`` - appear here too, distinguished by ``datasette.callback`` in place of ``db.query.text``.

344
tests/test_http_span.py Normal file
View file

@ -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)

172
tests/test_telemetry_registry.py
View file

@ -30,6 +30,9 @@ import pytest_asyncio
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
@ -67,6 +70,31 @@ EXPECTED_ATTRIBUTES = {
}
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.
@ -77,6 +105,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
@ -140,37 +185,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
@ -182,27 +252,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
@ -213,9 +290,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
@ -230,11 +310,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."
@ -253,10 +332,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}")
@ -291,6 +374,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<database>[^/]+)$", 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