quarkus: [PosgreSQL] JDBCConnectionException: Unable to release JDBC Connection

Describe the bug Unable to release connection using PostgreSQL + 1.1.0.Final/1.1.1.Final AND testcontainers

Expected behavior With 1.0.1.Final, the same integration test (using testcontainers) was working perfectly. Upgrading to 1.1.0.Final makes it break every time.

Actual behavior Running the same integration test (spawning a pg image using testcontainers, running a query, shutting down the test suite) fails with the following exception:

Caused by: org.hibernate.exception.JDBCConnectionException: Unable to release JDBC Connection
	at org.hibernate.exception.internal.SQLStateConversionDelegate.convert(SQLStateConversionDelegate.java:112)
	at org.hibernate.exception.internal.StandardSQLExceptionConverter.convert(StandardSQLExceptionConverter.java:42)
	at org.hibernate.engine.jdbc.spi.SqlExceptionHelper.convert(SqlExceptionHelper.java:113)
	at org.hibernate.engine.jdbc.spi.SqlExceptionHelper.convert(SqlExceptionHelper.java:99)
	at org.hibernate.resource.jdbc.internal.LogicalConnectionManagedImpl.releaseConnection(LogicalConnectionManagedImpl.java:195)
	at org.hibernate.resource.jdbc.internal.LogicalConnectionManagedImpl.afterStatement(LogicalConnectionManagedImpl.java:147)
	at org.hibernate.engine.jdbc.internal.JdbcCoordinatorImpl.afterStatementExecution(JdbcCoordinatorImpl.java:265)
	at org.hibernate.loader.Loader.getResultSet(Loader.java:2298)
	at org.hibernate.loader.Loader.executeQueryStatement(Loader.java:2050)
	at org.hibernate.loader.Loader.executeQueryStatement(Loader.java:2012)
	at org.hibernate.loader.Loader.doQuery(Loader.java:953)
	at org.hibernate.loader.Loader.doQueryAndInitializeNonLazyCollections(Loader.java:354)
	at org.hibernate.loader.Loader.doList(Loader.java:2815)
	at org.hibernate.loader.Loader.doList(Loader.java:2797)
	at org.hibernate.loader.Loader.listIgnoreQueryCache(Loader.java:2629)
	at org.hibernate.loader.Loader.list(Loader.java:2624)
	at org.hibernate.loader.hql.QueryLoader.list(QueryLoader.java:506)
	at org.hibernate.hql.internal.ast.QueryTranslatorImpl.list(QueryTranslatorImpl.java:396)
	at org.hibernate.engine.query.spi.HQLQueryPlan.performList(HQLQueryPlan.java:219)
	at org.hibernate.internal.SessionImpl.list(SessionImpl.java:1396)
	at org.hibernate.query.internal.AbstractProducedQuery.doList(AbstractProducedQuery.java:1558)
	at org.hibernate.query.internal.AbstractProducedQuery.list(AbstractProducedQuery.java:1526)
	... 75 more
Caused by: org.postgresql.util.PSQLException: This connection has been closed.
	at org.postgresql.jdbc.PgConnection.checkClosed(PgConnection.java:782)
	at org.postgresql.jdbc.PgConnection.getWarnings(PgConnection.java:681)
	at io.agroal.pool.ConnectionHandler.resetConnection(ConnectionHandler.java:129)
	at io.agroal.pool.ConnectionPool.returnConnectionHandler(ConnectionPool.java:308)
	at io.agroal.pool.ConnectionHandler.onConnectionWrapperClose(ConnectionHandler.java:100)
	at io.agroal.pool.wrapper.ConnectionWrapper.close(ConnectionWrapper.java:135)
	at org.hibernate.engine.jdbc.connections.internal.DatasourceConnectionProviderImpl.closeConnection(DatasourceConnectionProviderImpl.java:127)
	at org.hibernate.internal.NonContextualJdbcConnectionAccess.releaseConnection(NonContextualJdbcConnectionAccess.java:49)
	at org.hibernate.resource.jdbc.internal.LogicalConnectionManagedImpl.releaseConnection(LogicalConnectionManagedImpl.java:192)
	... 92 more

To Reproduce Steps to reproduce the behavior:

Create a simple service and @Inject an EntityManager
In some method, perform an HQL query and return query.getResultList()
Use this method in a QuarkusTest together with TestContainers

In the logs, I can see:

INFO: Container my-pg-database-full-of-data:latest started in PT10.073976S
janv. 06, 2020 5:33:34 PM org.hibernate.engine.jdbc.spi.SqlExceptionHelper logExceptions
WARN: SQL Error: 0, SQLState: 57P01

57P01 seems to be admin_shutdown, so my guess would be that TestContainers is requesting the container to shut down before the actual quarkus test finishes.

The only thing I changed is Quarkus version, code didn’t change, did not upgrade test-containers dependency neither, same docker pg image containing the same data (actually using my local cache).

Works perfectly fine in 1.0.1.Final, crashes in 1.1.0.Final

Do you have any idea what could create such a behavior (a 3rd-party dependency upgrade between 1.0.1.Final and 1.1.0.Final maybe?), anything I could investigate on, basically! 😃

Thanks

Configuration

# Add your application.properties here, if applicable.
# HTTP Server config
quarkus.http.port=9090
# DataSource
quarkus.datasource.driver=org.postgresql.Driver
quarkus.datasource.url=jdbc:postgresql://localhost:5432/somedb
quarkus.datasource.username=thelogin
quarkus.datasource.password=thepwd
# Hibernate
quarkus.hibernate-orm.dialect=org.hibernate.dialect.PostgreSQL95Dialect
#quarkus.hibernate-orm.log.sql=true
quarkus.datasource.min-size=10
quarkus.datasource.max-size=100

Environment (please complete the following information):

Quarkus version or git rev: either 1.1.0.Final or 1.1.1.Final

About this issue

Original URL
State: open
Created 4 years ago
Comments: 23 (8 by maintainers)

Most upvoted comments

Thank you so much for the reproducer! I really struggled to create one. This helps a lot.

aesteve on Jan 13, 2020

I ran into the same issue:

[INFO] Tests run: 13, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 17.361 s - in io.quarkus.workshop.superheroes.hero.Hero2ResourceTest
[INFO] Running io.quarkus.workshop.superheroes.hero.HeroResourceTest
23:32:24 INFO  [🐳.5]] (main) Creating container for image: postgres:10.5
23:32:24 INFO  [🐳.5]] (main) Starting container with ID: c7a1e6bb01a871c4faa8e4402e0b5f497f000874124a01763357d41863b74790
23:32:25 INFO  [🐳.5]] (main) Container postgres:10.5 is starting: c7a1e6bb01a871c4faa8e4402e0b5f497f000874124a01763357d41863b74790
23:32:27 INFO  [🐳.5]] (main) Container postgres:10.5 started in PT3.167364S
Hibernate: 
    select
        hero0_.id as id1_0_,
        hero0_.level as level2_0_,
        hero0_.name as name3_0_,
        hero0_.otherName as otherNam4_0_,
        hero0_.picture as picture5_0_,
        hero0_.powers as powers6_0_ 
    from
        Hero hero0_ limit ?
23:32:27 WARN  [or.hi.en.jd.sp.SqlExceptionHelper] (executor-thread-1) SQL Error: 0, SQLState: 08006
23:32:27 ERROR [or.hi.en.jd.sp.SqlExceptionHelper] (executor-thread-1) An I/O error occurred while sending to the backend.
23:32:27 WARN  [or.hi.en.jd.sp.SqlExceptionHelper] (executor-thread-1) SQL Error: 0, SQLState: 08003
23:32:27 ERROR [or.hi.en.jd.sp.SqlExceptionHelper] (executor-thread-1) This connection has been closed.
23:32:27 ERROR [io.qu.ve.ht.ru.QuarkusErrorHandler] (executor-thread-1) HTTP Request to /api/heroes failed, error id: ca69e6f4-d8d5-472c-b524-2113d19aee35-1: org.jboss.resteasy.spi.UnhandledException: javax.persistence.PersistenceException: org.hibernate.exception.JDBCConnectionException: Unable to release JDBC Connection
	at org.jboss.resteasy.core.ExceptionHandler.handleApplicationException(ExceptionHandler.java:106)
	at org.jboss.resteasy.core.ExceptionHandler.handleException(ExceptionHandler.java:372)
	at org.jboss.resteasy.core.SynchronousDispatcher.writeException(SynchronousDispatcher.java:209)
	at org.jboss.resteasy.core.SynchronousDispatcher.invoke(SynchronousDispatcher.java:496)
	at org.jboss.resteasy.core.SynchronousDispatcher.lambda$invoke$4(SynchronousDispatcher.java:252)
	at org.jboss.resteasy.core.SynchronousDispatcher.lambda$preprocess$0(SynchronousDispatcher.java:153)
	at org.jboss.resteasy.core.interception.jaxrs.PreMatchContainerRequestContext.filter(PreMatchContainerRequestContext.java:363)
	at org.jboss.resteasy.core.SynchronousDispatcher.preprocess(SynchronousDispatcher.java:156)
	at org.jboss.resteasy.core.SynchronousDispatcher.invoke(SynchronousDispatcher.java:238)
	at io.quarkus.resteasy.runtime.standalone.RequestDispatcher.service(RequestDispatcher.java:73)
	at io.quarkus.resteasy.runtime.standalone.VertxRequestHandler.dispatch(VertxRequestHandler.java:120)
	at io.quarkus.resteasy.runtime.standalone.VertxRequestHandler.access$000(VertxRequestHandler.java:36)
       ...
Caused by: javax.persistence.PersistenceException: org.hibernate.exception.JDBCConnectionException: Unable to release JDBC Connection
	at org.hibernate.internal.ExceptionConverterImpl.convert(ExceptionConverterImpl.java:154)
	at org.hibernate.query.internal.AbstractProducedQuery.list(AbstractProducedQuery.java:1535)
	at org.hibernate.query.Query.getResultList(Query.java:165)
	at io.quarkus.hibernate.orm.panache.runtime.PanacheQueryImpl.list(PanacheQueryImpl.java:137)
	at io.quarkus.hibernate.orm.panache.runtime.JpaOperations.listAll(JpaOperations.java:340)
	at io.quarkus.workshop.superheroes.hero.Hero.listAll(Hero.java)
	at io.quarkus.workshop.superheroes.hero.HeroService.findAllHeroes(HeroService.java:26)
       ...

I created a reproducer here: https://github.com/misl/QuarkusIssueReproducer The reproducer is basically the Hero service from the workshop. Only change is that there are 2 (identical) @QuarkusTest annotated classes HeroResourceTest and Hero2ResourceTest with the container stuff moved to a base HeroTestBase class. If either one of the ResourceTest classes is removed the tests run just fine.

Hope this helps to resolve the problem.

misl on Jan 12, 2020

I’ll try to, but that’s gonna be a hard task. The docker image I’m using for my tests is a PgSQL one, but containing a subset of real-life data.

For the reproducer to be public I’d need to publish such an image to a public docker registry.

That’s why I was hoping for Clément’s repo to have the same issue. But it doesn’t (I ran it locally).

No seriously, I have absolutely no clue what’s going on with versions >= 1.0.1.Final there must some weird race condition happening, (maybe with ryuk?), but the only thing I’m actually evidencing is that “something” is requesting the PostgreSQL database to shutdown (admin shutdown actually), before the test is actually finished.

I completely understand you can’t work without reproducer, but I don’t manage to create a proper one.

Some science-fictional guess would be that this change messed-up Ryuk (=the thing testcontainers uses to manage docker images) a bit like the bug happening here but I can’t find a way to evidence it.

Sorry :\

aesteve on Jan 9, 2020