EPiServer architecture and cross cutting concerns

Introduction

Let's spend a few moments to talk about a few different ways how to implement cross cutting concerns type of functionality like logging, caching, auditing etc while keeping a high code quality. Each has it's own pros and cons which makes different solutions good for different project sizes. I'll use logging as an example of a cross cutting funtionality to be added and a repository for news as an example of the "real" functionality to extend.

Architecture lvl 0: Basic cross cutting concerns code mixed with actual function

Also known as…no architecture…

Let's start with the simplest version; code for performance logging is mixed with code for the actual functionality you want to log. Dirty but fast to implement for a single class. This will give us something to discuss pros and cons for.

An example class called NewsRepository with only one function, GetAllNews() was created. This function returns a list of NewsItems and will serve as the example service/repository class. Support was then added for log4net, which is a nice logging framework which is installed by default with EPiServer. Below is the simple example class with some basic logging. It uses a PerformanceTimer class to get a really accurate time of execution (custom made class so it's not part of any framework if you are wondering). Feel free to use the .NET DateTime.Now instead if you don't need extreme precision. Thread.Sleep is used to simulate that this method takes a while to run. The advantage with this simple version of architecture, or lack of it, for handling cross cutting concerns is that it's easy to find all code that is being run, and as long as the amount of code is pretty small, it will be a good solution. The value of simplicity is a value in itself.

public class NewsRepository:INewsRepository
    {
        private readonly ILog _logger;
        public NewsRepository()
        {
            _logger = LogManager.GetLogger(typeof(NewsRepository));
        }
        public List<NewsItem> GetAllNews()
        {
            var timer = new PerformanceTimer();
            timer.Start();
            Thread.Sleep(200);
            var duration = timer.Stop();
            if (_logger.IsDebugEnabled)
            {
                _logger.Debug("Result of GetAllNews() in " + string.Format("{0:f4}", duration) + " seconds");
            }
            return new List<NewsItem>(){new NewsItem(){Headline = "Item 1"},new NewsItem(){Headline = "Item 2"}};
          
        }
    }

Architecture lvl 1: Implementing logging as a decorator to the original class

Ok, so that covered the basic case of logging. Not much to see yet. What can possibly go wrong with this beautiful code? Well, the main issue is that this function will contain both code for GetAllNews() and the code needed to provide logging within the same method. This is what you in computer science would refer to as low cohesion. The class does a bit of everything. Right now that is no big problem but what if some caching, security and auditing was thrown in as well while the customer comes up with 10 new improvements to the original functionality. Pretty soon this will become a method that is 500+ lines of code where only a small part actually is about the main functionality. Developers will then start to groan about code quality. Customers will start to groan about high maintainance bills. People are not happy and projects starts to fall apart. Not a happy place to be in… 
Let's back the tape and say this above was the first simplest implementation but now the customer also wants these cross cutting concerns above implemented plus some extra improvements to GetAllNews(). According to the nice, “you may fool me once” philosophy, it's now time to refactor to a bigger costume according to the single responsibility principle (S) where we split this mixed functionality into separate classes.

What if we extend the NewsRepository with a decorator pattern instead? This means that we create another class that implements the same interface but routes all calls to the original class (which only contains GetAllNews() functionality and no logging). This new decorator class can then add functionality to the original class without modifying the original class by placing itself "above" it. This is a much more SOLID approach…

Example of the new decorator class responsible for logging:

public class LoggingNewsDecorator:INewsRepository
{
        private readonly INewsRepository _newsRepository;
        private readonly ILog _logger;
        public LoggingNewsDecorator(INewsRepository newsRepository)
        {
            _newsRepository = newsRepository;
            _logger = LogManager.GetLogger(typeof(LoggingNewsDecorator));
        }
        public List<NewsItem> GetAllNews()
        {
            var timer = new PerformanceTimer();
            timer.Start();
            var result = _newsRepository.GetAllNews();
            var duration = timer.Stop();
            if (_logger.IsDebugEnabled)
            {
                _logger.Debug("Result of GetAllNews() in " + string.Format("{0:f4}", duration) + " seconds");
            }
            return result;
        }
}

As you can see, this class above implements the same interface but takes the original class as a parameter in the constructor to be able to route all method calls. The code for the logging can now be in this class (LoggingNewsDecorator) and the code for the actual functionality can be in the original class (NewsRepository). This is what computer science would refer to as high cohesion which is a good thing. That will definitely help keeping a nice separation and structure when the code is growing. It is also possible to hook up this logging decorator automatically with an IoC container like structuremap like this:

container.For<INewsRepository>()
         .Singleton()
         .Use<LoggingNewsDecorator>()
         .Ctor<INewsRepository>().Is<NewsRepository>();

This basically says that for the interface INewsRepository, use a singleton class of type LoggingNewsDecorator EXCEPT in the constructor when you try to make an instance of LoggingNewsDecorator; use the original NewsRepository there as parameter to the constructor instead. Otherwise you'll get a very funny circular reference thingy If you don't like IoC, feel free to create your classes manually. The decorator pattern doesn't need IoC but it sure is helpful to avoid typing as much.

Nice! Now with the decorator pattern in place you can actually chain classes for caching, auditing, logging etc on top of the actual functionality if you want.

TIP: If you are a fan of decorator pattern and interfaces, use a custom class to pass in parameters to methods and also return the response as a custom response class. This will minimize the number of times you need to update the interface when you add new filtering options etc. Visual Studio also has plenty of shortcuts to update classes and interfaces that helps keeping the additional work down to a minimum.

This is normally where you stop, even if you have a big project. Creating the decorators will involve a lot of copy / paste if you have many classes you want to apply them on. It's SOLID but not very DRY. Implementing cross cutting concerns with the decorator pattern when you have a large project is a nice way of solving the problem and keeping a nice structure. But let's try another step just for fun and do some magic.

Architecture lvl 2: Implementing cross cutting concerns with AOP (Aspect Oriented Programming)

"O day and night, but this is wondrous strange!” – Horatio

Decorators involve a lot of copy / paste code to act as a wrapper around the original class. Is it possible to autogenerate these decorators so you only need to create them once for each type of decorator?

As it turns out, you can, since this is exactly what Castles dynamic proxy component does. It lets you autogenerate a class to a specific interface. Let's see some magic in action if you combine castles dynamic proxy with structuremap! Download the nuget package for castle.core and start with register a structuremap interceptor like this:

container.RegisterInterceptor(new StructureMapInterceptor());

public class StructureMapInterceptor : TypeInterceptor
        {
            private readonly ProxyGenerator _proxy = new ProxyGenerator();

            public object Process(object target, IContext context)
            {
                var targetInterfaces = target.GetType().GetInterfaces();
                return _proxy.CreateInterfaceProxyWithTargetInterface(
                    targetInterfaces.First(), //What interface should we create proxy for
                    targetInterfaces,         //Any addition interfaces we need to support?
                    target,                   //Target class
                    new LoggingInterceptor());//What interceptors to generate 
                                              //and use in front of this target 
                 

            }

            public bool MatchesType(Type type)
            {
                if (type.IsSealed)
                    return false;
                if (type.Name.Contains("NewsRepository"))
                {
                    return true;
                }
               
                return false;
            }
        }

This StructureMapInterceptor will basically tell what decorators to generate and use for which classes, this is refered to as the pointcut in AOP. It’s nothing more than a mapping of classes vs decorators. This pointcut is done by first specifying in the MatchesType() method if any custom decorators should be generated for the calling type. Returning true will trigger the Process() method which will return what decorators to use and in which order and trigger the ProxyGenerator from Castle to generate them. If you have a security decorator / interceptor you'd probably want to run that first for instance. In this version we only generate a decorator for logging and this is implemented by the LoggingInterceptor class. 

Below, in the bonus material section, it is also shown how to match classes by attributes instead if you want to do that. This method, MatchesType(), is where you add logic for it anyway.

So, how do you create the logging interceptor class that implements the actual logging? So far we have only handled the mapping of what decorators to use for which classes...Let's check out the implementation of the actual interceptor for logging below:

public class LoggingInterceptor : IInterceptor
    {
        public void Intercept(IInvocation invocation)
        {
            var logger = LogManager.GetLogger(invocation.TargetType);
            try
            { 
                StringBuilder sb = null;
                if (logger.IsDebugEnabled)
                {
                    sb = new StringBuilder(invocation.TargetType.FullName)
                        .Append(".")
                        .Append(invocation.Method)
                        .Append("(");
                    for (int i = 0; i < invocation.Arguments.Length; i++)
                    {
                        if (i > 0)
                            sb.Append(", ");
                        sb.Append(invocation.Arguments[i]);
                    }
                    sb.Append(")");
                    logger.Debug(sb);
                }
                var timer = new PerformanceTimer();
                timer.Start();
                invocation.Proceed();
                var duration = timer.Stop();
                if (logger.IsDebugEnabled)
                {

                    logger.Debug("Result of " + sb + " is: " + invocation.ReturnValue + 
                        " in " + string.Format("{0:f4}", duration) + " seconds");
                }
            }
            catch (Exception e)
            {
                logger.Error(e);
                throw;
            }
        }
    }

This class will now work as our general logging decorator which can be put in front of any class that implements an interface! How cool is that? This class needs to implement an interface of type IInterceptor which only has a single method: Intercept. Information about the calling method etc is passed into the interceptor with the input parameter (IInvocation). To pass the method call along to the original class you can use invocation.Proceed(). This will call the actual GetNewsMethod() and return our little list of NewsItems.
Congratulations! With this single class, you can now enable logging and measure execution time on all classes you want in your solution without touching the actual functionality with a lot of copy / paste code. It's a bit of magic alright so I would personally only use this for logging and auditing. Implementing caching this way would probably leave me sleepless at night or at least with nightmares. This AOP way will probably only be worth the effort for really big projects where you have a lot of service layer classes etc. You will have to weigh the amount of duplicated code vs the increased complexity when choosing to go down this path.

Performance considerations with autogenerating classes with AOP

Since autogenerating the decorators is actually only done once and then stored, the performance hit will be small. The same as for a decorator class basically but with a few extra reflection calls within the interceptor. Not a huge drawback in my eyes. The question mark above a junior developers head will be the biggest drawback according to me. Documentation can help somewhat there.

Summary

So now you have 3 options above how to implement cross cutting concerns. My general suggestion is to stick to the first option with inline code for small trivial solutions, switch to the second option with using decorators when you notice that the small project will probably grow into a big one and use the third magic one with aspect oriented programming only if you feel lucky and in special cases like logging. If you don't document the AOP variant well, it will probably take around a year for a junior programmer to figure out how it works though so keep that in mind as a likely side effect of the "magic" version...

So, within 1 hour you can now implement performance logging on every class you want in a big project without actually touching an existing class and risk breaking it. How cool is that? Feel free to make your own interceptors for auditing and caching as an exercise

Happy coding fellas!

Bonus material 1; Adding support for attributes to enable logging on a class

1. Create custom attribute / annotation to be able to mark a class you want to log

[System.AttributeUsage(System.AttributeTargets.Class)]  
public class LogAttribute : System.Attribute
{
}

2. Set attribute on class to enable log

[Log]
public class NewsRepository:INewsRepository
{
}

3. Update the method that checks what classes should use what interceptors (MatchesType() method in the StructureMapInterceptor class above)

public bool MatchesType(Type type)
{
      if (type.IsSealed)
           return false;
      var attributes = System.Attribute.GetCustomAttributes(type); 
      if (attributes.Any(a => a is LogAttribute))
      {
           return true;
      }              
      return false;
}

4. Lean back and enjoy the little log messages ticking in...

Bonus material 2; Manual creation of proxy classes without an IoC container

Of course it’s also possible to use the ProxyGenerator class from Castle to “manually” generate a matching decorator class.

var newsRepository = new NewsRepository();
var proxyGenerator = new ProxyGenerator();

var newsRepositoryWithLogging = 
           (INewsRepository)proxyGenerator.CreateInterfaceProxyWithTargetInterface(
            newsRepository.GetType().GetInterfaces().First(),
            newsRepository.GetType().GetInterfaces(), newsRepository,
            new LoggingInterceptor());
var items = newsRepositoryWithLogging.GetAllNews();

Performance will definitely need some careful consideration when doing this manually though. Wrapping the above in a factory for class creation will help of course, combined with the singleton pattern to avoid doing it too often. But to be honest, using an IoC container makes much more sense to handle object creation when using AOP so regard the last example as a more theoretical exploration.

Happy coding again!