When to use 'nested diagnostic context' (NDC)?

Playing with log4net, I have seen the possibility to use a per-thread stack of context labels called the NDC.

The labels pushed on this stack are displayed in a PatternLayout by specifying the %x or the %ndc format parameter.

The usage is something like:

ILog log = log4net.LogManager.GetLogger(...) ;

//pattern layout format: "[%ndc] - %message%newline"

log.Info("message 1"); 
using(log4net.NDC.Push("context")
{
    using(log4net.NDC.Push("inner_context")
    {
      log.Info("message 2"); 
    }
    log.Info("message 3"); 
}
log.Info("message 4"); 

The output is something like:

null - message 1
context inner_context - message 2
context - message 3
null - message 4

In your programming experience with log4net, when did you find this feature to be useful?

Want an example?

Take the following Web API written using ASP.NET MVC4:

// GET api/HypervResource
public string Get()
{
    logger.Debug("Start of service test");
    System.Threading.Thread.Sleep(5000); // simulate work
    logger.Debug("End of service test");
    return "HypervResource controller running, use POST to send JSON encoded RPCs";
}

When server concurrent HTTP Requests are made, the logging can get interleaved. E.g.

2013-06-27 13:28:11,967 [10] DEBUG HypervResource.WmiCalls [(null)] - Start of service test
2013-06-27 13:28:12,976 [12] DEBUG HypervResource.WmiCalls [(null)] - Start of service test
2013-06-27 13:28:14,116 [13] DEBUG HypervResource.WmiCalls [(null)] - Start of service test
2013-06-27 13:28:16,971 [10] DEBUG HypervResource.WmiCalls [(null)] - End of service test
2013-06-27 13:28:17,979 [12] DEBUG HypervResource.WmiCalls [(null)] - End of service test
2013-06-27 13:28:19,119 [13] DEBUG HypervResource.WmiCalls [(null)] - End of service test

In this simple example, you could use the thread id to distinguish requests, but that can get tricky as the log file grows in complexity.

A better alternative is to provide unique identifiers that group together log messages for the same request. We can update the code as to the following:

// GET api/HypervResource
public string Get()
{
    using(log4net.NDC.Push(Guid.NewGuid().ToString()))
    {
        logger.Debug("Start of service test");
        System.Threading.Thread.Sleep(5000); // simulate work
        logger.Debug("End of service test");
        return "HypervResource controller running, use POST to send JSON encoded RPCs";
    }
}

This produces a log that you can grep to see the issues associated with a specific request. E.g.

2013-06-27 14:04:31,431 [11] DEBUG HypervResource.WmiCalls [525943cb-226a-43c2-8bd5-03c258d58a79] - Start of service test
2013-06-27 14:04:32,322 [12] DEBUG HypervResource.WmiCalls [5a8941ee-6e26-4c1d-a1dc-b4d9b776630d] - Start of service test
2013-06-27 14:04:34,450 [13] DEBUG HypervResource.WmiCalls [ff2246f1-04bc-4451-9e40-6aa1efb94073] - Start of service test
2013-06-27 14:04:36,434 [11] DEBUG HypervResource.WmiCalls [525943cb-226a-43c2-8bd5-03c258d58a79] - End of service test
2013-06-27 14:04:37,325 [12] DEBUG HypervResource.WmiCalls [5a8941ee-6e26-4c1d-a1dc-b4d9b776630d] - End of service test
2013-06-27 14:04:39,453 [13] DEBUG HypervResource.WmiCalls [ff2246f1-04bc-4451-9e40-6aa1efb94073] - End of service test

In a server application such as ASP.NET.

For example, you can push information about the current request on to the NDC.

These feature come in handy when you have lots of logs to go through. When would you have lots of logs? Diagnosing weird bug on a production system with interleaving outputs. Having more contexts gives you way to filter the output or not outputting unneeded logs.

Another case nested contexts could be useful is if a method or some feature is called several times in different contexts and you need a way to distinguish between them.

NDC.Push has been deprecated. The preferred way now (ThreadContext.Stacks["NDC"]) is this:

var disposable = ThreadContext.Stacks["NDC"].Push("context");
try
{
  Log.Info("begin"); // optional, but nice
  ...
}
finally
{
  Log.Info("end"); // optional, but nice
  disposable.Dispose();
}

Remember to check your conversion pattern so that it includes %property{NDC}:

<layout type="log4net.Layout.PatternLayout">
  <conversionPattern
    value="%date [%2thread] %-5level [%property{NDC}] - %.10240message%newline" />
</layout>