[J2EE/JBoss] Transactie timeout

[JKVA]

Op mijn project (JSF 1.1/Hibernate 3.2.2/JBoss 4.0.3/Oracle 10i) hebben we momenteel een probleem.

Het doet zich voor als een zoekopdracht op een back-end systeem heel traag is (hoeft niet per se back end te zijn, trage Hibernate query kan ook) en een Timeout optreedt. Op dat moment crasht de applicatie. Dat is vrij normaal.

Alleen de manier waarop is vervelend. Als in namelijk opnieuw de applicatie open en een pagina open, krijg ik ook foutmeldingen, welke voortkomen uit het feit dat er geen connectie geopend kan worden.

De stack trace:

code:

2007-06-05 12:26:12,576 DEBUG [org.hibernate.event.def.DefaultAutoFlushEventListener] Dont need to execute flush
2007-06-05 12:26:12,576 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to open PreparedStatement (open PreparedStatements: 14, globally: 14)
2007-06-05 12:26:12,576 DEBUG [org.hibernate.jdbc.ConnectionManager] opening JDBC connection
2007-06-05 12:26:12,576 DEBUG [org.hibernate.util.JDBCExceptionReporter] Cannot open connection [???]
org.jboss.util.NestedSQLException: Transaction is not active: tx=TransactionImpl:XidImpl[FormatId=257, GlobalId=DB005123/32, BranchQual=, localId=32]; - nested throwable: (javax.resource.ResourceException: Transaction is not active: tx=TransactionImpl:XidImpl[FormatId=257, GlobalId=DB005123/32, BranchQual=, localId=32])
    at org.jboss.resource.adapter.jdbc.WrapperDataSource.getConnection(WrapperDataSource.java:79)
    at org.hibernate.connection.DatasourceConnectionProvider.getConnection(DatasourceConnectionProvider.java:69)
    at org.hibernate.jdbc.ConnectionManager.openConnection(ConnectionManager.java:421)
    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:1538)
    at org.hibernate.loader.Loader.doQuery(Loader.java:661)
    at org.hibernate.loader.Loader.doQueryAndInitializeNonLazyCollections(Loader.java:224)
    at org.hibernate.loader.Loader.doList(Loader.java:2211)
    at org.hibernate.loader.Loader.listIgnoreQueryCache(Loader.java:2095)
    at org.hibernate.loader.Loader.list(Loader.java:2090)
    at org.hibernate.loader.criteria.CriteriaLoader.list(CriteriaLoader.java:94)
    at org.hibernate.impl.SessionImpl.list(SessionImpl.java:1569)
    at org.hibernate.impl.CriteriaImpl.list(CriteriaImpl.java:283)
    at ...
    at ...
    at ...
    at ...
    at sun.reflect.GeneratedMethodAccessor374.invoke(Unknown Source)
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
    at java.lang.reflect.Method.invoke(Method.java:585)
    at org.apache.myfaces.el.PropertyResolverImpl.getProperty(PropertyResolverImpl.java:400)
    at org.apache.myfaces.el.PropertyResolverImpl.getValue(PropertyResolverImpl.java:71)
    at com.sun.facelets.el.LegacyELContext$LegacyELResolver.getValue(LegacyELContext.java:141)
    at com.sun.el.parser.AstValue.getValue(AstValue.java:117)
    at com.sun.el.ValueExpressionImpl.getValue(ValueExpressionImpl.java:192)
    at com.sun.facelets.el.TagValueExpression.getValue(TagValueExpression.java:71)
    at com.sun.facelets.el.LegacyValueBinding.getValue(LegacyValueBinding.java:56)
    at org.apache.myfaces.trinidad.bean.FacesBeanImpl.getProperty(FacesBeanImpl.java:68)
    at org.apache.myfaces.trinidad.component.UIXComponentBase.getProperty(UIXComponentBase.java:1116)
    at org.apache.myfaces.trinidad.component.UIXIterator.getValue(UIXIterator.java:397)
    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 com.sun.facelets.util.DevTools.writeAttributes(DevTools.java:240)
    at com.sun.facelets.util.DevTools.writeStart(DevTools.java:284)
    at com.sun.facelets.util.DevTools.writeComponent(DevTools.java:189)
    at com.sun.facelets.util.DevTools.writeComponent(DevTools.java:207)
    at com.sun.facelets.util.DevTools.writeComponent(DevTools.java:207)
    at com.sun.facelets.util.DevTools.writeComponent(DevTools.java:207)
    at com.sun.facelets.util.DevTools.debugHtml(DevTools.java:107)
    at com.sun.facelets.FaceletViewHandler.handleRenderException(FaceletViewHandler.java:677)
    at com.sun.facelets.FaceletViewHandler.renderView(FaceletViewHandler.java:646)
    at org.apache.myfaces.trinidadinternal.application.ViewHandlerImpl.renderView(ViewHandlerImpl.java:182)
    at ...
    at org.apache.myfaces.lifecycle.LifecycleImpl.render(LifecycleImpl.java:300)
    at javax.faces.webapp.FacesServlet.service(FacesServlet.java:95)
    at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:252)
    at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:173)
    at ...
    at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:202)
    at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:173)
    at org.apache.myfaces.trinidadinternal.webapp.TrinidadFilterImpl._invokeDoFilter(TrinidadFilterImpl.java:210)
    at org.apache.myfaces.trinidadinternal.webapp.TrinidadFilterImpl._doFilterImpl(TrinidadFilterImpl.java:167)
    at org.apache.myfaces.trinidadinternal.webapp.TrinidadFilterImpl.doFilter(TrinidadFilterImpl.java:140)
    at org.apache.myfaces.trinidad.webapp.TrinidadFilter.doFilter(TrinidadFilter.java:93)
    at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:202)
    at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:173)
    at org.jboss.web.tomcat.filters.ReplyHeaderFilter.doFilter(ReplyHeaderFilter.java:81)
    at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:202)
    at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:173)
    at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:213)
    at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:178)
    at org.jboss.web.tomcat.security.CustomPrincipalValve.invoke(CustomPrincipalValve.java:39)
    at org.jboss.web.tomcat.security.SecurityAssociationValve.invoke(SecurityAssociationValve.java:159)
    at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:482)
    at org.jboss.web.tomcat.security.JaccContextValve.invoke(JaccContextValve.java:59)
    at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:126)
    at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:105)
    at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:107)
    at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:148)
    at org.apache.coyote.http11.Http11Processor.process(Http11Processor.java:856)
    at org.apache.coyote.http11.Http11Protocol$Http11ConnectionHandler.processConnection(Http11Protocol.java:744)
    at org.apache.tomcat.util.net.PoolTcpEndpoint.processSocket(PoolTcpEndpoint.java:527)
    at org.apache.tomcat.util.net.MasterSlaveWorkerThread.run(MasterSlaveWorkerThread.java:112)
    at java.lang.Thread.run(Thread.java:595)
Caused by: javax.resource.ResourceException: Transaction is not active: tx=TransactionImpl:XidImpl[FormatId=257, GlobalId=DB005123/32, BranchQual=, localId=32]
    at org.jboss.resource.connectionmanager.TxConnectionManager.getManagedConnection(TxConnectionManager.java:331)
    at org.jboss.resource.connectionmanager.BaseConnectionManager2.allocateConnection(BaseConnectionManager2.java:462)
    at org.jboss.resource.connectionmanager.BaseConnectionManager2$ConnectionManagerProxy.allocateConnection(BaseConnectionManager2.java:894)
    at org.jboss.resource.adapter.jdbc.WrapperDataSource.getConnection(WrapperDataSource.java:73)
    ... 76 more
2007-06-05 12:26:12,576 WARN  [org.hibernate.util.JDBCExceptionReporter] SQL Error: 0, SQLState: null
2007-06-05 12:26:12,576 ERROR [org.hibernate.util.JDBCExceptionReporter] Transaction is not active: tx=TransactionImpl:XidImpl[FormatId=257, GlobalId=DB005123/32, BranchQual=, localId=32]; - nested throwable: (javax.resource.ResourceException: Transaction is not active: tx=TransactionImpl:XidImpl[FormatId=257, GlobalId=DB005123/32, BranchQual=, localId=32])
2007-06-05 12:26:12,623 DEBUG [org.hibernate.impl.SessionImpl] closing session
2007-06-05 12:26:12,623 DEBUG [org.hibernate.jdbc.ConnectionManager] connection already null in cleanup : no action

Momenteel test ik de timeout door een breakpoint te zetten en wat opvalt is het volgende. Terwijl het breakpoint aan staat, krijg ik deze melding op de console:

code:

2007-06-05 12:12:41,790 WARN  [org.jboss.tm.TransactionImpl] Transaction TransactionImpl:XidImpl[FormatId=257, GlobalId=DB005123/32, BranchQual=, localId=32] timed out. status=STATUS_ACTIVE

Als ik dan verder step, merk ik dat er geen exception gegooid wordt (wat ik zou verwachten), maar dat de daaropvolgende code wordt aangeroepen. Op een gegeven moment komt er een criteria.list() en dan volgt er pas een Exception omdat Hibernate geen connection kan bemachtigen.

Op het moment dat deze fout is opgetreden, kan ik niets meer met de applicatie. Ik moet ofwel JBoss opnieuw opstarten, ofwel een tijd wachten (tot de timeout tijd is verstreken ofzo) tot ik weer verder kan werken.

Het lijkt wel of Hibernate de transactie open laat staan op de connectie, waardoor hij deze niet meer terug kan vragen.

Overigens gebruiken we een ServletFilter om exceptions af te vangen en een eventuele rollback uit te voeren.

Java:

    public void doFilter(ServletRequest req, ServletResponse res, FilterChain chain) throws IOException, ServletException {
        try {
            HibernateUtil.beginTransaction();

            chain.doFilter(req, res);
            HibernateUtil.commitTransaction();
        } catch (Throwable t) {
            HibernateUtil.rollbackTransaction();
            throw new ServletException(t);
        } finally {
            HibernateUtil.closeSession();
        }
    }

Iemand een idee?

[Verwijderd]

Het is een gok maar het klinkt alsof bepaalde onderdelen geserialiseerd worden en dat je daar dus last van hebt. Al eens geprobeerd om alle diskcaches leeg te gooien en dan direct weer op te starten?

[JKVA]

Verwijderd schreef op dinsdag 05 juni 2007 @ 13:21:
Het is een gok maar het klinkt alsof bepaalde onderdelen geserialiseerd worden en dat je daar dus last van hebt. Al eens geprobeerd om alle diskcaches leeg te gooien en dan direct weer op te starten?

Ik snap deze even niet. Doel je op geserialiseerde Hibernate Managed objecten?

[Verwijderd]

JKVA schreef op dinsdag 05 juni 2007 @ 14:11:
Ik snap deze even niet. Doel je op geserialiseerde Hibernate Managed objecten?

Ik doel eigenlijk op alles wat maar geserialiseerd kan worden, waaronder dus misschien Hibernate Managed objecten. Er lijkt transactie state te worden bewaard en dit leek me de eerste makkelijke stap.

[JKVA]

Het is opgelost. Niet allemaal mij gaan uitlachen, maar het was gewoon een domme programmeerfout.

Check deze gedownloade HibernateUtil:

Java:

    public static void rollbackTransaction() throws InfrastructureException {
        Transaction tx = (Transaction) THREADTRANSACTION.get();
        try {
            THREADTRANSACTION.set(null);
            if (tx != null && tx.isActive()) {
                log.debug("Tyring to rollback database transaction of this thread.");
                tx.rollback();
            }
        } catch (HibernateException ex) {
            throw new InfrastructureException(ex);
        } finally {
            closeSession();
        }
    }

Let vooral op de isactive. En deze jongen had bij het steppen geen enkele keer door dat er niet gerollbacked (is dat een woord?) werd.

De werkende code is dus:

Java:

    public static void rollbackTransaction() throws InfrastructureException {
        Transaction tx = (Transaction) THREADTRANSACTION.get();
        try {
            THREADTRANSACTION.set(null);
            if (tx != null) {
                log.debug("Tyring to rollback database transaction of this thread.");
                tx.rollback();
            }
        } catch (HibernateException ex) {
            throw new InfrastructureException(ex);
        } finally {
            closeSession();
        }
    }

[ Voor 24% gewijzigd door JKVA op 08-06-2007 08:01 ]