SQL should be logged at debug level

[rgamage]

Note that this change was reverted before the final release of 3.0. Instead we made it easy to configure any event to log at any level. See #15888

---

Currently, if we implement logging filtered at the Information level, we get details of every EF SQL query. This is clearly debug or trace level data, not Information. It clutters everyone's logs, and is useless because the data is hiding the interesting things like id numbers, field values, etc.

What I'd like to see is these EF SQL details to be down-graded to Debug level.

[ajcvickers]

@DamianEdwards @davidfowl TL;DR Please let us know if we should not change the default log level for SQL to debug.

We've seen this feedback (SQL should be logged at debug) fairly consistently, and I think the general consensus on the team is we should change the level to debug. However, the decision to log SQL at info level was made by Project K at a higher level, so checking in with you guys before pulling the trigger.

[davidfowl]

I think its fine to make it debug by default. It would be nice if it was a different provider name (one that said something like "Microsoft.EntityFramework.Queries") that can be dialed up or down in configuration.

[ajcvickers]

@rgamage The default experience when running an ASP.NET app in production is to log at Warning level. Logging at Info level is the default only for development environments.

With the implementation of #14970 it is now possible to easily configure any EF event to log at any level. This is making us revisit again whether changing the default level for SQL is the correct thing to do. Can you provide some more details of when and why you are using Info level logging?

/cc @divega @Eilon @DamianEdwards

[fschlaef]

For anyone wanting to re-enable query logging without embedding configuration in DbContext (with Serilog for example, which is what I'm doing), the override you're looking for is Microsoft.EntityFrameworkCore.Database.Command

Excerpt from my Serilog conf :

"Serilog": {
    "MinimumLevel": {
      "Default": "Debug",
      "Override": {
        "System": "Information",
        "Microsoft": "Information",
        "Microsoft.EntityFrameworkCore.Database.Command": "Debug"
      }
    }
}

This pretty much restores the old behavior, while maintaining control over what is logged in config files.

Edit : big downside compared to old behavior : all queries are now logged twice (once for Executing DbCommand and once again for Executed DbCommand)

@ajcvickers how would you use CoreEventId in json config files for use with Serilog ?

[JonPSmith]

I agree with reducing the logging load because I have seen the impact of looging on performance. However I do think that having access to the database commands (typically SQL) that EF Core produces is very important. This is a great way to understand a database access, especially if you are looking to performance tune things. I recommend this to everyone who is concerned with EF Core performance.

The problems I see is the simple solution of setting the LogLevel to Debug would include a whole load of other Debug information (well, it does when I tried it). I am therefore looking at ways to isolate the database commands. Here are some solutions I came up with:

1. Use @fschlaef solution, i.e. filter by the EventId/Name. That works but needs a more complex setup.
2. My favourite would be all existing Debug level logging, apart from Executing DbCommand to the Trace level. I realise this might be too bigger change inside EF Core, but it would make life easier for EF Core users.
3. The final approach is to publicise the DiagnosticSource for getting database commands. I have no experience of using DiagnosticSource so I don't know if this is difficult for developers to use, but it was recommended to me in issue Request for better parameter infromation in CommandExecuted log output #15085.

[ajcvickers]

@JonPSmith As documented, you can change the level of only this event to whatever you want with something like this:

protected override void OnConfiguring(DbContextOptionsBuilder optionsBuilder)
    => optionsBuilder
        .UseSqlServer(connectionString)
        .ConfigureWarnings(c => c.Log((RelationalEventId.CommandExecuting, LogLevel.Info)));

[JonPSmith]

@ajcvickers, Sorry, I read the headline and didn't read further - my bad.

That is an acceptable fix and I'll try to publicise that when I'm writing about EF Core 3.

[ajcvickers]

Note: we are reverting this breaking change. See #15888

[ErikEJ]

Also update breaking changes docs?

[ajcvickers]

@ErikEJ Done, but haven't sent the PR yet.