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 Fri, 22 Oct 2010 23:52:38 GMT

Hi, 

I was wondering if anyone has come across a problem like this. It looks like
a concurrency issue, but we don't know where to focus our attention. After
all, the problem is not the bpel:reply activity, but the invoke activity,
which resumes a wrong instance upon receiving a synchronous reply from the
JBI bus.

Any clues as to what the issue can be?

Kind regards,
Raul.


raulvk.soa wrote:
> 
> 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-tp30020659p30033238.html
Sent from the Apache Ode User mailing list archive at Nabble.com.


Mime
View raw message