Provide more verbose docker compose logging

Update `up` and `start` operations so that real-time logging is
provided. Prior to this commit, lengthy pull operations were not
logged which gave the impression that the application had
crashed.

Closes gh-34994
pull/35031/head
Phillip Webb 2 years ago
parent 7728488541
commit 3657f73b9a

@ -24,6 +24,8 @@ import java.util.Map;
import java.util.function.Function;
import java.util.stream.Collectors;
import org.springframework.boot.logging.LogLevel;
/**
* Default {@link DockerCompose} implementation backed by {@link DockerCli}.
*
@ -43,8 +45,8 @@ class DefaultDockerCompose implements DockerCompose {
}
@Override
public void up() {
this.cli.run(new DockerCliCommand.ComposeUp());
public void up(LogLevel logLevel) {
this.cli.run(new DockerCliCommand.ComposeUp(logLevel));
}
@Override
@ -53,8 +55,8 @@ class DefaultDockerCompose implements DockerCompose {
}
@Override
public void start() {
this.cli.run(new DockerCliCommand.ComposeStart());
public void start(LogLevel logLevel) {
this.cli.run(new DockerCliCommand.ComposeStart(logLevel));
}
@Override

@ -21,11 +21,13 @@ import java.util.ArrayList;
import java.util.Collections;
import java.util.List;
import java.util.Set;
import java.util.function.Consumer;
import org.apache.commons.logging.Log;
import org.apache.commons.logging.LogFactory;
import org.springframework.boot.docker.compose.core.DockerCliCommand.Type;
import org.springframework.boot.logging.LogLevel;
import org.springframework.core.log.LogMessage;
/**
@ -116,10 +118,18 @@ class DockerCli {
<R> R run(DockerCliCommand<R> dockerCommand) {
List<String> command = createCommand(dockerCommand.getType());
command.addAll(dockerCommand.getCommand());
String json = this.processRunner.run(command.toArray(new String[0]));
Consumer<String> outputConsumer = createOutputConsumer(dockerCommand.getLogLevel());
String json = this.processRunner.run(outputConsumer, command.toArray(new String[0]));
return dockerCommand.deserialize(json);
}
private Consumer<String> createOutputConsumer(LogLevel logLevel) {
if (logLevel == null || logLevel == LogLevel.OFF) {
return null;
}
return (line) -> logLevel.log(this.logger, line);
}
private <R> List<String> createCommand(Type type) {
return switch (type) {
case DOCKER -> new ArrayList<>(this.dockerCommand);

@ -22,6 +22,8 @@ import java.util.Collection;
import java.util.List;
import java.util.Objects;
import org.springframework.boot.logging.LogLevel;
/**
* Commands that can be executed by the {@link DockerCli}.
*
@ -34,6 +36,8 @@ abstract sealed class DockerCliCommand<R> {
private final Type type;
private final LogLevel logLevel;
private final Class<?> responseType;
private final boolean listResponse;
@ -41,7 +45,13 @@ abstract sealed class DockerCliCommand<R> {
private final List<String> command;
private DockerCliCommand(Type type, Class<?> responseType, boolean listResponse, String... command) {
this(type, LogLevel.OFF, responseType, listResponse, command);
}
private DockerCliCommand(Type type, LogLevel logLevel, Class<?> responseType, boolean listResponse,
String... command) {
this.type = type;
this.logLevel = logLevel;
this.responseType = responseType;
this.listResponse = listResponse;
this.command = List.of(command);
@ -51,6 +61,10 @@ abstract sealed class DockerCliCommand<R> {
return this.type;
}
LogLevel getLogLevel() {
return this.logLevel;
}
List<String> getCommand() {
return this.command;
}
@ -148,8 +162,8 @@ abstract sealed class DockerCliCommand<R> {
*/
static final class ComposeUp extends DockerCliCommand<Void> {
ComposeUp() {
super(Type.DOCKER_COMPOSE, Void.class, false, "up", "--no-color", "--quiet-pull", "--detach", "--wait");
ComposeUp(LogLevel logLevel) {
super(Type.DOCKER_COMPOSE, logLevel, Void.class, false, "up", "--no-color", "--detach", "--wait");
}
}
@ -170,8 +184,8 @@ abstract sealed class DockerCliCommand<R> {
*/
static final class ComposeStart extends DockerCliCommand<Void> {
ComposeStart() {
super(Type.DOCKER_COMPOSE, Void.class, false, "start", "--no-color", "--quiet-pull", "--detach", "--wait");
ComposeStart(LogLevel logLevel) {
super(Type.DOCKER_COMPOSE, logLevel, Void.class, false, "start", "--no-color", "--detach", "--wait");
}
}

@ -20,6 +20,8 @@ import java.time.Duration;
import java.util.List;
import java.util.Set;
import org.springframework.boot.logging.LogLevel;
/**
* Provides a high-level API to work with Docker compose.
*
@ -38,8 +40,9 @@ public interface DockerCompose {
/**
* Run {@code docker compose up} to startup services. Waits until all contains are
* started and healthy.
* @param logLevel the log level used to report progress
*/
void up();
void up(LogLevel logLevel);
/**
* Run {@code docker compose down} to shutdown any running services.
@ -51,8 +54,9 @@ public interface DockerCompose {
/**
* Run {@code docker compose start} to startup services. Waits until all contains are
* started and healthy.
* @param logLevel the log level used to report progress
*/
void start();
void start(LogLevel logLevel);
/**
* Run {@code docker compose stop} to shutdown any running services.

@ -16,13 +16,15 @@
package org.springframework.boot.docker.compose.core;
import java.io.ByteArrayOutputStream;
import java.io.BufferedReader;
import java.io.File;
import java.io.IOException;
import java.io.InputStream;
import java.io.InputStreamReader;
import java.io.UncheckedIOException;
import java.nio.charset.StandardCharsets;
import java.util.concurrent.CountDownLatch;
import java.util.function.Consumer;
import org.apache.commons.logging.Log;
import org.apache.commons.logging.LogFactory;
@ -69,10 +71,22 @@ class ProcessRunner {
* @throws ProcessExitException if execution failed
*/
String run(String... command) {
return run(null, command);
}
/**
* Runs the given {@code command}. If the process exits with an error code other than
* zero, an {@link ProcessExitException} will be thrown.
* @param outputConsumer consumer used to accept output one line at a time
* @param command the command to run
* @return the output of the command
* @throws ProcessExitException if execution failed
*/
String run(Consumer<String> outputConsumer, String... command) {
logger.trace(LogMessage.of(() -> "Running '%s'".formatted(String.join(" ", command))));
Process process = startProcess(command);
ReaderThread stdOutReader = new ReaderThread(process.getInputStream(), "stdout");
ReaderThread stdErrReader = new ReaderThread(process.getErrorStream(), "stderr");
ReaderThread stdOutReader = new ReaderThread(process.getInputStream(), "stdout", outputConsumer);
ReaderThread stdErrReader = new ReaderThread(process.getErrorStream(), "stderr", outputConsumer);
logger.trace("Waiting for process exit");
int exitCode = waitForProcess(process);
logger.trace(LogMessage.format("Process exited with exit code %d", exitCode));
@ -118,12 +132,15 @@ class ProcessRunner {
private final InputStream source;
private final ByteArrayOutputStream content = new ByteArrayOutputStream();
private final Consumer<String> outputConsumer;
private final StringBuilder output = new StringBuilder();
private final CountDownLatch latch = new CountDownLatch(1);
ReaderThread(InputStream source, String name) {
ReaderThread(InputStream source, String name, Consumer<String> outputConsumer) {
this.source = source;
this.outputConsumer = outputConsumer;
setName("OutputReader-" + name);
setDaemon(true);
start();
@ -131,8 +148,17 @@ class ProcessRunner {
@Override
public void run() {
try {
this.source.transferTo(this.content);
try (BufferedReader reader = new BufferedReader(
new InputStreamReader(this.source, StandardCharsets.UTF_8))) {
String line = reader.readLine();
while (line != null) {
this.output.append(line);
this.output.append("\n");
if (this.outputConsumer != null) {
this.outputConsumer.accept(line);
}
line = reader.readLine();
}
this.latch.countDown();
}
catch (IOException ex) {
@ -144,7 +170,7 @@ class ProcessRunner {
public String toString() {
try {
this.latch.await();
return new String(this.content.toByteArray(), StandardCharsets.UTF_8);
return this.output.toString();
}
catch (InterruptedException ex) {
return null;

@ -110,7 +110,7 @@ class DockerComposeLifecycleManager {
Startup startup = this.properties.getStartup();
Shutdown shutdown = this.properties.getShutdown();
if (lifecycleManagement.shouldStartup() && !dockerCompose.hasRunningServices()) {
startup.getCommand().applyTo(dockerCompose);
startup.getCommand().applyTo(dockerCompose, startup.getLogLevel());
if (lifecycleManagement.shouldShutdown()) {
this.shutdownHandlers.add(() -> shutdown.getCommand().applyTo(dockerCompose, shutdown.getTimeout()));
}

@ -23,6 +23,7 @@ import java.util.Set;
import org.springframework.boot.context.properties.ConfigurationProperties;
import org.springframework.boot.context.properties.bind.Binder;
import org.springframework.boot.logging.LogLevel;
/**
* Configuration properties for the 'docker compose'.
@ -136,6 +137,11 @@ public class DockerComposeProperties {
*/
private StartupCommand command = StartupCommand.UP;
/**
* Log level for output.
*/
private LogLevel logLevel = LogLevel.INFO;
public StartupCommand getCommand() {
return this.command;
}
@ -144,6 +150,14 @@ public class DockerComposeProperties {
this.command = command;
}
public LogLevel getLogLevel() {
return this.logLevel;
}
public void setLogLevel(LogLevel logLevel) {
this.logLevel = logLevel;
}
}
/**

@ -16,9 +16,10 @@
package org.springframework.boot.docker.compose.lifecycle;
import java.util.function.Consumer;
import java.util.function.BiConsumer;
import org.springframework.boot.docker.compose.core.DockerCompose;
import org.springframework.boot.logging.LogLevel;
/**
* Command used to startup docker compose.
@ -40,14 +41,14 @@ public enum StartupCommand {
*/
START(DockerCompose::start);
private final Consumer<DockerCompose> action;
private final BiConsumer<DockerCompose, LogLevel> action;
StartupCommand(Consumer<DockerCompose> action) {
StartupCommand(BiConsumer<DockerCompose, LogLevel> action) {
this.action = action;
}
void applyTo(DockerCompose dockerCompose) {
this.action.accept(dockerCompose);
void applyTo(DockerCompose dockerCompose, LogLevel logLevel) {
this.action.accept(dockerCompose, logLevel);
}
}

@ -27,6 +27,7 @@ import org.springframework.boot.docker.compose.core.DockerCliInspectResponse.Con
import org.springframework.boot.docker.compose.core.DockerCliInspectResponse.ExposedPort;
import org.springframework.boot.docker.compose.core.DockerCliInspectResponse.HostConfig;
import org.springframework.boot.docker.compose.core.DockerCliInspectResponse.NetworkSettings;
import org.springframework.boot.logging.LogLevel;
import static org.assertj.core.api.Assertions.assertThat;
import static org.assertj.core.api.Assertions.entry;
@ -50,8 +51,8 @@ class DefaultDockerComposeTests {
@Test
void upRunsUpCommand() {
DefaultDockerCompose compose = new DefaultDockerCompose(this.cli, HOST);
compose.up();
then(this.cli).should().run(new DockerCliCommand.ComposeUp());
compose.up(LogLevel.OFF);
then(this.cli).should().run(new DockerCliCommand.ComposeUp(LogLevel.OFF));
}
@Test
@ -65,8 +66,8 @@ class DefaultDockerComposeTests {
@Test
void startRunsStartCommand() {
DefaultDockerCompose compose = new DefaultDockerCompose(this.cli, HOST);
compose.start();
then(this.cli).should().run(new DockerCliCommand.ComposeStart());
compose.start(LogLevel.OFF);
then(this.cli).should().run(new DockerCliCommand.ComposeStart(LogLevel.OFF));
}
@Test

@ -21,6 +21,8 @@ import java.util.List;
import org.junit.jupiter.api.Test;
import org.springframework.boot.logging.LogLevel;
import static org.assertj.core.api.Assertions.assertThat;
/**
@ -66,9 +68,10 @@ class DockerCliCommandTests {
@Test
void composeUp() {
DockerCliCommand<?> command = new DockerCliCommand.ComposeUp();
DockerCliCommand<?> command = new DockerCliCommand.ComposeUp(LogLevel.INFO);
assertThat(command.getType()).isEqualTo(DockerCliCommand.Type.DOCKER_COMPOSE);
assertThat(command.getCommand()).containsExactly("up", "--no-color", "--quiet-pull", "--detach", "--wait");
assertThat(command.getLogLevel()).isEqualTo(LogLevel.INFO);
assertThat(command.getCommand()).containsExactly("up", "--no-color", "--detach", "--wait");
assertThat(command.deserialize("[]")).isNull();
}
@ -82,9 +85,10 @@ class DockerCliCommandTests {
@Test
void composeStart() {
DockerCliCommand<?> command = new DockerCliCommand.ComposeStart();
DockerCliCommand<?> command = new DockerCliCommand.ComposeStart(LogLevel.INFO);
assertThat(command.getType()).isEqualTo(DockerCliCommand.Type.DOCKER_COMPOSE);
assertThat(command.getCommand()).containsExactly("start", "--no-color", "--quiet-pull", "--detach", "--wait");
assertThat(command.getLogLevel()).isEqualTo(LogLevel.INFO);
assertThat(command.getCommand()).containsExactly("start", "--no-color", "--detach", "--wait");
assertThat(command.deserialize("[]")).isNull();
}

@ -41,6 +41,13 @@ class ProcessRunnerTests {
assertThat(out).isNotEmpty();
}
@Test
void runWhenHasOutputConsumer() {
StringBuilder output = new StringBuilder();
this.processRunner.run(output::append, "docker", "--version");
assertThat(output.toString()).isNotEmpty();
}
@Test
void runWhenProcessDoesNotStart() {
assertThatExceptionOfType(ProcessStartException.class)

@ -43,7 +43,6 @@ import org.springframework.util.FileCopyUtils;
import static org.assertj.core.api.Assertions.assertThat;
import static org.mockito.ArgumentMatchers.any;
import static org.mockito.ArgumentMatchers.isA;
import static org.mockito.BDDMockito.given;
import static org.mockito.BDDMockito.then;
import static org.mockito.Mockito.mock;
@ -132,10 +131,10 @@ class DockerComposeLifecycleManagerTests {
this.lifecycleManager.startup();
assertThat(listener.getEvent()).isNull();
then(this.dockerCompose).should().hasDefinedServices();
then(this.dockerCompose).should(never()).up();
then(this.dockerCompose).should(never()).start();
then(this.dockerCompose).should(never()).down(isA(Duration.class));
then(this.dockerCompose).should(never()).stop(isA(Duration.class));
then(this.dockerCompose).should(never()).up(any());
then(this.dockerCompose).should(never()).start(any());
then(this.dockerCompose).should(never()).down(any());
then(this.dockerCompose).should(never()).stop(any());
}
@Test
@ -147,10 +146,10 @@ class DockerComposeLifecycleManagerTests {
this.lifecycleManager.startup();
this.shutdownHandlers.run();
assertThat(listener.getEvent()).isNotNull();
then(this.dockerCompose).should().up();
then(this.dockerCompose).should(never()).start();
then(this.dockerCompose).should().down(isA(Duration.class));
then(this.dockerCompose).should(never()).stop(isA(Duration.class));
then(this.dockerCompose).should().up(any());
then(this.dockerCompose).should(never()).start(any());
then(this.dockerCompose).should().down(any());
then(this.dockerCompose).should(never()).stop(any());
}
@Test
@ -162,10 +161,10 @@ class DockerComposeLifecycleManagerTests {
this.lifecycleManager.startup();
this.shutdownHandlers.run();
assertThat(listener.getEvent()).isNotNull();
then(this.dockerCompose).should(never()).up();
then(this.dockerCompose).should(never()).start();
then(this.dockerCompose).should(never()).down(isA(Duration.class));
then(this.dockerCompose).should(never()).stop(isA(Duration.class));
then(this.dockerCompose).should(never()).up(any());
then(this.dockerCompose).should(never()).start(any());
then(this.dockerCompose).should(never()).down(any());
then(this.dockerCompose).should(never()).stop(any());
}
@Test
@ -177,10 +176,10 @@ class DockerComposeLifecycleManagerTests {
this.lifecycleManager.startup();
this.shutdownHandlers.run();
assertThat(listener.getEvent()).isNotNull();
then(this.dockerCompose).should(never()).up();
then(this.dockerCompose).should(never()).start();
then(this.dockerCompose).should(never()).down(isA(Duration.class));
then(this.dockerCompose).should(never()).stop(isA(Duration.class));
then(this.dockerCompose).should(never()).up(any());
then(this.dockerCompose).should(never()).start(any());
then(this.dockerCompose).should(never()).down(any());
then(this.dockerCompose).should(never()).stop(any());
}
@Test
@ -192,10 +191,10 @@ class DockerComposeLifecycleManagerTests {
this.lifecycleManager.startup();
this.shutdownHandlers.run();
assertThat(listener.getEvent()).isNotNull();
then(this.dockerCompose).should().up();
then(this.dockerCompose).should(never()).start();
then(this.dockerCompose).should(never()).down(isA(Duration.class));
then(this.dockerCompose).should(never()).stop(isA(Duration.class));
then(this.dockerCompose).should().up(any());
then(this.dockerCompose).should(never()).start(any());
then(this.dockerCompose).should(never()).down(any());
then(this.dockerCompose).should(never()).stop(any());
this.shutdownHandlers.assertNoneAdded();
}
@ -209,10 +208,10 @@ class DockerComposeLifecycleManagerTests {
this.lifecycleManager.startup();
this.shutdownHandlers.run();
assertThat(listener.getEvent()).isNotNull();
then(this.dockerCompose).should(never()).up();
then(this.dockerCompose).should().start();
then(this.dockerCompose).should().down(isA(Duration.class));
then(this.dockerCompose).should(never()).stop(isA(Duration.class));
then(this.dockerCompose).should(never()).up(any());
then(this.dockerCompose).should().start(any());
then(this.dockerCompose).should().down(any());
then(this.dockerCompose).should(never()).stop(any());
}
@Test
@ -225,10 +224,10 @@ class DockerComposeLifecycleManagerTests {
this.lifecycleManager.startup();
this.shutdownHandlers.run();
assertThat(listener.getEvent()).isNotNull();
then(this.dockerCompose).should().up();
then(this.dockerCompose).should(never()).start();
then(this.dockerCompose).should(never()).down(isA(Duration.class));
then(this.dockerCompose).should().stop(isA(Duration.class));
then(this.dockerCompose).should().up(any());
then(this.dockerCompose).should(never()).start(any());
then(this.dockerCompose).should(never()).down(any());
then(this.dockerCompose).should().stop(any());
}
@Test

@ -19,6 +19,7 @@ package org.springframework.boot.docker.compose.lifecycle;
import org.junit.jupiter.api.Test;
import org.springframework.boot.docker.compose.core.DockerCompose;
import org.springframework.boot.logging.LogLevel;
import static org.mockito.BDDMockito.then;
import static org.mockito.Mockito.mock;
@ -36,14 +37,14 @@ class StartupCommandTests {
@Test
void applyToWhenUp() {
StartupCommand.UP.applyTo(this.dockerCompose);
then(this.dockerCompose).should().up();
StartupCommand.UP.applyTo(this.dockerCompose, LogLevel.INFO);
then(this.dockerCompose).should().up(LogLevel.INFO);
}
@Test
void applyToWhenStart() {
StartupCommand.START.applyTo(this.dockerCompose);
then(this.dockerCompose).should().start();
StartupCommand.START.applyTo(this.dockerCompose, LogLevel.INFO);
then(this.dockerCompose).should().start(LogLevel.INFO);
}
}

Loading…
Cancel
Save