In this article I’d like to discuss how to implement consistent logging as a cross cutting concern via Aspect Oriented Programming. We’ll look at some code that achieves this and we’ll also consider some of the implications of using this approach to logging.
Most people are used to adding logging to their code via inline log statements with whatever text they feel is appropriate. This is generally fine when you know what you need to log but becomes a problem when you don’t. It also adds noise to business logic. If you consider that you may also want to add exception handling, transaction management and auditing you can quickly find yourself in a situation where methods are quite long and a good percentage of the code has nothing to do with the business logic that you should be focussing on.
Aspect Oriented Programming (AOP) is a programming style which extracts these cross cutting concerns. There are several ways of achieving this such as code weaving with PostSharp or method interception using Castle Dynamic Proxy. This article will focus on the latter as it is a simple low friction way to get started with AOP.
If you’re using a dependency injection framework such as Castle Windsor or Autofaq it’s very easy to get started with interceptors. You can configure your container to use interception. For example with Autofaq you can add the Autofac.Extras.DynamicProxy2 package which contains the EnableInterfaceInterceptors and InterceptedBy extension methods for IRegistrationBuilder. The first method as the name suggests switches on the interception feature. The second method allows you to configure a registration with a particular interceptor. You can specify interceptor classes which realize the IInterceptor interface from the Castle.Core package.
IInterceptor defines an Intercept method which takes an IInvocation instance. This describes the method which is being intercepted. When the container resolves a dependency which is configured to use an interceptor it will give you back a dynamic proxy which implements the interface you requested. When you call a method against the proxy it will invoke the intercept method on your interceptor passing in the IInvocation instance which describes the method call you tried to make. This interface defines properties for things like the method being called, the arguments being passed to that method and the return value. It also defines a Proceed method which you should call in your interceptor code if and when you want to continue on to calling the method on the target implementation.
This is an extremely powerful feature which makes it easy to extract cross cutting concerns and have code in one place which used to be in every method call.
For logging it means that you can log the name of the class and the name of the method. You can json serialise the arguments and the return value or exception details if an exception is thrown. You can also start a stopwatch before you call proceed and stop it after the underlying method has executed and log the elapsed time. But instead of having this code in every method you have it in one place.
I’ve put an implementation of this on github at https://github.com/maz100/Isla. I’ve configured it to write log messages as json and there is a test method in JsonInvocationLoggingInterceptorTests called TestReadFromFile which shows how you can read a log file into a collection and query it to find out things like the longest running method call or the number of errors logged in the last hour.
There are a few things to bear in mind if you decide to adopt this approach. Firstly you need to make sure your interfaces accurately describe what your code is doing. If you just have one void method called DoStuff which takes no arguments you’re not going to get much value from AOP logging. Secondly if you choose to serialise arguments and return values you need to be aware that the larger these objects are the longer it will take to serialise them. This was most apparent on one project I worked on where the classes being serialised were deep object graphs. Consequently the log files were extremely large and performance, whilst acceptable was certainly affected. However we found the logs to be invaluable during development as we could search the logs detailing large batch processes and very quickly report on the results. You may also want to consider how to exclude certain information from your logs, for example classes that contain a password or credit card details. Finally you need to make sure the whole team understands the concept of AOP. The container configuration ties together your interceptors and your implementations. Unless you understand that it won’t be clear how to navigate the code. However, I’ve used this approach with many teams and I’ve always found it to be extremely beneficial.
This article described how to implement Aspect Oriented Programming using Castle Dynamic Proxy. We started be explaining why you might want to extract cross cutting concerns from your business logic. We then looked at the packages and interfaces available using Autofaq as the example container. Next I discussed how the container invokes your interceptors and how to call the target method as part of your interception. Finally we considered some of the pros and cons of using this approach to logging.
Life in Brighton 