26 Juni 2011

Exception Logging Antipatterns

Here are some logging antipatterns I have seen again and again in real life production code. If your application has one global exception handler, catching and logging should be done only in this central place. If you want to provide additional information throw a new exception and attach the original exception. I assume that the logging framework is capable of dumping an exception recursively, that means with all inner exceptions and their stacktraces.

Catch Log Throw
catch (Exception ex)
{
    _logger.WriteError(ex);
    throw;
}

No additionally info is added. The global exception handler will log this error anyway, therefore the logging is redundant and blows up your log. The correct solution is to not catch the exception at all.

Catch Log Throw Other

catch (Exception ex)
{
    _logger.WriteError(ex, "information");
    throw new InvalidOperationException("information"); // same information
}
Same as Catch Log Throw, but now you have two totally unrelated log entries. Solution: use the InnerException mechanism to create a new exception and don't log the old one:
throw new InvalidOperationException("information", ex);

Log Un-thrown Exceptions
catch (Exception ex)
{
    var myException = new MyException("information");
    _logger.WriteError(myException);
    throw myException;
}

In this case an un-thrown exception is logged. This could cause problems, because the exception is not fully initialized until it was thrown. For example the Stacktrace property would be null. Solution: don't log, just attach the original exception ex to MyException:
throw new MyException("information", ex);

Non Atomic Logging
catch (Exception ex)
{
    _logger.WriteError(ex.Message);
    _logger.WriteError("Some information");
    _logger.WriteError(ex);
    _logger.WriteError("More information");
}

Several log messages are created for one cause. In the log they appear unrelated and can be mixed with other log message. Solution: Combine the information into one atomic write to the logging system: _logger.WriteError(ex, "Some information and more information");

Expensive Log Messages
{
    [...] // some code
    _logger.WriteInformation(Helper.ReflectAllProperties(this));
}
This one is really dangerous for your performance. An expensive log message is generated all the time even if the logging system is configured to ignore it. If you have expensive message, put the generation into an if block side by side with the logging statement:
if (_logger.ShouldWrite(LogLevel.Information))
{
    // do expensive logging here
    _logger.WriteInformation(Helper.ReflectAllProperties(this));

}