8 Replies Latest reply on Jun 12, 2007 6:02 AM by tom.baeyens

    possible bug with JTA transactions

    camunda

      Hi,

      I am not yet sure if it is a bug or a missconfiguration from me. But I am nearly convinced that it is a bug ;-)

      I use the JtaDbPersistenceServiceFactory for pesisting (transactionEnabled=true, currentSessionEnabled=true). Now I trigger a process with a small action, which queries process name from jbpm (and therefor create a own jbpmContext). My testcode:

       private String testProcess = "<process-definition name='Test'>"
       + "<start-state name='startState'>"
       + " <transition name='startTransactionTest' to='end'>"
       + " <action name='test' class='com.camunda.ccs.process.test.ExecuteJbpmCommand'/>"
       + " </transition>"
       + "</start-state>"
       + "<end-state name='end'/>"
       + "</process-definition>";
      
       public void testHibernateSession() {
       // deploy process
       DeployProcessCommand deployCmd = new DeployProcessCommand();
       deployCmd.setXml( testProcess );
       Tk4jbpmConfiguration.getCommandService().execute(deployCmd);
      
       // now start it
       StartProcessInstanceCommand cmd = new StartProcessInstanceCommand();
       cmd.setProcessName("test");
       ProcessInstance pi = (ProcessInstance) Tk4jbpmConfiguration.getCommandService().execute(cmd);
      
       // process is ended
       assertNotNull(pi.getEnd());
       }
      

      (The Tk4jbpmConfiguration.getCommandService() just gets a reference to a EJB-3-ServiceBean, which runs the execute in TransactionAttributeType.REQUIRED).

      The aciton is very easy:
      public class ExecuteJbpmCommand implements ActionHandler {
       public void execute(ExecutionContext ctx) throws Exception {
       GetProcessDefinitionCommand cmd = new GetProcessDefinitionCommand();
       Tk4jbpmConfiguration.getCommandService().execute(cmd);
       }
      }
      


      Now I get the following problem: The first context starts a transaction (and gets the current user transaction from hibrnate). The second jbpmContext get the same transaction. But it commits & closes it at the end (the commit has of xourse no effect on the JTA-Transaction, but the begun marker of the hibernate JTATransaction is set to false!). After that, we get a Exception while closing the JTATransaction the second time. If we ignore it, everything seems to work fine.

      You can also see that in the logs:


      DEBUG [org.jbpm.JbpmContext] creating org.jbpm.JbpmContext@27e905
      DEBUG [com.camunda.toolkit.jbpm.service.CommandServiceBean] executing org.jbpm.command.StartProcessInstanceCommand@336f59...
      DEBUG [org.jbpm.persistence.db.DbPersistenceService] using current hibernate session SessionImpl(...)
      DEBUG [org.jbpm.persistence.db.DbPersistenceService] beginning hibernate transaction
      DEBUG [org.hibernate.transaction.JTATransaction] Looking for UserTransaction under: UserTransaction
      DEBUG [org.hibernate.transaction.JTATransaction] Obtained UserTransaction
      DEBUG [org.hibernate.transaction.JTATransaction] begin
      DEBUG [org.jbpm.persistence.db.DbPersistenceService] begun hibernate transaction org.hibernate.transaction.JTATransaction@d34b8c

      DEBUG [org.jbpm.configuration.JbpmContextInfo] creating jbpm context with service factories '[message, tx, scheduler, authentication, persistence, logging]'
      DEBUG [org.jbpm.JbpmContext] creating org.jbpm.JbpmContext@12f2476
      DEBUG [com.camunda.toolkit.jbpm.service.CommandServiceBean] executing org.jbpm.command.GetProcessDefinitionCommand@2fe28...
      DEBUG [org.jbpm.persistence.db.DbPersistenceService] using current hibernate session SessionImpl(...)
      DEBUG [org.jbpm.persistence.db.DbPersistenceService] beginning hibernate transaction
      DEBUG [org.jbpm.persistence.db.DbPersistenceService] begun hibernate transaction org.hibernate.transaction.JTATransaction@d34b8c
      DEBUG [com.camunda.toolkit.jbpm.service.CommandServiceBean] ... finished with org.jbpm.command.GetProcessDefinitionCommand@2fe28
      DEBUG [org.jbpm.JbpmContext] closing org.jbpm.JbpmContext@12f2476
      DEBUG [org.jbpm.svc.Services] closing service 'persistence': org.jbpm.persistence.jta.JtaDbPersistenceService@1d6c90d
      DEBUG [org.jbpm.persistence.db.DbPersistenceService] committing hibernate transaction org.hibernate.transaction.JTATransaction@d34b8c
      DEBUG [org.hibernate.transaction.JTATransaction] commit

      DEBUG [com.camunda.toolkit.jbpm.service.CommandServiceBean] ... finished with org.jbpm.command.StartProcessInstanceCommand@336f59
      DEBUG [org.jbpm.JbpmContext] closing org.jbpm.JbpmContext@27e905
      DEBUG [org.jbpm.svc.Services] closing service 'persistence': org.jbpm.persistence.jta.JtaDbPersistenceService@383c13
      DEBUG [org.jbpm.persistence.db.DbPersistenceService] committing hibernate transaction org.hibernate.transaction.JTATransaction@d34b8c
      ERROR [org.jbpm.persistence.db.DbPersistenceService] hibernate commit failed
      org.hibernate.TransactionException: Transaction not successfully started
      at org.hibernate.transaction.JTATransaction.commit(JTATransaction.java:126)
      at org.jbpm.persistence.db.DbPersistenceService.commit(DbPersistenceService.java:255)
      at org.jbpm.persistence.db.DbPersistenceService.close(DbPersistenceService.java:213)
      at org.jbpm.persistence.jta.JtaDbPersistenceService.close(JtaDbPersistenceService.java:34)
      at org.jbpm.svc.Services.close(Services.java:222)
      at org.jbpm.JbpmContext.close(JbpmContext.java:139)
      at com.camunda.toolkit.jbpm.service.CommandServiceBean.execute(CommandServiceBean.java:91)


      Now, what is the right way to handle it? I am not completly sure at this point...

      Any remarks?

        • 1. Re: possible bug with JTA transactions
          camunda

          I am also a bit puzzled about the following exception, if there are logs to save after a Signal. But why is not the correct current JTATransaction used here? (sorry, I didn't get a exact test case yet)


          ERROR

          com.camunda.toolkit.jbpm.service.CommandServiceBean

          could not close jbpm context after command org.jbpm.command.SignalCommand

          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.prepareStatement(AbstractBatcher.java:94)
          at org.hibernate.id.IdentityGenerator$GetGeneratedKeysDelegate.prepare(IdentityGenerator.java:69)
          at org.hibernate.id.insert.AbstractReturningDelegate.performInsert(AbstractReturningDelegate.java:30)
          at org.hibernate.persister.entity.AbstractEntityPersister.insert(AbstractEntityPersister.java:2158)
          at org.hibernate.persister.entity.AbstractEntityPersister.insert(AbstractEntityPersister.java:2638)
          at org.hibernate.action.EntityIdentityInsertAction.execute(EntityIdentityInsertAction.java:48)
          at org.hibernate.engine.ActionQueue.execute(ActionQueue.java:248)
          at org.hibernate.event.def.AbstractSaveEventListener.performSaveOrReplicate(AbstractSaveEventListener.java:298)
          at org.hibernate.event.def.AbstractSaveEventListener.performSave(AbstractSaveEventListener.java:181)
          at org.hibernate.event.def.AbstractSaveEventListener.saveWithGeneratedId(AbstractSaveEventListener.java:107)
          at org.hibernate.event.def.DefaultSaveOrUpdateEventListener.saveWithGeneratedOrRequestedId(DefaultSaveOrUpdateEventListener.java:187)
          at org.hibernate.event.def.DefaultSaveEventListener.saveWithGeneratedOrRequestedId(DefaultSaveEventListener.java:33)
          at org.hibernate.event.def.DefaultSaveOrUpdateEventListener.entityIsTransient(DefaultSaveOrUpdateEventListener.java:172)
          at org.hibernate.event.def.DefaultSaveEventListener.performSaveOrUpdate(DefaultSaveEventListener.java:27)
          at org.hibernate.event.def.DefaultSaveOrUpdateEventListener.onSaveOrUpdate(DefaultSaveOrUpdateEventListener.java:70)
          at org.hibernate.impl.SessionImpl.fireSave(SessionImpl.java:535)
          at org.hibernate.impl.SessionImpl.save(SessionImpl.java:523)
          at org.hibernate.impl.SessionImpl.save(SessionImpl.java:519)
          at org.jbpm.logging.db.DbLoggingService.log(DbLoggingService.java:57)
          at org.jbpm.svc.save.SaveLogsOperation.save(SaveLogsOperation.java:47)
          at org.jbpm.svc.Services.save(Services.java:161)
          at org.jbpm.JbpmContext.save(JbpmContext.java:427)
          at org.jbpm.JbpmContext.autoSave(JbpmContext.java:620)
          at org.jbpm.JbpmContext.close(JbpmContext.java:137)
          at com.camunda.toolkit.jbpm.service.CommandServiceBean.execute(CommandServiceBean.java:90)
          ...

          Caused by: org.jboss.util.NestedSQLException: Transaction is not active: tx=TransactionImpl:XidImpl[FormatId=257, GlobalId=titan.computation.de/494320, BranchQual=, localId=494320]; - nested throwable: (javax.resource.ResourceException: Transaction is not active: tx=TransactionImpl:XidImpl[FormatId=257, GlobalId=titan.computation.de/494320, BranchQual=, localId=494320])
          at org.jboss.resource.adapter.jdbc.WrapperDataSource.getConnection(WrapperDataSource.java:94)
          at org.hibernate.connection.DatasourceConnectionProvider.getConnection(DatasourceConnectionProvider.java:69)
          at org.hibernate.jdbc.ConnectionManager.openConnection(ConnectionManager.java:423)
          ... 61 more

          Caused by: javax.resource.ResourceException: Transaction is not active: tx=TransactionImpl:XidImpl[FormatId=257, GlobalId=titan.computation.de/494320, BranchQual=, localId=494320]
          at org.jboss.resource.connectionmanager.TxConnectionManager.getManagedConnection(TxConnectionManager.java:290)
          at org.jboss.resource.connectionmanager.BaseConnectionManager2.allocateConnection(BaseConnectionManager2.java:379)
          at org.jboss.resource.connectionmanager.BaseConnectionManager2$ConnectionManagerProxy.allocateConnection(BaseConnectionManager2.java:812)
          at org.jboss.resource.adapter.jdbc.WrapperDataSource.getConnection(WrapperDataSource.java:88)
          ... 63 more


          • 2. Re: possible bug with JTA transactions
            tom.baeyens

            did you use the exact same configuration as in the .ear file in the deploy directory ?

            • 3. Re: possible bug with JTA transactions
              camunda

              Hi Tom,

              of course not :-) But the jbpm.cfg.xml is the same, yes. So the critical points, the transactions configuration, is exactly the same. Important is to start a second jbpmContext inside a action (so a "nested" jbpmContext) to reporudce the first error I described.

              Maybe it depends on the hibernate version if you can not reporduce it? Maybe they have changed the commit() method, but sounds strange to me....

              • 4. Re: possible bug with JTA transactions
                tom.baeyens

                the JtaDbPersistenceServiceFactory was developed rather specifically for 2 use cases. It should support the enterprise beans CMT transactions and it should also support the web application with the same configuration. The web application uses hibernate transactions.

                Took me quite a while to get that combination to work. So I'm not sure of wether this is a problem due to the specific nature of this persistence service factory and hence that the nested transactions are just is out of scope. Or wether this can be easiliy fixed in the context sketched above.

                • 5. Re: possible bug with JTA transactions
                  camunda

                   

                  and hence that the nested transactions are just is out of scope

                  Hi Tom,
                  sorry, I didn't get the point what you wanted to say with that.

                  Ok, I can configure the PersistenceServoiceFactory NOT to use transactions, that should omit the exception and also work in our managed environment (CMT), but even then it is still not solved in jbpm itself.

                  And the second exception with the Logging still appears then by the way...

                  • 6. Re: possible bug with JTA transactions
                    camunda

                    Okay, I changed it now to not use transactions.

                    But still I get this exceptions and some logs are missing afterwords:


                    2007-06-06 14:51:28,443 WARN [org.hibernate.util.JDBCExceptionReporter] SQL Error: 0, SQLState: null
                    2007-06-06 14:51:28,456 ERROR [org.hibernate.util.JDBCExceptionReporter] Transaction is not active: tx=TransactionImpl:XidImpl[FormatId=257, GlobalId=titan.computation.de/12
                    931, BranchQual=, localId=12931]; - nested throwable: (javax.resource.ResourceException: Transaction is not active: tx=TransactionImpl:XidImpl[FormatId=257, GlobalId=titan.c
                    omputation.de/12931, BranchQual=, localId=12931])
                    2007-06-06 14:51:28,734 ERROR [com.camunda.toolkit.jbpm.service.CommandServiceBean] could not close jbpm context after command org.jbpm.command.SignalCommand
                    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.prepareStatement(AbstractBatcher.java:94)
                     at org.hibernate.id.IdentityGenerator$GetGeneratedKeysDelegate.prepare(IdentityGenerator.java:69)
                     at org.hibernate.id.insert.AbstractReturningDelegate.performInsert(AbstractReturningDelegate.java:30)
                     at org.hibernate.persister.entity.AbstractEntityPersister.insert(AbstractEntityPersister.java:2158)
                     at org.hibernate.persister.entity.AbstractEntityPersister.insert(AbstractEntityPersister.java:2638)
                     at org.hibernate.action.EntityIdentityInsertAction.execute(EntityIdentityInsertAction.java:48)
                     at org.hibernate.engine.ActionQueue.execute(ActionQueue.java:248)
                     at org.hibernate.event.def.AbstractSaveEventListener.performSaveOrReplicate(AbstractSaveEventListener.java:298)
                     at org.hibernate.event.def.AbstractSaveEventListener.performSave(AbstractSaveEventListener.java:181)
                     at org.hibernate.event.def.AbstractSaveEventListener.saveWithGeneratedId(AbstractSaveEventListener.java:107)
                     at org.hibernate.event.def.DefaultSaveOrUpdateEventListener.saveWithGeneratedOrRequestedId(DefaultSaveOrUpdateEventListener.java:187)
                     at org.hibernate.event.def.DefaultSaveEventListener.saveWithGeneratedOrRequestedId(DefaultSaveEventListener.java:33)
                     at org.hibernate.event.def.DefaultSaveOrUpdateEventListener.entityIsTransient(DefaultSaveOrUpdateEventListener.java:172)
                     at org.hibernate.event.def.DefaultSaveEventListener.performSaveOrUpdate(DefaultSaveEventListener.java:27)
                     at org.hibernate.event.def.DefaultSaveOrUpdateEventListener.onSaveOrUpdate(DefaultSaveOrUpdateEventListener.java:70)
                     at org.hibernate.impl.SessionImpl.fireSave(SessionImpl.java:535)
                     at org.hibernate.impl.SessionImpl.save(SessionImpl.java:523)
                     at org.hibernate.impl.SessionImpl.save(SessionImpl.java:519)
                     at org.jbpm.logging.db.DbLoggingService.log(DbLoggingService.java:57)
                     at org.jbpm.svc.save.SaveLogsOperation.save(SaveLogsOperation.java:47)
                     at org.jbpm.svc.Services.save(Services.java:161)
                     at org.jbpm.JbpmContext.save(JbpmContext.java:427)
                     at org.jbpm.JbpmContext.autoSave(JbpmContext.java:620)
                     at org.jbpm.JbpmContext.close(JbpmContext.java:137)
                     at com.camunda.toolkit.jbpm.service.CommandServiceBean.execute(CommandServiceBean.java:93)
                     at sun.reflect.GeneratedMethodAccessor667.invoke(Unknown Source)
                     at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
                     at java.lang.reflect.Method.invoke(Method.java:597)
                     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$Required.invoke(TxInterceptor.java:197)
                     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.RoleBasedAuthorizationInterceptor.invoke(RoleBasedAuthorizationInterceptor.java:167)
                     at org.jboss.ejb3.security.RoleBasedAuthorizationInterceptor.invoke(RoleBasedAuthorizationInterceptor.java:100)
                     at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:101)
                     at org.jboss.aspects.security.AuthenticationInterceptor.invoke(AuthenticationInterceptor.java:78)
                     at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:101)
                     at org.jboss.ejb3.ENCPropagationInterceptor.invoke(ENCPropagationInterceptor.java:47)
                     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.ejb3.stateless.StatelessContainer.dynamicInvoke(StatelessContainer.java:225)
                     at org.jboss.aop.Dispatcher.invoke(Dispatcher.java:106)
                     at org.jboss.aspects.remoting.AOPRemotingInvocationHandler.invoke(AOPRemotingInvocationHandler.java:82)
                     at org.jboss.remoting.ServerInvoker.invoke(ServerInvoker.java:828)
                     at org.jboss.remoting.ServerInvoker.invoke(ServerInvoker.java:681)
                     at org.jboss.remoting.transport.socket.ServerThread.processInvocation(ServerThread.java:358)
                     at org.jboss.remoting.transport.socket.ServerThread.dorun(ServerThread.java:412)
                     at org.jboss.remoting.transport.socket.ServerThread.run(ServerThread.java:239)
                    Caused by: org.jboss.util.NestedSQLException: Transaction is not active: tx=TransactionImpl:XidImpl[FormatId=257, GlobalId=titan.computation.de/12931, BranchQual=, localId=1
                    2931]; - nested throwable: (javax.resource.ResourceException: Transaction is not active: tx=TransactionImpl:XidImpl[FormatId=257, GlobalId=titan.computation.de/12931, Branch
                    Qual=, localId=12931])
                     at org.jboss.resource.adapter.jdbc.WrapperDataSource.getConnection(WrapperDataSource.java:94)
                     at org.hibernate.connection.DatasourceConnectionProvider.getConnection(DatasourceConnectionProvider.java:69)
                     at org.hibernate.jdbc.ConnectionManager.openConnection(ConnectionManager.java:423)
                     ... 61 more
                    Caused by: javax.resource.ResourceException: Transaction is not active: tx=TransactionImpl:XidImpl[FormatId=257, GlobalId=titan.computation.de/12931, BranchQual=, localId=12
                    931]
                     at org.jboss.resource.connectionmanager.TxConnectionManager.getManagedConnection(TxConnectionManager.java:290)
                     at org.jboss.resource.connectionmanager.BaseConnectionManager2.allocateConnection(BaseConnectionManager2.java:379)
                     at org.jboss.resource.connectionmanager.BaseConnectionManager2$ConnectionManagerProxy.allocateConnection(BaseConnectionManager2.java:812)
                     at org.jboss.resource.adapter.jdbc.WrapperDataSource.getConnection(WrapperDataSource.java:88)
                     ... 63 more
                    


                    This at least seems to be a bug in JTA transaction management, or?

                    • 7. Re: possible bug with JTA transactions
                      camunda

                      Sorry Tom for disturbing again, but it is still not solved our problem. How can we go on now? Any plans to investigate? Or any plans in chaning the persistence configuration?

                      Or is it up to us to go deep into that code?

                      • 8. Re: possible bug with JTA transactions
                        tom.baeyens

                        i have tried to reproduce in the meantime but failed.

                        did you change any of the configurations or packaging ? or did you use the .ear as-is ?

                        how can i reproduce this ?