Events dispatched by the scheduler not played by Aggregate or Saga

Albert_Attard · December 19, 2017, 1:17pm

Hi everyone,

I am trying to use schedulers from within a Saga so that these fire an event at a given point in time. To keep the example simple I started with a basic Todo application where each Todo expires 5 seconds after it is created. Following is my Saga.

@Saga

public class TodoCompletionSaga implements Serializable {

private transient EventScheduler scheduler;
private ScheduleToken deadline;

@StartSaga
@SagaEventHandler(associationProperty = “todoId”)
public void handle(final TodoCreatedEvent event) {
deadline = scheduler.schedule(Duration.ofSeconds(5), TodoExpiredEvent.of(event.getTodoId()));
}

// Other methods omitted for brevity

}

The scheduler is triggered and an event is sent to the event bus as shown in one of the log entries emitted during the process.

2017-12-19 14:08:37.131 INFO 7628 — [actory_Worker-1] o.a.e.scheduling.quartz.FireEventJob : Job successfully executed. Scheduled Event [GenericEventMessage] has been published.

Unfortunately no event handler is capturing this event. Both my aggregate and the same sage are not invoked whenever this event is executed by the scheduler.

Any idea of what I am doing wrong?

Thanks in advance

allardbz · December 21, 2017, 1:24pm

Hi Albert,

just like any event, the Scheduled Events also need some form of association with the Saga instance. I can see you’re passing the “todoId” to the TodoExpiredEvent, but how did you configure the handler on the Saga?

I would expect a method like:

@SagaEventHandler(associationProperty = “todoId”)
public void handle(TodoExpiredEvent event) { … }

Cheers,

Allard

Albert_Attard · December 21, 2017, 1:32pm

Thank you for your reply Allard,

Yes, I am associating the saga method that deals with this event with the todoId as shown next.

@EndSaga
@SagaEventHandler(associationProperty = “todoId”)
public void handle(final TodoExpiredEvent event) {
TodoCompletionSaga.LOGGER.debug(“Todo {} has expired”, event.getTodoId());
if (deadline != null) {
scheduler.cancelSchedule(deadline);
}
}

Furthermore, the aggregate too is not capturing this event, which parts of the aggregate are shown next

@Aggregate
public class Todo {

private static final Logger LOGGER = LoggerFactory.getLogger(Todo.class);

@AggregateIdentifier
private TodoId todoId;
private TodoStage stage;

@EventSourcingHandler
public void apply(final TodoExpiredEvent event) {
Todo.LOGGER.debug(“Expired command: {}”, event);
stage = TodoStage.EXPIRED;
}
}

All other command and events are working well, but the expired event triggered through the scheduler is not captured by the expected handlers.

allardbz · December 21, 2017, 3:20pm

The Saga should be able to receive this event. However, that the Aggregate doesn’t receive this event, is normal. Aggregates only “see” events they have applied / published themselves. That is because the handlers there are used for Event Sourcing, not general event handling.

Don’t you see the Saga handling the event either? Are you use the todoId is correctly passed to the field and then getter? It wouldn’t be the first case I where a missing field assignment caused an issue…

Cheers,

Allard

Albert_Attard · December 21, 2017, 9:44pm

Thank you for your replay Allard.

No the Saga is not receiving the event. I had the impression that the @SagaEventHandler validates the associationProperty and I believe that an exception is thrown if this is not present.

I understand that the event are serialized by the scheduler using the Java Serialization and this tested for that too.

@Test
public void serialization() {
final TodoExpiredEvent event = TodoExpiredEvent.of(TodoId.random());
final byte[] bytes = SerializationUtils.serialize(event);
final Object deserialised = SerializationUtils.deserialize(bytes);
Assert.assertEquals(event, deserialised);
Assert.assertEquals(event.getTodoId(), ((TodoExpiredEvent) deserialised).getTodoId());
}

Following are the two Saga methods in question.

@StartSaga
@SagaEventHandler(associationProperty = “todoId”)
public void handle(final TodoCreatedEvent event) {
TodoCompletionSaga.LOGGER.debug(“Todo started: {}”, event.getTodoId());
deadline = scheduler.schedule(Duration.ofSeconds(5), TodoExpiredEvent.of(event.getTodoId()));
TodoCompletionSaga.LOGGER.debug(“Deadline: {}”, deadline);
}

@EndSaga
@SagaEventHandler(associationProperty = “todoId”)
public void handle(final TodoExpiredEvent event) {
TodoCompletionSaga.LOGGER.debug(“Todo {} has expired”, event.getTodoId());
if (deadline != null) {
scheduler.cancelSchedule(deadline);
}
}

The scheduler publishes the event object but the saga’s event handler never gets triggered as shown in the following log fragment (highlighted the areas of interest)

2017-12-21 22:03:19.871 DEBUG 11604 — [ restartedMain] o.a.common.IdentifierFactory : Using default UUID-based IdentifierFactory
2017-12-21 22:03:19.874 DEBUG 11604 — [ restartedMain] o.a.commandhandling.SimpleCommandBus : Handling command [com.javacreed.examples.axon.todo.CreateTodoCommand]
2017-12-21 22:03:19.877 DEBUG 11604 — [ restartedMain] o.a.m.unitofwork.AbstractUnitOfWork : Starting Unit Of Work
2017-12-21 22:03:19.877 DEBUG 11604 — [SchedulerThread] org.quartz.core.QuartzSchedulerThread : batch acquisition of 0 triggers
2017-12-21 22:03:19.904 DEBUG 11604 — [ restartedMain] o.a.m.u.MessageProcessingContext : Adding handler org.axonframework.messaging.unitofwork.AbstractUnitOfWork$$Lambda$220/1848160916 for phase ROLLBACK
2017-12-21 22:03:19.905 DEBUG 11604 — [ restartedMain] o.a.m.u.MessageProcessingContext : Notifying handlers for phase STARTED
2017-12-21 22:03:19.911 DEBUG 11604 — [ restartedMain] o.a.m.u.MessageProcessingContext : Adding handler org.axonframework.commandhandling.SimpleCommandBus$$Lambda$224/865163146 for phase COMMIT
2017-12-21 22:03:19.920 DEBUG 11604 — [ restartedMain] o.a.m.u.MessageProcessingContext : Adding handler org.axonframework.commandhandling.SimpleCommandBus$$Lambda$225/1197151042 for phase ROLLBACK
2017-12-21 22:03:19.932 DEBUG 11604 — [ restartedMain] o.a.m.u.MessageProcessingContext : Adding handler org.axonframework.eventhandling.AbstractEventBus$$Lambda$244/506084848 for phase PREPARE_COMMIT
2017-12-21 22:03:19.932 DEBUG 11604 — [ restartedMain] o.a.m.u.MessageProcessingContext : Adding handler org.axonframework.eventhandling.AbstractEventBus$$Lambda$245/1277405206 for phase COMMIT
2017-12-21 22:03:19.933 DEBUG 11604 — [ restartedMain] o.a.m.u.MessageProcessingContext : Adding handler org.axonframework.eventhandling.AbstractEventBus$$Lambda$246/1849321786 for phase AFTER_COMMIT
2017-12-21 22:03:19.933 DEBUG 11604 — [ restartedMain] o.a.m.u.MessageProcessingContext : Adding handler org.axonframework.eventhandling.AbstractEventBus$$Lambda$247/692124702 for phase CLEANUP
2017-12-21 22:03:19.935 DEBUG 11604 — [ restartedMain] o.a.m.u.MessageProcessingContext : Adding handler org.axonframework.commandhandling.model.LockingRepository$$Lambda$248/656475673 for phase CLEANUP
2017-12-21 22:03:19.936 DEBUG 11604 — [ restartedMain] o.a.m.u.MessageProcessingContext : Adding handler org.axonframework.commandhandling.model.AbstractRepository$$Lambda$252/1866405795 for phase ROLLBACK
2017-12-21 22:03:19.937 DEBUG 11604 — [ restartedMain] o.a.m.u.MessageProcessingContext : Adding handler org.axonframework.commandhandling.model.AbstractRepository$$Lambda$254/1835623073 for phase PREPARE_COMMIT
2017-12-21 22:03:19.939 DEBUG 11604 — [ restartedMain] o.a.m.unitofwork.AbstractUnitOfWork : Committing Unit Of Work
2017-12-21 22:03:19.939 DEBUG 11604 — [ restartedMain] o.a.m.u.MessageProcessingContext : Notifying handlers for phase PREPARE_COMMIT
2017-12-21 22:03:20.073 DEBUG 11604 — [ restartedMain] o.a.m.unitofwork.AbstractUnitOfWork : Starting Unit Of Work
2017-12-21 22:03:20.073 DEBUG 11604 — [ restartedMain] o.a.m.u.MessageProcessingContext : Adding handler org.axonframework.messaging.unitofwork.AbstractUnitOfWork$$Lambda$220/1848160916 for phase ROLLBACK
2017-12-21 22:03:20.073 DEBUG 11604 — [ restartedMain] o.a.m.u.MessageProcessingContext : Adding handler org.axonframework.messaging.unitofwork.AbstractUnitOfWork$$Lambda$277/1956472485 for phase CLEANUP
2017-12-21 22:03:20.074 DEBUG 11604 — [ restartedMain] o.a.m.u.MessageProcessingContext : Notifying handlers for phase STARTED
2017-12-21 22:03:20.133 DEBUG 11604 — [ restartedMain] o.a.m.u.MessageProcessingContext : Adding handler org.axonframework.eventhandling.saga.repository.LockingSagaRepository$$Lambda$302/1934269158 for phase CLEANUP
2017-12-21 22:03:20.138 DEBUG 11604 — [ restartedMain] o.a.m.u.MessageProcessingContext : Adding handler org.axonframework.eventhandling.saga.repository.AnnotatedSagaRepository$$Lambda$305/1425980838 for phase PREPARE_COMMIT
2017-12-21 22:03:20.144 DEBUG 11604 — [ restartedMain] o.a.m.u.MessageProcessingContext : Adding handler org.axonframework.eventhandling.saga.repository.AnnotatedSagaRepository$$Lambda$306/1155520366 for phase CLEANUP

2017-12-21 22:03:20.146 DEBUG 11604 — [ restartedMain] c.j.e.axon.todo.TodoCompletionSaga : Todo started: 7f418565-b37c-482d-b3c1-d4cbb32d5ab7

2017-12-21 22:03:20.156 DEBUG 11604 — [ restartedMain] o.q.i.jdbcjobstore.StdRowLockSemaphore : Lock ‘TRIGGER_ACCESS’ is desired by: restartedMain
2017-12-21 22:03:20.156 DEBUG 11604 — [ restartedMain] o.q.i.jdbcjobstore.StdRowLockSemaphore : Lock ‘TRIGGER_ACCESS’ is being obtained: restartedMain
2017-12-21 22:03:20.158 DEBUG 11604 — [ restartedMain] o.q.i.jdbcjobstore.StdRowLockSemaphore : Lock ‘TRIGGER_ACCESS’ given to: restartedMain
2017-12-21 22:03:20.310 DEBUG 11604 — [ restartedMain] o.q.i.jdbcjobstore.StdRowLockSemaphore : Lock ‘TRIGGER_ACCESS’ returned by: restartedMain

2017-12-21 22:03:20.311 DEBUG 11604 — [ restartedMain] c.j.e.axon.todo.TodoCompletionSaga : Deadline: Quartz Schedule token for job [event-b922da4c-5a44-4e7d-8ddc-f56d274a215c] in group [AxonFramework-Events]

2017-12-21 22:03:20.311 DEBUG 11604 — [ restartedMain] o.a.m.unitofwork.AbstractUnitOfWork : Committing Unit Of Work
2017-12-21 22:03:20.311 DEBUG 11604 — [ restartedMain] o.a.m.u.MessageProcessingContext : Notifying handlers for phase PREPARE_COMMIT
2017-12-21 22:03:20.313 DEBUG 11604 — [SchedulerThread] org.quartz.core.QuartzSchedulerThread : batch acquisition of 0 triggers
2017-12-21 22:03:20.406 DEBUG 11604 — [ restartedMain] o.a.e.saga.repository.jpa.JpaSagaStore : Storing saga id 9db7878b-155d-4c9c-aa80-31a4319a38f8 as <com.javacreed.examples.axon.todo.TodoCompletionSaga>event-b922da4c-5a44-4e7d-8ddc-f56d274a215cAxonFramework-Events</com.javacreed.examples.axon.todo.TodoCompletionSaga>
2017-12-21 22:03:20.406 DEBUG 11604 — [ restartedMain] o.a.m.u.MessageProcessingContext : Notifying handlers for phase COMMIT
2017-12-21 22:03:20.407 DEBUG 11604 — [ restartedMain] o.a.m.u.MessageProcessingContext : Adding handler org.axonframework.messaging.unitofwork.AbstractUnitOfWork$$Lambda$311/460911243 for phase AFTER_COMMIT
2017-12-21 22:03:20.407 DEBUG 11604 — [ restartedMain] o.a.m.u.MessageProcessingContext : Adding handler org.axonframework.messaging.unitofwork.AbstractUnitOfWork$$Lambda$312/1761807290 for phase ROLLBACK
2017-12-21 22:03:20.408 DEBUG 11604 — [ restartedMain] o.a.m.u.MessageProcessingContext : Notifying handlers for phase COMMIT
2017-12-21 22:03:20.416 DEBUG 11604 — [ restartedMain] o.a.m.u.MessageProcessingContext : Notifying handlers for phase AFTER_COMMIT
2017-12-21 22:03:20.422 DEBUG 11604 — [ restartedMain] o.a.m.u.MessageProcessingContext : Notifying handlers for phase AFTER_COMMIT
2017-12-21 22:03:20.423 DEBUG 11604 — [ restartedMain] o.a.m.u.MessageProcessingContext : Notifying handlers for phase CLEANUP
2017-12-21 22:03:20.423 DEBUG 11604 — [ restartedMain] o.a.m.u.MessageProcessingContext : Notifying handlers for phase CLEANUP
2017-12-21 22:03:20.423 DEBUG 11604 — [ restartedMain] o.a.m.u.MessageProcessingContext : Notifying handlers for phase CLOSED
2017-12-21 22:03:20.423 DEBUG 11604 — [ restartedMain] o.a.m.u.MessageProcessingContext : Notifying handlers for phase CLOSED
2017-12-21 22:03:20.423 DEBUG 11604 — [ restartedMain] com.javacreed.examples.axon.Demo : Seeping for 120 seconds
2017-12-21 22:03:46.625 DEBUG 11604 — [SchedulerThread] org.quartz.core.QuartzSchedulerThread : batch acquisition of 1 triggers
2017-12-21 22:03:46.632 DEBUG 11604 — [SchedulerThread] o.q.i.jdbcjobstore.StdRowLockSemaphore : Lock ‘TRIGGER_ACCESS’ is desired by: schedulerFactory_QuartzSchedulerThread
2017-12-21 22:03:46.639 DEBUG 11604 — [SchedulerThread] o.q.i.jdbcjobstore.StdRowLockSemaphore : Lock ‘TRIGGER_ACCESS’ is being obtained: schedulerFactory_QuartzSchedulerThread
2017-12-21 22:03:46.639 DEBUG 11604 — [SchedulerThread] o.q.i.jdbcjobstore.StdRowLockSemaphore : Lock ‘TRIGGER_ACCESS’ given to: schedulerFactory_QuartzSchedulerThread
2017-12-21 22:03:46.679 DEBUG 11604 — [SchedulerThread] o.q.i.jdbcjobstore.StdRowLockSemaphore : Lock ‘TRIGGER_ACCESS’ returned by: schedulerFactory_QuartzSchedulerThread
2017-12-21 22:03:46.682 DEBUG 11604 — [SchedulerThread] c.j.e.a.q.AutowiringSpringBeanJobFactory : Creating job from bundle: org.quartz.spi.TriggerFiredBundle@60feb87b
2017-12-21 22:03:46.685 DEBUG 11604 — [SchedulerThread] c.j.e.a.q.AutowiringSpringBeanJobFactory : Job created: org.axonframework.eventhandling.scheduling.quartz.FireEventJob@799c98a1
2017-12-21 22:03:46.687 DEBUG 11604 — [actory_Worker-1] org.quartz.core.JobRunShell : Calling execute on job AxonFramework-Events.event-b922da4c-5a44-4e7d-8ddc-f56d274a215c
2017-12-21 22:03:46.687 DEBUG 11604 — [actory_Worker-1] o.a.e.scheduling.quartz.FireEventJob : Starting job to publish a scheduled event
2017-12-21 22:03:46.687 DEBUG 11604 — [actory_Worker-1] o.a.m.unitofwork.AbstractUnitOfWork : Starting Unit Of Work
2017-12-21 22:03:46.688 DEBUG 11604 — [SchedulerThread] org.quartz.core.QuartzSchedulerThread : batch acquisition of 0 triggers
2017-12-21 22:03:46.693 DEBUG 11604 — [actory_Worker-1] o.a.m.u.MessageProcessingContext : Adding handler org.axonframework.messaging.unitofwork.AbstractUnitOfWork$$Lambda$220/1848160916 for phase ROLLBACK
2017-12-21 22:03:46.693 DEBUG 11604 — [actory_Worker-1] o.a.m.u.MessageProcessingContext : Notifying handlers for phase STARTED
2017-12-21 22:03:46.694 DEBUG 11604 — [actory_Worker-1] o.a.m.u.MessageProcessingContext : Adding handler org.axonframework.eventhandling.scheduling.quartz.FireEventJob$$Lambda$317/1102514343 for phase COMMIT
2017-12-21 22:03:46.695 DEBUG 11604 — [actory_Worker-1] o.a.m.u.MessageProcessingContext : Adding handler org.axonframework.eventhandling.scheduling.quartz.FireEventJob$$Lambda$318/1166578761 for phase ROLLBACK
2017-12-21 22:03:46.696 DEBUG 11604 — [actory_Worker-1] o.a.m.u.MessageProcessingContext : Adding handler org.axonframework.eventhandling.AbstractEventBus$$Lambda$244/506084848 for phase PREPARE_COMMIT
2017-12-21 22:03:46.696 DEBUG 11604 — [actory_Worker-1] o.a.m.u.MessageProcessingContext : Adding handler org.axonframework.eventhandling.AbstractEventBus$$Lambda$245/1277405206 for phase COMMIT
2017-12-21 22:03:46.696 DEBUG 11604 — [actory_Worker-1] o.a.m.u.MessageProcessingContext : Adding handler org.axonframework.eventhandling.AbstractEventBus$$Lambda$246/1849321786 for phase AFTER_COMMIT
2017-12-21 22:03:46.696 DEBUG 11604 — [actory_Worker-1] o.a.m.u.MessageProcessingContext : Adding handler org.axonframework.eventhandling.AbstractEventBus$$Lambda$247/692124702 for phase CLEANUP
2017-12-21 22:03:46.696 DEBUG 11604 — [actory_Worker-1] o.a.m.unitofwork.AbstractUnitOfWork : Committing Unit Of Work
2017-12-21 22:03:46.696 DEBUG 11604 — [actory_Worker-1] o.a.m.u.MessageProcessingContext : Notifying handlers for phase PREPARE_COMMIT
2017-12-21 22:03:46.756 DEBUG 11604 — [actory_Worker-1] o.a.m.unitofwork.AbstractUnitOfWork : Starting Unit Of Work
2017-12-21 22:03:46.756 DEBUG 11604 — [actory_Worker-1] o.a.m.u.MessageProcessingContext : Adding handler org.axonframework.messaging.unitofwork.AbstractUnitOfWork$$Lambda$220/1848160916 for phase ROLLBACK
2017-12-21 22:03:46.756 DEBUG 11604 — [actory_Worker-1] o.a.m.u.MessageProcessingContext : Adding handler org.axonframework.messaging.unitofwork.AbstractUnitOfWork$$Lambda$277/1956472485 for phase CLEANUP
2017-12-21 22:03:46.756 DEBUG 11604 — [actory_Worker-1] o.a.m.u.MessageProcessingContext : Notifying handlers for phase STARTED
2017-12-21 22:03:46.756 DEBUG 11604 — [actory_Worker-1] o.a.m.unitofwork.AbstractUnitOfWork : Committing Unit Of Work
2017-12-21 22:03:46.762 DEBUG 11604 — [actory_Worker-1] o.a.m.u.MessageProcessingContext : Notifying handlers for phase PREPARE_COMMIT
2017-12-21 22:03:46.763 DEBUG 11604 — [actory_Worker-1] o.a.m.u.MessageProcessingContext : Notifying handlers for phase COMMIT
2017-12-21 22:03:46.763 DEBUG 11604 — [actory_Worker-1] o.a.m.u.MessageProcessingContext : Adding handler org.axonframework.messaging.unitofwork.AbstractUnitOfWork$$Lambda$311/460911243 for phase AFTER_COMMIT
2017-12-21 22:03:46.763 DEBUG 11604 — [actory_Worker-1] o.a.m.u.MessageProcessingContext : Adding handler org.axonframework.messaging.unitofwork.AbstractUnitOfWork$$Lambda$312/1761807290 for phase ROLLBACK
2017-12-21 22:03:46.763 DEBUG 11604 — [actory_Worker-1] o.a.m.u.MessageProcessingContext : Notifying handlers for phase COMMIT
2017-12-21 22:03:46.798 DEBUG 11604 — [actory_Worker-1] o.a.m.u.MessageProcessingContext : Notifying handlers for phase AFTER_COMMIT
2017-12-21 22:03:46.798 DEBUG 11604 — [actory_Worker-1] o.a.m.u.MessageProcessingContext : Notifying handlers for phase AFTER_COMMIT
2017-12-21 22:03:46.798 DEBUG 11604 — [actory_Worker-1] o.a.m.u.MessageProcessingContext : Notifying handlers for phase CLEANUP
2017-12-21 22:03:46.798 DEBUG 11604 — [actory_Worker-1] o.a.m.u.MessageProcessingContext : Notifying handlers for phase CLEANUP
2017-12-21 22:03:46.798 DEBUG 11604 — [actory_Worker-1] o.a.m.u.MessageProcessingContext : Notifying handlers for phase CLOSED
2017-12-21 22:03:46.798 DEBUG 11604 — [actory_Worker-1] o.a.m.u.MessageProcessingContext : Notifying handlers for phase CLOSED

2017-12-21 22:03:46.798 INFO 11604 — [actory_Worker-1] o.a.e.scheduling.quartz.FireEventJob : Job successfully executed. Scheduled Event [GenericEventMessage] has been published.

2017-12-21 22:03:46.800 DEBUG 11604 — [actory_Worker-1] o.q.i.jdbcjobstore.StdRowLockSemaphore : Lock ‘TRIGGER_ACCESS’ is desired by: schedulerFactory_Worker-1
2017-12-21 22:03:46.801 DEBUG 11604 — [actory_Worker-1] o.q.i.jdbcjobstore.StdRowLockSemaphore : Lock ‘TRIGGER_ACCESS’ is being obtained: schedulerFactory_Worker-1
2017-12-21 22:03:46.801 DEBUG 11604 — [actory_Worker-1] o.q.i.jdbcjobstore.StdRowLockSemaphore : Lock ‘TRIGGER_ACCESS’ given to: schedulerFactory_Worker-1
2017-12-21 22:03:46.924 DEBUG 11604 — [actory_Worker-1] o.q.i.jdbcjobstore.StdRowLockSemaphore : Lock ‘TRIGGER_ACCESS’ returned by: schedulerFactory_Worker-1
2017-12-21 22:04:12.894 DEBUG 11604 — [SchedulerThread] org.quartz.core.QuartzSchedulerThread : batch acquisition of 0 triggers
2017-12-21 22:04:42.029 DEBUG 11604 — [SchedulerThread] org.quartz.core.QuartzSchedulerThread : batch acquisition of 0 triggers
2017-12-21 22:05:06.430 DEBUG 11604 — [SchedulerThread] org.quartz.core.QuartzSchedulerThread : batch acquisition of 0 triggers
2017-12-21 22:05:20.429 DEBUG 11604 — [ restartedMain] com.javacreed.examples.axon.Demo : Done

I am trying to understand what’s wrong but I cannot get my head around it. Any help is really appreciated.

Thanks again,

Albert_Attard · December 21, 2017, 10:14pm

Hi,

In order to see better what is happening I have added an event handler that captures all events.

import org.axonframework.eventhandling.EventHandler;
import org.axonframework.eventhandling.GenericEventMessage;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
import org.springframework.stereotype.Service;

@Service
public class EventInspectorService {

private static final Logger LOGGER = LoggerFactory.getLogger(EventInspectorService.class);

@EventHandler
public void handle(final Object event) {
EventInspectorService.LOGGER.debug(“Event: {}”, event.getClass().getCanonicalName());
EventInspectorService.LOGGER.debug(" {}", event);

if (event instanceof GenericEventMessage) {
final GenericEventMessage<?> message = (GenericEventMessage<?>) event;
final Object payload = message.getPayload();
EventInspectorService.LOGGER.debug(“Payload: {}”, payload.getClass().getCanonicalName());
EventInspectorService.LOGGER.debug(" {}", payload);
}
}
}

I noticed that the event that is being published by the scheduler is of type org.axonframework.eventhandling.GenericEventMessage and not TodoExpiredEvent. When looking at this variable with the debugger, noticed that payload is of type TodoExpiredEvent.

2017-12-21 22:40:57.841 DEBUG 12292 — [actory_Worker-1] c.j.e.axon.todo.EventInspectorService : Event: org.axonframework.eventhandling.GenericEventMessage
2017-12-21 22:40:57.841 DEBUG 12292 — [actory_Worker-1] c.j.e.axon.todo.EventInspectorService : org.axonframework.eventhandling.GenericEventMessage@7ec567ad

Furthermore, strangely enough the instanceof check is resolving to false. I could not understand this, given that AXON is only loaded through the axon-spring-boot-starter dependency (see attached image). I am lost here and any help is more than welcome. It seems that the object returned by the scheduler is not of the expected type and maybe that’s why the Saga is not getting the event. This can be possible due to class conflict (same class loaded from different JARs or by different class loaders), even though I am not seeing that. Can it be that I am missing some configuration? I’ve attached the complete project for reference.

Thanks again,
Albert

Dependency Hiererchy.png

saga-quartz-axon-example.zip (21.8 KB)

Albert_Attard · December 21, 2017, 10:26pm

Hi,

Maven is not showing any collisions

mvn dependency:tree -Dverbose -Dincludes=org.axonframework
[INFO] Scanning for projects…
[INFO]
[INFO] ------------------------------------------------------------------------
[INFO] Building saga-quartz-axon-example 0.0.1-SNAPSHOT
[INFO] ------------------------------------------------------------------------
[INFO]
[INFO] — maven-dependency-plugin:2.10:tree (default-cli) @ saga-quartz-axon-example —
[WARNING] Using Maven 2 dependency tree to get verbose output, which may be inconsistent with actual Maven 3 resolution
[INFO] com.javacreed.examples:saga-quartz-axon-example:jar:0.0.1-SNAPSHOT
[INFO] ± org.axonframework:axon-spring-boot-starter:jar:3.1:compile
[INFO] | - org.axonframework:axon-spring-boot-autoconfigure:jar:3.1:compile
[INFO] | - org.axonframework:axon-spring:jar:3.1:compile
[INFO] | - org.axonframework:axon-core:jar:3.1:compile
[INFO] - org.axonframework:axon-test:jar:3.1:test
[INFO] - (org.axonframework:axon-core:jar:3.1:compile - scope updated from test; omitted for duplicate)
[INFO] ------------------------------------------------------------------------
[INFO] BUILD SUCCESS
[INFO] ------------------------------------------------------------------------

Regards,

allardbz · December 22, 2017, 8:44am

Hi,

if instanceof on the message’s payload returns false, but the class names are identical, this means the classes have been loaded by different class loaders.
Are you using Spring-Boot-DevTools? It does some class loading tricks that not all frameworks are familiar with. Axon has been adapted (as much as possible) to account for these class loading tricks, but perhaps Quartz hasn’t. Alternatively, did you explicitly define a serializer in your Spring context?

Allard

Albert_Attard · December 22, 2017, 4:55pm

You were right Allard.

The Spring Boot Dev-Tools was causing the issue. Once I commented our the dependency for the dev-tools, things started to work as expected.

Thanks again for your support
Albert Attard