Non-sticky sessions not working

[Eric B]

I'm trying to setup Tomcat 6 to use MSM 1.4.1 on Redhat. Tomcat
starts up fine, but whenever the web app tries to find my session, I
get this output to catalina.out:
---------------------------------------------------------------------------
Apr 9, 2011 7:48:51 PM de.javakaffee.web.msm.LockingStrategy
onBackupWithoutLoadedSession
WARNING: Found no validity info for session id
9DFF4A4A98D2E02BBB4B3482503A808F-n1
---------------------------------------------------------------------------

Any idea what's wrong? I've added "de.javakaffee.level = DEBUG" to
the end of conf/logging.properties, but no debug information is being
logged by MSM. Anyone know how to enable debug logging for MSM?

Thank you in advance for your help. I've included my configuration
files below. Also, the application I'm using this with is Central
Authentication Service, https://wiki.jasig.org/display/CAS/Home.

Thanks,
Eric


MSM lines Tomcat startup process in catalina.out:
---------------------------------------------------------------------------
Apr 9, 2011 7:48:44 PM
de.javakaffee.web.msm.MemcachedBackupSessionManager startInternal
INFO: MemcachedBackupSessionManager starts initialization...
(configured nodes definition n1:server1.domain.name:11211
n2:server2.domain.name:11211, failover nodes null)
2011-04-09 19:48:44.649 INFO net.spy.memcached.MemcachedConnection:
Added {QA sa=server2.domain.name/1.2.3.4:11211, #Rops=0, #Wops=0,
#iq=0, topRop=null, topWop=null, toWrite=0, interested=0} to connect
queue
2011-04-09 19:48:44.650 INFO net.spy.memcached.MemcachedConnection:
Added {QA sa=server1.domain.name/1.2.3.4:11211, #Rops=0, #Wops=0,
#iq=0, topRop=null, topWop=null, toWrite=0, interested=0} to connect
queue
Apr 9, 2011 7:48:44 PM
de.javakaffee.web.msm.MemcachedBackupSessionManager setLockingMode
INFO: Setting lockingMode to AUTO
Apr 9, 2011 7:48:44 PM
de.javakaffee.web.msm.MemcachedBackupSessionManager
createTranscoderFactory
INFO: Creating transcoder factory
de.javakaffee.web.msm.JavaSerializationTranscoderFactory
Apr 9, 2011 7:48:44 PM
de.javakaffee.web.msm.MemcachedBackupSessionManager startInternal
INFO: MemcachedBackupSessionManager finished initialization, have node
ids [n1, n2] and failover node ids []
2011-04-09 19:48:44.918 INFO net.spy.memcached.MemcachedConnection:
Connection state changed for sun.nio.ch.SelectionKeyImpl@1f8a6890
2011-04-09 19:48:44.989 INFO net.spy.memcached.MemcachedConnection:
Connection state changed for sun.nio.ch.SelectionKeyImpl@201a503f
---------------------------------------------------------------------------


These jar files are in tomcat6's lib directory:
- memcached-2.5.jar
- memcached-session-manager-1.4.1.jar

I'm using the default conf/server.xml file (removed comments for
brevity):
---------------------------------------------------------------------------
<?xml version='1.0' encoding='utf-8'?>
<Server port="8005" shutdown="SHUTDOWN">
<Listener className="org.apache.catalina.core.AprLifecycleListener"
SSLEngine="on" />
<Listener className="org.apache.catalina.core.JasperListener" />
<Listener
className="org.apache.catalina.core.JreMemoryLeakPreventionListener" /
>
<Listener
className="org.apache.catalina.mbeans.ServerLifecycleListener" />
<Listener
className="org.apache.catalina.mbeans.GlobalResourcesLifecycleListener" /
>
<GlobalNamingResources>
<Resource name="UserDatabase" auth="Container"
type="org.apache.catalina.UserDatabase"
description="User database that can be updated and
saved"

factory="org.apache.catalina.users.MemoryUserDatabaseFactory"
pathname="conf/tomcat-users.xml" />
</GlobalNamingResources>
<Service name="Catalina">
<Connector port="8080" protocol="HTTP/1.1"
connectionTimeout="20000"
redirectPort="8443" />
<Connector port="8009" protocol="AJP/1.3" redirectPort="8443" />
<Engine name="Catalina" defaultHost="localhost">
<Realm className="org.apache.catalina.realm.UserDatabaseRealm"
resourceName="UserDatabase"/>
<Host name="localhost" appBase="webapps"
unpackWARs="true" autoDeploy="true"
xmlValidation="false" xmlNamespaceAware="false">
</Host>
</Engine>
</Service>
</Server>

Here's my web app's context file:
---------------------------------------------------------------------------
<?xml version="1.0" encoding="UTF-8"?>
<Context path="/sso" allowLinking="true" cookies="true">
<Manager
className="de.javakaffee.web.msm.MemcachedBackupSessionManager"
enabled="true"
memcachedNodes="n1:server1.domain.name:11211 n2:server2.domain.name:
11211"
sticky="false"
lockingMode="auto"
sessionBackupAsync="false"

transcoderFactoryClass="de.javakaffee.web.msm.JavaSerializationTranscoderFactory"
/>
</Context>
---------------------------------------------------------------------------

[Martin Grotzke]

Hi Eric,

(top posting as I'm writing from my mobile)

Verbose logging: try FINE instead of DEBUG. You can also checkout the msm sample webapp (https://github.com/magro/msm-sample-webapp/tree/simpleservlet simpleservlet branch, in runtime/tomcat1/conf) for comparison

Does it work with a single memcached only?

Does it work with lockingMode NONE?

Does it work without CAS?

Can you attach complete log output for two requests?

Can you run memcached with -vv and attach log output?

Cheers,
Martin

[Eric B]

Thanks for those pointers and questions. I'll get back to you with
information requested if the debugging log doesn't shed some light on
my problems.

Thanks,
Eric

On Apr 9, 11:45 pm, Martin Grotzke <martin.grot...@googlemail.com>
wrote:

> Hi Eric,
>
> (top posting as I'm writing from my mobile)
>
> Verbose logging: try FINE instead of DEBUG. You can also checkout the msm

> sample webapp (https://github.com/magro/msm-sample-webapp/tree/simpleservletsimplese...

[Eric B]

Martin,
Adding "de.javakaffee.level=FINE" to the end of the conf/
logging.properties file did the trick. I was able to see debug output
in catalina.out.

I switch my Apache connector from mod_proxy to mod_jk and MSM just
started working (at least in my Staging environment).

Thank you for responding to my question so quickly and making this
great addition to Tomcat.

Thanks,
Eric

[Martin Grotzke]

Hi Eric,

On 04/11/2011 02:09 AM, Eric B wrote:
> Martin,
> Adding "de.javakaffee.level=FINE" to the end of the conf/
> logging.properties file did the trick. I was able to see debug output
> in catalina.out.

Great. I just added a hint regarding this log configuration to
SetupAndConfiguration.

>
> I switch my Apache connector from mod_proxy to mod_jk and MSM just
> started working (at least in my Staging environment).

Wow, interesting! Do you know the reason? Didn't mod_proxy pass the
cookie correctly?

Btw, the new mod_jk is mod_proxy_ajp, you might also try this one.

>
> Thank you for responding to my question so quickly and making this
> great addition to Tomcat.

You're welcome! :-)

One thing I'd be interested in is how lockingMode AUTO works for you.
Non-sticky session mode (and lockingMode AUTO) is relatively new, also I
don't have an own production environment running this combination. So if
you could share your experiences this would be really great!

Cheers,
Martin

[Eric B]

We tried switching to our new CAS server group, with MSM, today and
had more of these errors. Enough that we had to revert back to the
old CAS server group.

---------------------------------------------------
Apr 14, 2011 11:58:32 AM de.javakaffee.web.msm.LockingStrategy

onBackupWithoutLoadedSession
WARNING: Found no validity info for session id

F61E9B70C68C4499FC0D584C738704BD-n6
---------------------------------------------------

My current context configuration is below. I took out the locking
attribute.
---------------------------------------------------
<Manager
className="de.javakaffee.web.msm.MemcachedBackupSessionManager"

memcachedNodes="n1:server1.domain.name:11211 n2:server2.domain.name:

11211 n3:server.domain.name:11211 n4:server.domain.name:11211
n5:server.domain.name:11211 n6:server.domain.name:11211
n7:server.domain.name:11211 n8:server.domain.name:11211"

transcoderFactoryClass="de.javakaffee.web.msm.JavaSerializationTranscoderFactory"
sticky="false"
/>
---------------------------------------------------

It seems that sessions are not being saved fast enough or are silently
failing to save in memcache. I'm going to have to switch to something
like http://blog.digital-morphosis.com/2010/08/tomcat-cluster-configuration-without.html
because of my deadline. If I have time, I'll provide more information
here to help get this working.

Thanks,
Eric

[Martin Grotzke]

Hi Eric,

did/can you try setting sessionBackupAsync="false"?

If you can just post tomcat logs and memcached output (when running with -vv) I can have a look.

Cheers,
Martin

[Martin Grotzke]

Hi Eric,

I checked the code again I found a potential reason for the missing
validity infos: The validity info was set at the end of the request via
the memcached client (spymemcached), but without waiting for the result.
As spymemcached maintains its own thread/queue for communication with
memcached, it might have happened that the servlet request/response
returns, but the validity info is not yet stored in memcached. So when
the next request for the session comes in very fast (perhaps due to a
redirect, ajax call etc.) the validity might not be found in memcached -
which results in the warning you're seeing.

The attached msm jar contains a fix for the validity info: it now
respects the sessionBackupAsync and sessionBackupTimeout settings. So,
if sessionBackupAsync="false" and sessionBackupTimeout="500", msm waits
(now also when storing the validity info) 500 millis.

Cheers,
Martin

--
Martin Grotzke
http://twitter.com/martin_grotzke

[Martin Grotzke]

On 04/15/2011 09:31 AM, Martin Grotzke wrote:
> The attached msm jar contains a fix for the validity info: it now
> respects the sessionBackupAsync and sessionBackupTimeout settings.

The code modification was missing a "!", so that the
sessionBackupTimeout was taken into account when sessionBackupAsync="true".

Attached is a jar with a fix, just for the case s.o. would be interested
in the fix.

Sorry and cheers,
Martin