2

I've enterprise application that's using sql serve database and deployed on Websphere Application Server V8.0 and lately, it's been decided to use c3p0 connection pooling. Now after starting the deployed ear for sometime we are facing some down times leading to errors in loading/saving some values inside the code. The exceptions showed are the following and none other. I omitted some lines with dots that I can't share.

logs deleted due characters limit. Kindly check the update below.

c3p0 configuration

#hibernate C3P0 config
connection.provider_class= org.hibernate.connection.C3P0ConnectionProvider
hibernate.c3p0.idle_test_period= 300
hibernate.c3p0.unreturnedConnectionTimeout= 30
hibernate.c3p0.debugUnreturnedConnectionStackTraces= false
hibernate.c3p0.maxConnectionAge= 2000
hibernate.c3p0.min_size= 1
hibernate.c3p0.max_size= 1000
hibernate.c3p0.timeout= 1000
hibernate.c3p0.maxIdleTimeExcessConnections= 15
hibernate.c3p0.testConnectionOnCheckin= true
hibernate.c3p0.testConnectionOnCheckout = true
hibernate.c3p0.preferredTestQuery= SELECT 1;
hibernate.c3p0.privilegeSpawnedThreads= true
hibernate.c3p0.contextClassLoaderSource= library
hibernate.c3p0.idleConnectionTestPeriod = 300

This also happens when changing some values like

idleConnectionTestPeriod = 30
maxConnectionAge = 500

idleConnectionTestPeriod = 1
maxConnectionAge = 500

Notes:

  • this shows after waiting more than 15 minutes after deploying the ear on the server and starting random using testing.

  • Hibernate 4.3.1 is used here with c3p0 0.9.2.1 that ships with it. Java EE 6 is used on WAS 6.0 but hibernate (not JPA) api for DB transactions.

  • In the code I use getCurrentSession() and there is only one servlet which at its end I close the session (As I understand this is not needed since I don't use openSession()).

I just look for even hints of what could cause this ? maybe something closing the connection outside of my application scope hand ? any suggestions are more than welcome.

UPDATE:

After some monitoring and checking the logs, here is what I note about C3P0 behavior:

The logs:

[2/12/18 14:28:49:945 EET] 0000009a SystemOut     O 2018-02-12 14:28:49 DEBUG C3P0PooledConnectionPool:452 - Test of PooledConnection [com.mchange.v2.c3p0.impl.NewPooledConnection@d55cf62d] on CHECKIN has SUCCEEDED.
[2/12/18 14:28:50:130 EET] 0000009c SystemOut     O 2018-02-12 14:28:50 INFO  Connection:84 - beginConnection method called
[2/12/18 14:28:50:131 EET] 0000009c SystemOut     O 2018-02-12 14:28:50 DEBUG C3P0PooledConnectionPool:448 - Testing PooledConnection [com.mchange.v2.c3p0.impl.NewPooledConnection@d55cf62d] on CHECKOUT.
[2/12/18 14:28:50:134 EET] 0000009c SystemOut     O 2018-02-12 14:28:50 DEBUG C3P0PooledConnectionPool:452 - Test of PooledConnection [com.mchange.v2.c3p0.impl.NewPooledConnection@d55cf62d] on CHECKOUT has SUCCEEDED.
[2/12/18 14:28:50:135 EET] 0000009c SystemOut     O 2018-02-12 14:28:50 DEBUG BasicResourcePool:1747 - trace com.mchange.v2.resourcepool.BasicResourcePool@926084ea [managed: 2, unused: 1, excluded: 0] (e.g. com.mchange.v2.c3p0.impl.NewPooledConnection@195f9907)
[2/12/18 14:28:50:148 EET] 00000096 SystemOut     O 2018-02-12 14:28:50 INFO  Connection:84 - beginConnection method called
[2/12/18 14:28:50:149 EET] 00000096 SystemOut     O 2018-02-12 14:28:50 DEBUG NewPooledConnection:490 - com.mchange.v2.c3p0.impl.NewPooledConnection@d162951 handling a throwable.
com.microsoft.sqlserver.jdbc.SQLServerException: The connection is closed.
    at com.microsoft.sqlserver.jdbc.SQLServerException.makeFromDriverError(SQLServerException.java:190)
    at com.microsoft.sqlserver.jdbc.SQLServerConnection.checkClosed(SQLServerConnection.java:388)
    at com.microsoft.sqlserver.jdbc.SQLServerConnection.prepareStatement(SQLServerConnection.java:2166)
    at com.microsoft.sqlserver.jdbc.SQLServerConnection.prepareStatement(SQLServerConnection.java:1853)
    at com.mchange.v2.c3p0.impl.NewProxyConnection.prepareStatement(NewProxyConnection.java:162)
    at org.hibernate.engine.jdbc.internal.StatementPreparerImpl$5.doPrepare(StatementPreparerImpl.java:162)
    at org.hibernate.engine.jdbc.internal.StatementPreparerImpl$StatementPreparationTemplate.prepareStatement(StatementPreparerImpl.java:186)
    at org.hibernate.engine.jdbc.internal.StatementPreparerImpl.prepareQueryStatement(StatementPreparerImpl.java:160)
    at org.hibernate.loader.Loader.prepareQueryStatement(Loader.java:1884)
    at org.hibernate.loader.Loader.executeQueryStatement(Loader.java:1861)
    at org.hibernate.loader.Loader.executeQueryStatement(Loader.java:1838)
    at org.hibernate.loader.Loader.doQuery(Loader.java:909)
    at org.hibernate.loader.Loader.doQueryAndInitializeNonLazyCollections(Loader.java:354)
    at org.hibernate.loader.Loader.doList(Loader.java:2551)
    at org.hibernate.loader.Loader.doList(Loader.java:2537)
    at org.hibernate.loader.Loader.listIgnoreQueryCache(Loader.java:2367)
    at org.hibernate.loader.Loader.list(Loader.java:2362)
    at org.hibernate.loader.criteria.CriteriaLoader.list(CriteriaLoader.java:126)
    at org.hibernate.internal.SessionImpl.list(SessionImpl.java:1678)
    at org.hibernate.internal.CriteriaImpl.list(CriteriaImpl.java:380)
    .
    .
    .
    at sun.reflect.GeneratedMethodAccessor101.invoke(Unknown Source)
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:37)
    at java.lang.reflect.Method.invoke(Method.java:611)
    at org.apache.wink.server.internal.handlers.InvokeMethodHandler.handleRequest(InvokeMethodHandler.java:63)
    at org.apache.wink.server.handlers.AbstractHandler.handleRequest(AbstractHandler.java:33)
    at org.apache.wink.server.handlers.RequestHandlersChain.handle(RequestHandlersChain.java:26)
    at org.apache.wink.server.handlers.RequestHandlersChain.handle(RequestHandlersChain.java:22)
    at org.apache.wink.server.handlers.AbstractHandlersChain.doChain(AbstractHandlersChain.java:75)
    at org.apache.wink.server.internal.handlers.CreateInvocationParametersHandler.handleRequest(CreateInvocationParametersHandler.java:54)
    at org.apache.wink.server.handlers.RequestHandlersChain.handle(RequestHandlersChain.java:26)
    at org.apache.wink.server.handlers.RequestHandlersChain.handle(RequestHandlersChain.java:22)
    at org.apache.wink.server.handlers.AbstractHandlersChain.doChain(AbstractHandlersChain.java:75)
    at org.apache.wink.server.internal.handlers.FindResourceMethodHandler.handleSubResourceMethod(FindResourceMethodHandler.java:188)
    at org.apache.wink.server.internal.handlers.FindResourceMethodHandler.handleRequest(FindResourceMethodHandler.java:110)
    at org.apache.wink.server.handlers.RequestHandlersChain.handle(RequestHandlersChain.java:26)
    at org.apache.wink.server.handlers.RequestHandlersChain.handle(RequestHandlersChain.java:22)
    at org.apache.wink.server.handlers.AbstractHandlersChain.doChain(AbstractHandlersChain.java:75)
    at org.apache.wink.server.internal.handlers.FindRootResourceHandler.handleRequest(FindRootResourceHandler.java:95)
    at org.apache.wink.server.handlers.RequestHandlersChain.handle(RequestHandlersChain.java:26)
    at org.apache.wink.server.handlers.RequestHandlersChain.handle(RequestHandlersChain.java:22)
    at org.apache.wink.server.handlers.AbstractHandlersChain.doChain(AbstractHandlersChain.java:75)
    at org.apache.wink.server.internal.handlers.HeadMethodHandler.handleRequest(HeadMethodHandler.java:53)
    at org.apache.wink.server.handlers.RequestHandlersChain.handle(RequestHandlersChain.java:26)
    at org.apache.wink.server.handlers.RequestHandlersChain.handle(RequestHandlersChain.java:22)
    at org.apache.wink.server.handlers.AbstractHandlersChain.doChain(AbstractHandlersChain.java:75)
    at org.apache.wink.server.internal.handlers.OptionsMethodWADLHandler.handleRequest(OptionsMethodWADLHandler.java:51)
    at org.apache.wink.server.handlers.RequestHandlersChain.handle(RequestHandlersChain.java:26)
    at org.apache.wink.server.handlers.RequestHandlersChain.handle(RequestHandlersChain.java:22)
    at org.apache.wink.server.handlers.AbstractHandlersChain.doChain(AbstractHandlersChain.java:75)
    at org.apache.wink.server.internal.handlers.SearchResultHandler.handleRequest(SearchResultHandler.java:33)
    at org.apache.wink.server.handlers.RequestHandlersChain.handle(RequestHandlersChain.java:26)
    at org.apache.wink.server.handlers.RequestHandlersChain.handle(RequestHandlersChain.java:22)
    at org.apache.wink.server.handlers.AbstractHandlersChain.doChain(AbstractHandlersChain.java:75)
    at org.apache.wink.server.internal.log.ResourceInvocation.handleRequest(ResourceInvocation.java:92)
    at org.apache.wink.server.handlers.RequestHandlersChain.handle(RequestHandlersChain.java:26)
    at org.apache.wink.server.handlers.RequestHandlersChain.handle(RequestHandlersChain.java:22)
    at org.apache.wink.server.handlers.AbstractHandlersChain.doChain(AbstractHandlersChain.java:75)
    at org.apache.wink.server.internal.log.Requests.handleRequest(Requests.java:76)
    at org.apache.wink.server.handlers.RequestHandlersChain.handle(RequestHandlersChain.java:26)
    at org.apache.wink.server.handlers.RequestHandlersChain.handle(RequestHandlersChain.java:22)
    at org.apache.wink.server.handlers.AbstractHandlersChain.doChain(AbstractHandlersChain.java:75)
    at org.apache.wink.server.handlers.AbstractHandlersChain.run(AbstractHandlersChain.java:60)
    at org.apache.wink.server.internal.RequestProcessor.handleRequestWithoutFaultBarrier(RequestProcessor.java:207)
    at org.apache.wink.server.internal.RequestProcessor.handleRequest(RequestProcessor.java:154)
    at org.apache.wink.server.internal.servlet.RestServlet.service(RestServlet.java:124)
    at javax.servlet.http.HttpServlet.service(HttpServlet.java:668)
    at com.ibm.ws.webcontainer.servlet.ServletWrapper.service(ServletWrapper.java:1232)
    at com.ibm.ws.webcontainer.servlet.ServletWrapper.handleRequest(ServletWrapper.java:781)
    at com.ibm.ws.webcontainer.servlet.ServletWrapper.handleRequest(ServletWrapper.java:480)
    at com.ibm.ws.webcontainer.servlet.ServletWrapperImpl.handleRequest(ServletWrapperImpl.java:178)
    at com.ibm.ws.webcontainer.filter.WebAppFilterManager.invokeFilters(WebAppFilterManager.java:1114)
    at com.ibm.ws.webcontainer.servlet.CacheServletWrapper.handleRequest(CacheServletWrapper.java:87)
    at com.ibm.ws.webcontainer.WebContainer.handleRequest(WebContainer.java:940)
    at com.ibm.ws.webcontainer.WSWebContainer.handleRequest(WSWebContainer.java:1817)
    at com.ibm.ws.webcontainer.channel.WCChannelLink.ready(WCChannelLink.java:200)
    at com.ibm.ws.http.channel.inbound.impl.HttpInboundLink.handleDiscrimination(HttpInboundLink.java:463)
    at com.ibm.ws.http.channel.inbound.impl.HttpInboundLink.handleNewRequest(HttpInboundLink.java:530)
    at com.ibm.ws.http.channel.inbound.impl.HttpInboundLink.processRequest(HttpInboundLink.java:316)
    at com.ibm.ws.http.channel.inbound.impl.HttpICLReadCallback.complete(HttpICLReadCallback.java:88)
    at com.ibm.ws.ssl.channel.impl.SSLReadServiceContext$SSLReadCompletedCallback.complete(SSLReadServiceContext.java:1818)
    at com.ibm.ws.tcp.channel.impl.AioReadCompletionListener.futureCompleted(AioReadCompletionListener.java:175)
    at com.ibm.io.async.AbstractAsyncFuture.invokeCallback(AbstractAsyncFuture.java:217)
    at com.ibm.io.async.AsyncChannelFuture.fireCompletionActions(AsyncChannelFuture.java:161)
    at com.ibm.io.async.AsyncFuture.completed(AsyncFuture.java:138)
    at com.ibm.io.async.ResultHandler.complete(ResultHandler.java:204)
    at com.ibm.io.async.ResultHandler.runEventProcessingLoop(ResultHandler.java:775)
    at com.ibm.io.async.ResultHandler$2.run(ResultHandler.java:905)
    at com.ibm.ws.util.ThreadPool$Worker.run(ThreadPool.java:1881)
[2/12/18 14:28:50:149 EET] 00000096 SystemOut     O 2018-02-12 14:28:50 DEBUG SqlUtils:97 - Attempted to convert SQLException to SQLException. Leaving it alone. [SQLState: null; errorCode: 0]
com.microsoft.sqlserver.jdbc.SQLServerException: The connection is closed.
    at com.microsoft.sqlserver.jdbc.SQLServerException.makeFromDriverError(SQLServerException.java:190)
    .
    .
    same above
[2/12/18 14:28:50:150 EET] 00000096 SystemOut     O 2018-02-12 14:28:50 DEBUG DefaultConnectionTester:138 - Testing a Connection in response to an Exception:
com.microsoft.sqlserver.jdbc.SQLServerException: The connection is closed.
    at com.microsoft.sqlserver.jdbc.SQLServerException.makeFromDriverError(SQLServerException.java:190)
    .
    .
    same above
[2/12/18 14:28:50:151 EET] 00000096 SystemOut     O 2018-02-12 14:28:50 DEBUG DefaultConnectionTester:92 - Connection ConnectionID:33 ClientConnectionId: 751fc09e-1fbd-42fe-9368-b7706a48800a failed Connection test with an Exception! [query=SELECT 1;]
com.microsoft.sqlserver.jdbc.SQLServerException: The connection is closed.
    at com.microsoft.sqlserver.jdbc.SQLServerException.makeFromDriverError(SQLServerException.java:190)
    .
    .
    same above
[2/12/18 14:28:50:151 EET] 0000009c SystemOut     O 2018-02-12 14:28:50 INFO  Connection:114 - commit method called
[2/12/18 14:28:50:151 EET] 00000096 SystemOut     O 2018-02-12 14:28:50 DEBUG NewPooledConnection:509 - com.mchange.v2.c3p0.impl.NewPooledConnection@d162951 invalidated by Exception.
com.microsoft.sqlserver.jdbc.SQLServerException: The connection is closed.
    at com.microsoft.sqlserver.jdbc.SQLServerException.makeFromDriverError(SQLServerException.java:190)
    .
    .
    same above
[2/12/18 14:28:50:158 EET] 00000096 SystemOut     O 2018-02-12 14:28:50 DEBUG C3P0PooledConnectionPool:941 - CONNECTION ERROR OCCURRED!
[2/12/18 14:28:50:159 EET] 00000096 SystemOut     O 2018-02-12 14:28:50 DEBUG BasicResourcePool:780 - Resource com.mchange.v2.c3p0.impl.NewPooledConnection@d162951 marked broken by pool (com.mchange.v2.resourcepool.BasicResourcePool@926084ea).
[2/12/18 14:28:50:159 EET] 00000096 SystemOut     O 2018-02-12 14:28:50 DEBUG BasicResourcePool:1526 - Excluded resource com.mchange.v2.c3p0.impl.NewPooledConnection@d162951
java.lang.Exception: DEBUG STACK TRACE: Excluded resource stack trace
    at com.mchange.v2.resourcepool.BasicResourcePool.excludeResource(BasicResourcePool.java:1526)
    at com.mchange.v2.resourcepool.BasicResourcePool._markBroken(BasicResourcePool.java:1219)
    at com.mchange.v2.resourcepool.BasicResourcePool.markBroken(BasicResourcePool.java:782)
    at com.mchange.v2.c3p0.impl.C3P0PooledConnectionPool$ConnectionEventListenerImpl.doMarkPoolStatus(C3P0PooledConnectionPool.java:977)
    at com.mchange.v2.c3p0.impl.C3P0PooledConnectionPool$ConnectionEventListenerImpl.connectionErrorOccurred(C3P0PooledConnectionPool.java:964)
    at com.mchange.v2.c3p0.util.ConnectionEventSupport.fireConnectionErrorOccurred(ConnectionEventSupport.java:88)
    at com.mchange.v2.c3p0.impl.NewPooledConnection.fireConnectionErrorOccurred(NewPooledConnection.java:577)
    at com.mchange.v2.c3p0.impl.NewPooledConnection.handleThrowable(NewPooledConnection.java:557)
    at com.mchange.v2.c3p0.impl.NewProxyConnection.prepareStatement(NewProxyConnection.java:179)
    at org.hibernate.engine.jdbc.internal.StatementPreparerImpl$5.doPrepare(StatementPreparerImpl.java:162)
    at org.hibernate.engine.jdbc.internal.StatementPreparerImpl$StatementPreparationTemplate.prepareStatement(StatementPreparerImpl.java:186)
    at org.hibernate.engine.jdbc.internal.StatementPreparerImpl.prepareQueryStatement(StatementPreparerImpl.java:160)
    at org.hibernate.loader.Loader.prepareQueryStatement(Loader.java:1884)
    at org.hibernate.loader.Loader.executeQueryStatement(Loader.java:1861)
    at org.hibernate.loader.Loader.executeQueryStatement(Loader.java:1838)
    at org.hibernate.loader.Loader.doQuery(Loader.java:909)
    at org.hibernate.loader.Loader.doQueryAndInitializeNonLazyCollections(Loader.java:354)
    at org.hibernate.loader.Loader.doList(Loader.java:2551)
    at org.hibernate.loader.Loader.doList(Loader.java:2537)
    at org.hibernate.loader.Loader.listIgnoreQueryCache(Loader.java:2367)
    at org.hibernate.loader.Loader.list(Loader.java:2362)
    at org.hibernate.loader.criteria.CriteriaLoader.list(CriteriaLoader.java:126)
    at org.hibernate.internal.SessionImpl.list(SessionImpl.java:1678)
    at org.hibernate.internal.CriteriaImpl.list(CriteriaImpl.java:380)
    .
    .
    .
    at sun.reflect.GeneratedMethodAccessor101.invoke(Unknown Source)
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:37)
    at java.lang.reflect.Method.invoke(Method.java:611)
    at org.apache.wink.server.internal.handlers.InvokeMethodHandler.handleRequest(InvokeMethodHandler.java:63)
    at org.apache.wink.server.handlers.AbstractHandler.handleRequest(AbstractHandler.java:33)
    at org.apache.wink.server.handlers.RequestHandlersChain.handle(RequestHandlersChain.java:26)
    at org.apache.wink.server.handlers.RequestHandlersChain.handle(RequestHandlersChain.java:22)
    at org.apache.wink.server.handlers.AbstractHandlersChain.doChain(AbstractHandlersChain.java:75)
    at org.apache.wink.server.internal.handlers.CreateInvocationParametersHandler.handleRequest(CreateInvocationParametersHandler.java:54)
    at org.apache.wink.server.handlers.RequestHandlersChain.handle(RequestHandlersChain.java:26)
    at org.apache.wink.server.handlers.RequestHandlersChain.handle(RequestHandlersChain.java:22)
    at org.apache.wink.server.handlers.AbstractHandlersChain.doChain(AbstractHandlersChain.java:75)
    at org.apache.wink.server.internal.handlers.FindResourceMethodHandler.handleSubResourceMethod(FindResourceMethodHandler.java:188)
    at org.apache.wink.server.internal.handlers.FindResourceMethodHandler.handleRequest(FindResourceMethodHandler.java:110)
    at org.apache.wink.server.handlers.RequestHandlersChain.handle(RequestHandlersChain.java:26)
    at org.apache.wink.server.handlers.RequestHandlersChain.handle(RequestHandlersChain.java:22)
    at org.apache.wink.server.handlers.AbstractHandlersChain.doChain(AbstractHandlersChain.java:75)
    at org.apache.wink.server.internal.handlers.FindRootResourceHandler.handleRequest(FindRootResourceHandler.java:95)
    at org.apache.wink.server.handlers.RequestHandlersChain.handle(RequestHandlersChain.java:26)
    at org.apache.wink.server.handlers.RequestHandlersChain.handle(RequestHandlersChain.java:22)
    at org.apache.wink.server.handlers.AbstractHandlersChain.doChain(AbstractHandlersChain.java:75)
    at org.apache.wink.server.internal.handlers.HeadMethodHandler.handleRequest(HeadMethodHandler.java:53)
    at org.apache.wink.server.handlers.RequestHandlersChain.handle(RequestHandlersChain.java:26)
    at org.apache.wink.server.handlers.RequestHandlersChain.handle(RequestHandlersChain.java:22)
    at org.apache.wink.server.handlers.AbstractHandlersChain.doChain(AbstractHandlersChain.java:75)
    at org.apache.wink.server.internal.handlers.OptionsMethodWADLHandler.handleRequest(OptionsMethodWADLHandler.java:51)
    at org.apache.wink.server.handlers.RequestHandlersChain.handle(RequestHandlersChain.java:26)
    .
    .
    .
    at javax.servlet.http.HttpServlet.service(HttpServlet.java:668)
    at com.ibm.ws.webcontainer.servlet.ServletWrapper.service(ServletWrapper.java:1232)
    at com.ibm.ws.webcontainer.servlet.ServletWrapper.handleRequest(ServletWrapper.java:781)
    at com.ibm.ws.webcontainer.servlet.ServletWrapper.handleRequest(ServletWrapper.java:480)
    at com.ibm.ws.webcontainer.servlet.ServletWrapperImpl.handleRequest(ServletWrapperImpl.java:178)
    at com.ibm.ws.webcontainer.filter.WebAppFilterManager.invokeFilters(WebAppFilterManager.java:1114)
    at com.ibm.ws.webcontainer.servlet.CacheServletWrapper.handleRequest(CacheServletWrapper.java:87)
    at com.ibm.ws.webcontainer.WebContainer.handleRequest(WebContainer.java:940)
    at com.ibm.ws.webcontainer.WSWebContainer.handleRequest(WSWebContainer.java:1817)
    at com.ibm.ws.webcontainer.channel.WCChannelLink.ready(WCChannelLink.java:200)
    at com.ibm.ws.http.channel.inbound.impl.HttpInboundLink.handleDiscrimination(HttpInboundLink.java:463)
    at com.ibm.ws.http.channel.inbound.impl.HttpInboundLink.handleNewRequest(HttpInboundLink.java:530)
    at com.ibm.ws.http.channel.inbound.impl.HttpInboundLink.processRequest(HttpInboundLink.java:316)
    at com.ibm.ws.http.channel.inbound.impl.HttpICLReadCallback.complete(HttpICLReadCallback.java:88)
    at com.ibm.ws.ssl.channel.impl.SSLReadServiceContext$SSLReadCompletedCallback.complete(SSLReadServiceContext.java:1818)
    at com.ibm.ws.tcp.channel.impl.AioReadCompletionListener.futureCompleted(AioReadCompletionListener.java:175)
    at com.ibm.io.async.AbstractAsyncFuture.invokeCallback(AbstractAsyncFuture.java:217)
    at com.ibm.io.async.AsyncChannelFuture.fireCompletionActions(AsyncChannelFuture.java:161)
    at com.ibm.io.async.AsyncFuture.completed(AsyncFuture.java:138)
    at com.ibm.io.async.ResultHandler.complete(ResultHandler.java:204)
    at com.ibm.io.async.ResultHandler.runEventProcessingLoop(ResultHandler.java:775)
    at com.ibm.io.async.ResultHandler$2.run(ResultHandler.java:905)
    at com.ibm.ws.util.ThreadPool$Worker.run(ThreadPool.java:1881)
[2/12/18 14:28:50:161 EET] 00000096 SystemOut     O 2018-02-12 14:28:50 ERROR TransactionRestService:85 - could not prepare statement
com.microsoft.sqlserver.jdbc.SQLServerException: The connection is closed.
    at com.microsoft.sqlserver.jdbc.SQLServerException.makeFromDriverError(SQLServerException.java:190)
    .
    .
    same above
[2/12/18 14:28:50:162 EET] 00000098 SystemOut     O 2018-02-12 14:28:50 DEBUG BasicResourcePool:2114 - Refurbishing idle resources - Mon Feb 12 14:28:50 EET 2018 [com.mchange.v2.resourcepool.BasicResourcePool@926084ea]
[2/12/18 14:28:50:162 EET] 00000098 SystemOut     O 2018-02-12 14:28:50 DEBUG ThreadPoolAsynchronousRunner:236 - com.mchange.v2.async.ThreadPoolAsynchronousRunner@4fc3c56c: Adding task to queue -- com.mchange.v2.resourcepool.BasicResourcePool$AsyncTestIdleResourceTask@aa7c1b2
[2/12/18 14:28:50:162 EET] 00000098 SystemOut     O 2018-02-12 14:28:50 DEBUG BasicResourcePool:1747 - trace com.mchange.v2.resourcepool.BasicResourcePool@926084ea [managed: 2, unused: 1, excluded: 1] (e.g. com.mchange.v2.c3p0.impl.NewPooledConnection@195f9907)
[2/12/18 14:28:50:162 EET] 00000099 SystemOut     O 2018-02-12 14:28:50 DEBUG C3P0PooledConnectionPool:448 - Testing PooledConnection [com.mchange.v2.c3p0.impl.NewPooledConnection@8da52587] on IDLE CHECK.
[2/12/18 14:28:50:162 EET] 0000009c SystemOut     O 2018-02-12 14:28:50 DEBUG ThreadPoolAsynchronousRunner:236 - com.mchange.v2.async.ThreadPoolAsynchronousRunner@4fc3c56c: Adding task to queue -- com.mchange.v2.resourcepool.BasicResourcePool$1RefurbishCheckinResourceTask@d092ae04
[2/12/18 14:28:50:163 EET] 0000009c SystemOut     O 2018-02-12 14:28:50 DEBUG BasicResourcePool:1747 - trace com.mchange.v2.resourcepool.BasicResourcePool@926084ea [managed: 2, unused: 1, excluded: 1] (e.g. com.mchange.v2.c3p0.impl.NewPooledConnection@195f9907)
[2/12/18 14:28:50:163 EET] 0000009c SystemOut     O 2018-02-12 14:28:50 INFO  Connection:84 - beginConnection method called
[2/12/18 14:28:50:163 EET] 0000009b SystemOut     O 2018-02-12 14:28:50 DEBUG C3P0PooledConnectionPool:448 - Testing PooledConnection [com.mchange.v2.c3p0.impl.NewPooledConnection@d55cf62d] on CHECKIN.
[2/12/18 14:28:50:164 EET] 0000009c SystemOut     O 2018-02-12 14:28:50 DEBUG BasicResourcePool:616 - Resource we want to check out is in idleCheck! (waiting until idle-check completes.) [com.mchange.v2.resourcepool.BasicResourcePool@926084ea]
[2/12/18 14:28:50:166 EET] 00000099 SystemOut     O 2018-02-12 14:28:50 DEBUG C3P0PooledConnectionPool:452 - Test of PooledConnection [com.mchange.v2.c3p0.impl.NewPooledConnection@8da52587] on IDLE CHECK has SUCCEEDED.
[2/12/18 14:28:50:166 EET] 0000009c SystemOut     O 2018-02-12 14:28:50 DEBUG C3P0PooledConnectionPool:448 - Testing PooledConnection [com.mchange.v2.c3p0.impl.NewPooledConnection@8da52587] on CHECKOUT.
[2/12/18 14:28:50:166 EET] 0000009b SystemOut     O 2018-02-12 14:28:50 DEBUG C3P0PooledConnectionPool:452 - Test of PooledConnection [com.mchange.v2.c3p0.impl.NewPooledConnection@d55cf62d] on CHECKIN has SUCCEEDED.
[2/12/18 14:28:50:171 EET] 0000009c SystemOut     O 2018-02-12 14:28:50 DEBUG C3P0PooledConnectionPool:452 - Test of PooledConnection [com.mchange.v2.c3p0.impl.NewPooledConnection@8da52587] on CHECKOUT has SUCCEEDED.
[2/12/18 14:28:50:171 EET] 0000009c SystemOut     O 2018-02-12 14:28:50 DEBUG BasicResourcePool:1747 - trace com.mchange.v2.resourcepool.BasicResourcePool@926084ea [managed: 2, unused: 1, excluded: 1] (e.g. com.mchange.v2.c3p0.impl.NewPooledConnection@195f9907)
[2/12/18 14:28:50:177 EET] 0000009c SystemOut     O 2018-02-12 14:28:50 INFO  ServiceTransactionLogger:305 - validateTransactionLogEntity.getId : 927951
[2/12/18 14:28:50:178 EET] 0000009c SystemOut     O 2018-02-12 14:28:50 INFO  Connection:84 - beginConnection method called
[2/12/18 14:28:50:178 EET] 0000009c SystemOut     O 2018-02-12 14:28:50 INFO  Connection:84 - beginConnection method called
[2/12/18 14:28:50:194 EET] 0000009c SystemOut     O 2018-02-12 14:28:50 INFO  Connection:114 - commit method called
[2/12/18 14:28:50:198 EET] 0000009c SystemOut     O 2018-02-12 14:28:50 DEBUG SqlUtils:111 - Converting Throwable to SQLException...
java.lang.NullPointerException
    at com.mchange.v2.c3p0.impl.NewProxyPreparedStatement.maybeDirtyTransaction(NewProxyPreparedStatement.java:2520)
    at com.mchange.v2.c3p0.impl.NewProxyPreparedStatement.getMaxRows(NewProxyPreparedStatement.java:1403)
    at org.hibernate.engine.jdbc.internal.JdbcCoordinatorImpl.close(JdbcCoordinatorImpl.java:530)
    at org.hibernate.engine.jdbc.internal.JdbcCoordinatorImpl.release(JdbcCoordinatorImpl.java:407)
    at org.hibernate.engine.jdbc.batch.internal.AbstractBatchImpl.releaseStatements(AbstractBatchImpl.java:173)
    at org.hibernate.engine.jdbc.batch.internal.NonBatchingBatch.addToBatch(NonBatchingBatch.java:76)
    at org.hibernate.persister.entity.AbstractEntityPersister.update(AbstractEntityPersister.java:3281)
    at org.hibernate.persister.entity.AbstractEntityPersister.updateOrInsert(AbstractEntityPersister.java:3183)
    at org.hibernate.persister.entity.AbstractEntityPersister.update(AbstractEntityPersister.java:3525)
    at org.hibernate.action.internal.EntityUpdateAction.execute(EntityUpdateAction.java:158)
    at org.hibernate.engine.spi.ActionQueue.executeActions(ActionQueue.java:453)
    at org.hibernate.engine.spi.ActionQueue.executeActions(ActionQueue.java:345)
    at org.hibernate.event.internal.AbstractFlushingEventListener.performExecutions(AbstractFlushingEventListener.java:350)
    at org.hibernate.event.internal.DefaultFlushEventListener.onFlush(DefaultFlushEventListener.java:56)
    at org.hibernate.internal.SessionImpl.flush(SessionImpl.java:1218)
    .
    .
    .
[2/12/18 14:28:50:201 EET] 0000009c SystemOut     O 2018-02-12 14:28:50 DEBUG ThreadPoolAsynchronousRunner:236 - com.mchange.v2.async.ThreadPoolAsynchronousRunner@4fc3c56c: Adding task to queue -- com.mchange.v2.resourcepool.BasicResourcePool$1RefurbishCheckinResourceTask@b8c426fb
[2/12/18 14:28:50:202 EET] 0000009c SystemOut     O 2018-02-12 14:28:50 DEBUG BasicResourcePool:1747 - trace com.mchange.v2.resourcepool.BasicResourcePool@926084ea [managed: 2, unused: 1, excluded: 1] (e.g. com.mchange.v2.c3p0.impl.NewPooledConnection@195f9907)
[2/12/18 14:28:50:202 EET] 0000009c SystemOut     O 2018-02-12 14:28:50 INFO  Connection:84 - beginConnection method called
[2/12/18 14:28:50:202 EET] 0000009a SystemOut     O 2018-02-12 14:28:50 DEBUG C3P0PooledConnectionPool:448 - Testing PooledConnection [com.mchange.v2.c3p0.impl.NewPooledConnection@8da52587] on CHECKIN.
[2/12/18 14:28:50:202 EET] 0000009c SystemOut     O 2018-02-12 14:28:50 DEBUG C3P0PooledConnectionPool:448 - Testing PooledConnection [com.mchange.v2.c3p0.impl.NewPooledConnection@d55cf62d] on CHECKOUT.
[2/12/18 14:28:50:203 EET] 0000009a SystemOut     O 2018-02-12 14:28:50 DEBUG C3P0PooledConnectionPool:452 - Test of PooledConnection [com.mchange.v2.c3p0.impl.NewPooledConnection@8da52587] on CHECKIN has SUCCEEDED.
[2/12/18 14:28:50:206 EET] 0000009c SystemOut     O 2018-02-12 14:28:50 DEBUG C3P0PooledConnectionPool:452 - Test of PooledConnection [com.mchange.v2.c3p0.impl.NewPooledConnection@d55cf62d] on CHECKOUT has SUCCEEDED.
[2/12/18 14:28:50:206 EET] 0000009c SystemOut     O 2018-02-12 14:28:50 DEBUG BasicResourcePool:1747 - trace com.mchange.v2.resourcepool.BasicResourcePool@926084ea [managed: 2, unused: 1, excluded: 1] (e.g. com.mchange.v2.c3p0.impl.NewPooledConnection@195f9907)
Anddo
  • 2,144
  • 1
  • 14
  • 33
  • Why are you adding c3po when WAS comes with excellent connection management built in to it? See https://stackoverflow.com/questions/4406935/how-can-i-set-datasource-when-im-creating-hibernate-sessionfactory – Steve C Feb 08 '18 at 13:37
  • That's good question and I was wondering the same but here are the reasons. 1. because there was another project that was using default hibernate pooling and after moving to c3p0 they noticed high stability so c3p0 got a rep. 2. Due to first reason, it was out of my hands decision :(. – Anddo Feb 08 '18 at 22:43

1 Answers1

2

Probably Connections are being close()ed due to unreturnedConnectionTimeout. Try disabling that setting.

If you find with the setting removed, you experience pool exhaustion due to a Connection leak, set debugUnreturnedConnectionStackTraces to true in order to understand and fix the Connection leak.

If you can't do that, make unreturnedConnectionTimeout longer, to diminish the likelihood of cleaning Connections up while the application may still intend to use them.

But it's much better to fix the Connection leak, then turn unreturnedConnectionTimeout off entirely.

Steve Waldman
  • 13,689
  • 1
  • 35
  • 45
  • OK good suggestion. The problem found to be related to servers hosting the application. There is a problem of resources utilization leading to close connections bettween my web application and its sql server database in favor of another web app that consumes more resources. So using current settings before, there were no problems but now resources are almost all consumed. **Is there any way to enforce holding connections by the pool and preventing any destruction of these connections ?**. I will try your suggestion but as these new discoveries, I expect to stay the same. – Anddo Feb 10 '18 at 12:27
  • It's not connection leak. I tried and monitored connections from sql management tool. Sadly I'm getting frustrated with this. – Anddo Feb 12 '18 at 08:17
  • Updated after some investigation. Thank you for your suggestions and feel free to shoot more. – Anddo Feb 12 '18 at 19:38
  • The Connection is getting closed beneath your application. The only way c3p0 would do this is `unreturnedConnectionTimeout`. You should definitely remove that setting (or set it to `0`, which means disabled), and see if the behavior changes. If it does not, the issue is likely on the server side or with the network between your application and the server. – Steve Waldman Feb 13 '18 at 22:28
  • According to IBM (for Websphere AS) response, firewall or network might be the root cause of that issue. I was hoping that c3p0 would drop the connections from the pool after marked broken, not leaving it in the excluded list though. Even hibernate native pooling doesn't do that. – Anddo Feb 14 '18 at 07:04
  • Excluded Connections are dropped from the pool as soon as they are checked back in. That's what excluded means. They are never recycled or reused. They are remembered until they are checked-in only so that the pool doesn't throw an Exception, as it would if a client tried to check-in a Connection that had never been checked out of the pool. – Steve Waldman Feb 15 '18 at 07:24
  • The key words are **"they are checked back in"**. We don't close (release to pool) the connection in the code, we barely close sessions and transactions and depending on the pool to handle any other process. About "**They are never recycled or reused**", I suspect it maybe a bug or something I don't understand but the connection actually being used in the app (which leads to "The connection is closed" exception) whenever servlet is loaded so that leads me to thinking the connection is closed and still with the app and in the excluded list and will never checked in !!!!!!!!! – Anddo Feb 15 '18 at 07:33
  • 1
    If you are not checking Connections back in after use, you are getting no benefit from using a Connection pool. If you continually check out Connections but do not check them back in, that’s a Connection leak. If you are checking out one or some small number if Connections and holding them open indefinitely, that is precisely the architecture Connection pools were invented to supercede. Nothing can “fix” a broken Connection that you are just holding out and onto. You should be checking out Connections “just in time”, then checking them back in immediately after use. – Steve Waldman Feb 15 '18 at 07:39
  • OK that would be not easy to do but one last question, any idea how to close the connection to release it to the pool ? Can't find an indicator via SessionFactory or something !!. Finally, thank you very much, you have been most helpful and informative. – Anddo Feb 15 '18 at 11:18
  • Sorry! I missed this question. I think hibernate wraps Connections in Sessions. Close the Session promptly after use (but NOT the SessionFactory, which wraps the Connection pool and should survive for the lifetime of the application). – Steve Waldman Feb 18 '18 at 07:25
  • No problem. That's what I'm already doing. Although I'm using getCurrentSession() (instead of openSession()) which should close on its own (https://stackoverflow.com/questions/8046662/hibernate-opensession-vs-getcurrentsession) but I do close the session in one place in the app though and seems I miss exception handling to close it though. Thank you again. – Anddo Feb 18 '18 at 09:15