6.0.1.Final transaction completion bug

[jay.guidos-bidstrading.com]

Hi All,

I have a new problem in 6.0.1.Final that was not in 6.0.0.Final.

I have a process that starts in an EJB and the process launches a Work Item. The work item runs in its own thread, and after the work is done it updates the kieSession agenda. Depending on timing, the EJB method may complete before the work item does, as the process start() method does not wait for the process to finish.

In 6.0.0 this all worked fine, but in 6.0.1 the hibernate triggers have been changed around somewhat and I get an exception if the work item completes before the EJB method's transaction completed.  The basic sequence of events is:

Thread 1: <start TX-1>

Thread 1: EJB-method: startProcess()

Thread 1: start work item, create thread 2

     Thread 2:  do work

     Thread 2: <start TX-2>

     Thread 2: update session agenda

     Thread 2: <end TX-2>

     Thread 2: complete work item

Thread 1: EJB-method end

Thread 1: <end TX-1>

The problem is that TX-2 causes the JPA process instance manager to disconnect all its process instances, and then throw away the kruntime and process data:

org.jbpm.process.instance.impl.ProcessInstanceImpl

    public void disconnect() {
        ((InternalProcessRuntime) kruntime.getProcessRuntime()).getProcessInstanceManager().internalRemoveProcessInstance(this);
        process = null;
        kruntime = null;
    }

Then when the hibernate update triggers fire at the conclusion of TX-1 I get the exception trace I included below.  Note that if I manage to get TX-1 completed before Thread 2 completes it's transaction then I am ok, because Thread 2 does not update the process.

I hacked a fix by not throwing away the process during the disconnect (commenting out line 5, above) which solves the problem but is fundamentally wrong. Is this a new bug or should I be doing things differently?

Jay

Caused by: java.lang.RuntimeException: Process instance 1[BidsDay.TestJobControl] is disconnected.
  at org.jbpm.process.instance.impl.ProcessInstanceImpl.getProcess(ProcessInstanceImpl.java:90) [jbpm-flow-6.0.1.Final.jar:6.0.1.Final]
  at org.jbpm.persistence.processinstance.ProcessInstanceInfo.update(ProcessInstanceInfo.java:225) [jbpm-persistence-jpa-6.0.1.Final.jar:6.0.1.Final]
  at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) [rt.jar:1.7.0_17]
  at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57) [rt.jar:1.7.0_17]
  at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) [rt.jar:1.7.0_17]
  at java.lang.reflect.Method.invoke(Method.java:601) [rt.jar:1.7.0_17]
  at org.hibernate.ejb.event.BeanCallback.invoke(BeanCallback.java:39) [hibernate-entitymanager-4.0.1.Final.jar:4.0.1.Final]
  at org.hibernate.ejb.event.EntityCallbackHandler.callback(EntityCallbackHandler.java:110) [hibernate-entitymanager-4.0.1.Final.jar:4.0.1.Final]
  at org.hibernate.ejb.event.EntityCallbackHandler.preUpdate(EntityCallbackHandler.java:95) [hibernate-entitymanager-4.0.1.Final.jar:4.0.1.Final]
  at org.hibernate.ejb.event.EJB3FlushEntityEventListener.invokeInterceptor(EJB3FlushEntityEventListener.java:65) [hibernate-entitymanager-4.0.1.Final.jar:4.0.1.Final]
  at org.hibernate.event.internal.DefaultFlushEntityEventListener.handleInterception(DefaultFlushEntityEventListener.java:315) [hibernate-core-4.0.1.Final.jar:4.0.1.Final]
  at org.hibernate.event.internal.DefaultFlushEntityEventListener.scheduleUpdate(DefaultFlushEntityEventListener.java:266) [hibernate-core-4.0.1.Final.jar:4.0.1.Final]
  at org.hibernate.event.internal.DefaultFlushEntityEventListener.onFlushEntity(DefaultFlushEntityEventListener.java:149) [hibernate-core-4.0.1.Final.jar:4.0.1.Final]
  at org.hibernate.event.internal.AbstractFlushingEventListener.flushEntities(AbstractFlushingEventListener.java:225) [hibernate-core-4.0.1.Final.jar:4.0.1.Final]
  at org.hibernate.event.internal.AbstractFlushingEventListener.flushEverythingToExecutions(AbstractFlushingEventListener.java:99) [hibernate-core-4.0.1.Final.jar:4.0.1.Final]
  at org.hibernate.event.internal.DefaultFlushEventListener.onFlush(DefaultFlushEventListener.java:51) [hibernate-core-4.0.1.Final.jar:4.0.1.Final]
  at org.hibernate.internal.SessionImpl.flush(SessionImpl.java:1081) [hibernate-core-4.0.1.Final.jar:4.0.1.Final]
  at org.hibernate.internal.SessionImpl.managedFlush(SessionImpl.java:315) [hibernate-core-4.0.1.Final.jar:4.0.1.Final]
  at org.hibernate.engine.transaction.synchronization.internal.SynchronizationCallbackCoordinatorImpl.beforeCompletion(SynchronizationCallbackCoordinatorImpl.java:104) [hibernate-core-4.0.1.Final.jar:4.0.1.Final]

[swiderski.maciej]

looks like you're sharing process instance in your work item, if it's async operation (like you said runs in separate thread) you should not share the instance of process instance but rather load it from ksession when actually needed - after the works has been done by the work item handler. Another note is that with such design you explicitly asking for race condition as both (start process and async operation) will try to alter same process instance which could lead to optimistic locking exception.

That is just a wild gues as I haven't seen the actual code.

HTH

[jay.guidos-bidstrading.com]

Hi Maciej,

Well thats the thing. As far as I know I am not accessing any process instance inside of my worker thread. As a test, I boiled my WorkItem down to this, and I still see the same transaction issue.  The code below works in 6.0.0, but not in 6.0.1.

What do you think?

   public void executeWorkItem(WorkItem workItem, WorkItemManager manager)

    {

        workerThread.set(new Thread(new Runnable(){

            public void run()

            {

                getKsession().insert(new WorkDone("TestMePlease"));

            }

        }, THREAD_NAME_PREFIX + (threadCounter++)));

        workerThread.get().start();

    }

[swiderski.maciej]

and how do you get access to ksession?

another thing is there any rule that will react on the inserted fact that might impact the processing? You mentioned as well that there is transaction start and end in the work item handler but can't seem to find it in the code you provided. What would be good to see is to have complete stack trace and bit more details about the calls that are done when you execute the process.

HTH

[jay.guidos-bidstrading.com]

That is the ksession that comes from the caller thread.  I don't do any explicit transaction management on the worker thread, but the session implementation is the Command-based one, which does its own transaction management I believe.

I think maybe I am just on the wrong track here. What is the CORRECT way to obtain another ksession from within the worker thread?  I had tried to load a new ksession from the runtime in my worker thread, but that ended up triggering all the work item handler producers and so on, causing all kinds of other issues.  Maybe you could suggest the right approach?

Jay

[swiderski.maciej]

could you please first describe what's your use case and what you try to do? As spinning another thread to insert fact into a session looks like an overkill.

If you have some part of your app that could be shared as reproducer that would be excellent as indeed it might be a bug. I'll try to build up a reproducer for that but I am afraid it's related to ejb etc as transaction is handled on EJB layer (CMT) and somehow you bypass the lock on ksession as it should not be allowed to call another operation on same ksession from another thread until it's still running - command based ksession is synchronized on command execution level.

And complete stack trace please

HTH

[jay.guidos-bidstrading.com]

Hi Maciej!

The code I showed you was not my real code, it was a snippet I made to reproduce the bug.  My 'real' work item handler executes a long running process (3 to 5 minutes) and then updates the ksession with the result.  I stripped out everything but the result update in order to show you the problem.

I have already promised you an EJB sample app, this is as good a time as any to get it to you.  I will make it up today, can you remind me again what repo to push it to?  I will leave in the bug-repoducing code,  you can use that as your test case.

Jay

[swiderski.maciej]

Excellent Jay, feel free to leave it on your github and I'll clone from there.

Cheers

[jay.guidos-bidstrading.com]

Hi Maciej,

As promised, I have put up a fully functioning EJB-based KIE application: https://github.com/jayguidos/jbpm-ejb-example-app

As noted in the README of that project, I also posted a KIE project that it will run with at:  https://github.com/jayguidos/jbpm-ejb-example-kie-project

This is a cut-down version of our actual application, with a single process KIE project and a single custom threaded work item (our actual project has about a dozen custom work items).

I have it running against 6.0.1.Final, with a patch to avoid the transaction bug you and I are discussing (I notice a few more posts of people hitting the same bug now).  You should be able to follow the instructions to get it installed and running.

Please let me know if you are having trouble and I will fix and/or enhance the instructions to make it more clear.

I have a number of issues I would like to discuss with you about this example, but perhaps we should have a private discussion about them.  If you would like, you can contact me at my work email (jay DOT guidos at bidstrading DOT com)

and I will go over it with you.

Hope you like it!

Jay

[swiderski.maciej]

thanks Jay for the sample application, I'll do my best to check it out this week and will get back to you. Already cloned it and build so it's a first step

for other issues either drop them here or join us on IRC.

HTH

[swiderski.maciej]

alright, check your pull requests page of your project. Just sent you some fixes that should make it work as expected in 6.0.1. As mentioned on the other thread, issue is with synchronization of ksession when running within externally manage transact (like cmt or bmt). Will add that to code base as well as part of this jira

HTH