From d0a74b032b9a663eff49f5951be787bd0b49bb1b Mon Sep 17 00:00:00 2001 From: Oliver Stacey Date: Fri, 1 Apr 2016 12:23:53 -0700 Subject: [PATCH 1/3] When starting a container fails, don't wait until the full timeout; bail out immediately. --- .../containers/GenericContainer.java | 26 +++++++++++--- .../junit/GenericContainerRuleTest.java | 34 +++++++++++++++++++ 2 files changed, 56 insertions(+), 4 deletions(-) diff --git a/core/src/main/java/org/testcontainers/containers/GenericContainer.java b/core/src/main/java/org/testcontainers/containers/GenericContainer.java index 08e21581ecb..b253e2e787b 100644 --- a/core/src/main/java/org/testcontainers/containers/GenericContainer.java +++ b/core/src/main/java/org/testcontainers/containers/GenericContainer.java @@ -2,6 +2,7 @@ import com.github.dockerjava.api.DockerClient; import com.github.dockerjava.api.DockerException; +import com.github.dockerjava.api.NotFoundException; import com.github.dockerjava.api.async.ResultCallback; import com.github.dockerjava.api.command.CreateContainerCmd; import com.github.dockerjava.api.command.InspectContainerResponse; @@ -52,6 +53,8 @@ public class GenericContainer extends FailureDetectingExternalResource implements LinkableContainer { public static final int STARTUP_RETRY_COUNT = 3; + public static final int CONTAINER_RUNNING_TIMEOUT_SEC = 30; + /* * Default settings */ @@ -163,21 +166,36 @@ private void tryStart(Profiler profiler) { containerIsStarting(containerInfo); // Wait until the container is running (may not be fully started) - profiler.start("Wait until container state=running"); - Unreliables.retryUntilTrue(30, TimeUnit.SECONDS, () -> { + profiler.start("Wait until container state=running, or there's evidence it failed to start."); + final Boolean[] startedOK = {null}; + Unreliables.retryUntilTrue(CONTAINER_RUNNING_TIMEOUT_SEC, TimeUnit.SECONDS, () -> { //noinspection CodeBlock2Expr return DOCKER_CLIENT_RATE_LIMITER.getWhenReady(() -> { InspectContainerResponse inspectionResponse = dockerClient.inspectContainerCmd(containerId).exec(); - return inspectionResponse.getState().isRunning(); + if (inspectionResponse.getState().isRunning()) { + startedOK[0] = true; + return true; + } else if (inspectionResponse.getState().getFinishedAt() != null) { + // container started, but is now not running. That means it started but has since stopped; + // likely due to misconfiguration. + startedOK[0] = false; + return true; + } + return false; }); }); + if (!startedOK[0]) { + // Bail out, don't wait for the port to start listening. + // (Exception thrown here will be caught below and wrapped) + throw new NotFoundException("Container has already stopped."); + } + profiler.start("Wait until container started"); waitUntilContainerStarted(); logger().info("Container {} started", dockerImageName); containerIsStarted(containerInfo); - } catch (Exception e) { logger().error("Could not start container", e); diff --git a/core/src/test/java/org/testcontainers/junit/GenericContainerRuleTest.java b/core/src/test/java/org/testcontainers/junit/GenericContainerRuleTest.java index 86feb08480a..f85b2dce2c9 100644 --- a/core/src/test/java/org/testcontainers/junit/GenericContainerRuleTest.java +++ b/core/src/test/java/org/testcontainers/junit/GenericContainerRuleTest.java @@ -11,6 +11,7 @@ import org.junit.Test; import org.redisson.Config; import org.redisson.Redisson; +import org.rnorth.ducttape.RetryCountExceededException; import org.rnorth.ducttape.unreliables.Unreliables; import org.testcontainers.containers.GenericContainer; @@ -203,4 +204,37 @@ protected static void writeStringToFile(File contentFolder, String filename, Str printStream.println(string); printStream.close(); } + + @Test + public void failFastWhenContainerHaltsImmediately() throws Exception { + + long startingTimeMs = System.currentTimeMillis(); + final GenericContainer failsImmediately = new GenericContainer("alpine:3.2") + .withCommand("/bin/sh", "-c", "return false"); + + try { + assertThrows( + "When we start a container that halts immediately, an exception is thrown", + RetryCountExceededException.class, + () -> { + failsImmediately.start(); + return null; + }); + + // Check how long it took, to verify that we ARE bailing out early. + // Want to strike a balance here; too short and this test will fail intermittently + // on slow systems and/or due to GC variation, too long and we won't properly test + // what we're intending to test. + int allowedSecondsToFailure = + GenericContainer.STARTUP_RETRY_COUNT * GenericContainer.CONTAINER_RUNNING_TIMEOUT_SEC / 2; + long completedTimeMs = System.currentTimeMillis(); + assertTrue("container should not take long to start up", + completedTimeMs - startingTimeMs < 1000L * allowedSecondsToFailure); + } finally { + failsImmediately.stop(); + } + + + } + } From 08414c548374c1ac8572bafb26be5700d417d8ed Mon Sep 17 00:00:00 2001 From: Oliver Stacey Date: Fri, 1 Apr 2016 19:37:10 -0700 Subject: [PATCH 2/3] Move status-interpeting code into its own class, with its own unit tests. --- core/pom.xml | 12 +++ .../containers/GenericContainer.java | 29 +++++-- .../testcontainers/utility/DockerStatus.java | 78 +++++++++++++++++ .../utility/DockerStatusTest.java | 84 +++++++++++++++++++ 4 files changed, 197 insertions(+), 6 deletions(-) create mode 100644 core/src/main/java/org/testcontainers/utility/DockerStatus.java create mode 100644 core/src/test/java/org/testcontainers/utility/DockerStatusTest.java diff --git a/core/pom.xml b/core/pom.xml index e96240f453d..f3b70ae8972 100644 --- a/core/pom.xml +++ b/core/pom.xml @@ -54,6 +54,18 @@ 3.0.2 test + + org.mockito + mockito-core + 1.10.19 + test + + + org.hamcrest + hamcrest-core + + + diff --git a/core/src/main/java/org/testcontainers/containers/GenericContainer.java b/core/src/main/java/org/testcontainers/containers/GenericContainer.java index b253e2e787b..4b2fae0e191 100644 --- a/core/src/main/java/org/testcontainers/containers/GenericContainer.java +++ b/core/src/main/java/org/testcontainers/containers/GenericContainer.java @@ -26,7 +26,11 @@ import org.testcontainers.containers.output.OutputFrame; import org.testcontainers.containers.traits.LinkableContainer; import org.testcontainers.images.RemoteDockerImage; -import org.testcontainers.utility.*; +import org.testcontainers.utility.ContainerReaper; +import org.testcontainers.utility.DockerLoggerFactory; +import org.testcontainers.utility.DockerMachineClient; +import org.testcontainers.utility.DockerStatus; +import org.testcontainers.utility.PathOperations; import java.io.File; import java.io.IOException; @@ -34,6 +38,7 @@ import java.net.URL; import java.nio.file.Path; import java.time.Duration; +import java.time.Instant; import java.util.*; import java.util.concurrent.Future; import java.util.concurrent.TimeUnit; @@ -55,6 +60,7 @@ public class GenericContainer extends FailureDetectingExternalResource implement public static final int STARTUP_RETRY_COUNT = 3; public static final int CONTAINER_RUNNING_TIMEOUT_SEC = 30; + /* * Default settings */ @@ -82,6 +88,13 @@ public class GenericContainer extends FailureDetectingExternalResource implement @NonNull private Duration startupTimeout = Duration.ofSeconds(60); + /** + * If a container has been running for less than this time, don't consider it + * successful yet - try again. + */ + @NonNull + private Duration minimumDurationToConsiderRunning = Duration.ofMillis(100); + /* * Unique instance of DockerClient for use by this container object. */ @@ -140,7 +153,7 @@ public void start() { } } - private void tryStart(Profiler profiler) { + private void tryStart(Profiler profiler) { try { String dockerImageName = image.get(); logger().debug("Starting container: {}", dockerImageName); @@ -171,13 +184,17 @@ private void tryStart(Profiler profiler) { Unreliables.retryUntilTrue(CONTAINER_RUNNING_TIMEOUT_SEC, TimeUnit.SECONDS, () -> { //noinspection CodeBlock2Expr return DOCKER_CLIENT_RATE_LIMITER.getWhenReady(() -> { + // record "now" before fetching status; otherwise the time to fetch the status + // will contribute to how long the container has been running. + Instant now = Instant.now(); InspectContainerResponse inspectionResponse = dockerClient.inspectContainerCmd(containerId).exec(); - if (inspectionResponse.getState().isRunning()) { + + if (DockerStatus.isContainerRunning(inspectionResponse.getState(), + minimumDurationToConsiderRunning, + now)) { startedOK[0] = true; return true; - } else if (inspectionResponse.getState().getFinishedAt() != null) { - // container started, but is now not running. That means it started but has since stopped; - // likely due to misconfiguration. + } else if (DockerStatus.isContainerStopped(inspectionResponse.getState())) { startedOK[0] = false; return true; } diff --git a/core/src/main/java/org/testcontainers/utility/DockerStatus.java b/core/src/main/java/org/testcontainers/utility/DockerStatus.java new file mode 100644 index 00000000000..7445e5a3b81 --- /dev/null +++ b/core/src/main/java/org/testcontainers/utility/DockerStatus.java @@ -0,0 +1,78 @@ +package org.testcontainers.utility; + +import com.github.dockerjava.api.command.InspectContainerResponse; + +import java.time.Duration; +import java.time.Instant; +import java.time.format.DateTimeFormatter; + +/** + * Utility functions for dealing with docker status based on the information available to us, and trying to be + * defensive. + *

+ *

In docker-java version 2.2.0, which we're using, only these + * fields are available in the container state returned from Docker Inspect: "isRunning", "isPaused", "startedAt", and + * "finishedAt". There are states that can occur (including "created", "OOMkilled" and "dead") that aren't directly + * shown through this result. + *

+ *

Docker also doesn't seem to use null values for timestamps; see DOCKER_TIMESTAMP_ZERO, below. + */ +public class DockerStatus { + + /** + * When the docker client has an "empty" timestamp, it returns this special value, rather than + * null or an empty string. + */ + static final String DOCKER_TIMESTAMP_ZERO = "0001-01-01T00:00:00Z"; + + /** + * Based on this status, is this container running, and has it been doing so for the specified amount of time? + * + * @param state the state provided by InspectContainer + * @param minimumDuration minimum duration to consider this as "solidly" running. + * @param now the time to consider as the current time + * @return true if we can conclude that the container is running, false otherwise + */ + public static boolean isContainerRunning(InspectContainerResponse.ContainerState state, Duration minimumDuration, + Instant now) { + if (state.isRunning()) { + Instant startedAt = DateTimeFormatter.ISO_INSTANT.parse( + state.getStartedAt(), Instant::from); + + if (startedAt.isBefore(now.minus(minimumDuration))) { + return true; + } + } + return false; + } + + /** + * Based on this status, has the container halted? + * + * @param state the state provided by InspectContainer + * @return true if we can conclude that the container has started but is now stopped, false otherwise. + */ + public static boolean isContainerStopped(InspectContainerResponse.ContainerState state) { + + // get some preconditions out of the way + if (state.isRunning() || state.isPaused()) { + return false; + } + + // if the finished timestamp is non-empty, that means the container started and finished. + if (!isDockerTimestampEmpty(state.getStartedAt()) && !isDockerTimestampEmpty(state.getFinishedAt())) { + return true; + } + return false; + } + + public static boolean isDockerTimestampEmpty(String dockerTimestamp) { + // This is a defensive approach. Current versions of Docker use the DOCKER_TIMESTAMP_ZERO value, but + // that could change. + return dockerTimestamp == null + || dockerTimestamp.isEmpty() + || dockerTimestamp.equals(DOCKER_TIMESTAMP_ZERO) + || DateTimeFormatter.ISO_INSTANT.parse(dockerTimestamp, Instant::from).getEpochSecond() < 0L; + } + +} diff --git a/core/src/test/java/org/testcontainers/utility/DockerStatusTest.java b/core/src/test/java/org/testcontainers/utility/DockerStatusTest.java new file mode 100644 index 00000000000..9122684aed4 --- /dev/null +++ b/core/src/test/java/org/testcontainers/utility/DockerStatusTest.java @@ -0,0 +1,84 @@ +package org.testcontainers.utility; + +import static org.junit.Assert.assertFalse; +import static org.junit.Assert.assertTrue; +import static org.mockito.Mockito.when; + +import com.github.dockerjava.api.command.InspectContainerResponse; +import org.junit.Test; +import org.mockito.Mockito; + +import java.time.Duration; +import java.time.Instant; +import java.time.format.DateTimeFormatter; + +/** + * + */ +public class DockerStatusTest { + + private static Instant now = Instant.now(); + + private static InspectContainerResponse.ContainerState running = + buildState(true, false, buildTimestamp(now.minusMillis(30)), DockerStatus.DOCKER_TIMESTAMP_ZERO); + + private static InspectContainerResponse.ContainerState runningVariant = + buildState(true, false, buildTimestamp(now.minusMillis(30)), ""); + + private static InspectContainerResponse.ContainerState shortRunning = + buildState(true, false, buildTimestamp(now.minusMillis(10)), DockerStatus.DOCKER_TIMESTAMP_ZERO); + + private static InspectContainerResponse.ContainerState created = + buildState(false, false, DockerStatus.DOCKER_TIMESTAMP_ZERO, DockerStatus.DOCKER_TIMESTAMP_ZERO); + + // a container in the "created" state is not running, and has both startedAt and finishedAt empty. + private static InspectContainerResponse.ContainerState createdVariant = + buildState(false, false, null, null); + + private static InspectContainerResponse.ContainerState exited = + buildState(false, false, buildTimestamp(now.minusMillis(100)), buildTimestamp(now.minusMillis(90))); + + private static InspectContainerResponse.ContainerState paused = + buildState(false, true, buildTimestamp(now.minusMillis(100)), DockerStatus.DOCKER_TIMESTAMP_ZERO); + + private static Duration minimumDuration = Duration.ofMillis(20); + + @Test + public void testRunning() throws Exception { + assertTrue(DockerStatus.isContainerRunning(running, minimumDuration, now)); + assertTrue(DockerStatus.isContainerRunning(runningVariant, minimumDuration, now)); + assertFalse(DockerStatus.isContainerRunning(shortRunning, minimumDuration, now)); + assertFalse(DockerStatus.isContainerRunning(created, minimumDuration, now)); + assertFalse(DockerStatus.isContainerRunning(createdVariant, minimumDuration, now)); + assertFalse(DockerStatus.isContainerRunning(exited, minimumDuration, now)); + assertFalse(DockerStatus.isContainerRunning(paused, minimumDuration, now)); + } + + @Test + public void testStopped() throws Exception { + assertFalse(DockerStatus.isContainerStopped(running)); + assertFalse(DockerStatus.isContainerStopped(runningVariant)); + assertFalse(DockerStatus.isContainerStopped(shortRunning)); + assertFalse(DockerStatus.isContainerStopped(created)); + assertFalse(DockerStatus.isContainerStopped(createdVariant)); + assertTrue(DockerStatus.isContainerStopped(exited)); + assertFalse(DockerStatus.isContainerStopped(paused)); + } + + private static String buildTimestamp(Instant instant) { + return DateTimeFormatter.ISO_INSTANT.format(instant); + } + + // ContainerState is a non-static inner class, with private member variables, in a different package. + // It's simpler to mock it that to try to create one. + private static InspectContainerResponse.ContainerState buildState(boolean running, boolean paused, + String startedAt, String finishedAt) { + + InspectContainerResponse.ContainerState state = Mockito.mock(InspectContainerResponse.ContainerState.class); + when(state.isRunning()).thenReturn(running); + when(state.isPaused()).thenReturn(paused); + when(state.getStartedAt()).thenReturn(startedAt); + when(state.getFinishedAt()).thenReturn(finishedAt); + return state; + } +} From c681a6f59d224b86d304bbc2beb64d0d92ca1ef0 Mon Sep 17 00:00:00 2001 From: Oliver Stacey Date: Thu, 7 Apr 2016 14:24:12 -0700 Subject: [PATCH 3/3] Introduced "minimumRunningDuration" on GenericContainer, to catch the case where a container starts but then quickly stops. --- .../containers/GenericContainer.java | 18 ++++++++++----- .../testcontainers/utility/DockerStatus.java | 14 +++++++---- .../junit/GenericContainerRuleTest.java | 6 ++--- .../testcontainers/junit/TestBadCleanup.java | 23 ------------------- 4 files changed, 24 insertions(+), 37 deletions(-) delete mode 100644 core/src/test/java/org/testcontainers/junit/TestBadCleanup.java diff --git a/core/src/main/java/org/testcontainers/containers/GenericContainer.java b/core/src/main/java/org/testcontainers/containers/GenericContainer.java index 4b2fae0e191..63adfc2d9d4 100644 --- a/core/src/main/java/org/testcontainers/containers/GenericContainer.java +++ b/core/src/main/java/org/testcontainers/containers/GenericContainer.java @@ -88,12 +88,8 @@ public class GenericContainer extends FailureDetectingExternalResource implement @NonNull private Duration startupTimeout = Duration.ofSeconds(60); - /** - * If a container has been running for less than this time, don't consider it - * successful yet - try again. - */ @NonNull - private Duration minimumDurationToConsiderRunning = Duration.ofMillis(100); + private Duration minimumRunningDuration = null; /* * Unique instance of DockerClient for use by this container object. @@ -190,7 +186,7 @@ private void tryStart(Profiler profiler) { InspectContainerResponse inspectionResponse = dockerClient.inspectContainerCmd(containerId).exec(); if (DockerStatus.isContainerRunning(inspectionResponse.getState(), - minimumDurationToConsiderRunning, + minimumRunningDuration, now)) { startedOK[0] = true; return true; @@ -526,6 +522,16 @@ public String getContainerIpAddress() { return DockerClientFactory.instance().dockerHostIpAddress(); } + /** + * Only consider a container to have successfully started if it has been running for this duration. The default + * value is null; if that's the value, ignore this check. + */ + + public GenericContainer withMinimumRunningDuration(Duration minimumRunningDuration) { + this.setMinimumRunningDuration(minimumRunningDuration); + return this; + } + /** * Get the IP address that this container may be reached on (may not be the local machine). * diff --git a/core/src/main/java/org/testcontainers/utility/DockerStatus.java b/core/src/main/java/org/testcontainers/utility/DockerStatus.java index 7445e5a3b81..b5d57a61cb5 100644 --- a/core/src/main/java/org/testcontainers/utility/DockerStatus.java +++ b/core/src/main/java/org/testcontainers/utility/DockerStatus.java @@ -28,18 +28,22 @@ public class DockerStatus { /** * Based on this status, is this container running, and has it been doing so for the specified amount of time? * - * @param state the state provided by InspectContainer - * @param minimumDuration minimum duration to consider this as "solidly" running. - * @param now the time to consider as the current time + * @param state the state provided by InspectContainer + * @param minimumRunningDuration minimum duration to consider this as "solidly" running, or null + * @param now the time to consider as the current time * @return true if we can conclude that the container is running, false otherwise */ - public static boolean isContainerRunning(InspectContainerResponse.ContainerState state, Duration minimumDuration, + public static boolean isContainerRunning(InspectContainerResponse.ContainerState state, + Duration minimumRunningDuration, Instant now) { if (state.isRunning()) { + if (minimumRunningDuration == null) { + return true; + } Instant startedAt = DateTimeFormatter.ISO_INSTANT.parse( state.getStartedAt(), Instant::from); - if (startedAt.isBefore(now.minus(minimumDuration))) { + if (startedAt.isBefore(now.minus(minimumRunningDuration))) { return true; } } diff --git a/core/src/test/java/org/testcontainers/junit/GenericContainerRuleTest.java b/core/src/test/java/org/testcontainers/junit/GenericContainerRuleTest.java index f85b2dce2c9..5b895eaaeb6 100644 --- a/core/src/test/java/org/testcontainers/junit/GenericContainerRuleTest.java +++ b/core/src/test/java/org/testcontainers/junit/GenericContainerRuleTest.java @@ -17,6 +17,7 @@ import java.io.*; import java.net.Socket; +import java.time.Duration; import java.util.Arrays; import java.util.List; import java.util.concurrent.TimeUnit; @@ -210,7 +211,8 @@ public void failFastWhenContainerHaltsImmediately() throws Exception { long startingTimeMs = System.currentTimeMillis(); final GenericContainer failsImmediately = new GenericContainer("alpine:3.2") - .withCommand("/bin/sh", "-c", "return false"); + .withCommand("/bin/sh", "-c", "return false") + .withMinimumRunningDuration(Duration.ofMillis(100)); try { assertThrows( @@ -233,8 +235,6 @@ public void failFastWhenContainerHaltsImmediately() throws Exception { } finally { failsImmediately.stop(); } - - } } diff --git a/core/src/test/java/org/testcontainers/junit/TestBadCleanup.java b/core/src/test/java/org/testcontainers/junit/TestBadCleanup.java deleted file mode 100644 index c259138a5e3..00000000000 --- a/core/src/test/java/org/testcontainers/junit/TestBadCleanup.java +++ /dev/null @@ -1,23 +0,0 @@ -package org.testcontainers.junit; - -import org.junit.Ignore; -import org.junit.Rule; -import org.junit.Test; -import org.testcontainers.containers.GenericContainer; - -/** - * Failing test for manual testing of container cleanup. - */ -public class TestBadCleanup { - @Rule - public GenericContainer failingContainer = - new GenericContainer("alpine:3.2") - .withCommand("/bin/sh","-c","false") - .withExposedPorts(8080); - - @Test @Ignore - public void testBadCleanup() throws Exception { - // no op - // this test will pass, but a "docker ps -a" afterward will see two leftover containers. - } -} \ No newline at end of file