[CallbackCommand] Token id 5 from process instance 5 is no
jjarkko Aug 15, 2008 8:08 AMHello,
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}