search

magro / memcached-session-manager

A tomcat session manager that backups sessions in memcached and pulls them from there if asked for unknown sessions
Apache License 2.0
758 stars 348 forks source link

Session not updated #385

Open cn-sws opened 6 years ago

cn-sws commented 6 years ago

Hi, running version 2.2.2 with sticky="false" and default locking. Sometimes a session does not seem to get updated. The harder I work it the worse the problem seems to become. (was running 2.1.1 but upgraded to 2.2.2 to try and get working. both versions give same result) This is the error I get: 25-Jul-2018 04:34:55.272 FINE [http-nio-8080-exec-3] de.javakaffee.web.msm.RequestTrackingHostValve.invoke >>>>>> Request starting: POST /dispatch/RaReadAction (requestedSessionId E15EC82C92320AE8C8C7EE5CE8E7B537) ================== 25-Jul-2018 04:34:55.273 WARNING [http-nio-8080-exec-3] com.gwtplatform.dispatch.rpc.server.AbstractDispatchServiceImpl.execute Action exception while executing com.shiftworksolutions.platform.mercury.shared.roster.admin.RaReadAction: Session has expired. Please reload the page to establish a new session. The WARNING is coming from our application code that has expected to get a particular item from the session but its not there. The FINE is indicating which session it is expecting: E15EC82C92320AE8C8C7EE5CE8E7B537. I would have thought between the msm message and our application message there should have been other msm messages such as 25-Jul-2018 04:34:52.032 FINE [http-nio-8080-exec-4] de.javakaffee.web.msm.MemcachedSessionService.loadFromMemcached Loading session from memcached: E6C3CA43FCB545A36F9B23F877B38051 25-Jul-2018 04:34:52.033 FINE [http-nio-8080-exec-4] de.javakaffee.web.msm.JavaSerializationTranscoder.deserializeAttributes loading attribute 'sessionVar' with value 'com.shiftworksolutions.project.bccr.server.boot.SessionVar@329af1fd' 25-Jul-2018 04:34:52.034 FINE [http-nio-8080-exec-4] de.javakaffee.web.msm.MemcachedSessionService.loadFromMemcached Found session with id E6C3CA43FCB545A36F9B23F877B38051

Looking earlier in the logs for all mentions of the sessionId of concern show only these in an earlier thread 25-Jul-2018 04:34:53.900 FINE [http-nio-8080-exec-4] de.javakaffee.web.msm.RequestTrackingHostValve.invoke >>>>>> Request starting: POST /Main/appRpc (requestedSessionId FF21B8439C41D8F787EBF294F56F5056) ================== 25-Jul-2018 04:34:53.901 FINE [http-nio-8080-exec-4] de.javakaffee.web.msm.MemcachedBackupSessionManager.removeInternal remove invoked, removeFromMemcached: true, id: FF21B8439C41D8F787EBF294F56F5056 25-Jul-2018 04:34:53.901 FINE [http-nio-8080-exec-4] de.javakaffee.web.msm.MemcachedSessionService.deleteFromMemcached Deleting session from memcached: FF21B8439C41D8F787EBF294F56F5056 25-Jul-2018 04:34:53.902 INFO [http-nio-8080-exec-4] com.shiftworksolutions.platform.mercury.server.authentication.LoginServlet.doGet Forwarding to login page 25-Jul-2018 04:34:53.903 FINE [http-nio-8080-exec-4] de.javakaffee.web.msm.MemcachedSessionService.backupSession Session E15EC82C92320AE8C8C7EE5CE8E7B537 is still used by another request, skipping backup and (optional) lock handling/release. 25-Jul-2018 04:34:53.904 FINE [http-nio-8080-exec-4] de.javakaffee.web.msm.RequestTrackingHostValve.logDebugRequestSessionCookie Have request session cookie: domain=null, maxAge=-1, path=null, value=FF21B8439C41D8F787EBF294F56F5056, version=0, secure=false 25-Jul-2018 04:34:53.904 FINE [http-nio-8080-exec-4] de.javakaffee.web.msm.RequestTrackingHostValve.logDebugResponseCookie Request finished, with Set-Cookie header: JSESSIONID=E15EC82C92320AE8C8C7EE5CE8E7B537; Path=/; HttpOnly 25-Jul-2018 04:34:53.904 FINE [http-nio-8080-exec-4] de.javakaffee.web.msm.RequestTrackingHostValve.invoke <<<<<< Request finished: POST /Main/appRpc ================== Nothing seems to have created or stored the session we want. That is, nothing like 25-Jul-2018 04:33:35.674 FINE [http-nio-8080-exec-7] de.javakaffee.web.msm.BackupSessionService.backupSession Starting for session id E6C3CA43FCB545A36F9B23F877B38051 25-Jul-2018 04:33:35.674 FINE [http-nio-8080-exec-7] de.javakaffee.web.msm.BackupSessionTask.call Starting for session id E6C3CA43FCB545A36F9B23F877B38051 25-Jul-2018 04:33:35.681 FINE [http-nio-8080-exec-7] de.javakaffee.web.msm.JavaSerializationTranscoder.writeAttributes storing attribute 'sessionVar' with value 'com.shiftworksolutions.project.bccr.server.boot.SessionVar@365a979a' 25-Jul-2018 04:33:35.685 FINE [http-nio-8080-exec-7] de.javakaffee.web.msm.BackupSessionTask.doBackupSession Trying to store session in memcached: E6C3CA43FCB545A36F9B23F877B38051 25-Jul-2018 04:33:35.686 FINE [http-nio-8080-exec-7] de.javakaffee.web.msm.BackupSessionTask.call Finished for session id E6C3CA43FCB545A36F9B23F877B38051, returning status SUCCESS 25-Jul-2018 04:33:35.688 FINE [http-nio-8080-exec-7] de.javakaffee.web.msm.LockingStrategy.onAfterBackupSession Stored session validity info for session E6C3CA43FCB545A36F9B23F877B38051

lockingMode all or auto seems to help a bit but not completely.

cn-sws commented 6 years ago

some more examples. with logging on auto. 25-Jul-2018 06:18:49.791 FINE [http-nio-8080-exec-9] de.javakaffee.web.msm.RequestTrackingHostValve.invoke >>>>>> Request starting: POST /Main/appRpc (requestedSessionId AECC8FA528109C93B8EB987A4263A0DF) ================== 25-Jul-2018 06:18:49.791 FINE [http-nio-8080-exec-9] de.javakaffee.web.msm.MemcachedSessionService.loadFromMemcached Loading session from memcached: AECC8FA528109C93B8EB987A4263A0DF 25-Jul-2018 06:18:49.791 FINE [http-nio-8080-exec-9] de.javakaffee.web.msm.ReadOnlyRequestsCache.isReadOnlyRequest Asked for readonly request: POST /Main/appRpc (false) 25-Jul-2018 06:18:49.791 FINE [http-nio-8080-exec-9] de.javakaffee.web.msm.LockingStrategy.lock Locking session AECC8FA528109C93B8EB987A4263A0DF 25-Jul-2018 06:18:49.794 FINE [http-nio-8080-exec-9] de.javakaffee.web.msm.LockingStrategy.acquireLock Locked session AECC8FA528109C93B8EB987A4263A0DF 25-Jul-2018 06:18:49.794 FINE [http-nio-8080-exec-9] de.javakaffee.web.msm.LockingStrategy.lock Locked session AECC8FA528109C93B8EB987A4263A0DF 25-Jul-2018 06:18:49.795 FINE [http-nio-8080-exec-9] de.javakaffee.web.msm.LockingStrategy.releaseLock Releasing lock for session AECC8FA528109C93B8EB987A4263A0DF 25-Jul-2018 06:18:49.796 FINE [http-nio-8080-exec-9] de.javakaffee.web.msm.MemcachedSessionService.loadFromMemcached Session AECC8FA528109C93B8EB987A4263A0DF not found in memcached. 25-Jul-2018 06:18:49.796 FINE [http-nio-8080-exec-9] de.javakaffee.web.msm.MemcachedSessionService.createSession createSession invoked: null 25-Jul-2018 06:18:49.796 FINE [http-nio-8080-exec-9] de.javakaffee.web.msm.MemcachedSessionService.createSession Created new session with id 5C09973413BF56B9B9AD88D59F3FEBB6 25-Jul-2018 06:18:49.796 FINE [http-nio-8080-exec-9] de.javakaffee.web.msm.MemcachedBackupSessionManager.removeInternal remove invoked, removeFromMemcached: true, id: 5C09973413BF56B9B9AD88D59F3FEBB6 25-Jul-2018 06:18:49.796 FINE [http-nio-8080-exec-9] de.javakaffee.web.msm.MemcachedSessionService.deleteFromMemcached Deleting session from memcached: 5C09973413BF56B9B9AD88D59F3FEBB6 25-Jul-2018 06:18:49.797 INFO [http-nio-8080-exec-9] com.shiftworksolutions.platform.mercury.server.authentication.LoginServlet.doGet Forwarding to login page 25-Jul-2018 06:18:49.799 FINE [http-nio-8080-exec-9] de.javakaffee.web.msm.MemcachedSessionService.backupSession No session found in session map for 5C09973413BF56B9B9AD88D59F3FEBB6 25-Jul-2018 06:18:49.799 FINE [http-nio-8080-exec-9] de.javakaffee.web.msm.RequestTrackingHostValve.logDebugRequestSessionCookie Have request session cookie: domain=null, maxAge=-1, path=null, value=AECC8FA528109C93B8EB987A4263A0DF, version=0, secure=false 25-Jul-2018 06:18:49.799 FINE [http-nio-8080-exec-9] de.javakaffee.web.msm.RequestTrackingHostValve.logDebugResponseCookie Request finished, with Set-Cookie header: JSESSIONID=CD55CE158554EC690B99F9AC1BAD2402; Path=/; HttpOnly 25-Jul-2018 06:18:49.799 FINE [http-nio-8080-exec-9] de.javakaffee.web.msm.RequestTrackingHostValve.invoke <<<<<< Request finished: POST /Main/appRpc ==================

and then later when trying to read this session:

25-Jul-2018 06:18:57.395 FINE [http-nio-8080-exec-8] de.javakaffee.web.msm.RequestTrackingHostValve.invoke >>>>>> Request starting: POST /dispatch/RaReadAction (requestedSessionId CD55CE158554EC690B99F9AC1BAD2402) ================== 25-Jul-2018 06:18:57.395 WARNING [http-nio-8080-exec-8] com.gwtplatform.dispatch.rpc.server.AbstractDispatchServiceImpl.execute Action exception while executing com.shiftworksolutions.platform.mercury.shared.roster.admin.RaReadAction: Session has expired. Please reload the page to establish a new session.

..... lots of stack trace

25-Jul-2018 06:18:57.404 FINE [http-nio-8080-exec-8] de.javakaffee.web.msm.MemcachedSessionService.backupSession Session CD55CE158554EC690B99F9AC1BAD2402 is still used by another request, skipping backup and (optional) lock handling/release. 25-Jul-2018 06:18:57.405 FINE [http-nio-8080-exec-8] de.javakaffee.web.msm.RequestTrackingHostValve.logDebugRequestSessionCookie Have request session cookie: domain=null, maxAge=-1, path=null, value=CD55CE158554EC690B99F9AC1BAD2402, version=0, secure=false 25-Jul-2018 06:18:57.405 FINE [http-nio-8080-exec-8] de.javakaffee.web.msm.RequestTrackingHostValve.invoke <<<<<< Request finished: POST /dispatch/RaReadAction ==================

cn-sws commented 6 years ago

sticky="true" and it all works. above testing was on a single server. going to start testing against multiple servers behind AWS application load balancer. ELB will have no stickiness turned on so sessions can go from server to server.