[
https://issues.apache.org/jira/browse/ODE-327?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel
]
Rafal Rusin resolved ODE-327.
-----------------------------
Fix Version/s: 1.3.5
(was: 2.0)
Resolution: Duplicate
> Process instance hangs in state ACTIVE after processing concurrently RECEIVE
> in BPEL Engine and incomming message in JBI transport layer
> ----------------------------------------------------------------------------------------------------------------------------------------
>
> Key: ODE-327
> URL: https://issues.apache.org/jira/browse/ODE-327
> Project: ODE
> Issue Type: Bug
> Components: JBI Integration
> Affects Versions: 1.2
> Environment: ServiceMix, Oracle EXTERNAL, Commons DBCP Managed
> Connection Pool
> Reporter: Rafal Rusin
> Fix For: 1.3.5
>
>
> The scenario is following:
> Process:
> 1. Declare correlation C with ID
> 2. Set some ID to message M
> 3. INVOKE Partner (initiate correlation C on sending)
> 4. RECEIVE PartnerCallback M2 (with correlation C set to initiate = NO)
> Partner Process (external):
> 1. RECEIVE M3
> 2. INVOKE PartnerCallback M3
> The problem is when the message from Partner Process arrives concurrently
> while processing RECEIVE in 4.
> The two transactions seem to read state in DB (there's no RECEIVE registered
> for incoming message; and no message stored in DB for entered RECEIVE). So
> those two register in DB and there's no more action.
> Here's a detailed log (cut some lines) of this situation:
> 11:50:28,984 | DEBUG | pool-19-thread-13 | BpelProcess |
> l.engine.PartnerLinkMyRoleImpl 127 | INPUTMSG: 42.deliveryReportEvent: MSG
> RCVD keys=[{CorrelationKey setId=236, values=[168244]}] mySessionId=null
> partnerSessionId=null
> 11:50:28,987 | DEBUG | pool-19-thread-13 | BpelProcess |
> l.engine.PartnerLinkMyRoleImpl 236 | INPUTMSG: 42.deliveryReportEvent:
> SAVING to DB (no match)
>
> 11:50:29,104 | DEBUG | pool-19-thread-20 | ScopeFrame |
> he.ode.bpel.runtime.ScopeFrame 263 | Write variable: name={Variable
> __PROCESS_SCOPE:PROCESS:OXsdTyp
> eVarType#35} value=<?xml version="1.0" encoding="UTF-8"?>
> <xsd-complex-type-wrapper>
> <status
> xmlns="http://touk.pl/schema/monitoringVariables";
> xmlns:monitoringVariables="http://touk.pl/schema/monitoringVariables";>SENT_CORRECTLY</status>
> <monitoringVariables:changeDate
> xmlns:monitoringVariables="http://touk.pl/schema/monitoringVariables";>2008-07-09T11:50:28+01:00</monitoringVariables:chang
> eDate>
> </xsd-complex-type-wrapper>
> 11:50:29,110 | DEBUG | pool-19-thread-20 | BpelProcess |
> .engine.BpelRuntimeContextImpl 309 | SELECT: PickResponseChannel#95: USING
> CORRELATOR 42.deliveryReportEvent
> 11:50:29,110 | INFO | pool-19-thread-20 | Query |
> log.Log4JLogFactory$LogAdapter 80 | This query on type "class
> org.apache.ode.dao.jpa.CorrelatorDAOImpl" must l
> oad the entire candidate class extent and evaluate the query in-memory. This
> may be very slow. The query must be executed in memory because OpenJPA is
> configured with IgnoreCache=f
> alse and FlushBeforeQueries=false and there are dirty instances that may
> affect the query's outcome in the cache.
> 11:50:29,117 | DEBUG | pool-19-thread-20 | BpelProcess |
> .engine.BpelRuntimeContextImpl 388 | SELECT: PickResponseChannel#95: ADDED
> ROUTE 42.deliveryReportEvent: {Corre
> lationKey setId=236, values=[168244]} --> 168244
> 11:50:29,118 | DEBUG | pool-19-thread-20 | BpelRuntimeContextImpl |
> .engine.BpelRuntimeContextImpl 839 | Setting execution state on instance
> 168244
> 11:50:29,151 | DEBUG | pool-19-thread-25 | InstanceLockManager |
> pel.engine.InstanceLockManager 50 | Thread[pool-19-thread-25,5,main]:
> lock(iid=168244, time=1MICROSECONDS)
> 11:50:29,152 | DEBUG | pool-19-thread-25 | InstanceLockManager |
> pel.engine.InstanceLockManager 63 | Thread[pool-19-thread-25,5,main]:
> lock(iid=168244, time=1MICROSECONDS)-->G
> RANTED
> 11:50:29,155 | DEBUG | pool-19-thread-25 | BpelProcess |
> he.ode.bpel.engine.BpelProcess 360 | >>
> handleWorkEvent(jobData={type=MATCHER, inmem=false, ckey=236~168244, co
> rrelatorId=42.deliveryReportEvent, iid=168244})
> 11:50:29,162 | DEBUG | pool-19-thread-25 | BpelRuntimeContextImpl |
> .engine.BpelRuntimeContextImpl 161 | BpelRuntimeContextImpl created for
> instance 168244. INDEXED STATE={{OScope
> 'SendPROCESSScope' id=229}::42=[SCOPE(...)], {OScope 'SendPROCESSScope'
> id=229}::41=[ACTIVITYGUARD(...)],
> OFlow#98-ProcessMessages::15=[ACTIVITYGUARD(...)],
> OSequence#100-SendPROCESS::19=[ACTIV
> ITYGUARD(...)], {OScope '__PROCESS_SCOPE:PROCESS' id=20}::0=[ACTIVE(...)],
> {OScope 'ProcessScope' id=99}::18=[SCOPE(...)], {OScope 'ProcessScope'
> id=229}::42=[ACTIVE(...)], OSequen
> ce#47-PROCESSAlert::1=[ACTIVITYGUARD(...)],
> OPickReceive#290-receive-activity-line-378::64=[PICK(...)],
> OSequence#237-SendPROCESS::44=[SEQUENCE(self=(OSequence#237-SendPROCESS,TerminationChannel
> #61,ParentScopeChannel#63),
> linkframe=org.apache.ode.bpel.runtime.linkfr...@fe0c2,
> remaining=[OPickReceive#290-receive-activity-line-378,
> OSwitch#293-if-activity-line-383])], OSequen
> ce#47-PROCESSAlert::2=[SEQUENCE(self=(OSequence#47-PROCESSAlert,TerminationChannel#3,ParentScopeChannel#5),
> linkframe=org.apache.ode.bpel.runtime.linkfr...@6d11d3,
> remaining=[OFlow#98-Proces
> sMessages])],
> OPickReceive#290-receive-activity-line-378::63=[ACTIVITYGUARD(...)], {OScope
> 'SendPROCESSScope' id=99}::18=[ACTIVE(...)], {OScope 'SendPROCESSScope'
> id=99}::17=[ACTIVITYGUARD(.
> ..)],
> OSequence#100-SendPROCESS::20=[SEQUENCE(self=(OSequence#100-SendPROCESS,TerminationChannel#29,ParentScopeChannel#31),
> linkframe=org.apache.ode.bpel.runtime.linkfr...@fe0c2, remaining=[
> OSwitch#227-PROCESSNotEmpty, OThrow#333-Completed])],
> OSequence#237-SendPROCESS::43=[ACTIVITYGUARD(...)],
> OSwitch#227-PROCESSNotEmpty::39=[ACTIVITYGUARD(...)],
> OFlow#98-ProcessMessages::16=[<T:A
> ct:Flow:ProcessMessages>], {OScope '__PROCESS_SCOPE:PROCESS_Alert'
> id=20}::0=[SCOPE(...)]}
> 11:50:29,163 | DEBUG | pool-19-thread-25 | BpelProcess |
> he.ode.bpel.engine.BpelProcess 406 | Matcher event for iid 168244
> 11:50:29,164 | DEBUG | pool-19-thread-25 | BpelRuntimeContextImpl |
> .engine.BpelRuntimeContextImpl 1316 | MatcherEvent handling:
> correlatorId=42.deliveryReportEvent, ckey={Correlat
> ionKey setId=236, values=[168244]}
> 11:50:29,152 | DEBUG | pool-19-thread-24 | rRoleMessageExchangeImpl |
> PartnerRoleMessageExchangeImpl 63 | replyAsync mex=hqejbhcnphr3f2nurln3kn
> 11:50:29,168 | DEBUG | pool-19-thread-24 | BpelRuntimeContextImpl |
> .engine.BpelRuntimeContextImpl 839 | Setting execution state on instance
> 168246
> 11:50:28,993 | DEBUG | pool-19-thread-16 | ScopeFrame |
> he.ode.bpel.runtime.ScopeFrame 237 | Initialize variable: name={Variable
> __PROCESS_SCOPE:UnifyFMS.dispatcherPlk
> VarResponse:OMessageVarType#22} value=<?xml version="1.0" encoding="UTF-8"?>
> <message><parameters><sendResponse
> xmlns="http://.../queue"/></parameters></message>
> 11:50:29,460 | DEBUG | pool-19-thread-25 | BpelRuntimeContextImpl |
> .engine.BpelRuntimeContextImpl 1348 | MatcherEvent handling: nothing to do,
> no matching message in DB
> 11:50:29,461 | DEBUG | pool-19-thread-25 | InstanceLockManager |
> pel.engine.InstanceLockManager 88 | Thread[pool-19-thread-25,5,main]:
> unlock(iid=168244)
>
> And entry from ODE_MESSAGE_EXCHANGE table (indicating that MEX was committed
> to DB, however line 11:50:29,460 says it's not found):
> hqejbhcnphr3f2nurln3kj {http://.../DeliveryReport2 (null)
> ID:127.0.1.1-11b074d2328-2:3461 236~168244 QUEUED (null) 77
> (CLOB) (null) (null) deliveryReportEvent 42 REQUEST_ONLY (null)
> (null) 0 ASYNC 174 (null) 104 (null) 177888 (null)
> Regards
--
This message is automatically generated by JIRA.
-
You can reply to this email to add a comment to the issue online.
