diff --git a/multiapps-controller-process/src/main/java/org/cloudfoundry/multiapps/controller/process/Constants.java b/multiapps-controller-process/src/main/java/org/cloudfoundry/multiapps/controller/process/Constants.java index 633429ab47..7834e487be 100644 --- a/multiapps-controller-process/src/main/java/org/cloudfoundry/multiapps/controller/process/Constants.java +++ b/multiapps-controller-process/src/main/java/org/cloudfoundry/multiapps/controller/process/Constants.java @@ -26,6 +26,9 @@ public class Constants { public static final String MTA_BACKUP_NAMESPACE = "mta-backup"; public static final String MTA_FOR_DELETION_PREFIX = "to-be-deleted"; + public static final Long UNSET_LAST_LOG_TIMESTAMP_MS = 0L; + public static final int LOG_STALLED_TASK_MINUTE_INTERVAL = 5; + protected Constants() { } } diff --git a/multiapps-controller-process/src/main/java/org/cloudfoundry/multiapps/controller/process/Messages.java b/multiapps-controller-process/src/main/java/org/cloudfoundry/multiapps/controller/process/Messages.java index 73e8e26094..4444158361 100644 --- a/multiapps-controller-process/src/main/java/org/cloudfoundry/multiapps/controller/process/Messages.java +++ b/multiapps-controller-process/src/main/java/org/cloudfoundry/multiapps/controller/process/Messages.java @@ -336,6 +336,7 @@ public class Messages { public static final String DELETING_BACKUP_DESCRIPTOR_WITH_MTA_ID_0_SPACE_1_NAMESPACE_2_AND_VERSION_3 = "Deleting backup descriptor with mta id \"{0}\" in space \"{1}\" namespace \"{2}\" and version \"{3}\""; public static final String DELETING_BACKUP_DESCRIPTORS_WITH_MTA_ID_0_SPACE_1_NAMESPACE_2_AND_SKIP_VERSIONS_3 = "Deleting backup descriptors with mta id \"{0}\" in space \"{1}\" namespace \"{2}\" and skip the following mta versions \"{3}\""; public static final String EXISTING_APPS_TO_BACKUP = "Existing apps to backup: {0}"; + public static final String TASK_0_ON_APPLICATION_1_IS_STILL_2 = "Task \"{0}\" on application \"{1}\" is still \"{2}\""; // Progress messages public static final String OPERATION_ID = "Operation ID: {0}"; diff --git a/multiapps-controller-process/src/main/java/org/cloudfoundry/multiapps/controller/process/steps/PollExecuteTaskStatusExecution.java b/multiapps-controller-process/src/main/java/org/cloudfoundry/multiapps/controller/process/steps/PollExecuteTaskStatusExecution.java index cc65b0624f..e52e205445 100644 --- a/multiapps-controller-process/src/main/java/org/cloudfoundry/multiapps/controller/process/steps/PollExecuteTaskStatusExecution.java +++ b/multiapps-controller-process/src/main/java/org/cloudfoundry/multiapps/controller/process/steps/PollExecuteTaskStatusExecution.java @@ -1,6 +1,7 @@ package org.cloudfoundry.multiapps.controller.process.steps; import java.text.MessageFormat; +import java.time.Duration; import java.util.UUID; import org.cloudfoundry.multiapps.controller.client.facade.CloudControllerClient; @@ -9,6 +10,7 @@ import org.cloudfoundry.multiapps.controller.core.cf.CloudControllerClientFactory; import org.cloudfoundry.multiapps.controller.core.security.token.TokenService; import org.cloudfoundry.multiapps.controller.persistence.services.ProcessLoggerProvider; +import org.cloudfoundry.multiapps.controller.process.Constants; import org.cloudfoundry.multiapps.controller.process.Messages; import org.cloudfoundry.multiapps.controller.process.variables.Variables; import org.slf4j.Logger; @@ -18,6 +20,9 @@ public class PollExecuteTaskStatusExecution implements AsyncExecution { private static final Logger LOGGER = LoggerFactory.getLogger(PollExecuteTaskStatusExecution.class); + private static final long LOG_INTERVAL_FOR_MESSAGE = Duration.ofMinutes(Constants.LOG_STALLED_TASK_MINUTE_INTERVAL) + .toMillis(); + private final CloudControllerClientFactory clientFactory; private final TokenService tokenService; @@ -54,8 +59,12 @@ public AsyncExecutionState execute(ProcessContext context) { if (currentState == CloudTask.State.FAILED) { context.getStepLogger() .error(Messages.ERROR_EXECUTING_TASK_0_ON_APP_1, taskToPoll.getName(), app.getName()); + context.setVariable(Variables.LAST_TASK_POLL_LOG_TIMESTAMP, Constants.UNSET_LAST_LOG_TIMESTAMP_MS); return AsyncExecutionState.ERROR; } + if (currentState == CloudTask.State.RUNNING || currentState == CloudTask.State.PENDING) { + logStalledTask(context, taskToPoll, app, currentState); + } return AsyncExecutionState.RUNNING; } @@ -65,4 +74,25 @@ public String getPollingErrorMessage(ProcessContext context) { CloudTask task = context.getVariable(Variables.STARTED_TASK); return MessageFormat.format(Messages.ERROR_EXECUTING_TASK_0_ON_APP_1, task.getName(), app.getName()); } + + private void logStalledTask(ProcessContext context, CloudTask task, CloudApplicationExtended app, CloudTask.State currentState) { + Long currentTimeNow = System.currentTimeMillis(); + Long lastLog = context.getVariable(Variables.LAST_TASK_POLL_LOG_TIMESTAMP); + if (!lastLog.equals(Constants.UNSET_LAST_LOG_TIMESTAMP_MS)) { + printTaskExecutionStatusIfDue(context, task, app, currentState, currentTimeNow, lastLog); + } else { + context.setVariable(Variables.LAST_TASK_POLL_LOG_TIMESTAMP, currentTimeNow); + } + } + + private void printTaskExecutionStatusIfDue(ProcessContext context, CloudTask task, CloudApplicationExtended app, + CloudTask.State currentState, Long currentTimeNow, Long lastLog) { + if (currentTimeNow - lastLog >= LOG_INTERVAL_FOR_MESSAGE) { + context.getStepLogger() + .info(Messages.TASK_0_ON_APPLICATION_1_IS_STILL_2, task.getName(), app.getName(), currentState.name() + .toLowerCase()); + context.setVariable(Variables.LAST_TASK_POLL_LOG_TIMESTAMP, currentTimeNow); + } + } + } diff --git a/multiapps-controller-process/src/main/java/org/cloudfoundry/multiapps/controller/process/variables/Variables.java b/multiapps-controller-process/src/main/java/org/cloudfoundry/multiapps/controller/process/variables/Variables.java index 5f8e987e7c..f8ce64e6b9 100644 --- a/multiapps-controller-process/src/main/java/org/cloudfoundry/multiapps/controller/process/variables/Variables.java +++ b/multiapps-controller-process/src/main/java/org/cloudfoundry/multiapps/controller/process/variables/Variables.java @@ -208,6 +208,10 @@ public interface Variables { Variable START_TIME = ImmutableSimpleVariable. builder() .name("startTime") .build(); + Variable LAST_TASK_POLL_LOG_TIMESTAMP = ImmutableSimpleVariable. builder() + .name("lastTaskPollLogTimestamp") + .defaultValue(0L) + .build(); Variable SKIP_MANAGE_SERVICE_BROKER = ImmutableSimpleVariable. builder() .name("skipManageServiceBroker") .build(); diff --git a/multiapps-controller-process/src/test/java/org/cloudfoundry/multiapps/controller/process/steps/PollExecuteTaskStatusStepTest.java b/multiapps-controller-process/src/test/java/org/cloudfoundry/multiapps/controller/process/steps/PollExecuteTaskStatusStepTest.java index c58a09fb92..dec10c5b2d 100644 --- a/multiapps-controller-process/src/test/java/org/cloudfoundry/multiapps/controller/process/steps/PollExecuteTaskStatusStepTest.java +++ b/multiapps-controller-process/src/test/java/org/cloudfoundry/multiapps/controller/process/steps/PollExecuteTaskStatusStepTest.java @@ -14,7 +14,9 @@ import org.cloudfoundry.multiapps.controller.client.lib.domain.ImmutableCloudApplicationExtended; import org.cloudfoundry.multiapps.controller.core.cf.CloudControllerClientFactory; import org.cloudfoundry.multiapps.controller.core.security.token.TokenService; +import org.cloudfoundry.multiapps.controller.process.Constants; import org.cloudfoundry.multiapps.controller.process.variables.Variables; +import org.junit.jupiter.api.Test; import org.junit.jupiter.params.ParameterizedTest; import org.junit.jupiter.params.provider.Arguments; import org.junit.jupiter.params.provider.MethodSource; @@ -22,6 +24,8 @@ import org.mockito.Mockito; import static org.junit.jupiter.api.Assertions.assertEquals; +import static org.junit.jupiter.api.Assertions.assertTrue; +import static org.junit.jupiter.api.AssertionsKt.assertNotNull; import static org.mockito.ArgumentMatchers.any; import static org.mockito.Mockito.when; @@ -85,6 +89,49 @@ void testPollStateExecution(CloudTask.State currentTaskState, long currentTime, testExecuteOperations(); } + @Test + void testFirstTimeOnlyInitializesTimestamp() { + initializeParameters(CloudTask.State.PENDING, System.currentTimeMillis()); + + context.setVariable(Variables.LAST_TASK_POLL_LOG_TIMESTAMP, null); + this.expectedExecutionStatus = AsyncExecutionState.RUNNING; + + testExecuteOperations(); + + Long timeStamp = context.getVariable(Variables.LAST_TASK_POLL_LOG_TIMESTAMP); + assertTrue(timeStamp > 0); + } + + @Test + void testTimestampIsChangedWhenIntervalPassed() { + initializeParameters(CloudTask.State.PENDING, System.currentTimeMillis()); + long logInterval = Duration.ofMinutes(Constants.LOG_STALLED_TASK_MINUTE_INTERVAL) + .toMillis(); + + long currentTime = System.currentTimeMillis(); + long fakeLastTimestampOfLog = currentTime - logInterval - 3000; + context.setVariable(Variables.LAST_TASK_POLL_LOG_TIMESTAMP, fakeLastTimestampOfLog); + + this.expectedExecutionStatus = AsyncExecutionState.RUNNING; + + testExecuteOperations(); + + Long updatedTimeStampOfLog = context.getVariable(Variables.LAST_TASK_POLL_LOG_TIMESTAMP); + assertNotNull(updatedTimeStampOfLog); + assertTrue(updatedTimeStampOfLog >= fakeLastTimestampOfLog + logInterval); + } + + @Test + void testTimestampIsClearedOnFailed() { + initializeParameters(CloudTask.State.FAILED, System.currentTimeMillis()); + context.setVariable(Variables.LAST_TASK_POLL_LOG_TIMESTAMP, System.currentTimeMillis()); + this.expectedExecutionStatus = AsyncExecutionState.ERROR; + + testExecuteOperations(); + + assertEquals(Constants.UNSET_LAST_LOG_TIMESTAMP_MS, context.getVariable(Variables.LAST_TASK_POLL_LOG_TIMESTAMP)); + } + private void initializeParameters(CloudTask.State currentTaskState, long currentTime) { step.currentTimeSupplier = () -> currentTime; prepareContext();