Database Connection to MySQL times out even after setting c3p0.testConnectionOnCheckout=true

Question

I have an app that uses hibernate (v3.6.4) , with connection pooling provided by C3P0 (v0.9.1.2) .

The problem is I get a JDBC communications link failure if I make a DB query , if the app process ( and hence the C3P0 pool ) has been running for more time than the MySQL wait_timeout value. I set the value of wait_timeout in /etc/mysql/my.cnf to 600 seconds for testing this issue :

2013-01-27 20:08:00,088 ERROR [Thread-0] (JDBCExceptionReporter.java:234) - Communications link failure

The last packet successfully received from the server was 665,943 milliseconds ago.  The last packet sent successfully to the server was 6 milliseconds ago.
org.hibernate.exception.JDBCConnectionException: could not execute query
at org.hibernate.exception.SQLStateConverter.convert(SQLStateConverter.java:99)
at org.hibernate.exception.JDBCExceptionHelper.convert(JDBCExceptionHelper.java:66)
at org.hibernate.loader.Loader.doList(Loader.java:2536)
at org.hibernate.loader.Loader.listIgnoreQueryCache(Loader.java:2276)
at org.hibernate.loader.Loader.list(Loader.java:2271)
at org.hibernate.loader.criteria.CriteriaLoader.list(CriteriaLoader.java:119)
at org.hibernate.impl.SessionImpl.list(SessionImpl.java:1716)
at org.hibernate.impl.CriteriaImpl.list(CriteriaImpl.java:347) 
.....
Caused by: com.mysql.jdbc.exceptions.jdbc4.CommunicationsException: Communications link failure
The last packet successfully received from the server was 665,943 milliseconds ago.  The last packet sent successfully to the server was 6 milliseconds ago.
at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method)
at sun.reflect.NativeConstructorAccessorImpl.newInstance(Unknown Source)
at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(Unknown Source)
at java.lang.reflect.Constructor.newInstance(Unknown Source)
at com.mysql.jdbc.Util.handleNewInstance(Util.java:411)
at com.mysql.jdbc.SQLError.createCommunicationsException(SQLError.java:1116)
at com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:3102)
at com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:2991)
at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:3532)
at com.mysql.jdbc.MysqlIO.sendCommand(MysqlIO.java:2002)
at com.mysql.jdbc.MysqlIO.sqlQueryDirect(MysqlIO.java:2163)
at com.mysql.jdbc.ConnectionImpl.execSQL(ConnectionImpl.java:2624)
at com.mysql.jdbc.PreparedStatement.executeInternal(PreparedStatement.java:2127)
at com.mysql.jdbc.PreparedStatement.executeQuery(PreparedStatement.java:2293)
at  com.mchange.v2.c3p0.impl.NewProxyPreparedStatement.executeQuery(NewProxyPreparedStatement.java:76)
at org.hibernate.jdbc.AbstractBatcher.getResultSet(AbstractBatcher.java:208)
at org.hibernate.loader.Loader.getResultSet(Loader.java:1953)
at org.hibernate.loader.Loader.doQuery(Loader.java:802)
at org.hibernate.loader.Loader.doQueryAndInitializeNonLazyCollections(Loader.java:274)
at org.hibernate.loader.Loader.doList(Loader.java:2533)
... 9 more
Caused by: java.io.EOFException: Can not read response from server. Expected to read 4 bytes, read 0 bytes before connection was unexpectedly lost.
at com.mysql.jdbc.MysqlIO.readFully(MysqlIO.java:2552)
at com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:3002)
... 22 more

2013-01-27 20:19:00,179  WARN [Thread-0] (NewPooledConnection.java:487) - [c3p0] Another error has occurred [ com.mysql.jdbc.exceptions.jdbc4.CommunicationsException: The last packet successfully received from the server was 1,326,037 milliseconds ago.  The last packet sent successfully to the server was 660,100 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. ] which will not be reported to listeners!
com.mysql.jdbc.exceptions.jdbc4.CommunicationsException: The last packet successfully received from the server was 1,326,037 milliseconds ago.  The last packet sent successfully to the server was 660,100 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(Unknown Source)
at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(Unknown Source)
at java.lang.reflect.Constructor.newInstance(Unknown Source)
at com.mysql.jdbc.Util.handleNewInstance(Util.java:411)
at com.mysql.jdbc.SQLError.createCommunicationsException(SQLError.java:1116)
at com.mysql.jdbc.MysqlIO.send(MysqlIO.java:3364)
at com.mysql.jdbc.MysqlIO.sendCommand(MysqlIO.java:1983)
at com.mysql.jdbc.MysqlIO.sqlQueryDirect(MysqlIO.java:2163)
at com.mysql.jdbc.ConnectionImpl.execSQL(ConnectionImpl.java:2624)
at com.mysql.jdbc.PreparedStatement.executeInternal(PreparedStatement.java:2127)
at com.mysql.jdbc.PreparedStatement.executeQuery(PreparedStatement.java:2293)
at com.mchange.v2.c3p0.impl.NewProxyPreparedStatement.executeQuery(NewProxyPreparedStatement.java:76)
at org.hibernate.jdbc.AbstractBatcher.getResultSet(AbstractBatcher.java:208)
at org.hibernate.loader.Loader.getResultSet(Loader.java:1953)
at org.hibernate.loader.Loader.doQuery(Loader.java:802)
at org.hibernate.loader.Loader.doQueryAndInitializeNonLazyCollections(Loader.java:274)
at org.hibernate.loader.Loader.doList(Loader.java:2533)
at org.hibernate.loader.Loader.listIgnoreQueryCache(Loader.java:2276)
at org.hibernate.loader.Loader.list(Loader.java:2271)
at org.hibernate.loader.criteria.CriteriaLoader.list(CriteriaLoader.java:119)
at org.hibernate.impl.SessionImpl.list(SessionImpl.java:1716)
at org.hibernate.impl.CriteriaImpl.list(CriteriaImpl.java:347)
....
Caused by: java.net.SocketException: Broken pipe
at java.net.SocketOutputStream.socketWrite0(Native Method)
at java.net.SocketOutputStream.socketWrite(Unknown Source)
at java.net.SocketOutputStream.write(Unknown Source)
at java.io.BufferedOutputStream.flushBuffer(Unknown Source)
at java.io.BufferedOutputStream.flush(Unknown Source)
at com.mysql.jdbc.MysqlIO.send(MysqlIO.java:3345)
... 20 more

This looked like a common issue so in order to resolve this , I have tried to tune these hibernate / c3p0 properties after checking the hibernate / c3p0 documentation and answers to already asked questions on Stack Overflow :

Relevant hibernate properties :

<property name="hibernate.connection.driver_class">com.mysql.jdbc.Driver</property>
<property name="hibernate.connection.url">jdbc:mysql://localhost:3306/gsui?useUnicode=true&amp;characterEncoding=UTF-8&amp;autoReconnect=true</property>

<property name="hibernate.connection.autoReconnect">true</property>

<!-- C3p0 Performance Improvements -->
<property name="hibernate.c3p0.acquire_increment">1</property>
<property name="hibernate.c3p0.idle_test_period">300</property>
<property name="hibernate.c3p0.maxConnectionAge">3600</property>
<property name="hibernate.c3p0.timeout">120</property>
<property name="hibernate.c3p0.max_size">300</property>
<property name="hibernate.c3p0.min_size">1</property>
<property name="hibernate.c3p0.max_statements">100</property>
<property name="hibernate.c3p0.preferredTestQuery">select 1;</property>

<property name="hibernate.connection.useUnicode">
    true
</property>
<property name="hibernate.connection.characterEncoding">
    UTF-8
</property>
<property name="hibernate.connection.charSet">
    UTF-8
</property>

I also set c3p0.testConnectionOnCheckout to true in a c3p0 properties file I maintain :

c3p0.testConnectionOnCheckout=true

In the logs , the C3P0 pool initializes fine with the following messages :

2013-01-27 19:45:04,607  INFO [main] (ConnectionProviderFactory.java:173) - Initializing connection provider: org.hibernate.connection.C3P0ConnectionProvider
2013-01-27 19:45:04,609  INFO [main] (C3P0ConnectionProvider.java:103) - C3P0 using driver: com.mysql.jdbc.Driver at URL: jdbc:mysql://localhost:3306/gsui?useUnicode=true&characterEncoding=UTF-8&autoReconnect=true
2013-01-27 19:45:04,610  INFO [main] (C3P0ConnectionProvider.java:104) - Connection properties: {useUnicode=true, autoReconnect=true, user=root, password=****, shutdown=true, characterEncoding=UTF-8, charSet=UTF-8}
2013-01-27 19:45:04,610  INFO [main] (C3P0ConnectionProvider.java:107) - autocommit mode: false
2013-01-27 19:45:04,629  INFO [main] (MLog.java:80) - MLog clients using log4j logging.
2013-01-27 19:45:04,757  INFO [main] (C3P0Registry.java:204) - Initializing c3p0-0.9.1.2 [built 21-May-2007 15:04:56; debug? true; trace: 10]
2013-01-27 19:45:04,842  INFO [main] (C3P0ConnectionProvider.java:194) - JDBC isolation level: READ_COMMITTED
2013-01-27 19:45:04,871  INFO [main] (AbstractPoolBackedDataSource.java:462) - Initializing c3p0 pool... com.mchange.v2.c3p0.PoolBackedDataSource@9f4a7137 [ connectionPoolDataSource -> com.mchange.v2.c3p0.WrapperConnectionPoolDataSource@71b9e1e9 [ acquireIncrement -> 1, acquireRetryAttempts -> 30, acquireRetryDelay -> 1000, autoCommitOnClose -> false, automaticTestTable -> null, breakAfterAcquireFailure -> false, checkoutTimeout -> 0, connectionCustomizerClassName -> null, connectionTesterClassName -> com.mchange.v2.c3p0.impl.DefaultConnectionTester, debugUnreturnedConnectionStackTraces -> false, factoryClassLocation -> null, forceIgnoreUnresolvedTransactions -> false, identityToken -> z8kfsx8sz4pted1s4b69w|51f726b9, idleConnectionTestPeriod -> 300, initialPoolSize -> 1, maxAdministrativeTaskTime -> 0, maxConnectionAge -> 3600, maxIdleTime -> 120, maxIdleTimeExcessConnections -> 0, maxPoolSize -> 300, maxStatements -> 100, maxStatementsPerConnection -> 0, minPoolSize -> 1, nestedDataSource -> com.mchange.v2.c3p0.DriverManagerDataSource@58f45048 [ description -> null, driverClass -> null, factoryClassLocation -> null, identityToken -> z8kfsx8sz4pted1s4b69w|454b7177, jdbcUrl -> jdbc:mysql://localhost:3306/gsui?useUnicode=true&characterEncoding=UTF-8&autoReconnect=true, properties -> {useUnicode=true, autoReconnect=true, user=******, password=******, shutdown=true, characterEncoding=UTF-8, charSet=UTF-8} ], preferredTestQuery -> select 1;, propertyCycle -> 0, testConnectionOnCheckin -> false, testConnectionOnCheckout -> true, unreturnedConnectionTimeout -> 0, usesTraditionalReflectiveProxies -> false; userOverrides: {} ], dataSourceName -> null, factoryClassLocation -> null, identityToken -> z8kfsx8sz4pted1s4b69w|71ffd9f1, numHelperThreads -> 3 ]

From the above logs , one finds that testConnectionOnCheckout=true and autoReconnect=true in C3P0. Can someone help me figure out why C3P0 checks out a timed-out connection anyway ? Thanks.

Answer 1

We started having the same "Communications Link" issue when we upgraded hibernate to 4.3.x using JPA and C3P0 for connection pooling.

It seems like this would be a connection pool issue since connections were being kept longer than the database wait_timeout (which was the default 8 hours) despite my C3P0 settings. However, I fixed the issue by changing the hibernate configuration in our persistence.xml with:

<property name="hibernate.connection.release_mode" value="after_transaction" />

It seems the default behavior in hibernate changed to not release the connection after transactions, so you have to explicitly set this mode if you're using pooling.