SagaCreationException causes are obfuscated

[mattupstate]

While developing a toy application I encountered a problem with saga creation. The exact problem was difficult to determine because of the exception handling hierarchy and minimal log output from the framework. For instance, the only feedback from Axon is from a log message produced by DefaultCommandGateway that looks like:

$ 2018-08-23 15:17:38.761  WARN 64992 --- [nio-8080-exec-3] o.a.c.gateway.DefaultCommandGateway      : Command 'com.example.command.StartRegistrationCommand' resulted in org.axonframework.eventhandling.saga.repository.SagaCreationException(An error occurred while attempting to create a new managed instance)

After digging around the source code and not finding anything that would log the underlying cause, I went ahead and installed a patch in my local Maven repository to afford myself more verbose log output (because I'm a bad debugger). I added a logger and some output in the AnnotatedSagaRepository::doCreateInstance method since that appears to be closest to the exception. Turns out, I didn't have an EventScheduler bean in my Spring Application context, of which the saga had a dependency on.

Maybe this is by design, or I'm missing something altogether, but I would expect some way to learn about the underlying cause of a saga not being able to be created via some log output from Axon.

Finally, and this is unrelated to the aforementioned issue, but is it also by design that the axon-spring-boot-autoconfigure module doesn't setup a SimpleEventScheduler bean by default?

[smcvb]

@mattupstate digging through Axon code does not immediately provide me a clear answer why your exception stack trace ends with the An error occurred while attempting to create a new managed instance message. I would have expected more info trailing it 🤔
As I requested on your User Group question, it might be something obvious from how you Saga is set up.

Would you be in the liberty to provide a snippet of your Saga, specifically with the EventScheduler added to it? And additionally, what version of Axon and Spring (I am assuming you're using Spring from your auto-config question) you are using.

For you final quesiton: The SimpleEventScheduler is not a default bean, as we do not regard it as a production ready EventScheduler. It stores the events in memory rather than actually persisting it, which posses a liability for production situations. We currently do not auto configure the QuartzEventScheduler as you have noticed. This might be something to be put on the back log.

Whilst we're on the topic of scheduling events, you might be interested in the DeadlineManager.
The DeadlineManager allows you to schedule a deadline in the scope of one specific Aggregate or Saga, which differs from the EventScheduler as the latter schedules an event, typically used as a deadline) for all the world to see.
The ref. guide adjustment is underway, so a sample should be visible soon.

Concluding though, if you would be able to provide some sample code of your saga, I think I will be able to write a dedicated test to verify this scenario and potentially adding clearer logging to the creation process.

[mattupstate]

@smcvb I realize now that a default SimpleEventScheduler would not be ideal out of the box, thanks for explaining that. I did notice the DeadlineManager feature that was added recently, just haven't got around to trying it out yet, but definitely will soon.

At any rate, seeing as this is just a toy app so far, here is what my saga implementation looks like with the caveat that it looks like this today, though it should look more or less the same as it did when I was experiencing the issue:

package com.example.domain.aggregate;

import com.example.domain.command.CompleteRegistrationCommand;
import com.example.domain.command.StartEmailAddressVerificationCommand;
import com.example.domain.event.EmailAddressVerificationCompletedEvent;
import com.example.domain.event.PhoneNumberVerificationCompletedEvent;
import com.example.domain.event.RegistrationCompletedEvent;
import com.example.domain.event.RegistrationDeadlineExpiredEvent;
import com.example.domain.event.RegistrationStartedEvent;
import com.example.domain.vo.UserId;
import com.example.domain.vo.VerificationToken;
import java.io.Serializable;
import java.time.Duration;
import lombok.Setter;
import lombok.extern.slf4j.Slf4j;
import org.axonframework.commandhandling.gateway.CommandGateway;
import org.axonframework.eventhandling.saga.EndSaga;
import org.axonframework.eventhandling.saga.SagaEventHandler;
import org.axonframework.eventhandling.saga.StartSaga;
import org.axonframework.eventhandling.scheduling.EventScheduler;
import org.axonframework.eventhandling.scheduling.ScheduleToken;
import org.axonframework.spring.stereotype.Saga;
import org.springframework.beans.factory.annotation.Autowired;

@Slf4j
@Saga
public class UserRegistrationSaga implements Serializable {

  @Setter(onMethod_ = {@Autowired})
  transient CommandGateway commandGateway;

  @Setter(onMethod_ = {@Autowired})
  transient EventScheduler eventScheduler;

  boolean emailAddressVerified = false;
  boolean phoneNumberVerified = false;
  ScheduleToken deadlineScheduleToken;

  @StartSaga
  @SagaEventHandler(associationProperty = "userId")
  public void handle(final RegistrationStartedEvent event) {
    log.debug("Received {}", event);

    final UserId userId = event.getUserId();
    final Duration completeRegistrationWithin = event.getCompleteRegistrationWithin();
    final String emailAddress = event.getEmailAddress();
    final String postEmailAddressVerificationUrl =
        event.getPostEmailAddressVerificationRedirectUrl();
    final Duration verifyEmailAddressWithin = event.getVerifyEmailAddressWithin();

    deadlineScheduleToken =
        eventScheduler.schedule(
            completeRegistrationWithin, new RegistrationDeadlineExpiredEvent(userId));

    log.debug(
        "Scheduled RegistrationDeadlineExpiredEvent to be published {} from now",
        completeRegistrationWithin);

    commandGateway.send(
        new StartEmailAddressVerificationCommand(
            userId,
            emailAddress,
            postEmailAddressVerificationUrl,
            verifyEmailAddressWithin,
            new VerificationToken()));
  }

  @SagaEventHandler(associationProperty = "userId")
  public void handle(final EmailAddressVerificationCompletedEvent event) {
    log.debug("Received {}", event);
    emailAddressVerified = true;
    checkForCompleteness(event.getUserId());
  }

  @SagaEventHandler(associationProperty = "userId")
  public void handle(final PhoneNumberVerificationCompletedEvent event) {
    log.debug("Received {}", event);
    phoneNumberVerified = true;
    checkForCompleteness(event.getUserId());
  }

  @EndSaga
  @SagaEventHandler(associationProperty = "userId")
  public void handle(final RegistrationCompletedEvent event) {
    log.debug("Received {}", event);
    eventScheduler.cancelSchedule(deadlineScheduleToken);
    logSagaHasEnded(event.getClass(), event.getUserId());
  }

  @EndSaga
  @SagaEventHandler(associationProperty = "userId")
  public void handle(final RegistrationDeadlineExpiredEvent event) {
    log.debug("Received {}", event);
    logSagaHasEnded(event.getClass(), event.getUserId());
  }

  private void checkForCompleteness(final UserId userId) {
    if (emailAddressVerified && phoneNumberVerified) {
      commandGateway.send(new CompleteRegistrationCommand(userId));
    }
  }

  private void logSagaHasEnded(final Class eventClass, final UserId userId) {
    logSagaHasEnded(eventClass.getSimpleName(), userId);
  }

  private void logSagaHasEnded(final String eventName, final UserId userId) {
    log.debug("{} caused UserRegistrationSaga to end. {}", eventName, userId);
  }
}

[smcvb]

Are you using Spring to auto configure your components @mattupstate?
I am not familiar with combining the @Setter of Lombok with the @Autowired annotation like you're doing.
If you replace that @Setter annotation with a regular @Autowired/@Inject, you should be fine with wiring your components. Taken you're in a Spring environment though.

If you're not, you will can leverage the ConfigurationResourceInjector to let Axon automatically wire infrastructure components like the CommandGateway and EventScheduler from the Configuration.
The CommandGateway will surely be pulled in, for the EventScheduler you might need to add it as a component to the Configurer.

[mattupstate]

@smcvb yes, I'm using Axon in a Spring Boot application. Everything works as expected with Lombok or with plain old setters with @Autowired (I tried both just in case). If it helps, here's how I'm configuring beans, including the EventScheduler:

package com.example.web.config;

import org.axonframework.eventsourcing.eventstore.EventStorageEngine;
import org.axonframework.eventsourcing.eventstore.inmemory.InMemoryEventStorageEngine;
import org.axonframework.spring.eventhandling.scheduling.java.SimpleEventSchedulerFactoryBean;
import org.springframework.context.annotation.Bean;
import org.springframework.context.annotation.Configuration;
import org.springframework.context.annotation.Profile;

@Configuration
@Profile("dev")
public class DevAxonConfiguration {

  @Bean
  public EventStorageEngine eventStorageEngine() {
    return new InMemoryEventStorageEngine();
  }

  @Bean
  public SimpleEventSchedulerFactoryBean simpleEventSchedulerFactoryBean() {
    return new SimpleEventSchedulerFactoryBean();
  }

  @Bean
  public CommandBusPostProcessor commandBusPostProcessor() {
    // Add's command message interceptors
    return new CommandBusPostProcessor();
  }
}

Now, if I remove SimpleEventSchedulerFactoryBean from the configuration Axon cannot create instances of the saga and will only provide the following console/log output:

2018-09-05 09:03:10.495 DEBUG 48667 --- [nio-8080-exec-3] c.example.domain.aggregate.User          : Received StartRegistrationCommand(userId=UserId(identifier=c7ed3d2f-bbe3-4d37-aebb-009cc33b2ea6), emailAddress=******@example.com, password=*****, timeZone=sun.util.calendar.ZoneInfo[id="America/New_York",offset=-18000000,dstSavings=3600000,useDaylight=true,transitions=235,lastRule=java.util.SimpleTimeZone[id=America/New_York,offset=-18000000,dstSavings=3600000,useDaylight=true,startYear=0,startMode=3,startMonth=2,startDay=8,startDayOfWeek=1,startTime=7200000,startTimeMode=0,endMode=3,endMonth=10,endDay=1,endDayOfWeek=1,endTime=7200000,endTimeMode=0]], locale=en_US, postEmailAddressVerificationRedirectUrl=http://localhost:4200, verifyEmailAddressWithin=PT20S, completeRegistrationWithin=PT2M)
2018-09-05 09:03:10.683 DEBUG 48667 --- [nio-8080-exec-3] c.example.domain.aggregate.User          : Received RegistrationStartedEvent(userId=UserId(identifier=c7ed3d2f-bbe3-4d37-aebb-009cc33b2ea6), emailAddress=******@example.com, passwordHash=******, postEmailAddressVerificationRedirectUrl=http://localhost:4200, verifyEmailAddressWithin=PT20S, completeRegistrationWithin=PT2M)
2018-09-05 09:03:10.733  WARN 48667 --- [nio-8080-exec-3] o.a.c.gateway.DefaultCommandGateway      : Command 'com.example.domain.command.StartRegistrationCommand' resulted in org.axonframework.eventhandling.saga.repository.SagaCreationException(An error occurred while attempting to create a new managed instance)

So the issue here, I think, is that Axon does not yet surface the underlying exception so I can understand exactly what went wrong when Axon tried to create an instance of the saga. But perhaps I'm missing something?

[smcvb]

Thanks for the explanation @mattupstate.
This should be sufficient info to investigate this inconvenience.

I get the feeling though that the issue you had, that the Saga wasn't being created, has been resolved by adding the SimpleEventSchedulerFactoryBean, correct?

That might make the issue less pressing for now, albeit still a nice clean up thing.
Any progress on this will be documented here, so you'll be kept up to date :-)

[mattupstate]

Yes, the issue I had had been solved. Just might have been able to solve it a bit quicker with some help from Axon ;-)

[smcvb]

Completely correct @mattupstate! I can assure you we will work on this so that future users will not run into the same issues you ran in to.

[abuijze]

The reason the exception isn't logged in its full "stacktrace glory" is because the result is also returned as part of the commandGateway.send method. The completable future there will complete exceptionally, providing you with all details.
We do not want to log stack traces when we return them, to prevent log pollution.

So I don't think the framework itself should do anything more than it's currently doing.