JDBC connection timed out cannot reconnect

I have my Spring Hibernate web application running on MySQL which is causing problems.

I've searched around and tried different configurations, read quite a few threads on this website, but it still pops up with a smile.

Error message: 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 successfully sent to the server was 63.313.144 milliseconds ago. greater than the server-specified "wait_timeout" value. You should consider expiring and / or validating the connection before using it in your application by increasing the server configured values ​​for client timeouts or using the Connector / J connection property "autoReconnect = true" to avoid this issue.

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 datasource, c3p0 config and Hibernate:

@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 I go back to the web application the next morning and it hasn't been accessed all night.

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

This means that my web application is trying to use a connection that has expired and was closed on the MySQL side, and my web application still thinks it is a valid connection.

Let's say that I had to disconnect my web application's connections before MySQL did it. This way the web application will not reuse any connection that has already been disconnected and closed on the MySQL side, since the connection would have already been disconnected on the web application side.

It looks like my whole c3p0 config with this kind of unused connection sync effect is not doing the job.

I am 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 should I explicitly close connections?

This is how I install 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 don't see any close () method being implemented and not called there. Is there something missing in my code?

EDIT: Added log for C3P0. Here's the 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$1PooledConnectionResourcePoolManager@e38aca.acquireResource() 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$1PooledConnectionResourcePoolManager@e38aca.acquireResource() 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$1PooledConnectionResourcePoolManager@e38aca.acquireResource() 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 these are 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.]

      

+3


source to share


2 answers


I am guessing that the problem is due to the database server killing the connection and the application connection pool still has a handle. If the timeout in the application connection pool is shorter than on the database server side, the connection is resumed by the application connection pool before it is killed by the database server, thus avoiding the problem. My MySQL database server has a timeout of 28800 seconds, and my C3P0 application connection pool has a timeout of 14400 seconds. It makes sense that the wait chain should be shortened from servers to clients.



+2


source


Added the following options to my JDBC connection to solve your problem:



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

      

0


source







All Articles