Ayende @ Rahien

Refunds available at head office

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.

Comments

Davy Brion
07/31/2008 09:16 PM by
Davy Brion

AOP and Logging are great together... check out the following post on how you can easily log each method's incoming parameters, and its return value:

http://davybrion.com/blog/2008/05/adding-behavior-with-postsharp/

i wouldn't use that in production, but for debugging it's great

Tobin Harris
07/31/2008 09:54 PM by
Tobin Harris

Thanks Ayende, that's a great example and I'm looking forward to trying it out :)

Torkel
08/01/2008 07:37 AM by
Torkel

Yes, I love this usage of AOP. I used this approach to trace all in/out communication to a SAP RFC interface, with 40+ methods, each method having 5-15 arguments. The logging code for the SAP interface was huge when I started on the project and yet it did seldom include the relevant information.

By using this AOP approach I could remove all that duplicated logging code and at the same time be able to turn on/off logging and serialize all the arguments and return values to xml (and save in db), this made production troubleshooting so much easier!

Rik Hemsley
08/01/2008 09:47 AM by
Rik Hemsley

The code using StringBuilder smelled, so I had to do this:

logger.Debug

(

"{0}.{1}({2})",

invocation.TargetType.FullName,

invocation.Method,

string.Join(", ", invocation.Arguments.ToArray())

);

Gauthier Segay
08/01/2008 07:09 PM by
Gauthier Segay

you may want to bypass or cribble some arguments such as one named password or having [DoNotLog] meta attribute.

Sammy
08/05/2008 09:18 AM by
Sammy

I have a couple of questions please:

  1. In your test code, you have an empty catch block. I always thought this will block invocation.Proceed() from catching the exception itself. Am I wrong?

  2. Do you use AOP for ALL your application logging? If you don't, what kind of logging would you do inline - that is, within the function code?

  3. Do you retrieve a Logger for each type of class usually, or would you recommend having a logger type for, for instance, the whole assembly?

Thanks!

Ayende Rahien
08/05/2008 11:30 PM by
Ayende Rahien

1) the test code is not the code that is intrecepted, it is the code that is using the intercepted component.

2) pretty much, I something do extra stuff when it is really required. Very rare, though

3) logger per type

John Simons
09/21/2008 10:44 PM by
John Simons

Just wondering if the same technique can be applied for auditing?

John Simons
09/22/2008 06:16 AM by
John Simons

Can you give me some pointers ?

My audit table is something like this:

Changed By=jsimons

At=12 Mar 2008 18:00

Type Of Object Modified=User

ObjectKey=scropp

Data Modified=

    Last Name

        Before = Cropp

        After = Smith

    .....

So that I can query it by saying something like: Who was the last person to modify the LastName of a User with username=scropp?

Also, my repository is Active Directory and the auditing data is kept in sql.

I've been thinking about this problem for a while, and I don't seem to come up with a clean solution that does not involve adding extra code to each of my models (User, Group,....) that require auditing.

Any help would be very appreciated :)

Ayende Rahien
09/22/2008 06:29 AM by
Ayende Rahien

You intercept property changes and write them to the audit table.

I am not sure that I understand what the problem is.

John Simons
09/22/2008 08:03 AM by
John Simons

Sorry Orien that I'm not making myself clear.

Let's say that I have:

public class UserRepository : IUserRepository

{

    public void Save(User user)

    {

    }


    User Load(string username){}

}

and User is:

class User {

string username,

string FirstName,

string LastName,

....

}

If I want to audit on the Save method and audit what the value was before and after I would have to write something like this:

public void Save(User user)

{

User userBeforeChange = Load(user.Username);

....

Audit.Write("FirstName Before={0}, After={1}", userBeforeChange.Firstname, user.Firstname);

}

I guess my question is how can I use AOP in this case instead of having to write the code above on every IRepository ?

John Simons
09/22/2008 10:07 PM by
John Simons

Thanks Oren, I'll have a look at that post

Comments have been closed on this topic.