[CallbackCommand] Token id 5 from process instance 5 is no

[jjarkko]

Hello,
I'm having this quite tedious and hard to fix problem.
I'm calling JBPM Process from Esb which in turn calls Esb services using EsbActionHandler. In the process end state I'll use EsbNotifier on node-enter event to give reply back to Esb.

However, quite often, the process hangs and control doesn't return to action pipeline thus causing clients to hang.

Only message in normal log is
"WARN [CallbackCommand] Token id 17 from process instance 9 is no longer on expected node, expected 8 but discovered 9"
Where the number varies depending process version etc.

I've tested this with the default hsqldb setup, xa hsqldb, local-tx mysql and I can get the same result on all configurations.

I looked on the source of CallbackCommand but it didn't unwrap itself yet.

Sometimes cleaning jbpm database puts the problem away for awhile. But it will return sooner or later.


Below is part of the log

08-08-15 14:43:28,483 DEBUG [org.hibernate.pretty.Printer] more......
2008-08-15 14:43:28,483 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
2008-08-15 14:43:28,483 DEBUG [org.hibernate.jdbc.ConnectionManager] opening JDBC connection
2008-08-15 14:43:28,483 DEBUG [org.hibernate.SQL] update JBPM_TOKEN set VERSION_=?, NAME_=?, START_=?, END_=?, NODEENTER_=?, NEXTLOGINDEX_=?, ISABLETOREACTIVATEPARENT_=?, ISTERMINATIONIMPLICIT_=?, ISSUSPENDED_=?, LOCK_=?, NODE_=?, PROCESSINSTANCE_=?, PARENT_=?, SUBPROCESSINSTANCE_=? where ID_=? and VERSION_=?
2008-08-15 14:43:28,483 DEBUG [org.hibernate.engine.TwoPhaseLoad] resolving associations for [org.jbpm.graph.exe.Token#5]
2008-08-15 14:43:28,484 DEBUG [org.hibernate.engine.TwoPhaseLoad] done materializing entity [org.jbpm.graph.exe.Token#5]
2008-08-15 14:43:28,484 DEBUG [org.hibernate.engine.StatefulPersistenceContext] initializing non-lazy collections
2008-08-15 14:43:28,484 DEBUG [org.hibernate.loader.Loader] done entity load
2008-08-15 14:43:28,484 DEBUG [org.hibernate.impl.SessionImpl] initializing proxy: [org.jbpm.graph.exe.ProcessInstance#5]
2008-08-15 14:43:28,484 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
2008-08-15 14:43:28,484 DEBUG [org.hibernate.loader.Loader] loading entity: [org.jbpm.graph.exe.ProcessInstance#5]
2008-08-15 14:43:28,484 DEBUG [org.hibernate.jdbc.ConnectionManager] skipping aggressive-release due to flush cycle
2008-08-15 14:43:28,484 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
2008-08-15 14:43:28,484 DEBUG [org.hibernate.jdbc.ConnectionManager] opening JDBC connection
2008-08-15 14:43:28,484 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to open PreparedStatement (open PreparedStatements: 0, globally: 1)
2008-08-15 14:43:28,484 DEBUG [org.hibernate.SQL] update JBPM_TOKENVARIABLEMAP set VERSION_=?, TOKEN_=?, CONTEXTINSTANCE_=? where ID_=? and VERSION_=?
2008-08-15 14:43:28,484 DEBUG [org.hibernate.SQL] select processins0_.ID_ as ID1_20_0_, processins0_.VERSION_ as VERSION2_20_0_, processins0_.KEY_ as KEY3_20_0_, processins0_.START_ as START4_20_0_, processins0_.END_ as END5_20_0_, processins0_.ISSUSPENDED_ as ISSUSPEN6_20_0_, processins0_.PROCESSDEFINITION_ as PROCESSD7_20_0_, processins0_.ROOTTOKEN_ as ROOTTOKEN8_20_0_, processins0_.SUPERPROCESSTOKEN_ as SUPERPRO9_20_0_ from JBPM_PROCESSINSTANCE processins0_ where processins0_.ID_=?
2008-08-15 14:43:28,484 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to close PreparedStatement (open PreparedStatements: 1, globally: 2)
2008-08-15 14:43:28,484 DEBUG [org.hibernate.jdbc.ConnectionManager] skipping aggressive-release due to flush cycle
2008-08-15 14:43:28,484 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to open PreparedStatement (open PreparedStatements: 0, globally: 1)
2008-08-15 14:43:28,484 DEBUG [org.hibernate.SQL] update JBPM_TOKEN set VERSION_=?, NAME_=?, START_=?, END_=?, NODEENTER_=?, NEXTLOGINDEX_=?, ISABLETOREACTIVATEPARENT_=?, ISTERMINATIONIMPLICIT_=?, ISSUSPENDED_=?, LOCK_=?, NODE_=?, PROCESSINSTANCE_=?, PARENT_=?, SUBPROCESSINSTANCE_=? where ID_=? and VERSION_=?
2008-08-15 14:43:28,484 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to open ResultSet (open ResultSets: 0, globally: 0)
2008-08-15 14:43:28,484 DEBUG [org.hibernate.loader.Loader] result row: EntityKey[org.jbpm.graph.exe.ProcessInstance#5]
2008-08-15 14:43:28,485 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to close ResultSet (open ResultSets: 1, globally: 1)
2008-08-15 14:43:28,485 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to close PreparedStatement (open PreparedStatements: 1, globally: 2)
2008-08-15 14:43:28,485 DEBUG [org.hibernate.jdbc.ConnectionManager] aggressively releasing JDBC connection
2008-08-15 14:43:28,485 DEBUG [org.hibernate.jdbc.ConnectionManager] releasing JDBC connection [ (open PreparedStatements: 0, globally: 1) (open ResultSets: 0, globally: 0)]
2008-08-15 14:43:28,485 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
2008-08-15 14:43:28,485 DEBUG [org.hibernate.engine.TwoPhaseLoad] resolving associations for [org.jbpm.graph.exe.ProcessInstance#5]
2008-08-15 14:43:28,485 DEBUG [org.hibernate.jdbc.ConnectionManager] skipping aggressive-release due to flush cycle
2008-08-15 14:43:28,485 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
2008-08-15 14:43:28,485 DEBUG [org.hibernate.SQL] update JBPM_VARIABLEINSTANCE set VERSION_=?, NAME_=?, CONVERTER_=?, TOKEN_=?, TOKENVARIABLEMAP_=?, PROCESSINSTANCE_=?, STRINGVALUE_=? where ID_=? and VERSION_=?
2008-08-15 14:43:28,485 DEBUG [org.hibernate.engine.TwoPhaseLoad] done materializing entity [org.jbpm.graph.exe.ProcessInstance#5]
2008-08-15 14:43:28,485 DEBUG [org.hibernate.engine.StatefulPersistenceContext] initializing non-lazy collections
2008-08-15 14:43:28,485 DEBUG [org.hibernate.loader.Loader] done entity load
2008-08-15 14:43:28,485 DEBUG [org.hibernate.impl.SessionImpl] initializing proxy: [org.jbpm.graph.def.Node#9]
2008-08-15 14:43:28,485 DEBUG [org.hibernate.cache.NonstrictReadWriteCache] Cache lookup: org.jbpm.graph.def.Node#9
2008-08-15 14:43:28,485 DEBUG [org.hibernate.cache.NonstrictReadWriteCache] Cache hit
2008-08-15 14:43:28,496 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
2008-08-15 14:43:28,496 DEBUG [org.hibernate.jdbc.ConnectionManager] skipping aggressive-release due to flush cycle
2008-08-15 14:43:28,496 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
2008-08-15 14:43:28,496 DEBUG [org.hibernate.engine.StatefulPersistenceContext] initializing non-lazy collections
2008-08-15 14:43:28,496 DEBUG [org.hibernate.SQL] update JBPM_VARIABLEINSTANCE set VERSION_=?, NAME_=?, CONVERTER_=?, TOKEN_=?, TOKENVARIABLEMAP_=?, PROCESSINSTANCE_=?, BYTEARRAYVALUE_=? where ID_=? and VERSION_=?
2008-08-15 14:43:28,496 DEBUG [org.hibernate.cache.NonstrictReadWriteCache] Cache lookup: org.jbpm.graph.def.Node.exceptionHandlers#9
2008-08-15 14:43:28,496 DEBUG [org.hibernate.cache.NonstrictReadWriteCache] Cache hit


2008-08-15 14:43:28,496 WARN [org.jboss.soa.esb.services.jbpm.cmd.CallbackCommand] Token id 5 from process instance 5 is no longer on expected node, expected 8 but discovered 9


2008-08-15 14:43:28,496 DEBUG [org.jbpm.JbpmContext] closing jbpmContext org.jbpm.JbpmContext@2488b69c
2008-08-15 14:43:28,496 DEBUG [org.jbpm.svc.Services] closing service 'persistence': org.jbpm.persistence.jta.JtaDbPersistenceService@6da6fd38
2008-08-15 14:43:28,496 DEBUG [org.jbpm.svc.Services] closing service 'tx': org.jbpm.tx.TxService@6e3a9fc5
2008-08-15 14:43:28,497 DEBUG [org.hibernate.event.def.AbstractFlushingEventListener] processing flush-time cascades
2008-08-15 14:43:28,497 DEBUG [org.hibernate.event.def.AbstractFlushingEventListener] dirty checking collections
2008-08-15 14:43:28,497 DEBUG [org.hibernate.engine.Collections] Collection found: [org.jbpm.graph.exe.Token.children#5], was: [org.jbpm.graph.exe.Token.children#5] (uninitialized)
2008-08-15 14:43:28,497 DEBUG [org.hibernate.engine.Collections] Collection found: [org.jbpm.graph.exe.Token.comments#5], was: [org.jbpm.graph.exe.Token.comments#5] (uninitialized)
2008-08-15 14:43:28,497 DEBUG [org.hibernate.engine.Collections] Collection found: [org.jbpm.graph.exe.ProcessInstance.runtimeActions#5], was: [org.jbpm.graph.exe.ProcessInstance.runtimeActions#5] (uninitialized)
2008-08-15 14:43:28,497 DEBUG [org.hibernate.engine.Collections] Collection found: [org.jbpm.graph.exe.ProcessInstance.instances#5], was: [org.jbpm.graph.exe.ProcessInstance.instances#5] (uninitialized)
2008-08-15 14:43:28,497 DEBUG [org.hibernate.engine.Collections] Collection found: [org.jbpm.graph.def.Node.events#9], was: [org.jbpm.graph.def.Node.events#9] (uninitialized)
2008-08-15 14:43:28,497 DEBUG [org.hibernate.engine.Collections] Collection found: [org.jbpm.graph.def.Node.exceptionHandlers#9], was: [org.jbpm.graph.def.Node.exceptionHandlers#9] (initialized)
2008-08-15 14:43:28,497 DEBUG [org.hibernate.engine.Collections] Collection found: [org.jbpm.graph.def.Node.leavingTransitions#9], was: [org.jbpm.graph.def.Node.leavingTransitions#9] (uninitialized)
2008-08-15 14:43:28,497 DEBUG [org.hibernate.engine.Collections] Collection found: [org.jbpm.graph.def.Node.arrivingTransitions#9], was: [org.jbpm.graph.def.Node.arrivingTransitions#9] (uninitialized)
2008-08-15 14:43:28,497 DEBUG [org.hibernate.event.def.AbstractFlushingEventListener] Flushed: 0 insertions, 0 updates, 0 deletions to 3 objects
2008-08-15 14:43:28,497 DEBUG [org.hibernate.event.def.AbstractFlushingEventListener] Flushed: 0 (re)creations, 0 updates, 0 removals to 8 collections
2008-08-15 14:43:28,497 DEBUG [org.hibernate.pretty.Printer] listing entities:
2008-08-15 14:43:28,497 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
2008-08-15 14:43:28,497 DEBUG [org.hibernate.jdbc.ConnectionManager] skipping aggressive-release due to flush cycle
2008-08-15 14:43:28,497 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
2008-08-15 14:43:28,497 DEBUG [org.hibernate.SQL] update JBPM_VARIABLEINSTANCE set VERSION_=?, NAME_=?, CONVERTER_=?, TOKEN_=?, TOKENVARIABLEMAP_=?, PROCESSINSTANCE_=?, BYTEARRAYVALUE_=? where ID_=? and VERSION_=?
2008-08-15 14:43:28,498 DEBUG [org.hibernate.pretty.Printer] org.jbpm.graph.exe.Token{isSuspended=false, isTerminationImplicit=false, lock=null, children=<uninitialized>, parent=null, processInstance=org.jbpm.graph.exe.ProcessInstance#5, nextLogIndex=20, version=4, id=5, node=org.jbpm.graph.def.Node#9, nodeEnter=2008-08-15 14:42:56, subProcessInstance=null, start=2008-08-15 14:42:56, name=null, isAbleToReactivateParent=true, comments=<uninitialized>, end=null}
2008-08-15 14:43:28,498 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
2008-08-15 14:43:28,498 DEBUG [org.hibernate.jdbc.ConnectionManager] skipping aggressive-release due to flush cycle
2008-08-15 14:43:28,498 DEBUG [org.hibernate.pretty.Printer] org.jbpm.graph.exe.ProcessInstance{processDefinition=org.jbpm.graph.def.ProcessDefinition#2, id=5, superProcessToken=null, start=2008-08-15 14:42:56, isSuspended=false, runtimeActions=<uninitialized>, rootToken=org.jbpm.graph.exe.Token#5, instances=<uninitialized>, end=null, key=null, version=1}
2008-08-15 14:43:28,498 DEBUG [org.hibernate.persister.collection.AbstractCollectionPersister] Inserting collection: [org.jbpm.bytes.ByteArray.byteBlocks#126]
2008-08-15 14:43:28,498 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
2008-08-15 14:43:28,498 DEBUG [org.hibernate.pretty.Printer] org.jbpm.graph.node.Fork{isAsyncExclusive=false, events=<uninitialized>, isAsync=false, leavingTransitions=<uninitialized>, script=null, exceptionHandlers=[], id=9, processDefinition=org.jbpm.graph.def.ProcessDefinition#2, superState=null, description=null, name=fork1, arrivingTransitions=<uninitialized>, action=null}

[jjarkko]

I noticed that if the process takes a while to return you'll get the error message and the process and actionpipeline are hung. I'd say if the work takes more than 10 seconds the service will hang.

[jjarkko]

Actually further investigation revealed that if the last Esb service which is called from the jbpm process calls Thread.sleep(50); the service will work everytime.
Thread.sleep( 0 - 10 ) causes that service to fail always , weird isn't?

JBPM process:
start node
node: call esb service 1 calls ext WS using Axis
node: call esb service 2 which calls some ext service using httpclient
node: call esb service 3 analyses the results, aka. Thread.sleep(30)
end-state: end1

Routing is direct, start -> service 1 -> service 2 -> service 3 -> end

 <end-state name="end1">
 <event type="node-enter">
 <action name="notify"
 class="org.jboss.soa.esb.services.jbpm.actionhandlers.EsbNotifier">
 <bpmToEsbVars>
 <mapping bpm="theBody" esb="BODY_CONTENT" />
 <mapping bpm="customer" esb="customer"></mapping>
 </bpmToEsbVars>
 <replyToOriginator>reply</replyToOriginator>
 </action>
 </event>
 </end-state>

Method from esb service 3:

 public Message process(Message message) throws Exception {
 logHeader();

 Thread.sleep(50); // This prevents
 // "WARN [CallbackCommand] Token id 17 from process instance 9 is no
 // longer on expected node,
 // expected 8 but discovered 9"
 logFooter();
 return message;
 }

So, using Thread.sleep(50) is a workaround, a little nasty one perhaps.

[kconner]

It sounds as if you may have a race between the outgoing message (from jBPM) and the transaction which commits the process state to the database.

You should really be using a transactional transport to talk to your services so that the outgoing message (in the case of JMS/InVM) is not sent until the transaction commits. The database state would then be consistent and at the values expected by the response.

The other possibility would be a timeout on the jBPM node advancing the process instance but that does not fit the description you have given.

Kev