JDBC connection timeout cannot reconnect

Question

I have my Spring Hibernate web application running on MySQL that gives me trouble.

I have searched around and tried different configurations, read quite a few threads on this website, but it still pops up its smiling head.

The error message is: Caused by: com.mysql.jdbc.exceptions.jdbc4.CommunicationsException: The last packet successfully received from the server was 63,313,144 milliseconds ago. The last packet sent successfully to the server was 63,313,144 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.

Caused by: com.mysql.jdbc.exceptions.jdbc4.CommunicationsException: The last packet successfully received from the server was 63,313,144 milliseconds ago.  The last packet sent successfully to the server was 63,313,144 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.
    at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method)
    at sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:57)
    at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45)
    at java.lang.reflect.Constructor.newInstance(Constructor.java:526)
    at com.mysql.jdbc.Util.handleNewInstance(Util.java:408)
    at com.mysql.jdbc.SQLError.createCommunicationsException(SQLError.java:1137)
    at com.mysql.jdbc.MysqlIO.send(MysqlIO.java:3965)
    at com.mysql.jdbc.MysqlIO.sendCommand(MysqlIO.java:2578)
    at com.mysql.jdbc.MysqlIO.sqlQueryDirect(MysqlIO.java:2758)
    at com.mysql.jdbc.ConnectionImpl.execSQL(ConnectionImpl.java:2820)
    at com.mysql.jdbc.ConnectionImpl.setAutoCommit(ConnectionImpl.java:5359)
    at net.sf.log4jdbc.ConnectionSpy.setAutoCommit(ConnectionSpy.java:764)
    at com.mchange.v2.c3p0.impl.NewProxyConnection.setAutoCommit(NewProxyConnection.java:912)
    at org.hibernate.engine.transaction.internal.jdbc.JdbcTransaction.doBegin(JdbcTransaction.java:72)
    at org.hibernate.engine.transaction.spi.AbstractTransactionImpl.begin(AbstractTransactionImpl.java:162)
    at org.hibernate.internal.SessionImpl.beginTransaction(SessionImpl.java:1435)
    at org.hibernate.jpa.internal.TransactionImpl.begin(TransactionImpl.java:61)
    at org.springframework.orm.jpa.vendor.HibernateJpaDialect.beginTransaction(HibernateJpaDialect.java:159)
    at org.springframework.orm.jpa.JpaTransactionManager.doBegin(JpaTransactionManager.java:380)
    ... 46 more
Caused by: java.net.SocketException: Broken pipe
    at java.net.SocketOutputStream.socketWrite0(Native Method)
    at java.net.SocketOutputStream.socketWrite(SocketOutputStream.java:113)
    at java.net.SocketOutputStream.write(SocketOutputStream.java:159)
    at java.io.BufferedOutputStream.flushBuffer(BufferedOutputStream.java:82)
    at java.io.BufferedOutputStream.flush(BufferedOutputStream.java:140)
    at com.mysql.jdbc.MysqlIO.send(MysqlIO.java:3946)
    ... 58 more

The MySQL wait_timeout value is 28800.

My data source, c3p0 and Hibernate configuration is:

@Bean
public DataSource dataSource() throws PropertyVetoException {
    ComboPooledDataSource dataSource = new ComboPooledDataSource();
    dataSource.setDriverClass(databaseProperties.getHibernateDriverClassName());
    dataSource.setJdbcUrl(databaseProperties.getDataSourceUrl());
    dataSource.setUser(databaseProperties.getDataSourceUsername());
    dataSource.setPassword(databaseProperties.getDataSourcePassword());
    dataSource.setAcquireIncrement(5);
    dataSource.setMaxStatementsPerConnection(20);
    dataSource.setMaxStatements(100);
    dataSource.setMinPoolSize(2);
    dataSource.setMaxPoolSize(5);
    return dataSource;
}

@Bean
public LocalContainerEntityManagerFactoryBean entityManagerFactory() throws PropertyVetoException {
    HibernateJpaVendorAdapter jpaVendorAdapter = new HibernateJpaVendorAdapter();
    jpaVendorAdapter.setDatabasePlatform(databaseProperties.getHibernateDialect());
    jpaVendorAdapter.setShowSql(true);
    jpaVendorAdapter.setGenerateDdl(false);

    Map<String, String> jpaPropertiesMap = new HashMap<String, String>();
    jpaPropertiesMap.put("hibernate.dialect", databaseProperties.getHibernateDialect());
    jpaPropertiesMap.put("hibernate.show_sql", "true");
    jpaPropertiesMap.put("hibernate.format_sql", "true");
    jpaPropertiesMap.put("hibernate.hbm2ddl.auto", databaseProperties.getHibernateHbm2ddlAuto());
    jpaPropertiesMap.put("hibernate.transaction.factory_class", "org.hibernate.transaction.JDBCTransactionFactory");
    jpaPropertiesMap.put("hibernate.ejb.naming_strategy", "org.hibernate.cfg.ImprovedNamingStrategy");
    jpaPropertiesMap.put("hibernate.c3p0.min_size", "5");
    jpaPropertiesMap.put("hibernate.c3p0.max_size", "20");
    jpaPropertiesMap.put("hibernate.c3p0.timeout", "1000");
    jpaPropertiesMap.put("c3p0.maxConnectionAge", "7200");
    jpaPropertiesMap.put("c3p0.maxIdleTime", "7200");
    jpaPropertiesMap.put("c3p0.unreturnedConnectionTimeout", "60");
    jpaPropertiesMap.put("c3p0.debugUnreturnedConnectionStackTraces", "true");
    jpaPropertiesMap.put("hibernate.c3p0.max_statements", "50");
    // Prevent JPA from converting the dates to the UTC time zone
    jpaPropertiesMap.put("jadira.usertype.autoRegisterUserTypes", "true");
    jpaPropertiesMap.put("jadira.usertype.databaseZone", "jvm");
    jpaPropertiesMap.put("jadira.usertype.javaZone", "jvm");

    LocalContainerEntityManagerFactoryBean factoryBean = new LocalContainerEntityManagerFactoryBean();
    factoryBean.setJpaVendorAdapter(jpaVendorAdapter);
    factoryBean.setPackagesToScan("com.nsn.nitro.project.data.jpa.domain");
    factoryBean.setJpaPropertyMap(jpaPropertiesMap);
    String[] mappingsResources = new String[] {"custom/typedef.hbm.xml"};        
    factoryBean.setMappingResources(mappingsResources);
    factoryBean.setDataSource(dataSource());
    return factoryBean;
}

The error happens when the next morning I come back to the web application and it has not been accessed for the whole night.

I understand that MySQL wait_timeout is the number of seconds MySQL will wait for a connection to be used again before closing it down.

That means that my web application is trying to use a connection that has expired and been closed on MySQL side, with my web application still thinking it is a valid connection.

I suppose I should then make my web application time out connections before MySQL does. This way, the web application would not reuse any connection already timed out and closed on MySQL side, since the connection would have already been timed out on the web application side.

It feels like all my c3p0 configuration to that effect of timing out the unused connection is not doing its job.

I'm using the following stack:

MySQL mysql-5.6.14
mysql-connector-java 5.1.32
Spring 4.1.0.RELEASE
spring-data-jpa 1.6.2.RELEASE
Hibernate 4.3.6.Final
hibernate-jpa-2.1-api 1.0.0.Final
C3P0 0.9.2.1

What am I doing wrong in my configuration ?

Or am I supposed to explicitly close connections ?

Here is how I set up the repositories:

public interface LanguageRepository extends GenericRepository<Language, Long> {
}

@Repository
@Transactional
public class GenericRepositoryImpl<T, ID extends Serializable> extends SimpleJpaRepository<T, ID> implements GenericRepository<T, ID> {

    private EntityManager entityManager;

    public GenericRepositoryImpl(JpaEntityInformation<T, ID> entityMetadata, EntityManager entityManager) {
        super(entityMetadata, entityManager);

        this.entityManager = entityManager;
    }

    public GenericRepositoryImpl(Class<T> domainClass, EntityManager entityManager) {
        super(domainClass, entityManager);

        this.entityManager = entityManager;
    }

    public EntityManager getEntityManager() {
        return entityManager;
    }

    @Override
    @Transactional
    public T deleteById(ID id) throws EntityNotFoundException {
        T entity = findOne(id);
        if (entity != null) {
            delete(entity);
        } else {
            throw new EntityNotFoundException("The entity could not be found and was not deleted");
        }
        return entity;
    }

}

public class GenericRepositoryFactoryBean<R extends JpaRepository<T, I>, T, I extends Serializable> extends JpaRepositoryFactoryBean<R, T, I> {

    protected RepositoryFactorySupport createRepositoryFactory(EntityManager entityManager) {
        return new BaseRepositoryFactory<T, I>(entityManager);
    }

    protected static class BaseRepositoryFactory<T, I extends Serializable> extends JpaRepositoryFactory {

        private EntityManager entityManager;

        public BaseRepositoryFactory(EntityManager entityManager) {
            super(entityManager);

            this.entityManager = entityManager;
        }

        @Override
        protected Object getTargetRepository(RepositoryMetadata metadata) {
            return new GenericRepositoryImpl<T, I>((JpaEntityInformation<T, I>) getEntityInformation(metadata.getDomainType()), entityManager);
        }

        @Override
        protected Class<?> getRepositoryBaseClass(RepositoryMetadata metadata) {
            return GenericRepositoryImpl.class;
        }
    }

}

@NoRepositoryBean
public interface GenericRepository<T, ID extends Serializable> extends JpaRepository<T, ID> {

    public EntityManager getEntityManager();

    public T deleteById(ID id) throws EntityNotFoundException;

}

I cannot see any close() method being implemented nor called in there. Something missing in my code ?

EDIT: Added logging for C3P0. Here is what is output:

2014-10-17 14:29:00,464 INFO   [AbstractPoolBackedDataSource] Initializing c3p0 pool... com.mchange.
v2.c3p0.ComboPooledDataSource [ acquireIncrement -> 5, acquireRetryAttempts -> 30, acquireRetryDelay
 -> 1000, autoCommitOnClose -> false, automaticTestTable -> null, breakAfterAcquireFailure -> false,
 checkoutTimeout -> 0, connectionCustomizerClassName -> null, connectionTesterClassName -> com.mchan
ge.v2.c3p0.impl.DefaultConnectionTester, dataSourceName -> agvw3s958cggbnis1syx|1acb901, debugUnretu
rnedConnectionStackTraces -> false, description -> null, driverClass -> net.sf.log4jdbc.DriverSpy, f
actoryClassLocation -> null, forceIgnoreUnresolvedTransactions -> false, identityToken -> agvw3s958c
ggbnis1syx|1acb901, idleConnectionTestPeriod -> 0, initialPoolSize -> 3, jdbcUrl -> jdbc:log4jdbc:my
sql://127.0.0.1:3306/nitroproject, maxAdministrativeTaskTime -> 0, maxConnectionAge -> 0, maxIdleTim
e -> 0, maxIdleTimeExcessConnections -> 0, maxPoolSize -> 5, maxStatements -> 100, maxStatementsPerC
onnection -> 20, minPoolSize -> 2, numHelperThreads -> 3, preferredTestQuery -> null, properties -> 
{user=******, password=******}, propertyCycle -> 0, statementCacheNumDeferredCloseThreads -> 0, test
ConnectionOnCheckin -> false, testConnectionOnCheckout -> false, unreturnedConnectionTimeout -> 0, u
serOverrides -> {}, usesTraditionalReflectiveProxies -> false ] 
2014-10-17 14:29:00,479 DEBUG  [BasicResourcePool] incremented pending_acquires: 1 
2014-10-17 14:29:00,480 DEBUG  [BasicResourcePool] Starting acquisition series. Incremented pending_
acquires [1],  attempts_remaining: 30 
2014-10-17 14:29:00,480 DEBUG  [ThreadPoolAsynchronousRunner] com.mchange.v2.async.ThreadPoolAsynchr
onousRunner@11dbedc: Adding task to queue -- com.mchange.v2.resourcepool.BasicResourcePool$Scattered
AcquireTask@1dd75ae 
2014-10-17 14:29:00,481 DEBUG  [BasicResourcePool] incremented pending_acquires: 2 
2014-10-17 14:29:00,481 DEBUG  [BasicResourcePool] Starting acquisition series. Incremented pending_
acquires [2],  attempts_remaining: 30 
2014-10-17 14:29:00,482 DEBUG  [ThreadPoolAsynchronousRunner] com.mchange.v2.async.ThreadPoolAsynchr
onousRunner@11dbedc: Adding task to queue -- com.mchange.v2.resourcepool.BasicResourcePool$Scattered
AcquireTask@15083c7 
2014-10-17 14:29:00,482 DEBUG  [BasicResourcePool] incremented pending_acquires: 3 
2014-10-17 14:29:00,483 DEBUG  [BasicResourcePool] Starting acquisition series. Incremented pending_
acquires [3],  attempts_remaining: 30 
2014-10-17 14:29:00,483 DEBUG  [ThreadPoolAsynchronousRunner] com.mchange.v2.async.ThreadPoolAsynchr
onousRunner@11dbedc: Adding task to queue -- com.mchange.v2.resourcepool.BasicResourcePool$Scattered
AcquireTask@fbbf1d 
2014-10-17 14:29:00,511 DEBUG  [GooGooStatementCache] checkinAll(): com.mchange.v2.c3p0.stmt.DoubleMaxStatementCache stats -- total size: 0; checked out: 0; num connections: 0; num keys: 0 
2014-10-17 14:29:00,523 DEBUG  [C3P0PooledConnectionPool] com.mchange.v2.c3p0.impl.C3P0PooledConnectionPool$[e-mail]() returning.  
2014-10-17 14:29:00,523 DEBUG  [BasicResourcePool] trace com.mchange.v2.resourcepool.BasicResourcePool@ad2e72 [managed: 1, unused: 1, excluded: 0] 
2014-10-17 14:29:00,523 DEBUG  [BasicResourcePool] decremented pending_acquires: 2 
2014-10-17 14:29:00,523 DEBUG  [BasicResourcePool] Acquisition series terminated successfully. Decremented pending_acquires [2],  attempts_remaining: 30 
2014-10-17 14:29:00,521 DEBUG  [BasicResourcePool] com.mchange.v2.resourcepool.BasicResourcePool@ad2e72 config: [start -> 3; min -> 2; max -> 5; inc -> 5; num_acq_attempts -> 30; acq_attempt_delay -> 1000; check_idle_resources_delay -> 0; mox_resource_age -> 0; max_idle_time -> 0; excess_max_idle_time -> 0; destroy_unreturned_resc_time -> 0; expiration_enforcement_delay -> 0; break_on_acquisition_failure -> false; debug_store_checkout_exceptions -> false] 
2014-10-17 14:29:00,523 DEBUG  [C3P0PooledConnectionPoolManager] Created new pool for auth, username (masked): 'ni******'. 
2014-10-17 14:29:00,523 DEBUG  [BasicResourcePool] trace com.mchange.v2.resourcepool.BasicResourcePool@ad2e72 [managed: 1, unused: 0, excluded: 0] (e.g. com.mchange.v2.c3p0.impl.NewPooledConnection@acde7c) 
2014-10-17 14:29:00,524 DEBUG  [GooGooStatementCache] checkinAll(): com.mchange.v2.c3p0.stmt.DoubleMaxStatementCache stats -- total size: 0; checked out: 0; num connections: 0; num keys: 0 
2014-10-17 14:29:00,525 DEBUG  [C3P0PooledConnectionPool] com.mchange.v2.c3p0.impl.C3P0PooledConnectionPool$[e-mail]() returning.  
2014-10-17 14:29:00,525 DEBUG  [BasicResourcePool] trace com.mchange.v2.resourcepool.BasicResourcePool@ad2e72 [managed: 2, unused: 1, excluded: 0] (e.g. com.mchange.v2.c3p0.impl.NewPooledConnection@acde7c) 
2014-10-17 14:29:00,525 DEBUG  [BasicResourcePool] decremented pending_acquires: 1 
2014-10-17 14:29:00,529 DEBUG  [BasicResourcePool] Acquisition series terminated successfully. Decremented pending_acquires [1],  attempts_remaining: 30 
2014-10-17 14:29:00,525 DEBUG  [GooGooStatementCache] checkinAll(): com.mchange.v2.c3p0.stmt.DoubleMaxStatementCache stats -- total size: 0; checked out: 0; num connections: 0; num keys: 0 
2014-10-17 14:29:00,530 DEBUG  [C3P0PooledConnectionPool] com.mchange.v2.c3p0.impl.C3P0PooledConnectionPool$[e-mail]() returning.  
2014-10-17 14:29:00,530 DEBUG  [BasicResourcePool] trace com.mchange.v2.resourcepool.BasicResourcePool@ad2e72 [managed: 3, unused: 2, excluded: 0] (e.g. com.mchange.v2.c3p0.impl.NewPooledConnection@acde7c) 
2014-10-17 14:29:00,530 DEBUG  [BasicResourcePool] decremented pending_acquires: 0 
2014-10-17 14:29:00,530 DEBUG  [BasicResourcePool] Acquisition series terminated successfully. Decremented pending_acquires [0],  attempts_remaining: 30 
2014-10-17 14:29:00,562 DEBUG  [GooGooStatementCache] checkinAll(): com.mchange.v2.c3p0.stmt.DoubleMaxStatementCache stats -- total size: 0; checked out: 0; num connections: 0; num keys: 0 
2014-10-17 14:29:00,574 DEBUG  [ThreadPoolAsynchronousRunner] com.mchange.v2.async.ThreadPoolAsynchronousRunner@11dbedc: Adding task to queue -- com.mchange.v2.resourcepool.BasicResourcePool$1RefurbishCheckinResourceTask@1fec09e 
2014-10-17 14:29:00,574 DEBUG  [GooGooStatementCache] checkinAll(): com.mchange.v2.c3p0.stmt.DoubleMaxStatementCache stats -- total size: 0; checked out: 0; num connections: 0; num keys: 0 
2014-10-17 14:29:00,575 DEBUG  [BasicResourcePool] trace com.mchange.v2.resourcepool.BasicResourcePool@ad2e72 [managed: 3, unused: 2, excluded: 0] (e.g. com.mchange.v2.c3p0.impl.NewPooledConnection@acde7c) 
2014-10-17 14:29:00,575 DEBUG  [NewProxyConnection] com.mchange.v2.c3p0.impl.NewProxyConnection@39069f: close() called more than once. 
2014-10-17 14:29:02,260 DEBUG  [BasicResourcePool] trace com.mchange.v2.resourcepool.BasicResourcePool@ad2e72 [managed: 3, unused: 2, excluded: 0] (e.g. com.mchange.v2.c3p0.impl.NewPooledConnection@acde7c) 
2014-10-17 14:29:03,111 DEBUG  [GooGooStatementCache] checkinAll(): com.mchange.v2.c3p0.stmt.DoubleMaxStatementCache stats -- total size: 0; checked out: 0; num connections: 0; num keys: 0 
2014-10-17 14:29:03,112 DEBUG  [ThreadPoolAsynchronousRunner] com.mchange.v2.async.ThreadPoolAsynchronousRunner@11dbedc: Adding task to queue -- com.mchange.v2.resourcepool.BasicResourcePool$1RefurbishCheckinResourceTask@146219b 
2014-10-17 14:29:03,112 DEBUG  [GooGooStatementCache] checkinAll(): com.mchange.v2.c3p0.stmt.DoubleM
axStatementCache stats -- total size: 0; checked out: 0; num connections: 0; num keys: 0 
2014-10-17 14:29:03,113 DEBUG  [BasicResourcePool] trace com.mchange.v2.resourcepool.BasicResourcePo
ol@ad2e72 [managed: 3, unused: 2, excluded: 0] (e.g. com.mchange.v2.c3p0.impl.NewPooledConnection@acde7c) 
2014-10-17 14:29:03,262 DEBUG  [DefaultListableBeanFactory] Returning cached instance of singleton bean 'org.springframework.transaction.config.internalTransactionAdvisor' 
2014-10-17 14:29:03,285 DEBUG  [DefaultListableBeanFactory] Finished creating instance of bean 'entityManagerFactory' 

And then it loops outputting this:

2014-10-17 14:34:10,399 DEBUG  [ThreadPoolAsynchronousRunner] com.mchange.v2.async.ThreadPoolAsynchronousRunner$DeadlockDetector@70b40a -- Running DeadlockDetector[Exiting. No pending tasks.] 
2014-10-17 14:34:10,825 DEBUG  [ThreadPoolAsynchronousRunner] com.mchange.v2.async.ThreadPoolAsynchronousRunner$DeadlockDetector@15e34e2 -- Running DeadlockDetector[Exiting. No pending tasks.] 
2014-10-17 14:34:10,825 DEBUG  [ThreadPoolAsynchronousRunner] com.mchange.v2.async.ThreadPoolAsynchronousRunner$DeadlockDetector@15e34e2 -- Running DeadlockDetector[Exiting. No pending tasks.]

Alice

Can you verify that c3p0 has the config that you think that it has? c3p0 dumps DataSource config upon pool initialization at INFO. Can you find and include that log entry? – Krystin

I cannot see any statement logged by C3P0 so I guess I must configure my logging... – Alice

I read that when a data source is injected, as in my case, the hibernate.c3p0 properties are ignored... I need to fine tune the configuration. – Alice

I now added the c3p0 log output. – Alice

My c3p0 configuration was ignored. And there was no max idle time. So the connections would die on MySQL side while remaining available in the pool. So I changed the configuration to: dataSource.setMinPoolSize(10); dataSource.setMaxPoolSize(200); dataSource.setMaxIdleTime(3600); And I now have a max idle time set to 3600 seconds. I reckon it will solve my issue. – Alice

I could reproduce the issue playing with the maxIdleTime value, so it was indeed that property missing. – Alice

Answer 1

I suppose the issue comes up because the database server kills the connection while the application connection pool still has a handle on it. By having a time out on the application connection pool shorter than on the database server side, the connection gets renewed by the application connection pool before it gets killed by the database server, thus avoiding the issue. My MySQL database server has a timeout wait of 28800 seconds and my application connection pool C3P0 has a timeout wait of 14400 seconds. It makes sense that the chain of timeout waits has to go shorter from servers to clients.

Alice

Answer 2

Added the following params to JDBC connection would solve your problem:

 testOnBorrow="true" validationQuery="SELECT 1" validationInterval="60000"

Flooded

With this setting. Your client will send the "SELECT 1" query to your MySql server every 60 seconds. It acts as a heart beat and prevents MySql server think your are timeout and cutting the connection. – Flooded