| title | description | author | ms.date | uid |
|---|---|---|---|---|
Simple logging - EF Core |
Logging from an EF Core DbContext using LogTo |
ajcvickers |
10/03/2020 |
core/logging-events-diagnostics/simple-logging |
Tip
You can download this article's sample from GitHub.
Entity Framework Core (EF Core) simple logging can be used to easily obtain logs while developing and debugging applications. This form of logging requires minimal configuration and no additional NuGet packages.
Tip
EF Core also integrates with Microsoft.Extensions.Logging, which requires more configuration, but is often more suitable for logging in production applications.
EF Core logs can be accessed from any type of application through the use of xref:Microsoft.EntityFrameworkCore.DbContextOptionsBuilder.LogTo%2A when configuring a DbContext instance. This configuration is commonly done in an override of xref:Microsoft.EntityFrameworkCore.DbContext.OnConfiguring%2A?displayProperty=nameWithType. For example:
[!code-csharpLogToConsole]
Alternately, LogTo can be called as part of xref:Microsoft.Extensions.DependencyInjection.EntityFrameworkServiceCollectionExtensions.AddDbContext%2A or when creating a xref:Microsoft.EntityFrameworkCore.DbContextOptions instance to pass to the DbContext constructor.
Tip
OnConfiguring is still called when AddDbContext is used or a DbContextOptions instance is passed to the DbContext constructor. This makes it the ideal place to apply context configuration regardless of how the DbContext is constructed.
LogTo requires an xref:System.Action%601 delegate that accepts a string. EF Core will call this delegate with a string for each log message generated. It is then up to the delegate to do something with the given message.
The xref:System.Console.WriteLine%2A?displayProperty=nameWithType method is often used for this delegate, as shown above. This results in each log message being written to the console.
xref:System.Diagnostics.Debug.WriteLine%2A?displayProperty=nameWithType can be used to send output to the Debug window in Visual Studio or other IDEs. Lambda syntax must be used in this case because the Debug class is compiled out of release builds. For example:
[!code-csharpLogToDebug]
Writing to a file requires creating a xref:System.IO.StreamWriter or similar for the file. The xref:System.IO.StreamWriter.WriteLine%2A method can then be used as in the other examples above. Remember to ensure the file is closed cleanly by disposing the writer when the context is disposed. For example:
[!code-csharpLogToFile]
Tip
Consider using Microsoft.Extensions.Logging for logging to files in production applications.
By default, EF Core will not include the values of any data in exception messages. This is because such data may be confidential, and could be revealed in production use if an exception is not handled.
However, knowing data values, especially for keys, can be very helpful when debugging. This can be enabled in EF Core by calling xref:Microsoft.EntityFrameworkCore.DbContextOptionsBuilder.EnableSensitiveDataLogging. For example:
[!code-csharpSensitiveDataLogging]
For performance reasons, EF Core does not wrap each call to read a value from the database provider in a try-catch block. However, this sometimes results in exceptions that are hard to diagnose, especially when the database returns a NULL when not allowed by the model.
Turning on xref:Microsoft.EntityFrameworkCore.DbContextOptionsBuilder.EnableDetailedErrors%2A will cause EF to introduce these try-catch blocks and thereby provide more detailed errors. For example:
[!code-csharpEnableDetailedErrors]
Every EF Core log message is assigned to a level defined by the xref:Microsoft.Extensions.Logging.LogLevel enum. By default, EF Core simple logging includes every message at Debug level or above. LogTo can be passed a higher minimum level to filter out some messages. For example, passing Information results in a minimal set of logs limited to database access and some housekeeping messages.
[!code-csharpInfoOnly]
Every log message is assigned an xref:Microsoft.Extensions.Logging.EventId. These IDs can be accessed from the xref:Microsoft.EntityFrameworkCore.Diagnostics.CoreEventId class or the xref:Microsoft.EntityFrameworkCore.Diagnostics.RelationalEventId class for relational-specific messages. A database provider may also have provider-specific IDs in a similar class. For example, xref:Microsoft.EntityFrameworkCore.Diagnostics.SqlServerEventId for the SQL Server provider.
LogTo can be configured to only log the messages associated with one or more event IDs. For example, to log only messages for the context being initialized or disposed:
[!code-csharpEventIds]
Every log message is assigned to a named hierarchical logger category. The categories are:
| Category | Messages |
|---|---|
| Microsoft.EntityFrameworkCore | All EF Core messages |
| Microsoft.EntityFrameworkCore.Database | All database interactions |
| Microsoft.EntityFrameworkCore.Database.Connection | Uses of a database connection |
| Microsoft.EntityFrameworkCore.Database.Command | Uses of a database command |
| Microsoft.EntityFrameworkCore.Database.Transaction | Uses of a database transaction |
| Microsoft.EntityFrameworkCore.Update | Saving entities, excluding database interactions |
| Microsoft.EntityFrameworkCore.Model | All model and metadata interactions |
| Microsoft.EntityFrameworkCore.Model.Validation | Model validation |
| Microsoft.EntityFrameworkCore.Query | Queries, excluding database interactions |
| Microsoft.EntityFrameworkCore.Infrastructure | General events, such as context creation |
| Microsoft.EntityFrameworkCore.Scaffolding | Database reverse engineering |
| Microsoft.EntityFrameworkCore.Migrations | Migrations |
| Microsoft.EntityFrameworkCore.ChangeTracking | Change tracking interactions |
LogTo can be configured to only log the messages from one or more categories. For example, to log only database interactions:
[!code-csharpDatabaseCategory]
Notice that the xref:Microsoft.EntityFrameworkCore.DbLoggerCategory class provides a hierarchical API for finding a category and avoids the need to hard-code strings.
Since categories are hierarchical, this example using the Database category will include all messages for the subcategories Database.Connection, Database.Command, and Database.Transaction.
LogTo allows a custom filter to be used for cases where none of the filtering options above are sufficient. For example, to log any message at level Information or above, as well as messages for opening and closing a connection:
[!code-csharpCustomFilter]
Tip
Filtering using custom filters or using any of the other options shown here is more efficient than filtering in the LogTo delegate. This is because if the filter determines the message should not be logged, then the log message is not even created.
The EF Core xref:Microsoft.EntityFrameworkCore.DbContextOptionsBuilder.ConfigureWarnings%2A API allows applications to change what happens when a specific event is encountered. This can be used to:
- Change the log level at which the event is logged
- Skip logging the event altogether
- Throw an exception when the event occurs
The previous example used a custom filter to log every message at LogLevel.Information as well as two events defined for LogLevel.Debug. The same can be achieved by changing the log level of the two Debug events to Information:
[!code-csharpChangeLogLevel]
In a similar way, an individual event can be suppressed from logging. This is particularly useful for ignoring a warning that has been reviewed and understood. For example:
[!code-csharpSuppressMessage]
Finally, EF Core can be configured to throw for a given event. This is particularly useful for changing a warning into an error. (Indeed, this was the original purpose of ConfigureWarnings method, hence the name.) For example:
[!code-csharpThrowForEvent]
The default content from LogTo is formatted across multiple lines. The first line contains message metadata:
- The xref:Microsoft.Extensions.Logging.LogLevel as a four-character prefix
- A local timestamp, formatted for the current culture
- The xref:Microsoft.Extensions.Logging.EventId in the form that can be copy/pasted to get the member from xref:Microsoft.EntityFrameworkCore.Diagnostics.CoreEventId or one of the other
EventIdclasses, plus the raw ID value - The event category, as described above.
For example:
info: 10/6/2020 10:52:45.581 RelationalEventId.CommandExecuted[20101] (Microsoft.EntityFrameworkCore.Database.Command)
Executed DbCommand (0ms) [Parameters=[], CommandType='Text', CommandTimeout='30']
CREATE TABLE "Blogs" (
"Id" INTEGER NOT NULL CONSTRAINT "PK_Blogs" PRIMARY KEY AUTOINCREMENT,
"Name" INTEGER NOT NULL
);
dbug: 10/6/2020 10:52:45.582 RelationalEventId.TransactionCommitting[20210] (Microsoft.EntityFrameworkCore.Database.Transaction)
Committing transaction.
dbug: 10/6/2020 10:52:45.585 RelationalEventId.TransactionCommitted[20202] (Microsoft.EntityFrameworkCore.Database.Transaction)
Committed transaction.
This content can be customized by passing values from xref:Microsoft.EntityFrameworkCore.Diagnostics.DbContextLoggerOptions, as shown in the following sections.
Tip
Consider using Microsoft.Extensions.Logging for more control over log formatting.
By default, timestamps are designed for local consumption while debugging. Use xref:Microsoft.EntityFrameworkCore.Diagnostics.DbContextLoggerOptions.DefaultWithUtcTime?displayProperty=nameWithType to use culture-agnostic UTC timestamps instead, but keep everything else the same. For example:
[!code-csharpUtc]
This example results in the following log formatting:
info: 2020-10-06T17:55:39.0333701Z RelationalEventId.CommandExecuted[20101] (Microsoft.EntityFrameworkCore.Database.Command)
Executed DbCommand (0ms) [Parameters=[], CommandType='Text', CommandTimeout='30']
CREATE TABLE "Blogs" (
"Id" INTEGER NOT NULL CONSTRAINT "PK_Blogs" PRIMARY KEY AUTOINCREMENT,
"Name" INTEGER NOT NULL
);
dbug: 2020-10-06T17:55:39.0333892Z RelationalEventId.TransactionCommitting[20210] (Microsoft.EntityFrameworkCore.Database.Transaction)
Committing transaction.
dbug: 2020-10-06T17:55:39.0351684Z RelationalEventId.TransactionCommitted[20202] (Microsoft.EntityFrameworkCore.Database.Transaction)
Committed transaction.
Sometimes it is useful to get exactly one line per log message. This can be enabled by xref:Microsoft.EntityFrameworkCore.Diagnostics.DbContextLoggerOptions.SingleLine?displayProperty=nameWithType. For example:
[!code-csharpSingleLine]
This example results in the following log formatting:
info: 10/6/2020 10:52:45.723 RelationalEventId.CommandExecuted[20101] (Microsoft.EntityFrameworkCore.Database.Command) -> Executed DbCommand (0ms) [Parameters=[], CommandType='Text', CommandTimeout='30']CREATE TABLE "Blogs" ( "Id" INTEGER NOT NULL CONSTRAINT "PK_Blogs" PRIMARY KEY AUTOINCREMENT, "Name" INTEGER NOT NULL);
dbug: 10/6/2020 10:52:45.723 RelationalEventId.TransactionCommitting[20210] (Microsoft.EntityFrameworkCore.Database.Transaction) -> Committing transaction.
dbug: 10/6/2020 10:52:45.725 RelationalEventId.TransactionCommitted[20202] (Microsoft.EntityFrameworkCore.Database.Transaction) -> Committed transaction.
Other flags in xref:Microsoft.EntityFrameworkCore.Diagnostics.DbContextLoggerOptions can be used to trim down the amount of metadata included in the log. This can be useful in conjunction with single-line logging. For example:
[!code-csharpTerseLogs]
This example results in the following log formatting:
2020-10-06T17:52:45.7320362Z -> Executed DbCommand (0ms) [Parameters=[], CommandType='Text', CommandTimeout='30']CREATE TABLE "Blogs" ( "Id" INTEGER NOT NULL CONSTRAINT "PK_Blogs" PRIMARY KEY AUTOINCREMENT, "Name" INTEGER NOT NULL);
2020-10-06T17:52:45.7320531Z -> Committing transaction.
2020-10-06T17:52:45.7339441Z -> Committed transaction.
EF Core simple logging differs from xref:System.Data.Entity.Database.Log?displayProperty=nameWithType in EF6 in two important ways:
- Log messages are not limited to only database interactions
- The logging must be configured at context initialization time
For the first difference, the filtering described above can be used to limit which messages are logged.
The second difference is an intentional change to improve performance by not generating log messages when they are not needed. However, it is still possible to get a similar behavior to EF6 by creating a Log property on your DbContext and then using it only when it has been set. For example:
[!code-csharpDatabaseLog]