This is a bit of a funny ("odd" as opposed to "amusing") one today, as I set out to investigate a hypothesis with preconceived expectations, but it turns out the expectations were wrong. But in a good way as it turns out.
A wee while ago - in the weeks leading up to ColdFusion 10's release - I was involved in a discussion about how applicationStop() works, and that it apparently had a moderately serious glitch in it that rendered it not production-ready.
What seemed to be happening was that as soon as applicationStop() was called, it did what it said on the tin: stopped the application. However it did this without any consideration of any requests which might still be running, and they'd possibly error if suddenly the application scope vanished. This could be a risk because applicationStop() only stops the application: it doesn't start it again... It relies on the next incoming request to trigger this. However an already-running request will - in the meantime - not have an application!
I'm an fairly certain I tested this on CF9.0.1 and the beta of CF10, and these concerns were borne-out.
This morning I wrote some test code to demonstrate this to you, and go "oh dear... that's not good, is it?".
Here's the code I used:
That's pretty straight-forward, but let me go over it (and apologies that the code listing is not in the same order as the descriptions below... Gist doesn't preserve the order I entered the files, it sorts them alphabetically. It's better to analyse them in the order I list 'em below.
Application.cfc
onApplicationStart()
This creates a unique key for the application, as well as setting a coupla variables that are inter-related: they have the same timestamp. These are used to check potential race conditions later in the code.It also params a server-scoped variable which I use to track the sequence of requests, independent of the application.
onRequestStart()
This increments the request count and logs that a request had been started, logging the request ID, the file requested, the current timestamp down to the millisecond, and the application ID. This allows easy tracking of the sequence that requests start (and: with a similar entry in onRequestEnd(), when they finish, too).onRequestEnd()
This just logs the same thing as onRequestStart(). This allows us to see how long requests take to run, as well as which requests start during other already-running requests.formattedNow()
I'm using this timestamp string in a few different places, so I've factored it out into a separate method.start.cfm
I just use this to hit the application and start it. I hit it first up, then again immediately after calling stop.cfm. It dumps some telemetry, just to demonstrate everything is running as I expect.stop.cfm
This one just calls applicationStop(), dumping the application scope after the stop, to sere what's in there.long.cfm
This emulates a long request that uses one application scope variable at the beginning, does 10 sec of other stuff, then uses another application scope variable, wherein the application variables are intrinsically related (in this example, they have the same timestamp info). This is to emulate application scope variables that need to be inter-related for the system to have integrity. If during this request the timestamps differ between the two variables, then it's a demonstration we've lsot appliaction integrity during the request. The delay is in there to give me time to call stop.cfm, then start.cfm with a coupla seconds in between. I want to see the effects on this request of the application being stopped and started again whilst it's running.other.cfm
This is the same as long.cfm, script without the delay. I just this just as some other request to run that isn't stopping or starting things, and is readily identifiable in the logs.When running the test, thus is the sequence of events:
- Start ColdFusion
- Hit start.cfm, and let it run
- Hit long.cfm, and whilst it's running...
- ... hit stop.cfm...
- ...and start.cfm...
- ... and other.cfm.
- Then long.cfm finally finishes
What I was expecting was for there to be problems with long.cfm after the application has been restarted.
Here's the output from the various files:
start.cfm
| Started - struct | |
|---|---|
| applicationname | testApplicationStop |
| firstvar | First var using 13:37:24.451<br /> |
| key | 07E97FD5-C963-FC3B-8104D105AF1D5524 |
| secondvar | Second using 13:37:24.451<br /> |
| startedat | 13:37:24.451<br /> |
long.cfm
First var using 13:37:24.451
Second using 13:37:24.451
stop.cfm
| Stopped - struct | |
|---|---|
| applicationname | testApplicationStop |
| firstvar | First var using 13:37:24.451<br /> |
| key | 07E97FD5-C963-FC3B-8104D105AF1D5524 |
| secondvar | Second using 13:37:24.451<br /> |
| startedat | 13:37:24.451<br /> |
start.cfm again
| Started - struct | |
|---|---|
| applicationname | testApplicationStop |
| firstvar | First var using 13:37:32.257<br /> |
| key | 07EAB0C1-FE6B-C3A1-4F4F9BAC8A5FA0EF |
| secondvar | Second using 13:37:32.257<br /> |
| startedat | 13:37:32.257<br /> |
other.cfm
First var using 13:37:32.257
Second using 13:37:32.257
And here's what was logged:
Request 1 of start.cfm started at 13:23:41.397 for application key: 076BE690-A6E4-20B4-89A358404A013484 (076BE690-A6E4-20B4-89A358404A013484)
Request 1 of start.cfm ended at 13:23:42.929 for application key: 076BE690-A6E4-20B4-89A358404A013484 (076BE690-A6E4-20B4-89A358404A013484)
Request 2 of long.cfm started at 13:23:47.271 for application key: 076BE690-A6E4-20B4-89A358404A013484 (076BE690-A6E4-20B4-89A358404A013484)
Request 3 of stop.cfm started at 13:23:49.420 for application key: 076BE690-A6E4-20B4-89A358404A013484 (076BE690-A6E4-20B4-89A358404A013484)
Request 3 of stop.cfm ended at 13:23:49.441 for application key: 076BE690-A6E4-20B4-89A358404A013484 (076BE690-A6E4-20B4-89A358404A013484)
Request 4 of start.cfm started at 13:23:51.219 for application key: 076D66FA-AE07-D41F-B1D24161D6FE9638 (076D66FA-AE07-D41F-B1D24161D6FE9638)
Request 4 of start.cfm ended at 13:23:51.243 for application key: 076D66FA-AE07-D41F-B1D24161D6FE9638 (076D66FA-AE07-D41F-B1D24161D6FE9638)
Request 5 of other.cfm started at 13:23:53.983 for application key: 076D66FA-AE07-D41F-B1D24161D6FE9638 (076D66FA-AE07-D41F-B1D24161D6FE9638)
Request 5 of other.cfm ended at 13:23:53.985 for application key: 076D66FA-AE07-D41F-B1D24161D6FE9638 (076D66FA-AE07-D41F-B1D24161D6FE9638)
Request 2 of long.cfm ended at 13:23:57.281 for application key: 076BE690-A6E4-20B4-89A358404A013484 (076BE690-A6E4-20B4-89A358404A013484)
The bottom line is that everything worked fine. long.cfm ran uninterrupted, and it even maintained the application scoped variables as they were at the start of the request.
ColdFusion is even clever enough for applicationStop() to not be blocked until long.cfm had finished, it stopped the application concurrent with long.cfm continuing. And start.cfm restarting the application did not interfere with long.cfm either. Finally, just for good measure, the subsequent other.cfm request ran fine.
So... err... how had I come to the conclusion there was a problem here before? Maybe Adobe listened to us and fixed it in CF10... so I ran the code on CF9.0.2 add well. Still no problem. I doubt Adobe works have slotted a fix for a CF9.0.1 issue into 9.0.2, which was really just to get rid of Verity, as far add I know.
Hmmmmmm... So my current thinking is that my earlier tests were flawed, and there actually was never a problem. I'm gonna have to see if I can dig out my code from the previous tests, and check it out.
There were a coupla other people involved in this original discussion who I'll tap-up too. One was Dave McGuigan who I know will be reading this, the other I'm not sure knows about these random babblings that I'm blogging: I'll hit 'im up offline and see if he wants to pitch-in.
Even if this turns out to be a "failed" experiment - from the perspective that my hypothesis was disproven - it's good to know that applicationStop() does work the way it does. So this was not a complete waste of my time. And also hopefully not a waste of your time reading all this!
Now... on with my Saturday...
--
Adam
