From 8194cb5a1d90d734ae52375033648383ba345b7d Mon Sep 17 00:00:00 2001 From: Alex Garcia Date: Thu, 30 Jul 2026 17:30:52 -0700 Subject: [PATCH 01/13] Add opentelemetry-api dependency and datasette/telemetry.py scaffolding Datasette core is gaining OpenTelemetry spans alongside the existing hand-rolled tracer. This commit only lays the groundwork - no span is emitted yet. Core takes a runtime dependency on opentelemetry-api and nothing more. It deliberately never creates a TracerProvider, configures an exporter, or touches sampling: that belongs to whoever runs Datasette, normally via an opentelemetry-instrument agent. Owning a provider in core was tried in an earlier design and produced a cross-request span leak, a process-global provider that tests could not tear down, and a sampling env var that silently blanked output. With no provider installed every span is a NonRecordingSpan and costs approximately nothing. datasette/telemetry.py exposes the module-level tracer plus sql_attribute(), which truncates SQL to 2048 characters. On a public instance the SQL is attacker-controlled and unbounded - someone can paste a 10MB query into ?sql= - so it must never reach a telemetry pipeline verbatim. opentelemetry-sdk goes in the dev dependency group only, because the test suite needs it to assert on spans while the package itself must not import it. tests/test_telemetry.py enforces that by importing datasette in a fresh interpreter and inspecting sys.modules, which catches a lazy import inside a function body that a grep would miss. conftest.py gains a session-scoped autouse fixture installing an SDK provider with an InMemorySpanExporter. It has to be session-scoped because set_tracer_provider() is effectively once-per-process - a second call logs a warning and is ignored. SimpleSpanProcessor rather than BatchSpanProcessor, so assertions made right after a request never race a background export thread. The otel_spans fixture that later tickets assert against is added here too. test_datasette_package_never_imports_the_sdk is moved to the front of the run. Late in a serial run the pytest process holds enough threads that the fork half of subprocess' fork+exec segfaults the interpreter on macOS/CPython 3.13. That reproduces with any subprocess call in that position on an unmodified tree, so it is a pre-existing hazard rather than something this commit introduces; the repo already moves its other subprocess-spawning tests to the front for related reasons. Co-Authored-By: Claude Opus 5 --- datasette/telemetry.py | 24 ++++++++++++++++ pyproject.toml | 2 ++ tests/conftest.py | 62 +++++++++++++++++++++++++++++++++++++++++ tests/test_telemetry.py | 25 +++++++++++++++++ 4 files changed, 113 insertions(+) create mode 100644 datasette/telemetry.py create mode 100644 tests/test_telemetry.py diff --git a/datasette/telemetry.py b/datasette/telemetry.py new file mode 100644 index 00000000..6f5ed093 --- /dev/null +++ b/datasette/telemetry.py @@ -0,0 +1,24 @@ +""" +OpenTelemetry integration for Datasette core. + +Core depends on `opentelemetry-api` only. It never creates a +`TracerProvider`, 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` and costs approximately nothing. +""" + +from opentelemetry import trace as otel_trace + +tracer = otel_trace.get_tracer("datasette") + +MAX_SQL_LENGTH = 2048 + + +def sql_attribute(sql: str) -> str: + "Truncate SQL text so it is safe to attach to a span as an attribute." + sql = sql.strip() + if len(sql) <= MAX_SQL_LENGTH: + return sql + return sql[:MAX_SQL_LENGTH] + "…[truncated]" diff --git a/pyproject.toml b/pyproject.toml index e658955f..9dd231d7 100644 --- a/pyproject.toml +++ b/pyproject.toml @@ -40,6 +40,7 @@ dependencies = [ "setuptools", "pip", "pydantic>=2", + "opentelemetry-api>=1.37", ] [project.urls] @@ -70,6 +71,7 @@ dev = [ "cogapp>=3.3.0", "multipart-form-data-conformance==0.1a0", "ruff>=0.16.0", + "opentelemetry-sdk>=1.37", # docs "Sphinx==7.4.7", "furo==2025.9.25", diff --git a/tests/conftest.py b/tests/conftest.py index 12dce417..b01f111d 100644 --- a/tests/conftest.py +++ b/tests/conftest.py @@ -58,6 +58,62 @@ def find_free_port(): return sock.getsockname()[1] +_otel_span_exporter = None + + +@pytest.fixture(scope="session", autouse=True) +def _otel_provider(): + """ + Install a real OTel SDK TracerProvider + InMemorySpanExporter exactly + once, before any span is ever created in this process. + + This has to be session-scoped and autouse because + `opentelemetry.trace.set_tracer_provider()` is effectively + once-per-process: a second call logs a warning and is ignored. So the + install must happen exactly once, before anything asserts on spans. + + `datasette.telemetry.tracer` is a module-level `ProxyTracer`. Once a + provider exists, the first span it starts resolves a concrete tracer + and caches it permanently. It does *not* cache the no-op tracer, so + any span started before this fixture runs is merely lost rather than + poisoning the tracer for the rest of the process. If the SDK isn't + installed, do nothing: core spans stay no-op `NonRecordingSpan`s and + the rest of the suite is unaffected. + """ + global _otel_span_exporter + try: + from opentelemetry import trace as otel_trace + from opentelemetry.sdk.trace import TracerProvider + from opentelemetry.sdk.trace.export import SimpleSpanProcessor + from opentelemetry.sdk.trace.export.in_memory_span_exporter import ( + InMemorySpanExporter, + ) + except ImportError: + return + exporter = InMemorySpanExporter() + provider = TracerProvider() + # SimpleSpanProcessor exports synchronously on span end - no background + # batching thread, so assertions immediately after a request never race. + provider.add_span_processor(SimpleSpanProcessor(exporter)) + otel_trace.set_tracer_provider(provider) + _otel_span_exporter = exporter + + +@pytest.fixture +def otel_spans(): + """ + Function-scoped access to the finished-spans exporter: clears any spans + left over from previous tests, then yields the exporter so a test can + call `.get_finished_spans()` after making requests. Skips (rather than + fails) if the OTel SDK is not installed. + """ + pytest.importorskip("opentelemetry.sdk") + if _otel_span_exporter is None: + pytest.skip("OpenTelemetry SDK provider was not installed") + _otel_span_exporter.clear() + yield _otel_span_exporter + + @pytest.fixture def bare_ds(): """ @@ -168,6 +224,12 @@ 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. + move_to_front(items, "test_datasette_package_never_imports_the_sdk") def move_to_front(items, test_name): diff --git a/tests/test_telemetry.py b/tests/test_telemetry.py new file mode 100644 index 00000000..b71be504 --- /dev/null +++ b/tests/test_telemetry.py @@ -0,0 +1,25 @@ +import subprocess +import sys + + +def test_datasette_package_never_imports_the_sdk(): + """ + Core depends on opentelemetry-api only. The SDK is a test dependency. + + 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. + """ + code = ( + "import datasette.app, datasette.database, datasette.telemetry, sys; " + "print([m for m in sys.modules if m.startswith('opentelemetry.sdk')])" + ) + result = subprocess.run( + [sys.executable, "-c", code], capture_output=True, text=True, check=True + ) + assert ( + result.stdout.strip() == "[]" + ), f"datasette imported the OpenTelemetry SDK: {result.stdout.strip()}" From b40b06f1cbd87115336b2aa3f3eda7c083b6bbf2 Mon Sep 17 00:00:00 2001 From: Alex Garcia Date: Thu, 30 Jul 2026 17:45:32 -0700 Subject: [PATCH 02/13] Emit a db.query span around Database.execute() Datasette's existing tracer times a "sql" block that wraps a good deal more than the query itself - queueing onto the thread pool, the pool wait, and result marshalling all disappear into one number. That is simonw/datasette#1730, "SQL tracing should much more closely track the SQL query execution", open since 2022. A db.query span here is the outer half of the answer; a later change adds the inner span drawn around the sqlite3 call itself, and the gap between the two is exactly the thread pool wait the current tracer folds away. The span carries OTel semantic-convention attributes (db.system, db.namespace, db.query.text) plus a few datasette.* ones. db.query.text goes through sql_attribute(), which caps it at 2048 characters, because on a public instance the SQL is attacker-supplied and unbounded. Only len(params) is recorded, never a parameter value. The existing `with trace(...)` wrapper stays exactly where it is and the new span nests inside it. This change removes nothing: ?_trace=1 and the trace_debug setting keep working unchanged. The two systems are independent code paths. Exception handling on the span is explicit rather than inherited from start_as_current_span's defaults, which would record the exception and set StatusCode.ERROR on anything passing through. That is wrong here because some SQL failures are the expected answer. ArrayFacet.suggest() runs json_type() against every column precisely to discover which ones raise "malformed JSON", and passes log_sql_errors=False to say so. Left to the defaults, a table with N text columns marks N queries per page as failed - burying genuine failures and tripping any alerting keyed on span status. Measured on a plain table page before this: 4 error spans out of 225, all expected. Suppressed errors now leave the status UNSET and set datasette.sql_error_suppressed instead, so they stay discoverable without reading as failures. QueryInterrupted still sets ERROR unconditionally. That is not quite right either - facet suggestion is designed to time out - but the fix needs its own reasoning and lands separately. Behaviour change worth calling out: time_limit_ms is hoisted out of sql_operation_in_thread so the span can record it on the event loop. It is therefore read at call time rather than at thread-execution time. Benign in practice, since ds.sql_time_limit_ms is set at startup, but it is a real change. Co-Authored-By: Claude Opus 5 --- datasette/database.py | 54 +++++++++++-- tests/test_telemetry.py | 169 ++++++++++++++++++++++++++++++++++++++++ 2 files changed, 217 insertions(+), 6 deletions(-) diff --git a/datasette/database.py b/datasette/database.py index e162d34e..f78eb925 100644 --- a/datasette/database.py +++ b/datasette/database.py @@ -11,8 +11,10 @@ from collections import namedtuple from pathlib import Path import sqlite_utils +from opentelemetry.trace import Status, StatusCode from .inspect import inspect_hash +from .telemetry import sql_attribute, tracer from .tracer import trace from .utils import ( call_with_supported_arguments, @@ -529,12 +531,11 @@ class Database: """Executes sql against db_name in a thread""" self._check_not_closed() page_size = page_size or self.ds.page_size + time_limit_ms = self.ds.sql_time_limit_ms + if custom_time_limit and custom_time_limit < time_limit_ms: + time_limit_ms = custom_time_limit def sql_operation_in_thread(conn): - time_limit_ms = self.ds.sql_time_limit_ms - if custom_time_limit and custom_time_limit < time_limit_ms: - time_limit_ms = custom_time_limit - with sqlite_timelimit(conn, time_limit_ms): try: cursor = conn.cursor() @@ -565,8 +566,49 @@ class Database: else: return Results(rows, False, cursor.description) - with trace("sql", database=self.name, sql=sql.strip(), params=params): - results = await self.execute_fn(sql_operation_in_thread) + # 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", + record_exception=False, + set_status_on_exception=False, + ) as span: + span.set_attribute("db.system", "sqlite") + span.set_attribute("db.namespace", self.name) + span.set_attribute("db.query.text", sql_attribute(sql)) + span.set_attribute("datasette.time_limit_ms", time_limit_ms) + if params: + span.set_attribute("datasette.param_count", len(params)) + try: + results = await self.execute_fn(sql_operation_in_thread) + except QueryInterrupted as e: + span.set_status(Status(StatusCode.ERROR, str(e))) + span.set_attribute("datasette.interrupted", True) + span.record_exception(e) + 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. + if log_sql_errors: + span.record_exception(e) + span.set_status(Status(StatusCode.ERROR, str(e))) + else: + span.set_attribute("datasette.sql_error_suppressed", True) + raise + span.set_attribute("datasette.truncated", results.truncated) + span.set_attribute("datasette.rows_returned", len(results.rows)) return results @property diff --git a/tests/test_telemetry.py b/tests/test_telemetry.py index b71be504..a13898ff 100644 --- a/tests/test_telemetry.py +++ b/tests/test_telemetry.py @@ -1,6 +1,31 @@ +import json +import sqlite3 import subprocess import sys +import pytest +from opentelemetry.trace import StatusCode + +from datasette.telemetry import MAX_SQL_LENGTH, sql_attribute + +SECRET_PARAM_VALUE = "SUPER_SECRET_PARAM_VALUE_XYZ_123" + +INVALID_SQL = "select this_is_not_valid_sql from nowhere" + + +def _db_query_spans(otel_spans): + return [span for span in otel_spans.get_finished_spans() if span.name == "db.query"] + + +def _all_attribute_values(otel_spans): + "Every attribute value across every finished span, for the 'no leaked param values' test." + values = [] + for span in otel_spans.get_finished_spans(): + values.extend((span.attributes or {}).values()) + for event in span.events: + values.extend((event.attributes or {}).values()) + return values + def test_datasette_package_never_imports_the_sdk(): """ @@ -23,3 +48,147 @@ def test_datasette_package_never_imports_the_sdk(): assert ( result.stdout.strip() == "[]" ), f"datasette imported the OpenTelemetry SDK: {result.stdout.strip()}" + + +@pytest.mark.asyncio +async def test_db_query_span_basic_attributes(ds_client, otel_spans): + response = await ds_client.get("/fixtures/-/query.json?sql=select+1") + assert response.status_code == 200 + + spans = _db_query_spans(otel_spans) + assert spans, "expected at least one db.query span" + span = spans[-1] + + assert span.attributes["db.system"] == "sqlite" + assert span.attributes["db.namespace"] == "fixtures" + assert span.attributes["db.query.text"] == "select 1" + assert span.attributes["datasette.rows_returned"] == 1 + assert span.attributes["datasette.truncated"] is False + assert isinstance(span.attributes["datasette.time_limit_ms"], int) + assert span.status.status_code == StatusCode.UNSET + + +@pytest.mark.asyncio +async def test_facetable_request_produces_db_query_spans(ds_client, otel_spans): + response = await ds_client.get("/fixtures/facetable.json") + assert response.status_code == 200 + + 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) + assert all(span.attributes["db.query.text"] for span in spans) + # Rendering the page also queries the internal database, so only some of + # these spans belong to "fixtures". + assert any(span.attributes["db.namespace"] == "fixtures" for span in 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. + assert sql_attribute(" select 1\n") == "select 1" + + long_sql = "select 1 -- " + ("x" * 3000) + truncated = sql_attribute(long_sql) + assert len(truncated) == MAX_SQL_LENGTH + len("…[truncated]") + assert truncated.startswith("select 1 -- ") + assert truncated.endswith("…[truncated]") + + +@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. + long_sql = "select 1 -- " + ("x" * 3000) + response = await ds_client.get("/fixtures/-/query.json", params={"sql": long_sql}) + assert response.status_code == 200 + + spans = _db_query_spans(otel_spans) + assert spans + assert any(len(span.attributes["db.query.text"]) > 100 for span in spans), ( + "expected the long query to reach a span - otherwise this test would " + "pass even if truncation were never applied" + ) + for span in spans: + recorded = span.attributes["db.query.text"] + assert len(recorded) <= MAX_SQL_LENGTH + len("…[truncated]") + + +@pytest.mark.asyncio +async def test_no_span_attribute_ever_contains_a_parameter_value(ds_client, otel_spans): + response = await ds_client.get( + "/fixtures/-/query.json", + 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. + assert SECRET_PARAM_VALUE in json.dumps(response.json()) + + for value in _all_attribute_values(otel_spans): + if isinstance(value, str): + assert SECRET_PARAM_VALUE not in value + elif isinstance(value, (list, tuple)): + for item in value: + if isinstance(item, str): + assert SECRET_PARAM_VALUE not in item + + spans = _db_query_spans(otel_spans) + assert spans + span = spans[-1] + assert "select :secret" in span.attributes["db.query.text"] + assert span.attributes.get("datasette.param_count") == 1 + + +@pytest.mark.asyncio +async def test_query_interrupted_sets_error_status(ds_client, otel_spans): + response = await ds_client.get( + "/fixtures/-/query.json", + params={"sql": "select sleep(0.05)", "_timelimit": 5}, + ) + assert response.status_code == 400 + + spans = _db_query_spans(otel_spans) + assert spans + span = spans[-1] + assert span.status.status_code == StatusCode.ERROR + assert span.attributes["datasette.interrupted"] is True + assert span.events + assert all(event.name == "exception" for event in span.events) + + +@pytest.mark.asyncio +async def test_unsuppressed_sql_error_is_a_span_error(ds_client, otel_spans): + db = ds_client.ds.get_database("fixtures") + with pytest.raises(sqlite3.OperationalError): + await db.execute(INVALID_SQL) + + spans = _db_query_spans(otel_spans) + assert spans + span = spans[-1] + assert span.status.status_code == StatusCode.ERROR + assert any(event.name == "exception" for event in span.events) + assert "datasette.sql_error_suppressed" not in span.attributes + + +@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. + """ + db = ds_client.ds.get_database("fixtures") + with pytest.raises(sqlite3.OperationalError): + await db.execute(INVALID_SQL, log_sql_errors=False) + + spans = _db_query_spans(otel_spans) + assert spans + span = spans[-1] + assert span.status.status_code == StatusCode.UNSET + assert span.attributes["datasette.sql_error_suppressed"] is True + assert not [event for event in span.events if event.name == "exception"] From 59bfa495cc9b31f1ba5920aa50f8916c6ef6d53a Mon Sep 17 00:00:00 2001 From: Alex Garcia Date: Thu, 30 Jul 2026 17:52:55 -0700 Subject: [PATCH 03/13] Emit db.query spans from the three write entry points execute_write(), execute_write_script() and execute_write_many() were the only Database methods that ran SQL without producing an OpenTelemetry span, so any instance doing writes - which is every instance, since Datasette builds its internal catalog through these methods at startup - showed reads in a trace and nothing else. The same db.system, db.namespace and db.query.text attributes the read path already sets now appear here, with db.query.text going through sql_attribute() so attacker-supplied SQL cannot put an unbounded string on a span. execute_write_many() records the parameter-set count as datasette.param_sets, not datasette.rows_returned. executemany() consumes parameter sets and returns no rows at all, so a rows_returned name would be describing something that does not exist - and a consumer building a "rows written" dashboard on top of it would be charting the wrong number. These spans only cover the event-loop side of a write. The time actually spent waiting on the write queue and executing on the write thread is not attributed yet; that needs context propagation across the thread boundary and lands separately. Writes with block=False are worse still - execute_write_fn returns before the write happens, so the span closes early. Span links fix that later. As with the read path, the existing `with trace(...)` wrappers stay put and the new spans nest inside them, so ?_trace=1 keeps working unchanged - including execute_write_many's `count`, which the old tracer stashes through the context manager's return value. Co-Authored-By: Claude Opus 5 --- datasette/database.py | 50 +++++++++++++++++++++------ tests/test_telemetry.py | 75 +++++++++++++++++++++++++++++++++++++++++ 2 files changed, 114 insertions(+), 11 deletions(-) diff --git a/datasette/database.py b/datasette/database.py index f78eb925..cc35c038 100644 --- a/datasette/database.py +++ b/datasette/database.py @@ -259,10 +259,21 @@ class Database: cursor, return_all=return_all, returning_limit=returning_limit ) - with trace("sql", database=self.name, sql=sql.strip(), params=params): - results = await self.execute_write_fn( - _inner, block=block, request=request, transaction=transaction - ) + # 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 + ): + with tracer.start_as_current_span("db.query") as span: + span.set_attribute("db.system", "sqlite") + span.set_attribute("db.namespace", self.name) + span.set_attribute("db.query.text", sql_attribute(sql)) + if params: + span.set_attribute("datasette.param_count", len(params)) + results = await self.execute_write_fn( + _inner, block=block, request=request, transaction=transaction + ) return results async def execute_write_script(self, sql, block=True, request=None): @@ -271,10 +282,18 @@ class Database: def _inner(conn): return conn.executescript(sql) - with trace("sql", database=self.name, sql=sql.strip(), executescript=True): - results = await self.execute_write_fn( - _inner, block=block, transaction=False, request=request - ) + # Nested on purpose - see the note in execute_write(). + with trace( # noqa: SIM117 + "sql", database=self.name, sql=sql.strip(), executescript=True + ): + with tracer.start_as_current_span("db.query") as span: + span.set_attribute("db.system", "sqlite") + span.set_attribute("db.namespace", self.name) + span.set_attribute("db.query.text", sql_attribute(sql)) + span.set_attribute("datasette.executescript", True) + results = await self.execute_write_fn( + _inner, block=block, transaction=False, request=request + ) return results async def execute_write_many(self, sql, params_seq, block=True, request=None): @@ -291,12 +310,21 @@ 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: - results, count = await self.execute_write_fn( - _inner, block=block, request=request - ) + with tracer.start_as_current_span("db.query") as span: + span.set_attribute("db.system", "sqlite") + span.set_attribute("db.namespace", self.name) + span.set_attribute("db.query.text", sql_attribute(sql)) + span.set_attribute("datasette.executemany", True) + 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("datasette.param_sets", count) kwargs["count"] = count return results diff --git a/tests/test_telemetry.py b/tests/test_telemetry.py index a13898ff..d8e89446 100644 --- a/tests/test_telemetry.py +++ b/tests/test_telemetry.py @@ -6,6 +6,7 @@ import sys import pytest from opentelemetry.trace import StatusCode +from datasette.app import Datasette from datasette.telemetry import MAX_SQL_LENGTH, sql_attribute SECRET_PARAM_VALUE = "SUPER_SECRET_PARAM_VALUE_XYZ_123" @@ -17,6 +18,21 @@ def _db_query_spans(otel_spans): return [span for span in otel_spans.get_finished_spans() if span.name == "db.query"] +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. + """ + return [ + span + for span in _db_query_spans(otel_spans) + if span.attributes["db.namespace"] == namespace + ] + + def _all_attribute_values(otel_spans): "Every attribute value across every finished span, for the 'no leaked param values' test." values = [] @@ -192,3 +208,62 @@ async def test_suppressed_sql_error_is_not_a_span_error(ds_client, otel_spans): assert span.status.status_code == StatusCode.UNSET assert span.attributes["datasette.sql_error_suppressed"] is True assert not [event for event in span.events if event.name == "exception"] + + +@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. + 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"]) + + spans = _spans_for_namespace(otel_spans, "t03_write_span") + assert spans, "expected db.query spans from execute_write()" + span = spans[-1] + + assert span.attributes["db.system"] == "sqlite" + assert span.attributes["db.namespace"] == "t03_write_span" + assert span.attributes["db.query.text"] == ( + "insert into docs (id, name) values (?, ?)" + ) + assert span.attributes["datasette.param_count"] == 2 + + +@pytest.mark.asyncio +async def test_execute_write_script_sets_executescript_attribute(otel_spans): + db = Datasette(memory=True).add_memory_database("t03_write_script_span") + await db.execute_write_script( + "create table docs (id integer primary key);\n" + "insert into docs (id) values (1);" + ) + + spans = _spans_for_namespace(otel_spans, "t03_write_script_span") + assert spans, "expected a db.query span from execute_write_script()" + span = spans[-1] + + assert span.attributes["db.system"] == "sqlite" + assert span.attributes["datasette.executescript"] is True + assert "insert into docs" in span.attributes["db.query.text"] + + +@pytest.mark.asyncio +async def test_execute_write_many_records_param_sets_not_rows_returned(otel_spans): + db = Datasette(memory=True).add_memory_database("t03_write_many_span") + 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, 6)] + ) + + spans = _spans_for_namespace(otel_spans, "t03_write_many_span") + many_spans = [ + span for span in spans if span.attributes.get("datasette.executemany") is True + ] + assert len(many_spans) == 1 + 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 From 582d79a148f65e4b6e1295719dbbe3886536612d Mon Sep 17 00:00:00 2001 From: Alex Garcia Date: Thu, 30 Jul 2026 18:05:34 -0700 Subject: [PATCH 04/13] Propagate otel context across the thread boundaries Spans created on a worker thread resolve their parent from that thread's ambient context, so without this every span produced below Database came back as an unparented root, disconnected from the request that caused it. Carrying the caller's context across each boundary is also what makes the thread-pool wait visible: db.query covers the full round trip, the new db.query.execute covers only the work inside the worker, and the gap between them is the queueing the old tracer folds invisibly into one number. - execute_fn()'s executor.submit() and execute_isolated_fn()'s run_in_executor() (immutable databases) now run the callable inside a contextvars.copy_context(). A *fresh* copy per submit is required: concurrently entering one shared Context raises "RuntimeError: cannot enter context ... already entered". - WriteTask carries the otel Context captured on the event loop at enqueue time plus an enqueued_at_ns timestamp (both need __slots__ entries, or they fail with AttributeError at runtime). _execute_writes attaches that context right after the _SHUTDOWN check and detaches it in a finally spanning all three execution branches - the write thread is persistent and shared, so a leaked token would grow its context stack for every write processed afterwards, and a wrong-token detach only logs rather than raising. - New spans: db.query.execute (read worker thread), db.write.queue_wait (explicit start/end timestamps, so its duration is the real enqueue -> dequeue wait rather than the microseconds spent building the span) and db.write.execute (skipped in the conn_exception branch, where fn never runs). db.query.execute honours log_sql_errors for the same reason db.query does: facet suggestion probes with log_sql_errors=False and would otherwise paint two red spans per text column on every table page. - The write-thread warm-up prepare_connection is left as a documented orphan root - no caller context exists that early. Tests assert actual parent/child span-id relationships in a shared trace, not just that spans exist, since an unparented root looks identical to a correct span if you only check presence. Note that copy_context() copies every ContextVar, not just OTel's, so Datasette's own context vars (_skip_permission_checks, _permission_check_cache, _in_datasette_client) now flow into worker threads where they previously did not. Co-Authored-By: Claude Opus 5 --- datasette/database.py | 228 ++++++++++++++++++++++--------- tests/test_internals_database.py | 109 +++++++++++++++ tests/test_telemetry.py | 192 +++++++++++++++++++++++++- 3 files changed, 463 insertions(+), 66 deletions(-) diff --git a/datasette/database.py b/datasette/database.py index cc35c038..d7cbc99b 100644 --- a/datasette/database.py +++ b/datasette/database.py @@ -1,16 +1,19 @@ import asyncio import atexit +import contextvars import inspect import os import queue import sys import tempfile import threading +import time import uuid from collections import namedtuple from pathlib import Path import sqlite_utils +from opentelemetry import context as otel_context_api from opentelemetry.trace import Status, StatusCode from .inspect import inspect_hash @@ -351,9 +354,15 @@ class Database: return _run() 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 + # write queue to block; run against a fresh read-only connection. + # 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. + ctx = contextvars.copy_context() return await asyncio.get_running_loop().run_in_executor( - self.ds.executor, _run + self.ds.executor, ctx.run, _run ) # Threaded mode - send to write thread return await self._send_to_write_thread(fn, isolated_connection=True) @@ -458,8 +467,21 @@ class Database: task_id = uuid.uuid5(uuid.NAMESPACE_DNS, "datasette.io") loop = asyncio.get_running_loop() reply_future = loop.create_future() + # Captured here, on the event loop, at enqueue time: the otel + # Context (carrying the enclosing db.query span, if any) and the + # timestamp used to build the db.write.queue_wait span once this + # task is dequeued on the write thread. self._write_queue.put( - WriteTask(fn, task_id, loop, reply_future, isolated_connection, transaction) + WriteTask( + fn, + task_id, + loop, + reply_future, + isolated_connection, + transaction, + otel_context_api.get_current(), + time.time_ns(), + ) ) if block: return await reply_future @@ -473,6 +495,9 @@ 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 caller otel context yet to attach - any spans + # created by plugin hooks here are orphans (roots). self.ds._prepare_connection(conn, self.name) except Exception as e: # noqa: BLE001 # Stored and re-raised to whoever queues the next write @@ -487,40 +512,79 @@ class Database: # Best-effort close as the write thread exits pass return - exception = None - result = None - if conn_exception is not None: - exception = conn_exception - elif task.isolated_connection: - try: - isolated_connection = self.connect(write=True) + # Restore the caller's otel context (captured on the event loop + # at enqueue time) so spans created while processing this task + # parent correctly to the request that queued it. 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. + token = otel_context_api.attach(task.otel_context) + 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. + tracer.start_span( + "db.write.queue_wait", start_time=task.enqueued_at_ns + ).end(end_time=time.time_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: - result = task.fn(isolated_connection) - finally: - isolated_connection.close() - try: - self._all_file_connections.remove(isolated_connection) - except ValueError: - # Was probably a memory connection - pass - except Exception as e: # noqa: BLE001 - # Write thread must survive any task failure or the database wedges - sys.stderr.write(f"{e}\n") - sys.stderr.flush() - exception = e - else: - try: - if task.transaction: - with conn: - conn.execute("BEGIN IMMEDIATE") - result = task.fn(conn) - else: - result = task.fn(conn) - except Exception as e: # noqa: BLE001 - sys.stderr.write(f"{e}\n") - sys.stderr.flush() - exception = e - _deliver_write_result(task, result, exception) + with tracer.start_as_current_span("db.write.execute") as span: + span.set_attribute( + "datasette.isolated_connection", + task.isolated_connection, + ) + span.set_attribute( + "datasette.transaction", task.transaction + ) + isolated_connection = self.connect(write=True) + try: + result = task.fn(isolated_connection) + finally: + isolated_connection.close() + try: + self._all_file_connections.remove( + isolated_connection + ) + except ValueError: + # Was probably a memory connection + pass + except Exception as e: # noqa: BLE001 + # Write thread must survive any task failure or the database wedges + sys.stderr.write(f"{e}\n") + sys.stderr.flush() + exception = e + else: + try: + with tracer.start_as_current_span("db.write.execute") as span: + span.set_attribute( + "datasette.isolated_connection", + task.isolated_connection, + ) + span.set_attribute( + "datasette.transaction", task.transaction + ) + if task.transaction: + with conn: + conn.execute("BEGIN IMMEDIATE") + result = task.fn(conn) + else: + result = task.fn(conn) + except Exception as e: # noqa: BLE001 + sys.stderr.write(f"{e}\n") + sys.stderr.flush() + exception = e + _deliver_write_result(task, result, exception) + finally: + otel_context_api.detach(token) async def execute_fn(self, fn): self._check_not_closed() @@ -542,7 +606,13 @@ class Database: with self._pending_execute_futures_lock: self._check_not_closed() - future = self.ds.executor.submit(in_thread) + # 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. + ctx = contextvars.copy_context() + future = self.ds.executor.submit(ctx.run, in_thread) self._pending_execute_futures.add(future) future.add_done_callback(self._remove_pending_execute_future) return await asyncio.wrap_future(future) @@ -564,35 +634,51 @@ class Database: time_limit_ms = custom_time_limit def sql_operation_in_thread(conn): - with sqlite_timelimit(conn, time_limit_ms): - try: - cursor = conn.cursor() - cursor.execute(sql, params if params is not None else {}) - max_returned_rows = self.ds.max_returned_rows - if max_returned_rows == page_size: - max_returned_rows += 1 - if max_returned_rows and truncate: - rows = cursor.fetchmany(max_returned_rows + 1) - truncated = len(rows) > max_returned_rows - rows = rows[:max_returned_rows] - else: - rows = cursor.fetchall() - truncated = False - except (sqlite3.OperationalError, sqlite3.DatabaseError) as e: - if e.args == ("interrupted",): - raise QueryInterrupted(e, sql, params) - if log_sql_errors: - sys.stderr.write( - f"ERROR: conn={conn}, sql = {sql!r}, params = {params}: {e}\n" - ) - sys.stderr.flush() - raise + # 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. + # + # Callers passing log_sql_errors=False are probing and treat a + # failure as an expected answer - see the matching handling on the + # db.query span in execute(). Without this, facet suggestion marks + # two spans per text column as failed on every table page. + with tracer.start_as_current_span( + "db.query.execute", + record_exception=log_sql_errors, + set_status_on_exception=log_sql_errors, + ): + with sqlite_timelimit(conn, time_limit_ms): + try: + cursor = conn.cursor() + cursor.execute(sql, params if params is not None else {}) + max_returned_rows = self.ds.max_returned_rows + if max_returned_rows == page_size: + max_returned_rows += 1 + if max_returned_rows and truncate: + rows = cursor.fetchmany(max_returned_rows + 1) + truncated = len(rows) > max_returned_rows + rows = rows[:max_returned_rows] + else: + rows = cursor.fetchall() + truncated = False + except (sqlite3.OperationalError, sqlite3.DatabaseError) as e: + if e.args == ("interrupted",): + raise QueryInterrupted(e, sql, params) + if log_sql_errors: + sys.stderr.write( + f"ERROR: conn={conn}, sql = {sql!r}, params = {params}: {e}\n" + ) + sys.stderr.flush() + raise - if truncate: - return Results(rows, truncated, cursor.description) + if truncate: + return Results(rows, truncated, cursor.description) - else: - return Results(rows, False, cursor.description) + 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 @@ -924,16 +1010,26 @@ def _apply_write_wrapper(fn, wrapper_factory, track_event): class WriteTask: __slots__ = ( + "enqueued_at_ns", "fn", "isolated_connection", "loop", + "otel_context", "reply_future", "task_id", "transaction", ) def __init__( - self, fn, task_id, loop, reply_future, isolated_connection, transaction + self, + fn, + task_id, + loop, + reply_future, + isolated_connection, + transaction, + otel_context, + enqueued_at_ns, ): self.fn = fn self.task_id = task_id @@ -941,6 +1037,8 @@ class WriteTask: self.reply_future = reply_future self.isolated_connection = isolated_connection self.transaction = transaction + self.otel_context = otel_context + self.enqueued_at_ns = enqueued_at_ns def _deliver_write_result(task, result, exception): diff --git a/tests/test_internals_database.py b/tests/test_internals_database.py index b1093b1c..ce0d7a53 100644 --- a/tests/test_internals_database.py +++ b/tests/test_internals_database.py @@ -3,11 +3,13 @@ Tests for the datasette.database.Database class """ import asyncio +import threading import uuid from types import SimpleNamespace import pytest import sqlite_utils +from opentelemetry import context as otel_context_api from datasette.app import Datasette from datasette.database import ( @@ -1223,3 +1225,110 @@ async def test_database_close_is_idempotent(tmpdir): # Second call should be a no-op, not raise db.close() ds._internal_database.close() + + +_CONTEXT_LEAK_MARKER_KEY = "otel-context-leak-marker" + + +@pytest.mark.asyncio +@pytest.mark.parametrize("num_sql_threads", (0, 1)) +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. + + 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. + """ + name = f"context_leak_test_{num_sql_threads}" + db_path = tmp_path / f"{name}.db" + sqlite3.connect(db_path).close() + ds = Datasette([str(db_path)], settings={"num_sql_threads": num_sql_threads}) + db = ds.get_database(name) + await db.execute_write("create table t (id integer primary key)") + + write_thread_name = f"_execute_writes for database {name}" + depth = {"value": 0} + real_attach = otel_context_api.attach + real_detach = otel_context_api.detach + + def counting_attach(context): + token = real_attach(context) + if threading.current_thread().name == write_thread_name: + depth["value"] += 1 + return token + + def counting_detach(token): + real_detach(token) + 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. + monkeypatch.setattr(otel_context_api, "attach", counting_attach) + monkeypatch.setattr(otel_context_api, "detach", counting_detach) + + seen_markers = [] + seen_depths = [] + + def probe(conn): + seen_markers.append(otel_context_api.get_value(_CONTEXT_LEAK_MARKER_KEY)) + seen_depths.append(depth["value"]) + + 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: + for i in range(5): + ctx = otel_context_api.set_value(_CONTEXT_LEAK_MARKER_KEY, f"marker-{i}") + token = real_attach(ctx) + try: + if i == 2: + with pytest.raises(ValueError): + await db.execute_write_fn(failing_probe) + else: + await db.execute_write_fn(probe) + 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. + assert otel_context_api.get_value(_CONTEXT_LEAK_MARKER_KEY) is None + await db.execute_write_fn(probe) + finally: + db.close() + + assert seen_markers == [ + "marker-0", + "marker-1", + "marker-2", + "marker-3", + "marker-4", + None, + ] + assert len(set(seen_depths)) == 1, ( + f"write thread context stack grew across tasks: {seen_depths} - " + "a token was attached without being detached" + ) diff --git a/tests/test_telemetry.py b/tests/test_telemetry.py index d8e89446..f232a39d 100644 --- a/tests/test_telemetry.py +++ b/tests/test_telemetry.py @@ -2,12 +2,15 @@ import json import sqlite3 import subprocess import sys +import time import pytest +import sqlite_utils from opentelemetry.trace import StatusCode from datasette.app import Datasette -from datasette.telemetry import MAX_SQL_LENGTH, sql_attribute +from datasette.database import Database +from datasette.telemetry import MAX_SQL_LENGTH, sql_attribute, tracer SECRET_PARAM_VALUE = "SUPER_SECRET_PARAM_VALUE_XYZ_123" @@ -33,6 +36,26 @@ 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. + """ + return [ + span + for span in otel_spans.get_finished_spans() + if span.name == name + and span.parent is not None + and span.parent.span_id == parent_span_context.span_id + and span.parent.trace_id == parent_span_context.trace_id + and span.context.trace_id == parent_span_context.trace_id + ] + + def _all_attribute_values(otel_spans): "Every attribute value across every finished span, for the 'no leaked param values' test." values = [] @@ -267,3 +290,170 @@ async def test_execute_write_many_records_param_sets_not_rows_returned(otel_span # 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. + + +@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. + response = await ds_client.get("/fixtures/-/query.json?sql=select+1") + assert response.status_code == 200 + + query_spans = [ + span + for span in _spans_for_namespace(otel_spans, "fixtures") + if span.attributes["db.query.text"] == "select 1" + ] + assert query_spans, "expected a db.query span for 'select 1'" + query_span = query_spans[-1] + + assert [ + span + for span in otel_spans.get_finished_spans() + if span.name == "db.query.execute" + ], "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. + 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. + db_path = tmp_path / "t04_immutable.db" + sqlite_utils.Database(str(db_path))["t"].insert({"id": 1}, pk="id") + + ds = Datasette() + db = Database(ds, path=str(db_path), is_mutable=False) + ds.add_database(db, name="t04_immutable") + + def fn(conn): + with tracer.start_as_current_span("t04-child-in-isolated-worker"): + pass + + try: + with tracer.start_as_current_span("t04-parent-on-event-loop") as parent: + parent_context = parent.get_span_context() + await db.execute_isolated_fn(fn) + finally: + ds.remove_database("t04_immutable") + + assert [ + span + 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" + children = _children_named( + otel_spans, "t04-child-in-isolated-worker", parent_context + ) + assert len(children) == 1 + + +@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. + db = Datasette(memory=True).add_memory_database("t04_write_spans") + await db.execute_write("create table docs (id integer primary key)") + + query_spans = _spans_for_namespace(otel_spans, "t04_write_spans") + assert query_spans, "expected a db.query span from execute_write()" + query_span = query_spans[-1] + + queue_wait_children = _children_named( + otel_spans, "db.write.queue_wait", query_span.context + ) + execute_children = _children_named( + otel_spans, "db.write.execute", query_span.context + ) + assert len(queue_wait_children) == 1 + assert len(execute_children) == 1 + + 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. + 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. + ds = Datasette(memory=True) + db = ds.add_memory_database("t04_queue_wait") + await db.execute_write("create table docs (id integer primary key)") + + 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. + _, 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 + + query_spans = [ + span + for span in _spans_for_namespace(otel_spans, "t04_queue_wait") + if span.attributes["db.query.text"] == "insert into docs (id) values (1)" + ] + assert query_spans, "expected a db.query span for the queued-behind insert" + queue_wait_children = _children_named( + otel_spans, "db.write.queue_wait", query_spans[-1].context + ) + 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. + assert duration_ns > 10_000_000, f"queue wait was only {duration_ns}ns" + + +@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. + """ + db = ds_client.ds.get_database("fixtures") + with pytest.raises(sqlite3.OperationalError): + await db.execute(INVALID_SQL, log_sql_errors=False) + + execute_spans = [ + span + for span in otel_spans.get_finished_spans() + if span.name == "db.query.execute" + ] + assert execute_spans + span = execute_spans[-1] + assert span.status.status_code == StatusCode.UNSET + assert not [event for event in span.events if event.name == "exception"] From 4ebec0b1ea4a9e49cbf062a8882d774cd2fa9a36 Mon Sep 17 00:00:00 2001 From: Alex Garcia Date: Thu, 30 Jul 2026 18:16:46 -0700 Subject: [PATCH 05/13] Give startup's ~20 orphan spans somewhere to belong invoke_startup() runs before any request exists, so nothing it does has an ambient span to nest under. Measured on a fresh instance: 19 distinct traces, 19 of them single- or few-span roots - the register_* hook dispatches, the internal catalog's db.query reads and its db.write.* catalog writes. In a trace UI that is nineteen pieces of noise sitting next to every real trace, which for an operator opening Jaeger for the first time is the difference between "this works" and "this is unusable". Bracketing the whole method body in one datasette.startup span takes that to 1. This is not a propagation fix - ticket 04's context propagation was already correct, it simply had nothing to propagate. The bulk of the app.py diff is re-indentation; `git diff -w` shows the real change (plus one line-length rewrap black applied to the StartupError raise). register_output_renderer and asgi_wrapper stay orphans deliberately: both are dispatched from Datasette.__init__ / .app(), before invoke_startup() exists to be called, and wrapping them would mean holding a span open across object construction in library code that may never serve a request. Suppressing instrumentation during warm-up was rejected as an alternative: a slow prepare_connection runs on every connection, not just at startup, and is exactly what tracing should reveal. Also corrects the stale write-thread warm-up comment in database.py. It is still a root, but for a reason worth stating precisely: a raw threading.Thread does not inherit the starting thread's context, so the datasette.startup span current on the event loop does not reach it. Read connections do warm up under copy_context() and nest correctly. Co-Authored-By: Claude Opus 5 --- datasette/app.py | 109 ++++++++++++++++++++++------------------ datasette/database.py | 11 +++- tests/test_telemetry.py | 86 +++++++++++++++++++++++++++++++ 3 files changed, 156 insertions(+), 50 deletions(-) diff --git a/datasette/app.py b/datasette/app.py index 42be7425..d3626ab2 100644 --- a/datasette/app.py +++ b/datasette/app.py @@ -49,6 +49,7 @@ from .events import Event from .plugins import DEFAULT_PLUGINS, get_plugins, pm from .renderer import json_renderer from .resources import DatabaseResource, TableResource +from .telemetry import tracer from .tokens import TokenInvalid from .tracer import AsgiTracer from .url_builder import Urls @@ -778,57 +779,69 @@ class Datasette: # This must be called for Datasette to be in a usable state if self._startup_invoked: return - # Register event classes - event_classes = [] - for hook in pm.hook.register_events(datasette=self): - extra_classes = await await_me_maybe(hook) - if extra_classes: - event_classes.extend(extra_classes) - self.event_classes = tuple(event_classes) + # invoke_startup() runs before any request exists, so every span its + # children create - the register_* hook dispatches, the internal + # catalog's db.query/db.write spans, and the prepare_connection + # warm-up of the read connections those touch - would otherwise be + # its own orphan root trace: around twenty of them on a fresh + # instance. Bracketing the whole thing gives them somewhere to belong. + # 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. + with tracer.start_as_current_span("datasette.startup"): + # Register event classes + event_classes = [] + for hook in pm.hook.register_events(datasette=self): + extra_classes = await await_me_maybe(hook) + if extra_classes: + event_classes.extend(extra_classes) + self.event_classes = tuple(event_classes) - # Register actions, but watch out for duplicate name/abbr - action_names = {} - action_abbrs = {} - for hook in pm.hook.register_actions(datasette=self): - if hook: - for action in hook: - if ( - action.name in action_names - and action != action_names[action.name] - ): - raise StartupError(f"Duplicate action name: {action.name}") - if ( - action.abbr - and action.abbr in action_abbrs - and action != action_abbrs[action.abbr] - ): - raise StartupError(f"Duplicate action abbr: {action.abbr}") - action_names[action.name] = action - if action.abbr: - action_abbrs[action.abbr] = action - self.actions[action.name] = action + # Register actions, but watch out for duplicate name/abbr + action_names = {} + action_abbrs = {} + for hook in pm.hook.register_actions(datasette=self): + if hook: + for action in hook: + if ( + action.name in action_names + and action != action_names[action.name] + ): + raise StartupError(f"Duplicate action name: {action.name}") + if ( + action.abbr + and action.abbr in action_abbrs + and action != action_abbrs[action.abbr] + ): + raise StartupError(f"Duplicate action abbr: {action.abbr}") + action_names[action.name] = action + if action.abbr: + action_abbrs[action.abbr] = action + self.actions[action.name] = action - # Register column types (classes, not instances) - self._column_types = {} - for hook in pm.hook.register_column_types(datasette=self): - if hook: - for ct_cls in hook: - if ct_cls.name in self._column_types: - raise StartupError(f"Duplicate column type name: {ct_cls.name}") - self._column_types[ct_cls.name] = ct_cls + # Register column types (classes, not instances) + self._column_types = {} + for hook in pm.hook.register_column_types(datasette=self): + if hook: + for ct_cls in hook: + if ct_cls.name in self._column_types: + raise StartupError( + f"Duplicate column type name: {ct_cls.name}" + ) + self._column_types[ct_cls.name] = ct_cls - for hook in pm.hook.prepare_jinja2_environment( - env=self._jinja_env, datasette=self - ): - await await_me_maybe(hook) - # Ensure internal tables and metadata are populated before startup hooks - await self._refresh_schemas() - await self._save_queries_from_config() - # Load column_types from config into internal DB - await self._apply_column_types_config() - for hook in pm.hook.startup(datasette=self): - await await_me_maybe(hook) - self._startup_invoked = True + for hook in pm.hook.prepare_jinja2_environment( + env=self._jinja_env, datasette=self + ): + await await_me_maybe(hook) + # Ensure internal tables and metadata are populated before startup hooks + await self._refresh_schemas() + await self._save_queries_from_config() + # Load column_types from config into internal DB + await self._apply_column_types_config() + for hook in pm.hook.startup(datasette=self): + await await_me_maybe(hook) + self._startup_invoked = True def sign(self, value, namespace="default"): return URLSafeSerializer(self._secret, namespace).dumps(value) diff --git a/datasette/database.py b/datasette/database.py index d7cbc99b..38b38f48 100644 --- a/datasette/database.py +++ b/datasette/database.py @@ -496,8 +496,15 @@ class Database: try: conn = self.connect(write=True) # This warm-up runs before any write has ever been queued, so - # there is no caller otel context yet to attach - any spans - # created by plugin hooks here are orphans (roots). + # 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. self.ds._prepare_connection(conn, self.name) except Exception as e: # noqa: BLE001 # Stored and re-raised to whoever queues the next write diff --git a/tests/test_telemetry.py b/tests/test_telemetry.py index f232a39d..7894670c 100644 --- a/tests/test_telemetry.py +++ b/tests/test_telemetry.py @@ -6,6 +6,7 @@ import time import pytest import sqlite_utils +from opentelemetry import trace as otel_trace from opentelemetry.trace import StatusCode from datasette.app import Datasette @@ -56,6 +57,27 @@ 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. + """ + seen = set() + current = span + while current.parent is not None: + if current.parent.span_id == ancestor_span_context.span_id: + return current.parent.trace_id == ancestor_span_context.trace_id + if current.parent.span_id in seen: + return False + seen.add(current.parent.span_id) + current = by_span_id.get(current.parent.span_id) + if current is None: + return False + return False + + def _all_attribute_values(otel_spans): "Every attribute value across every finished span, for the 'no leaked param values' test." values = [] @@ -457,3 +479,67 @@ async def test_suppressed_error_does_not_mark_execute_span(ds_client, otel_spans span = execute_spans[-1] assert span.status.status_code == StatusCode.UNSET assert not [event for event in span.events if event.name == "exception"] + + +@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. + """ + 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. + 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. + assert ( + not otel_trace.get_current_span().get_span_context().is_valid + ), "this test must run with no ambient span" + + await ds.invoke_startup() + + spans = otel_spans.get_finished_spans() + assert len(spans) > 10, f"expected startup to emit many spans, got {len(spans)}" + + startup_spans = [span for span in spans if span.name == "datasette.startup"] + assert len(startup_spans) == 1 + startup = startup_spans[0] + assert startup.parent is None, "datasette.startup should be a root span" + + trace_ids = {span.context.trace_id for span in spans} + assert trace_ids == {startup.context.trace_id}, ( + f"startup produced {len(trace_ids)} distinct traces; every span it " + "causes should share the datasette.startup trace" + ) + + roots = [span for span in spans if span.parent is None] + assert [span.name for span in roots] == ["datasette.startup"] + + 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_queries = [ + span + for span in spans + if span.name == "db.query" and span.attributes["db.namespace"] == "__INTERNAL__" + ] + assert internal_queries, "expected internal-catalog db.query spans during startup" + assert all( + _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. + write_spans = [span for span in spans if span.name.startswith("db.write.")] + assert write_spans, "expected db.write.* spans during startup" + assert all( + _descends_from(span, startup.context, by_span_id) for span in write_spans + ) From 77b025be281b1215c51c2f62c75fb3d6b1c7092d Mon Sep 17 00:00:00 2001 From: Alex Garcia Date: Thu, 30 Jul 2026 18:29:16 -0700 Subject: [PATCH 06/13] Make db.query spans match OpenTelemetry semantic conventions Three corrections to the emitted data, bundled because changing what is on the wire after operators have built dashboards on it is a breaking change - so they belong in the first release that ships spans at all, not a later one. db.query is now SpanKind.CLIENT. Trace UIs key their database rendering off the span kind rather than off db.system, so the spans rendered as ordinary internal work despite carrying db.system and db.query.text. The three child spans stay INTERNAL on purpose: db.query.execute, db.write.execute and db.write.queue_wait are Datasette's decomposition of one logical query, not three 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. The instrumentation scope now carries the Datasette version and a schema URL, so a backend can tell which Datasette produced a span. The URL is 1.29.0 rather than the latest semconv release because that is the highest version at which every name emitted here is the current spelling: db.system was renamed to db.system.name in 1.30.0 and this code still emits the older form. Claiming a later schema would be false, and would stop a consumer translating that name forward, since the claim asserts the rename already happened. db.operation.name is the statement's leading keyword matched against a fixed allowlist, not a parse. On a public instance the SQL is attacker-controlled and this attribute is a candidate metric dimension in a later phase, so echoing back an arbitrary first token would let a visitor's typo mint a permanent series. Anything unrecognised gets no attribute rather than a wrong one. execute_write_script() does not set it at all, since semantic conventions say not to extract an operation name from query text that can hold several statements. db.collection.name comes only from a new table= argument on Database.execute(), and is never derived from the SQL: deriving it would be a parse, and on an instance where anyone can create a table the value set has no ceiling. It is passed from every query in the table and row views that targets exactly one user table. Internal-catalog reads and the row view's cross-table foreign key counts are deliberately left without it. Co-Authored-By: Claude Opus 5 --- datasette/database.py | 38 +++++-- datasette/telemetry.py | 89 ++++++++++++++++- datasette/views/row.py | 9 +- datasette/views/table.py | 16 ++- tests/test_telemetry.py | 209 ++++++++++++++++++++++++++++++++++++++- 5 files changed, 346 insertions(+), 15 deletions(-) diff --git a/datasette/database.py b/datasette/database.py index 38b38f48..1b9a5076 100644 --- a/datasette/database.py +++ b/datasette/database.py @@ -14,10 +14,10 @@ from pathlib import Path import sqlite_utils from opentelemetry import context as otel_context_api -from opentelemetry.trace import Status, StatusCode +from opentelemetry.trace import SpanKind, Status, StatusCode from .inspect import inspect_hash -from .telemetry import sql_attribute, tracer +from .telemetry import sql_attribute, sql_operation_name, tracer from .tracer import trace from .utils import ( call_with_supported_arguments, @@ -268,10 +268,13 @@ class Database: with trace( # noqa: SIM117 "sql", database=self.name, sql=sql.strip(), params=params ): - with tracer.start_as_current_span("db.query") as span: + with tracer.start_as_current_span("db.query", kind=SpanKind.CLIENT) as span: span.set_attribute("db.system", "sqlite") span.set_attribute("db.namespace", self.name) span.set_attribute("db.query.text", sql_attribute(sql)) + operation_name = sql_operation_name(sql) + if operation_name: + span.set_attribute("db.operation.name", operation_name) if params: span.set_attribute("datasette.param_count", len(params)) results = await self.execute_write_fn( @@ -289,7 +292,11 @@ class Database: with trace( # noqa: SIM117 "sql", database=self.name, sql=sql.strip(), executescript=True ): - with tracer.start_as_current_span("db.query") as span: + # 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(). + with tracer.start_as_current_span("db.query", kind=SpanKind.CLIENT) as span: span.set_attribute("db.system", "sqlite") span.set_attribute("db.namespace", self.name) span.set_attribute("db.query.text", sql_attribute(sql)) @@ -317,11 +324,16 @@ class Database: with trace( "sql", database=self.name, sql=sql.strip(), executemany=True ) as kwargs: - with tracer.start_as_current_span("db.query") as span: + with tracer.start_as_current_span("db.query", kind=SpanKind.CLIENT) as span: span.set_attribute("db.system", "sqlite") span.set_attribute("db.namespace", self.name) span.set_attribute("db.query.text", sql_attribute(sql)) span.set_attribute("datasette.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) results, count = await self.execute_write_fn( _inner, block=block, request=request ) @@ -632,8 +644,16 @@ class Database: custom_time_limit=None, page_size=None, log_sql_errors=True, + table=None, ): - """Executes sql against db_name in a thread""" + """Executes sql against db_name in a thread + + `table`, if passed, is recorded as the `db.collection.name` span + attribute. It exists for callers that already know which table the + query targets - the table and row views - and is never derived from + `sql` itself: deriving it would be a parse, and on an instance where + anyone can create a table the resulting value set has no ceiling. + """ self._check_not_closed() page_size = page_size or self.ds.page_size time_limit_ms = self.ds.sql_time_limit_ms @@ -698,6 +718,7 @@ class Database: # can be honoured - see the comment on the generic handler below. with tracer.start_as_current_span( "db.query", + kind=SpanKind.CLIENT, record_exception=False, set_status_on_exception=False, ) as span: @@ -705,6 +726,11 @@ class Database: span.set_attribute("db.namespace", self.name) span.set_attribute("db.query.text", sql_attribute(sql)) span.set_attribute("datasette.time_limit_ms", time_limit_ms) + operation_name = sql_operation_name(sql) + if operation_name: + span.set_attribute("db.operation.name", operation_name) + if table: + span.set_attribute("db.collection.name", table) if params: span.set_attribute("datasette.param_count", len(params)) try: diff --git a/datasette/telemetry.py b/datasette/telemetry.py index 6f5ed093..37195584 100644 --- a/datasette/telemetry.py +++ b/datasette/telemetry.py @@ -9,9 +9,34 @@ harness). With no provider installed every span produced here is a `NonRecordingSpan` and costs approximately nothing. """ +import re + from opentelemetry import trace as otel_trace -tracer = otel_trace.get_tracer("datasette") +from .version import __version__ + +# 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. +SCHEMA_URL = "https://opentelemetry.io/schemas/1.29.0" + +tracer = otel_trace.get_tracer("datasette", __version__, schema_url=SCHEMA_URL) MAX_SQL_LENGTH = 2048 @@ -22,3 +47,65 @@ def sql_attribute(sql: str) -> str: if len(sql) <= MAX_SQL_LENGTH: return sql return sql[:MAX_SQL_LENGTH] + "…[truncated]" + + +# 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 is +# a candidate dimension on a query-duration metric in a later phase. 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. +DB_OPERATION_ALLOWLIST = frozenset( + { + "SELECT", + "INSERT", + "UPDATE", + "DELETE", + "CREATE", + "DROP", + "ALTER", + "PRAGMA", + "EXPLAIN", + "REPLACE", + "VACUUM", + "ANALYZE", + "WITH", + } +) + +_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. + + 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. + """ + match = _LEADING_KEYWORD.match(sql) + if not match: + return None + keyword = match.group(1).upper() + if keyword in DB_OPERATION_ALLOWLIST: + return keyword + return None diff --git a/datasette/views/row.py b/datasette/views/row.py index b1388299..b5196a83 100644 --- a/datasette/views/row.py +++ b/datasette/views/row.py @@ -407,7 +407,7 @@ class RowView(BaseView): raise Forbidden("You do not have permission to view this table") results = await resolved.db.execute( - resolved.sql, resolved.params, truncate=True + resolved.sql, resolved.params, truncate=True, table=table ) columns = [r[0] for r in results.description] rows = list(results.rows) @@ -652,6 +652,9 @@ class RowView(BaseView): ] ) try: + # No table= here: this counts incoming references across every + # foreign key pointing at this row, so it spans many tables and + # there is no single value db.collection.name could take. rows = list(await db.execute(sql, {"id": pk_values[0]})) except QueryInterrupted: # Almost certainly hit the timeout @@ -840,7 +843,7 @@ class RowUpdateView(BaseView): returned_row = None if data.get("return"): results = await resolved.db.execute( - resolved.sql, resolved.params, truncate=True + resolved.sql, resolved.params, truncate=True, table=resolved.table ) returned_row = results.dicts()[0] result["rows"] = [returned_row] @@ -858,7 +861,7 @@ class RowUpdateView(BaseView): message_row = returned_row if message_row is None: results = await resolved.db.execute( - resolved.sql, resolved.params, truncate=True + resolved.sql, resolved.params, truncate=True, table=resolved.table ) message_row = results.first() self.ds.add_message( diff --git a/datasette/views/table.py b/datasette/views/table.py index 7c814b27..6d920fd8 100644 --- a/datasette/views/table.py +++ b/datasette/views/table.py @@ -1170,6 +1170,7 @@ class TableInsertView(BaseView): "rowid, " if pks == ["rowid"] else "", table_name, where_clause ), args, + table=table_name, ) result["rows"] = fetched_rows.dicts() else: @@ -1382,7 +1383,9 @@ class TableDropView(BaseView): "database": database_name, "table": table_name, "row_count": ( - await db.execute(f"select count(*) from [{table_name}]") + await db.execute( + f"select count(*) from [{table_name}]", table=table_name + ) ).single_value(), "message": 'Pass "confirm": true to confirm', }, @@ -1576,7 +1579,10 @@ class TableAutocompleteView(BaseView): try: results = await db.execute( - sql, params, custom_time_limit=AUTOCOMPLETE_TIME_LIMIT_MS + sql, + params, + custom_time_limit=AUTOCOMPLETE_TIME_LIMIT_MS, + table=table_name, ) except QueryInterrupted: fallback_where = _autocomplete_prefix_like(pks[0]) @@ -1597,6 +1603,7 @@ class TableAutocompleteView(BaseView): fallback_sql, params, custom_time_limit=AUTOCOMPLETE_TIME_LIMIT_MS, + table=table_name, ) except QueryInterrupted: return Response.json({"ok": True, "rows": []}) @@ -2163,7 +2170,9 @@ async def table_view_data( # Execute the main query! try: - results = await db.execute(sql, params, truncate=True, **extra_args) + results = await db.execute( + sql, params, truncate=True, table=table_name, **extra_args + ) except (sqlite3.OperationalError, InvalidSql) as e: raise DatasetteError(str(e), title="Invalid SQL", status=400) @@ -2439,6 +2448,7 @@ async def _next_value_and_url( await db.execute( prefix_lookup_sql, {**{f"pk{i}": rows[-2][pk] for i, pk in enumerate(pks)}}, + table=table_name, ) ).single_value() if isinstance(prefix, dict) and "value" in prefix: diff --git a/tests/test_telemetry.py b/tests/test_telemetry.py index 7894670c..c49a11cf 100644 --- a/tests/test_telemetry.py +++ b/tests/test_telemetry.py @@ -7,11 +7,18 @@ import time import pytest import sqlite_utils from opentelemetry import trace as otel_trace -from opentelemetry.trace import StatusCode +from opentelemetry.trace import SpanKind, StatusCode from datasette.app import Datasette from datasette.database import Database -from datasette.telemetry import MAX_SQL_LENGTH, sql_attribute, tracer +from datasette.telemetry import ( + MAX_SQL_LENGTH, + SCHEMA_URL, + sql_attribute, + sql_operation_name, + tracer, +) +from datasette.version import __version__ SECRET_PARAM_VALUE = "SUPER_SECRET_PARAM_VALUE_XYZ_123" @@ -543,3 +550,201 @@ async def test_invoke_startup_produces_one_trace_not_dozens_of_orphans(otel_span assert all( _descends_from(span, startup.context, by_span_id) for span in write_spans ) + + +# --- Semantic conventions: span kind, scope, db.operation/collection ------- + + +@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. + """ + # 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. + 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)] + ) + await db.execute_write_script("insert into docs (id) values (99);") + await db.execute("select id from docs") + + query_spans = _spans_for_namespace(otel_spans, "t06_span_kind") + assert len(query_spans) == 4, "expected a db.query span per entry point" + for span in query_spans: + text = span.attributes["db.query.text"] + assert span.kind == SpanKind.CLIENT, f"db.query for {text!r} should be CLIENT" + + for name in ("db.query.execute", "db.write.execute", "db.write.queue_wait"): + children = [ + span for span in otel_spans.get_finished_spans() if span.name == name + ] + assert children, f"expected at least one {name} span" + for span in children: + assert span.kind == SpanKind.INTERNAL, f"{name} should be INTERNAL" + + +@pytest.mark.asyncio +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`. + """ + response = await ds_client.get("/fixtures/-/query.json?sql=select+1") + assert response.status_code == 200 + + spans = _db_query_spans(otel_spans) + assert spans, "expected at least one db.query span" + scope = spans[-1].instrumentation_scope + + 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. + 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" + + +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(). + 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. + 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. + 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 + + +@pytest.mark.asyncio +async def test_db_operation_name_on_real_span(ds_client, otel_spans): + response = await ds_client.get("/fixtures/-/query.json?sql=select+1") + assert response.status_code == 200 + + spans = [ + span + for span in _spans_for_namespace(otel_spans, "fixtures") + if span.attributes["db.query.text"] == "select 1" + ] + assert spans, "expected a db.query span for 'select 1'" + assert spans[-1].attributes["db.operation.name"] == "SELECT" + + +@pytest.mark.asyncio +async def test_execute_write_sets_db_operation_name(otel_spans): + db = Datasette(memory=True).add_memory_database("t06_write_operation") + 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)] + ) + + spans = _spans_for_namespace(otel_spans, "t06_write_operation") + by_operation = { + span.attributes["db.query.text"]: span.attributes.get("db.operation.name") + for span in spans + } + assert by_operation["create table docs (id integer primary key)"] == "CREATE" + assert by_operation["insert into docs (id) values (?)"] == "INSERT" + + +@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. + + The script deliberately starts with `create`, which *is* on the + allowlist - so this fails if the call site ever starts calling + sql_operation_name(). + """ + db = Datasette(memory=True).add_memory_database("t06_script_operation") + await db.execute_write_script( + "create table docs (id integer primary key);\n" + "insert into docs (id) values (1);" + ) + + spans = _spans_for_namespace(otel_spans, "t06_script_operation") + script_spans = [ + span for span in spans if span.attributes.get("datasette.executescript") is True + ] + assert len(script_spans) == 1 + assert "db.operation.name" not in script_spans[0].attributes + + +@pytest.mark.asyncio +async def test_db_collection_name_set_from_table_argument(ds_client, otel_spans): + db = ds_client.ds.get_database("fixtures") + await db.execute("select pk from facetable limit 1", table="facetable") + + spans = _spans_for_namespace(otel_spans, "fixtures") + assert spans + assert spans[-1].attributes["db.collection.name"] == "facetable" + + +@pytest.mark.asyncio +async def test_db_collection_name_absent_without_table_argument(ds_client, otel_spans): + """ + db.collection.name comes only from an explicit table= argument and is + never derived from the SQL. + + Deriving it would be a parse, and on an instance where anybody can create + a table the value set has no ceiling. Without this test the one above + would still pass if the table name were being read out of the query text. + """ + db = ds_client.ds.get_database("fixtures") + await db.execute("select pk from facetable limit 1") + + spans = _spans_for_namespace(otel_spans, "fixtures") + assert spans + span = spans[-1] + assert span.attributes["db.query.text"] == "select pk from facetable limit 1" + assert "db.collection.name" not in span.attributes + + +@pytest.mark.parametrize( + "path,table", + ( + ("/fixtures/facetable.json", "facetable"), + ("/fixtures/simple_primary_key/1.json", "simple_primary_key"), + ), +) +@pytest.mark.asyncio +async def test_table_and_row_pages_set_db_collection_name( + ds_client, otel_spans, path, table +): + "The table and row views know their table, so their queries carry it." + response = await ds_client.get(path) + assert response.status_code == 200 + + spans = _spans_for_namespace(otel_spans, "fixtures") + assert spans + assert any( + span.attributes.get("db.collection.name") == table for span in spans + ), f"expected a db.query span from {path} carrying db.collection.name" From e24a2c122fb646d72f3db2f2b6cd50e78130726c Mon Sep 17 00:00:00 2001 From: Alex Garcia Date: Thu, 30 Jul 2026 18:36:49 -0700 Subject: [PATCH 07/13] Link block=False write spans to their enqueuer instead of parenting them A block=False write returns without awaiting the reply future, so the enclosing db.query span finishes - and exports - before db.write.queue_wait and db.write.execute even exist. They were still parented to it, which produced a child bar ending ~50ms after its already-closed parent: legal OpenTelemetry, but it renders as nonsense in a trace UI. Parenting asserts containment; a link asserts causation without containment. The enqueueing request causes the write without containing it, which is exactly what a span link is for. So for block=False both write spans are now roots - started with an explicit empty Context, so the write thread's ambient context cannot supply a parent either - each carrying one link back to the enqueueing span. block=True is untouched, since there the caller really does await the reply and containment is accurate. The link carries no attributes. There is only one kind of link here, so naming the relationship would be a constant conveying nothing the link's existence does not already say. Accepted trade-off: a linked span will not appear inside the request's waterfall in most trace UIs. It shows up as its own trace with a "linked from" reference rather than a bar under the request. For a fire-and-forget write whose latency the request never pays, that is the right trade - correctness over at-a-glance nesting for a case the request-latency view was never accurate for anyway. This does add root traces, which looks like it cuts against the startup span work that spent its whole diff removing them. The difference is reachability: those roots were orphans, whereas these are reachable from the request that caused them via the link. Nothing in core issues block=False writes today - it is a plugin-facing path - so this changes no trace Datasette produces on its own. Co-Authored-By: Claude Opus 5 --- datasette/database.py | 85 +++++++++++++++++---- tests/test_telemetry.py | 161 ++++++++++++++++++++++++++++++++++++++++ 2 files changed, 231 insertions(+), 15 deletions(-) diff --git a/datasette/database.py b/datasette/database.py index 1b9a5076..3c14c1c0 100644 --- a/datasette/database.py +++ b/datasette/database.py @@ -14,7 +14,7 @@ from pathlib import Path import sqlite_utils from opentelemetry import context as otel_context_api -from opentelemetry.trace import SpanKind, Status, StatusCode +from opentelemetry.trace import Link, SpanKind, Status, StatusCode, get_current_span from .inspect import inspect_hash from .telemetry import sql_attribute, sql_operation_name, tracer @@ -482,7 +482,9 @@ class Database: # Captured here, on the event loop, at enqueue time: the otel # Context (carrying the enclosing db.query span, if any) and the # timestamp used to build the db.write.queue_wait span once this - # task is dequeued on the write thread. + # task is dequeued on the write thread. `block` travels with the + # task too, because it decides whether that context is this task's + # parent or only a link target - see `_execute_writes`. self._write_queue.put( WriteTask( fn, @@ -493,6 +495,7 @@ class Database: transaction, otel_context_api.get_current(), time.time_ns(), + block, ) ) if block: @@ -531,15 +534,52 @@ class Database: # Best-effort close as the write thread exits pass return - # Restore the caller's otel context (captured on the event loop - # at enqueue time) so spans created while processing this task - # parent correctly to the request that queued it. 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. - token = otel_context_api.attach(task.otel_context) + # `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 already have closed (and + # exported) before this task's spans even start - parenting to + # it would make a child appear to outlive its already-closed + # parent, which OTel allows but which renders badly in most + # trace UIs. The enqueueing request *caused* this write + # without *containing* it, so nothing is attached here - + # instead each write span is started as its own root (explicit + # empty `context=`, so the write thread's ambient context + # cannot supply a parent either) carrying one `Link` back to + # the enqueueing span's context, built once into + # `write_span_kwargs` and spread into every start_span call + # below. + token = None + write_span_kwargs = {} + if task.block: + token = otel_context_api.attach(task.otel_context) + else: + enqueueing_span_context = get_current_span( + task.otel_context + ).get_span_context() + # No attributes on the link: there is only one kind of link + # here, so naming the relationship would be a constant that + # carries no information a consumer does not already have + # from the link's existence. + links = ( + [Link(enqueueing_span_context)] + if enqueueing_span_context.is_valid + else [] + ) + write_span_kwargs = { + "context": otel_context_api.Context(), + "links": links, + } try: exception = None result = None @@ -548,7 +588,9 @@ class Database: # waiting in the queue (enqueue -> dequeue), not the near- # zero time spent constructing/ending the span object here. tracer.start_span( - "db.write.queue_wait", start_time=task.enqueued_at_ns + "db.write.queue_wait", + start_time=task.enqueued_at_ns, + **write_span_kwargs, ).end(end_time=time.time_ns()) if conn_exception is not None: # fn never runs in this branch, so there is nothing to @@ -556,7 +598,9 @@ class Database: exception = conn_exception elif task.isolated_connection: try: - with tracer.start_as_current_span("db.write.execute") as span: + with tracer.start_as_current_span( + "db.write.execute", **write_span_kwargs + ) as span: span.set_attribute( "datasette.isolated_connection", task.isolated_connection, @@ -583,7 +627,9 @@ class Database: exception = e else: try: - with tracer.start_as_current_span("db.write.execute") as span: + with tracer.start_as_current_span( + "db.write.execute", **write_span_kwargs + ) as span: span.set_attribute( "datasette.isolated_connection", task.isolated_connection, @@ -603,7 +649,8 @@ class Database: exception = e _deliver_write_result(task, result, exception) finally: - otel_context_api.detach(token) + if token is not None: + otel_context_api.detach(token) async def execute_fn(self, fn): self._check_not_closed() @@ -1043,6 +1090,7 @@ def _apply_write_wrapper(fn, wrapper_factory, track_event): class WriteTask: __slots__ = ( + "block", "enqueued_at_ns", "fn", "isolated_connection", @@ -1063,6 +1111,7 @@ class WriteTask: transaction, otel_context, enqueued_at_ns, + block, ): self.fn = fn self.task_id = task_id @@ -1072,6 +1121,12 @@ 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 def _deliver_write_result(task, result, exception): diff --git a/tests/test_telemetry.py b/tests/test_telemetry.py index c49a11cf..0a6d0192 100644 --- a/tests/test_telemetry.py +++ b/tests/test_telemetry.py @@ -2,10 +2,12 @@ import json import sqlite3 import subprocess import sys +import threading import time import pytest import sqlite_utils +from opentelemetry import context as otel_context_api from opentelemetry import trace as otel_trace from opentelemetry.trace import SpanKind, StatusCode @@ -463,6 +465,165 @@ async def test_write_queue_wait_duration_reflects_real_wait(otel_spans): 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}). + + `_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. + """ + db = Datasette(memory=True).add_memory_database(name) + await db.execute_write("create table docs (id integer primary key)") + + def insert(conn): + conn.execute("insert into docs (id) values (1)") + + otel_spans.clear() + with tracer.start_as_current_span("enqueueing-span") as enqueuer: + 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. + _, reply_future = queued + await reply_future + + spans = {} + for span in otel_spans.get_finished_spans(): + if span.name in ("db.write.queue_wait", "db.write.execute"): + assert span.name not in spans, f"more than one {span.name} span" + spans[span.name] = span + assert set(spans) == {"db.write.queue_wait", "db.write.execute"} + return enqueuer_context, spans + + +@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. + enqueuer_context, spans = await _write_spans_from_one_enqueue( + otel_spans, "t07_blocking_write", block=True + ) + for name, span in spans.items(): + assert span.parent is not None, f"{name} lost its parent" + assert span.parent.span_id == enqueuer_context.span_id, name + assert span.parent.trace_id == enqueuer_context.trace_id, name + assert span.context.trace_id == enqueuer_context.trace_id, name + assert span.links == (), f"{name} should be parented, not linked" + + +@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. + 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. + 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. + assert ( + spans["db.write.queue_wait"].context.trace_id + != spans["db.write.execute"].context.trace_id + ) + + +@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 + ) + for name, span in spans.items(): + assert len(span.links) == 1, name + assert dict(span.links[0].attributes or {}) == {}, name + + +@pytest.mark.asyncio +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". + + 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. + """ + ds = Datasette(memory=True) + db = ds.add_memory_database("t07_ambient_write_thread") + write_thread_name = "_execute_writes for database t07_ambient_write_thread" + real_prepare_connection = ds._prepare_connection + leaked = {} + + 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. + 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)) + return real_prepare_connection(conn, database) + + ds._prepare_connection = prepare_connection + try: + await db.execute_write("create table docs (id integer primary key)") + + def insert(conn): + conn.execute("insert into docs (id) values (1)") + + otel_spans.clear() + with tracer.start_as_current_span("enqueueing-span") as enqueuer: + enqueuer_context = enqueuer.get_span_context() + _, reply_future = await db._send_to_write_thread(insert, block=False) + await reply_future + finally: + ds._prepare_connection = real_prepare_connection + db.close() + + assert "span_id" in leaked, "the ambient context was never leaked - test is vacuous" + write_spans = [ + span + for span in otel_spans.get_finished_spans() + if span.name in ("db.write.queue_wait", "db.write.execute") + ] + assert len(write_spans) == 2 + for span in write_spans: + assert span.parent is None, ( + f"{span.name} parented to the write thread's leftover ambient " + "context instead of being a root" + ) + assert span.links[0].context.span_id == enqueuer_context.span_id + + @pytest.mark.asyncio async def test_suppressed_error_does_not_mark_execute_span(ds_client, otel_spans): """ From 8d32eac89508453eb519ae6d4377950aa03a19a0 Mon Sep 17 00:00:00 2001 From: Alex Garcia Date: Thu, 30 Jul 2026 18:46:34 -0700 Subject: [PATCH 08/13] Name every span and attribute once, in a registry the docs are built from The span and attribute names were string literals spread across four call sites in database.py and one in app.py, with a hand-written reference page that would have been true only on the day it was written. That drift is not hypothetical: an earlier iteration of this work carried a README asserting parameter values were never recorded for two branches after that had stopped being true. datasette/telemetry_registry.py now holds each name once, with its documentation. Attribute and SpanName subclass str, so a registry entry *is* the string OpenTelemetry wants - no wrapper API over the OTel calls, no parallel structure to keep in step, and a typo becomes an ImportError rather than a silently misnamed attribute. docs/internals.rst renders the span reference from it via cog, and `cog --check docs/*.rst` already runs in CI, so the reference cannot drift from the definitions. Nothing changes on the wire: the emitted span names and attribute keys are byte-identical before and after, verified by diffing a dump of both. tests/test_telemetry_registry.py exercises a real workload and compares it against the registry in both directions - emitted-but-unregistered catches instrumentation added without documentation, registered-but-never-emitted catches documentation that has outlived its code. Because the call sites now take their names from the registry, neither direction can catch a rename: move DB_NAMESPACE to "db.namespace2" and code and registry still agree while every dashboard breaks. So the literal names are also written out in the test and asserted against the registry and against the wire separately. That pair is the only comparison in the file not derived from the registry itself. Co-Authored-By: Claude Opus 5 --- datasette/app.py | 3 +- datasette/database.py | 106 ++++++----- datasette/telemetry_registry.py | 269 +++++++++++++++++++++++++++ docs/internals.rst | 72 +++++++ docs/telemetry_doc.py | 37 ++++ tests/test_telemetry_registry.py | 309 +++++++++++++++++++++++++++++++ 6 files changed, 751 insertions(+), 45 deletions(-) create mode 100644 datasette/telemetry_registry.py create mode 100644 docs/telemetry_doc.py create mode 100644 tests/test_telemetry_registry.py diff --git a/datasette/app.py b/datasette/app.py index d3626ab2..7499c6f9 100644 --- a/datasette/app.py +++ b/datasette/app.py @@ -50,6 +50,7 @@ from .plugins import DEFAULT_PLUGINS, get_plugins, pm from .renderer import json_renderer from .resources import DatabaseResource, TableResource from .telemetry import tracer +from .telemetry_registry import STARTUP from .tokens import TokenInvalid from .tracer import AsgiTracer from .url_builder import Urls @@ -788,7 +789,7 @@ class Datasette: # 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. - with tracer.start_as_current_span("datasette.startup"): + with tracer.start_as_current_span(STARTUP): # Register event classes event_classes = [] for hook in pm.hook.register_events(datasette=self): diff --git a/datasette/database.py b/datasette/database.py index 3c14c1c0..22984d6f 100644 --- a/datasette/database.py +++ b/datasette/database.py @@ -14,10 +14,32 @@ from pathlib import Path import sqlite_utils from opentelemetry import context as otel_context_api -from opentelemetry.trace import Link, SpanKind, Status, StatusCode, get_current_span +from opentelemetry.trace import Link, Status, StatusCode, get_current_span from .inspect import inspect_hash from .telemetry import sql_attribute, sql_operation_name, tracer +from .telemetry_registry import ( + DB_COLLECTION_NAME, + DB_NAMESPACE, + DB_OPERATION_NAME, + DB_QUERY, + DB_QUERY_EXECUTE, + DB_QUERY_TEXT, + DB_SYSTEM, + DB_WRITE_EXECUTE, + DB_WRITE_QUEUE_WAIT, + EXECUTEMANY, + EXECUTESCRIPT, + INTERRUPTED, + ISOLATED_CONNECTION, + PARAM_COUNT, + PARAM_SETS, + ROWS_RETURNED, + SQL_ERROR_SUPPRESSED, + TIME_LIMIT_MS, + TRANSACTION, + TRUNCATED, +) from .tracer import trace from .utils import ( call_with_supported_arguments, @@ -268,15 +290,15 @@ class Database: with trace( # noqa: SIM117 "sql", database=self.name, sql=sql.strip(), params=params ): - with tracer.start_as_current_span("db.query", kind=SpanKind.CLIENT) as span: - span.set_attribute("db.system", "sqlite") - span.set_attribute("db.namespace", self.name) - span.set_attribute("db.query.text", sql_attribute(sql)) + 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(DB_QUERY_TEXT, sql_attribute(sql)) operation_name = sql_operation_name(sql) if operation_name: - span.set_attribute("db.operation.name", operation_name) + span.set_attribute(DB_OPERATION_NAME, operation_name) if params: - span.set_attribute("datasette.param_count", len(params)) + span.set_attribute(PARAM_COUNT, len(params)) results = await self.execute_write_fn( _inner, block=block, request=request, transaction=transaction ) @@ -296,11 +318,11 @@ class Database: # 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(). - with tracer.start_as_current_span("db.query", kind=SpanKind.CLIENT) as span: - span.set_attribute("db.system", "sqlite") - span.set_attribute("db.namespace", self.name) - span.set_attribute("db.query.text", sql_attribute(sql)) - span.set_attribute("datasette.executescript", True) + 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(DB_QUERY_TEXT, sql_attribute(sql)) + span.set_attribute(EXECUTESCRIPT, True) results = await self.execute_write_fn( _inner, block=block, transaction=False, request=request ) @@ -324,22 +346,22 @@ class Database: with trace( "sql", database=self.name, sql=sql.strip(), executemany=True ) as kwargs: - with tracer.start_as_current_span("db.query", kind=SpanKind.CLIENT) as span: - span.set_attribute("db.system", "sqlite") - span.set_attribute("db.namespace", self.name) - span.set_attribute("db.query.text", sql_attribute(sql)) - span.set_attribute("datasette.executemany", True) + 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(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) + span.set_attribute(DB_OPERATION_NAME, operation_name) 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("datasette.param_sets", count) + span.set_attribute(PARAM_SETS, count) kwargs["count"] = count return results @@ -588,7 +610,7 @@ class Database: # waiting in the queue (enqueue -> dequeue), not the near- # zero time spent constructing/ending the span object here. tracer.start_span( - "db.write.queue_wait", + DB_WRITE_QUEUE_WAIT, start_time=task.enqueued_at_ns, **write_span_kwargs, ).end(end_time=time.time_ns()) @@ -599,15 +621,13 @@ class Database: elif task.isolated_connection: try: with tracer.start_as_current_span( - "db.write.execute", **write_span_kwargs + DB_WRITE_EXECUTE, **write_span_kwargs ) as span: span.set_attribute( - "datasette.isolated_connection", + ISOLATED_CONNECTION, task.isolated_connection, ) - span.set_attribute( - "datasette.transaction", task.transaction - ) + span.set_attribute(TRANSACTION, task.transaction) isolated_connection = self.connect(write=True) try: result = task.fn(isolated_connection) @@ -628,15 +648,13 @@ class Database: else: try: with tracer.start_as_current_span( - "db.write.execute", **write_span_kwargs + DB_WRITE_EXECUTE, **write_span_kwargs ) as span: span.set_attribute( - "datasette.isolated_connection", + ISOLATED_CONNECTION, task.isolated_connection, ) - span.set_attribute( - "datasette.transaction", task.transaction - ) + span.set_attribute(TRANSACTION, task.transaction) if task.transaction: with conn: conn.execute("BEGIN IMMEDIATE") @@ -720,7 +738,7 @@ class Database: # db.query span in execute(). Without this, facet suggestion marks # two spans per text column as failed on every table page. with tracer.start_as_current_span( - "db.query.execute", + DB_QUERY_EXECUTE, record_exception=log_sql_errors, set_status_on_exception=log_sql_errors, ): @@ -764,27 +782,27 @@ class Database: # 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=SpanKind.CLIENT, + DB_QUERY, + kind=DB_QUERY.kind, record_exception=False, set_status_on_exception=False, ) as span: - span.set_attribute("db.system", "sqlite") - span.set_attribute("db.namespace", self.name) - span.set_attribute("db.query.text", sql_attribute(sql)) - span.set_attribute("datasette.time_limit_ms", time_limit_ms) + span.set_attribute(DB_SYSTEM, "sqlite") + span.set_attribute(DB_NAMESPACE, self.name) + span.set_attribute(DB_QUERY_TEXT, sql_attribute(sql)) + span.set_attribute(TIME_LIMIT_MS, time_limit_ms) operation_name = sql_operation_name(sql) if operation_name: - span.set_attribute("db.operation.name", operation_name) + span.set_attribute(DB_OPERATION_NAME, operation_name) if table: - span.set_attribute("db.collection.name", table) + span.set_attribute(DB_COLLECTION_NAME, table) if params: - span.set_attribute("datasette.param_count", len(params)) + span.set_attribute(PARAM_COUNT, len(params)) try: results = await self.execute_fn(sql_operation_in_thread) except QueryInterrupted as e: span.set_status(Status(StatusCode.ERROR, str(e))) - span.set_attribute("datasette.interrupted", True) + span.set_attribute(INTERRUPTED, True) span.record_exception(e) raise except Exception as e: @@ -799,10 +817,10 @@ class Database: span.record_exception(e) span.set_status(Status(StatusCode.ERROR, str(e))) else: - span.set_attribute("datasette.sql_error_suppressed", True) + span.set_attribute(SQL_ERROR_SUPPRESSED, True) raise - span.set_attribute("datasette.truncated", results.truncated) - span.set_attribute("datasette.rows_returned", len(results.rows)) + span.set_attribute(TRUNCATED, results.truncated) + span.set_attribute(ROWS_RETURNED, len(results.rows)) return results @property diff --git a/datasette/telemetry_registry.py b/datasette/telemetry_registry.py new file mode 100644 index 00000000..40b32cc5 --- /dev/null +++ b/datasette/telemetry_registry.py @@ -0,0 +1,269 @@ +""" +The single source of truth for every span and span attribute that Datasette +core 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. +""" + +from opentelemetry.trace import SpanKind + + +class Attribute(str): + """ + A span attribute key, carrying its own documentation. + + Subclasses `str` so it can be handed straight to `set_attribute()`. + """ + + __slots__ = ("description", "optional") + + def __new__(cls, name, description, optional=False): + self = super().__new__(cls, name) + self.description = description + self.optional = optional + return self + + def __repr__(self): + return f"Attribute({str(self)!r})" + + +class SpanName(str): + "A span name, carrying its documentation and the attributes it may set." + + __slots__ = ("attributes", "description", "kind", "prefix") + + def __new__( + cls, name, description, attributes=(), prefix=False, kind=SpanKind.INTERNAL + ): + self = super().__new__(cls, name) + self.description = description + self.attributes = tuple(attributes) + # True for a span family whose emitted names carry a variable suffix, + # so the conformance test matches by prefix rather than equality. + # Nothing sets it yet. + self.prefix = prefix + # 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 + + def __repr__(self): + return f"SpanName({str(self)!r})" + + +# --- Attributes ----------------------------------------------------------- +# +# Shared attributes are defined once and referenced by every span that sets +# them, so "which spans carry db.namespace?" is answerable by grep. + +DB_SYSTEM = Attribute("db.system", "Always ``sqlite``.") +DB_NAMESPACE = Attribute("db.namespace", "Name of the database being queried.") +DB_QUERY_TEXT = Attribute( + "db.query.text", + "The SQL, truncated to 2048 characters. Never the parameter values.", +) +DB_OPERATION_NAME = Attribute( + "db.operation.name", + "The statement's leading keyword - ``SELECT``, ``INSERT``, ``CREATE``, and " + "so on - matched against a small fixed allowlist. Omitted rather than set " + "to an arbitrary value: the allowlist exists because this attribute is a " + "candidate dimension for a query-duration metric in a later phase, and " + "echoing an unrecognised first token from user-supplied SQL would be an " + "unbounded-cardinality hazard. Also omitted for " + "``execute_write_script()``, which runs multiple statements - per " + "semantic conventions, the operation name should not be extracted from " + "query text that can contain more than one operation. Note that a " + "statement beginning with a CTE reports ``WITH``, not the operation " + "inside it - a substantial share of Datasette's own reads take that " + "form. Resolving it further would mean parsing.", + optional=True, +) +DB_COLLECTION_NAME = Attribute( + "db.collection.name", + "The primary table, set only where the view already knows it - the table " + "and row pages. Omitted for arbitrary ``?sql=`` queries, where determining " + "the table would mean parsing the query.", + optional=True, +) + +PARAM_COUNT = Attribute( + "datasette.param_count", + "Number of bound parameters. Recorded instead of the values themselves.", + optional=True, +) +PARAM_SETS = Attribute( + "datasette.param_sets", + "Number of parameter sets consumed by ``execute_write_many()``. Not a row " + "count - ``executemany()`` returns no rows. The parameter values " + "themselves are never recorded: that sequence can hold thousands of rows.", + optional=True, +) +TIME_LIMIT_MS = Attribute( + "datasette.time_limit_ms", + "The :ref:`setting_sql_time_limit_ms` value this query ran under. Set on " + "reads, which are the queries that time limit applies to.", + optional=True, +) +ROWS_RETURNED = Attribute( + "datasette.rows_returned", + "Number of rows a read returned. Set on the read path only, and only when " + "the read succeeded.", + optional=True, +) +TRUNCATED = Attribute( + "datasette.truncated", + "True if the result was cut short by :ref:`setting_max_returned_rows`.", + optional=True, +) +INTERRUPTED = Attribute( + "datasette.interrupted", + "True if the query was cancelled for exceeding the time limit. The span " + "status is also set to ``ERROR``.", + optional=True, +) +SQL_ERROR_SUPPRESSED = Attribute( + "datasette.sql_error_suppressed", + "True when the query failed but the caller passed ``log_sql_errors=False``, " + "meaning it was probing and treats failure as an expected answer. Facet " + "suggestion does this against every column.", + optional=True, +) +EXECUTESCRIPT = Attribute( + "datasette.executescript", + "True for ``execute_write_script()``, which runs multiple statements.", + optional=True, +) +EXECUTEMANY = Attribute( + "datasette.executemany", + "True for ``execute_write_many()``, which runs one statement against many " + "parameter sets.", + optional=True, +) +ISOLATED_CONNECTION = Attribute( + "datasette.isolated_connection", + "True if the write ran on its own connection rather than the shared write " + "connection.", +) +TRANSACTION = Attribute( + "datasette.transaction", + "False for statements such as ``VACUUM`` that cannot run inside a transaction.", +) + + +# --- Spans ---------------------------------------------------------------- + +DB_QUERY = SpanName( + "db.query", + "A SQL operation issued by Datasette, covering the full round trip " + "including any time spent queued for a thread.", + ( + DB_SYSTEM, + DB_NAMESPACE, + DB_QUERY_TEXT, + DB_OPERATION_NAME, + DB_COLLECTION_NAME, + PARAM_COUNT, + PARAM_SETS, + TIME_LIMIT_MS, + ROWS_RETURNED, + TRUNCATED, + INTERRUPTED, + SQL_ERROR_SUPPRESSED, + EXECUTESCRIPT, + EXECUTEMANY, + ), + kind=SpanKind.CLIENT, +) + +DB_QUERY_EXECUTE = SpanName( + "db.query.execute", + "The read executing inside a SQL worker thread. Child of ``db.query``; the " + "gap between the two is time spent waiting for a thread.", +) + +DB_WRITE_QUEUE_WAIT = SpanName( + "db.write.queue_wait", + "Time a write spent waiting in its database's write queue before the write " + "thread picked it up. Child of ``db.query`` for a ``block=True`` write, " + "where the caller awaits the write and containment is accurate. For a " + "``block=False`` write the caller does not await it - the enqueueing " + "request *caused* the write without *containing* it, and the write's " + "spans can outlive the request's own - so this is a root span instead, " + "carrying an OpenTelemetry link back to the enqueueing span rather than " + "a parent. A link records causation without asserting containment, which " + "is exactly the distinction here.", +) + +DB_WRITE_EXECUTE = SpanName( + "db.write.execute", + "The write executing on the write thread. Child of ``db.query`` for a " + "``block=True`` write; for ``block=False`` a root span with a link back " + "to the enqueueing span instead - see ``db.write.queue_wait`` above.", + (ISOLATED_CONNECTION, TRANSACTION), +) + +STARTUP = SpanName( + "datasette.startup", + "``invoke_startup()`` running: ``register_events``, ``register_actions``, " + "``register_column_types``, ``prepare_jinja2_environment``, internal-database " + "schema catalog refresh (including the ``prepare_connection`` warm-up this " + "triggers for each database touched for the first time), saved queries, " + "column type config and the ``startup`` hook. Runs once per process, before " + "any request exists, so without this span every child it creates would be " + "its own orphan root trace. A connection warmed later - lazily, the first " + "time a *request* touches a new database or thread - nests under that " + "request's own span instead, not under this one, since this span has " + "already ended by then.", +) + +SPANS = ( + DB_QUERY, + DB_QUERY_EXECUTE, + DB_WRITE_QUEUE_WAIT, + DB_WRITE_EXECUTE, + STARTUP, +) + + +def span_for(emitted_name): + """ + Resolve an emitted span name to its registry entry, or None. + + Handles span families whose emitted names carry a suffix that is not + knowable in advance - `prefix=True` entries. Phase 1 has none, but the + lookup is what the conformance test calls, so it lives here rather than + in the test. + """ + for span in SPANS: + if span.prefix: + if emitted_name.startswith(span): + return span + elif emitted_name == span: + return span + return None + + +def attribute_allowed(span, emitted_key): + "Whether `emitted_key` is a registered attribute of `span`." + if span is None: + return False + return emitted_key in span.attributes diff --git a/docs/internals.rst b/docs/internals.rst index d2bd46ef..b2215d9d 100644 --- a/docs/internals.rst +++ b/docs/internals.rst @@ -2313,6 +2313,78 @@ The ``Database`` class also provides properties and methods for introspecting th } } +.. _internals_telemetry: + +OpenTelemetry +============= + +Datasette core depends on `opentelemetry-api `__ only. It never creates a ``TracerProvider``, never configures an exporter and never sets a sampler. With no OpenTelemetry SDK provider installed, every span described below is a no-op ``NonRecordingSpan`` - the overhead is close to zero and nothing is recorded or exported anywhere. + +Turning tracing on is entirely an operational decision made outside of Datasette itself: run Datasette under the standard ``opentelemetry-instrument`` agent, or embed Datasette inside a host application that installs its own provider. + +Everything Datasette emits carries the instrumentation scope ``datasette``, versioned with the running Datasette version and declaring the `semantic conventions schema `__ its attribute names follow. + +Span reference +-------------- + +Attribute names use the ``datasette.*`` prefix for Datasette-specific data, alongside standard OpenTelemetry attributes such as ``db.system``. + +This reference is generated from ``datasette/telemetry_registry.py``, the single source of truth for every span and attribute Datasette emits. A conformance test makes real requests and compares what is actually emitted against that registry in both directions, so nothing here is hand-maintained and nothing can silently drift out of date. + +Spans are ``SpanKind.INTERNAL`` unless a kind is listed below. Only ``db.query`` is ``CLIENT``: it is the one span that represents a call to a database rather than Datasette's own work, and trace UIs use the kind to decide whether to render a span as a database call. Its children stay ``INTERNAL`` because they are Datasette's decomposition of that one query - marking them ``CLIENT`` too would make a single query look like several database calls to anything counting by kind. + +.. [[[cog + from telemetry_doc import spans + spans(cog) +.. ]]] + +``db.query`` + A SQL operation issued by Datasette, covering the full round trip including any time spent queued for a thread. + + Kind: ``CLIENT``. + + Attributes: + + - ``db.system`` - Always ``sqlite``. + - ``db.namespace`` - Name of the database being queried. + - ``db.query.text`` - The SQL, truncated to 2048 characters. Never the parameter values. + - ``db.operation.name`` *(optional)* - The statement's leading keyword - ``SELECT``, ``INSERT``, ``CREATE``, and so on - matched against a small fixed allowlist. Omitted rather than set to an arbitrary value: the allowlist exists because this attribute is a candidate dimension for a query-duration metric in a later phase, and echoing an unrecognised first token from user-supplied SQL would be an unbounded-cardinality hazard. Also omitted for ``execute_write_script()``, which runs multiple statements - per semantic conventions, the operation name should not be extracted from query text that can contain more than one operation. Note that a statement beginning with a CTE reports ``WITH``, not the operation inside it - a substantial share of Datasette's own reads take that form. Resolving it further would mean parsing. + - ``db.collection.name`` *(optional)* - The primary table, set only where the view already knows it - the table and row pages. Omitted for arbitrary ``?sql=`` queries, where determining the table would mean parsing the query. + - ``datasette.param_count`` *(optional)* - Number of bound parameters. Recorded instead of the values themselves. + - ``datasette.param_sets`` *(optional)* - Number of parameter sets consumed by ``execute_write_many()``. Not a row count - ``executemany()`` returns no rows. The parameter values themselves are never recorded: that sequence can hold thousands of rows. + - ``datasette.time_limit_ms`` *(optional)* - The :ref:`setting_sql_time_limit_ms` value this query ran under. Set on reads, which are the queries that time limit applies to. + - ``datasette.rows_returned`` *(optional)* - Number of rows a read returned. Set on the read path only, and only when the read succeeded. + - ``datasette.truncated`` *(optional)* - True if the result was cut short by :ref:`setting_max_returned_rows`. + - ``datasette.interrupted`` *(optional)* - True if the query was cancelled for exceeding the time limit. The span status is also set to ``ERROR``. + - ``datasette.sql_error_suppressed`` *(optional)* - True when the query failed but the caller passed ``log_sql_errors=False``, meaning it was probing and treats failure as an expected answer. Facet suggestion does this against every column. + - ``datasette.executescript`` *(optional)* - True for ``execute_write_script()``, which runs multiple statements. + - ``datasette.executemany`` *(optional)* - True for ``execute_write_many()``, which runs one statement against many parameter sets. + +``db.query.execute`` + The read executing inside a SQL worker thread. Child of ``db.query``; the gap between the two is time spent waiting for a thread. + + No attributes. + +``db.write.queue_wait`` + Time a write spent waiting in its database's write queue before the write thread picked it up. Child of ``db.query`` for a ``block=True`` write, where the caller awaits the write and containment is accurate. For a ``block=False`` write the caller does not await it - the enqueueing request *caused* the write without *containing* it, and the write's spans can outlive the request's own - so this is a root span instead, carrying an OpenTelemetry link back to the enqueueing span rather than a parent. A link records causation without asserting containment, which is exactly the distinction here. + + No attributes. + +``db.write.execute`` + The write executing on the write thread. Child of ``db.query`` for a ``block=True`` write; for ``block=False`` a root span with a link back to the enqueueing span instead - see ``db.write.queue_wait`` above. + + Attributes: + + - ``datasette.isolated_connection`` - True if the write ran on its own connection rather than the shared write connection. + - ``datasette.transaction`` - False for statements such as ``VACUUM`` that cannot run inside a transaction. + +``datasette.startup`` + ``invoke_startup()`` running: ``register_events``, ``register_actions``, ``register_column_types``, ``prepare_jinja2_environment``, internal-database schema catalog refresh (including the ``prepare_connection`` warm-up this triggers for each database touched for the first time), saved queries, column type config and the ``startup`` hook. Runs once per process, before any request exists, so without this span every child it creates would be its own orphan root trace. A connection warmed later - lazily, the first time a *request* touches a new database or thread - nests under that request's own span instead, not under this one, since this span has already ended by then. + + No attributes. + +.. [[[end]]] + .. _internals_csrf: CSRF protection diff --git a/docs/telemetry_doc.py b/docs/telemetry_doc.py new file mode 100644 index 00000000..3551ef0e --- /dev/null +++ b/docs/telemetry_doc.py @@ -0,0 +1,37 @@ +""" +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. +""" + + +def _attribute_lines(cog, attributes): + if not attributes: + cog.out(" No attributes.\n\n") + return + cog.out(" Attributes:\n\n") + for attribute in attributes: + suffix = " *(optional)*" if attribute.optional else "" + cog.out(f" - ``{attribute}``{suffix} - {attribute.description}\n") + cog.out("\n") + + +def spans(cog): + from opentelemetry.trace import SpanKind + + from datasette.telemetry_registry import SPANS + + cog.out("\n") + for span in SPANS: + title = f"{span}*" if span.prefix else str(span) + cog.out(f"``{title}``\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. + if span.kind != SpanKind.INTERNAL: + cog.out(f" Kind: ``{span.kind.name}``.\n\n") + _attribute_lines(cog, span.attributes) diff --git a/tests/test_telemetry_registry.py b/tests/test_telemetry_registry.py new file mode 100644 index 00000000..335eb946 --- /dev/null +++ b/tests/test_telemetry_registry.py @@ -0,0 +1,309 @@ +""" +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. +""" + +import itertools + +import pytest +import pytest_asyncio + +pytest.importorskip("opentelemetry.sdk") + +from datasette import telemetry_registry as reg +from datasette.app import Datasette +from datasette.database import QueryInterrupted +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. +EXPECTED_ATTRIBUTES = { + "db.query": { + "db.system", + "db.namespace", + "db.query.text", + "db.operation.name", + "db.collection.name", + "datasette.param_count", + "datasette.param_sets", + "datasette.time_limit_ms", + "datasette.rows_returned", + "datasette.truncated", + "datasette.interrupted", + "datasette.sql_error_suppressed", + "datasette.executescript", + "datasette.executemany", + }, + "db.query.execute": set(), + "db.write.queue_wait": set(), + "db.write.execute": { + "datasette.isolated_connection", + "datasette.transaction", + }, + "datasette.startup": set(), +} +EXPECTED_SPANS = set(EXPECTED_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. +_names = itertools.count() + + +def _unique(prefix): + return f"{prefix}{next(_names)}" + + +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. + """ + name = _unique("registry") + ds = Datasette(memory=True) + ds.add_memory_database(name) + # datasette.startup - and the internal catalog work nested under it + await ds.invoke_startup() + db = ds.get_database(name) + + # Writes: db.write.queue_wait, db.write.execute, db.query + await db.execute_write("create table t (id integer primary key, v text)") + # datasette.executemany, datasette.param_sets + await db.execute_write_many( + "insert into t (id, v) values (?, ?)", [[i, f"v{i}"] for i in range(30)] + ) + # datasette.executescript + await db.execute_write_script("create table t2 (id integer); drop table t2;") + # datasette.transaction=False - VACUUM cannot run inside a transaction + await db.execute_write("vacuum", transaction=False) + # datasette.isolated_connection=True + await db.execute_isolated_fn(lambda conn: conn.execute("select 1").fetchone()) + + # Reads: db.query.execute, datasette.rows_returned, datasette.truncated, + # datasette.param_count, datasette.time_limit_ms + 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 + 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. + with pytest.raises(QueryInterrupted): + await db.execute( + "with recursive c(x) as (select 0 union all select x+1 from c) " + "select * from c", + custom_time_limit=1, + ) + + # db.collection.name - set only by views that already know their table + 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 + return ds + + +@pytest_asyncio.fixture +async def emitted(otel_spans): + "Every span name and (span name, attribute key) pair a broad workload emits." + # otel_spans has already cleared the exporter, and nothing is cleared + # after this point: the workload's own startup emits datasette.startup. + ds = await exercise() + spans = otel_spans.get_finished_spans() + assert spans, "no spans captured - the fixture is not exercising anything" + names = set() + pairs = set() + for span in spans: + # str() because span.name is the registry's SpanName instance, and a + # set of those would compare equal to literals but read confusingly + # in a failure message. + names.add(str(span.name)) + for key in span.attributes or {}: + pairs.add((str(span.name), str(key))) + ds.close() + return {"names": names, "pairs": pairs} + + +def _keys_by_span(pairs): + by_span = {} + for span_name, key in pairs: + by_span.setdefault(span_name, set()).add(key) + return by_span + + +@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. + """ + assert emitted["names"] == EXPECTED_SPANS + by_span = _keys_by_span(emitted["pairs"]) + assert {name: by_span.get(name, set()) for name in emitted["names"]} == ( + EXPECTED_ATTRIBUTES + ) + + +def test_registry_matches_the_expected_names(): + "The other half of the rename check: the registry against the same literals." + assert {str(span) for span in reg.SPANS} == EXPECTED_SPANS + for span in reg.SPANS: + assert {str(attribute) for attribute in span.attributes} == EXPECTED_ATTRIBUTES[ + str(span) + ], f"{span} attributes have drifted" + + +@pytest.mark.asyncio +async def test_every_emitted_span_is_registered(emitted): + "A span added without a registry entry would be missing from the docs." + unregistered = sorted( + name for name in emitted["names"] if reg.span_for(name) is None + ) + assert ( + not unregistered + ), f"these spans are emitted but not in telemetry_registry.SPANS: {unregistered}" + + +@pytest.mark.asyncio +async def test_every_emitted_attribute_is_registered(emitted): + "An attribute added without a registry entry would be missing from the docs." + unregistered = sorted( + f"{span_name} -> {key}" + for span_name, key in emitted["pairs"] + if not reg.attribute_allowed(reg.span_for(span_name), key) + ) + assert ( + not unregistered + ), "these span attributes are emitted but not registered: " + ", ".join( + unregistered + ) + + +@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. + """ + missing = sorted( + str(span) + for span in reg.SPANS + if not any(reg.span_for(name) is span for name in emitted["names"]) + ) + assert not missing, ( + f"these spans are documented but never emitted by the workload: {missing}. " + "Either the instrumentation was removed, or exercise() no longer reaches it." + ) + + +@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. + """ + by_span = _keys_by_span(emitted["pairs"]) + missing = [] + for span in reg.SPANS: + emitted_keys = by_span.get(str(span), set()) + for attribute in span.attributes: + if attribute not in emitted_keys: + missing.append(f"{span} -> {attribute}") + assert not missing, ( + "these attributes are documented but never emitted by the workload: " + + ", ".join(sorted(missing)) + ) + + +def test_registry_has_no_duplicate_names(): + assert len(set(reg.SPANS)) == len(reg.SPANS) + for span in reg.SPANS: + assert len(set(span.attributes)) == len( + span.attributes + ), f"{span} lists an attribute twice" + + +def test_registry_entries_are_documented(): + "Every entry carries a description - the docs are generated from these." + for span in reg.SPANS: + assert span.description.strip(), f"{span} has no description" + for attribute in span.attributes: + assert attribute.description.strip(), f"{span} -> {attribute} has none" + + +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" + assert reg.DB_NAMESPACE == "db.namespace" + assert f"{reg.DB_QUERY}.execute" == "db.query.execute" + + +def test_span_and_attribute_lookup(): + assert reg.span_for("db.query") is reg.DB_QUERY + assert reg.span_for("datasette.startup") is reg.STARTUP + assert reg.span_for("not.a.datasette.span") is None + assert reg.attribute_allowed(reg.DB_QUERY, "db.namespace") + assert not reg.attribute_allowed(reg.DB_QUERY, "db.namespace.extra") + assert not reg.attribute_allowed(reg.DB_QUERY, "datasette.isolated_connection") + assert not reg.attribute_allowed(None, "db.namespace") + + +def test_prefix_span_lookup(): + """ + `prefix=True` matching, exercised directly. + + Phase 1 registers no prefix spans, so without this the branch in + `span_for()` would be untested code that the conformance tests silently + never reach. + """ + hook = reg.SpanName("datasette.hook.", "A hypothetical span family", prefix=True) + original = reg.SPANS + reg.SPANS = original + (hook,) + try: + assert reg.span_for("datasette.hook.render_cell") is hook + assert reg.span_for("datasette.hook.anything") is hook + assert reg.span_for("datasette.hookish") is None + assert reg.span_for("db.query") is reg.DB_QUERY + finally: + reg.SPANS = original From b74231c190ce4ca71be5ce7f69513c63d30625fe Mon Sep 17 00:00:00 2001 From: Alex Garcia Date: Thu, 30 Jul 2026 18:58:53 -0700 Subject: [PATCH 09/13] Stop marking a deliberately-short query budget as a span error Datasette has a family of callers that run a query under a tiny time limit and treat "did not finish" as a usable answer. table_counts() is the loudest: the homepage counts every table with a 10ms budget and stores None for the ones that blow it. The QueryInterrupted handler on the db.query span was unconditional, so on a two-table database that produced four ERROR spans - two db.query and two db.query.execute - on every homepage hit. Measured on a 30MB two-table database: 4 red spans before, 0 after. Honouring log_sql_errors here would have silenced none of it. Only the three ArrayFacet json_type() probes pass log_sql_errors=False, and they are not the queries that time out; table_counts() and ColumnFacet.suggest both leave it at its True default. The signal that does separate the two cases is the budget itself: a caller asking for less time than sql_time_limit_ms is saying the query may not finish. Keying off that needs no new API and no changes outside database.py. A query that runs out the instance-wide limit is still an error. datasette.interrupted is still set in every case - it is the signal worth having, and only the ERROR status becomes conditional. Its registry description said the status is "also set to ERROR" full stop, which is now wrong, and that string is published in docs/internals.rst. The inner db.query.execute span carried the same bug through set_status_on_exception=log_sql_errors, so its exception handling is now explicit, matching the db.query span above it. The context manager's flags apply to every exception type alike and this span has to tell two apart. test_query_interrupted_sets_error_status forced its timeout with ?_timelimit=5, which is exactly the signal now reclassified as expected. It now forces one via sql_time_limit_ms so it still tests what it was written to test. Also documents, at the copy_context() sites, that context propagation carries Datasette's non-OTel ContextVars into worker threads too. Verified harmless: nothing reads _skip_permission_checks, _permission_check_cache or _in_datasette_client off the event loop, and Context.run() restores the thread's previous context on return, so no value can reach the next task on the shared pool. Co-Authored-By: Claude Opus 5 --- datasette/database.py | 116 +++++++++++++++++++++--------- datasette/telemetry_registry.py | 6 +- docs/internals.rst | 2 +- tests/test_telemetry.py | 120 +++++++++++++++++++++++++++++--- 4 files changed, 201 insertions(+), 43 deletions(-) diff --git a/datasette/database.py b/datasette/database.py index 22984d6f..7114a691 100644 --- a/datasette/database.py +++ b/datasette/database.py @@ -394,6 +394,9 @@ class Database: # 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. + # + # It also propagates every *other* ContextVar - see the note in + # execute_fn() for why that is safe. ctx = contextvars.copy_context() return await asyncio.get_running_loop().run_in_executor( self.ds.executor, ctx.run, _run @@ -695,6 +698,22 @@ class Database: # 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. ctx = contextvars.copy_context() future = self.ds.executor.submit(ctx.run, in_thread) self._pending_execute_futures.add(future) @@ -722,7 +741,19 @@ class Database: self._check_not_closed() page_size = page_size or self.ds.page_size time_limit_ms = self.ds.sql_time_limit_ms - if custom_time_limit and custom_time_limit < 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. + 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): @@ -733,38 +764,53 @@ class Database: # databases) - so it parents correctly to the enclosing # db.query span despite running on a different thread. # - # Callers passing log_sql_errors=False are probing and treat a - # failure as an expected answer - see the matching handling on the - # db.query span in execute(). Without this, facet suggestion marks - # two spans per text column as failed on every table page. + # 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. with tracer.start_as_current_span( DB_QUERY_EXECUTE, - record_exception=log_sql_errors, - set_status_on_exception=log_sql_errors, - ): - with sqlite_timelimit(conn, time_limit_ms): - try: - cursor = conn.cursor() - cursor.execute(sql, params if params is not None else {}) - max_returned_rows = self.ds.max_returned_rows - if max_returned_rows == page_size: - max_returned_rows += 1 - if max_returned_rows and truncate: - rows = cursor.fetchmany(max_returned_rows + 1) - truncated = len(rows) > max_returned_rows - rows = rows[:max_returned_rows] - else: - rows = cursor.fetchall() - truncated = False - except (sqlite3.OperationalError, sqlite3.DatabaseError) as e: - if e.args == ("interrupted",): - raise QueryInterrupted(e, sql, params) - if log_sql_errors: - sys.stderr.write( - f"ERROR: conn={conn}, sql = {sql!r}, params = {params}: {e}\n" - ) - sys.stderr.flush() - raise + record_exception=False, + set_status_on_exception=False, + ) as execute_span: + try: + with sqlite_timelimit(conn, time_limit_ms): + try: + cursor = conn.cursor() + cursor.execute(sql, params if params is not None else {}) + max_returned_rows = self.ds.max_returned_rows + if max_returned_rows == page_size: + max_returned_rows += 1 + if max_returned_rows and truncate: + rows = cursor.fetchmany(max_returned_rows + 1) + truncated = len(rows) > max_returned_rows + rows = rows[:max_returned_rows] + else: + rows = cursor.fetchall() + truncated = False + except (sqlite3.OperationalError, sqlite3.DatabaseError) as e: + if e.args == ("interrupted",): + raise QueryInterrupted(e, sql, params) + if log_sql_errors: + sys.stderr.write( + f"ERROR: conn={conn}, sql = {sql!r}, params = {params}: {e}\n" + ) + sys.stderr.flush() + raise + except QueryInterrupted as e: + if not timeout_expected: + execute_span.record_exception(e) + execute_span.set_status(Status(StatusCode.ERROR, str(e))) + raise + except Exception as e: + if log_sql_errors: + execute_span.record_exception(e) + execute_span.set_status(Status(StatusCode.ERROR, str(e))) + raise if truncate: return Results(rows, truncated, cursor.description) @@ -801,9 +847,13 @@ class Database: try: results = await self.execute_fn(sql_operation_in_thread) except QueryInterrupted as e: - span.set_status(Status(StatusCode.ERROR, str(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) - span.record_exception(e) + if not timeout_expected: + span.set_status(Status(StatusCode.ERROR, str(e))) + span.record_exception(e) raise except Exception as e: # log_sql_errors=False means the caller is probing and diff --git a/datasette/telemetry_registry.py b/datasette/telemetry_registry.py index 40b32cc5..2d0692a8 100644 --- a/datasette/telemetry_registry.py +++ b/datasette/telemetry_registry.py @@ -137,7 +137,11 @@ TRUNCATED = Attribute( INTERRUPTED = Attribute( "datasette.interrupted", "True if the query was cancelled for exceeding the time limit. The span " - "status is also set to ``ERROR``.", + "status is also set to ``ERROR``, unless the caller asked for a budget " + "shorter than :ref:`setting_sql_time_limit_ms` - as table counts, facet " + "suggestion and autocomplete all do - in which case running out of time " + "is an expected answer rather than a failure and the status is left " + "unset.", optional=True, ) SQL_ERROR_SUPPRESSED = Attribute( diff --git a/docs/internals.rst b/docs/internals.rst index b2215d9d..e7028637 100644 --- a/docs/internals.rst +++ b/docs/internals.rst @@ -2355,7 +2355,7 @@ Spans are ``SpanKind.INTERNAL`` unless a kind is listed below. Only ``db.query`` - ``datasette.time_limit_ms`` *(optional)* - The :ref:`setting_sql_time_limit_ms` value this query ran under. Set on reads, which are the queries that time limit applies to. - ``datasette.rows_returned`` *(optional)* - Number of rows a read returned. Set on the read path only, and only when the read succeeded. - ``datasette.truncated`` *(optional)* - True if the result was cut short by :ref:`setting_max_returned_rows`. - - ``datasette.interrupted`` *(optional)* - True if the query was cancelled for exceeding the time limit. The span status is also set to ``ERROR``. + - ``datasette.interrupted`` *(optional)* - True if the query was cancelled for exceeding the time limit. The span status is also set to ``ERROR``, unless the caller asked for a budget shorter than :ref:`setting_sql_time_limit_ms` - as table counts, facet suggestion and autocomplete all do - in which case running out of time is an expected answer rather than a failure and the status is left unset. - ``datasette.sql_error_suppressed`` *(optional)* - True when the query failed but the caller passed ``log_sql_errors=False``, meaning it was probing and treats failure as an expected answer. Facet suggestion does this against every column. - ``datasette.executescript`` *(optional)* - True for ``execute_write_script()``, which runs multiple statements. - ``datasette.executemany`` *(optional)* - True for ``execute_write_many()``, which runs one statement against many parameter sets. diff --git a/tests/test_telemetry.py b/tests/test_telemetry.py index 0a6d0192..0022883a 100644 --- a/tests/test_telemetry.py +++ b/tests/test_telemetry.py @@ -12,7 +12,7 @@ from opentelemetry import trace as otel_trace from opentelemetry.trace import SpanKind, StatusCode from datasette.app import Datasette -from datasette.database import Database +from datasette.database import Database, QueryInterrupted from datasette.telemetry import ( MAX_SQL_LENGTH, SCHEMA_URL, @@ -26,6 +26,15 @@ 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. +SLOW_SQL = """ +with recursive counter(x) as ( + select 1 union all select x + 1 from counter where x < 50000000 +) +select max(x) from counter +""" + def _db_query_spans(otel_spans): return [span for span in otel_spans.get_finished_spans() if span.name == "db.query"] @@ -212,14 +221,22 @@ 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(ds_client, otel_spans): - response = await ds_client.get( - "/fixtures/-/query.json", - params={"sql": "select sleep(0.05)", "_timelimit": 5}, - ) - assert response.status_code == 400 +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. - spans = _db_query_spans(otel_spans) + 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. + """ + ds = Datasette(memory=True, settings={"sql_time_limit_ms": 20}) + db = ds.add_memory_database("t09_instance_limit_timeout") + with pytest.raises(QueryInterrupted): + await db.execute(SLOW_SQL) + + spans = _spans_for_namespace(otel_spans, "t09_instance_limit_timeout") assert spans span = spans[-1] assert span.status.status_code == StatusCode.ERROR @@ -228,6 +245,93 @@ async def test_query_interrupted_sets_error_status(ds_client, otel_spans): assert all(event.name == "exception" for event in span.events) +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. + """ + 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. + counts = await db.table_counts(1) + assert counts == { + "big": None + }, "the count did not actually time out, so the rest of this test is vacuous" + + spans = [ + span + for span in _spans_for_namespace(otel_spans, database_name) + if "count(*)" in span.attributes["db.query.text"] + ] + assert len(spans) == 1 + return spans[0] + + +@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. + 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"] + + +@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. + """ + 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 + child = children[0] + assert child.status.status_code != StatusCode.ERROR + assert not [event for event in child.events if event.name == "exception"] + + +@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. + """ + ds = Datasette(memory=True, settings={"sql_time_limit_ms": 20}) + db = ds.add_memory_database("t09_custom_limit_ignored") + with pytest.raises(QueryInterrupted): + await db.execute(SLOW_SQL, custom_time_limit=5000) + + 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. + assert span.attributes["datasette.time_limit_ms"] == 20 + assert span.attributes["datasette.interrupted"] is True + assert span.status.status_code == StatusCode.ERROR + assert any(event.name == "exception" for event in span.events) + + children = _children_named(otel_spans, "db.query.execute", span.context) + assert len(children) == 1 + assert children[0].status.status_code == StatusCode.ERROR + + @pytest.mark.asyncio async def test_unsuppressed_sql_error_is_a_span_error(ds_client, otel_spans): db = ds_client.ds.get_database("fixtures") From 1052dc5c7b676193d175810f8f97580aae6b4493 Mon Sep 17 00:00:00 2001 From: Alex Garcia Date: Thu, 30 Jul 2026 19:10:04 -0700 Subject: [PATCH 10/13] Document what the database-layer spans emit, and how to turn them on The span reference itself is generated from the registry, so this adds the prose the generated list cannot supply: how to actually see a span, what is deliberately never recorded, and where the instrumentation stops short. The "how to turn it on" part is the part people get wrong. Core installs no provider, so OTEL_TRACES_EXPORTER=console against a plain `datasette` process emits nothing at all - that variable is read by the SDK auto-configuration which only runs under `opentelemetry-instrument`. Documented as a warning because it reads like a bug when you hit it. Two more measured facts get the same treatment: the SDK's BatchSpanProcessor default schedule delay is 5000ms (checked, not assumed - `BatchSpanProcessor._default_schedule_delay_millis()` on opentelemetry-sdk 1.44), so nothing appears for five seconds; and without OTEL_SERVICE_NAME the default resource reports service.name=unknown_service. Privacy properties are stated positively rather than left implicit: SQL truncated at 2048 characters, parameter values never recorded, no actor identifiers, table names only from an explicit `table=` argument. The last of those is now documented on db.execute() itself, since it is public API. The limitations section claims only what was measured. An earlier draft said two traces per process are orphaned by the register_output_renderer and asgi_wrapper hooks; measuring it showed a default install emits zero spans from either, because Datasette queries no database there - it is a plugin that would produce the orphan. Corrected to say that. It also deliberately does NOT say an embedder must install its provider before Datasette's first span or get nothing. That claim is false: ProxyTracer._tracer returns the no-op tracer without caching it when no provider is set, so early spans are dropped and nothing is poisoned. The telemetry.py docstring said no-op spans "cost approximately nothing". The benchmark for this diff does not support a claim that strong - a table page emits ~58 spans - so it now states the measurement instead: median 9.80ms to 9.98ms across 15 runs, inside a 1.4ms run-to-run spread. Co-Authored-By: Claude Opus 5 --- datasette/telemetry.py | 10 +++++-- docs/changelog.rst | 10 +++++++ docs/internals.rst | 62 ++++++++++++++++++++++++++++++++++++++++-- 3 files changed, 78 insertions(+), 4 deletions(-) diff --git a/datasette/telemetry.py b/datasette/telemetry.py index 37195584..3a205cee 100644 --- a/datasette/telemetry.py +++ b/datasette/telemetry.py @@ -5,8 +5,14 @@ Core depends on `opentelemetry-api` only. It never creates a `TracerProvider`, 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` and costs approximately nothing. +harness). + +With no provider installed every span produced here is a +`NonRecordingSpan`. That is not free - a table page emits ~58 spans - +but it is below what an end-to-end page benchmark can resolve: measured +across 15 runs of a 5,000-row table page, the median moved 9.80ms to +9.98ms while run-to-run spread was 1.4ms. Installing an SDK provider is +what costs something measurable. """ import re diff --git a/docs/changelog.rst b/docs/changelog.rst index 66a7caab..cec8e92d 100644 --- a/docs/changelog.rst +++ b/docs/changelog.rst @@ -4,6 +4,16 @@ Changelog ========= +.. _v_unreleased: + +Unreleased +---------- + +- Datasette's database layer now emits `OpenTelemetry `__ spans: one per query, covering the full round trip including time spent waiting for a SQL worker thread, plus separate child spans for the execution itself and for time spent in the write queue. Datasette core depends on ``opentelemetry-api`` only and never installs an SDK provider, an exporter or a sampler, so there is no effect and no measurable overhead unless tracing is switched on externally - normally with the standard ``opentelemetry-instrument`` agent. See :ref:`internals_telemetry`. (:issue:`1730`) +- :ref:`db.execute(sql, ..., table=None) ` has a new optional ``table=`` parameter, naming the table a query is about so it can be recorded on that query's OpenTelemetry span. It has no effect on query execution, and Datasette never derives it from the SQL. (:issue:`1730`) + +Nothing is removed by this change: the ``?_trace=1`` query string parameter, the ``trace_debug`` setting and the :ref:`internals_tracer` module all continue to work as before. + .. _v1_0_a38: 1.0a38 (2026-08-06) diff --git a/docs/internals.rst b/docs/internals.rst index e7028637..31666e0e 100644 --- a/docs/internals.rst +++ b/docs/internals.rst @@ -1963,6 +1963,9 @@ Executes a SQL query against the database and returns the resulting rows (see :r ``log_sql_errors`` - boolean Should any SQL errors be logged to the console in addition to being raised as an error? Defaults to ``True``. +``table`` - string + The name of the table this query is about, if the caller already knows it. This has no effect on how the query executes - it is recorded as the ``db.collection.name`` attribute on the :ref:`OpenTelemetry span ` for the query. Datasette never derives this from the SQL, so leave it unset for queries that do not have one obvious table. + .. _database_results: Results @@ -2318,16 +2321,47 @@ The ``Database`` class also provides properties and methods for introspecting th OpenTelemetry ============= -Datasette core depends on `opentelemetry-api `__ only. It never creates a ``TracerProvider``, never configures an exporter and never sets a sampler. With no OpenTelemetry SDK provider installed, every span described below is a no-op ``NonRecordingSpan`` - the overhead is close to zero and nothing is recorded or exported anywhere. +Datasette core depends on `opentelemetry-api `__ only. It never creates a ``TracerProvider``, never configures an exporter and never sets a sampler. With no OpenTelemetry SDK provider installed, every span described below is a no-op ``NonRecordingSpan``: nothing is recorded, nothing is exported, and the cost does not show up in page latency. Benchmarking a table page with and without this instrumentation, the median moved by less than the run-to-run variation of the benchmark itself. Turning tracing on is entirely an operational decision made outside of Datasette itself: run Datasette under the standard ``opentelemetry-instrument`` agent, or embed Datasette inside a host application that installs its own provider. Everything Datasette emits carries the instrumentation scope ``datasette``, versioned with the running Datasette version and declaring the `semantic conventions schema `__ its attribute names follow. +This is separate from, and does not replace, the built-in :ref:`internals_tracer` mechanism behind ``?_trace=1`` and the :ref:`setting_trace_debug` setting. Both continue to work exactly as before. + +.. _internals_telemetry_turning_on: + +Turning tracing on +------------------ + +Install an OpenTelemetry SDK, an exporter and the instrumentation agent, then launch Datasette through ``opentelemetry-instrument``: + +.. code-block:: bash + + pip install opentelemetry-distro opentelemetry-exporter-otlp + OTEL_SERVICE_NAME=datasette \ + OTEL_EXPORTER_OTLP_ENDPOINT=http://localhost:4317 \ + OTEL_METRICS_EXPORTER=none \ + OTEL_LOGS_EXPORTER=none \ + opentelemetry-instrument datasette mydb.db + +Point ``OTEL_EXPORTER_OTLP_ENDPOINT`` at whichever tracing backend you use. To print spans straight to the terminal instead, with no backend at all, drop that variable and set ``OTEL_TRACES_EXPORTER=console`` in its place. + +A few things catch people out the first time: + +.. warning:: + ``OTEL_TRACES_EXPORTER=console datasette mydb.db`` produces **nothing**. That environment variable is read by the OpenTelemetry SDK's auto-configuration, which only runs when the ``opentelemetry-instrument`` agent wraps the process. Datasette core installs no provider, so a plain ``datasette`` process emits nothing at all, whatever ``OTEL_`` variables are set. + +Spans do not appear immediately. The SDK's default ``BatchSpanProcessor`` flushes on a timer, every 5 seconds. Either wait, or stop the process - shutdown triggers a final flush - or set ``OTEL_BSP_SCHEDULE_DELAY=1000`` while you are experimenting. That last one is for demos, not for production. + +Always set ``OTEL_SERVICE_NAME``. Without it the SDK's default resource reports a ``service.name`` of ``unknown_service``, and your traces will be filed under that instead of under a name you can search for. + +Setting ``OTEL_METRICS_EXPORTER=none`` and ``OTEL_LOGS_EXPORTER=none`` is worth doing unless your backend accepts those signals too - ``opentelemetry-distro`` defaults every signal to OTLP, and a traces-only backend will reject the other two noisily. Datasette itself emits no metrics and no logs through OpenTelemetry. + Span reference -------------- -Attribute names use the ``datasette.*`` prefix for Datasette-specific data, alongside standard OpenTelemetry attributes such as ``db.system``. +Datasette emits five spans. Four of them describe the database layer - one per query, one for the work that query does inside a SQL worker thread, and two more for the write queue - and the fifth covers startup. Attribute names use the ``datasette.*`` prefix for Datasette-specific data, alongside standard OpenTelemetry attributes such as ``db.system``. This reference is generated from ``datasette/telemetry_registry.py``, the single source of truth for every span and attribute Datasette emits. A conformance test makes real requests and compares what is actually emitted against that registry in both directions, so nothing here is hand-maintained and nothing can silently drift out of date. @@ -2385,6 +2419,30 @@ Spans are ``SpanKind.INTERNAL`` unless a kind is listed below. Only ``db.query`` .. [[[end]]] +.. _internals_telemetry_privacy: + +Privacy and safety +------------------ + +Spans leave your infrastructure whenever you configure an exporter, so what goes into them is a security decision. Datasette's rules are: + +- **SQL text is truncated to 2048 characters.** On a public instance the SQL is supplied by visitors and is unbounded in length, so ``db.query.text`` is cut off - with a ``…[truncated]`` marker - rather than allowed to set the size of a span. +- **SQL parameter values are never recorded.** Only ``datasette.param_count``, a count. Parameter values are the part of a query most likely to hold something sensitive, and separating them from the SQL is the reason bound parameters exist. +- **No actor identifiers are recorded.** No actor ID, no actor JSON, no client IP address. Nothing on a span identifies who made the request. +- **Table names come only from an explicit** ``table=`` **argument.** ``db.collection.name`` is set by callers that already know which table they are working with, and is never derived from the SQL. Deriving it would mean parsing, and on an instance where visitors can create tables the set of possible values has no ceiling. + +The SQL itself, though, *is* recorded, and on a public instance that means anything a visitor types into the query editor or passes as ``?sql=`` will be exported along with the span. That is the trade-off tracing a query engine makes. + +.. _internals_telemetry_limitations: + +Known limitations +----------------- + +- **Datasette does not create a span for the HTTP request itself.** Every span listed above is therefore a root span unless something above Datasette - an ASGI instrumentation layer, or the web framework embedding it - has already started one for the request, in which case Datasette's spans nest underneath it correctly. +- **Two plugin hooks run outside the** ``datasette.startup`` **span.** ``register_output_renderer`` is dispatched from ``Datasette.__init__()`` and ``asgi_wrapper`` from ``Datasette.app()``, both of which happen before ``invoke_startup()``. Datasette itself queries no database in either, so a default install emits nothing there - but a plugin that does will produce a root trace. Covering these would mean holding a span open across object construction, which is worse than the orphan. +- ``db.operation.name`` **reports** ``WITH`` **for a statement that opens with a common table expression**, rather than the operation inside it, and a substantial share of Datasette's own reads take that form. The attribute is a leading-keyword match against a fixed allowlist, deliberately not a parse. +- **Spans emitted before a provider is installed are not recorded.** If you are embedding Datasette in a host application, install your ``TracerProvider`` before serving traffic. This is ordinary OpenTelemetry behaviour rather than anything Datasette controls; nothing is permanently affected, those particular spans are simply dropped. + .. _internals_csrf: CSRF protection From f5eada266e69605072f60b05bd21d5c90f10ef68 Mon Sep 17 00:00:00 2001 From: Alex Garcia Date: Thu, 30 Jul 2026 19:33:04 -0700 Subject: [PATCH 11/13] Give every span a request to belong to Nothing in Datasette created a span for the HTTP request itself, so every span the database layer emits was a root span. Measured on this branch: one faceted table page produces 70 spans in 36 separate traces, none of which carries a URL. A trace UI shows that as dozens of unrelated single-span traces per page, interleaved across concurrent requests - worse than ?_trace=1 at the exact job people reach for tracing to do. With the request span it is 71 spans in 1 trace. `opentelemetry-instrument` does not fix this on its own: auto-instrumentation only picks up frameworks that ship an instrumentor entry point, and Datasette's raw ASGI app is not one. TelemetryMiddleware is mounted outermost in Datasette.app(), after the asgi_wrapper() plugin loop, so plugin middleware and the CSRF layer run *inside* the span. Putting it in DatasetteRouter instead would leave a span created by an instrumented plugin as an orphan root - reintroducing the problem for exactly the code most likely to be instrumented. It stays at ~90 lines, against roughly 700 for opentelemetry-instrumentation-asgi, because Datasette's app does not return before its body is sent: route_path awaits response.asgi_send(send), and a streaming CSV export runs its generator inline inside AsgiStream.asgi_send. So a plain `finally` covers the response body and no deferred-end machinery is needed. Two decisions worth flagging for review: - Inbound W3C traceparent and baggage are extracted, using the *global* propagator. That is the ecosystem norm (Flask, Django, FastAPI, the ASGI instrumentation), and going through the global propagator leaves the operator in control with no Datasette setting to invent: OTEL_PROPAGATORS=none disables it entirely. A public instance that does not want client-influenced traces should strip those headers at the proxy. - url.query is not recorded, anywhere. Datasette query strings carry user-supplied SQL in ?sql= and canned query parameters. client.address is not recorded either. The status code is sniffed from the ASGI http.response.start message rather than read off a Response, because asgi_static, the favicon route, AsgiStream and AsgiFileDownload all send that message themselves and never build one. Only a >= 500 sets an error status - per semantic conventions a 4xx is the client's mistake, and Datasette 404s are routine enough that treating them as errors would bury a real 500. The registry gains a `dynamic` flag, because this span's name is composed at runtime and so can never equal a fixed registry string. Dynamic entries resolve by span kind instead, and only after exact and prefix matching has failed, so they cannot shadow a span that does have a registered name. Co-Authored-By: Claude Opus 5 --- datasette/app.py | 24 ++- datasette/telemetry.py | 194 +++++++++++++++++ datasette/telemetry_registry.py | 110 +++++++++- docs/internals.rst | 21 +- tests/test_http_span.py | 344 +++++++++++++++++++++++++++++++ tests/test_telemetry_registry.py | 172 ++++++++++++---- 6 files changed, 814 insertions(+), 51 deletions(-) create mode 100644 tests/test_http_span.py diff --git a/datasette/app.py b/datasette/app.py index 7499c6f9..939c8cf8 100644 --- a/datasette/app.py +++ b/datasette/app.py @@ -49,7 +49,7 @@ from .events import Event from .plugins import DEFAULT_PLUGINS, get_plugins, pm from .renderer import json_renderer from .resources import DatabaseResource, TableResource -from .telemetry import tracer +from .telemetry import TelemetryMiddleware, tracer from .telemetry_registry import STARTUP from .tokens import TokenInvalid from .tracer import AsgiTracer @@ -780,12 +780,16 @@ class Datasette: # This must be called for Datasette to be in a usable state if self._startup_invoked: return - # invoke_startup() runs before any request exists, so every span its - # children create - the register_* hook dispatches, the internal - # catalog's db.query/db.write spans, and the prepare_connection - # warm-up of the read connections those touch - would otherwise be - # its own orphan root trace: around twenty of them on a fresh - # instance. Bracketing the whole thing gives them somewhere to belong. + # `datasette serve` calls invoke_startup() before uvicorn starts, so + # on the CLI path every span its children create - the register_* + # hook dispatches, the internal catalog's db.query/db.write spans, + # and the prepare_connection warm-up of the read connections those + # touch - would otherwise be its own orphan root trace: around twenty + # of them on a fresh instance. Bracketing the whole thing gives them + # somewhere to belong. An ASGI-hosted or programmatic deployment + # reaches here instead through AsgiRunOnFirstRequest, in which case + # this span nests under the first request's own span - honest enough, + # since it genuinely is that request's latency. # A connection warmed lazily later, by a request touching a new # database for the first time, nests under that request instead: # this span has already ended by then. @@ -2868,6 +2872,12 @@ class Datasette: asgi = AsgiRunOnFirstRequest(asgi, on_startup=[self._startup_sequence]) for wrapper in pm.hook.asgi_wrapper(datasette=self): asgi = wrapper(asgi) + # Outermost, deliberately: plugin asgi_wrapper() middleware, the + # CSRF layer and the first-request startup fallback all run *inside* + # this span, so a span created by an instrumented plugin - or by + # startup work triggered by the first request - parents to the + # request instead of becoming its own orphan root trace. + asgi = TelemetryMiddleware(asgi) return asgi diff --git a/datasette/telemetry.py b/datasette/telemetry.py index 3a205cee..31541a47 100644 --- a/datasette/telemetry.py +++ b/datasette/telemetry.py @@ -18,7 +18,19 @@ what costs something measurable. import re from opentelemetry import trace as otel_trace +from opentelemetry.propagate import extract +from opentelemetry.propagators.textmap import Getter +from opentelemetry.trace import SpanKind, Status, StatusCode +from .telemetry_registry import ( + ERROR_TYPE, + HTTP_REQUEST_METHOD, + HTTP_RESPONSE_STATUS_CODE, + SERVER_ADDRESS, + URL_PATH, + URL_SCHEME, + USER_AGENT_ORIGINAL, +) from .version import __version__ # The semantic-convention version whose spellings this instrumentation @@ -115,3 +127,185 @@ def sql_operation_name(sql: str) -> str | None: if keyword in DB_OPERATION_ALLOWLIST: return keyword return None + + +# --- The HTTP request span ------------------------------------------------ + + +class _ScopeHeadersGetter(Getter): + """ + Read W3C trace context out of an ASGI scope's headers. + + `scope["headers"]` is a list of `(bytes, bytes)` pairs, lowercased by the + server per the ASGI spec - but `.lower()` is applied again here because + that is a spec promise about servers, not something this process + controls. Header bytes are latin-1 by RFC 9110. + """ + + def get(self, carrier, key): + wanted = key.lower().encode("latin-1") + values = [v.decode("latin-1") for k, v in carrier if k.lower() == wanted] + return values or None + + def keys(self, carrier): + return [k.decode("latin-1") for k, _ in carrier] + + +_HEADERS_GETTER = _ScopeHeadersGetter() + + +# An unclamped method is an unbounded dimension a client controls: anyone can +# send `FOO / HTTP/1.1`. Semantic conventions say map anything unrecognised to +# `_OTHER`. These nine are the methods of RFC 9110 plus PATCH (RFC 5789). +_KNOWN_METHODS = frozenset( + {"GET", "HEAD", "POST", "PUT", "DELETE", "CONNECT", "OPTIONS", "TRACE", "PATCH"} +) + + +def clamp_http_method(method): + "The request method if it is one we recognise, else ``_OTHER``." + method = (method or "").upper() + return method if method in _KNOWN_METHODS else "_OTHER" + + +def _first_header(headers, name): + "The first value of a header, decoded, or None." + for key, value in headers: + if key.lower() == name: + return value.decode("latin-1") + return None + + +def _url_path(scope): + """ + The request path, with any query string removed. + + `raw_path` is preferred because it is the bytes the client sent, before + percent-decoding - Datasette routes on database and table names that can + contain encoded slashes, which `scope["path"]` has already collapsed. + + The split on "?" is not decoration. The ASGI spec's `raw_path` excludes + the query string, and uvicorn honours that, but the name is used the + other way round elsewhere in this same dependency tree: httpx's + `URL.raw_path` is documented as "raw bytes of both the path and query". + A server that followed that reading would hand us `?sql=...` here, and + Datasette's query strings carry user-supplied SQL, which core never + records. A literal "?" cannot appear unencoded in a path, so the split + costs nothing when the server is well behaved. + """ + raw_path = scope.get("raw_path") + if raw_path: + if isinstance(raw_path, bytes): + raw_path = raw_path.decode("latin-1") + return raw_path.split("?", 1)[0] + return scope.get("path", "") + + +class TelemetryMiddleware: + """ + One `SpanKind.SERVER` span per HTTP request. + + Mounted outermost in `Datasette.app()`, so every other span raised while + serving a request - database queries, plugin middleware, startup work on + a cold ASGI-hosted deployment - has somewhere to belong instead of + becoming its own root trace. + + Deliberately much smaller than `opentelemetry-instrumentation-asgi`, + which needs several hundred lines of deferred-end machinery for + applications that return before their body is sent. Datasette does not: + `DatasetteRouter.route_path` awaits `response.asgi_send(send)`, and for a + streaming CSV export `AsgiStream.asgi_send` runs the generator inline. + All of it happens inside the single `await self.app(...)` below, so + ending the span in a `finally` covers the response body too. + """ + + def __init__(self, app): + self.app = app + + async def __call__(self, scope, receive, send): + # First, before anything else: `AsgiLifespan` is *inside* this + # middleware, so lifespan startup and shutdown have to pass through + # untouched or the server never starts. Same for websockets. + if scope["type"] != "http": + await self.app(scope, receive, send) + return + headers = scope.get("headers") or [] + # The *global* propagator, deliberately: it leaves the operator in + # control with no Datasette-specific setting - OTEL_PROPAGATORS=none + # disables extraction entirely, OTEL_PROPAGATORS=tracecontext drops + # baggage - and core configuring propagation itself would be the same + # mistake as core configuring sampling. + context = extract(headers, getter=_HEADERS_GETTER) + method = clamp_http_method(scope.get("method", "")) + # The method, not the URL: a span name has to be low cardinality, and + # the method is what is known out here at the edge, before any routing + # has happened. + with tracer.start_as_current_span( + method, context=context, kind=SpanKind.SERVER + ) as span: + if not span.is_recording(): + # No provider installed, or a sampler dropped this trace. + # Everything below would be discarded, so skip building the + # `send` wrapper and let a default install pay almost + # nothing. Note this cannot be `get_span_context().is_valid`: + # with no provider but an inbound `traceparent`, the API's + # NoOpTracer returns a NonRecordingSpan carrying the *remote* + # context, which is perfectly valid and still records nothing. + await self.app(scope, receive, send) + return + span.set_attribute(HTTP_REQUEST_METHOD, method) + span.set_attribute(URL_PATH, _url_path(scope)) + scheme = scope.get("scheme") + if scheme: + span.set_attribute(URL_SCHEME, scheme) + host = _first_header(headers, b"host") + if host: + span.set_attribute(SERVER_ADDRESS, host) + user_agent = _first_header(headers, b"user-agent") + if user_agent: + span.set_attribute(USER_AGENT_ORIGINAL, user_agent) + + # The status cannot be read off a Response object: `asgi_static`, + # the favicon route, `AsgiStream` and `AsgiFileDownload` all call + # `send` directly and never build one. Wrapping `send` is the only + # thing that sees every response, including the 404 and 500 + # handlers. + status_holder = {} + + async def wrapped_send(message): + if ( + message["type"] == "http.response.start" + and "status" not in status_holder + ): + status_holder["status"] = message["status"] + await send(message) + + escaped = False + try: + # Positional (scope, receive, send) throughout this codebase - + # `wrapped_send` is the third argument. `receive` is passed + # through unwrapped. + await self.app(scope, receive, wrapped_send) + except BaseException as exception: + # BaseException, not Exception: `route_path` turns almost + # everything into a 500 itself, but `asyncio.CancelledError` + # on client disconnect is a BaseException its `except + # Exception` deliberately does not catch. + escaped = True + span.set_attribute(ERROR_TYPE, type(exception).__name__) + span.set_status(Status(StatusCode.ERROR, str(exception))) + raise + finally: + status = status_holder.get("status") + if status is not None: + span.set_attribute(HTTP_RESPONSE_STATUS_CODE, status) + # 4xx is NOT an error for a SERVER span per semantic + # conventions - the client made the mistake, not us. + # + # `not escaped` because this block still runs when an + # exception is on its way out, and a response can have + # started before it: the exception's class name is more + # use than the string "500", so it wins. + if status >= 500 and not escaped: + span.set_status(Status(StatusCode.ERROR)) + span.set_attribute(ERROR_TYPE, str(status)) diff --git a/datasette/telemetry_registry.py b/datasette/telemetry_registry.py index 2d0692a8..ddecbc5b 100644 --- a/datasette/telemetry_registry.py +++ b/datasette/telemetry_registry.py @@ -47,10 +47,16 @@ class Attribute(str): class SpanName(str): "A span name, carrying its documentation and the attributes it may set." - __slots__ = ("attributes", "description", "kind", "prefix") + __slots__ = ("attributes", "description", "dynamic", "kind", "prefix") def __new__( - cls, name, description, attributes=(), prefix=False, kind=SpanKind.INTERNAL + cls, + name, + description, + attributes=(), + prefix=False, + dynamic=False, + kind=SpanKind.INTERNAL, ): self = super().__new__(cls, name) self.description = description @@ -59,6 +65,13 @@ class SpanName(str): # so the conformance test matches by prefix rather than equality. # Nothing sets it yet. self.prefix = prefix + # True when the emitted name is composed at runtime and shares no + # fixed prefix with the registry entry - the HTTP request span, whose + # name is the request method. There is no substring of the entry that + # could be matched against the wire, so `span_for()` resolves these by + # span kind instead, and the entry's own string is a template written + # for a human reading the generated reference. + self.dynamic = dynamic # SpanKind.INTERNAL by default - every span Datasette emits describes # its own internal work. db.query is the one exception: it is a real # database call, so semantic conventions (and trace UIs, which key @@ -75,6 +88,53 @@ class SpanName(str): # Shared attributes are defined once and referenced by every span that sets # them, so "which spans carry db.namespace?" is answerable by grep. +HTTP_REQUEST_METHOD = Attribute( + "http.request.method", + "The HTTP method, clamped to the nine methods RFC 9110 and RFC 5789 " + "define. Anything else is reported as ``_OTHER``: the method is a " + "client-controlled string, so echoing it back unbounded would be a " + "cardinality hazard.", +) +HTTP_RESPONSE_STATUS_CODE = Attribute( + "http.response.status_code", + "The status of the response, read from the ASGI ``http.response.start`` " + "message rather than from a :ref:`internals_response` object - several " + "views, including static files, file downloads and streaming CSV, send " + "that message themselves and never build one. Omitted if the connection " + "closed before anything was sent.", + optional=True, +) +URL_PATH = Attribute( + "url.path", + "The path portion of the URL. The query string is deliberately **not** " + "recorded, on this or any other span: Datasette puts user-supplied SQL in " + "``?sql=`` and canned query parameters in the query string, so exporting " + "it by default would export exactly the data the rest of this " + "instrumentation is careful with.", +) +URL_SCHEME = Attribute("url.scheme", "``http`` or ``https``.") +SERVER_ADDRESS = Attribute( + "server.address", + "The ``Host`` header. Client-controlled, so treat it as untrusted input " + "rather than as the identity of the server.", + optional=True, +) +USER_AGENT_ORIGINAL = Attribute( + "user_agent.original", + "The ``User-Agent`` header, verbatim. Omitted if the client sent none. " + "The client's IP address is deliberately not recorded: core records no " + "identifier that would tie a span to a person.", + optional=True, +) +ERROR_TYPE = Attribute( + "error.type", + "Set when the request failed: the exception class name if one escaped the " + "application, otherwise the status code as a string for a 5xx response. " + "A 4xx does **not** set this and does not set an error status - per " + "semantic conventions a client error is not a server span's failure.", + optional=True, +) + DB_SYSTEM = Attribute("db.system", "Always ``sqlite``.") DB_NAMESPACE = Attribute("db.namespace", "Name of the database being queried.") DB_QUERY_TEXT = Attribute( @@ -175,6 +235,30 @@ TRANSACTION = Attribute( # --- Spans ---------------------------------------------------------------- +HTTP_REQUEST = SpanName( + "{http.request.method}", + "One span per HTTP request, created by the outermost layer of the ASGI " + "stack - so plugin ``asgi_wrapper()`` middleware, CSRF protection and " + "every database span raised while serving the request all nest inside " + "it. Without it each of those would be its own root trace. The span name " + "is not a fixed string: it is the value of ``http.request.method``. " + "W3C ``traceparent`` and ``baggage`` headers are extracted using the " + "global propagator, so a request arriving from an already-traced caller " + "continues that trace; set ``OTEL_PROPAGATORS=none`` to turn that off, " + "and strip those headers at your proxy if your instance is public.", + ( + HTTP_REQUEST_METHOD, + URL_PATH, + URL_SCHEME, + SERVER_ADDRESS, + USER_AGENT_ORIGINAL, + HTTP_RESPONSE_STATUS_CODE, + ERROR_TYPE, + ), + dynamic=True, + kind=SpanKind.SERVER, +) + DB_QUERY = SpanName( "db.query", "A SQL operation issued by Datasette, covering the full round trip " @@ -240,6 +324,7 @@ STARTUP = SpanName( ) SPANS = ( + HTTP_REQUEST, DB_QUERY, DB_QUERY_EXECUTE, DB_WRITE_QUEUE_WAIT, @@ -248,21 +333,32 @@ SPANS = ( ) -def span_for(emitted_name): +def span_for(emitted_name, kind=None): """ Resolve an emitted span name to its registry entry, or None. - Handles span families whose emitted names carry a suffix that is not - knowable in advance - `prefix=True` entries. Phase 1 has none, but the - lookup is what the conformance test calls, so it lives here rather than - in the test. + Handles the two entry kinds whose emitted names are not knowable in + advance: + + - `prefix=True` - the name carries a variable suffix, matched by prefix. + Phase 1 registers none. + - `dynamic=True` - the name has no fixed part at all, so it is matched on + `kind` instead and the caller has to supply one. Exact and prefix + entries are tried first, so a dynamic entry can never shadow a span + that does have a registered name. """ for span in SPANS: + if span.dynamic: + continue if span.prefix: if emitted_name.startswith(span): return span elif emitted_name == span: return span + if kind is not None: + for span in SPANS: + if span.dynamic and span.kind == kind: + return span return None diff --git a/docs/internals.rst b/docs/internals.rst index 31666e0e..ec50716f 100644 --- a/docs/internals.rst +++ b/docs/internals.rst @@ -2361,17 +2361,34 @@ Setting ``OTEL_METRICS_EXPORTER=none`` and ``OTEL_LOGS_EXPORTER=none`` is worth Span reference -------------- -Datasette emits five spans. Four of them describe the database layer - one per query, one for the work that query does inside a SQL worker thread, and two more for the write queue - and the fifth covers startup. Attribute names use the ``datasette.*`` prefix for Datasette-specific data, alongside standard OpenTelemetry attributes such as ``db.system``. +Datasette emits six spans. One covers the HTTP request, and is the root everything else raised while serving that request hangs from. Four describe the database layer - one per query, one for the work that query does inside a SQL worker thread, and two more for the write queue. The sixth covers startup. Attribute names use the ``datasette.*`` prefix for Datasette-specific data, alongside standard OpenTelemetry attributes such as ``db.system``. This reference is generated from ``datasette/telemetry_registry.py``, the single source of truth for every span and attribute Datasette emits. A conformance test makes real requests and compares what is actually emitted against that registry in both directions, so nothing here is hand-maintained and nothing can silently drift out of date. -Spans are ``SpanKind.INTERNAL`` unless a kind is listed below. Only ``db.query`` is ``CLIENT``: it is the one span that represents a call to a database rather than Datasette's own work, and trace UIs use the kind to decide whether to render a span as a database call. Its children stay ``INTERNAL`` because they are Datasette's decomposition of that one query - marking them ``CLIENT`` too would make a single query look like several database calls to anything counting by kind. +Spans are ``SpanKind.INTERNAL`` unless a kind is listed below. Two are not: the request span is ``SERVER``, and ``db.query`` is ``CLIENT`` because it is the one span that represents a call to a database rather than Datasette's own work. Trace UIs use the kind to decide whether to render a span as an inbound request or as a database call. ``db.query``'s children stay ``INTERNAL`` because they are Datasette's decomposition of that one query - marking them ``CLIENT`` too would make a single query look like several database calls to anything counting by kind. + +The request span's name is the only one that is not a fixed string - it is composed from the request, so the heading below shows the template rather than a literal you will see in a trace. .. [[[cog from telemetry_doc import spans spans(cog) .. ]]] +``{http.request.method}`` + One span per HTTP request, created by the outermost layer of the ASGI stack - so plugin ``asgi_wrapper()`` middleware, CSRF protection and every database span raised while serving the request all nest inside it. Without it each of those would be its own root trace. The span name is not a fixed string: it is the value of ``http.request.method``. W3C ``traceparent`` and ``baggage`` headers are extracted using the global propagator, so a request arriving from an already-traced caller continues that trace; set ``OTEL_PROPAGATORS=none`` to turn that off, and strip those headers at your proxy if your instance is public. + + Kind: ``SERVER``. + + Attributes: + + - ``http.request.method`` - The HTTP method, clamped to the nine methods RFC 9110 and RFC 5789 define. Anything else is reported as ``_OTHER``: the method is a client-controlled string, so echoing it back unbounded would be a cardinality hazard. + - ``url.path`` - The path portion of the URL. The query string is deliberately **not** recorded, on this or any other span: Datasette puts user-supplied SQL in ``?sql=`` and canned query parameters in the query string, so exporting it by default would export exactly the data the rest of this instrumentation is careful with. + - ``url.scheme`` - ``http`` or ``https``. + - ``server.address`` *(optional)* - The ``Host`` header. Client-controlled, so treat it as untrusted input rather than as the identity of the server. + - ``user_agent.original`` *(optional)* - The ``User-Agent`` header, verbatim. Omitted if the client sent none. The client's IP address is deliberately not recorded: core records no identifier that would tie a span to a person. + - ``http.response.status_code`` *(optional)* - The status of the response, read from the ASGI ``http.response.start`` message rather than from a :ref:`internals_response` object - several views, including static files, file downloads and streaming CSV, send that message themselves and never build one. Omitted if the connection closed before anything was sent. + - ``error.type`` *(optional)* - Set when the request failed: the exception class name if one escaped the application, otherwise the status code as a string for a 5xx response. A 4xx does **not** set this and does not set an error status - per semantic conventions a client error is not a server span's failure. + ``db.query`` A SQL operation issued by Datasette, covering the full round trip including any time spent queued for a thread. diff --git a/tests/test_http_span.py b/tests/test_http_span.py new file mode 100644 index 00000000..740d437d --- /dev/null +++ b/tests/test_http_span.py @@ -0,0 +1,344 @@ +""" +The HTTP request span. + +`tests/test_telemetry_registry.py` already pins the span's name shape, kind +and attribute keys against literals, so this file deliberately does not +repeat that. What it covers is the three properties of the middleware that +the registry conformance test structurally cannot see: + +- **where the middleware sits.** Outermost is the entire point - moving it + inside the plugin `asgi_wrapper()` loop leaves plugin middleware creating + orphan root traces, which is the problem this span exists to fix, and every + attribute assertion still passes. +- **method clamping**, which a workload of ordinary GETs can never exercise. +- **the query string never being recorded**, which only fails if a request + actually carries one. +""" + +import asyncio +import itertools + +import pytest +import pytest_asyncio + +pytest.importorskip("opentelemetry.sdk") + +from opentelemetry.trace import SpanKind, StatusCode + +from datasette import hookimpl +from datasette.app import Datasette +from datasette.telemetry import TelemetryMiddleware, tracer + +# Named in-memory databases are shared-cache: two Datasette instances given +# the same name share one SQLite database and the second `create table` +# fails. +_names = itertools.count() + + +PLUGIN_MIDDLEWARE_SPAN = "test.plugin.middleware" + + +class _MiddlewarePlugin: + "A plugin asgi_wrapper() that creates a span, standing in for a real one." + + __name__ = "HttpSpanMiddlewarePlugin" + + @hookimpl + def asgi_wrapper(self, datasette): + def wrap(app): + async def wrapped(scope, receive, send): + with tracer.start_as_current_span(PLUGIN_MIDDLEWARE_SPAN): + await app(scope, receive, send) + + return wrapped + + return wrap + + +class _RaisingMiddlewarePlugin: + """ + A plugin asgi_wrapper() that raises. + + `route_path` converts almost every exception into a 500 itself, so an + exception escaping into the request span is only reachable from *outside* + the router - a plugin wrapper, or a failure inside the 500 handler. + """ + + __name__ = "HttpSpanRaisingMiddlewarePlugin" + + def __init__(self, call_app_first): + self.call_app_first = call_app_first + + @hookimpl + def asgi_wrapper(self, datasette): + call_app_first = self.call_app_first + + def wrap(app): + async def wrapped(scope, receive, send): + if call_app_first: + await app(scope, receive, send) + raise RuntimeError("wrapper exploded") + + return wrapped + + return wrap + + +class _BoomPlugin: + "A route that raises, which route_path turns into a 500." + + __name__ = "HttpSpanBoomPlugin" + + @hookimpl + def register_routes(self): + return [(r"^/-/http-span-boom$", lambda: 1 / 0)] + + +@pytest_asyncio.fixture +async def ds(): + name = f"httpspan{next(_names)}" + instance = Datasette(memory=True) + instance.add_memory_database(name) + await instance.invoke_startup() + await instance.get_database(name).execute_write( + "create table t (id integer primary key, v text)" + ) + instance.db_name = name + try: + yield instance + finally: + instance.close() + + +def _server_spans(otel_spans): + return [ + span for span in otel_spans.get_finished_spans() if span.kind is SpanKind.SERVER + ] + + +@pytest.mark.asyncio +async def test_plugin_asgi_wrapper_middleware_runs_inside_the_request_span( + ds, otel_spans +): + """ + The placement check. + + A span created by a plugin `asgi_wrapper()` must be a *child* of the + request span. If the middleware is mounted anywhere inside the plugin + loop the two swap places - the plugin's span becomes the root and the + request span its child - which is exactly the orphaning this is meant to + prevent, and which no attribute assertion notices. + """ + ds.pm.register(_MiddlewarePlugin(), name="httpspan-middleware") + try: + otel_spans.clear() + response = await ds.client.get(f"/{ds.db_name}/t") + assert response.status_code == 200 + finally: + ds.pm.unregister(name="httpspan-middleware") + + spans = otel_spans.get_finished_spans() + server = [span for span in spans if span.kind is SpanKind.SERVER] + assert len(server) == 1, "expected exactly one SERVER span per request" + request_span = server[0] + assert request_span.parent is None, "the request span should be the trace root" + + plugin_spans = [span for span in spans if span.name == PLUGIN_MIDDLEWARE_SPAN] + assert len(plugin_spans) == 1 + assert plugin_spans[0].parent is not None + assert plugin_spans[0].parent.span_id == request_span.context.span_id + assert plugin_spans[0].context.trace_id == request_span.context.trace_id + + # And the database work is in the same trace, not off on its own. + queries = [span for span in spans if span.name == "db.query"] + assert queries, "a table page should have issued at least one query" + for query in queries: + assert query.context.trace_id == request_span.context.trace_id + + +@pytest.mark.asyncio +async def test_unrecognised_method_is_clamped(ds, otel_spans): + """ + Anyone can send `FROB / HTTP/1.1`. An unclamped method is an unbounded + dimension a client controls, so semantic conventions map anything off the + known list to `_OTHER` - and the span name is the method, so an unclamped + one would put attacker-supplied text in the span name too. + """ + otel_spans.clear() + await ds.client.request("FROB", f"/{ds.db_name}/t") + server = _server_spans(otel_spans) + assert len(server) == 1 + assert server[0].name == "_OTHER" + assert server[0].attributes["http.request.method"] == "_OTHER" + + +@pytest.mark.asyncio +async def test_known_method_is_not_clamped(ds, otel_spans): + "The other half of clamping: a real method must survive it verbatim." + otel_spans.clear() + await ds.client.get(f"/{ds.db_name}/t") + server = _server_spans(otel_spans) + assert len(server) == 1 + assert server[0].name == "GET" + assert server[0].attributes["http.request.method"] == "GET" + + +@pytest.mark.asyncio +async def test_the_query_string_is_never_recorded(ds, otel_spans): + """ + Datasette puts user-supplied SQL in `?sql=` and canned query parameters in + the query string, so no span may carry it. Asserting on the absence of a + `url.query` key alone would not catch it arriving under some other name, + so this searches every attribute value of every span for the marker. + """ + marker = "canary-9f2b1c" + otel_spans.clear() + await ds.client.get(f"/{ds.db_name}/t?_facet=v&_nosuch={marker}") + spans = otel_spans.get_finished_spans() + assert _server_spans(otel_spans), "no request span was emitted" + leaked = [ + f"{span.name} -> {key}={value!r}" + for span in spans + for key, value in (span.attributes or {}).items() + if marker in str(value) or key == "url.query" + ] + assert not leaked, "the query string reached a span attribute: " + ", ".join(leaked) + + +@pytest.mark.asyncio +async def test_url_path_is_recorded_without_the_query_string(ds, otel_spans): + otel_spans.clear() + await ds.client.get(f"/{ds.db_name}/t?_facet=v") + server = _server_spans(otel_spans) + assert len(server) == 1 + assert server[0].attributes["url.path"] == f"/{ds.db_name}/t" + + +@pytest.mark.asyncio +async def test_escaping_exception_sets_error_type_and_reraises(ds, otel_spans): + """ + An exception that gets past `route_path` must be recorded, not swallowed. + + No response ever started, so there is no status code to record either. + """ + ds.pm.register( + _RaisingMiddlewarePlugin(call_app_first=False), name="httpspan-raiser" + ) + try: + otel_spans.clear() + with pytest.raises(RuntimeError): + await ds.client.get(f"/{ds.db_name}/t") + finally: + ds.pm.unregister(name="httpspan-raiser") + server = _server_spans(otel_spans) + assert len(server) == 1 + assert server[0].attributes["error.type"] == "RuntimeError" + assert "http.response.status_code" not in server[0].attributes + assert server[0].status.status_code is StatusCode.ERROR + + +@pytest.mark.asyncio +async def test_an_escaping_exception_beats_the_status_code_for_error_type( + ds, otel_spans +): + """ + Both paths can fire on one request: a 500 response is sent and *then* + something raises on the way out. The `finally` block runs while the + exception is propagating, so without the guard it would overwrite the + exception's class name with the string "500" - strictly less information + about what actually went wrong. + """ + ds.pm.register(_BoomPlugin(), name="httpspan-boom") + ds.pm.register( + _RaisingMiddlewarePlugin(call_app_first=True), name="httpspan-raiser" + ) + try: + otel_spans.clear() + with pytest.raises(RuntimeError): + await ds.client.get("/-/http-span-boom") + finally: + ds.pm.unregister(name="httpspan-raiser") + ds.pm.unregister(name="httpspan-boom") + server = _server_spans(otel_spans) + assert len(server) == 1 + # The 500 really was sent, so the status is still recorded ... + assert server[0].attributes["http.response.status_code"] == 500 + # ... but error.type names the exception, not the status. + assert server[0].attributes["error.type"] == "RuntimeError" + + +@pytest.mark.asyncio +async def test_a_404_is_not_an_error(ds, otel_spans): + """ + Per semantic conventions a 4xx is the client's mistake, not the server's, + so a SERVER span must record the status and leave both its own status and + `error.type` alone. Datasette 404s are routine - every missing table, and + every bot probing for /wp-login.php - so treating them as errors would + drown a real 500 in noise. + """ + otel_spans.clear() + response = await ds.client.get("/no-such-database-at-all") + assert response.status_code == 404 + server = _server_spans(otel_spans) + assert len(server) == 1 + assert server[0].attributes["http.response.status_code"] == 404 + assert "error.type" not in server[0].attributes + assert server[0].status.status_code is StatusCode.UNSET + + +@pytest.mark.asyncio +async def test_only_the_first_http_response_start_is_recorded(otel_spans): + """ + The `send` wrapper keeps the first status it sees. + + Nothing in Datasette sends two `http.response.start` messages, so this + drives the middleware directly rather than pretending a request could + reach it. Without the guard a misbehaving plugin's second start message + would silently replace the status the client actually received. + """ + + async def two_starts(scope, receive, send): + await send({"type": "http.response.start", "status": 200, "headers": []}) + await send({"type": "http.response.start", "status": 503, "headers": []}) + await send({"type": "http.response.body", "body": b""}) + + middleware = TelemetryMiddleware(two_starts) + scope = { + "type": "http", + "method": "GET", + "path": "/twice", + "raw_path": b"/twice", + "scheme": "http", + "headers": [], + } + otel_spans.clear() + await middleware(scope, None, lambda message: asyncio.sleep(0)) + server = _server_spans(otel_spans) + assert len(server) == 1 + assert server[0].attributes["http.response.status_code"] == 200 + assert "error.type" not in server[0].attributes + + +@pytest.mark.asyncio +async def test_lifespan_scope_passes_through_unspanned(otel_spans): + """ + `AsgiLifespan` sits *inside* this middleware, so the scope-type check has + to come first or startup and shutdown events never reach it. A SERVER + span for a lifespan scope is the symptom of that check being missing or + late. + """ + instance = Datasette(memory=True) + app = instance.app() + events = iter([{"type": "lifespan.startup"}, {"type": "lifespan.shutdown"}]) + sent = [] + + async def receive(): + return next(events) + + async def send(message): + sent.append(message["type"]) + + otel_spans.clear() + await app({"type": "lifespan"}, receive, send) + assert sent == ["lifespan.startup.complete", "lifespan.shutdown.complete"] + assert not _server_spans(otel_spans) diff --git a/tests/test_telemetry_registry.py b/tests/test_telemetry_registry.py index 335eb946..96b2a7c5 100644 --- a/tests/test_telemetry_registry.py +++ b/tests/test_telemetry_registry.py @@ -30,6 +30,9 @@ import pytest_asyncio pytest.importorskip("opentelemetry.sdk") +from opentelemetry.trace import SpanKind + +from datasette import hookimpl from datasette import telemetry_registry as reg from datasette.app import Datasette from datasette.database import QueryInterrupted @@ -66,6 +69,31 @@ EXPECTED_ATTRIBUTES = { } EXPECTED_SPANS = set(EXPECTED_ATTRIBUTES) +# The HTTP request span is handled separately because its name is composed at +# runtime - it is the request method - so there is no fixed string to pin it +# to. What can still be pinned, and is what a dashboard depends on, is the +# shape of the name and the attribute keys. The workload below only issues +# GETs, so a change that stopped clamping the method, or that started naming +# the span after the path, fails here. +EXPECTED_HTTP_SPAN_NAME = "{http.request.method}" +EXPECTED_HTTP_SPAN_NAMES = {"GET"} +EXPECTED_HTTP_ATTRIBUTES = { + "http.request.method", + "url.path", + "url.scheme", + "server.address", + "user_agent.original", + "http.response.status_code", + "error.type", +} + +# The registry's own name for the request span is that template, not anything +# that appears on the wire. +EXPECTED_REGISTRY_ATTRIBUTES = dict( + EXPECTED_ATTRIBUTES, **{EXPECTED_HTTP_SPAN_NAME: EXPECTED_HTTP_ATTRIBUTES} +) +EXPECTED_REGISTRY_NAMES = set(EXPECTED_REGISTRY_ATTRIBUTES) + # Named in-memory databases are shared-cache, so two Datasette instances using # the same name share one SQLite database - and the second `create table` # fails. Every workload below therefore gets its own name. @@ -76,6 +104,23 @@ def _unique(prefix): return f"{prefix}{next(_names)}" +class _BoomPlugin: + """ + A route that raises. + + `error.type` on the request span is only ever set by a 5xx, and nothing + in Datasette returns one on a healthy instance - `route_path` converts + exceptions into a 500 itself, so the workload has to supply the + exception. + """ + + __name__ = "TelemetryRegistryBoomPlugin" + + @hookimpl + def register_routes(self): + return [(r"^/-/telemetry-registry-boom$", lambda: 1 / 0)] + + async def exercise(): """ Drive enough of Datasette to emit every span and attribute the registry @@ -128,37 +173,62 @@ async def exercise(): custom_time_limit=1, ) - # db.collection.name - set only by views that already know their table + # db.collection.name - set only by views that already know their table. + # These requests are also what produces the HTTP request span and its + # http.request.method / url.path / url.scheme / server.address / + # user_agent.original / http.response.status_code attributes. assert (await ds.client.get(f"/{name}/t?_facet=v")).status_code == 200 assert (await ds.client.get(f"/{name}/t/1.json")).status_code == 200 + + # error.type on the request span, which only a 5xx sets + ds.pm.register(_BoomPlugin(), name="telemetry-registry-boom") + try: + response = await ds.client.get("/-/telemetry-registry-boom") + assert response.status_code == 500 + finally: + ds.pm.unregister(name="telemetry-registry-boom") return ds @pytest_asyncio.fixture async def emitted(otel_spans): - "Every span name and (span name, attribute key) pair a broad workload emits." + """ + Every (span name, span kind, attribute keys) triple a broad workload emits. + + The kind is carried because the request span's name is composed at + runtime, so `span_for()` resolves it by kind instead. + """ # otel_spans has already cleared the exporter, and nothing is cleared # after this point: the workload's own startup emits datasette.startup. ds = await exercise() spans = otel_spans.get_finished_spans() assert spans, "no spans captured - the fixture is not exercising anything" - names = set() - pairs = set() - for span in spans: - # str() because span.name is the registry's SpanName instance, and a - # set of those would compare equal to literals but read confusingly - # in a failure message. - names.add(str(span.name)) - for key in span.attributes or {}: - pairs.add((str(span.name), str(key))) + # str() because span.name is the registry's SpanName instance, and a set + # of those would compare equal to literals but read confusingly in a + # failure message. + collected = tuple( + ( + str(span.name), + span.kind, + frozenset(str(key) for key in span.attributes or {}), + ) + for span in spans + ) ds.close() - return {"names": names, "pairs": pairs} + return collected -def _keys_by_span(pairs): +def _partition(emitted): + "The statically named spans, and the dynamically named request spans." + static = [record for record in emitted if record[1] is not SpanKind.SERVER] + server = [record for record in emitted if record[1] is SpanKind.SERVER] + return static, server + + +def _keys_by_span(records): by_span = {} - for span_name, key in pairs: - by_span.setdefault(span_name, set()).add(key) + for name, _kind, keys in records: + by_span.setdefault(name, set()).update(keys) return by_span @@ -170,27 +240,34 @@ async def test_workload_emits_exactly_the_expected_names(emitted): Not derived from the registry, so this is what catches a rename that the registry and the call sites make together. """ - assert emitted["names"] == EXPECTED_SPANS - by_span = _keys_by_span(emitted["pairs"]) - assert {name: by_span.get(name, set()) for name in emitted["names"]} == ( - EXPECTED_ATTRIBUTES - ) + static, server = _partition(emitted) + by_span = _keys_by_span(static) + assert set(by_span) == EXPECTED_SPANS + assert by_span == EXPECTED_ATTRIBUTES + + assert server, "the workload made HTTP requests but no SERVER span was emitted" + server_keys = _keys_by_span(server) + assert set(server_keys) == EXPECTED_HTTP_SPAN_NAMES + union = set() + for keys in server_keys.values(): + union |= keys + assert union == EXPECTED_HTTP_ATTRIBUTES def test_registry_matches_the_expected_names(): "The other half of the rename check: the registry against the same literals." - assert {str(span) for span in reg.SPANS} == EXPECTED_SPANS + assert {str(span) for span in reg.SPANS} == EXPECTED_REGISTRY_NAMES for span in reg.SPANS: - assert {str(attribute) for attribute in span.attributes} == EXPECTED_ATTRIBUTES[ - str(span) - ], f"{span} attributes have drifted" + assert { + str(attribute) for attribute in span.attributes + } == EXPECTED_REGISTRY_ATTRIBUTES[str(span)], f"{span} attributes have drifted" @pytest.mark.asyncio async def test_every_emitted_span_is_registered(emitted): "A span added without a registry entry would be missing from the docs." unregistered = sorted( - name for name in emitted["names"] if reg.span_for(name) is None + {name for name, kind, _ in emitted if reg.span_for(name, kind) is None} ) assert ( not unregistered @@ -201,9 +278,12 @@ async def test_every_emitted_span_is_registered(emitted): async def test_every_emitted_attribute_is_registered(emitted): "An attribute added without a registry entry would be missing from the docs." unregistered = sorted( - f"{span_name} -> {key}" - for span_name, key in emitted["pairs"] - if not reg.attribute_allowed(reg.span_for(span_name), key) + { + f"{name} -> {key}" + for name, kind, keys in emitted + for key in keys + if not reg.attribute_allowed(reg.span_for(name, kind), key) + } ) assert ( not unregistered @@ -218,11 +298,10 @@ async def test_every_registered_span_is_emitted(emitted): The direction nothing else catches: the docs must not describe a span that no longer exists. """ - missing = sorted( - str(span) - for span in reg.SPANS - if not any(reg.span_for(name) is span for name in emitted["names"]) - ) + # By identity, not by name: a dynamic entry's own string never appears on + # the wire, so comparing strings would be comparing the wrong things. + resolved = {id(reg.span_for(name, kind)) for name, kind, _ in emitted} + missing = sorted(str(span) for span in reg.SPANS if id(span) not in resolved) assert not missing, ( f"these spans are documented but never emitted by the workload: {missing}. " "Either the instrumentation was removed, or exercise() no longer reaches it." @@ -241,10 +320,14 @@ async def test_every_registered_attribute_is_emitted(emitted): new attribute only appears in some rare case, extend exercise() to reach that case. """ - by_span = _keys_by_span(emitted["pairs"]) + by_entry = {} + for name, kind, keys in emitted: + entry = reg.span_for(name, kind) + if entry is not None: + by_entry.setdefault(id(entry), set()).update(keys) missing = [] for span in reg.SPANS: - emitted_keys = by_span.get(str(span), set()) + emitted_keys = by_entry.get(id(span), set()) for attribute in span.attributes: if attribute not in emitted_keys: missing.append(f"{span} -> {attribute}") @@ -279,6 +362,25 @@ def test_registry_entries_are_usable_as_plain_strings(): assert f"{reg.DB_QUERY}.execute" == "db.query.execute" +def test_dynamic_span_lookup(): + """ + `dynamic=True` matching, which is how the request span resolves. + + The last two assertions are the ones worth having: a dynamic entry must + not swallow a span that does have a registered name, and must not match at + all when the caller supplies no kind - otherwise every unregistered span + in the suite would silently resolve to the request span and the + emitted-but-not-registered direction would stop catching anything. + """ + assert reg.span_for("GET", SpanKind.SERVER) is reg.HTTP_REQUEST + assert reg.span_for("POST /^/(?P[^/]+)$", SpanKind.SERVER) is ( + reg.HTTP_REQUEST + ) + assert reg.span_for("GET") is None + assert reg.span_for("anything at all", SpanKind.INTERNAL) is None + assert reg.span_for("db.query", SpanKind.SERVER) is reg.DB_QUERY + + def test_span_and_attribute_lookup(): assert reg.span_for("db.query") is reg.DB_QUERY assert reg.span_for("datasette.startup") is reg.STARTUP From 74cd01860f4a0e29ed339889c2ac229831a9eeaa Mon Sep 17 00:00:00 2001 From: Alex Garcia Date: Thu, 30 Jul 2026 19:52:12 -0700 Subject: [PATCH 12/13] Name the request span after the route it matched The request span was created at the ASGI edge, before anything knew which route would match, so it carried nothing but the method: every request in a trace UI showed up as "GET", and the only URL on it was url.path, which is unbounded on a public instance and useless as a grouping key. Routing resolves in DatasetteRouter, so that is where the span gets http.route and its semconv `{method} {route}` name. http.route is the compiled route pattern, not a prettified /{database}/{table} template. Datasette routes with compiled regexes and the route table is fixed when the app is built, so the pattern is exact, bounded and needs no parsing; the transform into something prettier accretes edge cases, and Django's instrumentation ships regex-flavoured routes for the same reason. A request that matches no route gets no http.route and keeps its bare method name, which is what semantic conventions ask for. Two things the obvious implementation gets wrong, both found by testing it: - The router must not read `get_current_span()`. A plugin asgi_wrapper() runs *inside* the request middleware, so an instrumented plugin makes its own span current for the whole request - and the route then lands on that plugin's INTERNAL span, renaming it, while the actual request span never gets the one attribute a trace UI groups by. It reproduces with a five-line plugin. The span is passed through the ASGI scope instead, falling back to the current span so an externally-created SERVER span is still enriched. - The method has to be clamped again here. The middleware clamps it for the attribute, but the name is rebuilt from request.method, which is the raw client string - so an unclamped rename put `FROB /(?P...` back into the span name that the middleware had just kept it out of. Both guards are `is_recording()`, not `get_span_context().is_valid`: with no provider but an inbound traceparent the API returns a NonRecordingSpan carrying the remote context, which is valid and records nothing, so an is_valid guard would do the work on every request from a traced caller. Tests cover the route and name, the unrouted 404 fallback, the full attribute set, db.query spans reaching the request span by parent walk, a 500, an inbound traceparent becoming a remote parent, ?sql= never reaching a span attribute, and - in a subprocess, because the suite's provider fixture is session-scoped and unavoidable - the no-provider fast path handing the app the original `send`. The streaming test uses a table larger than one page so the export genuinely issues queries during the body send; without that it passes however early the span ends. Measured on this branch against fixtures.db: a faceted table page went from 112 spans in 56 traces to 113 spans in 1. Co-Authored-By: Claude Opus 5 --- datasette/app.py | 27 +- datasette/telemetry.py | 36 +++ datasette/telemetry_registry.py | 31 +- docs/internals.rst | 38 ++- tests/conftest.py | 1 + tests/test_http_span.py | 537 ++++++++++++++++++++++++++++++- tests/test_telemetry_registry.py | 52 ++- 7 files changed, 681 insertions(+), 41 deletions(-) diff --git a/datasette/app.py b/datasette/app.py index 939c8cf8..37c4e882 100644 --- a/datasette/app.py +++ b/datasette/app.py @@ -49,8 +49,13 @@ from .events import Event from .plugins import DEFAULT_PLUGINS, get_plugins, pm from .renderer import json_renderer from .resources import DatabaseResource, TableResource -from .telemetry import TelemetryMiddleware, tracer -from .telemetry_registry import STARTUP +from .telemetry import ( + TelemetryMiddleware, + clamp_http_method, + request_span, + tracer, +) +from .telemetry_registry import HTTP_ROUTE, STARTUP from .tokens import TokenInvalid from .tracer import AsgiTracer from .url_builder import Urls @@ -2958,8 +2963,26 @@ class DatasetteRouter: match, view = resolve_routes(self.routes, path) if match is None: + # No route matched, so the span keeps the bare method name it was + # given at the edge and gets no http.route. That is what semantic + # conventions ask for when the route is unknown. return await self.handle_404(request, send) + # The request span was started at the ASGI edge, before routing, so it + # carries only the method as a name. Now that the route is known, give + # it the `{method} {route}` shape semantic conventions want, and the + # http.route attribute - the low-cardinality counterpart to url.path, + # and so the one to group by. + span = request_span(scope) + if span is not None: + route = match.re.pattern + span.set_attribute(HTTP_ROUTE, route) + # Clamped, for the same reason the middleware clamps it: the method + # is a client-controlled string, and an unclamped one here would + # put attacker-supplied text back into the span name that the + # middleware just kept out of it. + span.update_name(f"{clamp_http_method(request.method)} {route}") + new_scope = dict(scope, url_route={"kwargs": match.groupdict()}) request.scope = new_scope try: diff --git a/datasette/telemetry.py b/datasette/telemetry.py index 31541a47..311d661f 100644 --- a/datasette/telemetry.py +++ b/datasette/telemetry.py @@ -201,6 +201,38 @@ def _url_path(scope): return scope.get("path", "") +# The request span is handed to `DatasetteRouter.route_path` through the ASGI +# scope rather than through `get_current_span()`, because by the time routing +# happens the current span may well be something else: a plugin +# `asgi_wrapper()` runs *inside* this middleware, and an instrumented one makes +# its own span current for the whole request. Reading the current span there +# would set `http.route` on that plugin's span - and rename it - while leaving +# the actual request span without the one attribute a trace UI groups by. Not +# hypothetical: an ordinary tracing plugin triggers it. +# +# Namespaced per the ASGI spec's rules for extension keys. Absent when the span +# is not recording, which is exactly when the router should skip the work too. +REQUEST_SPAN_SCOPE_KEY = "datasette.telemetry.request_span" + + +def request_span(scope): + """ + The recording request span for an ASGI scope, or None. + + Falls back to the current span so that a `DatasetteRouter` running under + some other instrumentation - one that started a SERVER span but of course + knows nothing about this scope key - still gets enriched. + """ + span = scope.get(REQUEST_SPAN_SCOPE_KEY) + if span is None: + span = otel_trace.get_current_span() + # is_recording(), not `get_span_context().is_valid`: with no provider but + # an inbound `traceparent`, the API's NoOpTracer hands back a + # NonRecordingSpan carrying the *remote* context, which is perfectly valid + # and still records nothing. + return span if span.is_recording() else None + + class TelemetryMiddleware: """ One `SpanKind.SERVER` span per HTTP request. @@ -265,6 +297,10 @@ class TelemetryMiddleware: if user_agent: span.set_attribute(USER_AGENT_ORIGINAL, user_agent) + # A copy, not a mutation: the scope belongs to the server, and + # every other layer in Datasette extends it the same way. + scope = dict(scope, **{REQUEST_SPAN_SCOPE_KEY: span}) + # The status cannot be read off a Response object: `asgi_static`, # the favicon route, `AsgiStream` and `AsgiFileDownload` all call # `send` directly and never build one. Wrapping `send` is the only diff --git a/datasette/telemetry_registry.py b/datasette/telemetry_registry.py index ddecbc5b..4e750605 100644 --- a/datasette/telemetry_registry.py +++ b/datasette/telemetry_registry.py @@ -67,10 +67,11 @@ class SpanName(str): self.prefix = prefix # True when the emitted name is composed at runtime and shares no # fixed prefix with the registry entry - the HTTP request span, whose - # name is the request method. There is no substring of the entry that - # could be matched against the wire, so `span_for()` resolves these by - # span kind instead, and the entry's own string is a template written - # for a human reading the generated reference. + # name is the request method followed by the matched route. There is + # no substring of the entry that could be matched against the wire, so + # `span_for()` resolves these by span kind instead, and the entry's own + # string is a template written for a human reading the generated + # reference. self.dynamic = dynamic # SpanKind.INTERNAL by default - every span Datasette emits describes # its own internal work. db.query is the one exception: it is a real @@ -104,6 +105,20 @@ HTTP_RESPONSE_STATUS_CODE = Attribute( "closed before anything was sent.", optional=True, ) +HTTP_ROUTE = Attribute( + "http.route", + "The route the request matched, as the compiled regular expression " + "pattern Datasette routes with - for example " + "``/(?P[^\\/\\.]+)/(?P[^\\/\\.]+)(\\.(?P\\w+))?$`` " + "for a table page. It is deliberately the pattern rather than a prettified " + "``/{database}/{table}`` template: the route table is fixed when the app " + "is built, so the pattern is exact, bounded and needs no parsing, whereas " + "the transform into something prettier accretes edge cases. Unlike " + "``url.path`` this is low cardinality, so it is the attribute to group by. " + "Omitted when no route matched - a 404 - which is also when the span name " + "falls back to the bare method.", + optional=True, +) URL_PATH = Attribute( "url.path", "The path portion of the URL. The query string is deliberately **not** " @@ -236,18 +251,22 @@ TRANSACTION = Attribute( # --- Spans ---------------------------------------------------------------- HTTP_REQUEST = SpanName( - "{http.request.method}", + "{http.request.method} {http.route}", "One span per HTTP request, created by the outermost layer of the ASGI " "stack - so plugin ``asgi_wrapper()`` middleware, CSRF protection and " "every database span raised while serving the request all nest inside " "it. Without it each of those would be its own root trace. The span name " - "is not a fixed string: it is the value of ``http.request.method``. " + "is not a fixed string: it is the method followed by the matched route, " + "and just the method for a request that matched no route. The span starts " + "at the ASGI edge, before routing has happened, so it is named for the " + "method there and renamed once the route is known. " "W3C ``traceparent`` and ``baggage`` headers are extracted using the " "global propagator, so a request arriving from an already-traced caller " "continues that trace; set ``OTEL_PROPAGATORS=none`` to turn that off, " "and strip those headers at your proxy if your instance is public.", ( HTTP_REQUEST_METHOD, + HTTP_ROUTE, URL_PATH, URL_SCHEME, SERVER_ADDRESS, diff --git a/docs/internals.rst b/docs/internals.rst index ec50716f..da99e557 100644 --- a/docs/internals.rst +++ b/docs/internals.rst @@ -2367,21 +2367,26 @@ This reference is generated from ``datasette/telemetry_registry.py``, the single Spans are ``SpanKind.INTERNAL`` unless a kind is listed below. Two are not: the request span is ``SERVER``, and ``db.query`` is ``CLIENT`` because it is the one span that represents a call to a database rather than Datasette's own work. Trace UIs use the kind to decide whether to render a span as an inbound request or as a database call. ``db.query``'s children stay ``INTERNAL`` because they are Datasette's decomposition of that one query - marking them ``CLIENT`` too would make a single query look like several database calls to anything counting by kind. -The request span's name is the only one that is not a fixed string - it is composed from the request, so the heading below shows the template rather than a literal you will see in a trace. +The request span's name is the only one that is not a fixed string - it is composed from the request, so the heading below shows the template rather than a literal you will see in a trace. A request to a table page produces a span named, in full:: + + GET /(?P[^\/\.]+)/(?P
[^\/\.]+)(\.(?P\w+))?$ + +That is the route's compiled regular expression, not a prettified ``/{database}/{table}`` template. It is deliberate: Datasette routes with compiled patterns and the route table is fixed when the app is built, so the pattern is exact, bounded and needs no parsing, while transforming it into something prettier accretes edge cases. Django's own instrumentation ships regex-flavoured routes for the same reason. .. [[[cog from telemetry_doc import spans spans(cog) .. ]]] -``{http.request.method}`` - One span per HTTP request, created by the outermost layer of the ASGI stack - so plugin ``asgi_wrapper()`` middleware, CSRF protection and every database span raised while serving the request all nest inside it. Without it each of those would be its own root trace. The span name is not a fixed string: it is the value of ``http.request.method``. W3C ``traceparent`` and ``baggage`` headers are extracted using the global propagator, so a request arriving from an already-traced caller continues that trace; set ``OTEL_PROPAGATORS=none`` to turn that off, and strip those headers at your proxy if your instance is public. +``{http.request.method} {http.route}`` + One span per HTTP request, created by the outermost layer of the ASGI stack - so plugin ``asgi_wrapper()`` middleware, CSRF protection and every database span raised while serving the request all nest inside it. Without it each of those would be its own root trace. The span name is not a fixed string: it is the method followed by the matched route, and just the method for a request that matched no route. The span starts at the ASGI edge, before routing has happened, so it is named for the method there and renamed once the route is known. W3C ``traceparent`` and ``baggage`` headers are extracted using the global propagator, so a request arriving from an already-traced caller continues that trace; set ``OTEL_PROPAGATORS=none`` to turn that off, and strip those headers at your proxy if your instance is public. Kind: ``SERVER``. Attributes: - ``http.request.method`` - The HTTP method, clamped to the nine methods RFC 9110 and RFC 5789 define. Anything else is reported as ``_OTHER``: the method is a client-controlled string, so echoing it back unbounded would be a cardinality hazard. + - ``http.route`` *(optional)* - The route the request matched, as the compiled regular expression pattern Datasette routes with - for example ``/(?P[^\/\.]+)/(?P
[^\/\.]+)(\.(?P\w+))?$`` for a table page. It is deliberately the pattern rather than a prettified ``/{database}/{table}`` template: the route table is fixed when the app is built, so the pattern is exact, bounded and needs no parsing, whereas the transform into something prettier accretes edge cases. Unlike ``url.path`` this is low cardinality, so it is the attribute to group by. Omitted when no route matched - a 404 - which is also when the span name falls back to the bare method. - ``url.path`` - The path portion of the URL. The query string is deliberately **not** recorded, on this or any other span: Datasette puts user-supplied SQL in ``?sql=`` and canned query parameters in the query string, so exporting it by default would export exactly the data the rest of this instrumentation is careful with. - ``url.scheme`` - ``http`` or ``https``. - ``server.address`` *(optional)* - The ``Host`` header. Client-controlled, so treat it as untrusted input rather than as the identity of the server. @@ -2436,6 +2441,29 @@ The request span's name is the only one that is not a fixed string - it is compo .. [[[end]]] +.. _internals_telemetry_requests: + +Requests and inbound trace context +---------------------------------- + +Datasette creates the request span itself, at the outermost layer of the ASGI stack, so a trace is complete out of the box with no plugin and no extra instrumentation package. Everything raised while serving the request - plugin ``asgi_wrapper()`` middleware, CSRF protection, every database query - nests inside it. + +**Inbound trace context is trusted by default.** W3C ``traceparent`` and ``baggage`` headers are extracted from every request using the global propagator, so a request arriving from an already-traced caller continues that trace instead of starting a new one. That is what every other framework instrumentation does - Flask, Django, FastAPI and ``opentelemetry-instrumentation-asgi`` all extract unconditionally - but on an instance open to the internet it means an arbitrary client can influence your traces: + +- **Trace-ID pollution.** The client chooses the trace ID its request is filed under. +- **Sampling control.** The SDK's default sampler is ``parentbased_always_on``, so under any parent-based sampler a client's sampled flag can force recording - a telemetry-cost denial of service - or suppress it. +- **Baggage injection**, through the default composite propagator. + +Because extraction goes through the *global* propagator there is no Datasette setting to configure, and the remedies are the standard OpenTelemetry ones: + +- Strip ``traceparent``, ``tracestate`` and ``baggage`` at your reverse proxy, which is the right answer for a public instance fronted by one. +- Set ``OTEL_PROPAGATORS=none`` to disable extraction entirely, or ``OTEL_PROPAGATORS=tracecontext`` to keep trace continuation and drop baggage. +- Use a sampler that is not parent-based, which neutralises the sampling concern on its own. + +**Installing an ASGI instrumentation as well is harmless.** If you wire up ``opentelemetry-instrumentation-asgi`` through an ``asgi_wrapper()`` plugin, its middleware lands *inside* Datasette's own, so its span becomes a redundant child ``SERVER`` span in the same trace. Nothing is re-orphaned. There is no setting to turn Datasette's request span off, because "turn it off" is already covered by installing no provider, or by ``OTEL_SDK_DISABLED=true``. + +**Where** ``datasette.startup`` **lands depends on how you run Datasette.** ``datasette serve`` calls ``invoke_startup()`` before the server starts accepting connections, so the startup span is its own trace. An ASGI-hosted or programmatic deployment reaches startup lazily, on the first request, so there the startup span nests under that first request - which is honest, since it genuinely is that request's latency. + .. _internals_telemetry_privacy: Privacy and safety @@ -2447,6 +2475,7 @@ Spans leave your infrastructure whenever you configure an exporter, so what goes - **SQL parameter values are never recorded.** Only ``datasette.param_count``, a count. Parameter values are the part of a query most likely to hold something sensitive, and separating them from the SQL is the reason bound parameters exist. - **No actor identifiers are recorded.** No actor ID, no actor JSON, no client IP address. Nothing on a span identifies who made the request. - **Table names come only from an explicit** ``table=`` **argument.** ``db.collection.name`` is set by callers that already know which table they are working with, and is never derived from the SQL. Deriving it would mean parsing, and on an instance where visitors can create tables the set of possible values has no ceiling. +- **The query string is never recorded.** There is no ``url.query`` attribute on the request span or on any other span. Datasette puts user-supplied SQL in ``?sql=`` and canned query parameters in the query string, so recording it by default would export exactly the class of data the rules above are careful with. Only ``url.path`` and ``http.route`` are recorded. The SQL itself, though, *is* recorded, and on a public instance that means anything a visitor types into the query editor or passes as ``?sql=`` will be exported along with the span. That is the trade-off tracing a query engine makes. @@ -2455,7 +2484,8 @@ The SQL itself, though, *is* recorded, and on a public instance that means anyth Known limitations ----------------- -- **Datasette does not create a span for the HTTP request itself.** Every span listed above is therefore a root span unless something above Datasette - an ASGI instrumentation layer, or the web framework embedding it - has already started one for the request, in which case Datasette's spans nest underneath it correctly. +- ``http.route`` **is a compiled regular expression, not a pretty route template.** See :ref:`internals_telemetry_requests` above for why. +- **Inbound trace context is trusted by default**, which on a public instance means a client can influence your trace IDs, your sampling and your baggage. :ref:`internals_telemetry_requests` lists the remedies. - **Two plugin hooks run outside the** ``datasette.startup`` **span.** ``register_output_renderer`` is dispatched from ``Datasette.__init__()`` and ``asgi_wrapper`` from ``Datasette.app()``, both of which happen before ``invoke_startup()``. Datasette itself queries no database in either, so a default install emits nothing there - but a plugin that does will produce a root trace. Covering these would mean holding a span open across object construction, which is worse than the orphan. - ``db.operation.name`` **reports** ``WITH`` **for a statement that opens with a common table expression**, rather than the operation inside it, and a substantial share of Datasette's own reads take that form. The attribute is a leading-keyword match against a fixed allowlist, deliberately not a parse. - **Spans emitted before a provider is installed are not recorded.** If you are embedding Datasette in a host application, install your ``TracerProvider`` before serving traffic. This is ordinary OpenTelemetry behaviour rather than anything Datasette controls; nothing is permanently affected, those particular spans are simply dropped. diff --git a/tests/conftest.py b/tests/conftest.py index b01f111d..b2453133 100644 --- a/tests/conftest.py +++ b/tests/conftest.py @@ -230,6 +230,7 @@ def pytest_collection_modifyitems(config, items): # (SIGSEGV/SIGBUS inside _execute_child). Reproduces with any subprocess # call placed there, on an unmodified tree - running it first avoids it. move_to_front(items, "test_datasette_package_never_imports_the_sdk") + move_to_front(items, "test_no_provider_takes_the_fast_path") def move_to_front(items, test_name): diff --git a/tests/test_http_span.py b/tests/test_http_span.py index 740d437d..ff792489 100644 --- a/tests/test_http_span.py +++ b/tests/test_http_span.py @@ -3,31 +3,53 @@ The HTTP request span. `tests/test_telemetry_registry.py` already pins the span's name shape, kind and attribute keys against literals, so this file deliberately does not -repeat that. What it covers is the three properties of the middleware that -the registry conformance test structurally cannot see: +repeat that. What it covers is the properties of the middleware and of the +router's `http.route` enrichment that the registry conformance test +structurally cannot see: - **where the middleware sits.** Outermost is the entire point - moving it inside the plugin `asgi_wrapper()` loop leaves plugin middleware creating orphan root traces, which is the problem this span exists to fix, and every attribute assertion still passes. +- **which span the route lands on**, which only diverges once something else + has made a span current. - **method clamping**, which a workload of ordinary GETs can never exercise. - **the query string never being recorded**, which only fails if a request actually carries one. +- **the span outliving a streamed response body**, which only a paging export + can distinguish from ending far too early. """ import asyncio import itertools +import json +import subprocess +import sys +import textwrap +import time import pytest import pytest_asyncio pytest.importorskip("opentelemetry.sdk") -from opentelemetry.trace import SpanKind, StatusCode +from opentelemetry.trace import ( + NonRecordingSpan, + SpanContext, + SpanKind, + StatusCode, + TraceFlags, +) from datasette import hookimpl from datasette.app import Datasette -from datasette.telemetry import TelemetryMiddleware, tracer +from datasette.telemetry import ( + REQUEST_SPAN_SCOPE_KEY, + TelemetryMiddleware, + request_span, + tracer, +) +from datasette.utils import resolve_routes # Named in-memory databases are shared-cache: two Datasette instances given # the same name share one SQLite database and the second `create table` @@ -110,12 +132,51 @@ async def ds(): instance.close() +@pytest_asyncio.fixture +async def ds_paging(): + """ + An instance whose table is bigger than `max_returned_rows`. + + That is what makes `?_stream=1` genuinely page: `stream_csv` loops calling + `fetch_data` for each page *inside* the response body send, so the trace + contains `db.query` spans that start after the response has begun. On a + table that fits in one page every query finishes before the body starts + and the span-covers-the-body assertion cannot fail. + """ + name = f"httpspanpaging{next(_names)}" + # Both settings matter. `?_stream=1` forces `_size=max`, which is + # `max_returned_rows` - so lowering only that gives one page of five rows + # and no `next` token, and the export never loops. + instance = Datasette( + memory=True, settings={"max_returned_rows": 5, "default_page_size": 3} + ) + instance.add_memory_database(name) + await instance.invoke_startup() + db = instance.get_database(name) + await db.execute_write("create table t (id integer primary key, v text)") + await db.execute_write_many( + "insert into t (id, v) values (?, ?)", [[i, f"v{i}"] for i in range(40)] + ) + instance.db_name = name + try: + yield instance + finally: + instance.close() + + def _server_spans(otel_spans): return [ span for span in otel_spans.get_finished_spans() if span.kind is SpanKind.SERVER ] +def _route_for(ds, path): + "The compiled pattern Datasette's own router resolves `path` to." + match, _view = resolve_routes(ds._routes(), path) + assert match is not None, f"{path} matches no route" + return match.re.pattern + + @pytest.mark.asyncio async def test_plugin_asgi_wrapper_middleware_runs_inside_the_request_span( ds, otel_spans @@ -140,20 +201,20 @@ async def test_plugin_asgi_wrapper_middleware_runs_inside_the_request_span( spans = otel_spans.get_finished_spans() server = [span for span in spans if span.kind is SpanKind.SERVER] assert len(server) == 1, "expected exactly one SERVER span per request" - request_span = server[0] - assert request_span.parent is None, "the request span should be the trace root" + server_span = server[0] + assert server_span.parent is None, "the request span should be the trace root" plugin_spans = [span for span in spans if span.name == PLUGIN_MIDDLEWARE_SPAN] assert len(plugin_spans) == 1 assert plugin_spans[0].parent is not None - assert plugin_spans[0].parent.span_id == request_span.context.span_id - assert plugin_spans[0].context.trace_id == request_span.context.trace_id + assert plugin_spans[0].parent.span_id == server_span.context.span_id + assert plugin_spans[0].context.trace_id == server_span.context.trace_id # And the database work is in the same trace, not off on its own. queries = [span for span in spans if span.name == "db.query"] assert queries, "a table page should have issued at least one query" for query in queries: - assert query.context.trace_id == request_span.context.trace_id + assert query.context.trace_id == server_span.context.trace_id @pytest.mark.asyncio @@ -161,15 +222,20 @@ async def test_unrecognised_method_is_clamped(ds, otel_spans): """ Anyone can send `FROB / HTTP/1.1`. An unclamped method is an unbounded dimension a client controls, so semantic conventions map anything off the - known list to `_OTHER` - and the span name is the method, so an unclamped - one would put attacker-supplied text in the span name too. + known list to `_OTHER`. + + The span name is checked too, and it is the reason the router clamps the + method a second time when it renames the span: the middleware's clamping + protects the attribute, but the name is rebuilt from `request.method` in + `route_path`, which is the raw client string. An unclamped rename would + put attacker-supplied text straight back into the span name. """ otel_spans.clear() await ds.client.request("FROB", f"/{ds.db_name}/t") server = _server_spans(otel_spans) assert len(server) == 1 - assert server[0].name == "_OTHER" assert server[0].attributes["http.request.method"] == "_OTHER" + assert server[0].name == f"_OTHER {server[0].attributes['http.route']}" @pytest.mark.asyncio @@ -179,8 +245,8 @@ async def test_known_method_is_not_clamped(ds, otel_spans): await ds.client.get(f"/{ds.db_name}/t") server = _server_spans(otel_spans) assert len(server) == 1 - assert server[0].name == "GET" assert server[0].attributes["http.request.method"] == "GET" + assert server[0].name == f"GET {server[0].attributes['http.route']}" @pytest.mark.asyncio @@ -275,6 +341,10 @@ async def test_a_404_is_not_an_error(ds, otel_spans): `error.type` alone. Datasette 404s are routine - every missing table, and every bot probing for /wp-login.php - so treating them as errors would drown a real 500 in noise. + + Note this 404 *does* match a route: `/no-such-database-at-all` matches the + database pattern and the view then raises `NotFound`. Most Datasette 404s + are that shape rather than the unrouted one below. """ otel_spans.clear() response = await ds.client.get("/no-such-database-at-all") @@ -286,6 +356,29 @@ async def test_a_404_is_not_an_error(ds, otel_spans): assert server[0].status.status_code is StatusCode.UNSET +@pytest.mark.asyncio +async def test_an_unrouted_404_has_no_route_and_a_bare_method_name(ds, otel_spans): + """ + When no route matches there is nothing to set `http.route` to, so the span + keeps the bare method name it was given at the edge - which is exactly the + fallback semantic conventions specify for an unknown route. + + `/a/b/c/d/e` is used rather than a plausible-looking missing name because + Datasette's route table is greedy: `/no-such-database-at-all` matches the + database pattern, and `/-/nope/deeper` matches the row pattern. Only a + path deeper than any route matches nothing at all. + """ + otel_spans.clear() + response = await ds.client.get("/a/b/c/d/e") + assert response.status_code == 404 + server = _server_spans(otel_spans) + assert len(server) == 1 + assert server[0].name == "GET" + assert "http.route" not in server[0].attributes + assert server[0].attributes["http.response.status_code"] == 404 + assert server[0].status.status_code is StatusCode.UNSET + + @pytest.mark.asyncio async def test_only_the_first_http_response_start_is_recorded(otel_spans): """ @@ -342,3 +435,421 @@ async def test_lifespan_scope_passes_through_unspanned(otel_spans): await app({"type": "lifespan"}, receive, send) assert sent == ["lifespan.startup.complete", "lifespan.shutdown.complete"] assert not _server_spans(otel_spans) + + +@pytest.mark.asyncio +async def test_http_route_is_the_compiled_pattern(ds, otel_spans): + """ + `http.route` is the route's compiled regex, not a prettified template. + + Asserted against what Datasette's own router resolves rather than against + a copied literal, so this pins the *relationship* - the attribute is the + matched route - and does not break when a core pattern is edited. + """ + path = f"/{ds.db_name}/t" + expected = _route_for(ds, path) + otel_spans.clear() + assert (await ds.client.get(path)).status_code == 200 + server = _server_spans(otel_spans) + assert len(server) == 1 + assert server[0].attributes["http.route"] == expected + assert server[0].name == f"GET {expected}" + # The pattern really is the ugly one, and that is deliberate - if someone + # adds a prettifier this is the assertion that should make them argue for + # it rather than slip it in. + assert "(?P" in expected + + +@pytest.mark.asyncio +async def test_the_route_lands_on_the_request_span_not_a_plugins_current_span( + ds, otel_spans +): + """ + The route is set on the span the middleware started, found through the + ASGI scope - not on whatever span happens to be current when routing + resolves. + + Those are the same span only until a plugin `asgi_wrapper()` starts one of + its own. A plugin wrapper runs *inside* this middleware, so an instrumented + plugin makes its span current for the whole request: reading the current + span in `route_path` renames that plugin's INTERNAL span to + `GET ` and hangs `http.route` off it, while the actual request span + keeps a bare method name and never gets the one attribute a trace UI + groups requests by. Verified by reproducing it, not by reasoning about it. + """ + ds.pm.register(_MiddlewarePlugin(), name="httpspan-middleware") + try: + otel_spans.clear() + path = f"/{ds.db_name}/t" + expected = _route_for(ds, path) + assert (await ds.client.get(path)).status_code == 200 + finally: + ds.pm.unregister(name="httpspan-middleware") + + spans = otel_spans.get_finished_spans() + server = _server_spans(otel_spans) + assert len(server) == 1 + assert server[0].attributes["http.route"] == expected + assert server[0].name == f"GET {expected}" + # And the plugin's span is untouched: same name, no route attribute. + plugin_spans = [span for span in spans if span.name == PLUGIN_MIDDLEWARE_SPAN] + assert len(plugin_spans) == 1 + assert "http.route" not in (plugin_spans[0].attributes or {}) + + +@pytest.mark.asyncio +async def test_request_span_attributes(ds, otel_spans): + "The whole attribute set on one ordinary request." + path = f"/{ds.db_name}/t" + otel_spans.clear() + assert (await ds.client.get(path)).status_code == 200 + server = _server_spans(otel_spans) + assert len(server) == 1 + attributes = server[0].attributes + assert attributes["http.request.method"] == "GET" + assert attributes["url.path"] == path + assert attributes["url.scheme"] == "http" + assert attributes["http.response.status_code"] == 200 + assert attributes["http.route"] == _route_for(ds, path) + assert server[0].status.status_code is StatusCode.UNSET + # Never, on any span: an IP is borderline PII and the query string carries + # user-supplied SQL. + assert "client.address" not in attributes + assert "url.query" not in attributes + + +@pytest.mark.asyncio +async def test_db_query_spans_are_children_of_the_request_span(ds, otel_spans): + """ + The point of the whole PR. + + Not just "same trace ID" - every `db.query` span must reach the request + span by walking parents, and the request span must be the only root. A + stray root would show up in a trace UI as its own single-span trace, which + is the state this replaces. + """ + otel_spans.clear() + assert (await ds.client.get(f"/{ds.db_name}/t?_facet=v")).status_code == 200 + spans = otel_spans.get_finished_spans() + server = _server_spans(otel_spans) + assert len(server) == 1 + server_span = server[0] + assert server_span.parent is None + + by_span_id = {span.context.span_id: span for span in spans} + roots = [span for span in spans if span.parent is None] + assert [span.name for span in roots] == [server_span.name], ( + "every span from a request should hang off the request span, but these " + f"are roots: {sorted(span.name for span in roots)}" + ) + + queries = [span for span in spans if span.name == "db.query"] + assert queries, "a faceted table page should have issued queries" + for query in queries: + assert query.context.trace_id == server_span.context.trace_id + # Walk up to the root, which must be the request span. + current = query + seen = 0 + while current.parent is not None: + current = by_span_id[current.parent.span_id] + seen += 1 + assert seen < 20, "parent chain did not terminate" + assert current is server_span + + +@pytest.mark.asyncio +async def test_500_sets_error_status_and_error_type(ds, otel_spans): + """ + A plain 500 - no exception escaping the app, because `route_path` converts + it into a response itself. The status is the only signal the middleware + gets, so `error.type` is the status as a string. + """ + ds.pm.register(_BoomPlugin(), name="httpspan-boom") + try: + otel_spans.clear() + response = await ds.client.get("/-/http-span-boom") + assert response.status_code == 500 + finally: + ds.pm.unregister(name="httpspan-boom") + server = _server_spans(otel_spans) + assert len(server) == 1 + assert server[0].attributes["http.response.status_code"] == 500 + assert server[0].attributes["error.type"] == "500" + assert server[0].status.status_code is StatusCode.ERROR + + +@pytest.mark.asyncio +async def test_csv_stream_span_covers_the_body_send(ds_paging, otel_spans): + """ + The span must not end when the handler returns - it has to cover the + response body. + + `stream_csv` runs its generator inline inside `AsgiStream.asgi_send`, and + that call happens inside the single `await self.app(...)` the middleware + makes, so a plain `finally` is enough and no deferred-end machinery is + needed. This is the assertion that holds that claim up: a `db.query` that + starts during the body send must still finish before the request span + does. + + Only meaningful on an export that actually pages, hence `ds_paging` - on a + single-page table every query is over before the body begins and this + passes however early the span ends. The middle assertion below, that some + query *started* after `http.response.start` went out, is what keeps the + test honest about that; it is why the app is driven as raw ASGI rather + than through `ds.client`, which cannot timestamp the response start. + + `time.time_ns()` is the same clock the SDK stamps spans with, so the two + are directly comparable. + """ + app = ds_paging.app() + body = [] + response_started_at = None + + async def receive(): + return {"type": "http.request", "body": b"", "more_body": False} + + async def send(message): + nonlocal response_started_at + if message["type"] == "http.response.start": + assert message["status"] == 200 + response_started_at = time.time_ns() + else: + body.append(message.get("body") or b"") + + otel_spans.clear() + await app( + { + "type": "http", + "http_version": "1.1", + "method": "GET", + "path": f"/{ds_paging.db_name}/t.csv", + "raw_path": f"/{ds_paging.db_name}/t.csv".encode("latin-1"), + "query_string": b"_stream=1", + "scheme": "http", + "headers": [(b"host", b"localhost")], + }, + receive, + send, + ) + # 40 rows plus a header - the export really did read past one page + assert len(b"".join(body).decode("utf-8").strip().splitlines()) == 41 + assert response_started_at is not None + + spans = otel_spans.get_finished_spans() + server = _server_spans(otel_spans) + assert len(server) == 1 + server_span = server[0] + queries = [span for span in spans if span.name == "db.query"] + assert len(queries) > 1 + during_body = [span for span in queries if span.start_time > response_started_at] + assert during_body, ( + "no query ran after the response started, so this workload cannot " + "distinguish a span that covers the body send from one that ends when " + "the handler returns - the export is not paging" + ) + last_query_end = max(span.end_time for span in queries) + assert server_span.end_time > last_query_end, ( + "the request span ended before the last query of a streaming export - " + "it is not covering the response body" + ) + for query in queries: + assert query.context.trace_id == server_span.context.trace_id + + +@pytest.mark.asyncio +async def test_inbound_traceparent_becomes_the_parent(ds, otel_spans): + """ + W3C trace context is extracted with the global propagator, so a request + from an already-traced caller continues that trace. + + The sampled flag has to be set: the SDK's default sampler is + parentbased_always_on, so a `-00` flag would drop the span and the test + would fail for a reason that has nothing to do with propagation. + """ + trace_id = "4bf92f3577b34da6a3ce929d0e0e4736" + parent_span_id = "00f067aa0ba902b7" + otel_spans.clear() + response = await ds.client.get( + f"/{ds.db_name}/t", + headers={"traceparent": f"00-{trace_id}-{parent_span_id}-01"}, + ) + assert response.status_code == 200 + server = _server_spans(otel_spans) + assert len(server) == 1 + server_span = server[0] + assert f"{server_span.context.trace_id:032x}" == trace_id + assert server_span.parent is not None + assert f"{server_span.parent.span_id:016x}" == parent_span_id + assert server_span.parent.is_remote + # And the database spans joined the caller's trace too, not a new one. + queries = [ + span for span in otel_spans.get_finished_spans() if span.name == "db.query" + ] + assert queries + for query in queries: + assert f"{query.context.trace_id:032x}" == trace_id + + +@pytest.mark.asyncio +async def test_user_supplied_sql_in_the_query_string_is_never_recorded(ds, otel_spans): + """ + The `?sql=` case specifically, which is the one that matters: this is the + request where the query string *is* user-supplied SQL, and it reaches a + view that runs it. The marker is searched for across every attribute of + every span in the trace, not just for a `url.query` key, so recording it + under some other name fails too. + + `db.query.text` legitimately contains the SQL - that is documented and + deliberate - so the marker is checked against the request span's own + attributes, and against `url.*` and `http.*` keys everywhere. + """ + marker = "secret_marker_5b1f" + otel_spans.clear() + # `/{db}?sql=` 302s to the query view, so go straight there - a redirect + # would leave the SQL only on a span for a request that never ran it. + response = await ds.client.get(f"/{ds.db_name}/-/query?sql=select+'{marker}'") + assert response.status_code == 200 + spans = otel_spans.get_finished_spans() + server = _server_spans(otel_spans) + assert len(server) == 1 + leaked = [ + f"{span.name} -> {key}={value!r}" + for span in spans + for key, value in (span.attributes or {}).items() + if (span is server[0] or str(key).startswith(("url.", "http."))) + and (marker in str(value) or str(key) == "url.query") + ] + assert not leaked, "the query string reached a span attribute: " + ", ".join(leaked) + # The request really did carry the marker, so the search above had + # something to find. + assert marker in response.text + + +def test_request_span_skips_a_valid_but_non_recording_span(): + """ + `request_span()` is guarded on `is_recording()`, not on + `get_span_context().is_valid`, and this is the case that separates them. + + With no provider installed but an inbound `traceparent`, the API's + NoOpTracer hands back a `NonRecordingSpan` carrying the *remote* span + context - valid, sampled, and recording nothing. An `is_valid` guard would + wave that through and the router would build the name string and call + `set_attribute`/`update_name` on a span that discards both. + + Tested at this level deliberately: through a real request the two guards + are indistinguishable, because every call the router makes on a + NonRecordingSpan is already a no-op. The only difference is the work done + to get there, so the guard itself is what has to be asserted on. + """ + remote = SpanContext( + trace_id=0x4BF92F3577B34DA6A3CE929D0E0E4736, + span_id=0x00F067AA0BA902B7, + is_remote=True, + trace_flags=TraceFlags(TraceFlags.SAMPLED), + ) + assert remote.is_valid + non_recording = NonRecordingSpan(remote) + assert non_recording.is_recording() is False + assert request_span({REQUEST_SPAN_SCOPE_KEY: non_recording}) is None + # Nothing current, nothing in the scope: the INVALID_SPAN fallback. + assert request_span({}) is None + # And the case it must not skip. + with tracer.start_as_current_span("test.request_span.recording") as span: + assert request_span({REQUEST_SPAN_SCOPE_KEY: span}) is span + # Falling back to the current span is how an externally installed + # SERVER span still gets enriched. + assert request_span({}) is span + + +NO_PROVIDER_PROGRAM = textwrap.dedent(""" + import asyncio, json, sys + + from datasette.telemetry import TelemetryMiddleware + + seen = {} + + + async def inner(scope, receive, send): + seen.setdefault("sends", []).append(send) + seen.setdefault("scopes", []).append(scope) + await send({"type": "http.response.start", "status": 200, "headers": []}) + await send({"type": "http.response.body", "body": b""}) + + + async def real_send(message): + pass + + + async def main(): + middleware = TelemetryMiddleware(inner) + for headers in ([], [(b"traceparent", b"00-" + b"a" * 32 + b"-" + b"b" * 16 + b"-01")]): + await middleware( + { + "type": "http", + "method": "GET", + "path": "/", + "raw_path": b"/", + "scheme": "http", + "headers": headers, + }, + None, + real_send, + ) + print( + json.dumps( + { + "unwrapped": [send is real_send for send in seen["sends"]], + "scope_keys": [ + "datasette.telemetry.request_span" in scope + for scope in seen["scopes"] + ], + "sdk_imported": any( + name.startswith("opentelemetry.sdk") for name in sys.modules + ), + } + ) + ) + + + asyncio.run(main()) + """) + + +def test_no_provider_takes_the_fast_path(): + """ + With no `TracerProvider` installed the middleware must hand the + application the *original* `send`, not a wrapper - a default Datasette + install should pay essentially nothing for instrumentation it is not + using. + + This has to run in a subprocess. The suite's `_otel_provider` fixture is + session-scoped and autouse, and `set_tracer_provider()` is effectively + once-per-process, so in-process every span is recording and the fast path + is unreachable. + + The second case, with an inbound `traceparent`, is the one that pins the + check itself. With no provider the API's NoOpTracer returns a + NonRecordingSpan carrying the *remote* span context: its + `get_span_context().is_valid` is True while `is_recording()` is False. A + fast path guarded on `is_valid` would therefore silently stop working for + exactly the requests that arrive from an already-traced caller - which on + a real deployment behind an instrumented proxy is all of them. + + conftest.py's pytest_collection_modifyitems() moves this test to the front + of the run by name - if you rename it, rename it there too. + """ + result = subprocess.run( + [sys.executable, "-c", NO_PROVIDER_PROGRAM], + capture_output=True, + text=True, + check=True, + ) + report = json.loads(result.stdout) + assert report["sdk_imported"] is False, "the SDK loaded in a fresh interpreter" + assert report["unwrapped"] == [True, True], ( + "the middleware wrapped `send` with no provider installed; the second " + "entry is the inbound-traceparent case, which fails if the fast path " + "is guarded on is_valid instead of is_recording()" + ) + # Same fast path, other observable: nothing is stashed in the scope either. + assert report["scope_keys"] == [False, False] diff --git a/tests/test_telemetry_registry.py b/tests/test_telemetry_registry.py index 96b2a7c5..398f72aa 100644 --- a/tests/test_telemetry_registry.py +++ b/tests/test_telemetry_registry.py @@ -70,15 +70,22 @@ EXPECTED_ATTRIBUTES = { EXPECTED_SPANS = set(EXPECTED_ATTRIBUTES) # The HTTP request span is handled separately because its name is composed at -# runtime - it is the request method - so there is no fixed string to pin it -# to. What can still be pinned, and is what a dashboard depends on, is the -# shape of the name and the attribute keys. The workload below only issues -# GETs, so a change that stopped clamping the method, or that started naming -# the span after the path, fails here. -EXPECTED_HTTP_SPAN_NAME = "{http.request.method}" -EXPECTED_HTTP_SPAN_NAMES = {"GET"} +# runtime - the request method, then the route it matched - so there is no +# fixed string to pin it to. What can still be pinned, and is what a dashboard +# depends on, is the shape of that name and the attribute keys. +# +# The route half is deliberately not spelled out as a literal: it is a core +# route regex, and pinning those here would make an unrelated routing change +# fail the telemetry conformance test. What is pinned instead is that the name +# is exactly the method, a space, and the span's own `http.route` value - the +# `{method} {route}` shape semantic conventions specify. The workload below +# only issues GETs, so a change that stopped clamping the method, or that +# started naming the span after the path, fails here. +EXPECTED_HTTP_SPAN_NAME = "{http.request.method} {http.route}" +EXPECTED_HTTP_METHOD_NAMES = {"GET"} EXPECTED_HTTP_ATTRIBUTES = { "http.request.method", + "http.route", "url.path", "url.scheme", "server.address", @@ -193,10 +200,12 @@ async def exercise(): @pytest_asyncio.fixture async def emitted(otel_spans): """ - Every (span name, span kind, attribute keys) triple a broad workload emits. + Every (span name, span kind, attributes) triple a broad workload emits. The kind is carried because the request span's name is composed at - runtime, so `span_for()` resolves it by kind instead. + runtime, so `span_for()` resolves it by kind instead. The attributes are + carried as a mapping rather than a set of keys because the request span's + name has to be checked against its own `http.route` value. """ # otel_spans has already cleared the exporter, and nothing is cleared # after this point: the workload's own startup emits datasette.startup. @@ -210,7 +219,7 @@ async def emitted(otel_spans): ( str(span.name), span.kind, - frozenset(str(key) for key in span.attributes or {}), + {str(key): value for key, value in (span.attributes or {}).items()}, ) for span in spans ) @@ -227,8 +236,8 @@ def _partition(emitted): def _keys_by_span(records): by_span = {} - for name, _kind, keys in records: - by_span.setdefault(name, set()).update(keys) + for name, _kind, attributes in records: + by_span.setdefault(name, set()).update(attributes) return by_span @@ -246,11 +255,22 @@ async def test_workload_emits_exactly_the_expected_names(emitted): assert by_span == EXPECTED_ATTRIBUTES assert server, "the workload made HTTP requests but no SERVER span was emitted" - server_keys = _keys_by_span(server) - assert set(server_keys) == EXPECTED_HTTP_SPAN_NAMES union = set() - for keys in server_keys.values(): - union |= keys + methods = set() + for name, _kind, attributes in server: + union |= set(attributes) + route = attributes.get("http.route") + # Every request in the workload matches a route, so every one of these + # names must be `{method} {route}`. A 404 would be a bare method - the + # http_route tests cover that case with a real request. + assert route, f"the request span {name!r} carries no http.route" + method, _, name_route = name.partition(" ") + assert name_route == route, ( + f"the request span is named {name!r}, which is not the " + f"`{{method}} {{route}}` of {method!r} and {route!r}" + ) + methods.add(method) + assert methods == EXPECTED_HTTP_METHOD_NAMES assert union == EXPECTED_HTTP_ATTRIBUTES From 745b7872b8bd141698db9631a815a4efffefc777 Mon Sep 17 00:00:00 2001 From: Alex Garcia Date: Thu, 30 Jul 2026 20:14:08 -0700 Subject: [PATCH 13/13] Remove the hand-rolled tracer now that OpenTelemetry covers the same ground Datasette had two tracing systems since the OpenTelemetry spans landed. The hand-rolled one measures the wrong thing - issue 1730, open since 2022, is about exactly that - and it cannot be rebuilt on top of the new spans without core owning a TracerProvider, which is the one thing the OTel design refuses to do. Rather than carry duplicate instrumentation on the db.execute() hot path indefinitely, the old system goes. Deleted: datasette/tracer.py, the trace_debug setting, the AsgiTracer response-rewriting middleware and the ?_trace=1 query-string argument. - datasette/database.py: the four `with trace(...)` wrappers PR 1 deliberately nested the OTel spans inside are removed and the bodies dedented. That also retires the `# noqa: SIM117` comments those wrappers required - a leftover unnecessary noqa trips ruff's RUF100 - and `kwargs["count"] = count` in execute_write_many, which fed the old tracer only. `git diff -w` on this file shows nothing but the deleted lines. - datasette/views/base.py: stream_csv() still read ?_trace=1 to wrap CSV output in an HTML " async def stream_fn(r): - nonlocal data, trace + nonlocal data limited_writer = LimitedWriter(r, datasette.setting("max_csv_mb")) - if trace: - await limited_writer.write(preamble) - writer = csv.writer(EscapeHtmlWriter(limited_writer)) - else: - writer = csv.writer(limited_writer) + writer = csv.writer(limited_writer) first = True next = None while first or (next and stream): @@ -322,14 +306,12 @@ async def stream_csv(datasette, fetch_data, request, database): sys.stderr.flush() await r.write(str(ex)) return - await limited_writer.write(postamble) headers = {} if datasette.cors: add_cors_headers(headers) if request.args.get("_dl", None): - if not trace: - content_type = "text/csv; charset=utf-8" + content_type = "text/csv; charset=utf-8" disposition = 'attachment; filename="{}.csv"'.format( request.url_vars.get("table", database) ) diff --git a/datasette/views/table.py b/datasette/views/table.py index 6d920fd8..91e0aa37 100644 --- a/datasette/views/table.py +++ b/datasette/views/table.py @@ -8,7 +8,6 @@ from dataclasses import dataclass, field import markupsafe import sqlite_utils -from datasette import tracer from datasette.column_types import SQLiteType from datasette.database import QueryInterrupted from datasette.events import ( @@ -1690,8 +1689,7 @@ async def _sort_order(table_metadata, sortable_columns, request, order_by): async def table_view(datasette, request): await datasette.refresh_schemas() - with tracer.trace_child_tasks(): - response = await table_view_traced(datasette, request) + response = await table_view_traced(datasette, request) # CORS if datasette.cors: diff --git a/docs/changelog.rst b/docs/changelog.rst index cec8e92d..a3d39a63 100644 --- a/docs/changelog.rst +++ b/docs/changelog.rst @@ -11,8 +11,7 @@ Unreleased - Datasette's database layer now emits `OpenTelemetry `__ spans: one per query, covering the full round trip including time spent waiting for a SQL worker thread, plus separate child spans for the execution itself and for time spent in the write queue. Datasette core depends on ``opentelemetry-api`` only and never installs an SDK provider, an exporter or a sampler, so there is no effect and no measurable overhead unless tracing is switched on externally - normally with the standard ``opentelemetry-instrument`` agent. See :ref:`internals_telemetry`. (:issue:`1730`) - :ref:`db.execute(sql, ..., table=None) ` has a new optional ``table=`` parameter, naming the table a query is about so it can be recorded on that query's OpenTelemetry span. It has no effect on query execution, and Datasette never derives it from the SQL. (:issue:`1730`) - -Nothing is removed by this change: the ``?_trace=1`` query string parameter, the ``trace_debug`` setting and the :ref:`internals_tracer` module all continue to work as before. +- **Breaking change:** Datasette's hand-rolled tracer has been removed, now that OpenTelemetry covers the same ground. The ``?_trace=1`` query string parameter, the ``trace_debug`` setting and the ``datasette.tracer`` module are all gone. ``datasette.tracer.trace()`` and ``datasette.tracer.trace_child_tasks()`` were documented plugin APIs, so any plugin importing them will now raise ``ModuleNotFoundError`` and needs a new release. `datasette-pretty-traces `__ does not import that module, but it renders ``?_trace=1`` output, so it no longer has anything to display. (:issue:`1730`) .. _v1_0_a38: @@ -1161,7 +1160,7 @@ Datasette also now requires Python 3.7 or higher. - ``sqlite_stat`` tables are now hidden by default. (:issue:`1587`) - SpatiaLite tables ``data_licenses``, ``KNN`` and ``KNN2`` are now hidden by default. (:issue:`1601`) - SQL query tracing mechanism now works for queries executed in ``asyncio`` sub-tasks, such as those created by ``asyncio.gather()``. (:issue:`1576`) -- :ref:`internals_tracer` mechanism is now documented. +- ``datasette.tracer`` mechanism is now documented. - Common Datasette symbols can now be imported directly from the top-level ``datasette`` package, see :ref:`internals_shortcuts`. Those symbols are ``Response``, ``Forbidden``, ``NotFound``, ``hookimpl``, ``actor_matches_allow``. (:issue:`957`) - ``/-/versions`` page now returns additional details for libraries used by SpatiaLite. (:issue:`1607`) - Documentation now links to the `Datasette Tutorials `__. @@ -1327,7 +1326,7 @@ New features - ``?_facet_size=max`` sets that to the maximum, which defaults to 1,000 and is controlled by the the :ref:`setting_max_returned_rows` setting. If facet results are truncated the … at the bottom of the facet list now links to this parameter. (:issue:`1337`) - ``?_nofacet=1`` option to disable all facet calculations on a page, used as a performance optimization for CSV exports and ``?_shape=array/object``. (:issue:`1349`, :issue:`263`) - ``?_nocount=1`` option to disable full query result counts. (:issue:`1353`) -- ``?_trace=1`` debugging option is now controlled by the new :ref:`setting_trace_debug` setting, which is turned off by default. (:issue:`1359`) +- ``?_trace=1`` debugging option is now controlled by the new ``trace_debug`` setting, which is turned off by default. (:issue:`1359`) Bug fixes and other improvements ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~ diff --git a/docs/cli-reference.rst b/docs/cli-reference.rst index 2302f742..7688a819 100644 --- a/docs/cli-reference.rst +++ b/docs/cli-reference.rst @@ -283,8 +283,6 @@ These can be passed to ``datasette serve`` using ``datasette serve --setting nam protocol (default=False) template_debug Allow display of template debug information with ?_context=1 (default=False) - trace_debug Allow display of SQL trace debug information with - ?_trace=1 (default=False) base_url Datasette URLs should use this base path (default=/) diff --git a/docs/internals.rst b/docs/internals.rst index da99e557..96404966 100644 --- a/docs/internals.rst +++ b/docs/internals.rst @@ -2327,8 +2327,6 @@ Turning tracing on is entirely an operational decision made outside of Datasette Everything Datasette emits carries the instrumentation scope ``datasette``, versioned with the running Datasette version and declaring the `semantic conventions schema `__ its attribute names follow. -This is separate from, and does not replace, the built-in :ref:`internals_tracer` mechanism behind ``?_trace=1`` and the :ref:`setting_trace_debug` setting. Both continue to work exactly as before. - .. _internals_telemetry_turning_on: Turning tracing on @@ -2773,8 +2771,6 @@ Async version of :ref:`call_with_supported_arguments `__. The JSON output shows full details of every SQL query that was executed to generate the page. - -The `datasette-pretty-traces `__ plugin can be installed to provide a more readable display of this information. You can see `a demo of that here `__. - -You can add your own custom traces to the JSON output using the ``trace()`` context manager. This takes a string that identifies the type of trace being recorded, and records any keyword arguments as additional JSON keys on the resulting trace object. - -The start and end time, duration and a traceback of where the trace was executed will be automatically attached to the JSON object. - -This example uses trace to record the start, end and duration of any HTTP GET requests made using the function: - -.. code-block:: python - - from datasette.tracer import trace - import httpx - - - async def fetch_url(url): - with trace("fetch-url", url=url): - async with httpx.AsyncClient() as client: - return await client.get(url) - -.. _internals_tracer_trace_child_tasks: - -Tracing child tasks -------------------- - -If your code uses a mechanism such as ``asyncio.gather()`` to execute code in additional tasks you may find that some of the traces are missing from the display. - -You can use the ``trace_child_tasks()`` context manager to ensure these child tasks are correctly handled. - -.. code-block:: python - - from datasette import tracer - - with tracer.trace_child_tasks(): - results = await asyncio.gather( - # ... async tasks here - ) - -This example uses the :ref:`register_routes() ` plugin hook to add a page at ``/parallel-queries`` which executes two SQL queries in parallel using ``asyncio.gather()`` and returns their results. - -.. code-block:: python - - from datasette import hookimpl - from datasette import tracer - - - @hookimpl - def register_routes(): - async def parallel_queries(datasette): - db = datasette.get_database() - with tracer.trace_child_tasks(): - one, two = await asyncio.gather( - db.execute("select 1"), - db.execute("select 2"), - ) - return Response.json( - { - "one": one.single_value(), - "two": two.single_value(), - } - ) - - return [ - (r"/parallel-queries$", parallel_queries), - ] - -Note that running parallel SQL queries in this way has `been known to cause problems in the past `__, so treat this example with caution. - -Adding ``?_trace=1`` will show that the trace covers both of those child tasks. - .. _internals_shortcuts: Import shortcuts diff --git a/docs/introspection.rst b/docs/introspection.rst index 14b6249f..96504c08 100644 --- a/docs/introspection.rst +++ b/docs/introspection.rst @@ -124,7 +124,6 @@ Shows the :ref:`configuration ` for this instance of Datasette. T "ok": true, "settings": { "template_debug": true, - "trace_debug": true, "force_https_urls": true } } diff --git a/docs/json_api.rst b/docs/json_api.rst index a96fd73d..7ab4e72b 100644 --- a/docs/json_api.rst +++ b/docs/json_api.rst @@ -313,16 +313,6 @@ query string arguments: For how many seconds should this response be cached by HTTP proxies? Use ``?_ttl=0`` to disable HTTP caching entirely for this request. -``?_trace=1`` - Turns on tracing for this page: SQL queries executed during the request will - be gathered and included in the response, either in a new ``"_traces"`` key - for JSON responses or at the bottom of the page if the response is in HTML. - - The structure of the data returned here should be considered highly unstable - and very likely to change. - - Only available if the :ref:`setting_trace_debug` setting is enabled. - .. _json_api_extra: Expanding JSON responses diff --git a/docs/settings.rst b/docs/settings.rst index 9c114e4a..625da7d1 100644 --- a/docs/settings.rst +++ b/docs/settings.rst @@ -335,24 +335,6 @@ Some examples: * https://latest.datasette.io/fixtures?_context=1 * https://latest.datasette.io/fixtures/roadside_attractions?_context=1 -.. _setting_trace_debug: - -trace_debug -~~~~~~~~~~~ - -This setting enables appending ``?_trace=1`` to any page in order to see the SQL queries and other trace information that was used to generate that page. - -Enable it like this:: - - datasette mydatabase.db --setting trace_debug 1 - -Some examples: - -* https://latest.datasette.io/?_trace=1 -* https://latest.datasette.io/fixtures/roadside_attractions?_trace=1 - -See :ref:`internals_tracer` for details on how to hook into this mechanism as a plugin author. - .. _setting_base_url: base_url diff --git a/tests/conftest.py b/tests/conftest.py index b2453133..d1d60ebf 100644 --- a/tests/conftest.py +++ b/tests/conftest.py @@ -461,6 +461,5 @@ from .fixtures import ( # noqa: F401 app_client_two_attached_databases_one_immutable, app_client_with_cors, app_client_with_dot, - app_client_with_trace, make_app_client, ) diff --git a/tests/fixtures.py b/tests/fixtures.py index 83607c1a..e0fbb93e 100644 --- a/tests/fixtures.py +++ b/tests/fixtures.py @@ -230,12 +230,6 @@ def app_client_two_attached_databases_one_immutable(): yield client -@pytest.fixture(scope="session") -def app_client_with_trace(): - with make_app_client(settings={"trace_debug": True}, is_immutable=True) as client: - yield client - - @pytest.fixture(scope="session") def app_client_shorter_time_limit(): with make_app_client(20) as client: diff --git a/tests/plugins/my_plugin.py b/tests/plugins/my_plugin.py index baf20a77..d656b921 100644 --- a/tests/plugins/my_plugin.py +++ b/tests/plugins/my_plugin.py @@ -3,7 +3,7 @@ import base64 import json import urllib.parse -from datasette import hookimpl, tracer +from datasette import hookimpl from datasette.facets import Facet from datasette.permissions import Action from datasette.resources import DatabaseResource @@ -278,11 +278,10 @@ def register_routes(): async def parallel_queries(datasette): db = datasette.get_database() - with tracer.trace_child_tasks(): - one, two = await asyncio.gather( - db.execute("select coalesce(sleep(0.1), 1)"), - db.execute("select coalesce(sleep(0.1), 2)"), - ) + one, two = await asyncio.gather( + db.execute("select coalesce(sleep(0.1), 1)"), + db.execute("select coalesce(sleep(0.1), 2)"), + ) return Response.json({"one": one.single_value(), "two": two.single_value()}) return [ diff --git a/tests/test_api.py b/tests/test_api.py index 76c30e46..6fb88974 100644 --- a/tests/test_api.py +++ b/tests/test_api.py @@ -706,7 +706,6 @@ async def test_settings_json(ds_client): "truncate_cells_html": 2048, "force_https_urls": False, "template_debug": False, - "trace_debug": False, "base_url": "/", } diff --git a/tests/test_csv.py b/tests/test_csv.py index 7758a3c0..c1ab02ed 100644 --- a/tests/test_csv.py +++ b/tests/test_csv.py @@ -1,9 +1,9 @@ import urllib.parse import pytest -from bs4 import BeautifulSoup as Soup from datasette.app import Datasette +from datasette.telemetry_registry import DB_QUERY, DB_QUERY_TEXT EXPECTED_TABLE_CSV = """id,content 1,hello @@ -229,24 +229,43 @@ async def test_table_csv_stream(ds_client): assert len([b for b in response.content.split(b"\r\n") if b]) == 1002 -def test_csv_trace(app_client_with_trace): - response = app_client_with_trace.get("/fixtures/simple_primary_key.csv?_trace=1") - assert response.headers["content-type"] == "text/html; charset=utf-8" - soup = Soup(response.text, "html.parser") - assert ( - soup.find("textarea").text - == "id,content\r\n1,hello\r\n2,world\r\n3,\r\n4,RENDER_CELL_DEMO\r\n5,RENDER_CELL_ASYNC\r\n" - ) - assert "select id, content from simple_primary_key" in soup.find("pre").text +def db_query_texts(otel_spans): + "Every db.query.text recorded by a db.query span since the exporter was cleared." + return [ + span.attributes.get(DB_QUERY_TEXT, "") + for span in otel_spans.get_finished_spans() + if span.name == DB_QUERY + ] -def test_table_csv_stream_does_not_calculate_facets(app_client_with_trace): - response = app_client_with_trace.get("/fixtures/simple_primary_key.csv?_trace=1") - soup = Soup(response.text, "html.parser") - assert "select content, count(*) as n" not in soup.find("pre").text +# Both faceting and facet suggestion aggregate with a named count: facet +# results use "count(*) as count", suggestions use "count(*) as n". Matching +# on those rather than on a whole query string, because the surrounding SQL +# has been rewritten before - the previous version of this test looked for +# "select content, count(*) as n", which facet suggestion stopped emitting +# when it moved to a "with limited as (...)" CTE, leaving the assertion +# unable to fail. +FACET_QUERY_MARKERS = ("count(*) as n", "count(*) as count") -def test_table_csv_stream_does_not_calculate_counts(app_client_with_trace): - response = app_client_with_trace.get("/fixtures/simple_primary_key.csv?_trace=1") - soup = Soup(response.text, "html.parser") - assert "select count(*)" not in soup.find("pre").text +@pytest.mark.asyncio +async def test_table_csv_stream_does_not_calculate_facets(ds_client, otel_spans): + response = await ds_client.get("/fixtures/simple_primary_key.csv") + assert response.status_code == 200 + queries = db_query_texts(otel_spans) + # Guard: without this, a change that stopped the CSV route running any + # query at all - or that broke span capture - would leave the real + # assertion below trivially true. + assert any("from simple_primary_key" in q for q in queries), queries + assert not any( + marker in query for query in queries for marker in FACET_QUERY_MARKERS + ), queries + + +@pytest.mark.asyncio +async def test_table_csv_stream_does_not_calculate_counts(ds_client, otel_spans): + response = await ds_client.get("/fixtures/simple_primary_key.csv") + assert response.status_code == 200 + queries = db_query_texts(otel_spans) + assert any("from simple_primary_key" in q for q in queries), queries + assert not any("select count(*)" in q for q in queries), queries diff --git a/tests/test_html.py b/tests/test_html.py index 6a7b4907..54abc999 100644 --- a/tests/test_html.py +++ b/tests/test_html.py @@ -1141,8 +1141,13 @@ async def test_navigation_menu_links( @pytest.mark.asyncio -async def test_trace_correctly_escaped(ds_client): - response = await ds_client.get("/fixtures/-/query?sql=select+'

Hello'&_trace=1") +async def test_query_page_escapes_sql(ds_client): + # This was previously test_trace_correctly_escaped, which appended + # ?_trace=1. It never exercised the tracer - ds_client has no trace_debug - + # so what it actually covered was the query page echoing user-supplied SQL + # back into HTML. That page is the subject of two historical reflected-XSS + # advisories (issue 1360), so the coverage is kept now the tracer is gone. + response = await ds_client.get("/fixtures/-/query?sql=select+'

Hello'") assert "select '

Hello" not in response.text assert "select '<h1>Hello" in response.text diff --git a/tests/test_table_api.py b/tests/test_table_api.py index 6c0c021b..95a746e1 100644 --- a/tests/test_table_api.py +++ b/tests/test_table_api.py @@ -4,6 +4,7 @@ import urllib import pytest from datasette.fixtures import generate_compound_rows, generate_sortable_rows +from datasette.telemetry_registry import DB_QUERY, DB_QUERY_TEXT from datasette.utils import detect_json1, tilde_encode from datasette.utils.sqlite import sqlite_version @@ -1201,11 +1202,25 @@ async def test_nocount(ds_client, nocount, expected_count): assert response.json()["count"] == expected_count -def test_nocount_nofacet_if_shape_is_object(app_client_with_trace): - response = app_client_with_trace.get( - "/fixtures/facetable.json?_trace=1&_shape=object" +@pytest.mark.asyncio +async def test_nocount_nofacet_if_shape_is_object(ds_client, otel_spans): + # ?_extra=count and ?_facet=state each cause a count(*) query on their + # own. _shape=object is supposed to suppress both, so asking for them + # explicitly is what makes this test able to fail - a plain + # ?_shape=object request would never have run either query anyway. + response = await ds_client.get( + "/fixtures/facetable.json?_shape=object&_extra=count&_facet=state" ) - assert "count(*)" not in response.text + assert response.status_code == 200 + queries = [ + span.attributes.get(DB_QUERY_TEXT, "") + for span in otel_spans.get_finished_spans() + if span.name == DB_QUERY + ] + # Guard: prove the request really did query the table, so the assertion + # below is measuring suppression rather than an empty span list. + assert any("from facetable" in q for q in queries), queries + assert not any("count(*)" in q for q in queries), queries @pytest.mark.asyncio diff --git a/tests/test_tracer.py b/tests/test_tracer.py deleted file mode 100644 index 21cfa952..00000000 --- a/tests/test_tracer.py +++ /dev/null @@ -1,98 +0,0 @@ -import pytest - -from .fixtures import make_app_client - - -@pytest.mark.parametrize("trace_debug", (True, False)) -def test_trace(trace_debug): - with make_app_client(settings={"trace_debug": trace_debug}) as client: - response = client.get("/fixtures/simple_primary_key.json?_trace=1") - assert response.status == 200 - - data = response.json - if not trace_debug: - assert "_trace" not in data - return - - assert "_trace" in data - trace_info = data["_trace"] - assert isinstance(trace_info["request_duration_ms"], float) - assert isinstance(trace_info["sum_trace_duration_ms"], float) - assert isinstance(trace_info["num_traces"], int) - assert isinstance(trace_info["traces"], list) - traces = trace_info["traces"] - assert len(traces) == trace_info["num_traces"] - for trace in traces: - assert isinstance(trace["type"], str) - assert isinstance(trace["start"], float) - assert isinstance(trace["end"], float) - assert trace["duration_ms"] == (trace["end"] - trace["start"]) * 1000 - assert isinstance(trace["traceback"], list) - assert isinstance(trace["database"], str) - assert isinstance(trace["sql"], str) - assert isinstance(trace.get("params"), (list, dict, None.__class__)) - - sqls = [trace["sql"] for trace in traces if "sql" in trace] - # There should be SQL statements from request handling in the trace. - # Note: CREATE TABLE, INSERT OR REPLACE, executescript, and executemany - # are not expected here because internal tables are now created and - # populated during invoke_startup(), before the request is traced. - assert any(sql.startswith("select ") for sql in sqls), "No select statements traced" - - -def test_trace_silently_fails_for_large_page(): - # Max HTML size is 256KB - with make_app_client(settings={"trace_debug": True}) as client: - # Small response should have trace - small_response = client.get("/fixtures/simple_primary_key.json?_trace=1") - assert small_response.status == 200 - assert "_trace" in small_response.json - - # Big response should not - big_response = client.get( - "/fixtures/-/query.json", - params={"_trace": 1, "sql": "select zeroblob(1024 * 256)"}, - ) - assert big_response.status == 200 - assert "_trace" not in big_response.json - - -def test_trace_query_errors(): - with make_app_client(settings={"trace_debug": True}) as client: - response = client.get( - "/fixtures/-/query.json", - params={"_trace": 1, "sql": "select * from non_existent_table"}, - ) - assert response.status == 400 - - data = response.json - assert "_trace" in data - trace_info = data["_trace"] - assert trace_info["traces"][-1]["error"] == "no such table: non_existent_table" - - -@pytest.mark.asyncio -async def test_trace_child_tasks_resets_contextvar_on_exception(): - from datasette import tracer - - before = tracer.trace_task_id.get() - with pytest.raises(ValueError), tracer.trace_child_tasks(): - assert tracer.trace_task_id.get() is not None - raise ValueError("simulated error") - # The contextvar must be reset even though the block raised - assert tracer.trace_task_id.get() == before - - -def test_trace_parallel_queries(): - with make_app_client(settings={"trace_debug": True}) as client: - response = client.get("/parallel-queries?_trace=1") - assert response.status == 200 - - data = response.json - assert data["one"] == 1 - assert data["two"] == 2 - trace_info = data["_trace"] - traces = [trace for trace in trace_info["traces"] if "sql" in trace] - one, two = traces - # "two" should have started before "one" ended - assert two["start"] < one["end"] diff --git a/tests/test_utils.py b/tests/test_utils.py index 1808b3cf..6f08cfa3 100644 --- a/tests/test_utils.py +++ b/tests/test_utils.py @@ -852,13 +852,13 @@ def test_truncate_url(url, length, expected): ), ( [ - ("settings.trace_debug", "true"), + ("settings.template_debug", "true"), ("plugins.datasette-ripgrep.path", "/etc"), - ("settings.trace_debug", "false"), + ("settings.template_debug", "false"), ], { "settings": { - "trace_debug": False, + "template_debug": False, }, "plugins": { "datasette-ripgrep": {