Skip to content

Postgres JDBC 42.0.0 produces tons of error logs on container startup #317

Description

@mihhail-lapushkin
2017-03-24 18:56:50.647 ERROR --- [      pool-3-thread-2] o.p.Driver                               : Connection error: 
org.postgresql.util.PSQLException: The connection attempt failed.
	at org.postgresql.core.v3.ConnectionFactoryImpl.openConnectionImpl(ConnectionFactoryImpl.java:275) ~[postgresql-42.0.0.jar:42.0.0]
	at org.postgresql.core.ConnectionFactory.openConnection(ConnectionFactory.java:49) ~[postgresql-42.0.0.jar:42.0.0]
	at org.postgresql.jdbc.PgConnection.<init>(PgConnection.java:194) ~[postgresql-42.0.0.jar:42.0.0]
	at org.postgresql.Driver.makeConnection(Driver.java:431) ~[postgresql-42.0.0.jar:42.0.0]
	at org.postgresql.Driver.connect(Driver.java:247) ~[postgresql-42.0.0.jar:42.0.0]
	at org.testcontainers.containers.JdbcDatabaseContainer.lambda$createConnection$2(JdbcDatabaseContainer.java:123) ~[jdbc-1.2.0.jar:?]
	at org.rnorth.ducttape.unreliables.Unreliables.lambda$retryUntilSuccess$0(Unreliables.java:41) ~[duct-tape-1.0.6.jar:?]
	at java.util.concurrent.FutureTask.run(FutureTask.java:266) [?:1.8.0_121]
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142) [?:1.8.0_121]
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) [?:1.8.0_121]
	at java.lang.Thread.run(Thread.java:745) [?:1.8.0_121]
Caused by: java.io.EOFException
	at org.postgresql.core.PGStream.receiveChar(PGStream.java:284) ~[postgresql-42.0.0.jar:42.0.0]
	at org.postgresql.core.v3.ConnectionFactoryImpl.doAuthentication(ConnectionFactoryImpl.java:418) ~[postgresql-42.0.0.jar:42.0.0]
	at org.postgresql.core.v3.ConnectionFactoryImpl.openConnectionImpl(ConnectionFactoryImpl.java:222) ~[postgresql-42.0.0.jar:42.0.0]
	... 10 more

With 9.4.1212 they are produced as well, but not logged.

Probably this change made them appear by default with some logging configurations:
https://www.postgresql.org/about/news/1736/

java.util.logging is now used for logging: logging documentation

Is it something that could be fixed on your side or I should just disable all logging for PG driver?
Feels, like a bad idea...

Activity

  1. changed the title [-]Postgres JDBC 42.0.0 produces tons of errors on container startup[/-] [+]Postgres JDBC 42.0.0 produces tons of error logs on container startup[/+] on Mar 24, 2017
  2. rnorth commented on Apr 1, 2017

    @rnorth
    Member

    Hi @mihhail-lapushkin
    That sounds unfortunate - logging is always more difficult than it should be :(
    Part of the problem is that testcontainers tries to establish a connection pretty aggressively during container startup. We could reduce the frequency of retries, but you're still going to receive some of these error logs.

    I think you're probably going to need to adjust the logging, really, but it's not exactly good that your only option seems to be to disable all driver logging... I wonder if anybody else has any ideas?

    Richard

  3. gesellix commented on Apr 1, 2017

    @gesellix
    Contributor

    Could the aggressive connection retries be replaced by a more specific "up and running" check? I'm thinking of the Docker healthcheck feature, though it alone won't really fix anything. The actual fix would be to use a PostgreSQL specific check. Does it provide some built in feature?

  4. kiview commented on Apr 2, 2017

    @kiview
    Member

    I've recently talked with rhuss, one of the authors of the docker-maven-plugin, since they of course face similar problems, in checking the up state of a container. He said they've gotten the best results by checking the containers's log output for a message, indicating a successful startup.

    This of course very much depends on container's implementation, but maybe we could simply allow the usage of a LogOutputWaitStrategy?

    @gesellix Postgres distributes a pg_isready client executable, we could launch a different container containing this executable and connect it to the postgres container. I wonder how I generic approach would look in this case, something like ExternalContainerWaitStrategy maybe?

  5. gesellix commented on Apr 2, 2017

    @gesellix
    Contributor

    @kiview how does pg_isready work? I assume it also somehow needs to perform requests to the PG server and handle potential connectivity errors gracefully.

    Either way: one needs to decide whether a more generic approach (watching log output) vs. highly specific solutions (using or simulating pg_isready) is preferred. Maybe both options should be possible and the user needs to decide?

  6. kiview commented on Apr 2, 2017

    @kiview
    Member

    pg_isready simply returns different exit codes. So we'd have to loop the call until 0 is returned. It also need network connectivity to the database. https://www.postgresql.org/docs/9.3/static/app-pg-isready.html

    I think we already planned to refactor the JdbcContainers to favor composition over inheritance, which would allow us, to specify the WaitStrategy for these specialized containers in a more decoupled way I've think. I already did some prototype work to extract the current wait behavior into a JdbcWaitStrategy:
    https://github.com/testcontainers/testcontainers-spock/blob/jdbc-wait/src/main/groovy/com/groovycoder/spockdockerextension/wait/JdbcWaitStrategy.groovy
    However this implementation would of course throw the same exceptions.

    Currently I'd prefer to implement a LogOutputWaitStrategy based solution and also make this available for GenericContainer.

  7. gesellix commented on Apr 2, 2017

    @gesellix
    Contributor

    I would also start with a generic/log based solution - specific ones can always be built on top.

  8. kiview commented on Apr 2, 2017

    @kiview
    Member

    I'll start working on LogWaitStrategy we can use for GenericContainers then. Afterwards we have to look into PostgresContainer how to be incorperate the new wait strategy. We wanted to refactor this after all, so I assume this approach is fine?

  9. rnorth commented on Apr 2, 2017

    @rnorth
    Member

    @kiview This sounds good to me, though we're really aiming to make the inheritance->composition transition at the same time as general breaking API changes for v2.0. If it can be done and make things better without changing the API for users right now, that'd be great!

    We collectively need to discuss the v2.0 API changes and composition model, and I'd really appreciate your input on that - it's something we should all talk about soon.

    For the LogWaitStrategy I hope you might get some value/reuse out of WaitingConsumer, if you've not already come across that!

  10. kiview commented on Apr 2, 2017

    @kiview
    Member

    WaitingConsumer looks like a good match for this task, it's currently only used for internal testing, right?

    I'll start with the LogWaitStrategy for GenericContainer and see if I can incorporate it into JdbcDatabaseContainer or PostgreSQLContainer without breaking anything.

  11. asafm commented on Apr 4, 2017

    @asafm
    Contributor
  12. kiview commented on Apr 7, 2017

    @kiview
    Member

    I assume we don't want to add a production scope HikariCP dependency to testcontainers-postgres.

    When looking into the Postgres log output, I've discovered that the official postgres image will restart once, before being completely ready. We basically see the following output once the database is ready:

    LOG:  database system was shut down at 2017-04-07 17:01:42 UTC
    LOG:  MultiXact member wraparound protections are now enabled
    LOG:  autovacuum launcher started
    LOG:  database system is ready to accept connections
     done
    server started
    ALTER ROLE
    
    /usr/local/bin/docker-entrypoint.sh: ignoring /docker-entrypoint-initdb.d/*
    
    LOG:  received fast shutdown request
    LOG:  aborting any active transactions
    waiting for server to shut down....LOG:  autovacuum launcher shutting down
    LOG:  shutting down
    LOG:  database system is shut down
     done
    server stopped
    
    PostgreSQL init process complete; ready for start up.
    
    LOG:  database system was shut down at 2017-04-07 17:01:43 UTC
    LOG:  MultiXact member wraparound protections are now enabled
    LOG:  autovacuum launcher started
    LOG:  database system is ready to accept connections
    

    This means a simple logline based approach won't cut it, we need multiple occurrences of database system is ready to accept connections.

  13. kiview commented on Apr 8, 2017

    @kiview
    Member

    Seems they've discovered the same problem in the docker-maven plugin and added multiline log matching:
    fabric8io/docker-maven-plugin#628
    fabric8io/docker-maven-plugin#743

  14. added a commit that references this issue on Apr 30, 2017
    36613b8
  15. laurikimmel commented on Apr 8, 2018

    @laurikimmel

    @kiview thanks for the hint.

    We had similar long standing issue with Postgres image in our own code base. We are using TCP probe for waiting strategy - with sensible timeouts trying to open connection to expected service port. Once successful service is considered up and running. Only problem we have seen so far was with Postgres container while running on Linux. At the same time it was working fine on MacOS and Windows.

    I didn't realise the root cause was inside the container before seeing your comment above. Fix was quite simple. Wait bit more for Postgres - until n successful probes in a row.

    Btw. we would like to migrate to testcontainers once TestNG is supported.

  16. kiview commented on Apr 9, 2018

    @kiview
    Member

    Hey @laurikimmel, great that this information could help.
    Please see this comment in #132, you can already use Testcontainers in TestNG (and in general even outside of any test frameworks) if you start and stop containers manually (and still benefit from additional Testcontainers features such as WaitStrategies).

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

    No labels
    No labels

    Type

    No type

    Projects

    No projects

      Milestone

      No milestone

      Relationships

      None yet

      Development

      No branches or pull requests

      Issue actions