mirror of
https://github.com/simonw/datasette.git
synced 2026-09-03 15:14:08 +02:00
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 <textarea> debug page. That whole branch, including the EscapeHtmlWriter selection and the conditional content-type, is gone. The EscapeHtmlWriter class itself stays in datasette.utils - it is an importable public name and removing it would widen the API break. - .github/workflows/deploy-latest.yml no longer passes --setting trace_debug 1. Worth stating precisely, because the ticket claimed otherwise: this would not have broken the deploy. Setting.convert() in cli.py only rewrites a bare name to settings.<name> for *known* settings, so `--setting trace_debug 1` would have been silently accepted as a meaningless top-level config key. The flag is removed because it is dead, not because it errors. Tests. tests/test_tracer.py is deleted outright (6 items). Four other tests used ?_trace=1 as an assertion instrument rather than testing tracing: - test_csv_trace tested the trace mechanism itself - deleted. - test_table_csv_stream_does_not_calculate_facets, test_table_csv_stream_does_not_calculate_counts and test_nocount_nofacet_if_shape_is_object test real behaviour, and are rebuilt against captured spans. All three had silently stopped being able to fail: the facets test looked for "select content, count(*) as n", which facet suggestion has not emitted since it moved to a `with limited as (...)` CTE, and none of the three requested the count or facet work whose suppression they claim to check. The rebuilt versions ask for it explicitly, match strings the current SQL contains, and carry a guard assertion so an empty span list cannot masquerade as a pass. Each was confirmed to fail with the covered code broken. - test_trace_correctly_escaped is kept, renamed test_query_page_escapes_sql, with ?_trace=1 dropped. It ran against ds_client, which has no trace_debug, so it never exercised the tracer - what it actually covered is the query page echoing user SQL into HTML, the surface of the two reflected-XSS advisories in issue 1360, and nothing else in the suite covers it. Deleting it would have quietly dropped that. tests/test_utils.py's pairs_to_nested_config case used settings.trace_debug to check that a later key overrides an earlier one; it now uses template_debug rather than losing the case. Docs: the datasette.tracer section of internals.rst, the trace_debug section of settings.rst, the ?_trace=1 entries in json_api.rst and introspection.rst, and the regenerated cli-reference.rst. changelog.rst gets a breaking-change entry and keeps all its historical ?_trace=1 entries - two of them had to lose a :ref: role pointing at a label this commit deletes, or Sphinx warns on every build. 2368 passed, 39 skipped, 6 xfailed, 15 xpassed, 140 subtests, against 2375 / 141 before. Net -7 tests, fully accounted for: -6 test_tracer.py, -1 test_csv_trace, -1 test_trace_correctly_escaped, +1 test_query_page_escapes_sql. The lost subtest is the per-setting case trace_debug generated in test_settings_are_documented. Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
This commit is contained in:
Alex Garcia
parent
74cd01860f
commit
745b7872b8
21 changed files with 170 additions and 557 deletions
2
.github/workflows/deploy-latest.yml
vendored
2
.github/workflows/deploy-latest.yml
vendored
|
|
@ -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
|
||||
|
|
|
|||
|
|
@ -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],
|
||||
|
|
|
|||
|
|
@ -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
|
||||
|
|
|
|||
|
|
@ -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)
|
||||
|
|
@ -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)
|
||||
)
|
||||
|
|
|
|||
|
|
@ -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:
|
||||
|
|
|
|||
|
|
@ -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
|
||||
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
|
||||
|
|
|
|||
|
|
@ -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=/)
|
||||
|
||||
|
|
|
|||
|
|
@ -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
|
||||
|
|
|
|||
|
|
@ -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
|
||||
}
|
||||
}
|
||||
|
|
|
|||
|
|
@ -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
|
||||
|
|
|
|||
|
|
@ -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
|
||||
|
|
|
|||
|
|
@ -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,
|
||||
)
|
||||
|
|
|
|||
|
|
@ -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:
|
||||
|
|
|
|||
|
|
@ -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 [
|
||||
|
|
|
|||
|
|
@ -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": "/",
|
||||
}
|
||||
|
||||
|
|
|
|||
|
|
@ -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
|
||||
|
|
|
|||
|
|
@ -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 '<h1>Hello" in response.text
|
||||
|
||||
|
|
|
|||
|
|
@ -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
|
||||
|
|
|
|||
|
|
@ -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"]
|
||||
|
|
@ -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": {
|
||||
|
|
|
|||
Loading…
Add table
Add a link
Reference in a new issue