Saga Event Processor Persistence Exception

Axon Server
, ,
1

Hi,
I’m running version 4.6.7 of the axon server with an axon-based spring boot application (version 2.7.5).
Sagas can’t be processed to to this strange error that I’m unable to debug kindly advise…

2022-11-23 16:46:47.821  WARN 1 --- [agaProcessor]-0] o.a.e.TrackingEventProcessor             : Error occurred. Starting retry mode.

javax.persistence.PersistenceException: org.hibernate.exception.DataException: could not execute statement
	at org.hibernate.internal.ExceptionConverterImpl.convert(ExceptionConverterImpl.java:154) ~[hibernate-core-5.6.12.Final.jar!/:5.6.12.Final]
	at org.hibernate.internal.ExceptionConverterImpl.convert(ExceptionConverterImpl.java:181) ~[hibernate-core-5.6.12.Final.jar!/:5.6.12.Final]
	at org.hibernate.internal.ExceptionConverterImpl.convert(ExceptionConverterImpl.java:188) ~[hibernate-core-5.6.12.Final.jar!/:5.6.12.Final]
	at org.hibernate.internal.SessionImpl.doFlush(SessionImpl.java:1411) ~[hibernate-core-5.6.12.Final.jar!/:5.6.12.Final]
	at org.hibernate.internal.SessionImpl.flush(SessionImpl.java:1394) ~[hibernate-core-5.6.12.Final.jar!/:5.6.12.Final]
	at java.base/jdk.internal.reflect.DirectMethodHandleAccessor.invoke(DirectMethodHandleAccessor.java:104) ~[na:na]
	at java.base/java.lang.reflect.Method.invoke(Method.java:577) ~[na:na]
	at org.springframework.orm.jpa.SharedEntityManagerCreator$SharedEntityManagerInvocationHandler.invoke(SharedEntityManagerCreator.java:311) ~[spring-orm-5.3.23.jar!/:5.3.23]
	at jdk.proxy2/jdk.proxy2.$Proxy131.flush(Unknown Source) ~[na:na]
	at org.axonframework.modelling.saga.repository.jpa.JpaSagaStore.insertSaga(JpaSagaStore.java:307) ~[axon-modelling-4.6.2.jar!/:4.6.2]
	at org.axonframework.modelling.saga.repository.AnnotatedSagaRepository.storeSaga(AnnotatedSagaRepository.java:219) ~[axon-modelling-4.6.2.jar!/:4.6.2]
	at org.axonframework.modelling.saga.repository.AnnotatedSagaRepository.lambda$doCreateInstance$3(AnnotatedSagaRepository.java:139) ~[axon-modelling-4.6.2.jar!/:4.6.2]
	at org.axonframework.messaging.unitofwork.MessageProcessingContext.notifyHandlers(MessageProcessingContext.java:72) ~[axon-messaging-4.6.2.jar!/:4.6.2]
	at org.axonframework.messaging.unitofwork.BatchingUnitOfWork.lambda$notifyHandlers$2(BatchingUnitOfWork.java:161) ~[axon-messaging-4.6.2.jar!/:4.6.2]
	at java.base/java.util.ArrayList$Itr.forEachRemaining(ArrayList.java:1003) ~[na:na]
	at org.axonframework.messaging.unitofwork.BatchingUnitOfWork.notifyHandlers(BatchingUnitOfWork.java:161) ~[axon-messaging-4.6.2.jar!/:4.6.2]
	at org.axonframework.messaging.unitofwork.AbstractUnitOfWork.changePhase(AbstractUnitOfWork.java:236) ~[axon-messaging-4.6.2.jar!/:4.6.2]
	at org.axonframework.messaging.unitofwork.AbstractUnitOfWork.commitAsRoot(AbstractUnitOfWork.java:87) ~[axon-messaging-4.6.2.jar!/:4.6.2]
	at org.axonframework.messaging.unitofwork.AbstractUnitOfWork.commit(AbstractUnitOfWork.java:75) ~[axon-messaging-4.6.2.jar!/:4.6.2]
	at org.axonframework.messaging.unitofwork.BatchingUnitOfWork.executeWithResult(BatchingUnitOfWork.java:117) ~[axon-messaging-4.6.2.jar!/:4.6.2]
	at org.axonframework.eventhandling.AbstractEventProcessor.processInUnitOfWork(AbstractEventProcessor.java:166) ~[axon-messaging-4.6.2.jar!/:4.6.2]
	at org.axonframework.eventhandling.TrackingEventProcessor.processBatch(TrackingEventProcessor.java:490) ~[axon-messaging-4.6.2.jar!/:4.6.2]
	at org.axonframework.eventhandling.TrackingEventProcessor.processingLoop(TrackingEventProcessor.java:318) ~[axon-messaging-4.6.2.jar!/:4.6.2]
	at org.axonframework.eventhandling.TrackingEventProcessor$TrackingSegmentWorker.run(TrackingEventProcessor.java:1145) ~[axon-messaging-4.6.2.jar!/:4.6.2]
	at org.axonframework.eventhandling.TrackingEventProcessor$WorkerLauncher.cleanUp(TrackingEventProcessor.java:1340) ~[axon-messaging-4.6.2.jar!/:4.6.2]
	at org.axonframework.eventhandling.TrackingEventProcessor$WorkerLauncher.run(TrackingEventProcessor.java:1317) ~[axon-messaging-4.6.2.jar!/:4.6.2]
	at java.base/java.lang.Thread.run(Thread.java:833) ~[na:na]
Caused by: org.hibernate.exception.DataException: could not execute statement
	at org.hibernate.exception.internal.SQLStateConversionDelegate.convert(SQLStateConversionDelegate.java:115) ~[hibernate-core-5.6.12.Final.jar!/:5.6.12.Final]
	at org.hibernate.exception.internal.StandardSQLExceptionConverter.convert(StandardSQLExceptionConverter.java:37) ~[hibernate-core-5.6.12.Final.jar!/:5.6.12.Final]
	at org.hibernate.engine.jdbc.spi.SqlExceptionHelper.convert(SqlExceptionHelper.java:113) ~[hibernate-core-5.6.12.Final.jar!/:5.6.12.Final]
	at org.hibernate.engine.jdbc.spi.SqlExceptionHelper.convert(SqlExceptionHelper.java:99) ~[hibernate-core-5.6.12.Final.jar!/:5.6.12.Final]
	at org.hibernate.engine.jdbc.internal.ResultSetReturnImpl.executeUpdate(ResultSetReturnImpl.java:200) ~[hibernate-core-5.6.12.Final.jar!/:5.6.12.Final]
	at org.hibernate.engine.jdbc.batch.internal.NonBatchingBatch.addToBatch(NonBatchingBatch.java:46) ~[hibernate-core-5.6.12.Final.jar!/:5.6.12.Final]
	at org.hibernate.persister.entity.AbstractEntityPersister.insert(AbstractEntityPersister.java:3375) ~[hibernate-core-5.6.12.Final.jar!/:5.6.12.Final]
	at org.hibernate.persister.entity.AbstractEntityPersister.insert(AbstractEntityPersister.java:3908) ~[hibernate-core-5.6.12.Final.jar!/:5.6.12.Final]
	at org.hibernate.action.internal.EntityInsertAction.execute(EntityInsertAction.java:107) ~[hibernate-core-5.6.12.Final.jar!/:5.6.12.Final]
	at org.hibernate.engine.spi.ActionQueue.executeActions(ActionQueue.java:604) ~[hibernate-core-5.6.12.Final.jar!/:5.6.12.Final]
	at org.hibernate.engine.spi.ActionQueue.lambda$executeActions$1(ActionQueue.java:478) ~[hibernate-core-5.6.12.Final.jar!/:5.6.12.Final]
	at java.base/java.util.LinkedHashMap.forEach(LinkedHashMap.java:721) ~[na:na]
	at org.hibernate.engine.spi.ActionQueue.executeActions(ActionQueue.java:475) ~[hibernate-core-5.6.12.Final.jar!/:5.6.12.Final]
	at org.hibernate.event.internal.AbstractFlushingEventListener.performExecutions(AbstractFlushingEventListener.java:344) ~[hibernate-core-5.6.12.Final.jar!/:5.6.12.Final]
	at org.hibernate.event.internal.DefaultFlushEventListener.onFlush(DefaultFlushEventListener.java:40) ~[hibernate-core-5.6.12.Final.jar!/:5.6.12.Final]
	at org.hibernate.event.service.internal.EventListenerGroupImpl.fireEventOnEachListener(EventListenerGroupImpl.java:107) ~[hibernate-core-5.6.12.Final.jar!/:5.6.12.Final]
	at org.hibernate.internal.SessionImpl.doFlush(SessionImpl.java:1407) ~[hibernate-core-5.6.12.Final.jar!/:5.6.12.Final]
	... 23 common frames omitted
Caused by: org.postgresql.util.PSQLException: ERROR: value too long for type character varying(255)
	at org.postgresql.core.v3.QueryExecutorImpl.receiveErrorResponse(QueryExecutorImpl.java:2676) ~[postgresql-42.5.0.jar!/:42.5.0]
	at org.postgresql.core.v3.QueryExecutorImpl.processResults(QueryExecutorImpl.java:2366) ~[postgresql-42.5.0.jar!/:42.5.0]
	at org.postgresql.core.v3.QueryExecutorImpl.execute(QueryExecutorImpl.java:356) ~[postgresql-42.5.0.jar!/:42.5.0]
	at org.postgresql.jdbc.PgStatement.executeInternal(PgStatement.java:496) ~[postgresql-42.5.0.jar!/:42.5.0]
	at org.postgresql.jdbc.PgStatement.execute(PgStatement.java:413) ~[postgresql-42.5.0.jar!/:42.5.0]
	at org.postgresql.jdbc.PgPreparedStatement.executeWithFlags(PgPreparedStatement.java:190) ~[postgresql-42.5.0.jar!/:42.5.0]
	at org.postgresql.jdbc.PgPreparedStatement.executeUpdate(PgPreparedStatement.java:152) ~[postgresql-42.5.0.jar!/:42.5.0]
	at com.zaxxer.hikari.pool.ProxyPreparedStatement.executeUpdate(ProxyPreparedStatement.java:61) ~[HikariCP-4.0.3.jar!/:na]
	at com.zaxxer.hikari.pool.HikariProxyPreparedStatement.executeUpdate(HikariProxyPreparedStatement.java) ~[HikariCP-4.0.3.jar!/:na]
	at org.hibernate.engine.jdbc.internal.ResultSetReturnImpl.executeUpdate(ResultSetReturnImpl.java:197) ~[hibernate-core-5.6.12.Final.jar!/:5.6.12.Final]
	... 35 common frames omitted

2022-11-23 16:46:47.822  WARN 1 --- [agaProcessor]-0] o.a.e.TrackingEventProcessor             : Releasing claim on token and preparing for retry in 1s
2022-11-23 16:46:47.838  INFO 1 --- [agaProcessor]-0] o.a.e.TrackingEventProcessor             : Released claim
2022-11-23 16:46:48.873  INFO 1 --- [agaProcessor]-0] o.a.e.TrackingEventProcessor             : Fetched token: IndexTrackingToken{globalIndex=0} for segment: Segment[0/0]
2022-11-23 16:46:48.909  WARN 1 --- [agaProcessor]-0] o.h.engine.jdbc.spi.SqlExceptionHelper   : SQL Error: 0, SQLState: 22001
2022-11-23 16:46:48.910 ERROR 1 --- [agaProcessor]-0] o.h.engine.jdbc.spi.SqlExceptionHelper   : ERROR: value too long for type character varying(255)
2022-11-23 16:46:48.910  INFO 1 --- [agaProcessor]-0] o.h.e.j.b.internal.AbstractBatchImpl     : HHH000010: On release of batch it still contained JDBC statements
2

Seems like the root cause is: : ERROR: value too long for type character varying(255). So you need to change either the schema of how the Saga is stored, or prevent that string from becoming to large.

3

Thanks for the quick reply Gerard,

That’s interesting.

Axon is responsible for the saga schema persistence when Jpa is involved/autoconfigured. It could be a bug with version 4.6.1+

4

If you are on 4.6.1 of framework, 4.6.2 might fix it. It worked with the same code and same events with 4.5?

5

Turns out the error originated from a string being stored in the DB exceeding the default 255-character limit.
The error has nothing to do with Axon. I’m glad this nightmare is over.

Thanks, Gerard.