Blogging on logging

Everyone loves a log. A trace log can provide insight into the goings-on of a running system. An audit log gives you an important “paper trail” tracking who did what and when. An error log might be an important aid for exception-driven development. While there seems to be broad agreement that logging is essential (especially in distributed systems), there is little consensus on specific design patterns and code structures to implement it.

Here is an illustration of a commonplace (and problematic) strategy:

void DoSomething(MyData data)
{
    GlobalTraceLog.WriteVerbose("Doing something with {0}...", data.ToString());
    try
    {
        // ... code goes here ...
    }
    catch (Exception e)
    {
        GlobalTraceLog.WriteError("Something failed! {0}", e.ToString());
        throw;
    }

    GlobalTraceLog.WriteInfo("Did something.");
}

What’s the problem? There are at least two big ones. The first is the use of a static global log instance — the dreaded singleton anti-pattern. With this design it is hard to determine whether a given object will log anything since the dependency is not explicitly declared, not to mention the negative testability implications. The data is also completely unstructured. As Gregory Szorc points out, if you intend for your logs to be read by machines (e.g. to do data mining or alerting) it is unwise to use a raw text format suitable for humans only.

Let’s say that your logging data is only for humans, by design. Further, it is not associated with any user story or specific business value. In that case, maybe the static text logger approach is fine. You are dismissed from this blog post! Otherwise, read on…

I’ve written before about generating and analyzing structured trace logs. In those code samples, I used an approach of passing an EventSource instance to the classes generating the logs. (Technically this is a bit of an empty gesture given the unfortunate singleton-ish nature of EventSource, but it demonstrates the principle.) One potential improvement on this basic approach which observes the dependency inversion principle is to pass a logging interface instead, e.g.:

// The log producer
public class MyComponent
{
    public MyComponent(IComponentEvents events) { /* ... */ }
    public int DoOperation() { /* ... */ }
}

// The typed log event abstraction
public interface IComponentEvents
{
    void OperationStarted(Guid id);
    void OperationCompleted(Guid id, int result);
}

// The concrete EventSource type implements the interface
public ComponentEventSource : EventSource, IComponentEvents
{
    // ...
}

This has less coupling to a specific logging technology and can thus facilitate a straightforward set of unit tests which verify the events produced — though at the cost of a test double implementing the necessary event interface:

[TestClass]
public class MyComponentTest
{
    [TestMethod]
    public void ShouldNotifyOnOperationStartAndCompletion()
    {
        MemoryComponentEvents events = new MemoryComponentEvents();
        MyComponent component = new MyComponent(events);

        int result = component.DoOperation();

        Assert.AreEqual(1, events.Started.Count);
        Assert.AreEqual(1, events.Completed.Count);
        Assert.AreNotEqual(Guid.Empty, events.Started[0]);
        Assert.AreEqual(events.Started[0], events.Completed[0].Item1);
        Assert.AreEqual(result, events.Completed[0].Item2);
    }

    // Keeps track of events in memory, for unit tests
    private sealed class MemoryComponentEvents : IComponentEvents
    {
        // ...
        public IList<Guid> Started { /* ... */ }
        public IList<Guid, int> Completed { /* ... */ }

        public void OperationStarted(Guid id)
        {
            this.Started.Add(id);
        }

        public void OperationCompleted(Guid id, int result)
        {
            this.Completed.Add(Tuple.Create(id, result));
        }
    }
}

There are some other patterns you could use but I have not seen them much in practice. For example, you could associate each log operation with a plain .NET event handler or leverage IObservable from Reactive Extensions. These could work but introduce more complexity around the registration/subscription process.

So why not step away from the statics and go from strings to structure? Your logging and overall system design could become that much more testable (read: better).