[GERONIMO-2577] Geronimo cluster (Tomcat Version)cannot continue the HttpSession when current node is down.

• Type: Bug
• Status: Open
• Priority: Major
• Resolution: Unresolved
• Affects Version/s: 1.1, 1.1.1
• Component/s: Clustering, Tomcat
• Security Level: public (Regular issues)

Environment

JDK - Sun java version "1_5_0_09"(32bit)
OS- Red Hat Enterprise Linux ES4 update4(32bit)
Http Server - Apache 2.0.59 +mod_jk 1.2.19

• Assignee: Unassigned
• Reporter: Kaoru Matsumura
• Created: 17/Nov/06 12:27
• Updated: 16/Feb/07 04:54

Description

We run Geronimo cluster with three nodes.
In our environment, with DeltaManager set for replication module, we found that the last node cound not continue the processes when the other nodes is intentionally halted in order.

We recognize Tomcat 5.5.15 is OK with the same configuration and operations.

Test Application
================
The Web application program, which was used for the test, simply reads the number of access count, and then write the count to HttpSession object.

Configuration?Files
==================
We refer http://cwiki.apache.org/GMOxDOC11/clustering-sample-application.html

• config.xml
  We add the following parameters to the standard configuration.

<gbean name="TomcatEngine">
<attribute name="initParams">name=Geronimo
jvmRoute=nodeA</attribute>
</gbean>

Operations
===============
1 Have browser access to Test Application , and reload several times.(*1) HttpSession object is created on the nodeA.
2 And then, We kill the process of geronimo on the nodeA with $kill -9 <Process ID>.(*2)
3 Reload the browser at one time. The node changes to nodeB.(*3)
4 Reload the browser several times.(*4)
5 And then, We kill the process of geronimo on the nodeB with $kill -9 <Process ID>.(*5)
6 Reload the browser at one time.(And then, We expect that the process continues at the nodeC.)
But the HttpSessionID of the HttpSession object is changed to another ID and the counter value is back to 1.(*6)
As a result, the geronimo cluster cannot continue the process.

For avoidance
===============
When replication module is SimpleTcpReplicationManager, the geronimo cluster can continue the process.

Debug levels logs
==================
(*1)
nodeA
----------
20:06:17,736 DEBUG [CoyoteAdapter] Requested cookie session id is 7160C8614D20687D3548E8488AB65AC3.nodeA
20:06:17,736 DEBUG [JvmRouteBinderValve] Found Cluster DeltaManager org.apache.catalina.cluster.session.DeltaManager@2cb491 at /ClusterCheck
20:06:17,736 DEBUG [JvmRouteBinderValve] Turnover Check time 0 msec
20:06:17,737 DEBUG [MsgContext] COMMIT
20:06:17,737 DEBUG [JkInputStream] COMMIT sending headers org.apache.coyote.Response@118994d === MimeHeaders ===

20:06:17,737 DEBUG [MsgContext] CLOSE
20:06:17,738 DEBUG [REQ_TIME] Time pre=0/ service=2 242 /ClusterCheck/counter
20:06:17,738 DEBUG [ReplicationValve] Invoking replication request on /ClusterCheck/counter
20:06:17,738 DEBUG [DeltaManager] Manager [/ClusterCheck]: create session message [7160C8614D20687D3548E8488AB65AC3.nodeA] delta request.
20:06:17,757 DEBUG [McastService] Mcast receive ping from member org.apache.catalina.cluster.mcast.McastMember[tcp://192.168.1.3:4001,catalina,192.168.1.3,4001, alive=58960]
-----------

nodeC
-----------
20:06:17,655 DEBUG [SimpleTcpCluster] Assuming clocks are synched: Replication for 7160C8614D20687D3548E8488AB65AC3.nodeA-1162811177738 took=-83 ms.
20:06:17,655 DEBUG [DeltaManager] Manager [/ClusterCheck]: Received SessionMessage of type=(SESSION-DELTA) from [org.apache.catalina.cluster.mcast.McastMember[tcp://192.168.1.1:4001,catalina,192.168.1.1,4001, alive=130441]]
20:06:17,655 DEBUG [DeltaManager] Manager [/ClusterCheck]: received session [7160C8614D20687D3548E8488AB65AC3.nodeA] delta.
-----------

(*2)
nodeB (same as nodeC)
-----------
20:06:39,817 INFO [SimpleTcpCluster] Received member disappeared:org.apache.catalina.cluster.mcast.McastMember[tcp://192.168.1.1:4001,catalina,192.168.1.1,4001, alive=149288]
20:06:39,818 DEBUG [MapperListener] Handle geronimo:type=IDataSender,senderAddress=192.168.1.1,senderPort=4001 type : JMX.mbean.unregistered
20:06:39,818 DEBUG [MapperListener] Handle geronimo:type=IDataSender,senderAddress=192.168.1.1,senderPort=4001 type : JMX.mbean.unregistered
20:06:39,818 DEBUG [MapperListener] Handle geronimo:type=IDataSender,senderAddress=192.168.1.1,senderPort=4001 type : JMX.mbean.unregistered
20:06:39,818 DEBUG [DataSender] Sender close socket to [192.168.1.1:4,001] (close count 1)
20:06:39,818 DEBUG [DataSender] Sender disconnect from [192.168.1.1:4,001] (disconnect count 1)
----------

(*3)
nodeB
---------------
20:06:40,640 DEBUG [CoyoteAdapter] Requested cookie session id is 7160C8614D20687D3548E8488AB65AC3.nodeA
20:06:40,641 DEBUG [JvmRouteBinderValve] Found Cluster DeltaManager org.apache.catalina.cluster.session.DeltaManager@16d383a at /ClusterCheck
20:06:40,641 DEBUG [JvmRouteBinderValve] Detected a failover with different jvmRoute - orginal route: [nodeA] new one: [nodeB] at session id [7160C8614D20687D3548E8488AB65AC3.nodeA]
20:06:40,641 DEBUG [JvmRouteBinderValve] Found Cluster DeltaManager org.apache.catalina.cluster.session.DeltaManager@16d383a at /ClusterCheck
20:06:40,642 DEBUG [JvmRouteBinderValve] Setting cookie with session id [7160C8614D20687D3548E8488AB65AC3.nodeB] name: [JSESSIONID] path: [/ClusterCheck] secure: [false]
20:06:40,643 DEBUG [JvmRouteBinderValve] Set Orginal Session id at request attriute org.apache.catalina.cluster.session.JvmRouteOrignalSessionID value: 7160C8614D20687D3548E8488AB65AC3.nodeA
20:06:40,648 DEBUG [DataSender] Create sender [/192.168.1.3:4,001]
20:06:40,650 DEBUG [DataSender] Sender open socket to [192.168.1.3:4,001] (open count 1)
20:06:40,663 DEBUG [JvmRouteBinderValve] Changed session from [7160C8614D20687D3548E8488AB65AC3.nodeA] to [7160C8614D20687D3548E8488AB65AC3.nodeB]
--------------

nodeC
--------------
20:06:40,572 DEBUG [SimpleTcpCluster] Assuming clocks are synched: Replication for 7160C8614D20687D3548E8488AB65AC3.nodeA##localhost##/ClusterCheck##0##1162811200571 took=-72 ms.
20:06:40,580 DEBUG [SimpleTcpCluster] Message org.apache.catalina.cluster.session.SessionIDMessage@128ccdf from type org.apache.catalina.cluster.session.SessionIDMessage transfered but no listener registered
20:06:40,652 DEBUG [SimpleTcpCluster] Assuming clocks are synched: Replication for 7160C8614D20687D3548E8488AB65AC3.nodeB-1162811200691 took=-39 ms.
20:06:40,652 DEBUG [DeltaManager] Manager [/ClusterCheck]: Received SessionMessage of type=(SESSION-DELTA) from [org.apache.catalina.cluster.mcast.McastMember[tcp://192.168.1.2:4001,catalina,192.168.1.2,4001, alive=113760]]
--------------

(*4)
nodeB
---------------
20:06:43,677 DEBUG [CoyoteAdapter] Requested cookie session id is 7160C8614D20687D3548E8488AB65AC3.nodeB
20:06:43,677 DEBUG [JvmRouteBinderValve] Found Cluster DeltaManager org.apache.catalina.cluster.session.DeltaManager@16d383a at /ClusterCheck
20:06:43,677 DEBUG [JvmRouteBinderValve] Turnover Check time 0 msec
20:06:43,678 DEBUG [MsgContext] COMMIT
20:06:43,678 DEBUG [JkInputStream] COMMIT sending headers org.apache.coyote.Response@11e2b21 === MimeHeaders ===

20:06:43,678 DEBUG [MsgContext] CLOSE
20:06:43,678 DEBUG [REQ_TIME] Time pre=0/ service=1 242 /ClusterCheck/counter
20:06:43,679 DEBUG [ReplicationValve] Invoking replication request on /ClusterCheck/counter
20:06:43,679 DEBUG [DeltaManager] Manager [/ClusterCheck]: create session message [7160C8614D20687D3548E8488AB65AC3.nodeB] delta request.
20:06:43,721 DEBUG [HandlerRequest] Invoke returned 0
---------------

nodeC
---------------
20:06:43,637 DEBUG [SimpleTcpCluster] Assuming clocks are synched: Replication for 7160C8614D20687D3548E8488AB65AC3.nodeB-1162811203679 took=-42 ms.
20:06:43,637 DEBUG [DeltaManager] Manager [/ClusterCheck]: Received SessionMessage of type=(SESSION-DELTA) from [org.apache.catalina.cluster.mcast.McastMember[tcp://192.168.1.2:4001,catalina,192.168.1.2,4001, alive=116748]]
---------------

(*5)
nodeC
---------------
20:07:03,844 INFO [SimpleTcpCluster] Received member disappeared:org.apache.catalina.cluster.mcast.McastMember[tcp://192.168.1.2:4001,catalina,192.168.1.2,4001, alive=133704]
---------------

(*6)
nodeC
---------------
20:07:04,950 DEBUG [CoyoteAdapter] Requested cookie session id is 7160C8614D20687D3548E8488AB65AC3.nodeB
20:07:04,950 DEBUG [StandardWrapper] Allocating non-STM instance
20:07:04,976 DEBUG [DeltaManager] Created a DeltaSession with Id [E5F29B4F1C7F849618B4442076B84DB1.nodeC] Total count=2
20:07:04,983 DEBUG [MsgContext] COMMIT
20:07:04,985 DEBUG [JkInputStream] COMMIT sending headers org.apache.coyote.Response@1222045 === MimeHeaders ===
Set-Cookie = JSESSIONID=E5F29B4F1C7F849618B4442076B84DB1.nodeC; Path=/ClusterCheck

20:07:04,986 DEBUG [MsgContext] CLOSE
---------------