Skip to content

LogMessageWaitStrategy for PostgreSQLContainer times out #455

Closed
Closed
LogMessageWaitStrategy for PostgreSQLContainer times out#455
Labels
client/docker-for-windowsmodules/jdbcresolution/acknowledgedtype/bug

Description

@gbtec-markusmeier
gbtec-markusmeier
opened on Sep 14, 2017

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.

Activity

  1. kiview commented on Sep 14, 2017

    @kiview
    kiview
    on Sep 14, 2017
    Member

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

  2. gbtec-markusmeier commented on Sep 14, 2017

    @gbtec-markusmeier
    gbtec-markusmeier
    on Sep 14, 2017
    Author

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

  3. kiview commented on Sep 14, 2017

    @kiview
    kiview
    on Sep 14, 2017
    Member

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

  4. ingogriebsch commented on Sep 29, 2017

    @ingogriebsch
    ingogriebsch
    on Sep 29, 2017

    @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. :)

  5. kiview commented on Sep 30, 2017

    @kiview
    kiview
    on Sep 30, 2017
    Member

    @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.

  6. kiview commented on Oct 2, 2017

    @kiview
    kiview
    on Oct 2, 2017
    Member

    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,

  7. ingogriebsch commented on Oct 6, 2017

    @ingogriebsch
    ingogriebsch
    on Oct 6, 2017

    @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.

  8. gbtec-markusmeier commented on Oct 10, 2017

    @gbtec-markusmeier
    gbtec-markusmeier
    on Oct 10, 2017
    Author

    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
  9. gbtec-markusmeier
    changed the title [-]LogMessageWaitStrategy for PostgreSQLContainer times out on Windows machines[/-] [+]LogMessageWaitStrategy for PostgreSQLContainer times[/+] on Oct 14, 2017

  10. gbtec-markusmeier commented on Oct 14, 2017

    @gbtec-markusmeier
    gbtec-markusmeier
    on Oct 14, 2017
    Author

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

  11. gbtec-markusmeier
    changed the title [-]LogMessageWaitStrategy for PostgreSQLContainer times[/-] [+]LogMessageWaitStrategy for PostgreSQLContainer times out[/+] on Oct 14, 2017

  12. kiview commented on Oct 14, 2017

    @kiview
    kiview
    on Oct 14, 2017
    Member

    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.

  13. rnorth commented on Oct 16, 2017

    @rnorth
    rnorth
    on Oct 16, 2017
    Member

    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?

  14. gbtec-markusmeier commented on Oct 17, 2017

    @gbtec-markusmeier
    gbtec-markusmeier
    on Oct 17, 2017
    Author

    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?

  15. kiview commented on Oct 17, 2017

    @kiview
    kiview
    on Oct 17, 2017
    Member

    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?

  16. 23 remaining items

  17. kiview
    closed this as completedon Oct 9, 2018
  18. danoost
    added a commit that references this issue on Mar 3, 2021

    Potential fix for tests in Actions occasionally failing.

    f8d8a9f

  19. SgtSilvio commented on Sep 18, 2022

    @SgtSilvio
    SgtSilvio
    on Sep 18, 2022
    Contributor

    This problem is very likely caused by #5843

  20. SgtSilvio
    added 3 commits that reference this issue on Sep 18, 2022

    Fixes testcontainers#5843: log consumers are now called with exactly …

    3c8eb12

    Fixes testcontainers#5843: log consumers are now called with exactly …

    53fa80d

    Fixes testcontainers#5843: log consumers are now called with exactly …

    e4842f8
  21. SgtSilvio
    added 6 commits that reference this issue on Oct 4, 2022

    Fixes testcontainers#5843: log consumers are now called with exactly …

    1b43161

    Fixes testcontainers#5843: log consumers are now called with exactly …

    f52e799

    Fixes testcontainers#5843: log consumers are now called with exactly …

    96df082

    Fixes testcontainers#5843: log consumers are now called with exactly …

    74df6d1

    Fixes testcontainers#5843: log consumers are now called with exactly …

    342d669

    Fixes testcontainers#5843: log consumers are now called with exactly …

    fc4a7f5
  22. SgtSilvio
    added a commit that references this issue on Nov 2, 2022

    Fixes testcontainers#5843: log consumers are now called with exactly …

    164882a
  23. SgtSilvio
    added 2 commits that reference this issue on Jan 16, 2023

    Fixes testcontainers#5843: log consumers are now called with exactly …

    9d79384

    Fixes testcontainers#5843: log consumers are now called with exactly …

    15dcf98
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Metadata

Metadata

Assignees

No one assigned

    Labels

    client/docker-for-windowsmodules/jdbcresolution/acknowledgedtype/bug

    Type

    No type

    Projects

    No projects

      Milestone

      No milestone

      Relationships

      None yet

      Development

      No branches or pull requests

      Issue actions