Schduling event firing transation error

Imported from Google Groups
1

Here is the scenario

Saga fire scheduling event… successful
Scheduling event fires after time duration and is handled by saga…successful
Saga fires another scheduling event, however now handling of that event does NOT fire and get this error in the firing of the scheduled event…snippet of log below…Any Ideas

Hibernate: select sagaentry0_.sagaId as sagaId6_0_, sagaentry0_.serializedSaga as serializ2_6_0_ from SagaEntry sagaentry0_ where sagaentry0_.sagaId=?

2011-05-07 22:53:11,627 [scheduler_Worker-1] ERROR org.quartz.core.JobRunShell - Job AxonFramework-Events.event-1552c585-80e3-4a3e-811b-dadea0ac9174 threw an unhandled Exception:

javax.persistence.TransactionRequiredException: no transaction is in progress

at org.hibernate.ejb.AbstractEntityManagerImpl.flush(AbstractEntityManagerImpl.java:301)

at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)

at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)

at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)

at java.lang.reflect.Method.invoke(Method.java:597)

at org.springframework.orm.jpa.ExtendedEntityManagerCreator$ExtendedEntityManagerInvocationHandler.invoke(ExtendedEntityManagerCreator.java:365)

at $Proxy29.flush(Unknown Source)

at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)

at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)

at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)

at java.lang.reflect.Method.invoke(Method.java:597)

at org.springframework.orm.jpa.SharedEntityManagerCreator$SharedEntityManagerInvocationHandler.invoke(SharedEntityManagerCreator.java:240)

at $Proxy29.flush(Unknown Source)

at org.axonframework.saga.repository.jpa.JpaSagaRepository.updateSaga(JpaSagaRepository.java:102)

at org.axonframework.saga.repository.AbstractSagaRepository.commit(AbstractSagaRepository.java:110)

at org.axonframework.saga.AbstractSagaManager.commit(AbstractSagaManager.java:136)

at org.axonframework.saga.AbstractSagaManager.invokeSagaHandler(AbstractSagaManager.java:117)

at org.axonframework.saga.AbstractSagaManager.access$100(AbstractSagaManager.java:40)

at org.axonframework.saga.AbstractSagaManager$SagaInvocationTask.run(AbstractSagaManager.java:210)

at org.axonframework.saga.SynchronousSagaExecutionWrapper.scheduleEventProcessingTask(SynchronousSagaExecutionWrapper.java:31)

at org.axonframework.saga.AbstractSagaManager$SagaLookupAndInvocationTask.run(AbstractSagaManager.java:229)

at org.axonframework.saga.SynchronousSagaExecutionWrapper.scheduleLookupTask(SynchronousSagaExecutionWrapper.java:26)

at org.axonframework.saga.AbstractSagaManager.handle(AbstractSagaManager.java:86)

at org.axonframework.eventhandling.SimpleEventBus.publish(SimpleEventBus.java:110)

at org.axonframework.eventhandling.scheduling.quartz.FireEventJob.execute(FireEventJob.java:55)

at org.quartz.core.JobRunShell.run(JobRunShell.java:216)

at org.quartz.simpl.SimpleThreadPool$WorkerThread.run(SimpleThreadPool.java:549)

2011-05-07 22:53:11,629 [scheduler_Worker-1] ERROR org.quartz.core.ErrorLogger - Job (AxonFramework-Events.event-1552c585-80e3-4a3e-811b-dadea0ac9174 threw an exception.

org.quartz.SchedulerException: Job threw an unhandled exception. [See nested exception: javax.persistence.TransactionRequiredException: no transaction is in progress]

at org.quartz.core.JobRunShell.run(JobRunShell.java:227)

at org.quartz.simpl.SimpleThreadPool$WorkerThread.run(SimpleThreadPool.java:549)

Caused by: javax.persistence.TransactionRequiredException: no transaction is in progress

at org.hibernate.ejb.AbstractEntityManagerImpl.flush(AbstractEntityManagerImpl.java:301)

at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)

at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)

at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)

at java.lang.reflect.Method.invoke(Method.java:597)

at org.springframework.orm.jpa.ExtendedEntityManagerCreator$ExtendedEntityManagerInvocationHandler.invoke(ExtendedEntityManagerCreator.java:365)

at $Proxy29.flush(Unknown Source)

at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)

at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)

at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)

at java.lang.reflect.Method.invoke(Method.java:597)

at org.springframework.orm.jpa.SharedEntityManagerCreator$SharedEntityManagerInvocationHandler.invoke(SharedEntityManagerCreator.java:240)

at $Proxy29.flush(Unknown Source)

at org.axonframework.saga.repository.jpa.JpaSagaRepository.updateSaga(JpaSagaRepository.java:102)

at org.axonframework.saga.repository.AbstractSagaRepository.commit(AbstractSagaRepository.java:110)

at org.axonframework.saga.AbstractSagaManager.commit(AbstractSagaManager.java:136)

at org.axonframework.saga.AbstractSagaManager.invokeSagaHandler(AbstractSagaManager.java:117)

at org.axonframework.saga.AbstractSagaManager.access$100(AbstractSagaManager.java:40)

at org.axonframework.saga.AbstractSagaManager$SagaInvocationTask.run(AbstractSagaManager.java:210)

at org.axonframework.saga.SynchronousSagaExecutionWrapper.scheduleEventProcessingTask(SynchronousSagaExecutionWrapper.java:31)

at org.axonframework.saga.AbstractSagaManager$SagaLookupAndInvocationTask.run(AbstractSagaManager.java:229)

at org.axonframework.saga.SynchronousSagaExecutionWrapper.scheduleLookupTask(SynchronousSagaExecutionWrapper.java:26)

at org.axonframework.saga.AbstractSagaManager.handle(AbstractSagaManager.java:86)

at org.axonframework.eventhandling.SimpleEventBus.publish(SimpleEventBus.java:110)

at org.axonframework.eventhandling.scheduling.quartz.FireEventJob.execute(FireEventJob.java:55)

at org.quartz.core.JobRunShell.run(JobRunShell.java:216)

… 1 more

2

On Further review of the debug log…it seems that the events are firing and handling correctly however this error keeps on showing up in the log…seems like the JobRun is throwing an exception for the Axon job.

Cheers.

3

The scenario is reproducible in a interesting pattern…hmm

incoming time Schedule event firing handler in Saga trying to schedule another Schedule event via scheduler at a later time in the same handler. The error shows up immediately after the scheduler.schedule call. After error the scheduler timed events still seem to be firing correctly.

4

The first scheduled event is published in a thread managed by Quartz. There probably isn't an active transaction on that one. If you register a transaction manager on your SagaManager, that should fix the problem.

Cheers,

Allard

5

Tried it…did not work. Have replicated the problem with the test in axon core for SimpleTiming Saga. Info log is below. Let me know if you need debug log. However Axon framework unit test should show this error

Cheers…

Here is the entry for SagaManager config that was modified…to add transactionManager

<axon:saga-manager id=“sagaManager” saga-repository=“sagaRepository” event-bus=“eventBus” transaction-manager=“transactionManger”>

axon:types

test.SimpleTimingSaga

</axon:types>

</axon:saga-manager>

Here is the log with isolated unit test from axon core

2011-05-08 11:16:24,752 [main] INFO org.springframework.test.context.TestContextManager - @TestExecutionListeners is not present for class [class test.QuartzSagaTimerIntegrationTest]: using defaults.

2011-05-08 11:16:24,857 [main] INFO org.springframework.beans.factory.xml.XmlBeanDefinitionReader - Loading XML bean definitions from class path resource [META-INF/spring/saga-quartz-integration-test.xml]

2011-05-08 11:16:25,103 [main] INFO org.springframework.beans.factory.xml.XmlBeanDefinitionReader - Loading XML bean definitions from class path resource [META-INF/spring/db-context.xml]

2011-05-08 11:16:25,138 [main] INFO org.springframework.beans.factory.xml.XmlBeanDefinitionReader - Loading XML bean definitions from class path resource [META-INF/spring/test-context.xml]

2011-05-08 11:16:25,182 [main] INFO org.springframework.context.support.GenericApplicationContext - Refreshing org.springframework.context.support.GenericApplicationContext@1f8b81e3: startup date [Sun May 08 11:16:25 EDT 2011]; root of context hierarchy

2011-05-08 11:16:25,328 [main] INFO org.springframework.beans.factory.config.PropertyPlaceholderConfigurer - Loading properties file from class path resource [META-INF/spring/hsqldb.database.properties]

2011-05-08 11:16:25,334 [main] INFO org.springframework.beans.factory.annotation.AutowiredAnnotationBeanPostProcessor - JSR-330 ‘javax.inject.Inject’ annotation found and supported for autowiring

2011-05-08 11:16:25,362 [main] INFO org.springframework.beans.factory.support.DefaultListableBeanFactory - Pre-instantiating singletons in org.springframework.beans.factory.support.DefaultListableBeanFactory@7f5e2075: defining beans [org.springframework.context.annotation.internalConfigurationAnnotationProcessor,org.springframework.context.annotation.internalAutowiredAnnotationProcessor,org.springframework.context.annotation.internalRequiredAnnotationProcessor,org.springframework.context.annotation.internalCommonAnnotationProcessor,org.springframework.context.annotation.internalPersistenceAnnotationProcessor,org.springframework.aop.config.internalAutoProxyCreator,org.springframework.transaction.annotation.AnnotationTransactionAttributeSource#0,org.springframework.transaction.interceptor.TransactionInterceptor#0,org.springframework.transaction.config.internalTransactionAdvisor,org.springframework.beans.factory.config.PropertyPlaceholderConfigurer#0,entityManagerFactory,transactionManager,org.springframework.orm.jpa.support.PersistenceAnnotationBeanPostProcessor#0,dataSource,org.axonframework.eventstore.jpa.JpaEventStore#0,eventBus,sagaRepository,commandBus,sagaManager,com.testing.server.infrastructure.quartz.QuartzTableMaker#0,org.axonframework.saga.spring.SpringResourceInjector#0,org.axonframework.eventhandling.scheduling.quartz.QuartzEventScheduler#0,scheduler]; root of factory hierarchy

2011-05-08 11:16:25,443 [main] INFO org.springframework.jdbc.datasource.DriverManagerDataSource - Loaded JDBC driver: org.hsqldb.jdbcDriver

2011-05-08 11:16:25,460 [main] INFO org.springframework.orm.jpa.LocalContainerEntityManagerFactoryBean - Building JPA container EntityManagerFactory for persistence unit ‘eventStore’

2011-05-08 11:16:25,489 [main] INFO org.hibernate.cfg.annotations.Version - Hibernate Annotations 3.4.0.GA

2011-05-08 11:16:25,497 [main] INFO org.hibernate.cfg.Environment - Hibernate 3.3.0.SP1

2011-05-08 11:16:25,500 [main] INFO org.hibernate.cfg.Environment - hibernate.properties not found

2011-05-08 11:16:25,503 [main] INFO org.hibernate.cfg.Environment - Bytecode provider name : javassist

2011-05-08 11:16:25,506 [main] INFO org.hibernate.cfg.Environment - using JDK 1.4 java.sql.Timestamp handling

2011-05-08 11:16:25,547 [main] INFO org.hibernate.annotations.common.Version - Hibernate Commons Annotations 3.1.0.GA

2011-05-08 11:16:25,549 [main] INFO org.hibernate.ejb.Version - Hibernate EntityManager 3.4.0.GA

2011-05-08 11:16:25,564 [main] INFO org.hibernate.ejb.Ejb3Configuration - Processing PersistenceUnitInfo [

name: eventStore

…]

2011-05-08 11:16:25,629 [main] INFO org.hibernate.cfg.AnnotationBinder - Binding entity from annotated class: org.axonframework.eventstore.jpa.DomainEventEntry

2011-05-08 11:16:25,656 [main] INFO org.hibernate.cfg.annotations.EntityBinder - Bind entity org.axonframework.eventstore.jpa.DomainEventEntry on table DomainEventEntry

2011-05-08 11:16:25,698 [main] INFO org.hibernate.cfg.AnnotationBinder - Binding entity from annotated class: org.axonframework.eventstore.jpa.SnapshotEventEntry

2011-05-08 11:16:25,698 [main] INFO org.hibernate.cfg.annotations.EntityBinder - Bind entity org.axonframework.eventstore.jpa.SnapshotEventEntry on table SnapshotEventEntry

2011-05-08 11:16:25,700 [main] INFO org.hibernate.cfg.AnnotationBinder - Binding entity from annotated class: org.axonframework.saga.repository.jpa.AssociationValueEntry

2011-05-08 11:16:25,700 [main] INFO org.hibernate.cfg.annotations.EntityBinder - Bind entity org.axonframework.saga.repository.jpa.AssociationValueEntry on table AssociationValueEntry

2011-05-08 11:16:25,703 [main] INFO org.hibernate.cfg.AnnotationBinder - Binding entity from annotated class: org.axonframework.saga.repository.jpa.SagaEntry

2011-05-08 11:16:25,703 [main] INFO org.hibernate.cfg.annotations.EntityBinder - Bind entity org.axonframework.saga.repository.jpa.SagaEntry on table SagaEntry

2011-05-08 11:16:25,708 [main] INFO org.hibernate.cfg.AnnotationConfiguration - Hibernate Validator not found: ignoring

2011-05-08 11:16:25,730 [main] INFO org.hibernate.cfg.search.HibernateSearchEventListenerRegister - Unable to find org.hibernate.search.event.FullTextIndexEventListener on the classpath. Hibernate Search is not enabled.

2011-05-08 11:16:25,766 [main] INFO org.hibernate.connection.ConnectionProviderFactory - Initializing connection provider: org.hibernate.ejb.connection.InjectedDataSourceConnectionProvider

2011-05-08 11:16:25,769 [main] INFO org.hibernate.ejb.connection.InjectedDataSourceConnectionProvider - Using provided datasource

2011-05-08 11:16:25,878 [main] INFO org.hibernate.cfg.SettingsFactory - RDBMS: HSQL Database Engine, version: 1.8.0

2011-05-08 11:16:25,878 [main] INFO org.hibernate.cfg.SettingsFactory - JDBC driver: HSQL Database Engine Driver, version: 1.8.0

2011-05-08 11:16:25,890 [main] INFO org.hibernate.dialect.Dialect - Using dialect: org.hibernate.dialect.HSQLDialect

2011-05-08 11:16:25,894 [main] INFO org.hibernate.transaction.TransactionFactoryFactory - Transaction strategy: org.hibernate.transaction.JDBCTransactionFactory

2011-05-08 11:16:25,895 [main] INFO org.hibernate.transaction.TransactionManagerLookupFactory - No TransactionManagerLookup configured (in JTA environment, use of read-write or transactional second-level cache is not recommended)

2011-05-08 11:16:25,895 [main] INFO org.hibernate.cfg.SettingsFactory - Automatic flush during beforeCompletion(): disabled

2011-05-08 11:16:25,895 [main] INFO org.hibernate.cfg.SettingsFactory - Automatic session close at end of transaction: disabled

2011-05-08 11:16:25,895 [main] INFO org.hibernate.cfg.SettingsFactory - JDBC batch size: 15

2011-05-08 11:16:25,895 [main] INFO org.hibernate.cfg.SettingsFactory - JDBC batch updates for versioned data: disabled

2011-05-08 11:16:25,896 [main] INFO org.hibernate.cfg.SettingsFactory - Scrollable result sets: enabled

2011-05-08 11:16:25,896 [main] INFO org.hibernate.cfg.SettingsFactory - JDBC3 getGeneratedKeys(): disabled

2011-05-08 11:16:25,896 [main] INFO org.hibernate.cfg.SettingsFactory - Connection release mode: auto

2011-05-08 11:16:25,896 [main] INFO org.hibernate.cfg.SettingsFactory - Default batch fetch size: 1

2011-05-08 11:16:25,896 [main] INFO org.hibernate.cfg.SettingsFactory - Generate SQL with comments: disabled

2011-05-08 11:16:25,897 [main] INFO org.hibernate.cfg.SettingsFactory - Order SQL updates by primary key: disabled

2011-05-08 11:16:25,897 [main] INFO org.hibernate.cfg.SettingsFactory - Order SQL inserts for batching: disabled

2011-05-08 11:16:25,897 [main] INFO org.hibernate.cfg.SettingsFactory - Query translator: org.hibernate.hql.ast.ASTQueryTranslatorFactory

2011-05-08 11:16:25,898 [main] INFO org.hibernate.hql.ast.ASTQueryTranslatorFactory - Using ASTQueryTranslatorFactory

2011-05-08 11:16:25,899 [main] INFO org.hibernate.cfg.SettingsFactory - Query language substitutions: {}

2011-05-08 11:16:25,899 [main] INFO org.hibernate.cfg.SettingsFactory - JPA-QL strict compliance: enabled

2011-05-08 11:16:25,899 [main] INFO org.hibernate.cfg.SettingsFactory - Second-level cache: enabled

2011-05-08 11:16:25,899 [main] INFO org.hibernate.cfg.SettingsFactory - Query cache: disabled

2011-05-08 11:16:25,899 [main] INFO org.hibernate.cfg.SettingsFactory - Cache region factory : org.hibernate.cache.impl.NoCachingRegionFactory

2011-05-08 11:16:25,899 [main] INFO org.hibernate.cfg.SettingsFactory - Optimize cache for minimal puts: disabled

2011-05-08 11:16:25,899 [main] INFO org.hibernate.cfg.SettingsFactory - Structured second-level cache entries: disabled

2011-05-08 11:16:25,904 [main] INFO org.hibernate.cfg.SettingsFactory - Statistics: disabled

2011-05-08 11:16:25,905 [main] INFO org.hibernate.cfg.SettingsFactory - Deleted entity synthetic identifier rollback: disabled

2011-05-08 11:16:25,906 [main] INFO org.hibernate.cfg.SettingsFactory - Default entity-mode: pojo

2011-05-08 11:16:25,906 [main] INFO org.hibernate.cfg.SettingsFactory - Named query checking : enabled

2011-05-08 11:16:25,942 [main] INFO org.hibernate.impl.SessionFactoryImpl - building session factory

2011-05-08 11:16:26,165 [main] INFO org.hibernate.impl.SessionFactoryObjectFactory - Not binding factory to JNDI, no JNDI name configured

2011-05-08 11:16:26,168 [main] INFO org.hibernate.tool.hbm2ddl.SchemaUpdate - Running hbm2ddl schema update

2011-05-08 11:16:26,168 [main] INFO org.hibernate.tool.hbm2ddl.SchemaUpdate - fetching database metadata

2011-05-08 11:16:26,173 [main] INFO org.hibernate.tool.hbm2ddl.SchemaUpdate - updating schema

2011-05-08 11:16:26,187 [main] INFO org.hibernate.tool.hbm2ddl.DatabaseMetadata - table not found: AssociationValueEntry

2011-05-08 11:16:26,188 [main] INFO org.hibernate.tool.hbm2ddl.DatabaseMetadata - table not found: DomainEventEntry

2011-05-08 11:16:26,188 [main] INFO org.hibernate.tool.hbm2ddl.DatabaseMetadata - table not found: SagaEntry

2011-05-08 11:16:26,189 [main] INFO org.hibernate.tool.hbm2ddl.DatabaseMetadata - table not found: SnapshotEventEntry

2011-05-08 11:16:26,189 [main] INFO org.hibernate.tool.hbm2ddl.DatabaseMetadata - table not found: AssociationValueEntry

2011-05-08 11:16:26,190 [main] INFO org.hibernate.tool.hbm2ddl.DatabaseMetadata - table not found: DomainEventEntry

2011-05-08 11:16:26,190 [main] INFO org.hibernate.tool.hbm2ddl.DatabaseMetadata - table not found: SagaEntry

2011-05-08 11:16:26,191 [main] INFO org.hibernate.tool.hbm2ddl.DatabaseMetadata - table not found: SnapshotEventEntry

2011-05-08 11:16:26,196 [main] INFO org.hibernate.tool.hbm2ddl.SchemaUpdate - schema update complete

2011-05-08 11:16:26,711 [main] INFO org.springframework.scheduling.quartz.SchedulerFactoryBean - Loading Quartz config from [class path resource [META-INF/spring/quartz.test.properties]]

2011-05-08 11:16:26,745 [main] INFO org.quartz.simpl.SimpleThreadPool - Job execution threads will use class loader of thread: main

2011-05-08 11:16:26,764 [main] INFO org.quartz.core.SchedulerSignalerImpl - Initialized Scheduler Signaller of type: class org.quartz.core.SchedulerSignalerImpl

2011-05-08 11:16:26,766 [main] INFO org.quartz.core.QuartzScheduler - Quartz Scheduler v.1.8.4 created.

2011-05-08 11:16:26,777 [main] INFO org.springframework.scheduling.quartz.LocalDataSourceJobStore - JobStoreCMT initialized.

2011-05-08 11:16:26,778 [main] INFO org.quartz.core.QuartzScheduler - Scheduler meta-data: Quartz Scheduler (v1.8.4) ‘scheduler’ with instanceId ‘1’

Scheduler class: ‘org.quartz.core.QuartzScheduler’ - running locally.

NOT STARTED.

Currently in standby mode.

Number of jobs executed: 0

Using thread pool ‘org.quartz.simpl.SimpleThreadPool’ - with 10 threads.

Using job-store ‘org.springframework.scheduling.quartz.LocalDataSourceJobStore’ - which supports persistence. and is clustered.

2011-05-08 11:16:26,778 [main] INFO org.quartz.impl.StdSchedulerFactory - Quartz scheduler ‘scheduler’ initialized from an externally provided properties instance.

2011-05-08 11:16:26,778 [main] INFO org.quartz.impl.StdSchedulerFactory - Quartz scheduler version: 1.8.4

2011-05-08 11:16:26,781 [main] INFO org.quartz.core.QuartzScheduler - JobFactory set to: org.springframework.scheduling.quartz.AdaptableJobFactory@2c8210fc

2011-05-08 11:16:26,799 [main] INFO org.springframework.context.support.DefaultLifecycleProcessor - Starting beans in phase 2147483647

2011-05-08 11:16:26,799 [main] INFO org.springframework.scheduling.quartz.SchedulerFactoryBean - Starting Quartz Scheduler now

2011-05-08 11:16:26,819 [main] INFO org.quartz.core.QuartzScheduler - Scheduler scheduler_$_1 started.

2011-05-08 11:16:27,149 [main] INFO test.SimpleTimingSaga - entering handle(StartingEvent event) and getting ready to schedule MySagaExpiredEvent

2011-05-08 11:16:28,163 [scheduler_Worker-1] INFO test.SimpleTimingSaga - in handle(MySagaExpiredEvent event) and setting triggered=true

2011-05-08 11:16:28,163 [main] INFO test.SimpleTimingSaga - isTriggered() is returning true

2011-05-08 11:16:28,166 [Thread-5] INFO org.springframework.context.support.GenericApplicationContext - Closing org.springframework.context.support.GenericApplicationContext@1f8b81e3: startup date [Sun May 08 11:16:25 EDT 2011]; root of context hierarchy

2011-05-08 11:16:28,168 [Thread-5] INFO org.springframework.context.support.DefaultLifecycleProcessor - Stopping beans in phase 2147483647

2011-05-08 11:16:28,169 [scheduler_Worker-1] ERROR org.quartz.core.JobRunShell - Job AxonFramework-Events.event-5197bec7-3fbb-47c7-9178-61323e6ddf1f threw an unhandled Exception:

javax.persistence.TransactionRequiredException: no transaction is in progress

at org.hibernate.ejb.AbstractEntityManagerImpl.flush(AbstractEntityManagerImpl.java:301)

at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)

at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)

at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)

at java.lang.reflect.Method.invoke(Method.java:597)

at org.springframework.orm.jpa.ExtendedEntityManagerCreator$ExtendedEntityManagerInvocationHandler.invoke(ExtendedEntityManagerCreator.java:365)

at $Proxy19.flush(Unknown Source)

at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)

at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)

at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)

at java.lang.reflect.Method.invoke(Method.java:597)

at org.springframework.orm.jpa.SharedEntityManagerCreator$SharedEntityManagerInvocationHandler.invoke(SharedEntityManagerCreator.java:240)

at $Proxy19.flush(Unknown Source)

at org.axonframework.saga.repository.jpa.JpaSagaRepository.updateSaga(JpaSagaRepository.java:102)

at org.axonframework.saga.repository.AbstractSagaRepository.commit(AbstractSagaRepository.java:110)

at org.axonframework.saga.AbstractSagaManager.commit(AbstractSagaManager.java:136)

at org.axonframework.saga.AbstractSagaManager.invokeSagaHandler(AbstractSagaManager.java:117)

at org.axonframework.saga.AbstractSagaManager.access$100(AbstractSagaManager.java:40)

at org.axonframework.saga.AbstractSagaManager$SagaInvocationTask.run(AbstractSagaManager.java:210)

at org.axonframework.saga.SynchronousSagaExecutionWrapper.scheduleEventProcessingTask(SynchronousSagaExecutionWrapper.java:31)

at org.axonframework.saga.AbstractSagaManager$SagaLookupAndInvocationTask.run(AbstractSagaManager.java:229)

at org.axonframework.saga.SynchronousSagaExecutionWrapper.scheduleLookupTask(SynchronousSagaExecutionWrapper.java:26)

at org.axonframework.saga.AbstractSagaManager.handle(AbstractSagaManager.java:86)

at org.axonframework.eventhandling.SimpleEventBus.publish(SimpleEventBus.java:110)

at org.axonframework.eventhandling.scheduling.quartz.FireEventJob.execute(FireEventJob.java:55)

at org.quartz.core.JobRunShell.run(JobRunShell.java:216)

at org.quartz.simpl.SimpleThreadPool$WorkerThread.run(SimpleThreadPool.java:549)

2011-05-08 11:16:28,170 [Thread-5] INFO org.quartz.core.QuartzScheduler - Scheduler scheduler_$_1 paused.

2011-05-08 11:16:28,171 [Thread-5] INFO org.springframework.beans.factory.support.DefaultListableBeanFactory - Destroying singletons in org.springframework.beans.factory.support.DefaultListableBeanFactory@7f5e2075: defining beans [org.springframework.context.annotation.internalConfigurationAnnotationProcessor,org.springframework.context.annotation.internalAutowiredAnnotationProcessor,org.springframework.context.annotation.internalRequiredAnnotationProcessor,org.springframework.context.annotation.internalCommonAnnotationProcessor,org.springframework.context.annotation.internalPersistenceAnnotationProcessor,org.springframework.aop.config.internalAutoProxyCreator,org.springframework.transaction.annotation.AnnotationTransactionAttributeSource#0,org.springframework.transaction.interceptor.TransactionInterceptor#0,org.springframework.transaction.config.internalTransactionAdvisor,org.springframework.beans.factory.config.PropertyPlaceholderConfigurer#0,entityManagerFactory,transactionManager,org.springframework.orm.jpa.support.PersistenceAnnotationBeanPostProcessor#0,dataSource,org.axonframework.eventstore.jpa.JpaEventStore#0,eventBus,sagaRepository,commandBus,sagaManager,com.testing.server.infrastructure.quartz.QuartzTableMaker#0,org.axonframework.saga.spring.SpringResourceInjector#0,org.axonframework.eventhandling.scheduling.quartz.QuartzEventScheduler#0,scheduler]; root of factory hierarchy

2011-05-08 11:16:28,171 [scheduler_Worker-1] ERROR org.quartz.core.ErrorLogger - Job (AxonFramework-Events.event-5197bec7-3fbb-47c7-9178-61323e6ddf1f threw an exception.

org.quartz.SchedulerException: Job threw an unhandled exception. [See nested exception: javax.persistence.TransactionRequiredException: no transaction is in progress]

at org.quartz.core.JobRunShell.run(JobRunShell.java:227)

at org.quartz.simpl.SimpleThreadPool$WorkerThread.run(SimpleThreadPool.java:549)

Caused by: javax.persistence.TransactionRequiredException: no transaction is in progress

at org.hibernate.ejb.AbstractEntityManagerImpl.flush(AbstractEntityManagerImpl.java:301)

at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)

at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)

at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)

at java.lang.reflect.Method.invoke(Method.java:597)

at org.springframework.orm.jpa.ExtendedEntityManagerCreator$ExtendedEntityManagerInvocationHandler.invoke(ExtendedEntityManagerCreator.java:365)

at $Proxy19.flush(Unknown Source)

at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)

at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)

at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)

at java.lang.reflect.Method.invoke(Method.java:597)

at org.springframework.orm.jpa.SharedEntityManagerCreator$SharedEntityManagerInvocationHandler.invoke(SharedEntityManagerCreator.java:240)

at $Proxy19.flush(Unknown Source)

at org.axonframework.saga.repository.jpa.JpaSagaRepository.updateSaga(JpaSagaRepository.java:102)

at org.axonframework.saga.repository.AbstractSagaRepository.commit(AbstractSagaRepository.java:110)

at org.axonframework.saga.AbstractSagaManager.commit(AbstractSagaManager.java:136)

at org.axonframework.saga.AbstractSagaManager.invokeSagaHandler(AbstractSagaManager.java:117)

at org.axonframework.saga.AbstractSagaManager.access$100(AbstractSagaManager.java:40)

at org.axonframework.saga.AbstractSagaManager$SagaInvocationTask.run(AbstractSagaManager.java:210)

at org.axonframework.saga.SynchronousSagaExecutionWrapper.scheduleEventProcessingTask(SynchronousSagaExecutionWrapper.java:31)

at org.axonframework.saga.AbstractSagaManager$SagaLookupAndInvocationTask.run(AbstractSagaManager.java:229)

at org.axonframework.saga.SynchronousSagaExecutionWrapper.scheduleLookupTask(SynchronousSagaExecutionWrapper.java:26)

at org.axonframework.saga.AbstractSagaManager.handle(AbstractSagaManager.java:86)

at org.axonframework.eventhandling.SimpleEventBus.publish(SimpleEventBus.java:110)

at org.axonframework.eventhandling.scheduling.quartz.FireEventJob.execute(FireEventJob.java:55)

at org.quartz.core.JobRunShell.run(JobRunShell.java:216)

… 1 more

2011-05-08 11:16:28,172 [Thread-5] INFO org.springframework.scheduling.quartz.SchedulerFactoryBean - Shutting down Quartz Scheduler

2011-05-08 11:16:28,172 [Thread-5] INFO org.quartz.core.QuartzScheduler - Scheduler scheduler_$_1 shutting down.

2011-05-08 11:16:28,173 [Thread-5] INFO org.quartz.core.QuartzScheduler - Scheduler scheduler_$_1 paused.

2011-05-08 11:16:28,173 [Thread-5] INFO org.quartz.core.QuartzScheduler - Scheduler scheduler_$_1 shutdown complete.

2011-05-08 11:16:28,174 [Thread-5] INFO org.springframework.orm.jpa.LocalContainerEntityManagerFactoryBean - Closing JPA EntityManagerFactory for persistence unit ‘eventStore’

2011-05-08 11:16:28,174 [Thread-5] INFO org.hibernate.impl.SessionFactoryImpl - closing

6

Hi,

after some further investigation, it seems that there is no support for transactions for events generated by the event scheduler. That can cause problems when listeners depend on a transaction being attached to the thread.
I’ll provide support for that soon. I have created issue #156 for this.

Cheers,

Allard

7

Thank You…Below is a debug log with more granularity for your reference…

Cheers…

2011-05-08 11:47:43,346 [main] DEBUG org.hibernate.jdbc.AbstractBatcher - about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
2011-05-08 11:47:43,346 [main] DEBUG org.hibernate.SQL -
DROP TABLE qrtz_trigger_listeners IF EXISTS
2011-05-08 11:47:43,347 [main] DEBUG org.hibernate.jdbc.AbstractBatcher - about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
2011-05-08 11:47:43,347 [main] DEBUG org.hibernate.jdbc.AbstractBatcher - about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
2011-05-08 11:47:43,347 [main] DEBUG org.hibernate.SQL -
DROP TABLE qrtz_blob_triggers IF EXISTS
2011-05-08 11:47:43,347 [main] DEBUG org.hibernate.jdbc.AbstractBatcher - about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
2011-05-08 11:47:43,347 [main] DEBUG org.hibernate.jdbc.AbstractBatcher - about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
2011-05-08 11:47:43,347 [main] DEBUG org.hibernate.SQL -
DROP TABLE qrtz_cron_triggers IF EXISTS
2011-05-08 11:47:43,348 [main] DEBUG org.hibernate.jdbc.AbstractBatcher - about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
2011-05-08 11:47:43,348 [main] DEBUG org.hibernate.jdbc.AbstractBatcher - about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
2011-05-08 11:47:43,348 [main] DEBUG org.hibernate.SQL -
DROP TABLE qrtz_simple_triggers IF EXISTS
2011-05-08 11:47:43,348 [main] DEBUG org.hibernate.jdbc.AbstractBatcher - about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
2011-05-08 11:47:43,348 [main] DEBUG org.hibernate.jdbc.AbstractBatcher - about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
2011-05-08 11:47:43,348 [main] DEBUG org.hibernate.SQL -
DROP TABLE qrtz_triggers IF EXISTS
2011-05-08 11:47:43,349 [main] DEBUG org.hibernate.jdbc.AbstractBatcher - about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
2011-05-08 11:47:43,349 [main] DEBUG org.hibernate.jdbc.AbstractBatcher - about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
2011-05-08 11:47:43,349 [main] DEBUG org.hibernate.SQL -
DROP TABLE qrtz_job_listeners IF EXISTS
2011-05-08 11:47:43,349 [main] DEBUG org.hibernate.jdbc.AbstractBatcher - about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
2011-05-08 11:47:43,349 [main] DEBUG org.hibernate.jdbc.AbstractBatcher - about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
2011-05-08 11:47:43,349 [main] DEBUG org.hibernate.SQL -
DROP TABLE qrtz_job_details IF EXISTS
2011-05-08 11:47:43,350 [main] DEBUG org.hibernate.jdbc.AbstractBatcher - about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
2011-05-08 11:47:43,350 [main] DEBUG org.hibernate.jdbc.AbstractBatcher - about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
2011-05-08 11:47:43,350 [main] DEBUG org.hibernate.SQL -

CREATE TABLE qrtz_job_details
(
JOB_NAME VARCHAR(200) NOT NULL,
JOB_GROUP VARCHAR(200) NOT NULL,
DESCRIPTION VARCHAR(250) NULL,
JOB_CLASS_NAME VARCHAR(250) NOT NULL,
IS_DURABLE BOOLEAN NOT NULL,
IS_VOLATILE BOOLEAN NOT NULL,
IS_STATEFUL BOOLEAN NOT NULL,
REQUESTS_RECOVERY BOOLEAN NOT NULL,
JOB_DATA BINARY NULL,
PRIMARY KEY (JOB_NAME,JOB_GROUP)
)
2011-05-08 11:47:43,351 [main] DEBUG org.hibernate.jdbc.AbstractBatcher - about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
2011-05-08 11:47:43,351 [main] DEBUG org.hibernate.jdbc.AbstractBatcher - about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
2011-05-08 11:47:43,351 [main] DEBUG org.hibernate.SQL -

CREATE TABLE qrtz_job_listeners
(
JOB_NAME VARCHAR(200) NOT NULL,
JOB_GROUP VARCHAR(200) NOT NULL,
JOB_LISTENER VARCHAR(200) NOT NULL,
PRIMARY KEY (JOB_NAME,JOB_GROUP,JOB_LISTENER),
FOREIGN KEY (JOB_NAME,JOB_GROUP)
REFERENCES QRTZ_JOB_DETAILS(JOB_NAME,JOB_GROUP)
)
2011-05-08 11:47:43,352 [main] DEBUG org.hibernate.jdbc.AbstractBatcher - about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
2011-05-08 11:47:43,353 [main] DEBUG org.hibernate.jdbc.AbstractBatcher - about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
2011-05-08 11:47:43,353 [main] DEBUG org.hibernate.SQL -

CREATE TABLE qrtz_triggers
(
TRIGGER_NAME VARCHAR(200) NOT NULL,
TRIGGER_GROUP VARCHAR(200) NOT NULL,
JOB_NAME VARCHAR(200) NOT NULL,
JOB_GROUP VARCHAR(200) NOT NULL,
IS_VOLATILE BOOLEAN NOT NULL,
DESCRIPTION VARCHAR(250) NULL,
NEXT_FIRE_TIME NUMERIC(13) NULL,
PREV_FIRE_TIME NUMERIC(13) NULL,
PRIORITY INTEGER NULL,
TRIGGER_STATE VARCHAR(16) NOT NULL,
TRIGGER_TYPE VARCHAR(8) NOT NULL,
START_TIME NUMERIC(13) NOT NULL,
END_TIME NUMERIC(13) NULL,
CALENDAR_NAME VARCHAR(200) NULL,
MISFIRE_INSTR NUMERIC(2) NULL,
JOB_DATA BINARY NULL,
PRIMARY KEY (TRIGGER_NAME,TRIGGER_GROUP),
FOREIGN KEY (JOB_NAME,JOB_GROUP)
REFERENCES QRTZ_JOB_DETAILS(JOB_NAME,JOB_GROUP)
)
2011-05-08 11:47:43,354 [main] DEBUG org.hibernate.jdbc.AbstractBatcher - about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
2011-05-08 11:47:43,355 [main] DEBUG org.hibernate.jdbc.AbstractBatcher - about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
2011-05-08 11:47:43,355 [main] DEBUG org.hibernate.SQL -

CREATE TABLE qrtz_simple_triggers
(
TRIGGER_NAME VARCHAR(200) NOT NULL,
TRIGGER_GROUP VARCHAR(200) NOT NULL,
REPEAT_COUNT NUMERIC(7) NOT NULL,
REPEAT_INTERVAL NUMERIC(12) NOT NULL,
TIMES_TRIGGERED NUMERIC(10) NOT NULL,
PRIMARY KEY (TRIGGER_NAME,TRIGGER_GROUP),
FOREIGN KEY (TRIGGER_NAME,TRIGGER_GROUP)
REFERENCES QRTZ_TRIGGERS(TRIGGER_NAME,TRIGGER_GROUP)
)
2011-05-08 11:47:43,356 [main] DEBUG org.hibernate.jdbc.AbstractBatcher - about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
2011-05-08 11:47:43,356 [main] DEBUG org.hibernate.jdbc.AbstractBatcher - about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
2011-05-08 11:47:43,357 [main] DEBUG org.hibernate.SQL -

CREATE TABLE qrtz_cron_triggers
(
TRIGGER_NAME VARCHAR(200) NOT NULL,
TRIGGER_GROUP VARCHAR(200) NOT NULL,
CRON_EXPRESSION VARCHAR(120) NOT NULL,
TIME_ZONE_ID VARCHAR(80),
PRIMARY KEY (TRIGGER_NAME,TRIGGER_GROUP),
FOREIGN KEY (TRIGGER_NAME,TRIGGER_GROUP)
REFERENCES QRTZ_TRIGGERS(TRIGGER_NAME,TRIGGER_GROUP)
)
2011-05-08 11:47:43,357 [main] DEBUG org.hibernate.jdbc.AbstractBatcher - about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
2011-05-08 11:47:43,358 [main] DEBUG org.hibernate.jdbc.AbstractBatcher - about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
2011-05-08 11:47:43,358 [main] DEBUG org.hibernate.SQL -

CREATE TABLE qrtz_blob_triggers
(
TRIGGER_NAME VARCHAR(200) NOT NULL,
TRIGGER_GROUP VARCHAR(200) NOT NULL,
BLOB_DATA BINARY NULL,
PRIMARY KEY (TRIGGER_NAME,TRIGGER_GROUP),
FOREIGN KEY (TRIGGER_NAME,TRIGGER_GROUP)
REFERENCES QRTZ_TRIGGERS(TRIGGER_NAME,TRIGGER_GROUP)
)
2011-05-08 11:47:43,358 [main] DEBUG org.hibernate.jdbc.AbstractBatcher - about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
2011-05-08 11:47:43,359 [main] DEBUG org.hibernate.jdbc.AbstractBatcher - about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
2011-05-08 11:47:43,359 [main] DEBUG org.hibernate.SQL -

CREATE TABLE qrtz_trigger_listeners
(
TRIGGER_NAME VARCHAR(200) NOT NULL,
TRIGGER_GROUP VARCHAR(200) NOT NULL,
TRIGGER_LISTENER VARCHAR(200) NOT NULL,
PRIMARY KEY (TRIGGER_NAME,TRIGGER_GROUP,TRIGGER_LISTENER),
FOREIGN KEY (TRIGGER_NAME,TRIGGER_GROUP)
REFERENCES QRTZ_TRIGGERS(TRIGGER_NAME,TRIGGER_GROUP)
)
2011-05-08 11:47:43,359 [main] DEBUG org.hibernate.jdbc.AbstractBatcher - about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
2011-05-08 11:47:43,360 [main] DEBUG org.hibernate.jdbc.AbstractBatcher - about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
2011-05-08 11:47:43,360 [main] DEBUG org.hibernate.SQL -

CREATE TABLE qrtz_calendars
(
CALENDAR_NAME VARCHAR(200) NOT NULL,
CALENDAR BINARY NOT NULL,
PRIMARY KEY (CALENDAR_NAME)
)
2011-05-08 11:47:43,360 [main] DEBUG org.hibernate.jdbc.AbstractBatcher - about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
2011-05-08 11:47:43,360 [main] DEBUG org.hibernate.jdbc.AbstractBatcher - about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
2011-05-08 11:47:43,360 [main] DEBUG org.hibernate.SQL -

CREATE TABLE qrtz_paused_trigger_grps
(
TRIGGER_GROUP VARCHAR(200) NOT NULL,
PRIMARY KEY (TRIGGER_GROUP)
)
2011-05-08 11:47:43,361 [main] DEBUG org.hibernate.jdbc.AbstractBatcher - about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
2011-05-08 11:47:43,361 [main] DEBUG org.hibernate.jdbc.AbstractBatcher - about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
2011-05-08 11:47:43,361 [main] DEBUG org.hibernate.SQL -

CREATE TABLE qrtz_fired_triggers
(
ENTRY_ID VARCHAR(95) NOT NULL,
TRIGGER_NAME VARCHAR(200) NOT NULL,
TRIGGER_GROUP VARCHAR(200) NOT NULL,
IS_VOLATILE BOOLEAN NOT NULL,
INSTANCE_NAME VARCHAR(200) NOT NULL,
FIRED_TIME NUMERIC(13) NOT NULL,
PRIORITY INTEGER NOT NULL,
STATE VARCHAR(16) NOT NULL,
JOB_NAME VARCHAR(200) NULL,
JOB_GROUP VARCHAR(200) NULL,
IS_STATEFUL BOOLEAN NULL,
REQUESTS_RECOVERY BOOLEAN NULL,
PRIMARY KEY (ENTRY_ID)
)
2011-05-08 11:47:43,362 [main] DEBUG org.hibernate.jdbc.AbstractBatcher - about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
2011-05-08 11:47:43,362 [main] DEBUG org.hibernate.jdbc.AbstractBatcher - about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
2011-05-08 11:47:43,362 [main] DEBUG org.hibernate.SQL -

CREATE TABLE qrtz_scheduler_state
(
INSTANCE_NAME VARCHAR(200) NOT NULL,
LAST_CHECKIN_TIME NUMERIC(13) NOT NULL,
CHECKIN_INTERVAL NUMERIC(13) NOT NULL,
PRIMARY KEY (INSTANCE_NAME)
)
2011-05-08 11:47:43,363 [main] DEBUG org.hibernate.jdbc.AbstractBatcher - about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
2011-05-08 11:47:43,363 [main] DEBUG org.hibernate.jdbc.AbstractBatcher - about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
2011-05-08 11:47:43,363 [main] DEBUG org.hibernate.SQL -

CREATE TABLE qrtz_locks
(
LOCK_NAME VARCHAR(40) NOT NULL,
PRIMARY KEY (LOCK_NAME)
)
2011-05-08 11:47:43,364 [main] DEBUG org.hibernate.jdbc.AbstractBatcher - about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
2011-05-08 11:47:43,364 [main] DEBUG org.hibernate.jdbc.AbstractBatcher - about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
2011-05-08 11:47:43,364 [main] DEBUG org.hibernate.SQL -

INSERT INTO qrtz_locks values(‘TRIGGER_ACCESS’)
2011-05-08 11:47:43,365 [main] DEBUG org.hibernate.jdbc.AbstractBatcher - about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
2011-05-08 11:47:43,366 [main] DEBUG org.hibernate.jdbc.AbstractBatcher - about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
2011-05-08 11:47:43,366 [main] DEBUG org.hibernate.SQL -
INSERT INTO qrtz_locks values(‘JOB_ACCESS’)
2011-05-08 11:47:43,366 [main] DEBUG org.hibernate.jdbc.AbstractBatcher - about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
2011-05-08 11:47:43,366 [main] DEBUG org.hibernate.jdbc.AbstractBatcher - about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
2011-05-08 11:47:43,366 [main] DEBUG org.hibernate.SQL -
INSERT INTO qrtz_locks values(‘CALENDAR_ACCESS’)
2011-05-08 11:47:43,366 [main] DEBUG org.hibernate.jdbc.AbstractBatcher - about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
2011-05-08 11:47:43,367 [main] DEBUG org.hibernate.jdbc.AbstractBatcher - about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
2011-05-08 11:47:43,367 [main] DEBUG org.hibernate.SQL -
INSERT INTO qrtz_locks values(‘STATE_ACCESS’)
2011-05-08 11:47:43,367 [main] DEBUG org.hibernate.jdbc.AbstractBatcher - about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
2011-05-08 11:47:43,367 [main] DEBUG org.hibernate.jdbc.AbstractBatcher - about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
2011-05-08 11:47:43,367 [main] DEBUG org.hibernate.SQL -
INSERT INTO qrtz_locks values(‘MISFIRE_ACCESS’)
2011-05-08 11:47:43,367 [main] DEBUG org.hibernate.jdbc.AbstractBatcher - about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
2011-05-08 11:47:43,368 [main] DEBUG org.springframework.orm.jpa.JpaTransactionManager - Initiating transaction commit
2011-05-08 11:47:43,368 [main] DEBUG org.springframework.orm.jpa.JpaTransactionManager - Committing JPA transaction on EntityManager [org.hibernate.ejb.EntityManagerImpl@7c0cbf92]
2011-05-08 11:47:43,368 [main] DEBUG org.hibernate.transaction.JDBCTransaction - commit
2011-05-08 11:47:43,368 [main] DEBUG org.hibernate.transaction.JDBCTransaction - re-enabling autocommit
2011-05-08 11:47:43,368 [main] DEBUG org.hibernate.transaction.JDBCTransaction - committed JDBC Connection
2011-05-08 11:47:43,368 [main] DEBUG org.hibernate.jdbc.ConnectionManager - aggressively releasing JDBC connection
2011-05-08 11:47:43,369 [main] DEBUG org.hibernate.jdbc.ConnectionManager - releasing JDBC connection [ (open PreparedStatements: 0, globally: 0) (open ResultSets: 0, globally: 0)]
2011-05-08 11:47:43,369 [main] DEBUG org.springframework.orm.jpa.JpaTransactionManager - Closing JPA EntityManager [org.hibernate.ejb.EntityManagerImpl@7c0cbf92] after transaction
2011-05-08 11:47:43,369 [main] DEBUG org.springframework.orm.jpa.EntityManagerFactoryUtils - Closing JPA EntityManager
2011-05-08 11:47:43,369 [main] DEBUG org.springframework.beans.factory.support.DefaultListableBeanFactory - Returning cached instance of singleton bean ‘org.springframework.transaction.config.internalTransactionAdvisor’
2011-05-08 11:47:43,372 [main] DEBUG org.springframework.transaction.annotation.AnnotationTransactionAttributeSource - Adding transactional method ‘createTables’ with attribute: PROPAGATION_REQUIRED,ISOLATION_DEFAULT; ‘’
2011-05-08 11:47:43,377 [main] DEBUG org.springframework.aop.framework.autoproxy.InfrastructureAdvisorAutoProxyCreator - Creating implicit proxy for bean ‘com.testing.server.infrastructure.quartz.QuartzTableMaker#0’ with 0 common interceptors and 1 specific interceptors
2011-05-08 11:47:43,380 [main] DEBUG org.springframework.aop.framework.JdkDynamicAopProxy - Creating JDK dynamic proxy: target source is SingletonTargetSource for target object [com.testing.server.infrastructure.quartz.QuartzTableMaker@3b34c0a6]
2011-05-08 11:47:43,392 [main] DEBUG org.springframework.beans.factory.support.DefaultListableBeanFactory - Finished creating instance of bean ‘com.testing.server.infrastructure.quartz.QuartzTableMaker#0’
2011-05-08 11:47:43,402 [main] DEBUG org.springframework.beans.factory.support.DefaultListableBeanFactory - Returning cached instance of singleton bean ‘org.axonframework.saga.spring.SpringResourceInjector#0’
2011-05-08 11:47:43,402 [main] DEBUG org.springframework.beans.factory.support.DefaultListableBeanFactory - Creating shared instance of singleton bean ‘org.axonframework.eventhandling.scheduling.quartz.QuartzEventScheduler#0’
2011-05-08 11:47:43,402 [main] DEBUG org.springframework.beans.factory.support.DefaultListableBeanFactory - Creating instance of bean ‘org.axonframework.eventhandling.scheduling.quartz.QuartzEventScheduler#0’
2011-05-08 11:47:43,409 [main] DEBUG org.springframework.context.annotation.CommonAnnotationBeanPostProcessor - Found init method on class [org.axonframework.eventhandling.scheduling.quartz.QuartzEventScheduler]: public void org.axonframework.eventhandling.scheduling.quartz.QuartzEventScheduler.initialize() throws org.quartz.SchedulerException
2011-05-08 11:47:43,409 [main] DEBUG org.springframework.context.annotation.CommonAnnotationBeanPostProcessor - Found init method on class [org.axonframework.eventhandling.scheduling.quartz.QuartzEventScheduler]: org.springframework.beans.factory.annotation.InitDestroyAnnotationBeanPostProcessor$LifecycleElement@33ebcb90
2011-05-08 11:47:43,413 [main] DEBUG org.springframework.beans.factory.annotation.InjectionMetadata - Found injected element on class [org.axonframework.eventhandling.scheduling.quartz.QuartzEventScheduler]: ResourceElement for public void org.axonframework.eventhandling.scheduling.quartz.QuartzEventScheduler.setScheduler(org.quartz.Scheduler)
2011-05-08 11:47:43,413 [main] DEBUG org.springframework.beans.factory.annotation.InjectionMetadata - Found injected element on class [org.axonframework.eventhandling.scheduling.quartz.QuartzEventScheduler]: ResourceElement for public void org.axonframework.eventhandling.scheduling.quartz.QuartzEventScheduler.setEventBus(org.axonframework.eventhandling.EventBus)
2011-05-08 11:47:43,415 [main] DEBUG org.springframework.beans.factory.support.DefaultListableBeanFactory - Eagerly caching bean ‘org.axonframework.eventhandling.scheduling.quartz.QuartzEventScheduler#0’ to allow for resolving potential circular references
2011-05-08 11:47:43,415 [main] DEBUG org.springframework.beans.factory.annotation.InjectionMetadata - Processing injected method of bean ‘org.axonframework.eventhandling.scheduling.quartz.QuartzEventScheduler#0’: ResourceElement for public void org.axonframework.eventhandling.scheduling.quartz.QuartzEventScheduler.setScheduler(org.quartz.Scheduler)
2011-05-08 11:47:43,415 [main] DEBUG org.springframework.beans.factory.annotation.InjectionMetadata - Processing injected method of bean ‘org.axonframework.eventhandling.scheduling.quartz.QuartzEventScheduler#0’: ResourceElement for public void org.axonframework.eventhandling.scheduling.quartz.QuartzEventScheduler.setEventBus(org.axonframework.eventhandling.EventBus)
2011-05-08 11:47:43,416 [main] DEBUG org.springframework.beans.factory.support.DefaultListableBeanFactory - Creating shared instance of singleton bean ‘scheduler’
2011-05-08 11:47:43,416 [main] DEBUG org.springframework.beans.factory.support.DefaultListableBeanFactory - Creating instance of bean ‘scheduler’
2011-05-08 11:47:43,420 [main] DEBUG org.springframework.beans.factory.support.DefaultListableBeanFactory - Eagerly caching bean ‘scheduler’ to allow for resolving potential circular references
2011-05-08 11:47:43,431 [main] DEBUG org.springframework.beans.factory.support.DefaultListableBeanFactory - Returning cached instance of singleton bean ‘dataSource’
2011-05-08 11:47:43,431 [main] DEBUG org.springframework.beans.factory.support.DefaultListableBeanFactory - Returning cached instance of singleton bean ‘transactionManager’
2011-05-08 11:47:43,431 [main] DEBUG org.springframework.beans.factory.support.DefaultListableBeanFactory - Invoking afterPropertiesSet() on bean with name ‘scheduler’
2011-05-08 11:47:43,445 [main] INFO org.springframework.scheduling.quartz.SchedulerFactoryBean - Loading Quartz config from [class path resource [META-INF/spring/quartz.test.properties]]
2011-05-08 11:47:43,487 [main] INFO org.quartz.simpl.SimpleThreadPool - Job execution threads will use class loader of thread: main
2011-05-08 11:47:43,506 [main] INFO org.quartz.core.SchedulerSignalerImpl - Initialized Scheduler Signaller of type: class org.quartz.core.SchedulerSignalerImpl
2011-05-08 11:47:43,508 [main] INFO org.quartz.core.QuartzScheduler - Quartz Scheduler v.1.8.4 created.
2011-05-08 11:47:43,517 [main] DEBUG org.springframework.jdbc.datasource.DataSourceUtils - Fetching JDBC Connection from DataSource
2011-05-08 11:47:43,517 [main] DEBUG org.springframework.jdbc.datasource.DriverManagerDataSource - Creating new JDBC DriverManager Connection to [jdbc:hsqldb:mem:addressbook]
2011-05-08 11:47:43,518 [main] DEBUG org.springframework.jdbc.datasource.DataSourceUtils - Returning JDBC Connection to DataSource
2011-05-08 11:47:43,520 [main] INFO org.springframework.scheduling.quartz.LocalDataSourceJobStore - JobStoreCMT initialized.
2011-05-08 11:47:43,522 [main] INFO org.quartz.core.QuartzScheduler - Scheduler meta-data: Quartz Scheduler (v1.8.4) ‘scheduler’ with instanceId ‘1’
Scheduler class: ‘org.quartz.core.QuartzScheduler’ - running locally.
NOT STARTED.
Currently in standby mode.
Number of jobs executed: 0
Using thread pool ‘org.quartz.simpl.SimpleThreadPool’ - with 10 threads.
Using job-store ‘org.springframework.scheduling.quartz.LocalDataSourceJobStore’ - which supports persistence. and is clustered.

2011-05-08 11:47:43,522 [main] INFO org.quartz.impl.StdSchedulerFactory - Quartz scheduler ‘scheduler’ initialized from an externally provided properties instance.
2011-05-08 11:47:43,522 [main] INFO org.quartz.impl.StdSchedulerFactory - Quartz scheduler version: 1.8.4
2011-05-08 11:47:43,525 [main] INFO org.quartz.core.QuartzScheduler - JobFactory set to: org.springframework.scheduling.quartz.AdaptableJobFactory@5a0eddac
2011-05-08 11:47:43,526 [main] DEBUG org.springframework.orm.jpa.JpaTransactionManager - Creating new transaction with name [null]: PROPAGATION_REQUIRED,ISOLATION_DEFAULT
2011-05-08 11:47:43,526 [main] DEBUG org.springframework.orm.jpa.JpaTransactionManager - Opened new EntityManager [org.hibernate.ejb.EntityManagerImpl@5fb7565] for JPA transaction
2011-05-08 11:47:43,526 [main] DEBUG org.hibernate.impl.SessionImpl - opened session at timestamp: 13048696635
2011-05-08 11:47:43,526 [main] DEBUG org.hibernate.transaction.JDBCTransaction - begin
2011-05-08 11:47:43,526 [main] DEBUG org.hibernate.jdbc.ConnectionManager - opening JDBC connection
2011-05-08 11:47:43,526 [main] DEBUG org.springframework.jdbc.datasource.DriverManagerDataSource - Creating new JDBC DriverManager Connection to [jdbc:hsqldb:mem:addressbook]
2011-05-08 11:47:43,526 [main] DEBUG org.hibernate.transaction.JDBCTransaction - current autocommit status: true
2011-05-08 11:47:43,526 [main] DEBUG org.hibernate.transaction.JDBCTransaction - disabling autocommit
2011-05-08 11:47:43,526 [main] DEBUG org.springframework.orm.jpa.JpaTransactionManager - Exposing JPA transaction as JDBC transaction [org.springframework.orm.jpa.vendor.HibernateJpaDialect$HibernateConnectionHandle@3fd83cf4]
2011-05-08 11:47:43,527 [main] DEBUG org.springframework.orm.jpa.JpaTransactionManager - Initiating transaction commit
2011-05-08 11:47:43,527 [main] DEBUG org.springframework.orm.jpa.JpaTransactionManager - Committing JPA transaction on EntityManager [org.hibernate.ejb.EntityManagerImpl@5fb7565]
2011-05-08 11:47:43,527 [main] DEBUG org.hibernate.transaction.JDBCTransaction - commit
2011-05-08 11:47:43,527 [main] DEBUG org.hibernate.transaction.JDBCTransaction - re-enabling autocommit
2011-05-08 11:47:43,527 [main] DEBUG org.hibernate.transaction.JDBCTransaction - committed JDBC Connection
2011-05-08 11:47:43,527 [main] DEBUG org.hibernate.jdbc.ConnectionManager - aggressively releasing JDBC connection
2011-05-08 11:47:43,527 [main] DEBUG org.hibernate.jdbc.ConnectionManager - releasing JDBC connection [ (open PreparedStatements: 0, globally: 0) (open ResultSets: 0, globally: 0)]
2011-05-08 11:47:43,527 [main] DEBUG org.springframework.orm.jpa.JpaTransactionManager - Closing JPA EntityManager [org.hibernate.ejb.EntityManagerImpl@5fb7565] after transaction
2011-05-08 11:47:43,527 [main] DEBUG org.springframework.orm.jpa.EntityManagerFactoryUtils - Closing JPA EntityManager
2011-05-08 11:47:43,528 [main] DEBUG org.springframework.beans.factory.support.DefaultListableBeanFactory - Returning cached instance of singleton bean ‘org.springframework.transaction.config.internalTransactionAdvisor’
2011-05-08 11:47:43,530 [main] DEBUG org.springframework.beans.factory.support.DefaultListableBeanFactory - Finished creating instance of bean ‘scheduler’
2011-05-08 11:47:43,530 [main] DEBUG org.springframework.beans.factory.support.DefaultListableBeanFactory - Returning cached instance of singleton bean ‘org.springframework.transaction.config.internalTransactionAdvisor’
2011-05-08 11:47:43,535 [main] DEBUG org.springframework.beans.factory.support.DefaultListableBeanFactory - Returning cached instance of singleton bean ‘eventBus’
2011-05-08 11:47:43,536 [main] DEBUG org.springframework.context.annotation.CommonAnnotationBeanPostProcessor - Invoking init method on bean ‘org.axonframework.eventhandling.scheduling.quartz.QuartzEventScheduler#0’: public void org.axonframework.eventhandling.scheduling.quartz.QuartzEventScheduler.initialize() throws org.quartz.SchedulerException
2011-05-08 11:47:43,538 [main] DEBUG org.springframework.beans.factory.support.DefaultListableBeanFactory - Returning cached instance of singleton bean ‘org.springframework.transaction.config.internalTransactionAdvisor’
2011-05-08 11:47:43,539 [main] DEBUG org.springframework.beans.factory.support.DefaultListableBeanFactory - Finished creating instance of bean ‘org.axonframework.eventhandling.scheduling.quartz.QuartzEventScheduler#0’
2011-05-08 11:47:43,539 [main] DEBUG org.springframework.beans.factory.support.DefaultListableBeanFactory - Returning cached instance of singleton bean ‘scheduler’
2011-05-08 11:47:43,542 [main] DEBUG org.springframework.context.support.GenericApplicationContext - Unable to locate LifecycleProcessor with name ‘lifecycleProcessor’: using default [org.springframework.context.support.DefaultLifecycleProcessor@56091d7c]
2011-05-08 11:47:43,543 [main] DEBUG org.springframework.beans.factory.support.DefaultListableBeanFactory - Returning cached instance of singleton bean ‘scheduler’
2011-05-08 11:47:43,543 [main] DEBUG org.springframework.beans.factory.support.DefaultListableBeanFactory - Returning cached instance of singleton bean ‘lifecycleProcessor’
2011-05-08 11:47:43,545 [main] DEBUG org.springframework.beans.factory.support.DefaultListableBeanFactory - Returning cached instance of singleton bean ‘scheduler’
2011-05-08 11:47:43,545 [main] DEBUG org.springframework.beans.factory.support.DefaultListableBeanFactory - Returning cached instance of singleton bean ‘lifecycleProcessor’
2011-05-08 11:47:43,546 [main] INFO org.springframework.context.support.DefaultLifecycleProcessor - Starting beans in phase 2147483647
2011-05-08 11:47:43,546 [main] DEBUG org.springframework.context.support.DefaultLifecycleProcessor - Starting bean ‘scheduler’ of type [class org.springframework.scheduling.quartz.SchedulerFactoryBean]
2011-05-08 11:47:43,546 [main] INFO org.springframework.scheduling.quartz.SchedulerFactoryBean - Starting Quartz Scheduler now
2011-05-08 11:47:43,548 [main] DEBUG org.springframework.jdbc.datasource.DriverManagerDataSource - Creating new JDBC DriverManager Connection to [jdbc:hsqldb:mem:addressbook]
2011-05-08 11:47:43,558 [main] DEBUG org.quartz.impl.jdbcjobstore.SimpleSemaphore - Lock ‘STATE_ACCESS’ is desired by: main
2011-05-08 11:47:43,558 [main] DEBUG org.quartz.impl.jdbcjobstore.SimpleSemaphore - Lock ‘STATE_ACCESS’ is being obtained: main
2011-05-08 11:47:43,559 [main] DEBUG org.quartz.impl.jdbcjobstore.SimpleSemaphore - Lock ‘STATE_ACCESS’ given to: main
2011-05-08 11:47:43,567 [main] DEBUG org.quartz.impl.jdbcjobstore.SimpleSemaphore - Lock ‘STATE_ACCESS’ retuned by: main
2011-05-08 11:47:43,567 [main] DEBUG org.springframework.jdbc.datasource.DataSourceUtils - Returning JDBC Connection to DataSource
2011-05-08 11:47:43,567 [main] DEBUG org.springframework.scheduling.quartz.LocalDataSourceJobStore - ClusterManager: Check-in complete.
2011-05-08 11:47:43,576 [main] INFO org.quartz.core.QuartzScheduler - Scheduler scheduler_$1 started.
2011-05-08 11:47:43,576 [main] DEBUG org.springframework.context.support.DefaultLifecycleProcessor - Successfully started bean ‘scheduler’
2011-05-08 11:47:43,576 [QuartzScheduler_scheduler-1_MisfireHandler] DEBUG org.springframework.scheduling.quartz.LocalDataSourceJobStore - MisfireHandler: scanning for misfires…
2011-05-08 11:47:43,577 [QuartzScheduler_scheduler-1_MisfireHandler] DEBUG org.springframework.jdbc.datasource.DriverManagerDataSource - Creating new JDBC DriverManager Connection to [jdbc:hsqldb:mem:addressbook]
2011-05-08 11:47:43,579 [scheduler_QuartzSchedulerThread] DEBUG org.springframework.jdbc.datasource.DriverManagerDataSource - Creating new JDBC DriverManager Connection to [jdbc:hsqldb:mem:addressbook]
2011-05-08 11:47:43,582 [main] DEBUG org.springframework.beans.factory.annotation.InjectionMetadata - Found injected element on class [test.QuartzSagaTimerIntegrationTest]: AutowiredFieldElement for private org.axonframework.eventhandling.EventBus test.QuartzSagaTimerIntegrationTest.eventBus
2011-05-08 11:47:43,582 [main] DEBUG org.springframework.beans.factory.annotation.InjectionMetadata - Found injected element on class [test.QuartzSagaTimerIntegrationTest]: AutowiredFieldElement for private org.axonframework.saga.SagaRepository test.QuartzSagaTimerIntegrationTest.repository
2011-05-08 11:47:43,582 [main] DEBUG org.springframework.beans.factory.annotation.InjectionMetadata - Found injected element on class [test.QuartzSagaTimerIntegrationTest]: AutowiredFieldElement for private org.springframework.transaction.PlatformTransactionManager test.QuartzSagaTimerIntegrationTest.transactionManager
2011-05-08 11:47:43,582 [main] DEBUG org.springframework.beans.factory.annotation.InjectionMetadata - Processing injected method of bean ‘test.QuartzSagaTimerIntegrationTest’: AutowiredFieldElement for private org.axonframework.eventhandling.EventBus test.QuartzSagaTimerIntegrationTest.eventBus
2011-05-08 11:47:43,583 [main] DEBUG org.springframework.beans.factory.support.DefaultListableBeanFactory - Returning cached instance of singleton bean ‘eventBus’
2011-05-08 11:47:43,583 [main] DEBUG org.springframework.beans.factory.annotation.AutowiredAnnotationBeanPostProcessor - Autowiring by type from bean name ‘test.QuartzSagaTimerIntegrationTest’ to bean named ‘eventBus’
2011-05-08 11:47:43,583 [main] DEBUG org.springframework.beans.factory.annotation.InjectionMetadata - Processing injected method of bean ‘test.QuartzSagaTimerIntegrationTest’: AutowiredFieldElement for private org.axonframework.saga.SagaRepository test.QuartzSagaTimerIntegrationTest.repository
2011-05-08 11:47:43,583 [QuartzScheduler_scheduler-1_MisfireHandler] DEBUG org.springframework.scheduling.quartz.LocalDataSourceJobStore - Found 0 triggers that missed their scheduled fire-time.
2011-05-08 11:47:43,583 [QuartzScheduler_scheduler-1_MisfireHandler] DEBUG org.springframework.jdbc.datasource.DataSourceUtils - Returning JDBC Connection to DataSource
2011-05-08 11:47:43,584 [main] DEBUG org.springframework.beans.factory.support.DefaultListableBeanFactory - Returning cached instance of singleton bean ‘sagaRepository’
2011-05-08 11:47:43,584 [scheduler_QuartzSchedulerThread] DEBUG org.springframework.jdbc.datasource.DataSourceUtils - Returning JDBC Connection to DataSource
2011-05-08 11:47:43,584 [main] DEBUG org.springframework.beans.factory.annotation.AutowiredAnnotationBeanPostProcessor - Autowiring by type from bean name ‘test.QuartzSagaTimerIntegrationTest’ to bean named ‘sagaRepository’
2011-05-08 11:47:43,584 [main] DEBUG org.springframework.beans.factory.annotation.InjectionMetadata - Processing injected method of bean ‘test.QuartzSagaTimerIntegrationTest’: AutowiredFieldElement for private org.springframework.transaction.PlatformTransactionManager test.QuartzSagaTimerIntegrationTest.transactionManager
2011-05-08 11:47:43,584 [main] DEBUG org.springframework.beans.factory.support.DefaultListableBeanFactory - Returning cached instance of singleton bean ‘transactionManager’
2011-05-08 11:47:43,584 [main] DEBUG org.springframework.beans.factory.annotation.AutowiredAnnotationBeanPostProcessor - Autowiring by type from bean name ‘test.QuartzSagaTimerIntegrationTest’ to bean named ‘transactionManager’
2011-05-08 11:47:43,585 [main] DEBUG org.springframework.beans.factory.support.DefaultListableBeanFactory - Returning cached instance of singleton bean ‘org.springframework.transaction.config.internalTransactionAdvisor’
2011-05-08 11:47:43,679 [QuartzScheduler_scheduler-1_MisfireHandler] DEBUG org.springframework.scheduling.quartz.LocalDataSourceJobStore - MisfireHandler: scanning for misfires…
2011-05-08 11:47:43,679 [QuartzScheduler_scheduler-1_MisfireHandler] DEBUG org.springframework.jdbc.datasource.DriverManagerDataSource - Creating new JDBC DriverManager Connection to [jdbc:hsqldb:mem:addressbook]
2011-05-08 11:47:43,680 [QuartzScheduler_scheduler-1_MisfireHandler] DEBUG org.springframework.scheduling.quartz.LocalDataSourceJobStore - Found 0 triggers that missed their scheduled fire-time.
2011-05-08 11:47:43,680 [QuartzScheduler_scheduler-1_MisfireHandler] DEBUG org.springframework.jdbc.datasource.DataSourceUtils - Returning JDBC Connection to DataSource
2011-05-08 11:47:43,779 [QuartzScheduler_scheduler-1_MisfireHandler] DEBUG org.springframework.scheduling.quartz.LocalDataSourceJobStore - MisfireHandler: scanning for misfires…
2011-05-08 11:47:43,780 [QuartzScheduler_scheduler-1_MisfireHandler] DEBUG org.springframework.jdbc.datasource.DriverManagerDataSource - Creating new JDBC DriverManager Connection to [jdbc:hsqldb:mem:addressbook]
2011-05-08 11:47:43,780 [QuartzScheduler_scheduler-1_MisfireHandler] DEBUG org.springframework.scheduling.quartz.LocalDataSourceJobStore - Found 0 triggers that missed their scheduled fire-time.
2011-05-08 11:47:43,781 [QuartzScheduler_scheduler-1_MisfireHandler] DEBUG org.springframework.jdbc.datasource.DataSourceUtils - Returning JDBC Connection to DataSource
2011-05-08 11:47:43,818 [main] DEBUG org.axonframework.eventhandling.SimpleEventBus - EventListener [EventListener$$EnhancerByMockitoWithCGLIB$$2862b5a2] subscribed successfully
2011-05-08 11:47:43,819 [main] DEBUG org.springframework.orm.jpa.JpaTransactionManager - Creating new transaction with name [null]: PROPAGATION_REQUIRED,ISOLATION_DEFAULT
2011-05-08 11:47:43,819 [main] DEBUG org.springframework.orm.jpa.JpaTransactionManager - Opened new EntityManager [org.hibernate.ejb.EntityManagerImpl@3aeebf17] for JPA transaction
2011-05-08 11:47:43,819 [main] DEBUG org.hibernate.impl.SessionImpl - opened session at timestamp: 13048696638
2011-05-08 11:47:43,819 [main] DEBUG org.hibernate.transaction.JDBCTransaction - begin
2011-05-08 11:47:43,819 [main] DEBUG org.hibernate.jdbc.ConnectionManager - opening JDBC connection
2011-05-08 11:47:43,819 [main] DEBUG org.springframework.jdbc.datasource.DriverManagerDataSource - Creating new JDBC DriverManager Connection to [jdbc:hsqldb:mem:addressbook]
2011-05-08 11:47:43,820 [main] DEBUG org.hibernate.transaction.JDBCTransaction - current autocommit status: true
2011-05-08 11:47:43,820 [main] DEBUG org.hibernate.transaction.JDBCTransaction - disabling autocommit
2011-05-08 11:47:43,820 [main] DEBUG org.springframework.orm.jpa.JpaTransactionManager - Exposing JPA transaction as JDBC transaction [org.springframework.orm.jpa.vendor.HibernateJpaDialect$HibernateConnectionHandle@10439d3b]
2011-05-08 11:47:43,879 [QuartzScheduler_scheduler-1_MisfireHandler] DEBUG org.springframework.scheduling.quartz.LocalDataSourceJobStore - MisfireHandler: scanning for misfires…
2011-05-08 11:47:43,879 [QuartzScheduler_scheduler-1_MisfireHandler] DEBUG org.springframework.jdbc.datasource.DriverManagerDataSource - Creating new JDBC DriverManager Connection to [jdbc:hsqldb:mem:addressbook]
2011-05-08 11:47:43,880 [QuartzScheduler_scheduler-1_MisfireHandler] DEBUG org.springframework.scheduling.quartz.LocalDataSourceJobStore - Found 0 triggers that missed their scheduled fire-time.
2011-05-08 11:47:43,880 [QuartzScheduler_scheduler-1_MisfireHandler] DEBUG org.springframework.jdbc.datasource.DataSourceUtils - Returning JDBC Connection to DataSource
2011-05-08 11:47:43,923 [main] DEBUG org.axonframework.eventhandling.SimpleEventBus - Dispatching Event [StartingEvent] to EventListener [AnnotatedSagaManager]
2011-05-08 11:47:43,936 [main] DEBUG org.springframework.beans.factory.annotation.InjectionMetadata - Found injected element on class [test.SimpleTimingSaga]: AutowiredMethodElement for public void test.SimpleTimingSaga.setTimer(org.axonframework.eventhandling.scheduling.EventScheduler)
2011-05-08 11:47:43,937 [main] DEBUG org.springframework.beans.factory.annotation.InjectionMetadata - Processing injected method of bean ‘test.SimpleTimingSaga’: AutowiredMethodElement for public void test.SimpleTimingSaga.setTimer(org.axonframework.eventhandling.scheduling.EventScheduler)
2011-05-08 11:47:43,937 [main] DEBUG org.springframework.beans.factory.support.DefaultListableBeanFactory - Returning cached instance of singleton bean ‘org.axonframework.eventhandling.scheduling.quartz.QuartzEventScheduler#0’
2011-05-08 11:47:43,937 [main] DEBUG org.springframework.beans.factory.annotation.AutowiredAnnotationBeanPostProcessor - Autowiring by type from bean name ‘test.SimpleTimingSaga’ to bean named ‘org.axonframework.eventhandling.scheduling.quartz.QuartzEventScheduler#0’
2011-05-08 11:47:43,955 [main] DEBUG org.hibernate.event.def.AbstractSaveEventListener - executing identity-insert immediately
2011-05-08 11:47:43,956 [main] DEBUG org.hibernate.jdbc.AbstractBatcher - about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
2011-05-08 11:47:43,956 [main] DEBUG org.hibernate.SQL - insert into AssociationValueEntry (id, associationKey, associationValue, sagaId) values (null, ?, ?, ?)
2011-05-08 11:47:43,957 [main] DEBUG org.hibernate.jdbc.AbstractBatcher - about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
2011-05-08 11:47:43,958 [main] DEBUG org.hibernate.jdbc.AbstractBatcher - about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
2011-05-08 11:47:43,958 [main] DEBUG org.hibernate.SQL - call identity()
2011-05-08 11:47:43,958 [main] DEBUG org.hibernate.id.IdentifierGeneratorFactory - Natively generated identity: 1
2011-05-08 11:47:43,958 [main] DEBUG org.hibernate.jdbc.AbstractBatcher - about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
2011-05-08 11:47:43,964 [main] DEBUG org.hibernate.event.def.AbstractFlushingEventListener - processing flush-time cascades
2011-05-08 11:47:43,965 [main] DEBUG org.hibernate.event.def.AbstractFlushingEventListener - dirty checking collections
2011-05-08 11:47:43,967 [main] DEBUG org.hibernate.event.def.AbstractFlushingEventListener - Flushed: 0 insertions, 0 updates, 0 deletions to 1 objects
2011-05-08 11:47:43,967 [main] DEBUG org.hibernate.event.def.AbstractFlushingEventListener - Flushed: 0 (re)creations, 0 updates, 0 removals to 0 collections
2011-05-08 11:47:43,968 [main] DEBUG org.hibernate.pretty.Printer - listing entities:
2011-05-08 11:47:43,968 [main] DEBUG org.hibernate.pretty.Printer - org.axonframework.saga.repository.jpa.AssociationValueEntry{id=1, sagaId=63bbec89-cb33-43b6-ab68-783cf41e6970, associationValue=2c6d8085f480a4b0e3e4b1b6b6e2e4adb0b3e2e3adb4b4e5e6ade1e2b7e4adb6b0b3b0b1b4b8b3e3b6b9b4, associationKey=association}
2011-05-08 11:47:43,969 [main] DEBUG org.hibernate.event.def.AbstractSaveEventListener - executing identity-insert immediately
2011-05-08 11:47:43,969 [main] DEBUG org.hibernate.jdbc.AbstractBatcher - about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
2011-05-08 11:47:43,969 [main] DEBUG org.hibernate.SQL - insert into AssociationValueEntry (id, associationKey, associationValue, sagaId) values (null, ?, ?, ?)
2011-05-08 11:47:43,970 [main] DEBUG org.hibernate.jdbc.AbstractBatcher - about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
2011-05-08 11:47:43,970 [main] DEBUG org.hibernate.jdbc.AbstractBatcher - about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
2011-05-08 11:47:43,970 [main] DEBUG org.hibernate.SQL - call identity()
2011-05-08 11:47:43,970 [main] DEBUG org.hibernate.id.IdentifierGeneratorFactory - Natively generated identity: 2
2011-05-08 11:47:43,970 [main] DEBUG org.hibernate.jdbc.AbstractBatcher - about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
2011-05-08 11:47:43,970 [main] DEBUG org.hibernate.event.def.AbstractFlushingEventListener - processing flush-time cascades
2011-05-08 11:47:43,970 [main] DEBUG org.hibernate.event.def.AbstractFlushingEventListener - dirty checking collections
2011-05-08 11:47:43,971 [main] DEBUG org.hibernate.event.def.AbstractFlushingEventListener - Flushed: 0 insertions, 0 updates, 0 deletions to 2 objects
2011-05-08 11:47:43,971 [main] DEBUG org.hibernate.event.def.AbstractFlushingEventListener - Flushed: 0 (re)creations, 0 updates, 0 removals to 0 collections
2011-05-08 11:47:43,971 [main] DEBUG org.hibernate.pretty.Printer - listing entities:
2011-05-08 11:47:43,971 [main] DEBUG org.hibernate.pretty.Printer - org.axonframework.saga.repository.jpa.AssociationValueEntry{id=2, sagaId=63bbec89-cb33-43b6-ab68-783cf41e6970, associationValue=2c6d8085f480a4b6b3e2e2e5e3b8b9ade3e2b3b3adb4b3e2b6ade1e2b6b8adb7b8b3e3e6b4b1e5b6b9b7b0, associationKey=sagaIdentifier}
2011-05-08 11:47:43,971 [main] DEBUG org.hibernate.pretty.Printer - org.axonframework.saga.repository.jpa.AssociationValueEntry{id=1, sagaId=63bbec89-cb33-43b6-ab68-783cf41e6970, associationValue=2c6d8085f480a4b0e3e4b1b6b6e2e4adb0b3e2e3adb4b4e5e6ade1e2b7e4adb6b0b3b0b1b4b8b3e3b6b9b4, associationKey=association}
2011-05-08 11:47:43,976 [main] DEBUG org.hibernate.event.def.AbstractSaveEventListener - generated identifier: 63bbec89-cb33-43b6-ab68-783cf41e6970, using strategy: org.hibernate.id.Assigned
2011-05-08 11:47:43,977 [main] DEBUG org.hibernate.event.def.AbstractFlushingEventListener - processing flush-time cascades
2011-05-08 11:47:43,977 [main] DEBUG org.hibernate.event.def.AbstractFlushingEventListener - dirty checking collections
2011-05-08 11:47:43,978 [main] DEBUG org.hibernate.event.def.AbstractFlushingEventListener - Flushed: 1 insertions, 0 updates, 0 deletions to 3 objects
2011-05-08 11:47:43,978 [main] DEBUG org.hibernate.event.def.AbstractFlushingEventListener - Flushed: 0 (re)creations, 0 updates, 0 removals to 0 collections
2011-05-08 11:47:43,978 [main] DEBUG org.hibernate.pretty.Printer - listing entities:
2011-05-08 11:47:43,978 [main] DEBUG org.hibernate.pretty.Printer - org.axonframework.saga.repository.jpa.AssociationValueEntry{id=2, sagaId=63bbec89-cb33-43b6-ab68-783cf41e6970, associationValue=2c6d8085f480a4b6b3e2e2e5e3b8b9ade3e2b3b3adb4b3e2b6ade1e2b6b8adb7b8b3e3e6b4b1e5b6b9b7b0, associationKey=sagaIdentifier}
2011-05-08 11:47:43,978 [main] DEBUG org.hibernate.pretty.Printer - org.axonframework.saga.repository.jpa.SagaEntry{sagaId=63bbec89-cb33-43b6-ab68-783cf41e6970, serializedSaga=2c6d8085f3f28095f4e5f3f4aed3e9edf0ece5d4e9ede9eee7d3e1e7e15338a56a8cbab477838081da8089f4f2e9e7e7e5f2e5e4f8f280b7eff2e7aee1f8efeee6f2e1ede5f7eff2ebaef3e1e7e1aee1eeeeeff4e1f4e9efeeaec1e2f3f4f2e1e3f4c1eeeeeff4e1f4e5e4d3e1e7e1a199ce58bc069602838083da8088e9f3c1e3f4e9f6e5cc8091e1f3f3efe3e9e1f4e9efeed6e1ecf5e5f3f480aacceff2e7afe1f8efeee6f2e1ede5f7eff2ebaff3e1e7e1afc1f3f3efe3e9e1f4e9efeed6e1ecf5e5f3bbcc808ae9e4e5eef4e9e6e9e5f2f48092cceae1f6e1afece1eee7afd3f4f2e9eee7bbf8f081f3f280b7eff2e7aee1f8efeee6f2e1ede5f7eff2ebaef3e1e7e1aee1eeeeeff4e1f4e9efeeaec1f3f3efe3e9e1f4e9efeed6e1ecf5e5f3c9edf0ecf252a65574607a42838081cc8086f6e1ecf5e5f3f4808fcceae1f6e1aff5f4e9ecafd3e5f4bbf8f0f3f28091eae1f6e1aef5f4e9ecaec8e1f3e8d3e5f43ac40515163837b4838080f8f0f78c80808090bfc0808080808082f3f280a7eff2e7aee1f8efeee6f2e1ede5f7eff2ebaef3e1e7e1aec1f3f3efe3e9e1f4e9efeed6e1ecf5e5b118ccbc87c08c3d828082cc808bf0f2eff0e5f2f4f9cbe5f9f180fe8083cc808df0f2eff0e5f2f4f9d6e1ecf5e5f48092cceae1f6e1afece1eee7afcfe2eae5e3f4bbf8f0f4808be1f3f3efe3e9e1f4e9efeef480a4b0e3e4b1b6b6e2e4adb0b3e2e3adb4b4e5e6ade1e2b7e4adb6b0b3b0b1b4b8b3e3b6b9b4f3f180fe808af4808ef3e1e7e1c9e4e5eef4e9e6e9e5f2f480a4b6b3e2e2e5e3b8b9ade3e2b3b3adb4b3e2b6ade1e2b6b8adb7b8b3e3e6b4b1e5b6b9b7b0f8f8f180fe8091f880f8}
2011-05-08 11:47:43,979 [main] DEBUG org.hibernate.pretty.Printer - org.axonframework.saga.repository.jpa.AssociationValueEntry{id=1, sagaId=63bbec89-cb33-43b6-ab68-783cf41e6970, associationValue=2c6d8085f480a4b0e3e4b1b6b6e2e4adb0b3e2e3adb4b4e5e6ade1e2b7e4adb6b0b3b0b1b4b8b3e3b6b9b4, associationKey=association}
2011-05-08 11:47:43,979 [QuartzScheduler_scheduler-1_MisfireHandler] DEBUG org.springframework.scheduling.quartz.LocalDataSourceJobStore - MisfireHandler: scanning for misfires…
2011-05-08 11:47:43,979 [QuartzScheduler_scheduler-1_MisfireHandler] DEBUG org.springframework.jdbc.datasource.DriverManagerDataSource - Creating new JDBC DriverManager Connection to [jdbc:hsqldb:mem:addressbook]
2011-05-08 11:47:43,980 [QuartzScheduler_scheduler-1_MisfireHandler] DEBUG org.springframework.scheduling.quartz.LocalDataSourceJobStore - Found 0 triggers that missed their scheduled fire-time.
2011-05-08 11:47:43,980 [QuartzScheduler_scheduler-1_MisfireHandler] DEBUG org.springframework.jdbc.datasource.DataSourceUtils - Returning JDBC Connection to DataSource
2011-05-08 11:47:43,982 [main] DEBUG org.hibernate.jdbc.AbstractBatcher - about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
2011-05-08 11:47:43,982 [main] DEBUG org.hibernate.SQL - insert into SagaEntry (serializedSaga, sagaId) values (?, ?)
2011-05-08 11:47:43,983 [main] DEBUG org.hibernate.jdbc.AbstractBatcher - Executing batch size: 1
2011-05-08 11:47:43,983 [main] DEBUG org.hibernate.jdbc.AbstractBatcher - about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
2011-05-08 11:47:43,984 [main] INFO test.SimpleTimingSaga - entering handle(StartingEvent event) and getting ready to schedule MySagaExpiredEvent
2011-05-08 11:47:43,988 [main] DEBUG org.quartz.impl.jdbcjobstore.SimpleSemaphore - Lock ‘TRIGGER_ACCESS’ is desired by: main
2011-05-08 11:47:43,989 [main] DEBUG org.quartz.impl.jdbcjobstore.SimpleSemaphore - Lock ‘TRIGGER_ACCESS’ is being obtained: main
2011-05-08 11:47:43,989 [main] DEBUG org.quartz.impl.jdbcjobstore.SimpleSemaphore - Lock ‘TRIGGER_ACCESS’ given to: main
2011-05-08 11:47:44,037 [main] DEBUG org.quartz.impl.jdbcjobstore.SimpleSemaphore - Lock ‘TRIGGER_ACCESS’ retuned by: main
2011-05-08 11:47:44,038 [scheduler_QuartzSchedulerThread] DEBUG org.springframework.jdbc.datasource.DriverManagerDataSource - Creating new JDBC DriverManager Connection to [jdbc:hsqldb:mem:addressbook]
2011-05-08 11:47:44,041 [main] DEBUG org.hibernate.event.def.AbstractFlushingEventListener - processing flush-time cascades
2011-05-08 11:47:44,042 [main] DEBUG org.hibernate.event.def.AbstractFlushingEventListener - dirty checking collections
2011-05-08 11:47:44,042 [main] DEBUG org.hibernate.event.def.AbstractFlushingEventListener - Flushed: 0 insertions, 0 updates, 0 deletions to 3 objects
2011-05-08 11:47:44,042 [main] DEBUG org.hibernate.event.def.AbstractFlushingEventListener - Flushed: 0 (re)creations, 0 updates, 0 removals to 0 collections
2011-05-08 11:47:44,042 [main] DEBUG org.hibernate.pretty.Printer - listing entities:
2011-05-08 11:47:44,042 [main] DEBUG org.hibernate.pretty.Printer - org.axonframework.saga.repository.jpa.AssociationValueEntry{id=2, sagaId=63bbec89-cb33-43b6-ab68-783cf41e6970, associationValue=2c6d8085f480a4b6b3e2e2e5e3b8b9ade3e2b3b3adb4b3e2b6ade1e2b6b8adb7b8b3e3e6b4b1e5b6b9b7b0, associationKey=sagaIdentifier}
2011-05-08 11:47:44,043 [main] DEBUG org.hibernate.pretty.Printer - org.axonframework.saga.repository.jpa.SagaEntry{sagaId=63bbec89-cb33-43b6-ab68-783cf41e6970, serializedSaga=2c6d8085f3f28095f4e5f3f4aed3e9edf0ece5d4e9ede9eee7d3e1e7e15338a56a8cbab477838081da8089f4f2e9e7e7e5f2e5e4f8f280b7eff2e7aee1f8efeee6f2e1ede5f7eff2ebaef3e1e7e1aee1eeeeeff4e1f4e9efeeaec1e2f3f4f2e1e3f4c1eeeeeff4e1f4e5e4d3e1e7e1a199ce58bc069602838083da8088e9f3c1e3f4e9f6e5cc8091e1f3f3efe3e9e1f4e9efeed6e1ecf5e5f3f480aacceff2e7afe1f8efeee6f2e1ede5f7eff2ebaff3e1e7e1afc1f3f3efe3e9e1f4e9efeed6e1ecf5e5f3bbcc808ae9e4e5eef4e9e6e9e5f2f48092cceae1f6e1afece1eee7afd3f4f2e9eee7bbf8f081f3f280b7eff2e7aee1f8efeee6f2e1ede5f7eff2ebaef3e1e7e1aee1eeeeeff4e1f4e9efeeaec1f3f3efe3e9e1f4e9efeed6e1ecf5e5f3c9edf0ecf252a65574607a42838081cc8086f6e1ecf5e5f3f4808fcceae1f6e1aff5f4e9ecafd3e5f4bbf8f0f3f28091eae1f6e1aef5f4e9ecaec8e1f3e8d3e5f43ac40515163837b4838080f8f0f78c80808090bfc0808080808082f3f280a7eff2e7aee1f8efeee6f2e1ede5f7eff2ebaef3e1e7e1aec1f3f3efe3e9e1f4e9efeed6e1ecf5e5b118ccbc87c08c3d828082cc808bf0f2eff0e5f2f4f9cbe5f9f180fe8083cc808df0f2eff0e5f2f4f9d6e1ecf5e5f48092cceae1f6e1afece1eee7afcfe2eae5e3f4bbf8f0f4808be1f3f3efe3e9e1f4e9efeef480a4b0e3e4b1b6b6e2e4adb0b3e2e3adb4b4e5e6ade1e2b7e4adb6b0b3b0b1b4b8b3e3b6b9b4f3f180fe808af4808ef3e1e7e1c9e4e5eef4e9e6e9e5f2f480a4b6b3e2e2e5e3b8b9ade3e2b3b3adb4b3e2b6ade1e2b6b8adb7b8b3e3e6b4b1e5b6b9b7b0f8f8f180fe8091f880f8}
2011-05-08 11:47:44,043 [main] DEBUG org.hibernate.pretty.Printer - org.axonframework.saga.repository.jpa.AssociationValueEntry{id=1, sagaId=63bbec89-cb33-43b6-ab68-783cf41e6970, associationValue=2c6d8085f480a4b0e3e4b1b6b6e2e4adb0b3e2e3adb4b4e5e6ade1e2b7e4adb6b0b3b0b1b4b8b3e3b6b9b4, associationKey=association}
2011-05-08 11:47:44,043 [main] DEBUG org.axonframework.eventhandling.SimpleEventBus - Dispatching Event [StartingEvent] to EventListener [EventListener$$EnhancerByMockitoWithCGLIB$$2862b5a2]
2011-05-08 11:47:44,044 [scheduler_QuartzSchedulerThread] DEBUG org.springframework.jdbc.datasource.DataSourceUtils - Returning JDBC Connection to DataSource
2011-05-08 11:47:44,058 [main] DEBUG org.springframework.orm.jpa.JpaTransactionManager - Initiating transaction commit
2011-05-08 11:47:44,058 [main] DEBUG org.springframework.orm.jpa.JpaTransactionManager - Committing JPA transaction on EntityManager [org.hibernate.ejb.EntityManagerImpl@3aeebf17]
2011-05-08 11:47:44,058 [main] DEBUG org.hibernate.transaction.JDBCTransaction - commit
2011-05-08 11:47:44,058 [main] DEBUG org.hibernate.event.def.AbstractFlushingEventListener - processing flush-time cascades
2011-05-08 11:47:44,059 [main] DEBUG org.hibernate.event.def.AbstractFlushingEventListener - dirty checking collections
2011-05-08 11:47:44,059 [main] DEBUG org.hibernate.event.def.AbstractFlushingEventListener - Flushed: 0 insertions, 0 updates, 0 deletions to 3 objects
2011-05-08 11:47:44,059 [main] DEBUG org.hibernate.event.def.AbstractFlushingEventListener - Flushed: 0 (re)creations, 0 updates, 0 removals to 0 collections
2011-05-08 11:47:44,059 [main] DEBUG org.hibernate.pretty.Printer - listing entities:
2011-05-08 11:47:44,059 [main] DEBUG org.hibernate.pretty.Printer - org.axonframework.saga.repository.jpa.AssociationValueEntry{id=2, sagaId=63bbec89-cb33-43b6-ab68-783cf41e6970, associationValue=2c6d8085f480a4b6b3e2e2e5e3b8b9ade3e2b3b3adb4b3e2b6ade1e2b6b8adb7b8b3e3e6b4b1e5b6b9b7b0, associationKey=sagaIdentifier}
2011-05-08 11:47:44,059 [main] DEBUG org.hibernate.pretty.Printer - org.axonframework.saga.repository.jpa.SagaEntry{sagaId=63bbec89-cb33-43b6-ab68-783cf41e6970, serializedSaga=2c6d8085f3f28095f4e5f3f4aed3e9edf0ece5d4e9ede9eee7d3e1e7e15338a56a8cbab477838081da8089f4f2e9e7e7e5f2e5e4f8f280b7eff2e7aee1f8efeee6f2e1ede5f7eff2ebaef3e1e7e1aee1eeeeeff4e1f4e9efeeaec1e2f3f4f2e1e3f4c1eeeeeff4e1f4e5e4d3e1e7e1a199ce58bc069602838083da8088e9f3c1e3f4e9f6e5cc8091e1f3f3efe3e9e1f4e9efeed6e1ecf5e5f3f480aacceff2e7afe1f8efeee6f2e1ede5f7eff2ebaff3e1e7e1afc1f3f3efe3e9e1f4e9efeed6e1ecf5e5f3bbcc808ae9e4e5eef4e9e6e9e5f2f48092cceae1f6e1afece1eee7afd3f4f2e9eee7bbf8f081f3f280b7eff2e7aee1f8efeee6f2e1ede5f7eff2ebaef3e1e7e1aee1eeeeeff4e1f4e9efeeaec1f3f3efe3e9e1f4e9efeed6e1ecf5e5f3c9edf0ecf252a65574607a42838081cc8086f6e1ecf5e5f3f4808fcceae1f6e1aff5f4e9ecafd3e5f4bbf8f0f3f28091eae1f6e1aef5f4e9ecaec8e1f3e8d3e5f43ac40515163837b4838080f8f0f78c80808090bfc0808080808082f3f280a7eff2e7aee1f8efeee6f2e1ede5f7eff2ebaef3e1e7e1aec1f3f3efe3e9e1f4e9efeed6e1ecf5e5b118ccbc87c08c3d828082cc808bf0f2eff0e5f2f4f9cbe5f9f180fe8083cc808df0f2eff0e5f2f4f9d6e1ecf5e5f48092cceae1f6e1afece1eee7afcfe2eae5e3f4bbf8f0f4808be1f3f3efe3e9e1f4e9efeef480a4b0e3e4b1b6b6e2e4adb0b3e2e3adb4b4e5e6ade1e2b7e4adb6b0b3b0b1b4b8b3e3b6b9b4f3f180fe808af4808ef3e1e7e1c9e4e5eef4e9e6e9e5f2f480a4b6b3e2e2e5e3b8b9ade3e2b3b3adb4b3e2b6ade1e2b6b8adb7b8b3e3e6b4b1e5b6b9b7b0f8f8f180fe8091f880f8}
2011-05-08 11:47:44,060 [main] DEBUG org.hibernate.pretty.Printer - org.axonframework.saga.repository.jpa.AssociationValueEntry{id=1, sagaId=63bbec89-cb33-43b6-ab68-783cf41e6970, associationValue=2c6d8085f480a4b0e3e4b1b6b6e2e4adb0b3e2e3adb4b4e5e6ade1e2b7e4adb6b0b3b0b1b4b8b3e3b6b9b4, associationKey=association}
2011-05-08 11:47:44,060 [main] DEBUG org.hibernate.transaction.JDBCTransaction - re-enabling autocommit
2011-05-08 11:47:44,060 [main] DEBUG org.hibernate.transaction.JDBCTransaction - committed JDBC Connection
2011-05-08 11:47:44,060 [main] DEBUG org.hibernate.jdbc.ConnectionManager - aggressively releasing JDBC connection
2011-05-08 11:47:44,060 [main] DEBUG org.hibernate.jdbc.ConnectionManager - releasing JDBC connection [ (open PreparedStatements: 0, globally: 0) (open ResultSets: 0, globally: 0)]
2011-05-08 11:47:44,060 [main] DEBUG org.springframework.orm.jpa.JpaTransactionManager - Closing JPA EntityManager [org.hibernate.ejb.EntityManagerImpl@3aeebf17] after transaction
2011-05-08 11:47:44,060 [main] DEBUG org.springframework.orm.jpa.EntityManagerFactoryUtils - Closing JPA EntityManager
2011-05-08 11:47:44,079 [QuartzScheduler_scheduler-1_MisfireHandler] DEBUG org.springframework.scheduling.quartz.LocalDataSourceJobStore - MisfireHandler: scanning for misfires…
2011-05-08 11:47:44,080 [QuartzScheduler_scheduler-1_MisfireHandler] DEBUG org.springframework.jdbc.datasource.DriverManagerDataSource - Creating new JDBC DriverManager Connection to [jdbc:hsqldb:mem:addressbook]
2011-05-08 11:47:44,081 [QuartzScheduler_scheduler-1_MisfireHandler] DEBUG org.springframework.scheduling.quartz.LocalDataSourceJobStore - Found 0 triggers that missed their scheduled fire-time.
2011-05-08 11:47:44,081 [QuartzScheduler_scheduler-1_MisfireHandler] DEBUG org.springframework.jdbc.datasource.DataSourceUtils - Returning JDBC Connection to DataSource
2011-05-08 11:47:44,179 [QuartzScheduler_scheduler-1_MisfireHandler] DEBUG org.springframework.scheduling.quartz.LocalDataSourceJobStore - MisfireHandler: scanning for misfires…
2011-05-08 11:47:44,179 [QuartzScheduler_scheduler-1_MisfireHandler] DEBUG org.springframework.jdbc.datasource.DriverManagerDataSource - Creating new JDBC DriverManager Connection to [jdbc:hsqldb:mem:addressbook]
2011-05-08 11:47:44,180 [QuartzScheduler_scheduler-1_MisfireHandler] DEBUG org.springframework.scheduling.quartz.LocalDataSourceJobStore - Found 0 triggers that missed their scheduled fire-time.
2011-05-08 11:47:44,181 [QuartzScheduler_scheduler-1_MisfireHandler] DEBUG org.springframework.jdbc.datasource.DataSourceUtils - Returning JDBC Connection to DataSource
2011-05-08 11:47:44,279 [QuartzScheduler_scheduler-1_MisfireHandler] DEBUG org.springframework.scheduling.quartz.LocalDataSourceJobStore - MisfireHandler: scanning for misfires…
2011-05-08 11:47:44,279 [QuartzScheduler_scheduler-1_MisfireHandler] DEBUG org.springframework.jdbc.datasource.DriverManagerDataSource - Creating new JDBC DriverManager Connection to [jdbc:hsqldb:mem:addressbook]
2011-05-08 11:47:44,280 [QuartzScheduler_scheduler-1_MisfireHandler] DEBUG org.springframework.scheduling.quartz.LocalDataSourceJobStore - Found 0 triggers that missed their scheduled fire-time.
2011-05-08 11:47:44,280 [QuartzScheduler_scheduler-1_MisfireHandler] DEBUG org.springframework.jdbc.datasource.DataSourceUtils - Returning JDBC Connection to DataSource
2011-05-08 11:47:44,379 [QuartzScheduler_scheduler-1_MisfireHandler] DEBUG org.springframework.scheduling.quartz.LocalDataSourceJobStore - MisfireHandler: scanning for misfires…
2011-05-08 11:47:44,380 [QuartzScheduler_scheduler-1_MisfireHandler] DEBUG org.springframework.jdbc.datasource.DriverManagerDataSource - Creating new JDBC DriverManager Connection to [jdbc:hsqldb:mem:addressbook]
2011-05-08 11:47:44,380 [QuartzScheduler_scheduler-1_MisfireHandler] DEBUG org.springframework.scheduling.quartz.LocalDataSourceJobStore - Found 0 triggers that missed their scheduled fire-time.
2011-05-08 11:47:44,381 [QuartzScheduler_scheduler-1_MisfireHandler] DEBUG org.springframework.jdbc.datasource.DataSourceUtils - Returning JDBC Connection to DataSource
2011-05-08 11:47:44,479 [QuartzScheduler_scheduler-1_MisfireHandler] DEBUG org.springframework.scheduling.quartz.LocalDataSourceJobStore - MisfireHandler: scanning for misfires…
2011-05-08 11:47:44,479 [QuartzScheduler_scheduler-1_MisfireHandler] DEBUG org.springframework.jdbc.datasource.DriverManagerDataSource - Creating new JDBC DriverManager Connection to [jdbc:hsqldb:mem:addressbook]
2011-05-08 11:47:44,480 [QuartzScheduler_scheduler-1_MisfireHandler] DEBUG org.springframework.scheduling.quartz.LocalDataSourceJobStore - Found 0 triggers that missed their scheduled fire-time.
2011-05-08 11:47:44,480 [QuartzScheduler_scheduler-1_MisfireHandler] DEBUG org.springframework.jdbc.datasource.DataSourceUtils - Returning JDBC Connection to DataSource
2011-05-08 11:47:44,509 [Timer-0] DEBUG org.quartz.utils.UpdateChecker - Checking for available updated version of Quartz…
2011-05-08 11:47:44,579 [QuartzScheduler_scheduler-1_MisfireHandler] DEBUG org.springframework.scheduling.quartz.LocalDataSourceJobStore - MisfireHandler: scanning for misfires…
2011-05-08 11:47:44,579 [QuartzScheduler_scheduler-1_MisfireHandler] DEBUG org.springframework.jdbc.datasource.DriverManagerDataSource - Creating new JDBC DriverManager Connection to [jdbc:hsqldb:mem:addressbook]
2011-05-08 11:47:44,580 [QuartzScheduler_scheduler-1_MisfireHandler] DEBUG org.springframework.scheduling.quartz.LocalDataSourceJobStore - Found 0 triggers that missed their scheduled fire-time.
2011-05-08 11:47:44,581 [QuartzScheduler_scheduler-1_MisfireHandler] DEBUG org.springframework.jdbc.datasource.DataSourceUtils - Returning JDBC Connection to DataSource
2011-05-08 11:47:44,679 [QuartzScheduler_scheduler-1_MisfireHandler] DEBUG org.springframework.scheduling.quartz.LocalDataSourceJobStore - MisfireHandler: scanning for misfires…
2011-05-08 11:47:44,679 [QuartzScheduler_scheduler-1_MisfireHandler] DEBUG org.springframework.jdbc.datasource.DriverManagerDataSource - Creating new JDBC DriverManager Connection to [jdbc:hsqldb:mem:addressbook]
2011-05-08 11:47:44,688 [QuartzScheduler_scheduler-1_MisfireHandler] DEBUG org.springframework.scheduling.quartz.LocalDataSourceJobStore - Found 0 triggers that missed their scheduled fire-time.
2011-05-08 11:47:44,688 [QuartzScheduler_scheduler-1_MisfireHandler] DEBUG org.springframework.jdbc.datasource.DataSourceUtils - Returning JDBC Connection to DataSource
2011-05-08 11:47:44,779 [QuartzScheduler_scheduler-1_MisfireHandler] DEBUG org.springframework.scheduling.quartz.LocalDataSourceJobStore - MisfireHandler: scanning for misfires…
2011-05-08 11:47:44,779 [QuartzScheduler_scheduler-1_MisfireHandler] DEBUG org.springframework.jdbc.datasource.DriverManagerDataSource - Creating new JDBC DriverManager Connection to [jdbc:hsqldb:mem:addressbook]
2011-05-08 11:47:44,780 [QuartzScheduler_scheduler-1_MisfireHandler] DEBUG org.springframework.scheduling.quartz.LocalDataSourceJobStore - Found 0 triggers that missed their scheduled fire-time.
2011-05-08 11:47:44,780 [QuartzScheduler_scheduler-1_MisfireHandler] DEBUG org.springframework.jdbc.datasource.DataSourceUtils - Returning JDBC Connection to DataSource
2011-05-08 11:47:44,879 [QuartzScheduler_scheduler-1_MisfireHandler] DEBUG org.springframework.scheduling.quartz.LocalDataSourceJobStore - MisfireHandler: scanning for misfires…
2011-05-08 11:47:44,880 [QuartzScheduler_scheduler-1_MisfireHandler] DEBUG org.springframework.jdbc.datasource.DriverManagerDataSource - Creating new JDBC DriverManager Connection to [jdbc:hsqldb:mem:addressbook]
2011-05-08 11:47:44,880 [QuartzScheduler_scheduler-1_MisfireHandler] DEBUG org.springframework.scheduling.quartz.LocalDataSourceJobStore - Found 0 triggers that missed their scheduled fire-time.
2011-05-08 11:47:44,880 [QuartzScheduler_scheduler-1_MisfireHandler] DEBUG org.springframework.jdbc.datasource.DataSourceUtils - Returning JDBC Connection to DataSource
2011-05-08 11:47:44,979 [QuartzScheduler_scheduler-1_MisfireHandler] DEBUG org.springframework.scheduling.quartz.LocalDataSourceJobStore - MisfireHandler: scanning for misfires…
2011-05-08 11:47:44,980 [QuartzScheduler_scheduler-1_MisfireHandler] DEBUG org.springframework.jdbc.datasource.DriverManagerDataSource - Creating new JDBC DriverManager Connection to [jdbc:hsqldb:mem:addressbook]
2011-05-08 11:47:44,981 [QuartzScheduler_scheduler-1_MisfireHandler] DEBUG org.springframework.scheduling.quartz.LocalDataSourceJobStore - Found 0 triggers that missed their scheduled fire-time.
2011-05-08 11:47:44,981 [QuartzScheduler_scheduler-1_MisfireHandler] DEBUG org.springframework.jdbc.datasource.DataSourceUtils - Returning JDBC Connection to DataSource
2011-05-08 11:47:44,985 [scheduler_QuartzSchedulerThread] DEBUG org.quartz.impl.jdbcjobstore.SimpleSemaphore - Lock ‘TRIGGER_ACCESS’ is desired by: scheduler_QuartzSchedulerThread
2011-05-08 11:47:44,985 [scheduler_QuartzSchedulerThread] DEBUG org.quartz.impl.jdbcjobstore.SimpleSemaphore - Lock ‘TRIGGER_ACCESS’ is being obtained: scheduler_QuartzSchedulerThread
2011-05-08 11:47:44,985 [scheduler_QuartzSchedulerThread] DEBUG org.quartz.impl.jdbcjobstore.SimpleSemaphore - Lock ‘TRIGGER_ACCESS’ given to: scheduler_QuartzSchedulerThread
2011-05-08 11:47:44,986 [scheduler_QuartzSchedulerThread] DEBUG org.springframework.jdbc.datasource.DriverManagerDataSource - Creating new JDBC DriverManager Connection to [jdbc:hsqldb:mem:addressbook]
2011-05-08 11:47:44,992 [scheduler_QuartzSchedulerThread] DEBUG org.quartz.impl.jdbcjobstore.SimpleSemaphore - Lock ‘TRIGGER_ACCESS’ retuned by: scheduler_QuartzSchedulerThread
2011-05-08 11:47:44,992 [scheduler_QuartzSchedulerThread] DEBUG org.springframework.jdbc.datasource.DataSourceUtils - Returning JDBC Connection to DataSource
2011-05-08 11:47:44,994 [scheduler_QuartzSchedulerThread] DEBUG org.springframework.jdbc.datasource.DriverManagerDataSource - Creating new JDBC DriverManager Connection to [jdbc:hsqldb:mem:addressbook]
2011-05-08 11:47:44,995 [scheduler_Worker-1] DEBUG org.quartz.core.JobRunShell - Calling execute on job AxonFramework-Events.event-7ffe26a9-b231-44d0-b06b-3d1cb043c9db
2011-05-08 11:47:44,995 [scheduler_Worker-1] DEBUG org.axonframework.eventhandling.scheduling.quartz.FireEventJob - Starting job to publish a scheduled event
2011-05-08 11:47:44,995 [scheduler_Worker-1] DEBUG org.axonframework.eventhandling.SimpleEventBus - Dispatching Event [MySagaExpiredEvent] to EventListener [AnnotatedSagaManager]
2011-05-08 11:47:44,995 [scheduler_QuartzSchedulerThread] DEBUG org.springframework.jdbc.datasource.DataSourceUtils - Returning JDBC Connection to DataSource
2011-05-08 11:47:44,995 [scheduler_Worker-1] INFO test.SimpleTimingSaga - in handle(MySagaExpiredEvent event) and setting triggered=true
2011-05-08 11:47:44,995 [main] INFO test.SimpleTimingSaga - isTriggered() is returning true
2011-05-08 11:47:44,996 [scheduler_Worker-1] DEBUG org.springframework.orm.jpa.SharedEntityManagerCreator$SharedEntityManagerInvocationHandler - Creating new EntityManager for shared EntityManager invocation
2011-05-08 11:47:44,996 [scheduler_Worker-1] DEBUG org.hibernate.impl.SessionImpl - opened session at timestamp: 13048696649
2011-05-08 11:47:44,996 [main] DEBUG org.springframework.test.context.support.DirtiesContextTestExecutionListener - After test method: context [[TestContext@5f70bea5 testClass = QuartzSagaTimerIntegrationTest, locations = array[‘classpath:META-INF/spring/saga-quartz-integration-test.xml’], testInstance = test.QuartzSagaTimerIntegrationTest@62f47396, testMethod = testJobExecutesInTime@QuartzSagaTimerIntegrationTest, testException = [null]]], class dirties context [false], class mode [null], method dirties context [false].
2011-05-08 11:47:44,997 [main] DEBUG org.springframework.test.context.support.DirtiesContextTestExecutionListener - After test class: context [[TestContext@5f70bea5 testClass = QuartzSagaTimerIntegrationTest, locations = array[‘classpath:META-INF/spring/saga-quartz-integration-test.xml’], testInstance = [null], testMethod = [null], testException = [null]]], dirtiesContext [false].
2011-05-08 11:47:44,998 [scheduler_Worker-1] DEBUG org.hibernate.loader.Loader - loading entity: [org.axonframework.saga.repository.jpa.SagaEntry#63bbec89-cb33-43b6-ab68-783cf41e6970]
2011-05-08 11:47:44,998 [scheduler_Worker-1] DEBUG org.hibernate.jdbc.AbstractBatcher - about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
2011-05-08 11:47:44,998 [scheduler_Worker-1] DEBUG org.hibernate.jdbc.ConnectionManager - opening JDBC connection
2011-05-08 11:47:44,998 [scheduler_Worker-1] DEBUG org.springframework.jdbc.datasource.DriverManagerDataSource - Creating new JDBC DriverManager Connection to [jdbc:hsqldb:mem:addressbook]
2011-05-08 11:47:44,998 [scheduler_Worker-1] DEBUG org.hibernate.SQL - select sagaentry0.sagaId as sagaId3_0_, sagaentry0_.serializedSaga as serializ2_3_0_ from SagaEntry sagaentry0_ where sagaentry0_.sagaId=?
2011-05-08 11:47:44,999 [scheduler_Worker-1] DEBUG org.hibernate.jdbc.AbstractBatcher - about to open ResultSet (open ResultSets: 0, globally: 0)
2011-05-08 11:47:44,999 [scheduler_Worker-1] DEBUG org.hibernate.loader.Loader - result row: EntityKey[org.axonframework.saga.repository.jpa.SagaEntry#63bbec89-cb33-43b6-ab68-783cf41e6970]
2011-05-08 11:47:45,001 [scheduler_Worker-1] DEBUG org.hibernate.jdbc.AbstractBatcher - about to close ResultSet (open ResultSets: 1, globally: 1)
2011-05-08 11:47:45,001 [Thread-5] INFO org.springframework.context.support.GenericApplicationContext - Closing org.springframework.context.support.GenericApplicationContext@42552c: startup date [Sun May 08 11:47:41 EDT 2011]; root of context hierarchy
2011-05-08 11:47:45,001 [scheduler_Worker-1] DEBUG org.hibernate.jdbc.AbstractBatcher - about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
2011-05-08 11:47:45,001 [scheduler_Worker-1] DEBUG org.hibernate.jdbc.ConnectionManager - aggressively releasing JDBC connection
2011-05-08 11:47:45,002 [scheduler_Worker-1] DEBUG org.hibernate.jdbc.ConnectionManager - releasing JDBC connection [ (open PreparedStatements: 0, globally: 0) (open ResultSets: 0, globally: 0)]
2011-05-08 11:47:45,002 [scheduler_Worker-1] DEBUG org.hibernate.engine.TwoPhaseLoad - resolving associations for [org.axonframework.saga.repository.jpa.SagaEntry#63bbec89-cb33-43b6-ab68-783cf41e6970]
2011-05-08 11:47:45,002 [Thread-5] DEBUG org.springframework.beans.factory.support.DefaultListableBeanFactory - Returning cached instance of singleton bean ‘scheduler’
2011-05-08 11:47:45,002 [Thread-5] DEBUG org.springframework.beans.factory.support.DefaultListableBeanFactory - Returning cached instance of singleton bean ‘lifecycleProcessor’
2011-05-08 11:47:45,002 [scheduler_Worker-1] DEBUG org.hibernate.engine.TwoPhaseLoad - done materializing entity [org.axonframework.saga.repository.jpa.SagaEntry#63bbec89-cb33-43b6-ab68-783cf41e6970]
2011-05-08 11:47:45,002 [scheduler_Worker-1] DEBUG org.hibernate.engine.StatefulPersistenceContext - initializing non-lazy collections
2011-05-08 11:47:45,002 [scheduler_Worker-1] DEBUG org.hibernate.loader.Loader - done entity load
2011-05-08 11:47:45,002 [scheduler_Worker-1] DEBUG org.hibernate.jdbc.ConnectionManager - aggressively releasing JDBC connection
2011-05-08 11:47:45,003 [scheduler_Worker-1] DEBUG org.springframework.orm.jpa.EntityManagerFactoryUtils - Closing JPA EntityManager
2011-05-08 11:47:45,003 [Thread-5] DEBUG org.springframework.beans.factory.support.DefaultListableBeanFactory - Returning cached instance of singleton bean ‘scheduler’
2011-05-08 11:47:45,003 [scheduler_Worker-1] DEBUG org.springframework.orm.jpa.SharedEntityManagerCreator$SharedEntityManagerInvocationHandler - Creating new EntityManager for shared EntityManager invocation
2011-05-08 11:47:45,003 [Thread-5] DEBUG org.springframework.beans.factory.support.DefaultListableBeanFactory - Returning cached instance of singleton bean ‘lifecycleProcessor’
2011-05-08 11:47:45,003 [Thread-5] INFO org.springframework.context.support.DefaultLifecycleProcessor - Stopping beans in phase 2147483647
2011-05-08 11:47:45,003 [scheduler_Worker-1] DEBUG org.hibernate.impl.SessionImpl - opened session at timestamp: 13048696650
2011-05-08 11:47:45,004 [scheduler_Worker-1] DEBUG org.springframework.orm.jpa.EntityManagerFactoryUtils - Closing JPA EntityManager
2011-05-08 11:47:45,004 [Thread-5] DEBUG org.springframework.context.support.DefaultLifecycleProcessor - Asking bean ‘scheduler’ of type [class org.springframework.scheduling.quartz.SchedulerFactoryBean] to stop
2011-05-08 11:47:45,005 [scheduler_Worker-1] ERROR org.quartz.core.JobRunShell - Job AxonFramework-Events.event-7ffe26a9-b231-44d0-b06b-3d1cb043c9db threw an unhandled Exception:
javax.persistence.TransactionRequiredException: no transaction is in progress
at org.hibernate.ejb.AbstractEntityManagerImpl.flush(AbstractEntityManagerImpl.java:301)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
at java.lang.reflect.Method.invoke(Method.java:597)
at org.springframework.orm.jpa.ExtendedEntityManagerCreator$ExtendedEntityManagerInvocationHandler.invoke(ExtendedEntityManagerCreator.java:365)
at $Proxy19.flush(Unknown Source)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
at java.lang.reflect.Method.invoke(Method.java:597)
at org.springframework.orm.jpa.SharedEntityManagerCreator$SharedEntityManagerInvocationHandler.invoke(SharedEntityManagerCreator.java:240)
at $Proxy19.flush(Unknown Source)
at org.axonframework.saga.repository.jpa.JpaSagaRepository.updateSaga(JpaSagaRepository.java:102)
at org.axonframework.saga.repository.AbstractSagaRepository.commit(AbstractSagaRepository.java:110)
at org.axonframework.saga.AbstractSagaManager.commit(AbstractSagaManager.java:136)
at org.axonframework.saga.AbstractSagaManager.invokeSagaHandler(AbstractSagaManager.java:117)
at org.axonframework.saga.AbstractSagaManager.access$100(AbstractSagaManager.java:40)
at org.axonframework.saga.AbstractSagaManager$SagaInvocationTask.run(AbstractSagaManager.java:210)
at org.axonframework.saga.SynchronousSagaExecutionWrapper.scheduleEventProcessingTask(SynchronousSagaExecutionWrapper.java:31)
at org.axonframework.saga.AbstractSagaManager$SagaLookupAndInvocationTask.run(AbstractSagaManager.java:229)
at org.axonframework.saga.SynchronousSagaExecutionWrapper.scheduleLookupTask(SynchronousSagaExecutionWrapper.java:26)
at org.axonframework.saga.AbstractSagaManager.handle(AbstractSagaManager.java:86)
at org.axonframework.eventhandling.SimpleEventBus.publish(SimpleEventBus.java:110)
at org.axonframework.eventhandling.scheduling.quartz.FireEventJob.execute(FireEventJob.java:55)
at org.quartz.core.JobRunShell.run(JobRunShell.java:216)
at org.quartz.simpl.SimpleThreadPool$WorkerThread.run(SimpleThreadPool.java:549)
2011-05-08 11:47:45,005 [Thread-5] INFO org.quartz.core.QuartzScheduler - Scheduler scheduler_$1 paused.
2011-05-08 11:47:45,008 [scheduler_Worker-1] ERROR org.quartz.core.ErrorLogger - Job (AxonFramework-Events.event-7ffe26a9-b231-44d0-b06b-3d1cb043c9db threw an exception.
org.quartz.SchedulerException: Job threw an unhandled exception. [See nested exception: javax.persistence.TransactionRequiredException: no transaction is in progress]
at org.quartz.core.JobRunShell.run(JobRunShell.java:227)
at org.quartz.simpl.SimpleThreadPool$WorkerThread.run(SimpleThreadPool.java:549)
Caused by: javax.persistence.TransactionRequiredException: no transaction is in progress
at org.hibernate.ejb.AbstractEntityManagerImpl.flush(AbstractEntityManagerImpl.java:301)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
at java.lang.reflect.Method.invoke(Method.java:597)
at org.springframework.orm.jpa.ExtendedEntityManagerCreator$ExtendedEntityManagerInvocationHandler.invoke(ExtendedEntityManagerCreator.java:365)
at $Proxy19.flush(Unknown Source)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
at java.lang.reflect.Method.invoke(Method.java:597)
at org.springframework.orm.jpa.SharedEntityManagerCreator$SharedEntityManagerInvocationHandler.invoke(SharedEntityManagerCreator.java:240)
at $Proxy19.flush(Unknown Source)
at org.axonframework.saga.repository.jpa.JpaSagaRepository.updateSaga(JpaSagaRepository.java:102)
at org.axonframework.saga.repository.AbstractSagaRepository.commit(AbstractSagaRepository.java:110)
at org.axonframework.saga.AbstractSagaManager.commit(AbstractSagaManager.java:136)
at org.axonframework.saga.AbstractSagaManager.invokeSagaHandler(AbstractSagaManager.java:117)
at org.axonframework.saga.AbstractSagaManager.access$100(AbstractSagaManager.java:40)
at org.axonframework.saga.AbstractSagaManager$SagaInvocationTask.run(AbstractSagaManager.java:210)
at org.axonframework.saga.SynchronousSagaExecutionWrapper.scheduleEventProcessingTask(SynchronousSagaExecutionWrapper.java:31)
at org.axonframework.saga.AbstractSagaManager$SagaLookupAndInvocationTask.run(AbstractSagaManager.java:229)
at org.axonframework.saga.SynchronousSagaExecutionWrapper.scheduleLookupTask(SynchronousSagaExecutionWrapper.java:26)
at org.axonframework.saga.AbstractSagaManager.handle(AbstractSagaManager.java:86)
at org.axonframework.eventhandling.SimpleEventBus.publish(SimpleEventBus.java:110)
at org.axonframework.eventhandling.scheduling.quartz.FireEventJob.execute(FireEventJob.java:55)
at org.quartz.core.JobRunShell.run(JobRunShell.java:216)
… 1 more
2011-05-08 11:47:45,011 [scheduler_Worker-1] DEBUG org.quartz.impl.jdbcjobstore.SimpleSemaphore - Lock ‘TRIGGER_ACCESS’ is desired by: scheduler_Worker-1
2011-05-08 11:47:45,011 [scheduler_Worker-1] DEBUG org.quartz.impl.jdbcjobstore.SimpleSemaphore - Lock ‘TRIGGER_ACCESS’ is being obtained: scheduler_Worker-1
2011-05-08 11:47:45,011 [scheduler_Worker-1] DEBUG org.quartz.impl.jdbcjobstore.SimpleSemaphore - Lock ‘TRIGGER_ACCESS’ given to: scheduler_Worker-1
2011-05-08 11:47:45,011 [scheduler_Worker-1] DEBUG org.springframework.jdbc.datasource.DriverManagerDataSource - Creating new JDBC DriverManager Connection to [jdbc:hsqldb:mem:addressbook]
2011-05-08 11:47:45,008 [Thread-5] DEBUG org.springframework.context.support.DefaultLifecycleProcessor - Bean ‘scheduler’ completed its stop procedure
2011-05-08 11:47:45,013 [Thread-5] INFO org.springframework.beans.factory.support.DefaultListableBeanFactory - Destroying singletons in org.springframework.beans.factory.support.DefaultListableBeanFactory@2e61a907: defining beans [org.springframework.context.annotation.internalConfigurationAnnotationProcessor,org.springframework.context.annotation.internalAutowiredAnnotationProcessor,org.springframework.context.annotation.internalRequiredAnnotationProcessor,org.springframework.context.annotation.internalCommonAnnotationProcessor,org.springframework.context.annotation.internalPersistenceAnnotationProcessor,org.springframework.aop.config.internalAutoProxyCreator,org.springframework.transaction.annotation.AnnotationTransactionAttributeSource#0,org.springframework.transaction.interceptor.TransactionInterceptor#0,org.springframework.transaction.config.internalTransactionAdvisor,org.springframework.beans.factory.config.PropertyPlaceholderConfigurer#0,entityManagerFactory,transactionManager,org.springframework.orm.jpa.support.PersistenceAnnotationBeanPostProcessor#0,dataSource,org.axonframework.eventstore.jpa.JpaEventStore#0,eventBus,sagaRepository,commandBus,sagaManager,com.testing.server.infrastructure.quartz.QuartzTableMaker#0,org.axonframework.saga.spring.SpringResourceInjector#0,org.axonframework.eventhandling.scheduling.quartz.QuartzEventScheduler#0,scheduler]; root of factory hierarchy
2011-05-08 11:47:45,013 [Thread-5] DEBUG org.springframework.beans.factory.support.DefaultListableBeanFactory - Retrieved dependent beans for bean ‘org.axonframework.eventhandling.scheduling.quartz.QuartzEventScheduler#0’: [test.SimpleTimingSaga]
2011-05-08 11:47:45,014 [Thread-5] DEBUG org.springframework.beans.factory.support.DisposableBeanAdapter - Invoking destroy() on bean with name ‘scheduler’
2011-05-08 11:47:45,014 [Thread-5] INFO org.springframework.scheduling.quartz.SchedulerFactoryBean - Shutting down Quartz Scheduler
2011-05-08 11:47:45,014 [Thread-5] INFO org.quartz.core.QuartzScheduler - Scheduler scheduler$1 shutting down.
2011-05-08 11:47:45,014 [Thread-5] INFO org.quartz.core.QuartzScheduler - Scheduler scheduler$1 paused.
2011-05-08 11:47:45,014 [scheduler_Worker-1] DEBUG org.springframework.scheduling.quartz.LocalDataSourceJobStore - Deleting job: AxonFramework-Events.event-7ffe26a9-b231-44d0-b06b-3d1cb043c9db
2011-05-08 11:47:45,019 [scheduler_Worker-1] DEBUG org.quartz.impl.jdbcjobstore.SimpleSemaphore - Lock ‘TRIGGER_ACCESS’ retuned by: scheduler_Worker-1
2011-05-08 11:47:45,019 [scheduler_Worker-1] DEBUG org.springframework.jdbc.datasource.DataSourceUtils - Returning JDBC Connection to DataSource
2011-05-08 11:47:45,019 [scheduler_Worker-1] DEBUG org.quartz.simpl.SimpleThreadPool - WorkerThread is shut down.
2011-05-08 11:47:45,018 [Thread-5] INFO org.quartz.core.QuartzScheduler - Scheduler scheduler$_1 shutdown complete.
2011-05-08 11:47:45,020 [Thread-5] DEBUG org.springframework.context.annotation.CommonAnnotationBeanPostProcessor - Invoking destroy method on bean ‘sagaManager’: public void org.axonframework.saga.AbstractSagaManager.unsubscribe()
2011-05-08 11:47:45,021 [Thread-5] DEBUG org.axonframework.eventhandling.SimpleEventBus - EventListener AnnotatedSagaManager unsubscribed successfully
2011-05-08 11:47:45,021 [Thread-5] DEBUG org.springframework.beans.factory.support.DefaultListableBeanFactory - Retrieved dependent beans for bean ‘(inner bean)’: [(inner bean), sagaManager]
2011-05-08 11:47:45,021 [Thread-5] DEBUG org.springframework.beans.factory.support.DefaultListableBeanFactory - Retrieved dependent beans for bean ‘sagaRepository’: [test.QuartzSagaTimerIntegrationTest]
2011-05-08 11:47:45,021 [Thread-5] DEBUG org.springframework.beans.factory.support.DefaultListableBeanFactory - Retrieved dependent beans for bean ‘org.axonframework.eventstore.XStreamEventSerializer#722b9406’: [org.axonframework.eventstore.jpa.JpaEventStore#0]
2011-05-08 11:47:45,022 [Thread-5] DEBUG org.springframework.beans.factory.support.DisposableBeanAdapter - Invoking destroy() on bean with name ‘entityManagerFactory’
2011-05-08 11:47:45,022 [Thread-5] INFO org.springframework.orm.jpa.LocalContainerEntityManagerFactoryBean - Closing JPA EntityManagerFactory for persistence unit ‘eventStore’
2011-05-08 11:47:45,022 [Thread-5] INFO org.hibernate.impl.SessionFactoryImpl - closing
2011-05-08 11:47:45,024 [Thread-5] DEBUG org.springframework.beans.factory.support.DefaultListableBeanFactory - Retrieved dependent beans for bean ‘org.springframework.orm.jpa.vendor.HibernateJpaVendorAdapter#26d66426’: [entityManagerFactory]
2011-05-08 11:47:45,024 [Thread-5] DEBUG org.springframework.beans.factory.support.DefaultListableBeanFactory - Retrieved dependent beans for bean ‘org.springframework.transaction.annotation.AnnotationTransactionAttributeSource#0’: [org.springframework.transaction.config.internalTransactionAdvisor]