Receiving a CommunicationsException using Spring Data JPA and mysql database

Question

on a project i am importing data from an oracle database into a mysql database. The import is working fine. I user hibernate envers to track changes on a specific field of an entity. However, if i try to request the stored data via a rest endpoint (controller -> service -> repository) i receive a exception.

If i call the endpoint on a daily basis, the application works fine. But if the the endpoint is not triggered e.g. over the weekend, then the application fails.

Following the dependencies i am using in the project:

<parent>
    <groupId>org.springframework.boot</groupId>
    <artifactId>spring-boot-starter-parent</artifactId>
    <version>2.0.1.RELEASE</version>
    <relativePath/>
</parent>

<dependency>
<groupId>org.springframework.boot</groupId>
<artifactId>spring-boot-starter-data-jpa</artifactId>
</dependency>
<dependency>
    <groupId>mysql</groupId>
    <artifactId>mysql-connector-java</artifactId>
    <scope>runtime</scope>
</dependency>
<dependency>
    <groupId>com.oracle.jdbc</groupId>
    <artifactId>ojdbc8</artifactId>
    <version>${oracle.version}</version>
    <scope>runtime</scope>
</dependency>
<dependency>
    <groupId>org.hibernate</groupId>
    <artifactId>hibernate-java8</artifactId>
</dependency>
<dependency>
    <groupId>org.hibernate</groupId>
    <artifactId>hibernate-envers</artifactId>
</dependency>
<dependency>
    <groupId>org.liquibase</groupId>
    <artifactId>liquibase-core</artifactId>
</dependency>

The application properties for the mysql database connection:

spring:
  datasource:
    url: jdbc:mysql://servername:3306/schema
    username: username
    password: password
    initialize-mode: never
  jpa:
    open-in-view: false
    database-platform: org.hibernate.dialect.MySQL5Dialect
  liquibase:
    change-log: classpath:/db/changelog/changelog-master.xml

The configuration of the primary database, I am using the default hikari connection pool.

@SpringBootApplication
@EnableScheduling
public class MyApplication {

    public static void main(String[] args) {
        SpringApplication.run(MyApplication.class, args);
    }

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

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

    @Bean
    @Primary
    public JdbcTemplate primaryJdbcTemplate() {
        return new JdbcTemplate(primaryDataSource());
    }
}

The following exception do i receive, if the application was not called over a longer period:

2018-09-17T11:50:11.639708697Z com.mysql.jdbc.exceptions.jdbc4.CommunicationsException: The last packet successfully received from the server was 271,547,086 milliseconds ago.  The last packet sent successfully to the server was 271,547,087 milliseconds ago. is longer than the server configured value of 'wait_timeout'. You should consider either expiring and/or testing connection validity before use in your application, increasing the server configured values for client timeouts, or using the Connector/J connection property 'autoReconnect=true' to avoid this problem.
2018-09-17T11:50:11.639718269Z  at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method) ~[na:1.8.0_181]
2018-09-17T11:50:11.639724140Z  at sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:62) ~[na:1.8.0_181]
2018-09-17T11:50:11.639729703Z  at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45) ~[na:1.8.0_181]
2018-09-17T11:50:11.639735197Z  at java.lang.reflect.Constructor.newInstance(Constructor.java:423) ~[na:1.8.0_181]
2018-09-17T11:50:11.639740378Z  at com.mysql.jdbc.Util.handleNewInstance(Util.java:425) ~[mysql-connector-java-5.1.46.jar!/:5.1.46]
2018-09-17T11:50:11.639745633Z  at com.mysql.jdbc.SQLError.createCommunicationsException(SQLError.java:990) ~[mysql-connector-java-5.1.46.jar!/:5.1.46]
2018-09-17T11:50:11.639751054Z  at com.mysql.jdbc.MysqlIO.send(MysqlIO.java:3749) ~[mysql-connector-java-5.1.46.jar!/:5.1.46]
2018-09-17T11:50:11.639756342Z  at com.mysql.jdbc.MysqlIO.sendCommand(MysqlIO.java:2512) ~[mysql-connector-java-5.1.46.jar!/:5.1.46]
2018-09-17T11:50:11.639772891Z  at com.mysql.jdbc.MysqlIO.sqlQueryDirect(MysqlIO.java:2683) ~[mysql-connector-java-5.1.46.jar!/:5.1.46]
2018-09-17T11:50:11.639778495Z  at com.mysql.jdbc.ConnectionImpl.execSQL(ConnectionImpl.java:2486) ~[mysql-connector-java-5.1.46.jar!/:5.1.46]
2018-09-17T11:50:11.639783448Z  at com.mysql.jdbc.PreparedStatement.executeInternal(PreparedStatement.java:1858) ~[mysql-connector-java-5.1.46.jar!/:5.1.46]
2018-09-17T11:50:11.639789900Z  at com.mysql.jdbc.PreparedStatement.executeQuery(PreparedStatement.java:1966) ~[mysql-connector-java-5.1.46.jar!/:5.1.46]
2018-09-17T11:50:11.639795247Z  at com.zaxxer.hikari.pool.ProxyPreparedStatement.executeQuery(ProxyPreparedStatement.java:52) ~[HikariCP-2.7.8.jar!/:na]
2018-09-17T11:50:11.639800145Z  at com.zaxxer.hikari.pool.HikariProxyPreparedStatement.executeQuery(HikariProxyPreparedStatement.java) [HikariCP-2.7.8.jar!/:na]
2018-09-17T11:50:11.639805182Z  at org.hibernate.engine.jdbc.internal.ResultSetReturnImpl.extract(ResultSetReturnImpl.java:60) [hibernate-core-5.2.16.Final.jar!/:5.2.16.Final]
2018-09-17T11:50:11.639810237Z  at org.hibernate.loader.Loader.getResultSet(Loader.java:2168) [hibernate-core-5.2.16.Final.jar!/:5.2.16.Final]
2018-09-17T11:50:11.639815102Z  at org.hibernate.loader.Loader.executeQueryStatement(Loader.java:1931) [hibernate-core-5.2.16.Final.jar!/:5.2.16.Final]
2018-09-17T11:50:11.639819990Z  at org.hibernate.loader.Loader.executeQueryStatement(Loader.java:1893) [hibernate-core-5.2.16.Final.jar!/:5.2.16.Final]
2018-09-17T11:50:11.639824896Z  at org.hibernate.loader.Loader.doQuery(Loader.java:938) [hibernate-core-5.2.16.Final.jar!/:5.2.16.Final]
2018-09-17T11:50:11.639829655Z  at org.hibernate.loader.Loader.doQueryAndInitializeNonLazyCollections(Loader.java:341) [hibernate-core-5.2.16.Final.jar!/:5.2.16.Final]
2018-09-17T11:50:11.639834611Z  at org.hibernate.loader.Loader.doList(Loader.java:2692) [hibernate-core-5.2.16.Final.jar!/:5.2.16.Final]
2018-09-17T11:50:11.639839395Z  at org.hibernate.loader.Loader.doList(Loader.java:2675) [hibernate-core-5.2.16.Final.jar!/:5.2.16.Final]
2018-09-17T11:50:11.639844167Z  at org.hibernate.loader.Loader.listIgnoreQueryCache(Loader.java:2507) [hibernate-core-5.2.16.Final.jar!/:5.2.16.Final]
2018-09-17T11:50:11.639849073Z  at org.hibernate.loader.Loader.list(Loader.java:2502) [hibernate-core-5.2.16.Final.jar!/:5.2.16.Final]
2018-09-17T11:50:11.639853943Z  at org.hibernate.loader.hql.QueryLoader.list(QueryLoader.java:502) [hibernate-core-5.2.16.Final.jar!/:5.2.16.Final]
2018-09-17T11:50:11.639858773Z  at org.hibernate.hql.internal.ast.QueryTranslatorImpl.list(QueryTranslatorImpl.java:392) [hibernate-core-5.2.16.Final.jar!/:5.2.16.Final]
2018-09-17T11:50:11.639863765Z  at org.hibernate.engine.query.spi.HQLQueryPlan.performList(HQLQueryPlan.java:216) [hibernate-core-5.2.16.Final.jar!/:5.2.16.Final]
2018-09-17T11:50:11.639868646Z  at org.hibernate.internal.SessionImpl.list(SessionImpl.java:1489) [hibernate-core-5.2.16.Final.jar!/:5.2.16.Final]
2018-09-17T11:50:11.639874051Z  at org.hibernate.query.internal.AbstractProducedQuery.doList(AbstractProducedQuery.java:1445) [hibernate-core-5.2.16.Final.jar!/:5.2.16.Final]
2018-09-17T11:50:11.639882957Z  at org.hibernate.query.internal.AbstractProducedQuery.list(AbstractProducedQuery.java:1414) [hibernate-core-5.2.16.Final.jar!/:5.2.16.Final]
2018-09-17T11:50:11.639888299Z  at org.hibernate.query.internal.AbstractProducedQuery.uniqueResult(AbstractProducedQuery.java:1457) [hibernate-core-5.2.16.Final.jar!/:5.2.16.Final]
2018-09-17T11:50:11.639893354Z  at org.hibernate.envers.internal.reader.AuditReaderImpl.getRevisionNumberForDate(AuditReaderImpl.java:195) [hibernate-envers-5.2.16.Final.jar!/:5.2.16.Final]
.....(common frames ommitted)
2018-09-17T11:50:11.640471778Z Caused by: java.net.SocketException: Broken pipe (Write failed)
2018-09-17T11:50:11.640476371Z  at java.net.SocketOutputStream.socketWrite0(Native Method) ~[na:1.8.0_181]
2018-09-17T11:50:11.640481083Z  at java.net.SocketOutputStream.socketWrite(SocketOutputStream.java:111) ~[na:1.8.0_181]
2018-09-17T11:50:11.640485818Z  at java.net.SocketOutputStream.write(SocketOutputStream.java:155) ~[na:1.8.0_181]
2018-09-17T11:50:11.640490460Z  at java.io.BufferedOutputStream.flushBuffer(BufferedOutputStream.java:82) ~[na:1.8.0_181]
2018-09-17T11:50:11.640495069Z  at java.io.BufferedOutputStream.flush(BufferedOutputStream.java:140) ~[na:1.8.0_181]
2018-09-17T11:50:11.640499775Z  at com.mysql.jdbc.MysqlIO.send(MysqlIO.java:3731) ~[mysql-connector-java-5.1.46.jar!/:5.1.46]
2018-09-17T11:50:11.640504540Z  ... 124 common frames omitted
2018-09-17T11:50:11.640508983Z 
2018-09-17T11:50:11.640513301Z 2018-09-17 11:50:11.639  WARN 1 --- [  XNIO-2 task-5] o.h.engine.jdbc.spi.SqlExceptionHelper   : SQL Error: 0, SQLState: 08S01

The next time i call the application rest endpoint i receive the following exception:

2018-09-17 12:01:59.571 WARN 1 --- [ XNIO-2 task-6] o.h.engine.jdbc.spi.SqlExceptionHelper : SQL Error: 0, SQLState: null 2018-09-17 12:01:59.571 ERROR 1 --- [ XNIO-2 task-6] o.h.engine.jdbc.spi.SqlExceptionHelper : Connection is closed 2018-09-17 12:01:59.577 ERROR 1 --- [ XNIO-2 task-6] io.undertow.request : UT005023: Exception handling request to /userdata/changed/1 2018-09-17T12:01:59.578946831Z 2018-09-17T12:01:59.578952545Z org.springframework.web.util.NestedServletException: Request processing failed; nested exception is javax.persistence.PersistenceException: org.hibernate.exception.GenericJDBCException: could not prepare statement

2018-09-17T12:01:59.579639175Z Caused by: java.sql.SQLException: Connection is closed
2018-09-17T12:01:59.579643612Z  at com.zaxxer.hikari.pool.ProxyConnection$ClosedConnection.lambda$getClosedConnection$0(ProxyConnection.java:490) ~[HikariCP-2.7.8.jar!/:na]
2018-09-17T12:01:59.579648391Z  at com.sun.proxy.$Proxy75.prepareStatement(Unknown Source) ~[na:na]
2018-09-17T12:01:59.579652972Z  at com.zaxxer.hikari.pool.ProxyConnection.prepareStatement(ProxyConnection.java:318) ~[HikariCP-2.7.8.jar!/:na]
2018-09-17T12:01:59.579657687Z  at com.zaxxer.hikari.pool.HikariProxyConnection.prepareStatement(HikariProxyConnection.java) ~[HikariCP-2.7.8.jar!/:na]
2018-09-17T12:01:59.579662500Z  at org.hibernate.engine.jdbc.internal.StatementPreparerImpl$5.doPrepare(StatementPreparerImpl.java:145) ~[hibernate-core-5.2.16.Final.jar!/:5.2.16.Final]
2018-09-17T12:01:59.579667400Z  at org.hibernate.engine.jdbc.internal.StatementPreparerImpl$StatementPreparationTemplate.prepareStatement(StatementPreparerImpl.java:171) ~[hibernate-core-5.2.16.Final.jar!/:5.2.16.Final]
2018-09-17T12:01:59.579672405Z  ... 117 common frames omitted

Maybe someone has any idea, why the connection to the database gets invalid.

Here are the settings of the hikari

Driver class com.mysql.jdbc.Driver found in Thread context class loader sun.misc.Launcher$AppClassLoader@18b4aac2
HikariPool-1 - configuration:
allowPoolSuspension.............false
autoCommit......................true
catalog.........................none
connectionInitSql...............none
connectionTestQuery.............none
connectionTimeout...............30000
dataSource......................none
dataSourceClassName.............none
dataSourceJNDI..................none
dataSourceProperties............{password=<masked>}
driverClassName................."com.mysql.jdbc.Driver"
healthCheckProperties...........{}
healthCheckRegistry.............none
idleTimeout.....................600000
initializationFailFast..........true
initializationFailTimeout.......1
isolateInternalQueries..........false
jdbc4ConnectionTest.............false
jdbcUrl.........................jdbc:mysql://server:3306/schema
leakDetectionThreshold..........0
maxLifetime.....................1800000
maximumPoolSize.................10
metricRegistry..................none
metricsTrackerFactory...........none
minimumIdle.....................10
password........................<masked>
poolName........................"HikariPool-1"
readOnly........................false
registerMbeans..................false
scheduledExecutor...............none
scheduledExecutorService........internal
schema..........................none
threadFactory...................internal
transactionIsolation............default
username........................"user"
validationTimeout...............5000

Answer 1

i expected the issue at the wrong part of my application. I configured the envers AuditReader as spring bean and injected a entity manager. The entity manager holds a database connection that breaks when the database is closing the connection after the configured timeout.

@Configuration
@RequiredArgsConstructor
public class AuditConfiguration {

    private final EntityManagerFactory entityManagerFactory;

    @Bean
    public AuditReader auditReader() {
        return AuditReaderFactory.get(entityManagerFactory.createEntityManager());
    }
}

So i removed this configuration and create a entity manager for every request to the audit reader.

@Component
@RequiredArgsConstructor
public class AuditService {

    private final EntityManagerFactory entityManagerFactory;

    public int getLatestRevision() {
        return AuditReaderFactory.get(entityManagerFactory.createEntityManager())
                .getRevisionNumberForDate(from(now()))
                .intValue();
    }
}

With this setup hikari is handling the database connections correct and the exception does not occur anymore.

Answer 2

Use jdbc url as below , while making connection:

url: jdbc:mysql://servername:3306/schema?autoReconnect=true