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, 05 Nov 2010 00:38:31 GMT

Hi,

In my case, I've blamed in on a transitory problem in the underlying Apache
Derby store.
The process instance received the response from the last INVOKE activity,
reloaded the process from the DB, collected all responses and sent the final
reply back to the caller. 

After doing so, apparently the process wasn't cleaned up correctly from the
Derby store and the Job Scheduler picked it up again later on, executing the
same transaction over again, but the out message was already set on the JBI
exchange, thus causing this error. There was no JBI exchange to ignite the
process again, I've checked the NMR logs.

In fact, the first JBI response wasn't even send out of ODE. It looks like
that job failed too.

Does my theory make any sense?

Is this a typical problem with EMBEDDED Apache Derby? Are there known
stability issues? What DB setting do you really recommend? 

Right now we have switched all processes to in-memory to avoid DB
instability.

Many thanks,
Raúl.


Tammo van Lessen wrote:
> 
> Hi,
> 
> mind you sharing your solution with us? The reason for the overwhelming
> amount of replies is probably that no one has run into this problem yet.
> 
> Thanks,
>   Tammo
> 
> On 28.10.2010 19:38, raulvk.soa wrote:
>> 
>> Thanks for the overwhelming amount of replies!
>> 
>> Fixed the problem.
>> 
>> Regards.
>> 
>> 
>> 
>> raulvk.soa wrote:
>>>
>>> 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!
>>>>
>>>>
>>>>
>>>
>>>
>> 
> 
> -- 
> Tammo van Lessen - http://www.taval.de
> 
> 

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


Mime
View raw message