Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Add a way to disable query logging programmatically #939

Merged
merged 2 commits into from
Dec 29, 2020
Merged

Add a way to disable query logging programmatically #939

merged 2 commits into from
Dec 29, 2020

Conversation

SomeoneToIgnore
Copy link
Contributor

I'd like to disable the query logging entirely due to #633 and a few other reasons.

Currently, it looks like I can do this two ways:

  • set RUST_LOG env variable or add more configuration into the logger directly: a fragile indirect way, since can be spoiled too easy and not verifiable by the compiler
  • use ConnectOptions-like trait for my db and pass the LevelFilter::Off there, which is good except for the fact that I use tracing instead of log and I need to drag in another dependency just to disable the logging.

This PR adds another method to ConnectOptions that allows disabling the logs without requiring somebody to use log crate for that.

@abonander
Copy link
Collaborator

abonander commented Dec 29, 2020

If you don't have logging enabled then we shouldn't be generating the logs anyway.

I think the real fix is to change this check here to log::log_enabled!(target: "sqlx::query", lvl). Then, if you're not even using the log crate it shouldn't matter.

IMO, we should also drop the default level here to LogLevelFilter::Debug or even ::Trace. It doesn't make sense to log full formatted queries at INFO.

@SomeoneToIgnore
Copy link
Contributor Author

SomeoneToIgnore commented Dec 29, 2020

Technically I do have the logging enabled, since tracing supports log crate logs too automatically with the default settings.

I have it + my RA_LOG set to info, all this combined makes sqlx think that it should log some statements, I believe.

I will check more later, but not sure I have to adjust that place you've pointed to.

@abonander
Copy link
Collaborator

Changing the default logging level to Debug or Trace would fix that. I'd rather fix the logging than add a redundant configuration method.

@SomeoneToIgnore
Copy link
Contributor Author

SomeoneToIgnore commented Dec 29, 2020

Changing the default logging level to Debug or Trace would fix that.

This is an incorrect statement, here's the code in question that I want to turn off:

if let Some(lvl) = lvl.to_level() {
if lvl <= log::STATIC_MAX_LEVEL && lvl <= log::max_level() {

First, it gets the log level (None is returned for the LogLevel::Off only) and then logs the statement if the log level is not big enough(?): anyway, I don't see any other way to disable it but just to actually call the corresponding config methods.

redundant configuration method

It could be redundant, if the query logging would have been disabled by default.
It is redundant for people who use log crate solemnly, but it's not for others, that's my whole point.

@SomeoneToIgnore
Copy link
Contributor Author

SomeoneToIgnore commented Dec 29, 2020

We can take a step back and discuss the issue more, if you don't like the method so much that you're eager to call it redundant.

My original issue, rephrased: I use tracing with an automatic log support (but I don't have log crate itself in my dependencies and don't want to have) + some regular RA_LOG setting.
sqlx, by deafult, starts to log the query statements that causes issues, I want to turn them off without using log crate in my dependencies.

How can I do that?
I see the following ways to tackle this, from less disruptive to the most one:

  • a new API method in the config, as in this PR
  • publicly reexport LogLevel in sqlx so that people are able to set the log level without the need to care about the log library they use
  • turn off the logging feature entirely by default

Any other thoughts?

@mehcode
Copy link
Member

mehcode commented Dec 29, 2020

I think I understand where you're coming from here.

    fn disable_statement_logging(&mut self) -> &mut Self {
        self.log_statements(LevelFilter::Off)
            .log_slow_statements(LevelFilter::Off, Duration::default())
    }

You want this so you don't need to have log in your direct dependencies. By itself, this does look redundant so I see where @abonander is coming from as well.

I think a nice compromise for now is to re-export LevelFilter from sqlx so logging can be configured.

To be honest, I'm not super happy with the logging configuration as it stands. We only have what we have to have something.

Can I ask why you want to disable the logging? Is it to remove the query formatting (which is somewhat slow)? As just hitting info! shouldn't matter if you have the level configured for SQLx to be higher than info.

Just checked the issue. Would a solution where we only log the query summary (avoiding sqlformat in the normal path) and execution time at info! work? And then you can enable a full SQL echo (off by default).

@abonander
Copy link
Collaborator

It's not worth arguing over a 3 line addition. I prefer this new method over debating about an appropriate place to reexport LevelFilter or reexporting the entire log crate.

@abonander abonander merged commit 7cb49d2 into launchbadge:master Dec 29, 2020
@SomeoneToIgnore SomeoneToIgnore deleted the disable-query-logging branch December 29, 2020 19:31
@SomeoneToIgnore
Copy link
Contributor Author

SomeoneToIgnore commented Dec 29, 2020

Thank you for your time on this and sorry if I had spent too much of your time on this.

Since you were curious anyway, one more big reason to turn off the query logging (besides the nasty perf issues) is the fact that they are printed multiline and HUGE:

[2020-12-29T19:17:24Z INFO  sqlx::query] insert into test_table(a) values …; rows: 0, elapsed: 4.115ms
    
    insert into
      test_table(a)
    values
      (?),
    (?),
    (?),
    (?),
    (?),
    (?),
    (?),
/// a thousand(s) of lines more

Note that there's no metadata to the left of the (?) and other query lines.
When the application is loaded properly and multiple concurrent requests log something, the log output with this sql gets messed up, it's hard to get a single query out of this, but when multiple big SQLs are logged simultaneously, no way you can distinguish one from another.
And then there's ELK and similar set-ups that just don't know what to do with the (?), log entries (especially if they are mixed with something else) and cannot properly group those logs.

So IMO the log printing feature brings lots of pain for real production with somewhat serious batch queries (1000 rows inserted at once is not that big IMO).
I love this feature when doing local investigations or development, but on prod it had brought us issues only alas.

Would a solution where we only log the query summary (avoiding sqlformat in the normal path) and execution time at info! work? And then you can enable a full SQL echo (off by default).

That might work, sure, "SQL echo off by default" is something I've expected to have with the current issues this feature has.

@abonander
Copy link
Collaborator

@SomeoneToIgnore typed up some thoughts in #942 if you'd like to weigh in

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging this pull request may close these issues.

3 participants