At one of our client installations, the lucee server seems to be periodically shutting down… seems to be happening around once or twice a week lately.
This is the entire catalina logfile for the last time it happened (catalina.2020-11-26.log)
26-Nov-2020 05:47:00.497 INFO [Thread-12041] org.apache.coyote.AbstractProtocol.pause Pausing ProtocolHandler ["http-nio-8808"]
26-Nov-2020 05:47:00.769 INFO [Thread-12041] org.apache.coyote.AbstractProtocol.pause Pausing ProtocolHandler ["ajp-nio-8009"]
26-Nov-2020 05:47:00.943 INFO [Thread-12041] org.apache.catalina.core.StandardService.stopInternal Stopping service [Catalina]
26-Nov-2020 05:47:00.998 WARNING [Thread-12041] org.apache.catalina.loader.WebappClassLoaderBase.clearReferencesThreads The web application [ROOT] appears to have started a thread named [Thread-43] but has failed to stop it. This is very likely to create a memory leak. Stack trace of thread:
java.base@11.0.3/java.lang.Object.wait(Native Method)
lucee.commons.io.SystemUtil.wait(SystemUtil.java:720)
lucee.runtime.schedule.ScheduledTaskThread.sleepEL(ScheduledTaskThread.java:236)
lucee.runtime.schedule.ScheduledTaskThread._run(ScheduledTaskThread.java:172)
lucee.runtime.schedule.ScheduledTaskThread.run(ScheduledTaskThread.java:126)
26-Nov-2020 05:47:01.002 WARNING [Thread-12041] org.apache.catalina.loader.WebappClassLoaderBase.clearReferencesThreads The web application [ROOT] appears to have started a thread named [Thread-44] but has failed to stop it. This is very likely to create a memory leak. Stack trace of thread:
java.base@11.0.3/java.lang.Object.wait(Native Method)
lucee.commons.io.SystemUtil.wait(SystemUtil.java:720)
lucee.runtime.schedule.ScheduledTaskThread.sleepEL(ScheduledTaskThread.java:236)
lucee.runtime.schedule.ScheduledTaskThread._run(ScheduledTaskThread.java:172)
lucee.runtime.schedule.ScheduledTaskThread.run(ScheduledTaskThread.java:126)
26-Nov-2020 05:47:11.448 WARNING [Thread-12041] org.apache.catalina.loader.WebappClassLoaderBase.clearReferencesThreads The web application [ROOT] appears to have started a thread named [Thread-12042] but has failed to stop it. This is very likely to create a memory leak. Stack trace of thread:
java.base@11.0.3/java.lang.Object.wait(Native Method)
lucee.commons.io.retirement.RetireOutputStreamFactory$RetireThread.run(RetireOutputStreamFactory.java:72)
26-Nov-2020 05:47:11.464 INFO [Thread-12041] org.apache.coyote.AbstractProtocol.stop Stopping ProtocolHandler ["http-nio-8808"]
26-Nov-2020 05:47:11.479 INFO [Thread-12041] org.apache.coyote.AbstractProtocol.stop Stopping ProtocolHandler ["ajp-nio-8009"]
26-Nov-2020 05:47:11.479 INFO [Thread-12043] org.apache.catalina.util.LifecycleBase.stop The stop() method was called on component [StandardServer[8005]] after stop() had already been called. The second call will be ignored.
26-Nov-2020 05:47:11.495 INFO [Thread-12043] org.apache.coyote.AbstractProtocol.destroy Destroying ProtocolHandler ["http-nio-8808"]
26-Nov-2020 05:47:11.495 INFO [Thread-12043] org.apache.coyote.AbstractProtocol.destroy Destroying ProtocolHandler ["ajp-nio-8009"]
26-Nov-2020 05:47:11.510 INFO [Thread-12041] org.apache.catalina.util.LifecycleBase.destroy The destroy() method was called on component [StandardServer[8005]] after destroy() had already been called. The second call will be ignored.
I see the message
org.apache.catalina.core.StandardService.stopInternal Stopping service [Catalina]
which seems to indicate that it’s shutting down normally, as opposed to hitting a fatal exception, but I don’t know if there’s a way to tell what initiated the shutdown. The lucee-stderr log file shows the same info, but adds a bunch of exceptions and stack traces (after the “Stopping service [Catalina]” though, nothing before that). There’s a bunch of MissingIncludeExeptions from a badly formed url in a scheduled task that I’ve been meaning to take care of, and then there are a couple ThreadDeath exceptions which seem to correspond to the warnings above (Thread-43, Thread-44).
I’ve been meaning to ask about those “memory leak” thread warnings for a while…I don’t think they have anything to do with this problem though. I seem to get that warning for a couple threads named “Thread-{x}”, “Thread-{x+1}” every time I stop the lucee server on my dev machine. I can see them in FusionReactor, and they are always just a couple threads in TIMED_WAITING state. I’ve been assuming they are harmless…(?)
Anyways, the unexpected shutdowns are getting to be pretty annoying to the client, and I can’t tell what is causing them. Is it possible that there’s an unhandled exception in my code that’s not showing up in this log? Or does that “Stopping service” message actually mean it’s just doing a graceful shutdown because “something” told it to?
OS: Windows Server 2019
Java Version: 11.0.3 (AdoptOpenJDK) 64bit
Tomcat Version: 9.0.19
Lucee Version: 5.3.7.47