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
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), [EMAIL PROTECTED],
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),
[EMAIL PROTECTED], 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),
[EMAIL PROTECTED], 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.
