Some Eclipse Foundation services are deprecated, or will be soon. Please ensure you've read this important communication.

Bug 425930

Summary:	JDBC Session Manager constantly reloading session if save intervall expired once
Product:	[RT] Jetty	Reporter:	Christoph Laeubrich <laeubi>
Component:	server	Assignee:	Jan Bartel <janb>
Status:	RESOLVED FIXED	QA Contact:
Severity:	critical
Priority:	P3	CC:	fuhrmann.hauke, janb, jetty-inbox
Version:	8.1.13
Target Milestone:	9.1.x
Hardware:	PC
OS:	All
Whiteboard:

Description Christoph Laeubrich

2014-01-16 14:00:07 EST

If the session is not changed for "saveintervall" seconds the session is reloaded from the db. From this point on, the session is reloaded on each request since the lastsavetime read from db will be of course always smaller.

This puts unneccesary load on the db as well as deserializing tasks to the CPU.

Beside this: What is the point in releoading the session at all? It seems redundant and IMO should be not coupled to the savelastaccess but having a seperate setting for this, maybe even with a setting to disable this behaviour at all.

See this debug output that shows a continious update every second that do not change the session, the first 60 seconds it finds the session in cache, then it reloads everytime:
09:58:12.229  (JDBCSessionManager.java:468) getSession(nodeIDno9gfce4424d13ozjr5pmj9il): in session map,  now=1389862692229 lastSaved=1389862591624 interval=60000 lastNode=nodeID thisNode=nodeID difference=100605 [qtp3413279-26] 

09:58:12.230  (JDBCSessionManager.java:486) getSession(nodeIDno9gfce4424d13ozjr5pmj9il): stale session. Reloading session data from db. [qtp3413279-26] 

09:58:13.369  (JDBCSessionManager.java:836) LOADED session Session rowId=_0.0.0.0_nodeIDno9gfce4424d13ozjr5pmj9il,id=nodeIDno9gfce4424d13ozjr5pmj9il,lastNode=nodeID,created=1389862480092,accessed=1389862665854,lastAccessed=1389862586593,cookieSet=0,lastSaved=1389862666339,expiry=1389864465854 [qtp3413279-26] 

09:58:13.369  (JDBCSessionManager.java:537) getSession(nodeIDno9gfce4424d13ozjr5pmj9il): Session not stale Session rowId=_0.0.0.0_nodeIDno9gfce4424d13ozjr5pmj9il,id=nodeIDno9gfce4424d13ozjr5pmj9il,lastNode=nodeID,created=1389862480092,accessed=1389862665854,lastAccessed=1389862586593,cookieSet=0,lastSaved=1389862666339,expiry=1389864465854 [qtp3413279-26] 

09:58:13.555  (JDBCSessionManager.java:468) getSession(nodeIDno9gfce4424d13ozjr5pmj9il): in session map,  now=1389862693554 lastSaved=1389862591624 interval=60000 lastNode=nodeID thisNode=nodeID difference=101930 [qtp3413279-29] 

09:58:13.561  (JDBCSessionManager.java:486) getSession(nodeIDno9gfce4424d13ozjr5pmj9il): stale session. Reloading session data from db. [qtp3413279-29] 

09:58:14.548  (JDBCSessionManager.java:836) LOADED session Session rowId=_0.0.0.0_nodeIDno9gfce4424d13ozjr5pmj9il,id=nodeIDno9gfce4424d13ozjr5pmj9il,lastNode=nodeID,created=1389862480092,accessed=1389862665854,lastAccessed=1389862586593,cookieSet=0,lastSaved=1389862666339,expiry=1389864465854 [qtp3413279-29] 

09:58:14.548  (JDBCSessionManager.java:537) getSession(nodeIDno9gfce4424d13ozjr5pmj9il): Session not stale Session rowId=_0.0.0.0_nodeIDno9gfce4424d13ozjr5pmj9il,id=nodeIDno9gfce4424d13ozjr5pmj9il,lastNode=nodeID,created=1389862480092,accessed=1389862665854,lastAccessed=1389862586593,cookieSet=0,lastSaved=1389862666339,expiry=1389864465854 [qtp3413279-29] 

09:58:17.223  (JDBCSessionManager.java:468) getSession(nodeIDno9gfce4424d13ozjr5pmj9il): in session map,  now=1389862697223 lastSaved=1389862591624 interval=60000 lastNode=nodeID thisNode=nodeID difference=105599 [qtp3413279-29] 

09:58:17.223  (JDBCSessionManager.java:486) getSession(nodeIDno9gfce4424d13ozjr5pmj9il): stale session. Reloading session data from db. [qtp3413279-29] 

09:58:18.304  (JDBCSessionManager.java:836) LOADED session Session rowId=_0.0.0.0_nodeIDno9gfce4424d13ozjr5pmj9il,id=nodeIDno9gfce4424d13ozjr5pmj9il,lastNode=nodeID,created=1389862480092,accessed=1389862665854,lastAccessed=1389862586593,cookieSet=0,lastSaved=1389862666339,expiry=1389864465854 [qtp3413279-29] 

09:58:18.305  (JDBCSessionManager.java:537) getSession(nodeIDno9gfce4424d13ozjr5pmj9il): Session not stale Session rowId=_0.0.0.0_nodeIDno9gfce4424d13ozjr5pmj9il,id=nodeIDno9gfce4424d13ozjr5pmj9il,lastNode=nodeID,created=1389862480092,accessed=1389862665854,lastAccessed=1389862586593,cookieSet=0,lastSaved=1389862666339,expiry=1389864465854 [qtp3413279-29] 

09:58:19.546  (JDBCSessionManager.java:468) getSession(nodeIDno9gfce4424d13ozjr5pmj9il): in session map,  now=1389862699545 lastSaved=1389862591624 interval=60000 lastNode=nodeID thisNode=nodeID difference=107921 [qtp3413279-28] 

09:58:19.546  (JDBCSessionManager.java:486) getSession(nodeIDno9gfce4424d13ozjr5pmj9il): stale session. Reloading session data from db. [qtp3413279-28]

Comment 1 Jan Bartel

2014-01-17 03:32:50 EST

Laeubi,

Can you confirm this happens with jetty-9.1.x?

Also, can you show me the full log from where the session is first created? The first log line shows session nodeIDno9gfce4424d13ozjr5pmj9il in memory has lastSavedTime=1389862591624, yet the lastSavedTime in the database is later than that at 1389862666339 - I can't immediately see how that can be the case, so I'd like the full log for that session please. Also include your configuration settings for saveInterval etc on the JDBCSessionManager.

thanks
Jan

Comment 2 Christoph Laeubrich

2014-01-17 03:45:00 EST

Hi Jan, I currently can only confirm this on jetty 8, since we currently can't update due to third party dependencies.

You can on jetty 8 reproduce this relativly simple (using default settings):
- enable debug logging for JDBCSessionManager
- open a page that changes the session *once* so a session is created and persited but afterwards never changed!
- refresh this page on a regular basis (10sec) and see everything works fine
- wait for more than 60 seconds (the default saveIntervall)
- refresh the page
- on each refresh the session is reloaded from the db

Maybe this is not present anymore in jetty-9 then it would be nice to port this fix back to jetty-8

Comment 3 Christoph Laeubrich

2014-01-17 03:51:02 EST

to make it clear:
- even if you refresh regular after 60 seconds the session gets reloaded, so after aprox 6 refreshes if you refresh every 10 sec you shoudl see the case where it reloads. Important thing is that the session does not change!

Comment 4 Jan Bartel

2014-01-19 21:15:15 EST

Hi laeubi,

Fixed this for 9.1.2.

thanks
Jan

Comment 5 Christoph Laeubrich

2014-01-20 02:12:58 EST

Hi Jan,

thanks for your fix, can this be fixed and released for Jetty 8 also?
Since there are 3rd-party dependencies we can't upgrade to jetty-9 yet.