[Bug]: testcontainers-postgresql wait strategy invalid when persistent volume is set

[ZIRAKrezovic]

Module

PostgreSQL

Testcontainers version

1.19.3

Using the latest Testcontainers version?

Yes

Host OS

Windows

Host Arch

x86

Docker version

Client:
 Version:           24.0.2-rd
 API version:       1.42 (downgraded from 1.43)
 Go version:        go1.20.4
 Git commit:        e63f5fa
 Built:             Fri May 26 16:43:15 2023
 OS/Arch:           windows/amd64
 Context:           default

Server:
 Engine:
  Version:          23.0.6
  API version:      1.42 (minimum version 1.12)
  Go version:       go1.20.4
  Git commit:       9dbdbd4b6d7681bd18c897a6ba0376073c2a72ff
  Built:            Fri May 12 13:54:36 2023
  OS/Arch:          linux/amd64
  Experimental:     false
 containerd:
  Version:          v1.7.2
  GitCommit:        0cae528dd6cb557f7201036e9f43420650207b58
 runc:
  Version:          1.1.7
  GitCommit:        860f061b76bb4fc671f0f9e900f7d80ff93d4eb7
 docker-init:
  Version:          0.19.0
  GitCommit:

What happened?

When I mount a persistent volume to the PostgreSQL container at /var/lib/postgresql/data, all subsequent startups will fail with error

Caused by: org.testcontainers.containers.ContainerLaunchException: Timed out waiting for log output matching '.*database system is ready to accept connections.*\s'

When observing docker logs, the following is shown for fresh container

The files belonging to this database system will be owned by user "postgres".
This user must also own the server process.

The database cluster will be initialized with locale "en_US.utf8".
The default database encoding has accordingly been set to "UTF8".
The default text search configuration will be set to "english".

Data page checksums are disabled.

fixing permissions on existing directory /var/lib/postgresql/data ... ok
creating subdirectories ... ok
selecting dynamic shared memory implementation ... posix
selecting default max_connections ... 100
selecting default shared_buffers ... 128MB
selecting default time zone ... UTC
creating configuration files ... ok
running bootstrap script ... ok
sh: locale: not found
2023-12-20 14:25:43.715 UTC [30] WARNING:  no usable system locales were found
performing post-bootstrap initialization ... ok
syncing data to disk ... ok


Success. You can now start the database server using:

    pg_ctl -D /var/lib/postgresql/data -l logfile start

initdb: warning: enabling "trust" authentication for local connections
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.
waiting for server to start....2023-12-20 14:25:44.080 UTC [36] LOG:  starting PostgreSQL 16.1 on x86_64-pc-linux-musl, compiled by gcc (Alpine 13.2.1_git20231014) 13.2.1 20231014, 64-bit
2023-12-20 14:25:44.081 UTC [36] LOG:  listening on Unix socket "/var/run/postgresql/.s.PGSQL.5432"
2023-12-20 14:25:44.082 UTC [39] LOG:  database system was shut down at 2023-12-20 14:25:43 UTC
2023-12-20 14:25:44.084 UTC [36] LOG:  database system is ready to accept connections
 done
server started
CREATE DATABASE


/usr/local/bin/docker-entrypoint.sh: ignoring /docker-entrypoint-initdb.d/*

waiting for server to shut down....2023-12-20 14:25:44.201 UTC [36] LOG:  received fast shutdown request
2023-12-20 14:25:44.201 UTC [36] LOG:  aborting any active transactions
2023-12-20 14:25:44.202 UTC [36] LOG:  background worker "logical replication launcher" (PID 42) exited with exit code 1
2023-12-20 14:25:44.202 UTC [37] LOG:  shutting down
2023-12-20 14:25:44.202 UTC [37] LOG:  checkpoint starting: shutdown immediate
2023-12-20 14:25:44.206 UTC [37] LOG:  checkpoint complete: wrote 925 buffers (5.6%); 0 WAL file(s) added, 0 removed, 0 recycled; write=0.005 s, sync=0.001 s, total=0.005 s; sync files=0, longest=0.000 s, average=0.000 s; distance=4269 kB, estimate=4269 kB; lsn=0/191BA30, redo lsn=0/191BA30
2023-12-20 14:25:44.209 UTC [36] LOG:  database system is shut down
 done
server stopped

PostgreSQL init process complete; ready for start up.

2023-12-20 14:25:44.313 UTC [1] LOG:  starting PostgreSQL 16.1 on x86_64-pc-linux-musl, compiled by gcc (Alpine 13.2.1_git20231014) 13.2.1 20231014, 64-bit
2023-12-20 14:25:44.314 UTC [1] LOG:  listening on IPv4 address "0.0.0.0", port 5432
2023-12-20 14:25:44.314 UTC [1] LOG:  listening on IPv6 address "::", port 5432
2023-12-20 14:25:44.314 UTC [1] LOG:  listening on Unix socket "/var/run/postgresql/.s.PGSQL.5432"
2023-12-20 14:25:44.315 UTC [52] LOG:  database system was shut down at 2023-12-20 14:25:44 UTC
2023-12-20 14:25:44.316 UTC [1] LOG:  database system is ready to accept connections

When observing docker logs for a container that starts with pre-existing database

PostgreSQL Database directory appears to contain a database; Skipping initialization

2023-12-20 14:27:21.144 UTC [1] LOG:  starting PostgreSQL 16.1 on x86_64-pc-linux-musl, compiled by gcc (Alpine 13.2.1_git20231014) 13.2.1 20231014, 64-bit
2023-12-20 14:27:21.144 UTC [1] LOG:  listening on IPv4 address "0.0.0.0", port 5432
2023-12-20 14:27:21.144 UTC [1] LOG:  listening on IPv6 address "::", port 5432
2023-12-20 14:27:21.144 UTC [1] LOG:  listening on Unix socket "/var/run/postgresql/.s.PGSQL.5432"
2023-12-20 14:27:21.145 UTC [24] LOG:  database system was interrupted; last known up at 2023-12-20 14:25:44 UTC
2023-12-20 14:27:21.145 UTC [24] LOG:  database system was not properly shut down; automatic recovery in progress
2023-12-20 14:27:21.146 UTC [24] LOG:  redo starts at 0/191BAA8
2023-12-20 14:27:21.148 UTC [24] LOG:  invalid record length at 0/19A0218: expected at least 24, got 0
2023-12-20 14:27:21.148 UTC [24] LOG:  redo done at 0/19A01E0 system usage: CPU: user: 0.00 s, system: 0.00 s, elapsed: 0.00 s
2023-12-20 14:27:21.148 UTC [22] LOG:  checkpoint starting: end-of-recovery immediate wait
2023-12-20 14:27:21.150 UTC [22] LOG:  checkpoint complete: wrote 122 buffers (0.7%); 0 WAL file(s) added, 0 removed, 0 recycled; write=0.002 s, sync=0.001 s, total=0.002 s; sync files=0, longest=0.000 s, average=0.000 s; distance=529 kB, estimate=529 kB; lsn=0/19A0218, redo lsn=0/19A0218
2023-12-20 14:27:21.152 UTC [1] LOG:  database system is ready to accept connections

If I test the regex shown above on https://www.freeformatter.com/java-regex-tester.html for first one I get

However, if I test the same regex against second output

Note that in second log output, there is no line after database system is ready to accept connections string. In the first example, it seems to match the middle result

2023-12-20 14:25:44.084 UTC [36] LOG:  database system is ready to accept connections
 done

If I remove final \\s from regex, then it works for already started container.

Edit: It appears that times(2) is problematic, and not the regex itself.

Relevant log output

No response

Additional Information

No response

[ZIRAKrezovic]

Fixed with override

public class PSQLContainer extends PostgreSQLContainer<PSQLContainer> {
    public PSQLContainer(DockerImageName dockerImageName, boolean persistenceEnabled) {
        super(dockerImageName);

        this.waitStrategy =
                new LogMessageWaitStrategy()
                        .withRegEx(".*database system is ready to accept connections.*\\s")
                        .withTimes(persistenceEnabled ? 1 : 2)
                        .withStartupTimeout(Duration.of(60, ChronoUnit.SECONDS));
    }
}

If persistence is not supposed to work, simply close the bug.

[eddumelendez]

Duplicate #5359

[ZIRAKrezovic]

Alternative wait strategy that mostly seems to work just fine most of the time, just a bit more noisy on the container logs

public class PSQLContainer extends PostgreSQLContainer<PSQLContainer> {
    public PSQLContainer(DockerImageName dockerImageName) {
        super(dockerImageName);

        this.waitStrategy =
                new ShellStrategy()
                        .withCommand(
                                "psql -q -o /dev/null -c \"SELECT 1\" -d $POSTGRES_DB -U $POSTGRES_USER")
                        .withStartupTimeout(Duration.of(60, ChronoUnit.SECONDS));
    }
}

In case somebody needs it.

[lfvjimisola]

Same experience. Went the same path as @ZIRAKrezovic, i.e. checking if regexp matched log output.

The bind mount is needed for example with more strict K8s such as OpenShift.

It would be really great if this bug was fixed since it's just a simple change in the reg exp.