Logging and AspectJ

Posting the first message in this blog. As I'm writing here as programmer targeting other programmers let the first topic be about logging and aspect oriented programming.

In the majority of available sources logging appears to be the most favorite example of applying AOP. So some time ago we decided to improve logging in our ETaxi project (which I will probably describe in some later posts). We already had some simple aspects logging user access to certain high level methods directly corresponding to URLs. Slowly this appears to be non sufficient to identify the sources of some strange problems that arose on production environments.
So now we have 3 different choices to further apply logging to our project:

1. Try to generalize all logging and perform it using aspects
2. Use logging embedded into main program logic
3. Somehow merge 1 and 2

Today I tried to analyze (and predict consequences) of using different approaches for us.
As I'm pretty much new to AOP (using it only for half a year) the following analyze could sure be full of mistakes so I appreciate comments.

Pros of 1:

• Logging is decoupled from the main logic so main logic flow is much easier to read
• Logging is concentrated and not scattered throughout the project which means it is easier to employ some common policies
  

Cons of 1:

The cons are based on the fact that pros are valid only when you can in some general form identify all points of interest for logging to be applied. As example consider the following Java code snippet

private Order order;
private Driver driver;
private OrderService service;

public void run() {
if(isDriverBusy(driver)) {
//the 1st log I want to move to aspects
log.info(order+" skipped. Driver "+driver+" is busy");
return;
}

//..some other processing probably with other method exit points

service.scheduleFurtherProcessing(order);
  //the 2nd log I want to move to aspects
  log.info("Further processing scheduled for "+order);
}

In this code example I want to log 2 things:

• If isDriverBusy(driver) returns true I want to log that processing of order is finished because driver is busy
• After service.scheduleFurtherProcessing(order) I want to log that current processing finished and next iteration scheduled.

The first thing is difficult to be handled in some generic way with AspectJ logging because after execution of some method I want directly expose part of object state in log message. I don't mean it is impossible, no! This is very possible, but you will not be able to do this with some simple tracing aspect which traces some methods entrance/exit - and this is the problem.
If you want to solve the problem you will need one of the following

• Write advice that dumps the state of this on method exit/enter - then you will be able to view necessary information BUT you will have severe clutter in you log messages because in most situation you need only tiny part of state to be dumped
• Write advice & pointcut which identifies and solves this particular problem - you will end up with tons of specific advices & pointcuts which is: first - much more code than simply put in log messages, and second - makes you aspects very prone to refactorings when you can accidentally loose some of you logging and not notice that
• Employ some 'clever' idea. For example you can mark fields that should be dumped within class' method executions with annotation and dump only them. But this binds your code to aspects. Also methods which receives the state as parameter will dump corresponding objects twice which is annoying. This topic is different in that probably the main problem is with my ability to identify 'really clever' idea, here I appreciate any help (which will not suffer from the problems I mentioned)

The second thing is similar in that if I want to do it I need specific pointcut and advice targeting end of call to service.scheduleFurtherProcessing(order)
in the flow of run() method which as I already said means writing too much code for the simple log message

Cons of 2

are reverse of Pros of 1

Pros of 2

• Ability to easily match messages written to log with actual code
• Debug is simpler (at least when using Idea)
• Runtime performance is better, no need to use reflection to dump anything
• Compile time is shorter the less aspects are used in project

Analyzing cons and pros given above we decided to use the third approach mixing two other together. The idea is to reduce clutter of in-place logging with aspects, but use explicit messages whenever necessary. Thus we loose ability to centralize all logging in one place but be able to have fine control without too much of (fragile) effort. For example we decided to accompany explicit logging with support of @Log annotation. Methods marked with that annotation will be logged on entrance and exit by corresponding aspect.

That's all. Please leave your suggestions, corrections and improvements in comments