Entity Framework Core Logging in details

Logging is an important aspect of any .NET app for debugging purpose. Through Logging we can generate SQL logs and Change Tracking information in Entity Framework Core. There are 2 types of logging in EF Core:

1. Simple logging
2. Microsoft.Extensions.Logging

Simple Logging

Entity Framework Core Simple Logging requires minimum configuration can log information to both Console and Files. EF Core logs can be accessed through the use of LogTo() method during override of DbContext.OnConfiguring method of DbContext class.

protected override void OnConfiguring(DbContextOptionsBuilder optionsBuilder)
    => optionsBuilder.LogTo(Console.WriteLine);

The above configuration will provide the logs in the console window as shown in the below image.

We can also enforce EF Core to direct logs to the debug window. The OnConfiguring method code in this case will be:

protected override void OnConfiguring(DbContextOptionsBuilder optionsBuilder)
    => optionsBuilder.LogTo(message => Debug.WriteLine(message));

Check the below image.

Logging to a file

The Entity Framework Logs can also be saved in a file. We will use StreamWriter class to save the logs to this file. The code for this is given below.

private readonly StreamWriter stream = new StreamWriter("mylog.txt", append: true);

protected override void OnConfiguring(DbContextOptionsBuilder optionsBuilder)
    => optionsBuilder.LogTo(stream.WriteLine);

public override void Dispose()
{
    base.Dispose();
    stream.Dispose();
}

public override async ValueTask DisposeAsync()
{
    await base.DisposeAsync();
    await stream.DisposeAsync();
}

Detailed Messages

EF Core does not include the values of any data in exception messages for security reason as these could be revealed in production use if developers forget to handle an exception. However for debugging you can enable these data by calling EnableSensitiveDataLogging() method. See the below code.

protected override void OnConfiguring(DbContextOptionsBuilder optionsBuilder)
    => optionsBuilder.LogTo(Console.WriteLine).EnableSensitiveDataLogging();

We can also enables detailed errors when handling of data value exceptions that occur during processing of query results. This can be done by the use of EnableSensitiveDataLogging() method.

protected override void OnConfiguring(DbContextOptionsBuilder optionsBuilder)
    => optionsBuilder.LogTo(Console.WriteLine).EnableDetailedErrors();

Filtering Log Messages

The LogLevel Enum defines different levels and these levels are assigned to every log messages. By default, EF Core simple logging provides messages in the Debug level or above. We can pass LogLevel Enum to LogTo method to filter out the messages. For example, passing LogLevel.Information results in logs related to database access and general flow of the application.

protected override void OnConfiguring(DbContextOptionsBuilder optionsBuilder)
    => optionsBuilder.LogTo(Console.WriteLine, LogLevel.Information);

The LogLevel Enum values are described below.

Every log message is assigned an EventId which consists of an “Id” property (Identifier), with the “Name” property (short description of event). The EventId can be accessed from the “CoreEventId” or the “RelationalEventId” class.

In the below example we have configured LogTo method to log messages for the context being initialized or disposed.

protected override void OnConfiguring(DbContextOptionsBuilder optionsBuilder)
    => optionsBuilder.LogTo(Console.WriteLine, new[] { CoreEventId.ContextDisposed, CoreEventId.ContextInitialized });

A database provider like SQL Server provider also have these IDs which in this case is the SqlServerEventId class. See the below example.

protected override void OnConfiguring(DbContextOptionsBuilder optionsBuilder)
    => optionsBuilder.LogTo(Console.WriteLine, new[] { SqlServerEventId.ForeignKeyReferencesMissingPrincipalTableWarning, SqlServerEventId.TableFound });

Each log message is also assigned a hierarchical logger category. The categories are.

The LogTo method can be configured to only log the messages from one or more categories. In the below example, we log only the database interactions.

protected override void OnConfiguring(DbContextOptionsBuilder optionsBuilder)
    => optionsBuilder.LogTo(Console.WriteLine, new[] { DbLoggerCategory.Database.Name });

Note that the DbLoggerCategory class is used to find a category and avoids the need to hard-code strings. The categories are hierarchical in nature so the Database category will include all messages for the subcategories Database.Connection, Database.Command, and Database.Transaction.

We can also define our custom filter for logging messages. It is a fast method since if the filter determines the message should not be logged, then the log message is not even created.

In the below example the log messages are displayed for Information level based on the Connection Opened and Closed scenarios.

protected override void OnConfiguring(DbContextOptionsBuilder optionsBuilder)
    => optionsBuilder
        .LogTo(
            Console.WriteLine,
            (eventId, logLevel) => logLevel >= LogLevel.Information
                                   || eventId == RelationalEventId.ConnectionOpened
                                   || eventId == RelationalEventId.ConnectionClosed);

Configuring Messages

We can also configure log messages as discussed below:

1. Change the log level
2. Skip logging
3. Throw an exception

In the below example we changed the log level of the two Debug events (RelationalEventId.ConnectionOpened, RelationalEventId.ConnectionClosed) to Information.

protected override void OnConfiguring(DbContextOptionsBuilder optionsBuilder)
    => optionsBuilder
        .ConfigureWarnings(
            b => b.Log(
                (RelationalEventId.ConnectionOpened, LogLevel.Information),
                (RelationalEventId.ConnectionClosed, LogLevel.Information)))
        .LogTo(Console.WriteLine, LogLevel.Information);

Certain conditions can be supressed from logging. Example below supressed CoreEventId.DetachedLazyLoadingWarning from loggging.

protected override void OnConfiguring(DbContextOptionsBuilder optionsBuilder)
    => optionsBuilder
        .ConfigureWarnings(b => b.Ignore(CoreEventId.DetachedLazyLoadingWarning))
        .LogTo(Console.WriteLine);

We can also raise errors when certain events happen. Below example shows throwing exception for RelationalEventId.MultipleCollectionIncludeWarning.

protected override void OnConfiguring(DbContextOptionsBuilder optionsBuilder)
    => optionsBuilder
        .ConfigureWarnings(b => b.Throw(RelationalEventId.MultipleCollectionIncludeWarning))
        .LogTo(Console.WriteLine);

We can include culture-agnostic UTC timestamps on log messages as shown below. This can be helpful during debugging process.

protected override void OnConfiguring(DbContextOptionsBuilder optionsBuilder)
    => optionsBuilder.LogTo(
        Console.WriteLine,
        LogLevel.Debug,
        DbContextLoggerOptions.DefaultWithUtcTime);

In the below example we will see exactly one line per log message.

protected override void OnConfiguring(DbContextOptionsBuilder optionsBuilder)
    => optionsBuilder.LogTo(
        Console.WriteLine,
        LogLevel.Debug,
        DbContextLoggerOptions.DefaultWithLocalTime | DbContextLoggerOptions.SingleLine);

We can also trim down the amount of metadata included in the log.

protected override void OnConfiguring(DbContextOptionsBuilder optionsBuilder)
    => optionsBuilder.LogTo(
        Console.WriteLine,
        LogLevel.Debug,
        DbContextLoggerOptions.UtcTime | DbContextLoggerOptions.SingleLine);

Microsoft.Extensions.Logging

Microsoft.Extensions.Logging should be used in Production where as use Simple logging in Development phase. By default all ASP.NET Core apps uses Microsoft.Extensions.Logging. To make Entity Framework Core to automatically use this logging method, their are 2 ways to do this.

Call AddDbContext or AddDbContextPool in the Program.cs for using in the dependency injection feature.

builder.Services.AddDbContext<CompanyContext>(options =>
  options.UseSqlServer(builder.Configuration.GetConnectionString("DefaultConnection")));

Next, on the Controller it is available through Dependency Injection using the ILogger interface as given below.

public class HomeController : Controller
{
    private readonly ILogger<HomeController> _logger;

    public HomeController(ILogger<HomeController> logger)
    {
        _logger = logger;
    }

    public IActionResult Index()
    {
        _logger.LogInformation("Inside the Index action");
        return View();
    }
}

In the DbContext, we create a ILoggerFactory object and store it as a static/global instance. Use it each time a DbContext is created by the use of UseLoggerFactory method. The instance of ILoggerFactory should then be registered with EF Core on the DbContextOptionsBuilder. Check the below code.

public static readonly ILoggerFactory MyLoggerFactory
    = LoggerFactory.Create(builder => { builder.AddConsole(); });

protected override void OnConfiguring(DbContextOptionsBuilder optionsBuilder)
    => optionsBuilder
        .UseLoggerFactory(MyLoggerFactory)
        .UseSqlServer(@"Server=(localdb)\mssqllocaldb;Database=Company;Trusted_Connection=True;ConnectRetryCount=0");

Sensitive Data & Detailed Exception

To view sensitive data use EnableSensitiveDataLogging method.

protected override void OnConfiguring(DbContextOptionsBuilder optionsBuilder)
     => optionsBuilder.UseLoggerFactory(MyLoggerFactory).EnableSensitiveDataLogging();

To view detailed messages use EnableDetailedErrors method.

protected override void OnConfiguring(DbContextOptionsBuilder optionsBuilder)
    => optionsBuilder.UseLoggerFactory(MyLoggerFactory).EnableDetailedErrors();