"Session closed. There are xxx sessions remaining."

Targets Web
1

Running my stand-alone web app in the debugger, I am now seeing thousands of the following in the IDE console:

Session closed. There are xxx sessions remaining.

xxx usually starts in the mid-200’s or 500’s and it counts down around 5 per second. It rarely (if ever) reaches zero–it adds another 200+ at some point and then keeps counting down.

Sometimes it pauses for a 20-90 seconds–usually kicking all the connected users out whenever that happens.

I’ve searched for “remaining” and “closed” in my code, but they are not present–so the console messages are NOT part of my code!

If I pause the application, it shows that it’s just in the default Xojo Event Loop–not running any of my code.

Anyone have any ideas?

Versions & Stuff:
Stand-alone Web App running on Windows server 2016.
Previous version of the app has been running for years without issue.
I rebuilt it using Xojo 2018r4, MBS 2019.1, and updated GraffitiSuite (don’t have version handy) and it ran for several weeks before the web app kicked everyone out and stopped responding this morning.
Restarting the server and the app didn’t solve the problem (it runs for a minute or so and then locks up again), so I ran it in debug mode in the IDE to try to track down what’s going on.
In debug mode, I found the above console messages, and it doesn’t seem to lock up entirely like the built app was this morning. It still kicks people out every few mintues and then they have to reconnect to it.

2

I just did a search in my app for MBS since I used those plugins a lot in my applications. This particular app only uses CURLSMBS and SQLDatabaseMBS, so it seems unlikely that MBS is involved.

3

This messages are perfectly normal for Webapps running in the debugger. As are the statistics that are spit out after quitting the debug app. What would concern me more is where the heck are the 200-500 sessions to the debug-app coming from?

I can only speculate that there is something constantly polling the url/ip and port the debug app is running on. The app then creates for each new request a session which is never connected and thus the cleanup thread has to remove them after the timeout. Such a scenario can cause high load and combined with even a tiny memory leak can kill the app in the end.

4

I agree with the oddity about where all the sessions are coming from:

The session.open event logs all connections–but it’s not showing hundreds of sessions starting per minute (just a handful of legit users per hour).

There is a HandleSpecialURL method, but it only opens a relative handful of those daily, and logs those, too.

What else could be opening the hundreds of sessions without triggering either HandleSpecialURL or session.open?

5

Are you running on port 80, and have installed Apache or something else that wants to also use that port?

6

Session.Open is only fired if a Session was fully established with a working Ajax/SSE connection to the Browser. Just do some tests yourself, to help I’ve prepared a little demo: https://www.dropbox.com/s/cf6raqjnb7zpoi4/Xojo_Web_Session_Start_End.xojo_binary_project?dl=1 this shows the following event order in several cases:

[code]* Regular Browser
10:28:02 : My Application Launched
Feb 20 10:28:02 My Application.debug[29724] : Session.Constructor 4FE02DA8A22E0FB0FB78319E4C8B69034D4EC8DB
Feb 20 10:28:02 My Application.debug[29724] : Session.PrepareSession 4FE02DA8A22E0FB0FB78319E4C8B69034D4EC8DB
10:28:03 : Feb 20 10:28:03 My Application.debug[29724] : Session.Open 4FE02DA8A22E0FB0FB78319E4C8B69034D4EC8DB
10:28:58 : Session closed. There are 0 sessions remaining.
Feb 20 10:28:52 My Application.debug[29724] : Session.Close 4FE02DA8A22E0FB0FB78319E4C8B69034D4EC8DB
Feb 20 10:28:55 My Application.debug[29724] : Session.Destructor 4FE02DA8A22E0FB0FB78319E4C8B69034D4EC8DB
10:29:02 : My Application Ended

  • $curl -v --compressed http://127.0.0.1:8080
    11:02:08 : Feb 20 11:02:08 My Application.debug[29803] : Session.Constructor D277DEE34DD11B9378B848E39CE29D17ADEBC600
    Feb 20 11:02:08 My Application.debug[29803] : Session.AllowUnsupportedBrowser D277DEE34DD11B9378B848E39CE29D17ADEBC600 False
    11:02:44 : Session closed. There is 1 session remaining.
    Feb 20 11:02:44 My Application.debug[29803] : Session.Close D277DEE34DD11B9378B848E39CE29D17ADEBC600
    Feb 20 11:02:44 My Application.debug[29803] : Session.Destructor D277DEE34DD11B9378B848E39CE29D17ADEBC600

  • Browser with disabled JS
    11:44:07 : Feb 20 11:44:07 My Application.debug[29803] : Session.Constructor 310998A39F301E4C9779A203FA9C8129F40A529A
    Feb 20 11:44:07 My Application.debug[29803] : Session.PrepareSession 310998A39F301E4C9779A203FA9C8129F40A529A
    11:44:47 : Session closed. There is 1 session remaining.
    Feb 20 11:44:47 My Application.debug[29803] : Session.Close 310998A39F301E4C9779A203FA9C8129F40A529A
    Feb 20 11:44:47 My Application.debug[29803] : Session.Destructor 310998A39F301E4C9779A203FA9C8129F40A529A
    [/code]
    Further, please have a look to https://forum.xojo.com/51945-session-close-event-firing-without-a-session-open where a similar topic was discussed.

7

David, Lots of other apps/services running on that server (mostly Xojo stand-alones), but none on the same TCP ports, and this app didn’t use port 80.

Tobias, Thanks for the great info and links–I’ve learned a lot more about Xojo’s handling of web sessions and the debugging console as a result of this particular issue (despite 5+ years of building numerous successfully deployed mission-critical business workflow web apps in Xojo). There’s always more to learn!

Looks like I was being slammed with thousands of illegitimate requests–possibly hacking attempts. I’ve seen waves like that hit plenty of services in the past, but it seems more than coincidental that this particular app ran fine for three years until just a week or so after I recompiled it in 2018r4. In any case, here’s what I tracked down and changed to fix it:

One feature of the app requires it to accept info pushed from an external source that doesn’t allow IP restrictions because their randomly-timed pushes “use a variety of IP addresses from ranges that can change at any time.”

Since it can’t restrict by IP, the app performs a variety of validation on every connection attempt to make sure it’s a legitimate, well-formed push --everything else is immediately redirected elsewhere.

All indications are that the redirects were working properly to dump the thousands of illegitimate connection attempts during the request storm–they were all failing the first of several validation checks–but with the side-effect of bogging down the system to the point of kicking off legitimate internal users.

I was able to resolve the problem last night through a combination of security-tightening measures. I won’t list them all here, but it included tweaking the firm’s hardware firewall settings to use non-IP methods of catching more illegitimate requests before they reach the server/app so that it doesn’t have to filter as many itself. The app is now back to normal (which is to say, zero unexpected sessions or connection attempts since I made the changes, but lots of measures in place for when they eventually happen).

8

Seth, glad I could be of help here. For the filtering stuff, I would recommend to do it even earlier in App.HandleURL and Return True to discard illegitimate requests w/o the overhead of starting a session at all. However, there seems to be a bug in case the Path is empty (/) where a Session is stated anyhow. I’ve updated the sample project at the link above to demonstrate this. For the mentioned problem, I’ve opened <https://xojo.com/issue/54973>

9

Thanks for the additional useful info Tobias! Hopefully they’ll fix that in 2019r1!