This may be something I don’t understand about inclusive gateways but when the attached process is executed it completes, even though the service task on one of the two branches fails with an optimistic locking exception (the exception is expected).
I would have expected the join gateway to block until all branches reach it, but that doesn’t seem to be the case here… am I missing something?
The execution log shows that the inclusive gateway starts executing even though the failed service task didn’t reach it:
15:17:41.544 [main] DEBUG c.f.b.executor.services.BpmnService - Received event PROCESS_STARTED, class FlowableProcessStartedEventImpl, context: org.flowable.common.engine.impl.interceptor.CommandContext@5f0f70c7
15:17:41.545 [main] DEBUG o.f.e.i.a.ContinueProcessOperation - Executing activityBehavior class org.flowable.engine.impl.bpmn.behavior.NoneStartEventActivityBehavior on activity 'startEvent1' with execution 66adbcff-cab7-11eb-a6dd-acde48001122
15:17:41.547 [main] DEBUG o.f.e.i.a.TakeOutgoingSequenceFlowsOperation - Leaving flow node class org.flowable.bpmn.model.StartEvent with id 'startEvent1' by following it's 1 outgoing sequenceflow
15:17:41.549 [main] DEBUG o.f.e.i.a.ContinueProcessOperation - Sequence flow 'sf1' encountered. Continuing process by following it using execution 66adbcff-cab7-11eb-a6dd-acde48001122
15:17:41.549 [main] DEBUG o.f.e.i.a.ContinueProcessOperation - Executing activityBehavior class org.flowable.engine.impl.bpmn.behavior.InclusiveGatewayActivityBehavior on activity 'fork' with execution 66adbcff-cab7-11eb-a6dd-acde48001122
15:17:41.551 [main] DEBUG o.f.e.i.a.TakeOutgoingSequenceFlowsOperation - Leaving flow node class org.flowable.bpmn.model.InclusiveGateway with id 'fork' by following it's 2 outgoing sequenceflow
15:17:41.569 [main] DEBUG o.a.i.t.jdbc.JdbcTransaction - Committing JDBC Connection [HikariProxyConnection@1947349264 wrapping conn1: url=jdbc:h2:mem:activiti7edbbd59-7b83-4edd-8397-80209e8a3ea3 user=SA]
15:17:41.570 [main] DEBUG o.a.i.t.jdbc.JdbcTransaction - Opening JDBC Connection
15:17:41.572 [main] DEBUG o.a.i.t.jdbc.JdbcTransaction - Resetting autocommit to true on JDBC Connection [HikariProxyConnection@1099892020 wrapping conn0: url=jdbc:h2:mem:activiti7edbbd59-7b83-4edd-8397-80209e8a3ea3 user=SA]
15:17:41.573 [main] DEBUG o.a.i.t.jdbc.JdbcTransaction - Closing JDBC Connection [HikariProxyConnection@1099892020 wrapping conn0: url=jdbc:h2:mem:activiti7edbbd59-7b83-4edd-8397-80209e8a3ea3 user=SA]
15:17:41.573 [main] DEBUG o.a.i.t.jdbc.JdbcTransaction - Resetting autocommit to true on JDBC Connection [HikariProxyConnection@1947349264 wrapping conn1: url=jdbc:h2:mem:activiti7edbbd59-7b83-4edd-8397-80209e8a3ea3 user=SA]
15:17:41.573 [main] DEBUG o.a.i.t.jdbc.JdbcTransaction - Closing JDBC Connection [HikariProxyConnection@1947349264 wrapping conn1: url=jdbc:h2:mem:activiti7edbbd59-7b83-4edd-8397-80209e8a3ea3 user=SA]
15:17:41.573 [flowable-async-job-executor-thread-1] DEBUG o.a.i.t.jdbc.JdbcTransaction - Opening JDBC Connection
15:17:41.573 [flowable-async-job-executor-thread-2] DEBUG o.a.i.t.jdbc.JdbcTransaction - Opening JDBC Connection
15:17:41.578 [flowable-async-job-executor-thread-1] DEBUG o.f.e.i.a.ContinueProcessOperation - Executing activityBehavior class org.flowable.engine.impl.bpmn.helper.ClassDelegate on activity 'service1' with execution 66adbcff-cab7-11eb-a6dd-acde48001122
15:17:41.578 [flowable-async-job-executor-thread-2] DEBUG o.f.e.i.a.ContinueProcessOperation - Executing activityBehavior class org.flowable.engine.impl.bpmn.helper.ClassDelegate on activity 'service2' with execution 66af1c93-cab7-11eb-a6dd-acde48001122
15:17:44.594 [flowable-async-job-executor-thread-2] INFO ParallelBranch - Service Task 2: Updated variable TheVariable to val_2
15:17:44.612 [flowable-async-job-executor-thread-2] DEBUG o.f.e.i.a.TakeOutgoingSequenceFlowsOperation - Leaving flow node class org.flowable.bpmn.model.ServiceTask with id 'service2' by following it's 1 outgoing sequenceflow
15:17:44.612 [flowable-async-job-executor-thread-2] DEBUG o.f.e.i.a.ContinueProcessOperation - Sequence flow 'sf5' encountered. Continuing process by following it using execution 66af1c93-cab7-11eb-a6dd-acde48001122
15:17:44.613 [flowable-async-job-executor-thread-2] DEBUG o.f.e.i.a.ContinueProcessOperation - Executing activityBehavior class org.flowable.engine.impl.bpmn.behavior.InclusiveGatewayActivityBehavior on activity 'join' with execution 66af1c93-cab7-11eb-a6dd-acde48001122
15:17:44.615 [flowable-async-job-executor-thread-2] DEBUG o.f.e.i.a.ExecuteInactiveBehaviorsOperation - Found InactiveActivityBehavior instance of class class org.flowable.engine.impl.bpmn.behavior.InclusiveGatewayActivityBehavior that can be executed on activity 'join'
15:17:44.627 [flowable-async-job-executor-thread-2] DEBUG o.a.i.t.jdbc.JdbcTransaction - Committing JDBC Connection [HikariProxyConnection@1369104504 wrapping conn1: url=jdbc:h2:mem:activiti7edbbd59-7b83-4edd-8397-80209e8a3ea3 user=SA]
15:17:44.628 [flowable-async-job-executor-thread-2] DEBUG o.a.i.t.jdbc.JdbcTransaction - Resetting autocommit to true on JDBC Connection [HikariProxyConnection@1369104504 wrapping conn1: url=jdbc:h2:mem:activiti7edbbd59-7b83-4edd-8397-80209e8a3ea3 user=SA]
15:17:44.628 [flowable-async-job-executor-thread-2] DEBUG o.a.i.t.jdbc.JdbcTransaction - Closing JDBC Connection [HikariProxyConnection@1369104504 wrapping conn1: url=jdbc:h2:mem:activiti7edbbd59-7b83-4edd-8397-80209e8a3ea3 user=SA]
15:17:46.594 [flowable-async-job-executor-thread-1] INFO ParallelBranch - Service Task 1: Updated variable TheVariable to val_1
15:17:46.595 [flowable-async-job-executor-thread-1] DEBUG o.f.e.i.a.TakeOutgoingSequenceFlowsOperation - Leaving flow node class org.flowable.bpmn.model.ServiceTask with id 'service1' by following it's 1 outgoing sequenceflow
15:17:46.595 [flowable-async-job-executor-thread-1] DEBUG o.f.e.i.a.ContinueProcessOperation - Sequence flow 'sf4' encountered. Continuing process by following it using execution 66adbcff-cab7-11eb-a6dd-acde48001122
15:17:46.596 [flowable-async-job-executor-thread-1] DEBUG o.f.e.i.a.ContinueProcessOperation - Executing activityBehavior class org.flowable.engine.impl.bpmn.behavior.InclusiveGatewayActivityBehavior on activity 'join' with execution 66adbcff-cab7-11eb-a6dd-acde48001122
15:17:46.599 [flowable-async-job-executor-thread-1] DEBUG o.f.e.i.a.TakeOutgoingSequenceFlowsOperation - Leaving flow node class org.flowable.bpmn.model.InclusiveGateway with id 'join' by following it's 1 outgoing sequenceflow
15:17:46.599 [flowable-async-job-executor-thread-1] DEBUG o.f.e.i.a.ContinueProcessOperation - Sequence flow 'sf6' encountered. Continuing process by following it using execution 66adbcff-cab7-11eb-a6dd-acde48001122
15:17:46.600 [flowable-async-job-executor-thread-1] DEBUG o.f.e.i.a.ContinueProcessOperation - Executing activityBehavior class org.flowable.engine.impl.bpmn.behavior.ScriptTaskActivityBehavior on activity 'log_result' with execution 66adbcff-cab7-11eb-a6dd-acde48001122
15:17:47.041 [flowable-async-job-executor-thread-1] INFO ParallelBranch - Final value: val_1
15:17:47.041 [flowable-async-job-executor-thread-1] DEBUG o.f.e.i.a.TakeOutgoingSequenceFlowsOperation - Leaving flow node class org.flowable.bpmn.model.ScriptTask with id 'log_result' by following it's 1 outgoing sequenceflow
15:17:47.042 [flowable-async-job-executor-thread-1] DEBUG o.f.e.i.a.ContinueProcessOperation - Sequence flow 'sf7' encountered. Continuing process by following it using execution 66adbcff-cab7-11eb-a6dd-acde48001122
15:17:47.042 [flowable-async-job-executor-thread-1] DEBUG o.f.e.i.a.ContinueProcessOperation - Executing activityBehavior class org.flowable.engine.impl.bpmn.behavior.NoneEndEventActivityBehavior on activity 'endEvent1' with execution 66adbcff-cab7-11eb-a6dd-acde48001122
15:17:47.042 [flowable-async-job-executor-thread-1] DEBUG c.f.b.executor.services.BpmnService - Received event ACTIVITY_STARTED, class FlowableActivityEventImpl, context: org.flowable.common.engine.impl.interceptor.CommandContext@cb5a06a
15:17:47.042 [flowable-async-job-executor-thread-1] DEBUG c.f.b.executor.services.BpmnService - Received event ACTIVITY_COMPLETED, class FlowableActivityEventImpl, context: org.flowable.common.engine.impl.interceptor.CommandContext@cb5a06a
15:17:47.042 [flowable-async-job-executor-thread-1] DEBUG o.f.e.i.a.TakeOutgoingSequenceFlowsOperation - Leaving flow node class org.flowable.bpmn.model.EndEvent with id 'endEvent1' by following it's 0 outgoing sequenceflow
15:17:47.042 [flowable-async-job-executor-thread-1] DEBUG o.f.e.i.a.TakeOutgoingSequenceFlowsOperation - No outgoing sequence flow found for flow node 'endEvent1'.
15:17:47.043 [flowable-async-job-executor-thread-1] DEBUG o.f.e.i.agenda.EndExecutionOperation - Ending execution 66adbcff-cab7-11eb-a6dd-acde48001122
15:17:47.044 [flowable-async-job-executor-thread-1] DEBUG o.f.e.i.agenda.EndExecutionOperation - Parent execution found. Continuing process using execution 66aa3a8b-cab7-11eb-a6dd-acde48001122
15:17:47.045 [flowable-async-job-executor-thread-1] DEBUG o.f.e.i.agenda.EndExecutionOperation - No parent execution found. Verifying if process instance 66aa3a8b-cab7-11eb-a6dd-acde48001122 can be stopped.
15:17:47.046 [flowable-async-job-executor-thread-1] DEBUG o.f.e.i.agenda.EndExecutionOperation - No active executions found. Ending process instance 66aa3a8b-cab7-11eb-a6dd-acde48001122
15:17:47.049 [main] INFO o.f.j.s.i.a.AbstractAsyncExecutor - Shutting down the async job executor [org.flowable.job.service.impl.asyncexecutor.DefaultAsyncJobExecutor].
15:17:47.049 [flowable-bpmn-acquire-timer-jobs] DEBUG o.f.j.s.i.a.AcquireTimerJobsRunnable - timer job acquisition thread woke up
15:17:47.049 [flowable-bpmn-acquire-async-jobs] DEBUG o.f.j.s.i.a.AcquireAsyncJobsDueRunnable - async job acquisition for engine bpmn, thread woke up
15:17:47.049 [flowable-bpmn-reset-expired-jobs] INFO o.f.j.s.i.a.ResetExpiredJobsRunnable - stopped resetting expired jobs for engine bpmn
15:17:47.049 [flowable-bpmn-acquire-timer-jobs] INFO o.f.j.s.i.a.AcquireTimerJobsRunnable - stopped async job due acquisition
15:17:47.049 [flowable-bpmn-acquire-async-jobs] INFO o.f.j.s.i.a.AcquireAsyncJobsDueRunnable - stopped async job due acquisition for engine bpmn
15:17:47.049 [main] DEBUG o.a.i.t.jdbc.JdbcTransaction - Opening JDBC Connection
15:17:47.056 [main] DEBUG o.a.i.t.jdbc.JdbcTransaction - Committing JDBC Connection [HikariProxyConnection@587346608 wrapping conn1: url=jdbc:h2:mem:activiti7edbbd59-7b83-4edd-8397-80209e8a3ea3 user=SA]
15:17:47.056 [main] DEBUG o.a.i.t.jdbc.JdbcTransaction - Resetting autocommit to true on JDBC Connection [HikariProxyConnection@587346608 wrapping conn1: url=jdbc:h2:mem:activiti7edbbd59-7b83-4edd-8397-80209e8a3ea3 user=SA]
15:17:47.056 [main] DEBUG o.a.i.t.jdbc.JdbcTransaction - Closing JDBC Connection [HikariProxyConnection@587346608 wrapping conn1: url=jdbc:h2:mem:activiti7edbbd59-7b83-4edd-8397-80209e8a3ea3 user=SA]
15:17:47.057 [main] DEBUG o.a.i.t.jdbc.JdbcTransaction - Opening JDBC Connection
15:17:47.057 [main] DEBUG o.a.i.t.jdbc.JdbcTransaction - Committing JDBC Connection [HikariProxyConnection@1962629977 wrapping conn1: url=jdbc:h2:mem:activiti7edbbd59-7b83-4edd-8397-80209e8a3ea3 user=SA]
15:17:47.057 [main] DEBUG o.a.i.t.jdbc.JdbcTransaction - Resetting autocommit to true on JDBC Connection [HikariProxyConnection@1962629977 wrapping conn1: url=jdbc:h2:mem:activiti7edbbd59-7b83-4edd-8397-80209e8a3ea3 user=SA]
15:17:47.057 [main] DEBUG o.a.i.t.jdbc.JdbcTransaction - Closing JDBC Connection [HikariProxyConnection@1962629977 wrapping conn1: url=jdbc:h2:mem:activiti7edbbd59-7b83-4edd-8397-80209e8a3ea3 user=SA]
15:17:47.058 [main] DEBUG o.a.i.t.jdbc.JdbcTransaction - Opening JDBC Connection
15:17:47.058 [main] DEBUG o.a.i.t.jdbc.JdbcTransaction - Resetting autocommit to true on JDBC Connection [HikariProxyConnection@150306380 wrapping conn1: url=jdbc:h2:mem:activiti7edbbd59-7b83-4edd-8397-80209e8a3ea3 user=SA]
15:17:47.058 [main] DEBUG o.a.i.t.jdbc.JdbcTransaction - Closing JDBC Connection [HikariProxyConnection@150306380 wrapping conn1: url=jdbc:h2:mem:activiti7edbbd59-7b83-4edd-8397-80209e8a3ea3 user=SA]
15:17:47.059 [flowable-async-job-executor-thread-1] DEBUG o.a.i.t.jdbc.JdbcTransaction - Rolling back JDBC Connection [HikariProxyConnection@624141831 wrapping conn0: url=jdbc:h2:mem:activiti7edbbd59-7b83-4edd-8397-80209e8a3ea3 user=SA]
15:17:47.059 [flowable-async-job-executor-thread-1] DEBUG o.a.i.t.jdbc.JdbcTransaction - Resetting autocommit to true on JDBC Connection [HikariProxyConnection@624141831 wrapping conn0: url=jdbc:h2:mem:activiti7edbbd59-7b83-4edd-8397-80209e8a3ea3 user=SA]
15:17:47.059 [flowable-async-job-executor-thread-1] DEBUG o.a.i.t.jdbc.JdbcTransaction - Closing JDBC Connection [HikariProxyConnection@624141831 wrapping conn0: url=jdbc:h2:mem:activiti7edbbd59-7b83-4edd-8397-80209e8a3ea3 user=SA]
15:17:47.060 [flowable-async-job-executor-thread-1] DEBUG o.a.i.t.jdbc.JdbcTransaction - Opening JDBC Connection
15:17:47.062 [flowable-async-job-executor-thread-1] ERROR o.f.j.s.i.a.DefaultAsyncRunnableExecutionExceptionHandler - Job 66af6ab7-cab7-11eb-a6dd-acde48001122 failed
org.flowable.common.engine.api.FlowableOptimisticLockingException: Execution[ id '66adbcff-cab7-11eb-a6dd-acde48001122' ] - activity 'endEvent1' - parent '66aa3a8b-cab7-11eb-a6dd-acde48001122' was updated by another transaction concurrently
at org.flowable.common.engine.impl.db.DbSqlSession.flushUpdates(DbSqlSession.java:577)
at org.flowable.common.engine.impl.db.DbSqlSession.flush(DbSqlSession.java:364)
at org.flowable.common.engine.impl.interceptor.CommandContext.flushSessions(CommandContext.java:211)
at org.flowable.common.engine.impl.interceptor.CommandContext.close(CommandContext.java:69)
at org.flowable.common.engine.impl.interceptor.CommandContextInterceptor.execute(CommandContextInterceptor.java:92)
at org.flowable.common.engine.impl.interceptor.LogInterceptor.execute(LogInterceptor.java:30)
at org.flowable.common.engine.impl.cfg.CommandExecutorImpl.execute(CommandExecutorImpl.java:56)
at org.flowable.common.engine.impl.cfg.CommandExecutorImpl.execute(CommandExecutorImpl.java:51)
at org.flowable.job.service.impl.asyncexecutor.ExecuteAsyncRunnable.executeJob(ExecuteAsyncRunnable.java:127)
at org.flowable.job.service.impl.asyncexecutor.ExecuteAsyncRunnable.run(ExecuteAsyncRunnable.java:115)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
at java.lang.Thread.run(Thread.java:748)
15:17:47.063 [flowable-async-job-executor-thread-1] DEBUG o.a.i.t.jdbc.JdbcTransaction - Opening JDBC Connection
15:17:47.063 [flowable-async-job-executor-thread-1] DEBUG o.a.i.t.jdbc.JdbcTransaction - Resetting autocommit to true on JDBC Connection [HikariProxyConnection@2077845793 wrapping conn1: url=jdbc:h2:mem:activiti7edbbd59-7b83-4edd-8397-80209e8a3ea3 user=SA]
15:17:47.063 [flowable-async-job-executor-thread-1] DEBUG o.a.i.t.jdbc.JdbcTransaction - Closing JDBC Connection [HikariProxyConnection@2077845793 wrapping conn1: url=jdbc:h2:mem:activiti7edbbd59-7b83-4edd-8397-80209e8a3ea3 user=SA]
15:17:47.064 [flowable-async-job-executor-thread-1] ERROR c.f.b.e.s.ProcessCompletionListener - ProcessCompletion future not found in internal map for process isntance id 66aa3a8b-cab7-11eb-a6dd-acde48001122
15:17:47.064 [flowable-async-job-executor-thread-1] DEBUG o.a.i.t.jdbc.JdbcTransaction - Resetting autocommit to true on JDBC Connection [HikariProxyConnection@904510468 wrapping conn0: url=jdbc:h2:mem:activiti7edbbd59-7b83-4edd-8397-80209e8a3ea3 user=SA]
15:17:47.064 [flowable-async-job-executor-thread-1] DEBUG o.a.i.t.jdbc.JdbcTransaction - Closing JDBC Connection [HikariProxyConnection@904510468 wrapping conn0: url=jdbc:h2:mem:activiti7edbbd59-7b83-4edd-8397-80209e8a3ea3 user=SA]
15:17:47.064 [flowable-async-job-executor-thread-1] DEBUG o.f.j.s.i.a.ExecuteAsyncRunnable - Optimistic locking exception during job execution. If you have multiple async executors running against the same database, this exception means that this thread tried to acquire an exclusive job, which already was changed by another async executor thread.This is expected behavior in a clustered environment. You can ignore this message if you indeed have multiple job executor threads running against the same database. Exception message: Execution[ id '66adbcff-cab7-11eb-a6dd-acde48001122' ] - activity 'endEvent1' - parent '66aa3a8b-cab7-11eb-a6dd-acde48001122' was updated by another transaction concurrently
I misread the logs… the end event is reached synchronously from the second service task, and the failure happens at that point as the transaction tries to commit.
Yes, here is a complete log (starting from the fork).
Both service tasks have the same settings: exclusive = false, async = true, regular delegate (not FutureDelegate)
17:09:44.569 [main] DEBUG o.f.e.i.a.TakeOutgoingSequenceFlowsOperation - Leaving flow node class org.flowable.bpmn.model.ParallelGateway with id 'fork' by following it's 2 outgoing sequenceflow
17:09:44.569 [main] DEBUG o.f.e.i.a.ContinueProcessOperation - Sequence flow 'sf2' encountered. Continuing process by following it using execution 8d275851-cd22-11eb-a28e-acde48001122
17:09:44.569 [main] DEBUG o.f.e.i.a.ContinueProcessOperation - Sequence flow 'sf3' encountered. Continuing process by following it using execution 8d277f65-cd22-11eb-a28e-acde48001122
17:09:44.574 [main] DEBUG o.a.i.t.jdbc.JdbcTransaction - Committing JDBC Connection [HikariProxyConnection@773865813 wrapping conn2501: url=jdbc:h2:mem:activitieb507aaa-a1dd-44f1-ba25-ef933cc134e3 user=SA]
17:09:44.577 [flowable-async-job-executor-thread-2] DEBUG o.f.e.i.a.ContinueProcessOperation - Executing activityBehavior class org.flowable.engine.impl.bpmn.helper.ClassDelegate on activity 'service2' with execution 8d277f65-cd22-11eb-a28e-acde48001122
17:09:44.577 [flowable-async-job-executor-thread-1] DEBUG o.f.e.i.a.ContinueProcessOperation - Executing activityBehavior class org.flowable.engine.impl.bpmn.helper.ClassDelegate on activity 'service1' with execution 8d275851-cd22-11eb-a28e-acde48001122
17:09:45.582 [flowable-async-job-executor-thread-1] INFO ParallelBranch - Service Task 1: Updated variable TheVariable to val_1
17:09:45.583 [flowable-async-job-executor-thread-1] DEBUG o.f.e.i.a.TakeOutgoingSequenceFlowsOperation - Leaving flow node class org.flowable.bpmn.model.ServiceTask with id 'service1' by following it's 1 outgoing sequenceflow
17:09:45.583 [flowable-async-job-executor-thread-1] DEBUG o.f.e.i.a.ContinueProcessOperation - Sequence flow 'sf4' encountered. Continuing process by following it using execution 8d275851-cd22-11eb-a28e-acde48001122
17:09:45.583 [flowable-async-job-executor-thread-1] DEBUG o.f.e.i.a.ContinueProcessOperation - Executing activityBehavior class org.flowable.engine.impl.bpmn.behavior.ParallelGatewayActivityBehavior on activity 'join' with execution 8d275851-cd22-11eb-a28e-acde48001122
17:09:45.587 [flowable-async-job-executor-thread-1] DEBUG o.a.i.t.jdbc.JdbcTransaction - Committing JDBC Connection [HikariProxyConnection@748180074 wrapping conn2502: url=jdbc:h2:mem:activitieb507aaa-a1dd-44f1-ba25-ef933cc134e3 user=SA]
17:09:46.584 [flowable-async-job-executor-thread-2] INFO ParallelBranch - Service Task 2: Updated variable TheVariable to val_1val_2
17:09:46.585 [flowable-async-job-executor-thread-2] DEBUG o.f.e.i.a.TakeOutgoingSequenceFlowsOperation - Leaving flow node class org.flowable.bpmn.model.ServiceTask with id 'service2' by following it's 1 outgoing sequenceflow
17:09:46.585 [flowable-async-job-executor-thread-2] DEBUG o.f.e.i.a.ContinueProcessOperation - Sequence flow 'sf5' encountered. Continuing process by following it using execution 8d277f65-cd22-11eb-a28e-acde48001122
17:09:46.585 [flowable-async-job-executor-thread-2] DEBUG o.f.e.i.a.ContinueProcessOperation - Executing activityBehavior class org.flowable.engine.impl.bpmn.behavior.ParallelGatewayActivityBehavior on activity 'join' with execution 8d277f65-cd22-11eb-a28e-acde48001122
17:09:46.586 [flowable-async-job-executor-thread-2] DEBUG o.f.e.i.a.TakeOutgoingSequenceFlowsOperation - Leaving flow node class org.flowable.bpmn.model.ParallelGateway with id 'join' by following it's 1 outgoing sequenceflow
17:09:46.586 [flowable-async-job-executor-thread-2] DEBUG o.f.e.i.a.ContinueProcessOperation - Sequence flow 'sf6' encountered. Continuing process by following it using execution 8d277f65-cd22-11eb-a28e-acde48001122
17:09:46.586 [flowable-async-job-executor-thread-2] DEBUG o.f.e.i.a.ContinueProcessOperation - Executing activityBehavior class org.flowable.engine.impl.bpmn.behavior.ScriptTaskActivityBehavior on activity 'log_result' with execution 8d277f65-cd22-11eb-a28e-acde48001122
17:09:46.596 [flowable-async-job-executor-thread-2] INFO ParallelBranch - Final value: val_1val_2
17:09:46.596 [flowable-async-job-executor-thread-2] DEBUG o.f.e.i.a.TakeOutgoingSequenceFlowsOperation - Leaving flow node class org.flowable.bpmn.model.ScriptTask with id 'log_result' by following it's 1 outgoing sequenceflow
17:09:46.596 [flowable-async-job-executor-thread-2] DEBUG o.f.e.i.a.ContinueProcessOperation - Sequence flow 'sf7' encountered. Continuing process by following it using execution 8d277f65-cd22-11eb-a28e-acde48001122
17:09:46.597 [flowable-async-job-executor-thread-2] DEBUG o.f.e.i.a.ContinueProcessOperation - Executing activityBehavior class org.flowable.engine.impl.bpmn.behavior.NoneEndEventActivityBehavior on activity 'endEvent1' with execution 8d277f65-cd22-11eb-a28e-acde48001122
17:09:46.597 [flowable-async-job-executor-thread-2] DEBUG o.f.e.i.a.TakeOutgoingSequenceFlowsOperation - Leaving flow node class org.flowable.bpmn.model.EndEvent with id 'endEvent1' by following it's 0 outgoing sequenceflow
17:09:46.597 [flowable-async-job-executor-thread-2] DEBUG o.f.e.i.a.TakeOutgoingSequenceFlowsOperation - No outgoing sequence flow found for flow node 'endEvent1'.
17:09:46.597 [flowable-async-job-executor-thread-2] DEBUG o.f.e.i.agenda.EndExecutionOperation - Ending execution 8d277f65-cd22-11eb-a28e-acde48001122
17:09:46.599 [flowable-async-job-executor-thread-2] DEBUG o.f.e.i.agenda.EndExecutionOperation - Parent execution found. Continuing process using execution 8d27584c-cd22-11eb-a28e-acde48001122
17:09:46.600 [flowable-async-job-executor-thread-2] DEBUG o.f.e.i.agenda.EndExecutionOperation - No parent execution found. Verifying if process instance 8d27584c-cd22-11eb-a28e-acde48001122 can be stopped.
17:09:46.601 [flowable-async-job-executor-thread-2] DEBUG o.f.e.i.agenda.EndExecutionOperation - No active executions found. Ending process instance 8d27584c-cd22-11eb-a28e-acde48001122
17:09:46.607 [flowable-async-job-executor-thread-2] DEBUG o.a.i.t.jdbc.JdbcTransaction - Committing JDBC Connection [HikariProxyConnection@1861268115 wrapping conn2503: url=jdbc:h2:mem:activitieb507aaa-a1dd-44f1-ba25-ef933cc134e3 user=SA]
17:09:46.607 [flowable-async-job-executor-thread-2] DEBUG o.a.i.t.jdbc.JdbcTransaction - Resetting autocommit to true on JDBC Connection [HikariProxyConnection@1861268115 wrapping conn2503: url=jdbc:h2:mem:activitieb507aaa-a1dd-44f1-ba25-ef933cc134e3 user=SA]
17:09:46.607 [flowable-async-job-executor-thread-2] DEBUG o.a.i.t.jdbc.JdbcTransaction - Closing JDBC Connection [HikariProxyConnection@1861268115 wrapping conn2503: url=jdbc:h2:mem:activitieb507aaa-a1dd-44f1-ba25-ef933cc134e3 user=SA]
17:09:46.608 [main] INFO o.f.j.s.i.a.AbstractAsyncExecutor - Shutting down the async job executor [org.flowable.job.service.impl.asyncexecutor.DefaultAsyncJobExecutor].
17:09:46.608 [flowable-bpmn-acquire-timer-jobs] DEBUG o.f.j.s.i.a.AcquireTimerJobsRunnable - timer job acquisition thread woke up
17:09:46.608 [flowable-bpmn-acquire-timer-jobs] INFO o.f.j.s.i.a.AcquireTimerJobsRunnable - stopped async job due acquisition
17:09:46.608 [flowable-bpmn-reset-expired-jobs] INFO o.f.j.s.i.a.ResetExpiredJobsRunnable - stopped resetting expired jobs for engine bpmn
17:09:46.608 [flowable-bpmn-acquire-async-jobs] DEBUG o.f.j.s.i.a.AcquireAsyncJobsDueRunnable - async job acquisition for engine bpmn, thread woke up
17:09:46.608 [flowable-bpmn-acquire-async-jobs] INFO o.f.j.s.i.a.AcquireAsyncJobsDueRunnable - stopped async job due acquisition for engine bpmn
17:09:46.608 [main] DEBUG o.a.i.t.jdbc.JdbcTransaction - Opening JDBC Connection
org.opentest4j.AssertionFailedError: Process should trigger a locking exception
at org.junit.jupiter.api.AssertionUtils.fail(AssertionUtils.java:39)
at org.junit.jupiter.api.Assertions.fail(Assertions.java:109)
at com.fico.bpmn.executor.test.parallel.ParallelBranchTests.testTwoDelegatesConflict(ParallelBranchTests.java:177)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:498)
at org.junit.platform.commons.util.ReflectionUtils.invokeMethod(ReflectionUtils.java:686)
at org.junit.jupiter.engine.execution.MethodInvocation.proceed(MethodInvocation.java:60)
at org.junit.jupiter.engine.execution.InvocationInterceptorChain$ValidatingInvocation.proceed(InvocationInterceptorChain.java:131)
at org.junit.jupiter.engine.extension.TimeoutExtension.intercept(TimeoutExtension.java:149)
at org.junit.jupiter.engine.extension.TimeoutExtension.interceptTestableMethod(TimeoutExtension.java:140)
at org.junit.jupiter.engine.extension.TimeoutExtension.interceptTestTemplateMethod(TimeoutExtension.java:92)
at org.junit.jupiter.engine.execution.ExecutableInvoker$ReflectiveInterceptorCall.lambda$ofVoidMethod$0(ExecutableInvoker.java:115)
at org.junit.jupiter.engine.execution.ExecutableInvoker.lambda$invoke$0(ExecutableInvoker.java:105)
at org.junit.jupiter.engine.execution.InvocationInterceptorChain$InterceptedInvocation.proceed(InvocationInterceptorChain.java:106)
at org.junit.jupiter.engine.execution.InvocationInterceptorChain.proceed(InvocationInterceptorChain.java:64)
at org.junit.jupiter.engine.execution.InvocationInterceptorChain.chainAndInvoke(InvocationInterceptorChain.java:45)
at org.junit.jupiter.engine.execution.InvocationInterceptorChain.invoke(InvocationInterceptorChain.java:37)
at org.junit.jupiter.engine.execution.ExecutableInvoker.invoke(ExecutableInvoker.java:104)
at org.junit.jupiter.engine.execution.ExecutableInvoker.invoke(ExecutableInvoker.java:98)
at org.junit.jupiter.engine.descriptor.TestMethodTestDescriptor.lambda$invokeTestMethod$6(TestMethodTestDescriptor.java:212)
at org.junit.platform.engine.support.hierarchical.ThrowableCollector.execute(ThrowableCollector.java:73)
at org.junit.jupiter.engine.descriptor.TestMethodTestDescriptor.invokeTestMethod(TestMethodTestDescriptor.java:208)
at org.junit.jupiter.engine.descriptor.TestMethodTestDescriptor.execute(TestMethodTestDescriptor.java:137)
at org.junit.jupiter.engine.descriptor.TestMethodTestDescriptor.execute(TestMethodTestDescriptor.java:71)
at org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$5(NodeTestTask.java:135)
at org.junit.platform.engine.support.hierarchical.ThrowableCollector.execute(ThrowableCollector.java:73)
at org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$7(NodeTestTask.java:125)
at org.junit.platform.engine.support.hierarchical.Node.around(Node.java:135)
at org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$8(NodeTestTask.java:123)
at org.junit.platform.engine.support.hierarchical.ThrowableCollector.execute(ThrowableCollector.java:73)
at org.junit.platform.engine.support.hierarchical.NodeTestTask.executeRecursively(NodeTestTask.java:122)
at org.junit.platform.engine.support.hierarchical.NodeTestTask.execute(NodeTestTask.java:80)
at org.junit.platform.engine.support.hierarchical.SameThreadHierarchicalTestExecutorService.submit(SameThreadHierarchicalTestExecutorService.java:32)
at org.junit.platform.engine.support.hierarchical.NodeTestTask$DefaultDynamicTestExecutor.execute(NodeTestTask.java:198)
at org.junit.jupiter.engine.descriptor.TestTemplateTestDescriptor.execute(TestTemplateTestDescriptor.java:138)
at org.junit.jupiter.engine.descriptor.TestTemplateTestDescriptor.lambda$execute$2(TestTemplateTestDescriptor.java:106)
at java.util.stream.ForEachOps$ForEachOp$OfRef.accept(ForEachOps.java:184)
at java.util.stream.ReferencePipeline$3$1.accept(ReferencePipeline.java:193)
at java.util.stream.ReferencePipeline$2$1.accept(ReferencePipeline.java:175)
at java.util.stream.ReferencePipeline$3$1.accept(ReferencePipeline.java:193)
at java.util.stream.ForEachOps$ForEachOp$OfRef.accept(ForEachOps.java:184)
at java.util.stream.ReferencePipeline$11$1.accept(ReferencePipeline.java:373)
at java.util.stream.ReferencePipeline$3$1.accept(ReferencePipeline.java:193)
at java.util.stream.ReferencePipeline$3$1.accept(ReferencePipeline.java:193)
at java.util.stream.ReferencePipeline$3$1.accept(ReferencePipeline.java:193)
at java.util.stream.ForEachOps$ForEachOp$OfRef.accept(ForEachOps.java:184)
at java.util.stream.ReferencePipeline$3$1.accept(ReferencePipeline.java:193)
at java.util.Spliterators$ArraySpliterator.forEachRemaining(Spliterators.java:948)
at java.util.stream.ReferencePipeline$Head.forEach(ReferencePipeline.java:580)
at java.util.stream.ReferencePipeline$7$1.accept(ReferencePipeline.java:270)
at java.util.stream.ReferencePipeline$3$1.accept(ReferencePipeline.java:193)
at java.util.stream.ReferencePipeline$3$1.accept(ReferencePipeline.java:193)
at java.util.Spliterators$ArraySpliterator.forEachRemaining(Spliterators.java:948)
at java.util.stream.AbstractPipeline.copyInto(AbstractPipeline.java:481)
at java.util.stream.AbstractPipeline.wrapAndCopyInto(AbstractPipeline.java:471)
at java.util.stream.ForEachOps$ForEachOp.evaluateSequential(ForEachOps.java:151)
at java.util.stream.ForEachOps$ForEachOp$OfRef.evaluateSequential(ForEachOps.java:174)
at java.util.stream.AbstractPipeline.evaluate(AbstractPipeline.java:234)
at java.util.stream.ReferencePipeline.forEach(ReferencePipeline.java:418)
at java.util.stream.ReferencePipeline$7$1.accept(ReferencePipeline.java:270)
at java.util.stream.ReferencePipeline$3$1.accept(ReferencePipeline.java:193)
at java.util.stream.ReferencePipeline$3$1.accept(ReferencePipeline.java:193)
at java.util.stream.ReferencePipeline$3$1.accept(ReferencePipeline.java:193)
at java.util.ArrayList$ArrayListSpliterator.forEachRemaining(ArrayList.java:1382)
at java.util.stream.AbstractPipeline.copyInto(AbstractPipeline.java:481)
at java.util.stream.AbstractPipeline.wrapAndCopyInto(AbstractPipeline.java:471)
at java.util.stream.ForEachOps$ForEachOp.evaluateSequential(ForEachOps.java:151)
at java.util.stream.ForEachOps$ForEachOp$OfRef.evaluateSequential(ForEachOps.java:174)
at java.util.stream.AbstractPipeline.evaluate(AbstractPipeline.java:234)
at java.util.stream.ReferencePipeline.forEach(ReferencePipeline.java:418)
at java.util.stream.ReferencePipeline$7$1.accept(ReferencePipeline.java:270)
at java.util.ArrayList$ArrayListSpliterator.forEachRemaining(ArrayList.java:1382)
at java.util.stream.AbstractPipeline.copyInto(AbstractPipeline.java:481)
at java.util.stream.AbstractPipeline.wrapAndCopyInto(AbstractPipeline.java:471)
at java.util.stream.ForEachOps$ForEachOp.evaluateSequential(ForEachOps.java:151)
at java.util.stream.ForEachOps$ForEachOp$OfRef.evaluateSequential(ForEachOps.java:174)
at java.util.stream.AbstractPipeline.evaluate(AbstractPipeline.java:234)
at java.util.stream.ReferencePipeline.forEach(ReferencePipeline.java:418)
at org.junit.jupiter.engine.descriptor.TestTemplateTestDescriptor.execute(TestTemplateTestDescriptor.java:106)
at org.junit.jupiter.engine.descriptor.TestTemplateTestDescriptor.execute(TestTemplateTestDescriptor.java:41)
at org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$5(NodeTestTask.java:135)
at org.junit.platform.engine.support.hierarchical.ThrowableCollector.execute(ThrowableCollector.java:73)
at org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$7(NodeTestTask.java:125)
at org.junit.platform.engine.support.hierarchical.Node.around(Node.java:135)
at org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$8(NodeTestTask.java:123)
at org.junit.platform.engine.support.hierarchical.ThrowableCollector.execute(ThrowableCollector.java:73)
at org.junit.platform.engine.support.hierarchical.NodeTestTask.executeRecursively(NodeTestTask.java:122)
at org.junit.platform.engine.support.hierarchical.NodeTestTask.execute(NodeTestTask.java:80)
at java.util.ArrayList.forEach(ArrayList.java:1257)
at org.junit.platform.engine.support.hierarchical.SameThreadHierarchicalTestExecutorService.invokeAll(SameThreadHierarchicalTestExecutorService.java:38)
at org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$5(NodeTestTask.java:139)
at org.junit.platform.engine.support.hierarchical.ThrowableCollector.execute(ThrowableCollector.java:73)
at org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$7(NodeTestTask.java:125)
at org.junit.platform.engine.support.hierarchical.Node.around(Node.java:135)
at org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$8(NodeTestTask.java:123)
at org.junit.platform.engine.support.hierarchical.ThrowableCollector.execute(ThrowableCollector.java:73)
at org.junit.platform.engine.support.hierarchical.NodeTestTask.executeRecursively(NodeTestTask.java:122)
at org.junit.platform.engine.support.hierarchical.NodeTestTask.execute(NodeTestTask.java:80)
at java.util.ArrayList.forEach(ArrayList.java:1257)
at org.junit.platform.engine.support.hierarchical.SameThreadHierarchicalTestExecutorService.invokeAll(SameThreadHierarchicalTestExecutorService.java:38)
at org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$5(NodeTestTask.java:139)
at org.junit.platform.engine.support.hierarchical.ThrowableCollector.execute(ThrowableCollector.java:73)
at org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$7(NodeTestTask.java:125)
at org.junit.platform.engine.support.hierarchical.Node.around(Node.java:135)
at org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$8(NodeTestTask.java:123)
at org.junit.platform.engine.support.hierarchical.ThrowableCollector.execute(ThrowableCollector.java:73)
at org.junit.platform.engine.support.hierarchical.NodeTestTask.executeRecursively(NodeTestTask.java:122)
at org.junit.platform.engine.support.hierarchical.NodeTestTask.execute(NodeTestTask.java:80)
at org.junit.platform.engine.support.hierarchical.SameThreadHierarchicalTestExecutorService.submit(SameThreadHierarchicalTestExecutorService.java:32)
at org.junit.platform.engine.support.hierarchical.HierarchicalTestExecutor.execute(HierarchicalTestExecutor.java:57)
at org.junit.platform.engine.support.hierarchical.HierarchicalTestEngine.execute(HierarchicalTestEngine.java:51)
at org.junit.platform.launcher.core.DefaultLauncher.execute(DefaultLauncher.java:248)
at org.junit.platform.launcher.core.DefaultLauncher.lambda$execute$5(DefaultLauncher.java:211)
at org.junit.platform.launcher.core.DefaultLauncher.withInterceptedStreams(DefaultLauncher.java:226)
at org.junit.platform.launcher.core.DefaultLauncher.execute(DefaultLauncher.java:199)
at org.junit.platform.launcher.core.DefaultLauncher.execute(DefaultLauncher.java:132)
at com.intellij.junit5.JUnit5IdeaTestRunner.startRunnerWithArgs(JUnit5IdeaTestRunner.java:69)
at com.intellij.rt.junit.IdeaTestRunner$Repeater.startRunnerWithArgs(IdeaTestRunner.java:33)
at com.intellij.rt.junit.JUnitStarter.prepareStreamsAndStart(JUnitStarter.java:230)
at com.intellij.rt.junit.JUnitStarter.main(JUnitStarter.java:58)
In fact I spent the day trying to figure out how to achieve “true parallel execution” with the process above… and things are far from simple.
My findings are summarized below, both tasks have identical settings (“future” means use a FutureJavaDelegate or not, “parallel” indicates the tasks actually ran concurrently).
Settings #3 yiel concurrent execution, but they rely on the same tx being shared across all tasks; this means any failure in a single task will require re-executing all the tasks.
I would like settings #5 to work: non-exclusive tasks picked up by distinct threads, and use a FutureDelegate to keep transactions short… however the FutureDelegate currently keeps a transaction open for the length of the task (even if it executes in the bg).
I am thinking I need a short transaction for the duration of afterExecute, just to read & udpate process state after the task background heavy lifting has completed… any thoughts?
The fact the “exclusive” jobs can still be executed concurrently by the main thread when they are synchronous came as a surprise, this would be worth documenting maybe?
Franck
1. isolation: read_com exclusive: true async: true future: true result: val_2val_1 parallel: false
# async=true => distinct threads and exclusive prevents // execution ("Could not lock exclusive job")
# slow since executor sleeps 10s before retrying
2. isolation: read_com exclusive: true async: true future: false result: val_2val_1 parallel: false
# Same as above, future makes no difference here
3. isolation: read_com exclusive: true async: false future: true result: val_1val_2 parallel: true
# the same thread starts the 1st task, then immediately the second one since the task execution went in the background.
# the first task to complete updates the main transaction; the second to completed picks up that change & updates as well, same tx.
# !IMPORTANT! refresh state in afterExecute!
# exclusive=true prevents 2 jobs from executing tasks in //, it doesn't prevent two tasks in the same thread from executing in //
4. isolation: read_com exclusive: true async: false future: false result: val_1val_2 parallel: false
# sequential, same tx, no issue
5. isolation: read_com exclusive: false async: true future: true result: val_1val_2 parallel: true
# Distinct threads, the 2nd task manages to commit because it refreshes its state in afterExecute, after the 1st tx has committed.
# this is dicey, and it fails at higher isolation levels
6. isolation: read_com exclusive: false async: true future: false result: FAIL parallel: true
# async=true means 2 distinct threads picked up 1 task each => commit conflict since tx starts when the task starts
# since the join gateway is sync, execution proceeds in the 2nd task's executor thread down to the end event, after which the commit fails (late detection)
7. isolation: read_com exclusive: false async: false future: true result: val_1val_2 parallel: true
# exclusive made no difference here, same thread picked the 2 tasks in sequence as in case #3
8. isolation: read_com exclusive: false async: false future: false result: val_1val_2 parallel: false
# no async continuation => single thread, executor cannot start 2nd job until the first (non-future) one completes.
