http://coldfusion.com logo
Join Slack
Powered by
Upgraded Lucee from 5.3.9 to 5.3.10 on a dev serve...
# lucee
d
Upgraded Lucee from 5.3.9 to 5.3.10 on a dev server and have noticed that the server takes much longer to start. We use the web.cfc to 'warm' the instance and an internal URL we call from the web.cfc throws 
Bad Gateway (502)
. The Lucee admin is also not available for some minutes, but if I wait for that to become available, then I call our refresh URL, everything works fine. Instance is running under Commandbox 5.7 on Windows. More logging info in thread....
Logging from web.cfc
Copy code
"INFO","on-start-1","01/01/2023","08:58:28","","Lucee starting instance"
"INFO","on-start-1","01/01/2023","08:58:31","","Check <http://myurl.com/index.cfm|myurl.com/index.cfm> returned: Bad Gateway (502)"
"INFO","on-start-1","01/01/2023","08:58:31","","Calling the refresh url because it seems the site borked"
"INFO","on-start-1","01/01/2023","08:58:32","","Refresh URL returned: Bad Gateway (502)"
from server/application.log
Copy code
"DEBUG","main","01/01/2023","08:58:26","OSGi","Start bundle: [org.lucee.ehcache:2.10.3]"
"INFO","main","01/01/2023","08:58:26","startup","touched monitors"
"INFO","main","01/01/2023","08:58:26","startup","Start CFML Controller"
"INFO","main","01/01/2023","08:58:26","add-event-listener","UT010041: The servlet context has already been initialized, you can only call this method from a ServletContainerInitializer or a ServletContextListener;java.lang.IllegalStateException: UT010041: The servlet context has already been initialized, you can only call this method from a ServletContainerInitializer or a ServletContextListener
	at io.undertow.servlet.spec.ServletContextImpl.ensureNotInitialized(ServletContextImpl.java:1030)
	at io.undertow.servlet.spec.ServletContextImpl.addListener(ServletContextImpl.java:745)
	at lucee.runtime.engine.CFMLEngineImpl.addEventListener(CFMLEngineImpl.java:849)
	at lucee.runtime.engine.CFMLEngineImpl.addServletConfig(CFMLEngineImpl.java:794)
	at lucee.loader.engine.CFMLEngineWrapper.addServletConfig(CFMLEngineWrapper.java:87)
	at lucee.loader.engine.CFMLEngineFactory.getInstance(CFMLEngineFactory.java:169)
	at lucee.loader.engine.CFMLEngineFactory.getInstance(CFMLEngineFactory.java:202)
	at lucee.loader.servlet.LuceeServlet.init(LuceeServlet.java:42)
	at io.undertow.servlet.core.LifecyleInterceptorInvocation.proceed(LifecyleInterceptorInvocation.java:117)
	at io.undertow.servlet.core.ManagedServlet$DefaultInstanceStrategy.start(ManagedServlet.java:309)
	at io.undertow.servlet.core.ManagedServlet.createServlet(ManagedServlet.java:145)
	at io.undertow.servlet.core.DeploymentManagerImpl$2.call(DeploymentManagerImpl.java:588)
	at io.undertow.servlet.core.DeploymentManagerImpl$2.call(DeploymentManagerImpl.java:559)
	at io.undertow.servlet.core.ServletRequestContextThreadSetupAction$1.call(ServletRequestContextThreadSetupAction.java:42)
	at io.undertow.servlet.core.ContextClassLoaderSetupAction$1.call(ContextClassLoaderSetupAction.java:43)
	at io.undertow.servlet.api.LegacyThreadSetupActionWrapper$1.call(LegacyThreadSetupActionWrapper.java:44)
	at io.undertow.servlet.core.DeploymentManagerImpl.start(DeploymentManagerImpl.java:601)
	at runwar.Server.createServletDeployment(Server.java:1360)
	at runwar.Server.startServer(Server.java:527)
	at runwar.Start.main(Start.java:51)
"
"INFO","main","01/01/2023","08:58:26","startup","Lucee was not able to register an event listener with io.undertow.servlet.spec.ServletContextImpl"
"INFO","main","01/01/2023","08:58:26","startup","load Context"
"INFO","main","01/01/2023","08:58:26","startup","got context directory"
"INFO","main","01/01/2023","08:58:26","startup","init factory"
"INFO","main","01/01/2023","09:02:21","startup","loaded config"
"INFO","main","01/01/2023","09:02:21","add-event-listener","UT010041: The servlet context has already been initialized, you can only call this method from a ServletContainerInitializer or a ServletContextListener;java.lang.IllegalStateException: UT010041: The servlet context has already been initialized, you can only call this method from a ServletContainerInitializer or a ServletContextListener
	at io.undertow.servlet.spec.ServletContextImpl.ensureNotInitialized(ServletContextImpl.java:1030)
	at io.undertow.servlet.spec.ServletContextImpl.addListener(ServletContextImpl.java:745)
	at lucee.runtime.engine.CFMLEngineImpl.addEventListener(CFMLEngineImpl.java:849)....
For 5.3.9 I get similar messages, but the timings for the web.cfc logs seems to be later than where the instance is trying to start:
Copy code
"INFO","Thread-60","01/01/2023","09:09:50","","Lucee starting instance"
"INFO","XNIO-1 task-1","01/01/2023","09:09:54","","E:\webs\dev\www\ControlPanel\Server.cfc, "
"INFO","XNIO-1 task-1","01/01/2023","09:09:54","","serverKey: e:\webs\dev\, "
"INFO","XNIO-1 task-1","01/01/2023","09:10:17","","serverKey: e:\webs\dev\, "
"INFO","Thread-60","01/01/2023","09:10:34","","Check <http://myurl.com/index.cfm|myurl.com/index.cfm> returned: OK (200)"
"INFO","Thread-60","01/01/2023","09:10:41","","Check myurl/index.cfm returned: OK (200)"
Copy code
"INFO","main","01/01/2023","09:09:49","startup","Lucee was not able to register an event listener with io.undertow.servlet.spec.ServletContextImpl"
"INFO","main","01/01/2023","09:09:49","startup","load Context"
"INFO","main","01/01/2023","09:09:49","startup","got context directory"
"INFO","main","01/01/2023","09:09:49","startup","init factory"
"INFO","main","01/01/2023","09:09:50","startup","loaded config"
"INFO","main","01/01/2023","09:09:50","add-event-listener","UT010041: The servlet context has already been initialized, you can only call this method from a ServletContainerInitializer or a ServletContextListener;java.lang.IllegalStateException: UT010041: The servlet context has already been initialized, you can only call this method from a ServletContainerInitializer or a ServletContextListener
There arent any timestamps in the commandbox logs, but the time between 
[ERROR] runwar.context: [ERROR] LogFactory: Load of custom hashtable failed
and 
[DEBUG] runwar.server: New servlet context created for [default]
Was approximately 4 minutes
@bdw429s is there some way to get timestamps in the server.out log so I can confirm this?
b
Also, what version of box?
d
5.7
👍 1
b
See if log 4j has a placeholder for time ok the logging pattern
Oh look, it's the first example in my docs, lol
Copy code
server set runwar.args='--log-pattern "[%-5p] %d{dd MMM yyyy HH:mm:ss.SSS} %c: %m%n"'
d
haha..copying and pasting right now....
5.3.9:
Copy code
[INFO ] 01 Jan 2023 09:44:50.337 runwar.context: [INFO] Http service whiteboard started
[ERROR] 01 Jan 2023 09:44:51.147 runwar.context: [ERROR] LogFactory: Load of custom hashtable failed
[DEBUG] 01 Jan 2023 09:44:53.942 runwar.server: New servlet context created for [default]
[DEBUG] 01 Jan 2023 09:44:53.945 runwar.server: started servlet deployment manager
5.3.10:
Copy code
[INFO ] 01 Jan 2023 09:47:04.713 runwar.context: [INFO] Http service whiteboard started
[ERROR] 01 Jan 2023 09:47:05.554 runwar.context: [ERROR] LogFactory: Load of custom hashtable failed
[DEBUG] 01 Jan 2023 09:51:13.309 runwar.server: New servlet context created for [default]
[DEBUG] 01 Jan 2023 09:51:13.310 runwar.server: started servlet deployment manager
Interestingly, if I forget the server, then put it back to 5.3.9:
Copy code
[ERROR] 01 Jan 2023 09:57:32.410 runwar.context: [ERROR] LogFactory: Load of custom hashtable failed
[DEBUG] 01 Jan 2023 09:57:52.947 runwar.server: New servlet context created for [default]
Assuming this is the build time for the instance, e.g. unzipping the WEB-INF etc But on next start:
Copy code
[ERROR] 01 Jan 2023 10:01:55.824 runwar.context: [ERROR] LogFactory: Load of custom hashtable failed
[DEBUG] 01 Jan 2023 10:01:58.572 runwar.server: New servlet context created for [default]
b
Take a stack trace of the jvm while it's booting
It may be trying to download stuff
d
I am not entirely sure how to do that and Google isnt helping 😐
b
I'll not at a pc, but the main thread is waiting to join to another thread, and the thread calling web.cfm is running sleep().
Need to cross reference the lucee source to see what it's doing
d
yeah I put a sleep in the web.cfc to see if it would help, that was before I realised it was a 4 minute gap 🙂
err...ok, so I just disabled the web.cfc and now...
Copy code
[ERROR] 01 Jan 2023 11:00:42.570 runwar.context: [ERROR] LogFactory: Load of custom hashtable failed
[DEBUG] 01 Jan 2023 11:00:45.559 runwar.server: New servlet context created for [default]
So that would suggest that the server start is reliant on the web.cfc completing, which doesnt make sense because I thought the web.cfc was initiated after the web context was available (which is why we use it to run a warmup url)
The timing then makes sense because we call 4 urls, and we do it 5 times with a 10 second gap if they throw an error.
b
Log the errors.
d
Bad Gateway (502)
its got NGINX in front of Lucee, and thats logging this
Copy code
2023/01/01 10:52:40 [error] 8672#6748: *193695 connect() failed (10061: No connection could be made because the target machine actively refused it) while connecting to upstream, client: 127.0.0.1
b
I'm not sure how web.cfm works, but will lucee not respond to external requests until it's started up?
d
Yep, the web.cfc is supposed to be run once the web context is available, weve been using this in production for a couple of years to run the startup stuff for our app
👍 1
Ping @zackster , let me know if this needs a ticket, or further testing as it will block our migration to later versions.
g
Ok I have the same issue on our staging server, now. After upgrading to the latest - thinking it might have helped with a DB issue. It takes FOREVER to be available for requests after a tomcat restart. (I haven't timed it - sorry) In fact it was so bad that I restarted the entire box thinking something else was at play - and still I couldn't load our app. Getting a mix of 502 or 504s depending on when I tried to load the application. The JAVA process is running - but never consumes more than 2% CPU. (normally shows 0.2 or 0.3%) During this "initial" - not working - time.
z
@Dean first up, can you test with the latest 5.3.10 snapshot, we've done some work since the last release on startup config performance after @Mark Drew (he/him) and I did some deep diving testing this out
👍 1
d
Same problem on 5.3.10.116-SNAPSHOT @zackster
Copy code
[ERROR] 06 Jan 2023 10:54:52.041 runwar.context: [ERROR] LogFactory: Load of custom hashtable failed
[DEBUG] 06 Jan 2023 10:59:00.595 runwar.server: New servlet context created for [default]
Same on 5.4.0-SNAPSHOT+27
Copy code
[ERROR] 06 Jan 2023 11:24:07.135 runwar.context: [ERROR] LogFactory: Load of custom hashtable failed
[DEBUG] 06 Jan 2023 11:28:14.808 runwar.server: New servlet context created for [default]
z
ok can you provide a minimal test case to repo?
d
Not sure what you mean by that, but this in 
web.cfc
in the web context directory
Copy code
component {
    public function onWebStart(reload) {
        fileAppend(filepath="#expandPath('{lucee-web}')#\..\..\logs\server.out.txt", data= "#lsDateTimeFormat(now(),"iso")# starting web.cfc#(chr(10))#")
        sleep(120000)
        fileAppend(filepath="#expandPath('{lucee-web}')#\..\..\logs\server.out.txt", data= "#lsDateTimeFormat(now(), "iso")# ending web.cfc#(chr(10))#")
    }
}
produces the following result for 5.3.10
Copy code
[INFO ] 08 Jan 2023 08:39:06.033 runwar.context: [INFO] Http service whiteboard started
[ERROR] 08 Jan 2023 08:39:06.916 runwar.context: [ERROR] LogFactory: Load of custom hashtable failed
2023-01-08T08:39:17+11:00 starting web.cfc
2023-01-08T08:41:17+11:00 ending web.cfc
[DEBUG] 08 Jan 2023 08:41:17.627 runwar.server: New servlet context created for [default]
[DEBUG] 08 Jan 2023 08:41:17.629 runwar.server: started servlet deployment manager
[DEBUG] 08 Jan 2023 08:41:17.629 runwar.server: Direct Buffers: true
and on 5.3.9
Copy code
[INFO ] 08 Jan 2023 08:30:32.267 runwar.context: [INFO] Http service whiteboard started
[ERROR] 08 Jan 2023 08:30:33.142 runwar.context: [ERROR] LogFactory: Load of custom hashtable failed
[DEBUG] 08 Jan 2023 08:30:50.654 runwar.server: New servlet context created for [default]
[DEBUG] 08 Jan 2023 08:30:50.657 runwar.server: started servlet deployment manager
[DEBUG] 08 Jan 2023 08:30:50.657 runwar.server: Direct Buffers: true
2023-01-08T08:30:50+11:00 starting web.cfc
....{bunch of unrelated log entries}....
2023-01-08T08:32:50+11:00 ending web.cfc
Apologies for dragging up an old thread, but I finally got time to write a test case for this. https://github.com/deanmaunder/lucee-docker-test Our 
onWebStart()
needs to have access to the initialised web context, but in 5.3.10 this seems to wait for the 
onWebStart()
to complete before coming up. If I set a rather long sleep, say 2 minutes, I get:
Copy code
lucee-docker-test-lucee5310-1  | [INFO] 2023-03-26T00:57:56Z runwar.context - Start web.cfc
lucee-docker-test-lucee5310-1  | [ERROR] 2023-03-26T00:58:26Z runwar.context - lucee.runtime.exp.NativeException: sleep interrupted
Assuming this is by design for 5.3.10, is it possible to have something like 
onWebContextLoaded()
? @zackster
z
as I mentioned the changes in 5.3.10 were made by @micha to avoid some problems with startup performance and loading configurations, in collaboration with @Mark Drew (he/him) these two methods in 
web.cfc
and 
server.cfc
are as (I think) are only intended to be for the before the context is initialized, so your suggestion makes sense.
d
Yes that makes sense if config needs to be loaded before the context is initialized. Do I need to do anything further to help progress this?
3 Views
Open in Slack
PreviousNext
Powered by