11 Replies Latest reply on Jan 29, 2010 4:17 AM by Ronald van Kuijk

    Problem with timer

    Jonas Brüstel Newbie

      === Environment ==============================
      - jBPM Version : 4.2
      - Database : HSQLDB
      - JDK : 1.6
      - Container : java version "1.6.0_15"
      Java(TM) SE Runtime Environment (build 1.6.0_15-b03)
      Java HotSpot(TM) 64-Bit Server VM (build 14.1-b02, mixed mode)

      === Process ==================================

      <?xml version="1.0" encoding="UTF-8"?>
      <process name="loop" xmlns="http://jbpm.org/4.2/jpdl">
       <start g="24,96,48,48" name="start1">
       <transition g="-56,-20" name="to check status" to="check status"/>
       </start>
      
       <java class="java.util.Random" method="nextInt" name="check status" var="randomResult" g="204,96,157,49">
       <transition to="exclusive1"/>
       </java>
      
       <decision g="432,96,48,48" name="exclusive1">
       <transition g="-11,-21" name="ok" to="end1">
       <condition expr="#{randomResult=="6"}" />
       </transition>
       <transition g="455,253:-95,-22" name="not ready yet" to="wait"/>
       </decision>
      
       <task name="wait" g="204,228,157,49">
       <transition name="try again" to="check status" g="-66,-8">
       <timer duedate="15 seconds"/>
       </transition>
       </task>
      
       <end g="600,96,157,52" name="end1"/>
      </process>
      


      === Debug logs &Stacktrace ==============================
      2009-11-30 18:47:43,652 DEBUG [org.jbpm.pvm.internal.model.ProcessDefinitionImpl] (http-127.0.0.1-8080-3) creating new execution for process 'loop'
      2009-11-30 18:47:43,653 DEBUG [org.jbpm.pvm.internal.id.DatabaseIdComposer] (http-127.0.0.1-8080-3) generated execution id loop.20067
      2009-11-30 18:47:43,654 DEBUG [org.jbpm.pvm.internal.model.op.ExecuteActivity] (http-127.0.0.1-8080-3) executing activity(start1)
      2009-11-30 18:47:43,654 DEBUG [org.jbpm.pvm.internal.model.op.ExecuteActivity] (http-127.0.0.1-8080-3) executing activity(check status)
      2009-11-30 18:47:43,655 DEBUG [org.jbpm.pvm.internal.model.ScopeInstanceImpl] (http-127.0.0.1-8080-3) create variable 'randomResult' in 'execution[loop.20067]' with value '1116249621'
      2009-11-30 18:47:43,657 DEBUG [org.jbpm.pvm.internal.model.op.ExecuteActivity] (http-127.0.0.1-8080-3) executing activity(exclusive1)
      2009-11-30 18:47:43,678 DEBUG [org.jbpm.pvm.internal.id.DatabaseIdComposer] (http-127.0.0.1-8080-3) generated execution id loop.20067.wait
      2009-11-30 18:47:43,678 DEBUG [org.jbpm.pvm.internal.model.ExecutionImpl] (http-127.0.0.1-8080-3) created execution[loop.20067.wait]
      2009-11-30 18:47:43,678 DEBUG [org.jbpm.pvm.internal.model.ScopeInstanceImpl] (http-127.0.0.1-8080-3) creating timer on execution[loop.20067.wait]
      2009-11-30 18:47:43,709 DEBUG [org.jbpm.pvm.internal.session.TimerSession] (http-127.0.0.1-8080-3) scheduling timer[20072|2009-11-30 18:47:58,679|try again]
      2009-11-30 18:47:43,711 DEBUG [org.jbpm.pvm.internal.model.op.ExecuteActivity] (http-127.0.0.1-8080-3) execution[loop.20067.wait] executes activity(wait)
      2009-11-30 18:47:58,689 DEBUG [org.jbpm.pvm.internal.jobexecutor.DispatcherThread] (DispatcherThread) submitting jobs [20072]
      2009-11-30 18:47:58,700 DEBUG [org.jbpm.pvm.internal.jobexecutor.DispatcherThread] (DispatcherThread) added jobs [20072] to the queue
      2009-11-30 18:47:58,712 DEBUG [org.jbpm.pvm.internal.cmd.ExecuteJobCmd] (pool-9-thread-1) executing job timer[20072|2009-11-30 18:47:58,679|try again]...
      2009-11-30 18:47:58,713 DEBUG [org.jbpm.pvm.internal.job.TimerImpl] (pool-9-thread-1) executing timer[20072|2009-11-30 18:47:58,679|try again]
      2009-11-30 18:47:58,717 DEBUG [org.jbpm.pvm.internal.job.TimerImpl] (pool-9-thread-1) feeding timer signal try again into execution[loop.20067.wait]
      2009-11-30 18:47:58,725 DEBUG [org.jbpm.pvm.internal.model.op.Signal] (pool-9-thread-1) execution[loop.20067.wait] signals activity(wait)
      2009-11-30 18:47:58,731 DEBUG [org.jbpm.pvm.internal.model.ExecutionImpl] (pool-9-thread-1) destroying timers of execution[loop.20067.wait]
      2009-11-30 18:47:58,737 DEBUG [org.jbpm.pvm.internal.model.ExecutionImpl] (pool-9-thread-1) execution[loop.20067.wait] ends
      2009-11-30 18:47:58,742 DEBUG [org.jbpm.pvm.internal.model.op.ExecuteActivity] (pool-9-thread-1) executing activity(check status)
      2009-11-30 18:47:58,742 DEBUG [org.jbpm.pvm.internal.model.ScopeInstanceImpl] (pool-9-thread-1) updating variable 'randomResult' in 'execution[loop.20067]' to value '751427787'
      2009-11-30 18:47:58,743 DEBUG [org.jbpm.pvm.internal.model.op.ExecuteActivity] (pool-9-thread-1) executing activity(exclusive1)
      2009-11-30 18:47:58,748 DEBUG [org.jbpm.pvm.internal.id.DatabaseIdComposer] (pool-9-thread-1) generated execution id loop.20067.wait
      2009-11-30 18:47:58,749 DEBUG [org.jbpm.pvm.internal.model.ExecutionImpl] (pool-9-thread-1) created execution[loop.20067.wait]
      2009-11-30 18:47:58,749 DEBUG [org.jbpm.pvm.internal.model.ScopeInstanceImpl] (pool-9-thread-1) creating timer on execution[loop.20067.wait]
      2009-11-30 18:47:58,749 DEBUG [org.jbpm.pvm.internal.session.TimerSession] (pool-9-thread-1) scheduling timer[20078|2009-11-30 18:48:13,749|try again]
      2009-11-30 18:47:58,755 DEBUG [org.jbpm.pvm.internal.model.op.ExecuteActivity] (pool-9-thread-1) execution[loop.20067.wait] executes activity(wait)
      2009-11-30 18:47:58,756 DEBUG [org.jbpm.pvm.internal.job.TimerImpl] (pool-9-thread-1) deleting timer[20072|2009-11-30 18:47:58,679|try again]
      2009-11-30 18:47:58,756 DEBUG [org.jbpm.pvm.internal.cmd.ExecuteJobCmd] (pool-9-thread-1) executed job timer[20072|2009-11-30 18:47:58,679|try again]
      2009-11-30 18:47:58,766 WARN [org.hibernate.util.JDBCExceptionReporter] (pool-9-thread-1) SQL Error: -104, SQLState: 23000
      2009-11-30 18:47:58,766 ERROR [org.hibernate.util.JDBCExceptionReporter] (pool-9-thread-1) Violation of unique constraint $$: duplicate value(s) for column(s) $$: SYS_CT_50 in statement [update JBPM4_EXECUTION set DBVERSION_=?, ACTIVITYNAME_=?, PROCDEFID_=?, HASVARS_=?, NAME_=?, KEY_=?, ID_=?, STATE_=?, SUSPHISTSTATE_=?, PRIORITY_=?, HISACTINST_=?, PARENT_=?, INSTANCE_=?, SUPEREXEC_=?, SUBPROCINST_=? where DBID_=? and DBVERSION_=?]
      2009-11-30 18:47:58,767 ERROR [org.hibernate.event.def.AbstractFlushingEventListener] (pool-9-thread-1) Could not synchronize database state with session
      org.hibernate.exception.ConstraintViolationException: could not update: [org.jbpm.pvm.internal.model.ExecutionImpl#20077]
      at org.hibernate.exception.SQLStateConverter.convert(SQLStateConverter.java:94)
      at org.hibernate.exception.JDBCExceptionHelper.convert(JDBCExceptionHelper.java:66)
      at org.hibernate.persister.entity.AbstractEntityPersister.update(AbstractEntityPersister.java:2453)
      at org.hibernate.persister.entity.AbstractEntityPersister.updateOrInsert(AbstractEntityPersister.java:2335)
      at org.hibernate.persister.entity.AbstractEntityPersister.update(AbstractEntityPersister.java:2635)
      at org.hibernate.action.EntityUpdateAction.execute(EntityUpdateAction.java:115)
      at org.hibernate.engine.ActionQueue.execute(ActionQueue.java:279)
      at org.hibernate.engine.ActionQueue.executeActions(ActionQueue.java:263)
      at org.hibernate.engine.ActionQueue.executeActions(ActionQueue.java:168)
      at org.hibernate.event.def.AbstractFlushingEventListener.performExecutions(AbstractFlushingEventListener.java:321)
      at org.hibernate.event.def.DefaultFlushEventListener.onFlush(DefaultFlushEventListener.java:50)
      at org.hibernate.impl.SessionImpl.flush(SessionImpl.java:1027)
      at org.hibernate.impl.SessionImpl.managedFlush(SessionImpl.java:365)
      at org.hibernate.transaction.CacheSynchronization.beforeCompletion(CacheSynchronization.java:88)
      at com.arjuna.ats.internal.jta.resources.arjunacore.SynchronizationImple.beforeCompletion(SynchronizationImple.java:101)
      at com.arjuna.ats.arjuna.coordinator.TwoPhaseCoordinator.beforeCompletion(TwoPhaseCoordinator.java:263)
      at com.arjuna.ats.arjuna.coordinator.TwoPhaseCoordinator.end(TwoPhaseCoordinator.java:86)
      at com.arjuna.ats.arjuna.AtomicAction.commit(AtomicAction.java:177)
      at com.arjuna.ats.internal.jta.transaction.arjunacore.TransactionImple.commitAndDisassociate(TransactionImple.java:1414)
      at com.arjuna.ats.internal.jta.transaction.arjunacore.BaseTransaction.commit(BaseTransaction.java:135)
      at com.arjuna.ats.jbossatx.BaseTransactionManagerDelegate.commit(BaseTransactionManagerDelegate.java:75)
      at org.jboss.tm.usertx.client.ServerVMClientUserTransaction.commit(ServerVMClientUserTransaction.java:162)
      at org.jbpm.pvm.internal.tx.jta.JtaTransaction.commit(JtaTransaction.java:91)
      at org.jbpm.pvm.internal.tx.jta.JtaTransactionInterceptor.executeInNewTx(JtaTransactionInterceptor.java:89)
      at org.jbpm.pvm.internal.tx.jta.JtaTransactionInterceptor.execute(JtaTransactionInterceptor.java:66)
      at org.jbpm.pvm.internal.svc.RetryInterceptor.execute(RetryInterceptor.java:55)
      at org.jbpm.pvm.internal.tx.jta.JtaRetryInterceptor.executeWithRetry(JtaRetryInterceptor.java:52)
      at org.jbpm.pvm.internal.tx.jta.JtaRetryInterceptor.execute(JtaRetryInterceptor.java:45)
      at org.jbpm.pvm.internal.svc.EnvironmentInterceptor.executeInNewEnvironment(EnvironmentInterceptor.java:53)
      at org.jbpm.pvm.internal.svc.EnvironmentInterceptor.execute(EnvironmentInterceptor.java:40)
      at org.jbpm.pvm.internal.svc.SkipInterceptor.execute(SkipInterceptor.java:43)
      at org.jbpm.pvm.internal.jobexecutor.JobParcel.run(JobParcel.java:48)
      at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:441)
      at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:303)
      at java.util.concurrent.FutureTask.run(FutureTask.java:138)
      at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
      at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
      at java.lang.Thread.run(Thread.java:619)
      Caused by: java.sql.SQLException: Violation of unique constraint $$: duplicate value(s) for column(s) $$: SYS_CT_50 in statement [update JBPM4_EXECUTION set DBVERSION_=?, ACTIVITYNAME_=?, PROCDEFID_=?, HASVARS_=?, NAME_=?, KEY_=?, ID_=?, STATE_=?, SUSPHISTSTATE_=?, PRIORITY_=?, HISACTINST_=?, PARENT_=?, INSTANCE_=?, SUPEREXEC_=?, SUBPROCINST_=? where DBID_=? and DBVERSION_=?]
      at org.hsqldb.jdbc.Util.throwError(Unknown Source)
      at org.hsqldb.jdbc.jdbcPreparedStatement.executeUpdate(Unknown Source)
      at org.jboss.resource.adapter.jdbc.CachedPreparedStatement.executeUpdate(CachedPreparedStatement.java:94)
      at org.jboss.resource.adapter.jdbc.WrappedPreparedStatement.executeUpdate(WrappedPreparedStatement.java:365)
      at org.hibernate.persister.entity.AbstractEntityPersister.update(AbstractEntityPersister.java:2435)
      ... 35 more
      2009-11-30 18:47:58,771 WARN [com.arjuna.ats.arjuna.logging.arjLoggerI18N] (pool-9-thread-1) [com.arjuna.ats.arjuna.coordinator.TwoPhaseCoordinator_2] TwoPhaseCoordinator.beforeCompletion - failed for com.arjuna.ats.internal.jta.resources.arjunacore.SynchronizationImple@5eff06be
      org.hibernate.exception.ConstraintViolationException: could not update: [org.jbpm.pvm.internal.model.ExecutionImpl#20077]
      at org.hibernate.exception.SQLStateConverter.convert(SQLStateConverter.java:94)
      at org.hibernate.exception.JDBCExceptionHelper.convert(JDBCExceptionHelper.java:66)
      at org.hibernate.persister.entity.AbstractEntityPersister.update(AbstractEntityPersister.java:2453)
      at org.hibernate.persister.entity.AbstractEntityPersister.updateOrInsert(AbstractEntityPersister.java:2335)
      at org.hibernate.persister.entity.AbstractEntityPersister.update(AbstractEntityPersister.java:2635)
      at org.hibernate.action.EntityUpdateAction.execute(EntityUpdateAction.java:115)
      at org.hibernate.engine.ActionQueue.execute(ActionQueue.java:279)
      at org.hibernate.engine.ActionQueue.executeActions(ActionQueue.java:263)
      at org.hibernate.engine.ActionQueue.executeActions(ActionQueue.java:168)
      at org.hibernate.event.def.AbstractFlushingEventListener.performExecutions(AbstractFlushingEventListener.java:321)
      at org.hibernate.event.def.DefaultFlushEventListener.onFlush(DefaultFlushEventListener.java:50)
      at org.hibernate.impl.SessionImpl.flush(SessionImpl.java:1027)
      at org.hibernate.impl.SessionImpl.managedFlush(SessionImpl.java:365)
      at org.hibernate.transaction.CacheSynchronization.beforeCompletion(CacheSynchronization.java:88)
      at com.arjuna.ats.internal.jta.resources.arjunacore.SynchronizationImple.beforeCompletion(SynchronizationImple.java:101)
      at com.arjuna.ats.arjuna.coordinator.TwoPhaseCoordinator.beforeCompletion(TwoPhaseCoordinator.java:263)
      at com.arjuna.ats.arjuna.coordinator.TwoPhaseCoordinator.end(TwoPhaseCoordinator.java:86)
      at com.arjuna.ats.arjuna.AtomicAction.commit(AtomicAction.java:177)
      at com.arjuna.ats.internal.jta.transaction.arjunacore.TransactionImple.commitAndDisassociate(TransactionImple.java:1414)
      at com.arjuna.ats.internal.jta.transaction.arjunacore.BaseTransaction.commit(BaseTransaction.java:135)
      at com.arjuna.ats.jbossatx.BaseTransactionManagerDelegate.commit(BaseTransactionManagerDelegate.java:75)
      at org.jboss.tm.usertx.client.ServerVMClientUserTransaction.commit(ServerVMClientUserTransaction.java:162)
      at org.jbpm.pvm.internal.tx.jta.JtaTransaction.commit(JtaTransaction.java:91)
      at org.jbpm.pvm.internal.tx.jta.JtaTransactionInterceptor.executeInNewTx(JtaTransactionInterceptor.java:89)
      at org.jbpm.pvm.internal.tx.jta.JtaTransactionInterceptor.execute(JtaTransactionInterceptor.java:66)
      at org.jbpm.pvm.internal.svc.RetryInterceptor.execute(RetryInterceptor.java:55)
      at org.jbpm.pvm.internal.tx.jta.JtaRetryInterceptor.executeWithRetry(JtaRetryInterceptor.java:52)
      at org.jbpm.pvm.internal.tx.jta.JtaRetryInterceptor.execute(JtaRetryInterceptor.java:45)
      at org.jbpm.pvm.internal.svc.EnvironmentInterceptor.executeInNewEnvironment(EnvironmentInterceptor.java:53)
      at org.jbpm.pvm.internal.svc.EnvironmentInterceptor.execute(EnvironmentInterceptor.java:40)
      at org.jbpm.pvm.internal.svc.SkipInterceptor.execute(SkipInterceptor.java:43)
      at org.jbpm.pvm.internal.jobexecutor.JobParcel.run(JobParcel.java:48)
      at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:441)
      at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:303)
      at java.util.concurrent.FutureTask.run(FutureTask.java:138)
      at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
      at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
      at java.lang.Thread.run(Thread.java:619)
      Caused by: java.sql.SQLException: Violation of unique constraint $$: duplicate value(s) for column(s) $$: SYS_CT_50 in statement [update JBPM4_EXECUTION set DBVERSION_=?, ACTIVITYNAME_=?, PROCDEFID_=?, HASVARS_=?, NAME_=?, KEY_=?, ID_=?, STATE_=?, SUSPHISTSTATE_=?, PRIORITY_=?, HISACTINST_=?, PARENT_=?, INSTANCE_=?, SUPEREXEC_=?, SUBPROCINST_=? where DBID_=? and DBVERSION_=?]
      at org.hsqldb.jdbc.Util.throwError(Unknown Source)
      at org.hsqldb.jdbc.jdbcPreparedStatement.executeUpdate(Unknown Source)
      at org.jboss.resource.adapter.jdbc.CachedPreparedStatement.executeUpdate(CachedPreparedStatement.java:94)
      at org.jboss.resource.adapter.jdbc.WrappedPreparedStatement.executeUpdate(WrappedPreparedStatement.java:365)
      at org.hibernate.persister.entity.AbstractEntityPersister.update(AbstractEntityPersister.java:2435)
      ... 35 more
      2009-11-30 18:47:58,774 ERROR [org.jbpm.pvm.internal.jobexecutor.JobParcel] (pool-9-thread-1) exception in job block
      org.jbpm.api.JbpmException: couldn't rollback: BaseTransaction.rollback - [com.arjuna.ats.internal.jta.transaction.arjunacore.notx] [com.arjuna.ats.internal.jta.transaction.arjunacore.notx] no transaction!
      at org.jbpm.pvm.internal.tx.jta.JtaTransaction.rollback(JtaTransaction.java:85)
      at org.jbpm.pvm.internal.tx.jta.JtaTransactionInterceptor.executeInNewTx(JtaTransactionInterceptor.java:92)
      at org.jbpm.pvm.internal.tx.jta.JtaTransactionInterceptor.execute(JtaTransactionInterceptor.java:66)
      at org.jbpm.pvm.internal.svc.RetryInterceptor.execute(RetryInterceptor.java:55)
      at org.jbpm.pvm.internal.tx.jta.JtaRetryInterceptor.executeWithRetry(JtaRetryInterceptor.java:52)
      at org.jbpm.pvm.internal.tx.jta.JtaRetryInterceptor.execute(JtaRetryInterceptor.java:45)
      at org.jbpm.pvm.internal.svc.EnvironmentInterceptor.executeInNewEnvironment(EnvironmentInterceptor.java:53)
      at org.jbpm.pvm.internal.svc.EnvironmentInterceptor.execute(EnvironmentInterceptor.java:40)
      at org.jbpm.pvm.internal.svc.SkipInterceptor.execute(SkipInterceptor.java:43)
      at org.jbpm.pvm.internal.jobexecutor.JobParcel.run(JobParcel.java:48)
      at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:441)
      at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:303)
      at java.util.concurrent.FutureTask.run(FutureTask.java:138)
      at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
      at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
      at java.lang.Thread.run(Thread.java:619)
      Caused by: java.lang.IllegalStateException: BaseTransaction.rollback - [com.arjuna.ats.internal.jta.transaction.arjunacore.notx] [com.arjuna.ats.internal.jta.transaction.arjunacore.notx] no transaction!
      ....


      === Problem description =========================


      Hi,

      the errors above appears after starting the process via the jBPM console.
      Is my process definition wrong? I would like to check if a service is running and proceed afterwards.
      The problems seems to be located at the timer.

      Thanks for your help. I'm new to jBPM and open for any solutions.

      Greetings,
      Jonas