[Proposal] [Next] Query Logging Improvements

[abonander]

A lot of people will probably agree with me when I say there's room for improvement with how we currently log queries.

1. Logging is very noisy because we always print the whole query at INFO. I think at most we should be printing at INFO is the source file and line of the query (which we can do with #[track_caller] and std::panic::Location::caller()), maybe the first couple keywords in the query as context, and the time the query took. We should only be logging the full query (with parameters interpolated) at TRACE.

2. Logging is expensive because we pretty-print the SQL. I think we shouldn't be doing nearly that much to it. At most, we should be removing excess indentation so the query isn't weirdly left-padded in logs. I think sqlformat can help us there instead of rolling it ourselves. (cc @shssoichiro)

3. It doesn't make sense for ConnectOptions::{log_statements, log_slow_statements} to take a log::LevelFilter; instead, it should be Option<log::Level>. Then, if someone is using a crate like tracing that includes log but doesn't want to use log directly, they can still disable query logging by passing None (Add a way to disable query logging programmatically #939).

4. (Bug) we don't actually obey the log-level setting for sqlx::query, only the global log setting. This doesn't need to be in next, though; I'll be fixing it shortly. Done: fix(logging): make query logging obey level setting for sqlx::query target #945

[abonander]

I'm thinking we can change how much we log based on the log level set for sqlx::query:

At INFO, we only print a short summary of the query as mentioned in bullet point 1, so something like this:

[INFO sqlx::query] "SELECT foo, ... FROM bar ..." at src/db/my_query.rs:42 executed in 490.32ns

At DEBUG (and the slow-query logging at WARN or otherwise configured level), we print that plus query parameters:

[DEBUG sqlx::query] "SELECT foo, ... FROM bar ..." at src/db/my_query.rs:42 executed in 490.32ns; parameters: ["baz", 1234567, "2020-12-29T12:28:19-08:00"]

At TRACE, we print the whole query verbatim (only excess left-padding removed) with parameters interpolated:

[TRACE sqlx::query] query at src/db/my_query.rs:42 executed in 490.32ns:
SELECT 
    foo, 
    baz, 
    quux
FROM bar
WHERE 
    baz = 'baz' AND quux <> 1234567 AND created_at > `2020-12-29T12:28:19-08:00`
LIMIT 5

Thanks to #[track_caller], we can get source file and line info for both the query macros and functions.

[SomeoneToIgnore]

Looks great, thanks for coming with this up.
I have nothing to add to the issue message, but the first comment with the query format proposal looks worth discussing.

• On DEBUG level, to avoid accidentally printing a couple of thousands parameters, might be good to limit them with some arbitrary number.

• I like the idea to separate the verbosity levels and wonder if we should drag the separation further and split logging level and logging verbosity?

If I've understood the current proposal right, sqlx query verbosity changes depending on the log::Level we set for either.
With this model, would it ever be possible to WARN slow query with parameters in the log message? Maybe somebody would be insterested in logging the whole slow query with some non-TRACE level.

If you think that might make sense, consider keeping the log level just the log level and add some kind of verbosity parameter to the query settings builder, allowing to switch the formats.

==
Come to think of it, this separation might serve as a better compromise with non-log users due to being framework agnostic.

[abonander]

With this model, would it ever be possible to WARN slow query with parameters in the log message?

I didn't think of slow query logging when I wrote that out but yeah, it should definitely include the parameters so it's possible to repro the slowdown. So the slow query log at WARN should probably be the same format as DEBUG.

On DEBUG level, to avoid accidentally printing a couple of thousands parameters, might be good to limit them with some arbitrary number.

That's hard cause like, what arbitrary number is acceptable? What about for a slow-query log? Then you'd probably want all the parameters for reproducibility. Perhaps for slow-query logging we should have an option to dump the full query data with the complete SQL and all parameters to a file or some other sink.

[shssoichiro]

I like the ideas for INFO and TRACE, but I don't think printing parameters is a good idea. It has the potential for injecting PII into logs.

[abonander]

True, but it could come in handy for reproducing slow queries. Instead of changing output for DEBUG/WARN, maybe we have a setter on ConnectOptions?

/// Log query arguments (values substituted into value placeholders, i.e. `$N` / `?`).
///
/// ### Note: Beware of Personally Identifiable Information
/// This will likely expose personally identifiable information (PII), or otherwise infringe on privacy of users 
//// (which may be protected by law), if the logs are submitted to third-party providers like Sentry, Firebase, etc.
///
/// Take care when enabling this option.
pub fn log_arguments(&mut self, log_args: bool) -> &mut Self

As suggested in my previous comment, maybe we don't want to lean directly on log for saving reproducible queries but instead allow directly configuring a sink for query data for processing/storage.

[jkoudys]

@abonander big agree on the 2nd point. Personally I strongly dislike that the query is formatted at all -- we're losing valuable information in the logs! The original, unaltered string can have a lot of interesting hints at the cause of a problem that are simply being thrown away irrecoverably. I could always pipe the query through an sql formatter from vim if I really cared about it being pretty - taking that hit at runtime seems pointless. The query formatter it's running now is doing a full tokenization, which is so much more expensive than the remove-the-indent bit you suggest.

[SomeoneToIgnore]

So the slow query log at WARN should probably be the same format as DEBUG.

I presume, you have to do the same for Error level too then, keeping in mind that any user can change the log levels for both queries with the code like

let mut connection_options = MySqlConnectOptions::from_str(connection_url)?;
connection_options
    .log_statements(log::LevelFilter::Error)
    .log_slow_statements(log::LevelFilter::Error, Duration::from_secs(1));
let pool = MySqlPoolOptions::new().connect_with(connection_options).await?;

So, putting all formats and queries together, did I get you right:

	regular query format	slow query format
off	—	—
trace	full query, interpolated	full query, interpolated
debug	short summary + parameters	short summary + parameters
info	short summary	short summary + parameters
warn	short summary	short summary + parameters
error	short summary	short summary + parameters

?

For me, it's

• a bit odd to see inconsistent query formats on different log levels
• just odd to see a library behavior to change due to different log level (configurable via env variables!), I fail to recall any similar cases for libraries. Keeping in mind the performance issues, still looks like a footgun feature in general

Thus said, I still would have preferred something like enum QueryLogFormat { Full, WithParameters(Option<usize>), Summary, None } with the way to set it simiarly to the log::LevelFilter now + some reasonable defaults for both queries.

But the choice is yours after all, I won't insist on this point of view much 🙂

[SomeoneToIgnore]

what arbitrary number is acceptable? What about for a slow-query log?

I think you can either make it configurable, or just pick some arbitrary number (100?) and recommend to log the full log for all parameters.

Parameters' value inflate with their quantity drastically: 1-10 params can be valuable, but what about 1843, especially when they are displayed detached from the main query? :)

Then you'd probably want all the parameters for reproducibility. Perhaps for slow-query logging we should have an option to dump the full query data with the complete SQL and all parameters to a file or some other sink.

Great ideas in general, not sure if feasible to implement right away.
Slow sql detection + configurable query format + the pointer to the place where the query originates might be enough to cover the majority of the use cases.

I like the idea to try and be as failsafe as possible for the end user, but not sure it's possible in general to predict everything and log the query in the best possible format, keeping this whole shebang configurable might be just enough.

[shssoichiro]

I'm also +1 for making query logging configurable, perhaps as an option when building the sqlx Connection, with some sensible default. Probably we would want two parameters, one to configure the standard log level (defaults to either off or the short summary) and one to configure the slow query log level (defaults to the short summary).

[mehcode]

Let's take a step back here and go survey how other large SQL frameworks do this. Rails, Django, etc. There must be some inspiration on what works well to draw from.

[Fishrock123]

It would be nice if tracing events could be emitted alongside the logging events (with a separate loglevel) at some granularity.

We'd prefer this stuff in our honeycomb traces. I turn all the default "info" stuff from SQLx down to "debug" because it's not useful enough in production.