4 Replies Latest reply on Jul 15, 2009 3:54 PM by arpan sharma

    errors with the example websale workflow

    arpan sharma Newbie

      HI,

      I am working with JBpm-3.2.6.SP1. I want to know if the websale process should be visible automatically when I install jbpm and login to the jbpm-console ?

      I cannot see it though..I see it only after I import it and deploy it in eclipse ..

      After deploying, when i click evaluate on the Create New Websale order task, i get the following errors :

      Error completing task: An exception of type "org.jbpm.JbpmException" was thrown. The message is: ejb timer entity lookup problem
      Closing the database context failed: An exception of type org.hibernate.exception.DataException was thrown, with the message: could not insert: [org.jbpm.graph.log.ActionLog]

      Can anyone help me with this ?

        • 1. Re: errors with the example websale workflow
          Ronald van Kuijk Master

          Depends on what setup you use (e.g. which database)

          Regarding the second error (and in more general) you have to provide more data, *full* stacktraces etc

          • 2. Re: errors with the example websale workflow
            arpan sharma Newbie

            Hi,

            I am using MySQL.

            I am getting the following error when i click on Evaluate button for the Create new websale order task.

            Error completing task: An exception of type "org.jbpm.JbpmException" was thrown. The message is: ejb timer entity lookup problem
            Closing the database context failed: An exception of type org.hibernate.exception.DataException was thrown, with the message: could not insert: [org.jbpm.graph.log.ActionLog]

            The server log is as follows

            2009-07-15 14:25:30,075 DEBUG [org.jbpm.configuration.JbpmContextInfo] creating jbpm context with service factories '[message, tx, scheduler, authentication, persistence, logging]'
            2009-07-15 14:25:30,078 DEBUG [org.jbpm.JbpmContext] creating org.jbpm.JbpmContext@7d53d8
            2009-07-15 14:25:30,078 DEBUG [org.jbpm.persistence.jta.JtaDbPersistenceService] beginning null
            2009-07-15 14:25:30,079 DEBUG [org.jbpm.persistence.db.DbPersistenceService] using current hibernate session
            2009-07-15 14:25:30,079 DEBUG [org.hibernate.jdbc.JDBCContext] successfully registered Synchronization
            2009-07-15 14:25:30,079 DEBUG [org.hibernate.impl.SessionImpl] opened session at timestamp: 5110506824003584
            2009-07-15 14:25:30,079 DEBUG [org.hibernate.cache.NonstrictReadWriteCache] Cache lookup: org.jbpm.graph.def.ProcessDefinition#10
            2009-07-15 14:25:30,079 DEBUG [org.hibernate.cache.NonstrictReadWriteCache] Cache hit
            2009-07-15 14:25:30,080 DEBUG [org.hibernate.engine.StatefulPersistenceContext] initializing non-lazy collections
            2009-07-15 14:25:30,081 DEBUG [org.hibernate.event.def.AbstractFlushingEventListener] processing flush-time cascades
            2009-07-15 14:25:30,081 DEBUG [org.hibernate.event.def.AbstractFlushingEventListener] dirty checking collections
            2009-07-15 14:25:30,081 DEBUG [org.hibernate.engine.Collections] Collection found: [org.jbpm.graph.def.ProcessDefinition.events#10], was: [org.jbpm.graph.def.ProcessDefinition.events#10] (uninitialized)
            2009-07-15 14:25:30,081 DEBUG [org.hibernate.engine.Collections] Collection found: [org.jbpm.graph.def.ProcessDefinition.exceptionHandlers#10], was: [org.jbpm.graph.def.ProcessDefinition.exceptionHandlers#10] (uninitialized)
            2009-07-15 14:25:30,081 DEBUG [org.hibernate.engine.Collections] Collection found: [org.jbpm.graph.def.ProcessDefinition.nodes#10], was: [org.jbpm.graph.def.ProcessDefinition.nodes#10] (uninitialized)
            2009-07-15 14:25:30,082 DEBUG [org.hibernate.engine.Collections] Collection found: [org.jbpm.graph.def.ProcessDefinition.actions#10], was: [org.jbpm.graph.def.ProcessDefinition.actions#10] (uninitialized)
            2009-07-15 14:25:30,082 DEBUG [org.hibernate.engine.Collections] Collection found: [org.jbpm.graph.def.ProcessDefinition.definitions#10], was: [org.jbpm.graph.def.ProcessDefinition.definitions#10] (uninitialized)
            2009-07-15 14:25:30,082 DEBUG [org.hibernate.event.def.AbstractFlushingEventListener] Flushed: 0 insertions, 0 updates, 0 deletions to 1 objects
            2009-07-15 14:25:30,082 DEBUG [org.hibernate.event.def.AbstractFlushingEventListener] Flushed: 0 (re)creations, 0 updates, 0 removals to 5 collections
            2009-07-15 14:25:30,082 DEBUG [org.hibernate.pretty.Printer] listing entities:
            2009-07-15 14:25:30,082 DEBUG [org.hibernate.pretty.Printer] org.jbpm.graph.def.ProcessDefinition{id=10, nodes=, events=, description=null, name=websale, isTerminationImplicit=false, startState=org.jbpm.graph.def.Node#54, definitions=, actions=, version=2, exceptionHandlers=}
            2009-07-15 14:25:30,082 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
            2009-07-15 14:25:30,082 DEBUG [org.hibernate.jdbc.ConnectionManager] opening JDBC connection
            2009-07-15 14:25:30,083 DEBUG [org.hibernate.SQL]
            /* named HQL query GraphSession.findAllProcessInstancesForDefinition */ select
            processins0_.ID_ as ID1_20_,
            processins0_.VERSION_ as VERSION2_20_,
            processins0_.KEY_ as KEY3_20_,
            processins0_.START_ as START4_20_,
            processins0_.END_ as END5_20_,
            processins0_.ISSUSPENDED_ as ISSUSPEN6_20_,
            processins0_.PROCESSDEFINITION_ as PROCESSD7_20_,
            processins0_.ROOTTOKEN_ as ROOTTOKEN8_20_,
            processins0_.SUPERPROCESSTOKEN_ as SUPERPRO9_20_
            from
            JBPM_PROCESSINSTANCE processins0_
            where
            processins0_.PROCESSDEFINITION_=?
            order by
            processins0_.START_ desc
            2009-07-15 14:25:30,085 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to open ResultSet (open ResultSets: 0, globally: 0)
            2009-07-15 14:25:30,085 DEBUG [org.hibernate.loader.Loader] result row: EntityKey[org.jbpm.graph.exe.ProcessInstance#20]
            2009-07-15 14:25:30,087 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to close ResultSet (open ResultSets: 1, globally: 1)
            2009-07-15 14:25:30,087 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
            2009-07-15 14:25:30,087 DEBUG [org.hibernate.jdbc.ConnectionManager] aggressively releasing JDBC connection
            2009-07-15 14:25:30,087 DEBUG [org.hibernate.jdbc.ConnectionManager] releasing JDBC connection [ (open PreparedStatements: 0, globally: 0) (open ResultSets: 0, globally: 0)]
            2009-07-15 14:25:30,087 DEBUG [org.hibernate.engine.TwoPhaseLoad] resolving associations for [org.jbpm.graph.exe.ProcessInstance#20]
            2009-07-15 14:25:30,088 DEBUG [org.hibernate.engine.TwoPhaseLoad] done materializing entity [org.jbpm.graph.exe.ProcessInstance#20]
            2009-07-15 14:25:30,088 DEBUG [org.hibernate.engine.StatefulPersistenceContext] initializing non-lazy collections
            2009-07-15 14:25:30,169 DEBUG [org.jbpm.JbpmContext] closing jbpmContext org.jbpm.JbpmContext@7d53d8
            2009-07-15 14:25:30,170 DEBUG [org.jbpm.svc.Services] closing service 'persistence': org.jbpm.persistence.jta.JtaDbPersistenceService@99e8f8
            2009-07-15 14:25:30,170 DEBUG [org.jbpm.persistence.jta.JtaDbPersistenceService] committing org.jboss.tm.usertx.client.ServerVMClientUserTransaction@1ef0b44
            2009-07-15 14:25:30,170 DEBUG [org.hibernate.event.def.AbstractFlushingEventListener] processing flush-time cascades
            2009-07-15 14:25:30,170 DEBUG [org.hibernate.event.def.AbstractFlushingEventListener] dirty checking collections
            2009-07-15 14:25:30,171 DEBUG [org.hibernate.engine.Collections] Collection found: [org.jbpm.graph.def.ProcessDefinition.events#10], was: [org.jbpm.graph.def.ProcessDefinition.events#10] (uninitialized)
            2009-07-15 14:25:30,171 DEBUG [org.hibernate.engine.Collections] Collection found: [org.jbpm.graph.def.ProcessDefinition.exceptionHandlers#10], was: [org.jbpm.graph.def.ProcessDefinition.exceptionHandlers#10] (uninitialized)
            2009-07-15 14:25:30,171 DEBUG [org.hibernate.engine.Collections] Collection found: [org.jbpm.graph.def.ProcessDefinition.nodes#10], was: [org.jbpm.graph.def.ProcessDefinition.nodes#10] (uninitialized)
            2009-07-15 14:25:30,171 DEBUG [org.hibernate.engine.Collections] Collection found: [org.jbpm.graph.def.ProcessDefinition.actions#10], was: [org.jbpm.graph.def.ProcessDefinition.actions#10] (uninitialized)
            2009-07-15 14:25:30,171 DEBUG [org.hibernate.engine.Collections] Collection found: [org.jbpm.graph.def.ProcessDefinition.definitions#10], was: [org.jbpm.graph.def.ProcessDefinition.definitions#10] (uninitialized)
            2009-07-15 14:25:30,172 DEBUG [org.hibernate.engine.Collections] Collection found: [org.jbpm.graph.exe.ProcessInstance.runtimeActions#20], was: [org.jbpm.graph.exe.ProcessInstance.runtimeActions#20] (uninitialized)
            2009-07-15 14:25:30,172 DEBUG [org.hibernate.engine.Collections] Collection found: [org.jbpm.graph.exe.ProcessInstance.instances#20], was: [org.jbpm.graph.exe.ProcessInstance.instances#20] (uninitialized)
            2009-07-15 14:25:30,172 DEBUG [org.hibernate.event.def.AbstractFlushingEventListener] Flushed: 0 insertions, 0 updates, 0 deletions to 2 objects
            2009-07-15 14:25:30,172 DEBUG [org.hibernate.event.def.AbstractFlushingEventListener] Flushed: 0 (re)creations, 0 updates, 0 removals to 7 collections
            2009-07-15 14:25:30,172 DEBUG [org.hibernate.pretty.Printer] listing entities:
            2009-07-15 14:25:30,173 DEBUG [org.hibernate.pretty.Printer] org.jbpm.graph.exe.ProcessInstance{processDefinition=org.jbpm.graph.def.ProcessDefinition#10, id=20, superProcessToken=null, start=2009-07-15 14:16:23, isSuspended=false, runtimeActions=, rootToken=org.jbpm.graph.exe.Token#20, instances=, end=null, key=null, version=1}
            2009-07-15 14:25:30,173 DEBUG [org.hibernate.pretty.Printer] org.jbpm.graph.def.ProcessDefinition{id=10, nodes=, events=, description=null, name=websale, isTerminationImplicit=false, startState=org.jbpm.graph.def.Node#54, definitions=, actions=, version=2, exceptionHandlers=}
            2009-07-15 14:25:30,174 DEBUG [org.hibernate.jdbc.ConnectionManager] aggressively releasing JDBC connection
            2009-07-15 14:25:30,180 DEBUG [org.jbpm.svc.Services] closing service 'tx': org.jbpm.tx.TxService@1afcfd4
            2009-07-15 14:25:30,181 DEBUG [org.jbpm.svc.Services] closing service 'authentication': org.jbpm.security.authentication.DefaultAuthenticationService@175705e
            2009-07-15 14:25:33,383 DEBUG [org.jbpm.configuration.JbpmContextInfo] creating jbpm context with service factories '[message, tx, scheduler, authentication, persistence, logging]'
            2009-07-15 14:25:33,383 DEBUG [org.jbpm.JbpmContext] creating org.jbpm.JbpmContext@192d7d0
            2009-07-15 14:25:33,383 DEBUG [org.jbpm.persistence.jta.JtaDbPersistenceService] beginning null
            2009-07-15 14:25:33,384 DEBUG [org.jbpm.persistence.db.DbPersistenceService] using current hibernate session
            2009-07-15 14:25:33,384 DEBUG [org.hibernate.jdbc.JDBCContext] successfully registered Synchronization
            2009-07-15 14:25:33,384 DEBUG [org.hibernate.impl.SessionImpl] opened session at timestamp: 5110506837540864
            2009-07-15 14:25:33,384 DEBUG [org.hibernate.cache.NonstrictReadWriteCache] Cache lookup: org.jbpm.graph.def.ProcessDefinition#10
            2009-07-15 14:25:33,384 DEBUG [org.hibernate.cache.NonstrictReadWriteCache] Cache hit
            2009-07-15 14:25:33,385 DEBUG [org.hibernate.engine.StatefulPersistenceContext] initializing non-lazy collections
            2009-07-15 14:25:33,386 DEBUG [org.hibernate.event.def.AbstractSaveEventListener] executing identity-insert immediately
            2009-07-15 14:25:33,386 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
            2009-07-15 14:25:33,386 DEBUG [org.hibernate.jdbc.ConnectionManager] opening JDBC connection
            2009-07-15 14:25:33,387 DEBUG [org.hibernate.SQL]
            /* insert org.jbpm.graph.exe.Token
            */ insert
            into
            JBPM_TOKEN
            (VERSION_, NAME_, START_, END_, NODEENTER_, NEXTLOGINDEX_, ISABLETOREACTIVATEPARENT_, ISTERMINATIONIMPLICIT_, ISSUSPENDED_, LOCK_, NODE_, PROCESSINSTANCE_, PARENT_, SUBPROCESSINSTANCE_)
            values
            (?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?)
            2009-07-15 14:25:33,389 DEBUG [org.hibernate.id.IdentifierGeneratorFactory] Natively generated identity: 21
            2009-07-15 14:25:33,389 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
            2009-07-15 14:25:33,389 DEBUG [org.hibernate.jdbc.ConnectionManager] aggressively releasing JDBC connection
            2009-07-15 14:25:33,389 DEBUG [org.hibernate.jdbc.ConnectionManager] releasing JDBC connection [ (open PreparedStatements: 0, globally: 0) (open ResultSets: 0, globally: 0)]
            2009-07-15 14:25:33,390 DEBUG [org.hibernate.event.def.AbstractSaveEventListener] executing identity-insert immediately
            2009-07-15 14:25:33,390 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
            2009-07-15 14:25:33,390 DEBUG [org.hibernate.jdbc.ConnectionManager] opening JDBC connection
            2009-07-15 14:25:33,390 DEBUG [org.hibernate.SQL]
            /* insert org.jbpm.graph.exe.ProcessInstance
            */ insert
            into
            JBPM_PROCESSINSTANCE
            (VERSION_, KEY_, START_, END_, ISSUSPENDED_, PROCESSDEFINITION_, ROOTTOKEN_, SUPERPROCESSTOKEN_)
            values
            (?, ?, ?, ?, ?, ?, ?, ?)
            2009-07-15 14:25:33,392 DEBUG [org.hibernate.id.IdentifierGeneratorFactory] Natively generated identity: 21
            2009-07-15 14:25:33,392 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
            2009-07-15 14:25:33,392 DEBUG [org.hibernate.jdbc.ConnectionManager] aggressively releasing JDBC connection
            2009-07-15 14:25:33,392 DEBUG [org.hibernate.jdbc.ConnectionManager] releasing JDBC connection [ (open PreparedStatements: 0, globally: 0) (open ResultSets: 0, globally: 0)]
            2009-07-15 14:25:33,392 DEBUG [org.hibernate.cache.NonstrictReadWriteCache] Cache lookup: org.jbpm.graph.def.ProcessDefinition.definitions#10
            2009-07-15 14:25:33,392 DEBUG [org.hibernate.cache.NonstrictReadWriteCache] Cache hit
            2009-07-15 14:25:33,393 DEBUG [org.hibernate.cache.NonstrictReadWriteCache] Cache lookup: org.jbpm.module.def.ModuleDefinition#28
            2009-07-15 14:25:33,393 DEBUG [org.hibernate.cache.NonstrictReadWriteCache] Cache hit
            2009-07-15 14:25:33,393 DEBUG [org.hibernate.engine.StatefulPersistenceContext] initializing non-lazy collections
            2009-07-15 14:25:33,393 DEBUG [org.hibernate.cache.NonstrictReadWriteCache] Cache lookup: org.jbpm.module.def.ModuleDefinition#29
            2009-07-15 14:25:33,393 DEBUG [org.hibernate.cache.NonstrictReadWriteCache] Cache hit
            2009-07-15 14:25:33,393 DEBUG [org.hibernate.engine.StatefulPersistenceContext] initializing non-lazy collections
            2009-07-15 14:25:33,393 DEBUG [org.hibernate.cache.NonstrictReadWriteCache] Cache lookup: org.jbpm.module.def.ModuleDefinition#30
            2009-07-15 14:25:33,394 DEBUG [org.hibernate.cache.NonstrictReadWriteCache] Cache hit
            2009-07-15 14:25:33,394 DEBUG [org.hibernate.engine.StatefulPersistenceContext] initializing non-lazy collections
            2009-07-15 14:25:33,394 DEBUG [org.jbpm.graph.def.GraphElement] event 'process-start' on ProcessDefinition(websale) for Token(/)
            2009-07-15 14:25:33,395 DEBUG [org.hibernate.cache.NonstrictReadWriteCache] Cache lookup: org.jbpm.graph.def.ProcessDefinition.events#10
            2009-07-15 14:25:33,395 DEBUG [org.hibernate.cache.NonstrictReadWriteCache] Cache hit
            2009-07-15 14:25:33,395 DEBUG [org.hibernate.impl.SessionImpl] initializing proxy: [org.jbpm.graph.def.Node#54]
            2009-07-15 14:25:33,395 DEBUG [org.hibernate.cache.NonstrictReadWriteCache] Cache lookup: org.jbpm.graph.def.Node#54
            2009-07-15 14:25:33,395 DEBUG [org.hibernate.cache.NonstrictReadWriteCache] Cache hit
            2009-07-15 14:25:33,396 DEBUG [org.hibernate.engine.StatefulPersistenceContext] initializing non-lazy collections
            2009-07-15 14:25:33,397 DEBUG [org.hibernate.impl.SessionImpl] initializing proxy: [org.jbpm.taskmgmt.def.Task#26]
            2009-07-15 14:25:33,397 DEBUG [org.hibernate.cache.NonstrictReadWriteCache] Cache lookup: org.jbpm.taskmgmt.def.Task#26
            2009-07-15 14:25:33,397 DEBUG [org.hibernate.cache.NonstrictReadWriteCache] Cache hit
            2009-07-15 14:25:33,397 WARN [org.hibernate.engine.StatefulPersistenceContext.ProxyWarnLog] Narrowing proxy to class org.jbpm.graph.node.StartState - this operation breaks ==
            2009-07-15 14:25:33,398 DEBUG [org.hibernate.engine.StatefulPersistenceContext] initializing non-lazy collections
            2009-07-15 14:25:33,398 DEBUG [org.hibernate.event.def.AbstractSaveEventListener] executing identity-insert immediately
            2009-07-15 14:25:33,398 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
            2009-07-15 14:25:33,399 DEBUG [org.hibernate.jdbc.ConnectionManager] opening JDBC connection
            2009-07-15 14:25:33,399 DEBUG [org.hibernate.SQL]
            /* insert org.jbpm.taskmgmt.exe.TaskInstance
            */ insert
            into
            JBPM_TASKINSTANCE
            (VERSION_, NAME_, DESCRIPTION_, ACTORID_, CREATE_, START_, END_, DUEDATE_, PRIORITY_, ISCANCELLED_, ISSUSPENDED_, ISOPEN_, ISSIGNALLING_, ISBLOCKING_, TASK_, TOKEN_, PROCINST_, SWIMLANINSTANCE_, TASKMGMTINSTANCE_, CLASS_)
            values
            (?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, 'T')
            2009-07-15 14:25:33,405 DEBUG [org.hibernate.id.IdentifierGeneratorFactory] Natively generated identity: 27
            2009-07-15 14:25:33,405 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
            2009-07-15 14:25:33,405 DEBUG [org.hibernate.jdbc.ConnectionManager] aggressively releasing JDBC connection
            2009-07-15 14:25:33,406 DEBUG [org.hibernate.jdbc.ConnectionManager] releasing JDBC connection [ (open PreparedStatements: 0, globally: 0) (open ResultSets: 0, globally: 0)]
            2009-07-15 14:25:33,406 DEBUG [org.jbpm.graph.def.GraphElement] event 'task-create' on Task(Create new web sale order) for Token(/)
            2009-07-15 14:25:33,406 DEBUG [org.hibernate.cache.NonstrictReadWriteCache] Cache lookup: org.jbpm.taskmgmt.def.Task.events#26
            2009-07-15 14:25:33,407 DEBUG [org.hibernate.cache.NonstrictReadWriteCache] Cache hit
            2009-07-15 14:25:33,407 DEBUG [org.hibernate.impl.SessionImpl] initializing proxy: [org.jbpm.graph.node.StartState#54]
            2009-07-15 14:25:33,407 DEBUG [org.hibernate.cache.NonstrictReadWriteCache] Cache lookup: org.jbpm.graph.def.Node.events#54
            2009-07-15 14:25:33,407 DEBUG [org.hibernate.cache.NonstrictReadWriteCache] Cache hit
            2009-07-15 14:25:33,408 DEBUG [org.hibernate.impl.SessionImpl] initializing proxy: [org.jbpm.taskmgmt.def.Swimlane#17]
            2009-07-15 14:25:33,409 DEBUG [org.hibernate.loader.Loader] loading entity: [org.jbpm.taskmgmt.def.Swimlane#17]
            2009-07-15 14:25:33,409 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
            2009-07-15 14:25:33,409 DEBUG [org.hibernate.jdbc.ConnectionManager] opening JDBC connection
            2009-07-15 14:25:33,410 DEBUG [org.hibernate.SQL]
            /* load org.jbpm.taskmgmt.def.Swimlane */ select
            swimlane0_.ID_ as ID1_16_0_,
            swimlane0_.NAME_ as NAME2_16_0_,
            swimlane0_.ACTORIDEXPRESSION_ as ACTORIDE3_16_0_,
            swimlane0_.POOLEDACTORSEXPRESSION_ as POOLEDAC4_16_0_,
            swimlane0_.ASSIGNMENTDELEGATION_ as ASSIGNME5_16_0_,
            swimlane0_.TASKMGMTDEFINITION_ as TASKMGMT6_16_0_
            from
            JBPM_SWIMLANE swimlane0_
            where
            swimlane0_.ID_=?
            2009-07-15 14:25:33,411 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to open ResultSet (open ResultSets: 0, globally: 0)
            2009-07-15 14:25:33,411 DEBUG [org.hibernate.loader.Loader] result row: EntityKey[org.jbpm.taskmgmt.def.Swimlane#17]
            2009-07-15 14:25:33,412 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to close ResultSet (open ResultSets: 1, globally: 1)
            2009-07-15 14:25:33,412 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
            2009-07-15 14:25:33,412 DEBUG [org.hibernate.jdbc.ConnectionManager] aggressively releasing JDBC connection
            2009-07-15 14:25:33,412 DEBUG [org.hibernate.jdbc.ConnectionManager] releasing JDBC connection [ (open PreparedStatements: 0, globally: 0) (open ResultSets: 0, globally: 0)]
            2009-07-15 14:25:33,413 DEBUG [org.hibernate.engine.TwoPhaseLoad] resolving associations for [org.jbpm.taskmgmt.def.Swimlane#17]
            2009-07-15 14:25:33,413 DEBUG [org.hibernate.engine.TwoPhaseLoad] done materializing entity [org.jbpm.taskmgmt.def.Swimlane#17]
            2009-07-15 14:25:33,413 DEBUG [org.hibernate.engine.StatefulPersistenceContext] initializing non-lazy collections
            2009-07-15 14:25:33,413 DEBUG [org.hibernate.loader.Loader] done entity load
            2009-07-15 14:25:33,414 DEBUG [org.jbpm.taskmgmt.exe.TaskInstance] assigning task 'Create new web sale order' to 'user'
            2009-07-15 14:25:33,414 DEBUG [org.jbpm.graph.def.GraphElement] event 'task-assign' on Task(Create new web sale order) for Token(/)
            2009-07-15 14:25:33,414 DEBUG [org.jbpm.svc.Services] executing default save operations
            2009-07-15 14:25:33,414 DEBUG [org.jbpm.svc.save.HibernateSaveOperation] saving process instance
            2009-07-15 14:25:33,452 DEBUG [org.jbpm.svc.save.SaveLogsOperation] posting logs to logging service.
            2009-07-15 14:25:33,453 DEBUG [org.hibernate.event.def.AbstractSaveEventListener] executing identity-insert immediately
            2009-07-15 14:25:33,453 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
            2009-07-15 14:25:33,453 DEBUG [org.hibernate.jdbc.ConnectionManager] opening JDBC connection
            2009-07-15 14:25:33,453 DEBUG [org.hibernate.SQL]
            /* insert org.jbpm.graph.log.ProcessInstanceCreateLog
            */ insert
            into
            JBPM_LOG
            (INDEX_, DATE_, TOKEN_, PARENT_, CLASS_)
            values
            (?, ?, ?, ?, 'I')
            2009-07-15 14:25:33,455 DEBUG [org.hibernate.id.IdentifierGeneratorFactory] Natively generated identity: 472
            2009-07-15 14:25:33,455 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
            2009-07-15 14:25:33,456 DEBUG [org.hibernate.jdbc.ConnectionManager] aggressively releasing JDBC connection
            2009-07-15 14:25:33,456 DEBUG [org.hibernate.jdbc.ConnectionManager] releasing JDBC connection [ (open PreparedStatements: 0, globally: 0) (open ResultSets: 0, globally: 0)]
            2009-07-15 14:25:33,456 DEBUG [org.hibernate.event.def.AbstractSaveEventListener] executing identity-insert immediately
            2009-07-15 14:25:33,457 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
            2009-07-15 14:25:33,457 DEBUG [org.hibernate.jdbc.ConnectionManager] opening JDBC connection
            2009-07-15 14:25:33,458 DEBUG [org.hibernate.SQL]
            /* insert org.jbpm.taskmgmt.log.TaskCreateLog
            */ insert
            into
            JBPM_LOG
            (INDEX_, DATE_, TOKEN_, PARENT_, TASKINSTANCE_, TASKACTORID_, CLASS_)
            values
            (?, ?, ?, ?, ?, ?, '1')
            2009-07-15 14:25:33,461 DEBUG [org.hibernate.id.IdentifierGeneratorFactory] Natively generated identity: 473
            2009-07-15 14:25:33,464 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
            2009-07-15 14:25:33,465 DEBUG [org.hibernate.jdbc.ConnectionManager] aggressively releasing JDBC connection
            2009-07-15 14:25:33,469 DEBUG [org.hibernate.jdbc.ConnectionManager] releasing JDBC connection [ (open PreparedStatements: 0, globally: 0) (open ResultSets: 0, globally: 0)]
            2009-07-15 14:25:33,470 DEBUG [org.hibernate.event.def.AbstractSaveEventListener] executing identity-insert immediately
            2009-07-15 14:25:33,470 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
            2009-07-15 14:25:33,470 DEBUG [org.hibernate.jdbc.ConnectionManager] opening JDBC connection
            2009-07-15 14:25:33,471 DEBUG [org.hibernate.SQL]
            /* insert org.jbpm.taskmgmt.log.TaskAssignLog
            */ insert
            into
            JBPM_LOG
            (INDEX_, DATE_, TOKEN_, PARENT_, TASKINSTANCE_, TASKOLDACTORID_, TASKACTORID_, CLASS_)
            values
            (?, ?, ?, ?, ?, ?, ?, '2')
            2009-07-15 14:25:33,473 DEBUG [org.hibernate.id.IdentifierGeneratorFactory] Natively generated identity: 474
            2009-07-15 14:25:33,473 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
            2009-07-15 14:25:33,473 DEBUG [org.hibernate.jdbc.ConnectionManager] aggressively releasing JDBC connection
            2009-07-15 14:25:33,473 DEBUG [org.hibernate.jdbc.ConnectionManager] releasing JDBC connection [ (open PreparedStatements: 0, globally: 0) (open ResultSets: 0, globally: 0)]
            2009-07-15 14:25:33,474 DEBUG [org.jbpm.svc.save.CascadeSaveOperation] cascading save of 'ProcessInstance(21)'
            2009-07-15 14:25:33,474 DEBUG [org.jbpm.JbpmContext] closing jbpmContext org.jbpm.JbpmContext@192d7d0
            2009-07-15 14:25:33,474 DEBUG [org.jbpm.svc.Services] closing service 'persistence': org.jbpm.persistence.jta.JtaDbPersistenceService@f4104f
            2009-07-15 14:25:33,475 DEBUG [org.jbpm.persistence.jta.JtaDbPersistenceService] committing org.jboss.tm.usertx.client.ServerVMClientUserTransaction@1ef0b44
            2009-07-15 14:25:33,475 DEBUG [org.hibernate.event.def.AbstractFlushingEventListener] processing flush-time cascades
            2009-07-15 14:25:33,476 DEBUG [org.hibernate.event.def.AbstractSaveEventListener] executing identity-insert immediately
            2009-07-15 14:25:33,480 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
            2009-07-15 14:25:33,480 DEBUG [org.hibernate.jdbc.ConnectionManager] opening JDBC connection
            2009-07-15 14:25:33,480 DEBUG [org.hibernate.SQL]
            /* insert org.jbpm.context.exe.ContextInstance
            */ insert
            into
            JBPM_MODULEINSTANCE
            (VERSION_, PROCESSINSTANCE_, CLASS_)
            values
            (?, ?, 'C')
            2009-07-15 14:25:33,492 DEBUG [org.hibernate.id.IdentifierGeneratorFactory] Natively generated identity: 25
            2009-07-15 14:25:33,492 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
            2009-07-15 14:25:33,492 DEBUG [org.hibernate.jdbc.ConnectionManager] aggressively releasing JDBC connection
            2009-07-15 14:25:33,493 DEBUG [org.hibernate.jdbc.ConnectionManager] releasing JDBC connection [ (open PreparedStatements: 0, globally: 0) (open ResultSets: 0, globally: 0)]
            2009-07-15 14:25:33,493 DEBUG [org.hibernate.event.def.AbstractSaveEventListener] executing identity-insert immediately
            2009-07-15 14:25:33,493 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
            2009-07-15 14:25:33,494 DEBUG [org.hibernate.jdbc.ConnectionManager] opening JDBC connection
            2009-07-15 14:25:33,494 DEBUG [org.hibernate.SQL]
            /* insert org.jbpm.taskmgmt.exe.TaskMgmtInstance
            */ insert
            into
            JBPM_MODULEINSTANCE
            (VERSION_, PROCESSINSTANCE_, TASKMGMTDEFINITION_, CLASS_)
            values
            (?, ?, ?, 'T')
            2009-07-15 14:25:33,496 DEBUG [org.hibernate.id.IdentifierGeneratorFactory] Natively generated identity: 26
            2009-07-15 14:25:33,496 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
            2009-07-15 14:25:33,496 DEBUG [org.hibernate.jdbc.ConnectionManager] aggressively releasing JDBC connection
            2009-07-15 14:25:33,496 DEBUG [org.hibernate.jdbc.ConnectionManager] releasing JDBC connection [ (open PreparedStatements: 0, globally: 0) (open ResultSets: 0, globally: 0)]
            2009-07-15 14:25:33,497 DEBUG [org.hibernate.event.def.AbstractSaveEventListener] executing identity-insert immediately
            2009-07-15 14:25:33,498 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
            2009-07-15 14:25:33,498 DEBUG [org.hibernate.jdbc.ConnectionManager] opening JDBC connection
            2009-07-15 14:25:33,498 DEBUG [org.hibernate.SQL]
            /* insert org.jbpm.taskmgmt.exe.SwimlaneInstance
            */ insert
            into
            JBPM_SWIMLANEINSTANCE
            (VERSION_, NAME_, ACTORID_, SWIMLANE_, TASKMGMTINSTANCE_)
            values
            (?, ?, ?, ?, ?)
            2009-07-15 14:25:33,500 DEBUG [org.hibernate.id.IdentifierGeneratorFactory] Natively generated identity: 11
            2009-07-15 14:25:33,500 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
            2009-07-15 14:25:33,500 DEBUG [org.hibernate.jdbc.ConnectionManager] aggressively releasing JDBC connection
            2009-07-15 14:25:33,501 DEBUG [org.hibernate.jdbc.ConnectionManager] releasing JDBC connection [ (open PreparedStatements: 0, globally: 0) (open ResultSets: 0, globally: 0)]
            2009-07-15 14:25:33,502 DEBUG [org.hibernate.event.def.AbstractFlushingEventListener] dirty checking collections
            2009-07-15 14:25:33,502 DEBUG [org.hibernate.engine.Collections] Collection found: [org.jbpm.graph.def.ProcessDefinition.events#10], was: [org.jbpm.graph.def.ProcessDefinition.events#10] (initialized)
            2009-07-15 14:25:33,502 DEBUG [org.hibernate.engine.Collections] Collection found: [org.jbpm.graph.def.ProcessDefinition.exceptionHandlers#10], was: [org.jbpm.graph.def.ProcessDefinition.exceptionHandlers#10] (uninitialized)
            2009-07-15 14:25:33,503 DEBUG [org.hibernate.engine.Collections] Collection found: [org.jbpm.graph.def.ProcessDefinition.nodes#10], was: [org.jbpm.graph.def.ProcessDefinition.nodes#10] (uninitialized)
            2009-07-15 14:25:33,503 DEBUG [org.hibernate.engine.Collections] Collection found: [org.jbpm.graph.def.ProcessDefinition.actions#10], was: [org.jbpm.graph.def.ProcessDefinition.actions#10] (uninitialized)
            2009-07-15 14:25:33,504 DEBUG [org.hibernate.engine.Collections] Collection found: [org.jbpm.graph.def.ProcessDefinition.definitions#10], was: [org.jbpm.graph.def.ProcessDefinition.definitions#10] (initialized)
            2009-07-15 14:25:33,505 DEBUG [org.hibernate.engine.Collections] Collection found: [org.jbpm.graph.exe.ProcessInstance.instances#21], was: [] (initialized)
            2009-07-15 14:25:33,508 DEBUG [org.hibernate.engine.Collections] Collection found: [org.jbpm.file.def.FileDefinition.processFiles#29], was: [org.jbpm.file.def.FileDefinition.processFiles#29] (uninitialized)
            2009-07-15 14:25:33,509 DEBUG [org.hibernate.engine.Collections] Collection found: [org.jbpm.taskmgmt.def.TaskMgmtDefinition.swimlanes#30], was: [org.jbpm.taskmgmt.def.TaskMgmtDefinition.swimlanes#30] (uninitialized)
            2009-07-15 14:25:33,528 DEBUG [org.hibernate.engine.Collections] Collection found: [org.jbpm.taskmgmt.def.TaskMgmtDefinition.tasks#30], was: [org.jbpm.taskmgmt.def.TaskMgmtDefinition.tasks#30] (uninitialized)
            2009-07-15 14:25:33,529 DEBUG [org.hibernate.engine.Collections] Collection found: [org.jbpm.graph.def.Node.events#54], was: [org.jbpm.graph.def.Node.events#54] (initialized)
            2009-07-15 14:25:33,529 DEBUG [org.hibernate.engine.Collections] Collection found: [org.jbpm.graph.def.Node.exceptionHandlers#54], was: [org.jbpm.graph.def.Node.exceptionHandlers#54] (uninitialized)
            2009-07-15 14:25:33,529 DEBUG [org.hibernate.engine.Collections] Collection found: [org.jbpm.graph.def.Node.leavingTransitions#54], was: [org.jbpm.graph.def.Node.leavingTransitions#54] (uninitialized)
            2009-07-15 14:25:33,529 DEBUG [org.hibernate.engine.Collections] Collection found: [org.jbpm.graph.def.Node.arrivingTransitions#54], was: [org.jbpm.graph.def.Node.arrivingTransitions#54] (uninitialized)
            2009-07-15 14:25:33,530 DEBUG [org.hibernate.engine.Collections] Collection found: [org.jbpm.taskmgmt.def.Task.events#26], was: [org.jbpm.taskmgmt.def.Task.events#26] (initialized)
            2009-07-15 14:25:33,530 DEBUG [org.hibernate.engine.Collections] Collection found: [org.jbpm.taskmgmt.def.Task.exceptionHandlers#26], was: [org.jbpm.taskmgmt.def.Task.exceptionHandlers#26] (uninitialized)
            2009-07-15 14:25:33,531 DEBUG [org.hibernate.engine.Collections] Collection found: [org.jbpm.taskmgmt.def.Swimlane.tasks#17], was: [org.jbpm.taskmgmt.def.Swimlane.tasks#17] (uninitialized)
            2009-07-15 14:25:33,532 DEBUG [org.hibernate.engine.Collections] Collection found: [org.jbpm.taskmgmt.exe.TaskMgmtInstance.swimlaneInstances#26], was: [] (initialized)
            2009-07-15 14:25:33,532 DEBUG [org.hibernate.engine.Collections] Collection found: [org.jbpm.taskmgmt.exe.TaskMgmtInstance.taskInstances#26], was: [] (initialized)
            2009-07-15 14:25:33,532 DEBUG [org.hibernate.event.def.AbstractFlushingEventListener] Flushed: 0 insertions, 3 updates, 0 deletions to 16 objects
            2009-07-15 14:25:33,532 DEBUG [org.hibernate.event.def.AbstractFlushingEventListener] Flushed: 3 (re)creations, 0 updates, 0 removals to 18 collections
            2009-07-15 14:25:33,532 DEBUG [org.hibernate.pretty.Printer] listing entities:
            2009-07-15 14:25:33,533 DEBUG [org.hibernate.pretty.Printer] org.jbpm.taskmgmt.log.TaskCreateLog{id=473, index=1, token=org.jbpm.graph.exe.Token#21, taskActorId=null, parent=null, date=2009-07-15 14:25:33, taskInstance=org.jbpm.taskmgmt.exe.TaskInstance#27}
            2009-07-15 14:25:33,534 DEBUG [org.hibernate.pretty.Printer] org.jbpm.graph.log.ProcessInstanceCreateLog{id=472, index=0, token=org.jbpm.graph.exe.Token#21, parent=null, date=2009-07-15 14:25:33}
            2009-07-15 14:25:33,534 DEBUG [org.hibernate.pretty.Printer] org.jbpm.taskmgmt.def.Task{swimlane=org.jbpm.taskmgmt.def.Swimlane#17, taskController=null, condition=null, taskNode=null, events=[], pooledActorsExpression=null, startState=org.jbpm.graph.node.StartState#54, isBlocking=false, exceptionHandlers=, id=26, processDefinition=org.jbpm.graph.def.ProcessDefinition#10, actorIdExpression=null, isSignalling=true, taskMgmtDefinition=null, description=null, priority=3, name=Create new web sale order, dueDate=null, assignmentDelegation=null}
            2009-07-15 14:25:33,535 DEBUG [org.hibernate.pretty.Printer] org.jbpm.taskmgmt.log.TaskAssignLog{id=474, index=2, taskNewActorId=user, token=org.jbpm.graph.exe.Token#21, parent=null, taskOldActorId=null, date=2009-07-15 14:25:33, taskInstance=org.jbpm.taskmgmt.exe.TaskInstance#27}
            2009-07-15 14:25:33,535 DEBUG [org.hibernate.pretty.Printer] org.jbpm.taskmgmt.def.Swimlane{id=17, actorIdExpression=null, taskMgmtDefinition=org.jbpm.taskmgmt.def.TaskMgmtDefinition#30, pooledActorsExpression=null, name=buyer, tasks=, assignmentDelegation=null}
            2009-07-15 14:25:33,540 DEBUG [org.hibernate.pretty.Printer] org.jbpm.context.def.ContextDefinition{processDefinition=org.jbpm.graph.def.ProcessDefinition#10, id=28, name=org.jbpm.context.def.ContextDefinition}
            2009-07-15 14:25:33,540 DEBUG [org.hibernate.pretty.Printer] org.jbpm.file.def.FileDefinition{processFiles=, processDefinition=org.jbpm.graph.def.ProcessDefinition#10, id=29, name=org.jbpm.file.def.FileDefinition}
            2009-07-15 14:25:33,541 DEBUG [org.hibernate.pretty.Printer] org.jbpm.graph.node.StartState{superState=null, processDefinition=org.jbpm.graph.def.ProcessDefinition#10, id=54, isAsyncExclusive=false, events=[], description=null, arrivingTransitions=, name=Create new web sale order, action=null, isAsync=false, leavingTransitions=, exceptionHandlers=}
            2009-07-15 14:25:33,541 DEBUG [org.hibernate.pretty.Printer] org.jbpm.taskmgmt.def.TaskMgmtDefinition{swimlanes=, processDefinition=org.jbpm.graph.def.ProcessDefinition#10, id=30, name=org.jbpm.taskmgmt.def.TaskMgmtDefinition, tasks=, startTask=org.jbpm.taskmgmt.def.Task#26}
            2009-07-15 14:25:33,541 DEBUG [org.hibernate.pretty.Printer] org.jbpm.taskmgmt.exe.TaskMgmtInstance{id=26, taskMgmtDefinition=org.jbpm.taskmgmt.def.TaskMgmtDefinition#30, swimlaneInstances=[org.jbpm.taskmgmt.exe.SwimlaneInstance#11], taskInstances=[org.jbpm.taskmgmt.exe.TaskInstance#27], processInstance=org.jbpm.graph.exe.ProcessInstance#21, version=0}
            2009-07-15 14:25:33,541 DEBUG [org.hibernate.pretty.Printer] org.jbpm.context.exe.ContextInstance{id=25, processInstance=org.jbpm.graph.exe.ProcessInstance#21, tokenVariableMaps=null, version=0}
            2009-07-15 14:25:33,542 DEBUG [org.hibernate.pretty.Printer] org.jbpm.graph.exe.ProcessInstance{processDefinition=org.jbpm.graph.def.ProcessDefinition#10, id=21, superProcessToken=null, start=2009-07-15 14:25:33, isSuspended=false, runtimeActions=null, rootToken=org.jbpm.graph.exe.Token#21, instances=[org.jbpm.module.exe.ModuleInstance#25, org.jbpm.module.exe.ModuleInstance#26], end=null, key=null, version=1}
            2009-07-15 14:25:33,542 DEBUG [org.hibernate.pretty.Printer] org.jbpm.graph.exe.Token{isSuspended=false, isTerminationImplicit=false, lock=null, children=null, parent=null, processInstance=org.jbpm.graph.exe.ProcessInstance#21, nextLogIndex=3, version=0, id=21, node=org.jbpm.graph.def.Node#54, nodeEnter=null, subProcessInstance=null, start=2009-07-15 14:25:33, name=null, isAbleToReactivateParent=true, comments=null, end=null}
            2009-07-15 14:25:33,542 DEBUG [org.hibernate.pretty.Printer] org.jbpm.taskmgmt.exe.SwimlaneInstance{id=11, swimlane=org.jbpm.taskmgmt.def.Swimlane#17, actorId=user, name=buyer, taskMgmtInstance=org.jbpm.taskmgmt.exe.TaskMgmtInstance#26, pooledActors=null, version=0}
            2009-07-15 14:25:33,543 DEBUG [org.hibernate.pretty.Printer] org.jbpm.taskmgmt.exe.TaskInstance{task=org.jbpm.taskmgmt.def.Task#26, isCancelled=false, isSuspended=false, processInstance=org.jbpm.graph.exe.ProcessInstance#21, isBlocking=false, pooledActors=null, variableInstances=null, create=2009-07-15 14:25:33, version=0, isOpen=true, id=27, swimlaneInstance=org.jbpm.taskmgmt.exe.SwimlaneInstance#11, isSignalling=true, token=org.jbpm.graph.exe.Token#21, start=null, description=null, actorId=user, priority=3, name=Create new web sale order, taskMgmtInstance=org.jbpm.taskmgmt.exe.TaskMgmtInstance#26, dueDate=null, comments=null, end=null}
            2009-07-15 14:25:33,544 DEBUG [org.hibernate.pretty.Printer] org.jbpm.graph.def.ProcessDefinition{id=10, nodes=, events=[], description=null, name=websale, isTerminationImplicit=false, startState=org.jbpm.graph.def.Node#54, definitions=[org.jbpm.module.def.ModuleDefinition#28, org.jbpm.module.def.ModuleDefinition#29, org.jbpm.module.def.ModuleDefinition#30], actions=, version=2, exceptionHandlers=}
            2009-07-15 14:25:33,544 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
            2009-07-15 14:25:33,544 DEBUG [org.hibernate.jdbc.ConnectionManager] opening JDBC connection
            2009-07-15 14:25:33,544 DEBUG [org.hibernate.SQL]
            /* update
            org.jbpm.graph.exe.Token */ update
            JBPM_TOKEN
            set
            VERSION_=?,
            NAME_=?,
            START_=?,
            END_=?,
            NODEENTER_=?,
            NEXTLOGINDEX_=?,
            ISABLETOREACTIVATEPARENT_=?,
            ISTERMINATIONIMPLICIT_=?,
            ISSUSPENDED_=?,
            LOCK_=?,
            NODE_=?,
            PROCESSINSTANCE_=?,
            PARENT_=?,
            SUBPROCESSINSTANCE_=?
            where
            ID_=?
            and VERSION_=?
            2009-07-15 14:25:33,724 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
            2009-07-15 14:25:33,725 DEBUG [org.hibernate.jdbc.ConnectionManager] skipping aggressive-release due to flush cycle
            2009-07-15 14:25:33,725 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
            2009-07-15 14:25:33,725 DEBUG [org.hibernate.SQL]
            /* update
            org.jbpm.graph.exe.ProcessInstance */ update
            JBPM_PROCESSINSTANCE
            set
            VERSION_=?,
            KEY_=?,
            START_=?,
            END_=?,
            ISSUSPENDED_=?,
            PROCESSDEFINITION_=?,
            ROOTTOKEN_=?,
            SUPERPROCESSTOKEN_=?
            where
            ID_=?
            and VERSION_=?
            2009-07-15 14:25:33,727 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
            2009-07-15 14:25:33,727 DEBUG [org.hibernate.jdbc.ConnectionManager] skipping aggressive-release due to flush cycle
            2009-07-15 14:25:33,727 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
            2009-07-15 14:25:33,727 DEBUG [org.hibernate.SQL]
            /* update
            org.jbpm.taskmgmt.exe.TaskInstance */ update
            JBPM_TASKINSTANCE
            set
            VERSION_=?,
            NAME_=?,
            DESCRIPTION_=?,
            ACTORID_=?,
            CREATE_=?,
            START_=?,
            END_=?,
            DUEDATE_=?,
            PRIORITY_=?,
            ISCANCELLED_=?,
            ISSUSPENDED_=?,
            ISOPEN_=?,
            ISSIGNALLING_=?,
            ISBLOCKING_=?,
            TASK_=?,
            TOKEN_=?,
            PROCINST_=?,
            SWIMLANINSTANCE_=?,
            TASKMGMTINSTANCE_=?
            where
            ID_=?
            and VERSION_=?
            2009-07-15 14:25:33,730 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
            2009-07-15 14:25:33,730 DEBUG [org.hibernate.jdbc.ConnectionManager] skipping aggressive-release due to flush cycle
            2009-07-15 14:25:33,730 DEBUG [org.hibernate.persister.collection.AbstractCollectionPersister] Inserting collection: [org.jbpm.graph.exe.ProcessInstance.instances#21]
            2009-07-15 14:25:33,730 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
            2009-07-15 14:25:33,730 DEBUG [org.hibernate.SQL]
            /* create one-to-many row org.jbpm.graph.exe.ProcessInstance.instances */ update
            JBPM_MODULEINSTANCE
            set
            PROCESSINSTANCE_=?,
            NAME_=?
            where
            ID_=?
            2009-07-15 14:25:33,731 DEBUG [org.hibernate.jdbc.AbstractBatcher] reusing prepared statement
            2009-07-15 14:25:33,731 DEBUG [org.hibernate.SQL]
            /* create one-to-many row org.jbpm.graph.exe.ProcessInstance.instances */ update
            JBPM_MODULEINSTANCE
            set
            PROCESSINSTANCE_=?,
            NAME_=?
            where
            ID_=?
            2009-07-15 14:25:33,731 DEBUG [org.hibernate.persister.collection.AbstractCollectionPersister] done inserting collection: 2 rows inserted
            2009-07-15 14:25:33,731 DEBUG [org.hibernate.jdbc.AbstractBatcher] Executing batch size: 2
            2009-07-15 14:25:33,733 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
            2009-07-15 14:25:33,733 DEBUG [org.hibernate.jdbc.ConnectionManager] skipping aggressive-release due to flush cycle
            2009-07-15 14:25:33,733 DEBUG [org.hibernate.jdbc.ConnectionManager] aggressively releasing JDBC connection
            2009-07-15 14:25:33,733 DEBUG [org.hibernate.jdbc.ConnectionManager] releasing JDBC connection [ (open PreparedStatements: 0, globally: 0) (open ResultSets: 0, globally: 0)]
            2009-07-15 14:25:33,749 DEBUG [org.jbpm.svc.Services] closing service 'tx': org.jbpm.tx.TxService@f2818d
            2009-07-15 14:25:33,749 DEBUG [org.jbpm.svc.Services] closing service 'logging': org.jbpm.logging.db.DbLoggingService@1177565
            2009-07-15 14:25:33,749 DEBUG [org.jbpm.svc.Services] closing service 'authentication': org.jbpm.security.authentication.DefaultAuthenticationService@11c4ef6
            2009-07-15 14:25:33,777 DEBUG [org.jbpm.configuration.JbpmContextInfo] creating jbpm context with service factories '[message, tx, scheduler, authentication, persistence, logging]'
            2009-07-15 14:25:33,777 DEBUG [org.jbpm.JbpmContext] creating org.jbpm.JbpmContext@1841ae5
            2009-07-15 14:25:33,777 DEBUG [org.jbpm.persistence.jta.JtaDbPersistenceService] beginning null
            2009-07-15 14:25:33,778 DEBUG [org.jbpm.persistence.db.DbPersistenceService] using current hibernate session
            2009-07-15 14:25:33,778 DEBUG [org.hibernate.jdbc.JDBCContext] successfully registered Synchronization
            2009-07-15 14:25:33,778 DEBUG [org.hibernate.impl.SessionImpl] opened session at timestamp: 5110506839154688
            2009-07-15 14:25:33,778 DEBUG [org.hibernate.loader.Loader] loading entity: [org.jbpm.graph.exe.ProcessInstance#21]
            2009-07-15 14:25:33,778 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
            2009-07-15 14:25:33,778 DEBUG [org.hibernate.jdbc.ConnectionManager] opening JDBC connection
            2009-07-15 14:25:33,779 DEBUG [org.hibernate.SQL]
            /* load org.jbpm.graph.exe.ProcessInstance */ 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_=?
            2009-07-15 14:25:33,781 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to open ResultSet (open ResultSets: 0, globally: 0)
            2009-07-15 14:25:33,781 DEBUG [org.hibernate.loader.Loader] result row: EntityKey[org.jbpm.graph.exe.ProcessInstance#21]
            2009-07-15 14:25:33,782 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to close ResultSet (open ResultSets: 1, globally: 1)
            2009-07-15 14:25:33,782 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
            2009-07-15 14:25:33,782 DEBUG [org.hibernate.jdbc.ConnectionManager] aggressively releasing JDBC connection
            2009-07-15 14:25:33,782 DEBUG [org.hibernate.jdbc.ConnectionManager] releasing JDBC connection [ (open PreparedStatements: 0, globally: 0) (open ResultSets: 0, globally: 0)]
            2009-07-15 14:25:33,783 DEBUG [org.hibernate.engine.TwoPhaseLoad] resolving associations for [org.jbpm.graph.exe.ProcessInstance#21]
            2009-07-15 14:25:33,784 DEBUG [org.hibernate.engine.TwoPhaseLoad] done materializing entity [org.jbpm.graph.exe.ProcessInstance#21]
            2009-07-15 14:25:33,784 DEBUG [org.hibernate.engine.StatefulPersistenceContext] initializing non-lazy collections
            2009-07-15 14:25:33,784 DEBUG [org.hibernate.loader.Loader] done entity load
            2009-07-15 14:25:33,785 DEBUG [org.hibernate.impl.SessionImpl] initializing proxy: [org.jbpm.graph.exe.Token#21]
            2009-07-15 14:25:33,785 DEBUG [org.hibernate.loader.Loader] loading entity: [org.jbpm.graph.exe.Token#21]
            2009-07-15 14:25:33,785 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
            2009-07-15 14:25:33,785 DEBUG [org.hibernate.jdbc.ConnectionManager] opening JDBC connection
            2009-07-15 14:25:33,785 DEBUG [org.hibernate.SQL]
            /* load org.jbpm.graph.exe.Token */ select
            token0_.ID_ as ID1_21_0_,
            token0_.VERSION_ as VERSION2_21_0_,
            token0_.NAME_ as NAME3_21_0_,
            token0_.START_ as START4_21_0_,
            token0_.END_ as END5_21_0_,
            token0_.NODEENTER_ as NODEENTER6_21_0_,
            token0_.NEXTLOGINDEX_ as NEXTLOGI7_21_0_,
            token0_.ISABLETOREACTIVATEPARENT_ as ISABLETO8_21_0_,
            token0_.ISTERMINATIONIMPLICIT_ as ISTERMIN9_21_0_,
            token0_.ISSUSPENDED_ as ISSUSPE10_21_0_,
            token0_.LOCK_ as LOCK11_21_0_,
            token0_.NODE_ as NODE12_21_0_,
            token0_.PROCESSINSTANCE_ as PROCESS13_21_0_,
            token0_.PARENT_ as PARENT14_21_0_,
            token0_.SUBPROCESSINSTANCE_ as SUBPROC15_21_0_
            from
            JBPM_TOKEN token0_
            where
            token0_.ID_=?
            2009-07-15 14:25:33,974 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to open ResultSet (open ResultSets: 0, globally: 0)
            2009-07-15 14:25:33,974 DEBUG [org.hibernate.loader.Loader] result row: EntityKey[org.jbpm.graph.exe.Token#21]
            2009-07-15 14:25:33,975 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to close ResultSet (open ResultSets: 1, globally: 1)
            2009-07-15 14:25:33,975 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
            2009-07-15 14:25:33,975 DEBUG [org.hibernate.jdbc.ConnectionManager] aggressively releasing JDBC connection
            2009-07-15 14:25:33,976 DEBUG [org.hibernate.jdbc.ConnectionManager] releasing JDBC connection [ (open PreparedStatements: 0, globally: 0) (open ResultSets: 0, globally: 0)]
            2009-07-15 14:25:33,976 DEBUG [org.hibernate.engine.TwoPhaseLoad] resolving associations for [org.jbpm.graph.exe.Token#21]
            2009-07-15 14:25:33,976 DEBUG [org.hibernate.engine.TwoPhaseLoad] done materializing entity [org.jbpm.graph.exe.Token#21]
            2009-07-15 14:25:33,976 DEBUG [org.hibernate.engine.StatefulPersistenceContext] initializing non-lazy collections
            2009-07-15 14:25:33,977 DEBUG [org.hibernate.loader.Loader] done entity load
            2009-07-15 14:25:33,977 DEBUG [org.hibernate.loader.Loader] loading collection: [org.jbpm.graph.exe.Token.comments#21]
            2009-07-15 14:25:33,977 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
            2009-07-15 14:25:33,977 DEBUG [org.hibernate.jdbc.ConnectionManager] opening JDBC connection
            2009-07-15 14:25:33,977 DEBUG [org.hibernate.SQL]
            /* load one-to-many org.jbpm.graph.exe.Token.comments */ select
            comments0_.TOKEN_ as TOKEN6_1_,
            comments0_.ID_ as ID1_1_,
            comments0_.TOKENINDEX_ as TOKENINDEX8_1_,
            comments0_.ID_ as ID1_19_0_,
            comments0_.VERSION_ as VERSION2_19_0_,
            comments0_.ACTORID_ as ACTORID3_19_0_,
            comments0_.TIME_ as TIME4_19_0_,
            comments0_.MESSAGE_ as MESSAGE5_19_0_,
            comments0_.TOKEN_ as TOKEN6_19_0_,
            comments0_.TASKINSTANCE_ as TASKINST7_19_0_
            from
            JBPM_COMMENT comments0_
            where
            comments0_.TOKEN_=?
            2009-07-15 14:25:33,979 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to open ResultSet (open ResultSets: 0, globally: 0)
            2009-07-15 14:25:33,979 DEBUG [org.hibernate.loader.Loader] result set contains (possibly empty) collection: [org.jbpm.graph.exe.Token.comments#21]
            2009-07-15 14:25:33,979 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to close ResultSet (open ResultSets: 1, globally: 1)
            2009-07-15 14:25:33,979 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
            2009-07-15 14:25:33,979 DEBUG [org.hibernate.jdbc.ConnectionManager] aggressively releasing JDBC connection
            2009-07-15 14:25:33,980 DEBUG [org.hibernate.jdbc.ConnectionManager] releasing JDBC connection [ (open PreparedStatements: 0, globally: 0) (open ResultSets: 0, globally: 0)]
            2009-07-15 14:25:33,980 DEBUG [org.hibernate.engine.loading.CollectionLoadContext] 1 collections were found in result set for role: org.jbpm.graph.exe.Token.comments
            2009-07-15 14:25:33,980 DEBUG [org.hibernate.engine.loading.CollectionLoadContext] collection fully initialized: [org.jbpm.graph.exe.Token.comments#21]
            2009-07-15 14:25:33,980 DEBUG [org.hibernate.engine.loading.CollectionLoadContext] 1 collections initialized for role: org.jbpm.graph.exe.Token.comments
            2009-07-15 14:25:33,980 DEBUG [org.hibernate.engine.StatefulPersistenceContext] initializing non-lazy collections
            2009-07-15 14:25:33,980 DEBUG [org.hibernate.loader.Loader] done loading collection
            2009-07-15 14:25:33,980 DEBUG [org.hibernate.loader.Loader] loading collection: [org.jbpm.graph.exe.Token.children#21]
            2009-07-15 14:25:33,981 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
            2009-07-15 14:25:33,981 DEBUG [org.hibernate.jdbc.ConnectionManager] opening JDBC connection
            2009-07-15 14:25:33,981 DEBUG [org.hibernate.SQL]
            /* load one-to-many org.jbpm.graph.exe.Token.children */ select
            children0_.PARENT_ as PARENT14_1_,
            children0_.ID_ as ID1_1_,
            children0_.NAME_ as NAME3_1_,
            children0_.ID_ as ID1_21_0_,
            children0_.VERSION_ as VERSION2_21_0_,
            children0_.NAME_ as NAME3_21_0_,
            children0_.START_ as START4_21_0_,
            children0_.END_ as END5_21_0_,
            children0_.NODEENTER_ as NODEENTER6_21_0_,
            children0_.NEXTLOGINDEX_ as NEXTLOGI7_21_0_,
            children0_.ISABLETOREACTIVATEPARENT_ as ISABLETO8_21_0_,
            children0_.ISTERMINATIONIMPLICIT_ as ISTERMIN9_21_0_,
            children0_.ISSUSPENDED_ as ISSUSPE10_21_0_,
            children0_.LOCK_ as LOCK11_21_0_,
            children0_.NODE_ as NODE12_21_0_,
            children0_.PROCESSINSTANCE_ as PROCESS13_21_0_,
            children0_.PARENT_ as PARENT14_21_0_,
            children0_.SUBPROCESSINSTANCE_ as SUBPROC15_21_0_
            from
            JBPM_TOKEN children0_
            where
            children0_.PARENT_=?
            2009-07-15 14:25:34,144 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to open ResultSet (open ResultSets: 0, globally: 0)
            2009-07-15 14:25:34,144 DEBUG [org.hibernate.loader.Loader] result set contains (possibly empty) collection: [org.jbpm.graph.exe.Token.children#21]
            2009-07-15 14:25:34,144 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to close ResultSet (open ResultSets: 1, globally: 1)
            2009-07-15 14:25:34,145 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
            2009-07-15 14:25:34,145 DEBUG [org.hibernate.jdbc.ConnectionManager] aggressively releasing JDBC connection
            2009-07-15 14:25:34,145 DEBUG [org.hibernate.jdbc.ConnectionManager] releasing JDBC connection [ (open PreparedStatements: 0, globally: 0) (open ResultSets: 0, globally: 0)]
            2009-07-15 14:25:34,145 DEBUG [org.hibernate.engine.loading.CollectionLoadContext] 1 collections were found in result set for role: org.jbpm.graph.exe.Token.children
            2009-07-15 14:25:34,145 DEBUG [org.hibernate.engine.loading.CollectionLoadContext] collection fully initialized: [org.jbpm.graph.exe.Token.children#21]
            2009-07-15 14:25:34,145 DEBUG [org.hibernate.engine.loading.CollectionLoadContext] 1 collections initialized for role: org.jbpm.graph.exe.Token.children
            2009-07-15 14:25:34,145 DEBUG [org.hibernate.engine.StatefulPersistenceContext] initializing non-lazy collections
            2009-07-15 14:25:34,145 DEBUG [org.hibernate.loader.Loader] done loading collection
            2009-07-15 14:25:34,146 DEBUG [org.hibernate.loader.Loader] loading collection: [org.jbpm.graph.exe.ProcessInstance.instances#21]
            2009-07-15 14:25:34,146 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
            2009-07-15 14:25:34,146 DEBUG [org.hibernate.jdbc.ConnectionManager] opening JDBC connection
            2009-07-15 14:25:34,146 DEBUG [org.hibernate.SQL]
            /* load one-to-many org.jbpm.graph.exe.ProcessInstance.instances */ select
            instances0_.PROCESSINSTANCE_ as PROCESSI4_1_,
            instances0_.ID_ as ID1_1_,
            instances0_.NAME_ as NAME6_1_,
            instances0_.ID_ as ID1_23_0_,
            instances0_.VERSION_ as VERSION3_23_0_,
            instances0_.PROCESSINSTANCE_ as PROCESSI4_23_0_,
            instances0_.TASKMGMTDEFINITION_ as TASKMGMT5_23_0_,
            instances0_.CLASS_ as CLASS2_23_0_
            from
            JBPM_MODULEINSTANCE instances0_
            where
            instances0_.PROCESSINSTANCE_=?
            2009-07-15 14:25:34,148 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to open ResultSet (open ResultSets: 0, globally: 0)
            2009-07-15 14:25:34,148 DEBUG [org.hibernate.loader.Loader] result set contains (possibly empty) collection: [org.jbpm.graph.exe.ProcessInstance.instances#21]
            2009-07-15 14:25:34,148 DEBUG [org.hibernate.loader.Loader] result row: EntityKey[org.jbpm.module.exe.ModuleInstance#25]
            2009-07-15 14:25:34,148 DEBUG [org.hibernate.loader.Loader] found row of collection: [org.jbpm.graph.exe.ProcessInstance.instances#21]
            2009-07-15 14:25:34,149 DEBUG [org.hibernate.loader.Loader] result row: EntityKey[org.jbpm.module.exe.ModuleInstance#26]
            2009-07-15 14:25:34,149 DEBUG [org.hibernate.loader.Loader] found row of collection: [org.jbpm.graph.exe.ProcessInstance.instances#21]
            2009-07-15 14:25:34,149 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to close ResultSet (open ResultSets: 1, globally: 1)
            2009-07-15 14:25:34,149 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
            2009-07-15 14:25:34,149 DEBUG [org.hibernate.jdbc.ConnectionManager] aggressively releasing JDBC connection
            2009-07-15 14:25:34,150 DEBUG [org.hibernate.jdbc.ConnectionManager] releasing JDBC connection [ (open PreparedStatements: 0, globally: 0) (open ResultSets: 0, globally: 0)]
            2009-07-15 14:25:34,150 DEBUG [org.hibernate.engine.TwoPhaseLoad] resolving associations for [org.jbpm.context.exe.ContextInstance#25]
            2009-07-15 14:25:34,150 DEBUG [org.hibernate.engine.TwoPhaseLoad] done materializing entity [org.jbpm.context.exe.ContextInstance#25]
            2009-07-15 14:25:34,150 DEBUG [org.hibernate.engine.TwoPhaseLoad] resolving associations for [org.jbpm.taskmgmt.exe.TaskMgmtInstance#26]
            2009-07-15 14:25:34,150 DEBUG [org.hibernate.engine.TwoPhaseLoad] done materializing entity [org.jbpm.taskmgmt.exe.TaskMgmtInstance#26]
            2009-07-15 14:25:34,151 DEBUG [org.hibernate.engine.loading.CollectionLoadContext] 1 collections were found in result set for role: org.jbpm.graph.exe.ProcessInstance.instances
            2009-07-15 14:25:34,151 DEBUG [org.hibernate.engine.loading.CollectionLoadContext] collection fully initialized: [org.jbpm.graph.exe.ProcessInstance.instances#21]
            2009-07-15 14:25:34,151 DEBUG [org.hibernate.engine.loading.CollectionLoadContext] 1 collections initialized for role: org.jbpm.graph.exe.ProcessInstance.instances
            2009-07-15 14:25:34,151 DEBUG [org.hibernate.engine.StatefulPersistenceContext] initializing non-lazy collections
            2009-07-15 14:25:34,151 DEBUG [org.hibernate.loader.Loader] done loading collection
            2009-07-15 14:25:34,151 DEBUG [org.hibernate.loader.Loader] loading collection: [org.jbpm.taskmgmt.exe.TaskMgmtInstance.taskInstances#26]
            2009-07-15 14:25:34,206 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
            2009-07-15 14:25:34,206 DEBUG [org.hibernate.jdbc.ConnectionManager] opening JDBC connection
            2009-07-15 14:25:34,207 DEBUG [org.hibernate.SQL]
            /* load one-to-many org.jbpm.taskmgmt.exe.TaskMgmtInstance.taskInstances */ select
            taskinstan0_.TASKMGMTINSTANCE_ as TASKMGM21_1_,
            taskinstan0_.ID_ as ID1_1_,
            taskinstan0_.ID_ as ID1_27_0_,
            taskinstan0_.VERSION_ as VERSION3_27_0_,
            taskinstan0_.NAME_ as NAME4_27_0_,
            taskinstan0_.DESCRIPTION_ as DESCRIPT5_27_0_,
            taskinstan0_.ACTORID_ as ACTORID6_27_0_,
            taskinstan0_.CREATE_ as CREATE7_27_0_,
            taskinstan0_.START_ as START8_27_0_,
            taskinstan0_.END_ as END9_27_0_,
            taskinstan0_.DUEDATE_ as DUEDATE10_27_0_,
            taskinstan0_.PRIORITY_ as PRIORITY11_27_0_,
            taskinstan0_.ISCANCELLED_ as ISCANCE12_27_0_,
            taskinstan0_.ISSUSPENDED_ as ISSUSPE13_27_0_,
            taskinstan0_.ISOPEN_ as ISOPEN14_27_0_,
            taskinstan0_.ISSIGNALLING_ as ISSIGNA15_27_0_,
            taskinstan0_.ISBLOCKING_ as ISBLOCKING16_27_0_,
            taskinstan0_.TASK_ as TASK17_27_0_,
            taskinstan0_.TOKEN_ as TOKEN18_27_0_,
            taskinstan0_.PROCINST_ as PROCINST19_27_0_,
            taskinstan0_.SWIMLANINSTANCE_ as SWIMLAN20_27_0_,
            taskinstan0_.TASKMGMTINSTANCE_ as TASKMGM21_27_0_
            from
            JBPM_TASKINSTANCE taskinstan0_
            where
            taskinstan0_.TASKMGMTINSTANCE_=?
            2009-07-15 14:25:34,210 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to open ResultSet (open ResultSets: 0, globally: 0)
            2009-07-15 14:25:34,210 DEBUG [org.hibernate.loader.Loader] result set contains (possibly empty) collection: [org.jbpm.taskmgmt.exe.TaskMgmtInstance.taskInstances#26]
            2009-07-15 14:25:34,211 DEBUG [org.hibernate.loader.Loader] result row: EntityKey[org.jbpm.taskmgmt.exe.TaskInstance#27]
            2009-07-15 14:25:34,213 DEBUG [org.hibernate.loader.Loader] found row of collection: [org.jbpm.taskmgmt.exe.TaskMgmtInstance.taskInstances#26]
            2009-07-15 14:25:34,213 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to close ResultSet (open ResultSets: 1, globally: 1)
            2009-07-15 14:25:34,213 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
            2009-07-15 14:25:34,213 DEBUG [org.hibernate.jdbc.ConnectionManager] aggressively releasing JDBC connection
            2009-07-15 14:25:34,213 DEBUG [org.hibernate.jdbc.ConnectionManager] releasing JDBC connection [ (open PreparedStatements: 0, globally: 0) (open ResultSets: 0, globally: 0)]
            2009-07-15 14:25:34,214 DEBUG [org.hibernate.engine.TwoPhaseLoad] resolving associations for [org.jbpm.taskmgmt.exe.TaskInstance#27]
            2009-07-15 14:25:34,214 DEBUG [org.hibernate.engine.TwoPhaseLoad] done materializing entity [org.jbpm.taskmgmt.exe.TaskInstance#27]
            2009-07-15 14:25:34,215 DEBUG [org.hibernate.engine.loading.CollectionLoadContext] 1 collections were found in result set for role: org.jbpm.taskmgmt.exe.TaskMgmtInstance.taskInstances
            2009-07-15 14:25:34,215 DEBUG [org.hibernate.engine.loading.CollectionLoadContext] collection fully initialized: [org.jbpm.taskmgmt.exe.TaskMgmtInstance.taskInstances#26]
            2009-07-15 14:25:34,215 DEBUG [org.hibernate.engine.loading.CollectionLoadContext] 1 collections initialized for role: org.jbpm.taskmgmt.exe.TaskMgmtInstance.taskInstances
            2009-07-15 14:25:34,215 DEBUG [org.hibernate.engine.StatefulPersistenceContext] initializing non-lazy collections
            2009-07-15 14:25:34,215 DEBUG [org.hibernate.loader.Loader] done loading collection
            2009-07-15 14:25:34,238 DEBUG [org.hibernate.loader.Loader] loading collection: [org.jbpm.taskmgmt.exe.TaskInstance.pooledActors#27]
            2009-07-15 14:25:34,238 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
            2009-07-15 14:25:34,238 DEBUG [org.hibernate.jdbc.ConnectionManager] opening JDBC connection
            2009-07-15 14:25:34,239 DEBUG [org.hibernate.SQL]
            /* load collection org.jbpm.taskmgmt.exe.TaskInstance.pooledActors */ select
            pooledacto0_.TASKINSTANCE_ as TASKINST1_1_,
            pooledacto0_.POOLEDACTOR_ as POOLEDAC2_1_,
            pooledacto1_.ID_ as ID1_29_0_,
            pooledacto1_.VERSION_ as VERSION2_29_0_,
            pooledacto1_.ACTORID_ as ACTORID3_29_0_,
            pooledacto1_.SWIMLANEINSTANCE_ as SWIMLANE4_29_0_
            from
            JBPM_TASKACTORPOOL pooledacto0_
            left outer join
            JBPM_POOLEDACTOR pooledacto1_
            on pooledacto0_.POOLEDACTOR_=pooledacto1_.ID_
            where
            pooledacto0_.TASKINSTANCE_=?
            2009-07-15 14:25:34,241 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to open ResultSet (open ResultSets: 0, globally: 0)
            2009-07-15 14:25:34,366 DEBUG [org.hibernate.loader.Loader] result set contains (possibly empty) collection: [org.jbpm.taskmgmt.exe.TaskInstance.pooledActors#27]
            2009-07-15 14:25:34,366 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to close ResultSet (open ResultSets: 1, globally: 1)
            2009-07-15 14:25:34,366 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
            2009-07-15 14:25:34,366 DEBUG [org.hibernate.jdbc.ConnectionManager] aggressively releasing JDBC connection
            2009-07-15 14:25:34,366 DEBUG [org.hibernate.jdbc.ConnectionManager] releasing JDBC connection [ (open PreparedStatements: 0, globally: 0) (open ResultSets: 0, globally: 0)]
            2009-07-15 14:25:34,366 DEBUG [org.hibernate.engine.loading.CollectionLoadContext] 1 collections were found in result set for role: org.jbpm.taskmgmt.exe.TaskInstance.pooledActors
            2009-07-15 14:25:34,366 DEBUG [org.hibernate.engine.loading.CollectionLoadContext] collection fully initialized: [org.jbpm.taskmgmt.exe.TaskInstance.pooledActors#27]
            2009-07-15 14:25:34,366 DEBUG [org.hibernate.engine.loading.CollectionLoadContext] 1 collections initialized for role: org.jbpm.taskmgmt.exe.TaskInstance.pooledActors
            2009-07-15 14:25:34,366 DEBUG [org.hibernate.engine.StatefulPersistenceContext] initializing non-lazy collections
            2009-07-15 14:25:34,366 DEBUG [org.hibernate.loader.Loader] done loading collection
            2009-07-15 14:25:34,366 DEBUG [org.hibernate.impl.SessionImpl] initializing proxy: [org.jbpm.taskmgmt.exe.SwimlaneInstance#11]
            2009-07-15 14:25:34,367 DEBUG [org.hibernate.loader.Loader] loading entity: [org.jbpm.taskmgmt.exe.SwimlaneInstance#11]
            2009-07-15 14:25:34,367 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
            2009-07-15 14:25:34,367 DEBUG [org.hibernate.jdbc.ConnectionManager] opening JDBC connection
            2009-07-15 14:25:34,367 DEBUG [org.hibernate.SQL]
            /* load org.jbpm.taskmgmt.exe.SwimlaneInstance */ select
            swimlanein0_.ID_ as ID1_30_0_,
            swimlanein0_.VERSION_ as VERSION2_30_0_,
            swimlanein0_.NAME_ as NAME3_30_0_,
            swimlanein0_.ACTORID_ as ACTORID4_30_0_,
            swimlanein0_.SWIMLANE_ as SWIMLANE5_30_0_,
            swimlanein0_.TASKMGMTINSTANCE_ as TASKMGMT6_30_0_
            from
            JBPM_SWIMLANEINSTANCE swimlanein0_
            where
            swimlanein0_.ID_=?
            2009-07-15 14:25:34,368 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to open ResultSet (open ResultSets: 0, globally: 0)
            2009-07-15 14:25:34,369 DEBUG [org.hibernate.loader.Loader] result row: EntityKey[org.jbpm.taskmgmt.exe.SwimlaneInstance#11]
            2009-07-15 14:25:34,369 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to close ResultSet (open ResultSets: 1, globally: 1)
            2009-07-15 14:25:34,369 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
            2009-07-15 14:25:34,369 DEBUG [org.hibernate.jdbc.ConnectionManager] aggressively releasing JDBC connection
            2009-07-15 14:25:34,369 DEBUG [org.hibernate.jdbc.ConnectionManager] releasing JDBC connection [ (open PreparedStatements: 0, globally: 0) (open ResultSets: 0, globally: 0)]
            2009-07-15 14:25:34,370

            • 3. Re: errors with the example websale workflow
              Ronald van Kuijk Master

              Arpan,

              Where is the error in the stacktrace? I only see DEBUG, no errors.

              • 4. Re: errors with the example websale workflow
                arpan sharma Newbie

                HI,

                I am wondering as well, the log does not show any errors, still i get an error message...Can you tell me what could be possibly wrong ?