Creating an Entity Framework Interceptor to Log All Queries

Debugging queries generated by Entity Framework can be a huge hassle. In the past, the easiest way to was to either use an Entity Framework profiler and most of them are not free or use a profiler in the database engine to capture them. However, Entity Framework has the concept of an Interceptor that can be used to perform some action before or after a query or command executes. Sadly, the IDbCommandInterceptor interface isn’t widely documented or used. In this post, I will show you how to set up an Interceptor to log all the commands being executed by Entity Framework very quickly.

Since we know what an interceptor is, how can we capture the commands that Entity Framework is executing? Add a new class to your project and name it DbCommandInterceptor. This class has to inherit from System.Data.Entity.Infrastructure.Interception.IDbCommandInterceptor

If we then implement the interface, we will have six methods: NonQueryExecuted, NonQueryExecuting, ReaderExecuted, ReaderExecuting, ScalarExecuting, and ScalarExecuted. Each of these six method have a very similar signature. They each accept two arguments, DbCommand and DbCommandInterceptionContext<int>. The query or command (CommandText) that is being executed, as well as the parameters (Parameters) that are being passed to the database are within the DbCommand object. It is important to note that when a single command is executed, the xxxExecuting methods are being called before execution and xxxExecuted methods are called after execution. Unless you have a really, really good reason, I recommend using one or the other as the command text and parameters for before and after are going to be the same and will create twice as many log entries for no further information.

You might be wondering if you can get timings from  this information but, sadly, you cannot. Not without some additional work. You can probably figure that out on your own but it might be helpful to know that you can alter the query before it is executed and that same query will be there after execution so you could add a Guid to the call or even a timestamp and then after the call, find that information and use it to your advantage.

Next, we need to log the command text and parameters. You could choose to just print out everything including the parameters. In my case, I decided to substitute the parameter values in place of the parameters in the command text. Below is the method that handles that.

private void LogCommandText(DbCommand command, DbCommandInterceptionContext context)
{
    string commandText = command.CommandText.Replace(Environment.NewLine, " ");

    if(!string.IsNullOrEmpty(commandText.Trim()))
    {
        StringBuilder sb = new StringBuilder();

        if(command.Parameters.Count > 0)
        {
            for(int i = 0; i < command.Parameters.Count; i++)
            {
                DbParameter param = command.Parameters[i];

                string name = param.ParameterName;
                string value = "'" + param.Value.ToString() + "'";

                commandText = commandText.Replace("@" + name, value + " /*" + param.ParameterName + "*/ ");
            }
        }

        sb.AppendLine($"ENTITY_FRAMEWORK_QUERY -  Command_Text: {commandText}.");
    }
}

Then, to call this method, just make this simple change:

public void ScalarExecuting(DbCommand command, DbCommandInterceptionContext<object> interceptionContext)
{
    LogCommandText(command, interceptionContext);
}

You will also want to remove the throw new NotImplementedException()

blocks from the executing/executed methods, even if you aren’t implementing the logging feature in those methods.

Finally, the last thing to do is enable the Interceptor. This can be done in the web.config or app.config file in the <entityFramework>...</entityFramework>

section.

.

<interceptors>
  <interceptor type="Namespace.Goes.Here.With.Interceptor.Name, Project.Name.Goes.Here"></interceptor>
</interceptors>