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.