memcached-session-manager icon indicating copy to clipboard operation
memcached-session-manager copied to clipboard
verified publisher icon magro

Session attributes are getting lost sometime in concurrent request i guess #i added lockingmode to All but it does not seems hellping at all

Open erLovepreet opened this issue 10 years ago • 37 comments

here are my memcached configuration

<Manager className="de.javakaffee.web.msm.MemcachedBackupSessionManager" sticky="false" memcachedNodes="localhost:11211" failoverNodes="" requestUriIgnorePattern=".*.(png|gif|jpg|css|js|ico)$" sessionBackupAsync="false" lockingMode="all" transcoderFactoryClass="de.javakaffee.web.msm.serializer.kryo.KryoTranscoderFactory"
/>

FINE: Starting for session id 7ECDF6FB9A2DF19ECD4B0C7BFA98D9AF.tomcat81 Jan 09, 2016 11:10:29 PM de.javakaffee.web.msm.BackupSessionTask doBackupSession

FINE: Trying to store session in memcached: 7ECDF6FB9A2DF19ECD4B0C7BFA98D9AF.tomcat81

Jan 09, 2016 11:10:29 PM de.javakaffee.web.msm.BackupSessionTask call FINE: Finished for session id 7ECDF6FB9A2DF19ECD4B0C7BFA98D9AF.tomcat81, returning status SUCCESS Jan 09, 2016 11:10:29 PM de.javakaffee.web.msm.LockingStrategy onAfterBackupSession FINE: Stored session validity info for session 7ECDF6FB9A2DF19ECD4B0C7BFA98D9AF.tomcat81 Jan 09, 2016 11:10:29 PM de.javakaffee.web.msm.RequestTrackingHostValve logDebugRequestSessionCookie FINE: Have request session cookie: domain=null, maxAge=-1, path=null, value=D4B1CE0FFDF440D7374D0A3A3F365BBB.tomcat81, version=0, secure=false Jan 09, 2016 11:10:29 PM de.javakaffee.web.msm.RequestTrackingHostValve logDebugResponseCookie FINE: Request finished, with Set-Cookie header: JSESSIONID=7ECDF6FB9A2DF19ECD4B0C7BFA98D9AF.tomcat81; Path=/contextpath/; HttpOnly Jan 09, 2016 11:10:29 PM de.javakaffee.web.msm.RequestTrackingHostValve invoke FINE: <<<<<< Request finished: POST /previousRequest ==================

//here i am trying to set some attribute. --------------------------------------------setsession------------------------isLoggedIn

Jan 09, 2016 11:10:30 PM de.javakaffee.web.msm.MemcachedSessionService backupSession FINE: No session found in session map for 7ECDF6FB9A2DF19ECD4B0C7BFA98D9AF.tomcat81 Jan 09, 2016 11:10:30 PM de.javakaffee.web.msm.LockingStrategy onBackupWithoutLoadedSession FINE: Stored session validity info for session 7ECDF6FB9A2DF19ECD4B0C7BFA98D9AF.tomcat81 Jan 09, 2016 11:10:30 PM de.javakaffee.web.msm.RequestTrackingHostValve logDebugRequestSessionCookie FINE: Have request session cookie: domain=null, maxAge=-1, path=null, value=7ECDF6FB9A2DF19ECD4B0C7BFA98D9AF.tomcat81, version=0, secure=false Jan 09, 2016 11:10:30 PM de.javakaffee.web.msm.RequestTrackingHostValve invoke

FINE: <<<<<< Request finished: POST /someRequest ================== //request which sets the attribute is over

Jan 09, 2016 11:10:30 PM de.javakaffee.web.msm.LockingStrategy pingSession FINE: The session was ping'ed successfully. Jan 09, 2016 11:10:30 PM de.javakaffee.web.msm.RequestTrackingHostValve invoke

//someother request FINE: >>>>>> Request starting: GET /someother request (requestedSessionId 7ECDF6FB9A2DF19ECD4B0C7BFA98D9AF.tomcat81) ==================

Jan 09, 2016 11:10:30 PM de.javakaffee.web.msm.MemcachedSessionService loadFromMemcached FINE: Loading session from memcached: 7ECDF6FB9A2DF19ECD4B0C7BFA98D9AF.tomcat81 Jan 09, 2016 11:10:30 PM de.javakaffee.web.msm.MemcachedSessionService loadFromMemcached FINE: Found session with id 7ECDF6FB9A2DF19ECD4B0C7BFA98D9AF.tomcat81

--------------------------getting attribute from same session but getting null

Jan 09, 2016 11:10:30 PM de.javakaffee.web.msm.BackupSessionService backupSession

//now it is trying to update the session in memcahed but session is alredy dirty read by previous request

FINE: Starting for session id 7ECDF6FB9A2DF19ECD4B0C7BFA98D9AF.tomcat81 Jan 09, 2016 11:10:30 PM de.javakaffee.web.msm.BackupSessionTask call FINE: Starting for session id 7ECDF6FB9A2DF19ECD4B0C7BFA98D9AF.tomcat81 Jan 09, 2016 11:10:30 PM de.javakaffee.web.msm.BackupSessionTask call FINE: Finished for session id 7ECDF6FB9A2DF19ECD4B0C7BFA98D9AF.tomcat81, returning status SKIPPED Jan 09, 2016 11:10:30 PM de.javakaffee.web.msm.LockingStrategy onAfterBackupSession

i have tried it with locking mode also but problem is still exists According to me the problem is thread which is calling BackupSessionTask for backup , it is taking time to update the session in memcached mean while other request do dirty read if my guess was right you should have wait for thread before assigning session from memcached to other request

if i am missing some configuration please let me know Thanks in advance

erLovepreet avatar Jan 10 '16 16:01 erLovepreet

The provided logs do not provide all information, therefore I'm not sure if anything relevant is missing. Please share the full log of the related requests.

magro avatar Jan 11 '16 07:01 magro

Exactly what information you wants....because i have pasted all related logs in the post (these are tomcat logs )

erLovepreet avatar Jan 11 '16 08:01 erLovepreet

Are you sure you didn't remove parts of the logs? There should some more stuff being logged.

magro avatar Jan 11 '16 10:01 magro

Sir these are the exact logs i havn't changed any thing as far i know for doubt clearence i am pasting logs again

FINE: Starting for session id 7ECDF6FB9A2DF19ECD4B0C7BFA98D9AF.tomcat81 Jan 09, 2016 11:10:29 PM de.javakaffee.web.msm.BackupSessionTask doBackupSession FINE: Trying to store session in memcached: 7ECDF6FB9A2DF19ECD4B0C7BFA98D9AF.tomcat81 Jan 09, 2016 11:10:29 PM de.javakaffee.web.msm.BackupSessionTask call FINE: Finished for session id 7ECDF6FB9A2DF19ECD4B0C7BFA98D9AF.tomcat81, returning status SUCCESS Jan 09, 2016 11:10:29 PM de.javakaffee.web.msm.LockingStrategy onAfterBackupSession FINE: Stored session validity info for session 7ECDF6FB9A2DF19ECD4B0C7BFA98D9AF.tomcat81 Jan 09, 2016 11:10:29 PM de.javakaffee.web.msm.RequestTrackingHostValve logDebugRequestSessionCookie FINE: Have request session cookie: domain=null, maxAge=-1, path=null, value=D4B1CE0FFDF440D7374D0A3A3F365BBB.tomcat81, version=0, secure=false Jan 09, 2016 11:10:29 PM de.javakaffee.web.msm.RequestTrackingHostValve logDebugResponseCookie FINE: Request finished, with Set-Cookie header: JSESSIONID=7ECDF6FB9A2DF19ECD4B0C7BFA98D9AF.tomcat81; Path=/zcubator93/; HttpOnly Jan 09, 2016 11:10:29 PM de.javakaffee.web.msm.RequestTrackingHostValve invoke FINE: <<<<<< Request finished: POST /zcubator93/control/ssologin ==================

--------------------------------------------setsession------------------------isLoggedIn

Jan 09, 2016 11:10:30 PM de.javakaffee.web.msm.MemcachedSessionService backupSession FINE: No session found in session map for 7ECDF6FB9A2DF19ECD4B0C7BFA98D9AF.tomcat81 Jan 09, 2016 11:10:30 PM de.javakaffee.web.msm.LockingStrategy onBackupWithoutLoadedSession FINE: Stored session validity info for session 7ECDF6FB9A2DF19ECD4B0C7BFA98D9AF.tomcat81 Jan 09, 2016 11:10:30 PM de.javakaffee.web.msm.RequestTrackingHostValve logDebugRequestSessionCookie FINE: Have request session cookie: domain=null, maxAge=-1, path=null, value=7ECDF6FB9A2DF19ECD4B0C7BFA98D9AF.tomcat81, version=0, secure=false Jan 09, 2016 11:10:30 PM de.javakaffee.web.msm.RequestTrackingHostValve invoke FINE: <<<<<< Request finished: POST /zcubator93/control/authenticate ================== Jan 09, 2016 11:10:30 PM de.javakaffee.web.msm.LockingStrategy pingSession FINE: The session was ping'ed successfully. Jan 09, 2016 11:10:30 PM de.javakaffee.web.msm.RequestTrackingHostValve invoke FINE: >>>>>> Request starting: GET /zcubator93/control/nexturl?nextUrl=marketingCenter&menuName=zcubator&subMenuName=first (requestedSessionId 7ECDF6FB9A2DF19ECD4B0C7BFA98D9AF.tomcat81) ================== ------------------------------>>>>>>>>>>>>>>>http://zcubmem.test/zcubator93/control/nexturl Jan 09, 2016 11:10:30 PM de.javakaffee.web.msm.MemcachedSessionService loadFromMemcached FINE: Loading session from memcached: 7ECDF6FB9A2DF19ECD4B0C7BFA98D9AF.tomcat81 Jan 09, 2016 11:10:30 PM de.javakaffee.web.msm.MemcachedSessionService loadFromMemcached FINE: Found session with id 7ECDF6FB9A2DF19ECD4B0C7BFA98D9AF.tomcat81 -------------------------------------------------------getting session attribute null---------------------------------------------------------------------

Jan 09, 2016 11:10:30 PM de.javakaffee.web.msm.BackupSessionService backupSession FINE: Starting for session id 7ECDF6FB9A2DF19ECD4B0C7BFA98D9AF.tomcat81 Jan 09, 2016 11:10:30 PM de.javakaffee.web.msm.BackupSessionTask call FINE: Starting for session id 7ECDF6FB9A2DF19ECD4B0C7BFA98D9AF.tomcat81 Jan 09, 2016 11:10:30 PM de.javakaffee.web.msm.BackupSessionTask call FINE: Finished for session id 7ECDF6FB9A2DF19ECD4B0C7BFA98D9AF.tomcat81, returning status SKIPPED Jan 09, 2016 11:10:30 PM de.javakaffee.web.msm.LockingStrategy onAfterBackupSession

erLovepreet avatar Jan 11 '16 10:01 erLovepreet

Ok, thanks!

Where does --------------------------------------------setsession------------------------isLoggedIn come from? Is this logged by POST /zcubator93/control/authenticate?

It seems as if POST /zcubator93/control/ssologin and POST /zcubator93/control/authenticate are running in parallel, is this possible?

As it seems, POST /zcubator93/control/ssologin changes the session id, and probably this is not propagated to the session map, so that POST /zcubator93/control/authenticate does not find the session and also does not update the session in memcached.

How are you changing the session id?

magro avatar Jan 11 '16 22:01 magro

Where does --------------------------------------------setsession------------------------isLoggedIn come from? Is this logged by POST /zcubator93/control/authenticate? Yes, it is logged by this jsp authenticate.jsp

It seems as if POST /zcubator93/control/ssologin and POST /zcubator93/control/authenticate are running in parallel, is this possible? Actually it seems , but the actual case is ssologin calls authenticate

Actual case is ssologin invalidate the session and authenticate makes new session and sets a attribute --------------------------------------------setsession------------------------isLoggedIn

but after send redirect from authenticate the variable is not visible on next jsp. -------------------------------------------------------getting session attribute null--------------------------------------------------------------------

because session is not get updated after authenticate.jsp ...and next jsp gets session from memcached and getting value null-

erLovepreet avatar Jan 12 '16 08:01 erLovepreet

I'm missing the "Request starting" logs for ssologin and authenticate. What do you mean with "ssologin calls authenticate", can you describe this is more detail? Am 12.01.2016 09:48 schrieb "erLovepreet" [email protected]:

Where does --------------------------------------------setsession------------------------isLoggedIn come from? Is this logged by POST /zcubator93/control/authenticate? Yes, it is logged by this jsp authenticate.jsp

It seems as if POST /zcubator93/control/ssologin and POST /zcubator93/control/authenticate are running in parallel, is this possible? Actually it seems , but the actual case is ssologin calls authenticate

Actual case is ssologin invalidate the session and authenticate makes new session and sets a attribute

--------------------------------------------setsession------------------------isLoggedIn

but after send redirect from authenticate the variable is not visible on next jsp. -------------------------------------------------------getting session attribute null--------------------------------------------------------------------

because session is not get updated after authenticate.jsp ...and next jsp gets session from memcached and getting value null-

— Reply to this email directly or view it on GitHub https://github.com/magro/memcached-session-manager/issues/283#issuecomment-170841001 .

magro avatar Jan 12 '16 22:01 magro

sorry for that sir, These are all logs

FINE: >>>>>> Request starting: POST /zcubator93/control/ssologin (requestedSessionId D88BB292CB7EFE970F1EA02AD9E6459F.tomcat81) ================= Jan 10, 2016 10:41:02 PM de.javakaffee.web.msm.MemcachedSessionService loadFromMemcached FINE: Loading session from memcached: D88BB292CB7EFE970F1EA02AD9E6459F.tomcat81 Jan 10, 2016 10:41:02 PM de.javakaffee.web.msm.MemcachedSessionService loadFromMemcached FINE: Session D88BB292CB7EFE970F1EA02AD9E6459F.tomcat81 not found in memcached. Jan 10, 2016 10:41:02 PM de.javakaffee.web.msm.MemcachedSessionService createSession FINE: createSession invoked: null Jan 10, 2016 10:41:02 PM de.javakaffee.web.msm.MemcachedSessionService createSession FINE: Created new session with id E7BE4147A192682FB9085AFDBBCDC009.tomcat81 Jan 10, 2016 10:41:02 PM de.javakaffee.web.msm.RequestTrackingHostValve invoke FINE: >>>>>> Request starting: POST /zcubator93/control/authenticate (requestedSessionId E7BE4147A192682FB9085AFDBBCDC009.tomcat81) ================== !!!!!!!!22 : Jan 10, 2016 10:41:02 PM de.javakaffee.web.msm.BackupSessionService backupSession FINE: Starting for session id E7BE4147A192682FB9085AFDBBCDC009.tomcat81 Jan 10, 2016 10:41:02 PM de.javakaffee.web.msm.BackupSessionTask call FINE: Starting for session id E7BE4147A192682FB9085AFDBBCDC009.tomcat81 Jan 10, 2016 10:41:02 PM de.javakaffee.web.msm.BackupSessionTask doBackupSession FINE: Trying to store session in memcached: E7BE4147A192682FB9085AFDBBCDC009.tomcat81 Jan 10, 2016 10:41:02 PM de.javakaffee.web.msm.BackupSessionTask call FINE: Finished for session id E7BE4147A192682FB9085AFDBBCDC009.tomcat81, returning status SUCCESS Jan 10, 2016 10:41:02 PM de.javakaffee.web.msm.LockingStrategy onAfterBackupSession FINE: Stored session validity info for session E7BE4147A192682FB9085AFDBBCDC009.tomcat81 Jan 10, 2016 10:41:02 PM de.javakaffee.web.msm.RequestTrackingHostValve logDebugRequestSessionCookie FINE: Have request session cookie: domain=null, maxAge=-1, path=null, value=D88BB292CB7EFE970F1EA02AD9E6459F.tomcat81, version=0, secure=false Jan 10, 2016 10:41:02 PM de.javakaffee.web.msm.RequestTrackingHostValve logDebugResponseCookie FINE: Request finished, with Set-Cookie header: JSESSIONID=E7BE4147A192682FB9085AFDBBCDC009.tomcat81; Path=/zcubator93/; HttpOnly Jan 10, 2016 10:41:02 PM de.javakaffee.web.msm.RequestTrackingHostValve invoke FINE: <<<<<< Request finished: POST /zcubator93/control/ssologin ================== --------------------------------------------setsession------------------------isLoggedIn Jan 10, 2016 10:41:02 PM de.javakaffee.web.msm.MemcachedSessionService backupSession FINE: No session found in session map for E7BE4147A192682FB9085AFDBBCDC009.tomcat81 Jan 10, 2016 10:41:02 PM de.javakaffee.web.msm.LockingStrategy pingSession FINE: The session was ping'ed successfully. Jan 10, 2016 10:41:02 PM de.javakaffee.web.msm.LockingStrategy onBackupWithoutLoadedSession FINE: Stored session validity info for session E7BE4147A192682FB9085AFDBBCDC009.tomcat81 Jan 10, 2016 10:41:02 PM de.javakaffee.web.msm.RequestTrackingHostValve logDebugRequestSessionCookie FINE: Have request session cookie: domain=null, maxAge=-1, path=null, value=E7BE4147A192682FB9085AFDBBCDC009.tomcat81, version=0, secure=false Jan 10, 2016 10:41:02 PM de.javakaffee.web.msm.RequestTrackingHostValve invoke FINE: <<<<<< Request finished: POST /zcubator93/control/authenticate ================== Jan 10, 2016 10:41:02 PM de.javakaffee.web.msm.RequestTrackingHostValve invoke FINE: >>>>>> Request starting: GET /zcubator93/control/nexturl?nextUrl=marketingCenter&menuName=zcubator&subMenuName=first (requestedSessionId E7BE4147A192682FB9085AFDBBCDC009.tomcat81) ================== Jan 10, 2016 10:41:02 PM de.javakaffee.web.msm.MemcachedSessionService loadFromMemcached FINE: Loading session from memcached: E7BE4147A192682FB9085AFDBBCDC009.tomcat81 Jan 10, 2016 10:41:02 PM de.javakaffee.web.msm.MemcachedSessionService loadFromMemcached FINE: Found session with id E7BE4147A192682FB9085AFDBBCDC009.tomcat81 -------------------------------------------------------getting session attribute null--------------------------------------------------------------------- Jan 10, 2016 10:41:02 PM de.javakaffee.web.msm.BackupSessionService backupSession FINE: Starting for session id E7BE4147A192682FB9085AFDBBCDC009.tomcat81 Jan 10, 2016 10:41:02 PM de.javakaffee.web.msm.BackupSessionTask call FINE: Starting for session id E7BE4147A192682FB9085AFDBBCDC009.tomcat81 Jan 10, 2016 10:41:02 PM de.javakaffee.web.msm.BackupSessionTask call FINE: Finished for session id E7BE4147A192682FB9085AFDBBCDC009.tomcat81, returning status SKIPPED Jan 10, 2016 10:41:02 PM de.javakaffee.web.msm.LockingStrategy onAfterBackupSession FINE: Stored session validity info for session E7BE4147A192682FB9085AFDBBCDC009.tomcat81 Jan 10, 2016 10:41:02 PM de.javakaffee.web.msm.LockingStrategy pingSession FINE: The session was ping'ed successfully. Jan 10, 2016 10:41:02 PM de.javakaffee.web.msm.RequestTrackingHostValve logDebugRequestSessionCookie FINE: Have request session cookie: domain=null, maxAge=-1, path=null, value=E7BE4147A192682FB9085AFDBBCDC009.tomcat81, version=0, secure=false Jan 10, 2016 10:41:02 PM de.javakaffee.web.msm.RequestTrackingHostValve invoke FINE: <<<<<< Request finished: GET /zcubator93/control/nexturl?nextUrl=marketingCenter&menuName=zcubator&subMenuName=first ==================

I hope this time you have all the logs . please let me know if i m missing anything Thanks in advance

What do you mean with "ssologin calls authenticate", can you describe this is more detail? sir actually ssologin.jsp invalidate the session and it submit a form to authentication.jsp and as you can see authentication create new session and set same attributes( that i m having problem of getting lost because of thread delay) .... authentication.jsp again call response.send redirect to /nexturl as u can see in logs .... and while nexturl request (i an using struts2 framework) interceptor gets call and inquire the attribute that is earlier set by authentication.jsp .... this request seems parallel as you can see in logs request of authentication.jsp is finished after interceptor inquires about attribute from session.

erLovepreet avatar Jan 13 '16 06:01 erLovepreet

Ok, I think I found s.th. Can you try the latest snapshot? https://dl.dropboxusercontent.com/u/1439289/memcached-session-manager-1.9.0-RC2-SNAPSHOT.jar https://www.dropbox.com/s/z0ezcpqumoqik2y/memcached-session-manager-tc6-1.9.0-RC2-SNAPSHOT.jar https://www.dropbox.com/s/xhovf5vbxacnct0/memcached-session-manager-tc7-1.9.0-RC2-SNAPSHOT.jar https://www.dropbox.com/s/m84e0rjsmm8hor2/memcached-session-manager-tc8-1.9.0-RC2-SNAPSHOT.jar (choose the appropriate tc* jar according to your tomcat version)

magro avatar Jan 13 '16 08:01 magro

sir the problem is still there ... :( do you understand the problem ? means why this problem is reproducing Please let me know ..... as far i get , the problem is concurrent request.

erLovepreet avatar Jan 15 '16 09:01 erLovepreet

I had a theory for the reason (yes, related to concurrent requests), but it seems to be wrong. Can you share logs for the issue with the new version/jars? Am 15.01.2016 10:08 schrieb "erLovepreet" [email protected]:

sir the problem is still there ... :( do you understand the problem ? means why this problem is reproducing Please let me know ..... as far i get , the problem is concurrent request.

— Reply to this email directly or view it on GitHub https://github.com/magro/memcached-session-manager/issues/283#issuecomment-171907643 .

magro avatar Jan 15 '16 09:01 magro

@erLovepreet Can you please also update to the latest version 1.9.1 and share logs for concurrent requests / the issue?

magro avatar Feb 08 '16 12:02 magro

Hi sir,

Sorry for late reply , i got that problem and i applied temporary solution for that problem. and i have used SNAPSHOT jars but i am getting some other problem i have used these two jars rest are same memcached-session-manager-1.9.0-RC2-SNAPSHOT.jar memcached-session-manager-tc8-1.9.0-RC2-SNAPSHOT(1).jar

This doesnot even work in our project environment in our project we authenticate user and create session and set variable like isLoggedIn -true to session and then our interceptor checks every time whether user requested with particular session have that variable or not if not it will redirect user to login screen thats what our project do

now about new jars problem is : every time i login it redirect to login success but at very next request it redirect user to again login screen

i am sharing logs of login time and very next request

login time logs

Feb 11, 2016 11:58:14 AM de.javakaffee.web.msm.RequestTrackingHostValve invoke FINE: >>>>>> Request starting: POST /zcubator9315/control/authenticate (requestedSessionId 3EB70B36E7D164E105044C0A18A5238D.tomcat81) ================== Feb 11, 2016 11:58:14 AM de.javakaffee.web.msm.MemcachedSessionService loadFromMemcached FINE: Loading session from memcached: 3EB70B36E7D164E105044C0A18A5238D.tomcat81 Feb 11, 2016 11:58:14 AM de.javakaffee.web.msm.MemcachedSessionService loadFromMemcached FINE: Session 3EB70B36E7D164E105044C0A18A5238D.tomcat81 not found in memcached. Feb 11, 2016 11:58:14 AM de.javakaffee.web.msm.MemcachedSessionService createSession FINE: createSession invoked: null Feb 11, 2016 11:58:14 AM de.javakaffee.web.msm.MemcachedSessionService createSession FINE: Created new session with id 6B0996AAC22C2B8C934C1587D5435905.tomcat81 !!!!!!!!22 :

......................................this is where isLoggedin in set in session.........................

canAccessCustomerFeedback>>>>>>>>>>>>>>>>>>>>>>>>>>>>>true Feb 11, 2016 11:58:14 AM de.javakaffee.web.msm.BackupSessionService backupSession FINE: Starting for session id 6B0996AAC22C2B8C934C1587D5435905.tomcat81 Feb 11, 2016 11:58:14 AM de.javakaffee.web.msm.BackupSessionTask call FINE: Starting for session id 6B0996AAC22C2B8C934C1587D5435905.tomcat81 Feb 11, 2016 11:58:14 AM de.javakaffee.web.msm.BackupSessionTask doBackupSession FINE: Trying to store session in memcached: 6B0996AAC22C2B8C934C1587D5435905.tomcat81 Feb 11, 2016 11:58:14 AM de.javakaffee.web.msm.BackupSessionTask call FINE: Finished for session id 6B0996AAC22C2B8C934C1587D5435905.tomcat81, returning status SUCCESS Feb 11, 2016 11:58:14 AM de.javakaffee.web.msm.LockingStrategy onAfterBackupSession FINE: Stored session validity info for session 6B0996AAC22C2B8C934C1587D5435905.tomcat81 Feb 11, 2016 11:58:14 AM de.javakaffee.web.msm.RequestTrackingHostValve logDebugRequestSessionCookie FINE: Have request session cookie: domain=null, maxAge=-1, path=null, value=3EB70B36E7D164E105044C0A18A5238D.tomcat81, version=0, secure=false Feb 11, 2016 11:58:14 AM de.javakaffee.web.msm.RequestTrackingHostValve logDebugResponseCookie FINE: Request finished, with Set-Cookie header: JSESSIONID=6B0996AAC22C2B8C934C1587D5435905.tomcat81; Path=/zcubator9315/; HttpOnly Feb 11, 2016 11:58:14 AM de.javakaffee.web.msm.RequestTrackingHostValve invoke FINE: <<<<<< Request finished: POST /zcubator9315/control/authenticate ================== Feb 11, 2016 11:58:14 AM de.javakaffee.web.msm.RequestTrackingHostValve invoke FINE: >>>>>> Request starting: GET /zcubator9315/control/nexturl?nextUrl=marketingCenter&menuName=zcubator&subMenuName=first (requestedSessionId 6B0996AAC22C2B8C934C1587D5435905.tomcat81) ================== Feb 11, 2016 11:58:14 AM de.javakaffee.web.msm.MemcachedSessionService loadFromMemcached FINE: Loading session from memcached: 6B0996AAC22C2B8C934C1587D5435905.tomcat81 Feb 11, 2016 11:58:14 AM de.javakaffee.web.msm.MemcachedSessionService loadFromMemcached FINE: Found session with id 6B0996AAC22C2B8C934C1587D5435905.tomcat81 Feb 11, 2016 11:58:15 AM de.javakaffee.web.msm.BackupSessionService backupSession FINE: Starting for session id 6B0996AAC22C2B8C934C1587D5435905.tomcat81 Feb 11, 2016 11:58:15 AM de.javakaffee.web.msm.BackupSessionTask call FINE: Starting for session id 6B0996AAC22C2B8C934C1587D5435905.tomcat81 Feb 11, 2016 11:58:15 AM de.javakaffee.web.msm.BackupSessionTask doBackupSession FINE: Trying to store session in memcached: 6B0996AAC22C2B8C934C1587D5435905.tomcat81 Feb 11, 2016 11:58:15 AM de.javakaffee.web.msm.BackupSessionTask call FINE: Finished for session id 6B0996AAC22C2B8C934C1587D5435905.tomcat81, returning status SUCCESS Feb 11, 2016 11:58:15 AM de.javakaffee.web.msm.LockingStrategy onAfterBackupSession FINE: Stored session validity info for session 6B0996AAC22C2B8C934C1587D5435905.tomcat81 Feb 11, 2016 11:58:15 AM de.javakaffee.web.msm.RequestTrackingHostValve logDebugRequestSessionCookie FINE: Have request session cookie: domain=null, maxAge=-1, path=null, value=6B0996AAC22C2B8C934C1587D5435905.tomcat81, version=0, secure=false Feb 11, 2016 11:58:15 AM de.javakaffee.web.msm.RequestTrackingHostValve invoke FINE: <<<<<< Request finished: GET /zcubator9315/control/nexturl?nextUrl=marketingCenter&menuName=zcubator&subMenuName=first ================== Feb 11, 2016 11:58:15 AM de.javakaffee.web.msm.RequestTrackingHostValve invoke FINE: >>>>>> Request starting: GET /zcubator9315/control/marketingCenter (requestedSessionId 6B0996AAC22C2B8C934C1587D5435905.tomcat81) ================== Feb 11, 2016 11:58:15 AM de.javakaffee.web.msm.MemcachedSessionService loadFromMemcached FINE: Loading session from memcached: 6B0996AAC22C2B8C934C1587D5435905.tomcat81 Feb 11, 2016 11:58:15 AM de.javakaffee.web.msm.MemcachedSessionService loadFromMemcached FINE: Found session with id 6B0996AAC22C2B8C934C1587D5435905.tomcat81 Feb 11, 2016 11:58:15 AM de.javakaffee.web.msm.RequestTrackingHostValve invoke FINE: >>>>>> Ignoring: GET /zcubator9315/tenants/AdvantaClean/static/Fran091211/images/buildLogo.png (requestedSessionId 6B0996AAC22C2B8C934C1587D5435905.tomcat81) ================== Feb 11, 2016 11:58:15 AM de.javakaffee.web.msm.MemcachedSessionService requestFinished FINE: Session 6B0996AAC22C2B8C934C1587D5435905.tomcat81 is still used by another request, skipping backup and (optional) lock handling/release. Feb 11, 2016 11:58:15 AM de.javakaffee.web.msm.RequestTrackingHostValve invoke FINE: <<<<<< Ignored: GET /zcubator9315/tenants/AdvantaClean/static/Fran091211/images/buildLogo.png ================== recentPPCCallsExist false Feb 11, 2016 11:58:15 AM de.javakaffee.web.msm.BackupSessionService backupSession FINE: Starting for session id 6B0996AAC22C2B8C934C1587D5435905.tomcat81 Feb 11, 2016 11:58:15 AM de.javakaffee.web.msm.BackupSessionTask call FINE: Starting for session id 6B0996AAC22C2B8C934C1587D5435905.tomcat81 Feb 11, 2016 11:58:15 AM de.javakaffee.web.msm.BackupSessionTask doBackupSession FINE: Trying to store session in memcached: 6B0996AAC22C2B8C934C1587D5435905.tomcat81 Feb 11, 2016 11:58:15 AM de.javakaffee.web.msm.BackupSessionTask call FINE: Finished for session id 6B0996AAC22C2B8C934C1587D5435905.tomcat81, returning status SUCCESS Feb 11, 2016 11:58:15 AM de.javakaffee.web.msm.LockingStrategy onAfterBackupSession FINE: Stored session validity info for session 6B0996AAC22C2B8C934C1587D5435905.tomcat81 Feb 11, 2016 11:58:15 AM de.javakaffee.web.msm.RequestTrackingHostValve logDebugRequestSessionCookie FINE: Have request session cookie: domain=null, maxAge=-1, path=null, value=6B0996AAC22C2B8C934C1587D5435905.tomcat81, version=0, secure=false Feb 11, 2016 11:58:15 AM de.javakaffee.web.msm.RequestTrackingHostValve invoke FINE: <<<<<< Request finished: GET /zcubator9315/control/marketingCenter ================== Feb 11, 2016 11:58:15 AM de.javakaffee.web.msm.RequestTrackingHostValve invoke FINE: >>>>>> Ignoring: GET /zcubator9315/tenants/AdvantaClean/static/Fran091211/images/buildLogo.png (requestedSessionId 6B0996AAC22C2B8C934C1587D5435905.tomcat81) ================== Feb 11, 2016 11:58:15 AM de.javakaffee.web.msm.MemcachedSessionService findSession FINE: Returning for session id 6B0996AAC22C2B8C934C1587D5435905.tomcat81 (isConnectorSessionLookup: false, isIgnoredRequest: true) Feb 11, 2016 11:58:15 AM de.javakaffee.web.msm.MemcachedSessionService findSession FINE: Returning for session id 6B0996AAC22C2B8C934C1587D5435905.tomcat81 (isConnectorSessionLookup: false, isIgnoredRequest: true) Feb 11, 2016 11:58:15 AM de.javakaffee.web.msm.MemcachedSessionService findSession FINE: Returning for session id 6B0996AAC22C2B8C934C1587D5435905.tomcat81 (isConnectorSessionLookup: false, isIgnoredRequest: true) Feb 11, 2016 11:58:15 AM de.javakaffee.web.msm.MemcachedSessionService createSession FINE: createSession invoked: null Feb 11, 2016 11:58:15 AM de.javakaffee.web.msm.MemcachedSessionService createSession FINE: Created new session with id 44C08DD05006678837759C0C540132E0.tomcat81 Feb 11, 2016 11:58:15 AM de.javakaffee.web.msm.RequestTrackingHostValve invoke FINE: <<<<<< Ignored: GET /zcubator9315/tenants/AdvantaClean/static/Fran091211/images/buildLogo.png ================== Feb 11, 2016 11:58:15 AM de.javakaffee.web.msm.RequestTrackingHostValve invoke FINE: >>>>>> Ignoring: GET /zcubator9315/static/Fran091211/onboard/loading_background.png (requestedSessionId 44C08DD05006678837759C0C540132E0.tomcat81) ================== Feb 11, 2016 11:58:15 AM de.javakaffee.web.msm.MemcachedSessionService findSession FINE: Returning for session id 44C08DD05006678837759C0C540132E0.tomcat81 (isConnectorSessionLookup: false, isIgnoredRequest: true) Feb 11, 2016 11:58:15 AM de.javakaffee.web.msm.MemcachedSessionService findSession FINE: Returning for session id 44C08DD05006678837759C0C540132E0.tomcat81 (isConnectorSessionLookup: false, isIgnoredRequest: true) Feb 11, 2016 11:58:15 AM de.javakaffee.web.msm.MemcachedSessionService findSession FINE: Returning for session id 44C08DD05006678837759C0C540132E0.tomcat81 (isConnectorSessionLookup: false, isIgnoredRequest: true) Feb 11, 2016 11:58:15 AM de.javakaffee.web.msm.MemcachedSessionService createSession FINE: createSession invoked: null Feb 11, 2016 11:58:15 AM de.javakaffee.web.msm.MemcachedSessionService createSession FINE: Created new session with id 4ACA10FC49E11DD32DEC5F6F7073A143.tomcat81 Feb 11, 2016 11:58:15 AM de.javakaffee.web.msm.RequestTrackingHostValve invoke FINE: <<<<<< Ignored: GET /zcubator9315/static/Fran091211/onboard/loading_background.png ==================

next request logs

Feb 11, 2016 11:58:45 AM de.javakaffee.web.msm.RequestTrackingHostValve invoke FINE: >>>>>> Request starting: GET /zcubator9315/control/nexturl?nextUrl=main&menuName=intranet&subMenuName=first (requestedSessionId 4ACA10FC49E11DD32DEC5F6F7073A143.tomcat81) ================== Feb 11, 2016 11:58:45 AM de.javakaffee.web.msm.MemcachedSessionService loadFromMemcached FINE: Loading session from memcached: 4ACA10FC49E11DD32DEC5F6F7073A143.tomcat81 Feb 11, 2016 11:58:45 AM de.javakaffee.web.msm.MemcachedSessionService loadFromMemcached FINE: Session 4ACA10FC49E11DD32DEC5F6F7073A143.tomcat81 not found in memcached. Feb 11, 2016 11:58:45 AM de.javakaffee.web.msm.MemcachedSessionService createSession FINE: createSession invoked: null Feb 11, 2016 11:58:45 AM de.javakaffee.web.msm.MemcachedSessionService createSession FINE: Created new session with id 31F5CECBD45876A87B6D37F3C756B8DF.tomcat81 Feb 11, 2016 11:58:45 AM de.javakaffee.web.msm.BackupSessionService backupSession FINE: Starting for session id 31F5CECBD45876A87B6D37F3C756B8DF.tomcat81 Feb 11, 2016 11:58:45 AM de.javakaffee.web.msm.BackupSessionTask call FINE: Starting for session id 31F5CECBD45876A87B6D37F3C756B8DF.tomcat81 Feb 11, 2016 11:58:45 AM de.javakaffee.web.msm.BackupSessionTask doBackupSession FINE: Trying to store session in memcached: 31F5CECBD45876A87B6D37F3C756B8DF.tomcat81 Feb 11, 2016 11:58:45 AM de.javakaffee.web.msm.BackupSessionTask call FINE: Finished for session id 31F5CECBD45876A87B6D37F3C756B8DF.tomcat81, returning status SUCCESS Feb 11, 2016 11:58:45 AM de.javakaffee.web.msm.LockingStrategy onAfterBackupSession FINE: Stored session validity info for session 31F5CECBD45876A87B6D37F3C756B8DF.tomcat81 Feb 11, 2016 11:58:45 AM de.javakaffee.web.msm.RequestTrackingHostValve logDebugRequestSessionCookie FINE: Have request session cookie: domain=null, maxAge=-1, path=null, value=4ACA10FC49E11DD32DEC5F6F7073A143.tomcat81, version=0, secure=false Feb 11, 2016 11:58:45 AM de.javakaffee.web.msm.RequestTrackingHostValve logDebugResponseCookie FINE: Request finished, with Set-Cookie header: JSESSIONID=31F5CECBD45876A87B6D37F3C756B8DF.tomcat81; Path=/zcubator9315/; HttpOnly Feb 11, 2016 11:58:45 AM de.javakaffee.web.msm.RequestTrackingHostValve invoke FINE: <<<<<< Request finished: GET /zcubator9315/control/nexturl?nextUrl=main&menuName=intranet&subMenuName=first ================== Feb 11, 2016 11:58:45 AM de.javakaffee.web.msm.RequestTrackingHostValve invoke FINE: >>>>>> Request starting: GET /zcubator9315/control/login?message=NoSession (requestedSessionId 31F5CECBD45876A87B6D37F3C756B8DF.tomcat81) ================== Feb 11, 2016 11:58:45 AM de.javakaffee.web.msm.MemcachedSessionService loadFromMemcached FINE: Loading session from memcached: 31F5CECBD45876A87B6D37F3C756B8DF.tomcat81 Feb 11, 2016 11:58:45 AM de.javakaffee.web.msm.MemcachedSessionService loadFromMemcached FINE: Found session with id 31F5CECBD45876A87B6D37F3C756B8DF.tomcat81 Feb 11, 2016 11:58:45 AM de.javakaffee.web.msm.MemcachedBackupSessionManager removeInternal FINE: remove invoked, removeFromMemcached: true, id: 31F5CECBD45876A87B6D37F3C756B8DF.tomcat81 Feb 11, 2016 11:58:45 AM de.javakaffee.web.msm.MemcachedSessionService deleteFromMemcached FINE: Deleting session from memcached: 31F5CECBD45876A87B6D37F3C756B8DF.tomcat81 Feb 11, 2016 11:58:45 AM de.javakaffee.web.msm.MemcachedSessionService backupSession FINE: No session found in session map for 31F5CECBD45876A87B6D37F3C756B8DF.tomcat81 Feb 11, 2016 11:58:45 AM de.javakaffee.web.msm.RequestTrackingHostValve logDebugRequestSessionCookie FINE: Have request session cookie: domain=null, maxAge=-1, path=null, value=31F5CECBD45876A87B6D37F3C756B8DF.tomcat81, version=0, secure=false Feb 11, 2016 11:58:45 AM de.javakaffee.web.msm.RequestTrackingHostValve invoke FINE: <<<<<< Request finished: GET /zcubator9315/control/login?message=NoSession ================== Feb 11, 2016 11:58:45 AM de.javakaffee.web.msm.RequestTrackingHostValve invoke FINE: >>>>>> Ignoring: GET /zcubator9315/tenants/AdvantaClean/static/Fran091211/images/loginLogo.jpg (requestedSessionId 31F5CECBD45876A87B6D37F3C756B8DF.tomcat81) ================== Feb 11, 2016 11:58:45 AM de.javakaffee.web.msm.MemcachedSessionService createSession FINE: createSession invoked: null Feb 11, 2016 11:58:45 AM de.javakaffee.web.msm.MemcachedSessionService createSession FINE: Created new session with id 190BF4EECA221851DD3FFBF0B78098AB.tomcat81 Feb 11, 2016 11:58:45 AM de.javakaffee.web.msm.RequestTrackingHostValve invoke FINE: <<<<<< Ignored: GET /zcubator9315/tenants/AdvantaClean/static/Fran091211/images/loginLogo.jpg ================== Feb 11, 2016 11:58:45 AM de.javakaffee.web.msm.RequestTrackingHostValve invoke FINE: >>>>>> Ignoring: GET /zcubator9315/tenants/AdvantaClean/static/Fran091211/images/loginLogo.jpg (requestedSessionId 190BF4EECA221851DD3FFBF0B78098AB.tomcat81) ================== Feb 11, 2016 11:58:45 AM de.javakaffee.web.msm.MemcachedSessionService findSession FINE: Returning for session id 190BF4EECA221851DD3FFBF0B78098AB.tomcat81 (isConnectoogin time and very next request rSessionLookup: false, isIgnoredRequest: true) Feb 11, 2016 11:58:45 AM de.javakaffee.web.msm.MemcachedSessionService findSession FINE: Returning for session id 190BF4EECA221851DD3FFBF0B78098AB.tomcat81 (isConnectorSessionLookup: false, isIgnoredRequest: true) Feb 11, 2016 11:58:45 AM de.javakaffee.web.msm.MemcachedSessionService findSession FINE: Returning for session id 190BF4EECA221851DD3FFBF0B78098AB.tomcat81 (isConnectorSessionLookup: false, isIgnoredRequest: true) Feb 11, 2016 11:58:45 AM de.javakaffee.web.msm.MemcachedSessionService createSession FINE: createSession invoked: null Feb 11, 2016 11:58:45 AM de.javakaffee.web.msm.MemcachedSessionService createSession FINE: Created new session with id 0525CC2D10556ADC28C1AEA4BBC6DA10.tomcat81 Feb 11, 2016 11:58:45 AM de.javakaffee.web.msm.RequestTrackingHostValve invoke FINE: <<<<<< Ignored: GET /zcubator9315/tenants/AdvantaClean/static/Fran091211/images/loginLogo.jpg ==================

erLovepreet avatar Feb 11 '16 06:02 erLovepreet

Ok. My next hypothesis is that the issue is caused by assets (png, jpg etc), that a new session is created for them. To verify this, can you please remove the requestUriIgnorePattern attribute and report what's happening and share logs again? Am 11.02.2016 07:42 schrieb "erLovepreet" [email protected]:

Hi sir,

Sorry for late reply , i got that problem and i applied temporary solution for that problem. and i have used SNAPSHOT jars but i am getting some other problem i have used these two jars rest are same memcached-session-manager-1.9.0-RC2-SNAPSHOT.jar memcached-session-manager-tc8-1.9.0-RC2-SNAPSHOT(1).jar

This doesnot even work in our project environment in our project we authenticate user and create session and set variable like isLoggedIn -true to session and then our interceptor checks every time whether user requested with particular session have that variable or not if not it will redirect user to login screen thats what our project do

now about new jars problem is : every time i login it redirect to login success but at very next request it redirect user to again login screen

i am sharing logs of login time and very next request

login time logs

Feb 11, 2016 11:58:14 AM de.javakaffee.web.msm.RequestTrackingHostValve invoke FINE: >>>>>> Request starting: POST /zcubator9315/control/authenticate

(requestedSessionId 3EB70B36E7D164E105044C0A18A5238D.tomcat81)

Feb 11, 2016 11:58:14 AM de.javakaffee.web.msm.MemcachedSessionService loadFromMemcached FINE: Loading session from memcached: 3EB70B36E7D164E105044C0A18A5238D.tomcat81 Feb 11, 2016 11:58:14 AM de.javakaffee.web.msm.MemcachedSessionService loadFromMemcached FINE: Session 3EB70B36E7D164E105044C0A18A5238D.tomcat81 not found in memcached. Feb 11, 2016 11:58:14 AM de.javakaffee.web.msm.MemcachedSessionService createSession FINE: createSession invoked: null Feb 11, 2016 11:58:14 AM de.javakaffee.web.msm.MemcachedSessionService createSession FINE: Created new session with id 6B0996AAC22C2B8C934C1587D5435905.tomcat81 !!!!!!!!22 :

......................................this is where isLoggedin in set in session.........................

canAccessCustomerFeedback>>>>>>>>>>>>>>>>>>>>>>>>>>>>>true Feb 11, 2016 11:58:14 AM de.javakaffee.web.msm.BackupSessionService backupSession FINE: Starting for session id 6B0996AAC22C2B8C934C1587D5435905.tomcat81 Feb 11, 2016 11:58:14 AM de.javakaffee.web.msm.BackupSessionTask call FINE: Starting for session id 6B0996AAC22C2B8C934C1587D5435905.tomcat81 Feb 11, 2016 11:58:14 AM de.javakaffee.web.msm.BackupSessionTask doBackupSession FINE: Trying to store session in memcached: 6B0996AAC22C2B8C934C1587D5435905.tomcat81 Feb 11, 2016 11:58:14 AM de.javakaffee.web.msm.BackupSessionTask call FINE: Finished for session id 6B0996AAC22C2B8C934C1587D5435905.tomcat81, returning status SUCCESS Feb 11, 2016 11:58:14 AM de.javakaffee.web.msm.LockingStrategy onAfterBackupSession FINE: Stored session validity info for session 6B0996AAC22C2B8C934C1587D5435905.tomcat81 Feb 11, 2016 11:58:14 AM de.javakaffee.web.msm.RequestTrackingHostValve logDebugRequestSessionCookie FINE: Have request session cookie: domain=null, maxAge=-1, path=null, value=3EB70B36E7D164E105044C0A18A5238D.tomcat81, version=0, secure=false Feb 11, 2016 11:58:14 AM de.javakaffee.web.msm.RequestTrackingHostValve logDebugResponseCookie FINE: Request finished, with Set-Cookie header: JSESSIONID=6B0996AAC22C2B8C934C1587D5435905.tomcat81; Path=/zcubator9315/; HttpOnly Feb 11, 2016 11:58:14 AM de.javakaffee.web.msm.RequestTrackingHostValve invoke

FINE: <<<<<< Request finished: POST /zcubator9315/control/authenticate

Feb 11, 2016 11:58:14 AM de.javakaffee.web.msm.RequestTrackingHostValve invoke FINE: >>>>>> Request starting: GET /zcubator9315/control/nexturl?nextUrl=marketingCenter&menuName=zcubator&subMenuName=first

(requestedSessionId 6B0996AAC22C2B8C934C1587D5435905.tomcat81)

Feb 11, 2016 11:58:14 AM de.javakaffee.web.msm.MemcachedSessionService loadFromMemcached FINE: Loading session from memcached: 6B0996AAC22C2B8C934C1587D5435905.tomcat81 Feb 11, 2016 11:58:14 AM de.javakaffee.web.msm.MemcachedSessionService loadFromMemcached FINE: Found session with id 6B0996AAC22C2B8C934C1587D5435905.tomcat81 Feb 11, 2016 11:58:15 AM de.javakaffee.web.msm.BackupSessionService backupSession FINE: Starting for session id 6B0996AAC22C2B8C934C1587D5435905.tomcat81 Feb 11, 2016 11:58:15 AM de.javakaffee.web.msm.BackupSessionTask call FINE: Starting for session id 6B0996AAC22C2B8C934C1587D5435905.tomcat81 Feb 11, 2016 11:58:15 AM de.javakaffee.web.msm.BackupSessionTask doBackupSession FINE: Trying to store session in memcached: 6B0996AAC22C2B8C934C1587D5435905.tomcat81 Feb 11, 2016 11:58:15 AM de.javakaffee.web.msm.BackupSessionTask call FINE: Finished for session id 6B0996AAC22C2B8C934C1587D5435905.tomcat81, returning status SUCCESS Feb 11, 2016 11:58:15 AM de.javakaffee.web.msm.LockingStrategy onAfterBackupSession FINE: Stored session validity info for session 6B0996AAC22C2B8C934C1587D5435905.tomcat81 Feb 11, 2016 11:58:15 AM de.javakaffee.web.msm.RequestTrackingHostValve logDebugRequestSessionCookie FINE: Have request session cookie: domain=null, maxAge=-1, path=null, value=6B0996AAC22C2B8C934C1587D5435905.tomcat81, version=0, secure=false Feb 11, 2016 11:58:15 AM de.javakaffee.web.msm.RequestTrackingHostValve invoke FINE: <<<<<< Request finished: GET

/zcubator9315/control/nexturl?nextUrl=marketingCenter&menuName=zcubator&subMenuName=first

Feb 11, 2016 11:58:15 AM de.javakaffee.web.msm.RequestTrackingHostValve invoke FINE: >>>>>> Request starting: GET /zcubator9315/control/marketingCenter

(requestedSessionId 6B0996AAC22C2B8C934C1587D5435905.tomcat81)

Feb 11, 2016 11:58:15 AM de.javakaffee.web.msm.MemcachedSessionService loadFromMemcached FINE: Loading session from memcached: 6B0996AAC22C2B8C934C1587D5435905.tomcat81 Feb 11, 2016 11:58:15 AM de.javakaffee.web.msm.MemcachedSessionService loadFromMemcached FINE: Found session with id 6B0996AAC22C2B8C934C1587D5435905.tomcat81 Feb 11, 2016 11:58:15 AM de.javakaffee.web.msm.RequestTrackingHostValve invoke FINE: >>>>>> Ignoring: GET /zcubator9315/tenants/AdvantaClean/static/Fran091211/images/buildLogo.png

(requestedSessionId 6B0996AAC22C2B8C934C1587D5435905.tomcat81)

Feb 11, 2016 11:58:15 AM de.javakaffee.web.msm.MemcachedSessionService requestFinished FINE: Session 6B0996AAC22C2B8C934C1587D5435905.tomcat81 is still used by another request, skipping backup and (optional) lock handling/release. Feb 11, 2016 11:58:15 AM de.javakaffee.web.msm.RequestTrackingHostValve invoke FINE: <<<<<< Ignored: GET

/zcubator9315/tenants/AdvantaClean/static/Fran091211/images/buildLogo.png

recentPPCCallsExist false Feb 11, 2016 11:58:15 AM de.javakaffee.web.msm.BackupSessionService backupSession FINE: Starting for session id 6B0996AAC22C2B8C934C1587D5435905.tomcat81 Feb 11, 2016 11:58:15 AM de.javakaffee.web.msm.BackupSessionTask call FINE: Starting for session id 6B0996AAC22C2B8C934C1587D5435905.tomcat81 Feb 11, 2016 11:58:15 AM de.javakaffee.web.msm.BackupSessionTask doBackupSession FINE: Trying to store session in memcached: 6B0996AAC22C2B8C934C1587D5435905.tomcat81 Feb 11, 2016 11:58:15 AM de.javakaffee.web.msm.BackupSessionTask call FINE: Finished for session id 6B0996AAC22C2B8C934C1587D5435905.tomcat81, returning status SUCCESS Feb 11, 2016 11:58:15 AM de.javakaffee.web.msm.LockingStrategy onAfterBackupSession FINE: Stored session validity info for session 6B0996AAC22C2B8C934C1587D5435905.tomcat81 Feb 11, 2016 11:58:15 AM de.javakaffee.web.msm.RequestTrackingHostValve logDebugRequestSessionCookie FINE: Have request session cookie: domain=null, maxAge=-1, path=null, value=6B0996AAC22C2B8C934C1587D5435905.tomcat81, version=0, secure=false Feb 11, 2016 11:58:15 AM de.javakaffee.web.msm.RequestTrackingHostValve invoke

FINE: <<<<<< Request finished: GET /zcubator9315/control/marketingCenter

Feb 11, 2016 11:58:15 AM de.javakaffee.web.msm.RequestTrackingHostValve invoke FINE: >>>>>> Ignoring: GET /zcubator9315/tenants/AdvantaClean/static/Fran091211/images/buildLogo.png

(requestedSessionId 6B0996AAC22C2B8C934C1587D5435905.tomcat81)

Feb 11, 2016 11:58:15 AM de.javakaffee.web.msm.MemcachedSessionService findSession FINE: Returning for session id 6B0996AAC22C2B8C934C1587D5435905.tomcat81 (isConnectorSessionLookup: false, isIgnoredRequest: true) Feb 11, 2016 11:58:15 AM de.javakaffee.web.msm.MemcachedSessionService findSession FINE: Returning for session id 6B0996AAC22C2B8C934C1587D5435905.tomcat81 (isConnectorSessionLookup: false, isIgnoredRequest: true) Feb 11, 2016 11:58:15 AM de.javakaffee.web.msm.MemcachedSessionService findSession FINE: Returning for session id 6B0996AAC22C2B8C934C1587D5435905.tomcat81 (isConnectorSessionLookup: false, isIgnoredRequest: true) Feb 11, 2016 11:58:15 AM de.javakaffee.web.msm.MemcachedSessionService createSession FINE: createSession invoked: null Feb 11, 2016 11:58:15 AM de.javakaffee.web.msm.MemcachedSessionService createSession FINE: Created new session with id 44C08DD05006678837759C0C540132E0.tomcat81 Feb 11, 2016 11:58:15 AM de.javakaffee.web.msm.RequestTrackingHostValve invoke FINE: <<<<<< Ignored: GET

/zcubator9315/tenants/AdvantaClean/static/Fran091211/images/buildLogo.png

Feb 11, 2016 11:58:15 AM de.javakaffee.web.msm.RequestTrackingHostValve invoke FINE: >>>>>> Ignoring: GET /zcubator9315/static/Fran091211/onboard/loading_background.png

(requestedSessionId 44C08DD05006678837759C0C540132E0.tomcat81)

Feb 11, 2016 11:58:15 AM de.javakaffee.web.msm.MemcachedSessionService findSession FINE: Returning for session id 44C08DD05006678837759C0C540132E0.tomcat81 (isConnectorSessionLookup: false, isIgnoredRequest: true) Feb 11, 2016 11:58:15 AM de.javakaffee.web.msm.MemcachedSessionService findSession FINE: Returning for session id 44C08DD05006678837759C0C540132E0.tomcat81 (isConnectorSessionLookup: false, isIgnoredRequest: true) Feb 11, 2016 11:58:15 AM de.javakaffee.web.msm.MemcachedSessionService findSession FINE: Returning for session id 44C08DD05006678837759C0C540132E0.tomcat81 (isConnectorSessionLookup: false, isIgnoredRequest: true) Feb 11, 2016 11:58:15 AM de.javakaffee.web.msm.MemcachedSessionService createSession FINE: createSession invoked: null Feb 11, 2016 11:58:15 AM de.javakaffee.web.msm.MemcachedSessionService createSession FINE: Created new session with id 4ACA10FC49E11DD32DEC5F6F7073A143.tomcat81 Feb 11, 2016 11:58:15 AM de.javakaffee.web.msm.RequestTrackingHostValve invoke FINE: <<<<<< Ignored: GET

/zcubator9315/static/Fran091211/onboard/loading_background.png

next request logs

Feb 11, 2016 11:58:45 AM de.javakaffee.web.msm.RequestTrackingHostValve invoke FINE: >>>>>> Request starting: GET /zcubator9315/control/nexturl?nextUrl=main&menuName=intranet&subMenuName=first

(requestedSessionId 4ACA10FC49E11DD32DEC5F6F7073A143.tomcat81)

Feb 11, 2016 11:58:45 AM de.javakaffee.web.msm.MemcachedSessionService loadFromMemcached FINE: Loading session from memcached: 4ACA10FC49E11DD32DEC5F6F7073A143.tomcat81 Feb 11, 2016 11:58:45 AM de.javakaffee.web.msm.MemcachedSessionService loadFromMemcached FINE: Session 4ACA10FC49E11DD32DEC5F6F7073A143.tomcat81 not found in memcached. Feb 11, 2016 11:58:45 AM de.javakaffee.web.msm.MemcachedSessionService createSession FINE: createSession invoked: null Feb 11, 2016 11:58:45 AM de.javakaffee.web.msm.MemcachedSessionService createSession FINE: Created new session with id 31F5CECBD45876A87B6D37F3C756B8DF.tomcat81 Feb 11, 2016 11:58:45 AM de.javakaffee.web.msm.BackupSessionService backupSession FINE: Starting for session id 31F5CECBD45876A87B6D37F3C756B8DF.tomcat81 Feb 11, 2016 11:58:45 AM de.javakaffee.web.msm.BackupSessionTask call FINE: Starting for session id 31F5CECBD45876A87B6D37F3C756B8DF.tomcat81 Feb 11, 2016 11:58:45 AM de.javakaffee.web.msm.BackupSessionTask doBackupSession FINE: Trying to store session in memcached: 31F5CECBD45876A87B6D37F3C756B8DF.tomcat81 Feb 11, 2016 11:58:45 AM de.javakaffee.web.msm.BackupSessionTask call FINE: Finished for session id 31F5CECBD45876A87B6D37F3C756B8DF.tomcat81, returning status SUCCESS Feb 11, 2016 11:58:45 AM de.javakaffee.web.msm.LockingStrategy onAfterBackupSession FINE: Stored session validity info for session 31F5CECBD45876A87B6D37F3C756B8DF.tomcat81 Feb 11, 2016 11:58:45 AM de.javakaffee.web.msm.RequestTrackingHostValve logDebugRequestSessionCookie FINE: Have request session cookie: domain=null, maxAge=-1, path=null, value=4ACA10FC49E11DD32DEC5F6F7073A143.tomcat81, version=0, secure=false Feb 11, 2016 11:58:45 AM de.javakaffee.web.msm.RequestTrackingHostValve logDebugResponseCookie FINE: Request finished, with Set-Cookie header: JSESSIONID=31F5CECBD45876A87B6D37F3C756B8DF.tomcat81; Path=/zcubator9315/; HttpOnly Feb 11, 2016 11:58:45 AM de.javakaffee.web.msm.RequestTrackingHostValve invoke FINE: <<<<<< Request finished: GET

/zcubator9315/control/nexturl?nextUrl=main&menuName=intranet&subMenuName=first

Feb 11, 2016 11:58:45 AM de.javakaffee.web.msm.RequestTrackingHostValve invoke FINE: >>>>>> Request starting: GET /zcubator9315/control/login?message=NoSession (requestedSessionId 31F5CECBD45876A87B6D37F3C756B8DF.tomcat81) ================== Feb 11, 2016 11:58:45 AM de.javakaffee.web.msm.MemcachedSessionService loadFromMemcached FINE: Loading session from memcached: 31F5CECBD45876A87B6D37F3C756B8DF.tomcat81 Feb 11, 2016 11:58:45 AM de.javakaffee.web.msm.MemcachedSessionService loadFromMemcached FINE: Found session with id 31F5CECBD45876A87B6D37F3C756B8DF.tomcat81 Feb 11, 2016 11:58:45 AM de.javakaffee.web.msm.MemcachedBackupSessionManager removeInternal FINE: remove invoked, removeFromMemcached: true, id: 31F5CECBD45876A87B6D37F3C756B8DF.tomcat81 Feb 11, 2016 11:58:45 AM de.javakaffee.web.msm.MemcachedSessionService deleteFromMemcached FINE: Deleting session from memcached: 31F5CECBD45876A87B6D37F3C756B8DF.tomcat81 Feb 11, 2016 11:58:45 AM de.javakaffee.web.msm.MemcachedSessionService backupSession FINE: No session found in session map for 31F5CECBD45876A87B6D37F3C756B8DF.tomcat81 Feb 11, 2016 11:58:45 AM de.javakaffee.web.msm.RequestTrackingHostValve logDebugRequestSessionCookie FINE: Have request session cookie: domain=null, maxAge=-1, path=null, value=31F5CECBD45876A87B6D37F3C756B8DF.tomcat81, version=0, secure=false Feb 11, 2016 11:58:45 AM de.javakaffee.web.msm.RequestTrackingHostValve invoke FINE: <<<<<< Request finished: GET /zcubator9315/control/login?message=NoSession ================== Feb 11, 2016 11:58:45 AM de.javakaffee.web.msm.RequestTrackingHostValve invoke FINE: >>>>>> Ignoring: GET /zcubator9315/tenants/AdvantaClean/static/Fran091211/images/loginLogo.jpg

(requestedSessionId 31F5CECBD45876A87B6D37F3C756B8DF.tomcat81)

Feb 11, 2016 11:58:45 AM de.javakaffee.web.msm.MemcachedSessionService createSession FINE: createSession invoked: null Feb 11, 2016 11:58:45 AM de.javakaffee.web.msm.MemcachedSessionService createSession FINE: Created new session with id 190BF4EECA221851DD3FFBF0B78098AB.tomcat81 Feb 11, 2016 11:58:45 AM de.javakaffee.web.msm.RequestTrackingHostValve invoke FINE: <<<<<< Ignored: GET

/zcubator9315/tenants/AdvantaClean/static/Fran091211/images/loginLogo.jpg

Feb 11, 2016 11:58:45 AM de.javakaffee.web.msm.RequestTrackingHostValve invoke FINE: >>>>>> Ignoring: GET /zcubator9315/tenants/AdvantaClean/static/Fran091211/images/loginLogo.jpg

(requestedSessionId 190BF4EECA221851DD3FFBF0B78098AB.tomcat81)

Feb 11, 2016 11:58:45 AM de.javakaffee.web.msm.MemcachedSessionService findSession FINE: Returning for session id 190BF4EECA221851DD3FFBF0B78098AB.tomcat81 (isConnectoogin time and very next request rSessionLookup: false, isIgnoredRequest: true) Feb 11, 2016 11:58:45 AM de.javakaffee.web.msm.MemcachedSessionService findSession FINE: Returning for session id 190BF4EECA221851DD3FFBF0B78098AB.tomcat81 (isConnectorSessionLookup: false, isIgnoredRequest: true) Feb 11, 2016 11:58:45 AM de.javakaffee.web.msm.MemcachedSessionService findSession FINE: Returning for session id 190BF4EECA221851DD3FFBF0B78098AB.tomcat81 (isConnectorSessionLookup: false, isIgnoredRequest: true) Feb 11, 2016 11:58:45 AM de.javakaffee.web.msm.MemcachedSessionService createSession FINE: createSession invoked: null Feb 11, 2016 11:58:45 AM de.javakaffee.web.msm.MemcachedSessionService createSession FINE: Created new session with id 0525CC2D10556ADC28C1AEA4BBC6DA10.tomcat81 Feb 11, 2016 11:58:45 AM de.javakaffee.web.msm.RequestTrackingHostValve invoke FINE: <<<<<< Ignored: GET

/zcubator9315/tenants/AdvantaClean/static/Fran091211/images/loginLogo.jpg

— Reply to this email directly or view it on GitHub https://github.com/magro/memcached-session-manager/issues/283#issuecomment-182738323 .

magro avatar Feb 11 '16 15:02 magro

Sir, Bad news doesn't work again :(

here's the log

Feb 12, 2016 12:37:45 PM de.javakaffee.web.msm.RequestTrackingHostValve invoke FINE: >>>>>> Request starting: GET /franconnect9315/control/othersidelogin?clientKey=BASE_TEST (requestedSessionId 6D2647B3A9A5C3049376CDAC02BA68FD.tomcat81) ================== Feb 12, 2016 12:37:45 PM de.javakaffee.web.msm.MemcachedSessionService loadFromMemcached FINE: Loading session from memcached: 6D2647B3A9A5C3049376CDAC02BA68FD.tomcat81 Feb 12, 2016 12:37:45 PM de.javakaffee.web.msm.MemcachedSessionService loadFromMemcached FINE: Found session with id 6D2647B3A9A5C3049376CDAC02BA68FD.tomcat81

tabUrl==========null clientKey=BASE_TEST

.......................I gona call invalidate...........................

Feb 12, 2016 12:37:45 PM de.javakaffee.web.msm.MemcachedBackupSessionManager removeInternal FINE: remove invoked, removeFromMemcached: true, id: 6D2647B3A9A5C3049376CDAC02BA68FD.tomcat81 Feb 12, 2016 12:37:45 PM de.javakaffee.web.msm.MemcachedSessionService deleteFromMemcached FINE: Deleting session from memcached: 6D2647B3A9A5C3049376CDAC02BA68FD.tomcat81 Feb 12, 2016 12:37:45 PM de.javakaffee.web.msm.MemcachedSessionService backupSession FINE: No session found in session map for 6D2647B3A9A5C3049376CDAC02BA68FD.tomcat81 Feb 12, 2016 12:37:45 PM de.javakaffee.web.msm.RequestTrackingHostValve logDebugRequestSessionCookie FINE: Have request session cookie: domain=null, maxAge=-1, path=null, value=6D2647B3A9A5C3049376CDAC02BA68FD.tomcat81, version=0, secure=false Feb 12, 2016 12:37:45 PM de.javakaffee.web.msm.RequestTrackingHostValve invoke FINE: <<<<<< Request finished: GET /franconnect9315/control/othersidelogin?clientKey=BASE_TEST ================== Feb 12, 2016 12:37:45 PM de.javakaffee.web.msm.RequestTrackingHostValve invoke FINE: >>>>>> Request starting: POST /zcubator9315/control/ssologin (requestedSessionId 44AAAEAD9DE90088D5088874D01CD258.tomcat81) ================== Feb 12, 2016 12:37:45 PM de.javakaffee.web.msm.MemcachedSessionService loadFromMemcached FINE: Loading session from memcached: 44AAAEAD9DE90088D5088874D01CD258.tomcat81 Feb 12, 2016 12:37:45 PM de.javakaffee.web.msm.MemcachedSessionService loadFromMemcached FINE: Session 44AAAEAD9DE90088D5088874D01CD258.tomcat81 not found in memcached. Feb 12, 2016 12:37:45 PM de.javakaffee.web.msm.MemcachedSessionService createSession FINE: createSession invoked: null Feb 12, 2016 12:37:45 PM de.javakaffee.web.msm.MemcachedSessionService createSession FINE: Created new session with id F3FBB268522CA19FC05BD77F1F9123BF.tomcat81 Feb 12, 2016 12:37:46 PM de.javakaffee.web.msm.RequestTrackingHostValve invoke FINE: >>>>>> Request starting: POST /zcubator9315/control/authenticate (requestedSessionId F3FBB268522CA19FC05BD77F1F9123BF.tomcat81) ================== !!!!!!!!22 : Feb 12, 2016 12:37:46 PM de.javakaffee.web.msm.BackupSessionService backupSession FINE: Starting for session id F3FBB268522CA19FC05BD77F1F9123BF.tomcat81 Feb 12, 2016 12:37:46 PM de.javakaffee.web.msm.BackupSessionTask call FINE: Starting for session id F3FBB268522CA19FC05BD77F1F9123BF.tomcat81 Feb 12, 2016 12:37:46 PM de.javakaffee.web.msm.BackupSessionTask doBackupSession FINE: Trying to store session in memcached: F3FBB268522CA19FC05BD77F1F9123BF.tomcat81 Feb 12, 2016 12:37:46 PM de.javakaffee.web.msm.BackupSessionTask call FINE: Finished for session id F3FBB268522CA19FC05BD77F1F9123BF.tomcat81, returning status SUCCESS

......................................this is where isLoggedin in set in session.........................

Feb 12, 2016 12:37:46 PM de.javakaffee.web.msm.LockingStrategy onAfterBackupSession FINE: Stored session validity info for session F3FBB268522CA19FC05BD77F1F9123BF.tomcat81 Feb 12, 2016 12:37:46 PM de.javakaffee.web.msm.RequestTrackingHostValve logDebugRequestSessionCookie FINE: Have request session cookie: domain=null, maxAge=-1, path=null, value=44AAAEAD9DE90088D5088874D01CD258.tomcat81, version=0, secure=false Feb 12, 2016 12:37:46 PM de.javakaffee.web.msm.RequestTrackingHostValve logDebugResponseCookie FINE: Request finished, with Set-Cookie header: JSESSIONID=F3FBB268522CA19FC05BD77F1F9123BF.tomcat81; Path=/zcubator9315/; HttpOnly Feb 12, 2016 12:37:46 PM de.javakaffee.web.msm.RequestTrackingHostValve invoke FINE: <<<<<< Request finished: POST /zcubator9315/control/ssologin ================== canAccessCustomerFeedback>>>>>>>>>>>>>>>>>>>>>>>>>>>>>true Feb 12, 2016 12:37:46 PM de.javakaffee.web.msm.MemcachedSessionService backupSession FINE: No session found in session map for F3FBB268522CA19FC05BD77F1F9123BF.tomcat81 Feb 12, 2016 12:37:46 PM de.javakaffee.web.msm.LockingStrategy onBackupWithoutLoadedSession FINE: Stored session validity info for session F3FBB268522CA19FC05BD77F1F9123BF.tomcat81 Feb 12, 2016 12:37:46 PM de.javakaffee.web.msm.RequestTrackingHostValve logDebugRequestSessionCookie FINE: Have request session cookie: domain=null, maxAge=-1, path=null, value=F3FBB268522CA19FC05BD77F1F9123BF.tomcat81, version=0, secure=false Feb 12, 2016 12:37:46 PM de.javakaffee.web.msm.RequestTrackingHostValve invoke FINE: <<<<<< Request finished: POST /zcubator9315/control/authenticate ================== Feb 12, 2016 12:37:46 PM de.javakaffee.web.msm.LockingStrategy pingSession FINE: The session was ping'ed successfully. Feb 12, 2016 12:37:46 PM de.javakaffee.web.msm.RequestTrackingHostValve invoke FINE: >>>>>> Request starting: GET /zcubator9315/control/nexturl?nextUrl=marketingCenter&menuName=zcubator&subMenuName=first (requestedSessionId F3FBB268522CA19FC05BD77F1F9123BF.tomcat81) ================== Feb 12, 2016 12:37:46 PM de.javakaffee.web.msm.MemcachedSessionService loadFromMemcached FINE: Loading session from memcached: F3FBB268522CA19FC05BD77F1F9123BF.tomcat81 Feb 12, 2016 12:37:46 PM de.javakaffee.web.msm.MemcachedSessionService loadFromMemcached FINE: Found session with id F3FBB268522CA19FC05BD77F1F9123BF.tomcat81 Feb 12, 2016 12:37:46 PM de.javakaffee.web.msm.BackupSessionService backupSession FINE: Starting for session id F3FBB268522CA19FC05BD77F1F9123BF.tomcat81 Feb 12, 2016 12:37:46 PM de.javakaffee.web.msm.BackupSessionTask call FINE: Starting for session id F3FBB268522CA19FC05BD77F1F9123BF.tomcat81 Feb 12, 2016 12:37:46 PM de.javakaffee.web.msm.BackupSessionTask call FINE: Finished for session id F3FBB268522CA19FC05BD77F1F9123BF.tomcat81, returning status SKIPPED Feb 12, 2016 12:37:46 PM de.javakaffee.web.msm.LockingStrategy onAfterBackupSession FINE: Stored session validity info for session F3FBB268522CA19FC05BD77F1F9123BF.tomcat81 Feb 12, 2016 12:37:46 PM de.javakaffee.web.msm.RequestTrackingHostValve logDebugRequestSessionCookie FINE: Have request session cookie: domain=null, maxAge=-1, path=null, value=F3FBB268522CA19FC05BD77F1F9123BF.tomcat81, version=0, secure=false Feb 12, 2016 12:37:46 PM de.javakaffee.web.msm.RequestTrackingHostValve invoke FINE: <<<<<< Request finished: GET /zcubator9315/control/nexturl?nextUrl=marketingCenter&menuName=zcubator&subMenuName=first ================== Feb 12, 2016 12:37:46 PM de.javakaffee.web.msm.LockingStrategy pingSession FINE: The session was ping'ed successfully. Feb 12, 2016 12:37:46 PM de.javakaffee.web.msm.RequestTrackingHostValve invoke FINE: >>>>>> Request starting: GET /zcubator9315/control/login?message=NoSession (requestedSessionId F3FBB268522CA19FC05BD77F1F9123BF.tomcat81) ================== Feb 12, 2016 12:37:46 PM de.javakaffee.web.msm.MemcachedSessionService loadFromMemcached FINE: Loading session from memcached: F3FBB268522CA19FC05BD77F1F9123BF.tomcat81 Feb 12, 2016 12:37:46 PM de.javakaffee.web.msm.MemcachedSessionService loadFromMemcached FINE: Found session with id F3FBB268522CA19FC05BD77F1F9123BF.tomcat81

One thing i want you to know that this only occurs when previous request takes too much time to execute. means we can reproduce it with the help of thread.sleep().

erLovepreet avatar Feb 12 '16 07:02 erLovepreet

Can you create a reproducable sample based on https://github.com/magro/memcached-session-manager/tree/master/samples? Then I can check and analyze this.

magro avatar Feb 13 '16 09:02 magro

@erLovepreet How's it going, can you create a reproducable sample for your issue?

magro avatar Mar 07 '16 22:03 magro

I also noticed a similar issue. Digging into the logs I found the following stack trace:

WARNING: Could not load session with id 99124C00B7D1AFEAA5DF8697B74C4E81 from memcached.
java.lang.NullPointerException
    at de.javakaffee.web.msm.MemcachedSessionService.loadFromMemcached(MemcachedSessionService.java:1138)
    at de.javakaffee.web.msm.MemcachedSessionService.findSession(MemcachedSessionService.java:595)
    at de.javakaffee.web.msm.MemcachedBackupSessionManager.findSession(MemcachedBackupSessionManager.java:208)
    at org.apache.catalina.connector.Request.isRequestedSessionIdValid(Request.java:2374)
    at org.apache.catalina.connector.CoyoteAdapter.parseSessionCookiesId(CoyoteAdapter.java:1236)
    at org.apache.catalina.connector.CoyoteAdapter.postParseRequest(CoyoteAdapter.java:921)
    at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:517)
    at org.apache.coyote.http11.AbstractHttp11Processor.process(AbstractHttp11Processor.java:1095)
    at org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process(AbstractProtocol.java:672)
    at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1500)
    at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.run(NioEndpoint.java:1456)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
    at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
    at java.lang.Thread.run(Thread.java:745)

Configuration: Tomcat: 8.0.32 msm: 1.9.2 using a local memcache node

Thanks for any hint. If I can help with some more detailed logs, please let me know how to enable them. Thanks.

mirion avatar Mar 24 '16 18:03 mirion

@mirion can you reproduce this issue on your local machine or does it only happen in production from time to time? I'll have a look at the NPE soon.

magro avatar Mar 24 '16 18:03 magro

@mirion The NPE at this line is really weird - is it possible that this happened during startup or shutdown phase? Did you see it one or during a very short period, ofter several times during otherwise normal operation?

magro avatar Mar 24 '16 20:03 magro

@magro, The NPE may indeed appear during an app reload as I found the stack trace into eclipse.

I noticed initially that the sessions are expiring very quickly (few minutes). Since we just moved to tomcat 8, I was thinking that we missed some configuration but I checked the settings and everything is looking fine.

I can now reproduce the problem (not the NPE) into my local development environment. If you could give me some instructions on how to debug it, we may make some progress and eventually fix it.

The configuration that I'm using is the following (into context.xml):

<Manager className="de.javakaffee.web.msm.MemcachedBackupSessionManager" memcachedNodes="localhost:11211" requestUriIgnorePattern=".*\.(ico|png|gif|jpg|css|js)$"/>

I also noticed something very strange. It looks like the session is found into memcache but it is not restored correctly/completely. For example, I'm storing the database connection URL and after the session restore I'm getting a NPE when trying to use that URL. I have the main credentials object but they are missing that particular piece of information. This is really weird. Do you think that it may be an issue with kryo? On the other hand, we are using kryo for other stuff and I didn't notice any problem.

mirion avatar Mar 24 '16 21:03 mirion

@mirion Great that you're able to reproduce it!

  1. Re quick expiration: in tomcat indeed things changed, see also commit eddf4c45. If it's only happening with msm and not without msm then please submit a separate issue for this.

  2. Re incomplete deserialization: the config you posted does not mention kryo, so either kryo cannot be the reason, or the config you posted was incomplete ;-) Assuming the latter, you can change the serializer/transcoder to java and see if this solves the issue. Then it would have to do with kryo, and the solution would be either to use java serialization or with kryo to write/configure custom serializers for problematic classes. Does it happen only with the same certain classes (which once?), or randomly with different classes?

magro avatar Mar 24 '16 22:03 magro

Btw, I just noticed that URLs in fact cannot be (de)serialized with kryo...

magro avatar Mar 24 '16 23:03 magro

@magro Thanks a lot.

  1. I'll take a look at commit #eddf4c4. If I understand well, I should remove session-timeout from conf/web.xml and use maxInactiveInterval into the Manager's def? I can't reproduce the bug without msm because I have a complex system that uses several webapps in the same time. msm helps me to obtain a sort of SSO and also load balancing.
  2. My mistake. Initially we used kryo, but had some trouble with it (don't remember what exact happened - it may be related to this: https://github.com/EsotericSoftware/kryo/issues/128). Therefore we switched to Java serialization. I'll try again with kryo.
  3. I have the impression that we have a sort of race condition because it happens when 2 requests are sent about in the same time to 2 different webapps that are supposed to share the same session.
  4. What shall I do in order to activate the debug log?

Thnaks.

mirion avatar Mar 24 '16 23:03 mirion

We are not saving the URL as an object but the coordinates of the server and we later compose the JDBC URL to build the datasource if needed. I'll make a code inspection to check if the session manager bug is not triggering in fact a bug into our code, that otherwise can't arise because we are supposed to have a good session with all the data available.

In any case, beyond this serialization issue, the session expiration still exists.

mirion avatar Mar 24 '16 23:03 mirion

Re 1: you shouldn't have to do anything, I just wanted to mention that things in tomcat had changed. The mentioned commit handles this already.

Re 3: not sure what happens when different webapps share the same session - things may go wrong (because the manager/msm has no longer control)

magro avatar Mar 25 '16 00:03 magro

Re 4: see https://github.com/magro/memcached-session-manager/wiki/SetupAndConfiguration#configure-logging

magro avatar Mar 25 '16 00:03 magro

@magro Re 1. I was forced to set maxInactiveInterval into the manager. I know that is deprecated, but for unknown reasons I was not able to convince tomcat to use the value from web.xml (which was working well into version 7.0). I made a quick inspection of the code, but I couldn't find anything suspect.

Re 3. There was a problem with my local tomcat configuration. The Context didn't have sessionCookiePath="/" Once this set, it started to work perfectly. In fact, there is no reason why several webapps should not be able to share the same session (which is the case now). If I'm understanding correctly the mechanism, the session manager that is loaded by the container provides the sessions to the different applications. Therefore it is supposed to work, and it does. This mechanism combined with msm provides great load balancing infrastructure. Thanks a lot for your work.

mirion avatar Mar 25 '16 20:03 mirion

Great to hear that it's working now! Although I'd say that for each webapp a dedicated manager instance exists, which is necessary for appropriate lifecycle handling.

Strange to hear that the session timeout in web.xml doesn't work - was it the webapps web.xml or the global one? Does it also not work without msm?

magro avatar Mar 25 '16 21:03 magro

I'm sure that you know better how the session managers are working. I didn't dig into your code, but I suppose that you (synchronously?) save the session into the storage (memcache). Therefore even if the manager is different, the session can be can be recovered by another webapp. Since I never noticed any issue, even under heavy load (during load tests) I arrived at the conclusion that the sessions data is effectively shared. And it looks that I'm not the only one using the same procedure: http://forum.broadleafcommerce.org/viewtopic.php?t=4184 If my findings are supported by your code, it may be useful to put this info into the wiki. If I'm just benefiting from a side effect, it may make sense to harden this path and fully embrace it. Shared session managers are a common issue.

It was the global web.xml. I didn't remove the setting but I noticed that it is useless. Will check again when I'll have more time available.

mirion avatar Mar 25 '16 21:03 mirion