Activiti causes Exception 'Transaction is not active in the current thread'

[stephan_bauer]

Dear Activiti-Team,

we have a setup with Activiti (5.16.3) inside Glassfish from which it should get its transactions, because of the following transactionManager-configuration in activiti-standalone-context.xml:

   <jee:jndi-lookup jndi-name="java:appserver/TransactionManager" id="transactionManager" />

    <bean id="processEngineConfiguration" class="org.activiti.engine.impl.cfg.JtaProcessEngineConfiguration">
        <!–<property name="dataSource" ref="dataSource" />–>
        <property name="dataSourceJndiName" value="jdbc/activitiDS" />
        <property name="transactionsExternallyManaged" value="true" />
        <property name="transactionManager" ref="transactionManager" />
        <property name="databaseSchemaUpdate" value="true" />
        <property name="jobExecutorActivate" value="true" />
        <property name="enableDatabaseEventLogging" value="true" />
        <property name="history" value="full" />
       
‍‍‍‍‍‍‍‍‍‍‍‍‍‍

Recently, the JobExecutor starts to throw Exceptions like this:

Information:   11 Mrz 2015 11:50:05,092 [Thread-30] DEBUG org.activiti.engine.impl.interceptor.LogInterceptor:40 - — AcquireJobsCmd finished ——————————————————–
Information:   11 Mrz 2015 11:50:05,092 [Thread-30] DEBUG org.activiti.engine.impl.interceptor.LogInterceptor:41 -
Information:   11 Mrz 2015 11:50:05,092 [Thread-30] DEBUG org.activiti.engine.impl.interceptor.LogInterceptor:33 -
Information:   11 Mrz 2015 11:50:05,092 [pool-24-thread-1] DEBUG org.activiti.engine.impl.interceptor.LogInterceptor:33 -
Information:   11 Mrz 2015 11:50:05,092 [Thread-30] DEBUG org.activiti.engine.impl.interceptor.LogInterceptor:34 - — starting AcquireJobsCmd ——————————————————–
Information:   11 Mrz 2015 11:50:05,092 [pool-24-thread-1] DEBUG org.activiti.engine.impl.interceptor.LogInterceptor:34 - — starting ExecuteJobsCmd ——————————————————–
Information:   11 Mrz 2015 11:50:05,092 [Thread-30] DEBUG org.activiti.engine.impl.interceptor.JtaTransactionInterceptor:45 - Running command with propagation REQUIRED
Schwerwiegend:   RAR5029:Unexpected exception while registering component 
java.lang.IllegalStateException: Transaction is not active in the current thread.
   at com.sun.enterprise.transaction.JavaEETransactionImpl.checkTransationActive(JavaEETransactionImpl.java:722)
   at com.sun.enterprise.transaction.JavaEETransactionImpl.enlistResource(JavaEETransactionImpl.java:658)
   at com.sun.enterprise.transaction.JavaEETransactionManagerSimplified.enlistXAResource(JavaEETransactionManagerSimplified.java:1313)
   at com.sun.enterprise.transaction.JavaEETransactionManagerSimplified.enlistResource(JavaEETransactionManagerSimplified.java:371)
   at com.sun.enterprise.resource.rm.ResourceManagerImpl.registerResource(ResourceManagerImpl.java:152)
   at com.sun.enterprise.resource.rm.ResourceManagerImpl.enlistResource(ResourceManagerImpl.java:112)
   at com.sun.enterprise.resource.pool.PoolManagerImpl.getResource(PoolManagerImpl.java:211)
   at com.sun.enterprise.connectors.ConnectionManagerImpl.getResource(ConnectionManagerImpl.java:354)
   at com.sun.enterprise.connectors.ConnectionManagerImpl.internalGetConnection(ConnectionManagerImpl.java:307)
   at com.sun.enterprise.connectors.ConnectionManagerImpl.allocateConnection(ConnectionManagerImpl.java:196)
   at com.sun.enterprise.connectors.ConnectionManagerImpl.allocateConnection(ConnectionManagerImpl.java:171)
   at com.sun.enterprise.connectors.ConnectionManagerImpl.allocateConnection(ConnectionManagerImpl.java:166)
   at com.sun.gjc.spi.base.AbstractDataSource.getConnection(AbstractDataSource.java:114)
   at org.apache.ibatis.transaction.managed.ManagedTransaction.openConnection(ManagedTransaction.java:84)
   at org.apache.ibatis.transaction.managed.ManagedTransaction.getConnection(ManagedTransaction.java:58)
   at org.apache.ibatis.executor.BaseExecutor.getConnection(BaseExecutor.java:271)
   at org.apache.ibatis.executor.SimpleExecutor.prepareStatement(SimpleExecutor.java:69)
   at org.apache.ibatis.executor.SimpleExecutor.doQuery(SimpleExecutor.java:56)
   at org.apache.ibatis.executor.BaseExecutor.queryFromDatabase(BaseExecutor.java:259)
   at org.apache.ibatis.executor.BaseExecutor.query(BaseExecutor.java:132)
   at org.apache.ibatis.executor.CachingExecutor.query(CachingExecutor.java:105)
   at org.apache.ibatis.executor.CachingExecutor.query(CachingExecutor.java:81)
   at org.apache.ibatis.session.defaults.DefaultSqlSession.selectList(DefaultSqlSession.java:104)
   at org.apache.ibatis.session.defaults.DefaultSqlSession.selectList(DefaultSqlSession.java:98)
   at org.apache.ibatis.session.defaults.DefaultSqlSession.selectOne(DefaultSqlSession.java:62)
   at org.activiti.engine.impl.db.DbSqlSession.selectOne(DbSqlSession.java:437)
   at org.activiti.engine.impl.persistence.entity.JobEntityManager.findJobById(JobEntityManager.java:91)
   at org.activiti.engine.impl.cmd.ExecuteJobsCmd.execute(ExecuteJobsCmd.java:59)
   at org.activiti.engine.impl.interceptor.CommandInvoker.execute(CommandInvoker.java:24)
   at org.activiti.engine.impl.interceptor.CommandContextInterceptor.execute(CommandContextInterceptor.java:57)
   at org.activiti.engine.impl.interceptor.JtaTransactionInterceptor.execute(JtaTransactionInterceptor.java:64)
   at org.activiti.engine.impl.interceptor.LogInterceptor.execute(LogInterceptor.java:37)
   at org.activiti.engine.impl.cfg.CommandExecutorImpl.execute(CommandExecutorImpl.java:40)
   at org.activiti.engine.impl.cfg.CommandExecutorImpl.execute(CommandExecutorImpl.java:35)
   at org.activiti.engine.impl.jobexecutor.ExecuteJobsRunnable.run(ExecuteJobsRunnable.java:52)
   at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
   at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
   at java.lang.Thread.run(Thread.java:745)

Warnung:   RAR7132: Unable to enlist the resource in transaction. Returned resource to pool. Pool name: [ NGS-Activiti-ConnectionPool ]
Warnung:   RAR5117 : Failed to obtain/create connection from connection pool [ NGS-Activiti-ConnectionPool ]. Reason : com.sun.appserv.connectors.internal.api.PoolingException: java.lang.IllegalStateException: Transaction is not active in the current thread.
Warnung:   RAR5114 : Error allocating connection : [Error in allocating a connection. Cause: java.lang.IllegalStateException: Transaction is not active in the current thread.]
Information:   11 Mrz 2015 11:50:05,093 [pool-24-thread-1] DEBUG org.activiti.engine.impl.interceptor.JtaTransactionInterceptor:45 - Running command with propagation REQUIRED
Information:   11 Mrz 2015 11:50:05,093 [pool-24-thread-1] DEBUG org.activiti.engine.impl.cmd.ExecuteJobsCmd:56 - Executing job 52553
Information:   11 Mrz 2015 11:50:05,093 [Thread-30] DEBUG org.apache.ibatis.transaction.managed.ManagedTransaction:82 - Opening JDBC Connection
Information:   11 Mrz 2015 11:50:05,093 [pool-24-thread-1] DEBUG org.apache.ibatis.transaction.managed.ManagedTransaction:82 - Opening JDBC Connection
Information:   11 Mrz 2015 11:50:05,093 [Thread-30] DEBUG org.apache.ibatis.logging.jdbc.BaseJdbcLogger:132 - ooo Using Connection [com.sun.gjc.spi.jdbc40.ConnectionWrapper40@18e13c39]
Information:   11 Mrz 2015 11:50:05,093 [Thread-30] DEBUG org.apache.ibatis.logging.jdbc.BaseJdbcLogger:132 - ==>  Preparing: select RES.* from ACT_RU_JOB RES LEFT OUTER JOIN ACT_RU_EXECUTION PI ON PI.ID_ = RES.PROCESS_INSTANCE_ID_ where (RES.RETRIES_ > 0) and (RES.DUEDATE_ is null or RES.DUEDATE_ <= ?) and (RES.LOCK_OWNER_ is null or RES.LOCK_EXP_TIME_ <= ?) and ( (RES.EXECUTION_ID_ is null) or (PI.SUSPENSION_STATE_ = 1) ) LIMIT ? OFFSET ?
Information:   11 Mrz 2015 11:50:05,094 [Thread-30] DEBUG org.apache.ibatis.logging.jdbc.BaseJdbcLogger:132 - ==> Parameters: 2015-03-11 11:50:05.093(Timestamp), 2015-03-11 11:50:05.093(Timestamp), 1(Integer), 0(Integer)
Information:   11 Mrz 2015 11:50:05,095 [pool-24-thread-1] DEBUG org.activiti.engine.impl.interceptor.CommandContext:170 - Error while closing command context
org.apache.ibatis.exceptions.PersistenceException: 
### Error querying database.  Cause: java.sql.SQLException: Error in allocating a connection. Cause: java.lang.IllegalStateException: Transaction is not active in the current thread.
### The error may exist in org/activiti/db/mapping/entity/Job.xml
### The error may involve org.activiti.engine.impl.persistence.entity.JobEntity.selectJob
### The error occurred while executing a query
### Cause: java.sql.SQLException: Error in allocating a connection. Cause: java.lang.IllegalStateException: Transaction is not active in the current thread.
   at org.apache.ibatis.exceptions.ExceptionFactory.wrapException(ExceptionFactory.java:23)
   at org.apache.ibatis.session.defaults.DefaultSqlSession.selectList(DefaultSqlSession.java:107)
   at org.apache.ibatis.session.defaults.DefaultSqlSession.selectList(DefaultSqlSession.java:98)
   at org.apache.ibatis.session.defaults.DefaultSqlSession.selectOne(DefaultSqlSession.java:62)
   at org.activiti.engine.impl.db.DbSqlSession.selectOne(DbSqlSession.java:437)
   at org.activiti.engine.impl.persistence.entity.JobEntityManager.findJobById(JobEntityManager.java:91)
   at org.activiti.engine.impl.cmd.ExecuteJobsCmd.execute(ExecuteJobsCmd.java:59)
   at org.activiti.engine.impl.interceptor.CommandInvoker.execute(CommandInvoker.java:24)
   at org.activiti.engine.impl.interceptor.CommandContextInterceptor.execute(CommandContextInterceptor.java:57)
   at org.activiti.engine.impl.interceptor.JtaTransactionInterceptor.execute(JtaTransactionInterceptor.java:64)
   at org.activiti.engine.impl.interceptor.LogInterceptor.execute(LogInterceptor.java:37)
   at org.activiti.engine.impl.cfg.CommandExecutorImpl.execute(CommandExecutorImpl.java:40)
   at org.activiti.engine.impl.cfg.CommandExecutorImpl.execute(CommandExecutorImpl.java:35)
   at org.activiti.engine.impl.jobexecutor.ExecuteJobsRunnable.run(ExecuteJobsRunnable.java:52)
   at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
   at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
   at java.lang.Thread.run(Thread.java:745)
Caused by: java.sql.SQLException: Error in allocating a connection. Cause: java.lang.IllegalStateException: Transaction is not active in the current thread.
   at com.sun.gjc.spi.base.AbstractDataSource.getConnection(AbstractDataSource.java:121)
   at org.apache.ibatis.transaction.managed.ManagedTransaction.openConnection(ManagedTransaction.java:84)
   at org.apache.ibatis.transaction.managed.ManagedTransaction.getConnection(ManagedTransaction.java:58)
   at org.apache.ibatis.executor.BaseExecutor.getConnection(BaseExecutor.java:271)
   at org.apache.ibatis.executor.SimpleExecutor.prepareStatement(SimpleExecutor.java:69)
   at org.apache.ibatis.executor.SimpleExecutor.doQuery(SimpleExecutor.java:56)
   at org.apache.ibatis.executor.BaseExecutor.queryFromDatabase(BaseExecutor.java:259)
   at org.apache.ibatis.executor.BaseExecutor.query(BaseExecutor.java:132)
   at org.apache.ibatis.executor.CachingExecutor.query(CachingExecutor.java:105)
   at org.apache.ibatis.executor.CachingExecutor.query(CachingExecutor.java:81)
   at org.apache.ibatis.session.defaults.DefaultSqlSession.selectList(DefaultSqlSession.java:104)
   … 15 more
Caused by: javax.resource.spi.ResourceAllocationException: Error in allocating a connection. Cause: java.lang.IllegalStateException: Transaction is not active in the current thread.
   at com.sun.enterprise.connectors.ConnectionManagerImpl.internalGetConnection(ConnectionManagerImpl.java:319)
   at com.sun.enterprise.connectors.ConnectionManagerImpl.allocateConnection(ConnectionManagerImpl.java:196)
   at com.sun.enterprise.connectors.ConnectionManagerImpl.allocateConnection(ConnectionManagerImpl.java:171)
   at com.sun.enterprise.connectors.ConnectionManagerImpl.allocateConnection(ConnectionManagerImpl.java:166)
   at com.sun.gjc.spi.base.AbstractDataSource.getConnection(AbstractDataSource.java:114)
   … 25 more
Caused by: com.sun.appserv.connectors.internal.api.PoolingException: java.lang.IllegalStateException: Transaction is not active in the current thread.
   at com.sun.enterprise.resource.pool.PoolManagerImpl.getResource(PoolManagerImpl.java:221)
   at com.sun.enterprise.connectors.ConnectionManagerImpl.getResource(ConnectionManagerImpl.java:354)
   at com.sun.enterprise.connectors.ConnectionManagerImpl.internalGetConnection(ConnectionManagerImpl.java:307)
   … 29 more
Caused by: com.sun.appserv.connectors.internal.api.PoolingException: java.lang.IllegalStateException: Transaction is not active in the current thread.
   at com.sun.enterprise.resource.rm.ResourceManagerImpl.registerResource(ResourceManagerImpl.java:173)
   at com.sun.enterprise.resource.rm.ResourceManagerImpl.enlistResource(ResourceManagerImpl.java:112)
   at com.sun.enterprise.resource.pool.PoolManagerImpl.getResource(PoolManagerImpl.java:211)
   … 31 more
Caused by: java.lang.IllegalStateException: Transaction is not active in the current thread.
   at com.sun.enterprise.transaction.JavaEETransactionImpl.checkTransationActive(JavaEETransactionImpl.java:722)
   at com.sun.enterprise.transaction.JavaEETransactionImpl.enlistResource(JavaEETransactionImpl.java:658)
   at com.sun.enterprise.transaction.JavaEETransactionManagerSimplified.enlistXAResource(JavaEETransactionManagerSimplified.java:1313)
   at com.sun.enterprise.transaction.JavaEETransactionManagerSimplified.enlistResource(JavaEETransactionManagerSimplified.java:371)
   at com.sun.enterprise.resource.rm.ResourceManagerImpl.registerResource(ResourceManagerImpl.java:152)
   … 33 more
Information:   11 Mrz 2015 11:50:05,098 [Thread-30] DEBUG org.apache.ibatis.logging.jdbc.BaseJdbcLogger:132 - <==      Total: 0
Information:   11 Mrz 2015 11:50:05,098 [pool-24-thread-1] DEBUG org.activiti.engine.impl.interceptor.LogInterceptor:40 - — ExecuteJobsCmd finished ——————————————————–
Information:   11 Mrz 2015 11:50:05,099 [Thread-30] DEBUG org.activiti.engine.impl.db.DbSqlSession:576 - flush summary: 0 insert, 0 update, 0 delete.
Information:   11 Mrz 2015 11:50:05,099 [pool-24-thread-1] DEBUG org.activiti.engine.impl.interceptor.LogInterceptor:41 -
Information:   11 Mrz 2015 11:50:05,099 [Thread-30] DEBUG org.activiti.engine.impl.db.DbSqlSession:586 - now executing flush…
Information:   11 Mrz 2015 11:50:05,099 [pool-24-thread-1] ERROR org.activiti.engine.impl.jobexecutor.ExecuteJobsRunnable:55 - exception during job execution: 
‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍

The Appserver is not under load, this is from my dev-machine, where i currently perform single integrationtests only.
All Connection-Pools are configured for XA-Transaction as we have some cases where the activiti-app needs to talk to several other remote ejbs in other deployment-units in one request. 

Any idea what could be the issue?

Many thanks in advance,
Stephan

[jbarrez]

Hmmm in the logs you posted : "org.activiti.engine.impl.interceptor.JtaTransactionInterceptor:45 - Running command with propagation REQUIRED"

If I'm correct, this should start a new transaction in JTA, right? So i'm a bit puzzled.

I'm assuming it used to work before? What config where you using then?

[stephan_bauer]

Hi Joram,

finally the problem has gone away. Our main problem was, that our servicetasks were not threadsafe. I wasn't aware that they have to. Thus we had some instance variables like the processinstanceid. This led of course to chaotic behavior when a second or even more threads were using the same instance of a servicetask. In the course of analyzing the problems we had several other exception types as well. We finally decided to migrate to Jboss Wildfly 8.2, even though we now can strongly assume, that Glassfish was not to blame.

Nevertheless many thanks,
Stephan

[jbarrez]

Allright thanks for posting back. Yes, indeed delegates should be thread safe.
But I'm still not sure how that relates to the JTA problem though … any more insight into why, from a technical view, that happened?