CFML sessions not timing out

[Christian Meis]

Hi group,

in search of the reason for Java memory problems with a live app, I came across this:

First for the environment:

The app is running in Lucee 4.5.3.018 final on Tomcat 8.0.24, Java 8. The server is CentOS 6 64-bit, dedicated to the application alone.

The app is using CFML sessions with a session timeout of 180 seconds. It's being used by thousands of users over each day, but every

single interaction is rather short with the user just clicking through 2 or 3 pages.

Now for the problem:

It looks like sessions never expire and session data is being kept forever. This leads to the heap filling up and sometime further down the 

road Tomcat will just crash with an OOM.

I don't see a reason why the sessions shouldn't timeout. 

I have been counting the sessions using somehting like this code snippet:

<cfset sessionTracker = createObject("java","coldfusion.runtime.SessionTracker")>

<cfoutput>#sessionTracker.getSessionCount()#</cfoutput>

I'm aware of comments that accessing the session this way will perhaps update the sessions' "lastAccessed" timestamp and prevent 

the session from timing out. Although I'm not sure if this - if at all - won't happen only if accessing a specific session with

getSessionCollection() and working from there.

But even if I check the session number this way only every 30 minutes - which is way over the session timeout of 3 minutes - sessions

still keep stacking up.

Has anyone seen similar behaviour?

Any suggestions for the easiest/quickest way to identify the source of the problem?

Best regards,

Christian

[Jochem van Dieten]

On Sep 20, 2016 16:52, "'Christian Meis' via Lucee" wrote:
> It looks like sessions never expire and session data is being kept forever. This leads to the heap filling up and sometime further down the 
> road Tomcat will just crash with an OOM.

The first thing I would do is put some logging in onSessionEnd and see if it gets triggered.

Jochem

[Christian Meis]

Hi Jochem,

sorry, and thanks for pointing out the obvious.

I forgot to mentioned this in my original post. I have injected logging to file in the onSessionStart/onSessionEnd routines.

No session end is being logged...

Christian

[Mark Drew]

Does this even work? 

Looks like the session tracker has been implemented in Lucee (although I would say it shouldn’t!) 

you can see the code here:

https://github.com/lucee/Lucee/blob/9eb38f0e565c94cc3c496f455eb94ba7535b5d94/core/src/main/java/coldfusion/runtime/SessionTracker.java

and that calls the ScopeContext:

https://github.com/lucee/Lucee/blob/9eb38f0e565c94cc3c496f455eb94ba7535b5d94/core/src/main/java/lucee/runtime/type/scope/ScopeContext.java#L312

Which just loops through the items and counts them, doesn’t look like it would update them. 

MD 

[Christian Meis]

Mark, what do you mean by "does this even work"?

Counting the sessions using the getSessionCount() function? This seems to work, i.e. it's not throwing an error and giving an result which looks reasonable enough for me.

Christian

[Mark Drew]

Yeah, it works, I am just surprised since it’s a coldfusion object not a lucee one. But I just did a check and it has been implemented. 

I was just typing as I was thinking before I checked the code. So anyway, using that function shouldn’t update the sessions. 

MD 

[Christian Meis]

So what could be the reason for sessions not timing out or onSessionEnd not being called?

I'm PRETTY sure the clients really "go away". This is some kind of "captive portal login page", i.e. the users are logging in here and then more or less never should get back here.

Tests with our own devices and know session ids and logging all requests with their respective session ids also shows that users behave as expected ;-)

Christian

[Mark Drew]

Hi there

“The first thing you should do is actually see what is in the memory or what is filling it up.  Can you post your setenv.sh ? Also you should install Fusion Reactor to see what is really going on. 

Is the actual problem getting out of memory problems rather than sessions being stored? Could be anything that is filling up the memory rather than just sessions?

If you are counting the sessions, do you have a log of session over time? 

How much is in each session too?  Does shortening the session time help?

MD 

[Christian Meis]

Hi Mark,

as I stumbled upon this issue while searching for the reason of out of memory conditions, I cannot rule out other things are part of the problem here, too.

Sooner or later Tomcat is crashing because memory is filled up - which obviously is the real problem. I wouldn't mind sessions being stored "too long".

But when sessions aren't destroyed even hours after the last request (with session timeout set to 3 minutes), something's wrong here nevertheless.

The setenv.sh is like this:

============ 8< ======================

CATALINA_OPTS="-Xms1512m -Xmx1512m \

        -XX:+HeapDumpOnOutOfMemoryError -XX:HeapDumpPath=/opt/heapdumps \

        -Djava.security.egd=file:/dev/./urandom \

        -javaagent:lib/lucee-inst.jar \

        -Dcom.sun.management.jmxremote \

        -Dcom.sun.management.jmxremote.port=5022 \

        -Dcom.sun.management.jmxremote.ssl=false \

        -Dcom.sun.management.jmxremote.authenticate=false \

        -Dcom.sun.management.jmxremote.local.only=false \

        -Djava.rmi.server.hostname=localhost";

export CATALINA_OPTS;

============ 8< ======================

The JXM remote management config was used to connection VisualVM to the server better see what's going on here.

So I'll try to install FusionReactor to get a better insight in to what really is using up all the memory.
I never used FR before - any hints regarding where to look? As the FR website states "FusionReactor is not built for memory analysis down to the object level."

I had thought FR only would allow me to see IF there are those kinds of problems, and I would have to start taking apart a heap dump to see what's really 

hogging all this memory.

Having started to take apart a heap dump with VisualVM, I still have a hard time pointing my finger on something.

One thing I noted was there were a LOT of strings containing typical data from my sessions.

That really was the point where I started to look after how many sessions were active and came across the original topic here - sessions accumulating and not being destroyed.

Unfortunately I don't have a chart/log of sessions over time. But - depending on usage - the estimated session creation rate could have been about 1 to 3 sessions/sec I guess. 

I would have to implement logging for this, but don't see how it would affect the problem?

Christian

[Mark Drew]

I would see if you can log your memory in a file and you can graph the number of sessions. That would be an easy way to see how much space they are using, even if you then put in a timestamp and the quantity, you can see if that is the actual reason or the memory is not being garbage collected. 

What is IN the session? is just simple values

session.name = “bob”

or do you have queries/components etc?

MD 

--
Get 10% off of the regular price for this years CFCamp in Munich, Germany (Oct. 20th & 21st) with the Lucee discount code Lucee@cfcamp. 189€ instead of 210€. Visit https://ti.to/cfcamp/cfcamp-2016/discount/Lucee@cfcamp
---
You received this message because you are subscribed to the Google Groups "Lucee" group.
To unsubscribe from this group and stop receiving emails from it, send an email to lucee+un...@googlegroups.com.
To post to this group, send email to lu...@googlegroups.com.
To view this discussion on the web visit https://groups.google.com/d/msgid/lucee/fce858a9-0b1f-4eed-9e9d-80d730be0f88%40googlegroups.com.
For more options, visit https://groups.google.com/d/optout.

[Christian Meis]

Mark, first I appreciate that you spend your time on this!

The session contents are some structures containing only simple values (strings, integers).

A typical session will probably be about 7 to 10 kB worth of data, after a quick calculation.

Those are some dozen simple strings, and some html snippets / template parts dynamically generated / individualized which are used to construct the answers to the clients.

Christian

[Mark Drew]

One option would be to move the session storage to something else to see if that is actually the case. You can set sessions to be stored in a database, or mongoDB for example

(here is a gist of some of the steps: https://gist.github.com/roryl/44f730ecd8ba2593b03e45f1189fcf5f) 

that way you know that ram isn’t being used for sessions.  I would have to know more to help you out more of course! 

MD 

To view this discussion on the web visit https://groups.google.com/d/msgid/lucee/b735970b-9452-4186-a218-b7866a77c29f%40googlegroups.com.

[Christian Meis]

Moving session storage to the database might be a good ideo to isolate the source of the problem.

I just have to find a time slice to do this config change on the production system.

I'll keep you posted!

Christian

[Christian Meis]

OK, moved session storage to the database on short notice ;-)

This is only running for about 16 minutes with this configuration, and as I said there's not that much load/users on the system during this time of the day.

From a first look it does seem though that the growing memory usage is not there anymore. I'll have some more hours to tell more definitely.

But this seems to point to the fact that sessions are the problem and not ended (as the onSessionEnd() isn't called, too). So GC cannot get rid of them.

This will create the problem at another location: the database will fill up with stale session data. I can even now see that session data from sessions that

SHOULD have time out still are in the database.

I haven't found something in the docs, but I assume that Lucee should be doing the housekeeping for session data in the database, too? Or will I have

to take care of that myself (i.e. deleting old data after their "expires" value)?

Christian

[Mark Drew]

I think that is left up to you to clear up to be honest as sessions *could* be resumed somehow. 

Just make a query and get SQL server to run it at intervals (can one do this?) 

MD 

[Christian Meis]

OK, I'll take care of acting as the cleaning maid for the database later on ;-)

What get's me is that onSessionEnd() isn't called at - well - session end. Or when the session end SHOULD be.

I remember a thread in this group some time ago about onSessionEnd() not being called with clustered sessions, as it wouldn't be clear WHEN a session really ends.

But here there's no clustering involved.

For several reasons I'd like to keep the session storage in RAM rather than the database.

So if the problem of Lucee not ending the sessions / detecting the session end is solved, I could put the session storage back to RAM as I suppose that GC would then keep everything nice and tidy.

So what would be the way to trace the reason for Lucee missing the right time to end a session due to a session timeout?

For completeness I should probably add that Lucee is sitting behind a loadbalancer here, BUT this shouldn't be relevant: There's only ONE Lucee server behind it (so NOT really load-balancing right now, only SSL offloading 

and being prepared for loadbalancing later on).

Does that make sense?

Christian

[Christian Meis]

Last observation before leaving office:

The session count (via sessionTracker.getSessionCount()) now DOES get lower from time to time now, and definitely is WAY lower than the number of sessiondata records in the database.

So Lucee seems to actually end sessions in this setup (as opposed to when the session storage is in RAM).

Christian

[Mark Drew]

All this makes sense and lucee *SHOULD* be running on Session end. 

My advice would be to copy your code, create a new server (dev) and do early returns in all the functions of the application and then see if onSessionEnd is running with basically no code running and then add code until I find out what it is. This is a basic function and I doubt it would not be working for everybody (so it would be something in your code) 

Regards

Mark Drew

[Jochem van Dieten]

On Sep 20, 2016 18:07, "'Christian Meis' via Lucee" wrote:
> So what could be the reason for sessions not timing out or onSessionEnd not being called?

You are using JEE / Tomcat sessions right? Have you configured the sessions through Lucee or through the session-config element in web.xml?

Jochem

[Christian Meis]

I configured the webcontext in Lucee for CFML sessions.

Christian

--

Get 10% off of the regular price for this years CFCamp in Munich, Germany (Oct. 20th & 21st) with the Lucee discount code Lucee@cfcamp. 189€ instead of 210€. Visit https://ti.to/cfcamp/cfcamp-2016/discount/Lucee@cfcamp
---
You received this message because you are subscribed to the Google Groups "Lucee" group.

To unsubscribe from this group and stop receiving emails from it, send an email to lucee+unsubscribe@googlegroups.com.

To post to this group, send email to lu...@googlegroups.com.

To view this discussion on the web visit https://groups.google.com/d/msgid/lucee/CABPCP-2HMMX2vT_TiHcyfV1698Zd1X2Y%3Dg4TH1Yav%2BjZQJ8PWQ%40mail.gmail.com.

[Christian Meis]

OK, so now Lucee is running on this box for roughly 19 hours, and the memory leakage is gone.

What's strange though:

The database shows data for over 63.000 sessions, but Lucee only has about 600-800 sessions active, if I can trust the "sessionTracker.getSessionCount()" construct.

So it LOOKS like Lucee is really somehow ending the sessions.

On the other hand, the logging in the onSessionEnd is NEVER triggered, so Lucee doesn't seem to call onSessionEnd?!

(The logging from onSessionStart is showing all new sessions correctly ...)

 

My advice would be to copy your code, create a new server (dev) and do early returns in all the functions of the application and then see if onSessionEnd is running with basically no code running and then add code until I find out what it is. This is a basic function and I doubt it would not be working for everybody (so it would be something in your code) 

I'll do that, but:

- I am sure (by having debugged some of my own sessions there also with a packet sniffer etc.) that after the user is finished using the app, he/she will not again send any request to this server.

- We don't run anything on this server that could in any way "re-trigger" the sessions, so no scheduled tasks, gateways, cronjobs, whatever.

So what should our code have to do with a session not timing out?

The ONLY thing I could imagine is something like a hanging database connections from requests in this session. Would that cause Lucee to keep the session? Just thinking loud.

Christian

[Paul Klinkenberg]

Hi Christian,

Have you read the discussion "onSessionEnd doesn't call if using sessionstorage to database": https://groups.google.com/forum/#!topic/lucee/sAbPehQ8KCc

It seems, onSessionEnd is by Lucee's design not meant to be called. At least in March 2015, when the discussion was active.

Whether the getSessionCount() method is telling the truth, can be checked by also querying your MSSQL storage:

select name AS applicationName
   , count(1) as totalSessionNum
   , SUM(CASE WHEN expires >= #getTickCount()# THEN 0 ELSE 1 END) AS expired
   , SUM(CASE WHEN expires < #getTickCount()# THEN 0 ELSE 1 END) AS valid
from cf_session_data
GROUP BY name
ORDER BY 1

A small discrepancy between the 2 is okay, because the server's session data (in memory) is sent to the DB storage asynchronous.

I ran the sessionTracker.getSessionCount() code with debug info on, and my sessionStorage set to database. I did not see any extra call to my database server in the debug log, while checking the sessions in the database would have been the *only* way for Lucee to find out the correct amount of active sessions, because the test server is within a Lucee cluster, as noted in Application.cfc with "this.sessionCluster=true;".

Conclusion: sessionTracker.getSessionCount() does not work correctly on (at least) clustered configurations.

Kind regards,

Paul Klinkenberg

--
Get 10% off of the regular price for this years CFCamp in Munich, Germany (Oct. 20th & 21st) with the Lucee discount code Lucee@cfcamp. 189€ instead of 210€. Visit https://ti.to/cfcamp/cfcamp-2016/discount/Lucee@cfcamp
---
You received this message because you are subscribed to the Google Groups "Lucee" group.
To unsubscribe from this group and stop receiving emails from it, send an email to lucee+un...@googlegroups.com.
To post to this group, send email to lu...@googlegroups.com.

To view this discussion on the web visit https://groups.google.com/d/msgid/lucee/6cb61a1d-bfd8-4cad-aed7-8fbf9102a906%40googlegroups.com.

[Christian Meis]

Hi Paul,

yes, now I remember having read that thread back then ;-)

I didn't bother to look into the source code, but will assume the behaviour still is the same.

I think your query is the wrong way - if getTickCount is GREATER than the expires field, the session should still be valid?!

Anyway. I think I'll have to go the hard way and try to strip of the source code piece by piece to see where the problem might be triggered.

(On a dev system with the sessions in RAM, so onSessionEnd will really get called.)

Christian