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);

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.

Using complex type messages with EasyNetQ

This is the second post in series about EasyNetQ. In the first post I am explaining how to install RabbitMQ and write simple application which publishes and consumes string messages.

Complex type message

Usually you will need to send more complex types than string. Fortunately it is no harder than sending string messages. All you need to do is to create library project which will contain your message types and share it between publishers and consumers.

Load the example application you made in the first post and add new Class Library project to the solution named Messages. Add new class PersonName to that project which will represent persons name:

Next, add new class CreateAccountMessage to represent a message which is raised when user created new account:

Consuming complex type messages

There really is no difference in consuming complex type message from simple type message. All dirty work related to routing, serialisation and deserialisation is handled by EasyNetQ. All you have to do is to add reference to Messages project from your ConsumerApplication project and change Subscribe registration to

bus.Subscribe<CreateAccountMessage>("consumer1", message =>
    Console.WriteLine("Creating account for {0} {1}, age {2}.", message.Name.FirstName, message.Name.LastName, message.Age)
);

Publishing complex type messages

Again, as you would expect, nothing complicated here. Just add reference to Messages project from the PublisherApplication and change the call to Publish method to:

bus.Publish(new CreateAccountMessage("Joe", "Smith", 26));

Now run the ConsumerApplication by right clicking project name in Solution Explorer and selecting Debug > Start new instance. Next run the PublishedApplication project in the same way and you should see ConsumerApplication receiving the message.

Why do I have to share Messages

As you could see there is a need for sharing project with messages between publisher and consumer project. This is dictated by the way EasyNetQ is handling message delivery. Under the hood, the EasyNetQ is registering exchange and queue in RabbitMQ server using message strongly type names, which in our case will be Messages.CreateAccountMessage:Messages. If the consumer will subscribe to the bus with message type residing in different assembly (such as ConsumerApplication) then it won’t match the type of published message, even though they have the same definition.
Anyway, the requirement for sharing message types is not that bad as it will prevent problems with different versions of messages being published and consumed. It also allows for sharing message’s behaviour, as only data is carried over the message bus.

EasyNetQ with RabbitMQ – easy way to messaging

Few people have asked me already how to start using RabbitMQ in .NET, so I decided to write a short post about it.

Installation

First, visit erlang’s page, download erlang distribution according to your system (either 32 or 64 bit) and install it. If you have 64 bit machine (and you really should have) than get the 64 bit distribution, otherwise erlang process won’t be able to address more than 2GB of memory.

Next download RabbitMQ server and install it. I strongly recommend to install Management Plugin, which comes with RabbitMQ installation. All you need to do is run following command from command prompt (you may have to navigate to RabbitMQ’s sbin folder):

rabbitmq-plugins enable rabbitmq_management

There are detailed instructions on Management Plugin and its installation at http://www.rabbitmq.com/management.html.

Additionally, you may find useful RabbitMQTools – a power shell module for managing RabbitMQ servers.

EasyNetQ

Although pivotal provides a great .NET library for working with RabbitMQ, there is even better solution which will be sufficient in most cases – EasyNetQ. EasyNetQ provides nice abstraction over some low level concepts of RabbitMQ, such as topology registration, messages serialisation or error handling. It also gives an easy interface to work with some popular messaging patters such as Publish / Subscribe or Message Bus.

Hello World!

Lets create our first application. Start new console application project in Visual Studio and name it ConsumerApplication.
Add EasyNetQ nuget package:

Install-Package EasyNetQ

and replace Main.cs code with following:

Now, add new console application project to the solution and call it ProducerApplication. You also have to add EasyNetQ nuget package to this project.
Replace Main.cs code with following:

To run the example, first right click on the ConsumerApplication project and select Debug > Start new instance. This will run the ConsumerApplication. Next, do that same on the PublisherApplication and you should see that in the ConsumerApplication window there is a lot of diagnostics information printed and right at the bottom there is the Hello World! message.

How it works

Under the bonnet EasyNetQ is doing quite a work to make all this happen. When publishing the message, EasyNetQ performs a check to see whether the related Exchange exists in RabbitMQ and if it doesn’t than creates it. On the other hand, call to Subscribe method will verify whether both exchange and queue exists and they are bound together. As you can see in the console windows, EasyNetQ runs quite verbose diagnostics which are priceless when it comes to debugging. If there was a problem with consuming the message, such as exception thrown by consumer code, then it will be automatically moved to error queue for further analysis. You can also rely on EasyNetQ to manage connections to RabbitMQ server so you do not need to worry when the connection was dropped etc.

Summary

As you could see from the above example it is very easy to start with messaging using combination of RabbitMQ and EasyNetQ.
From serialising / de-serialising messages, diagnostics and error handling, managing connection to managing topology – all handled automatically by EasyNetQ so you can concentrate your efforts on making awesome applications. As you will see in the second article, working with complex type messages is no more complicated.

MSTest: ExpectedExceptionWithMessageAttribute

The unit testing system which comes with Visual Studio offers a way to assert whether a test has thrown specific exception. It is done by using ExpectedExceptionAttribute on test method:

[TestMethod]
[ExpectedException(typeof(InvalidOperationException))]
public void ThrowsInvalidOperationException()
{
    throw new InvalidOperationException();
}

The problem with this solution is that it checks only for the type of the exception, but there is no way to assert exception’s message (There is overloaded constructor which takes string as a second parameter, but this string is not a message to assert, but it is a message which will be displayed when assertion fails.). As exceptions are an important part of application’s domain, our unit tests should assert them and check whether messages are containing useful and valid information. Below example, which is very simplistic, shows how one exception type may reference to two different conditions:

        public void ProcessNameAndDescription(string name, string description)
        {
            if (name == null)
                throw new ArgumentNullException("name", "Parameter \"name\" may not be null.");

            if (description == null)
                throw new ArgumentNullException("description", "Parameter \"description\" may not be null.");

            // rest of the code
        }

In the above example, the ArgumentNullAttribute can be thrown because of two reasons: either the name or description parameter is null. The tests could be as follow:

        [TestMethod]
        [ExpectedException(typeof(ArgumentNullException))]
        public void ThrowsArgumentNullExceptionWhenProcessingNullName()
        {
            ProcessNameAndDescription(null, "some description");
        }

        [TestMethod]
        [ExpectedException(typeof(ArgumentNullException))]
        public void ThrowsArgumentNullExceptionWhenProcessingNullDescription()
        {
            ProcessNameAndDescription("some name", null);
        }

That works, although it is really easy to make a mistake and assert wrong condition (especially when you use copy pasting for such methods), and without asserting exception’s message there is no way to discover which parameter was wrong.

ExpectedExceptionWithMessageAttribute

Fortunately the unit testing framework can be easily extended and we can create our own attribute which will assert for exception and its message. All what has to be done is to create a new attribute class which inherits from ExpectedExceptionBaseAttribute and provides the implementation of Verify abstract method. When tested code throws an exception, this exception is passed to Verify method and can be checked whether it is what should be expected or not. Below is a source code for sample implementation:

    [AttributeUsage(AttributeTargets.Method, AllowMultiple = false, Inherited = true)]
    public sealed class ExpectedExceptionWithMessageAttribute : ExpectedExceptionBaseAttribute
    {
        #region private members

        [DebuggerBrowsable(DebuggerBrowsableState.Never)]
        private readonly Type _exceptionType;

        [DebuggerBrowsable(DebuggerBrowsableState.Never)]
        private readonly string _expectedMessagePattern;

        #endregion

        #region public properties

        public Type ExceptionType
        {
            get { return this._exceptionType; }
        }

        public string ExpectedMessagePattern
        {
            get { return this._expectedMessagePattern; }
        }

        public bool AllowDerivedTypes
        {
            get;
            set;
        }

        #endregion

        #region ctor()

        public ExpectedExceptionWithMessageAttribute(Type exceptionType, string expectedMessage)
            : this(exceptionType, expectedMessage, String.Empty)
        {
        }

        public ExpectedExceptionWithMessageAttribute(Type exceptionType, string expectedMessage, string noExceptionMessage)
            : base(noExceptionMessage)
        {
            #region preconditions

            if (exceptionType == null)
                throw new ArgumentNullException("exceptionType", "Parameter \"exceptionType\" may not be null.");

            if (!typeof(Exception).IsAssignableFrom(exceptionType))
                throw new ArgumentException("The expected exception type must be System.Exception or a type derived from System.Exception.", "exceptionType");

            if (expectedMessage == null)
                throw new ArgumentNullException("expectedMessage", "Parameter \"expectedMessage\" may not be null.");

            #endregion

            this._exceptionType = exceptionType;
            this._expectedMessagePattern = expectedMessage;
        }

        #endregion

        protected override void Verify(Exception exception)
        {
            Type exceptionType = exception.GetType();

            if (this.AllowDerivedTypes)
            {
                if (!this.ExceptionType.IsAssignableFrom(exceptionType))
                {
                    base.RethrowIfAssertException(exception);
                    this.HandleInvalidExpectedExceptionOrMessage("Test method {0}.{1} threw exception {2}, but exception {3} or a type derived from it was expected.\r\nException message: {4}.", exception);
                }
                else if (!Regex.IsMatch(exception.Message, this.ExpectedMessagePattern))
                {
                    this.HandleInvalidExpectedExceptionOrMessage("Test method {0}.{1} threw expected exception {2} with message \"{4}\" but message with pattern \"{5}\" was expected.", exception);
                }
            }
            else
            {
                if (exceptionType != this.ExceptionType)
                {
                    base.RethrowIfAssertException(exception);
                    this.HandleInvalidExpectedExceptionOrMessage("Test method {0}.{1} threw exception {2}, but exception {3} was expected.\r\nException message: {4}.", exception);
                }
                else if (!Regex.IsMatch(exception.Message, this.ExpectedMessagePattern))
                {
                    this.HandleInvalidExpectedExceptionOrMessage("Test method {0}.{1} threw expected exception {2} with message \"{4}\" but message with pattern \"{5}\" was expected.", exception);
                }
            }
        }

        private void HandleInvalidExpectedExceptionOrMessage(string messageTemplate, Exception exceptionThrow)
        {
            throw new Exception(String.Format(messageTemplate,
                        base.TestContext.FullyQualifiedTestClassName,
                        base.TestContext.TestName,
                        exceptionThrow.GetType().FullName,
                        this.ExceptionType.FullName,
                        exceptionThrow.Message,
                        this.ExpectedMessagePattern));
        }
    }

Now, we can assert exception for a message pattern (using regular expressions) and our tests may be changed to following:

        [TestMethod]
        [ExpectedExceptionWithMessage(typeof(ArgumentNullException), "Parameter \"name\" may not be null.")]
        public void ThrowsArgumentNullExceptionWhenProcessingNullName()
        {
            ProcessNameAndDescription(null, "some description");
        }

        [TestMethod]
        [ExpectedExceptionWithMessage(typeof(ArgumentNullException), "Parameter \"description\".*")]
        public void ThrowsArgumentNullExceptionWhenProcessingNullDescription()
        {
            ProcessNameAndDescription("some name", null);
        }

Final note

One final note on asserting exceptions. I do not recommend using this approach for every exception and write your code in a way that only exception’s message distinguishes between different types of errors. The application should be designed in a way, that all domain specific exceptions are represented with their own exception types, such as: ClientAccountLockedOut, DeliveryAddressUnrecognised, etc. so we can assert for those exceptions and assert exception’s message to confirm that it contains valuable information (an Id of client’s account, or description why the address has not been recognised).

Gallery

Compile errors while migrating from Unity 1.2 to version 2.0

While migrating project from Unity version 1.2 to version 2.0 I came across several compiler errors like below:

c.Resolve<ILogger>();

with following error message:

The non-generic method 'Microsoft.Practices.Unity.UnityContainer.Resolve(System.Type, string, params Microsoft.Practices.Unity.ResolverOverride[])' cannot be used with type arguments

It happened because in the code we were specifying types with a namespace like below:

Microsoft.Practices.Unity.UnityContainer c = new Microsoft.Practices.Unity.UnityContainer();

and there was no using directive aliasing the Microsoft.Practices.Unity namespace. Because the new version of Unity defines those generic methods (and many more) as extension methods, the following using statement is required:

using Microsoft.Practices.Unity;

Fortunately, this time the migration was rather easy and after updating using section in several classes we were good to go.

You can read more about Extension Methods at following address
http://msdn.microsoft.com/en-us/library/bb383977.aspx

You can read more about Unity Container methods at following address
http://msdn.microsoft.com/en-us/library/microsoft.practices.unity.unitycontainer_methods(PandP.20).aspx

You can read more about Unity Container methods at following address
http://msdn.microsoft.com/en-us/library/ff660929(PandP.20).aspx