ASP.NET MVC 3 Aspect Oriented Programming with Castle Interceptors

Aspect Oriented Programming, or AOP in short is a powerful tool that can be useful when developing any kind of software. Most kinds of complex applications have some kind of cross cutting concerns that are spread throughout the application. Some traditional examples of these include logging, exception handling, authorization and profiling / benchmarking. AOP is a way to separate these cross cutting concerns from the affected code. I liken AOP to a kind of declarative programming in contrast to imperative programming which is by far the most dominant programming paradigm today.

In a traditional imperative language, you would need to code by hand how and where you would like the logging to be done, such as by making a call to a to a LogManager of some sort to log a message. This means that your method that needs to be logged will need to contain the logging aspect inside it. With AOP you can do a more declarative statement such as “All calls to methods in classes inheriting from type T should be logged” without touching the actual method or class that you want to be logged.

Some languages support AOP out of the box, such as Python with its decorators. C# has not had any built-in support for it, although there are commercial libraries such as PostSharp that achieve this by injecting IL code to the assembly.

I want to talk about Castle.Windsor Interceptors which I think brings AOP to the masses within the .NET community. Castle.Windsor Interceptors work by proxying classes and allows you to act before and after a method is invoked on a target class.

I will show a simple example to integrate Castle Interceptors with a ASP.NET MVC 3 application and do logging through Interceptors. ASP.NET MVC 3 as a framework allows implementation of some cross cutting concerns through ActionFilters, but this might not always be enough for what you want and are only limited to Controllers and their Action methods. Windsor Interceptors allow for a much more powerful way to intercept method calls and act on them, on any of your classes.

I am using the following libraries / frameworks for this example (in the case that this article is still relevant after a few years..):

  • ASP.NET MVC 3
  • Castle Windsor 2.5.3
  • Castle Windsor Logging Facility
  • log4net 1.2

We will start by integrating Castle.Windsor into the ASP.NET MVC 3 project. There is an excellent tutorial available for this already, so I will cut it short. We will use the Fluent API and thus skip the .xml configuration. We start by creating an empty MVC 3 app and creating our ControllerFactory that will handle the lifecycle of our Controllers.

public class WindsorControllerFactory : DefaultControllerFactory
{
    private readonly IKernel kernel;

    public WindsorControllerFactory(IKernel kernel)
    {
        this.kernel = kernel;
    }

    public override void ReleaseController(IController controller)
    {
        kernel.ReleaseComponent(controller);
    }

    protected override IController GetControllerInstance(RequestContext requestContext, Type controllerType)
    {
        if (controllerType == null)
        {
            throw new HttpException(404,
                                    string.Format("The controller for path '{0}' could not be found.",
                                                    requestContext.HttpContext.Request.Path));
        }
        return (IController) kernel.Resolve(controllerType);
    }
}

We then plug this to application through Global.asax

protected void Application_Start()
{
    AreaRegistration.RegisterAllAreas();
    RegisterGlobalFilters(GlobalFilters.Filters);
    RegisterRoutes(RouteTable.Routes);
    RegisterCastle();
}

private void RegisterCastle()
{
    container = new WindsorContainer().Install(FromAssembly.This());
    ControllerBuilder.Current.SetControllerFactory(new WindsorControllerFactory(container.Kernel));
}

We then need to register the controllers using the Fluent API. For this let’s create a ControllerInstaller class:

public class ControllerInstaller : IWindsorInstaller
{
    public void Install(IWindsorContainer container, IConfigurationStore store)
    {
        container.Register(AllTypes.FromThisAssembly()
                                .BasedOn()
                                .If(Component.IsInSameNamespaceAs())
                                .If(t => t.Name.EndsWith("Controller"))
                                .Configure((c => c.LifeStyle.Transient)));
    }
}

From now on, Castle Windsor will take care of the lifecycle of our controllers.
Next step is to plug in our logging. You can use the Castle.Windsor Logging Facility for this, in this case I will use log4net. You need to add references to Castle.Facilities.Logging and also Castle.Services.Logging.Log4netIntegration and create an installer:

public class LoggerInstaller : IWindsorInstaller
{
    public void Install(IWindsorContainer container, IConfigurationStore store)
    {
        container.AddFacility(f => f.LogUsing(LoggerImplementation.Log4net).WithAppConfig());
    }
}

Add to the web.config the following as well to log all messages at Debug level and up to the debug window (during debugging). log4net has a lot of methods for declaring different kind of logging mechanisms, which I won’t go into detail here.

 <configSections>
    <section name="log4net" type="log4net.Config.Log4NetConfigurationSectionHandler, log4net" requirePermission="false" />
  </configSections>
<log4net debug="true">
    <root>
        <level value="DEBUG" />
        <appender-ref ref="TraceAppender" />
    </root>
    <appender name="TraceAppender" type="log4net.Appender.TraceAppender">
        <layout type="log4net.Layout.PatternLayout">
            <conversionPattern value="%date [%thread] %-5level %logger - %message%newline" />
        </layout>
    </appender>
</log4net>

Next up is creating our Interceptor class to log all Action methods. To do this we need to intercept the calls to OnActionExecuting and OnActionExecuted methods on the Controller which will invoke before and after the appropriate Action method, respectively. This is pretty similar to how custom ActionFilters work. There is a lot more you can do here, such as viewing the input parameters, handling exceptions, profiling performance and so forth.

public class ControllerLogInterceptor : IInterceptor
{
    private readonly ILogger logger;

    public ControllerLogInterceptor(ILogger logger)
    {
        this.logger = logger;
    }

    public void Intercept(IInvocation invocation)
    {
        switch (invocation.Method.Name)
        {
            case "OnActionExecuting":
                OnActionExecuting(invocation);
                break;
            case "OnActionExecuted":
                OnActionExecuted(invocation);
                break;
        }
        invocation.Proceed();
    }

    private void OnActionExecuted(IInvocation invocation)
    {
        var actionExecutedContext = invocation.Arguments[0] as ActionExecutedContext;
        logger.Debug("Executed action: " + invocation.TargetType.Name + "." +
                        actionExecutedContext.ActionDescriptor.ActionName);
    }

    private void OnActionExecuting(IInvocation invocation)
    {
        var actionExecutingContext = invocation.Arguments[0] as ActionExecutingContext;
        logger.Debug("Executing action: " + invocation.TargetType.Name + "." +
                        actionExecutingContext.ActionDescriptor.ActionName);
    }
}

The last step is to register our Interceptor and also configure controllers to use this interceptor.

public class LogInterceptorInstaller : IWindsorInstaller
{
    public void Install(IWindsorContainer container, IConfigurationStore store)
    {
        container.Register(Component.For<ControllerLogInterceptor>());
    }
}

To register the interceptor, change the ControllerInstaller as follows (notice the Interceptors.. part):

public void Install(IWindsorContainer container, IConfigurationStore store)
{
    container.Register(AllTypes.FromThisAssembly()
                            .BasedOn()
                            .If(Component.IsInSameNamespaceAs())
                            .If(t => t.Name.EndsWith("Controller"))
                            .Configure((c => c.LifeStyle.Transient.Interceptors<ControllerLogInterceptor>())));
}

Now you should get some log output in your application, according to your log4net config.

2011-06-02 21:20:35,279 [10] DEBUG MvcLogging.Castle.ControllerLogInterceptor - Executing action: HomeController.Index
2011-06-02 21:20:35,290 [10] DEBUG MvcLogging.Castle.ControllerLogInterceptor - Executed action: HomeController.Index

As you can see, we didn’t have to touch our Controllers at all to implement tracing of actions. This was a quite simple example to implement Logging in ASP.NET MVC 3 using AOP. There are more creative uses of AOP and I will look at those in a future article.