My analysis:

JBPM-4249 addresses the issue about SingletonRuntimeManager with CMT/BMT. But this BZ is a different issue. I confirmed that it's reproducible with "no CMT/BMT in BPMS 6.0.3" and "Enabled TransactionLockInterceptor in jBPM 6.1.0.Final".

I debugged with byteman (you can find logsingleton.rule in the zip) and observed the log below:

19:18:24,741 INFO  [stdout] (http-/127.0.0.1:8080-5) approveTask (taskId = 17) by jiri
19:18:24,753 INFO  [stdout] (http-/127.0.0.1:8080-5) processTaskState : ksession = org.drools.core.command.impl.CommandBasedStatefulKnowledgeSession@1cdeb03b
19:18:24,783 INFO  [stdout] (http-/127.0.0.1:8080-9) startProcess : ksession = org.drools.core.command.impl.CommandBasedStatefulKnowledgeSession@1cdeb03b
19:18:24,783 INFO  [stdout] (http-/127.0.0.1:8080-5) execute : this = org.drools.persistence.SingleSessionCommandService@7c2970f1
19:18:24,787 INFO  [stdout] (http-/127.0.0.1:8080-5) execute : this = org.drools.persistence.SingleSessionCommandService@7c2970f1
19:18:24,798 INFO  [stdout] (http-/127.0.0.1:8080-5) execute : this = org.drools.persistence.SingleSessionCommandService@7c2970f1
19:18:24,798 INFO  [stdout] (http-/127.0.0.1:8080-5) execute : this = org.drools.persistence.SingleSessionCommandService@7c2970f1
19:18:24,799 INFO  [stdout] (http-/127.0.0.1:8080-5) execute : this = org.drools.persistence.SingleSessionCommandService@7c2970f1
19:18:24,799 INFO  [stdout] (http-/127.0.0.1:8080-5) execute : this = org.drools.persistence.SingleSessionCommandService@7c2970f1
19:18:24,799 INFO  [stdout] (http-/127.0.0.1:8080-5) execute : this = org.drools.persistence.SingleSessionCommandService@7c2970f1
19:18:24,800 INFO  [stdout] (http-/127.0.0.1:8080-5) execute : this = org.drools.persistence.SingleSessionCommandService@7c2970f1
19:18:24,800 INFO  [stdout] (http-/127.0.0.1:8080-5) execute : this = org.drools.persistence.SingleSessionCommandService@7c2970f1
19:18:24,810 INFO  [stdout] (http-/127.0.0.1:8080-9) execute : this = org.drools.persistence.SingleSessionCommandService@7c2970f1
19:18:24,813 INFO  [stdout] (http-/127.0.0.1:8080-9) execute : this = org.drools.persistence.SingleSessionCommandService@7c2970f1
19:18:24,823 INFO  [stdout] (http-/127.0.0.1:8080-5) disconnect : this = WorkflowProcessInstance9 [processId=com.sample.rewards-basic,state=1]
19:18:24,823 INFO  [stdout] (http-/127.0.0.1:8080-5) disconnect : this = WorkflowProcessInstance11 [processId=com.sample.rewards-basic,state=1]
19:18:24,825 INFO  [stdout] (http-/127.0.0.1:8080-9) getProcess null : this = WorkflowProcessInstance11 [processId=com.sample.rewards-basic,state=1]
19:18:24,832 INFO  [stdout] (http-/127.0.0.1:8080-9) getProcess null : this = WorkflowProcessInstance11 [processId=com.sample.rewards-basic,state=1]
19:18:24,832 INFO  [stdout] (http-/127.0.0.1:8080-9) getProcess null : this = WorkflowProcessInstance11 [processId=com.sample.rewards-basic,state=1]
19:18:24,832 WARN  [org.drools.persistence.SingleSessionCommandService] (http-/127.0.0.1:8080-9) Could not commit session: java.lang.RuntimeException: Process instance 11[com.sample.rewards-basic] is disconnected.
	at org.jbpm.process.instance.impl.ProcessInstanceImpl.getProcess(ProcessInstanceImpl.java:90) [jbpm-flow-6.0.3-redhat-6.jar:6.0.3-redhat-6]
	at org.jbpm.process.instance.impl.ProcessInstanceImpl.getContextInstance(ProcessInstanceImpl.java:161) [jbpm-flow-6.0.3-redhat-6.jar:6.0.3-redhat-6]
	at org.jbpm.workflow.instance.WorkflowRuntimeException.initialize(WorkflowRuntimeException.java:56) [jbpm-flow-6.0.3-redhat-6.jar:6.0.3-redhat-6]
	at org.jbpm.workflow.instance.WorkflowRuntimeException.<init>(WorkflowRuntimeException.java:42) [jbpm-flow-6.0.3-redhat-6.jar:6.0.3-redhat-6]
	at org.jbpm.workflow.instance.impl.NodeInstanceImpl.trigger(NodeInstanceImpl.java:161) [jbpm-flow-6.0.3-redhat-6.jar:6.0.3-redhat-6]
	at org.jbpm.ruleflow.instance.RuleFlowProcessInstance.internalStart(RuleFlowProcessInstance.java:35) [jbpm-flow-6.0.3-redhat-6.jar:6.0.3-redhat-6]
	at org.jbpm.process.instance.impl.ProcessInstanceImpl.start(ProcessInstanceImpl.java:226) [jbpm-flow-6.0.3-redhat-6.jar:6.0.3-redhat-6]
	at org.jbpm.workflow.instance.impl.WorkflowProcessInstanceImpl.start(WorkflowProcessInstanceImpl.java:363) [jbpm-flow-6.0.3-redhat-6.jar:6.0.3-redhat-6]
	at org.jbpm.process.instance.ProcessRuntimeImpl.startProcessInstance(ProcessRuntimeImpl.java:194) [jbpm-flow-6.0.3-redhat-6.jar:6.0.3-redhat-6]
	at org.jbpm.process.instance.ProcessRuntimeImpl.startProcess(ProcessRuntimeImpl.java:176) [jbpm-flow-6.0.3-redhat-6.jar:6.0.3-redhat-6]
	at org.jbpm.process.instance.ProcessRuntimeImpl.startProcess(ProcessRuntimeImpl.java:168) [jbpm-flow-6.0.3-redhat-6.jar:6.0.3-redhat-6]
	at org.drools.core.common.AbstractWorkingMemory.startProcess(AbstractWorkingMemory.java:1575) [drools-core-6.0.3-redhat-6.jar:6.0.3-redhat-6]
	at org.drools.core.impl.StatefulKnowledgeSessionImpl.startProcess(StatefulKnowledgeSessionImpl.java:366) [drools-core-6.0.3-redhat-6.jar:6.0.3-redhat-6]
	at org.drools.core.command.runtime.process.StartProcessCommand.execute(StartProcessCommand.java:121) [drools-core-6.0.3-redhat-6.jar:6.0.3-redhat-6]
	at org.drools.core.command.runtime.process.StartProcessCommand.execute(StartProcessCommand.java:40) [drools-core-6.0.3-redhat-6.jar:6.0.3-redhat-6]
	at org.drools.core.command.impl.DefaultCommandService.execute(DefaultCommandService.java:36) [drools-core-6.0.3-redhat-6.jar:6.0.3-redhat-6]
	at org.drools.core.command.impl.AbstractInterceptor.executeNext(AbstractInterceptor.java:41) [drools-core-6.0.3-redhat-6.jar:6.0.3-redhat-6]
	at org.drools.persistence.SingleSessionCommandService$TransactionInterceptor.execute(SingleSessionCommandService.java:533) [drools-persistence-jpa-6.0.3-redhat-6.jar:6.0.3-redhat-6]
	at org.drools.core.command.impl.AbstractInterceptor.executeNext(AbstractInterceptor.java:41) [drools-core-6.0.3-redhat-6.jar:6.0.3-redhat-6]
	at org.drools.persistence.jpa.OptimisticLockRetryInterceptor.execute(OptimisticLockRetryInterceptor.java:73) [drools-persistence-jpa-6.0.3-redhat-6.jar:6.0.3-redhat-6]
	at org.drools.persistence.SingleSessionCommandService.execute(SingleSessionCommandService.java:377) [drools-persistence-jpa-6.0.3-redhat-6.jar:6.0.3-redhat-6]
	at org.drools.core.command.impl.CommandBasedStatefulKnowledgeSession.startProcess(CommandBasedStatefulKnowledgeSession.java:232) [drools-core-6.0.3-redhat-6.jar:6.0.3-redhat-6]
	at org.jbpm.examples.ejb.ProcessBean.startProcess(ProcessBean.java:68) [classes:]
...

This indicates that thread#8080-9 was working inside the synchronized SingleSessionCommandService.execute() but thread#8080-5 disconnected the process instance (#11).

Why possible? Because thread#8080-5 called ProcessRuntimeImpl.clearProcessInstances() on afterCompletion() and the commit was issued by TaskTransactionInterceptor (not by SingleSessionCommandService$TransactionInterceptor).

Daemon Thread [http-/127.0.0.1:8080-5] (Suspended (breakpoint at line 235 in ProcessInstanceImpl)) (out of synch)	
	owns: Object  (id=21903)	
	owns: TaskTransactionInterceptor  (id=21904)	
	RuleFlowProcessInstance(ProcessInstanceImpl).disconnect() line: 235	
	RuleFlowProcessInstance(WorkflowProcessInstanceImpl).disconnect() line: 320	
	JPAProcessInstanceManager.clearProcessInstances() line: 164	
	ProcessRuntimeImpl.clearProcessInstances() line: 470	
	SingleSessionCommandService$SynchronizationImpl.afterCompletion(int) line: 463	
	TransactionSynchronizationContainer.afterCompletion(int) line: 26	
	JtaTransactionSynchronizationAdapter.afterCompletion(int) line: 22	
	SynchronizationImple.afterCompletion(int) line: 96	
	AtomicAction(TwoPhaseCoordinator).afterCompletion(int, boolean) line: 402	
	AtomicAction(TwoPhaseCoordinator).end(boolean) line: 103	
	AtomicAction(AtomicAction).commit(boolean) line: 162	
	TransactionImple.commitAndDisassociate() line: 1165	
	TransactionManagerImple(BaseTransaction).commit() line: 126	
	TransactionManagerDelegate(BaseTransactionManagerDelegate).commit() line: 75	
	ServerVMClientUserTransaction.commit() line: 167	
	JtaTransactionManager.commit(boolean) line: 210	
	TaskTransactionInterceptor.execute(Command<T>) line: 56	
	TaskCommandExecutorImpl.execute(Command<T>) line: 40	
	CommandBasedTaskService.complete(long, String, Map<String,Object>) line: 144	
	TaskBean.approveTask(String, long) line: 68 (out of synch)
...

So this disconnection can happen even during the other thread's synchronized SingleSessionCommandService.execute().

Hmm, if my analysis is correct, TransactionLockInterceptor should be able to help...? I will test TransactionLockInterceptor again and investigate what is going on...

Okay, I seemed to have misread my results before.

Now I have re-tested the following combinations:

A) BPMS 6.0.3 (6.0.3-redhat-6) + Singleton
 -> Frequent "Process instance XXX is disconnected."

B) jBPM 6.1.0.Final + Singleton 
 -> Frequent "Process instance XXX is disconnected."

C) jBPM 6.1.0.Final + Singleton + TransactionLockInterceptor enabled
 -> No issue

D) jBPM 6.1.0.Final + Singleton + BMT + TransactionLockInterceptor enabled
 -> Non-frequent "javax.persistence.TransactionRequiredException: No active JTA transaction on joinTransaction call"

So, I must say that TransactionLockInterceptor (JBPM-4249) fixed this BZ's issue as well. The pattern D) seems to tell that TransactionLockInterceptor is not perfect because it depends on transaction synchronization order. But anyway, this BZ will be fixed in BPMS 6.1.0 by enabling TransactionLockInterceptor.

Now, I feel like voting TransactionLockInterceptor default to "enabled" for SingletonRuntimeManager because this disconnect issue is reproducible with Human Task scenario even without CMT/BMT (Outer transaction by TaskTransactionInterceptor).

WDYT, Maciej?

---------------------------------
FYI) Log when pattern D) reproduced:
===
22:34:57,125 DEBUG [org.drools.persistence.jta.TransactionLockInterceptor] (http-/127.0.0.1:8080-9) About to register lock release handler by http-/127.0.0.1:8080-9
22:34:57,125 DEBUG [org.drools.persistence.jta.TransactionLockInterceptor] (http-/127.0.0.1:8080-1) About to get a lock on command service by http-/127.0.0.1:8080-1
22:34:57,125 INFO  [stdout] (http-/127.0.0.1:8080-9) Process started ... : processInstanceId = 271
22:34:57,126 INFO  [stdout] (http-/127.0.0.1:8080-5) approveTask (taskId = 539) by jiri
22:34:57,128 DEBUG [org.drools.persistence.jta.TransactionLockInterceptor] (http-/127.0.0.1:8080-9) Releasing on transaction completion by http-/127.0.0.1:8080-9
22:34:57,128 DEBUG [org.drools.persistence.jta.TransactionLockInterceptor] (http-/127.0.0.1:8080-9) Successfully released lock by http-/127.0.0.1:8080-9
22:34:57,128 DEBUG [org.drools.persistence.jta.TransactionLockInterceptor] (http-/127.0.0.1:8080-1) Lock taken by http-/127.0.0.1:8080-1
22:34:57,128 WARN  [org.drools.persistence.SingleSessionCommandService] (http-/127.0.0.1:8080-1) Could not commit session: javax.persistence.TransactionRequiredException: No active JTA transaction on joinTransaction call
	at org.hibernate.ejb.AbstractEntityManagerImpl.joinTransaction(AbstractEntityManagerImpl.java:1233) [hibernate-entitymanager-4.2.7.SP1-redhat-3.jar:4.2.7.SP1-redhat-3]
	at org.hibernate.ejb.AbstractEntityManagerImpl.joinTransaction(AbstractEntityManagerImpl.java:1183) [hibernate-entitymanager-4.2.7.SP1-redhat-3.jar:4.2.7.SP1-redhat-3]
	at org.drools.persistence.jpa.JpaPersistenceContext.joinTransaction(JpaPersistenceContext.java:66) [drools-persistence-jpa-6.1.0.Final.jar:6.1.0.Final]
	at org.drools.persistence.SingleSessionCommandService$TransactionInterceptor.execute(SingleSessionCommandService.java:490) [drools-persistence-jpa-6.1.0.Final.jar:6.1.0.Final]
	at org.drools.core.command.impl.AbstractInterceptor.executeNext(AbstractInterceptor.java:41) [drools-core-6.1.0.Final.jar:6.1.0.Final]
	at org.drools.persistence.jpa.OptimisticLockRetryInterceptor.execute(OptimisticLockRetryInterceptor.java:73) [drools-persistence-jpa-6.1.0.Final.jar:6.1.0.Final]
	at org.drools.core.command.impl.AbstractInterceptor.executeNext(AbstractInterceptor.java:41) [drools-core-6.1.0.Final.jar:6.1.0.Final]
	at org.drools.persistence.jta.TransactionLockInterceptor.execute(TransactionLockInterceptor.java:72) [drools-persistence-jpa-6.1.0.Final.jar:6.1.0.Final]
===

thanks for details analysis Toshiya. 

Not fully convinced we should enable transaction lock interceptor by default but from the other hand don't see any negative side effects of doing so. Singleton runtime manager could simply enable it via environment so no need to set any system properties.

Shall we then enable it singleton runtime manager? Votes please :) 

And you're right, transaction lock interceptor is not perfect either but it does cover majority of cases where race condition might affect the execution but still leaves some cases uncovered as you mentioned due to transaction sync order. Although not sure we can do much about it.

transaction lock interceptor enabled by default for singleton strategy, tough when there is any setting regarding transaction lock interceptor (either via environment entry or system property) defaults are not set.

jbpm
master:
https://github.com/droolsjbpm/jbpm/commit/f082b82c9047ee41c82001d7c0d86673f1eda82d

6.2.x:
https://github.com/droolsjbpm/jbpm/commit/49f1d4977966544118e35337d4baba3138b1a0f6

Created attachment 975165 [details]
rewards-basic.zip

Toshiya,
Thank you for the reproducer. I was able to reproduce the issue as you reported it using BPMS 6.0.3 and EAP 6.1.1.

I had to update the example rewards-basic application for version 6.1.0.ER3 of BPM Suite, here is the current list of changes made:
https://mojo.redhat.com/docs/DOC-1005328

I got to a point, where the rewards-basic for BPMS 6.1.0.ER3 can be deployed on EAP 6.3, the rewards process can be started and the first task completed. However the second task does not appear in mary's list of tasks, so I cannot run your jmeter scenario. There is no exception.

Maciej,
Can you please take a look on rewards-basic web application updated for BPMS 6.1.0.ER3? The second human task does not appear, there is no exception and I am unable to verify the fix of this issue.

Jiri,

since you inject TaskService it misses the event listener to inform process about task completion and thus it does not move to the second task. To overcome this you can simply add such a class you your project that will automatically bind it to every task service instance:

package org.jbpm.examples.util;

import javax.enterprise.context.ApplicationScoped;

import org.jbpm.services.task.wih.ExternalTaskEventListener;

@ApplicationScoped
public class CdiExternalTaskEventListener extends ExternalTaskEventListener {

}

Created attachment 977344 [details]
server-log-bpms610er3.log

Thanks Maciej!

I have added CdiExternalTaskEventListener as you suggested to the attached rewards-basic.zip, which uses BPM Suite 6.1.0.ER3. The problem with second task in the process has been fixed.

I have tried to run jmeter test plan with 10 threads and 10 loops.
I can confirm that the original problem has been fixed, there is no more message that the 'Process instance XXX is disconnected.'

p.s. However when the process instance id=64 is started, an OptimisticLockingException is thrown:

15:28:47,283 INFO  [stdout] (http-/127.0.0.1:8080-6) Process started ... : processInstanceId = 64
15:28:47,287 WARN  [com.arjuna.ats.arjuna] (http-/127.0.0.1:8080-10) ARJUNA012125: TwoPhaseCoordinator.beforeCompletion - failed for SynchronizationImple< 0:ffff0a221e05:7ccaf2d2:54ad423f:d03, org.hibernate.engine.transaction.synchronization.internal.RegisteredSynchronization@60ebdb57 >: javax.persistence.OptimisticLockException: Row was updated or deleted by another transaction (or unsaved-value mapping was incorrect): [org.jbpm.services.task.impl.model.TaskImpl#125]

The whole server.log is attached.

Toshiya, is this expected? Thanks.

The reported problem has been fixed. Verified in BPM Suite 6.1.0.ER3.

There may be another problem, so if confirmed a new bugzilla will be filed.

Hi Jiri,

I tested the attached rewards-basic.zip with 6.2.0-SNAPSHOT + EAP 6.3.0.

I also observed OptimisticLockException with 10 threads * 10 loops.

=====
17:07:17,475 INFO  [stdout] (http-/127.0.0.1:8080-1) retrieveTaskList by mary
17:07:17,476 INFO  [stdout] (http-/127.0.0.1:8080-1)  task.getId() = 104
17:07:17,476 INFO  [stdout] (http-/127.0.0.1:8080-1)  task.getId() = 103
17:07:17,478 INFO  [stdout] (http-/127.0.0.1:8080-1) approveTask (taskId = 104) by mary
17:07:17,483 INFO  [stdout] (http-/127.0.0.1:8080-10) retrieveTaskList by mary
17:07:17,483 INFO  [stdout] (http-/127.0.0.1:8080-10)  task.getId() = 104
17:07:17,483 INFO  [stdout] (http-/127.0.0.1:8080-10)  task.getId() = 103
17:07:17,486 INFO  [stdout] (http-/127.0.0.1:8080-10) approveTask (taskId = 104) by mary
17:07:17,494 INFO  [stdout] (http-/127.0.0.1:8080-7) Process started ... : processInstanceId = 53
17:07:17,496 WARN  [com.arjuna.ats.arjuna] (http-/127.0.0.1:8080-1) ARJUNA012125: TwoPhaseCoordinator.beforeCompletion - failed for SynchronizationImple<0:ffff7f000001:785d43fd:54ae2e2a:2c64, org.hibernate.engine.transaction.synchronization.internal.RegisteredSynchronization@3fded465 >: javax.persistence.OptimisticLockException: Row was updated or deleted by another transaction (or unsaved-value mapping was incorrect): [org.jbpm.services.task.impl.model.TaskImpl#104]
	at org.hibernate.ejb.AbstractEntityManagerImpl.wrapStaleStateException(AbstractEntityManagerImpl.java:1413) [hibernate-entitymanager-4.2.14.SP1-redhat-1.jar:4.2.14.SP1-redhat-1]
...
=====

Thread#8080-1 and #8080-10 tried to start(or complete) the same task#104 so OptimisticLockException is an expected result. Please check the stdout logs to see if you face the same scenario.

Jiri,

I think it's odd that TaskService is not singleton while RuntimeManager is singleton in the rewards-basic (So synchronization of TaskTransactionInterceptor.execute() doesn't work).

Don't you follow this practice?

- Use TaskService taken from RuntimeManager for write operations (e.g. start, complete etc.)

- Use independent TaskService (e.g. injected) for read operations

I wrote the practice based on PerProcessInstance but it would be applied to Singleton as well https://access.redhat.com/solutions/1278833

WDYT?

I sent a PR for your master (PerProcessInstance).

https://github.com/jsvitak/jbpm-6-examples/pull/8

Created attachment 979498 [details]
rewards-basic-BZ1161574-singleton-taskService.zip

=== IMPORTANT NOTE ===

This BZ was marked as "VERIFIED" but actually, this is "NOTABUG".

The first reproducer "rewards-basic-bpms603-singleton-no-outer-tx.zip" uses an injected TaskService to complete a Task. This is an invalid use of API. If you use a TaskService (= SynchronizedTaskService) taken from Singleton RuntimeEngine, the transaction is protected and "Process instance XXX is disconnected" will not happen.

The last reproducer "rewards-basic-BZ1161574-singleton-taskService.zip" does correctly use a TaskService taken from Singleton RuntimeEngine so the "disconnected" issue is not reproducible even if you disable TransactionLockInterceptor.

So enabling TransactionLockInterceptor by default was not necessary. I filed another BZ to revert back the default.

https://bugzilla.redhat.com/show_bug.cgi?id=1258797