From feb1f96eef41b73b682f24cc0aa20f6c429a6b48 Mon Sep 17 00:00:00 2001 From: Valera V Harseko Date: Sat, 19 Sep 2026 11:26:38 +0300 Subject: [PATCH] [#219] Make UpdateCommand job-wait loop verdict fresh and its test clock-independent WaitForJobsStepExecutor evaluated the timeout after sleeping and then returned the stale "still running" result of the poll made before the sleep, so a stalled runner (or a job finishing during the last sleep) produced "Running jobs did not finish" even though the next poll would have found no jobs. This is what made testEnterMaintenanceMode flake on macos-latest / JDK 26 with its 100ms budget. Check the timeout before each sleep so the verdict is always based on the latest poll, measure elapsed time with the monotonic nanoTime, and route time and sleeping through an injectable WaitClock so the loop can be driven deterministically in tests. testEnterMaintenanceMode now uses the fake clock; a new test reproduces the CI stall and asserts that the step succeeds when the next poll finds no running jobs. Fixes #219 --- .../openidm/shell/impl/UpdateCommand.java | 105 +++++++++++++----- .../openidm/shell/impl/UpdateCommandTest.java | 70 +++++++++++- 2 files changed, 145 insertions(+), 30 deletions(-) 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..14511b687c 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()); @@ -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; } /** 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..e666b3c932 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,6 +272,47 @@ public void testEnterMaintenanceMode() throws Exception { 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( @@ -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) {