jbpm timer transaction issues
pbrewer_uk Nov 13, 2007 9:53 AMI'm using Seam 2.0.0.GA with jbpm 3.2.1.GA and have a simple timer process that simple creates a task and if it is not completed by a user within 1 minute a timer fires and progresses the workflow automatically, writing out messages to the logs as it goes:
<?xml version="1.0" encoding="UTF-8"?> <process-definition xmlns="urn:jbpm.org:jpdl-3.1" xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance" xsi:schemaLocation="urn:jbpm.org:jpdl-3.1 http://jbpm.org/jpdl-3.1.xsd" name="timerTest"> <start-state name="start"> <transition name="" to="timerTest" /> </start-state> <task-node name="timerTest"> <event type="node-enter"> <action expression="#{timerTestWorkflow.logNodeEnter}" /> </event> <event type="node-leave"> <action expression="#{timerTestWorkflow.logNodeLeave}" /> </event> <task name="timerTestTask" description="TimerTestTask"> <assignment actor-id="admin" /> <event type="task-create"> <action expression="#{timerTestWorkflow.logTaskCreate}" /> </event> <event type="timer-create"> <action expression="#{timerTestWorkflow.logTimerCreate}" /> </event> <timer duedate="1 minute" transition="finished"> <action expression="#{timerTestWorkflow.logTimerFired}" /> </timer> </task> <transition name="finished" to="end" /> </task-node> <end-state name="end"></end-state> </process-definition>
However, when the timer fires I get the following exception, and the workflow doesn't complete.
2007-11-13 14:34:44,863 DEBUG [org.jbpm.job.executor.JobExecutorThread] acquiring jobs for execution... 2007-11-13 14:34:44,863 DEBUG [org.jbpm.configuration.JbpmContextInfo] creating jbpm context with service factories '[message, tx, scheduler, authentication, persistence, logging]' 2007-11-13 14:34:44,863 DEBUG [org.jbpm.JbpmContext] creating org.jbpm.JbpmContext@346072 2007-11-13 14:34:44,863 DEBUG [org.jbpm.persistence.db.DbPersistenceServiceFactory] creating persistence service 2007-11-13 14:34:44,863 DEBUG [org.jbpm.persistence.db.DbPersistenceService] creating hibernate session 2007-11-13 14:34:44,863 DEBUG [org.jbpm.job.executor.JobExecutorThread] querying for acquirable job... 2007-11-13 14:34:44,863 DEBUG [org.jbpm.job.executor.JobExecutorThread] trying to obtain a lock for 'timer(timerTestTask,07-11-13 14:34:42,667,TaskInstance: 9,Token: 15)' 2007-11-13 14:34:44,878 WARN [org.hibernate.engine.StatefulPersistenceContext.ProxyWarnLog] Narrowing proxy to class org.jbpm.graph.node.TaskNode - this operation breaks == 2007-11-13 14:34:44,878 TRACE [org.hibernate.event.def.DefaultInitializeCollectionEventListener] initializing collection [org.jbpm.taskmgmt.def.Task.exceptionHandlers#1619] 2007-11-13 14:34:44,878 TRACE [org.hibernate.event.def.DefaultInitializeCollectionEventListener] checking second-level cache 2007-11-13 14:34:44,878 TRACE [org.hibernate.event.def.DefaultInitializeCollectionEventListener] collection initialized from cache 2007-11-13 14:34:44,878 DEBUG [org.jbpm.JbpmContext] closing jbpmContext org.jbpm.JbpmContext@346072 2007-11-13 14:34:44,878 DEBUG [org.jbpm.svc.Services] closing service 'persistence': org.jbpm.persistence.db.DbPersistenceService@1457b0f 2007-11-13 14:34:44,878 DEBUG [org.jbpm.persistence.db.DbPersistenceService] flushing hibernate session SessionImpl(PersistenceContext[entityKeys=[EntityKey[org.jbpm.job.Job#9], EntityKey[org.jbpm.graph.exe.Token#15], EntityKey[org.jbpm.taskmgmt.exe.TaskInstance#9], EntityKey[org.jbpm.taskmgmt.def.Task#1619]],collectionKeys=[CollectionKey[org.jbpm.taskmgmt.exe.TaskInstance.variableInstances#9], CollectionKey[org.jbpm.taskmgmt.def.Task.events#1619], CollectionKey[org.jbpm.graph.exe.Token.children#15], CollectionKey[org.jbpm.taskmgmt.exe.TaskInstance.comments#9], CollectionKey[org.jbpm.taskmgmt.def.Task.exceptionHandlers#1619], CollectionKey[org.jbpm.taskmgmt.exe.TaskInstance.pooledActors#9], CollectionKey[org.jbpm.graph.exe.Token.comments#15]]];ActionQueue[insertions=[] updates=[] deletions=[] collectionCreations=[] collectionRemovals=[] collectionUpdates=[]]) 2007-11-13 14:34:44,894 DEBUG [org.jbpm.persistence.db.DbPersistenceService] closing hibernate session 2007-11-13 14:34:44,894 DEBUG [org.jbpm.svc.Services] closing service 'tx': org.jbpm.tx.TxService@2a3502 2007-11-13 14:34:44,894 DEBUG [org.jbpm.job.executor.JobExecutorThread] obtained locks on following jobs: [timer(timerTestTask,07-11-13 14:34:42,667,TaskInstance: 9,Token: 15)] 2007-11-13 14:34:44,894 DEBUG [org.jbpm.configuration.JbpmContextInfo] creating jbpm context with service factories '[message, tx, scheduler, authentication, persistence, logging]' 2007-11-13 14:34:44,894 DEBUG [org.jbpm.JbpmContext] creating org.jbpm.JbpmContext@fe331c 2007-11-13 14:34:44,894 DEBUG [org.jbpm.persistence.db.DbPersistenceServiceFactory] creating persistence service 2007-11-13 14:34:44,894 DEBUG [org.jbpm.persistence.db.DbPersistenceService] creating hibernate session 2007-11-13 14:34:44,894 DEBUG [org.jbpm.job.executor.JobExecutorThread] executing job timer(timerTestTask,07-11-13 14:34:42,667,TaskInstance: 9,Token: 15) 2007-11-13 14:34:44,894 WARN [org.hibernate.engine.StatefulPersistenceContext.ProxyWarnLog] Narrowing proxy to class org.jbpm.graph.node.TaskNode - this operation breaks == 2007-11-13 14:34:44,894 TRACE [org.hibernate.event.def.DefaultInitializeCollectionEventListener] initializing collection [org.jbpm.taskmgmt.def.Task.exceptionHandlers#1619] 2007-11-13 14:34:44,894 TRACE [org.hibernate.event.def.DefaultInitializeCollectionEventListener] checking second-level cache 2007-11-13 14:34:44,894 TRACE [org.hibernate.event.def.DefaultInitializeCollectionEventListener] collection initialized from cache 2007-11-13 14:34:44,894 TRACE [org.hibernate.event.def.DefaultInitializeCollectionEventListener] initializing collection [org.jbpm.taskmgmt.def.Task.events#1619] 2007-11-13 14:34:44,894 TRACE [org.hibernate.event.def.DefaultInitializeCollectionEventListener] checking second-level cache 2007-11-13 14:34:44,894 TRACE [org.hibernate.event.def.DefaultInitializeCollectionEventListener] collection initialized from cache 2007-11-13 14:34:44,894 TRACE [org.hibernate.event.def.DefaultInitializeCollectionEventListener] initializing collection [org.jbpm.graph.exe.ProcessInstance.runtimeActions#15] 2007-11-13 14:34:44,894 TRACE [org.hibernate.event.def.DefaultInitializeCollectionEventListener] checking second-level cache 2007-11-13 14:34:44,894 TRACE [org.hibernate.event.def.DefaultInitializeCollectionEventListener] collection not cached 2007-11-13 14:34:44,910 TRACE [org.hibernate.event.def.DefaultInitializeCollectionEventListener] collection initialized 2007-11-13 14:34:44,910 TRACE [org.hibernate.event.def.DefaultInitializeCollectionEventListener] initializing collection [org.jbpm.graph.def.Node.exceptionHandlers#7373] 2007-11-13 14:34:44,910 TRACE [org.hibernate.event.def.DefaultInitializeCollectionEventListener] checking second-level cache 2007-11-13 14:34:44,910 TRACE [org.hibernate.event.def.DefaultInitializeCollectionEventListener] collection initialized from cache 2007-11-13 14:34:44,910 TRACE [org.hibernate.event.def.DefaultInitializeCollectionEventListener] initializing collection [org.jbpm.graph.def.Node.events#7373] 2007-11-13 14:34:44,910 TRACE [org.hibernate.event.def.DefaultInitializeCollectionEventListener] checking second-level cache 2007-11-13 14:34:44,910 TRACE [org.hibernate.event.def.DefaultInitializeCollectionEventListener] collection initialized from cache 2007-11-13 14:34:44,910 TRACE [org.hibernate.event.def.DefaultInitializeCollectionEventListener] initializing collection [org.jbpm.graph.def.ProcessDefinition.exceptionHandlers#567] 2007-11-13 14:34:44,910 TRACE [org.hibernate.event.def.DefaultInitializeCollectionEventListener] checking second-level cache 2007-11-13 14:34:44,910 TRACE [org.hibernate.event.def.DefaultInitializeCollectionEventListener] collection initialized from cache 2007-11-13 14:34:44,910 TRACE [org.hibernate.event.def.DefaultInitializeCollectionEventListener] initializing collection [org.jbpm.graph.def.ProcessDefinition.events#567] 2007-11-13 14:34:44,910 TRACE [org.hibernate.event.def.DefaultInitializeCollectionEventListener] checking second-level cache 2007-11-13 14:34:44,910 TRACE [org.hibernate.event.def.DefaultInitializeCollectionEventListener] collection initialized from cache 2007-11-13 14:34:44,910 DEBUG [org.jbpm.job.Timer] executing timer 'timer(timerTestTask,07-11-13 14:34:42,667,TaskInstance: 9,Token: 15)' 2007-11-13 14:34:44,910 TRACE [org.hibernate.event.def.DefaultInitializeCollectionEventListener] initializing collection [org.jbpm.graph.exe.ProcessInstance.instances#15] 2007-11-13 14:34:44,910 TRACE [org.hibernate.event.def.DefaultInitializeCollectionEventListener] checking second-level cache 2007-11-13 14:34:44,910 TRACE [org.hibernate.event.def.DefaultInitializeCollectionEventListener] collection not cached 2007-11-13 14:34:44,910 TRACE [org.hibernate.event.def.DefaultInitializeCollectionEventListener] collection initialized 2007-11-13 14:34:44,910 DEBUG [org.jbpm.graph.def.GraphElement] executing action 'action[#{timerTestWorkflow.logTimerFired}]' 2007-11-13 14:34:44,925 DEBUG [org.jbpm.configuration.JbpmContextInfo] creating jbpm context with service factories '[message, tx, scheduler, authentication, persistence, logging]' 2007-11-13 14:34:44,925 DEBUG [org.jbpm.JbpmContext] creating org.jbpm.JbpmContext@17084b8 2007-11-13 14:34:44,925 DEBUG [org.jbpm.configuration.JbpmContextInfo] creating jbpm context with service factories '[message, tx, scheduler, authentication, persistence, logging]' 2007-11-13 14:34:44,925 DEBUG [org.jbpm.JbpmContext] creating org.jbpm.JbpmContext@19666a 2007-11-13 14:34:44,925 DEBUG [org.jbpm.JbpmContext] closing jbpmContext org.jbpm.JbpmContext@19666a 2007-11-13 14:34:44,925 DEBUG [org.jbpm.persistence.db.DbPersistenceServiceFactory] creating persistence service 2007-11-13 14:34:44,925 DEBUG [org.jbpm.persistence.db.DbPersistenceService] creating hibernate session 2007-11-13 14:34:44,925 TRACE [org.hibernate.event.def.DefaultInitializeCollectionEventListener] initializing collection [org.jbpm.taskmgmt.exe.TaskInstance.variableInstances#9] 2007-11-13 14:34:44,925 TRACE [org.hibernate.event.def.DefaultInitializeCollectionEventListener] checking second-level cache 2007-11-13 14:34:44,925 TRACE [org.hibernate.event.def.DefaultInitializeCollectionEventListener] collection not cached 2007-11-13 14:34:44,925 TRACE [org.hibernate.event.def.DefaultInitializeCollectionEventListener] collection initialized 2007-11-13 14:34:44,941 TRACE [org.hibernate.event.def.DefaultInitializeCollectionEventListener] initializing collection [org.jbpm.graph.exe.ProcessInstance.instances#15] 2007-11-13 14:34:44,941 TRACE [org.hibernate.event.def.DefaultInitializeCollectionEventListener] checking second-level cache 2007-11-13 14:34:44,941 TRACE [org.hibernate.event.def.DefaultInitializeCollectionEventListener] collection not cached 2007-11-13 14:34:44,941 TRACE [org.hibernate.event.def.DefaultInitializeCollectionEventListener] collection initialized 2007-11-13 14:34:44,941 TRACE [org.hibernate.event.def.DefaultInitializeCollectionEventListener] initializing collection [org.jbpm.context.exe.ContextInstance.tokenVariableMaps#29] 2007-11-13 14:34:44,941 TRACE [org.hibernate.event.def.DefaultInitializeCollectionEventListener] checking second-level cache 2007-11-13 14:34:44,941 TRACE [org.hibernate.event.def.DefaultInitializeCollectionEventListener] collection not cached 2007-11-13 14:34:44,941 TRACE [org.hibernate.event.def.DefaultInitializeCollectionEventListener] collection initialized 2007-11-13 14:34:44,941 TRACE [org.hibernate.event.def.DefaultInitializeCollectionEventListener] initializing collection [org.jbpm.context.exe.TokenVariableMap.variableInstances#13] 2007-11-13 14:34:44,941 TRACE [org.hibernate.event.def.DefaultInitializeCollectionEventListener] checking second-level cache 2007-11-13 14:34:44,941 TRACE [org.hibernate.event.def.DefaultInitializeCollectionEventListener] collection not cached 2007-11-13 14:34:44,941 TRACE [org.hibernate.event.def.DefaultInitializeCollectionEventListener] collection initialized 2007-11-13 14:34:44,941 INFO [uk.co.iblocks.midas.workflow.TimerTestWorkflow] logTimerFired 2007-11-13 14:34:44,941 DEBUG [org.jbpm.JbpmContext] closing jbpmContext org.jbpm.JbpmContext@17084b8 2007-11-13 14:34:44,941 DEBUG [org.jbpm.svc.Services] executing default save operations 2007-11-13 14:34:44,941 DEBUG [org.jbpm.svc.save.HibernateSaveOperation] saving process instance 2007-11-13 14:34:44,941 DEBUG [org.jbpm.svc.save.SaveLogsOperation] flushing logs to logging service. 2007-11-13 14:34:44,941 DEBUG [org.jbpm.svc.save.CascadeSaveOperation] cascading save of 'org.jbpm.graph.exe.ProcessInstance@565388' 2007-11-13 14:34:44,941 DEBUG [org.jbpm.svc.Services] executing default save operations 2007-11-13 14:34:44,941 DEBUG [org.jbpm.svc.save.HibernateSaveOperation] saving process instance 2007-11-13 14:34:44,941 DEBUG [org.jbpm.svc.save.SaveLogsOperation] flushing logs to logging service. 2007-11-13 14:34:44,941 DEBUG [org.jbpm.svc.save.CascadeSaveOperation] cascading save of 'org.jbpm.graph.exe.ProcessInstance@565388' 2007-11-13 14:34:44,941 DEBUG [org.jbpm.svc.Services] closing service 'persistence': org.jbpm.persistence.db.DbPersistenceService@1f3ca88 2007-11-13 14:34:44,941 DEBUG [org.jbpm.persistence.db.DbPersistenceService] flushing hibernate session SessionImpl(PersistenceContext[entityKeys=[EntityKey[org.jbpm.graph.exe.Token#15], EntityKey[org.jbpm.taskmgmt.exe.TaskInstance#9], EntityKey[org.jbpm.context.exe.TokenVariableMap#13], EntityKey[org.jbpm.graph.exe.ProcessInstance#15], EntityKey[org.jbpm.taskmgmt.exe.TaskMgmtInstance#30], EntityKey[org.jbpm.module.exe.ModuleInstance#29]],collectionKeys=[CollectionKey[org.jbpm.taskmgmt.exe.TaskInstance.variableInstances#9], CollectionKey[org.jbpm.taskmgmt.exe.TaskMgmtInstance.taskInstances#30], CollectionKey[org.jbpm.graph.exe.ProcessInstance.runtimeActions#15], CollectionKey[org.jbpm.graph.exe.Token.children#15], CollectionKey[org.jbpm.context.exe.ContextInstance.tokenVariableMaps#29], CollectionKey[org.jbpm.taskmgmt.exe.TaskInstance.comments#9], CollectionKey[org.jbpm.taskmgmt.exe.TaskInstance.pooledActors#9], CollectionKey[org.jbpm.graph.exe.Token.comments#15], CollectionKey[org.jbpm.graph.exe.ProcessInstance.instances#15], CollectionKey[org.jbpm.taskmgmt.exe.TaskMgmtInstance.swimlaneInstances#30], CollectionKey[org.jbpm.context.exe.TokenVariableMap.variableInstances#13]]];ActionQueue[insertions=[] updates=[] deletions=[] collectionCreations=[] collectionRemovals=[] collectionUpdates=[]]) 2007-11-13 14:34:44,941 DEBUG [org.jbpm.persistence.db.DbPersistenceService] closing hibernate session 2007-11-13 14:34:44,941 DEBUG [org.jbpm.svc.Services] closing service 'tx': org.jbpm.tx.TxService@b1221b 2007-11-13 14:34:44,941 DEBUG [org.jbpm.svc.Services] closing service 'logging': org.jbpm.logging.db.DbLoggingService@1362c68 2007-11-13 14:34:44,941 TRACE [org.hibernate.event.def.DefaultInitializeCollectionEventListener] initializing collection [org.jbpm.graph.def.Node.leavingTransitions#7373] 2007-11-13 14:34:44,941 TRACE [org.hibernate.event.def.DefaultInitializeCollectionEventListener] checking second-level cache 2007-11-13 14:34:44,941 TRACE [org.hibernate.event.def.DefaultInitializeCollectionEventListener] collection not cached 2007-11-13 14:34:44,956 TRACE [org.hibernate.event.def.DefaultInitializeCollectionEventListener] initializing collection [org.jbpm.graph.def.Transition.exceptionHandlers#9566] 2007-11-13 14:34:44,956 TRACE [org.hibernate.event.def.DefaultInitializeCollectionEventListener] checking second-level cache 2007-11-13 14:34:44,956 TRACE [org.hibernate.event.def.DefaultInitializeCollectionEventListener] collection not cached 2007-11-13 14:34:44,956 TRACE [org.hibernate.event.def.DefaultInitializeCollectionEventListener] collection initialized 2007-11-13 14:34:44,956 TRACE [org.hibernate.event.def.DefaultInitializeCollectionEventListener] collection initialized 2007-11-13 14:34:44,956 DEBUG [org.jbpm.graph.def.GraphElement] event 'before-signal' on 'TaskNode(timerTest)' for 'Token(/)' 2007-11-13 14:34:44,956 TRACE [org.hibernate.event.def.DefaultInitializeCollectionEventListener] initializing collection [org.jbpm.taskmgmt.exe.TaskMgmtInstance.taskInstances#30] 2007-11-13 14:34:44,956 TRACE [org.hibernate.event.def.DefaultInitializeCollectionEventListener] checking second-level cache 2007-11-13 14:34:44,956 TRACE [org.hibernate.event.def.DefaultInitializeCollectionEventListener] collection not cached 2007-11-13 14:34:44,956 TRACE [org.hibernate.event.def.DefaultInitializeCollectionEventListener] collection initialized 2007-11-13 14:34:44,972 DEBUG [org.jbpm.graph.def.GraphElement] event 'node-leave' on 'TaskNode(timerTest)' for 'Token(/)' 2007-11-13 14:34:44,972 TRACE [org.hibernate.event.def.DefaultInitializeCollectionEventListener] initializing collection [org.jbpm.graph.def.Event.actions#1272] 2007-11-13 14:34:44,972 TRACE [org.hibernate.event.def.DefaultInitializeCollectionEventListener] checking second-level cache 2007-11-13 14:34:44,972 TRACE [org.hibernate.event.def.DefaultInitializeCollectionEventListener] collection not cached 2007-11-13 14:34:44,972 TRACE [org.hibernate.event.def.DefaultInitializeCollectionEventListener] collection initialized 2007-11-13 14:34:44,972 DEBUG [org.jbpm.graph.def.GraphElement] executing action 'action[#{timerTestWorkflow.logNodeLeave}]' 2007-11-13 14:34:44,972 DEBUG [org.jbpm.graph.exe.Token] token[15] is locked by token[15] 2007-11-13 14:34:45,003 DEBUG [org.jbpm.configuration.JbpmContextInfo] creating jbpm context with service factories '[message, tx, scheduler, authentication, persistence, logging]' 2007-11-13 14:34:45,003 DEBUG [org.jbpm.JbpmContext] creating org.jbpm.JbpmContext@655c61 2007-11-13 14:34:45,003 DEBUG [org.jbpm.configuration.JbpmContextInfo] creating jbpm context with service factories '[message, tx, scheduler, authentication, persistence, logging]' 2007-11-13 14:34:45,003 DEBUG [org.jbpm.JbpmContext] creating org.jbpm.JbpmContext@93efc3 2007-11-13 14:34:45,003 DEBUG [org.jbpm.JbpmContext] closing jbpmContext org.jbpm.JbpmContext@93efc3 2007-11-13 14:34:45,003 DEBUG [org.jbpm.persistence.db.DbPersistenceServiceFactory] creating persistence service 2007-11-13 14:34:45,003 DEBUG [org.jbpm.persistence.db.DbPersistenceService] creating hibernate session 2007-11-13 14:34:45,003 TRACE [org.hibernate.event.def.DefaultInitializeCollectionEventListener] initializing collection [org.jbpm.graph.exe.ProcessInstance.instances#15] 2007-11-13 14:34:45,003 TRACE [org.hibernate.event.def.DefaultInitializeCollectionEventListener] checking second-level cache 2007-11-13 14:34:45,003 TRACE [org.hibernate.event.def.DefaultInitializeCollectionEventListener] collection not cached 2007-11-13 14:34:45,003 TRACE [org.hibernate.event.def.DefaultInitializeCollectionEventListener] collection initialized 2007-11-13 14:34:45,003 TRACE [org.hibernate.event.def.DefaultInitializeCollectionEventListener] initializing collection [org.jbpm.context.exe.ContextInstance.tokenVariableMaps#29] 2007-11-13 14:34:45,003 TRACE [org.hibernate.event.def.DefaultInitializeCollectionEventListener] checking second-level cache 2007-11-13 14:34:45,003 TRACE [org.hibernate.event.def.DefaultInitializeCollectionEventListener] collection not cached 2007-11-13 14:34:45,003 TRACE [org.hibernate.event.def.DefaultInitializeCollectionEventListener] collection initialized 2007-11-13 14:34:45,003 TRACE [org.hibernate.event.def.DefaultInitializeCollectionEventListener] initializing collection [org.jbpm.context.exe.TokenVariableMap.variableInstances#13] 2007-11-13 14:34:45,003 TRACE [org.hibernate.event.def.DefaultInitializeCollectionEventListener] checking second-level cache 2007-11-13 14:34:45,003 TRACE [org.hibernate.event.def.DefaultInitializeCollectionEventListener] collection not cached 2007-11-13 14:34:45,003 TRACE [org.hibernate.event.def.DefaultInitializeCollectionEventListener] collection initialized 2007-11-13 14:34:45,003 INFO [uk.co.iblocks.midas.workflow.TimerTestWorkflow] logNodeLeave 2007-11-13 14:34:45,019 DEBUG [org.jbpm.JbpmContext] closing jbpmContext org.jbpm.JbpmContext@655c61 2007-11-13 14:34:45,019 DEBUG [org.jbpm.svc.Services] executing default save operations 2007-11-13 14:34:45,019 DEBUG [org.jbpm.svc.save.HibernateSaveOperation] saving process instance 2007-11-13 14:34:45,019 DEBUG [org.jbpm.svc.save.SaveLogsOperation] flushing logs to logging service. 2007-11-13 14:34:45,019 DEBUG [org.jbpm.svc.save.CascadeSaveOperation] cascading save of 'org.jbpm.graph.exe.ProcessInstance@101cc3e' 2007-11-13 14:34:45,019 DEBUG [org.jbpm.svc.Services] executing default save operations 2007-11-13 14:34:45,019 DEBUG [org.jbpm.svc.save.HibernateSaveOperation] saving process instance 2007-11-13 14:34:45,019 DEBUG [org.jbpm.svc.save.SaveLogsOperation] flushing logs to logging service. 2007-11-13 14:34:45,019 DEBUG [org.jbpm.svc.save.CascadeSaveOperation] cascading save of 'org.jbpm.graph.exe.ProcessInstance@101cc3e' 2007-11-13 14:34:45,019 DEBUG [org.jbpm.svc.Services] closing service 'persistence': org.jbpm.persistence.db.DbPersistenceService@4c61c2 2007-11-13 14:34:45,019 DEBUG [org.jbpm.persistence.db.DbPersistenceService] flushing hibernate session SessionImpl(PersistenceContext[entityKeys=[EntityKey[org.jbpm.graph.exe.Token#15], EntityKey[org.jbpm.context.exe.TokenVariableMap#13], EntityKey[org.jbpm.graph.exe.ProcessInstance#15], EntityKey[org.jbpm.module.exe.ModuleInstance#30], EntityKey[org.jbpm.module.exe.ModuleInstance#29]],collectionKeys=[CollectionKey[org.jbpm.taskmgmt.exe.TaskMgmtInstance.taskInstances#30], CollectionKey[org.jbpm.graph.exe.ProcessInstance.runtimeActions#15], CollectionKey[org.jbpm.graph.exe.Token.children#15], CollectionKey[org.jbpm.context.exe.ContextInstance.tokenVariableMaps#29], CollectionKey[org.jbpm.graph.exe.Token.comments#15], CollectionKey[org.jbpm.graph.exe.ProcessInstance.instances#15], CollectionKey[org.jbpm.taskmgmt.exe.TaskMgmtInstance.swimlaneInstances#30], CollectionKey[org.jbpm.context.exe.TokenVariableMap.variableInstances#13]]];ActionQueue[insertions=[] updates=[] deletions=[] collectionCreations=[] collectionRemovals=[] collectionUpdates=[]]) 2007-11-13 14:34:45,019 DEBUG [org.jbpm.persistence.db.DbPersistenceService] closing hibernate session 2007-11-13 14:34:45,019 DEBUG [org.jbpm.svc.Services] closing service 'tx': org.jbpm.tx.TxService@1e5484b 2007-11-13 14:34:45,019 DEBUG [org.jbpm.svc.Services] closing service 'logging': org.jbpm.logging.db.DbLoggingService@1ed55b9 2007-11-13 14:34:45,019 DEBUG [org.jbpm.graph.exe.Token] token[15] is unlocked by token[15] 2007-11-13 14:34:45,019 DEBUG [org.jbpm.graph.def.GraphElement] event 'transition' on 'Transition(finished)' for 'Token(/)' 2007-11-13 14:34:45,019 TRACE [org.hibernate.event.def.DefaultInitializeCollectionEventListener] initializing collection [org.jbpm.graph.def.Transition.events#9566] 2007-11-13 14:34:45,019 TRACE [org.hibernate.event.def.DefaultInitializeCollectionEventListener] checking second-level cache 2007-11-13 14:34:45,019 TRACE [org.hibernate.event.def.DefaultInitializeCollectionEventListener] collection not cached 2007-11-13 14:34:45,034 TRACE [org.hibernate.event.def.DefaultInitializeCollectionEventListener] collection initialized 2007-11-13 14:34:45,034 TRACE [org.hibernate.event.def.DefaultInitializeCollectionEventListener] initializing collection [org.jbpm.graph.def.Node.exceptionHandlers#7374] 2007-11-13 14:34:45,034 TRACE [org.hibernate.event.def.DefaultInitializeCollectionEventListener] checking second-level cache 2007-11-13 14:34:45,034 TRACE [org.hibernate.event.def.DefaultInitializeCollectionEventListener] collection not cached 2007-11-13 14:34:45,034 TRACE [org.hibernate.event.def.DefaultInitializeCollectionEventListener] collection initialized 2007-11-13 14:34:45,034 DEBUG [org.jbpm.graph.def.GraphElement] event 'node-enter' on 'EndState(end)' for 'Token(/)' 2007-11-13 14:34:45,034 TRACE [org.hibernate.event.def.DefaultInitializeCollectionEventListener] initializing collection [org.jbpm.graph.def.Node.events#7374] 2007-11-13 14:34:45,034 TRACE [org.hibernate.event.def.DefaultInitializeCollectionEventListener] checking second-level cache 2007-11-13 14:34:45,034 TRACE [org.hibernate.event.def.DefaultInitializeCollectionEventListener] collection not cached 2007-11-13 14:34:45,034 TRACE [org.hibernate.event.def.DefaultInitializeCollectionEventListener] collection initialized 2007-11-13 14:34:45,034 TRACE [org.hibernate.event.def.DefaultInitializeCollectionEventListener] initializing collection [org.jbpm.graph.exe.Token.children#15] 2007-11-13 14:34:45,034 TRACE [org.hibernate.event.def.DefaultInitializeCollectionEventListener] checking second-level cache 2007-11-13 14:34:45,034 TRACE [org.hibernate.event.def.DefaultInitializeCollectionEventListener] collection not cached 2007-11-13 14:34:45,034 TRACE [org.hibernate.event.def.DefaultInitializeCollectionEventListener] collection initialized 2007-11-13 14:34:45,034 DEBUG [org.jbpm.graph.def.GraphElement] event 'process-end' on 'ProcessDefinition(timerTest)' for 'Token(/)' 2007-11-13 14:34:45,034 ERROR [org.jbpm.db.JobSession] org.hibernate.TransactionException: could not register synchronization 2007-11-13 14:34:45,034 DEBUG [org.jbpm.job.executor.JobExecutorThread] exception while executing 'timer(timerTestTask,07-11-13 14:34:42,667,TaskInstance: 9,Token: 15)' org.jbpm.JbpmException: couldn't delete jobs for 'org.jbpm.graph.exe.ProcessInstance@d208f1' at org.jbpm.db.JobSession.deleteJobsForProcessInstance(JobSession.java:211) at org.jbpm.scheduler.db.DbSchedulerService.deleteTimersByProcessInstance(DbSchedulerService.java:54) at org.jbpm.graph.exe.ProcessInstance.end(ProcessInstance.java:330) at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39) at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25) at java.lang.reflect.Method.invoke(Method.java:597) at org.hibernate.proxy.pojo.javassist.JavassistLazyInitializer.invoke(JavassistLazyInitializer.java:173) at org.jbpm.graph.exe.ProcessInstance_$$_javassist_174.end(ProcessInstance_$$_javassist_174.java) at org.jbpm.graph.exe.Token.notifyParentOfTokenEnd(Token.java:332) at org.jbpm.graph.exe.Token.end(Token.java:304) at org.jbpm.graph.exe.Token.end(Token.java:254) at org.jbpm.graph.node.EndState.execute(EndState.java:59) at org.jbpm.graph.def.Node.enter(Node.java:319) at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39) at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25) at java.lang.reflect.Method.invoke(Method.java:597) at org.hibernate.proxy.pojo.javassist.JavassistLazyInitializer.invoke(JavassistLazyInitializer.java:173) at org.jbpm.graph.def.Node_$$_javassist_169.enter(Node_$$_javassist_169.java) at org.jbpm.graph.def.Transition.take(Transition.java:151) at org.jbpm.graph.def.Node.leave(Node.java:394) at org.jbpm.graph.node.TaskNode.leave(TaskNode.java:209) at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39) at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25) at java.lang.reflect.Method.invoke(Method.java:597) at org.hibernate.proxy.pojo.javassist.JavassistLazyInitializer.invoke(JavassistLazyInitializer.java:173) at org.jbpm.graph.def.Node_$$_javassist_169.leave(Node_$$_javassist_169.java) at org.jbpm.graph.exe.Token.signal(Token.java:195) at org.jbpm.graph.exe.Token.signal(Token.java:158) at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39) at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25) at java.lang.reflect.Method.invoke(Method.java:597) at org.hibernate.proxy.pojo.javassist.JavassistLazyInitializer.invoke(JavassistLazyInitializer.java:173) at org.jbpm.graph.exe.Token_$$_javassist_105.signal(Token_$$_javassist_105.java) at org.jbpm.job.Timer.execute(Timer.java:93) at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39) at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25) at java.lang.reflect.Method.invoke(Method.java:597) at org.hibernate.proxy.pojo.javassist.JavassistLazyInitializer.invoke(JavassistLazyInitializer.java:173) at org.jbpm.job.Job_$$_javassist_173.execute(Job_$$_javassist_173.java) at org.jbpm.job.executor.JobExecutorThread.executeJob(JobExecutorThread.java:164) at org.jbpm.job.executor.JobExecutorThread.run(JobExecutorThread.java:64) Caused by: org.hibernate.TransactionException: could not register synchronization at org.hibernate.transaction.JTATransaction.registerSynchronization(JTATransaction.java:309) at org.jbpm.db.JobSession.deleteJobsForProcessInstance(JobSession.java:208) ... 45 more Caused by: java.lang.NullPointerException at org.hibernate.transaction.JTATransaction.registerSynchronization(JTATransaction.java:306) ... 46 more 2007-11-13 14:34:45,050 DEBUG [org.jbpm.JbpmContext] closing jbpmContext org.jbpm.JbpmContext@fe331c 2007-11-13 14:34:45,050 DEBUG [org.jbpm.svc.Services] closing service 'persistence': org.jbpm.persistence.db.DbPersistenceService@200022 2007-11-13 14:34:45,050 DEBUG [org.jbpm.persistence.db.DbPersistenceService] flushing hibernate session SessionImpl(PersistenceContext[entityKeys=[EntityKey[org.jbpm.taskmgmt.exe.TaskInstance#9], EntityKey[org.jbpm.graph.def.Action#3053], EntityKey[org.jbpm.graph.exe.Token#15], EntityKey[org.jbpm.graph.def.Event#1272], EntityKey[org.jbpm.graph.def.Action#3054], EntityKey[org.jbpm.graph.def.Event#1271], EntityKey[org.jbpm.graph.def.Event#1274], EntityKey[org.jbpm.taskmgmt.def.Task#1619], EntityKey[org.jbpm.graph.def.Event#1273], EntityKey[org.jbpm.graph.def.ProcessDefinition#567], EntityKey[org.jbpm.graph.def.Event#1275], EntityKey[org.jbpm.graph.node.TaskNode#7373], EntityKey[org.jbpm.graph.def.Node#7374], EntityKey[org.jbpm.graph.def.Transition#9566], EntityKey[org.jbpm.module.exe.ModuleInstance#30], EntityKey[org.jbpm.module.exe.ModuleInstance#29], EntityKey[org.jbpm.job.Job#9], EntityKey[org.jbpm.graph.exe.ProcessInstance#15]],collectionKeys=[CollectionKey[org.jbpm.taskmgmt.exe.TaskInstance.variableInstances#9], CollectionKey[org.jbpm.taskmgmt.def.Task.events#1619], CollectionKey[org.jbpm.graph.exe.Token.children#15], CollectionKey[org.jbpm.context.exe.ContextInstance.tokenVariableMaps#29], CollectionKey[org.jbpm.graph.def.Event.actions#1274], CollectionKey[org.jbpm.taskmgmt.exe.TaskInstance.comments#9], CollectionKey[org.jbpm.graph.def.Transition.events#9566], CollectionKey[org.jbpm.graph.def.Event.actions#1275], CollectionKey[org.jbpm.graph.def.ProcessDefinition.exceptionHandlers#567], CollectionKey[org.jbpm.graph.def.Event.actions#1272], CollectionKey[org.jbpm.graph.def.ProcessDefinition.nodes#567], CollectionKey[org.jbpm.graph.def.Event.actions#1273], CollectionKey[org.jbpm.graph.def.Node.leavingTransitions#7374], CollectionKey[org.jbpm.graph.def.Node.leavingTransitions#7373], CollectionKey[org.jbpm.graph.def.Event.actions#1271], CollectionKey[org.jbpm.graph.def.ProcessDefinition.events#567], CollectionKey[org.jbpm.taskmgmt.exe.TaskMgmtInstance.swimlaneInstances#30], CollectionKey[org.jbpm.graph.node.TaskNode.tasks#7373], CollectionKey[org.jbpm.graph.exe.Token.comments#15], CollectionKey[org.jbpm.graph.exe.ProcessInstance.instances#15], CollectionKey[org.jbpm.graph.def.ProcessDefinition.definitions#567], CollectionKey[org.jbpm.graph.exe.ProcessInstance.runtimeActions#15], CollectionKey[org.jbpm.graph.def.Node.events#7373], CollectionKey[org.jbpm.taskmgmt.def.Task.exceptionHandlers#1619], CollectionKey[org.jbpm.taskmgmt.exe.TaskInstance.pooledActors#9], CollectionKey[org.jbpm.graph.def.Node.exceptionHandlers#7374], CollectionKey[org.jbpm.graph.def.Node.events#7374], CollectionKey[org.jbpm.graph.def.Node.exceptionHandlers#7373], CollectionKey[org.jbpm.graph.def.Node.arrivingTransitions#7373], CollectionKey[org.jbpm.graph.def.Node.arrivingTransitions#7374], CollectionKey[org.jbpm.graph.def.ProcessDefinition.actions#567], CollectionKey[org.jbpm.taskmgmt.exe.TaskMgmtInstance.taskInstances#30], CollectionKey[org.jbpm.graph.def.Transition.exceptionHandlers#9566]]];ActionQueue[insertions=[] updates=[] deletions=[] collectionCreations=[] collectionRemovals=[] collectionUpdates=[]]) 2007-11-13 14:34:45,066 DEBUG [org.jbpm.persistence.db.DbPersistenceService] closing hibernate session 2007-11-13 14:34:45,066 DEBUG [org.jbpm.svc.Services] closing service 'tx': org.jbpm.tx.TxService@162d2df 2007-11-13 14:34:45,066 DEBUG [org.jbpm.svc.Services] closing service 'scheduler': org.jbpm.scheduler.db.DbSchedulerService@1023556
If anyone has any idea's how to solve or workaround this problem I would be very grateful. If you need any further info (e.g. configuration etc) please do not hesitate to ask.
BTW I've also tried using jBpm 3.2.2 which has the same issue.
Thanks in advance,
Pete