Search This Blog

Filtering 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).

Get link

Facebook

Twitter

Pinterest

Email

Other Apps

Labels

Comments

Though not directly related but still important point is correct logging level for libraries, every java app use several library and if all are in DEBUG mode its extremely difficult to get information by correctly setting higher level for library and lower level for source you reduce clutter.

Unfortunately, filtering logs is only a crude workaround. You will still be confronted with hellish stack traces in debugger or profiler and if your tool doesn't support filtering (like Eclipse and jvisualvm don't) you're SOL.

Correct solution? Don't use Java. Or any other technology which forces that amount of bloat on you as application programmer.

You're correct with the language vs framework distinction. But the reality is you have little choice if you are on a project which uses the frightening Spring/Hibernate combo - you can't just throw away legacy code. And remember that Spring was supposed to make everything so much easier compared to EJB. We see how that worked out.

The point is that in Java culture authors of frameworks and libraries pick an inherently misguided approach to solve problems - adding more and more functionality and creating more and more complex middleware and tools instead of getting rid of all the crud, focusing on the task at hand and the simplest, most efficient way to deal with it. Actually, I assume that some commercial tool vendors will be wishing to sell me a stack trace filter feature for $$$. Create a problem, solve it, then make others pay you for it - also reminds me of Microsoft's business model.

What you end up with using that philosophy is "workarounds for workarounds". You wouldn't need them if you dropped some of your core assumptions in the language, too. For example, if you want a high degree of dynamic runtime extensibility (which btw is a nice thing to have), why bother with a static type system and classic compile-build-run cycle in the first place.

I could also put it this way: if you just want to do application programming (where your focus lies entirely on business logic), Java with its prevalent frameworks is a poor tool. It keeps bothering you with details that should be black-box abstractions at your level of thinking. And if you want to understand and engineer for performance, it forces you to opening all the black boxes even more, through all the layers down to bare metal - a truly Herculean task.

As for JVM, yes it's a stable and efficient technology, but I wouldn't say it offsets the complexity drawbacks in real life development. Firstly, other VMs are rapidly catching up. Secondly, with today's hardware many application projects don't need that best-case performance - you can kill them with iron by scaling out (so less efficient VMs are ok - if your application is anything serious, you will need to scale out anyway). Thirdly, by putting all the extra layers on top of a fast JVM it will become slow, too, so it can't even compete face-to-face with alternatives.