Runtime exception on a simple/test setup.

[Ivan Latysh]

Test setup:
 2 memcached nodes with default configs on 2 separate servers.
 2 tomcat running on a single server on different ports (non-sticky sessions)

To simplify the set-up only 1 Tomcat is running and using a standard examples app that comes with Tomcat (/examples/servlets/servlet/SessionExample).

When I try to add a session parameter 'test' I am getting runtime exceptions in the catalina logs. And the same exception is thrown for every attempt to set a session parameter.

Any idea of what am I doing wrong ?

[tomcat]
Using CATALINA_BASE:   /usr/tomcat/t1
Using CATALINA_HOME:   /usr/tomcat/t1
Using CATALINA_TMPDIR: /usr/tomcat/t1/temp
Using JRE_HOME:        /usr/java/default
Using CLASSPATH:       /usr/tomcat/t1/bin/bootstrap.jar
Server version: Apache Tomcat/6.0.35
Server built:   Nov 28 2011 11:20:06
Server number:  6.0.35.0
OS Name:        Linux
OS Version:     2.6.18-308.1.1.el5
Architecture:   amd64
JVM Version:    1.6.0_23-b05
JVM Vendor:     Sun Microsystems Inc.
[/tomcat]

[tomcat/lib]
-rw-r--r-- 1 root root  135127 Apr  5 14:15 kryo1-1.05-all.jar
-rw-r--r-- 1 root root   56215 Apr 21  2011 kryo-serializers-0.9.jar
-rw-r--r-- 1 root root  127689 Jan 25 16:33 memcached-session-manager-1.6.1.jar
-rw-r--r-- 1 root root   11474 Jan 25 16:33 memcached-session-manager-tc6-1.6.1.jar
-rw-r--r-- 1 root root   23491 Jan 25 16:32 msm-kryo-serializer-1.6.1.jar
-rw-r--r-- 1 root root  389693 Mar 22 00:15 spymemcached-2.8.1.jar
[/tomcat/lib]

[context.xml]
<Context>
    <WatchedResource>WEB-INF/web.xml</WatchedResource>

    <Manager className="de.javakaffee.web.msm.MemcachedBackupSessionManager"
       memcachedNodes="n1:memcached1:11211,n2:memcached2:11211"
       sticky="false"
       sessionBackupAsync="false"
       lockingMode="auto"
       requestUriIgnorePattern=".*\.(ico|png|gif|jpg|css|js)$"
       transcoderFactoryClass="de.javakaffee.web.msm.serializer.kryo.KryoTranscoderFactory"/>
</Context>
[/context.xml]

[catalina.out]
Jun 27, 2012 11:47:09 AM org.apache.catalina.core.AprLifecycleListener init
INFO: The APR based Apache Tomcat Native library which allows optimal performance in production environments was not found on the java.library.path: /usr/java/jdk1.6.0_23/jre/lib/amd64/server:/usr/java/jdk1.6.0_23/jre/lib/amd64:/usr/java/jdk1.6.0_23/jre/../lib/amd64:/usr/java/packages/lib/amd64:/usr/lib64:/lib64:/lib:/usr/lib
Jun 27, 2012 11:47:09 AM org.apache.coyote.http11.Http11Protocol init
INFO: Initializing Coyote HTTP/1.1 on http-8081
Jun 27, 2012 11:47:09 AM org.apache.catalina.startup.Catalina load
INFO: Initialization processed in 404 ms
Jun 27, 2012 11:47:09 AM org.apache.catalina.core.StandardService start
INFO: Starting service Catalina
Jun 27, 2012 11:47:09 AM org.apache.catalina.core.StandardEngine start
INFO: Starting Servlet Engine: Apache Tomcat/6.0.35
Jun 27, 2012 11:47:09 AM org.apache.catalina.startup.HostConfig deployDirectory
INFO: Deploying web application directory examples
Jun 27, 2012 11:47:09 AM de.javakaffee.web.msm.MemcachedSessionService startInternal
INFO: MemcachedSessionService starts initialization... (configured nodes definition n1:memcached1:11211,n2:memcached2:11211, failover nodes null)
2012-06-27 11:47:09.874 INFO net.spy.memcached.MemcachedConnection:  Added {QA sa=memcached1/10.2.148.30:11211, #Rops=0, #Wops=0, #iq=0, topRop=null, topWop=null, toWrite=0, interested=0} to connect queue
2012-06-27 11:47:09.876 INFO net.spy.memcached.MemcachedConnection:  Added {QA sa=memcached2/10.2.148.31:11211, #Rops=0, #Wops=0, #iq=0, topRop=null, topWop=null, toWrite=0, interested=0} to connect queue
2012-06-27 11:47:09.877 INFO net.spy.memcached.MemcachedConnection:  Connection state changed for sun.nio.ch.SelectionKeyImpl@51d8d39f
Jun 27, 2012 11:47:09 AM de.javakaffee.web.msm.SessionTrackerValve <init>
INFO: Setting ignorePattern to .*\.(ico|png|gif|jpg|css|js)$
2012-06-27 11:47:09.878 INFO net.spy.memcached.MemcachedConnection:  Connection state changed for sun.nio.ch.SelectionKeyImpl@722d95b3
Jun 27, 2012 11:47:09 AM de.javakaffee.web.msm.SessionTrackerValveTC6 getSessionCookieName
FINE: Using session cookie name from context: JSESSIONID
Jun 27, 2012 11:47:09 AM de.javakaffee.web.msm.MemcachedSessionService setLockingMode
INFO: Setting lockingMode to AUTO
Jun 27, 2012 11:47:09 AM de.javakaffee.web.msm.MemcachedSessionService createTranscoderFactory
INFO: Creating transcoder factory de.javakaffee.web.msm.serializer.kryo.KryoTranscoderFactory
Jun 27, 2012 11:47:09 AM de.javakaffee.web.msm.MemcachedSessionService loadTranscoderFactoryClass
FINE: Loading transcoder factory class de.javakaffee.web.msm.serializer.kryo.KryoTranscoderFactory using classloader WebappClassLoader
  context: /examples
  delegate: false
  repositories:
    /WEB-INF/classes/
----------> Parent Classloader:
org.apache.catalina.loader.StandardClassLoader@693a317a

Jun 27, 2012 11:47:09 AM de.javakaffee.web.msm.serializer.kryo.KryoTranscoder <init>
INFO: Starting with initialBufferSize 102400 and maxBufferSize 2048000
Jun 27, 2012 11:47:09 AM de.javakaffee.web.msm.MemcachedSessionService startInternal
INFO: MemcachedSessionService finished initialization, sticky false, operation timeout 1000, with node ids [n1, n2] and failover node ids []
Jun 27, 2012 11:47:09 AM org.apache.coyote.http11.Http11Protocol start
INFO: Starting Coyote HTTP/1.1 on http-8081
Jun 27, 2012 11:47:09 AM org.apache.jk.common.ChannelSocket init
INFO: JK: ajp13 listening on /0.0.0.0:8011
Jun 27, 2012 11:47:09 AM org.apache.jk.server.JkMain start
INFO: Jk running ID=0 time=0/12  config=null
Jun 27, 2012 11:47:10 AM org.apache.catalina.startup.Catalina start
INFO: Server startup in 462 ms
Jun 27, 2012 11:47:17 AM de.javakaffee.web.msm.SessionIdFormat createSessionId
FINE: Creating new session id with orig id 'ping' and memcached id 'n1'.
Jun 27, 2012 11:47:17 AM de.javakaffee.web.msm.NodeAvailabilityCache updateIsNodeAvailable
FINE: CacheLoader returned node availability 'true' for node 'n1'.
Jun 27, 2012 11:47:17 AM de.javakaffee.web.msm.MemcachedSessionService loadFromMemcached
FINE: Loading session from memcached: C24A2F163B8393827A325667A7BBD8AC-n1
Jun 27, 2012 11:47:17 AM de.javakaffee.web.msm.MemcachedSessionService loadFromMemcached
WARNING: Could not load session with id C24A2F163B8393827A325667A7BBD8AC-n1 from memcached.
java.lang.RuntimeException: There's no request set, this indicates that this findSessionwas triggered by the container which should already be handled in findSession.
    at de.javakaffee.web.msm.LockingStrategyAuto.onBeforeLoadFromMemcached(LockingStrategyAuto.java:119)
    at de.javakaffee.web.msm.MemcachedSessionService.loadFromMemcached(MemcachedSessionService.java:1008)
    at de.javakaffee.web.msm.MemcachedSessionService.findSession(MemcachedSessionService.java:578)
    at de.javakaffee.web.msm.MemcachedBackupSessionManager.findSession(MemcachedBackupSessionManager.java:215)
    at org.apache.catalina.connector.Request.doGetSession(Request.java:2419)
    at org.apache.catalina.connector.Request.getSessionInternal(Request.java:2343)
    at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:431)
    at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:127)
    at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:102)
    at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:109)
    at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:293)
    at org.apache.coyote.http11.Http11Processor.process(Http11Processor.java:859)
    at org.apache.coyote.http11.Http11Protocol$Http11ConnectionHandler.process(Http11Protocol.java:602)
    at org.apache.tomcat.util.net.JIoEndpoint$Worker.run(JIoEndpoint.java:489)
    at java.lang.Thread.run(Thread.java:662)
Jun 27, 2012 11:47:17 AM de.javakaffee.web.msm.SessionTrackerValve invoke
FINE: >>>>>> Request starting: /examples/servlets/servlet/SessionExample ==================
Jun 27, 2012 11:47:17 AM de.javakaffee.web.msm.MemcachedSessionService loadFromMemcached
FINE: Loading session from memcached: C24A2F163B8393827A325667A7BBD8AC-n1
Jun 27, 2012 11:47:17 AM de.javakaffee.web.msm.ReadOnlyRequestsCache isReadOnlyRequest
FINE: Asked for readonly request: /examples/servlets/servlet/SessionExample (false)
Jun 27, 2012 11:47:17 AM de.javakaffee.web.msm.LockingStrategy lock
FINE: Locking session C24A2F163B8393827A325667A7BBD8AC-n1
Jun 27, 2012 11:47:17 AM de.javakaffee.web.msm.LockingStrategy acquireLock
FINE: Locked session C24A2F163B8393827A325667A7BBD8AC-n1
Jun 27, 2012 11:47:17 AM de.javakaffee.web.msm.LockingStrategy lock
FINE: Locked session C24A2F163B8393827A325667A7BBD8AC-n1
Jun 27, 2012 11:47:17 AM de.javakaffee.web.msm.MemcachedSessionService loadFromMemcached
FINE: Found session with id C24A2F163B8393827A325667A7BBD8AC-n1
Jun 27, 2012 11:47:17 AM de.javakaffee.web.msm.BackupSessionService backupSession
FINE: Starting for session id C24A2F163B8393827A325667A7BBD8AC-n1
Jun 27, 2012 11:47:17 AM de.javakaffee.web.msm.BackupSessionTask call
FINE: Starting for session id C24A2F163B8393827A325667A7BBD8AC-n1
Jun 27, 2012 11:47:17 AM de.javakaffee.web.msm.BackupSessionTask call
FINE: Finished for session id C24A2F163B8393827A325667A7BBD8AC-n1, returning status SKIPPED
Jun 27, 2012 11:47:17 AM de.javakaffee.web.msm.BackupSessionTask releaseLock
FINE: Releasing lock for session C24A2F163B8393827A325667A7BBD8AC-n1
Jun 27, 2012 11:47:17 AM de.javakaffee.web.msm.LockingStrategy onAfterBackupSession
FINE: Stored session validity info for session C24A2F163B8393827A325667A7BBD8AC-n1
Jun 27, 2012 11:47:17 AM de.javakaffee.web.msm.ReadOnlyRequestsCache readOnlyRequest
FINE: Registering readonly request: /examples/servlets/servlet/SessionExample
Jun 27, 2012 11:47:17 AM de.javakaffee.web.msm.SessionTrackerValve logDebugRequestSessionCookie
FINE: Have request session cookie: domain=null, maxAge=-1, path=null, value=C24A2F163B8393827A325667A7BBD8AC-n1, version=0, secure=false
Jun 27, 2012 11:47:17 AM de.javakaffee.web.msm.LockingStrategy pingSession
FINE: Got ping result false
Jun 27, 2012 11:47:17 AM de.javakaffee.web.msm.LockingStrategy$OnAfterBackupSessionTask call
FINE: Storing backup in secondary memcached for non-sticky session C24A2F163B8393827A325667A7BBD8AC-n1
Jun 27, 2012 11:47:17 AM de.javakaffee.web.msm.SessionTrackerValve invoke
FINE: <<<<<< Request finished: /examples/servlets/servlet/SessionExample ==================
Jun 27, 2012 11:47:17 AM de.javakaffee.web.msm.SessionIdFormat createSessionId
FINE: Creating new session id with orig id 'ping' and memcached id 'n2'.
Jun 27, 2012 11:47:17 AM de.javakaffee.web.msm.NodeAvailabilityCache updateIsNodeAvailable
FINE: CacheLoader returned node availability 'true' for node 'n2'.
Jun 27, 2012 11:47:17 AM de.javakaffee.web.msm.LockingStrategy$OnAfterBackupSessionTask pingSessionBackup
FINE: Got backup ping result false
Jun 27, 2012 11:47:17 AM de.javakaffee.web.msm.SessionIdFormat createSessionId
FINE: Creating new session id with orig id 'ping' and memcached id 'n1'.
Jun 27, 2012 11:47:17 AM de.javakaffee.web.msm.NodeAvailabilityCache updateIsNodeAvailable
FINE: CacheLoader returned node availability 'true' for node 'n1'.
Jun 27, 2012 11:47:17 AM de.javakaffee.web.msm.MemcachedSessionService loadFromMemcached
FINE: Loading session from memcached: C24A2F163B8393827A325667A7BBD8AC-n1
Jun 27, 2012 11:47:17 AM de.javakaffee.web.msm.MemcachedSessionService loadFromMemcached
WARNING: Could not load session with id C24A2F163B8393827A325667A7BBD8AC-n1 from memcached.
java.lang.RuntimeException: There's no request set, this indicates that this findSessionwas triggered by the container which should already be handled in findSession.
    at de.javakaffee.web.msm.LockingStrategyAuto.onBeforeLoadFromMemcached(LockingStrategyAuto.java:119)
    at de.javakaffee.web.msm.MemcachedSessionService.loadFromMemcached(MemcachedSessionService.java:1008)
    at de.javakaffee.web.msm.MemcachedSessionService.findSession(MemcachedSessionService.java:578)
    at de.javakaffee.web.msm.MemcachedBackupSessionManager.findSession(MemcachedBackupSessionManager.java:215)
    at org.apache.catalina.connector.Request.doGetSession(Request.java:2419)
    at org.apache.catalina.connector.Request.getSessionInternal(Request.java:2343)
    at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:431)
    at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:127)
    at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:102)
    at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:109)
    at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:293)
    at org.apache.coyote.http11.Http11Processor.process(Http11Processor.java:859)
    at org.apache.coyote.http11.Http11Protocol$Http11ConnectionHandler.process(Http11Protocol.java:602)
    at org.apache.tomcat.util.net.JIoEndpoint$Worker.run(JIoEndpoint.java:489)
    at java.lang.Thread.run(Thread.java:662)
Jun 27, 2012 11:47:17 AM de.javakaffee.web.msm.MemcachedSessionService loadFromMemcached
FINE: Loading session from memcached: C24A2F163B8393827A325667A7BBD8AC-n1
Jun 27, 2012 11:47:17 AM de.javakaffee.web.msm.MemcachedSessionService loadFromMemcached
WARNING: Could not load session with id C24A2F163B8393827A325667A7BBD8AC-n1 from memcached.
java.lang.RuntimeException: There's no request set, this indicates that this findSessionwas triggered by the container which should already be handled in findSession.
    at de.javakaffee.web.msm.LockingStrategyAuto.onBeforeLoadFromMemcached(LockingStrategyAuto.java:119)
    at de.javakaffee.web.msm.MemcachedSessionService.loadFromMemcached(MemcachedSessionService.java:1008)
    at de.javakaffee.web.msm.MemcachedSessionService.findSession(MemcachedSessionService.java:578)
    at de.javakaffee.web.msm.MemcachedBackupSessionManager.findSession(MemcachedBackupSessionManager.java:215)
    at org.apache.catalina.connector.Request.doGetSession(Request.java:2419)
    at org.apache.catalina.connector.Request.getSessionInternal(Request.java:2343)
    at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:431)
    at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:127)
    at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:102)
    at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:109)
    at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:293)
    at org.apache.coyote.http11.Http11Processor.process(Http11Processor.java:859)
    at org.apache.coyote.http11.Http11Protocol$Http11ConnectionHandler.process(Http11Protocol.java:602)
    at org.apache.tomcat.util.net.JIoEndpoint$Worker.run(JIoEndpoint.java:489)
    at java.lang.Thread.run(Thread.java:662)
[/catalina.out]

[Martin Grotzke]

Hi Ivan,

I've never played/tested with the tomcat examples obviously, but that's
a great idea! :-)

Not sure what's going on there, I had to take a deeper look at the
examples code.

Can you try the attached jars and see if it works with them? It should.

Another option would be to change lockingMode "auto" to "none", although
this is obviously only a workaround.

Not related to this issue, but relevant if you're serializing stuff from
the webapp (WEB-INF/{classes,lib}: msm-kryo-serializer and kryo jars
should reside in the webapps WEB-INF/lib.

Cheers,
Martin

--
inoio gmbh - http://inoio.de
Breitenfelder Str. 13c, 20251 Hamburg
Amtsgericht Hamburg, HRB 123031
Geschäftsführer: Dennis Brakhane, Martin Grotzke, Ole Langbehn

[Ivan Latysh]

On 27/06/2012 2:39 PM, Martin Grotzke wrote:

> I've never played/tested with the tomcat examples obviously, but that's
> a great idea! :-)
>
> Not sure what's going on there, I had to take a deeper look at the
> examples code.
>
> Can you try the attached jars and see if it works with them? It should.

You are 100% correct, attached jars has fixed the issue!

Also want to say Thank You for such fast response. I have a few open source projects on my own, and know how hard is to
provide immediate feedback.

--
Ivan Latysh
IvanL...@gmail.com

[Martin Grotzke]

On 06/27/2012 09:34 PM, Ivan Latysh wrote:
> On 27/06/2012 2:39 PM, Martin Grotzke wrote:
>
>> I've never played/tested with the tomcat examples obviously, but that's
>> a great idea! :-)
>>
>> Not sure what's going on there, I had to take a deeper look at the
>> examples code.
>>
>> Can you try the attached jars and see if it works with them? It should.
> You are 100% correct, attached jars has fixed the issue!

Great, I'll release the current version of msm as soon as possible.

>
> Also want to say Thank You for such fast response. I have a few open
> source projects on my own, and know how hard is to provide immediate
> feedback.

Thanx, you're welcome! :-)

Cheers,
Martin