When using @ChangeUnit, if @Execution fails, and then @RollbackExecution fails, the original execution failure is not logged anywhere

[oliverlockwood]

Description

When using @ChangeUnit, if @Execution fails, and then @RollbackExecution fails, the original execution failure is not logged anywhere.

As a result I have to wrap every single @Execution method in a try/catch block to log exceptions myself.

PRIORITY

NORMAL

Version and environment

Mongock

• Mongock version: 5.3.6
• Modules involved: springboot, MongoDB
• How Mongock is used: some legacy @ChangeLog/@ChangeSet combinations, new @ChangeUnit

Environment

• Spring-Boot 3.1.8
• spring-data-mongodb 4.1.7

Steps to Reproduce

1. Create a @ChangeUnit class
2. Within it, create an @Execution method which throws an exception, and a @RollbackExecution method which throws a different exception
3. Run the application - the original exception is not logged anywhere

Behaviour

Expected behavior: I expect MongoDB to log the @Execution failure, as at least a warning, so I don't have to wrap every @Execution method with a try-catch to do the logging.

Actual behavior: No such log.

How often the bug happens: 100% of the time.

Link to repository using Mongock

Not provided.

Additional context

Here's a stacktrace showing the failure of the @RollbackExecution method - and nothing from the failure of the @Execution method.

io.mongock.api.exception.MongockException: java.lang.reflect.InvocationTargetException
    at io.mongock.runner.core.executor.ChangeExecutorBase.lambda$rollbackProcessedChangeSetsIfApply$4(ChangeExecutorBase.java:182)
    at java.base/java.util.ArrayDeque.forEach(Unknown Source)
    at io.mongock.runner.core.executor.ChangeExecutorBase.rollbackProcessedChangeSetsIfApply(ChangeExecutorBase.java:178)
    at io.mongock.runner.core.executor.ChangeExecutorBase.processSingleChangeLog(ChangeExecutorBase.java:130)
    at io.mongock.runner.core.executor.ChangeExecutorBase.processChangeLogs(ChangeExecutorBase.java:107)
    at io.mongock.runner.core.executor.ChangeExecutorBase.lambda$processMigration$1(ChangeExecutorBase.java:101)
    at io.mongock.runner.core.executor.NonTransactioner.executeInTransaction(NonTransactioner.java:17)
    at io.mongock.runner.core.executor.ChangeExecutorBase.processMigration(ChangeExecutorBase.java:101)
    at io.mongock.runner.core.executor.operation.migrate.MigrateExecutorBase.executeMigration(MigrateExecutorBase.java:66)
    at io.mongock.runner.core.executor.operation.migrate.MigrateExecutorBase.executeMigration(MigrateExecutorBase.java:18)
    at io.mongock.runner.core.executor.MongockRunnerImpl.execute(MongockRunnerImpl.java:57)
    at io.mongock.runner.springboot.base.MongockApplicationRunner.run(MongockApplicationRunner.java:18)
    at org.springframework.boot.SpringApplication.lambda$callRunner$4(SpringApplication.java:778)
    at org.springframework.util.function.ThrowingConsumer$1.acceptWithException(ThrowingConsumer.java:83)
    at org.springframework.util.function.ThrowingConsumer.accept(ThrowingConsumer.java:60)
    at org.springframework.util.function.ThrowingConsumer$1.accept(ThrowingConsumer.java:88)
    at org.springframework.boot.SpringApplication.callRunner(SpringApplication.java:790)
    at org.springframework.boot.SpringApplication.callRunner(SpringApplication.java:778)
    at org.springframework.boot.SpringApplication.lambda$callRunners$3(SpringApplication.java:766)
    at java.base/java.util.stream.ForEachOps$ForEachOp$OfRef.accept(Unknown Source)
    at java.base/java.util.stream.SortedOps$SizedRefSortingSink.end(Unknown Source)
    at java.base/java.util.stream.AbstractPipeline.copyInto(Unknown Source)
    at java.base/java.util.stream.AbstractPipeline.wrapAndCopyInto(Unknown Source)
    at java.base/java.util.stream.ForEachOps$ForEachOp.evaluateSequential(Unknown Source)
    at java.base/java.util.stream.ForEachOps$ForEachOp$OfRef.evaluateSequential(Unknown Source)
    at java.base/java.util.stream.AbstractPipeline.evaluate(Unknown Source)
    at java.base/java.util.stream.ReferencePipeline.forEach(Unknown Source)
    at org.springframework.boot.SpringApplication.callRunners(SpringApplication.java:766)
    at org.springframework.boot.SpringApplication.run(SpringApplication.java:331)
    at org.springframework.boot.SpringApplication.run(SpringApplication.java:1321)
    at org.springframework.boot.SpringApplication.run(SpringApplication.java:1310)
    at com.oliverlockwood.myapp.Application.main(Application.java:46)
    at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
    at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(Unknown Source)
    at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source)
    at java.base/java.lang.reflect.Method.invoke(Unknown Source)
    at org.springframework.boot.loader.MainMethodRunner.run(MainMethodRunner.java:49)
    at org.springframework.boot.loader.Launcher.launch(Launcher.java:95)
    at org.springframework.boot.loader.Launcher.launch(Launcher.java:58)
    at org.springframework.boot.loader.JarLauncher.main(JarLauncher.java:65)\nCaused by: java.lang.reflect.InvocationTargetException: null
    at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
    at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(Unknown Source)
    at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source)
    at java.base/java.lang.reflect.Method.invoke(Unknown Source)
    at io.mongock.runner.core.executor.ChangeLogRuntimeImpl.runChangeSet(ChangeLogRuntimeImpl.java:82)
    at io.mongock.runner.core.executor.ChangeExecutorBase.executeChangeSetMethod(ChangeExecutorBase.java:397)
    at io.mongock.runner.core.executor.ChangeExecutorBase.rollbackIfPresentAndTrackChangeEntry(ChangeExecutorBase.java:281)
    at io.mongock.runner.core.executor.ChangeExecutorBase.lambda$rollbackProcessedChangeSetsIfApply$4(ChangeExecutorBase.java:180)
    ... 39 common frames omitted\nCaused by: java.lang.UnsupportedOperationException: It is not practical to roll back this migration, which deletes (if present) and recreates an index
    at com.oliverlockwood.myapp.persistence.changesets.MongoMigration002.rollback(MongoMigration002.java:78)
    ... 47 common frames omitted

[osantana85]

Hello @oliverlockwood , thanks for raising the issue. We'll take a look and let you know as soon as possible.

[oliverlockwood]

@osantana85 are there any updates on this, please?

[osantana85]

Hello @oliverlockwood ,

When a ChangeUnit execution fails it will write something like this in the output log:

2024-03-26 11:32:32.998  INFO 60861 --- [           main] i.m.r.c.executor.ChangeLogRuntimeImpl    : method[io.mongock.examples.mongodb.springboot.quickstart.migration.ClientUpdaterChangeUnit] with arguments: []
2024-03-26 11:32:33.002  INFO 60861 --- [           main] i.m.r.c.executor.ChangeLogRuntimeImpl    : method[execution] with arguments: [org.springframework.data.mongodb.core.MongoTemplate]
2024-03-26 11:32:33.014  INFO 60861 --- [           main] i.m.r.core.executor.ChangeExecutorBase   : FAILED OVER - {"id"="client-updater", "type"="execution", "author"="mongock", "class"="ClientUpdaterChangeUnit", "method"="execution"}
2024-03-26 11:32:33.027  INFO 60861 --- [           main] i.m.r.core.executor.ChangeExecutorBase   : Mongock migration aborted and DB transaction not enabled. Starting manual rollback process
2024-03-26 11:32:33.032  INFO 60861 --- [           main] i.m.r.c.executor.ChangeLogRuntimeImpl    : method[rollbackExecution] with arguments: [org.springframework.data.mongodb.core.MongoTemplate]
2024-03-26 11:32:33.034  INFO 60861 --- [           main] i.m.r.core.executor.ChangeExecutorBase   : ROLL BACK FAILED- {"id"="client-updater", "type"="execution", "author"="mongock", "class"="ClientUpdaterChangeUnit", "method"="execution"}
2024-03-26 11:32:33.039  INFO 60861 --- [           main] i.m.driver.core.lock.LockManagerDefault  : Mongock waiting to release the lock
2024-03-26 11:32:33.039  INFO 60861 --- [           main] i.m.driver.core.lock.LockManagerDefault  : Mongock releasing the lock
2024-03-26 11:32:33.043  INFO 60861 --- [           main] i.m.driver.core.lock.LockManagerDefault  : Mongock released the lock
2024-03-26 11:32:33.043  INFO 60861 --- [           main] i.m.r.c.e.o.migrate.MigrateExecutorBase  : Mongock has finished
2024-03-26 11:32:33.046 ERROR 60861 --- [           main] i.m.r.core.executor.MongockRunnerImpl    : Error in mongock process. ABORTED OPERATION

Can you please attach your complete execution output log?

[dieppa]

@oliverlockwood is this still relevant or we can close it?

[oliverlockwood]

@dieppa @osantana85 yes, it is still relevant.

A log saying that the original execution failed, without giving the actual error and stacktrace of the original failure, is next to useless in diagnosing why the original execution failed.

Honestly, I had not thought it would be really necessary for me to spend the time to show my copy of the logs showing exactly the same "Error in MongoCK operation" log which you have already reproduced yourself, which demonstrates the issue pretty clearly. Do you see the details of the original error in your logs? No. That is the issue.

[dieppa]

@oliverlockwood I see your point and it totally make sense. I haven't looked at it myself, but the change should be relatively easy.

@osantana85 and myself will take of this, do a release shortly and let you know.

Thanks!

[osantana85]

@oliverlockwood released in Mongock's version 5.4.2.

[dieppa]

Thanks @osantana85