Logging and Intercepting Database Operations (EF6 Onwards)

Notice that context.Database.Log is set to Console.Write. This is all that is needed to log SQL to the console.

Example output

Let’s add some simple query/insert/update code so that we can see some output:

using (var context = new BlogContext()) 
{ 
    context.Database.Log = Console.Write; 
 
    var blog = context.Blogs.First(b => b.Title == "One Unicorn"); 
 
    blog.Posts.First().Title = "Green Eggs and Ham"; 
 
    blog.Posts.Add(new Post { Title = "I do not like them!" }); 
 
    context.SaveChangesAsync().Wait(); 
}

This will generate the following output:

SELECT TOP (1)
    [Extent1].[Id] AS [Id],
    [Extent1].[Title] AS [Title]
    FROM [dbo].[Blogs] AS [Extent1]
    WHERE (N‘One Unicorn‘ = [Extent1].[Title]) AND ([Extent1].[Title] IS NOT NULL)
-- Executing at 10/8/2013 10:55:41 AM -07:00
-- Completed in 4 ms with result: SqlDataReader

SELECT
    [Extent1].[Id] AS [Id],
    [Extent1].[Title] AS [Title],
    [Extent1].[BlogId] AS [BlogId]
    FROM [dbo].[Posts] AS [Extent1]
    WHERE [Extent1].[BlogId] = @EntityKeyValue1
-- EntityKeyValue1: ‘1‘ (Type = Int32)
-- Executing at 10/8/2013 10:55:41 AM -07:00
-- Completed in 2 ms with result: SqlDataReader

UPDATE [dbo].[Posts]
SET [Title] = @0
WHERE ([Id] = @1)
-- @0: ‘Green Eggs and Ham‘ (Type = String, Size = -1)
-- @1: ‘1‘ (Type = Int32)
-- Executing asynchronously at 10/8/2013 10:55:41 AM -07:00
-- Completed in 12 ms with result: 1

INSERT [dbo].[Posts]([Title], [BlogId])
VALUES (@0, @1)
SELECT [Id]
FROM [dbo].[Posts]
WHERE @@ROWCOUNT > 0 AND [Id] = scope_identity()
-- @0: ‘I do not like them!‘ (Type = String, Size = -1)
-- @1: ‘1‘ (Type = Int32)
-- Executing asynchronously at 10/8/2013 10:55:41 AM -07:00
-- Completed in 2 ms with result: SqlDataReader

(Note that this is the output assuming any database initialization has already happened. If database initialization had not already happened then there would be a lot more output showing all the work Migrations does under the covers to check for or create a new database.)

What gets logged?

When the Log property is set all of the following will be logged:

• SQL for all different kinds of commands. For example:
  • Queries, including normal LINQ queries, eSQL queries, and raw queries from methods such as SqlQuery
  • Inserts, updates, and deletes generated as part of SaveChanges
  • Relationship loading queries such as those generated by lazy loading
• Parameters
• Whether or not the command is being executed asynchronously
• A timestamp indicating when the command started executing
• Whether or not the command completed successfully, failed by throwing an exception, or, for async, was canceled
• Some indication of the result value
• The approximate amount of time it took to execute the command. Note that this is the time from sending the command to getting the result object back. It does not include time to read the results.

Looking at the example output above, each of the four commands logged are:

• The query resulting from the call to context.Blogs.First
  • Notice that the ToString method of getting the SQL would not have worked for this query since “First” does not provide an IQueryable on which ToString could be called
• The query resulting from the lazy-loading of blog.Posts
  • Notice the parameter details for the key value for which lazy loading is happening
  • Only properties of the parameter that are set to non-default values are logged. For example, the Size property is only shown if it is non-zero.
• Two commands resulting from SaveChangesAsync; one for the update to change a post title, the other for an insert to add a new post
  • Notice the parameter details for the FK and Title properties
  • Notice that these commands are being executed asynchronously

Logging to different places

As shown above logging to the console is super easy. It’s also easy to log to memory, file, etc. by using different kinds of TextWriter.

If you are familiar with LINQ to SQL you might notice that in LINQ to SQL the Log property is set to the actual TextWriter object (e.g. Console.Out) while in EF the Log property is set to a method that accepts a string (e.g. Console.Write or Console.Out.Write). The reason for this is to decouple EF from TextWriter by accepting any delegate that can act as a sink for strings. For example, imagine that you already have some logging framework and it defines a logging method like so:

public class MyLogger 
{ 
    public void Log(string component, string message) 
    { 
        Console.WriteLine("Component: {0} Message: {1} ", component, message); 
    } 
}

This could be hooked up to the EF Log property like this:

var logger = new MyLogger(); 
context.Database.Log = s => logger.Log("EFApp", s);

Result logging

The default logger logs command text (SQL), parameters, and the “Executing” line with a timestamp before the command is sent to the database. A “completed” line containing elapsed time is logged following execution of the command.

Note that for async commands the “completed” line is not logged until the async task actually completes, fails, or is canceled.

The “completed” line contains different information depending on the type of command and whether or not execution was successful.

Successful execution

For commands that complete successfully the output is “Completed in x ms with result: “ followed by some indication of what the result was. For commands that return a data reader the result indication is the type of DbDataReader returned. For commands that return an integer value such as the update command shown above the result shown is that integer.

Failed execution

For commands that fail by throwing an exception, the output contains the message from the exception. For example, using SqlQuery to query against a table that does exist will result in log output something like this:

SELECT * from ThisTableIsMissing
-- Executing at 5/13/2013 10:19:05 AM
-- Failed in 1 ms with error: Invalid object name ‘ThisTableIsMissing‘.

Canceled execution

For async commands where the task is canceled the result could be failure with an exception, since this is what the underlying ADO.NET provider often does when an attempt is made to cancel. If this doesn’t happen and the task is canceled cleanly then the output will look something like this:

update Blogs set Title = ‘No‘ where Id = -1
-- Executing asynchronously at 5/13/2013 10:21:10 AM
-- Canceled in 1 ms

Changing log content and formatting

DatabaseLogFormatter

Under the covers the Database.Log property makes use of a DatabaseLogFormatter object. This object effectively binds an IDbCommandInterceptor implementation (see below) to a delegate that accepts strings and a DbContext. This means that methods on DatabaseLogFormatter are called before and after the execution of commands by EF. These DatabaseLogFormatter methods gather and format log output and send it to the delegate.

Customizing DatabaseLogFormatter

Changing what is logged and how it is formatted can be achieved by creating a new class that derives from DatabaseLogFormatter and overrides methods as appropriate. The most common methods to override are:

• LogCommand – Override this to change how commands are logged before they are executed. By default LogCommand calls LogParameter for each parameter; you may choose to do the same in your override or handle parameters differently instead.
• LogResult – Override this to change how the outcome from executing a command is logged.
• LogParameter – Override this to change the formatting and content of parameter logging.

For example, suppose we wanted to log just a single line before each command is sent to the database. This can be done with two overrides:

• Override LogCommand to format and write the single line of SQL
• Override LogResult to do nothing.

The code would look something like this:

public class OneLineFormatter : DatabaseLogFormatter 
{ 
    public OneLineFormatter(DbContext context, Action<string> writeAction) 
        : base(context, writeAction) 
    { 
    } 
 
    public override void LogCommand<TResult>( 
        DbCommand command, DbCommandInterceptionContext<TResult> interceptionContext) 
    { 
        Write(string.Format( 
            "Context ‘{0}‘ is executing command ‘{1}‘{2}", 
            Context.GetType().Name, 
            command.CommandText.Replace(Environment.NewLine, ""), 
            Environment.NewLine)); 
    } 
 
    public override void LogResult<TResult>( 
        DbCommand command, DbCommandInterceptionContext<TResult> interceptionContext) 
    { 
    } 
}

To log output simply call the Write method which will send output to the configured write delegate.

(Note that this code does simplistic removal of line breaks just as an example. It will likely not work well for viewing complex SQL.)

Setting the DatabaseLogFormatter

Once a new DatabaseLogFormatter class has been created it needs to be registered with EF. This is done using code-based configuration. In a nutshell this means creating a new class that derives from DbConfiguration in the same assembly as your DbContext class and then calling SetDatabaseLogFormatter in the constructor of this new class. For example:

public class MyDbConfiguration : DbConfiguration 
{ 
    public MyDbConfiguration() 
    { 
        SetDatabaseLogFormatter( 
            (context, writeAction) => new OneLineFormatter(context, writeAction)); 
    } 
}

Using the new DatabaseLogFormatter

This new DatabaseLogFormatter will now be used anytime Database.Log is set. So, running the code from part 1 will now result in the following output:

Context ‘BlogContext‘ is executing command ‘SELECT TOP (1) [Extent1].[Id] AS [Id], [Extent1].[Title] AS [Title]FROM [dbo].[Blogs] AS [Extent1]WHERE (N‘One Unicorn‘ = [Extent1].[Title]) AND ([Extent1].[Title] IS NOT NULL)‘
Context ‘BlogContext‘ is executing command ‘SELECT [Extent1].[Id] AS [Id], [Extent1].[Title] AS [Title], [Extent1].[BlogId] AS [BlogId]FROM [dbo].[Posts] AS [Extent1]WHERE [Extent1].[BlogId] = @EntityKeyValue1‘
Context ‘BlogContext‘ is executing command ‘update [dbo].[Posts]set [Title] = @0where ([Id] = @1)‘
Context ‘BlogContext‘ is executing command ‘insert [dbo].[Posts]([Title], [BlogId])values (@0, @1)select [Id]from [dbo].[Posts]where @@rowcount > 0 and [Id] = scope_identity()‘

Interception building blocks

So far we have looked at how to use DbContext.Database.Log to log the SQL generated by EF. But this code is actually a relatively thin façade over some low-level building blocks for more general interception.

Interception interfaces

The interception code is built around the concept of interception interfaces. These interfaces inherit from IDbInterceptor and define methods that are called when EF performs some action. The intent is to have one interface per type of object being intercepted. For example, the IDbCommandInterceptor interface defines methods that are called before EF makes a call to ExecuteNonQuery, ExecuteScalar, ExecuteReader, and related methods. Likewise, the interface defines methods that are called when each of these operations completes. The DatabaseLogFormatter class that we looked at above implements this interface to log commands.

The interception context

Looking at the methods defined on any of the interceptor interfaces it is apparent that every call is given an object of type DbInterceptionContext or some type derived from this such as DbCommandInterceptionContext<>. This object contains contextual information about the action that EF is taking. For example, if the action is being taken on behalf of a DbContext, then the DbContext is included in the DbInterceptionContext. Similarly, for commands that are being executed asynchronously, the IsAsync flag is set on DbCommandInterceptionContext.

Result handling

The DbCommandInterceptionContext<> class contains a properties called Result, OriginalResult, Exception, and OriginalException. These properties are set to null/zero for calls to the interception methods that are called before the operation is executed—i.e. the …Executing methods. If the operation is executed and succeeds, then Result and OriginalResult are set to the result of the operation. These values can then be observed in the interception methods that are called after the operation has executed—i.e. the …Executed methods. Likewise, if the operation throws, then the Exception and OriginalException properties will be set.

Suppressing execution

If an interceptor sets the Result property before the command has executed (in one of the …Executing methods) then EF will not attempt to actually execute the command, but will instead just use the result set. In other words, the interceptor can suppress execution of the command but have EF continue as if the command had been executed.

An example of how this might be used is the command batching that has traditionally been done with a wrapping provider. The interceptor would store the command for later execution as a batch but would “pretend” to EF that the command had executed as normal. Note that it requires more than this to implement batching, but this is an example of how changing the interception result might be used.

Execution can also be suppressed by setting the Exception property in one of the …Executing methods. This causes EF to continue as if execution of the operation had failed by throwing the given exception. This may, of course, cause the application to crash, but it may also be a transient exception or some other exception that is handled by EF. For example, this could be used in test environments to test the behavior of an application when command execution fails.

Changing the result after execution

If an interceptor sets the Result property after the command has executed (in one of the …Executed methods) then EF will use the changed result instead of the result that was actually returned from the operation. Similarly, if an interceptor sets the Exception property after the command has executed, then EF will throw the set exception as if the operation had thrown the exception.

An interceptor can also set the Exception property to null to indicate that no exception should be thrown. This can be useful if execution of the operation failed but the interceptor wishes EF to continue as if the operation had succeeded. This usually also involves setting the Result so that EF has some result value to work with as it continues.

OriginalResult and OriginalException

After EF has executed an operation it will set either the Result and OriginalResult properties if execution did not fail or the Exception and OriginalException properties if execution failed with an exception.

The OriginalResult and OriginalException properties are read-only and are only set by EF after actually executing an operation. These properties cannot be set by interceptors. This means that any interceptor can distinguish between an exception or result that has been set by some other interceptor as opposed to the real exception or result that occurred when the operation was executed.

Registering interceptors

Once a class that implements one or more of the interception interfaces has been created it can be registered with EF using the DbInterception class. For example:

DbInterception.Add(new NLogCommandInterceptor());

Interceptors can also be registered at the app-domain level using the DbConfiguration code-based configuration mechanism.

Example: Logging to NLog

Let’s put all this together into an example that using IDbCommandInterceptor and NLog to:

• Log a warning for any command that is executed non-asynchronously
• Log an error for any command that throws when executed

Here’s the class that does the logging, which should be registered as shown above:

public class NLogCommandInterceptor : IDbCommandInterceptor 
{ 
    private static readonly Logger Logger = LogManager.GetCurrentClassLogger(); 
 
    public void NonQueryExecuting( 
        DbCommand command, DbCommandInterceptionContext<int> interceptionContext) 
    { 
        LogIfNonAsync(command, interceptionContext); 
    } 
 
    public void NonQueryExecuted( 
        DbCommand command, DbCommandInterceptionContext<int> interceptionContext) 
    { 
        LogIfError(command, interceptionContext); 
    } 
 
    public void ReaderExecuting( 
        DbCommand command, DbCommandInterceptionContext<DbDataReader> interceptionContext) 
    { 
        LogIfNonAsync(command, interceptionContext); 
    } 
 
    public void ReaderExecuted( 
        DbCommand command, DbCommandInterceptionContext<DbDataReader> interceptionContext) 
    { 
        LogIfError(command, interceptionContext); 
    } 
 
    public void ScalarExecuting( 
        DbCommand command, DbCommandInterceptionContext<object> interceptionContext) 
    { 
        LogIfNonAsync(command, interceptionContext); 
    } 
 
    public void ScalarExecuted( 
        DbCommand command, DbCommandInterceptionContext<object> interceptionContext) 
    { 
        LogIfError(command, interceptionContext); 
    } 
 
    private void LogIfNonAsync<TResult>( 
        DbCommand command, DbCommandInterceptionContext<TResult> interceptionContext) 
    { 
        if (!interceptionContext.IsAsync) 
        { 
            Logger.Warn("Non-async command used: {0}", command.CommandText); 
        } 
    } 
 
    private void LogIfError<TResult>( 
        DbCommand command, DbCommandInterceptionContext<TResult> interceptionContext) 
    { 
        if (interceptionContext.Exception != null) 
        { 
            Logger.Error("Command {0} failed with exception {1}", 
                command.CommandText, interceptionContext.Exception); 
        } 
    } 
}

Notice how this code uses the interception context to discover when a command is being executed non-asynchronously and to discover when there was an error executing a command.

Logging and Intercepting Database Operations (EF6 Onwards)

标签：