PublicDomain Logging description and usage

Introduction

This article describes how to use the Logging API in the PublicDomain package. Features of the PublicDomain Logging API include:

• Fully extensible model
• Configuration parser
• Logging on a background thread to avoid performance slow-down due to logging
• Log guards
• CompositeLogger
• FileLogger along with RolloverStrategy
• ApplicationLogger class for quick and dirty logging

PublicDomain

The PublicDomain package is a completely free, public domain collection of oft-needed code and packages for .NET. There is no license, so the code (or any part of it) may be included even in corporate applications. Public domain code has no authority and is provided 'AS-IS'.

High Level Architecture

The architecture was designed with simplicity and extensibility in mind. Some of the concepts include:

Logger Class

Everything is based off the abstract PublicDomain.Logging.Logger class. All of the loggers extend and implement this class. The rest of the classes in the package manipulate instances of Loggers. The reason that an interface was not chosen was to allow for the possibility of future performance enhancements such as conditional compilation.

The basic API of the Logger class:

Properties

• Enabled - A boolean which marks if a Logger is enabled or disabled. This is used for log guards
• Threshold - The severity threshold at which point a log message is logged. For example, if the threshold is Debug, all messages with severity greater than or equal to Debug will be logged. All other messages will be discarded. The default threshold is Warn
• Category - The category of a logger instance is used to give context to a log message. For example, if the message output is:
  
  [2007-08-14T05:09:48 2 Error40 Auditor ] My log message
  
  Then the category is "Auditor"
• Filters - A List of ILogFilter instances which determine if a message is loggable. The default filter is the threshold filter
• Formatter - The ILogFormatter which provides a string with placeholders which is used in string.Format with the log parameters. The formatter creates the final log string which is output.

Methods

• DumpStack() - Prints the current stack along with any passed in parameters where the log statement is. Equivalent to a "Where am I" log statement
• Entry() - Optional design pattern of placing Entry and Exit log calls at the beginning and end of every method
• Exit() - Optional design pattern of placing Entry and Exit log calls at the beginning and end of every method
• Log() - The fundamental Log method which takes a severity, log message, and format parameters. If there are more than 0 format parameters, then the log message will be treated as string.Format(message, formatParameters). If no format parameters are passed in, then the string.Format is optimized away
• LogDebug10() - Calls Log() with Severity = Debug10. The value 10 exists to make it obvious thresholds relative to each other. If a programmer does not use logging often, it may be non-obvious whether Warn is higher than Info
• LogInfo20() - Calls Log() with Severity = Info20. The value 20 exists to make it obvious thresholds relative to each other. If a programmer does not use logging often, it may be non-obvious whether Warn is higher than Info
• LogWarn30() - Calls Log() with Severity = Warn30. The value 30 exists to make it obvious thresholds relative to each other. If a programmer does not use logging often, it may be non-obvious whether Warn is higher than Info
• LogError40() - Calls Log() with Severity = Error40. The value 40 exists to make it obvious thresholds relative to each other. If a programmer does not use logging often, it may be non-obvious whether Warn is higher than Info.
• LogFatal50() - Calls Log() with Severity = Fatal50. The value 50 exists to make it obvious thresholds relative to each other. If a programmer does not use logging often, it may be non-obvious whether Warn is higher than Info.
• LogException() - Useful design pattern for handling logging of exceptions. Uses the proper severity and also creates a message with the full exception details, including details of all inner exceptions.
• Write() - The actual method called from the background thread to finalize the log message.

Configuration Parser

Every application requires a very granular use of logging, which can be dynamically enabled and disabled. Most often, this is specified with a string that has a delimited list of log classes and their appropriate thresholds.

For example, let's say I have class A and class B. I want to load the initial logging parameters through an external configuration file, and later I may want to change the status of each logger.

using System;
using System.Collections.Generic;
using System.Text;
using PublicDomain;
using PublicDomain.Logging;

namespace play
{
    class Program
    {
        public static readonly LoggingConfig Loggers;

        static Program()
        {
            // Create the actual logger which is a rolling file logger
            Logger fileLogger = new RollingFileLogger("mylog{0}.log");
            fileLogger.Formatter = new SimpleLogFormatter();

            // This configuration may be loaded from a resource or
            // from a config file:
            string config = "all=off";

            // Create the logging config. This creates a delegate
            // which will be called any time another part of the code
            // asks for a Logger instance.
            Loggers = new LoggingConfig(config, delegate
                (string className, LoggerSeverity threshold)
            {
                Logger result = new SimpleCompositeLogger
                        (fileLogger, className);
                result.Threshold = threshold;
                return result;
            }, null);
        }

        static void Main(string[] args)
        {
        }
    }

    class A
    {
        /// <summary>
        /// The Logger instance for all methods within class A
        /// </summary>
        internal static readonly Logger Log =
                Program.Loggers.CreateLogger(typeof(A));

        public void foo()
        {
            Log.LogDebug10("calling foo");
        }
    }

    class B
    {
        /// <summary>
        /// The Logger instance for all methods within class B
        /// </summary>
        internal static readonly Logger Log =
                Program.Loggers.CreateLogger(typeof(A));

        public void foo()
        {
            Log.LogInfo20("calling foo {0}", typeof(B).Name);
        }
    }
}

Some ideas from the code above regardless of programming language (in this case C#):

• Notice that there is a public LoggingConfig in the Program class which all other parts of my program should be able to have access to. However those classes decide to create their loggers (in this case internal static readonly), they always go to Program.Loggers
• The code creates a RollingFileLogger. The {0} is replaced with the integer number of the rolling file
• The config variable is what initializes the loggers. "all" represents any loggers not specifically identified in the rest of the string. The value on the other side of the equal sign is the threshold to log at. "off" obviously means don't log at all. You may also put Info, Warn, etc. You may also omit=X and it will log everything (Threshold = Infinity).
• LoggingConfig in the constructor is passed a delegate which is called every time a class asks for a Logger. In this case, it returns a new Logger instance which wraps the RollingFileLogger.

Now that I have various Logger instances in other classes, I can dynamically turn them on or off by passing a new configuration string. By default, we started with all loggers turned off (all=off).

public static void UpdateLoggers(string config)
{
    Loggers.Load(config);
}

We may call this from something that reads input from the user or re-reads a configuration file. Let's say we called it with:

Program.UpdateLoggers("play.A=Debug,play.B");

In this case, we will be setting the threshold of the A class (we need to specify the fully namespace-qualified name) to debug, and the threshold of the B class to infinity (meaning all logging is enabled).

Also, when we ask for a Logger:

Program.Loggers.CreateLogger(typeof(A)); 

In this case, we used the name of the class as the Logger name. We can also pass other things like "logical" class names:

Program.Loggers.CreateLogger("mylogger", "Database"); 

This way, we can update class A's logger, simply by loading the configuration "Database=Debug".

Of course, the value of this is that you can "share" configuration across multiple loggers. If certain classes may deal with database access, you can add this string to all of them, and when you turn on database logging, all of them will log.

Efficiency

Logging efficiency is very important. The two major efficiency improvements in this log package are log guards, and logging on a background thread.

Log Guards

The concept of log guards are pretty simple but very effective. Let's say, I have the following method, which logs entry/exit, and also some debug within the method:

public int foo(int x, int y)
{
    Log.Entry("foo {0},{1},{2}", x, y, x*y);

    // Do some calculation
    int result = x * y * 1984;

    // Log some debug
    Log.LogDebug10("The result mod 7 * 10000 is: {0}", (result % 7) * 10000);

    // Log the exit
    Log.Exit("foo result={0}", result);

    return result;
}

Now, in this case, let's say the Log is turned off. None of these messages will be logged since internally a check will be made and realize that the Logger is off.

However, the .NET JIT and the compiler have no idea that Log.Entry, Log.LogDebug10, and Log.Exit don't really need to be called. Therefore, the runtime will need to create all of the overhead of calling a method, the stacks, etc. Moreover, the runtime will also have to properly process all of the parameters passed to the methods:

Log.Entry("foo {0},{1},{2}", x, y, x*y);
Log.LogDebug10("The result mod 7 * 10000 is: {0}", (result % 7) * 10000);

Both of these methods have non-trivial calculation in their calls. You could imagine that this is very common, and if the Logger is off, a total waste.

To the uninitiated, Log guards seem verbose and very novice, however these are used often in corporate applications and large, unnamed, million line products from major corporations. This is a well studied problem, and this solution is well known:

public int foo(int x, int y)
{
    if (Log.Enabled) Log.Entry("foo {0},{1},{2}", x, y, x*y);

    // Do some calculation
    int result = x * y * 1984;

    // Log some debug
    if (Log.Enabled) Log.LogDebug10("The result mod 7 * 10000 is: {0}",
                            (result % 7) * 10000);

    // Log the exit
    if (Log.Enabled) Log.Exit("foo result={0}", result);

    return result;
}

Notice that each log statement is now "guarded" with "if (Log.Enabled)". This will avoid any unnecessary stack creation or parameter management. Just to mention, if the LoggerConfig is updated and a Logger state is changed (from enabled to disabled, or vice versa), then this code works.

Background Thread Logging

Logging is often turned off in critical sections of the code. Many times, it is needed only to debug a problem. However, often problems are related to race conditions or may not be reproduced if the program slows down significantly. Therefore, when a log is turned on, it is important that it is as efficient as possible.

A naïve implementation of a Logger API would simply Log all messages directly when the Log method is called. However, imagine a high performance section which has a bug in which you need to enable logging. If you are logging to a file (which is most common), all of the overhead of disk access may be incredibly massive.

Therefore, we don't want to log synchronously on the thread that called the Log method. The default implementation of the Logging API is to put all messages on a globally static background thread which is processed every 5 seconds, and the log messages are written out in batch. It is also ensured using the PublicDomain.FinalizableBackgroundThread class that if the program exits with log messages in the queue, that those messages will be written out (unless your program crashes).

ApplicationLogger

Most of the above conversation has been about writing highly scalable, extensible, configurable, and performant logging.

That's all wonderful, but what if I'm writing a pretty small program? I want a quick and dirty logging solution:

ApplicationLogger

using System;
using System.Collections.Generic;
using System.Text;
using PublicDomain;
using PublicDomain.Logging;

namespace play
{
    class Program
    {
        static void Main(string[] args)
        {
            if (ApplicationLogger.Current.Enabled)
        ApplicationLogger.Current.Threshold = LoggerSeverity.Debug10;

            if (ApplicationLogger.Current.Enabled)
        ApplicationLogger.Current.LogDebug10("starting program");

            Console.WriteLine(A.foo(5, 6));

            if (ApplicationLogger.Current.Enabled)
        ApplicationLogger.Current.LogDebug10("ending program");
        }
    }

    class A
    {
        public static int foo(int x, int y)
        {
            if (ApplicationLogger.Current.Enabled)
        ApplicationLogger.Current.Entry("foo {0},{1}", x, y);

            int result = x * y;

            if (ApplicationLogger.Current.Enabled)
        ApplicationLogger.Current.Exit("foo {0}", result);

            return result;
        }
    }
} 

The PublicDomain.Logging.ApplicationLogger class has a Current static Logger which can be used to write to a RollingFileLogger in the CurrentDirectory of the application.

The log guards are of course optional if you don't really care about performance and want "nicer" code.