Programming exercises: Separate a stalled image pull from a slow one

The pull had a single wall-clock budget of 900 seconds, which is far
longer than a whole build used to take and holds a build thread and an
agent slot for the entire time. Lower the default to 300 seconds.

A single budget also cannot tell the two failures apart. Track how many
updates the daemon reports for a pull and judge it on movement as well
as on total time: a large image over a slow link keeps reporting
progress and may use the full budget, while a pull that reports nothing
at all is abandoned after image-pull-stall-timeout-seconds, 60 by
default. That is what an unreachable registry looks like from the agent
when a firewall drops the packets rather than refusing the connection,
and there is no reason to wait out the full budget for it.

The two cases now fail with different messages, so the build log says
whether the registry was slow or silent. Both close the callback, so
the pull is really abandoned rather than left running in the background.

Author: krusche

src/main/java/de/tum/cit/aet/artemis/buildagent/service/BuildAgentDockerService.java

@@ -2,6 +2,7 @@
 
 import static de.tum.cit.aet.artemis.core.config.Constants.PROFILE_BUILDAGENT;
 
+import java.io.IOException;
 import java.nio.file.Files;
 import java.nio.file.Path;
 import java.time.Duration;
@@ -16,6 +17,7 @@
 import java.util.Set;
 import java.util.concurrent.ConcurrentHashMap;
 import java.util.concurrent.TimeUnit;
+import java.util.concurrent.atomic.AtomicLong;
 import java.util.concurrent.locks.ReentrantLock;
 import java.util.stream.Collectors;
 
@@ -88,6 +90,9 @@ public class BuildAgentDockerService {
 
     private static final Logger log = LoggerFactory.getLogger(BuildAgentDockerService.class);
 
+    /** How often a running pull is re-examined while waiting, short enough to notice a stall promptly. */
+    private static final int PULL_PROGRESS_POLL_INTERVAL_SECONDS = 5;
+
     private final BuildAgentConfiguration buildAgentConfiguration;
 
     private final DistributedDataAccessService distributedDataAccessService;
@@ -133,9 +138,20 @@ public class BuildAgentDockerService {
      * not on the exercise, so a slow registry must not eat into the time budget a student's build gets. Without this, a pull that never makes progress would block
      * the build thread indefinitely.
      */
-    @Value("${artemis.continuous-integration.image-pull-timeout-seconds:900}")
+    @Value("${artemis.continuous-integration.image-pull-timeout-seconds:300}")
     private int imagePullTimeoutSeconds;
 
+    /**
+     * Maximum time a Docker image pull may report no progress at all before it is aborted.
+     * <p>
+     * This separates the two ways a pull goes wrong. A large image over a slow link keeps emitting progress and is
+     * allowed to run until {@link #imagePullTimeoutSeconds}. A pull that is not getting through at all, because the
+     * registry is unreachable or a firewall silently drops the packets rather than refusing the connection, emits
+     * nothing, and there is no reason to hold a build thread and an agent slot for the full budget waiting for it.
+     */
+    @Value("${artemis.continuous-integration.image-pull-stall-timeout-seconds:60}")
+    private int imagePullStallTimeoutSeconds;
+
     /**
      * IDs of the build jobs that are currently pulling a Docker image, with the time the pull started.
      * <p>
@@ -174,6 +190,12 @@ public void applicationReady() {
             log.error(errorMessage);
             throw new IllegalArgumentException(errorMessage);
         }
+        if (imagePullStallTimeoutSeconds <= 0) {
+            String errorMessage = "The Docker image pull stall timeout must be a positive number of seconds, but was " + imagePullStallTimeoutSeconds
+                    + ". It should be changed in the application properties under 'artemis.continuous-integration.image-pull-stall-timeout-seconds'.";
+            log.error(errorMessage);
+            throw new IllegalArgumentException(errorMessage);
+        }
 
         // Schedule the cleanup of dangling build containers once 10 seconds after the application has started and then every containerCleanupScheduleMinutes minutes
         taskScheduler.scheduleAtFixedRate(this::cleanUpContainers, Instant.now().plusSeconds(10), Duration.ofMinutes(containerCleanupScheduleMinutes));
@@ -260,8 +282,27 @@ public void cleanUpContainers() {
      */
     public static class MyPullImageResultCallback extends PullImageResultCallback {
 
+        /**
+         * How many updates the daemon has reported for this pull. Written from the docker-java callback thread and
+         * read by the waiting build thread, hence atomic.
+         * <p>
+         * A counter rather than a timestamp: the caller owns the clock, so "no progress yet" is measured from when
+         * the wait started rather than from when this object happened to be constructed.
+         */
+        private final AtomicLong progressCount = new AtomicLong();
+
+        /**
+         * How many updates the daemon has reported so far.
+         *
+         * @return the number of progress updates received for this pull
+         */
+        public long progressCount() {
+            return progressCount.get();
+        }
+
         @Override
         public void onNext(PullResponseItem item) {
+            progressCount.incrementAndGet();
             String msg = "~~~~~~~~~~~~~~~~~~~~ Pull image progress: " + item.getStatus() + " ~~~~~~~~~~~~~~~~~~~~";
             log.debug(msg);
             super.onNext(item);
@@ -421,14 +462,50 @@ private void doPullDockerImage(BuildJobQueueItem buildJob, BuildLogsMap buildLog
      * @throws InterruptedException if the current thread is interrupted while waiting
      * @throws LocalCIException     if the pull does not finish within the configured timeout
      */
-    private void awaitPullCompletion(PullImageResultCallback callback, String imageName, BuildJobQueueItem buildJob, BuildLogsMap buildLogsMap) throws InterruptedException {
-        if (callback.awaitCompletion(imagePullTimeoutSeconds, TimeUnit.SECONDS)) {
-            return;
+    private void awaitPullCompletion(MyPullImageResultCallback callback, String imageName, BuildJobQueueItem buildJob, BuildLogsMap buildLogsMap) throws InterruptedException {
+        final long deadlineNanos = System.nanoTime() + TimeUnit.SECONDS.toNanos(imagePullTimeoutSeconds);
+        final long stallNanos = TimeUnit.SECONDS.toNanos(imagePullStallTimeoutSeconds);
+        long lastProgressAtNanos = System.nanoTime();
+        long lastProgressCount = callback.progressCount();
+
+        // Wait in slices rather than one long wait, so the pull can also be judged on whether it is still moving.
+        while (!callback.awaitCompletion(PULL_PROGRESS_POLL_INTERVAL_SECONDS, TimeUnit.SECONDS)) {
+            long progressCount = callback.progressCount();
+            if (progressCount != lastProgressCount) {
+                lastProgressCount = progressCount;
+                lastProgressAtNanos = System.nanoTime();
+            }
+            if (System.nanoTime() - lastProgressAtNanos > stallNanos) {
+                abortPull(callback, imageName, buildJob, buildLogsMap,
+                        "reported no progress for " + imagePullStallTimeoutSeconds + " seconds. The registry is most likely unreachable from this agent, for example "
+                                + "because a firewall drops the packets instead of refusing the connection");
+            }
+            if (System.nanoTime() - deadlineNanos >= 0) {
+                abortPull(callback, imageName, buildJob, buildLogsMap, "did not finish within " + imagePullTimeoutSeconds + " seconds");
+            }
+        }
+    }
+
+    /**
+     * Closes the callback so the pull is really abandoned rather than left running in the background, then fails the build job.
+     *
+     * @param callback     the callback of the running pull command
+     * @param imageName    the name of the Docker image being pulled
+     * @param buildJob     the build job the pull belongs to
+     * @param buildLogsMap a map for appending log entries related to the build process
+     * @param reason       what went wrong, phrased to continue "Pulling docker image <name> ..."
+     */
+    private static void abortPull(MyPullImageResultCallback callback, String imageName, BuildJobQueueItem buildJob, BuildLogsMap buildLogsMap, String reason) {
+        try {
+            callback.close();
+        }
+        catch (IOException e) {
+            log.warn("Could not close the callback of the aborted pull of docker image {}", imageName, e);
         }
-        String msg = "~~~~~~~~~~~~~~~~~~~~ Pulling docker image " + imageName + " timed out after " + imagePullTimeoutSeconds + " seconds ~~~~~~~~~~~~~~~~~~~~";
+        String msg = "~~~~~~~~~~~~~~~~~~~~ Pulling docker image " + imageName + " " + reason + " ~~~~~~~~~~~~~~~~~~~~";
         log.error(msg);
         buildLogsMap.appendBuildLogEntry(buildJob.id(), msg);
-        throw new LocalCIException("Timed out after " + imagePullTimeoutSeconds + " seconds while pulling docker image " + imageName);
+        throw new LocalCIException("Pulling docker image " + imageName + " " + reason);
     }
 
     /**

src/main/resources/config/application-buildagent.yml

@@ -71,7 +71,9 @@ artemis:
                 no-proxy: localhost,127.0.0.1
         # The maximum number of seconds a single Docker image pull may take before it is aborted. This is independent of the build timeout below: how long a pull takes
         # depends on the image size and on the registry and network, not on the exercise. Without it, a pull that stops making progress blocks the build thread forever.
-        image-pull-timeout-seconds: 900
+        image-pull-timeout-seconds: 300
+        # Abort much earlier when the pull is not moving at all, which is what an unreachable registry looks like.
+        image-pull-stall-timeout-seconds: 60
         # Configuration for the cleanup of Docker images
         image-cleanup:
             enabled: false

src/test/java/de/tum/cit/aet/artemis/buildagent/service/BuildAgentDockerServiceTest.java

@@ -6,6 +6,7 @@
 import static org.mockito.ArgumentMatchers.anyInt;
 import static org.mockito.ArgumentMatchers.anyLong;
 import static org.mockito.ArgumentMatchers.anyString;
+import static org.mockito.Mockito.atLeastOnce;
 import static org.mockito.Mockito.doReturn;
 import static org.mockito.Mockito.doThrow;
 import static org.mockito.Mockito.mock;
@@ -14,11 +15,13 @@
 import static org.mockito.Mockito.verify;
 import static org.mockito.Mockito.when;
 
+import java.io.IOException;
 import java.time.Instant;
 import java.time.ZonedDateTime;
 import java.util.List;
 import java.util.concurrent.TimeUnit;
 import java.util.concurrent.atomic.AtomicBoolean;
+import java.util.concurrent.atomic.AtomicLong;
 
 import org.junit.jupiter.api.MethodOrderer;
 import org.junit.jupiter.api.Order;
@@ -119,39 +122,90 @@ void testPullDockerImage() {
         BuildConfig buildConfig = new BuildConfig("echo 'test'", "test-image-name", "test", "test", "test", "test", null, null, false, false, null, 0, null, null, null, null);
         BuildAgentDTO buildAgent = new BuildAgentDTO("buildagent1", "address1", "buildagent1");
         var build = new BuildJobQueueItem("1", "job1", buildAgent, 1, 1, 1, 1, 1, BuildStatus.SUCCESSFUL, null, null, buildConfig, null);
+        // This test only cares that a missing image drives the code into a pull. Bound the wait so it cannot depend on
+        // whatever the shared dockerClient mock still carries from another test: without a completing pull the service
+        // would now correctly wait out the stall budget before giving up.
+        int originalStallTimeout = (int) ReflectionTestUtils.getField(buildAgentDockerService, "imagePullStallTimeoutSeconds");
+        ReflectionTestUtils.setField(buildAgentDockerService, "imagePullStallTimeoutSeconds", 1);
         // Pull image
         try {
             buildAgentDockerService.pullDockerImage(build, new BuildLogsMap());
         }
         catch (LocalCIException e) {
-            // Expected exception
-            if (!(e.getCause() instanceof NotFoundException)) {
-                throw e;
-            }
+            // Expected: the image is missing, so either the pull itself reports the failure or it never gets through.
+        }
+        finally {
+            ReflectionTestUtils.setField(buildAgentDockerService, "imagePullStallTimeoutSeconds", originalStallTimeout);
         }
 
-        // Verify that pullImageCmd() was called.
-        verify(dockerClient, times(1)).pullImageCmd("test-image-name");
+        // Verify that a pull was attempted. The count is deliberately not pinned: the service retries a failed pull,
+        // so how often it gets here depends on how the pull fails rather than on what this test is about.
+        verify(dockerClient, atLeastOnce()).pullImageCmd("test-image-name");
     }
 
     @Test
-    void testPullDockerImageFailsWhenPullExceedsTimeout() throws InterruptedException {
+    void testPullDockerImageFailsFastWhenPullMakesNoProgress() throws InterruptedException, IOException {
         var build = mockPendingImagePull();
-        // Simulate a pull that never finishes: the timed await reports that the image did not arrive within the timeout.
+        // A pull that is not getting through at all: the await never completes and the daemon reports nothing, so the
+        // progress counter never moves.
         when(pullImageCallback.awaitCompletion(anyLong(), any(TimeUnit.class))).thenReturn(false);
+        when(pullImageCallback.progressCount()).thenReturn(0L);
+        int originalStallTimeout = (int) ReflectionTestUtils.getField(buildAgentDockerService, "imagePullStallTimeoutSeconds");
+        ReflectionTestUtils.setField(buildAgentDockerService, "imagePullStallTimeoutSeconds", 1);
 
         try {
-            assertThatThrownBy(() -> buildAgentDockerService.pullDockerImage(build, buildLogsMap)).isInstanceOf(LocalCIException.class);
+            // This must not wait for the full pull budget: an unreachable registry is recognisable from the silence alone.
+            assertThatThrownBy(() -> buildAgentDockerService.pullDockerImage(build, buildLogsMap)).isInstanceOf(LocalCIException.class).rootCause()
+                    .hasMessageContaining("reported no progress");
 
-            assertThat(buildLogsMap.getAndTruncateBuildLogs(build.id())).anyMatch(logEntry -> logEntry.log().contains("timed out after"));
+            assertThat(buildLogsMap.getAndTruncateBuildLogs(build.id())).anyMatch(logEntry -> logEntry.log().contains("reported no progress"));
             // The job must not stay registered as pulling, otherwise stale detection would never look at it again.
             assertThat(buildAgentDockerService.isImagePullInProgress(build.id())).isFalse();
+            // The pull is abandoned rather than left running in the background.
+            verify(pullImageCallback).close();
+        }
+        finally {
+            ReflectionTestUtils.setField(buildAgentDockerService, "imagePullStallTimeoutSeconds", originalStallTimeout);
+            buildLogsMap.removeBuildLogs(build.id());
+        }
+    }
+
+    @Test
+    void testPullDockerImageFailsWhenAProgressingPullExceedsTheTotalTimeout() throws InterruptedException {
+        var build = mockPendingImagePull();
+        // A pull that keeps reporting progress but never arrives, so only the overall budget can stop it.
+        when(pullImageCallback.awaitCompletion(anyLong(), any(TimeUnit.class))).thenReturn(false);
+        AtomicLong reportedProgress = new AtomicLong();
+        when(pullImageCallback.progressCount()).thenAnswer(invocation -> reportedProgress.incrementAndGet());
+        int originalTimeout = (int) ReflectionTestUtils.getField(buildAgentDockerService, "imagePullTimeoutSeconds");
+        ReflectionTestUtils.setField(buildAgentDockerService, "imagePullTimeoutSeconds", 1);
+
+        try {
+            assertThatThrownBy(() -> buildAgentDockerService.pullDockerImage(build, buildLogsMap)).isInstanceOf(LocalCIException.class).rootCause()
+                    .hasMessageContaining("did not finish within");
+
+            assertThat(buildLogsMap.getAndTruncateBuildLogs(build.id())).anyMatch(logEntry -> logEntry.log().contains("did not finish within"));
+            assertThat(buildAgentDockerService.isImagePullInProgress(build.id())).isFalse();
         }
         finally {
+            ReflectionTestUtils.setField(buildAgentDockerService, "imagePullTimeoutSeconds", originalTimeout);
             buildLogsMap.removeBuildLogs(build.id());
         }
     }
 
+    @Test
+    void testNonPositivePullStallTimeoutIsRejectedAtStartup() {
+        int originalStallTimeout = (int) ReflectionTestUtils.getField(buildAgentDockerService, "imagePullStallTimeoutSeconds");
+        try {
+            ReflectionTestUtils.setField(buildAgentDockerService, "imagePullStallTimeoutSeconds", 0);
+            assertThatThrownBy(() -> buildAgentDockerService.applicationReady()).isInstanceOf(IllegalArgumentException.class)
+                    .hasMessageContaining("image-pull-stall-timeout-seconds");
+        }
+        finally {
+            ReflectionTestUtils.setField(buildAgentDockerService, "imagePullStallTimeoutSeconds", originalStallTimeout);
+        }
+    }
+
     @Test
     void testImagePullIsVisibleWhileItIsRunning() throws InterruptedException {
         var build = mockPendingImagePull();