Introduction
log4net is a highly flexible logging framework available for .NET. Now firstly, let me say that this article assumes a basic familiarity with the log4net framework, and is in not intended either as an introduction to log4net or a tutorial in how to configure and use log4net.
If you are unfamiliar with log4net, you can find the documentation here, or have a look at this article on CodeProject.
The Problem
One of my main criticisms of log4net is that I find the syntax somewhat clumsy. Take, for example, the following code to add a line of simple debugging logging:
ILog log = LogManager.GetLogger("MyLog");
if (log.IsDebugEnabled)
{
using (ThreadContext.Stacks["MyProperty"].Push("MyValue"))
{
using(ThreadContext.Stacks["MyOtherProperty"].Push("MyOtherValue"))
{
log.Debug("This is a debugging message.");
}
}
}
Dim log As ILog = LogManager.GetLogger("MyLog")
If log.IsDebugEnabled Then
Using ThreadContext.Stacks("MyProperty").Push("MyValue")
Using ThreadContext.Stacks("MyOtherProperty").Push("MyOtherValue")
log.Debug("This is a debugging message.")
End Using
End Using
End If
As you can see, performing what should be a simple logging operation takes up about half-a-dozen lines of code. Clearly for even the smallest application, littering the code with statements like those just shown, simply for logging purposes, is not exactly desirable and would soon become unreadable as the logging code starts to drown out the logic code.
What is needed is a solution whereby a logging operation can be accomplished with a single line of code.
The Solution
My solution is a static class, called Logger
, which has two methods (plus overloads): Initialize()
to initialize log4net, and Log()
which actually performs the logging operation
Firstly, let's look at the Initialize()
method. This has two overloads: one takes a single parameter which specifies the config file to be used by log4net. The parameterless overload specifies that log4net should pull its configuration from web.config or app.config:
private static bool isInitialized;
public static void Initialize()
{
Initialize(null);
}
public static void Initialize(string configFile)
{
if (!isInitialized)
{
if (!String.IsNullOrEmpty(configFile))
XmlConfigurator.ConfigureAndWatch(new FileInfo(configFile));
else
XmlConfigurator.Configure();
isInitialized = true;
}
else
throw new LoggingInitializationException(
"Logging has already been initialized.");
}
Private _isInitialized As Boolean
Public Sub Initialize()
Initialize(Nothing)
End Sub
Public Sub Initialize(ByVal configFile As String)
If Not _isInitialized Then
If Not String.IsNullOrEmpty(configFile) Then
XmlConfigurator.ConfigureAndWatch(New FileInfo(configFile))
Else
XmlConfigurator.Configure()
End If
_isInitialized = True
Else
Throw New LoggingInitializationException("Logging has already been initialized.")
End If
End Sub
Next, we'll look at the Log()
method and its overloads. These methods accept various combinations of the following parameters:
Parameter | Description |
---|
logName | The name of the log to write the event to. If omitted, the event is written to all logs. |
loggingLevel | The level (debug, info, warning, error or fatal) of the event. |
message | The message. |
loggingProperties | An object whose properties map to log4net PatternLayout properties (e.g.: %property{Foo} where Foo is the name of the property). |
exception | The exception (if any) to be logged. |
All of the Log()
method overloads ultimately call LogBase()
which is where the actual calls to log4net are made. The code for this method is as follows:
private static void LogBase(ILog log, LoggingLevel loggingLevel,
string message, object loggingProperties, Exception exception)
{
if (ShouldLog(log, loggingLevel))
{
PushLoggingProperties(loggingProperties);
switch (loggingLevel)
{
case LoggingLevel.Debug: log.Debug(message, exception); break;
case LoggingLevel.Info: log.Info(message, exception); break;
case LoggingLevel.Warning: log.Warn(message, exception); break;
case LoggingLevel.Error: log.Error(message, exception); break;
case LoggingLevel.Fatal: log.Fatal(message, exception); break;
}
PopLoggingProperties(loggingProperties);
}
}
Private Sub LogBase(ByVal log As ILog, ByVal loggingLevel As LoggingLevel, _
ByVal message As String, ByVal loggingProperties _
As Object, ByVal exception As Exception)
If ShouldLog(log, loggingLevel) Then
PushLoggingProperties(loggingProperties)
Select Case loggingLevel
Case VisualBasic.LoggingLevel.Debug
log.Debug(message, exception)
Case VisualBasic.LoggingLevel.Info
log.Info(message, exception)
Case VisualBasic.LoggingLevel.Warning
log.Warn(message, exception)
Case VisualBasic.LoggingLevel.Error
log.Error(message, exception)
Case VisualBasic.LoggingLevel.Fatal
log.Fatal(message, exception)
End Select
PopLoggingProperties(loggingProperties)
End If
End Sub
As you can see, the first call made by this method is to the ShouldLog()
method, which determines whether or not the event should be logged, based on the current logging level:
private static bool ShouldLog(ILog log, LoggingLevel loggingLevel)
{
switch (loggingLevel)
{
case LoggingLevel.Debug: return log.IsDebugEnabled;
case LoggingLevel.Info: return log.IsInfoEnabled;
case LoggingLevel.Warning: return log.IsWarnEnabled;
case LoggingLevel.Error: return log.IsErrorEnabled;
case LoggingLevel.Fatal: return log.IsFatalEnabled;
default: return false;
}
}
Private Function ShouldLog(ByVal log As ILog, _
ByVal loggingLevel As LoggingLevel) As Boolean
Select Case loggingLevel
Case VisualBasic.LoggingLevel.Debug
Return log.IsDebugEnabled
Case VisualBasic.LoggingLevel.Info
Return log.IsInfoEnabled
Case VisualBasic.LoggingLevel.Warning
Return log.IsWarnEnabled
Case VisualBasic.LoggingLevel.Error
Return log.IsErrorEnabled
Case VisualBasic.LoggingLevel.Fatal
Return log.IsFatalEnabled
Case Else
Return False
End Select
End Function
If this method returns true
, the next method to be called is PushLoggingProperties()
. This takes the loggingProperties
parameter and uses Reflection to push the values of each of the properties onto the log4net ThreadContext
stack:
private static void PushLoggingProperties(object loggingProperties)
{
if (loggingProperties != null)
{
Type attrType = loggingProperties.GetType();
PropertyInfo[] properties = attrType.GetProperties(
BindingFlags.Public | BindingFlags.Instance);
for (int i = 0; i < properties.Length; i++)
{
object value = properties[i].GetValue(loggingProperties, null);
if (value != null)
ThreadContext.Stacks[properties[i].Name].Push(value.ToString());
}
}
}
Private Sub PushLoggingProperties(ByVal loggingProperties As Object)
If Not loggingProperties Is Nothing Then
Dim attrType As Type = loggingProperties.GetType()
Dim properties() As PropertyInfo = attrType.GetProperties(
BindingFlags.Public Or BindingFlags.Instance)
For i As Integer = 0 To properties.Length - 1 Step +1
Dim value As Object = properties(i).GetValue(loggingProperties, Nothing)
If Not value Is Nothing Then
ThreadContext.Stacks(properties(i).Name).Push(value.ToString())
End If
Next
End If
End Sub
Next, the code calls the appropriate logging method on the log4net ILog
object, based on the current logging level. This is followed by a call to the PopLoggingProperties()
which simply performs the reverse of PushLoggingProperties()
and pops the properties off the stack.
Some Examples
Here are some examples of the Logger
class in action. In these examples, we are using the following PatternLayout
:
<layout type="log4net.Layout.PatternLayout">
<conversionPattern
value="%date [%thread] %-5level %logger [%property{User}]:
%{property{Environment} - %message%newline%exception" />
</layout>
Logger.Initialize();
Logger.Log(LoggingLevel.Debug, "Calling method Foo().",
new { User = "Joe Bloggs", Environment = "UAT" });
try
{
int i = 25;
int j = 0;
int foo = i / j;
}
catch (DivideByZeroException ex)
{
Logger.Log("ErrorLog", LoggingLevel.Error, "Attempted to divide by zero.",
new { User = "Fred Bloggs", Environment = "Production" }, ex);
}
Logger.Initialize()
Logger.Log(LoggingLevel.Debug, "Calling method Foo().", _
New With {.User = "Joe Bloggs", .Environment = "UAT"})
Try
Dim i As Integer = 25
Dim j As Integer = 0
Dim foo As Integer = CInt(i / j)
Catch ex As DivideByZeroException
Logger.Log("ErrorLog", LoggingLevel.Error, "Attempted to divide by zero.", _
New With {.User = "Fred Bloggs", .Environment = "Production"}, ex)
End Try
Summary
With a simple wrapper, it is possible abstract away the code for interacting with the log4net framework, and at the same time improve the readability of our code by reducing logging operations to single lines.
You can download the complete code from here.