Saturday, October 28, 2006

Using Spring AOP to log swallowed exceptions

One example of bad programming style is to catch exceptions and then silently do nothing with - them, aka "swallowing" exceptions - which looks something like this:



...
preWork();

try {
doWork();
} catch (Exception e) {
// FIXME
// Dunno what to do with this exception...
}

postWork();
...


If this is your own code then you should fix it (and then severly punish yourself!). If it is someone elses code - for example a third party lib - and you have to use it then it can be very frustrating to have your code die silently; it makes code so much more difficult to debug.

(As a side note, exception swallowing is probably more common in Java because of a feature of the language - typed exceptions. But I've seen swallowed exception code in plently of other C++-like languages.)

I recently had such a problem when I was enhancing a Spring MVC application that used Tiles to lay out pages. Tiles often swallows exceptions. gggrrr.

What to do? It would take a fair amount of effort to fix exception handling in the Tiles code and also a fair amount of effort to step through the application code with a debugger.

Fortunately, Spring - the ultimate software hammer - provided the base infrastructure for a simple solution:
  • Use ThrowsAdvice AOP advice to intercept an exception thrown from the application code, log the exception at ERROR level, and let the exception flow continue.
Step 1: Create a ThrowsAdvice to that will intercept and log an exception


package robertmaldon.util;

import java.lang.reflect.Method;

import java.io.PrintWriter;
import java.io.StringWriter;

import org.apache.commons.logging.Log;
import org.apache.commons.logging.LogFactory;

import org.springframework.aop.ThrowsAdvice;

public final class LogThrowsAdvice implements ThrowsAdvice {
private Log logger = LogFactory.getLog(this.getClass());

public void afterThrowing(Method method, Object[] args,
Object target, Exception ex) throws Throwable {
logger.error("Intercepted exception of type ["
+ ex.getClass().getName()
+ "] thrown by target class ["
+ target.getClass().getName()
+ "] and method [" + method.toString() + "]");

logger.error(getStackTrace(ex));

// Rethrow the exception in case something else downstream can
// handle it.
throw ex;
}

private String getStackTrace(Exception ex) {
try {
StringWriter sw = new StringWriter();
PrintWriter pw = new PrintWriter(sw);
ex.printStackTrace(pw);

return sw.toString();
} catch (Exception e) {
return e.toString();
}
}
}


Step 2: Create the bean definition for the ThrowsAdvice and configure an autoproxy to wire the advice to your application code.


<!-- Bean definitions for your application code -->
<bean id="petStoreController1" .../>
<bean id="petStoreController2" .../>

<!-- Define the ThrowsAdvice bean -->
<bean id="logThrowsAdvice" class="robertmaldon.util.LogThrowsAdvice" />

<!-- Wire the advice to the application code -->
<bean class="org.springframework.aop.framework.autoproxy.BeanNameAutoProxyCreator">
<property name="beanNames"><value>petStoreController*</value></property>
<property name="interceptorNames">
<list>
<value>logThrowsAdvice</value>
</list>
</property>
</bean>


Step 3: There is no step 3!

Very simple, very easy.

This approach is good for development, but may introduce too much overhead for production.

9 comments:

Rockstar said...

Sweet. I was just looking for a solution to this problem. Thanks.

AV said...

Do you have an idea of the truth overhead in Production, and where can it be coming from?

I mean, I've tried this solution myself, and the overhead seems to come from concurrency when Spring is locating the throws advisor, but I'm not sure :(

Robert Maldon said...

Hi Electric,

I've only used this technique to help debug in development so I haven't analyzed any performance impact.

In an unrelated project I did some testing of the "new" AOP in Spring 2 and found that it added only microseconds to the overhead, so if you have the time you might want to look into using Spring 2 AOP instead - but I won't absolutely guarantee it will fix any performance problems :)

If I get the time I might profile Spring 1 AOP and Spring 2 AOP for this particular application.

Madnuel said...

Thanks man! Very usefull! Do you know how I can format de error messages with a configuration file?

Robert Maldon said...

Manuel, you might get some out of the box formatting from whatever underlying logger you use. e.g. if the underlying logger is log4j then some of the logging format can be config driven via the PatternLayout. For more sophisticated formatting you'll probably have to roll your own.

David C Peterson said...

Hi, this is great. The only problem I have is that I'm not running a container. I'm actually using a main method. When I do that, I get a $Proxy24 object instead of my object returned which makes it hard to run my code from my main() method.

public static void main(String[] args) throws Exception {

ApplicationContext ctx = new FileSystemXmlApplicationContext(
"classpath:applicationContext.xml");
// EXCEPTION, $Proxy24 is returned instead of FolderWatcher.
FolderWatcher reader = (FolderWatcher) ctx.getBean("FolderWatcher");

while (true) {
Exchange exchange = null;
reader.process(exchange);
Thread.sleep(10000);
}
}

David C Peterson said...

in BeanNameAutoProxyCreator, if I set the property
property name="proxyTargetClass" value="true"
then I do indeed get my class instance and can call methods on it without the classcastexception.
However, my bean doesn't get dependency injection happening. So all my class properties are null. :(

Mahesh Patro said...

I have two after advice aspect for a method. If my 1st advice throws exception, it should not execute the 2nd aspect at all and report the error to caller. Seems like it swallows the exception and goes to next advice.

Robert Maldon said...

Hi Mahesh,

Does the situation you describe only happen when debug after throws advice is added?