Add an occasional message when a task execution fails to complete for a long time LMCROSSITXSADEPLOY-3279

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() {
     }
 }

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}";

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);
+        }
+    }
+
 }

multiapps-controller-process/src/main/java/org/cloudfoundry/multiapps/controller/process/variables/Variables.java

@@ -208,6 +208,10 @@ public interface Variables {
     Variable<Long> START_TIME = ImmutableSimpleVariable.<Long> builder()
                                                        .name("startTime")
                                                        .build();
+    Variable<Long> LAST_TASK_POLL_LOG_TIMESTAMP = ImmutableSimpleVariable.<Long> builder()
+                                                                         .name("lastTaskPollLogTimestamp")
+                                                                         .defaultValue(0L)
+                                                                         .build();
     Variable<Boolean> SKIP_MANAGE_SERVICE_BROKER = ImmutableSimpleVariable.<Boolean> builder()
                                                                           .name("skipManageServiceBroker")
                                                                           .build();

multiapps-controller-process/src/test/java/org/cloudfoundry/multiapps/controller/process/steps/PollExecuteTaskStatusStepTest.java

@@ -14,14 +14,18 @@
 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;
 import org.mockito.Mock;
 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();