ode-user mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From "raulvk.soa" <raulvk....@gmail.com>
Subject Re: ODE picking wrong instance on bpel:reply
Date Thu, 21 Oct 2010 17:16:03 GMT

Hi,

Sorry to bump my own thread. I've further looked into this, and I think I
have confirmed the source of the problem.

I've been looking at the generated BPEL events, and I see the sequence of
events which I have pasted further down. I have only pasted the events which
I believe are relevant in this case.

As you will see, my process receives a response from the JBI endpoint,
carries out some work and finishes (ProcessCompletionEvent).

However, later on (notice the timestamps), another instance executes and
upon receiving the response from the JBI endpoint, it decides that it should
be routed to the same instance as before (look at the InstanceIds and
MessageExchangeIds, they are exactly the same). How can this be, if the
process was already completed?!

The significant BPEL events:


2010-10-21 14:41:24,101 | DEBUG | org.apache.ode.bpel.iapi.BpelEventListener
|
ProcessMessageExchangeEvent:
        Operation = JBIServiceOperation
        PortType = {http://www.mycompany.org}JBIServicePortType
        MessageExchangeId = hqejbhcnphr5opnw0po5db
        Aspect = 3
        Type = instanceLifecycle
        ProcessInstanceId = 112945
        ProcessId = {http://www.mycompany.org}MyProcess-0
        ProcessName = {http://www.mycompany.org}MyProcess
        Timestamp = Thu Oct 21 14:41:24 WEST 2010
        LineNo = -1
        Class = class org.apache.ode.bpel.evt.ProcessMessageExchangeEvent

		[...]

2010-10-21 14:41:24,877 | DEBUG | org.apache.ode.bpel.iapi.BpelEventListener
|
ProcessCompletionEvent:
        Type = instanceLifecycle
        ProcessInstanceId = 112945
        ProcessId = {http://www.mycompany.org}MyProcess-0
        ProcessName = {http://www.mycompany.org}MyProcess
        Timestamp = Thu Oct 21 14:41:24 WEST 2010
        LineNo = -1
        Class = class org.apache.ode.bpel.evt.ProcessCompletionEvent

		[...]
		
2010-10-21 14:41:50,457 | DEBUG | org.apache.ode.bpel.iapi.BpelEventListener
|
ProcessMessageExchangeEvent:
        Operation = JBIServiceOperation
        PortType = {http://www.mycompany.org}JBIServicePortType
        MessageExchangeId = hqejbhcnphr5opnw0po5db
        Aspect = 4
        Type = instanceLifecycle
        ProcessInstanceId = 112945
        ProcessId = {http://www.mycompany.org}MyProcess-0
        ProcessName = {http://www.mycompany.org}MyProcess
        Timestamp = Thu Oct 21 14:41:50 WEST 2010
        LineNo = -1
        Class = class org.apache.ode.bpel.evt.ProcessMessageExchangeEvent

		[...]

Many thanks,
Raul.


raulvk.soa wrote:
> 
> Hi,
> 
> We are seeing a strange issue with Apache ODE 1.3.4 in a JBI environment
> (ServiceMix). 
> We have a business process with various bpel:invoke activities, calling
> In-Out synchronous JBI endpoints.
> 
> When the process finishes, it collects all the responses from the
> bpel:invoke activities, builds an aggregate message, and sends the message
> back via a bpel:reply activity.
> 
> When the bpel:reply activity executes, we see the following Exception:
> 
> javax.jbi.messaging.MessagingException: Out message is already set
>         at
> org.apache.servicemix.jbi.messaging.MessageExchangeImpl.setMessage(MessageExchangeImpl.java:360)
>         at
> org.apache.servicemix.jbi.messaging.MessageExchangeImpl.setOutMessage(MessageExchangeImpl.java:550)
>         at org.apache.ode.jbi.OdeService.outResponse(OdeService.java:340)
>         at org.apache.ode.jbi.OdeService.onResponse(OdeService.java:211)
>         at
> org.apache.ode.jbi.MessageExchangeContextImpl.onAsyncReply(MessageExchangeContextImpl.java:53)
>         at
> org.apache.ode.bpel.engine.BpelRuntimeContextImpl.doAsyncReply(BpelRuntimeContextImpl.java:581)
>         at
> org.apache.ode.bpel.engine.BpelRuntimeContextImpl.reply2(BpelRuntimeContextImpl.java:622)
>         at
> org.apache.ode.bpel.engine.BpelRuntimeContextImpl.reply(BpelRuntimeContextImpl.java:589)
>         at org.apache.ode.bpel.runtime.REPLY.run(REPLY.java:68)
>         at sun.reflect.GeneratedMethodAccessor187.invoke(Unknown Source)
>         at
> sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
>         at java.lang.reflect.Method.invoke(Method.java:597)
>         at
> org.apache.ode.jacob.vpu.JacobVPU$JacobThreadImpl.run(JacobVPU.java:451)
>         at org.apache.ode.jacob.vpu.JacobVPU.execute(JacobVPU.java:139)
>         [...]
> 
> It looks like the OUT message was already set! However, no bpel:reply has
> executed previously!
> 
> To figure out what is happening, and if we grep the log file for the mexid
> that fails (hqejbhcnphr5opnw0po5d0), we see the following:
> 
> 2010-10-21 16:01:23,023 | DEBUG | ServiceBridge |
> org.apache.ode.jbi.ServiceBridge | {MyRoleMex#hqejbhcnphr5otnqi165q2
> [Client ID:10.10.10.10-12bcf3a00b8-5:250] calling
> {http://www.mycompany.org}MyProcess.MyProcessOperation(...)}: mmex
> copyProperties
> 2010-10-21 16:01:23,027 | DEBUG | OdeService |
> org.apache.ode.jbi.OdeService | ODE MEX {MyRoleMex#hqejbhcnphr5otnqi165q2
> [Client ID:10.10.10.10-12bcf3a00b8-5:250] calling
> {http://www.mycompany.org}MyProcess.MyProcessOperation(...)} completed
> ASYNCHRONOUSLY.
> 2010-10-21 16:01:23,027 | DEBUG | OdeService |
> org.apache.ode.jbi.OdeService | Commiting ODE MEX
> {MyRoleMex#hqejbhcnphr5otnqi165q2 [Client
> ID:10.10.10.10-12bcf3a00b8-5:250] calling
> {http://www.mycompany.org}MyProcess.MyProcessOperation(...)}
> 2010-10-21 16:01:23,054 | DEBUG | BpelEngineImpl |
> org.apache.ode.bpel.engine.BpelEngineImpl | handleJobDetails:
> InvokeInternal event for mexid hqejbhcnphr5otnqi165q2
> 2010-10-21 16:01:23,059 | DEBUG | BpelProcess |
> org.apache.ode.bpel.engine.BpelProcess | >>
> handleJobDetails(jobData=JobDetails( instanceId: null mexId:
> hqejbhcnphr5otnqi165q2 processId: {http://www.mycompany.org}MyProcess-0
> type: INVOKE_INTERNAL channel: null correlatorId: null correlationKeySet:
> null retryCount: null inMem: false detailsExt: {}))
> 2010-10-21 16:01:23,059 | DEBUG | BpelProcess |
> org.apache.ode.bpel.engine.BpelProcess | InvokeInternal event for mexid
> hqejbhcnphr5otnqi165q2
> 2010-10-21 16:01:23,079 | DEBUG | BpelProcess |
> org.apache.ode.bpel.engine.BpelRuntimeContextImpl | SELECT:
> PickResponseChannel#9: FOUND match for NEW instance
> mexRef={MyRoleMex#hqejbhcnphr5otnqi165q2 [Client
> ID:10.10.10.10-12bcf3a00b8-5:250] calling
> {http://www.mycompany.org}MyProcess.MyProcessOperation(...)}
> 2010-10-21 16:01:24,647 | DEBUG | OdeService |
> org.apache.ode.jbi.OdeService | Processing MEX tracker mexId:
> hqejbhcnphr5otnqi165q2 clientId: ID:10.10.10.10-12bcf3a00b8-5:250
> 2010-10-21 16:01:24,652 | DEBUG | MyRoleMessageExchangeImpl |
> org.apache.ode.bpel.engine.MyRoleMessageExchangeImpl | Releasing mex
> hqejbhcnphr5otnqi165q2
> 2010-10-21 16:01:25,531 | DEBUG | OdeService |
> org.apache.ode.jbi.OdeService$1 | Consuming MEX tracker mexId:
> hqejbhcnphr5otnqi165q2 clientId: ID:10.10.10.10-12bcf3a00b8-5:250
> [smx@abanar /usr/local/apache-servicemix-3.3.1/data/log/ProcesosNegocio]$
> grep hqejbhcnphr5opnw0po5d0 ProcesosNegocio.log
> 2010-10-21 14:41:23,062 | DEBUG | ServiceBridge |
> org.apache.ode.jbi.ServiceBridge | {MyRoleMex#hqejbhcnphr5opnw0po5d0
> [Client ID:10.10.10.10-12bc8bd6a88-5:1288] calling
> {http://www.mycompany.org}MyProcess.MyProcessOperation(...)}: mmex
> copyProperties
> 2010-10-21 14:41:23,065 | DEBUG | OdeService |
> org.apache.ode.jbi.OdeService | ODE MEX {MyRoleMex#hqejbhcnphr5opnw0po5d0
> [Client ID:10.10.10.10-12bc8bd6a88-5:1288] calling
> {http://www.mycompany.org}MyProcess.MyProcessOperation(...)} completed
> ASYNCHRONOUSLY.
> 2010-10-21 14:41:23,065 | DEBUG | OdeService |
> org.apache.ode.jbi.OdeService | Commiting ODE MEX
> {MyRoleMex#hqejbhcnphr5opnw0po5d0 [Client
> ID:10.10.10.10-12bc8bd6a88-5:1288] calling
> {http://www.mycompany.org}MyProcess.MyProcessOperation(...)}
> 2010-10-21 14:41:23,103 | DEBUG | BpelEngineImpl |
> org.apache.ode.bpel.engine.BpelEngineImpl | handleJobDetails:
> InvokeInternal event for mexid hqejbhcnphr5opnw0po5d0
> 2010-10-21 14:41:23,107 | DEBUG | BpelProcess |
> org.apache.ode.bpel.engine.BpelProcess | >>
> handleJobDetails(jobData=JobDetails( instanceId: null mexId:
> hqejbhcnphr5opnw0po5d0 processId: {http://www.mycompany.org}MyProcess-0
> type: INVOKE_INTERNAL channel: null correlatorId: null correlationKeySet:
> null retryCount: null inMem: false detailsExt: {}))
> 2010-10-21 14:41:23,107 | DEBUG | BpelProcess |
> org.apache.ode.bpel.engine.BpelProcess | InvokeInternal event for mexid
> hqejbhcnphr5opnw0po5d0
> 2010-10-21 14:41:23,120 | DEBUG | BpelProcess |
> org.apache.ode.bpel.engine.BpelRuntimeContextImpl | SELECT:
> PickResponseChannel#9: FOUND match for NEW instance
> mexRef={MyRoleMex#hqejbhcnphr5opnw0po5d0 [Client
> ID:10.10.10.10-12bc8bd6a88-5:1288] calling
> {http://www.mycompany.org}MyProcess.MyProcessOperation(...)}
> 2010-10-21 14:41:24,871 | DEBUG | OdeService |
> org.apache.ode.jbi.OdeService | Processing MEX tracker mexId:
> hqejbhcnphr5opnw0po5d0 clientId: ID:10.10.10.10-12bc8bd6a88-5:1288
> 2010-10-21 14:41:24,873 | DEBUG | MyRoleMessageExchangeImpl |
> org.apache.ode.bpel.engine.MyRoleMessageExchangeImpl | Releasing mex
> hqejbhcnphr5opnw0po5d0
> 2010-10-21 14:41:50,623 | DEBUG | OdeService |
> org.apache.ode.jbi.OdeService | Processing MEX tracker mexId:
> hqejbhcnphr5opnw0po5d0 clientId: ID:10.10.10.10-12bc8bd6a88-5:1288
> 2010-10-21 14:41:50,625 | ERROR | OdeService |
> org.apache.ode.jbi.OdeService | Error processing response from ODE to JBI
> mexId: hqejbhcnphr5opnw0po5d0 clientId: ID:10.10.10.10-12bc8bd6a88-5:1288
> 
> (Notice the like "Releasing..." line, and then notice the process being
> picked up again).
> 
> We have spent hours trying to figure out the problem, but we can't get our
> heads around it. Any ideas?
> 
> Many thanks!
> 
> 
> 

-- 
View this message in context: http://old.nabble.com/ODE-picking-wrong-instance-on-bpel%3Areply-tp30020659p30021625.html
Sent from the Apache Ode User mailing list archive at Nabble.com.


Mime
View raw message