This commit is contained in:
Alex Garcia 2026-09-01 23:25:02 +00:00 committed by GitHub
commit 394ccf2624
No known key found for this signature in database
GPG key ID: B5690EEEBB952194
21 changed files with 170 additions and 557 deletions

View file

@ -117,7 +117,7 @@ jobs:
--plugins-dir=plugins \
--branch=$GITHUB_SHA \
--version-note=$GITHUB_SHA \
--extra-options="--setting template_debug 1 --setting trace_debug 1 --crossdb --root" \
--extra-options="--setting template_debug 1 --crossdb --root" \
--install 'datasette-ephemeral-tables>=0.2.2' \
--service "datasette-latest$SUFFIX" \
--secret $LATEST_DATASETTE_SECRET

View file

@ -57,7 +57,6 @@ from .telemetry import (
)
from .telemetry_registry import HTTP_ROUTE, STARTUP
from .tokens import TokenInvalid
from .tracer import AsgiTracer
from .url_builder import Urls
from .utils import (
SPATIALITE_FUNCTIONS,
@ -294,11 +293,6 @@ SETTINGS = (
False,
"Allow display of template debug information with ?_context=1",
),
Setting(
"trace_debug",
False,
"Allow display of SQL trace debug information with ?_trace=1",
),
Setting("base_url", "/", "Datasette URLs should use this base path"),
)
_HASH_URLS_REMOVED = "The hash_urls setting has been removed, try the datasette-hashed-urls plugin instead"
@ -2867,8 +2861,6 @@ class Datasette:
self.close()
asgi = CrossOriginProtectionMiddleware(DatasetteRouter(self, routes), self)
if self.setting("trace_debug"):
asgi = AsgiTracer(asgi)
asgi = AsgiLifespan(
asgi,
on_startup=[self._startup_sequence],

View file

@ -40,7 +40,6 @@ from .telemetry_registry import (
TRANSACTION,
TRUNCATED,
)
from .tracer import trace
from .utils import (
call_with_supported_arguments,
detect_fts,
@ -284,24 +283,18 @@ class Database:
cursor, return_all=return_all, returning_limit=returning_limit
)
# 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, 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)
if params:
span.set_attribute(PARAM_COUNT, len(params))
results = await self.execute_write_fn(
_inner, block=block, request=request, transaction=transaction
)
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)
if params:
span.set_attribute(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):
@ -310,22 +303,18 @@ class Database:
def _inner(conn):
return conn.executescript(sql)
# Nested on purpose - see the note in execute_write().
with trace( # noqa: SIM117
"sql", database=self.name, sql=sql.strip(), executescript=True
):
# No db.operation.name here, deliberately: executescript() runs
# several semicolon-separated statements, and semantic conventions
# say the attribute should not be extracted from query text that
# can hold more than one operation - see sql_operation_name().
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
)
# 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=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
)
return results
async def execute_write_many(self, sql, params_seq, block=True, request=None):
@ -342,27 +331,22 @@ 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:
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)
results, count = await self.execute_write_fn(
_inner, block=block, request=request
)
# count is the number of parameter *sets* consumed by
# executemany(), not a row count - executemany returns no rows.
span.set_attribute(PARAM_SETS, count)
kwargs["count"] = count
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)
results, count = await self.execute_write_fn(
_inner, block=block, request=request
)
# count is the number of parameter *sets* consumed by
# executemany(), not a row count - executemany returns no rows.
span.set_attribute(PARAM_SETS, count)
return results
async def execute_isolated_fn(self, fn):
@ -701,8 +685,7 @@ class Database:
#
# 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) -
# (datasette/permissions.py) and _in_datasette_client (app.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
@ -711,9 +694,9 @@ class Database:
# 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.
# would be read - a plugin calling datasette.in_client() 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)
@ -818,59 +801,53 @@ class Database:
else:
return Results(rows, False, cursor.description)
# SIM117 wants these two context managers merged. They are kept nested
# deliberately: the hand-rolled tracer's wrapper is on its way out, and
# nesting makes removing it a single-line deletion.
with trace( # noqa: SIM117
"sql", database=self.name, sql=sql.strip(), params=params
):
# Exception handling is explicit rather than left to the context
# manager's defaults, so that callers passing log_sql_errors=False
# can be honoured - see the comment on the generic handler below.
with tracer.start_as_current_span(
DB_QUERY,
kind=DB_QUERY.kind,
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(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(PARAM_COUNT, len(params))
try:
results = await self.execute_fn(sql_operation_in_thread)
except QueryInterrupted as e:
# datasette.interrupted is set either way - it is the
# signal worth having. Only the ERROR status is
# conditional; see the timeout_expected comment above.
span.set_attribute(INTERRUPTED, True)
if not timeout_expected:
span.set_status(Status(StatusCode.ERROR, str(e)))
span.record_exception(e)
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(SQL_ERROR_SUPPRESSED, True)
raise
span.set_attribute(TRUNCATED, results.truncated)
span.set_attribute(ROWS_RETURNED, len(results.rows))
# Exception handling is explicit rather than left to the context
# manager's defaults, so that callers passing log_sql_errors=False
# can be honoured - see the comment on the generic handler below.
with tracer.start_as_current_span(
DB_QUERY,
kind=DB_QUERY.kind,
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(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(PARAM_COUNT, len(params))
try:
results = await self.execute_fn(sql_operation_in_thread)
except QueryInterrupted as e:
# datasette.interrupted is set either way - it is the
# signal worth having. Only the ERROR status is
# conditional; see the timeout_expected comment above.
span.set_attribute(INTERRUPTED, True)
if not timeout_expected:
span.set_status(Status(StatusCode.ERROR, str(e)))
span.record_exception(e)
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(SQL_ERROR_SUPPRESSED, True)
raise
span.set_attribute(TRUNCATED, results.truncated)
span.set_attribute(ROWS_RETURNED, len(results.rows))
return results
@property

View file

@ -1,156 +0,0 @@
import asyncio
import json
import time
import traceback
from contextlib import contextmanager
from contextvars import ContextVar
from markupsafe import escape
tracers = {}
TRACE_RESERVED_KEYS = {"type", "start", "end", "duration_ms", "traceback"}
trace_task_id = ContextVar("trace_task_id", default=None)
def get_task_id():
current = trace_task_id.get(None)
if current is not None:
return current
try:
loop = asyncio.get_event_loop()
except RuntimeError:
return None
return id(asyncio.current_task(loop=loop))
@contextmanager
def trace_child_tasks():
token = trace_task_id.set(get_task_id())
try:
yield
finally:
trace_task_id.reset(token)
@contextmanager
def trace(trace_type, **kwargs):
assert not TRACE_RESERVED_KEYS.intersection(
kwargs.keys()
), f".trace() keyword parameters cannot include {TRACE_RESERVED_KEYS}"
task_id = get_task_id()
if task_id is None:
yield kwargs
return
tracer = tracers.get(task_id)
if tracer is None:
yield kwargs
return
start = time.perf_counter()
captured_error = None
try:
yield kwargs
except Exception as ex:
captured_error = ex
raise
finally:
end = time.perf_counter()
trace_info = {
"type": trace_type,
"start": start,
"end": end,
"duration_ms": (end - start) * 1000,
"traceback": traceback.format_list(traceback.extract_stack(limit=6)[:-3]),
"error": str(captured_error) if captured_error else None,
}
trace_info.update(kwargs)
tracer.append(trace_info)
@contextmanager
def capture_traces(tracer):
# tracer is a list
task_id = get_task_id()
if task_id is None:
yield
return
tracers[task_id] = tracer
yield
del tracers[task_id]
class AsgiTracer:
# If the body is larger than this we don't attempt to append the trace
max_body_bytes = 1024 * 256 # 256 KB
def __init__(self, app):
self.app = app
async def __call__(self, scope, receive, send):
if b"_trace=1" not in scope.get("query_string", b"").split(b"&"):
await self.app(scope, receive, send)
return
trace_start = time.perf_counter()
traces = []
accumulated_body = b""
size_limit_exceeded = False
response_headers = []
async def wrapped_send(message):
nonlocal accumulated_body, size_limit_exceeded, response_headers
if message["type"] == "http.response.start":
response_headers = message["headers"]
await send(message)
return
if message["type"] != "http.response.body" or size_limit_exceeded:
await send(message)
return
# Accumulate body until the end or until size is exceeded
accumulated_body += message["body"]
if len(accumulated_body) > self.max_body_bytes:
# Send what we have accumulated so far
await send(
{
"type": "http.response.body",
"body": accumulated_body,
"more_body": bool(message.get("more_body")),
}
)
size_limit_exceeded = True
return
if not message.get("more_body"):
# We have all the body - modify it and send the result
# TODO: What to do about Content-Type or other cases?
trace_info = {
"request_duration_ms": 1000 * (time.perf_counter() - trace_start),
"sum_trace_duration_ms": sum(t["duration_ms"] for t in traces),
"num_traces": len(traces),
"traces": traces,
}
content_type = next(
(
v.decode("utf8")
for k, v in response_headers
if k.lower() == b"content-type"
),
"",
)
if "text/html" in content_type and b"</body>" in accumulated_body:
extra = escape(json.dumps(trace_info, indent=2))
extra_html = f"<pre>{extra}</pre></body>".encode()
accumulated_body = accumulated_body.replace(b"</body>", extra_html)
elif "json" in content_type and accumulated_body.startswith(b"{"):
data = json.loads(accumulated_body.decode("utf8"))
if "_trace" not in data:
data["_trace"] = trace_info
accumulated_body = json.dumps(data).encode("utf8")
await send({"type": "http.response.body", "body": accumulated_body})
with capture_traces(traces):
await self.app(scope, receive, wrapped_send)

View file

@ -3,7 +3,6 @@ import hashlib
import sys
from datasette.utils import (
EscapeHtmlWriter,
InvalidSql,
LimitedWriter,
add_cors_headers,
@ -225,26 +224,11 @@ async def stream_csv(datasette, fetch_data, request, database):
headings.append(f"{column}_label")
content_type = "text/plain; charset=utf-8"
preamble = ""
postamble = ""
trace = request.args.get("_trace")
if trace:
content_type = "text/html; charset=utf-8"
preamble = (
"<html><head><title>CSV debug</title></head>"
'<body><textarea style="width: 90%; height: 70vh">'
)
postamble = "</textarea></body></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)
)

View file

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

View file

@ -11,8 +11,7 @@ Unreleased
- Datasette's database layer now emits `OpenTelemetry <https://opentelemetry.io/>`__ 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) <database_execute>` 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 <https://datasette.io/plugins/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 <https://datasette.io/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
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~

View file

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

View file

@ -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 <https://opentelemetry.io/docs/specs/otel/schemas/>`__ 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 <internals_utils_call_with_
.. autofunction:: datasette.utils.async_call_with_supported_arguments
.. _internals_tracer:
JSON encoding
-------------
@ -2782,82 +2778,6 @@ JSON encoding
.. autoclass:: datasette.utils.CustomJSONEncoder
datasette.tracer
================
Running Datasette with ``--setting trace_debug 1`` enables trace debug output, which can then be viewed by adding ``?_trace=1`` to the query string for any page.
You can see an example of this at the bottom of `latest.datasette.io/fixtures/facetable?_trace=1 <https://latest.datasette.io/fixtures/facetable?_trace=1>`__. The JSON output shows full details of every SQL query that was executed to generate the page.
The `datasette-pretty-traces <https://datasette.io/plugins/datasette-pretty-traces>`__ plugin can be installed to provide a more readable display of this information. You can see `a demo of that here <https://latest-with-plugins.datasette.io/github/commits?_trace=1>`__.
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_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 <https://github.com/simonw/datasette/issues/2189>`__, so treat this example with caution.
Adding ``?_trace=1`` will show that the trace covers both of those child tasks.
.. _internals_shortcuts:
Import shortcuts

View file

@ -124,7 +124,6 @@ Shows the :ref:`configuration <configuration>` for this instance of Datasette. T
"ok": true,
"settings": {
"template_debug": true,
"trace_debug": true,
"force_https_urls": true
}
}

View file

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

View file

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

View file

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

View file

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

View file

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

View file

@ -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": "/",
}

View file

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

View file

@ -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+'<h1>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+'<h1>Hello'")
assert "select '<h1>Hello" not in response.text
assert "select &#39;&lt;h1&gt;Hello" in response.text

View file

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

View file

@ -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"]

View file

@ -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": {