Log4Net Recommended Practices pt 1: Your Code

§ October 14, 2008 15:49 by beefarino |

So far my log4net writings have focused on specific aspects of the log4net framework.  These next posts are about putting the pieces together.

To that end, I would like to start with one recent example of how logging has saved hide.

The Call

My company phone starting cock-a-doodle-dooing about 3pm one afternoon.  It was the Director of Support calling - I'll refer to him as Bob - he was on-site trying to get a kiosk up and running for a major client, but a security configuration application was reporting a failure.  This application is basically a permissions engine that modifies DACLs on cryptographic keys, files, and registry keys based on a database of access rules.  The client was going live in an hour or so, so time was a critical factor.

"I've tried everything I know - the database is correct, the AD users are there, the security service is running, and I'm running as an administrator," he said nervously, "but it keeps failing at the same point on this one machine.  It worked on all the other machines, but this one kiosk keeps failing."

"Ok, let's open the log file.  It should be at <file path>.  Find it?" I asked.

"Um.... yep.  Ok, it's open."

"Alright.  Jump to the end, find the last line.  Read it to me."  

This is the layout of the log file for the application:

DATETIME LOGGERNAME [LEVEL] (CONTEXT) MESSAGE_STACKTRACE

The last two lines in the log appeared like so:

12:34:56 TaskExecutionContext [DEBUG] (ACLRuleBuilding) Attempting to locate computer domain name using WMI class [Win32_ComputerSystem] property [Domain].

12:34:56 SetCryptoKeyDACLTask [ERROR] (ACLRuleBuilding) An exception was raised while translating the user name to the domain: System.Runtime.InteropServices.COMException at ...

I had never encountered this error before in development, testing, or the two years the application's been used in the field.  However, the data in that one log message was enough for me to help Bob resolve the issue over the phone.  There were four bits of information that I gleaned from Bob's reading of that log message that allowed me to isolate the problem:

  1. The logger name told me that the SetCryptoKeyDACLTask class issued the error.
  2. The logging context told me that the error was occurring while the application was building ACL rules (as opposed to applying them).
  3. The log message told me the failure was occurring when the application was attempting to translate a username to the computer's domain.
  4. The preceding DEBUG log message indicates that the application was trying to find the computer's domain name immediately before the exception was raised.

"Hmmm, haven't seen that one before either," I said, "but it looks like the app is failing when it's trying to determine the computer's domain.  Any idea why this might be happening on this machine as opposed to the others?"

"Well, I had to add the machine to the domain and then ...."  I hear a loud *smack* as Bob hits himself in the head.  "Okay, I think I figured it out."

It turns out that Bob had neglected to reboot the kiosk after adding it to the domain, so when my application started spelunking through WMI to determine the computer's domain, an exception was being raised.  After a few minutes, the kiosk was running perfectly, and Bob and the client enjoyed a smooth go-live.

All things considered, Bob would have resolved this issue on his own eventually by blindly rebooting the machine and starting the security configuration process over again.  The point is that the application log contained enough information to isolate the problem to a very specific cause without resorting to looking at the source code.  COMExceptions are notoriously ambiguous; if that was all we had to go on, we may not have been able to determine the cause of the exception.

Some Recommended Practices

Let's take a look at some of the code that produced the log message:

namespace Log4Net_BestPractices1
{
    public class SetCryptoDACLTask : ITask
    {
        static log4net.ILog Log = log4net.LogManager.GetLogger(
            System.Reflection.MethodBase.GetCurrentMethod().DeclaringType
        );
        
        string userName;
        
        public void Execute( ITaskExecutionContext context )
        {        
            if( Log.IsDebugEnabled )
            {
                Log.DebugFormat( "Executing task under context [{0}]...", ( null == context ? "null" : context.Description ) );
            }
            
            // ...
            
            using( log4net.NDC.Push( "ACLRuleBuilding" ) )
            {
                // ...
                string principalName = null;
                
                try
                {
                    principalName =
                        context.TranslatePrincipalNameToDomain(
                            userName
                        );
                }
                catch( Exception e )                
                {
                    Log.Error(
                        "An exception was raised while translating the user name to the domain",
                        e
                    );
                    
                    throw;
                }
                
                // ...
            }
            
            // ...
            
            Log.Debug( "Task execution has completed." );
        }
    }
}

This code demonstrates some effective logging techniques I recommend you employ in your own applications:

  1. Use a unique logger object for each type in your application (see line 5).  This will automagically tag each log message with the class that wrote it.  Using this technique provides a log that reads like a novel of your application's activity.  
  2. Whenever you catch an exception, log it (see line 30).  Even if you just plan to throw it again, log it.  In addition, log4net knows how to format Exception objects, so don't try and build your own string from the exception data.
  3. Don't be afraid to pepper your application with piddly little log messages (see lines 15 and 47).  Each one becomes a marker of activity and can prove invaluable when trying to work an issue.  While logging does consume resources, that consumption can be controlled and optimized (something I'll talk about in the next post).  In all but the most CPU-intensive applications, the impact of logging won't be noticed when configured properly.
  4. Whenever you use one of the *Format overrides (see line 15), be extra-special-careful about validating the argument list.  It's very easy to forget to check for null references before using a property accessor, for example, because "it's just logging code."  
  5. Always remember that the argument list is evaluated before the logging method is called.  If an argument to the log method is expensive to obtain, be sure to guard your log statement with a check of the appropriate Is*Enabled property (see line 13).
  6. Before an object calls on a shared dependency, consider pushing a tag onto the log context stack (see line 20).  This will provide continuity in the log, allowing you to determine the caller of the shared code that logged a particular message.
  7. Whenever you use a formatted log statement, surround the format argument placeholders (the {}'s) with brackets or parentheses (see line 15).  Doing this will mark the areas in each log message that vary, making the log scan a bit easier.  In addition, it makes empty or null formatting arguments more obvious.  For instance, if the log message in line 15 was formatted with an empty context.Description value, the message would appear as "Executing task under context []..."  Without those brackets, the same message would be written as "Executing task under context ..." The former message makes it obvious that the context failed to provide a description value, the latter does not.

Coming Up

In upcoming posts I'll discuss log4net configuration scenarios and log reader clients.

In the meantime, if you have any additional logging practices you'd like to share, please feel free to comment on this entry!



Log4Net Tutorial pt 8: Lossy Logging

§ September 11, 2008 15:42 by beefarino |

Ok, so I know I've said twice now that I was going to relay some real-life log4net experiences, but a few days ago Georg Jansen (author of the very kewl Log4Net Dashboard, which I plan to describe in a future post) demonstrated a feature of log4net I've never used before: lossy logging.  After using the feature for a few days, I'm completely sold on it and decided to write up another tutorial.

What is Lossy Logging?

Logging is a very useful tool, but it's not something you want to leave enabled in production if you don't need it.  Each log message take a few cycles away from your application, and the persistence of messages does consume system resources.  Of course you can configure log4net to disable logging, either by setting the root logger level to OFF or removing all appenders from the root logger.  The problem is that by disabling logging altogether, you won't get any juicy details if something goes awry in your application.

Lossy logging gives you a great compromise: under normal operation your application will not log any messages; however, if your application logs an error, a small batch of messages leading up to the error is placed into the log, giving you the error and a snapshot of system activity just before it happened.  How awesome it that?!

Lossy Logging Example

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

namespace Tutorial8_LossyLog
{
    class Program
    {
        static void Main( string[] args )
        {
            log4net.Config.XmlConfigurator.Configure();
            static log4net.ILog Log = log4net.LogManager.GetLogger(
                System.Reflection.MethodBase.GetCurrentMethod().DeclaringType
            );
               
            for( int i = 0; i < 100; ++i )
            {
                Log.DebugFormat( "this is debug msg #{0}", i );
            }
               
            Log.Error( "error: an error occurred!" );           
            Log.Warn( "warning: you've been warned" );
        }
    }
}

The program outputs a series of 100 numbered debug log messages, followed by a single error message and a warning message.

Add an app.config to the project:

<?xml version="1.0" encoding="utf-8" ?>
<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>

    <appender name="LossyConsoleAppender" type="log4net.Appender.BufferingForwardingAppender">
      <bufferSize value="20" />
      <lossy value="true"/>
      <evaluator type="log4net.Core.LevelEvaluator">
        <threshold value="ERROR" />
      </evaluator>
      <appender-ref ref="ConsoleAppender" />
    </appender>

    <root>
      <level value="DEBUG" />
      <appender-ref ref="LossyConsoleAppender" />
    </root>
  </log4net>
</configuration>

The logging configuration defines two appenders, one very generic Console appender and a BufferingForwardingAppender.  As the name implies, the latter appender buffers log messages and forwards them in batches to one or more other appenders.  You can probably tell from the configuration XML that I've set this appender up with a 20-message buffer.  The lossy and evaluator parameters work together to define when the log message buffer is forwarded to the "base" appender.  More on that in a moment ....

Build and run; the command console will output the following:

DEBUG - this is debug msg #81
DEBUG - this is debug msg #82
DEBUG - this is debug msg #83
DEBUG - this is debug msg #84
DEBUG - this is debug msg #85
DEBUG - this is debug msg #86
DEBUG - this is debug msg #87
DEBUG - this is debug msg #88
DEBUG - this is debug msg #89
DEBUG - this is debug msg #90
DEBUG - this is debug msg #91
DEBUG - this is debug msg #92
DEBUG - this is debug msg #93
DEBUG - this is debug msg #94
DEBUG - this is debug msg #95
DEBUG - this is debug msg #96
DEBUG - this is debug msg #97
DEBUG - this is debug msg #98
DEBUG - this is debug msg #99
ERROR - error: an error occurred!

The program issues a total of 102 log messages (100 DEBUG, one ERROR, and one WARN), but the console only contains 20 messages (19 DEBUG and 1 ERROR).  So what happened to the other 82 DEBUG and WARN messages?

When the BufferingForwardingAppender's lossy property is enabled, the appender will buffer log messages without forwarding them.  If the buffer fills up, the oldest messages are dropped from the buffer to make room for the new messages.  

The evaluator property determines when the appender forwards the messages from the buffer to its base appenders.  There is only one evaluator defined in log4net - the LevelEvaluator.  The LevelEvaluator triggers the forward when a log message is received that meets or exceeds the configured threshold.  The example above is configured so that an ERROR message triggers the appender to forward its buffer to the ConsoleAppender.

Lossy Appender Types

Here is a list of appenders in the log4net distribution that can operate "lossy:"

log4net.Appender.AdoNetAppender
log4net.Appender.RemotingAppender
log4net.Appender.SmtpAppender
log4net.Appender.SmtpPickupDirAppender
log4net.Appender.BufferingForwardingAppender

Coming Up

Ok, seriously, next time it'll be all about log4net best practices, and I promise to show you how you can't live without it.  Really!



Log4Net Tutorial pt 7: Filters

§ September 5, 2008 06:37 by beefarino |

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:

Type NameDescription
log4net.Filter.LevelMatchFilter Filters log events that match a specific logging level; alternatively this can be configured to filter events that DO NOT match a specific logging level.
log4net.Filter.LevelRangeFilter Similar to the LevelMatchFilter, except that instead of filtering a single log level, this filters on an inclusive range of contiguous levels.
log4net.Filter.LoggerMatchFilter Filters log events based on the name of the logger object from which they are emitted.
log4net.Filter.StringMatchFilter Filters log events based on a string or regular expression match against the log message.
log4net.Filter.PropertyFilter Filters log events based on a value or regular expression match against a specific context property.
log4net.Filter.DenyAllFilter Effectively drops all logging events for the appender.

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.



Log4Net Tutorial pt 6: Log Event Context

§ September 1, 2008 14:54 by beefarino |

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.

ContextDescription
log4net.GlobalContext A global context shared across all application threads and app domains. If two threads set the same property on the GlobalContext, one value will overwrite the other.
log4net.ThreadContext Any properties set in this context are scoped to the calling thread. In other words, in this context two threads can set the same property to different values without stomping on each other.
log4net.ThreadLogicalContext This context behaves similarly to the ThreadContext, except that the scope is defined by logical thread boundaries. I'll be honest and say that I've never used the ThreadLogicalContext in my career, but if you're working with a custom thread pool algorithm or hosting the CLR, you may find some use for this one.

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.