Thursday, March 25, 2010

Filter your stack traces

Probably the first utility I write when starting up a new project is ExceptionUtils.getFilteredStackTrace(Throwable e)
The idea here is to:
1. "Flatten" the trace. e.printStackTrace attempts to display the stack trace of the creation of each Exception in the chain. In my experience, only the stack of the "bottom" exception is interesting.
2. Filter out third party lines. 99% of the time, the offending code is mine, not my library's. So why show those endless lines from Tomcat, JUnit, Hibernate, etc?

Filtering isn't always appropriate. Sometimes the trace provides good insight into what your libraries are trying to do when the messages aren't clear. I also recommend turning filtering off in production, where you really need all of the info you can get. However, most of the time, you mainly just want to see what your own code was up to when the exception was thrown, and this approach removes massive amounts of noise.

Here's an example. I took the standard Hibernate Person model and hooked it up to the H2 database. I altered the model to make username unique, so that this test fails:


Here's the output from the filtered run:

HibExample.test: Exception: org.hibernate.exception.ConstraintViolationException: could not insert: [hib.Person]
Caused by: org.h2.jdbc.JdbcSQLException: Unique index or primary key violation: "CONSTRAINT_INDEX_8 ON PUBLIC.PERSON(FIRSTNAME)"; SQL statement:
insert into PERSON (PERSON_ID, age, firstname, lastname) values (null, ?, ?, ?) [23001-132]
 37 lines skipped for [org.h2, org.hibernate, sun., java.lang.reflect.Method, $Proxy]
 at hib.HibExample.test(HibExample.java:18)
 24 lines skipped for [sun., java.lang.reflect.Method, org.junit, org.eclipse]

And here's e.printStackTrace

org.hibernate.exception.ConstraintViolationException: could not insert: [hib.Person]
 at org.hibernate.exception.SQLStateConverter.convert(SQLStateConverter.java:94)
 at org.hibernate.exception.JDBCExceptionHelper.convert(JDBCExceptionHelper.java:66)
 at org.hibernate.id.insert.AbstractReturningDelegate.performInsert(AbstractReturningDelegate.java:64)
 at org.hibernate.persister.entity.AbstractEntityPersister.insert(AbstractEntityPersister.java:2176)
 at org.hibernate.persister.entity.AbstractEntityPersister.insert(AbstractEntityPersister.java:2656)
 at org.hibernate.action.EntityIdentityInsertAction.execute(EntityIdentityInsertAction.java:71)
 at org.hibernate.engine.ActionQueue.execute(ActionQueue.java:279)
 at org.hibernate.event.def.AbstractSaveEventListener.performSaveOrReplicate(AbstractSaveEventListener.java:321)
 at org.hibernate.event.def.AbstractSaveEventListener.performSave(AbstractSaveEventListener.java:204)
 at org.hibernate.event.def.AbstractSaveEventListener.saveWithGeneratedId(AbstractSaveEventListener.java:130)
 at org.hibernate.event.def.DefaultPersistEventListener.entityIsTransient(DefaultPersistEventListener.java:154)
 at org.hibernate.event.def.DefaultPersistEventListener.onPersist(DefaultPersistEventListener.java:110)
 at org.hibernate.event.def.DefaultPersistEventListener.onPersist(DefaultPersistEventListener.java:61)
 at org.hibernate.impl.SessionImpl.firePersist(SessionImpl.java:646)
 at org.hibernate.impl.SessionImpl.persist(SessionImpl.java:620)
 at org.hibernate.impl.SessionImpl.persist(SessionImpl.java:624)
 at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
 at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
 at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
 at java.lang.reflect.Method.invoke(Method.java:597)
 at org.hibernate.context.ThreadLocalSessionContext$TransactionProtectionWrapper.invoke(ThreadLocalSessionContext.java:342)
 at $Proxy4.persist(Unknown Source)
 at hib.HibExample.test(HibExample.java:16)
 at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
 at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
 at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
 at java.lang.reflect.Method.invoke(Method.java:597)
 at org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:44)
 at org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:15)
 at org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:41)
 at org.junit.internal.runners.statements.InvokeMethod.evaluate(InvokeMethod.java:20)
 at org.junit.internal.runners.statements.RunBefores.evaluate(RunBefores.java:28)
 at org.junit.internal.runners.statements.RunAfters.evaluate(RunAfters.java:31)
 at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:70)
 at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:44)
 at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:180)
 at org.junit.runners.ParentRunner.access$000(ParentRunner.java:41)
 at org.junit.runners.ParentRunner$1.evaluate(ParentRunner.java:173)
 at org.junit.internal.runners.statements.RunBefores.evaluate(RunBefores.java:28)
 at org.junit.internal.runners.statements.RunAfters.evaluate(RunAfters.java:31)
 at org.junit.runners.ParentRunner.run(ParentRunner.java:220)
 at org.eclipse.jdt.internal.junit4.runner.JUnit4TestReference.run(JUnit4TestReference.java:49)
 at org.eclipse.jdt.internal.junit.runner.TestExecution.run(TestExecution.java:38)
 at org.eclipse.jdt.internal.junit.runner.RemoteTestRunner.runTests(RemoteTestRunner.java:467)
 at org.eclipse.jdt.internal.junit.runner.RemoteTestRunner.runTests(RemoteTestRunner.java:683)
 at org.eclipse.jdt.internal.junit.runner.RemoteTestRunner.run(RemoteTestRunner.java:390)
 at org.eclipse.jdt.internal.junit.runner.RemoteTestRunner.main(RemoteTestRunner.java:197)
Caused by: org.h2.jdbc.JdbcSQLException: Unique index or primary key violation: "CONSTRAINT_INDEX_8 ON PUBLIC.PERSON(FIRSTNAME)"; SQL statement:
insert into PERSON (PERSON_ID, age, firstname, lastname) values (null, ?, ?, ?) [23001-132]
 at org.h2.message.DbException.getJdbcSQLException(DbException.java:316)
 at org.h2.message.DbException.get(DbException.java:167)
 at org.h2.message.DbException.get(DbException.java:144)
 at org.h2.index.BaseIndex.getDuplicateKeyException(BaseIndex.java:157)
 at org.h2.index.PageBtree.find(PageBtree.java:115)
 at org.h2.index.PageBtreeLeaf.addRow(PageBtreeLeaf.java:137)
 at org.h2.index.PageBtreeLeaf.addRowTry(PageBtreeLeaf.java:92)
 at org.h2.index.PageBtreeIndex.addRow(PageBtreeIndex.java:88)
 at org.h2.index.PageBtreeIndex.add(PageBtreeIndex.java:79)
 at org.h2.table.RegularTable.addRow(RegularTable.java:112)
 at org.h2.command.dml.Insert.insertRows(Insert.java:120)
 at org.h2.command.dml.Insert.update(Insert.java:82)
 at org.h2.command.CommandContainer.update(CommandContainer.java:70)
 at org.h2.command.Command.executeUpdate(Command.java:198)
 at org.h2.jdbc.JdbcPreparedStatement.executeUpdateInternal(JdbcPreparedStatement.java:141)
 at org.h2.jdbc.JdbcPreparedStatement.executeUpdate(JdbcPreparedStatement.java:127)
 at org.hibernate.id.IdentityGenerator$GetGeneratedKeysDelegate.executeAndExtract(IdentityGenerator.java:94)
 at org.hibernate.id.insert.AbstractReturningDelegate.performInsert(AbstractReturningDelegate.java:57)
 ... 44 more

Update: Here's a good starter version of the filtering code. It may have bugs: I quickly ported it. It depends on Google Collections, because I can no longer imagine coding without them!

1 comment:

Dave said...

Care to post the code to ExceptionUtils.filteredStackTrace() ? ;) I'd love to look at it