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
>> [...@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.
