Happy New Year and all that sort of carry-on.
I'm still wading through this ColdFusion Bug Subscriber thing I'm writing using Coldbox. It's slow progress because the "wading" side of things erodes my patience fairly quickly, and I find something else to do. I hasten to add most of the wading is of my own manufacture due to vacillating over how to approach things, but in the early stages of things, Coldbox was being a bit annoying too. Mostly due to me not knowing what I'm doing, that said.
Anyway, I want to get it finished (it's 80% done, I guess), so have been trying to make forward progress with it over the last coupla days whilst I'm off work. With one thing or another, I have made about five lines of code's worth of progress in the last three days or so of sitting at my computer. There was a blog article or three in there, as well as a bit of Skyrim (yes, still playing Skyrim). But a lot of it has been sitting scratching my head and going "why? Just why?".
I've been completely stopped dead by a mysterious bug in my code for about a day now. Initially I assumed it was my fault (this is always a good place to start to apportion blame when there are things going wrong in your code: yourself), then I thought it was Coldbox's fault. Then I thought it was my fault again (just not being helped by CB), but I finally - earlier this afternoon - concluded it was a bug in ColdFusion.
In one of my controllers, I have this code (it'll be mostly meaningless out of context, I know, but it demonstrates where I started my examination of "WTF?"
public string function create(event, rc, prc){
var bug = getModel("Bug");
var validation = bug.validate(rc);
event.noRender();
if (validation.isValid){ // OK, "subscribe" the user to the bug
var bugToSubscribe = bug.get(accountData={adobeId=rc.bug}); // if the bug was validated, then it'll've been added too
var accountToSubscribe = getModel("Account").get(accountData={id=getPlugin("SessionStorage").getVar("id")});
bug.associateAccount(bugId=bugToSubscribe.getId(), accountid=accountToSubscribe);
event.setValue("messages", ["Subscribed to bug"]);
}else{ //bounce 'em back
event.setValue("messages", validation.messages);
}
setNextEvent(event="bug.main", persist="messages");
}
I was getting an error back from the hightlighted line saying that bugToSubscribe didn't exist. This could be the case if the earlier call to bug.get() didn't find a bug matching that ID (get() basically calls entityLoad()). This seemed a bit curious because it should not have passed the validation test if it didn't exist. Plus I knew the bug did actually exist in the DB.
So I put some debugging into bug.get(), checking what args were actually making their way into it, and having a look at the query it was running. And finishing with an abort. And I still got the error at the highlighted code. OK, so Coldbox was caching CFCs or something, so I restarted the app, and tried again. Same. So I put an abort immediately after the call to bug.get in the code above:
var bugToSubscribe = bug.get(accountData={adobeId=rc.bug}); // if the bug was validated, then it'll've been added too
writeDump(var=local, label="after bug.get()");
abort;
var accountToSubscribe = getModel("Account").get(accountData={id=getPlugin("SessionStorage").getVar("id")});
I messed around a bit and ended up with this sort of thing:
public string function create(event, rc, prc){ var bug = getModel("Bug"); var validation = bug.validate(rc); event.noRender(); if (validation.isValid){ // OK, "subscribe" the user to the bugraiseException(type="e0", message="exception0"); var bugToSubscribe = bug.get(accountData={adobeId=rc.bug}); // if the bug was validated, then it'll've been added tooraiseException(type="e1", message="exception1"); var accountToSubscribe = getModel("Account").get(accountData={id=getPlugin("SessionStorage").getVar("id")}); raiseException(type="e2", message="exception2"); bug.associateAccount(bugId=bugToSubscribe.getId(), accountid=accountToSubscribe); event.setValue("messages", ["Subscribed to bug"]); }else{ //bounce 'em back event.setValue("messages", validation.messages); } setNextEvent(event="bug.main", persist="messages"); } private void function raiseException(required string type, required string message){ param name="request.debugId" default=createUuid(); writeLog(file="raiseException", text="#request.debugId# #type# #message#"); throw(type=type, message=message, detail=request.debugId); }
And this yielded exception2. But not exception0 nor exception1. This is the point at which I started wondering WTH Coldbox was doing with exceptions, because it was clearly doing something with them, as I was getting an unhelpful Coldbox error screen instead of just the error being displayed, so I followed that avenue for a while, but other than some idiosyncracies in how they go about things, it was not CB's fault. I had thought it might have been suppressing exceptions in some situations but not others, but no. Basically those exceptions were not being raised at all.
It really seemed like code was being skipped somehow. So I decided to be less aggressive with logging my telemetry, and created a variation of raiseException() which just wrote to a log file without the exception, and put that in various places in the code, however I neglected to comment-out the exception0 call:
if (validation.isValid){ // OK, "subscribe" the user to the buglogProgress("before exception0"); raiseException(type="e0", message="exception0"); logProgress("after exception0"); var bugToSubscribe = bug.get(accountData={adobeId=rc.bug}); // if the bug was validated, then it'll've been added toologProgress("after bug.get()"); raiseException(type="e1", message="exception1"); // [...] public void function logProgress(required string message){ param name="request.debugId" default=createUuid(); writeLog(file="progress", text="#request.debugId# #message#"); }
And suddenly I started getting exception0 being raised. So I removed the calls to logProgress(), and I was back to seeing exception2 being raised again. I put them back in, and I was back to seeing exception0. I'd def moved on from WTH to WTF now.
Thinking by now that I am insane, I decided "I'm not seeing it, but there's a problem with that logProgress() function", so I got rid of it, and replaced it with just:
foo = "bar";
And exception0 was again raised. I swapped the foo line and the raiseException() line and was back to exception2. I put a writeOutput(foo) after the raiseException() of exception0... back to seeing exception0 again. Remove it: exception2.
I concluded that... as weird as it seems, it was just that line of code that wasn't being executed: it was skipping straight to the call to bug.get(). OK, so I took the exception0 call out completely, and left the foo="bar" line in, to see if I got to the next exception, exception1. No. Back to exception2. I thought "not again", and horsed about until I had this:
logProgress("before bug.get()");
bugToSubscribe = bug.get(accountData={adobeId=rc.bug});
logProgress("before getModel()");
accountToSubscribe = getModel("Account").get(accountData={id=getPlugin("SessionStorage").getVar("id")});
logProgress("before associateAccount()");
bug.associateAccount(bugId=bugToSubscribe.getId(), accountid=accountToSubscribe);
And the code was "working", except only the last logProgress() call was actually logging anything.
And then I had a flash of recollection, and saw what it was:
logProgress("before bug.get()");
bugToSubscribe = bug.get(accountData={adobeId=rc.bug});
logProgress("before getModel()");
accountToSubscribe = getModel("Account").get(accountData={id=getPlugin("SessionStorage").getVar("id")});
logProgress("before associateAccount()");
bug.associateAccount(bugId=bugToSubscribe.getId(), accountid=accountToSubscribe);
We'd had this before at work. In some situations when using shorthand struct notation like that being used as a method argument value, the previous line of code simply doesn't get executed. We had never managed to get a repro case for it, but we knew that the fix was easy:
var accountData = structNew();
accountData.adobeId = rc.bug;
bugToSubscribe = bug.get(accountData=accountData);
accountData = structNew();
accountData.id=getPlugin("SessionStorage").getVar("id");
accountToSubscribe = getModel("Account").get(accountData=accountData);
bug.associateAccount(bugId=bugToSubscribe.getId(), accountid=accountToSubscribe);
This particular code cannot be distilled down to a portable repro case, but I tried to extract all the relevant bits into something I could give to Adobe, but I still cannot replicate this in standalone files. Thinking about it now, in both the situation with our code at work and this code (and not my attempts at repro), the CFCs were all being cached via some caching tier (ColdSpring @ work, and whatever CB does in the case of this code). Maybe that's got something to do with it.
There's little chance of getting this fixed if I can't give Adobe an example of how to reproduce it, so I guess this is just something to tuck away in yer brain somewhere: if you mysteriously get lines of code not running... look around for inline shorthand struct notation.
UPDATE. I Thanks to Brad finding a repro case for this, I have posted a quick follow-up article to this one.
--
Adam
