You are viewing a plain text version of this content. The canonical link for it is here.
Posted to dev@ode.apache.org by "Rafal Rusin (JIRA)" <ji...@apache.org> on 2008/07/10 10:01:33 UTC
[jira] Updated: (ODE-327) Process instance hangs in state ACTIVE
after processing concurrently RECEIVE in BPEL Engine and incomming message
in JBI transport layer
[ https://issues.apache.org/jira/browse/ODE-327?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]
Rafal Rusin updated ODE-327:
----------------------------
Component/s: BPEL Runtime
> 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: BPEL Runtime
> Affects Versions: 1.2
> Environment: ServiceMix, Oracle EXTERNAL, Commons DBCP Managed Connection Pool
> Reporter: Rafal Rusin
>
> 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.LinkFrame@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.LinkFrame@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.LinkFrame@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.