[OT] Using the NDC while logging

[Sri Sankaran <Sr...@sas.com>]

I would welcome your opinion on the proper use of the Nested Diagnostic Context (NDC) when logging using log4j.

As you know in a multi-threaded servlet environment, the NDC provides valuable contextual information to help make sense of otherwise hopelessly interleaved messages in the log device.  What is the correct procedure for setting up the NDC?  It seems like every log message must be sandwiched by a push() and a pop().  For example:

  NDC.push("something");
  log.debug("The message being logged");
  NDC.pop();

What is the overhead of changing all log statements to this format?  Especially requiring consideration is the fact that the "something" that uniquely identifies a context isn't always readily available and may require some computation to obtain.  For example, the unique identifier may be the userid which is (probably) stashed away in the session, so the above three line segment is really:

  NDC.push((String)session.getAttribute("user.key"));
  log.debug("The message being logged");
  NDC.pop();

This not only adds to the latency (?) it also necessitates the -- otherwise unnecessary -- passing of the session object around.  It also muddies logging in the business layer that has no notion of sessions.

Further, can't a session's processing get preempted between the push() and the actual logging resulting in something like:

John: The message being logged
null: The message being logged

Or am I missing something?

Your thoughts?

Sri

Re: [OT] Using the NDC while logging

[Tim Shadel <ti...@zserve.com>]

My understanding of NDC is a bit different.  Each thread maintains its 
own NDC stack, and that stack is printed on every log served by that thread.

SO, you don't need to sandwich all logging calls between push() and 
pop().  You just wrap them around the identifying region.

For example, in Struts I believe you could do the following

... execute(...) {
   NDC.push( /*userid*/ );

   SomeObject.someMethodCallThatDoesLogging();
   andAnotherOne();

   NDC.pop();
}

As long as the calls between the push() and pop() are processed by the 
same thread (and I don't see why they wouldn't be), then you'll get 
userid information printed on logs that know nothing about HttpSession 
objects.

SO, I don't think you need to muddle the business layer by trying to 
pass session objects around.  Just as long as the push() and pop() 
bracket the business logic calls at a higher level, and the business 
calls are made using the same thread (i.e. inter-process calls to EJBs 
obviously wouldn't keep it, and I don't know how various containers deal 
with in-process Servlet engine/EJB container thread work).

Does that mesh with anyone else's understanding?  Or did I miss somthing 
in the explanation?

--Tim

Sri Sankaran wrote:
> I would welcome your opinion on the proper use of the Nested Diagnostic Context (NDC) when logging using log4j.
> 
> As you know in a multi-threaded servlet environment, the NDC provides valuable contextual information to help make sense of otherwise hopelessly interleaved messages in the log device.  What is the correct procedure for setting up the NDC?  It seems like every log message must be sandwiched by a push() and a pop().  For example:
> 
>   NDC.push("something");
>   log.debug("The message being logged");
>   NDC.pop();
> 
> What is the overhead of changing all log statements to this format?  Especially requiring consideration is the fact that the "something" that uniquely identifies a context isn't always readily available and may require some computation to obtain.  For example, the unique identifier may be the userid which is (probably) stashed away in the session, so the above three line segment is really:
> 
>   NDC.push((String)session.getAttribute("user.key"));
>   log.debug("The message being logged");
>   NDC.pop();
> 
> This not only adds to the latency (?) it also necessitates the -- otherwise unnecessary -- passing of the session object around.  It also muddies logging in the business layer that has no notion of sessions.
> 
> Further, can't a session's processing get preempted between the push() and the actual logging resulting in something like:
> 
> John: The message being logged
> null: The message being logged
> 
> Or am I missing something?
> 
> Your thoughts?
> 
> Sri
> 



---------------------------------------------------------------------
To unsubscribe, e-mail: struts-user-unsubscribe@jakarta.apache.org
For additional commands, e-mail: struts-user-help@jakarta.apache.org

Re: [OT] Using the NDC while logging

[Aidan Monroe <km...@yahoo.com>]

This is a very good question. I have just started
looking at this as well and would welcome any
information anyone has on it.


--- Sri Sankaran <Sr...@sas.com> wrote:
> I would welcome your opinion on the proper use of
> the Nested Diagnostic Context (NDC) when logging
> using log4j.
> 
> As you know in a multi-threaded servlet environment,
> the NDC provides valuable contextual information to
> help make sense of otherwise hopelessly interleaved
> messages in the log device.  What is the correct
> procedure for setting up the NDC?  It seems like
> every log message must be sandwiched by a push() and
> a pop().  For example:
> 
>   NDC.push("something");
>   log.debug("The message being logged");
>   NDC.pop();
> 
> What is the overhead of changing all log statements
> to this format?  Especially requiring consideration
> is the fact that the "something" that uniquely
> identifies a context isn't always readily available
> and may require some computation to obtain.  For
> example, the unique identifier may be the userid
> which is (probably) stashed away in the session, so
> the above three line segment is really:
> 
>  
> NDC.push((String)session.getAttribute("user.key"));
>   log.debug("The message being logged");
>   NDC.pop();
> 
> This not only adds to the latency (?) it also
> necessitates the -- otherwise unnecessary -- passing
> of the session object around.  It also muddies
> logging in the business layer that has no notion of
> sessions.
> 
> Further, can't a session's processing get preempted
> between the push() and the actual logging resulting
> in something like:
> 
> John: The message being logged
> null: The message being logged
> 
> Or am I missing something?
> 
> Your thoughts?
> 
> Sri
> 


__________________________________________________
Do you Yahoo!?
Yahoo! Platinum - Watch CBS' NCAA March Madness, live on your desktop!
http://platinum.yahoo.com

---------------------------------------------------------------------
To unsubscribe, e-mail: struts-user-unsubscribe@jakarta.apache.org
For additional commands, e-mail: struts-user-help@jakarta.apache.org