wrap timed streams and iterators in tracing::Spans; follow Opentelemetry conventions by zvkemp · Pull Request #3313 · transact-rs/sqlx

zvkemp · 2024-06-26T15:46:49Z

Does your PR solve an issue?

When exporting to instrumentation collectors, timed spans are generally more desirable than discrete events annotated with timing data. This PR:

wraps the existing logger and pool::acquire tracing events in tracing spans. Common metadata is moved to the span; generally the tracing subscriber can (and does by default in fmt::subscriber) write span-level metadata when events are logged, so the current output should be the same. The span level is set to the max level of the event log configuration, where appropriate.
Adds an associated NAME_LOWERCASE constant to Database, which follows the semantic conventions defined by Opentelemetry (https://opentelemetry.io/docs/specs/semconv/attributes-registry/db/). This value is attached to the span as db.system.

iamjpotts · 2024-08-15T20:52:42Z

-                        // Human-friendly - includes units (usually ms). Also kept for backward compatibility
-                        ?elapsed,
-                        // Search friendly - numeric
-                        elapsed_secs = elapsed.as_secs_f64(),


Removing elapsed and elapsed_secs is a breaking change to the instrumentation and reporting that others have built on top of existing sqlx logging.

Good ole' Hyrum's Law https://www.hyrumslaw.com/

Strictly speaking, we never made the exact format of log messages part of our API contract, but I'd also be pretty annoyed if this changed out from under me.

It'd also make me a hypocrite, given how the query macros came about.

Was hoping this would be rolled into the breaking-changes-allowed 8.x release, as it's a little superfluous to track timings in addition to the tracing span's own timing, but I certainly see how it's useful. Restored and rebased.

Thanks.

A standards based approach would certainly be better in the long run.

I have my own logging breaking change pr open - but its much smaller in scope and at @abonander's suggestion we tagged a few users who were interested to see if that break will affect them, as an alternative to maintaining two outputs.

The break that was in this PR (removing the elapses) would affect people.

Was hoping this would be rolled into the breaking-changes-allowed 8.x release

Yeah, to be perfectly honest, this PR required more thinking than I wanted to do while I was trying to wrap up 0.8.0.

At a certain point, I have to stop myself from looking at new PRs, or else I'll sit there forever trying to get every one of them merged before I kick out a release.

If we're happy calling this a breaking change, we can plan to land this for 0.9.0.

At a certain point, I have to stop myself from looking at new PRs, or else I'll sit there forever trying to get every one of them merged before I kick out a release.

Completely understand; hope you didn't take my comment as a criticism. Currently re-working this to not be a breaking change; the tracing span should be opt-in if it lands in 0.8, and whether or not that would change in 0.9 is an open question.

iamjpotts · 2024-09-06T15:18:35Z

+                         // Human-friendly - includes units (usually ms). Also kept for backward compatibility
+                         ?elapsed,
+                         // Search friendly - numeric
+                         elapsed_secs = elapsed.as_secs_f64(),


Indentation looks like it might trip up the format linting, and in any case for git history it would be nice to avoid reordering the fields.

Indentation addressed (sorry, the formatter is still not good at catching things in macro invocations). Can you clarify the issue with field ordering? The shared fields were moved into the span, but in the same order

Unfortunately the fields need to also be kept in the existing logging after being added to the new span.

Moving them from the individual log statement to the span changes the json structure that loggers like tracing-subscriber with the json feature will output - with that crate the items move from .fields to .span - which is good for standardization, but breaks existing consumers. We need both to avoid a breaking change.

I see, there doesn't currently seem to be a way to configure the json formatter to flatten the span fields into the event output (though maybe there should be?).

Would it be acceptable to gate some of this behavior behind a feature flag? It sounds like the span isn't really necessary for the slow query logger, and the event isn't really necessary for opentelemetry tracing. It would also be nice for those two things to work well together with a minimum of duplication.

The slow query logger can already be configured to never trigger.

For example, if span tracking was added, but no existing logging was diminished or removed, a crate user could set slow_statements_level to LevelFilter::Off and rely exclusively on metrics reported on the span for their monitoring and alerting.

I suppose that's true. I'm reusing this config to control span visibility as well, so I'll rework how that happens.

iamjpotts · 2024-09-06T17:59:34Z


-                if was_slow {
+                self.span.record("summary", summary);
+                self.span.record("db.statement", sql);


Something else to keep in mind, and may need adjustment here, is that logging the query isn't free.

Its not uncommon for select statements to exceed 25KB or 50KB or more, and 100% logging of those will have a materially negative impact on both the running application outputting the logs, and the log observer attempting to capture them.

This is why the current implementation only logs the query when the query is slow.

Yes, I'm taking that into account. The revised implementation will allow the span to be leveled individually, and the query will only be recorded if any of the events or spans are within the configured level.

zvkemp · 2024-09-06T19:25:15Z

I've pushed a new commit to refactor these changes; notably it allows setting a span level independently from the log level (defaults to Off, which creates a no-op span). This complicates the level checking a bit but should avoid doing unnecessary work or recording large fields when they aren't explicitly required by the configuration. Note that I haven't had a chance to validate these changes yet, but should be able to test it out soon.

iamjpotts · 2024-09-06T21:40:16Z

Great.

I'm interested in local validation also.

I think eventually my first iteration of the logging could be pared back in a 0.9 version of the crate. Spans are better conceptually and for standards, but we need to consider some of the conditional logging scenarios, and for now, some backwards compatibility.

I may get to it this weekend. Cheers.

sj-robert · 2026-03-19T20:48:51Z

Is this the only thing blocking 0.9.0? Because I am desperate for that release 😅 anything I can do to help?

abonander · 2026-04-14T18:56:04Z

I'm so sorry for letting this languish as long as I did, but unfortunately I don't think this is mergeable at this point:

Numerous merge conflicts.
The added span fields don't actually match the semantic conventions: https://opentelemetry.io/docs/specs/semconv/db/database-spans/
- db.system -> db.system.name
- db.statement -> db.query.text
- These could have simply been changed since this PR was opened but either way at this point they're outdated.
tracing::enabled!() is fundamentally broken and we need to stop using it: Nested event generation bypasses level filtering tokio-rs/tracing#2448 (comment)
I think we need to phase out dynamic event and span levels entirely because it isn't really idiomatic to tracing. Libraries are meant to hardcode the verbosity level and then the user is supposed to add filters for what they do and don't want to see in traces.

QueryLogger now opens a hardcoded INFO-level `db.query` span in `new()` that closes on drop, with field names following the OTel database span semantic conventions (`db.system.name`, `db.query.text`, `db.response.returned_rows`, `db.response.affected_rows`, `otel.kind = "client"`). The existing close-time event is emitted inside the span via `Span::in_scope` so callers get both — the span for OTel correlation, the event for the existing `rows_affected`/`elapsed_secs` fields under whatever level `LogSettings` configures. `QueryLogger::new` keeps its old signature; drivers attach the system name via the additive `with_db_system_name` builder, which records the `db.system.name` attribute on the already-open span. QueryLogger stores `Span`, not `EnteredSpan`, so it stays `Send` across the postgres/mysql `try_stream!` paths that broke transact-rs#3176. A small `InstrumentedStream` wrapper enters the span on each `poll_next` and drops the guard before returning, so no guard is held across an await. SQLite's synchronous `Iterator` path just relies on the close-event in-scope emission. Design constraints come from abonander's 2026-04-14 review on transact-rs#3313: current OTel semconv field names, no `tracing::enabled!()` (broken per tokio-rs/tracing#2448), hardcoded verbosity rather than runtime- configurable span levels.

QueryLogger now opens a hardcoded INFO-level `db.query` span in `new()` that closes on drop, with field names following the OTel database span semantic conventions (`db.system.name`, `db.query.text`, `db.response.returned_rows`, `db.response.affected_rows`, `otel.kind = "client"`). The existing close-time event is emitted inside the span via `Span::in_scope` so callers get both — the span for OTel correlation, the event for the existing `rows_affected`/`elapsed_secs` fields under whatever level `LogSettings` configures. `QueryLogger::new` keeps its old signature; drivers attach the system name via the additive `with_db_system_name` builder, which records the `db.system.name` attribute on the already-open span. QueryLogger stores `Span`, not `EnteredSpan`, so it stays `Send` across the postgres/mysql `try_stream!` paths that broke transact-rs#3176. A small `InstrumentedStream` wrapper (using `pin-project-lite`, already present transitively via the async runtimes) enters the span on each `poll_next` and drops the guard before returning, so no guard is held across an await. SQLite's synchronous `Iterator` path just relies on the close-event in-scope emission. Design constraints come from abonander's 2026-04-14 review on transact-rs#3313: current OTel semconv field names, no `tracing::enabled!()` (broken per tokio-rs/tracing#2448), hardcoded verbosity rather than runtime- configurable span levels.

zvkemp force-pushed the logging-conventions branch from d4738ae to 6f96abe Compare July 17, 2024 13:14

iamjpotts reviewed Aug 15, 2024

View reviewed changes

zvkemp force-pushed the logging-conventions branch 2 times, most recently from e632167 to a5a0a89 Compare September 6, 2024 14:58

iamjpotts reviewed Sep 6, 2024

View reviewed changes

zvkemp force-pushed the logging-conventions branch from a5a0a89 to 83a4f71 Compare September 6, 2024 15:45

wrap timed streams and iterators in tracing::Spans

21967bd

zvkemp force-pushed the logging-conventions branch from 83a4f71 to 21967bd Compare September 6, 2024 15:47

iamjpotts reviewed Sep 6, 2024

View reviewed changes

allow setting span level independently from log levels

40fc7e3

abonander added the breaking label Sep 7, 2024

abonander added this to the 0.9.0 milestone Sep 9, 2024

holmofy mentioned this pull request Oct 13, 2024

Integrate opentelemetry summer-rs/summer-rs#4

Open

abonander closed this Apr 14, 2026

Diggsey mentioned this pull request May 21, 2026

Open per-query tracing span in QueryLogger #4270

Open

Conversation

zvkemp commented Jun 26, 2024

Does your PR solve an issue?

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

zvkemp Sep 9, 2024 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

iamjpotts Sep 6, 2024 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

zvkemp commented Sep 6, 2024

Uh oh!

iamjpotts commented Sep 6, 2024

Uh oh!

sj-robert commented Mar 19, 2026

Uh oh!

abonander commented Apr 14, 2026

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

4 participants

zvkemp Sep 9, 2024 •

edited

Loading

iamjpotts Sep 6, 2024 •

edited

Loading