[jboss-user] [jBPM Users] - Re: workflow design about wait states
mmusaji
do-not-reply at jboss.com
Tue Sep 15 07:19:34 EDT 2009
As expected...
| if(executionService.findProcessInstanceById(processInstanceId) != null) {
| assertFalse(processInstance.isEnded());
| }else {
| assertNull(executionService.findProcessInstanceById(processInstanceId));
| }
|
| 11:48:43,264 FIN | [BaseJbpmTestCase] === starting testProcess =============================
| 11:48:43,389 FIN | [BaseJbpmTestCase] using ProcessEngine 78236
| log4j:WARN No appenders could be found for logger (org.hibernate.cfg.Environment).
| log4j:WARN Please initialize the log4j system properly.
| 11:48:44,530 FIN | [ProcessDefinitionImpl] creating new execution for process 'process'
| 11:48:44,545 FIN | [DefaultIdGenerator] generated execution id process.363
| 11:48:44,545 FIN | [ExecuteActivity] executing activity(20045467)
| 11:48:44,545 FIN | [ExecuteActivity] executing activity(custom one)
| Executing
| custom one
| 11:48:44,561 FIN | [Signal] signalling activity(custom one), signalName=null
| 11:48:44,561 FIN | [ExecuteActivity] executing activity(fork)
| 11:48:44,561 FIN | [DefaultIdGenerator] generated execution id process.363.custom two
| 11:48:44,561 FIN | [ExecutionImpl] created execution[process.363.custom two]
| 11:48:44,561 FIN | [JobExecutorMessageSession] sending message ExecuteActivityMessage
| 11:48:44,576 INF | [JobExecutorThread] starting...
| 11:48:44,576 INF | [JobExecutorThread] starting...
| 11:48:44,576 INF | [JobExecutorThread] starting...
| 11:48:44,576 INF | [DispatcherThread] starting...
| 11:48:44,576 FIN | [DefaultIdGenerator] generated execution id process.363.custom three
| 11:48:44,576 FIN | [ExecutionImpl] created execution[process.363.custom three]
| 11:48:44,576 FIN | [JobExecutorMessageSession] sending message ExecuteActivityMessage
| 11:48:44,576 FIN | [AcquireJobsCmd] start querying first acquirable job...
| 11:48:44,576 FIN | [AcquireJobsCmd] locking jobs []
| 11:48:44,576 FIN | [GetNextDueDateCmd] getting next due date...
| 11:48:44,576 FIN | [GetNextDueDateCmd] next due date is null
| 11:48:44,576 FIN | [DispatcherThread] DispatcherThread will wait for max 600ms on org.jbpm.pvm.internal.jobexecutor.JobExecutor at 1417690
| 11:48:44,576 FIN | [DispatcherThread] DispatcherThread woke up
| 11:48:44,576 FIN | [AcquireJobsCmd] start querying first acquirable job...
| 11:48:44,592 FIN | [AcquireJobsCmd] locking jobs [519]
| 11:48:44,592 FIN | [DispatcherThread] pushing jobs on the queue [519]
| 11:48:44,592 FIN | [DispatcherThread] added jobs [519] to the queue
| 11:48:44,592 FIN | [AcquireJobsCmd] start querying first acquirable job...
| 11:48:44,592 FIN | [JobExecutorThread] took job(s) [519] from queue
| 11:48:44,592 FIN | [AcquireJobsCmd] locking jobs [520]
| 11:48:44,592 FIN | [DispatcherThread] pushing jobs on the queue [520]
| 11:48:44,592 FIN | [DispatcherThread] added jobs [520] to the queue
| 11:48:44,592 FIN | [AcquireJobsCmd] start querying first acquirable job...
| 11:48:44,592 FIN | [JobExecutorThread] took job(s) [520] from queue
| 11:48:44,608 FIN | [AcquireJobsCmd] locking jobs []
| 11:48:44,608 FIN | [ExecuteJobCmd] executing job ExecuteActivityMessage[519]...
| 11:48:44,608 FIN | [ExecuteJobCmd] executing job ExecuteActivityMessage[519]...
| 11:48:44,608 FIN | [GetNextDueDateCmd] getting next due date...
| 11:48:44,608 FIN | [GetNextDueDateCmd] next due date is null
| 11:48:44,655 FIN | [ExecuteActivity] execution[process.363.custom two] executes activity(custom two)
| 11:48:44,655 FIN | [JobExecutorMessageSession] sending message ExecuteActivityMessage
| 11:48:44,655 FIN | [ExecuteJobCmd] executing job ExecuteActivityMessage[520]...
| Executing
| custom two
| 11:48:44,670 FIN | [DispatcherThread] DispatcherThread will wait for max 600ms on org.jbpm.pvm.internal.jobexecutor.JobExecutor at 1417690
| Executing
| custom three
| Executing
| custom two
| 11:48:44,670 FIN | [ExecuteJobCmd] executed job ExecuteActivityMessage[519]
| 11:48:44,670 FIN | [ExecuteActivity] execution[process.363.custom three] executes activity(custom three)
| 11:48:44,670 FIN | [JobExecutorMessageSession] sending message ExecuteActivityMessage
| 11:48:44,670 FIN | [ExecuteJobCmd] executed job ExecuteActivityMessage[520]
| 11:48:44,670 FIN | [ExecuteActivity] execution[process.363.custom two] executes activity(custom two)
| 11:48:44,670 FIN | [JobExecutorMessageSession] sending message ExecuteActivityMessage
| 11:48:44,670 FIN | [ExecuteJobCmd] executing job ExecuteActivityMessage[520]...
| 11:48:44,670 FIN | [ExecuteJobCmd] executed job ExecuteActivityMessage[519]
| 11:48:44,670 FIN | [DispatcherThread] DispatcherThread woke up
| 11:48:44,670 FIN | [AcquireJobsCmd] start querying first acquirable job...
| 11:48:44,686 FIN | [AcquireJobsCmd] locking jobs [521, 522]
| 11:48:44,686 FIN | [DispatcherThread] pushing jobs on the queue [521, 522]
| 11:48:44,686 FIN | [DispatcherThread] added jobs [521, 522] to the queue
| 11:48:44,686 FIN | [AcquireJobsCmd] start querying first acquirable job...
| 11:48:44,686 FIN | [AcquireJobsCmd] locking jobs []
| 11:48:44,686 FIN | [GetNextDueDateCmd] getting next due date...
| 11:48:44,686 FIN | [GetNextDueDateCmd] next due date is null
| 11:48:44,686 FIN | [DispatcherThread] DispatcherThread will wait for max 600ms on org.jbpm.pvm.internal.jobexecutor.JobExecutor at 1417690
| 11:48:44,686 FIN | [JobExecutorThread] took job(s) [521, 522] from queue
| 11:48:44,686 FIN | [DispatcherThread] DispatcherThread woke up
| 11:48:44,686 FIN | [AcquireJobsCmd] start querying first acquirable job...
| Executing
| custom three
| 11:48:44,686 FIN | [AcquireJobsCmd] locking jobs []
| 11:48:44,686 FIN | [GetNextDueDateCmd] getting next due date...
| 11:48:44,686 FIN | [ExecuteActivity] execution[process.363.custom three] executes activity(custom three)
| 11:48:44,686 FIN | [JobExecutorMessageSession] sending message ExecuteActivityMessage
| 11:48:44,686 FIN | [GetNextDueDateCmd] next due date is null
| 11:48:44,686 FIN | [DispatcherThread] DispatcherThread will wait for max 600ms on org.jbpm.pvm.internal.jobexecutor.JobExecutor at 1417690
| 11:48:44,686 FIN | [ExecuteJobCmd] executed job ExecuteActivityMessage[520]
| 11:48:44,686 FIN | [ExecuteJobCmd] executing job ExecuteActivityMessage[521]...
| 11:48:44,701 FIN | [DispatcherThread] DispatcherThread woke up
| 11:48:44,701 FIN | [AcquireJobsCmd] start querying first acquirable job...
| 11:48:44,701 FIN | [ExecuteActivity] execution[process.363.custom two] executes activity(join)
| 11:48:44,701 FIN | [AcquireJobsCmd] locking jobs []
| 11:48:44,701 FIN | [GetNextDueDateCmd] getting next due date...
| 11:48:44,701 FIN | [ExecuteJobCmd] executed job ExecuteActivityMessage[521]
| 11:48:44,701 FIN | [GetNextDueDateCmd] next due date is null
| 11:48:44,701 FIN | [DispatcherThread] DispatcherThread will wait for max 600ms on org.jbpm.pvm.internal.jobexecutor.JobExecutor at 1417690
| 11:48:44,701 FIN | [ExecuteJobCmd] executing job ExecuteActivityMessage[522]...
| 11:48:44,701 FIN | [ExecuteActivity] execution[process.363.custom three] executes activity(join)
| 11:48:44,701 FIN | [ExecutionImpl] execution[process.363.custom two] ends
| 11:48:44,701 FIN | [ExecutionImpl] execution[process.363.custom three] ends
| 11:48:44,701 FIN | [ExecuteActivity] executing activity(custom four)
| Executing
| custom four
| 11:48:44,701 FIN | [ExecuteJobCmd] executed job ExecuteActivityMessage[522]
| 11:48:44,733 FIN | [ExecuteJobCmd] job 519 no longer exists
| 11:48:44,748 FIN | [ExecuteJobCmd] job 520 no longer exists
| 11:48:44,748 FIN | [Signal] signalling activity(custom four), signalName=null
| 11:48:44,748 FIN | [ExecuteActivity] executing activity(end)
| 11:48:44,764 SEV | [BaseJbpmTestCase]
| ### EXCEPTION ###########################################
| 11:48:44,764 SEV | [BaseJbpmTestCase] ASSERTION FAILURE: null
| junit.framework.AssertionFailedError
| at junit.framework.Assert.fail(Assert.java:47)
| at junit.framework.Assert.assertTrue(Assert.java:20)
| at junit.framework.Assert.assertNull(Assert.java:233)
| at junit.framework.Assert.assertNull(Assert.java:226)
| at org.workflow.test.forum.ProcessTest.testProcess(ProcessTest.java:56)
| at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
| at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
| at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
| at java.lang.reflect.Method.invoke(Method.java:597)
| at junit.framework.TestCase.runTest(TestCase.java:154)
| at org.jbpm.test.BaseJbpmTestCase.runTest(BaseJbpmTestCase.java:80)
| at junit.framework.TestCase.runBare(TestCase.java:127)
| 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 ###########################################
| 11:48:44,764 SEV | [BaseJbpmTestCase]
| 11:48:44,780 FIN | [DbSessionImpl] deleting history process instance process.363
| 11:48:44,795 FIN | [DbSessionImpl] deleting process instance process.363
| 11:48:44,795 FIN | [DeleteDeploymentCmd] deleting deployment 149
| 11:48:44,826 FIN | [BaseJbpmTestCase] === ending testProcess =============================
|
Doesn't look like the process is completing correctly. Also very randomly sometimes custom four node is running ok, and sometimes I get a failure in assertNull(executionInFour) This doesn't make much sense to me, why is it giving different outputs?
Here's an example, you can see the nodes which ran. No sign of custom four.
| 12:18:12,797 FIN | [BaseJbpmTestCase] === starting testProcess =============================
| 12:18:12,938 FIN | [BaseJbpmTestCase] using ProcessEngine 6301159
| log4j:WARN No appenders could be found for logger (org.hibernate.cfg.Environment).
| log4j:WARN Please initialize the log4j system properly.
| 12:18:14,094 FIN | [ProcessDefinitionImpl] creating new execution for process 'process'
| 12:18:14,094 FIN | [DefaultIdGenerator] generated execution id process.399
| 12:18:14,094 FIN | [ExecuteActivity] executing activity(16408563)
| 12:18:14,094 FIN | [ExecuteActivity] executing activity(custom one)
| Executing
| custom one
| 12:18:14,125 FIN | [Signal] signalling activity(custom one), signalName=null
| 12:18:14,125 FIN | [ExecuteActivity] executing activity(fork)
| 12:18:14,125 FIN | [DefaultIdGenerator] generated execution id process.399.custom two
| 12:18:14,125 FIN | [ExecutionImpl] created execution[process.399.custom two]
| 12:18:14,125 FIN | [JobExecutorMessageSession] sending message ExecuteActivityMessage
| 12:18:14,125 INF | [DispatcherThread] starting...
| 12:18:14,125 INF | [JobExecutorThread] starting...
| 12:18:14,125 INF | [JobExecutorThread] starting...
| 12:18:14,125 INF | [JobExecutorThread] starting...
| 12:18:14,141 FIN | [DefaultIdGenerator] generated execution id process.399.custom three
| 12:18:14,141 FIN | [ExecutionImpl] created execution[process.399.custom three]
| 12:18:14,141 FIN | [JobExecutorMessageSession] sending message ExecuteActivityMessage
| 12:18:14,141 FIN | [AcquireJobsCmd] start querying first acquirable job...
| 12:18:14,141 FIN | [AcquireJobsCmd] locking jobs [581]
| 12:18:14,141 FIN | [DispatcherThread] pushing jobs on the queue [581]
| 12:18:14,141 FIN | [DispatcherThread] added jobs [581] to the queue
| 12:18:14,157 FIN | [JobExecutorThread] took job(s) [581] from queue
| 12:18:14,157 FIN | [AcquireJobsCmd] start querying first acquirable job...
| 12:18:14,157 FIN | [AcquireJobsCmd] locking jobs [582]
| 12:18:14,157 FIN | [DispatcherThread] pushing jobs on the queue [582]
| 12:18:14,157 FIN | [DispatcherThread] added jobs [582] to the queue
| 12:18:14,157 FIN | [AcquireJobsCmd] start querying first acquirable job...
| 12:18:14,157 FIN | [JobExecutorThread] took job(s) [582] from queue
| 12:18:14,203 FIN | [ExecuteJobCmd] executing job ExecuteActivityMessage[581]...
| 12:18:14,203 FIN | [AcquireJobsCmd] locking jobs []
| 12:18:14,203 FIN | [GetNextDueDateCmd] getting next due date...
| 12:18:14,203 FIN | [GetNextDueDateCmd] next due date is null
| 12:18:14,203 FIN | [DispatcherThread] DispatcherThread will wait for max 600ms on org.jbpm.pvm.internal.jobexecutor.JobExecutor at cd4544
| Executing
| custom two
| Executing
| custom three
| 12:18:14,203 FIN | [ExecuteActivity] execution[process.399.custom two] executes activity(custom two)
| 12:18:14,219 FIN | [JobExecutorMessageSession] sending message ExecuteActivityMessage
| 12:18:14,219 FIN | [ExecuteJobCmd] executing job ExecuteActivityMessage[582]...
| 12:18:14,219 FIN | [ExecuteJobCmd] executed job ExecuteActivityMessage[581]
| 12:18:14,219 FIN | [ExecuteActivity] execution[process.399.custom three] executes activity(custom three)
| 12:18:14,219 FIN | [JobExecutorMessageSession] sending message ExecuteActivityMessage
| 12:18:14,219 FIN | [ExecuteJobCmd] executed job ExecuteActivityMessage[582]
| 12:18:14,219 FIN | [ExecuteJobCmd] executing job ExecuteActivityMessage[581]...
| 12:18:14,219 FIN | [DispatcherThread] DispatcherThread woke up
| Executing
| custom two
| 12:18:14,235 FIN | [AcquireJobsCmd] start querying first acquirable job...
| 12:18:14,235 FIN | [ExecuteActivity] execution[process.399.custom two] executes activity(custom two)
| 12:18:14,235 FIN | [JobExecutorMessageSession] sending message ExecuteActivityMessage
| 12:18:14,235 FIN | [ExecuteJobCmd] executed job ExecuteActivityMessage[581]
| 12:18:14,235 FIN | [AcquireJobsCmd] locking jobs [584]
| 12:18:14,235 FIN | [DispatcherThread] pushing jobs on the queue [584]
| 12:18:14,235 FIN | [DispatcherThread] added jobs [584] to the queue
| 12:18:14,235 FIN | [JobExecutorThread] took job(s) [584] from queue
| 12:18:14,235 FIN | [AcquireJobsCmd] start querying first acquirable job...
| 12:18:14,235 FIN | [AcquireJobsCmd] locking jobs []
| 12:18:14,235 FIN | [GetNextDueDateCmd] getting next due date...
| 12:18:14,235 FIN | [ExecuteJobCmd] executing job ExecuteActivityMessage[584]...
| 12:18:14,235 FIN | [GetNextDueDateCmd] next due date is null
| 12:18:14,235 FIN | [DispatcherThread] skipped wait because new message arrived
| 12:18:14,235 FIN | [AcquireJobsCmd] start querying first acquirable job...
| 12:18:14,235 FIN | [AcquireJobsCmd] locking jobs [585]
| 12:18:14,250 FIN | [DispatcherThread] pushing jobs on the queue [585]
| 12:18:14,250 FIN | [DispatcherThread] added jobs [585] to the queue
| 12:18:14,250 FIN | [JobExecutorThread] took job(s) [585] from queue
| 12:18:14,250 FIN | [AcquireJobsCmd] start querying first acquirable job...
| 12:18:14,250 FIN | [ExecuteActivity] execution[process.399.custom three] executes activity(join)
| 12:18:14,250 FIN | [ExecuteJobCmd] executing job ExecuteActivityMessage[585]...
| 12:18:14,250 FIN | [AcquireJobsCmd] locking jobs []
| 12:18:14,250 FIN | [ExecuteJobCmd] executed job ExecuteActivityMessage[584]
| 12:18:14,250 FIN | [GetNextDueDateCmd] getting next due date...
| 12:18:14,250 FIN | [GetNextDueDateCmd] next due date is null
| 12:18:14,250 FIN | [DispatcherThread] DispatcherThread will wait for max 600ms on org.jbpm.pvm.internal.jobexecutor.JobExecutor at cd4544
| 12:18:14,266 FIN | [ExecuteActivity] execution[process.399.custom two] executes activity(join)
| 12:18:14,266 FIN | [ExecuteJobCmd] executed job ExecuteActivityMessage[585]
| 12:18:14,282 FIN | [ExecuteJobCmd] job 581 no longer exists
| 12:18:14,282 FIN | [ExecuteJobCmd] job 582 no longer exists
| 12:18:14,297 SEV | [BaseJbpmTestCase]
| ### EXCEPTION ###########################################
| 12:18:14,297 SEV | [BaseJbpmTestCase] ASSERTION FAILURE: null
| junit.framework.AssertionFailedError
| at junit.framework.Assert.fail(Assert.java:47)
| at junit.framework.Assert.assertTrue(Assert.java:20)
| at junit.framework.Assert.assertNotNull(Assert.java:220)
| at junit.framework.Assert.assertNotNull(Assert.java:213)
| at org.workflow.test.forum.ProcessTest.testProcess(ProcessTest.java:53)
| at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
| at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
| at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
| at java.lang.reflect.Method.invoke(Method.java:597)
| at junit.framework.TestCase.runTest(TestCase.java:154)
| at org.jbpm.test.BaseJbpmTestCase.runTest(BaseJbpmTestCase.java:80)
| at junit.framework.TestCase.runBare(TestCase.java:127)
| 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 ###########################################
| 12:18:14,297 SEV | [BaseJbpmTestCase]
| 12:18:14,313 FIN | [DbSessionImpl] deleting history process instance process.399
| 12:18:14,328 FIN | [DbSessionImpl] deleting process instance process.399
| 12:18:14,344 FIN | [DeleteDeploymentCmd] deleting deployment 161
| 12:18:14,360 FIN | [BaseJbpmTestCase] === ending testProcess =============================
|
View the original post : http://www.jboss.org/index.html?module=bb&op=viewtopic&p=4255268#4255268
Reply to the post : http://www.jboss.org/index.html?module=bb&op=posting&mode=reply&p=4255268
More information about the jboss-user
mailing list