search

kitodo / kitodo-production

Kitodo.Production is a workflow management tool for mass digitization and is part of the Kitodo Digital Library Suite.
http://www.kitodo.org/software/kitodoproduction/
GNU General Public License v3.0
60 stars 64 forks source link

Hibernate connections not returned to the connection pool #296

Open matthias-ronge opened 9 years ago

matthias-ronge commented 9 years ago

There is a hibernate connection leak in Goobi Production, 1.10.2. Adding the following configuration options in c3p0.properties kills the lost connections after running idle for (in this example) 32,768 secs (> 9 hrs) and logs a stack trace back to the point where the connection was initially acquired:

c3p0.debugUnreturnedConnectionStackTraces=true
c3p0.unreturnedConnectionTimeout=32768

This is one of the debug stack traces which essentially says that the connection is acquired somewhere down in a library call which is triggered from BaseDAO.java in line 152:

java.lang.Exception: DEBUG ONLY: Overdue resource check-out stack trace.
        at com.mchange.v2.resourcepool.BasicResourcePool.checkoutResource(BasicResourcePool.java:506)
        at com.mchange.v2.c3p0.impl.C3P0PooledConnectionPool.checkoutPooledConnection(C3P0PooledConnectionPool.java:525)
        at com.mchange.v2.c3p0.impl.AbstractPoolBackedDataSource.getConnection(AbstractPoolBackedDataSource.java:128)
        at org.hibernate.service.jdbc.connections.internal.C3P0ConnectionProvider.getConnection(C3P0ConnectionProvider.java:84)
        at org.hibernate.internal.AbstractSessionImpl$NonContextualJdbcConnectionAccess.obtainConnection(AbstractSessionImpl.java:278)
        at org.hibernate.engine.jdbc.internal.LogicalConnectionImpl.obtainConnection(LogicalConnectionImpl.java:297)
        at org.hibernate.engine.jdbc.internal.LogicalConnectionImpl.getConnection(LogicalConnectionImpl.java:169)
        at org.hibernate.engine.jdbc.internal.proxy.ConnectionProxyHandler.extractPhysicalConnection(ConnectionProxyHandler.java:82)
        at org.hibernate.engine.jdbc.internal.proxy.ConnectionProxyHandler.continueInvocation(ConnectionProxyHandler.java:138)
        at org.hibernate.engine.jdbc.internal.proxy.AbstractProxyHandler.invoke(AbstractProxyHandler.java:81)
        at $Proxy50.prepareStatement(Unknown Source)
        at org.hibernate.engine.jdbc.internal.StatementPreparerImpl$5.doPrepare(StatementPreparerImpl.java:147)
        at org.hibernate.engine.jdbc.internal.StatementPreparerImpl$StatementPreparationTemplate.prepareStatement(StatementPreparerImpl.java:166)
        at org.hibernate.engine.jdbc.internal.StatementPreparerImpl.prepareQueryStatement(StatementPreparerImpl.java:145)
        at org.hibernate.loader.Loader.prepareQueryStatement(Loader.java:1711)
        at org.hibernate.loader.Loader.doQuery(Loader.java:828)
        at org.hibernate.loader.Loader.doQueryAndInitializeNonLazyCollections(Loader.java:289)
        at org.hibernate.loader.Loader.doList(Loader.java:2438)
        at org.hibernate.loader.Loader.doList(Loader.java:2424)
        at org.hibernate.loader.Loader.listIgnoreQueryCache(Loader.java:2254)
        at org.hibernate.loader.Loader.list(Loader.java:2249)
        at org.hibernate.loader.hql.QueryLoader.list(QueryLoader.java:470)
        at org.hibernate.hql.internal.ast.QueryTranslatorImpl.list(QueryTranslatorImpl.java:355)
        at org.hibernate.engine.query.spi.HQLQueryPlan.performList(HQLQueryPlan.java:195)
        at org.hibernate.internal.SessionImpl.list(SessionImpl.java:1248)
        at org.hibernate.internal.QueryImpl.list(QueryImpl.java:101)
        at org.hibernate.internal.AbstractQueryImpl.uniqueResult(AbstractQueryImpl.java:890)
        at de.sub.goobi.persistence.BaseDAO.retrieveAnzahl(Unknown Source)
        at de.sub.goobi.persistence.BenutzerDAO.count(Unknown Source)
        at de.sub.goobi.forms.StatistikForm.getAnzahlBenutzer(Unknown Source)
        at sun.reflect.GeneratedMethodAccessor67934.invoke(Unknown Source)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source)
        at java.lang.reflect.Method.invoke(Unknown Source)
        at org.apache.myfaces.el.PropertyResolverImpl.getProperty(PropertyResolverImpl.java:457)
        at org.apache.myfaces.el.PropertyResolverImpl.getValue(PropertyResolverImpl.java:85)
        at org.apache.myfaces.custom.security.SecurityContextPropertyResolver.getValue(SecurityContextPropertyResolver.java:101)
        at org.apache.myfaces.el.ELParserHelper$MyPropertySuffix.evaluate(ELParserHelper.java:535)
        at org.apache.commons.el.ComplexValue.evaluate(ComplexValue.java:145)
        at org.apache.myfaces.el.ValueBindingImpl.getValue(ValueBindingImpl.java:386)
        at javax.faces.component.UIOutput.getValue(UIOutput.java:80)
        at org.apache.myfaces.shared_impl.renderkit.RendererUtils.getStringValue(RendererUtils.java:223)
        at org.apache.myfaces.shared_impl.renderkit.html.HtmlTextRendererBase.renderOutput(HtmlTextRendererBase.java:69)
        at org.apache.myfaces.shared_impl.renderkit.html.HtmlTextRendererBase.encodeEnd(HtmlTextRendererBase.java:57)
        at javax.faces.component.UIComponentBase.encodeEnd(UIComponentBase.java:539)
        at org.apache.myfaces.shared_impl.renderkit.RendererUtils.renderChild(RendererUtils.java:419)
        at org.apache.myfaces.shared_impl.renderkit.html.HtmlGridRendererBase.renderChildren(HtmlGridRendererBase.java:229)
        at org.apache.myfaces.shared_impl.renderkit.html.HtmlGridRendererBase.encodeEnd(HtmlGridRendererBase.java:101)
        at javax.faces.component.UIComponentBase.encodeEnd(UIComponentBase.java:539)
        at org.apache.myfaces.shared_impl.renderkit.RendererUtils.renderChild(RendererUtils.java:419)
        at org.apache.myfaces.shared_impl.renderkit.RendererUtils.renderChildren(RendererUtils.java:400)
        at org.apache.myfaces.shared_impl.renderkit.RendererUtils.renderChild(RendererUtils.java:417)
        at org.apache.myfaces.shared_impl.renderkit.RendererUtils.renderChildren(RendererUtils.java:400)
        at org.apache.myfaces.shared_impl.renderkit.RendererUtils.renderChild(RendererUtils.java:417)
        at org.apache.myfaces.shared_impl.renderkit.RendererUtils.renderChildren(RendererUtils.java:400)
        at org.apache.myfaces.shared_impl.renderkit.RendererUtils.renderChild(RendererUtils.java:417)
        at org.apache.myfaces.shared_impl.renderkit.html.HtmlGridRendererBase.renderChildren(HtmlGridRendererBase.java:229)
        at org.apache.myfaces.shared_impl.renderkit.html.HtmlGridRendererBase.encodeEnd(HtmlGridRendererBase.java:101)
        at javax.faces.component.UIComponentBase.encodeEnd(UIComponentBase.java:539)
        at org.apache.myfaces.shared_impl.renderkit.RendererUtils.renderChild(RendererUtils.java:419)
        at org.apache.myfaces.shared_impl.renderkit.html.HtmlGridRendererBase.renderChildren(HtmlGridRendererBase.java:229)
        at org.apache.myfaces.shared_impl.renderkit.html.HtmlGridRendererBase.encodeEnd(HtmlGridRendererBase.java:101)
        at javax.faces.component.UIComponentBase.encodeEnd(UIComponentBase.java:539)
        at javax.faces.webapp.UIComponentTag.encodeEnd(UIComponentTag.java:498)
        at javax.faces.webapp.UIComponentTag.doEndTag(UIComponentTag.java:366)
        at org.apache.myfaces.shared_impl.taglib.UIComponentBodyTagBase.doEndTag(UIComponentBodyTagBase.java:57)
        at org.apache.jsp.newpages.Main_jsp._jspx_meth_h_005fpanelGrid_005f6(Main_jsp.java:6965)
        at org.apache.jsp.newpages.Main_jsp._jspx_meth_h_005fform_005f3(Main_jsp.java:6781)
        at org.apache.jsp.newpages.Main_jsp._jspx_meth_htm_005ftd_005f9(Main_jsp.java:6738)
        at org.apache.jsp.newpages.Main_jsp._jspx_meth_htm_005ftr_005f3(Main_jsp.java:1841)
        at org.apache.jsp.newpages.Main_jsp._jspx_meth_htm_005ftable_005f2(Main_jsp.java:1793)
        at org.apache.jsp.newpages.Main_jsp._jspx_meth_f_005fview_005f0(Main_jsp.java:423)
        at org.apache.jsp.newpages.Main_jsp._jspService(Main_jsp.java:317)
        at org.apache.jasper.runtime.HttpJspBase.service(HttpJspBase.java:70)
        at javax.servlet.http.HttpServlet.service(HttpServlet.java:717)
        at org.apache.jasper.servlet.JspServletWrapper.service(JspServletWrapper.java:388)
        at org.apache.jasper.servlet.JspServlet.serviceJspFile(JspServlet.java:313)
        at org.apache.jasper.servlet.JspServlet.service(JspServlet.java:260)
        at javax.servlet.http.HttpServlet.service(HttpServlet.java:717)
        at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:290)
        at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
        at org.apache.catalina.core.ApplicationDispatcher.invoke(ApplicationDispatcher.java:646)
        at org.apache.catalina.core.ApplicationDispatcher.processRequest(ApplicationDispatcher.java:436)
        at org.apache.catalina.core.ApplicationDispatcher.doForward(ApplicationDispatcher.java:374)
        at org.apache.catalina.core.ApplicationDispatcher.forward(ApplicationDispatcher.java:302)
        at org.apache.myfaces.context.servlet.ServletExternalContextImpl.dispatch(ServletExternalContextImpl.java:419)
        at org.apache.myfaces.application.jsp.JspViewHandlerImpl.renderView(JspViewHandlerImpl.java:211)
        at org.jenia.faces.template.handler.ViewHandler.renderView(ViewHandler.java:76)
        at org.ajax4jsf.application.ViewHandlerWrapper.renderView(ViewHandlerWrapper.java:108)
        at org.ajax4jsf.application.AjaxViewHandler.renderView(AjaxViewHandler.java:216)
        at org.apache.myfaces.lifecycle.RenderResponseExecutor.execute(RenderResponseExecutor.java:41)
        at org.apache.myfaces.lifecycle.LifecycleImpl.render(LifecycleImpl.java:132)
        at javax.faces.webapp.FacesServlet.service(FacesServlet.java:140)
        at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:290)
        at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
        at org.ajax4jsf.webapp.BaseXMLFilter.doXmlFilter(BaseXMLFilter.java:141)
        at org.ajax4jsf.webapp.BaseFilter.doFilter(BaseFilter.java:281)
        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.ApplicationDispatcher.invoke(ApplicationDispatcher.java:646)
        at org.apache.catalina.core.ApplicationDispatcher.processRequest(ApplicationDispatcher.java:436)
        at org.apache.catalina.core.ApplicationDispatcher.doForward(ApplicationDispatcher.java:374)
        at org.apache.catalina.core.ApplicationDispatcher.forward(ApplicationDispatcher.java:302)
        at org.apache.jasper.runtime.PageContextImpl.doForward(PageContextImpl.java:709)
        at org.apache.jasper.runtime.PageContextImpl.forward(PageContextImpl.java:680)
        at org.apache.jsp.newpages.index_jsp._jspService(index_jsp.java:55)
        at org.apache.jasper.runtime.HttpJspBase.service(HttpJspBase.java:70)
        at javax.servlet.http.HttpServlet.service(HttpServlet.java:717)
        at org.apache.jasper.servlet.JspServletWrapper.service(JspServletWrapper.java:388)
        at org.apache.jasper.servlet.JspServlet.serviceJspFile(JspServlet.java:313)
        at org.apache.jasper.servlet.JspServlet.service(JspServlet.java:260)
        at javax.servlet.http.HttpServlet.service(HttpServlet.java:717)
        at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:290)
        at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
        at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:233)
        at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:191)
        at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:127)
        at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:103)
        at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:109)
        at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:293)
        at org.apache.coyote.http11.Http11Processor.process(Http11Processor.java:861)
        at org.apache.coyote.http11.Http11Protocol$Http11ConnectionHandler.process(Http11Protocol.java:606)
        at org.apache.tomcat.util.net.JIoEndpoint$Worker.run(JIoEndpoint.java:489)

After some searching around, I think that perhaps the solution is here: In short, it says that closing a SessionFactory is insufficient in Hibernate when using MySQL, and the underlying C3P0ConnectionProvider must be manually stop()ped. However, I don’t know what else it might break if we start to close objects that were—though by accident—always open in the past and I am not sure if this is the solution at all.

henning-gerhardt commented 9 years ago

Stopping / Closing database connection on shutdown should be ok but not while working. Should the used connection pooling not handling (open and close database connection) this?