I've discussed using XML to configure lognet, during which I briefly touched on log4net appenders.  An appender is an object that persists your log messages someplace.  In this post, I'd like to give you a quick overview of the wealth of apppenders available in log4net and show you how you can use them to direct a single log message to multiple places.

A Quick Survey

Here is a quick sampling of the appenders available in the log4net distribution:

There's a lot of them, so to keep this post reasonable I'm focusing on the most basic appenders: the console appenders, debug appenders, and file appenders.  However, all of the available appenders are covered in detail in the log4net documentation if you want to learn more about them, and I'll be describing other appenders in upcoming posts as well.

ConsoleAppender and ColoredConsoleAppender

These appenders are useful only for console applications, where they provide immediate feedback during program execution.

There is one configurable aspect of the ConsoleAppender - the target property identifies what output stream to use when outputting log entries:

<appender name="ConsoleAppender" type="log4net.Appender.ConsoleAppender">
    <target value="Console.Error" />
    <layout type="log4net.Layout.SimpleLayout" />
</appender>

It can be either "Console.Out" (the default value if left uspecified) to use the standard output stream or "Console.Error" to use the standard error stream.  

I always favor ColoredConsoleAppender over ConsoleAppender, because the ColoredConsoleAppender will colorize the log message by its severity level.  This makes finding relevant log messages amidst the program output a lot easier.  For example, compare this output from the ConsoleAppender:

to the same output from the ColoredConsoleAppender:

The color mapping is completely configurable, as shown in this example appender configuration XML:

<appender name="ColoredConsoleAppender" type="log4net.Appender.ColoredConsoleAppender">
  <target value="Console.Error" />
  <mapping>
    <level value="FATAL" />
    <foreColor value="Red" />
    <backColor value="White" />
  </mapping>
  <mapping>
    <level value="ERROR" />
    <foreColor value="Red, HighIntensity" />
  </mapping>
  <mapping>
    <level value="WARN" />
    <foreColor value="Yellow" />
  </mapping>
  <mapping>
    <level value="INFO" />
    <foreColor value="Cyan" />
  </mapping>
  <mapping>
    <level value="DEBUG" />
    <foreColor value="Green" />
  </mapping>
  <layout type="log4net.Layout.SimpleLayout" />
</appender>

Each <mapping /> element must contain a severity level, and can also contain a <foreColor /> and/or <backColor /> element.  Color selection is limited to the following choices:

• Blue
• Green
• Red
• Yellow
• Purple
• Cyan
• White

In addition, you can include "HighIntensity" in the color value to use a brighter shade of a color, as shown in the ERROR color mapping in the above configuration example.

These appenders are useful only for console-based programs.  It won't hurt anything if you try to use this appender from a UI or web application, you just won't see any of your log messages.  

DebugAppender and TraceAppender

These appenders act as adapters on the .NET System.Diagnostics.Debug and System.Diagnostics.Trace classes.  Because of this, there is very little option in their configurations; both appenders have a single configurable property named ImmediateFlush that controls whether log output is flushed to the Debug or Trace writers immediately:

<appender name="DebugAppender" type="log4net.Appender.DebugAppender">
    <immediateFlush value="true" />
    <layout type="log4net.Layout.SimpleLayout" />
</appender>

I use the DebugAppender routinely to help work problems in the debugger - the log output shows up right in the debug output window of Visual Studio.  This can be invaluable when trying to isolate race conditions or realtime effects where a breakpoint would ruin the reproducability of the issue.

I've used the TraceAppender when extending applications where custom TraceListener implementations were already in use; this allowed existing modules using log4net to adapt immediately to the proprietary TraceListeners, no code required.

FileAppender and RollingFileAppender

These appenders write log messages to files.  Their configuration is a bit more involved than the other appenders we've discussed.  A typical configuration for the FileAppender might look like this:

<appender name="FileAppender" type="log4net.Appender.FileAppender">
    <file value="log-file.txt" />
    <appendToFile value="true" />
    <encoding value="utf-8" />
    <layout type="log4net.Layout.SimpleLayout" />
</appender>

Here's a quick summary of the more common configuration attributes for the FileAppender:

• file: the full or relative path to the log file;
• appendToFile: boolean indicating whether the log file should be appended (true) or overwritten (false).  If false, the file overwrite occurs during log4net initialization.  If unspecified, the log file is appended;
• immediateFlush: boolean indicating whether to flush the log file TextWriter after each log message is written.  The default is true (flush each message after its written);
• lockingModel: allows control over the log file locking strategy.  This can be either "log4net.Appender.FileAppender+MinimalLock" to allow for loose file locking or "log4net.Appender.FileAppender+ExclusiveLock" to lock the file during program execution.  The default is the exlusive lock, and I highly recommend you stick with that lock for performance reasons.

Now that I've described the FileAppender, heed this advice:

Do not use the FileAppender, ever ever ever.  Use the RollingFileAppender instead.

The log file managed by FileAppender will be allowed to grow without bounds.  This will Tonya-Harding your application's stability when given enough time.  The RollingFileAppender provides rudimentary log file management, configurable size- or date-boxing of the log file, and limited rolling backups of the log file.

<appender name="RollingFileAppender" type="log4net.Appender.RollingFileAppender">
    <file value="log-file.txt" />
    <appendToFile value="true" />
    <rollingStyle value="Size" />
    <maxSizeRollBackups value="10" />
    <maximumFileSize value="1MB" />
    <staticLogFileName value="true" />
    <layout type="log4net.Layout.SimpleLayout" />
</appender>

There is a lot of configurability to the RollingFileAppender; in addition to the options available to the FileAppender, the RollingFileAppender includes these parameters:

• rollingStyle: this controls how log files are "rolled," and can be one of the following values:
  • Once: the log file is rolled every time log4net is initialized (typically at application startup);
  • Size: the log file is rolled once it breaches a certain size;
  • Date: the log file is rolled based on the current date;
  • Composite: the log file is rolled based on size constraints and the current date;
• maximumFileSize: the size cap on the log file.  This is an expression of size in the form of "#(KB|MB|GB)".  For instance, "100KB" or "10MB";
• maxSizeRollBackups: the maximum number of rolled log file backups to maintain when rollingStyle is SIZE; when rollingStyle is COMPOSITE, this indicates the maximum number of roll-offs maintained per day; this property has no effect when rollingStyle is ONCE or DATE;
• datePattern: the date pattern used to roll files based on date.  The value of this parameter needs to adhere to the format used by the SimpleDateFormatter class;
• staticLogFileName: a bit of a misnomer - when true this setting indicates whether log4net should actively write logs to the configured file (log-file.txt in our example configuration) and maintain rolling backups by copy.  When false, this setting indicates that log4net will actively log to the latest roll-off file (e.g., log-file1.txt, log-file2.txt, log-file3.txt, etc);
• countDirection: indicates how roll-off file numbering is managed.  When this parameter is >= 0, the newest log file will have the largest number; e.g., log-file.txt.5 will be newer than log-file.txt.4.  When countDirection < 0, the newest log file will have the lowest number; e.g., log-file.txt.1 will be newer than log-file.txt.2.  If unspecified, countDirection defaults to (-1);

Keep in mind that when using a file appender, the user running the logging process must have rights to create and/or modify the log file in order for log messages to be written properly.  In addition, log4net will create the log file if it does not exist, but it will not create directories in the log file path that do not already exist.  If log4net encounters a problem initializing the file appender (e.g., it cannot create the log file for security reasons), the log file will not be written but your application will continue to execute normally.

Using Multiple Appenders

With all of these appenders available, it may seem difficult to choose just one to meet your logging needs.  But why choose one when you can have as many as you want?

Using multiple appenders is a simple task of specifying each appender you need under the root logger, like so:

<root>
    <level value="ALL" />
    <appender-ref ref="DebugAppender" />
    <appender-ref ref="ColoredConsoleAppender" />
</root>

You can use as many appenders as you want; however, know that for each appender you use you will accrue some runtime overhead.  

Coming Up

You now have control over where your log messages persist.  Next time, I'll describe how you can control the format your log messages as they are written out by each appender, including how to insert context information - such as the thread id, timestamp, or user identity - into the log message automagically.

Edit Notes

07.03.2008: Theo pointed out some inaccuracies in the way I was describing the maxSizeRollBackups and countDirection properties of the RollingFileAppender, which I've attempted to correct.  Thanks, Theo!

Previously, I offered a quick overview of using log4net.

In this post, I'll show you how to use an XML file to configure log4net, and demonstrate some of the basic ways you can control the verbosity of your log.

Using the XML Configurator

Open Visual Studio, create a new console application, and add a reference to the log4net assembly.  Add the following code to your Main() method:

using System;

namespace Tutorial2_BasicXmlConfiguration
{
    class Program
    {
        static void Main( string[] args )
        {
            log4net.Config.XmlConfigurator.Configure();
            log4net.ILog log = log4net.LogManager.GetLogger( typeof( Program ) );

            log.Info( "beginning loop" );

            for( int c = 0; c < 100; ++c )
            {
                log.DebugFormat( "iteration #{0}", c );
            }

            log.Info( "loop has completed" );

            Console.ReadLine();            
        }
    }
}

On line 9, log4net is bootstrapped using the XmlConfigurator.  This configuration strategy relies on an XML document to supply configuration for log4net.  The static Configure method is overloaded to accept the configuration XML from a file, stream, URI, or an XmlElement object; the parameterless form of the method used here instructs log4net to load the XML from the application's configuration file.  

In addition to the Configure method, the XmlConfigurator offers a static ConfigureAndWatch() method that accepts a FileInfo reference.  ConfigureAndWatch() will monitor the configuration XML file and reconfigure log4net when a change is detected.  This allows you to alter logging behavior at whim while the application is running - very handy for troubleshooting applications in the field, but it adds overhead in the form of a FileSystemWatcher used to monitor the configuration file.

Add the following application configuration file to the console project:

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

  <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>

There are a few important things in there.  First is the declaration of the log4net configuration section on line 3; this is mandatory.  The log4net configuration takes up lines 6-15.  There are two parts to the configuration:

1. one or more appender declarations taking the form of <appender /> elements, and
2. the root logger declaration, represented by the <root /> XML element.

A real discussion of appenders will have to wait; for now, suffice it to say that a log4net appender is a place where your log entries end up.  In this case, the log is being "appended" to the console.

The root logger controls the general behavior of log4net.  In this example, the root logger is told to send everything to the console appender.

Time to compile and run.  You'll get the following output:

INFO - beginning loop
DEBUG - iteration #0
DEBUG - iteration #1
DEBUG - iteration #2
DEBUG - iteration #3
DEBUG - iteration #4
DEBUG - iteration #5
DEBUG - iteration #6
DEBUG - iteration #7
DEBUG - iteration #8
DEBUG - iteration #9
DEBUG - iteration #10
DEBUG - iteration #11
DEBUG - iteration #12
DEBUG - iteration #13
DEBUG - iteration #14
DEBUG - iteration #15
DEBUG - iteration #16
DEBUG - iteration #17
DEBUG - iteration #18
DEBUG - iteration #19
DEBUG - iteration #20
DEBUG - iteration #21
DEBUG - iteration #22
DEBUG - iteration #23
DEBUG - iteration #24
DEBUG - iteration #25
DEBUG - iteration #26
DEBUG - iteration #27
DEBUG - iteration #28
DEBUG - iteration #29
DEBUG - iteration #30
DEBUG - iteration #31
DEBUG - iteration #32
DEBUG - iteration #33
DEBUG - iteration #34
DEBUG - iteration #35
DEBUG - iteration #36
DEBUG - iteration #37
DEBUG - iteration #38
DEBUG - iteration #39
DEBUG - iteration #40
DEBUG - iteration #41
DEBUG - iteration #42
DEBUG - iteration #43
DEBUG - iteration #44
DEBUG - iteration #45
DEBUG - iteration #46
DEBUG - iteration #47
DEBUG - iteration #48
DEBUG - iteration #49
DEBUG - iteration #50
DEBUG - iteration #51
DEBUG - iteration #52
DEBUG - iteration #53
DEBUG - iteration #54
DEBUG - iteration #55
DEBUG - iteration #56
DEBUG - iteration #57
DEBUG - iteration #58
DEBUG - iteration #59
DEBUG - iteration #60
DEBUG - iteration #61
DEBUG - iteration #62
DEBUG - iteration #63
DEBUG - iteration #64
DEBUG - iteration #65
DEBUG - iteration #66
DEBUG - iteration #67
DEBUG - iteration #68
DEBUG - iteration #69
DEBUG - iteration #70
DEBUG - iteration #71
DEBUG - iteration #72
DEBUG - iteration #73
DEBUG - iteration #74
DEBUG - iteration #75
DEBUG - iteration #76
DEBUG - iteration #77
DEBUG - iteration #78
DEBUG - iteration #79
DEBUG - iteration #80
DEBUG - iteration #81
DEBUG - iteration #82
DEBUG - iteration #83
DEBUG - iteration #84
DEBUG - iteration #85
DEBUG - iteration #86
DEBUG - iteration #87
DEBUG - iteration #88
DEBUG - iteration #89
DEBUG - iteration #90
DEBUG - iteration #91
DEBUG - iteration #92
DEBUG - iteration #93
DEBUG - iteration #94
DEBUG - iteration #95
DEBUG - iteration #96
DEBUG - iteration #97
DEBUG - iteration #98
DEBUG - iteration #99
INFO - loop has completed

Taming log4net Output

This example logs a fair amount of cruft.  The DEBUG-level logging inside of the loop overshadows the INFO-level logging outside of the loop.  In a real scenario, this DEBUG-level output may be necessary when troubleshooting application behavior, but it becomes a lot noise when instrumenting the application in production.

Thankfully log4net provides a filter on the logging output.  In your project's app.config, find the <level /> XML element and alter it like so:

<level value="INFO" />

Compile and run; the program log is significantly truncated:

INFO - beginning loop
INFO - loop has completed

Specifically, all DEBUG-level log entries are missing from the log output.  The level value instructs the logger of the minimum level at which log entries should be processed.  It can be one of these values:

• ALL: all log entries are appended to the log;
• DEBUG: Debug, Info, Warn, Error, and Fatal messages are appended to the log.  This is functionally identical to ALL;
• INFO: Info, Warn, Error, and Fatal messages are appended to the log;
• WARN: Warn, Error, and Fatal messages are appended to the log;
• ERROR: Error and Fatal messages are appended to the log;
• FATAL: only Fatal messages are appended to the log;
• OFF: all log entries are ignored.  Logging is effectively disabled in this case.

Coming Up

You have enough knowledge at this point to do some pretty powerful things; however, there's a lot more to be had from log4net.  Next time I'll discuss the many varieties of appenders that ship with log4net, and demonstrate how log4net can funnel a single log message to multiple places. 

I've found logging to be one of the most effective debugging and troubleshooting techniques in my engineering bag, but I'm surprised at how infrequently other people seem to use it.  The arguments orbit around the notion that adding any form of logging won't be that helpful, or that it will slow the application to a crawl.  My experience with application logging has been very positive, and quite frankly I would be a lot less effective without it.

This post is the first in a series aimed at making you comfortable and confident in using log4net as an application logging layer in your .NET applications.  Seriously, it'll make your life a lot easier.

About log4net

My logging layer of choice for .NET is log4net from the Apache Software Foundation.  It's open source, well-documented, extensible, and comes ripe with features right off the vine.  There are alternative logging platforms available if open source isn't an option for you, such as the Microsoft Logging Application Block or, if you're willing to fork out some cash, LucidLog.Net; I can't comment on them directly as I have no experience with either - I've heard good things, but I've also heard that log4net is more feature-rich that both of these.

Note: This series of posts references log4net version 1.2.10.

Getting log4net

log4net is available here as a zip archive. 

The archive contains a ton of stuff; for posterity, here are some hilites of what you'll find in there:

• \bin houses the log4net binaries.  The distribution contains versions of log4net built for specific platforms of .NET, including Microsoft .NET, Mono, Rotor, and the Compact Framework.
• \doc contains the log4net documentation.  Open index.html to start your perusing. 
• \examples contains several small, digestible sample logging applications in various languages and platforms.
• \src holds the log4net source code.
• \tests contains unit tests for the log4net source code.

A Quick Example

1. Open Visual Studio and create a new Console application project.
2. Add to the project a reference to the \bin\net\2.0\release\log4net.dll assembly in the log4net distribution.
3. Modify your Main() method like so:

using System;
namespace Tutorial1_GettingStarted
{
    class Program
    {
        static void Main( string[] args )
        {
            log4net.Config.BasicConfigurator.Configure();
            log4net.ILog log = log4net.LogManager.GetLogger( typeof( Program ) );           

            log.Debug( "Hello World!" );
            log.Info( "I'm a simple log4net tutorial." );
            log.Warn( "... better be careful ..." );
            log.Error( "ruh-roh: an error occurred" );
            log.Fatal( "OMG we're dooooooomed!" );
           
            Console.ReadLine();  // so you can read the output
        }
    }
}

Before running the application, take a close look at the code.  On line 8, the log4net subsystem is configured in the most basic way possible.  Using the BasicConfigurator will cause log4net to output log entries to the console using a default layout (more on layouts in a moment).  log4net configuration is a very broad topic and can get rather deep, but it can be this shallow and narrow too. 

Line 9 requests a logger from the LogManager object.  Logger objects implement the ILog interface, which is what your application will use to instrument itself and percolate log entries.

Lines 11-15 use the logger to log a few statements with various severity levels.  log4net defines 5 such levels:

• Debug: fine-grained statements concerning program state, typically used for debugging;
• Info: informational statements concerning program state, representing program events or behavior tracking;
• Warn: statements that describe potentially harmful events or states in the program;
• Error: statements that describe non-fatal errors in the application; this level is used quite often for logging handled exceptions;
• Fatal: statements representing the most severe of error conditions, assumedly resulting in program termination.

Compile and run the application, and you'll see output to the console similar to the following:

93 [10] DEBUG Tutorial1_GettingStarted.Program (null) - Hello World!
156 [10] INFO Tutorial1_GettingStarted.Program (null) - I'm a simple log4net tutorial.
156 [10] WARN Tutorial1_GettingStarted.Program (null) - ... better be careful ...
156 [10] ERROR Tutorial1_GettingStarted.Program (null) - ruh-roh: an error occurred
156 [10] FATAL Tutorial1_GettingStarted.Program (null) - OMG we're dooooooomed!

Note that each log statement is accompanied by a bunch of data.  I mentioned that the BasicConfigurator uses a default layout; layouts determine how log4net formats a log statement.  In this case, the BasicConfigurator is using a layout that includes stuff like the identifier of the thread from which the log entry was made, the level of the log entry, etc.

Coming Up

That's it for now - just a quick survey of the logging landscape to get you started.  Next time I'd like to talk more about log4net configuration, specifically how to use the app.config file to make log4net ignore log entries below a certain severity level.