CFML: onApplicationStart will run whilst onApplicationEnd is still underway

G'day:
This is another article which comes on the back of research stemming from not knowing the answer to a Stackoverflow question. In this case the questioner had noticed that onApplicationStart() seems to re-run (so the application is restarting) whilst onApplicationEnd() from a previous application shutdown is still underway.


I figured this would be unfortunately if this was true, so decided to find out.

I knocked out this code:

// Application.cfc
component {

    this.name = "shutdownSequenceTest12";
    logIt("Begin Pseudoconstructor");
    this.applicationTimeout        = createTimespan(0,0,2,0);
    variables.sleepDuration        = 3000;
    sleep(variables.sleepDuration);
    logIt("End Pseudoconstructor");


    function onApplicationStart(){
        logIt("Begin onApplicationStart()");
        sleep(variables.sleepDuration);
        logIt("Mid onApplicationStart()");
        sleep(variables.sleepDuration);
        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()");
        sleep(variables.sleepDuration * 3); // need some time to react
        logIt("Mid onApplicationEnd()");
        sleep(variables.sleepDuration * 3); // need some time to react
        logIt("End onApplicationEnd()");
    }
    
    function logIt(required String message){
        writeLog(file=this.name, text="#message# from @ #listLast(CGI.script_name, '/\')#");
    }

}

This basically emulates an app that takes some time to execute its various stages, so I can interleave requests and see how they run.

I then created two CFM templates:

<!--- 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")>

I use the former to "warm" the application, then use the latter to shut it down. Whilst the shutdown is in progress, I re-run the normalRequest.cfm, to see what happens.

Here's the resultant log file:

Begin Pseudoconstructor from @ normalRequest.cfm
End Pseudoconstructor from @ normalRequest.cfm
Begin onApplicationStart() from @ normalRequest.cfm
Mid 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 Pseudoconstructor from @ shutdownRequest.cfm
End Pseudoconstructor from @ shutdownRequest.cfm
Begin onRequestStart() from @ shutdownRequest.cfm
Start requested template from @ shutdownRequest.cfm
Begin onApplicationEnd() from @ shutdownRequest.cfm
Begin Pseudoconstructor from @ normalRequest.cfm
End Pseudoconstructor from @ normalRequest.cfm
Begin onApplicationStart() from @ normalRequest.cfm
Mid onApplicationStart() from @ normalRequest.cfm
Mid onApplicationEnd() from @ shutdownRequest.cfm
End onApplicationStart() from @ normalRequest.cfm
Begin onRequestStart() from @ normalRequest.cfm
Start requested template from @ normalRequest.cfm
End onRequestEnd() from @ normalRequest.cfm
End onApplicationEnd() from @ shutdownRequest.cfm
End requested template from @ shutdownRequest.cfm
End onRequestEnd() from @ shutdownRequest.cfm


Here the initial warming request is greyed out.

The next request is me requesting a shutdown, and whilst that's still running, I perform another normal request, which commences the application starting again. However the application is still in the process of being shut down from last time. Note that the stop/start event handler processing are intertwined there: the re-start actually finishes before the shutdown of the previous application is complete.

I think this is something to be aware of, and it makes a kind of sense.

Bear in mind that onApplicationStart() and onApplication() end are event handlers, not the events themselves. They do not represent the application starting or the application stopping, they are simply something that ColdFusion will fire off for us when it handles the start/stop process.

So if we were being dogmatic about things, then this is correct behaviour. However in reality, I think it's legitimate for a running onApplicationStop() process should block the next onApplicationStart() process, just like one won't get two almost concurrent requests both trying to run onApplicationStart() each: only the first one runs it, and the second one waits until the first one is done before proceeding (and by then the application is started, so that second request doesn't even try to run onApplicationStart() itself). I think there's a good case for onApplicationStop() to be synchronised with onApplicationStart().

I have not run this on Railo yet, but I will after I walk down to the park to get some coffee.

Thoughts?

Update: I've written a follow-up to this article, which shows how to resolve this issue.

--
Adam