Spring boot, hibernate, hikariCP and mysql no communication after inactivity

Question

We are facing a weird error. When we first srtart the server we can login etc. After a few hours of inactivity we cannot login anymore. We can solve the problem by restarting the application, but it will occur at least one time each day. To restart the application is only a shortterm solution and we need to find a more stable solution to this a critical problem.

I am using the following configuration:

Environment

Hibernate       : 5.2.13
JPA             : spring-boot-starter-data-jpa (1.5.10)
JDK version     : 1.8.0_191
Database        : Mysql (version 5.7.25)
JDBC Driver     : 5.1.45
Spring Boot     : 1.5.10
OS              : Ubuntu 16.04.6

Hikari

HikariCP version: 2.7.7

datasource:
        type: com.zaxxer.hikari.HikariDataSource
        driver-class-name: com.mysql.jdbc.Driver
        url: jdbc:mysql://localhost:3306/<database>?useUnicode=true&characterEncoding=utf8&useSSL=false
        username: <username>
        password: <secret password>
        hikari:
            data-source-properties:
                cachePrepStmts: true
                prepStmtCacheSize: 250
                prepStmtCacheSqlLimit: 2048
                useServerPrepStmts: true

From the application log:

AuthenticationServiceException[http-nio-18080-exec-9] UserJWTController: Authentication exception trace: {}
org.springframework.security.authentication.InternalAuthenticationServiceException: Could not open JPA EntityManager for transaction; nested exception is org.hibernate.TransactionException: JDBC begin transaction failed: uthentication.dao.DaoAuthenticationProvider.retrieveUser(DaoAuthenticationProvider.java:126)
        at org.springframework.security.authentication.dao.AbstractUserDetailsAuthenticationProvider.authenticate(AbstractUserDetailsAuthenticationProvider.java:144)
        at org.springframework.security.authentication.ProviderManager.authenticate(ProviderManager.java:174)
        at com.example.web.rest.UserJWTController.authorize(UserJWTController.java:48)
        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
        at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
        at java.lang.reflect.Method.invoke(Method.java:498)
        at org.springframework.web.method.support.InvocableHandlerMethod.doInvoke(InvocableHandlerMethod.java:205)
        at org.springframework.web.method.support.InvocableHandlerMethod.invokeForRequest(InvocableHandlerMethod.java:133)
        at org.springframework.web.servlet.mvc.method.annotation.ServletInvocableHandlerMethod.invokeAndHandle(ServletInvocableHandlerMethod.java:97)
        at org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.invokeHandlerMethod(RequestMappingHandlerAdapter.java:827)
        ...
        ...
        ...
        ...
        ...
        ...
        Caused by: org.springframework.transaction.CannotCreateTransactionException: Could not open JPA EntityManager for transaction; nested exception is org.hibernate.TransactionException: JDBC begin transaction failed: 
        at org.springframework.orm.jpa.JpaTransactionManager.doBegin(JpaTransactionManager.java:431)
        at org.springframework.transaction.support.AbstractPlatformTransactionManager.getTransaction(AbstractPlatformTransactionManager.java:373)
        at org.springframework.transaction.interceptor.TransactionAspectSupport.createTransactionIfNecessary(TransactionAspectSupport.java:461)
        at org.springframework.transaction.interceptor.TransactionAspectSupport.invokeWithinTransaction(TransactionAspectSupport.java:277)
        at org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:96)
        at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:179)
        at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:213)
        at com.sun.proxy.$Proxy159.loadUserByUsername(Unknown Source)
        at org.springframework.security.authentication.dao.DaoAuthenticationProvider.retrieveUser(DaoAuthenticationProvider.java:114)
        ... 107 common frames omitted
Caused by: org.hibernate.TransactionException: JDBC begin transaction failed: 
        at org.hibernate.resource.jdbc.internal.AbstractLogicalConnectionImplementor.begin(AbstractLogicalConnectionImplementor.java:73)
        at org.hibernate.resource.jdbc.internal.LogicalConnectionManagedImpl.begin(LogicalConnectionManagedImpl.java:263)
        at org.hibernate.resource.transaction.backend.jdbc.internal.JdbcResourceLocalTransactionCoordinatorImpl$TransactionDriverControlImpl.begin(JdbcResourceLocalTransactionCoordinatorImpl.java:214)
        at org.hibernate.engine.transaction.internal.TransactionImpl.begin(TransactionImpl.java:56)
        at org.springframework.orm.jpa.vendor.HibernateJpaDialect.beginTransaction(HibernateJpaDialect.java:189)
        at org.springframework.orm.jpa.JpaTransactionManager.doBegin(JpaTransactionManager.java:380)
        ... 115 common frames omitted
Caused by: com.mysql.jdbc.exceptions.jdbc4.MySQLNonTransientConnectionException: No operations allowed after connection closed.
        at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method)
        at sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:62)
        at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45)
        at java.lang.reflect.Constructor.newInstance(Constructor.java:423)
        at com.mysql.jdbc.Util.handleNewInstance(Util.java:425)
        at com.mysql.jdbc.Util.getInstance(Util.java:408)
        at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:919)
        at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:898)
        at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:887)
        at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:861)
        at com.mysql.jdbc.ConnectionImpl.throwConnectionClosedException(ConnectionImpl.java:1184)
        at com.mysql.jdbc.ConnectionImpl.checkClosed(ConnectionImpl.java:1179)
        at com.mysql.jdbc.ConnectionImpl.setAutoCommit(ConnectionImpl.java:4770)
        at sun.reflect.GeneratedMethodAccessor325.invoke(Unknown Source)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
        at java.lang.reflect.Method.invoke(Method.java:498)
        at org.apache.tomcat.jdbc.pool.ProxyConnection.invoke(ProxyConnection.java:126)
        at org.apache.tomcat.jdbc.pool.JdbcInterceptor.invoke(JdbcInterceptor.java:108)
        at org.apache.tomcat.jdbc.pool.interceptor.AbstractCreateStatementInterceptor.invoke(AbstractCreateStatementInterceptor.java:79)
        at org.apache.tomcat.jdbc.pool.JdbcInterceptor.invoke(JdbcInterceptor.java:108)
        at org.apache.tomcat.jdbc.pool.DisposableConnectionFacade.invoke(DisposableConnectionFacade.java:81)
        at com.sun.proxy.$Proxy98.setAutoCommit(Unknown Source)
        at org.hibernate.resource.jdbc.internal.AbstractLogicalConnectionImplementor.begin(AbstractLogicalConnectionImplementor.java:67)
        ... 120 common frames omitted
Caused by: com.mysql.jdbc.exceptions.jdbc4.CommunicationsException: Communications link failure

The last packet successfully received from the server was 33,215,831 milliseconds ago.  The last packet sent successfully to the server was 7 milliseconds ago.

I really don't know how to trigger this issue manually after a restart so we have to wait a few hours before this state kicks in.

It seems that we are not the only one having this issue, but after days without solving it, it's a bit frustrating.

We need to solve this soon, any ideas?

Answer 1

I found a solution to our problem. It seemed like the configuration we did in the yaml file didn't work properly so I had to configure the HikariCP programmatically.

I removed the configuration for hikari in the yaml file and afterwards the datasource looked like:

datasource:
    type: com.zaxxer.hikari.HikariDataSource

And the datasource config looks the following:

@Configuration
public class DatasourceConfiguration {

    private static final Logger log = LoggerFactory.getLogger(DatasourceConfiguration.class);

    private final Environment env;

    public DatasourceConfiguration(Environment env) {
        this.env = env;
    }

    @Bean(name="primaryDatasource")
    @Primary
    @ConfigurationProperties(prefix="spring.datasource")
    public DataSource dataSource() {

        HikariConfig config = new HikariConfig();
        config.setDriverClassName("com.mysql.jdbc.Driver");
        config.setPoolName("JPAHikariCP");
        config.setAutoCommit(false);
        config.setConnectionTestQuery("SELECT 1");

        String profile = env.getProperty("spring.profiles.active");

        Optional<String> db = Optional.of("database");
        Optional<String> username = Optional.of("user");
        Optional<String> password = Optional.of("pass");

        if("test".equals(profile) || "dev".equals(profile)) {
            config.addDataSourceProperty("cachePrepStmts", true);
            config.addDataSourceProperty("prepStmtCacheSize", 250);
            config.addDataSourceProperty("prepStmtCacheSqlLimit", 2048);
            config.addDataSourceProperty("useServerPrepStmts", true);
        }

        config.setJdbcUrl(String.format("jdbc:mysql://localhost:3306/%s?useUnicode=true&characterEncoding=utf8&useSSL=false", db.get()));
        config.setUsername(username.get());
        config.setPassword(password.get());

        return new HikariDataSource(config);
    }



}

And now it works.