Skip to content

Commit

Permalink
Improve image pull handling, with better logging and timeout behaviour (
Browse files Browse the repository at this point in the history
  • Loading branch information
rnorth committed Jul 22, 2019
1 parent 908a4ec commit 4df20c2
Show file tree
Hide file tree
Showing 11 changed files with 362 additions and 83 deletions.
15 changes: 11 additions & 4 deletions core/src/main/java/org/testcontainers/DockerClientFactory.java
Expand Up @@ -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;
Expand Down Expand Up @@ -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...");
Expand Down Expand Up @@ -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();
}
}

Expand Down
Expand Up @@ -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;
Expand All @@ -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.*;
Expand Down
Expand Up @@ -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;
Expand Down Expand Up @@ -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;
Expand Down
@@ -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();
}
}
98 changes: 45 additions & 53 deletions core/src/main/java/org/testcontainers/images/RemoteDockerImage.java
Expand Up @@ -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;
Expand All @@ -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();
Expand Down

0 comments on commit 4df20c2

Please sign in to comment.