From 688332889f3f4be407b2685de2c41cd00c13f656 Mon Sep 17 00:00:00 2001 From: Krasimir Kargov Date: Wed, 24 Sep 2025 08:28:38 +0300 Subject: [PATCH 1/5] Add an occasional message when a task execution fails to complete for a long time LMCROSSITXSADEPLOY-3279 --- .../controller/process/Constants.java | 3 ++ .../controller/process/Messages.java | 1 + .../steps/PollExecuteTaskStatusExecution.java | 25 ++++++++++ .../process/variables/Variables.java | 4 ++ .../steps/PollExecuteTaskStatusStepTest.java | 47 +++++++++++++++++++ 5 files changed, 80 insertions(+) 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..63422aa3ce 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 LONG_DEFAULT_NULL_VALUE = 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..0e02017c66 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, null); return AsyncExecutionState.ERROR; } + if (currentState == CloudTask.State.RUNNING || currentState == CloudTask.State.PENDING) { + logStalledTask(context, taskToPoll, app, currentState); + } return AsyncExecutionState.RUNNING; } @@ -65,4 +74,20 @@ 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()); } + + protected 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.LONG_DEFAULT_NULL_VALUE)) { + 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); + } + } else { + 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..b064c3e1e5 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.LONG_DEFAULT_NULL_VALUE, context.getVariable(Variables.LAST_TASK_POLL_LOG_TIMESTAMP)); + } + private void initializeParameters(CloudTask.State currentTaskState, long currentTime) { step.currentTimeSupplier = () -> currentTime; prepareContext(); From 5fb28d7136ff1c80af31d00b532a8d8ff9f3b89b Mon Sep 17 00:00:00 2001 From: Krasimir Kargov Date: Wed, 24 Sep 2025 17:05:02 +0300 Subject: [PATCH 2/5] Fixing resetting value of timestamp when the task has failed previously LMCROSSITXSADEPLOY-3279 --- .../process/steps/PollExecuteTaskStatusExecution.java | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) 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 0e02017c66..b98ed43720 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 @@ -59,7 +59,7 @@ 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, null); + context.setVariable(Variables.LAST_TASK_POLL_LOG_TIMESTAMP, Constants.LONG_DEFAULT_NULL_VALUE); return AsyncExecutionState.ERROR; } if (currentState == CloudTask.State.RUNNING || currentState == CloudTask.State.PENDING) { From d6b94898be639e54a7fbdd388f0a26ebae3310f1 Mon Sep 17 00:00:00 2001 From: Krasimir Kargov Date: Thu, 25 Sep 2025 09:38:29 +0300 Subject: [PATCH 3/5] Changing method's access specifier LMCROSSITXSADEPLOY-3279 --- .../process/steps/PollExecuteTaskStatusExecution.java | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) 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 b98ed43720..b09cba6038 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 @@ -75,7 +75,7 @@ public String getPollingErrorMessage(ProcessContext context) { return MessageFormat.format(Messages.ERROR_EXECUTING_TASK_0_ON_APP_1, task.getName(), app.getName()); } - protected void logStalledTask(ProcessContext context, CloudTask task, CloudApplicationExtended app, CloudTask.State currentState) { + 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.LONG_DEFAULT_NULL_VALUE)) { From e5b3646e0da74445866975af70dfc00884ebb6c9 Mon Sep 17 00:00:00 2001 From: Krasimir Kargov Date: Fri, 26 Sep 2025 16:43:24 +0300 Subject: [PATCH 4/5] Reformatting and changing constant name LMCROSSITXSADEPLOY-3279 --- .../controller/process/Constants.java | 2 +- .../steps/PollExecuteTaskStatusExecution.java | 21 ++++++++++++------- .../steps/PollExecuteTaskStatusStepTest.java | 2 +- 3 files changed, 15 insertions(+), 10 deletions(-) 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 63422aa3ce..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,7 +26,7 @@ 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 LONG_DEFAULT_NULL_VALUE = 0L; + 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/steps/PollExecuteTaskStatusExecution.java b/multiapps-controller-process/src/main/java/org/cloudfoundry/multiapps/controller/process/steps/PollExecuteTaskStatusExecution.java index b09cba6038..3fb433f65e 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 @@ -59,7 +59,7 @@ 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.LONG_DEFAULT_NULL_VALUE); + 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) { @@ -78,16 +78,21 @@ public String getPollingErrorMessage(ProcessContext context) { 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.LONG_DEFAULT_NULL_VALUE)) { - 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); - } + if (!lastLog.equals(Constants.UNSET_LAST_LOG_TIMESTAMP_MS)) { + checkIfProgressMessageShouldBeDone(context, task, app, currentState, currentTimeNow, lastLog); } else { context.setVariable(Variables.LAST_TASK_POLL_LOG_TIMESTAMP, currentTimeNow); } } + private void checkIfProgressMessageShouldBeDone(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/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 b064c3e1e5..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 @@ -129,7 +129,7 @@ void testTimestampIsClearedOnFailed() { testExecuteOperations(); - assertEquals(Constants.LONG_DEFAULT_NULL_VALUE, context.getVariable(Variables.LAST_TASK_POLL_LOG_TIMESTAMP)); + assertEquals(Constants.UNSET_LAST_LOG_TIMESTAMP_MS, context.getVariable(Variables.LAST_TASK_POLL_LOG_TIMESTAMP)); } private void initializeParameters(CloudTask.State currentTaskState, long currentTime) { From 0b7e6c4e751d96525b8dfe62a8ff43e9c530993c Mon Sep 17 00:00:00 2001 From: Krasimir Kargov Date: Fri, 26 Sep 2025 17:01:14 +0300 Subject: [PATCH 5/5] Change method name LMCROSSITXSADEPLOY-3279 --- .../process/steps/PollExecuteTaskStatusExecution.java | 6 +++--- 1 file changed, 3 insertions(+), 3 deletions(-) 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 3fb433f65e..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 @@ -79,14 +79,14 @@ private void logStalledTask(ProcessContext context, CloudTask task, CloudApplica Long currentTimeNow = System.currentTimeMillis(); Long lastLog = context.getVariable(Variables.LAST_TASK_POLL_LOG_TIMESTAMP); if (!lastLog.equals(Constants.UNSET_LAST_LOG_TIMESTAMP_MS)) { - checkIfProgressMessageShouldBeDone(context, task, app, currentState, currentTimeNow, lastLog); + printTaskExecutionStatusIfDue(context, task, app, currentState, currentTimeNow, lastLog); } else { context.setVariable(Variables.LAST_TASK_POLL_LOG_TIMESTAMP, currentTimeNow); } } - private void checkIfProgressMessageShouldBeDone(ProcessContext context, CloudTask task, CloudApplicationExtended app, - CloudTask.State currentState, Long currentTimeNow, Long lastLog) { + 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()