Logging (Developer side)

 21 May 2015 -  Giulio Vian -  ~4 Minutes

I wrote lot of code in my life, and I discovered some patterns that can be useful to other people, so let’s share and discuss. More than design patterns, they are ways of applying classical Gang of Four Design Patterns   in specific contexts.

Today, I will start discussing writing logging and monitoring code, and you will see why I take these two together. The code examples use the C# language, but the ideas can be equally applied to C++, Java, Go or any other object oriented language with an interface feature that decouples implementation from definition.

The common way

A typical logging code goes like this

    Item[] Process(Item[] items)
    {
        logger.Debug("Entered Process");
        for (int i = 0; i < 10; i++)
        {
            logger.Info("About to process item #{0}", i);
            // ...
        }
        logger.Debug("Exiting Process");
    }

with logger being some kind of semi-global variable that represents the entry point to the logging library or subsystem. Info and Debug methods resemble the log4J/log4net style.

Why I do not like it

What is wrong with it? Many things:

1. There is no clear distinction between application code and infrastructure code;
2. Formatting information is dispersed throughout the application;
3. Positional loosely typed arguments;
4. Hard-coded strings, that is no built-in localization;
5. Dependence on a specific logging library;
6. Logging code is scattered in all source files impeding global changes.

What I propose

I propose a different approach that almost completely decouples application code from infrastructure code.

    Item[] Process(Item[] items)
    {
        logger.EnteredProcess();
        for (int i = 0; i < 10; i++)
        {
            logger.AboutToProcessItem(i);
            // ...
        }
        logger.ExitingProcess();
    }

here logger is an instance of a class that implements an interface ILogEvents or similar.

public interface ILogEvents
{
    void EnteredProcess();
    void AboutToProcessItem(int i);
    void ExitingProcess();
}

class ConsoleLogger : ILogEvents
{
    public void EnteredProcess()
    {
        Console.WriteLine("Entered Process");
    }
    public void AboutToProcessItem(int i)
    {
        Console.WriteLine("About to process item #{0}", i);
    }
    public void ExitingProcess()
    {
        Console.WriteLine("Exiting Process");
    }
}

note that the caller is completely decoupled from implementation. Logging can be on a file or in a window of a GUI application.

The idea that the caller signal an event to the logging and monitoring infrastructure, means that implementation can be much richer. Let’s add some monitoring information.

class ConsoleLogger : ILogEvents
{
    var processStopwatch = new Stopwatch();
    public void EnteredProcess()
    {
        processStopwatch.Restart();
        Console.WriteLine("Entered Process");
    }
    //...
    public void ExitingProcess()
    {
        processStopwatch.Stop();
        Console.WriteLine("Exiting Process after {0} ms", processStopwatch.ElapsedMilliseconds);
    }
}

or fancy formatting

    public void AboutToProcessItem(int i)
    {
        ConsoleColor save = Console.ForegroundColor;
        Console.ForegroundColor = ConsoleColor.Cyan;
        Console.WriteLine("[Info ] About to process item #{0}", i);
        Console.ForegroundColor = save;
    }

or localization

class ConsoleLogger : ILogEvents
{
    ResourceManager resmgr = new ResourceManager("MyApplication.LoggingMessages", 
                          Assembly.GetExecutingAssembly());
    public void EnteredProcess()
    {
        // in a server context, you should pick from configuration or system CurrentCulture
        Console.WriteLine(resmgr.GetString("EnteredProcess",Thread.CurrentThread.CurrentUICulture));
    }
    
    //...
}

The caller never changes: no need to recompile!

I let the reader refactor this code in common classes or using a library. The crucial part is the separation of concern between application code and infrastructural code.

No pain, no gain

No approach is perfect and this has also its drawbacks. Let’s enumerate some.

1. A gargantuan interface with tens or hundreds of methods;
2. The reference to the object implementing the interface must be passed around from high-level classes to lesser ones;
3. The class implementing the interface tends to know all kind of types.

This latter requires an explanation; imagine that we pass, not just the index, but the Item we are about to process:

    logger.AboutToProcessItem(i, items[i]);

as a consequence our ILogEvents interface will reference the Item type.

public interface ILogEvents
{
    void EnteredProcess();
    void AboutToProcessItem(int i, Item item);
    void ExitingProcess();
}

The caller code is simpler, but couples the interface and the implementer class. At least, re-compiling is required. The balance here is similar to writing good unit tests and make them robust in face of refactoring and changes.

Mitigation

These problems can be mitigated by using multiple logging interfaces — a good rule of thumb, can be one interface per module or assembly. The logger object can be stored in some pseudo-global variable, to avoid passing it around. As usual, you must be careful when code is multi-threaded or asynchronous.

Final words

My proposal is no rocket science, but I would like to see if it has been used elsewhere. Could be that I am the only one who had to fight with code so poorly instrumented, to be forced going to the draw-board.