Skip to content

Commit 4df20c2

Browse files
rnorthrnorth
authored
Improve image pull handling, with better logging and timeout behaviour (testcontainers#1320)
1 parent 908a4ec commit 4df20c2

11 files changed

Lines changed: 362 additions & 83 deletions

File tree

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

Lines changed: 11 additions & 4 deletions
Original file line numberDiff line numberDiff line change
@@ -4,19 +4,25 @@
44
import com.github.dockerjava.api.command.CreateContainerCmd;
55
import com.github.dockerjava.api.exception.InternalServerErrorException;
66
import com.github.dockerjava.api.exception.NotFoundException;
7-
import com.github.dockerjava.api.model.*;
7+
import com.github.dockerjava.api.model.AccessMode;
8+
import com.github.dockerjava.api.model.Bind;
9+
import com.github.dockerjava.api.model.Image;
10+
import com.github.dockerjava.api.model.Info;
11+
import com.github.dockerjava.api.model.Version;
12+
import com.github.dockerjava.api.model.Volume;
813
import com.github.dockerjava.core.command.ExecStartResultCallback;
9-
import com.github.dockerjava.core.command.PullImageResultCallback;
1014
import com.google.common.annotations.VisibleForTesting;
1115
import com.google.common.collect.ImmutableMap;
1216
import lombok.Getter;
17+
import lombok.SneakyThrows;
1318
import lombok.Synchronized;
1419
import lombok.extern.slf4j.Slf4j;
1520
import org.hamcrest.BaseMatcher;
1621
import org.hamcrest.Description;
1722
import org.rnorth.visibleassertions.VisibleAssertions;
1823
import org.testcontainers.dockerclient.DockerClientProviderStrategy;
1924
import org.testcontainers.dockerclient.DockerMachineClientProviderStrategy;
25+
import org.testcontainers.images.TimeLimitedLoggedPullImageResultCallback;
2026
import org.testcontainers.utility.ComparableVersion;
2127
import org.testcontainers.utility.MountableFile;
2228
import org.testcontainers.utility.ResourceReaper;
@@ -125,7 +131,7 @@ public DockerClient client() {
125131
ryukContainerId = ResourceReaper.start(hostIpAddress, client);
126132
log.info("Ryuk started - will monitor and terminate Testcontainers containers on JVM exit");
127133
}
128-
134+
129135
boolean checksEnabled = !TestcontainersConfiguration.getInstance().isDisableChecks();
130136
if (checksEnabled) {
131137
VisibleAssertions.info("Checking the system...");
@@ -215,10 +221,11 @@ private boolean checkMountableFile() {
215221
/**
216222
* Check whether the image is available locally and pull it otherwise
217223
*/
224+
@SneakyThrows
218225
public void checkAndPullImage(DockerClient client, String image) {
219226
List<Image> images = client.listImagesCmd().withImageNameFilter(image).exec();
220227
if (images.isEmpty()) {
221-
client.pullImageCmd(image).exec(new PullImageResultCallback()).awaitSuccess();
228+
client.pullImageCmd(image).exec(new TimeLimitedLoggedPullImageResultCallback(log)).awaitCompletion();
222229
}
223230
}
224231

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

Lines changed: 2 additions & 6 deletions
Original file line numberDiff line numberDiff line change
@@ -19,9 +19,7 @@
1919
import org.testcontainers.containers.output.OutputFrame;
2020
import org.testcontainers.containers.output.Slf4jLogConsumer;
2121
import org.testcontainers.containers.startupcheck.IndefiniteWaitOneShotStartupCheckStrategy;
22-
import org.testcontainers.containers.wait.strategy.Wait;
23-
import org.testcontainers.containers.wait.strategy.WaitAllStrategy;
24-
import org.testcontainers.containers.wait.strategy.WaitStrategy;
22+
import org.testcontainers.containers.wait.strategy.*;
2523
import org.testcontainers.lifecycle.Startable;
2624
import org.testcontainers.utility.*;
2725
import org.yaml.snakeyaml.Yaml;
@@ -32,9 +30,7 @@
3230
import java.io.File;
3331
import java.io.FileInputStream;
3432
import java.io.IOException;
35-
import java.nio.file.Files;
36-
import java.nio.file.Path;
37-
import java.nio.file.Paths;
33+
import java.nio.file.*;
3834
import java.time.Duration;
3935
import java.util.AbstractMap.SimpleEntry;
4036
import java.util.*;

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

Lines changed: 40 additions & 6 deletions
Original file line numberDiff line numberDiff line change
@@ -3,9 +3,22 @@
33
import com.github.dockerjava.api.DockerClient;
44
import com.github.dockerjava.api.command.CreateContainerCmd;
55
import com.github.dockerjava.api.command.InspectContainerResponse;
6-
import com.github.dockerjava.api.model.*;
6+
import com.github.dockerjava.api.model.Bind;
7+
import com.github.dockerjava.api.model.ContainerNetwork;
8+
import com.github.dockerjava.api.model.ExposedPort;
9+
import com.github.dockerjava.api.model.HostConfig;
10+
import com.github.dockerjava.api.model.Info;
11+
import com.github.dockerjava.api.model.Link;
12+
import com.github.dockerjava.api.model.PortBinding;
13+
import com.github.dockerjava.api.model.Volume;
14+
import com.github.dockerjava.api.model.VolumesFrom;
715
import com.google.common.base.Strings;
8-
import lombok.*;
16+
import lombok.AccessLevel;
17+
import lombok.Data;
18+
import lombok.EqualsAndHashCode;
19+
import lombok.NonNull;
20+
import lombok.Setter;
21+
import lombok.SneakyThrows;
922
import org.apache.commons.compress.archivers.tar.TarArchiveInputStream;
1023
import org.apache.commons.compress.archivers.tar.TarArchiveOutputStream;
1124
import org.apache.commons.compress.utils.IOUtils;
@@ -33,13 +46,34 @@
3346
import org.testcontainers.lifecycle.Startable;
3447
import org.testcontainers.lifecycle.TestDescription;
3548
import org.testcontainers.lifecycle.TestLifecycleAware;
36-
import org.testcontainers.utility.*;
37-
38-
import java.io.*;
49+
import org.testcontainers.utility.Base58;
50+
import org.testcontainers.utility.DockerLoggerFactory;
51+
import org.testcontainers.utility.DockerMachineClient;
52+
import org.testcontainers.utility.MountableFile;
53+
import org.testcontainers.utility.PathUtils;
54+
import org.testcontainers.utility.ResourceReaper;
55+
import org.testcontainers.utility.TestcontainersConfiguration;
56+
import org.testcontainers.utility.ThrowingFunction;
57+
58+
import java.io.ByteArrayInputStream;
59+
import java.io.ByteArrayOutputStream;
60+
import java.io.File;
61+
import java.io.FileOutputStream;
62+
import java.io.IOException;
63+
import java.io.InputStream;
3964
import java.nio.charset.Charset;
4065
import java.nio.file.Path;
4166
import java.time.Duration;
42-
import java.util.*;
67+
import java.util.ArrayList;
68+
import java.util.Arrays;
69+
import java.util.Collections;
70+
import java.util.HashMap;
71+
import java.util.HashSet;
72+
import java.util.LinkedHashSet;
73+
import java.util.List;
74+
import java.util.Map;
75+
import java.util.Optional;
76+
import java.util.Set;
4377
import java.util.concurrent.Future;
4478
import java.util.concurrent.TimeUnit;
4579
import java.util.concurrent.atomic.AtomicInteger;

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

Lines changed: 121 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,121 @@
1+
package org.testcontainers.images;
2+
3+
import com.github.dockerjava.api.model.PullResponseItem;
4+
import com.github.dockerjava.core.command.PullImageResultCallback;
5+
import org.slf4j.Logger;
6+
7+
import java.io.Closeable;
8+
import java.time.Duration;
9+
import java.time.Instant;
10+
import java.util.*;
11+
12+
import static java.lang.String.format;
13+
import static org.apache.commons.io.FileUtils.byteCountToDisplaySize;
14+
15+
/**
16+
* {@link PullImageResultCallback} with improved logging of pull progress.
17+
*/
18+
class LoggedPullImageResultCallback extends PullImageResultCallback {
19+
private final Logger logger;
20+
21+
private final Set<String> allLayers = new HashSet<>();
22+
private final Set<String> downloadedLayers = new HashSet<>();
23+
private final Set<String> pulledLayers = new HashSet<>();
24+
private final Map<String, Long> totalSizes = new HashMap<>();
25+
private final Map<String, Long> currentSizes = new HashMap<>();
26+
private boolean completed;
27+
private Instant start;
28+
29+
LoggedPullImageResultCallback(final Logger logger) {
30+
this.logger = logger;
31+
}
32+
33+
@Override
34+
public void onStart(final Closeable stream) {
35+
super.onStart(stream);
36+
start = Instant.now();
37+
38+
logger.info("Starting to pull image");
39+
}
40+
41+
@Override
42+
public void onNext(final PullResponseItem item) {
43+
super.onNext(item);
44+
45+
final String statusLowercase = item.getStatus() != null ? item.getStatus().toLowerCase() : "";
46+
final String id = item.getId();
47+
48+
if (item.getProgressDetail() != null) {
49+
allLayers.add(id);
50+
}
51+
52+
if (statusLowercase.equalsIgnoreCase("download complete")) {
53+
downloadedLayers.add(id);
54+
}
55+
56+
if (statusLowercase.equalsIgnoreCase("pull complete")) {
57+
pulledLayers.add(id);
58+
}
59+
60+
if (item.getProgressDetail() != null) {
61+
Long total = item.getProgressDetail().getTotal();
62+
Long current = item.getProgressDetail().getCurrent();
63+
64+
if (total != null && total > totalSizes.getOrDefault(id, 0L)) {
65+
totalSizes.put(id, total);
66+
}
67+
if (current != null && current > currentSizes.getOrDefault(id, 0L)) {
68+
currentSizes.put(id, current);
69+
}
70+
}
71+
72+
if (statusLowercase.startsWith("pulling from" ) || statusLowercase.contains("complete" )) {
73+
74+
long totalSize = totalLayerSize();
75+
long currentSize = downloadedLayerSize();
76+
77+
int pendingCount = allLayers.size() - downloadedLayers.size();
78+
String friendlyTotalSize;
79+
if (pendingCount > 0) {
80+
friendlyTotalSize = "? MB";
81+
} else {
82+
friendlyTotalSize = byteCountToDisplaySize(totalSize);
83+
}
84+
85+
logger.info("Pulling image layers: {} pending, {} downloaded, {} extracted, ({}/{})",
86+
format("%2d", pendingCount),
87+
format("%2d", downloadedLayers.size()),
88+
format("%2d", pulledLayers.size()),
89+
byteCountToDisplaySize(currentSize),
90+
friendlyTotalSize);
91+
}
92+
93+
if (statusLowercase.contains("complete")) {
94+
completed = true;
95+
}
96+
}
97+
98+
@Override
99+
public void onComplete() {
100+
super.onComplete();
101+
102+
final long downloadedLayerSize = downloadedLayerSize();
103+
final long duration = Duration.between(start, Instant.now()).getSeconds();
104+
105+
if (completed) {
106+
logger.info("Pull complete. {} layers, pulled in {}s (downloaded {} at {}/s)",
107+
allLayers.size(),
108+
duration,
109+
byteCountToDisplaySize(downloadedLayerSize),
110+
byteCountToDisplaySize(downloadedLayerSize / duration));
111+
}
112+
}
113+
114+
private long downloadedLayerSize() {
115+
return currentSizes.values().stream().filter(Objects::nonNull).mapToLong(it -> it).sum();
116+
}
117+
118+
private long totalLayerSize() {
119+
return totalSizes.values().stream().filter(Objects::nonNull).mapToLong(it -> it).sum();
120+
}
121+
}

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

Lines changed: 45 additions & 53 deletions
Original file line numberDiff line numberDiff line change
@@ -24,6 +24,10 @@
2424
@ToString
2525
public class RemoteDockerImage extends LazyFuture<String> {
2626

27+
/**
28+
* @deprecated this field will become private in a later release
29+
*/
30+
@Deprecated
2731
public static final Set<DockerImageName> AVAILABLE_IMAGE_NAME_CACHE = new HashSet<>();
2832

2933
private DockerImageName imageName;
@@ -42,59 +46,47 @@ protected final String resolve() {
4246

4347
DockerClient dockerClient = DockerClientFactory.instance().client();
4448
try {
45-
int attempts = 0;
46-
Exception lastException = null;
47-
while (true) {
48-
// Does our cache already know the image?
49-
if (AVAILABLE_IMAGE_NAME_CACHE.contains(imageName)) {
50-
logger.trace("{} is already in image name cache", imageName);
51-
break;
52-
}
53-
54-
// Update the cache
55-
ListImagesCmd listImagesCmd = dockerClient.listImagesCmd();
56-
57-
if (Boolean.parseBoolean(System.getProperty("useFilter"))) {
58-
listImagesCmd = listImagesCmd.withImageNameFilter(imageName.toString());
59-
}
60-
61-
List<Image> updatedImages = listImagesCmd.exec();
62-
updatedImages.stream()
63-
.map(Image::getRepoTags)
64-
.filter(Objects::nonNull)
65-
.flatMap(Stream::of)
66-
.map(DockerImageName::new)
67-
.collect(Collectors.toCollection(() -> AVAILABLE_IMAGE_NAME_CACHE));
68-
69-
// And now?
70-
if (AVAILABLE_IMAGE_NAME_CACHE.contains(imageName)) {
71-
logger.trace("{} is in image name cache following listing of images", imageName);
72-
break;
73-
}
74-
75-
// Log only on first attempt
76-
if (attempts == 0) {
77-
logger.info("Pulling docker image: {}. Please be patient; this may take some time but only needs to be done once.", imageName);
78-
}
79-
80-
if (attempts++ >= 3) {
81-
logger.error("Retry limit reached while trying to pull image: {}. Please check output of `docker pull {}`", imageName, imageName);
82-
throw new ContainerFetchException("Retry limit reached while trying to pull image: " + imageName, lastException);
83-
}
84-
85-
// The image is not available locally - pull it
86-
try {
87-
final PullImageResultCallback callback = new PullImageResultCallback();
88-
dockerClient
89-
.pullImageCmd(imageName.getUnversionedPart())
90-
.withTag(imageName.getVersionPart())
91-
.exec(callback);
92-
callback.awaitCompletion();
93-
AVAILABLE_IMAGE_NAME_CACHE.add(imageName);
94-
break;
95-
} catch (Exception e) {
96-
lastException = e;
97-
}
49+
// Does our cache already know the image?
50+
if (AVAILABLE_IMAGE_NAME_CACHE.contains(imageName)) {
51+
logger.trace("{} is already in image name cache", imageName);
52+
return imageName.toString();
53+
}
54+
55+
// Update the cache
56+
ListImagesCmd listImagesCmd = dockerClient.listImagesCmd();
57+
58+
if (Boolean.parseBoolean(System.getProperty("useFilter"))) {
59+
listImagesCmd = listImagesCmd.withImageNameFilter(imageName.toString());
60+
}
61+
62+
List<Image> updatedImages = listImagesCmd.exec();
63+
updatedImages.stream()
64+
.map(Image::getRepoTags)
65+
.filter(Objects::nonNull)
66+
.flatMap(Stream::of)
67+
.map(DockerImageName::new)
68+
.collect(Collectors.toCollection(() -> AVAILABLE_IMAGE_NAME_CACHE));
69+
70+
// And now?
71+
if (AVAILABLE_IMAGE_NAME_CACHE.contains(imageName)) {
72+
logger.trace("{} is in image name cache following listing of images", imageName);
73+
return imageName.toString();
74+
}
75+
76+
logger.info("Pulling docker image: {}. Please be patient; this may take some time but only needs to be done once.", imageName);
77+
78+
// The image is not available locally - pull it
79+
try {
80+
final PullImageResultCallback callback = new TimeLimitedLoggedPullImageResultCallback(logger);
81+
dockerClient
82+
.pullImageCmd(imageName.getUnversionedPart())
83+
.withTag(imageName.getVersionPart())
84+
.exec(callback);
85+
callback.awaitCompletion();
86+
AVAILABLE_IMAGE_NAME_CACHE.add(imageName);
87+
} catch (Exception e) {
88+
logger.error("Failed to pull image: {}. Please check output of `docker pull {}`", imageName, imageName);
89+
throw new ContainerFetchException("Failed to pull image: " + imageName, e);
9890
}
9991

10092
return imageName.toString();

0 commit comments

Comments
 (0)