CFML: REST requests don't seem to correctly use Application.cfc either

G'day:
The emphasis in the title is an allusion to web socket requests also not respecting them.

God knows what this article will read like. I headed to the pub to catch the last quarter of the Aussie v Lions match, and I've been sitting here since. I'm over in Portumna visiting my son, and other than my 4h appointment doing that, I've kinda got nothing better to do here, so I'm still in the pub (which has wireless), amusing myself and drinking Guinness. Am just finishing my third pint. And will order a fourth. It's 3pm ;-)


Anyway, someone posted a question on Stack Overflow about how erroring REST requests don't fire onError() calls. This is a known issue: 3506757. But it was enough for me to furrow my brow and decide to have a look into it.

Now I'm no REST expert (neither in the context of ColdFusion, nor in general), so it always takes me a bit to get a REST CFC / function working, but I've come up with this test environment:

// Application.cfc
component {

    this.name    = "testappCfcIssue09";

    public void function onApplicationStart(){
        restInitApplication(expandPath("../api"), "api");
    }

    public void function onError(){
        writeLog(file=this.name, text="#GetFunctionCalledName()# called");
        writeDump(var=local, label=this.name);
        abort;
    }

}

This is a fairly vanilla Application.cfc. The onApplicationStart() stuff is just to work around some lazy programming on the part of Adobe, in that when one changes a REST-aware CFC, it will error until one restarts the REST engine. The onError() is just there in case REST calls call this onError() instead of the one in the directory the REST CFCs are in (I came into this not knowing how this stuff was handled at all, so just making sure).

<!--- testException.cfm --->
<cfhttp method="get" url="http://#CGI.http_host#/rest/api/Messaging/forceError" result="response">
</cfhttp>
<cfdump var="#response#" label="HTTP Response">

[I have decided against Guinness for the fourth: it's cider. It's a cracking hot day here today in Portumna, so not really Guinness weather]

This calls my REST method, and dumps the response. Now, over in the API dir, I have this lot:

//Messaging.cfc
component rest=true {

    remote string function gday(required string name restargsource="query") httpmethod="get"  {
        return "G'day #name#";
    }

    remote string function forceError() httpmethod="get" restpath="forceError"  {
        throw(type="ForcedException", message="Exception forced", detail="Because you asked me to");
    }
} 

The first method is just me testing that stuff was actually working properly with a vanilla method. The second method is one that forces an error, specifically so I can see what happens when an exception occurs.

And I have this Application.cfc in this directory as well, to log everything which goes on during REST requests:

// Application.cfc
component {

    this.name                = "restRequestLogging02";
    this.sessionManagement    = true;

    public void function onApplicationStart(){
        writeLog(file=this.name, text="#getFunctionCalledName()# called");
    }

    public void function onApplicationEnd(){
        writeLog(file=this.name, text="#getFunctionCalledName()# called");
    }

    public void function onSessionStart(){
        writeLog(file=this.name, text="#getFunctionCalledName()# called");
    }

    public void function onSessionEnd(){
        writeLog(file=this.name, text="#getFunctionCalledName()# called");
    }

    public void function onRequestStart(){
        writeLog(file=this.name, text="#getFunctionCalledName()# called");
    }

    public void function onRequestEnd(){
        writeLog(file=this.name, text="#getFunctionCalledName()# called");
    }

    public void function onRequest(){
        writeLog(file=this.name, text="#getFunctionCalledName()# called");
        include arguments[1];
    }

    public any function onCfcRequest(required string cfc, required string method, required struct args){
        writeLog(file=this.name, text="#getFunctionCalledName()# called");
        var o = createObject(arguments.cfc);
        var metadata = getMetadata(o[method]); 
        
        if (structKeyExists(metadata, "access") && metadata.access == "remote"){
            return invoke(o, method, args);
        }else{
            throw(type="InvalidMethodException", message="Invalid method called", detail="The method #method# does not exists or is inaccessible remotely");
        }
    }

    public void function onError(){
        writeLog(file=this.name, text="#getFunctionCalledName()# called");
        writeDump(local);
        abort;
    }

    public void function onMissingTemplate(){
        writeLog(file=this.name, text="#getFunctionCalledName()# called");
        writeeDump(local);
        abort;
    }

}

The only non-obvious method in this is the onCfcRequest() one. The code here is reflective of the unexpected "security issue" onCfcRequest() could effect in an application that I blogged about a while ago. Any onCfcRequest() method should do this lot as a minimum. That consideration aside, basically every event handler call is logged. That's the crux of things.



So I hit testException.cfm, and I get this:

HTTP Response - struct
FILECONTENT	{"Detail":"Because you asked me to","Message":"Exception forced","Type":"ForcedException"}
STATUSCODE	500 Internal Server Error

(I've knocked out all the irrelevant bumpf)

So we get the exception in the file content, and we get an HTTP 500 status. This is what we'd expect on the client consuming end of a REST call. Cool.

But what about the logs?

Firstly, I got nothing in the consuming application's own log: testappCfcIssue09.log. This is fine: a failing remote call should not be an error situation in the consuming app.

This is what I got in restRequestLogging02.log:

onApplicationStart called
onSessionStart called
onRequestStart called
onRequestEnd called

OK... so no onError(), we already knew this. This is definitely a bug, but still: Adobe know about it. However what's also missing? There's no evidence that onCfcRequest() was fired. This is another bug, which as far as I can tell has not been raised yet.

On a whim, I also checked the other logs ColdFusion maintains.

exception.log

 "Error","catalina-exec-4","07/06/13","15:30:10",,"coldfusion.xml.rpc.CFCInvocationException: [coldfusion.runtime.CustomException : Exception forced. Because you asked me to]"
coldfusion.rest.method.dispatch.CFRestException: coldfusion.xml.rpc.CFCInvocationException: [coldfusion.runtime.CustomException : Exception forced. Because you asked me to]

Right, so ColdFusion did understand an exception occurred, it just didn't see fit to raise the error event to the application.

coldfusion-out.log

Jul 6, 2013 15:34:33 PM Error [catalina-exec-1] - coldfusion.xml.rpc.CFCInvocationException: [coldfusion.runtime.CustomException : Exception forced. Because you asked me to]

I'm not sure this should have gone into the out log if it's already in the exception log, but hey.

coldfusion-error.log

Nothing. Really? Surely a bug. I'd like Adobe to explain why there's an exception log and an error log, btw, but that's a gripe for another day, I think. But something referred to as an error log should log errors. I'm not going too quickly when I suggest that, am I?

server.log

We get the error again:
"Error","catalina-exec-4","07/06/13","15:30:10",,"coldfusion.xml.rpc.CFCInvocationException: [coldfusion.runtime.CustomException : Exception focred. Because you asked me to]"
"Error","catalina-exec-1","07/06/13","15:34:33",,"coldfusion.xml.rpc.CFCInvocationException: [coldfusion.runtime.CustomException : Exception focred. Because you asked me to]"

Now, I don't know how things are generally logged, but surely errors go in the error (or exception) log, and not anywhere else? Why's this stuff in the server log? I would have expected the server log to be logging stuff to do with... oh, I don't know, the server. Not logging (error or otherwise) from miscellaneous requests.

Right, to there's two bugs there: no call to onError(), and no call to onCfcRequest(). The former is logged as 3506757, but I can't find the latter. I'll log a ticket: 3590745.

[I've just discovered this pub has a beer garden. It's sunny and about 25degC out there - perfect weather in my opinion - and I've been hunkering down indoors in the dark due to not knowing any better! But now my battery is low, and I need the mains. Dammit. Anyway... fifth pint: cider again]

---

I read that the site-wide (or more accurately: "ColdFusion server-wide") error handler will pick up these errors, in the comment against issue 3506757. Let's try.

Here's my error handler:

<cflog file="sitewide" text="#serializeJson(variables)#">

And I have verified it's running for other requests. I rehit my REST web service that raises the exception and I get...

... f*** all.

So - short of Paul elaborating on what he means that it "works" - I'm gonna call "bullshit" on that.

---

Bottom line: given some Application.cfc event handlers run when REST requests are received, then all of them ought to work. And, as far as I can tell, Adobe's suggested work-around isn't true (which is odd, because Paul is one of their more solid developers, so I suspect there's a communications disconnect on this particular count). Plus there's a weird approach to what is logged where.

And my battery is dead, my cider is almost out and it occurs to me I haven't eaten yet today. I had better go see what Portumna has on offer this afternoon. And absorb some sunshine. 16:45.

--
Adam