topic Re: JobEntity [id=*****] was updated by another transaction concurrently in Alfresco Forum

JobEntity [id=*****] was updated by another transaction concurrently

abhitorem — Sat, 10 Feb 2018 19:27:11 GMT

‌ ‌ Hi Team, In our Application, we are using Spring Boot with Activiti Rest 5.22.x Process Engine. We created workflow which have a Service Task with marked# Async as true calling the Class through the DelegateExpression Attribute by injecting the Spring Bean. On execution when control comes to t

Re: JobEntity [id=*****] was updated by another transaction concurrently

Anonymous — Sun, 11 Feb 2018 01:02:53 GMT

How long time will your service task take?
Perhaps the processing time of your service task exceeds the lock time.

Default lock time is 500s.

An asynchronous service task is detected in the daemon thread of each server.
An asynchronous service task is processed by an asynchronous thread of the detected server.
Before processing, an asynchronous service task's job record is locked.

Re: JobEntity [id=*****] was updated by another transaction concurrently

abhitorem — Sun, 11 Feb 2018 13:46:52 GMT

Thanks for the quick Response,

It is a short running process, approx execution time for the service Task would be not more than 10sec. The Service Task is getting executed quickly when i run it using rest API externally. This is not specific to one Service Task repeats the same for all the Service Tasks in the Work Flow.

Re: JobEntity [id=*****] was updated by another transaction concurrently

abhitorem — Sun, 11 Feb 2018 15:02:34 GMT

Yoshimoto,

After investigating some more in the logs, the Service Task actually got executed and while deleting the job from act_ru_job table(proir going to preceding UserTask) it is throwing the below exception:

[pool-2-thread-3] DEBUG org.activiti.engine.impl.persistence.entity.ExecutionEntity.updateExecution - <== Updates: 1
20180211 08:56:28.518 [pool-2-thread-3] DEBUG org.activiti.engine.impl.db.DbSqlSession - updating: HistoricVariableInstanceEntity[id=3465275, name=Force_Skip, revision=0, type=boolean, longValue=0]
20180211 08:56:28.518 [pool-2-thread-3] DEBUG org.activiti.engine.impl.persistence.entity.HistoricVariableInstanceEntity.updateHistoricVariableInstance - ==> Preparing: update ACT_HI_VARINST set REV_ = ?, BYTEARRAY_ID_ = ?, DOUBLE_ = ?, LONG_ = ?, TEXT_ = ?, TEXT2_ = ?, VAR_TYPE_ = ?, LAST_UPDATED_TIME_ = ? where ID_ = ? and REV_ = ? 
20180211 08:56:28.518 [pool-2-thread-3] DEBUG org.activiti.engine.impl.persistence.entity.HistoricVariableInstanceEntity.updateHistoricVariableInstance - ==> Parameters: 1(Integer), null, null, 0(Long), null, null, boolean(String), 2018-02-11 08:56:28.499(Timestamp), 3465275(String), 0(Integer)
20180211 08:56:28.519 [pool-2-thread-3] DEBUG org.activiti.engine.impl.persistence.entity.HistoricVariableInstanceEntity.updateHistoricVariableInstance - <== Updates: 1
20180211 08:56:28.519 [pool-2-thread-3] DEBUG org.activiti.engine.impl.db.DbSqlSession - executing: delete JobEntity [id=3465296]
20180211 08:56:28.519 [pool-2-thread-3] DEBUG org.activiti.engine.impl.persistence.entity.JobEntity.deleteMessage - ==> Preparing: delete from ACT_RU_JOB where ID_ = ? and REV_ = ? 
20180211 08:56:28.519 [pool-2-thread-3] DEBUG org.activiti.engine.impl.persistence.entity.JobEntity.deleteMessage - ==> Parameters: 3465296(String), 2(Integer)
20180211 08:56:28.520 [pool-2-thread-3] DEBUG org.activiti.engine.impl.persistence.entity.JobEntity.deleteMessage - <== Updates: 0
20180211 08:56:28.520 [pool-2-thread-3] DEBUG org.activiti.engine.impl.interceptor.CommandContext - Optimistic locking exception : org.activiti.engine.ActivitiOptimisticLockingException: JobEntity [id=3465296] was updated by another transaction concurrently
20180211 08:56:28.520 [pool-2-thread-3] DEBUG org.springframework.jdbc.datasource.DataSourceTransactionManager - Participating in existing transaction
20180211 08:56:28.520 [pool-2-thread-3] DEBUG org.apache.ibatis.transaction.managed.ManagedTransaction - Closing JDBC Connection [Transaction-aware proxy for target Connection [ProxyConnection[PooledConnection[oracle.jdbc.driver.T4CConnection@4e7f63d0]]]]
20180211 08:56:28.521 [pool-2-thread-3] DEBUG org.springframework.transaction.support.TransactionTemplate - Initiating transaction rollback on application exception
org.activiti.engine.ActivitiOptimisticLockingException: JobEntity [id=3465296] was updated by another transaction concurrently
at org.activiti.engine.impl.db.DbSqlSession$CheckedDeleteOperation.execute(DbSqlSession.java:295) ~[activiti-engine-5.22.0.jar:5.22.0]
at org.activiti.engine.impl.db.DbSqlSession.flushRegularDeletes(DbSqlSession.java:897) ~[activiti-engine-5.22.0.jar:5.22.0]
at org.activiti.engine.impl.db.DbSqlSession.flushDeletes(DbSqlSession.java:890) ~[activiti-engine-5.22.0.jar:5.22.0]
at org.activiti.engine.impl.db.DbSqlSession.flush(DbSqlSession.java:617) ~[activiti-engine-5.22.0.jar:5.22.0]
at org.activiti.engine.impl.interceptor.CommandContext.flushSessions(CommandContext.java:212) ~[activiti-engine-5.22.0.jar:5.22.0]
at org.activiti.engine.impl.interceptor.CommandContext.close(CommandContext.java:138) ~[activiti-engine-5.22.0.jar:5.22.0]
at org.activiti.engine.impl.interceptor.CommandContextInterceptor.execute(CommandContextInterceptor.java:66) ~[activiti-engine-5.22.0.jar:5.22.0]
at org.activiti.spring.SpringTransactionInterceptor$1.doInTransaction(SpringTransactionInterceptor.java:47) ~[activiti-spring-5.22.0.jar:5.22.0]
at org.springframework.transaction.support.TransactionTemplate.execute(TransactionTemplate.java:133) ~[spring-tx-4.3.8.RELEASE.jar:4.3.8.RELEASE]
at org.activiti.spring.SpringTransactionInterceptor.execute(SpringTransactionInterceptor.java:45) [activiti-spring-5.22.0.jar:5.22.0]
at org.activiti.engine.impl.interceptor.LogInterceptor.execute(LogInterceptor.java:37) [activiti-engine-5.22.0.jar:5.22.0]
at org.activiti.engine.impl.cfg.CommandExecutorImpl.execute(CommandExecutorImpl.java:40) [activiti-engine-5.22.0.jar:5.22.0]
at org.activiti.engine.impl.cfg.CommandExecutorImpl.execute(CommandExecutorImpl.java:35) [activiti-engine-5.22.0.jar:5.22.0]
at org.activiti.engine.impl.jobexecutor.ExecuteJobsRunnable.handleMultipleJobs(ExecuteJobsRunnable.java:94) [activiti-engine-5.22.0.jar:5.22.0]
at org.activiti.engine.impl.jobexecutor.ExecuteJobsRunnable.run(ExecuteJobsRunnable.java:49) [activiti-engine-5.22.0.jar:5.22.0]
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142) [na:1.8.0_74]
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) [na:1.8.0_74]
at java.lang.Thread.run(Thread.java:745) [na:1.8.0_74]
20180211 08:56:28.521 [pool-2-thread-3] DEBUG org.springframework.orm.jpa.EntityManagerFactoryUtils - Closing JPA EntityManager
20180211 08:56:28.521 [pool-2-thread-3] DEBUG org.springframework.jdbc.datasource.DataSourceUtils - Returning JDBC Connection to DataSource
20180211 08:56:28.521 [pool-2-thread-3] DEBUG org.springframework.jdbc.datasource.DataSourceTransactionManager - Initiating transaction rollback
20180211 08:56:28.521 [pool-2-thread-3] DEBUG org.springframework.jdbc.datasource.DataSourceTransactionManager - Rolling back JDBC transaction on Connection [ProxyConnection[PooledConnection[oracle.jdbc.driver.T4CConnection@4e7f63d0]]]
20180211 08:56:28.525 [pool-2-thread-3] DEBUG org.activiti.engine.impl.interceptor.LogInterceptor -

20180211 08:56:28.525 [pool-2-thread-3] DEBUG org.activiti.engine.impl.interceptor.LogInterceptor - --- starting --------------------------------------------------------
20180211 08:56:28.525 [pool-2-thread-3] DEBUG org.activiti.spring.SpringTransactionInterceptor - Running command with propagation REQUIRES_NEW
20180211 08:56:28.525 [pool-2-thread-3] DEBUG org.springframework.jdbc.datasource.DataSourceTransactionManager - Suspending current transaction, creating new transaction with name [null]
20180211 08:56:28.525 [pool-2-thread-3] DEBUG org.springframework.jdbc.datasource.DataSourceTransactionManager - Acquired Connection [ProxyConnection[PooledConnection[oracle.jdbc.driver.T4CConnection@702762e3]]] for JDBC transaction
20180211 08:56:28.525 [pool-2-thread-3] DEBUG org.springframework.jdbc.datasource.DataSourceTransactionManager - Switching JDBC Connection [ProxyConnection[PooledConnection[oracle.jdbc.driver.T4CConnection@702762e3]]] to manual commit
20180211 08:56:28.525 [pool-2-thread-3] DEBUG org.activiti.engine.impl.interceptor.LogInterceptor -

20180211 08:56:28.525 [pool-2-thread-3] DEBUG org.activiti.engine.impl.interceptor.LogInterceptor - --- starting JobRetryCmd --------------------------------------------------------
20180211 08:56:28.525 [pool-2-thread-3] DEBUG org.activiti.spring.SpringTransactionInterceptor - Running command with propagation REQUIRES_NEW
20180211 08:56:28.525 [pool-2-thread-3] DEBUG org.springframework.jdbc.datasource.DataSourceTransactionManager - Suspending current transaction, creating new transaction with name [null]
20180211 08:56:28.525 [pool-2-thread-3] DEBUG org.springframework.jdbc.datasource.DataSourceTransactionManager - Acquired Connection [ProxyConnection[PooledConnection[oracle.jdbc.driver.T4CConnection@e6286ab]]] for JDBC transaction
20180211 08:56:28.525 [pool-2-thread-3] DEBUG org.springframework.jdbc.datasource.DataSourceTransactionManager - Switching JDBC Connection [ProxyConnection[PooledConnection[oracle.jdbc.driver.T4CConnection@e6286ab]]] to manual commit
20180211 08:56:28.525 [pool-2-thread-3] DEBUG org.apache.ibatis.transaction.managed.ManagedTransaction - Opening JDBC Connection
20180211 08:56:28.525 [pool-2-thread-3] DEBUG org.activiti.engine.impl.persistence.entity.JobEntity.selectJob - ==> Preparing: select * from ACT_RU_JOB where ID_ = ? 
20180211 08:56:28.526 [pool-2-thread-3] DEBUG org.activiti.engine.impl.persistence.entity.JobEntity.selectJob - ==> Parameters: 3465296(String)
20180211 08:56:28.527 [pool-2-thread-3] DEBUG org.activiti.engine.impl.persistence.entity.JobEntity.selectJob - <== Total: 1
20180211 08:56:28.527 [pool-2-thread-3] DEBUG org.activiti.engine.impl.persistence.entity.ExecutionEntity.selectExecution - ==> Preparing: select * from ACT_RU_EXECUTION where ID_ = ? 
20180211 08:56:28.527 [pool-2-thread-3] DEBUG org.activiti.engine.impl.persistence.entity.ExecutionEntity.selectExecution - ==> Parameters: 3465292(String)
20180211 08:56:28.528 [pool-2-thread-3] DEBUG org.activiti.engine.impl.persistence.entity.ExecutionEntity.selectExecution - <== Total: 1
20180211 08:56:28.528 [pool-2-thread-3] DEBUG org.activiti.engine.impl.cmd.JobRetryCmd - activitiy or FailedJobRetryTimerCycleValue is null in job 3465296'. only decrementing retries.
20180211 08:56:28.528 [pool-2-thread-3] DEBUG org.activiti.engine.impl.db.DbSqlSession - update JobEntity [id=3465296]
20180211 08:56:28.528 [pool-2-thread-3] DEBUG org.activiti.engine.impl.db.DbSqlSession - flush summary: 0 insert, 1 update, 0 delete.
20180211 08:56:28.528 [pool-2-thread-3] DEBUG org.activiti.engine.impl.db.DbSqlSession - now executing flush...
20180211 08:56:28.528 [pool-2-thread-3] DEBUG org.activiti.engine.impl.db.DbSqlSession - updating: JobEntity [id=3465296]
20180211 08:56:28.528 [pool-2-thread-3] DEBUG org.activiti.engine.impl.persistence.entity.JobEntity.updateMessage - ==> Preparing: update ACT_RU_JOB SET REV_ = ?, LOCK_EXP_TIME_ = ?, LOCK_OWNER_ = ?, RETRIES_ = ?, EXCEPTION_STACK_ID_ = ?, EXCEPTION_MSG_ = ?, DUEDATE_ = ? where ID_= ? and REV_ = ? 
20180211 08:56:28.529 [pool-2-thread-3] DEBUG org.activiti.engine.impl.persistence.entity.JobEntity.updateMessage - ==> Parameters: 4(Integer), null, null, 2(Integer), null, null, 2018-02-11 08:56:38.528(Timestamp), 3465296(String), 3(Integer)
20180211 08:56:28.530 [pool-2-thread-3] DEBUG org.activiti.engine.impl.persistence.entity.JobEntity.updateMessage - <== Updates: 1
20180211 08:56:28.530 [pool-2-thread-3] DEBUG org.apache.ibatis.transaction.managed.ManagedTransaction - Closing JDBC Connection [Transaction-aware proxy for target Connection [ProxyConnection[PooledConnection[oracle.jdbc.driver.T4CConnection@e6286ab]]]]
20180211 08:56:28.530 [pool-2-thread-3] DEBUG org.springframework.jdbc.datasource.DataSourceTransactionManager - Initiating transaction commit
20180211 08:56:28.530 [pool-2-thread-3] DEBUG org.springframework.jdbc.datasource.DataSourceTransactionManager - Committing JDBC transaction on Connection [ProxyConnection[PooledConnection[oracle.jdbc.driver.T4CConnection@e6286ab]]]
20180211 08:56:28.532 [pool-2-thread-3] DEBUG org.activiti.engine.impl.interceptor.LogInterceptor -

20180211 08:56:28.532 [pool-2-thread-3] DEBUG org.activiti.engine.impl.interceptor.LogInterceptor - --- starting --------------------------------------------------------
20180211 08:56:28.532 [pool-2-thread-3] DEBUG org.activiti.spring.SpringTransactionInterceptor - Running command with propagation REQUIRES_NEW
20180211 08:56:28.532 [pool-2-thread-3] DEBUG org.springframework.jdbc.datasource.DataSourceTransactionManager - Suspending current transaction, creating new transaction with name [null]
20180211 08:56:28.585 [pool-2-thread-3] DEBUG org.springframework.jdbc.datasource.DataSourceTransactionManager - Acquired Connection [ProxyConnection[PooledConnection[oracle.jdbc.driver.T4CConnection@5288cb7b]]] for JDBC transaction
20180211 08:56:28.586 [pool-2-thread-3] DEBUG org.springframework.jdbc.datasource.DataSourceTransactionManager - Switching JDBC Connection [ProxyConnection[PooledConnection[oracle.jdbc.driver.T4CConnection@5288cb7b]]] to manual commit
20180211 08:56:28.586 [pool-2-thread-3] DEBUG org.activiti.engine.impl.jobexecutor.JobAddedNotification - notifying job executor of new job
20180211 08:56:28.586 [pool-2-thread-3] DEBUG org.springframework.jdbc.datasource.DataSourceTransactionManager - Initiating transaction commit
20180211 08:56:28.586 [Thread-12] DEBUG org.activiti.engine.impl.jobexecutor.AcquireJobsRunnableImpl - job acquisition thread woke up
20180211 08:56:28.586 [pool-2-thread-3] DEBUG org.springframework.jdbc.datasource.DataSourceTransactionManager - Committing JDBC transaction on Connection [ProxyConnection[PooledConnection[oracle.jdbc.driver.T4CConnection@5288cb7b]]]
20180211 08:56:28.586 [Thread-12] DEBUG org.activiti.engine.impl.interceptor.LogInterceptor -

20180211 08:56:28.586 [Thread-12] DEBUG org.activiti.engine.impl.interceptor.LogInterceptor - --- starting AcquireJobsCmd --------------------------------------------------------
20180211 08:56:28.586 [Thread-12] DEBUG org.activiti.spring.SpringTransactionInterceptor - Running command with propagation REQUIRED
20180211 08:56:28.586 [Thread-12] DEBUG org.springframework.jdbc.datasource.DataSourceTransactionManager - Creating new transaction with name [null]: PROPAGATION_REQUIRED,ISOLATION_DEFAULT
20180211 08:56:28.586 [pool-2-thread-3] DEBUG org.springframework.jdbc.datasource.DataSourceTransactionManager - Releasing JDBC Connection [ProxyConnection[PooledConnection[oracle.jdbc.driver.T4CConnection@5288cb7b]]] after transaction
20180211 08:56:28.586 [pool-2-thread-3] DEBUG org.springframework.jdbc.datasource.DataSourceUtils - Returning JDBC Connection to DataSource
20180211 08:56:28.586 [pool-2-thread-3] DEBUG org.springframework.jdbc.datasource.DataSourceTransactionManager - Resuming suspended transaction after completion of inner transaction
20180211 08:56:28.586 [pool-2-thread-3] DEBUG org.activiti.engine.impl.interceptor.LogInterceptor - --- finished --------------------------------------------------------
20180211 08:56:28.586 [pool-2-thread-3] DEBUG org.activiti.engine.impl.interceptor.LogInterceptor -‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍

Re: JobEntity [id=*****] was updated by another transaction concurrently

Anonymous — Mon, 12 Feb 2018 05:19:31 GMT

‌

Please give the log before this or the log of another server with the same time.
If we check the log, we may be able to know who update the same job record.

Also, if possible, please give the process definition.

Re: JobEntity [id=*****] was updated by another transaction concurrently

ryandawson — Mon, 12 Feb 2018 12:14:49 GMT

Out of curiosity, does the problem also happen if you put a Thread.sleep in the ServiceTask? I wonder if it's actually executing very quickly and the transactions to start and end the job are overlapping. If so a Thread.sleep would stop the error from happening and give us a clue about the cause. It would also be good to know whether the issue also affects v6.

Re: JobEntity [id=*****] was updated by another transaction concurrently

abhitorem — Wed, 14 Feb 2018 14:36:05 GMT

Ryan Dawson‌

The Service Task would take around 10-20Secs to proceed to the next Task and so the overlapping of the start and End time would not be the concern.

After investigating further more with forum threads regarding Activiti JobExecutor with clustering concept, seems like could be a possibility that running multiple Instances that point to the same Activiti DB could cause the ActvitiOptimisticLocking Exception. So, to check with that we've made our teams local Instances down and tried to re-create the scenario. There was no logs with the issue were ActivitiOptimisticLocking Exception is seen.

Looks like the culprit is Job Executor, when multiple Instances(Process Engines) running pointing to the same DB, this could create the race condition. Which explains why it throws AcitivitiOptimisticLocking Exception.

For now we've made the one Instance JobExecutor to true and all other Instances was set to false. This case where we manually set to 'false' won't be applicable when we move the code to other Environments with multiple App servers running.

I suppose Activiti need to smartly pick the Job Executor and execute Jobs without other JobExecutor locks the record..but it is not the case which is doing..!

As our turnover is close by need to find any permanent fix to it. Please help me out. Thanks

Re: JobEntity [id=*****] was updated by another transaction concurrently

ryandawson — Wed, 14 Feb 2018 15:32:59 GMT

Would you be able to try it on v6? For example Issue with multi instance parallel user task and conditional sequence flows · Issue #1633 · Activiti/Activiti · GitHub is an issue in this area that does not reproduce on v6.

Re: JobEntity [id=*****] was updated by another transaction concurrently

abhitorem — Wed, 14 Feb 2018 16:02:56 GMT

Ryan Dawson‌

Currently can't move to v6 Engine,

1. Since we are utilizing the third party Services. Were the Activiti v5.22.x was included in there Jar (they are planning to move to v7 in the coming months). Plugin v6 and calling v6 directly would take some effort to re-write the base classes.

2. version update would also impact the DB.(think wouldn't work with lower versions)

Are there any alternatives.

Re: JobEntity [id=*****] was updated by another transaction concurrently

ryandawson — Wed, 14 Feb 2018 16:32:25 GMT

Presumably you could run the tasks sync rather than async but I guess you don't want to do that. It might help to see exactly the bpmn snippet by which the serviceTask is invoked. It could be worth reviewing the Async executor configuration options at Activiti User Guide to see if there are any that might help (as daisuke-yoshimoto _‌ has suggested). You could also look at running v6 with v5 compatibility turned on (Activiti Migraton Guide : Activiti v5 to Activiti v6 ) so as to minimise the amount of code changes. The change would affect the DB but would want to do it in a test environment first (e.g. you could create a new db or schema just to test this change on) - it would be best to start with a small PoC that you could run separately before you upgrade any environments that are important for you.

Using v7 could be very interesting as that would give you different options for scaling. We do have a gitter chat for discussion of v7 Activiti/Activiti7 - Gitter