dfche
dfche

Reputation: 3693

HikariCP - connection is not available

We have Spring-boot/Hibernate/PostgreSQL application in our project and use Hikari as the connection pool. We keep running into the following problem: after few hours active connections number grows to the limit and we get the errors like this (full stack trace is at the end of the question):

Caused by: java.sql.SQLTransientConnectionException: HikariPool-0 - Connection is not available, request timed out after 30000ms.
    at com.zaxxer.hikari.pool.HikariPool.getConnection(HikariPool.java:213) ~[HikariCP-2.4.1.jar:na]
    at com.zaxxer.hikari.pool.HikariPool.getConnection(HikariPool.java:163) ~[HikariCP-2.4.1.jar:na]
    at com.zaxxer.hikari.HikariDataSource.getConnection(HikariDataSource.java:85) ~[HikariCP-2.4.1.jar:na]
    at org.hibernate.engine.jdbc.connections.internal.DatasourceConnectionProviderImpl.getConnection(DatasourceConnectionProviderImpl.java:139) ~[hibernate-core-4.3.6.Final.jar:4.3.6.Final]
    at org.hibernate.internal.AbstractSessionImpl$NonContextualJdbcConnectionAccess.obtainConnection(AbstractSessionImpl.java:380) ~[hibernate-core-4.3.6.Final.jar:4.3.6.Final]
    at org.hibernate.engine.jdbc.internal.LogicalConnectionImpl.obtainConnection(LogicalConnectionImpl.java:228) ~[hibernate-core-4.3.6.Final.jar:4.3.6.Final]
    ... 126 common frames omitted

Here is the version info:

Spring-boot version:   1.2.3.RELEASE
HikariCP version:      2.4.1
Hibernate version:     4.3.6.Final
Postgresql jdbc:       9.3-1102-jdbc41
Server version:        Apache Tomcat/8.0.23
JVM Version:           1.8.0_45-b14

JPA/Hibernate config:

jpa:
    database-platform: org.hibernate.dialect.PostgreSQL82Dialect
    database: POSTGRESQL
    openInView: false
    show_sql: false
    generate-ddl: false
    hibernate:
        ddl-auto: none
        naming-strategy: org.hibernate.cfg.EJB3NamingStrategy
    properties:
        hibernate.cache.use_second_level_cache: true
        hibernate.cache.use_query_cache: false
        hibernate.generate_statistics: false
        hibernate.cache.region.factory_class: org.hibernate.cache.ehcache.SingletonEhCacheRegionFactory
        hibernate.enable_lazy_load_no_trans: true
        hibernate.event.merge.entity_copy_observer: allow

HikariCP config:

2015-10-06 12:26:44,252 DEBUG [localhost-startStop-1] HikariConfig: HikariPool-0 - configuration:
2015-10-06 12:26:44,274 DEBUG [localhost-startStop-1] HikariConfig: allowPoolSuspension.............false
2015-10-06 12:26:44,274 DEBUG [localhost-startStop-1] HikariConfig: autoCommit......................true
2015-10-06 12:26:44,274 DEBUG [localhost-startStop-1] HikariConfig: catalog.........................
2015-10-06 12:26:44,274 DEBUG [localhost-startStop-1] HikariConfig: connectionInitSql...............
2015-10-06 12:26:44,274 DEBUG [localhost-startStop-1] HikariConfig: connectionTestQuery.............
2015-10-06 12:26:44,274 DEBUG [localhost-startStop-1] HikariConfig: connectionTimeout...............30000
2015-10-06 12:26:44,274 DEBUG [localhost-startStop-1] HikariConfig: dataSource......................
2015-10-06 12:26:44,274 DEBUG [localhost-startStop-1] HikariConfig: dataSourceClassName.............org.postgresql.ds.PGSimpleDataSource
2015-10-06 12:26:44,274 DEBUG [localhost-startStop-1] HikariConfig: dataSourceJNDI..................
2015-10-06 12:26:44,274 DEBUG [localhost-startStop-1] HikariConfig: dataSourceProperties............{user=postgres, password=<masked>, databaseName=lms, serverName=*.*.*.*:5432}
2015-10-06 12:26:44,274 DEBUG [localhost-startStop-1] HikariConfig: driverClassName.................
2015-10-06 12:26:44,274 DEBUG [localhost-startStop-1] HikariConfig: healthCheckProperties...........{}
2015-10-06 12:26:44,274 DEBUG [localhost-startStop-1] HikariConfig: healthCheckRegistry.............
2015-10-06 12:26:44,274 DEBUG [localhost-startStop-1] HikariConfig: idleTimeout.....................30000
2015-10-06 12:26:44,275 DEBUG [localhost-startStop-1] HikariConfig: initializationFailFast..........true
2015-10-06 12:26:44,275 DEBUG [localhost-startStop-1] HikariConfig: isolateInternalQueries..........false
2015-10-06 12:26:44,275 DEBUG [localhost-startStop-1] HikariConfig: jdbc4ConnectionTest.............false
2015-10-06 12:26:44,275 DEBUG [localhost-startStop-1] HikariConfig: jdbcUrl.........................
2015-10-06 12:26:44,275 DEBUG [localhost-startStop-1] HikariConfig: leakDetectionThreshold..........0
2015-10-06 12:26:44,275 DEBUG [localhost-startStop-1] HikariConfig: maxLifetime.....................1800000
2015-10-06 12:26:44,275 DEBUG [localhost-startStop-1] HikariConfig: maximumPoolSize.................20
2015-10-06 12:26:44,275 DEBUG [localhost-startStop-1] HikariConfig: metricRegistry..................com.codahale.metrics.MetricRegistry@63d2fc48
2015-10-06 12:26:44,275 DEBUG [localhost-startStop-1] HikariConfig: metricsTrackerFactory...........
2015-10-06 12:26:44,275 DEBUG [localhost-startStop-1] HikariConfig: minimumIdle.....................10
2015-10-06 12:26:44,275 DEBUG [localhost-startStop-1] HikariConfig: password........................<masked>
2015-10-06 12:26:44,275 DEBUG [localhost-startStop-1] HikariConfig: poolName........................HikariPool-0
2015-10-06 12:26:44,275 DEBUG [localhost-startStop-1] HikariConfig: readOnly........................false
2015-10-06 12:26:44,275 DEBUG [localhost-startStop-1] HikariConfig: registerMbeans..................false
2015-10-06 12:26:44,275 DEBUG [localhost-startStop-1] HikariConfig: scheduledExecutorService........
2015-10-06 12:26:44,275 DEBUG [localhost-startStop-1] HikariConfig: threadFactory...................
2015-10-06 12:26:44,275 DEBUG [localhost-startStop-1] HikariConfig: transactionIsolation............
2015-10-06 12:26:44,275 DEBUG [localhost-startStop-1] HikariConfig: username........................
2015-10-06 12:26:44,275 DEBUG [localhost-startStop-1] HikariConfig: validationTimeout...............5000
2015-10-06 12:26:44,276 INFO  [localhost-startStop-1] HikariDataSource: HikariPool-0 - is starting.
2015-10-06 12:26:44,432 DEBUG [localhost-startStop-1] PoolElf: HikariPool-0 - Connection.setNetworkTimeout() is not supported (Method org.postgresql.jdbc4.Jdbc4Connection.getNetworkTimeout() is not yet implemented.)

Full stack trace:

2015-10-06 12:09:36,885 DEBUG [http-nio-8080-exec-25] PoolElf: HikariPool-0 - Reset (nothing) on connection org.postgresql.jdbc4.Jdbc4Connection@3cc4d919
2015-10-06 12:09:42,651 DEBUG [Hikari housekeeper (pool HikariPool-0)] HikariPool: Before cleanup   pool HikariPool-0 stats (total=20, active=20, idle=0, waiting=1)
2015-10-06 12:09:42,652 DEBUG [Hikari housekeeper (pool HikariPool-0)] HikariPool: After cleanup    pool HikariPool-0 stats (total=20, active=20, idle=0, waiting=1)
2015-10-06 12:10:06,885 DEBUG [http-nio-8080-exec-25] HikariPool: Timeout failure   pool HikariPool-0 stats (total=20, active=20, idle=0, waiting=0)
2015-10-06 12:10:06,885 WARN  [http-nio-8080-exec-25] SqlExceptionHelper: SQL Error: 0, SQLState: null
2015-10-06 12:10:06,885 ERROR [http-nio-8080-exec-25] SqlExceptionHelper: HikariPool-0 - Connection is not available, request timed out after 30000ms.
2015-10-06 12:10:06,885 DEBUG [http-nio-8080-exec-25] PoolElf: HikariPool-0 - Reset (nothing) on connection org.postgresql.jdbc4.Jdbc4Connection@3cc4d919
2015-10-06 12:10:06,886 ERROR [http-nio-8080-exec-25] ErrorPageFilter: Forwarding to error page from request [/api/courses/121387/quizzes/i6fa2562510bf8578712380a87a433e97/student/30175] due to exception [org.springframework.web.util.NestedServletException: Request processing failed; nested exception is org.hibernate.exception.JDBCConnectionException: Could not open connection]
java.lang.RuntimeException: org.springframework.web.util.NestedServletException: Request processing failed; nested exception is org.hibernate.exception.JDBCConnectionException: Could not open connection
    at lms.security.xauth.XAuthTokenFilter.doFilter(XAuthTokenFilter.java:86) ~[XAuthTokenFilter.class:na]
    at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:330) ~[spring-security-web-4.0.0.RELEASE.jar:na]
    at org.springframework.security.web.authentication.logout.LogoutFilter.doFilter(LogoutFilter.java:120) ~[spring-security-web-4.0.0.RELEASE.jar:na]
    at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:330) ~[spring-security-web-4.0.0.RELEASE.jar:na]
    at org.springframework.security.web.header.HeaderWriterFilter.doFilterInternal(HeaderWriterFilter.java:64) ~[spring-security-web-4.0.0.RELEASE.jar:na]
    at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107) [spring-web-4.1.6.RELEASE.jar:4.1.6.RELEASE]
    at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:330) ~[spring-security-web-4.0.0.RELEASE.jar:na]
    at org.springframework.security.web.context.SecurityContextPersistenceFilter.doFilter(SecurityContextPersistenceFilter.java:91) ~[spring-security-web-4.0.0.RELEASE.jar:na]
    at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:330) ~[spring-security-web-4.0.0.RELEASE.jar:na]
    at org.springframework.security.web.context.request.async.WebAsyncManagerIntegrationFilter.doFilterInternal(WebAsyncManagerIntegrationFilter.java:53) ~[spring-security-web-4.0.0.RELEASE.jar:na]
    at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107) [spring-web-4.1.6.RELEASE.jar:4.1.6.RELEASE]
    at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:330) ~[spring-security-web-4.0.0.RELEASE.jar:na]
    at org.springframework.security.web.FilterChainProxy.doFilterInternal(FilterChainProxy.java:213) ~[spring-security-web-4.0.0.RELEASE.jar:na]
    at org.springframework.security.web.FilterChainProxy.doFilter(FilterChainProxy.java:176) ~[spring-security-web-4.0.0.RELEASE.jar:na]
    at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:239) [catalina.jar:8.0.23]
    at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206) [catalina.jar:8.0.23]
    at org.springframework.boot.actuate.trace.WebRequestTraceFilter.doFilterInternal(WebRequestTraceFilter.java:102) ~[spring-boot-actuator-1.2.3.RELEASE.jar:1.2.3.RELEASE]
    at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107) [spring-web-4.1.6.RELEASE.jar:4.1.6.RELEASE]
    at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:239) [catalina.jar:8.0.23]
    at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206) [catalina.jar:8.0.23]
    at org.springframework.web.filter.CharacterEncodingFilter.doFilterInternal(CharacterEncodingFilter.java:85) ~[spring-web-4.1.6.RELEASE.jar:4.1.6.RELEASE]
    at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107) [spring-web-4.1.6.RELEASE.jar:4.1.6.RELEASE]
    at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:239) [catalina.jar:8.0.23]
    at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206) [catalina.jar:8.0.23]
    at org.springframework.boot.context.web.ErrorPageFilter.doFilter(ErrorPageFilter.java:113) [spring-boot-1.2.3.RELEASE.jar:1.2.3.RELEASE]
    at org.springframework.boot.context.web.ErrorPageFilter.access$000(ErrorPageFilter.java:59) [spring-boot-1.2.3.RELEASE.jar:1.2.3.RELEASE]
    at org.springframework.boot.context.web.ErrorPageFilter$1.doFilterInternal(ErrorPageFilter.java:88) [spring-boot-1.2.3.RELEASE.jar:1.2.3.RELEASE]
    at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107) [spring-web-4.1.6.RELEASE.jar:4.1.6.RELEASE]
    at org.springframework.boot.context.web.ErrorPageFilter.doFilter(ErrorPageFilter.java:106) [spring-boot-1.2.3.RELEASE.jar:1.2.3.RELEASE]
    at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:239) [catalina.jar:8.0.23]
    at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206) [catalina.jar:8.0.23]
    at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:219) [catalina.jar:8.0.23]
    at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:106) [catalina.jar:8.0.23]
    at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:502) [catalina.jar:8.0.23]
    at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:142) [catalina.jar:8.0.23]
    at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:79) [catalina.jar:8.0.23]
    at org.apache.catalina.valves.AbstractAccessLogValve.invoke(AbstractAccessLogValve.java:617) [catalina.jar:8.0.23]
    at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:88) [catalina.jar:8.0.23]
    at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:518) [catalina.jar:8.0.23]
    at org.apache.coyote.http11.AbstractHttp11Processor.process(AbstractHttp11Processor.java:1091) [tomcat-coyote.jar:8.0.23]
    at org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process(AbstractProtocol.java:668) [tomcat-coyote.jar:8.0.23]
    at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1521) [tomcat-coyote.jar:8.0.23]
    at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.run(NioEndpoint.java:1478) [tomcat-coyote.jar:8.0.23]
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142) [na:1.8.0_45]
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) [na:1.8.0_45]
    at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61) [tomcat-util.jar:8.0.23]
    at java.lang.Thread.run(Thread.java:745) [na:1.8.0_45]
Caused by: org.springframework.web.util.NestedServletException: Request processing failed; nested exception is org.hibernate.exception.JDBCConnectionException: Could not open connection
    at org.springframework.web.servlet.FrameworkServlet.processRequest(FrameworkServlet.java:978) ~[spring-webmvc-4.1.6.RELEASE.jar:4.1.6.RELEASE]
    at org.springframework.web.servlet.FrameworkServlet.doPost(FrameworkServlet.java:868) ~[spring-webmvc-4.1.6.RELEASE.jar:4.1.6.RELEASE]
    at javax.servlet.http.HttpServlet.service(HttpServlet.java:648) ~[servlet-api.jar:na]
    at org.springframework.web.servlet.FrameworkServlet.service(FrameworkServlet.java:842) ~[spring-webmvc-4.1.6.RELEASE.jar:4.1.6.RELEASE]
    at javax.servlet.http.HttpServlet.service(HttpServlet.java:729) ~[servlet-api.jar:na]
    at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:291) [catalina.jar:8.0.23]
    at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206) [catalina.jar:8.0.23]
    at com.codahale.metrics.servlet.AbstractInstrumentedFilter.doFilter(AbstractInstrumentedFilter.java:104) ~[metrics-servlet-3.1.1.jar:3.1.1]
    at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:239) [catalina.jar:8.0.23]
    at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206) [catalina.jar:8.0.23]
    at org.apache.tomcat.websocket.server.WsFilter.doFilter(WsFilter.java:52) ~[tomcat-websocket.jar:8.0.23]
    at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:239) [catalina.jar:8.0.23]
    at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206) [catalina.jar:8.0.23]
    at org.springframework.boot.actuate.autoconfigure.EndpointWebMvcAutoConfiguration$ApplicationContextHeaderFilter.doFilterInternal(EndpointWebMvcAutoConfiguration.java:291) ~[spring-boot-actuator-1.2.3.RELEASE.jar:1.2.3.RELEASE]
    at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107) [spring-web-4.1.6.RELEASE.jar:4.1.6.RELEASE]
    at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:239) [catalina.jar:8.0.23]
    at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206) [catalina.jar:8.0.23]
    at org.springframework.web.filter.HiddenHttpMethodFilter.doFilterInternal(HiddenHttpMethodFilter.java:77) ~[spring-web-4.1.6.RELEASE.jar:4.1.6.RELEASE]
    at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107) [spring-web-4.1.6.RELEASE.jar:4.1.6.RELEASE]
    at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:239) [catalina.jar:8.0.23]
    at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206) [catalina.jar:8.0.23]
    at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:316) ~[spring-security-web-4.0.0.RELEASE.jar:na]
    at org.springframework.security.web.access.intercept.FilterSecurityInterceptor.invoke(FilterSecurityInterceptor.java:126) ~[spring-security-web-4.0.0.RELEASE.jar:na]
    at org.springframework.security.web.access.intercept.FilterSecurityInterceptor.doFilter(FilterSecurityInterceptor.java:90) ~[spring-security-web-4.0.0.RELEASE.jar:na]
    at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:330) ~[spring-security-web-4.0.0.RELEASE.jar:na]
    at org.springframework.security.web.access.ExceptionTranslationFilter.doFilter(ExceptionTranslationFilter.java:114) ~[spring-security-web-4.0.0.RELEASE.jar:na]
    at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:330) ~[spring-security-web-4.0.0.RELEASE.jar:na]
    at org.springframework.security.web.session.SessionManagementFilter.doFilter(SessionManagementFilter.java:122) ~[spring-security-web-4.0.0.RELEASE.jar:na]
    at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:330) ~[spring-security-web-4.0.0.RELEASE.jar:na]
    at org.springframework.security.web.authentication.AnonymousAuthenticationFilter.doFilter(AnonymousAuthenticationFilter.java:111) ~[spring-security-web-4.0.0.RELEASE.jar:na]
    at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:330) ~[spring-security-web-4.0.0.RELEASE.jar:na]
    at org.springframework.security.web.servletapi.SecurityContextHolderAwareRequestFilter.doFilter(SecurityContextHolderAwareRequestFilter.java:168) ~[spring-security-web-4.0.0.RELEASE.jar:na]
    at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:330) ~[spring-security-web-4.0.0.RELEASE.jar:na]
    at org.springframework.security.web.savedrequest.RequestCacheAwareFilter.doFilter(RequestCacheAwareFilter.java:48) ~[spring-security-web-4.0.0.RELEASE.jar:na]
    at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:330) ~[spring-security-web-4.0.0.RELEASE.jar:na]
    at lms.security.xauth.XAuthTokenFilter.doFilter(XAuthTokenFilter.java:84) ~[XAuthTokenFilter.class:na]
    ... 46 common frames omitted
Caused by: org.hibernate.exception.JDBCConnectionException: Could not open connection
    at org.hibernate.exception.internal.SQLExceptionTypeDelegate.convert(SQLExceptionTypeDelegate.java:65) ~[hibernate-core-4.3.6.Final.jar:4.3.6.Final]
    at org.hibernate.exception.internal.StandardSQLExceptionConverter.convert(StandardSQLExceptionConverter.java:49) ~[hibernate-core-4.3.6.Final.jar:4.3.6.Final]
    at org.hibernate.engine.jdbc.spi.SqlExceptionHelper.convert(SqlExceptionHelper.java:126) ~[hibernate-core-4.3.6.Final.jar:4.3.6.Final]
    at org.hibernate.engine.jdbc.spi.SqlExceptionHelper.convert(SqlExceptionHelper.java:112) ~[hibernate-core-4.3.6.Final.jar:4.3.6.Final]
    at org.hibernate.engine.jdbc.internal.LogicalConnectionImpl.obtainConnection(LogicalConnectionImpl.java:235) ~[hibernate-core-4.3.6.Final.jar:4.3.6.Final]
    at org.hibernate.engine.jdbc.internal.LogicalConnectionImpl.getConnection(LogicalConnectionImpl.java:171) ~[hibernate-core-4.3.6.Final.jar:4.3.6.Final]
    at org.hibernate.engine.transaction.internal.jdbc.JdbcTransaction.doBegin(JdbcTransaction.java:67) ~[hibernate-core-4.3.6.Final.jar:4.3.6.Final]
    at org.hibernate.engine.transaction.spi.AbstractTransactionImpl.begin(AbstractTransactionImpl.java:162) ~[hibernate-core-4.3.6.Final.jar:4.3.6.Final]
    at org.hibernate.internal.SessionImpl.beginTransaction(SessionImpl.java:1435) ~[hibernate-core-4.3.6.Final.jar:4.3.6.Final]
    at org.hibernate.collection.internal.AbstractPersistentCollection.withTemporarySessionIfNeeded(AbstractPersistentCollection.java:250) ~[hibernate-core-4.3.6.Final.jar:4.3.6.Final]
    at org.hibernate.collection.internal.AbstractPersistentCollection.readElementByIndex(AbstractPersistentCollection.java:376) ~[hibernate-core-4.3.6.Final.jar:4.3.6.Final]
    at org.hibernate.collection.internal.PersistentMap.get(PersistentMap.java:164) ~[hibernate-core-4.3.6.Final.jar:4.3.6.Final]
    at java_util_Map$get.call(Unknown Source) ~[na:na]
    at lms.service.QuizService.processAnswers(QuizService.groovy:66) ~[QuizService.class:na]
    at lms.service.QuizService$$FastClassBySpringCGLIB$$4dcc8beb.invoke(<generated>) ~[spring-core-4.1.6.RELEASE.jar:na]
    at org.springframework.cglib.proxy.MethodProxy.invoke(MethodProxy.java:204) ~[spring-core-4.1.6.RELEASE.jar:4.1.6.RELEASE]
    at org.springframework.aop.framework.CglibAopProxy$CglibMethodInvocation.invokeJoinpoint(CglibAopProxy.java:717) ~[spring-aop-4.1.6.RELEASE.jar:4.1.6.RELEASE]
    at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:157) ~[spring-aop-4.1.6.RELEASE.jar:4.1.6.RELEASE]
    at org.springframework.transaction.interceptor.TransactionInterceptor$1.proceedWithInvocation(TransactionInterceptor.java:99) ~[spring-tx-4.1.6.RELEASE.jar:4.1.6.RELEASE]
    at org.springframework.transaction.interceptor.TransactionAspectSupport.invokeWithinTransaction(TransactionAspectSupport.java:281) ~[spring-tx-4.1.6.RELEASE.jar:4.1.6.RELEASE]
    at org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:96) ~[spring-tx-4.1.6.RELEASE.jar:4.1.6.RELEASE]
    at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:179) ~[spring-aop-4.1.6.RELEASE.jar:4.1.6.RELEASE]
    at org.springframework.aop.framework.CglibAopProxy$DynamicAdvisedInterceptor.intercept(CglibAopProxy.java:653) ~[spring-aop-4.1.6.RELEASE.jar:4.1.6.RELEASE]
    at lms.service.QuizService$$EnhancerBySpringCGLIB$$37a60c0a.processAnswers(<generated>) ~[spring-core-4.1.6.RELEASE.jar:na]
    at lms.web.rest.CourseResource.saveQuizResults(CourseResource.java:537) ~[CourseResource.class:na]
    at lms.web.rest.CourseResource$$FastClassBySpringCGLIB$$e3d2ba4d.invoke(<generated>) ~[spring-core-4.1.6.RELEASE.jar:na]
    at org.springframework.cglib.proxy.MethodProxy.invoke(MethodProxy.java:204) ~[spring-core-4.1.6.RELEASE.jar:4.1.6.RELEASE]
    at org.springframework.aop.framework.CglibAopProxy$CglibMethodInvocation.invokeJoinpoint(CglibAopProxy.java:717) ~[spring-aop-4.1.6.RELEASE.jar:4.1.6.RELEASE]
    at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:157) ~[spring-aop-4.1.6.RELEASE.jar:4.1.6.RELEASE]
    at org.springframework.security.access.intercept.aopalliance.MethodSecurityInterceptor.invoke(MethodSecurityInterceptor.java:68) ~[spring-security-core-4.0.0.RELEASE.jar:na]
    at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:179) ~[spring-aop-4.1.6.RELEASE.jar:4.1.6.RELEASE]
    at com.ryantenney.metrics.spring.TimedMethodInterceptor.invoke(TimedMethodInterceptor.java:48) ~[metrics-spring-3.0.4.jar:na]
    at com.ryantenney.metrics.spring.TimedMethodInterceptor.invoke(TimedMethodInterceptor.java:34) ~[metrics-spring-3.0.4.jar:na]
    at com.ryantenney.metrics.spring.AbstractMetricMethodInterceptor.invoke(AbstractMetricMethodInterceptor.java:59) ~[metrics-spring-3.0.4.jar:na]
    at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:179) ~[spring-aop-4.1.6.RELEASE.jar:4.1.6.RELEASE]
    at org.springframework.aop.framework.CglibAopProxy$DynamicAdvisedInterceptor.intercept(CglibAopProxy.java:653) ~[spring-aop-4.1.6.RELEASE.jar:4.1.6.RELEASE]
    at lms.web.rest.CourseResource$$EnhancerBySpringCGLIB$$ff854301.saveQuizResults(<generated>) ~[spring-core-4.1.6.RELEASE.jar:na]
    at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[na:1.8.0_45]
    at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) ~[na:1.8.0_45]
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[na:1.8.0_45]
    at java.lang.reflect.Method.invoke(Method.java:497) ~[na:1.8.0_45]
    at org.springframework.web.method.support.InvocableHandlerMethod.doInvoke(InvocableHandlerMethod.java:221) ~[spring-web-4.1.6.RELEASE.jar:4.1.6.RELEASE]
    at org.springframework.web.method.support.InvocableHandlerMethod.invokeForRequest(InvocableHandlerMethod.java:137) ~[spring-web-4.1.6.RELEASE.jar:4.1.6.RELEASE]
    at org.springframework.web.servlet.mvc.method.annotation.ServletInvocableHandlerMethod.invokeAndHandle(ServletInvocableHandlerMethod.java:110) ~[spring-webmvc-4.1.6.RELEASE.jar:4.1.6.RELEASE]
    at org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.invokeHandleMethod(RequestMappingHandlerAdapter.java:776) ~[spring-webmvc-4.1.6.RELEASE.jar:4.1.6.RELEASE]
    at org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.handleInternal(RequestMappingHandlerAdapter.java:705) ~[spring-webmvc-4.1.6.RELEASE.jar:4.1.6.RELEASE]
    at org.springframework.web.servlet.mvc.method.AbstractHandlerMethodAdapter.handle(AbstractHandlerMethodAdapter.java:85) ~[spring-webmvc-4.1.6.RELEASE.jar:4.1.6.RELEASE]
    at org.springframework.web.servlet.DispatcherServlet.doDispatch(DispatcherServlet.java:959) ~[spring-webmvc-4.1.6.RELEASE.jar:4.1.6.RELEASE]
    at org.springframework.web.servlet.DispatcherServlet.doService(DispatcherServlet.java:893) ~[spring-webmvc-4.1.6.RELEASE.jar:4.1.6.RELEASE]
    at org.springframework.web.servlet.FrameworkServlet.processRequest(FrameworkServlet.java:966) ~[spring-webmvc-4.1.6.RELEASE.jar:4.1.6.RELEASE]
    ... 81 common frames omitted
Caused by: java.sql.SQLTransientConnectionException: HikariPool-0 - Connection is not available, request timed out after 30000ms.
    at com.zaxxer.hikari.pool.HikariPool.getConnection(HikariPool.java:213) ~[HikariCP-2.4.1.jar:na]
    at com.zaxxer.hikari.pool.HikariPool.getConnection(HikariPool.java:163) ~[HikariCP-2.4.1.jar:na]
    at com.zaxxer.hikari.HikariDataSource.getConnection(HikariDataSource.java:85) ~[HikariCP-2.4.1.jar:na]
    at org.hibernate.engine.jdbc.connections.internal.DatasourceConnectionProviderImpl.getConnection(DatasourceConnectionProviderImpl.java:139) ~[hibernate-core-4.3.6.Final.jar:4.3.6.Final]
    at org.hibernate.internal.AbstractSessionImpl$NonContextualJdbcConnectionAccess.obtainConnection(AbstractSessionImpl.java:380) ~[hibernate-core-4.3.6.Final.jar:4.3.6.Final]
    at org.hibernate.engine.jdbc.internal.LogicalConnectionImpl.obtainConnection(LogicalConnectionImpl.java:228) ~[hibernate-core-4.3.6.Final.jar:4.3.6.Final]
    ... 126 common frames omitted
2015-10-06 12:10:12,651 DEBUG [Hikari housekeeper (pool HikariPool-0)] HikariPool: Before cleanup   pool HikariPool-0 stats (total=20, active=19, idle=1, waiting=0)
2015-10-06 12:10:12,652 DEBUG [Hikari housekeeper (pool HikariPool-0)] HikariPool: After cleanup    pool HikariPool-0 stats (total=20, active=19, idle=1, waiting=0)

Any clue would be helpful!

Upvotes: 132

Views: 265594

Answers (7)

urso
urso

Reputation: 51

I was a similar problem as described by user19316412

I'm using JdbcClient (springboot 3.2, java 21) and wanted to process the query result straight away.

        List<BigDecimal> out = jdbcClient
             .sql("""
                     SELECT DISTINCT percent
                     FROM order
                     WHERE active=true
                     """)
             .query((rs, __) -> rs.getBigDecimal("percent"))
             .stream()
             .map(bd -> bd.multiply(_100))
             .map(bd -> bd.setScale(0, RoundingMode.HALF_UP))
             .toList();

It looks quite ok, but quite quickly I received messages about the lack of connection to the database. Enable logging:

<logger name="com.zaxxer.hikari.pool" level="DEBUG" />

it showed the cause of the problem well:

[HikariPool-1 housekeeper] WARN  c.zaxxer.hikari.pool.ProxyLeakTask [] - Connection leak detection triggered for org.postgresql.jdbc.PgConnection@67e11bda on thread http-nio-8082-exec-3, stack trace follows
java.lang.Exception: Apparent connection leak detected
    at com.zaxxer.hikari.HikariDataSource.getConnection(HikariDataSource.java:128)
    at org.springframework.jdbc.datasource.DataSourceUtils.fetchConnection(DataSourceUtils.java:160)
    at org.springframework.jdbc.datasource.DataSourceUtils.doGetConnection(DataSourceUtils.java:118)
    at org.springframework.jdbc.datasource.DataSourceUtils.getConnection(DataSourceUtils.java:81)
    at org.springframework.jdbc.core.JdbcTemplate.execute(JdbcTemplate.java:653)
    at org.springframework.jdbc.core.JdbcTemplate.queryForStream(JdbcTemplate.java:844)
    at org.springframework.jdbc.core.JdbcTemplate.queryForStream(JdbcTemplate.java:863)
    at org.springframework.jdbc.core.namedparam.NamedParameterJdbcTemplate.queryForStream(NamedParameterJdbcTemplate.java:237)
    at org.springframework.jdbc.core.simple.DefaultJdbcClient$DefaultStatementSpec$NamedParamMappedQuerySpec.stream(DefaultJdbcClient.java:361)
    at pl.apinn.jflowers.DiscountController.ordersClientFromYear(DiscountController.java:59)
    at java.base/jdk.internal.reflect.DirectMethodHandleAccessor.invoke(DirectMethodHandleAccessor.java:103)
    at java.base/java.lang.reflect.Method.invoke(Method.java:578)

line: (DiscountController.java:59) points to .stream()

so I added a terminal operations: .list() on database query and it helped:

    List<BigDecimal> out = jdbcClient
            .sql("""
                    SELECT DISTINCT percent
                    FROM order
                    WHERE active=true
                    """)
            .query((rs, __) -> rs.getBigDecimal("percent"))
            .list()
            .stream()
            .map(bd -> bd.multiply(_100))
            .map(bd -> bd.setScale(0, RoundingMode.HALF_UP))
            .toList();

Upvotes: 3

user19316412
user19316412

Reputation: 61

I had a similar issue, and the culprit turned out to be the use of jdbc's "queryForStream". More info in the article below, but essentially you need to explicitly close the stream or the connection remains open.

https://mjchi7.github.io/posts/jdbctemplate-queryforstream-connection-leak/

Upvotes: 6

mumbasa
mumbasa

Reputation: 822

I faced the same problem on a project i was working with a colleague. He was using jdbc and he forgot to close some of his database connections after completion. this threw this error. make sure every database connection is closed if you are not using Hibernate or JDBC template.. Visit this site for more sample https://mkyong.com/jdbc/hikaripool-1-connection-is-not-available-request-timed-out-after-30002ms/

Upvotes: 3

Daniel Krait
Daniel Krait

Reputation: 99

problem was solved for me by adding the following properties to application.properties file:

  spring.datasource.hikari.connection-test-query=SELECT 1 FROM DUAL
  spring.datasource.hikari.connection-timeout=600000
  spring.datasource.hikari.maximum-pool-size=500
  spring.datasource.hikari.max-lifetime=1800000
  spring.datasource.hikari.minimum-idle=20
  spring.datasource.hikari.validation-timeout=3000
  spring.datasource.hikari.idle-timeout=60000

Upvotes: 9

Asif Kamran Malick
Asif Kamran Malick

Reputation: 3171

The VPN issue mentioned by AO_ is quite common yet neglected one.

One of the possible reasons could be that a person is requesting resources from server where requests are blocked by the organization's VPN. In that case one can try connecting via the VPN. This has happened to me in the past.

In a distributed work culture this can happen on several occasions mostly when the Internet connection gets lost/reset which disconnects from the VPN. The only way in such cases is to connect back to the VPN once the internet connection is back.

Upvotes: 0

Nitin
Nitin

Reputation: 1650

From stack trace:

HikariPool: Timeout failure pool HikariPool-0 stats (total=20, active=20, idle=0, waiting=0) Means pool reached maximum connections limit set in configuration.

The next line: HikariPool-0 - Connection is not available, request timed out after 30000ms. Means pool waited 30000ms for free connection but your application not returned any connection meanwhile.

Mostly it is connection leak (connection is not closed after borrowing from pool), set leakDetectionThreshold to the maximum value that you expect SQL query would take to execute.

otherwise, your maximum connections 'at a time' requirement is higher than 20 !

Upvotes: 55

dfche
dfche

Reputation: 3693

I managed to fix it finally. The problem is not related to HikariCP. The problem persisted because of some complex methods in REST controllers executing multiple changes in DB through JPA repositories. For some reasons calls to these interfaces resulted in a growing number of "freezed" active connections, exhausting the pool. Either annotating these methods as @Transactional or enveloping all the logic in a single call to transactional service method seem to solve the problem.

Upvotes: 104

Related Questions