[rules-users] Strange intermittent problem with Drools Flow
Dan Nathanson
dan at ddnconsulting.com
Fri Apr 1 14:03:55 EDT 2011
Hi Mauricio,
Thanks for looking into this. These are the types of errors that scare
me. They only happen in one environment and I cannot reproduce them.
How will I know if it happens in production?
We generate our rule flow's dynamically from our own concept of a
process flow. I don't have a custom work item implementation, but I
do have a custom WorkItemHandler registered against work items of type
"Step" called StepWorkItemHandler. StepWorkItemHandler has uses and
injected CallbackHandler to do actual processing. In test code, the
injected callback handler just records what steps (work items) have
been activated. In production code, the injected handler sends JMS
messages to notify assigned users that work needs to be completed.
Below is an example of a simple generated flow that fails
intermittently for one developer here. I captured it using the
XmlRuleFlowProcessDumper.
<?xml version="1.0" encoding="UTF-8"?>
<process xmlns="http://drools.org/drools-5.0/process"
xmlns:xs="http://www.w3.org/2001/XMLSchema-instance"
xs:schemaLocation="http://drools.org/drools-5.0/process
drools-processes-5.0.xsd"
type="RuleFlow" name="flow-1"
id="bd5556f7_581d_422f_a382_3bb3ac041c4f"
package-name="com.xxx.process.manager" >
<header>
<imports>
<import name="org.drools.ruleflow.instance.RuleFlowProcessInstance" />
</imports>
</header>
<nodes>
<start id="1" name="flow-1 Start" />
<join id="2" name="step-1 Reject Join" type="2" />
<workItem id="3" name="step-1 Step" >
<work name="Step" >
</work>
</workItem>
<workItem id="4" name="step-1 Approval" >
<work name="Step" >
</work>
</workItem>
<split id="5" name="step-1 Approval Split" type="2" >
<constraints>
<constraint toNodeId="2" toType="DROOLS_DEFAULT"
name="rejected" priority="110" type="code" dialect="java" >return
true;</constraint>
<constraint toNodeId="6" toType="DROOLS_DEFAULT"
name="approved" priority="100" type="rule" dialect="mvel"
>StepApproval( approved == true, sliceValue == "NO_SLICE",
approvalStepNodeId == "1a8a5a64-1e32-46a9-8b04-806c1706a97a"
)</constraint>
</constraints>
</split>
<state id="6" name="null Wait" >
<onEntry>
<action type="expression" dialect="java"
>Terminator.terminateFlow(context);</action>
</onEntry>
<constraints>
<constraint toNodeId="7" >Terminator()</constraint>
</constraints>
</state>
<end id="7" name="null End" />
</nodes>
<connections>
<connection from="1" to="2" />
<connection from="5" to="2" />
<connection from="2" to="3" />
<connection from="3" to="4" />
<connection from="4" to="5" />
<connection from="5" to="6" />
<connection from="6" to="7" />
</connections>
</process>
I'm attaching the log at trace level (there are no WARN level messages
at all) that shows this flow failing to complete. Lines of interest:
631: Generating the flow from our internal model
634: starting the flow
785: Process event listener shows that flow has started and proceeded
to work item 1 ("step-1 Step")
802: StepWorkItemHandler called for work item 1 "step-1 Step"
803: Process event listener shows "unwinding"of activations
904: Work item 1 "step-1 Step" completed
921: work item loaded
939: process instance loaded
956: Process event listener shows leaving "step-1 Step", activating
work item 2 "step-1 Approval"
969: StepWorkItemHandler called forwork item 2 "step-1 Approval"
970: Process event listener shows "unwinding"of activations
1024: work item 1 deleted
1032: Work item 2 "step-1 Approval" completed
1049: work item loaded
1067: process instance loaded
---Should now see leaving "step-1 Approval" and completing flow, but
don't see any further progress in the flow.---
1141: work item 2 deleted
The execution thread is part of the log output and it seems that
everything is done in one thread.
I've also attached a log file (without verbose hibernate output) for a
successful test run.
Regards,
Dan Nathanson
On Fri, Apr 1, 2011 at 2:42 AM, Mauricio Salatino <salaboy at gmail.com> wrote:
> Hi Dan,
> That's strange, it could be related to a non updated version of the fluent
> API.
> Send us the logs with warn verbosity and we will definitely take a look on
> it.
> If the workflow don't continue after a work item completion could be related
> with some kind of threading problem.
> What kind of work item are you implementing? Can you share some test with us
> that shows the desired behavior?
> Greetings.
>
> On Thu, Mar 31, 2011 at 4:32 PM, Dan Nathanson <dan at ddnconsulting.com>
> wrote:
>>
>> Hi,
>>
>> I'm seeing some odd behavior in some of my test cases. And it only
>> seems to happen to one guy. And he's done fresh checkouts of the code,
>> blown away his local M2 repository and verified installed software
>> like OS and Java is same as everyone else's.
>>
>> I have some test cases that build up some simple flows programatically
>> using fluent API. Very simple (start --> work item --> work item -->
>> state --> end). I am using Drools Flow 5.1.1 with JPA (in-memory H2
>> DB for unit tests). Intermittently, after completing a work item, the
>> flow doesn't continue. Logging in a process event listener shows that
>> the the work item node is never left, although I can see in the logs
>> that the work item is deleted from DB.
>>
>> There are no errors, warning or info level messages coming out of
>> Drools or Hibernate prior to the failure.
>>
>> It only happens to one guy, but he can reproduce the problem
>> regularly, although it moves around in different test cases and
>> different points in the flows.
>>
>> Anyone ever seen this behavior before? Any possible explanations?
>>
>> I'd attach the log file, but it is huge since I've got hibernate
>> logging set very verbose.
>>
>> Regards,
>>
>> Dan Nathanson
>> _______________________________________________
>> rules-users mailing list
>> rules-users at lists.jboss.org
>> https://lists.jboss.org/mailman/listinfo/rules-users
>
>
>
> --
> - CTO @ http://www.plugtree.com
> - MyJourney @ http://salaboy.wordpress.com
> - Co-Founder @ http://www.jbug.com.ar
>
> - Salatino "Salaboy" Mauricio -
>
-------------- next part --------------
12:03:16.413 [pool-1-thread-1] INFO o.s.c.s.ClassPathXmlApplicationContext - Refreshing org.springframework.context.support.ClassPathXmlApplicationContext at 7d6bb63e: startup date [Thu Mar 31 12:03:16 PDT 2011]; root of context hierarchy
12:03:16.413 [pool-1-thread-1] INFO o.s.b.f.xml.XmlBeanDefinitionReader - Loading XML bean definitions from class path resource [META-INF/proferi-component.xml]
12:03:16.445 [pool-1-thread-1] INFO o.s.b.f.xml.XmlBeanDefinitionReader - Loading XML bean definitions from class path resource [META-INF/proferi-component-test.xml]
12:03:16.460 [pool-1-thread-1] INFO o.s.b.f.s.DefaultListableBeanFactory - Overriding bean definition for bean 'processFlowService': replacing [Generic bean: class [com.proferi.core.NorbertProtobufService]; scope=; abstract=false; lazyInit=false; autowireMode=0; dependencyCheck=0; autowireCandidate=true; primary=false; factoryBeanName=null; factoryMethodName=null; initMethodName=null; destroyMethodName=null; defined in class path resource [META-INF/proferi-component.xml]] with [Generic bean: class [com.proferi.core.MockProtobufService]; scope=; abstract=false; lazyInit=false; autowireMode=0; dependencyCheck=0; autowireCandidate=true; primary=false; factoryBeanName=null; factoryMethodName=null; initMethodName=null; destroyMethodName=null; defined in class path resource [META-INF/proferi-component-test.xml]]
12:03:16.460 [pool-1-thread-1] INFO o.s.b.f.s.DefaultListableBeanFactory - Overriding bean definition for bean 'connectionFactory': replacing [Generic bean: class [org.hornetq.jms.client.HornetQConnectionFactory]; scope=; abstract=false; lazyInit=false; autowireMode=0; dependencyCheck=0; autowireCandidate=true; primary=false; factoryBeanName=null; factoryMethodName=null; initMethodName=null; destroyMethodName=null; defined in class path resource [META-INF/proferi-component.xml]] with [Generic bean: class [org.hornetq.jms.client.HornetQConnectionFactory]; scope=; abstract=false; lazyInit=false; autowireMode=0; dependencyCheck=0; autowireCandidate=true; primary=false; factoryBeanName=null; factoryMethodName=null; initMethodName=null; destroyMethodName=null; defined in class path resource [META-INF/proferi-component-test.xml]]
12:03:16.476 [pool-1-thread-1] INFO o.s.b.f.c.PropertyPlaceholderConfigurer - Loading properties file from class path resource [proferi-component.properties]
12:03:16.476 [pool-1-thread-1] INFO o.s.b.f.s.DefaultListableBeanFactory - Pre-instantiating singletons in org.springframework.beans.factory.support.DefaultListableBeanFactory at 1c944d4a: defining beans [processFlowManager,stepWorkItemHandler,stepActivationCallbackHandler,processEventListener,modelCache,modelFactory,droolsFlowAdapter,memberSetResolver,instanceCache,processFlowService,startProcessFlowHandler,getProcessFlowStatusHandler,stepCompletedServiceHandler,approvalCompletedServiceHandler,connectionFactory,protobufJmsListener,protobufConverter,messageHandler,cachedConnectionFactory,jmsTemplate,messageProducer,dataSource,transactionManager,entityManagerFactory,jpaAdapter,entityManager,org.springframework.beans.factory.config.PropertyPlaceholderConfigurer#0,testOutJmsTemplate,testInJmsTemplate,testInConverter,outListener,inSender,embeddedJmsBroker]; root of factory hierarchy
12:03:16.491 [pool-1-thread-1] DEBUG c.p.core.message.ProtobufJmsListener - invoking handleMessage on ProcessFlowMessageConsumer for a StepCompletedRequest
12:03:16.491 [pool-1-thread-1] DEBUG c.p.core.message.ProtobufJmsListener - invoking handleMessage on ProcessFlowMessageConsumer for a ApprovalCompletedRequest
12:03:16.491 [pool-1-thread-1] INFO o.s.o.j.LocalContainerEntityManagerFactoryBean - Building JPA container EntityManagerFactory for persistence unit 'org.drools.persistence.jpa'
12:03:16.491 [pool-1-thread-1] DEBUG org.hibernate.ejb.Ejb3Configuration - Processing PersistenceUnitInfo [
name: org.drools.persistence.jpa
persistence provider classname: org.hibernate.ejb.HibernatePersistence
classloader: sun.misc.Launcher$AppClassLoader at 12360be0
Temporary classloader: org.springframework.instrument.classloading.SimpleThrowawayClassLoader at 1fca73bf
excludeUnlistedClasses: false
JTA datasource: null
Non JTA datasource: org.apache.commons.dbcp.BasicDataSource at 247510e7
Transaction type: RESOURCE_LOCAL
PU root URL: file:/C:/testSource/platform/process-flow/process-flow-service/target/classes/
Jar files URLs []
Managed classes names [
org.drools.persistence.session.SessionInfo
org.drools.persistence.processinstance.ProcessInstanceInfo
org.drools.persistence.processinstance.variabletypes.JPAPersistedVariable
org.drools.persistence.processinstance.variabletypes.VariableInstanceInfo
org.drools.persistence.processinstance.variabletypes.SerializablePersistedVariable
org.drools.persistence.processinstance.WorkItemInfo]
Mapping files names []
Properties [
hibernate.max_fetch_depth: 3
hibernate.hbm2ddl.auto: create]
12:03:16.491 [pool-1-thread-1] DEBUG org.hibernate.ejb.Ejb3Configuration - Detect class: true; detect hbm: true
12:03:16.491 [pool-1-thread-1] DEBUG org.hibernate.ejb.Ejb3Configuration - Detect class: true; detect hbm: true
12:03:16.491 [pool-1-thread-1] DEBUG o.h.ejb.packaging.AbstractJarVisitor - Searching mapped entities in jar/par: file:/C:/testSource/platform/process-flow/process-flow-service/target/classes/
12:03:16.491 [pool-1-thread-1] DEBUG o.h.ejb.packaging.AbstractJarVisitor - Filtering: com.proferi.process.drools.CustomRuleFlowProcessFactory
12:03:16.491 [pool-1-thread-1] DEBUG o.h.ejb.packaging.AbstractJarVisitor - Filtering: com.proferi.process.drools.DroolsFlowAdapter$1
12:03:16.491 [pool-1-thread-1] DEBUG o.h.ejb.packaging.AbstractJarVisitor - Filtering: com.proferi.process.drools.DroolsFlowAdapter
12:03:16.491 [pool-1-thread-1] DEBUG o.h.ejb.packaging.AbstractJarVisitor - Filtering: com.proferi.process.drools.DroolsStepNode
12:03:16.491 [pool-1-thread-1] DEBUG o.h.ejb.packaging.AbstractJarVisitor - Filtering: com.proferi.process.drools.ProcessEventListener
12:03:16.491 [pool-1-thread-1] DEBUG o.h.ejb.packaging.AbstractJarVisitor - Filtering: com.proferi.process.drools.proxies.ConnectionProxy
12:03:16.491 [pool-1-thread-1] DEBUG o.h.ejb.packaging.AbstractJarVisitor - Filtering: com.proferi.process.drools.proxies.DroolsNodeProxy
12:03:16.491 [pool-1-thread-1] DEBUG o.h.ejb.packaging.AbstractJarVisitor - Filtering: com.proferi.process.drools.proxies.DroolsNodeProxyImpl
12:03:16.491 [pool-1-thread-1] DEBUG o.h.ejb.packaging.AbstractJarVisitor - Filtering: com.proferi.process.drools.proxies.EndProxy
12:03:16.491 [pool-1-thread-1] DEBUG o.h.ejb.packaging.AbstractJarVisitor - Filtering: com.proferi.process.drools.proxies.ImpliedJoinProxy
12:03:16.491 [pool-1-thread-1] DEBUG o.h.ejb.packaging.AbstractJarVisitor - Filtering: com.proferi.process.drools.proxies.ImpliedSplitProxy$1
12:03:16.507 [pool-1-thread-1] DEBUG o.h.ejb.packaging.AbstractJarVisitor - Filtering: com.proferi.process.drools.proxies.ImpliedSplitProxy
12:03:16.507 [pool-1-thread-1] DEBUG o.h.ejb.packaging.AbstractJarVisitor - Filtering: com.proferi.process.drools.proxies.ImpliedStepProxy
12:03:16.507 [pool-1-thread-1] DEBUG o.h.ejb.packaging.AbstractJarVisitor - Filtering: com.proferi.process.drools.proxies.Joiner
12:03:16.507 [pool-1-thread-1] DEBUG o.h.ejb.packaging.AbstractJarVisitor - Filtering: com.proferi.process.drools.proxies.JoinProxy$1
12:03:16.507 [pool-1-thread-1] DEBUG o.h.ejb.packaging.AbstractJarVisitor - Filtering: com.proferi.process.drools.proxies.JoinProxy
12:03:16.507 [pool-1-thread-1] DEBUG o.h.ejb.packaging.AbstractJarVisitor - Filtering: com.proferi.process.drools.proxies.NodeWrapper
12:03:16.507 [pool-1-thread-1] DEBUG o.h.ejb.packaging.AbstractJarVisitor - Filtering: com.proferi.process.drools.proxies.ProxyFactory$1
12:03:16.507 [pool-1-thread-1] DEBUG o.h.ejb.packaging.AbstractJarVisitor - Filtering: com.proferi.process.drools.proxies.ProxyFactory
12:03:16.507 [pool-1-thread-1] DEBUG o.h.ejb.packaging.AbstractJarVisitor - Filtering: com.proferi.process.drools.proxies.ProxyType
12:03:16.507 [pool-1-thread-1] DEBUG o.h.ejb.packaging.AbstractJarVisitor - Filtering: com.proferi.process.drools.proxies.SliceEndProxy$1
12:03:16.507 [pool-1-thread-1] DEBUG o.h.ejb.packaging.AbstractJarVisitor - Filtering: com.proferi.process.drools.proxies.SliceEndProxy
12:03:16.507 [pool-1-thread-1] DEBUG o.h.ejb.packaging.AbstractJarVisitor - Filtering: com.proferi.process.drools.proxies.SliceStartProxy
12:03:16.507 [pool-1-thread-1] DEBUG o.h.ejb.packaging.AbstractJarVisitor - Filtering: com.proferi.process.drools.proxies.SplitProxy$1
12:03:16.507 [pool-1-thread-1] DEBUG o.h.ejb.packaging.AbstractJarVisitor - Filtering: com.proferi.process.drools.proxies.SplitProxy
12:03:16.507 [pool-1-thread-1] DEBUG o.h.ejb.packaging.AbstractJarVisitor - Filtering: com.proferi.process.drools.proxies.Splitter
12:03:16.507 [pool-1-thread-1] DEBUG o.h.ejb.packaging.AbstractJarVisitor - Filtering: com.proferi.process.drools.proxies.StartProxy
12:03:16.507 [pool-1-thread-1] DEBUG o.h.ejb.packaging.AbstractJarVisitor - Filtering: com.proferi.process.drools.proxies.StateProxy
12:03:16.507 [pool-1-thread-1] DEBUG o.h.ejb.packaging.AbstractJarVisitor - Filtering: com.proferi.process.drools.proxies.StepProxy
12:03:16.507 [pool-1-thread-1] DEBUG o.h.ejb.packaging.AbstractJarVisitor - Filtering: com.proferi.process.drools.proxies.WaitProxy
12:03:16.507 [pool-1-thread-1] DEBUG o.h.ejb.packaging.AbstractJarVisitor - Filtering: com.proferi.process.drools.proxies.WrappingDroolsNodeProxyImpl
12:03:16.507 [pool-1-thread-1] DEBUG o.h.ejb.packaging.AbstractJarVisitor - Filtering: com.proferi.process.drools.ProxyBuilder
12:03:16.507 [pool-1-thread-1] DEBUG o.h.ejb.packaging.AbstractJarVisitor - Filtering: com.proferi.process.drools.StateNodeFactory
12:03:16.507 [pool-1-thread-1] DEBUG o.h.ejb.packaging.AbstractJarVisitor - Filtering: com.proferi.process.drools.StepNodeFactory
12:03:16.507 [pool-1-thread-1] DEBUG o.h.ejb.packaging.AbstractJarVisitor - Filtering: com.proferi.process.drools.StepWorkItemHandler
12:03:16.507 [pool-1-thread-1] DEBUG o.h.ejb.packaging.AbstractJarVisitor - Filtering: com.proferi.process.drools.UuidDataType
12:03:16.507 [pool-1-thread-1] DEBUG o.h.ejb.packaging.AbstractJarVisitor - Filtering: com.proferi.process.instances.EventNodeInstance
12:03:16.507 [pool-1-thread-1] DEBUG o.h.ejb.packaging.AbstractJarVisitor - Filtering: com.proferi.process.instances.ImpliedStepNodeInstance
12:03:16.507 [pool-1-thread-1] DEBUG o.h.ejb.packaging.AbstractJarVisitor - Filtering: com.proferi.process.instances.NodeInstance$StatusType
12:03:16.507 [pool-1-thread-1] DEBUG o.h.ejb.packaging.AbstractJarVisitor - Filtering: com.proferi.process.instances.NodeInstance
12:03:16.507 [pool-1-thread-1] DEBUG o.h.ejb.packaging.AbstractJarVisitor - Filtering: com.proferi.process.instances.ProcessFlowInstance$StatusType
12:03:16.507 [pool-1-thread-1] DEBUG o.h.ejb.packaging.AbstractJarVisitor - Filtering: com.proferi.process.instances.ProcessFlowInstance
12:03:16.507 [pool-1-thread-1] DEBUG o.h.ejb.packaging.AbstractJarVisitor - Filtering: com.proferi.process.instances.ProcessObjectInstance
12:03:16.507 [pool-1-thread-1] DEBUG o.h.ejb.packaging.AbstractJarVisitor - Filtering: com.proferi.process.instances.StepNodeInstance
12:03:16.507 [pool-1-thread-1] DEBUG o.h.ejb.packaging.AbstractJarVisitor - Filtering: com.proferi.process.manager.ExternalEvent
12:03:16.507 [pool-1-thread-1] DEBUG o.h.ejb.packaging.AbstractJarVisitor - Filtering: com.proferi.process.manager.ProcessFlowManager
12:03:16.507 [pool-1-thread-1] DEBUG o.h.ejb.packaging.AbstractJarVisitor - Filtering: com.proferi.process.manager.StepActivationCallbackHandler
12:03:16.507 [pool-1-thread-1] DEBUG o.h.ejb.packaging.AbstractJarVisitor - Filtering: com.proferi.process.manager.StepApproval
12:03:16.507 [pool-1-thread-1] DEBUG o.h.ejb.packaging.AbstractJarVisitor - Filtering: com.proferi.process.manager.Terminator
12:03:16.507 [pool-1-thread-1] DEBUG o.h.ejb.packaging.AbstractJarVisitor - Filtering: com.proferi.process.message.AsyncStepActivationCallbackHandler
12:03:16.507 [pool-1-thread-1] DEBUG o.h.ejb.packaging.AbstractJarVisitor - Filtering: com.proferi.process.message.JmsProcessFlowMessageProducer
12:03:16.507 [pool-1-thread-1] DEBUG o.h.ejb.packaging.AbstractJarVisitor - Filtering: com.proferi.process.message.ProcessFlowMessageConsumer
12:03:16.507 [pool-1-thread-1] DEBUG o.h.ejb.packaging.AbstractJarVisitor - Filtering: com.proferi.process.message.ProcessFlowMessageProducer
12:03:16.507 [pool-1-thread-1] DEBUG o.h.ejb.packaging.AbstractJarVisitor - Filtering: com.proferi.process.service.ApprovalCompletedServiceHandler
12:03:16.507 [pool-1-thread-1] DEBUG o.h.ejb.packaging.AbstractJarVisitor - Filtering: com.proferi.process.service.GetProcessFlowStatusServiceHandler
12:03:16.507 [pool-1-thread-1] DEBUG o.h.ejb.packaging.AbstractJarVisitor - Filtering: com.proferi.process.service.ProcessFlowServiceUtils$1
12:03:16.507 [pool-1-thread-1] DEBUG o.h.ejb.packaging.AbstractJarVisitor - Filtering: com.proferi.process.service.ProcessFlowServiceUtils
12:03:16.507 [pool-1-thread-1] DEBUG o.h.ejb.packaging.AbstractJarVisitor - Filtering: com.proferi.process.service.StartProcessFlowServiceHandler
12:03:16.507 [pool-1-thread-1] DEBUG o.h.ejb.packaging.AbstractJarVisitor - Filtering: com.proferi.process.service.StepCompletedServiceHandler
12:03:16.507 [pool-1-thread-1] DEBUG o.h.ejb.packaging.AbstractJarVisitor - Filtering: com.proferi.process.utils.ApprovedStepNodeSupport
12:03:16.507 [pool-1-thread-1] DEBUG o.h.ejb.packaging.AbstractJarVisitor - Filtering: com.proferi.process.utils.StepNodeSupport
12:03:16.507 [pool-1-thread-1] DEBUG o.h.ejb.packaging.AbstractJarVisitor - File Filter matched for META-INF/orm.xml
12:03:16.523 [pool-1-thread-1] DEBUG org.hibernate.util.DTDEntityResolver - trying to resolve system-id [file:///C:/testSource/platform/process-flow/process-flow-service/orm_1_0.xsd]
12:03:16.523 [pool-1-thread-1] DEBUG o.h.cfg.EJB3DTDEntityResolver - recognized EJB3 ORM namespace; attempting to resolve on classpath under org/hibernate/ejb
12:03:16.523 [pool-1-thread-1] DEBUG o.h.cfg.EJB3DTDEntityResolver - located [file:///C:/testSource/platform/process-flow/process-flow-service/orm_1_0.xsd] in classpath
12:03:16.523 [pool-1-thread-1] DEBUG o.h.cfg.AnnotationConfiguration - Execute first pass mapping processing
12:03:16.523 [pool-1-thread-1] INFO o.h.cfg.annotations.QueryBinder - Binding Named query: ProcessInstancesWaitingForEvent => select processInstanceInfo.processInstanceId from ProcessInstanceInfo processInstanceInfo where :type in elements(processInstanceInfo.eventTypes)
12:03:16.523 [pool-1-thread-1] DEBUG o.h.cfg.AnnotationConfiguration - Process hbm files
12:03:16.523 [pool-1-thread-1] DEBUG o.h.cfg.AnnotationConfiguration - Process annotated classes
12:03:16.523 [pool-1-thread-1] INFO org.hibernate.cfg.AnnotationBinder - Binding entity from annotated class: org.drools.persistence.session.SessionInfo
12:03:16.523 [pool-1-thread-1] DEBUG org.hibernate.cfg.Ejb3Column - Binding column DTYPE. Unique false. Nullable false.
12:03:16.523 [pool-1-thread-1] DEBUG o.h.cfg.annotations.EntityBinder - Import with entity name SessionInfo
12:03:16.523 [pool-1-thread-1] INFO o.h.cfg.annotations.EntityBinder - Bind entity org.drools.persistence.session.SessionInfo on table SessionInfo
12:03:16.523 [pool-1-thread-1] DEBUG org.hibernate.cfg.AnnotationBinder - Processing org.drools.persistence.session.SessionInfo property annotation
12:03:16.523 [pool-1-thread-1] DEBUG org.hibernate.cfg.AnnotationBinder - Processing org.drools.persistence.session.SessionInfo field annotation
12:03:16.538 [pool-1-thread-1] DEBUG org.hibernate.cfg.AnnotationBinder - Processing annotations of org.drools.persistence.session.SessionInfo.id
12:03:16.538 [pool-1-thread-1] DEBUG org.hibernate.cfg.Ejb3Column - Binding column id. Unique false. Nullable false.
12:03:16.538 [pool-1-thread-1] DEBUG org.hibernate.cfg.AnnotationBinder - id is an id
12:03:16.538 [pool-1-thread-1] DEBUG o.h.c.annotations.SimpleValueBinder - building SimpleValue for id
12:03:16.538 [pool-1-thread-1] DEBUG o.h.cfg.annotations.PropertyBinder - Building property id
12:03:16.538 [pool-1-thread-1] DEBUG org.hibernate.cfg.AnnotationBinder - Bind @Id on id
12:03:16.538 [pool-1-thread-1] DEBUG org.hibernate.cfg.AnnotationBinder - Processing annotations of org.drools.persistence.session.SessionInfo.lastModificationDate
12:03:16.538 [pool-1-thread-1] DEBUG org.hibernate.cfg.Ejb3Column - Binding column lastModificationDate. Unique false. Nullable true.
12:03:16.538 [pool-1-thread-1] DEBUG o.h.cfg.annotations.PropertyBinder - binding property lastModificationDate with lazy=false
12:03:16.538 [pool-1-thread-1] DEBUG o.h.c.annotations.SimpleValueBinder - building SimpleValue for lastModificationDate
12:03:16.538 [pool-1-thread-1] DEBUG o.h.cfg.annotations.PropertyBinder - Building property lastModificationDate
12:03:16.538 [pool-1-thread-1] DEBUG org.hibernate.cfg.AnnotationBinder - Processing annotations of org.drools.persistence.session.SessionInfo.rulesByteArray
12:03:16.538 [pool-1-thread-1] DEBUG org.hibernate.cfg.Ejb3Column - Binding column rulesByteArray. Unique false. Nullable true.
12:03:16.538 [pool-1-thread-1] DEBUG o.h.cfg.annotations.PropertyBinder - binding property rulesByteArray with lazy=false
12:03:16.538 [pool-1-thread-1] DEBUG o.h.c.annotations.SimpleValueBinder - building SimpleValue for rulesByteArray
12:03:16.538 [pool-1-thread-1] DEBUG o.h.cfg.annotations.PropertyBinder - Building property rulesByteArray
12:03:16.538 [pool-1-thread-1] DEBUG org.hibernate.cfg.AnnotationBinder - Processing annotations of org.drools.persistence.session.SessionInfo.startDate
12:03:16.538 [pool-1-thread-1] DEBUG org.hibernate.cfg.Ejb3Column - Binding column startDate. Unique false. Nullable true.
12:03:16.538 [pool-1-thread-1] DEBUG o.h.cfg.annotations.PropertyBinder - binding property startDate with lazy=false
12:03:16.538 [pool-1-thread-1] DEBUG o.h.c.annotations.SimpleValueBinder - building SimpleValue for startDate
12:03:16.538 [pool-1-thread-1] DEBUG o.h.cfg.annotations.PropertyBinder - Building property startDate
12:03:16.538 [pool-1-thread-1] DEBUG org.hibernate.cfg.AnnotationBinder - Processing annotations of org.drools.persistence.session.SessionInfo.version
12:03:16.538 [pool-1-thread-1] DEBUG org.hibernate.cfg.Ejb3Column - Binding column OPTLOCK. Unique false. Nullable true.
12:03:16.538 [pool-1-thread-1] DEBUG org.hibernate.cfg.AnnotationBinder - version is a version property
12:03:16.538 [pool-1-thread-1] DEBUG o.h.cfg.annotations.PropertyBinder - binding property version with lazy=false
12:03:16.538 [pool-1-thread-1] DEBUG o.h.c.annotations.SimpleValueBinder - building SimpleValue for version
12:03:16.538 [pool-1-thread-1] DEBUG o.h.cfg.annotations.PropertyBinder - Building property version
12:03:16.538 [pool-1-thread-1] DEBUG org.hibernate.cfg.AnnotationBinder - Version name: version, unsavedValue: undefined
12:03:16.538 [pool-1-thread-1] INFO org.hibernate.cfg.AnnotationBinder - Binding entity from annotated class: org.drools.persistence.processinstance.ProcessInstanceInfo
12:03:16.538 [pool-1-thread-1] DEBUG org.hibernate.cfg.Ejb3Column - Binding column DTYPE. Unique false. Nullable false.
12:03:16.538 [pool-1-thread-1] DEBUG o.h.cfg.annotations.EntityBinder - Import with entity name ProcessInstanceInfo
12:03:16.538 [pool-1-thread-1] INFO o.h.cfg.annotations.EntityBinder - Bind entity org.drools.persistence.processinstance.ProcessInstanceInfo on table ProcessInstanceInfo
12:03:16.538 [pool-1-thread-1] DEBUG org.hibernate.cfg.AnnotationBinder - Processing org.drools.persistence.processinstance.ProcessInstanceInfo property annotation
12:03:16.538 [pool-1-thread-1] DEBUG org.hibernate.cfg.AnnotationBinder - Processing org.drools.persistence.processinstance.ProcessInstanceInfo field annotation
12:03:16.538 [pool-1-thread-1] DEBUG org.hibernate.cfg.AnnotationBinder - Processing annotations of org.drools.persistence.processinstance.ProcessInstanceInfo.processInstanceId
12:03:16.538 [pool-1-thread-1] DEBUG org.hibernate.cfg.Ejb3Column - Binding column InstanceId. Unique false. Nullable true.
12:03:16.538 [pool-1-thread-1] DEBUG org.hibernate.cfg.AnnotationBinder - processInstanceId is an id
12:03:16.538 [pool-1-thread-1] DEBUG o.h.c.annotations.SimpleValueBinder - building SimpleValue for processInstanceId
12:03:16.538 [pool-1-thread-1] DEBUG o.h.cfg.annotations.PropertyBinder - Building property processInstanceId
12:03:16.538 [pool-1-thread-1] DEBUG org.hibernate.cfg.AnnotationBinder - Bind @Id on processInstanceId
12:03:16.538 [pool-1-thread-1] DEBUG org.hibernate.cfg.AnnotationBinder - Processing annotations of org.drools.persistence.processinstance.ProcessInstanceInfo.eventTypes
12:03:16.538 [pool-1-thread-1] DEBUG org.hibernate.cfg.Ejb3Column - Binding column null. Unique false. Nullable true.
12:03:16.538 [pool-1-thread-1] DEBUG org.hibernate.cfg.Ejb3Column - Binding column eventTypes. Unique false. Nullable true.
12:03:16.538 [pool-1-thread-1] DEBUG org.hibernate.cfg.Ejb3Column - Binding column null. Unique false. Nullable true.
12:03:16.538 [pool-1-thread-1] DEBUG org.hibernate.cfg.Ejb3Column - Binding column element. Unique false. Nullable true.
12:03:16.538 [pool-1-thread-1] DEBUG org.hibernate.cfg.Ejb3Column - Binding column mapkey. Unique false. Nullable true.
12:03:16.538 [pool-1-thread-1] DEBUG org.hibernate.cfg.Ejb3Column - Binding column null. Unique false. Nullable true.
12:03:16.538 [pool-1-thread-1] DEBUG org.hibernate.cfg.Ejb3Column - Binding column InstanceId. Unique false. Nullable false.
12:03:16.538 [pool-1-thread-1] DEBUG org.hibernate.cfg.Ejb3Column - Binding column null. Unique false. Nullable false.
12:03:16.538 [pool-1-thread-1] DEBUG o.h.cfg.annotations.CollectionBinder - Collection role: org.drools.persistence.processinstance.ProcessInstanceInfo.eventTypes
12:03:16.538 [pool-1-thread-1] DEBUG o.h.cfg.annotations.PropertyBinder - Building property eventTypes
12:03:16.538 [pool-1-thread-1] DEBUG org.hibernate.cfg.AnnotationBinder - Processing annotations of org.drools.persistence.processinstance.ProcessInstanceInfo.externalVariables
12:03:16.538 [pool-1-thread-1] DEBUG org.hibernate.cfg.Ejb3Column - Binding column externalVariables. Unique false. Nullable false.
12:03:16.538 [pool-1-thread-1] DEBUG o.h.cfg.annotations.PropertyBinder - binding property externalVariables with lazy=false
12:03:16.538 [pool-1-thread-1] DEBUG o.h.c.annotations.SimpleValueBinder - building SimpleValue for externalVariables
12:03:16.538 [pool-1-thread-1] DEBUG o.h.cfg.annotations.PropertyBinder - Building property externalVariables
12:03:16.538 [pool-1-thread-1] DEBUG org.hibernate.cfg.AnnotationBinder - Processing annotations of org.drools.persistence.processinstance.ProcessInstanceInfo.lastModificationDate
12:03:16.538 [pool-1-thread-1] DEBUG org.hibernate.cfg.Ejb3Column - Binding column lastModificationDate. Unique false. Nullable true.
12:03:16.538 [pool-1-thread-1] DEBUG o.h.cfg.annotations.PropertyBinder - binding property lastModificationDate with lazy=false
12:03:16.538 [pool-1-thread-1] DEBUG o.h.c.annotations.SimpleValueBinder - building SimpleValue for lastModificationDate
12:03:16.538 [pool-1-thread-1] DEBUG o.h.cfg.annotations.PropertyBinder - Building property lastModificationDate
12:03:16.538 [pool-1-thread-1] DEBUG org.hibernate.cfg.AnnotationBinder - Processing annotations of org.drools.persistence.processinstance.ProcessInstanceInfo.lastReadDate
12:03:16.538 [pool-1-thread-1] DEBUG org.hibernate.cfg.Ejb3Column - Binding column lastReadDate. Unique false. Nullable true.
12:03:16.538 [pool-1-thread-1] DEBUG o.h.cfg.annotations.PropertyBinder - binding property lastReadDate with lazy=false
12:03:16.538 [pool-1-thread-1] DEBUG o.h.c.annotations.SimpleValueBinder - building SimpleValue for lastReadDate
12:03:16.538 [pool-1-thread-1] DEBUG o.h.cfg.annotations.PropertyBinder - Building property lastReadDate
12:03:16.538 [pool-1-thread-1] DEBUG org.hibernate.cfg.AnnotationBinder - Processing annotations of org.drools.persistence.processinstance.ProcessInstanceInfo.processId
12:03:16.538 [pool-1-thread-1] DEBUG org.hibernate.cfg.Ejb3Column - Binding column processId. Unique false. Nullable true.
12:03:16.538 [pool-1-thread-1] DEBUG o.h.cfg.annotations.PropertyBinder - binding property processId with lazy=false
12:03:16.538 [pool-1-thread-1] DEBUG o.h.c.annotations.SimpleValueBinder - building SimpleValue for processId
12:03:16.538 [pool-1-thread-1] DEBUG o.h.cfg.annotations.PropertyBinder - Building property processId
12:03:16.538 [pool-1-thread-1] DEBUG org.hibernate.cfg.AnnotationBinder - Processing annotations of org.drools.persistence.processinstance.ProcessInstanceInfo.processInstanceByteArray
12:03:16.538 [pool-1-thread-1] DEBUG org.hibernate.cfg.Ejb3Column - Binding column processInstanceByteArray. Unique false. Nullable true.
12:03:16.538 [pool-1-thread-1] DEBUG o.h.cfg.annotations.PropertyBinder - binding property processInstanceByteArray with lazy=false
12:03:16.538 [pool-1-thread-1] DEBUG o.h.c.annotations.SimpleValueBinder - building SimpleValue for processInstanceByteArray
12:03:16.538 [pool-1-thread-1] DEBUG o.h.cfg.annotations.PropertyBinder - Building property processInstanceByteArray
12:03:16.538 [pool-1-thread-1] DEBUG org.hibernate.cfg.AnnotationBinder - Processing annotations of org.drools.persistence.processinstance.ProcessInstanceInfo.startDate
12:03:16.538 [pool-1-thread-1] DEBUG org.hibernate.cfg.Ejb3Column - Binding column startDate. Unique false. Nullable true.
12:03:16.538 [pool-1-thread-1] DEBUG o.h.cfg.annotations.PropertyBinder - binding property startDate with lazy=false
12:03:16.538 [pool-1-thread-1] DEBUG o.h.c.annotations.SimpleValueBinder - building SimpleValue for startDate
12:03:16.538 [pool-1-thread-1] DEBUG o.h.cfg.annotations.PropertyBinder - Building property startDate
12:03:16.538 [pool-1-thread-1] DEBUG org.hibernate.cfg.AnnotationBinder - Processing annotations of org.drools.persistence.processinstance.ProcessInstanceInfo.state
12:03:16.538 [pool-1-thread-1] DEBUG org.hibernate.cfg.Ejb3Column - Binding column state. Unique false. Nullable false.
12:03:16.538 [pool-1-thread-1] DEBUG o.h.cfg.annotations.PropertyBinder - binding property state with lazy=false
12:03:16.538 [pool-1-thread-1] DEBUG o.h.c.annotations.SimpleValueBinder - building SimpleValue for state
12:03:16.538 [pool-1-thread-1] DEBUG o.h.cfg.annotations.PropertyBinder - Building property state
12:03:16.538 [pool-1-thread-1] DEBUG org.hibernate.cfg.AnnotationBinder - Processing annotations of org.drools.persistence.processinstance.ProcessInstanceInfo.variables
12:03:16.538 [pool-1-thread-1] DEBUG org.hibernate.cfg.Ejb3Column - Binding column processInstanceId. Unique false. Nullable true.
12:03:16.538 [pool-1-thread-1] DEBUG org.hibernate.cfg.Ejb3Column - Binding column variables. Unique false. Nullable true.
12:03:16.538 [pool-1-thread-1] DEBUG org.hibernate.cfg.Ejb3Column - Binding column null. Unique false. Nullable true.
12:03:16.538 [pool-1-thread-1] DEBUG org.hibernate.cfg.Ejb3Column - Binding column element. Unique false. Nullable true.
12:03:16.538 [pool-1-thread-1] DEBUG org.hibernate.cfg.Ejb3Column - Binding column mapkey. Unique false. Nullable true.
12:03:16.538 [pool-1-thread-1] DEBUG org.hibernate.cfg.Ejb3Column - Binding column null. Unique false. Nullable true.
12:03:16.538 [pool-1-thread-1] DEBUG org.hibernate.cfg.Ejb3Column - Binding column null. Unique false. Nullable false.
12:03:16.538 [pool-1-thread-1] DEBUG org.hibernate.cfg.Ejb3Column - Binding column null. Unique false. Nullable false.
12:03:16.538 [pool-1-thread-1] DEBUG o.h.cfg.annotations.CollectionBinder - Collection role: org.drools.persistence.processinstance.ProcessInstanceInfo.variables
12:03:16.538 [pool-1-thread-1] DEBUG o.h.cfg.annotations.PropertyBinder - Building property variables
12:03:16.538 [pool-1-thread-1] DEBUG org.hibernate.cfg.AnnotationBinder - Processing annotations of org.drools.persistence.processinstance.ProcessInstanceInfo.version
12:03:16.538 [pool-1-thread-1] DEBUG org.hibernate.cfg.Ejb3Column - Binding column OPTLOCK. Unique false. Nullable true.
12:03:16.538 [pool-1-thread-1] DEBUG org.hibernate.cfg.AnnotationBinder - version is a version property
12:03:16.538 [pool-1-thread-1] DEBUG o.h.cfg.annotations.PropertyBinder - binding property version with lazy=false
12:03:16.538 [pool-1-thread-1] DEBUG o.h.c.annotations.SimpleValueBinder - building SimpleValue for version
12:03:16.538 [pool-1-thread-1] DEBUG o.h.cfg.annotations.PropertyBinder - Building property version
12:03:16.538 [pool-1-thread-1] DEBUG org.hibernate.cfg.AnnotationBinder - Version name: version, unsavedValue: undefined
12:03:16.538 [pool-1-thread-1] INFO org.hibernate.cfg.AnnotationBinder - Binding entity from annotated class: org.drools.persistence.processinstance.variabletypes.VariableInstanceInfo
12:03:16.538 [pool-1-thread-1] DEBUG org.hibernate.cfg.Ejb3Column - Binding column TYPE. Unique false. Nullable false.
12:03:16.538 [pool-1-thread-1] DEBUG o.h.cfg.annotations.EntityBinder - Import with entity name VariableInstanceInfo
12:03:16.538 [pool-1-thread-1] INFO o.h.cfg.annotations.EntityBinder - Bind entity org.drools.persistence.processinstance.variabletypes.VariableInstanceInfo on table VariableInstanceInfo
12:03:16.538 [pool-1-thread-1] DEBUG org.hibernate.cfg.AnnotationBinder - Setting discriminator for entity org.drools.persistence.processinstance.variabletypes.VariableInstanceInfo
12:03:16.538 [pool-1-thread-1] DEBUG org.hibernate.cfg.AnnotationBinder - Processing org.drools.persistence.processinstance.variabletypes.VariableInstanceInfo property annotation
12:03:16.538 [pool-1-thread-1] DEBUG org.hibernate.cfg.AnnotationBinder - Processing org.drools.persistence.processinstance.variabletypes.VariableInstanceInfo field annotation
12:03:16.538 [pool-1-thread-1] DEBUG org.hibernate.cfg.AnnotationBinder - Processing annotations of org.drools.persistence.processinstance.variabletypes.VariableInstanceInfo.id
12:03:16.538 [pool-1-thread-1] DEBUG org.hibernate.cfg.Ejb3Column - Binding column id. Unique false. Nullable true.
12:03:16.538 [pool-1-thread-1] DEBUG org.hibernate.cfg.AnnotationBinder - id is an id
12:03:16.538 [pool-1-thread-1] DEBUG o.h.c.annotations.SimpleValueBinder - building SimpleValue for id
12:03:16.538 [pool-1-thread-1] DEBUG o.h.cfg.annotations.PropertyBinder - Building property id
12:03:16.538 [pool-1-thread-1] DEBUG org.hibernate.cfg.AnnotationBinder - Bind @Id on id
12:03:16.538 [pool-1-thread-1] DEBUG org.hibernate.cfg.AnnotationBinder - Processing annotations of org.drools.persistence.processinstance.variabletypes.VariableInstanceInfo.name
12:03:16.538 [pool-1-thread-1] DEBUG org.hibernate.cfg.Ejb3Column - Binding column name. Unique false. Nullable true.
12:03:16.538 [pool-1-thread-1] DEBUG o.h.cfg.annotations.PropertyBinder - binding property name with lazy=false
12:03:16.538 [pool-1-thread-1] DEBUG o.h.c.annotations.SimpleValueBinder - building SimpleValue for name
12:03:16.538 [pool-1-thread-1] DEBUG o.h.cfg.annotations.PropertyBinder - Building property name
12:03:16.538 [pool-1-thread-1] DEBUG org.hibernate.cfg.AnnotationBinder - Processing annotations of org.drools.persistence.processinstance.variabletypes.VariableInstanceInfo.persister
12:03:16.538 [pool-1-thread-1] DEBUG org.hibernate.cfg.Ejb3Column - Binding column persister. Unique false. Nullable true.
12:03:16.538 [pool-1-thread-1] DEBUG o.h.cfg.annotations.PropertyBinder - binding property persister with lazy=false
12:03:16.538 [pool-1-thread-1] DEBUG o.h.c.annotations.SimpleValueBinder - building SimpleValue for persister
12:03:16.538 [pool-1-thread-1] DEBUG o.h.cfg.annotations.PropertyBinder - Building property persister
12:03:16.538 [pool-1-thread-1] DEBUG org.hibernate.cfg.AnnotationBinder - Processing annotations of org.drools.persistence.processinstance.variabletypes.VariableInstanceInfo.processInstanceId
12:03:16.538 [pool-1-thread-1] DEBUG org.hibernate.cfg.Ejb3Column - Binding column processInstanceId. Unique false. Nullable true.
12:03:16.538 [pool-1-thread-1] DEBUG o.h.cfg.annotations.PropertyBinder - binding property processInstanceId with lazy=false
12:03:16.538 [pool-1-thread-1] DEBUG o.h.c.annotations.SimpleValueBinder - building SimpleValue for processInstanceId
12:03:16.538 [pool-1-thread-1] DEBUG o.h.cfg.annotations.PropertyBinder - Building property processInstanceId
12:03:16.538 [pool-1-thread-1] DEBUG org.hibernate.cfg.AnnotationBinder - Processing annotations of org.drools.persistence.processinstance.variabletypes.VariableInstanceInfo.workItemId
12:03:16.538 [pool-1-thread-1] DEBUG org.hibernate.cfg.Ejb3Column - Binding column workItemId. Unique false. Nullable true.
12:03:16.538 [pool-1-thread-1] DEBUG o.h.cfg.annotations.PropertyBinder - binding property workItemId with lazy=false
12:03:16.538 [pool-1-thread-1] DEBUG o.h.c.annotations.SimpleValueBinder - building SimpleValue for workItemId
12:03:16.538 [pool-1-thread-1] DEBUG o.h.cfg.annotations.PropertyBinder - Building property workItemId
12:03:16.538 [pool-1-thread-1] INFO org.hibernate.cfg.AnnotationBinder - Binding entity from annotated class: org.drools.persistence.processinstance.variabletypes.JPAPersistedVariable
12:03:16.538 [pool-1-thread-1] DEBUG o.h.cfg.annotations.EntityBinder - Import with entity name JPAPersistedVariable
12:03:16.538 [pool-1-thread-1] DEBUG org.hibernate.cfg.AnnotationBinder - Processing org.drools.persistence.processinstance.variabletypes.JPAPersistedVariable field annotation
12:03:16.538 [pool-1-thread-1] DEBUG org.hibernate.cfg.AnnotationBinder - Processing annotations of org.drools.persistence.processinstance.variabletypes.JPAPersistedVariable.entityClass
12:03:16.538 [pool-1-thread-1] DEBUG org.hibernate.cfg.Ejb3Column - Binding column entityClass. Unique false. Nullable true.
12:03:16.538 [pool-1-thread-1] DEBUG o.h.cfg.annotations.PropertyBinder - binding property entityClass with lazy=false
12:03:16.538 [pool-1-thread-1] DEBUG o.h.c.annotations.SimpleValueBinder - building SimpleValue for entityClass
12:03:16.538 [pool-1-thread-1] DEBUG o.h.cfg.annotations.PropertyBinder - Building property entityClass
12:03:16.538 [pool-1-thread-1] DEBUG org.hibernate.cfg.AnnotationBinder - Processing annotations of org.drools.persistence.processinstance.variabletypes.JPAPersistedVariable.entityId
12:03:16.538 [pool-1-thread-1] DEBUG org.hibernate.cfg.Ejb3Column - Binding column entityId. Unique false. Nullable true.
12:03:16.538 [pool-1-thread-1] DEBUG o.h.cfg.annotations.PropertyBinder - binding property entityId with lazy=false
12:03:16.538 [pool-1-thread-1] DEBUG o.h.c.annotations.SimpleValueBinder - building SimpleValue for entityId
12:03:16.538 [pool-1-thread-1] DEBUG o.h.cfg.annotations.PropertyBinder - Building property entityId
12:03:16.538 [pool-1-thread-1] INFO org.hibernate.cfg.AnnotationBinder - Binding entity from annotated class: org.drools.persistence.processinstance.variabletypes.SerializablePersistedVariable
12:03:16.538 [pool-1-thread-1] DEBUG o.h.cfg.annotations.EntityBinder - Import with entity name SerializablePersistedVariable
12:03:16.538 [pool-1-thread-1] DEBUG org.hibernate.cfg.AnnotationBinder - Processing org.drools.persistence.processinstance.variabletypes.SerializablePersistedVariable field annotation
12:03:16.538 [pool-1-thread-1] DEBUG org.hibernate.cfg.AnnotationBinder - Processing annotations of org.drools.persistence.processinstance.variabletypes.SerializablePersistedVariable.content
12:03:16.538 [pool-1-thread-1] DEBUG org.hibernate.cfg.Ejb3Column - Binding column content. Unique false. Nullable true.
12:03:16.538 [pool-1-thread-1] DEBUG o.h.cfg.annotations.PropertyBinder - binding property content with lazy=false
12:03:16.538 [pool-1-thread-1] DEBUG o.h.c.annotations.SimpleValueBinder - building SimpleValue for content
12:03:16.538 [pool-1-thread-1] DEBUG o.h.cfg.annotations.PropertyBinder - Building property content
12:03:16.538 [pool-1-thread-1] INFO org.hibernate.cfg.AnnotationBinder - Binding entity from annotated class: org.drools.persistence.processinstance.WorkItemInfo
12:03:16.538 [pool-1-thread-1] DEBUG org.hibernate.cfg.Ejb3Column - Binding column DTYPE. Unique false. Nullable false.
12:03:16.538 [pool-1-thread-1] DEBUG o.h.cfg.annotations.EntityBinder - Import with entity name WorkItemInfo
12:03:16.538 [pool-1-thread-1] INFO o.h.cfg.annotations.EntityBinder - Bind entity org.drools.persistence.processinstance.WorkItemInfo on table WorkItemInfo
12:03:16.538 [pool-1-thread-1] DEBUG org.hibernate.cfg.AnnotationBinder - Processing org.drools.persistence.processinstance.WorkItemInfo property annotation
12:03:16.538 [pool-1-thread-1] DEBUG org.hibernate.cfg.AnnotationBinder - Processing org.drools.persistence.processinstance.WorkItemInfo field annotation
12:03:16.538 [pool-1-thread-1] DEBUG org.hibernate.cfg.AnnotationBinder - Processing annotations of org.drools.persistence.processinstance.WorkItemInfo.workItemId
12:03:16.538 [pool-1-thread-1] DEBUG org.hibernate.cfg.Ejb3Column - Binding column workItemId. Unique false. Nullable false.
12:03:16.538 [pool-1-thread-1] DEBUG org.hibernate.cfg.AnnotationBinder - workItemId is an id
12:03:16.538 [pool-1-thread-1] DEBUG o.h.c.annotations.SimpleValueBinder - building SimpleValue for workItemId
12:03:16.538 [pool-1-thread-1] DEBUG o.h.cfg.annotations.PropertyBinder - Building property workItemId
12:03:16.538 [pool-1-thread-1] DEBUG org.hibernate.cfg.AnnotationBinder - Bind @Id on workItemId
12:03:16.538 [pool-1-thread-1] DEBUG org.hibernate.cfg.AnnotationBinder - Processing annotations of org.drools.persistence.processinstance.WorkItemInfo.creationDate
12:03:16.538 [pool-1-thread-1] DEBUG org.hibernate.cfg.Ejb3Column - Binding column creationDate. Unique false. Nullable true.
12:03:16.538 [pool-1-thread-1] DEBUG o.h.cfg.annotations.PropertyBinder - binding property creationDate with lazy=false
12:03:16.538 [pool-1-thread-1] DEBUG o.h.c.annotations.SimpleValueBinder - building SimpleValue for creationDate
12:03:16.538 [pool-1-thread-1] DEBUG o.h.cfg.annotations.PropertyBinder - Building property creationDate
12:03:16.538 [pool-1-thread-1] DEBUG org.hibernate.cfg.AnnotationBinder - Processing annotations of org.drools.persistence.processinstance.WorkItemInfo.externalVariables
12:03:16.538 [pool-1-thread-1] DEBUG org.hibernate.cfg.Ejb3Column - Binding column externalVariables. Unique false. Nullable false.
12:03:16.538 [pool-1-thread-1] DEBUG o.h.cfg.annotations.PropertyBinder - binding property externalVariables with lazy=false
12:03:16.538 [pool-1-thread-1] DEBUG o.h.c.annotations.SimpleValueBinder - building SimpleValue for externalVariables
12:03:16.538 [pool-1-thread-1] DEBUG o.h.cfg.annotations.PropertyBinder - Building property externalVariables
12:03:16.538 [pool-1-thread-1] DEBUG org.hibernate.cfg.AnnotationBinder - Processing annotations of org.drools.persistence.processinstance.WorkItemInfo.name
12:03:16.538 [pool-1-thread-1] DEBUG org.hibernate.cfg.Ejb3Column - Binding column name. Unique false. Nullable true.
12:03:16.538 [pool-1-thread-1] DEBUG o.h.cfg.annotations.PropertyBinder - binding property name with lazy=false
12:03:16.538 [pool-1-thread-1] DEBUG o.h.c.annotations.SimpleValueBinder - building SimpleValue for name
12:03:16.538 [pool-1-thread-1] DEBUG o.h.cfg.annotations.PropertyBinder - Building property name
12:03:16.538 [pool-1-thread-1] DEBUG org.hibernate.cfg.AnnotationBinder - Processing annotations of org.drools.persistence.processinstance.WorkItemInfo.processInstanceId
12:03:16.538 [pool-1-thread-1] DEBUG org.hibernate.cfg.Ejb3Column - Binding column processInstanceId. Unique false. Nullable false.
12:03:16.538 [pool-1-thread-1] DEBUG o.h.cfg.annotations.PropertyBinder - binding property processInstanceId with lazy=false
12:03:16.538 [pool-1-thread-1] DEBUG o.h.c.annotations.SimpleValueBinder - building SimpleValue for processInstanceId
12:03:16.538 [pool-1-thread-1] DEBUG o.h.cfg.annotations.PropertyBinder - Building property processInstanceId
12:03:16.538 [pool-1-thread-1] DEBUG org.hibernate.cfg.AnnotationBinder - Processing annotations of org.drools.persistence.processinstance.WorkItemInfo.state
12:03:16.538 [pool-1-thread-1] DEBUG org.hibernate.cfg.Ejb3Column - Binding column state. Unique false. Nullable false.
12:03:16.538 [pool-1-thread-1] DEBUG o.h.cfg.annotations.PropertyBinder - binding property state with lazy=false
12:03:16.538 [pool-1-thread-1] DEBUG o.h.c.annotations.SimpleValueBinder - building SimpleValue for state
12:03:16.538 [pool-1-thread-1] DEBUG o.h.cfg.annotations.PropertyBinder - Building property state
12:03:16.538 [pool-1-thread-1] DEBUG org.hibernate.cfg.AnnotationBinder - Processing annotations of org.drools.persistence.processinstance.WorkItemInfo.variables
12:03:16.538 [pool-1-thread-1] DEBUG org.hibernate.cfg.Ejb3Column - Binding column workItemId. Unique false. Nullable true.
12:03:16.538 [pool-1-thread-1] DEBUG org.hibernate.cfg.Ejb3Column - Binding column variables. Unique false. Nullable true.
12:03:16.538 [pool-1-thread-1] DEBUG org.hibernate.cfg.Ejb3Column - Binding column null. Unique false. Nullable true.
12:03:16.538 [pool-1-thread-1] DEBUG org.hibernate.cfg.Ejb3Column - Binding column element. Unique false. Nullable true.
12:03:16.538 [pool-1-thread-1] DEBUG org.hibernate.cfg.Ejb3Column - Binding column mapkey. Unique false. Nullable true.
12:03:16.538 [pool-1-thread-1] DEBUG org.hibernate.cfg.Ejb3Column - Binding column null. Unique false. Nullable true.
12:03:16.538 [pool-1-thread-1] DEBUG org.hibernate.cfg.Ejb3Column - Binding column null. Unique false. Nullable false.
12:03:16.538 [pool-1-thread-1] DEBUG org.hibernate.cfg.Ejb3Column - Binding column null. Unique false. Nullable false.
12:03:16.538 [pool-1-thread-1] DEBUG o.h.cfg.annotations.CollectionBinder - Collection role: org.drools.persistence.processinstance.WorkItemInfo.variables
12:03:16.554 [pool-1-thread-1] DEBUG o.h.cfg.annotations.PropertyBinder - Building property variables
12:03:16.554 [pool-1-thread-1] DEBUG org.hibernate.cfg.AnnotationBinder - Processing annotations of org.drools.persistence.processinstance.WorkItemInfo.version
12:03:16.554 [pool-1-thread-1] DEBUG org.hibernate.cfg.Ejb3Column - Binding column OPTLOCK. Unique false. Nullable true.
12:03:16.554 [pool-1-thread-1] DEBUG org.hibernate.cfg.AnnotationBinder - version is a version property
12:03:16.554 [pool-1-thread-1] DEBUG o.h.cfg.annotations.PropertyBinder - binding property version with lazy=false
12:03:16.554 [pool-1-thread-1] DEBUG o.h.c.annotations.SimpleValueBinder - building SimpleValue for version
12:03:16.554 [pool-1-thread-1] DEBUG o.h.cfg.annotations.PropertyBinder - Building property version
12:03:16.554 [pool-1-thread-1] DEBUG org.hibernate.cfg.AnnotationBinder - Version name: version, unsavedValue: undefined
12:03:16.554 [pool-1-thread-1] DEBUG org.hibernate.cfg.AnnotationBinder - Processing annotations of org.drools.persistence.processinstance.WorkItemInfo.workItemByteArray
12:03:16.554 [pool-1-thread-1] DEBUG org.hibernate.cfg.Ejb3Column - Binding column workItemByteArray. Unique false. Nullable true.
12:03:16.554 [pool-1-thread-1] DEBUG o.h.cfg.annotations.PropertyBinder - binding property workItemByteArray with lazy=false
12:03:16.554 [pool-1-thread-1] DEBUG o.h.c.annotations.SimpleValueBinder - building SimpleValue for workItemByteArray
12:03:16.554 [pool-1-thread-1] DEBUG o.h.cfg.annotations.PropertyBinder - Building property workItemByteArray
12:03:16.554 [pool-1-thread-1] DEBUG o.h.cfg.AnnotationConfiguration - processing fk mappings (*ToOne and JoinedSubclass)
12:03:16.554 [pool-1-thread-1] DEBUG org.hibernate.cfg.Configuration - processing extends queue
12:03:16.554 [pool-1-thread-1] DEBUG org.hibernate.cfg.Configuration - processing collection mappings
12:03:16.554 [pool-1-thread-1] DEBUG o.hibernate.cfg.CollectionSecondPass - Second pass for collection: org.drools.persistence.processinstance.WorkItemInfo.variables
12:03:16.554 [pool-1-thread-1] DEBUG o.h.cfg.annotations.CollectionBinder - Binding a OneToMany: org.drools.persistence.processinstance.WorkItemInfo.variables through a foreign key
12:03:16.554 [pool-1-thread-1] INFO o.h.cfg.annotations.CollectionBinder - Mapping collection: org.drools.persistence.processinstance.WorkItemInfo.variables -> VariableInstanceInfo
12:03:16.554 [pool-1-thread-1] DEBUG o.hibernate.cfg.CollectionSecondPass - Mapped collection key: workItemId, index: name, one-to-many: org.drools.persistence.processinstance.variabletypes.VariableInstanceInfo
12:03:16.554 [pool-1-thread-1] DEBUG o.hibernate.cfg.CollectionSecondPass - Second pass for collection: org.drools.persistence.processinstance.ProcessInstanceInfo.variables
12:03:16.554 [pool-1-thread-1] DEBUG o.h.cfg.annotations.CollectionBinder - Binding a OneToMany: org.drools.persistence.processinstance.ProcessInstanceInfo.variables through a foreign key
12:03:16.554 [pool-1-thread-1] INFO o.h.cfg.annotations.CollectionBinder - Mapping collection: org.drools.persistence.processinstance.ProcessInstanceInfo.variables -> VariableInstanceInfo
12:03:16.554 [pool-1-thread-1] DEBUG o.hibernate.cfg.CollectionSecondPass - Mapped collection key: processInstanceId, index: name, one-to-many: org.drools.persistence.processinstance.variabletypes.VariableInstanceInfo
12:03:16.554 [pool-1-thread-1] DEBUG o.hibernate.cfg.CollectionSecondPass - Second pass for collection: org.drools.persistence.processinstance.ProcessInstanceInfo.eventTypes
12:03:16.554 [pool-1-thread-1] DEBUG o.h.cfg.annotations.CollectionBinder - Binding a collection of element: org.drools.persistence.processinstance.ProcessInstanceInfo.eventTypes
12:03:16.554 [pool-1-thread-1] DEBUG o.h.c.annotations.SimpleValueBinder - building SimpleValue for null
12:03:16.554 [pool-1-thread-1] DEBUG o.hibernate.cfg.CollectionSecondPass - Mapped collection key: InstanceId, element: element
12:03:16.554 [pool-1-thread-1] DEBUG org.hibernate.cfg.Configuration - processing native query and ResultSetMapping mappings
12:03:16.554 [pool-1-thread-1] DEBUG org.hibernate.cfg.Configuration - processing association property references
12:03:16.554 [pool-1-thread-1] DEBUG org.hibernate.cfg.Configuration - processing foreign key constraints
12:03:16.554 [pool-1-thread-1] DEBUG org.hibernate.cfg.Configuration - resolving reference to class: org.drools.persistence.processinstance.ProcessInstanceInfo
12:03:16.554 [pool-1-thread-1] DEBUG org.hibernate.cfg.Configuration - resolving reference to class: org.drools.persistence.processinstance.WorkItemInfo
12:03:16.554 [pool-1-thread-1] DEBUG org.hibernate.cfg.Configuration - resolving reference to class: org.drools.persistence.processinstance.ProcessInstanceInfo
12:03:16.554 [pool-1-thread-1] INFO o.h.cfg.AnnotationConfiguration - Hibernate Validator not found: ignoring
12:03:16.554 [pool-1-thread-1] DEBUG o.h.ejb.event.CallbackResolver - Adding update as PreUpdate callback for entity org.drools.persistence.processinstance.WorkItemInfo.
12:03:16.554 [pool-1-thread-1] DEBUG o.h.ejb.event.CallbackResolver - Adding update as PrePersist callback for entity org.drools.persistence.session.SessionInfo.
12:03:16.554 [pool-1-thread-1] DEBUG o.h.ejb.event.CallbackResolver - Adding update as PreUpdate callback for entity org.drools.persistence.session.SessionInfo.
12:03:16.554 [pool-1-thread-1] DEBUG o.h.ejb.event.CallbackResolver - Adding update as PreUpdate callback for entity org.drools.persistence.processinstance.ProcessInstanceInfo.
12:03:16.554 [pool-1-thread-1] DEBUG org.hibernate.ejb.util.NamingHelper - No JNDI name configured for binding Ejb3Configuration
12:03:16.554 [pool-1-thread-1] DEBUG o.h.cfg.AnnotationConfiguration - Validator not present in classpath, ignoring event listener registration
12:03:16.554 [pool-1-thread-1] DEBUG o.h.c.s.HibernateSearchEventListenerRegister - Search not present in classpath, ignoring event listener registration.
12:03:16.554 [pool-1-thread-1] INFO o.h.c.s.HibernateSearchEventListenerRegister - Unable to find org.hibernate.search.event.FullTextIndexEventListener on the classpath. Hibernate Search is not enabled.
12:03:16.554 [pool-1-thread-1] DEBUG org.hibernate.cfg.Configuration - Preparing to build session factory with filters : {}
12:03:16.554 [pool-1-thread-1] DEBUG o.h.cfg.AnnotationConfiguration - Execute first pass mapping processing
12:03:16.554 [pool-1-thread-1] DEBUG o.h.cfg.AnnotationConfiguration - Process hbm files
12:03:16.554 [pool-1-thread-1] DEBUG o.h.cfg.AnnotationConfiguration - Process annotated classes
12:03:16.554 [pool-1-thread-1] DEBUG o.h.cfg.AnnotationConfiguration - processing fk mappings (*ToOne and JoinedSubclass)
12:03:16.554 [pool-1-thread-1] DEBUG org.hibernate.cfg.Configuration - processing extends queue
12:03:16.554 [pool-1-thread-1] DEBUG org.hibernate.cfg.Configuration - processing collection mappings
12:03:16.554 [pool-1-thread-1] DEBUG org.hibernate.cfg.Configuration - processing native query and ResultSetMapping mappings
12:03:16.554 [pool-1-thread-1] DEBUG org.hibernate.cfg.Configuration - processing association property references
12:03:16.554 [pool-1-thread-1] DEBUG org.hibernate.cfg.Configuration - processing foreign key constraints
12:03:16.554 [pool-1-thread-1] DEBUG org.hibernate.cfg.Configuration - resolving reference to class: org.drools.persistence.processinstance.ProcessInstanceInfo
12:03:16.554 [pool-1-thread-1] DEBUG org.hibernate.cfg.Configuration - resolving reference to class: org.drools.persistence.processinstance.WorkItemInfo
12:03:16.554 [pool-1-thread-1] DEBUG org.hibernate.cfg.Configuration - resolving reference to class: org.drools.persistence.processinstance.ProcessInstanceInfo
12:03:16.554 [pool-1-thread-1] INFO o.h.c.ConnectionProviderFactory - Initializing connection provider: org.hibernate.ejb.connection.InjectedDataSourceConnectionProvider
12:03:16.554 [pool-1-thread-1] INFO o.h.e.c.InjectedDataSourceConnectionProvider - Using provided datasource
12:03:16.554 [pool-1-thread-1] INFO org.hibernate.cfg.SettingsFactory - RDBMS: H2, version: 1.3.148 (2010-12-12)
12:03:16.554 [pool-1-thread-1] INFO org.hibernate.cfg.SettingsFactory - JDBC driver: H2 JDBC Driver, version: 1.3.148 (2010-12-12)
12:03:16.554 [pool-1-thread-1] INFO org.hibernate.dialect.Dialect - Using dialect: org.hibernate.dialect.H2Dialect
12:03:16.554 [pool-1-thread-1] INFO o.h.t.TransactionFactoryFactory - Transaction strategy: org.hibernate.transaction.JDBCTransactionFactory
12:03:16.554 [pool-1-thread-1] INFO o.h.t.TransactionManagerLookupFactory - No TransactionManagerLookup configured (in JTA environment, use of read-write or transactional second-level cache is not recommended)
12:03:16.554 [pool-1-thread-1] INFO org.hibernate.cfg.SettingsFactory - Automatic flush during beforeCompletion(): disabled
12:03:16.554 [pool-1-thread-1] INFO org.hibernate.cfg.SettingsFactory - Automatic session close at end of transaction: disabled
12:03:16.554 [pool-1-thread-1] INFO org.hibernate.cfg.SettingsFactory - JDBC batch size: 15
12:03:16.554 [pool-1-thread-1] INFO org.hibernate.cfg.SettingsFactory - JDBC batch updates for versioned data: disabled
12:03:16.554 [pool-1-thread-1] INFO org.hibernate.cfg.SettingsFactory - Scrollable result sets: enabled
12:03:16.554 [pool-1-thread-1] DEBUG org.hibernate.cfg.SettingsFactory - Wrap result sets: disabled
12:03:16.554 [pool-1-thread-1] INFO org.hibernate.cfg.SettingsFactory - JDBC3 getGeneratedKeys(): enabled
12:03:16.554 [pool-1-thread-1] INFO org.hibernate.cfg.SettingsFactory - Connection release mode: auto
12:03:16.554 [pool-1-thread-1] INFO org.hibernate.cfg.SettingsFactory - Maximum outer join fetch depth: 3
12:03:16.554 [pool-1-thread-1] INFO org.hibernate.cfg.SettingsFactory - Default batch fetch size: 1
12:03:16.554 [pool-1-thread-1] INFO org.hibernate.cfg.SettingsFactory - Generate SQL with comments: disabled
12:03:16.554 [pool-1-thread-1] INFO org.hibernate.cfg.SettingsFactory - Order SQL updates by primary key: disabled
12:03:16.554 [pool-1-thread-1] INFO org.hibernate.cfg.SettingsFactory - Order SQL inserts for batching: disabled
12:03:16.554 [pool-1-thread-1] INFO org.hibernate.cfg.SettingsFactory - Query translator: org.hibernate.hql.ast.ASTQueryTranslatorFactory
12:03:16.554 [pool-1-thread-1] INFO o.h.h.ast.ASTQueryTranslatorFactory - Using ASTQueryTranslatorFactory
12:03:16.554 [pool-1-thread-1] INFO org.hibernate.cfg.SettingsFactory - Query language substitutions: {}
12:03:16.554 [pool-1-thread-1] INFO org.hibernate.cfg.SettingsFactory - JPA-QL strict compliance: enabled
12:03:16.554 [pool-1-thread-1] INFO org.hibernate.cfg.SettingsFactory - Second-level cache: enabled
12:03:16.554 [pool-1-thread-1] INFO org.hibernate.cfg.SettingsFactory - Query cache: disabled
12:03:16.554 [pool-1-thread-1] INFO org.hibernate.cfg.SettingsFactory - Cache region factory : org.hibernate.cache.impl.NoCachingRegionFactory
12:03:16.554 [pool-1-thread-1] INFO org.hibernate.cfg.SettingsFactory - Optimize cache for minimal puts: disabled
12:03:16.554 [pool-1-thread-1] INFO org.hibernate.cfg.SettingsFactory - Structured second-level cache entries: disabled
12:03:16.554 [pool-1-thread-1] INFO org.hibernate.cfg.SettingsFactory - Statistics: disabled
12:03:16.554 [pool-1-thread-1] INFO org.hibernate.cfg.SettingsFactory - Deleted entity synthetic identifier rollback: disabled
12:03:16.554 [pool-1-thread-1] INFO org.hibernate.cfg.SettingsFactory - Default entity-mode: pojo
12:03:16.554 [pool-1-thread-1] INFO org.hibernate.cfg.SettingsFactory - Named query checking : enabled
12:03:16.569 [pool-1-thread-1] INFO o.hibernate.impl.SessionFactoryImpl - building session factory
12:03:16.569 [pool-1-thread-1] DEBUG o.hibernate.impl.SessionFactoryImpl - Session factory constructed with filter configurations : {}
12:03:16.569 [pool-1-thread-1] DEBUG o.hibernate.impl.SessionFactoryImpl - instantiating session factory with properties: {java.runtime.name=Java(TM) SE Runtime Environment, sun.boot.library.path=C:\Java\jdk1.6.0_20\jre\bin, java.vm.version=16.3-b01, java.vm.vendor=Sun Microsystems Inc., java.vendor.url=http://java.sun.com/, path.separator=;, java.vm.name=Java HotSpot(TM) 64-Bit Server VM, file.encoding.pkg=sun.io, user.country=US, sun.java.launcher=SUN_STANDARD, sun.os.patch.level=, java.vm.specification.name=Java Virtual Machine Specification, user.dir=C:\testSource\platform\process-flow\process-flow-service, java.runtime.version=1.6.0_20-b02, hibernate.ejb.discard_pc_on_close=false, java.awt.graphicsenv=sun.awt.Win32GraphicsEnvironment, basedir=C:\testSource\platform\process-flow\process-flow-service, java.endorsed.dirs=C:\Java\jdk1.6.0_20\jre\lib\endorsed, os.arch=amd64, surefire.real.class.path=C:\testSource\platform\process-flow\process-flow-service\target\surefire\surefirebooter8889461808117535765.jar, hibernate.connection.autocommit=true, java.io.tmpdir=C:\Users\brad\AppData\Local\Temp\, line.separator=
, java.vm.specification.vendor=Sun Microsystems Inc., user.variant=, os.name=Windows 7, sun.jnu.encoding=Cp1252, java.library.path=C:\Java\jdk1.6.0_20\jre\bin;.;C:\Windows\Sun\Java\bin;C:\Windows\system32;C:\Windows;C:\Program Files\Common Files\Microsoft Shared\Windows Live;C:\Program Files (x86)\Common Files\Microsoft Shared\Windows Live;C:\Windows\system32;C:\Windows;C:\Windows\System32\Wbem;C:\Windows\System32\WindowsPowerShell\v1.0\;C:\Program Files\ThinkPad\Bluetooth Software\;C:\Program Files\ThinkPad\Bluetooth Software\syswow64;C:\Program Files\Intel\WiFi\bin\;C:\Program Files\Common Files\Intel\WirelessCommon\;C:\Program Files (x86)\Common Files\Lenovo;C:\Program Files (x86)\Common Files\Ulead Systems\MPEG;C:\Program Files (x86)\Lenovo\Access Connections\;C:\Program Files\Common Files\Lenovo;C:\Program Files (x86)\Lenovo\Client Security Solution;C:\Program Files\Lenovo\Client Security Solution;C:\Program Files\TortoiseSVN\bin;C:\maven\apache-maven-3.0.2\bin;C:\Ant\apache-ant-1.8.1\bin;C:\XEmacs\XEmacs-21.4.22\i586-pc-win32;C:\UnxUtils\usr\local\wbin;C:\Program Files (x86)\Windows Live\Shared;C:\ProtoC;C:\Program Files (x86)\QuickTime\QTSystem\, surefire.test.class.path=C:\testSource\platform\process-flow\process-flow-service\target\test-classes;C:\testSource\platform\process-flow\process-flow-service\target\classes;C:\Users\brad\.m2\repository\com\proferi\platform\process\process-flow-protocol\0.0.1-SNAPSHOT\process-flow-protocol-0.0.1-SNAPSHOT.jar;C:\Users\brad\.m2\repository\com\google\guava\guava\r08\guava-r08.jar;C:\Users\brad\.m2\repository\com\google\protobuf\protobuf-java\2.3.0\protobuf-java-2.3.0.jar;C:\Users\brad\.m2\repository\com\proferi\platform\platformtypes\0.0.1-SNAPSHOT\platformtypes-0.0.1-SNAPSHOT.jar;C:\Users\brad\.m2\repository\com\proferi\platform\platformcore\0.0.1-SNAPSHOT\platformcore-0.0.1-SNAPSHOT.jar;C:\Users\brad\.m2\repository\com\linkedin\norbert\norbert-java-network\1.0.1-SNAPSHOT\norbert-java-network-1.0.1-SNAPSHOT.jar;C:\Users\brad\.m2\repository\com\linkedin\norbert\norbert-java-cluster\1.0.1-SNAPSHOT\norbert-java-cluster-1.0.1-SNAPSHOT.jar;C:\Users\brad\.m2\repository\com\linkedin\norbert\norbert-cluster\1.0.1-SNAPSHOT\norbert-cluster-1.0.1-SNAPSHOT.jar;C:\Users\brad\.m2\repository\org\apache\hadoop\zookeeper\3.3.0\zookeeper-3.3.0.jar;C:\Users\brad\.m2\repository\jline\jline\0.9.94\jline-0.9.94.jar;C:\Users\brad\.m2\repository\junit\junit\4.8.2\junit-4.8.2.jar;C:\Users\brad\.m2\repository\com\linkedin\norbert\norbert-network\1.0.1-SNAPSHOT\norbert-network-1.0.1-SNAPSHOT.jar;C:\Users\brad\.m2\repository\org\jboss\netty\netty\3.2.1.Final\netty-3.2.1.Final.jar;C:\Users\brad\.m2\repository\org\scala-lang\scala-library\2.8.1\scala-library-2.8.1.jar;C:\Users\brad\.m2\repository\org\springframework\spring-context\3.0.5.RELEASE\spring-context-3.0.5.RELEASE.jar;C:\Users\brad\.m2\repository\org\springframework\spring-expression\3.0.5.RELEASE\spring-expression-3.0.5.RELEASE.jar;C:\Users\brad\.m2\repository\org\springframework\spring-asm\3.0.5.RELEASE\spring-asm-3.0.5.RELEASE.jar;C:\Users\brad\.m2\repository\javax\jms\jms\1.1\jms-1.1.jar;C:\Users\brad\.m2\repository\org\apache\commons\commons-daemon\1.0.5\commons-daemon-1.0.5.jar;C:\Users\brad\.m2\repository\com\proferi\platform\utilities\0.0.1-SNAPSHOT\utilities-0.0.1-SNAPSHOT.jar;C:\Users\brad\.m2\repository\com\fasterxml\uuid\java-uuid-generator\3.1.0\java-uuid-generator-3.1.0.jar;C:\Users\brad\.m2\repository\org\slf4j\slf4j-api\1.6.1\slf4j-api-1.6.1.jar;C:\Users\brad\.m2\repository\ch\qos\logback\logback-core\0.9.28\logback-core-0.9.28.jar;C:\Users\brad\.m2\repository\ch\qos\logback\logback-classic\0.9.28\logback-classic-0.9.28.jar;C:\Users\brad\.m2\repository\org\slf4j\jcl-over-slf4j\1.6.1\jcl-over-slf4j-1.6.1.jar;C:\Users\brad\.m2\repository\org\slf4j\log4j-over-slf4j\1.6.1\log4j-over-slf4j-1.6.1.jar;C:\Users\brad\.m2\repository\com\proferi\platform\appmodel\0.0.1-SNAPSHOT\appmodel-0.0.1-SNAPSHOT.jar;C:\Users\brad\.m2\repository\commons-lang\commons-lang\2.5\commons-lang-2.5.jar;C:\Users\brad\.m2\repository\org\springframework\spring-beans\3.0.5.RELEASE\spring-beans-3.0.5.RELEASE.jar;C:\Users\brad\.m2\repository\xmlunit\xmlunit\1.3\xmlunit-1.3.jar;C:\Users\brad\.m2\repository\org\codehaus\btm\btm\1.3.2\btm-1.3.2.jar;C:\Users\brad\.m2\repository\org\apache\geronimo\specs\geronimo-jms_1.1_spec\1.0.1\geronimo-jms_1.1_spec-1.0.1.jar;C:\Users\brad\.m2\repository\org\apache\geronimo\specs\geronimo-jta_1.0.1B_spec\1.0.1\geronimo-jta_1.0.1B_spec-1.0.1.jar;C:\Users\brad\.m2\repository\org\drools\drools-core\5.1.1\drools-core-5.1.1.jar;C:\Users\brad\.m2\repository\org\mvel\mvel2\2.0.16\mvel2-2.0.16.jar;C:\Users\brad\.m2\repository\org\drools\drools-api\5.1.1\drools-api-5.1.1.jar;C:\Users\brad\.m2\repository\org\drools\drools-persistence-jpa\5.1.1\drools-persistence-jpa-5.1.1.jar;C:\Users\brad\.m2\repository\org\drools\drools-compiler\5.1.1\drools-compiler-5.1.1.jar;C:\Users\brad\.m2\repository\org\antlr\antlr-runtime\3.1.3\antlr-runtime-3.1.3.jar;C:\Users\brad\.m2\repository\org\eclipse\jdt\core\compiler\ecj\3.5.1\ecj-3.5.1.jar;C:\Users\brad\.m2\repository\org\hibernate\hibernate-entitymanager\3.4.0.GA\hibernate-entitymanager-3.4.0.GA.jar;C:\Users\brad\.m2\repository\org\hibernate\ejb3-persistence\1.0.2.GA\ejb3-persistence-1.0.2.GA.jar;C:\Users\brad\.m2\repository\org\hibernate\hibernate-annotations\3.4.0.GA\hibernate-annotations-3.4.0.GA.jar;C:\Users\brad\.m2\repository\org\hibernate\hibernate-commons-annotations\3.1.0.GA\hibernate-commons-annotations-3.1.0.GA.jar;C:\Users\brad\.m2\repository\org\hibernate\hibernate-core\3.3.0.SP1\hibernate-core-3.3.0.SP1.jar;C:\Users\brad\.m2\repository\antlr\antlr\2.7.6\antlr-2.7.6.jar;C:\Users\brad\.m2\repository\commons-collections\commons-collections\3.1\commons-collections-3.1.jar;C:\Users\brad\.m2\repository\javax\persistence\persistence-api\1.0\persistence-api-1.0.jar;C:\Users\brad\.m2\repository\dom4j\dom4j\1.6.1\dom4j-1.6.1.jar;C:\Users\brad\.m2\repository\xml-apis\xml-apis\1.0.b2\xml-apis-1.0.b2.jar;C:\Users\brad\.m2\repository\javax\transaction\jta\1.1\jta-1.1.jar;C:\Users\brad\.m2\repository\com\h2database\h2\1.3.148\h2-1.3.148.jar;C:\Users\brad\.m2\repository\javassist\javassist\3.4.GA\javassist-3.4.GA.jar;C:\Users\brad\.m2\repository\org\drools\drools-bpmn2\5.1.1\drools-bpmn2-5.1.1.jar;C:\Users\brad\.m2\repository\org\drools\drools-spring\5.1.1\drools-spring-5.1.1.jar;C:\Users\brad\.m2\repository\org\drools\drools-decisiontables\5.1.1\drools-decisiontables-5.1.1.jar;C:\Users\brad\.m2\repository\org\drools\drools-templates\5.1.1\drools-templates-5.1.1.jar;C:\Users\brad\.m2\repository\net\sourceforge\jexcelapi\jxl\2.6.10\jxl-2.6.10.jar;C:\Users\brad\.m2\repository\org\drools\drools-grid-core\5.1.1\drools-grid-core-5.1.1.jar;C:\Users\brad\.m2\repository\org\apache\mina\mina-core\2.0.0-M6\mina-core-2.0.0-M6.jar;C:\Users\brad\.m2\repository\org\springframework\spring-core\3.0.5.RELEASE\spring-core-3.0.5.RELEASE.jar;C:\Users\brad\.m2\repository\log4j\log4j\1.2.9\log4j-1.2.9.jar;C:\Users\brad\.m2\repository\org\hornetq\hornetq-core\2.1.2.Final\hornetq-core-2.1.2.Final.jar;C:\Users\brad\.m2\repository\org\hornetq\hornetq-jms\2.1.2.Final\hornetq-jms-2.1.2.Final.jar;C:\Users\brad\.m2\repository\org\springframework\spring-jms\3.0.5.RELEASE\spring-jms-3.0.5.RELEASE.jar;C:\Users\brad\.m2\repository\aopalliance\aopalliance\1.0\aopalliance-1.0.jar;C:\Users\brad\.m2\repository\org\springframework\spring-aop\3.0.5.RELEASE\spring-aop-3.0.5.RELEASE.jar;C:\Users\brad\.m2\repository\org\springframework\spring-tx\3.0.5.RELEASE\spring-tx-3.0.5.RELEASE.jar;C:\Users\brad\.m2\repository\org\springframework\spring-jdbc\3.0.5.RELEASE\spring-jdbc-3.0.5.RELEASE.jar;C:\Users\brad\.m2\repository\org\springframework\spring-orm\3.0.5.RELEASE\spring-orm-3.0.5.RELEASE.jar;C:\Users\brad\.m2\repository\org\springframework\spring-test\3.0.5.RELEASE\spring-test-3.0.5.RELEASE.jar;C:\Users\brad\.m2\repository\postgresql\postgresql\9.0-801.jdbc4\postgresql-9.0-801.jdbc4.jar;C:\Users\brad\.m2\repository\commons-dbcp\commons-dbcp\1.4\commons-dbcp-1.4.jar;C:\Users\brad\.m2\repository\commons-pool\commons-pool\1.5.4\commons-pool-1.5.4.jar;, java.specification.name=Java Platform API Specification, java.class.version=50.0, sun.management.compiler=HotSpot 64-Bit Server Compiler, hibernate.transaction.factory_class=org.hibernate.transaction.JDBCTransactionFactory, os.version=6.1, user.home=C:\Users\brad, user.timezone=America/Los_Angeles, java.awt.printerjob=sun.awt.windows.WPrinterJob, hibernate.connection.release_mode=auto, java.specification.version=1.6, file.encoding=Cp1252, user.name=brad, java.class.path=C:\testSource\platform\process-flow\process-flow-service\target\test-classes;C:\testSource\platform\process-flow\process-flow-service\target\classes;C:\Users\brad\.m2\repository\com\proferi\platform\process\process-flow-protocol\0.0.1-SNAPSHOT\process-flow-protocol-0.0.1-SNAPSHOT.jar;C:\Users\brad\.m2\repository\com\google\guava\guava\r08\guava-r08.jar;C:\Users\brad\.m2\repository\com\google\protobuf\protobuf-java\2.3.0\protobuf-java-2.3.0.jar;C:\Users\brad\.m2\repository\com\proferi\platform\platformtypes\0.0.1-SNAPSHOT\platformtypes-0.0.1-SNAPSHOT.jar;C:\Users\brad\.m2\repository\com\proferi\platform\platformcore\0.0.1-SNAPSHOT\platformcore-0.0.1-SNAPSHOT.jar;C:\Users\brad\.m2\repository\com\linkedin\norbert\norbert-java-network\1.0.1-SNAPSHOT\norbert-java-network-1.0.1-SNAPSHOT.jar;C:\Users\brad\.m2\repository\com\linkedin\norbert\norbert-java-cluster\1.0.1-SNAPSHOT\norbert-java-cluster-1.0.1-SNAPSHOT.jar;C:\Users\brad\.m2\repository\com\linkedin\norbert\norbert-cluster\1.0.1-SNAPSHOT\norbert-cluster-1.0.1-SNAPSHOT.jar;C:\Users\brad\.m2\repository\org\apache\hadoop\zookeeper\3.3.0\zookeeper-3.3.0.jar;C:\Users\brad\.m2\repository\jline\jline\0.9.94\jline-0.9.94.jar;C:\Users\brad\.m2\repository\junit\junit\4.8.2\junit-4.8.2.jar;C:\Users\brad\.m2\repository\com\linkedin\norbert\norbert-network\1.0.1-SNAPSHOT\norbert-network-1.0.1-SNAPSHOT.jar;C:\Users\brad\.m2\repository\org\jboss\netty\netty\3.2.1.Final\netty-3.2.1.Final.jar;C:\Users\brad\.m2\repository\org\scala-lang\scala-library\2.8.1\scala-library-2.8.1.jar;C:\Users\brad\.m2\repository\org\springframework\spring-context\3.0.5.RELEASE\spring-context-3.0.5.RELEASE.jar;C:\Users\brad\.m2\repository\org\springframework\spring-expression\3.0.5.RELEASE\spring-expression-3.0.5.RELEASE.jar;C:\Users\brad\.m2\repository\org\springframework\spring-asm\3.0.5.RELEASE\spring-asm-3.0.5.RELEASE.jar;C:\Users\brad\.m2\repository\javax\jms\jms\1.1\jms-1.1.jar;C:\Users\brad\.m2\repository\org\apache\commons\commons-daemon\1.0.5\commons-daemon-1.0.5.jar;C:\Users\brad\.m2\repository\com\proferi\platform\utilities\0.0.1-SNAPSHOT\utilities-0.0.1-SNAPSHOT.jar;C:\Users\brad\.m2\repository\com\fasterxml\uuid\java-uuid-generator\3.1.0\java-uuid-generator-3.1.0.jar;C:\Users\brad\.m2\repository\org\slf4j\slf4j-api\1.6.1\slf4j-api-1.6.1.jar;C:\Users\brad\.m2\repository\ch\qos\logback\logback-core\0.9.28\logback-core-0.9.28.jar;C:\Users\brad\.m2\repository\ch\qos\logback\logback-classic\0.9.28\logback-classic-0.9.28.jar;C:\Users\brad\.m2\repository\org\slf4j\jcl-over-slf4j\1.6.1\jcl-over-slf4j-1.6.1.jar;C:\Users\brad\.m2\repository\org\slf4j\log4j-over-slf4j\1.6.1\log4j-over-slf4j-1.6.1.jar;C:\Users\brad\.m2\repository\com\proferi\platform\appmodel\0.0.1-SNAPSHOT\appmodel-0.0.1-SNAPSHOT.jar;C:\Users\brad\.m2\repository\commons-lang\commons-lang\2.5\commons-lang-2.5.jar;C:\Users\brad\.m2\repository\org\springframework\spring-beans\3.0.5.RELEASE\spring-beans-3.0.5.RELEASE.jar;C:\Users\brad\.m2\repository\xmlunit\xmlunit\1.3\xmlunit-1.3.jar;C:\Users\brad\.m2\repository\org\codehaus\btm\btm\1.3.2\btm-1.3.2.jar;C:\Users\brad\.m2\repository\org\apache\geronimo\specs\geronimo-jms_1.1_spec\1.0.1\geronimo-jms_1.1_spec-1.0.1.jar;C:\Users\brad\.m2\repository\org\apache\geronimo\specs\geronimo-jta_1.0.1B_spec\1.0.1\geronimo-jta_1.0.1B_spec-1.0.1.jar;C:\Users\brad\.m2\repository\org\drools\drools-core\5.1.1\drools-core-5.1.1.jar;C:\Users\brad\.m2\repository\org\mvel\mvel2\2.0.16\mvel2-2.0.16.jar;C:\Users\brad\.m2\repository\org\drools\drools-api\5.1.1\drools-api-5.1.1.jar;C:\Users\brad\.m2\repository\org\drools\drools-persistence-jpa\5.1.1\drools-persistence-jpa-5.1.1.jar;C:\Users\brad\.m2\repository\org\drools\drools-compiler\5.1.1\drools-compiler-5.1.1.jar;C:\Users\brad\.m2\repository\org\antlr\antlr-runtime\3.1.3\antlr-runtime-3.1.3.jar;C:\Users\brad\.m2\repository\org\eclipse\jdt\core\compiler\ecj\3.5.1\ecj-3.5.1.jar;C:\Users\brad\.m2\repository\org\hibernate\hibernate-entitymanager\3.4.0.GA\hibernate-entitymanager-3.4.0.GA.jar;C:\Users\brad\.m2\repository\org\hibernate\ejb3-persistence\1.0.2.GA\ejb3-persistence-1.0.2.GA.jar;C:\Users\brad\.m2\repository\org\hibernate\hibernate-annotations\3.4.0.GA\hibernate-annotations-3.4.0.GA.jar;C:\Users\brad\.m2\repository\org\hibernate\hibernate-commons-annotations\3.1.0.GA\hibernate-commons-annotations-3.1.0.GA.jar;C:\Users\brad\.m2\repository\org\hibernate\hibernate-core\3.3.0.SP1\hibernate-core-3.3.0.SP1.jar;C:\Users\brad\.m2\repository\antlr\antlr\2.7.6\antlr-2.7.6.jar;C:\Users\brad\.m2\repository\commons-collections\commons-collections\3.1\commons-collections-3.1.jar;C:\Users\brad\.m2\repository\javax\persistence\persistence-api\1.0\persistence-api-1.0.jar;C:\Users\brad\.m2\repository\dom4j\dom4j\1.6.1\dom4j-1.6.1.jar;C:\Users\brad\.m2\repository\xml-apis\xml-apis\1.0.b2\xml-apis-1.0.b2.jar;C:\Users\brad\.m2\repository\javax\transaction\jta\1.1\jta-1.1.jar;C:\Users\brad\.m2\repository\com\h2database\h2\1.3.148\h2-1.3.148.jar;C:\Users\brad\.m2\repository\javassist\javassist\3.4.GA\javassist-3.4.GA.jar;C:\Users\brad\.m2\repository\org\drools\drools-bpmn2\5.1.1\drools-bpmn2-5.1.1.jar;C:\Users\brad\.m2\repository\org\drools\drools-spring\5.1.1\drools-spring-5.1.1.jar;C:\Users\brad\.m2\repository\org\drools\drools-decisiontables\5.1.1\drools-decisiontables-5.1.1.jar;C:\Users\brad\.m2\repository\org\drools\drools-templates\5.1.1\drools-templates-5.1.1.jar;C:\Users\brad\.m2\repository\net\sourceforge\jexcelapi\jxl\2.6.10\jxl-2.6.10.jar;C:\Users\brad\.m2\repository\org\drools\drools-grid-core\5.1.1\drools-grid-core-5.1.1.jar;C:\Users\brad\.m2\repository\org\apache\mina\mina-core\2.0.0-M6\mina-core-2.0.0-M6.jar;C:\Users\brad\.m2\repository\org\springframework\spring-core\3.0.5.RELEASE\spring-core-3.0.5.RELEASE.jar;C:\Users\brad\.m2\repository\log4j\log4j\1.2.9\log4j-1.2.9.jar;C:\Users\brad\.m2\repository\org\hornetq\hornetq-core\2.1.2.Final\hornetq-core-2.1.2.Final.jar;C:\Users\brad\.m2\repository\org\hornetq\hornetq-jms\2.1.2.Final\hornetq-jms-2.1.2.Final.jar;C:\Users\brad\.m2\repository\org\springframework\spring-jms\3.0.5.RELEASE\spring-jms-3.0.5.RELEASE.jar;C:\Users\brad\.m2\repository\aopalliance\aopalliance\1.0\aopalliance-1.0.jar;C:\Users\brad\.m2\repository\org\springframework\spring-aop\3.0.5.RELEASE\spring-aop-3.0.5.RELEASE.jar;C:\Users\brad\.m2\repository\org\springframework\spring-tx\3.0.5.RELEASE\spring-tx-3.0.5.RELEASE.jar;C:\Users\brad\.m2\repository\org\springframework\spring-jdbc\3.0.5.RELEASE\spring-jdbc-3.0.5.RELEASE.jar;C:\Users\brad\.m2\repository\org\springframework\spring-orm\3.0.5.RELEASE\spring-orm-3.0.5.RELEASE.jar;C:\Users\brad\.m2\repository\org\springframework\spring-test\3.0.5.RELEASE\spring-test-3.0.5.RELEASE.jar;C:\Users\brad\.m2\repository\postgresql\postgresql\9.0-801.jdbc4\postgresql-9.0-801.jdbc4.jar;C:\Users\brad\.m2\repository\commons-dbcp\commons-dbcp\1.4\commons-dbcp-1.4.jar;C:\Users\brad\.m2\repository\commons-pool\commons-pool\1.5.4\commons-pool-1.5.4.jar;, hibernate.bytecode.use_reflection_optimizer=false, hibernate.use_identifier_rollback=false, java.vm.specification.version=1.0, sun.arch.data.model=64, java.home=C:\Java\jdk1.6.0_20\jre, hibernate.dialect=org.hibernate.dialect.H2Dialect, java.specification.vendor=Sun Microsystems Inc., user.language=en, awt.toolkit=sun.awt.windows.WToolkit, java.vm.info=mixed mode, java.version=1.6.0_20, hibernate.transaction.flush_before_completion=false, java.ext.dirs=C:\Java\jdk1.6.0_20\jre\lib\ext;C:\Windows\Sun\Java\lib\ext, sun.boot.class.path=C:\Java\jdk1.6.0_20\jre\lib\endorsed\activation.jar;C:\Java\jdk1.6.0_20\jre\lib\endorsed\jaxb-api.jar;C:\Java\jdk1.6.0_20\jre\lib\endorsed\jaxws-api.jar;C:\Java\jdk1.6.0_20\jre\lib\endorsed\stax-api.jar;C:\Java\jdk1.6.0_20\jre\lib\resources.jar;C:\Java\jdk1.6.0_20\jre\lib\rt.jar;C:\Java\jdk1.6.0_20\jre\lib\sunrsasign.jar;C:\Java\jdk1.6.0_20\jre\lib\jsse.jar;C:\Java\jdk1.6.0_20\jre\lib\jce.jar;C:\Java\jdk1.6.0_20\jre\lib\charsets.jar;C:\Java\jdk1.6.0_20\jre\classes, java.vendor=Sun Microsystems Inc., localRepository=C:\Users\brad\.m2\repository, file.separator=\, java.vendor.url.bug=http://java.sun.com/cgi-bin/bugreport.cgi, hibernate.connection.provider_class=org.hibernate.ejb.connection.InjectedDataSourceConnectionProvider, hibernate.hbm2ddl.auto=create, sun.cpu.endian=little, sun.io.unicode.encoding=UnicodeLittle, hibernate.query.jpaql_strict_compliance=true, sun.desktop=windows, hibernate.max_fetch_depth=3, sun.cpu.isalist=amd64}
12:03:16.569 [pool-1-thread-1] DEBUG o.h.p.entity.AbstractEntityPersister - Static SQL for entity: org.drools.persistence.processinstance.variabletypes.JPAPersistedVariable
12:03:16.569 [pool-1-thread-1] DEBUG o.h.p.entity.AbstractEntityPersister - Version select: select id from VariableInstanceInfo where id =?
12:03:16.569 [pool-1-thread-1] DEBUG o.h.p.entity.AbstractEntityPersister - Snapshot select: select jpapersist_.id, jpapersist_.name as name90_, jpapersist_.persister as persister90_, jpapersist_.processInstanceId as processI5_90_, jpapersist_.workItemId as workItemId90_, jpapersist_.entityClass as entityCl7_90_, jpapersist_.entityId as entityId90_ from VariableInstanceInfo jpapersist_ where jpapersist_.id=?
12:03:16.569 [pool-1-thread-1] DEBUG o.h.p.entity.AbstractEntityPersister - Insert 0: insert into VariableInstanceInfo (name, persister, processInstanceId, workItemId, entityClass, entityId, TYPE, id) values (?, ?, ?, ?, ?, ?, 'JPAPersistedVariable', ?)
12:03:16.569 [pool-1-thread-1] DEBUG o.h.p.entity.AbstractEntityPersister - Update 0: update VariableInstanceInfo set name=?, persister=?, processInstanceId=?, workItemId=?, entityClass=?, entityId=? where id=?
12:03:16.569 [pool-1-thread-1] DEBUG o.h.p.entity.AbstractEntityPersister - Delete 0: delete from VariableInstanceInfo where id=?
12:03:16.569 [pool-1-thread-1] DEBUG o.h.p.entity.AbstractEntityPersister - Identity insert: insert into VariableInstanceInfo (id, name, persister, processInstanceId, workItemId, entityClass, entityId, TYPE) values (null, ?, ?, ?, ?, ?, ?, 'JPAPersistedVariable')
12:03:16.569 [pool-1-thread-1] DEBUG o.h.p.entity.AbstractEntityPersister - Static SQL for entity: org.drools.persistence.processinstance.WorkItemInfo
12:03:16.569 [pool-1-thread-1] DEBUG o.h.p.entity.AbstractEntityPersister - Version select: select OPTLOCK from WorkItemInfo where workItemId =?
12:03:16.569 [pool-1-thread-1] DEBUG o.h.p.entity.AbstractEntityPersister - Snapshot select: select workitemin_.workItemId, workitemin_.creationDate as creation2_91_, workitemin_.externalVariables as external3_91_, workitemin_.name as name91_, workitemin_.processInstanceId as processI5_91_, workitemin_.state as state91_, workitemin_.OPTLOCK as OPTLOCK91_, workitemin_.workItemByteArray as workItem8_91_ from WorkItemInfo workitemin_ where workitemin_.workItemId=?
12:03:16.569 [pool-1-thread-1] DEBUG o.h.p.entity.AbstractEntityPersister - Insert 0: insert into WorkItemInfo (creationDate, externalVariables, name, processInstanceId, state, OPTLOCK, workItemByteArray, workItemId) values (?, ?, ?, ?, ?, ?, ?, ?)
12:03:16.569 [pool-1-thread-1] DEBUG o.h.p.entity.AbstractEntityPersister - Update 0: update WorkItemInfo set creationDate=?, externalVariables=?, name=?, processInstanceId=?, state=?, OPTLOCK=?, workItemByteArray=? where workItemId=? and OPTLOCK=?
12:03:16.569 [pool-1-thread-1] DEBUG o.h.p.entity.AbstractEntityPersister - Delete 0: delete from WorkItemInfo where workItemId=? and OPTLOCK=?
12:03:16.569 [pool-1-thread-1] DEBUG o.h.p.entity.AbstractEntityPersister - Identity insert: insert into WorkItemInfo (workItemId, creationDate, externalVariables, name, processInstanceId, state, OPTLOCK, workItemByteArray) values (null, ?, ?, ?, ?, ?, ?, ?)
12:03:16.569 [pool-1-thread-1] DEBUG o.h.p.entity.AbstractEntityPersister - Static SQL for entity: org.drools.persistence.session.SessionInfo
12:03:16.569 [pool-1-thread-1] DEBUG o.h.p.entity.AbstractEntityPersister - Version select: select OPTLOCK from SessionInfo where id =?
12:03:16.569 [pool-1-thread-1] DEBUG o.h.p.entity.AbstractEntityPersister - Snapshot select: select sessioninf_.id, sessioninf_.lastModificationDate as lastModi2_88_, sessioninf_.rulesByteArray as rulesByt3_88_, sessioninf_.startDate as startDate88_, sessioninf_.OPTLOCK as OPTLOCK88_ from SessionInfo sessioninf_ where sessioninf_.id=?
12:03:16.569 [pool-1-thread-1] DEBUG o.h.p.entity.AbstractEntityPersister - Insert 0: insert into SessionInfo (lastModificationDate, rulesByteArray, startDate, OPTLOCK, id) values (?, ?, ?, ?, ?)
12:03:16.569 [pool-1-thread-1] DEBUG o.h.p.entity.AbstractEntityPersister - Update 0: update SessionInfo set lastModificationDate=?, rulesByteArray=?, startDate=?, OPTLOCK=? where id=? and OPTLOCK=?
12:03:16.569 [pool-1-thread-1] DEBUG o.h.p.entity.AbstractEntityPersister - Delete 0: delete from SessionInfo where id=? and OPTLOCK=?
12:03:16.569 [pool-1-thread-1] DEBUG o.h.p.entity.AbstractEntityPersister - Identity insert: insert into SessionInfo (id, lastModificationDate, rulesByteArray, startDate, OPTLOCK) values (null, ?, ?, ?, ?)
12:03:16.569 [pool-1-thread-1] DEBUG o.h.p.entity.AbstractEntityPersister - Static SQL for entity: org.drools.persistence.processinstance.variabletypes.SerializablePersistedVariable
12:03:16.569 [pool-1-thread-1] DEBUG o.h.p.entity.AbstractEntityPersister - Version select: select id from VariableInstanceInfo where id =?
12:03:16.569 [pool-1-thread-1] DEBUG o.h.p.entity.AbstractEntityPersister - Snapshot select: select serializab_.id, serializab_.name as name90_, serializab_.persister as persister90_, serializab_.processInstanceId as processI5_90_, serializab_.workItemId as workItemId90_, serializab_.content as content90_ from VariableInstanceInfo serializab_ where serializab_.id=?
12:03:16.569 [pool-1-thread-1] DEBUG o.h.p.entity.AbstractEntityPersister - Insert 0: insert into VariableInstanceInfo (name, persister, processInstanceId, workItemId, content, TYPE, id) values (?, ?, ?, ?, ?, 'SerializablePersistedVariable', ?)
12:03:16.569 [pool-1-thread-1] DEBUG o.h.p.entity.AbstractEntityPersister - Update 0: update VariableInstanceInfo set name=?, persister=?, processInstanceId=?, workItemId=?, content=? where id=?
12:03:16.569 [pool-1-thread-1] DEBUG o.h.p.entity.AbstractEntityPersister - Delete 0: delete from VariableInstanceInfo where id=?
12:03:16.569 [pool-1-thread-1] DEBUG o.h.p.entity.AbstractEntityPersister - Identity insert: insert into VariableInstanceInfo (id, name, persister, processInstanceId, workItemId, content, TYPE) values (null, ?, ?, ?, ?, ?, 'SerializablePersistedVariable')
12:03:16.569 [pool-1-thread-1] DEBUG o.h.p.entity.AbstractEntityPersister - Static SQL for entity: org.drools.persistence.processinstance.variabletypes.VariableInstanceInfo
12:03:16.569 [pool-1-thread-1] DEBUG o.h.p.entity.AbstractEntityPersister - Version select: select id from VariableInstanceInfo where id =?
12:03:16.569 [pool-1-thread-1] DEBUG o.h.p.entity.AbstractEntityPersister - Snapshot select: select variablein_.id, variablein_.name as name90_, variablein_.persister as persister90_, variablein_.processInstanceId as processI5_90_, variablein_.workItemId as workItemId90_ from VariableInstanceInfo variablein_ where variablein_.id=?
12:03:16.569 [pool-1-thread-1] DEBUG o.h.p.entity.AbstractEntityPersister - Insert 0: insert into VariableInstanceInfo (name, persister, processInstanceId, workItemId, TYPE, id) values (?, ?, ?, ?, 'GEN', ?)
12:03:16.569 [pool-1-thread-1] DEBUG o.h.p.entity.AbstractEntityPersister - Update 0: update VariableInstanceInfo set name=?, persister=?, processInstanceId=?, workItemId=? where id=?
12:03:16.569 [pool-1-thread-1] DEBUG o.h.p.entity.AbstractEntityPersister - Delete 0: delete from VariableInstanceInfo where id=?
12:03:16.569 [pool-1-thread-1] DEBUG o.h.p.entity.AbstractEntityPersister - Identity insert: insert into VariableInstanceInfo (id, name, persister, processInstanceId, workItemId, TYPE) values (null, ?, ?, ?, ?, 'GEN')
12:03:16.569 [pool-1-thread-1] DEBUG o.h.p.entity.AbstractEntityPersister - Static SQL for entity: org.drools.persistence.processinstance.ProcessInstanceInfo
12:03:16.569 [pool-1-thread-1] DEBUG o.h.p.entity.AbstractEntityPersister - Version select: select OPTLOCK from ProcessInstanceInfo where InstanceId =?
12:03:16.569 [pool-1-thread-1] DEBUG o.h.p.entity.AbstractEntityPersister - Snapshot select: select processins_.InstanceId, processins_.externalVariables as external2_89_, processins_.lastModificationDate as lastModi3_89_, processins_.lastReadDate as lastRead4_89_, processins_.processId as processId89_, processins_.processInstanceByteArray as processI6_89_, processins_.startDate as startDate89_, processins_.state as state89_, processins_.OPTLOCK as OPTLOCK89_ from ProcessInstanceInfo processins_ where processins_.InstanceId=?
12:03:16.569 [pool-1-thread-1] DEBUG o.h.p.entity.AbstractEntityPersister - Insert 0: insert into ProcessInstanceInfo (externalVariables, lastModificationDate, lastReadDate, processId, processInstanceByteArray, startDate, state, OPTLOCK, InstanceId) values (?, ?, ?, ?, ?, ?, ?, ?, ?)
12:03:16.569 [pool-1-thread-1] DEBUG o.h.p.entity.AbstractEntityPersister - Update 0: update ProcessInstanceInfo set externalVariables=?, lastModificationDate=?, lastReadDate=?, processId=?, processInstanceByteArray=?, startDate=?, state=?, OPTLOCK=? where InstanceId=? and OPTLOCK=?
12:03:16.569 [pool-1-thread-1] DEBUG o.h.p.entity.AbstractEntityPersister - Delete 0: delete from ProcessInstanceInfo where InstanceId=? and OPTLOCK=?
12:03:16.569 [pool-1-thread-1] DEBUG o.h.p.entity.AbstractEntityPersister - Identity insert: insert into ProcessInstanceInfo (InstanceId, externalVariables, lastModificationDate, lastReadDate, processId, processInstanceByteArray, startDate, state, OPTLOCK) values (null, ?, ?, ?, ?, ?, ?, ?, ?)
12:03:16.569 [pool-1-thread-1] DEBUG o.h.p.c.AbstractCollectionPersister - Static SQL for collection: org.drools.persistence.processinstance.ProcessInstanceInfo.eventTypes
12:03:16.569 [pool-1-thread-1] DEBUG o.h.p.c.AbstractCollectionPersister - Row insert: insert into EventTypes (InstanceId, element) values (?, ?)
12:03:16.569 [pool-1-thread-1] DEBUG o.h.p.c.AbstractCollectionPersister - Row update: update EventTypes set element=? where InstanceId=? and element=?
12:03:16.569 [pool-1-thread-1] DEBUG o.h.p.c.AbstractCollectionPersister - Row delete: delete from EventTypes where InstanceId=? and element=?
12:03:16.569 [pool-1-thread-1] DEBUG o.h.p.c.AbstractCollectionPersister - One-shot delete: delete from EventTypes where InstanceId=?
12:03:16.569 [pool-1-thread-1] DEBUG o.h.p.c.AbstractCollectionPersister - Static SQL for collection: org.drools.persistence.processinstance.ProcessInstanceInfo.variables
12:03:16.569 [pool-1-thread-1] DEBUG o.h.p.c.AbstractCollectionPersister - Row insert: update VariableInstanceInfo set processInstanceId=? where id=?
12:03:16.569 [pool-1-thread-1] DEBUG o.h.p.c.AbstractCollectionPersister - Row delete: update VariableInstanceInfo set processInstanceId=null where processInstanceId=? and id=?
12:03:16.569 [pool-1-thread-1] DEBUG o.h.p.c.AbstractCollectionPersister - One-shot delete: update VariableInstanceInfo set processInstanceId=null where processInstanceId=?
12:03:16.569 [pool-1-thread-1] DEBUG o.h.p.c.AbstractCollectionPersister - Static SQL for collection: org.drools.persistence.processinstance.WorkItemInfo.variables
12:03:16.569 [pool-1-thread-1] DEBUG o.h.p.c.AbstractCollectionPersister - Row insert: update VariableInstanceInfo set workItemId=? where id=?
12:03:16.569 [pool-1-thread-1] DEBUG o.h.p.c.AbstractCollectionPersister - Row delete: update VariableInstanceInfo set workItemId=null where workItemId=? and id=?
12:03:16.569 [pool-1-thread-1] DEBUG o.h.p.c.AbstractCollectionPersister - One-shot delete: update VariableInstanceInfo set workItemId=null where workItemId=?
12:03:16.569 [pool-1-thread-1] DEBUG o.h.loader.entity.EntityLoader - Static select for entity org.drools.persistence.processinstance.variabletypes.JPAPersistedVariable: select jpapersist0_.id as id90_0_, jpapersist0_.name as name90_0_, jpapersist0_.persister as persister90_0_, jpapersist0_.processInstanceId as processI5_90_0_, jpapersist0_.workItemId as workItemId90_0_, jpapersist0_.entityClass as entityCl7_90_0_, jpapersist0_.entityId as entityId90_0_ from VariableInstanceInfo jpapersist0_ where jpapersist0_.id=? and jpapersist0_.TYPE='JPAPersistedVariable'
12:03:16.569 [pool-1-thread-1] DEBUG o.h.loader.entity.EntityLoader - Static select for entity org.drools.persistence.processinstance.variabletypes.JPAPersistedVariable: select jpapersist0_.id as id90_0_, jpapersist0_.name as name90_0_, jpapersist0_.persister as persister90_0_, jpapersist0_.processInstanceId as processI5_90_0_, jpapersist0_.workItemId as workItemId90_0_, jpapersist0_.entityClass as entityCl7_90_0_, jpapersist0_.entityId as entityId90_0_ from VariableInstanceInfo jpapersist0_ where jpapersist0_.id=? and jpapersist0_.TYPE='JPAPersistedVariable'
12:03:16.569 [pool-1-thread-1] DEBUG o.h.loader.entity.EntityLoader - Static select for entity org.drools.persistence.processinstance.variabletypes.JPAPersistedVariable: select jpapersist0_.id as id90_0_, jpapersist0_.name as name90_0_, jpapersist0_.persister as persister90_0_, jpapersist0_.processInstanceId as processI5_90_0_, jpapersist0_.workItemId as workItemId90_0_, jpapersist0_.entityClass as entityCl7_90_0_, jpapersist0_.entityId as entityId90_0_ from VariableInstanceInfo jpapersist0_ where jpapersist0_.id=? and jpapersist0_.TYPE='JPAPersistedVariable' for update
12:03:16.569 [pool-1-thread-1] DEBUG o.h.loader.entity.EntityLoader - Static select for entity org.drools.persistence.processinstance.variabletypes.JPAPersistedVariable: select jpapersist0_.id as id90_0_, jpapersist0_.name as name90_0_, jpapersist0_.persister as persister90_0_, jpapersist0_.processInstanceId as processI5_90_0_, jpapersist0_.workItemId as workItemId90_0_, jpapersist0_.entityClass as entityCl7_90_0_, jpapersist0_.entityId as entityId90_0_ from VariableInstanceInfo jpapersist0_ where jpapersist0_.id=? and jpapersist0_.TYPE='JPAPersistedVariable' for update
12:03:16.569 [pool-1-thread-1] DEBUG o.h.loader.entity.EntityLoader - Static select for entity org.drools.persistence.processinstance.variabletypes.JPAPersistedVariable: select jpapersist0_.id as id90_0_, jpapersist0_.name as name90_0_, jpapersist0_.persister as persister90_0_, jpapersist0_.processInstanceId as processI5_90_0_, jpapersist0_.workItemId as workItemId90_0_, jpapersist0_.entityClass as entityCl7_90_0_, jpapersist0_.entityId as entityId90_0_ from VariableInstanceInfo jpapersist0_ where jpapersist0_.id=? and jpapersist0_.TYPE='JPAPersistedVariable' for update
12:03:16.569 [pool-1-thread-1] DEBUG o.h.loader.entity.EntityLoader - Static select for action ACTION_MERGE on entity org.drools.persistence.processinstance.variabletypes.JPAPersistedVariable: select jpapersist0_.id as id90_0_, jpapersist0_.name as name90_0_, jpapersist0_.persister as persister90_0_, jpapersist0_.processInstanceId as processI5_90_0_, jpapersist0_.workItemId as workItemId90_0_, jpapersist0_.entityClass as entityCl7_90_0_, jpapersist0_.entityId as entityId90_0_ from VariableInstanceInfo jpapersist0_ where jpapersist0_.id=? and jpapersist0_.TYPE='JPAPersistedVariable'
12:03:16.569 [pool-1-thread-1] DEBUG o.h.loader.entity.EntityLoader - Static select for action ACTION_REFRESH on entity org.drools.persistence.processinstance.variabletypes.JPAPersistedVariable: select jpapersist0_.id as id90_0_, jpapersist0_.name as name90_0_, jpapersist0_.persister as persister90_0_, jpapersist0_.processInstanceId as processI5_90_0_, jpapersist0_.workItemId as workItemId90_0_, jpapersist0_.entityClass as entityCl7_90_0_, jpapersist0_.entityId as entityId90_0_ from VariableInstanceInfo jpapersist0_ where jpapersist0_.id=? and jpapersist0_.TYPE='JPAPersistedVariable'
12:03:16.569 [pool-1-thread-1] DEBUG o.h.loader.entity.EntityLoader - Static select for entity org.drools.persistence.processinstance.WorkItemInfo: select workitemin0_.workItemId as workItemId91_0_, workitemin0_.creationDate as creation2_91_0_, workitemin0_.externalVariables as external3_91_0_, workitemin0_.name as name91_0_, workitemin0_.processInstanceId as processI5_91_0_, workitemin0_.state as state91_0_, workitemin0_.OPTLOCK as OPTLOCK91_0_, workitemin0_.workItemByteArray as workItem8_91_0_ from WorkItemInfo workitemin0_ where workitemin0_.workItemId=?
12:03:16.569 [pool-1-thread-1] DEBUG o.h.loader.entity.EntityLoader - Static select for entity org.drools.persistence.processinstance.WorkItemInfo: select workitemin0_.workItemId as workItemId91_0_, workitemin0_.creationDate as creation2_91_0_, workitemin0_.externalVariables as external3_91_0_, workitemin0_.name as name91_0_, workitemin0_.processInstanceId as processI5_91_0_, workitemin0_.state as state91_0_, workitemin0_.OPTLOCK as OPTLOCK91_0_, workitemin0_.workItemByteArray as workItem8_91_0_ from WorkItemInfo workitemin0_ where workitemin0_.workItemId=?
12:03:16.569 [pool-1-thread-1] DEBUG o.h.loader.entity.EntityLoader - Static select for entity org.drools.persistence.processinstance.WorkItemInfo: select workitemin0_.workItemId as workItemId91_0_, workitemin0_.creationDate as creation2_91_0_, workitemin0_.externalVariables as external3_91_0_, workitemin0_.name as name91_0_, workitemin0_.processInstanceId as processI5_91_0_, workitemin0_.state as state91_0_, workitemin0_.OPTLOCK as OPTLOCK91_0_, workitemin0_.workItemByteArray as workItem8_91_0_ from WorkItemInfo workitemin0_ where workitemin0_.workItemId=? for update
12:03:16.569 [pool-1-thread-1] DEBUG o.h.loader.entity.EntityLoader - Static select for entity org.drools.persistence.processinstance.WorkItemInfo: select workitemin0_.workItemId as workItemId91_0_, workitemin0_.creationDate as creation2_91_0_, workitemin0_.externalVariables as external3_91_0_, workitemin0_.name as name91_0_, workitemin0_.processInstanceId as processI5_91_0_, workitemin0_.state as state91_0_, workitemin0_.OPTLOCK as OPTLOCK91_0_, workitemin0_.workItemByteArray as workItem8_91_0_ from WorkItemInfo workitemin0_ where workitemin0_.workItemId=? for update
12:03:16.569 [pool-1-thread-1] DEBUG o.h.loader.entity.EntityLoader - Static select for entity org.drools.persistence.processinstance.WorkItemInfo: select workitemin0_.workItemId as workItemId91_0_, workitemin0_.creationDate as creation2_91_0_, workitemin0_.externalVariables as external3_91_0_, workitemin0_.name as name91_0_, workitemin0_.processInstanceId as processI5_91_0_, workitemin0_.state as state91_0_, workitemin0_.OPTLOCK as OPTLOCK91_0_, workitemin0_.workItemByteArray as workItem8_91_0_ from WorkItemInfo workitemin0_ where workitemin0_.workItemId=? for update
12:03:16.569 [pool-1-thread-1] DEBUG o.h.loader.entity.EntityLoader - Static select for action ACTION_MERGE on entity org.drools.persistence.processinstance.WorkItemInfo: select workitemin0_.workItemId as workItemId91_1_, workitemin0_.creationDate as creation2_91_1_, workitemin0_.externalVariables as external3_91_1_, workitemin0_.name as name91_1_, workitemin0_.processInstanceId as processI5_91_1_, workitemin0_.state as state91_1_, workitemin0_.OPTLOCK as OPTLOCK91_1_, workitemin0_.workItemByteArray as workItem8_91_1_, variables1_.workItemId as workItemId3_, variables1_.id as id3_, variables1_.name as formula16_3_, variables1_.id as id90_0_, variables1_.name as name90_0_, variables1_.persister as persister90_0_, variables1_.processInstanceId as processI5_90_0_, variables1_.workItemId as workItemId90_0_, variables1_.entityClass as entityCl7_90_0_, variables1_.entityId as entityId90_0_, variables1_.content as content90_0_, variables1_.TYPE as TYPE90_0_ from WorkItemInfo workitemin0_ left outer join VariableInstanceInfo variables1_ on workitemin0_.workItemId=variables1_.workItemId where workitemin0_.workItemId=?
12:03:16.569 [pool-1-thread-1] DEBUG o.h.loader.entity.EntityLoader - Static select for action ACTION_REFRESH on entity org.drools.persistence.processinstance.WorkItemInfo: select workitemin0_.workItemId as workItemId91_1_, workitemin0_.creationDate as creation2_91_1_, workitemin0_.externalVariables as external3_91_1_, workitemin0_.name as name91_1_, workitemin0_.processInstanceId as processI5_91_1_, workitemin0_.state as state91_1_, workitemin0_.OPTLOCK as OPTLOCK91_1_, workitemin0_.workItemByteArray as workItem8_91_1_, variables1_.workItemId as workItemId3_, variables1_.id as id3_, variables1_.name as formula16_3_, variables1_.id as id90_0_, variables1_.name as name90_0_, variables1_.persister as persister90_0_, variables1_.processInstanceId as processI5_90_0_, variables1_.workItemId as workItemId90_0_, variables1_.entityClass as entityCl7_90_0_, variables1_.entityId as entityId90_0_, variables1_.content as content90_0_, variables1_.TYPE as TYPE90_0_ from WorkItemInfo workitemin0_ left outer join VariableInstanceInfo variables1_ on workitemin0_.workItemId=variables1_.workItemId where workitemin0_.workItemId=?
12:03:16.569 [pool-1-thread-1] DEBUG o.h.loader.entity.EntityLoader - Static select for entity org.drools.persistence.session.SessionInfo: select sessioninf0_.id as id88_0_, sessioninf0_.lastModificationDate as lastModi2_88_0_, sessioninf0_.rulesByteArray as rulesByt3_88_0_, sessioninf0_.startDate as startDate88_0_, sessioninf0_.OPTLOCK as OPTLOCK88_0_ from SessionInfo sessioninf0_ where sessioninf0_.id=?
12:03:16.569 [pool-1-thread-1] DEBUG o.h.loader.entity.EntityLoader - Static select for entity org.drools.persistence.session.SessionInfo: select sessioninf0_.id as id88_0_, sessioninf0_.lastModificationDate as lastModi2_88_0_, sessioninf0_.rulesByteArray as rulesByt3_88_0_, sessioninf0_.startDate as startDate88_0_, sessioninf0_.OPTLOCK as OPTLOCK88_0_ from SessionInfo sessioninf0_ where sessioninf0_.id=?
12:03:16.569 [pool-1-thread-1] DEBUG o.h.loader.entity.EntityLoader - Static select for entity org.drools.persistence.session.SessionInfo: select sessioninf0_.id as id88_0_, sessioninf0_.lastModificationDate as lastModi2_88_0_, sessioninf0_.rulesByteArray as rulesByt3_88_0_, sessioninf0_.startDate as startDate88_0_, sessioninf0_.OPTLOCK as OPTLOCK88_0_ from SessionInfo sessioninf0_ where sessioninf0_.id=? for update
12:03:16.569 [pool-1-thread-1] DEBUG o.h.loader.entity.EntityLoader - Static select for entity org.drools.persistence.session.SessionInfo: select sessioninf0_.id as id88_0_, sessioninf0_.lastModificationDate as lastModi2_88_0_, sessioninf0_.rulesByteArray as rulesByt3_88_0_, sessioninf0_.startDate as startDate88_0_, sessioninf0_.OPTLOCK as OPTLOCK88_0_ from SessionInfo sessioninf0_ where sessioninf0_.id=? for update
12:03:16.569 [pool-1-thread-1] DEBUG o.h.loader.entity.EntityLoader - Static select for entity org.drools.persistence.session.SessionInfo: select sessioninf0_.id as id88_0_, sessioninf0_.lastModificationDate as lastModi2_88_0_, sessioninf0_.rulesByteArray as rulesByt3_88_0_, sessioninf0_.startDate as startDate88_0_, sessioninf0_.OPTLOCK as OPTLOCK88_0_ from SessionInfo sessioninf0_ where sessioninf0_.id=? for update
12:03:16.569 [pool-1-thread-1] DEBUG o.h.loader.entity.EntityLoader - Static select for action ACTION_MERGE on entity org.drools.persistence.session.SessionInfo: select sessioninf0_.id as id88_0_, sessioninf0_.lastModificationDate as lastModi2_88_0_, sessioninf0_.rulesByteArray as rulesByt3_88_0_, sessioninf0_.startDate as startDate88_0_, sessioninf0_.OPTLOCK as OPTLOCK88_0_ from SessionInfo sessioninf0_ where sessioninf0_.id=?
12:03:16.569 [pool-1-thread-1] DEBUG o.h.loader.entity.EntityLoader - Static select for action ACTION_REFRESH on entity org.drools.persistence.session.SessionInfo: select sessioninf0_.id as id88_0_, sessioninf0_.lastModificationDate as lastModi2_88_0_, sessioninf0_.rulesByteArray as rulesByt3_88_0_, sessioninf0_.startDate as startDate88_0_, sessioninf0_.OPTLOCK as OPTLOCK88_0_ from SessionInfo sessioninf0_ where sessioninf0_.id=?
12:03:16.569 [pool-1-thread-1] DEBUG o.h.loader.entity.EntityLoader - Static select for entity org.drools.persistence.processinstance.variabletypes.SerializablePersistedVariable: select serializab0_.id as id90_0_, serializab0_.name as name90_0_, serializab0_.persister as persister90_0_, serializab0_.processInstanceId as processI5_90_0_, serializab0_.workItemId as workItemId90_0_, serializab0_.content as content90_0_ from VariableInstanceInfo serializab0_ where serializab0_.id=? and serializab0_.TYPE='SerializablePersistedVariable'
12:03:16.569 [pool-1-thread-1] DEBUG o.h.loader.entity.EntityLoader - Static select for entity org.drools.persistence.processinstance.variabletypes.SerializablePersistedVariable: select serializab0_.id as id90_0_, serializab0_.name as name90_0_, serializab0_.persister as persister90_0_, serializab0_.processInstanceId as processI5_90_0_, serializab0_.workItemId as workItemId90_0_, serializab0_.content as content90_0_ from VariableInstanceInfo serializab0_ where serializab0_.id=? and serializab0_.TYPE='SerializablePersistedVariable'
12:03:16.569 [pool-1-thread-1] DEBUG o.h.loader.entity.EntityLoader - Static select for entity org.drools.persistence.processinstance.variabletypes.SerializablePersistedVariable: select serializab0_.id as id90_0_, serializab0_.name as name90_0_, serializab0_.persister as persister90_0_, serializab0_.processInstanceId as processI5_90_0_, serializab0_.workItemId as workItemId90_0_, serializab0_.content as content90_0_ from VariableInstanceInfo serializab0_ where serializab0_.id=? and serializab0_.TYPE='SerializablePersistedVariable' for update
12:03:16.569 [pool-1-thread-1] DEBUG o.h.loader.entity.EntityLoader - Static select for entity org.drools.persistence.processinstance.variabletypes.SerializablePersistedVariable: select serializab0_.id as id90_0_, serializab0_.name as name90_0_, serializab0_.persister as persister90_0_, serializab0_.processInstanceId as processI5_90_0_, serializab0_.workItemId as workItemId90_0_, serializab0_.content as content90_0_ from VariableInstanceInfo serializab0_ where serializab0_.id=? and serializab0_.TYPE='SerializablePersistedVariable' for update
12:03:16.585 [pool-1-thread-1] DEBUG o.h.loader.entity.EntityLoader - Static select for entity org.drools.persistence.processinstance.variabletypes.SerializablePersistedVariable: select serializab0_.id as id90_0_, serializab0_.name as name90_0_, serializab0_.persister as persister90_0_, serializab0_.processInstanceId as processI5_90_0_, serializab0_.workItemId as workItemId90_0_, serializab0_.content as content90_0_ from VariableInstanceInfo serializab0_ where serializab0_.id=? and serializab0_.TYPE='SerializablePersistedVariable' for update
12:03:16.585 [pool-1-thread-1] DEBUG o.h.loader.entity.EntityLoader - Static select for action ACTION_MERGE on entity org.drools.persistence.processinstance.variabletypes.SerializablePersistedVariable: select serializab0_.id as id90_0_, serializab0_.name as name90_0_, serializab0_.persister as persister90_0_, serializab0_.processInstanceId as processI5_90_0_, serializab0_.workItemId as workItemId90_0_, serializab0_.content as content90_0_ from VariableInstanceInfo serializab0_ where serializab0_.id=? and serializab0_.TYPE='SerializablePersistedVariable'
12:03:16.585 [pool-1-thread-1] DEBUG o.h.loader.entity.EntityLoader - Static select for action ACTION_REFRESH on entity org.drools.persistence.processinstance.variabletypes.SerializablePersistedVariable: select serializab0_.id as id90_0_, serializab0_.name as name90_0_, serializab0_.persister as persister90_0_, serializab0_.processInstanceId as processI5_90_0_, serializab0_.workItemId as workItemId90_0_, serializab0_.content as content90_0_ from VariableInstanceInfo serializab0_ where serializab0_.id=? and serializab0_.TYPE='SerializablePersistedVariable'
12:03:16.585 [pool-1-thread-1] DEBUG o.h.loader.entity.EntityLoader - Static select for entity org.drools.persistence.processinstance.variabletypes.VariableInstanceInfo: select variablein0_.id as id90_0_, variablein0_.name as name90_0_, variablein0_.persister as persister90_0_, variablein0_.processInstanceId as processI5_90_0_, variablein0_.workItemId as workItemId90_0_, variablein0_.entityClass as entityCl7_90_0_, variablein0_.entityId as entityId90_0_, variablein0_.content as content90_0_, variablein0_.TYPE as TYPE90_0_ from VariableInstanceInfo variablein0_ where variablein0_.id=?
12:03:16.585 [pool-1-thread-1] DEBUG o.h.loader.entity.EntityLoader - Static select for entity org.drools.persistence.processinstance.variabletypes.VariableInstanceInfo: select variablein0_.id as id90_0_, variablein0_.name as name90_0_, variablein0_.persister as persister90_0_, variablein0_.processInstanceId as processI5_90_0_, variablein0_.workItemId as workItemId90_0_, variablein0_.entityClass as entityCl7_90_0_, variablein0_.entityId as entityId90_0_, variablein0_.content as content90_0_, variablein0_.TYPE as TYPE90_0_ from VariableInstanceInfo variablein0_ where variablein0_.id=?
12:03:16.585 [pool-1-thread-1] DEBUG o.h.loader.entity.EntityLoader - Static select for entity org.drools.persistence.processinstance.variabletypes.VariableInstanceInfo: select variablein0_.id as id90_0_, variablein0_.name as name90_0_, variablein0_.persister as persister90_0_, variablein0_.processInstanceId as processI5_90_0_, variablein0_.workItemId as workItemId90_0_, variablein0_.entityClass as entityCl7_90_0_, variablein0_.entityId as entityId90_0_, variablein0_.content as content90_0_, variablein0_.TYPE as TYPE90_0_ from VariableInstanceInfo variablein0_ where variablein0_.id=? for update
12:03:16.585 [pool-1-thread-1] DEBUG o.h.loader.entity.EntityLoader - Static select for entity org.drools.persistence.processinstance.variabletypes.VariableInstanceInfo: select variablein0_.id as id90_0_, variablein0_.name as name90_0_, variablein0_.persister as persister90_0_, variablein0_.processInstanceId as processI5_90_0_, variablein0_.workItemId as workItemId90_0_, variablein0_.entityClass as entityCl7_90_0_, variablein0_.entityId as entityId90_0_, variablein0_.content as content90_0_, variablein0_.TYPE as TYPE90_0_ from VariableInstanceInfo variablein0_ where variablein0_.id=? for update
12:03:16.585 [pool-1-thread-1] DEBUG o.h.loader.entity.EntityLoader - Static select for entity org.drools.persistence.processinstance.variabletypes.VariableInstanceInfo: select variablein0_.id as id90_0_, variablein0_.name as name90_0_, variablein0_.persister as persister90_0_, variablein0_.processInstanceId as processI5_90_0_, variablein0_.workItemId as workItemId90_0_, variablein0_.entityClass as entityCl7_90_0_, variablein0_.entityId as entityId90_0_, variablein0_.content as content90_0_, variablein0_.TYPE as TYPE90_0_ from VariableInstanceInfo variablein0_ where variablein0_.id=? for update
12:03:16.585 [pool-1-thread-1] DEBUG o.h.loader.entity.EntityLoader - Static select for action ACTION_MERGE on entity org.drools.persistence.processinstance.variabletypes.VariableInstanceInfo: select variablein0_.id as id90_0_, variablein0_.name as name90_0_, variablein0_.persister as persister90_0_, variablein0_.processInstanceId as processI5_90_0_, variablein0_.workItemId as workItemId90_0_, variablein0_.entityClass as entityCl7_90_0_, variablein0_.entityId as entityId90_0_, variablein0_.content as content90_0_, variablein0_.TYPE as TYPE90_0_ from VariableInstanceInfo variablein0_ where variablein0_.id=?
12:03:16.585 [pool-1-thread-1] DEBUG o.h.loader.entity.EntityLoader - Static select for action ACTION_REFRESH on entity org.drools.persistence.processinstance.variabletypes.VariableInstanceInfo: select variablein0_.id as id90_0_, variablein0_.name as name90_0_, variablein0_.persister as persister90_0_, variablein0_.processInstanceId as processI5_90_0_, variablein0_.workItemId as workItemId90_0_, variablein0_.entityClass as entityCl7_90_0_, variablein0_.entityId as entityId90_0_, variablein0_.content as content90_0_, variablein0_.TYPE as TYPE90_0_ from VariableInstanceInfo variablein0_ where variablein0_.id=?
12:03:16.585 [pool-1-thread-1] DEBUG o.h.loader.entity.EntityLoader - Static select for entity org.drools.persistence.processinstance.ProcessInstanceInfo: select processins0_.InstanceId as InstanceId89_0_, processins0_.externalVariables as external2_89_0_, processins0_.lastModificationDate as lastModi3_89_0_, processins0_.lastReadDate as lastRead4_89_0_, processins0_.processId as processId89_0_, processins0_.processInstanceByteArray as processI6_89_0_, processins0_.startDate as startDate89_0_, processins0_.state as state89_0_, processins0_.OPTLOCK as OPTLOCK89_0_ from ProcessInstanceInfo processins0_ where processins0_.InstanceId=?
12:03:16.585 [pool-1-thread-1] DEBUG o.h.loader.entity.EntityLoader - Static select for entity org.drools.persistence.processinstance.ProcessInstanceInfo: select processins0_.InstanceId as InstanceId89_0_, processins0_.externalVariables as external2_89_0_, processins0_.lastModificationDate as lastModi3_89_0_, processins0_.lastReadDate as lastRead4_89_0_, processins0_.processId as processId89_0_, processins0_.processInstanceByteArray as processI6_89_0_, processins0_.startDate as startDate89_0_, processins0_.state as state89_0_, processins0_.OPTLOCK as OPTLOCK89_0_ from ProcessInstanceInfo processins0_ where processins0_.InstanceId=?
12:03:16.585 [pool-1-thread-1] DEBUG o.h.loader.entity.EntityLoader - Static select for entity org.drools.persistence.processinstance.ProcessInstanceInfo: select processins0_.InstanceId as InstanceId89_0_, processins0_.externalVariables as external2_89_0_, processins0_.lastModificationDate as lastModi3_89_0_, processins0_.lastReadDate as lastRead4_89_0_, processins0_.processId as processId89_0_, processins0_.processInstanceByteArray as processI6_89_0_, processins0_.startDate as startDate89_0_, processins0_.state as state89_0_, processins0_.OPTLOCK as OPTLOCK89_0_ from ProcessInstanceInfo processins0_ where processins0_.InstanceId=? for update
12:03:16.585 [pool-1-thread-1] DEBUG o.h.loader.entity.EntityLoader - Static select for entity org.drools.persistence.processinstance.ProcessInstanceInfo: select processins0_.InstanceId as InstanceId89_0_, processins0_.externalVariables as external2_89_0_, processins0_.lastModificationDate as lastModi3_89_0_, processins0_.lastReadDate as lastRead4_89_0_, processins0_.processId as processId89_0_, processins0_.processInstanceByteArray as processI6_89_0_, processins0_.startDate as startDate89_0_, processins0_.state as state89_0_, processins0_.OPTLOCK as OPTLOCK89_0_ from ProcessInstanceInfo processins0_ where processins0_.InstanceId=? for update
12:03:16.585 [pool-1-thread-1] DEBUG o.h.loader.entity.EntityLoader - Static select for entity org.drools.persistence.processinstance.ProcessInstanceInfo: select processins0_.InstanceId as InstanceId89_0_, processins0_.externalVariables as external2_89_0_, processins0_.lastModificationDate as lastModi3_89_0_, processins0_.lastReadDate as lastRead4_89_0_, processins0_.processId as processId89_0_, processins0_.processInstanceByteArray as processI6_89_0_, processins0_.startDate as startDate89_0_, processins0_.state as state89_0_, processins0_.OPTLOCK as OPTLOCK89_0_ from ProcessInstanceInfo processins0_ where processins0_.InstanceId=? for update
12:03:16.585 [pool-1-thread-1] DEBUG o.h.loader.entity.EntityLoader - Static select for action ACTION_MERGE on entity org.drools.persistence.processinstance.ProcessInstanceInfo: select processins0_.InstanceId as InstanceId89_1_, processins0_.externalVariables as external2_89_1_, processins0_.lastModificationDate as lastModi3_89_1_, processins0_.lastReadDate as lastRead4_89_1_, processins0_.processId as processId89_1_, processins0_.processInstanceByteArray as processI6_89_1_, processins0_.startDate as startDate89_1_, processins0_.state as state89_1_, processins0_.OPTLOCK as OPTLOCK89_1_, variables1_.processInstanceId as processI5_3_, variables1_.id as id3_, variables1_.name as formula17_3_, variables1_.id as id90_0_, variables1_.name as name90_0_, variables1_.persister as persister90_0_, variables1_.processInstanceId as processI5_90_0_, variables1_.workItemId as workItemId90_0_, variables1_.entityClass as entityCl7_90_0_, variables1_.entityId as entityId90_0_, variables1_.content as content90_0_, variables1_.TYPE as TYPE90_0_ from ProcessInstanceInfo processins0_ left outer join VariableInstanceInfo variables1_ on processins0_.InstanceId=variables1_.processInstanceId where processins0_.InstanceId=?
12:03:16.585 [pool-1-thread-1] DEBUG o.h.loader.entity.EntityLoader - Static select for action ACTION_REFRESH on entity org.drools.persistence.processinstance.ProcessInstanceInfo: select processins0_.InstanceId as InstanceId89_1_, processins0_.externalVariables as external2_89_1_, processins0_.lastModificationDate as lastModi3_89_1_, processins0_.lastReadDate as lastRead4_89_1_, processins0_.processId as processId89_1_, processins0_.processInstanceByteArray as processI6_89_1_, processins0_.startDate as startDate89_1_, processins0_.state as state89_1_, processins0_.OPTLOCK as OPTLOCK89_1_, variables1_.processInstanceId as processI5_3_, variables1_.id as id3_, variables1_.name as formula17_3_, variables1_.id as id90_0_, variables1_.name as name90_0_, variables1_.persister as persister90_0_, variables1_.processInstanceId as processI5_90_0_, variables1_.workItemId as workItemId90_0_, variables1_.entityClass as entityCl7_90_0_, variables1_.entityId as entityId90_0_, variables1_.content as content90_0_, variables1_.TYPE as TYPE90_0_ from ProcessInstanceInfo processins0_ left outer join VariableInstanceInfo variables1_ on processins0_.InstanceId=variables1_.processInstanceId where processins0_.InstanceId=?
12:03:16.585 [pool-1-thread-1] DEBUG o.h.l.c.BasicCollectionLoader - Static select for collection org.drools.persistence.processinstance.ProcessInstanceInfo.eventTypes: select eventtypes0_.InstanceId as InstanceId0_, eventtypes0_.element as element0_ from EventTypes eventtypes0_ where eventtypes0_.InstanceId=?
12:03:16.585 [pool-1-thread-1] DEBUG o.h.l.collection.OneToManyLoader - Static select for one-to-many org.drools.persistence.processinstance.ProcessInstanceInfo.variables: select variables0_.processInstanceId as processI5_1_, variables0_.id as id1_, variables0_.name as formula17_1_, variables0_.id as id90_0_, variables0_.name as name90_0_, variables0_.persister as persister90_0_, variables0_.processInstanceId as processI5_90_0_, variables0_.workItemId as workItemId90_0_, variables0_.entityClass as entityCl7_90_0_, variables0_.entityId as entityId90_0_, variables0_.content as content90_0_, variables0_.TYPE as TYPE90_0_ from VariableInstanceInfo variables0_ where variables0_.processInstanceId=?
12:03:16.585 [pool-1-thread-1] DEBUG o.h.l.collection.OneToManyLoader - Static select for one-to-many org.drools.persistence.processinstance.WorkItemInfo.variables: select variables0_.workItemId as workItemId1_, variables0_.id as id1_, variables0_.name as formula16_1_, variables0_.id as id90_0_, variables0_.name as name90_0_, variables0_.persister as persister90_0_, variables0_.processInstanceId as processI5_90_0_, variables0_.workItemId as workItemId90_0_, variables0_.entityClass as entityCl7_90_0_, variables0_.entityId as entityId90_0_, variables0_.content as content90_0_, variables0_.TYPE as TYPE90_0_ from VariableInstanceInfo variables0_ where variables0_.workItemId=?
12:03:16.585 [pool-1-thread-1] DEBUG o.h.impl.SessionFactoryObjectFactory - registered: 8aa080de2f0d4c38012f0d4c53690008 (unnamed)
12:03:16.585 [pool-1-thread-1] INFO o.h.impl.SessionFactoryObjectFactory - Not binding factory to JNDI, no JNDI name configured
12:03:16.585 [pool-1-thread-1] DEBUG o.hibernate.impl.SessionFactoryImpl - instantiated session factory
12:03:16.585 [pool-1-thread-1] DEBUG o.h.cfg.AnnotationConfiguration - Execute first pass mapping processing
12:03:16.585 [pool-1-thread-1] DEBUG o.h.cfg.AnnotationConfiguration - Process hbm files
12:03:16.585 [pool-1-thread-1] DEBUG o.h.cfg.AnnotationConfiguration - Process annotated classes
12:03:16.585 [pool-1-thread-1] DEBUG o.h.cfg.AnnotationConfiguration - processing fk mappings (*ToOne and JoinedSubclass)
12:03:16.585 [pool-1-thread-1] DEBUG org.hibernate.cfg.Configuration - processing extends queue
12:03:16.585 [pool-1-thread-1] DEBUG org.hibernate.cfg.Configuration - processing collection mappings
12:03:16.585 [pool-1-thread-1] DEBUG org.hibernate.cfg.Configuration - processing native query and ResultSetMapping mappings
12:03:16.585 [pool-1-thread-1] DEBUG org.hibernate.cfg.Configuration - processing association property references
12:03:16.585 [pool-1-thread-1] DEBUG org.hibernate.cfg.Configuration - processing foreign key constraints
12:03:16.585 [pool-1-thread-1] DEBUG org.hibernate.cfg.Configuration - resolving reference to class: org.drools.persistence.processinstance.ProcessInstanceInfo
12:03:16.585 [pool-1-thread-1] DEBUG org.hibernate.cfg.Configuration - resolving reference to class: org.drools.persistence.processinstance.WorkItemInfo
12:03:16.585 [pool-1-thread-1] DEBUG org.hibernate.cfg.Configuration - resolving reference to class: org.drools.persistence.processinstance.ProcessInstanceInfo
12:03:16.585 [pool-1-thread-1] DEBUG o.h.cfg.AnnotationConfiguration - Execute first pass mapping processing
12:03:16.585 [pool-1-thread-1] DEBUG o.h.cfg.AnnotationConfiguration - Process hbm files
12:03:16.585 [pool-1-thread-1] DEBUG o.h.cfg.AnnotationConfiguration - Process annotated classes
12:03:16.585 [pool-1-thread-1] DEBUG o.h.cfg.AnnotationConfiguration - processing fk mappings (*ToOne and JoinedSubclass)
12:03:16.585 [pool-1-thread-1] DEBUG org.hibernate.cfg.Configuration - processing extends queue
12:03:16.585 [pool-1-thread-1] DEBUG org.hibernate.cfg.Configuration - processing collection mappings
12:03:16.585 [pool-1-thread-1] DEBUG org.hibernate.cfg.Configuration - processing native query and ResultSetMapping mappings
12:03:16.585 [pool-1-thread-1] DEBUG org.hibernate.cfg.Configuration - processing association property references
12:03:16.585 [pool-1-thread-1] DEBUG org.hibernate.cfg.Configuration - processing foreign key constraints
12:03:16.585 [pool-1-thread-1] DEBUG org.hibernate.cfg.Configuration - resolving reference to class: org.drools.persistence.processinstance.ProcessInstanceInfo
12:03:16.585 [pool-1-thread-1] DEBUG org.hibernate.cfg.Configuration - resolving reference to class: org.drools.persistence.processinstance.WorkItemInfo
12:03:16.585 [pool-1-thread-1] DEBUG org.hibernate.cfg.Configuration - resolving reference to class: org.drools.persistence.processinstance.ProcessInstanceInfo
12:03:16.585 [pool-1-thread-1] INFO o.h.tool.hbm2ddl.SchemaExport - Running hbm2ddl schema export
12:03:16.585 [pool-1-thread-1] DEBUG o.h.tool.hbm2ddl.SchemaExport - import file not found: /import.sql
12:03:16.585 [pool-1-thread-1] INFO o.h.tool.hbm2ddl.SchemaExport - exporting generated schema to database
12:03:16.585 [pool-1-thread-1] DEBUG o.h.tool.hbm2ddl.SchemaExport - alter table EventTypes drop constraint FKB0E5621F82849DA
12:03:16.585 [pool-1-thread-1] DEBUG o.h.tool.hbm2ddl.SchemaExport - alter table VariableInstanceInfo drop constraint FK7BE49B9FF8EDED9
12:03:16.585 [pool-1-thread-1] DEBUG o.h.tool.hbm2ddl.SchemaExport - alter table VariableInstanceInfo drop constraint FK7BE49B9F85916989
12:03:16.585 [pool-1-thread-1] DEBUG o.h.tool.hbm2ddl.SchemaExport - drop table EventTypes if exists
12:03:16.585 [pool-1-thread-1] DEBUG o.h.tool.hbm2ddl.SchemaExport - drop table ProcessInstanceInfo if exists
12:03:16.585 [pool-1-thread-1] DEBUG o.h.tool.hbm2ddl.SchemaExport - drop table SessionInfo if exists
12:03:16.585 [pool-1-thread-1] DEBUG o.h.tool.hbm2ddl.SchemaExport - drop table VariableInstanceInfo if exists
12:03:16.585 [pool-1-thread-1] DEBUG o.h.tool.hbm2ddl.SchemaExport - drop table WorkItemInfo if exists
12:03:16.585 [pool-1-thread-1] DEBUG o.h.tool.hbm2ddl.SchemaExport - create table EventTypes (InstanceId bigint not null, element varchar(255))
12:03:16.585 [pool-1-thread-1] DEBUG o.h.tool.hbm2ddl.SchemaExport - create table ProcessInstanceInfo (InstanceId bigint generated by default as identity, externalVariables bit not null, lastModificationDate timestamp, lastReadDate timestamp, processId varchar(255), processInstanceByteArray blob, startDate timestamp, state integer not null, OPTLOCK integer, primary key (InstanceId))
12:03:16.585 [pool-1-thread-1] DEBUG o.h.tool.hbm2ddl.SchemaExport - create table SessionInfo (id integer generated by default as identity, lastModificationDate timestamp, rulesByteArray blob, startDate timestamp, OPTLOCK integer, primary key (id))
12:03:16.585 [pool-1-thread-1] DEBUG o.h.tool.hbm2ddl.SchemaExport - create table VariableInstanceInfo (TYPE varchar(50) not null, id bigint generated by default as identity, name varchar(255), persister varchar(255), processInstanceId bigint, workItemId bigint, entityClass varchar(255), entityId binary(255), content blob, primary key (id))
12:03:16.585 [pool-1-thread-1] DEBUG o.h.tool.hbm2ddl.SchemaExport - create table WorkItemInfo (workItemId bigint generated by default as identity, creationDate timestamp, externalVariables bit not null, name varchar(255), processInstanceId bigint not null, state bigint not null, OPTLOCK integer, workItemByteArray blob, primary key (workItemId))
12:03:16.585 [pool-1-thread-1] DEBUG o.h.tool.hbm2ddl.SchemaExport - alter table EventTypes add constraint FKB0E5621F82849DA foreign key (InstanceId) references ProcessInstanceInfo
12:03:16.585 [pool-1-thread-1] DEBUG o.h.tool.hbm2ddl.SchemaExport - alter table VariableInstanceInfo add constraint FK7BE49B9FF8EDED9 foreign key (workItemId) references WorkItemInfo
12:03:16.585 [pool-1-thread-1] DEBUG o.h.tool.hbm2ddl.SchemaExport - alter table VariableInstanceInfo add constraint FK7BE49B9F85916989 foreign key (processInstanceId) references ProcessInstanceInfo
12:03:16.585 [pool-1-thread-1] INFO o.h.tool.hbm2ddl.SchemaExport - schema export complete
12:03:16.585 [pool-1-thread-1] DEBUG o.hibernate.impl.SessionFactoryImpl - Checking 1 named HQL queries
12:03:16.585 [pool-1-thread-1] DEBUG o.hibernate.impl.SessionFactoryImpl - Checking named query: ProcessInstancesWaitingForEvent
12:03:16.585 [pool-1-thread-1] DEBUG o.h.hql.ast.QueryTranslatorImpl - parse() - HQL: select processInstanceInfo.processInstanceId from org.drools.persistence.processinstance.ProcessInstanceInfo processInstanceInfo where :type in elements(processInstanceInfo.eventTypes)
12:03:16.601 [pool-1-thread-1] DEBUG org.hibernate.hql.ast.AST - --- HQL AST ---
\-[QUERY] 'query'
+-[SELECT_FROM] 'SELECT_FROM'
| +-[FROM] 'from'
| | \-[RANGE] 'RANGE'
| | +-[DOT] '.'
| | | +-[DOT] '.'
| | | | +-[DOT] '.'
| | | | | +-[DOT] '.'
| | | | | | +-[IDENT] 'org'
| | | | | | \-[IDENT] 'drools'
| | | | | \-[IDENT] 'persistence'
| | | | \-[IDENT] 'processinstance'
| | | \-[IDENT] 'ProcessInstanceInfo'
| | \-[ALIAS] 'processInstanceInfo'
| \-[SELECT] 'select'
| \-[DOT] '.'
| +-[IDENT] 'processInstanceInfo'
| \-[IDENT] 'processInstanceId'
\-[WHERE] 'where'
\-[IN] 'in'
+-[COLON] ':'
| \-[IDENT] 'type'
\-[IN_LIST] 'inList'
\-[ELEMENTS] 'elements'
\-[DOT] '.'
+-[IDENT] 'processInstanceInfo'
\-[IDENT] 'eventTypes'
12:03:16.601 [pool-1-thread-1] DEBUG org.hibernate.hql.ast.ErrorCounter - throwQueryException() : no errors
12:03:16.601 [pool-1-thread-1] DEBUG o.h.hql.antlr.HqlSqlBaseWalker - select << begin [level=1, statement=select]
12:03:16.601 [pool-1-thread-1] DEBUG o.hibernate.hql.ast.tree.FromElement - FromClause{level=1} : org.drools.persistence.processinstance.ProcessInstanceInfo (processInstanceInfo) -> processins0_
12:03:16.601 [pool-1-thread-1] DEBUG o.h.hql.ast.tree.FromReferenceNode - Resolved : processInstanceInfo -> processins0_.InstanceId
12:03:16.601 [pool-1-thread-1] DEBUG org.hibernate.hql.ast.tree.DotNode - getDataType() : processInstanceId -> org.hibernate.type.LongType at 1c04ec59
12:03:16.601 [pool-1-thread-1] DEBUG o.h.hql.ast.tree.FromReferenceNode - Resolved : processInstanceInfo.processInstanceId -> processins0_.InstanceId
12:03:16.601 [pool-1-thread-1] DEBUG o.h.hql.ast.tree.FromReferenceNode - Resolved : processInstanceInfo -> processins0_.InstanceId
12:03:16.601 [pool-1-thread-1] DEBUG org.hibernate.hql.ast.tree.DotNode - getDataType() : eventTypes -> org.hibernate.type.SetType(org.drools.persistence.processinstance.ProcessInstanceInfo.eventTypes)
12:03:16.601 [pool-1-thread-1] DEBUG o.hibernate.hql.ast.tree.FromElement - FromClause{level=1} : null (no alias) -> eventtypes1_
12:03:16.601 [pool-1-thread-1] DEBUG o.hibernate.hql.ast.tree.FromClause - addCollectionJoinFromElementByPath() : processInstanceInfo.eventTypes -> EventTypes
12:03:16.601 [pool-1-thread-1] DEBUG org.hibernate.hql.ast.tree.DotNode - dereferenceCollection() : Created new FROM element for processInstanceInfo.eventTypes : EventTypes eventtypes1_
12:03:16.601 [pool-1-thread-1] DEBUG o.hibernate.hql.ast.tree.MethodNode - Creating elements for processInstanceInfo.eventTypes[].elements
12:03:16.601 [pool-1-thread-1] DEBUG o.h.hql.ast.tree.FromElementType - toColumns(eventtypes1_,elements) : subquery = select eventtypes1_.element from EventTypes eventtypes1_ where processins0_.InstanceId=eventtypes1_.InstanceId
12:03:16.601 [pool-1-thread-1] DEBUG o.h.hql.antlr.HqlSqlBaseWalker - select : finishing up [level=1, statement=select]
12:03:16.601 [pool-1-thread-1] DEBUG org.hibernate.hql.ast.HqlSqlWalker - processQuery() : ( SELECT ( {select clause} ( processins0_.InstanceId processins0_.InstanceId processInstanceId ) ) ( FromClause{level=1} ) ( where ( in ? ( inList ( select eventtypes1_.element from EventTypes eventtypes1_ where processins0_.InstanceId=eventtypes1_.InstanceId ( . processins0_.InstanceId eventTypes ) ) ) ) ) )
12:03:16.601 [pool-1-thread-1] DEBUG o.h.hql.ast.util.JoinProcessor - Using FROM fragment [ProcessInstanceInfo processins0_]
12:03:16.601 [pool-1-thread-1] DEBUG o.h.hql.antlr.HqlSqlBaseWalker - select >> end [level=1, statement=select]
12:03:16.601 [pool-1-thread-1] DEBUG org.hibernate.hql.ast.AST - --- SQL AST ---
\-[SELECT] QueryNode: 'SELECT' querySpaces (ProcessInstanceInfo,EventTypes)
+-[SELECT_CLAUSE] SelectClause: '{select clause}'
| +-[DOT] DotNode: 'processins0_.InstanceId' {propertyName=processInstanceId,dereferenceType=4,propertyPath=processInstanceId,path=processInstanceInfo.processInstanceId,tableAlias=processins0_,className=org.drools.persistence.processinstance.ProcessInstanceInfo,classAlias=processInstanceInfo}
| | +-[ALIAS_REF] IdentNode: 'processins0_.InstanceId' {alias=processInstanceInfo, className=org.drools.persistence.processinstance.ProcessInstanceInfo, tableAlias=processins0_}
| | \-[IDENT] IdentNode: 'processInstanceId' {originalText=processInstanceId}
| \-[SELECT_COLUMNS] SqlNode: ' as col_0_0_'
+-[FROM] FromClause: 'from' FromClause{level=1, fromElementCounter=1, fromElements=2, fromElementByClassAlias=[processInstanceInfo], fromElementByTableAlias=[processins0_, eventtypes1_], fromElementsByPath=[], collectionJoinFromElementsByPath=[processInstanceInfo.eventTypes], impliedElements=[]}
| +-[FROM_FRAGMENT] FromElement: 'ProcessInstanceInfo processins0_' FromElement{explicit,collection join,not a fetch join,fetch non-lazy properties,classAlias=processInstanceInfo,role=null,tableName=ProcessInstanceInfo,tableAlias=processins0_,origin=null,colums={,className=org.drools.persistence.processinstance.ProcessInstanceInfo}}
| \-[FROM_FRAGMENT] ImpliedFromElement: '' ImpliedFromElement{implied,collection join,not a fetch join,fetch non-lazy properties,classAlias=null,role=org.drools.persistence.processinstance.ProcessInstanceInfo.eventTypes,tableName={none},tableAlias=eventtypes1_,origin=ProcessInstanceInfo processins0_,colums={,className=null}}
\-[WHERE] SqlNode: 'where'
\-[IN] InLogicOperatorNode: 'in'
+-[NAMED_PARAM] ParameterNode: '?' {name=type, expectedType=null}
\-[IN_LIST] SqlNode: 'inList'
\-[SQL_TOKEN] CollectionFunction: 'select eventtypes1_.element from EventTypes eventtypes1_ where processins0_.InstanceId=eventtypes1_.InstanceId' {method=elements,selectColumns=[select eventtypes1_.element from EventTypes eventtypes1_ where processins0_.InstanceId=eventtypes1_.InstanceId],fromElement=eventtypes1_}
\-[DOT] DotNode: '.' {propertyName=eventTypes,dereferenceType=3,propertyPath=eventTypes,path=processInstanceInfo.eventTypes,tableAlias=eventtypes1_,className=null,classAlias=null}
+-[ALIAS_REF] IdentNode: 'processins0_.InstanceId' {alias=processInstanceInfo, className=org.drools.persistence.processinstance.ProcessInstanceInfo, tableAlias=processins0_}
\-[IDENT] IdentNode: 'eventTypes' {originalText=eventTypes}
12:03:16.601 [pool-1-thread-1] DEBUG org.hibernate.hql.ast.ErrorCounter - throwQueryException() : no errors
12:03:16.601 [pool-1-thread-1] DEBUG o.h.hql.ast.QueryTranslatorImpl - HQL: select processInstanceInfo.processInstanceId from org.drools.persistence.processinstance.ProcessInstanceInfo processInstanceInfo where :type in elements(processInstanceInfo.eventTypes)
12:03:16.601 [pool-1-thread-1] DEBUG o.h.hql.ast.QueryTranslatorImpl - SQL: select processins0_.InstanceId as col_0_0_ from ProcessInstanceInfo processins0_ where ? in (select eventtypes1_.element from EventTypes eventtypes1_ where processins0_.InstanceId=eventtypes1_.InstanceId)
12:03:16.601 [pool-1-thread-1] DEBUG org.hibernate.hql.ast.ErrorCounter - throwQueryException() : no errors
START MY CODE
12:03:16.601 [pool-1-thread-1] DEBUG o.hibernate.impl.SessionFactoryImpl - Checking 0 named SQL queries
12:03:16.616 [pool-1-thread-1] DEBUG c.p.process.drools.ProxyBuilder - Approval constraint [StepApproval( approved == true, sliceValue == "NO_SLICE", approvalStepNodeId == "4e04c435-8f06-4bcc-b8a4-e91744575c2b" )]
12:03:16.616 [pool-1-thread-1] DEBUG c.p.process.drools.DroolsFlowAdapter - Created new StepNodeInstance [step-1 Step] with ID [06ea0b5c-6ad0-43a7-8d53-4a0304c094a0]
12:03:16.616 [pool-1-thread-1] DEBUG c.p.process.drools.DroolsFlowAdapter - Created new ImpliedStepNodeInstance [step-1 Approval] with ID [35fdffaf-ed0c-45dc-86ac-9a8a7cd851f5]
12:03:16.616 [pool-1-thread-1] DEBUG c.p.process.drools.DroolsFlowAdapter - Starting process flow [flow-1] instance [29de16c7-8803-4c57-bcc5-5cf9afeddb14]
12:03:16.694 [pool-1-thread-1] DEBUG o.d.p.s.SingleSessionCommandService - Instantiating DroolsSpringTransactionManager
12:03:16.694 [pool-1-thread-1] DEBUG o.d.c.s.b.p.DroolsSpringTransactionManager - Current TX name (According to TransactionSynchronizationManager) : null
12:03:16.694 [pool-1-thread-1] DEBUG o.s.orm.jpa.JpaTransactionManager - Found thread-bound EntityManager [org.hibernate.ejb.EntityManagerImpl at 3851ddd2] for JPA transaction
12:03:16.694 [pool-1-thread-1] DEBUG o.s.orm.jpa.JpaTransactionManager - Creating new transaction with name [null]: PROPAGATION_REQUIRED,ISOLATION_DEFAULT
12:03:16.694 [pool-1-thread-1] DEBUG org.hibernate.impl.SessionImpl - opened session at timestamp: 13015981966
12:03:16.694 [pool-1-thread-1] DEBUG o.h.transaction.JDBCTransaction - begin
12:03:16.694 [pool-1-thread-1] DEBUG org.hibernate.jdbc.ConnectionManager - opening JDBC connection
12:03:16.694 [pool-1-thread-1] DEBUG o.h.transaction.JDBCTransaction - current autocommit status: false
12:03:16.694 [pool-1-thread-1] DEBUG o.s.orm.jpa.JpaTransactionManager - Exposing JPA transaction as JDBC transaction [org.springframework.orm.jpa.vendor.HibernateJpaDialect$HibernateConnectionHandle at 6ba22e1]
12:03:16.694 [pool-1-thread-1] DEBUG o.s.o.j.ExtendedEntityManagerCreator$ExtendedEntityManagerInvocationHandler - Joined local transaction
12:03:16.694 [pool-1-thread-1] DEBUG o.h.e.def.AbstractSaveEventListener - executing identity-insert immediately
12:03:16.694 [pool-1-thread-1] DEBUG org.hibernate.jdbc.AbstractBatcher - about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
12:03:16.694 [pool-1-thread-1] DEBUG org.hibernate.SQL - insert into SessionInfo (id, lastModificationDate, rulesByteArray, startDate, OPTLOCK) values (null, ?, ?, ?, ?)
12:03:16.694 [pool-1-thread-1] TRACE org.hibernate.type.TimestampType - binding null to parameter: 1
12:03:16.694 [pool-1-thread-1] TRACE org.hibernate.type.TimestampType - binding '2011-03-31 12:03:16' to parameter: 3
12:03:16.694 [pool-1-thread-1] TRACE org.hibernate.type.IntegerType - binding '0' to parameter: 4
12:03:16.694 [pool-1-thread-1] DEBUG o.h.id.IdentifierGeneratorFactory - Natively generated identity: 1
12:03:16.694 [pool-1-thread-1] DEBUG org.hibernate.jdbc.AbstractBatcher - about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
12:03:16.694 [pool-1-thread-1] DEBUG o.s.orm.jpa.JpaTransactionManager - Initiating transaction commit
12:03:16.694 [pool-1-thread-1] DEBUG o.s.orm.jpa.JpaTransactionManager - Committing JPA transaction on EntityManager [org.hibernate.ejb.EntityManagerImpl at 3851ddd2]
12:03:16.694 [pool-1-thread-1] DEBUG o.h.transaction.JDBCTransaction - commit
12:03:16.694 [pool-1-thread-1] DEBUG o.h.e.d.AbstractFlushingEventListener - processing flush-time cascades
12:03:16.694 [pool-1-thread-1] DEBUG o.h.e.d.AbstractFlushingEventListener - dirty checking collections
12:03:16.694 [pool-1-thread-1] DEBUG o.h.e.d.AbstractFlushingEventListener - Flushed: 0 insertions, 0 updates, 0 deletions to 1 objects
12:03:16.694 [pool-1-thread-1] DEBUG o.h.e.d.AbstractFlushingEventListener - Flushed: 0 (re)creations, 0 updates, 0 removals to 0 collections
12:03:16.694 [pool-1-thread-1] DEBUG org.hibernate.pretty.Printer - listing entities:
12:03:16.694 [pool-1-thread-1] DEBUG org.hibernate.pretty.Printer - org.drools.persistence.session.SessionInfo{id=1, startDate=2011-03-31 12:03:16, rulesByteArray=2c6d8085f7e6808080808080808080808080808080808080808080808080808080808080808080808d8084cdc1c9ce808081808d8084cdc1c9ce8081808180808080808081808180818081808a80808081808080808081808080818180818081808180808080808080808081, lastModificationDate=null, version=0}
12:03:16.694 [pool-1-thread-1] DEBUG o.h.transaction.JDBCTransaction - committed JDBC Connection
12:03:16.694 [pool-1-thread-1] DEBUG org.hibernate.jdbc.ConnectionManager - aggressively releasing JDBC connection
12:03:16.694 [pool-1-thread-1] DEBUG org.hibernate.jdbc.ConnectionManager - releasing JDBC connection [ (open PreparedStatements: 0, globally: 0) (open ResultSets: 0, globally: 0)]
12:03:16.694 [pool-1-thread-1] DEBUG o.s.orm.jpa.JpaTransactionManager - Not closing pre-bound JPA EntityManager after transaction
12:03:16.694 [pool-1-thread-1] DEBUG o.d.c.s.b.p.DroolsSpringTransactionManager - Current TX name (According to TransactionSynchronizationManager) : null
12:03:16.694 [pool-1-thread-1] DEBUG o.s.orm.jpa.JpaTransactionManager - Found thread-bound EntityManager [org.hibernate.ejb.EntityManagerImpl at 3851ddd2] for JPA transaction
12:03:16.694 [pool-1-thread-1] DEBUG o.s.orm.jpa.JpaTransactionManager - Creating new transaction with name [null]: PROPAGATION_REQUIRED,ISOLATION_DEFAULT
12:03:16.694 [pool-1-thread-1] DEBUG o.h.transaction.JDBCTransaction - begin
12:03:16.694 [pool-1-thread-1] DEBUG org.hibernate.jdbc.ConnectionManager - opening JDBC connection
12:03:16.694 [pool-1-thread-1] DEBUG o.h.transaction.JDBCTransaction - current autocommit status: false
12:03:16.694 [pool-1-thread-1] DEBUG o.s.orm.jpa.JpaTransactionManager - Exposing JPA transaction as JDBC transaction [org.springframework.orm.jpa.vendor.HibernateJpaDialect$HibernateConnectionHandle at 1722fe15]
12:03:16.694 [pool-1-thread-1] DEBUG org.hibernate.impl.SessionImpl - opened session at timestamp: 13015981966
12:03:16.694 [pool-1-thread-1] DEBUG o.h.transaction.JDBCTransaction - begin
12:03:16.694 [pool-1-thread-1] DEBUG org.hibernate.jdbc.ConnectionManager - opening JDBC connection
12:03:16.694 [pool-1-thread-1] DEBUG o.h.transaction.JDBCTransaction - current autocommit status: false
12:03:16.694 [pool-1-thread-1] DEBUG o.s.o.j.ExtendedEntityManagerCreator$ExtendedEntityManagerInvocationHandler - Starting resource local transaction on application-managed EntityManager [org.hibernate.ejb.EntityManagerImpl at 7a572090]
12:03:16.694 [pool-1-thread-1] DEBUG o.s.o.j.ExtendedEntityManagerCreator$ExtendedEntityManagerInvocationHandler - Joined local transaction
12:03:16.694 [pool-1-thread-1] DEBUG o.s.o.j.ExtendedEntityManagerCreator$ExtendedEntityManagerInvocationHandler - Joined local transaction
12:03:16.694 [pool-1-thread-1] DEBUG o.s.orm.jpa.JpaTransactionManager - Initiating transaction commit
12:03:16.694 [pool-1-thread-1] DEBUG o.s.orm.jpa.JpaTransactionManager - Committing JPA transaction on EntityManager [org.hibernate.ejb.EntityManagerImpl at 3851ddd2]
12:03:16.694 [pool-1-thread-1] DEBUG o.h.transaction.JDBCTransaction - commit
12:03:16.694 [pool-1-thread-1] DEBUG o.h.e.d.AbstractFlushingEventListener - processing flush-time cascades
12:03:16.694 [pool-1-thread-1] DEBUG o.h.e.d.AbstractFlushingEventListener - dirty checking collections
12:03:16.694 [pool-1-thread-1] DEBUG o.h.e.d.AbstractFlushingEventListener - Flushed: 0 insertions, 0 updates, 0 deletions to 1 objects
12:03:16.694 [pool-1-thread-1] DEBUG o.h.e.d.AbstractFlushingEventListener - Flushed: 0 (re)creations, 0 updates, 0 removals to 0 collections
12:03:16.694 [pool-1-thread-1] DEBUG org.hibernate.pretty.Printer - listing entities:
12:03:16.694 [pool-1-thread-1] DEBUG org.hibernate.pretty.Printer - org.drools.persistence.session.SessionInfo{id=1, startDate=2011-03-31 12:03:16, rulesByteArray=2c6d8085f7e6808080808080808080808080808080808080808080808080808080808080808080808d8084cdc1c9ce808081808d8084cdc1c9ce8081808180808080808081808180818081808a80808081808080808081808080818180818081808180808080808080808081, lastModificationDate=null, version=0}
12:03:16.694 [pool-1-thread-1] DEBUG o.h.transaction.JDBCTransaction - committed JDBC Connection
12:03:16.694 [pool-1-thread-1] DEBUG org.hibernate.jdbc.ConnectionManager - aggressively releasing JDBC connection
12:03:16.694 [pool-1-thread-1] DEBUG org.hibernate.jdbc.ConnectionManager - releasing JDBC connection [ (open PreparedStatements: 0, globally: 0) (open ResultSets: 0, globally: 0)]
12:03:16.694 [pool-1-thread-1] DEBUG o.h.transaction.JDBCTransaction - commit
12:03:16.710 [pool-1-thread-1] DEBUG o.h.transaction.JDBCTransaction - committed JDBC Connection
12:03:16.710 [pool-1-thread-1] DEBUG org.hibernate.jdbc.ConnectionManager - aggressively releasing JDBC connection
12:03:16.710 [pool-1-thread-1] DEBUG org.hibernate.jdbc.ConnectionManager - releasing JDBC connection [ (open PreparedStatements: 0, globally: 0) (open ResultSets: 0, globally: 0)]
12:03:16.710 [pool-1-thread-1] DEBUG o.s.orm.jpa.JpaTransactionManager - Not closing pre-bound JPA EntityManager after transaction
12:03:16.710 [pool-1-thread-1] DEBUG o.d.c.s.b.p.DroolsSpringTransactionManager - Current TX name (According to TransactionSynchronizationManager) : null
12:03:16.710 [pool-1-thread-1] DEBUG o.s.orm.jpa.JpaTransactionManager - Found thread-bound EntityManager [org.hibernate.ejb.EntityManagerImpl at 3851ddd2] for JPA transaction
12:03:16.710 [pool-1-thread-1] DEBUG o.s.orm.jpa.JpaTransactionManager - Creating new transaction with name [null]: PROPAGATION_REQUIRED,ISOLATION_DEFAULT
12:03:16.710 [pool-1-thread-1] DEBUG o.h.transaction.JDBCTransaction - begin
12:03:16.710 [pool-1-thread-1] DEBUG org.hibernate.jdbc.ConnectionManager - opening JDBC connection
12:03:16.710 [pool-1-thread-1] DEBUG o.h.transaction.JDBCTransaction - current autocommit status: false
12:03:16.710 [pool-1-thread-1] DEBUG o.s.orm.jpa.JpaTransactionManager - Exposing JPA transaction as JDBC transaction [org.springframework.orm.jpa.vendor.HibernateJpaDialect$HibernateConnectionHandle at 6e1b0caf]
12:03:16.710 [pool-1-thread-1] DEBUG org.hibernate.impl.SessionImpl - opened session at timestamp: 13015981967
12:03:16.710 [pool-1-thread-1] DEBUG o.h.transaction.JDBCTransaction - begin
12:03:16.710 [pool-1-thread-1] DEBUG org.hibernate.jdbc.ConnectionManager - opening JDBC connection
12:03:16.710 [pool-1-thread-1] DEBUG o.h.transaction.JDBCTransaction - current autocommit status: false
12:03:16.710 [pool-1-thread-1] DEBUG o.s.o.j.ExtendedEntityManagerCreator$ExtendedEntityManagerInvocationHandler - Starting resource local transaction on application-managed EntityManager [org.hibernate.ejb.EntityManagerImpl at 31ddeda2]
12:03:16.710 [pool-1-thread-1] DEBUG o.s.o.j.ExtendedEntityManagerCreator$ExtendedEntityManagerInvocationHandler - Joined local transaction
12:03:16.710 [pool-1-thread-1] DEBUG o.s.o.j.ExtendedEntityManagerCreator$ExtendedEntityManagerInvocationHandler - Joined local transaction
12:03:16.710 [pool-1-thread-1] DEBUG o.s.orm.jpa.JpaTransactionManager - Initiating transaction commit
12:03:16.710 [pool-1-thread-1] DEBUG o.s.orm.jpa.JpaTransactionManager - Committing JPA transaction on EntityManager [org.hibernate.ejb.EntityManagerImpl at 3851ddd2]
12:03:16.710 [pool-1-thread-1] DEBUG o.h.transaction.JDBCTransaction - commit
12:03:16.710 [pool-1-thread-1] DEBUG o.h.e.d.AbstractFlushingEventListener - processing flush-time cascades
12:03:16.710 [pool-1-thread-1] DEBUG o.h.e.d.AbstractFlushingEventListener - dirty checking collections
12:03:16.710 [pool-1-thread-1] DEBUG o.h.e.d.AbstractFlushingEventListener - Flushed: 0 insertions, 0 updates, 0 deletions to 1 objects
12:03:16.710 [pool-1-thread-1] DEBUG o.h.e.d.AbstractFlushingEventListener - Flushed: 0 (re)creations, 0 updates, 0 removals to 0 collections
12:03:16.710 [pool-1-thread-1] DEBUG org.hibernate.pretty.Printer - listing entities:
12:03:16.710 [pool-1-thread-1] DEBUG org.hibernate.pretty.Printer - org.drools.persistence.session.SessionInfo{id=1, startDate=2011-03-31 12:03:16, rulesByteArray=2c6d8085f7e6808080808080808080808080808080808080808080808080808080808080808080808d8084cdc1c9ce808081808d8084cdc1c9ce8081808180808080808081808180818081808a80808081808080808081808080818180818081808180808080808080808081, lastModificationDate=null, version=0}
12:03:16.710 [pool-1-thread-1] DEBUG o.h.transaction.JDBCTransaction - committed JDBC Connection
12:03:16.710 [pool-1-thread-1] DEBUG org.hibernate.jdbc.ConnectionManager - aggressively releasing JDBC connection
12:03:16.710 [pool-1-thread-1] DEBUG org.hibernate.jdbc.ConnectionManager - releasing JDBC connection [ (open PreparedStatements: 0, globally: 0) (open ResultSets: 0, globally: 0)]
12:03:16.710 [pool-1-thread-1] DEBUG o.h.transaction.JDBCTransaction - commit
12:03:16.710 [pool-1-thread-1] DEBUG o.h.transaction.JDBCTransaction - committed JDBC Connection
12:03:16.710 [pool-1-thread-1] DEBUG org.hibernate.jdbc.ConnectionManager - aggressively releasing JDBC connection
12:03:16.710 [pool-1-thread-1] DEBUG org.hibernate.jdbc.ConnectionManager - releasing JDBC connection [ (open PreparedStatements: 0, globally: 0) (open ResultSets: 0, globally: 0)]
12:03:16.710 [pool-1-thread-1] DEBUG o.s.orm.jpa.JpaTransactionManager - Not closing pre-bound JPA EntityManager after transaction
12:03:16.710 [pool-1-thread-1] DEBUG o.d.c.s.b.p.DroolsSpringTransactionManager - Current TX name (According to TransactionSynchronizationManager) : null
12:03:16.710 [pool-1-thread-1] DEBUG o.s.orm.jpa.JpaTransactionManager - Found thread-bound EntityManager [org.hibernate.ejb.EntityManagerImpl at 3851ddd2] for JPA transaction
12:03:16.710 [pool-1-thread-1] DEBUG o.s.orm.jpa.JpaTransactionManager - Creating new transaction with name [null]: PROPAGATION_REQUIRED,ISOLATION_DEFAULT
12:03:16.710 [pool-1-thread-1] DEBUG o.h.transaction.JDBCTransaction - begin
12:03:16.710 [pool-1-thread-1] DEBUG org.hibernate.jdbc.ConnectionManager - opening JDBC connection
12:03:16.710 [pool-1-thread-1] DEBUG o.h.transaction.JDBCTransaction - current autocommit status: false
12:03:16.710 [pool-1-thread-1] DEBUG o.s.orm.jpa.JpaTransactionManager - Exposing JPA transaction as JDBC transaction [org.springframework.orm.jpa.vendor.HibernateJpaDialect$HibernateConnectionHandle at 611c4041]
12:03:16.710 [pool-1-thread-1] DEBUG org.hibernate.impl.SessionImpl - opened session at timestamp: 13015981967
12:03:16.710 [pool-1-thread-1] DEBUG o.h.transaction.JDBCTransaction - begin
12:03:16.710 [pool-1-thread-1] DEBUG org.hibernate.jdbc.ConnectionManager - opening JDBC connection
12:03:16.710 [pool-1-thread-1] DEBUG o.h.transaction.JDBCTransaction - current autocommit status: false
12:03:16.710 [pool-1-thread-1] DEBUG o.s.o.j.ExtendedEntityManagerCreator$ExtendedEntityManagerInvocationHandler - Starting resource local transaction on application-managed EntityManager [org.hibernate.ejb.EntityManagerImpl at 5be9d36]
12:03:16.710 [pool-1-thread-1] DEBUG o.s.o.j.ExtendedEntityManagerCreator$ExtendedEntityManagerInvocationHandler - Joined local transaction
12:03:16.710 [pool-1-thread-1] DEBUG o.s.o.j.ExtendedEntityManagerCreator$ExtendedEntityManagerInvocationHandler - Joined local transaction
12:03:16.710 [pool-1-thread-1] DEBUG o.s.orm.jpa.JpaTransactionManager - Initiating transaction commit
12:03:16.710 [pool-1-thread-1] DEBUG o.s.orm.jpa.JpaTransactionManager - Committing JPA transaction on EntityManager [org.hibernate.ejb.EntityManagerImpl at 3851ddd2]
12:03:16.710 [pool-1-thread-1] DEBUG o.h.transaction.JDBCTransaction - commit
12:03:16.710 [pool-1-thread-1] DEBUG o.h.e.d.AbstractFlushingEventListener - processing flush-time cascades
12:03:16.710 [pool-1-thread-1] DEBUG o.h.e.d.AbstractFlushingEventListener - dirty checking collections
12:03:16.710 [pool-1-thread-1] DEBUG o.h.e.d.AbstractFlushingEventListener - Flushed: 0 insertions, 0 updates, 0 deletions to 1 objects
12:03:16.710 [pool-1-thread-1] DEBUG o.h.e.d.AbstractFlushingEventListener - Flushed: 0 (re)creations, 0 updates, 0 removals to 0 collections
12:03:16.710 [pool-1-thread-1] DEBUG org.hibernate.pretty.Printer - listing entities:
12:03:16.710 [pool-1-thread-1] DEBUG org.hibernate.pretty.Printer - org.drools.persistence.session.SessionInfo{id=1, startDate=2011-03-31 12:03:16, rulesByteArray=2c6d8085f7e6808080808080808080808080808080808080808080808080808080808080808080808d8084cdc1c9ce808081808d8084cdc1c9ce8081808180808080808081808180818081808a80808081808080808081808080818180818081808180808080808080808081, lastModificationDate=null, version=0}
12:03:16.710 [pool-1-thread-1] DEBUG o.h.transaction.JDBCTransaction - committed JDBC Connection
12:03:16.710 [pool-1-thread-1] DEBUG org.hibernate.jdbc.ConnectionManager - aggressively releasing JDBC connection
12:03:16.710 [pool-1-thread-1] DEBUG org.hibernate.jdbc.ConnectionManager - releasing JDBC connection [ (open PreparedStatements: 0, globally: 0) (open ResultSets: 0, globally: 0)]
12:03:16.710 [pool-1-thread-1] DEBUG o.h.transaction.JDBCTransaction - commit
12:03:16.710 [pool-1-thread-1] DEBUG o.h.transaction.JDBCTransaction - committed JDBC Connection
12:03:16.710 [pool-1-thread-1] DEBUG org.hibernate.jdbc.ConnectionManager - aggressively releasing JDBC connection
12:03:16.710 [pool-1-thread-1] DEBUG org.hibernate.jdbc.ConnectionManager - releasing JDBC connection [ (open PreparedStatements: 0, globally: 0) (open ResultSets: 0, globally: 0)]
12:03:16.710 [pool-1-thread-1] DEBUG o.s.orm.jpa.JpaTransactionManager - Not closing pre-bound JPA EntityManager after transaction
12:03:16.710 [pool-1-thread-1] DEBUG o.d.c.s.b.p.DroolsSpringTransactionManager - Current TX name (According to TransactionSynchronizationManager) : null
12:03:16.710 [pool-1-thread-1] DEBUG o.s.orm.jpa.JpaTransactionManager - Found thread-bound EntityManager [org.hibernate.ejb.EntityManagerImpl at 3851ddd2] for JPA transaction
12:03:16.710 [pool-1-thread-1] DEBUG o.s.orm.jpa.JpaTransactionManager - Creating new transaction with name [null]: PROPAGATION_REQUIRED,ISOLATION_DEFAULT
12:03:16.710 [pool-1-thread-1] DEBUG o.h.transaction.JDBCTransaction - begin
12:03:16.710 [pool-1-thread-1] DEBUG org.hibernate.jdbc.ConnectionManager - opening JDBC connection
12:03:16.710 [pool-1-thread-1] DEBUG o.h.transaction.JDBCTransaction - current autocommit status: false
12:03:16.710 [pool-1-thread-1] DEBUG o.s.orm.jpa.JpaTransactionManager - Exposing JPA transaction as JDBC transaction [org.springframework.orm.jpa.vendor.HibernateJpaDialect$HibernateConnectionHandle at 2543472c]
12:03:16.710 [pool-1-thread-1] DEBUG org.hibernate.impl.SessionImpl - opened session at timestamp: 13015981967
12:03:16.710 [pool-1-thread-1] DEBUG o.h.transaction.JDBCTransaction - begin
12:03:16.710 [pool-1-thread-1] DEBUG org.hibernate.jdbc.ConnectionManager - opening JDBC connection
12:03:16.710 [pool-1-thread-1] DEBUG o.h.transaction.JDBCTransaction - current autocommit status: false
12:03:16.710 [pool-1-thread-1] DEBUG o.s.o.j.ExtendedEntityManagerCreator$ExtendedEntityManagerInvocationHandler - Starting resource local transaction on application-managed EntityManager [org.hibernate.ejb.EntityManagerImpl at 63f5acd0]
12:03:16.710 [pool-1-thread-1] DEBUG o.s.o.j.ExtendedEntityManagerCreator$ExtendedEntityManagerInvocationHandler - Joined local transaction
12:03:16.710 [pool-1-thread-1] DEBUG o.s.o.j.ExtendedEntityManagerCreator$ExtendedEntityManagerInvocationHandler - Joined local transaction
12:03:16.710 [pool-1-thread-1] DEBUG o.h.e.def.AbstractSaveEventListener - executing identity-insert immediately
12:03:16.710 [pool-1-thread-1] DEBUG org.hibernate.jdbc.AbstractBatcher - about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
12:03:16.710 [pool-1-thread-1] DEBUG org.hibernate.SQL - insert into ProcessInstanceInfo (InstanceId, externalVariables, lastModificationDate, lastReadDate, processId, processInstanceByteArray, startDate, state, OPTLOCK) values (null, ?, ?, ?, ?, ?, ?, ?, ?)
12:03:16.710 [pool-1-thread-1] TRACE org.hibernate.type.BooleanType - binding 'false' to parameter: 1
12:03:16.710 [pool-1-thread-1] TRACE org.hibernate.type.TimestampType - binding null to parameter: 2
12:03:16.710 [pool-1-thread-1] TRACE org.hibernate.type.TimestampType - binding null to parameter: 3
12:03:16.710 [pool-1-thread-1] TRACE org.hibernate.type.StringType - binding 'd9686dff_98a5_4670_bdfa_fd03f2c8ed42' to parameter: 4
12:03:16.710 [pool-1-thread-1] TRACE org.hibernate.type.TimestampType - binding '2011-03-31 12:03:16' to parameter: 6
12:03:16.710 [pool-1-thread-1] TRACE org.hibernate.type.IntegerType - binding '0' to parameter: 7
12:03:16.710 [pool-1-thread-1] TRACE org.hibernate.type.IntegerType - binding '0' to parameter: 8
12:03:16.710 [pool-1-thread-1] DEBUG o.h.id.IdentifierGeneratorFactory - Natively generated identity: 1
12:03:16.710 [pool-1-thread-1] DEBUG org.hibernate.jdbc.AbstractBatcher - about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
12:03:16.710 [pool-1-thread-1] DEBUG c.p.p.drools.ProcessEventListener - Starting process [flow-1]...
12:03:16.710 [pool-1-thread-1] DEBUG c.p.p.drools.ProcessEventListener - Triggering node [flow-1 Start]...
12:03:16.710 [pool-1-thread-1] DEBUG c.p.p.drools.ProcessEventListener - Leaving node [flow-1 Start]...
12:03:16.710 [pool-1-thread-1] DEBUG c.p.p.drools.ProcessEventListener - Triggering node [step-1 Reject Join]...
12:03:16.710 [pool-1-thread-1] DEBUG c.p.p.drools.ProcessEventListener - Leaving node [step-1 Reject Join]...
12:03:16.710 [pool-1-thread-1] DEBUG c.p.p.drools.ProcessEventListener - Triggering node [step-1 Step]...
12:03:16.710 [pool-1-thread-1] DEBUG o.h.e.def.AbstractSaveEventListener - executing identity-insert immediately
12:03:16.710 [pool-1-thread-1] DEBUG org.hibernate.jdbc.AbstractBatcher - about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
12:03:16.710 [pool-1-thread-1] DEBUG org.hibernate.SQL - insert into WorkItemInfo (workItemId, creationDate, externalVariables, name, processInstanceId, state, OPTLOCK, workItemByteArray) values (null, ?, ?, ?, ?, ?, ?, ?)
12:03:16.710 [pool-1-thread-1] TRACE org.hibernate.type.TimestampType - binding '2011-03-31 12:03:16' to parameter: 1
12:03:16.710 [pool-1-thread-1] TRACE org.hibernate.type.BooleanType - binding 'false' to parameter: 2
12:03:16.710 [pool-1-thread-1] TRACE org.hibernate.type.StringType - binding 'Step' to parameter: 3
12:03:16.710 [pool-1-thread-1] TRACE org.hibernate.type.LongType - binding '1' to parameter: 4
12:03:16.710 [pool-1-thread-1] TRACE org.hibernate.type.LongType - binding '0' to parameter: 5
12:03:16.710 [pool-1-thread-1] TRACE org.hibernate.type.IntegerType - binding '0' to parameter: 6
12:03:16.710 [pool-1-thread-1] DEBUG o.h.id.IdentifierGeneratorFactory - Natively generated identity: 1
12:03:16.710 [pool-1-thread-1] DEBUG org.hibernate.jdbc.AbstractBatcher - about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
12:03:16.710 [pool-1-thread-1] DEBUG c.p.p.drools.StepWorkItemHandler - Executing Step with Drools work item ID [1] for Step with instance UUID [06ea0b5c-6ad0-43a7-8d53-4a0304c094a0] in slice [NO_SLICE]
12:03:16.710 [pool-1-thread-1] DEBUG c.p.p.drools.ProcessEventListener - Node [step-1 Step] triggered.
12:03:16.710 [pool-1-thread-1] DEBUG c.p.p.drools.ProcessEventListener - Node [step-1 Reject Join] left.
12:03:16.710 [pool-1-thread-1] DEBUG c.p.p.drools.ProcessEventListener - Node [step-1 Reject Join] triggered.
12:03:16.710 [pool-1-thread-1] DEBUG c.p.p.drools.ProcessEventListener - Node [flow-1 Start] left.
12:03:16.710 [pool-1-thread-1] DEBUG c.p.p.drools.ProcessEventListener - Node [flow-1 Start] triggered.
12:03:16.710 [pool-1-thread-1] DEBUG c.p.p.drools.ProcessEventListener - Process [flow-1] started.
12:03:16.710 [pool-1-thread-1] DEBUG o.s.orm.jpa.JpaTransactionManager - Initiating transaction commit
12:03:16.710 [pool-1-thread-1] DEBUG o.s.orm.jpa.JpaTransactionManager - Committing JPA transaction on EntityManager [org.hibernate.ejb.EntityManagerImpl at 3851ddd2]
12:03:16.710 [pool-1-thread-1] DEBUG o.h.transaction.JDBCTransaction - commit
12:03:16.710 [pool-1-thread-1] DEBUG o.h.e.d.AbstractFlushingEventListener - processing flush-time cascades
12:03:16.710 [pool-1-thread-1] DEBUG o.h.e.d.AbstractFlushingEventListener - dirty checking collections
12:03:16.710 [pool-1-thread-1] DEBUG o.h.e.d.AbstractFlushingEventListener - Flushed: 0 insertions, 1 updates, 0 deletions to 1 objects
12:03:16.710 [pool-1-thread-1] DEBUG o.h.e.d.AbstractFlushingEventListener - Flushed: 0 (re)creations, 0 updates, 0 removals to 0 collections
12:03:16.710 [pool-1-thread-1] DEBUG org.hibernate.pretty.Printer - listing entities:
12:03:16.710 [pool-1-thread-1] DEBUG org.hibernate.pretty.Printer - org.drools.persistence.session.SessionInfo{id=1, startDate=2011-03-31 12:03:16, rulesByteArray=2c6d8085f7d8808080808080808080808080808080808080808080808080808080808080808082808d8084cdc1c9ce808081808d8084cdc1c9ce808180818080808080808180818081808180818180818081808180808080808080808081, lastModificationDate=2011-03-31 12:03:16, version=1}
12:03:16.710 [pool-1-thread-1] DEBUG org.hibernate.jdbc.AbstractBatcher - about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
12:03:16.710 [pool-1-thread-1] DEBUG org.hibernate.SQL - update SessionInfo set lastModificationDate=?, rulesByteArray=?, startDate=?, OPTLOCK=? where id=? and OPTLOCK=?
12:03:16.710 [pool-1-thread-1] TRACE org.hibernate.type.TimestampType - binding '2011-03-31 12:03:16' to parameter: 1
12:03:16.710 [pool-1-thread-1] TRACE org.hibernate.type.TimestampType - binding '2011-03-31 12:03:16' to parameter: 3
12:03:16.710 [pool-1-thread-1] TRACE org.hibernate.type.IntegerType - binding '1' to parameter: 4
12:03:16.710 [pool-1-thread-1] TRACE org.hibernate.type.IntegerType - binding '1' to parameter: 5
12:03:16.710 [pool-1-thread-1] TRACE org.hibernate.type.IntegerType - binding '0' to parameter: 6
12:03:16.710 [pool-1-thread-1] DEBUG org.hibernate.jdbc.AbstractBatcher - about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
12:03:16.710 [pool-1-thread-1] DEBUG o.h.transaction.JDBCTransaction - committed JDBC Connection
12:03:16.710 [pool-1-thread-1] DEBUG org.hibernate.jdbc.ConnectionManager - aggressively releasing JDBC connection
12:03:16.710 [pool-1-thread-1] DEBUG org.hibernate.jdbc.ConnectionManager - releasing JDBC connection [ (open PreparedStatements: 0, globally: 0) (open ResultSets: 0, globally: 0)]
12:03:16.710 [pool-1-thread-1] DEBUG o.h.transaction.JDBCTransaction - commit
12:03:16.710 [pool-1-thread-1] DEBUG o.h.e.d.AbstractFlushingEventListener - processing flush-time cascades
12:03:16.710 [pool-1-thread-1] DEBUG o.h.e.d.AbstractFlushingEventListener - dirty checking collections
12:03:16.710 [pool-1-thread-1] DEBUG org.hibernate.engine.Collections - Collection found: [org.drools.persistence.processinstance.ProcessInstanceInfo.eventTypes#1], was: [<unreferenced>] (initialized)
12:03:16.710 [pool-1-thread-1] DEBUG org.hibernate.engine.Collections - Collection found: [org.drools.persistence.processinstance.ProcessInstanceInfo.variables#1], was: [<unreferenced>] (initialized)
12:03:16.710 [pool-1-thread-1] DEBUG org.hibernate.engine.Collections - Collection found: [org.drools.persistence.processinstance.WorkItemInfo.variables#1], was: [<unreferenced>] (initialized)
12:03:16.710 [pool-1-thread-1] DEBUG o.h.e.d.AbstractFlushingEventListener - Flushed: 0 insertions, 2 updates, 0 deletions to 2 objects
12:03:16.710 [pool-1-thread-1] DEBUG o.h.e.d.AbstractFlushingEventListener - Flushed: 3 (re)creations, 0 updates, 0 removals to 3 collections
12:03:16.710 [pool-1-thread-1] DEBUG org.hibernate.pretty.Printer - listing entities:
12:03:16.710 [pool-1-thread-1] DEBUG org.hibernate.pretty.Printer - org.drools.persistence.processinstance.WorkItemInfo{creationDate=2011-03-31 12:03:16, processInstanceId=1, name=Step, workItemByteArray=2c6d8085f7a4808080808080808180808080808080818084d3f4e5f080808080808080838084d5d5c9c4f3f2808eeae1f6e1aef5f4e9ecaed5d5c9c43c19837718ed05af828082ca808cece5e1f3f4d3e9e7c2e9f4f3ca808bedeff3f4d3e9e7c2e9f4f3f8f038246997c4d7dcabce8444b50f86cb4cf78c808ae9eef3f4e1eee3e5c9e4f3f180fe80800dd3ca8384401420866a8bdcea50c327f78c808af3ece9e3e5d6e1ecf5e5f48088cecfdfd3ccc9c3c5, state=0, externalVariables=false, workItemId=1, version=0, variables=[]}
12:03:16.710 [pool-1-thread-1] DEBUG org.hibernate.pretty.Printer - org.drools.persistence.processinstance.ProcessInstanceInfo{startDate=2011-03-31 12:03:16, processInstanceId=1, processId=d9686dff_98a5_4670_bdfa_fd03f2c8ed42, processInstanceByteArray=2c6d8085f7df8088d2f5ece5c6eceff7808080808080808180a4e4b9b6b8b6e4e6e6dfb9b8e1b5dfb4b6b7b0dfe2e4e6e1dfe6e4b0b3e6b2e3b8e5e4b4b2808080818080808080808083808080818095f0f2efe3e5f3f3c6eceff7c9eef3f4e1eee3e5c9e4f3f2808eeae1f6e1aef5f4e9ecaed5d5c9c43c19837718ed05af828082ca808cece5e1f3f4d3e9e7c2e9f4f3ca808bedeff3f4d3e9e7c2e9f4f3f8f03c45dc792f6d5b94a95e96470883ccd7f7aa808080808092808080808080808280808080808080838095808080808080808180808080808180808080, state=1, lastModificationDate=2011-03-31 12:03:16, lastReadDate=2011-03-31 12:03:16, externalVariables=false, eventTypes=[], version=1, variables=[]}
12:03:16.710 [pool-1-thread-1] DEBUG org.hibernate.jdbc.AbstractBatcher - about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
12:03:16.710 [pool-1-thread-1] DEBUG org.hibernate.SQL - update ProcessInstanceInfo set externalVariables=?, lastModificationDate=?, lastReadDate=?, processId=?, processInstanceByteArray=?, startDate=?, state=?, OPTLOCK=? where InstanceId=? and OPTLOCK=?
12:03:16.710 [pool-1-thread-1] TRACE org.hibernate.type.BooleanType - binding 'false' to parameter: 1
12:03:16.710 [pool-1-thread-1] TRACE org.hibernate.type.TimestampType - binding '2011-03-31 12:03:16' to parameter: 2
12:03:16.710 [pool-1-thread-1] TRACE org.hibernate.type.TimestampType - binding '2011-03-31 12:03:16' to parameter: 3
12:03:16.710 [pool-1-thread-1] TRACE org.hibernate.type.StringType - binding 'd9686dff_98a5_4670_bdfa_fd03f2c8ed42' to parameter: 4
12:03:16.710 [pool-1-thread-1] TRACE org.hibernate.type.TimestampType - binding '2011-03-31 12:03:16' to parameter: 6
12:03:16.710 [pool-1-thread-1] TRACE org.hibernate.type.IntegerType - binding '1' to parameter: 7
12:03:16.710 [pool-1-thread-1] TRACE org.hibernate.type.IntegerType - binding '1' to parameter: 8
12:03:16.710 [pool-1-thread-1] TRACE org.hibernate.type.LongType - binding '1' to parameter: 9
12:03:16.710 [pool-1-thread-1] TRACE org.hibernate.type.IntegerType - binding '0' to parameter: 10
12:03:16.710 [pool-1-thread-1] DEBUG org.hibernate.jdbc.AbstractBatcher - about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
12:03:16.710 [pool-1-thread-1] DEBUG org.hibernate.jdbc.AbstractBatcher - about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
12:03:16.710 [pool-1-thread-1] DEBUG org.hibernate.SQL - update WorkItemInfo set creationDate=?, externalVariables=?, name=?, processInstanceId=?, state=?, OPTLOCK=?, workItemByteArray=? where workItemId=? and OPTLOCK=?
12:03:16.710 [pool-1-thread-1] TRACE org.hibernate.type.TimestampType - binding '2011-03-31 12:03:16' to parameter: 1
12:03:16.710 [pool-1-thread-1] TRACE org.hibernate.type.BooleanType - binding 'false' to parameter: 2
12:03:16.710 [pool-1-thread-1] TRACE org.hibernate.type.StringType - binding 'Step' to parameter: 3
12:03:16.710 [pool-1-thread-1] TRACE org.hibernate.type.LongType - binding '1' to parameter: 4
12:03:16.710 [pool-1-thread-1] TRACE org.hibernate.type.LongType - binding '0' to parameter: 5
12:03:16.710 [pool-1-thread-1] TRACE org.hibernate.type.IntegerType - binding '1' to parameter: 6
12:03:16.710 [pool-1-thread-1] TRACE org.hibernate.type.LongType - binding '1' to parameter: 8
12:03:16.710 [pool-1-thread-1] TRACE org.hibernate.type.IntegerType - binding '0' to parameter: 9
12:03:16.710 [pool-1-thread-1] DEBUG org.hibernate.jdbc.AbstractBatcher - about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
12:03:16.710 [pool-1-thread-1] DEBUG o.h.p.c.AbstractCollectionPersister - Inserting collection: [org.drools.persistence.processinstance.ProcessInstanceInfo.eventTypes#1]
12:03:16.710 [pool-1-thread-1] DEBUG o.h.p.c.AbstractCollectionPersister - collection was empty
12:03:16.710 [pool-1-thread-1] DEBUG o.h.p.c.AbstractCollectionPersister - Inserting collection: [org.drools.persistence.processinstance.ProcessInstanceInfo.variables#1]
12:03:16.710 [pool-1-thread-1] DEBUG o.h.p.c.AbstractCollectionPersister - collection was empty
12:03:16.710 [pool-1-thread-1] DEBUG o.h.p.c.AbstractCollectionPersister - Inserting collection: [org.drools.persistence.processinstance.WorkItemInfo.variables#1]
12:03:16.710 [pool-1-thread-1] DEBUG o.h.p.c.AbstractCollectionPersister - collection was empty
12:03:16.710 [pool-1-thread-1] DEBUG o.h.transaction.JDBCTransaction - committed JDBC Connection
12:03:16.710 [pool-1-thread-1] DEBUG org.hibernate.jdbc.ConnectionManager - aggressively releasing JDBC connection
12:03:16.710 [pool-1-thread-1] DEBUG org.hibernate.jdbc.ConnectionManager - releasing JDBC connection [ (open PreparedStatements: 0, globally: 0) (open ResultSets: 0, globally: 0)]
12:03:16.710 [pool-1-thread-1] DEBUG o.s.orm.jpa.JpaTransactionManager - Not closing pre-bound JPA EntityManager after transaction
12:03:16.710 [pool-1-thread-1] DEBUG o.d.c.s.b.p.DroolsSpringTransactionManager - Current TX name (According to TransactionSynchronizationManager) : null
12:03:16.710 [pool-1-thread-1] DEBUG o.s.orm.jpa.JpaTransactionManager - Found thread-bound EntityManager [org.hibernate.ejb.EntityManagerImpl at 3851ddd2] for JPA transaction
12:03:16.710 [pool-1-thread-1] DEBUG o.s.orm.jpa.JpaTransactionManager - Creating new transaction with name [null]: PROPAGATION_REQUIRED,ISOLATION_DEFAULT
12:03:16.710 [pool-1-thread-1] DEBUG o.h.transaction.JDBCTransaction - begin
12:03:16.710 [pool-1-thread-1] DEBUG org.hibernate.jdbc.ConnectionManager - opening JDBC connection
12:03:16.710 [pool-1-thread-1] DEBUG o.h.transaction.JDBCTransaction - current autocommit status: false
12:03:16.710 [pool-1-thread-1] DEBUG o.s.orm.jpa.JpaTransactionManager - Exposing JPA transaction as JDBC transaction [org.springframework.orm.jpa.vendor.HibernateJpaDialect$HibernateConnectionHandle at 4dbed348]
12:03:16.710 [pool-1-thread-1] DEBUG org.hibernate.impl.SessionImpl - opened session at timestamp: 13015981967
12:03:16.710 [pool-1-thread-1] DEBUG o.h.transaction.JDBCTransaction - begin
12:03:16.710 [pool-1-thread-1] DEBUG org.hibernate.jdbc.ConnectionManager - opening JDBC connection
12:03:16.710 [pool-1-thread-1] DEBUG o.h.transaction.JDBCTransaction - current autocommit status: false
12:03:16.710 [pool-1-thread-1] DEBUG o.s.o.j.ExtendedEntityManagerCreator$ExtendedEntityManagerInvocationHandler - Starting resource local transaction on application-managed EntityManager [org.hibernate.ejb.EntityManagerImpl at 2b2143d8]
12:03:16.710 [pool-1-thread-1] DEBUG o.s.o.j.ExtendedEntityManagerCreator$ExtendedEntityManagerInvocationHandler - Joined local transaction
12:03:16.710 [pool-1-thread-1] DEBUG o.s.o.j.ExtendedEntityManagerCreator$ExtendedEntityManagerInvocationHandler - Joined local transaction
12:03:16.710 [pool-1-thread-1] DEBUG o.s.orm.jpa.JpaTransactionManager - Initiating transaction commit
12:03:16.710 [pool-1-thread-1] DEBUG o.s.orm.jpa.JpaTransactionManager - Committing JPA transaction on EntityManager [org.hibernate.ejb.EntityManagerImpl at 3851ddd2]
12:03:16.710 [pool-1-thread-1] DEBUG o.h.transaction.JDBCTransaction - commit
12:03:16.710 [pool-1-thread-1] DEBUG o.h.e.d.AbstractFlushingEventListener - processing flush-time cascades
12:03:16.710 [pool-1-thread-1] DEBUG o.h.e.d.AbstractFlushingEventListener - dirty checking collections
12:03:16.710 [pool-1-thread-1] DEBUG o.h.e.d.AbstractFlushingEventListener - Flushed: 0 insertions, 0 updates, 0 deletions to 1 objects
12:03:16.710 [pool-1-thread-1] DEBUG o.h.e.d.AbstractFlushingEventListener - Flushed: 0 (re)creations, 0 updates, 0 removals to 0 collections
12:03:16.710 [pool-1-thread-1] DEBUG org.hibernate.pretty.Printer - listing entities:
12:03:16.710 [pool-1-thread-1] DEBUG org.hibernate.pretty.Printer - org.drools.persistence.session.SessionInfo{id=1, startDate=2011-03-31 12:03:16, rulesByteArray=2c6d8085f7d8808080808080808080808080808080808080808080808080808080808080808082808d8084cdc1c9ce808081808d8084cdc1c9ce808180818080808080808180818081808180818180818081808180808080808080808081, lastModificationDate=2011-03-31 12:03:16, version=1}
12:03:16.710 [pool-1-thread-1] DEBUG o.h.transaction.JDBCTransaction - committed JDBC Connection
12:03:16.710 [pool-1-thread-1] DEBUG org.hibernate.jdbc.ConnectionManager - aggressively releasing JDBC connection
12:03:16.710 [pool-1-thread-1] DEBUG org.hibernate.jdbc.ConnectionManager - releasing JDBC connection [ (open PreparedStatements: 0, globally: 0) (open ResultSets: 0, globally: 0)]
12:03:16.710 [pool-1-thread-1] DEBUG o.h.transaction.JDBCTransaction - commit
12:03:16.710 [pool-1-thread-1] DEBUG o.h.transaction.JDBCTransaction - committed JDBC Connection
12:03:16.710 [pool-1-thread-1] DEBUG org.hibernate.jdbc.ConnectionManager - aggressively releasing JDBC connection
12:03:16.710 [pool-1-thread-1] DEBUG org.hibernate.jdbc.ConnectionManager - releasing JDBC connection [ (open PreparedStatements: 0, globally: 0) (open ResultSets: 0, globally: 0)]
12:03:16.710 [pool-1-thread-1] DEBUG o.s.orm.jpa.JpaTransactionManager - Not closing pre-bound JPA EntityManager after transaction
12:03:16.710 [pool-1-thread-1] DEBUG c.p.process.drools.DroolsFlowAdapter - Completing step instance [step-1 Step] with workItemId [1]
12:03:16.710 [pool-1-thread-1] DEBUG o.d.c.s.b.p.DroolsSpringTransactionManager - Current TX name (According to TransactionSynchronizationManager) : null
12:03:16.710 [pool-1-thread-1] DEBUG o.s.orm.jpa.JpaTransactionManager - Found thread-bound EntityManager [org.hibernate.ejb.EntityManagerImpl at 3851ddd2] for JPA transaction
12:03:16.710 [pool-1-thread-1] DEBUG o.s.orm.jpa.JpaTransactionManager - Creating new transaction with name [null]: PROPAGATION_REQUIRED,ISOLATION_DEFAULT
12:03:16.710 [pool-1-thread-1] DEBUG o.h.transaction.JDBCTransaction - begin
12:03:16.710 [pool-1-thread-1] DEBUG org.hibernate.jdbc.ConnectionManager - opening JDBC connection
12:03:16.710 [pool-1-thread-1] DEBUG o.h.transaction.JDBCTransaction - current autocommit status: false
12:03:16.710 [pool-1-thread-1] DEBUG o.s.orm.jpa.JpaTransactionManager - Exposing JPA transaction as JDBC transaction [org.springframework.orm.jpa.vendor.HibernateJpaDialect$HibernateConnectionHandle at 14ed3007]
12:03:16.710 [pool-1-thread-1] DEBUG org.hibernate.impl.SessionImpl - opened session at timestamp: 13015981967
12:03:16.710 [pool-1-thread-1] DEBUG o.h.transaction.JDBCTransaction - begin
12:03:16.710 [pool-1-thread-1] DEBUG org.hibernate.jdbc.ConnectionManager - opening JDBC connection
12:03:16.710 [pool-1-thread-1] DEBUG o.h.transaction.JDBCTransaction - current autocommit status: false
12:03:16.710 [pool-1-thread-1] DEBUG o.s.o.j.ExtendedEntityManagerCreator$ExtendedEntityManagerInvocationHandler - Starting resource local transaction on application-managed EntityManager [org.hibernate.ejb.EntityManagerImpl at 5fec264c]
12:03:16.710 [pool-1-thread-1] DEBUG o.s.o.j.ExtendedEntityManagerCreator$ExtendedEntityManagerInvocationHandler - Joined local transaction
12:03:16.710 [pool-1-thread-1] DEBUG o.s.o.j.ExtendedEntityManagerCreator$ExtendedEntityManagerInvocationHandler - Joined local transaction
12:03:16.710 [pool-1-thread-1] DEBUG org.hibernate.loader.Loader - loading entity: [org.drools.persistence.processinstance.WorkItemInfo#1]
12:03:16.710 [pool-1-thread-1] DEBUG org.hibernate.jdbc.AbstractBatcher - about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
12:03:16.710 [pool-1-thread-1] DEBUG org.hibernate.SQL - select workitemin0_.workItemId as workItemId91_0_, workitemin0_.creationDate as creation2_91_0_, workitemin0_.externalVariables as external3_91_0_, workitemin0_.name as name91_0_, workitemin0_.processInstanceId as processI5_91_0_, workitemin0_.state as state91_0_, workitemin0_.OPTLOCK as OPTLOCK91_0_, workitemin0_.workItemByteArray as workItem8_91_0_ from WorkItemInfo workitemin0_ where workitemin0_.workItemId=?
12:03:16.710 [pool-1-thread-1] TRACE org.hibernate.type.LongType - binding '1' to parameter: 1
12:03:16.710 [pool-1-thread-1] DEBUG org.hibernate.jdbc.AbstractBatcher - about to open ResultSet (open ResultSets: 0, globally: 0)
12:03:16.710 [pool-1-thread-1] DEBUG org.hibernate.loader.Loader - result row: EntityKey[org.drools.persistence.processinstance.WorkItemInfo#1]
12:03:16.710 [pool-1-thread-1] TRACE org.hibernate.type.TimestampType - returning '2011-03-31 12:03:16' as column: creation2_91_0_
12:03:16.710 [pool-1-thread-1] TRACE org.hibernate.type.BooleanType - returning 'false' as column: external3_91_0_
12:03:16.710 [pool-1-thread-1] TRACE org.hibernate.type.StringType - returning 'Step' as column: name91_0_
12:03:16.710 [pool-1-thread-1] TRACE org.hibernate.type.LongType - returning '1' as column: processI5_91_0_
12:03:16.710 [pool-1-thread-1] TRACE org.hibernate.type.LongType - returning '0' as column: state91_0_
12:03:16.710 [pool-1-thread-1] TRACE org.hibernate.type.IntegerType - returning '1' as column: OPTLOCK91_0_
12:03:16.710 [pool-1-thread-1] DEBUG org.hibernate.jdbc.AbstractBatcher - about to close ResultSet (open ResultSets: 1, globally: 1)
12:03:16.710 [pool-1-thread-1] DEBUG org.hibernate.jdbc.AbstractBatcher - about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
12:03:16.710 [pool-1-thread-1] DEBUG org.hibernate.engine.TwoPhaseLoad - resolving associations for [org.drools.persistence.processinstance.WorkItemInfo#1]
12:03:16.710 [pool-1-thread-1] DEBUG org.hibernate.engine.TwoPhaseLoad - done materializing entity [org.drools.persistence.processinstance.WorkItemInfo#1]
12:03:16.710 [pool-1-thread-1] DEBUG o.h.e.StatefulPersistenceContext - initializing non-lazy collections
12:03:16.710 [pool-1-thread-1] DEBUG org.hibernate.loader.Loader - done entity load
12:03:16.710 [pool-1-thread-1] DEBUG org.hibernate.loader.Loader - loading entity: [org.drools.persistence.processinstance.ProcessInstanceInfo#1]
12:03:16.710 [pool-1-thread-1] DEBUG org.hibernate.jdbc.AbstractBatcher - about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
12:03:16.710 [pool-1-thread-1] DEBUG org.hibernate.SQL - select processins0_.InstanceId as InstanceId89_0_, processins0_.externalVariables as external2_89_0_, processins0_.lastModificationDate as lastModi3_89_0_, processins0_.lastReadDate as lastRead4_89_0_, processins0_.processId as processId89_0_, processins0_.processInstanceByteArray as processI6_89_0_, processins0_.startDate as startDate89_0_, processins0_.state as state89_0_, processins0_.OPTLOCK as OPTLOCK89_0_ from ProcessInstanceInfo processins0_ where processins0_.InstanceId=?
12:03:16.710 [pool-1-thread-1] TRACE org.hibernate.type.LongType - binding '1' to parameter: 1
12:03:16.710 [pool-1-thread-1] DEBUG org.hibernate.jdbc.AbstractBatcher - about to open ResultSet (open ResultSets: 0, globally: 0)
12:03:16.710 [pool-1-thread-1] DEBUG org.hibernate.loader.Loader - result row: EntityKey[org.drools.persistence.processinstance.ProcessInstanceInfo#1]
12:03:16.710 [pool-1-thread-1] TRACE org.hibernate.type.BooleanType - returning 'false' as column: external2_89_0_
12:03:16.710 [pool-1-thread-1] TRACE org.hibernate.type.TimestampType - returning '2011-03-31 12:03:16' as column: lastModi3_89_0_
12:03:16.710 [pool-1-thread-1] TRACE org.hibernate.type.TimestampType - returning '2011-03-31 12:03:16' as column: lastRead4_89_0_
12:03:16.710 [pool-1-thread-1] TRACE org.hibernate.type.StringType - returning 'd9686dff_98a5_4670_bdfa_fd03f2c8ed42' as column: processId89_0_
12:03:16.710 [pool-1-thread-1] TRACE org.hibernate.type.TimestampType - returning '2011-03-31 12:03:16' as column: startDate89_0_
12:03:16.710 [pool-1-thread-1] TRACE org.hibernate.type.IntegerType - returning '1' as column: state89_0_
12:03:16.710 [pool-1-thread-1] TRACE org.hibernate.type.IntegerType - returning '1' as column: OPTLOCK89_0_
12:03:16.710 [pool-1-thread-1] DEBUG org.hibernate.jdbc.AbstractBatcher - about to close ResultSet (open ResultSets: 1, globally: 1)
12:03:16.710 [pool-1-thread-1] DEBUG org.hibernate.jdbc.AbstractBatcher - about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
12:03:16.710 [pool-1-thread-1] DEBUG org.hibernate.engine.TwoPhaseLoad - resolving associations for [org.drools.persistence.processinstance.ProcessInstanceInfo#1]
12:03:16.710 [pool-1-thread-1] DEBUG org.hibernate.engine.TwoPhaseLoad - done materializing entity [org.drools.persistence.processinstance.ProcessInstanceInfo#1]
12:03:16.710 [pool-1-thread-1] DEBUG o.h.e.StatefulPersistenceContext - initializing non-lazy collections
12:03:16.710 [pool-1-thread-1] DEBUG org.hibernate.loader.Loader - done entity load
12:03:16.710 [pool-1-thread-1] DEBUG c.p.p.drools.ProcessEventListener - Leaving node [step-1 Step]...
12:03:16.710 [pool-1-thread-1] DEBUG c.p.p.drools.ProcessEventListener - Triggering node [step-1 Approval]...
12:03:16.710 [pool-1-thread-1] DEBUG o.h.e.def.AbstractSaveEventListener - executing identity-insert immediately
12:03:16.710 [pool-1-thread-1] DEBUG org.hibernate.jdbc.AbstractBatcher - about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
12:03:16.710 [pool-1-thread-1] DEBUG org.hibernate.SQL - insert into WorkItemInfo (workItemId, creationDate, externalVariables, name, processInstanceId, state, OPTLOCK, workItemByteArray) values (null, ?, ?, ?, ?, ?, ?, ?)
12:03:16.710 [pool-1-thread-1] TRACE org.hibernate.type.TimestampType - binding '2011-03-31 12:03:16' to parameter: 1
12:03:16.710 [pool-1-thread-1] TRACE org.hibernate.type.BooleanType - binding 'false' to parameter: 2
12:03:16.710 [pool-1-thread-1] TRACE org.hibernate.type.StringType - binding 'Step' to parameter: 3
12:03:16.710 [pool-1-thread-1] TRACE org.hibernate.type.LongType - binding '1' to parameter: 4
12:03:16.710 [pool-1-thread-1] TRACE org.hibernate.type.LongType - binding '0' to parameter: 5
12:03:16.710 [pool-1-thread-1] TRACE org.hibernate.type.IntegerType - binding '0' to parameter: 6
12:03:16.710 [pool-1-thread-1] DEBUG o.h.id.IdentifierGeneratorFactory - Natively generated identity: 2
12:03:16.710 [pool-1-thread-1] DEBUG org.hibernate.jdbc.AbstractBatcher - about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
12:03:16.710 [pool-1-thread-1] DEBUG c.p.p.drools.StepWorkItemHandler - Executing Step with Drools work item ID [2] for Step with instance UUID [35fdffaf-ed0c-45dc-86ac-9a8a7cd851f5] in slice [NO_SLICE]
12:03:16.710 [pool-1-thread-1] DEBUG c.p.p.drools.ProcessEventListener - Node [step-1 Approval] triggered.
12:03:16.710 [pool-1-thread-1] DEBUG c.p.p.drools.ProcessEventListener - Node [step-1 Step] left.
12:03:16.710 [pool-1-thread-1] DEBUG org.hibernate.loader.Loader - loading collection: [org.drools.persistence.processinstance.WorkItemInfo.variables#1]
12:03:16.710 [pool-1-thread-1] DEBUG org.hibernate.jdbc.AbstractBatcher - about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
12:03:16.710 [pool-1-thread-1] DEBUG org.hibernate.SQL - select variables0_.workItemId as workItemId1_, variables0_.id as id1_, variables0_.name as formula16_1_, variables0_.id as id90_0_, variables0_.name as name90_0_, variables0_.persister as persister90_0_, variables0_.processInstanceId as processI5_90_0_, variables0_.workItemId as workItemId90_0_, variables0_.entityClass as entityCl7_90_0_, variables0_.entityId as entityId90_0_, variables0_.content as content90_0_, variables0_.TYPE as TYPE90_0_ from VariableInstanceInfo variables0_ where variables0_.workItemId=?
12:03:16.710 [pool-1-thread-1] TRACE org.hibernate.type.LongType - binding '1' to parameter: 1
12:03:16.710 [pool-1-thread-1] DEBUG org.hibernate.jdbc.AbstractBatcher - about to open ResultSet (open ResultSets: 0, globally: 0)
12:03:16.710 [pool-1-thread-1] DEBUG org.hibernate.loader.Loader - result set contains (possibly empty) collection: [org.drools.persistence.processinstance.WorkItemInfo.variables#1]
12:03:16.710 [pool-1-thread-1] DEBUG org.hibernate.jdbc.AbstractBatcher - about to close ResultSet (open ResultSets: 1, globally: 1)
12:03:16.710 [pool-1-thread-1] DEBUG org.hibernate.jdbc.AbstractBatcher - about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
12:03:16.710 [pool-1-thread-1] DEBUG o.h.e.loading.CollectionLoadContext - 1 collections were found in result set for role: org.drools.persistence.processinstance.WorkItemInfo.variables
12:03:16.710 [pool-1-thread-1] DEBUG o.h.e.loading.CollectionLoadContext - collection fully initialized: [org.drools.persistence.processinstance.WorkItemInfo.variables#1]
12:03:16.710 [pool-1-thread-1] DEBUG o.h.e.loading.CollectionLoadContext - 1 collections initialized for role: org.drools.persistence.processinstance.WorkItemInfo.variables
12:03:16.710 [pool-1-thread-1] DEBUG o.h.e.StatefulPersistenceContext - initializing non-lazy collections
12:03:16.710 [pool-1-thread-1] DEBUG org.hibernate.loader.Loader - done loading collection
12:03:16.710 [pool-1-thread-1] DEBUG o.s.orm.jpa.JpaTransactionManager - Initiating transaction commit
12:03:16.710 [pool-1-thread-1] DEBUG o.s.orm.jpa.JpaTransactionManager - Committing JPA transaction on EntityManager [org.hibernate.ejb.EntityManagerImpl at 3851ddd2]
12:03:16.710 [pool-1-thread-1] DEBUG o.h.transaction.JDBCTransaction - commit
12:03:16.710 [pool-1-thread-1] DEBUG o.h.e.d.AbstractFlushingEventListener - processing flush-time cascades
12:03:16.710 [pool-1-thread-1] DEBUG o.h.e.d.AbstractFlushingEventListener - dirty checking collections
12:03:16.710 [pool-1-thread-1] DEBUG o.h.e.d.AbstractFlushingEventListener - Flushed: 0 insertions, 0 updates, 0 deletions to 1 objects
12:03:16.710 [pool-1-thread-1] DEBUG o.h.e.d.AbstractFlushingEventListener - Flushed: 0 (re)creations, 0 updates, 0 removals to 0 collections
12:03:16.710 [pool-1-thread-1] DEBUG org.hibernate.pretty.Printer - listing entities:
12:03:16.710 [pool-1-thread-1] DEBUG org.hibernate.pretty.Printer - org.drools.persistence.session.SessionInfo{id=1, startDate=2011-03-31 12:03:16, rulesByteArray=2c6d8085f7d8808080808080808080808080808080808080808080808080808080808080808082808d8084cdc1c9ce808081808d8084cdc1c9ce808180818080808080808180818081808180818180818081808180808080808080808081, lastModificationDate=2011-03-31 12:03:16, version=1}
12:03:16.710 [pool-1-thread-1] DEBUG o.h.transaction.JDBCTransaction - committed JDBC Connection
12:03:16.710 [pool-1-thread-1] DEBUG org.hibernate.jdbc.ConnectionManager - aggressively releasing JDBC connection
12:03:16.710 [pool-1-thread-1] DEBUG org.hibernate.jdbc.ConnectionManager - releasing JDBC connection [ (open PreparedStatements: 0, globally: 0) (open ResultSets: 0, globally: 0)]
12:03:16.710 [pool-1-thread-1] DEBUG o.h.transaction.JDBCTransaction - commit
12:03:16.710 [pool-1-thread-1] DEBUG o.h.e.d.AbstractFlushingEventListener - processing flush-time cascades
12:03:16.710 [pool-1-thread-1] DEBUG o.h.e.d.AbstractFlushingEventListener - dirty checking collections
12:03:16.725 [pool-1-thread-1] DEBUG org.hibernate.engine.Collections - Collection found: [org.drools.persistence.processinstance.ProcessInstanceInfo.eventTypes#1], was: [org.drools.persistence.processinstance.ProcessInstanceInfo.eventTypes#1] (uninitialized)
12:03:16.725 [pool-1-thread-1] DEBUG org.hibernate.engine.Collections - Collection found: [org.drools.persistence.processinstance.ProcessInstanceInfo.variables#1], was: [org.drools.persistence.processinstance.ProcessInstanceInfo.variables#1] (uninitialized)
12:03:16.725 [pool-1-thread-1] DEBUG org.hibernate.engine.Collections - Collection found: [org.drools.persistence.processinstance.WorkItemInfo.variables#2], was: [<unreferenced>] (initialized)
12:03:16.725 [pool-1-thread-1] DEBUG org.hibernate.engine.Collections - Collection dereferenced: [org.drools.persistence.processinstance.WorkItemInfo.variables#1]
12:03:16.725 [pool-1-thread-1] DEBUG o.h.e.d.AbstractFlushingEventListener - Flushed: 0 insertions, 1 updates, 1 deletions to 3 objects
12:03:16.725 [pool-1-thread-1] DEBUG o.h.e.d.AbstractFlushingEventListener - Flushed: 1 (re)creations, 0 updates, 1 removals to 4 collections
12:03:16.725 [pool-1-thread-1] DEBUG org.hibernate.pretty.Printer - listing entities:
12:03:16.725 [pool-1-thread-1] DEBUG org.hibernate.pretty.Printer - org.drools.persistence.processinstance.WorkItemInfo{creationDate=2011-03-31 12:03:16, processInstanceId=1, name=Step, workItemByteArray=2c6d8085f7a4808080808080808280808080808080818084d3f4e5f080808080808080838084d5d5c9c4f3f2808eeae1f6e1aef5f4e9ecaed5d5c9c43c19837718ed05af828082ca808cece5e1f3f4d3e9e7c2e9f4f3ca808bedeff3f4d3e9e7c2e9f4f3f8f038246997c4d7dcabce8444b50f86cb4cf78c808ae9eef3f4e1eee3e5c9e4f3f180fe8080062c1a0afc58d175b57d7f2f6d8cc55cf78c808af3ece9e3e5d6e1ecf5e5f48088cecfdfd3ccc9c3c5, state=0, externalVariables=false, workItemId=2, version=0, variables=[]}
12:03:16.725 [pool-1-thread-1] DEBUG org.hibernate.pretty.Printer - org.drools.persistence.processinstance.WorkItemInfo{creationDate=2011-03-31 12:03:16, processInstanceId=1, name=Step, workItemByteArray=2c6d8085f7a4808080808080808180808080808080818084d3f4e5f080808080808080838084d5d5c9c4f3f2808eeae1f6e1aef5f4e9ecaed5d5c9c43c19837718ed05af828082ca808cece5e1f3f4d3e9e7c2e9f4f3ca808bedeff3f4d3e9e7c2e9f4f3f8f038246997c4d7dcabce8444b50f86cb4cf78c808ae9eef3f4e1eee3e5c9e4f3f180fe80800dd3ca8384401420866a8bdcea50c327f78c808af3ece9e3e5d6e1ecf5e5f48088cecfdfd3ccc9c3c5, state=0, externalVariables=false, workItemId=1, version=1, variables=[]}
12:03:16.725 [pool-1-thread-1] DEBUG org.hibernate.pretty.Printer - org.drools.persistence.processinstance.ProcessInstanceInfo{startDate=2011-03-31 12:03:16, processInstanceId=1, processId=d9686dff_98a5_4670_bdfa_fd03f2c8ed42, processInstanceByteArray=2c6d8085f7df8088d2f5ece5c6eceff7808080808080808180a4e4b9b6b8b6e4e6e6dfb9b8e1b5dfb4b6b7b0dfe2e4e6e1dfe6e4b0b3e6b2e3b8e5e4b4b2808080818080808080808083808080818095f0f2efe3e5f3f3c6eceff7c9eef3f4e1eee3e5c9e4f3f2808eeae1f6e1aef5f4e9ecaed5d5c9c43c19837718ed05af828082ca808cece5e1f3f4d3e9e7c2e9f4f3ca808bedeff3f4d3e9e7c2e9f4f3f8f03c45dc792f6d5b94a95e96470883ccd7f7aa808080808092808080808080808280808080808080838095808080808080808180808080808180808080, state=1, lastModificationDate=2011-03-31 12:03:16, lastReadDate=2011-03-31 12:03:16, externalVariables=false, eventTypes=<uninitialized>, version=1, variables=<uninitialized>}
12:03:16.725 [pool-1-thread-1] DEBUG org.hibernate.jdbc.AbstractBatcher - about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
12:03:16.725 [pool-1-thread-1] DEBUG org.hibernate.SQL - update WorkItemInfo set creationDate=?, externalVariables=?, name=?, processInstanceId=?, state=?, OPTLOCK=?, workItemByteArray=? where workItemId=? and OPTLOCK=?
12:03:16.725 [pool-1-thread-1] TRACE org.hibernate.type.TimestampType - binding '2011-03-31 12:03:16' to parameter: 1
12:03:16.725 [pool-1-thread-1] TRACE org.hibernate.type.BooleanType - binding 'false' to parameter: 2
12:03:16.725 [pool-1-thread-1] TRACE org.hibernate.type.StringType - binding 'Step' to parameter: 3
12:03:16.725 [pool-1-thread-1] TRACE org.hibernate.type.LongType - binding '1' to parameter: 4
12:03:16.725 [pool-1-thread-1] TRACE org.hibernate.type.LongType - binding '0' to parameter: 5
12:03:16.725 [pool-1-thread-1] TRACE org.hibernate.type.IntegerType - binding '1' to parameter: 6
12:03:16.725 [pool-1-thread-1] TRACE org.hibernate.type.LongType - binding '2' to parameter: 8
12:03:16.725 [pool-1-thread-1] TRACE org.hibernate.type.IntegerType - binding '0' to parameter: 9
12:03:16.725 [pool-1-thread-1] DEBUG org.hibernate.jdbc.AbstractBatcher - about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
12:03:16.725 [pool-1-thread-1] DEBUG o.h.p.c.AbstractCollectionPersister - Inserting collection: [org.drools.persistence.processinstance.WorkItemInfo.variables#2]
12:03:16.725 [pool-1-thread-1] DEBUG o.h.p.c.AbstractCollectionPersister - collection was empty
12:03:16.725 [pool-1-thread-1] DEBUG org.hibernate.jdbc.AbstractBatcher - about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
12:03:16.725 [pool-1-thread-1] DEBUG org.hibernate.SQL - delete from WorkItemInfo where workItemId=? and OPTLOCK=?
12:03:16.725 [pool-1-thread-1] TRACE org.hibernate.type.LongType - binding '1' to parameter: 1
12:03:16.725 [pool-1-thread-1] TRACE org.hibernate.type.IntegerType - binding '1' to parameter: 2
12:03:16.725 [pool-1-thread-1] DEBUG org.hibernate.jdbc.AbstractBatcher - about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
12:03:16.725 [pool-1-thread-1] DEBUG o.h.transaction.JDBCTransaction - committed JDBC Connection
12:03:16.725 [pool-1-thread-1] DEBUG org.hibernate.jdbc.ConnectionManager - aggressively releasing JDBC connection
12:03:16.725 [pool-1-thread-1] DEBUG org.hibernate.jdbc.ConnectionManager - releasing JDBC connection [ (open PreparedStatements: 0, globally: 0) (open ResultSets: 0, globally: 0)]
12:03:16.725 [pool-1-thread-1] DEBUG o.s.orm.jpa.JpaTransactionManager - Not closing pre-bound JPA EntityManager after transaction
12:03:16.725 [pool-1-thread-1] DEBUG c.p.process.drools.DroolsFlowAdapter - Completing step instance [step-1 Approval] with workItemId [2]
12:03:16.725 [pool-1-thread-1] DEBUG o.d.c.s.b.p.DroolsSpringTransactionManager - Current TX name (According to TransactionSynchronizationManager) : null
12:03:16.725 [pool-1-thread-1] DEBUG o.s.orm.jpa.JpaTransactionManager - Found thread-bound EntityManager [org.hibernate.ejb.EntityManagerImpl at 3851ddd2] for JPA transaction
12:03:16.725 [pool-1-thread-1] DEBUG o.s.orm.jpa.JpaTransactionManager - Creating new transaction with name [null]: PROPAGATION_REQUIRED,ISOLATION_DEFAULT
12:03:16.725 [pool-1-thread-1] DEBUG o.h.transaction.JDBCTransaction - begin
12:03:16.725 [pool-1-thread-1] DEBUG org.hibernate.jdbc.ConnectionManager - opening JDBC connection
12:03:16.725 [pool-1-thread-1] DEBUG o.h.transaction.JDBCTransaction - current autocommit status: false
12:03:16.725 [pool-1-thread-1] DEBUG o.s.orm.jpa.JpaTransactionManager - Exposing JPA transaction as JDBC transaction [org.springframework.orm.jpa.vendor.HibernateJpaDialect$HibernateConnectionHandle at 53ddcd5f]
12:03:16.725 [pool-1-thread-1] DEBUG org.hibernate.impl.SessionImpl - opened session at timestamp: 13015981967
12:03:16.725 [pool-1-thread-1] DEBUG o.h.transaction.JDBCTransaction - begin
12:03:16.725 [pool-1-thread-1] DEBUG org.hibernate.jdbc.ConnectionManager - opening JDBC connection
12:03:16.725 [pool-1-thread-1] DEBUG o.h.transaction.JDBCTransaction - current autocommit status: false
12:03:16.725 [pool-1-thread-1] DEBUG o.s.o.j.ExtendedEntityManagerCreator$ExtendedEntityManagerInvocationHandler - Starting resource local transaction on application-managed EntityManager [org.hibernate.ejb.EntityManagerImpl at 6d642fd]
12:03:16.725 [pool-1-thread-1] DEBUG o.s.o.j.ExtendedEntityManagerCreator$ExtendedEntityManagerInvocationHandler - Joined local transaction
12:03:16.725 [pool-1-thread-1] DEBUG o.s.o.j.ExtendedEntityManagerCreator$ExtendedEntityManagerInvocationHandler - Joined local transaction
12:03:16.725 [pool-1-thread-1] DEBUG org.hibernate.loader.Loader - loading entity: [org.drools.persistence.processinstance.WorkItemInfo#2]
12:03:16.725 [pool-1-thread-1] DEBUG org.hibernate.jdbc.AbstractBatcher - about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
12:03:16.725 [pool-1-thread-1] DEBUG org.hibernate.SQL - select workitemin0_.workItemId as workItemId91_0_, workitemin0_.creationDate as creation2_91_0_, workitemin0_.externalVariables as external3_91_0_, workitemin0_.name as name91_0_, workitemin0_.processInstanceId as processI5_91_0_, workitemin0_.state as state91_0_, workitemin0_.OPTLOCK as OPTLOCK91_0_, workitemin0_.workItemByteArray as workItem8_91_0_ from WorkItemInfo workitemin0_ where workitemin0_.workItemId=?
12:03:16.725 [pool-1-thread-1] TRACE org.hibernate.type.LongType - binding '2' to parameter: 1
12:03:16.725 [pool-1-thread-1] DEBUG org.hibernate.jdbc.AbstractBatcher - about to open ResultSet (open ResultSets: 0, globally: 0)
12:03:16.725 [pool-1-thread-1] DEBUG org.hibernate.loader.Loader - result row: EntityKey[org.drools.persistence.processinstance.WorkItemInfo#2]
12:03:16.725 [pool-1-thread-1] TRACE org.hibernate.type.TimestampType - returning '2011-03-31 12:03:16' as column: creation2_91_0_
12:03:16.725 [pool-1-thread-1] TRACE org.hibernate.type.BooleanType - returning 'false' as column: external3_91_0_
12:03:16.725 [pool-1-thread-1] TRACE org.hibernate.type.StringType - returning 'Step' as column: name91_0_
12:03:16.725 [pool-1-thread-1] TRACE org.hibernate.type.LongType - returning '1' as column: processI5_91_0_
12:03:16.725 [pool-1-thread-1] TRACE org.hibernate.type.LongType - returning '0' as column: state91_0_
12:03:16.725 [pool-1-thread-1] TRACE org.hibernate.type.IntegerType - returning '1' as column: OPTLOCK91_0_
12:03:16.725 [pool-1-thread-1] DEBUG org.hibernate.jdbc.AbstractBatcher - about to close ResultSet (open ResultSets: 1, globally: 1)
12:03:16.725 [pool-1-thread-1] DEBUG org.hibernate.jdbc.AbstractBatcher - about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
12:03:16.725 [pool-1-thread-1] DEBUG org.hibernate.engine.TwoPhaseLoad - resolving associations for [org.drools.persistence.processinstance.WorkItemInfo#2]
12:03:16.725 [pool-1-thread-1] DEBUG org.hibernate.engine.TwoPhaseLoad - done materializing entity [org.drools.persistence.processinstance.WorkItemInfo#2]
12:03:16.725 [pool-1-thread-1] DEBUG o.h.e.StatefulPersistenceContext - initializing non-lazy collections
12:03:16.725 [pool-1-thread-1] DEBUG org.hibernate.loader.Loader - done entity load
12:03:16.725 [pool-1-thread-1] DEBUG org.hibernate.loader.Loader - loading entity: [org.drools.persistence.processinstance.ProcessInstanceInfo#1]
12:03:16.725 [pool-1-thread-1] DEBUG org.hibernate.jdbc.AbstractBatcher - about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
12:03:16.725 [pool-1-thread-1] DEBUG org.hibernate.SQL - select processins0_.InstanceId as InstanceId89_0_, processins0_.externalVariables as external2_89_0_, processins0_.lastModificationDate as lastModi3_89_0_, processins0_.lastReadDate as lastRead4_89_0_, processins0_.processId as processId89_0_, processins0_.processInstanceByteArray as processI6_89_0_, processins0_.startDate as startDate89_0_, processins0_.state as state89_0_, processins0_.OPTLOCK as OPTLOCK89_0_ from ProcessInstanceInfo processins0_ where processins0_.InstanceId=?
12:03:16.725 [pool-1-thread-1] TRACE org.hibernate.type.LongType - binding '1' to parameter: 1
12:03:16.725 [pool-1-thread-1] DEBUG org.hibernate.jdbc.AbstractBatcher - about to open ResultSet (open ResultSets: 0, globally: 0)
12:03:16.725 [pool-1-thread-1] DEBUG org.hibernate.loader.Loader - result row: EntityKey[org.drools.persistence.processinstance.ProcessInstanceInfo#1]
12:03:16.725 [pool-1-thread-1] TRACE org.hibernate.type.BooleanType - returning 'false' as column: external2_89_0_
12:03:16.725 [pool-1-thread-1] TRACE org.hibernate.type.TimestampType - returning '2011-03-31 12:03:16' as column: lastModi3_89_0_
12:03:16.725 [pool-1-thread-1] TRACE org.hibernate.type.TimestampType - returning '2011-03-31 12:03:16' as column: lastRead4_89_0_
12:03:16.725 [pool-1-thread-1] TRACE org.hibernate.type.StringType - returning 'd9686dff_98a5_4670_bdfa_fd03f2c8ed42' as column: processId89_0_
12:03:16.725 [pool-1-thread-1] TRACE org.hibernate.type.TimestampType - returning '2011-03-31 12:03:16' as column: startDate89_0_
12:03:16.725 [pool-1-thread-1] TRACE org.hibernate.type.IntegerType - returning '1' as column: state89_0_
12:03:16.725 [pool-1-thread-1] TRACE org.hibernate.type.IntegerType - returning '1' as column: OPTLOCK89_0_
12:03:16.725 [pool-1-thread-1] DEBUG org.hibernate.jdbc.AbstractBatcher - about to close ResultSet (open ResultSets: 1, globally: 1)
12:03:16.725 [pool-1-thread-1] DEBUG org.hibernate.jdbc.AbstractBatcher - about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
12:03:16.725 [pool-1-thread-1] DEBUG org.hibernate.engine.TwoPhaseLoad - resolving associations for [org.drools.persistence.processinstance.ProcessInstanceInfo#1]
12:03:16.725 [pool-1-thread-1] DEBUG org.hibernate.engine.TwoPhaseLoad - done materializing entity [org.drools.persistence.processinstance.ProcessInstanceInfo#1]
12:03:16.725 [pool-1-thread-1] DEBUG o.h.e.StatefulPersistenceContext - initializing non-lazy collections
12:03:16.725 [pool-1-thread-1] DEBUG org.hibernate.loader.Loader - done entity load
12:03:16.725 [pool-1-thread-1] DEBUG org.hibernate.loader.Loader - loading collection: [org.drools.persistence.processinstance.WorkItemInfo.variables#2]
12:03:16.725 [pool-1-thread-1] DEBUG org.hibernate.jdbc.AbstractBatcher - about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
12:03:16.725 [pool-1-thread-1] DEBUG org.hibernate.SQL - select variables0_.workItemId as workItemId1_, variables0_.id as id1_, variables0_.name as formula16_1_, variables0_.id as id90_0_, variables0_.name as name90_0_, variables0_.persister as persister90_0_, variables0_.processInstanceId as processI5_90_0_, variables0_.workItemId as workItemId90_0_, variables0_.entityClass as entityCl7_90_0_, variables0_.entityId as entityId90_0_, variables0_.content as content90_0_, variables0_.TYPE as TYPE90_0_ from VariableInstanceInfo variables0_ where variables0_.workItemId=?
12:03:16.725 [pool-1-thread-1] TRACE org.hibernate.type.LongType - binding '2' to parameter: 1
12:03:16.725 [pool-1-thread-1] DEBUG org.hibernate.jdbc.AbstractBatcher - about to open ResultSet (open ResultSets: 0, globally: 0)
12:03:16.725 [pool-1-thread-1] DEBUG org.hibernate.loader.Loader - result set contains (possibly empty) collection: [org.drools.persistence.processinstance.WorkItemInfo.variables#2]
12:03:16.725 [pool-1-thread-1] DEBUG org.hibernate.jdbc.AbstractBatcher - about to close ResultSet (open ResultSets: 1, globally: 1)
12:03:16.725 [pool-1-thread-1] DEBUG org.hibernate.jdbc.AbstractBatcher - about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
12:03:16.725 [pool-1-thread-1] DEBUG o.h.e.loading.CollectionLoadContext - 1 collections were found in result set for role: org.drools.persistence.processinstance.WorkItemInfo.variables
12:03:16.725 [pool-1-thread-1] DEBUG o.h.e.loading.CollectionLoadContext - collection fully initialized: [org.drools.persistence.processinstance.WorkItemInfo.variables#2]
12:03:16.725 [pool-1-thread-1] DEBUG o.h.e.loading.CollectionLoadContext - 1 collections initialized for role: org.drools.persistence.processinstance.WorkItemInfo.variables
12:03:16.725 [pool-1-thread-1] DEBUG o.h.e.StatefulPersistenceContext - initializing non-lazy collections
12:03:16.725 [pool-1-thread-1] DEBUG org.hibernate.loader.Loader - done loading collection
12:03:16.725 [pool-1-thread-1] DEBUG o.s.orm.jpa.JpaTransactionManager - Initiating transaction commit
12:03:16.725 [pool-1-thread-1] DEBUG o.s.orm.jpa.JpaTransactionManager - Committing JPA transaction on EntityManager [org.hibernate.ejb.EntityManagerImpl at 3851ddd2]
12:03:16.725 [pool-1-thread-1] DEBUG o.h.transaction.JDBCTransaction - commit
12:03:16.725 [pool-1-thread-1] DEBUG o.h.e.d.AbstractFlushingEventListener - processing flush-time cascades
12:03:16.725 [pool-1-thread-1] DEBUG o.h.e.d.AbstractFlushingEventListener - dirty checking collections
12:03:16.725 [pool-1-thread-1] DEBUG o.h.e.d.AbstractFlushingEventListener - Flushed: 0 insertions, 1 updates, 0 deletions to 1 objects
12:03:16.725 [pool-1-thread-1] DEBUG o.h.e.d.AbstractFlushingEventListener - Flushed: 0 (re)creations, 0 updates, 0 removals to 0 collections
12:03:16.725 [pool-1-thread-1] DEBUG org.hibernate.pretty.Printer - listing entities:
12:03:16.725 [pool-1-thread-1] DEBUG org.hibernate.pretty.Printer - org.drools.persistence.session.SessionInfo{id=1, startDate=2011-03-31 12:03:16, rulesByteArray=2c6d8085f7d8808080808080808080808080808080808080808080808080808080808080808082808d8084cdc1c9ce808081808d8084cdc1c9ce808180818080808080808180818081808180818180818081808180808080808080808081, lastModificationDate=2011-03-31 12:03:16, version=1}
12:03:16.725 [pool-1-thread-1] DEBUG org.hibernate.jdbc.AbstractBatcher - about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
12:03:16.725 [pool-1-thread-1] DEBUG org.hibernate.SQL - update SessionInfo set lastModificationDate=?, rulesByteArray=?, startDate=?, OPTLOCK=? where id=? and OPTLOCK=?
12:03:16.725 [pool-1-thread-1] TRACE org.hibernate.type.TimestampType - binding '2011-03-31 12:03:16' to parameter: 1
12:03:16.725 [pool-1-thread-1] TRACE org.hibernate.type.TimestampType - binding '2011-03-31 12:03:16' to parameter: 3
12:03:16.725 [pool-1-thread-1] TRACE org.hibernate.type.IntegerType - binding '2' to parameter: 4
12:03:16.725 [pool-1-thread-1] TRACE org.hibernate.type.IntegerType - binding '1' to parameter: 5
12:03:16.725 [pool-1-thread-1] TRACE org.hibernate.type.IntegerType - binding '1' to parameter: 6
12:03:16.725 [pool-1-thread-1] DEBUG org.hibernate.jdbc.AbstractBatcher - about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
12:03:16.725 [pool-1-thread-1] DEBUG o.h.transaction.JDBCTransaction - committed JDBC Connection
12:03:16.725 [pool-1-thread-1] DEBUG org.hibernate.jdbc.ConnectionManager - aggressively releasing JDBC connection
12:03:16.725 [pool-1-thread-1] DEBUG org.hibernate.jdbc.ConnectionManager - releasing JDBC connection [ (open PreparedStatements: 0, globally: 0) (open ResultSets: 0, globally: 0)]
12:03:16.725 [pool-1-thread-1] DEBUG o.h.transaction.JDBCTransaction - commit
12:03:16.725 [pool-1-thread-1] DEBUG o.h.e.d.AbstractFlushingEventListener - processing flush-time cascades
12:03:16.725 [pool-1-thread-1] DEBUG o.h.e.d.AbstractFlushingEventListener - dirty checking collections
12:03:16.725 [pool-1-thread-1] DEBUG org.hibernate.engine.Collections - Collection found: [org.drools.persistence.processinstance.ProcessInstanceInfo.eventTypes#1], was: [org.drools.persistence.processinstance.ProcessInstanceInfo.eventTypes#1] (uninitialized)
12:03:16.725 [pool-1-thread-1] DEBUG org.hibernate.engine.Collections - Collection found: [org.drools.persistence.processinstance.ProcessInstanceInfo.variables#1], was: [org.drools.persistence.processinstance.ProcessInstanceInfo.variables#1] (uninitialized)
12:03:16.725 [pool-1-thread-1] DEBUG org.hibernate.engine.Collections - Collection dereferenced: [org.drools.persistence.processinstance.WorkItemInfo.variables#2]
12:03:16.725 [pool-1-thread-1] DEBUG o.h.e.d.AbstractFlushingEventListener - Flushed: 0 insertions, 1 updates, 1 deletions to 2 objects
12:03:16.725 [pool-1-thread-1] DEBUG o.h.e.d.AbstractFlushingEventListener - Flushed: 0 (re)creations, 0 updates, 1 removals to 3 collections
12:03:16.725 [pool-1-thread-1] DEBUG org.hibernate.pretty.Printer - listing entities:
12:03:16.725 [pool-1-thread-1] DEBUG org.hibernate.pretty.Printer - org.drools.persistence.processinstance.WorkItemInfo{creationDate=2011-03-31 12:03:16, processInstanceId=1, name=Step, workItemByteArray=2c6d8085f7a4808080808080808280808080808080818084d3f4e5f080808080808080838084d5d5c9c4f3f2808eeae1f6e1aef5f4e9ecaed5d5c9c43c19837718ed05af828082ca808cece5e1f3f4d3e9e7c2e9f4f3ca808bedeff3f4d3e9e7c2e9f4f3f8f038246997c4d7dcabce8444b50f86cb4cf78c808ae9eef3f4e1eee3e5c9e4f3f180fe8080062c1a0afc58d175b57d7f2f6d8cc55cf78c808af3ece9e3e5d6e1ecf5e5f48088cecfdfd3ccc9c3c5, state=0, externalVariables=false, workItemId=2, version=1, variables=[]}
12:03:16.725 [pool-1-thread-1] DEBUG org.hibernate.pretty.Printer - org.drools.persistence.processinstance.ProcessInstanceInfo{startDate=2011-03-31 12:03:16, processInstanceId=1, processId=d9686dff_98a5_4670_bdfa_fd03f2c8ed42, processInstanceByteArray=2c6d8085f7df8088d2f5ece5c6eceff7808080808080808180a4e4b9b6b8b6e4e6e6dfb9b8e1b5dfb4b6b7b0dfe2e4e6e1dfe6e4b0b3e6b2e3b8e5e4b4b2808080818080808080808083808080818095f0f2efe3e5f3f3c6eceff7c9eef3f4e1eee3e5c9e4f3f2808eeae1f6e1aef5f4e9ecaed5d5c9c43c19837718ed05af828082ca808cece5e1f3f4d3e9e7c2e9f4f3ca808bedeff3f4d3e9e7c2e9f4f3f8f03c45dc792f6d5b94a95e96470883ccd7f7aa808080808092808080808080808280808080808080838095808080808080808180808080808180808080, state=1, lastModificationDate=2011-03-31 12:03:16, lastReadDate=2011-03-31 12:03:16, externalVariables=false, eventTypes=<uninitialized>, version=1, variables=<uninitialized>}
12:03:16.725 [pool-1-thread-1] DEBUG org.hibernate.jdbc.AbstractBatcher - about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
12:03:16.725 [pool-1-thread-1] DEBUG org.hibernate.SQL - update ProcessInstanceInfo set externalVariables=?, lastModificationDate=?, lastReadDate=?, processId=?, processInstanceByteArray=?, startDate=?, state=?, OPTLOCK=? where InstanceId=? and OPTLOCK=?
12:03:16.725 [pool-1-thread-1] TRACE org.hibernate.type.BooleanType - binding 'false' to parameter: 1
12:03:16.725 [pool-1-thread-1] TRACE org.hibernate.type.TimestampType - binding '2011-03-31 12:03:16' to parameter: 2
12:03:16.725 [pool-1-thread-1] TRACE org.hibernate.type.TimestampType - binding '2011-03-31 12:03:16' to parameter: 3
12:03:16.725 [pool-1-thread-1] TRACE org.hibernate.type.StringType - binding 'd9686dff_98a5_4670_bdfa_fd03f2c8ed42' to parameter: 4
12:03:16.725 [pool-1-thread-1] TRACE org.hibernate.type.TimestampType - binding '2011-03-31 12:03:16' to parameter: 6
12:03:16.725 [pool-1-thread-1] TRACE org.hibernate.type.IntegerType - binding '1' to parameter: 7
12:03:16.725 [pool-1-thread-1] TRACE org.hibernate.type.IntegerType - binding '2' to parameter: 8
12:03:16.725 [pool-1-thread-1] TRACE org.hibernate.type.LongType - binding '1' to parameter: 9
12:03:16.725 [pool-1-thread-1] TRACE org.hibernate.type.IntegerType - binding '1' to parameter: 10
12:03:16.725 [pool-1-thread-1] DEBUG org.hibernate.jdbc.AbstractBatcher - about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
12:03:16.725 [pool-1-thread-1] DEBUG org.hibernate.jdbc.AbstractBatcher - about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
12:03:16.725 [pool-1-thread-1] DEBUG org.hibernate.SQL - delete from WorkItemInfo where workItemId=? and OPTLOCK=?
12:03:16.725 [pool-1-thread-1] TRACE org.hibernate.type.LongType - binding '2' to parameter: 1
12:03:16.725 [pool-1-thread-1] TRACE org.hibernate.type.IntegerType - binding '1' to parameter: 2
12:03:16.725 [pool-1-thread-1] DEBUG org.hibernate.jdbc.AbstractBatcher - about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
12:03:16.757 [pool-1-thread-1] DEBUG o.h.transaction.JDBCTransaction - committed JDBC Connection
12:03:16.772 [pool-1-thread-1] DEBUG org.hibernate.jdbc.ConnectionManager - aggressively releasing JDBC connection
12:03:16.772 [pool-1-thread-1] DEBUG org.hibernate.jdbc.ConnectionManager - releasing JDBC connection [ (open PreparedStatements: 0, globally: 0) (open ResultSets: 0, globally: 0)]
12:03:16.772 [pool-1-thread-1] DEBUG o.s.orm.jpa.JpaTransactionManager - Not closing pre-bound JPA EntityManager after transaction
12:03:16.772 [pool-1-thread-1] INFO o.s.c.s.ClassPathXmlApplicationContext - Closing org.springframework.context.support.ClassPathXmlApplicationContext at 7d6bb63e: startup date [Thu Mar 31 12:03:16 PDT 2011]; root of context hierarchy
12:03:16.772 [pool-1-thread-1] INFO o.s.c.s.DefaultLifecycleProcessor - Stopping beans in phase 0
12:03:16.772 [pool-1-thread-1] INFO o.s.b.f.s.DefaultListableBeanFactory - Destroying singletons in org.springframework.beans.factory.support.DefaultListableBeanFactory at 1c944d4a: defining beans [processFlowManager,stepWorkItemHandler,stepActivationCallbackHandler,processEventListener,modelCache,modelFactory,droolsFlowAdapter,memberSetResolver,instanceCache,processFlowService,startProcessFlowHandler,getProcessFlowStatusHandler,stepCompletedServiceHandler,approvalCompletedServiceHandler,connectionFactory,protobufJmsListener,protobufConverter,messageHandler,cachedConnectionFactory,jmsTemplate,messageProducer,dataSource,transactionManager,entityManagerFactory,jpaAdapter,entityManager,org.springframework.beans.factory.config.PropertyPlaceholderConfigurer#0,testOutJmsTemplate,testInJmsTemplate,testInConverter,outListener,inSender,embeddedJmsBroker]; root of factory hierarchy
12:03:16.772 [pool-1-thread-1] INFO o.s.o.j.LocalContainerEntityManagerFactoryBean - Closing JPA EntityManagerFactory for persistence unit 'org.drools.persistence.jpa'
12:03:16.772 [pool-1-thread-1] INFO o.hibernate.impl.SessionFactoryImpl - closing
-------------- next part --------------
09:16:06.453 [main] INFO o.s.c.s.ClassPathXmlApplicationContext - Refreshing org.springframework.context.support.ClassPathXmlApplicationContext at 1fbbdd48: startup date [Fri Apr 01 09:16:06 PDT 2011]; root of context hierarchy
09:16:06.606 [main] INFO o.s.b.f.xml.XmlBeanDefinitionReader - Loading XML bean definitions from class path resource [META-INF/proferi-component.xml]
09:16:06.987 [main] INFO o.s.b.f.xml.XmlBeanDefinitionReader - Loading XML bean definitions from class path resource [META-INF/proferi-component-test.xml]
09:16:07.088 [main] INFO o.s.b.f.s.DefaultListableBeanFactory - Overriding bean definition for bean 'processFlowService': replacing [Generic bean: class [com.proferi.core.NorbertProtobufService]; scope=; abstract=false; lazyInit=false; autowireMode=0; dependencyCheck=0; autowireCandidate=true; primary=false; factoryBeanName=null; factoryMethodName=null; initMethodName=null; destroyMethodName=null; defined in class path resource [META-INF/proferi-component.xml]] with [Generic bean: class [com.proferi.core.MockProtobufService]; scope=; abstract=false; lazyInit=false; autowireMode=0; dependencyCheck=0; autowireCandidate=true; primary=false; factoryBeanName=null; factoryMethodName=null; initMethodName=null; destroyMethodName=null; defined in class path resource [META-INF/proferi-component-test.xml]]
09:16:07.142 [main] INFO o.s.b.f.s.DefaultListableBeanFactory - Overriding bean definition for bean 'connectionFactory': replacing [Generic bean: class [org.hornetq.jms.client.HornetQConnectionFactory]; scope=; abstract=false; lazyInit=false; autowireMode=0; dependencyCheck=0; autowireCandidate=true; primary=false; factoryBeanName=null; factoryMethodName=null; initMethodName=null; destroyMethodName=null; defined in class path resource [META-INF/proferi-component.xml]] with [Generic bean: class [org.hornetq.jms.client.HornetQConnectionFactory]; scope=; abstract=false; lazyInit=false; autowireMode=0; dependencyCheck=0; autowireCandidate=true; primary=false; factoryBeanName=null; factoryMethodName=null; initMethodName=null; destroyMethodName=null; defined in class path resource [META-INF/proferi-component-test.xml]]
09:16:07.556 [main] INFO o.s.b.f.c.PropertyPlaceholderConfigurer - Loading properties file from class path resource [proferi-component.properties]
09:16:07.600 [main] INFO o.s.b.f.s.DefaultListableBeanFactory - Pre-instantiating singletons in org.springframework.beans.factory.support.DefaultListableBeanFactory at 30b48b11: defining beans [processFlowManager,stepWorkItemHandler,stepActivationCallbackHandler,processEventListener,modelCache,modelFactory,droolsFlowAdapter,memberSetResolver,instanceCache,processFlowService,startProcessFlowHandler,getProcessFlowStatusHandler,stepCompletedServiceHandler,approvalCompletedServiceHandler,connectionFactory,protobufJmsListener,protobufConverter,messageHandler,cachedConnectionFactory,jmsTemplate,messageProducer,dataSource,transactionManager,entityManagerFactory,jpaAdapter,entityManager,org.springframework.beans.factory.config.PropertyPlaceholderConfigurer#0,testOutJmsTemplate,testInJmsTemplate,testInConverter,outListener,inSender,embeddedJmsBroker]; root of factory hierarchy
09:16:08.196 [main] DEBUG org.springframework.beans.BeanUtils - No property editor [org.hornetq.api.core.client.ClientSessionFactoryEditor] found for type org.hornetq.api.core.client.ClientSessionFactory according to 'Editor' suffix convention
09:16:08.199 [main] DEBUG org.springframework.beans.BeanUtils - No property editor [org.hornetq.api.core.PairEditor] found for type org.hornetq.api.core.Pair according to 'Editor' suffix convention
09:16:08.719 [main] DEBUG c.p.core.message.ProtobufJmsListener - invoking handleMessage on ProcessFlowMessageConsumer for a StepCompletedRequest
09:16:08.720 [main] DEBUG c.p.core.message.ProtobufJmsListener - invoking handleMessage on ProcessFlowMessageConsumer for a ApprovalCompletedRequest
09:16:08.866 [main] DEBUG org.springframework.beans.BeanUtils - No property editor [org.springframework.orm.jpa.vendor.DatabaseEditor] found for type org.springframework.orm.jpa.vendor.Database according to 'Editor' suffix convention
09:16:08.907 [main] INFO o.s.o.j.LocalContainerEntityManagerFactoryBean - Building JPA container EntityManagerFactory for persistence unit 'org.drools.persistence.jpa'
09:16:12.232 [main] DEBUG c.p.process.drools.ProxyBuilder - Approval constraint [StepApproval( approved == true, sliceValue == "NO_SLICE", approvalStepNodeId == "1a8a5a64-1e32-46a9-8b04-806c1706a97a" )]
09:16:12.268 [main] DEBUG c.p.process.drools.DroolsFlowAdapter - Created new StepNodeInstance [step-1 Step] with ID [48305f48-1ea6-47c2-a74b-254e48247285]
09:16:12.277 [main] DEBUG c.p.process.drools.DroolsFlowAdapter - Created new ImpliedStepNodeInstance [step-1 Approval] with ID [6204a045-9c95-4392-8927-aa88333e38ce]
10:51:21.672 [main] DEBUG c.p.process.drools.DroolsFlowAdapter - Starting process flow [flow-1] instance [71d27a30-4db9-4133-b461-86318f48cd24]
10:51:25.643 [main] DEBUG o.d.p.s.SingleSessionCommandService - Instantiating DroolsSpringTransactionManager
10:51:25.804 [main] DEBUG o.d.c.s.b.p.DroolsSpringTransactionManager - Current TX name (According to TransactionSynchronizationManager) : null
10:51:25.807 [main] DEBUG o.s.orm.jpa.JpaTransactionManager - Found thread-bound EntityManager [org.hibernate.ejb.EntityManagerImpl at a70ad76] for JPA transaction
10:51:25.808 [main] DEBUG o.s.orm.jpa.JpaTransactionManager - Creating new transaction with name [null]: PROPAGATION_REQUIRED,ISOLATION_DEFAULT
10:51:25.878 [main] DEBUG o.s.orm.jpa.JpaTransactionManager - Exposing JPA transaction as JDBC transaction [org.springframework.orm.jpa.vendor.HibernateJpaDialect$HibernateConnectionHandle at 7a9eb4a1]
10:51:25.882 [main] DEBUG o.s.o.j.ExtendedEntityManagerCreator$ExtendedEntityManagerInvocationHandler - Joined local transaction
10:51:25.997 [main] DEBUG o.s.orm.jpa.JpaTransactionManager - Initiating transaction commit
10:51:25.998 [main] DEBUG o.s.orm.jpa.JpaTransactionManager - Committing JPA transaction on EntityManager [org.hibernate.ejb.EntityManagerImpl at a70ad76]
10:51:26.006 [main] DEBUG o.s.orm.jpa.JpaTransactionManager - Not closing pre-bound JPA EntityManager after transaction
10:51:26.009 [main] DEBUG o.d.c.s.b.p.DroolsSpringTransactionManager - Current TX name (According to TransactionSynchronizationManager) : null
10:51:26.010 [main] DEBUG o.s.orm.jpa.JpaTransactionManager - Found thread-bound EntityManager [org.hibernate.ejb.EntityManagerImpl at a70ad76] for JPA transaction
10:51:26.020 [main] DEBUG o.s.orm.jpa.JpaTransactionManager - Creating new transaction with name [null]: PROPAGATION_REQUIRED,ISOLATION_DEFAULT
10:51:26.021 [main] DEBUG o.s.orm.jpa.JpaTransactionManager - Exposing JPA transaction as JDBC transaction [org.springframework.orm.jpa.vendor.HibernateJpaDialect$HibernateConnectionHandle at 43e3556a]
10:51:26.023 [main] DEBUG o.s.o.j.ExtendedEntityManagerCreator$ExtendedEntityManagerInvocationHandler - Starting resource local transaction on application-managed EntityManager [org.hibernate.ejb.EntityManagerImpl at 1fcc4f8]
10:51:26.027 [main] DEBUG o.s.o.j.ExtendedEntityManagerCreator$ExtendedEntityManagerInvocationHandler - Joined local transaction
10:51:26.028 [main] DEBUG o.s.o.j.ExtendedEntityManagerCreator$ExtendedEntityManagerInvocationHandler - Joined local transaction
10:51:26.033 [main] DEBUG o.s.orm.jpa.JpaTransactionManager - Initiating transaction commit
10:51:26.034 [main] DEBUG o.s.orm.jpa.JpaTransactionManager - Committing JPA transaction on EntityManager [org.hibernate.ejb.EntityManagerImpl at a70ad76]
10:51:26.040 [main] DEBUG o.s.orm.jpa.JpaTransactionManager - Not closing pre-bound JPA EntityManager after transaction
10:51:26.078 [main] DEBUG o.d.c.s.b.p.DroolsSpringTransactionManager - Current TX name (According to TransactionSynchronizationManager) : null
10:51:26.079 [main] DEBUG o.s.orm.jpa.JpaTransactionManager - Found thread-bound EntityManager [org.hibernate.ejb.EntityManagerImpl at a70ad76] for JPA transaction
10:51:26.080 [main] DEBUG o.s.orm.jpa.JpaTransactionManager - Creating new transaction with name [null]: PROPAGATION_REQUIRED,ISOLATION_DEFAULT
10:51:26.081 [main] DEBUG o.s.orm.jpa.JpaTransactionManager - Exposing JPA transaction as JDBC transaction [org.springframework.orm.jpa.vendor.HibernateJpaDialect$HibernateConnectionHandle at 733e4c83]
10:51:26.130 [main] DEBUG o.s.o.j.ExtendedEntityManagerCreator$ExtendedEntityManagerInvocationHandler - Starting resource local transaction on application-managed EntityManager [org.hibernate.ejb.EntityManagerImpl at 7f116790]
10:51:26.131 [main] DEBUG o.s.o.j.ExtendedEntityManagerCreator$ExtendedEntityManagerInvocationHandler - Joined local transaction
10:51:26.132 [main] DEBUG o.s.o.j.ExtendedEntityManagerCreator$ExtendedEntityManagerInvocationHandler - Joined local transaction
10:51:26.133 [main] DEBUG o.s.orm.jpa.JpaTransactionManager - Initiating transaction commit
10:51:26.181 [main] DEBUG o.s.orm.jpa.JpaTransactionManager - Committing JPA transaction on EntityManager [org.hibernate.ejb.EntityManagerImpl at a70ad76]
10:51:26.182 [main] DEBUG o.s.orm.jpa.JpaTransactionManager - Not closing pre-bound JPA EntityManager after transaction
10:51:26.186 [main] DEBUG o.d.c.s.b.p.DroolsSpringTransactionManager - Current TX name (According to TransactionSynchronizationManager) : null
10:51:26.187 [main] DEBUG o.s.orm.jpa.JpaTransactionManager - Found thread-bound EntityManager [org.hibernate.ejb.EntityManagerImpl at a70ad76] for JPA transaction
10:51:26.188 [main] DEBUG o.s.orm.jpa.JpaTransactionManager - Creating new transaction with name [null]: PROPAGATION_REQUIRED,ISOLATION_DEFAULT
10:51:26.234 [main] DEBUG o.s.orm.jpa.JpaTransactionManager - Exposing JPA transaction as JDBC transaction [org.springframework.orm.jpa.vendor.HibernateJpaDialect$HibernateConnectionHandle at 4e2120fa]
10:51:26.235 [main] DEBUG o.s.o.j.ExtendedEntityManagerCreator$ExtendedEntityManagerInvocationHandler - Starting resource local transaction on application-managed EntityManager [org.hibernate.ejb.EntityManagerImpl at 60fc2528]
10:51:26.237 [main] DEBUG o.s.o.j.ExtendedEntityManagerCreator$ExtendedEntityManagerInvocationHandler - Joined local transaction
10:51:26.238 [main] DEBUG o.s.o.j.ExtendedEntityManagerCreator$ExtendedEntityManagerInvocationHandler - Joined local transaction
10:51:26.239 [main] DEBUG o.s.orm.jpa.JpaTransactionManager - Initiating transaction commit
10:51:26.239 [main] DEBUG o.s.orm.jpa.JpaTransactionManager - Committing JPA transaction on EntityManager [org.hibernate.ejb.EntityManagerImpl at a70ad76]
10:51:26.241 [main] DEBUG o.s.orm.jpa.JpaTransactionManager - Not closing pre-bound JPA EntityManager after transaction
10:51:26.244 [main] DEBUG o.d.c.s.b.p.DroolsSpringTransactionManager - Current TX name (According to TransactionSynchronizationManager) : null
10:51:26.245 [main] DEBUG o.s.orm.jpa.JpaTransactionManager - Found thread-bound EntityManager [org.hibernate.ejb.EntityManagerImpl at a70ad76] for JPA transaction
10:51:26.246 [main] DEBUG o.s.orm.jpa.JpaTransactionManager - Creating new transaction with name [null]: PROPAGATION_REQUIRED,ISOLATION_DEFAULT
10:51:26.247 [main] DEBUG o.s.orm.jpa.JpaTransactionManager - Exposing JPA transaction as JDBC transaction [org.springframework.orm.jpa.vendor.HibernateJpaDialect$HibernateConnectionHandle at 7792a63a]
10:51:26.295 [main] DEBUG o.s.o.j.ExtendedEntityManagerCreator$ExtendedEntityManagerInvocationHandler - Starting resource local transaction on application-managed EntityManager [org.hibernate.ejb.EntityManagerImpl at 3cdf672a]
10:51:26.296 [main] DEBUG o.s.o.j.ExtendedEntityManagerCreator$ExtendedEntityManagerInvocationHandler - Joined local transaction
10:51:26.297 [main] DEBUG o.s.o.j.ExtendedEntityManagerCreator$ExtendedEntityManagerInvocationHandler - Joined local transaction
10:51:26.359 [main] DEBUG c.p.p.drools.ProcessEventListener - Starting process [flow-1]...
10:51:26.387 [main] DEBUG c.p.p.drools.ProcessEventListener - Triggering node [flow-1 Start]...
10:51:26.389 [main] DEBUG c.p.p.drools.ProcessEventListener - Leaving node [flow-1 Start]...
10:51:26.390 [main] DEBUG c.p.p.drools.ProcessEventListener - Triggering node [step-1 Reject Join]...
10:51:26.391 [main] DEBUG c.p.p.drools.ProcessEventListener - Leaving node [step-1 Reject Join]...
10:51:26.395 [main] DEBUG c.p.p.drools.ProcessEventListener - Triggering node [step-1 Step]...
10:51:26.416 [main] DEBUG c.p.p.drools.StepWorkItemHandler - Executing Step with Drools work item ID [1] for Step with instance UUID [48305f48-1ea6-47c2-a74b-254e48247285] in slice [NO_SLICE]
10:51:26.417 [main] DEBUG c.p.p.drools.ProcessEventListener - Node [step-1 Step] triggered.
10:51:26.417 [main] DEBUG c.p.p.drools.ProcessEventListener - Node [step-1 Reject Join] left.
10:51:26.417 [main] DEBUG c.p.p.drools.ProcessEventListener - Node [step-1 Reject Join] triggered.
10:51:26.418 [main] DEBUG c.p.p.drools.ProcessEventListener - Node [flow-1 Start] left.
10:51:26.453 [main] DEBUG c.p.p.drools.ProcessEventListener - Node [flow-1 Start] triggered.
10:51:26.454 [main] DEBUG c.p.p.drools.ProcessEventListener - Process [flow-1] started.
10:51:26.455 [main] DEBUG o.s.orm.jpa.JpaTransactionManager - Initiating transaction commit
10:51:26.455 [main] DEBUG o.s.orm.jpa.JpaTransactionManager - Committing JPA transaction on EntityManager [org.hibernate.ejb.EntityManagerImpl at a70ad76]
10:51:26.494 [main] DEBUG o.s.orm.jpa.JpaTransactionManager - Not closing pre-bound JPA EntityManager after transaction
10:51:26.495 [main] DEBUG o.d.c.s.b.p.DroolsSpringTransactionManager - Current TX name (According to TransactionSynchronizationManager) : null
10:51:26.496 [main] DEBUG o.s.orm.jpa.JpaTransactionManager - Found thread-bound EntityManager [org.hibernate.ejb.EntityManagerImpl at a70ad76] for JPA transaction
10:51:26.496 [main] DEBUG o.s.orm.jpa.JpaTransactionManager - Creating new transaction with name [null]: PROPAGATION_REQUIRED,ISOLATION_DEFAULT
10:51:26.508 [main] DEBUG o.s.orm.jpa.JpaTransactionManager - Exposing JPA transaction as JDBC transaction [org.springframework.orm.jpa.vendor.HibernateJpaDialect$HibernateConnectionHandle at 47fb4a7b]
10:51:26.510 [main] DEBUG o.s.o.j.ExtendedEntityManagerCreator$ExtendedEntityManagerInvocationHandler - Starting resource local transaction on application-managed EntityManager [org.hibernate.ejb.EntityManagerImpl at 42d6f628]
10:51:26.510 [main] DEBUG o.s.o.j.ExtendedEntityManagerCreator$ExtendedEntityManagerInvocationHandler - Joined local transaction
10:51:26.511 [main] DEBUG o.s.o.j.ExtendedEntityManagerCreator$ExtendedEntityManagerInvocationHandler - Joined local transaction
10:51:26.512 [main] DEBUG o.s.orm.jpa.JpaTransactionManager - Initiating transaction commit
10:51:26.512 [main] DEBUG o.s.orm.jpa.JpaTransactionManager - Committing JPA transaction on EntityManager [org.hibernate.ejb.EntityManagerImpl at a70ad76]
10:51:26.513 [main] DEBUG o.s.orm.jpa.JpaTransactionManager - Not closing pre-bound JPA EntityManager after transaction
10:51:26.514 [main] DEBUG c.p.process.drools.DroolsFlowAdapter - Completing step instance [step-1 Step] with workItemId [1]
10:51:26.516 [main] DEBUG o.d.c.s.b.p.DroolsSpringTransactionManager - Current TX name (According to TransactionSynchronizationManager) : null
10:51:26.517 [main] DEBUG o.s.orm.jpa.JpaTransactionManager - Found thread-bound EntityManager [org.hibernate.ejb.EntityManagerImpl at a70ad76] for JPA transaction
10:51:26.517 [main] DEBUG o.s.orm.jpa.JpaTransactionManager - Creating new transaction with name [null]: PROPAGATION_REQUIRED,ISOLATION_DEFAULT
10:51:26.518 [main] DEBUG o.s.orm.jpa.JpaTransactionManager - Exposing JPA transaction as JDBC transaction [org.springframework.orm.jpa.vendor.HibernateJpaDialect$HibernateConnectionHandle at 3eb2aa1c]
10:51:26.567 [main] DEBUG o.s.o.j.ExtendedEntityManagerCreator$ExtendedEntityManagerInvocationHandler - Starting resource local transaction on application-managed EntityManager [org.hibernate.ejb.EntityManagerImpl at 7c63c132]
10:51:26.568 [main] DEBUG o.s.o.j.ExtendedEntityManagerCreator$ExtendedEntityManagerInvocationHandler - Joined local transaction
10:51:26.568 [main] DEBUG o.s.o.j.ExtendedEntityManagerCreator$ExtendedEntityManagerInvocationHandler - Joined local transaction
10:51:26.610 [main] DEBUG c.p.p.drools.ProcessEventListener - Leaving node [step-1 Step]...
10:51:26.611 [main] DEBUG c.p.p.drools.ProcessEventListener - Triggering node [step-1 Approval]...
10:51:26.613 [main] DEBUG c.p.p.drools.StepWorkItemHandler - Executing Step with Drools work item ID [2] for Step with instance UUID [6204a045-9c95-4392-8927-aa88333e38ce] in slice [NO_SLICE]
10:51:26.614 [main] DEBUG c.p.p.drools.ProcessEventListener - Node [step-1 Approval] triggered.
10:51:26.614 [main] DEBUG c.p.p.drools.ProcessEventListener - Node [step-1 Step] left.
10:51:26.638 [main] DEBUG o.s.orm.jpa.JpaTransactionManager - Initiating transaction commit
10:51:26.639 [main] DEBUG o.s.orm.jpa.JpaTransactionManager - Committing JPA transaction on EntityManager [org.hibernate.ejb.EntityManagerImpl at a70ad76]
10:51:26.652 [main] DEBUG o.s.orm.jpa.JpaTransactionManager - Not closing pre-bound JPA EntityManager after transaction
10:51:26.653 [main] DEBUG c.p.process.drools.DroolsFlowAdapter - Completing step instance [step-1 Approval] with workItemId [2]
10:51:26.653 [main] DEBUG o.d.c.s.b.p.DroolsSpringTransactionManager - Current TX name (According to TransactionSynchronizationManager) : null
10:51:26.672 [main] DEBUG o.s.orm.jpa.JpaTransactionManager - Found thread-bound EntityManager [org.hibernate.ejb.EntityManagerImpl at a70ad76] for JPA transaction
10:51:26.673 [main] DEBUG o.s.orm.jpa.JpaTransactionManager - Creating new transaction with name [null]: PROPAGATION_REQUIRED,ISOLATION_DEFAULT
10:51:26.675 [main] DEBUG o.s.orm.jpa.JpaTransactionManager - Exposing JPA transaction as JDBC transaction [org.springframework.orm.jpa.vendor.HibernateJpaDialect$HibernateConnectionHandle at 566dc8f0]
10:51:26.676 [main] DEBUG o.s.o.j.ExtendedEntityManagerCreator$ExtendedEntityManagerInvocationHandler - Starting resource local transaction on application-managed EntityManager [org.hibernate.ejb.EntityManagerImpl at 41a330e4]
10:51:26.677 [main] DEBUG o.s.o.j.ExtendedEntityManagerCreator$ExtendedEntityManagerInvocationHandler - Joined local transaction
10:51:26.678 [main] DEBUG o.s.o.j.ExtendedEntityManagerCreator$ExtendedEntityManagerInvocationHandler - Joined local transaction
10:51:26.686 [main] DEBUG c.p.p.drools.ProcessEventListener - Leaving node [step-1 Approval]...
10:51:26.687 [main] DEBUG c.p.p.drools.ProcessEventListener - Triggering node [step-1 Approval Split]...
10:51:26.694 [main] DEBUG c.p.p.drools.ProcessEventListener - Leaving node [step-1 Approval Split]...
10:51:26.695 [main] DEBUG c.p.p.drools.ProcessEventListener - Triggering node [step-1 Reject Join]...
10:51:26.695 [main] DEBUG c.p.p.drools.ProcessEventListener - Leaving node [step-1 Reject Join]...
10:51:26.696 [main] DEBUG c.p.p.drools.ProcessEventListener - Triggering node [step-1 Step]...
10:51:26.732 [main] DEBUG c.p.p.drools.StepWorkItemHandler - Executing Step with Drools work item ID [3] for Step with instance UUID [48305f48-1ea6-47c2-a74b-254e48247285] in slice [NO_SLICE]
10:51:26.733 [main] DEBUG c.p.p.drools.ProcessEventListener - Node [step-1 Step] triggered.
10:51:26.733 [main] DEBUG c.p.p.drools.ProcessEventListener - Node [step-1 Reject Join] left.
10:51:26.734 [main] DEBUG c.p.p.drools.ProcessEventListener - Node [step-1 Reject Join] triggered.
10:51:26.734 [main] DEBUG c.p.p.drools.ProcessEventListener - Node [step-1 Approval Split] left.
10:51:26.782 [main] DEBUG c.p.p.drools.ProcessEventListener - Node [step-1 Approval Split] triggered.
10:51:26.783 [main] DEBUG c.p.p.drools.ProcessEventListener - Node [step-1 Approval] left.
10:51:26.787 [main] DEBUG o.s.orm.jpa.JpaTransactionManager - Initiating transaction commit
10:51:26.788 [main] DEBUG o.s.orm.jpa.JpaTransactionManager - Committing JPA transaction on EntityManager [org.hibernate.ejb.EntityManagerImpl at a70ad76]
10:51:26.797 [main] DEBUG o.s.orm.jpa.JpaTransactionManager - Not closing pre-bound JPA EntityManager after transaction
10:51:26.798 [main] DEBUG c.p.process.drools.DroolsFlowAdapter - Completing step instance [step-1 Step] with workItemId [3]
10:51:26.798 [main] DEBUG o.d.c.s.b.p.DroolsSpringTransactionManager - Current TX name (According to TransactionSynchronizationManager) : null
10:51:26.836 [main] DEBUG o.s.orm.jpa.JpaTransactionManager - Found thread-bound EntityManager [org.hibernate.ejb.EntityManagerImpl at a70ad76] for JPA transaction
10:51:26.837 [main] DEBUG o.s.orm.jpa.JpaTransactionManager - Creating new transaction with name [null]: PROPAGATION_REQUIRED,ISOLATION_DEFAULT
10:51:26.837 [main] DEBUG o.s.orm.jpa.JpaTransactionManager - Exposing JPA transaction as JDBC transaction [org.springframework.orm.jpa.vendor.HibernateJpaDialect$HibernateConnectionHandle at 4bdb0f40]
10:51:26.839 [main] DEBUG o.s.o.j.ExtendedEntityManagerCreator$ExtendedEntityManagerInvocationHandler - Starting resource local transaction on application-managed EntityManager [org.hibernate.ejb.EntityManagerImpl at 1ac659a8]
10:51:26.839 [main] DEBUG o.s.o.j.ExtendedEntityManagerCreator$ExtendedEntityManagerInvocationHandler - Joined local transaction
10:51:26.840 [main] DEBUG o.s.o.j.ExtendedEntityManagerCreator$ExtendedEntityManagerInvocationHandler - Joined local transaction
10:51:26.846 [main] DEBUG c.p.p.drools.ProcessEventListener - Leaving node [step-1 Step]...
10:51:26.889 [main] DEBUG c.p.p.drools.ProcessEventListener - Triggering node [step-1 Approval]...
10:51:26.892 [main] DEBUG c.p.p.drools.StepWorkItemHandler - Executing Step with Drools work item ID [4] for Step with instance UUID [6204a045-9c95-4392-8927-aa88333e38ce] in slice [NO_SLICE]
10:51:26.892 [main] DEBUG c.p.p.drools.ProcessEventListener - Node [step-1 Approval] triggered.
10:51:26.893 [main] DEBUG c.p.p.drools.ProcessEventListener - Node [step-1 Step] left.
10:51:26.895 [main] DEBUG o.s.orm.jpa.JpaTransactionManager - Initiating transaction commit
10:51:26.896 [main] DEBUG o.s.orm.jpa.JpaTransactionManager - Committing JPA transaction on EntityManager [org.hibernate.ejb.EntityManagerImpl at a70ad76]
10:51:26.952 [main] DEBUG o.s.orm.jpa.JpaTransactionManager - Not closing pre-bound JPA EntityManager after transaction
10:51:26.953 [main] DEBUG c.p.process.drools.DroolsFlowAdapter - Approving step instance [step-1 Approval]
10:51:26.956 [main] DEBUG o.d.c.s.b.p.DroolsSpringTransactionManager - Current TX name (According to TransactionSynchronizationManager) : null
10:51:26.956 [main] DEBUG o.s.orm.jpa.JpaTransactionManager - Found thread-bound EntityManager [org.hibernate.ejb.EntityManagerImpl at a70ad76] for JPA transaction
10:51:26.994 [main] DEBUG o.s.orm.jpa.JpaTransactionManager - Creating new transaction with name [null]: PROPAGATION_REQUIRED,ISOLATION_DEFAULT
10:51:26.995 [main] DEBUG o.s.orm.jpa.JpaTransactionManager - Exposing JPA transaction as JDBC transaction [org.springframework.orm.jpa.vendor.HibernateJpaDialect$HibernateConnectionHandle at 192eb04e]
10:51:26.997 [main] DEBUG o.s.o.j.ExtendedEntityManagerCreator$ExtendedEntityManagerInvocationHandler - Starting resource local transaction on application-managed EntityManager [org.hibernate.ejb.EntityManagerImpl at 4838ddcc]
10:51:26.998 [main] DEBUG o.s.o.j.ExtendedEntityManagerCreator$ExtendedEntityManagerInvocationHandler - Joined local transaction
10:51:26.998 [main] DEBUG o.s.o.j.ExtendedEntityManagerCreator$ExtendedEntityManagerInvocationHandler - Joined local transaction
10:51:27.014 [main] DEBUG o.s.orm.jpa.JpaTransactionManager - Initiating transaction commit
10:51:27.015 [main] DEBUG o.s.orm.jpa.JpaTransactionManager - Committing JPA transaction on EntityManager [org.hibernate.ejb.EntityManagerImpl at a70ad76]
10:51:27.021 [main] DEBUG o.s.orm.jpa.JpaTransactionManager - Not closing pre-bound JPA EntityManager after transaction
10:51:27.022 [main] DEBUG c.p.process.drools.DroolsFlowAdapter - Completing step instance [step-1 Approval] with workItemId [4]
10:51:27.022 [main] DEBUG o.d.c.s.b.p.DroolsSpringTransactionManager - Current TX name (According to TransactionSynchronizationManager) : null
10:51:27.051 [main] DEBUG o.s.orm.jpa.JpaTransactionManager - Found thread-bound EntityManager [org.hibernate.ejb.EntityManagerImpl at a70ad76] for JPA transaction
10:51:27.052 [main] DEBUG o.s.orm.jpa.JpaTransactionManager - Creating new transaction with name [null]: PROPAGATION_REQUIRED,ISOLATION_DEFAULT
10:51:27.052 [main] DEBUG o.s.orm.jpa.JpaTransactionManager - Exposing JPA transaction as JDBC transaction [org.springframework.orm.jpa.vendor.HibernateJpaDialect$HibernateConnectionHandle at 6c4f7b4c]
10:51:27.054 [main] DEBUG o.s.o.j.ExtendedEntityManagerCreator$ExtendedEntityManagerInvocationHandler - Starting resource local transaction on application-managed EntityManager [org.hibernate.ejb.EntityManagerImpl at 5627f221]
10:51:27.054 [main] DEBUG o.s.o.j.ExtendedEntityManagerCreator$ExtendedEntityManagerInvocationHandler - Joined local transaction
10:51:27.055 [main] DEBUG o.s.o.j.ExtendedEntityManagerCreator$ExtendedEntityManagerInvocationHandler - Joined local transaction
10:51:27.062 [main] DEBUG c.p.p.drools.ProcessEventListener - Leaving node [step-1 Approval]...
10:51:27.063 [main] DEBUG c.p.p.drools.ProcessEventListener - Triggering node [step-1 Approval Split]...
10:51:27.063 [main] DEBUG c.p.p.drools.ProcessEventListener - Leaving node [step-1 Approval Split]...
10:51:27.066 [main] DEBUG c.p.p.drools.ProcessEventListener - Triggering node [null Wait]...
10:51:27.067 [main] DEBUG c.proferi.process.manager.Terminator - Active nodes: 1
10:51:27.067 [main] DEBUG c.proferi.process.manager.Terminator - Terminating Flow
10:51:27.133 [main] DEBUG c.p.p.drools.ProcessEventListener - Leaving node [null Wait]...
10:51:27.134 [main] DEBUG c.p.p.drools.ProcessEventListener - Triggering node [null End]...
10:51:27.134 [main] DEBUG c.p.p.drools.ProcessEventListener - Leaving node [null End]...
10:51:27.136 [main] DEBUG c.p.p.drools.ProcessEventListener - Completing process [flow-1]...
10:51:27.140 [main] DEBUG c.p.p.drools.ProcessEventListener - Process [flow-1] Complete.
10:51:27.143 [main] DEBUG c.p.p.drools.ProcessEventListener - Node [null End] left.
10:51:27.159 [main] DEBUG c.p.p.drools.ProcessEventListener - Node [null End] triggered.
10:51:27.160 [main] DEBUG c.p.p.drools.ProcessEventListener - Node [null Wait] left.
10:51:27.160 [main] DEBUG c.p.p.drools.ProcessEventListener - Node [null Wait] triggered.
10:51:27.161 [main] DEBUG c.p.p.drools.ProcessEventListener - Node [step-1 Approval Split] left.
10:51:27.161 [main] DEBUG c.p.p.drools.ProcessEventListener - Node [step-1 Approval Split] triggered.
10:51:27.162 [main] DEBUG c.p.p.drools.ProcessEventListener - Node [step-1 Approval] left.
10:51:27.165 [main] DEBUG o.s.orm.jpa.JpaTransactionManager - Initiating transaction commit
10:51:27.165 [main] DEBUG o.s.orm.jpa.JpaTransactionManager - Committing JPA transaction on EntityManager [org.hibernate.ejb.EntityManagerImpl at a70ad76]
10:51:27.172 [main] DEBUG o.s.orm.jpa.JpaTransactionManager - Not closing pre-bound JPA EntityManager after transaction
10:51:27.174 [main] INFO o.s.c.s.ClassPathXmlApplicationContext - Closing org.springframework.context.support.ClassPathXmlApplicationContext at 1fbbdd48: startup date [Fri Apr 01 09:16:06 PDT 2011]; root of context hierarchy
10:51:27.221 [main] INFO o.s.c.s.DefaultLifecycleProcessor - Stopping beans in phase 0
10:51:27.222 [main] INFO o.s.b.f.s.DefaultListableBeanFactory - Destroying singletons in org.springframework.beans.factory.support.DefaultListableBeanFactory at 30b48b11: defining beans [processFlowManager,stepWorkItemHandler,stepActivationCallbackHandler,processEventListener,modelCache,modelFactory,droolsFlowAdapter,memberSetResolver,instanceCache,processFlowService,startProcessFlowHandler,getProcessFlowStatusHandler,stepCompletedServiceHandler,approvalCompletedServiceHandler,connectionFactory,protobufJmsListener,protobufConverter,messageHandler,cachedConnectionFactory,jmsTemplate,messageProducer,dataSource,transactionManager,entityManagerFactory,jpaAdapter,entityManager,org.springframework.beans.factory.config.PropertyPlaceholderConfigurer#0,testOutJmsTemplate,testInJmsTemplate,testInConverter,outListener,inSender,embeddedJmsBroker]; root of factory hierarchy
Disconnected from the target VM, address: 'javadebug', transport: 'shared memory'
10:51:27.269 [main] INFO o.s.o.j.LocalContainerEntityManagerFactoryBean - Closing JPA EntityManagerFactory for persistence unit 'org.drools.persistence.jpa'
Process finished with exit code 0
More information about the rules-users
mailing list