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 5d98ff90c..4ae3f1b2d 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 mark repository updates as complete, exit maintenance mode, resume the scheduler, or restart OpenIDM in this case: check the progress of the update in its update log (`/openidm/maintenance/update/log/__updateId__`). If the status becomes `PENDING_REPO_UPDATES`, apply the repository update scripts and then call `/openidm/maintenance/update?_action=markComplete&updateId=__updateId__`; the update is not complete, and OpenIDM does not restart, until you do. Once the status is `COMPLETE`, OpenIDM restarts on its own if the update requires a restart; otherwise, exit maintenance mode and resume the scheduler. + -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 2a422a552..64831d9ed 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 @@ -233,9 +233,12 @@ 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") + // "" + constant is a compile-time constant, as an annotation value has to be. + @Parameter(names = {"--maxUpdateWaitTimeMs"}, + absentValue = "" + UpdateCommandConfig.DEFAULT_MAX_UPDATE_WAIT_TIME_MS) 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 fc8b95b5c..2f23b8bdb 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 @@ -293,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() + @@ -364,12 +368,12 @@ private void log(String message) { private void log(String message, Throwable throwable) { if (!config.isQuietMode()) { throwable.printStackTrace(session.getConsole()); - log(message); } if (null != logger) { throwable.printStackTrace(logger); - logger.flush(); } + // In quiet mode the log file is the only place the message ends up, so it is written there as well. + log(message); } /** @@ -752,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() @@ -778,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, @@ -795,19 +813,52 @@ 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 + "." + // The server blocks in PENDING_REPO_UPDATES until markComplete arrives, and only the skipped + // MARK_REPO_UPDATES_COMPLETE step sends it. + + " If the status becomes " + UPDATE_STATUS_PENDING_REPO_UPDATES + ", run the repository update" + + " scripts and then call the action " + UPDATE_ACTION_MARK_COMPLETE + " on " + UPDATE_ROUTE + + " with " + UPDATE_PARAM_UPDATE_ID + "=" + updateId + "; the update is complete only after" + + " that."; + if (isRestartRequired(state)) { + message += " OpenIDM restarts on its own once the status is " + UPDATE_STATUS_COMPLETE + "."; + } else { + message += " Once the status is " + UPDATE_STATUS_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; } /** @@ -922,11 +973,12 @@ 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. */ @Override public boolean onCondition(UpdateExecutionState state) { - return !isRestartRequired(state); + return !state.isDetached() && !isRestartRequired(state); } } @@ -970,11 +1022,12 @@ 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. */ @Override public boolean onCondition(UpdateExecutionState state) { - return !isRestartRequired(state); + return !state.isDetached() && !isRestartRequired(state); } } @@ -1012,11 +1065,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 4368a34ac..43b5a51fe 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; @@ -19,9 +20,15 @@ * Value bean to hold the provided command line input parameters, and config data, provided to the update command. */ public class UpdateCommandConfig { + /** + * Default of {@link #getMaxUpdateWaitTimeMs()}: wait until the installation reaches a terminal status. Shared with + * the {@code absentValue} of the {@code --maxUpdateWaitTimeMs} CLI option, so both defaults stay in step. + */ + static final long DEFAULT_MAX_UPDATE_WAIT_TIME_MS = 0L; + private String updateArchive; private long maxJobsFinishWaitTimeMs = -1; - private long maxUpdateWaitTimeMs = 30000; + private long maxUpdateWaitTimeMs = DEFAULT_MAX_UPDATE_WAIT_TIME_MS; private boolean acceptedLicense = false; private boolean skipRepoUpdatePreview = false; private String logFilePath = "logs/update.log"; @@ -71,7 +78,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 +89,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 cb7de894f..ccbdad80c 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 e666b3c93..9c6ad0daf 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 @@ -22,9 +22,15 @@ import static org.forgerock.openidm.shell.impl.UpdateCommand.UpdateStep.*; import static org.mockito.Mockito.*; +import java.io.ByteArrayOutputStream; +import java.io.PrintStream; +import java.nio.charset.StandardCharsets; +import java.nio.file.Files; +import java.nio.file.Path; import java.util.concurrent.TimeUnit; import org.apache.felix.service.command.CommandSession; +import org.assertj.core.api.AbstractCharSequenceAssert; import org.forgerock.json.JsonValue; import org.forgerock.json.resource.ActionRequest; import org.forgerock.json.resource.ActionResponse; @@ -46,6 +52,15 @@ * @see UpdateCommand */ public class UpdateCommandTest { + /** The detach hint for restartRequired=false: leave maintenance mode by hand. */ + private static final String EXIT_MAINTENANCE_HINT = + "the action " + MAINTENANCE_ACTION_DISABLE + " on " + MAINTENANCE_ROUTE; + /** The detach hint for restartRequired=false: resume the scheduler by hand. */ + private static final String RESUME_JOBS_HINT = + "the action " + SCHEDULER_ACTION_RESUME_JOBS + " on " + SCHEDULER_JOB_ROUTE; + /** The detach hint for restartRequired=true. */ + private static final String RESTART_HINT = "OpenIDM restarts on its own"; + private CommandSession session; @BeforeClass @@ -313,9 +328,115 @@ public void testWaitForJobsPollsAgainWhenTimeoutExpiresDuringSleep() throws Exce assertThat(executionState.getLastRecoveryStep()).isEqualTo(ENABLE_SCHEDULER); } - //@Test + /** + * 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( + HttpRemoteJsonResource resource = mockInstallStuckInProgress(); + + UpdateCommandConfig config = new UpdateCommandConfig() + .setUpdateArchive("test.zip") + .setLogFilePath(null) + .setQuietMode(false) + .setAcceptedLicense(true) + .setSkipRepoUpdatePreview(true) + .setMaxJobsFinishWaitTimeMs(1000L) + .setCheckJobsRunningFrequency(10L) + .setMaxUpdateWaitTimeMs(20L) + .setCheckCompleteFrequency(20L); + // every 20ms poll sees IN_PROGRESS. After the first poll the elapsed 20ms is not over the 20ms budget, so + // the log is polled once more, and the budget is exceeded before the third sleep. + ByteArrayOutputStream console = new ByteArrayOutputStream(); + UpdateCommand updateCommand = + new UpdateCommand(consoleSession(console), 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(); + verify(resource, times(2)).read(any(Context.class), argThat(new IsRouteMatcher(UPDATE_LOG_ROUTE))); + verifyNoRecoveryCalls(resource); + // restartRequired=false: the operator has to leave maintenance mode and resume the scheduler by hand. + assertDetachMessage(console.toString()) + .contains("did not complete within the allotted wait time of 20ms") + .contains("last known status: IN_PROGRESS") + .contains(EXIT_MAINTENANCE_HINT) + .contains(RESUME_JOBS_HINT) + .doesNotContain(RESTART_HINT); + } + + /** + * Issue #222: an interrupt ends the wait like the budget does, and the interrupt flag is kept for the caller. + */ + @Test + public void testInterruptDetachesFromInstall() throws Exception { + HttpRemoteJsonResource resource = mockInstallStuckInProgress(); + + UpdateCommandConfig config = new UpdateCommandConfig() + .setUpdateArchive("test.zip") + .setLogFilePath(null) + .setQuietMode(false) + .setAcceptedLicense(true) + .setSkipRepoUpdatePreview(true) + .setMaxJobsFinishWaitTimeMs(1000L) + .setCheckJobsRunningFrequency(10L) + // only bounds the test: were the interrupt swallowed, the wait would poll until this expires. + .setMaxUpdateWaitTimeMs(100L) + .setCheckCompleteFrequency(20L); + UpdateCommand.WaitClock interrupting = new UpdateCommand.WaitClock() { + private long nowMs; + + @Override + public long nanoTime() { + return TimeUnit.MILLISECONDS.toNanos(nowMs); + } + + @Override + public void sleep(long millis) throws InterruptedException { + nowMs += millis; + if (millis == 20L) { // checkCompleteFrequency; the job wait sleeps 10L + throw new InterruptedException(); + } + } + }; + ByteArrayOutputStream console = new ByteArrayOutputStream(); + UpdateCommand updateCommand = new UpdateCommand(consoleSession(console), resource, config, interrupting); + try { + 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(); + assertThat(Thread.currentThread().isInterrupted()).isTrue(); + // the first interrupted sleep ends the wait, so the update log is never polled. + verify(resource, never()).read(any(Context.class), argThat(new IsRouteMatcher(UPDATE_LOG_ROUTE))); + verifyNoRecoveryCalls(resource); + assertDetachMessage(console.toString()) + .contains("Got interrupted while waiting for the update process to complete") + .contains("last known status: IN_PROGRESS"); + } finally { + // clear the restored flag, so it does not leak into the next test. + Thread.interrupted(); + } + } + + /** + * An update with restartRequired=false whose log never leaves IN_PROGRESS, with the recovery calls mocked. + */ + private HttpRemoteJsonResource mockInstallStuckInProgress() throws ResourceException { + return mockInstallWithLogStatus("IN_PROGRESS"); + } + + /** + * An update with restartRequired=false whose log always reports the given status, with the recovery calls mocked. + */ + private HttpRemoteJsonResource mockInstallWithLogStatus(String logStatus) throws ResourceException { + return mockResource( mc(UPDATE_ROUTE, UPDATE_ACTION_AVAIL, json(object( field("updates", @@ -339,7 +460,7 @@ public void testTimeoutInstallUpdateArchive() throws Exception { json(object( field(ResourceResponse.FIELD_CONTENT_ID, "1234"), field(ResourceResponse.FIELD_CONTENT_REVISION, "1"), - field("status", "IN_PROGRESS") + field("status", logStatus) )) ), @@ -347,23 +468,6 @@ public void testTimeoutInstallUpdateArchive() throws Exception { 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(1000L) - .setCheckJobsRunningFrequency(10L) - .setMaxUpdateWaitTimeMs(10L) - .setCheckCompleteFrequency(20L); - UpdateCommand updateCommand = new UpdateCommand(session, resource, config); - UpdateExecutionState executionState = updateCommand.execute(new RootContext()); - - assertThat(executionState.getLastAttemptedStep()).isEqualTo(WAIT_FOR_INSTALL_DONE); - assertThat(executionState.getCompletedInstallStatus()).isNull(); - assertThat(executionState.getLastRecoveryStep()).isEqualTo(ENABLE_SCHEDULER); } @Test @@ -415,7 +519,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); @@ -476,7 +581,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); @@ -537,7 +643,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); @@ -545,6 +652,237 @@ 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); + ByteArrayOutputStream console = new ByteArrayOutputStream(); + UpdateCommand updateCommand = + new UpdateCommand(consoleSession(console), 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))); + // restartRequired=true: OpenIDM restarts on its own, so leaving maintenance mode by hand is not advised. + assertDetachMessage(console.toString()) + .contains("Error encountered while checking status of install") + .contains("last known status: IN_PROGRESS") + .contains(RESTART_HINT) + .doesNotContain(EXIT_MAINTENANCE_HINT) + .doesNotContain(RESUME_JOBS_HINT); + } + + /** + * Issue #222: in quiet mode the log file is the only record of a detach, so a polling error must write the + * follow-up instructions there, not just its stack trace. + */ + @Test + public void testPollingErrorDetachLogsFollowUpInQuietMode() throws Exception { + HttpRemoteJsonResource resource = mockInstallStuckInProgress(); + when(resource.read(any(Context.class), argThat(new IsRouteMatcher(UPDATE_LOG_ROUTE)))) + .thenThrow(ResourceException.newResourceException(ResourceException.UNAVAILABLE, "Connection lost")); + Path log = Files.createTempFile("update", ".log"); + try { + UpdateCommandConfig config = new UpdateCommandConfig() + .setUpdateArchive("test.zip") + .setLogFilePath(log.toString()) + .setQuietMode(true) + .setAcceptedLicense(true) + .setSkipRepoUpdatePreview(true) + .setMaxJobsFinishWaitTimeMs(1000L) + .setCheckJobsRunningFrequency(10L) + .setCheckCompleteFrequency(10L); + ByteArrayOutputStream console = new ByteArrayOutputStream(); + UpdateExecutionState executionState = + new UpdateCommand(consoleSession(console), resource, config, new FakeWaitClock(0L)) + .execute(new RootContext()); + + assertThat(executionState.isDetached()).isTrue(); + verifyNoRecoveryCalls(resource); + assertThat(console.toString()).isEmpty(); + // restartRequired=false: the operator has to leave maintenance mode and resume the scheduler by hand. + assertDetachMessage(new String(Files.readAllBytes(log), StandardCharsets.UTF_8)) + .contains("Error encountered while checking status of install") + .contains("Connection lost") + .contains(EXIT_MAINTENANCE_HINT) + .contains(RESUME_JOBS_HINT); + } finally { + Files.delete(log); + } + } + + /** + * Issue #222: as in {@link #testWaitForJobsPollsAgainWhenTimeoutExpiresDuringSleep()}, the install wait budget + * expires during a sleep, but the next poll finds the update complete. The step must report what the last poll + * saw instead of detaching from an update that has already finished. + */ + @Test + public void testInstallWaitPollsAgainWhenBudgetExpiresDuringSleep() throws Exception { + HttpRemoteJsonResource resource = mockInstallWithLogStatus(UPDATE_STATUS_COMPLETE); + + UpdateCommandConfig config = new UpdateCommandConfig() + .setUpdateArchive("test.zip") + .setLogFilePath(null) + .setQuietMode(false) + .setAcceptedLicense(true) + .setSkipRepoUpdatePreview(true) + .setMaxJobsFinishWaitTimeMs(1000L) + .setCheckJobsRunningFrequency(10L) + // the 10ms budget expires during the first 20ms sleep; the poll after it still decides. + .setMaxUpdateWaitTimeMs(10L) + .setCheckCompleteFrequency(20L); + UpdateExecutionState executionState = + new UpdateCommand(session, resource, config, new FakeWaitClock(0L)).execute(new RootContext()); + + assertThat(executionState.isDetached()).isFalse(); + assertThat(executionState.getCompletedInstallStatus()).isEqualTo(UPDATE_STATUS_COMPLETE); + assertThat(executionState.getLastRecoveryStep()).isEqualTo(ENABLE_SCHEDULER); + } + + /** + * 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. The CLI option shares this default. + */ + @Test + public void testDefaultWaitsForInstallWithoutLimit() throws Exception { + // maxUpdateWaitTimeMs is left at its default. + assertWaitsForInstallWithoutLimit(new UpdateCommandConfig()); + } + + /** + * Issue #222: a negative wait budget means no limit as well, as documented, rather than detaching at once. + */ + @Test + public void testNegativeBudgetWaitsForInstallWithoutLimit() throws Exception { + assertWaitsForInstallWithoutLimit(new UpdateCommandConfig().setMaxUpdateWaitTimeMs(-1L)); + } + + private void assertWaitsForInstallWithoutLimit(UpdateCommandConfig config) 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)))) + ); + + config.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); + } + + /** + * Asserts the part of the detach message that does not depend on restartRequired: the command says it stopped + * waiting instead of attempting recovery, names the update log to follow and how to unblock repo updates. + */ + private static AbstractCharSequenceAssert assertDetachMessage(String console) { + return assertThat(console) + .contains("Stopped waiting for the update") + .doesNotContain("attempting recovery steps") + .contains(UPDATE_LOG_ROUTE + "/1234") + .contains(UPDATE_STATUS_PENDING_REPO_UPDATES) + .contains("the action " + UPDATE_ACTION_MARK_COMPLETE + " on " + UPDATE_ROUTE + + " with " + UPDATE_PARAM_UPDATE_ID + "=1234"); + } + + /** + * Returns a session whose console writes into the given buffer. + */ + private static CommandSession consoleSession(ByteArrayOutputStream console) { + CommandSession consoleSession = mock(CommandSession.class); + when(consoleSession.getConsole()).thenReturn(new PrintStream(console, true)); + return consoleSession; + } + + 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.