EF6 SQL Logging – Part 2: Changing the content/formatting

In part 1 we saw how DbContext.Database.Log can be used to easily log SQL to the console or some other TextWriter. This post covers how the context and formatting of the output can be changed.

DatabaseLogFormatter

Under the covers the Database.Log property makes use of a DatabaseLogFormatter object. This object effectively binds a IDbCommandInterceptor implementation (see part 3 of this series) to a delegate that accepts strings and a DbContext. This means that interception 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.

Changing what is logged and how it is formatted can be achieved by creating a new class that derives from DatabaseLogFormatter and then overriding 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. (Executed could be overridden instead and this would probably be slightly more efficient, but functionally equivalent.)

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, object result, 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()'

More control?

In the next post we’ll take a look at implementing IDbCommandInterceptor directly for even more control of command interception and show an example that integrates directly with NLog without using the Database.Log property.