My current objective is to run a query whenever a session ends in my app, but I can’t seem to get the onSessionEnd() function defined in my Main.cfc handler to fire.
In my application.cfc, the onSessionEnd() function looks like this:
This is what my onSessionEnd() function looks like in the Main.cfc handler. I have tried writing to the console, changing the database, sending emails, and setting the event view all from the handler on my session timeouts, but nothing has been getting through.
At first glance, you’ve got it set up correctly. However, there’s a lot of debugging between “Meh, looks right” and “oh, I see!”.
I would walk through the basic debugging steps:
Throw a debugging statement into the Application.onSessionEnd() so you KNOW it is firing. Something basic that doesn’t require coldbox, complex logging config, or an eye-on-console to see.
e.g.
function onSessionEnd(){
var appPath = getDirectoryFromPath( getCurrentTemplatePath() ) ;
var currentTime = dateTimeFormat(now(), 'yyyy-mm-dd hh:nn:ss');
fileAppend( "#appPath#/session.log", "SESSION ENDED! #currentTime#");
}
Re-run the app and look for this line. You should see it roughly 10 seconds after each request, assuming session timeouts do what I think they do.
Do the same for your Main.onSessionStart().
Check every assumption.
a. Does arguments.appScope exist?
b. What about arguments.appScope.cbBootstrap?
c. If your Application.onSessionEnd() throws an error, where does it go? Does Lucee fire the onError() for these, or not? (It would certainly not fire any Coldbox error handling if the error happened OUTSIDE of Coldbox’s control.)
You never mentioned checking Lucee’s logs. There are a number of them, and it’s possible an error is being logged to a file, but not to the console.
I have tried writing to the console, changing the database, sending emails, and setting the event view all from the handler on my session timeouts, but nothing has been getting through.
Stick to something basic. Even referencing a single non-existent variable could be blowing this code path into lost-exception-hell. (a new phrase… I’m working on the terminology.)
TLDR: I would strongly suspect there’s an exception early on which is never handled and either not logged, or not noticed.
Does your Application.cfc have the boilerplate to call ColdBox’s on session end handler? If not, ColdBox will never get tapped. Also, put in some error logging with a try/catch. If it errors, you’d never know since it’s not tied to a specific page request.
Using your code, I was able to figure out that the onSessionEnd() and onSessionStart() functions in the application.cfc are both firing correctly and writing to a session.log file.
Using the isDefined() function, I was able to find out that both arguments.appScope and arguments.appScope.cbBootstrap both exist.
On your last two bullet-points (4c and 5) I may need some more assistance. How do I find out where the errors are being caught? Also, you mention Lucee’s logs. Are these the logs that come up when I enter server log --follow into commandbox? I don’t currently have any log files stored in my app’s directory.
On your last two bullet-points (4c and 5) I may need some more assistance. How do I find out where the errors are being caught? Also, you mention Lucee’s logs. Are these the logs that come up when I enter server log --follow into commandbox? I don’t currently have any log files stored in my app’s directory.
Add an function onError(){} method to your Application.cfc. Write out arguments.exception.message to your custom log/debug file. See docs.
I did not see anything added to the error.log file.
I opened up the Lucee logs using the instructions from Brad’s article. I’m not 100% sure what I’m looking for, but I used ctrl + f to look for any occurrences of onSessionEnd(). It didn’t look like any errors were surrounding the text associated with that text. I didn’t find anything with ctrl + f “OnError” either.
Is there anything specific that I should be searching for in the logs?
That’s fine - I think you looked in the right place for the right clues. You probably won’t find anything there, since Brad implied Lucee won’t fire onError() for exceptions during an onSessionEnd() execution:
Since that’s the case, wrap the entire contents of your onSessionEnd() in a try/catch block and log the result. This should tell you when and where the failure is.
After using going through the life cycle of a session, here’s what my session.log file looks like:
Session started... 2023-02-03 09:02:35Session started... 2023-02-03 09:02:49Session started... 2023-02-03 09:02:52Session started... 2023-02-03 09:03:05SESSION END INITIATED! 2023-02-03 09:03:31SESSION END SUCCESS! 2023-02-03 09:03:31SESSION END INITIATED! 2023-02-03 09:03:31SESSION END SUCCESS! 2023-02-03 09:03:31
No sessionEndError.log file was created, so it looks like this function isn’t erroring out. I’m curious that the problem may be coming from someplace else.
Dunno, you’re going to have to trace through and see what code is running or not running. The log file thing seems cumbersome. Just systemOUtput() to the console, set your session time out very small and you can trace through the code and see what runs and what doesn’t. Test your onsessinoend event in COldBox by hitting it directly to make sure it works.
So I finally found out the issue. Thanks to your help here, I have a solution:
It looked like the problem was my main.OnSessionEnd() event was not firing in the first place. I incorrectly lead this point by saying I had defined main.OnSessionEnd() as a value for the SessionEndHandler in my Coldbox.cfc. I did not (my bad)!
I had ended up showing you that I defined the SessionEndHandler key in a settings.cfc file under the path root/coldbox/system/web/settings.
Once I defined the correct sessionEndHandler key in coldbox.cfc I was good to go. This involved a lot of console/file output for debugging.
Thanks so much again for taking a look at this, but for future reference is there a better way to output to the console so it doesn’t get buried by Coldbox’s normal logging? I spent quite a bit of time using ctrl+f to find my debug messages that most of the time ended up getting binned. I’m assuming there’s a limit of the amount of characters that can live in the commandbox output for the server log --follow command.
This is a whole 'nuther topic, but basically… there is no normal level of logging for ColdBox. You have the ability (and, honestly, the responsibility) to tweak it if you’re seeing too much or too little output. Sounds like you have some level of debugging output enabled, so ColdBox is dumping logs to the console in the form of INFO or DEBUG or even TRACE messages.
I would suggest configuring a coldbox logging category (if not already defined) which sets the levelMax to WARN so you don’t get flooded by DEBUG or INFO-level messages.
Yeah, just control your logbox settings to dial up or down how much logging you see from ColdBox itself. You probably have something like this in your ColdBox.cfc
The info : [ "coldbox.system" ] line controls what messages you see from ColdBox. You can set it to error or off instead of info while testing.
No, not really. CommandBox will happily output an unlimited amount of text. The limit exists in the settings of your terminal app and is usually called “buffer” or similar. I don’t know what terminal/OS you’re using, but here’s a screenshot of my Windows CMD settings, where I’ve cranked the buffer size up to 9001 (because then it’s over 9000 ) I forget what it is by default, but it’s pretty small. This allows you to scroll back much farther.
) I forget what it is by default, but it’s pretty small. This allows you to scroll back much farther.
