matthew daugherty

Project Setup

We’ll begin by creating a console application, integrating log4net, and making a test logging call. One of the benefits of using log4net is how easily it can be added to a project.

Project Setup

First we need to create the basic application structure:

• Create a new Blank Solution named OrgChart
• Add a Console Application project named “OrgChart.UI”
• Add an Application Configuration File (App.config) to the project
• Add a Class Library project named “OrgChart.Data”
• Remove the file “Class1.cs” from the project
• Add a reference to the Data project into the UI project

Assuming you have already downloaded and unpacked log4net, add a reference to log4net.dll into both projects.

Configuration

Next we need to configure log4net. Define the configuration section by adding the following block to App.config:

<configuration>
  <configSections>
    <section name="log4net" type="log4net.Config.Log4NetConfigurationSectionHandler, log4net" />
  </configSections>
</configuration>

Now you can add the configuration section:

<configuration>
  ...
  <log4net>
    <appender name="ConsoleAppender" type="log4net.Appender.ConsoleAppender">
      <layout type="log4net.Layout.SimpleLayout" />
    </appender>
    <root>
      <level value="ALL" />
      <appender-ref ref="ConsoleAppender" />
    </root>
  </log4net>
</configuration>

This configuration block instructs the root (default) Logger to accept all log messages. It also associates the root Logger with an Appender that will write logged messages to the console. Loggers are the objects you will interact with in code. They expose the ILog interface which provides the methods used to log messages. Loggers are also responsible for filtering messages based on their level. Appenders are responsible for handling the messages sent to the Loggers. There are Appenders available for a variety of output destinations such as flat files, databases, and email. Multiple Appenders may be defined for an application. A list of Appenders and configuration samples are available on the log4net project site.

As the last configuration step, add the following line to the end of the AssemblyInfo.cs file in the UI project:

[assembly: log4net.Config.XmlConfigurator(Watch=true)]

This attribute instructs log4net to load its configuration from the application’s configuration file. It is possible to configure log4net to read its configuration from a different file. Setting the Watch parameter to true causes log4net to actively monitor the configuration file for changes.

Creating and Using a Logger

A logger object can be acquired by calling LogManager.GetLogger(). For reasons that will be explained shortly, you will typically create a static instance of a logger in each of your classes. Logging methods are exposed through the ILog interface.

The following code shows the complete console application:

using System;
using log4net;

namespace OrgChart.UI
{
    class Program
    {
        private static ILog _log = LogManager.GetLogger(typeof(Program));

        static void Main(string[] args)
        {
            _log.Info("OrgChart start");

            // TODO: add code here

            _log.Info("OrgChart stop");
            Console.WriteLine("Press [Enter] to exit...");
            Console.ReadLine();
        }
    }
}

Run the application and you should see the following output:

INFO - OrgChart start
INFO - OrgChart stop
Press [Enter] to exit...

That’s a good start; everything we need to use log4net is in place and working. Let’s move forward and explore the features log4net offers in more detail.

Logging Methods and Message Levels

Now that the basic structure of the application is in place we can get down to the business at hand: creating an org-chart and modeling office behavior. Begin by creating a class named “Employee” in the data project:

using System;
using log4net;

namespace OrgChart.Data
{
    public class Employee
    {
        private static ILog _log = LogManager.GetLogger(typeof(Employee));

        public string FirstName { get; private set; }
        public string LastName { get; private set; }

        public Employee(string firstName, string lastName)
        {
            FirstName = firstName;
            LastName = lastName;
            _log.Debug( String.Format("Employee {0} {1} created", FirstName, LastName ));
        }
    }
}

Note the logging call in the constructor. While developing the application it may be useful to confirm that a new Employee was created, but once the application is complete we would only want to log down to this detail when debugging a problem. This is a perfect time to use the Debug() method of the logger.

The ILog interface provides the following methods:

• Debug(Object message)
• Info(Object message)
• Warn(Object message)
• Error(Object message)
• Fatal(Object message)

The level of the message is determined by the method used. Also note that the message parameter is of type Object, not String. Non-string messages are automatically converted to strings via their ToString() method unless a custom log4net Object Renderer has been created and registered for the message type. All of these methods have a second signature that takes a message and an exception. When an exception is passed its message and stack trace will be logged along with the message object.

We can’t have our employees running amok so we will need some managers. Create a class named “Manager” in the data project. This class derives from Employee and contains a list of Employees.

using System;
using System.Collections.Generic;
using log4net;

namespace OrgChart.Data
{
    public class Manager : Employee
    {
        private static ILog _log = LogManager.GetLogger(typeof(Manager));

        private List<Employee> _employees = new List<Employee>();

        public Manager(string firstName, string lastName)
            : base(firstName, lastName) { }

        public void AddEmployee(Employee employee)
        {
            _employees.Add(employee);
        }
    }
}

Our hypothetical office has the following structure:

• Alice Anderson
• Bob Baker
• Carol M Conner
• David Dunn
• Carol A Conner

It’s unfortunate that the data model does not support middle initial since we have two employees named Carol Conner. Too late to change it now so let’s move forward. Add the following code to the Program class to create the office staff:

using OrgChart.Data;
...
_log.Info("OrgChart start");

Manager alice = new Manager("Alice", "Anderson");
Manager bob = new Manager("Bob", "Baker");
Employee carolM = new Employee("Carol", "Conner");
Manager david = new Manager("David", "Dunn");
Employee carolA = new Employee("Carol", "Conner");

alice.AddEmployee(bob);
alice.AddEmployee(david);
bob.AddEmployee(carolM);
david.AddEmployee(carolA);

_log.Info("OrgChart stop");

Run the application and you should see the following output:

INFO - OrgChart start
DEBUG - Employee Alice Anderson created
DEBUG - Employee Bob Baker created
DEBUG - Employee Carol Conner created
DEBUG - Employee David Dunn created
DEBUG - Employee Carol Conner created
INFO - OrgChart stop
Press [Enter] to exit...

Now that we have confirmed that the Employee objects are being created we really don’t want the debug messages showing up in the log. We also do not want to incur the overhead of the unneeded logging calls, especially if using an off-box store. We could comment out the logging statements or wrap them with #if DEBUG but then we would have to rebuild and redeploy if we want to debug a problem in production.

This situation is addressed in log4net by the loggers. Each logger may define a minimum level that a message must meet or exceed in order to be logged. You can configure this level by adjusting the element in the logger’s configuration block. The possible values from least restrictive to most are:

• ALL
• DEBUG
• INFO
• WARN
• ERROR
• FATAL
• OFF

As you can see, these correspond directly to the logging methods exposed by ILog. ILog methods that fall below the minimum level are ignored by the logger. This evaluation does add overhead but it is negligible.

Change the value attribute of the root logger’s element to “INFO”…

<root>
  <level value="INFO" />
  <appender-ref ref="ConsoleAppender" />
</root>

…and then run the application:

INFO - OrgChart start
INFO - OrgChart stop
Press [Enter] to exit...

Just what we wanted; the DEBUG level messages no longer appear in the log. But what if you want different components to use different levels? Let’s look at that next.

Logger Configuration and Hierarchical Logging

Time to put people to work. Add the following method to the Employee class…

virtual public void DoWork()
{
	_log.Info(String.Format("{0} {1} is doing some work", FirstName, LastName));
}

…and the following method to the Manager class:

public override void DoWork()
{
	_log.Info(String.Format("{0} {1} is delegating", FirstName, LastName));

	foreach (Employee employee in _employees)
	{
		employee.DoWork();
	}
}

Now add the following line to the console application:

david.AddEmployee(carolA);

alice.DoWork();

_log.Info("OrgChart stop");

Running the application will show everyone busy:

INFO - OrgChart start
INFO - Alice Anderson is delegating
INFO - Bob Baker is delegating
INFO - Carol Conner is doing some work
INFO - David Dunn is delegating
INFO - Carol Conner is doing some work
INFO - OrgChart stop
Press [Enter] to exit...

Let’s make one refinement. The INFO messages being logged by the UI are not really that interesting and have nothing to do with tracking employee activity. We should change the configuration so that only ERROR messages from the UI are logged. INFO messages from the data model should continue to be logged.

Now is a good time to discuss one of the core features of log4net: hierarchical logging. When a Logger is created it is inserted into a virtual tree of Loggers based on its name. For example, when a logger named “OrgChart.Data.Employee” is created it is automatically considered to be a descendent of the loggers “OrgChart” and “OrgChart.Data”, even if those Loggers have not been created. At the root of the virtual tree is the root logger. It is created automatically and cannot be accessed directly.

As you probably guessed, the element in the log4net configuration controls the Root Logger. This brings up an important point; recall that when we created the Logger in the console application we passed the type of the class:

private static ILog _log = LogManager.GetLogger(typeof(Program));

This resulted in a Logger named “OrgChart.UI.Program”. However, when we adjusted the level of the root logger it was still affected. This is because Logger configuration is inherited. Unless overridden at some level in the virtual tree, every Logger inherits the settings of the root logger.

To specify the settings for a particular logger you can add a element to the log4net configuration:

<root>
  <level value="INFO" />
  <appender-ref ref="ConsoleAppender" />
</root>
<logger name="OrgChart.UI">
  <level value="ERROR" />
</logger>
...

Note that the new element does not contain an element. In this case the OrgChart.UI Logger will evaluate a message’s level but not forward it to an Appender. Instead it will pass the message up the Logger hierarchy until it reaches a Logger with an Appender reference. The level of the message is not reevaluated by the higher-level Loggers.

A quick run shows that the INFO level messages from the UI are no longer being logged:

INFO - Alice Anderson is delegating
INFO - Bob Baker is delegating
INFO - Carol Conner is doing some work
INFO - David Dunn is delegating
INFO - Carol Conner is doing some work
Press [Enter] to exit...

Note that we accomplished this by configuring the logger named “OrgChart.UI”, not the logger we are actually creating in code which is named “OrgChart.UI.Program”. You may configure any Logger in the virtual tree regardless of whether it is actually in use; subordinate Loggers will automatically apply the configuration if they are created. By configuring the “OrgChart.UI” logger we are insulating the application against future changes. If a new UI class named “OrgChart.UI.Report” is created it will automatically adopt the correct logging policy.

Contexts and Layouts

Now that we have a detailed log of employee activity, Alice Anderson has approached us and asked us to confirm that Carol M is showing up for work. The five log messages that are showing up are clearly too much data to visually scan through so we need to find a way to filter out messages for employees other than Carol M.

log4net includes several filter classes, but before we jump into that we have a bigger problem: what exactly are we going to filter on? The log messages for Carol M and Carol A are identical. In order to differentiate the messages we will need some additional context.

In a multi-user, multi-application environment it can be difficult to isolate the logging data you are looking for. You may want to trace a single user’s activity or isolate exceptions based on a server name. To facilitate this log4net allows you to tag log messages with developer-defined identifiers called Context Properties.

The factory class used to create a Context Property determines its scope. For example, Context Properties created using the ThreadContext class are in-scope for all logging calls that occur on the same thread. A detailed discussion of Contexts and scope can be found on the log4net project site.

Let’s start with a simple example. Assume that our application is being used to model offices for several different companies. In order to distinguish our five employees we will create a Context Property named “Company”. Add the following line to the Main() method:

static void Main(string[] args)
{
	ThreadContext.Properties["Company"] = "ACME";

	_log.Info("OrgChart start");

Every logging call on this thread will now be tagged with the “Company” property. However, if you run the application you will not see this information appear in the log. This is because the SimpleLayout associated with the Appender does not print Context Properties. We’ll need to address this before we move on.

As mentioned above, Appenders are responsible for sending a log message to a particular destination, but the format of that message is determined by a Layout. The SimpleLayout class is useful for quick testing but is not appropriate for normal use. Let’s make a quick change to the log4net configuration:

<appender name="ConsoleAppender" type="log4net.Appender.ConsoleAppender">
	<!--<layout type="log4net.Layout.SimpleLayout" />-->
	<layout type="log4net.Layout.PatternLayout">
		<conversionPattern value="%-5level [%property{Company}] - %message%newline" />
	</layout>
</appender>

The PatternLayout class allows you to define the format of messages using a set of tokens. In this example we are going to output the message level (padded to 5 characters), the “Company” Context Property, and the message. A complete list of tokens appears in the PatternLayout documentation.

If we run the application now you will see the “Company” Context Property value:

INFO  [ACME] - Alice Anderson is delegating
INFO  [ACME] - Bob Baker is delegating
INFO  [ACME] - Carol Conner is doing some work
INFO  [ACME] - David Dunn is delegating
INFO  [ACME] - Carol Conner is doing some work
Press [Enter] to exit...

How can we use Context Properties to help distinguish between Carol M and Carol A? One approach would be to differentiate them by manager. Within each manager’s DoWork() method we could set a Context Property named “Manager” but this is problematic. What if there are multiple levels of managers? In that case each Manager would need to set the Context Property back to its previous value when the method exits. What happens if an exception is thrown and the context is not cleaned up? How would you adapt this approach if you needed to filter by someone’s grand-manager?

log4net provides a solution to this problem in the form of Context Stacks. A Context Stack is just like a Context Property except it is a stack; multiple values can be pushed into it and then popped out when appropriate. An example will make this clearer. Update the Manager.DoWork() method so that it looks like this:

public override void DoWork()
{
	_log.Info(String.Format("{0} {1} is delegating", FirstName, LastName));

	using (ThreadContext.Stacks["Manager"].Push(String.Format("({0} {1})", FirstName, LastName)))
	{
		foreach (Employee employee in _employees)
		{
			employee.DoWork();
		}
	} // value will be popped off the stack here
}

Before work is delegated the manager’s name is pushed into the “Manager” Context Stack. Notice how log4net makes use of the IDisposable pattern to make sure that the value is popped back out when the block is exited. Context Stacks are added to the Layout using the same syntax as Context Properties:

<layout type="log4net.Layout.PatternLayout">
	<conversionPattern value="%-5level [%property{Company}] [%property{Manager}] - %message%newline" />
</layout>

Run the application now…

INFO  [ACME] [(null)] - Alice Anderson is delegating
INFO  [ACME] [(Alice Anderson)] - Bob Baker is delegating
INFO  [ACME] [(Alice Anderson) (Bob Baker)] - Carol Conner is doing some work
INFO  [ACME] [(Alice Anderson)] - David Dunn is delegating
INFO  [ACME] [(Alice Anderson) (David Dunn)] - Carol Conner is doing some work
Press [Enter] to exit...

…and you will see that the messages contain the full reporting hierarchy of the Employee. This gives us a clear way to distinguish between Carol M and Carol A so let’s start filtering.

Filtering

A Filter is an object that controls which messages are processed by an Appender. Filters do not affect Loggers; filtering out DEBUG messages does not disable the ILog.Debug() method in the same way that the logger configuration does. A Filter only affects the Appender for which it is defined.

The Filter classes provided by log4net perform matching based on a given message characteristic. For example, one of the classes we will be using is the PropertyFilter class which matches a specified pattern against the value of a Context Property . A complete list of Filter classes can be found on the log4net project site.

If multiple Filters are defined for an Appender they form a pipeline in which each Filter votes on the message as it passes through. Filters may return an Accept, Deny, or Neutral vote. Accept causes the message to be immediately logged, Deny causes the message to be immediately discarded, and Neutral allows the message to be passed on to the next Filter in the pipeline. If a message reaches the end of the pipeline with no Deny votes then it is logged. By default most filters will return Accept on a match or Neutral on a non-match. To configure a Filter to return Deny on a match you can add to the filter definition.

The filter we want to define is something like “all messages that contain “Carol Conner” and have a Manager property that contains “Bob Baker”. Unfortunately, you can not combine filters to create and/or logic. This is where an understanding of how the Filter pipeline works comes in handy. Add the following filters to the ConsoleAppender:

<appender name="ConsoleAppender" type="log4net.Appender.ConsoleAppender">
  ...
  <filter type="log4net.Filter.PropertyFilter">
	<Key value="Manager" />
	<RegexToMatch value="^((?!Bob Baker).)*$" />
	<AcceptOnMatch value="false" />
  </filter>
  <filter type="log4net.Filter.StringMatchFilter">
	<StringToMatch value="Carol Conner" />
  </filter>
  <filter type="log4net.Filter.DenyAllFilter" />
</appender>

The first filter evaluates a message’s “Manager” Context Property. It is making use of the element which may be used instead of the element. The regular express translates to “does not contain Bob Baker”. Note that we have also included the element and set its value attribute to false. The net effect is that this filter will deny (and therefore immediately discard) any message that does not have a “Manager” Context Property that contain “Bob Baker”. All other messages will receive a neutral vote and be passed on to the next filter.

The first filter is enough to remove Carol A, but it is not specifically isolating Carol M. Any employee of Bob Baker would pass this filter. To tighten this down the second filter will accept (and therefore immediately log) any message that contains “Carol Conner”. All other messages (such as those for Bob’s other employees) will receive a neutral vote and be passed on to the next filter. Finally, the third filter will deny all messages. This prevents a message from being logged unless a previous Filter has specifically Accepted it.

We’ve finally accomplished our task. Run the application and you will see the log message that confirms Carol M is hard at work:

INFO  [ACME] [(Alice Anderson) (Bob Baker)] - Carol Conner is doing some work
Press [Enter] to exit...

Performance

One concern about heavily instrumenting code is the impact it will have on performance. There is a detailed discussion of this topic on the log4net project site. Assuming that you are willing to incur the overhead of conditional logging, there is one situation you should still watch out for. Add the following method to the Employee class…

public string GetLunchDestination()
{
	System.Threading.Thread.Sleep(5000);
	return "I don't know, where do you want to go?";
}

…and then add this line to the Program class:

alice.DoWork();

_log.Debug("Lunch Destination: " + bob.GetLunchDestination());

_log.Info("OrgChart stop");

Run the application and watch for the pause before “Press [Enter] to exit…” appears. Even though DEBUG messages are disabled, the parameters to the call were still evaluated. This resulted in an unnecessary (and expensive) operation being performed. The solution recommended by the log4net documentation is to check the status of the logger before making the logging call. For example:

if (_log.IsDebugEnabled)
{
	_log.Debug("Lunch Destination: " + bob.GetLunchDestination());
}

This does introduce a second evaluation, but that is much faster than processing the parameters in this case. You may also want to use this approach when you are logging an object that has a non-trivial ToString() method. If you are just logging simple values there is no benefit to checking the logger status first.

Wrapping Up…

So there you go, you’re an expert! log4net is well documented so any topic you would like more information on is most likely covered somewhere on the log4net project site.

I have a few additional tips on using log4net but I will save those for a future post.

Leave a Reply

Cancel

Name (required)

Mail (required)

Website

CAPTCHA Code *