Connection pool exhausted in JDBC master-slave when slave tries to acquire lock

• Key: AMQ-2296
• Type: Bug
• Status: Closed
• Resolution: Duplicate
• Priority: Major
• Assignee: Unassigned
• Reporter: Raphaël Ramirez
• Component/s: Broker
• Affects Version/s: 5.2.0
• Fix Version/s: 5.3.0

Description

When the slave broker fails to acquire the database lock, which is the normal behavior, we have this (this exception is normal and may be caught by a ExceptionHandler to avoid filling the logs):

09/06/2009 17:41:05 INFO org.apache.activemq.broker.BrokerService [http-8081-1] | Using Persistence Adapter: JDBCPersistenceAdaptor(app.db.ConfigurableDbcpDataSource@77baf4)
09/06/2009 17:41:06 INFO org.apache.activemq.store.jdbc.JDBCPersistenceAdapter [http-8081-1] | Database driver recognized: [mysql-ab_jdbc_driver]
12/06/2009 18:07:18 INFO org.apache.activemq.store.jdbc.DefaultDatabaseLocker [http-8081-1] | Attempting to acquire the exclusive lock to become the Master broker
12/06/2009 18:09:19 ERROR org.apache.activemq.store.jdbc.DefaultDatabaseLocker [http-8081-1] | Failed to acquire lock: java.sql.SQLException: Lock wait timeout exceeded; try restarting transaction
java.sql.SQLException: Lock wait timeout exceeded; try restarting transaction
...

But after 200 (=size of my DBCP connection pool) attempts, I get the following stacktrace :

13/06/2009 03:56:42 ERROR org.apache.activemq.store.jdbc.DefaultDatabaseLocker [http-8081-1] | Failed to acquire lock: org.apache.commons.dbcp.SQLNestedException: Cannot get a connection, pool error Timeout waiting for idle object
org.apache.commons.dbcp.SQLNestedException: Cannot get a connection, pool error Timeout waiting for idle object
at org.apache.commons.dbcp.PoolingDataSource.getConnection(PoolingDataSource.java:104)
at org.apache.commons.dbcp.BasicDataSource.getConnection(BasicDataSource.java:880)
at org.apache.activemq.store.jdbc.DefaultDatabaseLocker.start(DefaultDatabaseLocker.java:63)
at org.apache.activemq.store.jdbc.JDBCPersistenceAdapter.start(JDBCPersistenceAdapter.java:179)
at org.apache.activemq.broker.BrokerService.start(BrokerService.java:458)
at org.apache.activemq.xbean.XBeanBrokerService.afterPropertiesSet(XBeanBrokerService.java:52)
at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.invokeInitMethods(AbstractAutowireCapableBeanFactory.java:1369)
at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.initializeBean(AbstractAutowireCapableBeanFactory.java:1335)
at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.doCreateBean(AbstractAutowireCapableBeanFactory.java:473)
at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory$1.run(AbstractAutowireCapableBeanFactory.java:409)
at java.security.AccessController.doPrivileged(Native Method)
at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.createBean(AbstractAutowireCapableBeanFactory.java:380)
at org.springframework.beans.factory.support.AbstractBeanFactory$1.getObject(AbstractBeanFactory.java:264)
at org.springframework.beans.factory.support.DefaultSingletonBeanRegistry.getSingleton(DefaultSingletonBeanRegistry.java:222)
at org.springframework.beans.factory.support.AbstractBeanFactory.doGetBean(AbstractBeanFactory.java:261)
at org.springframework.beans.factory.support.AbstractBeanFactory.getBean(AbstractBeanFactory.java:185)
at org.springframework.beans.factory.support.AbstractBeanFactory.getBean(AbstractBeanFactory.java:164)
at org.springframework.beans.factory.support.DefaultListableBeanFactory.preInstantiateSingletons(DefaultListableBeanFactory.java:429)
at org.springframework.context.support.AbstractApplicationContext.finishBeanFactoryInitialization(AbstractApplicationContext.java:728)
at org.springframework.context.support.AbstractApplicationContext.refresh(AbstractApplicationContext.java:380)
at org.springframework.web.context.ContextLoader.createWebApplicationContext(ContextLoader.java:255)
at org.springframework.web.context.ContextLoader.initWebApplicationContext(ContextLoader.java:199)
at org.springframework.web.context.ContextLoaderListener.contextInitialized(ContextLoaderListener.java:45)
at org.apache.catalina.core.StandardContext.listenerStart(StandardContext.java:3934)
at org.apache.catalina.core.StandardContext.start(StandardContext.java:4429)
at org.apache.catalina.manager.ManagerServlet.start(ManagerServlet.java:1249)
at org.apache.catalina.manager.HTMLManagerServlet.start(HTMLManagerServlet.java:612)
at org.apache.catalina.manager.HTMLManagerServlet.doGet(HTMLManagerServlet.java:136)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:617)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:717)
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:290)
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:233)
at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:191)
at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:525)
at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:128)
at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:102)
at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:109)
at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:293)
at org.apache.coyote.http11.Http11Processor.process(Http11Processor.java:849)
at org.apache.coyote.http11.Http11Protocol$Http11ConnectionHandler.process(Http11Protocol.java:583)
at org.apache.tomcat.util.net.JIoEndpoint$Worker.run(JIoEndpoint.java:454)
at java.lang.Thread.run(Thread.java:619)
Caused by: java.util.NoSuchElementException: Timeout waiting for idle object
at org.apache.commons.pool.impl.GenericObjectPool.borrowObject(GenericObjectPool.java:825)
at org.apache.commons.dbcp.PoolingDataSource.getConnection(PoolingDataSource.java:96)
... 42 more

Here are my JDBC connection parameters :
persistenceDatabase.url -> jdbc:mysql://xxxxxx/msgbroker?relaxAutoCommit=true
persistenceDatabase.connectionPool.maxActive -> 200
persistenceDatabase.connectionPool.maxWait -> 1000
persistenceDatabase.connectionPool.maxIdle -> 10
persistenceDatabase.connectionPool.validationQuery -> select 1
persistenceDatabase.connectionPool.testOnBorrow -> false
persistenceDatabase.connectionPool.testOnReturn -> false

What happens is that a new connection is borrowed from the pool each time the slave is trying to acquire the exclusive lock, instead of using the existing connection.
This leads to a connection pool leak. See org.apache.activemq.store.jdbc.DefaultDatabaseLocker (line 63) :

connection = dataSource.getConnection();

Changing it to the following code solved the issue :

if (connection==null || connection.isClosed()) { connection = dataSource.getConnection(); connection.setAutoCommit(false); }

Now, an existing connection is used if it is available.