Thursday 4 August 2011

AspectJ and Custom Logging Annotation

Ive been using AspectJ for a while now and find its got some really cool usages as well as your standard ones like Transaction Management etc. One of the projects Ive brecently been working on has a very ridged process going through the motions in a very structured and standardised way. Originally when I created the little application I always had a log statement at the beginning of the method simply stating its purpose and incoming method args. As this would be a simple JAR application deployed and run via a main method, this sort of logging is good to determine run times and at what point the application gets to. I had already used AOP in the project to profile and time some of the very long running operations which is when I thought of nicely hooking in AspectJ and method logging together.

What I have created is a simple custom logging annotation which when applied to a method on a spring managed bean will log out at the given level and print the method name and args invoked with.


Ive created a sample/demonstration project over on my GitHub which can found here. To see the loogin simple run the main method inside the demonstration project form GitHub.

Here is a usage demonstration of how an application can utilise the Logging annotation.



Simply annotate your method and when it gets invoke you will having logging such as this.

13:27:48.560 [main] DEBUG c.morgan.design.demo.LoggingExample - Method Invocation=[logMe] - Args=[]
13:27:48.561 [main] INFO  c.morgan.design.demo.LoggingExample - Method Invocation=[logMeInfoWithMethodArgs] - Args=[abcdefg, 1234]
13:27:48.561 [main] WARN  c.morgan.design.demo.LoggingExample - Method Invocation=[logMeWarningWithMethodArgs] - Args=[abcdefg, 1234, true]
13:27:48.573 [main] DEBUG c.morgan.design.demo.LoggingExample - Method Invocation=[logMeDebugWithMethodArgs] - Args=[abcdefg, 1234, false, 0.2]

This is only a sample project, If this was to be used in a more production ready application I'm pretty sure I would pick a better name. :)

This is how the demonstration Logging Aspect looks:

I've chosen to take an annotation based approach but this could also be done using XML configuration.



Enhancements to make would be:

* Instead of having three different methods for the various logging level, have only one and retrieve the annotation from the method and determine its logging level from the annotation value.
* At the moment this only supports log-back and log4j, this could be made more abstract and determine the logging libraries for each application.
* Make it in to a library project in which you could simple include the library and configure it. i.e. only log for particular methods, packages etc.
* Allow for custom logging pattern configuration.

Anyway, its a small simple sample of the power of AspectJ, all comments welcome as usual.

2 comments:

  1. Hi James!
    You created three separated methods for different log level: logMeInfoWithMethodArgs, logMeWarningWithMethodArgs and logMeDebugWithMethodArgs. Let's consider making one such method common for all log levels - it requires in Aspect class getting information about loglevel related with @LogMe - do you have any idea how to get this?

    ReplyDelete
  2. Hi Andrzej,

    I believe that since its just an aspect pointcut which is being using to match each logging level I see no reason why you wouldnt be able to simply make the point cut more generic, I found a stack overflow post detailing how someone else has achieve a more generic pointcut, http://stackoverflow.com/a/12187657 . Once your pointcut is being matched, inspect the JoinPoint class which gets exposed, you can find details of the matching advice, here you should be able to find the LogLevel. Hope this helps.

    ReplyDelete