ode-dev mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From "Rafal Rusin (JIRA)" <j...@apache.org>
Subject [jira] Commented: (ODE-327) Process instance hangs in state ACTIVE after processing concurrently RECEIVE in BPEL Engine and incomming message in JBI transport layer
Date Thu, 10 Jul 2008 22:52:31 GMT

    [ https://issues.apache.org/jira/browse/ODE-327?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=12612680#action_12612680
] 

Rafal Rusin commented on ODE-327:
---------------------------------

Yes, this is true. 

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,460 | DEBUG | pool-19-thread-25 | BpelRuntimeContextImpl | .engine.BpelRuntimeContextImpl
1348 | MatcherEvent handling: nothing to do, no matching message in DB 

Here, a MatcherEvent is created and enqueued inside communication layer's (JBI) transaction
(via PartnerLinkMyRoleImpl.java). Then it's executed and sees that there's no message in DB,
because the previous transaction wasn't committed yet. So the solution is to enqueue event
in an afterCompletion of communication layer's transaction (or possibly acquire instance lock
until afterCompletion, because MatcherEvent acquires it also). 

But I don't see any generating of a matcher event in PICK.java in an afterCompletion of a
transaction. Is there an instance lock acquired during entering PICK?

Regards

> 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.


Mime
View raw message