MySql error occurs overnight - "Last packet sent to the server was 0 ms ago"

Question

I seem to be experiencing an exception in my application overnight.

My environment is a Java web application using Tomcat, written in Java6 and running on MySQL, with Hibernate3 used to connect to the database (using the MySQL connector 5.0.3 - mysql-connector-java-5.0.3-bin.jar)

There is a scheduled job which runs overnight (using quartz as the scheduler) and when run at 3am, it gives the following exception when trying to access the database (note, I've renamed bits of the stack trace with "xxx" as it is internal code for the company I work for):

03:00:00 ERROR bernate.transaction.JDBCTransaction: JDBC begin failed
com.mysql.jdbc.CommunicationsException: Communications link failure due to underlying exception: 

** BEGIN NESTED EXCEPTION ** 

java.io.EOFException

STACKTRACE:

java.io.EOFException
    at com.mysql.jdbc.MysqlIO.readFully(MysqlIO.java:1913)
    at com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:2304)
    at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:2803)
    at com.mysql.jdbc.MysqlIO.sendCommand(MysqlIO.java:1573)
    at com.mysql.jdbc.MysqlIO.sqlQueryDirect(MysqlIO.java:1665)
    at com.mysql.jdbc.Connection.execSQL(Connection.java:3118)
    at com.mysql.jdbc.Connection.setAutoCommit(Connection.java:5215)
    at org.apache.commons.dbcp.DelegatingConnection.setAutoCommit(DelegatingConnection.java:331)
    at org.apache.commons.dbcp.PoolingDataSource$PoolGuardConnectionWrapper.setAutoCommit(PoolingDataSource.java:317)
    at org.hibernate.transaction.JDBCTransaction.begin(JDBCTransaction.java:63)
    at org.hibernate.impl.SessionImpl.beginTransaction(SessionImpl.java:1326)
    at xxx.HibernateSession.beginThreadTransaction(HibernateSession.java:75)
    at xxx.HibernateSession.beginTransaction(HibernateSession.java:141)
    at xxx.TestCaseManager.runAllTestsInBackground(TestCaseManager.java:228)
    at xxx.scheduler.Job.execute(Job.java:42)
    at org.quartz.core.JobRunShell.run(JobRunShell.java:202)
    at org.quartz.simpl.SimpleThreadPool$WorkerThread.run(SimpleThreadPool.java:529)


** END NESTED EXCEPTION **



Last packet sent to the server was 0 ms ago.
    at com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:2515)
    at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:2803)
    at com.mysql.jdbc.MysqlIO.sendCommand(MysqlIO.java:1573)
    at com.mysql.jdbc.MysqlIO.sqlQueryDirect(MysqlIO.java:1665)
    at com.mysql.jdbc.Connection.execSQL(Connection.java:3118)
    at com.mysql.jdbc.Connection.setAutoCommit(Connection.java:5215)
    at org.apache.commons.dbcp.DelegatingConnection.setAutoCommit(DelegatingConnection.java:331)
    at org.apache.commons.dbcp.PoolingDataSource$PoolGuardConnectionWrapper.setAutoCommit(PoolingDataSource.java:317)
    at org.hibernate.transaction.JDBCTransaction.begin(JDBCTransaction.java:63)
    at org.hibernate.impl.SessionImpl.beginTransaction(SessionImpl.java:1326)
    at xxx.HibernateSession.beginThreadTransaction(HibernateSession.java:75)
    at xxx.HibernateSession.beginTransaction(HibernateSession.java:141)
    at xxx.TestCaseManager.runAllTestsInBackground(TestCaseManager.java:228)
    at xxx.scheduler.Job.execute(Job.java:42)
    at org.quartz.core.JobRunShell.run(JobRunShell.java:202)
    at org.quartz.simpl.SimpleThreadPool$WorkerThread.run(SimpleThreadPool.java:529)
03:00:00 ERROR bernate.transaction.JDBCTransaction: JDBC begin failed
com.mysql.jdbc.CommunicationsException: Communications link failure due to underlying exception: 

In the morning, when logging into the application (which also requires database access) it gives a similar exception, but after waiting about 5 minutes and trying again we can get into the app.

I've checked the database and I can perform simple SELECTs on tables it's trying to connect to. Any help would be appreciated.

Answer 1

Your DBCP Connection pool is timing out use the configuration below...

Simple solution is to make DBCP verify connections before giving them to the caller. Add the following properties to your BasicDataSource configuration:

<property name="testOnBorrow" value="true"/>
<property name="validationQuery" value="SELECT 1"/>

For a list of all options see here: http://commons.apache.org/dbcp/configuration.html

EDIT: For slight correction in what is happening see MJB's comment below.