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