Grails app seems like it's holding a reference to a stale DB connection

Question

Update: Rackspace have got back to me and told me that their MySQL cloud uses a wait_timeout value of 120 seconds

I've been banging my head against this so I thought I'd ask you guys. Any ideas you might have would be appreciated

util.JDBCExceptionReporter  - SQL Error: 0, SQLState: 08S01
util.JDBCExceptionReporter  - Communications link failure
The last packet successfully received from the server was 264,736 milliseconds 
ago. The last packet sent successfully to the server was 32 milliseconds ago.

The error occurs intermittently, often just minutes after the server in question comes up. The DB is nowhere near capacity in terms of load or connections, and I've tried dozens of different configuration combinations.

The fact that this connection last received a packet from the server 264 seconds ago is revealing because it's well above the 120 second timeout put in place by Rackspace. I've also confirmed from the DB end that my 30 second limit is being respected.

Things I've tried

• Setting DBCP to expire connections aggressively after 30 seconds, and verified that the MySQL instance reflects this behaviour via SELECT * FROM PROCESSLIST
• Switched connection string from hostname to IP address, so this isn't a DNS issue
• Various different combinations of connection settings
• Tried declaring the connection pool settings in DataSources.groovy or resources.groovy, but I'm fairly sure that the settings are being respected as the DB reflects them: anything over 30 seconds is quickly killed

Any ideas?

Right now my best guess is that something in Grails is holding onto a reference to a stale connection for long enough that the 120 second limit is problematic... but it's a desperate theory and realistically I doubt it's true, but that leaves me short of ideas.

The latest config I've tried:

dataSource {
    pooled = true
    driverClassName = "com.mysql.jdbc.Driver"
    dialect = 'org.hibernate.dialect.MySQL5InnoDBDialect'
    properties {
        maxActive = 50
        maxIdle = 20
        minIdle = 5 
        maxWait = 10000
        initialSize = 5
        minEvictableIdleTimeMillis = 1000 * 30
        timeBetweenEvictionRunsMillis = 1000 * 5
        numTestsPerEvictionRun = 50
        testOnBorrow = true
        testWhileIdle = true
        testOnReturn = true
        validationQuery = "SELECT 1"
    }
}

Stack trace:

2012-10-25 12:36:12,375 [http-bio-8080-exec-2] WARN  util.JDBCExceptionReporter  - SQL Error: 0, SQLState: 08S01
2012-10-25 12:36:12,375 [http-bio-8080-exec-2] ERROR util.JDBCExceptionReporter  - Communications link failure

The last packet successfully received from the server was 264,736 milliseconds ago.  The last packet sent successfully to the server was 32 milliseconds ago.
2012-10-25 12:36:12,433 [http-bio-8080-exec-2] ERROR errors.GrailsExceptionResolver  - EOFException occurred when processing request: [GET] /cart
Can not read response from server. Expected to read 4 bytes, read 0 bytes before connection was unexpectedly lost.. Stacktrace follows:
org.hibernate.exception.JDBCConnectionException: could not execute query
at grails.orm.HibernateCriteriaBuilder.invokeMethod(HibernateCriteriaBuilder.java:1531)
at SsoRealm.hasRole(SsoRealm.groovy:30)
at org.apache.shiro.grails.RealmWrapper.hasRole(RealmWrapper.groovy:193)
at org.apache.shiro.authz.ModularRealmAuthorizer.hasRole(ModularRealmAuthorizer.java:374)
at org.apache.shiro.mgt.AuthorizingSecurityManager.hasRole(AuthorizingSecurityManager.java:153)
at org.apache.shiro.subject.support.DelegatingSubject.hasRole(DelegatingSubject.java:225)
at ShiroSecurityFilters$_closure1_closure4_closure6.doCall(ShiroSecurityFilters.groovy:98)
at grails.plugin.cache.web.filter.PageFragmentCachingFilter.doFilter(PageFragmentCachingFilter.java:195)
at grails.plugin.cache.web.filter.AbstractFilter.doFilter(AbstractFilter.java:63)
at org.apache.shiro.grails.SavedRequestFilter.doFilter(SavedRequestFilter.java:55)
at org.apache.shiro.web.servlet.AbstractShiroFilter.executeChain(AbstractShiroFilter.java:449)
at org.apache.shiro.web.servlet.AbstractShiroFilter$1.call(AbstractShiroFilter.java:365)
at org.apache.shiro.subject.support.SubjectCallable.doCall(SubjectCallable.java:90)
at org.apache.shiro.subject.support.SubjectCallable.call(SubjectCallable.java:83)
at org.apache.shiro.subject.support.DelegatingSubject.execute(DelegatingSubject.java:380)
at org.apache.shiro.web.servlet.AbstractShiroFilter.doFilterInternal(AbstractShiroFilter.java:362)
at org.apache.shiro.web.servlet.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:125)
at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
at java.lang.Thread.run(Thread.java:662)
Caused by: com.mysql.jdbc.exceptions.jdbc4.CommunicationsException: Communications link failure

The last packet successfully received from the server was 264,736 milliseconds ago.  The last packet sent successfully to the server was 32 milliseconds ago.
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:3589)
at com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:3478)
at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:4019)
at com.mysql.jdbc.MysqlIO.sendCommand(MysqlIO.java:2490)
at com.mysql.jdbc.MysqlIO.sqlQueryDirect(MysqlIO.java:2651)
at com.mysql.jdbc.ConnectionImpl.execSQL(ConnectionImpl.java:2683)
at com.mysql.jdbc.PreparedStatement.executeInternal(PreparedStatement.java:2144)
at com.mysql.jdbc.PreparedStatement.executeQuery(PreparedStatement.java:2310)
at org.apache.commons.dbcp.DelegatingPreparedStatement.executeQuery(DelegatingPreparedStatement.java:96)
at org.apache.commons.dbcp.DelegatingPreparedStatement.executeQuery(DelegatingPreparedStatement.java:96)
... 20 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:3039)
at com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:3489)
... 29 more

Answer 1

Figured this out. The grails-elasticsearch plugin was holding onto stale connections. This was a known issue in that plugin and a fix came in via this pull request: