Exception Logging

There is often a requirement for an application to log unhandled (and sometimes “handled”) exceptions.  This logging could occur to a log file, to the Event Log, a logging server, etc.  There’s great reasons to log exceptions but logging exceptions can be fraught with problems.

I’ve have many clients that have been requested to log exceptions and simply threw (pardon the pun) in a call to some logging method in every catch block and added catch blocks around most code that could throw.  This certainly gets the exception logged but introduces at least one problem: if it’s an unhandled exception, when does the exception stop getting logged?  For example, given the following code:

    //…

    internal sealed class MyClass

    {

        private const int NAME_FIELDINDEX = 1;

        private IDAL dal;

        public MyClass ( )

        {

            // TODO: Base from configuration

            dal = MyOtherClass.Create();

        }

        public String GetName ( )

        {

            String name = String.Empty;

            try

            {

                dal.ReadField(NAME_FIELDINDEX, ref name);

            }

            catch (Exception exception)

            {

                Logger.LogException(exception);

                throw;

            }

            return name;

        }

    }

 

    //…

    internal sealed class MyOtherClass : IDAL

    {

        IDataReader dataReader;

        //…

        public static IDAL Create ( )

        {

            // TODO: do something real

            return new MyOtherClass();

        }

 

        // implements IDAL.ReadField<T>(int, ref T)

        public bool ReadField<T> ( int index, ref T value )

        {

            try

            {

                value = (T)dataReader.GetValue(index);

            }

            catch (InvalidCastException invalidCastException)

            {

                Logger.LogLogicError(Resources.GetMessage(Resources.MessageType.LogicError), invalidCastException);

                return false;

            }

            catch (Exception exception)

            {

                Logger.LogException(exception);

                throw;

            }

            return true;

        }

    }

 

    //…

    public static class Program

    {

        public static void Main ( )

        {

            // …

            MyClass myObject = new MyClass();

            String name = myObject.GetName();

            // …

        }

    }


…since no other method should know (or more importantly, rely-upon) the implementation details of another (like whether it logs exceptions or not) and with a notion that low-level exception logging should be implemented, each method is forced to log exceptions.  As a result, in this example, there would be two identical exceptions logged here.  Anyone debugging would have to know to begin researching the problem with the first in a series of identical exceptions; but, this could be a rat-hole because it assumes adjacently logged exceptions are really the same–which isn’t always going to be the case.  But, that’s the minor problem.  What if logging is performed to file and a StackException occurs?  Best case, nothing gets logged and several StackExceptions occur (calling another method in the presence of a StackException doesn’t go far and may just throw another StackException), worst case you’ve conceptually got an infinite loop and the remote possibility it can write the event, filling up the event log.  Same would occur with a file, quickly eating up disk space.  In low disk space situations or where there are policies to restrict the size of the Event Log you run into a denial of service problem (i.e. you’ve blocked all other applications from writing to the event log or to disk).

While the intentions are noble here, the result is not as useful as it was intended to be.  How do you correct this?

This situation can be corrected by mirroring accepted exception handling practices: only catch exceptions you can handle with the exception of a last-chance exception handler.  Since there’s the requirement of logging both unhandled and some handled exceptions; logging of handled exceptions needs to occur when the exception is handled, and the notion of low-level unhandled exception logging should be abandoned and unhandled exceptions would be logged at the last-chance handler.  This change would result in something like:

    //…

    internal sealed class MyClass

    {

        private const int NAME_FIELDINDEX = 1;

        private IDAL dal;

        public MyClass ( )

        {

            // TODO: Base from configuration

            dal = MyOtherClass.Create();

        }

        public String GetName ( )

        {

            String name = String.Empty;

            dal.ReadField(NAME_FIELDINDEX, ref name);

            return name;

        }

    }

 

    //…

    internal sealed class MyOtherClass : IDAL

    {

        IDataReader dataReader;

        //…

        public static IDAL Create ( )

        {

            // TODO: do something real

            return new MyOtherClass();

        }

 

        // implements IDAL.ReadField<T>(int, ref T)

        public bool ReadField<T> ( int index, ref T value )

        {

            try

            {

                value = (T)dataReader.GetValue(index);

            }

            catch (InvalidCastException invalidCastException)

            {

                Logger.LogLogicError(Resources.GetMessage(Resources.MessageType.LogicError), invalidCastException);

                return false;

            }

            return true;

        }

    }

 

    public static class Program

    {

 

        public static void Main ( )

        {

            try

            {

                MyClass myObject = new MyClass();

                String name = myObject.GetName();

                //…

            }

            catch (Exception exception)

            {

                // last-chance handler

                Logger.LogException(exception);

                throw; // optional re-throw

                // terminate

            }

        }

    }


I’ve added a last-change handler in Program.Main, removed the exception handler from MyClass.GetName, and removed the catch(Exception) block from MyOtherClass.GetField<T>. Now you’ve got simpler code (even in this example, more so in the real world), without the potential of duplicate exception logging and denial of service.  And taking into account the performance implications of try blocks, potentially faster code.

8 thoughts on “Exception Logging”

  1. Hey Peter, I found your blog after reading a post or two of yours on the MSDN forums.

    I agree with your last-chance handling and think the example is a good illustration.

    For people working on existing code bases or projects where proper handling isn’t implemented from the start, it can be somewhat of a foreign concept.

    Also, I like your ReadField(int, ref T) for IDAL! It’s a good idea that I may just have to steal. Too bad it isn’t possible to do: value = dataReader.GetValue(index) as T; if (value == null) return false; so an exception doesn’t have to be thrown though.

  2. Chris, actually, if you add a constraint you can use the as keyword. You’d have to have the constraint ” where T : class” on your IDAL interface method(s). For example:

    internal interface IDAL
    {
    //…
    bool ReadField(int index, ref T output) where T : class;
    //…
    }

    internal sealed class MyOtherClass : IDAL
    {
    //…
    // implements IDAL.ReadField(int, ref T)
    public bool ReadField
    (int index, ref T value) where T : class
    {
    value = dataReader.GetValue(index) as T;

    return true;
    }
    //…
    }

    …but then I wouldn’t have an example of using the LogLogicError :-)

  3. Hi,

    to support also value types, you may do the following:

    public bool ReadField(int index, out T value)
    {
    object ret = dataReader.GetValue(index);
    if(ret is T)
    {
    value = (T)ret;
    return true;
    }
    else
    {
    value = default(T);
    return false;
    }
    }

    The ‘is’ operator also works with value types. I also prefer an out parameter instead of a ref parameter because you don’t have the passed variable to be initialized. But now, you’ve to initialize it in the ReadField method. This is done by setting it to default(T) in the error case (null for reference types and all bits zeroed for value types).

    By the way: You mentioned problems with a StackOverflowException. Since .net 2.0, StackOverflowExceptions can’t be handled in a catch blog so you’ll never be able to log them. They lead to a direct AppDomain unload. But you may still have problems with an OutOfMemoryException. See the msdn documentation for reference: http://msdn2.microsoft.com/en-us/library/system.stackoverflowexception.aspx

  4. Hi Peter,

    In my applications, I use the AppDomain.UnhandledException event for the purpose of logging unhandled exceptions. Your last-chance handler is only able to log exceptions on the main-thread unlike a handler of the AppDomain.UnhandledException event which gets fired at unhandled exceptions of any thread.
    You also mentioned a problem in the case of a StackOverflowException. Since .net 2.0, a StackOverflowException can’t be catched by a catch-block and so you can’t log it. It leads directly to an app domain unload. See the msdn documentation for reference:
    http://msdn2.microsoft.com/en-us/library/system.stackoverflowexception.aspx

    I also want to say that it’s easy to have the ReadField supporting value types without having to catch an InvalidCastException:

    public bool ReadField(int index, out T value)
    {
    object valueObject = dataReader.GetValue(index);
    if(valueObject is T)
    {
    value = (T)valueObject;
    return true;
    }
    else
    {
    value = default(T);
    return false;
    }
    }

  5. Yes, StackOverflowException is an example I’ve been using for quite a while (since .NET 1.x), mostly as an easy-to-understand concept. I should qualify with “if you could catch StackOverflowException”. I should probably retire that example and favour OutOfMemoryException or something similar. As a concept it’s easy to understand the consequences of trying to catch StackOverflowException as Exception, in that it doesn’t make sense (if you could catch StackOverflowException).

  6. Sorry for the double-post. It seamed that it didn’t take the first post so I rewrote it (the content of the textarea was gone). After posting the second I could actually see the first one. You may delete it (and also this comment).

  7. I have a website (ASP.NET 2.0+C#+SQL Server 2000) published on the server. The server’s disk space runs out and so the website is no longer viewable to the user. I would like to provide a custom message to the user, if the server space is low.

    How to provide the customized message to the user, incase the disk space on the primary drive( c:\) runs out?

    Please help. Thank you

Leave a Reply

Your email address will not be published. Required fields are marked *

You may use these HTML tags and attributes: <a href="" title=""> <abbr title=""> <acronym title=""> <b> <blockquote cite=""> <cite> <code> <del datetime=""> <em> <i> <q cite=""> <strike> <strong>