Java : Simplify Exception Logging with AspectJ

This page last changed on Mar 17, 2006 by Kees de Kooter

Introduction

Some snippets from http://www.developer.com/java/other/print.php/3109831

What's wrong with conventional logging

Now that you have seen logging using conventional and AspectJ-based techniques, let's look at the shortcomings of conventional solutions. Figure 1 illustrates the overall schematic of current logging solutions. Every place that needs to log an event needs to explicitly invoke a call to the log() method of an appropriate logger. As you can see, the logging calls will be all over the core modules. When a new module is added to the system, all of its methods that need logging must be instrumented. Such instrumentation is invasive, causing the tangling of the core concerns with the logging concern. Further, if you ever happen to change the logging toolkit to a different API, you need to revisit every logging statement and modify it.

The most fundamental difference between conventional logging and AspectJ-based logging is modularization of the logging concern. Instead of writing modules that implement core concepts in addition to invoking logging operations, with AspectJ you write a few aspects that advise the execution of the operations in the core modules to perform the logging. That way, the core modules do not carry any logging-related code. By modularizing, you separate the logging concern from the core concerns.

 

Exception logging Since exception throwing is an important event in the system, logging the thrown exception is important. AspectJ-based solution offers a way to introduce such a functionality wihtout changing even a single line of code in the core part of the system. Similar to method tracing, you can switch the underlying logging implementation just by changing the aspect.

Next

Unfortunately the article ends right there, stating that exception logging is important, that you can use aspects to achieve it but not how. So I started experimenting.

I mainly use loggers for logging exceptions, I hardly use DEBUG statements an only once in a while an INFO statement. Copy-pasting some variant of the following line over and over again just does not feel right in an OO environment or any other programming environment for that matter.

private Log log = LogFactory.getLog(this.getClass());

 

I started off reading the AspectJ Programming Guide: http://www.eclipse.org/aspectj/doc/released/progguide/index.html

Putting it together in Eclipse

Next I installed the Eclipse AspectJ plugin using the Eclipse update manager (the update site is http://download.eclipse.org/technology/ajdt/31/update) and created a small test project.

I wrote a test class that throws exceptions and one that triggers them:

public class ExceptionThrower {

    public void throwException() throws Exception {

        throw new Exception("Duh - an exception");
    }
}

public class Main {

    public static void main(String[] args) {
        Main instance = new Main();
        instance.test();
    }

    public void test() {

        ExceptionThrower dummyException = new ExceptionThrower();

        try {
            dummyException.throwException();
        } catch (Exception e) {
            System.err.println("Caught by handler: " + e.toString());
        }
    }
}

 

I then wrote the aspect:

public aspect ExceptionLoggingAspect {

    before (Exception e): handler(Exception+) && args(e) {
        System.err.println("Caught by aspect: " + e.toString());
        e.printStackTrace();
    }
}

And although the eclipse compiler complains Only before advice is supported on handler join points (compiler limitation) the code works (smile). No more LogFactories polluting my code!

Caught by aspect: java.lang.Exception: Duh - an exception

java.lang.Exception: Duh - an exception

    at nl.boplicity.ExceptionThrower.throwException(ExceptionThrower.java:16)

    at nl.boplicity.Main.test(Main.java:26)

    at nl.boplicity.Main.main(Main.java:17)

Caught by handler: java.lang.Exception: Duh - an exception

Further reading: Using AspectJ with Maven

The real thing

It is time to implement the aspect in a real application. Log4j is picking up the wrong class information - it displays the name of the aspect - so we have to collect the source information ourselves

public aspect ExceptionLoggingAspect {

    private Log log = LogFactory.getLog(this.getClass());
    private Map loggedThrowables = new WeakHashMap();
    
    public pointcut scope(): within(nl.boplicity..*);
    
    after() throwing(Throwable t): scope() {
        
        logThrowable(t, thisJoinPointStaticPart, 
                thisEnclosingJoinPointStaticPart);
    }
    
    before (Throwable t): handler(Exception+) && args(t) && scope() {
        
        logThrowable(t, thisJoinPointStaticPart, 
                thisEnclosingJoinPointStaticPart);
    }
    
    protected synchronized void logThrowable(Throwable t, StaticPart location,
            StaticPart enclosing) {
        
        if (!loggedThrowables.containsKey(t)) {
            loggedThrowables.put(t, null);
            
            Signature signature = location.getSignature();
            
            String source = signature.getDeclaringTypeName() + ":" + 
                (enclosing.getSourceLocation().getLine());
            
            log.error("(a) " + source + " - " + t.toString(), t);
        }
    }
}

I congured log4j as follows, leaving out the %c:%L part which we assemble in the aspect now:

    <appender
        name="aspect-appender"
        class="org.apache.log4j.ConsoleAppender">
        <param
            name="Target"
            value="System.out" />
        <layout class="org.apache.log4j.PatternLayout">
            <param
                name="ConversionPattern"
                value="%d{ABSOLUTE} %5p %m%n" />
        </layout>
    </appender>

    <category
        name="nl.boplicity.aspects"
        additivity="false">
        <priority value="info"/>
        <appender-ref ref="aspect-appender"/>
    </category>

Comments:

But what about different logging behaviour according to the package the class belongs at? In this case you should implement one pointcut for each package, am I right?

 

Michele 

Posted by at Sep 11, 2006 16:01

The original exception is passed to the logging system. You can modify the logging behaviour using the standard log4j configuration.

Posted by kees at Sep 12, 2006 13:39