Efcore: Logging: Design all up logging approach

[rowanmiller]

[divega]

We made some progress for beta but we'll keep this item active to track further work.

[Eilon]

Please keep me, @SonjaKhan, @davidfowl, and @lodejard in the loop on this because I would like @SonjaKhan to produce some guidance for the team as a whole as part of the core Logging work. We'd like to learn where each sub-team sees value in logging, and generalize it.

[rowanmiller]

We had an all up aspnet brownbag on this the other day

[rowanmiller]

We're not 100% happy with where we have landed - so we want to revisit this in 2.0. Next step is for @ajcvickers to prepare something for a design meeting.

[ajcvickers]

Logging Proposal for 2.0

Scoping and sugar

Principle: logging is something that is setup and configured for the application, not per context instance.

To achieve this we introduce some new configuration APIs that are associated with the service provider. This is effectively application-level, or EF-global level configuration, although bound to the service provider so as not to be truly global.

We run the code to set configuration for this only once when we first use a new service provider.

This existing configuration would move:

• WarningsConfiguration
• MaxPoolSize
• IsSensitiveDataLoggingEnabled
• LoggerFactory
• MemoryCache
• ReplaceService

This means that ILogger no longer needs to be a scoped service, which solves the problem of logging forcing other services to be scoped.

Consequence/limitation: we cannot log for only one context instance and not another. This is something that we support with EF6, but does not work well with the logger abstractions we have. It would likely be ugly to implement and need something like:

• A LoggerProvider that keeps track of the context instances for which logging is enabled, removing instances when contexts are disposed.
• Passing the context instance to each Log call in a well-known way to allow for filtering

It's probably not worth doing all of this, especially given that most code just logs everything to one log anyway. For things that need correlation, we can do it in a way that is more natural to the logging abstractions, such as the work that was already done for connections.

API

We could introduce a new "On..." method for this API, but this is probably not necessary. Instead we could hang it off of "OnConfiguring". The logging sugar API (Issue #1199) would also go here, since it is application/global configuration. Maybe something like this:

C# optionsBuilder .UseSqlServer(@"Server=(localdb)\mssqllocaldb;Database=Demo;") .GlobalConfiguration(b => b .EnableSensitiveDataLogging() .Log(message => Console.WriteLine(message)));
As stated above, this new builder would only be run once the first time a new service provider is used. This could be confusing in a similar way to OnModelCreating, but then creating a new "On..." method could also be confusing in the same way.

Logger names and event IDs

From the Logging docs:

• "Name your loggers with a distinct prefix so they can easily be filtered or disabled."
• "A logging event may specify an integer event id. Event ids should uniquely identify a logging publication call site within a logging category (i.e. the name passed to ILoggerFactory.CreateLogger when creating the logger instance)."

Proposal for names/categories

Create a hierarchy of categories that we think best matches the semantics of what people will want to filter on. For example:

• Everything EF logs starts with "Microsoft.EntityFrameworkCore"
• Within this, everything related to the store/database starts with "Microsoft.EntityFrameworkCore.Database"
• Within this, all SQL starts with "Microsoft.EntityFrameworkCore.Database.Sql"
  
  
  
  • Query would use: Microsoft.EntityFrameworkCore.Database.Sql.Query
  
  
  • Migrations would use: Microsoft.EntityFrameworkCore.Database.Sql.Migrations
  
  
  • Update pipeline would use: Microsoft.EntityFrameworkCore.Database.Sql.Update
  
  
• Within this, connection logs start with "Microsoft.EntityFrameworkCore.Database.Connection"
• And so on...

Now filtering can be done with a simple "StartsWith" call in a LoggerProvider. We can also add nice sugar for this when using our Log API.

Proposal for event IDs

• Based on definition above, event IDs are for identifying a call site; each call site should have a different ID.
• When database providers log to one of the categories above, they should do so using an event ID that does not collide with one we are using
• However, given that an application (service provider) can only be used with one database provider at a time, maybe it is okay to have the following distinctions:
  
  
  
  • A range of values to use for core EF code (10000-19999)
  
  
  • A range to use for relational code (20000-29999)
  
  
  • A range to use for providers (30000-39999)
  
  

The range from 0-9999 is not used so that code (most likely provider code) that does not follow this convention will still likely not cause collisions.

[MaherJendoubi]

@ajcvickers Would you explain "not per context instance."? Thanks.

[ajcvickers]

@MaherJendoubi I mean you can't register logging for a single instance of a DbContext but rather must register logging for all instances of DbContext that are associated with a given IServiceProvider.

[ajcvickers]

Notes from design meeting discussion:

• For the "global configuration" we will try separating this out into a new builder/method combination:
  
  
  
  • OnStartup on the context (for the OnConfiguring style of code)
  
  
  • AddEntityFrameworkOptions on the service collection (for the AddDbContext style of code)
  
  
• We could consider allowing global configuration of all the other options as well, but will defer this for now
• Providers will generally use the same categories as core/relational code uses, often by using the logger we supply
• For event IDs, we will extend the range used by providers (to make @AndriySvyryd happy) and add a constant somewhere in our code for the provider start value
• We will not attempt to have providers coordinate separate ranges--benefit not worth the cost
• We will have globally unique IDs in EF core and relational code, even though they only really need to be unique within the category.

[ajcvickers]

Proposal for logging categories

Notes:

• Just a proposal: for discussion in the design meeting.
• The principle here is to provide categories that allow for easy filtering by application code.
  
  
  
  • Preferably with StartsWith or EndsWith or a combination of the two
  
  
• There are obviously other dimensions that could be used--for example, should SQL be included in Query category?

Categories:

• Microsoft.EntityFrameworkCore.Database.Sql
  
  
  
  • ExecutedCommand
  
  
• Microsoft.EntityFrameworkCore.Database.Connection
  
  
  
  • OpeningConnection
  
  
  • ClosingConnection
  
  
• Microsoft.EntityFrameworkCore.Database.Transaction
  
  
  
  • TransactionIgnoredWarning
  
  
  • AmbientTransactionWarning
  
  
  • BeginningTransaction
  
  
  • CommittingTransaction
  
  
  • RollingbackTransaction
  
  
• Microsoft.EntityFrameworkCore.Update
  
  
  
  • SavedChanges
  
  
• Microsoft.EntityFrameworkCore.Model.Validation
  
  
  
  • All model validation messages
  
  
• Microsoft.EntityFrameworkCore.Query
  
  
  
  • IncludeIgnoredWarning
  
  
  • CompilingQueryModel
  
  
  • PossibleUnintendedUseOfEqualsWarning
  
  
  • QueryClientEvaluationWarning
  
  
  • IncludingNavigation
  
  
  • CompilingQueryModel
  
  
  • OptimizedQueryModel
  
  
  • QueryPlan
  
  
• Microsoft.EntityFrameworkCore.Infrastructure
  
  
  
  • ManyServiceProvidersCreated
  
  
  • ServiceProviderCreated
  
  
• Microsoft.EntityFrameworkCore.Scaffolding
  
  
  
  • SequenceMustBeNamedWarning, ColumnMustBeNamedWarning, etc.
  
  
• Microsoft.EntityFrameworkCore.Migrations
  
  
  
  • RevertingMigration
  
  
  • ApplyingMigration
  
  
  • MigrateUsingConnection
  
  
  • MigrateUsingConnection
  
  
  • GeneratingMigrationDownScript
  
  
  • GeneratingMigrationUpScript
  
  
  • ForeignMigrations
  
  
  • DestructiveOperation
  
  
  • ForceRemoveMigration
  
  
  • NoMigrationFile
  
  
  • NoSnapshotFile
  
  
  • RemovingMigration
  
  
  • RemovingSnapshot
  
  
  • RevertingSnapshot
  
  
  • ReusingSnapshotName
  
  
  • NoMigrationMetadataFile
  
  
  • ManuallyDeleted
  
  
  • WritingMigration
  
  
  • WritingSnapshot
  
  
  • ReusingNamespace
  
  
  • ReusingDirectory
  
  

[ajcvickers]

Updated categories above based on design meeting discussion. Only change was to remove the .Design subcategory since it was deemed unnecessary.