Saga's and Event Processors hanging in clustered deployment

Hi Allard,

I have finally gotten the stack trace. I don’t see the JMS sendAndWait call below.

The context behind what you are seeing is the following:

  1. Deadline for billing has expired, so the Billable aggregate is eligible to be billed now. The event that marks the Billable as eligible is applied to the aggregate.
  2. The BillingSagaProcessor sees the new event in the domain_event_entry table and begins to process it.
  3. The BillingSaga attempts to add the Billable aggregate to the Billing aggregate’s bucket of work. This is performed indirectly, since the Billing aggregate might not exist, (but in our case, it does exist, also the Billing aggregate is eternal, so its history is snapshotted every 100 events).

From the looks of it, the BillingSaga is getting stuck at the point where it is trying to read the BillingAggregate’s snapshot from the DB. This would indicate that something else has the lock to the snapshot for that aggregate.

However, the second node in the cluster is the “follower” node, and cannot get the ownership token for the BillingSaga, since the first node is marked as the owner.

Then, back on the first node, I cannot think of any other process that would be holding the lock to that record on the snapshot_event_entry table. However, given this evidence, I will start looking around for something now.

Thank you,

David

"EventProcessor[BillableSagaProcessor]-0" Id=79 RUNNABLE (in native)
at java.net.SocketInputStream.socketRead0(Native Method)
at java.net.SocketInputStream.socketRead(SocketInputStream.java:116)
at java.net.SocketInputStream.read(SocketInputStream.java:171)
at java.net.SocketInputStream.read(SocketInputStream.java:141)
at sun.security.ssl.InputRecord.readFully(InputRecord.java:465)
at sun.security.ssl.InputRecord.read(InputRecord.java:503)
at sun.security.ssl.SSLSocketImpl.readRecord(SSLSocketImpl.java:975)
- locked java.lang.Object : class java.lang.management.MonitorInfo : java.lang.Object@3c6c79ce
at sun.security.ssl.SSLSocketImpl.readDataRecord(SSLSocketImpl.java:933)
at sun.security.ssl.AppInputStream.read(AppInputStream.java:105)
- locked sun.security.ssl.AppInputStream : class java.lang.management.MonitorInfo : sun.security.ssl.AppInputStream@12bff0d7
at java.io.FilterInputStream.read(FilterInputStream.java:133)
at com.mysql.cj.protocol.FullReadInputStream.readFully(FullReadInputStream.java:64)
at com.mysql.cj.protocol.a.SimplePacketReader.readMessage(SimplePacketReader.java:108)
at com.mysql.cj.protocol.a.SimplePacketReader.readMessage(SimplePacketReader.java:45)
at com.mysql.cj.protocol.a.TimeTrackingPacketReader.readMessage(TimeTrackingPacketReader.java:57)
at com.mysql.cj.protocol.a.TimeTrackingPacketReader.readMessage(TimeTrackingPacketReader.java:41)
at com.mysql.cj.protocol.a.MultiPacketReader.readMessage(MultiPacketReader.java:61)
at com.mysql.cj.protocol.a.MultiPacketReader.readMessage(MultiPacketReader.java:44)
at com.mysql.cj.protocol.a.ResultsetRowReader.read(ResultsetRowReader.java:75)
at com.mysql.cj.protocol.a.ResultsetRowReader.read(ResultsetRowReader.java:42)
at com.mysql.cj.protocol.a.NativeProtocol.read(NativeProtocol.java:1685)
at com.mysql.cj.protocol.a.TextResultsetReader.read(TextResultsetReader.java:82)
at com.mysql.cj.protocol.a.TextResultsetReader.read(TextResultsetReader.java:48)
at com.mysql.cj.protocol.a.NativeProtocol.read(NativeProtocol.java:1698)
at com.mysql.cj.protocol.a.NativeProtocol.readAllResults(NativeProtocol.java:1752)
at com.mysql.cj.protocol.a.NativeProtocol.sendQueryPacket(NativeProtocol.java:1041)
at com.mysql.cj.NativeSession.execSQL(NativeSession.java:1157)
at com.mysql.cj.jdbc.ClientPreparedStatement.executeInternal(ClientPreparedStatement.java:947)
- locked com.mysql.cj.jdbc.ConnectionImpl : class java.lang.management.MonitorInfo : com.mysql.cj.jdbc.ConnectionImpl@4470bcb7
at com.mysql.cj.jdbc.ClientPreparedStatement.executeQuery(ClientPreparedStatement.java:1020)
- locked com.mysql.cj.jdbc.ConnectionImpl : class java.lang.management.MonitorInfo : com.mysql.cj.jdbc.ConnectionImpl@4470bcb7
at com.zaxxer.hikari.pool.ProxyPreparedStatement.executeQuery(ProxyPreparedStatement.java:52)
at com.zaxxer.hikari.pool.HikariProxyPreparedStatement.executeQuery(HikariProxyPreparedStatement.java)
at org.hibernate.engine.jdbc.internal.ResultSetReturnImpl.extract(ResultSetReturnImpl.java:60)
at org.hibernate.loader.Loader.getResultSet(Loader.java:2167)
at org.hibernate.loader.Loader.executeQueryStatement(Loader.java:1930)
at org.hibernate.loader.Loader.executeQueryStatement(Loader.java:1892)
at org.hibernate.loader.Loader.doQuery(Loader.java:937)
at org.hibernate.loader.Loader.doQueryAndInitializeNonLazyCollections(Loader.java:340)
at org.hibernate.loader.Loader.doList(Loader.java:2689)
at org.hibernate.loader.Loader.doList(Loader.java:2672)
at org.hibernate.loader.Loader.listIgnoreQueryCache(Loader.java:2506)
at org.hibernate.loader.Loader.list(Loader.java:2501)
at org.hibernate.loader.hql.QueryLoader.list(QueryLoader.java:504)
at org.hibernate.hql.internal.ast.QueryTranslatorImpl.list(QueryTranslatorImpl.java:395)
at org.hibernate.engine.query.spi.HQLQueryPlan.performList(HQLQueryPlan.java:220)
at org.hibernate.internal.SessionImpl.list(SessionImpl.java:1507)
at org.hibernate.query.internal.AbstractProducedQuery.doList(AbstractProducedQuery.java:1537)
at org.hibernate.query.internal.AbstractProducedQuery.list(AbstractProducedQuery.java:1505)
at org.hibernate.query.Query.getResultList(Query.java:132)
at org.axonframework.eventsourcing.eventstore.jpa.JpaEventStorageEngine.lambda$readSnapshotData$4(JpaEventStorageEngine.java:268)
 // Here it should be attempting to read the snapshot of the BillingAggregate.
 // Since this aggregate never ends, its history is snapshotted every 100 events
at org.axonframework.eventsourcing.eventstore.jpa.JpaEventStorageEngine$$Lambda$1573/1032138518.get(Unknown Source)
at org.axonframework.common.transaction.TransactionManager.fetchInTransaction(TransactionManager.java:70)
at org.axonframework.eventsourcing.eventstore.jpa.JpaEventStorageEngine.readSnapshotData(JpaEventStorageEngine.java:257)
at org.axonframework.eventsourcing.eventstore.AbstractEventStorageEngine.readSnapshot(AbstractEventStorageEngine.java:85)
at org.axonframework.eventsourcing.eventstore.AbstractEventStore.readEvents(AbstractEventStore.java:77)
at org.axonframework.eventsourcing.EventSourcingRepository.readEvents(EventSourcingRepository.java:142)
at org.axonframework.eventsourcing.EventSourcingRepository.doLoadWithLock(EventSourcingRepository.java:119)
at org.axonframework.eventsourcing.EventSourcingRepository.doLoadWithLock(EventSourcingRepository.java:50)
at org.axonframework.modelling.command.LockingRepository.doLoad(LockingRepository.java:118)
at org.axonframework.modelling.command.LockingRepository.doLoad(LockingRepository.java:52)
at org.axonframework.modelling.command.AbstractRepository.lambda$load$4(AbstractRepository.java:122)
at org.axonframework.modelling.command.AbstractRepository$$Lambda$1572/202220648.apply(Unknown Source)
at java.util.HashMap.computeIfAbsent(HashMap.java:1127)
at org.axonframework.modelling.command.AbstractRepository.load(AbstractRepository.java:121)
at org.axonframework.modelling.command.AbstractRepository.load(AbstractRepository.java:146)
at com.mycustomapp.AddBillableHandler.handle(AddBillableCmdHandler.java:31)
    // adding Billable aggregate to Billing aggregate. Billing aggregate will release the Billable for billing
    // when it has been determined to acceptable to do so.
    // The Billable is added in the same manner as shown here:
    // https://github.com/AxonFramework/AxonBank/blob/master/core/src/main/java/org/axonframework/samples/bank/command/BankAccountCommandHandler.java
    // We are doing this in case the BillingAggregate does not yet exist (but in this case, it does already exist)
at sun.reflect.GeneratedMethodAccessor1487.invoke(Unknown Source)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:498)
at org.axonframework.messaging.annotation.AnnotatedMessageHandlingMember.handle(AnnotatedMessageHandlingMember.java:127)
at org.axonframework.messaging.annotation.WrappedMessageHandlingMember.handle(WrappedMessageHandlingMember.java:61)
at org.axonframework.commandhandling.AnnotationCommandHandlerAdapter.handle(AnnotationCommandHandlerAdapter.java:119)
at org.axonframework.commandhandling.AnnotationCommandHandlerAdapter.handle(AnnotationCommandHandlerAdapter.java:45)
at sun.reflect.GeneratedMethodAccessor429.invoke(Unknown Source)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:498)
at org.axonframework.spring.config.AbstractAnnotationHandlerBeanPostProcessor$AdapterIntroductionInterceptor.invoke(AbstractAnnotationHandlerBeanPostProcessor.java:273)
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:186)
at org.springframework.aop.framework.CglibAopProxy$DynamicAdvisedInterceptor.intercept(CglibAopProxy.java:688)
at com.mycustomapp.AddBillableHandler$$EnhancerBySpringCGLIB$$e906ad43.handle(<generated>)
at org.axonframework.messaging.DefaultInterceptorChain.proceed(DefaultInterceptorChain.java:57)
at org.axonframework.messaging.interceptors.CorrelationDataInterceptor.handle(CorrelationDataInterceptor.java:65)
at org.axonframework.messaging.DefaultInterceptorChain.proceed(DefaultInterceptorChain.java:55)
at org.axonframework.commandhandling.SimpleCommandBus$$Lambda$1474/1340686431.call(Unknown Source)
at org.axonframework.messaging.unitofwork.DefaultUnitOfWork.executeWithResult(DefaultUnitOfWork.java:74)
at org.axonframework.commandhandling.SimpleCommandBus.handle(SimpleCommandBus.java:176)
at org.axonframework.commandhandling.SimpleCommandBus.doDispatch(SimpleCommandBus.java:141)
at org.axonframework.commandhandling.SimpleCommandBus.dispatch(SimpleCommandBus.java:110)
at org.axonframework.commandhandling.gateway.AbstractCommandGateway.send(AbstractCommandGateway.java:75)
at org.axonframework.commandhandling.gateway.DefaultCommandGateway.send(DefaultCommandGateway.java:73)
at org.axonframework.commandhandling.gateway.DefaultCommandGateway.send(DefaultCommandGateway.java:127)
at com.mycustomapp.BillableSaga.transitionToPendingBillableAdded(BillableSaga.java:195)
at com.mycustomapp.BillableSaga.on(BillableSaga.java:83)
  // here, the saga around billing for the Billable has just been created
at sun.reflect.GeneratedMethodAccessor1485.invoke(Unknown Source)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:498)
at org.axonframework.messaging.annotation.AnnotatedMessageHandlingMember.handle(AnnotatedMessageHandlingMember.java:127)
at org.axonframework.modelling.saga.SagaMethodMessageHandlingMember.handle(SagaMethodMessageHandlingMember.java:80)
at org.axonframework.modelling.saga.AnnotatedSaga.lambda$handle$8(AnnotatedSaga.java:121)
at org.axonframework.modelling.saga.AnnotatedSaga$$Lambda$1676/629902786.call(Unknown Source)
at org.axonframework.messaging.Scope.executeWithResult(Scope.java:111)
at org.axonframework.modelling.saga.AnnotatedSaga.handle(AnnotatedSaga.java:121)
at org.axonframework.modelling.saga.AnnotatedSaga.lambda$handle$7(AnnotatedSaga.java:113)
at org.axonframework.modelling.saga.AnnotatedSaga$$Lambda$1675/1305259534.apply(Unknown Source)
at java.util.Optional.map(Optional.java:215)
at org.axonframework.modelling.saga.AnnotatedSaga.handle(AnnotatedSaga.java:113)
at org.axonframework.modelling.saga.AbstractSagaManager.doInvokeSaga(AbstractSagaManager.java:165)
at org.axonframework.modelling.saga.AbstractSagaManager.startNewSaga(AbstractSagaManager.java:107)
at org.axonframework.modelling.saga.AbstractSagaManager.handle(AbstractSagaManager.java:93)
at org.axonframework.eventhandling.MultiEventHandlerInvoker.handle(MultiEventHandlerInvoker.java:79)
at org.axonframework.eventhandling.AbstractEventProcessor.lambda$null$1(AbstractEventProcessor.java:157)
at org.axonframework.eventhandling.AbstractEventProcessor$$Lambda$1643/104548229.handle(Unknown Source)
at org.axonframework.messaging.DefaultInterceptorChain.proceed(DefaultInterceptorChain.java:57)
at org.axonframework.messaging.interceptors.CorrelationDataInterceptor.handle(CorrelationDataInterceptor.java:65)
at org.axonframework.messaging.DefaultInterceptorChain.proceed(DefaultInterceptorChain.java:55)
at org.axonframework.messaging.DefaultInterceptorChain.proceed(DefaultInterceptorChain.java:55)
at org.axonframework.eventhandling.TrackingEventProcessor.lambda$new$1(TrackingEventProcessor.java:160)
at org.axonframework.eventhandling.TrackingEventProcessor$$Lambda$1288/1215027014.handle(Unknown Source)
at org.axonframework.messaging.DefaultInterceptorChain.proceed(DefaultInterceptorChain.java:55)
at org.axonframework.eventhandling.AbstractEventProcessor.lambda$processInUnitOfWork$2(AbstractEventProcessor.java:165)
at org.axonframework.eventhandling.AbstractEventProcessor$$Lambda$1636/475978775.call(Unknown Source)
at org.axonframework.messaging.unitofwork.BatchingUnitOfWork.executeWithResult(BatchingUnitOfWork.java:86)
at org.axonframework.eventhandling.AbstractEventProcessor.processInUnitOfWork(AbstractEventProcessor.java:151)
at org.axonframework.eventhandling.TrackingEventProcessor.processBatch(TrackingEventProcessor.java:395)
at org.axonframework.eventhandling.TrackingEventProcessor.processingLoop(TrackingEventProcessor.java:269)
at org.axonframework.eventhandling.TrackingEventProcessor$TrackingSegmentWorker.run(TrackingEventProcessor.java:990)
at org.axonframework.eventhandling.TrackingEventProcessor$WorkerLauncher.run(TrackingEventProcessor.java:1100)
at java.lang.Thread.run(Thread.java:748)
Number of locked synchronizers = 2
- java.util.concurrent.locks.ReentrantLock$NonfairSync : : class java.lang.management.LockInfo : java.util.concurrent.locks.ReentrantLock$NonfairSync@6ec249a8
- java.util.concurrent.locks.ReentrantLock$NonfairSync : : class java.lang.management.LockInfo : java.util.concurrent.locks.ReentrantLock$NonfairSync@666bf920