SONAR-11278 log failing computation step

2 files changed, 49 insertions, 7 deletions

diff --git a/server/sonar-ce-task/src/main/java/org/sonar/ce/task/step/ComputationStepExecutor.java b/server/sonar-ce-task/src/main/java/org/sonar/ce/task/step/ComputationStepExecutor.java
index 381a824cc32..8318fe8d8ab 100644
--- a/server/sonar-ce-task/src/main/java/org/sonar/ce/task/step/ComputationStepExecutor.java
+++ b/server/sonar-ce-task/src/main/java/org/sonar/ce/task/step/ComputationStepExecutor.java
@@ -26,6 +26,7 @@ import org.sonar.api.utils.log.Loggers;
 import org.sonar.core.util.logs.Profiler;
 
 import static com.google.common.base.Preconditions.checkArgument;
+import static java.lang.String.format;
 import static java.util.Objects.requireNonNull;
 
 public final class ComputationStepExecutor {
@@ -65,8 +66,18 @@ public final class ComputationStepExecutor {
     StepStatisticsImpl statistics = new StepStatisticsImpl(stepProfiler);
     ComputationStep.Context context = new StepContextImpl(statistics);
     for (ComputationStep step : steps.instances()) {
-      stepProfiler.start();
+      executeStep(stepProfiler, context, step);
+    }
+  }
+
+  private static void executeStep(Profiler stepProfiler, ComputationStep.Context context, ComputationStep step) {
+    String status = "FAILED";
+    stepProfiler.start();
+    try {
       step.execute(context);
+      status = "SUCCESS";
+    } finally {
+      stepProfiler.addContext("status", status);
       stepProfiler.stopInfo(step.getDescription());
     }
   }
@@ -96,7 +107,7 @@ public final class ComputationStepExecutor {
     @Override
     public ComputationStep.Statistics add(String key, Object value) {
       requireNonNull(key, "Statistic has null key");
-      requireNonNull(value, () -> String.format("Statistic with key [%s] has null value", key));
+      requireNonNull(value, () -> format("Statistic with key [%s] has null value", key));
       checkArgument(!key.equalsIgnoreCase("time"), "Statistic with key [time] is not accepted");
       checkArgument(!profiler.hasContext(key), "Statistic with key [%s] is already present", key);
       profiler.addContext(key, value);
diff --git a/server/sonar-ce-task/src/test/java/org/sonar/ce/task/step/ComputationStepExecutorTest.java b/server/sonar-ce-task/src/test/java/org/sonar/ce/task/step/ComputationStepExecutorTest.java
index 8e7acad22f5..71810a3ce55 100644
--- a/server/sonar-ce-task/src/test/java/org/sonar/ce/task/step/ComputationStepExecutorTest.java
+++ b/server/sonar-ce-task/src/test/java/org/sonar/ce/task/step/ComputationStepExecutorTest.java
@@ -91,15 +91,46 @@ public class ComputationStepExecutorTest {
 
     try (ChangeLogLevel executor = new ChangeLogLevel(ComputationStepExecutor.class, LoggerLevel.INFO);
       ChangeLogLevel logLevel1 = new ChangeLogLevel(step1.getClass(), LoggerLevel.INFO);
-      ChangeLogLevel logLevel2 = new ChangeLogLevel(step1.getClass(), LoggerLevel.INFO);
-      ChangeLogLevel logLevel3 = new ChangeLogLevel(step2.getClass(), LoggerLevel.INFO)) {
+      ChangeLogLevel logLevel2 = new ChangeLogLevel(step2.getClass(), LoggerLevel.INFO);
+      ChangeLogLevel logLevel3 = new ChangeLogLevel(step3.getClass(), LoggerLevel.INFO)) {
       new ComputationStepExecutor(mockComputationSteps(step1, step2, step3)).execute();
 
       List<String> infoLogs = logTester.logs(LoggerLevel.INFO);
       assertThat(infoLogs).hasSize(3);
-      assertThat(infoLogs.get(0)).contains("Step One | foo=100 | bar=20 | time=");
-      assertThat(infoLogs.get(1)).contains("Step Two | foo=50 | baz=10 | time=");
-      assertThat(infoLogs.get(2)).contains("Step Three | time=");
+      assertThat(infoLogs.get(0)).contains("Step One | foo=100 | bar=20 | status=SUCCESS | time=");
+      assertThat(infoLogs.get(1)).contains("Step Two | foo=50 | baz=10 | status=SUCCESS | time=");
+      assertThat(infoLogs.get(2)).contains("Step Three | status=SUCCESS | time=");
+    }
+  }
+
+  @Test
+  public void execute_logs_end_timing_and_statistics_for_each_ComputationStep_in_INFO_level_even_if_failed() {
+    RuntimeException expected = new RuntimeException("faking step failing with RuntimeException");
+    ComputationStep step1 = new StepWithStatistics("Step One", "foo", "100", "bar", "20");
+    ComputationStep step2 = new StepWithStatistics("Step Two", "foo", "50", "baz", "10");
+    ComputationStep step3 = new StepWithStatistics("Step Three", "donut", "crash") {
+      @Override
+      public void execute(Context context) {
+        super.execute(context);
+        throw expected;
+      }
+    } ;
+
+    try (ChangeLogLevel executor = new ChangeLogLevel(ComputationStepExecutor.class, LoggerLevel.INFO);
+      ChangeLogLevel logLevel1 = new ChangeLogLevel(step1.getClass(), LoggerLevel.INFO);
+      ChangeLogLevel logLevel2 = new ChangeLogLevel(step2.getClass(), LoggerLevel.INFO);
+      ChangeLogLevel logLevel3 = new ChangeLogLevel(step3.getClass(), LoggerLevel.INFO)) {
+
+      try {
+        new ComputationStepExecutor(mockComputationSteps(step1, step2, step3)).execute();
+        fail("a RuntimeException should have been thrown");
+      } catch (RuntimeException e) {
+        List<String> infoLogs = logTester.logs(LoggerLevel.INFO);
+        assertThat(infoLogs).hasSize(3);
+        assertThat(infoLogs.get(0)).contains("Step One | foo=100 | bar=20 | status=SUCCESS | time=");
+        assertThat(infoLogs.get(1)).contains("Step Two | foo=50 | baz=10 | status=SUCCESS | time=");
+        assertThat(infoLogs.get(2)).contains("Step Three | donut=crash | status=FAILED | time=");
+      }
     }
   }