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
760 stars 346 forks source link

Couldn't recover session from backup node with non-sticky mode #403

Open Pablo-CC opened 5 years ago

Pablo-CC commented 5 years ago

This is my scenario:

tomcat 8 memcached 1.4.15 memcached-session-manager 2.3.0 spymemcached 2.9.1

Manager configuration in both Tomcats:

<Manager className="de.javakaffee.web.msm.MemcachedBackupSessionManager" lockingMode="auto" memcachedNodes="n1:host1_ip:11211,n2:host2_ip:1211" sticky="false" />

host1 hosts tomcat server1 and n1 host2 hostst tomcat server2 and n2

These are the steps I reproduce and what I see in memcached:

1.-wget --user=user --password=pass server1/some_path

IN MEMCACHED NODE n1:

<30 set validity:72E32CC53C53AB04F2A2AB19D82C351A-n1 0 1800 20 30 STORED <30 add lock:72E32CC53C53AB04F2A2AB19D82C351A-n1 0 5 6 30 STORED <30 set 72E32CC53C53AB04F2A2AB19D82C351A-n1 0 3600 571 30 STORED <30 get 72E32CC53C53AB04F2A2AB19D82C351A-n1 30 sending key 72E32CC53C53AB04F2A2AB19D82C351A-n1 30 END <30 get validity:72E32CC53C53AB04F2A2AB19D82C351A-n1 30 sending key validity:72E32CC53C53AB04F2A2AB19D82C351A-n1 30 END <30 set validity:72E32CC53C53AB04F2A2AB19D82C351A-n1 0 1800 20 30 STORED <30 delete lock:72E32CC53C53AB04F2A2AB19D82C351A-n1 30 DELETED <30 add 72E32CC53C53AB04F2A2AB19D82C351A-n1 0 5 1 30 NOT_STORED

IN MEMCACHED NODE n2:

<30 set bak:72E32CC53C53AB04F2A2AB19D82C351A-n1 0 3600 571 30 STORED <30 set bak:validity:72E32CC53C53AB04F2A2AB19D82C351A-n1 0 1800 20 30 STORED <30 get ping-n2 30 END <30 add bak:72E32CC53C53AB04F2A2AB19D82C351A-n1 0 5 1 30 NOT_STORED <30 set bak:validity:72E32CC53C53AB04F2A2AB19D82C351A-n1 0 1800 20 30 STORED

2.-I kill memcached node n1 (pkill memcached) 3.- wget server2/some_path --header "Cookie: JSESSIONID=72E32CC53C53AB04F2A2AB19D82C351A-n1"

IN MEMCACHED NODE n2:

<30 get ping-n2 30 END <30 get bak:validity:72E32CC53C53AB04F2A2AB19D82C351A-n1 30 sending key bak:validity:72E32CC53C53AB04F2A2AB19D82C351A-n1 30 END <30 get bak:72E32CC53C53AB04F2A2AB19D82C351A-n1 30 sending key bak:72E32CC53C53AB04F2A2AB19D82C351A-n1 30 END <30 set validity:72E32CC53C53AB04F2A2AB19D82C351A-n2 0 1800 20 30 STORED <30 set 72E32CC53C53AB04F2A2AB19D82C351A-n2 0 3600 571 30 STORED

4.-401 Unauthorized response

What is funny is that from this moment I can restore the session if I manually modify cookie's suffix: 72E32CC53C53AB04F2A2AB19D82C351A-n2

Thank you for your time. I am quite a noob in this area so I would appreciate if you tried to keep it simple.

PS: I can seem to enable logging by following the instructions in project's wiki. Are they supposed to show up in catalina.out after restarting Tomcat instance? What should I see there?

Pablo-CC commented 5 years ago

Ok I think I have some logs that might be useful: The same steps are reproduces only that this time the cookie is JSESSIONID=53E4991C4D6894C03E38AD515EA77301-n1

2019-02-08 09:50:13.119 INFO net.spy.memcached.MemcachedConnection: Reconnecting due to exception on {QA sa=/172.28.128.7:11211, #Rops=1, #Wops=0, #iq=0, topRop=Cmd: get Keys: ping-n1Exp: 0, topWop=null, toWrite=0, interested=1} java.io.IOException: Disconnected unexpected, will reconnect. at net.spy.memcached.MemcachedConnection.handleReads(MemcachedConnection.java:552) at net.spy.memcached.MemcachedConnection.handleIO(MemcachedConnection.java:480) at net.spy.memcached.MemcachedConnection.handleIO(MemcachedConnection.java:261) at net.spy.memcached.MemcachedConnection.run(MemcachedConnection.java:964) 2019-02-08 09:50:13.119 WARN net.spy.memcached.MemcachedConnection: Closing, and reopening {QA sa=/172.28.128.7:11211, #Rops=1, #Wops=0, #iq=0, topRop=Cmd: get Keys: ping-n1Exp: 0, topWop=null, toWrite=0, interested=1}, attempt 0. 2019-02-08 09:50:13.119 WARN net.spy.memcached.protocol.ascii.AsciiMemcachedNodeImpl: Discarding partially completed op: Cmd: get Keys: ping-n1Exp: 0 Feb 08, 2019 9:50:13 AM de.javakaffee.web.msm.MemcachedSessionService changeSessionIdOnMemcachedFailover INFO: Session needs to be relocated as node n1 is not available, loading backup session for 53E4991C4D6894C03E38AD515EA77301-n1 2019-02-08 09:50:13.120 INFO net.spy.memcached.MemcachedConnection: Reconnecting due to exception on {QA sa=/172.28.128.8:11211, #Rops=1, #Wops=0, #iq=0, topRop=Cmd: get Keys: ping-n2Exp: 0, topWop=null, toWrite=0, interested=1} java.io.IOException: Disconnected unexpected, will reconnect. at net.spy.memcached.MemcachedConnection.handleReads(MemcachedConnection.java:552) at net.spy.memcached.MemcachedConnection.handleIO(MemcachedConnection.java:480) at net.spy.memcached.MemcachedConnection.handleIO(MemcachedConnection.java:261) at net.spy.memcached.MemcachedConnection.run(MemcachedConnection.java:964) 2019-02-08 09:50:13.121 WARN net.spy.memcached.MemcachedConnection: Closing, and reopening {QA sa=/172.28.128.8:11211, #Rops=1, #Wops=0, #iq=0, topRop=Cmd: get Keys: ping-n2Exp: 0, topWop=null, toWrite=0, interested=1}, attempt 0. 2019-02-08 09:50:13.121 WARN net.spy.memcached.protocol.ascii.AsciiMemcachedNodeImpl: Discarding partially completed op: Cmd: get Keys: ping-n2Exp: 0 Feb 08, 2019 9:50:13 AM de.javakaffee.web.msm.MemcachedSessionService loadBackupSession INFO: No next available node found for nodeId n1 2019-02-08 09:50:13.140 WARN net.spy.memcached.MemcachedConnection: handling node for operation is not set Feb 08, 2019 9:50:13 AM de.javakaffee.web.msm.LockingStrategy onBackupWithoutLoadedSession WARNING: An error when trying to load/update validity info. java.util.concurrent.CancellationException: Cancelled at net.spy.memcached.internal.OperationFuture.get(OperationFuture.java:170) at net.spy.memcached.internal.GetFuture.get(GetFuture.java:62) at net.spy.memcached.MemcachedClient.get(MemcachedClient.java:1125) at de.javakaffee.web.msm.storage.MemcachedStorageClient.get(MemcachedStorageClient.java:62) at de.javakaffee.web.msm.LockingStrategy.loadSessionValidityInfoForValidityKey(LockingStrategy.java:333) at de.javakaffee.web.msm.LockingStrategy.onBackupWithoutLoadedSession(LockingStrategy.java:231) at de.javakaffee.web.msm.LockingStrategyAuto.onBackupWithoutLoadedSession(LockingStrategyAuto.java:70) at de.javakaffee.web.msm.MemcachedSessionService.backupSession(MemcachedSessionService.java:1070) at de.javakaffee.web.msm.RequestTrackingHostValve.backupSession(RequestTrackingHostValve.java:232) at de.javakaffee.web.msm.RequestTrackingHostValve.invoke(RequestTrackingHostValve.java:161) at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:79) at org.apache.catalina.valves.AbstractAccessLogValve.invoke(AbstractAccessLogValve.java:620) at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:88) at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:502) at org.apache.coyote.http11.AbstractHttp11Processor.process(AbstractHttp11Processor.java:1104) at org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process(AbstractProtocol.java:684) at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1519) at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.run(NioEndpoint.java:1475) at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61) at java.lang.Thread.run(Thread.java:748) 2019-02-08 09:50:15.122 INFO net.spy.memcached.MemcachedConnection: Reconnecting {QA sa=/172.28.128.7:11211, #Rops=0, #Wops=0, #iq=0, topRop=null, topWop=null, toWrite=0, interested=0} 2019-02-08 09:50:15.123 INFO net.spy.memcached.MemcachedConnection: Reconnecting {QA sa=/172.28.128.8:11211, #Rops=0, #Wops=0, #iq=0, topRop=null, topWop=null, toWrite=0, interested=0} 2019-02-08 09:50:15.123 INFO net.spy.memcached.MemcachedConnection: Connection state changed for sun.nio.ch.SelectionKeyImpl@4fc63b44 2019-02-08 09:50:15.124 INFO net.spy.memcached.MemcachedConnection: Reconnecting due to failure to connect to {QA sa=/172.28.128.7:11211, #Rops=0, #Wops=0, #iq=0, topRop=null, topWop=null, toWrite=0, interested=0} java.net.ConnectException: Connection refused at sun.nio.ch.SocketChannelImpl.checkConnect(Native Method) at sun.nio.ch.SocketChannelImpl.finishConnect(SocketChannelImpl.java:717) at net.spy.memcached.MemcachedConnection.handleIO(MemcachedConnection.java:423) at net.spy.memcached.MemcachedConnection.handleIO(MemcachedConnection.java:261) at net.spy.memcached.MemcachedConnection.run(MemcachedConnection.java:964) 2019-02-08 09:50:15.125 WARN net.spy.memcached.MemcachedConnection: Closing, and reopening {QA sa=/172.28.128.7:11211, #Rops=0, #Wops=0, #iq=0, topRop=null, topWop=null, toWrite=0, interested=0}, attempt 1. 2019-02-08 09:50:15.125 INFO net.spy.memcached.MemcachedConnection: Connection state changed for sun.nio.ch.SelectionKeyImpl@7fca5141 2019-02-08 09:50:19.128 INFO net.spy.memcached.MemcachedConnection: Reconnecting {QA sa=/172.28.128.7:11211, #Rops=0, #Wops=0, #iq=0, topRop=null, topWop=null, toWrite=0, interested=0} 2019-02-08 09:50:19.129 INFO net.spy.memcached.MemcachedConnection: Connection state changed for sun.nio.ch.SelectionKeyImpl@323d9199 2019-02-08 09:50:19.130 INFO net.spy.memcached.MemcachedConnection: Reconnecting due to failure to connect to {QA sa=/172.28.128.7:11211, #Rops=0, #Wops=0, #iq=0, topRop=null, topWop=null, toWrite=0, interested=0} java.net.ConnectException: Connection refused at sun.nio.ch.SocketChannelImpl.checkConnect(Native Method) at sun.nio.ch.SocketChannelImpl.finishConnect(SocketChannelImpl.java:717) at net.spy.memcached.MemcachedConnection.handleIO(MemcachedConnection.java:423) at net.spy.memcached.MemcachedConnection.handleIO(MemcachedConnection.java:261) at net.spy.memcached.MemcachedConnection.run(MemcachedConnection.java:964) 2019-02-08 09:50:19.130 WARN net.spy.memcached.MemcachedConnection: Closing, and reopening {QA sa=/172.28.128.7:11211, #Rops=0, #Wops=0, #iq=0, topRop=null, topWop=null, toWrite=0, interested=0}, attempt 2. 2019-02-08 09:50:27.139 INFO net.spy.memcached.MemcachedConnection: Reconnecting {QA sa=/172.28.128.7:11211, #Rops=0, #Wops=0, #iq=0, topRop=null, topWop=null, toWrite=0, interested=0} 2019-02-08 09:50:27.140 INFO net.spy.memcached.MemcachedConnection: Connection state changed for sun.nio.ch.SelectionKeyImpl@61329002 2019-02-08 09:50:27.141 INFO net.spy.memcached.MemcachedConnection: Reconnecting due to failure to connect to {QA sa=/172.28.128.7:11211, #Rops=0, #Wops=0, #iq=0, topRop=null, topWop=null, toWrite=0, interested=0} java.net.ConnectException: Connection refused at sun.nio.ch.SocketChannelImpl.checkConnect(Native Method) at sun.nio.ch.SocketChannelImpl.finishConnect(SocketChannelImpl.java:717) at net.spy.memcached.MemcachedConnection.handleIO(MemcachedConnection.java:423) at net.spy.memcached.MemcachedConnection.handleIO(MemcachedConnection.java:261) 2019-02-08 09:50:27.141 WARN net.spy.memcached.MemcachedConnection: Closing, and reopening {QA sa=/172.28.128.7:11211, #Rops=0, #Wops=0, #iq=0, topRop=null, topWop=null, toWrite=0, interested=0}, attempt 3. 2019-02-08 09:50:43.158 INFO net.spy.memcached.MemcachedConnection: Reconnecting {QA sa=/172.28.128.7:11211, #Rops=0, #Wops=0, #iq=0, topRop=null, topWop=null, toWrite=0, interested=0} 2019-02-08 09:50:43.159 INFO net.spy.memcached.MemcachedConnection: Connection state changed for sun.nio.ch.SelectionKeyImpl@7e826fc3 2019-02-08 09:50:43.160 INFO net.spy.memcached.MemcachedConnection: Reconnecting due to failure to connect to {QA sa=/172.28.128.7:11211, #Rops=0, #Wops=0, #iq=0, topRop=null, topWop=null, toWrite=0, interested=0} java.net.ConnectException: Connection refused at sun.nio.ch.SocketChannelImpl.checkConnect(Native Method) at sun.nio.ch.SocketChannelImpl.finishConnect(SocketChannelImpl.java:717) at net.spy.memcached.MemcachedConnection.handleIO(MemcachedConnection.java:423) at net.spy.memcached.MemcachedConnection.handleIO(MemcachedConnection.java:261) at net.spy.memcached.MemcachedConnection.run(MemcachedConnection.java:964) 2019-02-08 09:50:43.160 WARN net.spy.memcached.MemcachedConnection: Closing, and reopening {QA sa=/172.28.128.7:11211, #Rops=0, #Wops=0, #iq=0, topRop=null, topWop=null, toWrite=0, interested=0}, attempt 4. 2019-02-08 09:51:13.173 INFO net.spy.memcached.MemcachedConnection: Reconnecting {QA sa=/172.28.128.7:11211, #Rops=0, #Wops=0, #iq=0, topRop=null, topWop=null, toWrite=0, interested=0} 2019-02-08 09:51:13.174 INFO net.spy.memcached.MemcachedConnection: Connection state changed for sun.nio.ch.SelectionKeyImpl@3bae9855 2019-02-08 09:51:13.174 INFO net.spy.memcached.MemcachedConnection: Reconnecting due to failure to connect to {QA sa=/172.28.128.7:11211, #Rops=0, #Wops=0, #iq=0, topRop=null, topWop=null, toWrite=0, interested=0} java.net.ConnectException: Connection refused at sun.nio.ch.SocketChannelImpl.checkConnect(Native Method) at sun.nio.ch.SocketChannelImpl.finishConnect(SocketChannelImpl.java:717) at net.spy.memcached.MemcachedConnection.handleIO(MemcachedConnection.java:423) at net.spy.memcached.MemcachedConnection.handleIO(MemcachedConnection.java:261) at net.spy.memcached.MemcachedConnection.run(MemcachedConnection.java:964) 2019-02-08 09:51:13.175 WARN net.spy.memcached.MemcachedConnection: Closing, and reopening {QA sa=/172.28.128.7:11211, #Rops=0, #Wops=0, #iq=0, topRop=null, topWop=null, toWrite=0, interested=0}, attempt 5.

RDiazR2 commented 5 years ago

Hello Pablo

Perhaps if you increase the log level, you can try to understand what is happening: https://github.com/magro/memcached-session-manager/wiki/SetupAndConfiguration#configure-logging

It seems connection is lost while session is relocated in node 2. It's a little bit strange because in your first information it seems the key are created in node 2 (72E32CC53C53AB04F2A2AB19D82C351A-n2). If everything works fine you should receive a "Set-cookie" headed with n2. So, your browser should use that new cookie in the further requests.

Raúl

Pablo-CC commented 5 years ago

Hello Pablo

Perhaps if you increase the log level, you can try to understand what is happening: https://github.com/magro/memcached-session-manager/wiki/SetupAndConfiguration#configure-logging

It seems connection is lost while session is relocated in node 2. It's a little bit strange because in your first information it seems the key are created in node 2 (72E32CC53C53AB04F2A2AB19D82C351A-n2). If everything works fine you should receive a "Set-cookie" headed with n2. So, your browser should use that new cookie in the further requests.

Raúl

That's exactly what happens, but I guess that means the session is restarted, right? What I want is that if the server fails in the middle of a download, another server can take over, recover the session (from the backup memcached node) and continue with the download from the point it was left.

RDiazR2 commented 5 years ago

If I don't understand it wrong, the session is not lost. Only the identifier is changed and browser or client is responsible of request using the new cookie.