SONAR-22142 improve logging of db-migration steps with progress information

server/sonar-db-migration/src/main/java/org/sonar/server/platform/db/migration/step/MigrationStepsExecutorImpl.java

@@ -24,29 +24,33 @@ import org.slf4j.Logger;
 import org.slf4j.LoggerFactory;
 import org.sonar.core.platform.Container;
 import org.sonar.core.util.logs.Profiler;
+import org.sonar.server.platform.db.migration.MutableDatabaseMigrationState;
 import org.sonar.server.platform.db.migration.history.MigrationHistory;
 
 import static com.google.common.base.Preconditions.checkState;
 
 public class MigrationStepsExecutorImpl implements MigrationStepsExecutor {
   private static final Logger LOGGER = LoggerFactory.getLogger("DbMigrations");
-  private static final String GLOBAL_START_MESSAGE = "Executing DB migrations...";
-  private static final String GLOBAL_END_MESSAGE = "Executed DB migrations: {}";
-  private static final String STEP_START_PATTERN = "{}...";
-  private static final String STEP_STOP_PATTERN = "{}: {}";
+  private static final String GLOBAL_START_MESSAGE = "Executing {} DB migrations...";
+  private static final String GLOBAL_END_MESSAGE = "Executed {}/{} DB migrations: {}";
+  private static final String STEP_START_PATTERN = "{}/{} {}...";
+  private static final String STEP_STOP_PATTERN = "{}/{} {}: {}";
 
   private final Container migrationContainer;
   private final MigrationHistory migrationHistory;
+  private final MutableDatabaseMigrationState databaseMigrationState;
 
-  public MigrationStepsExecutorImpl(Container migrationContainer, MigrationHistory migrationHistory) {
+  public MigrationStepsExecutorImpl(
+    Container migrationContainer, MigrationHistory migrationHistory, MutableDatabaseMigrationState databaseMigrationState) {
     this.migrationContainer = migrationContainer;
     this.migrationHistory = migrationHistory;
+    this.databaseMigrationState = databaseMigrationState;
   }
 
   @Override
   public void execute(List<RegisteredMigrationStep> steps, MigrationStatusListener listener) {
     Profiler globalProfiler = Profiler.create(LOGGER);
-    globalProfiler.startInfo(GLOBAL_START_MESSAGE);
+    globalProfiler.startInfo(GLOBAL_START_MESSAGE, databaseMigrationState.getTotalMigrations());
     boolean allStepsExecuted = false;
     try {
       for (RegisteredMigrationStep step : steps) {
@@ -56,9 +60,15 @@ public class MigrationStepsExecutorImpl implements MigrationStepsExecutor {
       allStepsExecuted = true;
     } finally {
       if (allStepsExecuted) {
-        globalProfiler.stopInfo(GLOBAL_END_MESSAGE, "success");
+        globalProfiler.stopInfo(GLOBAL_END_MESSAGE,
+          databaseMigrationState.getCompletedMigrations(),
+          databaseMigrationState.getTotalMigrations(),
+          "success");
       } else {
-        globalProfiler.stopError(GLOBAL_END_MESSAGE, "failure");
+        globalProfiler.stopError(GLOBAL_END_MESSAGE,
+          databaseMigrationState.getCompletedMigrations(),
+          databaseMigrationState.getTotalMigrations(),
+          "failure");
       }
     }
   }
@@ -72,7 +82,10 @@ public class MigrationStepsExecutorImpl implements MigrationStepsExecutor {
 
   private void execute(RegisteredMigrationStep step, MigrationStep migrationStep) {
     Profiler stepProfiler = Profiler.create(LOGGER);
-    stepProfiler.startInfo(STEP_START_PATTERN, step);
+    stepProfiler.startInfo(STEP_START_PATTERN,
+      databaseMigrationState.getCompletedMigrations() + 1,
+      databaseMigrationState.getTotalMigrations(),
+      step);
     boolean done = false;
     try {
       migrationStep.execute();
@@ -82,9 +95,17 @@ public class MigrationStepsExecutorImpl implements MigrationStepsExecutor {
       throw new MigrationStepExecutionException(step, e);
     } finally {
       if (done) {
-        stepProfiler.stopInfo(STEP_STOP_PATTERN, step, "success");
+        stepProfiler.stopInfo(STEP_STOP_PATTERN,
+          databaseMigrationState.getCompletedMigrations() + 1,
+          databaseMigrationState.getTotalMigrations(),
+          step,
+          "success");
       } else {
-        stepProfiler.stopError(STEP_STOP_PATTERN, step, "failure");
+        stepProfiler.stopError(STEP_STOP_PATTERN,
+          databaseMigrationState.getCompletedMigrations() + 1,
+          databaseMigrationState.getTotalMigrations(),
+          step,
+          "failure");
       }
     }
   }

server/sonar-db-migration/src/test/java/org/sonar/server/platform/db/migration/engine/MigrationContainerPopulatorImplTest.java

@@ -21,6 +21,7 @@ package org.sonar.server.platform.db.migration.engine;
 
 import org.junit.Before;
 import org.junit.Test;
+import org.sonar.server.platform.db.migration.MutableDatabaseMigrationState;
 import org.sonar.server.platform.db.migration.history.MigrationHistory;
 import org.sonar.server.platform.db.migration.step.MigrationStep;
 import org.sonar.server.platform.db.migration.step.MigrationSteps;
@@ -49,6 +50,7 @@ public class MigrationContainerPopulatorImplTest {
 
     // add MigrationStepsExecutorImpl's dependencies
     migrationContainer.add(mock(MigrationHistory.class));
+    migrationContainer.add(mock(MutableDatabaseMigrationState.class));
 
     migrationContainer.startComponents();
     underTest.populateContainer(migrationContainer);

server/sonar-db-migration/src/test/java/org/sonar/server/platform/db/migration/engine/MigrationEngineImplTest.java

@@ -25,6 +25,7 @@ import java.util.Optional;
 import org.junit.jupiter.api.BeforeEach;
 import org.junit.jupiter.api.Test;
 import org.sonar.core.platform.SpringComponentContainer;
+import org.sonar.server.platform.db.migration.MutableDatabaseMigrationState;
 import org.sonar.server.platform.db.migration.history.MigrationHistory;
 import org.sonar.server.platform.db.migration.step.MigrationStep;
 import org.sonar.server.platform.db.migration.step.MigrationSteps;
@@ -40,6 +41,7 @@ import static org.mockito.Mockito.when;
 
 class MigrationEngineImplTest {
   private final MigrationHistory migrationHistory = mock(MigrationHistory.class);
+  private final MutableDatabaseMigrationState databaseMigrationState = mock();
   private final SpringComponentContainer serverContainer = new SpringComponentContainer();
   private final MigrationSteps migrationSteps = mock(MigrationSteps.class);
   private final StepRegistry stepRegistry = new StepRegistry();
@@ -50,6 +52,7 @@ class MigrationEngineImplTest {
     serverContainer.add(migrationSteps);
     serverContainer.add(migrationHistory);
     serverContainer.add(stepRegistry);
+    serverContainer.add(databaseMigrationState);
     serverContainer.startComponents();
   }
 
@@ -85,9 +88,8 @@ class MigrationEngineImplTest {
   private record TestMigrationStep(StepRegistry registry) implements MigrationStep {
 
     @Override
-      public void execute() throws SQLException {
-        registry.stepRan = true;
-      }
+    public void execute() throws SQLException {
+      registry.stepRan = true;
     }
-
+  }
 }

server/sonar-db-migration/src/test/java/org/sonar/server/platform/db/migration/step/MigrationStepsExecutorImplTest.java

@@ -25,11 +25,13 @@ import java.util.Arrays;
 import java.util.Collections;
 import java.util.Iterator;
 import java.util.List;
-import org.junit.Rule;
-import org.junit.Test;
+import org.junit.jupiter.api.BeforeEach;
+import org.junit.jupiter.api.Test;
+import org.junit.jupiter.api.extension.RegisterExtension;
 import org.slf4j.event.Level;
-import org.sonar.api.testfixtures.log.LogTester;
+import org.sonar.api.testfixtures.log.LogTesterJUnit5;
 import org.sonar.core.platform.SpringComponentContainer;
+import org.sonar.server.platform.db.migration.MutableDatabaseMigrationState;
 import org.sonar.server.platform.db.migration.engine.MigrationContainer;
 import org.sonar.server.platform.db.migration.engine.SimpleMigrationContainer;
 import org.sonar.server.platform.db.migration.history.MigrationHistory;
@@ -39,38 +41,52 @@ import static java.util.Arrays.asList;
 import static org.assertj.core.api.Assertions.assertThat;
 import static org.assertj.core.api.Assertions.fail;
 import static org.mockito.Mockito.mock;
+import static org.mockito.Mockito.times;
+import static org.mockito.Mockito.verify;
+import static org.mockito.Mockito.verifyNoInteractions;
+import static org.mockito.Mockito.when;
 
-public class MigrationStepsExecutorImplTest {
-  @Rule
-  public LogTester logTester = new LogTester();
+class MigrationStepsExecutorImplTest {
+
+  @RegisterExtension
+  private final LogTesterJUnit5 logTester = new LogTesterJUnit5();
 
   private MigrationContainer migrationContainer = new SimpleMigrationContainer();
-  private MigrationHistory migrationHistor = mock(MigrationHistory.class);
-  private MigrationStepsExecutorImpl underTest = new MigrationStepsExecutorImpl(migrationContainer, migrationHistor);
-  private NoOpMigrationStatusListener noOpMigrationStatusListener = new NoOpMigrationStatusListener();
+  private MigrationHistory migrationHistory = mock(MigrationHistory.class);
+  private MutableDatabaseMigrationState databaseMigrationState = mock();
+  private MigrationStepsExecutorImpl underTest = new MigrationStepsExecutorImpl(migrationContainer, migrationHistory, databaseMigrationState);
+  private NoOpMigrationStatusListener migrationStatusListener = mock();
+
+  @BeforeEach
+  void setUp() {
+    when(databaseMigrationState.getTotalMigrations()).thenReturn(5);
+    when(databaseMigrationState.getCompletedMigrations()).thenReturn(2);
+  }
 
   @Test
-  public void execute_does_not_fail_when_stream_is_empty_and_log_start_stop_INFO() {
-    underTest.execute(Collections.emptyList(), null);
+  void execute_does_not_fail_when_stream_is_empty_and_log_start_stop_INFO() {
+    underTest.execute(Collections.emptyList(), migrationStatusListener);
 
+    verifyNoInteractions(migrationStatusListener);
     assertThat(logTester.logs()).hasSize(2);
-    assertLogLevel(Level.INFO, "Executing DB migrations...", "Executed DB migrations: success | time=");
+    assertLogLevel(Level.INFO, "Executing 5 DB migrations...", "Executed 2/5 DB migrations: success | time=");
   }
 
   @Test
-  public void execute_fails_with_ISE_if_no_instance_of_computation_step_exist_in_container() {
+  void execute_fails_with_ISE_if_no_instance_of_computation_step_exist_in_container() {
     List<RegisteredMigrationStep> steps = asList(registeredStepOf(1, MigrationStep1.class));
 
     ((SpringComponentContainer) migrationContainer).startComponents();
     try {
-      underTest.execute(steps, noOpMigrationStatusListener);
+      underTest.execute(steps, migrationStatusListener);
       fail("execute should have thrown a IllegalStateException");
     } catch (IllegalStateException e) {
       assertThat(e).hasMessage("Unable to load component " + MigrationStep1.class);
     } finally {
+      verifyNoInteractions(migrationStatusListener);
       assertThat(logTester.logs()).hasSize(2);
-      assertLogLevel(Level.INFO, "Executing DB migrations...");
-      assertLogLevel(Level.ERROR, "Executed DB migrations: failure | time=");
+      assertLogLevel(Level.INFO, "Executing 5 DB migrations...");
+      assertLogLevel(Level.ERROR, "Executed 2/5 DB migrations: failure | time=");
     }
   }
 
@@ -88,35 +104,38 @@ public class MigrationStepsExecutorImplTest {
   }
 
   @Test
-  public void execute_execute_the_instance_of_type_specified_in_step_in_stream_order() {
+  void execute_execute_the_instance_of_type_specified_in_step_in_stream_order() {
     migrationContainer.add(MigrationStep1.class, MigrationStep2.class, MigrationStep3.class);
     ((SpringComponentContainer) migrationContainer).startComponents();
 
     underTest.execute(asList(
-      registeredStepOf(1, MigrationStep2.class),
-      registeredStepOf(2, MigrationStep1.class),
-      registeredStepOf(3, MigrationStep3.class)), new NoOpMigrationStatusListener());
+        registeredStepOf(1, MigrationStep2.class),
+        registeredStepOf(2, MigrationStep1.class),
+        registeredStepOf(3, MigrationStep3.class)),
+      migrationStatusListener);
 
     assertThat(SingleCallCheckerMigrationStep.calledSteps)
       .containsExactly(MigrationStep2.class, MigrationStep1.class, MigrationStep3.class);
     assertThat(logTester.logs()).hasSize(8);
     assertLogLevel(Level.INFO,
-      "Executing DB migrations...",
-      "#1 '1-MigrationStep2'...",
-      "#1 '1-MigrationStep2': success | time=",
-      "#2 '2-MigrationStep1'...",
-      "#2 '2-MigrationStep1': success | time=",
-      "#3 '3-MigrationStep3'...",
-      "#3 '3-MigrationStep3': success | time=",
-      "Executed DB migrations: success | time=");
+      "Executing 5 DB migrations...",
+      "3/5 #1 '1-MigrationStep2'...",
+      "3/5 #1 '1-MigrationStep2': success | time=",
+      "3/5 #2 '2-MigrationStep1'...",
+      "3/5 #2 '2-MigrationStep1': success | time=",
+      "3/5 #3 '3-MigrationStep3'...",
+      "3/5 #3 '3-MigrationStep3': success | time=",
+      "Executed 2/5 DB migrations: success | time=");
 
     assertThat(migrationContainer.getComponentByType(MigrationStep1.class).isCalled()).isTrue();
     assertThat(migrationContainer.getComponentByType(MigrationStep2.class).isCalled()).isTrue();
     assertThat(migrationContainer.getComponentByType(MigrationStep3.class).isCalled()).isTrue();
+    verify(migrationStatusListener, times(3)).onMigrationStepCompleted();
+
   }
 
   @Test
-  public void execute_throws_MigrationStepExecutionException_on_first_failing_step_execution_throws_SQLException() {
+  void execute_throws_MigrationStepExecutionException_on_first_failing_step_execution_throws_SQLException() {
     migrationContainer.add(MigrationStep2.class, SqlExceptionFailingMigrationStep.class, MigrationStep3.class);
     List<RegisteredMigrationStep> steps = asList(
       registeredStepOf(1, MigrationStep2.class),
@@ -125,7 +144,7 @@ public class MigrationStepsExecutorImplTest {
 
     ((SpringComponentContainer) migrationContainer).startComponents();
     try {
-      underTest.execute(steps, noOpMigrationStatusListener);
+      underTest.execute(steps, migrationStatusListener);
       fail("a MigrationStepExecutionException should have been thrown");
     } catch (MigrationStepExecutionException e) {
       assertThat(e).hasMessage("Execution of migration step #2 '2-SqlExceptionFailingMigrationStep' failed");
@@ -133,18 +152,19 @@ public class MigrationStepsExecutorImplTest {
     } finally {
       assertThat(logTester.logs()).hasSize(6);
       assertLogLevel(Level.INFO,
-        "Executing DB migrations...",
-        "#1 '1-MigrationStep2'...",
-        "#1 '1-MigrationStep2': success | time=",
-        "#2 '2-SqlExceptionFailingMigrationStep'...");
+        "Executing 5 DB migrations...",
+        "3/5 #1 '1-MigrationStep2'...",
+        "3/5 #1 '1-MigrationStep2': success | time=",
+        "3/5 #2 '2-SqlExceptionFailingMigrationStep'...");
       assertLogLevel(Level.ERROR,
-        "#2 '2-SqlExceptionFailingMigrationStep': failure | time=",
-        "Executed DB migrations: failure | time=");
+        "3/5 #2 '2-SqlExceptionFailingMigrationStep': failure | time=",
+        "Executed 2/5 DB migrations: failure | time=");
     }
+    verify(migrationStatusListener, times(1)).onMigrationStepCompleted();
   }
 
   @Test
-  public void execute_throws_MigrationStepExecutionException_on_first_failing_step_execution_throws_any_exception() {
+  void execute_throws_MigrationStepExecutionException_on_first_failing_step_execution_throws_any_exception() {
     migrationContainer.add(MigrationStep2.class, RuntimeExceptionFailingMigrationStep.class, MigrationStep3.class);
 
     List<RegisteredMigrationStep> steps = asList(
@@ -154,11 +174,12 @@ public class MigrationStepsExecutorImplTest {
 
     ((SpringComponentContainer) migrationContainer).startComponents();
     try {
-      underTest.execute(steps, noOpMigrationStatusListener);
+      underTest.execute(steps, migrationStatusListener);
       fail("should throw MigrationStepExecutionException");
     } catch (MigrationStepExecutionException e) {
       assertThat(e).hasMessage("Execution of migration step #2 '2-RuntimeExceptionFailingMigrationStep' failed");
       assertThat(e.getCause()).isSameAs(RuntimeExceptionFailingMigrationStep.THROWN_EXCEPTION);
+      verify(migrationStatusListener, times(1)).onMigrationStepCompleted();
     }
   }
 

server/sonar-webserver-core/src/main/java/org/sonar/server/platform/db/migration/AutoDbMigration.java

@@ -19,29 +19,31 @@
  */
 package org.sonar.server.platform.db.migration;
 
-import org.sonar.api.Startable;
 import org.slf4j.LoggerFactory;
+import org.sonar.api.Startable;
 import org.sonar.server.platform.DefaultServerUpgradeStatus;
 import org.sonar.server.platform.db.migration.engine.MigrationEngine;
-import org.sonar.server.platform.db.migration.step.NoOpMigrationStatusListener;
+import org.sonar.server.platform.db.migration.step.MigrationStatusListenerImpl;
 
 public class AutoDbMigration implements Startable {
   private final DefaultServerUpgradeStatus serverUpgradeStatus;
   private final MigrationEngine migrationEngine;
+  private final MutableDatabaseMigrationState databaseMigrationState;
 
-  public AutoDbMigration(DefaultServerUpgradeStatus serverUpgradeStatus, MigrationEngine migrationEngine) {
+  public AutoDbMigration(DefaultServerUpgradeStatus serverUpgradeStatus, MigrationEngine migrationEngine, MutableDatabaseMigrationState databaseMigrationState) {
     this.serverUpgradeStatus = serverUpgradeStatus;
     this.migrationEngine = migrationEngine;
+    this.databaseMigrationState = databaseMigrationState;
   }
 
   @Override
   public void start() {
     if (serverUpgradeStatus.isFreshInstall()) {
       LoggerFactory.getLogger(getClass()).info("Automatically perform DB migration on fresh install");
-      migrationEngine.execute(new NoOpMigrationStatusListener());
+      migrationEngine.execute(new MigrationStatusListenerImpl(databaseMigrationState));
     } else if (serverUpgradeStatus.isUpgraded() && serverUpgradeStatus.isAutoDbUpgrade()) {
       LoggerFactory.getLogger(getClass()).info("Automatically perform DB migration, as automatic database upgrade is enabled");
-      migrationEngine.execute(new NoOpMigrationStatusListener());
+      migrationEngine.execute(new MigrationStatusListenerImpl(databaseMigrationState));
     }
   }
 

server/sonar-webserver-core/src/test/java/org/sonar/server/platform/db/migration/AutoDbMigrationTest.java

@@ -44,10 +44,11 @@ public class AutoDbMigrationTest {
   @Rule
   public LogTester logTester = new LogTester();
 
-  private DbClient dbClient = mock(DbClient.class, Mockito.RETURNS_DEEP_STUBS);
-  private DefaultServerUpgradeStatus serverUpgradeStatus = mock(DefaultServerUpgradeStatus.class);
-  private MigrationEngine migrationEngine = mock(MigrationEngine.class);
-  private AutoDbMigration underTest = new AutoDbMigration(serverUpgradeStatus, migrationEngine);
+  private final DbClient dbClient = mock(DbClient.class, Mockito.RETURNS_DEEP_STUBS);
+  private final DefaultServerUpgradeStatus serverUpgradeStatus = mock(DefaultServerUpgradeStatus.class);
+  private final MigrationEngine migrationEngine = mock(MigrationEngine.class);
+  private final MutableDatabaseMigrationState mutableDatabaseMigrationState = mock(MutableDatabaseMigrationState.class);
+  private final AutoDbMigration underTest = new AutoDbMigration(serverUpgradeStatus, migrationEngine, mutableDatabaseMigrationState);
 
   @Test
   public void start_runs_MigrationEngine_on_h2_if_fresh_install() {