[jBPM Users] - Re: StaleObjectException in JBPM 4.0
by 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
View the original post : http://www.jboss.org/index.html?module=bb&op=viewtopic&p=4251457#4251457
Reply to the post : http://www.jboss.org/index.html?module=bb&op=posting&mode=reply&p=4251457
16 years, 8 months
[jBPM Users] - Re: StaleObjectException in JBPM 4.0
by mmusaji
Looking at a recent post:
http://www.jboss.org/index.html?module=bb&op=viewtopic&t=160091&postdays=...
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?
View the original post : http://www.jboss.org/index.html?module=bb&op=viewtopic&p=4251451#4251451
Reply to the post : http://www.jboss.org/index.html?module=bb&op=posting&mode=reply&p=4251451
16 years, 8 months
[jBPM Users] - Re: Solution: JBPM3 and Spring Integration
by mmusaji
"mr_magoo" wrote : Note that because of the use of the transaction template, hibernate will assume that any staleobject exception coming out of the commit is an error. It will log and throw this exception.
| Personally I think this is very bad form in a library! :) In a multi-instance environment you will have to manually silence it as these optimistic lock failures are perfectly ok. They are caught and silenced in the core jbpm executor code but of course will not occur because of the delayed commit.
|
| e.g.
| org.hibernate.StaleObjectStateException: Row was updated or deleted by another transaction (or unsaved-value mapping was incorrect): [org.jbpm.job.ExecuteNode
| | Job#140392]
| | at org.hibernate.persister.entity.AbstractEntityPersister.check(AbstractEntityPersister.java:1782)
| | [...]
| | at org.hibernate.event.def.AbstractFlushingEventListener.performExecutions(AbstractFlushingEventListener.java:321) <== CULPRIT!
| | [...]
| | at org.jbpm.SpringExecutorThread.acquireJobs(SpringExecutorThread.java:33)
| |
|
| Please note that the above code does not deal with this problem at all. You will end up with 2 logged errors for every optimistic lock failure in a multi instance environment. The errors should be benign otherwise.
|
This is good to know. I'm not using Spring but I am getting this error when I'm executing multiple jobs in parallel using JBPM 4 and MySQL. I've been seeing all sorts of posts/blogs etc skimming this issue but none explaining the cause or if there is a solution.
The problem I am having is my workflow doesn't always complete because of the errors. It seems like it's a little hit and miss and sometimes will carry on through to completion and sometimes not.
http://www.jboss.org/index.html?module=bb&op=viewtopic&t=160253
Maybe should post in another thread.
View the original post : http://www.jboss.org/index.html?module=bb&op=viewtopic&p=4251444#4251444
Reply to the post : http://www.jboss.org/index.html?module=bb&op=posting&mode=reply&p=4251444
16 years, 8 months