[Java] Voorkomen dat stacktrace ingekort wordt

[ari3]

Ik ben een J2EE applicatie aan het debuggen op JBoss en ik loop vaak tegen het probleem aan dat als een transactie afgebroken wordt, de reden voor het afbreken niet eenvoudig kan worden achterhaald omdat de stacktrace ongewild ingekort wordt.

Onderstaande stacktrace laat zien dat een transactie wordt afgebroken maar dat de oorzaak voor het afbreken van de transactie (caused by) wordt ingekort met "... XX more". Hierdoor kan ik dus niet de oorzaak eenvoudig achterhalen.

code:

org.hibernate.exception.GenericJDBCException: Cannot open connection
    at org.hibernate.exception.SQLStateConverter.handledNonSpecificException(SQLStateConverter.java:103)
    at org.hibernate.exception.SQLStateConverter.convert(SQLStateConverter.java:91)
    at org.hibernate.exception.JDBCExceptionHelper.convert(JDBCExceptionHelper.java:43)
    at org.hibernate.exception.JDBCExceptionHelper.convert(JDBCExceptionHelper.java:29)
    at org.hibernate.jdbc.ConnectionManager.openConnection(ConnectionManager.java:426)
    at org.hibernate.jdbc.ConnectionManager.getConnection(ConnectionManager.java:144)
    at org.hibernate.jdbc.AbstractBatcher.prepareQueryStatement(AbstractBatcher.java:139)
    at org.hibernate.loader.Loader.prepareQueryStatement(Loader.java:1547)
    at org.hibernate.loader.Loader.doQuery(Loader.java:673)
    at org.hibernate.loader.Loader.doQueryAndInitializeNonLazyCollections(Loader.java:236)
    at org.hibernate.loader.Loader.loadEntity(Loader.java:1860)
    at org.hibernate.loader.entity.AbstractEntityLoader.load(AbstractEntityLoader.java:48)
    at org.hibernate.loader.entity.AbstractEntityLoader.load(AbstractEntityLoader.java:42)
    at org.hibernate.persister.entity.AbstractEntityPersister.load(AbstractEntityPersister.java:3044)
    at org.hibernate.event.def.DefaultLoadEventListener.loadFromDatasource(DefaultLoadEventListener.java:395)
    at org.hibernate.event.def.DefaultLoadEventListener.doLoad(DefaultLoadEventListener.java:375)
    at org.hibernate.event.def.DefaultLoadEventListener.load(DefaultLoadEventListener.java:139)
    at org.hibernate.event.def.DefaultLoadEventListener.onLoad(DefaultLoadEventListener.java:98)
    at org.hibernate.impl.SessionImpl.fireLoad(SessionImpl.java:878)
    at org.hibernate.impl.SessionImpl.immediateLoad(SessionImpl.java:836)
    at org.hibernate.proxy.AbstractLazyInitializer.initialize(AbstractLazyInitializer.java:66)
    at org.hibernate.proxy.AbstractLazyInitializer.getImplementation(AbstractLazyInitializer.java:111)
    at org.hibernate.proxy.pojo.javassist.JavassistLazyInitializer.invoke(JavassistLazyInitializer.java:166)
    at nl.bedrijf.pojo.Supplier_$$_javassist_1.toString(Supplier_$$_javassist_1.java)
    at java.lang.String.valueOf(String.java:2615)
    at java.lang.StringBuilder.append(StringBuilder.java:116)
    at nl.bedrijf.pojo.Plugin.toString(Plugin.java:85)
    at java.lang.String.valueOf(String.java:2615)
    at java.lang.StringBuilder.append(StringBuilder.java:116)
    at nl.bedrijf.pojo.Person.toString(PluginPerson.java:74)
    at java.lang.String.valueOf(String.java:2615)
    at java.lang.StringBuilder.append(StringBuilder.java:116)
    at nl.bedrijf.ModuleImpl.storePerson(ConnectorModuleImpl.java:1324)
    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:585)
    at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:112)
    at org.jboss.ejb3.interceptor.InvocationContextImpl.proceed(InvocationContextImpl.java:166)
    at org.jboss.ejb3.interceptor.EJB3InterceptorsInterceptor.invoke(EJB3InterceptorsInterceptor.java:63)
    at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:101)
    at org.jboss.ejb3.entity.TransactionScopedEntityManagerInterceptor.invoke(TransactionScopedEntityManagerInterceptor.java:54)
    at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:101)
    at org.jboss.ejb3.AllowedOperationsInterceptor.invoke(AllowedOperationsInterceptor.java:47)
    at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:101)
    at org.jboss.aspects.tx.TxPolicy.invokeInOurTx(TxPolicy.java:79)
    at org.jboss.aspects.tx.TxInterceptor$RequiresNew.invoke(TxInterceptor.java:262)
    at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:101)
    at org.jboss.aspects.tx.TxPropagationInterceptor.invoke(TxPropagationInterceptor.java:76)
    at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:101)
    at org.jboss.ejb3.stateless.StatelessInstanceInterceptor.invoke(StatelessInstanceInterceptor.java:62)
    at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:101)
    at org.jboss.aspects.security.AuthenticationInterceptor.invoke(AuthenticationInterceptor.java:77)
    at org.jboss.ejb3.security.Ejb3AuthenticationInterceptor.invoke(Ejb3AuthenticationInterceptor.java:106)
    at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:101)
    at org.jboss.ejb3.ENCPropagationInterceptor.invoke(ENCPropagationInterceptor.java:46)
    at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:101)
    at org.jboss.ejb3.asynchronous.AsynchronousInterceptor.invoke(AsynchronousInterceptor.java:106)
    at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:101)
    at org.jboss.wsf.container.jboss42.InvocationHandlerEJB3.invoke(InvocationHandlerEJB3.java:103)
    at org.jboss.ws.core.server.ServiceEndpointInvoker.invoke(ServiceEndpointInvoker.java:220)
    at org.jboss.wsf.stack.jbws.RequestHandlerImpl.processRequest(RequestHandlerImpl.java:408)
    at org.jboss.wsf.stack.jbws.RequestHandlerImpl.handleRequest(RequestHandlerImpl.java:272)
    at org.jboss.wsf.stack.jbws.RequestHandlerImpl.doPost(RequestHandlerImpl.java:189)
    at org.jboss.wsf.stack.jbws.RequestHandlerImpl.handleHttpRequest(RequestHandlerImpl.java:122)
    at org.jboss.wsf.stack.jbws.EndpointServlet.service(EndpointServlet.java:84)
    at javax.servlet.http.HttpServlet.service(HttpServlet.java:803)
    at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:290)
    at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
    at org.jboss.web.tomcat.filters.ReplyHeaderFilter.doFilter(ReplyHeaderFilter.java:96)
    at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:235)
    at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
    at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:230)
    at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:175)
    at org.jboss.web.tomcat.security.SecurityAssociationValve.invoke(SecurityAssociationValve.java:179)
    at org.jboss.web.tomcat.security.JaccContextValve.invoke(JaccContextValve.java:84)
    at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:128)
    at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:104)
    at org.jboss.web.tomcat.service.jca.CachedConnectionValve.invoke(CachedConnectionValve.java:157)
    at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:109)
    at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:241)
    at org.apache.coyote.http11.Http11Processor.process(Http11Processor.java:844)
    at org.apache.coyote.http11.Http11Protocol$Http11ConnectionHandler.process(Http11Protocol.java:580)
    at org.apache.tomcat.util.net.JIoEndpoint$Worker.run(JIoEndpoint.java:447)
    at java.lang.Thread.run(Thread.java:595)
Caused by: org.jboss.util.NestedSQLException: Transaction is not active: tx=TransactionImple < ac, BasicAction: -3f579720:a198:477b9149:17d status: ActionStatus.ABORT_ONLY >; - nested throwable: (javax.resource.ResourceException: Transaction is not active: tx=TransactionImple < ac, BasicAction: -3f579720:a198:477b9149:17d status: ActionStatus.ABORT_ONLY >)
    at org.jboss.resource.adapter.jdbc.WrapperDataSource.getConnection(WrapperDataSource.java:94)
    at org.hibernate.ejb.connection.InjectedDataSourceConnectionProvider.getConnection(InjectedDataSourceConnectionProvider.java:47)
    at org.hibernate.jdbc.ConnectionManager.openConnection(ConnectionManager.java:423)
    ... 80 more
Caused by: javax.resource.ResourceException: Transaction is not active: tx=TransactionImple < ac, BasicAction: -3f579720:a198:477b9149:17d status: ActionStatus.ABORT_ONLY >
    at org.jboss.resource.connectionmanager.TxConnectionManager.getManagedConnection(TxConnectionManager.java:304)
    at org.jboss.resource.connectionmanager.BaseConnectionManager2.allocateConnection(BaseConnectionManager2.java:396)
    at org.jboss.resource.connectionmanager.BaseConnectionManager2$ConnectionManagerProxy.allocateConnection(BaseConnectionManager2.java:842)
    at org.jboss.resource.adapter.jdbc.WrapperDataSource.getConnection(WrapperDataSource.java:88)
    ... 82 more

Wat ik zelf al bedacht heb:

- De applicatieserver is JBoss 4.2.1 en die gebruikt commons-logging als logfabriek en Log4j als logimplementatie. Ik heb Log4J configuratie bekeken, maar kon ik niets vinden wat het afkappen van de stacktrace zou kunnen beïnvloeden.
- Google op java jboss stacktrace truncation "cut off" "caused by" of permutaties daarvan leverde niets op. Vreemd, ik ben toch niet de eerste die hier tegenaan loopt.

Weet iemand hoe je kun voorkomen dat de stacktrace ingekort wordt?

[-FoX-]

De stacktrace is wel aanwezig, maar deze wordt afgekapt door de printStacktrace methode. Je zou gebruik kunnen maken van de commons-lang ExceptionUtils.getFullStackTrace(); methode om ervoor te zorgen dat de volledige stacktrace geprint wordt. Er zijn in deze class ook nog een aantal andere handige methodes.

[Confusion]

ari3 schreef op donderdag 03 januari 2008 @ 09:55:
Ik ben een J2EE applicatie aan het debuggen op JBoss en ik loop vaak tegen het probleem aan dat als een transactie afgebroken wordt, de reden voor het afbreken niet eenvoudig kan worden achterhaald omdat de stacktrace ongewild ingekort wordt.

Staat de oorzaak van de exceptie dan weleens in de 'weggelaten' stacktrace? In dit geval zou het dan achter "org.jboss.resource.adapter.jdbc.WrapperDataSource" zitten, wat een bug in een JBoss component zelf zou zijn. Nu is dat natuurlijk mogelijk, maar iets als 'transaction is not active' is eigenlijk altijd een fout van jezelf, op applicatie niveau. Daar heb je de rest van de stacktrace niet voor nodig; dat levert geen informatie op waarmee je de oorzaak kan achterhalen. (Tenzij dieper in de stacktrace nog eigen code, die daar via DI ofzo terecht is gekomen, wordt aangesproken natuurlijk).

[ Voor 6% gewijzigd door Confusion op 03-01-2008 10:33 ]

[Verwijderd]

Die verdomde Thread.run() ook altijd!

[Kwistnix]

Aangaande de GenericJDBCException, waarschijnlijk wordt het probleem veroorzaakt door een brakke Hibernate configuratie of JDBC driver. Verdere details over de call stack zullen daar geen verhelderende informatie over verschaffen.

[Verwijderd]

Meestal wil je gewoon de meest hoge eigen functie zien, in dit geval:
nl.bedrijf.pojo.Supplier_$$_javassist_1.toString(Supplier_$$_javassist_1.java)

en omdat daar niet echt een regelnummer bij staat eventueel de tweede:
nl.bedrijf.pojo.Plugin.toString(Plugin.java:85)

Als je daar niet verder mee komt, kan de fout inderdaad al eerder opgetreden zijn, maar het ligt dan misschien ook gewoon aan configuratie/installatie-fout (zoals de post boven mij aangeeft).
Anders kun je wellicht het e.e.a. unit testen en/of er met de debugger doorheen.

Het allerhoogste, en meest verste van je fout af liggende, is datgene wat je Thread gestart heeft. Zie ook comment van Mark Platvoet.

[ Voor 25% gewijzigd door Verwijderd op 03-01-2008 18:33 ]