OnApplicationEnd() And OnSessionEnd() Errors Don't Get Logged In ColdFusion
Over the last week or so, I've made some pretty large changes to the code behind my ColdFusion blogging software. As part of those changes, I've started using my Application.cfc's onSessionEnd() event handler. This event handler is used to tear down a given session, providing access to both the ending session as well as the sister application scope. The onSessionEnd() event handler accepts the session and application scopes as the first and second arguments respectively. Unfortunately, as I was making my updates, I accidentally switched the order of these two arguments. This error went unnoticed for two days because it turns out that neither onSessionEnd() nor onApplicationEnd() errors show up in the ColdFusion error logs.
Just to give you a taste of this error in action, here is a tiny Application.cfc ColdFusion framework component that I used to narrow down the problem:
<cfcomponent
output="false"
hint="I define the application settings and event handlers.">
<!--- Define application settings. --->
<cfset this.name = hash( getCurrentTemplatePath() ) />
<cfset this.applicationTimeout = createTimeSpan( 0, 0, 0, 15 ) />
<cfset this.sessionManagement = true />
<cfset this.sessionTimeout = createTimeSpan( 0, 0, 0, 5 ) />
<cffunction
name="onSessionEnd"
access="public"
returntype="void"
output="false"
hint="I tear down the session.">
<!--- Define arguments. --->
<cfargument
name="sessionScope"
type="any"
required="true"
hint="I am the session scope being torn down."
/>
<cfargument
name="applicationScope"
type="any"
required="true"
hint="I am the application scope."
/>
<!--- Log the session length. --->
<cfdump
var="#arguments.sessionScope.dateInitialized# : #now()#"
output="#expandPath( './log.htm' )#"
format="html"
/>
<!--- Return out. --->
<cfreturn />
</cffunction>
<cffunction
name="onApplicationEnd"
access="public"
returntype="void"
output="false"
hint="I tear down the application.">
<!--- Define arguments. --->
<cfargument
name="applicationScope"
type="any"
required="true"
hint="I am the application scope."
/>
<!--- Log the application length. --->
<cfdump
var="#arguments.applicationScope.dateInitialized# : #now()#"
output="#expandPath( './log.htm' )#"
format="html"
/>
<!--- Return out. --->
<cfreturn />
</cffunction>
</cfcomponent>
As you can see, both the onSessionEnd() and onApplicationEnd() ColdFusion application event handlers make reference to a dateInitialized property that doesn't exist. If I run this application and wait for both the application and the session to time out, neither undefined variable reference error will show up in the ColdFusion application log file. I've tested this both locally on ColdFusion 8 and ColdFusion 9 as well as in production on ColdFusion 8 and this remains true across the board.
If I add an onError() event handler to my Application.cfc ColdFusion framework component, both of these errors will be caught internally (at which point I can respond to them however I need to); but, without out any explicit error handling within the application, it appears that onApplicationEnd() and onSessionEnd() errors will go unnoticed.
As I was writing this, I did a bit of Googling to see if anyone else had come across this problem. As it turns out, Mark Kruger discussed the onSessionEnd() aspect in a blog post 5 years ago. That's a long time ago. This problem feels like a bug; but, perhaps if it has been around for so long, it is the expected behavior of the asynchronous event handlers (seeing as they sort of happen outside of the application)?
NOTE: My blogging software does have an onError() event handler. I was actually not getting alerts for a different bug altogether - one in my code. But, the debugging of that bug lead me to this separate problem.
Want to use code from this post? Check out the license.
Reader Comments
Hey Ben,
Interesting read. I think that I've also seen similar behaviour with remote methods which are being called as a web service.
So if I'm publishing a method using access="remote" and an exception occurs when a client is calling it, the exception is not logged in the servers exception logs.
Makes debugging these kinds of things notoriously hard.
I can't be sure that the behaviour I saw was genuin and not provoked by something which I was doing but I remember it frustrating the hell out of me, getting consumers of the web service contact me with exceptions they were getting and me not being able to get the proper stack-trace in the logs.
Robert
@Robert,
Very interesting. I don't use remote methods all that often, but I can certainly try that out for myself. Remote methods are definitely a bit different in that ColdFusion packages up the invocation and the response implicitly. So, in a way, they are special events like onApplicationEnd() and onSession() (which are not tied to any particular request).
I'll have to play around with that a bit.
@Ben,
Great stuff. One GOTCHA to be aware of, if you're building a client .cfm file using a <cfinvoke> to call the remote method then the exception will be logged, but by the calling .cfm and not the .cfc method.
So on first glance when testing it may appear that you're getting an exception logged, but this might not be an accurate depiction of a scenario when the client script is not sat on your server.
:-)
Robert
Hi Ben
Have you checked the CF bug tracker to see if there's a bug raised for this, and if not, have you raised one?
--
Adam
@Robert,
I'll see what I can come up with.
@Adam,
I did a quick search for onSessionEnd() and didn't seen anything in particular. I'll log a bug for it.
Hi Ben.
I saw that you've raised http://cfbugs.adobe.com/cfbugreport/flexbugui/cfbugtracker/main.html#bugId=83515. I've voted for it.
Cheers.
--
Adam
@Adam,
Awesome my man, thanks!
@Robert: I too hate the non-logging of cffunctions with access="remote" invoked as Web Services.
If you invoke them using a REST call (filename.cfc?method=xxx&arg=yyy&etc) in a browser, you get both a screen dump and logged errors. But that's not too useful for us, because we often need to pass a lot of data.
Here's what works for us: In the cffunction, build some Variables-scope variables from the Arguments scope, then cfinclude a worker routine in a cftry/cfcatch block, then cfreturn success and/or failure data. We like to use a struct for the returned data, which allows success data to be returned along with error data, as appropriate.
Don't try to reference the Arguments scope or cfreturn from inside the worker routine. At the time you do the call, test whether or not you're on the same machine as the CFC. If so, build the same Variables-scope data and cfinclude the exact same worker routine (much less overhead). If not on the same machine, invoke as a Web Service. Either way, you get error information.
We like to employ a naming convention where the cffunction name appears as part of the filename of the worker routine. That way, if something messes up, we know which file to look in.
Hope this helps.
@Steve,
Ah, so you've also experience the remote-access non-logging. I guess that confirms that it truly happens (I have not yet gotten around to testing it myself). Funky stuff.
Hi,
Apparently, when the session ends, you will not be able to access what ever was stored in the session because the session will have expired, thus you cannot access the variables in SessionScope in onSessionEnd.
Is this true?
If it is not, how is it that one will be able to access the session variables which will have expired in OnSessionEnd?
Thanks,
Nich
@Nich, onSessionEnd does not give you direct access to the Application and Session scopes. So that you should ARGUMENT them, like:
<!--- OnSessionEnd routine --->
<cffunction
name="OnSessionEnd"
access="public"
returntype="void"
output="false"
hint="running when session end and it is triger when we defined explicit sessionTimeout value into application settings">
<!--- Define arguments.-->
<cfargument
name="sessionScope"
type="struct"
required="true"
hint="I am the session scope used by the session."
/>
<cfargument name="appScope"
type="struct"
required="true"
hint="I am the application scope used by the session."
/>
<!--- executing an update for an defined session variable, session.username declared in onSessionStart... --->
<!---
suppose that:
application.adata = DNS DB defined in onApplicationStart
session.somevalue = value of table field from a db that you have tracked since session started... here i am updating an user status into db table :)
--->
<cflock name="myLock" type="Exclusive" timeout="5">
<cftransaction action="begin">
<cfquery name="upStatus" datasource="#ARGUMENTS.appScope.adata">
update mytable
set loggedin = false
where userid = <cfqueryparam value="#ARGUMENTS.sessionScope.somevalue" cfsqltype="cf_sql_bigint">;
</cfquery>
</cftransaction>
</cflock>
<cfreturn />
</cffunction>
@Rani Thank you for the info.
Hey Ben,
A really helpful page. One thing I don't see here is if it's possible to invoke a cfcomponent without a return value from inside onSessionEnd.
I want to do that but don't really see examples on the various sites. Something like
<cffunction name=onSessionEnd...
<cfinvoke component="endOfSessionData" method="writeData" />
... doesn't need to return a value, just run the function in the component.
All I want onSessionEnd to do is run a component in my CFC folder that writes a session array back to the DB. Cannot get it to work.
Great site!
Gerald