http://coldfusion.com logo
#box-products
Title
# box-products
s

sknowlton

05/11/2022, 4:45 PM
We have some legacy app bootstrap foo that runs on the first
onRequestStart()
the app gets. Sometimes it races ahead of Coldbox bootstrapping and so Wirebox and Coldbox are there but they're not done loading modules. What's the easiest way to say 'hey Coldbox, are you totally done loading everything?' or should we just set some app scope variable in
afterAspectsLoaded()
or someplace like that
b

bdw429s

05/11/2022, 4:46 PM
@sknowlton If ColdBox is bootstrapping in the
onApplicationStart()
, it should be impossible for any
onRequest()
calls to happen until the application is up.
It seems more likely that this is a re-init sort of scenario where ColdBox is doing a tear down/rebuild itself in onRequestStart.
s

sknowlton

05/11/2022, 4:48 PM
That used to be the case but 50 or 60 snapshots of Lucee ago, we noticed it wasn't the case and we started seeing our legacy app stuff which used to wait for Coldbox to just plow ahead. Haven't nailed down exactly where the train ran off the tracks
I don't think it's doing a teardown/rebuild
b

bdw429s

05/11/2022, 4:48 PM
very interesting. What version of Lucee are you on?
I know there was at least one fix in 5.3.9 that relates to the app initialization so anything is possible
s

sknowlton

05/11/2022, 4:49 PM
5.3.9.133, but we started seeing this stuff in the 5.3.9-80 rc or slightly before then
b

bdw429s

05/11/2022, 4:49 PM
Some console logs with timestamps from inside the app start and the on request may be useful to prove if they're going out of order.
Also, the full stack trace when it errors may help as well
s

sknowlton

05/11/2022, 4:50 PM
Here's a piece of one from the container start:
Copy code
OR] runwar.context: lucee.runtime.exp.ExpressionException: key [cbController] doesn't exist
        at lucee.runtime.type.util.StructSupport.invalidKey(StructSupport.java:67)
        at lucee.runtime.type.StructImpl.get(StructImpl.java:139)
        at coldbox.system.bootstrap_cfc$cf.udfCall1(/coldbox/system/Bootstrap.cfc:557)
        at coldbox.system.bootstrap_cfc$cf.udfCall(/coldbox/system/Bootstrap.cfc)
        at lucee.runtime.type.UDFImpl.implementation(UDFImpl.java:112)
        at lucee.runtime.type.UDFImpl._call(UDFImpl.java:350)
        at lucee.runtime.type.UDFImpl.call(UDFImpl.java:223)
        at lucee.runtime.ComponentImpl._call(ComponentImpl.java:697)
        at lucee.runtime.ComponentImpl._call(ComponentImpl.java:585)
        at lucee.runtime.ComponentImpl.call(ComponentImpl.java:1932)
        at lucee.runtime.util.VariableUtilImpl.callFunctionWithoutNamedValues(VariableUtilImpl.java:787)
        at lucee.runtime.PageContextImpl.getFunction(PageContextImpl.java:1762)
        at application_cfc$cf.udfCall(/Application.cfc:412)
        at lucee.runtime.type.UDFImpl.implementation(UDFImpl.java:112)
        at lucee.runtime.type.UDFImpl._call(UDFImpl.java:350)
        at lucee.runtime.type.UDFImpl.call(UDFImpl.java:223)
        at lucee.runtime.ComponentImpl._call(ComponentImpl.java:697)
        at lucee.runtime.ComponentImpl._call(ComponentImpl.java:585)
        at lucee.runtime.ComponentImpl.call(ComponentImpl.java:1932)
        at lucee.runtime.listener.ModernAppListener.call(ModernAppListener.java:444)
        at lucee.runtime.listener.ModernAppListener.onSessionStart(ModernAppListener.java:345)
        at lucee.runtime.PageContextImpl.initApplicationContext(PageContextImpl.java:3182)
        at lucee.runtime.listener.ModernAppListener._onRequest(ModernAppListener.java:122)
        at lucee.runtime.listener.ModernAppListener.onRequest(ModernAppListener.java:107)
        at lucee.runtime.PageContextImpl.execute(PageContextImpl.java:2475)
        at lucee.runtime.PageContextImpl._execute(PageContextImpl.java:2465)
        at lucee.runtime.PageContextImpl.executeCFML(PageContextImpl.java:2436)
        at lucee.runtime.engine.Request.exe(Request.java:45)
        at lucee.runtime.engine.CFMLEngineImpl._service(CFMLEngineImpl.java:1194)
        at lucee.runtime.engine.CFMLEngineImpl.serviceCFML(CFMLEngineImpl.java:1140)
        at lucee.loader.engine.CFMLEngineWrapper.serviceCFML(CFMLEngineWrapper.java:97)
        at lucee.loader.servlet.CFMLServlet.service(CFMLServlet.java:51)
        at javax.servlet.http.HttpServlet.service(HttpServlet.java:590)
        at io.undertow.servlet.handlers.ServletHandler.handleRequest(ServletHandler.java:74)
        at io.undertow.servlet.handlers.FilterHandler$FilterChainImpl.doFilter(FilterHandler.java:129)
        at org.cfmlprojects.regexpathinfofilter.RegexPathInfoFilter.doFilter(RegexPathInfoFilter.java:47)
        at io.undertow.servlet.core.ManagedFilter.doFilter(ManagedFilter.java:61)
        at io.undertow.servlet.handlers.FilterHandler$FilterChainImpl.doFilter(FilterHandler.java:131)
        at io.undertow.servlet.handlers.FilterHandler.handleRequest(FilterHandler.java:84)
        at io.undertow.servlet.handlers.security.ServletSecurityRoleHandler.handleRequest(ServletSecurityRoleHandler.java:62)
        at io.undertow.servlet.handlers.ServletChain$1.handleRequest(ServletChain.java:68)
        at io.undertow.servlet.handlers.ServletDispatchingHandler.handleRequest(ServletDispatchingHandler.java:36)
        at io.undertow.servlet.handlers.RedirectDirHandler.handleRequest(RedirectDirHandler.java:68)
        at io.undertow.server.handlers.PredicateHandler.handleRequest(PredicateHandler.java:43)
        at io.undertow.server.handlers.PredicateHandler.handleRequest(PredicateHandler.java:43)
        at io.undertow.servlet.handlers.ServletInitialHandler.dispatchRequest(ServletInitialHandler.java:257)
        at io.undertow.servlet.handlers.ServletInitialHandler.dispatchToPath(ServletInitialHandler.java:182)
        at io.undertow.servlet.spec.RequestDispatcherImpl.forwardImpl(RequestDispatcherImpl.java:225)
        at io.undertow.servlet.spec.RequestDispatcherImpl.forwardImplSetup(RequestDispatcherImpl.java:147)
        at io.undertow.servlet.spec.RequestDispatcherImpl.forward(RequestDispatcherImpl.java:110)
        at org.cfmlprojects.regexpathinfofilter.RegexPathInfoFilter.doFilter(RegexPathInfoFilter.java:45)
        at io.undertow.servlet.core.ManagedFilter.doFilter(ManagedFilter.java:61)
        at io.undertow.servlet.handlers.FilterHandler$FilterChainImpl.doFilter(FilterHandler.java:131)
        at io.undertow.servlet.handlers.FilterHandler.handleRequest(FilterHandler.java:84)
        at io.undertow.servlet.handlers.security.ServletSecurityRoleHandler.handleRequest(ServletSecurityRoleHandler.java:62)
        at io.undertow.servlet.handlers.ServletChain$1.handleRequest(ServletChain.java:68)
        at io.undertow.servlet.handlers.ServletDispatchingHandler.handleRequest(ServletDispatchingHandler.java:36)
        at io.undertow.servlet.handlers.RedirectDirHandler.handleRequest(RedirectDirHandler.java:68)
        at io.undertow.server.handlers.PredicateHandler.handleRequest(PredicateHandler.java:43)
        at io.undertow.server.handlers.PredicateHandler.handleRequest(PredicateHandler.java:43)
        at io.undertow.servlet.handlers.ServletInitialHandler.dispatchRequest(ServletInitialHandler.java:257)
        at io.undertow.servlet.handlers.ServletInitialHandler.dispatchToPath(ServletInitialHandler.java:182)
        at io.undertow.servlet.spec.RequestDispatcherImpl.forwardImpl(RequestDispatcherImpl.java:225)
        at io.undertow.servlet.spec.RequestDispatcherImpl.forwardImplSetup(RequestDispatcherImpl.java:147)
        at io.undertow.servlet.spec.RequestDispatcherImpl.forward(RequestDispatcherImpl.java:110)
        at org.tuckey.web.filters.urlrewrite.NormalRewrittenUrl.doRewrite(NormalRewrittenUrl.java:215)
        at org.tuckey.web.filters.urlrewrite.RuleChain.handleRewrite(RuleChain.java:171)
        at org.tuckey.web.filters.urlrewrite.RuleChain.doRules(RuleChain.java:145)
        at org.tuckey.web.filters.urlrewrite.UrlRewriter.processRequest(UrlRewriter.java:92)
        at org.tuckey.web.filters.urlrewrite.UrlRewriteFilter.doFilter(UrlRewriteFilter.java:405)
        at io.undertow.servlet.core.ManagedFilter.doFilter(ManagedFilter.java:61)
        at io.undertow.servlet.handlers.FilterHandler$FilterChainImpl.doFilter(FilterHandler.java:131)
        at io.undertow.servlet.handlers.FilterHandler.handleRequest(FilterHandler.java:84)
        at io.undertow.servlet.handlers.security.ServletSecurityRoleHandler.handleRequest(ServletSecurityRoleHandler.java:62)
        at io.undertow.servlet.handlers.ServletChain$1.handleRequest(ServletChain.java:68)
        at io.undertow.servlet.handlers.ServletDispatchingHandler.handleRequest(ServletDispatchingHandler.java:36)
        at io.undertow.servlet.handlers.RedirectDirHandler.handleRequest(RedirectDirHandler.java:68)
        at io.undertow.servlet.handlers.security.SSLInformationAssociationHandler.handleRequest(SSLInformationAssociationHandler.java:117)
        at io.undertow.servlet.handlers.security.ServletAuthenticationCallHandler.handleRequest(ServletAuthenticationCallHandler.java:57)
        at io.undertow.server.handlers.PredicateHandler.handleRequest(PredicateHandler.java:43)
        at io.undertow.security.handlers.AbstractConfidentialityHandler.handleRequest(AbstractConfidentialityHandler.java:46)
        at io.undertow.servlet.handlers.security.ServletConfidentialityConstraintHandler.handleRequest(ServletConfidentialityConstraintHandler.java:64)
        at io.undertow.security.handlers.AuthenticationMechanismsHandler.handleRequest(AuthenticationMechanismsHandler.java:60)
        at io.undertow.servlet.handlers.security.CachedAuthenticatedSessionHandler.handleRequest(CachedAuthenticatedSessionHandler.java:77)
        at io.undertow.security.handlers.AbstractSecurityContextAssociationHandler.handleRequest(AbstractSecurityContextAssociationHandler.java:43)
        at io.undertow.server.handlers.PredicateHandler.handleRequest(PredicateHandler.java:43)
        at io.undertow.servlet.handlers.SendErrorPageHandler.handleRequest(SendErrorPageHandler.java:52)
        at io.undertow.server.handlers.PredicateHandler.handleRequest(PredicateHandler.java:43)
        at io.undertow.servlet.handlers.ServletInitialHandler.handleFirstRequest(ServletInitialHandler.java:275)
        at io.undertow.servlet.handlers.ServletInitialHandler.access$100(ServletInitialHandler.java:79)
        at io.undertow.servlet.handlers.ServletInitialHandler$2.call(ServletInitialHandler.java:134)
        at io.undertow.servlet.handlers.ServletInitialHandler$2.call(ServletInitialHandler.java:131)
        at io.undertow.servlet.core.Serv
b

bdw429s

05/11/2022, 4:50 PM
Is it possible there are two requests hitting the server at the same time, or can you reproduce it in a vacuum with only a single hit?
s

sknowlton

05/11/2022, 4:50 PM
It's possible, between the healthcheck and us, but this is a local dev container
I don't see how it's possible for Bootstrap.cfc to be on line 557 and not have cbController
b

bdw429s

05/11/2022, 4:51 PM
What's on line
Copy code
at application_cfc$cf.udfCall(/Application.cfc:412)
The stack almost makes it look like it's an onsessionstart
s

sknowlton

05/11/2022, 4:51 PM
It is.
Copy code
public void function onSessionStart() {
		if ( !structKeyExists( application, 'cbBootstrap' ) ) {
			onApplicationStart();
		}
		application.cbBootStrap.onSessionStart();
	}
it's not triggering the if, 412 is just the onSessionStart
b

bdw429s

05/11/2022, 4:51 PM
Ahh, so that error isn't coming from onrequest!
s

sknowlton

05/11/2022, 4:51 PM
we have others that are coming from onRequest
They all go away after a couple seconds
b

bdw429s

05/11/2022, 4:52 PM
So the question is whether or not Lucee makes the onrequeststart method wait fo rthe app to be initialized
s

sknowlton

05/11/2022, 4:52 PM
Maybe something is triggering the session prior to the bootstrap being finished and it is doing a teardown/rebuild from that if
and I should just replace that if/onApplicationStart() with a while() to have it wait for cbBootstrap to finish
b

bdw429s

05/11/2022, 4:53 PM
You'd have to be careful with a while--- if there is a legit issue with the app coming up, you'll have threads that hang forever
I wonder if we can create a simple test case that proves stuff goes out of order.
s

sknowlton

05/11/2022, 4:54 PM
I guess the question is: what should onSessionStart do if cbBootstrap doesn't exist? just return?
say sorry pal, no session for you?
I guess we don't have anything really happening in our onSessionStart
so just whatever Coldbox does with it
b

bdw429s

05/11/2022, 4:55 PM
It could just not make the call, but of course, that means if you have important logic in your COldBox on sessions start handler, you could get an incomplete session
If ColdBox doesn't actually have an on session start handler, then it's just boilerplate
On a related note, I would probably consider it a bug that ColdBox's session start/end handlers don't have the fail fast logic in them
In other words, they should check and ensure the framework isn't in mid-reinit just like onRequest does.
Just on the off chance coldbox is somehow mid-reinit, even though you've said it shouldn't be
s

sknowlton

05/11/2022, 4:57 PM
got no errors when I took out that 'maybe re-bootstrap Coldbox in onSessionStart' call, but not sure we were getting errors 100% of the time previously. Will keep an eye on it, this is one of those moles that only pops up every so often so it hasn't had much attention on it before now
👍 1
I think we were causing it to reinit when any session tried to start before the original init was totally done
b

bdw429s

05/11/2022, 4:58 PM
That would make sense
even though I don't THINK a session should be allowed to start until the app is up
I'm doing a quick test to see if I can get them to fire out of order
w

wil-shiftinsert

05/11/2022, 5:16 PM
I have seen that behaviour before, i.e. a session start before the application is started
👍 1
Ok now I remember. If you create some object in application.cfc and access the application scope in the constructor of this object, it will fire onsessionstart or onrequeststart before the application has been started. We had this scenario with the cborm event handler. https://luceeserver.atlassian.net/browse/LDEV-3883
b

bdw429s

05/11/2022, 5:29 PM
ooh, that's an interesting combination
w

wil-shiftinsert

05/11/2022, 5:30 PM
There’s also a cborm or coldbox bug for that, Not sure if we should blame coldbox or cborm or lucee
s

sknowlton

05/11/2022, 5:33 PM
Can anybody articulate a use case for why, inside of Application.cfc, you reference the application scope, that should trigger a session or request? It seems counter-intuitive
w

wil-shiftinsert

05/11/2022, 5:34 PM
Sam, I totally agree. But this is exactly what the ORMEventhandler does since coldbox 6.5. I am just reading how Luis fixed this bug.
I spent several days finding out why cborm was broken. It was only some stupid test project to compare quick and cborm, but I couldn’t understand. And the cborm event handler has to be defined before coldbox starts.
s

sknowlton

05/11/2022, 5:37 PM
yeah, because of how Hibernate loads before everything. reason 553 I don't miss Hibernate
b

bdw429s

05/11/2022, 5:38 PM
@sknowlton Is hibernate active on the app in question where you're seeing this?
s

sknowlton

05/11/2022, 5:38 PM
Yes
Not super active anymore, but ... not dead yet
w

wil-shiftinsert

05/11/2022, 5:39 PM
There are plenty of reasons to hate hibernate. I could say the same for all bugs and performance problems I had in some other modules.
If you have some active ORM event handler it could cause some nasty side effects. Or just break without a decent error message.
s

sknowlton

05/11/2022, 5:40 PM
That's not what's breaking, though, and we don't have any custom event handlers
w

wil-shiftinsert

05/11/2022, 5:41 PM
Well, than that’s not causing out of order session and applicationstart. Just mentioning it is possible, because we wasted a lot of time on it. And I think it is a Lucee bug. I think it shouldn’t be allowed and need some proper exceptions
b

bdw429s

05/11/2022, 5:44 PM
Man, I can't seem to get a repro for this. I created this
Application.cfc
Copy code
component {

    this.name='brad';
    this.sessionManagement=true;

    function onApplicationStart() {
        systemoutput( 'onApplicationStart(): #getTickCount()#', 1 )

        new myClass();

        sleep(5000);
        
        systemoutput( 'onApplicationStart() DONE: #getTickCount()#', 1 )
    }

    function onRequestStart() {
        systemoutput( 'onRequestStart(): #getTickCount()#', 1 )
    }

    function onSessionStart() {
        systemoutput( 'onSessionStart(): #getTickCount()#', 1 )
    }

}
And then
myClass.cfc
is just
Copy code
component {

    function init() {
        application.foo = 'bar';
        
        systemoutput( application.foo, 1 );
    }

}
and there is an empty
index.cfm
When I fire two requests starting the app at the same time, I get this
Copy code
[INFO ] onApplicationStart(): 1652290966351
[INFO ] bar
[INFO ] onApplicationStart() DONE: 1652290971369
[INFO ] onSessionStart(): 1652290971389
[INFO ] onSessionStart(): 1652290971390
[INFO ] onRequestStart(): 1652290971396
[INFO ] onRequestStart(): 1652290971397
which would appear everything is waiting for
onApplicationStart()
to finish before proceeding.
There must be another piece to the puzzle
s

sknowlton

05/11/2022, 5:45 PM
it's cause you named the application
brad
. it's just doing everything too quickly
1
name it
sknowlton
and it'll laze around, firing random requests and promoting entropy
👍 1
b

bdw429s

05/11/2022, 5:46 PM
w

wil-shiftinsert

05/11/2022, 5:49 PM
You are creating the myClass inside of the onApplicationStart. If you create this class directly in Application.cfc it will probably fire in the wrong order.
👍 1
I saw Luis fixed the coldbox side for the orm stuff. So don’t try that on new box versions 🙂
b

bdw429s

05/11/2022, 5:55 PM
Moving
Copy code
new myClass();
to the Application.cfc pseudoconstructor didn't do it. I even had it touch the session scope too which is rather interesting since it means it was setting session variables before onSessionStart actually ran! 🤔
😀 1
w

wil-shiftinsert

05/11/2022, 5:57 PM
Maybe it is specific to certain Lucee versions. Interesting that you can set session variables….
s

sknowlton

05/13/2022, 2:31 PM
Reviving this thread with a new symptom of a similar (same?) issue - just brought up a container locally and on the first request got a
The target 'ExplicitCall' requested a missing dependency with a Name of '' and DSL of 'StackSportsService@stackSports'
with the stack trace pointing to
afterAspectsLoad()
in one of our interceptors. The relevant
stackSports
module wasn't loaded yet but it was firing
afterAspectsLoad()
. Am I using the wrong interception point here or is that not supposed to happen?