Skip to content

[#219] Make UpdateCommand job-wait loop verdict fresh and its test clock-independent #221

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Open
vharseko wants to merge 1 commit into
base: master
Choose a base branch
from
+145 −30
Open

[#219] Make UpdateCommand job-wait loop verdict fresh and its test clock-independent #221

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
1 commit
Select commit
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
105 changes: 76 additions & 29 deletions openidm-shell/src/main/java/org/forgerock/openidm/shell/impl/UpdateCommand.java
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -12,6 +12,7 @@
* information: "Portions copyright [year] [name of copyright owner]".
*
* Copyright 2015-2016 ForgeRock AS.
* Portions Copyright 2026 3A Systems, LLC.
*/
package org.forgerock.openidm.shell.impl;

Expand All @@ -35,6 +36,7 @@
import java.util.List;
import java.util.Map;
import java.util.Scanner;
import java.util.concurrent.TimeUnit;

import org.apache.felix.service.command.CommandSession;
import org.forgerock.json.JsonValue;
Expand Down Expand Up @@ -78,11 +80,46 @@ public class UpdateCommand {
private final CommandSession session;
private final HttpRemoteJsonResource resource;
private final UpdateCommandConfig config;
private final WaitClock clock;
private final Map<UpdateStep, StepExecutor> executorRegistry = new HashMap<>();
private PrintWriter logger;
private UpdateStep[] executeSequence;
private UpdateStep[] recoverySequence;

/**
* Source of elapsed time and of sleeping for the wait loops. Injectable from tests so that the loops can be
* driven deterministically instead of depending on the wall clock.
*/
interface WaitClock {
/**
* Returns a monotonic time in nanoseconds, as {@link System#nanoTime()}.
*
* @return the current monotonic time in nanoseconds.
*/
long nanoTime();

/**
* Blocks for the given number of milliseconds, as {@link Thread#sleep(long)}.
*
* @param millis the time to sleep in milliseconds.
* @throws InterruptedException if interrupted while sleeping.
*/
void sleep(long millis) throws InterruptedException;

/** The clock backed by {@link System#nanoTime()} and {@link Thread#sleep(long)}. */
WaitClock SYSTEM = new WaitClock() {
@Override
public long nanoTime() {
return System.nanoTime();
}

@Override
public void sleep(long millis) throws InterruptedException {
Thread.sleep(millis);
}
};
}

/**
* All steps associated with the update installation process.
*/
Expand Down Expand Up @@ -152,9 +189,24 @@ enum ExecutorStatus {
* @param config the configuration provided by the command line parameters.
*/
public UpdateCommand(CommandSession session, HttpRemoteJsonResource resource, UpdateCommandConfig config) {
this(session, resource, config, WaitClock.SYSTEM);
}

/**
* Constructor that also takes the clock the wait loops measure elapsed time and sleep with, so that tests can
* drive the loops without depending on the wall clock.
*
* @param session the command line session to possibly log output to, or to get keyboard input.
* @param resource the resource provider to execute REST calls to OpenIDM.
* @param config the configuration provided by the command line parameters.
* @param clock the clock to measure elapsed time and sleep with.
*/
UpdateCommand(CommandSession session, HttpRemoteJsonResource resource, UpdateCommandConfig config,
WaitClock clock) {
this.session = session;
this.resource = resource;
this.config = config;
this.clock = clock;

// Register the update steps.
registerStepExecutor(new GetArchiveDataStepExecutor());
Expand Down Expand Up @@ -547,42 +599,37 @@ public UpdateStep getStep() {
*/
@Override
public ExecutorStatus execute(Context context, UpdateExecutionState state) {
long start = System.currentTimeMillis();
long start = clock.nanoTime();
long maxWaitTime = config.getMaxJobsFinishWaitTimeMs();

boolean jobRunning;
boolean timeout = false;
log("Waiting for running jobs to finish.");
do {
try {
jobRunning = isJobRunning(context);
if (jobRunning) {
if (maxWaitTime < 0) {
log("Jobs are still running, exiting update process.");
return ExecutorStatus.FAIL;
}
try {
log("Waiting for jobs to finish...");
Thread.sleep(config.getCheckJobsRunningFrequency());
} catch (InterruptedException e) {
log("WARNING: Got interrupted while waiting for jobs to finish, exiting update process.");
return ExecutorStatus.FAIL;
}
timeout = (System.currentTimeMillis() - start > maxWaitTime);
try {
// The timeout is checked before sleeping, never after, so the verdict is always based on the
// latest poll: jobs that finish during the last sleep are seen rather than reported as still
// running.
while (isJobRunning(context)) {
if (maxWaitTime < 0) {
log("Jobs are still running, exiting update process.");
return ExecutorStatus.FAIL;
}
if (TimeUnit.NANOSECONDS.toMillis(clock.nanoTime() - start) > maxWaitTime) {
log("Running jobs did not finish within the allotted wait time of " + maxWaitTime + "ms.");
return ExecutorStatus.FAIL;
}
try {
log("Waiting for jobs to finish...");
clock.sleep(config.getCheckJobsRunningFrequency());
} catch (InterruptedException e) {
log("WARNING: Got interrupted while waiting for jobs to finish, exiting update process.");
return ExecutorStatus.FAIL;
}
} catch (ResourceException e) {
log("Error encountered while waiting for jobs to finish", e);
return ExecutorStatus.FAIL;
}
} while (jobRunning && !timeout);

if (jobRunning) {
log("Running jobs did not finish within the allotted wait time of " + maxWaitTime + "ms.");
} catch (ResourceException e) {
log("Error encountered while waiting for jobs to finish", e);
return ExecutorStatus.FAIL;
} else {
log("All running jobs have finished.");
return ExecutorStatus.SUCCESS;
}
log("All running jobs have finished.");
return ExecutorStatus.SUCCESS;
}

/**
Expand Down
70 changes: 69 additions & 1 deletion openidm-shell/src/test/java/org/forgerock/openidm/shell/impl/UpdateCommandTest.java
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -12,6 +12,7 @@
* information: "Portions copyright [year] [name of copyright owner]".
*
* Copyright 2015-2016 ForgeRock AS.
* Portions Copyright 2026 3A Systems, LLC.
*/
package org.forgerock.openidm.shell.impl;

Expand All @@ -21,6 +22,8 @@
import static org.forgerock.openidm.shell.impl.UpdateCommand.UpdateStep.*;
import static org.mockito.Mockito.*;

import java.util.concurrent.TimeUnit;

import org.apache.felix.service.command.CommandSession;
import org.forgerock.json.JsonValue;
import org.forgerock.json.resource.ActionRequest;
Expand Down Expand Up @@ -260,14 +263,56 @@ public void testEnterMaintenanceMode() throws Exception {
.setMaxJobsFinishWaitTimeMs(100L)
.setCheckJobsRunningFrequency(10L)
.setMaxUpdateWaitTimeMs(5000L);
UpdateCommand updateCommand = new UpdateCommand(session, resource, config);
// a fake clock keeps the 100ms jobs budget from being crossed by a stalled CI runner (issue #219).
UpdateCommand updateCommand = new UpdateCommand(session, resource, config, new FakeWaitClock(0L));
UpdateExecutionState executionState = updateCommand.execute(new RootContext());

assertThat(executionState.getLastAttemptedStep()).isEqualTo(INSTALL_ARCHIVE);
assertThat(executionState.getCompletedInstallStatus()).isNull();
assertThat(executionState.getLastRecoveryStep()).isEqualTo(ENABLE_SCHEDULER);
}

/**
* Regression test for issue #219: the jobs budget expires during a sleep, but the next poll finds no running
* jobs. The wait step must report what the last poll saw, not fail on the stale state from before the sleep.
*/
@Test
public void testWaitForJobsPollsAgainWhenTimeoutExpiresDuringSleep() throws Exception {
HttpRemoteJsonResource resource = mockResource(
mc(UPDATE_ROUTE, UPDATE_ACTION_AVAIL,
json(object(
field("updates", array(object(field("archive", "test.zip")))),
field("rejects", array())
))),
mc(UPDATE_ROUTE, UPDATE_ACTION_GET_LICENSE, json(object(field("license", "This is the license")))),
mc(SCHEDULER_JOB_ROUTE, SCHEDULER_ACTION_PAUSE, json(object(field("success", true)))),
// one job running at the first poll, none at the second.
mc(SCHEDULER_JOB_ROUTE, SCHEDULER_ACTION_LIST_JOBS, json(array(object())), json(array())),
// mock the next step to fail.
mc(MAINTENANCE_ROUTE, MAINTENANCE_ACTION_ENABLE, json(object(field("maintenanceEnabled", false)))),
// mock the calls on recovery.
mc(SCHEDULER_JOB_ROUTE, SCHEDULER_ACTION_RESUME_JOBS, json(object(field("success", true)))),
mc(MAINTENANCE_ROUTE, MAINTENANCE_ACTION_DISABLE, json(object(field("maintenanceEnabled", false))))
);

UpdateCommandConfig config = new UpdateCommandConfig()
.setUpdateArchive("test.zip")
.setLogFilePath(null)
.setQuietMode(false)
.setAcceptedLicense(true)
.setSkipRepoUpdatePreview(true)
.setMaxJobsFinishWaitTimeMs(100L)
.setCheckJobsRunningFrequency(10L)
.setMaxUpdateWaitTimeMs(1000L);
// every 10ms sleep stalls for another 190ms, so the 100ms budget is crossed during the first sleep.
UpdateCommand updateCommand = new UpdateCommand(session, resource, config, new FakeWaitClock(190L));
UpdateExecutionState executionState = updateCommand.execute(new RootContext());

assertThat(executionState.getLastAttemptedStep()).isEqualTo(ENTER_MAINTENANCE_MODE);
assertThat(executionState.getCompletedInstallStatus()).isNull();
assertThat(executionState.getLastRecoveryStep()).isEqualTo(ENABLE_SCHEDULER);
}

//@Test
public void testTimeoutInstallUpdateArchive() throws Exception {
HttpRemoteJsonResource resource = mockResource(
Expand Down Expand Up @@ -500,6 +545,29 @@ public void testSuccessfulInstallWithRestart() throws Exception {
assertThat(executionState.getLastRecoveryStep()).isEqualTo(FORCE_RESTART);
}

/**
* A {@link UpdateCommand.WaitClock} whose time only advances when the command sleeps: each sleep advances it by
* the requested duration plus a fixed stall, simulating a runner that is descheduled while sleeping.
*/
private static class FakeWaitClock implements UpdateCommand.WaitClock {
private final long stallMs;
private long nowMs;

FakeWaitClock(long stallMs) {
this.stallMs = stallMs;
}

@Override
public long nanoTime() {
return TimeUnit.MILLISECONDS.toNanos(nowMs);
}

@Override
public void sleep(long millis) {
nowMs += millis + stallMs;
}
}

private HttpRemoteJsonResource mockResource(MockCriteria... mockCriterion) throws ResourceException {
HttpRemoteJsonResource resource = mock(HttpRemoteJsonResource.class);
for (MockCriteria mockCriteria : mockCriterion) {
Expand Down
Loading