diff --git a/datasette/database.py b/datasette/database.py index 38b38f48..1b9a5076 100644 --- a/datasette/database.py +++ b/datasette/database.py @@ -14,10 +14,10 @@ from pathlib import Path import sqlite_utils from opentelemetry import context as otel_context_api -from opentelemetry.trace import Status, StatusCode +from opentelemetry.trace import SpanKind, Status, StatusCode from .inspect import inspect_hash -from .telemetry import sql_attribute, tracer +from .telemetry import sql_attribute, sql_operation_name, tracer from .tracer import trace from .utils import ( call_with_supported_arguments, @@ -268,10 +268,13 @@ class Database: with trace( # noqa: SIM117 "sql", database=self.name, sql=sql.strip(), params=params ): - with tracer.start_as_current_span("db.query") as span: + with tracer.start_as_current_span("db.query", kind=SpanKind.CLIENT) 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("datasette.param_count", len(params)) results = await self.execute_write_fn( @@ -289,7 +292,11 @@ class Database: with trace( # noqa: SIM117 "sql", database=self.name, sql=sql.strip(), executescript=True ): - with tracer.start_as_current_span("db.query") as span: + # 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=SpanKind.CLIENT) as span: span.set_attribute("db.system", "sqlite") span.set_attribute("db.namespace", self.name) span.set_attribute("db.query.text", sql_attribute(sql)) @@ -317,11 +324,16 @@ class Database: with trace( "sql", database=self.name, sql=sql.strip(), executemany=True ) as kwargs: - with tracer.start_as_current_span("db.query") as span: + with tracer.start_as_current_span("db.query", kind=SpanKind.CLIENT) 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("datasette.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 ) @@ -632,8 +644,16 @@ class Database: custom_time_limit=None, page_size=None, log_sql_errors=True, + table=None, ): - """Executes sql against db_name in a thread""" + """Executes sql against db_name in a thread + + `table`, if passed, is recorded as the `db.collection.name` span + attribute. It exists for callers that already know which table the + query targets - the table and row views - and is never derived from + `sql` itself: deriving it would be a parse, and on an instance where + anyone can create a table the resulting value set has no ceiling. + """ self._check_not_closed() page_size = page_size or self.ds.page_size time_limit_ms = self.ds.sql_time_limit_ms @@ -698,6 +718,7 @@ class Database: # can be honoured - see the comment on the generic handler below. with tracer.start_as_current_span( "db.query", + kind=SpanKind.CLIENT, record_exception=False, set_status_on_exception=False, ) as span: @@ -705,6 +726,11 @@ class Database: span.set_attribute("db.namespace", self.name) span.set_attribute("db.query.text", sql_attribute(sql)) span.set_attribute("datasette.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("datasette.param_count", len(params)) try: diff --git a/datasette/telemetry.py b/datasette/telemetry.py index 6f5ed093..37195584 100644 --- a/datasette/telemetry.py +++ b/datasette/telemetry.py @@ -9,9 +9,34 @@ harness). With no provider installed every span produced here is a `NonRecordingSpan` and costs approximately nothing. """ +import re + from opentelemetry import trace as otel_trace -tracer = otel_trace.get_tracer("datasette") +from .version import __version__ + +# The semantic-convention version whose spellings this instrumentation +# actually emits. Deliberately NOT the latest release. +# +# A schema URL is a machine-readable claim: a consumer doing schema +# translation replays the renames between the declared version and the one +# it wants, so the claim has to name the version whose spellings are on the +# wire. A wrong one makes translation wrong rather than merely uninformative. +# +# Datasette emits `db.system`, which was renamed to `db.system.name` in +# semconv 1.30.0. Everything else it emits (`db.namespace`, `db.query.text`, +# `db.operation.name`, `db.collection.name`) has been current since 1.26.0. +# So 1.29.0 is the highest version at which every name emitted here is the +# current spelling. Everything under `datasette.*` is Datasette's own and +# outside semconv, so it is unaffected either way. +# +# Declaring 1.43.0 would be false about `db.system`, and would actively STOP +# a consumer translating it forward, because it asserts the rename already +# happened. Bump this deliberately, in the same commit as the attribute +# renames it implies - it is a claim about the names, not decoration. +SCHEMA_URL = "https://opentelemetry.io/schemas/1.29.0" + +tracer = otel_trace.get_tracer("datasette", __version__, schema_url=SCHEMA_URL) MAX_SQL_LENGTH = 2048 @@ -22,3 +47,65 @@ def sql_attribute(sql: str) -> str: if len(sql) <= MAX_SQL_LENGTH: return sql return sql[:MAX_SQL_LENGTH] + "…[truncated]" + + +# db.operation.name is the leading keyword of a statement matched against a +# fixed allowlist - deliberately not a parse. +# +# This runs against arbitrary user-supplied SQL (the `?sql=` query string, +# canned queries, anything typed into the query editor), and the attribute is +# a candidate dimension on a query-duration metric in a later phase. A metric +# series is keyed by its attribute values, so echoing back an arbitrary first +# token would let one visitor's typo mint a new, permanent series. The +# allowlist bounds that at a fixed, small set regardless of what anyone sends. +DB_OPERATION_ALLOWLIST = frozenset( + { + "SELECT", + "INSERT", + "UPDATE", + "DELETE", + "CREATE", + "DROP", + "ALTER", + "PRAGMA", + "EXPLAIN", + "REPLACE", + "VACUUM", + "ANALYZE", + "WITH", + } +) + +_LEADING_KEYWORD = re.compile(r"^\s*([A-Za-z]+)") + + +def sql_operation_name(sql: str) -> str | None: + """ + The statement's leading keyword, if it is one we recognise. + + Returns None - never a guess - for anything not on the allowlist, + including a statement that opens with a comment or with punctuation such + as the "(" of a parenthesised SELECT. + + Known limitation: a statement beginning with a CTE reports `WITH` rather + than the operation inside it, and a substantial share of Datasette's own + reads take that form. Extracting more than the leading keyword means + handling comment stripping, parenthesised `(SELECT ...) UNION` and + compound names like `CREATE TABLE` - each a special case a hand-rolled + matcher would accrete and eventually get wrong. Omitting a name beats + guessing at one. + + Only safe to call with a single statement: `execute_write_script()` runs + several separated by semicolons, and semantic conventions say + `db.operation.name` "SHOULD NOT be extracted from db.query.text, when the + database system supports query text with multiple operations in non-batch + operations" - so that call site does not use this at all rather than + reporting only the first statement's operation. + """ + match = _LEADING_KEYWORD.match(sql) + if not match: + return None + keyword = match.group(1).upper() + if keyword in DB_OPERATION_ALLOWLIST: + return keyword + return None diff --git a/datasette/views/row.py b/datasette/views/row.py index b1388299..b5196a83 100644 --- a/datasette/views/row.py +++ b/datasette/views/row.py @@ -407,7 +407,7 @@ class RowView(BaseView): raise Forbidden("You do not have permission to view this table") results = await resolved.db.execute( - resolved.sql, resolved.params, truncate=True + resolved.sql, resolved.params, truncate=True, table=table ) columns = [r[0] for r in results.description] rows = list(results.rows) @@ -652,6 +652,9 @@ class RowView(BaseView): ] ) try: + # No table= here: this counts incoming references across every + # foreign key pointing at this row, so it spans many tables and + # there is no single value db.collection.name could take. rows = list(await db.execute(sql, {"id": pk_values[0]})) except QueryInterrupted: # Almost certainly hit the timeout @@ -840,7 +843,7 @@ class RowUpdateView(BaseView): returned_row = None if data.get("return"): results = await resolved.db.execute( - resolved.sql, resolved.params, truncate=True + resolved.sql, resolved.params, truncate=True, table=resolved.table ) returned_row = results.dicts()[0] result["rows"] = [returned_row] @@ -858,7 +861,7 @@ class RowUpdateView(BaseView): message_row = returned_row if message_row is None: results = await resolved.db.execute( - resolved.sql, resolved.params, truncate=True + resolved.sql, resolved.params, truncate=True, table=resolved.table ) message_row = results.first() self.ds.add_message( diff --git a/datasette/views/table.py b/datasette/views/table.py index 7c814b27..6d920fd8 100644 --- a/datasette/views/table.py +++ b/datasette/views/table.py @@ -1170,6 +1170,7 @@ class TableInsertView(BaseView): "rowid, " if pks == ["rowid"] else "", table_name, where_clause ), args, + table=table_name, ) result["rows"] = fetched_rows.dicts() else: @@ -1382,7 +1383,9 @@ class TableDropView(BaseView): "database": database_name, "table": table_name, "row_count": ( - await db.execute(f"select count(*) from [{table_name}]") + await db.execute( + f"select count(*) from [{table_name}]", table=table_name + ) ).single_value(), "message": 'Pass "confirm": true to confirm', }, @@ -1576,7 +1579,10 @@ class TableAutocompleteView(BaseView): try: results = await db.execute( - sql, params, custom_time_limit=AUTOCOMPLETE_TIME_LIMIT_MS + sql, + params, + custom_time_limit=AUTOCOMPLETE_TIME_LIMIT_MS, + table=table_name, ) except QueryInterrupted: fallback_where = _autocomplete_prefix_like(pks[0]) @@ -1597,6 +1603,7 @@ class TableAutocompleteView(BaseView): fallback_sql, params, custom_time_limit=AUTOCOMPLETE_TIME_LIMIT_MS, + table=table_name, ) except QueryInterrupted: return Response.json({"ok": True, "rows": []}) @@ -2163,7 +2170,9 @@ async def table_view_data( # Execute the main query! try: - results = await db.execute(sql, params, truncate=True, **extra_args) + results = await db.execute( + sql, params, truncate=True, table=table_name, **extra_args + ) except (sqlite3.OperationalError, InvalidSql) as e: raise DatasetteError(str(e), title="Invalid SQL", status=400) @@ -2439,6 +2448,7 @@ async def _next_value_and_url( await db.execute( prefix_lookup_sql, {**{f"pk{i}": rows[-2][pk] for i, pk in enumerate(pks)}}, + table=table_name, ) ).single_value() if isinstance(prefix, dict) and "value" in prefix: diff --git a/tests/test_telemetry.py b/tests/test_telemetry.py index 7894670c..c49a11cf 100644 --- a/tests/test_telemetry.py +++ b/tests/test_telemetry.py @@ -7,11 +7,18 @@ import time import pytest import sqlite_utils from opentelemetry import trace as otel_trace -from opentelemetry.trace import StatusCode +from opentelemetry.trace import SpanKind, StatusCode from datasette.app import Datasette from datasette.database import Database -from datasette.telemetry import MAX_SQL_LENGTH, sql_attribute, tracer +from datasette.telemetry import ( + MAX_SQL_LENGTH, + SCHEMA_URL, + sql_attribute, + sql_operation_name, + tracer, +) +from datasette.version import __version__ SECRET_PARAM_VALUE = "SUPER_SECRET_PARAM_VALUE_XYZ_123" @@ -543,3 +550,201 @@ async def test_invoke_startup_produces_one_trace_not_dozens_of_orphans(otel_span assert all( _descends_from(span, startup.context, by_span_id) for span in write_spans ) + + +# --- Semantic conventions: span kind, scope, db.operation/collection ------- + + +@pytest.mark.asyncio +async def test_db_query_is_client_kind_and_children_are_internal(otel_spans): + """ + db.query is a database client span; Datasette's decomposition of it is not. + + Trace UIs key their database rendering off the span kind rather than off + db.system, so db.query has to be CLIENT. db.query.execute, + db.write.execute and db.write.queue_wait deliberately stay INTERNAL: they + are parts of one logical query rather than three separate database calls, + and queue_wait touches no database at all - marking them CLIENT would + make one query look like several to anything counting spans by kind. + """ + # Named in-memory databases are shared-cache, so this needs its own name. + db = Datasette(memory=True).add_memory_database("t06_span_kind") + # All four db.query entry points, so a missed `kind=` on any one of them + # fails here - plus the write path (db.write.queue_wait, + # db.write.execute) and the read path (db.query.execute) children. + await db.execute_write("create table docs (id integer primary key)") + await db.execute_write_many( + "insert into docs (id) values (?)", [[i] for i in range(1, 4)] + ) + await db.execute_write_script("insert into docs (id) values (99);") + await db.execute("select id from docs") + + query_spans = _spans_for_namespace(otel_spans, "t06_span_kind") + assert len(query_spans) == 4, "expected a db.query span per entry point" + for span in query_spans: + text = span.attributes["db.query.text"] + assert span.kind == SpanKind.CLIENT, f"db.query for {text!r} should be CLIENT" + + for name in ("db.query.execute", "db.write.execute", "db.write.queue_wait"): + children = [ + span for span in otel_spans.get_finished_spans() if span.name == name + ] + assert children, f"expected at least one {name} span" + for span in children: + assert span.kind == SpanKind.INTERNAL, f"{name} should be INTERNAL" + + +@pytest.mark.asyncio +async def test_instrumentation_scope_declares_version_and_schema_url( + ds_client, otel_spans +): + """ + Spans say which Datasette produced them and which semconv version their + attribute names follow. + + Before get_tracer() was given a version and a schema URL every exported + scope was name='datasette' version='' schema_url='', so nothing + downstream could tell which Datasette a span came from, or whether + `db.system` meant `db.system` or the post-1.30.0 `db.system.name`. + """ + response = await ds_client.get("/fixtures/-/query.json?sql=select+1") + assert response.status_code == 200 + + spans = _db_query_spans(otel_spans) + assert spans, "expected at least one db.query span" + scope = spans[-1].instrumentation_scope + + assert scope.name == "datasette" + assert scope.version == __version__ + # The literal URL, not the SCHEMA_URL constant: comparing the span + # against the same constant the instrumentation is built from would only + # catch a dropped argument, never a wrong value. Bumping this is a claim + # about the attribute names on the wire - see SCHEMA_URL in telemetry.py. + assert scope.schema_url == "https://opentelemetry.io/schemas/1.29.0" + assert SCHEMA_URL == "https://opentelemetry.io/schemas/1.29.0" + assert __version__, "the scope version must not be empty" + + +def test_db_operation_name_from_leading_keyword(): + assert sql_operation_name("select 1") == "SELECT" + assert sql_operation_name(" insert into x (a) values (1)") == "INSERT" + # A leading CTE reports WITH rather than the operation inside it. That is + # the documented limitation, not an accident - see sql_operation_name(). + assert sql_operation_name("with foo as (select 1) select * from foo") == "WITH" + # Unrecognised leading keyword: no attribute rather than a wrong one, and + # no unbounded value set derived from attacker-supplied SQL. + assert sql_operation_name("gibberish 1") is None + # Not a parser: a parenthesised SELECT and a leading comment both yield + # nothing rather than a guess. + assert sql_operation_name("(select 1) union select 2") is None + assert sql_operation_name("-- a comment\nselect 1") is None + assert sql_operation_name("") is None + + +@pytest.mark.asyncio +async def test_db_operation_name_on_real_span(ds_client, otel_spans): + response = await ds_client.get("/fixtures/-/query.json?sql=select+1") + assert response.status_code == 200 + + spans = [ + span + for span in _spans_for_namespace(otel_spans, "fixtures") + if span.attributes["db.query.text"] == "select 1" + ] + assert spans, "expected a db.query span for 'select 1'" + assert spans[-1].attributes["db.operation.name"] == "SELECT" + + +@pytest.mark.asyncio +async def test_execute_write_sets_db_operation_name(otel_spans): + db = Datasette(memory=True).add_memory_database("t06_write_operation") + await db.execute_write("create table docs (id integer primary key)") + await db.execute_write_many( + "insert into docs (id) values (?)", [[i] for i in range(1, 4)] + ) + + spans = _spans_for_namespace(otel_spans, "t06_write_operation") + by_operation = { + span.attributes["db.query.text"]: span.attributes.get("db.operation.name") + for span in spans + } + assert by_operation["create table docs (id integer primary key)"] == "CREATE" + assert by_operation["insert into docs (id) values (?)"] == "INSERT" + + +@pytest.mark.asyncio +async def test_execute_write_script_has_no_operation_name(otel_spans): + """ + executescript() runs several statements, so naming the operation after + the first one would be a lie. Semantic conventions say db.operation.name + should not be extracted from query text that can hold more than one + operation, so the attribute is absent entirely. + + The script deliberately starts with `create`, which *is* on the + allowlist - so this fails if the call site ever starts calling + sql_operation_name(). + """ + db = Datasette(memory=True).add_memory_database("t06_script_operation") + await db.execute_write_script( + "create table docs (id integer primary key);\n" + "insert into docs (id) values (1);" + ) + + spans = _spans_for_namespace(otel_spans, "t06_script_operation") + script_spans = [ + span for span in spans if span.attributes.get("datasette.executescript") is True + ] + assert len(script_spans) == 1 + assert "db.operation.name" not in script_spans[0].attributes + + +@pytest.mark.asyncio +async def test_db_collection_name_set_from_table_argument(ds_client, otel_spans): + db = ds_client.ds.get_database("fixtures") + await db.execute("select pk from facetable limit 1", table="facetable") + + spans = _spans_for_namespace(otel_spans, "fixtures") + assert spans + assert spans[-1].attributes["db.collection.name"] == "facetable" + + +@pytest.mark.asyncio +async def test_db_collection_name_absent_without_table_argument(ds_client, otel_spans): + """ + db.collection.name comes only from an explicit table= argument and is + never derived from the SQL. + + Deriving it would be a parse, and on an instance where anybody can create + a table the value set has no ceiling. Without this test the one above + would still pass if the table name were being read out of the query text. + """ + db = ds_client.ds.get_database("fixtures") + await db.execute("select pk from facetable limit 1") + + spans = _spans_for_namespace(otel_spans, "fixtures") + assert spans + span = spans[-1] + assert span.attributes["db.query.text"] == "select pk from facetable limit 1" + assert "db.collection.name" not in span.attributes + + +@pytest.mark.parametrize( + "path,table", + ( + ("/fixtures/facetable.json", "facetable"), + ("/fixtures/simple_primary_key/1.json", "simple_primary_key"), + ), +) +@pytest.mark.asyncio +async def test_table_and_row_pages_set_db_collection_name( + ds_client, otel_spans, path, table +): + "The table and row views know their table, so their queries carry it." + response = await ds_client.get(path) + assert response.status_code == 200 + + spans = _spans_for_namespace(otel_spans, "fixtures") + assert spans + assert any( + span.attributes.get("db.collection.name") == table for span in spans + ), f"expected a db.query span from {path} carrying db.collection.name"