Filtering exception stack trace logging with Log4J and a custom ThrowableRenderer

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>

</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