samedi 18 juillet 2015

Logger, my Nemesis.

I have to admit something I don’t know if can be proud of. I have an actual problem with the logger libraries, like log4j on the JVM or log4net in .Net.

What’s your problem, bro?

If you use these languages, I’m sure you carry a dependency to this kind of lib. Logging is very important in our industry. Yet most of the time the logged information is completely useless. I write that because even if these libs make the logging simple, by preventing us to care about where the logs will be written, log rotation, log level or setting update at runtime, the logging practice is not a trivial. However, due to the ease of use of logging libs, developers think they can leave dependencies to loggers everywhere, and that it is not a big deal.

And that sucks from unit test perspective because:

  • The logger elements (loggers, appenders,…) needs configuration. It can be done through code (though being a butthurt) or with a configuration file, which involve complex magic and a dependcy to the file system. I want to write unit test and I find myself coding integration tests. Shit.
  • Calls to logger, as innocent as they look, are parts of the logic of the program. For that reason it should be tested. I cannot do that when the actual logging lib is linked, since they write in stdout, or a file.

The naive way to use such a logger is to put this kind of crap in the field definition part of the silly stuffs you call your classes.

public class Trololo 
{
    // I don’t understand this crazy tradition I see in C# code to put an
    // undescrore in front of private fields. Guys, if you want to write Python,
    // do it, it’s better for your health after all.
    private static ILog _logger = LogManager.GetLogger(typeof(Trololo));

    public void DoStuff() 
    {
        // Still naively, you may use it this way. It’s not a good practice
        // you don’t know if the debug level is really activated!
        _logger.Debug("Entering method DoStuff"); // guys… come on!
    }
}

And it’s bad since now you class is bound to a singleton you know nothing about (LogManager). All I know is that because of it, when I’ll try to run my class in my testing tools, I will be obliged to configure the log framework. We can do really better.

Why and what do we log

First of all, a logging policy should be decided by your client (the end user, the business representative, the operation guy, maybe the lawyer). This is hugely important as it will dictate:

  • the events you’ll have to log (user sign on, entities creation, access to restricted information,…)
  • the retention policy. How much time will you have to keep the logs

Notice that it will help you to choose the technical detail for painless logging:

  • Are you going to log on the file system, without file rotation because you log fairly nothing (please, don’t do that)?
  • Are you going to use file rotation because your client woke you up on Sunday morning because you enormous log file caused a no space left on device error and downtime?
  • Are you going to log more seriously on a DB or a queue or anything that do not penalise the file system hosting you application?

You also want to log your own stuff, basically when you don’t know what’s happening in your system. I consider it’s at the interfaces as they force you to make the hypothesis they just works (which is true, most of the time, for most of systems, I guess…).

It means that you do not need to log from everywhere. And it’s cool because getting rid of the coupling with the log manager won’t be fun at all.

The solution to avoid coupling: hide the dependency between a logging service

It’s really easy and exposed in the great book Growing Object Oriented Software Guided By Tests. Just wrap the logging stuff in a service. The code above can be nicely refactored to:

public interface LoggingService
{
    void LogDebug(string className, string message);
}

public class Log4NetLoggingService
{
    public void LogDebug(string className, string message)
    {
        var logger = LogManager.GetLogger(className);
        if (logger.IsDebugEnabled) 
        {
            logger.Debug(message);
        }
    }
}

public class Trololo 
{
    private LoggingService loggingService;

    // The logging service in injected through the constructor
    public Trololo(LoggingService loggingService)
    {
        this.loggingService = loggingService;
    }

    public void DoStuff() 
    {
        // It’s still a stupid logging message but anyway…
        loggingService.LogDebug("Entering method DoStuff");
    }
}

The use of the logger is made easier, since I do not have to test for logging level activation in my code. The Dependency Inversion Principle is respected. This is clean code.

You can also unit test the business requirements regarding logging. You just have to create a mock implementation of LoggingService that will give you access to logged messages.

The drawback is that you have to inject the dependency. Therefore, you will not be so prone to log everything from everywhere. You’ll have to choose. Hint: look at what is unsure in your system, that is what is coming from the interfaces. Log what is entered by the user, what you find in your database, network exception. If your inner system is implemented in plain object and thoroughly tested, you exactly know how it behave. Why do you want to put logs in it then? Moreover, what’s beyond your interfaces are dependencies already injected into your system. All you have to do is update your already existing DI configuration to integrate your LoggingService. Et voilà.

TL;DR.

Don’t use the loggers directly. Wrap them behind a service and think about you logging policy. If you disagree, it’s bad because you’re wrong.