Sessions are failing in production server

[snedapunk]

Our production has a netscaler load balancer and 5 machines running the latest Jboss on linux, with sticky sessions. We currently have a major problem that I HAVE to solve. Users are getting logged out because of a random session problem. Example. Today I logged in, and the session is set with an account. When I clicked the next page, I was redirected to login. I tried again and the same thing happened. I then tried yet again, and it worked as expected. I checked jmx-console's to display all sessions and there was about 600 active sessions. Production does not have session debug on, but when I found my logout in the server log, I also found that 5 to 10 others were also logged out near the exact time. This is because each request checks the session for the account and if it is not found then you are redirected to the login page.
Every now and then I find 2006-02-22 14:52:56,298 WARN [org.jboss.cache.TreeCache] node /JSESSION/localhost/ui/LQCTn4CBqjur2VUjM5+BnA** not found, but very few and not comparable to logouts. Could anybody please give me any guidance to help us with our production servers? Our customers keep complaining about our service ?. Below is my SyncReplTimeout= 15000
IsolationLevel= REPEATABLE_READ
LockAcquisitionTimeout=15000
NumberOfLocksHeld=0
TransactionManagerLookupClass= TransactionManagerLookupClass
NumberOfAttributes = 764
REPLqUEUEmAXeLEMENTS=1000
ClusterProperties= UDP(ip_mcast=true;ip_ttl=8;loopback=false;mcast_addr=230.1.2.7;mcast_port=45599;mcast_recv_buf_size=80000;mcast_send_buf_size=150000;ucast_recv_buf_size=80000;ucast_send_buf_size=150000):PING(down_thread=false;num_initial_members=3;timeout=2000;up_thread=false):MERGE2(max_interval=20000;min_interval=10000):FD_SOCK:VERIFY_SUSPECT(down_thread=false;timeout=1500;up_thread=false):pbcast.NAKACK(down_thread=false;gc_lag=50;max_xmit_size=8192;retransmit_timeout=600,1200,2400,4800;up_thread=false):UNICAST(down_thread=false;min_threshold=10;timeout=600,1200,2400;window_size=100):pbcast.STABLE(desired_avg_gossip=20000;down_thread=false;up_thread=false):FRAG(down_thread=false;frag_size=8192;up_thread=false):pbcast.GMS(join_retry_timeout=2000;join_timeout=5000;print_local_addr=true;shun=true):pbcast.STATE_TRANSFER(down_thread=true;up_thread=true)
Version= JBossCache 1.2.3[ $Id: Version.java,v 1.3 2005/05/31 15:21:50 bela Exp $]

ReplQueueInterval= 5000
UseReplQueue=false (should this be true?)
TransactionManager= org.jboss.tm.TxManager@1973ebd
DeadlockDetection=false
Name=TreeCache
CacheLoaderFetchPersistentState = true
EvictionThreadWakeupIntervalSeconds=-1
Coordinator=false
Instance= org.jboss.cache.TreeCache [385 nodes, 0 locks]
ItitialStateRetrievalTimeout=5000
CachMode= REPL_ASYNC
NumberOfNodes=385
FetchStateOnStartup=true
SyncRollBackphase=false
StateString=started
CacheLoaderFetchTransientState=true
InterceptorChain= class org.jboss.cache.interceptors.CallInterceptor class org.jboss.cache.interceptors.LockInterceptor class org.jboss.cache.interceptors.UnlockInterceptor class org.jboss.cache.interceptors.ReplicationInterceptor
ClusterName= Tomcat-Cluster
SyncCommitPhase=false

[snedapunk]

Also when I get the warning not found, I refresh printdetails() to list all session ids. It is not found. Then i wait a about 10 to 20 secs and hit refresh and search for the not found and it is their again sometimes.

We also use the session for A LOT of stuff, when printing the data in the session it takes pages.

Any info would help. Thanks

[snedapunk]

I found a user logged into node3 and then in the next request he was logged out at node 1(within the same minute) Then he relogged in at node1 and stayed there no problems. He complains he got logged out. I also verified other cases where users log into one machine, load balancer switches macine on them and the session fails login.

Is this correct with Debug mode on? It seems it happens all the time.


[sender=asdf1-in:33295, retval=null, received=false, suspected=false]
[sender=asdf2-in:33228, retval=null, received=false, suspected=false]
[sender=asdf3-in:32849, retval=null, received=false, suspected=false]
[sender=asdf4-in:33771, retval=null, received=false, suspected=false]

[brian.stansberry]

With REPL_ASYNC those kinds of messages are normal.

[snedapunk]

Is this normal behavior with our setup? That a user would log into one machine, and then on a given request afterwards could be redirected to a new machine, when the original machine was not down?
I have one production machine in debug, and here is the log. At the end of this, the user fails security check for the given session id, so the session id is the same. Why is there a remove call?
Thread[http-0.0.0.0-8080-18,5,jboss]]
2006-02-24 12:31:33,362 DEBUG [org.jboss.cache.Node] acquiring WL: fqn=/JSESSION/localhost/ui/nPL1hi7Yl6gh6QXewnz35w**, caller=Thread[http-0.0.0.0-8080-18,5,jboss], lock=
2006-02-24 12:31:33,362 DEBUG [org.jboss.cache.Node] acquired WL: fqn=/JSESSION/localhost/ui/nPL1hi7Yl6gh6QXewnz35w**, caller=Thread[http-0.0.0.0-8080-18,5,jboss], lock=write owner=Thread[http-0.0.0.0-8080-18,5,jboss]
2006-02-24 12:31:33,362 DEBUG [org.jboss.cache.Node] acquiring WL: fqn=/JSESSION/localhost/ui/nPL1hi7Yl6gh6QXewnz35w**, caller=Thread[http-0.0.0.0-8080-18,5,jboss], lock=write owner=Thread[http-0.0.0.0-8080-18,5,jboss]
2006-02-24 12:31:33,362 DEBUG [org.jboss.cache.lock.IdentityLock] acquireWriteLock(): caller already owns lock for /JSESSION/localhost/ui/nPL1hi7Yl6gh6QXewnz35w** (caller=Thread[http-0.0.0.0-8080-18,5,jboss])
2006-02-24 12:31:33,362 DEBUG [org.jboss.cache.Node] acquired WL: fqn=/JSESSION/localhost/ui/nPL1hi7Yl6gh6QXewnz35w**, caller=Thread[http-0.0.0.0-8080-18,5,jboss], lock=write owner=Thread[http-0.0.0.0-8080-18,5,jboss]
2006-02-24 12:31:33,362 DEBUG [org.jboss.cache.TreeCache] _remove(null, "/JSESSION/localhost/ui/nPL1hi7Yl6gh6QXewnz35w**")
2006-02-24 12:31:33,362 DEBUG [org.jboss.cache.Node] removed child nPL1hi7Yl6gh6QXewnz35w**
2006-02-24 12:31:33,362 DEBUG [org.jboss.cache.Node] acquiring RL: fqn=/JSESSION, caller=Thread[http-0.0.0.0-8080-18,5,jboss], lock=read owners=[Thread[http-0.0.0.0-8080-18,5,jboss]]
2006-02-24 12:31:33,362 DEBUG [org.jboss.cache.lock.IdentityLock] acquireReadLock(): caller Thread[http-0.0.0.0-8080-18,5,jboss] already owns lock for /JSESSION
2006-02-24 12:31:33,362 DEBUG [org.jboss.cache.Node] acquired RL: fqn=/JSESSION, caller=Thread[http-0.0.0.0-8080-18,5,jboss], lock=read owners=[Thread[http-0.0.0.0-8080-18,5,jboss]]
2006-02-24 12:31:33,362 DEBUG [org.jboss.cache.Node] acquiring RL: fqn=/JSESSION/localhost, caller=Thread[http-0.0.0.0-8080-18,5,jboss], lock=read owners=[Thread[http-0.0.0.0-8080-18,5,jboss]]
2006-02-24 12:31:33,362 DEBUG [org.jboss.cache.lock.IdentityLock] acquireReadLock(): caller Thread[http-0.0.0.0-8080-18,5,jboss] already owns lock for /JSESSION/localhost
2006-02-24 12:31:33,362 DEBUG [org.jboss.cache.Node] acquired RL: fqn=/JSESSION/localhost, caller=Thread[http-0.0.0.0-8080-18,5,jboss], lock=read owners=[Thread[http-0.0.0.0-8080-18,5,jboss]]
2006-02-24 12:31:33,363 DEBUG [org.jboss.cache.Node] acquiring RL: fqn=/JSESSION/localhost/ui, caller=Thread[http-0.0.0.0-8080-18,5,jboss], lock=read owners=[Thread[http-0.0.0.0-8080-18,5,jboss]]
2006-02-24 12:31:33,363 DEBUG [org.jboss.cache.lock.IdentityLock] acquireReadLock(): caller Thread[http-0.0.0.0-8080-18,5,jboss] already owns lock for /JSESSION/localhost/ui
2006-02-24 12:31:33,363 DEBUG [org.jboss.cache.Node] acquired RL: fqn=/JSESSION/localhost/ui, caller=Thread[http-0.0.0.0-8080-18,5,jboss], lock=read owners=[Thread[http-0.0.0.0-8080-18,5,jboss]]
2006-02-24 12:31:33,363 DEBUG [org.jboss.cache.interceptors.LockInterceptor] failed finding child nPL1hi7Yl6gh6QXewnz35w** of node /JSESSION/localhost/ui
2006-02-24 12:31:33,363 DEBUG [org.jboss.cache.TreeCache] _get("/JSESSION/localhost/ui/nPL1hi7Yl6gh6QXewnz35w**", VERSION, "true")
2006-02-24 12:31:33,363 DEBUG [org.jboss.cache.interceptors.UnlockInterceptor] releasing lock for /JSESSION/localhost/ui/nPL1hi7Yl6gh6QXewnz35w**:
2006-02-24 12:31:33,363 DEBUG [org.jboss.cache.interceptors.UnlockInterceptor] releasing lock for /JSESSION/localhost/ui: read owners=[Thread[http-0.0.0.0-8080-18,5,jboss]]
2006-02-24 12:31:33,363 DEBUG [org.jboss.cache.interceptors.UnlockInterceptor] releasing lock for /JSESSION/localhost: read owners=[Thread[http-0.0.0.0-8080-18,5,jboss]]
2006-02-24 12:31:33,363 DEBUG [org.jboss.cache.interceptors.UnlockInterceptor] releasing lock for /JSESSION: read owners=[Thread[http-0.0.0.0-8080-18,5,jboss]]
2006-02-24 12:31:33,363 DEBUG [org.jboss.cache.interceptors.ReplicationInterceptor] invoking method _remove([Ljava.lang.Object;@849551), members=[v12-in:33295, v13-in:33228, v14-in:32849, v15-in:33771, v11:33377], mode=REPL_ASYNC, exclude_self=true, timeout=15000
2006-02-24 12:31:33,363 DEBUG [org.jboss.cache.TreeCache] callRemoteMethods(): valid members are [v12-in:33295, v13-in:33228, v14-in:32849, v15-in:33771]
2006-02-24 12:31:33,363 DEBUG [org.jboss.cache.TreeCache] (v11:33377): responses for method _replicate:
[sender=v12-in:33295, retval=null, received=false, suspected=false]
[sender=v13-in:33228, retval=null, received=false, suspected=false]
[sender=v14-in:32849, retval=null, received=false, suspected=false]
[sender=v15-in:33771, retval=null, received=false, suspected=false]

[snedapunk]

Ok it appears as if the session has made it to the server but the values are null. This has happened on 1 of the 5 servers approx 500 times in one day so you can imagine how big this problem is for me. Please excuse the long log file but please if anybody can advice me in why a call to a session object is null when redirected to a new server. The object being implements serlizable.

2006-02-24 12:31:21,628 DEBUG [org.jboss.cache.interceptors.ReplicationInterceptor] replicate(): received prepare(<vrx14-in:32849>:43372, [_put(<vrx14-in:32849>:43372, /JSESSION/localhost/ui/nPL1hi7Yl6gh6QXewnz35w**, nPL1hi7Yl6gh6QXewnz35w**, [B@682b9c, true), _put(<vrx14-in:32849>:43372, /JSESSION/localhost/ui/nPL1hi7Yl6gh6QXewnz35w**, VERSION, 1, true)], vrx14-in:32849, true)
2006-02-24 12:31:21,630 DEBUG [org.jboss.cache.Node] createChild: fqn=/JSESSION/localhost/ui/nPL1hi7Yl6gh6QXewnz35w**, child_name=nPL1hi7Yl6gh6QXewnz35w**
2006-02-24 12:31:21,630 DEBUG [org.jboss.cache.interceptors.LockInterceptor] created child nPL1hi7Yl6gh6QXewnz35w**
2006-02-24 12:31:21,630 DEBUG [org.jboss.cache.Node] acquiring WL: fqn=/JSESSION/localhost/ui/nPL1hi7Yl6gh6QXewnz35w**, caller=<vrx14-in:32849>:43372, lock=
2006-02-24 12:31:21,630 DEBUG [org.jboss.cache.Node] acquired WL: fqn=/JSESSION/localhost/ui/nPL1hi7Yl6gh6QXewnz35w**, caller=<vrx14-in:32849>:43372, lock=write owner=<vrx14-in:32849>:43372
2006-02-24 12:31:21,630 DEBUG [org.jboss.cache.TreeCache] _put(<vrx14-in:32849>:43372, "/JSESSION/localhost/ui/nPL1hi7Yl6gh6QXewnz35w**", nPL1hi7Yl6gh6QXewnz35w**, [B@682b9c)
2006-02-24 12:31:21,631 DEBUG [org.jboss.cache.Node] acquiring RL: fqn=/JSESSION/localhost/ui/nPL1hi7Yl6gh6QXewnz35w**, caller=<vrx14-in:32849>:43372, lock=write owner=<vrx14-in:32849>:43372
2006-02-24 12:31:21,631 DEBUG [org.jboss.cache.lock.IdentityLock] acquireReadLock(): caller <vrx14-in:32849>:43372 already owns lock for /JSESSION/localhost/ui/nPL1hi7Yl6gh6QXewnz35w**
2006-02-24 12:31:21,631 DEBUG [org.jboss.cache.Node] acquired RL: fqn=/JSESSION/localhost/ui/nPL1hi7Yl6gh6QXewnz35w**, caller=<vrx14-in:32849>:43372, lock=write owner=<vrx14-in:32849>:43372
2006-02-24 12:31:21,631 DEBUG [org.jboss.cache.TreeCache] _get("/JSESSION/localhost/ui/nPL1hi7Yl6gh6QXewnz35w**", VERSION, "true")
2006-02-24 12:31:21,639 DEBUG [org.jboss.cache.Node] acquiring WL: fqn=/JSESSION/localhost/ui/nPL1hi7Yl6gh6QXewnz35w**, caller=<vrx14-in:32849>:43372, lock=write owner=<vrx14-in:32849>:43372
2006-02-24 12:31:21,639 DEBUG [org.jboss.cache.lock.IdentityLock] acquireWriteLock(): caller already owns lock for /JSESSION/localhost/ui/nPL1hi7Yl6gh6QXewnz35w** (caller=<vrx14-in:32849>:43372)
2006-02-24 12:31:21,640 DEBUG [org.jboss.cache.Node] acquired WL: fqn=/JSESSION/localhost/ui/nPL1hi7Yl6gh6QXewnz35w**, caller=<vrx14-in:32849>:43372, lock=write owner=<vrx14-in:32849>:43372
2006-02-24 12:31:21,640 DEBUG [org.jboss.cache.TreeCache] _put(<vrx14-in:32849>:43372, "/JSESSION/localhost/ui/nPL1hi7Yl6gh6QXewnz35w**", VERSION, 1)
2006-02-24 12:31:21,640 DEBUG [org.jboss.cache.Node] acquiring RL: fqn=/JSESSION/localhost/ui/nPL1hi7Yl6gh6QXewnz35w**, caller=<vrx14-in:32849>:43372, lock=write owner=<vrx14-in:32849>:43372
2006-02-24 12:31:21,640 DEBUG [org.jboss.cache.lock.IdentityLock] acquireReadLock(): caller <vrx14-in:32849>:43372 already owns lock for /JSESSION/localhost/ui/nPL1hi7Yl6gh6QXewnz35w**
2006-02-24 12:31:21,640 DEBUG [org.jboss.cache.Node] acquired RL: fqn=/JSESSION/localhost/ui/nPL1hi7Yl6gh6QXewnz35w**, caller=<vrx14-in:32849>:43372, lock=write owner=<vrx14-in:32849>:43372
2006-02-24 12:31:21,641 DEBUG [org.jboss.cache.TreeCache] _get("/JSESSION/localhost/ui/nPL1hi7Yl6gh6QXewnz35w**", VERSION, "true")
2006-02-24 12:31:21,649 DEBUG [org.jboss.cache.interceptors.LockInterceptor] releasing lock for /JSESSION/localhost/ui/nPL1hi7Yl6gh6QXewnz35w** (write owner=<vrx14-in:32849>:43372)
2006-02-24 12:31:26,792 DEBUG [org.jboss.cache.Node] acquiring RL: fqn=/JSESSION/localhost/ui/nPL1hi7Yl6gh6QXewnz35w**, caller=Thread[http-0.0.0.0-8080-18,5,jboss], lock=
2006-02-24 12:31:26,792 DEBUG [org.jboss.cache.Node] acquired RL: fqn=/JSESSION/localhost/ui/nPL1hi7Yl6gh6QXewnz35w**, caller=Thread[http-0.0.0.0-8080-18,5,jboss], lock=read owners=[Thread[http-0.0.0.0-8080-18,5,jboss]]
2006-02-24 12:31:26,792 DEBUG [org.jboss.cache.TreeCache] _get("/JSESSION/localhost/ui/nPL1hi7Yl6gh6QXewnz35w**", nPL1hi7Yl6gh6QXewnz35w**, "true")
2006-02-24 12:31:26,792 DEBUG [org.jboss.cache.interceptors.UnlockInterceptor] releasing lock for /JSESSION/localhost/ui/nPL1hi7Yl6gh6QXewnz35w**: read owners=[Thread[http-0.0.0.0-8080-18,5,jboss]]
2006-02-24 12:31:27,889 DEBUG [org.jboss.cache.Node] acquiring RL: fqn=/JSESSION/localhost/ui/nPL1hi7Yl6gh6QXewnz35w**, caller=Thread[ContainerBackgroundProcessor[StandardEngine[jboss.web]],5,jboss], lock=
2006-02-24 12:31:27,889 DEBUG [org.jboss.cache.Node] acquired RL: fqn=/JSESSION/localhost/ui/nPL1hi7Yl6gh6QXewnz35w**, caller=Thread[ContainerBackgroundProcessor[StandardEngine[jboss.web]],5,jboss], lock=read owners=[Thread[ContainerBackgroundProcessor[StandardEngine[jboss.web]],5,jboss]]
2006-02-24 12:31:27,889 DEBUG [org.jboss.cache.TreeCache] _get("/JSESSION/localhost/ui/nPL1hi7Yl6gh6QXewnz35w**", nPL1hi7Yl6gh6QXewnz35w**, "true")
2006-02-24 12:31:27,889 DEBUG [org.jboss.cache.interceptors.UnlockInterceptor] releasing lock for /JSESSION/localhost/ui/nPL1hi7Yl6gh6QXewnz35w**: read owners=[Thread[ContainerBackgroundProcessor[StandardEngine[jboss.web]],5,jboss]]
2006-02-24 12:31:29,029 DEBUG [org.jboss.cache.Node] acquiring WL: fqn=/JSESSION/localhost/ui/nPL1hi7Yl6gh6QXewnz35w**, caller=<vrx11:33377>:24691, lock=
2006-02-24 12:31:29,029 DEBUG [org.jboss.cache.Node] acquired WL: fqn=/JSESSION/localhost/ui/nPL1hi7Yl6gh6QXewnz35w**, caller=<vrx11:33377>:24691, lock=write owner=<vrx11:33377>:24691
2006-02-24 12:31:29,029 DEBUG [org.jboss.cache.TreeCache] _put(<vrx11:33377>:24691, "/JSESSION/localhost/ui/nPL1hi7Yl6gh6QXewnz35w**", nPL1hi7Yl6gh6QXewnz35w**, [B@53c280)
2006-02-24 12:31:29,030 DEBUG [org.jboss.cache.Node] acquiring RL: fqn=/JSESSION/localhost/ui/nPL1hi7Yl6gh6QXewnz35w**, caller=<vrx11:33377>:24691, lock=write owner=<vrx11:33377>:24691
2006-02-24 12:31:29,030 DEBUG [org.jboss.cache.lock.IdentityLock] acquireReadLock(): caller <vrx11:33377>:24691 already owns lock for /JSESSION/localhost/ui/nPL1hi7Yl6gh6QXewnz35w**
2006-02-24 12:31:29,030 DEBUG [org.jboss.cache.Node] acquired RL: fqn=/JSESSION/localhost/ui/nPL1hi7Yl6gh6QXewnz35w**, caller=<vrx11:33377>:24691, lock=write owner=<vrx11:33377>:24691
2006-02-24 12:31:29,030 DEBUG [org.jboss.cache.TreeCache] _get("/JSESSION/localhost/ui/nPL1hi7Yl6gh6QXewnz35w**", VERSION, "true")
2006-02-24 12:31:29,055 DEBUG [org.jboss.cache.Node] acquiring WL: fqn=/JSESSION/localhost/ui/nPL1hi7Yl6gh6QXewnz35w**, caller=<vrx11:33377>:24691, lock=write owner=<vrx11:33377>:24691
2006-02-24 12:31:29,055 DEBUG [org.jboss.cache.lock.IdentityLock] acquireWriteLock(): caller already owns lock for /JSESSION/localhost/ui/nPL1hi7Yl6gh6QXewnz35w** (caller=<vrx11:33377>:24691)
2006-02-24 12:31:29,055 DEBUG [org.jboss.cache.Node] acquired WL: fqn=/JSESSION/localhost/ui/nPL1hi7Yl6gh6QXewnz35w**, caller=<vrx11:33377>:24691, lock=write owner=<vrx11:33377>:24691
2006-02-24 12:31:29,055 DEBUG [org.jboss.cache.TreeCache] _put(<vrx11:33377>:24691, "/JSESSION/localhost/ui/nPL1hi7Yl6gh6QXewnz35w**", VERSION, 2)
2006-02-24 12:31:29,056 DEBUG [org.jboss.cache.Node] acquiring RL: fqn=/JSESSION/localhost/ui/nPL1hi7Yl6gh6QXewnz35w**, caller=<vrx11:33377>:24691, lock=write owner=<vrx11:33377>:24691
2006-02-24 12:31:29,056 DEBUG [org.jboss.cache.lock.IdentityLock] acquireReadLock(): caller <vrx11:33377>:24691 already owns lock for /JSESSION/localhost/ui/nPL1hi7Yl6gh6QXewnz35w**
2006-02-24 12:31:29,056 DEBUG [org.jboss.cache.Node] acquired RL: fqn=/JSESSION/localhost/ui/nPL1hi7Yl6gh6QXewnz35w**, caller=<vrx11:33377>:24691, lock=write owner=<vrx11:33377>:24691
2006-02-24 12:31:29,056 DEBUG [org.jboss.cache.TreeCache] _get("/JSESSION/localhost/ui/nPL1hi7Yl6gh6QXewnz35w**", VERSION, "true")
2006-02-24 12:31:29,086 DEBUG [org.jboss.cache.interceptors.ReplicationInterceptor] (vrx11:33377): running remote prepare for <vrx11:33377>:24691 with async mode=true and coord=vrx11:33377 (2 modifications): [_put(<vrx11:33377>:24691, /JSESSION/localhost/ui/nPL1hi7Yl6gh6QXewnz35w**, nPL1hi7Yl6gh6QXewnz35w**, [B@53c280, true), _put(<vrx11:33377>:24691, /JSESSION/localhost/ui/nPL1hi7Yl6gh6QXewnz35w**, VERSION, 2, true)]
2006-02-24 12:31:29,087 DEBUG [org.jboss.cache.interceptors.LockInterceptor] releasing lock for /JSESSION/localhost/ui/nPL1hi7Yl6gh6QXewnz35w** (write owner=<vrx11:33377>:24691)
2006-02-24 12:31:30,705 DEBUG [org.jboss.cache.interceptors.ReplicationInterceptor] replicate(): received prepare(<vrx14-in:32849>:43375, [_put(<vrx14-in:32849>:43375, /JSESSION/localhost/ui/nPL1hi7Yl6gh6QXewnz35w**, nPL1hi7Yl6gh6QXewnz35w**, [B@7a9b8f, true), _put(<vrx14-in:32849>:43375, /JSESSION/localhost/ui/nPL1hi7Yl6gh6QXewnz35w**, VERSION, 2, true)], vrx14-in:32849, true)
2006-02-24 12:31:30,705 DEBUG [org.jboss.cache.Node] acquiring WL: fqn=/JSESSION/localhost/ui/nPL1hi7Yl6gh6QXewnz35w**, caller=<vrx14-in:32849>:43375, lock=
2006-02-24 12:31:30,706 DEBUG [org.jboss.cache.Node] acquired WL: fqn=/JSESSION/localhost/ui/nPL1hi7Yl6gh6QXewnz35w**, caller=<vrx14-in:32849>:43375, lock=write owner=<vrx14-in:32849>:43375
2006-02-24 12:31:30,706 DEBUG [org.jboss.cache.TreeCache] _put(<vrx14-in:32849>:43375, "/JSESSION/localhost/ui/nPL1hi7Yl6gh6QXewnz35w**", nPL1hi7Yl6gh6QXewnz35w**, [B@7a9b8f)
2006-02-24 12:31:30,706 DEBUG [org.jboss.cache.Node] acquiring RL: fqn=/JSESSION/localhost/ui/nPL1hi7Yl6gh6QXewnz35w**, caller=<vrx14-in:32849>:43375, lock=write owner=<vrx14-in:32849>:43375
2006-02-24 12:31:30,706 DEBUG [org.jboss.cache.lock.IdentityLock] acquireReadLock(): caller <vrx14-in:32849>:43375 already owns lock for /JSESSION/localhost/ui/nPL1hi7Yl6gh6QXewnz35w**
2006-02-24 12:31:30,706 DEBUG [org.jboss.cache.Node] acquired RL: fqn=/JSESSION/localhost/ui/nPL1hi7Yl6gh6QXewnz35w**, caller=<vrx14-in:32849>:43375, lock=write owner=<vrx14-in:32849>:43375
2006-02-24 12:31:30,706 DEBUG [org.jboss.cache.TreeCache] _get("/JSESSION/localhost/ui/nPL1hi7Yl6gh6QXewnz35w**", VERSION, "true")
2006-02-24 12:31:30,715 DEBUG [org.jboss.cache.Node] acquiring WL: fqn=/JSESSION/localhost/ui/nPL1hi7Yl6gh6QXewnz35w**, caller=<vrx14-in:32849>:43375, lock=write owner=<vrx14-in:32849>:43375
2006-02-24 12:31:30,715 DEBUG [org.jboss.cache.lock.IdentityLock] acquireWriteLock(): caller already owns lock for /JSESSION/localhost/ui/nPL1hi7Yl6gh6QXewnz35w** (caller=<vrx14-in:32849>:43375)
2006-02-24 12:31:30,715 DEBUG [org.jboss.cache.Node] acquired WL: fqn=/JSESSION/localhost/ui/nPL1hi7Yl6gh6QXewnz35w**, caller=<vrx14-in:32849>:43375, lock=write owner=<vrx14-in:32849>:43375
2006-02-24 12:31:30,715 DEBUG [org.jboss.cache.TreeCache] _put(<vrx14-in:32849>:43375, "/JSESSION/localhost/ui/nPL1hi7Yl6gh6QXewnz35w**", VERSION, 2)
2006-02-24 12:31:30,716 DEBUG [org.jboss.cache.Node] acquiring RL: fqn=/JSESSION/localhost/ui/nPL1hi7Yl6gh6QXewnz35w**, caller=<vrx14-in:32849>:43375, lock=write owner=<vrx14-in:32849>:43375
2006-02-24 12:31:30,716 DEBUG [org.jboss.cache.lock.IdentityLock] acquireReadLock(): caller <vrx14-in:32849>:43375 already owns lock for /JSESSION/localhost/ui/nPL1hi7Yl6gh6QXewnz35w**
2006-02-24 12:31:30,716 DEBUG [org.jboss.cache.Node] acquired RL: fqn=/JSESSION/localhost/ui/nPL1hi7Yl6gh6QXewnz35w**, caller=<vrx14-in:32849>:43375, lock=write owner=<vrx14-in:32849>:43375
2006-02-24 12:31:30,716 DEBUG [org.jboss.cache.TreeCache] _get("/JSESSION/localhost/ui/nPL1hi7Yl6gh6QXewnz35w**", VERSION, "true")
2006-02-24 12:31:30,724 DEBUG [org.jboss.cache.interceptors.LockInterceptor] releasing lock for /JSESSION/localhost/ui/nPL1hi7Yl6gh6QXewnz35w** (write owner=<vrx14-in:32849>:43375)
2006-02-24 12:31:33,360 DEBUG [org.jboss.cache.Node] acquiring WL: fqn=/JSESSION/localhost/ui/nPL1hi7Yl6gh6QXewnz35w**, caller=Thread[http-0.0.0.0-8080-18,5,jboss], lock=
2006-02-24 12:31:33,360 DEBUG [org.jboss.cache.Node] acquired WL: fqn=/JSESSION/localhost/ui/nPL1hi7Yl6gh6QXewnz35w**, caller=Thread[http-0.0.0.0-8080-18,5,jboss], lock=write owner=Thread[http-0.0.0.0-8080-18,5,jboss]
2006-02-24 12:31:33,360 DEBUG [org.jboss.cache.TreeCache] _remove(null, "/JSESSION/localhost/ui/nPL1hi7Yl6gh6QXewnz35w**", nPL1hi7Yl6gh6QXewnz35w**)
2006-02-24 12:31:33,360 DEBUG [org.jboss.cache.Node] acquiring RL: fqn=/JSESSION/localhost/ui/nPL1hi7Yl6gh6QXewnz35w**, caller=Thread[http-0.0.0.0-8080-18,5,jboss], lock=write owner=Thread[http-0.0.0.0-8080-18,5,jboss]
2006-02-24 12:31:33,361 DEBUG [org.jboss.cache.lock.IdentityLock] acquireReadLock(): caller Thread[http-0.0.0.0-8080-18,5,jboss] already owns lock for /JSESSION/localhost/ui/nPL1hi7Yl6gh6QXewnz35w**
2006-02-24 12:31:33,361 DEBUG [org.jboss.cache.Node] acquired RL: fqn=/JSESSION/localhost/ui/nPL1hi7Yl6gh6QXewnz35w**, caller=Thread[http-0.0.0.0-8080-18,5,jboss], lock=write owner=Thread[http-0.0.0.0-8080-18,5,jboss]
2006-02-24 12:31:33,361 DEBUG [org.jboss.cache.TreeCache] _get("/JSESSION/localhost/ui/nPL1hi7Yl6gh6QXewnz35w**", VERSION, "true")
2006-02-24 12:31:33,361 DEBUG [org.jboss.cache.interceptors.UnlockInterceptor] releasing lock for /JSESSION/localhost/ui/nPL1hi7Yl6gh6QXewnz35w**: write owner=Thread[http-0.0.0.0-8080-18,5,jboss]
2006-02-24 12:31:33,362 DEBUG [org.jboss.cache.Node] acquiring WL: fqn=/JSESSION/localhost/ui/nPL1hi7Yl6gh6QXewnz35w**, caller=Thread[http-0.0.0.0-8080-18,5,jboss], lock=
2006-02-24 12:31:33,362 DEBUG [org.jboss.cache.Node] acquired WL: fqn=/JSESSION/localhost/ui/nPL1hi7Yl6gh6QXewnz35w**, caller=Thread[http-0.0.0.0-8080-18,5,jboss], lock=write owner=Thread[http-0.0.0.0-8080-18,5,jboss]
2006-02-24 12:31:33,362 DEBUG [org.jboss.cache.Node] acquiring WL: fqn=/JSESSION/localhost/ui/nPL1hi7Yl6gh6QXewnz35w**, caller=Thread[http-0.0.0.0-8080-18,5,jboss], lock=write owner=Thread[http-0.0.0.0-8080-18,5,jboss]
2006-02-24 12:31:33,362 DEBUG [org.jboss.cache.lock.IdentityLock] acquireWriteLock(): caller already owns lock for /JSESSION/localhost/ui/nPL1hi7Yl6gh6QXewnz35w** (caller=Thread[http-0.0.0.0-8080-18,5,jboss])
2006-02-24 12:31:33,362 DEBUG [org.jboss.cache.Node] acquired WL: fqn=/JSESSION/localhost/ui/nPL1hi7Yl6gh6QXewnz35w**, caller=Thread[http-0.0.0.0-8080-18,5,jboss], lock=write owner=Thread[http-0.0.0.0-8080-18,5,jboss]
2006-02-24 12:31:33,362 DEBUG [org.jboss.cache.TreeCache] _remove(null, "/JSESSION/localhost/ui/nPL1hi7Yl6gh6QXewnz35w**")
2006-02-24 12:31:33,362 DEBUG [org.jboss.cache.Node] removed child nPL1hi7Yl6gh6QXewnz35w**
2006-02-24 12:31:33,363 DEBUG [org.jboss.cache.interceptors.LockInterceptor] failed finding child nPL1hi7Yl6gh6QXewnz35w** of node /JSESSION/localhost/ui
2006-02-24 12:31:33,363 DEBUG [org.jboss.cache.TreeCache] _get("/JSESSION/localhost/ui/nPL1hi7Yl6gh6QXewnz35w**", VERSION, "true")
2006-02-24 12:31:33,363 DEBUG [org.jboss.cache.interceptors.UnlockInterceptor] releasing lock for /JSESSION/localhost/ui/nPL1hi7Yl6gh6QXewnz35w**:
2006-02-24 12:31:33,364 INFO session: nPL1hi7Yl6gh6QXewnz35w**

I try to get the account from session, user is forced to login wegpage.

2006-02-24 12:31:33,368 DEBUG [org.jboss.cache.interceptors.LockInterceptor] failed finding child nPL1hi7Yl6gh6QXewnz35w** of node /JSESSION/localhost/ui
2006-02-24 12:31:33,368 DEBUG [org.jboss.cache.TreeCache] _get("/JSESSION/localhost/ui/nPL1hi7Yl6gh6QXewnz35w**", nPL1hi7Yl6gh6QXewnz35w**, "true")
2006-02-24 12:37:49,309 DEBUG [org.jboss.cache.interceptors.LockInterceptor] failed finding child nPL1hi7Yl6gh6QXewnz35w** of node /JSESSION/localhost/ui
2006-02-24 12:37:49,309 DEBUG [org.jboss.cache.TreeCache] _get("/JSESSION/localhost/ui/nPL1hi7Yl6gh6QXewnz35w**", nPL1hi7Yl6gh6QXewnz35w**, "true")
2006-02-24 12:37:49,311 DEBUG [org.jboss.cache.interceptors.LockInterceptor] failed finding child nPL1hi7Yl6gh6QXewnz35w** of node /JSESSION/localhost/ui
2006-02-24 12:37:49,311 DEBUG [org.jboss.cache.TreeCache] _get("/JSESSION/localhost/ui/nPL1hi7Yl6gh6QXewnz35w**", nPL1hi7Yl6gh6QXewnz35w**, "true")
2006-02-24 12:37:49,312 DEBUG [org.jboss.cache.Node] createChild: fqn=/JSESSION/localhost/ui/nPL1hi7Yl6gh6QXewnz35w**, child_name=nPL1hi7Yl6gh6QXewnz35w**
2006-02-24 12:37:49,312 DEBUG [org.jboss.cache.interceptors.LockInterceptor] created child nPL1hi7Yl6gh6QXewnz35w**
2006-02-24 12:37:49,312 DEBUG [org.jboss.cache.Node] acquiring WL: fqn=/JSESSION/localhost/ui/nPL1hi7Yl6gh6QXewnz35w**, caller=<vrx11:33377>:25039, lock=
2006-02-24 12:37:49,312 DEBUG [org.jboss.cache.Node] acquired WL: fqn=/JSESSION/localhost/ui/nPL1hi7Yl6gh6QXewnz35w**, caller=<vrx11:33377>:25039, lock=write owner=<vrx11:33377>:25039
2006-02-24 12:37:49,312 DEBUG [org.jboss.cache.TreeCache] _put(<vrx11:33377>:25039, "/JSESSION/localhost/ui/nPL1hi7Yl6gh6QXewnz35w**", nPL1hi7Yl6gh6QXewnz35w**, [B@11fb8ef)
2006-02-24 12:37:49,313 DEBUG [org.jboss.cache.Node] acquiring RL: fqn=/JSESSION/localhost/ui/nPL1hi7Yl6gh6QXewnz35w**, caller=<vrx11:33377>:25039, lock=write owner=<vrx11:33377>:25039
2006-02-24 12:37:49,313 DEBUG [org.jboss.cache.lock.IdentityLock] acquireReadLock(): caller <vrx11:33377>:25039 already owns lock for /JSESSION/localhost/ui/nPL1hi7Yl6gh6QXewnz35w**
2006-02-24 12:37:49,313 DEBUG [org.jboss.cache.Node] acquired RL: fqn=/JSESSION/localhost/ui/nPL1hi7Yl6gh6QXewnz35w**, caller=<vrx11:33377>:25039, lock=write owner=<vrx11:33377>:25039
2006-02-24 12:37:49,313 DEBUG [org.jboss.cache.TreeCache] _get("/JSESSION/localhost/ui/nPL1hi7Yl6gh6QXewnz35w**", VERSION, "true")
2006-02-24 12:37:49,347 DEBUG [org.jboss.cache.Node] acquiring WL: fqn=/JSESSION/localhost/ui/nPL1hi7Yl6gh6QXewnz35w**, caller=<vrx11:33377>:25039, lock=write owner=<vrx11:33377>:25039
2006-02-24 12:37:49,347 DEBUG [org.jboss.cache.lock.IdentityLock] acquireWriteLock(): caller already owns lock for /JSESSION/localhost/ui/nPL1hi7Yl6gh6QXewnz35w** (caller=<vrx11:33377>:25039)
2006-02-24 12:37:49,347 DEBUG [org.jboss.cache.Node] acquired WL: fqn=/JSESSION/localhost/ui/nPL1hi7Yl6gh6QXewnz35w**, caller=<vrx11:33377>:25039, lock=write owner=<vrx11:33377>:25039
2006-02-24 12:37:49,347 DEBUG [org.jboss.cache.TreeCache] _put(<vrx11:33377>:25039, "/JSESSION/localhost/ui/nPL1hi7Yl6gh6QXewnz35w**", VERSION, 1)
2006-02-24 12:37:49,347 DEBUG [org.jboss.cache.Node] acquiring RL: fqn=/JSESSION/localhost/ui/nPL1hi7Yl6gh6QXewnz35w**, caller=<vrx11:33377>:25039, lock=write owner=<vrx11:33377>:25039
2006-02-24 12:37:49,347 DEBUG [org.jboss.cache.lock.IdentityLock] acquireReadLock(): caller <vrx11:33377>:25039 already owns lock for /JSESSION/localhost/ui/nPL1hi7Yl6gh6QXewnz35w**
2006-02-24 12:37:49,347 DEBUG [org.jboss.cache.Node] acquired RL: fqn=/JSESSION/localhost/ui/nPL1hi7Yl6gh6QXewnz35w**, caller=<vrx11:33377>:25039, lock=write owner=<vrx11:33377>:25039
2006-02-24 12:37:49,348 DEBUG [org.jboss.cache.TreeCache] _get("/JSESSION/localhost/ui/nPL1hi7Yl6gh6QXewnz35w**", VERSION, "true")
2006-02-24 12:37:49,389 DEBUG [org.jboss.cache.interceptors.ReplicationInterceptor] (vrx11:33377): running remote prepare for <vrx11:33377>:25039 with async mode=true and coord=vrx11:33377 (2 modifications): [_put(<vrx11:33377>:25039, /JSESSION/localhost/ui/nPL1hi7Yl6gh6QXewnz35w**, nPL1hi7Yl6gh6QXewnz35w**, [B@11fb8ef, true), _put(<vrx11:33377>:25039, /JSESSION/localhost/ui/nPL1hi7Yl6gh6QXewnz35w**, VERSION, 1, true)]
2006-02-24 12:37:49,391 DEBUG [org.jboss.cache.interceptors.LockInterceptor] releasing lock for /JSESSION/localhost/ui/nPL1hi7Yl6gh6QXewnz35w** (write owner=<vrx11:33377>:25039)
2006-02-24 12:37:49,872 DEBUG [org.jboss.cache.Node] acquiring WL: fqn=/JSESSION/localhost/ui/nPL1hi7Yl6gh6QXewnz35w**, caller=Thread[http-0.0.0.0-8080-2,5,jboss], lock=
2006-02-24 12:37:49,872 DEBUG [org.jboss.cache.Node] acquired WL: fqn=/JSESSION/localhost/ui/nPL1hi7Yl6gh6QXewnz35w**, caller=Thread[http-0.0.0.0-8080-2,5,jboss], lock=write owner=Thread[http-0.0.0.0-8080-2,5,jboss]
2006-02-24 12:37:49,872 DEBUG [org.jboss.cache.TreeCache] _remove(null, "/JSESSION/localhost/ui/nPL1hi7Yl6gh6QXewnz35w**", nPL1hi7Yl6gh6QXewnz35w**)
2006-02-24 12:37:49,872 DEBUG [org.jboss.cache.Node] acquiring RL: fqn=/JSESSION/localhost/ui/nPL1hi7Yl6gh6QXewnz35w**, caller=Thread[http-0.0.0.0-8080-2,5,jboss], lock=write owner=Thread[http-0.0.0.0-8080-2,5,jboss]
2006-02-24 12:37:49,872 DEBUG [org.jboss.cache.lock.IdentityLock] acquireReadLock(): caller Thread[http-0.0.0.0-8080-2,5,jboss] already owns lock for /JSESSION/localhost/ui/nPL1hi7Yl6gh6QXewnz35w**
2006-02-24 12:37:49,872 DEBUG [org.jboss.cache.Node] acquired RL: fqn=/JSESSION/localhost/ui/nPL1hi7Yl6gh6QXewnz35w**, caller=Thread[http-0.0.0.0-8080-2,5,jboss], lock=write owner=Thread[http-0.0.0.0-8080-2,5,jboss]
2006-02-24 12:37:49,872 DEBUG [org.jboss.cache.TreeCache] _get("/JSESSION/localhost/ui/nPL1hi7Yl6gh6QXewnz35w**", VERSION, "true")
2006-02-24 12:37:49,873 DEBUG [org.jboss.cache.interceptors.UnlockInterceptor] releasing lock for /JSESSION/localhost/ui/nPL1hi7Yl6gh6QXewnz35w**: write owner=Thread[http-0.0.0.0-8080-2,5,jboss]
2006-02-24 12:37:49,874 DEBUG [org.jboss.cache.Node] acquiring WL: fqn=/JSESSION/localhost/ui/nPL1hi7Yl6gh6QXewnz35w**, caller=Thread[http-0.0.0.0-8080-2,5,jboss], lock=
2006-02-24 12:37:49,874 DEBUG [org.jboss.cache.Node] acquired WL: fqn=/JSESSION/localhost/ui/nPL1hi7Yl6gh6QXewnz35w**, caller=Thread[http-0.0.0.0-8080-2,5,jboss], lock=write owner=Thread[http-0.0.0.0-8080-2,5,jboss]
2006-02-24 12:37:49,874 DEBUG [org.jboss.cache.Node] acquiring WL: fqn=/JSESSION/localhost/ui/nPL1hi7Yl6gh6QXewnz35w**, caller=Thread[http-0.0.0.0-8080-2,5,jboss], lock=write owner=Thread[http-0.0.0.0-8080-2,5,jboss]
2006-02-24 12:37:49,874 DEBUG [org.jboss.cache.lock.IdentityLock] acquireWriteLock(): caller already owns lock for /JSESSION/localhost/ui/nPL1hi7Yl6gh6QXewnz35w** (caller=Thread[http-0.0.0.0-8080-2,5,jboss])
2006-02-24 12:37:49,874 DEBUG [org.jboss.cache.Node] acquired WL: fqn=/JSESSION/localhost/ui/nPL1hi7Yl6gh6QXewnz35w**, caller=Thread[http-0.0.0.0-8080-2,5,jboss], lock=write owner=Thread[http-0.0.0.0-8080-2,5,jboss]
2006-02-24 12:37:49,874 DEBUG [org.jboss.cache.TreeCache] _remove(null, "/JSESSION/localhost/ui/nPL1hi7Yl6gh6QXewnz35w**")
2006-02-24 12:37:49,874 DEBUG [org.jboss.cache.Node] removed child nPL1hi7Yl6gh6QXewnz35w**
2006-02-24 12:37:49,875 DEBUG [org.jboss.cache.interceptors.LockInterceptor] failed finding child nPL1hi7Yl6gh6QXewnz35w** of node /JSESSION/localhost/ui
2006-02-24 12:37:49,875 DEBUG [org.jboss.cache.TreeCache] _get("/JSESSION/localhost/ui/nPL1hi7Yl6gh6QXewnz35w**", VERSION, "true")
2006-02-24 12:37:49,875 DEBUG [org.jboss.cache.interceptors.UnlockInterceptor] releasing lock for /JSESSION/localhost/ui/nPL1hi7Yl6gh6QXewnz35w**:
2006-02-24 12:37:49,876 DEBUG [org.jboss.cache.interceptors.LockInterceptor] failed finding child nPL1hi7Yl6gh6QXewnz35w** of node /JSESSION/localhost/ui
2006-02-24 12:37:49,876 DEBUG [org.jboss.cache.TreeCache] _get("/JSESSION/localhost/ui/nPL1hi7Yl6gh6QXewnz35w**", nPL1hi7Yl6gh6QXewnz35w**, "true")
2006-02-24 12:37:49,877 DEBUG [org.jboss.cache.Node] createChild: fqn=/JSESSION/localhost/ui/nPL1hi7Yl6gh6QXewnz35w**, child_name=nPL1hi7Yl6gh6QXewnz35w**
2006-02-24 12:37:49,877 DEBUG [org.jboss.cache.interceptors.LockInterceptor] created child nPL1hi7Yl6gh6QXewnz35w**
2006-02-24 12:37:49,877 DEBUG [org.jboss.cache.Node] acquiring WL: fqn=/JSESSION/localhost/ui/nPL1hi7Yl6gh6QXewnz35w**, caller=<vrx11:33377>:25043, lock=
2006-02-24 12:37:49,877 DEBUG [org.jboss.cache.Node] acquired WL: fqn=/JSESSION/localhost/ui/nPL1hi7Yl6gh6QXewnz35w**, caller=<vrx11:33377>:25043, lock=write owner=<vrx11:33377>:25043
2006-02-24 12:37:49,877 DEBUG [org.jboss.cache.TreeCache] _put(<vrx11:33377>:25043, "/JSESSION/localhost/ui/nPL1hi7Yl6gh6QXewnz35w**", nPL1hi7Yl6gh6QXewnz35w**, [B@7317e4)
2006-02-24 12:37:49,878 DEBUG [org.jboss.cache.Node] acquiring RL: fqn=/JSESSION/localhost/ui/nPL1hi7Yl6gh6QXewnz35w**, caller=<vrx11:33377>:25043, lock=write owner=<vrx11:33377>:25043
2006-02-24 12:37:49,878 DEBUG [org.jboss.cache.lock.IdentityLock] acquireReadLock(): caller <vrx11:33377>:25043 already owns lock for /JSESSION/localhost/ui/nPL1hi7Yl6gh6QXewnz35w**
2006-02-24 12:37:49,878 DEBUG [org.jboss.cache.Node] acquired RL: fqn=/JSESSION/localhost/ui/nPL1hi7Yl6gh6QXewnz35w**, caller=<vrx11:33377>:25043, lock=write owner=<vrx11:33377>:25043
2006-02-24 12:37:49,878 DEBUG [org.jboss.cache.TreeCache] _get("/JSESSION/localhost/ui/nPL1hi7Yl6gh6QXewnz35w**", VERSION, "true")
2006-02-24 12:37:49,892 DEBUG [org.jboss.cache.Node] acquiring WL: fqn=/JSESSION/localhost/ui/nPL1hi7Yl6gh6QXewnz35w**, caller=<vrx11:33377>:25043, lock=write owner=<vrx11:33377>:25043
2006-02-24 12:37:49,892 DEBUG [org.jboss.cache.lock.IdentityLock] acquireWriteLock(): caller already owns lock for /JSESSION/localhost/ui/nPL1hi7Yl6gh6QXewnz35w** (caller=<vrx11:33377>:25043)
2006-02-24 12:37:49,892 DEBUG [org.jboss.cache.Node] acquired WL: fqn=/JSESSION/localhost/ui/nPL1hi7Yl6gh6QXewnz35w**, caller=<vrx11:33377>:25043, lock=write owner=<vrx11:33377>:25043
2006-02-24 12:37:49,892 DEBUG [org.jboss.cache.TreeCache] _put(<vrx11:33377>:25043, "/JSESSION/localhost/ui/nPL1hi7Yl6gh6QXewnz35w**", VERSION, 1)
2006-02-24 12:37:49,893 DEBUG [org.jboss.cache.Node] acquiring RL: fqn=/JSESSION/localhost/ui/nPL1hi7Yl6gh6QXewnz35w**, caller=<vrx11:33377>:25043, lock=write owner=<vrx11:33377>:25043
2006-02-24 12:37:49,893 DEBUG [org.jboss.cache.lock.IdentityLock] acquireReadLock(): caller <vrx11:33377>:25043 already owns lock for /JSESSION/localhost/ui/nPL1hi7Yl6gh6QXewnz35w**
2006-02-24 12:37:49,893 DEBUG [org.jboss.cache.Node] acquired RL: fqn=/JSESSION/localhost/ui/nPL1hi7Yl6gh6QXewnz35w**, caller=<vrx11:33377>:25043, lock=write owner=<vrx11:33377>:25043
2006-02-24 12:37:49,893 DEBUG [org.jboss.cache.TreeCache] _get("/JSESSION/localhost/ui/nPL1hi7Yl6gh6QXewnz35w**", VERSION, "true")
2006-02-24 12:37:49,920 DEBUG [org.jboss.cache.interceptors.ReplicationInterceptor] (vrx11:33377): running remote prepare for <vrx11:33377>:25043 with async mode=true and coord=vrx11:33377 (2 modifications): [_put(<vrx11:33377>:25043, /JSESSION/localhost/ui/nPL1hi7Yl6gh6QXewnz35w**, nPL1hi7Yl6gh6QXewnz35w**, [B@7317e4, true), _put(<vrx11:33377>:25043, /JSESSION/localhost/ui/nPL1hi7Yl6gh6QXewnz35w**, VERSION, 1, true)]
2006-02-24 12:37:49,921 DEBUG [org.jboss.cache.interceptors.LockInterceptor] releasing lock for /JSESSION/localhost/ui/nPL1hi7Yl6gh6QXewnz35w** (write owner=<vrx11:33377>:25043)
users logs back in and has same session id and reports no problems.
2006-02-24 12:37:50,279 INFO [STDOUT] USER LOGIN with session id: nPL1hi7Yl6gh6QXewnz35w**, session creation time: 1140813469876, last access time: 1140813469876, max inactive interval: 3600, is new: true
2006-02-24 12:38:00,711 DEBUG [org.jboss.cache.Node] acquiring WL: fqn=/JSESSION/localhost/ui/nPL1hi7Yl6gh6QXewnz35w**, caller=<vrx11:33377>:25062, lock=
2006-02-24 12:38:00,711 DEBUG [org.jboss.cache.Node] acquired WL: fqn=/JSESSION/localhost/ui/nPL1hi7Yl6gh6QXewnz35w**, caller=<vrx11:33377>:25062, lock=write owner=<vrx11:33377>:25062
2006-02-24 12:38:00,711 DEBUG [org.jboss.cache.TreeCache] _put(<vrx11:33377>:25062, "/JSESSION/localhost/ui/nPL1hi7Yl6gh6QXewnz35w**", nPL1hi7Yl6gh6QXewnz35w**, [B@5862ea)
2006-02-24 12:38:00,712 DEBUG [org.jboss.cache.Node] acquiring RL: fqn=/JSESSION/localhost/ui/nPL1hi7Yl6gh6QXewnz35w**, caller=<vrx11:33377>:25062, lock=write owner=<vrx11:33377>:25062
2006-02-24 12:38:00,712 DEBUG [org.jboss.cache.lock.IdentityLock] acquireReadLock(): caller <vrx11:33377>:25062 already owns lock for /JSESSION/localhost/ui/nPL1hi7Yl6gh6QXewnz35w**
2006-02-24 12:38:00,712 DEBUG [org.jboss.cache.Node] acquired RL: fqn=/JSESSION/localhost/ui/nPL1hi7Yl6gh6QXewnz35w**, caller=<vrx11:33377>:25062, lock=write owner=<vrx11:33377>:25062
2006-02-24 12:38:00,712 DEBUG [org.jboss.cache.TreeCache] _get("/JSESSION/localhost/ui/nPL1hi7Yl6gh6QXewnz35w**", VERSION, "true")
2006-02-24 12:38:00,734 DEBUG [org.jboss.cache.Node] acquiring WL: fqn=/JSESSION/localhost/ui/nPL1hi7Yl6gh6QXewnz35w**, caller=<vrx11:33377>:25062, lock=write owner=<vrx11:33377>:25062
2006-02-24 12:38:00,734 DEBUG [org.jboss.cache.lock.IdentityLock] acquireWriteLock(): caller already owns lock for /JSESSION/localhost/ui/nPL1hi7Yl6gh6QXewnz35w** (caller=<vrx11:33377>:25062)
2006-02-24 12:38:00,735 DEBUG [org.jboss.cache.Node] acquired WL: fqn=/JSESSION/localhost/ui/nPL1hi7Yl6gh6QXewnz35w**, caller=<vrx11:33377>:25062, lock=write owner=<vrx11:33377>:25062
2006-02-24 12:38:00,735 DEBUG [org.jboss.cache.TreeCache] _put(<vrx11:33377>:25062, "/JSESSION/localhost/ui/nPL1hi7Yl6gh6QXewnz35w**", VERSION, 2)
2006-02-24 12:38:00,735 DEBUG [org.jboss.cache.Node] acquiring RL: fqn=/JSESSION/localhost/ui/nPL1hi7Yl6gh6QXewnz35w**, caller=<vrx11:33377>:25062, lock=write owner=<vrx11:33377>:25062
2006-02-24 12:38:00,735 DEBUG [org.jboss.cache.lock.IdentityLock] acquireReadLock(): caller <vrx11:33377>:25062 already owns lock for /JSESSION/localhost/ui/nPL1hi7Yl6gh6QXewnz35w**
2006-02-24 12:38:00,736 DEBUG [org.jboss.cache.Node] acquired RL: fqn=/JSESSION/localhost/ui/nPL1hi7Yl6gh6QXewnz35w**, caller=<vrx11:33377>:25062, lock=write owner=<vrx11:33377>:25062
2006-02-24 12:38:00,736 DEBUG [org.jboss.cache.TreeCache] _get("/JSESSION/localhost/ui/nPL1hi7Yl6gh6QXewnz35w**", VERSION, "true")
2006-02-24 12:38:00,765 DEBUG [org.jboss.cache.interceptors.ReplicationInterceptor] (vrx11:33377): running remote prepare for <vrx11:33377>:25062 with async mode=true and coord=vrx11:33377 (2 modifications): [_put(<vrx11:33377>:25062, /JSESSION/localhost/ui/nPL1hi7Yl6gh6QXewnz35w**, nPL1hi7Yl6gh6QXewnz35w**, [B@5862ea, true), _put(<vrx11:33377>:25062, /JSESSION/localhost/ui/nPL1hi7Yl6gh6QXewnz35w**, VERSION, 2, true)]
2006-02-24 12:38:00,766 DEBUG [org.jboss.cache.interceptors.LockInterceptor] releasing lock for /JSESSION/localhost/ui/nPL1hi7Yl6gh6QXewnz35w** (write owner=<vrx11:33377>:25062)
2006-02-24 12:38:48,050 INFO [STDOUT] USER GOES THROUGH SECURITY CHECK session id: nPL1hi7Yl6gh6QXewnz35w** session creation time: 1140813469876, last access time: 1140813474347, max inactive interval: 3600, is new: false
2006-02-24 12:38:54,612 DEBUG [org.jboss.cache.Node] acquiring WL: fqn=/JSESSION/localhost/ui/nPL1hi7Yl6gh6QXewnz35w**, caller=<vrx11:33377>:25095, lock=
2006-02-24 12:38:54,612 DEBUG [org.jboss.cache.Node] acquired WL: fqn=/JSESSION/localhost/ui/nPL1hi7Yl6gh6QXewnz35w**, caller=<vrx11:33377>:25095, lock=write owner=<vrx11:33377>:25095
2006-02-24 12:38:54,613 DEBUG [org.jboss.cache.TreeCache] _put(<vrx11:33377>:25095, "/JSESSION/localhost/ui/nPL1hi7Yl6gh6QXewnz35w**", nPL1hi7Yl6gh6QXewnz35w**, [B@7ea58c)
2006-02-24 12:38:54,613 DEBUG [org.jboss.cache.Node] acquiring RL: fqn=/JSESSION/localhost/ui/nPL1hi7Yl6gh6QXewnz35w**, caller=<vrx11:33377>:25095, lock=write owner=<vrx11:33377>:25095
2006-02-24 12:38:54,613 DEBUG [org.jboss.cache.lock.IdentityLock] acquireReadLock(): caller <vrx11:33377>:25095 already owns lock for /JSESSION/localhost/ui/nPL1hi7Yl6gh6QXewnz35w**
2006-02-24 12:38:54,613 DEBUG [org.jboss.cache.Node] acquired RL: fqn=/JSESSION/localhost/ui/nPL1hi7Yl6gh6QXewnz35w**, caller=<vrx11:33377>:25095, lock=write owner=<vrx11:33377>:25095
2006-02-24 12:38:54,613 DEBUG [org.jboss.cache.TreeCache] _get("/JSESSION/localhost/ui/nPL1hi7Yl6gh6QXewnz35w**", VERSION, "true")
2006-02-24 12:38:54,627 DEBUG [org.jboss.cache.Node] acquiring WL: fqn=/JSESSION/localhost/ui/nPL1hi7Yl6gh6QXewnz35w**, caller=<vrx11:33377>:25095, lock=write owner=<vrx11:33377>:25095
2006-02-24 12:38:54,628 DEBUG [org.jboss.cache.lock.IdentityLock] acquireWriteLock(): caller already owns lock for /JSESSION/localhost/ui/nPL1hi7Yl6gh6QXewnz35w** (caller=<vrx11:33377>:25095)
2006-02-24 12:38:54,628 DEBUG [org.jboss.cache.Node] acquired WL: fqn=/JSESSION/localhost/ui/nPL1hi7Yl6gh6QXewnz35w**, caller=<vrx11:33377>:25095, lock=write owner=<vrx11:33377>:25095
2006-02-24 12:38:54,628 DEBUG [org.jboss.cache.TreeCache] _put(<vrx11:33377>:25095, "/JSESSION/localhost/ui/nPL1hi7Yl6gh6QXewnz35w**", VERSION, 3)
2006-02-24 12:38:54,628 DEBUG [org.jboss.cache.Node] acquiring RL: fqn=/JSESSION/localhost/ui/nPL1hi7Yl6gh6QXewnz35w**, caller=<vrx11:33377>:25095, lock=write owner=<vrx11:33377>:25095
2006-02-24 12:38:54,628 DEBUG [org.jboss.cache.lock.IdentityLock] acquireReadLock(): caller <vrx11:33377>:25095 already owns lock for /JSESSION/localhost/ui/nPL1hi7Yl6gh6QXewnz35w**
2006-02-24 12:38:54,628 DEBUG [org.jboss.cache.Node] acquired RL: fqn=/JSESSION/localhost/ui/nPL1hi7Yl6gh6QXewnz35w**, caller=<vrx11:33377>:25095, lock=write owner=<vrx11:33377>:25095
2006-02-24 12:38:54,628 DEBUG [org.jboss.cache.TreeCache] _get("/JSESSION/localhost/ui/nPL1hi7Yl6gh6QXewnz35w**", VERSION, "true")
2006-02-24 12:38:54,652 DEBUG [org.jboss.cache.interceptors.ReplicationInterceptor] (vrx11:33377): running remote prepare for <vrx11:33377>:25095 with async mode=true and coord=vrx11:33377 (2 modifications): [_put(<vrx11:33377>:25095, /JSESSION/localhost/ui/nPL1hi7Yl6gh6QXewnz35w**, nPL1hi7Yl6gh6QXewnz35w**, [B@7ea58c, true), _put(<vrx11:33377>:25095, /JSESSION/localhost/ui/nPL1hi7Yl6gh6QXewnz35w**, VERSION, 3, true)]
2006-02-24 12:38:54,653 DEBUG [org.jboss.cache.interceptors.LockInterceptor] releasing lock for /JSESSION/localhost/ui/nPL1hi7Yl6gh6QXewnz35w** (write owner=<vrx11:33377>:25095)

2006-02-24 12:38:55,112 INFO [STDOUT] USER DOES ANOTHER REQUEST session id: nPL1hi7Yl6gh6QXewnz35w** session creation time: 1140813469876, last access time: 1140813531097, max inactive interval: 3600, is new: false
2006-02-24 12:38:56,388 INFO [STDOUT] USER DOES ANOTHER REQUEST user_id: 11345, session id: nPL1hi7Yl6gh6QXewnz35w**, session creation time: 1140813469876, last access time: 1140813536204, max inactive interval: 3600, is new: false

2006-02-24 12:39:04,929 DEBUG [org.jboss.cache.Node] acquiring WL: fqn=/JSESSION/localhost/ui/nPL1hi7Yl6gh6QXewnz35w**, caller=<vrx11:33377>:25102, lock=
2006-02-24 12:39:04,929 DEBUG [org.jboss.cache.Node] acquired WL: fqn=/JSESSION/localhost/ui/nPL1hi7Yl6gh6QXewnz35w**, caller=<vrx11:33377>:25102, lock=write owner=<vrx11:33377>:25102
2006-02-24 12:39:04,929 DEBUG [org.jboss.cache.TreeCache] _put(<vrx11:33377>:25102, "/JSESSION/localhost/ui/nPL1hi7Yl6gh6QXewnz35w**", nPL1hi7Yl6gh6QXewnz35w**, [B@13a1ca1)
2006-02-24 12:39:04,930 DEBUG [org.jboss.cache.Node] acquiring RL: fqn=/JSESSION/localhost/ui/nPL1hi7Yl6gh6QXewnz35w**, caller=<vrx11:33377>:25102, lock=write owner=<vrx11:33377>:25102
2006-02-24 12:39:04,930 DEBUG [org.jboss.cache.lock.IdentityLock] acquireReadLock(): caller <vrx11:33377>:25102 already owns lock for /JSESSION/localhost/ui/nPL1hi7Yl6gh6QXewnz35w**
2006-02-24 12:39:04,930 DEBUG [org.jboss.cache.Node] acquired RL: fqn=/JSESSION/localhost/ui/nPL1hi7Yl6gh6QXewnz35w**, caller=<vrx11:33377>:25102, lock=write owner=<vrx11:33377>:25102
2006-02-24 12:39:04,930 DEBUG [org.jboss.cache.TreeCache] _get("/JSESSION/localhost/ui/nPL1hi7Yl6gh6QXewnz35w**", VERSION, "true")
2006-02-24 12:39:04,944 DEBUG [org.jboss.cache.Node] acquiring WL: fqn=/JSESSION/localhost/ui/nPL1hi7Yl6gh6QXewnz35w**, caller=<vrx11:33377>:25102, lock=write owner=<vrx11:33377>:25102
2006-02-24 12:39:04,944 DEBUG [org.jboss.cache.lock.IdentityLock] acquireWriteLock(): caller already owns lock for /JSESSION/localhost/ui/nPL1hi7Yl6gh6QXewnz35w** (caller=<vrx11:33377>:25102)
2006-02-24 12:39:04,944 DEBUG [org.jboss.cache.Node] acquired WL: fqn=/JSESSION/localhost/ui/nPL1hi7Yl6gh6QXewnz35w**, caller=<vrx11:33377>:25102, lock=write owner=<vrx11:33377>:25102
2006-02-24 12:39:04,944 DEBUG [org.jboss.cache.TreeCache] _put(<vrx11:33377>:25102, "/JSESSION/localhost/ui/nPL1hi7Yl6gh6QXewnz35w**", VERSION, 4)
2006-02-24 12:39:04,945 DEBUG [org.jboss.cache.Node] acquiring RL: fqn=/JSESSION/localhost/ui/nPL1hi7Yl6gh6QXewnz35w**, caller=<vrx11:33377>:25102, lock=write owner=<vrx11:33377>:25102
2006-02-24 12:39:04,945 DEBUG [org.jboss.cache.lock.IdentityLock] acquireReadLock(): caller <vrx11:33377>:25102 already owns lock for /JSESSION/localhost/ui/nPL1hi7Yl6gh6QXewnz35w**
2006-02-24 12:39:04,945 DEBUG [org.jboss.cache.Node] acquired RL: fqn=/JSESSION/localhost/ui/nPL1hi7Yl6gh6QXewnz35w**, caller=<vrx11:33377>:25102, lock=write owner=<vrx11:33377>:25102
2006-02-24 12:39:04,945 DEBUG [org.jboss.cache.TreeCache] _get("/JSESSION/localhost/ui/nPL1hi7Yl6gh6QXewnz35w**", VERSION, "true")
2006-02-24 12:39:04,969 DEBUG [org.jboss.cache.interceptors.ReplicationInterceptor] (vrx11:33377): running remote prepare for <vrx11:33377>:25102 with async mode=true and coord=vrx11:33377 (2 modifications): [_put(<vrx11:33377>:25102, /JSESSION/localhost/ui/nPL1hi7Yl6gh6QXewnz35w**, nPL1hi7Yl6gh6QXewnz35w**, [B@13a1ca1, true), _put(<vrx11:33377>:25102, /JSESSION/localhost/ui/nPL1hi7Yl6gh6QXewnz35w**, VERSION, 4, true)]
2006-02-24 12:39:04,970 DEBUG [org.jboss.cache.interceptors.LockInterceptor] releasing lock for /JSESSION/localhost/ui/nPL1hi7Yl6gh6QXewnz35w** (write owner=<vrx11:33377>:25102)

2006-02-24 12:39:41,157 INFO [STDOUT] USER DOES ANOTHER REQUEST session id: nPL1hi7Yl6gh6QXewnz35w**, session creation time: 1140813469876, last access time: 1140813537423, max inactive interval: 3600, is new: false
2006-02-24 12:39:49,472 DEBUG [org.jboss.cache.Node] acquiring WL: fqn=/JSESSION/localhost/ui/nPL1hi7Yl6gh6QXewnz35w**, caller=<vrx11:33377>:25132, lock=
2006-02-24 12:39:49,472 DEBUG [org.jboss.cache.Node] acquired WL: fqn=/JSESSION/localhost/ui/nPL1hi7Yl6gh6QXewnz35w**, caller=<vrx11:33377>:25132, lock=write owner=<vrx11:33377>:25132
2006-02-24 12:39:49,472 DEBUG [org.jboss.cache.TreeCache] _put(<vrx11:33377>:25132, "/JSESSION/localhost/ui/nPL1hi7Yl6gh6QXewnz35w**", nPL1hi7Yl6gh6QXewnz35w**, [B@c0a024)
2006-02-24 12:39:49,473 DEBUG [org.jboss.cache.Node] acquiring RL: fqn=/JSESSION/localhost/ui/nPL1hi7Yl6gh6QXewnz35w**, caller=<vrx11:33377>:25132, lock=write owner=<vrx11:33377>:25132
2006-02-24 12:39:49,473 DEBUG [org.jboss.cache.lock.IdentityLock] acquireReadLock(): caller <vrx11:33377>:25132 already owns lock for /JSESSION/localhost/ui/nPL1hi7Yl6gh6QXewnz35w**
2006-02-24 12:39:49,473 DEBUG [org.jboss.cache.Node] acquired RL: fqn=/JSESSION/localhost/ui/nPL1hi7Yl6gh6QXewnz35w**, caller=<vrx11:33377>:25132, lock=write owner=<vrx11:33377>:25132
2006-02-24 12:39:49,473 DEBUG [org.jboss.cache.TreeCache] _get("/JSESSION/localhost/ui/nPL1hi7Yl6gh6QXewnz35w**", VERSION, "true")
2006-02-24 12:39:49,488 DEBUG [org.jboss.cache.Node] acquiring WL: fqn=/JSESSION/localhost/ui/nPL1hi7Yl6gh6QXewnz35w**, caller=<vrx11:33377>:25132, lock=write owner=<vrx11:33377>:25132
2006-02-24 12:39:49,488 DEBUG [org.jboss.cache.lock.IdentityLock] acquireWriteLock(): caller already owns lock for /JSESSION/localhost/ui/nPL1hi7Yl6gh6QXewnz35w** (caller=<vrx11:33377>:25132)
2006-02-24 12:39:49,488 DEBUG [org.jboss.cache.Node] acquired WL: fqn=/JSESSION/localhost/ui/nPL1hi7Yl6gh6QXewnz35w**, caller=<vrx11:33377>:25132, lock=write owner=<vrx11:33377>:25132
2006-02-24 12:39:49,488 DEBUG [org.jboss.cache.TreeCache] _put(<vrx11:33377>:25132, "/JSESSION/localhost/ui/nPL1hi7Yl6gh6QXewnz35w**", VERSION, 5)
2006-02-24 12:39:49,488 DEBUG [org.jboss.cache.Node] acquiring RL: fqn=/JSESSION/localhost/ui/nPL1hi7Yl6gh6QXewnz35w**, caller=<vrx11:33377>:25132, lock=write owner=<vrx11:33377>:25132
2006-02-24 12:39:49,488 DEBUG [org.jboss.cache.lock.IdentityLock] acquireReadLock(): caller <vrx11:33377>:25132 already owns lock for /JSESSION/localhost/ui/nPL1hi7Yl6gh6QXewnz35w**
2006-02-24 12:39:49,488 DEBUG [org.jboss.cache.Node] acquired RL: fqn=/JSESSION/localhost/ui/nPL1hi7Yl6gh6QXewnz35w**, caller=<vrx11:33377>:25132, lock=write owner=<vrx11:33377>:25132
2006-02-24 12:39:49,488 DEBUG [org.jboss.cache.TreeCache] _get("/JSESSION/localhost/ui/nPL1hi7Yl6gh6QXewnz35w**", VERSION, "true")
2006-02-24 12:39:49,516 DEBUG [org.jboss.cache.interceptors.ReplicationInterceptor] (vrx11:33377): running remote prepare for <vrx11:33377>:25132 with async mode=true and coord=vrx11:33377 (2 modifications): [_put(<vrx11:33377>:25132, /JSESSION/localhost/ui/nPL1hi7Yl6gh6QXewnz35w**, nPL1hi7Yl6gh6QXewnz35w**, [B@c0a024, true), _put(<vrx11:33377>:25132, /JSESSION/localhost/ui/nPL1hi7Yl6gh6QXewnz35w**, VERSION, 5, true)]
2006-02-24 12:39:49,516 DEBUG [org.jboss.cache.interceptors.LockInterceptor] releasing lock for /JSESSION/localhost/ui/nPL1hi7Yl6gh6QXewnz35w** (write owner=<vrx11:33377>:25132)

[brian.stansberry]

Couple things I see here:

First, clearly sticky sessions aren't working right on your load balancer. Your logs show replication traffic for a session coming in, followed a couple seconds later by a local request for the same session. You've got to get sticky sessions working correctly or you'll have no end of trouble.

Second, when remove is being called on the cache, the thread that's doing it is one of the Tomcat threads -- caller=Thread[http-0.0.0.0-8080-18,5,jboss]. Remove gets called on the cache when someone calls invalidate() on the session. Most likely the code that calls invalidate on the session is yours.

If you turn on DEBUG logging for org.jboss.web.tomcat.tc5.session you'll get info from the session management layer, which is what is manipulating the cache. Maybe that will tell you something more.

[snedapunk]

Thank you, it is very nice to hear from someone from Jboss. It's been a long week and I am going crazy over here with all these huge logs. ?
I found code for new users calls session.invalidate(), and then req.getSession(true);

2006-03-03 12:22:08,703 DEBUG [org.jboss.web.tomcat.tc5.session.JBossCacheManager] Session with id=s2oijE3+vZDOUCin6JLM4g** added. Current active sessions -3821
2006-03-03 12:22:08,703 DEBUG [org.jboss.web.tomcat.tc5.session.JBossCacheManager] Creating an ClusteredSession with id: s2oijE3+vZDOUCin6JLM4g**
2006-03-03 12:22:09,803 INFO [STDOUT] Invalidate session null


2006-03-03 12:22:09,805 DEBUG [org.jboss.web.tomcat.tc5.session.ClusteredSession] The session has expired with id: s2oijE3+vZDOUCin6JLM4g** is it local? false
2006-03-03 12:22:09,805 DEBUG [org.jboss.web.tomcat.tc5.session.JBossCacheManager] Removing session from store with id: s2oijE3+vZDOUCin6JLM4g**
2006-03-03 12:22:09,805 DEBUG [org.jboss.web.tomcat.tc5.session.JBossCacheService] Remove session from distributed store. Fqn: /JSESSION/localhost/ui/s2oijE3+vZDOUCin6JLM4g**

Further notice active session count is negative. It made it to like 10 before going down. Could this be the session problem?

[snedapunk]

2006-03-03 13:56:50,837 DEBUG [org.jboss.web.tomcat.tc5.session.ClusteredSession] The session has expired with id: IL1sieE+qt58grZK1oEMAQ** is it local? true
2006-03-03 13:56:50,837 DEBUG [org.jboss.web.tomcat.tc5.session.SessionIDGenerator] getSessionId called: vuIDxYaHELqMlxsoZ0-cpA**
2006-03-03 13:56:50,837 DEBUG [org.jboss.cache.Node] acquired RL: fqn=/JSESSION, caller=<vrx13-in:33364>:24340, lock=read owners=[<vrx13-in:33364>:24340]
2006-03-03 13:56:50,837 DEBUG [org.jboss.web.tomcat.tc5.session.JBossCacheManager] Removing session from local store with id: IL1sieE+qt58grZK1oEMAQ**
2006-03-03 13:56:50,837 DEBUG [org.jboss.web.tomcat.tc5.session.JBossCacheManager] check to see if needs to store and replicate session with id vuIDxYaHELqMlxsoZ0-cpA**
2006-03-03 13:56:50,837 DEBUG [org.jboss.web.tomcat.tc5.session.JBossCacheService] Remove session from my own distributed store only. Fqn: /JSESSION/localhost/ui/IL1sieE+qt58grZK1oEMAQ**

I think I have solved this issue. When we invalidate the session, it makes the session a local session instead of a clustered session. What do you guys think?

[brian.stansberry]

The negative active session count is a bug; thanks for pointing it out. See http://jira.jboss.com/jira/browse/JBAS-2897.

When we invalidate the session, it makes the session a local session instead of a clustered session. What do you guys think?

The logging from your last post shows what happens when a session times out, rather than being invalidated via an explicit call to session.invalidate(). Are you saying you changed the session replication code so it does this now? Or you somehow tweaked your webapp so it does causes an expiration rather than an invalidation (e.g. change the session's maxInactiveInterval to 1 so it will immediately expire)?

In any case, what happens after the last log statement is the session is removed from the local cache. However, it still exists in the other cluster node's caches. So, if your user fails over to another node, they will see the old session data.

[snedapunk]

I see. In your original post, you said and someone is calling invalidate and it is probably your code. I found code in our webapp that upon every login, we call getSession(), then invalidate() and getSession again. Imagine this in the post that you first responded to, when you said someone called invalidate and is was probably your code. Do you think that this can be responsible for this behavior of the original guy getting logged out? I talked to the network guys and they say they do have sticky sessions on. They call an echo servlet every 5 seconds, and if it does not respond I think in 3 seconds they mark the machine down and this is what caused the user (above your original post) to have the machine be switched on them. They also say that the machines are flapping on and off all day long, since this request times out a lot during the day.

I also have found multiple people that generated scripts to screen scrape our website. When they do this, each hit creates a new session and our current session timeout is 1 hour. Some with multiple threads a second hitting the servers. With at most 5 machines, what do you think is the maximum number of sessions at one time can be? We have Linux 2.6.9-22, 2 gigs of memory, 4 cpu?s per machine, !386, java version 1.4.2_08-b03.

I just installed Jboss on my laptop and created a cluster with my home pc. I am turning on advanced debug, changing settings to match production, and am going to try to develop some test cases.

I am real happy that you have joined my thread. This is currently my company?s biggest bug with our on demand application and we will be loosing large dollar customers because they keep complaining that they keep getting logged out and can not work effectively. Any input is greatly appreciated.

[brian.stansberry]

How are you handling logins? Why are you calling getSession(), then invalidate() and getSession() again? Who is this "original guy" you mention, and what's the relationship with the person who just logged in?

Re: max number of sessions, assuming a sessions doesn't have a ton of data stored in it, the issue isn't really how many sessions, but how many requests are causing session replication.

We've done some benchmarks where we handled ~ 450 requests per second on a 4 node cluster using REPL_SYNC. See http://jbento.oscj.net/httpsession2.html for details. The charts on that page show ~275 per sec, but we found that by driving the test fixture harder (shorter pause between requests) we could get ~ 450/s.

[snedapunk]

Logins come in the cookie, and an Account Object is added to the session. I did not write the code, I just need to fix it.

The original guy, is the long post that shows a user getting logged out just after logging in. he is the guy that got logged out, and what this post is all about.(1 of many, but his was short)

I know that session.invalidate was called a second before he made it to the new machine. How are invalidates handled? Does a message get sent to each machine, as I see invoking method _remove. Do you think that this method since it is not repl_SYNC, could have made it late to the new machine and invalidated his valid session on this machine even though it was valid?

Also I see this alot what does it mean? Some have this every hit but very few.
2006-03-05 03:50:30,099 DEBUG [org.jboss.web.tomcat.tc5.session.JBossCacheService] nodeDirty(): session in-memory data is invalidated with id: YykGduUTfsQrdoCdLLw43A** and verion id: 13vrx11.log

Could not get that load balancer setup using the mod_jk binaries to do testing either(Jboss clustering7). It complained about a file, and google showed she same problem for all.

[snedapunk]

Check this session out I just found. There is something very wrong. What has happened here. I find no data for this session any earlier.
Machine 11 DEBUG mode, Nothing previously from any of the machine for the entire day then comes

2006-03-05 14:41:43,666 DEBUG [org.jboss.web.tomcat.tc5.session.JBossCacheManager] findSessions: find ids from cache store: [a9E3EFp4WPlcCFxPJ2tzvg**, oKmlNi7yWW8i7oi2Wuzh1g**, z6BMVJQusJImGCvyi-tL8Q**, BIntb-RT6cTqivt5JX2INw**, h9MpVJwkDRYzwRbKES+d1A**, UmMMLGvnoN-tRd36APqoVg**]
2006-03-05 14:41:43,666 DEBUG [org.jboss.web.tomcat.tc5.session.ClusteredSession] initAfterLoad(): initialize the transient variables ...
2006-03-05 14:41:43,666 DEBUG [org.jboss.web.tomcat.tc5.session.JBossCacheManager] Creating an empty ClusteredSession: SessionBasedClusteredSession[null]
2006-03-05 14:41:43,669 DEBUG [org.jboss.web.tomcat.tc5.session.JBossCacheManager] loadSession(): id= UmMMLGvnoN-tRd36APqoVg**, session=SessionBasedClusteredSession[UmMMLGvnoN-tRd36APqoVg**]
....
2006-03-05 14:41:59,985 DEBUG [org.jboss.cache.interceptors.ReplicationInterceptor] replicate(): received prepare(<vrx14-in:33060>:46931, [_put(<vrx14-in:33060>:46931, /JSESSION/localhost/ui/UmMMLGvnoN-tRd36APqoVg**, UmMMLGvnoN-tRd36APqoVg**, [B@cd45b0, true), _put(<vrx14-in:33060>:46931, /JSESSION/localhost/ui/UmMMLGvnoN-tRd36APqoVg**, VERSION, 2, true)], vrx14-in:33060, true)


Now for every hit on the other machine v14, this machine continually complains about session being dirty. He does 5 page views
2006-03-05 14:56:48,711 DEBUG [org.jboss.cache.TreeCache] _put(<vrx14-in:33060>:47034, "/JSESSION/localhost/ui/UmMMLGvnoN-tRd36APqoVg**", UmMMLGvnoN-tRd36APqoVg**, [B@166f4da)
... each line has rl stuff so I'll just omit
2006-03-05 14:56:48,712 DEBUG [org.jboss.cache.TreeCache] _get("/JSESSION/localhost/ui/UmMMLGvnoN-tRd36APqoVg**", VERSION, "true")
2006-03-05 14:56:48,729 DEBUG [org.jboss.cache.interceptors.ReplicationInterceptor] ReplicationInterceptor: won't register for TX completion as GlobalTransaction is result of a PREPARE
2006-03-05 14:56:48,729 DEBUG [org.jboss.web.tomcat.tc5.session.JBossCacheService] nodeDirty(): session in-memory data is invalidated with id: UmMMLGvnoN-tRd36APqoVg** and verion id: 6


and then this happens on 11
2006-03-05 14:59:44,508 DEBUG [org.jboss.cache.TreeCache] _get("/JSESSION/localhost/ui/UmMMLGvnoN-tRd36APqoVg**", VERSION, "true")
2006-03-05 14:59:44,525 DEBUG [org.jboss.web.tomcat.tc5.session.JBossCacheService] nodeDirty(): session in-memory data is invalidated with id: UmMMLGvnoN-tRd36APqoVg** and verion id: 12
2006-03-05 14:59:44,525 DEBUG [org.jboss.cache.interceptors.LockInterceptor] committing cache with gtx <vrx14-in:33060>:47065
2006-03-05 14:59:44,525 DEBUG [org.jboss.cache.interceptors.LockInterceptor] releasing lock for /JSESSION/localhost/ui/UmMMLGvnoN-tRd36APqoVg** (write owner=<vrx14-in:33060>:47065)
2006-03-05 14:59:44,525 DEBUG [org.jboss.cache.interceptors.LockInterceptor] releasing lock for /JSESSION/localhost/ui (read owners=[<vrx14-in:33060>:47065])
2006-03-05 14:59:44,525 DEBUG [org.jboss.cache.interceptors.LockInterceptor] releasing lock for /JSESSION/localhost (read owners=[<vrx14-in:33060>:47065])
2006-03-05 14:59:44,525 DEBUG [org.jboss.cache.interceptors.LockInterceptor] releasing lock for /JSESSION (read owners=[<vrx14-in:33060>:47065])
2006-03-05 14:59:44,525 DEBUG [org.jboss.cache.interceptors.LockInterceptor] removing local transaction TransactionImpl:XidImpl[FormatId=257, GlobalId=vrx11-in.youwish.com/7732305, BranchQual=, localId=7732305] and global transaction <vrx14-in:33060>:47065

And the users session is invalidated, and he is forced to log back on. Notice it says new. But Machine 11 continues claiming its dirty.
2006-03-05 15:14:34,361 INFO session id: UmMMLGvnoN-tRd36APqoVg**, session creation time: 1141600473527, last access time: 1141600473527, max inactive interval: 3600, is new: true

Then notice that this happens exactly one hour from loading this session, and the user is forced to log back in on v11 again as shown below as if the session timedout 1 hour inactivity.

2006-03-05 15:41:47,539 DEBUG [org.jboss.web.tomcat.tc5.session.JBossCacheManager] loadSession(): id= knQPpw24S2035C6yA7aghw**, session=null
2006-03-05 15:41:47,547 DEBUG [org.jboss.web.tomcat.tc5.session.ClusteredSession] The session has expired with id: UmMMLGvnoN-tRd36APqoVg** is it local? true
2006-03-05 15:41:47,547 DEBUG [org.jboss.web.tomcat.tc5.session.JBossCacheManager] Removing session from local store with id: UmMMLGvnoN-tRd36APqoVg**
2006-03-05 15:41:47,547 DEBUG [org.jboss.web.tomcat.tc5.session.JBossCacheService] Remove session from my own distributed store only. Fqn: /JSESSION/localhost/ui/UmMMLGvnoN-tRd36APqoVg**

15:43:33 User is forced logged out on Machine 11.
2006-03-05 15:43:49,332 DEBUG [org.jboss.web.tomcat.tc5.session.JBossCacheManager] Session with id=UmMMLGvnoN-tRd36APqoVg** added. Current active sessions -11236
2006-03-05 15:43:49,332 DEBUG [org.jboss.web.tomcat.tc5.session.JBossCacheManager] Creating an ClusteredSession with id: UmMMLGvnoN-tRd36APqoVg**
2006-03-05 15:43:49,404 INFO USER CHECKED BY session creation time: 1141602229235, last access time: 1141602229235, max inactive interval: 3600, is new: true

[nayyares]

Hi,

We are using JBoss 4.0.4GA in our production 5 servers, and having same problem of sticky session, almost same log is generated as already has been posted, what is the solution to this problem?

for now we have solved this problem with restarting cluster :(

Thanks in advance.