Tomcat failover not working, how do I troubleshoot this

[Charles Richard]

Hi,

I am testing to get the Memcached session faillover working with 2 Tomcat instances both running Tomcat 6 (6.0.30) running on the same server.

The following configuration is setup on both Tomcats in the context.xml:

  <Manager className="de.javakaffee.web.msm.MemcachedBackupSessionManager"

    memcachedNodes="n1:172.23.1.136:11211,n2:172.23.1.137:11211"

    failoverNodes="n1"

    requestUriIgnorePattern=".*\.(ico|png|gif|jpg|css|js)$"

    />

I realize this config is not best practice but I only have one web server I can test this with for now so I'm just trying to make sure I can get it to work properly. This is a pre-test for a migration that is planned.

We use session stickyness so I'll check the cookie to tell me which tomcat worker I'm on (w4worker1, w4worker2) and I'll kill the tomcat instance I'm on and then instead of being able to continue to use the application I get sent to the login page. In this case, I was on w4worker1 and killed Tomcat w4worker1 hoping to get resolved to w4worker2

The following 3 jars were each copied in the Tomcat lib folder: memcached-session-manager-tc6-2.1.1.jar, memcached-session-manager-2.1.1.jar and spymemcached-2.11.1.jar

There are the last entries I see in the following logs:

Tomcat w4worker1:

Jun 6, 2017 10:05:36 AM de.javakaffee.web.msm.JavaSerializationTranscoder writeAttributes

FINE:   storing attribute 'session.appUserId' with value '11178'

Jun 6, 2017 10:05:36 AM de.javakaffee.web.msm.JavaSerializationTranscoder writeAttributes

FINE:   storing attribute 'session.appUser.loginURL' with value 'https://web04.tellthemfromme.com/login.htm'

Jun 6, 2017 10:05:36 AM de.javakaffee.web.msm.JavaSerializationTranscoder writeAttributes

FINE:   storing attribute 'ACEGI_SAVED_REQUEST_KEY' with value 'SavedRequest[https://web04.tellthemfromme.com/main.htm]'

Jun 6, 2017 10:05:36 AM de.javakaffee.web.msm.JavaSerializationTranscoder writeAttributes

FINE:   storing attribute 'javax.servlet.jsp.jstl.fmt.request.charset' with value 'ISO-8859-1'

Jun 6, 2017 10:05:36 AM de.javakaffee.web.msm.JavaSerializationTranscoder writeAttributes

FINE:   storing attribute 'ACEGI_SECURITY_LAST_USERNAME' with value 'charlesrich'

Jun 6, 2017 10:05:36 AM de.javakaffee.web.msm.BackupSessionTask call

FINE: Finished for session id 9F3C07D8038448D194E01D945E07D85E-n2.w4worker1, returning status SKIPPED

Jun 6, 2017 10:05:37 AM de.javakaffee.web.msm.MemcachedSessionService updateExpirationInMemcached

FINE: Checking session 9F3C07D8038448D194E01D945E07D85E-n2.w4worker1:

- isValid: true

- isExpiring: false

- isBackupRunning: false

- isExpirationUpdateRunning: false

- wasAccessedSinceLastBackup: true

- memcachedExpirationTime: 1772

Jun 6, 2017 10:05:37 AM de.javakaffee.web.msm.MemcachedSessionService updateExpirationInMemcached

FINE: Checking session 8A1A3FD76E84C5E060E96F088A7F61C0-n2.w4worker1:

- isValid: true

- isExpiring: false

- isBackupRunning: false

- isExpirationUpdateRunning: false

- wasAccessedSinceLastBackup: false

- memcachedExpirationTime: 1474

Jun 6, 2017 10:05:38 AM de.javakaffee.web.msm.RequestTrackingHostValve invoke

FINE: >>>>>> Ignoring: GET /assets/lang/en-au/css/default.css (requestedSessionId 9F3C07D8038448D194E01D945E07D85E-n2.w4worker1) ==================

Jun 6, 2017 10:05:38 AM de.javakaffee.web.msm.RequestTrackingHostValve invoke

FINE: <<<<<< Ignored: GET /assets/lang/en-au/css/default.css ==================

Jun 6, 2017 10:05:47 AM de.javakaffee.web.msm.MemcachedSessionService updateExpirationInMemcached

FINE: Checking session 9F3C07D8038448D194E01D945E07D85E-n2.w4worker1:

- isValid: true

- isExpiring: false

- isBackupRunning: false

- isExpirationUpdateRunning: false

- wasAccessedSinceLastBackup: true

- memcachedExpirationTime: 1762

Jun 6, 2017 10:05:47 AM de.javakaffee.web.msm.MemcachedSessionService updateExpirationInMemcached

FINE: Checking session 8A1A3FD76E84C5E060E96F088A7F61C0-n2.w4worker1:

- isValid: true

- isExpiring: false

- isBackupRunning: false

Tomcat w4worker2:

Jun 6, 2017 10:05:48 AM de.javakaffee.web.msm.RequestTrackingHostValve invoke

FINE: >>>>>> Request starting: GET / (requestedSessionId null) ==================

Jun 6, 2017 10:05:48 AM de.javakaffee.web.msm.MemcachedSessionService backupSession

FINE: No session found in session map for kqkIKdftAWWCW17tuBXt.w4worker2

Jun 6, 2017 10:05:48 AM de.javakaffee.web.msm.RequestTrackingHostValve logDebugResponseCookie

FINE: Request finished, with Set-Cookie header: JSESSIONID=kqkIKdftAWWCW17tuBXt.w4worker2; Path=/

Jun 6, 2017 10:05:48 AM de.javakaffee.web.msm.RequestTrackingHostValve invoke

FINE: <<<<<< Request finished: GET / ==================

Jun 6, 2017 10:06:07 AM de.javakaffee.web.msm.RequestTrackingHostValve invoke

FINE: >>>>>> Request starting: GET /searchViewUser.htm (requestedSessionId 9F3C07D8038448D194E01D945E07D85E-n2.w4worker1) ==================

Jun 6, 2017 10:06:07 AM de.javakaffee.web.msm.SessionIdFormat createSessionId

FINE: Creating new session id with orig id 'ping' and memcached id 'n2'.

Jun 6, 2017 10:06:07 AM de.javakaffee.web.msm.NodeAvailabilityCache updateIsNodeAvailable

FINE: CacheLoader returned node availability 'true' for node 'n2'.

Jun 6, 2017 10:06:07 AM de.javakaffee.web.msm.MemcachedSessionService loadFromMemcached

FINE: Loading session from memcached: 9F3C07D8038448D194E01D945E07D85E-n2.w4worker1

Jun 6, 2017 10:06:07 AM de.javakaffee.web.msm.JavaSerializationTranscoder deserializeAttributes

FINE:   loading attribute 'scopedTarget.userSession' with value 'com.thelearningbar.web.security.UserSession@7044fa1f'

Jun 6, 2017 10:06:07 AM de.javakaffee.web.msm.JavaSerializationTranscoder deserializeAttributes

Memcache N1 node:

slab class  39: chunk size    493552 perslab       2

slab class  40: chunk size    616944 perslab       1

slab class  41: chunk size    771184 perslab       1

slab class  42: chunk size   1048576 perslab       1

<26 server listening (auto-negotiate)

<27 server listening (auto-negotiate)

<28 send buffer was 124928, now 268435456

<29 send buffer was 124928, now 268435456

<28 server listening (udp)

<28 server listening (udp)

<28 server listening (udp)

<28 server listening (udp)

<29 server listening (udp)

<29 server listening (udp)

<29 server listening (udp)

<29 server listening (udp)

<30 new auto-negotiating client connection

<31 new auto-negotiating client connection

<32 new auto-negotiating client connection

<33 new auto-negotiating client connection

<34 new auto-negotiating client connection

<35 new auto-negotiating client connection

<36 new auto-negotiating client connection

<37 new auto-negotiating client connection

<38 new auto-negotiating client connection

<39 new auto-negotiating client connection

<40 new auto-negotiating client connection

<41 new auto-negotiating client connection

<42 new auto-negotiating client connection

<40 connection closed.

<41 connection closed.

<38 connection closed.

<39 connection closed.

<37 connection closed.

<42 connection closed.

<37 new auto-negotiating client connection

<38 new auto-negotiating client connection

<39 new auto-negotiating client connection

<40 new auto-negotiating client connection

<41 new auto-negotiating client connection

<42 new auto-negotiating client connection

<32 connection closed.

<35 connection closed.

<30 connection closed.

<34 connection closed.

<33 connection closed.

<36 connection closed.

<31 connection closed.

<30 new auto-negotiating client connection

<31 new auto-negotiating client connection

<32 new auto-negotiating client connection

<33 new auto-negotiating client connection

<34 new auto-negotiating client connection

<35 new auto-negotiating client connection

<36 new auto-negotiating client connection

<32 connection closed.

<33 connection closed.

<35 connection closed.

<36 connection closed.

<34 connection closed.

<31 connection closed.

<30 connection closed.

Memcache N2 node:

<31 set 9F3C07D8038448D194E01D945E07D85E-n2.w4worker1 0 1794 236

>31 STORED

<31 set 9F3C07D8038448D194E01D945E07D85E-n2.w4worker1 0 1794 2607

>31 STORED

<31 set 9F3C07D8038448D194E01D945E07D85E-n2.w4worker1 0 1794 2679

>31 STORED

<31 get ping-n2

>31 END

<31 set 9F3C07D8038448D194E01D945E07D85E-n2.w4worker1 0 1794 17463

>31 STORED

<31 set 9F3C07D8038448D194E01D945E07D85E-n2.w4worker1 0 1794 17512

>31 STORED

<31 get ping-n2

>31 END

<31 get ping-n2

>31 END

<31 get ping-n2

>31 END

<32 connection closed.

<35 connection closed.

<36 connection closed.

<33 connection closed.

<34 connection closed.

<31 connection closed.

<30 connection closed.

<37 get ping-n2

>37 END

<37 get 9F3C07D8038448D194E01D945E07D85E-n2.w4worker1

>37 sending key 9F3C07D8038448D194E01D945E07D85E-n2.w4worker1

>37 END

<37 delete 9F3C07D8038448D194E01D945E07D85E-n2.w4worker1

>37 DELETED

<37 set 9F3C07D8038448D194E01D945E07D85E-n2.w4worker2 0 1794 17510

>37 STORED

I can attach the actual log files if need be. Please let me know if I should attach them directly to this post or somewhere else if attaching the log files would be more useful.

I appreciate any hints on how to troubleshoot this.

Thanks,

Charles

[Martin Grotzke]

Hi Charles,

worker2 logs show the starting "requestedSessionId 9F3C07D8038448D194E01D945E07D85E-n2.w4worker1" which is fine. Were there more logs following the ones you shared? These would be especially interesting.
N2 logs also look good to me so far, no apparent issue there.

Cheers,
Martin

--

---
You received this message because you are subscribed to the Google Groups "memcached-session-manager" group.
To unsubscribe from this group and stop receiving emails from it, send an email to memcached-session-...@googlegroups.com.
For more options, visit https://groups.google.com/d/optout.

[Charles Richard]

Hi Martin,

I've reset the log files so they would be small enough so that it's hopefully not an issue just to attach them on here. Let me know if I missed anything.

My original session was FADAC67D9CB36F4B7E2634F24D76CBFA-n1.w4worker2 and then I killed w4worker2 .

After I logged into the application and was assigned to w4worker2, I tried to use PHPMemcachedAdmin to at least confirm the session was getting set in Memcached but I'm not sure I'm doing that properly. Should I be able to just go a "get FADAC67D9CB36F4B7E2634F24D76CBFA-n1.w4worker2"?

Thanks for your time!

Cheers,

Charles

[Charles Richard]

Actually, I got this to work wondering if my memcached cluster was not setup properly so I only used one memcached node in both my tomcat configs and the session faillover is now working.

If I understood properly, I was told by the consulting firm we're paying to help us migrate to AWS that the Memcache Elasticache service that we'll be pointing at will be a single point of failure for us so I think we'll only have one memcached node anyways. I realize having a single point of failure is never a good thing but for the time being, this is a risk we are willing to accept.

Thanks,

Charles

[Billy Bacon]

Hi Charles,

Unless you are trying to save on costs, you don't have to have a single point of failure with ElastiCache. You can tell ElastiCache to spin up 2 or more nodes and the cluster will give you a single memcached endpoint which is the only thing you need to use for your application configuration. If a node goes down, it seamlessly fails over to the other node. The endpoint url will look something like xxxxx.xxxxx..cfg.use1.cache.amazonaws.com:11211. I'm not sure why the folks you are working with would tell you will have a single point of failure. Maybe they think that URL is a single point of failure if it vaporizes, which isn't likely.

Hope that helps.

- Bacon -

--

[Charles Richard]

Hi Billy,

You're right. I'm not really sure why the consulting firm told us what they did but I think it was just a misconception on their part about how memcached would be configured. Once I showed them the configuration, they seemed to indicate the same thing you are.

Thanks for the helpful information!

Cheers,

Charles

To unsubscribe from this group and stop receiving emails from it, send an email to memcached-session-manager+unsub...@googlegroups.com.