Logging Entity Framework 6 queries to Azure Tables

I wrote about Semantic Logging (SL) in MVC and after watching Rowan Miller`s video from Tech Ed 2014 I decided to implement logging Entity Framework 6 queries to Azure Tables with EventSource (aka Semantic Logging / Structured Logging).

Motivation for logging Entity Framework 6 queries to Azure Tables

By MHO the motivation behind every logging system must include :

Finding and removing bugs which improves QoS and reduces Dev/Ops time to resolve an issue.
Good structured log which enables a less proficient programmers to solve the problem. Better support devs => higher ops. costs.
Proactive response – get into action long before the client gets to you. Or even better – you call the client first.
Measuring and optimizing performance of your app. As Mark Simms and Chris Clayton say that “premature optimization is the root of all evil.” is not so relevant when designing clod apps.

Explanation

Why so much “maintenance cost”? Because “maintenance cost” is the source of most of the cost of a big app and lowering it as much as possible is a key feature. That is why I consider the logging to be a key feature for every working program. When you do not have good logging ( and documentation ) in case of a failure or a bug you have to rely on the knowledge, of the internals of the application, that is inside the head of a few (some times just one) of your best developers which will not be around for 15 years probably. And 10+ years is the minimum lifespan of enterprise apps that I have encountered so far – desktop or web based.

What are the benefits of using EventSource for logging Entity Framework queries to Azure Tables compared to writing to file like in the video?

Why I do not like the idea of a log.txt?

Writing to log.txt places a file on each instance which makes it troublesome to get all the files from all instances and then combine them.
You have to first combine all the files from all your instances before you even start searching for particular queries.
You do not have structured logs but a bulk of text which makes searching cumbersome.
Searching through big txt log files is not a pleasure at all – wastes time of the administrator/developer/ops guy.
You have to do this every time you want to get all the logs and search for a problem or else.
You can not easily start SQL Profiler on Web Role. (On all your web roles? :))
I have personally used NLog for logging with a txt for web apps but when you go to multiple instances with great volume – it starts to become a burden rather then help.

Why I do like the idea of EventSource (ETW) with Azure Tables?

You have everything in one place right away.
You have it structured. For example – InstanceId, Query, Time, etc, …. however you like it.
You have tools to quickly and conveniently search Azure Tables. My favorite is Cerebrata/RegGate Azure Management Studio. But there are others free alternatives like Azure Storage Explorer
EventSource uses ETW which is asynchronous and very fast. Why bother about that? Watch this video where Mark Simms and Chris Clayton explain such a case where the synchrony of the logging framework was overlooked. Simms advises against Log4Net or other logging libraries which can not log asynchronously.
If you use separate storage account for diagnostics (aka logging) you will hardly hit the limit of Azure Table – up to 20,000 per second.

Implementation

Without further ado lets get to the code.

First the not so interesting part – The DbContext and DbSets to work with :

public class ProductContext : DbContext
{
    public DbSet<Category> Categories { get; set; }
    public DbSet<Product> Products { get; set; }
    public DbSet<Supplier> Suppliers { get; set; }
}

public class Category
{
   public int CategoryId { get; set; }
   public string Name { get; set; }

   public virtual ICollection<Product> Products { get; set; }
}

public class Product
{
    public int ProductId { get; set; }
    public string Name { get; set; }
    public int CategoryId { get; set; }
    public virtual Category Category { get; set; }
}

public class Supplier
{
   [Key]
   public string SupplierCode { get; set; }
   public string Name { get; set; }
}

Now the logger itself :

public class EfLogger : EventSource, IEfLogger
{
    public static class Keywords
    {
        // only powers of 2 -> 1,2,4,8,16,32,64,128
        public const EventKeywords All = (EventKeywords)2048;
    }

    public void LogQuery(string query)
    {
        LogQueryInternal(query);
    }

    [Event(100, Keywords = Keywords.All,Level = EventLevel.LogAlways)]
    private void LogQueryInternal(string query)
    {
        if (this.IsEnabled())
        {
                WriteEvent(100, query);
        }
    }
}

public interface IEfLogger
{
    void LogQuery(string query);
}

Why bother with the interface? You are probably going to drop it via DI into your DbContext builder. I still have doubts about how to implement logging because it is a cross cutting concern as explained by M. Seeman in his book: Drop it in over DI? Hide it behind static method? Mark the class with some passive attribute? Implement it as a Castle Windsor Dynamic Proxy Interceptor? It depends on the app 🙂

Now the logger setup :

public class LoggerContainer
{
   private static readonly List<EventListener> Listeners = new List<EventListener>();

    public static void SetupEntityFrameworkListener(IEfLogger efLogger)
    {
        try
        {
            EventSourceAnalyzer.InspectAll((EventSource)efLogger);
        }
        catch (EventSourceAnalyzerException eventSourceAnalyzerException)
        {
            string errorMsg = string.Format(
                        "Critical configuration error during event sources inspection. Exception Message : {0} StackTrace :{1} ",
                        eventSourceAnalyzerException.Message,
                        eventSourceAnalyzerException.StackTrace);
            EventLog.WriteEntry("Event Sources Initialization", errorMsg, EventLogEntryType.Error);
        }
        var listener = WindowsAzureTableLog.CreateListener(
"EfLog",  
ConfigurationSettings.AppSettings["DiagnosticsConnectionString"],
"EfLog"
);
        Listeners.Add(listener);

        listener.EnableEvents(
            (EventSource)efLogger,
            EventLevel.Informational,
            EfLogger.Keywords.All);
    }

    public static void DisposeEventListener()
    {
        foreach (var eventListener in Listeners)
        {
           eventListener.Dispose();
        }
    }
}

Now a screenshot of the results :

Cerebrata Table Broser - EntityFramework Log — Cerebrata Table Broser – EntityFramework Log

You can download the source code here. Do not forget to restore NuGet packages and build.

Motivation for logging Entity Framework 6 queries to Azure Tables

Explanation

Implementation

Resources