Filter irrelevant stack trace lines in logs

I love stack traces. Not because I love errors, but the moment they occur, stack trace is priceless source of information. For instance in web application the stack trace shows you the complete request processing path, from HTTP socket, through filters, servlets, controllers, services, DAOs, etc. – up to the place, where an error occurred. You can read them as a good book, where every event has cause and effect. I even implemented some enhancements in the way Logback prints exceptions, see Logging exceptions root cause first.

But one thing’s been bothering me for a while. The infamous “stack trace from hell” symptom – stack traces containing hundreds of irrelevant, cryptic, often auto-generated methods. AOP frameworks and over-engineered libraries tend to produce insanely long execution traces. Let me show a real-life example. In a sample application I am using the following technology stack:

Colours are important. According to framework/layer colour I painted a sample stack trace, caused by exception thrown somewhere deep while trying to fetch data from the database:

No longer that pleasant, don’t you think? Placing Spring between application and Hibernate in the first diagram was a huge oversimplification. Spring framework is a glue code that wires up and intercepts your business logic with surrounding layers. That is why application code is scattered and interleaved by dozens of lines of technical invocations (see green lines). I put as much stuff as I could into the application (Spring AOP, method-level @Secured annotations, custom aspects and interceptors, etc.) to emphasize the problem – but it is not Spring specific. EJB servers generate equally terrible stack traces (…from hell) between EJB calls. Should I care? Think about it, when you innocently call BookService.listBooks() from BookController.listBooks() do you expect to see this?

at com.blogspot.nurkiewicz.BookService.listBooks()
at com.blogspot.nurkiewicz.BookService$$FastClassByCGLIB$$e7645040.invoke()
at net.sf.cglib.proxy.MethodProxy.invoke()
at org.springframework.aop.framework.Cglib2AopProxy$CglibMethodInvocation.invokeJoinpoint()
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed()
at org.springframework.aop.aspectj.MethodInvocationProceedingJoinPoint.proceed()
at com.blogspot.nurkiewicz.LoggingAspect.logging()
at sun.reflect.NativeMethodAccessorImpl.invoke0()
at sun.reflect.NativeMethodAccessorImpl.invoke()
at sun.reflect.DelegatingMethodAccessorImpl.invoke()
at java.lang.reflect.Method.invoke()
at org.springframework.aop.aspectj.AbstractAspectJAdvice.invokeAdviceMethodWithGivenArgs()
at org.springframework.aop.aspectj.AbstractAspectJAdvice.invokeAdviceMethod()
at org.springframework.aop.aspectj.AspectJAroundAdvice.invoke()
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed()
at org.springframework.aop.interceptor.AbstractTraceInterceptor.invoke()
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed()
at org.springframework.transaction.interceptor.TransactionInterceptor.invoke()
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed()
at org.springframework.aop.interceptor.ExposeInvocationInterceptor.invoke()
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed()
at org.springframework.aop.framework.Cglib2AopProxy$DynamicAdvisedInterceptor.intercept()
at com.blogspot.nurkiewicz.BookService$$EnhancerByCGLIB$$7cb147e4.listBooks()
at com.blogspot.nurkiewicz.web.BookController.listBooks()

And have you even noticed there is custom aspect in between? That’s the thing, there is so much noise in the stack traces nowadays that following the actual business logic is virtually impossible. One of the best troubleshooting tools we have is bloated with irrelevant framework-related stuff we don’t need in 99% of the cases.

I implemented a very simple enhancement in Logback. Basically you can define a set of stack trace frame patterns that are suppose to be excluded from stack traces. Typically you will use package or class names that you are not interested in seeing. This is a sample logback.xml excerpt with the new feature enabled:

I am a bit extreme in filtering almost whole Spring framework + Java reflection and CGLIB classes. But it is just to give you an impression how much can you get. The very same error after applying my enhancement to Logback:

Just as a reminder, green is our application. Finally in one place, finally you can really see what was your code doing when an error occurred:

at com.blogspot.nurkiewicz.DefaultBookHelper.findBooks()
at com.blogspot.nurkiewicz.BookService.listBooks()
at com.blogspot.nurkiewicz.LoggingAspect.logging()
at com.blogspot.nurkiewicz.web.BookController.listBooks()

Simpler? If you like this feature, I opened a ticket LBCLASSIC-325: Filtering out selected stack trace frames. Vote and discuss. This is only a proof-of-concept, but if you like to have a look at the implementation (improvements are welcome!), it is available under my fork of Logback (around 20 lines of code).

3. JUnit Tutorial for Unit Testing

4. Java Annotations Tutorial3>

5. Java Interview Questions

6. Spring Interview Questions

7. Android UI Design

and many more ....

2 comments

I agree. I wrote a java lib that filters the stacktrace and it could be integrated with log4j. Only my lib takes the package prefix that you would be interested in and it cuts the rest. but the idea is the same

I actually wrote a library (https://github.com/michaelgantman/Mgnt/releases/tag/1.01) that contains several utilities. One of them is a general purpose stacktrace filter that I used extensively and found it very useful. The class is called TextUtils and it has method getStacktrace() with several overridden signatures. It takes a Throwable instance and allows to set a package prefix of the packages that are relevant. Let’s say your company’s code always resides in packages that start with “com.plain.*” So you set such a prefix and do this

logger.info(TextUtils.getStacktrace(e, true, “com.plain.”)); this will filter out very smartly all the useless parts of the trace leaving you with very concise stacktrace. Also I found it very convinient to pre-set the prefix and then just use the convinience method

TextUtils.getStacktrace(e); It will do the same. To preset the prefix just use method

setRelevantPackage(“com.plain.”); Also if you use Spring environment you can add the following segment to your Spring configuration and then you all set:

The library comes with well written (I hope) Javadoc that explains everything in detail. But here is a little teaser: you will get a following stacktrace:

at com.plain.BookService.listBooks() at com.plain.BookService$$FastClassByCGLIB$$e7645040.invoke() at net.sf.cglib.proxy.MethodProxy.invoke() … at com.plain.LoggingAspect.logging() at sun.reflect.NativeMethodAccessorImpl.invoke0() … at com.plain.BookService$$EnhancerByCGLIB$$7cb147e4.listBooks() at com.plain.web.BookController.listBooks() instead of

at com.plain.BookService.listBooks() at com.plain.BookService$$FastClassByCGLIB$$e7645040.invoke() at net.sf.cglib.proxy.MethodProxy.invoke() at org.springframework.aop.framework.Cglib2AopProxy$CglibMethodInvocation.invokeJoinpoint() at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed() at org.springframework.aop.aspectj.MethodInvocationProceedingJoinPoint.proceed() at com.plain.LoggingAspect.logging() at sun.reflect.NativeMethodAccessorImpl.invoke0() at sun.reflect.NativeMethodAccessorImpl.invoke() at sun.reflect.DelegatingMethodAccessorImpl.invoke() at java.lang.reflect.Method.invoke() at org.springframework.aop.aspectj.AbstractAspectJAdvice.invokeAdviceMethodWithGivenArgs() at org.springframework.aop.aspectj.AbstractAspectJAdvice.invokeAdviceMethod() at org.springframework.aop.aspectj.AspectJAroundAdvice.invoke() at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed() at org.springframework.aop.interceptor.AbstractTraceInterceptor.invoke() at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed() at org.springframework.transaction.interceptor.TransactionInterceptor.invoke() at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed() at org.springframework.aop.interceptor.ExposeInvocationInterceptor.invoke() at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed() at org.springframework.aop.framework.Cglib2AopProxy$DynamicAdvisedInterceptor.intercept() at com.plain.BookService$$EnhancerByCGLIB$$7cb147e4.listBooks() at com.plain.web.BookController.listBooks()

Newsletter

Join them now to gain exclusive access to the latest news in the Java world, as well as insights about Android, Scala, Groovy and other related technologies.

Email address:

Recent Jobs

No job listings found.

Join Us

With 1,240,600 monthly unique visitors and over 500 authors we are placed among the top Java related sites around. Constantly being on the lookout for partners; we encourage you to join us. So If you have a blog with unique and interesting content then you should check out our JCG partners program. You can also be a guest writer for Java Code Geeks and hone your writing skills!

Disclaimer

All trademarks and registered trademarks appearing on Java Code Geeks are the property of their respective owners. Java is a trademark or registered trademark of Oracle Corporation in the United States and other countries. Examples Java Code Geeks is not connected to Oracle Corporation and is not sponsored by Oracle Corporation.