Using annotations for trace logging

Question

I've been working with a codebase of a company that has a policy of writing lots of trace logging. So pretty much every method has a piece of code that starts like this:

String LOG_METHOD = "nameOfMethod(String,List<Long>):void";
if(logger.isTraceEnabled()) { 
    Object[] params = new Object[] { string, list };
    logger.trace(CompanyMessages.newMethodInstanceMessage(this, LOG_METHOD, params)); 
}

and end like this (either in a finally-clause or just at the end of the method:

if(logger.isTraceEnabled()) { 
    logger.trace(CompanyMessages.leaveMethodInstanceMessage(this, LOG_METHOD)); 
}

There is actually more code to it, but this is the basic idea. This is cluttering the code and other coders are constantly messing it up with their own interpretations which don't use the specific CompanyMessages-class which is needed to format the messages to be read by the monitoring tools. So I am looking for a way to get rid of all code above and just provide all methods which need trace-logging with annotations like: @LogBefore('logLevel') & @LogAfter('logLevel').

The reason I choose this solution is to make it so other developers don't have to learn anything new but to use annotations instead of code. I'm working in a server environment in which we deploy hundreds of web applications and dozens of developers. So I have been looking for a way to implement this in a web application without a lot of extra coding or additional large libraries. This means I'm looking for a small, stable AOP implementation using annotations similar to those I proposed, easy to configure in each web application. Performance is also important. What is the simplest example to implement this with AOP?

Edit: I did find something very similar to what I'm looking for, but this has a couple of problems. All classes that need logging must be configured, which would be more resource intensive than just using annotations. Would the spring configuration <aop:aspectj-autoproxy/> fix that?

Penile

Answer 1

Looks like Aspect Oriented Programming (AOP) could really help you with this. It's great at solving these cross-cutting concerns like logging and tracing and it supports annotations like those you need.

Have a look at AspectJ or Spring AOP.

It will involve some learning of the AOP principles and the API you choose but it's definitely worth the effort. Especially logging and tracing are among the first AOP tutorials you will encounter and it's pretty easy to do without having to go deeper.

Femmine

Answer 2

The annotations and AOP points are both valid. Use annotations to alert the AOP framework about the logging.

Another thing I would do is fix your logger.

You have:

String LOG_METHOD = "nameOfMethod(String,List<Long>):void"
if(logger.isTraceEnabled()) { 
    Object[] params = new Object[] { string, list };
    logger.trace(CompanyMessages.newMethodInstanceMessage(this, LOG_METHOD, params) ); 
}

Instead, consider something like this:

logger.trace(this, LOG_METHOD, string, list);

and you can implement it like this:

public void trace(Object obj, Object args...) {
    if (parentLogger.isTraceEnabled()) {
        logger.trace(CompanyMessages.newMethodInstanceMessage(obj, LOG_METHOD, args);
    }
}

Most of the logging utilities were written before we had varargs in Java, so we still see things like what you've written.

We also still want the guarding to prevent calling log when it's not enabled, but the primary motivation for that is because most folks in the past would do what you did, or, even worse:

logger.trace("My message: " + string + " with list " + list);

Which has has an expensive expression whether trace is enabled or not.

But by leveraging varargs, you can get both. Simply use something like MessageFormat (which you are probably doing already), you can easily get:

logger.trace("My message: {0} with list {1}", string, list);

With trace disabled, this is a cheap method call passing 3 pointers. So there is far less motivation to guard it and clutter your code.

Most of the modern loggers don't override nicely, so you typically have to encapsulate it rather than simply extend it.

It doesn't directly solve your issue, dynamically generating trace information. But it's a simple middle ground that readily, and incrementally, clean up your existing code base.

Also, there's 2 other options.

One, is to use a post processor that runs through your code and adds the logging in to places where it doesn't already exists. This saves you the burden of typing is all by hand, but it does clutter the code (since it still exists EVERYWHERE).

Two, is to use an annotation processor at compile time. This is more sophisticated. But what it does is during compilation, it runs through and augments your classes at compile time with the information. The nice thing is that your code is clean (save perhaps for the annotaion), but also all of the work is does at compile. There's not runtime impact not fancy classloaders of Object factories. Once it is built, you can toss your processor away, it's not needed at runtime at all.

There's a project, who's name escapes me, that leverages this. It automatically adds setters/getter to your code at compile. I've heard good things about it.

The AOP frameworks may well do this for you at compile, I'm not familiar enough with them to say, but either way, the technique is worth exploring.

At a minimum, though, wrap your logger. It's incremental, safe, and will gradually clean your code and aid your logging where the annotations may not work for you in general.

Shugart

Answer 3

I don't think annotations were the solution. To annotate a class or instance means giving classes additional information at runtime, per se it does not do anything. You would need some code that processes classes with annotations and adds code before and after each method based on those annotations during runtime.

So there is no way on adding annotations and ready to go, you classes start log their methods.

The solution should be AOP - this exact the problem AOP has been invented in the first place. Define classes/methods/actions on each method and you have you problem solved.

Well, probably you can make it work with annotations and modifying classes during runtime but you end up with self made AOP :-)

Cipolin

Thanks, this made me realise that my view on the workings of annotations was flawed. – Penile

Would love at least one example of AOP, even if simple – Marginate