Overlapping requests will not cause a race condition in a CFM's variables scope

G'day:
This is mostly a follow-up from a Stackoverflow question. The question is based around some confusion arising from a blog article which offers some misinformation about how functions can cause race conditions across two requests simply by not VARing variables, or accessing the variables scope explicitly instead of using a function-local variable. To be very clear from the outset: the blog article is mostly wrong.


The reason I'm writing this up here instead of Stackoverflow is twofold:

• if I'm gonna say someone's writing is wrong, I want to do it here where the editorial purview is mine;
• I put some work into the demo code & testing so I'm claiming it as my own, not Stackoverflow's. Not that the code is earthshattering by any means.
• (OK, three reasons): I can waffle to a degree I feel appropriate here.

The premise of the blog article is that even within a UDF in a CFM file, usage of the variables scope can cause a race condition across two requests because the variables scope reference is in a function, and that somehow works magic that means both requests see the same variable. This is flat-out incorrect, which I image you already know. However I'm not just going to post on Stackoverflow "[cough]bullshit", I want to demonstrate it.

Here's some code within a single CFM file:

<cfflush interval="16">
<cfscript>
    param name="URL.id" default="1";
    
    function foo(){
        variables.foo = now();
        msg("Top of foo(), variables.foo: [#variables.foo#]");
    
        //Do some other processing
        sleep(10000);
    
        msg("Bottom of foo(), variables.foo: [#variables.foo#]");
        return foo;
    }
    
    string function msg(required string message, string id=URL.id){
        var s = "[#timeFormat(now(), 'HH:MM:SS.LLL')#] [#id#] #message#";
        writeLog(file="variablesTestCfm1", text=s);
        writeOutput(s & "<br>");
    }
    
    msg("Begin request");
    msg("Before call to foo()");
    foo();
    msg("After call to foo(), variables.foo: [#variables.foo#]");
</cfscript>

This has a function which addresses the variables scope directly. The function takes 10sec to run, so we can check the value of the variables scope before and after easily across two requests. The msg() function just logs some metrics to screen and log (so both requests' telemetry can be seen separately and in a unified output showing each message as it happened in relation to the other messages.

I run this in two separate browsers, and get this output:

Request 1:
[08:53:36.320] [1] Begin request
[08:53:36.323] [1] Before call to foo()
[08:53:36.324] [1] Top of foo(), variables.foo: [{ts '2013-04-07 08:53:36'}]
[08:53:46.325] [1] Bottom of foo(), variables.foo: [{ts '2013-04-07 08:53:36'}]
[08:53:46.327] [1] After call to foo(), variables.foo: [{ts '2013-04-07 08:53:36'}]

Request 2:
[08:53:39.837] [2] Begin request
[08:53:39.840] [2] Before call to foo()
[08:53:39.842] [2] Top of foo(), variables.foo: [{ts '2013-04-07 08:53:39'}]
[08:53:49.844] [2] Bottom of foo(), variables.foo: [{ts '2013-04-07 08:53:39'}]
[08:53:49.846] [2] After call to foo(), variables.foo: [{ts '2013-04-07 08:53:39'}]

Log:
[08:53:36.320] [1] Begin request
[08:53:36.323] [1] Before call to foo()
[08:53:36.324] [1] Top of foo(), variables.foo: [{ts '2013-04-07 08:53:36'}]
[08:53:39.837] [2] Begin request
[08:53:39.840] [2] Before call to foo()
[08:53:39.842] [2] Top of foo(), variables.foo: [{ts '2013-04-07 08:53:39'}]
[08:53:46.325] [1] Bottom of foo(), variables.foo: [{ts '2013-04-07 08:53:36'}]
[08:53:46.327] [1] After call to foo(), variables.foo: [{ts '2013-04-07 08:53:36'}]
[08:53:49.844] [2] Bottom of foo(), variables.foo: [{ts '2013-04-07 08:53:39'}]
[08:53:49.846] [2] After call to foo(), variables.foo: [{ts '2013-04-07 08:53:39'}]

And it comes as no surprise that request 1's variables.foo is completely different from request 2's one. Neither impact each other in the slightest as they are both stored in different parts of memory.

Next I try a CFC-based version of the test. The CFC is instantiated in the variables scope of each request, so - again - there will be no race condition.  Code:

<!---cfcTestVariablesScope.cfm --->
<cfflush interval="16">
<cfscript>
    param name="URL.id" default="1";
    
    o = new CfcTest();
    
    o.msg("Begin request");
    o.msg("Before call to foo()");
    o.foo();
    o.msg("After call to foo(), variables.foo: [#o.getFoo()#]");
</cfscript>

// CfcTest.cfc
component {

    public date function foo(){
        variables.foo = now();
        msg("Top of foo(), variables.foo: [#variables.foo#]");
    
        //Do some other processing
        sleep(10000);
    
        msg("Bottom of foo(), variables.foo: [#variables.foo#]");
        return foo;
    }
    
    public string function msg(required string message, string id=URL.id){
        var s = "[#timeFormat(now(), 'HH:MM:SS.LLL')#] [#id#] #message#";
        writeLog(file="variablesTestCfc3", text=s);
        writeOutput(s & "<br>");
    }
    
    public date function getFoo(){
        return variables.foo;
    }

}

The functionality here is exactly the same as before, just tweaked to work within a CFC. The test results are identical to the first one, for all intents and purposes, so I will not both repeating them.

The last test I ran puts the CFC instance into the application scope, so clearly now there will be a race condition between the two requests, as they will both be hitting the same object in memory, so the variables scope within the CFC will be the same bit of memory:

<!---cfcTestApplicationScope.cfm--->
<cfflush interval="16">
<cfscript>
    param name="URL.id" default="1";
    
    application.o = new CfcTest();
    
    application.o.msg("Begin request");
    application.o.msg("Before call to foo()");
    application.o.foo();
    application.o.msg("After call to foo(), variables.foo: [#application.o.getFoo()#]");
</cfscript>

Now this time we see the race condition at work:

Request 1:
[09:07:04.325] [1] Begin request
[09:07:04.330] [1] Before call to foo()
[09:07:04.331] [1] Top of foo(), variables.foo: [{ts '2013-04-07 09:07:04'}]
[09:07:14.333] [1] Bottom of foo(), variables.foo: [{ts '2013-04-07 09:07:04'}]
[09:07:14.336] [1] After call to foo(), variables.foo: [{ts '2013-04-07 09:07:09'}]

Request 2:
[09:07:09.827] [2] Begin request
[09:07:09.832] [2] Before call to foo()
[09:07:09.834] [2] Top of foo(), variables.foo: [{ts '2013-04-07 09:07:09'}]
[09:07:19.836] [2] Bottom of foo(), variables.foo: [{ts '2013-04-07 09:07:09'}]
[09:07:19.839] [2] After call to foo(), variables.foo: [{ts '2013-04-07 09:07:09'}]

Log:
[09:07:04.325] [1] Begin request
[09:07:04.330] [1] Before call to foo()
[09:07:04.331] [1] Top of foo(), variables.foo: [{ts '2013-04-07 09:07:04'}]
[09:07:09.827] [2] Begin request
[09:07:09.832] [2] Before call to foo()
[09:07:09.834] [2] Top of foo(), variables.foo: [{ts '2013-04-07 09:07:09'}]
[09:07:14.333] [1] Bottom of foo(), variables.foo: [{ts '2013-04-07 09:07:04'}]
[09:07:14.336] [1] After call to foo(), variables.foo: [{ts '2013-04-07 09:07:09'}]
[09:07:19.836] [2] Bottom of foo(), variables.foo: [{ts '2013-04-07 09:07:09'}]
[09:07:19.839] [2] After call to foo(), variables.foo: [{ts '2013-04-07 09:07:09'}]

Here we see that request 1 sets the variable to one thing, then request 2 comes in after it and resets it to another thing, and thereafter request 1 has request 2's value. A race condition at work. So, yes, when using shared scoped CFCs, their variables scopes are also shared. Obviously. But this does not happen if the CFC is not in a shared scope, nor does it happen in a CFM file.

The originating blog article is wrong. I'll let them know.

---

But hang on a sec. There is something I don't get here. Let's look at that log more closely.

Update:
Sean did indeed come to my rescue and pointed out my stupidity. See if you can spot it. But I'll update the end of the article to explain what the story was. The short version: I was being dense. But continue reading and observe my level of stupidity...

[09:07:04.325] [1] Begin request
[09:07:04.330] [1] Before call to foo()
[09:07:04.331] [1] Top of foo(), variables.foo: [{ts '2013-04-07 09:07:04'}]
[09:07:09.827] [2] Begin request
[09:07:09.832] [2] Before call to foo()
[09:07:09.834] [2] Top of foo(), variables.foo: [{ts '2013-04-07 09:07:09'}]
[09:07:14.333] [1] Bottom of foo(), variables.foo: [{ts '2013-04-07 09:07:04'}]
[09:07:14.336] [1] After call to foo(), variables.foo: [{ts '2013-04-07 09:07:09'}]
[09:07:19.836] [2] Bottom of foo(), variables.foo: [{ts '2013-04-07 09:07:09'}]
[09:07:19.839] [2] After call to foo(), variables.foo: [{ts '2013-04-07 09:07:09'}]

Request 1 comes through and sets variables.foo to be "{ts '2013-04-07 09:07:04'}". And then request 2 comes through and sets variables.foo to be "{ts '2013-04-07 09:07:09'}". But then request 1 accesses variables.foo again, but it still has its value as set by request 1, before request 2 reset it. And on the very next line of code executed, the new value is again reported.

Err... hullo? What?

It looks to me like in the scope of a function, CF grabs its own copy of the variables scope, so any changes to said scope by an external entity (like another request) are nor reflected. It's only when the variable is next referenced outside the context of the function's scope is the real (ie: current) value reflected. This can't be correct, surely? However I just ran that code on Railo 4.1 too, and it worked the same way. And after tweaking the code so OpenBD could run it, it works the same way too. So I'm guessing I have a gap in my knowledge as to how these things work. I must chase that up. Sean, you'll be reading this... what am I missing? I'm hoping that it's just a case of it being Sunday morning, I'm actually still in bed, and I have had no coffee. So I'm just being daft/blind. But this pleases me, because I have found out I'm about to learn something.

But first: where's that coffee?

Update (cont'ed):
OK, so Sean pointed out that I'm recreating the application-scoped variable each request, which was a bit thick of me (I am blaming the coffee situation!). So I shoulda been doing this in my test rig:

if (!structKeyExists(application, "o")){
    application.o =createObject("CfcTest");
}

Having done that, everything works as I'd've expected it to, had I had my brain engaged:

[10:26:48.819] [1] Begin request
[10:26:48.821] [1] Before call to foo()
[10:26:48.822] [1] Top of foo(), variables.foo: [{ts '2013-04-07 10:26:48'}]
[10:26:52.947] [2] Begin request
[10:26:52.949] [2] Before call to foo()
[10:26:52.950] [2] Top of foo(), variables.foo: [{ts '2013-04-07 10:26:52'}]
[10:26:58.823] [1] Bottom of foo(), variables.foo: [{ts '2013-04-07 10:26:52'}]
[10:26:58.824] [1] After call to foo(), variables.foo: [{ts '2013-04-07 10:26:52'}]
[10:27:02.951] [2] Bottom of foo(), variables.foo: [{ts '2013-04-07 10:26:52'}]
[10:27:02.953] [2] After call to foo(), variables.foo: [{ts '2013-04-07 10:26:52'}]

Now I'm allowed to go have that coffee...

Cheers Sean.

--
Adam