7

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.

Henry
  • 32,689
  • 19
  • 120
  • 221
  • 2
    Henry... what are you doing inside of the infinite loop. There _are_ some things that preempt the global timeout (db calls, ftp, things that require outside resources). – Mark A Kruger May 09 '12 at 02:56
  • Guys... this question doesn't make any mention of CFTHREAD... not sure where that is coming from. – Mark A Kruger May 09 '12 at 13:20
  • @MarkAKruger I'm in the process of implementing something new. The codes are still unstable. I wrote it in CFScript and didn't expect the codes that end up being executed infinitely not get killed by CF's Request Timeout. – Henry May 09 '12 at 15:30
  • 1
    Well I think Barny's answer is probably definitive. I'm asking a few Adobe folks about it but the consensus seems to be that yes - loops inside of cfscript don't respond to global timeout values. If you rewrite your loop in tag format I'm guessing you would get the timeout you expect. Remember though native calls (file I/O, DB etc) will still be subject to this issue. – Mark A Kruger May 09 '12 at 15:59
  • @MarkAKruger interesting, so maybe loops in cfscript may be slightly more efficient, while loops in cfml are safer (with request timeout check), would you agree? It's sure nice to know "a few Adobe folks". :) Thank you. – Henry May 09 '12 at 16:12
  • I'm not sure you could assume they are more efficient without testing. I'm guessing the parser that compiles into Java is just "slightly" different. But certainly it looks like tag based cfloop is safer - especially with while() loops eh? – Mark A Kruger May 09 '12 at 18:47
  • 1
    Just had a thought on this issue, wouldn't it be troublesome for CF share hosting? – Henry May 10 '12 at 02:04
  • Henry - absolutely. ColdFusion on a shared account is a bit scary anyway unless it's strictly controlled by a group of known developers. That's why a VPS is always probably preferrable eh? – Mark A Kruger May 10 '12 at 02:37
  • I'm not sure if VPS would help much if one of the slices are at 100% at all times... – Henry May 10 '12 at 02:45
  • well that's true of any technology :) Gotta have resources available to make 'em work eh? – Mark A Kruger May 10 '12 at 13:13
  • @Henry does my answer with information on how to force a timeout check make more sense than my previous comments? – nosilleg Jul 31 '12 at 08:54
  • @nosilleg a little. I'm still unsure, if it throws the timeout exception, which invoke was throwing? First or the most recently called? – Henry Jul 31 '12 at 15:52

3 Answers3

13

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.

Jason Larke
  • 5,289
  • 25
  • 28
barnyr
  • 5,678
  • 21
  • 28
  • 1
    Barny - that is an awesome answer. I love it. Thanks for the examples. Looks like a good choice for a blog post and some further investigation. – Mark A Kruger May 09 '12 at 13:32
  • I'd plus for the answer, just for recommending Samurai. (But overall a great answer too!) – Sharondio May 09 '12 at 14:08
  • Thank you very much for your investigation! Very interesting / odd result. Who would have thought, same loop, but in cfscript, would not be checked against the request timeout. This should either be corrected, or documented somewhere... Are you using CF 9.0.1 as well? Maybe we should test it against CF7 or 8 to see if it's indeed the same result. – Henry May 09 '12 at 15:22
  • I'm using 9.0.1 here but I think it's been like that for a while. There may be a way of working out which tags/code checks for timeouts, but I suspect you'd need to take a very hard look at the CF codebase to work it out. – barnyr May 09 '12 at 15:29
  • @barnyr I see. Thank you. FYI, right now I'd use `trace()` to figure out where the infinite loop is, and use JRun Launcher to kill & restart the server. – Henry May 09 '12 at 15:34
  • 1
    @barnyr your investigation lead me to think.. if I call my cfscript in a strategic way, I can still get the Request Timeout behaviour. – Henry May 09 '12 at 15:37
  • Most probably, either by using a mix of CFML and script, so the request timeout gets checked by use of a or somewhere, but depending on the code, that could be messy. You could also simulate the behaviour by setting request.starttime=getTickCount() and periodically checking how long you've been going. You could throw an exception if your process has been working for too long. This assumes that you're not just waiting on one single long process like a DB call of HTTP request. – barnyr May 09 '12 at 15:45
  • @barnyr periodically check? That sounds like I need to use cfthread to do that? I use standard edition so I couldn't afford to rely on cfthread on every request. It sounds like as long as I execute the code by a cftag, like in the controller or even view layer, I shall be fine. Thanks again! – Henry May 09 '12 at 15:52
  • @Henry you should be able to "periodically check" anywhere inside cfscript by calling a tag based UDF that only contains `` in the body of the function. If you add a call to that function before the `` then CF will timeout as you desire. The UDF shouldn't have a noticeable impact on an intensive loop. No cfthread required. HTH – nosilleg Jul 24 '12 at 16:13
  • @nosilleg I don't understand. How would that work? call a function implemented in CFML with cfoutput before the loop? How would that help? – Henry Jul 24 '12 at 16:23
  • 1
    @Henry ColdFusion checks for request timeout before "executing" a limited number of tags. `cfoutput` is one of those tags, and the reason why most timeout errors report `cfoutput` as the culprit. So if you have a function that only has a `cfoutput` in it, then you will just be getting CF to check if the request timeout has expired, with little other overhead. Having it inside the loop will make the loop respect the request timeout. – nosilleg Jul 24 '12 at 18:15
  • @nosilleg I thought cfoutput tag would need to wrap Around the cfscript loop in order to have CF checks for the request timeout, right? – Henry Jul 24 '12 at 20:33
  • @Henry Nope. The `cfoutput` needs to happen inside the loop, but since it's `cfscript` you have to have a UDF to get the `cfoutput` tags in there. The `cfoutput` tags serve no purpose aside from getting CF to check the request timeout. I'll write up a better explanation and a sample when I get a chance. – nosilleg Jul 24 '12 at 23:01
3

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.

nosilleg
  • 2,143
  • 1
  • 22
  • 36
  • @Henry Getting the request to timeout, and figuring out what was happening to make the request timeout are two different things. This answer is just about getting the timeout to happen. You say "which invoke was throwing" do you mean which iteration of the loop? You would need to add in some more logic to figure that out. – nosilleg Aug 01 '12 at 15:49
2

I'm finding the same thing as Henry. Here's my test code:

Before thread<br />
<cfthread action="run" name="t1">
    <cfloop condition="true">
        <cfparam name="count" default="0">
        <cfset sleep(3000)>
        <cflog file="cfthreadTest" text="Log entry #++count#">
    </cfloop>
</cfthread>
After thread<br />

My request timeout is set to 20sec in CFAdmin, and this thread has now been running for 15min. That said, a thread is not "a request" so am not sure I would expect it to respect the request timeout. There's nothing documented that I can find that suggests it should respect the request timeout. That said... having some way of killing a thread would be "handy".

I guess this is only an "answer" in the context that I don't think your expectations are correct in that you expect it to respect the request timeout.

Adam Cameron
  • 29,677
  • 4
  • 37
  • 78