StaleObjectException in JBPM 4.0

[mmusaji]

After doing much reading and checking up on this I've still not found a solution that works. I'm using a MYSQL database and I've updated the ISOLATION LEVEL to read committed but still getting a StaleObjectException when my workflow goes through the fork.

Is there any other updates to this or a workaround. It does always occur but sometimes more than other times and not necessarily at the same time in the flow.

[kukeltje]

Testcase? Logging? etc....

[kukeltje]

Configuration? Versions of other things etc...etc...etc...

[mmusaji]

Apologies Ronald, I was hoping for more of a discussion as opposed to a solution to my specific problem.

Here's the fork and join from my workflow.

<java class="org.workflow.FindProviders" g="276,7,80,40" method="execute" name="find providers">
 <transition name="" to="fork"/>
 </java>

 <fork g="298,85,80,40" name="fork">
 <transition g="-62,-18" name="validate red" to="validate red request"/>
 <transition g="-64,-18" name="validate exp" to="validate exp request"/>
 <transition g="-63,-17" name="validate sys" to="validate sys request"/>
 </fork>

 <custom continue="async" name="validate red request" class="org.workflow.Validate1" exp="#{myFirstObj}">
 <transition g="-27,-18" name="" to="join"/>
 </custom>

 <custom continue="async" name="validate exp request" class="org.workflow.Validate2" exp="#{mySecondObj}">
 <transition g="-27,-18" name="" to="join"/>
 </custom>

 <custom continue="async" name="validate sys request" class="org.workflow.Validate3" exp="#{myThirdObj}">
 <transition g="-27,-18" name="" to="join"/>
 </custom>

 <join g="267,368,80,40" name="join">
 <transition name="check results" to="evaluate validation results" g="-47,-16"/>
 </join>
...

Starting the process using JobExecutor config

<jbpm-configuration>

 <process-engine-context>

 <job-executor threads="5" idle="10" idle-max="0" lock-millis="0" />

 </process-engine-context>

</jbpm-configuration>

Using MySQL and everytime I run the forks run concurrently as expected. But then sometimes in between the forks or sometimes after I get this exception

org.hibernate.StaleObjectStateException: Row was updated or deleted by another transaction (or unsaved-value mapping was incorrect): [org.jbpm.pvm.internal.model.ExecutionImpl#53]
 at org.hibernate.persister.entity.AbstractEntityPersister.check(AbstractEntityPersister.java:1792)
 at org.hibernate.persister.entity.AbstractEntityPersister.update(AbstractEntityPersister.java:2435)
 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.DefaultAutoFlushEventListener.onAutoFlush(DefaultAutoFlushEventListener.java:64)
 at org.hibernate.impl.SessionImpl.autoFlushIfRequired(SessionImpl.java:996)
 at org.hibernate.impl.SessionImpl.list(SessionImpl.java:1141)
 at org.hibernate.impl.QueryImpl.list(QueryImpl.java:102)
 at org.jbpm.pvm.internal.hibernate.DbSessionImpl.deleteProcessDefinitionHistory(DbSessionImpl.java:165)
 at org.jbpm.pvm.internal.cmd.DeleteDeploymentCmd.execute(DeleteDeploymentCmd.java:77)
 at org.jbpm.pvm.internal.svc.DefaultCommandService.execute(DefaultCommandService.java:42)
 at org.jbpm.pvm.internal.tx.StandardTransactionInterceptor.execute(StandardTransactionInterceptor.java:54)
 at org.jbpm.pvm.internal.svc.EnvironmentInterceptor.execute(EnvironmentInterceptor.java:54)
 at org.jbpm.pvm.internal.svc.RetryInterceptor.execute(RetryInterceptor.java:55)
 at org.jbpm.pvm.internal.repository.RepositoryServiceImpl.deleteDeploymentCascade(RepositoryServiceImpl.java:70)
 at biz.thelogicgroup.fraudswitch.workflow.FraudWorkflowTest.tearDown(FraudWorkflowTest.java:76)
 at junit.framework.TestCase.runBare(TestCase.java:130)
 at junit.framework.TestResult$1.protect(TestResult.java:106)
 at junit.framework.TestResult.runProtected(TestResult.java:124)
 at junit.framework.TestResult.run(TestResult.java:109)
 at junit.framework.TestCase.run(TestCase.java:118)
 at junit.framework.TestSuite.runTest(TestSuite.java:208)
 at junit.framework.TestSuite.run(TestSuite.java:203)
 at org.eclipse.jdt.internal.junit.runner.junit3.JUnit3TestReference.run(JUnit3TestReference.java:130)
 at org.eclipse.jdt.internal.junit.runner.TestExecution.run(TestExecution.java:38)
 at org.eclipse.jdt.internal.junit.runner.RemoteTestRunner.runTests(RemoteTestRunner.java:460)
 at org.eclipse.jdt.internal.junit.runner.RemoteTestRunner.runTests(RemoteTestRunner.java:673)
 at org.eclipse.jdt.internal.junit.runner.RemoteTestRunner.run(RemoteTestRunner.java:386)
 at org.eclipse.jdt.internal.junit.runner.RemoteTestRunner.main(RemoteTestRunner.java:196)
### EXCEPTION ###########################################
### EXCEPTION ###########################################

I read somewhere this is expected behaviour but this surely can't be right... can it?

[mmusaji]

Forgot to add, as you can see each fork is working on a different object. I thought I would try this as I was getting StaleObjectExceptions when they were working on the same object (understandable I thought!).

My previous thread before I got job executor working shows the old config.

http://www.jboss.org/index.html?module=bb&op=viewtopic&t=160069

But now they are all working on different objects I don't get why each fork cares what the other objects are doing?

[mmusaji]

Looking at a recent post:

http://www.jboss.org/index.html?module=bb&op=viewtopic&t=160091&postdays=0&postorder=asc&start=0

I am assuming now that this Exception is just "expected" behaviour, which is a little annoying but not much I can do about it from the sounds of it.

However, my workflow seems to not be working despite this. Sometimes it will run to the end of the workflow and other times it will halt at the join?

Any help would be greatly appreciated.

My workflow:

<?xml version="1.0" encoding="UTF-8"?>

<process name="process" xmlns="http://jbpm.org/4.0/jpdl">
 <start>
 <transition to="parse request"/>
 </start>

 <custom exp="#{mainObj}" class="org.application.workflow.ProcessRequest" name="process request">
 <transition to="evaluate process request result"/>
 </custom>

 <decision name="evaluate process request result" expr="#{content}" >
 <transition name="valid" to="find providers" />
 <transition name="invalid" to="error"/>
 </decision>

 <java class="org.application.workflow.FindProviders" method="execute" name="find providers">
 <transition to="fork"/>
 </java>

 <fork name="fork">
 <transition name="validate red" to="validate red request"/>
 <transition name="validate exp" to="validate exp request"/>
 <transition name="validate sys" to="validate sys request"/>
 </fork>

 <custom continue="async" name="validate red request" class="org.application.workflow.ValidateReDFraudRequest" exp="#{redObj}">
 <transition to="join"/>
 </custom>

 <custom continue="async" name="validate exp request" class="org.application.workflow.ValidateExpFraudRequest" exp="#{expObj}">
 <transition to="join"/>
 </custom>

 <custom continue="async" name="validate sys request" class="org.application.workflow.ValidateSysFraudRequest" exp="#{sysObj}">
 <transition to="join"/>
 </custom>

 <join name="join">
 <transition continue="exclusive" name="check results" to="evaluate validation results"/>
 </join>

 <decision name="evaluate validation results" expr="#{content}" >
 <transition name="valid" to="construct message" />
 <transition name="invalid" to="error"/>
 </decision>

 <java class="org.application.workflow.ConstructRequest" method="execute" name="construct message">
 <transition to="send"/>
 </java>

 <java class="org.application.workflow.SendRequest" method="execute" name="send">
 <transition to="get responses"/>
 </java>

 <java class="org.application.workflow.GetResponse" method="execute" name="get responses">
 <transition to="process responses"/>
 </java>

 <java class="org.application.workflow.ProcessResponse" method="execute" name="process responses">
 <transition name="complete" to="getmainObject"/>
 <transition name="process" to="find providers"/>
 <transition name="error" to="error"/>
 </java>

 <custom name="getmainObject" class="org.application.workflow.GetmainObject" exp="#{mainObj}">
 <transition to="end"/>
 </custom>

 <task name="end">
 <transition name="to complete" to="end process"/>
 </task>

 <end name="end process" state="complete"/>
 <end-error name="error"/>

 </process>

My Unit test:

 protected void setUp() throws Exception {
 super.setUp();

 variables.put("content", "valid");

 //create main object
 mainObj = new MainObject("001");

 //create other object information
 expObj = new ExpObject();
 expObj.setName("exp Name");
 expObj.setDetails("some exp details");


 sysObj = new SysObj();
 sysObj.setName("sys Name");
 sysObj.setDetails("Sys Details");

 redObj = new RedObj();
 redObj.setName("red Name");
 redObj.setDetails("red details");

 variables.put("mainObj", mainObj);
 variables.put("redObj", redObj);
 variables.put("expObj", expObj);
 variables.put("sysObj", sysObj);

 deploymentDbid = repositoryService.createDeployment()
 .addResourceFromClasspath("org/application/workflow/process.jpdl.xml")
 .deploy();
 }

 public void testSimple() {

 ProcessInstance processInstance = executionService.startProcessInstanceByKey("process", variables);
 String processInstanceId = processInstance.getId();

 }

My output:

13:05:21,077 FIN | [BaseJbpmTestCase] === starting testSimple =============================
13:05:21,217 FIN | [BaseJbpmTestCase] using ProcessEngine 6301159
13:05:21,280 INF | [Environment] Hibernate 3.3.1.GA
13:05:21,280 INF | [Environment] hibernate.properties not found
13:05:21,280 INF | [Environment] Bytecode provider name : javassist
13:05:21,280 INF | [Environment] using JDK 1.4 java.sql.Timestamp handling
13:05:21,311 INF | [Configuration] configuring from resource: jbpm.hibernate.cfg.xml
13:05:21,311 INF | [Configuration] Configuration resource: jbpm.hibernate.cfg.xml
13:05:21,342 INF | [Configuration] Reading mappings from resource : jbpm.repository.hbm.xml
13:05:21,420 INF | [Configuration] Reading mappings from resource : jbpm.execution.hbm.xml
13:05:21,483 INF | [Configuration] Reading mappings from resource : jbpm.history.hbm.xml
13:05:21,514 INF | [Configuration] Reading mappings from resource : jbpm.task.hbm.xml
13:05:21,530 INF | [Configuration] Reading mappings from resource : jbpm.identity.hbm.xml
13:05:21,530 INF | [Configuration] Configured SessionFactory: null
13:05:21,545 INF | [DriverManagerConnectionProvider] Using Hibernate built-in connection pool (not for production use!)
13:05:21,545 INF | [DriverManagerConnectionProvider] Hibernate connection pool size: 20
13:05:21,545 INF | [DriverManagerConnectionProvider] autocommit mode: false
13:05:21,545 INF | [DriverManagerConnectionProvider] using driver: com.mysql.jdbc.Driver at URL: jdbc:mysql://localhost:3306/jbpm4
13:05:21,545 INF | [DriverManagerConnectionProvider] connection properties: {user=jboss, password=****}
13:05:21,686 INF | [Dialect] Using dialect: org.hibernate.dialect.MySQLInnoDBDialect
13:05:21,702 INF | [TransactionFactoryFactory] Using default transaction strategy (direct JDBC transactions)
13:05:21,702 INF | [TransactionManagerLookupFactory] No TransactionManagerLookup configured (in JTA environment, use of read-write or transactional second-level cache is not recommended)
13:05:21,702 INF | [ASTQueryTranslatorFactory] Using ASTQueryTranslatorFactory
13:05:21,717 INF | [SessionFactoryImpl] building session factory
13:05:22,077 INF | [SessionFactoryObjectFactory] Not binding factory to JNDI, no JNDI name configured
13:05:22,389 FIN | [ProcessDefinitionImpl] creating new execution for process 'process'
13:05:22,389 FIN | [DefaultIdGenerator] generated execution id process.39
13:05:22,389 FIN | [ScopeInstanceImpl] create variable 'content' in 'execution[process.39]' with value 'valid'
13:05:22,389 FIN | [ScopeInstanceImpl] create variable 'redObj' in 'execution[process.39]' with value 'org.application.SDM.RedObject@1265109'
13:05:22,405 FIN | [ScopeInstanceImpl] create variable 'expObj' in 'execution[process.39]' with value 'org.application.SDM.ExpObject@e2892b'
13:05:22,405 FIN | [ScopeInstanceImpl] create variable 'sysObj' in 'execution[process.39]' with value 'org.application.SDM.SysObject@14b6b02'
13:05:22,405 FIN | [ScopeInstanceImpl] create variable 'mainObj' in 'execution[process.39]' with value 'org.application.SDM.MainObject@1a41cc7'
13:05:22,405 FIN | [ExecuteActivity] executing activity(16009656)
13:05:22,405 FIN | [ExecuteActivity] executing activity(process request)
13:05:22,405 FIN | [ExecuteActivity] executing activity(evaluate process request result)
DEBUG: process request
13:05:22,436 FIN | [ExecuteActivity] executing activity(find providers)
13:05:22,436 FIN | [ExecuteActivity] executing activity(fork)
13:05:22,436 FIN | [DefaultIdGenerator] generated execution id process.39.validate red
13:05:22,452 FIN | [ExecutionImpl] created execution[process.39.validate red]
13:05:22,452 FIN | [JobExecutorMessageSession] sending message ExecuteActivityMessage
DEBUG: process ID: processID 001
DEBUG: Finding Providers
13:05:22,452 INF | [JobExecutorThread] starting...
13:05:22,452 INF | [DispatcherThread] starting...
13:05:22,452 FIN | [DefaultIdGenerator] generated execution id process.39.validate exp
13:05:22,452 FIN | [ExecutionImpl] created execution[process.39.validate exp]
13:05:22,452 FIN | [JobExecutorMessageSession] sending message ExecuteActivityMessage
13:05:22,467 FIN | [AcquireJobsCmd] start querying first acquirable job...
13:05:22,467 FIN | [DefaultIdGenerator] generated execution id process.39.validate sys
13:05:22,467 FIN | [ExecutionImpl] created execution[process.39.validate sys]
13:05:22,467 FIN | [JobExecutorMessageSession] sending message ExecuteActivityMessage
13:05:22,467 FIN | [AcquireJobsCmd] locking jobs []
13:05:22,483 FIN | [DbSessionImpl] deleting history process instance process.39
13:05:22,483 FIN | [GetNextDueDateCmd] getting next due date...
13:05:22,483 FIN | [GetNextDueDateCmd] next due date is null
13:05:22,483 FIN | [AcquireJobsCmd] start querying first acquirable job...
13:05:22,483 FIN | [AcquireJobsCmd] locking jobs [43]
13:05:22,483 FIN | [DispatcherThread] pushing jobs on the queue [43]
13:05:22,483 FIN | [DispatcherThread] added jobs [43] to the queue
13:05:22,483 FIN | [AcquireJobsCmd] start querying first acquirable job...
13:05:22,499 FIN | [DbSessionImpl] deleting process instance process.39
13:05:22,499 FIN | [AcquireJobsCmd] locking jobs [44]
13:05:22,499 FIN | [JobExecutorThread] took job(s) [43] from queue
13:05:22,499 FIN | [DispatcherThread] pushing jobs on the queue [44]
13:05:22,499 FIN | [DispatcherThread] added jobs [44] to the queue
13:05:22,499 FIN | [AcquireJobsCmd] start querying first acquirable job...
13:05:22,514 FIN | [AcquireJobsCmd] locking jobs [45]
13:05:22,514 FIN | [DispatcherThread] pushing jobs on the queue [45]
### EXCEPTION ###########################################
13:05:22,514 SEV | [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.pvm.internal.model.op.ExecuteActivityMessage#43]
 at org.hibernate.persister.entity.AbstractEntityPersister.check(AbstractEntityPersister.java:1792)
 at org.hibernate.persister.entity.AbstractEntityPersister.delete(AbstractEntityPersister.java:2551)
 at org.hibernate.persister.entity.AbstractEntityPersister.delete(AbstractEntityPersister.java:2725)
 at org.hibernate.action.EntityDeleteAction.execute(EntityDeleteAction.java:97)
 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:172)
 at org.hibernate.event.def.AbstractFlushingEventListener.performExecutions(AbstractFlushingEventListener.java:321)
 at org.hibernate.event.def.DefaultAutoFlushEventListener.onAutoFlush(DefaultAutoFlushEventListener.java:64)
 at org.hibernate.impl.SessionImpl.autoFlushIfRequired(SessionImpl.java:996)
 at org.hibernate.impl.SessionImpl.list(SessionImpl.java:1141)
 at org.hibernate.impl.QueryImpl.list(QueryImpl.java:102)
 at org.jbpm.pvm.internal.hibernate.DbSessionImpl.deleteProcessDefinitionHistory(DbSessionImpl.java:165)
 at org.jbpm.pvm.internal.cmd.DeleteDeploymentCmd.execute(DeleteDeploymentCmd.java:77)
 at org.jbpm.pvm.internal.svc.DefaultCommandService.execute(DefaultCommandService.java:42)
 at org.jbpm.pvm.internal.tx.StandardTransactionInterceptor.execute(StandardTransactionInterceptor.java:54)
 at org.jbpm.pvm.internal.svc.EnvironmentInterceptor.execute(EnvironmentInterceptor.java:54)
 at org.jbpm.pvm.internal.svc.RetryInterceptor.execute(RetryInterceptor.java:55)
 at org.jbpm.pvm.internal.repository.RepositoryServiceImpl.deleteDeploymentCascade(RepositoryServiceImpl.java:70)
 at biz.thelogicgroup.processswitch.workflow.processWorkflowTest.tearDown(processWorkflowTest.java:77)
 at junit.framework.TestCase.runBare(TestCase.java:130)
 at junit.framework.TestResult$1.protect(TestResult.java:106)
 at junit.framework.TestResult.runProtected(TestResult.java:124)
 at junit.framework.TestResult.run(TestResult.java:109)
 at junit.framework.TestCase.run(TestCase.java:118)
 at junit.framework.TestSuite.runTest(TestSuite.java:208)
 at junit.framework.TestSuite.run(TestSuite.java:203)
 at org.eclipse.jdt.internal.junit.runner.junit3.JUnit3TestReference.run(JUnit3TestReference.java:130)
 at org.eclipse.jdt.internal.junit.runner.TestExecution.run(TestExecution.java:38)
 at org.eclipse.jdt.internal.junit.runner.RemoteTestRunner.runTests(RemoteTestRunner.java:460)
 at org.eclipse.jdt.internal.junit.runner.RemoteTestRunner.runTests(RemoteTestRunner.java:673)
 at org.eclipse.jdt.internal.junit.runner.RemoteTestRunner.run(RemoteTestRunner.java:386)
 at org.eclipse.jdt.internal.junit.runner.RemoteTestRunner.main(RemoteTestRunner.java:196)
### EXCEPTION ###########################################
13:05:22,514 FIN | [ExecuteJobCmd] executing job ExecuteActivityMessage[43]...
### EXCEPTION ###########################################
13:05:22,514 INF | [DefaultCommandService] exception while executing command org.jbpm.pvm.internal.cmd.DeleteDeploymentCmd@19ed7e
org.hibernate.StaleObjectStateException: Row was updated or deleted by another transaction (or unsaved-value mapping was incorrect): [org.jbpm.pvm.internal.model.op.ExecuteActivityMessage#43]
 at org.hibernate.persister.entity.AbstractEntityPersister.check(AbstractEntityPersister.java:1792)
 at org.hibernate.persister.entity.AbstractEntityPersister.delete(AbstractEntityPersister.java:2551)
 at org.hibernate.persister.entity.AbstractEntityPersister.delete(AbstractEntityPersister.java:2725)
 at org.hibernate.action.EntityDeleteAction.execute(EntityDeleteAction.java:97)
 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:172)
 at org.hibernate.event.def.AbstractFlushingEventListener.performExecutions(AbstractFlushingEventListener.java:321)
 at org.hibernate.event.def.DefaultAutoFlushEventListener.onAutoFlush(DefaultAutoFlushEventListener.java:64)
 at org.hibernate.impl.SessionImpl.autoFlushIfRequired(SessionImpl.java:996)
 at org.hibernate.impl.SessionImpl.list(SessionImpl.java:1141)
 at org.hibernate.impl.QueryImpl.list(QueryImpl.java:102)
 at org.jbpm.pvm.internal.hibernate.DbSessionImpl.deleteProcessDefinitionHistory(DbSessionImpl.java:165)
 at org.jbpm.pvm.internal.cmd.DeleteDeploymentCmd.execute(DeleteDeploymentCmd.java:77)
 at org.jbpm.pvm.internal.svc.DefaultCommandService.execute(DefaultCommandService.java:42)
 at org.jbpm.pvm.internal.tx.StandardTransactionInterceptor.execute(StandardTransactionInterceptor.java:54)
 at org.jbpm.pvm.internal.svc.EnvironmentInterceptor.execute(EnvironmentInterceptor.java:54)
 at org.jbpm.pvm.internal.svc.RetryInterceptor.execute(RetryInterceptor.java:55)
 at org.jbpm.pvm.internal.repository.RepositoryServiceImpl.deleteDeploymentCascade(RepositoryServiceImpl.java:70)
 at biz.thelogicgroup.processswitch.workflow.processWorkflowTest.tearDown(processWorkflowTest.java:77)
 at junit.framework.TestCase.runBare(TestCase.java:130)
 at junit.framework.TestResult$1.protect(TestResult.java:106)
 at junit.framework.TestResult.runProtected(TestResult.java:124)
 at junit.framework.TestResult.run(TestResult.java:109)
 at junit.framework.TestCase.run(TestCase.java:118)
 at junit.framework.TestSuite.runTest(TestSuite.java:208)
 at junit.framework.TestSuite.run(TestSuite.java:203)
 at org.eclipse.jdt.internal.junit.runner.junit3.JUnit3TestReference.run(JUnit3TestReference.java:130)
 at org.eclipse.jdt.internal.junit.runner.TestExecution.run(TestExecution.java:38)
 at org.eclipse.jdt.internal.junit.runner.RemoteTestRunner.runTests(RemoteTestRunner.java:460)
 at org.eclipse.jdt.internal.junit.runner.RemoteTestRunner.runTests(RemoteTestRunner.java:673)
 at org.eclipse.jdt.internal.junit.runner.RemoteTestRunner.run(RemoteTestRunner.java:386)
 at org.eclipse.jdt.internal.junit.runner.RemoteTestRunner.main(RemoteTestRunner.java:196)
### EXCEPTION ###########################################
13:05:22,530 FIN | [ExecuteActivity] execution[process.39.validate red] executes activity(validate red request)
DEBUG: Validating redObj Request
DEBUG: Provider Details: red details
DEBUG: Provider Details changed to: redObj Details have been changed
13:05:22,530 FIN | [ScopeInstanceImpl] updating variable 'redObj' in 'execution[process.39]' to value 'org.application.SDM.RedObject@67c1a6'
13:05:22,530 FIN | [ExecuteActivity] execution[process.39.validate red] executes activity(join)
13:05:22,530 FIN | [ExecuteJobCmd] executed job ExecuteActivityMessage[43]
DEBUG: Validating expObj Request
DEBUG: Provider Details: some exp details
DEBUG: Provider Details changed to: expObj Details have been changed
13:05:22,545 FIN | [JobExecutorThread] took job(s) [44] from queue
13:05:22,545 FIN | [DispatcherThread] added jobs [45] to the queue
13:05:22,545 FIN | [AcquireJobsCmd] start querying first acquirable job...
13:05:22,545 FIN | [AcquireJobsCmd] locking jobs []
13:05:22,545 FIN | [GetNextDueDateCmd] getting next due date...
13:05:22,545 FIN | [GetNextDueDateCmd] next due date is null
13:05:22,545 FIN | [AcquireJobsCmd] start querying first acquirable job...
13:05:22,545 FIN | [ExecuteJobCmd] executing job ExecuteActivityMessage[44]...
13:05:22,545 FIN | [AcquireJobsCmd] locking jobs []
13:05:22,545 FIN | [GetNextDueDateCmd] getting next due date...
13:05:22,545 FIN | [GetNextDueDateCmd] next due date is null
13:05:22,545 FIN | [AcquireJobsCmd] start querying first acquirable job...
13:05:22,545 FIN | [AcquireJobsCmd] locking jobs []
13:05:22,545 FIN | [GetNextDueDateCmd] getting next due date...
13:05:22,545 FIN | [ExecuteActivity] execution[process.39.validate exp] executes activity(validate exp request)
13:05:22,545 FIN | [GetNextDueDateCmd] next due date is null
13:05:22,545 FIN | [ScopeInstanceImpl] updating variable 'expObj' in 'execution[process.39]' to value 'org.application.SDM.ExpObject@1b2b131'
13:05:22,545 FIN | [ExecuteActivity] execution[process.39.validate exp] executes activity(join)
13:05:22,545 FIN | [AcquireJobsCmd] start querying first acquirable job...
DEBUG: Validating sysObj Request
DEBUG: Provider Details: Sys Details
DEBUG: Provider Details changed to: sysObj Details have been changed
13:05:22,545 FIN | [AcquireJobsCmd] locking jobs []
13:05:22,545 FIN | [GetNextDueDateCmd] getting next due date...
13:05:22,545 FIN | [GetNextDueDateCmd] next due date is null
13:05:22,545 FIN | [AcquireJobsCmd] start querying first acquirable job...
13:05:22,545 FIN | [ExecuteJobCmd] executed job ExecuteActivityMessage[44]
13:05:22,545 FIN | [AcquireJobsCmd] locking jobs []
13:05:22,545 FIN | [GetNextDueDateCmd] getting next due date...
13:05:22,561 FIN | [GetNextDueDateCmd] next due date is null
13:05:22,561 FIN | [AcquireJobsCmd] start querying first acquirable job...
13:05:22,561 FIN | [JobExecutorThread] took job(s) [45] from queue
13:05:22,561 FIN | [ExecuteJobCmd] executing job ExecuteActivityMessage[45]...
13:05:22,561 FIN | [AcquireJobsCmd] locking jobs []
13:05:22,561 FIN | [GetNextDueDateCmd] getting next due date...
13:05:22,561 FIN | [GetNextDueDateCmd] next due date is null
13:05:22,561 FIN | [AcquireJobsCmd] start querying first acquirable job...
13:05:22,561 FIN | [AcquireJobsCmd] locking jobs []
13:05:22,561 FIN | [ExecuteActivity] execution[process.39.validate sys] executes activity(validate sys request)
13:05:22,561 FIN | [GetNextDueDateCmd] getting next due date...
13:05:22,561 FIN | [ScopeInstanceImpl] updating variable 'sysObj' in 'execution[process.39]' to value 'org.application.SDM.SysObject@13acc52'
13:05:22,561 FIN | [GetNextDueDateCmd] next due date is null
13:05:22,561 FIN | [ExecuteActivity] execution[process.39.validate sys] executes activity(join)
13:05:22,561 FIN | [AcquireJobsCmd] start querying first acquirable job...
13:05:22,561 FIN | [AcquireJobsCmd] locking jobs []
13:05:22,561 FIN | [GetNextDueDateCmd] getting next due date...
13:05:22,561 FIN | [GetNextDueDateCmd] next due date is null
13:05:22,561 FIN | [AcquireJobsCmd] start querying first acquirable job...
13:05:22,561 FIN | [AcquireJobsCmd] locking jobs []
13:05:22,561 FIN | [GetNextDueDateCmd] getting next due date...
13:05:22,561 FIN | [ExecutionImpl] execution[process.39.validate red] ends
13:05:22,561 FIN | [GetNextDueDateCmd] next due date is null
13:05:22,561 FIN | [AcquireJobsCmd] start querying first acquirable job...
13:05:22,561 FIN | [ExecutionImpl] execution[process.39.validate exp] ends
13:05:22,561 FIN | [ExecutionImpl] execution[process.39.validate sys] ends
13:05:22,561 FIN | [AcquireJobsCmd] locking jobs []
13:05:22,561 FIN | [GetNextDueDateCmd] getting next due date...
13:05:22,577 FIN | [JobExecutorMessageSession] sending message ExecuteEventListenerMessage
13:05:22,577 FIN | [GetNextDueDateCmd] next due date is null
13:05:22,577 FIN | [AcquireJobsCmd] start querying first acquirable job...
13:05:22,577 FIN | [ExecuteJobCmd] executed job ExecuteActivityMessage[45]
13:05:22,577 FIN | [AcquireJobsCmd] locking jobs []
13:05:22,577 FIN | [GetNextDueDateCmd] getting next due date...
13:05:22,577 FIN | [GetNextDueDateCmd] next due date is null
13:05:22,577 FIN | [AcquireJobsCmd] start querying first acquirable job...
13:05:22,577 FIN | [AcquireJobsCmd] locking jobs [46]
13:05:22,577 FIN | [DispatcherThread] pushing jobs on the queue [46]
13:05:22,577 FIN | [DispatcherThread] added jobs [46] to the queue
13:05:22,577 FIN | [AcquireJobsCmd] start querying first acquirable job...
13:05:22,577 FIN | [JobExecutorThread] took job(s) [46] from queue
13:05:22,577 FIN | [ExecuteJobCmd] executing job message[46]...
13:05:22,577 FIN | [AcquireJobsCmd] locking jobs []
13:05:22,577 FIN | [GetNextDueDateCmd] getting next due date...
13:05:22,577 FIN | [GetNextDueDateCmd] next due date is null
13:05:22,577 FIN | [AcquireJobsCmd] start querying first acquirable job...
13:05:22,577 FIN | [AcquireJobsCmd] locking jobs []
13:05:22,577 FIN | [GetNextDueDateCmd] getting next due date...
13:05:22,592 FIN | [GetNextDueDateCmd] next due date is null
13:05:22,592 FIN | [AcquireJobsCmd] start querying first acquirable job...
13:05:22,592 FIN | [AcquireJobsCmd] locking jobs []
13:05:22,592 FIN | [GetNextDueDateCmd] getting next due date...
13:05:22,592 FIN | [GetNextDueDateCmd] next due date is null
13:05:22,592 FIN | [AcquireJobsCmd] start querying first acquirable job...
13:05:22,592 FIN | [AcquireJobsCmd] locking jobs []
13:05:22,592 FIN | [DbSessionImpl] deleting history process instance process.39
13:05:22,592 FIN | [GetNextDueDateCmd] getting next due date...
13:05:22,592 FIN | [GetNextDueDateCmd] next due date is null
13:05:22,592 FIN | [AcquireJobsCmd] start querying first acquirable job...
13:05:22,592 FIN | [AcquireJobsCmd] locking jobs []
13:05:22,592 FIN | [GetNextDueDateCmd] getting next due date...
13:05:22,592 FIN | [GetNextDueDateCmd] next due date is null
13:05:22,592 FIN | [DbSessionImpl] deleting process instance process.39
13:05:22,608 FIN | [AcquireJobsCmd] start querying first acquirable job...
13:05:22,608 FIN | [AcquireJobsCmd] locking jobs []
13:05:22,608 FIN | [GetNextDueDateCmd] getting next due date...
13:05:22,608 FIN | [DeleteDeploymentCmd] deleting deployment 220
13:05:22,608 FIN | [GetNextDueDateCmd] next due date is null
13:05:22,624 FIN | [BaseJbpmTestCase] === ending testSimple =============================

13:05:22,624 FIN | [AcquireJobsCmd] start querying first acquirable job...
13:05:22,624 FIN | [AcquireJobsCmd] locking jobs []
13:05:22,624 FIN | [GetNextDueDateCmd] getting next due date...
13:05:22,624 FIN | [GetNextDueDateCmd] next due date is null
13:05:22,639 FIN | [AcquireJobsCmd] start querying first acquirable job...
13:05:22,639 FIN | [AcquireJobsCmd] locking jobs []

What I would expect to see is after the join a few more debug lines as follows:

DEBUG: Constructing Message
DEBUG: Sending Message
13:14:15,688 FIN | [AcquireJobsCmd] locking jobs []
13:14:15,688 FIN | [GetNextDueDateCmd] getting next due date...
13:14:15,688 FIN | [GetNextDueDateCmd] next due date is null
13:14:15,688 FIN | [AcquireJobsCmd] start querying first acquirable job...
13:14:15,688 FIN | [AcquireJobsCmd] locking jobs []
13:14:15,688 FIN | [GetNextDueDateCmd] getting next due date...
13:14:15,688 FIN | [ExecuteActivity] executing activity(construct message)
13:14:15,688 FIN | [ExecuteActivity] executing activity(send)
DEBUG: Getting Response
DEBUG: Processing Response
DEBUG: Getting Main Object and Provider Information After Change
DEBUG: redObj Details have been changed
DEBUG: expObj Details have been changed
DEBUG: sysObj Details have been changed

I only see this sometimes.... why is it so unpredictable?

[jbarrez]

I quickly went trough your unit test:

* You have at least 2 threads: the JUnit thread and x jobexecutor threads

* The JUnit thread does executes all your codes until the end. At that point, the teardown() message is called causing your processdefinition to be deleted.

* However, the JobExecutor thread is still around. Now he comes into play and tries to execute some activity of a process definition that doesn't exist anymore.

Hence, your error message ("deleted by another transaction")

Try to add Thread.sleep(10000) at the end of your unit test. It should work now. The reason why it works sometimes is because sometimes the jobexecutor is scheduled before the JUnit thread (damn parallel programming ;-)

Hope this helps

[mmusaji]

You are a star :)

I'm kicking myself for now realising this now as it's seems soo obvious, but I guess that I got so caught up with trying to figure out JBPM I was blinded so to speak!

But thank you for such a quick response and good explanation.

[kukeltje]

@Joram

Second example why deleting the processinstance immediately is a *big* issue in unittests (isEnded() also does not work in situations where it is realy ended, strange
behaviour ;-)).

I think this should become part of the dev docs, don't you?

@mmusaji,

Great that it works and sorry you had to be the guineapig for 'this' I'll try to write a blog entry about these things and/or something for the docs

[jbarrez]

@Ronald:

The problem is not that the process instance is ended. In fact, it was probably still before the join activity.

However, the tearDown() method does a deleteDeploymentCasade() which deletes everything related to the deployment (including the active process instance). I agree that's kinda confusing ... but it sure helps us writing quick tests without having to clean up our database ourselves every test.

For unit tests, there is an assertion: assertProcessInstanceEnded(String pId).

So, I don't yet see the issue with processInstances. Perhaps you can enlighten me?

[kukeltje]

Sorry, to little info from my side.

If you *do* end the process in the unit test because you want to *know* it has ended, the teardown throws an exception.

And I agree that it is much easier for us to use, but as you already mention, the 'confusion' kicks in very often. Also many people do not know the new assertions.

Maybe the teardown should check if it is still running and do the sleep itself until it checks that the process has ended or sleeps 10 seconds and then kill it anyway (but maybe also delete running jobs etc)


Off Topic: so maybe a very little amount of data could be left in the execution table e.g. the process instance id and the fact that it has ended or whatever. This one record does not really clutter the db does it? Or in some command check if there is a process id in the history table if the execution returns null, more explicit warnings can be thrown then. Tom changed the getVariable to log a message that there is no process instance but there is not process instance ACTIVE anymore. Could also be kind of confusing. And instead of documenting all this, it is probably easier to log it in a nicer way.

[mmusaji]

I don't mind being a guinea pig. I hope this helps other people who have the same issue.

Most of what you guys are saying is going over my head, however I think if the teardown waited for the process to finish this would resolve this problem quite quickly.

If I wanted to do this and override the tear down method in my Junit can you please post an example of how I would go about this? Would be a large amount of code involving checking the db or is there "isAlive()" method somewhere?

[kukeltje]

"mmusaji" wrote:
I don't mind being a guinea pig. I hope this helps other people who have the same issue.

Not only others, also us (creating awareness)

"mmusaji" wrote:

Most of what you guys are saying is going over my head, however I think if the teardown waited for the process to finish this would resolve this problem quite quickly.

Then you at least got my main point ;-)

"mmusaji" wrote:

If I wanted to do this and override the tear down method in my Junit can you please post an example of how I would go about this? Would be a large amount of code involving checking the db or is there "isAlive()" method somewhere?

The source of the AbstractDBTestcase is the basis. But just before deleting it, retrieve the processinstance based on the id, if this succeeds,, sleep, then retrieve it again based on the processInstance id. If this returns null, it is ended and you can delete it