Custom Logging with Entity Framework EF6 by ThinqLinq

Coming from LINQ to SQL, I’ve long been a fan of its logging simplicity where you just set the context.log to a stream (console.out) to see the stream of sql statements being issued to the database. Prior to EF6, this has been a rather frustrating omission that has finally been rectified with EF 6. Now, you can log SQL statements just as simply, but with a slightly different implementation. In EF, you set the DbContext’s Database.Log property to an Action delegate that takes a string as input parameter. Thus to log requests to the Diagnostics Trace implementation, you simply set the following:

context.Database.Log = Sub(val) Diagnostics.Trace.WriteLine(val)

This is fine as long as you are willing to accept the default logging implementation. If you want to customize the log output, things get a bit trickier. In my example, I only want to log the calling method and elapsed time that the query took to execute. I’m not as concerned in my current need for the SQL string, but that is easily included as I’ll point out below.

To start, I need to set the calling method from my code that I’ll be able to access in the logging implementation. Since the calling code is actually in ASP.Net Web API calls returning IQueryables, and the database is not being executed until long after my application code has completed. I need to explicitly identify the application calling method rather than the last method from the call stack which would otherwise be one of the Web API internal methods. To handle this and centralize my set-up logic for the context, I’ll create a factory method which configures the context and use that instead of relying on the context’s constructor. Thanks to partial classes, I can extend the generated entity class and include this new property and factory constructor. To make matters even easier, I’ll take advantage of the CallerMemberName attribute to automatically pull the member name from the method that is calling the factory.

Public Class NorthwindEfEntities

    Public Shared Function ContextFactory(<CallerMemberName> Optional memberName As String = "") As NorthwindEfEntities
        Dim context = New NorthwindEfEntities()
        context.CallingMethod = memberName
        context.Database.Log = Sub(val) Diagnostics.Trace.WriteLine(val)
        Return context
    End Function

    Public Property CallingMethod As String

End Class

Now, to create the context we call this new ContextFactory method, but don’t pass the memberName explicitly. The compiler will add that for us automatically.

    Public Function GetCustomers() As IQueryable(Of DTO.DtoCustomer)
        cn = NorhwindEfEntities.ContextFactory
        ' Do some amazing query and return it.
   End Function

Now that we’ve set up the logger, we need to customize the output that is generated. To do this, we need to add a new class that derives from DatabaseLogFormatter (in the System.Data.Entity.Infrastructure.Interception namespace). If you don’t have this namespace, you may need to upgrade to EF6 on order to access the logging functionality. Since the base class doesn’t have a default parameterless constructor, we need to make a new one and simply delegate to the base implementation. With that out of the way, we can supply our own logging. The base implementation gives us hooks to the following interception points.

As stated before in our example, we want to write a log entry when the command completes including the calling method name and execution time. To do this we need to perform the following adjustments to the base implementation: 1) suppress logging the SQL statements in the LogCommand method by simply creating a noop and not delegating to the base implementation, and 2) replace the default result log information with our custom output in the LogResult method. To get the elapsed time, we directly leverage the Stopwatch property of the base class. Here then is our new custom formatter.

Imports System.Data.Entity.Infrastructure.Interception
Imports System.Data.Entity

Public Class CustomDbLogFormatter
    Inherits DatabaseLogFormatter

    Public Sub New(context As DbContext, writeAction As Action(Of String))
        MyBase.New(context, writeAction)
    End Sub

    Public Overrides Sub LogCommand(Of TResult)(command As Common.DbCommand, interceptionContext As DbCommandInterceptionContext(Of TResult))
        'MyBase.LogCommand(Of TResult)(command, interceptionContext)
    End Sub

    Public Overrides Sub LogResult(Of TResult)(command As Common.DbCommand, interceptionContext As DbCommandInterceptionContext(Of TResult))

        Dim context = interceptionContext.DbContexts.OfType(Of NorthwindEfEntities).FirstOrDefault()
        If context IsNot Nothing Then
            Trace.WriteLine(context.CallingMethod + " Completed in " + Stopwatch.ElapsedMilliseconds.ToString)
        End If
   
    End Sub
End Class

One step remains in order for this new logging implementation to take effect. We need to register the custom logger in our solution. To do this manually in code, we create a new class and derive from DbConfiguration. Then in the constructor, call the base class’s SetDatabaseLogFormatter to set the formatter to our new CustomDbLogFormatter. For more information on configuring the logging via your config file rather than in code, see AJ Vicker’s post today on EF 6.1 turning on SQL logging without recompiling your app.

Public Class LogConfiguration
    Inherits DbConfiguration

    Public Sub New()
        SetDatabaseLogFormatter(Function(context, action) New CustomDbLogFormatter(context, action))
    End Sub
End Class

Naturally, the value that we are outputting is just an example, you’re free to make your logging as complex as you want given these basic building blocks. For more details, make sure to read the EF team’s posts on the logging implementation.