[opencms-dev] Tons of CmsSqlManager SQLException: Already closed

[Alessandro Magnolo]

Hello,
while investigating on severe database bottlenecks in a big opencms
installation, I found out that when adding this directive in
log4j.properties:

log4j.logger.org.opencms.db.generic.CmsSqlManager=DEBUG

several megabytes of log files are generated, similar to this one:

11 Nov 2008 12:41:44,731 DEBUG [encms.db.generic.CmsSqlManager: 179]
Already closed
java.sql.SQLException: Already closed
	at org.apache.commons.dbcp.PoolablePreparedStatement.close(PoolablePreparedStatement.java:76)
	at org.apache.commons.dbcp.DelegatingStatement.close(DelegatingStatement.java:168)
	at org.opencms.db.generic.CmsSqlManager.closeAll(CmsSqlManager.java:176)
	at org.opencms.db.generic.CmsVfsDriver.readRelations(CmsVfsDriver.java:1811)
	at org.opencms.db.CmsDriverManager.getRelationsForResource(CmsDriverManager.java:3921)
	at org.opencms.db.generic.CmsUserDriver.internalResourcesForOrgUnit(CmsUserDriver.java:2436)
	at org.opencms.db.generic.CmsUserDriver.getResourcesForOrganizationalUnit(CmsUserDriver.java:854)
	at org.opencms.db.CmsDriverManager.getResourcesForOrganizationalUnit(CmsDriverManager.java:3941)
	at org.opencms.db.CmsSecurityManager.hasRoleForResource(CmsSecurityManager.java:2483)
	at org.opencms.security.CmsDefaultPermissionHandler.hasPermissions(CmsDefaultPermissionHandler.java:114)
	at org.opencms.db.CmsSecurityManager.hasPermissions(CmsSecurityManager.java:5560)
	at org.opencms.db.CmsDriverManager.filterPermissions(CmsDriverManager.java:8436)
	at org.opencms.db.CmsDriverManager.readResourcesWithProperty(CmsDriverManager.java:6465)
	at org.opencms.db.CmsSecurityManager.readResourcesWithProperty(CmsSecurityManager.java:4067)
	at org.opencms.file.CmsObject.readResourcesWithProperty(CmsObject.java:3589)
	at org.opencms.file.CmsObject.readResourcesWithProperty(CmsObject.java:3565)
	at org.opencms.workplace.tools.CmsToolManager.configureToolRoot(CmsToolManager.java:595)
	at org.opencms.workplace.tools.CmsToolManager.configure(CmsToolManager.java:200)
	at org.opencms.workplace.CmsWorkplaceManager.initialize(CmsWorkplaceManager.java:1174)
	at org.opencms.main.OpenCmsCore.initConfiguration(OpenCmsCore.java:1184)
	at org.opencms.main.OpenCmsCore.initContext(OpenCmsCore.java:1300)
	at org.opencms.main.OpenCmsCore.upgradeRunlevel(OpenCmsCore.java:1729)
	at org.opencms.main.OpenCmsListener.contextInitialized(OpenCmsListener.java:87)
	at org.apache.catalina.core.StandardContext.listenerStart(StandardContext.java:3692)
	at org.apache.catalina.core.StandardContext.start(StandardContext.java:4127)
	at org.apache.catalina.core.StandardContext.reload(StandardContext.java:2953)
	at org.apache.catalina.manager.ManagerServlet.reload(ManagerServlet.java:906)
	at org.apache.catalina.manager.HTMLManagerServlet.reload(HTMLManagerServlet.java:473)
	at org.apache.catalina.manager.HTMLManagerServlet.doGet(HTMLManagerServlet.java:98)
	at javax.servlet.http.HttpServlet.service(HttpServlet.java:689)
	at javax.servlet.http.HttpServlet.service(HttpServlet.java:802)
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:252)
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:173)
	at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:213)
	at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:178)
	at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:514)
	at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:126)
	at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:105)
	at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:107)
	at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:148)
	at org.apache.coyote.http11.Http11Processor.process(Http11Processor.java:868)
	at org.apache.coyote.http11.Http11BaseProtocol$Http11ConnectionHandler.processConnection(Http11BaseProtocol.java:663)
	at org.apache.tomcat.util.net.PoolTcpEndpoint.processSocket(PoolTcpEndpoint.java:527)
	at org.apache.tomcat.util.net.LeaderFollowerWorkerThread.runIt(LeaderFollowerWorkerThread.java:80)
	at org.apache.tomcat.util.threads.ThreadPool$ControlRunnable.run(ThreadPool.java:684)
	at java.lang.Thread.run(Thread.java:619)

The previous log file was generated by opencms 7.0.3 with an oracle
backend, as soon as the webapp was loaded. The same thing happens with
another simple installation of opencms version 7.0.5 and mysql. This
is a sample of the log generated on webapp load:

11 Nov 2008 12:56:00,477 DEBUG [encms.db.generic.CmsSqlManager: 179]
Already closed
java.sql.SQLException: Already closed
	at org.apache.commons.dbcp.PoolablePreparedStatement.close(PoolablePreparedStatement.java:76)
	at org.apache.commons.dbcp.DelegatingStatement.close(DelegatingStatement.java:168)
	at org.opencms.db.generic.CmsSqlManager.closeAll(CmsSqlManager.java:176)
	at org.opencms.db.generic.CmsVfsDriver.readRelations(CmsVfsDriver.java:1839)
	at org.opencms.db.CmsDriverManager.getRelationsForResource(CmsDriverManager.java:4083)
	at org.opencms.db.generic.CmsUserDriver.internalResourcesForOrgUnit(CmsUserDriver.java:2431)
	at org.opencms.db.generic.CmsUserDriver.getResourcesForOrganizationalUnit(CmsUserDriver.java:847)
	at org.opencms.db.CmsDriverManager.getResourcesForOrganizationalUnit(CmsDriverManager.java:4126)
	at org.opencms.db.CmsSecurityManager.hasRoleForResource(CmsSecurityManager.java:2516)
	at org.opencms.security.CmsDefaultPermissionHandler.hasPermissions(CmsDefaultPermissionHandler.java:114)
	at org.opencms.db.CmsSecurityManager.hasPermissions(CmsSecurityManager.java:5680)
	at org.opencms.db.CmsDriverManager.filterPermissions(CmsDriverManager.java:8636)
	at org.opencms.db.CmsDriverManager.readResourcesWithProperty(CmsDriverManager.java:6690)
	at org.opencms.db.CmsSecurityManager.readResourcesWithProperty(CmsSecurityManager.java:4151)
	at org.opencms.file.CmsObject.readResourcesWithProperty(CmsObject.java:3613)
	at org.opencms.file.CmsObject.readResourcesWithProperty(CmsObject.java:3587)
	at org.opencms.workplace.tools.CmsToolManager.configureToolRoot(CmsToolManager.java:595)
	at org.opencms.workplace.tools.CmsToolManager.configure(CmsToolManager.java:200)
	at org.opencms.workplace.CmsWorkplaceManager.initialize(CmsWorkplaceManager.java:1204)
	at org.opencms.main.OpenCmsCore.initConfiguration(OpenCmsCore.java:1182)
	at org.opencms.main.OpenCmsCore.initContext(OpenCmsCore.java:1310)
	at org.opencms.main.OpenCmsCore.upgradeRunlevel(OpenCmsCore.java:1735)
	at org.opencms.main.OpenCmsListener.contextInitialized(OpenCmsListener.java:87)
	at org.apache.catalina.core.StandardContext.listenerStart(StandardContext.java:3692)
	at org.apache.catalina.core.StandardContext.start(StandardContext.java:4127)
	at org.apache.catalina.core.StandardContext.reload(StandardContext.java:2953)
	at org.apache.catalina.manager.ManagerServlet.reload(ManagerServlet.java:906)
	at org.apache.catalina.manager.HTMLManagerServlet.reload(HTMLManagerServlet.java:473)
	at org.apache.catalina.manager.HTMLManagerServlet.doGet(HTMLManagerServlet.java:98)
	at javax.servlet.http.HttpServlet.service(HttpServlet.java:689)
	at javax.servlet.http.HttpServlet.service(HttpServlet.java:802)
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:252)
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:173)
	at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:213)
	at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:178)
	at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:514)
	at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:126)
	at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:105)
	at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:107)
	at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:148)
	at org.apache.coyote.http11.Http11Processor.process(Http11Processor.java:868)
	at org.apache.coyote.http11.Http11BaseProtocol$Http11ConnectionHandler.processConnection(Http11BaseProtocol.java:663)
	at org.apache.tomcat.util.net.PoolTcpEndpoint.processSocket(PoolTcpEndpoint.java:527)
	at org.apache.tomcat.util.net.LeaderFollowerWorkerThread.runIt(LeaderFollowerWorkerThread.java:80)
	at org.apache.tomcat.util.threads.ThreadPool$ControlRunnable.run(ThreadPool.java:684)
	at java.lang.Thread.run(Thread.java:619)

I guess this is a bug in opencms handling of the database pool, and I
fear that it is the cause of the problems with the database when the
load is high.

regards,
Alessandro Magnolo