Lucee restart deletes lucee-server.xml

#1

Restarting Lucee 5.1.0.34 on Ubuntu deletes the file /opt/lucee/tomcat/lucee-server/context/lucee-server.xml and some others within that folder, meaning that the datasource and mappings are lost.
Restarting Tomcat then restores the files with a default version of lucee-server.xml, meaning I have to set the password to access the server admin page and then re-enter the datasource and mappings.
Any idea what might be going on, or what clues I should check for in log files?

#2

you might be able to update the lucee.jar as noted in this bug about the same issue
https://luceeserver.atlassian.net/browse/LDEV-920

But upgrading to a newer release is probably a better solution, 5.1.0.34 is about 3 years old

#3

Thanks, really appreciate your help - updated to newest release and same problem. Also, if I restart Lucee, the /opt/lucee/tomcat/lucee-server/context/cfclasses folder is empty until I restart Tomcat, which deletes and recreates the folder. Is that normal?

#4

was this an older installation? did you do a fresh install?

as @micstriit noted in that issue, the problem may be with the lucee loader

#5

It was installed as 5.1.0.34 when I built the server.
Restarting from the web interface does not cause any problem.
After a Lucee restart there is a long series of entries in the felix.log like this:

DEBUG [Thu May 09 16:27:46 BST 2019]:
 not found by com.mysql.cj [92]
DEBUG [Thu May 09 16:27:46 BST 2019]:
com/mysql/cj/LocalizedErrorMessages_en.properties not found by com.mysql.cj [92]
DEBUG [Thu May 09 16:27:46 BST 2019]:
com/mysql/cj/LocalizedErrorMessages_en_GB.properties not found by com.mysql.cj [92]
DEBUG [Thu May 09 16:27:51 BST 2019]:
 not found by com.mysql.cj [92]
DEBUG [Thu May 09 16:28:02 BST 2019]:
META-INF/services/javax.xml.parsers.SAXParserFactory not found by lucee.core [46]

suggesting that bundles are missing.
catalina.out includes sections like these:

09-May-2019 16:29:53.395 SEVERE [main] org.apache.coyote.AbstractProtocol.init Failed to initialize end point associated with ProtocolHandler ["http-nio-8888"]
 java.net.BindException: Address already in use
	at sun.nio.ch.Net.bind0(Native Method)
	at sun.nio.ch.Net.bind(Net.java:433)
	at sun.nio.ch.Net.bind(Net.java:425)
	at sun.nio.ch.ServerSocketChannelImpl.bind(ServerSocketChannelImpl.java:223)
	at sun.nio.ch.ServerSocketAdaptor.bind(ServerSocketAdaptor.java:74)
	at org.apache.tomcat.util.net.NioEndpoint.bind(NioEndpoint.java:228)
	at org.apache.tomcat.util.net.AbstractEndpoint.init(AbstractEndpoint.java:866)
	at org.apache.tomcat.util.net.AbstractJsseEndpoint.init(AbstractJsseEndpoint.java:213)
	at org.apache.coyote.AbstractProtocol.init(AbstractProtocol.java:575)
	at org.apache.coyote.http11.AbstractHttp11Protocol.init(AbstractHttp11Protocol.java:65)
	at org.apache.catalina.connector.Connector.initInternal(Connector.java:944)
	at org.apache.catalina.util.LifecycleBase.init(LifecycleBase.java:107)
	at org.apache.catalina.core.StandardService.initInternal(StandardService.java:549)
	at org.apache.catalina.util.LifecycleBase.init(LifecycleBase.java:107)
	at org.apache.catalina.core.StandardServer.initInternal(StandardServer.java:873)
	at org.apache.catalina.util.LifecycleBase.init(LifecycleBase.java:107)
	at org.apache.catalina.startup.Catalina.load(Catalina.java:606)
	at org.apache.catalina.startup.Catalina.load(Catalina.java:629)
	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.lang.reflect.Method.invoke(Method.java:498)
	at org.apache.catalina.startup.Bootstrap.load(Bootstrap.java:311)
	at org.apache.catalina.startup.Bootstrap.main(Bootstrap.java:494)

09-May-2019 16:29:53.397 SEVERE [main] org.apache.catalina.core.StandardService.initInternal Failed to initialize connector [Connector[HTTP/1.1-8888]]
 org.apache.catalina.LifecycleException: Failed to initialize component [Connector[HTTP/1.1-8888]]
	at org.apache.catalina.util.LifecycleBase.init(LifecycleBase.java:112)
	at org.apache.catalina.core.StandardService.initInternal(StandardService.java:549)
	at org.apache.catalina.util.LifecycleBase.init(LifecycleBase.java:107)
	at org.apache.catalina.core.StandardServer.initInternal(StandardServer.java:873)
	at org.apache.catalina.util.LifecycleBase.init(LifecycleBase.java:107)
	at org.apache.catalina.startup.Catalina.load(Catalina.java:606)
	at org.apache.catalina.startup.Catalina.load(Catalina.java:629)
	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.lang.reflect.Method.invoke(Method.java:498)
	at org.apache.catalina.startup.Bootstrap.load(Bootstrap.java:311)
	at org.apache.catalina.startup.Bootstrap.main(Bootstrap.java:494)
Caused by: org.apache.catalina.LifecycleException: Protocol handler initialization failed
	at org.apache.catalina.connector.Connector.initInternal(Connector.java:946)
	at org.apache.catalina.util.LifecycleBase.init(LifecycleBase.java:107)
	... 12 more
Caused by: java.net.BindException: Address already in use
	at sun.nio.ch.Net.bind0(Native Method)
	at sun.nio.ch.Net.bind(Net.java:433)
	at sun.nio.ch.Net.bind(Net.java:425)
	at sun.nio.ch.ServerSocketChannelImpl.bind(ServerSocketChannelImpl.java:223)
	at sun.nio.ch.ServerSocketAdaptor.bind(ServerSocketAdaptor.java:74)
	at org.apache.tomcat.util.net.NioEndpoint.bind(NioEndpoint.java:228)
	at org.apache.tomcat.util.net.AbstractEndpoint.init(AbstractEndpoint.java:866)
	at org.apache.tomcat.util.net.AbstractJsseEndpoint.init(AbstractJsseEndpoint.java:213)
	at org.apache.coyote.AbstractProtocol.init(AbstractProtocol.java:575)
	at org.apache.coyote.http11.AbstractHttp11Protocol.init(AbstractHttp11Protocol.java:65)
	at org.apache.catalina.connector.Connector.initInternal(Connector.java:944)
	... 13 more

09-May-2019 16:29:53.399 INFO [main] org.apache.coyote.AbstractProtocol.init Initializing ProtocolHandler ["ajp-nio-8009"]
09-May-2019 16:29:53.401 SEVERE [main] org.apache.coyote.AbstractProtocol.init Failed to initialize end point associated with ProtocolHandler ["ajp-nio-8009"]
 java.net.BindException: Address already in use
	at sun.nio.ch.Net.bind0(Native Method)
	at sun.nio.ch.Net.bind(Net.java:433)
	at sun.nio.ch.Net.bind(Net.java:425)
	at sun.nio.ch.ServerSocketChannelImpl.bind(ServerSocketChannelImpl.java:223)
	at sun.nio.ch.ServerSocketAdaptor.bind(ServerSocketAdaptor.java:74)
	at org.apache.tomcat.util.net.NioEndpoint.bind(NioEndpoint.java:228)
	at org.apache.tomcat.util.net.AbstractEndpoint.init(AbstractEndpoint.java:866)
	at org.apache.tomcat.util.net.AbstractJsseEndpoint.init(AbstractJsseEndpoint.java:213)
	at org.apache.coyote.AbstractProtocol.init(AbstractProtocol.java:575)
	at org.apache.catalina.connector.Connector.initInternal(Connector.java:944)
	at org.apache.catalina.util.LifecycleBase.init(LifecycleBase.java:107)
	at org.apache.catalina.core.StandardService.initInternal(StandardService.java:549)
	at org.apache.catalina.util.LifecycleBase.init(LifecycleBase.java:107)
	at org.apache.catalina.core.StandardServer.initInternal(StandardServer.java:873)
	at org.apache.catalina.util.LifecycleBase.init(LifecycleBase.java:107)
	at org.apache.catalina.startup.Catalina.load(Catalina.java:606)
	at org.apache.catalina.startup.Catalina.load(Catalina.java:629)
	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.lang.reflect.Method.invoke(Method.java:498)
	at org.apache.catalina.startup.Bootstrap.load(Bootstrap.java:311)
	at org.apache.catalina.startup.Bootstrap.main(Bootstrap.java:494)

09-May-2019 16:29:53.401 SEVERE [main] org.apache.catalina.core.StandardService.initInternal Failed to initialize connector [Connector[AJP/1.3-8009]]
 org.apache.catalina.LifecycleException: Failed to initialize component [Connector[AJP/1.3-8009]]
	at org.apache.catalina.util.LifecycleBase.init(LifecycleBase.java:112)
	at org.apache.catalina.core.StandardService.initInternal(StandardService.java:549)
	at org.apache.catalina.util.LifecycleBase.init(LifecycleBase.java:107)
	at org.apache.catalina.core.StandardServer.initInternal(StandardServer.java:873)
	at org.apache.catalina.util.LifecycleBase.init(LifecycleBase.java:107)
	at org.apache.catalina.startup.Catalina.load(Catalina.java:606)
	at org.apache.catalina.startup.Catalina.load(Catalina.java:629)
	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.lang.reflect.Method.invoke(Method.java:498)
	at org.apache.catalina.startup.Bootstrap.load(Bootstrap.java:311)
	at org.apache.catalina.startup.Bootstrap.main(Bootstrap.java:494)
Caused by: org.apache.catalina.LifecycleException: Protocol handler initialization failed
	at org.apache.catalina.connector.Connector.initInternal(Connector.java:946)
	at org.apache.catalina.util.LifecycleBase.init(LifecycleBase.java:107)
	... 12 more
Caused by: java.net.BindException: Address already in use
	at sun.nio.ch.Net.bind0(Native Method)
	at sun.nio.ch.Net.bind(Net.java:433)
	at sun.nio.ch.Net.bind(Net.java:425)
	at sun.nio.ch.ServerSocketChannelImpl.bind(ServerSocketChannelImpl.java:223)
	at sun.nio.ch.ServerSocketAdaptor.bind(ServerSocketAdaptor.java:74)
	at org.apache.tomcat.util.net.NioEndpoint.bind(NioEndpoint.java:228)
	at org.apache.tomcat.util.net.AbstractEndpoint.init(AbstractEndpoint.java:866)
	at org.apache.tomcat.util.net.AbstractJsseEndpoint.init(AbstractJsseEndpoint.java:213)
	at org.apache.coyote.AbstractProtocol.init(AbstractProtocol.java:575)
	at org.apache.catalina.connector.Connector.initInternal(Connector.java:944)
	... 13 more

suggesting Tomcat is already running (?), and

ERROR: Error creating bundle cache.
java.lang.Exception: Unable to create bundle cache lock file: java.io.FileNotFoundException: /opt/lucee/tomcat/lucee-server/felix-cache/cache.lock (Permission denied)
	at org.apache.felix.framework.cache.BundleCache.<init>(BundleCache.java:172)
	at org.apache.felix.framework.Felix.init(Felix.java:699)
	at org.apache.felix.framework.Felix.init(Felix.java:637)
	at org.apache.felix.framework.Felix.start(Felix.java:1080)
	at lucee.loader.engine.CFMLEngineFactory.getFelix(CFMLEngineFactory.java:487)
	at lucee.loader.osgi.BundleLoader.loadBundles(BundleLoader.java:104)
	at lucee.loader.engine.CFMLEngineFactory.initEngine(CFMLEngineFactory.java:358)
	at lucee.loader.engine.CFMLEngineFactory.initEngineIfNecessary(CFMLEngineFactory.java:261)
	at lucee.loader.engine.CFMLEngineFactory.getInstance(CFMLEngineFactory.java:167)
	at lucee.loader.engine.CFMLEngineFactory.getInstance(CFMLEngineFactory.java:201)
	at lucee.loader.servlet.CFMLServlet.init(CFMLServlet.java:42)
	at org.apache.catalina.core.StandardWrapper.initServlet(StandardWrapper.java:1183)
	at org.apache.catalina.core.StandardWrapper.loadServlet(StandardWrapper.java:1099)
	at org.apache.catalina.core.StandardWrapper.load(StandardWrapper.java:989)
	at org.apache.catalina.core.StandardContext.loadOnStartup(StandardContext.java:4913)
	at org.apache.catalina.core.StandardContext.startInternal(StandardContext.java:5223)
	at org.apache.catalina.util.LifecycleBase.start(LifecycleBase.java:150)
	at org.apache.catalina.core.ContainerBase$StartChild.call(ContainerBase.java:1403)
	at org.apache.catalina.core.ContainerBase$StartChild.call(ContainerBase.java:1393)
	at java.util.concurrent.FutureTask.run(FutureTask.java:266)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
	at java.lang.Thread.run(Thread.java:745)
java.lang.NullPointerException
	at lucee.loader.osgi.BundleUtil.installBundle(BundleUtil.java:76)
	at lucee.loader.osgi.BundleUtil.addBundle(BundleUtil.java:68)
	at lucee.loader.osgi.BundleUtil.addBundle(BundleUtil.java:47)
	at lucee.loader.osgi.BundleLoader.loadBundles(BundleLoader.java:141)
	at lucee.loader.engine.CFMLEngineFactory.initEngine(CFMLEngineFactory.java:358)
	at lucee.loader.engine.CFMLEngineFactory.initEngineIfNecessary(CFMLEngineFactory.java:261)
	at lucee.loader.engine.CFMLEngineFactory.getInstance(CFMLEngineFactory.java:167)
	at lucee.loader.engine.CFMLEngineFactory.getInstance(CFMLEngineFactory.java:201)
	at lucee.loader.servlet.CFMLServlet.init(CFMLServlet.java:42)
	at org.apache.catalina.core.StandardWrapper.initServlet(StandardWrapper.java:1183)
	at org.apache.catalina.core.StandardWrapper.loadServlet(StandardWrapper.java:1099)
	at org.apache.catalina.core.StandardWrapper.load(StandardWrapper.java:989)
	at org.apache.catalina.core.StandardContext.loadOnStartup(StandardContext.java:4913)
	at org.apache.catalina.core.StandardContext.startInternal(StandardContext.java:5223)
	at org.apache.catalina.util.LifecycleBase.start(LifecycleBase.java:150)
	at org.apache.catalina.core.ContainerBase$StartChild.call(ContainerBase.java:1403)
	at org.apache.catalina.core.ContainerBase$StartChild.call(ContainerBase.java:1393)
	at java.util.concurrent.FutureTask.run(FutureTask.java:266)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
	at java.lang.Thread.run(Thread.java:745)
09-May-2019 16:29:54.273 SEVERE [wwwdev.gwc.org.uk-startStop-1] org.apache.catalina.core.StandardContext.loadOnStartup Servlet [CFMLServlet] in web application [] threw load() exception
 java.lang.NullPointerException
	at lucee.loader.osgi.BundleUtil.installBundle(BundleUtil.java:76)
	at lucee.loader.osgi.BundleUtil.addBundle(BundleUtil.java:68)
	at lucee.loader.osgi.BundleUtil.addBundle(BundleUtil.java:47)
	at lucee.loader.osgi.BundleLoader.loadBundles(BundleLoader.java:141)
	at lucee.loader.engine.CFMLEngineFactory.initEngine(CFMLEngineFactory.java:358)
	at lucee.loader.engine.CFMLEngineFactory.initEngineIfNecessary(CFMLEngineFactory.java:261)
	at lucee.loader.engine.CFMLEngineFactory.getInstance(CFMLEngineFactory.java:167)
	at lucee.loader.engine.CFMLEngineFactory.getInstance(CFMLEngineFactory.java:201)
	at lucee.loader.servlet.CFMLServlet.init(CFMLServlet.java:42)
	at org.apache.catalina.core.StandardWrapper.initServlet(StandardWrapper.java:1183)
	at org.apache.catalina.core.StandardWrapper.loadServlet(StandardWrapper.java:1099)
	at org.apache.catalina.core.StandardWrapper.load(StandardWrapper.java:989)
	at org.apache.catalina.core.StandardContext.loadOnStartup(StandardContext.java:4913)
	at org.apache.catalina.core.StandardContext.startInternal(StandardContext.java:5223)
	at org.apache.catalina.util.LifecycleBase.start(LifecycleBase.java:150)
	at org.apache.catalina.core.ContainerBase$StartChild.call(ContainerBase.java:1403)
	at org.apache.catalina.core.ContainerBase$StartChild.call(ContainerBase.java:1393)
	at java.util.concurrent.FutureTask.run(FutureTask.java:266)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
	at java.lang.Thread.run(Thread.java:745)

suggesting a permissions problem; I can set everything in /opt/lucee/tomcat/lucee-server to be owned by lucee but a restart reverts ownership of most folders to root (I use sudo to restart Lucee and Tomcat).

After a Tomcat restart, the felix.log shows the same bundles not found. catalina.out shows no errors but does show many warnings e.g.

09-May-2019 16:39:42.291 WARNING [wwwdev.gwc.org.uk-startStop-2] org.apache.catalina.loader.WebappClassLoaderBase.clearReferencesThreads The web application [ROOT] appears to have started a thread named [Thread-629] but has failed to stop it. This is very likely to create a memory leak. Stack trace of thread:
 java.lang.Thread.sleep(Native Method)
 lucee.runtime.schedule.ScheduledTaskThread.sleepEL(ScheduledTaskThread.java:168)
 lucee.runtime.schedule.ScheduledTaskThread._run(ScheduledTaskThread.java:121)
 lucee.runtime.schedule.ScheduledTaskThread.run(ScheduledTaskThread.java:78)
09-May-2019 16:39:42.292 WARNING [wwwdev.gwc.org.uk-startStop-2] org.apache.catalina.loader.WebappClassLoaderBase.clearReferencesThreads The web application [ROOT] appears to have started a thread named [Thread-630] but has failed to stop it. This is very likely to create a memory leak. Stack trace of thread:
 java.lang.Thread.sleep(Native Method)
 lucee.runtime.schedule.ScheduledTaskThread.sleepEL(ScheduledTaskThread.java:168)
 lucee.runtime.schedule.ScheduledTaskThread._run(ScheduledTaskThread.java:121)
 lucee.runtime.schedule.ScheduledTaskThread.run(ScheduledTaskThread.java:78)
09-May-2019 16:39:42.293 WARNING [wwwdev.gwc.org.uk-startStop-2] org.apache.catalina.loader.WebappClassLoaderBase.clearReferencesThreads The web application [ROOT] appears to have started a thread named [Thread-631] but has failed to stop it. This is very likely to create a memory leak. Stack trace of thread:
 java.lang.Thread.sleep(Native Method)
 lucee.runtime.schedule.ScheduledTaskThread.sleepEL(ScheduledTaskThread.java:168)
 lucee.runtime.schedule.ScheduledTaskThread._run(ScheduledTaskThread.java:121)
 lucee.runtime.schedule.ScheduledTaskThread.run(ScheduledTaskThread.java:78)

Anything jumping out???

#6

the scheduledTaskThread cruft can be ignored, there’s an open task about that one

CLONE - scheduled task errors when shutting down tomcat
https://luceeserver.atlassian.net/browse/LDEV-2222

Did you do a custom install or use the linux installer?

#7

Right, thanks…
I used the linux installer.