Search code examples
javaspringhibernatehikaricpconnectionexception

Hikari connection is not available and unexpected multiple pool issue

In my companies project, we are using Hikari for connection pool management. [Hibernate 4.3.5 + Spring 4 + Java 1.8] Below is the configuration

hibernate.connection.provider_class=com.zaxxer.hikari.hibernate.HikariConnectionProvider
hibernate.hikari.minimumIdle=5
hibernate.hikari.maximumPoolSize=10
hibernate.hikari.idleTimeout=60
hibernate.hikari.dataSourceClassName=com.mysql.jdbc.jdbc2.optional.MysqlDataSource

We are facing below problem two problem

  1. For some reason, Hikari is creating 2 connection pool HikariPool-1 and HikariPool-2.

  2. Only HikariPool-2 is being used and even that is giving error Connection is not available, request timed out after 30000ms after some time

Below are the logs of Hikari initiation and the error of request timed out.

log4j:WARN Please initialize the log4j system properly.
log4j:WARN See http://logging.apache.org/log4j/1.2/faq.html#noconfig for more info.
[2018-11-05 15:18:02] - [] - DEBUG com.zaxxer.hikari.hibernate.HikariConnectionProvider -- Configuring HikariCP
[2018-11-05 15:18:02] - [] - DEBUG com.zaxxer.hikari.HikariConfig -- HikariPool-1 - configuration:
[2018-11-05 15:18:02] - [] - DEBUG com.zaxxer.hikari.HikariConfig -- allowPoolSuspension.............false
[2018-11-05 15:18:02] - [] - DEBUG com.zaxxer.hikari.HikariConfig -- autoCommit......................true
[2018-11-05 15:18:02] - [] - DEBUG com.zaxxer.hikari.HikariConfig -- catalog.........................null
[2018-11-05 15:18:02] - [] - DEBUG com.zaxxer.hikari.HikariConfig -- connectionInitSql...............null
[2018-11-05 15:18:02] - [] - DEBUG com.zaxxer.hikari.HikariConfig -- connectionTestQuery............."SELECT 1"
[2018-11-05 15:18:02] - [] - DEBUG com.zaxxer.hikari.HikariConfig -- connectionTimeout...............30000
[2018-11-05 15:18:02] - [] - DEBUG com.zaxxer.hikari.HikariConfig -- dataSource......................null
[2018-11-05 15:18:02] - [] - DEBUG com.zaxxer.hikari.HikariConfig -- dataSourceClassName............."com.mysql.jdbc.jdbc2.optional.MysqlDataSource"
[2018-11-05 15:18:02] - [] - DEBUG com.zaxxer.hikari.HikariConfig -- dataSourceJNDI..................null
[2018-11-05 15:18:02] - [] - DEBUG com.zaxxer.hikari.HikariConfig -- dataSourceProperties............{user=walletadmin, url=jdbc:mysql://111.111.11.11:3306/database, 
password=<masked>}
[2018-11-05 15:18:02] - [] - DEBUG com.zaxxer.hikari.HikariConfig -- driverClassName.................null
[2018-11-05 15:18:02] - [] - DEBUG com.zaxxer.hikari.HikariConfig -- healthCheckProperties...........{}
[2018-11-05 15:18:02] - [] - DEBUG com.zaxxer.hikari.HikariConfig -- healthCheckRegistry.............null
[2018-11-05 15:18:02] - [] - DEBUG com.zaxxer.hikari.HikariConfig -- idleTimeout.....................10800
[2018-11-05 15:18:02] - [] - DEBUG com.zaxxer.hikari.HikariConfig -- initializationFailFast..........true
[2018-11-05 15:18:02] - [] - DEBUG com.zaxxer.hikari.HikariConfig -- isolateInternalQueries..........false
[2018-11-05 15:18:02] - [] - DEBUG com.zaxxer.hikari.HikariConfig -- jdbc4ConnectionTest.............false
[2018-11-05 15:18:02] - [] - DEBUG com.zaxxer.hikari.HikariConfig -- jdbcUrl.........................null
[2018-11-05 15:18:02] - [] - DEBUG com.zaxxer.hikari.HikariConfig -- leakDetectionThreshold..........0
[2018-11-05 15:18:02] - [] - DEBUG com.zaxxer.hikari.HikariConfig -- maxLifetime.....................1800000
[2018-11-05 15:18:02] - [] - DEBUG com.zaxxer.hikari.HikariConfig -- maximumPoolSize.................50
[2018-11-05 15:18:02] - [] - DEBUG com.zaxxer.hikari.HikariConfig -- metricRegistry..................null
[2018-11-05 15:18:02] - [] - DEBUG com.zaxxer.hikari.HikariConfig -- metricsTrackerFactory...........null
[2018-11-05 15:18:02] - [] - DEBUG com.zaxxer.hikari.HikariConfig -- minimumIdle.....................5
[2018-11-05 15:18:02] - [] - DEBUG com.zaxxer.hikari.HikariConfig -- password........................<masked>
[2018-11-05 15:18:02] - [] - DEBUG com.zaxxer.hikari.HikariConfig -- poolName........................"HikariPool-1"
[2018-11-05 15:18:02] - [] - DEBUG com.zaxxer.hikari.HikariConfig -- readOnly........................false
[2018-11-05 15:18:02] - [] - DEBUG com.zaxxer.hikari.HikariConfig -- registerMbeans..................false
[2018-11-05 15:18:02] - [] - DEBUG com.zaxxer.hikari.HikariConfig -- scheduledExecutorService........null
[2018-11-05 15:18:02] - [] - DEBUG com.zaxxer.hikari.HikariConfig -- threadFactory...................null
[2018-11-05 15:18:02] - [] - DEBUG com.zaxxer.hikari.HikariConfig -- transactionIsolation............null
[2018-11-05 15:18:02] - [] - DEBUG com.zaxxer.hikari.HikariConfig -- username........................null
[2018-11-05 15:18:02] - [] - DEBUG com.zaxxer.hikari.HikariConfig -- validationTimeout...............5000
[2018-11-05 15:18:02] - [] - INFO com.zaxxer.hikari.HikariDataSource -- HikariPool-1 - Started.
[2018-11-05 15:18:03] - [] - DEBUG com.zaxxer.hikari.hibernate.HikariConnectionProvider -- HikariCP Configured
[2018-11-05 15:18:03] - [] - DEBUG com.zaxxer.hikari.hibernate.HikariConnectionProvider -- Configuring HikariCP



[2018-11-05 15:18:03] - [] - DEBUG com.zaxxer.hikari.HikariConfig -- HikariPool-2 - configuration:
[2018-11-05 15:18:03] - [] - DEBUG com.zaxxer.hikari.HikariConfig -- allowPoolSuspension.............false
[2018-11-05 15:18:03] - [] - DEBUG com.zaxxer.hikari.HikariConfig -- autoCommit......................true
[2018-11-05 15:18:03] - [] - DEBUG com.zaxxer.hikari.HikariConfig -- catalog.........................null
[2018-11-05 15:18:03] - [] - DEBUG com.zaxxer.hikari.HikariConfig -- connectionInitSql...............null
[2018-11-05 15:18:03] - [] - DEBUG com.zaxxer.hikari.HikariConfig -- connectionTestQuery............."SELECT 1"
[2018-11-05 15:18:03] - [] - DEBUG com.zaxxer.hikari.HikariConfig -- connectionTimeout...............30000
[2018-11-05 15:18:03] - [] - DEBUG com.zaxxer.hikari.HikariConfig -- dataSource......................null
[2018-11-05 15:18:03] - [] - DEBUG com.zaxxer.hikari.HikariConfig -- dataSourceClassName............."com.mysql.jdbc.jdbc2.optional.MysqlDataSource"
[2018-11-05 15:18:03] - [] - DEBUG com.zaxxer.hikari.HikariConfig -- dataSourceJNDI..................null
[2018-11-05 15:18:03] - [] - DEBUG com.zaxxer.hikari.HikariConfig -- dataSourceProperties............{user=walletadmin, url=jdbc:mysql://111.111.11.11:3306/database, 
password=<masked>}
[2018-11-05 15:18:03] - [] - DEBUG com.zaxxer.hikari.HikariConfig -- driverClassName.................null
[2018-11-05 15:18:03] - [] - DEBUG com.zaxxer.hikari.HikariConfig -- healthCheckProperties...........{}
[2018-11-05 15:18:03] - [] - DEBUG com.zaxxer.hikari.HikariConfig -- healthCheckRegistry.............null
[2018-11-05 15:18:03] - [] - DEBUG com.zaxxer.hikari.HikariConfig -- idleTimeout.....................10800
[2018-11-05 15:18:03] - [] - DEBUG com.zaxxer.hikari.HikariConfig -- initializationFailFast..........true
[2018-11-05 15:18:03] - [] - DEBUG com.zaxxer.hikari.HikariConfig -- isolateInternalQueries..........false
[2018-11-05 15:18:03] - [] - DEBUG com.zaxxer.hikari.HikariConfig -- jdbc4ConnectionTest.............false
[2018-11-05 15:18:03] - [] - DEBUG com.zaxxer.hikari.HikariConfig -- jdbcUrl.........................null
[2018-11-05 15:18:03] - [] - DEBUG com.zaxxer.hikari.HikariConfig -- leakDetectionThreshold..........0
[2018-11-05 15:18:03] - [] - DEBUG com.zaxxer.hikari.HikariConfig -- maxLifetime.....................1800000
[2018-11-05 15:18:03] - [] - DEBUG com.zaxxer.hikari.HikariConfig -- maximumPoolSize.................50
[2018-11-05 15:18:03] - [] - DEBUG com.zaxxer.hikari.HikariConfig -- metricRegistry..................null
[2018-11-05 15:18:03] - [] - DEBUG com.zaxxer.hikari.HikariConfig -- metricsTrackerFactory...........null
[2018-11-05 15:18:03] - [] - DEBUG com.zaxxer.hikari.HikariConfig -- minimumIdle.....................5
[2018-11-05 15:18:03] - [] - DEBUG com.zaxxer.hikari.HikariConfig -- password........................<masked>
[2018-11-05 15:18:03] - [] - DEBUG com.zaxxer.hikari.HikariConfig -- poolName........................"HikariPool-2"
[2018-11-05 15:18:03] - [] - DEBUG com.zaxxer.hikari.HikariConfig -- readOnly........................false
[2018-11-05 15:18:03] - [] - DEBUG com.zaxxer.hikari.HikariConfig -- registerMbeans..................false
[2018-11-05 15:18:03] - [] - DEBUG com.zaxxer.hikari.HikariConfig -- scheduledExecutorService........null
[2018-11-05 15:18:03] - [] - DEBUG com.zaxxer.hikari.HikariConfig -- threadFactory...................null
[2018-11-05 15:18:03] - [] - DEBUG com.zaxxer.hikari.HikariConfig -- transactionIsolation............null
[2018-11-05 15:18:03] - [] - DEBUG com.zaxxer.hikari.HikariConfig -- username........................null
[2018-11-05 15:18:03] - [] - DEBUG com.zaxxer.hikari.HikariConfig -- validationTimeout...............5000
[2018-11-05 15:18:03] - [] - INFO com.zaxxer.hikari.HikariDataSource -- HikariPool-2 - Started.
[2018-11-05 15:18:03] - [] - DEBUG com.zaxxer.hikari.hibernate.HikariConnectionProvider -- HikariCP Configured

[2018-11-04 11:00:30] - [] - ERROR com.agwallet.serviceImpl.InstantGiftCardAcceptServiceImpl --  Exception getting from ================= instantGiftVirtualCardAccept() =============Could not open connection; nested exception is org.hibernate.exception.JDBCConnectionException: Could not open connection
org.springframework.dao.DataAccessResourceFailureException: Could not open connection; nested exception is org.hibernate.exception.JDBCConnectionException: Could not open connection
        at org.springframework.orm.jpa.vendor.HibernateJpaDialect.convertHibernateAccessException(HibernateJpaDialect.java:234)
        at org.springframework.orm.jpa.vendor.HibernateJpaDialect.translateExceptionIfPossible(HibernateJpaDialect.java:221)
        at org.springframework.orm.jpa.AbstractEntityManagerFactoryBean.translateExceptionIfPossible(AbstractEntityManagerFactoryBean.java:417)
        at org.springframework.dao.support.ChainedPersistenceExceptionTranslator.translateExceptionIfPossible(ChainedPersistenceExceptionTranslator.java:59)
        at org.springframework.dao.support.DataAccessUtils.translateIfNecessary(DataAccessUtils.java:213)
        at org.springframework.dao.support.PersistenceExceptionTranslationInterceptor.invoke(PersistenceExceptionTranslationInterceptor.java:147)
        at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:179)
        at org.springframework.data.jpa.repository.support.CrudMethodMetadataPostProcessor$CrudMethodMetadataPopulatingMethodInterceptor.invoke(CrudMethodMetadataPostProcessor.java:119)
        at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:179)
        at org.springframework.aop.interceptor.ExposeInvocationInterceptor.invoke(ExposeInvocationInterceptor.java:92)
        at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:179)
        at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:207)
        at com.sun.proxy.$Proxy86.findAllPendingGiftVirtualCard(Unknown Source)
        at com.agwallet.serviceImpl.InstantGiftCardAcceptServiceImpl.instantGiftVirtualCardAccept(InstantGiftCardAcceptServiceImpl.java:57)
        at com.agwallet.jobs.InstantActivationForGiftCardJob.instantGiftVirtualCardRequest(InstantActivationForGiftCardJob.java:29)
        at sun.reflect.GeneratedMethodAccessor66.invoke(Unknown Source)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
        at java.lang.reflect.Method.invoke(Method.java:498)
        at org.springframework.scheduling.support.ScheduledMethodRunnable.run(ScheduledMethodRunnable.java:65)
        at org.springframework.scheduling.support.DelegatingErrorHandlingRunnable.run(DelegatingErrorHandlingRunnable.java:54)
        at org.springframework.scheduling.concurrent.ReschedulingRunnable.run(ReschedulingRunnable.java:81)
        at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
        at java.util.concurrent.FutureTask.run(FutureTask.java:266)
        at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:180)
        at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
        at java.lang.Thread.run(Thread.java:745)
Caused by: org.hibernate.exception.JDBCConnectionException: Could not open connection
        at org.hibernate.exception.internal.SQLExceptionTypeDelegate.convert(SQLExceptionTypeDelegate.java:65)
        at org.hibernate.exception.internal.StandardSQLExceptionConverter.convert(StandardSQLExceptionConverter.java:49)
        at org.hibernate.engine.jdbc.spi.SqlExceptionHelper.convert(SqlExceptionHelper.java:126)
        at org.hibernate.engine.jdbc.spi.SqlExceptionHelper.convert(SqlExceptionHelper.java:112)
        at org.hibernate.engine.jdbc.internal.LogicalConnectionImpl.obtainConnection(LogicalConnectionImpl.java:235)
        at org.hibernate.engine.jdbc.internal.LogicalConnectionImpl.getConnection(LogicalConnectionImpl.java:171)
        at org.hibernate.engine.jdbc.internal.StatementPreparerImpl.connection(StatementPreparerImpl.java:63)
        at org.hibernate.engine.jdbc.internal.StatementPreparerImpl$5.doPrepare(StatementPreparerImpl.java:162)
        at org.hibernate.engine.jdbc.internal.StatementPreparerImpl$StatementPreparationTemplate.prepareStatement(StatementPreparerImpl.java:186)
        at org.hibernate.engine.jdbc.internal.StatementPreparerImpl.prepareQueryStatement(StatementPreparerImpl.java:160)
        at org.hibernate.loader.Loader.prepareQueryStatement(Loader.java:1884)
        at org.hibernate.loader.Loader.executeQueryStatement(Loader.java:1861)
        at org.hibernate.loader.Loader.executeQueryStatement(Loader.java:1838)
        at org.hibernate.loader.Loader.doQuery(Loader.java:909)
        at org.hibernate.loader.Loader.doQueryAndInitializeNonLazyCollections(Loader.java:354)
        at org.hibernate.loader.Loader.doList(Loader.java:2553)
        at org.hibernate.loader.Loader.doList(Loader.java:2539)
        at org.hibernate.loader.Loader.listIgnoreQueryCache(Loader.java:2369)
        at org.hibernate.loader.Loader.list(Loader.java:2364)
        at org.hibernate.loader.hql.QueryLoader.list(QueryLoader.java:496)
        at org.hibernate.hql.internal.ast.QueryTranslatorImpl.list(QueryTranslatorImpl.java:387)
        at org.hibernate.engine.query.spi.HQLQueryPlan.performList(HQLQueryPlan.java:231)
        at org.hibernate.internal.SessionImpl.list(SessionImpl.java:1264)
        at org.hibernate.internal.QueryImpl.list(QueryImpl.java:103)
        at org.hibernate.jpa.internal.QueryImpl.list(QueryImpl.java:573)
        at org.hibernate.jpa.internal.QueryImpl.getResultList(QueryImpl.java:449)
        at sun.reflect.GeneratedMethodAccessor65.invoke(Unknown Source)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
        at java.lang.reflect.Method.invoke(Method.java:498)
        at org.springframework.orm.jpa.SharedEntityManagerCreator$DeferredQueryInvocationHandler.invoke(SharedEntityManagerCreator.java:364)
        at com.sun.proxy.$Proxy96.getResultList(Unknown Source)
        at org.springframework.data.jpa.repository.query.JpaQueryExecution$CollectionExecution.doExecute(JpaQueryExecution.java:114)
        at org.springframework.data.jpa.repository.query.JpaQueryExecution.execute(JpaQueryExecution.java:78)
        at org.springframework.data.jpa.repository.query.AbstractJpaQuery.doExecute(AbstractJpaQuery.java:100)
        at org.springframework.data.jpa.repository.query.AbstractJpaQuery.execute(AbstractJpaQuery.java:91)
        at org.springframework.data.repository.core.support.RepositoryFactorySupport$QueryExecutorMethodInterceptor.doInvoke(RepositoryFactorySupport.java:454)
        at org.springframework.data.repository.core.support.RepositoryFactorySupport$QueryExecutorMethodInterceptor.invoke(RepositoryFactorySupport.java:432)
        at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:179)
        at org.springframework.data.projection.DefaultMethodInvokingMethodInterceptor.invoke(DefaultMethodInvokingMethodInterceptor.java:61)
        at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:179)
        at org.springframework.transaction.interceptor.TransactionInterceptor$1.proceedWithInvocation(TransactionInterceptor.java:99)
        at org.springframework.transaction.interceptor.TransactionAspectSupport.invokeWithinTransaction(TransactionAspectSupport.java:281)
        at org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:96)
        at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:179)
        at org.springframework.dao.support.PersistenceExceptionTranslationInterceptor.invoke(PersistenceExceptionTranslationInterceptor.java:136)
        ... 22 common frames omitted
Caused by: java.sql.SQLTransientConnectionException: HikariPool-2 - Connection is not available, request timed out after 30000ms.
        at com.zaxxer.hikari.pool.HikariPool.createTimeoutException(HikariPool.java:548)
        at com.zaxxer.hikari.pool.HikariPool.getConnection(HikariPool.java:186)
        at com.zaxxer.hikari.pool.HikariPool.getConnection(HikariPool.java:145)
        at com.zaxxer.hikari.HikariDataSource.getConnection(HikariDataSource.java:83)
        at com.zaxxer.hikari.hibernate.HikariConnectionProvider.getConnection(HikariConnectionProvider.java:106)
        at org.hibernate.internal.AbstractSessionImpl$NonContextualJdbcConnectionAccess.obtainConnection(AbstractSessionImpl.java:380)
        at org.hibernate.engine.jdbc.internal.LogicalConnectionImpl.obtainConnection(LogicalConnectionImpl.java:228)
        ... 62 common frames omitted
Solution

  • If you upgrade Hibernate from 4.3.5 to 4.3.6, there's a official ConnectionProvider for Hibernate:

    UPDATE : Hibernate 4.3.6+ As of Hibernate 4.3.6 there is an official ConnectionProvider class from Hibernate, which should be used instead of the HikariCP implementation. The class is called org.hibernate.hikaricp.internal.HikariCPConnectionProvider.

    So you should replace com.zaxxer.hikari.hibernate.HikariConnectionProvider with org.hibernate.hikaricp.internal.HikariCPConnectionProvider

    See also MySQL Hikari Configuration