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 08:53:31 GMT

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

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

I put waiting 10 seconds before accepting callbacks (here's a diff):

Index: jbi/src/main/java/org/apache/ode/jbi/OdeService.java
===================================================================
--- jbi/src/main/java/org/apache/ode/jbi/OdeService.java        (revision 674813)
+++ jbi/src/main/java/org/apache/ode/jbi/OdeService.java        (working copy)
@@ -216,6 +216,14 @@
             return;
         }

+        if (_endpoint.serviceName.getLocalPart().indexOf("Receive") != -1
+            || _endpoint.serviceName.getLocalPart().indexOf("Resp") != -1) {
+            Thread.sleep(10000);
+        }
+        if (_endpoint.serviceName.getLocalPart().indexOf("Report") != -1 ) {
+            Thread.sleep(20000);
+        }
+
         _ode.getTransactionManager().begin();

         boolean success = false;


And there were no hangs :-) 
I did also a thread dump (kill -3) in an ODE version without delays and there doesn't seem
to be any blocked ODE thread, so there are no pending transactions with dead locks.

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