Implementing AOP logging with windsor container

Long time no see :) Today I'm going to describe how to create some AOP functionality based on attributes and we'll see how to implement a very common task - logging with attributes. The same way you can implement audit, OpsDB writes, security, caching and so on, whatever you will want to.

So let's head on and write a logger:

    public static class Logger
{
private static readonly List<string> _logs = new List<string>();
public static void Log(string logMessage)
{
_logs.Add(logMessage);
}

/// <summary>
/// Returns a readonly collection of log messages
/// </summary>
public static IList<string> Logs
{
get
{
 return _logs.AsReadOnly();
}
}

public static void CleanWholeLog()
{
_logs.Clear();
}
}

And now the class we're going to use to test our logging, lets start with something really simple:

    [LoggedClass]
public class Calculator
{
[LoggedMember]
public virtual int AddWithFullLogging(int a, int b)
{
return a + b;
}
}

Now we want our attributes to work for us (Im not posting attributes code to spare some space as they are just empty classes inherited from Attribute). We would like to log parameters and return values of this method.

Lets head on with a unit test:

    [TestFixture]
public class When_calling_add_of_calculator
{
private const int FIRST_OPERAND = 2;
private const int SECOND_OPERAND = 3;
private const int RESULT = 5;
private readonly Calculator _calculator = ObjectFactory.GetCalculator();

[TestFixtureSetUp]
public void TestFixtureSetUp()
{
  Logger.CleanWholeLog();
  this._calculator.AddWithFullLogging(FIRST_OPERAND, SECOND_OPERAND);
}

[Test]
public void Both_parameters_and_return_value_get()
{
  Assert.That(Logger.Logs.Count, Is.EqualTo(2));
}

[Test]
public void Parameters_are_logged_correctly()
{
  var expectedParametersLogMessage = "Calculator.AddWithFullLogging method call. Parameters: :firstParam, :secondParam";
  expectedParametersLogMessage = expectedParametersLogMessage.Replace(":firstParam", FIRST_OPERAND.ToString());
  expectedParametersLogMessage = expectedParametersLogMessage.Replace(":secondParam", SECOND_OPERAND.ToString());
  Assert.That(Logger.Logs[0], Is.EqualTo(expectedParametersLogMessage));
}

[Test]
public void Return_value_is_logged_correctly()
{
  var expectedReturnValueLogMessage = "Calculator.AddWithFullLogging finished call. Return value: :returnValue";
  expectedReturnValueLogMessage = expectedReturnValueLogMessage.Replace(":returnValue", RESULT.ToString());
  Assert.That(Logger.Logs[1], Is.EqualTo(expectedReturnValueLogMessage));
}
}

We clear whole log before tests and then make a call to add function. Then we expect three things to happen: 

1. logger has 2 new entries - one for parameters and one for return value
   
2. parameters are logged correctly
3. return value is logged correcly

We're using object factory to create calculator for us. This is needed, because otherwise we wont be able to attach interceptors to its methods.

Here's the code for ObjectFactory class:

    public static class ObjectFactory
{
private static WindsorContainer _container;
private static void Init()
{
 if (_container == null)
 {
     _container = new WindsorContainer();
     _container.AddFacility("LoggingFacility", new LoggingFacility());
     _container.Register(Component.For(typeof(Calculator)));
 }
}
public static Calculator GetCalculator()
{
 Init();
 return _container.Resolve<Calculator>();
}
}

It registers calculator in container and just before that it adds Logging facility which will be intercepting registrations and add interceptors if it will find proper attributes.

Ok, so now we have it all setup lets proceed with implementation of our logging facility. In our case we would like to add logging interceptor to every method tagged with [LoggedMember] within the class tagged with [LoggedClass].

    public class LoggingFacility : AbstractFacility
{
protected override void Init()
{
   Kernel.AddComponent("LoggingInterceptor", typeof(LoggingInterceptor));
   Kernel.ComponentModelBuilder.AddContributor(new LoggingContributor());
}
}

    public class LoggingContributor : IContributeComponentModelConstruction
{
 public void ProcessModel(IKernel kernel, ComponentModel model)
 {
     if (model.Service.GetCustomAttributes(true).OfType<LoggedClassAttribute>().Count() == 1)
     {
         if (ServiceHasNonVirtualMethodsMarkedWithLoggedMemberAttributes(model))
         {
             throw new Exception("Cannot use LoggedMember attribute on nonvirtual members");
         }
         model.Interceptors.Add(new InterceptorReference(typeof(LoggingInterceptor)));
     }
 }

 private static bool ServiceHasNonVirtualMethodsMarkedWithLoggedMemberAttributes(ComponentModel model)
 {
     return model
                .Service
                .GetMethods()
                .Where(x => x.GetCustomAttributes(true)
                                .Where(y => y.GetType() == (typeof(LoggedMemberAttribute))).Count() == 1
                            && !x.IsVirtual ).Count() > 0;
 }
}

Lets run through the code. First we are defining our facility. It adds contributor to our model plus it registers interceptor that intercept calls and give logger a call. 

Then we difine contributor that checks if our service (in this case Calculator class) is tagged with [LoggedClass] attribute. If it is we're checking that every member with [LoggedMember] attribute is virtual, because we cannot intercept nonvirtual method calls thus making attribute not really working when used with nonvirtual members.

If all conditions are met we're adding logging interterceptor to method calls of calculator.

Now the easy part, we just have to implement interceptor:

    public class LoggingInterceptor : IInterceptor
 {
     public void Intercept(IInvocation invocation)
     {
         if (invocation.Method.GetCustomAttributes(true).Where(x => x.GetType() == typeof(LoggedMemberAttribute)).Count() > 0)
         {
             Logger.Log(GetParamsMessageFor(invocation));
             invocation.Proceed();
             Logger.Log(GetReturnValueMessageFor(invocation));
         }
         else
         {
             invocation.Proceed();
         }
     }

     private static string GetReturnValueMessageFor(IInvocation invocation)
     {
         var message = ":methodNameWithClassSpecifier finished call. Return value: :returnValue";
         message = message.Replace(":methodNameWithClassSpecifier", invocation.TargetType.Name + "." + invocation.Method.Name);
         message = message.Replace(":returnValue", invocation.ReturnValue.ToString());
         return message;
     }

     private static string GetParamsMessageFor(IInvocation invocation)
     {
         var message = ":methodNameWithClassSpecifier method call. Parameters:";// :firstParam, :secondParam";
        message=  message.Replace(":methodNameWithClassSpecifier", invocation.TargetType.Name + "." + invocation.Method.Name);
         if (invocation.Arguments.Length != 0)
         {
             message = AddInvocationArgumentsToMessage(message, invocation);
         }
         return message;
     }

     private static string AddInvocationArgumentsToMessage(string message, IInvocation invocation)
     {
         message += " " + invocation.Arguments[0];
         foreach (var argument in invocation.Arguments.Skip(1))
         {
             message += ", " + argument;
         }
         return message;
     }
 }

Note that interceptor checks if called method has [LoggedMethod] attribute, else it would log any virtual method call (even one without this attribute).