10 Replies Latest reply on Jan 30, 2007 9:18 AM by colsona

Timer Problem

colsona Jan 29, 2007 12:53 PM

I deployed the attached process definition an ran it usin the attached JobQueueBean. The process executes to the wait state and appears to create the timer. I found that the timer never fired. In step tracing the timer creation I found the following methid in the Jboss source:

public void createTimer(Timer timer) {
// this wont work cause the process instance is not yet saved
schedulerSession.saveTimer(timer);
}

I also found the timer service wasn't deployed by default. I changed our app startup bean to create the timer service and confirmed it was running. It was unable to find any timers in the database which is needed for proper timer operation. We checked the DB tables ourselves and found that it was empty. We need to know if this is a defect which we need to get resolved immediately or if we have configured wrong and need to reconfigure.

The process definition:

<?xml version="1.0" encoding="UTF-8"?>
<process-definition
 xmlns="urn:jbpm.org:jpdl-3.1" name="FileEvent">
 <start-state name="start">
 <transition name="" to="Is file complete"></transition>
 </start-state>
 <decision name="Is file complete">
 <handler class="com.spss.batch.queue.handlers.CheckFileComplete"/>
 <transition name="true" to="Start job process"/>
 <transition name="false" to="false"></transition>
 </decision>
 <state name="false">
 <timer duedate="10 seconds" name="Wait For File" repeat="false" transition="Is file complete">
 <action class="com.spss.batch.queue.actions.FileEventTimerAction"/>
 </timer>
 <transition name="File isn't complete" to="Is file complete"></transition>
 </state>
 <node name="Start job process">
 <event type="node-enter">
 <action class="com.spss.batch.queue.actions.StartJobProcess"></action>
 </event>
 <transition name="end" to="end1"></transition>
 </node>
 <end-state name="end1">
 <event type="node-enter">
 <action name="doTask"></action>
 </event>
 </end-state>
</process-definition>

The calling bean:

package com.spss.batch.queue;

import java.io.File;

import javax.ejb.EJB;
import javax.ejb.Stateless;

import org.apache.log4j.Logger;
import org.jbpm.JbpmConfiguration;
import org.jbpm.JbpmContext;
import org.jbpm.db.GraphSession;
import org.jbpm.graph.def.ProcessDefinition;
import org.jbpm.graph.exe.ProcessInstance;
import org.jbpm.graph.exe.Token;

@Stateless(name="BatchJobQueue", description="Job Queue Session Bean",mappedName="BatchJobQueue")
public class BatchJobQueueBean implements BatchJobQueue{
 Logger log = Logger.getLogger(BatchJobQueue.class);

 @EJB
 ProcessController controller;

 JbpmContext context = null;
 GraphSession graphSession = null;

 public void addJob(File watchFile, File fileID){
 //JobTask task = JobTaskFactory.createJobTask(watchFile);
 //JobQueue.getInstance().addJob(task);
 try{
 createBusinessProcess(watchFile, fileID);
// controller.createBusinessProcessDefinition();
// controller.createProcessInstance();
// controller.signalProcess();
 }catch(Exception ex){
 log.error("Unable to start process!",ex);
 throw new RuntimeException("Error starting job prcoess instance!",ex);
 }
 }
 private void initContext(){
 log.info("Getting jBPM context..");
 context = JbpmConfiguration.getInstance().createJbpmContext();
 log.info("Getting Graph Session..");
 graphSession = context.getGraphSession();
 }
 public long createBusinessProcess(File watch, File fileID) throws Exception {
 initContext();
 //JbpmContext context = ManagedJbpmContext.instance();
 log.info("Looking up process definition...");
 //ProcessDefinition processDefinition = graphSession.findLatestProcessDefinition("HelloWorld");
 ProcessDefinition processDefinition = null;
 if(processDefinition==null){
 log.info("Creating process definition...");
 String helloWorldName = "PROCESS_DEFINITIONS/FileEvent/processdefinition.xml";
 processDefinition = ProcessDefinition.parseXmlResource(helloWorldName);
 log.info("Saving process definition...");
 //context.deployProcessDefinition(processDefinition);
 graphSession.saveProcessDefinition(processDefinition);
 }
 log.info("Creating process instance...");
 ProcessInstance processInstance = processDefinition.createProcessInstance();
 long processID = processInstance.getId();
 JobTask task = JobTaskFactory.createJobTask(watch,fileID);
 processInstance.getContextInstance().createVariable(JobTask.JOB_TASK, task);
 log.info("Saving process instance..");
 context.save(processInstance);
 log.info("Closing context..");
 context.close();
 log.info("Process created!");
 return processID;
 }
 public void signalBusinessProcess(long processID){
 initContext();
 log.info("Looking up process instance...");
 ProcessInstance processInstance = context.loadProcessInstance(processID);
 log.info("Getting root token");
 Token token = processInstance.getRootToken();
 log.info("Signaling root token..");
 token.signal();
 //log.info("Ending root token..");
 //token.end();
 }

}

Action listener:

package com.spss.batch.queue.actions;

import org.jbpm.graph.def.ActionHandler;
import org.jbpm.graph.exe.ExecutionContext;

public class FileEventTimerAction implements ActionHandler {

 public void execute(ExecutionContext executionContext) throws Exception {
 executionContext.getNode().leave(executionContext);
 }

}

package com.spss.batch.queue.handlers;

import org.jbpm.graph.exe.ExecutionContext;
import org.jbpm.graph.node.DecisionHandler;

import com.spss.batch.queue.JobTask;

public class CheckFileComplete implements DecisionHandler {

 public String decide(ExecutionContext executionContext) throws Exception {
 JobTask task = (JobTask)executionContext.getProcessInstance().getContextInstance().getVariable(JobTask.JOB_TASK);
 System.out.println("CheckFileComplete: Processing task: "+task);
 if(task.isReady()){
 return Boolean.TRUE.toString();
 }else{
 return Boolean.FALSE.toString();
 }
 }

}

1. Re: Timer Problem

kukeltje Jan 29, 2007 1:18 PM (in response to colsona)

in your example the process is never signalled to get out of the start-state. The method signalBusinessProcess is never called.
Actions
2. Re: Timer Problem

colsona Jan 29, 2007 1:24 PM (in response to colsona)

Yes my test client which I didn't include does call this method. I have step traced the source and found that the timer is created and theoretically saved to the database. The timer record never actually shows up in the Db tables. There is no exception thrown on the DB save.

Asa
Actions

3. Re: Timer Problem

colsona Jan 29, 2007 1:29 PM (in response to colsona)

Here is the test client method for clarity.

 public void runTest() throws Exception {
 InitialContext ctx = new InitialContext();
 ctx.addToEnvironment(Context.INITIAL_CONTEXT_FACTORY,"org.jnp.interfaces.NamingContextFactory");
 ctx.addToEnvironment(Context.PROVIDER_URL,serverUrl);
 Object obj = ctx.lookup("ABOMv2/BatchJobQueue/remote");
 BatchJobQueue queue = (BatchJobQueue)obj;
 long processID = queue.createBusinessProcess(new File("C:\\FileTest\\testfile"), new File("C:\\FileTest\\test"));
 queue.signalBusinessProcess(processID);
 }

4. Re: Timer Problem

colsona Jan 29, 2007 1:32 PM (in response to colsona)

Here is a log snippet as well:

2007-01-27 14:16:00,433 INFO [com.spss.batch.queue.BatchJobQueue] Getting jBPM context..
2007-01-27 14:16:00,433 DEBUG [org.jbpm.configuration.JbpmContextInfo] creating jbpm context with service factories '[message, scheduler, logging, persistence, authentication]'
2007-01-27 14:16:00,433 DEBUG [org.jbpm.JbpmContext] creating JbpmContext
2007-01-27 14:16:00,433 INFO [com.spss.batch.queue.BatchJobQueue] Getting Graph Session..
2007-01-27 14:16:00,433 DEBUG [org.jbpm.persistence.db.DbPersistenceServiceFactory] creating persistence service
2007-01-27 14:16:00,433 DEBUG [org.jbpm.persistence.db.DbPersistenceService] creating hibernate session
2007-01-27 14:16:00,448 DEBUG [org.hibernate.impl.SessionImpl] opened session at timestamp: 4792014276395008
2007-01-27 14:16:00,448 DEBUG [org.jbpm.persistence.db.DbPersistenceService] beginning hibernate transaction
2007-01-27 14:16:00,448 DEBUG [org.hibernate.transaction.JTATransaction] Looking for UserTransaction under: UserTransaction
2007-01-27 14:16:00,448 DEBUG [org.hibernate.transaction.JTATransaction] Obtained UserTransaction
2007-01-27 14:16:00,448 DEBUG [org.hibernate.transaction.JTATransaction] begin
2007-01-27 14:16:00,448 DEBUG [org.hibernate.jdbc.JDBCContext] successfully registered Synchronization
2007-01-27 14:16:00,448 INFO [com.spss.batch.queue.BatchJobQueue] Looking up process definition...
2007-01-27 14:16:00,448 INFO [com.spss.batch.queue.BatchJobQueue] Creating process definition...
2007-01-27 14:16:00,448 DEBUG [org.jbpm.jpdl.xml.JpdlParser] resolving schema reference publicId(null) systemId(http://jbpm.org/jpdl-3.1.xsd)
2007-01-27 14:16:00,448 DEBUG [org.jbpm.jpdl.xml.JpdlParser] providing input source to local 'jpdl-3.1.xsd' resource
2007-01-27 14:16:00,495 WARN [org.jbpm.jpdl.xml.JpdlXmlReader] process xml warning: action does not have class nor ref-name attribute <action xmlns="urn:jbpm.org:jpdl-3.1" name="doTask" config-type="field" accept-propagated-events="true"/>
2007-01-27 14:16:00,495 INFO [com.spss.batch.queue.BatchJobQueue] Saving process definition...
2007-01-27 14:16:00,495 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
2007-01-27 14:16:00,495 DEBUG [org.hibernate.jdbc.ConnectionManager] opening JDBC connection
2007-01-27 14:16:00,495 DEBUG [org.hibernate.SQL] select abom_own.hibernate_sequence.nextval from dual
2007-01-27 14:16:00,495 INFO [STDOUT] Hibernate: select abom_own.hibernate_sequence.nextval from dual
2007-01-27 14:16:00,526 DEBUG [org.hibernate.id.SequenceGenerator] Sequence identifier generated: 75
2007-01-27 14:16:00,542 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
2007-01-27 14:16:00,542 DEBUG [org.hibernate.jdbc.ConnectionManager] aggressively releasing JDBC connection
2007-01-27 14:16:00,542 DEBUG [org.hibernate.jdbc.ConnectionManager] releasing JDBC connection [ (open PreparedStatements: 0, globally: 0) (open ResultSets: 0, globally: 0)]
2007-01-27 14:16:00,542 DEBUG [org.hibernate.event.def.AbstractSaveEventListener] generated identifier: 75, using strategy: org.hibernate.id.SequenceGenerator
2007-01-27 14:16:00,542 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
2007-01-27 14:16:00,542 DEBUG [org.hibernate.jdbc.ConnectionManager] opening JDBC connection
2007-01-27 14:16:00,542 DEBUG [org.hibernate.SQL] select abom_own.hibernate_sequence.nextval from dual
2007-01-27 14:16:00,542 INFO [STDOUT] Hibernate: select abom_own.hibernate_sequence.nextval from dual
2007-01-27 14:16:00,558 DEBUG [org.hibernate.id.SequenceGenerator] Sequence identifier generated: 76
2007-01-27 14:16:00,573 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
2007-01-27 14:16:00,573 DEBUG [org.hibernate.jdbc.ConnectionManager] aggressively releasing JDBC connection
2007-01-27 14:16:00,573 DEBUG [org.hibernate.jdbc.ConnectionManager] releasing JDBC connection [ (open PreparedStatements: 0, globally: 0) (open ResultSets: 0, globally: 0)]
2007-01-27 14:16:00,573 DEBUG [org.hibernate.event.def.AbstractSaveEventListener] generated identifier: 76, using strategy: org.hibernate.id.SequenceGenerator
2007-01-27 14:16:00,573 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
2007-01-27 14:16:00,573 DEBUG [org.hibernate.jdbc.ConnectionManager] opening JDBC connection
2007-01-27 14:16:00,573 DEBUG [org.hibernate.SQL] select abom_own.hibernate_sequence.nextval from dual
2007-01-27 14:16:00,573 INFO [STDOUT] Hibernate: select abom_own.hibernate_sequence.nextval from dual
2007-01-27 14:16:00,604 DEBUG [org.hibernate.id.SequenceGenerator] Sequence identifier generated: 77
2007-01-27 14:16:00,620 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
2007-01-27 14:16:00,620 DEBUG [org.hibernate.jdbc.ConnectionManager] aggressively releasing JDBC connection
2007-01-27 14:16:00,620 DEBUG [org.hibernate.jdbc.ConnectionManager] releasing JDBC connection [ (open PreparedStatements: 0, globally: 0) (open ResultSets: 0, globally: 0)]
2007-01-27 14:16:00,620 DEBUG [org.hibernate.event.def.AbstractSaveEventListener] generated identifier: 77, using strategy: org.hibernate.id.SequenceGenerator
2007-01-27 14:16:00,620 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
2007-01-27 14:16:00,620 DEBUG [org.hibernate.jdbc.ConnectionManager] opening JDBC connection
2007-01-27 14:16:00,620 DEBUG [org.hibernate.SQL] select abom_own.hibernate_sequence.nextval from dual
2007-01-27 14:16:00,620 INFO [STDOUT] Hibernate: select abom_own.hibernate_sequence.nextval from dual
2007-01-27 14:16:00,636 DEBUG [org.hibernate.id.SequenceGenerator] Sequence identifier generated: 78
2007-01-27 14:16:00,667 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
2007-01-27 14:16:00,667 DEBUG [org.hibernate.jdbc.ConnectionManager] aggressively releasing JDBC connection
2007-01-27 14:16:00,667 DEBUG [org.hibernate.jdbc.ConnectionManager] releasing JDBC connection [ (open PreparedStatements: 0, globally: 0) (open ResultSets: 0, globally: 0)]
2007-01-27 14:16:00,667 DEBUG [org.hibernate.event.def.AbstractSaveEventListener] generated identifier: 78, using strategy: org.hibernate.id.SequenceGenerator
2007-01-27 14:16:00,667 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
2007-01-27 14:16:00,667 DEBUG [org.hibernate.jdbc.ConnectionManager] opening JDBC connection
2007-01-27 14:16:00,667 DEBUG [org.hibernate.SQL] select abom_own.hibernate_sequence.nextval from dual
2007-01-27 14:16:00,667 INFO [STDOUT] Hibernate: select abom_own.hibernate_sequence.nextval from dual
2007-01-27 14:16:00,683 DEBUG [org.hibernate.id.SequenceGenerator] Sequence identifier generated: 79
2007-01-27 14:16:00,698 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
2007-01-27 14:16:00,698 DEBUG [org.hibernate.jdbc.ConnectionManager] aggressively releasing JDBC connection
2007-01-27 14:16:00,698 DEBUG [org.hibernate.jdbc.ConnectionManager] releasing JDBC connection [ (open PreparedStatements: 0, globally: 0) (open ResultSets: 0, globally: 0)]
2007-01-27 14:16:00,698 DEBUG [org.hibernate.event.def.AbstractSaveEventListener] generated identifier: 79, using strategy: org.hibernate.id.SequenceGenerator
2007-01-27 14:16:00,698 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
2007-01-27 14:16:00,698 DEBUG [org.hibernate.jdbc.ConnectionManager] opening JDBC connection
2007-01-27 14:16:00,698 DEBUG [org.hibernate.SQL] select abom_own.hibernate_sequence.nextval from dual
2007-01-27 14:16:00,698 INFO [STDOUT] Hibernate: select abom_own.hibernate_sequence.nextval from dual
2007-01-27 14:16:00,714 DEBUG [org.hibernate.id.SequenceGenerator] Sequence identifier generated: 80
2007-01-27 14:16:00,745 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
2007-01-27 14:16:00,745 DEBUG [org.hibernate.jdbc.ConnectionManager] aggressively releasing JDBC connection
2007-01-27 14:16:00,745 DEBUG [org.hibernate.jdbc.ConnectionManager] releasing JDBC connection [ (open PreparedStatements: 0, globally: 0) (open ResultSets: 0, globally: 0)]
2007-01-27 14:16:00,745 DEBUG [org.hibernate.event.def.AbstractSaveEventListener] generated identifier: 80, using strategy: org.hibernate.id.SequenceGenerator
2007-01-27 14:16:00,745 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
2007-01-27 14:16:00,745 DEBUG [org.hibernate.jdbc.ConnectionManager] opening JDBC connection
2007-01-27 14:16:00,745 DEBUG [org.hibernate.SQL] select abom_own.hibernate_sequence.nextval from dual
2007-01-27 14:16:00,745 INFO [STDOUT] Hibernate: select abom_own.hibernate_sequence.nextval from dual
2007-01-27 14:16:00,776 DEBUG [org.hibernate.id.SequenceGenerator] Sequence identifier generated: 81
2007-01-27 14:16:00,792 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
2007-01-27 14:16:00,792 DEBUG [org.hibernate.jdbc.ConnectionManager] aggressively releasing JDBC connection
2007-01-27 14:16:00,792 DEBUG [org.hibernate.jdbc.ConnectionManager] releasing JDBC connection [ (open PreparedStatements: 0, globally: 0) (open ResultSets: 0, globally: 0)]
2007-01-27 14:16:00,792 DEBUG [org.hibernate.event.def.AbstractSaveEventListener] generated identifier: 81, using strategy: org.hibernate.id.SequenceGenerator
2007-01-27 14:16:00,808 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
2007-01-27 14:16:00,808 DEBUG [org.hibernate.jdbc.ConnectionManager] opening JDBC connection
2007-01-27 14:16:00,808 DEBUG [org.hibernate.SQL] select abom_own.hibernate_sequence.nextval from dual
2007-01-27 14:16:00,808 INFO [STDOUT] Hibernate: select abom_own.hibernate_sequence.nextval from dual
2007-01-27 14:16:00,823 DEBUG [org.hibernate.id.SequenceGenerator] Sequence identifier generated: 82
2007-01-27 14:16:00,839 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
2007-01-27 14:16:00,839 DEBUG [org.hibernate.jdbc.ConnectionManager] aggressively releasing JDBC connection
2007-01-27 14:16:00,839 DEBUG [org.hibernate.jdbc.ConnectionManager] releasing JDBC connection [ (open PreparedStatements: 0, globally: 0) (open ResultSets: 0, globally: 0)]
2007-01-27 14:16:00,839 DEBUG [org.hibernate.event.def.AbstractSaveEventListener] generated identifier: 82, using strategy: org.hibernate.id.SequenceGenerator
2007-01-27 14:16:00,839 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
2007-01-27 14:16:00,839 DEBUG [org.hibernate.jdbc.ConnectionManager] opening JDBC connection
2007-01-27 14:16:00,839 DEBUG [org.hibernate.SQL] select abom_own.hibernate_sequence.nextval from dual
2007-01-27 14:16:00,839 INFO [STDOUT] Hibernate: select abom_own.hibernate_sequence.nextval from dual
2007-01-27 14:16:00,854 DEBUG [org.hibernate.id.SequenceGenerator] Sequence identifier generated: 83
2007-01-27 14:16:00,886 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
2007-01-27 14:16:00,886 DEBUG [org.hibernate.jdbc.ConnectionManager] aggressively releasing JDBC connection
2007-01-27 14:16:00,886 DEBUG [org.hibernate.jdbc.ConnectionManager] releasing JDBC connection [ (open PreparedStatements: 0, globally: 0) (open ResultSets: 0, globally: 0)]
2007-01-27 14:16:00,886 DEBUG [org.hibernate.event.def.AbstractSaveEventListener] generated identifier: 83, using strategy: org.hibernate.id.SequenceGenerator
2007-01-27 14:16:00,886 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
2007-01-27 14:16:00,886 DEBUG [org.hibernate.jdbc.ConnectionManager] opening JDBC connection
2007-01-27 14:16:00,886 DEBUG [org.hibernate.SQL] select abom_own.hibernate_sequence.nextval from dual
2007-01-27 14:16:00,886 INFO [STDOUT] Hibernate: select abom_own.hibernate_sequence.nextval from dual
2007-01-27 14:16:00,901 DEBUG [org.hibernate.id.SequenceGenerator] Sequence identifier generated: 84
2007-01-27 14:16:00,917 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
2007-01-27 14:16:00,917 DEBUG [org.hibernate.jdbc.ConnectionManager] aggressively releasing JDBC connection
2007-01-27 14:16:00,917 DEBUG [org.hibernate.jdbc.ConnectionManager] releasing JDBC connection [ (open PreparedStatements: 0, globally: 0) (open ResultSets: 0, globally: 0)]
2007-01-27 14:16:00,917 DEBUG [org.hibernate.event.def.AbstractSaveEventListener] generated identifier: 84, using strategy: org.hibernate.id.SequenceGenerator
2007-01-27 14:16:00,917 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
2007-01-27 14:16:00,917 DEBUG [org.hibernate.jdbc.ConnectionManager] opening JDBC connection
2007-01-27 14:16:00,917 DEBUG [org.hibernate.SQL] select abom_own.hibernate_sequence.nextval from dual
2007-01-27 14:16:00,917 INFO [STDOUT] Hibernate: select abom_own.hibernate_sequence.nextval from dual
2007-01-27 14:16:00,948 DEBUG [org.jbpm.configuration.JbpmContextInfo] creating jbpm context with service factories '[message, scheduler, logging, persistence, authentication]'
2007-01-27 14:16:00,948 DEBUG [org.jbpm.JbpmContext] creating JbpmContext
2007-01-27 14:16:00,948 DEBUG [org.jbpm.persistence.db.DbPersistenceServiceFactory] creating persistence service
2007-01-27 14:16:00,948 DEBUG [org.jbpm.persistence.db.DbPersistenceService] creating hibernate session
2007-01-27 14:16:00,948 DEBUG [org.hibernate.impl.SessionImpl] opened session at timestamp: 4792014278443008
2007-01-27 14:16:00,948 DEBUG [org.jbpm.persistence.db.DbPersistenceService] beginning hibernate transaction
2007-01-27 14:16:00,948 DEBUG [org.hibernate.transaction.JTATransaction] Looking for UserTransaction under: UserTransaction
2007-01-27 14:16:00,948 DEBUG [org.hibernate.transaction.JTATransaction] Obtained UserTransaction
2007-01-27 14:16:00,948 DEBUG [org.hibernate.transaction.JTATransaction] begin
2007-01-27 14:16:00,948 DEBUG [org.hibernate.transaction.JTATransaction] Began a new JTA transaction
2007-01-27 14:16:00,948 DEBUG [org.hibernate.jdbc.JDBCContext] successfully registered Synchronization
2007-01-27 14:16:00,948 DEBUG [org.jbpm.scheduler.impl.SchedulerThread] checking for timers
2007-01-27 14:16:00,948 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to open PreparedStatement (open PreparedStatements: 0, globally: 1)
2007-01-27 14:16:00,948 DEBUG [org.hibernate.jdbc.ConnectionManager] opening JDBC connection
2007-01-27 14:16:00,948 DEBUG [org.hibernate.SQL] select timer0_.ID_ as col_0_0_ from abom_own.JBPM_TIMER timer0_ where (timer0_.EXCEPTION_ is null) and timer0_.ISSUSPENDED_<>1 order by timer0_.DUEDATE_ asc
2007-01-27 14:16:00,948 INFO [STDOUT] Hibernate: select timer0_.ID_ as col_0_0_ from abom_own.JBPM_TIMER timer0_ where (timer0_.EXCEPTION_ is null) and timer0_.ISSUSPENDED_<>1 order by timer0_.DUEDATE_ asc
2007-01-27 14:16:00,948 DEBUG [org.hibernate.id.SequenceGenerator] Sequence identifier generated: 85
2007-01-27 14:16:00,964 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to close PreparedStatement (open PreparedStatements: 1, globally: 2)
2007-01-27 14:16:00,964 DEBUG [org.hibernate.jdbc.ConnectionManager] aggressively releasing JDBC connection
2007-01-27 14:16:00,964 DEBUG [org.hibernate.jdbc.ConnectionManager] releasing JDBC connection [ (open PreparedStatements: 0, globally: 1) (open ResultSets: 0, globally: 0)]
2007-01-27 14:16:00,964 DEBUG [org.hibernate.event.def.AbstractSaveEventListener] generated identifier: 85, using strategy: org.hibernate.id.SequenceGenerator
2007-01-27 14:16:00,964 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to open ResultSet (open ResultSets: 0, globally: 0)
2007-01-27 14:16:00,964 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to open PreparedStatement (open PreparedStatements: 0, globally: 1)
2007-01-27 14:16:00,964 DEBUG [org.hibernate.jdbc.ConnectionManager] opening JDBC connection
2007-01-27 14:16:00,964 DEBUG [org.hibernate.SQL] select abom_own.hibernate_sequence.nextval from dual
2007-01-27 14:16:00,964 INFO [STDOUT] Hibernate: select abom_own.hibernate_sequence.nextval from dual
2007-01-27 14:16:00,980 DEBUG [org.hibernate.impl.IteratorImpl] exhausted results
2007-01-27 14:16:00,980 DEBUG [org.hibernate.impl.IteratorImpl] closing iterator
2007-01-27 14:16:00,980 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to close ResultSet (open ResultSets: 1, globally: 1)
2007-01-27 14:16:00,980 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to close PreparedStatement (open PreparedStatements: 1, globally: 2)
2007-01-27 14:16:00,980 DEBUG [org.hibernate.jdbc.ConnectionManager] aggressively releasing JDBC connection
2007-01-27 14:16:00,980 DEBUG [org.hibernate.jdbc.ConnectionManager] releasing JDBC connection [ (open PreparedStatements: 0, globally: 1) (open ResultSets: 0, globally: 0)]
2007-01-27 14:16:00,980 DEBUG [org.jbpm.JbpmContext] closing JbpmContext
2007-01-27 14:16:00,980 DEBUG [org.jbpm.svc.Services] closing service 'persistence': org.jbpm.persistence.db.DbPersistenceService@201a5c
2007-01-27 14:16:00,980 DEBUG [org.jbpm.persistence.db.DbPersistenceService] committing hibernate transaction
2007-01-27 14:16:00,980 DEBUG [org.hibernate.transaction.JTATransaction] commit
2007-01-27 14:16:00,980 DEBUG [org.hibernate.id.SequenceGenerator] Sequence identifier generated: 86
2007-01-27 14:16:00,995 DEBUG [org.hibernate.transaction.JTATransaction] Committed JTA UserTransaction
2007-01-27 14:16:00,995 DEBUG [org.jbpm.persistence.db.DbPersistenceService] closing hibernate session
2007-01-27 14:16:00,995 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
2007-01-27 14:16:00,995 DEBUG [org.hibernate.jdbc.ConnectionManager] aggressively releasing JDBC connection
2007-01-27 14:16:00,995 DEBUG [org.hibernate.jdbc.ConnectionManager] releasing JDBC connection [ (open PreparedStatements: 0, globally: 0) (open ResultSets: 0, globally: 0)]
2007-01-27 14:16:00,995 DEBUG [org.hibernate.event.def.AbstractSaveEventListener] generated identifier: 86, using strategy: org.hibernate.id.SequenceGenerator
2007-01-27 14:16:01,011 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
2007-01-27 14:16:01,011 DEBUG [org.hibernate.jdbc.ConnectionManager] opening JDBC connection
2007-01-27 14:16:01,011 DEBUG [org.hibernate.SQL] select abom_own.hibernate_sequence.nextval from dual
2007-01-27 14:16:01,011 INFO [STDOUT] Hibernate: select abom_own.hibernate_sequence.nextval from dual
2007-01-27 14:16:01,026 DEBUG [org.hibernate.id.SequenceGenerator] Sequence identifier generated: 87
2007-01-27 14:16:01,042 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
2007-01-27 14:16:01,042 DEBUG [org.hibernate.jdbc.ConnectionManager] aggressively releasing JDBC connection
2007-01-27 14:16:01,042 DEBUG [org.hibernate.jdbc.ConnectionManager] releasing JDBC connection [ (open PreparedStatements: 0, globally: 0) (open ResultSets: 0, globally: 0)]
2007-01-27 14:16:01,042 DEBUG [org.hibernate.event.def.AbstractSaveEventListener] generated identifier: 87, using strategy: org.hibernate.id.SequenceGenerator
2007-01-27 14:16:01,042 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
2007-01-27 14:16:01,042 DEBUG [org.hibernate.jdbc.ConnectionManager] opening JDBC connection
2007-01-27 14:16:01,042 DEBUG [org.hibernate.SQL] select abom_own.hibernate_sequence.nextval from dual
2007-01-27 14:16:01,042 INFO [STDOUT] Hibernate: select abom_own.hibernate_sequence.nextval from dual
2007-01-27 14:16:01,058 DEBUG [org.hibernate.id.SequenceGenerator] Sequence identifier generated: 88
2007-01-27 14:16:01,089 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
2007-01-27 14:16:01,089 DEBUG [org.hibernate.jdbc.ConnectionManager] aggressively releasing JDBC connection
2007-01-27 14:16:01,089 DEBUG [org.hibernate.jdbc.ConnectionManager] releasing JDBC connection [ (open PreparedStatements: 0, globally: 0) (open ResultSets: 0, globally: 0)]
2007-01-27 14:16:01,089 DEBUG [org.hibernate.event.def.AbstractSaveEventListener] generated identifier: 88, using strategy: org.hibernate.id.SequenceGenerator
2007-01-27 14:16:01,089 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
2007-01-27 14:16:01,089 DEBUG [org.hibernate.jdbc.ConnectionManager] opening JDBC connection
2007-01-27 14:16:01,089 DEBUG [org.hibernate.SQL] select abom_own.hibernate_sequence.nextval from dual
2007-01-27 14:16:01,089 INFO [STDOUT] Hibernate: select abom_own.hibernate_sequence.nextval from dual
2007-01-27 14:16:01,105 DEBUG [org.hibernate.id.SequenceGenerator] Sequence identifier generated: 89
2007-01-27 14:16:01,120 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
2007-01-27 14:16:01,120 DEBUG [org.hibernate.jdbc.ConnectionManager] aggressively releasing JDBC connection
2007-01-27 14:16:01,120 DEBUG [org.hibernate.jdbc.ConnectionManager] releasing JDBC connection [ (open PreparedStatements: 0, globally: 0) (open ResultSets: 0, globally: 0)]
2007-01-27 14:16:01,120 DEBUG [org.hibernate.event.def.AbstractSaveEventListener] generated identifier: 89, using strategy: org.hibernate.id.SequenceGenerator
2007-01-27 14:16:01,120 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
2007-01-27 14:16:01,120 DEBUG [org.hibernate.jdbc.ConnectionManager] opening JDBC connection
2007-01-27 14:16:01,120 DEBUG [org.hibernate.SQL] select abom_own.hibernate_sequence.nextval from dual
2007-01-27 14:16:01,120 INFO [STDOUT] Hibernate: select abom_own.hibernate_sequence.nextval from dual
2007-01-27 14:16:01,151 DEBUG [org.hibernate.id.SequenceGenerator] Sequence identifier generated: 90
2007-01-27 14:16:01,167 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
2007-01-27 14:16:01,167 DEBUG [org.hibernate.jdbc.ConnectionManager] aggressively releasing JDBC connection
2007-01-27 14:16:01,167 DEBUG [org.hibernate.jdbc.ConnectionManager] releasing JDBC connection [ (open PreparedStatements: 0, globally: 0) (open ResultSets: 0, globally: 0)]
2007-01-27 14:16:01,167 DEBUG [org.hibernate.event.def.AbstractSaveEventListener] generated identifier: 90, using strategy: org.hibernate.id.SequenceGenerator
2007-01-27 14:16:01,167 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
2007-01-27 14:16:01,167 DEBUG [org.hibernate.jdbc.ConnectionManager] opening JDBC connection
2007-01-27 14:16:01,167 DEBUG [org.hibernate.SQL] select abom_own.hibernate_sequence.nextval from dual
2007-01-27 14:16:01,167 INFO [STDOUT] Hibernate: select abom_own.hibernate_sequence.nextval from dual
2007-01-27 14:16:01,183 DEBUG [org.hibernate.id.SequenceGenerator] Sequence identifier generated: 91
2007-01-27 14:16:01,214 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
2007-01-27 14:16:01,214 DEBUG [org.hibernate.jdbc.ConnectionManager] aggressively releasing JDBC connection
2007-01-27 14:16:01,214 DEBUG [org.hibernate.jdbc.ConnectionManager] releasing JDBC connection [ (open PreparedStatements: 0, globally: 0) (open ResultSets: 0, globally: 0)]
2007-01-27 14:16:01,214 DEBUG [org.hibernate.event.def.AbstractSaveEventListener] generated identifier: 91, using strategy: org.hibernate.id.SequenceGenerator
2007-01-27 14:16:01,214 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
2007-01-27 14:16:01,214 DEBUG [org.hibernate.jdbc.ConnectionManager] opening JDBC connection
2007-01-27 14:16:01,214 DEBUG [org.hibernate.SQL] select abom_own.hibernate_sequence.nextval from dual
2007-01-27 14:16:01,214 INFO [STDOUT] Hibernate: select abom_own.hibernate_sequence.nextval from dual
2007-01-27 14:16:01,230 DEBUG [org.hibernate.id.SequenceGenerator] Sequence identifier generated: 92
2007-01-27 14:16:01,245 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
2007-01-27 14:16:01,245 DEBUG [org.hibernate.jdbc.ConnectionManager] aggressively releasing JDBC connection
2007-01-27 14:16:01,245 DEBUG [org.hibernate.jdbc.ConnectionManager] releasing JDBC connection [ (open PreparedStatements: 0, globally: 0) (open ResultSets: 0, globally: 0)]
2007-01-27 14:16:01,245 DEBUG [org.hibernate.event.def.AbstractSaveEventListener] generated identifier: 92, using strategy: org.hibernate.id.SequenceGenerator
2007-01-27 14:16:01,245 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
2007-01-27 14:16:01,245 DEBUG [org.hibernate.jdbc.ConnectionManager] opening JDBC connection
2007-01-27 14:16:01,245 DEBUG [org.hibernate.SQL] select abom_own.hibernate_sequence.nextval from dual
2007-01-27 14:16:01,245 INFO [STDOUT] Hibernate: select abom_own.hibernate_sequence.nextval from dual
2007-01-27 14:16:01,276 DEBUG [org.hibernate.id.SequenceGenerator] Sequence identifier generated: 93
2007-01-27 14:16:01,292 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
2007-01-27 14:16:01,292 DEBUG [org.hibernate.jdbc.ConnectionManager] aggressively releasing JDBC connection
2007-01-27 14:16:01,292 DEBUG [org.hibernate.jdbc.ConnectionManager] releasing JDBC connection [ (open PreparedStatements: 0, globally: 0) (open ResultSets: 0, globally: 0)]
2007-01-27 14:16:01,292 DEBUG [org.hibernate.event.def.AbstractSaveEventListener] generated identifier: 93, using strategy: org.hibernate.id.SequenceGenerator
2007-01-27 14:16:01,292 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
2007-01-27 14:16:01,292 DEBUG [org.hibernate.jdbc.ConnectionManager] opening JDBC connection
2007-01-27 14:16:01,292 DEBUG [org.hibernate.SQL] select abom_own.hibernate_sequence.nextval from dual
2007-01-27 14:16:01,292 INFO [STDOUT] Hibernate: select abom_own.hibernate_sequence.nextval from dual
2007-01-27 14:16:01,308 DEBUG [org.hibernate.id.SequenceGenerator] Sequence identifier generated: 94
2007-01-27 14:16:01,323 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
2007-01-27 14:16:01,323 DEBUG [org.hibernate.jdbc.ConnectionManager] aggressively releasing JDBC connection
2007-01-27 14:16:01,323 DEBUG [org.hibernate.jdbc.ConnectionManager] releasing JDBC connection [ (open PreparedStatements: 0, globally: 0) (open ResultSets: 0, globally: 0)]
2007-01-27 14:16:01,323 DEBUG [org.hibernate.event.def.AbstractSaveEventListener] generated identifier: 94, using strategy: org.hibernate.id.SequenceGenerator
2007-01-27 14:16:01,339 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
2007-01-27 14:16:01,339 DEBUG [org.hibernate.jdbc.ConnectionManager] opening JDBC connection
2007-01-27 14:16:01,339 DEBUG [org.hibernate.SQL] select abom_own.hibernate_sequence.nextval from dual
2007-01-27 14:16:01,339 INFO [STDOUT] Hibernate: select abom_own.hibernate_sequence.nextval from dual
2007-01-27 14:16:01,355 DEBUG [org.hibernate.id.SequenceGenerator] Sequence identifier generated: 95
2007-01-27 14:16:01,370 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
2007-01-27 14:16:01,370 DEBUG [org.hibernate.jdbc.ConnectionManager] aggressively releasing JDBC connection
2007-01-27 14:16:01,370 DEBUG [org.hibernate.jdbc.ConnectionManager] releasing JDBC connection [ (open PreparedStatements: 0, globally: 0) (open ResultSets: 0, globally: 0)]
2007-01-27 14:16:01,370 DEBUG [org.hibernate.event.def.AbstractSaveEventListener] generated identifier: 95, using strategy: org.hibernate.id.SequenceGenerator
2007-01-27 14:16:01,370 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
2007-01-27 14:16:01,370 DEBUG [org.hibernate.jdbc.ConnectionManager] opening JDBC connection
2007-01-27 14:16:01,370 DEBUG [org.hibernate.SQL] select abom_own.hibernate_sequence.nextval from dual
2007-01-27 14:16:01,370 INFO [STDOUT] Hibernate: select abom_own.hibernate_sequence.nextval from dual
2007-01-27 14:16:01,386 DEBUG [org.hibernate.id.SequenceGenerator] Sequence identifier generated: 96
2007-01-27 14:16:01,417 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
2007-01-27 14:16:01,417 DEBUG [org.hibernate.jdbc.ConnectionManager] aggressively releasing JDBC connection
2007-01-27 14:16:01,417 DEBUG [org.hibernate.jdbc.ConnectionManager] releasing JDBC connection [ (open PreparedStatements: 0, globally: 0) (open ResultSets: 0, globally: 0)]
2007-01-27 14:16:01,417 DEBUG [org.hibernate.event.def.AbstractSaveEventListener] generated identifier: 96, using strategy: org.hibernate.id.SequenceGenerator
2007-01-27 14:16:01,417 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
2007-01-27 14:16:01,417 DEBUG [org.hibernate.jdbc.ConnectionManager] opening JDBC connection
2007-01-27 14:16:01,417 DEBUG [org.hibernate.SQL] select abom_own.hibernate_sequence.nextval from dual
2007-01-27 14:16:01,417 INFO [STDOUT] Hibernate: select abom_own.hibernate_sequence.nextval from dual
2007-01-27 14:16:01,433 DEBUG [org.hibernate.id.SequenceGenerator] Sequence identifier generated: 97
2007-01-27 14:16:01,448 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
2007-01-27 14:16:01,448 DEBUG [org.hibernate.jdbc.ConnectionManager] aggressively releasing JDBC connection
2007-01-27 14:16:01,448 DEBUG [org.hibernate.jdbc.ConnectionManager] releasing JDBC connection [ (open PreparedStatements: 0, globally: 0) (open ResultSets: 0, globally: 0)]
2007-01-27 14:16:01,448 DEBUG [org.hibernate.event.def.AbstractSaveEventListener] generated identifier: 97, using strategy: org.hibernate.id.SequenceGenerator
2007-01-27 14:16:01,448 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
2007-01-27 14:16:01,448 DEBUG [org.hibernate.jdbc.ConnectionManager] opening JDBC connection
2007-01-27 14:16:01,448 DEBUG [org.hibernate.SQL] select abom_own.hibernate_sequence.nextval from dual
2007-01-27 14:16:01,448 INFO [STDOUT] Hibernate: select abom_own.hibernate_sequence.nextval from dual
2007-01-27 14:16:01,480 DEBUG [org.hibernate.id.SequenceGenerator] Sequence identifier generated: 98
2007-01-27 14:16:01,495 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
2007-01-27 14:16:01,495 DEBUG [org.hibernate.jdbc.ConnectionManager] aggressively releasing JDBC connection
2007-01-27 14:16:01,495 DEBUG [org.hibernate.jdbc.ConnectionManager] releasing JDBC connection [ (open PreparedStatements: 0, globally: 0) (open ResultSets: 0, globally: 0)]
2007-01-27 14:16:01,495 DEBUG [org.hibernate.event.def.AbstractSaveEventListener] generated identifier: 98, using strategy: org.hibernate.id.SequenceGenerator
2007-01-27 14:16:01,495 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
2007-01-27 14:16:01,495 DEBUG [org.hibernate.jdbc.ConnectionManager] opening JDBC connection
2007-01-27 14:16:01,495 DEBUG [org.hibernate.SQL] select abom_own.hibernate_sequence.nextval from dual
2007-01-27 14:16:01,495 INFO [STDOUT] Hibernate: select abom_own.hibernate_sequence.nextval from dual
2007-01-27 14:16:01,511 DEBUG [org.hibernate.id.SequenceGenerator] Sequence identifier generated: 99
2007-01-27 14:16:01,542 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
2007-01-27 14:16:01,542 DEBUG [org.hibernate.jdbc.ConnectionManager] aggressively releasing JDBC connection
2007-01-27 14:16:01,542 DEBUG [org.hibernate.jdbc.ConnectionManager] releasing JDBC connection [ (open PreparedStatements: 0, globally: 0) (open ResultSets: 0, globally: 0)]
2007-01-27 14:16:01,542 DEBUG [org.hibernate.event.def.AbstractSaveEventListener] generated identifier: 99, using strategy: org.hibernate.id.SequenceGenerator
2007-01-27 14:16:01,542 INFO [com.spss.batch.queue.BatchJobQueue] Creating process instance...
2007-01-27 14:16:01,542 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
2007-01-27 14:16:01,542 DEBUG [org.hibernate.jdbc.ConnectionManager] opening JDBC connection
2007-01-27 14:16:01,542 DEBUG [org.hibernate.SQL] select abom_own.hibernate_sequence.nextval from dual
2007-01-27 14:16:01,542 INFO [STDOUT] Hibernate: select abom_own.hibernate_sequence.nextval from dual
2007-01-27 14:16:01,558 DEBUG [org.hibernate.id.SequenceGenerator] Sequence identifier generated: 100
2007-01-27 14:16:01,573 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
2007-01-27 14:16:01,573 DEBUG [org.hibernate.jdbc.ConnectionManager] aggressively releasing JDBC connection
2007-01-27 14:16:01,573 DEBUG [org.hibernate.jdbc.ConnectionManager] releasing JDBC connection [ (open PreparedStatements: 0, globally: 0) (open ResultSets: 0, globally: 0)]
2007-01-27 14:16:01,573 DEBUG [org.hibernate.event.def.AbstractSaveEventListener] generated identifier: 100, using strategy: org.hibernate.id.SequenceGenerator
2007-01-27 14:16:01,573 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
2007-01-27 14:16:01,573 DEBUG [org.hibernate.jdbc.ConnectionManager] opening JDBC connection
2007-01-27 14:16:01,573 DEBUG [org.hibernate.SQL] select abom_own.hibernate_sequence.nextval from dual
2007-01-27 14:16:01,573 INFO [STDOUT] Hibernate: select abom_own.hibernate_sequence.nextval from dual
2007-01-27 14:16:01,605 DEBUG [org.hibernate.id.SequenceGenerator] Sequence identifier generated: 101
2007-01-27 14:16:01,620 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
2007-01-27 14:16:01,620 DEBUG [org.hibernate.jdbc.ConnectionManager] aggressively releasing JDBC connection
2007-01-27 14:16:01,620 DEBUG [org.hibernate.jdbc.ConnectionManager] releasing JDBC connection [ (open PreparedStatements: 0, globally: 0) (open ResultSets: 0, globally: 0)]
2007-01-27 14:16:01,620 DEBUG [org.hibernate.event.def.AbstractSaveEventListener] generated identifier: 101, using strategy: org.hibernate.id.SequenceGenerator
2007-01-27 14:16:01,620 DEBUG [org.jbpm.graph.def.GraphElement] event 'process-start' on 'ProcessDefinition(FileEvent)' for 'Token(/)'
2007-01-27 14:16:01,620 DEBUG [org.jbpm.context.exe.VariableContainer] create variable 'jobTask' in 'TokenVariableMap10c6402' with value 'JobTask: file=C:\FileTest\test Watch File: C:\FileTest\testfile'
2007-01-27 14:16:01,620 INFO [com.spss.batch.queue.BatchJobQueue] Saving process instance..
2007-01-27 14:16:01,620 DEBUG [org.jbpm.svc.Services] executing default save operations
2007-01-27 14:16:01,620 DEBUG [org.jbpm.svc.save.HibernateSaveOperation] saving process instance
2007-01-27 14:16:01,620 DEBUG [org.jbpm.svc.save.SaveLogsOperation] flushing logs to logging service.
2007-01-27 14:16:01,620 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
2007-01-27 14:16:01,620 DEBUG [org.hibernate.jdbc.ConnectionManager] opening JDBC connection
2007-01-27 14:16:01,620 DEBUG [org.hibernate.SQL] select abom_own.hibernate_sequence.nextval from dual
2007-01-27 14:16:01,636 INFO [STDOUT] Hibernate: select abom_own.hibernate_sequence.nextval from dual
2007-01-27 14:16:01,652 DEBUG [org.hibernate.id.SequenceGenerator] Sequence identifier generated: 102
2007-01-27 14:16:01,667 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
2007-01-27 14:16:01,667 DEBUG [org.hibernate.jdbc.ConnectionManager] aggressively releasing JDBC connection
2007-01-27 14:16:01,667 DEBUG [org.hibernate.jdbc.ConnectionManager] releasing JDBC connection [ (open PreparedStatements: 0, globally: 0) (open ResultSets: 0, globally: 0)]
2007-01-27 14:16:01,667 DEBUG [org.hibernate.event.def.AbstractSaveEventListener] generated identifier: 102, using strategy: org.hibernate.id.SequenceGenerator
2007-01-27 14:16:01,667 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
2007-01-27 14:16:01,667 DEBUG [org.hibernate.jdbc.ConnectionManager] opening JDBC connection
2007-01-27 14:16:01,667 DEBUG [org.hibernate.SQL] select abom_own.hibernate_sequence.nextval from dual
2007-01-27 14:16:01,667 INFO [STDOUT] Hibernate: select abom_own.hibernate_sequence.nextval from dual
2007-01-27 14:16:01,683 DEBUG [org.hibernate.id.SequenceGenerator] Sequence identifier generated: 103
2007-01-27 14:16:01,714 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
2007-01-27 14:16:01,714 DEBUG [org.hibernate.jdbc.ConnectionManager] aggressively releasing JDBC connection
2007-01-27 14:16:01,714 DEBUG [org.hibernate.jdbc.ConnectionManager] releasing JDBC connection [ (open PreparedStatements: 0, globally: 0) (open ResultSets: 0, globally: 0)]
2007-01-27 14:16:01,714 DEBUG [org.hibernate.event.def.AbstractSaveEventListener] generated identifier: 103, using strategy: org.hibernate.id.SequenceGenerator
2007-01-27 14:16:01,714 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
2007-01-27 14:16:01,714 DEBUG [org.hibernate.jdbc.ConnectionManager] opening JDBC connection
2007-01-27 14:16:01,714 DEBUG [org.hibernate.SQL] select abom_own.hibernate_sequence.nextval from dual
2007-01-27 14:16:01,714 INFO [STDOUT] Hibernate: select abom_own.hibernate_sequence.nextval from dual
2007-01-27 14:16:01,730 DEBUG [org.hibernate.id.SequenceGenerator] Sequence identifier generated: 104
2007-01-27 14:16:01,745 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
2007-01-27 14:16:01,745 DEBUG [org.hibernate.jdbc.ConnectionManager] aggressively releasing JDBC connection
2007-01-27 14:16:01,745 DEBUG [org.hibernate.jdbc.ConnectionManager] releasing JDBC connection [ (open PreparedStatements: 0, globally: 0) (open ResultSets: 0, globally: 0)]
2007-01-27 14:16:01,745 DEBUG [org.hibernate.event.def.AbstractSaveEventListener] generated identifier: 104, using strategy: org.hibernate.id.SequenceGenerator
2007-01-27 14:16:01,745 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
2007-01-27 14:16:01,745 DEBUG [org.hibernate.jdbc.ConnectionManager] opening JDBC connection
2007-01-27 14:16:01,745 DEBUG [org.hibernate.SQL] select abom_own.hibernate_sequence.nextval from dual
2007-01-27 14:16:01,745 INFO [STDOUT] Hibernate: select abom_own.hibernate_sequence.nextval from dual
2007-01-27 14:16:01,777 DEBUG [org.hibernate.id.SequenceGenerator] Sequence identifier generated: 105
2007-01-27 14:16:01,792 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
2007-01-27 14:16:01,792 DEBUG [org.hibernate.jdbc.ConnectionManager] aggressively releasing JDBC connection
2007-01-27 14:16:01,792 DEBUG [org.hibernate.jdbc.ConnectionManager] releasing JDBC connection [ (open PreparedStatements: 0, globally: 0) (open ResultSets: 0, globally: 0)]
2007-01-27 14:16:01,792 DEBUG [org.hibernate.event.def.AbstractSaveEventListener] generated identifier: 105, using strategy: org.hibernate.id.SequenceGenerator
2007-01-27 14:16:01,792 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
2007-01-27 14:16:01,792 DEBUG [org.hibernate.jdbc.ConnectionManager] opening JDBC connection
2007-01-27 14:16:01,792 DEBUG [org.hibernate.SQL] select abom_own.hibernate_sequence.nextval from dual
2007-01-27 14:16:01,792 INFO [STDOUT] Hibernate: select abom_own.hibernate_sequence.nextval from dual
2007-01-27 14:16:01,808 DEBUG [org.hibernate.id.SequenceGenerator] Sequence identifier generated: 106
2007-01-27 14:16:01,823 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
2007-01-27 14:16:01,823 DEBUG [org.hibernate.jdbc.ConnectionManager] aggressively releasing JDBC connection
2007-01-27 14:16:01,823 DEBUG [org.hibernate.jdbc.ConnectionManager] releasing JDBC connection [ (open PreparedStatements: 0, globally: 0) (open ResultSets: 0, globally: 0)]
2007-01-27 14:16:01,823 DEBUG [org.hibernate.event.def.AbstractSaveEventListener] generated identifier: 106, using strategy: org.hibernate.id.SequenceGenerator
2007-01-27 14:16:01,823 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
2007-01-27 14:16:01,823 DEBUG [org.hibernate.jdbc.ConnectionManager] opening JDBC connection
2007-01-27 14:16:01,823 DEBUG [org.hibernate.SQL] select abom_own.hibernate_sequence.nextval from dual
2007-01-27 14:16:01,823 INFO [STDOUT] Hibernate: select abom_own.hibernate_sequence.nextval from dual
2007-01-27 14:16:01,855 DEBUG [org.hibernate.id.SequenceGenerator] Sequence identifier generated: 107
2007-01-27 14:16:01,870 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
2007-01-27 14:16:01,870 DEBUG [org.hibernate.jdbc.ConnectionManager] aggressively releasing JDBC connection
2007-01-27 14:16:01,870 DEBUG [org.hibernate.jdbc.ConnectionManager] releasing JDBC connection [ (open PreparedStatements: 0, globally: 0) (open ResultSets: 0, globally: 0)]
2007-01-27 14:16:01,870 DEBUG [org.hibernate.event.def.AbstractSaveEventListener] generated identifier: 107, using strategy: org.hibernate.id.SequenceGenerator
2007-01-27 14:16:01,870 DEBUG [org.jbpm.svc.save.CascadeSaveOperation] cascading save of 'org.jbpm.graph.exe.ProcessInstance@13acec3'
2007-01-27 14:16:01,870 INFO [com.spss.batch.queue.BatchJobQueue] Closing context..
2007-01-27 14:16:01,870 DEBUG [org.jbpm.JbpmContext] closing JbpmContext
2007-01-27 14:16:01,870 DEBUG [org.jbpm.svc.Services] closing service 'persistence': org.jbpm.persistence.db.DbPersistenceService@10b8624
2007-01-27 14:16:01,870 DEBUG [org.jbpm.persistence.db.DbPersistenceService] committing hibernate transaction
2007-01-27 14:16:01,870 DEBUG [org.hibernate.transaction.JTATransaction] commit
2007-01-27 14:16:01,870 DEBUG [org.hibernate.event.def.AbstractFlushingEventListener] processing flush-time cascades
2007-01-27 14:16:01,870 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
2007-01-27 14:16:01,870 DEBUG [org.hibernate.jdbc.ConnectionManager] opening JDBC connection
2007-01-27 14:16:01,870 DEBUG [org.hibernate.SQL] select abom_own.hibernate_sequence.nextval from dual
2007-01-27 14:16:01,870 INFO [STDOUT] Hibernate: select abom_own.hibernate_sequence.nextval from dual
2007-01-27 14:16:01,886 DEBUG [org.hibernate.id.SequenceGenerator] Sequence identifier generated: 108
2007-01-27 14:16:01,917 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
2007-01-27 14:16:01,917 DEBUG [org.hibernate.jdbc.ConnectionManager] aggressively releasing JDBC connection
2007-01-27 14:16:01,917 DEBUG [org.hibernate.jdbc.ConnectionManager] releasing JDBC connection [ (open PreparedStatements: 0, globally: 0) (open ResultSets: 0, globally: 0)]
2007-01-27 14:16:01,917 DEBUG [org.hibernate.event.def.AbstractSaveEventListener] generated identifier: 108, using strategy: org.hibernate.id.SequenceGenerator
2007-01-27 14:16:01,917 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
2007-01-27 14:16:01,917 DEBUG [org.hibernate.jdbc.ConnectionManager] opening JDBC connection
2007-01-27 14:16:01,917 DEBUG [org.hibernate.SQL] select abom_own.hibernate_sequence.nextval from dual
2007-01-27 14:16:01,917 INFO [STDOUT] Hibernate: select abom_own.hibernate_sequence.nextval from dual
2007-01-27 14:16:01,933 DEBUG [org.hibernate.id.SequenceGenerator] Sequence identifier generated: 109
2007-01-27 14:16:01,948 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
2007-01-27 14:16:01,948 DEBUG [org.hibernate.jdbc.ConnectionManager] aggressively releasing JDBC connection
2007-01-27 14:16:01,948 DEBUG [org.hibernate.jdbc.ConnectionManager] releasing JDBC connection [ (open PreparedStatements: 0, globally: 0) (open ResultSets: 0, globally: 0)]
2007-01-27 14:16:01,948 DEBUG [org.hibernate.event.def.AbstractSaveEventListener] generated identifier: 109, using strategy: org.hibernate.id.SequenceGenerator
2007-01-27 14:16:01,948 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
2007-01-27 14:16:01,948 DEBUG [org.hibernate.jdbc.ConnectionManager] opening JDBC connection
2007-01-27 14:16:01,948 DEBUG [org.hibernate.SQL] select abom_own.hibernate_sequence.nextval from dual
2007-01-27 14:16:01,948 INFO [STDOUT] Hibernate: select abom_own.hibernate_sequence.nextval from dual
2007-01-27 14:16:01,964 DEBUG [org.hibernate.id.SequenceGenerator] Sequence identifier generated: 110
2007-01-27 14:16:01,995 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
2007-01-27 14:16:01,995 DEBUG [org.hibernate.jdbc.ConnectionManager] aggressively releasing JDBC connection
2007-01-27 14:16:01,995 DEBUG [org.hibernate.jdbc.ConnectionManager] releasing JDBC connection [ (open PreparedStatements: 0, globally: 0) (open ResultSets: 0, globally: 0)]
2007-01-27 14:16:01,995 DEBUG [org.hibernate.event.def.AbstractSaveEventListener] generated identifier: 110, using strategy: org.hibernate.id.SequenceGenerator
2007-01-27 14:16:01,995 DEBUG [org.hibernate.event.def.AbstractFlushingEventListener] dirty checking collections
2007-01-27 14:16:01,995 DEBUG [org.hibernate.engine.Collections] Collection found: [org.jbpm.graph.def.ProcessDefinition.nodes#75], was: [<unreferenced>] (initialized)
2007-01-27 14:16:01,995 DEBUG [org.hibernate.engine.Collections] Collection found: [org.jbpm.graph.def.ProcessDefinition.actions#75], was: [<unreferenced>] (initialized)
2007-01-27 14:16:01,995 DEBUG [org.hibernate.engine.Collections] Collection found: [org.jbpm.graph.def.ProcessDefinition.definitions#75], was: [<unreferenced>] (initialized)
2007-01-27 14:16:01,995 DEBUG [org.hibernate.engine.Collections] Collection found: [org.jbpm.graph.def.Node.leavingTransitions#76], was: [<unreferenced>] (initialized)
2007-01-27 14:16:01,995 DEBUG [org.hibernate.engine.Collections] Collection found: [org.jbpm.graph.def.Node.leavingTransitions#78], was: [<unreferenced>] (initialized)
2007-01-27 14:16:01,995 DEBUG [org.hibernate.engine.Collections] Collection found: [org.jbpm.graph.def.Node.arrivingTransitions#78], was: [<unreferenced>] (initialized)
2007-01-27 14:16:01,995 DEBUG [org.hibernate.engine.Collections] Collection found: [org.jbpm.graph.def.Node.events#82], was: [<unreferenced>] (initialized)
2007-01-27 14:16:01,995 DEBUG [org.hibernate.engine.Collections] Collection found: [org.jbpm.graph.def.Node.leavingTransitions#82], was: [<unreferenced>] (initialized)
2007-01-27 14:16:01,995 DEBUG [org.hibernate.engine.Collections] Collection found: [org.jbpm.graph.def.Node.arrivingTransitions#82], was: [<unreferenced>] (initialized)
2007-01-27 14:16:01,995 DEBUG [org.hibernate.engine.Collections] Collection found: [org.jbpm.graph.def.Event.actions#83], was: [<unreferenced>] (initialized)
2007-01-27 14:16:01,995 DEBUG [org.hibernate.engine.Collections] Collection found: [org.jbpm.graph.def.Event.actions#85], was: [<unreferenced>] (initialized)
2007-01-27 14:16:01,995 DEBUG [org.hibernate.engine.Collections] Collection found: [org.jbpm.graph.def.Node.events#90], was: [<unreferenced>] (initialized)
2007-01-27 14:16:01,995 DEBUG [org.hibernate.engine.Collections] Collection found: [org.jbpm.graph.def.Node.leavingTransitions#90], was: [<unreferenced>] (initialized)
2007-01-27 14:16:01,995 DEBUG [org.hibernate.engine.Collections] Collection found: [org.jbpm.graph.def.Node.arrivingTransitions#90], was: [<unreferenced>] (initialized)
2007-01-27 14:16:01,995 DEBUG [org.hibernate.engine.Collections] Collection found: [org.jbpm.graph.def.Event.actions#91], was: [<unreferenced>] (initialized)
2007-01-27 14:16:01,995 DEBUG [org.hibernate.engine.Collections] Collection found: [org.jbpm.graph.def.Node.events#95], was: [<unreferenced>] (initialized)
2007-01-27 14:16:01,995 DEBUG [org.hibernate.engine.Collections] Collection found: [org.jbpm.graph.def.Node.arrivingTransitions#95], was: [<unreferenced>] (initialized)
2007-01-27 14:16:01,995 DEBUG [org.hibernate.engine.Collections] Collection found: [org.jbpm.graph.def.Event.actions#96], was: [<unreferenced>] (initialized)
2007-01-27 14:16:01,995 DEBUG [org.hibernate.engine.Collections] Collection found: [org.jbpm.graph.exe.ProcessInstance.instances#100], was: [<unreferenced>] (initialized)
2007-01-27 14:16:01,995 DEBUG [org.hibernate.engine.Collections] Collection found: [org.jbpm.bytes.ByteArray.byteBlocks#105], was: [<unreferenced>] (initialized)
2007-01-27 14:16:01,995 DEBUG [org.hibernate.engine.Collections] Collection found: [org.jbpm.bytes.ByteArray.byteBlocks#107], was: [<unreferenced>] (initialized)
2007-01-27 14:16:01,995 DEBUG [org.hibernate.engine.Collections] Collection found: [org.jbpm.context.exe.ContextInstance.tokenVariableMaps#109], was: [<unreferenced>] (initialized)
2007-01-27 14:16:01,995 DEBUG [org.hibernate.engine.Collections] Collection found: [org.jbpm.context.exe.TokenVariableMap.variableInstances#110], was: [<unreferenced>] (initialized)
2007-01-27 14:16:01,995 DEBUG [org.hibernate.event.def.AbstractFlushingEventListener] Flushed: 36 insertions, 8 updates, 0 deletions to 36 objects
2007-01-27 14:16:01,995 DEBUG [org.hibernate.event.def.AbstractFlushingEventListener] Flushed: 23 (re)creations, 0 updates, 0 removals to 23 collections
2007-01-27 14:16:01,995 DEBUG [org.hibernate.pretty.Printer] listing entities:
2007-01-27 14:16:01,995 DEBUG [org.hibernate.pretty.Printer] org.jbpm.graph.def.Transition{to=org.jbpm.graph.def.Node#90, events=null, from=org.jbpm.graph.def.Node#78, exceptionHandlers=null, name=true, id=80, processDefinition=org.jbpm.graph.def.ProcessDefinition#75}
2007-01-27 14:16:02,011 DEBUG [org.hibernate.pretty.Printer] org.jbpm.context.exe.variableinstance.ByteArrayInstance{processInstance=org.jbpm.graph.exe.ProcessInstance#100, value=org.jbpm.bytes.ByteArray#105, tokenVariableMap=org.jbpm.context.exe.TokenVariableMap#110, converter=org.jbpm.context.exe.converter.SerializableToByteArrayConverter@9cd826, token=org.jbpm.graph.exe.Token#101, name=jobTask, id=104}
2007-01-27 14:16:02,011 DEBUG [org.hibernate.pretty.Printer] org.jbpm.graph.def.Event{actions=[org.jbpm.graph.def.Action#86], graphElement=org.jbpm.graph.node.State#82, eventType=node-enter, id=85}
2007-01-27 14:16:02,011 DEBUG [org.hibernate.pretty.Printer] org.jbpm.graph.def.Transition{to=org.jbpm.graph.def.Node#78, events=null, from=org.jbpm.graph.def.Node#76, exceptionHandlers=null, name=, id=77, processDefinition=org.jbpm.graph.def.ProcessDefinition#75}
2007-01-27 14:16:02,011 DEBUG [org.hibernate.pretty.Printer] org.jbpm.graph.log.ProcessInstanceCreateLog{index=0, token=org.jbpm.graph.exe.Token#101, date=2007-01-27 14:16:01, parent=null, id=102}
2007-01-27 14:16:02,011 DEBUG [org.hibernate.pretty.Printer] org.jbpm.graph.exe.Token{comments=null, processInstance=org.jbpm.graph.exe.ProcessInstance#100, subProcessInstance=null, start=2007-01-27 14:16:01, isSuspended=false, end=null, node=org.jbpm.graph.def.Node#76, id=101, version=0, nextLogIndex=3, name=null, isTerminationImplicit=false, children=null, isAbleToReactivateParent=true, parent=null, nodeEnter=null}
2007-01-27 14:16:02,011 DEBUG [org.hibernate.pretty.Printer] org.jbpm.graph.node.EndState{events=[org.jbpm.graph.def.Event#96], leavingTransitions=null, action=null, superState=null, exceptionHandlers=null, name=end1, id=95, arrivingTransitions=[org.jbpm.graph.def.Transition#94], isAsync=false, processDefinition=org.jbpm.graph.def.ProcessDefinition#75}
2007-01-27 14:16:02,011 DEBUG [org.hibernate.pretty.Printer] org.jbpm.graph.def.Event{actions=[org.jbpm.graph.def.Action#97], graphElement=org.jbpm.graph.node.EndState#95, eventType=node-enter, id=96}
2007-01-27 14:16:02,011 DEBUG [org.hibernate.pretty.Printer] org.jbpm.graph.node.StartState{events=null, leavingTransitions=[org.jbpm.graph.def.Transition#77], action=null, superState=null, exceptionHandlers=null, name=start, id=76, arrivingTransitions=null, isAsync=false, processDefinition=org.jbpm.graph.def.ProcessDefinition#75}
2007-01-27 14:16:02,011 DEBUG [org.hibernate.pretty.Printer] org.jbpm.scheduler.def.CreateTimerAction{repeat=false, actionExpression=null, dueDate=10 seconds, timerAction=org.jbpm.graph.def.Action#87, referencedAction=null, id=86, isAsync=false, processDefinition=null, isPropagationAllowed=true, timerName=Wait For File, event=org.jbpm.graph.def.Event#85, actionDelegation=null, transitionName=Is file complete, name=null}
2007-01-27 14:16:02,011 DEBUG [org.hibernate.pretty.Printer] org.jbpm.graph.exe.ProcessInstance{start=2007-01-27 14:16:01, instances=[org.jbpm.module.exe.ModuleInstance#108, org.jbpm.module.exe.ModuleInstance#109], runtimeActions=null, isSuspended=false, end=null, superProcessToken=null, rootToken=org.jbpm.graph.exe.Token#101, id=100, processDefinition=org.jbpm.graph.def.ProcessDefinition#75, version=1}
2007-01-27 14:16:02,011 DEBUG [org.hibernate.pretty.Printer] org.jbpm.graph.def.Event{actions=[org.jbpm.graph.def.Action#84], graphElement=org.jbpm.graph.node.State#82, eventType=node-leave, id=83}
2007-01-27 14:16:02,011 DEBUG [org.hibernate.pretty.Printer] org.jbpm.context.log.variableinstance.ByteArrayUpdateLog{newValue=org.jbpm.bytes.ByteArray#107, index=2, variableInstance=org.jbpm.context.exe.VariableInstance#104, token=org.jbpm.graph.exe.Token#101, oldValue=null, date=2007-01-27 14:16:01, parent=null, id=106}
2007-01-27 14:16:02,011 DEBUG [org.hibernate.pretty.Printer] org.jbpm.context.exe.ContextInstance{processInstance=org.jbpm.graph.exe.ProcessInstance#100, id=109, tokenVariableMaps=[org.jbpm.context.exe.TokenVariableMap#110]}
2007-01-27 14:16:02,011 DEBUG [org.hibernate.pretty.Printer] org.jbpm.taskmgmt.def.TaskMgmtDefinition{swimlanes=null, startTask=null, tasks=null, name=null, id=99, processDefinition=org.jbpm.graph.def.ProcessDefinition#75}
2007-01-27 14:16:02,011 DEBUG [org.hibernate.pretty.Printer] org.jbpm.graph.def.Event{actions=[org.jbpm.graph.def.Action#92], graphElement=org.jbpm.graph.def.Node#90, eventType=node-enter, id=91}
2007-01-27 14:16:02,011 DEBUG [org.hibernate.pretty.Printer] org.jbpm.graph.def.Transition{to=org.jbpm.graph.def.Node#78, events=null, from=org.jbpm.graph.def.Node#82, exceptionHandlers=null, name=File isn't complete, id=89, processDefinition=org.jbpm.graph.def.ProcessDefinition#75}
2007-01-27 14:16:02,011 DEBUG [org.hibernate.pretty.Printer] org.jbpm.graph.node.Decision{events=null, action=null, leavingTransitions=[org.jbpm.graph.def.Transition#80, org.jbpm.graph.def.Transition#81], superState=null, id=78, decisionConditions=null, processDefinition=org.jbpm.graph.def.ProcessDefinition#75, isAsync=false, decisionDelegation=org.jbpm.instantiation.Delegation#79, decisionExpression=null, exceptionHandlers=null, name=Is file complete, arrivingTransitions=[org.jbpm.graph.def.Transition#77, org.jbpm.graph.def.Transition#89]}
2007-01-27 14:16:02,011 DEBUG [org.hibernate.pretty.Printer] org.jbpm.context.exe.TokenVariableMap{variableInstances=[org.jbpm.context.exe.VariableInstance#104], token=org.jbpm.graph.exe.Token#101, contextInstance=org.jbpm.context.exe.ContextInstance#109, id=110}
2007-01-27 14:16:02,011 DEBUG [org.hibernate.pretty.Printer] org.jbpm.bytes.ByteArray{name=null, byteBlocks=[2c6d8085f3f280a0e3efedaef3f0f3f3aee2e1f4e3e8aef1f5e5f5e5aed4e5f3f4caefe2d4e1f3ebbe4c21d0d08bec71828080f8f280a4e3efedaef3f0f3f3aee2e1f4e3e8aef1f5e5f5e5aec1e2f3f4f2e1e3f4caefe2d4e1f3eba6b55cf50a61b6bd828085ca8088e6e9ece5d3e9fae5ca8089ece1f3f4c3e8e5e3ebca808cece1f3f4cdefe4e9e6e9e5e4cc8088f4e1f3ebc6e9ece5f4808ecceae1f6e1afe9efafc6e9ece5bbcc8089f7e1f4e3e8c6e9ece5f180fe8082f8f080808080808080b480808190e47ccf5480808190e0a50136f3f2808ceae1f6e1aee9efaec6e9ece584ad24c58e8d647f838081cc8084f0e1f4e8f48092cceae1f6e1afece1eee7afd3f4f2e9eee7bbf8f0f48090c3badcc6e9ece5d4e5f3f4dcf4e5f3f4f78280dcf8f3f180fe8084f48094c3badcc6e9ece5d4e5f3f4dcf4e5f3f4e6e9ece5f78280dcf8], id=105}
2007-01-27 14:16:02,011 DEBUG [org.hibernate.pretty.Printer] org.jbpm.instantiation.Delegation{configType=field, configuration=null, className=com.spss.batch.queue.actions.StartJobProcess, id=93, processDefinition=org.jbpm.graph.def.ProcessDefinition#75}
2007-01-27 14:16:02,011 DEBUG [org.hibernate.pretty.Printer] more......
2007-01-27 14:16:02,011 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
2007-01-27 14:16:02,011 DEBUG [org.hibernate.jdbc.ConnectionManager] opening JDBC connection
2007-01-27 14:16:02,011 DEBUG [org.hibernate.SQL] insert into abom_own.JBPM_PROCESSDEFINITION (NAME_, VERSION_, ISTERMINATIONIMPLICIT_, STARTSTATE_, ID_) values (?, ?, ?, ?, ?)
2007-01-27 14:16:02,011 INFO [STDOUT] Hibernate: insert into abom_own.JBPM_PROCESSDEFINITION (NAME_, VERSION_, ISTERMINATIONIMPLICIT_, STARTSTATE_, ID_) values (?, ?, ?, ?, ?)
2007-01-27 14:16:02,011 DEBUG [org.hibernate.jdbc.AbstractBatcher] Executing batch size: 1
2007-01-27 14:16:02,105 DEBUG [org.hibernate.jdbc.Expectations] success of batch update unknown: 0
2007-01-27 14:16:02,105 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
2007-01-27 14:16:02,105 DEBUG [org.hibernate.jdbc.ConnectionManager] skipping aggressive-release due to flush cycle
2007-01-27 14:16:02,105 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
2007-01-27 14:16:02,105 DEBUG [org.hibernate.SQL] insert into abom_own.JBPM_NODE (NAME_, PROCESSDEFINITION_, ISASYNC_, ACTION_, SUPERSTATE_, CLASS_, ID_) values (?, ?, ?, ?, ?, 'R', ?)
2007-01-27 14:16:02,105 INFO [STDOUT] Hibernate: insert into abom_own.JBPM_NODE (NAME_, PROCESSDEFINITION_, ISASYNC_, ACTION_, SUPERSTATE_, CLASS_, ID_) values (?, ?, ?, ?, ?, 'R', ?)
2007-01-27 14:16:02,105 DEBUG [org.hibernate.jdbc.AbstractBatcher] Executing batch size: 1
2007-01-27 14:16:02,136 DEBUG [org.hibernate.jdbc.Expectations] success of batch update unknown: 0
2007-01-27 14:16:02,136 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
2007-01-27 14:16:02,136 DEBUG [org.hibernate.jdbc.ConnectionManager] skipping aggressive-release due to flush cycle
2007-01-27 14:16:02,136 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
2007-01-27 14:16:02,136 DEBUG [org.hibernate.SQL] insert into abom_own.JBPM_TRANSITION (NAME_, PROCESSDEFINITION_, FROM_, TO_, ID_) values (?, ?, ?, ?, ?)
2007-01-27 14:16:02,136 INFO [STDOUT] Hibernate: insert into abom_own.JBPM_TRANSITION (NAME_, PROCESSDEFINITION_, FROM_, TO_, ID_) values (?, ?, ?, ?, ?)
2007-01-27 14:16:02,136 DEBUG [org.hibernate.jdbc.AbstractBatcher] Executing batch size: 1
2007-01-27 14:16:02,152 DEBUG [org.hibernate.jdbc.Expectations] success of batch update unknown: 0
2007-01-27 14:16:02,152 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
2007-01-27 14:16:02,152 DEBUG [org.hibernate.jdbc.ConnectionManager] skipping aggressive-release due to flush cycle
2007-01-27 14:16:02,152 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
2007-01-27 14:16:02,152 DEBUG [org.hibernate.SQL] insert into abom_own.JBPM_DELEGATION (CLASSNAME_, CONFIGURATION_, CONFIGTYPE_, PROCESSDEFINITION_, ID_) values (?, ?, ?, ?, ?)
2007-01-27 14:16:02,152 INFO [STDOUT] Hibernate: insert into abom_own.JBPM_DELEGATION (CLASSNAME_, CONFIGURATION_, CONFIGTYPE_, PROCESSDEFINITION_, ID_) values (?, ?, ?, ?, ?)
2007-01-27 14:16:02,152 DEBUG [org.hibernate.jdbc.AbstractBatcher] Executing batch size: 1
2007-01-27 14:16:02,183 DEBUG [org.hibernate.jdbc.Expectations] success of batch update unknown: 0
2007-01-27 14:16:02,183 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
2007-01-27 14:16:02,183 DEBUG [org.hibernate.jdbc.ConnectionManager] skipping aggressive-release due to flush cycle
2007-01-27 14:16:02,183 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
2007-01-27 14:16:02,183 DEBUG [org.hibernate.SQL] insert into abom_own.JBPM_NODE (NAME_, PROCESSDEFINITION_, ISASYNC_, ACTION_, SUPERSTATE_, DECISIONEXPRESSION_, DECISIONDELEGATION, CLASS_, ID_) values (?, ?, ?, ?, ?, ?, ?, 'D', ?)
2007-01-27 14:16:02,183 INFO [STDOUT] Hibernate: insert into abom_own.JBPM_NODE (NAME_, PROCESSDEFINITION_, ISASYNC_, ACTION_, SUPERSTATE_, DECISIONEXPRESSION_, DECISIONDELEGATION, CLASS_, ID_) values (?, ?, ?, ?, ?, ?, ?, 'D', ?)
2007-01-27 14:16:02,183 DEBUG [org.hibernate.jdbc.AbstractBatcher] Executing batch size: 1
2007-01-27 14:16:02,214 DEBUG [org.hibernate.jdbc.Expectations] success of batch update unknown: 0
2007-01-27 14:16:02,214 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
2007-01-27 14:16:02,214 DEBUG [org.hibernate.jdbc.ConnectionManager] skipping aggressive-release due to flush cycle
2007-01-27 14:16:02,214 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
2007-01-27 14:16:02,214 DEBUG [org.hibernate.SQL] insert into abom_own.JBPM_TRANSITION (NAME_, PROCESSDEFINITION_, FROM_, TO_, ID_) values (?, ?, ?, ?, ?)
2007-01-27 14:16:02,214 INFO [STDOUT] Hibernate: insert into abom_own.JBPM_TRANSITION (NAME_, PROCESSDEFINITION_, FROM_, TO_, ID_) values (?, ?, ?, ?, ?)
2007-01-27 14:16:02,214 DEBUG [org.hibernate.jdbc.AbstractBatcher] reusing prepared statement
2007-01-27 14:16:02,214 DEBUG [org.hibernate.SQL] insert into abom_own.JBPM_TRANSITION (NAME_, PROCESSDEFINITION_, FROM_, TO_, ID_) values (?, ?, ?, ?, ?)
2007-01-27 14:16:02,214 INFO [STDOUT] Hibernate: insert into abom_own.JBPM_TRANSITION (NAME_, PROCESSDEFINITION_, FROM_, TO_, ID_) values (?, ?, ?, ?, ?)
2007-01-27 14:16:02,214 DEBUG [org.hibernate.jdbc.AbstractBatcher] Executing batch size: 2
2007-01-27 14:16:02,230 DEBUG [org.hibernate.jdbc.Expectations] success of batch update unknown: 0
2007-01-27 14:16:02,230 DEBUG [org.hibernate.jdbc.Expectations] success of batch update unknown: 1
2007-01-27 14:16:02,230 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
2007-01-27 14:16:02,230 DEBUG [org.hibernate.jdbc.ConnectionManager] skipping aggressive-release due to flush cycle
2007-01-27 14:16:02,230 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to open PreparedState

5. Re: Timer Problem

kukeltje Jan 29, 2007 1:59 PM (in response to colsona)

hhmmmmm..

2007-01-27 14:16:02,011 DEBUG [org.hibernate.pretty.Printer] org.jbpm.scheduler.def.CreateTimerAction{repeat=false, actionExpression=null, dueDate=10 seconds, timerAction=org.jbpm.graph.def.Action#87,referencedAction=null, id=86, isAsync=false, processDefinition=null, isPropagationAllowed=true, timerName=Wait For File, event=org.jbpm.graph.def.Event#85, actionDelegation=null, transitionName=Is file complete, name=null}

6. Re: Timer Problem

kukeltje Jan 29, 2007 2:00 PM (in response to colsona)

This is one beyond my experience. Maybe Tom, Koen or Alex have a clue.
Actions
7. Re: Timer Problem

tom.baeyens Jan 30, 2007 8:58 AM (in response to colsona)
// this wont work cause the process instance is not yet saved

that is fixed in the meantime. upon creation of process instances, task instances or other such stuff, the persistent objects are saved by hibernate so that they are assigned an id when they are constructed.

I just removed that comment.
Actions
8. Re: Timer Problem

colsona Jan 30, 2007 9:11 AM (in response to colsona)

I thought that might be the case but my timers still don't work.

Asa
Actions
9. Re: Timer Problem

tom.baeyens Jan 30, 2007 9:13 AM (in response to colsona)

before spending a lot of time on the timer issue, i would clean up the process xml. just to be sure to exclude any interference of another issue.

remove the process action at the end and make sure that the node has the transition that is specified in the timer (currently it has not)

then examine the jBPM debug logs (disable all other hibernate logging). you should get an idea of when state 'false' is entered. that is when the timer should be created. you should see a debug log like 'saving timer'

most likely this is a configuration/setup problem.

hope this helps

then i would suggest to set a breakpoint on the createTimer method.

is your transaction committing ?
Actions
10. Re: Timer Problem

colsona Jan 30, 2007 9:18 AM (in response to colsona)

I have already step traced to the creation of the timer. That is how I found the comment previously mentioned. I also step traced the timer service and found that no timer record was found in the DB. I queried the DB directly and the timer object wasn't in the table. There is no exception in the provided log what else would cause the transaction not to commit?

Asa
Actions

Go to original post