Lucee 4.5 and database connections - problem
176 views
Skip to first unread message
Christian Meis
Oct 19, 2016, 11:16:25 AM10/19/16
to Lucee
Hi group,
WEB-INF/lucee/logs/exception.log:
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.<init>(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.<init>(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
Christian Meis
Oct 20, 2016, 9:17:17 AM10/20/16
to Lucee
No one got any pointers or seen anything like this before?
Christian
Hans Versluis
Feb 20, 2017, 5:33:11 AM2/20/17
to Lucee
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:
Op woensdag 19 oktober 2016 17:16:25 UTC+2 schreef Christian Meis:
Reply all
Reply to author
Forward
0 new messages