Adam Cameron's Dev Blog: CFML: Preventing onApplicationStart from kicking off whilst onApplicationEnd is still running

G'day:
This is a follow-up from yesterday's article discussing that onApplicationStart() will run quite happily whilst onApplicationEnd() is still working. The person on Stackoverflow - rhinds - was trying to use locking to force the processes to queue-up, but was having issues. I volunteered to look into it further. And I have.

Here's a rough facsimile of what I was expecting the person was trying to do:

// Application.cfc
component {

    this.name = "lockApplicationScope4";
    this.applicationTimeout        = createTimespan(0,0,2,0);
    variables.sleepDuration        = 3000;
    sleep(variables.sleepDuration);


    function onApplicationStart(){
        logIt("Begin onApplicationStart()");
        logIt("Before lock onApplicationStart()");
        lock scope="application" type="exclusive" timeout=variables.sleepDuration/100 {
            logIt("Top of lock onApplicationStart()");
            sleep(variables.sleepDuration);
            logIt("Mid onApplicationStart()");
            sleep(variables.sleepDuration);
            logIt("Bottom of lock onApplicationStart()");
        }
        logIt("After lock onApplicationStart()");
        logIt("End onApplicationStart()");
    }

    function onRequestStart(){
        logIt("Begin onRequestStart()");
    }

    function onRequest(){
        include arguments[1];
    }

    function onRequestEnd(){
        sleep(variables.sleepDuration);
        logIt("End onRequestEnd()");
    }

    function onApplicationEnd(){
        logIt("Begin onApplicationEnd()");
        logIt("Before lock onApplicationEnd()");

        lock scope="application" type="exclusive" timeout=variables.sleepDuration/100 {
            logIt("Top of lock onApplicationEnd()");
            sleep(variables.sleepDuration * 3); // need some time to react
            logIt("Mid onApplicationEnd()");
            sleep(variables.sleepDuration * 3); // need some time to react
            logIt("Bottom of lock onApplicationEnd()");
        }
        logIt("End onApplicationEnd()");
    }
    
    function logIt(required String message){
        writeLog(file=this.name, text="#message# from @ #listLast(CGI.script_name, '/\')#");
    }

}

A lot of that is just telemetry-gathering so I can watch what's happening as it happens. The key bits are highlighted: I'm putting an exclusive application-scope lock on the code in onApplicationStart() and onApplicationEnd() so that the two won't run simultaneously.

My test code was much the same as yesterday:

<!--- normalRequest.cfm --->
<cfset logIt("Start requested template")>
<cfoutput>#now()#</cfoutput>

<!--- shutdownRequest.cfm --->
<cfset logIt("Start requested template")>
<cfoutput>#now()#</cfoutput>
<cfset applicationStop()>
<cfset logIt("End requested template")>

The test is run as follows:

hit normalRequest.cfm to "warm" the application. I let this run to conclusion.
Hit shutdownRequest.cfm, and after a few seconds whilst it's still running...
hit normalRequest.cfm again.

What happens here is that normalRequest.cfm will start the application up; then the call to shutdownRequest.cfm will call applicationStop() to commence application shutdown, but whilst that's happening, a concurrent call to normalRequest.cfm comes in and commences application startup again. Yesterday we saw that onApplicationStart() will start running whilst onApplicationEnd() is still running, which could cause "unexpected results". We're trying to mitigate this.

Here's the log from a test run:

Begin onApplicationStart() from @ normalRequest.cfm
Before lock onApplicationStart() from @ normalRequest.cfm
Top of lock onApplicationStart() from @ normalRequest.cfm
Mid onApplicationStart() from @ normalRequest.cfm
Bottom of lock onApplicationStart() from @ normalRequest.cfm
After lock onApplicationStart() from @ normalRequest.cfm
End onApplicationStart() from @ normalRequest.cfm
Begin onRequestStart() from @ normalRequest.cfm
Start requested template from @ normalRequest.cfm
End onRequestEnd() from @ normalRequest.cfm
Begin onRequestStart() from @ shutdownRequest.cfm
Start requested template from @ shutdownRequest.cfm
Begin onApplicationEnd() from @ shutdownRequest.cfm
Before lock onApplicationEnd() from @ shutdownRequest.cfm
End requested template from @ shutdownRequest.cfm
Begin onApplicationStart() from @ normalRequest.cfm
Before lock onApplicationStart() from @ normalRequest.cfm
Top of lock onApplicationStart() from @ normalRequest.cfm
End onRequestEnd() from @ shutdownRequest.cfm
Mid onApplicationStart() from @ normalRequest.cfm
Bottom of lock onApplicationStart() from @ normalRequest.cfm
After lock onApplicationStart() from @ normalRequest.cfm
End onApplicationStart() from @ normalRequest.cfm
Begin onRequestStart() from @ normalRequest.cfm
Start requested template from @ normalRequest.cfm
End onRequestEnd() from @ normalRequest.cfm

Something's up here. onApplicationEnd() is never getting into the lock. It looked to me like it was erroring but there was nothing in the log.

So I hastily changed onApplicationEnd() to do my own logging:

function onApplicationEnd(){
    logIt("Begin onApplicationEnd()");
    logIt("Before lock onApplicationEnd()");
    try {
        lock scope="application" type="exclusive" timeout=variables.sleepDuration/100 {
            logIt("Top of lock onApplicationEnd()");
            sleep(variables.sleepDuration * 3); // need some time to react
            logIt("Mid onApplicationEnd()");
            sleep(variables.sleepDuration * 3); // need some time to react
            logIt("Bottom of lock onApplicationEnd()");
        }
    }
    catch (any e){
        logIt("Exception in onApplicationEnd(): #e.message# #e.detail#");
    }
    logIt("End onApplicationEnd()");
}

And repeating the experiment, we see this (just the relevant bit):

Begin onApplicationEnd() from @ shutdownRequest.cfm
Before lock onApplicationEnd() from @ shutdownRequest.cfm
Exception in onApplicationEnd(): Cannot lock application scope. Cannot use cflock to lock the application or session shared scopes without these scopes using the cfapplication tag. To use the session scope, you must enable session management. Application and/or Session variables must also be enabled in the ColdFusion Administrator. from @ shutdownRequest.cfm
End onApplicationEnd() from @ shutdownRequest.cfm
So that explains that, and it kinda makes sense. Bear in mind that this is running in onApplicationEnd(), so the application scope is gone by the time this code runs.

So to do what rhinds wanted to effect, instead of using a scope lock, we can use a named lock quite safely here. IE:

function onApplicationStart(){
    logIt("Begin onApplicationStart()");
    logIt("Before lock onApplicationStart()");
    lock name="applicationEventHandlers" type="exclusive" timeout=variables.sleepDuration/100 {
        logIt("Top of lock onApplicationStart()");
        sleep(variables.sleepDuration);
        logIt("Mid onApplicationStart()");
        sleep(variables.sleepDuration);
        logIt("Bottom of lock onApplicationStart()");
    }
    logIt("After lock onApplicationStart()");
    logIt("End onApplicationStart()");
}

// ...

function onApplicationEnd(){
    logIt("Begin onApplicationEnd()");
    logIt("Before lock onApplicationEnd()");
    try {
        lock name="applicationEventHandlers" type="exclusive" timeout=variables.sleepDuration/100 {
            logIt("Top of lock onApplicationEnd()");
            sleep(variables.sleepDuration * 3); // need some time to react
            logIt("Mid onApplicationEnd()");
            sleep(variables.sleepDuration * 3); // need some time to react
            logIt("Bottom of lock onApplicationEnd()");
        }
    }
    catch (any e){
        logIt("Exception in onApplicationEnd(): #e.message# #e.detail#");
    }
    logIt("End onApplicationEnd()");
}

And now, running this, we get what we want:

Begin onRequestStart() from @ shutdownRequest.cfm
Start requested template from @ shutdownRequest.cfm
Begin onApplicationEnd() from @ shutdownRequest.cfm
Before lock onApplicationEnd() from @ shutdownRequest.cfm
Top of lock onApplicationEnd() from @ shutdownRequest.cfm
Begin onApplicationStart() from @ normalRequest.cfm
Before lock onApplicationStart() from @ normalRequest.cfm
Mid onApplicationEnd() from @ shutdownRequest.cfm
Bottom of lock onApplicationEnd() from @ shutdownRequest.cfm
End onApplicationEnd() from @ shutdownRequest.cfm
Top of lock onApplicationStart() from @ normalRequest.cfm
End requested template from @ shutdownRequest.cfm
End onRequestEnd() from @ shutdownRequest.cfm
Mid onApplicationStart() from @ normalRequest.cfm
Bottom of lock onApplicationStart() from @ normalRequest.cfm
After lock onApplicationStart() from @ normalRequest.cfm
End onApplicationStart() from @ normalRequest.cfm
Begin onRequestStart() from @ normalRequest.cfm
Start requested template from @ normalRequest.cfm
End onRequestEnd() from @ normalRequest.cfm
This was hard to colour-code sensibly but the green is the shutdown request, and the orange the following "restart" request. Within that, we can see the red text shows all the internals of onApplicationEnd() being run before the blue text that is onApplicationStart(). it all runs in series, so that's the result we want. Sorted.

So the work-around for this issue with onApplicationStart() and onApplicationEnd() running concurrently is to use a named lock.

Oh. And why did the error that we got when trying to lock the application scope in onApplicationEnd() not show up in the error log? because of this: 3041747. I even knew about that. It'd slipped my mind though. It'd be nice if Adobe - who apparently "didn't have time" to fix it - cracked on and found the time to sort that out.

--
Adam

Adam Cameron's Dev Blog

Tuesday, 9 April 2013

CFML: Preventing `onApplicationStart` from kicking off whilst `onApplicationEnd` is still running