In the Context tutorial I said that my next log4net post would focus on real-world examples.  However, I received this request from a college in the U.K.:

I would like to have 2 logs, ... I would like to have levels Debug, Info & Warn logged to the one log and all Error & Fatal logged to the second log. ...  Do you know if this is possible with log4net?

This is very easy to do using a feature of log4net I haven't discussed yet: filters.  Filters are applied to individual appenders via the log4net configuration, and they help the appender determine whether a log event should be processed by the appender.  They may sound like the appender threshold property, and indeed some filters behave similarly; however, filters offer far more control over logging behavior.

Filter Example

Open Visual Studio, create a new console project, and reference log4net.  Add the following code to the Program class:

namespace Tutorial7_Filters
{
    class Program
    {
        static void Main( string[] args )
        {
            log4net.Config.XmlConfigurator.Configure();
            log4net.ILog Log = log4net.LogManager.GetLogger(
                System.Reflection.MethodBase.GetCurrentMethod().DeclaringType
               );
            Log.Fatal( "this is a fatal msg" );
            Log.Error( "this is an error msg" );
            Log.Warn( "this is a warn msg" );
            Log.Info( "this is an info msg" );
            Log.Debug( "this is a debug msg" );
        }
    }
}

Add an app.config to the project and update it like so:

<?xml version="1.0" encoding="utf-8" ?>
<configuration>
  <configSections>
    <section name="log4net" type="log4net.Config.Log4NetConfigurationSectionHandler, log4net"/>
  </configSections>
  <log4net>
    <appender name="LogFileAppender" type="log4net.Appender.FileAppender">
      <file value="log.txt" />
      <filter type="log4net.Filter.LevelRangeFilter">
        <levelMin value="DEBUG" />
        <levelMax value="WARN" />
      </filter>
      <layout type="log4net.Layout.SimpleLayout" />
    </appender>
    <appender name="ErrorFileAppender" type="log4net.Appender.FileAppender">
      <file value="errors.txt" />
      <filter type="log4net.Filter.LevelRangeFilter">
        <levelMin value="ERROR" />
        <levelMax value="FATAL" />
      </filter>
      <layout type="log4net.Layout.SimpleLayout" />
    </appender>
    <root>
      <level value="DEBUG" />
      <appender-ref ref="LogFileAppender" />
      <appender-ref ref="ErrorFileAppender" />
    </root>
  </log4net>
</configuration>

This configuration defines two file appenders, each with a unique filter applied (lines 12 and 23).  The filter on the first appender will log events with levels DEBUG, INFO, and WARN; the filter on the second appender will log event with levels ERROR and FATAL.

Build and run; the command console will flash for a moment with no output.  Check the working directory and open log.txt:

WARN - this is a warn msg
INFO - this is an info msg
DEBUG - this is a debug msg

Note that only the DEBUG, INFO, and WARN messages appear in this file.  The errors.txt log file contains only ERROR and FATAL log messages:

FATAL - this is a fatal msg
ERROR - this is an error msg

Filter Survey

Here is a list of the filters available in the log4net distribution:

You can also define your own filter by implementing the log4net.Filter.IFilter interface or deriving from the log4net.Filter.FilterSkeleton class.

You can apply multiple filters to an appender; they will be evaluated as a chain in configuration order.  Each filter in the chain can either accept the message, deny the message, or punt to the next filter in the chain.   The first filter to explicitly allow or deny a log message stops the filter chain and determines the fate of log message.

Logger and Level Filters

The LoggerMatchFilter filters against the name of the logger emitting the message.  This filter can be configured using the following properties:

• loggerToMatch: a string value to match against the message's logger name.  The match is made using the String.StartsWith method;
• acceptOnMatch: a boolean value indicating whether a matching logger name results in accepting the message (true) or rejecting it (false).  This defaults to true, meaning that only matching logger names will be allowed into the appender.

The LevelMatchFilter filters against a specific log message level.  This filter can be configured using the following properties:

• levelToMatch: the log level to match - either DEBUG, INFO, WARN, ERROR, or FATAL;
• acceptOnMatch: a boolean value indicating whether to accept log levels matching the levelToMatch property (true), or reject log levels matching the levelToMatch property (false).  Defaults to true.

The LevelRangeFilter allows you to configure a range of log levels to filter on:

• levelMin: the minimum log level to match - either DEBUG, INFO, WARN, ERROR, or FATAL;
• levelMax: the minimum log level to match - either DEBUG, INFO, WARN, ERROR, or FATAL;
• acceptOnMatch: a boolean value indicating whether to accept log levels matching the levelToMatch property (true), or to punt filtering to the next filter in the chain (false).  Defaults to true.  Note that any log level outside of the [levelMin, levelMax] range is denied by this filter.

Message and Property Filters

If you need to filter messages based on their message content, you need StringMatchFilter.  This filter can be configured as follows:

• regexToMatch: a regular expression to match against the log message.  Note this regex is created with the Compiled option enabled for performance;
• stringToMatch: a static string to match against the log message.  The match is made using the String.IndexOf method to see if the static string exists in the log message, which is a case-sensitive search.
• acceptOnMatch: a boolean value indicating whether to accept log messages matching the string or regex (true), or to deny log messages matching the string or regex (false).  Defaults to true.  

Note that any log messages not matching the filter criteria are punted to the next filter in the chain.  If you specify both the regexToMatch and stringToMatch filters, the regexToMatch wins out and the string comparison is never executed, even if the regex fails to match.

The PropertyFilter performs the same behavior as the StringMatchFilter, except that the match is made against the value of a context property.  It is configured like so:

• key: the name of the property value to match;
• regexToMatch: a regular expression to match against the specified property value.  Note this regex is created with the Compiled option enabled for performance;
• stringToMatch: a static string to match against the specified property value.  The match is made using the String.IndexOf method to see if the static string exists in the property value, which is a case-sensitive search.
• acceptOnMatch: a boolean value indicating whether to accept messages with a property value matching the string or regex (true), or to deny messages with a property value matching the string or regex (false).  Defaults to true.  

Just like the StringMatchFilter, the PropertyFilter will punt filtering when the property value does not match the filter criteria, and regexToMatch trumps and excludes stringToMatch.  In addition, if the property identified does not exist in the current context, filtering is punted.

DenyAllFilter

This filter simply denies all filtering.  When this is used, it's always at the end of a filter chain to block unwanted log messages from the appender.

An Extended Example

Update Program.cs to the following:

namespace Tutorial7_Filters
{
    class Program
    {
        static void Main( string[] args )
        {
            log4net.Config.XmlConfigurator.Configure();
            log4net.ILog Log = log4net.LogManager.GetLogger( System.Reflection.MethodBase.GetCurrentMethod().DeclaringType );
            log4net.ILog OMGLog = log4net.LogManager.GetLogger( "OMGLogger" );
            
            Log.Fatal( "this is a fatal msg" );
            Log.Error( "this is an error msg" );
            Log.Warn( "this is a warn msg" );
            Log.Info( "this is an info msg" );
            Log.Debug( "this is a debug msg" );
            OMGLog.Fatal( "OMG!!  this is a fatal msg" );
            OMGLog.Error( "OMG!!  this is an error msg" );
            OMGLog.Warn( "OMG!!  this is a warn msg" );
            OMGLog.Info( "OMG!!  this is an info msg" );
            OMGLog.Debug( "OMG!!  this is a debug msg" );
        }
    }
}

On lines 8 and 9 two logger objects are created, one based off of the name of the containing type and another named simply "OMGLogger".  Now update the app.config to the following:

<?xml version="1.0" encoding="utf-8" ?>
<configuration>
  <configSections>
    <section name="log4net" type="log4net.Config.Log4NetConfigurationSectionHandler, log4net"/>
  </configSections>
  <log4net>
    <appender name="OMGLogAppender" type="log4net.Appender.FileAppender">
      <file value="omglog.txt" />
      
      <filter type="log4net.Filter.LevelRangeFilter">
        <levelMin value="ERROR" />
        <levelMax value="FATAL" />
        <acceptOnMatch value="false" />
      </filter>
      <filter type="log4net.Filter.LoggerMatchFilter">
        <loggerToMatch value="OMGLogger" />
      </filter>
      <filter type="log4net.Filter.DenyAllFilter" />
      <layout type="log4net.Layout.SimpleLayout" />
    </appender>
    <root>
      <level value="DEBUG" />
      <appender-ref ref="OMGLogAppender" />
    </root>
  </log4net>
</configuration>

Compile and run, the command console will blip on your screen.  Open the omglog.txt file:

FATAL - OMG!!  this is a fatal msg
ERROR - OMG!!  this is an error msg

Note that because of our chained filter, only log messages that meet the following criteria were allowed into the omglog.txt file:

1. the log message level is ERROR or FATAL;
2. the log message originated from the OMGLogger.

Coming Up

For realsies next time I'll discuss some personal experiences with log4net saving me hours of work and making me a hero.  I'll also cover some logging best practices in that or a later post.

There are times when your log messages need some context to be most useful.  For example, if your application supports multiple concurrent clients, it would be helpful to know the client to which each log statement applies.  If a piece of code is used by several components, it would be nice for the log messages to reflect which component is calling the code.  log4net provides a very simple mechanism to accommodate such needs.

Open Visual Studio, create a new console project, and add a reference to the log4net assembly.  Add the following code to your program.cs file:

namespace Tutorial6_Context
{
    class Program
    {
        private static log4net.ILog Log = log4net.LogManager.GetLogger( System.Reflection.MethodBase.GetCurrentMethod().DeclaringType );

        static void Main( string[] args )
        {
            log4net.Config.XmlConfigurator.Configure();
            log4net.ThreadContext.Properties[ "myContext" ] = "Logging from Main";
            Log.Info( "this is an info message" );
            Console.ReadLine();
        }
    }
}

Note line 10, where a property named "myContext" is added to the ThreadContext static class and assigned a simple string value.  Next add the following application configuration file to the project:

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

  <log4net>
 
    <appender name="ConsoleAppender" type="log4net.Appender.ConsoleAppender">
      <layout type="log4net.Layout.PatternLayout">
        <conversionPattern value="%logger (%property{myContext}) [%level]- %message%newline" />
      </layout>
    </appender>

    <root>
      <level value="ALL" />
      <appender-ref ref="ConsoleAppender" />
    </root>
  </log4net>
</configuration>

Line 11 contains the layout pattern for our log; the %property{myContext} format specifier will be replaced with the value of the "myContext" property at the time the message is logged.

Compile and run; the context value is reflected in the log output:

Tutorial6_Context.Program (Logging from Main) [INFO]- this is an info message

Context Scopes

There are actually three logging contexts available in log4net.  Like the logger architecture, contexts are organized into a hierarchy where properties in the more granular contexts override property values in less granular contexts.

Calculated Context Values

Context property values don't have to be strings.  You can set the value of a context property to any object reference; the value of the object's ToString method will be used to obtain the context property value when a logging event occurs.  This can be useful when you need a context property to represent a calculated state at the time of each logging event.  For instance, perhaps you want to track your application's use of the CPU:

namespace Tutorial6_Context
{
    public class CalcualtedContextProperty
    {
        public override string ToString()
        {
            return Process.GetCurrentProcess().TotalProcessorTime.ToString();
        }
    }
}

Set a context property value to an instance of this new class:

namespace Tutorial6_Context
{
    class Program
    {
        private static log4net.ILog Log = log4net.LogManager.GetLogger( System.Reflection.MethodBase.GetCurrentMethod().DeclaringType );

        static void Main( string[] args )
        {
            log4net.Config.XmlConfigurator.Configure();
            log4net.ThreadContext.Properties[ "myContext" ] = new CalculatedContextProperty();
            Log.Info( "this is an info message" );
            Console.ReadLine();
        }
    }
}

The result is each log entry containing the application's total CPU time at the time the log entry was made:

Tutorial6_Context.Program (00:00:00.2968750) [INFO]- this is an info message

ThreadContext Stacks

ThreadContext and ThreadLogicalContext can store property values in stacks (available via the Stacks static property of each class).  These stacks are very handy, as they allow you to track program states in the context of a log message:

namespace Tutorial6_Context
{
    class Program
    {
        static log4net.ILog Log = null;

        static void Main( string[] args )
        {
            log4net.Config.XmlConfigurator.Configure();
            Log = log4net.LogManager.GetLogger( System.Reflection.MethodBase.GetCurrentMethod().DeclaringType );
            using( log4net.ThreadContext.Stacks[ "myContext" ].Push( "outer" ) )
            {
                Log.Info( "this is the first message" );
                using( log4net.ThreadContext.Stacks[ "myContext" ].Push( "inner" ) )
                {
                    Log.Info( "this is the second message" );
                }
            }
            Log.Info( "this is the third message" );
            Console.ReadLine();
        }
    }
}

Pushing a property value onto a stack returns an IDisposable that, when disposed, pops the property value off of the stack.  The logging output reflects the state of the context stack at each logging event; the stack is represented as a space-delimited list, with newer items appearing later in the list:

Tutorial6_Context.Program (outer) [INFO]- this is the first message
Tutorial6_Context.Program (outer inner) [INFO]- this is the second message
Tutorial6_Context.Program ((null)) [INFO]- this is the third message

Context stacks are incredibly useful for wrapping access to a shared piece of code.  For example, in the following code two methods call the same utility routine; a marker is pushed onto the property stack before each call:

namespace Tutorial6_Context
{
    class Program
    {
        static log4net.ILog Log = null;

        static void Main( string[] args )
        {
            log4net.Config.XmlConfigurator.Configure();
            Log = log4net.LogManager.GetLogger( System.Reflection.MethodBase.GetCurrentMethod().DeclaringType );

            FirstAction();
            SecondAction();

            Console.ReadLine();

        }

        static void FirstAction()
        {
            using( log4net.ThreadContext.Stacks[ "myContext" ].Push( "FirstAction" ) )
            {
                UtilityRoutine();
            }
        }

        static void SecondAction()
        {
            using( log4net.ThreadContext.Stacks[ "myContext" ].Push( "SecondAction" ) )
            {
                UtilityRoutine();
            }
        }
        
        static void UtilityRoutine()
        {
            Log.Info( "this is an info message" );
        }
    }
}

Each log message produced by the utility routine reflects the context in which it was called:

Tutorial6_Context.Program (from:FirstAction) [INFO]- this is an info message
Tutorial6_Context.Program (from:SecondAction) [INFO]- this is an info message

Coming Up

These 6 tutorials cover the logging mechanics available in log4net.  So in the next post or two, I'd like to show you how logging has saved my hide using real examples from my career.

We've done a lot log4net configuration in the last few tutorials; time to mix in some code and discuss loggers.  This post is meant to show you the most common pattern of logger use.

Crack open Visual Studio, create a new console project, and add a reference to the log4net assembly.

Add the following application configuration file to the project:

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

  <log4net>

    <appender name="ConsoleAppender" type="log4net.Appender.ConsoleAppender">
      <layout type="log4net.Layout.PatternLayout">
        <conversionPattern value="%logger [%level]- %message%newline" />
      </layout>
    </appender>

    <root>
      <level value="ALL" />
      <appender-ref ref="ConsoleAppender" />
    </root>
  </log4net>
</configuration>

Add the following code to your program.cs file:

namespace Tutorial5_Loggers
{
    class Program
     {
        private static log4net.ILog Log = log4net.LogManager.GetLogger( System.Reflection.MethodBase.GetCurrentMethod().DeclaringType );

        static void Main( string[] args )
        {
            log4net.Config.XmlConfigurator.Configure();
            Log.Info( "this is an info message" );
            Console.ReadLine();
        }
    }
}

The logger object is created on line 5 via a the call to LogManager.GetLogger.  Compile and run and check out the output; it'll be similar to the following:

Tutorial5_Loggers.Program [INFO]- this is an info message

The first item in the log entry printed to the console is the name of the logger object that issued the log entry.  Because GetLogger was passed a reference to my Program type, the logger name is the fully qualified type name of the Program object.

Add another class to the project:

namespace Tutorial5_Loggers
{
    class MyClass
    {
        private static log4net.ILog Log = log4net.LogManager.GetLogger( System.Reflection.MethodBase.GetCurrentMethod().DeclaringType );

        public static void WriteLog()
        {
            Log.Info( "this is an info message" );
        }
    }
}

and add a call to MyClass.WriteLog to your Main method (see line 7 below):

static void Main( string[] args )
{
    log4net.Config.XmlConfigurator.Configure();

    Log.Info( "this is an info message" );

    MyClass.WriteLog();
    Console.ReadLine();
}

Compile and run, and note the logger name in the second log statement matches the type name of MyClass:

Tutorial5_Loggers.Program [INFO]- this is an info message
Tutorial5_Loggers.MyClass [INFO]- this is an info message

Hierarchical Logger Configuration

You can use loggers this way to isolate logging concerns across your objects, and I wholly recommend you do so.  This will enable you to throttle and direct log output from individual loggers using log4net's hierarchical configuration mechanism.

Update your app.config to the following:

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

  <log4net>
    <appender name="ConsoleAppender" type="log4net.Appender.ConsoleAppender">
      <layout type="log4net.Layout.PatternLayout">
        <conversionPattern value="%logger [%level]- %message%newline" />
      </layout>
    </appender>
    <appender name="FileAppender" type="log4net.Appender.FileAppender">
      <file value="log-file.txt" />
      <appendToFile value="false"/>
      <layout type="log4net.Layout.PatternLayout">
        <conversionPattern value="%logger [%level]- %message%newline" />
      </layout>
    </appender>

    <root>
      <level value="ALL" />
    </root>
    <logger name="Tutorial5_Loggers">
      <level value="ALL" />
      <appender-ref ref="FileAppender" />
    </logger>
    <logger name="Tutorial5_Loggers.Program">
      <level value="ALL" />
      <appender-ref ref="ConsoleAppender" />
    </logger>
    <logger name="Tutorial5_Loggers.MyClass">
      <level value="ALL" />
    </logger>
  </log4net>
</configuration>

On line 12 we add a file appender to the mix; lines 23-33 provide configuration for specific logger objects.  Note that the logger names correspond directly to the namespace-qualified type names and namespaces from our project.  Specifically:

• on line 23 a logger is configured specifically for the "Tutorial5_Loggers" namespace; this logger is configured to write logs to the file appender;
• on line 27, a logger is configured for the Program class; this logger is configured to write logs to the console;
• on line 31, a logger is configured for the MyClass class; this logger is not configured with an appender.

Compile and run, and you'll notice that:

• the console output displays only the log statement from the Program class;
• a "log-file.txt" file is written in the application folder, and this file contains the log statements from both the Program and MyClass types.

Now change the level value for the Tutorial5_Loggers.MyClass from ALL to OFF:

<logger name="Tutorial5_Loggers.MyClass">
  <level value="OFF" />
</logger>

Compile and run, and note that the log-file.txt file no longer contains the log statement from the MyClass object.  

This hierarchical configuration system can be incredibly useful; a common practice is to disable logging of "verbose" objects by targeting their specific type with a logging level set to OFF; another is to provide a "specific-needs" logger configured with a special appender, such as a gateway to the windows event log or a remote log viewer.  However, the system has a few caveats you need to know about:

• appenders accumulate through the hierarchy: if the Program class and Tutorial5_Logger namespace are each configured to append to the console, any log from the Program class will show up twice in the console (once for the class logger and once for the namespace logger);
• logger levels deeper in the hierarchy trump the shallow ones: if the Program class logging level is set to ALL and the Tutorial5_Logger namespace logging level is set to OFF, logs from the program class are still written to the appenders configured for Tutorial5_Logger.

Coming Up

The first 5 tutorials have given you some pretty heavy-hitting abilities.  Next time I'll discuss associating context to log messages, which can provide invaluable debugging information. 

After that rather lengthy post about common appenders, this discussion of patterns and layouts should be short and sweet.

A layout is just a template for your log messages.  Layouts are specified per-appender, and you can specify only one layout for an appender:

<appender name="ColoredConsoleAppender" type="log4net.Appender.ColoredConsoleAppender">
    <layout type="log4net.Layout.SimpleLayout" />
</appender>

We've been using the SimpleLayout in the previous tutorials.  This is the easiest layout to use and yields rather a Spartan log:

DEBUG - this is a debug message
INFO - this is an info message
WARN - this is a warn message
ERROR - this is an error message
FATAL - this is a fatal message

The PatternLayout allows you to specify a printf-style template for your log entries using a "conversion pattern," and gives you the opportunity to decorate each entry with some valuable instance data.  For instance, this configuration:

<appender name="ColoredConsoleAppender" type="log4net.Appender.ColoredConsoleAppender">
    <layout type="log4net.Layout.PatternLayout">
        <conversionPattern value="%date [%thread] %-5level %logger - %message%newline" />
    </layout>
</appender>

produces a log that appears like so:

2008-06-20 12:29:03,541 [2684] DEBUG Tutorial4.Program - this is a debug message
2008-06-20 12:29:03,556 [2684] INFO  Tutorial4.Program - this is an info message
2008-06-20 12:29:03,556 [2684] WARN  Tutorial4.Program - this is a warn message
2008-06-20 12:29:03,556 [2684] ERROR Tutorial4.Program - this is an error message
2008-06-20 12:29:03,556 [2684] FATAL Tutorial4.Program - this is a fatal message

The conversion pattern string can include literal text and the following format expressions:

This sample output is from a single log entry using a conversion pattern containing all of the format expressions above:

%appdomain: Tutorial4_LayoutsAndPatterns.vshost.exe
%date: 2008-06-20 13:04:38,020
%exception:
%file: D:\Project\Log4NetTutorial\Log4NetTutorial\Tutorial4_LayoutsAndPatterns\Program.cs
%identity:
%level: INFO
%line: 14
%location: Tutorial4_LayoutsAndPatterns.Program.Main(D:\Project\Log4NetTutorial\Log4NetTutorial\Tutorial4_LayoutsAndPatterns\Program.cs:14)
%logger: Tutorial4_LayoutsAndPatterns.Program
%method: Main
%message: this is an info message
%timestamp: 1015
%type: Tutorial4_LayoutsAndPatterns.Program
%username: MYDOMAIN\username
%utcdate: 2008-06-20 17:04:38,020
%%: %

If you want a highly structured and queryable log, then XMLLayout is for you:

<appender name="ColoredConsoleAppender" type="log4net.Appender.ColoredConsoleAppender">
      <layout type="log4net.Layout.XMLLayout" />
    </appender>

The XMLLayout produces a stream of XML elements representing individual log entries:

<log4net:event logger="Tutorial4_LayoutsAndPatterns.Program" timestamp="2008-06-20T13:17:44.2863922-04:00" level="DEBUG" thread="2156" domain="Tutorial4_LayoutsAndPatterns.vshost.exe" username="POKERTEK\jchristopher">
    <log4net:message>this is a debug message</log4net:message>
    <log4net:global-properties>
        <log4net:data name="log4net:HostName" value="nc-jchri-l-3" />
    </log4net:global-properties>
</log4net:event>
<log4net:event logger="Tutorial4_LayoutsAndPatterns.Program" timestamp="2008-06-20T13:17:44.3176424-04:00" level="INFO" thread="2156" domain="Tutorial4_LayoutsAndPatterns.vshost.exe" username="POKERTEK\jchristopher">
    <log4net:message>this is an info message</log4net:message>
    <log4net:global-properties>
        <log4net:data name="log4net:HostName" value="nc-jchri-l-3" />
    </log4net:global-properties>
</log4net:event>

A few caveats you should note regarding the XMLLayout:

• the log will contain a flat collection XML elements, but no containing root element; this means that you have to do some fernagling to read the XML as a document;
• each log entry will contain the username and identity values (see the table above), which are expensive to read and may have a noticable impact on application performance.

Coming Up

That rounds out a lot of our configuration discussion.  Next time I'll jump back into code and discuss logger objects, which are simply sources of log messages.  I'll show you how to organize your logging activity by object types to provide a more tractable log.