diff --git a/.github/workflows/deploy-latest.yml b/.github/workflows/deploy-latest.yml index 3fc83438..b7f2361f 100644 --- a/.github/workflows/deploy-latest.yml +++ b/.github/workflows/deploy-latest.yml @@ -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 diff --git a/datasette/app.py b/datasette/app.py index 37c4e882..8cee9b74 100644 --- a/datasette/app.py +++ b/datasette/app.py @@ -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], diff --git a/datasette/database.py b/datasette/database.py index 7114a691..efb8c56e 100644 --- a/datasette/database.py +++ b/datasette/database.py @@ -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 diff --git a/datasette/tracer.py b/datasette/tracer.py deleted file mode 100644 index 1fbda6f9..00000000 --- a/datasette/tracer.py +++ /dev/null @@ -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"" in accumulated_body: - extra = escape(json.dumps(trace_info, indent=2)) - extra_html = f"
{extra}
".encode() - accumulated_body = accumulated_body.replace(b"", 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) diff --git a/datasette/views/base.py b/datasette/views/base.py index 48108cec..d8340fc4 100644 --- a/datasette/views/base.py +++ b/datasette/views/base.py @@ -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 = ( - "CSV debug" - '" async def stream_fn(r): - nonlocal data, trace + nonlocal data limited_writer = LimitedWriter(r, datasette.setting("max_csv_mb")) - if trace: - await limited_writer.write(preamble) - writer = csv.writer(EscapeHtmlWriter(limited_writer)) - else: - writer = csv.writer(limited_writer) + writer = csv.writer(limited_writer) first = True next = None while first or (next and stream): @@ -322,14 +306,12 @@ async def stream_csv(datasette, fetch_data, request, database): sys.stderr.flush() await r.write(str(ex)) return - await limited_writer.write(postamble) headers = {} if datasette.cors: add_cors_headers(headers) if request.args.get("_dl", None): - if not trace: - content_type = "text/csv; charset=utf-8" + content_type = "text/csv; charset=utf-8" disposition = 'attachment; filename="{}.csv"'.format( request.url_vars.get("table", database) ) diff --git a/datasette/views/table.py b/datasette/views/table.py index 6d920fd8..91e0aa37 100644 --- a/datasette/views/table.py +++ b/datasette/views/table.py @@ -8,7 +8,6 @@ from dataclasses import dataclass, field import markupsafe import sqlite_utils -from datasette import tracer from datasette.column_types import SQLiteType from datasette.database import QueryInterrupted from datasette.events import ( @@ -1690,8 +1689,7 @@ async def _sort_order(table_metadata, sortable_columns, request, order_by): async def table_view(datasette, request): await datasette.refresh_schemas() - with tracer.trace_child_tasks(): - response = await table_view_traced(datasette, request) + response = await table_view_traced(datasette, request) # CORS if datasette.cors: diff --git a/docs/changelog.rst b/docs/changelog.rst index cec8e92d..a3d39a63 100644 --- a/docs/changelog.rst +++ b/docs/changelog.rst @@ -11,8 +11,7 @@ Unreleased - Datasette's database layer now emits `OpenTelemetry `__ spans: one per query, covering the full round trip including time spent waiting for a SQL worker thread, plus separate child spans for the execution itself and for time spent in the write queue. Datasette core depends on ``opentelemetry-api`` only and never installs an SDK provider, an exporter or a sampler, so there is no effect and no measurable overhead unless tracing is switched on externally - normally with the standard ``opentelemetry-instrument`` agent. See :ref:`internals_telemetry`. (:issue:`1730`) - :ref:`db.execute(sql, ..., table=None) ` has a new optional ``table=`` parameter, naming the table a query is about so it can be recorded on that query's OpenTelemetry span. It has no effect on query execution, and Datasette never derives it from the SQL. (:issue:`1730`) - -Nothing is removed by this change: the ``?_trace=1`` query string parameter, the ``trace_debug`` setting and the :ref:`internals_tracer` module all continue to work as before. +- **Breaking change:** Datasette's hand-rolled tracer has been removed, now that OpenTelemetry covers the same ground. The ``?_trace=1`` query string parameter, the ``trace_debug`` setting and the ``datasette.tracer`` module are all gone. ``datasette.tracer.trace()`` and ``datasette.tracer.trace_child_tasks()`` were documented plugin APIs, so any plugin importing them will now raise ``ModuleNotFoundError`` and needs a new release. `datasette-pretty-traces `__ does not import that module, but it renders ``?_trace=1`` output, so it no longer has anything to display. (:issue:`1730`) .. _v1_0_a38: @@ -1161,7 +1160,7 @@ Datasette also now requires Python 3.7 or higher. - ``sqlite_stat`` tables are now hidden by default. (:issue:`1587`) - SpatiaLite tables ``data_licenses``, ``KNN`` and ``KNN2`` are now hidden by default. (:issue:`1601`) - SQL query tracing mechanism now works for queries executed in ``asyncio`` sub-tasks, such as those created by ``asyncio.gather()``. (:issue:`1576`) -- :ref:`internals_tracer` mechanism is now documented. +- ``datasette.tracer`` mechanism is now documented. - Common Datasette symbols can now be imported directly from the top-level ``datasette`` package, see :ref:`internals_shortcuts`. Those symbols are ``Response``, ``Forbidden``, ``NotFound``, ``hookimpl``, ``actor_matches_allow``. (:issue:`957`) - ``/-/versions`` page now returns additional details for libraries used by SpatiaLite. (:issue:`1607`) - Documentation now links to the `Datasette Tutorials `__. @@ -1327,7 +1326,7 @@ New features - ``?_facet_size=max`` sets that to the maximum, which defaults to 1,000 and is controlled by the the :ref:`setting_max_returned_rows` setting. If facet results are truncated the … at the bottom of the facet list now links to this parameter. (:issue:`1337`) - ``?_nofacet=1`` option to disable all facet calculations on a page, used as a performance optimization for CSV exports and ``?_shape=array/object``. (:issue:`1349`, :issue:`263`) - ``?_nocount=1`` option to disable full query result counts. (:issue:`1353`) -- ``?_trace=1`` debugging option is now controlled by the new :ref:`setting_trace_debug` setting, which is turned off by default. (:issue:`1359`) +- ``?_trace=1`` debugging option is now controlled by the new ``trace_debug`` setting, which is turned off by default. (:issue:`1359`) Bug fixes and other improvements ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~ diff --git a/docs/cli-reference.rst b/docs/cli-reference.rst index 2302f742..7688a819 100644 --- a/docs/cli-reference.rst +++ b/docs/cli-reference.rst @@ -283,8 +283,6 @@ These can be passed to ``datasette serve`` using ``datasette serve --setting nam protocol (default=False) template_debug Allow display of template debug information with ?_context=1 (default=False) - trace_debug Allow display of SQL trace debug information with - ?_trace=1 (default=False) base_url Datasette URLs should use this base path (default=/) diff --git a/docs/internals.rst b/docs/internals.rst index da99e557..96404966 100644 --- a/docs/internals.rst +++ b/docs/internals.rst @@ -2327,8 +2327,6 @@ Turning tracing on is entirely an operational decision made outside of Datasette Everything Datasette emits carries the instrumentation scope ``datasette``, versioned with the running Datasette version and declaring the `semantic conventions schema `__ its attribute names follow. -This is separate from, and does not replace, the built-in :ref:`internals_tracer` mechanism behind ``?_trace=1`` and the :ref:`setting_trace_debug` setting. Both continue to work exactly as before. - .. _internals_telemetry_turning_on: Turning tracing on @@ -2773,8 +2771,6 @@ Async version of :ref:`call_with_supported_arguments `__. The JSON output shows full details of every SQL query that was executed to generate the page. - -The `datasette-pretty-traces `__ plugin can be installed to provide a more readable display of this information. You can see `a demo of that here `__. - -You can add your own custom traces to the JSON output using the ``trace()`` context manager. This takes a string that identifies the type of trace being recorded, and records any keyword arguments as additional JSON keys on the resulting trace object. - -The start and end time, duration and a traceback of where the trace was executed will be automatically attached to the JSON object. - -This example uses trace to record the start, end and duration of any HTTP GET requests made using the function: - -.. code-block:: python - - from datasette.tracer import trace - import httpx - - - async def fetch_url(url): - with trace("fetch-url", url=url): - async with httpx.AsyncClient() as client: - return await client.get(url) - -.. _internals_tracer_trace_child_tasks: - -Tracing child tasks -------------------- - -If your code uses a mechanism such as ``asyncio.gather()`` to execute code in additional tasks you may find that some of the traces are missing from the display. - -You can use the ``trace_child_tasks()`` context manager to ensure these child tasks are correctly handled. - -.. code-block:: python - - from datasette import tracer - - with tracer.trace_child_tasks(): - results = await asyncio.gather( - # ... async tasks here - ) - -This example uses the :ref:`register_routes() ` plugin hook to add a page at ``/parallel-queries`` which executes two SQL queries in parallel using ``asyncio.gather()`` and returns their results. - -.. code-block:: python - - from datasette import hookimpl - from datasette import tracer - - - @hookimpl - def register_routes(): - async def parallel_queries(datasette): - db = datasette.get_database() - with tracer.trace_child_tasks(): - one, two = await asyncio.gather( - db.execute("select 1"), - db.execute("select 2"), - ) - return Response.json( - { - "one": one.single_value(), - "two": two.single_value(), - } - ) - - return [ - (r"/parallel-queries$", parallel_queries), - ] - -Note that running parallel SQL queries in this way has `been known to cause problems in the past `__, so treat this example with caution. - -Adding ``?_trace=1`` will show that the trace covers both of those child tasks. - .. _internals_shortcuts: Import shortcuts diff --git a/docs/introspection.rst b/docs/introspection.rst index 14b6249f..96504c08 100644 --- a/docs/introspection.rst +++ b/docs/introspection.rst @@ -124,7 +124,6 @@ Shows the :ref:`configuration ` for this instance of Datasette. T "ok": true, "settings": { "template_debug": true, - "trace_debug": true, "force_https_urls": true } } diff --git a/docs/json_api.rst b/docs/json_api.rst index a96fd73d..7ab4e72b 100644 --- a/docs/json_api.rst +++ b/docs/json_api.rst @@ -313,16 +313,6 @@ query string arguments: For how many seconds should this response be cached by HTTP proxies? Use ``?_ttl=0`` to disable HTTP caching entirely for this request. -``?_trace=1`` - Turns on tracing for this page: SQL queries executed during the request will - be gathered and included in the response, either in a new ``"_traces"`` key - for JSON responses or at the bottom of the page if the response is in HTML. - - The structure of the data returned here should be considered highly unstable - and very likely to change. - - Only available if the :ref:`setting_trace_debug` setting is enabled. - .. _json_api_extra: Expanding JSON responses diff --git a/docs/settings.rst b/docs/settings.rst index 9c114e4a..625da7d1 100644 --- a/docs/settings.rst +++ b/docs/settings.rst @@ -335,24 +335,6 @@ Some examples: * https://latest.datasette.io/fixtures?_context=1 * https://latest.datasette.io/fixtures/roadside_attractions?_context=1 -.. _setting_trace_debug: - -trace_debug -~~~~~~~~~~~ - -This setting enables appending ``?_trace=1`` to any page in order to see the SQL queries and other trace information that was used to generate that page. - -Enable it like this:: - - datasette mydatabase.db --setting trace_debug 1 - -Some examples: - -* https://latest.datasette.io/?_trace=1 -* https://latest.datasette.io/fixtures/roadside_attractions?_trace=1 - -See :ref:`internals_tracer` for details on how to hook into this mechanism as a plugin author. - .. _setting_base_url: base_url diff --git a/tests/conftest.py b/tests/conftest.py index b2453133..d1d60ebf 100644 --- a/tests/conftest.py +++ b/tests/conftest.py @@ -461,6 +461,5 @@ from .fixtures import ( # noqa: F401 app_client_two_attached_databases_one_immutable, app_client_with_cors, app_client_with_dot, - app_client_with_trace, make_app_client, ) diff --git a/tests/fixtures.py b/tests/fixtures.py index 83607c1a..e0fbb93e 100644 --- a/tests/fixtures.py +++ b/tests/fixtures.py @@ -230,12 +230,6 @@ def app_client_two_attached_databases_one_immutable(): yield client -@pytest.fixture(scope="session") -def app_client_with_trace(): - with make_app_client(settings={"trace_debug": True}, is_immutable=True) as client: - yield client - - @pytest.fixture(scope="session") def app_client_shorter_time_limit(): with make_app_client(20) as client: diff --git a/tests/plugins/my_plugin.py b/tests/plugins/my_plugin.py index baf20a77..d656b921 100644 --- a/tests/plugins/my_plugin.py +++ b/tests/plugins/my_plugin.py @@ -3,7 +3,7 @@ import base64 import json import urllib.parse -from datasette import hookimpl, tracer +from datasette import hookimpl from datasette.facets import Facet from datasette.permissions import Action from datasette.resources import DatabaseResource @@ -278,11 +278,10 @@ def register_routes(): async def parallel_queries(datasette): db = datasette.get_database() - with tracer.trace_child_tasks(): - one, two = await asyncio.gather( - db.execute("select coalesce(sleep(0.1), 1)"), - db.execute("select coalesce(sleep(0.1), 2)"), - ) + one, two = await asyncio.gather( + db.execute("select coalesce(sleep(0.1), 1)"), + db.execute("select coalesce(sleep(0.1), 2)"), + ) return Response.json({"one": one.single_value(), "two": two.single_value()}) return [ diff --git a/tests/test_api.py b/tests/test_api.py index 76c30e46..6fb88974 100644 --- a/tests/test_api.py +++ b/tests/test_api.py @@ -706,7 +706,6 @@ async def test_settings_json(ds_client): "truncate_cells_html": 2048, "force_https_urls": False, "template_debug": False, - "trace_debug": False, "base_url": "/", } diff --git a/tests/test_csv.py b/tests/test_csv.py index 7758a3c0..c1ab02ed 100644 --- a/tests/test_csv.py +++ b/tests/test_csv.py @@ -1,9 +1,9 @@ import urllib.parse import pytest -from bs4 import BeautifulSoup as Soup from datasette.app import Datasette +from datasette.telemetry_registry import DB_QUERY, DB_QUERY_TEXT EXPECTED_TABLE_CSV = """id,content 1,hello @@ -229,24 +229,43 @@ async def test_table_csv_stream(ds_client): assert len([b for b in response.content.split(b"\r\n") if b]) == 1002 -def test_csv_trace(app_client_with_trace): - response = app_client_with_trace.get("/fixtures/simple_primary_key.csv?_trace=1") - assert response.headers["content-type"] == "text/html; charset=utf-8" - soup = Soup(response.text, "html.parser") - assert ( - soup.find("textarea").text - == "id,content\r\n1,hello\r\n2,world\r\n3,\r\n4,RENDER_CELL_DEMO\r\n5,RENDER_CELL_ASYNC\r\n" - ) - assert "select id, content from simple_primary_key" in soup.find("pre").text +def db_query_texts(otel_spans): + "Every db.query.text recorded by a db.query span since the exporter was cleared." + return [ + span.attributes.get(DB_QUERY_TEXT, "") + for span in otel_spans.get_finished_spans() + if span.name == DB_QUERY + ] -def test_table_csv_stream_does_not_calculate_facets(app_client_with_trace): - response = app_client_with_trace.get("/fixtures/simple_primary_key.csv?_trace=1") - soup = Soup(response.text, "html.parser") - assert "select content, count(*) as n" not in soup.find("pre").text +# Both faceting and facet suggestion aggregate with a named count: facet +# results use "count(*) as count", suggestions use "count(*) as n". Matching +# on those rather than on a whole query string, because the surrounding SQL +# has been rewritten before - the previous version of this test looked for +# "select content, count(*) as n", which facet suggestion stopped emitting +# when it moved to a "with limited as (...)" CTE, leaving the assertion +# unable to fail. +FACET_QUERY_MARKERS = ("count(*) as n", "count(*) as count") -def test_table_csv_stream_does_not_calculate_counts(app_client_with_trace): - response = app_client_with_trace.get("/fixtures/simple_primary_key.csv?_trace=1") - soup = Soup(response.text, "html.parser") - assert "select count(*)" not in soup.find("pre").text +@pytest.mark.asyncio +async def test_table_csv_stream_does_not_calculate_facets(ds_client, otel_spans): + response = await ds_client.get("/fixtures/simple_primary_key.csv") + assert response.status_code == 200 + queries = db_query_texts(otel_spans) + # Guard: without this, a change that stopped the CSV route running any + # query at all - or that broke span capture - would leave the real + # assertion below trivially true. + assert any("from simple_primary_key" in q for q in queries), queries + assert not any( + marker in query for query in queries for marker in FACET_QUERY_MARKERS + ), queries + + +@pytest.mark.asyncio +async def test_table_csv_stream_does_not_calculate_counts(ds_client, otel_spans): + response = await ds_client.get("/fixtures/simple_primary_key.csv") + assert response.status_code == 200 + queries = db_query_texts(otel_spans) + assert any("from simple_primary_key" in q for q in queries), queries + assert not any("select count(*)" in q for q in queries), queries diff --git a/tests/test_html.py b/tests/test_html.py index 6a7b4907..54abc999 100644 --- a/tests/test_html.py +++ b/tests/test_html.py @@ -1141,8 +1141,13 @@ async def test_navigation_menu_links( @pytest.mark.asyncio -async def test_trace_correctly_escaped(ds_client): - response = await ds_client.get("/fixtures/-/query?sql=select+'

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

Hello'") assert "select '

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