-1

I faced a weird issue while testing my application, I got to see in the log that there were exceptions as shown below:

28-Jun-2017 19:25:52.736 SEVERE [http-nio-8443-exec-2] org.springframework.security.web.authentication.UsernamePasswordAuthenticationFilter.doFilter An internal error occurred while trying to authenticate the user.
     org.springframework.security.authentication.InternalAuthenticationServiceException: Could not open Hibernate Session for transaction; nested exception is org.hibernate.exception.GenericJDBCException: Unable to acquire JDBC Connection
        at org.springframework.security.authentication.dao.DaoAuthenticationProvider.retrieveUser(DaoAuthenticationProvider.java:126)
        at org.springframework.security.authentication.dao.AbstractUserDetailsAuthenticationProvider.authenticate(AbstractUserDetailsAuthenticationProvider.java:144)
        at org.springframework.security.authentication.ProviderManager.authenticate(ProviderManager.java:174)
        at org.springframework.security.authentication.ProviderManager.authenticate(ProviderManager.java:199)
        at org.springframework.security.web.authentication.UsernamePasswordAuthenticationFilter.attemptAuthentication(UsernamePasswordAuthenticationFilter.java:94)
        at org.springframework.security.web.authentication.AbstractAuthenticationProcessingFilter.doFilter(AbstractAuthenticationProcessingFilter.java:212)
        at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:331)
        at org.springframework.security.web.authentication.logout.LogoutFilter.doFilter(LogoutFilter.java:116)
        at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:331)
        at org.springframework.security.web.csrf.CsrfFilter.doFilterInternal(CsrfFilter.java:124)
        at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107)
        at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:331)
        at org.springframework.security.web.header.HeaderWriterFilter.doFilterInternal(HeaderWriterFilter.java:64)
        at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107)
        at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:331)
        at org.springframework.security.web.context.request.async.WebAsyncManagerIntegrationFilter.doFilterInternal(WebAsyncManagerIntegrationFilter.java:56)
        at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107)
        at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:331)
        at org.springframework.security.web.context.SecurityContextPersistenceFilter.doFilter(SecurityContextPersistenceFilter.java:105)
        at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:331)
        at org.springframework.security.web.FilterChainProxy.doFilterInternal(FilterChainProxy.java:214)
        at org.springframework.security.web.FilterChainProxy.doFilter(FilterChainProxy.java:177)
        at org.springframework.web.filter.DelegatingFilterProxy.invokeDelegate(DelegatingFilterProxy.java:346)
        at org.springframework.web.filter.DelegatingFilterProxy.doFilter(DelegatingFilterProxy.java:262)
        at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:240)
        at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:207)
        at org.springframework.orm.hibernate5.support.OpenSessionInViewFilter.doFilterInternal(OpenSessionInViewFilter.java:151)
        at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107)
        at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:240)
        at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:207)
        at com.cksoft.employeesolution.filter.TenantIdentifierFilter.doFilter(TenantIdentifierFilter.java:55)
        at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:240)
        at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:207)
        at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:212)
        at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:94)
        at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:616)
        at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:141)
        at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:79)
        at org.apache.catalina.valves.AbstractAccessLogValve.invoke(AbstractAccessLogValve.java:620)
        at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:88)
        at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:502)
        at org.apache.coyote.http11.AbstractHttp11Processor.process(AbstractHttp11Processor.java:1132)
        at org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process(AbstractProtocol.java:684)
        at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1533)
        at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.run(NioEndpoint.java:1489)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
        at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
        at java.lang.Thread.run(Thread.java:745)
    Caused by: org.springframework.transaction.CannotCreateTransactionException: Could not open Hibernate Session for transaction; nested exception is org.hibernate.exception.GenericJDBCException: Unable to acquire JDBC Connection
        at org.springframework.orm.hibernate5.HibernateTransactionManager.doBegin(HibernateTransactionManager.java:542)
        at org.springframework.transaction.support.AbstractPlatformTransactionManager.getTransaction(AbstractPlatformTransactionManager.java:373)
        at org.springframework.transaction.interceptor.TransactionAspectSupport.createTransactionIfNecessary(TransactionAspectSupport.java:447)
        at org.springframework.transaction.interceptor.TransactionAspectSupport.invokeWithinTransaction(TransactionAspectSupport.java:277)
        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:213)
        at com.sun.proxy.$Proxy62.loadUserByUsername(Unknown Source)
        at org.springframework.security.authentication.dao.DaoAuthenticationProvider.retrieveUser(DaoAuthenticationProvider.java:114)
        ... 48 more
    Caused by: org.hibernate.exception.GenericJDBCException: Unable to acquire JDBC Connection
        at org.hibernate.exception.internal.StandardSQLExceptionConverter.convert(StandardSQLExceptionConverter.java:47)
        at org.hibernate.engine.jdbc.spi.SqlExceptionHelper.convert(SqlExceptionHelper.java:111)
        at org.hibernate.engine.jdbc.spi.SqlExceptionHelper.convert(SqlExceptionHelper.java:97)
        at org.hibernate.resource.jdbc.internal.LogicalConnectionManagedImpl.acquireConnectionIfNeeded(LogicalConnectionManagedImpl.java:87)
        at org.hibernate.resource.jdbc.internal.LogicalConnectionManagedImpl.getPhysicalConnection(LogicalConnectionManagedImpl.java:109)
        at org.hibernate.internal.SessionImpl.connection(SessionImpl.java:492)
        at org.springframework.orm.hibernate5.HibernateTransactionManager.doBegin(HibernateTransactionManager.java:448)
        ... 56 more
    Caused by: java.sql.SQLException: Cannot get a connection, pool error Timeout waiting for idle object
        at org.apache.commons.dbcp2.PoolingDataSource.getConnection(PoolingDataSource.java:142)
        at org.apache.commons.dbcp2.BasicDataSource.getConnection(BasicDataSource.java:1533)
        at com.cksoft.employeesolution.multitenancy.CustomMultiTenantConnectionProvider.getConnection(CustomMultiTenantConnectionProvider.java:46)
        at org.hibernate.internal.AbstractSessionImpl$ContextualJdbcConnectionAccess.obtainConnection(AbstractSessionImpl.java:429)
        at org.hibernate.resource.jdbc.internal.LogicalConnectionManagedImpl.acquireConnectionIfNeeded(LogicalConnectionManagedImpl.java:84)
        ... 59 more
    Caused by: java.util.NoSuchElementException: Timeout waiting for idle object
        at org.apache.commons.pool2.impl.GenericObjectPool.borrowObject(GenericObjectPool.java:449)
        at org.apache.commons.pool2.impl.GenericObjectPool.borrowObject(GenericObjectPool.java:363)
        at org.apache.commons.dbcp2.PoolingDataSource.getConnection(PoolingDataSource.java:134)
        ... 63 more

    28-Jun-2017 19:29:23.308 INFO [http-nio-8443-exec-8] org.apache.tomcat.websocket.server.WsRemoteEndpointImplServer.doClose Failed to close the ServletOutputStream connection cleanly
     java.io.IOException: Broken pipe
        at sun.nio.ch.FileDispatcherImpl.write0(Native Method)
        at sun.nio.ch.SocketDispatcher.write(SocketDispatcher.java:47)
        at sun.nio.ch.IOUtil.writeFromNativeBuffer(IOUtil.java:93)
        at sun.nio.ch.IOUtil.write(IOUtil.java:51)
        at sun.nio.ch.SocketChannelImpl.write(SocketChannelImpl.java:492)
        at org.apache.tomcat.util.net.SecureNioChannel.flush(SecureNioChannel.java:140)
        at org.apache.tomcat.util.net.SecureNioChannel.close(SecureNioChannel.java:385)
        at org.apache.tomcat.util.net.SecureNioChannel.close(SecureNioChannel.java:413)
        at org.apache.coyote.http11.upgrade.NioServletOutputStream.doClose(NioServletOutputStream.java:138)
        at org.apache.coyote.http11.upgrade.AbstractServletOutputStream.close(AbstractServletOutputStream.java:140)
        at org.apache.tomcat.websocket.server.WsRemoteEndpointImplServer.doClose(WsRemoteEndpointImplServer.java:139)
        at org.apache.tomcat.websocket.WsRemoteEndpointImplBase.close(WsRemoteEndpointImplBase.java:667)
        at org.apache.tomcat.websocket.server.WsRemoteEndpointImplServer.onWritePossible(WsRemoteEndpointImplServer.java:114)
        at org.apache.tomcat.websocket.server.WsRemoteEndpointImplServer.doWrite(WsRemoteEndpointImplServer.java:79)
        at org.apache.tomcat.websocket.WsRemoteEndpointImplBase.writeMessagePart(WsRemoteEndpointImplBase.java:453)
        at org.apache.tomcat.websocket.WsRemoteEndpointImplBase.startMessage(WsRemoteEndpointImplBase.java:341)
        at org.apache.tomcat.websocket.WsRemoteEndpointImplBase.startMessageBlock(WsRemoteEndpointImplBase.java:273)
        at org.apache.tomcat.websocket.WsSession.sendCloseMessage(WsSession.java:600)
        at org.apache.tomcat.websocket.WsSession.doClose(WsSession.java:490)
        at org.apache.tomcat.websocket.server.WsHttpUpgradeHandler.onError(WsHttpUpgradeHandler.java:149)
        at org.apache.tomcat.websocket.server.WsHttpUpgradeHandler.access$300(WsHttpUpgradeHandler.java:47)
        at org.apache.tomcat.websocket.server.WsHttpUpgradeHandler$WsReadListener.onError(WsHttpUpgradeHandler.java:206)
        at org.apache.tomcat.websocket.server.WsHttpUpgradeHandler$WsReadListener.onDataAvailable(WsHttpUpgradeHandler.java:189)
        at org.apache.coyote.http11.upgrade.AbstractServletInputStream.onDataAvailable(AbstractServletInputStream.java:198)
        at org.apache.coyote.http11.upgrade.AbstractProcessor.upgradeDispatch(AbstractProcessor.java:96)
        at org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process(AbstractProtocol.java:661)
        at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1533)
        at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.run(NioEndpoint.java:1489)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
        at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
        at java.lang.Thread.run(Thread.java:745)

After this I couldn't do registration/login etc. As it states it was failing to obtain the connection for the DB.

I have used DBCP2 and following configuration is being used for this.

<?xml version="1.0" encoding="UTF-8"?>
<beans xmlns="http://www.springframework.org/schema/beans"
    xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
    xsi:schemaLocation="http://www.springframework.org/schema/beans http://www.springframework.org/schema/beans/spring-beans.xsd">
    <bean class="org.apache.commons.dbcp2.BasicDataSource" id="dataSource"
        destroy-method="close">
        <property name="driverClassName" value="${db.driverClassName}" />
        <property name="url" value="${db.url}" />
        <property name="username" value="${db.username}" />
        <property name="password" value="${db.password}" />
        <property name="maxTotal" value="60" />
        <property name="maxWaitMillis" value="20000" />
    </bean>
</beans>

I am assuming here that the DB pool gets exhausted. But I am also closing connections in my Hibernate code as shown below.

@Override
    public void releaseAnyConnection(Connection connection) throws SQLException {
        if (LOG.isDebugEnabled()) {
            LOG.debug("Releasing connection obtained by : getAnyConnection", connection);
        }
        connection.close();
    }

    @Override
    public void releaseConnection(String tenantIdentifier, Connection connection) throws SQLException {
        if (LOG.isDebugEnabled()) {
            LOG.debug("Releasing connection for : {}", tenantIdentifier);
        }
        connection.close();
    }
Bilbo Baggins
  • 2,899
  • 10
  • 52
  • 77
  • Enable logging on the pool to see its state. It looks like the pool is running out of connections, so you're probably not closing all the connections as you think. I'd also use `try-with-resources` instead of relying on calling a separate closing method. – Kayaman Jun 30 '17 at 07:53
  • Does the rest of the configuration seems fine? or you suggest some improvement ? I will check and try to close it properly, as you can see these methods are from `MultiTenantConnectionProvider` of hibernate and hence I can't use try with resources. – Bilbo Baggins Jun 30 '17 at 08:37
  • Enable logging for the pool, it will tell you a lot better what's happening. – Kayaman Jun 30 '17 at 08:49

1 Answers1

0

I had similar issue, here was my stacktrace

Caused by: java.sql.SQLException: Cannot get a connection, general error
    at org.apache.commons.dbcp2.PoolingDataSource.getConnection(PoolingDataSource.java:148) ~[commons-dbcp2-2.7.0.jar!/:2.7.0]
    at org.apache.commons.dbcp2.BasicDataSource.getConnection(BasicDataSource.java:753) ~[commons-dbcp2-2.7.0.jar!/:2.7.0]
    at org.springframework.jdbc.datasource.DataSourceUtils.fetchConnection(DataSourceUtils.java:151) ~[spring-jdbc-5.0.4.RELEASE.jar!/:5.0.4.RELEASE]
    at org.springframework.jdbc.datasource.DataSourceUtils.doGetConnection(DataSourceUtils.java:115) ~[spring-jdbc-5.0.4.RELEASE.jar!/:5.0.4.RELEASE]
    at org.springframework.jdbc.datasource.DataSourceUtils.getConnection(DataSourceUtils.java:78) ~[spring-jdbc-5.0.4.RELEASE.jar!/:5.0.4.RELEASE]
    ... 124 more
Caused by: java.lang.InterruptedException
    at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.reportInterruptAfterWait(AbstractQueuedSynchronizer.java:2014) ~[?:1.8.0_222-ea]
    at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2048) ~[?:1.8.0_222-ea]
    at org.apache.commons.pool2.impl.LinkedBlockingDeque.takeFirst(LinkedBlockingDeque.java:590) ~[commons-pool2-2.5.0.jar!/:2.5.0]
    at org.apache.commons.pool2.impl.GenericObjectPool.borrowObject(GenericObjectPool.java:441) ~[commons-pool2-2.5.0.jar!/:2.5.0]
    at org.apache.commons.pool2.impl.GenericObjectPool.borrowObject(GenericObjectPool.java:362) ~[commons-pool2-2.5.0.jar!/:2.5.0]
    at org.apache.commons.dbcp2.PoolingDataSource.getConnection(PoolingDataSource.java:134) ~[commons-dbcp2-2.7.0.jar!/:2.7.0]
    at org.apache.commons.dbcp2.BasicDataSource.getConnection(BasicDataSource.java:753) ~[commons-dbcp2-2.7.0.jar!/:2.7.0]
    at org.springframework.jdbc.datasource.DataSourceUtils.fetchConnection(DataSourceUtils.java:151) ~[spring-jdbc-5.0.4.RELEASE.jar!/:5.0.4.RELEASE]
    at org.springframework.jdbc.datasource.DataSourceUtils.doGetConnection(DataSourceUtils.java:115) ~[spring-jdbc-5.0.4.RELEASE.jar!/:5.0.4.RELEASE]
    at org.springframework.jdbc.datasource.DataSourceUtils.getConnection(DataSourceUtils.java:78) ~[spring-jdbc-5.0.4.RELEASE.jar!/:5.0.4.RELEASE]
    ... 124 more

And this exception didn't appear immediately. Application was just hanging forever. I only saw this stacktrace, when I killed the application.

I'm using spring-jdbc, postgres.

What helped me was setting some dbcp2 properties. They were not set earlier, so default values were used. I set the following properties, and it helped:

spring.datasource.dbcp2.test-on-borrow=true
spring.datasource.dbcp2.test-on-create=true
spring.datasource.dbcp2.validation-query=select current_date
spring.datasource.dbcp2.max-wait-millis=10000

Not sure which of them helped me. I believe mostly in max-wait-millis. Because by default it is -1, so it was waiting forever for the available object in LinkedBlockingDeque. And in validation-query

Oleksii Volynskyi
  • 1,317
  • 1
  • 8
  • 5