Lucee 4.5 and database connections - problem

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

No one got any pointers or seen anything like this before?

ChristianAm Mittwoch, 19. Oktober 2016 17:16:25 UTC+2 schrieb Christian Meis:

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

I’m experiencing the same problem: Tomcat might not respond any more and
does not recover after the database is down during a couple of secons after
a nightly backup.
This only happens once or twice a month.

I would be very relieved if someone could fix this problem.

I’m using Lucee 4.5.2

@Christian, do you have any news on this issue?Op woensdag 19 oktober 2016 17:16:25 UTC+2 schreef Christian Meis:

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