Session Timeout and onSessionEnd strange behavior?

dev support
1

I’ve been looking into a problem that has occurred for a long time in our app. It occurred when we used CF9 and it occurs with Lucee. It doesn’t happen often.

It seems like there is a difference between when a session times out (and session variables are cleared) and when onSessionEnd is called (in Application.cfc).

We don’t use many session variables. We have one for the userId and we check that to make sure the session is current (ie. not timed out).

We also use a session variable to store a Java object that stores work state. Our app has a work list. People log on, see a work list, click an item, and begin working on the item. Working on an item means filling in a few forms which may take a few minutes. Data from the forms is stored in the Java object. When all the forms are completed a report is created (using info in the Java object) and stored in the db.

Sometimes a user is distracted and the session times out (Session.userId doesn’t exist anymore) while in the middle of completing the work forms. In this case, we put the item back on the worklist (when onSessionEnd occurs).

However, this doesn’t always work. There seems to be a (sizable) delay between when Session.userId is cleared and when onSessionEnd is called. If the user commences with activity in that time frame, the user is logged out (Session.userId is undefined) and the item is NOT returned to the worklist (because onSessionEnd) hasn’t run yet.

We end up with work items that are dangling. They were started, never completed, and don’t appear on the worklist.

Any idea as to what is going on? Maybe my understanding of sessions and timeouts is wrong?

Mike

2

firstly, please always mention which version of Lucee :slight_smile:

you might like to play around with a copy of test case to see if you can reproduce the problem?

3

I didn’t use that code but I was able to confirm the problem with the very simple code at the end (two files). The code logs all onSessionStart(), onSessionEnd(), onRequestStart(), onRequestEnd() and onRequest() calls in Application.cfc.

I set the session timeout to one minute, I didn’t want to wait too long.

I accessed the site at 20:10:55 and a session starts (first bold line). At 20:12:12 I access the form again (second bold line). A new session starts. At 20:12:14 I save the form, which sets the session variable (“who”) to “aaa”. I don’t touch the site for another 1 minute and 6 seconds, which is 20:13:20 (third bold line). I access the form and set the session variable to “bbb”.

At that same time a new session starts, which is expected. After all one minute has passed. However, you can see from the logs that the initial session (started at 20:12:12) never ended.

This is what is happening in our full fledged app. With the first session not ending, we are not able to clean up after that session.

“INFO”,“ajp-nio-8009-exec-3”,“12/08/2022”,“20:10:55”,“”,“Application STARTING”
“INFO”,“ajp-nio-8009-exec-3”,“12/08/2022”,“20:10:55”,“”,“Session STARTING”
“INFO”,“ajp-nio-8009-exec-3”,“12/08/2022”,“20:10:55”,“”,“Request STARTING for at /index.cfm.”
“INFO”,“ajp-nio-8009-exec-3”,“12/08/2022”,“20:10:55”,“”,“REQUEST for at /index.cfm”
“INFO”,“ajp-nio-8009-exec-3”,“12/08/2022”,“20:10:55”,“”,“Request ENDING for .”
“INFO”,“ajp-nio-8009-exec-5”,“12/08/2022”,“20:12:12”,“”,“Session STARTING”
“INFO”,“ajp-nio-8009-exec-5”,“12/08/2022”,“20:12:12”,“”,“Request STARTING for at /index.cfm.”
“INFO”,“ajp-nio-8009-exec-5”,“12/08/2022”,“20:12:12”,“”,“REQUEST for at /index.cfm”
“INFO”,“ajp-nio-8009-exec-5”,“12/08/2022”,“20:12:12”,“”,“Request ENDING for aaa.”
“INFO”,“ajp-nio-8009-exec-6”,“12/08/2022”,“20:12:14”,“”,“Request STARTING for aaa at /index.cfm.”
“INFO”,“ajp-nio-8009-exec-6”,“12/08/2022”,“20:12:14”,“”,“REQUEST for aaa at /index.cfm”
“INFO”,“ajp-nio-8009-exec-6”,“12/08/2022”,“20:12:14”,“”,“Request ENDING for aaa.”
“INFO”,“ajp-nio-8009-exec-8”,“12/08/2022”,“20:13:20”,“”,“Session STARTING”
“INFO”,“ajp-nio-8009-exec-8”,“12/08/2022”,“20:13:20”,“”,“Request STARTING for at /index.cfm.”
“INFO”,“ajp-nio-8009-exec-8”,“12/08/2022”,“20:13:20”,“”,“REQUEST for at /index.cfm”
“INFO”,“ajp-nio-8009-exec-8”,“12/08/2022”,“20:13:20”,“”,“Request ENDING for bbb.”

After some time, I go back and open the log again. Ah, I can see a session ending later on. This line now appears at the end of the log.

“INFO”,“Thread-125”,“12/08/2022”,“20:14:44”,“”,“Session ENDING for bbb.”

Here are the two files. One is application.cfc. The other is the index.cfm where we simply set a session variable.

APPLICATION.CFC

<CFCOMPONENT>

<CFSET This.ClientManagement = false>
<CFSET This.SessionManagement = true>
<CFSET This.sessiontimeout = CreateTimeSpan(0,0,1,0)>
<CFSET This.Name = "TestApp">

<CFFUNCTION name="onApplicationStart" RETURNTYPE="boolean">
	<CFLOG TEXT="Application STARTING" FILE="#This.Name#" TYPE="Information">
	<CFRETURN true>
</CFFUNCTION>

<CFFUNCTION name="onApplicationEnd" RETURNTYPE="void">
	<CFARGUMENT NAME="AppScope" REQUIRED=true />

	<CFLOG TEXT="Application ENDING" FILE="#This.Name#" TYPE="Information">
</CFFUNCTION>

<CFFUNCTION name="onSessionStart" RETURNTYPE="void">
	<CFSET Session.who = CreateUniqueId()>
	<CFLOG TEXT="Session STARTING for #Session.who#" FILE="#This.Name#" TYPE="Information">
</CFFUNCTION>

<CFFUNCTION NAME="onSessionEnd" RETURNTYPE="void">
	<CFARGUMENT NAME="SessionScope" REQUIRED=true />
	<CFARGUMENT NAME="AppScope" REQUIRED=true />

	<CFSET w = "">
	<CFIF IsDefined( "Arguments.SessionScope.Who" )>
		<CFSET w = Arguments.SessionScope.Who>
	</cfif>

	<CFLOG TEXT="Session ENDING for #w#." FILE="#This.Name#" TYPE="Information">
</CFFUNCTION>

<CFFUNCTION name="onRequestStart">
	<CFARGUMENT NAME="targetPage" TYPE="String" REQUIRED=true/>

	<CFSET w = "">
	<CFIF IsDefined( "Session.who" )>
		<CFSET w = Session.who>
	</cfif>

	<CFLOG TEXT="Request STARTING for #w# at #Arguments.targetPage#." FILE="#This.Name#" TYPE="Information">
</CFFUNCTION>

<CFFUNCTION NAME="onRequestEnd">

	<CFSET w = "">
	<CFIF IsDefined( "Session.who" )>
		<CFSET w = Session.who>
	</cfif>

	<CFLOG TEXT="Request ENDING for #w#." FILE="#This.Name#" TYPE="Information">

</CFFUNCTION>

<CFFUNCTION NAME="onRequest" RETURNTYPE="void">
	<CFARGUMENT NAME="targetPage" TYPE="string" REQUIRED="true"/>

	<CFSET w = "">
	<CFIF IsDefined( "Session.who" )>
		<CFSET w = Session.who>
	</cfif>

	<CFLOG TEXT="REQUEST for #w# at #Arguments.targetPage#" FILE="#This.Name#" TYPE="Information">

	<CFINCLUDE TEMPLATE="#Arguments.targetPage#">		<!--- Continue to the page. --->
</CFFUNCTION>

</CFCOMPONENT>

INDEX.CFM

<html>
<head>
<title>Test</title>
</head>
<body>

<h1>Hello</h1>

Time is <cfoutput>#Now()#</cfoutput>.

</body>
</html>
4

firstly, which version of Lucee are you using?

Also, I don’t see any session timeout in your example?

to make things a bit clearer, I’d be adding a CreateUniqueId() to the session in onSessionStart and always logging that out in onRequestStart and onSessionEnd

1 Like
5

I tried this with version 5.2.7.063 and then upgraded to the latest version 5.3.10.97. The problem occurred in both versions.

The session timeout was set to 1 minute in the server admin page.

However, even if the session timeout was 20 minutes. There should never be a time when a second session start occurs without the first session ending in the same browser window (maybe I don’t understand how sessions work?). Note that only one browser window was open and no cookies were reset in that browser window. I simply waited for one minute and few extra seconds.

Mike

6

I edited the index.cfm (in the initial post above) to simplify it and did more testing.

It looks like a bug to me. There is a short period of time after a session should timeout where (if there is activity on the web page), it is possible for a second session to start without the first session ever receiving an onSessionEnd.

I’ve never expected the session timeout to be exact. However, my understanding is that an onSessionEnd should always occur before a new onSessionStart can occur.

7

Didn’t had time to test your code locally, but having a quick look I can see that you are giving your application a name in your onApplicationStart():

Just a few lines above you are setting the this scope with the keyname “name” . This is also setting the application.name there. Note your code:

Like I’ve said, in the last line you are also setting the application.name with this.name, and you are setting a with a way too dynamic value. As soon as your calling template changes in the URL , you are also changing or creating a new application.name (setting “application.name” is quite the same as setting “this.name” in the Applikation.cfc). Because sessions are bound to application.name you might be jumping from application to application with all memory session around.

Really didn’t have much time to test, but I’d make this.name a fixed value first. Better… Use another scope than the this scope.

8

That’s a good find. I updated the code (see above). Hardwired the name. I also cleaned up the code in application.cfc to not use a local var named “who”, which could have interfered with the session var of the same name. Used CreateUniqueID() to create a unique session var value.

The end result is the same. Here is the log. I refresh the page a little after the time where the session should timeout.

I can’t figure out for the life of me why the first session doesn’t produce an onSessionEnd and yet a second session starts. All of this runs in one browser window.

“INFO”,“ajp-nio-8009-exec-2”,“12/09/2022”,“16:10:18”,“TestApp”,“Application STARTING”
“INFO”,“ajp-nio-8009-exec-2”,“12/09/2022”,“16:11:00”,“TestApp”,“Application STARTING”
“INFO”,“ajp-nio-8009-exec-2”,“12/09/2022”,“16:11:00”,“TestApp”,“Session STARTING for 1”
“INFO”,“ajp-nio-8009-exec-2”,“12/09/2022”,“16:11:00”,“TestApp”,“Request STARTING for 1 at /index.cfm.”
“INFO”,“ajp-nio-8009-exec-2”,“12/09/2022”,“16:11:00”,“TestApp”,“REQUEST for 1 at /index.cfm”
“INFO”,“ajp-nio-8009-exec-2”,“12/09/2022”,“16:11:00”,“TestApp”,“Request ENDING for 1.”
“INFO”,“ajp-nio-8009-exec-3”,“12/09/2022”,“16:12:05”,“TestApp”,“Session STARTING for 2”
“INFO”,“ajp-nio-8009-exec-3”,“12/09/2022”,“16:12:05”,“TestApp”,“Request STARTING for 2 at /index.cfm.”
“INFO”,“ajp-nio-8009-exec-3”,“12/09/2022”,“16:12:05”,“TestApp”,“REQUEST for 2 at /index.cfm”
“INFO”,“ajp-nio-8009-exec-3”,“12/09/2022”,“16:12:05”,“TestApp”,“Request ENDING for 2.”
“INFO”,“Thread-48”,“12/09/2022”,“16:13:46”,“TestApp”,“Session ENDING for 2.”

9

From where are the above log emtries getting the numbers „1“ and „2“? Is that for session.who and `w? can‘t see or find anything where it’s being set. Are you sure that code you showed us belongs to the same logs?

10

It is set in onSessionStart by calling createUniqueId(). I updated the code (above). You can see it there. Session.who = createUniqueId().

Yes, the code I updated the code (above) with the exact code I’m using.

In fact, I deleted the entire web site in IIS (it contained our entire app). Created a new website (in IIS). The only two files in the new site are the two that are above.