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 Logger
s. 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()
{
Logger fileLogger = new RollingFileLogger("mylog{0}.log");
fileLogger.Formatter = new SimpleLogFormatter();
string config = "all=off";
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
{
internal static readonly Logger Log =
Program.Loggers.CreateLogger(typeof(A));
public void foo()
{
Log.LogDebug10("calling foo");
}
}
class B
{
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);
int result = x * y * 1984;
Log.LogDebug10("The result mod 7 * 10000 is: {0}", (result % 7) * 10000);
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);
int result = x * y * 1984;
if (Log.Enabled) Log.LogDebug10("The result mod 7 * 10000 is: {0}",
(result % 7) * 10000);
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.