Coding Cockerel

Picking up the code from the previous post, let’s add another appender to the config file as this helps to demonstrate the relationship between loggers and appenders.

log4net provides an SmtpAppender which will send out log messages via email. This is useful for high priority messages such as errors, as the recipients are notified of a problem immediately rather than being contacted by disgruntled users. There is also no need to search the log files as the relevant information is contained in the email. The following snippet is an example of how to configure the SmtpAppender

<appender name="EmailAppender" type="log4net.Appender.SmtpAppender">
    <to value="foo@bar.com" />
    <from value="LoggingDemo website &lt;email.appender@foo.com&gt;" />
    <subject value="Message from LoggingDemo website" />
    <smtpHost value="exchange.foo.com" />
    <bufferSize value="0" />
    <layout type="log4net.Layout.PatternLayout">
        <conversionPattern value="%date{yyyy-MM-dd HH:mm:ss.fff} %-5level %message%newline" />
    </layout>
</appender>

The majority of the settings are self-explanatory, however it is worth noting that buffer size is set to zero. Had this been omitted the default of 512 would have been used, meaning that only when the buffer had 512K or more of logs would an email be sent, containing all of the messages. Setting the buffer size to zero will cause each log message to be sent in a separate email.

The appender can be added to the root logger using an appender-ref node in exactly the same way that the text file appender was. If you run the sample site again a log message will be appended to the LoggingDemo.log file and sent to the specified email address.

Capturing more detail about exceptions

So far we’ve just been logging simple messages. In the case of logging errors, messages such as “an error occurred”, or even the exception’s Message property, do not provide enough detail to diagnose a fault. However the logging methods (Warn, Error, and so on) on the ILog interface actually allow any object to be passed as the message – it does not have to be a string. So if we pass in an Exception object log4net will transform that into text before passing it to all of the logger’s appenders. If you try this you’ll see that properties such as the type of exception, the message and the stack trace are all recorded.

This is a reasonable solution although still short of the ideal. Other properties of the exception such as TargetSite, Source and Data (a little-known but useful dictionary in which extra error information can be stored) are not logged. Furthermore, in a web scenario you may wish to log data such as the URL of the request, the session ID, and so on.

What is needed is complete control over how an exception message is formatted before being sent to the appenders. This is where the IObjectRenderer interface comes in. We can create an exception renderer which, when registered in the config file, will be used each time log4net needs to convert an Exception into text before it is logged. So let’s do just that.

Creating and configuring the ExceptionRenderer class

Add a new class to the project called ExceptionRenderer, import the log4net.ObjectRenderer namespace, and make the class implement the IObjectRenderer interface. There is just one method to implement, RenderObject, and it provides us with a TextWriter to write our message with. From here it is pretty simple to cast the obj argument to an Exception and start writing out the properties, as shown below

public class ExceptionRenderer : IObjectRenderer
{
    public void RenderObject(RendererMap rendererMap, object obj, TextWriter writer)
    {
        Exception thrown = obj as Exception;
        while (thrown != null)
        {
            RenderException(thrown, writer);
            thrown = thrown.InnerException;
        }
    }

    private void RenderException(Exception ex, TextWriter writer)
    {
        writer.WriteLine(string.Format("Type: {0}", ex.GetType().FullName));
        writer.WriteLine(string.Format("Message: {0}", ex.Message));
        writer.WriteLine(string.Format("Source: {0}", ex.Source));
        writer.WriteLine(string.Format("TargetSite: {0}", ex.TargetSite));
        RenderExceptionData(ex, writer);
        writer.WriteLine(string.Format("StackTrace: {0}", ex.StackTrace));
    }

    private void RenderExceptionData(Exception ex, TextWriter writer)
    {
        foreach (DictionaryEntry entry in ex.Data)
        {
            writer.WriteLine(string.Format("{0}: {1}", entry.Key, entry.Value));
        }
    }
}

Note that the while loop ensures that all inner exceptions are also logged.

To make log4net aware of the renderer add the following line of XML under the root log4net node

<renderer renderingClass="LoggingDemo.ExceptionRenderer, LoggingDemo" renderedClass="System.Exception" />

The important point to note here is that the fully-qualified names of the classes must be used, much like when defining the appender’s type.

In order to test the renderer add a button to the default page and in its click handler add a call to a method which throws an exception. Then wrap this call in a try-catch block and, in the catch part, log the exception by passing it into the logger’s Error method. The code below should suffice

protected void ThrowButton_Click(object sender, EventArgs e)
{
    try
    {
        DoSomething();
    }
    catch (Exception ex)
    {
        ILog logger = LogManager.GetLogger(string.Empty);
        logger.Error(ex);
    }
}

private void DoSomething()
{
    ApplicationException ex = new ApplicationException("DoSomething() has failed.");
    ex.Data.Add("SomeKey", "SomeValue");
    ex.Data.Add("AnotherKey", "AnotherValue");
    throw ex;
}

The log file should now contain a well-formatted message listing all of the exception’s properties. As projects develop the ExceptionRenderer can be enhanced to record any other information you see fit.

Going further

The idea of producing custom renderers extends beyond exceptions. I mentioned logging web-specific data earlier; the best approach to this is to implement an HttpContextRenderer which would then output the URL, the query string, etc. Then the HttpContext object itself can just be passed straight into one of the logging methods of the logger.

The sample web application for this post is available here.

Logging is a feature that every application will need at some point during its lifetime, if not during development and testing then certainly when it has gone live. Despite this, developers often neglect to build it in from the start and then end up hurriedly shoehorning it in at the last minute. As a result the logging infrastructure is limited in its flexibility and usefulness.

Even if logging is integrated from the start, developers often choose to build their own logging code, using classes in the System.IO namespace to simply write some timestamps and messages out to a text file. Whilst there is nothing wrong with this, employing a dedicated logging framework can both cut down on development time and offer a rich set of features to play with. This article will provide an introduction to one such framework: log4net.

Introduction

log4net is an open source logging tool produced by the Apache Logging Services project. As such it is free to use and distribute, and its source code is available for download. The framework itself is built upon four key concepts

• an appender is responsible for writing log messages to a particular destination, e.g. database, text file, email
• a logger is made up of one or more appenders and provides methods for logging messages and objects
• a layout governs the formatting of log messages before they are written by the appender
• a renderer is used to transform an object into a log message. Users of log4net can create their own renderers to ensure that objects such as exceptions are formatted to their liking

This may seem a lot to digest at first but in reality only two items need to be set up in order to use log4net: an appender and the root logger.

Configuration

To get started with log4net, fire up Visual Studio 2008 and create a new Web Application project. Add a reference to the log4net dll (download from here) and a new XML document called Logging.config, which will be used to contain log4net’s configuration. It is possible to put this directly in the web.config however that would mean resetting the web site each time the logging settings were altered, which is impractical in a live scenario.

The configuration XML begins with a root log4net node, followed by one or more appender nodes. The simplest appender to use is the TextFileAppender, which can be set up as follows

<appender name="TextFileAppender" type="log4net.Appender.FileAppender">
  <file value="LoggingDemo.log" />
  <appendToFile value="true" />
  <lockingModel type="log4net.Appender.FileAppender+MinimalLock" />
  <layout type="log4net.Layout.PatternLayout">
    <conversionPattern value="%date{yyyy-MM-dd HH:mm:ss.fff} %-5level %message%newline" />
  </layout>
</appender>

As with all appenders, a friendly name (TextFileAppender) must be given, along with the full type name of the appender (log4net.Appender.FileAppender). Within the appender node though, the settings are very much specific to the particular appender. In the case of FileAppender, log4net is configured to append log messages to LoggingDemo.log, in the root of the web site. Had appendToFile been false, a new file would be created each time, which isn’t very useful. The minimal lock is being used so that the file can be deleted without resetting IIS to release it, although this hampers performance a little. The final item of interest is the layout, which will be covered in a later post.

The last piece of config is the most important: setting up the root logger, which is done like this

<root>
  <appender-ref ref="TextFileAppender" />
</root>

The log4net config file must contain at least one logger: the root logger. More loggers can be added underneath the root, building up a hierarchy, although that is beyond the scope of this article. In this example the root logger has been set to use the TextFileAppender, so all logged messages will be sent to the LoggingDemo.log file.

Usage

Now that log4net has been configured it’s time to add some C# to the test web site. First off an assembly-level attribute must be added to the source code, as follows

[assembly: XmlConfigurator(ConfigFile="Logging.config", Watch=true)]

The best place for this code is in AssemblyInfo.cs with all other assembly-level attributes. By adding this log4net becomes aware of where the logging config file is, and whether or not to monitor it for changes. A using statement is also needed to import types from the log4net namespace.

The next task is to get a reference to a logger object, which implements the ILog interface. This can be done by calling LogManager.GetLogger, passing in a type or a name, which helps to identify which logger should be returned. In this example there is only the root logger, so passing in any type is sufficient to retrieve the root logger. Add the following code to the Page_Load method of the Default.aspx page

[chsarp]
ILog log = LogManager.GetLogger(this.GetType());
[/csharp]

Recommended practice is to pass in the current type, that way if a type-specific logger is added later on, no code changes are required.

At this point the ILog object is ready to be used. It is important to decide what logging level is appropriate for the message, choosing one from this list

• DEBUG
• INFO
• WARN
• ERROR
• FATAL

For each level of detail there are methods for logging messages, exceptions, and passing in a format string with arguments, in a similar way to using the string.Format function. Check out the ILog interface definition for more details.

For now, just use the Info method and pass in any message, in this case just log the fact that the event has fired, for example

log.Info("Page_Load has fired");

Now run the web site and browse to the page; a log file should be created with a single line containing the log message. Hurrah!

Adjusting the logging level

Let’s return to the concept of logging level. The idea behind this is that, by adjusting the level in the config file, it is possible to see more, or less, messages in the log file. A typical scenario is that an application will run with minimal logging most of the time, recording just FATAL and ERROR level information.

However if a bug is reported it is simple to switch the level to INFO or even DEBUG, which will cause many more messages to be logged and hopefully provide an insight into the problem. The rule of thumb is that, for the level in the config file, all messages are logged at that level, and below. For example if log4net was told to log at the WARN level, all messages at the WARN, ERROR and FATAL levels will be logged.

To alter the logging level in the config file, change the root logger as follows

<root>
  <level value="WARN" />
  <appender-ref ref="TextFileAppender" />
</root>

Now that WARN is being used, run the test project again and this time the INFO message is not written to the LoggingDemo.log file. Note that it is also possible to set the logging level to ALL and NONE in addition to the specific levels mentioned earlier.

That’s it for now. In part two another appender will be added and I’ll also describe how to customise the format of the log messages.

Technorati tags: .NET log4net