Solución al error: Communications link failure due to underlying exception

Wed Sep 02 22:11:00 CEST 2009       Sergio Raposo Vargas       Administración, OpenCms

El problema

No os ha pasado nunca el intentar entrar en OpenCms y deciros que vuestra clave es incorrecta? Luego, se nos ocurre reiniciar el servidor y derrepente ya nos deja entrar? Pues llevo unos días encontrandome este error y me he puesto a investigar un poco que le pasa. Por lo visto, OpenCms tiene un problema, cuando el pool de conexiones se satura toma como solución bloquear la herramienta que provoca dicha saturación. El error que podemos encontrar en el log es:

org.opencms.db.CmsDbSqlException: Sucedió un error SQL ejecutando la siquiente consulta: com.mysql.jdbc.PreparedStatement@c407e: statement has been closed, no further internal information available.
    at org.opencms.db.generic.CmsUserDriver.readUserInfos(CmsUserDriver.java:1473)
    at org.opencms.db.generic.CmsUserDriver.internalCreateUser(CmsUserDriver.java:2304)
    at org.opencms.db.generic.CmsUserDriver.readUser(CmsUserDriver.java:1409)
    at org.opencms.db.CmsDriverManager.loginUser(CmsDriverManager.java:4700)
    at org.opencms.db.CmsSecurityManager.loginUser(CmsSecurityManager.java:2884)
    at org.opencms.file.CmsObject.loginUser(CmsObject.java:2267)
    at org.opencms.jsp.CmsJspLoginBean.login(CmsJspLoginBean.java:189)
    at org.opencms.jsp.CmsJspLoginBean.login(CmsJspLoginBean.java:169)
    at org.opencms.workplace.CmsLogin.displayDialog(CmsLogin.java:293)
    at org.apache.jsp.WEB_002dINF.jsp.online.system.login.index_html_jsp._jspService(index_html_jsp.java:48)
    at org.apache.jasper.runtime.HttpJspBase.service(HttpJspBase.java:98)
    at javax.servlet.http.HttpServlet.service(HttpServlet.java:803)
    at org.apache.jasper.servlet.JspServletWrapper.service(JspServletWrapper.java:331)
    at org.apache.jasper.servlet.JspServlet.serviceJspFile(JspServlet.java:329)
    at org.apache.jasper.servlet.JspServlet.service(JspServlet.java:265)
    at javax.servlet.http.HttpServlet.service(HttpServlet.java:803)
    at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:269)
    at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:188)
    at org.apache.catalina.core.ApplicationDispatcher.invoke(ApplicationDispatcher.java:691)
    at org.apache.catalina.core.ApplicationDispatcher.doInclude(ApplicationDispatcher.java:594)
    at org.apache.catalina.core.ApplicationDispatcher.include(ApplicationDispatcher.java:505)
    at org.opencms.flex.CmsFlexRequestDispatcher.includeExternal(CmsFlexRequestDispatcher.java:194)
    at org.opencms.flex.CmsFlexRequestDispatcher.include(CmsFlexRequestDispatcher.java:169)
    at org.opencms.loader.CmsJspLoader.service(CmsJspLoader.java:555)
    at org.opencms.flex.CmsFlexRequestDispatcher.includeInternalWithCache(CmsFlexRequestDispatcher.java:423)
    at org.opencms.flex.CmsFlexRequestDispatcher.include(CmsFlexRequestDispatcher.java:173)
    at org.opencms.loader.CmsJspLoader.dispatchJsp(CmsJspLoader.java:829)
    at org.opencms.loader.CmsJspLoader.load(CmsJspLoader.java:512)
    at org.opencms.loader.CmsResourceManager.loadResource(CmsResourceManager.java:964)
    at org.opencms.main.OpenCmsCore.showResource(OpenCmsCore.java:1524)
    at org.opencms.main.OpenCmsServlet.doGet(OpenCmsServlet.java:152)
    at org.opencms.main.OpenCmsServlet.doPost(OpenCmsServlet.java:164)
    at javax.servlet.http.HttpServlet.service(HttpServlet.java:710)
    at javax.servlet.http.HttpServlet.service(HttpServlet.java:803)
    at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:269)
    at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:188)
    at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:213)
    at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:174)
    at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:127)
    at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:117)
    at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:108)
    at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:151)
    at org.apache.coyote.http11.Http11Processor.process(Http11Processor.java:874)
    at org.apache.coyote.http11.Http11BaseProtocol$Http11ConnectionHandler.processConnection(Http11BaseProtocol.java:665)
    at org.apache.tomcat.util.net.PoolTcpEndpoint.processSocket(PoolTcpEndpoint.java:528)
    at org.apache.tomcat.util.net.LeaderFollowerWorkerThread.runIt(LeaderFollowerWorkerThread.java:81)
    at org.apache.tomcat.util.threads.ThreadPool$ControlRunnable.run(ThreadPool.java:689)
    at java.lang.Thread.run(Unknown Source)
Caused by: com.mysql.jdbc.CommunicationsException: Communications link failure due to underlying exception:

** BEGIN NESTED EXCEPTION **

java.net.SocketException
MESSAGE: Software caused connection abort: socket write error

STACKTRACE:

java.net.SocketException: Software caused connection abort: socket write error
    at java.net.SocketOutputStream.socketWrite0(Native Method)
    at java.net.SocketOutputStream.socketWrite(Unknown Source)
    at java.net.SocketOutputStream.write(Unknown Source)
    at java.io.BufferedOutputStream.flushBuffer(Unknown Source)
    at java.io.BufferedOutputStream.flush(Unknown Source)
    at com.mysql.jdbc.MysqlIO.send(MysqlIO.java:2744)
    at com.mysql.jdbc.MysqlIO.sendCommand(MysqlIO.java:1612)
    at com.mysql.jdbc.MysqlIO.sqlQueryDirect(MysqlIO.java:1723)
    at com.mysql.jdbc.Connection.execSQL(Connection.java:3256)
    at com.mysql.jdbc.PreparedStatement.executeInternal(PreparedStatement.java:1313)
    at com.mysql.jdbc.PreparedStatement.executeQuery(PreparedStatement.java:1448)
    at org.apache.commons.dbcp.DelegatingPreparedStatement.executeQuery(DelegatingPreparedStatement.java:93)
    at org.apache.commons.dbcp.DelegatingPreparedStatement.executeQuery(DelegatingPreparedStatement.java:93)
    at org.opencms.db.generic.CmsUserDriver.readUserInfos(CmsUserDriver.java:1449)
    at org.opencms.db.generic.CmsUserDriver.internalCreateUser(CmsUserDriver.java:2304)
    at org.opencms.db.generic.CmsUserDriver.readUser(CmsUserDriver.java:1409)
    at org.opencms.db.CmsDriverManager.loginUser(CmsDriverManager.java:4700)
    at org.opencms.db.CmsSecurityManager.loginUser(CmsSecurityManager.java:2884)
    at org.opencms.file.CmsObject.loginUser(CmsObject.java:2267)
    at org.opencms.jsp.CmsJspLoginBean.login(CmsJspLoginBean.java:189)
    at org.opencms.jsp.CmsJspLoginBean.login(CmsJspLoginBean.java:169)
    at org.opencms.workplace.CmsLogin.displayDialog(CmsLogin.java:293)
    at org.apache.jsp.WEB_002dINF.jsp.online.system.login.index_html_jsp._jspService(index_html_jsp.java:48)
    at org.apache.jasper.runtime.HttpJspBase.service(HttpJspBase.java:98)
    at javax.servlet.http.HttpServlet.service(HttpServlet.java:803)
    at org.apache.jasper.servlet.JspServletWrapper.service(JspServletWrapper.java:331)
    at org.apache.jasper.servlet.JspServlet.serviceJspFile(JspServlet.java:329)
    at org.apache.jasper.servlet.JspServlet.service(JspServlet.java:265)
    at javax.servlet.http.HttpServlet.service(HttpServlet.java:803)
    at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:269)
    at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:188)
    at org.apache.catalina.core.ApplicationDispatcher.invoke(ApplicationDispatcher.java:691)
    at org.apache.catalina.core.ApplicationDispatcher.doInclude(ApplicationDispatcher.java:594)
    at org.apache.catalina.core.ApplicationDispatcher.include(ApplicationDispatcher.java:505)
    at org.opencms.flex.CmsFlexRequestDispatcher.includeExternal(CmsFlexRequestDispatcher.java:194)
    at org.opencms.flex.CmsFlexRequestDispatcher.include(CmsFlexRequestDispatcher.java:169)
    at org.opencms.loader.CmsJspLoader.service(CmsJspLoader.java:555)
    at org.opencms.flex.CmsFlexRequestDispatcher.includeInternalWithCache(CmsFlexRequestDispatcher.java:423)
    at org.opencms.flex.CmsFlexRequestDispatcher.include(CmsFlexRequestDispatcher.java:173)
    at org.opencms.loader.CmsJspLoader.dispatchJsp(CmsJspLoader.java:829)
    at org.opencms.loader.CmsJspLoader.load(CmsJspLoader.java:512)
    at org.opencms.loader.CmsResourceManager.loadResource(CmsResourceManager.java:964)
    at org.opencms.main.OpenCmsCore.showResource(OpenCmsCore.java:1524)
    at org.opencms.main.OpenCmsServlet.doGet(OpenCmsServlet.java:152)
    at org.opencms.main.OpenCmsServlet.doPost(OpenCmsServlet.java:164)
    at javax.servlet.http.HttpServlet.service(HttpServlet.java:710)
    at javax.servlet.http.HttpServlet.service(HttpServlet.java:803)
    at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:269)
    at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:188)
    at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:213)
    at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:174)
    at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:127)
    at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:117)
    at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:108)
    at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:151)
    at org.apache.coyote.http11.Http11Processor.process(Http11Processor.java:874)
    at org.apache.coyote.http11.Http11BaseProtocol$Http11ConnectionHandler.processConnection(Http11BaseProtocol.java:665)
    at org.apache.tomcat.util.net.PoolTcpEndpoint.processSocket(PoolTcpEndpoint.java:528)
    at org.apache.tomcat.util.net.LeaderFollowerWorkerThread.runIt(LeaderFollowerWorkerThread.java:81)
    at org.apache.tomcat.util.threads.ThreadPool$ControlRunnable.run(ThreadPool.java:689)
    at java.lang.Thread.run(Unknown Source)


** END NESTED EXCEPTION **



Last packet sent to the server was 0 ms ago.
    at com.mysql.jdbc.MysqlIO.send(MysqlIO.java:2759)
    at com.mysql.jdbc.MysqlIO.sendCommand(MysqlIO.java:1612)
    at com.mysql.jdbc.MysqlIO.sqlQueryDirect(MysqlIO.java:1723)
    at com.mysql.jdbc.Connection.execSQL(Connection.java:3256)
    at com.mysql.jdbc.PreparedStatement.executeInternal(PreparedStatement.java:1313)
    at com.mysql.jdbc.PreparedStatement.executeQuery(PreparedStatement.java:1448)
    at org.apache.commons.dbcp.DelegatingPreparedStatement.executeQuery(DelegatingPreparedStatement.java:93)
    at org.apache.commons.dbcp.DelegatingPreparedStatement.executeQuery(DelegatingPreparedStatement.java:93)
    at org.opencms.db.generic.CmsUserDriver.readUserInfos(CmsUserDriver.java:1449)
    ... 47 more

La solución

La solución del problema pasa por cambiar un simple parámetro de configuración del fichero opencms.properties. Exactamente buscamos la linea:

# action to take when the pool is exhausted {grow|block|fail}
db.pool.default.whenExhaustedAction=block

Y debemos cambiarla a:

# action to take when the pool is exhausted {grow|block|fail}
db.pool.default.whenExhaustedAction=grow

De esta forma, si el pool de conexiones se satura no bloquerá OpenCms sino que aumentará el número de hilos de los que dispone por defecto.

Sinceramente no sé si es un error muy común, pero ya me cruce con este error en dos servidores distintos.