LogMessageWaitStrategy for PostgreSQLContainer times out

[gbtec-markusmeier]

When waiting for Postgres to start up, PostgreSQLContainer looks for the String ".*database system is ready to accept connections.*\\s".

The database though has already started when PostgreSQLContainer is ready for waiting and thus will never find the String.

This issues seems to appear only on Windows machines - on Linux it was not observable.

The new PostgreSQLContainer wait behaviour was introduced in #327.

[kiview]

Is this String not logged on Windows machines? This String should normally be logged two times before the database is ready.

[gbtec-markusmeier]

Yes, it is logged. It already came twice when PostgreSQLContainer starts waiting.

[kiview]

Ok, so that sounds like some race condition regarding the LogMessageWaitStrategy and might not be a PostgreSQLContainer (or Windows) specific problem.

[ingogriebsch]

@kiview Would like to ask if one can expect a fix for this bug in the near future? We are developing mostly on Windows machines and heavily using testcontainers in our services. Even if we have a little workaround it would be nice to get this issue solved. Don't know if it is also possible to support you in some way but if, we at least need to get some details explained. :)

[kiview]

@gbtec-ingogriebsch Since it might involve a race condition (which should be platform independent?), I don't know when it will be fixed. It would help to find this bug on Linux as well.

I'll be home next week (and I have a Windows 10 box at home) and I'll try to look into the problem.

[kiview]

Can someone share a project demonstrating this problem?

I just ran SimplePostgreSQLTest on my Windows 10 Pro 1703 with Docker 17.09.0 CE and starting the postgres container seems to work fine.

I see the following error in my console, the test succeeds however:

Okt 02, 2017 4:17:22 PM org.postgresql.Driver connect
SCHWERWIEGEND: Connection error: 
org.postgresql.util.PSQLException: Der Verbindungsversuch schlug fehl.
	at org.postgresql.core.v3.ConnectionFactoryImpl.openConnectionImpl(ConnectionFactoryImpl.java:275)
	at org.postgresql.core.ConnectionFactory.openConnection(ConnectionFactory.java:49)
	at org.postgresql.jdbc.PgConnection.<init>(PgConnection.java:194)
	at org.postgresql.Driver.makeConnection(Driver.java:431)
	at org.postgresql.Driver.connect(Driver.java:247)
	at com.zaxxer.hikari.util.DriverDataSource.getConnection(DriverDataSource.java:92)
	at com.zaxxer.hikari.util.DriverDataSource.getConnection(DriverDataSource.java:98)
	at com.zaxxer.hikari.pool.BaseHikariPool.addConnection(BaseHikariPool.java:438)
	at com.zaxxer.hikari.pool.BaseHikariPool$1.run(BaseHikariPool.java:413)
	at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
	at java.util.concurrent.FutureTask.run(FutureTask.java:266)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
	at java.lang.Thread.run(Thread.java:745)
Caused by: java.io.EOFException
	at org.postgresql.core.PGStream.receiveChar(PGStream.java:284)
	at org.postgresql.core.v3.ConnectionFactoryImpl.doAuthentication(ConnectionFactoryImpl.java:418)
	at org.postgresql.core.v3.ConnectionFactoryImpl.openConnectionImpl(ConnectionFactoryImpl.java:222)
	... 13 more

I think this happens when the container is shutting down, so nothing too bad.

Edit:
Indeed, happens when closing. Adding a ds.close() statement to the end of the test circumvents the error,

[ingogriebsch]

@kiview I'm using Docker for Windows, Version 17.06.1-ce-win24 (13025). I have not yet updated to Version 17.09.0-ce-win32 (13529). We will check if the problem is maybe solved if using the latest docker version.

And we can provide a simple test project for the problem we are having at the moment. But it will include nothing else as a Spring Boot app which has configured the postgres testcontainer triggered through the 'special' jdbc url.

[gbtec-markusmeier]

The result of https://github.com/testcontainers/testcontainers-java/blob/master/modules/jdbc-test/src/test/java/org/testcontainers/junit/SimplePostgreSQLTest.java on my machine:

13:21:08.851 DEBUG 🐳 [postgres:latest] - Starting container: postgres:latest
13:21:08.852 DEBUG 🐳 [postgres:latest] - Trying to start container: postgres:latest
13:21:08.852 DEBUG 🐳 [postgres:latest] - Trying to start container: postgres:latest (attempt 1/1)
13:21:08.852 DEBUG 🐳 [postgres:latest] - Starting container: postgres:latest
13:21:08.852 INFO  🐳 [postgres:latest] - Creating container for image: postgres:latest
13:21:09.037 INFO  🐳 [postgres:latest] - Starting container with ID: 3bed081e31e630abe1e97560afb3510013eaf84603541e58c4a6d36d0f7f3494
13:21:09.375 INFO  🐳 [postgres:latest] - Container postgres:latest is starting: 3bed081e31e630abe1e97560afb3510013eaf84603541e58c4a6d36d0f7f3494
13:22:09.467 ERROR 🐳 [postgres:latest] - Could not start container
org.testcontainers.containers.ContainerLaunchException: Timed out waiting for log output matching '.*database system is ready to accept connections.*\s'
	at org.testcontainers.containers.wait.LogMessageWaitStrategy.waitUntilReady(LogMessageWaitStrategy.java:31)
	at org.testcontainers.containers.GenericContainer$AbstractWaitStrategy.waitUntilReady(GenericContainer.java:943)
	at org.testcontainers.containers.PostgreSQLContainer.waitUntilContainerStarted(PostgreSQLContainer.java:92)
	at org.testcontainers.containers.GenericContainer.tryStart(GenericContainer.java:235)
	at org.testcontainers.containers.GenericContainer.lambda$start$0(GenericContainer.java:184)
	at org.rnorth.ducttape.unreliables.Unreliables.retryUntilSuccess(Unreliables.java:76)
	at org.testcontainers.containers.GenericContainer.start(GenericContainer.java:182)
	at org.testcontainers.containers.GenericContainer.starting(GenericContainer.java:544)
	at org.testcontainers.containers.FailureDetectingExternalResource$1.evaluate(FailureDetectingExternalResource.java:29)
	at org.junit.rules.RunRules.evaluate(RunRules.java:20)
	at org.junit.runners.ParentRunner.runLeaf(ParentRunner.java:325)
	at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:78)
	at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:57)
	at org.junit.runners.ParentRunner$3.run(ParentRunner.java:290)
	at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:71)
	at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:288)
	at org.junit.runners.ParentRunner.access$000(ParentRunner.java:58)
	at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:268)
	at org.junit.runners.ParentRunner.run(ParentRunner.java:363)
	at org.junit.runner.JUnitCore.run(JUnitCore.java:137)
	at com.intellij.junit4.JUnit4IdeaTestRunner.startRunnerWithArgs(JUnit4IdeaTestRunner.java:68)
	at com.intellij.rt.execution.junit.IdeaTestRunner$Repeater.startRunnerWithArgs(IdeaTestRunner.java:47)
	at com.intellij.rt.execution.junit.JUnitStarter.prepareStreamsAndStart(JUnitStarter.java:242)
	at com.intellij.rt.execution.junit.JUnitStarter.main(JUnitStarter.java:70)
13:22:09.467 ERROR 🐳 [postgres:latest] - Container log output (if any) will follow:
13:22:09.489 INFO  🐳 [postgres:latest] - STDOUT: The files belonging to this database system will be owned by user "postgres".
13:22:09.489 INFO  🐳 [postgres:latest] - STDOUT: This user must also own the server process.
13:22:09.489 INFO  🐳 [postgres:latest] - STDOUT: 
13:22:09.489 INFO  🐳 [postgres:latest] - STDOUT: The database cluster will be initialized with locale "en_US.utf8".
13:22:09.489 INFO  🐳 [postgres:latest] - STDOUT: The default database encoding has accordingly been set to "UTF8".
13:22:09.490 INFO  🐳 [postgres:latest] - STDOUT: The default text search configuration will be set to "english".
13:22:09.490 INFO  🐳 [postgres:latest] - STDOUT: 
13:22:09.490 INFO  🐳 [postgres:latest] - STDOUT: Data page checksums are disabled.
13:22:09.490 INFO  🐳 [postgres:latest] - STDOUT: 
13:22:09.490 INFO  🐳 [postgres:latest] - STDOUT: fixing permissions on existing directory /var/lib/postgresql/data ... ok
13:22:09.490 INFO  🐳 [postgres:latest] - STDOUT: creating subdirectories ... ok
13:22:09.490 INFO  🐳 [postgres:latest] - STDOUT: selecting default max_connections ... 100
13:22:09.490 INFO  🐳 [postgres:latest] - STDOUT: selecting default shared_buffers ... 128MB
13:22:09.490 INFO  🐳 [postgres:latest] - STDOUT: selecting dynamic shared memory implementation ... posix
13:22:09.490 INFO  🐳 [postgres:latest] - STDOUT: creating configuration files ... ok
13:22:09.490 INFO  🐳 [postgres:latest] - STDOUT: running bootstrap script ... ok
13:22:09.491 INFO  🐳 [postgres:latest] - STDOUT: performing post-bootstrap initialization ... ok
13:22:09.491 INFO  🐳 [postgres:latest] - STDERR: 
13:22:09.491 INFO  🐳 [postgres:latest] - STDERR: WARNING: enabling "trust" authentication for local connections
13:22:09.491 INFO  🐳 [postgres:latest] - STDERR: You can change this by editing pg_hba.conf or using the option -A, or
13:22:09.491 INFO  🐳 [postgres:latest] - STDERR: --auth-local and --auth-host, the next time you run initdb.
13:22:09.491 INFO  🐳 [postgres:latest] - STDOUT: syncing data to disk ... ok
13:22:09.491 INFO  🐳 [postgres:latest] - STDOUT: 
13:22:09.492 INFO  🐳 [postgres:latest] - STDOUT: Success. You can now start the database server using:
13:22:09.492 INFO  🐳 [postgres:latest] - STDOUT: 
13:22:09.492 INFO  🐳 [postgres:latest] - STDOUT: pg_ctl -D /var/lib/postgresql/data -l logfile start
13:22:09.492 INFO  🐳 [postgres:latest] - STDOUT: 
13:22:09.492 INFO  🐳 [postgres:latest] - STDOUT: waiting for server to start....2017-10-10 11:21:10.459 UTC [39] LOG:  listening on IPv4 address "127.0.0.1", port 5432
13:22:09.492 INFO  🐳 [postgres:latest] - STDOUT: 2017-10-10 11:21:10.459 UTC [39] LOG:  could not bind IPv6 address "::1": Cannot assign requested address
13:22:09.492 INFO  🐳 [postgres:latest] - STDOUT: 2017-10-10 11:21:10.459 UTC [39] HINT:  Is another postmaster already running on port 5432? If not, wait a few seconds and retry.
13:22:09.492 INFO  🐳 [postgres:latest] - STDOUT: 2017-10-10 11:21:10.465 UTC [39] LOG:  listening on Unix socket "/var/run/postgresql/.s.PGSQL.5432"
13:22:09.493 INFO  🐳 [postgres:latest] - STDOUT: 2017-10-10 11:21:10.479 UTC [40] LOG:  database system was shut down at 2017-10-10 11:21:10 UTC
13:22:09.493 INFO  🐳 [postgres:latest] - STDOUT: 2017-10-10 11:21:10.485 UTC [39] LOG:  database system is ready to accept connections
13:22:09.493 INFO  🐳 [postgres:latest] - STDOUT: done
13:22:09.493 INFO  🐳 [postgres:latest] - STDOUT: server started
13:22:09.494 INFO  🐳 [postgres:latest] - STDOUT: CREATE DATABASE
13:22:09.494 INFO  🐳 [postgres:latest] - STDOUT: 
13:22:09.494 INFO  🐳 [postgres:latest] - STDOUT: CREATE ROLE
13:22:09.494 INFO  🐳 [postgres:latest] - STDOUT: 
13:22:09.494 INFO  🐳 [postgres:latest] - STDOUT: 
13:22:09.494 INFO  🐳 [postgres:latest] - STDOUT: /usr/local/bin/docker-entrypoint.sh: ignoring /docker-entrypoint-initdb.d/*
13:22:09.495 INFO  🐳 [postgres:latest] - STDOUT: 
13:22:09.495 INFO  🐳 [postgres:latest] - STDOUT: waiting for server to shut down....2017-10-10 11:21:10.823 UTC [39] LOG:  received fast shutdown request
13:22:09.495 INFO  🐳 [postgres:latest] - STDOUT: 2017-10-10 11:21:10.827 UTC [39] LOG:  aborting any active transactions
13:22:09.495 INFO  🐳 [postgres:latest] - STDOUT: 2017-10-10 11:21:10.829 UTC [39] LOG:  worker process: logical replication launcher (PID 46) exited with exit code 1
13:22:09.495 INFO  🐳 [postgres:latest] - STDOUT: 2017-10-10 11:21:10.829 UTC [41] LOG:  shutting down
13:22:09.495 INFO  🐳 [postgres:latest] - STDOUT: 2017-10-10 11:21:10.851 UTC [39] LOG:  database system is shut down
13:22:09.495 INFO  🐳 [postgres:latest] - STDOUT: done
13:22:09.496 INFO  🐳 [postgres:latest] - STDOUT: server stopped
13:22:09.496 INFO  🐳 [postgres:latest] - STDOUT: 
13:22:09.496 INFO  🐳 [postgres:latest] - STDOUT: PostgreSQL init process complete; ready for start up.
13:22:09.496 INFO  🐳 [postgres:latest] - STDOUT: 
13:22:09.496 INFO  🐳 [postgres:latest] - STDERR: 2017-10-10 11:21:10.948 UTC [1] LOG:  listening on IPv4 address "0.0.0.0", port 5432
13:22:09.496 INFO  🐳 [postgres:latest] - STDERR: 2017-10-10 11:21:10.948 UTC [1] LOG:  listening on IPv6 address "::", port 5432
13:22:09.497 INFO  🐳 [postgres:latest] - STDERR: 2017-10-10 11:21:10.956 UTC [1] LOG:  listening on Unix socket "/var/run/postgresql/.s.PGSQL.5432"
13:22:09.497 INFO  🐳 [postgres:latest] - STDERR: 2017-10-10 11:21:10.972 UTC [52] LOG:  database system was shut down at 2017-10-10 11:21:10 UTC
13:22:09.497 INFO  🐳 [postgres:latest] - STDERR: 2017-10-10 11:21:10.977 UTC [1] LOG:  database system is ready to accept connections
13:22:10.173 DEBUG org.testcontainers.utility.ResourceReaper - Removed container and associated volume(s): postgres:latest

org.testcontainers.containers.ContainerLaunchException: Container startup failed

	at org.testcontainers.containers.GenericContainer.start(GenericContainer.java:189)
	at org.testcontainers.containers.GenericContainer.starting(GenericContainer.java:544)
	at org.testcontainers.containers.FailureDetectingExternalResource$1.evaluate(FailureDetectingExternalResource.java:29)
	at org.junit.rules.RunRules.evaluate(RunRules.java:20)
	at org.junit.runners.ParentRunner.runLeaf(ParentRunner.java:325)
	at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:78)
	at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:57)
	at org.junit.runners.ParentRunner$3.run(ParentRunner.java:290)
	at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:71)
	at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:288)
	at org.junit.runners.ParentRunner.access$000(ParentRunner.java:58)
	at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:268)
	at org.junit.runners.ParentRunner.run(ParentRunner.java:363)
	at org.junit.runner.JUnitCore.run(JUnitCore.java:137)
	at com.intellij.junit4.JUnit4IdeaTestRunner.startRunnerWithArgs(JUnit4IdeaTestRunner.java:68)
	at com.intellij.rt.execution.junit.IdeaTestRunner$Repeater.startRunnerWithArgs(IdeaTestRunner.java:47)
	at com.intellij.rt.execution.junit.JUnitStarter.prepareStreamsAndStart(JUnitStarter.java:242)
	at com.intellij.rt.execution.junit.JUnitStarter.main(JUnitStarter.java:70)
Caused by: org.rnorth.ducttape.RetryCountExceededException: Retry limit hit with exception
	at org.rnorth.ducttape.unreliables.Unreliables.retryUntilSuccess(Unreliables.java:83)
	at org.testcontainers.containers.GenericContainer.start(GenericContainer.java:182)
	... 17 more
Caused by: org.testcontainers.containers.ContainerLaunchException: Could not create/start container
	at org.testcontainers.containers.GenericContainer.tryStart(GenericContainer.java:256)
	at org.testcontainers.containers.GenericContainer.lambda$start$0(GenericContainer.java:184)
	at org.rnorth.ducttape.unreliables.Unreliables.retryUntilSuccess(Unreliables.java:76)
	... 18 more
Caused by: org.testcontainers.containers.ContainerLaunchException: Timed out waiting for log output matching '.*database system is ready to accept connections.*\s'
	at org.testcontainers.containers.wait.LogMessageWaitStrategy.waitUntilReady(LogMessageWaitStrategy.java:31)
	at org.testcontainers.containers.GenericContainer$AbstractWaitStrategy.waitUntilReady(GenericContainer.java:943)
	at org.testcontainers.containers.PostgreSQLContainer.waitUntilContainerStarted(PostgreSQLContainer.java:92)
	at org.testcontainers.containers.GenericContainer.tryStart(GenericContainer.java:235)
	... 20 more

[gbtec-markusmeier]

It is somewhat environment specific, but seems not to depend on the OS itself. Further investigating.

[kiview]

After additional research, it seems it is not a race condition, since followOutput() will also retrieve old output. However, in the failing environments, followOutput() doesn't seem to return any frames in the callback.

It might be somehow related to docker-java/docker-java#878, not sure though.

[rnorth]

That's not good. Do you think we should revert use of the log-based wait strategy until we can get to the bottom of this?

[gbtec-markusmeier]

I would appreciate that - we need to upgrade to testcontainers 1.4.x to make use of the latest java docker api and the TC_DAEMON parameter. Reverting it to use SELECT 1 would remedy this. But the revert would also re-introduce #317, wouldn't it?

[kiview]

Yes it would, but that's not really an error or a problem, more like verbose logging stuff happening. Other LogMessageWaitStrategy based containers wouldn't work either in this setup.

@rnorth
TBH I'm not sure what to do here right now. I was with @gbtec-markusmeier at the weekend, trying to fix the problem, pinpoint it, work around it, but the behavior regarding the log output was actually happening as soon as we've used logContainerCmd.withFollowStream(true).
So I think the problem might be somewhere in docker-java. I think it's interesting, this problem occurs specifically in the work environment of @gbtec-markusmeier and @gbtec-ingogriebsch, we weren't really able to spot the difference in the setup from which this problem might arise. My last idea was, that it might happen somewhere one the network layer, docker-java not being able to stream the logs.

@gbtec-markusmeier
Maybe we can raise an issue regarding the logContainerCmd.withFollowStream(true) problem in docker-java?