#130 A ResourcePool cannot acquire a new resource -- the factory or source appears to be down.

[philippe tseyen]

Tonight we had a database problem. After the problem was resolved some of our applications recovered without issues. However other applications did not recover. Their logs were filled with the stacktraces you see below. I also added the thread dump.

Thread dump


"C3P0PooledConnectionPoolManager-Helper Thread-#2" daemon prio=8 tid=0x6000000007024c00 nid=9376 lwp_id=2327924 waiting for monitor entry [0x9fffffffa6b00000]
java.lang.Thread.State: BLOCKED (on object monitor)
at com.mchange.v2.resourcepool.BasicResourcePool.isForceKillAcquiresPending(BasicResourcePool.java:874)

- waiting to lock <0x9fffffff0ac79720> (a com.mchange.v2.resourcepool.BasicResourcePool)
at com.mchange.v2.resourcepool.BasicResourcePool.access$700(BasicResourcePool.java:32)
at com.mchange.v2.resourcepool.BasicResourcePool$ScatteredAcquireTask.run(BasicResourcePool.java:1790)
at com.mchange.v2.async.ThreadPoolAsynchronousRunner$PoolThread.run(ThreadPoolAsynchronousRunner.java:635)

"C3P0PooledConnectionPoolManager-Helper Thread-#1" daemon prio=8 tid=0x6000000006fda400 nid=9375 lwp_id=2327923 runnable [0x9fffffffa6d00000]
java.lang.Thread.State: RUNNABLE
at com.mchange.v2.resourcepool.BasicResourcePool.isForceKillAcquiresPending(BasicResourcePool.java:874)

- locked <0x9fffffff0ac79720> (a com.mchange.v2.resourcepool.BasicResourcePool)
at com.mchange.v2.resourcepool.BasicResourcePool.access$700(BasicResourcePool.java:32)
at com.mchange.v2.resourcepool.BasicResourcePool$ScatteredAcquireTask.run(BasicResourcePool.java:1790)
at com.mchange.v2.async.ThreadPoolAsynchronousRunner$PoolThread.run(ThreadPoolAsynchronousRunner.java:635)

"C3P0PooledConnectionPoolManager-Helper Thread-#0" daemon prio=8 tid=0x6000000006fd9c00 nid=9374 lwp_id=2327922 waiting for monitor entry [0x9fffffffa7d00000]
java.lang.Thread.State: BLOCKED (on object monitor)
at com.mchange.v2.resourcepool.BasicResourcePool.isForceKillAcquiresPending(BasicResourcePool.java:874)

- waiting to lock <0x9fffffff0ac79720> (a com.mchange.v2.resourcepool.BasicResourcePool)
at com.mchange.v2.resourcepool.BasicResourcePool.access$700(BasicResourcePool.java:32)
at com.mchange.v2.resourcepool.BasicResourcePool$ScatteredAcquireTask.run(BasicResourcePool.java:1790)
at com.mchange.v2.async.ThreadPoolAsynchronousRunner$PoolThread.run(ThreadPoolAsynchronousRunner.java:635)

Stacktraces


ERROR 2014-05-21 08:36:01,248 [RegistrationThread:topic=AP2Integration] RegistrationThread^register - be.amaris.frame.infrastructure.exception.RemoteExceptionWithDetail: INFRA:internal.server.error([]) 7169edf0-e02b-11e3-b17d-0025b3b22062
be.amaris.frame.infrastructure.exception.RemoteExceptionWithDetail: INFRA:internal.server.error([]) 7169edf0-e02b-11e3-b17d-0025b3b22062
at be.amaris.frame.infrastructure.exception.serialization.ExceptionConverter.convertToRemoteExceptionWithDetail(ExceptionConverter.java:112)
at be.amaris.frame.infrastructure.appIntegration.impl.ResponseListenerHelper.waitForResponse(ResponseListenerHelper.java:101)
at be.amaris.frame.infrastructure.appIntegration.impl.ResponseListener.waitForResponse(ResponseListener.java:131)
at be.amaris.frame.infrastructure.appIntegration.impl.JmsClient.remoteSynchroneCall(JmsClient.java:206)
at be.amaris.frame.infrastructure.appIntegration.impl.JmsClient.synchroneCallEx(JmsClient.java:192)
at be.amaris.frame.infrastructure.appIntegration.impl.JmsClient.synchroneCall(JmsClient.java:176)
at be.amaris.frame.infrastructure.appIntegration.remote.RemoteServicesProxy.invoke(RemoteServicesProxy.java:95)
at com.sun.proxy.$Proxy127.registerActiveModule(Unknown Source)
at be.amaris.inf.infrastructure.RegistrationThread.register(RegistrationThread.java:132)
at be.amaris.inf.infrastructure.RegistrationThread.run(RegistrationThread.java:71)
Caused by remote: java.lang.RuntimeException: org.hibernate.exception.GenericJDBCException: Cannot open connection
at be.amaris.inf.service.integration.InfraDispatcher.dispatchMessage(InfraDispatcher.java:53)
at be.amaris.inf.service.integration.CommonListener.processMessage(CommonListener.java:60)
at be.amaris.frame.infrastructure.appIntegration.impl.AbstractJmsListener.processRequest(AbstractJmsListener.java:127)
at be.amaris.frame.infrastructure.appIntegration.impl.QueueListener.onMessage(QueueListener.java:72)
at org.apache.activemq.ActiveMQMessageConsumer.dispatch(ActiveMQMessageConsumer.java:1229)
at org.apache.activemq.ActiveMQSessionExecutor.dispatch(ActiveMQSessionExecutor.java:134)
at org.apache.activemq.ActiveMQSessionExecutor.iterate(ActiveMQSessionExecutor.java:205)
at org.apache.activemq.thread.PooledTaskRunner.runTask(PooledTaskRunner.java:122)
at org.apache.activemq.thread.PooledTaskRunner$1.run(PooledTaskRunner.java:43)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
at java.lang.Thread.run(Thread.java:744)
Caused by: org.hibernate.exception.GenericJDBCException: Cannot open connection
at org.hibernate.exception.SQLStateConverter.handledNonSpecificException(SQLStateConverter.java:126)
at org.hibernate.exception.SQLStateConverter.convert(SQLStateConverter.java:114)
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:142)
at org.hibernate.transaction.JDBCTransaction.begin(JDBCTransaction.java:85)
at org.hibernate.impl.SessionImpl.beginTransaction(SessionImpl.java:1354)
at be.amaris.frame.persistence.hibernate.HibernatePersistenceManager.checkStartTransaction(HibernatePersistenceManager.java:1215)
at be.amaris.frame.persistence.hibernate.HibernatePersistenceManager.find(HibernatePersistenceManager.java:454)
at be.amaris.frame.persistence.FrameDAO.find(FrameDAO.java:74)
at be.amaris.inf.service.dto.pm.ActiveModuleAssembler.assembleBO(ActiveModuleAssembler.java:63)
at be.amaris.inf.service.dto.pm.ActiveModuleAssembler.assembleBO(ActiveModuleAssembler.java:18)
at be.amaris.frame.service.dto.FrameAssembler.createBO(FrameAssembler.java:227)
at be.amaris.inf.service.CommonServices.registerActiveModule(CommonServices.java:394)
at sun.reflect.GeneratedMethodAccessor340.invoke(Unknown Source)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:606)
at be.amaris.frame.service.ServicesProxy.execute(ServicesProxy.java:151)
at be.amaris.frame.service.ServicesProxy.invokeMethod(ServicesProxy.java:111)
at be.amaris.frame.service.ServicesProxy.invoke(ServicesProxy.java:80)
at com.sun.proxy.$Proxy118.registerActiveModule(Unknown Source)
at sun.reflect.GeneratedMethodAccessor352.invoke(Unknown Source)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:606)
at be.amaris.frame.infrastructure.appIntegration.remote.Dispatcher.executeMethod(Dispatcher.java:85)
at be.amaris.frame.infrastructure.appIntegration.remote.Dispatcher.callMethod(Dispatcher.java:58)
at be.amaris.inf.service.integration.InfraDispatcher.dispatchMessage(InfraDispatcher.java:40)
... 11 more
Caused by: java.sql.SQLException: An SQLException was provoked by the following failure: com.mchange.v2.resourcepool.ResourcePoolException: A ResourcePool cannot acquire a new resource -- the factory or source appears to be down.
at com.mchange.v2.sql.SqlUtils.toSQLException(SqlUtils.java:106)
at com.mchange.v2.sql.SqlUtils.toSQLException(SqlUtils.java:65)
at com.mchange.v2.sql.SqlUtils.toSQLException(SqlUtils.java:62)
at com.mchange.v2.c3p0.impl.C3P0PooledConnectionPool.checkoutPooledConnection(C3P0PooledConnectionPool.java:643)
at com.mchange.v2.c3p0.impl.AbstractPoolBackedDataSource.getConnection(AbstractPoolBackedDataSource.java:128)
at be.amaris.frame.persistence.hibernate.C3P0ConnectionProvider.getConnection(C3P0ConnectionProvider.java:155)
at org.hibernate.jdbc.ConnectionManager.openConnection(ConnectionManager.java:446)
... 35 more
Caused by: com.mchange.v2.resourcepool.ResourcePoolException: A ResourcePool cannot acquire a new resource -- the factory or source appears to be down.
at com.mchange.v2.resourcepool.BasicResourcePool.awaitAvailable(BasicResourcePool.java:1366)
at com.mchange.v2.resourcepool.BasicResourcePool.prelimCheckoutResource(BasicResourcePool.java:594)
at com.mchange.v2.resourcepool.BasicResourcePool.checkoutResource(BasicResourcePool.java:514)
at com.mchange.v2.c3p0.impl.C3P0PooledConnectionPool.checkoutAndMarkConnectionInUse(C3P0PooledConnectionPool.java:707)
at com.mchange.v2.c3p0.impl.C3P0PooledConnectionPool.checkoutPooledConnection(C3P0PooledConnectionPool.java:634)
... 38 more


[Robin Allen]

I found this report because I'm faced with exactly the same thing as reported here.

After DB or network outage, c3p0 does not always recover.

'sampleLastAcquisitionFailureStackTrace' shows that acquire has failed due to "IO exception End of TNS data channel"

CPU usage on the machine hits 100%, all from c3p0.

Any attempt to get a new connection fails with ... "Caused by remote: java.lang.RuntimeException: org.hibernate.exception.GenericJDBCException: Cannot open connection"
.... "Caused by: java.sql.SQLException: An SQLException was provoked by the following failure: com.mchange.v2.resourcepool.ResourcePoolException: A ResourcePool cannot acquire a new resource -- the factory or source appears to be down."
Exactly as in this report.

The DB is up, and working fine. (Other identical nodes running same modules are using it just fine)

My pool has min 2, and those 2 existing connections are still working. But anything trying to make a 3rd connection fails.

'Soft Reset' jmx operation drops the 2 existing connections. Then ANY code trying to get a connection sees the same 'Cannot open connection' error.

'Hard Reset' jmx operation fixes everything immediately. CPU usage drops to zero. New DB connections get created. Everything returns to normal..... proving that C3P0's management of the pool is at fault.