diff --git a/.changeset/statement-span-only.md b/.changeset/statement-span-only.md new file mode 100644 index 0000000..e0fd60e --- /dev/null +++ b/.changeset/statement-span-only.md @@ -0,0 +1,5 @@ +--- +"@maple-dev/effect-orm": minor +--- + +A statement's client span is now the only span it gets. It carries `db.query.text` (the statement as sent), and on failure `db.response.status_code` (the SQLSTATE) beside `error.type`, so the SQL driver's own span, which repeated the query text under the database name, runs untraced. Pass `driverSpans: true` to `fromSqlClient` to keep it as a child for what only the driver records, such as `server.address` or connection waits. `observe` runs inside the statement span, so attributes it annotates land there. Plain SQL (`Db.sql`) spans are named after the statement's leading operation and first table (`UPDATE items`) instead of the database system, with `db.operation.name` and `db.collection.name` to match. diff --git a/docs/database.md b/docs/database.md index bf14d00..a6f5337 100644 --- a/docs/database.md +++ b/docs/database.md @@ -305,7 +305,8 @@ fails at BEGIN today: through the query path with a syntax error, and through `a Each statement `Database` runs is one client span, named and attributed the way the [OpenTelemetry database conventions](https://opentelemetry.io/docs/specs/semconv/database/database-spans/) -describe. A compiled query knows its operation and table, so the span needs no SQL parsing: +describe. A compiled query knows its operation and table; for plain SQL (`Db.sql`) they are the +leading word and the first table the text names, as the conventions allow: | Attribute | Value | | --------------------------- | -------------------------------------------------------------------- | @@ -313,12 +314,26 @@ describe. A compiled query knows its operation and table, so the span needs no S | `db.operation.name` | `SELECT`, `INSERT`, `UPDATE` or `DELETE` | | `db.collection.name` | The `FROM` or written table; absent over a subquery, union or CTE | | `db.query.summary` | `SELECT events`, or the name given with `withQuerySummary` | +| `db.query.text` | The statement as sent: Postgres keeps `$n`; ClickHouse inlines values | | `db.response.returned_rows` | The rows it returned | | `error.type` | On failure: the `DatabaseError` reason, such as `SqlSyntaxError` | +| `db.response.status_code` | On failure: the SQLSTATE, when the server sent one | -The span is named after the summary, so a trace reads `SELECT events` rather than `sql.execute`. -Effect's own `sql.execute` span runs inside it and carries the query text. To give a group of -statements a stable name of your own, wrap them: +The span is named after the summary, so a trace reads `SELECT events` rather than the database +name. It is the only span a statement gets: the SQL driver's own span would repeat the query text, +so the driver runs untraced. Pass `driverSpans: true` to `fromSqlClient` to keep it as a child, for +what only the driver records (`server.address`, connection waits). + +Attributes of your own go on the same span from `observe`, which runs inside it: + +```ts +Db.fromSqlClient(sql, { + dialect: postgresDialect, + observe: () => Effect.annotateCurrentSpan("peer.service", "orders-postgres"), +}) +``` + +To give a group of statements a stable name of your own, wrap them: ```ts Db.run(query, params).pipe(Db.withQuerySummary("dashboard.revenue_by_day")) diff --git a/src/database/database.ts b/src/database/database.ts index 3a94eaa..104d1c8 100644 --- a/src/database/database.ts +++ b/src/database/database.ts @@ -154,6 +154,13 @@ export interface FromSqlClientOptions { * into one span or log line per request. */ readonly observe?: (statement: Statement) => Effect.Effect + /** + * Keep the SQL driver's own span inside each statement span. Off by default: + * the statement span already carries the query text, so the driver's span is + * a second span per statement with nothing new. Turn it on to also get what + * only the driver records, such as `server.address` or connection waits. + */ + readonly driverSpans?: boolean /** * Refuse, as a `TenantScopeViolation` defect, any compiled statement whose * `tenantScope` is `"cross-tenant"` unless it was declared with @@ -208,6 +215,9 @@ export const fromSqlClient = (sql: SqlClient.SqlClient, options: FromSqlClientOp const capabilities = dialect.transactions ?? noTransactions const command = options.command ?? ((effect) => effect) const observe = options.observe ?? (() => Effect.void) + // The statement span is the span: the driver's own runs untraced unless asked for. + const driver = (effect: Effect.Effect): Effect.Effect => + options.driverSpans === true ? effect : Effect.withTracerEnabled(effect, false) // Result names exactly as the server sent them: the compiled decoder reads // the aliases it wrote. const raw = sql.withoutTransforms() @@ -249,7 +259,7 @@ export const fromSqlClient = (sql: SqlClient.SqlClient, options: FromSqlClientOp dialect, statement, guard(statement).pipe( - Effect.andThen(raw.unsafe>(statement.sql, statement.parameters ?? [])), + Effect.andThen(driver(raw.unsafe>(statement.sql, statement.parameters ?? []))), Effect.map((rows): ReadonlyArray> => rows), Effect.mapError(toDatabaseError(statement.sql)), ), @@ -282,7 +292,7 @@ export const fromSqlClient = (sql: SqlClient.SqlClient, options: FromSqlClientOp dialect, resolved, guard(resolved).pipe( - Effect.andThen(command(raw.unsafe(resolved.sql, resolved.parameters ?? []))), + Effect.andThen(driver(command(raw.unsafe(resolved.sql, resolved.parameters ?? [])))), Effect.asVoid, Effect.mapError(toDatabaseError(resolved.sql)), ), diff --git a/src/database/tracing.test.ts b/src/database/tracing.test.ts index d878538..14e1735 100644 --- a/src/database/tracing.test.ts +++ b/src/database/tracing.test.ts @@ -17,12 +17,18 @@ const recording = Tracer.make({ }, }) -const Live = Layer.effect( - Db.Database, - Effect.gen(function* () { - return Db.fromSqlClient(yield* SqlClient.SqlClient, { dialect: postgresDialect }) - }), -).pipe(Layer.provideMerge(PgliteClient.layer({ postgresqlconf: "timezone = 'UTC'" }))) +const liveWith = (options: Omit = {}) => + Layer.effect( + Db.Database, + Effect.gen(function* () { + return Db.fromSqlClient(yield* SqlClient.SqlClient, { dialect: postgresDialect, ...options }) + }), + ).pipe(Layer.provideMerge(PgliteClient.layer({ postgresqlconf: "timezone = 'UTC'" }))) + +const Live = liveWith({ + // What a consumer adds to every statement span from `observe`. + observe: () => Effect.annotateCurrentSpan("peer.service", "test-postgres"), +}) const Items = PG.table("traced_items", { columns: { id: PG.int4, name: PG.text }, primaryKey: ["id"] }) @@ -60,11 +66,12 @@ layer(Live)("Database statement spans", (it) => { "db.collection.name": "traced_items", "db.query.summary": "SELECT traced_items", "db.response.returned_rows": 0, + "peer.service": "test-postgres", }) - // Effect's own span runs inside it, carrying the query text. - const execute = spans.find((s) => s.attributes.has("effect.sql.method")) - assert(execute !== undefined) - expect(Option.getOrUndefined(execute.parent)).toBe(span) + // The parameterized text, not the values bound to it. + expect(span.attributes.get("db.query.text")).toMatch(/^SELECT[\s\S]+"traced_items"[\s\S]+\$1/) + // The statement span is the only one: the driver's runs untraced. + expect(spans.filter((s) => s.attributes.has("effect.sql.method"))).toEqual([]) }), ) @@ -91,6 +98,29 @@ layer(Live)("Database statement spans", (it) => { }), ) + it.effect("names plain SQL after its leading operation and first table", () => + Effect.gen(function* () { + const { exit, spans } = yield* traced(Db.execute(Db.sql`UPDATE traced_items SET name = ${"x"} WHERE id = ${2}`)) + assert(Exit.isSuccess(exit)) + const span = dbSpan(spans) + expect(span.name).toBe("UPDATE traced_items") + expect(Object.fromEntries(span.attributes)).toMatchObject({ + "db.operation.name": "UPDATE", + "db.collection.name": "traced_items", + "db.query.summary": "UPDATE traced_items", + }) + }), + ) + + it.effect("names plain SQL without a table after its operation alone", () => + Effect.gen(function* () { + const { spans } = yield* traced(Db.execute(Db.sql`SELECT pg_advisory_xact_lock(${1})`)) + const span = dbSpan(spans) + expect(span.name).toBe("SELECT") + expect(span.attributes.has("db.collection.name")).toBe(false) + }), + ) + it.effect("takes the summary from withQuerySummary", () => Effect.gen(function* () { const { spans } = yield* traced( @@ -109,11 +139,25 @@ layer(Live)("Database statement spans", (it) => { assert(Exit.isFailure(exit)) const span = dbSpan(spans) expect(span.attributes.get("error.type")).toBe("SqlSyntaxError") + expect(span.attributes.get("db.response.status_code")).toBe("42601") expect(span.status._tag).toBe("Ended") }), ) }) +layer(liveWith({ driverSpans: true }))("Database statement spans with driverSpans", (it) => { + it.effect("keeps the driver's span inside the statement span", () => + Effect.gen(function* () { + const { exit, spans } = yield* traced(Db.execute(Db.sql`SELECT 1`)) + assert(Exit.isSuccess(exit)) + const span = dbSpan(spans) + const driver = spans.find((s) => s.attributes.has("effect.sql.method")) + assert(driver !== undefined) + expect(Option.getOrUndefined(driver.parent)).toBe(span) + }), + ) +}) + describe("collection", () => { it("is the FROM table, or the written table, and absent otherwise", () => { const select = PG.compileUnsafe(PG.from(Items).select(($) => ({ id: $.id }))) diff --git a/src/database/tracing.ts b/src/database/tracing.ts index 5372ae8..f989f4b 100644 --- a/src/database/tracing.ts +++ b/src/database/tracing.ts @@ -2,9 +2,9 @@ // database semantic conventions describe: // https://opentelemetry.io/docs/specs/semconv/database/database-spans/ // -// Effect's own span still runs inside it with the query text, but it cannot -// carry these: it is named after the database, not the operation, and only a -// compiled query knows its table. +// It is the only span a statement gets: it carries the query text, so the SQL +// driver's own span (named after the database, not the operation, and blind to +// the table) runs untraced unless `driverSpans` asks for it. import { Context, Effect } from "effect" import type { CompiledQuery } from "../ch/compile" import type { Dialect } from "../ch/dialect" @@ -40,6 +40,20 @@ const OPERATIONS: Record, string> = { delete: "DELETE", } +// Plain SQL has no compiled operation or table, so they are read off its text, +// as the conventions allow: the first operation and the first collection named. +const LEADING_WORD = /^\s*(\w+)/ +const FIRST_TABLE = /(?:from|into|update|join|table)\s+\W?([\w.]+)/i + +/** The operation and table a statement names: compiled, or read off plain SQL. */ +const describeStatement = (statement: TracedStatement): { operation?: string; collection?: string } => { + if (statement.kind !== undefined) return { operation: OPERATIONS[statement.kind], collection: statement.collection } + return { + operation: LEADING_WORD.exec(statement.sql)?.[1]?.toUpperCase(), + collection: FIRST_TABLE.exec(statement.sql)?.[1], + } +} + /** * Runs `effect`, which sends `statement`, in its client span. The span name is * the summary when there is one, then `{operation} {table}`, then the system. @@ -54,19 +68,24 @@ export const traceStatement = ( Effect.withFiber((fiber) => { const configured = fiber.getRef(QuerySummary) const system = SYSTEM_NAMES[dialect.name] ?? dialect.name - const operation = statement.kind === undefined ? undefined : OPERATIONS[statement.kind] + const { operation, collection } = describeStatement(statement) const summary = - configured ?? (operation === undefined ? undefined : statement.collection === undefined ? operation : `${operation} ${statement.collection}`) - const attributes: Record = { "db.system.name": system } + configured ?? (operation === undefined ? undefined : collection === undefined ? operation : `${operation} ${collection}`) + const attributes: Record = { "db.system.name": system, "db.query.text": statement.sql } if (operation !== undefined) attributes["db.operation.name"] = operation - if (statement.collection !== undefined) attributes["db.collection.name"] = statement.collection + if (collection !== undefined) attributes["db.collection.name"] = collection if (summary !== undefined) attributes["db.query.summary"] = summary return effect.pipe( Effect.tap((result) => rowsOf === undefined ? Effect.void : Effect.annotateCurrentSpan("db.response.returned_rows", rowsOf(result)), ), // `error.type` is the failure's class: a DatabaseError's reason, else its tag. + // `db.response.status_code` is the SQLSTATE, when the server sent one. Effect.tapError((error) => { + const sqlState = + typeof error === "object" && error !== null && "sqlState" in error && typeof error.sqlState === "string" + ? error.sqlState + : undefined const reason = typeof error === "object" && error !== null ? "reason" in error && typeof error.reason === "string" @@ -75,7 +94,10 @@ export const traceStatement = ( ? error._tag : undefined : undefined - return reason === undefined ? Effect.void : Effect.annotateCurrentSpan("error.type", reason) + const failure: Record = {} + if (reason !== undefined) failure["error.type"] = reason + if (sqlState !== undefined) failure["db.response.status_code"] = sqlState + return Effect.annotateCurrentSpan(failure) }), Effect.withSpan(summary ?? system, { kind: "client", attributes }), )