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

[aesteve]

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:

1. Create a simple service and @Inject an EntityManager
2. In some method, perform an HQL query and return query.getResultList()
3. 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

[aesteve]

After a few more investigations: there's definitely something odd happening between TestContainers and QuarkusTest.

Running the exact same test suite without starting the docker image through @TestContainers but manually (before running the test suite from the IDE) works like a charm.

[aesteve]

With 1.1.1.Final:
 gradle -q --configuration testRuntimeClasspath --dependency org.testcontainers
Gives:

org.testcontainers:junit-jupiter:1.12.3
\--- io.quarkus:quarkus-bom:1.1.1.Final
     \--- testRuntimeClasspath

org.testcontainers:junit-jupiter:1.12.4 -> 1.12.3
\--- testRuntimeClasspath

Whereas with 1.0.1.Final:

org.testcontainers:junit-jupiter:1.12.0
\--- io.quarkus:quarkus-bom:1.0.1.Final
     \--- testRuntimeClasspath

org.testcontainers:junit-jupiter:1.12.4 -> 1.12.0
\--- testRuntimeClasspath

So this is the upgrade that's causing me trouble (probably because I'm doing as @cescoffier did here: https://github.com/quarkusio/quarkus/issues/2022 and some methods like withPortBindings have been deprecated).

I'm trying to dig into @TestContainers changelog to see if I'm finding something.

---

EDIT:
Unfortunately for me, no. That's not the issue. Changing my build.gradle.kts to:

    testImplementation("io.quarkus:quarkus-junit5")
    testImplementation("org.testcontainers:junit-jupiter") {
        version { strictly("1.12.0") }
    }
    testImplementation("org.testcontainers:testcontainers") {
        version { strictly("1.12.0") }
    }

gives me:

org.testcontainers:junit-jupiter:1.12.0 (unknown)
org.testcontainers:junit-jupiter:{strictly 1.12.0} -> 1.12.0
\--- testRuntimeClasspath

org.testcontainers:junit-jupiter:1.12.3 -> 1.12.0
\--- io.quarkus:quarkus-bom:1.1.1.Final
     \--- testRuntimeClasspath

But the test is still failing.

---

Note that the workaround mentioned in #2022 (not using @TestContainers annotation, but starting/stopping the container manually in @BeforeAll/@AfterAll) sometimes works. (some tests work, some don't, some tests fail on CI some other within the IDE).

Definitely looks like a race condition happening somewhere.

[aesteve]

@cescoffier if you still have the demo you were mentioning in #2022 , could you try to upgrade it to 1.1.1.Final? Maybe you'll face the same issue?

[cescoffier]

@aesteve in https://github.com/cescoffier/quarkus-todo-app, I'm using that approach.

[aesteve]

Thanks a lot!
I'll give the jdbcURL approach a try 🤞

---

Bad luck for me, the same approach does not work in my case, no idea why:

WARN: Datasource <default> not started: driver and/or url are not defined.
org.jboss.resteasy.spi.UnhandledException: javax.enterprise.inject.IllegalProductException: Normal scoped producer method may not return null: io.quarkus.agroal.runtime.DataSourceProducer.createDefaultDataSource()

[gsmet]

Could you create a simple reproducer? Preferably a simple Maven project?

[aesteve]

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]

I found something that may lead me on a track though.

1. The first test method in the class actually works, every time
2. The second (and the following) don't
3. If I'm running the tests independently (split every test in different classes: 1 single method per class), then there's absolutely no issue. The whole test suite is green.
4. If I don't use testcontainers and manage the docker image by myself, there's no issue at all

When using TestContainers, after each test method, the docker image is restarted.

I've set a breakpoint in ResultSetReturnImpl.extract and in the debugger, inspected the PgConnection instance (its hashcode), every time a query was made.

It looks the same every time (same hashcode).

When I re-run the test suite, it's a different hashcode, but, still the same for every method.

If the same PgConnection instance is shared among test methods, then there's no way my tests are going to work (since the DB has been restarted in between two methods).

That would explain the SQLState 08006 "an I/O error happened ..."

Is this possible (thus a track I should investigate further on)?

[misl]

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.

[aesteve]

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

[aesteve]

@gsmet now that @misl has created a proper reproducer, any chance you can tell us what we need to do to help? Thanks.

EDIT: I tried with 1.2.0.Final and still face this bug. It's starting to be a blocking point, I'd like to upgrade, mostly because new versions bring a lot of improvements to the Gradle plugin for instance (build that doesn't depend on buildNative) but I'm stuck with an old version because my tests are not passing with the latest versions. Is there any chance you'll like into the reproducer?

[aesteve]

I tried to upgrade to 1.2.1.Final but still face the same issue.

Last time I checked on Zulip (28/01/2020) @gastaldi told me he may have a look, but since then, no info at all.

Is @misl 's reproducer not enough in order to reproduce the issue?
Has someone given this bug a look?
Can we do something more to help?

Still blocked with Quarkus 1.0.1.Final and cannot upgrade safely, every time I try to, a lot of unit tests are failing because of this bug.

Could you at least tell us if you're going to look at it, so that I know if I should start rewriting the whole REST API set I developed with another stack? This confusing situation unfortunately starts to cause me troubles (hard to justify such a lag in version numbers :\ )

Thanks.

[gastaldi]

@aesteve my fault, I got sidetracked with other tasks and completely forgot about that one (I should have assigned the issue to myself that time).

@Sanne any idea what's going on?

[Sanne]

Thanks for the test!

@Sanne any idea what's going on?

No, it doesn't ring a bell - we'll have to find some time to look at this.

[aesteve]

@misl Did you manage to workaround the issue ?

Just not using a base class with the container stuff in it fixed the issue for you?

Thank you.

[aesteve]

~I finally found a way to bypass this bug by NOT using the @TestContainers annotation, and using QuarkusTestExtension start/stop methods instead to setup / teardown the database. In case someone faces the same issue.~

Nevermind, this workaround is also bugged. QuarkusTestResource is applied to every test, starting / stopping the db even though the test doesn't declare the @QuarkusTestResource. Not sure if it's related to the fact that I am using kotlin, or Gradle, or both... But the code in QuarkusTestExtension.doJavaStart() is invoked, and sets up my database in every of my @QuarkusTest no matter if the test class declares this @QuarkusTestResource or not.

[geoand]

Would love to see a reproducer of what you are mentioning @aesteve

[pschyma]

I'm using TestContainers by specifying a tc jdbc URL in application.properties like shown in [1]: jdbc:tc:postgresql:///databasename. So I don't need to use test resources. Is this an option for you @aesteve ?

[1] https://www.testcontainers.org/modules/databases/jdbc/

[gsmet]

@aesteve any chance you could work on a reproducer so that we can have a look?

[aesteve]

Not before one or two weeks. Unfortunately I'm really late for work, I had time to try an upgrade last week-end, but won't have bandwidth before end of april.

[aesteve]

For the issue re. TestResources, please follow the discussion here: https://github.com/quarkusio/quarkus/issues/8097#issuecomment-630654771

I'll keep this thread for the original issue : the "connection is already closed" issue.

---

But to sum up, using @TestResource to start/stop testcontainers can be used as a workaround. Unfortunately, IntellijIDEA seems to run the TestResource.start() method no matter the test you're running. Which is a bit of a pain (you'll test a simple class that does not depend on your container, and intellij will start it anyway).