EF 6.1: Turning on logging without recompiling

I already blogged about SQL logging in EF6. Part 3 of that series shows how to use EF with a logging framework such as NLog. If you do this then you can easily switch logging on and off using NLog or equivalent without any changes to the app. This is the approach I would use if I wanted to log SQL from EF. But what if logging was not considered at all when the app was created? Now with EF 6.1 you can switch logging on for any app without access to the source or recompiling.

How to do it

To log SQL to the console add the following entry to the entityFramework section in your application’s web.config or app.config:

<interceptors>
  <interceptor type="System.Data.Entity.Infrastructure.Interception.DatabaseLogger, EntityFramework"/>
</interceptors>

(If you are just working with the compiled application then look for a file like “MyApplication.exe.config” since this is what app.config is compiled into.)

To log to a filename instead use something like:

<interceptors>
  <interceptor type="System.Data.Entity.Infrastructure.Interception.DatabaseLogger, EntityFramework">
    <parameters>
      <parameter value="C:\Stuff\LogOutput.txt"/>
    </parameters>
  </interceptor>
</interceptors>

By default this will cause the log file to be overwritten with a new file each time the app starts. To instead append to the log file if it already exists use something like:

<interceptors>
  <interceptor type="System.Data.Entity.Infrastructure.Interception.DatabaseLogger, EntityFramework">
    <parameters>
      <parameter value="C:\Stuff\LogOutput.txt"/>
      <parameter value="true" type="System.Boolean"/>
    </parameters>
  </interceptor>
</interceptors>

What’s going on

This is the part of the post where I describe what’s going on in EF. You don’t need to read any of this to use logging, but for those interested here it is.

The built-in SQL logging uses a class called DatabaseLogFormatter.  DatabaseLogFormatter is an EF interceptor that implements various interfaces which inform it of operations on commands, connections, transactions, etc. It creates log output based on these operations and sends this log output to a registered delegate—effectively sending the formatted log output to a stream. Changing what is logged can be customized as described in part 2 of the logging series.

EF 6.1 introduced IDbConfigurationInterceptor. This is an interception interface which lets code examine and/or modify EF configuration when the app starts. Using this hook we can write a simple version of DatabaseLogger:

public class ExampleDatabaseLogger : IDbConfigurationInterceptor
{
    public void Loaded(
        DbConfigurationLoadedEventArgs loadedEventArgs,
        DbConfigurationInterceptionContext interceptionContext)
    {
        var formatterFactory = loadedEventArgs
                .DependencyResolver
                .GetService<Func<DbContext, Action<string>, DatabaseLogFormatter>>();

        var formatter = formatterFactory(null, Console.Write);

        DbInterception.Add(formatter);
    }
}

This is basically the same as DatabaseLogger in the EntityFramework assembly except that I have simplified it a bit by only including the code that logs to the Console. The Loaded method is called when EF configuration (as represented by the DbConfiguration class) has been loaded. Let’s look at the three lines of code in Loaded.

  • The first line asks EF for the registered DatabaseLogFormatter factory. We could just new up a new DatabaseLogFormatter here instead, but if the app has customized log formatting then this line will get that customized logger instead of the default.
  • The first line didn’t actually get the DatabaseLogFormatter. It instead got a factory that can be used to create DatabaseLogFormatter instances. The second line invokes that factory to get an actual formatter instance. Null is passed for the context since we are going to log for all context instances. The second argument to the factory is a delegate for the Console output stream—in this case, just a pointer to the Console.Write method. If we were logging to a file we would pass the Write method from our StreamWriter instance instead.
  • The third line registers the DatabaseLogFormatter as an interceptor, which is how logging in EF works as described above.

Since this class doesn’t define a constructor the C# compiler will generate a parameterless default constructor for it. It is this constructor that is called when the interceptor is registered in config with no parameters. We could also add constructors with parameters, such as the ones used in the real DatabaseLogger to register logging to a file. Keep in mind that the parameters must accept constant values that can be written into the config file.

About Arthur Vickers

Developer on the Entity Framework team at Microsoft.
This entry was posted in DbContext API, Entity Framework, Extensibility, Interception, Logging and tagged , , , , . Bookmark the permalink.

8 Responses to EF 6.1: Turning on logging without recompiling

  1. uzorrilla says:

    Really good staff!

    You can do a lot of things with this new interceptor and the ability to work with DbDependencyResolver

    Thanks

  2. Jon says:

    I’ve been wondering why Entity Framework doesn’t just use System.Diagnostics trace logging? Is there something wrong with it? .NET seems to be repeating the same annoying thing as Java where there are 10 different open source logging packages. I don’t understand why you can’t just use what is already built into .NET. If it is deficient, why not fix it.

    • There are many different approaches to logging each of which have their advantages and disadvantages. More generally, I don’t think that there is usually just one right way to do most things in software development. I personally really appreciate the community (individuals, open source projects, commercial companies) creating great new ways of doing things. This kind of innovation helps move the platform forward and make it richer to use. As developers of framework code we strive to achieve the best experience for developers on the .NET platform. In my mind this means both providing good out-of-the-box experiences and also providing the flexability to integrate with other components such that developers can use whatever parts of the ecosystem work best for them. This is what we have tried to do with logging. Out-of-the-box you can easily log to the console:

      context.Database.Log = Console.Write;

      Or to Diagnostics.Trace

      context.Database.Log = s => Trace.Write(s);

      Alternatively, you can connect EF up at a lower level to the console, Trace, or any other logging mechanism to get full control over how logging happens. We hope that the out-of-the-box experience is easy to use, while the lower-level building blocks provide the power and flexibility to modify the default experience where needed.

  3. Lohen says:

    Thank you Arthur for this tutorials. Do you know if i can log EF queries in a Database and not a Text file ? (i’m using EF 6.0.2)

    • There is nothing built in that logs directly to a database, but you could implement your own class to do this based on the information in these articles, or find a third-party logging framework that does this and hook up to it.

      Thanks,
      Arthur

  4. James Hancock says:

    Really wish that this would output the SQL in a way that could just be copied and pasted directly into management studio and run. The way it is now, is such a PITA to make work directly that it’s hard to do optimizations and understand if you’re just writting slow SQL or if it’s Entity Framework that is adding the overhead etc.

Leave a Reply

Fill in your details below or click an icon to log in:

WordPress.com Logo

You are commenting using your WordPress.com account. Log Out / Change )

Twitter picture

You are commenting using your Twitter account. Log Out / Change )

Facebook photo

You are commenting using your Facebook account. Log Out / Change )

Google+ photo

You are commenting using your Google+ account. Log Out / Change )

Connecting to %s