You are viewing a plain text version of this content. The canonical link for it is here.
Posted to log4net-user@logging.apache.org by Duncan Woods <du...@garradhassan.com> on 2006/06/26 16:16:38 UTC
When to log, when to throw - Help!
Hi all,
I don't think I have grasped something basic about using error handling
as I am having trouble integrating exceptions with logging. The goal of
my logging is at high levels to be comprehensible to a non software
engineer and provide sufficient information to fix any problem that has
occurred. Exceptions are the default error handling of .Net and almost
every object can throw them in some situation. Catch handlers around
every call is not realistic but the level of detail I add to the NDC is
sufficient.
The problem is that if I log an exception message at the catch handler,
I have lost the context of the NDC and the resultant log message is
unhelpful. What are the other options? What design guidelines do you set
down?
i) Log the exception's call stack
This does not give presentable messages
ii) Log and throw at the same time
This can cause the same message to be logged repeatedly through the
hierarchy as the error ripples up to the top level. Ugly and harms
admin's ability to use log4net to trigger actions based on trace message
contents.
c) Append the NDC to an exception message
Suffers from both the previous problems - its not nice that the NDC
becomes part of them message and rethrowing an exception will cause
multiple copies of the NDC.
Thanks in advance for your ideas,
Duncan
RE: When to log, when to throw - Help!
Posted by Duncan Woods <du...@garradhassan.com>.
Hi Mike,
Thanks for the response. You are right there are multiple requirements
on the logging system but I don't quite see how two loggers can solve
the problem. It is:
>> simply logs the error for your non-techie operator?
which is the real driver for needing context. Its the operators only
hope to being able fix the problem. It's not good enough to leave the
exception message and the stack trace because it does not give state
information about the object instances e.g.
Executing Model A1
Executing Model B7
Executing Model C2
Exception : Malformed TimeZone
is more useful than:
Model::Execute
Model::Execute
Model::Execute
Model::PrepareConfig
Exception : Malformed TimeZone
The operator can then go and check their C2 configuration.
There are of course workarounds for this dodgy example e.g. logging
"Preparing configuration" before doing something or better error
handling for configuration validation but being able to take advantage
of the ndc context would be the fail-safe when either of the others have
been omitted - which has happened.
thanks,
Duncan
________________________________
From: Mike Raath [mailto:raathm@gmail.com]
Sent: 30 June 2006 14:37
To: Log4NET User
Subject: Re: When to log, when to throw - Help!
It sounds like you have 2 different logging requirements, so why not
have 2 different loggers? Use the standard FileAppender or similar to
log the exception and full stack trace (you don't need to do any more
than log usingg the error method, and have another that simply logs the
error for your non-techie operator?
Both of these can be designed using the standard formatting strings and
the advantage is that you can then alert for different error priorities.
On 6/30/06, Duncan Woods <du...@garradhassan.com> wrote:
Hi Ron,
Thanks for reply.
>> I usually catch exceptions at higher levels (my user
interface
>> or business layer) and let lower levels such as my data level
>> simple bubble the exceptions up.
Precisely what I do but almost all the error messages are
unhelpful
without context. The following example gives a bit more of a
feel for
the hierarchical multi part operations that include external
plug-ins
(which also use log4net):
try
{
foreach (service in Services)
{
using(NDC.Push("Updating service " + service.Name))
{
foreach (model in service.models)
{
using(NDC.Push("Executing model " + model.Name))
{
foreach (input in model)
{
using(NDC.Push("Extracting input " + input.Name))
{
// db
}
using(NDC.Push("Calculate " + model.Name))
{
// external calc
}
}
}
}
}
}
}
catch (Exception e)
{
log.Error("Unexpected error. Cause: " + ex.Message, ex);
}
This works great for successful logging where each log message
is
qualified with its own context but every exception is fatal so
there are
few catch handlers. A typical framework exception like "Key not
found"
from a dictionary object is useless at the top level but with an
NDC an
error could be logged with:
"Updating service Foo, Executing model Bar, Extracting Input
Dingo".
which gives a chance to resolve the problem. If they are my own
exceptions (lots are) then I could do this:
catch (NdcException e)
{
using(NDC.Push(e.Ndc))
{
log.Error("Unexpected error. Cause: " + ex.Message, ex);
}
}
where e.Ndc is the state of the Ndc at the throw minus the ndc
at the
catch. I'd still have to wrap and rethrow non NdcExceptions at
every
level of the Ndc hierarchy. I suppose that when not using a
logging
framework I expect to catch, wrap and rethrow exceptions to give
them
context anyway but I'm not satisfied with that given that there
is an
Ndc sat there.
Thoughts?
http://logging.apache.org/log4net/release/manual/contexts.html
I need a thread context stack so I believe ndc is the best bet
since its
handled by tools like ChainSaw.
Thanks,
Duncan
-----Original Message-----
From: Ron Grabowski [mailto:rongrabowski@yahoo.com]
Sent: 30 June 2006 01:45
To: Log4NET User
Subject: Re: When to log, when to throw - Help!
A good rule of thumb about exceptions is that if you can't do
something
with the exception (i.e. handle it gracefully or recover from
it) then
you shouldn't be catching it. I usually catch exceptions at
higher
levels (my user interface or business layer) and let lower
levels such
as my data level simple bubble the exceptions up.
What items are are you pushing onto the NDC?
When you talk about the NDC and catch blocks, are you doing
this:
using(NDC.Push("test1"))
{
try
{
generateApplicationException("Oh no!");
}
catch (Exception ex)
{
log.Error("Unexpected error. Cause: " + ex.Message, ex);
}
}
Are you loosing the NDC inside of the catch block? Are you aware
of the
other context objects:
http://logging.apache.org/log4net/release/manual/contexts.html
If you want to keep the contents of the NDC seperate from the
logging
message itself, have you thought about creating a simple XML
layout
that does that (the log4j schema may or may not already do
this):
<log>
<message>Unexpected error. Cause: Oh no!</message>
<exception>
... ApplicationException ...
</exception>
<ndc>
<item level="0">test1</item>
<ndc>
</log>
Does that help any?
--- Duncan Woods <du...@garradhassan.com> wrote:
> Hi all,
>
> I don't think I have grasped something basic about using error
> handling
> as I am having trouble integrating exceptions with logging.
The goal
> of
> my logging is at high levels to be comprehensible to a non
software
> engineer and provide sufficient information to fix any problem
that
> has
> occurred. Exceptions are the default error handling of .Net
and
> almost
> every object can throw them in some situation. Catch handlers
around
> every call is not realistic but the level of detail I add to
the NDC
> is
> sufficient.
>
> The problem is that if I log an exception message at the catch
> handler,
> I have lost the context of the NDC and the resultant log
message is
> unhelpful. What are the other options? What design guidelines
do you
> set
> down?
>
> i) Log the exception's call stack
>
> This does not give presentable messages
>
> ii) Log and throw at the same time
>
> This can cause the same message to be logged repeatedly
through
> the
> hierarchy as the error ripples up to the top level. Ugly and
harms
> admin's ability to use log4net to trigger actions based on
trace
> message
> contents.
>
> c) Append the NDC to an exception message
>
> Suffers from both the previous problems - its not nice
that the
> NDC
> becomes part of them message and rethrowing an exception will
cause
> multiple copies of the NDC.
>
>
> Thanks in advance for your ideas,
>
> Duncan
Re: When to log, when to throw - Help!
Posted by Mike Raath <ra...@gmail.com>.
It sounds like you have 2 different logging requirements, so why not have 2
different loggers? Use the standard FileAppender or similar to log the
exception and full stack trace (you don't need to do any more than log
usingg the error method, and have another that simply logs the error for
your non-techie operator?
Both of these can be designed using the standard formatting strings and the
advantage is that you can then alert for different error priorities.
On 6/30/06, Duncan Woods <du...@garradhassan.com> wrote:
>
> Hi Ron,
>
> Thanks for reply.
>
> >> I usually catch exceptions at higher levels (my user interface
> >> or business layer) and let lower levels such as my data level
> >> simple bubble the exceptions up.
>
> Precisely what I do but almost all the error messages are unhelpful
> without context. The following example gives a bit more of a feel for
> the hierarchical multi part operations that include external plug-ins
> (which also use log4net):
>
> try
> {
> foreach (service in Services)
> {
> using(NDC.Push("Updating service " + service.Name))
> {
> foreach (model in service.models)
> {
> using(NDC.Push("Executing model " + model.Name))
> {
> foreach (input in model)
> {
> using(NDC.Push("Extracting input " + input.Name))
> {
> // db
> }
> using(NDC.Push("Calculate " + model.Name))
> {
> // external calc
> }
> }
> }
> }
> }
> }
> }
> catch (Exception e)
> {
> log.Error("Unexpected error. Cause: " + ex.Message, ex);
> }
>
> This works great for successful logging where each log message is
> qualified with its own context but every exception is fatal so there are
> few catch handlers. A typical framework exception like "Key not found"
> from a dictionary object is useless at the top level but with an NDC an
> error could be logged with:
>
> "Updating service Foo, Executing model Bar, Extracting Input Dingo".
>
> which gives a chance to resolve the problem. If they are my own
> exceptions (lots are) then I could do this:
>
> catch (NdcException e)
> {
> using(NDC.Push(e.Ndc))
> {
> log.Error("Unexpected error. Cause: " + ex.Message, ex);
> }
> }
>
> where e.Ndc is the state of the Ndc at the throw minus the ndc at the
> catch. I'd still have to wrap and rethrow non NdcExceptions at every
> level of the Ndc hierarchy. I suppose that when not using a logging
> framework I expect to catch, wrap and rethrow exceptions to give them
> context anyway but I'm not satisfied with that given that there is an
> Ndc sat there.
>
> Thoughts?
>
> http://logging.apache.org/log4net/release/manual/contexts.html
>
> I need a thread context stack so I believe ndc is the best bet since its
> handled by tools like ChainSaw.
>
> Thanks,
> Duncan
>
>
>
> -----Original Message-----
> From: Ron Grabowski [mailto:rongrabowski@yahoo.com]
> Sent: 30 June 2006 01:45
> To: Log4NET User
> Subject: Re: When to log, when to throw - Help!
>
> A good rule of thumb about exceptions is that if you can't do something
> with the exception (i.e. handle it gracefully or recover from it) then
> you shouldn't be catching it. I usually catch exceptions at higher
> levels (my user interface or business layer) and let lower levels such
> as my data level simple bubble the exceptions up.
>
> What items are are you pushing onto the NDC?
>
> When you talk about the NDC and catch blocks, are you doing this:
>
> using(NDC.Push("test1"))
> {
> try
> {
> generateApplicationException("Oh no!");
> }
> catch (Exception ex)
> {
> log.Error("Unexpected error. Cause: " + ex.Message, ex);
> }
> }
>
> Are you loosing the NDC inside of the catch block? Are you aware of the
> other context objects:
>
> http://logging.apache.org/log4net/release/manual/contexts.html
>
> If you want to keep the contents of the NDC seperate from the logging
> message itself, have you thought about creating a simple XML layout
> that does that (the log4j schema may or may not already do this):
>
> <log>
> <message>Unexpected error. Cause: Oh no!</message>
> <exception>
> ... ApplicationException ...
> </exception>
> <ndc>
> <item level="0">test1</item>
> <ndc>
> </log>
>
> Does that help any?
>
> --- Duncan Woods <du...@garradhassan.com> wrote:
>
> > Hi all,
> >
> > I don't think I have grasped something basic about using error
> > handling
> > as I am having trouble integrating exceptions with logging. The goal
> > of
> > my logging is at high levels to be comprehensible to a non software
> > engineer and provide sufficient information to fix any problem that
> > has
> > occurred. Exceptions are the default error handling of .Net and
> > almost
> > every object can throw them in some situation. Catch handlers around
> > every call is not realistic but the level of detail I add to the NDC
> > is
> > sufficient.
> >
> > The problem is that if I log an exception message at the catch
> > handler,
> > I have lost the context of the NDC and the resultant log message is
> > unhelpful. What are the other options? What design guidelines do you
> > set
> > down?
> >
> > i) Log the exception's call stack
> >
> > This does not give presentable messages
> >
> > ii) Log and throw at the same time
> >
> > This can cause the same message to be logged repeatedly through
> > the
> > hierarchy as the error ripples up to the top level. Ugly and harms
> > admin's ability to use log4net to trigger actions based on trace
> > message
> > contents.
> >
> > c) Append the NDC to an exception message
> >
> > Suffers from both the previous problems - its not nice that the
> > NDC
> > becomes part of them message and rethrowing an exception will cause
> > multiple copies of the NDC.
> >
> >
> > Thanks in advance for your ideas,
> >
> > Duncan
>
RE: When to log, when to throw - Help!
Posted by Duncan Woods <du...@garradhassan.com>.
>> DisposeReason might contain values like
>> ExplicitDisposeCall, ExitingTryBlock,...
Yes I can see that being useful. Similarly in-vain mechanisms that have crossed my mind are:
1. A means to append information to the current stack frame that persists into Exception.StackTrace
2. An event or system interrupt that triggers when any .Net exception is thrown
3. C++ style preprocessor/compiler directives
4. A means to extend functionality of System.Exception (and therefore all ex derived from it)
Do any of these exist?
thanks,
Duncan
-----Original Message-----
From: Ron Grabowski [mailto:rongrabowski@yahoo.com]
Sent: Mon 7/3/2006 6:44 PM
To: Log4NET User
Subject: RE: When to log, when to throw - Help!
Isn't the automatic clean-up more a feature of the using statement
rather than the ThreadContext? In VB.Net, you'd need to call Push and
Pop yourself.
If it were easy to define new language constructs perhaps a
Dispose(DisposeReason) could be added to explain why the object was
being disposed. DisposeReason might contain values like
ExplicitDisposeCall, ExitingTryBlock, ExitingTryBlockWithException,
etc. Then you could choose whether or not to pop values from the NDC
based on how the using block was being disposed. I'm not a language
designer so I don't know how practical that would be. ASP.Net does
something similiar when an item is being removed from the cache but
object disposition occurs much more frequently that removing items from
a cache.
Anyway, I can't think of a simple way to ensure that values don't get
popped when the NDC's Dispose method is called. I'll think about it
somemore...
--- Duncan Woods <du...@garradhassan.com> wrote:
> Hiya Ron,
>
> Thanks for the response. You certainly understand my intention.
>
> >> There's nothing wrong with calling Pop() yourself:
>
> Oh but there is!
>
> An important attraction of thread context is the automatic clear up
> that makes it impossible to screw-up. Forget one pop however and your
> context is misleading for the rest of the lifetime of the
> application. This may not be due to direct omission but by exceptions
> that are caught and handled or by different exit points from a
> function. Its a load of coding overhead and a disaster waiting to
> happen.
>
> Thanks for the suggestion, its the right output but not quite there!
>
> Thanks,
> Duncan
>
>
> -----Original Message-----
> From: Ron Grabowski [mailto:rongrabowski@yahoo.com]
> Sent: Fri 6/30/2006 9:14 PM
> To: Log4NET User
> Subject: RE: When to log, when to throw - Help!
>
> Let's configure a basic ConsoleAppender and use a using() block to
> push
> items onto the NDC from two loops:
>
> ConsoleAppender consoleAppender = new ConsoleAppender();
> consoleAppender.Layout = new PatternLayout(
> "MESSAGE [%message] NDC [%ndc] EXCEPTION [%exception]%newline");
> BasicConfigurator.Configure(consoleAppender);
>
> ILog log = LogManager.GetLogger(typeof(Class1));
>
> int[] oddNumbers = new int[5] {1, 3, 5, 7, 9};
> int[] evenNumbers = new int[5] {2, 4, 6, 8, 10};
>
> try
> {
> foreach (int oddNumber in oddNumbers)
> {
> using(NDC.Push("oddNumber: " + oddNumber))
> {
> foreach (int evenNumber in evenNumbers)
> {
> using(NDC.Push("evenNumber: " + evenNumber))
> {
> if (oddNumber == 7)
> {
> throw new ApplicationException("Oh no!");
> }
> log.DebugFormat("Sum: {0}",
> oddNumber + evenNumber);
> }
> }
> }
> }
> }
> catch (Exception ex)
> {
> log.Fatal(
> "Unhandled exception. Cause: " + ex.Message, ex);
> }
>
> That program produces the following output:
>
> MESSAGE [Sum: 3] NDC [oddNumber: 1 evenNumber: 2] EXCEPTION []
> MESSAGE [Sum: 5] NDC [oddNumber: 1 evenNumber: 4] EXCEPTION []
> MESSAGE [Sum: 7] NDC [oddNumber: 1 evenNumber: 6] EXCEPTION []
> MESSAGE [Sum: 9] NDC [oddNumber: 1 evenNumber: 8] EXCEPTION []
> MESSAGE [Sum: 11] NDC [oddNumber: 1 evenNumber: 10] EXCEPTION []
> MESSAGE [Sum: 5] NDC [oddNumber: 3 evenNumber: 2] EXCEPTION []
> MESSAGE [Sum: 7] NDC [oddNumber: 3 evenNumber: 4] EXCEPTION []
> MESSAGE [Sum: 9] NDC [oddNumber: 3 evenNumber: 6] EXCEPTION []
> MESSAGE [Sum: 11] NDC [oddNumber: 3 evenNumber: 8] EXCEPTION []
> MESSAGE [Sum: 13] NDC [oddNumber: 3 evenNumber: 10] EXCEPTION []
> MESSAGE [Sum: 7] NDC [oddNumber: 5 evenNumber: 2] EXCEPTION []
> MESSAGE [Sum: 9] NDC [oddNumber: 5 evenNumber: 4] EXCEPTION []
> MESSAGE [Sum: 11] NDC [oddNumber: 5 evenNumber: 6] EXCEPTION []
> MESSAGE [Sum: 13] NDC [oddNumber: 5 evenNumber: 8] EXCEPTION []
> MESSAGE [Sum: 15] NDC [oddNumber: 5 evenNumber: 10] EXCEPTION []
> MESSAGE [Unhandled exception. Cause: Oh no!] NDC [(null)] EXCEPTION
> [System.ApplicationException: Oh no!
> at ConsoleApplication1.Class1.ndcPushWithUsing() in
> c:\consoleapplication1\class1.cs:line 45
> ]
>
> I suspect your question is about the null NDC value when the
> exception
> occurs. It would be better to show this information:
>
> NDC [oddNumber: 7 evenNumber: 2]
>
> C#'s using() statement automatically calls Dispose() on its
> expression.
> When you leave the try block and enter the catch block the objects in
> the try block are disposed. In the case of NDC, the items are being
> popped from the stack and the stack becomes empty.
>
> There's nothing wrong with calling Pop() yourself:
>
> try
> {
> foreach (int oddNumber in oddNumbers)
> {
> NDC.Push("oddNumber: " + oddNumber);
> {
> foreach (int evenNumber in evenNumbers)
> {
> NDC.Push("evenNumber: " + evenNumber);
> {
> if (oddNumber == 7)
> {
> throw new ApplicationException("Oh no!");
> }
> log.DebugFormat("Sum: {0}",
> oddNumber + evenNumber);
> }
> NDC.Pop();
> }
> }
> NDC.Pop();
> }
> }
> catch (Exception ex)
> {
> log.Fatal(
> "Unhandled exception. Cause: " + ex.Message, ex);
> }
> finally
> {
> NDC.Clear();
> }
>
> That code produces the following output:
>
> MESSAGE [Sum: 3] NDC [oddNumber: 1 evenNumber: 2] EXCEPTION []
> MESSAGE [Sum: 5] NDC [oddNumber: 1 evenNumber: 4] EXCEPTION []
> MESSAGE [Sum: 7] NDC [oddNumber: 1 evenNumber: 6] EXCEPTION []
> MESSAGE [Sum: 9] NDC [oddNumber: 1 evenNumber: 8] EXCEPTION []
> MESSAGE [Sum: 11] NDC [oddNumber: 1 evenNumber: 10] EXCEPTION []
> MESSAGE [Sum: 5] NDC [oddNumber: 3 evenNumber: 2] EXCEPTION []
> MESSAGE [Sum: 7] NDC [oddNumber: 3 evenNumber: 4] EXCEPTION []
> MESSAGE [Sum: 9] NDC [oddNumber: 3 evenNumber: 6] EXCEPTION []
> MESSAGE [Sum: 11] NDC [oddNumber: 3 evenNumber: 8] EXCEPTION []
> MESSAGE [Sum: 13] NDC [oddNumber: 3 evenNumber: 10] EXCEPTION []
> MESSAGE [Sum: 7] NDC [oddNumber: 5 evenNumber: 2] EXCEPTION []
> MESSAGE [Sum: 9] NDC [oddNumber: 5 evenNumber: 4] EXCEPTION []
> MESSAGE [Sum: 11] NDC [oddNumber: 5 evenNumber: 6] EXCEPTION []
> MESSAGE [Sum: 13] NDC [oddNumber: 5 evenNumber: 8] EXCEPTION []
> MESSAGE [Sum: 15] NDC [oddNumber: 5 evenNumber: 10] EXCEPTION []
> MESSAGE [Unhandled exception. Cause: Oh no!] NDC [oddNumber: 7
> evenNumber: 2] EXCEPTION [System.ApplicationException: Oh no!
> at ConsoleApplication1.Class1.ndcPushWithUsing() in
> c:\consoleapplication1\class1.cs:line 45
> ]
>
> Is that an ok solution?
>
> - Ron
>
> --- Duncan Woods <du...@garradhassan.com> wrote:
>
> > Hi Ron,
> >
> > Thanks for reply.
> >
> > >> I usually catch exceptions at higher levels (my user interface
> > >> or business layer) and let lower levels such as my data level
> > >> simple bubble the exceptions up.
> >
> > Precisely what I do but almost all the error messages are unhelpful
> > without context. The following example gives a bit more of a feel
> for
> > the hierarchical multi part operations that include external
> plug-ins
> > (which also use log4net):
> >
> > try
> > {
> > foreach (service in Services)
> > {
> > using(NDC.Push("Updating service " + service.Name))
> > {
> > foreach (model in service.models)
> > {
> > using(NDC.Push("Executing model " + model.Name))
> > {
> > foreach (input in model)
> > {
> > using(NDC.Push("Extracting input " + input.Name))
> > {
> > // db
> > }
> > using(NDC.Push("Calculate " + model.Name))
> > {
>
=== message truncated ===
RE: When to log, when to throw - Help!
Posted by Duncan Woods <du...@garradhassan.com>.
Ron,
>> Isn't the automatic clean-up more a feature of the
>> using statement rather than the ThreadContext?
Sorry if I wasn't clear. I consider them intertwined because I wouldn't use explicit (push/pop) ThreadContext without automatic clear-up. Too error prone.
I have tried to work out a scheme for anonymous delegates to provide context safe exceptions but sadly there is too much dang strong typing so either you have to declare a delegate type for anything you wish to execute contextually or do what I attach below which is ugly in so many different ways! Basically it requires that each level of context is a separate method, which is perfectly acceptable (and often the case anyway), and then call it as a delegate but sadly passing arguments requires filthy casting and its broken for ref, out, value-types and return values.
I post it to see if it sparks the creativity of anyone else to find a more effective scheme that is simpler and type-safe.
On a related note - the NDC Method 'CloneStack' doesn't work as I expected - it doesn't return a copy but a reference that is manipulated without consent plus the contained items are classes internal to log4net that don't have a sensible ToString so you can't do diddly with them. This is why I had to pop and re-push the ndc to copy it in NdcException. Doesn't FxCop warn about this?
anyway... on to the ugliness, believe it or not, it is functionally the same example Ron gave before:
using System;
using System.Collections.Generic;
using System.Text;
using log4net;
using log4net.Appender;
using log4net.Config;
using log4net.Layout;
namespace ConsoleApplication
{
public delegate void ExecuteInContext(params object[] p);
// execute code passed as an anonymous delegate with context safe exceptions
public abstract class Context
{
public static void Execute(string context, ExecuteInContext call, params object[] p)
{
using (NDC.Push(context))
{
try
{
call(p);
}
catch (Exception e)
{
if (!(e is NdcException)) throw new NdcException(e);
else throw;
}
}
}
}
// Wrap a normal exception and append the ndc stack - requires more effort than it should
public class NdcException : Exception
{
public NdcException(Exception e)
: base(e.Message, e)
{
Stack<string> stack = new Stack<string>();
StringBuilder sb = new StringBuilder("Exception : ");
while (NDC.Depth > 0)
{
stack.Push(NDC.Pop());
}
while (stack.Count > 0)
{
string s = stack.Pop();
sb.AppendFormat("{0} ", s);
NDC.Push(s);
}
Ndc = sb.ToString();
}
public string Ndc;
}
class Program
{
static ConsoleAppender consoleAppender;
static ILog log;
static void Main(string[] args)
{
consoleAppender = new ConsoleAppender();
consoleAppender.Layout = new PatternLayout("MESSAGE [%message] NDC [%ndc]%newline");
BasicConfigurator.Configure(consoleAppender);
log = LogManager.GetLogger(typeof(Program));
int[] oddNumbers = new int[5] { 1, 3, 5, 7, 9 };
int[] evenNumbers = new int[5] { 2, 4, 6, 8, 10 };
try
{
foreach (int oddNumber in oddNumbers)
{
Context.Execute(
"oddNumber: " + oddNumber,
delegate(object[] p) {EachEven((int) p[0], (int[]) p[1]);},
oddNumber, evenNumbers);
}
}
// Provide a contextual exception message
catch (NdcException ex)
{
using (NDC.Push(ex.Ndc))
{
log.Fatal(ex.Message);
}
}
catch (Exception ex)
{
log.Fatal("Should never happen: " + ex.Message, ex);
}
}
public static void EachEven(int oddNumber, int[] evenNumbers)
{
foreach (int evenNumber in evenNumbers)
{
Context.Execute(
"evenNumber: " + evenNumber,
delegate(object[] p) {TestOdd((int) p[0], (int) p[1]);},
oddNumber, evenNumber);
}
}
public static void TestOdd(int oddNumber, int evenNumber)
{
if (oddNumber == 7)
{
throw new ApplicationException("Oh no!");
}
log.DebugFormat("Sum: {0}", oddNumber + evenNumber);
}
}
}
Thanks,
Duncan
RE: When to log, when to throw - Help!
Posted by Duncan Woods <du...@garradhassan.com>.
Hi there,
I have come up with a solution which I think works well enough for me.
It is to store the deepest level of context reached and instead of
popping off each level as the context goes out of scope, it is only
updated when a new context block is started.
The only drawback is that if an exception is thrown /after/ a context
block then it will be misleading. In the code below, if you throw at
XXX, then the NDC will be for the preceding block. I'll simply have to
treat this as part of the coding standards to only apply context to
entire levels of scope.
Any better suggestions?
Thanks,
Duncan
using System;
using System.Collections.Generic;
using System.Text;
using log4net;
using log4net.Appender;
using log4net.Layout;
using log4net.Config;
using System.Diagnostics;
namespace ConsoleApplication1
{
class Program
{
static ConsoleAppender consoleAppender;
static ILog log;
static void Main(string[] args)
{
consoleAppender = new ConsoleAppender();
consoleAppender.Layout = new PatternLayout("MESSAGE
[%message] NDC [%ndc]%newline");
BasicConfigurator.Configure(consoleAppender);
log = LogManager.GetLogger(typeof(Program));
int[] oddNumbers = new int[5] { 1, 3, 5, 7, 9 };
int[] evenNumbers = new int[5] { 2, 4, 6, 8, 10 };
try
{
foreach (int oddNumber in oddNumbers)
{
using (Context.Push("oddNumber: " + oddNumber))
{
foreach (int evenNumber in evenNumbers)
{
using (Context.Push("evenNumber: " +
evenNumber))
{
if (oddNumber == 7)
{
throw new ApplicationException("Oh
no!");
}
log.DebugFormat("Sum: {0}", oddNumber +
evenNumber);
}
// XXX
}
}
}
}
catch (Exception ex)
{
Context.LogException(log, "Unhandled exception '" +
ex.Message + "'", ex);
}
}
/// <summary>
///
/// </summary>
public class Context : IDisposable
{
public static Context Push(string s)
{
return new Context(s);
}
// Log the exception with the deepest ndc reached
public static void LogException(ILog log, string message,
Exception e)
{
Stack<string> ndc = new Stack<string>();
while (NDC.Depth > 0)
{
ndc.Push(NDC.Pop());
}
NDC.Push(DeepestNdc);
log.Error(message, e);
NDC.Pop();
while (ndc.Count > 0)
{
NDC.Push(ndc.Pop());
}
}
// Convert the deepest ndc to a string
public static string DeepestNdc
{
get
{
int i =
System.Threading.Thread.CurrentThread.ManagedThreadId;
Stack<string> context;
if (!deepest.TryGetValue(i, out context))
{
return "";
}
Stack<string> temp = new Stack<string>();
StringBuilder sb = new StringBuilder();
while (context.Count > 0)
{
temp.Push(context.Pop());
}
while (temp.Count > 0)
{
string ndc = temp.Pop();
sb.AppendFormat("{0} ", ndc);
context.Push(ndc);
}
return sb.ToString();
}
}
// Reset the deepest context to the current NDC value
public Context(string s)
{
int i =
System.Threading.Thread.CurrentThread.ManagedThreadId;
Stack<string> context;
if (!deepest.TryGetValue(i, out context))
{
context = new Stack<string>();
deepest[i] = context;
}
while (context.Count > NDC.Depth)
{
context.Pop();
}
context.Push(s);
NDC.Push(s);
}
public void Dispose()
{
NDC.Pop();
}
static Dictionary<int, Stack<string>> deepest = new
Dictionary<int, Stack<string>>();
}
}
}
RE: When to log, when to throw - Help!
Posted by Ron Grabowski <ro...@yahoo.com>.
Isn't the automatic clean-up more a feature of the using statement
rather than the ThreadContext? In VB.Net, you'd need to call Push and
Pop yourself.
If it were easy to define new language constructs perhaps a
Dispose(DisposeReason) could be added to explain why the object was
being disposed. DisposeReason might contain values like
ExplicitDisposeCall, ExitingTryBlock, ExitingTryBlockWithException,
etc. Then you could choose whether or not to pop values from the NDC
based on how the using block was being disposed. I'm not a language
designer so I don't know how practical that would be. ASP.Net does
something similiar when an item is being removed from the cache but
object disposition occurs much more frequently that removing items from
a cache.
Anyway, I can't think of a simple way to ensure that values don't get
popped when the NDC's Dispose method is called. I'll think about it
somemore...
--- Duncan Woods <du...@garradhassan.com> wrote:
> Hiya Ron,
>
> Thanks for the response. You certainly understand my intention.
>
> >> There's nothing wrong with calling Pop() yourself:
>
> Oh but there is!
>
> An important attraction of thread context is the automatic clear up
> that makes it impossible to screw-up. Forget one pop however and your
> context is misleading for the rest of the lifetime of the
> application. This may not be due to direct omission but by exceptions
> that are caught and handled or by different exit points from a
> function. Its a load of coding overhead and a disaster waiting to
> happen.
>
> Thanks for the suggestion, its the right output but not quite there!
>
> Thanks,
> Duncan
>
>
> -----Original Message-----
> From: Ron Grabowski [mailto:rongrabowski@yahoo.com]
> Sent: Fri 6/30/2006 9:14 PM
> To: Log4NET User
> Subject: RE: When to log, when to throw - Help!
>
> Let's configure a basic ConsoleAppender and use a using() block to
> push
> items onto the NDC from two loops:
>
> ConsoleAppender consoleAppender = new ConsoleAppender();
> consoleAppender.Layout = new PatternLayout(
> "MESSAGE [%message] NDC [%ndc] EXCEPTION [%exception]%newline");
> BasicConfigurator.Configure(consoleAppender);
>
> ILog log = LogManager.GetLogger(typeof(Class1));
>
> int[] oddNumbers = new int[5] {1, 3, 5, 7, 9};
> int[] evenNumbers = new int[5] {2, 4, 6, 8, 10};
>
> try
> {
> foreach (int oddNumber in oddNumbers)
> {
> using(NDC.Push("oddNumber: " + oddNumber))
> {
> foreach (int evenNumber in evenNumbers)
> {
> using(NDC.Push("evenNumber: " + evenNumber))
> {
> if (oddNumber == 7)
> {
> throw new ApplicationException("Oh no!");
> }
> log.DebugFormat("Sum: {0}",
> oddNumber + evenNumber);
> }
> }
> }
> }
> }
> catch (Exception ex)
> {
> log.Fatal(
> "Unhandled exception. Cause: " + ex.Message, ex);
> }
>
> That program produces the following output:
>
> MESSAGE [Sum: 3] NDC [oddNumber: 1 evenNumber: 2] EXCEPTION []
> MESSAGE [Sum: 5] NDC [oddNumber: 1 evenNumber: 4] EXCEPTION []
> MESSAGE [Sum: 7] NDC [oddNumber: 1 evenNumber: 6] EXCEPTION []
> MESSAGE [Sum: 9] NDC [oddNumber: 1 evenNumber: 8] EXCEPTION []
> MESSAGE [Sum: 11] NDC [oddNumber: 1 evenNumber: 10] EXCEPTION []
> MESSAGE [Sum: 5] NDC [oddNumber: 3 evenNumber: 2] EXCEPTION []
> MESSAGE [Sum: 7] NDC [oddNumber: 3 evenNumber: 4] EXCEPTION []
> MESSAGE [Sum: 9] NDC [oddNumber: 3 evenNumber: 6] EXCEPTION []
> MESSAGE [Sum: 11] NDC [oddNumber: 3 evenNumber: 8] EXCEPTION []
> MESSAGE [Sum: 13] NDC [oddNumber: 3 evenNumber: 10] EXCEPTION []
> MESSAGE [Sum: 7] NDC [oddNumber: 5 evenNumber: 2] EXCEPTION []
> MESSAGE [Sum: 9] NDC [oddNumber: 5 evenNumber: 4] EXCEPTION []
> MESSAGE [Sum: 11] NDC [oddNumber: 5 evenNumber: 6] EXCEPTION []
> MESSAGE [Sum: 13] NDC [oddNumber: 5 evenNumber: 8] EXCEPTION []
> MESSAGE [Sum: 15] NDC [oddNumber: 5 evenNumber: 10] EXCEPTION []
> MESSAGE [Unhandled exception. Cause: Oh no!] NDC [(null)] EXCEPTION
> [System.ApplicationException: Oh no!
> at ConsoleApplication1.Class1.ndcPushWithUsing() in
> c:\consoleapplication1\class1.cs:line 45
> ]
>
> I suspect your question is about the null NDC value when the
> exception
> occurs. It would be better to show this information:
>
> NDC [oddNumber: 7 evenNumber: 2]
>
> C#'s using() statement automatically calls Dispose() on its
> expression.
> When you leave the try block and enter the catch block the objects in
> the try block are disposed. In the case of NDC, the items are being
> popped from the stack and the stack becomes empty.
>
> There's nothing wrong with calling Pop() yourself:
>
> try
> {
> foreach (int oddNumber in oddNumbers)
> {
> NDC.Push("oddNumber: " + oddNumber);
> {
> foreach (int evenNumber in evenNumbers)
> {
> NDC.Push("evenNumber: " + evenNumber);
> {
> if (oddNumber == 7)
> {
> throw new ApplicationException("Oh no!");
> }
> log.DebugFormat("Sum: {0}",
> oddNumber + evenNumber);
> }
> NDC.Pop();
> }
> }
> NDC.Pop();
> }
> }
> catch (Exception ex)
> {
> log.Fatal(
> "Unhandled exception. Cause: " + ex.Message, ex);
> }
> finally
> {
> NDC.Clear();
> }
>
> That code produces the following output:
>
> MESSAGE [Sum: 3] NDC [oddNumber: 1 evenNumber: 2] EXCEPTION []
> MESSAGE [Sum: 5] NDC [oddNumber: 1 evenNumber: 4] EXCEPTION []
> MESSAGE [Sum: 7] NDC [oddNumber: 1 evenNumber: 6] EXCEPTION []
> MESSAGE [Sum: 9] NDC [oddNumber: 1 evenNumber: 8] EXCEPTION []
> MESSAGE [Sum: 11] NDC [oddNumber: 1 evenNumber: 10] EXCEPTION []
> MESSAGE [Sum: 5] NDC [oddNumber: 3 evenNumber: 2] EXCEPTION []
> MESSAGE [Sum: 7] NDC [oddNumber: 3 evenNumber: 4] EXCEPTION []
> MESSAGE [Sum: 9] NDC [oddNumber: 3 evenNumber: 6] EXCEPTION []
> MESSAGE [Sum: 11] NDC [oddNumber: 3 evenNumber: 8] EXCEPTION []
> MESSAGE [Sum: 13] NDC [oddNumber: 3 evenNumber: 10] EXCEPTION []
> MESSAGE [Sum: 7] NDC [oddNumber: 5 evenNumber: 2] EXCEPTION []
> MESSAGE [Sum: 9] NDC [oddNumber: 5 evenNumber: 4] EXCEPTION []
> MESSAGE [Sum: 11] NDC [oddNumber: 5 evenNumber: 6] EXCEPTION []
> MESSAGE [Sum: 13] NDC [oddNumber: 5 evenNumber: 8] EXCEPTION []
> MESSAGE [Sum: 15] NDC [oddNumber: 5 evenNumber: 10] EXCEPTION []
> MESSAGE [Unhandled exception. Cause: Oh no!] NDC [oddNumber: 7
> evenNumber: 2] EXCEPTION [System.ApplicationException: Oh no!
> at ConsoleApplication1.Class1.ndcPushWithUsing() in
> c:\consoleapplication1\class1.cs:line 45
> ]
>
> Is that an ok solution?
>
> - Ron
>
> --- Duncan Woods <du...@garradhassan.com> wrote:
>
> > Hi Ron,
> >
> > Thanks for reply.
> >
> > >> I usually catch exceptions at higher levels (my user interface
> > >> or business layer) and let lower levels such as my data level
> > >> simple bubble the exceptions up.
> >
> > Precisely what I do but almost all the error messages are unhelpful
> > without context. The following example gives a bit more of a feel
> for
> > the hierarchical multi part operations that include external
> plug-ins
> > (which also use log4net):
> >
> > try
> > {
> > foreach (service in Services)
> > {
> > using(NDC.Push("Updating service " + service.Name))
> > {
> > foreach (model in service.models)
> > {
> > using(NDC.Push("Executing model " + model.Name))
> > {
> > foreach (input in model)
> > {
> > using(NDC.Push("Extracting input " + input.Name))
> > {
> > // db
> > }
> > using(NDC.Push("Calculate " + model.Name))
> > {
>
=== message truncated ===
RE: When to log, when to throw - Help!
Posted by Duncan Woods <du...@garradhassan.com>.
Hiya Ron,
Thanks for the response. You certainly understand my intention.
>> There's nothing wrong with calling Pop() yourself:
Oh but there is!
An important attraction of thread context is the automatic clear up that makes it impossible to screw-up. Forget one pop however and your context is misleading for the rest of the lifetime of the application. This may not be due to direct omission but by exceptions that are caught and handled or by different exit points from a function. Its a load of coding overhead and a disaster waiting to happen.
Thanks for the suggestion, its the right output but not quite there!
Thanks,
Duncan
-----Original Message-----
From: Ron Grabowski [mailto:rongrabowski@yahoo.com]
Sent: Fri 6/30/2006 9:14 PM
To: Log4NET User
Subject: RE: When to log, when to throw - Help!
Let's configure a basic ConsoleAppender and use a using() block to push
items onto the NDC from two loops:
ConsoleAppender consoleAppender = new ConsoleAppender();
consoleAppender.Layout = new PatternLayout(
"MESSAGE [%message] NDC [%ndc] EXCEPTION [%exception]%newline");
BasicConfigurator.Configure(consoleAppender);
ILog log = LogManager.GetLogger(typeof(Class1));
int[] oddNumbers = new int[5] {1, 3, 5, 7, 9};
int[] evenNumbers = new int[5] {2, 4, 6, 8, 10};
try
{
foreach (int oddNumber in oddNumbers)
{
using(NDC.Push("oddNumber: " + oddNumber))
{
foreach (int evenNumber in evenNumbers)
{
using(NDC.Push("evenNumber: " + evenNumber))
{
if (oddNumber == 7)
{
throw new ApplicationException("Oh no!");
}
log.DebugFormat("Sum: {0}",
oddNumber + evenNumber);
}
}
}
}
}
catch (Exception ex)
{
log.Fatal(
"Unhandled exception. Cause: " + ex.Message, ex);
}
That program produces the following output:
MESSAGE [Sum: 3] NDC [oddNumber: 1 evenNumber: 2] EXCEPTION []
MESSAGE [Sum: 5] NDC [oddNumber: 1 evenNumber: 4] EXCEPTION []
MESSAGE [Sum: 7] NDC [oddNumber: 1 evenNumber: 6] EXCEPTION []
MESSAGE [Sum: 9] NDC [oddNumber: 1 evenNumber: 8] EXCEPTION []
MESSAGE [Sum: 11] NDC [oddNumber: 1 evenNumber: 10] EXCEPTION []
MESSAGE [Sum: 5] NDC [oddNumber: 3 evenNumber: 2] EXCEPTION []
MESSAGE [Sum: 7] NDC [oddNumber: 3 evenNumber: 4] EXCEPTION []
MESSAGE [Sum: 9] NDC [oddNumber: 3 evenNumber: 6] EXCEPTION []
MESSAGE [Sum: 11] NDC [oddNumber: 3 evenNumber: 8] EXCEPTION []
MESSAGE [Sum: 13] NDC [oddNumber: 3 evenNumber: 10] EXCEPTION []
MESSAGE [Sum: 7] NDC [oddNumber: 5 evenNumber: 2] EXCEPTION []
MESSAGE [Sum: 9] NDC [oddNumber: 5 evenNumber: 4] EXCEPTION []
MESSAGE [Sum: 11] NDC [oddNumber: 5 evenNumber: 6] EXCEPTION []
MESSAGE [Sum: 13] NDC [oddNumber: 5 evenNumber: 8] EXCEPTION []
MESSAGE [Sum: 15] NDC [oddNumber: 5 evenNumber: 10] EXCEPTION []
MESSAGE [Unhandled exception. Cause: Oh no!] NDC [(null)] EXCEPTION
[System.ApplicationException: Oh no!
at ConsoleApplication1.Class1.ndcPushWithUsing() in
c:\consoleapplication1\class1.cs:line 45
]
I suspect your question is about the null NDC value when the exception
occurs. It would be better to show this information:
NDC [oddNumber: 7 evenNumber: 2]
C#'s using() statement automatically calls Dispose() on its expression.
When you leave the try block and enter the catch block the objects in
the try block are disposed. In the case of NDC, the items are being
popped from the stack and the stack becomes empty.
There's nothing wrong with calling Pop() yourself:
try
{
foreach (int oddNumber in oddNumbers)
{
NDC.Push("oddNumber: " + oddNumber);
{
foreach (int evenNumber in evenNumbers)
{
NDC.Push("evenNumber: " + evenNumber);
{
if (oddNumber == 7)
{
throw new ApplicationException("Oh no!");
}
log.DebugFormat("Sum: {0}",
oddNumber + evenNumber);
}
NDC.Pop();
}
}
NDC.Pop();
}
}
catch (Exception ex)
{
log.Fatal(
"Unhandled exception. Cause: " + ex.Message, ex);
}
finally
{
NDC.Clear();
}
That code produces the following output:
MESSAGE [Sum: 3] NDC [oddNumber: 1 evenNumber: 2] EXCEPTION []
MESSAGE [Sum: 5] NDC [oddNumber: 1 evenNumber: 4] EXCEPTION []
MESSAGE [Sum: 7] NDC [oddNumber: 1 evenNumber: 6] EXCEPTION []
MESSAGE [Sum: 9] NDC [oddNumber: 1 evenNumber: 8] EXCEPTION []
MESSAGE [Sum: 11] NDC [oddNumber: 1 evenNumber: 10] EXCEPTION []
MESSAGE [Sum: 5] NDC [oddNumber: 3 evenNumber: 2] EXCEPTION []
MESSAGE [Sum: 7] NDC [oddNumber: 3 evenNumber: 4] EXCEPTION []
MESSAGE [Sum: 9] NDC [oddNumber: 3 evenNumber: 6] EXCEPTION []
MESSAGE [Sum: 11] NDC [oddNumber: 3 evenNumber: 8] EXCEPTION []
MESSAGE [Sum: 13] NDC [oddNumber: 3 evenNumber: 10] EXCEPTION []
MESSAGE [Sum: 7] NDC [oddNumber: 5 evenNumber: 2] EXCEPTION []
MESSAGE [Sum: 9] NDC [oddNumber: 5 evenNumber: 4] EXCEPTION []
MESSAGE [Sum: 11] NDC [oddNumber: 5 evenNumber: 6] EXCEPTION []
MESSAGE [Sum: 13] NDC [oddNumber: 5 evenNumber: 8] EXCEPTION []
MESSAGE [Sum: 15] NDC [oddNumber: 5 evenNumber: 10] EXCEPTION []
MESSAGE [Unhandled exception. Cause: Oh no!] NDC [oddNumber: 7
evenNumber: 2] EXCEPTION [System.ApplicationException: Oh no!
at ConsoleApplication1.Class1.ndcPushWithUsing() in
c:\consoleapplication1\class1.cs:line 45
]
Is that an ok solution?
- Ron
--- Duncan Woods <du...@garradhassan.com> wrote:
> Hi Ron,
>
> Thanks for reply.
>
> >> I usually catch exceptions at higher levels (my user interface
> >> or business layer) and let lower levels such as my data level
> >> simple bubble the exceptions up.
>
> Precisely what I do but almost all the error messages are unhelpful
> without context. The following example gives a bit more of a feel for
> the hierarchical multi part operations that include external plug-ins
> (which also use log4net):
>
> try
> {
> foreach (service in Services)
> {
> using(NDC.Push("Updating service " + service.Name))
> {
> foreach (model in service.models)
> {
> using(NDC.Push("Executing model " + model.Name))
> {
> foreach (input in model)
> {
> using(NDC.Push("Extracting input " + input.Name))
> {
> // db
> }
> using(NDC.Push("Calculate " + model.Name))
> {
> // external calc
> }
> }
> }
> }
> }
> }
> }
> catch (Exception e)
> {
> log.Error("Unexpected error. Cause: " + ex.Message, ex);
> }
>
> This works great for successful logging where each log message is
> qualified with its own context but every exception is fatal so there
> are
> few catch handlers. A typical framework exception like "Key not
> found"
> from a dictionary object is useless at the top level but with an NDC
> an
> error could be logged with:
>
> "Updating service Foo, Executing model Bar, Extracting Input Dingo".
>
> which gives a chance to resolve the problem. If they are my own
> exceptions (lots are) then I could do this:
>
> catch (NdcException e)
> {
> using(NDC.Push(e.Ndc))
> {
> log.Error("Unexpected error. Cause: " + ex.Message, ex);
> }
> }
>
> where e.Ndc is the state of the Ndc at the throw minus the ndc at the
> catch. I'd still have to wrap and rethrow non NdcExceptions at every
> level of the Ndc hierarchy. I suppose that when not using a logging
> framework I expect to catch, wrap and rethrow exceptions to give them
> context anyway but I'm not satisfied with that given that there is an
> Ndc sat there.
>
> Thoughts?
>
> http://logging.apache.org/log4net/release/manual/contexts.html
>
> I need a thread context stack so I believe ndc is the best bet since
> its
> handled by tools like ChainSaw.
>
> Thanks,
> Duncan
RE: When to log, when to throw - Help!
Posted by Ron Grabowski <ro...@yahoo.com>.
Let's configure a basic ConsoleAppender and use a using() block to push
items onto the NDC from two loops:
ConsoleAppender consoleAppender = new ConsoleAppender();
consoleAppender.Layout = new PatternLayout(
"MESSAGE [%message] NDC [%ndc] EXCEPTION [%exception]%newline");
BasicConfigurator.Configure(consoleAppender);
ILog log = LogManager.GetLogger(typeof(Class1));
int[] oddNumbers = new int[5] {1, 3, 5, 7, 9};
int[] evenNumbers = new int[5] {2, 4, 6, 8, 10};
try
{
foreach (int oddNumber in oddNumbers)
{
using(NDC.Push("oddNumber: " + oddNumber))
{
foreach (int evenNumber in evenNumbers)
{
using(NDC.Push("evenNumber: " + evenNumber))
{
if (oddNumber == 7)
{
throw new ApplicationException("Oh no!");
}
log.DebugFormat("Sum: {0}",
oddNumber + evenNumber);
}
}
}
}
}
catch (Exception ex)
{
log.Fatal(
"Unhandled exception. Cause: " + ex.Message, ex);
}
That program produces the following output:
MESSAGE [Sum: 3] NDC [oddNumber: 1 evenNumber: 2] EXCEPTION []
MESSAGE [Sum: 5] NDC [oddNumber: 1 evenNumber: 4] EXCEPTION []
MESSAGE [Sum: 7] NDC [oddNumber: 1 evenNumber: 6] EXCEPTION []
MESSAGE [Sum: 9] NDC [oddNumber: 1 evenNumber: 8] EXCEPTION []
MESSAGE [Sum: 11] NDC [oddNumber: 1 evenNumber: 10] EXCEPTION []
MESSAGE [Sum: 5] NDC [oddNumber: 3 evenNumber: 2] EXCEPTION []
MESSAGE [Sum: 7] NDC [oddNumber: 3 evenNumber: 4] EXCEPTION []
MESSAGE [Sum: 9] NDC [oddNumber: 3 evenNumber: 6] EXCEPTION []
MESSAGE [Sum: 11] NDC [oddNumber: 3 evenNumber: 8] EXCEPTION []
MESSAGE [Sum: 13] NDC [oddNumber: 3 evenNumber: 10] EXCEPTION []
MESSAGE [Sum: 7] NDC [oddNumber: 5 evenNumber: 2] EXCEPTION []
MESSAGE [Sum: 9] NDC [oddNumber: 5 evenNumber: 4] EXCEPTION []
MESSAGE [Sum: 11] NDC [oddNumber: 5 evenNumber: 6] EXCEPTION []
MESSAGE [Sum: 13] NDC [oddNumber: 5 evenNumber: 8] EXCEPTION []
MESSAGE [Sum: 15] NDC [oddNumber: 5 evenNumber: 10] EXCEPTION []
MESSAGE [Unhandled exception. Cause: Oh no!] NDC [(null)] EXCEPTION
[System.ApplicationException: Oh no!
at ConsoleApplication1.Class1.ndcPushWithUsing() in
c:\consoleapplication1\class1.cs:line 45
]
I suspect your question is about the null NDC value when the exception
occurs. It would be better to show this information:
NDC [oddNumber: 7 evenNumber: 2]
C#'s using() statement automatically calls Dispose() on its expression.
When you leave the try block and enter the catch block the objects in
the try block are disposed. In the case of NDC, the items are being
popped from the stack and the stack becomes empty.
There's nothing wrong with calling Pop() yourself:
try
{
foreach (int oddNumber in oddNumbers)
{
NDC.Push("oddNumber: " + oddNumber);
{
foreach (int evenNumber in evenNumbers)
{
NDC.Push("evenNumber: " + evenNumber);
{
if (oddNumber == 7)
{
throw new ApplicationException("Oh no!");
}
log.DebugFormat("Sum: {0}",
oddNumber + evenNumber);
}
NDC.Pop();
}
}
NDC.Pop();
}
}
catch (Exception ex)
{
log.Fatal(
"Unhandled exception. Cause: " + ex.Message, ex);
}
finally
{
NDC.Clear();
}
That code produces the following output:
MESSAGE [Sum: 3] NDC [oddNumber: 1 evenNumber: 2] EXCEPTION []
MESSAGE [Sum: 5] NDC [oddNumber: 1 evenNumber: 4] EXCEPTION []
MESSAGE [Sum: 7] NDC [oddNumber: 1 evenNumber: 6] EXCEPTION []
MESSAGE [Sum: 9] NDC [oddNumber: 1 evenNumber: 8] EXCEPTION []
MESSAGE [Sum: 11] NDC [oddNumber: 1 evenNumber: 10] EXCEPTION []
MESSAGE [Sum: 5] NDC [oddNumber: 3 evenNumber: 2] EXCEPTION []
MESSAGE [Sum: 7] NDC [oddNumber: 3 evenNumber: 4] EXCEPTION []
MESSAGE [Sum: 9] NDC [oddNumber: 3 evenNumber: 6] EXCEPTION []
MESSAGE [Sum: 11] NDC [oddNumber: 3 evenNumber: 8] EXCEPTION []
MESSAGE [Sum: 13] NDC [oddNumber: 3 evenNumber: 10] EXCEPTION []
MESSAGE [Sum: 7] NDC [oddNumber: 5 evenNumber: 2] EXCEPTION []
MESSAGE [Sum: 9] NDC [oddNumber: 5 evenNumber: 4] EXCEPTION []
MESSAGE [Sum: 11] NDC [oddNumber: 5 evenNumber: 6] EXCEPTION []
MESSAGE [Sum: 13] NDC [oddNumber: 5 evenNumber: 8] EXCEPTION []
MESSAGE [Sum: 15] NDC [oddNumber: 5 evenNumber: 10] EXCEPTION []
MESSAGE [Unhandled exception. Cause: Oh no!] NDC [oddNumber: 7
evenNumber: 2] EXCEPTION [System.ApplicationException: Oh no!
at ConsoleApplication1.Class1.ndcPushWithUsing() in
c:\consoleapplication1\class1.cs:line 45
]
Is that an ok solution?
- Ron
--- Duncan Woods <du...@garradhassan.com> wrote:
> Hi Ron,
>
> Thanks for reply.
>
> >> I usually catch exceptions at higher levels (my user interface
> >> or business layer) and let lower levels such as my data level
> >> simple bubble the exceptions up.
>
> Precisely what I do but almost all the error messages are unhelpful
> without context. The following example gives a bit more of a feel for
> the hierarchical multi part operations that include external plug-ins
> (which also use log4net):
>
> try
> {
> foreach (service in Services)
> {
> using(NDC.Push("Updating service " + service.Name))
> {
> foreach (model in service.models)
> {
> using(NDC.Push("Executing model " + model.Name))
> {
> foreach (input in model)
> {
> using(NDC.Push("Extracting input " + input.Name))
> {
> // db
> }
> using(NDC.Push("Calculate " + model.Name))
> {
> // external calc
> }
> }
> }
> }
> }
> }
> }
> catch (Exception e)
> {
> log.Error("Unexpected error. Cause: " + ex.Message, ex);
> }
>
> This works great for successful logging where each log message is
> qualified with its own context but every exception is fatal so there
> are
> few catch handlers. A typical framework exception like "Key not
> found"
> from a dictionary object is useless at the top level but with an NDC
> an
> error could be logged with:
>
> "Updating service Foo, Executing model Bar, Extracting Input Dingo".
>
> which gives a chance to resolve the problem. If they are my own
> exceptions (lots are) then I could do this:
>
> catch (NdcException e)
> {
> using(NDC.Push(e.Ndc))
> {
> log.Error("Unexpected error. Cause: " + ex.Message, ex);
> }
> }
>
> where e.Ndc is the state of the Ndc at the throw minus the ndc at the
> catch. I'd still have to wrap and rethrow non NdcExceptions at every
> level of the Ndc hierarchy. I suppose that when not using a logging
> framework I expect to catch, wrap and rethrow exceptions to give them
> context anyway but I'm not satisfied with that given that there is an
> Ndc sat there.
>
> Thoughts?
>
> http://logging.apache.org/log4net/release/manual/contexts.html
>
> I need a thread context stack so I believe ndc is the best bet since
> its
> handled by tools like ChainSaw.
>
> Thanks,
> Duncan
RE: When to log, when to throw - Help!
Posted by Duncan Woods <du...@garradhassan.com>.
Hi Ron,
Thanks for reply.
>> I usually catch exceptions at higher levels (my user interface
>> or business layer) and let lower levels such as my data level
>> simple bubble the exceptions up.
Precisely what I do but almost all the error messages are unhelpful
without context. The following example gives a bit more of a feel for
the hierarchical multi part operations that include external plug-ins
(which also use log4net):
try
{
foreach (service in Services)
{
using(NDC.Push("Updating service " + service.Name))
{
foreach (model in service.models)
{
using(NDC.Push("Executing model " + model.Name))
{
foreach (input in model)
{
using(NDC.Push("Extracting input " + input.Name))
{
// db
}
using(NDC.Push("Calculate " + model.Name))
{
// external calc
}
}
}
}
}
}
}
catch (Exception e)
{
log.Error("Unexpected error. Cause: " + ex.Message, ex);
}
This works great for successful logging where each log message is
qualified with its own context but every exception is fatal so there are
few catch handlers. A typical framework exception like "Key not found"
from a dictionary object is useless at the top level but with an NDC an
error could be logged with:
"Updating service Foo, Executing model Bar, Extracting Input Dingo".
which gives a chance to resolve the problem. If they are my own
exceptions (lots are) then I could do this:
catch (NdcException e)
{
using(NDC.Push(e.Ndc))
{
log.Error("Unexpected error. Cause: " + ex.Message, ex);
}
}
where e.Ndc is the state of the Ndc at the throw minus the ndc at the
catch. I'd still have to wrap and rethrow non NdcExceptions at every
level of the Ndc hierarchy. I suppose that when not using a logging
framework I expect to catch, wrap and rethrow exceptions to give them
context anyway but I'm not satisfied with that given that there is an
Ndc sat there.
Thoughts?
http://logging.apache.org/log4net/release/manual/contexts.html
I need a thread context stack so I believe ndc is the best bet since its
handled by tools like ChainSaw.
Thanks,
Duncan
-----Original Message-----
From: Ron Grabowski [mailto:rongrabowski@yahoo.com]
Sent: 30 June 2006 01:45
To: Log4NET User
Subject: Re: When to log, when to throw - Help!
A good rule of thumb about exceptions is that if you can't do something
with the exception (i.e. handle it gracefully or recover from it) then
you shouldn't be catching it. I usually catch exceptions at higher
levels (my user interface or business layer) and let lower levels such
as my data level simple bubble the exceptions up.
What items are are you pushing onto the NDC?
When you talk about the NDC and catch blocks, are you doing this:
using(NDC.Push("test1"))
{
try
{
generateApplicationException("Oh no!");
}
catch (Exception ex)
{
log.Error("Unexpected error. Cause: " + ex.Message, ex);
}
}
Are you loosing the NDC inside of the catch block? Are you aware of the
other context objects:
http://logging.apache.org/log4net/release/manual/contexts.html
If you want to keep the contents of the NDC seperate from the logging
message itself, have you thought about creating a simple XML layout
that does that (the log4j schema may or may not already do this):
<log>
<message>Unexpected error. Cause: Oh no!</message>
<exception>
... ApplicationException ...
</exception>
<ndc>
<item level="0">test1</item>
<ndc>
</log>
Does that help any?
--- Duncan Woods <du...@garradhassan.com> wrote:
> Hi all,
>
> I don't think I have grasped something basic about using error
> handling
> as I am having trouble integrating exceptions with logging. The goal
> of
> my logging is at high levels to be comprehensible to a non software
> engineer and provide sufficient information to fix any problem that
> has
> occurred. Exceptions are the default error handling of .Net and
> almost
> every object can throw them in some situation. Catch handlers around
> every call is not realistic but the level of detail I add to the NDC
> is
> sufficient.
>
> The problem is that if I log an exception message at the catch
> handler,
> I have lost the context of the NDC and the resultant log message is
> unhelpful. What are the other options? What design guidelines do you
> set
> down?
>
> i) Log the exception's call stack
>
> This does not give presentable messages
>
> ii) Log and throw at the same time
>
> This can cause the same message to be logged repeatedly through
> the
> hierarchy as the error ripples up to the top level. Ugly and harms
> admin's ability to use log4net to trigger actions based on trace
> message
> contents.
>
> c) Append the NDC to an exception message
>
> Suffers from both the previous problems - its not nice that the
> NDC
> becomes part of them message and rethrowing an exception will cause
> multiple copies of the NDC.
>
>
> Thanks in advance for your ideas,
>
> Duncan
Re: When to log, when to throw - Help!
Posted by Ron Grabowski <ro...@yahoo.com>.
A good rule of thumb about exceptions is that if you can't do something
with the exception (i.e. handle it gracefully or recover from it) then
you shouldn't be catching it. I usually catch exceptions at higher
levels (my user interface or business layer) and let lower levels such
as my data level simple bubble the exceptions up.
What items are are you pushing onto the NDC?
When you talk about the NDC and catch blocks, are you doing this:
using(NDC.Push("test1"))
{
try
{
generateApplicationException("Oh no!");
}
catch (Exception ex)
{
log.Error("Unexpected error. Cause: " + ex.Message, ex);
}
}
Are you loosing the NDC inside of the catch block? Are you aware of the
other context objects:
http://logging.apache.org/log4net/release/manual/contexts.html
If you want to keep the contents of the NDC seperate from the logging
message itself, have you thought about creating a simple XML layout
that does that (the log4j schema may or may not already do this):
<log>
<message>Unexpected error. Cause: Oh no!</message>
<exception>
... ApplicationException ...
</exception>
<ndc>
<item level="0">test1</item>
<ndc>
</log>
Does that help any?
--- Duncan Woods <du...@garradhassan.com> wrote:
> Hi all,
>
> I don't think I have grasped something basic about using error
> handling
> as I am having trouble integrating exceptions with logging. The goal
> of
> my logging is at high levels to be comprehensible to a non software
> engineer and provide sufficient information to fix any problem that
> has
> occurred. Exceptions are the default error handling of .Net and
> almost
> every object can throw them in some situation. Catch handlers around
> every call is not realistic but the level of detail I add to the NDC
> is
> sufficient.
>
> The problem is that if I log an exception message at the catch
> handler,
> I have lost the context of the NDC and the resultant log message is
> unhelpful. What are the other options? What design guidelines do you
> set
> down?
>
> i) Log the exception's call stack
>
> This does not give presentable messages
>
> ii) Log and throw at the same time
>
> This can cause the same message to be logged repeatedly through
> the
> hierarchy as the error ripples up to the top level. Ugly and harms
> admin's ability to use log4net to trigger actions based on trace
> message
> contents.
>
> c) Append the NDC to an exception message
>
> Suffers from both the previous problems - its not nice that the
> NDC
> becomes part of them message and rethrowing an exception will cause
> multiple copies of the NDC.
>
>
> Thanks in advance for your ideas,
>
> Duncan