xulunfan / memcached-session-manager

Automatically exported from code.google.com/p/memcached-session-manager
0 stars 0 forks source link

updateExpirationInMemcached prints negative memcachedExpirationTime #190

Closed GoogleCodeExporter closed 9 years ago

GoogleCodeExporter commented 9 years ago
What steps will reproduce the problem?
1.set the web.xml session-timeout to 5.
2.use sticky session
3.look the log.

What is the expected output? What do you see instead?
--------------------------------output-------------------------------------
2013-12-23 0:26:12 de.javakaffee.web.msm.MemcachedSessionService 
updateExpirationInMemcached
良好: Checking session 63F2661F123086C8D6EC9CF65F75C5D5-n2: 
- isValid: true
- isExpiring: false
- isBackupRunning: false
- isExpirationUpdateRunning: false
- wasAccessedSinceLastBackup: false
- memcachedExpirationTime: 298
2013-12-23 0:26:22 de.javakaffee.web.msm.MemcachedSessionService 
updateExpirationInMemcached
良好: Checking session 63F2661F123086C8D6EC9CF65F75C5D5-n2: 
- isValid: true
- isExpiring: false
- isBackupRunning: false
- isExpirationUpdateRunning: false
- wasAccessedSinceLastBackup: false
- memcachedExpirationTime: 288
2013-12-23 0:26:32 de.javakaffee.web.msm.MemcachedSessionService 
updateExpirationInMemcached
良好: Checking session 63F2661F123086C8D6EC9CF65F75C5D5-n2: 
- isValid: true
- isExpiring: false
- isBackupRunning: false
- isExpirationUpdateRunning: false
- wasAccessedSinceLastBackup: false
- memcachedExpirationTime: 278
2013-12-23 0:26:42 de.javakaffee.web.msm.MemcachedSessionService 
updateExpirationInMemcached
良好: Checking session 63F2661F123086C8D6EC9CF65F75C5D5-n2: 
- isValid: true
- isExpiring: false
- isBackupRunning: false
- isExpirationUpdateRunning: false
- wasAccessedSinceLastBackup: false
- memcachedExpirationTime: 268
2013-12-23 0:26:52 de.javakaffee.web.msm.MemcachedSessionService 
updateExpirationInMemcached
良好: Checking session 63F2661F123086C8D6EC9CF65F75C5D5-n2: 
- isValid: true
- isExpiring: false
- isBackupRunning: false
- isExpirationUpdateRunning: false
- wasAccessedSinceLastBackup: false
- memcachedExpirationTime: 258
2013-12-23 0:27:02 de.javakaffee.web.msm.MemcachedSessionService 
updateExpirationInMemcached
良好: Checking session 63F2661F123086C8D6EC9CF65F75C5D5-n2: 
- isValid: true
- isExpiring: false
- isBackupRunning: false
- isExpirationUpdateRunning: false
- wasAccessedSinceLastBackup: false
- memcachedExpirationTime: 248
2013-12-23 0:27:12 de.javakaffee.web.msm.MemcachedSessionService 
updateExpirationInMemcached
良好: Checking session 63F2661F123086C8D6EC9CF65F75C5D5-n2: 
- isValid: true
- isExpiring: false
- isBackupRunning: false
- isExpirationUpdateRunning: false
- wasAccessedSinceLastBackup: false
- memcachedExpirationTime: 238
2013-12-23 0:27:22 de.javakaffee.web.msm.MemcachedSessionService 
updateExpirationInMemcached
良好: Checking session 63F2661F123086C8D6EC9CF65F75C5D5-n2: 
- isValid: true
- isExpiring: false
- isBackupRunning: false
- isExpirationUpdateRunning: false
- wasAccessedSinceLastBackup: false
- memcachedExpirationTime: 228
2013-12-23 0:27:32 de.javakaffee.web.msm.MemcachedSessionService 
updateExpirationInMemcached
良好: Checking session 63F2661F123086C8D6EC9CF65F75C5D5-n2: 
- isValid: true
- isExpiring: false
- isBackupRunning: false
- isExpirationUpdateRunning: false
- wasAccessedSinceLastBackup: false
- memcachedExpirationTime: 218
2013-12-23 0:27:42 de.javakaffee.web.msm.MemcachedSessionService 
updateExpirationInMemcached
良好: Checking session 63F2661F123086C8D6EC9CF65F75C5D5-n2: 
- isValid: true
- isExpiring: false
- isBackupRunning: false
- isExpirationUpdateRunning: false
- wasAccessedSinceLastBackup: false
- memcachedExpirationTime: 208
2013-12-23 0:27:52 de.javakaffee.web.msm.MemcachedSessionService 
updateExpirationInMemcached
良好: Checking session 63F2661F123086C8D6EC9CF65F75C5D5-n2: 
- isValid: true
- isExpiring: false
- isBackupRunning: false
- isExpirationUpdateRunning: false
- wasAccessedSinceLastBackup: false
- memcachedExpirationTime: 198
2013-12-23 0:28:02 de.javakaffee.web.msm.MemcachedSessionService 
updateExpirationInMemcached
良好: Checking session 63F2661F123086C8D6EC9CF65F75C5D5-n2: 
- isValid: true
- isExpiring: false
- isBackupRunning: false
- isExpirationUpdateRunning: false
- wasAccessedSinceLastBackup: false
- memcachedExpirationTime: 188
2013-12-23 0:28:12 de.javakaffee.web.msm.MemcachedSessionService 
updateExpirationInMemcached
良好: Checking session 63F2661F123086C8D6EC9CF65F75C5D5-n2: 
- isValid: true
- isExpiring: false
- isBackupRunning: false
- isExpirationUpdateRunning: false
- wasAccessedSinceLastBackup: false
- memcachedExpirationTime: 178
2013-12-23 0:28:22 de.javakaffee.web.msm.MemcachedSessionService 
updateExpirationInMemcached
良好: Checking session 63F2661F123086C8D6EC9CF65F75C5D5-n2: 
- isValid: true
- isExpiring: false
- isBackupRunning: false
- isExpirationUpdateRunning: false
- wasAccessedSinceLastBackup: false
- memcachedExpirationTime: 167
2013-12-23 0:28:32 de.javakaffee.web.msm.MemcachedSessionService 
updateExpirationInMemcached
良好: Checking session 63F2661F123086C8D6EC9CF65F75C5D5-n2: 
- isValid: true
- isExpiring: false
- isBackupRunning: false
- isExpirationUpdateRunning: false
- wasAccessedSinceLastBackup: false
- memcachedExpirationTime: 157
2013-12-23 0:28:42 de.javakaffee.web.msm.MemcachedSessionService 
updateExpirationInMemcached
良好: Checking session 63F2661F123086C8D6EC9CF65F75C5D5-n2: 
- isValid: true
- isExpiring: false
- isBackupRunning: false
- isExpirationUpdateRunning: false
- wasAccessedSinceLastBackup: false
- memcachedExpirationTime: 147
2013-12-23 0:28:52 de.javakaffee.web.msm.MemcachedSessionService 
updateExpirationInMemcached
良好: Checking session 63F2661F123086C8D6EC9CF65F75C5D5-n2: 
- isValid: true
- isExpiring: false
- isBackupRunning: false
- isExpirationUpdateRunning: false
- wasAccessedSinceLastBackup: false
- memcachedExpirationTime: 137
2013-12-23 0:29:02 de.javakaffee.web.msm.MemcachedSessionService 
updateExpirationInMemcached
良好: Checking session 63F2661F123086C8D6EC9CF65F75C5D5-n2: 
- isValid: true
- isExpiring: false
- isBackupRunning: false
- isExpirationUpdateRunning: false
- wasAccessedSinceLastBackup: false
- memcachedExpirationTime: 127
2013-12-23 0:29:12 de.javakaffee.web.msm.MemcachedSessionService 
updateExpirationInMemcached
良好: Checking session 63F2661F123086C8D6EC9CF65F75C5D5-n2: 
- isValid: true
- isExpiring: false
- isBackupRunning: false
- isExpirationUpdateRunning: false
- wasAccessedSinceLastBackup: false
- memcachedExpirationTime: 117
2013-12-23 0:29:22 de.javakaffee.web.msm.MemcachedSessionService 
updateExpirationInMemcached
良好: Checking session 63F2661F123086C8D6EC9CF65F75C5D5-n2: 
- isValid: true
- isExpiring: false
- isBackupRunning: false
- isExpirationUpdateRunning: false
- wasAccessedSinceLastBackup: false
- memcachedExpirationTime: 107
2013-12-23 0:29:32 de.javakaffee.web.msm.MemcachedSessionService 
updateExpirationInMemcached
良好: Checking session 63F2661F123086C8D6EC9CF65F75C5D5-n2: 
- isValid: true
- isExpiring: false
- isBackupRunning: false
- isExpirationUpdateRunning: false
- wasAccessedSinceLastBackup: false
- memcachedExpirationTime: 97
2013-12-23 0:29:42 de.javakaffee.web.msm.MemcachedSessionService 
updateExpirationInMemcached
良好: Checking session 63F2661F123086C8D6EC9CF65F75C5D5-n2: 
- isValid: true
- isExpiring: false
- isBackupRunning: false
- isExpirationUpdateRunning: false
- wasAccessedSinceLastBackup: false
- memcachedExpirationTime: 87
2013-12-23 0:29:52 de.javakaffee.web.msm.MemcachedSessionService 
updateExpirationInMemcached
良好: Checking session 63F2661F123086C8D6EC9CF65F75C5D5-n2: 
- isValid: true
- isExpiring: false
- isBackupRunning: false
- isExpirationUpdateRunning: false
- wasAccessedSinceLastBackup: false
- memcachedExpirationTime: 77
2013-12-23 0:30:02 de.javakaffee.web.msm.MemcachedSessionService 
updateExpirationInMemcached
良好: Checking session 63F2661F123086C8D6EC9CF65F75C5D5-n2: 
- isValid: true
- isExpiring: false
- isBackupRunning: false
- isExpirationUpdateRunning: false
- wasAccessedSinceLastBackup: false
- memcachedExpirationTime: 67
2013-12-23 0:30:12 de.javakaffee.web.msm.MemcachedSessionService 
updateExpirationInMemcached
良好: Checking session 63F2661F123086C8D6EC9CF65F75C5D5-n2: 
- isValid: true
- isExpiring: false
- isBackupRunning: false
- isExpirationUpdateRunning: false
- wasAccessedSinceLastBackup: false
- memcachedExpirationTime: 57
2013-12-23 0:30:22 de.javakaffee.web.msm.MemcachedSessionService 
updateExpirationInMemcached
良好: Checking session 63F2661F123086C8D6EC9CF65F75C5D5-n2: 
- isValid: true
- isExpiring: false
- isBackupRunning: false
- isExpirationUpdateRunning: false
- wasAccessedSinceLastBackup: false
- memcachedExpirationTime: 47
2013-12-23 0:30:32 de.javakaffee.web.msm.MemcachedSessionService 
updateExpirationInMemcached
良好: Checking session 63F2661F123086C8D6EC9CF65F75C5D5-n2: 
- isValid: true
- isExpiring: false
- isBackupRunning: false
- isExpirationUpdateRunning: false
- wasAccessedSinceLastBackup: false
- memcachedExpirationTime: 37
2013-12-23 0:30:42 de.javakaffee.web.msm.MemcachedSessionService 
updateExpirationInMemcached
良好: Checking session 63F2661F123086C8D6EC9CF65F75C5D5-n2: 
- isValid: true
- isExpiring: false
- isBackupRunning: false
- isExpirationUpdateRunning: false
- wasAccessedSinceLastBackup: false
- memcachedExpirationTime: 27
2013-12-23 0:30:52 de.javakaffee.web.msm.MemcachedSessionService 
updateExpirationInMemcached
良好: Checking session 63F2661F123086C8D6EC9CF65F75C5D5-n2: 
- isValid: true
- isExpiring: false
- isBackupRunning: false
- isExpirationUpdateRunning: false
- wasAccessedSinceLastBackup: false
- memcachedExpirationTime: 17
2013-12-23 0:31:02 de.javakaffee.web.msm.MemcachedSessionService 
updateExpirationInMemcached
良好: Checking session 63F2661F123086C8D6EC9CF65F75C5D5-n2: 
- isValid: true
- isExpiring: false
- isBackupRunning: false
- isExpirationUpdateRunning: false
- wasAccessedSinceLastBackup: false
- memcachedExpirationTime: 7
2013-12-23 0:31:12 de.javakaffee.web.msm.MemcachedSessionService 
updateExpirationInMemcached
良好: Checking session 63F2661F123086C8D6EC9CF65F75C5D5-n2: 
- isValid: true
- isExpiring: false
- isBackupRunning: false
- isExpirationUpdateRunning: false
- wasAccessedSinceLastBackup: false
- memcachedExpirationTime: -3
2013-12-23 0:31:22 de.javakaffee.web.msm.MemcachedSessionService 
updateExpirationInMemcached
良好: Checking session 63F2661F123086C8D6EC9CF65F75C5D5-n2: 
- isValid: true
- isExpiring: false
- isBackupRunning: false
- isExpirationUpdateRunning: false
- wasAccessedSinceLastBackup: false
- memcachedExpirationTime: -13
2013-12-23 0:31:32 de.javakaffee.web.msm.MemcachedSessionService 
updateExpirationInMemcached
良好: Checking session 63F2661F123086C8D6EC9CF65F75C5D5-n2: 
- isValid: true
- isExpiring: false
- isBackupRunning: false
- isExpirationUpdateRunning: false
- wasAccessedSinceLastBackup: false
- memcachedExpirationTime: -23
2013-12-23 0:31:42 de.javakaffee.web.msm.MemcachedSessionService 
updateExpirationInMemcached
良好: Checking session 63F2661F123086C8D6EC9CF65F75C5D5-n2: 
- isValid: true
- isExpiring: false
- isBackupRunning: false
- isExpirationUpdateRunning: false
- wasAccessedSinceLastBackup: false
- memcachedExpirationTime: -33
sessionDestroyed:63F2661F123086C8D6EC9CF65F75C5D5-n2
2013-12-23 0:31:42 de.javakaffee.web.msm.MemcachedBackupSessionManager remove
良好: remove invoked, removeFromMemcached: true, id: 
63F2661F123086C8D6EC9CF65F75C5D5-n2
2013-12-23 0:31:42 de.javakaffee.web.msm.MemcachedSessionService 
deleteFromMemcached
良好: Deleting session from memcached: 63F2661F123086C8D6EC9CF65F75C5D5-n2
-----------------------------------output--------------------------------------
Why the memcachedExpirationTime is negative?In addition,the method 
MemcachedSessionService.updateExpirationInMemcached look like invoke 
abnormally.I can't understand the source code.

What version of the product are you using? On what operating system?

tomcat 6,msm 1.6.5  

I use ubuntu 10.04 os on a VMware,and install nginx and 3 memcached instances 
with port 11211,11212,11213.
I start 3 tomcat instances on my local machine with win7 os.

I am a Chinese,and my English is bad.Never mind that.anyone can help me ?

Original issue reported on code.google.com by 150349...@qq.com on 22 Dec 2013 at 5:17

GoogleCodeExporter commented 9 years ago
I agree that it seems weird that those negative times are logged. I need to 
check what's happening there. 

Besides this, do you experience unexpected behavior? 

Original comment by martin.grotzke on 22 Dec 2013 at 7:30

GoogleCodeExporter commented 9 years ago
This is my configuration in tomcat1.

<Manager className="de.javakaffee.web.msm.MemcachedBackupSessionManager"
    memcachedNodes="n1:192.168.1.110:11211,n2:192.168.1.110:11212,n3:192.168.1.110:11213"
    failoverNodes="n1"
    requestUriIgnorePattern=".*\.(ico|png|gif|jpg|css|js)$"
    transcoderFactoryClass="de.javakaffee.web.msm.serializer.kryo.KryoTranscoderFactory"
    />

This is my configuration in nginx.

user www-data;
worker_processes  1;

error_log  /var/log/nginx/error.log;
pid        /var/run/nginx.pid;

events {
    worker_connections  1024;
    # multi_accept on;
}

http {
    include       /etc/nginx/mime.types;

    access_log  /var/log/nginx/access.log;

    sendfile        on;
    #tcp_nopush     on;

    #keepalive_timeout  0;
    keepalive_timeout  65;
    tcp_nodelay        on;

    gzip  on;
    gzip_disable "MSIE [1-6]\.(?!.*SV1)";

    include /etc/nginx/conf.d/*.conf;
    include /etc/nginx/sites-enabled/*;

    log_format   main '$remote_addr - $remote_user [$time_local]  $status '
    '"$request" $body_bytes_sent "$http_referer" '
    '"$http_user_agent" "$http_x_forwarded_for"';

    upstream zxl_server {
       ip_hash;
       server 192.168.1.196:8000;
       server 192.168.1.196:8001;
       server 192.168.1.196:8002;
    }
    server {
       listen          80;
       server_name     192.168.1.110;
       access_log      /var/log/nginx/zxl.server.access.log main;

       location / {
          proxy_pass      http://zxl_server;
       }
    }
}

Besides this,I discover that the msm will be initialized one more times.The 
following is a log.
---------------------------------------output-----------------------------------
--
Using CATALINA_BASE:   "D:\AlreadyInstalled\apache-tomcat-1"
Using CATALINA_HOME:   "D:\AlreadyInstalled\apache-tomcat-1"
Using CATALINA_TMPDIR: "D:\AlreadyInstalled\apache-tomcat-1\temp"
Using JRE_HOME:        "C:\Program Files\Java\jdk1.6.0_23"
Using CLASSPATH:       "D:\AlreadyInstalled\apache-tomcat-1\bin\bootstrap.jar"
2013-12-23 0:25:40 org.apache.catalina.core.AprLifecycleListener init
信息: Loaded APR based Apache Tomcat Native library 1.1.27 using APR version 
1.4.6.
2013-12-23 0:25:40 org.apache.catalina.core.AprLifecycleListener init
信息: APR capabilities: IPv6 [true], sendfile [true], accept filters [false], 
random [true].
2013-12-23 0:25:41 org.apache.catalina.core.AprLifecycleListener initializeSSL
信息: OpenSSL successfully initialized with version OpenSSL 1.0.1d 5 Feb 2013
2013-12-23 0:25:41 org.apache.coyote.http11.Http11AprProtocol init
信息: Initializing Coyote HTTP/1.1 on http-8000
2013-12-23 0:25:41 org.apache.coyote.ajp.AjpAprProtocol init
信息: Initializing Coyote AJP/1.3 on ajp-9000
2013-12-23 0:25:41 org.apache.catalina.startup.Catalina load
信息: Initialization processed in 1310 ms
2013-12-23 0:25:41 org.apache.catalina.core.StandardService start
信息: Starting service Catalina
2013-12-23 0:25:41 org.apache.catalina.core.StandardEngine start
信息: Starting Servlet Engine: Apache Tomcat/6.0.37
2013-12-23 0:25:41 org.apache.catalina.startup.HostConfig deployDescriptor
信息: Deploying configuration descriptor host-manager.xml
2013-12-23 0:25:41 de.javakaffee.web.msm.MemcachedSessionService startInternal
信息: MemcachedSessionService starts initialization... (configured nodes 
definition 
n1:192.168.1.110:11211,n2:192.168.1.110:11212,n3:192.168.1.110:11213, failover 
nodes n1)
2013-12-23 00:25:41.973 INFO net.spy.memcached.MemcachedConnection:  Added {QA 
sa=/192.168.1.110:11211, #Rops=0, #Wops=0, #iq=0, topRop=null, topWop=null, 
toWrite=0, interested=0} to connect queue
2013-12-23 00:25:41.975 INFO net.spy.memcached.MemcachedConnection:  Added {QA 
sa=/192.168.1.110:11212, #Rops=0, #Wops=0, #iq=0, topRop=null, topWop=null, 
toWrite=0, interested=0} to connect queue
2013-12-23 00:25:41.976 INFO net.spy.memcached.MemcachedConnection:  Added {QA 
sa=/192.168.1.110:11213, #Rops=0, #Wops=0, #iq=0, topRop=null, topWop=null, 
toWrite=0, interested=0} to connect queue
2013-12-23 0:25:41 de.javakaffee.web.msm.MemcachedBackupSessionManager 
getSessionCookieName
良好: Using session cookie name from context: JSESSIONID
2013-12-23 00:25:41.983 INFO net.spy.memcached.MemcachedConnection:  Connection 
state changed for sun.nio.ch.SelectionKeyImpl@1742700
2013-12-23 0:25:41 de.javakaffee.web.msm.RequestTrackingHostValve <init>
信息: Setting ignorePattern to .*\.(ico|png|gif|jpg|css|js)$
2013-12-23 00:25:42.002 INFO net.spy.memcached.MemcachedConnection:  Connection 
state changed for sun.nio.ch.SelectionKeyImpl@9b42e6
2013-12-23 0:25:42 de.javakaffee.web.msm.MemcachedSessionService setLockingMode
信息: Setting lockingMode to null
2013-12-23 00:25:42.007 INFO net.spy.memcached.MemcachedConnection:  Connection 
state changed for sun.nio.ch.SelectionKeyImpl@14520eb
2013-12-23 0:25:42 de.javakaffee.web.msm.MemcachedSessionService 
createTranscoderFactory
信息: Creating transcoder factory 
de.javakaffee.web.msm.serializer.kryo.KryoTranscoderFactory
2013-12-23 0:25:42 de.javakaffee.web.msm.MemcachedSessionService 
loadTranscoderFactoryClass
良好: Loading transcoder factory class 
de.javakaffee.web.msm.serializer.kryo.KryoTranscoderFactory using classloader 
WebappClassLoader
  context: /host-manager
  delegate: false
  repositories:
----------> Parent Classloader:
org.apache.catalina.loader.StandardClassLoader@1eed786

2013-12-23 0:25:42 de.javakaffee.web.msm.serializer.kryo.KryoTranscoder <init>
信息: Starting with initialBufferSize 102400 and maxBufferSize 2048000
2013-12-23 0:25:42 de.javakaffee.web.msm.MemcachedSessionService startInternal
信息: MemcachedSessionService finished initialization, sticky true, operation 
timeout 1000, with node ids [n2, n3] and failover node ids [n1]
2013-12-23 0:25:42 org.apache.catalina.startup.HostConfig deployDescriptor
信息: Deploying configuration descriptor manager.xml
2013-12-23 0:25:42 de.javakaffee.web.msm.MemcachedSessionService startInternal
信息: MemcachedSessionService starts initialization... (configured nodes 
definition 
n1:192.168.1.110:11211,n2:192.168.1.110:11212,n3:192.168.1.110:11213, failover 
nodes n1)
2013-12-23 00:25:42.133 INFO net.spy.memcached.MemcachedConnection:  Added {QA 
sa=/192.168.1.110:11211, #Rops=0, #Wops=0, #iq=0, topRop=null, topWop=null, 
toWrite=0, interested=0} to connect queue
2013-12-23 00:25:42.134 INFO net.spy.memcached.MemcachedConnection:  Added {QA 
sa=/192.168.1.110:11212, #Rops=0, #Wops=0, #iq=0, topRop=null, topWop=null, 
toWrite=0, interested=0} to connect queue
2013-12-23 00:25:42.135 INFO net.spy.memcached.MemcachedConnection:  Added {QA 
sa=/192.168.1.110:11213, #Rops=0, #Wops=0, #iq=0, topRop=null, topWop=null, 
toWrite=0, interested=0} to connect queue
2013-12-23 0:25:42 de.javakaffee.web.msm.MemcachedBackupSessionManager 
getSessionCookieName
良好: Using session cookie name from context: JSESSIONID
2013-12-23 00:25:42.135 INFO net.spy.memcached.MemcachedConnection:  Connection 
state changed for sun.nio.ch.SelectionKeyImpl@b122a1
2013-12-23 0:25:42 de.javakaffee.web.msm.RequestTrackingHostValve <init>
信息: Setting ignorePattern to .*\.(ico|png|gif|jpg|css|js)$
2013-12-23 0:25:42 de.javakaffee.web.msm.MemcachedSessionService setLockingMode
信息: Setting lockingMode to null
2013-12-23 00:25:42.136 INFO net.spy.memcached.MemcachedConnection:  Connection 
state changed for sun.nio.ch.SelectionKeyImpl@1589e56
2013-12-23 0:25:42 de.javakaffee.web.msm.MemcachedSessionService 
createTranscoderFactory
信息: Creating transcoder factory 
de.javakaffee.web.msm.serializer.kryo.KryoTranscoderFactory
2013-12-23 0:25:42 de.javakaffee.web.msm.MemcachedSessionService 
loadTranscoderFactoryClass
良好: Loading transcoder factory class 
de.javakaffee.web.msm.serializer.kryo.KryoTranscoderFactory using classloader 
WebappClassLoader
  context: /manager
  delegate: false
  repositories:
----------> Parent Classloader:
org.apache.catalina.loader.StandardClassLoader@1eed786

2013-12-23 00:25:42.137 INFO net.spy.memcached.MemcachedConnection:  2013-12-23 
0:25:42 de.javakaffee.web.msm.serializer.kryo.KryoTranscoder <init>
信息: Starting with initialBufferSize 102400 and maxBufferSize 2048000
Connection state changed for sun.nio.ch.SelectionKeyImpl@1033a6f
2013-12-23 0:25:42 de.javakaffee.web.msm.MemcachedSessionService startInternal
信息: MemcachedSessionService finished initialization, sticky true, operation 
timeout 1000, with node ids [n2, n3] and failover node ids [n1]
2013-12-23 0:25:42 org.apache.catalina.startup.HostConfig deployWAR
信息: Deploying web application archive TestApache.war
2013-12-23 0:25:42 de.javakaffee.web.msm.MemcachedSessionService startInternal
信息: MemcachedSessionService starts initialization... (configured nodes 
definition 
n1:192.168.1.110:11211,n2:192.168.1.110:11212,n3:192.168.1.110:11213, failover 
nodes n1)
2013-12-23 00:25:42.188 INFO net.spy.memcached.MemcachedConnection:  Added {QA 
sa=/192.168.1.110:11211, #Rops=0, #Wops=0, #iq=0, topRop=null, topWop=null, 
toWrite=0, interested=0} to connect queue
2013-12-23 00:25:42.189 INFO net.spy.memcached.MemcachedConnection:  Added {QA 
sa=/192.168.1.110:11212, #Rops=0, #Wops=0, #iq=0, topRop=null, topWop=null, 
toWrite=0, interested=0} to connect queue
2013-12-23 00:25:42.190 INFO net.spy.memcached.MemcachedConnection:  Added {QA 
sa=/192.168.1.110:11213, #Rops=0, #Wops=0, #iq=0, topRop=null, topWop=null, 
toWrite=0, interested=0} to connect queue
2013-12-23 0:25:42 de.javakaffee.web.msm.MemcachedBackupSessionManager 
getSessionCookieName
良好: Using session cookie name from context: JSESSIONID
2013-12-23 00:25:42.191 INFO net.spy.memcached.MemcachedConnection:  Connection 
state changed for sun.nio.ch.SelectionKeyImpl@10b9279
2013-12-23 0:25:42 de.javakaffee.web.msm.RequestTrackingHostValve <init>
信息: Setting ignorePattern to .*\.(ico|png|gif|jpg|css|js)$
2013-12-23 0:25:42 de.javakaffee.web.msm.MemcachedSessionService setLockingMode
信息: Setting lockingMode to null
2013-12-23 00:25:42.193 INFO net.spy.memcached.MemcachedConnection:  Connection 
state changed for sun.nio.ch.SelectionKeyImpl@bd6a5f
2013-12-23 0:25:42 de.javakaffee.web.msm.MemcachedSessionService 
createTranscoderFactory
信息: Creating transcoder factory 
de.javakaffee.web.msm.serializer.kryo.KryoTranscoderFactory
2013-12-23 0:25:42 de.javakaffee.web.msm.MemcachedSessionService 
loadTranscoderFactoryClass
良好: Loading transcoder factory class 
de.javakaffee.web.msm.serializer.kryo.KryoTranscoderFactory using classloader 
WebappClassLoader
  context: /TestApache
  delegate: false
  repositories:
    /WEB-INF/classes/
----------> Parent Classloader:
org.apache.catalina.loader.StandardClassLoader@1eed786

2013-12-23 0:25:42 de.javakaffee.web.msm.serializer.kryo.KryoTranscoder <init>
信息: Starting with initialBufferSize 102400 and maxBufferSize 2048000
2013-12-23 0:25:42 de.javakaffee.web.msm.MemcachedSessionService startInternal
信息: MemcachedSessionService finished initialization, sticky true, operation 
timeout 1000, with node ids [n2, n3] and failover node ids [n1]
2013-12-23 00:25:42.196 INFO net.spy.memcached.MemcachedConnection:  Connection 
state changed for sun.nio.ch.SelectionKeyImpl@192a848
2013-12-23 0:25:42 org.apache.catalina.startup.HostConfig deployDirectory
信息: Deploying web application directory docs
2013-12-23 0:25:42 de.javakaffee.web.msm.MemcachedSessionService startInternal
信息: MemcachedSessionService starts initialization... (configured nodes 
definition 
n1:192.168.1.110:11211,n2:192.168.1.110:11212,n3:192.168.1.110:11213, failover 
nodes n1)
2013-12-23 00:25:42.226 INFO net.spy.memcached.MemcachedConnection:  Added {QA 
sa=/192.168.1.110:11211, #Rops=0, #Wops=0, #iq=0, topRop=null, topWop=null, 
toWrite=0, interested=0} to connect queue
2013-12-23 00:25:42.227 INFO net.spy.memcached.MemcachedConnection:  Added {QA 
sa=/192.168.1.110:11212, #Rops=0, #Wops=0, #iq=0, topRop=null, topWop=null, 
toWrite=0, interested=0} to connect queue
2013-12-23 00:25:42.228 INFO net.spy.memcached.MemcachedConnection:  Added {QA 
sa=/192.168.1.110:11213, #Rops=0, #Wops=0, #iq=0, topRop=null, topWop=null, 
toWrite=0, interested=0} to connect queue
2013-12-23 0:25:42 de.javakaffee.web.msm.MemcachedBackupSessionManager 
getSessionCookieName
良好: Using session cookie name from context: JSESSIONID
2013-12-23 00:25:42.228 INFO net.spy.memcached.MemcachedConnection:  Connection 
state changed for sun.nio.ch.SelectionKeyImpl@19eda2c
2013-12-23 0:25:42 de.javakaffee.web.msm.RequestTrackingHostValve <init>
信息: Setting ignorePattern to .*\.(ico|png|gif|jpg|css|js)$
2013-12-23 0:25:42 de.javakaffee.web.msm.MemcachedSessionService setLockingMode
信息: Setting lockingMode to null
2013-12-23 0:25:42 de.javakaffee.web.msm.MemcachedSessionService 
createTranscoderFactory
信息: Creating transcoder factory 
de.javakaffee.web.msm.serializer.kryo.KryoTranscoderFactory
2013-12-23 00:25:42.230 INFO2013-12-23 0:25:42 
de.javakaffee.web.msm.MemcachedSessionService loadTranscoderFactoryClass
良好: Loading transcoder factory class 
de.javakaffee.web.msm.serializer.kryo.KryoTranscoderFactory using classloader 
WebappClassLoader
  context: /docs
  delegate: false
  repositories:
----------> Parent Classloader:
org.apache.catalina.loader.StandardClassLoader@1eed786

 net.spy.memcached.MemcachedConnection:  Connection state changed for sun.nio.ch.SelectionKeyImpl@1cef4f7
2013-12-23 0:25:42 de.javakaffee.web.msm.serializer.kryo.KryoTranscoder <init>
信息: Starting with initialBufferSize 102400 and maxBufferSize 2048000
2013-12-23 00:25:42.231 INFO net.spy.memcached.MemcachedConnection:  Connection 
state changed for sun.nio.ch.SelectionKeyImpl@59a34
2013-12-23 0:25:42 de.javakaffee.web.msm.MemcachedSessionService startInternal
信息: MemcachedSessionService finished initialization, sticky true, operation 
timeout 1000, with node ids [n2, n3] and failover node ids [n1]
2013-12-23 0:25:42 org.apache.catalina.startup.HostConfig deployDirectory
信息: Deploying web application directory examples
2013-12-23 0:25:42 de.javakaffee.web.msm.MemcachedSessionService startInternal
信息: MemcachedSessionService starts initialization... (configured nodes 
definition 
n1:192.168.1.110:11211,n2:192.168.1.110:11212,n3:192.168.1.110:11213, failover 
nodes n1)
2013-12-23 00:25:42.343 INFO net.spy.memcached.MemcachedConnection:  Added {QA 
sa=/192.168.1.110:11211, #Rops=0, #Wops=0, #iq=0, topRop=null, topWop=null, 
toWrite=0, interested=0} to connect queue
2013-12-23 00:25:42.344 INFO net.spy.memcached.MemcachedConnection:  Added {QA 
sa=/192.168.1.110:11212, #Rops=0, #Wops=0, #iq=0, topRop=null, topWop=null, 
toWrite=0, interested=0} to connect queue
2013-12-23 00:25:42.344 INFO net.spy.memcached.MemcachedConnection:  Added {QA 
sa=/192.168.1.110:11213, #Rops=0, #Wops=0, #iq=0, topRop=null, topWop=null, 
toWrite=0, interested=0} to connect queue
2013-12-23 0:25:42 de.javakaffee.web.msm.MemcachedBackupSessionManager 
getSessionCookieName
良好: Using session cookie name from context: JSESSIONID
2013-12-23 0:25:42 de.javakaffee.web.msm.RequestTrackingHostValve <init>
信息: Setting ignorePattern to .*\.(ico|png|gif|jpg|css|js)$
2013-12-23 00:25:42.345 INFO net.spy.memcached.MemcachedConnection:  Connection 
state changed for sun.nio.ch.SelectionKeyImpl@18c74
2013-12-23 0:25:42 de.javakaffee.web.msm.MemcachedSessionService setLockingMode
信息: Setting lockingMode to null
2013-12-23 0:25:42 de.javakaffee.web.msm.MemcachedSessionService 
createTranscoderFactory
信息: Creating transcoder factory 
de.javakaffee.web.msm.serializer.kryo.KryoTranscoderFactory
2013-12-23 00:25:42.347 2013-12-23 0:25:42 
de.javakaffee.web.msm.MemcachedSessionService loadTranscoderFactoryClass
良好: 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@1eed786

INFO net.spy.memcached.MemcachedConnection:  Connection state changed for 
sun.nio.ch.SelectionKeyImpl@18c3679
2013-12-23 00:25:42.348 INFO net.spy.memcached.MemcachedConnection:  Connection 
state changed for sun.nio.ch.SelectionKeyImpl@4c47db
2013-12-23 0:25:42 de.javakaffee.web.msm.serializer.kryo.KryoTranscoder <init>
信息: Starting with initialBufferSize 102400 and maxBufferSize 2048000
2013-12-23 0:25:42 de.javakaffee.web.msm.MemcachedSessionService startInternal
信息: MemcachedSessionService finished initialization, sticky true, operation 
timeout 1000, with node ids [n2, n3] and failover node ids [n1]
2013-12-23 0:25:42 org.apache.catalina.startup.HostConfig deployDirectory
信息: Deploying web application directory ROOT
2013-12-23 0:25:42 de.javakaffee.web.msm.MemcachedSessionService startInternal
信息: MemcachedSessionService starts initialization... (configured nodes 
definition 
n1:192.168.1.110:11211,n2:192.168.1.110:11212,n3:192.168.1.110:11213, failover 
nodes n1)
2013-12-23 00:25:42.382 INFO net.spy.memcached.MemcachedConnection:  Added {QA 
sa=/192.168.1.110:11211, #Rops=0, #Wops=0, #iq=0, topRop=null, topWop=null, 
toWrite=0, interested=0} to connect queue
2013-12-23 00:25:42.383 INFO net.spy.memcached.MemcachedConnection:  Added {QA 
sa=/192.168.1.110:11212, #Rops=0, #Wops=0, #iq=0, topRop=null, topWop=null, 
toWrite=0, interested=0} to connect queue
2013-12-23 00:25:42.384 INFO net.spy.memcached.MemcachedConnection:  Added {QA 
sa=/192.168.1.110:11213, #Rops=0, #Wops=0, #iq=0, topRop=null, topWop=null, 
toWrite=0, interested=0} to connect queue
2013-12-23 0:25:42 de.javakaffee.web.msm.MemcachedBackupSessionManager 
getSessionCookieName
良好: Using session cookie name from context: JSESSIONID
2013-12-23 00:25:42.385 INFO net.spy.memcached.MemcachedConnection:  Connection 
state changed for sun.nio.ch.SelectionKeyImpl@21e554
2013-12-23 0:25:42 de.javakaffee.web.msm.RequestTrackingHostValve <init>
信息: Setting ignorePattern to .*\.(ico|png|gif|jpg|css|js)$
2013-12-23 00:25:42.386 2013-12-23 0:25:42 
de.javakaffee.web.msm.MemcachedSessionService setLockingMode
信息: Setting lockingMode to null
INFO net.spy.memcached.MemcachedConnection:  Connection state changed for 
sun.nio.ch.SelectionKeyImpl@19a029e
2013-12-23 0:25:42 de.javakaffee.web.msm.MemcachedSessionService 
createTranscoderFactory
信息: Creating transcoder factory 
de.javakaffee.web.msm.serializer.kryo.KryoTranscoderFactory
2013-12-23 0:25:42 de.javakaffee.web.msm.MemcachedSessionService 
loadTranscoderFactoryClass
良好: Loading transcoder factory class 
de.javakaffee.web.msm.serializer.kryo.KryoTranscoderFactory using classloader 
WebappClassLoader
  context: 
  delegate: false
  repositories:
----------> Parent Classloader:
org.apache.catalina.loader.StandardClassLoader@1eed786

2013-12-23 00:25:42.386 INFO net.spy.memcached.MemcachedConnection:  Connection 
state changed for sun.nio.ch.SelectionKeyImpl@15718f2
2013-12-23 0:25:42 de.javakaffee.web.msm.serializer.kryo.KryoTranscoder <init>
信息: Starting with initialBufferSize 102400 and maxBufferSize 2048000
2013-12-23 0:25:42 de.javakaffee.web.msm.MemcachedSessionService startInternal
信息: MemcachedSessionService finished initialization, sticky true, operation 
timeout 1000, with node ids [n2, n3] and failover node ids [n1]
2013-12-23 0:25:42 org.apache.coyote.http11.Http11AprProtocol start
信息: Starting Coyote HTTP/1.1 on http-8000
2013-12-23 0:25:42 org.apache.coyote.ajp.AjpAprProtocol start
信息: Starting Coyote AJP/1.3 on ajp-9000
2013-12-23 0:25:42 org.apache.catalina.startup.Catalina start
信息: Server startup in 771 ms
-----------------------------------------output---------------------------------
-
Why the msm is initialized more than one time?

In addition,the logs also look like abnormal when I send a request to one of 
the tomcat instances.The request also is handled more than one time.The 
following is a log.
-------------------------------------------output-------------------------------
-
2013-12-23 0:26:09 de.javakaffee.web.msm.RequestTrackingHostValve invoke
良好: >>>>>> Request starting: GET /TestApache/servlet/testServlet 
(requestedSessionId 57ECC0A95D81E7146D39980FBAC87B98-n3) ==================
2013-12-23 0:26:09 de.javakaffee.web.msm.RequestTrackingHostValve invoke
良好: >>>>>> Request starting: GET /TestApache/servlet/testServlet 
(requestedSessionId 57ECC0A95D81E7146D39980FBAC87B98-n3) ==================
####session第一次获取前
2013-12-23 0:26:09 de.javakaffee.web.msm.SessionIdFormat createSessionId
良好: Creating new session id with orig id 'ping' and memcached id 'n3'.
2013-12-23 0:26:09 de.javakaffee.web.msm.NodeAvailabilityCache 
updateIsNodeAvailable
良好: CacheLoader returned node availability 'true' for node 'n3'.
2013-12-23 0:26:09 de.javakaffee.web.msm.MemcachedSessionService 
loadFromMemcached
良好: Loading session from memcached: 57ECC0A95D81E7146D39980FBAC87B98-n3
2013-12-23 0:26:09 de.javakaffee.web.msm.MemcachedSessionService 
loadFromMemcached
良好: Session 57ECC0A95D81E7146D39980FBAC87B98-n3 not found in memcached.
####session第一次获取后:null
####session第二次获取前
2013-12-23 0:26:09 de.javakaffee.web.msm.MemcachedSessionService createSession
良好: createSession invoked: null
2013-12-23 0:26:09 de.javakaffee.web.msm.SessionIdFormat createSessionId
良好: Creating new session id with orig id 'ping' and memcached id 'n2'.
2013-12-23 0:26:09 de.javakaffee.web.msm.NodeAvailabilityCache 
updateIsNodeAvailable
良好: CacheLoader returned node availability 'true' for node 'n2'.
2013-12-23 0:26:09 de.javakaffee.web.msm.SessionIdFormat createSessionId
良好: Creating new session id with orig id '63F2661F123086C8D6EC9CF65F75C5D5' 
and memcached id 'n2'.
sessionCreated:63F2661F123086C8D6EC9CF65F75C5D5-n2
2013-12-23 0:26:09 de.javakaffee.web.msm.MemcachedSessionService createSession
良好: Created new session with id 63F2661F123086C8D6EC9CF65F75C5D5-n2
####session第二次获取后:org.apache.catalina.session.StandardSessionFacad
e@f07355
####username第一次获取前
####username第一次获取后:null
####username第一次设置前
attributeAdded:[name:username:zxl]
####username第一次设置后:null
2013-12-23 0:26:09 de.javakaffee.web.msm.MemcachedSessionService backupSession
良好: No session found in session map for 63F2661F123086C8D6EC9CF65F75C5D5-n2
2013-12-23 0:26:09 de.javakaffee.web.msm.RequestTrackingHostValve 
logDebugRequestSessionCookie
良好: Have request session cookie: domain=null, maxAge=-1, path=null, 
value=57ECC0A95D81E7146D39980FBAC87B98-n3, version=0, secure=false
2013-12-23 0:26:09 de.javakaffee.web.msm.RequestTrackingHostValve 
logDebugResponseCookie
良好: Request finished, with Set-Cookie header: 
JSESSIONID=63F2661F123086C8D6EC9CF65F75C5D5-n2; Path=/TestApache
2013-12-23 0:26:09 de.javakaffee.web.msm.RequestTrackingHostValve invoke
良好: <<<<<< Request finished: GET /TestApache/servlet/testServlet 
==================
2013-12-23 0:26:09 de.javakaffee.web.msm.BackupSessionService backupSession
良好: Starting for session id 63F2661F123086C8D6EC9CF65F75C5D5-n2
2013-12-23 0:26:09 de.javakaffee.web.msm.RequestTrackingHostValve 
logDebugRequestSessionCookie
良好: Have request session cookie: domain=null, maxAge=-1, path=null, 
value=57ECC0A95D81E7146D39980FBAC87B98-n3, version=0, secure=false
2013-12-23 0:26:09 de.javakaffee.web.msm.BackupSessionTask call
良好: Starting for session id 63F2661F123086C8D6EC9CF65F75C5D5-n2
2013-12-23 0:26:09 de.javakaffee.web.msm.RequestTrackingHostValve 
logDebugResponseCookie
良好: Request finished, with Set-Cookie header: 
JSESSIONID=63F2661F123086C8D6EC9CF65F75C5D5-n2; Path=/TestApache
2013-12-23 0:26:09 de.javakaffee.web.msm.RequestTrackingHostValve invoke
良好: <<<<<< Request finished: GET /TestApache/servlet/testServlet 
==================
2013-12-23 0:26:10 de.javakaffee.web.msm.BackupSessionTask doBackupSession
良好: Trying to store session in memcached: 
63F2661F123086C8D6EC9CF65F75C5D5-n2
2013-12-23 0:26:10 de.javakaffee.web.msm.BackupSessionTask call
良好: Finished for session id 63F2661F123086C8D6EC9CF65F75C5D5-n2, returning 
status SUCCESS
--------------------------------------output-----------------------------
I hope you can find your way to solve the problem.Thank you stand my poor 
English.

Original comment by 150349...@qq.com on 23 Dec 2013 at 5:12

GoogleCodeExporter commented 9 years ago
Perhaps the duplicate log output is just a logging issue and misleading. 

Do you experience unexpected behavior?

Original comment by martin.grotzke on 1 Jan 2014 at 11:41

GoogleCodeExporter commented 9 years ago
I want to make clear the principle of 'failoverNodes' by source code, but the 
repeated logs disrupted tracking process.
Now,I have 3 nodes,And this is the configuration of each node as follows.

<Context>
  <Manager className="de.javakaffee.web.msm.MemcachedBackupSessionManager"
    memcachedNodes="n1:10.100.10.21:11211,n2:10.100.10.22:11211,n3:10.100.10.23:11211"
    failoverNodes="n1"//In the node of IP 22 is n2 and In the node of IP 23 is n3
    requestUriIgnorePattern=".*\.(ico|png|gif|jpg|css|js)$"
    transcoderFactoryClass="de.javakaffee.web.msm.serializer.kryo.KryoTranscoderFactory"
    />
</Context>

I want to know that the session of node1 is a backup in which Memcache nodes, 
and what is strategy.I did not find the details in the project document.I need 
some help, thank you very much.

Original comment by 150349...@qq.com on 2 Jan 2014 at 5:10

GoogleCodeExporter commented 9 years ago
You've configured failoverNodes correctly.

I just updated the documentation (SetupAndConfiguration):

> This attribute must contain the ids of the memcached nodes that must only be 
used for session backup when none of the other memcached nodes are available. 
Therefore, you should list those memcached nodes, that are running on the same 
machine as this tomcat. E.g. if you have tomcat1 and memcached1 (n1) running on 
host1, and tomcat2 and memcached2 (n2) on host2, then you set n1 as failover 
node for tomcat1, so that tomcat1 does only store sessions in memcached1 if 
memcached2 is not available (for tomcat2 failoverNodes would be set to n2). 
With this setting host1 could completely crash and sessions from tomcat1 would 
still be available.

Is this description more clear now?

Original comment by martin.grotzke on 2 Jan 2014 at 8:28

GoogleCodeExporter commented 9 years ago
Your critical analysis helped me a great deal.But I still have some questions.
I did some testing before.In the above configuration, when 3 Tomcat and 3 
memcached instances were normal,the session of tomcat1 will backup in the 
memcached2,the session of tomcat2 will backup in the memcached3 and the session 
of tomcat3 will backup in the memcached1.
When I killed the tomcat1,the request arrived tomcat2.Because the session of 
tomcat1 was backup in the memcached2,the session will be acquired from 
memcached2 and stored in the tomcat2.Now,the session only be stored in the 
memcached2 and tomcat2.When the session is expired,the new session will be 
created in tomcat2 and stored in the memcached3.
This is normal?

Original comment by 150349...@qq.com on 2 Jan 2014 at 3:30

GoogleCodeExporter commented 9 years ago
Node selection for new sessions happens randomly, like 
pickRandomFrom(memcachedNodes.subtract(failoverNodes)).

If a session after a tomcat failover is stored in a memcached node that is 
configured as failoverNode this is an oversight and should be fixed. Can you 
please verify this and submit a separate issue if it's reproducible?

Original comment by martin.grotzke on 2 Jan 2014 at 7:02

GoogleCodeExporter commented 9 years ago
Now I have completely make clear the strategies for 'failoverNodes',and the 
problem about that session only be stored in the tomcat2 and memcached2 before 
can be reproduced, I will open a new separate issue.
Thanks to your help.But what about the negative memcachedExpirationTime?

Original comment by 150349...@qq.com on 3 Jan 2014 at 5:01

GoogleCodeExporter commented 9 years ago
Thanx for submitting the issue!

I just checked the negative memcachedExpirationTime, and it was caused by 
tomcats internal "processExpiresFrequency": tomcat doesn't expire() sessions as 
soon as they reached their timeout, but they're expired according to the 
configured processExpiresFrequency, which is 6 by default. Because tomcats 
background process runs every 10 seconds, and processExpiresFrequency is 6 by 
default, a session with timeout 5 minutes will be exipire'd 60 seconds after 
the session reached its timeout.
This lead to the negative memcachedExpirationTime.

I just changed the expiration time that is set for sessions in memcached to 
respect the offset caused by processExpiresFrequency so that msm should no 
longer print any negative memcachedExpirationTime.

Original comment by martin.grotzke on 3 Jan 2014 at 10:01

GoogleCodeExporter commented 9 years ago

Original comment by martin.grotzke on 3 Jan 2014 at 10:08

GoogleCodeExporter commented 9 years ago

Original comment by martin.grotzke on 2 Feb 2014 at 2:08