refactor: improved logging/report pipeline

dieppa · dieppa · commit 779e3fdba5e0 · 2026-05-25T12:35:53.000+01:00
diff --git a/core/flamingock-core-commons/src/main/java/io/flamingock/internal/common/core/response/data/ChangeResult.java b/core/flamingock-core-commons/src/main/java/io/flamingock/internal/common/core/response/data/ChangeResult.java
@@ -101,6 +101,10 @@ public boolean isFailed() {
         return status == ChangeStatus.FAILED;
     }
 
+    public boolean isRolledBack() {
+        return status == ChangeStatus.ROLLED_BACK;
+    }
+
     public boolean isApplied() {
         return status == ChangeStatus.APPLIED;
     }
diff --git a/core/flamingock-core-commons/src/main/java/io/flamingock/internal/common/core/response/data/ExecutionReportFormatter.java b/core/flamingock-core-commons/src/main/java/io/flamingock/internal/common/core/response/data/ExecutionReportFormatter.java
@@ -138,7 +138,9 @@ private static void appendStageBlock(StringBuilder sb, StageResult stage) {
         List<ChangeResult> changes = stage.getChanges() != null ? stage.getChanges() : Collections.emptyList();
         int applied = (int) changes.stream().filter(c -> c != null && c.isApplied()).count();
         int skipped = (int) changes.stream().filter(c -> c != null && c.isAlreadyApplied()).count();
-        int failed = (int) changes.stream().filter(c -> c != null && c.isFailed()).count();
+        // ROLLED_BACK is widened into the failed bucket — the change did not succeed even though
+        // the system was left clean. See PipelineRun.toResponse() for the matching aggregate logic.
+        int failed = (int) changes.stream().filter(c -> c != null && (c.isFailed() || c.isRolledBack())).count();
         sb.append("               changes: ")
           .append(applied).append(" applied, ")
           .append(skipped).append(" skipped, ")
@@ -261,7 +263,7 @@ private static List<String> failedChangeIds(StageResult stage) {
             return Collections.emptyList();
         }
         return changes.stream()
-                .filter(c -> c != null && c.isFailed() && c.getChangeId() != null)
+                .filter(c -> c != null && (c.isFailed() || c.isRolledBack()) && c.getChangeId() != null)
                 .map(ChangeResult::getChangeId)
                 .collect(Collectors.toList());
     }
diff --git a/core/flamingock-core-commons/src/test/java/io/flamingock/internal/common/core/response/data/ExecutionReportFormatterTest.java b/core/flamingock-core-commons/src/test/java/io/flamingock/internal/common/core/response/data/ExecutionReportFormatterTest.java
@@ -205,10 +205,67 @@ void reportToleratesStageWithNullStateAndNullChanges() {
         assertTrue(out.contains("(unnamed)"), out);
     }
 
+    @Test
+    void reportCountsRolledBackChangeAsFailedAndListsItsId() {
+        // Scenario mirrors the real-world MongoDB duplicate-key case: 5 already-applied changes
+        // plus 1 transactional change that failed and was auto-rolled-back (status ROLLED_BACK).
+        // The user-facing report must show 1 failed and list the change ID.
+        StageResult stage = StageResult.builder()
+                .stageId("database-init").stageName("database-init")
+                .state(StageState.failed(new ErrorInfo("MongoWriteException",
+                        "E11000 duplicate key", Collections.singletonList("InsertSeedData"),
+                        "database-init")))
+                .durationMs(126)
+                .changes(Arrays.asList(
+                        skippedChange("CreateCustomersTable"),
+                        skippedChange("CreateOrdersTable"),
+                        skippedChange("InsertSeedData"),
+                        skippedChange("CreateEmployeesTable"),
+                        skippedChange("CreateEmployeesCollection"),
+                        rolledBackChange("InsertEmployeeSeedData", "MongoWriteException", "E11000 duplicate key")))
+                .build();
+        ExecuteResponseData result = ExecuteResponseData.builder()
+                .status(ExecutionStatus.FAILED)
+                .totalStages(1).failedStages(1)
+                .totalChanges(6).appliedChanges(0).skippedChanges(5).failedChanges(1)
+                .totalDurationMs(221)
+                .stages(Collections.singletonList(stage))
+                .build();
+
+        String out = ExecutionReportFormatter.report(result);
+        assertTrue(out.contains("0 applied, 5 skipped, 1 failed"),
+                "per-stage block must count ROLLED_BACK as failed: " + out);
+        assertTrue(out.contains("failed change(s): InsertEmployeeSeedData"),
+                "failed change(s) line must include the rolled-back change ID: " + out);
+    }
+
+    @Test
+    void summaryCountsRolledBackChangeAsFailed() {
+        StageResult stage = StageResult.builder()
+                .stageId("database-init").stageName("database-init")
+                .state(StageState.failed(new ErrorInfo("MongoWriteException", "boom",
+                        Collections.singletonList("InsertEmployeeSeedData"), "database-init")))
+                .changes(Collections.singletonList(rolledBackChange("InsertEmployeeSeedData", "MongoWriteException", "boom")))
+                .build();
+        ExecuteResponseData result = ExecuteResponseData.builder()
+                .status(ExecutionStatus.FAILED)
+                .totalStages(1).failedStages(1)
+                .totalChanges(1).failedChanges(1)
+                .stages(Collections.singletonList(stage))
+                .build();
+
+        String out = ExecutionReportFormatter.summary(result);
+        assertTrue(out.contains("failed=1"), "summary must reflect ROLLED_BACK in failed=N: " + out);
+    }
+
     private static ChangeResult appliedChange(String id) {
         return ChangeResult.builder().changeId(id).status(ChangeStatus.APPLIED).build();
     }
 
+    private static ChangeResult skippedChange(String id) {
+        return ChangeResult.builder().changeId(id).status(ChangeStatus.ALREADY_APPLIED).build();
+    }
+
     private static ChangeResult failedChange(String id, String errorType, String errorMessage) {
         return ChangeResult.builder()
                 .changeId(id)
@@ -217,4 +274,13 @@ private static ChangeResult failedChange(String id, String errorType, String err
                 .errorMessage(errorMessage)
                 .build();
     }
+
+    private static ChangeResult rolledBackChange(String id, String errorType, String errorMessage) {
+        return ChangeResult.builder()
+                .changeId(id)
+                .status(ChangeStatus.ROLLED_BACK)
+                .errorType(errorType)
+                .errorMessage(errorMessage)
+                .build();
+    }
 }
diff --git a/core/flamingock-core/src/main/java/io/flamingock/internal/core/event/listener/DefaultPipelineCompletedReportListener.java b/core/flamingock-core/src/main/java/io/flamingock/internal/core/event/listener/DefaultPipelineCompletedReportListener.java
@@ -32,7 +32,8 @@
  */
 public final class DefaultPipelineCompletedReportListener implements Consumer<IPipelineCompletedEvent> {
 
-    public static final String LOGGER_NAME = "FK-Report";
+    // Bare component name; FlamingockLoggerFactory.getLogger prepends "FK-" → "FK-Report".
+    public static final String LOGGER_NAME = "Report";
 
     private static final Logger logger = FlamingockLoggerFactory.getLogger(LOGGER_NAME);
 
diff --git a/core/flamingock-core/src/main/java/io/flamingock/internal/core/event/listener/DefaultPipelineFailedReportListener.java b/core/flamingock-core/src/main/java/io/flamingock/internal/core/event/listener/DefaultPipelineFailedReportListener.java
@@ -34,7 +34,8 @@
  */
 public final class DefaultPipelineFailedReportListener implements Consumer<IPipelineFailedEvent> {
 
-    public static final String LOGGER_NAME = "FK-Report";
+    // Bare component name; FlamingockLoggerFactory.getLogger prepends "FK-" → "FK-Report".
+    public static final String LOGGER_NAME = "Report";
 
     private static final Logger logger = FlamingockLoggerFactory.getLogger(LOGGER_NAME);
 
diff --git a/core/flamingock-core/src/main/java/io/flamingock/internal/core/operation/PipelineExecuteOperationException.java b/core/flamingock-core/src/main/java/io/flamingock/internal/core/operation/PipelineExecuteOperationException.java
@@ -16,12 +16,12 @@
 package io.flamingock.internal.core.operation;
 
 import io.flamingock.internal.common.core.response.data.ExecuteResponseData;
-import io.flamingock.internal.common.core.response.data.ExecutionReportFormatter;
 
 /**
  * Thrown when a pipeline-wide error breaks iteration (e.g. {@code LockException}, planner abort,
  * unexpected throwable). Always carries the response data assembled so far plus the originating
- * cause.
+ * cause. The rich multi-line execution report is emitted by the default execution-report listener
+ * under the {@code FK-Report} logger; this exception itself stays a clean one-line signal.
  */
 public class PipelineExecuteOperationException extends ExecuteOperationException {
 
@@ -32,10 +32,4 @@ public PipelineExecuteOperationException(Throwable cause, ExecuteResponseData re
     public PipelineExecuteOperationException(String message, Throwable cause, ExecuteResponseData result) {
         super(message, cause, result);
     }
-
-    // Rich multi-line report; getMessage() stays as Throwable's default (cause-derived) for log aggregators.
-    @Override
-    public String toString() {
-        return ExecutionReportFormatter.report(getResult());
-    }
 }
diff --git a/core/flamingock-core/src/main/java/io/flamingock/internal/core/operation/StagedExecuteOperationException.java b/core/flamingock-core/src/main/java/io/flamingock/internal/core/operation/StagedExecuteOperationException.java
@@ -25,18 +25,14 @@
  *
  * <p>The {@link #getMessage()} is a single-line, log-aggregator-friendly summary (failed stage
  * count + names, change counts, run duration, and the IDs of any change requiring manual
- * intervention). The full multi-line per-stage report is available via {@link #toString()} —
- * see {@code docs/ERROR_REPORTING_PROPOSAL.md} for why the two intentionally differ.
+ * intervention). The rich multi-line per-stage report is emitted by the default execution-report
+ * listener under the {@code FK-Report} logger — see {@code docs/ERROR_REPORTING_PROPOSAL.md}.
+ * {@link #toString()} is intentionally not overridden; printing the exception (e.g. via
+ * {@code printStackTrace}) yields the same one-line summary, never the multi-line report.
  */
 public class StagedExecuteOperationException extends ExecuteOperationException {
 
     public StagedExecuteOperationException(ExecuteResponseData result) {
         super(ExecutionReportFormatter.summary(result), result);
     }
-
-    // Rich multi-line report; getMessage() stays one-line for log aggregators.
-    @Override
-    public String toString() {
-        return ExecutionReportFormatter.report(getResult());
-    }
 }
diff --git a/core/flamingock-core/src/main/java/io/flamingock/internal/core/pipeline/run/PipelineRun.java b/core/flamingock-core/src/main/java/io/flamingock/internal/core/pipeline/run/PipelineRun.java
@@ -176,7 +176,7 @@ public void markStageFailed(String stageName, StageExecutionException exception)
         StageRun run = lookupOrThrow(stageName);
         run.setResult(StageResult.builder(resultFromExecutor)
                 .state(StageState.failed(errorInfo))
-                .build());
+            .build());
     }
 
     /**
@@ -248,7 +248,10 @@ public ExecuteResponseData toResponse() {
                         appliedChanges++;
                     } else if (change.getStatus() == ChangeStatus.ALREADY_APPLIED) {
                         skippedChanges++;
-                    } else if (change.getStatus() == ChangeStatus.FAILED) {
+                    } else if (change.getStatus() == ChangeStatus.FAILED
+                            || change.getStatus() == ChangeStatus.ROLLED_BACK) {
+                        // ROLLED_BACK counts as a failed attempt for the user-facing aggregate.
+                        // The per-change record retains the precise status for downstream consumers.
                         failedChanges++;
                     }
                 }
diff --git a/core/flamingock-core/src/test/java/io/flamingock/internal/core/operation/StagedExecuteOperationExceptionTest.java b/core/flamingock-core/src/test/java/io/flamingock/internal/core/operation/StagedExecuteOperationExceptionTest.java
@@ -62,15 +62,18 @@ void getMessageAppendsManualInterventionChangeIds() {
     }
 
     @Test
-    void toStringReturnsMultiLineReport() {
+    void toStringIsSingleLineSummaryAndCarriesGetMessage() {
         ExecuteResponseData result = failureResult();
         StagedExecuteOperationException ex = new StagedExecuteOperationException(result);
 
         String rendered = ex.toString();
-        assertTrue(rendered.contains(System.lineSeparator()),
-                "toString must be multi-line: " + rendered);
-        assertTrue(rendered.contains("Flamingock execution report"), rendered);
-        assertTrue(rendered.contains("[FAILED]"), rendered);
+        // Default Throwable.toString() = "ClassName: message" — never the multi-line report,
+        // which lives in the FK-Report listener and would otherwise duplicate via printStackTrace.
+        assertTrue(rendered.contains(ex.getMessage()), rendered);
+        assertFalse(rendered.contains("Flamingock execution report"),
+                "toString must NOT carry the multi-line report banner: " + rendered);
+        assertFalse(rendered.contains("[FAILED]"),
+                "toString must NOT carry per-stage report rows: " + rendered);
     }
 
     private static ExecuteResponseData failureResult() {
diff --git a/core/flamingock-core/src/test/java/io/flamingock/internal/core/pipeline/run/PipelineRunToResponseTest.java b/core/flamingock-core/src/test/java/io/flamingock/internal/core/pipeline/run/PipelineRunToResponseTest.java
@@ -159,6 +159,34 @@ void notStartedStagesAreReportedInResponseWithNotStartedState() {
         assertTrue(response.getStages().get(1).getState().isNotStarted());
     }
 
+    @Test
+    void rolledBackChangeIsCountedAsFailedInAggregate() {
+        // Mirrors the real-world MongoDB duplicate-key case: a transactional change failed and was
+        // auto-rolled-back. PipelineRun must count it in failedChanges (not silently drop it).
+        AbstractLoadedStage stage = mockStage("database-init");
+        PipelineRun pipelineRun = PipelineRun.of(java.util.Collections.singletonList(stage));
+
+        StageResult stageResult = StageResult.builder()
+                .stageId("database-init").stageName("database-init")
+                .state(StageState.failed(null))
+                .addChange(ChangeResult.builder().changeId("c1").status(ChangeStatus.ALREADY_APPLIED).build())
+                .addChange(ChangeResult.builder().changeId("c2").status(ChangeStatus.ALREADY_APPLIED).build())
+                .addChange(ChangeResult.builder().changeId("c3").status(ChangeStatus.ROLLED_BACK).build())
+                .build();
+
+        pipelineRun.start();
+        pipelineRun.markStageFailed("database-init", StageExecutionException.fromResult(
+                new RuntimeException("boom"), stageResult, "c3"));
+        pipelineRun.stop();
+
+        ExecuteResponseData response = pipelineRun.toResponse();
+        assertEquals(3, response.getTotalChanges());
+        assertEquals(0, response.getAppliedChanges());
+        assertEquals(2, response.getSkippedChanges());
+        assertEquals(1, response.getFailedChanges(),
+                "ROLLED_BACK must be counted as failed in the user-facing aggregate");
+    }
+
     private static AbstractLoadedStage mockStage(String name) {
         AbstractLoadedStage stage = mock(AbstractLoadedStage.class);
         when(stage.getName()).thenReturn(name);
diff --git a/docs/ERROR_REPORTING_PROPOSAL.md b/docs/ERROR_REPORTING_PROPOSAL.md
@@ -1,9 +1,10 @@
 # Error reporting proposal — rich execution report via event listener
 
-**Status:** implemented (2026-05-24).
+**Status:** implemented (2026-05-25).
 - **Step 1 (single-line `getMessage()` summary) — DONE.** `StagedExecuteOperationException.getMessage()` delegates to `ExecutionReportFormatter.summary(...)`. MI change IDs are appended when any stage is blocked.
-- **Step 2 (`toString()` override with rich multi-line report) — DONE.** Both `StagedExecuteOperationException` and `PipelineExecuteOperationException` override `toString()` to return `ExecutionReportFormatter.report(...)`.
-- **Step 3 (default event listener writing via SLF4J + builder opt-out) — DONE.** Two separate listeners — `DefaultPipelineCompletedReportListener` (INFO) and `DefaultPipelineFailedReportListener` (ERROR) — both writing under the `FK-Report` logger. Composed with any user listener via `Consumer.andThen` when `enableDefaultExecutionReport(true)` (default). Inline summary `logger.info(...)` calls in `AbstractPipelineTraverseOperation` removed in favor of the listener.
+- **Step 2 (exception is one-line only; no `toString()` override) — DONE.** Originally we shipped a `toString()` override returning the multi-line report; real-world testing in Spring Boot showed `printStackTrace` then duplicated the listener's output. Reverted: both `StagedExecuteOperationException` and `PipelineExecuteOperationException` use `Throwable`'s default `toString()` (= `ClassName: getMessage()`). Multi-line rendering is exclusively the listener's job.
+- **Step 3 (default event listener writing via SLF4J + builder opt-out) — DONE.** Two separate listeners — `DefaultPipelineCompletedReportListener` (INFO) and `DefaultPipelineFailedReportListener` (ERROR) — both writing under the `FK-Report` logger (constant `LOGGER_NAME = "Report"`; `FlamingockLoggerFactory` prepends `FK-` automatically). Composed with any user listener via `Consumer.andThen` when `enableDefaultExecutionReport(true)` (default). Inline summary `logger.info(...)` calls in `AbstractPipelineTraverseOperation` removed in favor of the listener.
+- **Counter semantics.** `ChangeStatus.ROLLED_BACK` is widened into the `failedChanges` aggregate (in `PipelineRun.toResponse()`) and into the per-stage `failed` count + `failed change(s):` line (in `ExecutionReportFormatter`). The precise `ROLLED_BACK` status remains on each `ChangeResult` for consumers that need the distinction.
 
 **Related code:** `core/flamingock-core/.../operation/AbstractPipelineTraverseOperation.java`, `ExecuteOperationException` / `StagedExecuteOperationException` / `PipelineExecuteOperationException`, `core/flamingock-core-commons/.../response/data/{ExecuteResponseData,ExecutionReportFormatter}.java`, `core/flamingock-core/.../event/listener/`, `core/flamingock-core/.../builder/AbstractChangeRunnerBuilder.java`, `core/flamingock-core/.../configuration/core/CoreConfiguration.java`. Spring Boot wrappers under `platform-plugins/flamingock-springboot-integration/.../event/` pass `getResult()` through (and the four `SpringStage*Event` classes were re-typed to implement their correct `IStage*Event` interfaces — they were previously cross-wired to `IPipeline*Event`).
 

Original file line number	Diff line number	Diff line change
`@@ -101,6 +101,10 @@ public boolean isFailed() {`
`101`	`101`	`return status == ChangeStatus.FAILED;`
`102`	`102`	`}`
`103`	`103`
	`104`	`+ public boolean isRolledBack() {`
	`105`	`+ return status == ChangeStatus.ROLLED_BACK;`
	`106`	`+ }`
	`107`	`+`
`104`	`108`	`public boolean isApplied() {`
`105`	`109`	`return status == ChangeStatus.APPLIED;`
`106`	`110`	`}`
Original file line number	Diff line number	Diff line change
`@@ -176,7 +176,7 @@ public void markStageFailed(String stageName, StageExecutionException exception)`
`176`	`176`	`StageRun run = lookupOrThrow(stageName);`
`177`	`177`	`run.setResult(StageResult.builder(resultFromExecutor)`
`178`	`178`	`.state(StageState.failed(errorInfo))`
`179`		`- .build());`
	`179`	`+ .build());`
`180`	`180`	`}`
`181`	`181`
`182`	`182`	`/**`
`@@ -248,7 +248,10 @@ public ExecuteResponseData toResponse() {`
`248`	`248`	`appliedChanges++;`
`249`	`249`	`} else if (change.getStatus() == ChangeStatus.ALREADY_APPLIED) {`
`250`	`250`	`skippedChanges++;`
`251`		`- } else if (change.getStatus() == ChangeStatus.FAILED) {`
	`251`	`+ } else if (change.getStatus() == ChangeStatus.FAILED`
	`252`	`+ \|\| change.getStatus() == ChangeStatus.ROLLED_BACK) {`
	`253`	`+ // ROLLED_BACK counts as a failed attempt for the user-facing aggregate.`
	`254`	`+ // The per-change record retains the precise status for downstream consumers.`
`252`	`255`	`failedChanges++;`
`253`	`256`	`}`
`254`	`257`	`}`