FailOver and Session Stickness Behaviour

[eduardo_thp]

Hi, I´ve some doubts about how the server should behave in case of a failover, and also check if there´s any configuration to change this behaviour.

My environment:
2 jboss 4.0.5 servers, (jvmRoute="tomcat1" and jvmRoute="tomcat2", useJK=true)
1 apache 2.2.8 + mod_jk 1.2.26 for load balancing

Session Stickness is working fine.

Let me describe the behaviour:

Tomcat1 up
Tomcat2 up

I login into the application, so I create a session with tomcat1 so:

Tomcat1 up (my session)
Tomcat2 up

I stop Tomcat1, Tomcat2 assumes the session correctly. [session replication is working]

Tomcat1 down
Tomcat2 up (my session)

I start Tomcat1 again, what should be the behaviour ?

Tomcat1 should get back the session from tomcat2 or not ? is it possible to configure this behaviour ?

On my tests ... after tomcat1 start up... and some clicks on the app, tomcat2 receives the first request and the others are served by tomcat 1 again..

So, tomcat1 is getting the session back. (I didn´t want this to happen, I wanted that the session stayed on tomcat2)..

I also noticed an
version id 87 matches in-memory version for session yhKzl-nQzxawhiJ9+LcfWA**
error on tomcat2, before tomcat1 starts answering the requests.....

Can anyone help me ?

Do you need more log details/config details ?

I tried the 4 different isolation levels, and the behaviour is the same...

Thanks !!!

Eduardo

[brian.stansberry]

The session should stick to Tomcat2.

Are you using URLRewriting or session cookies?

[eduardo_thp]

We don´t have URLRewriting..
But yes we have a session cookie... JSESSIONID=XXXX**.tomcatX

Do you think this could be some issue with apache/mod_jk

Thanks

[brian.stansberry]

OK, no URL rewriting shoots down one vague theory. :)

I'd be surprised if it were a mod_jk issue.

If you could enable TRACE logging of category org.jboss.web.tomcat.tc5..session, run your test, grep that category out of the server.log files and post relevant bit here, that might help.

[eduardo_thp]

First of all, thanks a lot for your help !

I tested it again, with the trace.. but I wasn't able to find out anything.

One thing that I noticed is that, this behaviour is not always the same... sometimes the session keeps with server2.

Another thing I noticed on the log is a org.jboss.cache.interceptors.TxInterceptor

I'll paste the logs, where the session changes from one server to the other.

I don't have complete control over the development... I'll check if there's the possibility of having a direct call to the servers... (do you think that could cause the problem ?)

Thanks again !!!


Server1 LOG: (This is the one that went down and was restarted)
....
2008-06-23 11:49:21,634 INFO [org.jboss.system.server.Server] JBoss (MX MicroKernel) [4.0.5.GA (build: CVSTag=Branch_4_0 date=200610162339)] Started in 1m:19s:299ms
2008-06-23 11:49:27,666 DEBUG [org.jboss.web.tomcat.tc5.session.JBossCacheManager] Looking for sessions that have expired ...
2008-06-23 11:49:37,670 DEBUG [org.jboss.web.tomcat.tc5.session.JBossCacheManager] Looking for sessions that have expired ...
2008-06-23 11:49:47,674 DEBUG [org.jboss.web.tomcat.tc5.session.JBossCacheManager] Looking for sessions that have expired ...
2008-06-23 11:49:50,298 TRACE [org.jboss.web.tomcat.tc5.session.JBossCacheManager] Checking for session 8hAMi0gD0tJfyB3cfOskYQ** in the distributed cache
2008-06-23 11:49:50,298 DEBUG [org.jboss.web.tomcat.tc5.session.JBossCacheManager] Creating an empty ClusteredSession
2008-06-23 11:49:50,338 DEBUG [org.jboss.cache.interceptors.TxInterceptor] local transaction exists - registering global tx if not present for Thread[TP-Processor3,5,jboss]
2008-06-23 11:49:50,348 DEBUG [org.jboss.cache.transaction.DummyTransaction] registering synchronization handler tx=org.jboss.cache.transaction.DummyTransaction@137008a, handlers=[]
2008-06-23 11:49:53,382 DEBUG [org.jboss.cache.interceptors.TxInterceptor] local transaction exists - registering global tx if not present for Thread[TP-Processor3,5,jboss]
2008-06-23 11:49:53,382 DEBUG [org.jboss.cache.interceptors.TxInterceptor] Transaction org.jboss.cache.transaction.DummyTransaction@137008a is already registered.
2008-06-23 11:49:53,392 DEBUG [org.jboss.cache.transaction.DummyTransaction] processing beforeCompletion for tx=org.jboss.cache.transaction.DummyTransaction@137008a, handlers=[TxInterceptor.LocalSynchronizationHandler(gtx=GlobalTransaction:<websdk-appl1:4309>:1, tx=org.jboss.cache.transaction.DummyTransaction@137008a)]
2008-06-23 11:49:53,392 DEBUG [org.jboss.cache.transaction.DummyTransaction] processing afterCompletion for tx=org.jboss.cache.transaction.DummyTransaction@137008a, handlers=[TxInterceptor.LocalSynchronizationHandler(gtx=GlobalTransaction:<websdk-appl1:4309>:1, tx=org.jboss.cache.transaction.DummyTransaction@137008a)]
2008-06-23 11:49:53,392 DEBUG [org.jboss.cache.interceptors.TxInterceptor] Running commit phase. One phase? true
2008-06-23 11:49:53,392 TRACE [org.jboss.web.tomcat.tc5.session.JBossCacheManager] Updated timestamp for unloaded session 8hAMi0gD0tJfyB3cfOskYQ**
2008-06-23 11:49:53,392 TRACE [org.jboss.web.tomcat.tc5.session.JBossCacheManager] Updated timestamp for unloaded session 8hAMi0gD0tJfyB3cfOskYQ**
2008-06-23 11:49:53,392 DEBUG [org.jboss.cache.interceptors.TxInterceptor] Finished local commit/rollback method for GlobalTransaction:<websdk-appl1:4309>:1
2008-06-23 11:49:53,392 DEBUG [org.jboss.cache.interceptors.TxInterceptor] Finished commit phase
2008-06-23 11:49:53,392 DEBUG [org.jboss.web.tomcat.tc5.session.JBossCacheManager] Session with id=8hAMi0gD0tJfyB3cfOskYQ**.tomcat2 added. Current active sessions 1
2008-06-23 11:49:53,402 DEBUG [org.jboss.web.tomcat.tc5.session.JBossCacheManager] loadSession(): id= 8hAMi0gD0tJfyB3cfOskYQ**, session=SessionBasedClusteredSession[id: 8hAMi0gD0tJfyB3cfOskYQ**.tomcat2 lastAccessedTime: 1214239593763 version: 32 lastOutdated: 0]
2008-06-23 11:49:53,402 DEBUG [org.jboss.web.tomcat.tc5.session.JvmRouteValve] checkJvmRoute(): check if need to re-route based on JvmRoute. Session id: 8hAMi0gD0tJfyB3cfOskYQ**.tomcat2 jvmRoute: tomcat1
2008-06-23 11:49:53,402 DEBUG [org.jboss.web.tomcat.tc5.session.JvmRouteValve] handleJvmRoute(): We have detected a failover with different jvmRoute. old one: tomcat2 new one: tomcat1. Will reset the session id.
2008-06-23 11:49:53,402 DEBUG [org.jboss.web.tomcat.tc5.session.JvmRouteValve] resetSessionId(): changed catalina session to= [8hAMi0gD0tJfyB3cfOskYQ**.tomcat1] old one= [8hAMi0gD0tJfyB3cfOskYQ**.tomcat2]
2008-06-23 11:49:53,402 DEBUG [org.jboss.web.tomcat.tc5.session.JBossCacheManager] Setting cookie with session id:8hAMi0gD0tJfyB3cfOskYQ**.tomcat1 & name:JSESSIONID
2008-06-23 11:49:54,103 DEBUG [org.jboss.resource.connectionmanager.IdleRemover] internalRegisterPool: registering pool with interval 300000 old interval: 9223372036854775807
2008-06-23 11:49:54,103 DEBUG [org.jboss.resource.connectionmanager.IdleRemover] internalRegisterPool: about to notify thread: old next: 1214239944103, new next: 1214239944103
2008-06-23 11:49:57,057 TRACE [org.jboss.web.tomcat.tc5.session.JBossCacheManager] check to see if needs to store and replicate session with id 8hAMi0gD0tJfyB3cfOskYQ**.tomcat1
2008-06-23 11:49:57,057 TRACE [org.jboss.web.tomcat.tc5.session.ClusteredSession] processSessionRepl(): session is dirty. Will increment version from: 32 and replicate.
2008-06-23 11:49:57,678 DEBUG [org.jboss.web.tomcat.tc5.session.JBossCacheManager] Looking for sessions that have expired ...
2008-06-23 11:49:57,688 TRACE [org.jboss.web.tomcat.tc5.session.JBossCacheService] marshalled object to size 698564 bytes
2008-06-23 11:49:58,269 TRACE [org.jboss.web.tomcat.tc5.session.CacheListener] nodeDirty(): session in-memory data is invalidated with id: 8hAMi0gD0tJfyB3cfOskYQ** and version: 35
2008-06-23 11:50:03,887 TRACE [org.jboss.web.tomcat.tc5.session.JBossCacheManager] Updating session 8hAMi0gD0tJfyB3cfOskYQ** from the distributed cache
2008-06-23 11:50:03,887 DEBUG [org.jboss.cache.interceptors.TxInterceptor] local transaction exists - registering global tx if not present for Thread[TP-Processor3,5,jboss]
2008-06-23 11:50:03,887 DEBUG [org.jboss.cache.transaction.DummyTransaction] registering synchronization handler tx=org.jboss.cache.transaction.DummyTransaction@779c66, handlers=[]
2008-06-23 11:50:03,947 TRACE [org.jboss.web.tomcat.tc5.session.JBossCacheManager] Updating session 8hAMi0gD0tJfyB3cfOskYQ** from the distributed cache
2008-06-23 11:50:04,227 DEBUG [org.jboss.cache.transaction.DummyTransaction] processing beforeCompletion for tx=org.jboss.cache.transaction.DummyTransaction@779c66, handlers=[TxInterceptor.LocalSynchronizationHandler(gtx=GlobalTransaction:<websdk-appl1:4309>:2, tx=org.jboss.cache.transaction.DummyTransaction@779c66)]
2008-06-23 11:50:04,227 DEBUG [org.jboss.cache.transaction.DummyTransaction] processing afterCompletion for tx=org.jboss.cache.transaction.DummyTransaction@779c66, handlers=[TxInterceptor.LocalSynchronizationHandler(gtx=GlobalTransaction:<websdk-appl1:4309>:2, tx=org.jboss.cache.transaction.DummyTransaction@779c66)]
2008-06-23 11:50:04,227 DEBUG [org.jboss.cache.interceptors.TxInterceptor] Running commit phase. One phase? true
2008-06-23 11:50:04,227 DEBUG [org.jboss.cache.interceptors.TxInterceptor] Finished local commit/rollback method for GlobalTransaction:<websdk-appl1:4309>:2
2008-06-23 11:50:04,227 DEBUG [org.jboss.cache.interceptors.TxInterceptor] Finished commit phase
2008-06-23 11:50:04,227 DEBUG [org.jboss.web.tomcat.tc5.session.JBossCacheManager] loadSession(): id= 8hAMi0gD0tJfyB3cfOskYQ**, session=SessionBasedClusteredSession[id: 8hAMi0gD0tJfyB3cfOskYQ**.tomcat2 lastAccessedTime: 1214239797665 version: 35 lastOutdated: 0]
2008-06-23 11:50:04,227 DEBUG [org.jboss.cache.interceptors.TxInterceptor] local transaction exists - registering global tx if not present for Thread[TP-Processor2,5,jboss]
2008-06-23 11:50:04,227 DEBUG [org.jboss.cache.transaction.DummyTransaction] registering synchronization handler tx=org.jboss.cache.transaction.DummyTransaction@1b02a96, handlers=[]
2008-06-23 11:50:04,378 DEBUG [org.jboss.web.tomcat.tc5.session.JvmRouteValve] checkJvmRoute(): check if need to re-route based on JvmRoute. Session id: 8hAMi0gD0tJfyB3cfOskYQ**.tomcat2 jvmRoute: tomcat1
2008-06-23 11:50:04,378 DEBUG [org.jboss.web.tomcat.tc5.session.JvmRouteValve] handleJvmRoute(): We have detected a failover with different jvmRoute. old one: tomcat2 new one: tomcat1. Will reset the session id.
2008-06-23 11:50:04,378 DEBUG [org.jboss.web.tomcat.tc5.session.JvmRouteValve] resetSessionId(): changed catalina session to= [8hAMi0gD0tJfyB3cfOskYQ**.tomcat1] old one= [8hAMi0gD0tJfyB3cfOskYQ**.tomcat2]
2008-06-23 11:50:04,378 DEBUG [org.jboss.web.tomcat.tc5.session.JBossCacheManager] Setting cookie with session id:8hAMi0gD0tJfyB3cfOskYQ**.tomcat1 & name:JSESSIONID
2008-06-23 11:50:05,729 DEBUG [org.jboss.cache.transaction.DummyTransaction] processing beforeCompletion for tx=org.jboss.cache.transaction.DummyTransaction@1b02a96, handlers=[TxInterceptor.LocalSynchronizationHandler(gtx=GlobalTransaction:<websdk-appl1:4309>:3, tx=org.jboss.cache.transaction.DummyTransaction@1b02a96)]
2008-06-23 11:50:05,729 DEBUG [org.jboss.cache.transaction.DummyTransaction] processing afterCompletion for tx=org.jboss.cache.transaction.DummyTransaction@1b02a96, handlers=[TxInterceptor.LocalSynchronizationHandler(gtx=GlobalTransaction:<websdk-appl1:4309>:3, tx=org.jboss.cache.transaction.DummyTransaction@1b02a96)]
2008-06-23 11:50:05,729 DEBUG [org.jboss.cache.interceptors.TxInterceptor] Running commit phase. One phase? true
2008-06-23 11:50:05,729 DEBUG [org.jboss.cache.interceptors.TxInterceptor] Finished local commit/rollback method for GlobalTransaction:<websdk-appl1:4309>:3
2008-06-23 11:50:05,729 DEBUG [org.jboss.cache.interceptors.TxInterceptor] Finished commit phase
2008-06-23 11:50:05,729 DEBUG [org.jboss.web.tomcat.tc5.session.JBossCacheManager] loadSession(): id= 8hAMi0gD0tJfyB3cfOskYQ**, session=SessionBasedClusteredSession[id: 8hAMi0gD0tJfyB3cfOskYQ**.tomcat1 lastAccessedTime: 1214239797665 version: 35 lastOutdated: 0]
2008-06-23 11:50:05,729 DEBUG [org.jboss.web.tomcat.tc5.session.JvmRouteValve] checkJvmRoute(): check if need to re-route based on JvmRoute. Session id: 8hAMi0gD0tJfyB3cfOskYQ**.tomcat1 jvmRoute: tomcat1
2008-06-23 11:50:05,770 TRACE [org.jboss.web.tomcat.tc5.session.JBossCacheManager] check to see if needs to store and replicate session with id 8hAMi0gD0tJfyB3cfOskYQ**.tomcat1
2008-06-23 11:50:05,770 TRACE [org.jboss.web.tomcat.tc5.session.ClusteredSession] processSessionRepl(): session is dirty. Will increment version from: 35 and replicate.
2008-06-23 11:50:06,050 TRACE [org.jboss.web.tomcat.tc5.session.JBossCacheService] marshalled object to size 690832 bytes
2008-06-23 11:50:06,210 TRACE [org.jboss.web.tomcat.tc5.session.JBossCacheManager] check to see if needs to store and replicate session with id 8hAMi0gD0tJfyB3cfOskYQ**.tomcat1
2008-06-23 11:50:06,210 TRACE [org.jboss.web.tomcat.tc5.session.ClusteredSession] processSessionRepl(): session is dirty. Will increment version from: 36 and replicate.
2008-06-23 11:50:06,651 TRACE [org.jboss.web.tomcat.tc5.session.JBossCacheService] marshalled object to size 690832 bytes
2008-06-23 11:50:06,891 DEBUG [org.jboss.web.tomcat.tc5.session.JvmRouteValve] checkJvmRoute(): check if need to re-route based on JvmRoute. Session id: 8hAMi0gD0tJfyB3cfOskYQ**.tomcat1 jvmRoute: tomcat1
2008-06-23 11:50:06,901 TRACE [org.jboss.web.tomcat.tc5.session.JBossCacheManager] check to see if needs to store and replicate session with id 8hAMi0gD0tJfyB3cfOskYQ**.tomcat1
2008-06-23 11:50:06,901 TRACE [org.jboss.web.tomcat.tc5.session.ClusteredSession] processSessionRepl(): session is dirty. Will increment version from: 37 and replicate.
2008-06-23 11:50:07,031 TRACE [org.jboss.web.tomcat.tc5.session.JBossCacheService] marshalled object to size 690594 bytes
....



Server2 LOG: (This is the one the should have kept the session)
....
2008-06-23 11:48:16,753 DEBUG [org.jboss.web.tomcat.tc5.session.JBossCacheManager] Looking for sessions that have expired ...
2008-06-23 11:48:26,729 DEBUG [org.jboss.web.tomcat.tc5.session.JBossCacheManager] Looking for sessions that have expired ...
2008-06-23 11:48:31,093 INFO [org.jboss.cache.TreeCache] viewAccepted(): [websdk-appl2:1589|3] [websdk-appl2:1589, websdk-appl1:4309]
2008-06-23 11:48:31,333 INFO [org.jboss.cache.TreeCache] locking the subtree at / to transfer state
2008-06-23 11:48:31,343 DEBUG [org.jboss.cache.statetransfer.StateTransferGenerator_140] generated the in-memory state (693730 bytes)
2008-06-23 11:48:31,343 DEBUG [org.jboss.cache.statetransfer.StateTransferGenerator_140] returning the associated state (4 bytes)
2008-06-23 11:48:31,343 INFO [org.jboss.cache.statetransfer.StateTransferGenerator_140] returning the state for tree rooted in /(1048576 bytes)
2008-06-23 11:48:34,778 INFO [org.jboss.ha.framework.interfaces.HAPartition.lifecycle.Siemens2Cluster] New cluster view for partition Siemens2Cluster (id: 3, delta: 1) : [161.134.71.92:26266, 161.134.71.91:26266]
2008-06-23 11:48:34,778 DEBUG [org.jboss.ha.framework.interfaces.HAPartition.Siemens2Cluster] membership changed from 2 to 2
2008-06-23 11:48:34,778 DEBUG [org.jboss.ha.framework.interfaces.HAPartition.Siemens2Cluster] Begin notifyListeners, viewID: 3
2008-06-23 11:48:34,778 INFO [org.jboss.ha.framework.server.DistributedReplicantManagerImpl.Siemens2Cluster] I am (161.134.71.92:26266) received membershipChanged event:
2008-06-23 11:48:34,778 INFO [org.jboss.ha.framework.server.DistributedReplicantManagerImpl.Siemens2Cluster] Dead members: 0 ([])
2008-06-23 11:48:34,778 INFO [org.jboss.ha.framework.server.DistributedReplicantManagerImpl.Siemens2Cluster] New Members : 1 ([161.134.71.91:26266])
2008-06-23 11:48:34,778 INFO [org.jboss.ha.framework.server.DistributedReplicantManagerImpl.Siemens2Cluster] All Members : 2 ([161.134.71.92:26266, 161.134.71.91:26266])
2008-06-23 11:48:34,778 DEBUG [org.jboss.ha.framework.interfaces.HAPartition.Siemens2Cluster] End notifyListeners, viewID: 3
2008-06-23 11:48:34,808 DEBUG [org.jboss.ha.framework.interfaces.HAPartition.Siemens2Cluster] getState called.
2008-06-23 11:48:34,808 DEBUG [org.jboss.ha.framework.interfaces.HAPartition.Siemens2Cluster] getState for DistributedReplicantManager
2008-06-23 11:48:34,808 DEBUG [org.jboss.ha.framework.interfaces.HAPartition.Siemens2Cluster] getState for HASessionStateTransfer
2008-06-23 11:48:34,808 DEBUG [org.jboss.ha.hasessionstate.server.HASessionStateImpl./HASessionState/Default] Building and returning state of HASessionState
2008-06-23 11:48:34,808 DEBUG [org.jboss.ha.framework.interfaces.HAPartition.Siemens2Cluster] getState for HAJNDI
2008-06-23 11:48:34,808 DEBUG [org.jboss.ha.framework.interfaces.HAPartition.Siemens2Cluster] getState for DistributedState
2008-06-23 11:48:35,137 DEBUG [org.jboss.ha.framework.server.HARMIServerImpl$RefreshProxiesHATarget] replicantsChanged 'HAJNDI' to 2 (intra-view id: -241862587)
2008-06-23 11:48:35,197 DEBUG [org.jboss.cache.invalidation.bridges.JGCacheInvalidationBridge] The list of replicant for the JG bridge has changed, computing and updating local info...
2008-06-23 11:48:35,197 DEBUG [org.jboss.cache.invalidation.bridges.JGCacheInvalidationBridge] ... No bridge info was associated to this node
2008-06-23 11:48:35,257 DEBUG [org.jboss.cache.invalidation.bridges.JGCacheInvalidationBridge] Updating list of invalidation groups that are bridged...
2008-06-23 11:48:35,257 DEBUG [org.jboss.cache.invalidation.bridges.JGCacheInvalidationBridge] ... nothing needs to be bridged.
2008-06-23 11:48:36,695 DEBUG [org.jboss.web.tomcat.tc5.session.JBossCacheManager] Looking for sessions that have expired ...
008-06-23 11:48:46,672 DEBUG [org.jboss.web.tomcat.tc5.session.JBossCacheManager] Looking for sessions that have expired ...
2008-06-23 11:48:56,648 DEBUG [org.jboss.web.tomcat.tc5.session.JBossCacheManager] Looking for sessions that have expired ...
2008-06-23 11:49:06,625 DEBUG [org.jboss.web.tomcat.tc5.session.JBossCacheManager] Looking for sessions that have expired ...
2008-06-23 11:49:16,591 DEBUG [org.jboss.web.tomcat.tc5.session.JBossCacheManager] Looking for sessions that have expired ...
2008-06-23 11:49:26,567 DEBUG [org.jboss.web.tomcat.tc5.session.JBossCacheManager] Looking for sessions that have expired ...
2008-06-23 11:49:31,271 DEBUG [org.jboss.resource.connectionmanager.IdleRemover] run: IdleRemover notifying pools, interval: 150000
2008-06-23 11:49:36,544 DEBUG [org.jboss.web.tomcat.tc5.session.JBossCacheManager] Looking for sessions that have expired ...
2008-06-23 11:49:46,510 DEBUG [org.jboss.web.tomcat.tc5.session.JBossCacheManager] Looking for sessions that have expired ...
2008-06-23 11:49:48,038 DEBUG [org.jboss.web.tomcat.tc5.session.JvmRouteValve] checkJvmRoute(): check if need to re-route based on JvmRoute. Session id: 8hAMi0gD0tJfyB3cfOskYQ**.tomcat2 jvmRoute: tomcat2
2008-06-23 11:49:48,048 TRACE [org.jboss.web.tomcat.tc5.session.JBossCacheManager] check to see if needs to store and replicate session with id 8hAMi0gD0tJfyB3cfOskYQ**.tomcat2
2008-06-23 11:49:48,048 TRACE [org.jboss.web.tomcat.tc5.session.ClusteredSession] processSessionRepl(): session is dirty. Will increment version from: 32 and replicate.
2008-06-23 11:49:49,207 TRACE [org.jboss.web.tomcat.tc5.session.JBossCacheService] marshalled object to size 693472 bytes
2008-06-23 11:49:50,505 DEBUG [org.jboss.web.tomcat.tc5.session.JvmRouteValve] checkJvmRoute(): check if need to re-route based on JvmRoute. Session id: 8hAMi0gD0tJfyB3cfOskYQ**.tomcat2 jvmRoute: tomcat2
2008-06-23 11:49:50,515 TRACE [org.jboss.web.tomcat.tc5.session.JBossCacheManager] check to see if needs to store and replicate session with id 8hAMi0gD0tJfyB3cfOskYQ**.tomcat2
2008-06-23 11:49:50,515 TRACE [org.jboss.web.tomcat.tc5.session.ClusteredSession] processSessionRepl(): session is dirty. Will increment version from: 33 and replicate.
2008-06-23 11:49:50,605 TRACE [org.jboss.web.tomcat.tc5.session.JBossCacheService] marshalled object to size 693234 bytes
2008-06-23 11:49:56,487 DEBUG [org.jboss.web.tomcat.tc5.session.JBossCacheManager] Looking for sessions that have expired ...
2008-06-23 11:49:57,665 DEBUG [org.jboss.web.tomcat.tc5.session.JvmRouteValve] checkJvmRoute(): check if need to re-route based on JvmRoute. Session id: 8hAMi0gD0tJfyB3cfOskYQ**.tomcat2 jvmRoute: tomcat2
2008-06-23 11:49:57,685 TRACE [org.jboss.web.tomcat.tc5.session.JBossCacheManager] check to see if needs to store and replicate session with id 8hAMi0gD0tJfyB3cfOskYQ**.tomcat2
2008-06-23 11:49:57,685 TRACE [org.jboss.web.tomcat.tc5.session.ClusteredSession] processSessionRepl(): session is dirty. Will increment version from: 34 and replicate.
2008-06-23 11:49:57,985 INFO [org.jboss.web.tomcat.tc5.session.CacheListener] Possible concurrency problem: Replicated version id 33 matches in-memory version for session 8hAMi0gD0tJfyB3cfOskYQ**
2008-06-23 11:49:57,985 TRACE [org.jboss.web.tomcat.tc5.session.JBossCacheService] marshalled object to size 690584 bytes
2008-06-23 11:50:06,223 TRACE [org.jboss.web.tomcat.tc5.session.CacheListener] nodeDirty(): session in-memory data is invalidated with id: 8hAMi0gD0tJfyB3cfOskYQ** and version: 36
2008-06-23 11:50:06,463 DEBUG [org.jboss.web.tomcat.tc5.session.JBossCacheManager] Looking for sessions that have expired ...
2008-06-23 11:50:06,723 TRACE [org.jboss.web.tomcat.tc5.session.CacheListener] nodeDirty(): session in-memory data is invalidated with id: 8hAMi0gD0tJfyB3cfOskYQ** and version: 37
2008-06-23 11:50:07,222 TRACE [org.jboss.web.tomcat.tc5.session.CacheListener] nodeDirty(): session in-memory data is invalidated with id: 8hAMi0gD0tJfyB3cfOskYQ** and version: 38
2008-06-23 11:50:07,721 TRACE [org.jboss.web.tomcat.tc5.session.CacheListener] nodeDirty(): session in-memory data is invalidated with id: 8hAMi0gD0tJfyB3cfOskYQ** and version: 39
2008-06-23 11:50:11,710 TRACE [org.jboss.web.tomcat.tc5.session.CacheListener] nodeDirty(): session in-memory data is invalidated with id: 8hAMi0gD0tJfyB3cfOskYQ** and version: 40
2008-06-23 11:50:12,100 TRACE [org.jboss.web.tomcat.tc5.session.CacheListener] nodeDirty(): session in-memory data is invalidated with id: 8hAMi0gD0tJfyB3cfOskYQ** and version: 41
2008-06-23 11:50:12,898 TRACE [org.jboss.web.tomcat.tc5.session.CacheListener] nodeDirty(): session in-memory data is invalidated with id: 8hAMi0gD0tJfyB3cfOskYQ** and version: 42
2008-06-23 11:50:15,715 DEBUG [org.jboss.web.tomcat.tc5.session.JBossCacheManager] Looking for sessions that have expired ...
2008-06-23 11:50:25,691 DEBUG [org.jboss.web.tomcat.tc5.session.JBossCacheManager] Looking for sessions that have expired ...
2008-06-23 11:50:26,690 TRACE [org.jboss.web.tomcat.tc5.session.CacheListener] nodeDirty(): session in-memory data is invalidated with id: 8hAMi0gD0tJfyB3cfOskYQ** and version: 43
2008-06-23 11:50:28,218 TRACE [org.jboss.web.tomcat.tc5.session.CacheListener] nodeDirty(): session in-memory data is invalidated with id: 8hAMi0gD0tJfyB3cfOskYQ** and version: 44
....

[eduardo_thp]

It must be some issue with the session cookie !

I was tracing JK log... and saw that even setting the new route on the cookie, JK still identifies the last rout on the requests...

I'll keep testing.. I won't post the log here as it's too big...

anyway.. thanks for the help !!!

[brian.stansberry]

Yes, it sounds like my "I'd be surprised if it were a mod_jk issue" was hasty. Your logs show the JBoss-side session management code doing what it's supposed to -- the session has .tomcat2 appended, but a request goes to tomcat1 anyway. And then .tomcat1 does what it's supposed to do and changes the appended jvmRoute to tomcat1.

So yeah, looking through the JK logs is the way to go.

[eduardo_thp]

Hi..

Do you have any information of any problems to reset the JSESSIONID cookie, when there´s a pushlet running ?

The thing is I have a pushlet running, when server1 goes down and server2 assumes, the pushlet is the 1st request answered by server2, and this is the request that resets the Session cookie...

But, for the browser it is as if the pushlet hadn´t been disconnected, so it ignores the headers.

Have you ever heard about something like that ? Do you recommend any solution for that ?

Thanks !

[brian.stansberry]

But, for the browser it is as if the pushlet hadn´t been disconnected, so it ignores the headers.

Are you saying the presence of httpd as a proxy in the middle is masking the failure of server1 from the browser; the browser thinks the existing connection to server1 is maintained?

E.g.:

browser makes request to httpd
httpd makes request to server1
browser-to-httpd and httpd-to-server1 connections stay open as server1 pushes data
server1 fails, so httpd-to-server1 connection fails
mod_jk sees the original request is still open, so fails over to server2: httpd-to-server2 connection opened. browser is oblivious to this
server2 sends a new cookie header
browser isn't expecting more headers, so ignores that

[eduardo_thp]

That's it !

It's possible to see it, because the 2 html results are concatenated..

The results from the pushlet that was on server1.. are still at the beginning of the HTML, then there are the contents from the pushlet that is on server2.

It's as if the loadbalancer(mod_jk) x browser connection stays alive, eventhough loadbalancer x server1 connection goes down.

eg.
&#60;html>&#60;head>
&#60;script type="text/javascript" src="file.js" >&#60;/script>
&#60;/head>
&#60;body>&#60;/body>&#60;/html>
&#60;script>parent.setServerName('server1');&#60;/script>
&#60;script language='javascript'>event(.....);&#60;/script>
&#60;script language='javascript'>event(.....);&#60;/script>
&#60;script language='javascript'>event(.....);&#60;/script>
&#60;html>&#60;head>
&#60;script type="text/javascript" src="file.js" >&#60;/script>
&#60;/head>
&#60;body>&#60;/body>&#60;/html>
&#60;script>parent.setServerName('server2');&#60;/script>
&#60;script language='javascript'>event(.....);&#60;/script>
&#60;script language='javascript'>event(.....);&#60;/script>
&#60;script language='javascript'>event(.....);&#60;/script>

[brian.stansberry]

Have a look at http://tomcat.apache.org/connectors-doc/reference/workers.html, particularly the recovery_options parameter. You can try setting it to 1 or 2, which should cause the server1 failure to propagate to the browser instead of failing over.

[eduardo_thp]

Excelent ! It now worked as I expected !

I hadn't noticed this option there !!!

Thanks very much for the help !