Timeout waiting for idle object causes JIRA to crash?

[Frederic Iterbeke]

Hi all,

I am a JIRA n00b, have been using JIRA v4.4.1#660-r161644 with some plugins for a good month or so.

I've noticed sometimes our JIRA instance crashes for no apparent reason, and mostly after the last user has logged out of the system. The errors in the catalina.out log are all of the following form (apologies for the huge stacktrace):

2011-12-20 10:23:12,991 http-8080-7 ERROR anonymous 618x4653x5 - 78.22.102.159,10.0.0.242 /secure/Dashboard.jspa [NoModule] There was an error getting a DBCP datasource.
java.lang.RuntimeException: Unable to obtain a connection from the underlying connection pool
at org.ofbiz.core.entity.jdbc.interceptors.connection.ConnectionTracker.trackConnection(ConnectionTracker.java:59)
at org.ofbiz.core.entity.transaction.DBCPConnectionFactory.trackConnection(DBCPConnectionFactory.java:149)
at org.ofbiz.core.entity.transaction.DBCPConnectionFactory.getConnection(DBCPConnectionFactory.java:69)
at org.ofbiz.core.entity.ConnectionFactory.tryGenericConnectionSources(ConnectionFactory.java:69)
at org.ofbiz.core.entity.transaction.JNDIFactory.getConnection(JNDIFactory.java:146)
at org.ofbiz.core.entity.TransactionFactory.getConnection(TransactionFactory.java:101)
at org.ofbiz.core.entity.ConnectionFactory.getConnection(ConnectionFactory.java:59)
at org.ofbiz.core.entity.jdbc.SQLProcessor.getConnection(SQLProcessor.java:367)
at org.ofbiz.core.entity.GenericDAO.insert(GenericDAO.java:98)
at org.ofbiz.core.entity.GenericHelperDAO.create(GenericHelperDAO.java:64)
at org.ofbiz.core.entity.GenericDelegator.create(GenericDelegator.java:489)
at org.ofbiz.core.entity.GenericDelegator.create(GenericDelegator.java:469)
at org.ofbiz.core.entity.GenericValue.create(GenericValue.java:80)
at com.atlassian.crowd.embedded.ofbiz.db.OfBizHelper.createValue(OfBizHelper.java:162)
at com.atlassian.crowd.embedded.ofbiz.OfBizUserDao.storeAttributeValue(OfBizUserDao.java:290)
at com.atlassian.crowd.embedded.ofbiz.OfBizUserDao.storeAttributeValues(OfBizUserDao.java:267)
at com.atlassian.crowd.embedded.ofbiz.OfBizUserDao.storeAttributes(OfBizUserDao.java:250)
at com.atlassian.crowd.directory.AbstractInternalDirectory.storeUserAttributes(AbstractInternalDirectory.java:519)
at com.atlassian.crowd.manager.directory.DirectoryManagerGeneric.storeUserAttributes(DirectoryManagerGeneric.java:387)
at com.atlassian.crowd.manager.application.ApplicationServiceGeneric.storeUserAttributes(ApplicationServiceGeneric.java:509)
at com.atlassian.crowd.embedded.core.CrowdServiceImpl.setUserAttribute(CrowdServiceImpl.java:375)
at com.atlassian.crowd.embedded.core.CrowdServiceImpl.setUserAttribute(CrowdServiceImpl.java:363)
at com.atlassian.crowd.embedded.core.DelegatingCrowdService.setUserAttribute(DelegatingCrowdService.java:100)
at com.atlassian.crowd.embedded.core.FilteredCrowdServiceImpl.setUserAttribute(FilteredCrowdServiceImpl.java:43)
at com.atlassian.jira.security.login.LoginStoreImpl.setLong(LoginStoreImpl.java:136)
at com.atlassian.jira.security.login.LoginStoreImpl.recordLoginAttempt(LoginStoreImpl.java:59)
at com.atlassian.jira.security.login.LoginManagerImpl.recordLoginAttempt(LoginManagerImpl.java:321)
at com.atlassian.jira.security.login.LoginManagerImpl.onLoginAttempt(LoginManagerImpl.java:203)
at com.atlassian.jira.security.login.JiraElevatedSecurityGuard.onSuccessfulLoginAttempt(JiraElevatedSecurityGuard.java:34)
at com.atlassian.seraph.auth.DefaultAuthenticator.getUserFromCookie(DefaultAuthenticator.java:467)
at com.atlassian.seraph.auth.DefaultAuthenticator.getUser(DefaultAuthenticator.java:327)
at com.atlassian.seraph.filter.SecurityFilter.doFilter(SecurityFilter.java:125)
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:235)
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
at com.atlassian.security.auth.trustedapps.filter.TrustedApplicationsFilter.doFilter(TrustedApplicationsFilter.java:98)
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:235)
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
at com.atlassian.seraph.filter.BaseLoginFilter.doFilter(BaseLoginFilter.java:150)
at com.atlassian.jira.web.filters.JiraLoginFilter.doFilter(JiraLoginFilter.java:70)
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:235)
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
at com.atlassian.plugin.servlet.filter.IteratingFilterChain.doFilter(IteratingFilterChain.java:46)
at com.atlassian.plugin.servlet.filter.DelegatingPluginFilter$1.doFilter(DelegatingPluginFilter.java:66)
at com.atlassian.oauth.serviceprovider.internal.servlet.OAuthFilter.doFilter(OAuthFilter.java:71)
at com.atlassian.plugin.servlet.filter.DelegatingPluginFilter.doFilter(DelegatingPluginFilter.java:74)
at com.atlassian.plugin.servlet.filter.IteratingFilterChain.doFilter(IteratingFilterChain.java:42)
at com.atlassian.plugin.servlet.filter.ServletFilterModuleContainerFilter.doFilter(ServletFilterModuleContainerFilter.java:77)
at com.atlassian.plugin.servlet.filter.ServletFilterModuleContainerFilter.doFilter(ServletFilterModuleContainerFilter.java:63)
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:235)
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
at com.atlassian.util.profiling.filters.ProfilingFilter.doFilter(ProfilingFilter.java:99)
at com.atlassian.jira.web.filters.JIRAProfilingFilter.doFilter(JIRAProfilingFilter.java:19)
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:235)
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
at com.atlassian.johnson.filters.AbstractJohnsonFilter.doFilter(AbstractJohnsonFilter.java:71)
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:235)
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
at org.tuckey.web.filters.urlrewrite.UrlRewriteFilter.doFilter(UrlRewriteFilter.java:350)
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:235)
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
at com.atlassian.gzipfilter.GzipFilter.doFilterInternal(GzipFilter.java:75)
at com.atlassian.gzipfilter.GzipFilter.doFilter(GzipFilter.java:51)
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:235)
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
at com.atlassian.plugin.servlet.filter.IteratingFilterChain.doFilter(IteratingFilterChain.java:46)
at com.atlassian.plugin.servlet.filter.DelegatingPluginFilter$1.doFilter(DelegatingPluginFilter.java:66)
at com.sysbliss.jira.plugins.workflow.servlet.JWDSendRedirectFilter.doFilter(JWDSendRedirectFilter.java:25)
at com.atlassian.plugin.servlet.filter.DelegatingPluginFilter.doFilter(DelegatingPluginFilter.java:74)
at com.atlassian.plugin.servlet.filter.IteratingFilterChain.doFilter(IteratingFilterChain.java:42)
at com.atlassian.plugin.servlet.filter.ServletFilterModuleContainerFilter.doFilter(ServletFilterModuleContainerFilter.java:77)
at com.atlassian.plugin.servlet.filter.ServletFilterModuleContainerFilter.doFilter(ServletFilterModuleContainerFilter.java:63)
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:235)
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
at com.atlassian.jira.web.filters.steps.ChainedFilterStepRunner.doFilter(ChainedFilterStepRunner.java:74)
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:235)
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
at com.atlassian.core.filters.cache.AbstractCachingFilter.doFilter(AbstractCachingFilter.java:33)
at com.atlassian.core.filters.AbstractHttpFilter.doFilter(AbstractHttpFilter.java:31)
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:235)
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
at com.atlassian.core.filters.encoding.AbstractEncodingFilter.doFilter(AbstractEncodingFilter.java:41)
at com.atlassian.core.filters.AbstractHttpFilter.doFilter(AbstractHttpFilter.java:31)
at com.atlassian.jira.web.filters.PathMatchingEncodingFilter.doFilter(PathMatchingEncodingFilter.java:49)
at com.atlassian.core.filters.AbstractHttpFilter.doFilter(AbstractHttpFilter.java:31)
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:235)
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
at com.atlassian.jira.web.monitor.ActiveRequestsFilter$PassToChainFilterFunc.doFilter(ActiveRequestsFilter.java:346)
at com.atlassian.jira.web.monitor.ActiveRequestsFilter$DebugLogFilterFunc.doFilter(ActiveRequestsFilter.java:463)
at com.atlassian.jira.web.monitor.ActiveRequestsFilter.doFilter(ActiveRequestsFilter.java:173)
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:235)
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
at com.atlassian.jira.startup.JiraStartupChecklistFilter.doFilter(JiraStartupChecklistFilter.java:75)
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:235)
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
at com.atlassian.multitenant.servlet.MultiTenantServletFilter.doFilter(MultiTenantServletFilter.java:91)
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:235)
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
at com.atlassian.jira.web.filters.steps.ChainedFilterStepRunner.doFilter(ChainedFilterStepRunner.java:74)
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:235)
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.core.StandardHostValve.invoke(StandardHostValve.java:127)
at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:102)
at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:109)
at org.apache.catalina.valves.AccessLogValve.invoke(AccessLogValve.java:554)
at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:298)
at org.apache.coyote.http11.Http11Processor.process(Http11Processor.java:859)
at org.apache.coyote.http11.Http11Protocol$Http11ConnectionHandler.process(Http11Protocol.java:588)
at org.apache.tomcat.util.net.JIoEndpoint$Worker.run(JIoEndpoint.java:489)
at java.lang.Thread.run(Unknown Source)

Caused by: org.apache.commons.dbcp.SQLNestedException: Cannot get a connection, pool exhausted, cause: Timeout waiting for idle object
at org.apache.commons.dbcp.PoolingDataSource.getConnection(PoolingDataSource.java:148)
at org.ofbiz.core.entity.transaction.DBCPConnectionFactory$1.call(DBCPConnectionFactory.java:153)
at org.ofbiz.core.entity.transaction.DBCPConnectionFactory$1.call(DBCPConnectionFactory.java:150)
at org.ofbiz.core.entity.jdbc.interceptors.connection.ConnectionTracker.trackConnection(ConnectionTracker.java:53)
... 114 more
Caused by: java.util.NoSuchElementException: Timeout waiting for idle object
at org.apache.commons.pool.impl.GenericObjectPool.borrowObject(GenericObjectPool.java:801)
at org.apache.commons.dbcp.PoolingDataSource.getConnection(PoolingDataSource.java:140)

... 117 more

I am wondering whether this could be a configuration issue or rather something else, perhaps more structural? I only found old (fixed) issues within the existing JIRA tracker relating to one of the above errors... And it is rather annoying to have our JIRA server dying on us from time to time :)

Anyone have an idea of what could be going on, and how to solve it?

[Radu Dumitriu · Accepted solution]

Cannot get a connection, pool exhausted => configuration issue, nothing structural about it.

Increase the database connections pool size.

[Frederic Iterbeke]

I've adjusted the previous value of 15 to 25, following http://confluence.atlassian.com/display/JIRA044/Connecting+JIRA+to+PostgreSQL

Hope this will solve the crashes. Isn't 15 a very low setting for any database used for collaborative efforts?

In any case, thanks for the help!

[Frederic Iterbeke]

The adjustment does not fix the crash, although it does fix the error stated above. In the latest crash, there are no errors whatsoever present in the logs (atlassian-jira.log as well as catalina.out).

The crash appears out of nowhere, just one user (me) editing some issues in JIRA.

Plus, our Confluence server runs on the same machine on a different port, and that one does not crash at any time. So I suspect the problem is not the machine itself but JIRA... And since there is no more information in the logs I am wondering how to isolate the problem...

Any help would be very welcome :)

[Radu Dumitriu]

People name 'crash' different things. My crash means JVM core dump. What happened, actually ?

[Frederic Iterbeke]

Well, the JIRA app just stopped working. There was no response from the web application, resulting in a 502 bad gateway error from the nginx server redirecting to it. I've checked out the JIRA logs on the server, but no errors are present. So my guess is the application server crashed. I had to manually restart the JIRA application.

How can I know if the JVM crashed? And if so, where can I find the JVM core dump? I've worked in Java environments before but never had to look into application server crashes...

[Radu Dumitriu]

Was jira still responding (without hitting nginx) ? Was the network ok between nginx and jira ? Was the java process still running ? etc etc. So many things can go wrong ...

[Frederic Iterbeke]

The server runs more java processes than just Jira, so it is not that easy to know which process is which application. The network between nginx and Jira was fine. Jira wasn't responding locally either.

I must say I didn't check whether the process was still running or not.

If I encounter the problem again, I will check all of the above and repost here.

For now it seems to be working fine though. Thank you very much for your help and comment!

[Antonio Zerbinati]

I've got the same problem with Microsoft SQL Server. My Jira (in a linux dedicated VirtualMachine, Hyper-V ) is used only be ME so the default connection pool size should be adeguate! Sql Server is on a differend windows VM. Night time backups stop the VM for fews minuts, this can cause open connection to get lost...

It seams JIRA don't clean-up opened connections or don't recognise some connection are actually closed.

I've tried to wait two full days to see if pool "respawn" some connection, but nothing happened.

Restaring jira solve the problem for a few days.. then it happen again and again.. (once every ~10 days).

If the poll's full, it's completely used by jira for a single user activity.. and that's is wierd regardless of how many connections are allowed.

[Frederic Iterbeke]

It seems AZerbinati is right: the same thing happened again.

Checklist:

- Jira was still running as a java process, but no longer responded to either local or remote web calls; network was ok.

- Every web call leads to a cascade of errors in the catalina.out log file:

2012-01-16 09:34:33,950 http-8080-2 ERROR anonymous 567x3838x3 - xxx.xxx.39.241,xxx.xxx.0.242 / [NoModule] There was an error getting a DBCP datasource.
java.lang.RuntimeException: Unable to obtain a connection from the underlying connection pool
at org.ofbiz.core.entity.jdbc.interceptors.connection.ConnectionTracker.trackConnection(ConnectionTracker.java:59)
at

....

Caused by: java.lang.IllegalStateException: Pool not open
at org.apache.commons.pool.BaseObjectPool.assertOpen(BaseObjectPool.java:123)
at org.apache.commons.pool.impl.GenericObjectPool.borrowObject(GenericObjectPool.java:767)
at org.apache.commons.dbcp.PoolingDataSource.getConnection(PoolingDataSource.java:140)
at

...

However, we never close the connections pool... So I am puzzled as to what is closing it (implicitly).

Restarting the Jira process fixes things temporarily, but this is a seriously annoying bug.

[Antonio Zerbinati]

It's happened again, as expected.

This time I've also checked, via SQL Server Activity Monitor, that there were not connections at all!

But still connection Pool has exausted without reason Java side. Enlarge pool size is not a solution, this just get jira last longer...

this is a portion of the stacktrace of tomcat log, may it help.

2012-01-26 19:24:43,874 http-8080-9 ERROR anonymous 1159x5503x2 - 192.168.118.38 / [NoModule] There was an error getting a DBCP datasource.
java.lang.RuntimeException: Unable to obtain a connection from the underlying connection pool
        at org.ofbiz.core.entity.jdbc.interceptors.connection.ConnectionTracker.trackConnection(ConnectionTracker.java:59)
        at org.ofbiz.core.entity.transaction.DBCPConnectionFactory.trackConnection(DBCPConnectionFactory.java:149)

Caused by: org.apache.commons.dbcp.SQLNestedException: Cannot get a connection, pool exhausted, cause: Timeout waiting for idle object
        at org.apache.commons.dbcp.PoolingDataSource.getConnection(PoolingDataSource.java:148)
        at org.ofbiz.core.entity.transaction.DBCPConnectionFactory$1.call(DBCPConnectionFactory.java:153)
        at org.ofbiz.core.entity.transaction.DBCPConnectionFactory$1.call(DBCPConnectionFactory.java:150)
        at org.ofbiz.core.entity.jdbc.interceptors.connection.ConnectionTracker.trackConnection(ConnectionTracker.java:53)
        ... 119 more
Caused by: java.util.NoSuchElementException: Timeout waiting for idle object
        at org.apache.commons.pool.impl.GenericObjectPool.borrowObject(GenericObjectPool.java:801)
        at org.apache.commons.dbcp.PoolingDataSource.getConnection(PoolingDataSource.java:140)
        ... 122 more

[Antonio Zerbinati]

It's happened again, as expected.

This time I've also checked, via SQL Server Activity Monitor, that there were not connections at all!

But still connection Pool has exausted without reason Java side. Enlarge pool size is not a solution, this just get jira last longer...

this is a portion of the stacktrace of tomcat log, may it help.

2012-01-26 19:24:43,874 http-8080-9 ERROR anonymous 1159x5503x2 - 192.168.118.38 / [NoModule] There was an error getting a DBCP datasource.
java.lang.RuntimeException: Unable to obtain a connection from the underlying connection pool
        at org.ofbiz.core.entity.jdbc.interceptors.connection.ConnectionTracker.trackConnection(ConnectionTracker.java:59)
        at org.ofbiz.core.entity.transaction.DBCPConnectionFactory.trackConnection(DBCPConnectionFactory.java:149)

Caused by: org.apache.commons.dbcp.SQLNestedException: Cannot get a connection, pool exhausted, cause: Timeout waiting for idle object
        at org.apache.commons.dbcp.PoolingDataSource.getConnection(PoolingDataSource.java:148)
        at org.ofbiz.core.entity.transaction.DBCPConnectionFactory$1.call(DBCPConnectionFactory.java:153)
        at org.ofbiz.core.entity.transaction.DBCPConnectionFactory$1.call(DBCPConnectionFactory.java:150)
        at org.ofbiz.core.entity.jdbc.interceptors.connection.ConnectionTracker.trackConnection(ConnectionTracker.java:53)
        ... 119 more
Caused by: java.util.NoSuchElementException: Timeout waiting for idle object
        at org.apache.commons.pool.impl.GenericObjectPool.borrowObject(GenericObjectPool.java:801)
        at org.apache.commons.dbcp.PoolingDataSource.getConnection(PoolingDataSource.java:140)
        ... 122 more

[Omer]

I have exactly same problem with v4.4.4. Is there any progress about this issue?

Thank you

[Radu Dumitriu]

This may be caused by:

1) Incorrect configuration; It is an incredible wide problem because nobody seems to bother reading http://commons.apache.org/dbcp/configuration.html and their JDBC driver notes. For instance, setting maxWait on negative (-1) will resolve the problem (threads will wait).

2) A plugin that uses incorrectly connections from pool and leaks them (or the core Jira). If this is the case, you can use removeAbandoned properties to work around it.

[Frederic Iterbeke]

The adjustment does not fix the crash, although it does fix the error stated above. In the latest crash, there are no errors whatsoever present in the logs (atlassian-jira.log as well as catalina.out).

The crash appears out of nowhere, just one user (me) editing some issues in JIRA.

Plus, our Confluence server runs on the same machine on a different port, and that one does not crash at any time. So I suspect the problem is not the machine itself but JIRA... And since there is no more information in the logs I am wondering how to isolate the problem...

Any help would be very welcome :)