Igor Kromin |   Consultant. Coder. Blogger. Tinkerer. Gamer.

| Views: 587
Last week I wrote about enabling full stack trace in Maven's Surefire plugin and that got me thinking that much of the stack trace is actually not relevant. When it comes to logging, it's a waste of resources to write huge stack traces to disk that give no additional relevant information. So I thought lets see what can be done to address this.

I put together a very simple test case that used Log4J to log an exception to the console. The unfiltered output looked like this...
 Log4J unfiltered output
java.lang.RuntimeException: Numbers must be positive, please input both A and B as zero or above
at mypackage.MyClass.addPositive(MyClass.java:7)
at mypackage.MyClassTest.testAddNegative(MyClassTest.java:15)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:498)
at org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:47)
at org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:12)
at org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:44)
at org.junit.internal.runners.statements.InvokeMethod.evaluate(InvokeMethod.java:17)
at org.junit.runners.ParentRunner.runLeaf(ParentRunner.java:271)
at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:70)
at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:50)
at org.junit.runners.ParentRunner$3.run(ParentRunner.java:238)
at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:63)
at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:236)
at org.junit.runners.ParentRunner.access$000(ParentRunner.java:53)
at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:229)
at org.junit.runners.ParentRunner.run(ParentRunner.java:309)
at org.apache.maven.surefire.junit4.JUnit4Provider.execute(JUnit4Provider.java:367)
at org.apache.maven.surefire.junit4.JUnit4Provider.executeWithRerun(JUnit4Provider.java:274)
at org.apache.maven.surefire.junit4.JUnit4Provider.executeTestSet(JUnit4Provider.java:238)
at org.apache.maven.surefire.junit4.JUnit4Provider.invoke(JUnit4Provider.java:161)
at org.apache.maven.surefire.booter.ForkedBooter.invokeProviderInSameClassLoader(ForkedBooter.java:290)
at org.apache.maven.surefire.booter.ForkedBooter.runSuitesInProcess(ForkedBooter.java:242)
at org.apache.maven.surefire.booter.ForkedBooter.main(ForkedBooter.java:121)


That's a lot of irrelevant lines being shown! None of the junit runner or the surefire classes give me any valuable information here. So with a custom ThrowableRenderer I got the stack trace down to the essentials...
 Log4J filtered output
java.lang.RuntimeException : Numbers must be positive, please input both A and B as zero or above
at mypackage.MyClass.addPositive(MyClass.java:7)
at mypackage.MyClassTest.testAddNegative(MyClassTest.java:15)


Perfect! It's concise and gives me the exact location of the exception being thrown. All the noise is filtered out. Configuration for this is simple, something like this...
 Log4J configuration (properties file)
log4j.throwableRenderer=mypackage.BasicFilteredThrowableRenderer
log4j.throwableRenderer.filter=org.junit.,org.apache.maven.,sun.reflect.,java.lang.reflect.


The above translates to XML configuration easily too...
 Log4J configuration (XML file)
<log4j:configuration...
<throwableRenderer class="mypackage.BasicFilteredThrowableRenderer">
<param name="filter" value="org.junit.,org.apache.maven.,sun.reflect.,java.lang.reflect."/>
</throwableRenderer>
</log4j:configuration>


The main part here is setting the log4j.throwableRenderer property to the custom renderer class. This class needs to be on the classpath of course. The second property here is passed to the custom renderer by Log4J and is used to set up filters. See the setFilter() method below. I used a very simple filter mechanism, the filter string is a comma delimited string of package prefixes. Matching is done on the start of the package name only.



Here's a very simple class that does this kind of filtering...
 BasicFilteredThrowableRenderer.java
package mypackage;
import org.apache.log4j.spi.ThrowableRenderer;
import java.util.ArrayList;
public class BasicFilteredThrowableRenderer implements ThrowableRenderer {
private String[] filters;
private static final String PFX_AT = "\tat ";
public void setFilter(String filter) {
if (filter != null) {
this.filters = filter.split("\\,");
}
}
@Override
public String[] doRender(Throwable throwable) {
StackTraceElement[] stes = throwable.getStackTrace();
ArrayList<String> lines = new ArrayList<>();
lines.add(throwable.getClass().getName() + " : " + throwable.getMessage());
for (int i = 0; i < stes.length; i++) {
StackTraceElement ste = stes[i];
boolean doFilter = false;
for (int j = 0; j < filters.length; j++) {
if (filter(ste.getClassName(), j)) {
doFilter = true;
break;
}
}
if (!doFilter) {
lines.add(PFX_AT + ste.toString());
}
}
return lines.toArray(new String[lines.size()]);
}
protected boolean filter(String clazz, int filterNum) {
if (filters == null || filterNum >= filters.length || filterNum < 0) {
return false;
}
return clazz.startsWith(filters[filterNum]);
}
}


There's nothing magical there. Each of the stack trace elements is checked against the filter and only ones that do not match are added to the output string array.

The above renderer doesn't handle things like exception cause logging and doesn't count how many lines have been filtered out. These are all very useful if you're serious about having good logging information. You could also think about regex matching but I think that is an overkill in this situation.

The above will work with Log4J 1.2, I've not experimented with Log4J 2.x yet, once I do, I'll be sure to port this code over.

-i

Have comments or feedback on what I wrote? Please share them below! Found this useful? Consider sending me a small tip.
comments powered by Disqus
Other posts you may like...