Play Framework Connection Timeout issue
c3p0, hibernate, playframework
Solution
One really terrible thing about play 1.x is that it has this in its source code:
System.setProperty("com.mchange.v2.log.MLog", "com.mchange.v2.log.FallbackMLog");
System.setProperty("com.mchange.v2.log.FallbackMLog.DEFAULT_CUTOFF_LEVEL", "OFF");
That basically sends all c3p0 logging to `/dev/null`. So you have less information than you ought to about your problem.
That said, it sounds very much like an infrequent Connection leak. One thing you might do to verify this set `db.pool.timeout=0`. Then your application should simply hang, eventually, rather than throwing the Exceptions you see. Not that that's any better.
Another approach would be to define a `c3p0.properties` file and place it as a resource on the top-level of your application's `CLASSPATH`. Then you can try some c3p0 config that play1 does not pass through to c3p0, especially:
c3p0.unreturnedConnectionTimeout=5
That value should be something well below your db.pool.timeout. If it is a Connection leak, this will clunkily work around the problem by automagically cleaning up Connections that have been checked out for more than 5 seconds. Normally I strongly recommend `c3p0.unreturnedConnectionTimeout` be paired with `c3p0.debugUnreturnedConnectionStackTraces`, which dumps the stack trace of the code which called getConnection() and then leaked it. But, since you have no c3p0 logging, there's little point in that.
See the c3p0 docs.
All of that said, what you are experiencing would be an odd sort of Connection leak / pool exhaustion, though, since your pool never hits `maxPoolSize`. It can't, since your server-side max is 150 Connections.
But, it looks as though you never hit that either, you use a maximum of 127 Connections. If you had c3p0 logs, you could look to see if the pool is experiences Exceptions trying to acquire new Connections prior to your failures. But you don't have that. But it could be that your DBMS slows down dramatically prior to hitting that limit. If `Threads_connected` is the number of open Connections at the time you see these errors, it's hard to explain this as a Connection leak at all, since neither c3p0 nor the DBMS should be troubled by 12 open Connections.
Again, c3p0 log would help track this down very easily: We could verify `maxPoolSize` is what you think it is, and see whether c3p0 has experienced Connection acquisition failures. But we don't have that.
If you can attach to your JVM for JMX data (via e.g. VisualVM), you can look at the number of busy Connections over time. If it steadily rises until the failure, that's a Connection leak.
If it is a Connection leak, the bug in your code will likely be somewhere where your hibernate Sessions are close()ed, but not in a finally block, or they are close()ed in a finally block written so that an Exception prior to the `Session.close()` might be skipped of an Exception occurred earlier in the finally block. So you might want to search your codebase for where hibernate Session close()es occur, and make sure that Session cannot possibly be created and then not soon close()ed, not under any possible circumstance other than VM exit.
Good luck!
Problem
I have a play framework Java application (play v1.2.5) that works great for about a month & then yields the following error: ``` An unexpected error occured caused by exception PersistenceException: org.hibernate.exception.GenericJDBCException: Cannot open connection play.exceptions.UnexpectedException: Unexpected Error at play.Invoker$Invocation.onException(Invoker.java:244) at play.Invoker$Invocation.run(Invoker.java:286) at Invocation.HTTP Request(Play!) Caused by: javax.persistence.PersistenceException: org.hibernate.exception.GenericJDBCException: Cannot open connection at org.hibernate.ejb.AbstractEntityManagerImpl.convert(AbstractEntityManagerImpl.java:1389) at org.hibernate.ejb.AbstractEntityManagerImpl.convert(AbstractEntityManagerImpl.java:1317) at org.hibernate.ejb.AbstractEntityManagerImpl.throwPersistenceException(AbstractEntityManagerImpl.java:1399) at org.hibernate.ejb.TransactionImpl.begin(TransactionImpl.java:63) at play.db.jpa.JPAPlugin.startTx(JPAPlugin.java:377) at play.db.jpa.JPAPlugin.beforeInvocation(JPAPlugin.java:345) at play.plugins.PluginCollection.beforeInvocation(PluginCollection.java:473) at play.Invoker$Invocation.before(Invoker.java:217) at play.Invoker$Invocation.run(Invoker.java:277) ... 1 more Caused by: org.hibernate.exception.GenericJDBCException: Cannot open connection at org.hibernate.exception.SQLStateConverter.handledNonSpecificException(SQLStateConverter.java:140) at org.hibernate.exception.SQLStateConverter.convert(SQLStateConverter.java:128) at org.hibernate.exception.JDBCExceptionHelper.convert(JDBCExceptionHelper.java:66) at org.hibernate.exception.JDBCExceptionHelper.convert(JDBCExceptionHelper.java:52) at org.hibernate.jdbc.ConnectionManager.openConnection(ConnectionManager.java:449) at org.hibernate.jdbc.ConnectionManager.getConnection(ConnectionManager.java:167) at org.hibernate.jdbc.JDBCContext.connection(JDBCContext.java:160) at org.hibernate.transaction.JDBCTransaction.begin(JDBCTransaction.java:81) at org.hibernate.impl.SessionImpl.beginTransaction(SessionImpl.java:1473) at org.hibernate.ejb.TransactionImpl.begin(TransactionImpl.java:60) ... 6 more Caused by: java.sql.SQLException: An attempt by a client to checkout a Connection has timed out. at com.mchange.v2.sql.SqlUtils.toSQLException(SqlUtils.java:106) at com.mchange.v2.sql.SqlUtils.toSQLException(SqlUtils.java:65) at org.hibernate.ejb.connection.InjectedDataSourceConnectionProvider.getConnection(InjectedDataSourceConnectionProvider.java:71) at org.hibernate.jdbc.ConnectionManager.openConnection(ConnectionManager.java:446) ... 11 more Caused by: com.mchange.v2.resourcepool.TimeoutException: A client timed out while waiting to acquire a resource from com.mchange.v2.resourcepool.BasicResourcePool@22811ae4 -- timeout at awaitAvailable() at com.mchange.v2.resourcepool.BasicResourcePool.awaitAvailable(BasicResourcePool.java:1317) at com.mchange.v2.resourcepool.BasicResourcePool.prelimCheckoutResource(BasicResourcePool.java:557) at com.mchange.v2.resourcepool.BasicResourcePool.checkoutResource(BasicResourcePool.java:477) ... 13 more ``` If I restart Play, it works fine for about another month before the error repeats. My Play settings are: ``` db.pool.timeout=10000 db.pool.maxSize=500 db.pool.minSize=10 ``` The app connects to a MySQL db running on localhost. MySQL is configured for a max of 150 connections. Stats from MySQL are: mysql> show status like '%onne%'; ``` +--------------------------+-------+ | Variable_name | Value | +--------------------------+-------+ | Aborted_connects | 546 | | Connections | 33197 | | Max_used_connections | 127 | | Ssl_client_connects | 0 | | Ssl_connect_renegotiates | 0 | | Ssl_finished_connects | 0 | | Threads_connected | 11 | +--------------------------+-------+ ``` Any suggestions where to start debugging? UPDATE: Thanks to Steve's answer below, I found & fixed a Connection leak. I was unable to get JMX or any c3p0 logging working w/ Play 1.2.5. HOWEVER...I did add the following method to one of my controllers which allowed me to dump all the necessary c3p0 stats on demand: ``` public static void c3p0() { ComboPooledDataSource local = (ComboPooledDataSource) DB.datasource; try { Logger.info("===============C3P0 STATS================"); Logger.info("MaxConnectionAge: " + local.getMaxConnectionAge()); Logger.info("MaxPoolSize: " + local.getMaxPoolSize()); Logger.info("NumConnectionsAllUsers: " + local.getNumConnectionsAllUsers()); Logger.info("NumConnectionsDefaultUsers: " + local.getNumConnectionsDefaultUser()); Logger.info("NumBusyConnectionsAllUsers: " + local.getNumBusyConnectionsAllUsers()); Logger.info("NumBusyConnectionsDefaultUser: " + local.getNumBusyConnectionsDefaultUser()); Logger.info("LastCheckinFailureDefaultUser: " + local.getLastCheckinFailureDefaultUser()); Logger.info("NumFailedCheckinsDefaultUser: " + local.getNumFailedCheckinsDefaultUser()); Logger.info("NumFailedCheckoutsDefaultUser: " + local.getNumFailedCheckoutsDefaultUser()); Logger.info("NumIdleConnectionsAllUser: " + local.getNumIdleConnectionsAllUsers()); Logger.info("NumIdleConnectionsDefaultUser: " + local.getNumIdleConnectionsDefaultUser()); Logger.info("NumUnclosedOrphanedConnectionsAllUsers: " + local.getNumUnclosedOrphanedConnectionsAllUsers()); Logger.info("NumUnclosedOrphanedConnectionsDefaultUsers: " + local.getNumUnclosedOrphanedConnectionsDefaultUser()); Logger.info("===============END STATS================"); ok(); } catch (Exception e) { error(); } } ```