JUnit Integration test failure on PersistenceException

John_van_Weel · November 19, 2018, 3:14pm

Hey all,

I am new with Axon and am just getting started. I now have a Spring Boot integration test that sometimes fails due to @EventHandlers not getting triggered. It is noticable that these failures have a stacktrace related to the H2 database at the start of the test.
It seems that Axon is attempting to interact with the database while Hibernate is still creating it.

Using Axon 4 and Spring Boot 2.

Has anyone seen this before? And is creating an h2 database for integration tests a common practice, or do you have some other recommendation for testing the application?

Hibernate logs and stacktrace are below.

With kind regards,

John

Hibernate: drop table association_value_entry if exists
Hibernate: update token_entry set timestamp=? where processor_name=? and segment=? and owner=?
Hibernate: drop table domain_event_entry if exists
Hibernate: drop table saga_entry if exists
Hibernate: select domaineven0_.global_index as col_0_0_, domaineven0_.type as col_1_0_, domaineven0_.aggregate_identifier as col_2_0_, domaineven0_.sequence_number as col_3_0_, domaineven0_.event_identifier as col_4_0_, domaineven0_.time_stamp as col_5_0_, domaineven0_.payload_type as col_6_0_, domaineven0_.payload_revision as col_7_0_, domaineven0_.payload as col_8_0_, domaineven0_.meta_data as col_9_0_ from domain_event_entry domaineven0_ where domaineven0_.global_index>? or domaineven0_.global_index in (? , ?) order by domaineven0_.global_index ASC limit ?
2018-11-19 13:07:14.099  WARN [-service,,,] 17623 --- [s.querymodel]-0] o.h.engine.jdbc.spi.SqlExceptionHelper   : SQL Error: 42102, SQLState: 42S02
2018-11-19 13:07:14.099 ERROR [-service,,,] 17623 --- [s.querymodel]-0] o.h.engine.jdbc.spi.SqlExceptionHelper   : Table "DOMAIN_EVENT_ENTRY" not found; SQL statement:
select domaineven0_.global_index as col_0_0_, domaineven0_.type as col_1_0_, domaineven0_.aggregate_identifier as col_2_0_, domaineven0_.sequence_number as col_3_0_, domaineven0_.event_identifier as col_4_0_, domaineven0_.time_stamp as col_5_0_, domaineven0_.payload_type as col_6_0_, domaineven0_.payload_revision as col_7_0_, domaineven0_.payload as col_8_0_, domaineven0_.meta_data as col_9_0_ from domain_event_entry domaineven0_ where domaineven0_.global_index>? or domaineven0_.global_index in (? , ?) order by domaineven0_.global_index ASC limit ? [42102-197]
Hibernate: drop table snapshot_event_entry if exists
Hibernate: drop table token_entry if exists
Hibernate: drop sequence if exists hibernate_sequence
Hibernate: create sequence hibernate_sequence start with 1 increment by 1
Hibernate: create table association_value_entry (id bigint not null, association_key varchar(255) not null, association_value varchar(255), saga_id varchar(255) not null, saga_type varchar(255), primary key (id))
2018-11-19 13:07:14.102  WARN [-service,,,] 17623 --- [s.querymodel]-0] o.a.e.TrackingEventProcessor             : Error occurred. Starting retry mode.

javax.persistence.PersistenceException: org.hibernate.exception.SQLGrammarException: could not prepare statement

javax.persistence.PersistenceException: org.hibernate.exception.SQLGrammarException: could not prepare statement
   at org.hibernate.internal.ExceptionConverterImpl.convert(ExceptionConverterImpl.java:149) ~[hibernate-core-5.2.17.Final.jar:5.2.17.Final]
   at org.hibernate.internal.ExceptionConverterImpl.convert(ExceptionConverterImpl.java:157) ~[hibernate-core-5.2.17.Final.jar:5.2.17.Final]
   at org.hibernate.query.internal.AbstractProducedQuery.list(AbstractProducedQuery.java:1423) ~[hibernate-core-5.2.17.Final.jar:5.2.17.Final]
   at org.hibernate.query.Query.getResultList(Query.java:146) ~[hibernate-core-5.2.17.Final.jar:5.2.17.Final]
   at org.axonframework.eventsourcing.eventstore.jpa.JpaEventStorageEngine.lambda$fetchTrackedEvents$1(JpaEventStorageEngine.java:165) ~[axon-eventsourcing-4.0.jar:4.0]
   at org.axonframework.common.transaction.TransactionManager.fetchInTransaction(TransactionManager.java:70) ~[axon-messaging-4.0.jar:4.0]
   at org.axonframework.eventsourcing.eventstore.jpa.JpaEventStorageEngine.fetchTrackedEvents(JpaEventStorageEngine.java:145) ~[axon-eventsourcing-4.0.jar:4.0]
   at org.axonframework.eventsourcing.eventstore.BatchingEventStorageEngine.lambda$readEventData$1(BatchingEventStorageEngine.java:111) ~[axon-eventsourcing-4.0.jar:4.0]
   at org.axonframework.eventsourcing.eventstore.BatchingEventStorageEngine$EventStreamSpliterator.tryAdvance(BatchingEventStorageEngine.java:222) ~[axon-eventsourcing-4.0.jar:4.0]
   at java.util.stream.StreamSpliterators$WrappingSpliterator.lambda$initPartialTraversalState$0(StreamSpliterators.java:294) ~[na:1.8.0_181]
   at java.util.stream.StreamSpliterators$AbstractWrappingSpliterator.fillBuffer(StreamSpliterators.java:206) ~[na:1.8.0_181]
   at java.util.stream.StreamSpliterators$AbstractWrappingSpliterator.doAdvance(StreamSpliterators.java:169) ~[na:1.8.0_181]
   at java.util.stream.StreamSpliterators$WrappingSpliterator.tryAdvance(StreamSpliterators.java:300) ~[na:1.8.0_181]
   at java.util.Spliterators$1Adapter.hasNext(Spliterators.java:681) ~[na:1.8.0_181]
   at org.axonframework.eventsourcing.eventstore.EmbeddedEventStore$EventConsumer.peekPrivateStream(EmbeddedEventStore.java:389) ~[axon-eventsourcing-4.0.jar:4.0]
   at org.axonframework.eventsourcing.eventstore.EmbeddedEventStore$EventConsumer.peek(EmbeddedEventStore.java:348) ~[axon-eventsourcing-4.0.jar:4.0]
   at org.axonframework.eventsourcing.eventstore.EmbeddedEventStore$EventConsumer.hasNextAvailable(EmbeddedEventStore.java:325) ~[axon-eventsourcing-4.0.jar:4.0]
   at org.axonframework.common.stream.BlockingStream.hasNextAvailable(BlockingStream.java:40) ~[axon-messaging-4.0.jar:4.0]
   at org.axonframework.eventhandling.TrackingEventProcessor.checkSegmentCaughtUp(TrackingEventProcessor.java:269) ~[axon-messaging-4.0.jar:4.0]
   at org.axonframework.eventhandling.TrackingEventProcessor.processBatch(TrackingEventProcessor.java:216) ~[axon-messaging-4.0.jar:4.0]
   at org.axonframework.eventhandling.TrackingEventProcessor.processingLoop(TrackingEventProcessor.java:181) ~[axon-messaging-4.0.jar:4.0]
   at org.axonframework.eventhandling.TrackingEventProcessor$TrackingSegmentWorker.run(TrackingEventProcessor.java:661) [axon-messaging-4.0.jar:4.0]
   at org.axonframework.eventhandling.TrackingEventProcessor$WorkerLauncher.run(TrackingEventProcessor.java:771) [axon-messaging-4.0.jar:4.0]
   at org.axonframework.eventhandling.TrackingEventProcessor$TrackingSegmentWorker.run(TrackingEventProcessor.java:669) [axon-messaging-4.0.jar:4.0]
   at org.axonframework.eventhandling.TrackingEventProcessor$WorkerLauncher.run(TrackingEventProcessor.java:771) [axon-messaging-4.0.jar:4.0]
   at org.axonframework.eventhandling.TrackingEventProcessor$TrackingSegmentWorker.run(TrackingEventProcessor.java:669) [axon-messaging-4.0.jar:4.0]
   at org.axonframework.eventhandling.TrackingEventProcessor$WorkerLauncher.run(TrackingEventProcessor.java:771) [axon-messaging-4.0.jar:4.0]
   at org.axonframework.eventhandling.TrackingEventProcessor$CountingRunnable.run(TrackingEventProcessor.java:588) [axon-messaging-4.0.jar:4.0]
   at java.lang.Thread.run(Thread.java:748) [na:1.8.0_181]
Caused by: org.hibernate.exception.SQLGrammarException: could not prepare statement
   at org.hibernate.exception.internal.SQLStateConversionDelegate.convert(SQLStateConversionDelegate.java:106) ~[hibernate-core-5.2.17.Final.jar:5.2.17.Final]
   at org.hibernate.exception.internal.StandardSQLExceptionConverter.convert(StandardSQLExceptionConverter.java:42) ~[hibernate-core-5.2.17.Final.jar:5.2.17.Final]
   at org.hibernate.engine.jdbc.spi.SqlExceptionHelper.convert(SqlExceptionHelper.java:111) ~[hibernate-core-5.2.17.Final.jar:5.2.17.Final]
   at org.hibernate.engine.jdbc.internal.StatementPreparerImpl$StatementPreparationTemplate.prepareStatement(StatementPreparerImpl.java:181) ~[hibernate-core-5.2.17.Final.jar:5.2.17.Final]
   at org.hibernate.engine.jdbc.internal.StatementPreparerImpl.prepareQueryStatement(StatementPreparerImpl.java:147) ~[hibernate-core-5.2.17.Final.jar:5.2.17.Final]
   at org.hibernate.loader.Loader.prepareQueryStatement(Loader.java:1985) ~[hibernate-core-5.2.17.Final.jar:5.2.17.Final]
   at org.hibernate.loader.Loader.executeQueryStatement(Loader.java:1915) ~[hibernate-core-5.2.17.Final.jar:5.2.17.Final]
   at org.hibernate.loader.Loader.executeQueryStatement(Loader.java:1893) ~[hibernate-core-5.2.17.Final.jar:5.2.17.Final]
   at org.hibernate.loader.Loader.doQuery(Loader.java:938) ~[hibernate-core-5.2.17.Final.jar:5.2.17.Final]
   at org.hibernate.loader.Loader.doQueryAndInitializeNonLazyCollections(Loader.java:341) ~[hibernate-core-5.2.17.Final.jar:5.2.17.Final]
   at org.hibernate.loader.Loader.doList(Loader.java:2692) ~[hibernate-core-5.2.17.Final.jar:5.2.17.Final]
   at org.hibernate.loader.Loader.doList(Loader.java:2675) ~[hibernate-core-5.2.17.Final.jar:5.2.17.Final]
   at org.hibernate.loader.Loader.listIgnoreQueryCache(Loader.java:2507) ~[hibernate-core-5.2.17.Final.jar:5.2.17.Final]
   at org.hibernate.loader.Loader.list(Loader.java:2502) ~[hibernate-core-5.2.17.Final.jar:5.2.17.Final]
   at org.hibernate.loader.hql.QueryLoader.list(QueryLoader.java:502) ~[hibernate-core-5.2.17.Final.jar:5.2.17.Final]
   at org.hibernate.hql.internal.ast.QueryTranslatorImpl.list(QueryTranslatorImpl.java:392) ~[hibernate-core-5.2.17.Final.jar:5.2.17.Final]
   at org.hibernate.engine.query.spi.HQLQueryPlan.performList(HQLQueryPlan.java:216) ~[hibernate-core-5.2.17.Final.jar:5.2.17.Final]
   at org.hibernate.internal.SessionImpl.list(SessionImpl.java:1490) ~[hibernate-core-5.2.17.Final.jar:5.2.17.Final]
   at org.hibernate.query.internal.AbstractProducedQuery.doList(AbstractProducedQuery.java:1445) ~[hibernate-core-5.2.17.Final.jar:5.2.17.Final]
   at org.hibernate.query.internal.AbstractProducedQuery.list(AbstractProducedQuery.java:1414) ~[hibernate-core-5.2.17.Final.jar:5.2.17.Final]
   ... 26 common frames omitted
Caused by: org.h2.jdbc.JdbcSQLException: Table "DOMAIN_EVENT_ENTRY" not found; SQL statement:
select domaineven0_.global_index as col_0_0_, domaineven0_.type as col_1_0_, domaineven0_.aggregate_identifier as col_2_0_, domaineven0_.sequence_number as col_3_0_, domaineven0_.event_identifier as col_4_0_, domaineven0_.time_stamp as col_5_0_, domaineven0_.payload_type as col_6_0_, domaineven0_.payload_revision as col_7_0_, domaineven0_.payload as col_8_0_, domaineven0_.meta_data as col_9_0_ from domain_event_entry domaineven0_ where domaineven0_.global_index>? or domaineven0_.global_index in (? , ?) order by domaineven0_.global_index ASC limit ? [42102-197]
   at org.h2.message.DbException.getJdbcSQLException(DbException.java:357) ~[h2-1.4.197.jar:1.4.197]
   at org.h2.message.DbException.get(DbException.java:179) ~[h2-1.4.197.jar:1.4.197]
   at org.h2.message.DbException.get(DbException.java:155) ~[h2-1.4.197.jar:1.4.197]
   at org.h2.command.Parser.readTableOrView(Parser.java:5920) ~[h2-1.4.197.jar:1.4.197]
   at org.h2.command.Parser.readTableFilter(Parser.java:1430) ~[h2-1.4.197.jar:1.4.197]
   at org.h2.command.Parser.parseSelectSimpleFromPart(Parser.java:2138) ~[h2-1.4.197.jar:1.4.197]
   at org.h2.command.Parser.parseSelectSimple(Parser.java:2287) ~[h2-1.4.197.jar:1.4.197]
   at org.h2.command.Parser.parseSelectSub(Parser.java:2133) ~[h2-1.4.197.jar:1.4.197]
   at org.h2.command.Parser.parseSelectUnion(Parser.java:1946) ~[h2-1.4.197.jar:1.4.197]
   at org.h2.command.Parser.parseSelect(Parser.java:1919) ~[h2-1.4.197.jar:1.4.197]
   at org.h2.command.Parser.parsePrepared(Parser.java:463) ~[h2-1.4.197.jar:1.4.197]
   at org.h2.command.Parser.parse(Parser.java:335) ~[h2-1.4.197.jar:1.4.197]
   at org.h2.command.Parser.parse(Parser.java:307) ~[h2-1.4.197.jar:1.4.197]
   at org.h2.command.Parser.prepareCommand(Parser.java:278) ~[h2-1.4.197.jar:1.4.197]
   at org.h2.engine.Session.prepareLocal(Session.java:611) ~[h2-1.4.197.jar:1.4.197]
   at org.h2.engine.Session.prepareCommand(Session.java:549) ~[h2-1.4.197.jar:1.4.197]
   at org.h2.jdbc.JdbcConnection.prepareCommand(JdbcConnection.java:1247) ~[h2-1.4.197.jar:1.4.197]
   at org.h2.jdbc.JdbcPreparedStatement.<init>(JdbcPreparedStatement.java:76) ~[h2-1.4.197.jar:1.4.197]
   at org.h2.jdbc.JdbcConnection.prepareStatement(JdbcConnection.java:304) ~[h2-1.4.197.jar:1.4.197]
   at com.zaxxer.hikari.pool.ProxyConnection.prepareStatement(ProxyConnection.java:318) ~[HikariCP-2.7.9.jar:na]
   at com.zaxxer.hikari.pool.HikariProxyConnection.prepareStatement(HikariProxyConnection.java) ~[HikariCP-2.7.9.jar:na]
   at org.hibernate.engine.jdbc.internal.StatementPreparerImpl$5.doPrepare(StatementPreparerImpl.java:145) ~[hibernate-core-5.2.17.Final.jar:5.2.17.Final]
   at org.hibernate.engine.jdbc.internal.StatementPreparerImpl$StatementPreparationTemplate.prepareStatement(StatementPreparerImpl.java:171) ~[hibernate-core-5.2.17.Final.jar:5.2.17.Final]
   ... 42 common frames omitted

allardbz · November 20, 2018, 10:33am

Hi John,

it looks like a Tracking Processor has already started processing before the application itself has.
By default, Axon starts its configuration in phase 0. This should be very well after Hibernate initialization.

Do you have any configuration that starts processors directly, or that changes phases in which Hibernate or Axon components are started?

Cheers,

Allard

John_van_Weel · November 20, 2018, 12:20pm

Hello Allard,

Thank you for your quick reply! As far as I know we are not doing anything special with the phases of the application. We have a spring boot application with a @SpringBootTest. I didn’t know it was even possible to change the order of starting Axon or Hibernate.

I did find the code snippet below in a static @TestConfiguration block. I am not sure why we had this, may be a leftover from our trial & error period. Do you think this could be the cause? Removing it does not break our tests.

@Bean
public EventSourcingRepository<MyAggregate> eventSourcingRepository(final EventStore eventStore) {
    return EventSourcingRepository.builder(MyAggregate.class).eventStore(eventStore).build();
}

allardbz · November 20, 2018, 4:05pm

Hi John,

it’s been a long time since I have defined a Repository explicitly. This should all be autoconfigured for you.

Can you share your configuration?
Is your aggregate annotated with @Aggregate? Does it (also) have an @Entity (JPA/Hibernate) annotation?

Cheers,

Allard