Quarkus: [Another] Unable to acquire JDBC connection

[DorianMaliszewski]

Describe the bug
Hi everyone, I followed the guide on quarkus jdbc, quarkus hibernate orm and quarkus hibernate panache.
My environnement :

• Adoptopenjdk 8
• Quarkus 1.4.2 Final
• Dockerfile.jvm for quarkus
• Docker mariadb and postgres for development

What's the problem ?

• I launched the application with one datasource (same problem on postgres and mariadb).
• I put some configuration for timeout (extremely low because of my bug) : See below my conf
• After 1000/2000 requests, I get the error : Unable to acquire JDBC connection (Detail below on Scrrenshot section)
• The idle_in_transaction_session_timeout is set to 0 on Postgres
• The statement_timeout is set to 0 on Postgres too.

• This behaviour is the same on Mariadb.
• Sometimes it happens at the 50th request sometimes at the 200th, sometimes more but it happens everytime.

Expected behavior

No more Unable to acquire JDBC connection :sob: .

Actual behavior
(Describe the actual behavior clearly and concisely.)

To Reproduce
Steps to reproduce the behavior:

1. Make a JDBC connection on Mariadb or Postgres
2. Create a jax-rs get path
3. Create a service class annoted @RequestScoped
4. Make a findAll on your panache entity in the service class
5. Return the list in your jax-rs get path
6. Launch the app
7. Make many request in a short time (Bot or something else)
8. In a 1000/2000 requests you can get this error

Configuration

# Add your application.properties here, if applicable.
quarkus.datasource.url = jdbc:postgresql://localhost:3306/eztalk
quarkus.datasource.jdbc.url=jdbc:postgresql://localhost:3306/eztalk
quarkus.datasource.driver=org.postgresql.Driver
quarkus.datasource.jdbc.driver=org.postgresql.Driver
quarkus.datasource.username=USERNAME
quarkus.datasource.password=PASSWORD
quarkus.datasource.jdbc.min-size=4
quarkus.datasource.jdbc.max-size=50
quarkus.datasource.jdbc.max-lifetime=150
quarkus.datasource.jdbc.idle-removal-interval=50
quarkus.datasource.jdbc.background-validation-interval=10
quarkus.datasource.jdbc.leak-detection-interval=30
quarkus.datasource.jdbc.acquisition-timeout=10
quarkus.datasource.db-kind=postgresql

Screenshots
I can give you the error

eztalk-service_1        | Caused by: org.hibernate.exception.GenericJDBCException: Unable to acquire JDBC Connection
eztalk-service_1        |   at org.hibernate.exception.internal.StandardSQLExceptionConverter.convert(StandardSQLExceptionConverter.java:47)
eztalk-service_1        |   at org.hibernate.engine.jdbc.spi.SqlExceptionHelper.convert(SqlExceptionHelper.java:113)
eztalk-service_1        |   at org.hibernate.engine.jdbc.spi.SqlExceptionHelper.convert(SqlExceptionHelper.java:99)
eztalk-service_1        |   at org.hibernate.resource.jdbc.internal.LogicalConnectionManagedImpl.acquireConnectionIfNeeded(LogicalConnectionManagedImpl.java:107)
eztalk-service_1        |   at org.hibernate.resource.jdbc.internal.LogicalConnectionManagedImpl.getPhysicalConnection(LogicalConnectionManagedImpl.java:134)
eztalk-service_1        |   at org.hibernate.engine.jdbc.internal.StatementPreparerImpl.connection(StatementPreparerImpl.java:50)
eztalk-service_1        |   at org.hibernate.engine.jdbc.internal.StatementPreparerImpl$5.doPrepare(StatementPreparerImpl.java:149)
eztalk-service_1        |   at org.hibernate.engine.jdbc.internal.StatementPreparerImpl$StatementPreparationTemplate.prepareStatement(StatementPreparerImpl.java:176)
eztalk-service_1        |   at org.hibernate.engine.jdbc.internal.StatementPreparerImpl.prepareQueryStatement(StatementPreparerImpl.java:151)
eztalk-service_1        |   at org.hibernate.loader.Loader.prepareQueryStatement(Loader.java:2104)
eztalk-service_1        |   at org.hibernate.loader.Loader.executeQueryStatement(Loader.java:2034)
eztalk-service_1        |   at org.hibernate.loader.Loader.executeQueryStatement(Loader.java:2012)
eztalk-service_1        |   at org.hibernate.loader.Loader.doQuery(Loader.java:953)
eztalk-service_1        |   at org.hibernate.loader.Loader.doQueryAndInitializeNonLazyCollections(Loader.java:354)
eztalk-service_1        |   at org.hibernate.loader.Loader.doList(Loader.java:2838)
eztalk-service_1        |   at org.hibernate.loader.Loader.doList(Loader.java:2820)
eztalk-service_1        |   at org.hibernate.loader.Loader.listIgnoreQueryCache(Loader.java:2652)
eztalk-service_1        |   at org.hibernate.loader.Loader.list(Loader.java:2647)
eztalk-service_1        |   at org.hibernate.loader.hql.QueryLoader.list(QueryLoader.java:506)
eztalk-service_1        |   at org.hibernate.hql.internal.ast.QueryTranslatorImpl.list(QueryTranslatorImpl.java:396)
eztalk-service_1        |   at org.hibernate.engine.query.spi.HQLQueryPlan.performList(HQLQueryPlan.java:219)
eztalk-service_1        |   at org.hibernate.internal.SessionImpl.list(SessionImpl.java:1404)
eztalk-service_1        |   at org.hibernate.query.internal.AbstractProducedQuery.doList(AbstractProducedQuery.java:1565)
eztalk-service_1        |   at org.hibernate.query.internal.AbstractProducedQuery.list(AbstractProducedQuery.java:1533)
eztalk-service_1        |   ... 285 more
eztalk-service_1        | Caused by: java.sql.SQLException: Sorry, acquisition timeout!
eztalk-service_1        |   at io.agroal.pool.ConnectionPool.handlerFromSharedCache(ConnectionPool.java:244)
eztalk-service_1        |   at io.agroal.pool.ConnectionPool.getConnection(ConnectionPool.java:173)
eztalk-service_1        |   at io.agroal.pool.DataSource.getConnection(DataSource.java:66)
eztalk-service_1        |   at io.quarkus.hibernate.orm.runtime.customized.QuarkusConnectionProvider.getConnection(QuarkusConnectionProvider.java:23)
eztalk-service_1        |   at org.hibernate.internal.NonContextualJdbcConnectionAccess.obtainConnection(NonContextualJdbcConnectionAccess.java:38)
eztalk-service_1        |   at org.hibernate.resource.jdbc.internal.LogicalConnectionManagedImpl.acquireConnectionIfNeeded(LogicalConnectionManagedImpl.java:104)
eztalk-service_1        |   ... 305 more

Environment (please complete the following information):

• Output of uname -a or ver: Linux NOPLACELIKEHOME 4.19.107-1-MANJARO #1 SMP Fri Feb 28 21:14:27 UTC 2020 x86_64 GNU/Linux
• Output of java -version:

openjdk version "1.8.0_242"
OpenJDK Runtime Environment (build 1.8.0_242-b08)
OpenJDK 64-Bit Server VM (build 25.242-b08, mixed mode)

• GraalVM version (if different from Java): Not using
• Quarkus version or git rev: 1.4.2 Final
• Build tool (ie. output of mvnw --version or gradlew --version):

Apache Maven 3.6.3 (NON-CANONICAL_2019-11-27T20:26:29Z_root)
Maven home: /opt/maven
Java version: 1.8.0_242, vendor: Oracle Corporation, runtime: /usr/lib/jvm/java-8-openjdk/jre
Default locale: fr_FR, platform encoding: UTF-8
OS name: "linux", version: "4.19.107-1-manjaro", arch: "amd64", family: "unix"

Additional context

I tried to put acquisition timeout at 30s or more but it's the same and I don't think it can be possible to an user waiting more than 30s because it can be difficult to get a JDBC connection.
I tried to follow advices I saw on Google but none did the job.

I'm available by this issue, email, phone, or others to talk more about this.

Thank you in advance for the time you will take to read this,

[cpmoore]

Enable datasource metrics using

 <dependency>
            <groupId>io.quarkus</groupId>
            <artifactId>quarkus-smallrye-metrics</artifactId>
        </dependency>

and

quarkus.datasource.metrics.enabled=true
quarkus.datasource.jdbc.enable-metrics=true

Then check the vendor_agroal_active_count metric on the /metrics endpoint. Is it constantly increasing?
I had this issue where it eventually reached the max value and wouldn't create any more connections. Turned out to be an issue where my code wasn't closing the connection if the sql statement threw an exception.

[DorianMaliszewski]

Ok so my vendor_agroal_active_count is increasing over the requests, so what did you do ? The only error I took is Jackson mapping statement error ? Is this error which doesn't close the statement ?
Sometimes I get jackson error : Could not prepare statement for id .....

Like this one
com.fasterxml.jackson.databind.JsonMappingException: could not prepare statementError
And in my console :

eztalk-service_1        | 2020-05-07 01:05:27,304 WARN  [org.hib.eng.jdb.spi.SqlExceptionHelper] (executor-thread-1) SQL Error: 0, SQLState: null
eztalk-service_1        | 2020-05-07 01:05:27,304 ERROR [org.hib.eng.jdb.spi.SqlExceptionHelper] (executor-thread-1) Connection is closed
eztalk-service_1        | 2020-05-07 01:05:27,305 ERROR [io.und.req.io] (executor-thread-1) Exception handling request 575959f8-456c-497e-ae80-cf7c913b9a92-6 to /eztalk/patient-requests/: org.jboss.resteasy.spi.UnhandledException: com.fasterxml.jackson.databind.JsonMappingException: could not prepare statement
....
eztalk-service_1        | Caused by: com.fasterxml.jackson.databind.JsonMappingException: could not prepare statement
...
eztalk-service_1        | Caused by: org.hibernate.exception.GenericJDBCException: could not prepare statement
...
eztalk-service_1        | Caused by: java.sql.SQLException: Connection is closed
...
eztalk-service_1        | 2020-05-07 01:05:27,307 WARN  [org.hib.eng.jdb.spi.SqlExceptionHelper] (ForkJoinPool.commonPool-worker-2) SQL Error: 0, SQLState: null
eztalk-service_1        | 2020-05-07 01:05:27,308 ERROR [org.hib.eng.jdb.spi.SqlExceptionHelper] (ForkJoinPool.commonPool-worker-2) CallableStatement is closed
eztalk-service_1        | 2020-05-07 01:05:27,307 WARN  [io.agr.pool] (ForkJoinPool.commonPool-worker-0) Datasource '<default>': JDBC resources leaked: 1 ResultSet(s) and 1 Statement(s)

Do you think is this jackson error which take my app out ?

[DorianMaliszewski]

The vendor_agroal_active_count only increase when i send multiple requests, not only when i get the error, but it doesn't increase at every request...

[DorianMaliszewski]

I tested :

• 1 request error
• 1 request no error

active count + 2

this is my method :

• JAX-RS Get on /blablabla/ : BlablaResource.java
• BlablaResource.java call the Request Scoped BlablaService.java method (findAll)
• findAll in BlablaService.java only do Blabla.findAll().list();
• BlablaResource.java get the list and do
• Response.ok(list.parallelStream().map(BlablaDTO:new).collect(Collectors.toList())).build();

• What is wrong ? I didn't put any @Transactional on readOnly methods
• In my DTO constructor I access the relation of the persisted entity (readOnly) to put in my DTO

[DorianMaliszewski]

Problem found

Ok, so after multiple tests, I find where is the problem :

• Hibernate Panache

I don't know why but when I call Blabla.list("service = ?1", id) it works but doesn't close the statement, and in my metrics the agroal_active_* is increasing.

To resolve that

I just injected the entityManager in my service class and make the request with DTO projection in my request

Detail of my process

May be the statement is not close because :

• I get the request in my BlablaResource.java (findAll) with @Path and @Get annotations
• I use my BlablaService.java which I injected with @Inject
• This service class is @RequestScoped
• SO In my findAll method I call the findAllFromServiceClass method
• In findAllFromServiceClass method I just do a return Blabla.list("service = ?1", id)
• I get the list in findAll method and do .parallelStream().map(BlablaDTO::new).collect(Collectors.toList())
• In my DTO I try to access relation (@OneToMany, @OneToOne, ...)
• I think the problem come from this : when I try to access the relation in my DTO constructor the requests are made but the statement are never closed.

So, if someone can help me on that, or confirm that there are a problem with the extension, it would be nice.

I'm available to talk more about this, and may be help to solve this bug.

EDIT

I confirm the problem is when I do the transformation of Blabla to BlablaDTO, it's the same when I put it in BlablaResource or BlablaService.
To solve this I need to put the DTO constructor in the query directly

[nandorholozsnyak]

I have just bumped into this problem, and I understand the problem, but should not it be fixed somehow?

I was running stress tests on a Quarkus based application with JMeter, the thread number was 300 and the loop count was 100 and it started to throw this exception around the half of the test, so it was really annoying that it was creating exceptions, the error rate was really small, 0.01-0.02% percentage. The application is a simple CRUD based app, with some e-commerce based, list items, add items to cart, and start order and I also used Panache. I'm on 1.9.2.Final.
The http thread pool size was 300 and the datasource pool size was 50.

[gsmet]

@nandorholozsnyak if you can get us a reproducer, that would help.

[nandorholozsnyak]

Hey @gsmet , I will create one as soon as I can.

[gsmet]

/cc @Sanne FYI, there might be some odd issue lurking here.

[DorianMaliszewski]

@gsmet @Sanne Hi,
There are sometimes since I create this issue. I really think that the problem due to the different scope.
Another possibility is that I found that sometimes Jackson throw me an error.. may be this doesnt close the transaction.
On the other hand I found that the @Path which is normally RequestScoped by default doesn't update request variable (Like Claim for oidc) So may be there are an error in the lifecycle of the transaction.

I gave an exemple on the 8 May response. We can talk more about this error.

Sincerely,

[Sanne]

yes this looks tricky, I should investigate. I need to finish some releases, but hope to switch to this on Wednesday.

[Sanne]

Unless @barreiro maybe has some time to look into this? Please let me know :)

[tgallin]

Hi, I've witnessed the "acquisition timeout" issue too with an as400 database, using the jt400 driver. A problem that someone else also mentionned in this article https://stackoverflow.com/questions/62307245/quarkus-as400-datasource-doesnt-use-all-available-connections

I can provide details if needed. I'd be happy to help. I've been using Quarkus a lot since version 1.4.2 and really enjoy it. Thanks for the great work !