Transactional JMS message is delivered before JTA commit?

[camunda]

Hi.

I currently face a strange problem (JBoss ESB 4.4.GA):

1. A jbpm process reaches an ESB node (triggered by asynchronous communication via JMS)
2. The ESB node calls a "RequestResponse" ESB Service
3. The ESB does something, the JbpmCallback is called
4. The JbpmCallback is executed before the jbpm process instance could be committed to the database, hence the state in the database is still an old one: [org.jboss.soa.esb.services.jbpm.cmd.CallbackCommand] Token id 640 from process instance 365 is no longer on expected node, expected 339 but discovered 342

Jbpm is configured to use JTA. All ESB services (including the JbpmCallback) are configured to use JTA for JMS like this:

<jms-jca-provider name="JMS-Provider" connection-factory="java:JmsXA">
 <jms-bus busid="PingPongEsbChannel">
 <jms-message-filter dest-name="queue/test_PingPong_esb" dest-type="QUEUE"/>
 </jms-bus>
 ...

The service:

...
<service category="Test" name="PingPong">
 <listeners>
 <jms-listener name="internal" busidref="PingPongEsbChannel" />
 </listeners>
 <actions mep="RequestResponse">
 <action name="sysout1" class="org.jboss.soa.esb.actions.SystemPrintln" />
 </actions>
</service>
...

My thought was, that the message for the JbpmCallback is processed not before the first transaction is committed completly. But since the DB state is 'old', this seems to be not true??

The process:

...
<node name="test async continuation" async="true">
 <transition to="test ESB PingPong"></transition>
</node>
<node name="test ESB PingPong">
 <action class="org.jboss.soa.esb.services.jbpm.actionhandlers.EsbActionHandler">
 <esbCategoryName>Test</esbCategoryName>
 <esbServiceName>PingPong</esbServiceName>
 </action>
 <transition to="test timer and callback"></transition>
</node>
...

By the way: I get this behavior in around 60-70 % of the cases, not always. Seems to be a timing issues, but I currently don't have any idea.

What am I missing? Do you need more information? Thanks for any hints!

Cheers
Bernd

[camunda]

Seems to be related to https://jira.jboss.org/jira/browse/JBESB-1438. But the fixes mentioned there seem to be not existent in 4.4.GA?

[camunda]

Seems like the fix of JBESB-1438 was removed again in revision 19171. Anybody knows why? Shouldn't be the bug reopened then?

[kconner]

No, the original code was not sufficient and had to be redone.

The issues you need to be looking at are https://jira.jboss.org/jira/browse/JBESB-1618 and https://jira.jboss.org/jira/browse/JBESB-1665

[kconner]

The caller should be executed within a transactional context on the jBPM worker thread. If this is the case then the outgoing message should not be sent until the jBPM transaction commits.

The fact that you are seeing the service executed before the process had committed would suggest that it may not be running within a transactional context or the transport is not transactional.

Do you have logs showing the problem?

[camunda]

Plenty of it ;-) If you need some special classes just let me now...

I tried to cut out own stuff. At least you can see, that jbpm is triggered by the JobListenerBean, an EJB from the jbpm enterprise ear, so everything should run in a transaction correctly. Thats is why I am puzzled.

2008-12-01 13:54:12,957 DEBUG [org.jbpm.ejb.impl.JobListenerBean] getting job id from jms message...
2008-12-01 13:54:12,957 DEBUG [org.jbpm.ejb.impl.JobListenerBean] retrieved jobId '887' via jms message
2008-12-01 13:54:12,957 DEBUG [org.jbpm.configuration.JbpmContextInfo] creating jbpm context with service factories '[tx, message, logging, scheduler, persistence, authentication]'
2008-12-01 13:54:12,958 DEBUG [org.jbpm.JbpmContext] creating org.jbpm.JbpmContext@1116dc4
2008-12-01 13:54:12,958 DEBUG [org.jbpm.ejb.impl.CommandServiceBean] executing Command
2008-12-01 13:54:12,958 DEBUG [org.jbpm.persistence.db.DbPersistenceService] using current hibernate session
2008-12-01 13:54:12,961 DEBUG [org.jbpm.ejb.impl.ExecuteJobCommand] executing job[887]
2008-12-01 13:54:12,962 DEBUG [org.jbpm.job.ExecuteNodeJob] job[887] executes Node(test async continuation)
2008-12-01 13:54:12,966 DEBUG [org.jbpm.graph.exe.Token] token[766] is unlocked by job[887]
2008-12-01 13:54:12,969 DEBUG [org.jbpm.graph.def.GraphElement] event 'node-leave' on 'Node(test async continuation)' for 'Token(/)'
2008-12-01 13:54:12,978 DEBUG [org.jbpm.graph.def.GraphElement] event 'transition' on 'Transition(116ed50)' for 'Token(/)'
2008-12-01 13:54:13,085 DEBUG [org.jbpm.graph.def.GraphElement] event 'node-enter' on 'Node(test ESB PingPong)' for 'Token(/)'
2008-12-01 13:54:13,088 DEBUG [org.jbpm.graph.def.GraphElement] executing action 'Action(11ae9e7)'
2008-12-01 13:54:13,107 DEBUG [org.jboss.soa.esb.services.jbpm.actionhandlers.EsbActionHandler] Created ESB message=message: [ JBOSS_XML ]
header: [ ReplyTo: EPR: PortReference < <wsa:Address logical:JBossESB-Internal#JBpmCallbackService/>, <wsa:ReferenceProperties jbossesb:esbToBpmVars : <esbToBpmVars><mapping esb="body" bpm="entireOrderAsXML"/></esbToBpmVars>/>, <wsa:ReferenceProperties jbossesb:jbpmTokenId : 766/>, <wsa:ReferenceProperties jbossesb:jbpmNodeId : 386/>, <wsa:ReferenceProperties jbossesb:jbpmProcessInstId : 438/>, <wsa:ReferenceProperties jbossesb:jbpmProcessNodeVersionCounter386_766 : 0/> > ]
context: [ ]
body: [ objects: {} ]
fault: [ ]
attachments: [ Named:{}, Unnamed:[] ]
properties: [ {} ]
2008-12-01 13:54:13,120 DEBUG [org.jboss.soa.esb.services.jbpm.actionhandlers.EsbActionHandler] Message send successfully
2008-12-01 13:54:13,120 DEBUG [org.jbpm.svc.Services] executing default save operations
2008-12-01 13:54:13,120 DEBUG [org.jbpm.svc.save.HibernateSaveOperation] saving process instance
2008-12-01 13:54:13,120 DEBUG [org.jbpm.svc.save.SaveLogsOperation] flushing logs to logging service.
2008-12-01 13:54:13,221 DEBUG [org.jbpm.svc.save.CascadeSaveOperation] cascading save of 'ProcessInstance@151888d'
2008-12-01 13:54:13,221 DEBUG [org.jbpm.JbpmContext] closing jbpmContext org.jbpm.JbpmContext@1116dc4
2008-12-01 13:54:13,221 DEBUG [org.jbpm.svc.Services] executing default save operations
2008-12-01 13:54:13,221 DEBUG [org.jbpm.svc.save.HibernateSaveOperation] saving process instance
2008-12-01 13:54:13,222 DEBUG [org.jbpm.svc.save.SaveLogsOperation] flushing logs to logging service.
2008-12-01 13:54:13,223 DEBUG [org.jbpm.svc.save.CascadeSaveOperation] cascading save of 'ProcessInstance@151888d'
2008-12-01 13:54:13,223 DEBUG [org.jbpm.svc.Services] closing service 'logging': DbLoggingService@183f2a
2008-12-01 13:54:13,223 DEBUG [org.jbpm.svc.save.CascadeSaveOperation] cascading save of 'ProcessInstance@151888d'
2008-12-01 13:54:13,223 DEBUG [org.jbpm.svc.Services] closing service 'logging': DbLoggingService@183f2a
2008-12-01 13:54:13,223 DEBUG [org.jbpm.svc.save.CascadeSaveOperation] cascading save of 'ProcessInstance@151888d'
2008-12-01 13:54:13,223 DEBUG [org.jbpm.svc.Services] closing service 'logging': DbLoggingService@183f2a
2008-12-01 13:54:13,250 DEBUG [org.jboss.soa.esb.services.jbpm.Mapping] <mapping esb="body" bpm="entireOrderAsXML"/>:Mapping[ esb=body, bpm=entireOrderAsXML, isProcessScope=null, defaultValue=null ]
2008-12-01 13:54:13,250 DEBUG [org.jboss.soa.esb.services.jbpm.JBpmObjectMapper] value=null
2008-12-01 13:54:13,250 DEBUG [org.jboss.soa.esb.services.jbpm.cmd.CommandExecutor] Signaling Process with Transition=null, VariableMap={}
2008-12-01 13:54:13,250 DEBUG [org.jboss.soa.esb.services.jbpm.cmd.CommandExecutor] org.jboss.soa.esb.services.jbpm.cmd.CallbackCommand@19b5a0b
2008-12-01 13:54:13,250 DEBUG [org.jbpm.configuration.JbpmContextInfo] creating jbpm context with service factories '[tx, message, logging, scheduler, persistence, authentication]'
2008-12-01 13:54:13,250 DEBUG [org.jbpm.JbpmContext] creating org.jbpm.JbpmContext@1950feb
2008-12-01 13:54:13,250 DEBUG [org.jbpm.command.impl.CommandServiceImpl] executing Command@1484688
2008-12-01 13:54:13,250 DEBUG [org.jboss.soa.esb.services.jbpm.cmd.CallbackCommand] Expected nodeId=386, tokenId=766, processNodeVersion=0
2008-12-01 13:54:13,250 DEBUG [org.jbpm.persistence.db.DbPersistenceService] using current hibernate session
2008-12-01 13:54:13,259 WARN [org.jboss.soa.esb.services.jbpm.cmd.CallbackCommand] Token id 766 from process instance 438 is no longer on expected node, expected 386 but discovered 389
2008-12-01 13:54:13,260 DEBUG [org.jbpm.JbpmContext] closing jbpmContext org.jbpm.JbpmContext@1950feb
2008-12-01 13:54:13,260 DEBUG [org.jbpm.svc.Services] closing service 'persistence': org.jbpm.persistence.jta.JtaDbPersistenceService@1ac3b87
2008-12-01 13:54:13,274 DEBUG [org.jbpm.svc.Services] closing service 'persistence': org.jbpm.persistence.jta.JtaDbPersistenceService@86ae77

Thanks in advance!!

[kconner]

The log would suggest that everything has worked correctly from the perspective of the ESB at least.

We have never looked at the JobListenerBean, so are unaware of any potential issues with it, but looking at the log you have provided would suggest that the transaction was flushed correctly and that the outgoing parameters match the incoming ones.

The strange issue is the new node discovered by the callback handler as there does not appear to be a subsequent transition out of 'test ESB PingPong'.

What other changes have you made to the configuration? Could you send me the complete log for this?

Thanks,
Kev

[camunda]

I really don't get it, how transaction in the ESB work, seems to be quite strange. For the described problem I sent you, Kevin, some logs via email.

Now I have another situation: I call an ESB Service with "deliverSync" in a transactional context (started by a SLSB and called a first ESB Service). The Action-Pipeline of this service includes an EJBProcessor calling a SLSB. Now I see the SLSB called before the first transaction commits. This should not happen!

All services are configured to use Transactions/JTA:

<providers>
 <jms-jca-provider name="JMS-Provider" connection-factory="java:JmsXA" transacted="true">
...

Very wired... Any ideas? Any hints what could be configured wrong? BTW, we use JBoss Messaging 1.4.0.SP1, don't know if that plays a role...
Thanks.

[kconner]

Thanks, I have the logs and have just started looking at them.

We are not doing anything strange at all with transactions, and the interactions with JMS/TX should be the same with our without the ESB.

Give me some time to go through your first logs and see what I can find, lets take this one step at a time.

[kconner]

The logs you sent are showing a strange set of events but the issue seems to be located around the test async continuation.

Execution of this node appears to flush the state to the database, at least if I am reading this properly, and this is the state that is picked up by the callback handler. The ESB communication appears to pick up the correct information and it is returned as expected.

Could you change the logging to include the thread information and run this again? (see jboss-log4j.xml for the alternative format)

Could you also send me your process definition (xml this time) and describe what is happening in the 'test async continuation' node?

I would also like to see how you have configured the jBPM service, given that you are not using the normal ESB configuration. This may help to shed some light on the behaviour.

Sorry for all the questions but this is puzzling.

[camunda]

Hi Kevin. Thanks for investigating! For me it is quite puzzling too...

<process-definition name="TechnicalTestProcess">
 <start-state name="Start">
 <transition to="test async continuation"></transition>
 </start-state>

 <state name="test timer and callback">
 <timer duedate="1 second" name="TestTimer" transition="continue" />
 <transition to="log" name="continue"></transition>
 </state>

 <node name="test ESB PingPong">
 <action class="org.jboss.soa.esb.services.jbpm.actionhandlers.EsbActionHandler">
 <esbCategoryName>Test</esbCategoryName>
 <esbServiceName>PingPong</esbServiceName>
 </action>
 <transition to="test timer and callback"></transition>
 </node>

 <node name="test ClassLoader">
 <transition to="test ESB PingPong"></transition>
 </node>

 <node name="call some actions">
 <event type="node-enter">
 <action name="EsbAction" class="ActionInEsb"></action>
 <action name="ActionPar" class="ActionInPar"></action>
 <action name="ActionEsbLoadingParStuff" class="ActionInEsbLoadsActionInPar"></action>
 </event>
 <transition to="test ClassLoader"></transition>
 </node>

 <node name="test async continuation" async="true">
 <transition to="call some actions"></transition>
 </node>

 <node name="log">
 <event type="node-enter">
 <action name="log" class="LogAction"></action>
 </event>
 <transition to="End"></transition>
 </node>

 <end-state name="End" />
</process-definition>

This process-definition. The "test async continuation" uses jbpm asynchronous continuations.
In the jbpm enterprise ear this is configured to use JMS (so the the transaction is committed, a JMS message create to execute the process later and the node behaves as a wait state).
Then this message gets picked up and triggers the process (see http://docs.jboss.org/jbpm/v3/userguide/graphorientedprogramming.html#asynchronouscontinuations.
So obviously the state is committed to database.
The question is, why the JbpmCallback Service starts before the transaction is committed?

I double checked it, the jbpm queues also use the JmsXA Connection factory.

Basically I changed jbpm integration in esb to use the jbpm enterprise ear. I send you configuration and the requested log file via mail...

Thanks for all your help!!

[camunda]

Hi Kevin, did you had any new idea on this? I still have no glue what goes wrong here...

[kconner]

There is nothing obvious in the logs you have sent, and it looks as if the bean should have transactions enabled.

Can you please provide another log with the following categories enabled at DEBUG?

org.jboss.internal.soa.esb.couriers.JmsCourier and org.jboss.internal.soa.esb.rosetta.pooling.JmsConnectionPool.

Can you also send the complete log?

Thanks,
Kev

[camunda]

Hi Kevin,

I sent you more verbose logs via email... Quite strange, still don't have a good idea what is happening here... I bet it is some very, very small but successfully hidden configuration property or bug :-/

[kconner]

I have gone through the logs but I would like to see how you are defining the datasources used by JMS and jBPM.

I also noticed that you have enabled multiple last resources in the transaction manager, can you tell me why you have done this?

Thanks
Kev