logging-log4net-user mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From "Duncan Woods" <duncan.wo...@garradhassan.com>
Subject RE: When to log, when to throw - Help!
Date Fri, 30 Jun 2006 22:34:04 GMT
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 <duncan.woods@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


Mime
View raw message