Why doesn't a request with an infinite loop get killed by ColdFusion request timeout?

Question

First, I set Timeout Requests after (seconds) to 20 in CF Admin.

Then I run a cfm with a line like while(true);

The page will run way past 20 seconds, and the thread is still alive as I wrote this.

Below is a snapshot taken with Server Monitor

Thread  jrpp-3 request type - TEMPLATE REQUEST
*Template Path - D:\Projects\infiniteLoop.cfm
*Request Parameters - {}
*Request Method - GET
*Client IP address - 127.0.0.1
*Thread elapsed time - 322659 milliseconds

Is this normal?? This is CF9.0.1., developer edition. Multi-instance setup, with JRun.

The only way to stop the infinite loop is to restart CF.

Answer 1

Request timeouts in ColdFuison don't behave in the way you expect. They way it's presented you'd imagine that there's a watchdog which checks how long your request has been running and kills it on or shortly after the request timeout. What actually appears to happen is that only when certain tags are run does CF check whether the elapsed time of the request is over the set limit. <cfoutput> is one of the tags where it checks, which is why you often see the timeout exceeded message pointing to a cfoutput, even though you know it can't be taking long to execute.

<cfsetting requesttimeout="5" enableCFoutputOnly="no" />

<!--- Looping with a condition <cfloop blamed --->
<cfset request.counter=0 />
<cfloop condition="true">
    <cfset sleep(1000) />
    <cfset request.counter=request.counter+1>

    <cflog file="timeout" text="#request.counter#">

    <cfif request.counter GT 8>
        <cfbreak>
    </cfif>

</cfloop>

<!--- Looping with an index, times out, naming CFLOOP as the offending tag --->
<cfloop index="foo" from="1" to="8">
    <cfset sleep(1000) />
</cfloop>

<!--- Looping with an index, times out, naming CFOUTPUT as the offending tag --->
<cfloop index="foo" from="1" to="8">
    <cfset sleep(1000) />
    <cfoutput>Hello</cfoutput>
</cfloop>


<!--- Same loop, but in script. No timeout warning at all --->
<cfscript>
for(foo=1;foo<=8;foo++){
    sleep(1000);
}
</cfscript>

<!--- Same loop, now with WriteOutput() called. Still no timeout --->
<cfscript>
for(foo=1;foo<=8;foo++){
    sleep(1000);
    writeoutput("tick...");
}
</cfscript>

The code above shows some of the odd behaviour of the requesttimeout. As Mark Kruger pointed out, any call to an external resource will mean no checking for timeout, and its my guess that large blocks of script which are just executing your own logic will also not be checked, leaving the next output statement to be blamed.

If you need to trace where code is lagging and the timeout messages are pointing to the wrong place, I'd either use logging or jstack to grab stack traces from the server whilst the long-running code is running. Grab a few stack traces a few seconds apart, then run the log file through Samurai to find what the code is doing.

Answer 2

What you have described is unfortunately expected behaviour when you know the constraints of request timeout checking in ColdFusion. (Granted, it shouldn't be the expected behaviour.)

There is an long blog post by Charlie Arehart covering timeout issues. One section is titled "CF checks the time at the start of the next operation, but sadly only on SOME tags". Unfortunately cfscript is not one of those, and timeout will not be checked with pure script code. However, one of the tags that does trigger a timeout check is cfoutput and with that knowledge it's possible to make script based code respect request timeout. It is however a manual process in that you need to decide yourself where you should be checking for timeout.

<cffunction name="cf_checkRequestTimeout" access="public" output="false" returntype="void" hint="Force CF to check if the request has timed out.">

    <!--- CF checks Request timeout on cfoutput tag use.  --->
    <cfoutput></cfoutput>

</cffunction>

<cfscript>
    for(foo=1;foo<=61;foo++){
        sleep(1000);
        cf_checkRequestTimeout();
    }
</cfscript>

The error generated will blame line 4, which is misleading, but the stacktrace will show that the function was called from line 11, which then allows you to know which bit of code timed out. Obviously the granularity of that knowledge is based on the frequency of checking the timeout.

The cf_checkRequestTimeout (not checkRequestTimeout because that's an undocumented internal CF function) can be called outside of cfscript as well, so if, for example you have a cfquery you think is causing timeout issues then you can put the cf_checkRequestTimeout call after the cfquery and get timeout errors where they should be instead of further down the code execution.