Maciej Walkowiak

Appearance

← Back to blog

Container logs with Spring Boot and Testcontainers

Published on
  • Java
  • Testcontainers
  • Spring Boot

In this article you will learn how to enable container debug logs with Testcontainers and Spring Boot and how to leverage Spring Framework flexibility to turn logs on and off with a custom @EnableContainerLogs annotation. As a side effect you'll learn a little about Spring Framework internals enabling Spring's magic ✨.

Testcontainers - follow container logs ​

Similar to how sometimes during development I switch Spring Boot's debug flag to true to really understand what's going on, sometimes when I use Testcontainers I need to see the logs of the running container.

Testcontainers make it relatively easy to follow container logs. Once container has started, at any point in time you can call container.getLogs() to get complete logs output.

To see logs in real time, you can also follow the container logs - stream them either to stdout, or to a logging system like Slf4j.

java
container.followOutput(new Slf4jLogConsumer(LOGGER));

There's a catch though - when calling followOutput, the container must be already running. Otherwise, you'll get rather nasty NullPointerException:

console
java.lang.NullPointerException: containerId was not specified
	at java.base/java.util.Objects.requireNonNull(Objects.java:259)
	at org.testcontainers.shaded.com.github.dockerjava.core.command.LogContainerCmdImpl.withContainerId(LogContainerCmdImpl.java:85)
	at org.testcontainers.shaded.com.github.dockerjava.core.command.LogContainerCmdImpl.<init>(LogContainerCmdImpl.java:40)
	at org.testcontainers.shaded.com.github.dockerjava.core.DockerClientImpl.logContainerCmd(DockerClientImpl.java:440)
	at com.github.dockerjava.api.DockerClientDelegate.logContainerCmd(DockerClientDelegate.java:249)
	at com.github.dockerjava.api.DockerClientDelegate.logContainerCmd(DockerClientDelegate.java:249)
	at org.testcontainers.utility.LogUtils.attachConsumer(LogUtils.java:86)
	at org.testcontainers.utility.LogUtils.followOutput(LogUtils.java:37)
	at org.testcontainers.utility.LogUtils.followOutput(LogUtils.java:49)
	at org.testcontainers.containers.Container.followOutput(Container.java:413)
	at com.example.demo.DemoApplicationTests$Config.postgresContainer(DemoApplicationTests.java:26)

To configure logging before container has started, you must use instead withLogConsumer:

java
var container = new PostgreSQLContainer<>(DockerImageName.parse("postgres:latest"));
container.withLogConsumer(new Slf4jLogConsumer(LoggerFactory.getLogger("postgres")));
container.start();

Depending on the configuration, containers can produce quite large amount of logs - good when we need them, pretty bad when we don't. I've been looking for solution to make this configuration more declarative, letting me turning container logs on/off just when I need, without having to remember Testcontainers API, creating loggers etc - similar to how Spring Boot debug flag turns on debug logs for Spring components.

Modern Testcontainers with Spring Boot ​

Starting from version 3.1, Spring Boot comes with first-class support for Testcontainers. Not only you can choose Testcontainers dependency at start.spring.io to bring Testcontainers dependencies, but there is an actual spring-boot-testcontainers module turning containers into a part of a Spring Boot application.

As an example, a container instance is configured as a Spring bean, and annotated with @ServiceConnection (this applies to container types Spring Boot is aware of), Spring will be responsible for starting & stopping containers:

java
@SpringBootTest
class AppTests {

	@TestConfiguration
	static class Config {

		@Bean
		@ServiceConnection
		PostgreSQLContainer<?> postgresContainer() {
			return new PostgreSQLContainer<>(DockerImageName.parse("postgres:latest"));
		}

        @Bean
        @ServiceConnection // note that @ServiceConnection support for LocalStack comes in Spring Cloud AWS 3.2.0
        LocalStackContainer localStackContainer() {
            return new LocalStackContainer(DockerImageName.parse("localstack/localstack:3.2.0"));
        }
	}

	@Test
	void contextLoads() {
	}
}

Since containers are defined as beans, it opens interesting possibilities like bean processing.

Spring's BeanPostProcessor ​

If you have never written a Spring based library I imagine that you may not be familiar with BeanPostProcessor, even though it is used heavily by the framework itself.

BeanPostProcessor lets us hook into bean initialization lifecycle and either execute some piece of code before/after initialization, or even return completely different object - like a proxy.

There are two methods to implement, both are marked as default, so the implementation can implement only the relevant one.

java
public interface BeanPostProcessor {
	@Nullable
	default Object postProcessBeforeInitialization(Object bean, String beanName) throws BeansException {
		return bean;
	}
    
	@Nullable
	default Object postProcessAfterInitialization(Object bean, String beanName) throws BeansException {
		return bean;
	}
}

Both method are executed for each and every bean defined in the context - that's why the bean type is just an Object.

To get all container logs from the very beginning, we should hook into postProcessBeforeInitialization, to configure following output before the container starts.

ContainerLogsBeanPostProcessor ​

Now we can implement an actual processor that adds logging capabilities. Let's start with one forwarding logs to Slf4j (although this is not my preference):

java
import org.springframework.beans.BeansException;
import org.springframework.beans.factory.config.BeanPostProcessor;
import org.testcontainers.containers.Container;
import org.testcontainers.containers.output.BaseConsumer;

public class ContainerLogsBeanPostProcessor implements BeanPostProcessor {
    @Override
    public Object postProcessBeforeInitialization(Object bean, String beanName) throws BeansException {
        if (bean instanceof Container<?> container) {
            var logger = LoggerFactory.getLogger(beanName);
            var logConsumer = new Slf4jLogConsumer(logger);
            container.withLogConsumer(logConsumer);
        }
        return bean;
    }
}

beanName is going to be used as a logger name to be able to easily distinguish which container produces which logs - especially handy in case your application uses multiple containers of the same type - like two Postgres instances.

Once ContainerLogsBeanPostProcessor is configured as a bean:

java
@SpringBootTest
class AppTests {

	@TestConfiguration
	static class Config {

        @Bean
        ContainerLogsBeanPostProcessor containerLogsBeanPostProcessor() {
            return new ContainerLogsBeanPostProcessor();
        }

		@Bean
		@ServiceConnection
		PostgreSQLContainer<?> postgresContainer() {
			return new PostgreSQLContainer<>(DockerImageName.parse("postgres:latest"));
		}

        @Bean
        @ServiceConnection // note that @ServiceConnection support for LocalStack comes in Spring Cloud AWS 3.2.0
        LocalStackContainer localStackContainer() {
            return new LocalStackContainer(DockerImageName.parse("localstack/localstack:3.2.0"));
        }
	}

	@Test
	void contextLoads() {
	}
}

... and test runs, we can see logs from both LocalStack and Postgres containers in the console (look for localStackContainer and postgresContainer):

console
09:19:22.968 [Test worker] INFO org.springframework.test.context.support.AnnotationConfigContextLoaderUtils -- Could not detect default configuration classes for test class [com.example.demo.DemoApplicationTests]: DemoApplicationTests does not declare any static, non-private, non-final, nested classes annotated with @Configuration.
09:19:23.033 [Test worker] INFO org.springframework.boot.test.context.SpringBootTestContextBootstrapper -- Found @SpringBootConfiguration com.example.demo.DemoApplication for test class com.example.demo.DemoApplicationTests

  .   ____          _            __ _ _
 /\\ / ___'_ __ _ _(_)_ __  __ _ \ \ \ \
( ( )\___ | '_ | '_| | '_ \/ _` | \ \ \ \
 \\/  ___)| |_)| | | | | || (_| |  ) ) ) )
  '  |____| .__|_| |_|_| |_\__, | / / / /
 =========|_|==============|___/=/_/_/_/
 :: Spring Boot ::                (v3.2.4)

2024-03-23T09:19:23.194+01:00  INFO 12952 --- [demo] [    Test worker] com.example.demo.DemoApplicationTests    : Starting DemoApplicationTests using Java 21 with PID 12952 (started by maciej.walkowiak in /Users/maciej.walkowiak/Downloads/demo 3)
2024-03-23T09:19:23.195+01:00  INFO 12952 --- [demo] [    Test worker] com.example.demo.DemoApplicationTests    : No active profile set, falling back to 1 default profile: "default"
2024-03-23T09:19:23.477+01:00  WARN 12952 --- [demo] [    Test worker] trationDelegate$BeanPostProcessorChecker : Bean 'com.example.demo.TestDemoApplication' of type [com.example.demo.TestDemoApplication] is not eligible for getting processed by all BeanPostProcessors (for example: not eligible for auto-proxying). The currently created BeanPostProcessor [containerLogsBeanPostProcessor] is declared through a non-static factory method on that class; consider declaring it as static instead.
2024-03-23T09:19:23.508+01:00  INFO 12952 --- [demo] [    Test worker] org.testcontainers.images.PullPolicy     : Image pull policy will be performed by: DefaultPullPolicy()
2024-03-23T09:19:23.509+01:00  INFO 12952 --- [demo] [    Test worker] o.t.utility.ImageNameSubstitutor         : Image name substitution will be performed by: DefaultImageNameSubstitutor (composite of 'ConfigurationFileImageNameSubstitutor' and 'PrefixingImageNameSubstitutor')
2024-03-23T09:19:23.787+01:00  INFO 12952 --- [demo] [    Test worker] o.t.d.DockerClientProviderStrategy       : Found Docker environment with Testcontainers Host with tc.host=tcp://127.0.0.1:60591
2024-03-23T09:19:23.808+01:00  INFO 12952 --- [demo] [    Test worker] org.testcontainers.DockerClientFactory   : Docker host IP address is 127.0.0.1
2024-03-23T09:19:23.834+01:00  INFO 12952 --- [demo] [    Test worker] org.testcontainers.DockerClientFactory   : Connected to docker: 
  Server Version: 25.0.3 (via Testcontainers Desktop 1.8.0)
  API Version: 1.44
  Operating System: Docker Desktop
  Total Memory: 7841 MB
2024-03-23T09:19:23.891+01:00  INFO 12952 --- [demo] [    Test worker] tc.testcontainers/ryuk:0.6.0             : Creating container for image: testcontainers/ryuk:0.6.0
2024-03-23T09:19:23.953+01:00  INFO 12952 --- [demo] [    Test worker] o.t.utility.RegistryAuthLocator          : Credential helper/store (docker-credential-desktop) does not have credentials for https://index.docker.io/v1/
2024-03-23T09:19:24.065+01:00  INFO 12952 --- [demo] [    Test worker] tc.testcontainers/ryuk:0.6.0             : Container testcontainers/ryuk:0.6.0 is starting: f09f25ce203fb00f858e5d0c4ec840d768618d0e51b560385300920d79321b1c
2024-03-23T09:19:24.322+01:00  INFO 12952 --- [demo] [    Test worker] tc.testcontainers/ryuk:0.6.0             : Container testcontainers/ryuk:0.6.0 started in PT0.431032S
2024-03-23T09:19:24.327+01:00  INFO 12952 --- [demo] [    Test worker] o.t.utility.RyukResourceReaper           : Ryuk started - will monitor and terminate Testcontainers containers on JVM exit
2024-03-23T09:19:24.327+01:00  INFO 12952 --- [demo] [    Test worker] org.testcontainers.DockerClientFactory   : Checking the system...
2024-03-23T09:19:24.327+01:00  INFO 12952 --- [demo] [    Test worker] org.testcontainers.DockerClientFactory   : ✔︎ Docker server version should be at least 1.6.0
2024-03-23T09:19:24.328+01:00  INFO 12952 --- [demo] [    Test worker] tc.localstack/localstack:3.2.0           : LOCALSTACK_HOST environment variable set to 127.0.0.1 (to match host-routable address for container)
2024-03-23T09:19:24.328+01:00  INFO 12952 --- [demo] [    Test worker] tc.localstack/localstack:3.2.0           : Creating container for image: localstack/localstack:3.2.0
2024-03-23T09:19:24.646+01:00  INFO 12952 --- [demo] [    Test worker] tc.localstack/localstack:3.2.0           : Container localstack/localstack:3.2.0 is starting: eaef29b3241d75ea3b92e4d1446ec91473980373f87f4ddb1a588818f2b0a56c
2024-03-23T09:19:25.160+01:00  INFO 12952 --- [demo] [tream-154292601] localStackContainer                      : STDOUT: 
2024-03-23T09:19:25.160+01:00  INFO 12952 --- [demo] [tream-154292601] localStackContainer                      : STDOUT: LocalStack version: 3.2.0
2024-03-23T09:19:25.165+01:00  INFO 12952 --- [demo] [tream-154292601] localStackContainer                      : STDOUT: LocalStack Docker container id: eaef29b3241d
2024-03-23T09:19:25.165+01:00  INFO 12952 --- [demo] [tream-154292601] localStackContainer                      : STDOUT: LocalStack build date: 2024-02-28
2024-03-23T09:19:25.165+01:00  INFO 12952 --- [demo] [tream-154292601] localStackContainer                      : STDOUT: LocalStack build git hash: 4a4692dd5
2024-03-23T09:19:25.165+01:00  INFO 12952 --- [demo] [tream-154292601] localStackContainer                      : STDOUT: 
2024-03-23T09:19:26.778+01:00  INFO 12952 --- [demo] [tream-154292601] localStackContainer                      : STDOUT: 2024-03-23T08:19:26.776  INFO --- [-functhread6] hypercorn.error            : Running on https://0.0.0.0:4566 (CTRL + C to quit)
2024-03-23T09:19:26.778+01:00  INFO 12952 --- [demo] [tream-154292601] localStackContainer                      : STDOUT: 2024-03-23T08:19:26.776  INFO --- [-functhread6] hypercorn.error            : Running on https://0.0.0.0:4566 (CTRL + C to quit)
2024-03-23T09:19:26.855+01:00  INFO 12952 --- [demo] [tream-154292601] localStackContainer                      : STDOUT: 2024-03-23T08:19:26.853  INFO --- [  MainThread] localstack.utils.bootstrap : Execution of "start_runtime_components" took 607.06ms
2024-03-23T09:19:26.869+01:00  INFO 12952 --- [demo] [tream-154292601] localStackContainer                      : STDOUT: Ready.
2024-03-23T09:19:26.870+01:00  INFO 12952 --- [demo] [    Test worker] tc.localstack/localstack:3.2.0           : Container localstack/localstack:3.2.0 started in PT2.541883S
2024-03-23T09:19:31.931+01:00  INFO 12952 --- [demo] [    Test worker] tc.postgres:latest                       : Creating container for image: postgres:latest
2024-03-23T09:19:31.959+01:00  INFO 12952 --- [demo] [    Test worker] tc.postgres:latest                       : Container postgres:latest is starting: 79dd6c1c21d2eb33249a5d7977f1d1454c6bec7735912d7874165ecf281d57f1
2024-03-23T09:19:32.123+01:00  INFO 12952 --- [demo] [ream-1134068743] postgresContainer                        : STDOUT: The files belonging to this database system will be owned by user "postgres".
2024-03-23T09:19:32.124+01:00  INFO 12952 --- [demo] [ream-1134068743] postgresContainer                        : STDOUT: This user must also own the server process.
2024-03-23T09:19:32.124+01:00  INFO 12952 --- [demo] [ream-1134068743] postgresContainer                        : STDOUT: 
2024-03-23T09:19:32.124+01:00  INFO 12952 --- [demo] [ream-1134068743] postgresContainer                        : STDOUT: The database cluster will be initialized with locale "en_US.utf8".
2024-03-23T09:19:32.124+01:00  INFO 12952 --- [demo] [ream-1134068743] postgresContainer                        : STDOUT: The default database encoding has accordingly been set to "UTF8".
2024-03-23T09:19:32.124+01:00  INFO 12952 --- [demo] [ream-1134068743] postgresContainer                        : STDOUT: The default text search configuration will be set to "english".
2024-03-23T09:19:32.124+01:00  INFO 12952 --- [demo] [ream-1134068743] postgresContainer                        : STDOUT: 
2024-03-23T09:19:32.124+01:00  INFO 12952 --- [demo] [ream-1134068743] postgresContainer                        : STDOUT: Data page checksums are disabled.
2024-03-23T09:19:32.124+01:00  INFO 12952 --- [demo] [ream-1134068743] postgresContainer                        : STDOUT: 
2024-03-23T09:19:32.124+01:00  INFO 12952 --- [demo] [ream-1134068743] postgresContainer                        : STDOUT: fixing permissions on existing directory /var/lib/postgresql/data ... ok
2024-03-23T09:19:32.124+01:00  INFO 12952 --- [demo] [ream-1134068743] postgresContainer                        : STDOUT: creating subdirectories ... ok
2024-03-23T09:19:32.124+01:00  INFO 12952 --- [demo] [ream-1134068743] postgresContainer                        : STDOUT: selecting dynamic shared memory implementation ... posix
2024-03-23T09:19:32.133+01:00  INFO 12952 --- [demo] [ream-1134068743] postgresContainer                        : STDOUT: selecting default max_connections ... 100
2024-03-23T09:19:32.143+01:00  INFO 12952 --- [demo] [ream-1134068743] postgresContainer                        : STDOUT: selecting default shared_buffers ... 128MB
2024-03-23T09:19:32.148+01:00  INFO 12952 --- [demo] [ream-1134068743] postgresContainer                        : STDOUT: selecting default time zone ... Etc/UTC
2024-03-23T09:19:32.148+01:00  INFO 12952 --- [demo] [ream-1134068743] postgresContainer                        : STDOUT: creating configuration files ... ok
2024-03-23T09:19:32.241+01:00  INFO 12952 --- [demo] [ream-1134068743] postgresContainer                        : STDOUT: running bootstrap script ... ok
2024-03-23T09:19:32.428+01:00  INFO 12952 --- [demo] [ream-1134068743] postgresContainer                        : STDOUT: performing post-bootstrap initialization ... ok
2024-03-23T09:19:32.514+01:00  INFO 12952 --- [demo] [ream-1134068743] postgresContainer                        : STDOUT: syncing data to disk ... ok
2024-03-23T09:19:32.515+01:00  INFO 12952 --- [demo] [ream-1134068743] postgresContainer                        : STDOUT: 
2024-03-23T09:19:32.515+01:00  INFO 12952 --- [demo] [ream-1134068743] postgresContainer                        : STDOUT: 
2024-03-23T09:19:32.515+01:00  INFO 12952 --- [demo] [ream-1134068743] postgresContainer                        : STDOUT: Success. You can now start the database server using:
2024-03-23T09:19:32.515+01:00  INFO 12952 --- [demo] [ream-1134068743] postgresContainer                        : STDOUT: 
2024-03-23T09:19:32.515+01:00  INFO 12952 --- [demo] [ream-1134068743] postgresContainer                        : STDOUT:     pg_ctl -D /var/lib/postgresql/data -l logfile start
2024-03-23T09:19:32.515+01:00  INFO 12952 --- [demo] [ream-1134068743] postgresContainer                        : STDOUT: 
2024-03-23T09:19:32.515+01:00  INFO 12952 --- [demo] [ream-1134068743] postgresContainer                        : STDERR: initdb: warning: enabling "trust" authentication for local connections
2024-03-23T09:19:32.515+01:00  INFO 12952 --- [demo] [ream-1134068743] postgresContainer                        : STDERR: initdb: hint: You can change this by editing pg_hba.conf or using the option -A, or --auth-local and --auth-host, the next time you run initdb.
2024-03-23T09:19:32.540+01:00  INFO 12952 --- [demo] [ream-1134068743] postgresContainer                        : STDOUT: waiting for server to start....2024-03-23 08:19:32.538 UTC [48] LOG:  starting PostgreSQL 16.0 (Debian 16.0-1.pgdg120+1) on aarch64-unknown-linux-gnu, compiled by gcc (Debian 12.2.0-14) 12.2.0, 64-bit
2024-03-23T09:19:32.540+01:00  INFO 12952 --- [demo] [ream-1134068743] postgresContainer                        : STDOUT: 2024-03-23 08:19:32.539 UTC [48] LOG:  listening on Unix socket "/var/run/postgresql/.s.PGSQL.5432"
2024-03-23T09:19:32.541+01:00  INFO 12952 --- [demo] [ream-1134068743] postgresContainer                        : STDOUT: 2024-03-23 08:19:32.540 UTC [51] LOG:  database system was shut down at 2024-03-23 08:19:32 UTC
2024-03-23T09:19:32.543+01:00  INFO 12952 --- [demo] [ream-1134068743] postgresContainer                        : STDOUT: 2024-03-23 08:19:32.542 UTC [48] LOG:  database system is ready to accept connections
2024-03-23T09:19:32.633+01:00  INFO 12952 --- [demo] [ream-1134068743] postgresContainer                        : STDOUT:  done
2024-03-23T09:19:32.633+01:00  INFO 12952 --- [demo] [ream-1134068743] postgresContainer                        : STDOUT: server started
2024-03-23T09:19:32.694+01:00  INFO 12952 --- [demo] [ream-1134068743] postgresContainer                        : STDOUT: CREATE DATABASE
2024-03-23T09:19:32.694+01:00  INFO 12952 --- [demo] [ream-1134068743] postgresContainer                        : STDOUT: 
2024-03-23T09:19:32.694+01:00  INFO 12952 --- [demo] [ream-1134068743] postgresContainer                        : STDOUT: 
2024-03-23T09:19:32.695+01:00  INFO 12952 --- [demo] [ream-1134068743] postgresContainer                        : STDOUT: /usr/local/bin/docker-entrypoint.sh: ignoring /docker-entrypoint-initdb.d/*
2024-03-23T09:19:32.695+01:00  INFO 12952 --- [demo] [ream-1134068743] postgresContainer                        : STDOUT: 
2024-03-23T09:19:32.696+01:00  INFO 12952 --- [demo] [ream-1134068743] postgresContainer                        : STDOUT: waiting for server to shut down....2024-03-23 08:19:32.694 UTC [48] LOG:  received fast shutdown request
2024-03-23T09:19:32.696+01:00  INFO 12952 --- [demo] [ream-1134068743] postgresContainer                        : STDOUT: 2024-03-23 08:19:32.694 UTC [48] LOG:  aborting any active transactions
2024-03-23T09:19:32.696+01:00  INFO 12952 --- [demo] [ream-1134068743] postgresContainer                        : STDOUT: 2024-03-23 08:19:32.695 UTC [48] LOG:  background worker "logical replication launcher" (PID 54) exited with exit code 1
2024-03-23T09:19:32.696+01:00  INFO 12952 --- [demo] [ream-1134068743] postgresContainer                        : STDOUT: 2024-03-23 08:19:32.695 UTC [49] LOG:  shutting down
2024-03-23T09:19:32.696+01:00  INFO 12952 --- [demo] [ream-1134068743] postgresContainer                        : STDOUT: 2024-03-23 08:19:32.695 UTC [49] LOG:  checkpoint starting: shutdown immediate
2024-03-23T09:19:32.701+01:00  INFO 12952 --- [demo] [ream-1134068743] postgresContainer                        : STDOUT: 2024-03-23 08:19:32.700 UTC [49] LOG:  checkpoint complete: wrote 923 buffers (5.6%); 0 WAL file(s) added, 0 removed, 0 recycled; write=0.005 s, sync=0.001 s, total=0.006 s; sync files=0, longest=0.000 s, average=0.000 s; distance=4257 kB, estimate=4257 kB; lsn=0/1913040, redo lsn=0/1913040
2024-03-23T09:19:32.704+01:00  INFO 12952 --- [demo] [ream-1134068743] postgresContainer                        : STDOUT: 2024-03-23 08:19:32.703 UTC [48] LOG:  database system is shut down
2024-03-23T09:19:32.797+01:00  INFO 12952 --- [demo] [ream-1134068743] postgresContainer                        : STDOUT:  done
2024-03-23T09:19:32.797+01:00  INFO 12952 --- [demo] [ream-1134068743] postgresContainer                        : STDOUT: server stopped
2024-03-23T09:19:32.797+01:00  INFO 12952 --- [demo] [ream-1134068743] postgresContainer                        : STDOUT: 
2024-03-23T09:19:32.797+01:00  INFO 12952 --- [demo] [ream-1134068743] postgresContainer                        : STDOUT: PostgreSQL init process complete; ready for start up.
2024-03-23T09:19:32.798+01:00  INFO 12952 --- [demo] [ream-1134068743] postgresContainer                        : STDOUT: 
2024-03-23T09:19:32.812+01:00  INFO 12952 --- [demo] [ream-1134068743] postgresContainer                        : STDERR: 2024-03-23 08:19:32.811 UTC [1] LOG:  starting PostgreSQL 16.0 (Debian 16.0-1.pgdg120+1) on aarch64-unknown-linux-gnu, compiled by gcc (Debian 12.2.0-14) 12.2.0, 64-bit
2024-03-23T09:19:32.812+01:00  INFO 12952 --- [demo] [ream-1134068743] postgresContainer                        : STDERR: 2024-03-23 08:19:32.811 UTC [1] LOG:  listening on IPv4 address "0.0.0.0", port 5432
2024-03-23T09:19:32.812+01:00  INFO 12952 --- [demo] [ream-1134068743] postgresContainer                        : STDERR: 2024-03-23 08:19:32.811 UTC [1] LOG:  listening on IPv6 address "::", port 5432
2024-03-23T09:19:32.812+01:00  INFO 12952 --- [demo] [ream-1134068743] postgresContainer                        : STDERR: 2024-03-23 08:19:32.811 UTC [1] LOG:  listening on Unix socket "/var/run/postgresql/.s.PGSQL.5432"
2024-03-23T09:19:32.813+01:00  INFO 12952 --- [demo] [ream-1134068743] postgresContainer                        : STDERR: 2024-03-23 08:19:32.812 UTC [64] LOG:  database system was shut down at 2024-03-23 08:19:32 UTC
2024-03-23T09:19:32.815+01:00  INFO 12952 --- [demo] [ream-1134068743] postgresContainer                        : STDERR: 2024-03-23 08:19:32.814 UTC [1] LOG:  database system is ready to accept connections
2024-03-23T09:19:32.822+01:00  INFO 12952 --- [demo] [    Test worker] tc.postgres:latest                       : Container postgres:latest started in PT0.891102S
2024-03-23T09:19:32.823+01:00  INFO 12952 --- [demo] [    Test worker] tc.postgres:latest                       : Container is started (JDBC URL: jdbc:postgresql://127.0.0.1:55456/test?loggerLevel=OFF)

Cleaner output with custom log consumer ​

Since containers logs are logged through Slf4j which is configured for application logs - containers logs are a little noisy - they contain irrelevant information like the thread, PID and in many cases duplicated timestamp. We can fix that by either changing Logback configuration (too much work) or implementing custom logs consumer that logs to stdout:

java
public class StdOutConsumer<SELF extends BaseConsumer<SELF>> extends BaseConsumer<SELF> {
    private final String prefix;

    public StdOutConsumer(String prefix) {
        this.prefix = prefix;
    }

    @Override
    public void accept(OutputFrame outputFrame) {
        var utf8String = outputFrame.getUtf8StringWithoutLineEnding();
        switch (outputFrame.getType()) {
            case STDOUT -> System.out.printf("%s | %s%n", prefix, utf8String);
            case STDERR -> System.err.printf("%s | %s%n", prefix, utf8String);
            case END -> {}
        }
    }
}

To distinguish log lines between containers (handy especially if we start more than one container of a type), we can pass beanName as a logger prefix:

java
public class ContainerLogsBeanPostProcessor implements BeanPostProcessor {
    @Override
    public Object postProcessBeforeInitialization(Object bean, String beanName) throws BeansException {
        if (bean instanceof Container<?> container) {
            var logConsumer = new StdOutConsumer(beanName);
            container.withLogConsumer(logConsumer);
        }
        return bean;
    }
}

Logs are now more readable, and we can easily distinguish between log lines coming from the application and individual containers:

console
09:06:01.024 [Test worker] INFO org.springframework.test.context.support.AnnotationConfigContextLoaderUtils -- Could not detect default configuration classes for test class [com.example.demo.DemoApplicationTests]: DemoApplicationTests does not declare any static, non-private, non-final, nested classes annotated with @Configuration.
09:06:01.095 [Test worker] INFO org.springframework.boot.test.context.SpringBootTestContextBootstrapper -- Found @SpringBootConfiguration com.example.demo.DemoApplication for test class com.example.demo.DemoApplicationTests

  .   ____          _            __ _ _
 /\\ / ___'_ __ _ _(_)_ __  __ _ \ \ \ \
( ( )\___ | '_ | '_| | '_ \/ _` | \ \ \ \
 \\/  ___)| |_)| | | | | || (_| |  ) ) ) )
  '  |____| .__|_| |_|_| |_\__, | / / / /
 =========|_|==============|___/=/_/_/_/
 :: Spring Boot ::                (v3.2.4)

2024-03-25T09:06:01.259+01:00  INFO 27991 --- [demo] [    Test worker] com.example.demo.DemoApplicationTests    : Starting DemoApplicationTests using Java 21 with PID 27991 (started by maciej.walkowiak in /Users/maciej.walkowiak/Downloads/demo 3)
2024-03-25T09:06:01.260+01:00  INFO 27991 --- [demo] [    Test worker] com.example.demo.DemoApplicationTests    : No active profile set, falling back to 1 default profile: "default"
2024-03-25T09:06:01.577+01:00  WARN 27991 --- [demo] [    Test worker] trationDelegate$BeanPostProcessorChecker : Bean 'containerLogsSelector' of type [com.example.demo.ContainerLogsSelector$$SpringCGLIB$$0] is not eligible for getting processed by all BeanPostProcessors (for example: not eligible for auto-proxying). The currently created BeanPostProcessor [containerLogsBeanPostProcessor] is declared through a non-static factory method on that class; consider declaring it as static instead.
2024-03-25T09:06:01.611+01:00  INFO 27991 --- [demo] [    Test worker] org.testcontainers.images.PullPolicy     : Image pull policy will be performed by: DefaultPullPolicy()
2024-03-25T09:06:01.613+01:00  INFO 27991 --- [demo] [    Test worker] o.t.utility.ImageNameSubstitutor         : Image name substitution will be performed by: DefaultImageNameSubstitutor (composite of 'ConfigurationFileImageNameSubstitutor' and 'PrefixingImageNameSubstitutor')
2024-03-25T09:06:01.869+01:00  INFO 27991 --- [demo] [    Test worker] o.t.d.DockerClientProviderStrategy       : Found Docker environment with Testcontainers Host with tc.host=tcp://127.0.0.1:60591
2024-03-25T09:06:01.891+01:00  INFO 27991 --- [demo] [    Test worker] org.testcontainers.DockerClientFactory   : Docker host IP address is 127.0.0.1
2024-03-25T09:06:01.922+01:00  INFO 27991 --- [demo] [    Test worker] org.testcontainers.DockerClientFactory   : Connected to docker: 
  Server Version: 25.0.3 (via Testcontainers Desktop 1.8.0)
  API Version: 1.44
  Operating System: Docker Desktop
  Total Memory: 7841 MB
2024-03-25T09:06:01.986+01:00  INFO 27991 --- [demo] [    Test worker] tc.testcontainers/ryuk:0.6.0             : Creating container for image: testcontainers/ryuk:0.6.0
2024-03-25T09:06:02.362+01:00  INFO 27991 --- [demo] [    Test worker] o.t.utility.RegistryAuthLocator          : Credential helper/store (docker-credential-desktop) does not have credentials for https://index.docker.io/v1/
2024-03-25T09:06:02.496+01:00  INFO 27991 --- [demo] [    Test worker] tc.testcontainers/ryuk:0.6.0             : Container testcontainers/ryuk:0.6.0 is starting: 3cf7cb4b13df43103ffc15de6a99510a7cf06212d66050c99b920d41873614c9
2024-03-25T09:06:02.754+01:00  INFO 27991 --- [demo] [    Test worker] tc.testcontainers/ryuk:0.6.0             : Container testcontainers/ryuk:0.6.0 started in PT0.767871S
2024-03-25T09:06:02.759+01:00  INFO 27991 --- [demo] [    Test worker] o.t.utility.RyukResourceReaper           : Ryuk started - will monitor and terminate Testcontainers containers on JVM exit
2024-03-25T09:06:02.759+01:00  INFO 27991 --- [demo] [    Test worker] org.testcontainers.DockerClientFactory   : Checking the system...
2024-03-25T09:06:02.759+01:00  INFO 27991 --- [demo] [    Test worker] org.testcontainers.DockerClientFactory   : ✔︎ Docker server version should be at least 1.6.0
2024-03-25T09:06:02.759+01:00  INFO 27991 --- [demo] [    Test worker] tc.localstack/localstack:3.2.0           : LOCALSTACK_HOST environment variable set to 127.0.0.1 (to match host-routable address for container)
2024-03-25T09:06:02.759+01:00  INFO 27991 --- [demo] [    Test worker] tc.localstack/localstack:3.2.0           : Creating container for image: localstack/localstack:3.2.0
2024-03-25T09:06:03.024+01:00  INFO 27991 --- [demo] [    Test worker] tc.localstack/localstack:3.2.0           : Container localstack/localstack:3.2.0 is starting: db36f0f9e21f27ce119cb106ed3cefe63893166557a01d39109939a3727259a9
localStackContainer | 
localStackContainer | LocalStack version: 3.2.0
localStackContainer | LocalStack Docker container id: db36f0f9e21f
localStackContainer | LocalStack build date: 2024-02-28
localStackContainer | LocalStack build git hash: 4a4692dd5
localStackContainer | 
localStackContainer | 2024-03-25T08:06:05.013  INFO --- [-functhread6] hypercorn.error            : Running on https://0.0.0.0:4566 (CTRL + C to quit)
localStackContainer | 2024-03-25T08:06:05.013  INFO --- [-functhread6] hypercorn.error            : Running on https://0.0.0.0:4566 (CTRL + C to quit)
localStackContainer | 2024-03-25T08:06:05.206  INFO --- [  MainThread] localstack.utils.bootstrap : Execution of "start_runtime_components" took 605.11ms
localStackContainer | Ready.
2024-03-25T09:06:05.220+01:00  INFO 27991 --- [demo] [    Test worker] tc.localstack/localstack:3.2.0           : Container localstack/localstack:3.2.0 started in PT2.460509S
2024-03-25T09:06:10.380+01:00  INFO 27991 --- [demo] [    Test worker] tc.postgres:latest                       : Creating container for image: postgres:latest
2024-03-25T09:06:10.412+01:00  INFO 27991 --- [demo] [    Test worker] tc.postgres:latest                       : Container postgres:latest is starting: fa5daf64644f69fc9b383b5476dde3464496f53139e2160d7d06beaf84bdbae9
postgresContainer | The files belonging to this database system will be owned by user "postgres".
postgresContainer | This user must also own the server process.
postgresContainer | 
postgresContainer | The database cluster will be initialized with locale "en_US.utf8".
postgresContainer | The default database encoding has accordingly been set to "UTF8".
postgresContainer | The default text search configuration will be set to "english".
postgresContainer | 
postgresContainer | Data page checksums are disabled.
postgresContainer | 
postgresContainer | fixing permissions on existing directory /var/lib/postgresql/data ... ok
postgresContainer | creating subdirectories ... ok
postgresContainer | selecting dynamic shared memory implementation ... posix
postgresContainer | selecting default max_connections ... 100
postgresContainer | selecting default shared_buffers ... 128MB
postgresContainer | selecting default time zone ... Etc/UTC
postgresContainer | creating configuration files ... ok
postgresContainer | running bootstrap script ... ok
postgresContainer | performing post-bootstrap initialization ... ok
postgresContainer | syncing data to disk ... ok
postgresContainer | 
postgresContainer | 
postgresContainer | Success. You can now start the database server using:
postgresContainer | 
postgresContainer |     pg_ctl -D /var/lib/postgresql/data -l logfile start
postgresContainer | 
postgresContainer | initdb: warning: enabling "trust" authentication for local connections
postgresContainer | initdb: hint: You can change this by editing pg_hba.conf or using the option -A, or --auth-local and --auth-host, the next time you run initdb.
postgresContainer | waiting for server to start....2024-03-25 08:06:11.036 UTC [48] LOG:  starting PostgreSQL 16.0 (Debian 16.0-1.pgdg120+1) on aarch64-unknown-linux-gnu, compiled by gcc (Debian 12.2.0-14) 12.2.0, 64-bit
postgresContainer | 2024-03-25 08:06:11.036 UTC [48] LOG:  listening on Unix socket "/var/run/postgresql/.s.PGSQL.5432"
postgresContainer | 2024-03-25 08:06:11.038 UTC [51] LOG:  database system was shut down at 2024-03-25 08:06:10 UTC
postgresContainer | 2024-03-25 08:06:11.040 UTC [48] LOG:  database system is ready to accept connections
postgresContainer |  done
postgresContainer | server started
postgresContainer | CREATE DATABASE
postgresContainer | 
postgresContainer | 
postgresContainer | /usr/local/bin/docker-entrypoint.sh: ignoring /docker-entrypoint-initdb.d/*
postgresContainer | 
postgresContainer | waiting for server to shut down....2024-03-25 08:06:11.194 UTC [48] LOG:  received fast shutdown request
postgresContainer | 2024-03-25 08:06:11.194 UTC [48] LOG:  aborting any active transactions
postgresContainer | 2024-03-25 08:06:11.195 UTC [48] LOG:  background worker "logical replication launcher" (PID 54) exited with exit code 1
postgresContainer | 2024-03-25 08:06:11.195 UTC [49] LOG:  shutting down
postgresContainer | 2024-03-25 08:06:11.195 UTC [49] LOG:  checkpoint starting: shutdown immediate
postgresContainer | 2024-03-25 08:06:11.201 UTC [49] LOG:  checkpoint complete: wrote 923 buffers (5.6%); 0 WAL file(s) added, 0 removed, 0 recycled; write=0.006 s, sync=0.001 s, total=0.006 s; sync files=0, longest=0.000 s, average=0.000 s; distance=4257 kB, estimate=4257 kB; lsn=0/1913040, redo lsn=0/1913040
postgresContainer | 2024-03-25 08:06:11.204 UTC [48] LOG:  database system is shut down
postgresContainer |  done
postgresContainer | server stopped
postgresContainer | 
postgresContainer | PostgreSQL init process complete; ready for start up.
postgresContainer | 
postgresContainer | 2024-03-25 08:06:11.308 UTC [1] LOG:  starting PostgreSQL 16.0 (Debian 16.0-1.pgdg120+1) on aarch64-unknown-linux-gnu, compiled by gcc (Debian 12.2.0-14) 12.2.0, 64-bit
postgresContainer | 2024-03-25 08:06:11.308 UTC [1] LOG:  listening on IPv4 address "0.0.0.0", port 5432
postgresContainer | 2024-03-25 08:06:11.308 UTC [1] LOG:  listening on IPv6 address "::", port 5432
postgresContainer | 2024-03-25 08:06:11.308 UTC [1] LOG:  listening on Unix socket "/var/run/postgresql/.s.PGSQL.5432"
postgresContainer | 2024-03-25 08:06:11.310 UTC [64] LOG:  database system was shut down at 2024-03-25 08:06:11 UTC
postgresContainer | 2024-03-25 08:06:11.312 UTC [1] LOG:  database system is ready to accept connections
2024-03-25T09:06:11.319+01:00  INFO 27991 --- [demo] [    Test worker] tc.postgres:latest                       : Container postgres:latest started in PT0.939045S

Enable containers debug ​

Most (or maybe each?) containers can be configured to output more detailed logs. Testcontainers do not offer a simple API to switch them on, but with a little bit of googling we can find flags or environment variables to set in each type of container.

Since in this example I'm using only Postgres and LocalStack, I'll focus on them.

LocalStack Debug ​

To enable debug logs in LocalStack container, we must set environment variable DEBUG to 1:

java
new LocalStackContainer(DockerImageName.parse("localstack/localstack:3.2.0"))
    .withEnv("DEBUG", "1");

Postgres Debug ​

In Postgres, what to log gets configured through startup command parameters (explained in How to log PostgreSQL queries with Testcontainers ):

java
var postgres = new PostgreSQLContainer<>(DockerImageName.parse("postgres:latest"));
postgres.setCommand("postgres", "-c", "fsync=off", "-c", "log_statement=all");

Container debug logs in BeanPostProcessor ​

Let's make ContainerLogsBeanPostProcessor smarter, and add these flags depending on our needs:

java
public class ContainerLogsBeanPostProcessor implements BeanPostProcessor {
    private final boolean debug;

    public ContainerLogsBeanPostProcessor(boolean debug) {
        this.debug = debug;
    }

    @Override
    public Object postProcessBeforeInitialization(Object bean, String beanName) throws BeansException {
        if (bean instanceof Container<?> container) {
            var logConsumer = new StdOutConsumer(beanName);
            container.withLogConsumer(logConsumer);

            if (debug) {
                if (container instanceof PostgreSQLContainer<?> postgres) {
                    postgres.setCommand("postgres", "-c", "fsync=off", "-c", "log_statement=all");
                } else if (container instanceof LocalStackContainer localstack) {
                    localstack.withEnv("DEBUG", "1");
                }
            }
        }
        return bean;
    }
}

Declarative @EnableContainerLogging ​

Right now to enable container logs we need to declare a bean:

java
@Bean
ContainerLogsBeanPostProcessor containerLogsBeanPostProcessor() {
    return new ContainerLogsBeanPostProcessor(true);
}

While this is not bad, we can do better and make it feel more spring-like. I am sure you are familiar with @EnableAsync and @EnableScheduling from Spring Framework. We can leverage the same Spring infrastructure to create @EnableContainerLogs annotations.

On the annotation level, we want to be able to enable/disable container debug, so the usage would look like:

java
@EnableContainerLogs(debug = true)
class AppTests {
    // ...
}

The annotation will be meta-annotated with @Import, to import the ContainerLogsBeanPostProcessor bean:

java
@Target(ElementType.TYPE)
@Retention(RetentionPolicy.RUNTIME)
@Documented
@Inherited
@Import(ContainerLogsConfiguration.class)
public @interface EnableContainerLogs {
    boolean debug() default false;
}

... and the basic configuration class:

java
@TestConfiguration
public class ContainerLogsConfiguration {

    @Bean
    ContainerLogsBeanPostProcessor containerLogsBeanPostProcessor() {
        return new ContainerLogsBeanPostProcessor(???);
    }
}

But how to access EnableContainerLogs#debug() from the configuration class?

ImportAware Configuration ​

This is one of the lesser known Spring trick. To make @Configuration class aware of the annotation that imported it, and as a result get access to annotation properties, you can make the configuration class implement ImportAware:

java
@TestConfiguration
public class ContainerLogsConfiguration implements ImportAware {

    private AnnotationAttributes enableContainerLogs;

    @Override
    public void setImportMetadata(AnnotationMetadata importMetadata) {
        this.enableContainerLogs = AnnotationAttributes.fromMap(
                importMetadata.getAnnotationAttributes(EnableContainerLogs.class.getName()));
    }

    @Bean
    ContainerLogsBeanPostProcessor containerLogsBeanPostProcessor() {
        var debug = this.enableContainerLogs.getBoolean("debug");
        return new ContainerLogsBeanPostProcessor(debug);
    }
}

Summary ​

When things stop working for unknown reasons, being able to see detailed logs can help to solve the problem.

Declarative @EnableContainerLogs is very convenient, but if you feel like it is too much code in your code base you can just use Testcontainers API directly.

Even if you decide not to use this annotation, I hope you've learned something about how to build Spring-Magic-Like @EnableXXX annotations and you will make a good use of it!

Complete code is available on Github: https://github.com/maciejwalkowiak/springboot-testcontainers-container-logs-demo.

Feel free to drop a comment if you found any mistake or have a question. Also, feel free to reach out to me on twitter.com/maciejwalkowiak.

Let's stay in touch and follow me on Twitter: @maciejwalkowiak

Subscribe to RSS feed