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

Question

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?

Answer 1

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