Ayende @ Rahien

My name is Oren Eini
Founder of Hibernating Rhinos LTD and RavenDB.
You can reach me by phone or email:


+972 52-548-6969

, @ Q c

Posts: 6,124 | Comments: 45,474

filter by tags archive

Logging - the AOP way

time to read 3 min | 544 words

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);
		// actual method code 
		LogGateway.Success("DoSomethingInteresting", arg1, arg2);
	catch(Exception e)
		LogGateway.Error(e, "DoSomethingInteresting", arg1, arg2);
		throw e;
		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)
			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);
			StringBuilder sb = null;
			if (logger.IsDebugEnabled)
				sb = new StringBuilder(invocation.TargetType.FullName)
				for (int i = 0; i < invocation.Arguments.Length; i++)
					if (i > 0)
						sb.Append(", ");

				logger.Debug("Result of " + sb + " is: " + invocation.ReturnValue);
		catch (Exception e)

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()
			.Interceptors(new InterceptorReference(typeof(LoggingInterceptor))).First
BasicConfigurator.Configure(); // configure log4net
var sender = container.Resolve<ISmsSender>();
	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,
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.


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:


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

Tobin Harris

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


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

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






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


Gauthier Segay

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


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?


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

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

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


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

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

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

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

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

Comment preview

Comments have been closed on this topic.


  1. RavenDB 3.5 whirl wind tour: You want all the data, you can’t handle all the data - about one day from now
  2. The design of RavenDB 4.0: Making Lucene reliable - 3 days from now
  3. RavenDB 3.5 whirl wind tour: I’ll find who is taking my I/O bandwidth and they SHALL pay - 4 days from now
  4. The design of RavenDB 4.0: Physically segregating collections - 5 days from now
  5. RavenDB 3.5 Whirlwind tour: I need to be free to explore my data - 6 days from now

And 14 more posts are pending...

There are posts all the way to May 30, 2016


  1. RavenDB 3.5 whirl wind tour (14):
    29 Apr 2016 - A large cluster goes into a bar and order N^2 drinks
  2. The design of RavenDB 4.0 (13):
    28 Apr 2016 - The implications of the blittable format
  3. Tasks for the new comer (2):
    15 Apr 2016 - Quartz.NET with RavenDB
  4. Code through the looking glass (5):
    18 Mar 2016 - And a linear search to rule them
  5. Find the bug (8):
    29 Feb 2016 - When you can't rely on your own identity
View all series



Main feed Feed Stats
Comments feed   Comments Feed Stats