diff --git a/datasette/app.py b/datasette/app.py index 20b58295..3e4c5acf 100644 --- a/datasette/app.py +++ b/datasette/app.py @@ -175,9 +175,7 @@ app_root = Path(__file__).parent.parent logger = logging.getLogger(__name__) -# _in_datasette_client itself lives in telemetry.py so the request span -# middleware can read it without a circular import; its writers -# (_DatasetteClientContext) and reader (in_client()) both live here. +# _in_datasette_client is defined in telemetry.py to avoid a circular import class _DatasetteClientContext: @@ -653,9 +651,7 @@ class Datasette: self.root_enabled = False self.default_deny = default_deny self.client = DatasetteClient(self) - # Last, so that the observable-gauge callbacks - which may fire on the - # SDK's collection thread the instant this returns - never see a - # half-built instance. + # Last, so metric callbacks never see a partially initialized instance register_datasette(self) async def apply_metadata_json(self): @@ -797,19 +793,7 @@ class Datasette: # This must be called for Datasette to be in a usable state if self._startup_invoked: return - # `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. + # Group spans created during startup under a single parent span with tracer.start_as_current_span(STARTUP): # Register event classes event_classes = [] @@ -996,9 +980,7 @@ class Datasette: if self._closed: return self._closed = True - # Stop reporting gauges before tearing anything down, so a collection - # cycle landing mid-close cannot observe a half-closed instance. The - # WeakSet would drop it eventually anyway; this makes it immediate. + # Stop reporting metrics before closing databases unregister_datasette(self) first_exception = None dbs = list(self.databases.values()) + [self._internal_database] @@ -3185,11 +3167,8 @@ ORDER BY allowed.parent, allowed.child asgi, on_startup=[self._startup_sequence, self._launch_background_tasks], ) - # 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. + # Outermost, so spans from plugin middleware and first-request + # startup are children of the request span asgi = TelemetryMiddleware(asgi) return asgi @@ -3314,24 +3293,13 @@ class DatasetteRouter: request.scope = scope 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. + # Now the route is known, add it to the request span 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()}) diff --git a/datasette/database.py b/datasette/database.py index 726d5ddb..542b3012 100644 --- a/datasette/database.py +++ b/datasette/database.py @@ -310,9 +310,6 @@ class Database: raise QueryInterrupted(e, sql, params) raise - # SIM117 wants these two context managers merged. They are kept nested - # deliberately: the hand-rolled tracer's wrapper is on its way out, and - # nesting makes removing it a single-line deletion. with trace( # noqa: SIM117 "sql", database=self.name, sql=sql.strip(), params=params ): @@ -337,14 +334,10 @@ class Database: def _inner(conn): return conn.executescript(sql) - # Nested on purpose - see the note in execute_write(). with trace( # noqa: SIM117 "sql", database=self.name, sql=sql.strip(), executescript=True ): - # No db.operation.name here, deliberately: executescript() runs - # several semicolon-separated statements, and semantic conventions - # say the attribute should not be extracted from query text that - # can hold more than one operation - see sql_operation_name(). + # No db.operation.name, since the script can contain multiple statements with tracer.start_as_current_span(DB_QUERY, kind=DB_QUERY.kind) as span: span.set_attribute(DB_SYSTEM, "sqlite") span.set_attribute(DB_NAMESPACE, self.name) @@ -370,7 +363,6 @@ class Database: return conn.executemany(sql, count_params(params_seq)), count - # Nested on purpose - see the note in execute_write(). with trace( "sql", database=self.name, sql=sql.strip(), executemany=True ) as kwargs: @@ -379,8 +371,6 @@ class Database: span.set_attribute(DB_NAMESPACE, self.name) span.set_attribute(DB_QUERY_TEXT, sql_attribute(sql)) span.set_attribute(EXECUTEMANY, True) - # A single statement run with many parameter sets, so unlike - # execute_write_script() there is exactly one operation to name. operation_name = sql_operation_name(sql) if operation_name: span.set_attribute(DB_OPERATION_NAME, operation_name) @@ -388,8 +378,6 @@ class Database: results, count = await self._execute_write_fn( _inner, block=block, request=request ) - # count is the number of parameter *sets* consumed by - # executemany(), not a row count - executemany returns no rows. span.set_attribute(PARAM_SETS, count) kwargs["count"] = count return results @@ -412,17 +400,11 @@ class Database: # May already have been cleared by close(). pass - # One db.query span here, like execute_fn() / execute_write_fn(). - # The wrap must NOT move into _send_to_write_thread(): that is the - # shared tail for every write, and for block=False it is where the - # link back to this span is captured - a span opened there would be - # the link target for its own children. with tracer.start_as_current_span(DB_QUERY, kind=DB_QUERY.kind) as span: span.set_attribute(DB_SYSTEM, "sqlite") span.set_attribute(DB_NAMESPACE, self.name) span.set_attribute(CALLBACK, callback_name(fn)) - # "write" when mutable because the call blocks the write queue; - # "read" when immutable, where it runs on the read pool. + # Immutable databases run this on the read pool, not the write queue with record_operation_duration(self.name, "write" if write else "read"): if self.ds.executor is None: # non-threaded mode @@ -430,10 +412,7 @@ class Database: if not write: # Immutable database - no writes can ever occur, so there # is no write queue to block; run against a fresh - # read-only connection. copy_context() carries the - # caller's otel context onto the worker thread - see the - # notes in _execute_fn() for why it must be a fresh copy - # per submit and why carrying every ContextVar is safe. + # read-only connection ctx = contextvars.copy_context() return await asyncio.get_running_loop().run_in_executor( self.ds.executor, ctx.run, _run @@ -450,20 +429,13 @@ class Database: return await self.execute_isolated_fn(_analyze_sql) async def execute_write_fn(self, fn, block=True, transaction=True, request=None): - """Run `fn(conn)` on the write connection, traced as one database call. + """Run `fn(conn)` on the write connection, traced as a `db.query` span. - The public entry point for callback-style writes. Instrumented like - `execute_write()`: one `db.query` span (with `datasette.callback` in - place of `db.query.text`) above the `db.write.queue_wait` and - `db.write.execute` spans the write thread emits. The SQL-string write - methods call `_execute_write_fn()` directly, so they never get a - second span. For `block=False` this span ends at enqueue and the - write-thread spans become roots carrying a link back to it, exactly - as for `execute_write(block=False)`. + The SQL-string write methods call `_execute_write_fn()` directly to + avoid creating a second span. """ self._check_not_closed() - # The raw fn's name, before _wrap_fn_with_hooks() replaces it with a - # wrapper - otherwise every write would report the wrapper's name. + # Record the name before _wrap_fn_with_hooks() wraps fn name = callback_name(fn) with tracer.start_as_current_span(DB_QUERY, kind=DB_QUERY.kind) as span: span.set_attribute(DB_SYSTEM, "sqlite") @@ -576,9 +548,7 @@ class Database: task_id = uuid.uuid4() loop = asyncio.get_running_loop() reply_future = loop.create_future() - # The otel Context and enqueue timestamp are captured here, on the - # event loop, for the db.write.queue_wait span built at dequeue time. - # `block` travels too - it decides parent vs. link; see `_execute_writes`. + # Capture the OpenTelemetry context and enqueue time for the write thread self._write_queue.put( WriteTask( fn, @@ -604,16 +574,8 @@ class Database: conn = None try: conn = self.connect(write=True) - # This warm-up runs before any write has ever been queued, so - # there is no captured caller context to attach - and a raw - # threading.Thread does not inherit the context of whoever started - # it. Spans created by plugin hooks here are therefore roots even - # when the write thread is started from inside invoke_startup(): - # its datasette.startup span is current on the event loop but does - # not cross this thread boundary. Read connections differ - they - # warm up inside executor tasks submitted with copy_context(), so - # their prepare_connection spans do nest under whoever triggered - # them. + # Threads do not inherit the caller's context, so any spans + # created by prepare_connection hooks here are root spans self.ds._prepare_connection(conn, self.name) except Exception as e: # noqa: BLE001 # Stored and re-raised to whoever queues the next write @@ -628,26 +590,11 @@ class Database: # Best-effort close as the write thread exits pass return - # `task.block` decides how this task's spans relate to the - # context captured at enqueue time: - # - # - block=True: the caller genuinely awaits the reply, so - # containment is accurate. Restore that context as current - # (attach below) so db.write.queue_wait/db.write.execute parent - # normally to the request that queued them. The token must be - # detached below in `finally` - a leaked token silently - # poisons this thread's ambient context for every write - # processed after it, and a *wrong*-token detach only logs a - # warning rather than raising, so this pairing is load-bearing - # and easy to get wrong silently. - # - block=False: the caller returned already without awaiting, - # so the enqueueing span may have closed before this task's - # spans even start. The enqueueing request *caused* this write - # without *containing* it, so nothing is attached here - - # linked_root_span_kwargs() makes each write span a root with - # a Link back to the enqueueing span (see its docstring for - # the full rationale), built once into `write_span_kwargs` - # and spread into every start_span call below. + # block=True: the caller awaits the result, so the write spans + # are children of the caller's span. The token must be detached + # in the finally block or the context leaks into later writes. + # block=False: the caller may finish first, so the write spans + # are root spans with a link back to the caller's span. token = None write_span_kwargs = {} if task.block: @@ -657,10 +604,7 @@ class Database: try: exception = None result = None - # Explicit start_time/end_time rather than a `with` block: - # this span's duration is the time the task actually spent - # waiting in the queue (enqueue -> dequeue), not the near- - # zero time spent constructing/ending the span object here. + # Span covers the time from enqueue to dequeue dequeued_at_ns = time.time_ns() tracer.start_span( DB_WRITE_QUEUE_WAIT, @@ -669,8 +613,6 @@ class Database: ).end(end_time=dequeued_at_ns) record_write_queue_wait(self.name, dequeued_at_ns - task.enqueued_at_ns) if conn_exception is not None: - # fn never runs in this branch, so there is nothing to - # wrap in a db.write.execute span. exception = conn_exception elif task.isolated_connection: try: @@ -723,22 +665,15 @@ class Database: otel_context_api.detach(token) async def execute_fn(self, fn): - """Run `fn(conn)` on a read connection, traced as one database call. + """Run `fn(conn)` on a read connection, traced as a `db.query` span. - The public entry point for callback-style reads - plugins and core - both use it to run arbitrary Python against a connection. It is - instrumented exactly like `execute()`: one `db.query` span (with - `datasette.callback` in place of `db.query.text`, since there is no - SQL string to record) and a `db.query.execute` child covering the - time actually spent on the worker thread. `execute()` itself calls - `_execute_fn()` directly, so a SQL read never gets a second span. + `execute()` calls `_execute_fn()` directly to avoid creating a second + span. """ self._check_not_closed() def fn_in_execute_span(conn): - # Created on the worker thread; parents to the db.query span via - # the copy_context() propagation in _execute_fn(). The gap - # between the two spans is time spent waiting for a free thread. + # Runs on the worker thread with tracer.start_as_current_span(DB_QUERY_EXECUTE): return fn(conn) @@ -746,9 +681,6 @@ class Database: span.set_attribute(DB_SYSTEM, "sqlite") span.set_attribute(DB_NAMESPACE, self.name) span.set_attribute(CALLBACK, callback_name(fn)) - # Default exception handling applies, unlike execute(): there is - # no log_sql_errors=False probing caller and no expected-timeout - # budget on this path, so a raised exception is an error. with record_operation_duration(self.name, "read"): return await self._execute_fn(fn_in_execute_span) @@ -772,27 +704,9 @@ class Database: with self._pending_execute_futures_lock: self._check_not_closed() - # A fresh copy_context() is required per submit (not one shared - # copy reused across calls): concurrent execution of the same - # Context raises "RuntimeError: cannot enter context ... - # already entered". This propagates the caller's otel context - # (e.g. the enclosing db.query span) onto the worker thread. - # - # copy_context() is not selective: it also carries Datasette's own - # ContextVars - _skip_permission_checks and _permission_check_cache - # (datasette/permissions.py), _in_datasette_client (app.py) and, - # until the hand-rolled tracer goes, trace_task_id (tracer.py) - - # into worker threads, where they previously took their defaults. - # That is safe, for two reasons. Nothing reads them on a worker - # thread: the permission code that reads the first two is async and - # only ever runs on the event loop. And Context.run() restores the - # thread's previous context when the callable returns, so a value - # cannot outlive the submit that carried it and reach the next task - # on this shared pool - "skip permission checks" in particular can - # never bleed from one request into another's query. Where a value - # would be read - a plugin calling datasette.in_client() or trace() - # from inside an execute_fn callable - seeing the submitting - # request's value is the more accurate answer, not a leak. + # Run in a copy of the caller's context so spans created in the + # thread have the correct parent. This needs a fresh copy for + # each submit, since a Context cannot be entered concurrently. ctx = contextvars.copy_context() future = self.ds.executor.submit(ctx.run, in_thread) self._pending_execute_futures.add(future) @@ -812,37 +726,15 @@ class Database: self._check_not_closed() page_size = page_size or self.ds.page_size time_limit_ms = self.ds.sql_time_limit_ms - # A caller that hands in a budget shorter than the instance-wide - # sql_time_limit_ms is saying "this may not finish, and that is an - # answer I can use" - and every such caller in core does treat the - # timeout as normal: table_counts() stores None per table, facet - # suggestion moves on to the next column, autocomplete falls back to a - # prefix query. Those timeouts are therefore not span errors. Without - # this, the homepage alone emits one red span per table (it counts - # every table under a 10ms budget) on every single hit. - # - # A query that runs out the instance-wide limit is a different event - - # nobody asked for a short budget, so it stays an error. + # Callers that pass a shorter custom_time_limit, such as table counts + # and facet suggestions, expect timeouts, so they are not span errors timeout_expected = bool(custom_time_limit) and custom_time_limit < time_limit_ms if timeout_expected: time_limit_ms = custom_time_limit def sql_operation_in_thread(conn): - # This span is created inside the worker thread. Its parent is - # resolved from the ambient otel context, which was propagated - # onto this thread via copy_context() at the executor.submit() - # boundary in _execute_fn() (or run_in_executor() for immutable - # databases) - so it parents correctly to the enclosing - # db.query span despite running on a different thread. - # - # Exception handling is explicit rather than left to the context - # manager's flags, which apply to every exception type alike. This - # span needs to tell two apart: an expected timeout is never an - # error, while a genuine SQL failure is one unless the caller - # passed log_sql_errors=False, meaning it was probing and treats - # failure as an expected answer. Without the latter, facet - # suggestion marks two spans per text column as failed on every - # table page; without the former, so does every homepage hit. + # Expected timeouts and errors with log_sql_errors=False are not + # recorded as span errors, so exceptions are handled explicitly with tracer.start_as_current_span( DB_QUERY_EXECUTE, record_exception=False, @@ -889,15 +781,9 @@ class Database: else: return Results(rows, False, cursor.description) - # SIM117 wants these two context managers merged. They are kept nested - # deliberately: the hand-rolled tracer's wrapper is on its way out, and - # nesting makes removing it a single-line deletion. with trace( # noqa: SIM117 "sql", database=self.name, sql=sql.strip(), params=params ): - # Exception handling is explicit rather than left to the context - # manager's defaults, so that callers passing log_sql_errors=False - # can be honoured - see the comment on the generic handler below. with tracer.start_as_current_span( DB_QUERY, kind=DB_QUERY.kind, @@ -917,26 +803,15 @@ class Database: with record_operation_duration(self.name, "read"): results = await self._execute_fn(sql_operation_in_thread) except QueryInterrupted as e: - # datasette.interrupted is set either way - it is the - # signal worth having. Only the ERROR status is - # conditional; see the timeout_expected comment above. span.set_attribute(INTERRUPTED, True) if not timeout_expected: span.set_status(Status(StatusCode.ERROR, str(e))) span.record_exception(e) - # Expected timeouts (a caller that opted into a shorter - # budget, like facet suggestion) are not counted - see - # the M_QUERIES_INTERRUPTED registry entry for why. record_query_interrupted(self.name) raise except Exception as e: - # log_sql_errors=False means the caller is probing and - # treats failure as an expected answer, not an error. - # Facet suggestion is the big one: it runs json_type() - # against every column precisely to find out which ones - # raise, so a table with N text columns would otherwise - # mark N queries per page as failed - burying real errors - # and setting off any alerting based on span status. + # log_sql_errors=False callers, such as facet suggestion, + # expect some queries to fail if log_sql_errors: span.record_exception(e) span.set_status(Status(StatusCode.ERROR, str(e))) @@ -1035,10 +910,8 @@ class Database: ) return [r[0] for r in results.rows] - # These callbacks are named functions rather than lambdas so that their - # db.query spans carry a greppable datasette.callback - exactly the - # guidance the plugin telemetry docs give, applied to core's own - # highest-frequency introspection calls. + # Named functions rather than lambdas give more useful datasette.callback + # span attributes async def table_columns(self, table): def _table_columns(conn): @@ -1291,11 +1164,6 @@ class WriteTask: self.transaction = transaction self.otel_context = otel_context self.enqueued_at_ns = enqueued_at_ns - # Whether the enqueueing caller awaits the reply future. Decides how - # `_execute_writes` relates this task's spans to `otel_context`: - # parent (block=True) or span-link target (block=False). See the - # comment at the WriteTask construction site in - # `_send_to_write_thread`. self.block = block diff --git a/datasette/telemetry.py b/datasette/telemetry.py index 8795dd60..2fd5a9dc 100644 --- a/datasette/telemetry.py +++ b/datasette/telemetry.py @@ -1,19 +1,8 @@ """ -OpenTelemetry integration for Datasette core. +OpenTelemetry integration for Datasette. -Core depends on `opentelemetry-api` only. It never creates a -`TracerProvider` or a `MeterProvider`, never configures an exporter, and -never touches sampling - that is the responsibility of whoever is running -Datasette (an `opentelemetry-instrument` agent, a future plugin, or a test -harness). - -With no provider installed every span produced here is a -`NonRecordingSpan`. That is not free - a table page emits ~100 spans - -but end-to-end page benchmarks put the overhead below their own -run-to-run variation. Installing an SDK provider is what costs -something measurable. Every metric instrument is likewise a no-op -without a provider, and the observable-gauge callbacks are never -invoked at all. +This uses `opentelemetry-api` only. Providers, exporters and sampling are +configured by whoever runs Datasette, for example `opentelemetry-instrument`. """ import contextvars @@ -54,32 +43,12 @@ from .telemetry_registry import ( from .version import __version__ # True while code is executing within a datasette.client request. Defined -# here rather than in app.py (which owns its writers and the in_client() -# accessor) so TelemetryMiddleware can read it without a circular import: -# an in-process sub-request runs the full ASGI stack, so it emits a second, -# nested SERVER span - datasette.internal_client marks those so kind-based -# dashboards can filter the double-count out. +# here rather than in app.py to avoid a circular import. _in_datasette_client = contextvars.ContextVar("in_datasette_client", default=False) -# The semantic-convention version whose spellings this instrumentation -# actually emits. Deliberately NOT the latest release. -# -# A schema URL is a machine-readable claim: a consumer doing schema -# translation replays the renames between the declared version and the one -# it wants, so the claim has to name the version whose spellings are on the -# wire. A wrong one makes translation wrong rather than merely uninformative. -# -# Datasette emits `db.system`, which was renamed to `db.system.name` in -# semconv 1.30.0. Everything else it emits (`db.namespace`, `db.query.text`, -# `db.operation.name`, `db.collection.name`) has been current since 1.26.0. -# So 1.29.0 is the highest version at which every name emitted here is the -# current spelling. Everything under `datasette.*` is Datasette's own and -# outside semconv, so it is unaffected either way. -# -# Declaring 1.43.0 would be false about `db.system`, and would actively STOP -# a consumer translating it forward, because it asserts the rename already -# happened. Bump this deliberately, in the same commit as the attribute -# renames it implies - it is a claim about the names, not decoration. +# The semantic conventions version matching the attribute names used here. +# 1.30.0 renamed `db.system` to `db.system.name`, so update this when +# renaming attributes to match a newer version. SCHEMA_URL = "https://opentelemetry.io/schemas/1.29.0" tracer = otel_trace.get_tracer("datasette", __version__, schema_url=SCHEMA_URL) @@ -100,28 +69,22 @@ def callback_name(fn) -> str: """ The name recorded as `datasette.callback` for a callback-style call. - `functools.partial` objects (and other callables) have no `__qualname__`, - so fall back to the type's name rather than fail the query over telemetry. + Falls back to the type name for callables such as `functools.partial` + that have no `__qualname__`. """ return getattr(fn, "__qualname__", type(fn).__name__) def linked_root_span_kwargs(context=None): """ - Keyword arguments that start a span as a root in its own trace, carrying - a ``Link`` back to whatever span is current - the shape for work that a - request *caused* without *containing*. + Keyword arguments that start a new root span with a ``Link`` back to + the current span. - Use it when the causing span will end before the work does (a background - task, a scheduled job, a ``block=False`` write): parenting there would - draw a child outliving its closed parent, which renders badly in most - trace UIs. The explicit empty ``Context()`` also stops the worker - thread's ambient context from supplying an accidental parent. + Use this for work that can outlive the span that caused it, such as a + background task or a ``block=False`` write. - Pass ``context`` to link to the span current in a *captured* context - (e.g. one carried across a queue) rather than the caller's. If no valid - span is current there is simply no link. The link carries no attributes: - with only one kind of link, naming the relationship would add nothing. + Pass ``context`` to link to the span in a previously captured context + instead of the current one. If there is no valid span, no link is added. Works with any tracer:: @@ -135,15 +98,8 @@ def linked_root_span_kwargs(context=None): return {"context": otel_context_api.Context(), "links": links} -# db.operation.name is the leading keyword of a statement matched against a -# fixed allowlist - deliberately not a parse. -# -# This runs against arbitrary user-supplied SQL (the `?sql=` query string, -# canned queries, anything typed into the query editor), and the attribute -# has to stay safe to use as a metric dimension. A metric series is keyed by -# its attribute values, so echoing back an arbitrary first token would let -# one visitor's typo mint a new, permanent series. The allowlist bounds that -# at a fixed, small set regardless of what anyone sends. +# Keywords that can be recorded as db.operation.name. SQL can be supplied by +# users, so an allowlist keeps the number of distinct values small. DB_OPERATION_ALLOWLIST = frozenset( { "SELECT", @@ -167,26 +123,10 @@ _LEADING_KEYWORD = re.compile(r"^\s*([A-Za-z]+)") def sql_operation_name(sql: str) -> str | None: """ - The statement's leading keyword, if it is one we recognise. + The statement's leading keyword if it is in the allowlist, else None. - Returns None - never a guess - for anything not on the allowlist, - including a statement that opens with a comment or with punctuation such - as the "(" of a parenthesised SELECT. - - Known limitation: a statement beginning with a CTE reports `WITH` rather - than the operation inside it, and a substantial share of Datasette's own - reads take that form. Extracting more than the leading keyword means - handling comment stripping, parenthesised `(SELECT ...) UNION` and - compound names like `CREATE TABLE` - each a special case a hand-rolled - matcher would accrete and eventually get wrong. Omitting a name beats - guessing at one. - - Only safe to call with a single statement: `execute_write_script()` runs - several separated by semicolons, and semantic conventions say - `db.operation.name` "SHOULD NOT be extracted from db.query.text, when the - database system supports query text with multiple operations in non-batch - operations" - so that call site does not use this at all rather than - reporting only the first statement's operation. + Statements that start with a comment or "(" return None. Statements + starting with a CTE return `WITH`. Only call this for a single statement. """ match = _LEADING_KEYWORD.match(sql) if not match: @@ -201,14 +141,7 @@ def sql_operation_name(sql: str) -> str | None: 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. - """ + "Read W3C trace context from an ASGI scope's headers." def get(self, carrier, key): wanted = key.lower().encode("latin-1") @@ -222,9 +155,8 @@ class _ScopeHeadersGetter(Getter): _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). +# Methods defined by RFC 9110 plus PATCH (RFC 5789). Anything else is +# recorded as `_OTHER`, as recommended by semantic conventions. _KNOWN_METHODS = frozenset( {"GET", "HEAD", "POST", "PUT", "DELETE", "CONNECT", "OPTIONS", "TRACE", "PATCH"} ) @@ -248,16 +180,9 @@ 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, but the name is read both ways in the wild - httpx's - own `raw_path` includes the query - and Datasette's query strings carry - user-supplied SQL, which core never records. A literal "?" cannot appear - unencoded in a path, so the defensive split costs nothing when the server - is well behaved. + Prefers `raw_path`, which preserves encoded slashes in database and + table names. Some clients include the query string in `raw_path`, so + that is stripped as well. """ raw_path = scope.get("raw_path") if raw_path: @@ -267,17 +192,9 @@ 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. +# The request span is passed to the router in the ASGI scope, because a +# plugin's asgi_wrapper() middleware may have made its own span current. +# Absent if the span is not recording. REQUEST_SPAN_SCOPE_KEY = "datasette.telemetry.request_span" @@ -285,15 +202,12 @@ 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. + Falls back to the current span, for when Datasette is running under + other instrumentation. """ 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` - see the fast-path - # comment in TelemetryMiddleware for why valid is not the same as recording. return span if span.is_recording() else None @@ -301,52 +215,28 @@ 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. + The span ends after the full response, including any streamed body, + has been sent. """ 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. + # Pass lifespan and websocket scopes straight through 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. + # Uses the global propagator, configured with OTEL_PROPAGATORS 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. + # Renamed to include the route once 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. + # No provider installed, or the trace was not sampled await self.app(scope, receive, send) return span.set_attribute(HTTP_REQUEST_METHOD, method) @@ -363,15 +253,10 @@ class TelemetryMiddleware: if _in_datasette_client.get(): span.set_attribute(INTERNAL_CLIENT, True) - # 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 - # thing that sees every response, including the 404 and 500 - # handlers. + # Some responses are sent without a Response object, so the + # status is captured by wrapping send() status_holder = {} async def wrapped_send(message): @@ -386,10 +271,7 @@ class TelemetryMiddleware: try: 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. + # Includes asyncio.CancelledError when a client disconnects escaped = True span.set_attribute(ERROR_TYPE, type(exception).__name__) span.set_status(Status(StatusCode.ERROR, str(exception))) @@ -398,32 +280,14 @@ class TelemetryMiddleware: 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. + # 4xx responses are not errors for a server span. If an + # exception escaped, keep its class name as error.type. if status >= 500 and not escaped: span.set_status(Status(StatusCode.ERROR)) span.set_attribute(ERROR_TYPE, str(status)) # --- Metrics -------------------------------------------------------------- -# -# Two shapes. Observable gauges - a callback the SDK invokes on its own -# collection cycle, so a no-provider install never runs them - answer level -# questions no span can, like "am I saturating my SQL threads right now". -# Synchronous histograms/counters are recorded inline on the query path and -# survive trace sampling: 1% of traces still means 100% of the latency -# distribution. Why each metric exists is documented on its registry entry. -# -# Note a real difference from tracing: `_ProxyMeter` and its instruments -# forward to a provider installed *after* they were created, whereas -# `ProxyTracer` permanently caches the concrete tracer it first resolves. So -# module-level instruments here are safe, and tests do not need a provider -# installed before this module is imported. def _duration_attributes(database_name, operation): @@ -434,9 +298,8 @@ def _duration_attributes(database_name, operation): } -# Each instrument passes the SDK a short plain-text description; the registry -# entry for the same metric carries a longer RST one for the generated docs -# (it can use `:ref:` roles, which an exported description string cannot). +# Instruments use plain text descriptions. The registry entries have longer +# reStructuredText descriptions for the documentation. sql_operation_duration = meter.create_histogram( M_OPERATION_DURATION, @@ -457,10 +320,7 @@ write_queue_wait = meter.create_histogram( queries_interrupted = meter.create_counter( M_QUERIES_INTERRUPTED, unit=M_QUERIES_INTERRUPTED.unit, - description=( - "Queries cancelled for exceeding sql_time_limit_ms. Not derivable from " - "spans under sampling, and the signal that a time limit is too tight" - ), + description="Queries cancelled for exceeding sql_time_limit_ms", ) @@ -469,10 +329,8 @@ def record_operation_duration(database_name, operation): """ Record `db.client.operation.duration` for one SQL operation. - `error.type` is set from the exception class on failure, per semconv, so a - latency distribution can be split by success and failure. For a - `block=False` write this measures the enqueue, not the write - the same - caveat that applies to the surrounding span. + Sets `error.type` to the exception class on failure. For a `block=False` + write this measures the time taken to enqueue the write. """ attributes = _duration_attributes(database_name, operation) started = time.perf_counter() @@ -493,17 +351,11 @@ def record_query_interrupted(database_name): queries_interrupted.add(1, {DB_NAMESPACE: database_name}) -# Live Datasette instances, weakly held so that instrumenting an instance -# never keeps it alive. Guarded by a lock because the gauge callbacks run on -# the SDK's collection thread while the event loop may be building or closing -# a Datasette. +# Live Datasette instances reported by the gauges below. The lock is needed +# because gauge callbacks run on the SDK's collection thread. # -# Known limitation: the pool gauges below carry no attribute identifying which -# Datasette produced them, so if a single process runs more than one instance -# their observations collide and last-one-wins. Production runs one instance -# per process; adding an instance id to make the test suite's hundreds of -# instances distinguishable would mean unbounded attribute cardinality in -# exchange for fixing a case that does not occur in production. +# The pool gauges do not identify which instance they came from, so they +# are only meaningful for a process running a single Datasette instance. _live_datasettes = weakref.WeakSet() _live_datasettes_lock = threading.Lock() @@ -526,13 +378,7 @@ def _live_instances(): def _databases_of(ds): - """ - Every Database attached to an instance, including the internal database. - - The internal database is deliberately included: permission checks run SQL - against it on essentially every request, so its queue depth and connection - count are as operationally interesting as any user database's. - """ + "Every Database attached to an instance, including the internal database." databases = list(ds.databases.values()) internal = getattr(ds, "_internal_database", None) if internal is not None: @@ -540,10 +386,6 @@ def _databases_of(ds): return databases -# Each callback is a plain generator function so it can be unit-tested -# directly, without standing up an SDK provider and a metric reader. - - def observe_sql_thread_limit(options=None): "Size of the shared read-query thread pool (the num_sql_threads setting)." for ds in _live_instances(): @@ -557,10 +399,8 @@ def observe_sql_thread_queue_depth(options=None): """ Read queries waiting for a free thread in the shared pool. - This is the saturation signal: sustained above zero means requests are - queueing on num_sql_threads. `_work_queue` is a private attribute of - ThreadPoolExecutor, so its absence is tolerated rather than fatal - a - missing gauge is much better than a crashed collection cycle. + `_work_queue` is a private attribute of ThreadPoolExecutor, so this + reports nothing if it is missing. """ for ds in _live_instances(): if ds.executor is None: @@ -575,11 +415,8 @@ def observe_pending_queries(options=None): """ Read queries submitted to the pool and not yet finished, per database. - Summed across databases and compared against the thread limit, this is the - utilisation half of the saturation picture. `len()` is deliberately taken - without `_pending_execute_futures_lock`: it is atomic, and taking a lock - held on the request path from the collection thread would let telemetry - add latency to queries. + Reads `len()` without `_pending_execute_futures_lock` to avoid blocking + queries. """ for ds in _live_instances(): for db in _databases_of(ds): @@ -589,12 +426,7 @@ def observe_pending_queries(options=None): def observe_write_queue_depth(options=None): - """ - Writes queued behind the single write thread, per database. - - Every database serialises its writes through one thread, so this is - unbounded backpressure that no amount of num_sql_threads will relieve. - """ + "Writes queued behind the single write thread, per database." for ds in _live_instances(): for db in _databases_of(ds): write_queue = db._write_queue diff --git a/datasette/telemetry_registry.py b/datasette/telemetry_registry.py index 02903140..63d5b89b 100644 --- a/datasette/telemetry_registry.py +++ b/datasette/telemetry_registry.py @@ -1,25 +1,9 @@ """ -The single source of truth for every span and span attribute that Datasette -core emits. +Every span, metric and attribute that Datasette emits. -Three things read this module, which is the point of it existing: - -1. **The instrumentation itself.** `Attribute` and `SpanName` subclass `str`, - so a registry entry *is* the string OpenTelemetry wants. Call sites pass - `DB_NAMESPACE` where they used to pass `"db.namespace"` - no wrapper API - over the OTel calls, no parallel structure to keep in step, and a typo is - now an `ImportError` instead of a silently misnamed attribute. - -2. **The documentation.** `docs/telemetry_doc.py` renders the span reference - in `docs/internals.rst` from these definitions using cog, and - `cog --check` runs in CI - so the docs cannot drift from the code. - -3. **A conformance test.** `tests/test_telemetry_registry.py` makes real - requests, collects every span and attribute actually emitted, and compares - both directions: emitted-but-unregistered catches instrumentation added - without documentation, registered-but-never-emitted catches documentation - describing something that no longer exists. Neither the type system nor - the generated docs can catch that second case. +These entries are used by the instrumentation code, by `docs/telemetry_doc.py` +to generate the documentation, and by `tests/test_telemetry_registry.py` to +check that the emitted telemetry matches the registry. """ from opentelemetry.trace import SpanKind @@ -42,26 +26,13 @@ class Attribute(str): self = super().__new__(cls, name) self.description = description self.optional = optional - # A closed enum vocabulary for the attribute's values, or None for - # an open value set. Declaring one does two things: the conformance - # helpers assert every emitted value is a member, and it marks the - # attribute as bounded - safe to use as a metric dimension, where an - # open value set would be a cardinality hazard. + # The allowed values for this attribute, or None to allow any value self.values = frozenset(values) if values is not None else None return self def __reduce__(self): - # Copies and pickles collapse to a plain str. Without this, `copy` has - # to reconstruct a str subclass through `cls.__new__(cls)`, which these - # classes reject - their `__new__` requires the metadata arguments. It - # is not a theoretical problem: the SDK's ConsoleMetricExporter renders - # data points with `dataclasses.asdict()`, which deepcopies mappings, - # and registry entries are used as metric attribute keys - so every - # console metrics dump would crash. Collapsing is also the honest - # answer, not a workaround. On the wire and in a copy an entry *is* - # its string; the description, values and buckets describe the single - # registered instance in this module, and nothing reads them off a - # copy. + # Copies and pickles become a plain str, since __new__ requires the + # extra arguments. ConsoleMetricExporter deepcopies attribute keys. return (str, (str(self),)) def __repr__(self): @@ -88,24 +59,12 @@ class SpanName(str): self = super().__new__(cls, name) self.description = description self.attributes = tuple(attributes) - # True for a span family whose emitted names carry a variable suffix - # after a fixed prefix - e.g. a plugin's `chat {model}` registered as - # SpanName("chat ", ..., prefix=True) - so `span_for()` matches by - # prefix rather than equality. Core registers none itself; the flag - # exists for plugin registries. + # Match emitted names that start with this prefix, for names with a + # variable suffix such as SpanName("chat ", ..., prefix=True) self.prefix = prefix - # True when the emitted name is composed at runtime and shares no - # fixed prefix with the registry entry - the HTTP request span, whose - # name is the request method followed by the matched route. There is - # 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. + # The emitted name is built at runtime, so `span_for()` matches it by + # span kind. The entry's string is a template for the documentation. 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 - # their database styling off this) expect SpanKind.CLIENT. self.kind = kind return self @@ -128,10 +87,7 @@ class MetricName(str): self.unit = unit self.description = description self.attributes = tuple(attributes) - # Explicit histogram bucket boundaries, for histograms only. Passed to - # create_histogram() as explicit_bucket_boundaries_advisory and - # published in the generated docs, since an operator writing a - # histogram_quantile() query needs to know them. + # Explicit bucket boundaries, for histograms only self.buckets = tuple(buckets) if buckets is not None else None return self @@ -150,9 +106,6 @@ GAUGE = "Observable gauge" # --- Attributes ----------------------------------------------------------- -# -# 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", @@ -391,20 +344,10 @@ def span_for(emitted_name, kind=None, spans=None): """ Resolve an emitted span name to its registry entry, or None. - Handles the two entry kinds whose emitted names are not knowable in - advance: + Exact matches take precedence over `prefix=True` entries, which take + precedence over `dynamic=True` entries matched by `kind`. - - `prefix=True` - the name carries a variable suffix after a fixed - prefix, matched by prefix. Core registers none; plugin registries use - it for names like ``chat {model}``. - - `dynamic=True` - the name has no fixed part at all, so it is matched - on `kind` instead and the caller has to supply one. - - Exact matches win over prefix matches, and both win over dynamic, so a - looser entry can never shadow a span with a registered name. - - `spans` defaults to core's own registry; the plugin testing kit passes a - plugin's tuple instead. + `spans` defaults to Datasette's own registry. """ if spans is None: spans = SPANS @@ -427,9 +370,7 @@ def metric_for(emitted_name, metrics=None): """ Resolve an emitted metric name to its registry entry, or None. - The `span_for()` analogue - simpler, because metric names are always - static strings. `metrics` defaults to core's own registry; the plugin - testing kit passes a plugin's tuple instead. + `metrics` defaults to Datasette's own registry. """ if metrics is None: metrics = METRICS @@ -455,11 +396,7 @@ def attribute_value_allowed(entry, emitted_key, value): Whether `value` is permitted for `emitted_key` on `entry` (a `SpanName` or a `MetricName`). - True for any value when the attribute declares no `values=` enum; when it - does, membership is enforced - that is what makes a declared enum a real - cardinality bound rather than documentation. On a metric entry this is - where the bound matters most: a metric series is keyed by its attribute - values. + Any value is allowed if the attribute does not declare `values=`. """ if entry is None: return False @@ -471,22 +408,11 @@ def attribute_value_allowed(entry, emitted_key, value): # --- Metrics -------------------------------------------------------------- -# Every duration histogram here is in seconds, and OpenTelemetry's default -# bucket boundaries are tuned for milliseconds - their first non-zero boundary -# is 5, so without explicit boundaries every SQLite query lands in the single -# (0, 5] second bucket and every quantile query returns noise. -# -# These are the OpenTelemetry semantic conventions' recommended boundaries for -# db.client.operation.duration, in seconds, plus 0.0001 and 0.0005 at the -# bottom. The deviation is deliberate: those boundaries assume a network -# database client, whereas SQLite is in-process and a large fraction of real -# queries run in 30-80us, which would otherwise all pile into the first -# bucket and be indistinguishable from each other. -# -# One shared list is used for every duration histogram rather than a tailored -# list each, so that dashboards stay comparable and a queue wait can be read -# against the query duration it delays. It already spans 100us to 10s, which -# covers both a fast in-process read and a write queued behind contention. +# Bucket boundaries in seconds for every duration histogram. OpenTelemetry's +# defaults are designed for milliseconds and would put almost every SQLite +# query in the first bucket. These are the semantic conventions' recommended +# boundaries for db.client.operation.duration, plus 0.0001 and 0.0005 for +# fast in-process SQLite queries. DURATION_BUCKETS = (0.0001, 0.0005, 0.001, 0.005, 0.01, 0.05, 0.1, 0.5, 1, 5, 10) M_OPERATION_DURATION = MetricName( diff --git a/datasette/telemetry_testing.py b/datasette/telemetry_testing.py index 86cb5641..77a4431b 100644 --- a/datasette/telemetry_testing.py +++ b/datasette/telemetry_testing.py @@ -13,17 +13,9 @@ Usage from a plugin's ``conftest.py``:: otel_spans, ) -Importing the fixture names into a conftest registers them; ``otel_provider`` -and ``otel_meter_provider`` are session-scoped and autouse, so a real SDK -provider (when the SDK is installed) is in place before any test emits a -signal. Tests then take ``otel_spans`` / ``otel_metrics``. Everything here -imports the OpenTelemetry SDK lazily: with no SDK installed the fixtures -skip rather than fail, and importing this module costs nothing. - -The conformance helpers (`assert_spans_conform`, `assert_spans_covered`) -check a registry of `SpanName` entries against actually-finished spans in -both directions - emitted-but-unregistered and registered-but-never-emitted, -the two drift modes documented in `tests/test_telemetry_registry.py`. +Tests can then use the ``otel_spans`` and ``otel_metrics`` fixtures. The +OpenTelemetry SDK is imported lazily, and the fixtures skip if it is not +installed. """ import subprocess @@ -47,11 +39,7 @@ def install_span_exporter(): Install a TracerProvider + InMemorySpanExporter once per process and return the exporter, or None when the SDK is not installed. - `set_tracer_provider()` is effectively once-per-process (a second call - logs a warning and is ignored), so this must run before anything asserts - on spans. A `SimpleSpanProcessor` exports synchronously on span end - no - background batching thread, so assertions immediately after a request - never race. + Uses `SimpleSpanProcessor` so spans are exported as soon as they end. """ global _span_exporter if _span_exporter is not None: @@ -69,12 +57,8 @@ def install_span_exporter(): provider = TracerProvider() provider.add_span_processor(SimpleSpanProcessor(exporter)) otel_trace.set_tracer_provider(provider) - # set_tracer_provider() is once-per-process: if something else installed - # a provider first (another conftest, opentelemetry-instrument, an - # embedding app), the call above was silently ignored - and an exporter - # wired to nothing would make every span assertion fail confusingly, or - # pass vacuously on empty input. Leave the global unset in that case so - # the fixtures skip with a clear message instead. + # set_tracer_provider() is ignored if a provider was already installed, + # in which case the fixtures skip if otel_trace.get_tracer_provider() is not provider: return None _span_exporter = exporter @@ -86,10 +70,8 @@ def install_metric_reader(): Install a MeterProvider + InMemoryMetricReader once per process and return the reader, or None when the SDK is not installed. - DELTA temporality for counters and histograms, so each collection - reports only what happened since the previous one - with the SDK default - of CUMULATIVE, every metrics test would see every measurement from every - earlier test in the session. + Uses delta temporality for counters and histograms, so each collection + only reports measurements since the previous one. """ global _metric_reader if _metric_reader is not None: @@ -111,8 +93,6 @@ def install_metric_reader(): ) provider = MeterProvider(metric_readers=[reader]) otel_metrics_api.set_meter_provider(provider) - # Same once-per-process guard as the tracer side: a provider that did - # not take must not leave a reader that collects nothing. if otel_metrics_api.get_meter_provider() is not provider: return None _metric_reader = reader @@ -121,44 +101,19 @@ def install_metric_reader(): @pytest.fixture(scope="session", autouse=True) def otel_provider(): - """ - Session-scoped, autouse: install the span exporter exactly once, before - any span is created. - - `datasette.telemetry.tracer` (and a plugin's own tracer) is a - module-level `ProxyTracer`: once a provider exists, the first span it - starts resolves a concrete tracer and caches it permanently. It does - *not* cache the no-op tracer, so a span started before this fixture runs - is merely lost rather than poisoning the tracer for the process. With no - SDK installed this does nothing and spans stay no-op. - """ + "Install the span exporter once per test session, before any spans are created." install_span_exporter() @pytest.fixture(scope="session", autouse=True) def otel_meter_provider(): - """ - Session-scoped, autouse: install the metric reader once per process. - - Unlike the tracer, ordering is not load-bearing - `_ProxyMeter` and its - instruments forward to a provider installed after they were created. - Still autouse for symmetry, and so a single reader collects all run. - """ + "Install the metric reader once per test session." install_metric_reader() @pytest.fixture(autouse=True) def otel_reset(): - """ - Autouse, function-scoped: drain the span exporter and metric reader - after every test - including the ones that never look at telemetry. - - Without this, every test that exercises the app leaves its recorded - spans in the session-scoped exporter's list forever: a large suite - accumulates hundreds of thousands of ReadableSpans, degrading memory - and per-span export cost as the run goes on. Draining the metric reader - likewise stops delta state piling up between metric tests. - """ + "Clear recorded spans and drain collected metrics after every test." yield if _span_exporter is not None: _span_exporter.clear() @@ -169,9 +124,8 @@ def otel_reset(): @pytest.fixture def otel_spans(): """ - Function-scoped access to the finished-spans exporter: clears spans left - over from previous tests, then yields the exporter so a test can call - `.get_finished_spans()`. Skips if the OTel SDK is not installed. + The in-memory span exporter, cleared before the test. Call + `.get_finished_spans()` to retrieve spans. """ pytest.importorskip("opentelemetry.sdk") exporter = install_span_exporter() @@ -183,21 +137,16 @@ def otel_spans(): class MetricsCollector: """ - Thin reader over an `InMemoryMetricReader`. + Wraps an `InMemoryMetricReader`. - `collect()` runs a collection cycle - which is what invokes observable - gauge callbacks - and snapshots the result. Queries then run against - that snapshot rather than re-collecting, so a test that inspects - several metrics sees one consistent moment and does not drain delta - state twice. + `collect()` runs a collection cycle and stores a snapshot, which + `points()` and `point()` then query. """ def __init__(self, reader): self.reader = reader self.snapshot = {} - # (instrumentation scope name, sdk Metric) pairs from the last - # collect() - the metric conformance helpers read this, because the - # name-keyed snapshot deliberately flattens the scope away. + # (instrumentation scope name, sdk Metric) pairs from the last collect() self.collected = [] def collect(self): @@ -237,10 +186,7 @@ class MetricsCollector: @pytest.fixture def otel_metrics(): - """ - Function-scoped metrics collector. Drains delta state accumulated by - earlier tests before yielding, so counts start from zero. - """ + "A `MetricsCollector`, drained before the test so counts start from zero." pytest.importorskip("opentelemetry.sdk") reader = install_metric_reader() if reader is None: @@ -261,11 +207,10 @@ def _scoped(finished_spans, scope_name): def assert_spans_conform(registry_spans, finished_spans, scope_name=None): """ - Every finished span (optionally: only those from `scope_name`, which is - what a plugin should pass - its own tracer's name) resolves to an entry - in `registry_spans`, sets only registered attributes, and respects any - declared `values=` enums. This is the emitted-but-unregistered direction: - instrumentation added without documentation fails here. + Assert every finished span is registered in `registry_spans`, sets only + registered attributes and uses allowed attribute values. + + Pass `scope_name` to only check spans from that instrumentation scope. """ problems = [] for span in _scoped(finished_spans, scope_name): @@ -285,14 +230,8 @@ def assert_spans_conform(registry_spans, finished_spans, scope_name=None): def assert_spans_covered(registry_spans, finished_spans, scope_name=None): """ - Every entry in `registry_spans` was emitted at least once, and every one - of its registered non-`optional` attributes appeared on it at least - once. This is the registered-but-never-emitted direction - documentation - describing a signal that no longer exists, which is worse than omitting - it because a reader will build a dashboard on it. Run it against a - workload broad enough to exercise everything the registry claims; - `optional=True` attributes are exempt so a workload is not forced to - manufacture every error path (pin those with targeted tests instead). + Assert every entry in `registry_spans` was emitted at least once, with + each of its attributes that is not `optional=True`. """ spans = _scoped(finished_spans, scope_name) seen_attributes = {} @@ -318,9 +257,7 @@ def assert_spans_covered(registry_spans, finished_spans, scope_name=None): # Registry instrument kinds mapped to the SDK data type collected for them. -# A registry kind outside this table (a plugin's own vocabulary) is not -# kind-checked. Both counter kinds collect as Sum; monotonicity is what -# tells them apart, checked separately below. +# Both counter kinds collect as Sum, distinguished by is_monotonic. _KIND_TO_DATA_TYPE = { "Counter": "Sum", "UpDownCounter": "Sum", @@ -338,15 +275,11 @@ def _scoped_metrics(collector, scope_name): def assert_metrics_conform(registry_metrics, collector, scope_name=None): """ - Every metric in the collector's last `collect()` (optionally: only those - from `scope_name`, which is what a plugin should pass - its own meter's - name) is registered in `registry_metrics`, was created as the instrument - kind and unit the registry declares, sets only registered attributes, - and respects any declared `values=` enums. + Assert every metric in the collector's last `collect()` is registered in + `registry_metrics` with a matching instrument kind and unit, sets only + registered attributes and uses allowed attribute values. - The kind and unit checks catch a drift nothing else does: the registry - entry and the `meter.create_*()` call are separate statements, and a - dashboard built on the registry's word breaks silently if they disagree. + Pass `scope_name` to only check metrics from that instrumentation scope. """ problems = set() for metric in _scoped_metrics(collector, scope_name): @@ -390,14 +323,10 @@ def assert_metrics_conform(registry_metrics, collector, scope_name=None): def assert_metrics_covered(registry_metrics, collector, scope_name=None): """ - Every entry in `registry_metrics` was collected at least once, and every - registered non-`optional` attribute appeared on it at least once - the - registered-but-never-emitted direction for metrics. + Assert every entry in `registry_metrics` was collected at least once, + with each of its attributes that is not `optional=True`. - Run one broad workload, then a single `collect()`, then this: the reader - uses delta temporality, so measurements drained by an earlier collect() - are gone. `optional=True` attributes (e.g. an `error.type` only present - on failures) are exempt, same as the span-side helper. + Call `collect()` once after the workload and before this check. """ seen_attributes = {} for metric in _scoped_metrics(collector, scope_name): @@ -431,11 +360,8 @@ def assert_no_forbidden_values( emitted telemetry: span names, span attribute values, span event names and attributes, span status descriptions, or metric point attributes. - This is the enforcement half of the privacy rules in the plugin - telemetry documentation. The strongest way to use it is to *plant* - sentinel values in your test workload - a fake email address, a token, - a username your fixtures log in with - and assert they never leak into - a signal: + Use fake private values such as tokens or email addresses in your test + workload, then check that they were not recorded: FORBIDDEN = {"secret-token-123", "alice@example.com"} run_workload_using_those_values() @@ -443,14 +369,11 @@ def assert_no_forbidden_values( FORBIDDEN, finished_spans=otel_spans.get_finished_spans(), collector=otel_metrics, - scope_name="my_plugin", ) - Matching is plain substring on the string form of each value; empty - strings in `forbidden` are ignored. Pass `finished_spans` and/or a - collected `MetricsCollector`; `scope_name=None` checks every scope, - which is the right default here - a leak through *core's* signals (e.g. - SQL text carrying a secret) is still a leak. + Matches substrings of each value's string form. Empty strings in + `forbidden` are ignored. Leave `scope_name` unset to also check + Datasette's own telemetry. """ needles = [needle for needle in forbidden if needle] leaks = set() @@ -485,15 +408,10 @@ def assert_no_forbidden_values( def assert_package_never_imports_sdk(*module_names): """ Import the named modules in a fresh interpreter and assert none of them - dragged in `opentelemetry.sdk`. Checked via sys.modules in a subprocess - rather than by grepping, so a lazy `import opentelemetry.sdk` inside a - function body cannot slip past. A plugin should depend on - `opentelemetry-api` only, exactly as Datasette core does. + imported `opentelemetry.sdk`. - Run the test that calls this early in your suite: on macOS/CPython 3.13 - a process that has accumulated many threads can crash (SIGBUS) in - subprocess's fork+exec - Datasette's own conftest front-loads its - equivalent tests by name for exactly this reason. + Run the test that calls this early in your suite: on macOS with CPython + 3.13, starting a subprocess from a process with many threads can crash. """ imports = "; ".join(f"import {name}" for name in module_names) code = ( diff --git a/docs/plugin_telemetry.rst b/docs/plugin_telemetry.rst index fc6965f5..e4c7381d 100644 --- a/docs/plugin_telemetry.rst +++ b/docs/plugin_telemetry.rst @@ -5,8 +5,6 @@ Telemetry for plugin authors Datasette core emits OpenTelemetry spans and metrics for the work it does itself - see :ref:`internals_telemetry` for what those are and how an operator turns them on. This page is about the other half: instrumenting the work **your plugin** does, so that a plugin's queries, background jobs and custom operations show up in the same traces and the same metrics pipeline, using the same conventions. -Depend on ``opentelemetry-api`` only. Providers and exporters are configured by whoever runs Datasette. Without a provider, no telemetry is recorded. - .. _plugin_telemetry_scope: Use your own instrumentation scope diff --git a/docs/telemetry_doc.py b/docs/telemetry_doc.py index e08a2b45..9c4086ae 100644 --- a/docs/telemetry_doc.py +++ b/docs/telemetry_doc.py @@ -1,10 +1,6 @@ """ -Render the span reference in ``internals.rst`` from -``datasette/telemetry_registry.py``. - -Driven by cog, and ``cog --check docs/*.rst`` runs in CI - so adding a span -without documenting it, or documenting one that no longer exists, is a build -failure rather than something a reader discovers later. +Cog helpers that render the span and metric reference in ``internals.rst`` +from ``datasette/telemetry_registry.py``. """ @@ -32,9 +28,7 @@ def spans(cog): for span in SPANS: cog.out(f"``{span}``\n") cog.out(f" {span.description}\n\n") - # INTERNAL is the default and the overwhelming majority of spans - - # printing it on every one would be noise. Only the exceptional case, - # a real database call, is worth calling out. + # Only show the kind for spans that are not INTERNAL if span.kind != SpanKind.INTERNAL: cog.out(f" Kind: ``{span.kind.name}``.\n\n") _attribute_lines(cog, span.attributes) diff --git a/tests/conftest.py b/tests/conftest.py index 7222fdfa..5fdbd51d 100644 --- a/tests/conftest.py +++ b/tests/conftest.py @@ -58,8 +58,6 @@ def find_free_port(): return sock.getsockname()[1] -# The otel fixtures moved to datasette.telemetry_testing, which is public -# plugin API - core's suite consumes it exactly the way a plugin's would. from datasette.telemetry_testing import ( # noqa: F401 MetricsCollector, otel_meter_provider, @@ -183,11 +181,8 @@ def pytest_collection_modifyitems(config, items): move_to_front(items, "test_spatialite_error_if_attempt_to_open_spatialite") move_to_front(items, "test_package") move_to_front(items, "test_package_with_port") - # Same reason: this one shells out to a fresh interpreter. Late in a serial - # run the pytest process holds enough threads that the fork half of - # subprocess' fork+exec crashes the interpreter on macOS/CPython 3.13 - # (SIGSEGV/SIGBUS inside _execute_child). Reproduces with any subprocess - # call placed there, on an unmodified tree - running it first avoids it. + # These start subprocesses, which can crash on macOS/CPython 3.13 late in + # a test run once the pytest process has started many threads move_to_front(items, "test_datasette_package_never_imports_the_sdk") move_to_front(items, "test_kit_module_itself_never_imports_the_sdk") move_to_front(items, "test_no_provider_takes_the_fast_path") diff --git a/tests/test_http_span.py b/tests/test_http_span.py index a3853199..1fcc93b0 100644 --- a/tests/test_http_span.py +++ b/tests/test_http_span.py @@ -1,23 +1,6 @@ """ -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 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. +Tests for the HTTP request span created by TelemetryMiddleware and the +`http.route` enrichment added by the router. """ import asyncio @@ -51,9 +34,8 @@ from datasette.telemetry import ( ) 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` -# fails. +# Named in-memory databases are shared between instances, so each fixture +# needs a unique name. _names = itertools.count() @@ -61,7 +43,7 @@ PLUGIN_MIDDLEWARE_SPAN = "test.plugin.middleware" class _MiddlewarePlugin: - "A plugin asgi_wrapper() that creates a span, standing in for a real one." + "A plugin asgi_wrapper() that creates a span." __name__ = "HttpSpanMiddlewarePlugin" @@ -79,11 +61,8 @@ class _MiddlewarePlugin: 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. + A plugin asgi_wrapper() that raises. `route_path` turns most exceptions + into a 500, so this is how an exception reaches the request span. """ __name__ = "HttpSpanRaisingMiddlewarePlugin" @@ -135,18 +114,12 @@ async def ds(): @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. + An instance whose table is bigger than `max_returned_rows`, so a + `?_stream=1` export runs queries for later pages during the body send. """ 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. + # Both settings are needed: lowering only max_returned_rows gives a + # single page with no `next` token. instance = Datasette( memory=True, settings={"max_returned_rows": 5, "default_page_size": 3} ) @@ -182,13 +155,8 @@ 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. + Spans created by plugin asgi_wrapper() middleware are children of the + request span. """ ds.pm.register(_MiddlewarePlugin(), name="httpspan-middleware") try: @@ -210,7 +178,7 @@ async def test_plugin_asgi_wrapper_middleware_runs_inside_the_request_span( 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. + # Database spans are in the same trace. 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: @@ -220,15 +188,8 @@ async def test_plugin_asgi_wrapper_middleware_runs_inside_the_request_span( @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`. - - 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. + Unknown methods are recorded as `_OTHER` in both the attribute and the + span name, which the router rebuilds from the raw `request.method`. """ otel_spans.clear() await ds.client.request("FROB", f"/{ds.db_name}/t") @@ -240,7 +201,7 @@ async def test_unrecognised_method_is_clamped(ds, otel_spans): @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." + "Known methods are recorded unchanged." otel_spans.clear() await ds.client.get(f"/{ds.db_name}/t") server = _server_spans(otel_spans) @@ -251,12 +212,7 @@ async def test_known_method_is_not_clamped(ds, otel_spans): @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. - """ + "No attribute on any span contains the query string." marker = "canary-9f2b1c" otel_spans.clear() await ds.client.get(f"/{ds.db_name}/t?_facet=v&_nosuch={marker}") @@ -283,9 +239,8 @@ async def test_url_path_is_recorded_without_the_query_string(ds, otel_spans): @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. + An exception that escapes `route_path` is recorded and re-raised. No + response started, so no status code is recorded. """ ds.pm.register( _RaisingMiddlewarePlugin(call_app_first=False), name="httpspan-raiser" @@ -308,11 +263,8 @@ 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. + A 500 response followed by an exception records the exception class as + `error.type`, not "500". """ ds.pm.register(_BoomPlugin(), name="httpspan-boom") ds.pm.register( @@ -327,24 +279,16 @@ async def test_an_escaping_exception_beats_the_status_code_for_error_type( 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. - - 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. + A 4xx records the status code but no `error.type` or error status. + `/no-such-database-at-all` matches the database route, so `http.route` + is still set. """ otel_spans.clear() response = await ds.client.get("/no-such-database-at-all") @@ -354,7 +298,6 @@ async def test_a_404_is_not_an_error(ds, otel_spans): 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 - # Route enrichment must not be gated on a successful response. assert "http.route" in server[0].attributes assert server[0].name != "GET" @@ -362,14 +305,8 @@ async def test_a_404_is_not_an_error(ds, otel_spans): @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. + With no matching route the span keeps the bare method name. Most missing + paths still match a route, so this uses a path deeper than any route. """ otel_spans.clear() response = await ds.client.get("/a/b/c/d/e") @@ -384,14 +321,7 @@ async def test_an_unrouted_404_has_no_route_and_a_bare_method_name(ds, otel_span @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. - """ + "The `send` wrapper records the status from the first `http.response.start`." async def two_starts(scope, receive, send): await send({"type": "http.response.start", "status": 200, "headers": []}) @@ -418,10 +348,8 @@ async def test_only_the_first_http_response_start_is_recorded(otel_spans): @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. + Lifespan scopes reach `AsgiLifespan`, which sits inside this middleware, + without creating a SERVER span. """ instance = Datasette(memory=True) app = instance.app() @@ -442,13 +370,7 @@ async def test_lifespan_scope_passes_through_unspanned(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. - """ + "`http.route` is the compiled regex of the route Datasette's router resolves." path = f"/{ds.db_name}/t" expected = _route_for(ds, path) otel_spans.clear() @@ -457,9 +379,7 @@ async def test_http_route_is_the_compiled_pattern(ds, 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. + # The raw pattern, not a prettified template: assert "(?P" in expected @@ -469,16 +389,8 @@ async def test_the_route_lands_on_the_request_span_not_a_plugins_current_span( ): """ 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. + ASGI scope, not on a plugin `asgi_wrapper()` span that is current during + routing. """ ds.pm.register(_MiddlewarePlugin(), name="httpspan-middleware") try: @@ -494,7 +406,7 @@ async def test_the_route_lands_on_the_request_span_not_a_plugins_current_span( 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. + # The plugin's span keeps its name and has 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 {}) @@ -502,7 +414,7 @@ async def test_the_route_lands_on_the_request_span_not_a_plugins_current_span( @pytest.mark.asyncio async def test_request_span_attributes(ds, otel_spans): - "The whole attribute set on one ordinary request." + "The attributes recorded for an ordinary request." path = f"/{ds.db_name}/t" otel_spans.clear() assert (await ds.client.get(path)).status_code == 200 @@ -515,8 +427,7 @@ async def test_request_span_attributes(ds, otel_spans): 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. + # The client IP address and query string are not recorded. assert "client.address" not in attributes assert "url.query" not in attributes @@ -524,12 +435,8 @@ async def test_request_span_attributes(ds, otel_spans): @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. + Every `db.query` span descends from the request span, which is the only + root span. """ otel_spans.clear() assert (await ds.client.get(f"/{ds.db_name}/t?_facet=v")).status_code == 200 @@ -550,7 +457,7 @@ async def test_db_query_spans_are_children_of_the_request_span(ds, otel_spans): 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. + # Walk up to the root, which should be the request span. current = query seen = 0 while current.parent is not None: @@ -563,9 +470,8 @@ async def test_db_query_spans_are_children_of_the_request_span(ds, otel_spans): @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. + `route_path` turns the exception into a 500 response, so `error.type` is + the status code as a string. """ ds.pm.register(_BoomPlugin(), name="httpspan-boom") try: @@ -584,25 +490,11 @@ async def test_500_sets_error_status_and_error_type(ds, otel_spans): @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. + The request span covers a streamed CSV body, including queries for later + pages that run after the response has started. - `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. + Driven as raw ASGI to timestamp `http.response.start` with `time.time_ns()`, + the clock the SDK uses for spans. """ app = ds_paging.app() body = [] @@ -634,7 +526,7 @@ async def test_csv_stream_span_covers_the_body_send(ds_paging, otel_spans): receive, send, ) - # 40 rows plus a header - the export really did read past one page + # 40 rows plus a header, so the export read past the first page assert len(b"".join(body).decode("utf-8").strip().splitlines()) == 41 assert response_started_at is not None @@ -662,12 +554,8 @@ async def test_csv_stream_span_covers_the_body_send(ds_paging, otel_spans): @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. + An inbound `traceparent` header continues the caller's trace. It uses the + sampled flag (`-01`) because the SDK's default sampler is parent-based. """ trace_id = "4bf92f3577b34da6a3ce929d0e0e4736" parent_span_id = "00f067aa0ba902b7" @@ -684,7 +572,7 @@ async def test_inbound_traceparent_becomes_the_parent(ds, otel_spans): 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. + # Database spans are in the caller's trace too. queries = [ span for span in otel_spans.get_finished_spans() if span.name == "db.query" ] @@ -696,20 +584,12 @@ async def test_inbound_traceparent_becomes_the_parent(ds, otel_spans): @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. + SQL from `?sql=` is not recorded on the request span or in any `url.*` + or `http.*` attribute. `db.query.text` is expected to contain it. """ 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. + # `/{db}?sql=` redirects to the query view, so request that directly. response = await ds.client.get(f"/{ds.db_name}/-/query?sql=select+'{marker}'") assert response.status_code == 200 spans = otel_spans.get_finished_spans() @@ -723,26 +603,15 @@ async def test_user_supplied_sql_in_the_query_string_is_never_recorded(ds, otel_ 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. + # Confirm the query ran with the marker. 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. + `request_span()` returns None for a `NonRecordingSpan` with a valid remote + span context, which is what an inbound `traceparent` produces with no + provider installed. """ remote = SpanContext( trace_id=0x4BF92F3577B34DA6A3CE929D0E0E4736, @@ -754,13 +623,13 @@ def test_request_span_skips_a_valid_but_non_recording_span(): 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. + # No span in the scope and no current span: assert request_span({}) is None - # And the case it must not skip. + # A recording span is returned: 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. + # Falls back to the current span, such as one created by another + # SERVER instrumentation: assert request_span({}) is span @@ -820,26 +689,11 @@ NO_PROVIDER_PROGRAM = textwrap.dedent(""" 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. + With no `TracerProvider` installed the middleware passes the original + `send` to the application, including for requests with a `traceparent`. - 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. + Runs in a subprocess because the suite installs a provider for the whole + process. conftest.py moves this test to the front of the run by name. """ result = subprocess.run( [sys.executable, "-c", NO_PROVIDER_PROGRAM], @@ -854,19 +708,15 @@ def test_no_provider_takes_the_fast_path(): "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. + # Nothing is stored in the scope either. assert report["scope_keys"] == [False, False] @pytest.mark.asyncio async def test_internal_client_requests_are_marked(ds, otel_spans): """ - An in-process `datasette.client` request runs the full ASGI stack, so it - emits its own SERVER span - `datasette.internal_client` marks those so - kind-based dashboards can filter the double-count out. A request that - arrives through the raw ASGI app (the shape of a real inbound request, - without the DatasetteClient wrapper setting the ContextVar) must not - carry the attribute. + `datasette.internal_client` is set on SERVER spans for `datasette.client` + requests, but not for requests made directly to the ASGI app. """ otel_spans.clear() assert (await ds.client.get("/")).status_code == 200 diff --git a/tests/test_internals_database.py b/tests/test_internals_database.py index dcb13f9e..9398afb9 100644 --- a/tests/test_internals_database.py +++ b/tests/test_internals_database.py @@ -1329,27 +1329,11 @@ async def test_write_thread_context_is_detached_between_tasks( tmp_path, monkeypatch, num_sql_threads ): """ - The write thread attaches each task's otel Context and must detach it - again before picking up the next task. The thread is persistent and - shared, so a leaked token would grow that thread's context stack for the - rest of the process - and a *wrong*-token detach only logs a warning - rather than raising, so "does it throw" cannot catch either mistake. + The write thread attaches each task's OpenTelemetry context and detaches + it before the next task, including when the task raises an exception. - Two things are asserted, because neither alone is sufficient: - - 1. Each task observes the context value that was current on the event - loop when it was queued. This is what fails if the Context is not - carried on WriteTask, or is never attached. It does *not* catch a - missing detach: attach() replaces the current Context wholesale, so a - leftover one from a previous task is simply overwritten. - 2. The write thread's attach depth is identical at the same point in - every task. This is what fails if detach is missing - the stack grows - by one per task - and it holds across a task that raises, because the - detach lives in a `finally`. - - An otel context value is used rather than a plain contextvars.ContextVar: - a plain var set on the event loop never crosses into the write thread, so - the probe would read None every time and the test could not fail. + Checks that each task sees the context from when it was queued, and that + the write thread's attach depth does not grow between tasks. """ name = f"context_leak_test_{num_sql_threads}" db_path = tmp_path / f"{name}.db" @@ -1374,8 +1358,7 @@ async def test_write_thread_context_is_detached_between_tasks( if threading.current_thread().name == write_thread_name: depth["value"] -= 1 - # Patched on the opentelemetry.context module itself, which is what both - # database.py and opentelemetry.trace.use_span() look the functions up on. + # database.py and opentelemetry.trace both call these via the module monkeypatch.setattr(otel_context_api, "attach", counting_attach) monkeypatch.setattr(otel_context_api, "detach", counting_detach) @@ -1388,8 +1371,6 @@ async def test_write_thread_context_is_detached_between_tasks( def failing_probe(conn): probe(conn) - # Exercises the write thread's exception path: the detach still has - # to happen, which is why it lives in a `finally`. raise ValueError("deliberate failure inside a write task") try: @@ -1405,9 +1386,7 @@ async def test_write_thread_context_is_detached_between_tasks( finally: real_detach(token) - # Sanity check: no marker is active in *this* (event loop) context - # right now, so the final probe is a fair test of the write thread's - # own state rather than something this test forgot to clean up. + # No marker is set here, so the final probe should see None assert otel_context_api.get_value(_CONTEXT_LEAK_MARKER_KEY) is None await db.execute_write_fn(probe) finally: diff --git a/tests/test_telemetry.py b/tests/test_telemetry.py index f1b2b06b..801876df 100644 --- a/tests/test_telemetry.py +++ b/tests/test_telemetry.py @@ -26,8 +26,8 @@ SECRET_PARAM_VALUE = "SUPER_SECRET_PARAM_VALUE_XYZ_123" INVALID_SQL = "select this_is_not_valid_sql from nowhere" -# Bounded so a broken time limit fails the test instead of hanging it, but far -# too long to finish inside any of the millisecond budgets used below. +# Bounded so a broken time limit fails rather than hangs, but too slow to +# finish within the millisecond time limits used below. SLOW_SQL = """ with recursive counter(x) as ( select 1 union all select x + 1 from counter where x < 50000000 @@ -41,13 +41,7 @@ def _db_query_spans(otel_spans): def _spans_for_namespace(otel_spans, namespace): - """ - db.query spans belonging to one database. - - Datasette queries its internal catalog constantly - including while a - Datasette instance is being constructed - so a test that just grabbed - every db.query span would be reading someone else's traffic. - """ + "db.query spans for one database, excluding queries against the internal database." return [ span for span in _db_query_spans(otel_spans) @@ -56,14 +50,7 @@ def _spans_for_namespace(otel_spans, namespace): def _children_named(otel_spans, name, parent_span_context): - """ - Finished spans called `name` whose parent really is `parent_span_context`. - - Parentage is matched on span id, not on "a span with this name exists" - - a span can exist and still be an unparented root if a thread boundary - dropped the otel context, which is the exact failure these tests exist - to catch. - """ + "Finished spans called `name` that are direct children of `parent_span_context`." return [ span for span in otel_spans.get_finished_spans() @@ -76,12 +63,7 @@ def _children_named(otel_spans, name, parent_span_context): def _descends_from(span, ancestor_span_context, by_span_id): - """ - True if `span` reaches `ancestor_span_context` by walking parent links. - - Walks real span ids rather than trusting a shared trace id: a span can - carry the right trace id and still hang off the wrong parent. - """ + "True if `span` reaches `ancestor_span_context` by walking parent links." seen = set() current = span while current.parent is not None: @@ -97,7 +79,7 @@ def _descends_from(span, ancestor_span_context, by_span_id): def _all_attribute_values(otel_spans): - "Every attribute value across every finished span, for the 'no leaked param values' test." + "Every attribute value on every finished span and span event." values = [] for span in otel_spans.get_finished_spans(): values.extend((span.attributes or {}).values()) @@ -108,14 +90,9 @@ def _all_attribute_values(otel_spans): def test_datasette_package_never_imports_the_sdk(): """ - Core depends on opentelemetry-api only. The SDK is a test dependency. + Importing datasette does not load the OpenTelemetry SDK. - Checked by importing datasette in a fresh process and inspecting - sys.modules, rather than by grepping, so a lazy `import - opentelemetry.sdk` inside a function body cannot slip past. - - 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. + conftest.py moves this test to the front of the run by name. """ code = ( "import datasette.app, datasette.database, datasette.telemetry, sys; " @@ -149,13 +126,7 @@ async def test_db_query_span_basic_attributes(ds_client, otel_spans): @pytest.mark.asyncio async def test_truncated_result_sets_truncated_attribute(otel_spans): - """ - A result actually cut short by max_returned_rows records truncated=True. - - Every other test asserts the attribute is False, so a regression that - recorded the flag before the slice (or inverted it) would pass the rest - of the suite. - """ + "A result cut short by max_returned_rows records truncated=True." ds = Datasette(memory=True, settings={"max_returned_rows": 5}) db = ds.add_memory_database("t04_truncated") results = await db.execute( @@ -178,8 +149,7 @@ async def test_facetable_request_produces_db_query_spans(ds_client, otel_spans): spans = _db_query_spans(otel_spans) assert spans, "expected at least one db.query span" assert all(span.attributes["db.system"] == "sqlite" for span in spans) - # Every db.query names what ran: SQL text for the string methods, - # datasette.callback for callback-style calls (schema introspection here). + # Each span records the SQL or, for callback methods, the callback name: assert all( span.attributes.get("db.query.text") or span.attributes.get("datasette.callback") @@ -194,8 +164,7 @@ async def test_facetable_request_produces_db_query_spans(ds_client, otel_spans): def test_sql_attribute_truncates_at_2048(): short_sql = "select 1" assert sql_attribute(short_sql) == "select 1" - # Whitespace is stripped, so the same query logged twice with different - # surrounding whitespace produces one attribute value, not two. + # Surrounding whitespace is stripped: assert sql_attribute(" select 1\n") == "select 1" long_sql = "select 1 -- " + ("x" * 3000) @@ -207,8 +176,7 @@ def test_sql_attribute_truncates_at_2048(): @pytest.mark.asyncio async def test_db_query_text_is_truncated_in_real_span(ds_client, otel_spans): - # A long trailing SQL comment keeps the query valid and executable while - # pushing db.query.text well past the 2048 char cap. + # A long trailing comment keeps the SQL valid but over the 2048 character limit long_sql = "select 1 -- " + ("x" * 3000) response = await ds_client.get("/fixtures/-/query.json", params={"sql": long_sql}) assert response.status_code == 200 @@ -231,8 +199,7 @@ async def test_no_span_attribute_ever_contains_a_parameter_value(ds_client, otel params={"sql": "select :secret", "secret": SECRET_PARAM_VALUE}, ) assert response.status_code == 200 - # Sanity check the value really did flow through as a bound parameter, - # not inlined into the SQL text, otherwise this test would be vacuous. + # Confirm the bound parameter value was used by the query: assert SECRET_PARAM_VALUE in json.dumps(response.json()) for value in _all_attribute_values(otel_spans): @@ -253,13 +220,10 @@ async def test_no_span_attribute_ever_contains_a_parameter_value(ds_client, otel @pytest.mark.asyncio async def test_query_interrupted_sets_error_status(otel_spans): """ - A query that runs out the instance-wide sql_time_limit_ms is an error. + A query that exceeds the sql_time_limit_ms setting is a span error. - This used to force the timeout with `?_timelimit=5`, but a caller-supplied - budget shorter than the instance limit is now the signal that the timeout - was expected - see test_expected_timeout_is_not_a_span_error - so the - timeout has to come from the setting for this to still test what it was - written to test. + The limit comes from the setting because a shorter custom_time_limit + marks the timeout as expected. """ ds = Datasette(memory=True, settings={"sql_time_limit_ms": 20}) db = ds.add_memory_database("t09_instance_limit_timeout") @@ -276,23 +240,14 @@ async def test_query_interrupted_sets_error_status(otel_spans): async def _expected_timeout_count_span(otel_spans, database_name): - """ - Drive the real table_counts() path into a timeout; return its db.query span. - - table_counts() is where the headline instance of this lives: the homepage - counts every table under a 10ms budget and stores None for any table that - does not finish in time. Before this was fixed, a two-table database - produced four ERROR spans - two db.query and two db.query.execute - on - every single homepage hit. - """ + "Make table_counts() time out and return its db.query span." db = Datasette(memory=True).add_memory_database(database_name) await db.execute_write("create table big (id integer primary key, t text)") await db.execute_write_many( "insert into big (t) values (?)", [["x" * 50] for _ in range(11000)] ) - # count_limit caps the scan at 10001 rows, and below 20ms sqlite_timelimit() - # runs its progress handler on every VM instruction, so 1ms is not a close - # call - a scan of that size takes single-digit milliseconds at best. + # count_limit caps the scan at 10001 rows. Below 20ms sqlite_timelimit() + # checks the limit on every VM instruction, so this reliably exceeds 1ms. counts = await db.table_counts(1) assert counts == { "big": None @@ -310,7 +265,7 @@ async def _expected_timeout_count_span(otel_spans, database_name): @pytest.mark.asyncio async def test_expected_timeout_is_not_a_span_error(otel_spans): span = await _expected_timeout_count_span(otel_spans, "t09_expected_timeout") - # The useful signal survives; only the red status goes away. + # Recorded as interrupted, but not as an error: assert span.attributes["datasette.interrupted"] is True assert span.status.status_code != StatusCode.ERROR assert not [event for event in span.events if event.name == "exception"] @@ -318,13 +273,7 @@ async def test_expected_timeout_is_not_a_span_error(otel_spans): @pytest.mark.asyncio async def test_expected_timeout_does_not_error_the_inner_execute_span(otel_spans): - """ - The same fix has to reach db.query.execute, which sets its own status. - - Half of the original bug lived here: the inner span passed - set_status_on_exception=log_sql_errors, and table_counts() leaves - log_sql_errors at its True default, so it went ERROR too. - """ + "The db.query.execute child span is not marked as an error either." span = await _expected_timeout_count_span(otel_spans, "t09_expected_timeout_inner") children = _children_named(otel_spans, "db.query.execute", span.context) assert len(children) == 1 @@ -335,13 +284,7 @@ async def test_expected_timeout_does_not_error_the_inner_execute_span(otel_spans @pytest.mark.asyncio async def test_unexpected_timeout_is_still_a_span_error(otel_spans): - """ - A custom_time_limit *above* sql_time_limit_ms is not a short budget. - - This is the half of the rule that stops the fix collapsing into "never - report timeouts": the caller asked for 5 seconds, the instance overruled it - at 20ms, and nobody expected that. - """ + "A timeout is an error if custom_time_limit is above sql_time_limit_ms." ds = Datasette(memory=True, settings={"sql_time_limit_ms": 20}) db = ds.add_memory_database("t09_custom_limit_ignored") with pytest.raises(QueryInterrupted): @@ -350,8 +293,7 @@ async def test_unexpected_timeout_is_still_a_span_error(otel_spans): spans = _spans_for_namespace(otel_spans, "t09_custom_limit_ignored") assert spans span = spans[-1] - # Proves the caller's larger budget really was discarded - otherwise this - # would be asserting on a query that ran under a 5s limit. + # The setting overrides the larger custom_time_limit: assert span.attributes["datasette.time_limit_ms"] == 20 assert span.attributes["datasette.interrupted"] is True assert span.status.status_code == StatusCode.ERROR @@ -378,14 +320,7 @@ async def test_unsuppressed_sql_error_is_a_span_error(ds_client, otel_spans): @pytest.mark.asyncio async def test_suppressed_sql_error_is_not_a_span_error(ds_client, otel_spans): - """ - log_sql_errors=False means the caller is probing and expects failures. - - Facet suggestion runs `json_type(column)` against every column precisely - to discover which ones raise, so marking those spans as errors would put - two red spans per text column on every table page - burying real failures - and tripping any alerting keyed on span status. - """ + "With log_sql_errors=False the error is recorded as suppressed, not a span error." db = ds_client.ds.get_database("fixtures") with pytest.raises(sqlite3.OperationalError): await db.execute(INVALID_SQL, log_sql_errors=False) @@ -400,8 +335,7 @@ async def test_suppressed_sql_error_is_not_a_span_error(ds_client, otel_spans): @pytest.mark.asyncio async def test_execute_write_produces_db_query_span(otel_spans): - # Named in-memory databases are shared-cache, so every test in this file - # needs its own name or the second `create table` hits an existing table. + # Named in-memory databases are shared, so each test uses a unique name. db = Datasette(memory=True).add_memory_database("t03_write_span") await db.execute_write("create table docs (id integer primary key, name text)") await db.execute_write("insert into docs (id, name) values (?, ?)", [1, "one"]) @@ -451,27 +385,18 @@ async def test_execute_write_many_records_param_sets_not_rows_returned(otel_span span = many_spans[0] assert span.attributes["datasette.param_sets"] == 5 - # executemany() consumes parameter sets and returns no rows at all, so - # calling this a row count would be a lie. Asserted explicitly because the - # attribute really was named datasette.rows_returned at one point. assert "datasette.rows_returned" not in span.attributes # --- Context propagation across thread boundaries -------------------------- # -# Every assertion below checks parentage (child.parent.span_id == -# expected_parent.span_id, in the same trace), not merely that spans exist. -# Spans can exist and still be wrongly parented - or be unparented roots - if -# a thread boundary drops the otel context, which is exactly the failure mode -# these tests exist to prevent. +# These tests check span parentage, not just that the spans exist. @pytest.mark.asyncio async def test_db_query_execute_parents_to_db_query(ds_client, otel_spans): - # execute_fn()'s executor.submit() is thread boundary #1. The - # db.query.execute span is created inside the worker thread; without the - # copy_context() propagation it comes back as an unparented root span - # rather than a child of db.query. + # execute_fn() submits to the executor, so db.query.execute is created on + # another thread. response = await ds_client.get("/fixtures/-/query.json?sql=select+1") assert response.status_code == 200 @@ -490,19 +415,15 @@ async def test_db_query_execute_parents_to_db_query(ds_client, otel_spans): ], "expected at least one db.query.execute span" children = _children_named(otel_spans, "db.query.execute", query_span.context) assert len(children) == 1, "expected exactly one db.query.execute child of db.query" - # The execute span is strictly contained by the round-trip span, and the - # gap between the two is the thread-pool wait. + # db.query.execute runs within db.query; the gap is the thread pool wait. assert query_span.start_time <= children[0].start_time assert children[0].end_time <= query_span.end_time @pytest.mark.asyncio async def test_immutable_database_propagates_context(tmp_path, otel_spans): - # Thread boundary #3, the easy one to miss: immutable databases route - # execute_isolated_fn() through loop.run_in_executor() directly rather - # than through the write thread. A span created inside that worker must - # still parent to whatever was current when execute_isolated_fn() was - # awaited, or every immutable-database operation emits orphan roots. + # Immutable databases run execute_isolated_fn() on another thread using + # loop.run_in_executor(), not the write thread. db_path = tmp_path / "t04_immutable.db" sqlite_utils.Database(str(db_path))["t"].insert({"id": 1}, pk="id") @@ -526,10 +447,7 @@ async def test_immutable_database_propagates_context(tmp_path, otel_spans): for span in otel_spans.get_finished_spans() if span.name == "t04-child-in-isolated-worker" ], "expected a span created inside execute_isolated_fn's worker thread" - # execute_isolated_fn() now opens its own db.query span, so the chain is - # event-loop parent -> db.query -> worker child. The worker child - # parenting to that db.query span, across the thread, is the propagation - # this test exists to prove. + # Expected chain: event loop parent -> db.query -> worker thread child query_spans = _children_named(otel_spans, "db.query", parent_context) assert len(query_spans) == 1 children = _children_named( @@ -540,10 +458,8 @@ async def test_immutable_database_propagates_context(tmp_path, otel_spans): @pytest.mark.asyncio async def test_write_spans_parent_to_db_query(otel_spans): - # Thread boundary #2: WriteTask -> queue.Queue -> the write thread. - # db.write.queue_wait and db.write.execute are both direct children of - # the db.query span that was current on the event loop at enqueue time, - # so they are siblings rather than nested inside one another. + # execute_write() queues a WriteTask for the write thread. + # db.write.queue_wait and db.write.execute are both children of db.query. db = Datasette(memory=True).add_memory_database("t04_write_spans") await db.execute_write("create table docs (id integer primary key)") @@ -563,18 +479,14 @@ async def test_write_spans_parent_to_db_query(otel_spans): execute_span = execute_children[0] assert execute_span.attributes["datasette.isolated_connection"] is False assert execute_span.attributes["datasette.transaction"] is True - # Siblings, not parent/child: the queue wait is over by the time the - # write begins. + # The queue wait ends before the write begins. assert queue_wait_children[0].end_time <= execute_span.start_time @pytest.mark.asyncio async def test_write_queue_wait_duration_reflects_real_wait(otel_spans): - # db.write.queue_wait is built from explicit start/end timestamps - - # task.enqueued_at_ns, captured on the event loop, through to the moment - # the write thread dequeued it. If it were a plain `with` block on the - # write thread it would instead measure the microseconds spent building - # the span object, and this assertion would fail. + # db.write.queue_wait runs from task.enqueued_at_ns, captured on the event + # loop, to when the write thread dequeues the task. ds = Datasette(memory=True) db = ds.add_memory_database("t04_queue_wait") await db.execute_write("create table docs (id integer primary key)") @@ -582,9 +494,7 @@ async def test_write_queue_wait_duration_reflects_real_wait(otel_spans): def slow_write(conn): time.sleep(0.1) - # Queue a deliberately slow write without waiting for it, then queue a - # second write immediately behind it: the second task sits in the queue - # for roughly the duration of the first. + # Queue a slow write without waiting for it, then a second write behind it: _, slow_future = await db._send_to_write_thread(slow_write, block=False) await db.execute_write("insert into docs (id) values (1)") await slow_future @@ -600,23 +510,17 @@ async def test_write_queue_wait_duration_reflects_real_wait(otel_spans): ) assert len(queue_wait_children) == 1 duration_ns = queue_wait_children[0].end_time - queue_wait_children[0].start_time - # The slow write sleeps 100ms; anything above 10ms is far beyond the - # microseconds a mis-timestamped span would report. + # The slow write sleeps for 100ms assert duration_ns > 10_000_000, f"queue wait was only {duration_ns}ns" async def _write_spans_from_one_enqueue(otel_spans, name, block): """ - Run exactly one write through the write thread from inside a span of our - own, and return (enqueueing span context, {span name: span}). + Run one write through the write thread inside a span, returning + (enqueueing span context, {span name: span}). - `_send_to_write_thread` is called directly rather than `execute_write()` - because `execute_write()` opens its own db.query span, which would then - be the span current at enqueue time - so the parent/link would point at - that span rather than at the one this test controls. - - The exporter is cleared immediately before the enqueue so the write spans - collected here can only have come from this one write. + Uses _send_to_write_thread() because execute_write() would add its own + db.query span between the enqueueing span and the write spans. """ db = Datasette(memory=True).add_memory_database(name) await db.execute_write("create table docs (id integer primary key)") @@ -629,11 +533,8 @@ async def _write_spans_from_one_enqueue(otel_spans, name, block): enqueuer_context = enqueuer.get_span_context() queued = await db._send_to_write_thread(insert, block=block) if not block: - # The point of block=False is that the write happens after the - # caller has returned and the enqueueing span above has closed. - # Awaiting the reply future outside that `with` waits for the write - # thread deterministically - it is resolved only after both write - # spans have ended and been exported. + # Wait for the write after the enqueueing span has ended. The reply + # future resolves once both write spans have been exported. _, reply_future = queued await reply_future @@ -648,9 +549,8 @@ async def _write_spans_from_one_enqueue(otel_spans, name, block): @pytest.mark.asyncio async def test_blocking_write_spans_still_parent_normally(otel_spans): - # Regression guard for ticket 07: block=True genuinely has containment - - # the caller awaits the reply future - so those spans must keep parenting - # to the enqueueing span, and must not grow links. + # block=True waits for the write, so its spans are children of the + # enqueueing span, with no links. enqueuer_context, spans = await _write_spans_from_one_enqueue( otel_spans, "t07_blocking_write", block=True ) @@ -664,24 +564,21 @@ async def test_blocking_write_spans_still_parent_normally(otel_spans): @pytest.mark.asyncio async def test_nonblocking_write_spans_are_roots_with_a_link(otel_spans): - # block=False returns before the write runs, so the enqueueing span has - # already ended (and exported) by the time these spans start. Parenting - # them to it would draw a child outliving its closed parent, so they are - # roots in their own traces, linked back to the span that caused them. + # block=False returns before the write runs, so the write spans are roots + # linked to the enqueueing span. enqueuer_context, spans = await _write_spans_from_one_enqueue( otel_spans, "t07_nonblocking_write", block=False ) assert enqueuer_context.is_valid, "test's own enqueueing span was not recorded" for name, span in spans.items(): assert span.parent is None, f"{name} is still parented" - # A link does not join the linked trace: each of these is its own - # root trace, which is the correct shape and not a workaround. + # Each write span starts its own trace assert span.context.trace_id != enqueuer_context.trace_id, name assert len(span.links) == 1, f"{name} has links {span.links}" link_context = span.links[0].context assert link_context.trace_id == enqueuer_context.trace_id, name assert link_context.span_id == enqueuer_context.span_id, name - # The two write spans are independent roots, not nested in one another. + # The two write spans are separate roots assert ( spans["db.write.queue_wait"].context.trace_id != spans["db.write.execute"].context.trace_id @@ -690,8 +587,6 @@ async def test_nonblocking_write_spans_are_roots_with_a_link(otel_spans): @pytest.mark.asyncio async def test_nonblocking_write_link_has_no_attributes(otel_spans): - # There is only one kind of link here, so a relationship-name attribute - # would be a constant conveying nothing the link's existence does not. _, spans = await _write_spans_from_one_enqueue( otel_spans, "t07_nonblocking_link_attrs", block=False ) @@ -705,18 +600,10 @@ async def test_nonblocking_write_spans_ignore_the_write_threads_ambient_context( otel_spans, ): """ - block=False spans pass an explicit empty Context, not merely "no attach". + block=False spans ignore any context left attached on the write thread. - Nothing is attached for a block=False task, but "nothing attached" is not - the same as "no ambient context": the write thread is persistent, and - anything running on it - a prepare_connection plugin hook, say - can - attach a context and never detach it. Without the explicit `context=` - these spans would silently parent to that leftover span instead of being - roots, and no other test here would notice, because in every other test - the write thread's ambient context happens to be empty. - - So this test leaks exactly such a context on the write thread, the way a - careless plugin would, and then checks the write spans are still roots. + A prepare_connection hook could attach a context and never detach it. + This test does that, then checks the write spans are still roots. """ ds = Datasette(memory=True) db = ds.add_memory_database("t07_ambient_write_thread") @@ -726,8 +613,8 @@ async def test_nonblocking_write_spans_ignore_the_write_threads_ambient_context( def prepare_connection(conn, database): if threading.current_thread().name == write_thread_name: - # Runs once, on the write thread, before any task is dequeued - - # and never detaches, which is the whole point. + # Runs on the write thread before any task is dequeued, and never + # detaches. span = tracer.start_span("leaked-write-thread-ambient-span") leaked["span_id"] = span.get_span_context().span_id otel_context_api.attach(otel_trace.set_span_in_context(span)) @@ -766,14 +653,7 @@ async def test_nonblocking_write_spans_ignore_the_write_threads_ambient_context( @pytest.mark.asyncio async def test_suppressed_error_does_not_mark_execute_span(ds_client, otel_spans): - """ - The inner db.query.execute span must honour log_sql_errors too. - - It is created inside the worker thread, so without record_exception / - set_status_on_exception being passed through it would mark every facet - suggestion probe as failed even though the outer db.query span correctly - reports the failure as suppressed. - """ + "The inner db.query.execute span also respects log_sql_errors=False." db = ds_client.ds.get_database("fixtures") with pytest.raises(sqlite3.OperationalError): await db.execute(INVALID_SQL, log_sql_errors=False) @@ -791,23 +671,14 @@ async def test_suppressed_error_does_not_mark_execute_span(ds_client, otel_spans @pytest.mark.asyncio async def test_invoke_startup_produces_one_trace_not_dozens_of_orphans(otel_spans): - """ - invoke_startup() runs with no request, so nothing it does has an ambient - span to nest under. Without datasette.startup every register_* hook, every - internal-catalog read and every catalog write becomes its own single-span - root trace - around twenty of them per fresh instance. - """ + "Spans emitted by invoke_startup() share a single datasette.startup root span." ds = Datasette(memory=True) - # Named in-memory databases are shared-cache, so this needs its own name. ds.add_memory_database("t05_startup_db") - # Constructing a Datasette already touches the internal catalog, and that - # work is genuinely outside startup. Clear so the assertions below describe - # invoke_startup() alone. + # Ignore spans from constructing Datasette, which happens before startup otel_spans.clear() - # Deliberately no ambient span: this mirrors the ASGI lifespan path, where - # startup runs before any request exists. If something did wrap this call - # the "one root" assertion below would pass for the wrong reason. + # No ambient span, as in the ASGI lifespan path where startup runs before + # any request. assert ( not otel_trace.get_current_span().get_span_context().is_valid ), "this test must run with no ambient span" @@ -833,7 +704,7 @@ async def test_invoke_startup_produces_one_trace_not_dozens_of_orphans(otel_span by_span_id = {span.context.span_id: span for span in spans} - # The internal catalog reads are what made up the bulk of the orphans. + # Internal database reads: internal_queries = [ span for span in spans @@ -844,8 +715,7 @@ async def test_invoke_startup_produces_one_trace_not_dozens_of_orphans(otel_span _descends_from(span, startup.context, by_span_id) for span in internal_queries ) - # ...and the catalog writes, which reach the span through the write thread, - # so they also prove the ticket-04 context capture survives startup. + # Internal database writes, which run on the write thread: write_spans = [span for span in spans if span.name.startswith("db.write.")] assert write_spans, "expected db.write.* spans during startup" assert all( @@ -859,20 +729,11 @@ async def test_invoke_startup_produces_one_trace_not_dozens_of_orphans(otel_span @pytest.mark.asyncio async def test_db_query_is_client_kind_and_children_are_internal(otel_spans): """ - db.query is a database client span; Datasette's decomposition of it is not. - - Trace UIs key their database rendering off the span kind rather than off - db.system, so db.query has to be CLIENT. db.query.execute, - db.write.execute and db.write.queue_wait deliberately stay INTERNAL: they - are parts of one logical query rather than three separate database calls, - and queue_wait touches no database at all - marking them CLIENT would - make one query look like several to anything counting spans by kind. + db.query spans are CLIENT. Their child spans are INTERNAL because they are + parts of one query rather than separate database calls. """ - # Named in-memory databases are shared-cache, so this needs its own name. db = Datasette(memory=True).add_memory_database("t06_span_kind") - # All four db.query entry points, so a missed `kind=` on any one of them - # fails here - plus the write path (db.write.queue_wait, - # db.write.execute) and the read path (db.query.execute) children. + # Call each of the four SQL string methods: await db.execute_write("create table docs (id integer primary key)") await db.execute_write_many( "insert into docs (id) values (?)", [[i] for i in range(1, 4)] @@ -899,15 +760,7 @@ async def test_db_query_is_client_kind_and_children_are_internal(otel_spans): async def test_instrumentation_scope_declares_version_and_schema_url( ds_client, otel_spans ): - """ - Spans say which Datasette produced them and which semconv version their - attribute names follow. - - Before get_tracer() was given a version and a schema URL every exported - scope was name='datasette' version='' schema_url='', so nothing - downstream could tell which Datasette a span came from, or whether - `db.system` meant `db.system` or the post-1.30.0 `db.system.name`. - """ + "The instrumentation scope includes the Datasette version and schema URL." response = await ds_client.get("/fixtures/-/query.json?sql=select+1") assert response.status_code == 200 @@ -917,10 +770,7 @@ async def test_instrumentation_scope_declares_version_and_schema_url( assert scope.name == "datasette" assert scope.version == __version__ - # The literal URL, not the SCHEMA_URL constant: comparing the span - # against the same constant the instrumentation is built from would only - # catch a dropped argument, never a wrong value. Bumping this is a claim - # about the attribute names on the wire - see SCHEMA_URL in telemetry.py. + # Uses the literal URL so changing SCHEMA_URL requires updating this test assert scope.schema_url == "https://opentelemetry.io/schemas/1.29.0" assert SCHEMA_URL == "https://opentelemetry.io/schemas/1.29.0" assert __version__, "the scope version must not be empty" @@ -929,14 +779,11 @@ async def test_instrumentation_scope_declares_version_and_schema_url( def test_db_operation_name_from_leading_keyword(): assert sql_operation_name("select 1") == "SELECT" assert sql_operation_name(" insert into x (a) values (1)") == "INSERT" - # A leading CTE reports WITH rather than the operation inside it. That is - # the documented limitation, not an accident - see sql_operation_name(). + # A leading CTE reports WITH, not the operation inside it assert sql_operation_name("with foo as (select 1) select * from foo") == "WITH" - # Unrecognised leading keyword: no attribute rather than a wrong one, and - # no unbounded value set derived from attacker-supplied SQL. + # Unrecognized leading keyword assert sql_operation_name("gibberish 1") is None - # Not a parser: a parenthesised SELECT and a leading comment both yield - # nothing rather than a guess. + # A parenthesized SELECT or a leading comment also returns None assert sql_operation_name("(select 1) union select 2") is None assert sql_operation_name("-- a comment\nselect 1") is None assert sql_operation_name("") is None @@ -976,14 +823,10 @@ async def test_execute_write_sets_db_operation_name(otel_spans): @pytest.mark.asyncio async def test_execute_write_script_has_no_operation_name(otel_spans): """ - executescript() runs several statements, so naming the operation after - the first one would be a lie. Semantic conventions say db.operation.name - should not be extracted from query text that can hold more than one - operation, so the attribute is absent entirely. + Scripts can contain several statements, so db.operation.name is omitted. - The script deliberately starts with `create`, which *is* on the - allowlist - so this fails if the call site ever starts calling - sql_operation_name(). + The script starts with `create`, which is on the allowlist, so this fails + if the operation name is extracted anyway. """ db = Datasette(memory=True).add_memory_database("t06_script_operation") await db.execute_write_script( @@ -1022,8 +865,7 @@ async def test_execute_fn_produces_db_query_span(otel_spans): span.attributes["datasette.callback"] == "test_execute_fn_produces_db_query_span..count_rows" ) - # There is no SQL string for a callback, and no statement to take a - # leading keyword from - absent beats guessed. + # Callbacks have no SQL text to record or take an operation name from assert "db.query.text" not in span.attributes assert "db.operation.name" not in span.attributes children = _children_named(otel_spans, "db.query.execute", span.context) @@ -1032,7 +874,6 @@ async def test_execute_fn_produces_db_query_span(otel_spans): @pytest.mark.asyncio async def test_execute_fn_lambda_reports_lambda(otel_spans): - # Pins the documented behaviour rather than pretending lambdas have names. db = Datasette(memory=True).add_memory_database("t16_lambda") otel_spans.clear() await db.execute_fn(lambda conn: conn.execute("select 1").fetchone()) @@ -1067,9 +908,7 @@ async def test_execute_write_fn_produces_db_query_span(otel_spans): @pytest.mark.asyncio async def test_execute_write_fn_callback_name_is_not_the_hook_wrapper(otel_spans): - # A callback that declares track_event is the case where - # _wrap_fn_with_hooks() actually replaces fn with a wrapper - the span - # must still report the caller's function, not the wrapper's name. + # _wrap_fn_with_hooks() wraps callbacks that accept track_event db = Datasette(memory=True).add_memory_database("t16_wrapper_name") def create_with_events(conn, track_event): @@ -1087,9 +926,8 @@ async def test_execute_write_fn_callback_name_is_not_the_hook_wrapper(otel_spans @pytest.mark.asyncio async def test_execute_write_fn_nonblocking_spans_link_to_the_new_span(otel_spans): - # For block=False the public db.query span ends at enqueue and the - # write-thread spans become roots. Their link must target that new span, - # not whatever was current around the execute_write_fn() call. + # With block=False the write thread spans link to the db.query span from + # execute_write_fn(), not to the span that was current when it was called. db = Datasette(memory=True).add_memory_database("t16_nonblocking") await db.execute_write("create table docs (id integer primary key)") @@ -1100,8 +938,7 @@ async def test_execute_write_fn_nonblocking_spans_link_to_the_new_span(otel_span with tracer.start_as_current_span("t16-enqueueing-span") as enqueuer: enqueuer_context = enqueuer.get_span_context() await db.execute_write_fn(insert, block=False) - # Writes are serialized on the write thread, so a blocking write behind - # the non-blocking one waits for it deterministically. + # Writes run in order, so this waits for the non-blocking write to finish await db.execute_write("insert into docs (id) values (2)") query_spans = [ @@ -1125,9 +962,8 @@ async def test_execute_write_fn_nonblocking_spans_link_to_the_new_span(otel_span @pytest.mark.asyncio async def test_execute_does_not_double_wrap(otel_spans): - # The regression guard for the refactor: execute() and the SQL-string - # write methods call the private _execute_fn/_execute_write_fn, so they - # must not gain a second db.query span from the public wrappers. + # execute() and the SQL string write methods call the private + # _execute_fn() and _execute_write_fn(), so they create one db.query span. db = Datasette(memory=True).add_memory_database("t16_no_double_wrap") otel_spans.clear() await db.execute_write("create table t (id integer primary key)") @@ -1172,8 +1008,7 @@ async def test_execute_isolated_fn_span_on_mutable_and_immutable(tmp_path, otel_ @pytest.mark.asyncio async def test_execute_fn_exception_marks_span_error(otel_spans): - # Unlike execute(), there is no probing caller on this path - a callback - # that raises is an error, with the default record_exception behaviour. + # execute_fn() has no log_sql_errors option, so exceptions are span errors db = Datasette(memory=True).add_memory_database("t16_fn_error") def boom(conn): diff --git a/tests/test_telemetry_metrics.py b/tests/test_telemetry_metrics.py index 5229c4c9..2e465b82 100644 --- a/tests/test_telemetry_metrics.py +++ b/tests/test_telemetry_metrics.py @@ -1,19 +1,6 @@ """ -Tests for the OpenTelemetry metrics Datasette core emits. - -Two layers are tested separately and deliberately: - -- The gauge callbacks are plain generator functions, so they are called - directly for exact-value assertions. Going through the SDK for those would - be unreliable: the pool gauges carry no attribute identifying which - Datasette produced them, and a pytest session has many live instances, so - the SDK's last-value aggregation would report whichever one happened to be - observed last. - -- The SDK pipeline (instrument -> reader -> data points) is tested through - the `otel_metrics` fixture, using metrics that carry `db.namespace` - a - uniquely named in-memory database is enough to isolate those from every - other instance alive in the session. +Tests for the OpenTelemetry metrics emitted by Datasette. Gauge callbacks are +called directly, since the pool gauges have no attributes to tell instances apart. """ import asyncio @@ -65,25 +52,17 @@ def metrics_ds(): @pytest.mark.asyncio async def test_sql_thread_limit_gauge_reports_num_sql_threads(metrics_ds): values = [value for _, value in observations(telemetry.observe_sql_thread_limit)] - # Other instances are alive in this session, so assert membership rather - # than uniqueness - 7 is distinctive enough to only come from metrics_ds. + # Other Datasette instances may also be reporting: assert 7 in values @pytest.mark.asyncio async def test_no_thread_gauges_in_non_threaded_mode(): - """ - num_sql_threads=0 means there is no pool at all, so the pool gauges must - skip the instance rather than report a bogus limit of 0. - - The pool gauges carry no attributes, so the live-instance registry is - narrowed to just this instance for the assertion - counting global - observations instead would let an unrelated instance being garbage - collected mid-test shift the baseline. - """ + "Pool gauges skip instances with num_sql_threads=0, which have no pool." ds = Datasette(memory=True, settings={"num_sql_threads": 0}) try: assert ds.executor is None + # Pool gauges have no attributes, so observe only this instance: original = telemetry._live_datasettes telemetry._live_datasettes = weakref.WeakSet([ds]) try: @@ -91,7 +70,7 @@ async def test_no_thread_gauges_in_non_threaded_mode(): assert list(telemetry.observe_sql_thread_queue_depth()) == [] finally: telemetry._live_datasettes = original - # Per-database gauges are unaffected - they do not depend on the pool. + # Per-database gauges do not depend on the pool: assert observations(telemetry.observe_pending_queries, ds) finally: ds.close() @@ -100,11 +79,8 @@ async def test_no_thread_gauges_in_non_threaded_mode(): @pytest.mark.asyncio async def test_thread_queue_depth_gauge_reports_saturation(): """ - The headline alerting metric must actually read above zero when reads - queue behind num_sql_threads. This also pins the private - `ThreadPoolExecutor._work_queue` attribute the callback depends on: if a - stdlib rename ever removes it, this fails instead of the metric silently - vanishing (the callback tolerates its absence at collection time). + Queue depth is above zero when reads queue behind num_sql_threads. Also + fails if the private ThreadPoolExecutor._work_queue attribute goes away. """ ds = Datasette(memory=True, settings={"num_sql_threads": 1}) db = ds.add_memory_database("metrics_saturation_db") @@ -118,11 +94,10 @@ async def test_thread_queue_depth_gauge_reports_saturation(): try: first = asyncio.ensure_future(db.execute_fn(blocker)) - # Wait until the blocker owns the pool's only thread. + # Wait until the blocker is using the only thread: await asyncio.get_running_loop().run_in_executor(None, entered.wait, 10) second = asyncio.ensure_future(db.execute_fn(lambda conn: 2)) - # The second submission lands in the executor's queue on the next - # event-loop turn; poll briefly rather than assume the timing. + # The second query is queued on a later event loop turn, so poll: depths = [] for _ in range(500): depths = [ @@ -157,8 +132,7 @@ async def test_pending_queries_gauge_tracks_in_flight_queries(metrics_ds): assert value() == 0 - # sqlite3.sleep is not a thing, so block the worker thread on an event we - # control from the event loop and sample the gauge while it is held. + # Hold the worker thread until release is set: release = asyncio.Event() loop = asyncio.get_running_loop() entered = asyncio.Event() @@ -188,8 +162,7 @@ async def test_write_queue_depth_gauge(metrics_ds): if a == attributes ] - # No write has ever been queued, so there is no queue and no observation - - # rather than a fabricated zero for a queue that does not exist. + # No observation until the write queue has been created: assert depths() == [] await db.execute_write("create table t (id integer primary key)") @@ -277,11 +250,7 @@ async def test_operation_duration_records_error_type(otel_metrics): @pytest.mark.asyncio async def test_operation_duration_records_write_error_type(otel_metrics): - """ - Same as the read-path error test, but the write wrappers time a different - code path - `execute_write_fn`, the write thread and its reply future - - so error propagation through them is pinned separately. - """ + "A failed write is still timed and records error.type." ds = Datasette(memory=True) ds.add_memory_database("duration_write_error_db") try: @@ -319,7 +288,7 @@ async def test_write_queue_wait_histogram(otel_metrics): @pytest.mark.asyncio async def test_interrupted_queries_counter(otel_metrics): - "The count of time-limit kills, which sampled traces cannot provide." + "Queries cancelled by sql_time_limit_ms are counted." ds = Datasette(memory=True, settings={"sql_time_limit_ms": 1}) ds.add_memory_database("interrupted_db") try: @@ -344,7 +313,7 @@ async def test_interrupted_queries_counter(otel_metrics): @pytest.mark.asyncio async def test_metrics_are_reported_through_the_sdk_for_gauges(otel_metrics): - "End-to-end: a gauge callback reaches the reader as a data point." + "Gauge callbacks reach the metric reader as data points." ds = Datasette(memory=True) ds.add_memory_database("gauge_pipeline_db") try: @@ -373,14 +342,8 @@ def test_closed_datasette_stops_being_observed(): def test_registry_holds_instances_weakly(): """ - Registering an instance must never be the thing that keeps it alive. - - A stand-in object is used rather than a real Datasette because a Datasette - with a temp-disk internal database is pinned for the life of the process - by `Database.__init__`'s `atexit.register(self._cleanup_temp_file)`, which - holds the Database, which holds the Datasette. That is pre-existing and - unrelated to telemetry; what is tested here is that this registry adds no - reference of its own. + Registering an instance does not keep it alive. Uses a stand-in object + because an atexit handler in Database.__init__ keeps a real Datasette alive. """ import gc import weakref @@ -412,10 +375,8 @@ HISTOGRAM_PROBES = [ ), ] -# One value inside each of six distinct registry buckets. Under OpenTelemetry's -# default boundaries - [0, 5, 10, 25, ...], meant for milliseconds - the first -# five of these all land in (0, 5] and only 7.0 lands elsewhere, so the -# "occupies six buckets" assertion below fails if the advisory is ever dropped. +# One value in each of six registry buckets. The SDK's default boundaries +# would put the first five in the same bucket. SPREAD = [0.00005, 0.0003, 0.002, 0.03, 0.8, 7.0] @@ -428,18 +389,8 @@ def test_histograms_spread_values_across_buckets( otel_metrics, instrument_name, metric_name, attributes ): """ - The registry's boundaries reach the SDK, and a realistic spread of - seconds-scale durations occupies more than one bucket. - - Recording onto the instrument directly rather than driving a workload is - deliberate: real durations here are all tens of microseconds and would - share a bucket no matter what the boundaries were, which is exactly the - situation this test exists to detect. - - `explicit_bounds` is compared against the registry rather than against the - instrument's own configuration - the instrument is built *from* the - registry, so that comparison would be a value against itself. What is - checked here is that the advisory survived the trip through the SDK. + The registry's bucket boundaries reach the SDK. Values are recorded + directly because real test query durations would all share one bucket. """ from datasette.telemetry_registry import METRICS @@ -464,7 +415,7 @@ def test_histograms_spread_values_across_buckets( @pytest.mark.asyncio async def test_operation_duration_histogram_records_execute_fn(otel_metrics): - "Callback-style reads land in the same histogram as SQL-string reads." + "execute_fn() reads are recorded in the same histogram as SQL reads." ds = Datasette(memory=True) ds.add_memory_database("duration_fn_db") try: @@ -487,7 +438,7 @@ async def test_operation_duration_histogram_records_execute_fn(otel_metrics): @pytest.mark.asyncio async def test_operation_duration_histogram_records_execute_write_fn(otel_metrics): - "Callback-style writes - the JSON write API's whole diet - are counted too." + "execute_write_fn() writes are recorded in the same histogram." ds = Datasette(memory=True) ds.add_memory_database("duration_write_fn_db") try: diff --git a/tests/test_telemetry_registry.py b/tests/test_telemetry_registry.py index b5ef9deb..11a66a13 100644 --- a/tests/test_telemetry_registry.py +++ b/tests/test_telemetry_registry.py @@ -1,26 +1,6 @@ """ -Two-way conformance between `datasette/telemetry_registry.py` and what -Datasette actually emits. - -This is the test that makes the generated documentation trustworthy. cog -guarantees the docs match the registry; this guarantees the registry matches -the code. Without it, both could agree with each other and be wrong. - -It checks both directions, and the second one is the one nothing else catches: - -- **emitted but not registered** - instrumentation was added without - documenting it, so the reference page silently omits it. -- **registered but never emitted** - the reference page describes a span or - attribute that no longer exists, which is worse than omitting it, because a - reader will build a dashboard on it. - -Both of those directions compare the code against the registry. Neither can -catch a *rename*, because the call sites now take their names from the -registry - move `DB_NAMESPACE` to `"db.namespace2"` and code and registry -still agree with each other, while every existing dashboard breaks. So the -literal names live here too, spelled out, and are asserted against both the -registry and the wire. That is the one comparison in this file that is not -made against a value derived from the registry itself. +Tests that the spans, attributes and metrics Datasette emits match +datasette/telemetry_registry.py, in both directions. """ import copy @@ -42,10 +22,8 @@ from datasette.database import QueryInterrupted from datasette.telemetry_testing import assert_metrics_conform, assert_metrics_covered from datasette.utils.sqlite import sqlite3 -# The names as they appear on the wire, written out rather than read from the -# registry. If a change to the registry makes one of these fail, that change -# is renaming something a user's dashboards and saved queries depend on - -# which is a decision to take deliberately, here, not a line to re-derive. +# Written out as literals rather than read from the registry, so renaming a +# signal fails these tests. EXPECTED_ATTRIBUTES = { "db.query": { "db.system", @@ -73,18 +51,8 @@ EXPECTED_ATTRIBUTES = { } EXPECTED_SPANS = set(EXPECTED_ATTRIBUTES) -# The HTTP request span is handled separately because its name is composed at -# 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. +# The HTTP request span name is composed at runtime as "{method} {route}", so +# it is checked by shape rather than as a literal. The workload only issues GETs. EXPECTED_HTTP_SPAN_NAME = "{http.request.method} {http.route}" EXPECTED_HTTP_METHOD_NAMES = {"GET"} EXPECTED_HTTP_ATTRIBUTES = { @@ -99,16 +67,14 @@ EXPECTED_HTTP_ATTRIBUTES = { "datasette.internal_client", } -# The registry's own name for the request span is that template, not anything -# that appears on the wire. +# The registry uses the name template for the request span. 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. +# Named in-memory databases are shared between instances, so each workload +# uses a unique name. _names = itertools.count() @@ -117,14 +83,7 @@ def _unique(prefix): 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. - """ + "A route that raises, producing a 500 and error.type on the request span." __name__ = "TelemetryRegistryBoomPlugin" @@ -135,20 +94,13 @@ class _BoomPlugin: async def exercise(): """ - Drive enough of Datasette to emit every span and attribute the registry - claims exists. - - Each call is here because it is the only thing that produces some span or - attribute - see the comments. If you add instrumentation on a path this - does not reach, add the path rather than loosening the assertions. - - Returns the instance so the caller can close it; startup happens inside - so that the `datasette.startup` span lands in the collected set. + Drive enough of Datasette to emit every registered span and attribute, + including datasette.startup. Returns the instance so the caller can close it. """ name = _unique("registry") ds = Datasette(memory=True) ds.add_memory_database(name) - # datasette.startup - and the internal catalog work nested under it + # datasette.startup await ds.invoke_startup() db = ds.get_database(name) @@ -165,8 +117,7 @@ async def exercise(): # datasette.isolated_connection=True await db.execute_isolated_fn(lambda conn: conn.execute("select 1").fetchone()) - # datasette.callback, with named functions so the conformance run sees the - # attribute's documented value shape (a qualname, not just "") + # datasette.callback, using named functions rather than lambdas def registry_read_callback(conn): return conn.execute("select count(*) from t").fetchone() @@ -181,14 +132,11 @@ async def exercise(): await db.execute("select * from t where id > :n", {"n": 5}) await db.execute("select * from t", truncate=True) - # datasette.sql_error_suppressed - the caller is probing and treats - # failure as an expected answer + # datasette.sql_error_suppressed with pytest.raises(sqlite3.OperationalError): await db.execute("select nope from t", log_sql_errors=False) - # datasette.interrupted - only ever set when a query exceeds its time - # limit, so the workload has to force one rather than exempt it. An - # unbounded recursive CTE cannot finish, so 1ms is always exceeded. + # datasette.interrupted: an unbounded recursive CTE always exceeds 1ms with pytest.raises(QueryInterrupted): await db.execute( "with recursive c(x) as (select 0 union all select x+1 from c) " @@ -196,13 +144,11 @@ async def exercise(): custom_time_limit=1, ) - # These requests produce the HTTP request span and its - # http.request.method / url.path / url.scheme / server.address / - # user_agent.original / http.response.status_code attributes. + # HTTP request spans and their 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 + # error.type on the request span, set by a 5xx response ds.pm.register(_BoomPlugin(), name="telemetry-registry-boom") try: response = await ds.client.get("/-/telemetry-registry-boom") @@ -215,21 +161,13 @@ async def exercise(): @pytest_asyncio.fixture async def emitted(otel_spans): """ - 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. 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. + Every (span name, span kind, attributes) triple emitted by exercise(). + The kind is needed to resolve the dynamically named request span. """ - # 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" - # 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. + # str() so failure messages show plain strings, not registry instances collected = tuple( ( str(span.name), @@ -258,12 +196,7 @@ def _keys_by_span(records): @pytest.mark.asyncio async def test_workload_emits_exactly_the_expected_names(emitted): - """ - The wire format, pinned to literals. - - Not derived from the registry, so this is what catches a rename that the - registry and the call sites make together. - """ + "Emitted span and attribute names match the expected literals." static, server = _partition(emitted) by_span = _keys_by_span(static) assert set(by_span) == EXPECTED_SPANS @@ -275,9 +208,7 @@ async def test_workload_emits_exactly_the_expected_names(emitted): 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. + # Every request in the workload matches a route assert route, f"the request span {name!r} carries no http.route" method, _, name_route = name.partition(" ") assert name_route == route, ( @@ -290,7 +221,7 @@ async def test_workload_emits_exactly_the_expected_names(emitted): def test_registry_matches_the_expected_names(): - "The other half of the rename check: the registry against the same literals." + "Registry names match the expected literals." assert {str(span) for span in reg.SPANS} == EXPECTED_REGISTRY_NAMES for span in reg.SPANS: assert { @@ -329,12 +260,9 @@ async def test_every_emitted_attribute_is_registered(emitted): @pytest.mark.asyncio 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. - """ - # 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. + "The docs should not describe a span that is no longer emitted." + # Compare by identity: the request span's registry name never appears on + # the wire. 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, ( @@ -346,14 +274,8 @@ async def test_every_registered_span_is_emitted(emitted): @pytest.mark.asyncio async def test_every_registered_attribute_is_emitted(emitted): """ - Every registered attribute, optional or not, must actually be set at least - once by the workload. - - `optional` describes whether a reader should expect it on every span, not - whether the code still sets it - so an attribute deleted from the code but - left in the docs has to fail here even when it is marked optional. If a - new attribute only appears in some rare case, extend exercise() to reach - that case. + Every registered attribute, including optional ones, is emitted at least + once. If a new attribute only appears in rare cases, extend exercise(). """ by_entry = {} for name, kind, keys in emitted: @@ -381,7 +303,7 @@ def test_registry_has_no_duplicate_names(): def test_registry_entries_are_documented(): - "Every entry carries a description - the docs are generated from these." + "Every entry has a description, used to generate the docs." for span in reg.SPANS: assert span.description.strip(), f"{span} has no description" for attribute in span.attributes: @@ -389,7 +311,6 @@ def test_registry_entries_are_documented(): def test_registry_entries_are_usable_as_plain_strings(): - "The str subclassing is the whole reason call sites need no wrapper API." assert isinstance(reg.DB_QUERY, str) assert isinstance(reg.DB_NAMESPACE, str) assert reg.DB_QUERY == "db.query" @@ -399,30 +320,19 @@ def test_registry_entries_are_usable_as_plain_strings(): def test_registry_entries_survive_deepcopy_and_pickle(): """ - A copy of an entry is a plain `str`. - - These are `str` subclasses whose `__new__` requires the metadata - arguments, so without `__reduce__` `copy` cannot reconstruct one and - raises. That is not academic: the SDK's `ConsoleMetricExporter` renders - data points with `dataclasses.asdict()`, which deepcopies mappings, and - core passes registry entries as metric attribute keys - see - `test_console_metric_exporter_renders_core_metric_points`. + A copied or unpickled entry is a plain str. ConsoleMetricExporter + deepcopies metric attributes, which use registry entries as keys. """ for entry in (reg.DB_NAMESPACE, reg.DB_QUERY, reg.M_OPERATION_DURATION): assert copy.deepcopy({entry: 1}) == {str(entry): 1} assert type(copy.deepcopy(entry)) is str assert pickle.loads(pickle.dumps(entry)) == str(entry) - # The metadata still lives on the registered instance itself, which - # is the only place anything reads it. + # The original entry keeps its metadata assert entry.description.strip() @pytest.mark.asyncio async def test_console_metric_exporter_renders_core_metric_points(otel_metrics): - """ - The end-to-end shape of the bug above: a console metrics dump of - Datasette's own points has to survive `dataclasses.asdict()`. - """ from opentelemetry.sdk.metrics.export import ( ConsoleMetricExporter, MetricExportResult, @@ -432,8 +342,7 @@ async def test_console_metric_exporter_renders_core_metric_points(otel_metrics): ds = Datasette(memory=True) ds.add_memory_database(name) await ds.invoke_startup() - # One real query, so the dump contains a db.client.operation.duration - # point keyed by the DB_NAMESPACE registry entry. + # Produces a db.client.operation.duration point keyed by DB_NAMESPACE await ds.get_database(name).execute("select 1") data = otel_metrics.reader.get_metrics_data() @@ -445,13 +354,8 @@ async def test_console_metric_exporter_renders_core_metric_points(otel_metrics): def test_every_histogram_declares_bucket_boundaries(): """ - Every histogram must carry explicit boundaries, and only histograms may. - - OpenTelemetry's default boundaries start at 5 and are meant for - milliseconds, so a seconds-valued histogram that inherits them records - everything into one bucket. This is a registry self-consistency check, not - a check that the boundaries reached the SDK - for that see - `test_histograms_spread_values_across_buckets` in test_telemetry_metrics.py. + Every histogram declares bucket boundaries, and only histograms do. + OpenTelemetry's defaults are meant for milliseconds, not seconds. """ for metric in reg.METRICS: if metric.kind == reg.HISTOGRAM: @@ -468,13 +372,8 @@ def test_every_histogram_declares_bucket_boundaries(): 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. + dynamic=True entries such as the request span match on kind. They never + match without a kind, and never override a registered name. """ assert reg.span_for("GET", SpanKind.SERVER) is reg.HTTP_REQUEST assert reg.span_for("POST /^/(?P[^/]+)$", SpanKind.SERVER) is ( @@ -501,27 +400,15 @@ def test_span_and_attribute_lookup(): @pytest_asyncio.fixture async def emitted_metrics(otel_metrics): """ - Every (metric name, attribute key) pair produced by a broad workload, - plus the raw set of metric names - the metric-side counterpart of the - `emitted` span fixture above. - - Metrics use DELTA temporality (see `otel_meter_provider` in datasette.telemetry_testing), and the - function-scoped `otel_metrics` fixture drains any state left by an - earlier test before yielding, so this collection is not polluted by - other tests in the session - only by other *instances*, which is why the - checks below key everything off attribute names rather than values. + Metric names and (metric name, attribute key) pairs from a broad workload. + Checks use attribute keys rather than values, since other Datasette + instances in the session can also report points. """ - # The span workload already reaches every synchronous metric except the - # interrupted counter: reads and writes drive db.client.operation.duration - # and datasette.write.queue_wait, and both the suppressed-error probe and - # the custom_time_limit interrupt raise through record_operation_duration, - # setting error.type. + # Reaches every synchronous metric except datasette.sql.queries.interrupted ds = await exercise() - # datasette.sql.queries.interrupted counts only queries that exceed the - # *configured* limit - a caller opting into a deliberately short budget - # via custom_time_limit (as exercise() does) is excluded by design. So a - # second instance whose configured limit is tiny provides the real thing. + # datasette.sql.queries.interrupted ignores custom_time_limit timeouts, so + # this needs an instance with a low sql_time_limit_ms. slow_name = _unique("registry_metrics_slow") slow = Datasette(memory=True, settings={"sql_time_limit_ms": 5}) slow.add_memory_database(slow_name) @@ -533,8 +420,7 @@ async def emitted_metrics(otel_metrics): "select * from c" ) - # Collect while both instances are still registered, so the observable - # gauges - which observe live instances at collection time - report. + # Collect before closing the instances so the observable gauges report them otel_metrics.collect() snapshot = otel_metrics.snapshot assert snapshot, "no metrics captured - the fixture is not exercising anything" @@ -551,11 +437,8 @@ async def emitted_metrics(otel_metrics): @pytest.mark.asyncio async def test_metrics_conform_to_the_registry(emitted_metrics): """ - Emitted-but-unregistered, via the plugin kit's helper - consumed here - exactly the way a plugin's suite would. Beyond names and attribute keys, - this also asserts each instrument was created as the kind and unit its - registry entry declares, and that `datasette.operation` only ever takes - its declared enum values. + Emitted metric names, kinds, units, attribute keys and enum values match + the registry, using the plugin testing helper. """ assert_metrics_conform( reg.METRICS, emitted_metrics["collector"], scope_name="datasette" @@ -564,7 +447,6 @@ async def test_metrics_conform_to_the_registry(emitted_metrics): @pytest.mark.asyncio async def test_every_registered_metric_is_emitted(emitted_metrics): - "Registered-but-never-collected, via the plugin kit's helper." assert_metrics_covered( reg.METRICS, emitted_metrics["collector"], scope_name="datasette" ) @@ -572,23 +454,7 @@ async def test_every_registered_metric_is_emitted(emitted_metrics): @pytest.mark.asyncio async def test_every_registered_metric_attribute_is_emitted(emitted_metrics): - """ - The direction nothing else catches: the docs must not describe a metric - attribute that no longer exists. - - Unlike the span-side attribute check, this does not skip `optional` - attributes. The only optional metric attribute is `error.type` on - `db.client.operation.duration`, and the workload reaches it from two - independent directions: the suppressed-error probe and the - custom_time_limit interrupt in `exercise()`, both of which raise through - `record_operation_duration`. So it is checked like any other attribute - rather than exempted; marking something optional here would opt it out of - verification entirely. - - Gauges with no registered attributes (`datasette.sql.threads.limit` and - `.queue_depth`) fall out correctly with no special case: their - `metric.attributes` is empty, so the inner loop makes no assertion. - """ + "Every registered metric attribute, including optional ones, is emitted." emitted_keys_by_metric = {} for metric_name, key in emitted_metrics["pairs"]: emitted_keys_by_metric.setdefault(metric_name, set()).add(key) @@ -596,8 +462,7 @@ async def test_every_registered_metric_attribute_is_emitted(emitted_metrics): missing = [] for metric in reg.METRICS: if str(metric) not in emitted_metrics["names"]: - # Not emitted at all - already reported by - # test_every_registered_metric_is_emitted; do not double-report. + # Reported by test_every_registered_metric_is_emitted continue emitted_keys = emitted_keys_by_metric.get(str(metric), set()) for attribute in metric.attributes: @@ -610,13 +475,7 @@ async def test_every_registered_metric_attribute_is_emitted(emitted_metrics): def test_prefix_span_lookup(): - """ - `prefix=True` matching, exercised directly. - - Core registers no prefix spans - the flag exists for plugin registries - (e.g. a `chat {model}` span family) - so without this the branch in - `span_for()` would be untested code the conformance tests never reach. - """ + "prefix=True matching, which core does not use but plugin registries can." hook = reg.SpanName("myplugin.hook.", "A hypothetical span family", prefix=True) spans = reg.SPANS + (hook,) assert reg.span_for("myplugin.hook.render_cell", spans=spans) is hook @@ -626,7 +485,6 @@ def test_prefix_span_lookup(): def test_exact_match_wins_over_prefix(): - "A prefix family can never shadow a span with a registered exact name." family = reg.SpanName("db.", "Greedy prefix", prefix=True) spans = (family,) + reg.SPANS assert reg.span_for("db.query", spans=spans) is reg.DB_QUERY diff --git a/tests/test_telemetry_testing_kit.py b/tests/test_telemetry_testing_kit.py index 01a09411..ddf3b3f6 100644 --- a/tests/test_telemetry_testing_kit.py +++ b/tests/test_telemetry_testing_kit.py @@ -1,8 +1,6 @@ """ -The plugin telemetry kit (`datasette.telemetry_testing` plus the public -registry classes), exercised the way a third-party plugin would use it: a -toy plugin registry, a toy tracer scope, and the kit's own fixtures and -conformance helpers. +Tests for datasette.telemetry_testing and the public registry classes, using +a toy plugin registry and instrumentation scope. """ import pytest @@ -54,8 +52,7 @@ def test_conformance_passes_for_a_conforming_workload(otel_spans): _run_workload() finished = otel_spans.get_finished_spans() assert_spans_conform(TOY_SPANS, finished, scope_name=SCOPE) - # Coverage direction needs prefix families seen too - the chat span - # resolves to the CHAT entry despite its variable suffix. + # The chat span matches the CHAT prefix entry: assert_spans_covered(TOY_SPANS, finished, scope_name=SCOPE) @@ -98,8 +95,7 @@ def test_coverage_catches_a_never_emitted_span(otel_spans): def test_scope_filter_ignores_other_scopes(otel_spans): - # Core's own spans are in the exporter too; a plugin's conformance run - # must not fail because of them. + # Spans from other scopes, including Datasette's own, are ignored: other = otel_trace.get_tracer("someone-else", "1.0") with other.start_as_current_span("not.in.the.toy.registry"): pass @@ -134,14 +130,9 @@ def test_linked_root_span_kwargs_with_no_current_span(otel_spans): def test_kit_module_itself_never_imports_the_sdk(): """ - The kit imports the SDK lazily, so a plugin importing it at module - level does not violate the api-only dependency rule. + The kit imports the SDK lazily, so plugins can import it at module level. - 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. Like - every subprocess-spawning test in this suite, running it late crashes - the interpreter on macOS/CPython 3.13 (SIGBUS in fork+exec once the - process holds enough threads) - see the comment there. + conftest.py runs this test first by name. Update it there if you rename it. """ assert_package_never_imports_sdk("datasette.telemetry_testing") @@ -159,8 +150,7 @@ from datasette.telemetry_testing import ( toy_meter = otel_metrics_api.get_meter(SCOPE, "0.1") -# Instrument names must be unique per meter for the SDK, so each test mints -# its own via this counter rather than re-registering one name. +# Gives each test a unique instrument name: _metric_ids = itertools.count() @@ -251,14 +241,13 @@ def test_metrics_covered_skips_optional_attributes(otel_metrics): error_type = reg.Attribute("toyplugin.error", "Only on failure.", optional=True) registry = _toy_metric_registry(name, attributes=(OUTCOME, error_type)) counter = toy_meter.create_counter(name, unit="{job}") - counter.add(1, {OUTCOME: "ok"}) # no error attribute - and that is fine + counter.add(1, {OUTCOME: "ok"}) # No error attribute otel_metrics.collect() assert_metrics_covered(registry, otel_metrics, scope_name=SCOPE) def test_metrics_scope_filter_ignores_other_scopes(otel_metrics): - # Core's own metrics are in the reader too; a plugin's conformance run - # must not fail because of them. + # Metrics from other scopes, including Datasette's own, are ignored: name = f"toyplugin.scoped.{next(_metric_ids)}" registry = _toy_metric_registry(name) counter = toy_meter.create_counter(name, unit="{job}")