diff --git a/datasette/app.py b/datasette/app.py index 42be7425..d3626ab2 100644 --- a/datasette/app.py +++ b/datasette/app.py @@ -49,6 +49,7 @@ from .events import Event from .plugins import DEFAULT_PLUGINS, get_plugins, pm from .renderer import json_renderer from .resources import DatabaseResource, TableResource +from .telemetry import tracer from .tokens import TokenInvalid from .tracer import AsgiTracer from .url_builder import Urls @@ -778,57 +779,69 @@ class Datasette: # This must be called for Datasette to be in a usable state if self._startup_invoked: return - # Register event classes - event_classes = [] - for hook in pm.hook.register_events(datasette=self): - extra_classes = await await_me_maybe(hook) - if extra_classes: - event_classes.extend(extra_classes) - self.event_classes = tuple(event_classes) + # invoke_startup() runs before any request exists, so every span its + # children create - the register_* hook dispatches, the internal + # catalog's db.query/db.write spans, and the prepare_connection + # warm-up of the read connections those touch - would otherwise be + # its own orphan root trace: around twenty of them on a fresh + # instance. Bracketing the whole thing gives them somewhere to belong. + # A connection warmed lazily later, by a request touching a new + # database for the first time, nests under that request instead: + # this span has already ended by then. + with tracer.start_as_current_span("datasette.startup"): + # Register event classes + event_classes = [] + for hook in pm.hook.register_events(datasette=self): + extra_classes = await await_me_maybe(hook) + if extra_classes: + event_classes.extend(extra_classes) + self.event_classes = tuple(event_classes) - # Register actions, but watch out for duplicate name/abbr - action_names = {} - action_abbrs = {} - for hook in pm.hook.register_actions(datasette=self): - if hook: - for action in hook: - if ( - action.name in action_names - and action != action_names[action.name] - ): - raise StartupError(f"Duplicate action name: {action.name}") - if ( - action.abbr - and action.abbr in action_abbrs - and action != action_abbrs[action.abbr] - ): - raise StartupError(f"Duplicate action abbr: {action.abbr}") - action_names[action.name] = action - if action.abbr: - action_abbrs[action.abbr] = action - self.actions[action.name] = action + # Register actions, but watch out for duplicate name/abbr + action_names = {} + action_abbrs = {} + for hook in pm.hook.register_actions(datasette=self): + if hook: + for action in hook: + if ( + action.name in action_names + and action != action_names[action.name] + ): + raise StartupError(f"Duplicate action name: {action.name}") + if ( + action.abbr + and action.abbr in action_abbrs + and action != action_abbrs[action.abbr] + ): + raise StartupError(f"Duplicate action abbr: {action.abbr}") + action_names[action.name] = action + if action.abbr: + action_abbrs[action.abbr] = action + self.actions[action.name] = action - # Register column types (classes, not instances) - self._column_types = {} - for hook in pm.hook.register_column_types(datasette=self): - if hook: - for ct_cls in hook: - if ct_cls.name in self._column_types: - raise StartupError(f"Duplicate column type name: {ct_cls.name}") - self._column_types[ct_cls.name] = ct_cls + # Register column types (classes, not instances) + self._column_types = {} + for hook in pm.hook.register_column_types(datasette=self): + if hook: + for ct_cls in hook: + if ct_cls.name in self._column_types: + raise StartupError( + f"Duplicate column type name: {ct_cls.name}" + ) + self._column_types[ct_cls.name] = ct_cls - for hook in pm.hook.prepare_jinja2_environment( - env=self._jinja_env, datasette=self - ): - await await_me_maybe(hook) - # Ensure internal tables and metadata are populated before startup hooks - await self._refresh_schemas() - await self._save_queries_from_config() - # Load column_types from config into internal DB - await self._apply_column_types_config() - for hook in pm.hook.startup(datasette=self): - await await_me_maybe(hook) - self._startup_invoked = True + for hook in pm.hook.prepare_jinja2_environment( + env=self._jinja_env, datasette=self + ): + await await_me_maybe(hook) + # Ensure internal tables and metadata are populated before startup hooks + await self._refresh_schemas() + await self._save_queries_from_config() + # Load column_types from config into internal DB + await self._apply_column_types_config() + for hook in pm.hook.startup(datasette=self): + await await_me_maybe(hook) + self._startup_invoked = True def sign(self, value, namespace="default"): return URLSafeSerializer(self._secret, namespace).dumps(value) diff --git a/datasette/database.py b/datasette/database.py index d7cbc99b..38b38f48 100644 --- a/datasette/database.py +++ b/datasette/database.py @@ -496,8 +496,15 @@ class Database: try: conn = self.connect(write=True) # This warm-up runs before any write has ever been queued, so - # there is no caller otel context yet to attach - any spans - # created by plugin hooks here are orphans (roots). + # there is no captured caller context to attach - and a raw + # threading.Thread does not inherit the context of whoever started + # it. Spans created by plugin hooks here are therefore roots even + # when the write thread is started from inside invoke_startup(): + # its datasette.startup span is current on the event loop but does + # not cross this thread boundary. Read connections differ - they + # warm up inside executor tasks submitted with copy_context(), so + # their prepare_connection spans do nest under whoever triggered + # them. self.ds._prepare_connection(conn, self.name) except Exception as e: # noqa: BLE001 # Stored and re-raised to whoever queues the next write diff --git a/tests/test_telemetry.py b/tests/test_telemetry.py index f232a39d..7894670c 100644 --- a/tests/test_telemetry.py +++ b/tests/test_telemetry.py @@ -6,6 +6,7 @@ import time import pytest import sqlite_utils +from opentelemetry import trace as otel_trace from opentelemetry.trace import StatusCode from datasette.app import Datasette @@ -56,6 +57,27 @@ def _children_named(otel_spans, name, parent_span_context): ] +def _descends_from(span, ancestor_span_context, by_span_id): + """ + True if `span` reaches `ancestor_span_context` by walking parent links. + + Walks real span ids rather than trusting a shared trace id: a span can + carry the right trace id and still hang off the wrong parent. + """ + seen = set() + current = span + while current.parent is not None: + if current.parent.span_id == ancestor_span_context.span_id: + return current.parent.trace_id == ancestor_span_context.trace_id + if current.parent.span_id in seen: + return False + seen.add(current.parent.span_id) + current = by_span_id.get(current.parent.span_id) + if current is None: + return False + return False + + def _all_attribute_values(otel_spans): "Every attribute value across every finished span, for the 'no leaked param values' test." values = [] @@ -457,3 +479,67 @@ async def test_suppressed_error_does_not_mark_execute_span(ds_client, otel_spans span = execute_spans[-1] assert span.status.status_code == StatusCode.UNSET assert not [event for event in span.events if event.name == "exception"] + + +@pytest.mark.asyncio +async def test_invoke_startup_produces_one_trace_not_dozens_of_orphans(otel_spans): + """ + invoke_startup() runs with no request, so nothing it does has an ambient + span to nest under. Without datasette.startup every register_* hook, every + internal-catalog read and every catalog write becomes its own single-span + root trace - around twenty of them per fresh instance. + """ + ds = Datasette(memory=True) + # Named in-memory databases are shared-cache, so this needs its own name. + ds.add_memory_database("t05_startup_db") + # Constructing a Datasette already touches the internal catalog, and that + # work is genuinely outside startup. Clear so the assertions below describe + # invoke_startup() alone. + otel_spans.clear() + + # Deliberately no ambient span: this mirrors the ASGI lifespan path, where + # startup runs before any request exists. If something did wrap this call + # the "one root" assertion below would pass for the wrong reason. + assert ( + not otel_trace.get_current_span().get_span_context().is_valid + ), "this test must run with no ambient span" + + await ds.invoke_startup() + + spans = otel_spans.get_finished_spans() + assert len(spans) > 10, f"expected startup to emit many spans, got {len(spans)}" + + startup_spans = [span for span in spans if span.name == "datasette.startup"] + assert len(startup_spans) == 1 + startup = startup_spans[0] + assert startup.parent is None, "datasette.startup should be a root span" + + trace_ids = {span.context.trace_id for span in spans} + assert trace_ids == {startup.context.trace_id}, ( + f"startup produced {len(trace_ids)} distinct traces; every span it " + "causes should share the datasette.startup trace" + ) + + roots = [span for span in spans if span.parent is None] + assert [span.name for span in roots] == ["datasette.startup"] + + by_span_id = {span.context.span_id: span for span in spans} + + # The internal catalog reads are what made up the bulk of the orphans. + internal_queries = [ + span + for span in spans + if span.name == "db.query" and span.attributes["db.namespace"] == "__INTERNAL__" + ] + assert internal_queries, "expected internal-catalog db.query spans during startup" + assert all( + _descends_from(span, startup.context, by_span_id) for span in internal_queries + ) + + # ...and the catalog writes, which reach the span through the write thread, + # so they also prove the ticket-04 context capture survives startup. + write_spans = [span for span in spans if span.name.startswith("db.write.")] + assert write_spans, "expected db.write.* spans during startup" + assert all( + _descends_from(span, startup.context, by_span_id) for span in write_spans + )