One more point… none of the events are serializabe…? except scheduled events which are stored in quartz job store… not sure if this has anything to do with serialization as no appropriate error… and normal eventing into domainevententry seems to be ok.
Could not figure out… more tracing with hibernate SQL below… see that there is a null on payloadRevision, however dont think thats the error but more color…
Hibernate: insert into SnapshotEventEntry (eventIdentifier, metaData, payload, payloadRevision, payloadType, timeStamp, aggregateIdentifier, sequenceNumber, type) values (?, ?, ?, ?, ?, ?, ?, ?, ?)
2013-04-07 16:40:08,884 [taskExecutor-2] TRACE org.hibernate.type.descriptor.sql.BasicBinder - binding parameter [1] as [VARCHAR] - 20a08c46-f8c3-402b-a5a2-fd0fed345583
2013-04-07 16:40:08,884 [taskExecutor-2] TRACE org.hibernate.type.descriptor.sql.BasicBinder - binding parameter [2] as [BLOB] - [B@15cd7c6b
2013-04-07 16:40:08,884 [taskExecutor-2] TRACE org.hibernate.type.descriptor.sql.BasicBinder - binding parameter [3] as [BLOB] - [B@65a35ffb
2013-04-07 16:40:08,884 [taskExecutor-2] TRACE org.hibernate.type.descriptor.sql.BasicBinder - binding parameter [4] as [VARCHAR] -
2013-04-07 16:40:08,884 [taskExecutor-2] TRACE org.hibernate.type.descriptor.sql.BasicBinder - binding parameter [5] as [VARCHAR] - com.vrntmgr.server.deal.Deal
2013-04-07 16:40:08,884 [taskExecutor-2] TRACE org.hibernate.type.descriptor.sql.BasicBinder - binding parameter [6] as [VARCHAR] - 2013-04-07T16:40:08.872-04:00
2013-04-07 16:40:08,884 [taskExecutor-2] TRACE org.hibernate.type.descriptor.sql.BasicBinder - binding parameter [7] as [VARCHAR] - AC9378D3-17DF-4D64-B3E8-D31D2A4F5C48
2013-04-07 16:40:08,884 [taskExecutor-2] TRACE org.hibernate.type.descriptor.sql.BasicBinder - binding parameter [8] as [BIGINT] - 52
2013-04-07 16:40:08,885 [taskExecutor-2] TRACE org.hibernate.type.descriptor.sql.BasicBinder - binding parameter [9] as [VARCHAR] - Deal
2013-04-07 16:40:08,887 [taskExecutor-2] WARN org.hibernate.util.JDBCExceptionReporter - SQL Error: 0, SQLState: null
2013-04-07 16:40:08,887 [taskExecutor-2] ERROR org.hibernate.util.JDBCExceptionReporter - failed batch
2013-04-07 16:40:08,887 [taskExecutor-2] WARN org.axonframework.eventsourcing.AbstractSnapshotter - An attempt to create and store a snapshot resulted in an exception. Exception summary: {}
javax.persistence.PersistenceException: org.hibernate.exception.GenericJDBCException: Could not execute JDBC batch update
at org.hibernate.ejb.AbstractEntityManagerImpl.convert(AbstractEntityManagerImpl.java:1387)
at org.hibernate.ejb.AbstractEntityManagerImpl.convert(AbstractEntityManagerImpl.java:1315)
at org.hibernate.ejb.QueryImpl.getResultList(QueryImpl.java:255)
at org.axonframework.eventstore.jpa.DefaultEventEntryStore.findRedundantSnapshots(DefaultEventEntryStore.java:126)
at org.axonframework.eventstore.jpa.DefaultEventEntryStore.pruneSnapshots(DefaultEventEntryStore.java:97)
at org.axonframework.eventstore.jpa.JpaEventStore.appendSnapshotEvent(JpaEventStore.java:254)
at org.axonframework.eventsourcing.AbstractSnapshotter$CreateSnapshotTask.run(AbstractSnapshotter.java:90)
at org.axonframework.eventsourcing.SpringAggregateSnapshotter$TransactionalRunnableWrapper.run(SpringAggregateSnapshotter.java:137)
at org.axonframework.eventsourcing.AbstractSnapshotter$SilentTask.run(AbstractSnapshotter.java:145)
at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:895)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:918)
at java.lang.Thread.run(Thread.java:680)
Caused by: org.hibernate.exception.GenericJDBCException: Could not execute JDBC batch update
at org.hibernate.exception.SQLStateConverter.handledNonSpecificException(SQLStateConverter.java:140)
at org.hibernate.exception.SQLStateConverter.convert(SQLStateConverter.java:128)
at org.hibernate.exception.JDBCExceptionHelper.convert(JDBCExceptionHelper.java:66)
at org.hibernate.jdbc.AbstractBatcher.executeBatch(AbstractBatcher.java:275)
at org.hibernate.engine.ActionQueue.executeActions(ActionQueue.java:268)
at org.hibernate.engine.ActionQueue.executeActions(ActionQueue.java:184)
at org.hibernate.event.def.AbstractFlushingEventListener.performExecutions(AbstractFlushingEventListener.java:321)
at org.hibernate.event.def.DefaultAutoFlushEventListener.onAutoFlush(DefaultAutoFlushEventListener.java:64)
at org.hibernate.impl.SessionImpl.autoFlushIfRequired(SessionImpl.java:1185)
at org.hibernate.impl.SessionImpl.list(SessionImpl.java:1261)
at org.hibernate.impl.QueryImpl.list(QueryImpl.java:102)
at org.hibernate.ejb.QueryImpl.getResultList(QueryImpl.java:246)
… 9 more
Caused by: java.sql.BatchUpdateException: failed batch
at org.hsqldb.jdbc.jdbcStatement.executeBatch(Unknown Source)
at org.hsqldb.jdbc.jdbcPreparedStatement.executeBatch(Unknown Source)
at com.mchange.v2.c3p0.impl.NewProxyPreparedStatement.executeBatch(NewProxyPreparedStatement.java:1723)
at org.hibernate.jdbc.BatchingBatcher.doExecuteBatch(BatchingBatcher.java:70)
at org.hibernate.jdbc.AbstractBatcher.executeBatch(AbstractBatcher.java:268)
… 17 more
The errors above were from hsqldb… the error below is from mySQL… seems like duplicate entry insertion in snapshot arena… Thoughts… ideas… Cheers.
2013-04-08 04:17:24,900 [taskExecutor-1] WARN org.hibernate.util.JDBCExceptionReporter - SQL Error: 1062, SQLState: 23000
2013-04-08 04:17:24,900 [taskExecutor-1] ERROR org.hibernate.util.JDBCExceptionReporter - Duplicate entry ‘17B889B6-E292-4A04-B842-C9F7236F9294-8-Deal’ for key ‘PRIMARY’
2013-04-08 04:17:24,902 [taskExecutor-1] WARN org.axonframework.eventsourcing.AbstractSnapshotter - An attempt to create and store a snapshot resulted in an exception:
javax.persistence.PersistenceException: org.hibernate.exception.ConstraintViolationException: Could not execute JDBC batch update
at org.hibernate.ejb.AbstractEntityManagerImpl.convert(AbstractEntityManagerImpl.java:1387)
at org.hibernate.ejb.AbstractEntityManagerImpl.convert(AbstractEntityManagerImpl.java:1315)
at org.hibernate.ejb.QueryImpl.getResultList(QueryImpl.java:255)
at org.axonframework.eventstore.jpa.DefaultEventEntryStore.findRedundantSnapshots(DefaultEventEntryStore.java:126)
at org.axonframework.eventstore.jpa.DefaultEventEntryStore.pruneSnapshots(DefaultEventEntryStore.java:97)
at org.axonframework.eventstore.jpa.JpaEventStore.appendSnapshotEvent(JpaEventStore.java:254)
at org.axonframework.eventsourcing.AbstractSnapshotter$CreateSnapshotTask.run(AbstractSnapshotter.java:90)
at org.axonframework.eventsourcing.SpringAggregateSnapshotter$TransactionalRunnableWrapper.run(SpringAggregateSnapshotter.java:137)
at org.axonframework.eventsourcing.AbstractSnapshotter$SilentTask.run(AbstractSnapshotter.java:145)
at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:895)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:918)
at java.lang.Thread.run(Thread.java:680)
Caused by: org.hibernate.exception.ConstraintViolationException: Could not execute JDBC batch update
at org.hibernate.exception.SQLStateConverter.convert(SQLStateConverter.java:96)
at org.hibernate.exception.JDBCExceptionHelper.convert(JDBCExceptionHelper.java:66)
at org.hibernate.jdbc.AbstractBatcher.executeBatch(AbstractBatcher.java:275)
at org.hibernate.engine.ActionQueue.executeActions(ActionQueue.java:268)
at org.hibernate.engine.ActionQueue.executeActions(ActionQueue.java:184)
at org.hibernate.event.def.AbstractFlushingEventListener.performExecutions(AbstractFlushingEventListener.java:321)
at org.hibernate.event.def.DefaultAutoFlushEventListener.onAutoFlush(DefaultAutoFlushEventListener.java:64)
at org.hibernate.impl.SessionImpl.autoFlushIfRequired(SessionImpl.java:1185)
at org.hibernate.impl.SessionImpl.list(SessionImpl.java:1261)
at org.hibernate.impl.QueryImpl.list(QueryImpl.java:102)
at org.hibernate.ejb.QueryImpl.getResultList(QueryImpl.java:246)
… 9 more
Caused by: java.sql.BatchUpdateException: Duplicate entry ‘17B889B6-E292-4A04-B842-C9F7236F9294-8-Deal’ for key ‘PRIMARY’
at com.mysql.jdbc.PreparedStatement.executeBatchSerially(PreparedStatement.java:2007)
at com.mysql.jdbc.PreparedStatement.executeBatch(PreparedStatement.java:1443)
at com.mchange.v2.c3p0.impl.NewProxyPreparedStatement.executeBatch(NewProxyPreparedStatement.java:1723)
at org.hibernate.jdbc.BatchingBatcher.doExecuteBatch(BatchingBatcher.java:70)
at org.hibernate.jdbc.AbstractBatcher.executeBatch(AbstractBatcher.java:268)
… 17 more
Looks like there is a duplicate snapshot. This is normally not a problem. It could mean that there are two processes creating a snapshot at the same time. In that case, it’s a configuration issue. Otherwise, it’s perfectly fine to ignore (silence) this exception.
Cheers,
Allard
Unfortunately, this is happening with only one user using app with very frequent in log and seems like every time snapshotting is required this error happens. Not sure why this is happening even with single user as this did never happen before in 1.x environment.
Have gone back and redone the entire experience on the 1.4 branch of the app, and don’t see any of these errors for same app use case scenarios so now really need to strive to make this error go away and also not see it in cluttering production logs. Right now with single user this stack trace is clogging up the log also, so please help with any ideas to improve the situation by any configuration or code change options to pursue.
Thanks and cheers…
Hi,
unfortunately, from here, I cannot see what’s happening. Basically, the exception means that a same snapshot is created twice. This can have two reasons. You have either configured two snapshotters, which is not likely, but not impossible. Or your snapshotter is being triggered twice in a very short timeframe.
Do you snapshot asynchronously? Do you have any events from an aggregate that trigger a command on that same aggregate?
Meanwhile, I’ll also have a look at the snapshotting code to see if there is a way to detect this scenario and skip snapshotting. In the end, there is no point creating a snapshot of an aggregate that has been loaded using exclusively another snapshot.
Cheers,
Allard
Hi Allard, Thanls for the prompt response as always…
For your questions below.
- Only one snapshotter with standard Axon config element <axon:snapshotter id=“snapshotter”
event-store=“eventStore”
executor=“taskExecutor”
transaction-manager=“transactionManager”/>
- Yes there are events firing out of a starting aggregate… getting to aggregate boundary sagas to fire commands on other aggregate, which fire events coming back to original aggregates sagas as response and then calling a command on the starting aggregate firing internal state change on the aggregate… This is all synchronous… in the middle one event is async however have disabled that async cluster and event handling and made it synchronous… and can still get this error with same predictability all the time.
Let me know and i can send more detailed logs to you directly for Axon and/or app output to see this error predictably happening as it can be reproduced whenever time to snapshot in this case 5 events snapshot trigger threshold.
Thanks and Cheers…
Hi,
I’ll try to reproduce this problem in a simple scenario, so that I can make it part of the build process. But I think to know where the problem comes from.
Since your snapshotter is asynchronous, but the process is synchronous and processes the same aggregate twice, it is not unlkely that the snapshotter is triggered twice. The second trigger will cause the exact same snapshot version to be created as the first one. The snapshotter doesn’t detect this and simply stores the snapshot.
A workaround you could try is to use a synchronous snapshotter (removing the executor and transaction-manager is probably enough). I have created issue AXON-120 for this one (http://issues.axonframework.org/youtrack/issue/AXON-120).
Another remark I’d like to make is that a saga invoking a command on an aggregate based on an event of that same aggregate is a code smell. Are you sue the aggregate can’t make the decision the launch that event in the first place? It’s not always possible, but when it is, you don’t want to go through a saga.
Cheers,
Allard
Thanks for tracking this. Will try out sync option and report.
With respect to the remark on code smell… let me elaborate on why we do that and get input if we can improving it further.
We have aggregate A which produces Event A… Event A is intercepted by SagaA and calls command on Aggregate B. Aggregate B fires Event B which is intercepted by SagaA to complete/stop the saga as it was waiting for response of work being done on AggregateB. Now SagaA calls a command on Aggregate A to complete full round trip.
Hope this clarifies the context. One early on/legacy design point which we have emphasized is that the aggregate is not trapping events directly with EventHandler unless those are events which are only generated by itself. it is only trapping events it generates by firing of command operations on it. Obvious question that comes to mind is can aggregate event handler trap events from other aggregates without the firing of a command?
Look forward to thoughts and input.
Cheers and Thanks…
Hi,
your scenario sounds viable. >From previous mails, I was under the impression that the Saga sent a command directly from an event from the same aggregate. But that doesn’t seem to be the case.
Cheers,
Allard
Removed the task executor and transaction manager and still saw these errors… on a side note cache was not configured when seeing errors, however have configured cache based on the default axon-trader sample now and did not see this error yet which seems strange…
Is there any best practice guidance for axon-cache config for the aggregates… and what not to do?
Thanks and Cheers…
Hi,
the issue should have been addressed in 2.0.2. I did notice, however, that the exception is only being logged when the logger is on debug level. If the logger is on another level, a one-liner is logged mentioning that it occurred, but without the stacktrace.
Do you have logging on the debug level?
Cheers,
Allard