Yesterday we had a little introduction to Ninject. Today I’d like to examine what’s involved in getting some AOP style logging going for your application. I find that there are only very few places where I’m logging something that steps out of the bounds of being called at the end of the method when things succeed. I’m generally more interested in what happens when things go wrong and that’s when I log the exception. In some cases I’ll be interested in the actual parameters.
The code I’m going to show you will take care of basic logging needs but if you want more information about what happens inside your method you’re either going to need to extend my implementation or log the call from within your method body. We’re going to implement logging that when run with the debug level turned on will tell us that a method is going to execute, whether it finished successfully or with an error and if there was an error it will also log the exception.
To get this thing on the road, on the LightSpeed road that is. We’re going to use NLog to get flexible routing of log messages. We’re first going to create a LightSpeedTarget that is a customized NLog target (route destination) for your log messages.
The class above overrides the TargetWithLayout class from the NLog project. The attribute tells NLog how to find this target. In the constructor I override the default message layout because it was a bit too verbose to my liking.
We then override the Write method where we map the properties to our ApplicationEvent. And lastly we add the event to the repository and commit it.
Now if we want our application to use this we’re going to have to tell it how. Nlog does this by looking for an nlog.config file in your application directory. So let’s go ahead and add an nlog.config file to our project. I’ll show you the nlog.config file for the application. In my unit test project I’m using the console logger so I can see what’s going on :)
The NLog.config file for the application:
My NLog.config file for my test project:
This enables our application to use the target we just created. Moving on now to the Interceptor which is Ninject specific (You can do the same with other DI frameworks). In Ninject you can tell the kernel to intercept a method on a class and execute some logic before and after invocation of the method. We can tell Ninject to intercept all methods on a class, specific methods or when we say all methods we can still exclude some of them. For our logging example I chose to use all methods on a class. You can do this by decorating the class with an [Intercept] attribute. If you would want a method not to be intercepted you can by decorating that method with an [DoNotIntercept] attribute.
I took the liberty of inheriting of that attribute first.. that makes the rest of my code look a little bit prettier.
This class only overrides a couple of callbacks from its base class the SimpleFailureInterceptor. This is where the actual interception takes place.
This is al the work that is involved in the actual implementation of our logger. Now I’d like to get some confirmation that things actually do work. Unit testing to the rescue I’d say ;)
The first thing we’re going to need is way to verify that stuff actually got intercepted. I did that by subclassing the LoggingInterceptor with a LoggingCounterInterceptor in my unit test project.
In the code above we’re just adding 2 counter properties to the interceptor and adding their counts at the appropriate time. Next we’re going to need some kind of service class or something on which we can use our interceptor, enter the InterceptedServiceMock.
The code above has one method that should execute and one method that throws an exception so we can verify things get picked up accordingly. Now all that’s left to do is write the appropriate specs for them and see if they pass :)
Testing this got a little messy I have to admit that. Now for a concrete example of how that looks in my application:
And that’s how I implemented logging for my application :) Needless to say it was the testing that took me the longest to write. And from now on I don’t have to worry anymore about forgetting that logger call. I always have minimal logging going. AOP is usefull in a lot more cases but this seemed like a good and easy example.
Our next post will deal with initializing the modules in your application and their respective behaviors.