How to get extra exception details for logging?

Question

Recently i've encountered a problem of getting as much details from exception as i possibly could. The reason? Well, when you need to solve problems in shipped product the log is usually the only thing you have.

Obviously

Exception.ToString()

works pretty well but it is not very helpful when you deal with FaultException and who knows what surprises can custom exceptions give you.

So what is the best way to get exception details with decent level of paranoia?

Answer 1

Logging information from an exception may be useful, but the approach of transactional logging may provide much more information.

The idea is to trace as many log messages as you can, but don't write them out in your log files, and instead accumulate them in an in memory queue. If the operation that the user committed has completed successfully, then you just dispose the collection of trace messages. But if an exception was thrown, you can log both the exception and the trace messages you've accumulated during the execution.

The benefit is obvious - not only you have the information that something went wrong, but you also know what processes happened inside your system that lead to the exception.

Answer 2

I've looked around and googled on the topic. Susrpisingly there are not so many discussions on this. Anyway I tried to compound quintessence here.

Talk is cheap. Show me the code.

1. Here we have the sample code throwing the exception.

   protected void TestExceptionDetails()
   {
       try
       {
           int zero = 0;
   
           try
           {
               int z = zero / zero;
           }
           catch (Exception e)
           {
               var applicationException = new ApplicationException("rethrow", e);
               // put some hint why exception occured
               applicationException.Data.Add("divider_value", zero);
               throw applicationException;
           }
       }
       catch (Exception e)
       {
           var extendedexceptionDetails = GetExtendedexceptionDetails(e);
           log.ErrorFormat("Detailed:{0}", extendedexceptionDetails);
       }
   }
   

2. Here is the method GetExtendedExceptionDetails:

   /// <summary>
   /// This utility method can be used for retrieving extra details from exception objects.
   /// </summary>
   /// <param name="e">Exception.</param>
   /// <param name="indent">Optional parameter. String used for text indent.</param>
   /// <returns>String with as much details was possible to get from exception.</returns>
   public static string GetExtendedexceptionDetails(object e, string indent = null)
   {
       // we want to be robust when dealing with errors logging
       try
       {
           var sb = new StringBuilder(indent);
           // it's good to know the type of exception
           sb.AppendLine("Type: " + e.GetType().FullName);
           // fetch instance level properties that we can read
           var props = e.GetType().GetProperties(BindingFlags.Public | BindingFlags.Instance).Where(p => p.CanRead);
   
           foreach (PropertyInfo p in props)
           {
               try
               {
                   var v = p.GetValue(e, null);
   
                   // in case of Fault contracts we'd like to know what Detail contains
                   if (e is FaultException && p.Name == "Detail")
                   {
                       sb.AppendLine(string.Format("{0}{1}:", indent, p.Name));
                       sb.AppendLine(GetExtendedexceptionDetails(v, "  " + indent));// recursive call
                   }
                   // Usually this is InnerException
                   else if (v is Exception)
                   {
                       sb.AppendLine(string.Format("{0}{1}:", indent, p.Name));
                       sb.AppendLine(GetExtendedexceptionDetails(v as Exception, "  " + indent));// recursive call
                   }
                   // some other property
                   else
                   {
                       sb.AppendLine(string.Format("{0}{1}: '{2}'", indent, p.Name, v));
   
                       // Usually this is Data property
                       if (v is IDictionary)
                       {
                           var d = v as IDictionary;
                           sb.AppendLine(string.Format("{0}{1}={2}", " " + indent, "count", d.Count));
                           foreach (DictionaryEntry kvp in d)
                           {
                               sb.AppendLine(string.Format("{0}[{1}]:[{2}]", " " + indent, kvp.Key, kvp.Value));
                           }
                       }
                   }
               }
               catch (Exception exception)
               {
                   //swallow or log
               }
           }
   
           //remove redundant CR+LF in the end of buffer
           sb.Length = sb.Length - 2;
           return sb.ToString();
       }
       catch (Exception exception)
       {
           //log or swallow here
           return string.Empty;
       }
   }
   

As you can see we use Reflection to get instance properties and then get their values. I know it is expensive but we don't really know what possible properties the concrete exception exposes. And we all hope that errors won't occur so often in application that it would kill the performance.

Now let's look at what we actually gained.

This is what Exception.ToString returns:

System.ApplicationException: rethrow ---> System.DivideByZeroException: Attempted to divide by zero.
   at NET4.TestClasses.Other.TestExceptionDetails() in c:\tmp\prj\NET4\TestClasses\Other.cs:line 1116
   --- End of inner exception stack trace ---
   at NET4.TestClasses.Other.TestExceptionDetails() in c:\tmp\prj\NET4\TestClasses\Other.cs:line 1123

And this returns our new method:

Type: System.ApplicationException
Message: 'rethrow'
Data: 'System.Collections.ListDictionaryInternal'
 count=1
 [divider_value]:[0]
InnerException:
  Type: System.DivideByZeroException
  Message: 'Attempted to divide by zero.'
  Data: 'System.Collections.ListDictionaryInternal'
   count=0
  InnerException: ''
  TargetSite: 'Void TestExceptionDetails()'
  StackTrace: '   at NET4.TestClasses.Other.TestExceptionDetails() in c:\tmp\prj\NET4\TestClasses\Other.cs:line 1116'
  HelpLink: ''
  Source: 'NET4'
TargetSite: 'Void TestExceptionDetails()'
StackTrace: '   at NET4.TestClasses.Other.TestExceptionDetails() in c:\tmp\prj\NET4\TestClasses\Other.cs:line 1123'
HelpLink: ''
Source: 'NET4'

We use log4net for logging and to reduce the performance overhead there is ILog.IsErrorEnabled property. I just check it before calling the extended exception handling.