diff --git a/openidm-doc/src/main/asciidoc/install-guide/chap-update.adoc b/openidm-doc/src/main/asciidoc/install-guide/chap-update.adoc index 5d98ff90c1..1d3bda8375 100644 --- a/openidm-doc/src/main/asciidoc/install-guide/chap-update.adoc +++ b/openidm-doc/src/main/asciidoc/install-guide/chap-update.adoc @@ -221,10 +221,10 @@ The maximum time, in milliseconds, that the command should wait for scheduled jo Default: `-1`, (the process exits immediately if any jobs are running) `--maxUpdateWaitTimeMs` TIME:: -The maximum time, in milliseconds, that the server should wait for the update process to complete. +The maximum time, in milliseconds, that the command should wait for the update process to complete. When this time is exceeded, the command stops waiting but the update process continues on the server. The command does not exit maintenance mode, resume the scheduler, or restart OpenIDM in this case: check the progress of the update in its update log, and if the update does not require a restart, exit maintenance mode and resume the scheduler once the update is complete. + -Default: `30000` ms +Default: `0`, (the command waits until the update process is complete) `-l` or `--log` LOG_FILE:: Path to the log file. diff --git a/openidm-shell/src/main/java/org/forgerock/openidm/shell/impl/RemoteCommandScope.java b/openidm-shell/src/main/java/org/forgerock/openidm/shell/impl/RemoteCommandScope.java index dd484947bd..3ea5ab4fb7 100644 --- a/openidm-shell/src/main/java/org/forgerock/openidm/shell/impl/RemoteCommandScope.java +++ b/openidm-shell/src/main/java/org/forgerock/openidm/shell/impl/RemoteCommandScope.java @@ -231,9 +231,10 @@ public void update(CommandSession session, @Parameter(names = {"--maxJobsFinishWaitTimeMs"}, absentValue = "-1") final long maxJobsFinishWaitTimeMs, - @Descriptor("Timeout value to wait for update process to complete. Defaults to 30000 ms.") + @Descriptor("Timeout value to wait for update process to complete. When exceeded, the command stops " + + "waiting and the update continues on the server. Defaults to 0 to wait until it completes.") @MetaVar("TIME") - @Parameter(names = {"--maxUpdateWaitTimeMs"}, absentValue = "30000") + @Parameter(names = {"--maxUpdateWaitTimeMs"}, absentValue = "0") final long maxUpdateWaitTimeMs, @Descriptor("Log file path. (optional) Defaults to logs/update.log") diff --git a/openidm-shell/src/main/java/org/forgerock/openidm/shell/impl/UpdateCommand.java b/openidm-shell/src/main/java/org/forgerock/openidm/shell/impl/UpdateCommand.java index dfdb1267d5..1d59ccf56f 100644 --- a/openidm-shell/src/main/java/org/forgerock/openidm/shell/impl/UpdateCommand.java +++ b/openidm-shell/src/main/java/org/forgerock/openidm/shell/impl/UpdateCommand.java @@ -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; @@ -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; @@ -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 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. */ @@ -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()); @@ -241,6 +293,10 @@ public UpdateExecutionState execute(Context context) { ExecutorStatus status = executor.execute(context, executionResults); if (status.equals(ExecutorStatus.ABORT)) { return executionResults; + } else if (status.equals(ExecutorStatus.FAIL) && executionResults.isDetached()) { + log("ERROR: Stopped waiting for the update. Last Attempted step was " + + executionResults.getLastAttemptedStep() + "."); + break; } else if (status.equals(ExecutorStatus.FAIL)) { log("ERROR: Error during execution. The state of OpenIDM is now unknown. " + "Last Attempted step was " + executionResults.getLastAttemptedStep() + @@ -547,42 +603,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; } /** @@ -705,7 +756,10 @@ public boolean onCondition(UpdateExecutionState state) { } /** - * This will repeatably check the update installation status until it times out or returns a TERMINAL_STATE. + * This will repeatably check the update installation status until it returns a TERMINAL_STATE or the wait is + * given up. The wait is given up when the configured maximum wait time is exceeded, when the thread is interrupted + * or when the status cannot be read. The update may then still be running on the server, so the command detaches + * from it: the recovery steps are skipped and the log explains how to follow up. * * @see UpdateCommandConfig#getMaxUpdateWaitTimeMs() * @see UpdateCommandConfig#getCheckCompleteFrequency() @@ -731,16 +785,27 @@ public ExecutorStatus execute(Context context, UpdateExecutionState state) { "Install start time or Initial install status from install step is missing. Ensure the step " + INSTALL_ARCHIVE + " was completed"); } + long start = clock.nanoTime(); + long maxWaitTime = config.getMaxUpdateWaitTimeMs(); String status = installResponse.get("status").defaultTo(UPDATE_STATUS_IN_PROGRESS).asString().toUpperCase(); String updateId = installResponse.get(ResourceResponse.FIELD_CONTENT_ID).asString(); try { + // As in WaitForJobsStepExecutor, the timeout is checked before sleeping, so the verdict is always + // based on the latest poll. while (!TERMINAL_STATE.contains(status)) { + if (maxWaitTime > 0 && TimeUnit.NANOSECONDS.toMillis(clock.nanoTime() - start) > maxWaitTime) { + return detach(state, updateId, status, + "The update process did not complete within the allotted wait time of " + + maxWaitTime + "ms.", null); + } log("Update procedure is still processing..."); // Wait for the installation process to make some progress. try { - Thread.sleep(config.getCheckCompleteFrequency()); + clock.sleep(config.getCheckCompleteFrequency()); } catch (InterruptedException e) { - //ignore interruption and just check status. + Thread.currentThread().interrupt(); + return detach(state, updateId, status, + "Got interrupted while waiting for the update process to complete.", null); } // Query the status of the installation process. ResourceResponse response = resource.read(context, @@ -748,19 +813,46 @@ public ExecutorStatus execute(Context context, UpdateExecutionState state) { status = response.getContent().get("status").defaultTo(UPDATE_STATUS_IN_PROGRESS) .asString().toUpperCase(); } - if (TERMINAL_STATE.contains(status)) { - state.setCompletedInstallStatus(status); - log("The update process is complete with a status of " + status); - return ExecutorStatus.SUCCESS; - } else { - log("The update process failed to complete within the allotted time. " + - "Please verify the state of OpenIDM."); - return ExecutorStatus.FAIL; - } + state.setCompletedInstallStatus(status); + log("The update process is complete with a status of " + status); + return ExecutorStatus.SUCCESS; } catch (ResourceException e) { - log("Error encountered while checking status of install. The update might still be in process", e); - return ExecutorStatus.FAIL; + return detach(state, updateId, status, + "Error encountered while checking status of install.", e); + } + } + + /** + * Stops waiting for an update that may still be running on the server. The state is marked as detached so + * that the recovery steps do not leave maintenance mode, resume the scheduler or restart OpenIDM while the + * update is still being installed. + * + * @param state the current state of the execution sequence. + * @param updateId the id of the update being installed. + * @param status the last known status of the update. + * @param reason why the wait is given up. + * @param e the error that ended the wait, or null. + * @return ExecutorStatus.FAIL + */ + private ExecutorStatus detach(UpdateExecutionState state, String updateId, String status, String reason, + Exception e) { + state.setDetached(true); + String message = reason + " The update " + updateId + " might still be in progress on the server, " + + "last known status: " + status + ". Recovery steps are skipped. " + + "Check the progress with a read of " + UPDATE_LOG_ROUTE + "/" + updateId + "."; + if (isRestartRequired(state)) { + message += " OpenIDM restarts on its own once the update is complete."; + } else { + message += " Once the update is complete, exit maintenance mode with the action " + + MAINTENANCE_ACTION_DISABLE + " on " + MAINTENANCE_ROUTE + " and resume the scheduler with " + + "the action " + SCHEDULER_ACTION_RESUME_JOBS + " on " + SCHEDULER_JOB_ROUTE + "."; + } + if (null == e) { + log("ERROR: " + message); + } else { + log("ERROR: " + message, e); } + return ExecutorStatus.FAIL; } /** @@ -875,10 +967,11 @@ public ExecutorStatus execute(Context context, UpdateExecutionState state) { * {@inheritDoc} * * @return implemented to return true if the archive data is null or doesn't need to restart and therefore we - * should exit maintenance mode and if the archive data is null. + * should exit maintenance mode and if the archive data is null, unless the command detached from a + * possibly still running update. */ public boolean onCondition(UpdateExecutionState state) { - return !isRestartRequired(state); + return !state.isDetached() && !isRestartRequired(state); } } @@ -922,10 +1015,11 @@ public ExecutorStatus execute(Context context, UpdateExecutionState state) { * {@inheritDoc} * * @return implemented to return true if the archive data is null or doesn't need to restart and therefore we - * should exit maintenance mode and if the archive data is null. + * should exit maintenance mode and if the archive data is null, unless the command detached from a + * possibly still running update. */ public boolean onCondition(UpdateExecutionState state) { - return !isRestartRequired(state); + return !state.isDetached() && !isRestartRequired(state); } } @@ -963,11 +1057,12 @@ public ExecutorStatus execute(Context context, UpdateExecutionState state) { * {@inheritDoc} * If the archive data is null, then it means that the archive file wasn't found to install. No need to restart. * - * @return implemented to return true if the archive data is null or does need a restart. + * @return implemented to return true if the archive data is null or does need a restart, unless the command + * detached from a possibly still running update. */ @Override public boolean onCondition(UpdateExecutionState state) { - return isRestartRequired(state); + return !state.isDetached() && isRestartRequired(state); } } diff --git a/openidm-shell/src/main/java/org/forgerock/openidm/shell/impl/UpdateCommandConfig.java b/openidm-shell/src/main/java/org/forgerock/openidm/shell/impl/UpdateCommandConfig.java index 4368a34ace..4f1f6c107e 100644 --- a/openidm-shell/src/main/java/org/forgerock/openidm/shell/impl/UpdateCommandConfig.java +++ b/openidm-shell/src/main/java/org/forgerock/openidm/shell/impl/UpdateCommandConfig.java @@ -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; @@ -21,7 +22,7 @@ public class UpdateCommandConfig { private String updateArchive; private long maxJobsFinishWaitTimeMs = -1; - private long maxUpdateWaitTimeMs = 30000; + private long maxUpdateWaitTimeMs = 0; private boolean acceptedLicense = false; private boolean skipRepoUpdatePreview = false; private String logFilePath = "logs/update.log"; @@ -71,7 +72,9 @@ public UpdateCommandConfig setMaxJobsFinishWaitTimeMs(long maxJobsFinishWaitTime } /** - * Returns the Maximum time the update command should wait for the installation of the archive to take. + * Returns the Maximum time the update command should wait for the installation of the archive to take. A value + * of 0 or less waits until the installation reaches a terminal status. When the time is exceeded the command + * stops waiting without running the recovery steps; the installation continues on the server. * * @return the Maximum time the update command should wait for the installation of the archive to take. */ @@ -80,10 +83,11 @@ public long getMaxUpdateWaitTimeMs() { } /** - * Sets the Maximum time the update command should wait for the installation of the archive to take. + * Sets the Maximum time the update command should wait for the installation of the archive to take. A value + * of 0 or less waits until the installation reaches a terminal status. * * @param maxUpdateWaitTimeMs the Maximum time the update command should wait for the installation of the archive - * to take. + * to take, or 0 or less to wait without a limit. * @return this config instance */ public UpdateCommandConfig setMaxUpdateWaitTimeMs(long maxUpdateWaitTimeMs) { diff --git a/openidm-shell/src/main/java/org/forgerock/openidm/shell/impl/UpdateExecutionState.java b/openidm-shell/src/main/java/org/forgerock/openidm/shell/impl/UpdateExecutionState.java index cb7de894fc..ccbdad80c7 100644 --- a/openidm-shell/src/main/java/org/forgerock/openidm/shell/impl/UpdateExecutionState.java +++ b/openidm-shell/src/main/java/org/forgerock/openidm/shell/impl/UpdateExecutionState.java @@ -12,6 +12,7 @@ * information: "Portions copyright [year] [name of copyright owner]". * * Copyright 2015 ForgeRock AS. + * Portions Copyright 2026 3A Systems, LLC. */ package org.forgerock.openidm.shell.impl; @@ -28,6 +29,7 @@ class UpdateExecutionState { private String completedInstallStatus; private UpdateStep lastAttemptedStep; private UpdateStep lastRecoveryStep; + private boolean detached; /** * Returns the archive metadata regarding the archive to be installed. @@ -137,4 +139,23 @@ public UpdateStep getLastRecoveryStep() { public void setLastRecoveryStep(UpdateStep lastRecoveryStep) { this.lastRecoveryStep = lastRecoveryStep; } + + /** + * Returns true if the command stopped waiting for an update that may still be running on the server. The recovery + * steps must not run in that case, as they would leave maintenance mode or resume the scheduler mid-install. + * + * @return true if the command detached from a possibly still running update. + */ + public boolean isDetached() { + return detached; + } + + /** + * Sets whether the command stopped waiting for an update that may still be running on the server. + * + * @param detached true if the command detached from a possibly still running update. + */ + public void setDetached(boolean detached) { + this.detached = detached; + } } diff --git a/openidm-shell/src/test/java/org/forgerock/openidm/shell/impl/UpdateCommandTest.java b/openidm-shell/src/test/java/org/forgerock/openidm/shell/impl/UpdateCommandTest.java index 8875e699fd..5d9089fc36 100644 --- a/openidm-shell/src/test/java/org/forgerock/openidm/shell/impl/UpdateCommandTest.java +++ b/openidm-shell/src/test/java/org/forgerock/openidm/shell/impl/UpdateCommandTest.java @@ -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; @@ -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; @@ -260,7 +263,8 @@ 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); @@ -268,7 +272,53 @@ public void testEnterMaintenanceMode() throws Exception { assertThat(executionState.getLastRecoveryStep()).isEqualTo(ENABLE_SCHEDULER); } - //@Test + /** + * 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); + } + + /** + * Issue #222: when the update wait budget is exceeded, the command stops waiting and detaches from the update, + * which may still be running on the server. The recovery steps must not leave maintenance mode or resume the + * scheduler mid-install. + */ + @Test public void testTimeoutInstallUpdateArchive() throws Exception { HttpRemoteJsonResource resource = mockResource( mc(UPDATE_ROUTE, UPDATE_ACTION_AVAIL, @@ -313,12 +363,15 @@ public void testTimeoutInstallUpdateArchive() throws Exception { .setCheckJobsRunningFrequency(10L) .setMaxUpdateWaitTimeMs(10L) .setCheckCompleteFrequency(20L); - UpdateCommand updateCommand = new UpdateCommand(session, resource, config); + // every 20ms poll sees IN_PROGRESS, so the 10ms budget is exceeded before the second sleep. + UpdateCommand updateCommand = new UpdateCommand(session, resource, config, new FakeWaitClock(0L)); UpdateExecutionState executionState = updateCommand.execute(new RootContext()); assertThat(executionState.getLastAttemptedStep()).isEqualTo(WAIT_FOR_INSTALL_DONE); assertThat(executionState.getCompletedInstallStatus()).isNull(); - assertThat(executionState.getLastRecoveryStep()).isEqualTo(ENABLE_SCHEDULER); + assertThat(executionState.isDetached()).isTrue(); + assertThat(executionState.getLastRecoveryStep()).isNull(); + verifyNoRecoveryCalls(resource); } @Test @@ -370,7 +423,8 @@ public void testFailedInstallUpdateArchive() throws Exception { .setCheckJobsRunningFrequency(10L) .setMaxUpdateWaitTimeMs(5000L) .setCheckCompleteFrequency(10L); - UpdateCommand updateCommand = new UpdateCommand(session, resource, config); + // a fake clock keeps the wait budgets from being crossed by a stalled CI runner (issue #222). + UpdateCommand updateCommand = new UpdateCommand(session, resource, config, new FakeWaitClock(0L)); UpdateExecutionState executionState = updateCommand.execute(new RootContext()); assertThat(executionState.getLastAttemptedStep()).isEqualTo(MARK_REPO_UPDATES_COMPLETE); @@ -431,7 +485,8 @@ public void testSuccessfulInstall() throws Exception { .setCheckJobsRunningFrequency(10L) .setMaxUpdateWaitTimeMs(2000L) .setCheckCompleteFrequency(10L); - UpdateCommand updateCommand = new UpdateCommand(session, resource, config); + // a fake clock keeps the wait budgets from being crossed by a stalled CI runner (issue #222). + UpdateCommand updateCommand = new UpdateCommand(session, resource, config, new FakeWaitClock(0L)); UpdateExecutionState executionState = updateCommand.execute(new RootContext()); assertThat(executionState.getLastAttemptedStep()).isEqualTo(MARK_REPO_UPDATES_COMPLETE); @@ -492,7 +547,8 @@ public void testSuccessfulInstallWithRestart() throws Exception { .setCheckJobsRunningFrequency(10L) .setMaxUpdateWaitTimeMs(2000L) .setCheckCompleteFrequency(10L); - UpdateCommand updateCommand = new UpdateCommand(session, resource, config); + // a fake clock keeps the wait budgets from being crossed by a stalled CI runner (issue #222). + UpdateCommand updateCommand = new UpdateCommand(session, resource, config, new FakeWaitClock(0L)); UpdateExecutionState executionState = updateCommand.execute(new RootContext()); assertThat(executionState.getLastAttemptedStep()).isEqualTo(MARK_REPO_UPDATES_COMPLETE); @@ -500,6 +556,150 @@ public void testSuccessfulInstallWithRestart() throws Exception { assertThat(executionState.getLastRecoveryStep()).isEqualTo(FORCE_RESTART); } + /** + * Issue #222: an error while polling the update status leaves the update possibly running on the server, so the + * command detaches from it exactly as on a timeout instead of running the recovery steps. + */ + @Test + public void testPollingErrorDetachesFromInstall() throws Exception { + HttpRemoteJsonResource resource = mockResource( + mc(UPDATE_ROUTE, UPDATE_ACTION_AVAIL, + json(object( + field("updates", + array(object( + field("archive", "test.zip"), + field("restartRequired", true) + )) + ), + 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)))), + mc(SCHEDULER_JOB_ROUTE, SCHEDULER_ACTION_LIST_JOBS, json(array())), + mc(MAINTENANCE_ROUTE, MAINTENANCE_ACTION_ENABLE, json(object(field("maintenanceEnabled", true)))), + mc(UPDATE_ROUTE, UPDATE_ACTION_UPDATE, + json(object(field("status", "IN_PROGRESS"), field(ResourceResponse.FIELD_CONTENT_ID, "1234")))), + // mock the calls on recovery, which must not be made. + mc(SCHEDULER_JOB_ROUTE, SCHEDULER_ACTION_RESUME_JOBS, json(object(field("success", true)))), + mc(MAINTENANCE_ROUTE, MAINTENANCE_ACTION_DISABLE, json(object(field("maintenanceEnabled", false)))), + mc(UPDATE_ROUTE, UPDATE_ACTION_RESTART, json(object())) + ); + when(resource.read(any(Context.class), argThat(new IsRouteMatcher(UPDATE_LOG_ROUTE)))) + .thenThrow(ResourceException.newResourceException(ResourceException.UNAVAILABLE, "Connection lost")); + + UpdateCommandConfig config = new UpdateCommandConfig() + .setUpdateArchive("test.zip") + .setLogFilePath(null) + .setQuietMode(false) + .setAcceptedLicense(true) + .setSkipRepoUpdatePreview(true) + .setMaxJobsFinishWaitTimeMs(1000L) + .setCheckJobsRunningFrequency(10L) + .setCheckCompleteFrequency(10L); + UpdateCommand updateCommand = new UpdateCommand(session, resource, config, new FakeWaitClock(0L)); + UpdateExecutionState executionState = updateCommand.execute(new RootContext()); + + assertThat(executionState.getLastAttemptedStep()).isEqualTo(WAIT_FOR_INSTALL_DONE); + assertThat(executionState.getCompletedInstallStatus()).isNull(); + assertThat(executionState.isDetached()).isTrue(); + assertThat(executionState.getLastRecoveryStep()).isNull(); + verifyNoRecoveryCalls(resource); + verify(resource, never()).action(any(Context.class), + argThat(new IsActionMatcher(UPDATE_ROUTE, UPDATE_ACTION_RESTART))); + } + + /** + * Issue #222: the default wait budget is unlimited, so an install whose polls stall for longer than the former + * 30s default still runs to completion and to the regular recovery steps. + */ + @Test + public void testDefaultWaitsForInstallWithoutLimit() throws Exception { + JsonValue inProgress = json(object( + field(ResourceResponse.FIELD_CONTENT_ID, "1234"), + field(ResourceResponse.FIELD_CONTENT_REVISION, "1"), + field("status", "IN_PROGRESS") + )); + HttpRemoteJsonResource resource = mockResource( + mc(UPDATE_ROUTE, UPDATE_ACTION_AVAIL, + json(object( + field("updates", + array(object( + field("archive", "test.zip"), + field("restartRequired", false) + )) + ), + 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)))), + mc(SCHEDULER_JOB_ROUTE, SCHEDULER_ACTION_LIST_JOBS, json(array())), + mc(MAINTENANCE_ROUTE, MAINTENANCE_ACTION_ENABLE, json(object(field("maintenanceEnabled", true)))), + mc(UPDATE_ROUTE, UPDATE_ACTION_UPDATE, + json(object(field("status", "IN_PROGRESS"), field(ResourceResponse.FIELD_CONTENT_ID, "1234")))), + mc(UPDATE_LOG_ROUTE, null, + inProgress, inProgress, inProgress, + json(object( + field(ResourceResponse.FIELD_CONTENT_ID, "1234"), + field(ResourceResponse.FIELD_CONTENT_REVISION, "1"), + field("status", UPDATE_STATUS_COMPLETE) + ))), + // 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)))) + ); + + // maxUpdateWaitTimeMs is left at its default. + UpdateCommandConfig config = new UpdateCommandConfig() + .setUpdateArchive("test.zip") + .setLogFilePath(null) + .setQuietMode(false) + .setAcceptedLicense(true) + .setSkipRepoUpdatePreview(true) + .setMaxJobsFinishWaitTimeMs(1000L) + .setCheckJobsRunningFrequency(10L) + .setCheckCompleteFrequency(10L); + // every poll stalls for 40s, so four polls take well over the former 30s default. + UpdateCommand updateCommand = new UpdateCommand(session, resource, config, new FakeWaitClock(40000L)); + UpdateExecutionState executionState = updateCommand.execute(new RootContext()); + + assertThat(executionState.getLastAttemptedStep()).isEqualTo(MARK_REPO_UPDATES_COMPLETE); + assertThat(executionState.getCompletedInstallStatus()).isEqualTo(UPDATE_STATUS_COMPLETE); + assertThat(executionState.isDetached()).isFalse(); + assertThat(executionState.getLastRecoveryStep()).isEqualTo(ENABLE_SCHEDULER); + } + + private void verifyNoRecoveryCalls(HttpRemoteJsonResource resource) throws ResourceException { + verify(resource, never()).action(any(Context.class), + argThat(new IsActionMatcher(MAINTENANCE_ROUTE, MAINTENANCE_ACTION_DISABLE))); + verify(resource, never()).action(any(Context.class), + argThat(new IsActionMatcher(SCHEDULER_JOB_ROUTE, SCHEDULER_ACTION_RESUME_JOBS))); + } + + /** + * 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) {