Spring Data JPA - Database Issues Connection is not available, request timed out after 30000ms

Question

I have a pretty typical Spring Boot based web app, Spring Boot version 2.2.4 with the following "starters": data-jpa, mail, security, web, thymeleaf. I am using PostgreSQL as my data source and Spring Session JDBC. The app will run fine for a few hours, but eventually throw an error related to database connectivity:

2020-02-07 02:36:42.891  WARN 14412 --- [https-jsse-nio-8445-exec-9] o.h.engine.jdbc.spi.SqlExceptionHelper   : SQL Error: 0, SQLState: null
2020-02-07 02:36:42.891 ERROR 14412 --- [https-jsse-nio-8445-exec-9] o.h.engine.jdbc.spi.SqlExceptionHelper   : HikariPool-1 - Connection is not available, request timed out after 30001ms.
2020-02-07 02:36:42.891 ERROR 14412 --- [https-jsse-nio-8445-exec-9] o.a.c.c.C.[.[.[.[dispatcherServlet]      : Servlet.service() for servlet [dispatcherServlet] threw exception

The full stack trace:

    2020-02-07 02:36:42.891  WARN 14412 --- [https-jsse-nio-8445-exec-9] o.h.engine.jdbc.spi.SqlExceptionHelper   : SQL Error: 0, SQLState: null
2020-02-07 02:36:42.891 ERROR 14412 --- [https-jsse-nio-8445-exec-9] o.h.engine.jdbc.spi.SqlExceptionHelper   : HikariPool-1 - Connection is not available, request timed out after 30001ms.
2020-02-07 02:36:42.891 ERROR 14412 --- [https-jsse-nio-8445-exec-9] o.a.c.c.C.[.[.[.[dispatcherServlet]      : Servlet.service() for servlet [dispatcherServlet] threw exception

org.springframework.transaction.CannotCreateTransactionException: Could not open JPA EntityManager for transaction; nested exception is org.hibernate.exception.JDBCConnectionException: Unable to acquire JDBC Connection
    at org.springframework.orm.jpa.JpaTransactionManager.doBegin(JpaTransactionManager.java:448) ~[spring-orm-5.2.3.RELEASE.jar!/:5.2.3.RELEASE]
    at org.springframework.transaction.support.AbstractPlatformTransactionManager.getTransaction(AbstractPlatformTransactionManager.java:376) ~[spring-tx-5.2.3.RELEASE.jar!/:5.2.3.RELEASE]
    at org.springframework.transaction.support.TransactionTemplate.execute(TransactionTemplate.java:137) ~[spring-tx-5.2.3.RELEASE.jar!/:5.2.3.RELEASE]
    at org.springframework.session.jdbc.JdbcIndexedSessionRepository.findById(JdbcIndexedSessionRepository.java:414) ~[spring-session-jdbc-2.2.0.RELEASE.jar!/:2.2.0.RELEASE]
    at org.springframework.session.jdbc.JdbcIndexedSessionRepository.findById(JdbcIndexedSessionRepository.java:130) ~[spring-session-jdbc-2.2.0.RELEASE.jar!/:2.2.0.RELEASE]
    at org.springframework.session.web.http.SessionRepositoryFilter$SessionRepositoryRequestWrapper.getRequestedSession(SessionRepositoryFilter.java:351) ~[spring-session-core-2.2.0.RELEASE.jar!/:2.2.0.RELEASE]
    at org.springframework.session.web.http.SessionRepositoryFilter$SessionRepositoryRequestWrapper.getSession(SessionRepositoryFilter.java:289) ~[spring-session-core-2.2.0.RELEASE.jar!/:2.2.0.RELEASE]
    at org.springframework.session.web.http.SessionRepositoryFilter$SessionRepositoryRequestWrapper.getSession(SessionRepositoryFilter.java:192) ~[spring-session-core-2.2.0.RELEASE.jar!/:2.2.0.RELEASE]
    at javax.servlet.http.HttpServletRequestWrapper.getSession(HttpServletRequestWrapper.java:244) ~[tomcat-embed-core-9.0.30.jar!/:9.0.30]
    at org.springframework.security.web.savedrequest.HttpSessionRequestCache.getRequest(HttpSessionRequestCache.java:71) ~[spring-security-web-5.2.1.RELEASE.jar!/:5.2.1.RELEASE]
    at org.springframework.security.web.savedrequest.HttpSessionRequestCache.getMatchingRequest(HttpSessionRequestCache.java:92) ~[spring-security-web-5.2.1.RELEASE.jar!/:5.2.1.RELEASE]
    at org.springframework.security.web.savedrequest.RequestCacheAwareFilter.doFilter(RequestCacheAwareFilter.java:60) ~[spring-security-web-5.2.1.RELEASE.jar!/:5.2.1.RELEASE]
    at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:334) ~[spring-security-web-5.2.1.RELEASE.jar!/:5.2.1.RELEASE]
    at org.springframework.security.web.authentication.AbstractAuthenticationProcessingFilter.doFilter(AbstractAuthenticationProcessingFilter.java:200) ~[spring-security-web-5.2.1.RELEASE.jar!/:5.2.1.RELEASE]
    at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:334) ~[spring-security-web-5.2.1.RELEASE.jar!/:5.2.1.RELEASE]
    at org.springframework.security.web.authentication.logout.LogoutFilter.doFilter(LogoutFilter.java:116) ~[spring-security-web-5.2.1.RELEASE.jar!/:5.2.1.RELEASE]
    at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:334) ~[spring-security-web-5.2.1.RELEASE.jar!/:5.2.1.RELEASE]
    at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:103) ~[spring-web-5.2.3.RELEASE.jar!/:5.2.3.RELEASE]
    at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:334) ~[spring-security-web-5.2.1.RELEASE.jar!/:5.2.1.RELEASE]
    at org.springframework.security.web.context.SecurityContextPersistenceFilter.doFilter(SecurityContextPersistenceFilter.java:82) ~[spring-security-web-5.2.1.RELEASE.jar!/:5.2.1.RELEASE]
    at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:334) ~[spring-security-web-5.2.1.RELEASE.jar!/:5.2.1.RELEASE]
    at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:103) ~[spring-web-5.2.3.RELEASE.jar!/:5.2.3.RELEASE]
    at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:334) ~[spring-security-web-5.2.1.RELEASE.jar!/:5.2.1.RELEASE]
    at com.midamcorp.team.config.SimpleCORSFilter.doFilter(SimpleCORSFilter.java:43) ~[classes!/:na]
    at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:334) ~[spring-security-web-5.2.1.RELEASE.jar!/:5.2.1.RELEASE]
    at org.springframework.security.web.FilterChainProxy.doFilterInternal(FilterChainProxy.java:215) ~[spring-security-web-5.2.1.RELEASE.jar!/:5.2.1.RELEASE]
    at org.springframework.security.web.FilterChainProxy.doFilter(FilterChainProxy.java:178) ~[spring-security-web-5.2.1.RELEASE.jar!/:5.2.1.RELEASE]
    at org.springframework.web.filter.DelegatingFilterProxy.invokeDelegate(DelegatingFilterProxy.java:358) ~[spring-web-5.2.3.RELEASE.jar!/:5.2.3.RELEASE]
    at org.springframework.web.filter.DelegatingFilterProxy.doFilter(DelegatingFilterProxy.java:271) ~[spring-web-5.2.3.RELEASE.jar!/:5.2.3.RELEASE]
    at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193) ~[tomcat-embed-core-9.0.30.jar!/:9.0.30]
    at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166) ~[tomcat-embed-core-9.0.30.jar!/:9.0.30]
    at org.springframework.session.web.http.SessionRepositoryFilter.doFilterInternal(SessionRepositoryFilter.java:141) ~[spring-session-core-2.2.0.RELEASE.jar!/:2.2.0.RELEASE]
    at org.springframework.session.web.http.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:82) ~[spring-session-core-2.2.0.RELEASE.jar!/:2.2.0.RELEASE]
    at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193) ~[tomcat-embed-core-9.0.30.jar!/:9.0.30]
    at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166) ~[tomcat-embed-core-9.0.30.jar!/:9.0.30]
    at org.apache.catalina.core.ApplicationDispatcher.invoke(ApplicationDispatcher.java:712) ~[tomcat-embed-core-9.0.30.jar!/:9.0.30]
    at org.apache.catalina.core.ApplicationDispatcher.processRequest(ApplicationDispatcher.java:461) ~[tomcat-embed-core-9.0.30.jar!/:9.0.30]
    at org.apache.catalina.core.ApplicationDispatcher.doForward(ApplicationDispatcher.java:384) ~[tomcat-embed-core-9.0.30.jar!/:9.0.30]
    at org.apache.catalina.core.ApplicationDispatcher.forward(ApplicationDispatcher.java:312) ~[tomcat-embed-core-9.0.30.jar!/:9.0.30]
    at org.apache.catalina.core.StandardHostValve.custom(StandardHostValve.java:394) ~[tomcat-embed-core-9.0.30.jar!/:9.0.30]
    at org.apache.catalina.core.StandardHostValve.status(StandardHostValve.java:253) ~[tomcat-embed-core-9.0.30.jar!/:9.0.30]
    at org.apache.catalina.core.StandardHostValve.throwable(StandardHostValve.java:348) ~[tomcat-embed-core-9.0.30.jar!/:9.0.30]
    at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:173) ~[tomcat-embed-core-9.0.30.jar!/:9.0.30]
    at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:92) ~[tomcat-embed-core-9.0.30.jar!/:9.0.30]
    at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:74) ~[tomcat-embed-core-9.0.30.jar!/:9.0.30]
    at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:343) ~[tomcat-embed-core-9.0.30.jar!/:9.0.30]
    at org.apache.coyote.http11.Http11Processor.service(Http11Processor.java:367) ~[tomcat-embed-core-9.0.30.jar!/:9.0.30]
    at org.apache.coyote.AbstractProcessorLight.process(AbstractProcessorLight.java:65) ~[tomcat-embed-core-9.0.30.jar!/:9.0.30]
    at org.apache.coyote.AbstractProtocol$ConnectionHandler.process(AbstractProtocol.java:860) ~[tomcat-embed-core-9.0.30.jar!/:9.0.30]
    at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1598) ~[tomcat-embed-core-9.0.30.jar!/:9.0.30]
    at org.apache.tomcat.util.net.SocketProcessorBase.run(SocketProcessorBase.java:49) ~[tomcat-embed-core-9.0.30.jar!/:9.0.30]
    at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) ~[na:na]
    at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) ~[na:na]
    at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61) ~[tomcat-embed-core-9.0.30.jar!/:9.0.30]
    at java.base/java.lang.Thread.run(Thread.java:834) ~[na:na]
Caused by: org.hibernate.exception.JDBCConnectionException: Unable to acquire JDBC Connection
    at org.hibernate.exception.internal.SQLExceptionTypeDelegate.convert(SQLExceptionTypeDelegate.java:48) ~[hibernate-core-5.4.10.Final.jar!/:5.4.10.Final]
    at org.hibernate.exception.internal.StandardSQLExceptionConverter.convert(StandardSQLExceptionConverter.java:42) ~[hibernate-core-5.4.10.Final.jar!/:5.4.10.Final]
    at org.hibernate.engine.jdbc.spi.SqlExceptionHelper.convert(SqlExceptionHelper.java:113) ~[hibernate-core-5.4.10.Final.jar!/:5.4.10.Final]
    at org.hibernate.engine.jdbc.spi.SqlExceptionHelper.convert(SqlExceptionHelper.java:99) ~[hibernate-core-5.4.10.Final.jar!/:5.4.10.Final]
    at org.hibernate.resource.jdbc.internal.LogicalConnectionManagedImpl.acquireConnectionIfNeeded(LogicalConnectionManagedImpl.java:107) ~[hibernate-core-5.4.10.Final.jar!/:5.4.10.Final]
    at org.hibernate.resource.jdbc.internal.LogicalConnectionManagedImpl.getPhysicalConnection(LogicalConnectionManagedImpl.java:134) ~[hibernate-core-5.4.10.Final.jar!/:5.4.10.Final]
    at org.hibernate.resource.jdbc.internal.LogicalConnectionManagedImpl.getConnectionForTransactionManagement(LogicalConnectionManagedImpl.java:250) ~[hibernate-core-5.4.10.Final.jar!/:5.4.10.Final]
    at org.hibernate.resource.jdbc.internal.LogicalConnectionManagedImpl.begin(LogicalConnectionManagedImpl.java:258) ~[hibernate-core-5.4.10.Final.jar!/:5.4.10.Final]
    at org.hibernate.resource.transaction.backend.jdbc.internal.JdbcResourceLocalTransactionCoordinatorImpl$TransactionDriverControlImpl.begin(JdbcResourceLocalTransactionCoordinatorImpl.java:246) ~[hibernate-core-5.4.10.Final.jar!/:5.4.10.Final]
    at org.hibernate.engine.transaction.internal.TransactionImpl.begin(TransactionImpl.java:83) ~[hibernate-core-5.4.10.Final.jar!/:5.4.10.Final]
    at org.springframework.orm.jpa.vendor.HibernateJpaDialect.beginTransaction(HibernateJpaDialect.java:184) ~[spring-orm-5.2.3.RELEASE.jar!/:5.2.3.RELEASE]
    at org.springframework.orm.jpa.JpaTransactionManager.doBegin(JpaTransactionManager.java:402) ~[spring-orm-5.2.3.RELEASE.jar!/:5.2.3.RELEASE]
    ... 54 common frames omitted
Caused by: java.sql.SQLTransientConnectionException: HikariPool-1 - Connection is not available, request timed out after 30001ms.
    at com.zaxxer.hikari.pool.HikariPool.createTimeoutException(HikariPool.java:689) ~[HikariCP-3.4.2.jar!/:na]
    at com.zaxxer.hikari.pool.HikariPool.getConnection(HikariPool.java:196) ~[HikariCP-3.4.2.jar!/:na]
    at com.zaxxer.hikari.pool.HikariPool.getConnection(HikariPool.java:161) ~[HikariCP-3.4.2.jar!/:na]
    at com.zaxxer.hikari.HikariDataSource.getConnection(HikariDataSource.java:128) ~[HikariCP-3.4.2.jar!/:na]
    at org.hibernate.engine.jdbc.connections.internal.DatasourceConnectionProviderImpl.getConnection(DatasourceConnectionProviderImpl.java:122) ~[hibernate-core-5.4.10.Final.jar!/:5.4.10.Final]
    at org.hibernate.internal.NonContextualJdbcConnectionAccess.obtainConnection(NonContextualJdbcConnectionAccess.java:38) ~[hibernate-core-5.4.10.Final.jar!/:5.4.10.Final]
    at org.hibernate.resource.jdbc.internal.LogicalConnectionManagedImpl.acquireConnectionIfNeeded(LogicalConnectionManagedImpl.java:104) ~[hibernate-core-5.4.10.Final.jar!/:5.4.10.Final]
    ... 61 common frames omitted

The DB relevant properties in my application.properties:

primary.datasource.url=jdbc:postgresql://localhost:5432/main
primary.datasource.username=xxx
primary.datasource.password=xxx

spring.session.store-type=jdbc
session.datasource.url=jdbc:postgresql://localhost:5432/session
session.datasource.driverClassName=org.postgresql.Driver
session.datasource.username=xxx
session.datasource.password=xxx

Database config:

@Configuration
@EnableTransactionManagement
public class DatabaseConfig {

    @Bean
    @Primary
    @ConfigurationProperties("primary.datasource")
    public DataSourceProperties primaryDataSourceProperties() {
        return new DataSourceProperties();
    }

    @Bean
    @Primary
    public DataSource primaryDataSource() {
        return primaryDataSourceProperties().initializeDataSourceBuilder().type(HikariDataSource.class).build();
    }

    @Bean
    @ConfigurationProperties("session.datasource")
    public DataSourceProperties sessionDataSourceProperties() {
        return new DataSourceProperties();
    }

    @Bean
    @SpringSessionDataSource
    public DataSource springSessionDataSource() {
        return sessionDataSourceProperties().initializeDataSourceBuilder().type(HikariDataSource.class).build();
    }
}

This app is similar in structure to many I have built before and I never encountered the issue. The app has been in production for some time and did not not encounter the issue. This started maybe a month ago, but has become increasingly frequent. The app is regularly updated, but no updates to the database logic has been performed for quite a while. Another app contacts the same DB and has not encountered this issue. Logs in the database reveal no errors.

Any pointers would be greatly appreciated. Honestly, I am a bit at a loss. I set logging.level.com.zaxxer.hikari=DEBUG and logging.level.org.hibernate=INFO (debug produced WAY too much output irrelevant to the issue) in hopes that it could help me trace the issue, but no success. The full stack with these levels is shown above.

Answer 1

What is happening is your application is trying to get a DB Connection from the pool and it is timing out after 30 seconds (the default) because no more connections are available (they are all in use).

Are you setting any of these values for Hikari or just accepting the defaults?

datasource:
  hikari:
    connection-init-sql: SELECT 1
    connection-test-query: SELECT 1
    auto-commit: true
    connection-timeout: 3000
    idle-timeout: 600000
    leak-detection-threshold: 45000
    max-lifetime: 1800000
    maximum-pool-size: 10
    validation-timeout: 5000

To find your problem I suggest you do two things:

1. Turn on Leak Detection: leak-detection-threshold: 45000 and that will print out a log statement like this:

2020-02-07 18:16:26,100 WARN HikariPool-1 housekeeper ProxyLeakTask.? - Connection leak detection triggered for org.postgresql.jdbc.PgConnection@2dda7a8e on thread https-jsse-nio-8458-exec-11, stack trace follows
java.lang.Exception: Apparent connection leak detected
 at com.zaxxer.hikari.HikariDataSource.getConnection(HikariDataSource.java:128)
 at org.hibernate.engine.jdbc.connections.internal.DatasourceConnectionProviderImpl.getConnection(DatasourceConnectionProviderImpl.java:122)
 at org.hibernate.internal.NonContextualJdbcConnectionAccess.obtainConnection(NonContextualJdbcConnectionAccess.java:38)
 at org.hibernate.resource.jdbc.internal.LogicalConnectionManagedImpl.acquireConnectionIfNeeded(LogicalConnectionManagedImpl.java:104)
 at org.hibernate.resource.jdbc.internal.LogicalConnectionManagedImpl.getPhysicalConnection(LogicalConnectionManagedImpl.java:134)
 at org.hibernate.internal.SessionImpl.connection(SessionImpl.java:462)
 at jdk.internal.reflect.GeneratedMethodAccessor206.invoke(Unknown Source)
 at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
 at java.base/java.lang.reflect.Method.invoke(Method.java:566)
 at org.springframework.util.ReflectionUtils.invokeMethod(ReflectionUtils.java:282)
 at org.springframework.util.ReflectionUtils.invokeMethod(ReflectionUtils.java:266)
 at org.springframework.orm.jpa.vendor.HibernateJpaDialect$HibernateConnectionHandle.doGetConnection(HibernateJpaDialect.java:430)
 at org.springframework.orm.jpa.vendor.HibernateJpaDialect.beginTransaction(HibernateJpaDialect.java:174)
 at org.springframework.orm.jpa.JpaTransactionManager.doBegin(JpaTransactionManager.java:402)
 at org.springframework.transaction.support.AbstractPlatformTransactionManager.getTransaction(AbstractPlatformTransactionManager.java:376)
 at org.springframework.transaction.interceptor.TransactionAspectSupport.createTransactionIfNecessary(TransactionAspectSupport.java:572)
...

That will tell you where in your application, processes that are holding on to connections for longer than 45 seconds. You can change to 30 if you want.

2. enable this DEBUG in your logger:

    logging:
      level:
        com.zaxxer.hikari.pool.HikariPool: DEBUG

which will log statements like this every so often:

2020-02-07 04:17:38,798 DEBUG HikariPool-1 housekeeper HikariPool.logPoolState - HikariPool-1 - Pool stats (total=10, active=1, idle=9, waiting=0)

When active is equal to the total you know your pool is in full use and you will start to see that waiting number rise. Basically, at that point you need whatever process is leaking the connections to relinquish the connections or restart your app. Otherwise, you will start seeing those errors.

Also of note, 30 seconds (the default) is a long to wait for a connection to timeout. If this is a request coming from a web page, remember there is an actual user waiting for 30 seconds (most people are too impatient to wait that long) for something to happen. As you can see in our app we set it 3000ms (or 3 seconds).