From aedbebebed4b2048458a8a7b104f74de23cd2f22 Mon Sep 17 00:00:00 2001 From: Steve Marion Date: Fri, 3 May 2024 16:56:36 +0200 Subject: [PATCH] SONAR-22142 improve logging of db-migration steps with progress information --- .../step/MigrationStepsExecutorImpl.java | 43 +++++--- .../MigrationContainerPopulatorImplTest.java | 2 + .../engine/MigrationEngineImplTest.java | 10 +- .../step/MigrationStepsExecutorImplTest.java | 97 +++++++++++-------- .../db/migration/AutoDbMigration.java | 12 ++- .../db/migration/AutoDbMigrationTest.java | 9 +- 6 files changed, 111 insertions(+), 62 deletions(-) diff --git a/server/sonar-db-migration/src/main/java/org/sonar/server/platform/db/migration/step/MigrationStepsExecutorImpl.java b/server/sonar-db-migration/src/main/java/org/sonar/server/platform/db/migration/step/MigrationStepsExecutorImpl.java index e7105c0eff2..a98bd05106d 100644 --- a/server/sonar-db-migration/src/main/java/org/sonar/server/platform/db/migration/step/MigrationStepsExecutorImpl.java +++ b/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 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"); } } } diff --git a/server/sonar-db-migration/src/test/java/org/sonar/server/platform/db/migration/engine/MigrationContainerPopulatorImplTest.java b/server/sonar-db-migration/src/test/java/org/sonar/server/platform/db/migration/engine/MigrationContainerPopulatorImplTest.java index 9d6671ae0e7..2302f818619 100644 --- a/server/sonar-db-migration/src/test/java/org/sonar/server/platform/db/migration/engine/MigrationContainerPopulatorImplTest.java +++ b/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); diff --git a/server/sonar-db-migration/src/test/java/org/sonar/server/platform/db/migration/engine/MigrationEngineImplTest.java b/server/sonar-db-migration/src/test/java/org/sonar/server/platform/db/migration/engine/MigrationEngineImplTest.java index 9e079186159..42fd3394874 100644 --- a/server/sonar-db-migration/src/test/java/org/sonar/server/platform/db/migration/engine/MigrationEngineImplTest.java +++ b/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; } - + } } diff --git a/server/sonar-db-migration/src/test/java/org/sonar/server/platform/db/migration/step/MigrationStepsExecutorImplTest.java b/server/sonar-db-migration/src/test/java/org/sonar/server/platform/db/migration/step/MigrationStepsExecutorImplTest.java index 7eb31d0472b..ce74dd995d4 100644 --- a/server/sonar-db-migration/src/test/java/org/sonar/server/platform/db/migration/step/MigrationStepsExecutorImplTest.java +++ b/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 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 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 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(); } } diff --git a/server/sonar-webserver-core/src/main/java/org/sonar/server/platform/db/migration/AutoDbMigration.java b/server/sonar-webserver-core/src/main/java/org/sonar/server/platform/db/migration/AutoDbMigration.java index c6b2bef3da8..ef90950214f 100644 --- a/server/sonar-webserver-core/src/main/java/org/sonar/server/platform/db/migration/AutoDbMigration.java +++ b/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)); } } diff --git a/server/sonar-webserver-core/src/test/java/org/sonar/server/platform/db/migration/AutoDbMigrationTest.java b/server/sonar-webserver-core/src/test/java/org/sonar/server/platform/db/migration/AutoDbMigrationTest.java index b100e02b0cd..41e65c12cae 100644 --- a/server/sonar-webserver-core/src/test/java/org/sonar/server/platform/db/migration/AutoDbMigrationTest.java +++ b/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() { -- 2.39.5