Log once or log early?
Bear Giles | October 16, 2010First, a really good resource: Java antipatterns. I plead the Fifth on how many of these things I still do on occasion.
I disagree on one point though – logging once. I hate reading duplicate stack traces as much as everyone else but I think it’s a mistake to only log once. What are the problems?
- Swallowed Exceptions. It still happens. A lot. When it does you’ll lose all evidence of a problem unless you logged something earlier.
- Summarized Exceptions. This is showing the message without the stack trace. In an ideal world this would tell us exactly what we need to know but in practice it’s often a very generic message.
- Lost Exceptions. A stack trace will recursively call getCause(). So far so good — but did you know that SQLException includes a nextException() method? It’s used because a single problem will often cause multiple SQL exceptions and the ‘interesting’ one is usually not the one that’s ultimately propagated to the caller. The standard stack trace method isn’t smart enough to follow these links.
- Lost Information. A stack trace shows the line where the exception occurred but tells us nothing about the context.
There are two sane alternatives. The first approach is to look for the site of the (probable) original exception so you can catch it, log the method arguments and exception message and then rethrow the exception. It’s a single line or two in the log and will give you a lot of insight into duplicating the problem.
The second approach is to write an AOP interceptor that you use liberally. It’s a simple pass-through interceptor except that, in the event of an exception, it will log the method arguments before rethrowing the exception. This gives you a stack trace complete with method arguments.
I like the second approach since it’s extremely powerful during development but can be easily from the production system.
- import java.util.logging.Logger;
- import javax.interceptor.AroundInvoke;
- import javax.interceptor.InvocationContext;
- /*
- * Simple interceptor that logs method arguments when an exception occurs. A simple
- * variant of this lets a method discover it's stack trace at any time. (Just remember
- * to use a ThreadLocal Stack.)
- *
- * @author bgiles
- */
- public class SimpleInterceptor {
- private static final Logger log = Logger.getLogger(SimpleInterceptor.class.getName());
- /**
- * Simple interceptor that logs method arguments when an exception occurs.
- *
- * @param invocation
- * @return
- * @throws Exception
- */
- @AroundInvoke
- public Object logArgumentsOnException(InvocationContext invocation)
- throws Exception {
- Object results = null;
- try {
- results = invocation.proceed();
- } catch (Exception e) {
- StringBuilder sb = new StringBuilder(invocation.getMethod().getName());
- sb.append("(");
- for (Object o : invocation.getParameters()) {
- sb.append(String.valueOf(o));
- sb.append(", ");
- }
- sb.setLength(sb.length() - 2);
- sb.append("): ");
- sb.append(e.getClass().getName());
- sb.append(": ");
- sb.append(e.getMessage());
- log.warning(sb.toString());
- throw e;
- }
- return results;
- }
- }
import java.util.logging.Logger;
import javax.interceptor.AroundInvoke;
import javax.interceptor.InvocationContext;
/*
* Simple interceptor that logs method arguments when an exception occurs. A simple
* variant of this lets a method discover it's stack trace at any time. (Just remember
* to use a ThreadLocal Stack.)
*
* @author bgiles
*/
public class SimpleInterceptor {
private static final Logger log = Logger.getLogger(SimpleInterceptor.class.getName());
/**
* Simple interceptor that logs method arguments when an exception occurs.
*
* @param invocation
* @return
* @throws Exception
*/
@AroundInvoke
public Object logArgumentsOnException(InvocationContext invocation)
throws Exception {
Object results = null;
try {
results = invocation.proceed();
} catch (Exception e) {
StringBuilder sb = new StringBuilder(invocation.getMethod().getName());
sb.append("(");
for (Object o : invocation.getParameters()) {
sb.append(String.valueOf(o));
sb.append(", ");
}
sb.setLength(sb.length() - 2);
sb.append("): ");
sb.append(e.getClass().getName());
sb.append(": ");
sb.append(e.getMessage());
log.warning(sb.toString());
throw e;
}
return results;
}
}- Comments
- No Comments »
- Categories
- Uncategorized
Comments rss
Trackback
TaoSecurity
