How not to do logging: unnecessary abstractions

Posted at 07:00 on 11 September 2014

This is a very common pattern that I see over and over again in project after project:

public class MyService
{
    private ILogger _logger;
    /* snip */

    public MyService(ILogger logger, /* snip */)
    {
        _logger = logger;
        /* snip */
    }
}

There are a few problems here.

1. Don't use dependency injection to create your loggers.

The problem with using dependency injection to create your loggers is that it denies you access to one of the most useful features of these logging frameworks: hierarchical loggers. The recommended way to instantiate loggers is to have just one for each class, with each logger being named after the class in which it is used. For example, with log4net, you would do this:

namespace MyNamespace
{
    public class MyService
    {
        private static readonly ILog log
            = LogManager.GetLogger("MyNamespace.MyService");

        /* snip */
    }
}

With NLog it is even simpler:

namespace MyNamespace
{
    public class MyService
    {
        private static readonly Logger log
            = LogManager.GetCurrentClassLogger();

        /* snip */
    }
}

Why is this so important? Simple. It allows you to fine tune your logging output on a namespace-by-namespace or a class-by-class basis. For example, you could send debugging information from NHibernate's internals to a separate file, or log debug information only for your e-mail handling classes.

On the other hand, when you're using your IOC container to create a logger, you can only specify a single named logger right across the board for your entire application. Sure, some IOC containers give you a way to determine the type of object into which you are injecting your logger, but others don't, and I've never seen this done anyway even with those that do. You end up completely losing access to the hierarchy.

Another problem with using an IOC container here is that it limits your use of logging to classes that were created by the container in the first place. Sure, if your container exposes a service locator as a singleton (as for example StructureMap does with ObjectFactory.Instance) you could use that, but it's ugly, not all IOC containers do that, and those that do aren't always used that way anyway.

Finally, injected loggers do have an impact on performance. If you are injecting your loggers, your IOC container has to do more work each time you instantiate a new service, in order to locate the right logger and pass it in as a parameter. On the other hand, by creating loggers as static readonly members, you are only creating a single logger once per AppDomain for each class. This performance difference is admittedly small, but with classes that are instantiated frequently, it can easily add up.

2. Don't abstract your loggers in application code.

There's a case for writing an abstraction layer around your loggers when you're creating a NuGet package for third party distribution. Some .net developers use log4net because it's the one everyone's heard of; others swear by NLog because it's the best; and then you have the Microsoft-only crowd who won't touch anything other than the Logging Application Block. As a third party library developer, you have to support all three. (Well, maybe not so much the third, because the kind of people who use the Logging Application Block are often the kind of people who won't touch your library with a barge pole because you're not Microsoft.)

But as an application developer, you don't have to support anyone other than yourself, so an abstraction layer is superfluous here.

Besides being superfluous, the main problem with abstracting your loggers is that most people get it wrong. Your typical logging facade looks like this:

public interface ILogger
{
    void LogFatal(string message);
    void LogError(string message);
    void LogWarning(string message);
    void LogInfo(string message);
    void LogDebug(string message);
}

That's all. You're denying access to a whole lot of important features of your logger. For example, consider this code:

foreach (PropertyInfo prop in type.GetProperties())
{
    _logger.LogDebug(String.Format("Property {0} has type {1}",
        prop.Name, prop.PropertyType.Name));

    DoSomething(prop);
}

Even if your logger's logging level is set to something higher than Debug, you are still calling String.Format and various reflection properties in a loop. In some cases, this can have a significant performance impact. What you should be doing instead is making use of log4net's IsDebugEnabled property:

foreach (PropertyInfo prop in type.GetProperties())
{
    if (log.IsDebugEnabled) {
        log.DebugFormat("Property {0} has type {1}",
            prop.Name, prop.PropertyType.Name);
    }

    DoSomething(prop);
}

Exceptions are another one. You need to be able to pass exceptions to your logger, especially at the warning, error and fatal levels.

3. Don't mock your loggers in tests.

Of course, all this raises the question about testability. What about mocking your loggers, you may ask?

The answer is simple: you don't need to.

Your logging statements shouldn't affect the outcome of your tests. If they do, then you must be doing something pretty esoteric with your logging and getting it wrong, in which case, your tests should fail.

In any case, your tests are one place more than any other where you should be able to inspect your logging output. Mocking them loses you access to this vital information.