ode-user mailing list archives

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

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


Mime
View raw message