Asynchronous handling - DB deadlocks and concurrency issues

[Jakub Čech]

Hello, 

We have application written in Axon. So far we used synchronous processing and everything was fine. Now we switched to asychronous and we are trying to test our app with it. So I wrote simple test, which is sending commands to command bus parallely. For examle in threadPool=4 invoicationCount=20. I'm trying different scales as well. 

There are two (maybe) separate problems: 

1. 

We are getting DB deadlocks (postgresql). Most often in SagaRepository, but just probably because its used heavily. I was able to spot deadlocks in different repositories as well. Deadlock exeption:

javax.persistence.PersistenceException: org.hibernate.exception.LockAcquisitionException: could not execute statement

at org.hibernate.jpa.spi.AbstractEntityManagerImpl.convert(AbstractEntityManagerImpl.java:1763) ~[hibernate-entitymanager-4.3.5.Final.jar:4.3.5.Final]

at org.hibernate.jpa.spi.AbstractEntityManagerImpl.convert(AbstractEntityManagerImpl.java:1677) ~[hibernate-entitymanager-4.3.5.Final.jar:4.3.5.Final]

at org.hibernate.jpa.spi.AbstractEntityManagerImpl.throwPersistenceException(AbstractEntityManagerImpl.java:1771) ~[hibernate-entitymanager-4.3.5.Final.jar:4.3.5.Final]

at org.hibernate.jpa.spi.AbstractQueryImpl.executeUpdate(AbstractQueryImpl.java:87) ~[hibernate-entitymanager-4.3.5.Final.jar:4.3.5.Final]

at org.axonframework.saga.repository.jpa.JpaSagaRepository.updateSaga(JpaSagaRepository.java:173) ~[axon-core-2.3.1.jar:2.3.1]

at org.axonframework.saga.repository.AbstractSagaRepository.commit(AbstractSagaRepository.java:69) ~[axon-core-2.3.1.jar:2.3.1]

at org.axonframework.saga.annotation.AsyncSagaEventProcessor.persistProcessedSagas(AsyncSagaEventProcessor.java:221) [axon-core-2.3.1.jar:2.3.1]

at org.axonframework.saga.annotation.AsyncSagaEventProcessor.doProcessEvent(AsyncSagaEventProcessor.java:147) [axon-core-2.3.1.jar:2.3.1]

at org.axonframework.saga.annotation.AsyncSagaEventProcessor.onEvent(AsyncSagaEventProcessor.java:118) [axon-core-2.3.1.jar:2.3.1]

at org.axonframework.saga.annotation.AsyncSagaEventProcessor.onEvent(AsyncSagaEventProcessor.java:49) [axon-core-2.3.1.jar:2.3.1]

at com.lmax.disruptor.BatchEventProcessor.run(BatchEventProcessor.java:133) [disruptor-3.2.0.jar:na]

at org.axonframework.saga.annotation.AsyncAnnotatedSagaManager$StartDetectingRunnable.run(AsyncAnnotatedSagaManager.java:478) [axon-core-2.3.1.jar:2.3.1]

at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145) [na:1.7.0_67]

at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615) [na:1.7.0_67]

at java.lang.Thread.run(Thread.java:745) [na:1.7.0_67]

Caused by: org.hibernate.exception.LockAcquisitionException: could not execute statement

at org.hibernate.dialect.PostgreSQL81Dialect$2.convert(PostgreSQL81Dialect.java:416) ~[hibernate-core-4.3.5.Final.jar:4.3.5.Final]

at org.hibernate.exception.internal.StandardSQLExceptionConverter.convert(StandardSQLExceptionConverter.java:49) ~[hibernate-core-4.3.5.Final.jar:4.3.5.Final]

at org.hibernate.engine.jdbc.spi.SqlExceptionHelper.convert(SqlExceptionHelper.java:126) ~[hibernate-core-4.3.5.Final.jar:4.3.5.Final]

at org.hibernate.engine.jdbc.spi.SqlExceptionHelper.convert(SqlExceptionHelper.java:112) ~[hibernate-core-4.3.5.Final.jar:4.3.5.Final]

at org.hibernate.engine.jdbc.internal.ResultSetReturnImpl.executeUpdate(ResultSetReturnImpl.java:190) ~[hibernate-core-4.3.5.Final.jar:4.3.5.Final]

at org.hibernate.engine.jdbc.batch.internal.NonBatchingBatch.addToBatch(NonBatchingBatch.java:62) ~[hibernate-core-4.3.5.Final.jar:4.3.5.Final]

at org.hibernate.persister.entity.AbstractEntityPersister.update(AbstractEntityPersister.java:3281) ~[hibernate-core-4.3.5.Final.jar:4.3.5.Final]

at org.hibernate.persister.entity.AbstractEntityPersister.updateOrInsert(AbstractEntityPersister.java:3183) ~[hibernate-core-4.3.5.Final.jar:4.3.5.Final]

at org.hibernate.persister.entity.AbstractEntityPersister.update(AbstractEntityPersister.java:3525) ~[hibernate-core-4.3.5.Final.jar:4.3.5.Final]

at org.hibernate.action.internal.EntityUpdateAction.execute(EntityUpdateAction.java:159) ~[hibernate-core-4.3.5.Final.jar:4.3.5.Final]

at org.hibernate.engine.spi.ActionQueue.executeActions(ActionQueue.java:463) ~[hibernate-core-4.3.5.Final.jar:4.3.5.Final]

at org.hibernate.engine.spi.ActionQueue.executeActions(ActionQueue.java:349) ~[hibernate-core-4.3.5.Final.jar:4.3.5.Final]

at org.hibernate.event.internal.AbstractFlushingEventListener.performExecutions(AbstractFlushingEventListener.java:350) ~[hibernate-core-4.3.5.Final.jar:4.3.5.Final]

at org.hibernate.event.internal.DefaultAutoFlushEventListener.onAutoFlush(DefaultAutoFlushEventListener.java:67) ~[hibernate-core-4.3.5.Final.jar:4.3.5.Final]

at org.hibernate.internal.SessionImpl.autoFlushIfRequired(SessionImpl.java:1191) ~[hibernate-core-4.3.5.Final.jar:4.3.5.Final]

at org.hibernate.internal.SessionImpl.executeUpdate(SessionImpl.java:1281) ~[hibernate-core-4.3.5.Final.jar:4.3.5.Final]

at org.hibernate.internal.QueryImpl.executeUpdate(QueryImpl.java:118) ~[hibernate-core-4.3.5.Final.jar:4.3.5.Final]

at org.hibernate.jpa.internal.QueryImpl.internalExecuteUpdate(QueryImpl.java:371) ~[hibernate-entitymanager-4.3.5.Final.jar:4.3.5.Final]

at org.hibernate.jpa.spi.AbstractQueryImpl.executeUpdate(AbstractQueryImpl.java:78) ~[hibernate-entitymanager-4.3.5.Final.jar:4.3.5.Final]

... 11 common frames omitted

Caused by: org.postgresql.util.PSQLException: ERROR: deadlock detected

  Detail: Process 5040 waits for ShareLock on transaction 83222; blocked by process 9160.

Process 9160 waits for ExclusiveLock on tuple (0,153) of relation 79072 of database 19886; blocked by process 5040.

  Hint: See server log for query details.

at org.postgresql.core.v3.QueryExecutorImpl.receiveErrorResponse(QueryExecutorImpl.java:2157) ~[postgresql-9.2-1002.jdbc4.jar:na]

at org.postgresql.core.v3.QueryExecutorImpl.processResults(QueryExecutorImpl.java:1886) ~[postgresql-9.2-1002.jdbc4.jar:na]

at org.postgresql.core.v3.QueryExecutorImpl.execute(QueryExecutorImpl.java:255) ~[postgresql-9.2-1002.jdbc4.jar:na]

at org.postgresql.jdbc2.AbstractJdbc2Statement.execute(AbstractJdbc2Statement.java:555) ~[postgresql-9.2-1002.jdbc4.jar:na]

at org.postgresql.jdbc2.AbstractJdbc2Statement.executeWithFlags(AbstractJdbc2Statement.java:417) ~[postgresql-9.2-1002.jdbc4.jar:na]

at org.postgresql.jdbc2.AbstractJdbc2Statement.executeUpdate(AbstractJdbc2Statement.java:363) ~[postgresql-9.2-1002.jdbc4.jar:na]

at com.mchange.v2.c3p0.impl.NewProxyPreparedStatement.executeUpdate(NewProxyPreparedStatement.java:1423) ~[c3p0-0.9.5-pre8.jar:0.9.5-pre8]

at org.hibernate.engine.jdbc.internal.ResultSetReturnImpl.executeUpdate(ResultSetReturnImpl.java:187) ~[hibernate-core-4.3.5.Final.jar:4.3.5.Final]

... 25 common frames omitted

2.

Another problem is that commands which I sending are manipulating with some amount (among other things). And when I send 50 commands - amount should be increased by 50. But its just for example 40 (When there is no deadlock of course :-) ). As I was debugging this, I was able to tell that one thread incereases amount from 0 to 1, but another thread still see 0 and increases the value also to 1. Everything else looks fine. BusinessTransactions and Sagas are finished, other data looks fine. But this amount is on one shared Aggregate root and is manupulated by multiple threads/commands. Of course - bigger the thread pool is - the money lost is bigger :-)

From both problems I suspect transactions, but I'm not really sure. I would appreciate  maybe hint how to deal with transactions in Axon. 

Our project setup is probably typical - Spring, Hibernate, DB - posgreSQL

If more configuration details are needed - just tell. 

Thanks :-)

[Allard Buijze]

Hi Jakub,

this may be caused by the locking granularity in the database. I don't know what the default locking mechanism of postgres is, but many databases use page locks. If two sagas are on the same page, they can get in trouble. Part of this trouble is caused by the fact that Axon will query from a Saga (by default taking a readlock) and then updating it, requiring the database to upgrade the lock to a write lock. Put them on the same page and they'll start a fight.

I'll have a look at using write locks (SELECT FOR UPDATE) for the repositories instead. Until then, you can try setting the lock-level to row level locking on your database.

As for item 2, do you use event sourcing? My guess is that you don't. The issue is most likely to be found in the transaction isolation. Many databases use repeatable read by default, where the state as it was when you started the transaction (i.e. opened the connection). Since another thread is changing the counter, this is invisible. You can work around this issue by enforcing read-committed or read-uncommitted isolation levels on your connections.

Hope this helps.

Cheers,

Allard

--
You received this message because you are subscribed to the Google Groups "Axon Framework Users" group.
To unsubscribe from this group and stop receiving emails from it, send an email to axonframewor...@googlegroups.com.
For more options, visit https://groups.google.com/d/optout.

[Jakub Čech]

Hello again, 

So far I was not able to do with it much :(. 

We at least catched our bad configuration. We are using optimistic lock and it was configured badly. Now it seems that it's working correctly. Now we have other issues :-)  We are getting few different exceptions: 

org.springframework.orm.hibernate3.HibernateOptimisticLockingFailureException: Object of class [com.lbss.charging.ar.domain.model.account.receivable.ReceivableSubAccount] with identifier [-4136417867535856253]: optimistic locking failed; nested exception is org.hibernate.StaleObjectStateException: Row was updated or deleted by another transaction (or unsaved-value mapping was incorrect) : [com.lbss.charging.ar.domain.model.account.receivable.ReceivableSubAccount#-4136417867535856253]

at org.springframework.orm.hibernate3.SessionFactoryUtils.convertHibernateAccessException(SessionFactoryUtils.java:683) ~[spring-orm-3.2.4.RELEASE.jar:3.2.4.RELEASE]

at org.springframework.orm.jpa.vendor.HibernateJpaDialect.translateExceptionIfPossible(HibernateJpaDialect.java:106) ~[spring-orm-3.2.4.RELEASE.jar:3.2.4.RELEASE]

at org.springframework.orm.jpa.JpaTransactionManager.doCommit(JpaTransactionManager.java:517) ~[spring-orm-3.2.4.RELEASE.jar:3.2.4.RELEASE]

at org.springframework.transaction.support.AbstractPlatformTransactionManager.processCommit(AbstractPlatformTransactionManager.java:755) ~[spring-tx-3.2.4.RELEASE.jar:3.2.4.RELEASE]

at org.springframework.transaction.support.AbstractPlatformTransactionManager.commit(AbstractPlatformTransactionManager.java:724) ~[spring-tx-3.2.4.RELEASE.jar:3.2.4.RELEASE]

at org.axonframework.unitofwork.SpringTransactionManager.commitTransaction(SpringTransactionManager.java:73) ~[axon-core-2.3.1.jar:2.3.1]

at org.axonframework.unitofwork.SpringTransactionManager.commitTransaction(SpringTransactionManager.java:32) ~[axon-core-2.3.1.jar:2.3.1]

at org.axonframework.unitofwork.DefaultUnitOfWork.doCommit(DefaultUnitOfWork.java:145) ~[axon-core-2.3.1.jar:2.3.1]

at org.axonframework.unitofwork.NestableUnitOfWork.commit(NestableUnitOfWork.java:59) ~[axon-core-2.3.1.jar:2.3.1]

at org.axonframework.saga.annotation.AsyncSagaEventProcessor.persistProcessedSagas(AsyncSagaEventProcessor.java:227) [axon-core-2.3.1.jar:2.3.1]

at org.axonframework.saga.annotation.AsyncSagaEventProcessor.doProcessEvent(AsyncSagaEventProcessor.java:147) [axon-core-2.3.1.jar:2.3.1]

at org.axonframework.saga.annotation.AsyncSagaEventProcessor.onEvent(AsyncSagaEventProcessor.java:118) [axon-core-2.3.1.jar:2.3.1]

at org.axonframework.saga.annotation.AsyncSagaEventProcessor.onEvent(AsyncSagaEventProcessor.java:49) [axon-core-2.3.1.jar:2.3.1]

at com.lmax.disruptor.BatchEventProcessor.run(BatchEventProcessor.java:133) [disruptor-3.2.0.jar:na]

at org.axonframework.saga.annotation.AsyncAnnotatedSagaManager$StartDetectingRunnable.run(AsyncAnnotatedSagaManager.java:478) [axon-core-2.3.1.jar:2.3.1]

at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145) [na:1.7.0_67]

at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615) [na:1.7.0_67]

at java.lang.Thread.run(Thread.java:745) [na:1.7.0_67]

Caused by: org.hibernate.StaleObjectStateException: Row was updated or deleted by another transaction (or unsaved-value mapping was incorrect) : [com.lbss.charging.ar.domain.model.account.receivable.ReceivableSubAccount#-4136417867535856253]

at org.hibernate.persister.entity.AbstractEntityPersister.check(AbstractEntityPersister.java:2541) ~[hibernate-core-4.3.5.Final.jar:4.3.5.Final]

at org.hibernate.persister.entity.AbstractEntityPersister.update(AbstractEntityPersister.java:3285) ~[hibernate-core-4.3.5.Final.jar:4.3.5.Final]

at org.hibernate.persister.entity.AbstractEntityPersister.updateOrInsert(AbstractEntityPersister.java:3183) ~[hibernate-core-4.3.5.Final.jar:4.3.5.Final]

at org.hibernate.persister.entity.AbstractEntityPersister.update(AbstractEntityPersister.java:3525) ~[hibernate-core-4.3.5.Final.jar:4.3.5.Final]

at org.hibernate.action.internal.EntityUpdateAction.execute(EntityUpdateAction.java:159) ~[hibernate-core-4.3.5.Final.jar:4.3.5.Final]

at org.hibernate.engine.spi.ActionQueue.executeActions(ActionQueue.java:463) ~[hibernate-core-4.3.5.Final.jar:4.3.5.Final]

at org.hibernate.engine.spi.ActionQueue.executeActions(ActionQueue.java:349) ~[hibernate-core-4.3.5.Final.jar:4.3.5.Final]

at org.hibernate.event.internal.AbstractFlushingEventListener.performExecutions(AbstractFlushingEventListener.java:350) ~[hibernate-core-4.3.5.Final.jar:4.3.5.Final]

at org.hibernate.event.internal.DefaultFlushEventListener.onFlush(DefaultFlushEventListener.java:56) ~[hibernate-core-4.3.5.Final.jar:4.3.5.Final]

at org.hibernate.internal.SessionImpl.flush(SessionImpl.java:1222) ~[hibernate-core-4.3.5.Final.jar:4.3.5.Final]

at org.hibernate.internal.SessionImpl.managedFlush(SessionImpl.java:425) ~[hibernate-core-4.3.5.Final.jar:4.3.5.Final]

at org.hibernate.engine.transaction.internal.jdbc.JdbcTransaction.beforeTransactionCommit(JdbcTransaction.java:101) ~[hibernate-core-4.3.5.Final.jar:4.3.5.Final]

at org.hibernate.engine.transaction.spi.AbstractTransactionImpl.commit(AbstractTransactionImpl.java:177) ~[hibernate-core-4.3.5.Final.jar:4.3.5.Final]

at org.hibernate.jpa.internal.TransactionImpl.commit(TransactionImpl.java:77) ~[hibernate-entitymanager-4.3.5.Final.jar:4.3.5.Final]

at org.springframework.orm.jpa.JpaTransactionManager.doCommit(JpaTransactionManager.java:513) ~[spring-orm-3.2.4.RELEASE.jar:3.2.4.RELEASE]

... 15 common frames omitted

javax.persistence.EntityExistsException: A different object with the same identifier value was already associated with the session : [org.axonframework.saga.repository.jpa.SagaEntry#97a0ee37-1d22-4fcc-8987-8c41d9010181]

at org.hibernate.jpa.spi.AbstractEntityManagerImpl.convert(AbstractEntityManagerImpl.java:1735) ~[hibernate-entitymanager-4.3.5.Final.jar:4.3.5.Final]

at org.hibernate.jpa.spi.AbstractEntityManagerImpl.convert(AbstractEntityManagerImpl.java:1677) ~[hibernate-entitymanager-4.3.5.Final.jar:4.3.5.Final]

at org.hibernate.jpa.spi.AbstractEntityManagerImpl.convert(AbstractEntityManagerImpl.java:1683) ~[hibernate-entitymanager-4.3.5.Final.jar:4.3.5.Final]

at org.hibernate.jpa.spi.AbstractEntityManagerImpl.persist(AbstractEntityManagerImpl.java:1187) ~[hibernate-entitymanager-4.3.5.Final.jar:4.3.5.Final]

at sun.reflect.GeneratedMethodAccessor124.invoke(Unknown Source) ~[na:na]

at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[na:1.7.0_67]

at java.lang.reflect.Method.invoke(Method.java:606) ~[na:1.7.0_67]

at org.springframework.orm.jpa.SharedEntityManagerCreator$SharedEntityManagerInvocationHandler.invoke(SharedEntityManagerCreator.java:241) ~[spring-orm-3.2.4.RELEASE.jar:3.2.4.RELEASE]

at com.sun.proxy.$Proxy110.persist(Unknown Source) ~[na:na]

at org.axonframework.saga.repository.jpa.JpaSagaRepository.storeSaga(JpaSagaRepository.java:195) ~[axon-core-2.3.1.jar:2.3.1]

at org.axonframework.saga.repository.AbstractSagaRepository.add(AbstractSagaRepository.java:51) ~[axon-core-2.3.1.jar:2.3.1]

at org.axonframework.saga.annotation.AsyncSagaEventProcessor.persistProcessedSagas(AsyncSagaEventProcessor.java:219) [axon-core-2.3.1.jar:2.3.1]

at org.axonframework.saga.annotation.AsyncSagaEventProcessor.doProcessEvent(AsyncSagaEventProcessor.java:147) [axon-core-2.3.1.jar:2.3.1]

at org.axonframework.saga.annotation.AsyncSagaEventProcessor.onEvent(AsyncSagaEventProcessor.java:118) [axon-core-2.3.1.jar:2.3.1]

at org.axonframework.saga.annotation.AsyncSagaEventProcessor.onEvent(AsyncSagaEventProcessor.java:49) [axon-core-2.3.1.jar:2.3.1]

at com.lmax.disruptor.BatchEventProcessor.run(BatchEventProcessor.java:133) [disruptor-3.2.0.jar:na]

at org.axonframework.saga.annotation.AsyncAnnotatedSagaManager$StartDetectingRunnable.run(AsyncAnnotatedSagaManager.java:478) [axon-core-2.3.1.jar:2.3.1]

at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145) [na:1.7.0_67]

at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615) [na:1.7.0_67]

at java.lang.Thread.run(Thread.java:745) [na:1.7.0_67]

These are just two most interesting ones. Next to it are exceptions relating to business transaction and which doesnt make sence (synchronously).  Like : 

javax.persistence.NoResultException: No entity found for query

nullpointers, business exceptions (like we are paying invoice which is not in correct state yet). But from synchronous point of view it doesnt not any make sense - at least in this simple test scenario. But these I will try debug now. 

Plus I have feeling that deadlocks are gone just because of these other exceptions - maybe deadlocks just wont occur until this is fixed :-)

And to item 2:

You are correct, we don't use event sourcing, I tried to change isolation level on hibernate but no change at all. But I think I can put this on hold since first problem is now causing much more troubles. 

¨

I will update this topic when I am able to tell more. 

Thanks for your time :-)

Jakub

[Jakub Čech]

Ok so I gave it a little more time to study our app and axon (good point to say that this is not my creation). 

I rewrote a Repository to GenericJpaRepositories + now we using Axon's AbstractAggregateRoot. So far was both only our implementation - not done any locking etc..  DB deadlocks are gone now - thats fine.

But I still getting number of other exceptions  like:

org.springframework.transaction.TransactionSystemException: Could not commit JPA transaction; nested exception is javax.persistence.RollbackException: Transaction marked as rollbackOnly

at org.springframework.orm.jpa.JpaTransactionManager.doCommit(JpaTransactionManager.java:522) ~[spring-orm-3.2.4.RELEASE.jar:3.2.4.RELEASE]

at org.springframework.transaction.support.AbstractPlatformTransactionManager.processCommit(AbstractPlatformTransactionManager.java:755) ~[spring-tx-3.2.4.RELEASE.jar:3.2.4.RELEASE]

at org.springframework.transaction.support.AbstractPlatformTransactionManager.commit(AbstractPlatformTransactionManager.java:724) ~[spring-tx-3.2.4.RELEASE.jar:3.2.4.RELEASE]

at org.axonframework.unitofwork.SpringTransactionManager.commitTransaction(SpringTransactionManager.java:73) ~[axon-core-2.3.1.jar:2.3.1]

at org.axonframework.unitofwork.SpringTransactionManager.commitTransaction(SpringTransactionManager.java:32) ~[axon-core-2.3.1.jar:2.3.1]

at org.axonframework.unitofwork.DefaultUnitOfWork.doCommit(DefaultUnitOfWork.java:145) ~[axon-core-2.3.1.jar:2.3.1]

at org.axonframework.unitofwork.NestableUnitOfWork.commit(NestableUnitOfWork.java:59) ~[axon-core-2.3.1.jar:2.3.1]

at org.axonframework.saga.annotation.AsyncSagaEventProcessor.persistProcessedSagas(AsyncSagaEventProcessor.java:227) [axon-core-2.3.1.jar:2.3.1]

at org.axonframework.saga.annotation.AsyncSagaEventProcessor.doProcessEvent(AsyncSagaEventProcessor.java:147) [axon-core-2.3.1.jar:2.3.1]

at org.axonframework.saga.annotation.AsyncSagaEventProcessor.onEvent(AsyncSagaEventProcessor.java:118) [axon-core-2.3.1.jar:2.3.1]

at org.axonframework.saga.annotation.AsyncSagaEventProcessor.onEvent(AsyncSagaEventProcessor.java:49) [axon-core-2.3.1.jar:2.3.1]

at com.lmax.disruptor.BatchEventProcessor.run(BatchEventProcessor.java:133) [disruptor-3.2.0.jar:na]

at org.axonframework.saga.annotation.AsyncAnnotatedSagaManager$StartDetectingRunnable.run(AsyncAnnotatedSagaManager.java:478) [axon-core-2.3.1.jar:2.3.1]

at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145) [na:1.7.0_67]

at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615) [na:1.7.0_67]

at java.lang.Thread.run(Thread.java:745) [na:1.7.0_67]

Caused by: javax.persistence.RollbackException: Transaction marked as rollbackOnly

at org.hibernate.jpa.internal.TransactionImpl.commit(TransactionImpl.java:74) ~[hibernate-entitymanager-4.3.5.Final.jar:4.3.5.Final]

at org.springframework.orm.jpa.JpaTransactionManager.doCommit(JpaTransactionManager.java:513) ~[spring-orm-3.2.4.RELEASE.jar:3.2.4.RELEASE]

... 15 common frames omitted

javax.persistence.EntityExistsException: A different object with the same identifier value was already associated with the session : [org.axonframework.saga.repository.jpa.SagaEntry#dd492c08-6d94-4ea8-9e08-46c6215ea9ee]

at org.hibernate.jpa.spi.AbstractEntityManagerImpl.convert(AbstractEntityManagerImpl.java:1735) ~[hibernate-entitymanager-4.3.5.Final.jar:4.3.5.Final]

at org.hibernate.jpa.spi.AbstractEntityManagerImpl.convert(AbstractEntityManagerImpl.java:1677) ~[hibernate-entitymanager-4.3.5.Final.jar:4.3.5.Final]

at org.hibernate.jpa.spi.AbstractEntityManagerImpl.convert(AbstractEntityManagerImpl.java:1683) ~[hibernate-entitymanager-4.3.5.Final.jar:4.3.5.Final]

at org.hibernate.jpa.spi.AbstractEntityManagerImpl.persist(AbstractEntityManagerImpl.java:1187) ~[hibernate-entitymanager-4.3.5.Final.jar:4.3.5.Final]

at sun.reflect.GeneratedMethodAccessor101.invoke(Unknown Source) ~[na:na]

at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[na:1.7.0_67]

at java.lang.reflect.Method.invoke(Method.java:606) ~[na:1.7.0_67]

at org.springframework.orm.jpa.SharedEntityManagerCreator$SharedEntityManagerInvocationHandler.invoke(SharedEntityManagerCreator.java:241) ~[spring-orm-3.2.4.RELEASE.jar:3.2.4.RELEASE]

at com.sun.proxy.$Proxy112.persist(Unknown Source) ~[na:na]

at org.axonframework.saga.repository.jpa.JpaSagaRepository.storeSaga(JpaSagaRepository.java:195) ~[axon-core-2.3.1.jar:2.3.1]

at org.axonframework.saga.repository.AbstractSagaRepository.add(AbstractSagaRepository.java:51) ~[axon-core-2.3.1.jar:2.3.1]

at org.axonframework.saga.annotation.AsyncSagaEventProcessor.persistProcessedSagas(AsyncSagaEventProcessor.java:219) [axon-core-2.3.1.jar:2.3.1]

at org.axonframework.saga.annotation.AsyncSagaEventProcessor.doProcessEvent(AsyncSagaEventProcessor.java:147) [axon-core-2.3.1.jar:2.3.1]

at org.axonframework.saga.annotation.AsyncSagaEventProcessor.onEvent(AsyncSagaEventProcessor.java:118) [axon-core-2.3.1.jar:2.3.1]

at org.axonframework.saga.annotation.AsyncSagaEventProcessor.onEvent(AsyncSagaEventProcessor.java:49) [axon-core-2.3.1.jar:2.3.1]

at com.lmax.disruptor.BatchEventProcessor.run(BatchEventProcessor.java:133) [disruptor-3.2.0.jar:na]

at org.axonframework.saga.annotation.AsyncAnnotatedSagaManager$StartDetectingRunnable.run(AsyncAnnotatedSagaManager.java:478) [axon-core-2.3.1.jar:2.3.1]

at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145) [na:1.7.0_67]

at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615) [na:1.7.0_67]

at java.lang.Thread.run(Thread.java:745) [na:1.7.0_67]

I'm kinda stuck with these two. And as I said I'm not using Axon so long. Maybe I'm just missing out some configuration or something.

Thanks for your help.

Jakub

[Allard Buijze]

Hi Jakub,

there is a chance both exceptions are related. The first happens when a transaction is committed that has been marked for rollback. The mark happens when (among others), the EntityManager throws an exception.

The second exception could be the source for the rollback. This exception means that a saga was added to the repository which was already present. Did you write any custom code in the saga manager or repository?

Cheers,

Allard

[Jakub Čech]

Yes, in fact we have custom JpaSagaRepository - well it's just copy paste of Axon's JpaSagaRepository + added @Transactional annotation - I was told that it's because of some postgresql problem with loading large objects. But it doesn't seems to make any difference if I use original.. What did I notice is use-explicit-flush="false". And when I change this to true then it really does behave a little bit differently. These two exceptions are gone, but I get few :

javax.persistence.OptimisticLockException: Row was updated or deleted by another transaction

org.axonframework.repository.ConcurrencyException: The aggregate of type [ReceivableSubAccount] with identifier [3558364230739182868] could not be saved, as a valid lock is not held. Either another thread has saved an aggregate, or the current thread had released its lock earlier on.

And ok, this is possible to happen in concurrency environment I guess, but at the end of processing I end up in cycle  in AsyncSagaEventProcessor's retry procedure :

Hibernate: select nextval ('hibernate_sequence')

Hibernate: insert into AssociationValueEntry (associationKey, associationValue, sagaId, sagaType, id) values (?, ?, ?, ?, ?)

Hibernate: update BUSINESS_TRANSACTION set LASTEVENTSEQUENCENUMBER=?, CONCURRENCY_VERSION=?, DATE_STARTED=?, FAILED_COMMAND=?, KIND=?, LONG_VALUE_ID=?, ENTRY_CHANNEL_ID=?, STATE=?, STATE_MESSAGE=?, STRING_VALUE_ID=? where TRANSACTION_ID=? and CONCURRENCY_VERSION=?

10:10:07.421 [taskExecutor-5] org.axonframework.saga.annotation.AsyncSagaEventProcessor - Waiting 2000ms for next attempt

10:10:07.535 [taskExecutor-2] org.axonframework.saga.repository.jpa.JpaSagaRepository - Updating saga id 4a8cbb7d-8070-48bc-908d-0e3ec222a40d as <com.lbss.charging.ar.application.event.saga.InvoicePostingSaga><associations><values class="java.util.concurrent.CopyOnWriteArraySet"><al serialization="custom"><java.util.concurrent.CopyOnWriteArrayList><default/><int>2</int><association><key>sagaIdentifier</key><value>4a8cbb7d-8070-48bc-908d-0e3ec222a40d</value></association><association><key>transactionId</key><value>Persistence id: 3321</value></association></java.util.concurrent.CopyOnWriteArrayList></al></values></associations><identifier>4a8cbb7d-8070-48bc-908d-0e3ec222a40d</identifier><isActive>true</isActive><logger class="ch.qos.logback.classic.Logger"><name>com.lbss.charging.ar.application.event.saga.InvoicePostingSaga</name></logger><enterInvoiceBody><customerAccountId>-1549379481395838055</customerAccountId><invoiceId>-1899499968302399413</invoiceId><invoiceNumber>7c23455e-a2cd-4</invoiceNumber><invoiceKind>Onetime</invoiceKind><billingPeriod><start>2015-05-13 08:09:40.58 UTC</start><end>2015-05-13 08:09:40.58 UTC</end></billingPeriod><issueDate>2015-05-13 08:09:40.58 UTC</issueDate><dueDate>2015-05-24 21:56:20.58 UTC</dueDate><totalAmount><amount>10.00</amount><currencyCode>EUR</currencyCode></totalAmount><roundingDifference>0</roundingDifference><charges class="java.util.Arrays$ArrayList"><a class="com.lbss.charging.ar.api.invoice.data.FinancialCharge-array"><com.lbss.charging.ar.api.invoice.data.FinancialCharge><billingServiceCode>SA</billingServiceCode><totalAmount reference="../../../../totalAmount"/></com.lbss.charging.ar.api.invoice.data.FinancialCharge></a></charges><remittanceDetails class="java.util.Arrays$ArrayList"><a class="com.lbss.api.common.Property-array"><com.lbss.api.common.Property><code>a</code><value class="string">b</value></com.lbss.api.common.Property></a></remittanceDetails></enterInvoiceBody><invoiceId><id>2224</id></invoiceId><amount><amount>10.00</amount><metric class="com.lbss.commons.reference.dto.Currency"><code>EUR</code><phrases/><majorUnitSymbol>€</majorUnitSymbol><minorUnitSymbol>c</minorUnitSymbol><numericCode>978</numericCode><ratioOfMinorUnitToMajorUnit>100</ratioOfMinorUnitToMajorUnit></metric></amount><accountId><id>-1549379481395838055</id></accountId></com.lbss.charging.ar.application.event.saga.InvoicePostingSaga>

Hibernate: update BUSINESS_TRANSACTION set LASTEVENTSEQUENCENUMBER=?, CONCURRENCY_VERSION=?, DATE_STARTED=?, FAILED_COMMAND=?, KIND=?, LONG_VALUE_ID=?, ENTRY_CHANNEL_ID=?, STATE=?, STATE_MESSAGE=?, STRING_VALUE_ID=? where TRANSACTION_ID=? and CONCURRENCY_VERSION=?

10:10:07.538 [taskExecutor-2] org.axonframework.saga.annotation.AsyncSagaEventProcessor - Waiting 2000ms for next attempt

Hibernate: select nextval ('hibernate_sequence')

Hibernate: insert into AssociationValueEntry (associationKey, associationValue, sagaId, sagaType, id) values (?, ?, ?, ?, ?)

Hibernate: update BUSINESS_TRANSACTION set LASTEVENTSEQUENCENUMBER=?, CONCURRENCY_VERSION=?, DATE_STARTED=?, FAILED_COMMAND=?, KIND=?, LONG_VALUE_ID=?, ENTRY_CHANNEL_ID=?, STATE=?, STATE_MESSAGE=?, STRING_VALUE_ID=? where TRANSACTION_ID=? and CONCURRENCY_VERSION=?

10:10:09.426 [taskExecutor-5] org.axonframework.saga.annotation.AsyncSagaEventProcessor - Waiting 2000ms for next attempt

10:10:09.542 [taskExecutor-2] org.axonframework.saga.repository.jpa.JpaSagaRepository - Updating saga id 4a8cbb7d-8070-48bc-908d-0e3ec222a40d as <com.lbss.charging.ar.application.event.saga.InvoicePostingSaga><associations><values class="java.util.concurrent.CopyOnWriteArraySet"><al serialization="custom"><java.util.concurrent.CopyOnWriteArrayList><default/><int>2</int><association><key>sagaIdentifier</key><value>4a8cbb7d-8070-48bc-908d-0e3ec222a40d</value></association><association><key>transactionId</key><value>Persistence id: 3321</value></association></java.util.concurrent.CopyOnWriteArrayList></al></values></associations><identifier>4a8cbb7d-8070-48bc-908d-0e3ec222a40d</identifier><isActive>true</isActive><logger class="ch.qos.logback.classic.Logger"><name>com.lbss.charging.ar.application.event.saga.InvoicePostingSaga</name></logger><enterInvoiceBody><customerAccountId>-1549379481395838055</customerAccountId><invoiceId>-1899499968302399413</invoiceId><invoiceNumber>7c23455e-a2cd-4</invoiceNumber><invoiceKind>Onetime</invoiceKind><billingPeriod><start>2015-05-13 08:09:40.58 UTC</start><end>2015-05-13 08:09:40.58 UTC</end></billingPeriod><issueDate>2015-05-13 08:09:40.58 UTC</issueDate><dueDate>2015-05-24 21:56:20.58 UTC</dueDate><totalAmount><amount>10.00</amount><currencyCode>EUR</currencyCode></totalAmount><roundingDifference>0</roundingDifference><charges class="java.util.Arrays$ArrayList"><a class="com.lbss.charging.ar.api.invoice.data.FinancialCharge-array"><com.lbss.charging.ar.api.invoice.data.FinancialCharge><billingServiceCode>SA</billingServiceCode><totalAmount reference="../../../../totalAmount"/></com.lbss.charging.ar.api.invoice.data.FinancialCharge></a></charges><remittanceDetails class="java.util.Arrays$ArrayList"><a class="com.lbss.api.common.Property-array"><com.lbss.api.common.Property><code>a</code><value class="string">b</value></com.lbss.api.common.Property></a></remittanceDetails></enterInvoiceBody><invoiceId><id>2224</id></invoiceId><amount><amount>10.00</amount><metric class="com.lbss.commons.reference.dto.Currency"><code>EUR</code><phrases/><majorUnitSymbol>€</majorUnitSymbol><minorUnitSymbol>c</minorUnitSymbol><numericCode>978</numericCode><ratioOfMinorUnitToMajorUnit>100</ratioOfMinorUnitToMajorUnit></metric></amount><accountId><id>-1549379481395838055</id></accountId></com.lbss.charging.ar.application.event.saga.InvoicePostingSaga>

Hibernate: update BUSINESS_TRANSACTION set LASTEVENTSEQUENCENUMBER=?, CONCURRENCY_VERSION=?, DATE_STARTED=?, FAILED_COMMAND=?, KIND=?, LONG_VALUE_ID=?, ENTRY_CHANNEL_ID=?, STATE=?, STATE_MESSAGE=?, STRING_VALUE_ID=? where TRANSACTION_ID=? and CONCURRENCY_VERSION=?

10:10:09.546 [taskExecutor-2] org.axonframework.saga.annotation.AsyncSagaEventProcessor - Waiting 2000ms for next attempt

And it just go on and on.. Looks that won't end. 

[Allard Buijze]

OptimisticLockException... that sounds familiar. Which isolation level are you using on you database? Often, I see default being used, which is REPEATABLE_READ. In many cases, the result is that changes made by one thread, are invisible to the other, if the other thread had opened a connection to the database before the first thread did his commit. If you set isolation level to READ_COMMITTED, that problem doesn't exist. That's because Axon will block a thread from reading an aggregate until it has been committed by the thread currently owning it.

In the retry-loop of the AsyncSagaEventProcessor, I miss the actual exception. It should mention the exception that caused to to go into the retry-loop. Or is that the OptimisticLockException?

Cheers,

Allard

[Jakub Čech]

You are right that isolation level has influence on these exceptions. But when I set isolation to READ_UNCOMMITTED or READ_COMMITTED then I get this OptimisticLockException. When I set level to REPEATABLE_READ or SERIALIZABLE then I get worse exceptions : 

javax.persistence.PersistenceException: org.hibernate.exception.LockAcquisitionException: could not execute statement

at org.hibernate.jpa.spi.AbstractEntityManagerImpl.convert(AbstractEntityManagerImpl.java:1763) ~[hibernate-entitymanager-4.3.5.Final.jar:4.3.5.Final]

at org.hibernate.jpa.spi.AbstractEntityManagerImpl.convert(AbstractEntityManagerImpl.java:1677) ~[hibernate-entitymanager-4.3.5.Final.jar:4.3.5.Final]

at org.hibernate.jpa.spi.AbstractEntityManagerImpl.convert(AbstractEntityManagerImpl.java:1683) ~[hibernate-entitymanager-4.3.5.Final.jar:4.3.5.Final]

at org.hibernate.jpa.spi.AbstractEntityManagerImpl.flush(AbstractEntityManagerImpl.java:1338) ~[hibernate-entitymanager-4.3.5.Final.jar:4.3.5.Final]

at sun.reflect.GeneratedMethodAccessor111.invoke(Unknown Source) ~[na:na]

at sun.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source) ~[na:1.7.0_67]

at java.lang.reflect.Method.invoke(Unknown Source) ~[na:1.7.0_67]

at org.springframework.orm.jpa.SharedEntityManagerCreator$SharedEntityManagerInvocationHandler.invoke(SharedEntityManagerCreator.java:241) ~[spring-orm-3.2.4.RELEASE.jar:3.2.4.RELEASE]

at com.sun.proxy.$Proxy112.flush(Unknown Source) ~[na:na]

at org.axonframework.repository.GenericJpaRepository.doSaveWithLock(GenericJpaRepository.java:78) ~[axon-core-2.3.1.jar:2.3.1]

at org.axonframework.repository.LockingRepository.doSave(LockingRepository.java:128) ~[axon-core-2.3.1.jar:2.3.1]

at org.axonframework.repository.AbstractRepository$SimpleSaveAggregateCallback.save(AbstractRepository.java:169) ~[axon-core-2.3.1.jar:2.3.1]

at org.axonframework.unitofwork.DefaultUnitOfWork$AggregateEntry.saveAggregate(DefaultUnitOfWork.java:322) ~[axon-core-2.3.1.jar:2.3.1]

at org.axonframework.unitofwork.DefaultUnitOfWork.saveAggregates(DefaultUnitOfWork.java:287) ~[axon-core-2.3.1.jar:2.3.1]

at org.axonframework.unitofwork.NestableUnitOfWork.commit(NestableUnitOfWork.java:55) ~[axon-core-2.3.1.jar:2.3.1]

at org.axonframework.commandhandling.SimpleCommandBus.doDispatch(SimpleCommandBus.java:137) [axon-core-2.3.1.jar:2.3.1]

at org.axonframework.commandhandling.SimpleCommandBus.doDispatch(SimpleCommandBus.java:103) [axon-core-2.3.1.jar:2.3.1]

at org.axonframework.commandhandling.SimpleCommandBus.dispatch(SimpleCommandBus.java:75) [axon-core-2.3.1.jar:2.3.1]

at org.axonframework.commandhandling.gateway.AbstractCommandGateway.send(AbstractCommandGateway.java:81) [axon-core-2.3.1.jar:2.3.1]

at org.axonframework.commandhandling.gateway.AbstractCommandGateway.sendAndForget(AbstractCommandGateway.java:95) [axon-core-2.3.1.jar:2.3.1]

at org.axonframework.commandhandling.gateway.GatewayProxyFactory$DispatchOnInvocationHandler.invoke(GatewayProxyFactory.java:473) [axon-core-2.3.1.jar:2.3.1]

at org.axonframework.commandhandling.gateway.GatewayProxyFactory$DispatchOnInvocationHandler.invoke(GatewayProxyFactory.java:428) [axon-core-2.3.1.jar:2.3.1]

at org.axonframework.commandhandling.gateway.GatewayProxyFactory$FireAndForget.invoke(GatewayProxyFactory.java:636) [axon-core-2.3.1.jar:2.3.1]

at org.axonframework.commandhandling.gateway.GatewayProxyFactory$NullOnTimeout.invoke(GatewayProxyFactory.java:541) [axon-core-2.3.1.jar:2.3.1]

at org.axonframework.commandhandling.gateway.GatewayProxyFactory$NullOnInterrupted.invoke(GatewayProxyFactory.java:559) [axon-core-2.3.1.jar:2.3.1]

at org.axonframework.commandhandling.gateway.GatewayProxyFactory$WrapNonDeclaredCheckedExceptions.invoke(GatewayProxyFactory.java:516) [axon-core-2.3.1.jar:2.3.1]

at org.axonframework.commandhandling.gateway.GatewayProxyFactory$GatewayInvocationHandler.invoke(GatewayProxyFactory.java:423) [axon-core-2.3.1.jar:2.3.1]

at com.sun.proxy.$Proxy113.send(Unknown Source) [na:na]

at com.lbss.charging.ar.application.event.saga.InvoicePostingSaga.handle(InvoicePostingSaga.java:85) [classes/:na]

at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[na:1.7.0_67]

at sun.reflect.NativeMethodAccessorImpl.invoke(Unknown Source) ~[na:1.7.0_67]

at sun.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source) ~[na:1.7.0_67]

at java.lang.reflect.Method.invoke(Unknown Source) ~[na:1.7.0_67]

at org.axonframework.common.annotation.MethodMessageHandler.invoke(MethodMessageHandler.java:85) [axon-core-2.3.1.jar:2.3.1]

at org.axonframework.saga.annotation.SagaMethodMessageHandler.invoke(SagaMethodMessageHandler.java:214) [axon-core-2.3.1.jar:2.3.1]

at org.axonframework.saga.annotation.AbstractAnnotatedSaga.handle(AbstractAnnotatedSaga.java:80) [axon-core-2.3.1.jar:2.3.1]

at org.axonframework.saga.annotation.AsyncSagaEventProcessor.invokeExistingSagas(AsyncSagaEventProcessor.java:192) [axon-core-2.3.1.jar:2.3.1]

at org.axonframework.saga.annotation.AsyncSagaEventProcessor.doProcessEvent(AsyncSagaEventProcessor.java:126) [axon-core-2.3.1.jar:2.3.1]

at org.axonframework.saga.annotation.AsyncSagaEventProcessor.onEvent(AsyncSagaEventProcessor.java:118) [axon-core-2.3.1.jar:2.3.1]

at org.axonframework.saga.annotation.AsyncSagaEventProcessor.onEvent(AsyncSagaEventProcessor.java:49) [axon-core-2.3.1.jar:2.3.1]

at com.lmax.disruptor.BatchEventProcessor.run(BatchEventProcessor.java:133) [disruptor-3.2.0.jar:na]

at org.axonframework.saga.annotation.AsyncAnnotatedSagaManager$StartDetectingRunnable.run(AsyncAnnotatedSagaManager.java:478) [axon-core-2.3.1.jar:2.3.1]

at java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source) [na:1.7.0_67]

at java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source) [na:1.7.0_67]

at java.lang.Thread.run(Unknown Source) [na:1.7.0_67]

Caused by: org.hibernate.exception.LockAcquisitionException: could not execute statement

at org.hibernate.exception.internal.SQLStateConversionDelegate.convert(SQLStateConversionDelegate.java:140) ~[hibernate-core-4.3.5.Final.jar:4.3.5.Final]

at org.hibernate.exception.internal.StandardSQLExceptionConverter.convert(StandardSQLExceptionConverter.java:49) ~[hibernate-core-4.3.5.Final.jar:4.3.5.Final]

at org.hibernate.engine.jdbc.spi.SqlExceptionHelper.convert(SqlExceptionHelper.java:126) ~[hibernate-core-4.3.5.Final.jar:4.3.5.Final]

at org.hibernate.engine.jdbc.spi.SqlExceptionHelper.convert(SqlExceptionHelper.java:112) ~[hibernate-core-4.3.5.Final.jar:4.3.5.Final]

at org.hibernate.engine.jdbc.internal.ResultSetReturnImpl.executeUpdate(ResultSetReturnImpl.java:190) ~[hibernate-core-4.3.5.Final.jar:4.3.5.Final]

at org.hibernate.persister.entity.AbstractEntityPersister.update(AbstractEntityPersister.java:3285) ~[hibernate-core-4.3.5.Final.jar:4.3.5.Final]

at org.hibernate.persister.entity.AbstractEntityPersister.updateOrInsert(AbstractEntityPersister.java:3183) ~[hibernate-core-4.3.5.Final.jar:4.3.5.Final]

at org.hibernate.persister.entity.AbstractEntityPersister.update(AbstractEntityPersister.java:3525) ~[hibernate-core-4.3.5.Final.jar:4.3.5.Final]

at org.hibernate.action.internal.EntityUpdateAction.execute(EntityUpdateAction.java:159) ~[hibernate-core-4.3.5.Final.jar:4.3.5.Final]

at org.hibernate.engine.spi.ActionQueue.executeActions(ActionQueue.java:463) ~[hibernate-core-4.3.5.Final.jar:4.3.5.Final]

at org.hibernate.engine.spi.ActionQueue.executeActions(ActionQueue.java:349) ~[hibernate-core-4.3.5.Final.jar:4.3.5.Final]

at org.hibernate.event.internal.AbstractFlushingEventListener.performExecutions(AbstractFlushingEventListener.java:350) ~[hibernate-core-4.3.5.Final.jar:4.3.5.Final]

at org.hibernate.event.internal.DefaultFlushEventListener.onFlush(DefaultFlushEventListener.java:56) ~[hibernate-core-4.3.5.Final.jar:4.3.5.Final]

at org.hibernate.internal.SessionImpl.flush(SessionImpl.java:1222) ~[hibernate-core-4.3.5.Final.jar:4.3.5.Final]

at org.hibernate.jpa.spi.AbstractEntityManagerImpl.flush(AbstractEntityManagerImpl.java:1335) ~[hibernate-entitymanager-4.3.5.Final.jar:4.3.5.Final]

... 41 common frames omitted

Caused by: org.postgresql.util.PSQLException: ERROR: could not serialize access due to concurrent update

at org.postgresql.core.v3.QueryExecutorImpl.receiveErrorResponse(QueryExecutorImpl.java:2157) ~[postgresql-9.2-1002.jdbc4.jar:na]

at org.postgresql.core.v3.QueryExecutorImpl.processResults(QueryExecutorImpl.java:1886) ~[postgresql-9.2-1002.jdbc4.jar:na]

at org.postgresql.core.v3.QueryExecutorImpl.execute(QueryExecutorImpl.java:255) ~[postgresql-9.2-1002.jdbc4.jar:na]

at org.postgresql.jdbc2.AbstractJdbc2Statement.execute(AbstractJdbc2Statement.java:555) ~[postgresql-9.2-1002.jdbc4.jar:na]

at org.postgresql.jdbc2.AbstractJdbc2Statement.executeWithFlags(AbstractJdbc2Statement.java:417) ~[postgresql-9.2-1002.jdbc4.jar:na]

at org.postgresql.jdbc2.AbstractJdbc2Statement.executeUpdate(AbstractJdbc2Statement.java:363) ~[postgresql-9.2-1002.jdbc4.jar:na]

at com.mchange.v2.c3p0.impl.NewProxyPreparedStatement.executeUpdate(NewProxyPreparedStatement.java:1423) ~[c3p0-0.9.5-pre8.jar:0.9.5-pre8]

at org.hibernate.engine.jdbc.internal.ResultSetReturnImpl.executeUpdate(ResultSetReturnImpl.java:187) ~[hibernate-core-4.3.5.Final.jar:4.3.5.Final]

... 51 common frames omitted

and then lot of 

javax.persistence.PersistenceException: org.hibernate.exception.GenericJDBCException: could not extract ResultSet

at org.hibernate.jpa.spi.AbstractEntityManagerImpl.convert(AbstractEntityManagerImpl.java:1763) ~[hibernate-entitymanager-4.3.5.Final.jar:4.3.5.Final]

at org.hibernate.jpa.spi.AbstractEntityManagerImpl.convert(AbstractEntityManagerImpl.java:1677) ~[hibernate-entitymanager-4.3.5.Final.jar:4.3.5.Final]

at org.hibernate.jpa.internal.QueryImpl.getResultList(QueryImpl.java:458) ~[hibernate-entitymanager-4.3.5.Final.jar:4.3.5.Final]

at org.axonframework.saga.repository.jpa.JpaSagaRepository.findAssociatedSagaIdentifiers(JpaSagaRepository.java:133) ~[axon-core-2.3.1.jar:2.3.1]

at org.axonframework.saga.repository.AbstractSagaRepository.find(AbstractSagaRepository.java:39) ~[axon-core-2.3.1.jar:2.3.1]

at org.axonframework.saga.annotation.AsyncSagaEventProcessor.invokeExistingSagas(AsyncSagaEventProcessor.java:175) ~[axon-core-2.3.1.jar:2.3.1]

at org.axonframework.saga.annotation.AsyncSagaEventProcessor.doProcessEvent(AsyncSagaEventProcessor.java:126) ~[axon-core-2.3.1.jar:2.3.1]

at org.axonframework.saga.annotation.AsyncSagaEventProcessor.onEvent(AsyncSagaEventProcessor.java:118) ~[axon-core-2.3.1.jar:2.3.1]

at org.axonframework.saga.annotation.AsyncSagaEventProcessor.onEvent(AsyncSagaEventProcessor.java:49) ~[axon-core-2.3.1.jar:2.3.1]

at com.lmax.disruptor.BatchEventProcessor.run(BatchEventProcessor.java:133) ~[disruptor-3.2.0.jar:na]

at org.axonframework.saga.annotation.AsyncAnnotatedSagaManager$StartDetectingRunnable.run(AsyncAnnotatedSagaManager.java:478) [axon-core-2.3.1.jar:2.3.1]

at java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source) [na:1.7.0_67]

at java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source) [na:1.7.0_67]

at java.lang.Thread.run(Unknown Source) [na:1.7.0_67]

Caused by: org.hibernate.exception.GenericJDBCException: could not extract ResultSet

at org.hibernate.exception.internal.StandardSQLExceptionConverter.convert(StandardSQLExceptionConverter.java:54) ~[hibernate-core-4.3.5.Final.jar:4.3.5.Final]

at org.hibernate.engine.jdbc.spi.SqlExceptionHelper.convert(SqlExceptionHelper.java:126) ~[hibernate-core-4.3.5.Final.jar:4.3.5.Final]

at org.hibernate.engine.jdbc.spi.SqlExceptionHelper.convert(SqlExceptionHelper.java:112) ~[hibernate-core-4.3.5.Final.jar:4.3.5.Final]

at org.hibernate.engine.jdbc.internal.ResultSetReturnImpl.extract(ResultSetReturnImpl.java:89) ~[hibernate-core-4.3.5.Final.jar:4.3.5.Final]

at org.hibernate.loader.Loader.getResultSet(Loader.java:2065) ~[hibernate-core-4.3.5.Final.jar:4.3.5.Final]

at org.hibernate.loader.Loader.executeQueryStatement(Loader.java:1862) ~[hibernate-core-4.3.5.Final.jar:4.3.5.Final]

at org.hibernate.loader.Loader.executeQueryStatement(Loader.java:1838) ~[hibernate-core-4.3.5.Final.jar:4.3.5.Final]

at org.hibernate.loader.Loader.doQuery(Loader.java:909) ~[hibernate-core-4.3.5.Final.jar:4.3.5.Final]

at org.hibernate.loader.Loader.doQueryAndInitializeNonLazyCollections(Loader.java:354) ~[hibernate-core-4.3.5.Final.jar:4.3.5.Final]

at org.hibernate.loader.Loader.doList(Loader.java:2553) ~[hibernate-core-4.3.5.Final.jar:4.3.5.Final]

at org.hibernate.loader.Loader.doList(Loader.java:2539) ~[hibernate-core-4.3.5.Final.jar:4.3.5.Final]

at org.hibernate.loader.Loader.listIgnoreQueryCache(Loader.java:2369) ~[hibernate-core-4.3.5.Final.jar:4.3.5.Final]

at org.hibernate.loader.Loader.list(Loader.java:2364) ~[hibernate-core-4.3.5.Final.jar:4.3.5.Final]

at org.hibernate.loader.hql.QueryLoader.list(QueryLoader.java:496) ~[hibernate-core-4.3.5.Final.jar:4.3.5.Final]

at org.hibernate.hql.internal.ast.QueryTranslatorImpl.list(QueryTranslatorImpl.java:387) ~[hibernate-core-4.3.5.Final.jar:4.3.5.Final]

at org.hibernate.engine.query.spi.HQLQueryPlan.performList(HQLQueryPlan.java:231) ~[hibernate-core-4.3.5.Final.jar:4.3.5.Final]

at org.hibernate.internal.SessionImpl.list(SessionImpl.java:1264) ~[hibernate-core-4.3.5.Final.jar:4.3.5.Final]

at org.hibernate.internal.QueryImpl.list(QueryImpl.java:103) ~[hibernate-core-4.3.5.Final.jar:4.3.5.Final]

at org.hibernate.jpa.internal.QueryImpl.list(QueryImpl.java:573) ~[hibernate-entitymanager-4.3.5.Final.jar:4.3.5.Final]

at org.hibernate.jpa.internal.QueryImpl.getResultList(QueryImpl.java:449) ~[hibernate-entitymanager-4.3.5.Final.jar:4.3.5.Final]

... 11 common frames omitted

Caused by: org.postgresql.util.PSQLException: ERROR: current transaction is aborted, commands ignored until end of transaction block

at org.postgresql.core.v3.QueryExecutorImpl.receiveErrorResponse(QueryExecutorImpl.java:2157) ~[postgresql-9.2-1002.jdbc4.jar:na]

at org.postgresql.core.v3.QueryExecutorImpl.processResults(QueryExecutorImpl.java:1886) ~[postgresql-9.2-1002.jdbc4.jar:na]

at org.postgresql.core.v3.QueryExecutorImpl.execute(QueryExecutorImpl.java:255) ~[postgresql-9.2-1002.jdbc4.jar:na]

at org.postgresql.jdbc2.AbstractJdbc2Statement.execute(AbstractJdbc2Statement.java:555) ~[postgresql-9.2-1002.jdbc4.jar:na]

at org.postgresql.jdbc2.AbstractJdbc2Statement.executeWithFlags(AbstractJdbc2Statement.java:417) ~[postgresql-9.2-1002.jdbc4.jar:na]

at org.postgresql.jdbc2.AbstractJdbc2Statement.executeQuery(AbstractJdbc2Statement.java:302) ~[postgresql-9.2-1002.jdbc4.jar:na]

at com.mchange.v2.c3p0.impl.NewProxyPreparedStatement.executeQuery(NewProxyPreparedStatement.java:1392) ~[c3p0-0.9.5-pre8.jar:0.9.5-pre8]

at org.hibernate.engine.jdbc.internal.ResultSetReturnImpl.extract(ResultSetReturnImpl.java:80) ~[hibernate-core-4.3.5.Final.jar:4.3.5.Final]

... 27 common frames omitted

So isolation level looks fine. And yes, when I have this correct isolation level then it looks like I'm getting only these OptimisticLockExceptions. And when I debugging retry-loop I can see that I'm still getting that Exception :

javax.persistence.OptimisticLockException: Row was updated or deleted by another transaction (or unsaved-value mapping was incorrect) : [com.lbss.charging.ar.domain.model.transaction.BusinessTransaction#9361]

at org.hibernate.jpa.spi.AbstractEntityManagerImpl.wrapStaleStateException(AbstractEntityManagerImpl.java:1785)

at org.hibernate.jpa.spi.AbstractEntityManagerImpl.convert(AbstractEntityManagerImpl.java:1705)

at org.hibernate.jpa.spi.AbstractEntityManagerImpl.convert(AbstractEntityManagerImpl.java:1677)

at org.hibernate.jpa.spi.AbstractEntityManagerImpl.convert(AbstractEntityManagerImpl.java:1683)

at org.hibernate.jpa.spi.AbstractEntityManagerImpl.flush(AbstractEntityManagerImpl.java:1338)

at sun.reflect.GeneratedMethodAccessor122.invoke(Unknown Source)

at sun.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source)

at java.lang.reflect.Method.invoke(Unknown Source)

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

at com.sun.proxy.$Proxy112.flush(Unknown Source)

at org.axonframework.saga.repository.jpa.JpaSagaRepository.storeAssociationValue(JpaSagaRepository.java:125)

at org.axonframework.saga.repository.AbstractSagaRepository.add(AbstractSagaRepository.java:48)

at org.axonframework.saga.annotation.AsyncSagaEventProcessor.persistProcessedSagas(AsyncSagaEventProcessor.java:219)

at org.axonframework.saga.annotation.AsyncSagaEventProcessor.doProcessEvent(AsyncSagaEventProcessor.java:147)

at org.axonframework.saga.annotation.AsyncSagaEventProcessor.onEvent(AsyncSagaEventProcessor.java:118)

at org.axonframework.saga.annotation.AsyncSagaEventProcessor.onEvent(AsyncSagaEventProcessor.java:49)

at com.lmax.disruptor.BatchEventProcessor.run(BatchEventProcessor.java:133)

at org.axonframework.saga.annotation.AsyncAnnotatedSagaManager$StartDetectingRunnable.run(AsyncAnnotatedSagaManager.java:478)

at java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source)

at java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source)

at java.lang.Thread.run(Unknown Source)

Caused by: org.hibernate.StaleObjectStateException: Row was updated or deleted by another transaction (or unsaved-value mapping was incorrect) : [com.lbss.charging.ar.domain.model.transaction.BusinessTransaction#9361]

at org.hibernate.persister.entity.AbstractEntityPersister.check(AbstractEntityPersister.java:2541)

at org.hibernate.persister.entity.AbstractEntityPersister.update(AbstractEntityPersister.java:3285)

at org.hibernate.persister.entity.AbstractEntityPersister.updateOrInsert(AbstractEntityPersister.java:3183)

at org.hibernate.persister.entity.AbstractEntityPersister.update(AbstractEntityPersister.java:3525)

at org.hibernate.action.internal.EntityUpdateAction.execute(EntityUpdateAction.java:159)

at org.hibernate.engine.spi.ActionQueue.executeActions(ActionQueue.java:463)

at org.hibernate.engine.spi.ActionQueue.executeActions(ActionQueue.java:349)

at org.hibernate.event.internal.AbstractFlushingEventListener.performExecutions(AbstractFlushingEventListener.java:350)

at org.hibernate.event.internal.DefaultFlushEventListener.onFlush(DefaultFlushEventListener.java:56)

at org.hibernate.internal.SessionImpl.flush(SessionImpl.java:1222)

at org.hibernate.jpa.spi.AbstractEntityManagerImpl.flush(AbstractEntityManagerImpl.java:1335)

... 16 more

So it looks that I'm kind of stuck with this one.

Jakub

...

[Allard Buijze]

Apparently, Hibernate is trying to persist a com.lbss.charging.ar.domain.model.transaction.BusinessTransaction, but it was modified by some other transaction in the mean time. You probably have to look at where this object is used and which components are attempting to modify it. Make sure that you don't pass your entities in your Events, for example.

Cheers,

Allard

--

[Jakub Čech]

Hello again, 

There was no time for few weeks to keep focus on asynchronous Axon. And after some break it looks that I am able to solve it now :-). So for others here is what I have done :

1. using some instance of LockingRepository for command repositories.

2. Ours AR now extends some of Axon's AbstractAggregateRoot (I just have few questions below)

3. configure retryScheduler for commandGateway

4. publish events from Aggregate root with registerEvent(...) not directly through UnitOfWork.

5. setting transaction manager to AsycnhronousCluster

I think that's it. There was few bugs in our app apparently :-) and as we are coming closer to Axon's implementation it seems to work better and better. For that - Thank you :-)

Just few things I don't understand yet about AggregateRoots - I'm not completely sure what for is lastEventSequenceNumber in AbstractAggregateRoot and why do I have to keep column in every table for AR ( we are not using event sourcing - at least not yet)?

Next thing is that my concurrency problem is fixed only when I extend at least AbstractEventSourcedAggregateRoot. When I extend only AbstractAggregateRoot  then it fails. 

Test case: I apply 20 invoices to 1 account - I expect balance 2000.

Result with AbstractAggregateRoot  - I get around 2100 - 2200.

but with AbstractEventSourcedAggregateRoot or AbstractAnnotatedAggregateRoot everything is fine. And I'm confused now. Because we are not using event sourcing.

But well, it seems that I can extend AbstractEventSourcedAggregateRoot  even when I don't use event sourcing, is that right? Is that safe, no problem with that?

Thanks a lot, 

Jakub

...

[Allard Buijze]

Hi,

sorry for the late response. Unfortunately, internet access is still a scarce resource when abroad...

The EventSourcingAggregateRoot is safe to use, even if you don't use Event Sourcing. However, it is weird that the regular aggregate doesn't work the same way. The only difference with the EventSourcingAggregateRoot is the support for event sourcing (through the apply method).
Is the rest of your infrastructure exactly identical in both cases? If so can you share some of the code that shows the different behavior?

Cheers,

Allard

On do 25 jun. 2015 at 15:12 Allard Buijze <bui...@gmail.com> wrote:

Hi,

the

--

[Jakub Čech]

Hello Allard,

Ok, why not. I already created testing project just for this to simplify it. (I was not able to fix it in original project - there is just too much code) All setup duplicates our setup in original project.

Project is ready for that one simply test case -> concurrently putting invoices on one account. the code tries to duplicate original code -> there is saga etc....

I have putted it on github here: https://github.com/kubacech/async-axon-test

Test class is in src/test/java com.lbss.test.ConcurrencyTest.

Spring context is in src/main/resource/META-INF

I'm changing only one thing - superclass of com.lbss.test.domain.common.IdentifiedAggregateRoot  (between AbstractAnnotatedAggregateRoot and AbstractAggregateRoot).

It runs in both cases. There are some failures (OptimisticLockExceptions) but retry mechanism will take care of it. But the difference is at the end of the test on balance of account. When I use just AbstractAggregateRoot, then now is balance BIGGER then it shoud be. So when its retrying it has to write that amount on account more than once somehow.

Thanks, 

Jakub

...

[Allard Buijze]

Hi Jakub,

it seems that the issue is caused by a combination of the transactional boundary on the service that dispatches commands using fire and forget, the use of the SimpleCommandBus, Optimistic Locking and the JpaRepostory.

With the default Aggregate, the version field is completely managed by JPA. It appears that a number of commands fail because of JPA's optimistic locking. However, since commands are sent using fire-and-forget, the exceptions never arrive in the dispatching service, which will then attempt to commit the transaction. With the EventSourcingAggregate, the version is managed by Axon, and updated for each event registered with the aggregate.

I haven't figured out why the "amount" turns up higher than expected. I'd think it would be lower.

Using a pessimistic lock mechanism made the test pass, even when extending the AbstractAggregateRoot.

However, I'd advise to thoroughly reconsider the architecture in your application. You're probably better off letting Axon manage the transaction around your commands. Also consider your Command Handlers as the service layer. Your current services should be considered as "just" a gateway/API for external parties.

Hope this helps.

Cheers,

Allard

--