quarkus: [Another] Unable to acquire JDBC connection

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

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,

About this issue

  • Original URL
  • State: open
  • Created 4 years ago
  • Reactions: 8
  • Comments: 39 (9 by maintainers)

Most upvoted comments

Hi,

I have same kind of error with quarkus 2.13.4.Final and Jdk 17

I can give other informations if needed

2022-12-22T16:08:04.540Z: Dec 22, 2022 4:08:04 PM org.hibernate.engine.jdbc.spi.SqlExceptionHelper logExceptions
2022-12-22T16:08:04.540Z: ERROR: Acquisition timeout while waiting for new connection
2022-12-22T16:08:04.863Z: at org.hibernate.loader.Loader.prepareQueryStatement(Loader.java:2122)
2022-12-22T16:08:04.863Z: at org.hibernate.loader.Loader.executeQueryStatement(Loader.java:2059)
2022-12-22T16:08:04.863Z: at org.hibernate.loader.Loader.executeQueryStatement(Loader.java:2037)
2022-12-22T16:08:04.863Z: at org.hibernate.loader.Loader.doQuery(Loader.java:956)
2022-12-22T16:08:04.864Z: at org.hibernate.internal.SessionImpl.list(SessionImpl.java:1459)
2022-12-22T16:08:04.864Z: at org.hibernate.query.internal.AbstractProducedQuery.doList(AbstractProducedQuery.java:1649)
2022-12-22T16:08:04.864Z: at org.hibernate.query.internal.AbstractProducedQuery.list(AbstractProducedQuery.java:1617)
2022-12-22T16:08:04.861Z: Dec 22, 2022 4:08:04 PM io.quarkus.vertx.http.runtime.QuarkusErrorHandler handle
2022-12-22T16:08:04.861Z: ERROR: HTTP Request to /replayers/exercices/search?rangeStartIndex=0&rangeEndIndex=9& failed, error id: 12afb52a-4c91-443f-8113-4bc6f622eb27-1
2022-12-22T16:08:04.863Z: at org.hibernate.loader.Loader.doQueryAndInitializeNonLazyCollections(Loader.java:357)
2022-12-22T16:08:04.863Z: at org.hibernate.loader.Loader.doList(Loader.java:2868)
2022-12-22T16:08:04.864Z: ... 33 more
2022-12-22T16:08:04.864Z: Caused by: java.util.concurrent.TimeoutException
2022-12-22T16:08:04.864Z: at java.base/java.util.concurrent.FutureTask.get(FutureTask.java:204)
2022-12-22T16:08:04.864Z: at io.agroal.pool.ConnectionPool.handlerFromSharedCache(ConnectionPool.java:296)
2022-12-22T16:08:04.863Z: at org.hibernate.resource.jdbc.internal.LogicalConnectionManagedImpl.getPhysicalConnection(LogicalConnectionManagedImpl.java:138)
2022-12-22T16:08:04.863Z: at org.hibernate.engine.jdbc.internal.StatementPreparerImpl.connection(StatementPreparerImpl.java:50)
2022-12-22T16:08:04.863Z: at org.hibernate.engine.jdbc.internal.StatementPreparerImpl$5.doPrepare(StatementPreparerImpl.java:149)
2022-12-22T16:08:04.863Z: at org.hibernate.engine.jdbc.internal.StatementPreparerImpl$StatementPreparationTemplate.prepareStatement(StatementPreparerImpl.java:176)
2022-12-22T16:08:04.863Z: at org.hibernate.engine.jdbc.internal.StatementPreparerImpl.prepareQueryStatement(StatementPreparerImpl.java:151)
2022-12-22T16:08:04.864Z: at io.agroal.pool.DataSource.getConnection(DataSource.java:86)
2022-12-22T16:08:04.864Z: at io.quarkus.hibernate.orm.runtime.customized.QuarkusConnectionProvider.getConnection(QuarkusConnectionProvider.java:23)
2022-12-22T16:08:04.864Z: at org.hibernate.internal.NonContextualJdbcConnectionAccess.obtainConnection(NonContextualJdbcConnectionAccess.java:38)
2022-12-22T16:08:04.864Z: at org.hibernate.resource.jdbc.internal.LogicalConnectionManagedImpl.acquireConnectionIfNeeded(LogicalConnectionManagedImpl.java:108)
2022-12-22T16:08:04.862Z: at org.tcollignon.user.object.User__JpaIdentityProviderImpl.authenticate(Unknown Source)
2022-12-22T16:08:04.862Z: at io.quarkus.security.jpa.runtime.JpaIdentityProvider$1.get(JpaIdentityProvider.java:42)
2022-12-22T16:08:04.862Z: at io.quarkus.security.jpa.runtime.JpaIdentityProvider$1.get(JpaIdentityProvider.java:35)
2022-12-22T16:08:04.862Z: at io.quarkus.security.runtime.QuarkusIdentityProviderManagerImpl$1$1$1$1.run(QuarkusIdentityProviderManagerImpl.java:58)
2022-12-22T16:08:04.862Z: at io.quarkus.vertx.core.runtime.VertxCoreRecorder$14.runWith(VertxCoreRecorder.java:564)
2022-12-22T16:08:04.863Z: at org.hibernate.exception.internal.StandardSQLExceptionConverter.convert(StandardSQLExceptionConverter.java:42)
2022-12-22T16:08:04.863Z: at org.hibernate.engine.jdbc.spi.SqlExceptionHelper.convert(SqlExceptionHelper.java:113)
2022-12-22T16:08:04.863Z: at org.hibernate.engine.jdbc.spi.SqlExceptionHelper.convert(SqlExceptionHelper.java:99)
2022-12-22T16:08:04.863Z: at org.hibernate.resource.jdbc.internal.LogicalConnectionManagedImpl.acquireConnectionIfNeeded(LogicalConnectionManagedImpl.java:111)
2022-12-22T16:08:04.864Z: ... 13 more
2022-12-22T16:08:04.864Z: Caused by: java.sql.SQLException: Acquisition timeout while waiting for new connection
2022-12-22T16:08:04.864Z: at io.agroal.pool.ConnectionPool.handlerFromSharedCache(ConnectionPool.java:320)
2022-12-22T16:08:04.864Z: at io.agroal.pool.ConnectionPool.getConnection(ConnectionPool.java:248)
2022-12-22T16:08:04.865Z: ... 38 more
2022-12-22T16:08:04.863Z: at org.hibernate.loader.Loader.doList(Loader.java:2850)
2022-12-22T16:08:04.863Z: at org.hibernate.loader.Loader.listIgnoreQueryCache(Loader.java:2682)
2022-12-22T16:08:04.863Z: at org.hibernate.loader.Loader.list(Loader.java:2677)
2022-12-22T16:08:04.863Z: at org.hibernate.loader.hql.QueryLoader.list(QueryLoader.java:540)
2022-12-22T16:08:04.863Z: at org.hibernate.hql.internal.ast.QueryTranslatorImpl.list(QueryTranslatorImpl.java:400)
2022-12-22T16:08:04.863Z: at org.hibernate.engine.query.spi.HQLQueryPlan.performList(HQLQueryPlan.java:219)
2022-12-22T16:08:04.862Z: javax.persistence.PersistenceException: org.hibernate.exception.GenericJDBCException: Unable to acquire JDBC Connection
2022-12-22T16:08:04.862Z: at org.hibernate.internal.ExceptionConverterImpl.convert(ExceptionConverterImpl.java:154)
2022-12-22T16:08:04.862Z: at org.hibernate.query.internal.AbstractProducedQuery.list(AbstractProducedQuery.java:1626)
2022-12-22T16:08:04.862Z: at org.jboss.threads.EnhancedQueueExecutor$Task.run(EnhancedQueueExecutor.java:2449)
2022-12-22T16:08:04.862Z: at org.jboss.threads.EnhancedQueueExecutor$ThreadBody.run(EnhancedQueueExecutor.java:1452)
2022-12-22T16:08:04.862Z: at org.jboss.threads.DelegatingRunnable.run(DelegatingRunnable.java:29)
2022-12-22T16:08:04.862Z: at org.jboss.threads.ThreadLocalResettingRunnable.run(ThreadLocalResettingRunnable.java:29)
2022-12-22T16:08:04.862Z: at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
2022-12-22T16:08:04.862Z: at java.base/java.lang.Thread.run(Thread.java:833)
2022-12-22T16:08:04.862Z: Caused by: org.hibernate.exception.GenericJDBCException: Unable to acquire JDBC Connection
2022-12-22T16:08:04.862Z: at org.hibernate.query.Query.getResultList(Query.java:165)
2022-12-22T16:08:04.862Z: at io.quarkus.security.jpa.runtime.AbstractJpaIdentityProvider.getSingleUser(AbstractJpaIdentityProvider.java:53)
2022-12-22T16:16:37.108Z: Dec 22, 2022 4:16:36 PM io.quarkus.agroal.runtime.AgroalEventLoggingListener onWarning
2022-12-22T16:16:37.108Z: WARN: Datasource '<default>': Closing connection in incorrect state VALIDATION
2022-12-22T16:16:37.108Z: Dec 22, 2022 4:16:36 PM io.quarkus.agroal.runtime.AgroalEventLoggingListener onWarning
2022-12-22T16:16:37.108Z: WARN: Datasource '<default>': Closing connection in incorrect state VALIDATION```
+3
tcollignon on Jan 5, 2023

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

+3
DorianMaliszewski on May 8, 2020

Not sure if this is helpful/useful but all the services we migrated to the reactive (postgres) driver stopped experiencing these issues. Not discounting the possibility that same issues are occurring but being silently swallowed, but if anything it seems to me like the Vert.x driver has a better “dead connection” detection/restarting approach than the Agroal DS.

P.S. @rkorver it’s possible to increase the acquisition timeout property. You can look into that possibly, and decrease the time that idle connections are kept in the pool.

+2
kostacasa on Nov 11, 2022

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

+2
DorianMaliszewski on Nov 29, 2020

Same problem here at Azure with quarkus 2.16.7 and postgres. Unfortunately neither quarkus.datasource.jdbc.max-size nor migrating to pg flexible server helped.

+1
kraeftbraeu on Jun 30, 2023

Hi all,

The issue in my case was our (Azure) firewall shutting down the connections randomly.

One way to circumvent this is to activate a public endpoint on your azure databases, and connect directly through that (it won’t actually be accessible from outside your network, don’t worry) , but I’m sure there are other solutions to this as well. For example I’ve heard that an alternative solution is to switch to “flexible server” instead of single server.

Another issue is that agroal keeps the connections alive too long for the database so I solved that by setting:

quarkus.datasource.jdbc.max-lifetime=10m

Hope this helps cc: @tcollignon @kostacasa

+1
rkorver on Feb 21, 2023
Read more comments on GitHub
← quarkus: An empty entry is added in undefined List<String> config item
quarkus: Apache Tika can not parse Microsoft Docx format in native mode →