I am possibly having database connection issues on startup, what could be the problem?

Question

Hello Gents, I am having issues starting a confluence server instance. At first, I thought it was a permissions issues since the user 'confluence' was not the owner of the application directory but fixing that did nothing. Here is a piece of the atlassian-confluence.log logs that I have been seeing. Part of is telling me that is an issue connecting to the database but i checked the configs on confluence.cfg.xml and confirmed that the correct login credentials and also network access were correct. 2020-06-05 17:02:34,084 WARN [C3P0PooledConnectionPoolManager[identityToken->2t0opjaa11ficneksf367|dc80ff3]-HelperThread-#2] [mchange.v2.resourcepool.BasicResourcePool] log Having failed to acquire a resource, com.mchange.v2.resourcepool.BasicResourcePool@40795f36 is interrupting all Threads waiting on a resource to check out. Will try again in response to new client requests. 2020-06-05 17:02:38,075 WARN [C3P0PooledConnectionPoolManager[identityToken->2t0opjaa11ficneksf367|3401c5bb]-HelperThread-#2] [mchange.v2.resourcepool.BasicResourcePool] log com.mchange.v2.resourcepool.BasicResourcePool$ScatteredAcquireTask@30a4b839 -- Acquisition Attempt Failed!!! Clearing pending acquires. While trying to acquire a needed new resource, we failed to succeed more than the maximum number of allowed acquisition attempts (30). Last acquisition attempt exception: org.postgresql.util.PSQLException: This ResultSet is closed. at org.postgresql.jdbc2.AbstractJdbc2ResultSet.checkClosed(AbstractJdbc2ResultSet.java:2839) at org.postgresql.jdbc2.AbstractJdbc2ResultSet.setFetchSize(AbstractJdbc2ResultSet.java:1874) at org.postgresql.jdbc4.Jdbc4Statement.createResultSet(Jdbc4Statement.java:37) at org.postgresql.jdbc2.AbstractJdbc2Statement$StatementResultHandler.handleResultRows(AbstractJdbc2Statement.java:219) at org.postgresql.core.v3.QueryExecutorImpl.processResults(QueryExecutorImpl.java:1812) at org.postgresql.core.v3.QueryExecutorImpl.execute(QueryExecutorImpl.java:255) at org.postgresql.jdbc2.AbstractJdbc2Statement.execute(AbstractJdbc2Statement.java:555) at org.postgresql.jdbc2.AbstractJdbc2Statement.executeWithFlags(AbstractJdbc2Statement.java:403) at org.postgresql.jdbc2.AbstractJdbc2Connection.execSQLUpdate(AbstractJdbc2Connection.java:366) at org.postgresql.jdbc2.AbstractJdbc2Connection.getTransactionIsolation(AbstractJdbc2Connection.java:883) at com.mchange.v2.c3p0.impl.NewPooledConnection.(NewPooledConnection.java:120) at com.mchange.v2.c3p0.WrapperConnectionPoolDataSource.getPooledConnection(WrapperConnectionPoolDataSource.java:240) at com.mchange.v2.c3p0.WrapperConnectionPoolDataSource.getPooledConnection(WrapperConnectionPoolDataSource.java:206) at com.mchange.v2.c3p0.impl.C3P0PooledConnectionPool$1PooledConnectionResourcePoolManager.acquireResource(C3P0PooledConnectionPool.java:203) at com.mchange.v2.resourcepool.BasicResourcePool.doAcquire(BasicResourcePool.java:1138) at com.mchange.v2.resourcepool.BasicResourcePool.doAcquireAndDecrementPendingAcquiresWithinLockOnSuccess(BasicResourcePool.java:1125) at com.mchange.v2.resourcepool.BasicResourcePool.access$700(BasicResourcePool.java:44) at com.mchange.v2.resourcepool.BasicResourcePool$ScatteredAcquireTask.run(BasicResourcePool.java:1870) at com.mchange.v2.async.ThreadPoolAsynchronousRunner$PoolThread.run(ThreadPoolAsynchronousRunner.java:696) 2020-06-05 17:02:38,075 WARN [C3P0PooledConnectionPoolManager[identityToken->2t0opjaa11ficneksf367|3401c5bb]-HelperThread-#2] [mchange.v2.resourcepool.BasicResourcePool] log Having failed to acquire a resource, com.mchange.v2.resourcepool.BasicResourcePool@319bd776 is interrupting all Threads waiting on a resource to check out. Will try again in response to new client requests. 2020-06-05 17:02:38,076 ERROR [localhost-startStop-1] [sf.hibernate.util.JDBCExceptionReporter] logExceptions Connections could not be acquired from the underlying database! 2020-06-05 17:02:38,075 WARN [C3P0PooledConnectionPoolManager[identityToken->2t0opjaa11ficneksf367|3401c5bb]-HelperThread-#0] [mchange.v2.resourcepool.BasicResourcePool] log com.mchange.v2.resourcepool.BasicResourcePool$ScatteredAcquireTask@2cc844d9 -- Acquisition Attempt Failed!!! Clearing pending acquires. While trying to acquire a needed new resource, we failed to succeed more than the maximum number of allowed acquisition attempts (30). Last acquisition attempt exception: org.postgresql.util.PSQLException: This ResultSet is closed. at org.postgresql.jdbc2.AbstractJdbc2ResultSet.checkClosed(AbstractJdbc2ResultSet.java:2839) at org.postgresql.jdbc2.AbstractJdbc2ResultSet.setFetchSize(AbstractJdbc2ResultSet.java:1874) at org.postgresql.jdbc4.Jdbc4Statement.createResultSet(Jdbc4Statement.java:37) at org.postgresql.jdbc2.AbstractJdbc2Statement$StatementResultHandler.handleResultRows(AbstractJdbc2Statement.java:219) at org.postgresql.core.v3.QueryExecutorImpl.processResults(QueryExecutorImpl.java:1812) at org.postgresql.core.v3.QueryExecutorImpl.execute(QueryExecutorImpl.java:255) at org.postgresql.jdbc2.AbstractJdbc2Statement.execute(AbstractJdbc2Statement.java:555) at org.postgresql.jdbc2.AbstractJdbc2Statement.executeWithFlags(AbstractJdbc2Statement.java:403) at org.postgresql.jdbc2.AbstractJdbc2Connection.execSQLUpdate(AbstractJdbc2Connection.java:366) at org.postgresql.jdbc2.AbstractJdbc2Connection.getTransactionIsolation(AbstractJdbc2Connection.java:883) at com.mchange.v2.c3p0.impl.NewPooledConnection.(NewPooledConnection.java:120) at com.mchange.v2.c3p0.WrapperConnectionPoolDataSource.getPooledConnection(WrapperConnectionPoolDataSource.java:240) at com.mchange.v2.c3p0.WrapperConnectionPoolDataSource.getPooledConnection(WrapperConnectionPoolDataSource.java:206) at com.mchange.v2.c3p0.impl.C3P0PooledConnectionPool$1PooledConnectionResourcePoolManager.acquireResource(C3P0PooledConnectionPool.java:203) at com.mchange.v2.resourcepool.BasicResourcePool.doAcquire(BasicResourcePool.java:1138) at com.mchange.v2.resourcepool.BasicResourcePool.doAcquireAndDecrementPendingAcquiresWithinLockOnSuccess(BasicResourcePool.java:1125) at com.mchange.v2.resourcepool.BasicResourcePool.access$700(BasicResourcePool.java:44) at com.mchange.v2.resourcepool.BasicResourcePool$ScatteredAcquireTask.run(BasicResourcePool.java:1870) at com.mchange.v2.async.ThreadPoolAsynchronousRunner$PoolThread.run(ThreadPoolAsynchronousRunner.java:696) 2020-06-05 17:02:38,076 WARN [C3P0PooledConnectionPoolManager[identityToken->2t0opjaa11ficneksf367|3401c5bb]-HelperThread-#0] [mchange.v2.resourcepool.BasicResourcePool] log Having failed to acquire a resource, com.mchange.v2.resourcepool.BasicResourcePool@319bd776 is interrupting all Threads waiting on a resource to check out. Will try again in response to new client requests. 2020-06-05 17:02:38,076 WARN [localhost-startStop-1] [confluence.impl.vcache.SynchronousExternalCache] lambda$get$11 Failed to read entry from cache 'com.atlassian.bandana.BandanaPersister': Failed due to UNCLASSIFIED_FAILURE 2020-06-05 17:02:43,944 WARN [Navlink Plugin Executor:thread-4] [confluence.impl.vcache.SynchronousExternalCache] lambda$get$11 Failed to read entry from cache 'com.atlassian.bandana.BandanaPersister': Failed due to UNCLASSIFIED_FAILURE

Nic Brough -Adaptavist- · Answer

Ok, it now has a healthy pool, so we can rule that out, but now all I can suggest is that the database is being overwhelmed by something or the connection is failing over the network.

Does the database server look healthy?  No spikes in resource usage and no network slowdowns or outages?

Gustavo_Iturriaga_Jr · Answer

I went ahead and increased the pool size c3p0.max_size to 60 but I still get some errors:

2020-06-08 14:10:08,863 WARN [C3P0PooledConnectionPoolManager[identityToken->2t0opjaa15jo89g17pq7se|56803e16]-HelperThread-#1] [mchange.v2.resourcepool.BasicResourcePool] log Having failed to acquire a resource, com.mchange.v2.resourcepool.BasicResourcePool@503655f8 is interrupting all Threads waiting on a resource to check out. Will try again in response to new client requests.
2020-06-08 14:10:08,863 ERROR [localhost-startStop-1] [atlassian.confluence.plugin.BandanaPluginStateStore] save Exception when saving plugins state to the database. Saving to in memory state.
org.springframework.transaction.CannotCreateTransactionException: Could not open Hibernate Session for transaction; nested exception is net.sf.hibernate.exception.GenericJDBCException: Cannot open connection
at org.springframework.orm.hibernate.HibernateTransactionManager.doBegin(HibernateTransactionManager.java:473)
at org.springframework.transaction.support.AbstractPlatformTransactionManager.getTransaction(AbstractPlatformTransactionManager.java:373)
at sun.reflect.GeneratedMethodAccessor57.invoke(Unknown Source)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:498)
at org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:302)
at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:202)
at com.sun.proxy.$Proxy32.getTransaction(Unknown Source)
at org.springframework.transaction.interceptor.TransactionAspectSupport.createTransactionIfNecessary(TransactionAspectSupport.java:427)
at org.springframework.transaction.interceptor.TransactionAspectSupport.invokeWithinTransaction(TransactionAspectSupport.java:276)
at org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:96)
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:179)
at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:208)
at com.sun.proxy.$Proxy34.store(Unknown Source)
at com.atlassian.confluence.setup.bandana.ConfluenceCachingBandanaPersister.store(ConfluenceCachingBandanaPersister.java:140)
at com.atlassian.confluence.setup.bandana.ConfluenceCachingBandanaPersister.store(ConfluenceCachingBandanaPersister.java:118)
at com.atlassian.bandana.DefaultBandanaManager.setValue(DefaultBandanaManager.java:48)
at com.atlassian.confluence.plugin.BandanaPluginStateStore.lambda$save$0(BandanaPluginStateStore.java:36)
at com.atlassian.confluence.tenant.TenantGate$3.call(TenantGate.java:141)
at com.atlassian.confluence.plugin.BandanaPluginStateStore.save(BandanaPluginStateStore.java:42)
at com.atlassian.confluence.plugin.CachingPluginStateStore.save(CachingPluginStateStore.java:37)
at com.atlassian.plugin.manager.PluginPersistentStateModifier.apply(PluginPersistentStateModifier.java:32)
at com.atlassian.plugin.manager.PluginPersistentStateModifier.setEnabled(PluginPersistentStateModifier.java:53)
at com.atlassian.plugin.manager.PluginPersistentStateModifier.enable(PluginPersistentStateModifier.java:66)
at com.atlassian.plugin.manager.DefaultPluginManager.enablePluginModule(DefaultPluginManager.java:1975)
at com.atlassian.confluence.plugin.EventDispatchingPluginController.enablePluginModule(EventDispatchingPluginController.java:71)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:498)
at org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:302)
at org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint(ReflectiveMethodInvocation.java:190)
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:157)
at org.springframework.transaction.interceptor.TransactionInterceptor$1.proceedWithInvocation(TransactionInterceptor.java:99)
at org.springframework.transaction.interceptor.TransactionAspectSupport.invokeWithinTransaction(TransactionAspectSupport.java:281)
at org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:96)
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:179)
at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:208)
at com.sun.proxy.$Proxy97.enablePluginModule(Unknown Source)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:498)
at com.atlassian.plugin.util.ContextClassLoaderSettingInvocationHandler.invoke(ContextClassLoaderSettingInvocationHandler.java:26)
at com.sun.proxy.$Proxy379.enablePluginModule(Unknown Source)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:498)
at com.atlassian.plugin.osgi.bridge.external.HostComponentFactoryBean$DynamicServiceInvocationHandler.invoke(HostComponentFactoryBean.java:136)
at com.sun.proxy.$Proxy379.enablePluginModule(Unknown Source)
at com.atlassian.confluence.notifications.impl.descriptors.NotificationTemplateDescriptor.enabled(NotificationTemplateDescriptor.java:92)
at com.atlassian.plugin.manager.DefaultPluginManager.notifyModuleEnabled(DefaultPluginManager.java:1991)
at com.atlassian.plugin.manager.DefaultPluginManager.enableConfiguredPluginModule(DefaultPluginManager.java:1738)
at com.atlassian.plugin.manager.DefaultPluginManager.enableConfiguredPluginModules(DefaultPluginManager.java:1715)
at com.atlassian.plugin.manager.DefaultPluginManager.enableDependentPlugins(DefaultPluginManager.java:1227)
at com.atlassian.plugin.manager.DefaultPluginManager.addPlugins(DefaultPluginManager.java:1188)
at com.atlassian.plugin.manager.DefaultPluginManager.earlyStartup(DefaultPluginManager.java:573)
at com.atlassian.confluence.plugin.ConfluencePluginManager.earlyStartup(ConfluencePluginManager.java:141)
at com.atlassian.confluence.plugin.PluginFrameworkContextListener.contextInitialized(PluginFrameworkContextListener.java:63)
at org.apache.catalina.core.StandardContext.listenerStart(StandardContext.java:4842)
at org.apache.catalina.core.StandardContext.startInternal(StandardContext.java:5303)
at org.apache.catalina.util.LifecycleBase.start(LifecycleBase.java:147)
at org.apache.catalina.core.ContainerBase$StartChild.call(ContainerBase.java:1407)
at org.apache.catalina.core.ContainerBase$StartChild.call(ContainerBase.java:1397)
at java.util.concurrent.FutureTask.run(FutureTask.java:266)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
at java.lang.Thread.run(Thread.java:745)
Caused by: net.sf.hibernate.exception.GenericJDBCException: Cannot open connection
at net.sf.hibernate.exception.SQLStateConverter.handledNonSpecificException(SQLStateConverter.java:80)
at net.sf.hibernate.exception.SQLStateConverter.convert(SQLStateConverter.java:69)
at net.sf.hibernate.exception.JDBCExceptionHelper.convert(JDBCExceptionHelper.java:29)
at net.sf.hibernate.impl.BatcherImpl.convert(BatcherImpl.java:328)
at net.sf.hibernate.impl.BatcherImpl.openConnection(BatcherImpl.java:295)
at net.sf.hibernate.impl.SessionImpl.connect(SessionImpl.java:3407)
at net.sf.hibernate.impl.SessionImpl.connection(SessionImpl.java:3367)
at org.springframework.orm.hibernate.HibernateTransactionManager.doBegin(HibernateTransactionManager.java:422)
... 68 more
Caused by: java.sql.SQLException: Connections could not be acquired from the underlying database!
at com.mchange.v2.sql.SqlUtils.toSQLException(SqlUtils.java:118)
at com.mchange.v2.c3p0.impl.C3P0PooledConnectionPool.checkoutPooledConnection(C3P0PooledConnectionPool.java:692)
at com.mchange.v2.c3p0.impl.AbstractPoolBackedDataSource.getConnection(AbstractPoolBackedDataSource.java:140)
at net.sf.hibernate.connection.C3P0ConnectionProvider.getConnection(C3P0ConnectionProvider.java:36)
at bucket.core.persistence.hibernate.ConfluenceSharedConnectionProvider.getConnection(ConfluenceSharedConnectionProvider.java:34)
at net.sf.hibernate.impl.BatcherImpl.openConnection(BatcherImpl.java:292)
... 71 more
Caused by: com.mchange.v2.resourcepool.CannotAcquireResourceException: A ResourcePool could not acquire a resource from its primary factory or source.
at com.mchange.v2.resourcepool.BasicResourcePool.awaitAvailable(BasicResourcePool.java:1469)
at com.mchange.v2.resourcepool.BasicResourcePool.prelimCheckoutResource(BasicResourcePool.java:644)
at com.mchange.v2.resourcepool.BasicResourcePool.checkoutResource(BasicResourcePool.java:554)
at com.mchange.v2.c3p0.impl.C3P0PooledConnectionPool.checkoutAndMarkConnectionInUse(C3P0PooledConnectionPool.java:758)
at com.mchange.v2.c3p0.impl.C3P0PooledConnectionPool.checkoutPooledConnection(C3P0PooledConnectionPool.java:685)
... 75 more
2020-06-08 14:10:11,075 WARN [Navlink Plugin Executor:thread-5] [confluence.impl.vcache.SynchronousExternalCache] lambda$get$11 Failed to read entry from cache 'com.atlassian.bandana.BandanaPersister': Failed due to UNCLASSIFIED_FAILURE
2020-06-08 14:10:11,279 WARN [C3P0PooledConnectionPoolManager[identityToken->2t0opjaa15jo89g17pq7se|6c84519f]-HelperThread-#2] [mchange.v2.resourcepool.BasicResourcePool] log com.mchange.v2.resourcepool.BasicResourcePool$ScatteredAcquireTask@512b8d26 -- Acquisition Attempt Failed!!! Clearing pending acquires. While trying to acquire a needed new resource, we failed to succeed more than the maximum number of allowed acquisition attempts (30). Last acquisition attempt exception:
org.postgresql.util.PSQLException: This ResultSet is closed.
at org.postgresql.jdbc2.AbstractJdbc2ResultSet.checkClosed(AbstractJdbc2ResultSet.java:2839)
at org.postgresql.jdbc2.AbstractJdbc2ResultSet.setFetchSize(AbstractJdbc2ResultSet.java:1874)
at org.postgresql.jdbc4.Jdbc4Statement.createResultSet(Jdbc4Statement.java:37)
at org.postgresql.jdbc2.AbstractJdbc2Statement$StatementResultHandler.handleResultRows(AbstractJdbc2Statement.java:219)
at org.postgresql.core.v3.QueryExecutorImpl.processResults(QueryExecutorImpl.java:1812)
at org.postgresql.core.v3.QueryExecutorImpl.execute(QueryExecutorImpl.java:255)
at org.postgresql.jdbc2.AbstractJdbc2Statement.execute(AbstractJdbc2Statement.java:555)
at org.postgresql.jdbc2.AbstractJdbc2Statement.executeWithFlags(AbstractJdbc2Statement.java:403)
at org.postgresql.jdbc2.AbstractJdbc2Connection.execSQLUpdate(AbstractJdbc2Connection.java:366)
at org.postgresql.jdbc2.AbstractJdbc2Connection.getTransactionIsolation(AbstractJdbc2Connection.java:883)
at com.mchange.v2.c3p0.impl.NewPooledConnection.<init>(NewPooledConnection.java:120)
at com.mchange.v2.c3p0.WrapperConnectionPoolDataSource.getPooledConnection(WrapperConnectionPoolDataSource.java:240)
at com.mchange.v2.c3p0.WrapperConnectionPoolDataSource.getPooledConnection(WrapperConnectionPoolDataSource.java:206)
at com.mchange.v2.c3p0.impl.C3P0PooledConnectionPool$1PooledConnectionResourcePoolManager.acquireResource(C3P0PooledConnectionPool.java:203)
at com.mchange.v2.resourcepool.BasicResourcePool.doAcquire(BasicResourcePool.java:1138)
at com.mchange.v2.resourcepool.BasicResourcePool.doAcquireAndDecrementPendingAcquiresWithinLockOnSuccess(BasicResourcePool.java:1125)
at com.mchange.v2.resourcepool.BasicResourcePool.access$700(BasicResourcePool.java:44)
at com.mchange.v2.resourcepool.BasicResourcePool$ScatteredAcquireTask.run(BasicResourcePool.java:1870)
at com.mchange.v2.async.ThreadPoolAsynchronousRunner$PoolThread.run(ThreadPoolAsynchronousRunner.java:696)
2020-06-08 14:10:11,279 WARN [C3P0PooledConnectionPoolManager[identityToken->2t0opjaa15jo89g17pq7se|6c84519f]-HelperThread-#2] [mchange.v2.resourcepool.BasicResourcePool] log Having failed to acquire a resource, com.mchange.v2.resourcepool.BasicResourcePool@6f6d4fa9 is interrupting all Threads waiting on a resource to check out. Will try again in response to new client requests.
2020-06-08 14:10:21,075 WARN [Navlink Plugin Executor:thread-3] [confluence.impl.vcache.SynchronousExternalCache] lambda$get$11 Failed to read entry from cache 'com.atlassian.bandana.BandanaPersister': Failed due to UNCLASSIFIED_FAILURE
2020-06-08 14:10:31,075 WARN [Navlink Plugin Executor:thread-6] [confluence.impl.vcache.SynchronousExternalCache] lambda$get$11 Failed to read entry from cache 'com.atlassian.bandana.BandanaPersister': Failed due to UNCLASSIFIED_FAILURE
2020-06-08 14:10:39,108 WARN [C3P0PooledConnectionPoolManager[identityToken->2t0opjaa15jo89g17pq7se|56803e16]-HelperThread-#1] [mchange.v2.resourcepool.BasicResourcePool] log com.mchange.v2.resourcepool.BasicResourcePool$ScatteredAcquireTask@6f6d5d79 -- Acquisition Attempt Failed!!! Clearing pending acquires. While trying to acquire a needed new resource, we failed to succeed more than the maximum number of allowed acquisition attempts (30). Last acquisition attempt exception

Nic Brough -Adaptavist- · Answer

hibernate.c3p0.timeout - I can never remember it until I see it!