Lightweight logging and tracing on top of .NET trace listeners

31 Jan 2015

Even with a large number of logging frameworks to choose from -- NLog, Log4Net, MS Logging Application Block to name a few -- I prefer none of these. They're all decent at what they do, but I dislike taking a dependency on one when all I need is a small fraction of the functionality offered. Especially since a thin wrapper on top of the .NET trace listeners can oftentimes solve my logging needs, even in enterprise scenarios.

I would never venture into writing my own library from scratch. It's a deceptively simple task, complicated by multi-threading and file locking issues already taken care of by .NET trace listeners.

Defining the ILogger interface

In order to decouple client logging code from any particular framework, clients must log through the ILogger interface defined below. It should be mostly self-explanatory as it's modelled closely on Console.WriteLine and String.Format with a format string and values to substitute in. One possible implementation of the interface is then using .NET trace listeners.

public interface ILogger {
    void Verbose(string format, params object[] args);
    void Warning(string format, params object[] args);
    void Error(string format, params object[] args);
}

Implementing the ILogger interface

Now let's implement the ILogger interface in terms of out of the box .NET trace listeners. The beauty of these listeners is that they're typically configured in app.config or web.config, and hence runtime configurable. And we don't have to worry about the bits of pieces of their configuration as it's baked into the .NET framework.

using System;
using System.Linq;
using System.Diagnostics;

public class TraceLogger : ILogger {
    protected enum LogLevel {
        None = 0,
        Verbose,
        Warning,
        Error
    };

    public virtual void Verbose(string format, params object[] args) {
        WriteLine(format, LogLevel.Verbose, args);
    }

    public virtual void Warning(string format, params object[] args) {
        WriteLine(format, LogLevel.Warning, args);
    }

    public virtual void Error(string format, params object[] args) {
        WriteLine(format, LogLevel.Error, args);
    }

    private void WriteLine(string format, LogLevel l, params object[] args) {
        Trace.WriteLine(Format(format, l, args));
    }

    protected string Format(string format, LogLevel l, params object[] args) {
        var frame = new StackFrame(3);
        var method = frame.GetMethod();
        var type = method.DeclaringType;
        var name = method.Name;
        return string.Format(
            "{0} {1} {2}.{3} {4}",
            DateTime.Now.ToUniversalTime(), 
            l.ToString(), type, name, string.Format(format, args));
    }
}

The above implementation defines a fixed format for each entry such that only the actual message to be logged needs to be provided. Here's an example of how to log, although nothing will show in the console until we configure a trace logger:

ILogger l = new TraceLogger();
l.Verbose("1 + 2 = {0}", 1 + 2);

// results in:
// dateAndTimeInUtc | level | callingMethod | message
// 1/31/2015 12:54:41 PM Verbose Testbed.Console.Program.Main 1 + 2 = 3

To have TraceLogger emit log statements to the console and a file, make sure your config file contains the following section. Notice how the TextWriterTraceListener interprets the initializeData as the file name to log to. I default to name the log file the same as the assembly doing the logging:

<configuration>
  <system.diagnostics>
    <trace autoflush="true" indentsize="4">
      <listeners>
        <add name="console" type="System.Diagnostics.ConsoleTraceListener" />
        <add name="file" type="System.Diagnostics.TextWriterTraceListener" initializeData="Bdk.Console.log" />
      </listeners>
    </trace>
  </system.diagnostics>
  ...
</configuration>

Logging with colors

The downside to using ConsoleTraceListener is that it doesn't know about log levels. After all, log levels are local to the TraceLogger implementations. Nevertheless, during debugging it's useful to take advantage of log level information and color code console output accordingly. Warnings should stand out in yellow and errors in red to make them easier to spot.

To stay true to the Liskov Substitution Principle, we must ensure a colored console logger implementation is substitutable with the TraceLogger one. It must keep logging to any registered listener but the ConsoleTraceListener, if one is registered. We want to explicitly trace to the console and with a ConsoleTraceLogger already registered every log message would appear twice.

A custom logger would typically inherit from the .NET TraceLogger class and override the Write and WriteLine methods. This would enable us to add the custom trace listener class to the list of trace listeners in the config file. But as the TraceLogger class has no knowledge of log levels we'd have to add wrapper methods like the Verbose, Warning, and Errors which would call the overridden Write and WriteLine methods.

The TraceLogger derived classes form our low-level building blocks and polluting those with domain details is hardly good design. Instead, the ColoredConsoleLogger derives from TraceLogger and explicitly deals with any registered console logger:

public class ColoredConsoleLogger : TraceLogger {
    public override void Verbose(string format, params object[] args) {
        WriteLine(format, LogLevel.Verbose, System.Console.ForegroundColor, args);
    }

    public override void Warning(string format, params object[] args) {
        WriteLine(format, LogLevel.Warning, ConsoleColor.Yellow, args);
    }

    public override void Error(string format, params object[] args) {
        WriteLine(format, LogLevel.Error, ConsoleColor.Red);
    }

    private void WriteLine(string s, LogLevel l, ConsoleColor foregroundColor, params object[] args) {
        var original = System.Console.ForegroundColor;
        var logLine = Format(s, l, args);

        Trace.Listeners
            .Cast<TraceListener>()
            .Where(tl => tl.GetType() != typeof(ConsoleTraceListener))
            .ToList()
            .ForEach(tl => {
                tl.WriteLine(logLine);
                tl.Flush();
            });

        switch (l) {
            case LogLevel.Verbose:
                System.Console.ForegroundColor = foregroundColor;
                break;
            case LogLevel.Warning:
                System.Console.ForegroundColor = ConsoleColor.Yellow;
                break;
            case LogLevel.Error:
                System.Console.ForegroundColor = ConsoleColor.Red;
                break;
            default:
                throw new ArgumentException("Unsupported log level: " + l);
        }

        System.Console.WriteLine(logLine);
        System.Console.ForegroundColor = original;
    }
}

Conclusion

This ILogger interface and the couple of concrete implementations usually satisfy my requirements. I don't much differentiate between logging, tracing, and instrumentation as one tends to spill over into the other. I also don't limit the amount of output in production and prefer erring on the side of outputting too much. I can always filter the information using grep-like tools and that extra piece of information might come in handy.

Have comments or questions? Please drop me an email or tweet to @ronnieholm.