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/09 17:53:31 UTC
[jira] Created: (ODE-327) Process instance hangs in state ACTIVE
after processing concurrently RECEIVE in BPEL Engine and incomming message
in JBI transport layer
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), 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.
[jira] Updated: (ODE-327) Process instance hangs in state ACTIVE
after processing concurrently RECEIVE in BPEL Engine and incomming message
in JBI transport layer
Posted by "Rafal Rusin (JIRA)" <ji...@apache.org>.
[ https://issues.apache.org/jira/browse/ODE-327?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]
Rafal Rusin updated ODE-327:
----------------------------
Component/s: (was: BPEL Runtime)
JBI Integration
Moving to JBI Integration
> 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: 2.0
>
>
> 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.
[jira] Issue Comment Edited: (ODE-327) Process instance hangs in
state ACTIVE after processing concurrently RECEIVE in BPEL Engine and
incomming message in JBI transport layer
Posted by "Rafal Rusin (JIRA)" <ji...@apache.org>.
[ https://issues.apache.org/jira/browse/ODE-327?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=12612419#action_12612419 ]
rrusin edited comment on ODE-327 at 7/10/08 2:46 AM:
----------------------------------------------------------
OK, so I suggest a following solution:
Create a new Job (eg. MessageMatcherJob), wchich will check if there is stored Message and Receive for a given correlation. And if there are both of them in DB, it will continue process with them matched.
MessageMatcherJob will be queued to Scheduler on storing in DB (message in transport layer or receive in bpel engine). So one of those MessageMatcher jobs will be executed after the two parallel transactions from previous error case will be committed. So it will see in DB this situation and will continue process.
The other cases will be handled as currently and won't be broken.
What do you think about it?
Regards
was (Author: rrusin):
OK, so I suggest a following solution:
Create a new Job (eg. MessageMatcherJob), wchich will check if there is stored Message and Receive for a given correlation. And if there are both of them in DB, it will continue process with them matched.
MessageMatcherJob will be queued to Scheduler on storing message in DB both in communication layer and bpel engine. So one of those jobs will be executed after the two parallel transactions from previous error case will be committed. So it will see in DB this situation and will continue process.
What do you think about it?
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.
[jira] Commented: (ODE-327) Process instance hangs in state ACTIVE
after processing concurrently RECEIVE in BPEL Engine and incomming message
in JBI transport layer
Posted by "Rafal Rusin (JIRA)" <ji...@apache.org>.
[ https://issues.apache.org/jira/browse/ODE-327?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=12612382#action_12612382 ]
Rafal Rusin commented on ODE-327:
---------------------------------
The processes work in 95% of cases. I just run a test of about 100 requests and about 5 of them hanged in state ACTIVE, while the others completed successfully. I can't easily add waits to partner services, since they are outside ODE. But I can try to do this somehow.
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
> 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.
[jira] Commented: (ODE-327) Process instance hangs in state ACTIVE
after processing concurrently RECEIVE in BPEL Engine and incomming message
in JBI transport layer
Posted by "Rafal Rusin (JIRA)" <ji...@apache.org>.
[ 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.
[jira] Updated: (ODE-327) Process instance hangs in state ACTIVE
after processing concurrently RECEIVE in BPEL Engine and incomming message
in JBI transport layer
Posted by "Rafal Rusin (JIRA)" <ji...@apache.org>.
[ 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.
[jira] Commented: (ODE-327) Process instance hangs in state ACTIVE
after processing concurrently RECEIVE in BPEL Engine and incomming message
in JBI transport layer
Posted by "Matthieu Riou (JIRA)" <ji...@apache.org>.
[ https://issues.apache.org/jira/browse/ODE-327?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=12612578#action_12612578 ]
Matthieu Riou commented on ODE-327:
-----------------------------------
We're already doing something like this. When a receive is hit, it generates a matcher job. The matcher will check if a message has really been received and stored that could match this receive.
Additionally, I should say I'm pretty sure similar scenarios work with our Axis2 integration. So I'd look for potential race conditions in transaction commits in the JBI code.
> 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.
[jira] Commented: (ODE-327) Process instance hangs in state ACTIVE
after processing concurrently RECEIVE in BPEL Engine and incomming message
in JBI transport layer
Posted by "Rafal Rusin (JIRA)" <ji...@apache.org>.
[ 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.
[jira] Commented: (ODE-327) Process instance hangs in state ACTIVE
after processing concurrently RECEIVE in BPEL Engine and incomming message
in JBI transport layer
Posted by "Alex Boisvert (JIRA)" <ji...@apache.org>.
[ https://issues.apache.org/jira/browse/ODE-327?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=12612180#action_12612180 ]
Alex Boisvert commented on ODE-327:
-----------------------------------
Just curious, have you checked that the processes work if you add waits to avoid concurrent transactions?
> 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), 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.
[jira] Resolved: (ODE-327) Process instance hangs in state ACTIVE
after processing concurrently RECEIVE in BPEL Engine and incomming message
in JBI transport layer
Posted by "Rafal Rusin (JIRA)" <ji...@apache.org>.
[ 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.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.
[jira] Commented: (ODE-327) Process instance hangs in state ACTIVE
after processing concurrently RECEIVE in BPEL Engine and incomming message
in JBI transport layer
Posted by "Rafal Rusin (JIRA)" <ji...@apache.org>.
[ https://issues.apache.org/jira/browse/ODE-327?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=12612419#action_12612419 ]
Rafal Rusin commented on ODE-327:
---------------------------------
OK, so I suggest a following solution:
Create a new Job (eg. MessageMatcherJob), wchich will check if there is stored Message and Receive for a given correlation. And if there are both of them in DB, it will continue process with them matched.
MessageMatcherJob will be queued to Scheduler on storing message in DB both in communication layer and bpel engine. So one of those jobs will be executed after the two parallel transactions from previous error case will be committed. So it will see in DB this situation and will continue process.
What do you think about it?
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.