We have some legacy app bootstrap foo that runs on the first cfml #box-products

We have some legacy app bootstrap foo that runs on...

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

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.

bdw429s

05/11/2022, 4:46 PM

It seems more likely that this is a re-init sort of scenario where ColdBox is doing a tear down/rebuild itself in onRequestStart.

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

sknowlton

05/11/2022, 4:48 PM

I don't think it's doing a teardown/rebuild

bdw429s

05/11/2022, 4:48 PM

very interesting. What version of Lucee are you on?

bdw429s

05/11/2022, 4:49 PM

I know there was at least one fix in 5.3.9 that relates to the app initialization so anything is possible

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

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.

bdw429s

05/11/2022, 4:49 PM

Also, the full stack trace when it errors may help as well

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

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?

sknowlton

05/11/2022, 4:50 PM

It's possible, between the healthcheck and us, but this is a local dev container

sknowlton

05/11/2022, 4:51 PM

I don't see how it's possible for Bootstrap.cfc to be on line 557 and not have cbController

bdw429s

05/11/2022, 4:51 PM

What's on line

Copy code

at application_cfc$cf.udfCall(/Application.cfc:412)

bdw429s

05/11/2022, 4:51 PM

The stack almost makes it look like it's an onsessionstart

sknowlton

05/11/2022, 4:51 PM

It is.

Copy code

public void function onSessionStart() {
		if ( !structKeyExists( application, 'cbBootstrap' ) ) {
			onApplicationStart();
		}
		application.cbBootStrap.onSessionStart();
	}

sknowlton

05/11/2022, 4:51 PM

it's not triggering the if, 412 is just the onSessionStart

bdw429s

05/11/2022, 4:51 PM

Ahh, so that error isn't coming from onrequest!

sknowlton

05/11/2022, 4:51 PM

we have others that are coming from onRequest

sknowlton

05/11/2022, 4:52 PM

They all go away after a couple seconds

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

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

sknowlton

05/11/2022, 4:53 PM

and I should just replace that if/onApplicationStart() with a while() to have it wait for cbBootstrap to finish

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

bdw429s

05/11/2022, 4:54 PM

I wonder if we can create a simple test case that proves stuff goes out of order.

sknowlton

05/11/2022, 4:54 PM

I guess the question is: what should onSessionStart do if cbBootstrap doesn't exist? just return?

sknowlton

05/11/2022, 4:54 PM

say sorry pal, no session for you?

sknowlton

05/11/2022, 4:55 PM

I guess we don't have anything really happening in our onSessionStart

sknowlton

05/11/2022, 4:55 PM

so just whatever Coldbox does with it

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

bdw429s

05/11/2022, 4:55 PM

If ColdBox doesn't actually have an on session start handler, then it's just boilerplate

bdw429s

05/11/2022, 4:57 PM

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

bdw429s

05/11/2022, 4:57 PM

In other words, they should check and ensure the framework isn't in mid-reinit just like onRequest does.

bdw429s

05/11/2022, 4:57 PM

Just on the off chance coldbox is somehow mid-reinit, even though you've said it shouldn't be

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

sknowlton

05/11/2022, 4:58 PM

I think we were causing it to reinit when any session tried to start before the original init was totally done

bdw429s

05/11/2022, 4:58 PM

That would make sense

bdw429s

05/11/2022, 4:58 PM

even though I don't THINK a session should be allowed to start until the app is up

bdw429s

05/11/2022, 4:59 PM

I'm doing a quick test to see if I can get them to fire out of order

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

wil-shiftinsert

05/11/2022, 5:26 PM

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

bdw429s

05/11/2022, 5:29 PM

ooh, that's an interesting combination

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

wil-shiftinsert

05/11/2022, 5:33 PM

https://ortussolutions.atlassian.net/browse/COLDBOX-1094

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

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.

wil-shiftinsert

05/11/2022, 5:36 PM

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.

sknowlton

05/11/2022, 5:37 PM

yeah, because of how Hibernate loads before everything. reason 553 I don't miss Hibernate

bdw429s

05/11/2022, 5:38 PM

@sknowlton Is hibernate active on the app in question where you're seeing this?

sknowlton

05/11/2022, 5:38 PM

Yes

sknowlton

05/11/2022, 5:38 PM

Not super active anymore, but ... not dead yet

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.

wil-shiftinsert

05/11/2022, 5:40 PM

If you have some active ORM event handler it could cause some nasty side effects. Or just break without a decent error message.

sknowlton

05/11/2022, 5:40 PM

That's not what's breaking, though, and we don't have any custom event handlers

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

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.

bdw429s

05/11/2022, 5:44 PM

There must be another piece to the puzzle

sknowlton

05/11/2022, 5:45 PM

it's cause you named the application

brad

. it's just doing everything too quickly

✅ 1

sknowlton

05/11/2022, 5:45 PM

name it

sknowlton

and it'll laze around, firing random requests and promoting entropy

👍 1

bdw429s

05/11/2022, 5:46 PM

Looks like Pothys' repro case did include ORM event handlers https://github.com/lucee/Lucee/pull/1605/files#diff-baeb0543fbfff4e06de8e05211b34a6cc4e3965efc3143dd12dbcd13dd2953df

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

wil-shiftinsert

05/11/2022, 5:50 PM

I saw Luis fixed the coldbox side for the orm stuff. So don’t try that on new box versions 🙂

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

wil-shiftinsert

05/11/2022, 5:57 PM

Maybe it is specific to certain Lucee versions. Interesting that you can set session variables….

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?

Open in Slack

Previous Next