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
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
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!
The code using StringBuilder smelled, so I had to do this:
logger.Debug
(
);
Rik, really nice
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:
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?
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?
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!
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
Just wondering if the same technique can be applied for auditing?
Yes, it can be.
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=
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 :)
You intercept property changes and write them to the audit table.
I am not sure that I understand what the problem is.
Sorry Orien that I'm not making myself clear.
Let's say that I have:
public class UserRepository : IUserRepository
{
}
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)
{
}
I guess my question is how can I use AOP in this case instead of having to write the code above on every IRepository ?
This has nothing to do with AOP, actually.
You need to handle that using simple repository base class.
You can see another solution to this here:
ayende.com/.../...xtending-NHibernate-Proxies.aspx
Thanks Oren, I'll have a look at that post
Comment preview