Tuesday, 17 June 2014

Will sessions and applications timeout in the middle of long-running requests?

G'day:
The short version is "yes", as it turns out. I did not expect that.

This question came up today courtesy of Ron Stewart on Twitter:


Ron didn't specifically ask me, but it's one of those things I figured I should know, but found I didn't know for sure, so I had better test it out.

As it turns out, both ColdFusion and Railo will happily time-out sessions and applications whilst requests within those sessions / applications are still running. I dunno what I think about this, but my initial reaction is "that's not great".

Here's my test code:

// Application.cfc
component {

    variables.requestStartTime = getTickCount();

    this.name                = "timeoutTest13";
    this.sessionManagement    = true;
    this.applicationTimeout    = createTimespan(0,0,2,0);
    this.sessionTimeout        = createTimespan(0,0,1,0);

    function onApplicationStart(){
        writeLog(file=this.name, text="#getFunctionCalledName()# @ #getTickCount()-variables.requestStartTime#");
    }

    function onSessionStart(){
        writeLog(file=this.name, text="#getFunctionCalledName()# @ #getTickCount()-variables.requestStartTime#");
    }

    function onRequestStart(){
        writeLog(file=this.name, text="#getFunctionCalledName()# @ #getTickCount()-variables.requestStartTime#");
    }

    function onRequest(){
        include arguments[1];
    }
    
    function onRequestEnd(){
        writeLog(file=this.name, text="#getFunctionCalledName()# @ #getTickCount()-variables.requestStartTime#");
    }
    
    function onSessionEnd(){
        writeLog(file=this.name, text="#getFunctionCalledName()# @ #getTickCount()-variables.requestStartTime#");
    }
    
    function onApplicationEnd(){
        writeLog(file=this.name, text="#getFunctionCalledName()# @ #getTickCount()-variables.requestStartTime#");
    }

}

This is simple: it simply logs when various event handlers are fired.

And a baseline test:

<cfscript>
// baseline.cfm
writeLog(file=this.name, text="top of #listLast(getCurrentTemplatePath(), '/\')# @ #getTickCount()-variables.requestStartTime#");
</cfscript>

This is just to demonstrate the thing works. Typical output would be (this is from ColdFusion 11):

"Severity","ThreadID","Date","Time","Application","Message"
"Information","ajp-bio-8014-exec-1","06/17/14","18:47:12",,"C:\apps\adobe\ColdFusion\11\full\cfusion\logs\timeoutTest02.log initialized"
"Information","ajp-bio-8014-exec-1","06/17/14","18:47:12","TIMEOUTTEST02","onApplicationStart @ 32"
"Information","ajp-bio-8014-exec-1","06/17/14","18:47:12","TIMEOUTTEST02","onSessionStart @ 36"
"Information","ajp-bio-8014-exec-1","06/17/14","18:47:12","TIMEOUTTEST02","onRequestStart @ 37"
"Information","ajp-bio-8014-exec-1","06/17/14","18:47:12","TIMEOUTTEST02","top of baseline.cfm @ 46"
"Information","ajp-bio-8014-exec-1","06/17/14","18:47:12","TIMEOUTTEST02","onRequestEnd @ 47"
"Information","scheduler-1","06/17/14","18:48:19","TIMEOUTTEST02","onSessionEnd @ 67418"
"Information","scheduler-1","06/17/14","18:49:37",,"onApplicationEnd @ 145593"

So the application starts, the session starts, the request starts, runs, ends, and then after their timeouts, the session and applications end too. All as expected.

Next I had two tests: one with a request which ran longer than the 1min session timeout, and another which ran longer than the 2min application timeout:

<cfscript>
// requestLongerThanSessionTimeout.cfm
writeLog(file=this.name, text="top of #listLast(getCurrentTemplatePath(), '/\')# @ #getTickCount()-variables.requestStartTime#");
sleep(90*1000);
writeLog(file=this.name, text="bottom of #listLast(getCurrentTemplatePath(), '/\')# @ #getTickCount()-variables.requestStartTime#");
</cfscript>


<cfscript>
// requestLongerThanApplicationTimeout.cfm
writeLog(file=this.name, text="top of #listLast(getCurrentTemplatePath(), '/\')# @ #getTickCount()-variables.requestStartTime#");
sleep(150*1000);
writeLog(file=this.name, text="bottom of #listLast(getCurrentTemplatePath(), '/\')# @ #getTickCount()-variables.requestStartTime#");
</cfscript>

And we see from their logs (I'll just show the latter one, as they're both thematically the same):

"Severity","ThreadID","Date","Time","Application","Message"
"INFO","qtp1678014056-13","06/17/2014","18:59:07","","onApplicationStart @ 1"
"INFO","qtp1678014056-13","06/17/2014","18:59:07","","onSessionStart @ 5"
"INFO","qtp1678014056-13","06/17/2014","18:59:07","","onRequestStart @ 6"
"INFO","qtp1678014056-13","06/17/2014","18:59:07","","top of requestLongerThanApplicationTimeout.cfm @ 21"
"INFO","Thread-16","06/17/2014","19:00:29","","onSessionEnd @ 82145"
"INFO","Thread-16","06/17/2014","19:01:29","","onApplicationEnd @ 142174"
"INFO","qtp1678014056-13","06/17/2014","19:01:37","","bottom of requestLongerThanApplicationTimeout.cfm @ 150022"
"INFO","qtp1678014056-13","06/17/2014","19:01:37","","onRequestEnd @ 150026"

(this is from Railo this time)

Here we see:

  • the request starts
  • the session times out
  • the application times out
  • the request finishes
Now I kinda think that both session and application should be kept alive whilst things are still happening, because the way it currently works will leave the application (/session) in possibly an "unknown" state during the course of a request, and also there's no real way of saying "oi, don't timeout!" if we know a request might push the envelope there a bit.

Worth raising a bug / enhancement request? What behaviour did you expect here?

-- 
Adam




Posted by at
Labels: ,