Improve pull handling

core/src/main/java/org/testcontainers/DockerClientFactory.java

@@ -4,19 +4,25 @@
 import com.github.dockerjava.api.command.CreateContainerCmd;
 import com.github.dockerjava.api.exception.InternalServerErrorException;
 import com.github.dockerjava.api.exception.NotFoundException;
-import com.github.dockerjava.api.model.*;
+import com.github.dockerjava.api.model.AccessMode;
+import com.github.dockerjava.api.model.Bind;
+import com.github.dockerjava.api.model.Image;
+import com.github.dockerjava.api.model.Info;
+import com.github.dockerjava.api.model.Version;
+import com.github.dockerjava.api.model.Volume;
 import com.github.dockerjava.core.command.ExecStartResultCallback;
-import com.github.dockerjava.core.command.PullImageResultCallback;
 import com.google.common.annotations.VisibleForTesting;
 import com.google.common.collect.ImmutableMap;
 import lombok.Getter;
+import lombok.SneakyThrows;
 import lombok.Synchronized;
 import lombok.extern.slf4j.Slf4j;
 import org.hamcrest.BaseMatcher;
 import org.hamcrest.Description;
 import org.rnorth.visibleassertions.VisibleAssertions;
 import org.testcontainers.dockerclient.DockerClientProviderStrategy;
 import org.testcontainers.dockerclient.DockerMachineClientProviderStrategy;
+import org.testcontainers.images.TimeLimitedLoggedPullImageResultCallback;
 import org.testcontainers.utility.ComparableVersion;
 import org.testcontainers.utility.MountableFile;
 import org.testcontainers.utility.ResourceReaper;
@@ -125,7 +131,7 @@ public DockerClient client() {
                 ryukContainerId = ResourceReaper.start(hostIpAddress, client);
                 log.info("Ryuk started - will monitor and terminate Testcontainers containers on JVM exit");
             }
-           
+
             boolean checksEnabled = !TestcontainersConfiguration.getInstance().isDisableChecks();
             if (checksEnabled) {
                 VisibleAssertions.info("Checking the system...");
@@ -215,10 +221,11 @@ private boolean checkMountableFile() {
     /**
    * Check whether the image is available locally and pull it otherwise
    */
+    @SneakyThrows
     public void checkAndPullImage(DockerClient client, String image) {
         List<Image> images = client.listImagesCmd().withImageNameFilter(image).exec();
         if (images.isEmpty()) {
-            client.pullImageCmd(image).exec(new PullImageResultCallback()).awaitSuccess();
+            client.pullImageCmd(image).exec(new TimeLimitedLoggedPullImageResultCallback(log)).awaitCompletion();
         }
     }
 

core/src/main/java/org/testcontainers/containers/DockerComposeContainer.java

@@ -19,9 +19,7 @@
 import org.testcontainers.containers.output.OutputFrame;
 import org.testcontainers.containers.output.Slf4jLogConsumer;
 import org.testcontainers.containers.startupcheck.IndefiniteWaitOneShotStartupCheckStrategy;
-import org.testcontainers.containers.wait.strategy.Wait;
-import org.testcontainers.containers.wait.strategy.WaitAllStrategy;
-import org.testcontainers.containers.wait.strategy.WaitStrategy;
+import org.testcontainers.containers.wait.strategy.*;
 import org.testcontainers.lifecycle.Startable;
 import org.testcontainers.utility.*;
 import org.yaml.snakeyaml.Yaml;
@@ -32,9 +30,7 @@
 import java.io.File;
 import java.io.FileInputStream;
 import java.io.IOException;
-import java.nio.file.Files;
-import java.nio.file.Path;
-import java.nio.file.Paths;
+import java.nio.file.*;
 import java.time.Duration;
 import java.util.AbstractMap.SimpleEntry;
 import java.util.*;

core/src/main/java/org/testcontainers/containers/GenericContainer.java

@@ -3,9 +3,22 @@
 import com.github.dockerjava.api.DockerClient;
 import com.github.dockerjava.api.command.CreateContainerCmd;
 import com.github.dockerjava.api.command.InspectContainerResponse;
-import com.github.dockerjava.api.model.*;
+import com.github.dockerjava.api.model.Bind;
+import com.github.dockerjava.api.model.ContainerNetwork;
+import com.github.dockerjava.api.model.ExposedPort;
+import com.github.dockerjava.api.model.HostConfig;
+import com.github.dockerjava.api.model.Info;
+import com.github.dockerjava.api.model.Link;
+import com.github.dockerjava.api.model.PortBinding;
+import com.github.dockerjava.api.model.Volume;
+import com.github.dockerjava.api.model.VolumesFrom;
 import com.google.common.base.Strings;
-import lombok.*;
+import lombok.AccessLevel;
+import lombok.Data;
+import lombok.EqualsAndHashCode;
+import lombok.NonNull;
+import lombok.Setter;
+import lombok.SneakyThrows;
 import org.apache.commons.compress.archivers.tar.TarArchiveInputStream;
 import org.apache.commons.compress.archivers.tar.TarArchiveOutputStream;
 import org.apache.commons.compress.utils.IOUtils;
@@ -33,13 +46,34 @@
 import org.testcontainers.lifecycle.Startable;
 import org.testcontainers.lifecycle.TestDescription;
 import org.testcontainers.lifecycle.TestLifecycleAware;
-import org.testcontainers.utility.*;
-
-import java.io.*;
+import org.testcontainers.utility.Base58;
+import org.testcontainers.utility.DockerLoggerFactory;
+import org.testcontainers.utility.DockerMachineClient;
+import org.testcontainers.utility.MountableFile;
+import org.testcontainers.utility.PathUtils;
+import org.testcontainers.utility.ResourceReaper;
+import org.testcontainers.utility.TestcontainersConfiguration;
+import org.testcontainers.utility.ThrowingFunction;
+
+import java.io.ByteArrayInputStream;
+import java.io.ByteArrayOutputStream;
+import java.io.File;
+import java.io.FileOutputStream;
+import java.io.IOException;
+import java.io.InputStream;
 import java.nio.charset.Charset;
 import java.nio.file.Path;
 import java.time.Duration;
-import java.util.*;
+import java.util.ArrayList;
+import java.util.Arrays;
+import java.util.Collections;
+import java.util.HashMap;
+import java.util.HashSet;
+import java.util.LinkedHashSet;
+import java.util.List;
+import java.util.Map;
+import java.util.Optional;
+import java.util.Set;
 import java.util.concurrent.Future;
 import java.util.concurrent.TimeUnit;
 import java.util.concurrent.atomic.AtomicInteger;

core/src/main/java/org/testcontainers/images/LoggedPullImageResultCallback.java

@@ -0,0 +1,121 @@
+package org.testcontainers.images;
+
+import com.github.dockerjava.api.model.PullResponseItem;
+import com.github.dockerjava.core.command.PullImageResultCallback;
+import org.slf4j.Logger;
+
+import java.io.Closeable;
+import java.time.Duration;
+import java.time.Instant;
+import java.util.*;
+
+import static java.lang.String.format;
+import static org.apache.commons.io.FileUtils.byteCountToDisplaySize;
+
+/**
+ * {@link PullImageResultCallback} with improved logging of pull progress.
+ */
+class LoggedPullImageResultCallback extends PullImageResultCallback {
+    private final Logger logger;
+
+    private final Set<String> allLayers = new HashSet<>();
+    private final Set<String> downloadedLayers = new HashSet<>();
+    private final Set<String> pulledLayers = new HashSet<>();
+    private final Map<String, Long> totalSizes = new HashMap<>();
+    private final Map<String, Long> currentSizes = new HashMap<>();
+    private boolean completed;
+    private Instant start;
+
+    LoggedPullImageResultCallback(final Logger logger) {
+        this.logger = logger;
+    }
+
+    @Override
+    public void onStart(final Closeable stream) {
+        super.onStart(stream);
+        start = Instant.now();
+
+        logger.info("Starting to pull image");
+    }
+
+    @Override
+    public void onNext(final PullResponseItem item) {
+        super.onNext(item);
+
+        final String statusLowercase = item.getStatus() != null ? item.getStatus().toLowerCase() : "";
+        final String id = item.getId();
+
+        if (item.getProgressDetail() != null) {
+            allLayers.add(id);
+        }
+
+        if (statusLowercase.equalsIgnoreCase("download complete")) {
+            downloadedLayers.add(id);
+        }
+
+        if (statusLowercase.equalsIgnoreCase("pull complete")) {
+            pulledLayers.add(id);
+        }
+
+        if (item.getProgressDetail() != null) {
+            Long total = item.getProgressDetail().getTotal();
+            Long current = item.getProgressDetail().getCurrent();
+
+            if (total != null && total > totalSizes.getOrDefault(id, 0L)) {
+                totalSizes.put(id, total);
+            }
+            if (current != null && current > currentSizes.getOrDefault(id, 0L)) {
+                currentSizes.put(id, current);
+            }
+        }
+
+        if (statusLowercase.startsWith("pulling from" ) || statusLowercase.contains("complete" )) {
+
+            long totalSize = totalLayerSize();
+            long currentSize = downloadedLayerSize();
+
+            int pendingCount = allLayers.size() - downloadedLayers.size();
+            String friendlyTotalSize;
+            if (pendingCount > 0) {
+                friendlyTotalSize = "? MB";
+            } else {
+                friendlyTotalSize = byteCountToDisplaySize(totalSize);
+            }
+
+            logger.info("Pulling image layers: {} pending, {} downloaded, {} extracted, ({}/{})",
+                format("%2d", pendingCount),
+                format("%2d", downloadedLayers.size()),
+                format("%2d", pulledLayers.size()),
+                byteCountToDisplaySize(currentSize),
+                friendlyTotalSize);
+        }
+
+        if (statusLowercase.contains("complete")) {
+            completed = true;
+        }
+    }
+
+    @Override
+    public void onComplete() {
+        super.onComplete();
+
+        final long downloadedLayerSize = downloadedLayerSize();
+        final long duration = Duration.between(start, Instant.now()).getSeconds();
+
+        if (completed) {
+            logger.info("Pull complete. {} layers, pulled in {}s (downloaded {} at {}/s)",
+                allLayers.size(),
+                duration,
+                byteCountToDisplaySize(downloadedLayerSize),
+                byteCountToDisplaySize(downloadedLayerSize / duration));
+        }
+    }
+
+    private long downloadedLayerSize() {
+        return currentSizes.values().stream().filter(Objects::nonNull).mapToLong(it -> it).sum();
+    }
+
+    private long totalLayerSize() {
+        return totalSizes.values().stream().filter(Objects::nonNull).mapToLong(it -> it).sum();
+    }
+}

core/src/main/java/org/testcontainers/images/RemoteDockerImage.java

@@ -24,6 +24,10 @@
 @ToString
 public class RemoteDockerImage extends LazyFuture<String> {
 
+    /**
+     * @deprecated this field will become private in a later release
+     */
+    @Deprecated
     public static final Set<DockerImageName> AVAILABLE_IMAGE_NAME_CACHE = new HashSet<>();
 
     private DockerImageName imageName;
@@ -42,59 +46,47 @@ protected final String resolve() {
 
         DockerClient dockerClient = DockerClientFactory.instance().client();
         try {
-            int attempts = 0;
-            Exception lastException = null;
-            while (true) {
-                // Does our cache already know the image?
-                if (AVAILABLE_IMAGE_NAME_CACHE.contains(imageName)) {
-                    logger.trace("{} is already in image name cache", imageName);
-                    break;
-                }
-
-                // Update the cache
-                ListImagesCmd listImagesCmd = dockerClient.listImagesCmd();
-
-                if (Boolean.parseBoolean(System.getProperty("useFilter"))) {
-                    listImagesCmd = listImagesCmd.withImageNameFilter(imageName.toString());
-                }
-
-                List<Image> updatedImages = listImagesCmd.exec();
-                updatedImages.stream()
-                    .map(Image::getRepoTags)
-                    .filter(Objects::nonNull)
-                    .flatMap(Stream::of)
-                    .map(DockerImageName::new)
-                    .collect(Collectors.toCollection(() -> AVAILABLE_IMAGE_NAME_CACHE));
-
-                // And now?
-                if (AVAILABLE_IMAGE_NAME_CACHE.contains(imageName)) {
-                    logger.trace("{} is in image name cache following listing of images", imageName);
-                    break;
-                }
-
-                // Log only on first attempt
-                if (attempts == 0) {
-                    logger.info("Pulling docker image: {}. Please be patient; this may take some time but only needs to be done once.", imageName);
-                }
-
-                if (attempts++ >= 3) {
-                    logger.error("Retry limit reached while trying to pull image: {}. Please check output of `docker pull {}`", imageName, imageName);
-                    throw new ContainerFetchException("Retry limit reached while trying to pull image: " + imageName, lastException);
-                }
-
-                // The image is not available locally - pull it
-                try {
-                    final PullImageResultCallback callback = new PullImageResultCallback();
-                    dockerClient
-                        .pullImageCmd(imageName.getUnversionedPart())
-                        .withTag(imageName.getVersionPart())
-                        .exec(callback);
-                    callback.awaitCompletion();
-                    AVAILABLE_IMAGE_NAME_CACHE.add(imageName);
-                    break;
-                } catch (Exception e) {
-                    lastException = e;
-                }
+            // Does our cache already know the image?
+            if (AVAILABLE_IMAGE_NAME_CACHE.contains(imageName)) {
+                logger.trace("{} is already in image name cache", imageName);
+                return imageName.toString();
+            }
+
+            // Update the cache
+            ListImagesCmd listImagesCmd = dockerClient.listImagesCmd();
+
+            if (Boolean.parseBoolean(System.getProperty("useFilter"))) {
+                listImagesCmd = listImagesCmd.withImageNameFilter(imageName.toString());
+            }
+
+            List<Image> updatedImages = listImagesCmd.exec();
+            updatedImages.stream()
+                .map(Image::getRepoTags)
+                .filter(Objects::nonNull)
+                .flatMap(Stream::of)
+                .map(DockerImageName::new)
+                .collect(Collectors.toCollection(() -> AVAILABLE_IMAGE_NAME_CACHE));
+
+            // And now?
+            if (AVAILABLE_IMAGE_NAME_CACHE.contains(imageName)) {
+                logger.trace("{} is in image name cache following listing of images", imageName);
+                return imageName.toString();
+            }
+
+            logger.info("Pulling docker image: {}. Please be patient; this may take some time but only needs to be done once.", imageName);
+
+            // The image is not available locally - pull it
+            try {
+                final PullImageResultCallback callback = new TimeLimitedLoggedPullImageResultCallback(logger);
+                dockerClient
+                    .pullImageCmd(imageName.getUnversionedPart())
+                    .withTag(imageName.getVersionPart())
+                    .exec(callback);
+                callback.awaitCompletion();
+                AVAILABLE_IMAGE_NAME_CACHE.add(imageName);
+            } catch (Exception e) {
+                logger.error("Failed to pull image: {}. Please check output of `docker pull {}`", imageName, imageName);
+                throw new ContainerFetchException("Failed to pull image: " + imageName, e);
             }
 
             return imageName.toString();