3 Replies Latest reply on Jun 19, 2009 10:52 AM by Ronald van Kuijk

    Problem using multiple timers

    nikos dim Newbie

      Hi,

      We have identified a case in which when using 2 timers in a flow we get exception. To be more specific, we use the following process-definition.xml

      <?xml version="1.0" encoding="UTF-8"?>
      
      <process-definition
       xmlns="" name="TestWait">
       <start-state name="start">
       <transition name="" to="SysOut "></transition>
       </start-state>
       <node name="SysOut ">
       <event type="node-enter">
       <action name="action1" class="com.handlers.FlowActionHandler" config-type="constructor">System.out.println('WAITING FOR '+firstTimer);</action></event>
       <transition name="" to="Wait for firstTimer"></transition></node>
       <state name="Wait for firstTimer">
       <timer duedate="4 seconds" transition="resp"><action class="com.handlers.TimeoutActionHandler"></action></timer>
       <transition name="resp" to="SysOut after 1"></transition>
       </state>
       <node name="SysOut after 1">
       <event type="node-enter">
       <action name="action1" class="com.handlers.FlowActionHandler" config-type="constructor">
       System.out.println('After first timer. Going to second timer');
       </action>
       </event>
       <transition name="" to="Wait secondTimer"></transition>
       </node>
       <state name="Wait secondTimer">
       <timer duedate="10 seconds" transition="resp"><action class="com.handlers.TimeoutActionHandler"></action></timer>
       <transition name="resp" to="SysOut after 2"></transition>
       </state>
       <node name="SysOut after 2">
       <event type="node-enter">
       <action name="action1" class="com.handlers.FlowActionHandler" config-type="constructor">System.out.println('After second wait time');
       </action>
       </event>
       <transition name="" to="end1"></transition>
       </node>
       <end-state name="end1"></end-state>
      </process-definition>


      The source code of TimeoutActionHandler follows:

      public class TimeoutActionHandler implements ActionHandler {
       private static final long serialVersionUID = 1L;
       private Logger log = Logger.getLogger(TimeoutActionHandler.class);
      
       public void execute(ExecutionContext executionContext) throws Exception {
      
       ProcessInstance processInstance = executionContext.getProcessInstance();
       if (processInstance.getRootToken().isLocked()) {
       log.debug("A timer of Flow " + processInstance.getId() + " was skipped. The flow had been resumed.");
       return;
       }
      
       executionContext.setVariable(MESSAGE_CODE, "timeout");
       executionContext.leaveNode();
       }
      
      }


      The flow starts and we get in the first wait state, the token waits there for 4 seconds, then we have a System.out.println, then instead of getting in the second wait state, we get the second printout and we get errors. The errors we receive follow:
      2009-06-19 10:52:18,645 INFO [STDOUT] WAITING FOR 4 seconds
      2009-06-19 10:52:18,660 WARN [org.hibernate.engine.StatefulPersistenceContext.ProxyWarnLog] Narrowing proxy to class org.jbpm.graph.node.State - this operation breaks ==
      2009-06-19 10:52:22,225 WARN [org.hibernate.engine.StatefulPersistenceContext.ProxyWarnLog] Narrowing proxy to class org.jbpm.job.Timer - this operation breaks ==
      2009-06-19 10:52:22,310 INFO [STDOUT] After first timer. Going to second timer
      2009-06-19 10:52:22,327 WARN [org.hibernate.engine.StatefulPersistenceContext.ProxyWarnLog] Narrowing proxy to class org.jbpm.graph.node.State - this operation breaks ==
      2009-06-19 10:52:22,398 INFO [STDOUT] After second wait time
      2009-06-19 10:52:22,462 ERROR [org.hibernate.event.def.AbstractFlushingEventListener] Could not synchronize database state with session
      org.hibernate.StaleObjectStateException: Row was updated or deleted by another transaction (or unsaved-value mapping was incorrect): [org.jbpm.job.Timer#9853]
      at org.hibernate.persister.entity.AbstractEntityPersister.check(AbstractEntityPersister.java:1765)
      at org.hibernate.persister.entity.AbstractEntityPersister.delete(AbstractEntityPersister.java:2523)
      at org.hibernate.persister.entity.AbstractEntityPersister.delete(AbstractEntityPersister.java:2697)
      at org.hibernate.action.EntityDeleteAction.execute(EntityDeleteAction.java:74)
      at org.hibernate.engine.ActionQueue.execute(ActionQueue.java:250)
      at org.hibernate.engine.ActionQueue.executeActions(ActionQueue.java:234)
      at org.hibernate.engine.ActionQueue.executeActions(ActionQueue.java:146)
      at org.hibernate.event.def.AbstractFlushingEventListener.performExecutions(AbstractFlushingEventListener.java:298)
      at org.hibernate.event.def.DefaultFlushEventListener.onFlush(DefaultFlushEventListener.java:27)
      at org.hibernate.impl.SessionImpl.flush(SessionImpl.java:1000)
      at org.hibernate.impl.SessionImpl.managedFlush(SessionImpl.java:338)
      at org.hibernate.transaction.JDBCTransaction.commit(JDBCTransaction.java:106)
      at org.jbpm.persistence.db.DbPersistenceService.commit(DbPersistenceService.java:253)
      at org.jbpm.persistence.db.DbPersistenceService.close(DbPersistenceService.java:211)
      at org.jbpm.svc.Services.close(Services.java:222)
      at org.jbpm.JbpmContext.close(JbpmContext.java:139)
      at org.jbpm.job.executor.JobExecutorThread.executeJob(JobExecutorThread.java:267)
      at org.jbpm.job.executor.JobExecutorThread.run(JobExecutorThread.java:71)
      2009-06-19 10:52:22,469 ERROR [org.jbpm.persistence.db.DbPersistenceService] hibernate commit failed
      org.hibernate.StaleObjectStateException: Row was updated or deleted by another transaction (or unsaved-value mapping was incorrect): [org.jbpm.job.Timer#9853]
      at org.hibernate.persister.entity.AbstractEntityPersister.check(AbstractEntityPersister.java:1765)
      at org.hibernate.persister.entity.AbstractEntityPersister.delete(AbstractEntityPersister.java:2523)
      at org.hibernate.persister.entity.AbstractEntityPersister.delete(AbstractEntityPersister.java:2697)
      at org.hibernate.action.EntityDeleteAction.execute(EntityDeleteAction.java:74)
      at org.hibernate.engine.ActionQueue.execute(ActionQueue.java:250)
      at org.hibernate.engine.ActionQueue.executeActions(ActionQueue.java:234)
      at org.hibernate.engine.ActionQueue.executeActions(ActionQueue.java:146)
      at org.hibernate.event.def.AbstractFlushingEventListener.performExecutions(AbstractFlushingEventListener.java:298)
      at org.hibernate.event.def.DefaultFlushEventListener.onFlush(DefaultFlushEventListener.java:27)
      at org.hibernate.impl.SessionImpl.flush(SessionImpl.java:1000)
      at org.hibernate.impl.SessionImpl.managedFlush(SessionImpl.java:338)
      at org.hibernate.transaction.JDBCTransaction.commit(JDBCTransaction.java:106)
      at org.jbpm.persistence.db.DbPersistenceService.commit(DbPersistenceService.java:253)
      at org.jbpm.persistence.db.DbPersistenceService.close(DbPersistenceService.java:211)
      at org.jbpm.svc.Services.close(Services.java:222)
      at org.jbpm.JbpmContext.close(JbpmContext.java:139)
      at org.jbpm.job.executor.JobExecutorThread.executeJob(JobExecutorThread.java:267)
      at org.jbpm.job.executor.JobExecutorThread.run(JobExecutorThread.java:71)
      2009-06-19 10:52:22,471 ERROR [STDERR] org.jbpm.persistence.JbpmPersistenceException: hibernate commit failed
      2009-06-19 10:52:22,472 ERROR [STDERR] at org.jbpm.persistence.db.DbPersistenceService.close(DbPersistenceService.java:216)
      2009-06-19 10:52:22,472 ERROR [STDERR] at org.jbpm.svc.Services.close(Services.java:222)
      2009-06-19 10:52:22,472 ERROR [STDERR] at org.jbpm.JbpmContext.close(JbpmContext.java:139)
      2009-06-19 10:52:22,472 ERROR [STDERR] at org.jbpm.job.executor.JobExecutorThread.executeJob(JobExecutorThread.java:267)
      2009-06-19 10:52:22,472 ERROR [STDERR] at org.jbpm.job.executor.JobExecutorThread.run(JobExecutorThread.java:71)
      2009-06-19 10:52:22,472 ERROR [STDERR] Caused by: org.hibernate.StaleObjectStateException: Row was updated or deleted by another transaction (or unsaved-value mapping was incorrect): [org.jbpm.job.Timer#9853]
      2009-06-19 10:52:22,472 ERROR [STDERR] at org.hibernate.persister.entity.AbstractEntityPersister.check(AbstractEntityPersister.java:1765)
      2009-06-19 10:52:22,472 ERROR [STDERR] at org.hibernate.persister.entity.AbstractEntityPersister.delete(AbstractEntityPersister.java:2523)
      2009-06-19 10:52:22,472 ERROR [STDERR] at org.hibernate.persister.entity.AbstractEntityPersister.delete(AbstractEntityPersister.java:2697)
      2009-06-19 10:52:22,472 ERROR [STDERR] at org.hibernate.action.EntityDeleteAction.execute(EntityDeleteAction.java:74)
      2009-06-19 10:52:22,472 ERROR [STDERR] at org.hibernate.engine.ActionQueue.execute(ActionQueue.java:250)
      2009-06-19 10:52:22,472 ERROR [STDERR] at org.hibernate.engine.ActionQueue.executeActions(ActionQueue.java:234)
      2009-06-19 10:52:22,472 ERROR [STDERR] at org.hibernate.engine.ActionQueue.executeActions(ActionQueue.java:146)
      2009-06-19 10:52:22,473 ERROR [STDERR] at org.hibernate.event.def.AbstractFlushingEventListener.performExecutions(AbstractFlushingEventListener.java:298)
      2009-06-19 10:52:22,473 ERROR [STDERR] at org.hibernate.event.def.DefaultFlushEventListener.onFlush(DefaultFlushEventListener.java:27)
      2009-06-19 10:52:22,473 ERROR [STDERR] at org.hibernate.impl.SessionImpl.flush(SessionImpl.java:1000)
      2009-06-19 10:52:22,473 ERROR [STDERR] at org.hibernate.impl.SessionImpl.managedFlush(SessionImpl.java:338)
      2009-06-19 10:52:22,473 ERROR [STDERR] at org.hibernate.transaction.JDBCTransaction.commit(JDBCTransaction.java:106)
      2009-06-19 10:52:22,473 ERROR [STDERR] at org.jbpm.persistence.db.DbPersistenceService.commit(DbPersistenceService.java:253)
      2009-06-19 10:52:22,473 ERROR [STDERR] at org.jbpm.persistence.db.DbPersistenceService.close(DbPersistenceService.java:211)
      2009-06-19 10:52:22,473 ERROR [STDERR] ... 4 more
      2009-06-19 10:52:22,473 ERROR [org.jbpm.svc.Services] problem closing service 'persistence'
      org.jbpm.persistence.JbpmPersistenceException: hibernate commit failed
      at org.jbpm.persistence.db.DbPersistenceService.close(DbPersistenceService.java:216)
      at org.jbpm.svc.Services.close(Services.java:222)
      at org.jbpm.JbpmContext.close(JbpmContext.java:139)
      at org.jbpm.job.executor.JobExecutorThread.executeJob(JobExecutorThread.java:267)
      at org.jbpm.job.executor.JobExecutorThread.run(JobExecutorThread.java:71)
      Caused by: org.hibernate.StaleObjectStateException: Row was updated or deleted by another transaction (or unsaved-value mapping was incorrect): [org.jbpm.job.Timer#9853]
      at org.hibernate.persister.entity.AbstractEntityPersister.check(AbstractEntityPersister.java:1765)
      at org.hibernate.persister.entity.AbstractEntityPersister.delete(AbstractEntityPersister.java:2523)
      at org.hibernate.persister.entity.AbstractEntityPersister.delete(AbstractEntityPersister.java:2697)
      at org.hibernate.action.EntityDeleteAction.execute(EntityDeleteAction.java:74)
      at org.hibernate.engine.ActionQueue.execute(ActionQueue.java:250)
      at org.hibernate.engine.ActionQueue.executeActions(ActionQueue.java:234)
      at org.hibernate.engine.ActionQueue.executeActions(ActionQueue.java:146)
      at org.hibernate.event.def.AbstractFlushingEventListener.performExecutions(AbstractFlushingEventListener.java:298)
      at org.hibernate.event.def.DefaultFlushEventListener.onFlush(DefaultFlushEventListener.java:27)
      at org.hibernate.impl.SessionImpl.flush(SessionImpl.java:1000)
      at org.hibernate.impl.SessionImpl.managedFlush(SessionImpl.java:338)
      at org.hibernate.transaction.JDBCTransaction.commit(JDBCTransaction.java:106)
      at org.jbpm.persistence.db.DbPersistenceService.commit(DbPersistenceService.java:253)
      at org.jbpm.persistence.db.DbPersistenceService.close(DbPersistenceService.java:211)
      ... 4 more
      2009-06-19 10:52:22,474 ERROR [org.jbpm.job.executor.JobExecutorThread] problem committing job execution transaction for job 9853-timer(Wait for firstTimer,10:52:22,000) (flow with id 6380)
      org.jbpm.JbpmException: problem closing services {persistence=org.jbpm.persistence.JbpmPersistenceException: hibernate commit failed}
      at org.jbpm.svc.Services.close(Services.java:235)
      at org.jbpm.JbpmContext.close(JbpmContext.java:139)
      at org.jbpm.job.executor.JobExecutorThread.executeJob(JobExecutorThread.java:267)
      at org.jbpm.job.executor.JobExecutorThread.run(JobExecutorThread.java:71)
      Caused by: org.jbpm.persistence.JbpmPersistenceException: hibernate commit failed
      at org.jbpm.persistence.db.DbPersistenceService.close(DbPersistenceService.java:216)
      at org.jbpm.svc.Services.close(Services.java:222)
      ... 3 more
      Caused by: org.hibernate.StaleObjectStateException: Row was updated or deleted by another transaction (or unsaved-value mapping was incorrect): [org.jbpm.job.Timer#9853]
      at org.hibernate.persister.entity.AbstractEntityPersister.check(AbstractEntityPersister.java:1765)
      at org.hibernate.persister.entity.AbstractEntityPersister.delete(AbstractEntityPersister.java:2523)
      at org.hibernate.persister.entity.AbstractEntityPersister.delete(AbstractEntityPersister.java:2697)
      at org.hibernate.action.EntityDeleteAction.execute(EntityDeleteAction.java:74)
      at org.hibernate.engine.ActionQueue.execute(ActionQueue.java:250)
      at org.hibernate.engine.ActionQueue.executeActions(ActionQueue.java:234)
      at org.hibernate.engine.ActionQueue.executeActions(ActionQueue.java:146)
      at org.hibernate.event.def.AbstractFlushingEventListener.performExecutions(AbstractFlushingEventListener.java:298)
      at org.hibernate.event.def.DefaultFlushEventListener.onFlush(DefaultFlushEventListener.java:27)
      at org.hibernate.impl.SessionImpl.flush(SessionImpl.java:1000)
      at org.hibernate.impl.SessionImpl.managedFlush(SessionImpl.java:338)
      at org.hibernate.transaction.JDBCTransaction.commit(JDBCTransaction.java:106)
      at org.jbpm.persistence.db.DbPersistenceService.commit(DbPersistenceService.java:253)
      at org.jbpm.persistence.db.DbPersistenceService.close(DbPersistenceService.java:211)
      ... 4 more
      2009-06-19 10:52:22,475 ERROR [org.jbpm.job.executor.JobExecutorThread] exception in job executor thread. waiting 5000 milliseconds
      org.jbpm.JbpmException: problem closing services {persistence=org.jbpm.persistence.JbpmPersistenceException: hibernate commit failed}
      at org.jbpm.svc.Services.close(Services.java:235)
      at org.jbpm.JbpmContext.close(JbpmContext.java:139)
      at org.jbpm.job.executor.JobExecutorThread.executeJob(JobExecutorThread.java:267)
      at org.jbpm.job.executor.JobExecutorThread.run(JobExecutorThread.java:71)
      Caused by: org.jbpm.persistence.JbpmPersistenceException: hibernate commit failed
      at org.jbpm.persistence.db.DbPersistenceService.close(DbPersistenceService.java:216)
      at org.jbpm.svc.Services.close(Services.java:222)
      ... 3 more
      Caused by: org.hibernate.StaleObjectStateException: Row was updated or deleted by another transaction (or unsaved-value mapping was incorrect): [org.jbpm.job.Timer#9853]
      at org.hibernate.persister.entity.AbstractEntityPersister.check(AbstractEntityPersister.java:1765)
      at org.hibernate.persister.entity.AbstractEntityPersister.delete(AbstractEntityPersister.java:2523)
      at org.hibernate.persister.entity.AbstractEntityPersister.delete(AbstractEntityPersister.java:2697)
      at org.hibernate.action.EntityDeleteAction.execute(EntityDeleteAction.java:74)
      at org.hibernate.engine.ActionQueue.execute(ActionQueue.java:250)
      at org.hibernate.engine.ActionQueue.executeActions(ActionQueue.java:234)
      at org.hibernate.engine.ActionQueue.executeActions(ActionQueue.java:146)
      at org.hibernate.event.def.AbstractFlushingEventListener.performExecutions(AbstractFlushingEventListener.java:298)
      at org.hibernate.event.def.DefaultFlushEventListener.onFlush(DefaultFlushEventListener.java:27)
      at org.hibernate.impl.SessionImpl.flush(SessionImpl.java:1000)
      at org.hibernate.impl.SessionImpl.managedFlush(SessionImpl.java:338)
      at org.hibernate.transaction.JDBCTransaction.commit(JDBCTransaction.java:106)
      at org.jbpm.persistence.db.DbPersistenceService.commit(DbPersistenceService.java:253)
      at org.jbpm.persistence.db.DbPersistenceService.close(DbPersistenceService.java:211)
      ... 4 more



      You can see both the system outs and the errors produced. We would like to know if someone has faced the same error (and how to resolve it)or if there is a bug of jbpm that is already resolved in the new edition. We are using JBOSS 4.2.2 and jBPM 3.1