1 2 Previous Next 23 Replies Latest reply on Jan 7, 2009 11:20 AM by Kevin Conner

    Transactional JMS message is delivered before JTA commit?

    Bernd Ruecker Master

      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

        • 1. Re: Transactional JMS message is delivered before JTA commit
          Bernd Ruecker Master

          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?

          • 2. Re: Transactional JMS message is delivered before JTA commit
            Bernd Ruecker Master

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

            • 3. Re: Transactional JMS message is delivered before JTA commit
              Kevin Conner Master

              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

              • 4. Re: Transactional JMS message is delivered before JTA commit
                Kevin Conner Master

                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?

                • 5. Re: Transactional JMS message is delivered before JTA commit
                  Bernd Ruecker Master

                  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!!

                  • 6. Re: Transactional JMS message is delivered before JTA commit
                    Kevin Conner Master

                    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

                    • 7. Re: Transactional JMS message is delivered before JTA commit
                      Bernd Ruecker Master

                      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.

                      • 8. Re: Transactional JMS message is delivered before JTA commit
                        Kevin Conner Master

                        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.

                        • 9. Re: Transactional JMS message is delivered before JTA commit
                          Kevin Conner Master

                          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.

                          • 10. Re: Transactional JMS message is delivered before JTA commit
                            Bernd Ruecker Master

                            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!!

                            • 11. Re: Transactional JMS message is delivered before JTA commit
                              Bernd Ruecker Master

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

                              • 12. Re: Transactional JMS message is delivered before JTA commit
                                Kevin Conner Master

                                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

                                • 13. Re: Transactional JMS message is delivered before JTA commit
                                  Bernd Ruecker Master

                                  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 :-/

                                  • 14. Re: Transactional JMS message is delivered before JTA commit
                                    Kevin Conner Master

                                    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

                                    1 2 Previous Next