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 Wed, 27 Oct 2010 22:59:30 GMT

Hello.... no one has a clue on this?

Thanks.


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-tp30020659p30072069.html
Sent from the Apache Ode User mailing list archive at Nabble.com.


Mime
View raw message