Collect all logs of restarted containers (#293)

* Collect all logs of restarted containers * Comments * More comments * Simplify * Avoid break * Test * Changelog
palantir · Jul 11, 2019 · 7a09e98 · 7a09e98
1 parent 8b95d84
commit 7a09e98
Show file tree

Hide file tree

Showing 20 changed files with 175 additions and 163 deletions.
diff --git a/README.md b/README.md
@@ -170,7 +170,7 @@ public class DockerComposeRuleTest {
 }
 ```
 
-This will automatically record logs for all containers in real time to the specified directory. Collection will stop when the containers terminate.
+This will collect logs for all containers. Collection will occur when after the tests are finished executing.
 
 The `LogDirectory` class contains utility methods to generate these paths.  For example, you can write logs directly into the `$CIRCLE_ARTIFACTS` directory on CI (but fall back to `build/dockerLogs` locally) using:
 

diff --git a/changelog/@unreleased/pr-293.v2.yml b/changelog/@unreleased/pr-293.v2.yml
@@ -0,0 +1,5 @@
+type: improvement
+improvement:
+  description: Logs are collected after running tests instead of being streamed while tests are running. This enables logs of restarted containers to be collected.
+  links:
+  - https://github.com/palantir/docker-compose-rule/pull/293
diff --git a/...e-rule-core/src/main/java/com/palantir/docker/compose/configuration/ShutdownStrategy.java b/...e-rule-core/src/main/java/com/palantir/docker/compose/configuration/ShutdownStrategy.java
@@ -60,6 +60,8 @@ static ShutdownStrategy callbackAndThen(Runnable callback, ShutdownStrategy shut
         return new CallbackThenDelegateShutdownStrategy(shutdownStrategy, callback);
     }
 
+    default void stop(DockerCompose dockerCompose) throws IOException, InterruptedException {}
+
     void shutdown(DockerCompose dockerCompose, Docker docker) throws IOException, InterruptedException;
 
 }
diff --git a/...main/java/com/palantir/docker/compose/execution/CallbackThenDelegateShutdownStrategy.java b/...main/java/com/palantir/docker/compose/execution/CallbackThenDelegateShutdownStrategy.java
@@ -34,11 +34,16 @@ public CallbackThenDelegateShutdownStrategy(ShutdownStrategy delegate, Runnable
     }
 
     @Override
-    public void shutdown(DockerCompose dockerCompose, Docker docker) throws IOException, InterruptedException {
+    public void stop(DockerCompose dockerCompose) throws IOException, InterruptedException {
         try {
             callback.run();
         } finally {
-            delegate.shutdown(dockerCompose, docker);
+            delegate.stop(dockerCompose);
         }
     }
+
+    @Override
+    public void shutdown(DockerCompose dockerCompose, Docker docker) throws IOException, InterruptedException {
+        delegate.shutdown(dockerCompose, docker);
+    }
 }
diff --git a/...e-rule-core/src/main/java/com/palantir/docker/compose/execution/DefaultDockerCompose.java b/...e-rule-core/src/main/java/com/palantir/docker/compose/execution/DefaultDockerCompose.java
@@ -15,14 +15,12 @@
  */
 package com.palantir.docker.compose.execution;
 
-import static java.util.concurrent.TimeUnit.MILLISECONDS;
 import static org.apache.commons.lang3.Validate.validState;
 import static org.joda.time.Duration.standardMinutes;
 
 import com.github.zafarkhaja.semver.Version;
 import com.google.common.base.Strings;
 import com.google.common.collect.ImmutableList;
-import com.jayway.awaitility.Awaitility;
 import com.palantir.docker.compose.configuration.DockerComposeFiles;
 import com.palantir.docker.compose.configuration.ProjectName;
 import com.palantir.docker.compose.connection.Container;
@@ -35,7 +33,6 @@
 import java.util.Arrays;
 import java.util.List;
 import java.util.Optional;
-import java.util.concurrent.TimeUnit;
 import org.apache.commons.io.IOUtils;
 import org.joda.time.Duration;
 import org.slf4j.Logger;
@@ -44,7 +41,6 @@
 public class DefaultDockerCompose implements DockerCompose {
 
     public static final Version VERSION_1_7_0 = Version.valueOf("1.7.0");
-    private static final Duration COMMAND_TIMEOUT = standardMinutes(2);
     private static final Duration LOG_WAIT_TIMEOUT = standardMinutes(30);
     private static final Logger log = LoggerFactory.getLogger(DefaultDockerCompose.class);
 
@@ -87,6 +83,12 @@ public void down() throws IOException, InterruptedException {
         command.execute(swallowingDownCommandDoesNotExist(), "down", "--volumes");
     }
 
+    @Override
+    public void stop() throws IOException, InterruptedException {
+        command.execute(Command.throwingOnError(), "stop");
+
+    }
+
     @Override
     public void kill() throws IOException, InterruptedException {
         command.execute(Command.throwingOnError(), "kill");
@@ -187,24 +189,16 @@ public List<String> services() throws IOException, InterruptedException {
         return Arrays.asList(servicesOutput.split("(\r|\n)+"));
     }
 
-    /**
-     * Blocks until all logs collected from the container.
-     * @return Whether the docker container terminated prior to log collection ending
-     */
     @Override
     public boolean writeLogs(String container, OutputStream output) throws IOException {
         try {
-            Awaitility.await()
-                    .pollInterval(50, TimeUnit.MILLISECONDS)
-                    .atMost(LOG_WAIT_TIMEOUT.getMillis(), TimeUnit.MILLISECONDS)
-                    .until(() -> exists(container));
-            Process executedProcess = followLogs(container);
+            Process executedProcess = logs(container);
             IOUtils.copy(executedProcess.getInputStream(), output);
-            executedProcess.waitFor(COMMAND_TIMEOUT.getMillis(), MILLISECONDS);
+            executedProcess.waitFor();
+            return true;
         } catch (InterruptedException e) {
             return false;
         }
-        return true;
     }
 
     private boolean exists(final String containerName) throws IOException, InterruptedException {
@@ -219,11 +213,9 @@ private Optional<String> id(String containerName) throws IOException, Interrupte
         return Optional.of(id);
     }
 
-    private Process followLogs(String container) throws IOException, InterruptedException {
-        if (version().greaterThanOrEqualTo(VERSION_1_7_0)) {
-            return rawExecutable.execute("logs", "--no-color", "--follow", container);
-        }
-
+    private Process logs(String container) throws IOException, InterruptedException {
+        verifyDockerComposeVersionAtLeast(VERSION_1_7_0,
+                "You need at least docker-compose 1.7 to run docker-compose logs");
         return rawExecutable.execute("logs", "--no-color", container);
     }
 

diff --git a/...ule-core/src/main/java/com/palantir/docker/compose/execution/DelegatingDockerCompose.java b/...ule-core/src/main/java/com/palantir/docker/compose/execution/DelegatingDockerCompose.java
@@ -50,6 +50,11 @@ public void down() throws IOException, InterruptedException {
         dockerCompose.down();
     }
 
+    @Override
+    public void stop() throws IOException, InterruptedException {
+        dockerCompose.stop();
+    }
+
     @Override
     public void kill() throws IOException, InterruptedException {
         dockerCompose.kill();

diff --git a/...-compose-rule-core/src/main/java/com/palantir/docker/compose/execution/DockerCompose.java b/...-compose-rule-core/src/main/java/com/palantir/docker/compose/execution/DockerCompose.java
@@ -32,6 +32,7 @@ static Version version() throws IOException, InterruptedException {
     void build() throws IOException, InterruptedException;
     void up() throws IOException, InterruptedException;
     void down() throws IOException, InterruptedException;
+    void stop() throws IOException, InterruptedException;
     void kill() throws IOException, InterruptedException;
     void rm() throws IOException, InterruptedException;
     void up(Container container) throws IOException, InterruptedException;

diff --git a/...le-core/src/main/java/com/palantir/docker/compose/execution/GracefulShutdownStrategy.java b/...le-core/src/main/java/com/palantir/docker/compose/execution/GracefulShutdownStrategy.java
@@ -18,12 +18,15 @@ public class GracefulShutdownStrategy implements ShutdownStrategy {
     private static final Logger log = LoggerFactory.getLogger(GracefulShutdownStrategy.class);
 
     @Override
-    public void shutdown(DockerCompose dockerCompose, Docker docker) throws IOException, InterruptedException {
-        log.debug("Killing docker-compose cluster");
-        dockerCompose.down();
+    public void stop(DockerCompose dockerCompose) throws IOException, InterruptedException {
+        log.debug("Stopping docker-compose cluster");
+        dockerCompose.stop();
         dockerCompose.kill();
-        dockerCompose.rm();
-        docker.pruneNetworks();
     }
 
+    @Override
+    public void shutdown(DockerCompose dockerCompose, Docker docker) throws IOException, InterruptedException {
+        log.debug("Downing docker-compose cluster");
+        dockerCompose.down();
+    }
 }
diff --git a/...le-core/src/main/java/com/palantir/docker/compose/execution/KillDownShutdownStrategy.java b/...le-core/src/main/java/com/palantir/docker/compose/execution/KillDownShutdownStrategy.java
@@ -21,14 +21,14 @@ public class KillDownShutdownStrategy implements ShutdownStrategy {
     private static final Logger log = LoggerFactory.getLogger(KillDownShutdownStrategy.class);
 
     @Override
-    public void shutdown(DockerCompose dockerCompose, Docker docker)
-            throws IOException, InterruptedException {
+    public void stop(DockerCompose dockerCompose) throws IOException, InterruptedException {
         log.debug("Killing docker-compose cluster");
         dockerCompose.kill();
+    }
+
+    @Override
+    public void shutdown(DockerCompose dockerCompose, Docker docker) throws IOException, InterruptedException {
         log.debug("Downing docker-compose cluster");
         dockerCompose.down();
-        log.debug("docker-compose cluster killed");
-        docker.pruneNetworks();
-        log.debug("Networks pruned");
     }
 }
diff --git a/...e-rule-core/src/main/java/com/palantir/docker/compose/execution/SkipShutdownStrategy.java b/...e-rule-core/src/main/java/com/palantir/docker/compose/execution/SkipShutdownStrategy.java
@@ -23,5 +23,4 @@ public void shutdown(DockerCompose dockerCompose, Docker docker) {
                 + "******************************************************************************************");
     }
 
-
 }
diff --git a/...se-rule-core/src/main/java/com/palantir/docker/compose/logging/DoNothingLogCollector.java b/...se-rule-core/src/main/java/com/palantir/docker/compose/logging/DoNothingLogCollector.java
@@ -20,11 +20,5 @@
 public class DoNothingLogCollector implements LogCollector {
 
     @Override
-    public void startCollecting(DockerCompose dockerCompose) {
-    }
-
-    @Override
-    public void stopCollecting() {
-    }
-
+    public void collectLogs(DockerCompose dockerCompose) { }
 }
diff --git a/...compose-rule-core/src/main/java/com/palantir/docker/compose/logging/FileLogCollector.java b/...compose-rule-core/src/main/java/com/palantir/docker/compose/logging/FileLogCollector.java
@@ -54,7 +54,7 @@ public static LogCollector fromPath(String path) {
     }
 
     @Override
-    public synchronized void startCollecting(DockerCompose dockerCompose) throws IOException, InterruptedException {
+    public void collectLogs(DockerCompose dockerCompose) throws IOException, InterruptedException {
         if (executor != null) {
             throw new RuntimeException("Cannot start collecting the same logs twice");
         }
@@ -65,9 +65,15 @@ public synchronized void startCollecting(DockerCompose dockerCompose) throws IOE
         }
         executor = Executors.newFixedThreadPool(serviceNames.size());
         serviceNames.stream().forEachOrdered(service -> this.collectLogs(service, dockerCompose));
+
+        executor.shutdown();
+        if (!executor.awaitTermination(STOP_TIMEOUT_IN_MILLIS, TimeUnit.MILLISECONDS)) {
+            log.warn("docker containers were still running when log collection stopped");
+            executor.shutdownNow();
+        }
     }
 
-    private void collectLogs(String container, DockerCompose dockerCompose)  {
+    private void collectLogs(String container, DockerCompose dockerCompose) {
         executor.submit(() -> {
             File outputFile = new File(logDirectory, container + ".log");
             try {
@@ -85,17 +91,4 @@ private void collectLogs(String container, DockerCompose dockerCompose)  {
             }
         });
     }
-
-    @Override
-    public synchronized void stopCollecting() throws InterruptedException {
-        if (executor == null) {
-            return;
-        }
-        if (!executor.awaitTermination(STOP_TIMEOUT_IN_MILLIS, TimeUnit.MILLISECONDS)) {
-            log.warn("docker containers were still running when log collection stopped");
-            executor.shutdownNow();
-        }
-        executor = null;
-    }
-
 }
diff --git a/docker-compose-rule-core/src/main/java/com/palantir/docker/compose/logging/LogCollector.java b/docker-compose-rule-core/src/main/java/com/palantir/docker/compose/logging/LogCollector.java
@@ -20,8 +20,6 @@
 
 public interface LogCollector {
 
-    void startCollecting(DockerCompose dockerCompose) throws IOException, InterruptedException;
-
-    void stopCollecting() throws InterruptedException;
+    void collectLogs(DockerCompose dockerCompose) throws IOException, InterruptedException;
 
 }
diff --git a/...ava/com/palantir/docker/compose/execution/CallbackThenDelegateShutdownStrategyShould.java b/...ava/com/palantir/docker/compose/execution/CallbackThenDelegateShutdownStrategyShould.java
@@ -22,52 +22,64 @@
 import static org.mockito.Mockito.doThrow;
 import static org.mockito.Mockito.inOrder;
 import static org.mockito.Mockito.mock;
+import static org.mockito.Mockito.verifyNoMoreInteractions;
 
 import com.palantir.docker.compose.configuration.ShutdownStrategy;
-import java.io.IOException;
 import org.junit.Test;
 import org.mockito.InOrder;
 
 public class CallbackThenDelegateShutdownStrategyShould {
 
     @Test
-    public void call_callback_then_call_delegate() throws Exception {
+    public void call_callback_then_call_delegate_on_stop() throws Exception {
         ShutdownStrategy delegate = mock(ShutdownStrategy.class);
         Runnable callback = mock(Runnable.class);
 
         DockerCompose dockerCompose = mock(DockerCompose.class);
-        Docker docker = mock(Docker.class);
 
-        ShutdownStrategy.callbackAndThen(callback, delegate).shutdown(dockerCompose, docker);
+        ShutdownStrategy.callbackAndThen(callback, delegate).stop(dockerCompose);
 
         InOrder inOrder = inOrder(callback, delegate);
         inOrder.verify(callback).run();
-        inOrder.verify(delegate).shutdown(dockerCompose, docker);
-        inOrder.verifyNoMoreInteractions();
+        inOrder.verify(delegate).stop(dockerCompose);
+        verifyNoMoreInteractions(callback, delegate);
     }
 
     @Test
-    public void call_delegate_even_when_callback_throws() throws IOException, InterruptedException {
+    public void call_delegate_even_when_callback_throws_on_stop() throws Exception {
         ShutdownStrategy delegate = mock(ShutdownStrategy.class);
         Runnable callback = mock(Runnable.class);
 
         RuntimeException callbackException = new RuntimeException("exception in callback");
         doThrow(callbackException).when(callback).run();
 
         DockerCompose dockerCompose = mock(DockerCompose.class);
-        Docker docker = mock(Docker.class);
 
         try {
-            ShutdownStrategy.callbackAndThen(callback, delegate).shutdown(dockerCompose, docker);
+            ShutdownStrategy.callbackAndThen(callback, delegate).stop(dockerCompose);
             fail("expected exception");
         } catch (RuntimeException e) {
             assertThat(e, is(callbackException));
         }
 
         InOrder inOrder = inOrder(callback, delegate);
         inOrder.verify(callback).run();
-        inOrder.verify(delegate).shutdown(dockerCompose, docker);
-        inOrder.verifyNoMoreInteractions();
+        inOrder.verify(delegate).stop(dockerCompose);
+        verifyNoMoreInteractions(callback, delegate);
     }
 
+    @Test
+    public void call_down_on_shutdown() throws Exception {
+        ShutdownStrategy delegate = mock(ShutdownStrategy.class);
+        Runnable callback = mock(Runnable.class);
+
+        DockerCompose dockerCompose = mock(DockerCompose.class);
+        Docker docker = mock(Docker.class);
+
+        ShutdownStrategy.callbackAndThen(callback, delegate).shutdown(dockerCompose, docker);
+
+        InOrder inOrder = inOrder(delegate);
+        inOrder.verify(delegate).shutdown(dockerCompose, docker);
+        verifyNoMoreInteractions(callback, delegate);
+    }
 }
-Original file line number
+Diff line change
@@ Expand Up / @@ -170,7 +170,7 @@ public class DockerComposeRuleTest { @@
     }
     ```
-    This will automatically record logs for all containers in real time to the specified directory. Collection will stop when the containers terminate.
+    This will collect logs for all containers. Collection will occur when after the tests are finished executing.
     The `LogDirectory` class contains utility methods to generate these paths.  For example, you can write logs directly into the `$CIRCLE_ARTIFACTS` directory on CI (but fall back to `build/dockerLogs` locally) using:
@@ Expand Down @@
Original file line number	Diff line number	Diff line change
Expand Up		@@ -23,5 +23,4 @@ public void shutdown(DockerCompose dockerCompose, Docker docker) {
		+ "******************************************************************************************");
		}


		}