[
Date Prev][
Date Next][
Thread Prev][
Thread Next][
Date Index][
Thread Index]
[
List Home]
|
Re: [jetty-users] Session timeout
|
On 05/09/2017 05:10, Jan Bartel wrote:
John,
Can you provide the rest of your jetty configuration as regards
sessions. Also, please run your app with debug turned on for sessions
(-Dorg.eclipse.jetty.server.session.LEVEL=DEBUG) and post that. You
should see some debug info about the maximum idle time and expiry of the
session when you create one. Here's some examples for a run with the
standard jetty test webapp, with session-timeout=60 in web.xml:
My jetty configuration as regards sessions? I'm not sure what you want
here. The only relevant thing I can see is jetty-ssl-context.xml (my app
uses HTTPS) which I have not modified and which says:
<Set name="sslSessionTimeout"><Property
name="jetty.sslContext.sslSessionTimeout" default="-1"/></Set>
I have changed the session timeout to 5 minutes in my test rig, and I
get a debug message confirming this (the full log is at the end of this
message):
2017-09-05 17:22:55.874:DBUG:oejs.session:qtp48914743-19:
setIdleTimeout called: 300000
(My own debug message now says "Session timeout: 300", unlike what I
reported before. So more work needed on my part. There are no calls to
setMaxInactiveInterval() anywhere in my code)
I have put a breakpoint at the start of sessionDestroyed() in my app's
session listener, which is supposed to log session timeouts. (I first
noticed this problem because the session timeouts weren't being logged
they way they were when running under Jetty 8).
Previous tests showed that I didn't reach the breakpoint until I made
another request, but when testing with the DEBUG flag as you requested,
the breakpoint was reached exactly 10 minutes (not 5) after the last
request (note timestamp):
2017-09-05 17:32:55.877:DBUG:oejs.session:Scheduler-631659383: Timer
expired for session node01wxg3y4o0hxjr19v9q005s4rrj0
Later tests showed that a second request made between 5 and 10 minutes
later also triggers sessionDestroyed(), and that a request is needed to
trigger the call to sessionDestroyed() if the DEBUG flag is not turned
on; with no DEBUG parameter and no subsequent request,
sessionDestroyed() is never called.
The code for sessionDestroyed() looks like this:
public void sessionDestroyed(HttpSessionEvent event) {
HttpSession session = event.getSession();
SessionState state = (SessionState)session.getAttribute("state");
if (state != null) { ... }
This is called from sessionHandler.removeSession() line 1056. Stepping
past the first line, I see the "session" variable being set, and
inspection shows that it contains an attribute called "state" which is a
SessionState object, as expected.
However, when I try to call getAttribute() on the second line, I get an
IllegalStateException, which didn't used to happen in Jetty 8; I used to
be able to retrieve my session state info (including the logged-in
username) and use that information to log the session timeout.
Here's the log:
2017-09-05 17:22:55.831:DBUG:oejs.session:qtp48914743-19: Got Session ID
node0iww65qwpvgrp1smbdzdo6no1o0.node0 from cookie
2017-09-05 17:22:55.832:DBUG:oejs.session:qtp48914743-19: Session
node0iww65qwpvgrp1smbdzdo6no1o0 not found locally, attempting to load
2017-09-05 17:22:55.836:DBUG:oejs.session:qtp48914743-19:
sessionHandler=org.eclipse.jetty.server.session.SessionHandler1045925128==dftMaxIdleSec=300
2017-09-05 17:22:55.836:DBUG:oejs.session:qtp48914743-19: session=null
2017-09-05 17:22:55.873:DBUG:oejs.session:qtp48914743-19: Checking
node0iww65qwpvgrp1smbdzdo6no1o0 is in use by at least one context
2017-09-05 17:22:55.873:DBUG:oejs.session:qtp48914743-19: Checked
node0iww65qwpvgrp1smbdzdo6no1o0, in use: false
2017-09-05 17:22:55.873:DBUG:oejs.session:qtp48914743-19: Creating new
session id=node01wxg3y4o0hxjr19v9q005s4rrj0
2017-09-05 17:22:55.873:DBUG:oejs.session:qtp48914743-19: Req count=1
for id=node01wxg3y4o0hxjr19v9q005s4rrj0
2017-09-05 17:22:55.873:DBUG:oejs.session:qtp48914743-19:
updateInactivityTimer
2017-09-05 17:22:55.874:DBUG:oejs.session:qtp48914743-19: setIdleTimeout
called: 300000
2017-09-05 17:22:55.874:DBUG:oejs.session:qtp48914743-19: No inactive
session eviction
2017-09-05 17:22:57.854:DBUG:oejs.session:qtp48914743-19:
FinalSession=org.eclipse.jetty.server.session.Session@62736aa3
old_session_manager=null
this=org.eclipse.jetty.server.session.SessionHandler1045925128==dftMaxIdleSec=300
2017-09-05 17:22:57.855:DBUG:oejs.session:qtp48914743-19: Non
passivating SessionDataStore, session in SessionCache only
id=node01wxg3y4o0hxjr19v9q005s4rrj0
2017-09-05 17:22:58.045:DBUG:oejs.session:qtp48914743-20: Got Session ID
node01wxg3y4o0hxjr19v9q005s4rrj0.node0 from cookie
2017-09-05 17:22:58.046:DBUG:oejs.session:qtp48914743-20: Testing expiry
on session node01wxg3y4o0hxjr19v9q005s4rrj0: expires at 1504621675873
now 1504621378046 maxIdle 300000
2017-09-05 17:22:58.046:DBUG:oejs.session:qtp48914743-20: Testing expiry
on session node01wxg3y4o0hxjr19v9q005s4rrj0: expires at 1504621678046
now 1504621378046 maxIdle 300000
2017-09-05 17:22:58.046:DBUG:oejs.session:qtp48914743-20:
sessionHandler=org.eclipse.jetty.server.session.SessionHandler1045925128==dftMaxIdleSec=300
2017-09-05 17:22:58.046:DBUG:oejs.session:qtp48914743-20:
session=org.eclipse.jetty.server.session.Session@62736aa3
2017-09-05 17:22:58.060:DBUG:oejs.session:qtp48914743-23: Got Session ID
node01wxg3y4o0hxjr19v9q005s4rrj0.node0 from cookie
2017-09-05 17:22:58.060:DBUG:oejs.session:qtp48914743-23: Testing expiry
on session node01wxg3y4o0hxjr19v9q005s4rrj0: expires at 1504621678046
now 1504621378060 maxIdle 300000
2017-09-05 17:22:58.061:DBUG:oejs.session:qtp48914743-23: Testing expiry
on session node01wxg3y4o0hxjr19v9q005s4rrj0: expires at 1504621678061
now 1504621378061 maxIdle 300000
2017-09-05 17:22:58.061:DBUG:oejs.session:qtp48914743-23:
sessionHandler=org.eclipse.jetty.server.session.SessionHandler1045925128==dftMaxIdleSec=300
2017-09-05 17:22:58.061:DBUG:oejs.session:qtp48914743-23:
session=org.eclipse.jetty.server.session.Session@62736aa3
2017-09-05 17:22:58.064:DBUG:oejs.session:qtp48914743-23:
FinalSession=org.eclipse.jetty.server.session.Session@62736aa3
old_session_manager=null
this=org.eclipse.jetty.server.session.SessionHandler1045925128==dftMaxIdleSec=300
2017-09-05 17:22:58.065:DBUG:oejs.session:qtp48914743-23: Req count=1
for id=node01wxg3y4o0hxjr19v9q005s4rrj0
2017-09-05 17:22:58.072:DBUG:oejs.session:qtp48914743-20:
FinalSession=org.eclipse.jetty.server.session.Session@62736aa3
old_session_manager=null
this=org.eclipse.jetty.server.session.SessionHandler1045925128==dftMaxIdleSec=300
2017-09-05 17:22:58.072:DBUG:oejs.session:qtp48914743-20: Non
passivating SessionDataStore, session in SessionCache only
id=node01wxg3y4o0hxjr19v9q005s4rrj0
2017-09-05 17:22:58.235:DBUG:oejs.session:qtp48914743-20: Got Session ID
node01wxg3y4o0hxjr19v9q005s4rrj0.node0 from cookie
2017-09-05 17:22:58.235:DBUG:oejs.session:qtp48914743-20: Testing expiry
on session node01wxg3y4o0hxjr19v9q005s4rrj0: expires at 1504621678061
now 1504621378235 maxIdle 300000
2017-09-05 17:22:58.235:DBUG:oejs.session:qtp48914743-20: Testing expiry
on session node01wxg3y4o0hxjr19v9q005s4rrj0: expires at 1504621678235
now 1504621378235 maxIdle 300000
2017-09-05 17:22:58.235:DBUG:oejs.session:qtp48914743-20:
sessionHandler=org.eclipse.jetty.server.session.SessionHandler1045925128==dftMaxIdleSec=300
2017-09-05 17:22:58.235:DBUG:oejs.session:qtp48914743-20:
session=org.eclipse.jetty.server.session.Session@62736aa3
2017-09-05 17:22:58.247:DBUG:oejs.session:qtp48914743-20:
FinalSession=org.eclipse.jetty.server.session.Session@62736aa3
old_session_manager=null
this=org.eclipse.jetty.server.session.SessionHandler1045925128==dftMaxIdleSec=300
2017-09-05 17:22:58.248:DBUG:oejs.session:qtp48914743-20: Non
passivating SessionDataStore, session in SessionCache only
id=node01wxg3y4o0hxjr19v9q005s4rrj0
2017-09-05 17:23:01.559:DBUG:oejs.session:qtp48914743-18: Got Session ID
node01wxg3y4o0hxjr19v9q005s4rrj0.node0 from cookie
2017-09-05 17:23:01.559:DBUG:oejs.session:qtp48914743-18: Testing expiry
on session node01wxg3y4o0hxjr19v9q005s4rrj0: expires at 1504621678235
now 1504621381559 maxIdle 300000
2017-09-05 17:23:01.559:DBUG:oejs.session:qtp48914743-18: Testing expiry
on session node01wxg3y4o0hxjr19v9q005s4rrj0: expires at 1504621681559
now 1504621381559 maxIdle 300000
2017-09-05 17:23:01.559:DBUG:oejs.session:qtp48914743-18:
sessionHandler=org.eclipse.jetty.server.session.SessionHandler1045925128==dftMaxIdleSec=300
2017-09-05 17:23:01.560:DBUG:oejs.session:qtp48914743-18:
session=org.eclipse.jetty.server.session.Session@62736aa3
2017-09-05 17:23:01.570:INFO:/:qtp48914743-18: Login:
node01wxg3y4o0hxjr19v9q005s4rrj0
2017-09-05 17:23:01.855:DBUG:oejs.session:qtp48914743-18:
FinalSession=org.eclipse.jetty.server.session.Session@62736aa3
old_session_manager=null
this=org.eclipse.jetty.server.session.SessionHandler1045925128==dftMaxIdleSec=300
2017-09-05 17:23:01.855:DBUG:oejs.session:qtp48914743-18: Non
passivating SessionDataStore, session in SessionCache only
id=node01wxg3y4o0hxjr19v9q005s4rrj0
2017-09-05 17:23:01.916:DBUG:oejs.session:qtp48914743-25: Got Session ID
node01wxg3y4o0hxjr19v9q005s4rrj0.node0 from cookie
2017-09-05 17:23:01.916:DBUG:oejs.session:qtp48914743-25: Testing expiry
on session node01wxg3y4o0hxjr19v9q005s4rrj0: expires at 1504621681559
now 1504621381916 maxIdle 300000
2017-09-05 17:23:01.916:DBUG:oejs.session:qtp48914743-25: Testing expiry
on session node01wxg3y4o0hxjr19v9q005s4rrj0: expires at 1504621681916
now 1504621381916 maxIdle 300000
2017-09-05 17:23:01.917:DBUG:oejs.session:qtp48914743-25:
sessionHandler=org.eclipse.jetty.server.session.SessionHandler1045925128==dftMaxIdleSec=300
2017-09-05 17:23:01.917:DBUG:oejs.session:qtp48914743-25:
session=org.eclipse.jetty.server.session.Session@62736aa3
2017-09-05 17:23:02.375:DBUG:oejs.session:qtp48914743-25:
FinalSession=org.eclipse.jetty.server.session.Session@62736aa3
old_session_manager=null
this=org.eclipse.jetty.server.session.SessionHandler1045925128==dftMaxIdleSec=300
2017-09-05 17:23:02.378:DBUG:oejs.session:qtp48914743-25: Non
passivating SessionDataStore, session in SessionCache only
id=node01wxg3y4o0hxjr19v9q005s4rrj0
2017-09-05 17:23:02.657:DBUG:oejs.session:qtp48914743-19: Got Session ID
node01wxg3y4o0hxjr19v9q005s4rrj0.node0 from cookie
2017-09-05 17:23:02.657:DBUG:oejs.session:qtp48914743-19: Testing expiry
on session node01wxg3y4o0hxjr19v9q005s4rrj0: expires at 1504621681916
now 1504621382657 maxIdle 300000
2017-09-05 17:23:02.657:DBUG:oejs.session:qtp48914743-19: Testing expiry
on session node01wxg3y4o0hxjr19v9q005s4rrj0: expires at 1504621682657
now 1504621382657 maxIdle 300000
2017-09-05 17:23:02.658:DBUG:oejs.session:qtp48914743-19:
sessionHandler=org.eclipse.jetty.server.session.SessionHandler1045925128==dftMaxIdleSec=300
2017-09-05 17:23:02.658:DBUG:oejs.session:qtp48914743-19:
session=org.eclipse.jetty.server.session.Session@62736aa3
2017-09-05 17:23:02.659:DBUG:oejs.session:qtp48914743-19:
FinalSession=org.eclipse.jetty.server.session.Session@62736aa3
old_session_manager=null
this=org.eclipse.jetty.server.session.SessionHandler1045925128==dftMaxIdleSec=300
2017-09-05 17:23:02.660:DBUG:oejs.session:qtp48914743-19: Non
passivating SessionDataStore, session in SessionCache only
id=node01wxg3y4o0hxjr19v9q005s4rrj0
2017-09-05 17:27:55.875:DBUG:oejs.session:Scheduler-631659383: Timer
expired for session node01wxg3y4o0hxjr19v9q005s4rrj0
2017-09-05 17:27:55.875:DBUG:oejs.session:Scheduler-631659383:
Inspecting session node01wxg3y4o0hxjr19v9q005s4rrj0, valid=true
2017-09-05 17:27:55.875:DBUG:oejs.session:Scheduler-631659383: Testing
expiry on session node01wxg3y4o0hxjr19v9q005s4rrj0: expires at
1504621682657 now 1504621675875 maxIdle 300000
2017-09-05 17:27:55.875:DBUG:oejs.session:Scheduler-631659383: Checking
for idle node01wxg3y4o0hxjr19v9q005s4rrj0
2017-09-05 17:32:55.877:DBUG:oejs.session:Scheduler-631659383: Timer
expired for session node01wxg3y4o0hxjr19v9q005s4rrj0
2017-09-05 17:32:55.877:DBUG:oejs.session:Scheduler-631659383:
Inspecting session node01wxg3y4o0hxjr19v9q005s4rrj0, valid=true
2017-09-05 17:32:55.877:DBUG:oejs.session:Scheduler-631659383: Testing
expiry on session node01wxg3y4o0hxjr19v9q005s4rrj0: expires at
1504621682657 now 1504621975877 maxIdle 300000
2017-09-05 17:32:55.877:DBUG:oejs.session:Scheduler-631659383: Session
node01wxg3y4o0hxjr19v9q005s4rrj0 is candidate for expiry
2017-09-05 17:33:28.530:DBUG:oejs.session:Scheduler-631659383:
Scavenging sessions
2017-09-05 17:33:28.530:DBUG:oejs.session:Scheduler-631659383:
Scavenging sessions
2017-09-05 17:33:28.530:DBUG:oejs.session:Scheduler-631659383:
Scavenging session ids []
2017-09-05 17:33:28.530:DBUG:oejs.session:Scheduler-631659383:
SessionDataStore checking expiration on []
2017-09-05 17:33:28.530:DBUG:oejs.session:Scheduler-631659383:
Scavenging sessions
2017-09-05 17:33:28.530:DBUG:oejs.session:Scheduler-631659383:
Scavenging session ids [node01wxg3y4o0hxjr19v9q005s4rrj0]
2017-09-05 17:33:28.530:DBUG:oejs.session:Scheduler-631659383:
SessionDataStore checking expiration on [node01wxg3y4o0hxjr19v9q005s4rrj0]
2017-09-05 17:33:28.530:DBUG:oejs.session:Scheduler-631659383: Expiring
node01wxg3y4o0hxjr19v9q005s4rrj0
2017-09-05 17:33:28.531:DBUG:oejs.session:Scheduler-631659383: Session
node01wxg3y4o0hxjr19v9q005s4rrj0 not found locally, attempting to load
2017-09-05 17:33:28.531:DBUG:oejs.session:Scheduler-631659383: Session
node01wxg3y4o0hxjr19v9q005s4rrj0 deleted in db true
2017-09-05 17:33:28.531:DBUG:oejs.session:Scheduler-631659383: Session
node01wxg3y4o0hxjr19v9q005s4rrj0 deleted in db true
2017-09-05 17:33:28.531:DBUG:oejs.session:Scheduler-631659383:
setIdleTimeout called: -1
2017-09-05 17:33:28.531:DBUG:oejs.session:Scheduler-631659383: Session
timer stopped
--
John English
