Single Responsibility Principle applied to exception logging

In the previous post How to log exceptions I said that you should let your logging framework handle exception logging. In this post I will explain why it is a bad idea to generate log messages in the catch block.

Lets first look at an example:

try
{
    UpdateAccount(userAccount);
}
catch (SqlException e)
{
    var sb = new StringBuilder();
    sb.AppendLine(e.ToString());
    sb.AppendFormat("Sql number: {0}", e.Number);
    sb.AppendFormat("Sql procedure: {0}", e.Procedure);
    sb.AppendFormat("Sql server: {0}", e.Server);

    logger.Error(sb.ToString());
}

As you can see, the main code invokes method UpdateAccount, which we can assume will perform update in the database. In the catch block error message is constructed with exception details and logged.

The first thing which you can easily notice is that exception handling block is much bigger than the main code. When analysing this code the user will have to filter out big chunk of exception formatting.

Next, because message formatting is embedded in the method, it will have to be duplicated across code base wherever SqlException is handled. The more places it is duplicated the harder it is to update.

And finally – it breaks Single Responsibility Principle. As defined by Uncle Bob:

A class should have one, and only one, reason to change.

In the above example, the class will have at least three reasons to change:

  1. the change in handling account update (this is the primary reason for this class)
  2. change in error message formatting, including adding/removing details
  3. change in error types handled, such as adding new error type to be logged

This is problematic because adding new exception property to be logged requires re-running all tests related to this call, including regression test. Suddenly a simple change is no longer simple.

The error message formatting logic belongs to the logging framework. Use type renderer for formatting message according to your needs. To handle logging new exception types you only need to create new type renderer and register it with logging framework. You can even reuse type renderers between different applications.
And the catch block will shrinks to one line of code:

logger.Error("Updating user account failed.", e);
Advertisements

How to log exceptions

If you log exceptions by saving it’s message:

logger.Error("Operation failed." + ex.Message);

or it’s string representation:

logger.Error("Operation failed." + ex.ToString());

you do it wrong! It makes extremely hard if not impossible to find out what went wrong in the application.
To be able to successfully debug application from log files you have to log at least: exception type, message, stack trace and, recursively, inner exceptions. For more specific exceptions you also want to log their properties. And then there is an AggregateException for which you need to log all aggregated exceptions.

Logging frameworks

There are many logging frameworks available and you should definitely use one. Make sure that the framework will handle exception logging and than use it! Even if the framework allows for passing object to be logged, for exceptions you should use an overload method which takes exception as a parameter. Those methods will take care of saving at least most important details about the exception and usually will support saving properties of specific exceptions such as ErrorCode or Procedure from SqlException. You may also find that the framework takes special rendering class which allows for better control of rendered message.

log4net

The log4net is one of the frameworks I use and it has support for handling typical exceptions as well as for providing custom renderers. All logging methods have overload which takes an exception object as a parameter. You use it like that:

ILog logger;
[...]

try
{
    // code
}
catch (Exception ex)
{
    loger.Error("Failed to publish message to the bus.", ex);
    throw;
}

When the operation fails then you should have something like this in the log:

2014-05-09 15:56:45,180 [8] ERROR - Failed to publish message to the bus.
System.Exception: The operation failed.
   at Log4NetSpike.Program.TestException() in C:CodeCustom SolutionSpikesLog4NetSpikeLog4NetSpikeProgram.cs:line 43

If exception has InnerException than we get it’s details as well:

2014-05-09 16:03:10,968 [9] ERROR - Log exception
System.Exception: outer exception ---> System.Exception: The inner operation failed.
   at Log4NetSpike.Program.DoThrow() in C:CodeCustom SolutionSpikesLog4NetSpikeLog4NetSpikeProgram.cs:line 53
   at Log4NetSpike.Program.TestInnerException() in C:CodeCustom SolutionSpikesLog4NetSpikeLog4NetSpikeProgram.cs:line 62
   --- End of inner exception stack trace ---
   at Log4NetSpike.Program.TestInnerException() in C:CodeCustom SolutionSpikesLog4NetSpikeLog4NetSpikeProgram.cs:line 67

Using Exception Renderer

If you do not like the way the exception is rendered, or you want to log some custom exception properties then you can provide your own class which inherits from IObjectRenderer. Below is a sample renderer which logs detailed data fromSqlException:

To register the renderer add following line into your log4net configuration:

<renderer renderingClass="Log4NetSpike.SqlExceptionRenderer, Log4NetSpike" renderedClass="System.Data.SqlClient.SqlException, System.Data, Version=4.0.0.0, Culture=neutral, PublicKeyToken=b77a5c561934e089"/>

(set value of renderingClass to fully qualified name of the renderer you use.)

Debugging with logs

Now, once you have detailed information about the exception you can begin debugging. I usually start with checking the exception message and type. Next I use stack trace to find source code (if you use ReSharper than check out Browse Stack Trace from menu Tools) and by checking previous messages I try to determine what was going on in the app.