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

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

Hello'") assert "select '

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