ColdFusion: bug in runAsync

G'day:

In my article yesterday ("CFML: runAsync doesn't seem very asynchronous on Lucee") I mentioned in passing that I'd found a bug in ColdFusion's runAsync implementation. I wasn't focusing on ColdFusion at the time, so I didn't try to repro it; however I have now.

Don't worry about the wall of code, it's the same thing three times to increase the odds of the bug situation to surface:

// /vendor/ColdFusion/2021/runAsyncBug/repro.cfm
telemetry = []
recordTelemetry = (label) => {
    telemetry.append(label)
}

recordTelemetry("Begin")

recordTelemetry("f1 before define")
f1 = runAsync(() => {
    recordTelemetry("f1 main")
}).then(() => {
    recordTelemetry("f1 then1")
}).then(() => {
    recordTelemetry("f1 then2")
})
recordTelemetry("f1 after define")

recordTelemetry("f2 before define")
f2 = runAsync(() => {
    recordTelemetry("f2 main")
}).then(() => {
    recordTelemetry("f2 then1")
}).then(() => {
    recordTelemetry("f2 then2")
})
recordTelemetry("f2 after define")

recordTelemetry("f3 before define")
f3 = runAsync(() => {
    recordTelemetry("f3 main")
}).then(() => {
    recordTelemetry("f3 then1")
}).then(() => {
    recordTelemetry("f3 then2")
})
recordTelemetry("f3 after define")

recordTelemetry("f1 before get")
f1.get()
recordTelemetry("f1 after get")

recordTelemetry("f2 before get")
f2.get()
recordTelemetry("f2 after get")

recordTelemetry("f3 before get")
f3.get()
recordTelemetry("f3 after get")

recordTelemetry("End")

writeDump(telemetry)

tallies = [
    "Begin" = 0,
    "f1 before define" = 0,
    "f1 main" = 0,
    "f1 then1" = 0,
    "f1 then2" = 0,
    "f1 after define" = 0,
    "f2 before define" = 0,
    "f2 main" = 0,
    "f2 then1" = 0,
    "f2 then2" = 0,
    "f2 after define" = 0,
    "f3 before define" = 0,
    "f3 main" = 0,
    "f3 then1" = 0,
    "f3 then2" = 0,
    "f3 after define" = 0,
    "f1 before get" = 0,
    "f1 after get" = 0,
    "f2 before get" = 0,
    "f2 after get" = 0,
    "f3 before get" = 0,
    "f3 after get" = 0,
    "End" = 0
]
errors = tallies
    .map((k) => telemetry.findAll(k).len())
    .filter((_, v) => v != 1)

writeDump(errors)

This code is very similar to the cod ein the earlier article I linked to. I create three futures: f1, f2, f3; and each of those has a main task and two then handlers. All the task and then handlers do is append to a telemetry array. This is pared down from some code that actually did more stuff that I wanted to be async.

All going well (and 75% of the time, this is the case), we should end up with an array of 23 telemetry entries, one each for the entries in the code. We can't guarantee the order cos most of it is running asynchronously.

What I was seeing though, is sometimes entries were missing, but some others were doubled up. Here's an example of that:

See how the telemetry array has no entries for "f2 then1" and "f3 before get"; but instead has two each of "f3 then1" and "f2 before get". Odd.

Also about 5% of the time I get this:

Variable LABEL is undefined.

The error occurred in /app/cfml/vendor/ColdFusion/2021/runAsyncBug/repro.cfm: line 4

2 : telemetry = [] 3 : recordTelemetry = (label) => { 4 : telemetry.append(label) 5 : } 6 :

There are always 23 entries; just some are wrong. There seems to be any number of wrong ones, but usually only a couple. The example above is a fairly typical run.

I tried a variant of the test with a lock around the write to the telemetry array:

recordTelemetry = (label) => {
    lock type="exclusive" name="telemetry" timeout=1 throwontimeout=true {
        telemetry.append(label)
    }
}

But this did not make a difference.

Also the fact I am using a function expression using closure over the telemetry array is significant. If I just have a function statement:

function recordTelemetry(label) {
    telemetry.append(label)
}

There is no problem.

I dunno what to make of this, but it'll give the Adobe ColdFusion Team something to work with anyhow.

Oh: this is not an issue with Lucee.

Righto.

--
Adam