Axon improperly handling merged segments

user_134894 0
Viewed 307

We have an application, which uses Axon Server, where we're implementing automatic scaling of instances within a k8s cluster.

The scaling code looks at the Axon Server API to determine which processors have either free thread instances or unassigned segments. If free thread instances are found then the segment is split. If a warning is seen with a message "Not all segments claimed" then the processor is merged. Once the split/merge request is done, we poll on the API to get the processor information, waiting for the tracker count to change accordingly.

When scaling up (splitting) this works fine. When scaling down (merging) we fairly often see an exception in the application logs, pertaining to the management of the tokens in the JPA token store.

The following log was 300ms after having sent the merge API request. Prior to this, 2 instances, each configured for 2 threads, were running. We'd scaled up to 4 threads total, and then I killed one instance. This left 2 segments unassigned. Hence the need to merge. We would ideally like to merge and move before an instance dies, but we do need to be able to handle unexpected instance death like this.

2020-06-12 14:41:51.417  INFO 14056 [:] --- [EventHandler]-0] o.h.e.internal.DefaultLoadEventListener  : HHH000327: Error performing load command : org.hibernate.StaleObjectStateException: Row was updated or deleted by another transaction (or unsaved-value mapping was incorrect) : [org.axonframework.eventhandling.tokenstore.jpa.TokenEntry#org.axonframework.eventhandling.tokenstore.jpa.TokenEntry$PK@9e1d11cf]

org.hibernate.StaleObjectStateException: Row was updated or deleted by another transaction (or unsaved-value mapping was incorrect) : [org.axonframework.eventhandling.tokenstore.jpa.TokenEntry#org.axonframework.eventhandling.tokenstore.jpa.TokenEntry$PK@9e1d11cf]
    at org.hibernate.dialect.lock.PessimisticWriteSelectLockingStrategy.lock(PessimisticWriteSelectLockingStrategy.java:76)
    at org.hibernate.persister.entity.AbstractEntityPersister.lock(AbstractEntityPersister.java:1928)
    at org.hibernate.event.internal.AbstractLockUpgradeEventListener.upgradeLock(AbstractLockUpgradeEventListener.java:82)
    at org.hibernate.event.internal.DefaultLoadEventListener.loadFromSessionCache(DefaultLoadEventListener.java:569)
    at org.hibernate.event.internal.DefaultLoadEventListener.doLoad(DefaultLoadEventListener.java:444)
    at org.hibernate.event.internal.DefaultLoadEventListener.load(DefaultLoadEventListener.java:222)
    at org.hibernate.event.internal.DefaultLoadEventListener.lockAndLoad(DefaultLoadEventListener.java:406)
    at org.hibernate.event.internal.DefaultLoadEventListener.doOnLoad(DefaultLoadEventListener.java:127)
    at org.hibernate.event.internal.DefaultLoadEventListener.onLoad(DefaultLoadEventListener.java:92)
    at org.hibernate.internal.SessionImpl.fireLoad(SessionImpl.java:1256)
    at org.hibernate.internal.SessionImpl.access$1900(SessionImpl.java:207)
    at org.hibernate.internal.SessionImpl$IdentifierLoadAccessImpl.doLoad(SessionImpl.java:2866)
    at org.hibernate.internal.SessionImpl$IdentifierLoadAccessImpl.load(SessionImpl.java:2847)
    at org.hibernate.internal.SessionImpl.find(SessionImpl.java:3482)
    at org.hibernate.internal.SessionImpl.find(SessionImpl.java:3456)
    at jdk.internal.reflect.GeneratedMethodAccessor219.invoke(Unknown Source)
    at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
    at java.base/java.lang.reflect.Method.invoke(Method.java:566)
    at org.springframework.orm.jpa.SharedEntityManagerCreator$SharedEntityManagerInvocationHandler.invoke(SharedEntityManagerCreator.java:308)
    at com.sun.proxy.$Proxy277.find(Unknown Source)
    at org.axonframework.eventhandling.tokenstore.jpa.JpaTokenStore.loadToken(JpaTokenStore.java:216)
    at org.axonframework.eventhandling.tokenstore.jpa.JpaTokenStore.storeToken(JpaTokenStore.java:111)
    at org.axonframework.eventhandling.TrackingEventProcessor$MergeSegmentInstruction.runSafe(TrackingEventProcessor.java:1385)
    at org.axonframework.eventhandling.TrackingEventProcessor$Instruction.lambda$null$0(TrackingEventProcessor.java:1139)
    at org.axonframework.common.transaction.TransactionManager.executeInTransaction(TransactionManager.java:47)
    at org.axonframework.eventhandling.TrackingEventProcessor$Instruction.lambda$run$1(TrackingEventProcessor.java:1139)
    at org.axonframework.common.ProcessUtils.executeWithRetry(ProcessUtils.java:33)
    at org.axonframework.eventhandling.TrackingEventProcessor$Instruction.run(TrackingEventProcessor.java:1139)
    at org.axonframework.eventhandling.TrackingEventProcessor.processInstructions(TrackingEventProcessor.java:332)
    at org.axonframework.eventhandling.TrackingEventProcessor.processingLoop(TrackingEventProcessor.java:297)
    at org.axonframework.eventhandling.TrackingEventProcessor$TrackingSegmentWorker.run(TrackingEventProcessor.java:1161)
    at org.axonframework.eventhandling.TrackingEventProcessor$WorkerLauncher.run(TrackingEventProcessor.java:1276)
    at java.base/java.lang.Thread.run(Thread.java:834)

2020-06-12 14:41:51.431 ERROR 14056 [:] --- [ault-executor-0] o.a.a.c.p.EventProcessorControlService   : Failed to merge segment [3] for processor [MyEventHandler]

java.util.concurrent.CompletionException: javax.persistence.OptimisticLockException: Row was updated or deleted by another transaction (or unsaved-value mapping was incorrect) : [org.axonframework.eventhandling.tokenstore.jpa.TokenEntry#org.axonframework.eventhandling.tokenstore.jpa.TokenEntry$PK@9e1d11cf]
    at java.base/java.util.concurrent.CompletableFuture.encodeThrowable(CompletableFuture.java:331)
    at java.base/java.util.concurrent.CompletableFuture.completeThrowable(CompletableFuture.java:346)
    at java.base/java.util.concurrent.CompletableFuture$UniApply.tryFire(CompletableFuture.java:632)
    at java.base/java.util.concurrent.CompletableFuture.postComplete(CompletableFuture.java:506)
    at java.base/java.util.concurrent.CompletableFuture.completeExceptionally(CompletableFuture.java:2088)
    at org.axonframework.eventhandling.TrackingEventProcessor$Instruction.run(TrackingEventProcessor.java:1143)
    at org.axonframework.eventhandling.TrackingEventProcessor.processInstructions(TrackingEventProcessor.java:332)
    at org.axonframework.eventhandling.TrackingEventProcessor.processingLoop(TrackingEventProcessor.java:297)
    at org.axonframework.eventhandling.TrackingEventProcessor$TrackingSegmentWorker.run(TrackingEventProcessor.java:1161)
    at org.axonframework.eventhandling.TrackingEventProcessor$WorkerLauncher.run(TrackingEventProcessor.java:1276)
    at java.base/java.lang.Thread.run(Thread.java:834)
Caused by: javax.persistence.OptimisticLockException: Row was updated or deleted by another transaction (or unsaved-value mapping was incorrect) : [org.axonframework.eventhandling.tokenstore.jpa.TokenEntry#org.axonframework.eventhandling.tokenstore.jpa.TokenEntry$PK@9e1d11cf]
    at org.hibernate.internal.ExceptionConverterImpl.wrapStaleStateException(ExceptionConverterImpl.java:226)
    at org.hibernate.internal.ExceptionConverterImpl.convert(ExceptionConverterImpl.java:93)
    at org.hibernate.internal.ExceptionConverterImpl.convert(ExceptionConverterImpl.java:200)
    at org.hibernate.internal.SessionImpl.find(SessionImpl.java:3515)
    at org.hibernate.internal.SessionImpl.find(SessionImpl.java:3456)
    at jdk.internal.reflect.GeneratedMethodAccessor219.invoke(Unknown Source)
    at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
    at java.base/java.lang.reflect.Method.invoke(Method.java:566)
    at org.springframework.orm.jpa.SharedEntityManagerCreator$SharedEntityManagerInvocationHandler.invoke(SharedEntityManagerCreator.java:308)
    at com.sun.proxy.$Proxy277.find(Unknown Source)
    at org.axonframework.eventhandling.tokenstore.jpa.JpaTokenStore.loadToken(JpaTokenStore.java:216)
    at org.axonframework.eventhandling.tokenstore.jpa.JpaTokenStore.storeToken(JpaTokenStore.java:111)
    at org.axonframework.eventhandling.TrackingEventProcessor$MergeSegmentInstruction.runSafe(TrackingEventProcessor.java:1385)
    at org.axonframework.eventhandling.TrackingEventProcessor$Instruction.lambda$null$0(TrackingEventProcessor.java:1139)
    at org.axonframework.common.transaction.TransactionManager.executeInTransaction(TransactionManager.java:47)
    at org.axonframework.eventhandling.TrackingEventProcessor$Instruction.lambda$run$1(TrackingEventProcessor.java:1139)
    at org.axonframework.common.ProcessUtils.executeWithRetry(ProcessUtils.java:33)
    at org.axonframework.eventhandling.TrackingEventProcessor$Instruction.run(TrackingEventProcessor.java:1139)
    ... 5 common frames omitted

Is this the result of some misconfiguration of our JPA token store, or is there some incantation I'm missing?

axon hibernate
1 Answers

As you are I believe already aware of, you have found a bug from Axon Framework's side on the matter here @ptomli. You filed an issue on the Axon Server SE GitHub repository for this (which can be found here), that further explains some additional steps.

The AxonIQ team has investigated the problem and indeed uncovered this to be an issue, which was marked under issue #1451 and resolved in this pull request.

In short, it had to do with an ordering requirement in the framework, which expected users to provide the lowest segmentId of the pair of segments to be merged. The fix for this is currently included in 4.4.

Upon investigation an additional issue was discovered, which didn't allow the merge operation if the segment to merge is unclaimed by any thread. This delegation process to do allow this will be resolved on Axon Server's end, for which the work is marked in issue #136.

Hoping this provides all the necessary info for you to proceed @ptomli, and for others to understand how this has been resolved.

user_22156490
Related