TimerEntity was updated by another transaction concurrently

[bardioc]

Hello,

I've created a simple test case to show a optimistic locking error with the TimerCatchEvent. I've tried to build a unit test from this, but somehow it only occurs when directly implemented in the process.

We're currently using WebSphere 8.0, Activiti-5.9-SNAPSHOT as well as Oracle as DB for the persistence. The model used for this test is the same as found in the IntermediateTimerTest-case in the activiti-engine test suite.

[attachment=0]IntermediateTimerTest.png[/attachment]

The timer is configured as PT5S.

I'm creating a singleton process engine with the EJB-Annotation @Singleton and @Startup. The configuration utilizes the Spring based UOWTransaction manager required for WebSphere.

    <bean id="transactionManager" class="org.springframework.transaction.jta.WebSphereUowTransactionManager" />
    
    <bean id="processEngineConfiguration" class="org.activiti.spring.SpringProcessEngineConfiguration">    
        <property name="jobExecutorActivate" value="false" />      
        <property name="transactionManager"  ref="transactionManager" /> 
    </bean>
‍‍‍‍‍‍‍‍

The database is retrieved via @Resource annotation to utilize the currently active transaction.

conf.setJobExecutorActivate(true);
conf.setDataSource(dataSource);
conf.setHistory(ProcessEngineConfiguration.HISTORY_ACTIVITY);
conf.setDatabaseSchemaUpdate(ProcessEngineConfiguration.DB_SCHEMA_UPDATE_TRUE);
‍‍‍‍‍‍

When I afterwards create two process instances directly after each other:

final ProcessInstance instance
    = engine.getRuntimeService().startProcessInstanceByKey("IntermediateTimerTest");

final ProcessInstance instance2
    = engine.getRuntimeService().startProcessInstanceByKey("IntermediateTimerTest");
‍‍‍‍‍‍‍

Both fall into the timer. When the timer fires an exception is thrown:

[21.10.11 11:40:09:084 CEST] 00000026 CommandContex E   Error while closing command context
org.activiti.engine.ActivitiOptimisticLockingException: TimerEntity[311] was updated by another transaction concurrently
   at org.activiti.engine.impl.db.DbSqlSession.flushUpdates(DbSqlSession.java:435)
   at org.activiti.engine.impl.db.DbSqlSession.flush(DbSqlSession.java:348)
   at org.activiti.engine.impl.interceptor.CommandContext.flushSessions(CommandContext.java:147)
   at org.activiti.engine.impl.interceptor.CommandContext.close(CommandContext.java:103)
   at org.activiti.engine.impl.interceptor.CommandContextInterceptor.execute(CommandContextInterceptor.java:49)
   at org.activiti.spring.SpringTransactionInterceptor$1.doInTransaction(SpringTransactionInterceptor.java:42)
   at org.springframework.transaction.jta.WebSphereUowTransactionManager$UOWActionAdapter.run(WebSphereUowTransactionManager.java:337)
   at com.ibm.ws.uow.EmbeddableUOWManagerImpl.runUnderNewUOW(EmbeddableUOWManagerImpl.java:786)
   at com.ibm.ws.uow.EmbeddableUOWManagerImpl.runUnderUOW(EmbeddableUOWManagerImpl.java:365)
   at org.springframework.transaction.jta.WebSphereUowTransactionManager.execute(WebSphereUowTransactionManager.java:281)
   at org.springframework.transaction.support.TransactionTemplate.execute(TransactionTemplate.java:124)
   at org.activiti.spring.SpringTransactionInterceptor.execute(SpringTransactionInterceptor.java:40)
   at org.activiti.engine.impl.interceptor.LogInterceptor.execute(LogInterceptor.java:33)
   at org.activiti.engine.impl.jobexecutor.JobAcquisitionThread.run(JobAcquisitionThread.java:63)
‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍

Can somebody please help me to understand, what I did wrong or is this a bug in the system?

Thank you very much!

[bardioc]

I found out, that in the exception, the flushUpdates in DbSqlSession checks, whether exactly 1 row is updated:


  protected void flushUpdates(List<PersistentObject> updatedObjects) {
      // … left out code
      int updatedRecords = sqlSession.update(updateStatement, updatedObject);
      if (updatedRecords!=1) {
        throw new ActivitiOptimisticLockingException(toString(updatedObject)+" was updated by another transaction concurrently");
      }
    }
    updatedObjects.clear();
  }

The method is called first for a TimerEntity (hash A) resulting in 1 update, the second time for another Timer Entity (hash B) resulting in 0 updates. This second call leads to the exception. However, why should this be a concurrent update, if nothing has been updated?

I found out, that actually, TimerEntity (hash A) and Timer Entity (Hash B) reflect the same timer. Both created by the JobAcquisitionThread. It seems, the JobAcquisitonThread runs once through its 'run()' method to execute the timer, and then again on its next 'run()' finds the timer once more. Thats why the second call leads to the concurrent update.

I'll try to dig deeper into this code and to find out, how one can prevent the Acquisition thread from finding the same timer again.

[geekonek]

We hit similiar case for single process instance. There's some race condition in timer handling.

POC code in https://github.com/geekonek/activiti-timer-racecondition-poc

Whole process seems to be working ok, just two exceptions are logged.


Oct 25, 2011 10:32:29 AM org.activiti.engine.impl.interceptor.CommandContext close
SEVERE: Error while closing command context
org.activiti.engine.ActivitiOptimisticLockingException: TimerEntity[174] was updated by another transaction concurrently
        at org.activiti.engine.impl.db.DbSqlSession.flushUpdates(DbSqlSession.java:435)
        at org.activiti.engine.impl.db.DbSqlSession.flush(DbSqlSession.java:348)
        at org.activiti.engine.impl.interceptor.CommandContext.flushSessions(CommandContext.java:147)
        at org.activiti.engine.impl.interceptor.CommandContext.close(CommandContext.java:103)
        at org.activiti.engine.impl.interceptor.CommandContextInterceptor.execute(CommandContextInterceptor.java:49)
        at org.activiti.engine.impl.interceptor.LogInterceptor.execute(LogInterceptor.java:33)
        at org.activiti.engine.impl.jobexecutor.JobAcquisitionThread.run(JobAcquisitionThread.java:63)
Oct 25, 2011 10:32:29 AM org.activiti.engine.impl.jobexecutor.JobAcquisitionThread run
SEVERE: exception during job acquisition: TimerEntity[174] was updated by another transaction concurrently
org.activiti.engine.ActivitiOptimisticLockingException: TimerEntity[174] was updated by another transaction concurrently
        at org.activiti.engine.impl.db.DbSqlSession.flushUpdates(DbSqlSession.java:435)
        at org.activiti.engine.impl.db.DbSqlSession.flush(DbSqlSession.java:348)
        at org.activiti.engine.impl.interceptor.CommandContext.flushSessions(CommandContext.java:147)
        at org.activiti.engine.impl.interceptor.CommandContext.close(CommandContext.java:103)
        at org.activiti.engine.impl.interceptor.CommandContextInterceptor.execute(CommandContextInterceptor.java:49)
        at org.activiti.engine.impl.interceptor.LogInterceptor.execute(LogInterceptor.java:33)
        at org.activiti.engine.impl.jobexecutor.JobAcquisitionThread.run(JobAcquisitionThread.java:63)


[meditel]

Hi,

I have the same problem and don't know why the exceptions …
This might need to open a Jira …

BR,
Meditel

[bardioc]

Hey cool, good that I'm not the only one facing this.

I'll open a JIRA and attach a link to the POC you provided. Hopefully someone can investigate this.

Thank you,

Heiko

[partizano]

Hi,

I have the same problem…

[meditel]

I have created a Jira : http://jira.codehaus.org/browse/ACT-966
Please vote.

BR,
Meditel

[trademak]

Hi,

I investigated this and I'm not encountering any problems.
Did you run into these problems in unit tests only or also in the Activiti Explorer?
Because in a unit test it's not easy to test job functionality like intermediate timers.
I've implemented a unit test that starts 100 process instances of a process definition that includes a start event, an intermediate timer event (10 seconds) and an end event.
Can you try and test you're processes in a similar way?

public class TimerTest extends PluggableActivitiTestCase {
 
  public void testTimer() throws Exception {
    // Set the clock fixed
    Date startTime = new Date();
 
    String deploymentId = repositoryService.createDeployment()
       .addClasspathResource("diagrams/timer.bpmn20.xml")
       .name("timer")
       .deploy()
       .getId();
    // prepare stuff and start process instance
    for(int i = 0; i < 100; i++) {
      ProcessInstance processInstance = runtimeService
          .startProcessInstanceByKey("helloworld");
      assertNotNull(processInstance.getId());
      System.out.println("id " + processInstance.getId() + " "
          + processInstance.getProcessDefinitionId());
    }
 
    ClockUtil.setCurrentTime(new Date(startTime.getTime() + 12000));
    waitForJobExecutorToProcessAllJobs(5000L, 25L);
 
    // and the job is done
    assertEquals(0, managementService.createJobQuery().count());
   
    System.out.println("all jobs finished");
    processEngine.getRepositoryService().deleteDeployment(deploymentId, true);
  }
}

[meditel]

In my case i have a 3 applications running in a single tomcat instance and so i have fixed this issue by switching to false the 'jobExecutorActivate' property in 2 applications :

<property name="jobExecutorActivate" value="false" />

So if i have well understand, we must have only one jobExecutorActivate.

BR,
Meditel

[bardioc]

In my case i have a 3 applications running in a single tomcat instance and so i have fixed this issue by switching to false the 'jobExecutorActivate' property in 2 applications :

<property name="jobExecutorActivate" value="false" />

So if i have well understand, we must have only one jobExecutorActivate.

BR,
Meditel

Actually from reading the documentation again and checking my special case, you seem to be right. I've to have two process engines running. One is responsible for processes started from a EJB, one for processes started from a message driven bean. Currently, both are configured the same, having its job executor set true. I added break points on both of them and even though the two processes from the example are initiated by the process engine for the MDB, the other job executor "finds" the processes. Thats the reason why they are tried twice.

I realize that this is a problem one can overcome by just having a single job executor for the whole application, respectively the same persistence database. However, we might think about finding a way to distinguish the two process engines (maybe by naming them) and make the corresponding job executor simply find jobs that belong to them? What do you think? My problem here is actually, that I create two process engines, cause I inject a data source into the EJB as well as the MDB to take advantage of the user transaction, the MDB or the EJB created. I'm currently rethinking this and try to figure out if its really necessary.

Best regards,

Heiko

@trademak: To have a unit test for this, two concurrent process engines both with activated job executor and the SAME persistence database will most probably show the issue.