Skip to content

Commit 4419e7f

Browse files
karrgovkarrgov
committed
Add an occasional message when a task execution fails to complete for a long time
LMCROSSITXSADEPLOY-3279
1 parent 93ac941 commit 4419e7f

File tree

5 files changed

+91
-0
lines changed

5 files changed

+91
-0
lines changed

‎multiapps-controller-process/src/main/java/org/cloudfoundry/multiapps/controller/process/Constants.java‎

Lines changed: 3 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -26,6 +26,9 @@ public class Constants {
2626
public static final String MTA_BACKUP_NAMESPACE = "mta-backup";
2727
public static final String MTA_FOR_DELETION_PREFIX = "to-be-deleted";
2828

29+
public static final Long LONG_DEFAULT_NULL_VALUE = 0L;
30+
public static final int LOG_STALLED_TASK_MINUTE_INTERVAL = 5;
31+
2932
protected Constants() {
3033
}
3134
}

‎multiapps-controller-process/src/main/java/org/cloudfoundry/multiapps/controller/process/Messages.java‎

Lines changed: 1 addition & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -336,6 +336,7 @@ public class Messages {
336336
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}\"";
337337
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}\"";
338338
public static final String EXISTING_APPS_TO_BACKUP = "Existing apps to backup: {0}";
339+
public static final String TASK_0_ON_APPLICATION_1_IS_STILL_2 = "Task \"{0}\" on application \"{1}\" is still \"{2}\"";
339340

340341
// Progress messages
341342
public static final String OPERATION_ID = "Operation ID: {0}";

‎multiapps-controller-process/src/main/java/org/cloudfoundry/multiapps/controller/process/steps/PollExecuteTaskStatusExecution.java‎

Lines changed: 25 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -1,6 +1,7 @@
11
package org.cloudfoundry.multiapps.controller.process.steps;
22

33
import java.text.MessageFormat;
4+
import java.time.Duration;
45
import java.util.UUID;
56

67
import org.cloudfoundry.multiapps.controller.client.facade.CloudControllerClient;
@@ -9,6 +10,7 @@
910
import org.cloudfoundry.multiapps.controller.core.cf.CloudControllerClientFactory;
1011
import org.cloudfoundry.multiapps.controller.core.security.token.TokenService;
1112
import org.cloudfoundry.multiapps.controller.persistence.services.ProcessLoggerProvider;
13+
import org.cloudfoundry.multiapps.controller.process.Constants;
1214
import org.cloudfoundry.multiapps.controller.process.Messages;
1315
import org.cloudfoundry.multiapps.controller.process.variables.Variables;
1416
import org.slf4j.Logger;
@@ -18,6 +20,9 @@ public class PollExecuteTaskStatusExecution implements AsyncExecution {
1820

1921
private static final Logger LOGGER = LoggerFactory.getLogger(PollExecuteTaskStatusExecution.class);
2022

23+
private static final long LOG_INTERVAL_FOR_MESSAGE = Duration.ofMinutes(Constants.LOG_STALLED_TASK_MINUTE_INTERVAL)
24+
.toMillis();
25+
2126
private final CloudControllerClientFactory clientFactory;
2227
private final TokenService tokenService;
2328

@@ -54,8 +59,12 @@ public AsyncExecutionState execute(ProcessContext context) {
5459
if (currentState == CloudTask.State.FAILED) {
5560
context.getStepLogger()
5661
.error(Messages.ERROR_EXECUTING_TASK_0_ON_APP_1, taskToPoll.getName(), app.getName());
62+
context.setVariable(Variables.LAST_TASK_POLL_LOG_TIMESTAMP, null);
5763
return AsyncExecutionState.ERROR;
5864
}
65+
if (currentState == CloudTask.State.RUNNING || currentState == CloudTask.State.PENDING) {
66+
logStalledTask(context, taskToPoll, app, currentState);
67+
}
5968
return AsyncExecutionState.RUNNING;
6069
}
6170

@@ -65,4 +74,20 @@ public String getPollingErrorMessage(ProcessContext context) {
6574
CloudTask task = context.getVariable(Variables.STARTED_TASK);
6675
return MessageFormat.format(Messages.ERROR_EXECUTING_TASK_0_ON_APP_1, task.getName(), app.getName());
6776
}
77+
78+
protected void logStalledTask(ProcessContext context, CloudTask task, CloudApplicationExtended app, CloudTask.State currentState) {
79+
Long currentTimeNow = System.currentTimeMillis();
80+
Long lastLog = context.getVariable(Variables.LAST_TASK_POLL_LOG_TIMESTAMP);
81+
if (!lastLog.equals(Constants.LONG_DEFAULT_NULL_VALUE)) {
82+
if (currentTimeNow - lastLog >= LOG_INTERVAL_FOR_MESSAGE) {
83+
context.getStepLogger()
84+
.info(Messages.TASK_0_ON_APPLICATION_1_IS_STILL_2, task.getName(), app.getName(), currentState.name()
85+
.toLowerCase());
86+
context.setVariable(Variables.LAST_TASK_POLL_LOG_TIMESTAMP, currentTimeNow);
87+
}
88+
} else {
89+
context.setVariable(Variables.LAST_TASK_POLL_LOG_TIMESTAMP, currentTimeNow);
90+
}
91+
}
92+
6893
}

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

Lines changed: 4 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -208,6 +208,10 @@ public interface Variables {
208208
Variable<Long> START_TIME = ImmutableSimpleVariable.<Long> builder()
209209
.name("startTime")
210210
.build();
211+
Variable<Long> LAST_TASK_POLL_LOG_TIMESTAMP = ImmutableSimpleVariable.<Long> builder()
212+
.name("lastTaskPollLogTimestamp")
213+
.defaultValue(0L)
214+
.build();
211215
Variable<Boolean> SKIP_MANAGE_SERVICE_BROKER = ImmutableSimpleVariable.<Boolean> builder()
212216
.name("skipManageServiceBroker")
213217
.build();

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

Lines changed: 58 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -14,14 +14,18 @@
1414
import org.cloudfoundry.multiapps.controller.client.lib.domain.ImmutableCloudApplicationExtended;
1515
import org.cloudfoundry.multiapps.controller.core.cf.CloudControllerClientFactory;
1616
import org.cloudfoundry.multiapps.controller.core.security.token.TokenService;
17+
import org.cloudfoundry.multiapps.controller.process.Constants;
1718
import org.cloudfoundry.multiapps.controller.process.variables.Variables;
19+
import org.junit.jupiter.api.Test;
1820
import org.junit.jupiter.params.ParameterizedTest;
1921
import org.junit.jupiter.params.provider.Arguments;
2022
import org.junit.jupiter.params.provider.MethodSource;
2123
import org.mockito.Mock;
2224
import org.mockito.Mockito;
2325

2426
import static org.junit.jupiter.api.Assertions.assertEquals;
27+
import static org.junit.jupiter.api.Assertions.assertTrue;
28+
import static org.junit.jupiter.api.AssertionsKt.assertNotNull;
2529
import static org.mockito.ArgumentMatchers.any;
2630
import static org.mockito.Mockito.when;
2731

@@ -85,6 +89,60 @@ void testPollStateExecution(CloudTask.State currentTaskState, long currentTime,
8589
testExecuteOperations();
8690
}
8791

92+
@Test
93+
void testFirstTimeOnlyInitializesTimestamp() {
94+
initializeParameters(CloudTask.State.PENDING, System.currentTimeMillis());
95+
96+
context.setVariable(Variables.LAST_TASK_POLL_LOG_TIMESTAMP, null);
97+
this.expectedExecutionStatus = AsyncExecutionState.RUNNING;
98+
99+
testExecuteOperations();
100+
101+
Long timeStamp = context.getVariable(Variables.LAST_TASK_POLL_LOG_TIMESTAMP);
102+
assertTrue(timeStamp > 0);
103+
}
104+
105+
@Test
106+
void testTimestampIsChangedWhenIntervalPassed() {
107+
initializeParameters(CloudTask.State.PENDING, System.currentTimeMillis());
108+
long logInterval = Duration.ofMinutes(Constants.LOG_STALLED_TASK_MINUTE_INTERVAL)
109+
.toMillis();
110+
111+
long currentTime = System.currentTimeMillis();
112+
long fakeLastTimestampOfLog = currentTime - logInterval - 3000;
113+
context.setVariable(Variables.LAST_TASK_POLL_LOG_TIMESTAMP, fakeLastTimestampOfLog);
114+
115+
this.expectedExecutionStatus = AsyncExecutionState.RUNNING;
116+
117+
testExecuteOperations();
118+
119+
Long updatedTimeStampOfLog = context.getVariable(Variables.LAST_TASK_POLL_LOG_TIMESTAMP);
120+
assertNotNull(updatedTimeStampOfLog);
121+
assertTrue(updatedTimeStampOfLog >= fakeLastTimestampOfLog + logInterval);
122+
}
123+
124+
@Test
125+
void testTimestampIsClearedOnSucceeded() {
126+
initializeParameters(CloudTask.State.SUCCEEDED, System.currentTimeMillis());
127+
context.setVariable(Variables.LAST_TASK_POLL_LOG_TIMESTAMP, System.currentTimeMillis());
128+
this.expectedExecutionStatus = AsyncExecutionState.FINISHED;
129+
130+
testExecuteOperations();
131+
132+
assertEquals(Constants.LONG_DEFAULT_NULL_VALUE, context.getVariable(Variables.LAST_TASK_POLL_LOG_TIMESTAMP));
133+
}
134+
135+
@Test
136+
void testTimestampIsClearedOnFailed() {
137+
initializeParameters(CloudTask.State.FAILED, System.currentTimeMillis());
138+
context.setVariable(Variables.LAST_TASK_POLL_LOG_TIMESTAMP, System.currentTimeMillis());
139+
this.expectedExecutionStatus = AsyncExecutionState.ERROR;
140+
141+
testExecuteOperations();
142+
143+
assertEquals(Constants.LONG_DEFAULT_NULL_VALUE, context.getVariable(Variables.LAST_TASK_POLL_LOG_TIMESTAMP));
144+
}
145+
88146
private void initializeParameters(CloudTask.State currentTaskState, long currentTime) {
89147
step.currentTimeSupplier = () -> currentTime;
90148
prepareContext();

0 commit comments

Comments
 (0)