Logging - the AOP way

Logging is probably the most mentioned sweet spot of AOP. Probably because it is the simplest and most straightforward example most people can think of. I remember going over a piece of code that handles billions of transactions a day(that is for you, Jdn), and seeing something like this:

public void DoSomethingInteresting(string arg1, int arg2)
{
	LogGateway.Enter("DoSomethingInteresting", arg1, arg2);
	try
	{
		// actual method code 
		LogGateway.Success("DoSomethingInteresting", arg1, arg2);
	}
	catch(Exception e)
	{
		LogGateway.Error(e, "DoSomethingInteresting", arg1, arg2);
		throw e;
	}
	finally
	{
		LogGateway.Exit("DoSomethingInteresting", arg1, arg2);
	}
}

That was repeated for each and every method in the system. It was horrible.

I don't care how you do it, but there are at least 7 AOP approaches in the CLR, at least three of them are applicable in your environment.

I am going to show how to handle that with Windsor's AOP, but the same thing is applicable using other approaches. First, our service:

public interface ISmsSender
{
	int Send(string to, string msg);
}

public class SmsSender : ISmsSender
{
	public int Send(string to, string msg)
	{
		if(msg.Length>160)
			throw new ArgumentException("too long","msg");
		return to.Length;
	}
}

And now we need to define the interceptor:

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);
			}

			invocation.Proceed();
			if(logger.IsDebugEnabled)
			{
				
				logger.Debug("Result of " + sb + " is: " + invocation.ReturnValue);
			}
		}
		catch (Exception e)
		{
			logger.Error(e);
			throw;
		}
	}
}

The code is really simple, we get the logger instance ( in this case, from log4net ), check if logging is enabled and if so, write the method and parameters to the log. We then execute the code and log the return value as well.

If there was an error, we log that as well.

Here is my test code:

var container = new WindsorContainer()
	.Register(
		Component.For<LoggingInterceptor>(),
		Component.For<ISmsSender>().ImplementedBy<SmsSender>()
			.Interceptors(new InterceptorReference(typeof(LoggingInterceptor))).First
	);
BasicConfigurator.Configure(); // configure log4net
var sender = container.Resolve<ISmsSender>();
try
{
	sender.Send("ayende", "short");
	sender.Send("rahien", new string('q', 161));
}
catch (Exception)
{
	
}

And the output for that is:

241 [1] DEBUG ConsoleApplication9.SmsSender (null) - ConsoleApplication9.SmsSender.Int32 Send(System.String, System.String)(ayende, short)
272 [1] DEBUG ConsoleApplication9.SmsSender (null) - Result of ConsoleApplication9.SmsSender.Int32 Send(System.String, System.String)(ayende, short) is: 6
272 [1] DEBUG ConsoleApplication9.SmsSender (null) - ConsoleApplication9.SmsSender.Int32 Send(System.String, System.String)(rahien,
    qqqqqqqqqqqqqqqqqqqqqqqqqqqqqqqqqqqqqqqqqqqqqqqqqqqqqqq
    qqqqqqqqqqqqqqqqqqqqqqqqqqqqqqqqqqqqqqqqqqqqqqqqqqqqqqq
    qqqqqqqqqqqqqqqqqqqqqqqqqqqqqqqqqqqqqqqqqqqqqqqqqqq)
273 [1] ERROR ConsoleApplication9.SmsSender (null) - System.ArgumentException: too long
Parameter name: msg
   at ConsoleApplication9.SmsSender.Send(String to, String msg) in C:\Users\ayende\Documents\Visual Studio 2008\Projects\ConsoleApplication9\ConsoleApplication9\ISmsSender.cs:line 15
   at ISmsSenderProxyb24fc36182fb434fa7f466d148259c48.InvocationSend_1.InvokeMethodOnTarget()
   at Castle.DynamicProxy.AbstractInvocation.Proceed() in e:\OSS\Castle\Tools\Castle.DynamicProxy2\Castle.DynamicProxy\AbstractInvocation.cs:line 140
   at ConsoleApplication9.LoggingInterceptor.Intercept(IInvocation invocation) in C:\Users\ayende\Documents\Visual Studio 2008\Projects\ConsoleApplication9\ConsoleApplication9\Program.cs:line 65

Simple, elegant, and doesn't clutter my code.

Print | posted on Thursday, July 31, 2008 9:40 PM