Recently I had the opportunity to refactor a legacy system that urgently needed it. This code, belonging to a massive web service, had many different elements coupled together through a mix of static helpers, independent Unity containers that were resolved on-site (more about this later), and delayed component instantiations, with configuration getters and setters creating a web of a system that was very difficult to understand and work with, not to mention its many maintainability concerns.

Besides this poor architecture, another main problem of the service was logging. Dozens of different instances of the same logger were created in the supposedly short life of the service; these copies had dependency issues of their own and only worked properly when created within a given service, and under very particular conditions and configurations. Moreover, they were supposed to log many methods and operations all across the board, mudding up any and every class they were supposed to log, in a clear violation of the DRY principle.

It was agreed that the whole system required a massive maintenance work, and as so a research process started. It was more or less easily agreed that the dependency issues could be solved via proper usage of a dependency injection framework, but consensus was not as wide when it came to using this approach to solve our logging problem. What if we could just mark some classes and methods as target for loggers? What if we had a single logger to rule them all? Since logging is a cross-cutting concern that spreads across the system and is not necessarily the responsibility of a given class, but a consequence of its behaviour, we could perfectly abstract it to some other element and let the class do its own work and minding its own business, hiding any logging logic in a different layer. That’s the principle of Aspect-Oriented Programming, and through this article I will try to guide you through the following topics:

  1. Understanding Dependency Injection and Inversion of Control.
  2. Learning a few basics of Castle Windsorworks, and how to build (or refactor) a system to take advantage of it.
  3. Configuring Interceptors to isolate cross-cutting concerns in a separate layer.

Inversion of Control and Dependency Injection

Sometimes used interchangeably, they are closely related but different concepts.

  • Inversion of Control: Is a generic term for a software engineering principle stating that rather than having the application call the methods in a framework, the framework calls implementations provided by the application (hence the “inversion”).
  • Dependency Injection: A form of Inversion of Control in which the dependencies of a given class are not created on the class’ creation, but passed in as part of the class construction, or later through interface or setter methods.

An example would probably help, right? Feel free to download the sample code here, and follow the snippets below.

Let’s suppose a simple Calculator class with a few methods for the basic arithmetic operations (addition, subtraction, multiplication and division), and a ILogger dependency, that will log the calls to our different methods and, if any, potential exceptions. In a standard, non-DI scenario, our class would be created more or less in this fashion:

using SimpleLogger;
using System;

namespace SimpleCalculator
{
    public class Calculator : ICalculator
    {
        private readonly ILogger logger;

        public Calculator()
        {
            logger = new Logger();
        }

        public decimal Add(decimal x, decimal y) {
            logger.LogMessage(
                "Calculator", 
                "Add", 
                "Calculating stuff.", 
                System.Diagnostics.TraceEventType.Information);
            var result = x + y;
            Console.WriteLine(result);
            return result;
        }

        /* Other methods removed for brevity */
    }
}

It will work fine, of course, and the developer doesn’t need to worry about the logger instantiation when we create a Calculator object. But what if we have a given logger instance that we want to share across services? What if we want to unit test our Calculator, how would we mock or fake this logger? What if we change our Logger for a new AwesomeLogger class, also inheriting from ILogger? In these scenarios we’d be in trouble, and many of these nasty side effects are a product of tightly coupling our Calculator and Logger classes.

However, we can also do this:

using SimpleLogger;
using System;

namespace SimpleCalculator
{
    public class Calculator : ICalculator
    {
        private readonly ILogger logger;

        public Calculator(ILogger myLogger)
        {
            logger = myLogger;
        }

        /* All methods removed for brevity */
    }
}

That grants us a lot of flexibility regarding the relation between Calculator and Logger, which are now decoupled. Multiple different loggers could be used, and even mocks created and easily passed to mock functionality of the dependency, helping us test our Calculator class. And the only price to pay is the need to instance our Logger before creating or Calculator and passing its dependency, is that right? Even better, as we don’t need to worry about that at all. That’s precisely what Dependency Injection frameworks do.

Castle Windsor

There are many great Dependency Injection frameworks out there: Autofac, Unity and Castle Windsor are just some among the many options. In our example we are using the latter.

In a nutshell, Castle Windsor is an Inversion of Control container. It is a tool that helps us pre-defining dependencies of our classes in a container, taking care of instantiation whenever we want to create said objects. In other words, we will tell Windsor how to instantiate stuff, and it will do it for us, instead of manually doing it ourselves.

Before we move on, there are a few concepts that you should be comfortable with:

  • Container → An object that controls the creation, destruction, lifetime, configuration, and dependencies of other objects.
  • Service → Any abstract contract describing some cohesive unit of functionality, normally defined by an interface.
  • Component → The concrete, actual implementation of the service. One service (interface) can have one or several components (classes).
  • Dependency → A requirement of a component on the services of other components, or other arbitrary values needed for a component to provide its service.

By defining our system in these terms we can ensure a decoupled set of relations among the system building blocks. As for our high level lifecycle, we should honor the Three Calls Pattern:

  • Move container creation to the very top of your app (regardless of how small or big it is).
  • Call said container, ever, three times: for Registration, Resolve, and Release (dispose).
  • Resist the temptation to create a reference (e.g. Singleton) and resolve stuff as you need it, as that is effectively acting as a Service Locator antipattern.

Knowing that, let’s configure our container. I have done so in a small static class for convenience, but this can be changed as required:

public static class DependencyInjection
    {
        public static WindsorContainer CreateContainer()
        {
            var container = new WindsorContainer();

            // Main classes
            container.Register(Component.For<ILogger>().ImplementedBy<Logger>());
            container.Register(Component.For<IApp>().ImplementedBy<App>());

            container.Register(Component.For<ICalculator>().ImplementedBy<Calculator>());

            return container;
        }
    }

As you can see above, we are first creating a container. Immediately after, we register our services and their implementations (that App class is nothing but a wrapper I created to have an App foundation in a very simple Console project). And that’s it, that’s absolutely all we need. Let’s create our `Calculator` then. This will be the our app, note how calculator will be injected automatically:

using SimpleCalculator;
using System;
using System.Text.RegularExpressions;

namespace ConsoleApp
{
    public class App : IApp
    {
        private readonly ICalculator calculator;

        public App(ICalculator calculator)
        {
            this.calculator = calculator;
            string input = String.Empty;


            Console.WriteLine("Please type your two number operation and press Enter to continue.");
            Console.WriteLine("Quit the app by typing 'exit'");
            while ((input = Console.ReadLine().ToLower()) != "exit")
            {
                // Operations
                try
                {
                    ParseOperation(input);
                } catch (Exception ex)
                {
                    Console.WriteLine(string.Format("Error: {0}", ex.Message));
                }
            }
        }

        /* Methods removed for brevity */
    }
}

And this is how our calculator looks:

using SimpleLogger;
using System;

namespace SimpleCalculator
{
    public class Calculator : ICalculator
    {
        private readonly ILogger logger;

        public Calculator(ILogger myLogger)
        {
            logger = myLogger;
        }

        public decimal Add(decimal x, decimal y) {
            logger.LogMessage("Calculator", "Add", "Calculating stuff.", System.Diagnostics.TraceEventType.Information);
            var result = x + y;
            Console.WriteLine(result);
            return result;
        }

        public decimal Subtract(decimal x, decimal y)
        {
            logger.LogMessage("Calculator", "Subtract", "Calculating stuff.", System.Diagnostics.TraceEventType.Information);
            var result = x - y;
            Console.WriteLine(result);
            return result;
        }

        public decimal Multiply(decimal x, decimal y)
        {
            logger.LogMessage("Calculator", "Multiply", "Calculating stuff.", System.Diagnostics.TraceEventType.Information);
            var result = x * y;
            Console.WriteLine(result);
            return result;
        }

        public decimal Divide(decimal x, decimal y)
        {
            try
            {
                var result = x / y;
                logger.LogMessage("Calculator", "Divide", "Calculating stuff.", System.Diagnostics.TraceEventType.Information);
                Console.WriteLine(result);
                return result;
            }
            catch (Exception ex)
            {
                logger.LogMessage("Calculator", "Divide", string.Format("Whooops! Error: {0}", ex.Message), System.Diagnostics.TraceEventType.Error);
                throw ex;
            }
        }
    }
}

That’s all we needed. Upon resolving our app, the calculator will be injected into it (itself having been injected the logger), and the console loop will keep the user in the app until the user decides to quit, then control will return to the Main method and container will be disposed of. The whole life of the app (create, resolve, release) can be seen in the Main method:

using ConsoleApp.DI;
using System;

namespace ConsoleApp
{
    class Program
    {
        static void Main(string[] args)
        {
            Console.WriteLine("Starting the calculator app...");

            // DI initialisation
            var container = DependencyInjection.CreateContainer();

            var app = container.Resolve<IApp>();

            container.Dispose();

            Console.WriteLine("Done!");
            Console.ReadKey();
        }
    }
}

We are now using Castle Windsor to handle dependencies for us, but let’s take a look back to our calculator. See how every method needs to make an explicit call to the logger? By using interceptors we will be able to get rid of that logic, isolating logging in a separate unit of work.

Interception

Interceptors are simple proxies. If we set up an interceptor for a class, any call to methods of that class will be intercepted. We can then apply any arbitrary logic in a different layer having access to the very invocation and its params, later letting the invocation proceed normally. through interception of our arithmetic methods in the calculator we can do logging, taking the logger out of the calculator and into a different layer. Let’s configure Windsor to do that.

public static class DependencyInjection
    {
        public static WindsorContainer CreateContainer()
        {
            var container = new WindsorContainer();

            // Main classes
            container.Register(Component.For<ILogger>().ImplementedBy<Logger>());
            container.Register(Component.For<IApp>().ImplementedBy<App>());

            // Interceptors
            // Declaring interceptor at registration (manually), although it can be done automatically as well
            container.Register(Component.For<IInterceptor>().ImplementedBy<LoggingInterceptor>());
            container.Register(Component.For<ICalculator>().ImplementedBy<InterceptedCalculator>().Interceptors<LoggingInterceptor>());

            return container;
        }
    }

Registration is done in very much the same fashion we did, but now we need to register the interceptor itself, and then configure the intercepted class with our interceptor. As for the interceptor, it looks like this:

using Castle.DynamicProxy;
using SimpleCalculator.Interception.Attributes;
using SimpleLogger;
using System;

namespace ConsoleApp.Interception
{
    class LoggingInterceptor : IInterceptor
    {
        ILogger Logger;

        public LoggingInterceptor(ILogger logger)
        {
            Logger = logger;
        }

        public void Intercept(IInvocation invocation)
        {
            // Only public methods can be logged
            if (!invocation.Method.IsPublic)
            {
                // Run the intercepted method as normal.
                Console.WriteLine("(Skipping logging due to private method)");
                invocation.Proceed();
            }
            // Attributes
            else if (AttributeExistsOnMethod<DoNotLog>(invocation))
            {
                // Run the intercepted method as normal.
                Console.WriteLine("(Skipping logging due to attribute)");
                invocation.Proceed();
            }
            else
            {
                // Log and continue
                Logger.LogMessage(invocation.GetType().Name, invocation.Method.Name, "Calculating stuff.", System.Diagnostics.TraceEventType.Information);

                try
                {
                    invocation.Proceed();
                }
                // If exception occurs in intercepted method, log exception as well
                catch (Exception ex)
                {
                    Logger.LogMessage(invocation.GetType().Name, invocation.Method.Name, string.Format("Whooops! Error: {0}", ex.Message), System.Diagnostics.TraceEventType.Error);
                    throw ex;
                }
            }
        }

        private static bool AttributeExistsOnMethod<TAttribute>(IInvocation invocation)
        {
            var attribute = Attribute.GetCustomAttribute(invocation.Method, typeof(TAttribute), true);

            return attribute != null;
        }
    }
}

There are some important bits and pieces we need to make sure to see here. Firstly, note how the logger dependency has moved into our LoggingInterceptor class. This class must inherit from IInterceptor, and include an Intercept method accepting an argument IInvocation.

Every time a method in the InterceptedCalculator is called, Intercept will be triggered. Of course this behaviour is configurable, and we indeed are using a log public methods by default approach as you can see in the first lines, where we allow the invocation to proceed without any additional code if the method has the attribute DoNotLog or if the method is private.

In any other event, we want the event to be logged. We call the LogMessage method of our logger to log in our method call indirectly using reflection to get method details such as method name, and then we let the invocation proceed. In case of an exception happening, we’ll log it and then rethrow it, so that the control is returned to the proxied class.

Wrapping up

By intercepting our logging we have cleaned up our InterceptedCalculator class of any logging logic, and simplified the logging process in case we have several types of ICalculator services, as it is the case in this small test project, as it was in the multi-layered services of the production code that inspired the creation of this proof of concept. In addition to this, the containerised structure of our project helps us keeping our dependencies under control, which will prove more than useful on more complex scenarios, when we need to have a tighter control of our instances and its life cycle.

Other resources