datasette/tests/test_telemetry.py

Ignoring revisions in .git-blame-ignore-revs. Click here to bypass and see the normal blame view.

750 lines
30 KiB
Python
Raw Normal View History

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(<column>) 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 <noreply@anthropic.com>
2026-07-30 17:45:32 -07:00
import json
import sqlite3
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 <noreply@anthropic.com>
2026-07-30 17:30:52 -07:00
import subprocess
import sys
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 <noreply@anthropic.com>
2026-07-30 18:05:34 -07:00
import time
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 <noreply@anthropic.com>
2026-07-30 17:30:52 -07:00
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(<column>) 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 <noreply@anthropic.com>
2026-07-30 17:45:32 -07:00
import pytest
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 <noreply@anthropic.com>
2026-07-30 18:05:34 -07:00
import sqlite_utils
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 <noreply@anthropic.com>
2026-07-30 18:16:46 -07:00
from opentelemetry import trace as otel_trace
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 <noreply@anthropic.com>
2026-07-30 18:29:16 -07:00
from opentelemetry.trace import SpanKind, StatusCode
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(<column>) 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 <noreply@anthropic.com>
2026-07-30 17:45:32 -07:00
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 <noreply@anthropic.com>
2026-07-30 17:52:55 -07:00
from datasette.app import Datasette
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 <noreply@anthropic.com>
2026-07-30 18:05:34 -07:00
from datasette.database import Database
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 <noreply@anthropic.com>
2026-07-30 18:29:16 -07:00
from datasette.telemetry import (
MAX_SQL_LENGTH,
SCHEMA_URL,
sql_attribute,
sql_operation_name,
tracer,
)
from datasette.version import __version__
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(<column>) 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 <noreply@anthropic.com>
2026-07-30 17:45:32 -07:00
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"]
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 <noreply@anthropic.com>
2026-07-30 17:52:55 -07:00
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
]
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 <noreply@anthropic.com>
2026-07-30 18:05:34 -07:00
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
]
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 <noreply@anthropic.com>
2026-07-30 18:16:46 -07:00
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
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(<column>) 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 <noreply@anthropic.com>
2026-07-30 17:45:32 -07:00
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
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 <noreply@anthropic.com>
2026-07-30 17:30:52 -07:00
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()}"
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(<column>) 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 <noreply@anthropic.com>
2026-07-30 17:45:32 -07:00
@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"]
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 <noreply@anthropic.com>
2026-07-30 17:52:55 -07:00
@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
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 <noreply@anthropic.com>
2026-07-30 18:05:34 -07:00
# --- 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"]
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 <noreply@anthropic.com>
2026-07-30 18:16:46 -07:00
@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
)
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 <noreply@anthropic.com>
2026-07-30 18:29:16 -07:00
# --- 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"