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

CacheLoader returned node availability 'false' for node 'n1'. #376

Open davedennis opened 6 years ago

davedennis commented 6 years ago

Hi,

I've been playing around with this set up for a few days and have a problem with creating sessions and node availability being null it looks like. Just a little background it's a tomcat8 app running on two EC2 instances behind one LB. Using AWS memcache.

Error:

14-Mar-2018 18:03:39.395 FINE [http-nio-10.43.67.169-8080-exec-8] de.javakaffee.web.msm.RequestTrackingHostValve.invoke >>>>>> Request starting: GET /PublicGUI-SupportGUI/v1/login.xhtml (requestedSessionId 084A16D9D197B1A5F4CEFB2BD77E15E6) ==================
14-Mar-2018 18:03:39.395 FINE [http-nio-10.43.67.169-8080-exec-8] de.javakaffee.web.msm.MemcachedNodesManager.canHitMemcached The sessionId does not contain a nodeId so that the memcached node could not be identified.
14-Mar-2018 18:03:39.395 FINE [http-nio-10.43.67.169-8080-exec-8] de.javakaffee.web.msm.MemcachedNodesManager.canHitMemcached The sessionId does not contain a nodeId so that the memcached node could not be identified.
14-Mar-2018 18:03:39.396 FINE [http-nio-10.43.67.169-8080-exec-8] de.javakaffee.web.msm.MemcachedSessionService.createSession createSession invoked: null
14-Mar-2018 18:03:39.396 FINE [http-nio-10.43.67.169-8080-exec-8] de.javakaffee.web.msm.SessionIdFormat.createSessionId Creating new session id with orig id 'ping' and memcached id 'n1'.
14-Mar-2018 18:03:39.396 FINE [http-nio-10.43.67.169-8080-exec-8] de.javakaffee.web.msm.NodeAvailabilityCache.updateIsNodeAvailable CacheLoader returned node availability 'false' for node 'n1'.
14-Mar-2018 18:03:39.396 FINE [http-nio-10.43.67.169-8080-exec-8] de.javakaffee.web.msm.SessionIdFormat.createSessionId Creating new session id with orig id '791D9784D5A9DE011A30BA3957DCBD0B' and memcached id 'null'.
14-Mar-2018 18:03:39.396 FINE [http-nio-10.43.67.169-8080-exec-8] de.javakaffee.web.msm.MemcachedSessionService.createSession Created new session with id 791D9784D5A9DE011A30BA3957DCBD0B
14-Mar-2018 18:03:39.397 FINE [http-nio-10.43.67.169-8080-exec-8] de.javakaffee.web.msm.MemcachedNodesManager.canHitMemcached The sessionId does not contain a nodeId so that the memcached node could not be identified.
14-Mar-2018 18:03:39.407 FINE [http-nio-10.43.67.169-8080-exec-8] de.javakaffee.web.msm.BackupSessionService.backupSession Starting for session id 791D9784D5A9DE011A30BA3957DCBD0B
14-Mar-2018 18:03:39.407 FINE [http-nio-10.43.67.169-8080-exec-8] de.javakaffee.web.msm.BackupSessionService.backupSession Skipping backup for session id 791D9784D5A9DE011A30BA3957DCBD0B as the session id is not usable for memcached.
14-Mar-2018 18:03:39.407 FINE [http-nio-10.43.67.169-8080-exec-8] de.javakaffee.web.msm.RequestTrackingHostValve.logDebugRequestSessionCookie Have request session cookie: domain=null, maxAge=-1, path=null, value=084A16D9D197B1A5F4CEFB2BD77E15E6, version=0, secure=false
14-Mar-2018 18:03:39.407 FINE [http-nio-10.43.67.169-8080-exec-8] de.javakaffee.web.msm.RequestTrackingHostValve.logDebugResponseCookie Request finished, with Set-Cookie header: JSESSIONID=791D9784D5A9DE011A30BA3957DCBD0B; Path=/PublicGUI-SupportGUI/v1/; HttpOnly
14-Mar-2018 18:03:39.407 FINE [http-nio-10.43.67.169-8080-exec-8] de.javakaffee.web.msm.RequestTrackingHostValve.invoke <<<<<< Request finished: GET /PublicGUI-SupportGUI/v1/login.xhtml ==================
14-Mar-2018 18:03:40.611 FINE [http-nio-10.43.67.169-8080-exec-9] de.javakaffee.web.msm.RequestTrackingHostValve.invoke >>>>>> Request starting: GET /InternalService-TomcatContainerStatus/v1/services/appserverstatus (requestedSessionId null) ==================
14-Mar-2018 18:03:40.742 FINE [http-nio-10.43.67.169-8080-exec-9] de.javakaffee.web.msm.RequestTrackingHostValve.invoke <<<<<< Request finished: GET /InternalService-TomcatContainerStatus/v1/services/appserverstatus ==================
14-Mar-2018 18:03:40.879 FINE [http-nio-10.43.67.169-8080-exec-10] de.javakaffee.web.msm.RequestTrackingHostValve.invoke >>>>>> Request starting: GET /PublicGUI-SupportGUI/v1/login.xhtml (requestedSessionId 86AB32364781588C44F19A434B84732E) ==================
14-Mar-2018 18:03:40.879 FINE [http-nio-10.43.67.169-8080-exec-10] de.javakaffee.web.msm.MemcachedNodesManager.canHitMemcached The sessionId does not contain a nodeId so that the memcached node could not be identified.
14-Mar-2018 18:03:40.880 FINE [http-nio-10.43.67.169-8080-exec-10] de.javakaffee.web.msm.MemcachedNodesManager.canHitMemcached The sessionId does not contain a nodeId so that the memcached node could not be identified.
14-Mar-2018 18:03:40.880 FINE [http-nio-10.43.67.169-8080-exec-10] de.javakaffee.web.msm.MemcachedSessionService.createSession createSession invoked: null
14-Mar-2018 18:03:40.880 FINE [http-nio-10.43.67.169-8080-exec-10] de.javakaffee.web.msm.SessionIdFormat.createSessionId Creating new session id with orig id 'ping' and memcached id 'n1'.
14-Mar-2018 18:03:40.880 FINE [http-nio-10.43.67.169-8080-exec-10] de.javakaffee.web.msm.NodeAvailabilityCache.updateIsNodeAvailable CacheLoader returned node availability 'false' for node 'n1'.

Here is the config in my context.xml:

    <Manager className="de.javakaffee.web.msm.MemcachedBackupSessionManager"
        memcachedNodes="n1:memcache-one-node.drkx12.cfg.usw2.cache.amazonaws.com:11211"
             sticky="true"
             storageKeyPrefix="context"
             sessionBackupAsync="false"
             requestUriIgnorePattern=".*\.(ico|png|gif|jpg|css|js)$"
           />

Has this error been seen before?

I'll attach a longer error example. exampleerror.txt

davedennis commented 6 years ago

removing the n1: from my memcacheNodes seems to have fixed it. Any insight on why would be helpful.

UPDATE: I take that back. removing the n1 sends a request to both nodes and does not ping pong from each node. So it defeats the purpose.

magro commented 6 years ago

Great that this solved it. Unfortunately I cannot tell what was the problem with the node id. Surely it would require some analysis to understand the cause of the issues.

Cheers, Martin

davedennis notifications@github.com schrieb am Mi., 14. März 2018, 19:29:

removing the n1: from my memcacheNodes seems to have fixed it. Any insight on why would be helpful.

— You are receiving this because you are subscribed to this thread. Reply to this email directly, view it on GitHub https://github.com/magro/memcached-session-manager/issues/376#issuecomment-373128368, or mute the thread https://github.com/notifications/unsubscribe-auth/AAD7Hc1yjFt0K9Q3j2XtcU-ML5CJ2g0jks5teWGigaJpZM4Sq7HI .

magro commented 6 years ago

D'oh, the github emails did not contain the update. Can you share logs including the tomcat startup, and then for requests after having cleared cookies?

davedennis commented 6 years ago

@magro I'll post what I can. My startup logs are fairly large. Is this enough detail? I added some of the cookie logs at the end. catalina.txt catalina.txt

magro commented 6 years ago

You're using tomcat clustering, which might conflict with msm session management. Can you turn tomcat clustering off?

davedennis commented 6 years ago

@magro That's a good question. I didn't even realize I was. I'll have to look at the context and see. That's something that could donk it up? I'll have to look at another one of my context files and compare contrast. Ideally I would not want to take it out. But if they are not compatible I can try.

Update:

I took out -

and still see

14-Mar-2018 22:34:19.660 FINE [http-nio-10.43.67.169-8080-exec-4] de.javakaffee.web.msm.MemcachedNodesManager.canHitMemcached The sessionId does not contain a nodeId so that the memcached node could not be identified.
14-Mar-2018 22:34:19.661 FINE [http-nio-10.43.67.169-8080-exec-4] de.javakaffee.web.msm.MemcachedNodesManager.canHitMemcached The sessionId does not contain a nodeId so that the memcached node could not be identified.
14-Mar-2018 22:34:19.661 FINE [http-nio-10.43.67.169-8080-exec-4] de.javakaffee.web.msm.MemcachedNodesManager.canHitMemcached The sessionId does not contain a nodeId so that the memcached node could not be identified.
14-Mar-2018 22:34:19.661 FINE [http-nio-10.43.67.169-8080-exec-4] de.javakaffee.web.msm.MemcachedNodesManager.canHitMemcached The sessionId does not contain a nodeId so that the memcached node could not be identified.
14-Mar-2018 22:34:19.661 FINE [http-nio-10.43.67.169-8080-exec-4] de.javakaffee.web.msm.MemcachedNodesManager.canHitMemcached The sessionId does not contain a nodeId so that the memcached node could not be identified.
14-Mar-2018 22:34:19.661 FINE [http-nio-10.43.67.169-8080-exec-4] de.javakaffee.web.msm.MemcachedSessionService.createSession createSession invoked: null
14-Mar-2018 22:34:19.661 FINE [http-nio-10.43.67.169-8080-exec-4] de.javakaffee.web.msm.SessionIdFormat.createSessionId Creating new session id with orig id 'ping' and memcached id 'n1'.
14-Mar-2018 22:34:19.662 FINE [http-nio-10.43.67.169-8080-exec-4] de.javakaffee.web.msm.NodeAvailabilityCache.updateIsNodeAvailable CacheLoader returned node availability 'false' for node 'n1'.
14-Mar-2018 22:34:19.662 FINE [http-nio-10.43.67.169-8080-exec-4] de.javakaffee.web.msm.SessionIdFormat.createSessionId Creating new session id with orig id '2C57AE44DC0344C1C06E47AAC338BE5E' and memcached id 'null'.
14-Mar-2018 22:34:19.662 FINE [http-nio-10.43.67.169-8080-exec-4] de.javakaffee.web.msm.MemcachedSessionService.createSession Created new session with id 2C57AE44DC0344C1C06E47AAC338BE5E
14-Mar-2018 22:34:19.662 FINE [http-nio-10.43.67.169-8080-exec-4] de.javakaffee.web.msm.BackupSessionService.backupSession Starting for session id 2C57AE44DC0344C1C06E47AAC338BE5E
14-Mar-2018 22:34:19.662 FINE [http-nio-10.43.67.169-8080-exec-4] de.javakaffee.web.msm.BackupSessionService.backupSession Skipping backup for session id 2C57AE44DC0344C1C06E47AAC338BE5E as the session id is not usable for memcached.
14-Mar-2018 22:34:19.662 FINE [http-nio-10.43.67.169-8080-exec-4] de.javakaffee.web.msm.RequestTrackingHostValve.logDebugRequestSessionCookie Have request session cookie: domain=null, maxAge=-1, path=null, value=33A39E8CBCBF302EF70071446A3FD035, version=0, secure=false
14-Mar-2018 22:34:19.662 FINE [http-nio-10.43.67.169-8080-exec-4] de.javakaffee.web.msm.RequestTrackingHostValve.logDebugResponseCookie Request finished, with Set-Cookie header: JSESSIONID=2C57AE44DC0344C1C06E47AAC338BE5E; Path=/PublicGUI-SupportGUI/v1/; HttpOnly
14-Mar-2018 22:34:19.662 FINE [http-nio-10.43.67.169-8080-exec-4] de.javakaffee.web.msm.RequestTrackingHostValve.invoke <<<<<< Request finished: POST /PublicGUI-SupportGUI/v1/j_spring_security_check ==================
14-Mar-2018 22:34:19.940 FINE [http-nio-10.43.67.169-8080-exec-5] de.javakaffee.web.msm.RequestTrackingHostValve.invoke >>>>>> Request starting: GET /PublicGUI-SupportGUI/v1/login.xhtml (requestedSessionId 6D773989DEBCC63F2085AE8923FFFF5C) ==================
14-Mar-2018 22:34:19.940 FINE [http-nio-10.43.67.169-8080-exec-5] de.javakaffee.web.msm.MemcachedNodesManager.canHitMemcached The sessionId does not contain a nodeId so that the memcached node could not be identified.
14-Mar-2018 22:34:19.940 FINE [http-nio-10.43.67.169-8080-exec-5] de.javakaffee.web.msm.MemcachedNodesManager.canHitMemcached The sessionId does not contain a nodeId so that the memcached node could not be identified.
14-Mar-2018 22:34:19.940 FINE [http-nio-10.43.67.169-8080-exec-5] de.javakaffee.web.msm.MemcachedSessionService.createSession createSession invoked: null
14-Mar-2018 22:34:19.940 FINE [http-nio-10.43.67.169-8080-exec-5] de.javakaffee.web.msm.SessionIdFormat.createSessionId Creating new session id with orig id '1427D3AAFFDADC34283FF69A935EB7AB' and memcached id 'null'.
14-Mar-2018 22:34:19.941 FINE [http-nio-10.43.67.169-8080-exec-5] de.javakaffee.web.msm.MemcachedSessionService.createSession Created new session with id 1427D3AAFFDADC34283FF69A935EB7AB
14-Mar-2018 22:34:19.941 FINE [http-nio-10.43.67.169-8080-exec-5] de.javakaffee.web.msm.MemcachedNodesManager.canHitMemcached The sessionId does not contain a nodeId so that the memcached node could not be identified.
14-Mar-2018 22:34:19.947 FINE [http-nio-10.43.67.169-8080-exec-5] de.javakaffee.web.msm.BackupSessionService.backupSession Starting for session id 1427D3AAFFDADC34283FF69A935EB7AB
14-Mar-2018 22:34:19.947 FINE [http-nio-10.43.67.169-8080-exec-5] de.javakaffee.web.msm.BackupSessionService.backupSession Skipping backup for session id 1427D3AAFFDADC34283FF69A935EB7AB as the session id is not usable for memcached.
14-Mar-2018 22:34:19.947 FINE [http-nio-10.43.67.169-8080-exec-5] de.javakaffee.web.msm.RequestTrackingHostValve.logDebugRequestSessionCookie Have request session cookie: domain=null, maxAge=-1, path=null, value=6D773989DEBCC63F2085AE8923FFFF5C, version=0, secure=false
14-Mar-2018 22:34:19.947 FINE [http-nio-10.43.67.169-8080-exec-5] de.javakaffee.web.msm.RequestTrackingHostValve.logDebugResponseCookie Request finished, with Set-Cookie header: JSESSIONID=1427D3AAFFDADC34283FF69A935EB7AB; Path=/PublicGUI-SupportGUI/v1/; HttpOnly
14-Mar-2018 22:34:19.947 FINE [http-nio-10.43.67.169-8080-exec-5] de.javakaffee.web.msm.RequestTrackingHostValve.invoke <<<<<< Request finished: GET /PublicGUI-SupportGUI/v1/login.xhtml ==================
14-Mar-2018 22:34:22.735 FINE [http-nio-10.43.67.169-8080-exec-6] de.javakaffee.web.msm.RequestTrackingHostValve.invoke >>>>>> Request starting: GET /InternalService-TomcatContainerStatus/v1/services/appserverstatus (requestedSessionId null) ==================
14-Mar-2018 22:34:22.869 FINE [http-nio-10.43.67.169-8080-exec-6] de.javakaffee.web.msm.RequestTrackingHostValve.invoke <<<<<< Request finished: GET /InternalService-TomcatContainerStatus/v1/services/appserverstatus ==================
14-Mar-2018 22:34:25.891 FINE [ContainerBackgroundProcessor[StandardEngine[Catalina]]] de.javakaffee.web.msm.MemcachedSessionService.updateExpirationInMemcached Checking session B44BDBD2BA6B94323E6EB5E86869ECFC:
HajoV commented 6 years ago

Looks like issue 350.

Leave out the dash of your context (PublicGUI-SupportGUI) or use another storageKeyPrefix (eg. storageKeyPrefix="context" in your config).