Hi group,
I have several Lucee instances that stop working now and then. “Stop
working” means: Tomcat doesn’t answer the request, and only a restart (of
Tomcat) will resolve the situation.
This might happen again days or weeks after a service restart. On one
system Lucee wasn’t able to survive more than a few minutes before crashing
- and this with literally only one or
two users using the application.
System environment:
CentOS 6 x64
Lucee 4.5.3.018, “standard” install using the installer, not behind Apache.
Java 1.8.0
Connecting to MySQL datasources in a Galera cluster that are sitting behind
a HAproxy loadbalancer.
Just now this happened on a system serving about 150-400 concurrent
sessions all during the day.
I found this in the logs:
tomcat/logs/catalina.out:
;;lucee.runtime.engine.Controler$ControlerThread.stop0(java.lang.Object);
java.lang.NoSuchMethodException: lucee.runtime.engine.
Controler$ControlerThread.stop0(java.lang.Object)
at java.lang.Class.getMethod(Class.java:1786)
at lucee.commons.io.StopThread.run(SystemUtil.java:1085)
Wed Oct 19 16:07:54 CEST 2016-906 conflict in same thread: on /opt/lucee/
tomcat/webapps/ROOT/WEB-INF/lucee/logs/datasource.log
Exception in thread “http-nio-8888-exec-44” java.lang.
IllegalMonitorStateException
at java.util.concurrent.locks.ReentrantLock$Sync.tryRelease(
ReentrantLock.java:151)
at java.util.concurrent.locks.AbstractQueuedSynchronizer.release(
AbstractQueuedSynchronizer.java:1261)
at java.util.concurrent.locks.ReentrantLock.unlock(ReentrantLock.
java:457)
at java.util.concurrent.LinkedBlockingQueue.poll(LinkedBlockingQueue
.java:474)
at org.apache.tomcat.util.threads.TaskQueue.poll(TaskQueue.java:85)
at org.apache.tomcat.util.threads.TaskQueue.poll(TaskQueue.java:31)
at java.util.concurrent.ThreadPoolExecutor.getTask(
ThreadPoolExecutor.java:1066)
at java.util.concurrent.ThreadPoolExecutor.runWorker(
ThreadPoolExecutor.java:1127)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(
ThreadPoolExecutor.java:617)
at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(
TaskThread.java:61)
at java.lang.Thread.run(Thread.java:745)
Exception in thread “http-nio-8888-exec-102” java.lang.
IllegalMonitorStateException
at java.util.concurrent.locks.ReentrantLock$Sync.tryRelease(
ReentrantLock.java:151)
at java.util.concurrent.locks.AbstractQueuedSynchronizer.release(
AbstractQueuedSynchronizer.java:1261)
at java.util.concurrent.locks.ReentrantLock.unlock(ReentrantLock.
java:457)
at java.util.concurrent.LinkedBlockingQueue.poll(LinkedBlockingQueue
.java:474)
at org.apache.tomcat.util.threads.TaskQueue.poll(TaskQueue.java:85)
at org.apache.tomcat.util.threads.TaskQueue.poll(TaskQueue.java:31)
at java.util.concurrent.ThreadPoolExecutor.getTask(
ThreadPoolExecutor.java:1066)
at java.util.concurrent.ThreadPoolExecutor.runWorker(
ThreadPoolExecutor.java:1127)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(
ThreadPoolExecutor.java:617)
at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(
TaskThread.java:61)
at java.lang.Thread.run(Thread.java:745)
Exception in thread “http-nio-8888-exec-99” java.lang.
IllegalMonitorStateException
at java.util.concurrent.locks.ReentrantLock$Sync.tryRelease(
ReentrantLock.java:151)
at java.util.concurrent.locks.AbstractQueuedSynchronizer.release(
AbstractQueuedSynchronizer.java:1261)
at java.util.concurrent.locks.ReentrantLock.unlock(ReentrantLock.
java:457)
at java.util.concurrent.LinkedBlockingQueue.poll(LinkedBlockingQueue
.java:474)
at org.apache.tomcat.util.threads.TaskQueue.poll(TaskQueue.java:85)
at org.apache.tomcat.util.threads.TaskQueue.poll(TaskQueue.java:31)
at java.util.concurrent.ThreadPoolExecutor.getTask(
ThreadPoolExecutor.java:1066)
at java.util.concurrent.ThreadPoolExecutor.runWorker(
ThreadPoolExecutor.java:1127)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(
ThreadPoolExecutor.java:617)
at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(
TaskThread.java:61)
at java.lang.Thread.run(Thread.java:745)
WEB-INF/lucee/logs/exception.log:
“ERROR”,“http-nio-8888-exec-115”,“10/19/2016”,“16:08:36”,“”,
";lucee.runtime.exp.DatabaseException
Statement cancelled due to timeout or client request;
at com.mysql.jdbc.StatementImpl.execute(StatementImpl.java:861):861
at com.mysql.jdbc.StatementImpl.execute(StatementImpl.java:681):681
at
lucee.runtime.db.driver.state.StateUtil.execute(StateUtil.java:37):37
at
lucee.runtime.db.driver.state.StateStatement.execute(StateStatement.java:43):43
at lucee.runtime.type.util.QueryUtil.execute(QueryUtil.java:232):232
at lucee.runtime.type.QueryImpl.(QueryImpl.java:243):243
at lucee.runtime.tag.Query.executeDatasoure(Query.java:802):802
at lucee.runtime.tag.Query.doEndTag(Query.java:604):604
at
index_cfm$cf.call(/opt/lucee/tomcat/webapps/ROOT/index.cfm:112):112
at
lucee.runtime.PageContextImpl.doInclude(PageContextImpl.java:954):954
at
lucee.runtime.PageContextImpl.doInclude(PageContextImpl.java:906):906
at
lucee.runtime.listener.ModernAppListener._onRequest(ModernAppListener.java:225):225
at
lucee.runtime.listener.MixedAppListener.onRequest(MixedAppListener.java:37):37
at
lucee.runtime.PageContextImpl.execute(PageContextImpl.java:2265):2265
at
lucee.runtime.PageContextImpl.execute(PageContextImpl.java:2228):2228
at
lucee.runtime.engine.CFMLEngineImpl.serviceCFML(CFMLEngineImpl.java:456):456
at lucee.loader.servlet.CFMLServlet.service(CFMLServlet.java:47):47
at javax.servlet.http.HttpServlet.service(HttpServlet.java:729):729
at
org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:292):292
at
org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:207):207
at
org.apache.tomcat.websocket.server.WsFilter.doFilter(WsFilter.java:52):52
at
org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:240):240
at
org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:207):207
at
org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:212):212
at
org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:106):106
at
org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:502):502
at
org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:141):141
at
org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:79):79
at mod_cfml.core.invoke(core.java:152):152
at
org.apache.catalina.valves.AbstractAccessLogValve.invoke(AbstractAccessLogValve.java:616):616
at
org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:88):88
at
org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:528):528
at
org.apache.coyote.http11.AbstractHttp11Processor.process(AbstractHttp11Processor.java:1100):1100
at
org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process(AbstractProtocol.java:687):687
at
org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1520):1520
at
org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.run(NioEndpoint.java:1476):1476
at
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142):1142
at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617):617
at
org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61):61
at java.lang.Thread.run(Thread.java:745):745
WEB-INF/lucee/logs/datasource.log:
“ERROR”,“http-nio-8888-exec-113”,“10/19/2016”,“16:08:37”,“”,"query
tag;lucee.runtime.exp.DatabaseException
Statement cancelled due to timeout or client request;
at com.mysql.jdbc.StatementImpl.execute(StatementImpl.java:861):861
at com.mysql.jdbc.StatementImpl.execute(StatementImpl.java:681):681
at
lucee.runtime.db.driver.state.StateUtil.execute(StateUtil.java:37):37
at
lucee.runtime.db.driver.state.StateStatement.execute(StateStatement.java:43):43
at lucee.runtime.type.util.QueryUtil.execute(QueryUtil.java:232):232
at lucee.runtime.type.QueryImpl.(QueryImpl.java:243):243
at lucee.runtime.tag.Query.executeDatasoure(Query.java:802):802
at lucee.runtime.tag.Query.doEndTag(Query.java:604):604
at
index_cfm$cf.call(/opt/lucee/tomcat/webapps/ROOT/index.cfm:112):112
at
lucee.runtime.PageContextImpl.doInclude(PageContextImpl.java:954):954
at
lucee.runtime.PageContextImpl.doInclude(PageContextImpl.java:906):906
at
lucee.runtime.listener.ModernAppListener._onRequest(ModernAppListener.java:225):225
at
lucee.runtime.listener.MixedAppListener.onRequest(MixedAppListener.java:37):37
at
lucee.runtime.PageContextImpl.execute(PageContextImpl.java:2265):2265
at
lucee.runtime.PageContextImpl.execute(PageContextImpl.java:2228):2228
at
lucee.runtime.engine.CFMLEngineImpl.serviceCFML(CFMLEngineImpl.java:456):456
at lucee.loader.servlet.CFMLServlet.service(CFMLServlet.java:47):47
at javax.servlet.http.HttpServlet.service(HttpServlet.java:729):729
at
org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:292):292
at
org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:207):207
at
org.apache.tomcat.websocket.server.WsFilter.doFilter(WsFilter.java:52):52
at
org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:240):240
at
org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:207):207
at
org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:212):212
at
org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:106):106
at
org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:502):502
at
org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:141):141
at
org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:79):79
at mod_cfml.core.invoke(core.java:152):152
at
org.apache.catalina.valves.AbstractAccessLogValve.invoke(AbstractAccessLogValve.java:616):616
at
org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:88):88
at
org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:528):528
at
org.apache.coyote.http11.AbstractHttp11Processor.process(AbstractHttp11Processor.java:1100):1100
at
org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process(AbstractProtocol.java:687):687
at
org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1520):1520
at
org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.run(NioEndpoint.java:1476):1476
at
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142):1142
at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617):617
at
org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61):61
at java.lang.Thread.run(Thread.java:745):745
"
My datasources do have a connection limit of 100 or 200, the MySQL server
has a max_connections of 400. So that should not be a problem.
Could it be that somehow the connection pool is “filled up” or connections
aren’t freed again? The datasource connection timeout is set to 1 second.
There was LDEV-777 regarding a not thread-safe connection pool counter -
could this be connected in any way (although Lucee 4.3.5.018 should have
this
fix included…)?
Looking for pointers how to proceed and nail down the error…
Best regards,
Christian