Logging

Entity Framework Core makes use of the logging infrastructure of .NET Core. This can come in handy because it offers a glimpse (or even more) into what Entity Framework is doing, like the SQL it is generating, how long the operations take, etc.

The logging framework of .NET Core—used by Entity Framework Core—consists of the following:

• Logger factories: The top-level registration point. Normally, we can just use the built-in LoggerFactory and add logger providers to it.
• Logger providers: These are implementations of ILoggerProvider that are registered to the .NET Core-provided ILoggerFactory.
• Actual loggers: These are ILogger implementations returned by a logger provider, and do the actual logging.

A logger is returned for a concrete logger category. Logger categories come from infrastructure class names, the ones that provide the logging information. Because Entity Framework Core is built using a modular, layered approach, some of its operations will come from the datastore-agnostic core (DbContext, InternalQueryCompiler). Others will come from the relational layers (RelationalCommandBuilderFactory, RelationalModelValidator, SqlServerQueryCompilationContextFactory, SqlServerCompositeMethodCallTranslator), and finally, others will come from database-specific classes (SqlServerConnection).

Each logging entry actually consists of:

• Log Level: The severity of the log entry, such as Critical, Debug, Error, Information, or Trace.
• Event ID: A provider-specific code that represents the type of event being logged (more on this in a second).
• State: An optional contextual object to pass more information to the logger.
• Exception: An exception, to use in the case of an error (normally for the Critical or Error) log levels.
• Formatter: An optional formatter object to help format the log output, in cases where it is necessary.

The event ID is specific to the infrastructure. Some common values are as follows:

Table 6

In the case of relational data sources, these values are specified in the RelationalEventId enumeration. There is also CoreEventId for EF Core generic events (context initialized, etc.) and SqlServerRelationalId (for SQL Server-specific events, of course). Other databases will feature similar constants.

When we add logging to an Entity Framework context through the OnConfiguring method, we start to get things in the logging target of our choice—in this example, it is the console. For example, we issue a query such as this:

Code Listing  128

We're likely to get output like the following in the console:

info:

Microsoft.EntityFrameworkCore.Storage.Internal.RelationalCommandBuilderFactory[1]

   Executed DbCommand (2ms) [Parameters=[], CommandType='Text', CommandTimeout='30']

      SELECT [x].[ProjectId], [x].[Start]

      FROM [Project] AS [x]

      WHERE [x].[Start] = @__Today_0

Notice that the SQL does not include the actual filtering value (DateTime.Today); instead, it references the parameter name that was used. Besides the actual SQL, we can see that the execution took two milliseconds.

How do we interpret this? Well, first, we can see the log level, info in this case. Then we have the provider class that logged this (the category name), RelationalCommandBuilderFactory, and then the event inside [], which in this example is 1. Finally, we have the actual message, which is specific to the log event parameters (Executed DbCommand).

Microsoft makes some logging providers for .NET Core available:

Table 7

You can also write your own logging provider. You need to create a logging provider factory, register it with an Entity Framework Core context, and it will be used automatically. Here is an example for writing a (simple) log provider that calls a supplied delegate:

Code Listing  129

So, to add this provider, you need to do this:

Code Listing  130

You can either pass a filter to AddAction or not. If you don’t, anything will be logged.

Entity Framework Core will use the logger factory provided in the “default” dependency injection configuration, if you are using ASP.NET Core, but you can also provide your own, with your specific settings. For example, in .NET Core 2.x, you can filter out which events to log, based on the log category (the class name bound to the logger), the log level or the provider itself. For example, if you wish to log to the console all the SQL being produced by EF Core, you can do something like this:

Code Listing  131

So, the UseLoggerFactory method allows you to supply your own logger provider to a DbContext. You can both set it the way I’ve shown (using a DbContextOptionsBuilder<T>) or through the OnConfiguring method. The DbLoggerCategory class and its subclasses contain names for logger category names, and they are:

Table 8

The Name property contains the category name which is also output by the logger.

Finally, you can change the behavior of certain events–ignore, log, throw an exception–by making a call to ConfigureWarnings inside the OnConfiguring method:

Code Listing  132

Setting a default is as simple as this:

Code Listing  133

In this case, the default log behavior is to ignore everything and only log transaction commits.

Diagnostics

EF Core also leverages the diagnostics framework. In order to understand it, you must know that all .NET Core components produce diagnostic information (events), which can be consumed by listeners registered to the default DiagnosticListener (instantiated automatically and registered to the dependency injection framework). For example, EF Core produces events for the "Microsoft.EntityFrameworkCore.Database.Command.CommandExecuted" and "Microsoft.EntityFrameworkCore.Database.Command.CommandExecuting" occurrences. So, we can hook a listener to the DiagnosticListener, a reference to which we can obtain from the DI framework:

Code Listing  134

And a sample listener could look like this:

Code Listing  135

These two methods can be named whatever you want, but they must be decorated with [DiagnosticName] attributes with these names, and take the same-name parameters. When EF Core executes commands (SQL), they will be called, and the developer is even given a chance to modify the generated SQL or the parameters to the DbCommand.

There are many events that EF Core produces, and they match the names of RelationalEventId and CoreEventId (and SqlServerEventId, for SQL Server):

Table 9

These names should be meaningful enough for you to understand, but a problem with them is that they all take different parameters (the ones that need to go in the listener method marked with [DiagnosticName]). You will need to consult the documentation on each of these properties to find out which they are.