You are viewing a plain text version of this content. The canonical link for it is here.
Posted to users@tomcat.apache.org by Nir A <ni...@netomedia.com> on 2013/12/16 18:01:19 UTC
Tomcat Clustering - when the tomcat instances are on different machines
Hi,
We started working on our next generation platform project.
One of our requirement is to have session replication via tomcat clustering.
We have managed to set up a cluster with replication when the tomcats
(7.0.47) were both on the SAME machine as a POC.
Now as we are setting up the production configuration... (one tomcat is on
server "10.0.110.44" and the other "10.0.110.45")
We are having the following issues:
*When we try to configure the both tomcats with the delta manager, we use
this server.xml in both of them:*
.. / default configuration here ../
<Host name="localhost" appBase="webapps"
unpackWARs="true" autoDeploy="true">
<Cluster className="org.apache.catalina.ha.tcp.SimpleTcpCluster"
channelSendOptions="6">
<Manager className="org.apache.catalina.ha.session.DeltaManager"
expireSessionsOnShutdown="false"
notifyListenersOnReplication="true"/>
<Channel
className="org.apache.catalina.tribes.group.GroupChannel">
<Membership
className="org.apache.catalina.tribes.membership.McastService"
address="228.0.0.4"
port="45564"
frequency="500"
dropTime="3000"/>
<Receiver
className="org.apache.catalina.tribes.transport.nio.NioReceiver"
address="auto"
port="5000"
selectorTimeout="100"
maxThreads="6"/>
<Sender
className="org.apache.catalina.tribes.transport.ReplicationTransmitter">
<Transport
className="org.apache.catalina.tribes.transport.nio.PooledParallelSender"/>
</Sender>
<Interceptor
className="org.apache.catalina.tribes.group.interceptors.TcpFailureDetector"/>
<Interceptor
className="org.apache.catalina.tribes.group.interceptors.MessageDispatch15Interceptor"/>
<Interceptor
className="org.apache.catalina.tribes.group.interceptors.ThroughputInterceptor"/>
</Channel>
<Valve className="org.apache.catalina.ha.tcp.ReplicationValve"
filter=".*\.gif|.*\.js|.*\.jpeg|.*\.jpg|.*\.png|.*\.htm|.*\.html|.*\.css|.*\.txt"/>
<Deployer
className="org.apache.catalina.ha.deploy.FarmWarDeployer"
tempDir="/tmp/war-temp/"
deployDir="/tmp/war-deploy/"
watchDir="/tmp/war-listen/"
watchEnabled="false"/>
<ClusterListener
className="org.apache.catalina.ha.session.ClusterSessionListener"/>
</Cluster>
<Valve className="org.apache.catalina.valves.AccessLogValve"
directory="logs"
prefix="localhost_access_log." suffix=".txt"
pattern="%h %l %u %t "%r" %s %b" />
</Host>
*This configuration fails to replicate sessions and the error we get in the
logs :*
INFO: Cluster is about to start
Dec 16, 2013 6:42:26 PM org.apache.catalina.tribes.transport.ReceiverBase
bind
INFO: Receiver Server Socket bound to:/127.0.1.1:5000
Dec 16, 2013 6:42:26 PM
org.apache.catalina.tribes.membership.McastServiceImpl setupSocket
INFO: Setting cluster mcast soTimeout to 500
Dec 16, 2013 6:42:26 PM
org.apache.catalina.tribes.membership.McastServiceImpl waitForMembers
INFO: Sleeping for 1000 milliseconds to establish cluster membership, start
level:4
Dec 16, 2013 6:42:27 PM org.apache.catalina.ha.tcp.SimpleTcpCluster
memberAdded
INFO: Replication member
added:org.apache.catalina.tribes.membership.MemberImpl[tcp://{127, 0, 1,
1}:5000,{127, 0, 1, 1},5000, alive=2516, securePort=-1, UDP Port=-1,
id={-90 41 -113 110 96 -50 78 -88 -79 -103 1 61 -60 -125 75 44 },
payload={}, command={}, domain={}, ]
Dec 16, 2013 6:42:27 PM org.apache.catalina.tribes.io.BufferPool
getBufferPool
INFO: Created a buffer pool with max size:104857600 bytes of
type:org.apache.catalina.tribes.io.BufferPool15Impl
Dec 16, 2013 6:42:27 PM
org.apache.catalina.tribes.membership.McastServiceImpl waitForMembers
INFO: Done sleeping, membership established, start level:4
Dec 16, 2013 6:42:27 PM
org.apache.catalina.tribes.membership.McastServiceImpl waitForMembers
INFO: Sleeping for 1000 milliseconds to establish cluster membership, start
level:8
Dec 16, 2013 6:42:28 PM
org.apache.catalina.tribes.membership.McastServiceImpl waitForMembers
INFO: Done sleeping, membership established, start level:8
Dec 16, 2013 6:42:28 PM org.apache.catalina.ha.deploy.FarmWarDeployer start
INFO: Cluster FarmWarDeployer started.
Dec 16, 2013 6:42:28 PM org.apache.catalina.startup.HostConfig deployWAR
INFO: Deploying web application archive
/usr/local/tomcat7/apache-tomcat-7.0.47/webapps/HATest.war
Dec 16, 2013 6:42:29 PM org.apache.catalina.ha.session.DeltaManager
startInternal
INFO: Register manager /HATest to cluster element Host with name localhost
Dec 16, 2013 6:42:29 PM org.apache.catalina.ha.session.DeltaManager
startInternal
INFO: Starting clustering manager at /HATest
Dec 16, 2013 6:42:29 PM
org.apache.catalina.tribes.group.interceptors.ThroughputInterceptor report
INFO: ThroughputInterceptor Report[
Tx Msg:1 messages
Sent:0.00 MB (total)
Sent:0.00 MB (application)
Time:0.01 seconds
Tx Speed:0.04 MB/sec (total)
TxSpeed:0.04 MB/sec (application)
Error Msg:0
Rx Msg:2 messages
Rx Speed:0.00 MB/sec (since 1st msg)
Received:0.00 MB]
Dec 16, 2013 6:42:29 PM org.apache.catalina.ha.session.DeltaManager
getAllClusterSessions
INFO: Manager [/HATest], requesting session state from
org.apache.catalina.tribes.membership.MemberImpl[tcp://{127, 0, 1,
1}:5000,{127, 0, 1, 1},5000, alive=4517, securePort=-1, UDP Port=-1,
id={-90 41 -113 110 96 -50 78 -88 -79 -103 1 61 -60 -125 75 44 },
payload={}, command={}, domain={}, ]. This operation will timeout if no
session state has been received within 60 seconds.
Dec 16, 2013 6:43:29 PM org.apache.catalina.ha.session.DeltaManager
waitForSendAllSessions
SEVERE: Manager [/HATest]: No session state send at 12/16/13 6:42 PM
received, timing out after 60,102 ms.
Dec 16, 2013 6:43:29 PM org.apache.catalina.ha.session.DeltaManager
getAllClusterSessions
WARNING: Manager [/HATest]: Drop message SESSION-GET-ALL inside
GET_ALL_SESSIONS sync phase start date 12/16/13 6:42 PM message date 1/1/70
2:00 AM
Dec 16, 2013 6:43:29 PM org.apache.catalina.startup.HostConfig
deployDirectory
INFO: Deploying web application directory
/usr/local/tomcat7/apache-tomcat-7.0.47/webapps/docs
Dec 16, 2013 6:43:29 PM org.apache.catalina.startup.HostConfig
deployDirectory
INFO: Deploying web application directory
/usr/local/tomcat7/apache-tomcat-7.0.47/webapps/host-manager
Dec 16, 2013 6:43:29 PM org.apache.catalina.startup.HostConfig
deployDirectory
INFO: Deploying web application directory
/usr/local/tomcat7/apache-tomcat-7.0.47/webapps/ROOT
Dec 16, 2013 6:43:29 PM org.apache.catalina.startup.HostConfig
deployDirectory
INFO: Deploying web application directory
/usr/local/tomcat7/apache-tomcat-7.0.47/webapps/examples
Dec 16, 2013 6:43:30 PM org.apache.catalina.startup.HostConfig
deployDirectory
INFO: Deploying web application directory
/usr/local/tomcat7/apache-tomcat-7.0.47/webapps/manager
Dec 16, 2013 6:43:30 PM org.apache.catalina.ha.session.DeltaManager
startInternal
INFO: Register manager /manager to cluster element Host with name localhost
Dec 16, 2013 6:43:30 PM org.apache.catalina.ha.session.DeltaManager
startInternal
INFO: Starting clustering manager at /manager
Dec 16, 2013 6:43:30 PM org.apache.catalina.ha.session.DeltaManager
getAllClusterSessions
INFO: Manager [/manager], requesting session state from
org.apache.catalina.tribes.membership.MemberImpl[tcp://{127, 0, 1,
1}:5000,{127, 0, 1, 1},5000, alive=65057, securePort=-1, UDP Port=-1,
id={-90 41 -113 110 96 -50 78 -88 -79 -103 1 61 -60 -125 75 44 },
payload={}, command={}, domain={}, ]. This operation will timeout if no
session state has been received within 60 seconds.
Dec 16, 2013 6:44:16 PM
org.apache.catalina.tribes.group.interceptors.TcpFailureDetector
memberDisappeared
INFO: Verification complete. Member
disappeared[org.apache.catalina.tribes.membership.MemberImpl[tcp://{127, 0,
1, 1}:5000,{127, 0, 1, 1},5000, alive=112037, securePort=-1, UDP Port=-1,
id={-90 41 -113 110 96 -50 78 -88 -79 -103 1 61 -60 -125 75 44 },
payload={}, command={66 65 66 89 45 65 76 69 88 ...(9)}, domain={}, ]]
Dec 16, 2013 6:44:16 PM org.apache.catalina.ha.tcp.SimpleTcpCluster
memberDisappeared
INFO: Received member
disappeared:org.apache.catalina.tribes.membership.MemberImpl[tcp://{127, 0,
1, 1}:5000,{127, 0, 1, 1},5000, alive=112037, securePort=-1, UDP Port=-1,
id={-90 41 -113 110 96 -50 78 -88 -79 -103 1 61 -60 -125 75 44 },
payload={}, command={66 65 66 89 45 65 76 69 88 ...(9)}, domain={}, ]
Dec 16, 2013 6:44:22 PM org.apache.catalina.ha.tcp.SimpleTcpCluster
memberAdded
INFO: Replication member
added:org.apache.catalina.tribes.membership.MemberImpl[tcp://{127, 0, 1,
1}:5000,{127, 0, 1, 1},5000, alive=1014, securePort=-1, UDP Port=-1, id={75
3 86 -1 25 78 67 111 -125 -65 74 58 79 -20 93 16 }, payload={}, command={},
domain={}, ]
Dec 16, 2013 6:44:30 PM org.apache.catalina.ha.session.DeltaManager
waitForSendAllSessions
SEVERE: Manager [/manager]: No session state send at 12/16/13 6:43 PM
received, timing out after 60,081 ms.
Dec 16, 2013 6:44:30 PM org.apache.catalina.ha.session.DeltaManager
getAllClusterSessions
WARNING: Manager [/manager]: Drop message SESSION-GET-ALL inside
GET_ALL_SESSIONS sync phase start date 12/16/13 6:43 PM message date 1/1/70
2:00 AM
Dec 16, 2013 6:44:30 PM org.apache.coyote.AbstractProtocol start
INFO: Starting ProtocolHandler ["http-bio-8080"]
Dec 16, 2013 6:44:30 PM org.apache.coyote.AbstractProtocol start
INFO: Starting ProtocolHandler ["ajp-bio-8009"]
Dec 16, 2013 6:44:30 PM org.apache.catalina.startup.Catalina start
INFO: Server startup in 123619 ms
*When we try to configure the Backup manager (which is my goal actually)
with the same server.xml only with backup manager tag:*
<Manager className="org.apache.catalina.ha.session.BackupManager"
expireSessionsOnShutdown="false"
notifyListenersOnReplication="true"
mapSendOptions="6"/>
*We get the following log (again, no replication):*
INFO: Cluster is about to start
Dec 16, 2013 6:56:40 PM org.apache.catalina.tribes.transport.ReceiverBase
bind
INFO: Receiver Server Socket bound to:/127.0.1.1:5000
Dec 16, 2013 6:56:40 PM
org.apache.catalina.tribes.membership.McastServiceImpl setupSocket
INFO: Setting cluster mcast soTimeout to 500
Dec 16, 2013 6:56:40 PM
org.apache.catalina.tribes.membership.McastServiceImpl waitForMembers
INFO: Sleeping for 1000 milliseconds to establish cluster membership, start
level:4
Dec 16, 2013 6:56:40 PM org.apache.catalina.ha.tcp.SimpleTcpCluster
memberAdded
INFO: Replication member
added:org.apache.catalina.tribes.membership.MemberImpl[tcp://{127, 0, 1,
1}:5000,{127, 0, 1, 1},5000, alive=23027, securePort=-1, UDP Port=-1,
id={52 -40 0 -117 -60 82 71 -42 -110 21 -91 -16 88 -96 -46 -113 },
payload={}, command={}, domain={}, ]
Dec 16, 2013 6:56:41 PM org.apache.catalina.tribes.io.BufferPool
getBufferPool
INFO: Created a buffer pool with max size:104857600 bytes of
type:org.apache.catalina.tribes.io.BufferPool15Impl
Dec 16, 2013 6:56:41 PM
org.apache.catalina.tribes.membership.McastServiceImpl waitForMembers
INFO: Done sleeping, membership established, start level:4
Dec 16, 2013 6:56:41 PM
org.apache.catalina.tribes.membership.McastServiceImpl waitForMembers
INFO: Sleeping for 1000 milliseconds to establish cluster membership, start
level:8
Dec 16, 2013 6:56:42 PM
org.apache.catalina.tribes.membership.McastServiceImpl waitForMembers
INFO: Done sleeping, membership established, start level:8
Dec 16, 2013 6:56:42 PM org.apache.catalina.ha.deploy.FarmWarDeployer start
INFO: Cluster FarmWarDeployer started.
Dec 16, 2013 6:56:42 PM org.apache.catalina.startup.HostConfig deployWAR
INFO: Deploying web application archive
/usr/local/tomcat7/apache-tomcat-7.0.47/webapps/HATest.war
Dec 16, 2013 6:56:43 PM
org.apache.catalina.tribes.tipis.AbstractReplicatedMap init
INFO: Initializing AbstractReplicatedMap with context name:/HATest-map
Dec 16, 2013 6:56:43 PM
org.apache.catalina.tribes.group.interceptors.ThroughputInterceptor report
INFO: ThroughputInterceptor Report[
Tx Msg:1 messages
Sent:0.00 MB (total)
Sent:0.00 MB (application)
Time:0.01 seconds
Tx Speed:0.09 MB/sec (total)
TxSpeed:0.09 MB/sec (application)
Error Msg:0
Rx Msg:2 messages
Rx Speed:0.00 MB/sec (since 1st msg)
Received:0.00 MB]
Dec 16, 2013 6:56:43 PM org.apache.catalina.startup.HostConfig
deployDirectory
INFO: Deploying web application directory
/usr/local/tomcat7/apache-tomcat-7.0.47/webapps/docs
Dec 16, 2013 6:56:43 PM org.apache.catalina.startup.HostConfig
deployDirectory
INFO: Deploying web application directory
/usr/local/tomcat7/apache-tomcat-7.0.47/webapps/host-manager
Dec 16, 2013 6:56:43 PM org.apache.catalina.startup.HostConfig
deployDirectory
INFO: Deploying web application directory
/usr/local/tomcat7/apache-tomcat-7.0.47/webapps/ROOT
Dec 16, 2013 6:56:43 PM org.apache.catalina.startup.HostConfig
deployDirectory
INFO: Deploying web application directory
/usr/local/tomcat7/apache-tomcat-7.0.47/webapps/examples
Dec 16, 2013 6:56:44 PM org.apache.catalina.startup.HostConfig
deployDirectory
INFO: Deploying web application directory
/usr/local/tomcat7/apache-tomcat-7.0.47/webapps/manager
Dec 16, 2013 6:56:44 PM
org.apache.catalina.tribes.tipis.AbstractReplicatedMap init
INFO: Initializing AbstractReplicatedMap with context name:/manager-map
Dec 16, 2013 6:56:44 PM org.apache.coyote.AbstractProtocol start
INFO: Starting ProtocolHandler ["http-bio-8080"]
Dec 16, 2013 6:56:44 PM org.apache.coyote.AbstractProtocol start
INFO: Starting ProtocolHandler ["ajp-bio-8009"]
Dec 16, 2013 6:56:44 PM org.apache.catalina.startup.Catalina start
INFO: Server startup in 3535 ms
*It appears there are no severe errors on the log file with the backup
manager setup, but still we got no replication going.*
*Of course we added the *<distributable/>
*tag to both our web.xml of the tomcats AND for the WAR's web.xml as well.*
*Any ideas why this is happening? *
Regards and many thanks,
NGT.
Re: Tomcat Clustering - when the tomcat instances are on different machines
Posted by Keiichi Fujino <kf...@apache.org>.
In order to trace create session completely, it was necessary that changing
log level of LazyReplicatedMap. (sorry about that.)
However this log indicates that session replication works.
For example.
Dec 17, 2013 1:52:21 PM
> org.apache.catalina.tribes.tipis.AbstractReplicatedMap messageReceived
> FINER: Map message received from:tcp://{127, 0, 1, 1}:5000
> msg:MapMessage[context=/HATest-map; type=MSG_BACKUP;
> key=69713914F61869565FF52E909EDB7C1C;
> value=DeltaSession[69713914F61869565FF52E909EDB7C1C]
>
This log means that tc1 received session replication
message(type=MSG_BACKUP) from tc2.
session Id is 69713914F61869565FF52E909EDB7C1C.
> Dec 17, 2013 1:52:21 PM
> org.apache.catalina.tribes.tipis.AbstractReplicatedMap replicate
> FINER: Replicate invoked on key:69713914F61869565FF52E909EDB7C1C
>
>
This log means that tc1 replicate session attribute to tc2.
sesison Id is 69713914F61869565FF52E909EDB7C1C.
--
Keiichi.Fujino
Re: Tomcat Clustering - when the tomcat instances are on different machines
Posted by Nir A <ni...@netomedia.com>.
Here is a full scenario:
1) Both tomcats are down
2) starting up tc1:
Dec 17, 2013 1:49:31 PM org.apache.catalina.core.AprLifecycleListener init
INFO: The APR based Apache Tomcat Native library which allows optimal
performance in production environments was not found on the
java.library.path: /usr/java/packages/lib/amd64:/usr/lib/jni:/lib:/usr/lib
Dec 17, 2013 1:49:31 PM org.apache.coyote.AbstractProtocol init
INFO: Initializing ProtocolHandler ["http-bio-8080"]
Dec 17, 2013 1:49:31 PM org.apache.coyote.AbstractProtocol init
INFO: Initializing ProtocolHandler ["ajp-bio-8009"]
Dec 17, 2013 1:49:31 PM org.apache.catalina.startup.Catalina load
INFO: Initialization processed in 782 ms
Dec 17, 2013 1:49:31 PM org.apache.catalina.core.StandardService
startInternal
INFO: Starting service Catalina
Dec 17, 2013 1:49:31 PM org.apache.catalina.core.StandardEngine
startInternal
INFO: Starting Servlet Engine: Apache Tomcat/7.0.47
Dec 17, 2013 1:49:31 PM org.apache.catalina.ha.tcp.SimpleTcpCluster
startInternal
INFO: Cluster is about to start
Dec 17, 2013 1:49:31 PM org.apache.catalina.tribes.transport.ReceiverBase
bind
INFO: Receiver Server Socket bound to:/127.0.1.1:5000
Dec 17, 2013 1:49:31 PM
org.apache.catalina.tribes.membership.McastServiceImpl setupSocket
INFO: Setting cluster mcast soTimeout to 500
Dec 17, 2013 1:49:31 PM
org.apache.catalina.tribes.membership.McastServiceImpl waitForMembers
INFO: Sleeping for 1000 milliseconds to establish cluster membership, start
level:4
Dec 17, 2013 1:49:32 PM
org.apache.catalina.tribes.membership.McastServiceImpl waitForMembers
INFO: Done sleeping, membership established, start level:4
Dec 17, 2013 1:49:32 PM
org.apache.catalina.tribes.membership.McastServiceImpl waitForMembers
INFO: Sleeping for 1000 milliseconds to establish cluster membership, start
level:8
Dec 17, 2013 1:49:33 PM
org.apache.catalina.tribes.membership.McastServiceImpl waitForMembers
INFO: Done sleeping, membership established, start level:8
Dec 17, 2013 1:49:33 PM org.apache.catalina.ha.deploy.FarmWarDeployer start
INFO: Cluster FarmWarDeployer started.
Dec 17, 2013 1:49:33 PM org.apache.catalina.startup.HostConfig deployWAR
INFO: Deploying web application archive
/usr/local/tomcat7/apache-tomcat-7.0.47/webapps/HATest.war
Dec 17, 2013 1:49:34 PM
org.apache.catalina.tribes.tipis.AbstractReplicatedMap init
INFO: Initializing AbstractReplicatedMap with context name:/HATest-map
Dec 17, 2013 1:49:34 PM
org.apache.catalina.tribes.tipis.AbstractReplicatedMap init
FINER: Created Lazy Map with name:/HATest-map, bytes:{47, 72, 65, 84, 101,
115, 116, 45, 109, 97, 112}
Dec 17, 2013 1:49:34 PM org.apache.catalina.startup.HostConfig
deployDirectory
INFO: Deploying web application directory
/usr/local/tomcat7/apache-tomcat-7.0.47/webapps/docs
Dec 17, 2013 1:49:34 PM org.apache.catalina.startup.HostConfig
deployDirectory
INFO: Deploying web application directory
/usr/local/tomcat7/apache-tomcat-7.0.47/webapps/host-manager
Dec 17, 2013 1:49:34 PM org.apache.catalina.startup.HostConfig
deployDirectory
INFO: Deploying web application directory
/usr/local/tomcat7/apache-tomcat-7.0.47/webapps/ROOT
Dec 17, 2013 1:49:34 PM org.apache.catalina.startup.HostConfig
deployDirectory
INFO: Deploying web application directory
/usr/local/tomcat7/apache-tomcat-7.0.47/webapps/examples
Dec 17, 2013 1:49:35 PM org.apache.catalina.startup.HostConfig
deployDirectory
INFO: Deploying web application directory
/usr/local/tomcat7/apache-tomcat-7.0.47/webapps/manager
Dec 17, 2013 1:49:35 PM org.apache.coyote.AbstractProtocol start
INFO: Starting ProtocolHandler ["http-bio-8080"]
Dec 17, 2013 1:49:35 PM org.apache.coyote.AbstractProtocol start
INFO: Starting ProtocolHandler ["ajp-bio-8009"]
Dec 17, 2013 1:49:35 PM org.apache.catalina.startup.Catalina start
INFO: Server startup in 3608 ms
3) Starting up tc2:
tc2 log:
Dec 17, 2013 1:50:59 PM org.apache.catalina.core.AprLifecycleListener init
INFO: The APR based Apache Tomcat Native library which allows optimal
performance in production environments was not found on the
java.library.path: /usr/java/packages/lib/amd64:/usr/lib/jni:/lib:/usr/lib
Dec 17, 2013 1:51:00 PM org.apache.coyote.AbstractProtocol init
INFO: Initializing ProtocolHandler ["http-bio-8080"]
Dec 17, 2013 1:51:00 PM org.apache.coyote.AbstractProtocol init
INFO: Initializing ProtocolHandler ["ajp-bio-8009"]
Dec 17, 2013 1:51:00 PM org.apache.catalina.startup.Catalina load
INFO: Initialization processed in 777 ms
Dec 17, 2013 1:51:00 PM org.apache.catalina.core.StandardService
startInternal
INFO: Starting service Catalina
Dec 17, 2013 1:51:00 PM org.apache.catalina.core.StandardEngine
startInternal
INFO: Starting Servlet Engine: Apache Tomcat/7.0.47
Dec 17, 2013 1:51:00 PM org.apache.catalina.ha.tcp.SimpleTcpCluster
startInternal
INFO: Cluster is about to start
Dec 17, 2013 1:51:00 PM org.apache.catalina.tribes.transport.ReceiverBase
bind
INFO: Receiver Server Socket bound to:/127.0.1.1:5000
Dec 17, 2013 1:51:00 PM
org.apache.catalina.tribes.membership.McastServiceImpl setupSocket
INFO: Setting cluster mcast soTimeout to 500
Dec 17, 2013 1:51:00 PM
org.apache.catalina.tribes.membership.McastServiceImpl waitForMembers
INFO: Sleeping for 1000 milliseconds to establish cluster membership, start
level:4
Dec 17, 2013 1:51:00 PM org.apache.catalina.ha.tcp.SimpleTcpCluster
memberAdded
INFO: Replication member
added:org.apache.catalina.tribes.membership.MemberImpl[tcp://{127, 0, 1,
1}:5000,{127, 0, 1, 1},5000, alive=88573, securePort=-1, UDP Port=-1,
id={-17 33 93 -21 86 85 69 -11 -92 -85 44 7 10 121 -40 21 }, payload={},
command={}, domain={}, ]
Dec 17, 2013 1:51:00 PM org.apache.catalina.tribes.io.BufferPool
getBufferPool
INFO: Created a buffer pool with max size:104857600 bytes of
type:org.apache.catalina.tribes.io.BufferPool15Impl
Dec 17, 2013 1:51:01 PM
org.apache.catalina.tribes.membership.McastServiceImpl waitForMembers
INFO: Done sleeping, membership established, start level:4
Dec 17, 2013 1:51:01 PM
org.apache.catalina.tribes.membership.McastServiceImpl waitForMembers
INFO: Sleeping for 1000 milliseconds to establish cluster membership, start
level:8
Dec 17, 2013 1:51:02 PM
org.apache.catalina.tribes.membership.McastServiceImpl waitForMembers
INFO: Done sleeping, membership established, start level:8
Dec 17, 2013 1:51:02 PM org.apache.catalina.ha.deploy.FarmWarDeployer start
INFO: Cluster FarmWarDeployer started.
Dec 17, 2013 1:51:02 PM org.apache.catalina.startup.HostConfig deployWAR
INFO: Deploying web application archive
/usr/local/tomcat7/apache-tomcat-7.0.47/webapps/HATest.war
Dec 17, 2013 1:51:02 PM
org.apache.catalina.tribes.tipis.AbstractReplicatedMap init
INFO: Initializing AbstractReplicatedMap with context name:/HATest-map
Dec 17, 2013 1:51:02 PM
org.apache.catalina.tribes.tipis.AbstractReplicatedMap init
FINER: Created Lazy Map with name:/HATest-map, bytes:{47, 72, 65, 84, 101,
115, 116, 45, 109, 97, 112}
Dec 17, 2013 1:51:02 PM
org.apache.catalina.tribes.group.interceptors.ThroughputInterceptor report
INFO: ThroughputInterceptor Report[
Tx Msg:1 messages
Sent:0.00 MB (total)
Sent:0.00 MB (application)
Time:0.01 seconds
Tx Speed:0.07 MB/sec (total)
TxSpeed:0.07 MB/sec (application)
Error Msg:0
Rx Msg:2 messages
Rx Speed:0.00 MB/sec (since 1st msg)
Received:0.00 MB]
Dec 17, 2013 1:51:02 PM
org.apache.catalina.tribes.tipis.AbstractReplicatedMap messageReceived
FINER: Map[/HATest-map] received message:MapMessage[context=/HATest-map;
type=MSG_INIT; key=null; value=null
Dec 17, 2013 1:51:02 PM
org.apache.catalina.tribes.tipis.AbstractReplicatedMap messageReceived
FINER: Map message received from:tcp://{127, 0, 1, 1}:5000
msg:MapMessage[context=/HATest-map; type=MSG_INIT; key=null; value=null
Dec 17, 2013 1:51:02 PM
org.apache.catalina.tribes.tipis.AbstractReplicatedMap messageReceived
FINER: Map[/HATest-map] received message:MapMessage[context=/HATest-map;
type=MSG_START; key=null; value=null
Dec 17, 2013 1:51:02 PM
org.apache.catalina.tribes.tipis.AbstractReplicatedMap messageReceived
FINER: Map message received from:tcp://{127, 0, 1, 1}:5000
msg:MapMessage[context=/HATest-map; type=MSG_START; key=null; value=null
Dec 17, 2013 1:51:02 PM org.apache.catalina.startup.HostConfig
deployDirectory
INFO: Deploying web application directory
/usr/local/tomcat7/apache-tomcat-7.0.47/webapps/docs
Dec 17, 2013 1:51:03 PM org.apache.catalina.startup.HostConfig
deployDirectory
INFO: Deploying web application directory
/usr/local/tomcat7/apache-tomcat-7.0.47/webapps/host-manager
Dec 17, 2013 1:51:03 PM org.apache.catalina.startup.HostConfig
deployDirectory
INFO: Deploying web application directory
/usr/local/tomcat7/apache-tomcat-7.0.47/webapps/ROOT
Dec 17, 2013 1:51:03 PM org.apache.catalina.startup.HostConfig
deployDirectory
INFO: Deploying web application directory
/usr/local/tomcat7/apache-tomcat-7.0.47/webapps/examples
Dec 17, 2013 1:51:03 PM org.apache.catalina.startup.HostConfig
deployDirectory
INFO: Deploying web application directory
/usr/local/tomcat7/apache-tomcat-7.0.47/webapps/manager
Dec 17, 2013 1:51:03 PM org.apache.coyote.AbstractProtocol start
INFO: Starting ProtocolHandler ["http-bio-8080"]
Dec 17, 2013 1:51:03 PM org.apache.coyote.AbstractProtocol start
INFO: Starting ProtocolHandler ["ajp-bio-8009"]
Dec 17, 2013 1:51:03 PM org.apache.catalina.startup.Catalina start
INFO: Server startup in 3600 ms
tc1 log:
Dec 17, 2013 1:51:01 PM org.apache.catalina.ha.tcp.SimpleTcpCluster
memberAdded
INFO: Replication member
added:org.apache.catalina.tribes.membership.MemberImpl[tcp://{127, 0, 1,
1}:5000,{127, 0, 1, 1},5000, alive=1016, securePort=-1, UDP Port=-1, id={4
-36 -108 -26 115 -100 72 -58 -122 -54 -89 67 -117 -43 -45 -100 },
payload={}, command={}, domain={}, ]
Dec 17, 2013 1:51:01 PM org.apache.catalina.tribes.io.BufferPool
getBufferPool
INFO: Created a buffer pool with max size:104857600 bytes of
type:org.apache.catalina.tribes.io.BufferPool15Impl
Dec 17, 2013 1:51:03 PM
org.apache.catalina.tribes.group.interceptors.ThroughputInterceptor report
INFO: ThroughputInterceptor Report[
Tx Msg:1 messages
Sent:0.00 MB (total)
Sent:0.00 MB (application)
Time:0.01 seconds
Tx Speed:0.08 MB/sec (total)
TxSpeed:0.08 MB/sec (application)
Error Msg:0
Rx Msg:1 messages
Rx Speed:0.00 MB/sec (since 1st msg)
Received:0.00 MB]
4) creating a session on tc1:
tc1 log:
c 17, 2013 1:52:21 PM
org.apache.catalina.tribes.tipis.AbstractReplicatedMap get
FINER: Requesting id:C30A9ECB97450A2D989C5B9A475B7817 entry:null
Dec 17, 2013 1:52:21 PM
org.apache.catalina.tribes.tipis.AbstractReplicatedMap get
FINER: Requesting id:C30A9ECB97450A2D989C5B9A475B7817 entry:null
Dec 17, 2013 1:52:21 PM
org.apache.catalina.tribes.tipis.AbstractReplicatedMap get
FINER: Requesting id:C30A9ECB97450A2D989C5B9A475B7817 entry:null
Dec 17, 2013 1:52:21 PM
org.apache.catalina.tribes.tipis.AbstractReplicatedMap accept
FINER: Map[/HATest-map] accepting....MapMessage[context=/HATest-map;
type=MSG_BACKUP; key=null; value=null
Dec 17, 2013 1:52:21 PM
org.apache.catalina.tribes.tipis.AbstractReplicatedMap accept
FINER: Msg[/HATest-map] accepted[true]....MapMessage[context=/HATest-map;
type=MSG_BACKUP; key=null; value=null
Dec 17, 2013 1:52:21 PM
org.apache.catalina.tribes.tipis.AbstractReplicatedMap messageReceived
FINER: Map[/HATest-map] received message:MapMessage[context=/HATest-map;
type=MSG_BACKUP; key=null; value=null
Dec 17, 2013 1:52:21 PM
org.apache.catalina.tribes.tipis.AbstractReplicatedMap messageReceived
FINER: Map message received from:tcp://{127, 0, 1, 1}:5000
msg:MapMessage[context=/HATest-map; type=MSG_BACKUP;
key=69713914F61869565FF52E909EDB7C1C;
value=DeltaSession[69713914F61869565FF52E909EDB7C1C]
Dec 17, 2013 1:52:21 PM
org.apache.catalina.tribes.tipis.AbstractReplicatedMap replicate
FINER: Replicate invoked on key:69713914F61869565FF52E909EDB7C1C
Dec 17, 2013 1:52:21 PM
org.apache.catalina.tribes.tipis.AbstractReplicatedMap accept
FINER: Map[/HATest-map] accepting....MapMessage[context=/HATest-map;
type=MSG_BACKUP; key=null; value=null
Dec 17, 2013 1:52:21 PM
org.apache.catalina.tribes.tipis.AbstractReplicatedMap accept
FINER: Msg[/HATest-map] accepted[true]....MapMessage[context=/HATest-map;
type=MSG_BACKUP; key=null; value=null
Dec 17, 2013 1:52:21 PM
org.apache.catalina.tribes.tipis.AbstractReplicatedMap messageReceived
FINER: Map[/HATest-map] received message:MapMessage[context=/HATest-map;
type=MSG_BACKUP; key=null; value=null
Dec 17, 2013 1:52:21 PM
org.apache.catalina.tribes.tipis.AbstractReplicatedMap messageReceived
FINER: Map message received from:tcp://{127, 0, 1, 1}:5000
msg:MapMessage[context=/HATest-map; type=MSG_BACKUP;
key=69713914F61869565FF52E909EDB7C1C; value=null
tc2 log:
NO CHANGE.
P.S when we try to create a new session on tc2 the outcome is exactly like
stage 3)
Thanks,
On Tue, Dec 17, 2013 at 1:31 PM, Keiichi Fujino <kf...@apache.org> wrote:
> 2013/12/17 Nir A <ni...@netomedia.com>
>
> > In the tomcat manager We can see that our web application called "HATest"
> > is having the sessions.
> > Its a small demo of a shopping cart that keeps the items in the session.
> >
> > here is an example of a session we created in on of the tomcats nodes:
> >
> > Details for Session 33265A9C6318C014ADA92220A76F566C Session Id
> > 33265A9C6318C014ADA92220A76F566C Guessed Locale
> > Guessed User
> > Creation Time 2013-12-17 11:56:07 Last Accessed Time 2013-12-17
> > 12:01:13 Session
> > Max Inactive Interval 00:30:00 Used Time 00:05:06 Inactive Time
> 00:00:02
> > TTL 00:29:57
> > 1 attributes Remove Attribute Attribute name Attribute value
> >
> > Books [my book!, Some other book]
> >
> >
> >
> Does this say that there is only one session?
> You said "We have 3 sessions currently: one on node-1 and 2 on node-2" on
> previous mail.
> In other words, do you say that manager app should display 3 sessions (both
> primary and backup) ?
>
>
> >
> > In our previous POC where all instances were local we had this exact
> > session replication.
> > We could see on the manager of instance 2 that a new "Backup" session is
> > created (replicated) right after the creation of a new session in
> instance
> > 1..
> >
> > 1) is it possible to get some more logging info from anywhere?
> > 2) How come when i create a new session in an instance we dont see in the
> > catalina.log another message being fired to update?
> >
> >
> If you change log level of AbstractReplicatedMap, you can trace the session
> replication of BackupManager.
>
> e.g. logging.propertie
> java.util.logging.ConsoleHandler.level = FINEST
> org.apache.catalina.tribes.tipis.AbstractReplicatedMap.level = FINEST
>
>
>
>
>
> > Thanks again,
> >
> >
> >
> > On Tue, Dec 17, 2013 at 11:54 AM, Keiichi Fujino <kf...@apache.org>
> > wrote:
> >
> > > It seems that there is no problem.
> > > Initialization of AbstractReplicatedMap seems to work correctly.
> > >
> > >
> > >
> > > >
> > > > We have 3 sessions currently: one on node-1 and 2 on node-2 but there
> > are
> > > > only primary sessions on each (3) and not backup sessions at all.
> what
> > > > could be the problem?
> > > >
> > > >
> > > How did you confirm this?
> > > please show more detail.
> > >
> > >
> > >
> > > > On Tue, Dec 17, 2013 at 10:25 AM, Keiichi Fujino <kfujino@apache.org
> >
> > > > wrote:
> > > >
> > > > > DeltaManager starts session sync phase by sending a SESSION-GET-ALL
> > > > message
> > > > > at startup.
> > > > > DeltaManager that has received the SESSION-GET-ALL message sends
> all
> > > > > session data by sending a ALL-SESSION-DATA message.
> > > > > Then sends a SESSION-STATE-TRANSFERED message in order to notify
> the
> > > > > transmission completion.
> > > > > DeltaManager that has received the SESSION-STATE-TRANSFERED message
> > > > > completes session sync phase.
> > > > >
> > > > >
> > > > > According to this log,
> > > > >
> > > > >
> > > > >
> > > > > > Dec 16, 2013 6:43:29 PM
> org.apache.catalina.ha.session.DeltaManager
> > > > > > waitForSendAllSessions
> > > > > > SEVERE: Manager [/HATest]: No session state send at 12/16/13 6:42
> > PM
> > > > > > received, timing out after 60,102 ms.
> > > > > >
> > > > >
> > > > > This log means that time-out occurred in session sync phase.
> (Default
> > > 60
> > > > > seconds)
> > > > >
> > > > > and
> > > > >
> > > > >
> > > > >
> > > > > > Dec 16, 2013 6:43:29 PM
> org.apache.catalina.ha.session.DeltaManager
> > > > > > getAllClusterSessions
> > > > > > WARNING: Manager [/HATest]: Drop message SESSION-GET-ALL inside
> > > > > > GET_ALL_SESSIONS sync phase start date 12/16/13 6:42 PM message
> > date
> > > > > 1/1/70
> > > > > > 2:00 AM
> > > > > >
> > > > >
> > > > > This log means that SESSION-GET-ALL message that received during
> > > session
> > > > > sync phase is dropped.
> > > > >
> > > > > Thus, It seems that two nodes were started at the same time.
> > > > > If SESSION-GET-ALL message is dropped, SESSION-STATE-TRANSFERED
> > message
> > > > can
> > > > > not be received.
> > > > > As a result, will be time-out in session sync phase.
> > > > >
> > > > > You should start Tomcat in proper order (rather than
> simultaneously).
> > > > >
> > > > > Another problem.
> > > > > In warning log, time stamp of the SESSION-GET-ALL messages that
> were
> > > > > dropped has become to 1/1/70.
> > > > > This is just a trivial bug.
> > > > > I will fix this later.
> > > > > That way, the correct time stamp will be output.
> > > > >
> > > > >
> > > > >
> > > > >
> > > > > > Dec 16, 2013 6:43:29 PM org.apache.catalina.startup.HostConfig
> > > > > > deployDirectory
> > > > > > INFO: Deploying web application directory
> > > > > > /usr/local/tomcat7/apache-tomcat-7.0.47/webapps/docs
> > > > > > Dec 16, 2013 6:43:29 PM org.apache.catalina.startup.HostConfig
> > > > > > deployDirectory
> > > > > > INFO: Deploying web application directory
> > > > > > /usr/local/tomcat7/apache-tomcat-7.0.47/webapps/host-manager
> > > > > > Dec 16, 2013 6:43:29 PM org.apache.catalina.startup.HostConfig
> > > > > > deployDirectory
> > > > > > INFO: Deploying web application directory
> > > > > > /usr/local/tomcat7/apache-tomcat-7.0.47/webapps/ROOT
> > > > > > Dec 16, 2013 6:43:29 PM org.apache.catalina.startup.HostConfig
> > > > > > deployDirectory
> > > > > > INFO: Deploying web application directory
> > > > > > /usr/local/tomcat7/apache-tomcat-7.0.47/webapps/examples
> > > > > > Dec 16, 2013 6:43:30 PM org.apache.catalina.startup.HostConfig
> > > > > > deployDirectory
> > > > > > INFO: Deploying web application directory
> > > > > > /usr/local/tomcat7/apache-tomcat-7.0.47/webapps/manager
> > > > > > Dec 16, 2013 6:43:30 PM
> org.apache.catalina.ha.session.DeltaManager
> > > > > > startInternal
> > > > > > INFO: Register manager /manager to cluster element Host with name
> > > > > localhost
> > > > > > Dec 16, 2013 6:43:30 PM
> org.apache.catalina.ha.session.DeltaManager
> > > > > > startInternal
> > > > > > INFO: Starting clustering manager at /manager
> > > > > > Dec 16, 2013 6:43:30 PM
> org.apache.catalina.ha.session.DeltaManager
> > > > > > getAllClusterSessions
> > > > > > INFO: Manager [/manager], requesting session state from
> > > > > > org.apache.catalina.tribes.membership.MemberImpl[tcp://{127, 0,
> 1,
> > > > > > 1}:5000,{127, 0, 1, 1},5000, alive=65057, securePort=-1, UDP
> > Port=-1,
> > > > > > id={-90 41 -113 110 96 -50 78 -88 -79 -103 1 61 -60 -125 75 44 },
> > > > > > payload={}, command={}, domain={}, ]. This operation will timeout
> > if
> > > no
> > > > > > session state has been received within 60 seconds.
> > > > > > Dec 16, 2013 6:44:16 PM
> > > > > > org.apache.catalina.tribes.group.interceptors.TcpFailureDetector
> > > > > > memberDisappeared
> > > > > > INFO: Verification complete. Member
> > > > > >
> > > >
> > disappeared[org.apache.catalina.tribes.membership.MemberImpl[tcp://{127,
> > > > > 0,
> > > > > > 1, 1}:5000,{127, 0, 1, 1},5000, alive=112037, securePort=-1, UDP
> > > > Port=-1,
> > > > > > id={-90 41 -113 110 96 -50 78 -88 -79 -103 1 61 -60 -125 75 44 },
> > > > > > payload={}, command={66 65 66 89 45 65 76 69 88 ...(9)},
> domain={},
> > > ]]
> > > > > > Dec 16, 2013 6:44:16 PM
> org.apache.catalina.ha.tcp.SimpleTcpCluster
> > > > > > memberDisappeared
> > > > > > INFO: Received member
> > > > > >
> > > >
> > disappeared:org.apache.catalina.tribes.membership.MemberImpl[tcp://{127,
> > > > > 0,
> > > > > > 1, 1}:5000,{127, 0, 1, 1},5000, alive=112037, securePort=-1, UDP
> > > > Port=-1,
> > > > > > id={-90 41 -113 110 96 -50 78 -88 -79 -103 1 61 -60 -125 75 44 },
> > > > > > payload={}, command={66 65 66 89 45 65 76 69 88 ...(9)},
> > domain={}, ]
> > > > > > Dec 16, 2013 6:44:22 PM
> org.apache.catalina.ha.tcp.SimpleTcpCluster
> > > > > > memberAdded
> > > > > > INFO: Replication member
> > > > > >
> added:org.apache.catalina.tribes.membership.MemberImpl[tcp://{127,
> > 0,
> > > > 1,
> > > > > > 1}:5000,{127, 0, 1, 1},5000, alive=1014, securePort=-1, UDP
> > Port=-1,
> > > > > id={75
> > > > > > 3 86 -1 25 78 67 111 -125 -65 74 58 79 -20 93 16 }, payload={},
> > > > > command={},
> > > > > > domain={}, ]
> > > > > > Dec 16, 2013 6:44:30 PM
> org.apache.catalina.ha.session.DeltaManager
> > > > > > waitForSendAllSessions
> > > > > > SEVERE: Manager [/manager]: No session state send at 12/16/13
> 6:43
> > PM
> > > > > > received, timing out after 60,081 ms.
> > > > > > Dec 16, 2013 6:44:30 PM
> org.apache.catalina.ha.session.DeltaManager
> > > > > > getAllClusterSessions
> > > > > > WARNING: Manager [/manager]: Drop message SESSION-GET-ALL inside
> > > > > > GET_ALL_SESSIONS sync phase start date 12/16/13 6:43 PM message
> > date
> > > > > 1/1/70
> > > > > > 2:00 AM
> > > > > > Dec 16, 2013 6:44:30 PM org.apache.coyote.AbstractProtocol start
> > > > > > INFO: Starting ProtocolHandler ["http-bio-8080"]
> > > > > > Dec 16, 2013 6:44:30 PM org.apache.coyote.AbstractProtocol start
> > > > > > INFO: Starting ProtocolHandler ["ajp-bio-8009"]
> > > > > > Dec 16, 2013 6:44:30 PM org.apache.catalina.startup.Catalina
> start
> > > > > > INFO: Server startup in 123619 ms
> > > > > >
> > > > > >
> > > > > >
> > > > > >
> > > > > >
> > > > > > *When we try to configure the Backup manager (which is my goal
> > > > actually)
> > > > > > with the same server.xml only with backup manager tag:*
> > > > > > <Manager
> className="org.apache.catalina.ha.session.BackupManager"
> > > > > > expireSessionsOnShutdown="false"
> > > > > > notifyListenersOnReplication="true"
> > > > > > mapSendOptions="6"/>
> > > > > >
> > > > > >
> > > > > > *We get the following log (again, no replication):*
> > > > > >
> > > > > >
> > > > > > INFO: Cluster is about to start
> > > > > > Dec 16, 2013 6:56:40 PM
> > > > org.apache.catalina.tribes.transport.ReceiverBase
> > > > > > bind
> > > > > > INFO: Receiver Server Socket bound to:/127.0.1.1:5000
> > > > > > Dec 16, 2013 6:56:40 PM
> > > > > > org.apache.catalina.tribes.membership.McastServiceImpl
> setupSocket
> > > > > > INFO: Setting cluster mcast soTimeout to 500
> > > > > > Dec 16, 2013 6:56:40 PM
> > > > > > org.apache.catalina.tribes.membership.McastServiceImpl
> > waitForMembers
> > > > > > INFO: Sleeping for 1000 milliseconds to establish cluster
> > membership,
> > > > > start
> > > > > > level:4
> > > > > > Dec 16, 2013 6:56:40 PM
> org.apache.catalina.ha.tcp.SimpleTcpCluster
> > > > > > memberAdded
> > > > > > INFO: Replication member
> > > > > >
> added:org.apache.catalina.tribes.membership.MemberImpl[tcp://{127,
> > 0,
> > > > 1,
> > > > > > 1}:5000,{127, 0, 1, 1},5000, alive=23027, securePort=-1, UDP
> > Port=-1,
> > > > > > id={52 -40 0 -117 -60 82 71 -42 -110 21 -91 -16 88 -96 -46 -113
> },
> > > > > > payload={}, command={}, domain={}, ]
> > > > > > Dec 16, 2013 6:56:41 PM org.apache.catalina.tribes.io.BufferPool
> > > > > > getBufferPool
> > > > > > INFO: Created a buffer pool with max size:104857600 bytes of
> > > > > > type:org.apache.catalina.tribes.io.BufferPool15Impl
> > > > > > Dec 16, 2013 6:56:41 PM
> > > > > > org.apache.catalina.tribes.membership.McastServiceImpl
> > waitForMembers
> > > > > > INFO: Done sleeping, membership established, start level:4
> > > > > > Dec 16, 2013 6:56:41 PM
> > > > > > org.apache.catalina.tribes.membership.McastServiceImpl
> > waitForMembers
> > > > > > INFO: Sleeping for 1000 milliseconds to establish cluster
> > membership,
> > > > > start
> > > > > > level:8
> > > > > > Dec 16, 2013 6:56:42 PM
> > > > > > org.apache.catalina.tribes.membership.McastServiceImpl
> > waitForMembers
> > > > > > INFO: Done sleeping, membership established, start level:8
> > > > > > Dec 16, 2013 6:56:42 PM
> > org.apache.catalina.ha.deploy.FarmWarDeployer
> > > > > start
> > > > > > INFO: Cluster FarmWarDeployer started.
> > > > > > Dec 16, 2013 6:56:42 PM org.apache.catalina.startup.HostConfig
> > > > deployWAR
> > > > > > INFO: Deploying web application archive
> > > > > > /usr/local/tomcat7/apache-tomcat-7.0.47/webapps/HATest.war
> > > > > > Dec 16, 2013 6:56:43 PM
> > > > > > org.apache.catalina.tribes.tipis.AbstractReplicatedMap init
> > > > > > INFO: Initializing AbstractReplicatedMap with context
> > > name:/HATest-map
> > > > > > Dec 16, 2013 6:56:43 PM
> > > > > >
> org.apache.catalina.tribes.group.interceptors.ThroughputInterceptor
> > > > > report
> > > > > > INFO: ThroughputInterceptor Report[
> > > > > > Tx Msg:1 messages
> > > > > > Sent:0.00 MB (total)
> > > > > > Sent:0.00 MB (application)
> > > > > > Time:0.01 seconds
> > > > > > Tx Speed:0.09 MB/sec (total)
> > > > > > TxSpeed:0.09 MB/sec (application)
> > > > > > Error Msg:0
> > > > > > Rx Msg:2 messages
> > > > > > Rx Speed:0.00 MB/sec (since 1st msg)
> > > > > > Received:0.00 MB]
> > > > > >
> > > > > > Dec 16, 2013 6:56:43 PM org.apache.catalina.startup.HostConfig
> > > > > > deployDirectory
> > > > > > INFO: Deploying web application directory
> > > > > > /usr/local/tomcat7/apache-tomcat-7.0.47/webapps/docs
> > > > > > Dec 16, 2013 6:56:43 PM org.apache.catalina.startup.HostConfig
> > > > > > deployDirectory
> > > > > > INFO: Deploying web application directory
> > > > > > /usr/local/tomcat7/apache-tomcat-7.0.47/webapps/host-manager
> > > > > > Dec 16, 2013 6:56:43 PM org.apache.catalina.startup.HostConfig
> > > > > > deployDirectory
> > > > > > INFO: Deploying web application directory
> > > > > > /usr/local/tomcat7/apache-tomcat-7.0.47/webapps/ROOT
> > > > > > Dec 16, 2013 6:56:43 PM org.apache.catalina.startup.HostConfig
> > > > > > deployDirectory
> > > > > > INFO: Deploying web application directory
> > > > > > /usr/local/tomcat7/apache-tomcat-7.0.47/webapps/examples
> > > > > > Dec 16, 2013 6:56:44 PM org.apache.catalina.startup.HostConfig
> > > > > > deployDirectory
> > > > > > INFO: Deploying web application directory
> > > > > > /usr/local/tomcat7/apache-tomcat-7.0.47/webapps/manager
> > > > > > Dec 16, 2013 6:56:44 PM
> > > > > > org.apache.catalina.tribes.tipis.AbstractReplicatedMap init
> > > > > > INFO: Initializing AbstractReplicatedMap with context
> > > name:/manager-map
> > > > > > Dec 16, 2013 6:56:44 PM org.apache.coyote.AbstractProtocol start
> > > > > > INFO: Starting ProtocolHandler ["http-bio-8080"]
> > > > > > Dec 16, 2013 6:56:44 PM org.apache.coyote.AbstractProtocol start
> > > > > > INFO: Starting ProtocolHandler ["ajp-bio-8009"]
> > > > > > Dec 16, 2013 6:56:44 PM org.apache.catalina.startup.Catalina
> start
> > > > > > INFO: Server startup in 3535 ms
> > > > > >
> > > > > >
> > > > > >
> > > > > >
> > > > > >
> > > > > >
> > > > > > *It appears there are no severe errors on the log file with the
> > > backup
> > > > > > manager setup, but still we got no replication going.*
> > > > > > *Of course we added the *<distributable/>
> > > > > > *tag to both our web.xml of the tomcats AND for the WAR's web.xml
> > as
> > > > > well.*
> > > > > >
> > > > > >
> > > > > > *Any ideas why this is happening? *
> > > > > >
> > > > > > Regards and many thanks,
> > > > > >
> > > > > > NGT.
> > > > > >
> > > > > > --
> > > > > > Keiichi.Fujino
> > > > >
> > > >
> > > > --
> > > > Keiichi.Fujino
> > > >
> > >
> >
> > --
> > Keiichi.Fujino
> >
>
Re: Tomcat Clustering - when the tomcat instances are on different machines
Posted by Keiichi Fujino <kf...@apache.org>.
2013/12/17 Nir A <ni...@netomedia.com>
> In the tomcat manager We can see that our web application called "HATest"
> is having the sessions.
> Its a small demo of a shopping cart that keeps the items in the session.
>
> here is an example of a session we created in on of the tomcats nodes:
>
> Details for Session 33265A9C6318C014ADA92220A76F566C Session Id
> 33265A9C6318C014ADA92220A76F566C Guessed Locale
> Guessed User
> Creation Time 2013-12-17 11:56:07 Last Accessed Time 2013-12-17
> 12:01:13 Session
> Max Inactive Interval 00:30:00 Used Time 00:05:06 Inactive Time 00:00:02
> TTL 00:29:57
> 1 attributes Remove Attribute Attribute name Attribute value
>
> Books [my book!, Some other book]
>
>
>
Does this say that there is only one session?
You said "We have 3 sessions currently: one on node-1 and 2 on node-2" on
previous mail.
In other words, do you say that manager app should display 3 sessions (both
primary and backup) ?
>
> In our previous POC where all instances were local we had this exact
> session replication.
> We could see on the manager of instance 2 that a new "Backup" session is
> created (replicated) right after the creation of a new session in instance
> 1..
>
> 1) is it possible to get some more logging info from anywhere?
> 2) How come when i create a new session in an instance we dont see in the
> catalina.log another message being fired to update?
>
>
If you change log level of AbstractReplicatedMap, you can trace the session
replication of BackupManager.
e.g. logging.propertie
java.util.logging.ConsoleHandler.level = FINEST
org.apache.catalina.tribes.tipis.AbstractReplicatedMap.level = FINEST
> Thanks again,
>
>
>
> On Tue, Dec 17, 2013 at 11:54 AM, Keiichi Fujino <kf...@apache.org>
> wrote:
>
> > It seems that there is no problem.
> > Initialization of AbstractReplicatedMap seems to work correctly.
> >
> >
> >
> > >
> > > We have 3 sessions currently: one on node-1 and 2 on node-2 but there
> are
> > > only primary sessions on each (3) and not backup sessions at all. what
> > > could be the problem?
> > >
> > >
> > How did you confirm this?
> > please show more detail.
> >
> >
> >
> > > On Tue, Dec 17, 2013 at 10:25 AM, Keiichi Fujino <kf...@apache.org>
> > > wrote:
> > >
> > > > DeltaManager starts session sync phase by sending a SESSION-GET-ALL
> > > message
> > > > at startup.
> > > > DeltaManager that has received the SESSION-GET-ALL message sends all
> > > > session data by sending a ALL-SESSION-DATA message.
> > > > Then sends a SESSION-STATE-TRANSFERED message in order to notify the
> > > > transmission completion.
> > > > DeltaManager that has received the SESSION-STATE-TRANSFERED message
> > > > completes session sync phase.
> > > >
> > > >
> > > > According to this log,
> > > >
> > > >
> > > >
> > > > > Dec 16, 2013 6:43:29 PM org.apache.catalina.ha.session.DeltaManager
> > > > > waitForSendAllSessions
> > > > > SEVERE: Manager [/HATest]: No session state send at 12/16/13 6:42
> PM
> > > > > received, timing out after 60,102 ms.
> > > > >
> > > >
> > > > This log means that time-out occurred in session sync phase. (Default
> > 60
> > > > seconds)
> > > >
> > > > and
> > > >
> > > >
> > > >
> > > > > Dec 16, 2013 6:43:29 PM org.apache.catalina.ha.session.DeltaManager
> > > > > getAllClusterSessions
> > > > > WARNING: Manager [/HATest]: Drop message SESSION-GET-ALL inside
> > > > > GET_ALL_SESSIONS sync phase start date 12/16/13 6:42 PM message
> date
> > > > 1/1/70
> > > > > 2:00 AM
> > > > >
> > > >
> > > > This log means that SESSION-GET-ALL message that received during
> > session
> > > > sync phase is dropped.
> > > >
> > > > Thus, It seems that two nodes were started at the same time.
> > > > If SESSION-GET-ALL message is dropped, SESSION-STATE-TRANSFERED
> message
> > > can
> > > > not be received.
> > > > As a result, will be time-out in session sync phase.
> > > >
> > > > You should start Tomcat in proper order (rather than simultaneously).
> > > >
> > > > Another problem.
> > > > In warning log, time stamp of the SESSION-GET-ALL messages that were
> > > > dropped has become to 1/1/70.
> > > > This is just a trivial bug.
> > > > I will fix this later.
> > > > That way, the correct time stamp will be output.
> > > >
> > > >
> > > >
> > > >
> > > > > Dec 16, 2013 6:43:29 PM org.apache.catalina.startup.HostConfig
> > > > > deployDirectory
> > > > > INFO: Deploying web application directory
> > > > > /usr/local/tomcat7/apache-tomcat-7.0.47/webapps/docs
> > > > > Dec 16, 2013 6:43:29 PM org.apache.catalina.startup.HostConfig
> > > > > deployDirectory
> > > > > INFO: Deploying web application directory
> > > > > /usr/local/tomcat7/apache-tomcat-7.0.47/webapps/host-manager
> > > > > Dec 16, 2013 6:43:29 PM org.apache.catalina.startup.HostConfig
> > > > > deployDirectory
> > > > > INFO: Deploying web application directory
> > > > > /usr/local/tomcat7/apache-tomcat-7.0.47/webapps/ROOT
> > > > > Dec 16, 2013 6:43:29 PM org.apache.catalina.startup.HostConfig
> > > > > deployDirectory
> > > > > INFO: Deploying web application directory
> > > > > /usr/local/tomcat7/apache-tomcat-7.0.47/webapps/examples
> > > > > Dec 16, 2013 6:43:30 PM org.apache.catalina.startup.HostConfig
> > > > > deployDirectory
> > > > > INFO: Deploying web application directory
> > > > > /usr/local/tomcat7/apache-tomcat-7.0.47/webapps/manager
> > > > > Dec 16, 2013 6:43:30 PM org.apache.catalina.ha.session.DeltaManager
> > > > > startInternal
> > > > > INFO: Register manager /manager to cluster element Host with name
> > > > localhost
> > > > > Dec 16, 2013 6:43:30 PM org.apache.catalina.ha.session.DeltaManager
> > > > > startInternal
> > > > > INFO: Starting clustering manager at /manager
> > > > > Dec 16, 2013 6:43:30 PM org.apache.catalina.ha.session.DeltaManager
> > > > > getAllClusterSessions
> > > > > INFO: Manager [/manager], requesting session state from
> > > > > org.apache.catalina.tribes.membership.MemberImpl[tcp://{127, 0, 1,
> > > > > 1}:5000,{127, 0, 1, 1},5000, alive=65057, securePort=-1, UDP
> Port=-1,
> > > > > id={-90 41 -113 110 96 -50 78 -88 -79 -103 1 61 -60 -125 75 44 },
> > > > > payload={}, command={}, domain={}, ]. This operation will timeout
> if
> > no
> > > > > session state has been received within 60 seconds.
> > > > > Dec 16, 2013 6:44:16 PM
> > > > > org.apache.catalina.tribes.group.interceptors.TcpFailureDetector
> > > > > memberDisappeared
> > > > > INFO: Verification complete. Member
> > > > >
> > >
> disappeared[org.apache.catalina.tribes.membership.MemberImpl[tcp://{127,
> > > > 0,
> > > > > 1, 1}:5000,{127, 0, 1, 1},5000, alive=112037, securePort=-1, UDP
> > > Port=-1,
> > > > > id={-90 41 -113 110 96 -50 78 -88 -79 -103 1 61 -60 -125 75 44 },
> > > > > payload={}, command={66 65 66 89 45 65 76 69 88 ...(9)}, domain={},
> > ]]
> > > > > Dec 16, 2013 6:44:16 PM org.apache.catalina.ha.tcp.SimpleTcpCluster
> > > > > memberDisappeared
> > > > > INFO: Received member
> > > > >
> > >
> disappeared:org.apache.catalina.tribes.membership.MemberImpl[tcp://{127,
> > > > 0,
> > > > > 1, 1}:5000,{127, 0, 1, 1},5000, alive=112037, securePort=-1, UDP
> > > Port=-1,
> > > > > id={-90 41 -113 110 96 -50 78 -88 -79 -103 1 61 -60 -125 75 44 },
> > > > > payload={}, command={66 65 66 89 45 65 76 69 88 ...(9)},
> domain={}, ]
> > > > > Dec 16, 2013 6:44:22 PM org.apache.catalina.ha.tcp.SimpleTcpCluster
> > > > > memberAdded
> > > > > INFO: Replication member
> > > > > added:org.apache.catalina.tribes.membership.MemberImpl[tcp://{127,
> 0,
> > > 1,
> > > > > 1}:5000,{127, 0, 1, 1},5000, alive=1014, securePort=-1, UDP
> Port=-1,
> > > > id={75
> > > > > 3 86 -1 25 78 67 111 -125 -65 74 58 79 -20 93 16 }, payload={},
> > > > command={},
> > > > > domain={}, ]
> > > > > Dec 16, 2013 6:44:30 PM org.apache.catalina.ha.session.DeltaManager
> > > > > waitForSendAllSessions
> > > > > SEVERE: Manager [/manager]: No session state send at 12/16/13 6:43
> PM
> > > > > received, timing out after 60,081 ms.
> > > > > Dec 16, 2013 6:44:30 PM org.apache.catalina.ha.session.DeltaManager
> > > > > getAllClusterSessions
> > > > > WARNING: Manager [/manager]: Drop message SESSION-GET-ALL inside
> > > > > GET_ALL_SESSIONS sync phase start date 12/16/13 6:43 PM message
> date
> > > > 1/1/70
> > > > > 2:00 AM
> > > > > Dec 16, 2013 6:44:30 PM org.apache.coyote.AbstractProtocol start
> > > > > INFO: Starting ProtocolHandler ["http-bio-8080"]
> > > > > Dec 16, 2013 6:44:30 PM org.apache.coyote.AbstractProtocol start
> > > > > INFO: Starting ProtocolHandler ["ajp-bio-8009"]
> > > > > Dec 16, 2013 6:44:30 PM org.apache.catalina.startup.Catalina start
> > > > > INFO: Server startup in 123619 ms
> > > > >
> > > > >
> > > > >
> > > > >
> > > > >
> > > > > *When we try to configure the Backup manager (which is my goal
> > > actually)
> > > > > with the same server.xml only with backup manager tag:*
> > > > > <Manager className="org.apache.catalina.ha.session.BackupManager"
> > > > > expireSessionsOnShutdown="false"
> > > > > notifyListenersOnReplication="true"
> > > > > mapSendOptions="6"/>
> > > > >
> > > > >
> > > > > *We get the following log (again, no replication):*
> > > > >
> > > > >
> > > > > INFO: Cluster is about to start
> > > > > Dec 16, 2013 6:56:40 PM
> > > org.apache.catalina.tribes.transport.ReceiverBase
> > > > > bind
> > > > > INFO: Receiver Server Socket bound to:/127.0.1.1:5000
> > > > > Dec 16, 2013 6:56:40 PM
> > > > > org.apache.catalina.tribes.membership.McastServiceImpl setupSocket
> > > > > INFO: Setting cluster mcast soTimeout to 500
> > > > > Dec 16, 2013 6:56:40 PM
> > > > > org.apache.catalina.tribes.membership.McastServiceImpl
> waitForMembers
> > > > > INFO: Sleeping for 1000 milliseconds to establish cluster
> membership,
> > > > start
> > > > > level:4
> > > > > Dec 16, 2013 6:56:40 PM org.apache.catalina.ha.tcp.SimpleTcpCluster
> > > > > memberAdded
> > > > > INFO: Replication member
> > > > > added:org.apache.catalina.tribes.membership.MemberImpl[tcp://{127,
> 0,
> > > 1,
> > > > > 1}:5000,{127, 0, 1, 1},5000, alive=23027, securePort=-1, UDP
> Port=-1,
> > > > > id={52 -40 0 -117 -60 82 71 -42 -110 21 -91 -16 88 -96 -46 -113 },
> > > > > payload={}, command={}, domain={}, ]
> > > > > Dec 16, 2013 6:56:41 PM org.apache.catalina.tribes.io.BufferPool
> > > > > getBufferPool
> > > > > INFO: Created a buffer pool with max size:104857600 bytes of
> > > > > type:org.apache.catalina.tribes.io.BufferPool15Impl
> > > > > Dec 16, 2013 6:56:41 PM
> > > > > org.apache.catalina.tribes.membership.McastServiceImpl
> waitForMembers
> > > > > INFO: Done sleeping, membership established, start level:4
> > > > > Dec 16, 2013 6:56:41 PM
> > > > > org.apache.catalina.tribes.membership.McastServiceImpl
> waitForMembers
> > > > > INFO: Sleeping for 1000 milliseconds to establish cluster
> membership,
> > > > start
> > > > > level:8
> > > > > Dec 16, 2013 6:56:42 PM
> > > > > org.apache.catalina.tribes.membership.McastServiceImpl
> waitForMembers
> > > > > INFO: Done sleeping, membership established, start level:8
> > > > > Dec 16, 2013 6:56:42 PM
> org.apache.catalina.ha.deploy.FarmWarDeployer
> > > > start
> > > > > INFO: Cluster FarmWarDeployer started.
> > > > > Dec 16, 2013 6:56:42 PM org.apache.catalina.startup.HostConfig
> > > deployWAR
> > > > > INFO: Deploying web application archive
> > > > > /usr/local/tomcat7/apache-tomcat-7.0.47/webapps/HATest.war
> > > > > Dec 16, 2013 6:56:43 PM
> > > > > org.apache.catalina.tribes.tipis.AbstractReplicatedMap init
> > > > > INFO: Initializing AbstractReplicatedMap with context
> > name:/HATest-map
> > > > > Dec 16, 2013 6:56:43 PM
> > > > > org.apache.catalina.tribes.group.interceptors.ThroughputInterceptor
> > > > report
> > > > > INFO: ThroughputInterceptor Report[
> > > > > Tx Msg:1 messages
> > > > > Sent:0.00 MB (total)
> > > > > Sent:0.00 MB (application)
> > > > > Time:0.01 seconds
> > > > > Tx Speed:0.09 MB/sec (total)
> > > > > TxSpeed:0.09 MB/sec (application)
> > > > > Error Msg:0
> > > > > Rx Msg:2 messages
> > > > > Rx Speed:0.00 MB/sec (since 1st msg)
> > > > > Received:0.00 MB]
> > > > >
> > > > > Dec 16, 2013 6:56:43 PM org.apache.catalina.startup.HostConfig
> > > > > deployDirectory
> > > > > INFO: Deploying web application directory
> > > > > /usr/local/tomcat7/apache-tomcat-7.0.47/webapps/docs
> > > > > Dec 16, 2013 6:56:43 PM org.apache.catalina.startup.HostConfig
> > > > > deployDirectory
> > > > > INFO: Deploying web application directory
> > > > > /usr/local/tomcat7/apache-tomcat-7.0.47/webapps/host-manager
> > > > > Dec 16, 2013 6:56:43 PM org.apache.catalina.startup.HostConfig
> > > > > deployDirectory
> > > > > INFO: Deploying web application directory
> > > > > /usr/local/tomcat7/apache-tomcat-7.0.47/webapps/ROOT
> > > > > Dec 16, 2013 6:56:43 PM org.apache.catalina.startup.HostConfig
> > > > > deployDirectory
> > > > > INFO: Deploying web application directory
> > > > > /usr/local/tomcat7/apache-tomcat-7.0.47/webapps/examples
> > > > > Dec 16, 2013 6:56:44 PM org.apache.catalina.startup.HostConfig
> > > > > deployDirectory
> > > > > INFO: Deploying web application directory
> > > > > /usr/local/tomcat7/apache-tomcat-7.0.47/webapps/manager
> > > > > Dec 16, 2013 6:56:44 PM
> > > > > org.apache.catalina.tribes.tipis.AbstractReplicatedMap init
> > > > > INFO: Initializing AbstractReplicatedMap with context
> > name:/manager-map
> > > > > Dec 16, 2013 6:56:44 PM org.apache.coyote.AbstractProtocol start
> > > > > INFO: Starting ProtocolHandler ["http-bio-8080"]
> > > > > Dec 16, 2013 6:56:44 PM org.apache.coyote.AbstractProtocol start
> > > > > INFO: Starting ProtocolHandler ["ajp-bio-8009"]
> > > > > Dec 16, 2013 6:56:44 PM org.apache.catalina.startup.Catalina start
> > > > > INFO: Server startup in 3535 ms
> > > > >
> > > > >
> > > > >
> > > > >
> > > > >
> > > > >
> > > > > *It appears there are no severe errors on the log file with the
> > backup
> > > > > manager setup, but still we got no replication going.*
> > > > > *Of course we added the *<distributable/>
> > > > > *tag to both our web.xml of the tomcats AND for the WAR's web.xml
> as
> > > > well.*
> > > > >
> > > > >
> > > > > *Any ideas why this is happening? *
> > > > >
> > > > > Regards and many thanks,
> > > > >
> > > > > NGT.
> > > > >
> > > > > --
> > > > > Keiichi.Fujino
> > > >
> > >
> > > --
> > > Keiichi.Fujino
> > >
> >
>
> --
> Keiichi.Fujino
>
Re: Tomcat Clustering - when the tomcat instances are on different machines
Posted by Nir A <ni...@netomedia.com>.
In the tomcat manager We can see that our web application called "HATest"
is having the sessions.
Its a small demo of a shopping cart that keeps the items in the session.
here is an example of a session we created in on of the tomcats nodes:
Details for Session 33265A9C6318C014ADA92220A76F566C Session Id
33265A9C6318C014ADA92220A76F566C Guessed Locale
Guessed User
Creation Time 2013-12-17 11:56:07 Last Accessed Time 2013-12-17
12:01:13 Session
Max Inactive Interval 00:30:00 Used Time 00:05:06 Inactive Time 00:00:02
TTL 00:29:57
1 attributes Remove Attribute Attribute name Attribute value
Books [my book!, Some other book]
In our previous POC where all instances were local we had this exact
session replication.
We could see on the manager of instance 2 that a new "Backup" session is
created (replicated) right after the creation of a new session in instance
1..
1) is it possible to get some more logging info from anywhere?
2) How come when i create a new session in an instance we dont see in the
catalina.log another message being fired to update?
Thanks again,
On Tue, Dec 17, 2013 at 11:54 AM, Keiichi Fujino <kf...@apache.org> wrote:
> It seems that there is no problem.
> Initialization of AbstractReplicatedMap seems to work correctly.
>
>
>
> >
> > We have 3 sessions currently: one on node-1 and 2 on node-2 but there are
> > only primary sessions on each (3) and not backup sessions at all. what
> > could be the problem?
> >
> >
> How did you confirm this?
> please show more detail.
>
>
>
> > On Tue, Dec 17, 2013 at 10:25 AM, Keiichi Fujino <kf...@apache.org>
> > wrote:
> >
> > > DeltaManager starts session sync phase by sending a SESSION-GET-ALL
> > message
> > > at startup.
> > > DeltaManager that has received the SESSION-GET-ALL message sends all
> > > session data by sending a ALL-SESSION-DATA message.
> > > Then sends a SESSION-STATE-TRANSFERED message in order to notify the
> > > transmission completion.
> > > DeltaManager that has received the SESSION-STATE-TRANSFERED message
> > > completes session sync phase.
> > >
> > >
> > > According to this log,
> > >
> > >
> > >
> > > > Dec 16, 2013 6:43:29 PM org.apache.catalina.ha.session.DeltaManager
> > > > waitForSendAllSessions
> > > > SEVERE: Manager [/HATest]: No session state send at 12/16/13 6:42 PM
> > > > received, timing out after 60,102 ms.
> > > >
> > >
> > > This log means that time-out occurred in session sync phase. (Default
> 60
> > > seconds)
> > >
> > > and
> > >
> > >
> > >
> > > > Dec 16, 2013 6:43:29 PM org.apache.catalina.ha.session.DeltaManager
> > > > getAllClusterSessions
> > > > WARNING: Manager [/HATest]: Drop message SESSION-GET-ALL inside
> > > > GET_ALL_SESSIONS sync phase start date 12/16/13 6:42 PM message date
> > > 1/1/70
> > > > 2:00 AM
> > > >
> > >
> > > This log means that SESSION-GET-ALL message that received during
> session
> > > sync phase is dropped.
> > >
> > > Thus, It seems that two nodes were started at the same time.
> > > If SESSION-GET-ALL message is dropped, SESSION-STATE-TRANSFERED message
> > can
> > > not be received.
> > > As a result, will be time-out in session sync phase.
> > >
> > > You should start Tomcat in proper order (rather than simultaneously).
> > >
> > > Another problem.
> > > In warning log, time stamp of the SESSION-GET-ALL messages that were
> > > dropped has become to 1/1/70.
> > > This is just a trivial bug.
> > > I will fix this later.
> > > That way, the correct time stamp will be output.
> > >
> > >
> > >
> > >
> > > > Dec 16, 2013 6:43:29 PM org.apache.catalina.startup.HostConfig
> > > > deployDirectory
> > > > INFO: Deploying web application directory
> > > > /usr/local/tomcat7/apache-tomcat-7.0.47/webapps/docs
> > > > Dec 16, 2013 6:43:29 PM org.apache.catalina.startup.HostConfig
> > > > deployDirectory
> > > > INFO: Deploying web application directory
> > > > /usr/local/tomcat7/apache-tomcat-7.0.47/webapps/host-manager
> > > > Dec 16, 2013 6:43:29 PM org.apache.catalina.startup.HostConfig
> > > > deployDirectory
> > > > INFO: Deploying web application directory
> > > > /usr/local/tomcat7/apache-tomcat-7.0.47/webapps/ROOT
> > > > Dec 16, 2013 6:43:29 PM org.apache.catalina.startup.HostConfig
> > > > deployDirectory
> > > > INFO: Deploying web application directory
> > > > /usr/local/tomcat7/apache-tomcat-7.0.47/webapps/examples
> > > > Dec 16, 2013 6:43:30 PM org.apache.catalina.startup.HostConfig
> > > > deployDirectory
> > > > INFO: Deploying web application directory
> > > > /usr/local/tomcat7/apache-tomcat-7.0.47/webapps/manager
> > > > Dec 16, 2013 6:43:30 PM org.apache.catalina.ha.session.DeltaManager
> > > > startInternal
> > > > INFO: Register manager /manager to cluster element Host with name
> > > localhost
> > > > Dec 16, 2013 6:43:30 PM org.apache.catalina.ha.session.DeltaManager
> > > > startInternal
> > > > INFO: Starting clustering manager at /manager
> > > > Dec 16, 2013 6:43:30 PM org.apache.catalina.ha.session.DeltaManager
> > > > getAllClusterSessions
> > > > INFO: Manager [/manager], requesting session state from
> > > > org.apache.catalina.tribes.membership.MemberImpl[tcp://{127, 0, 1,
> > > > 1}:5000,{127, 0, 1, 1},5000, alive=65057, securePort=-1, UDP Port=-1,
> > > > id={-90 41 -113 110 96 -50 78 -88 -79 -103 1 61 -60 -125 75 44 },
> > > > payload={}, command={}, domain={}, ]. This operation will timeout if
> no
> > > > session state has been received within 60 seconds.
> > > > Dec 16, 2013 6:44:16 PM
> > > > org.apache.catalina.tribes.group.interceptors.TcpFailureDetector
> > > > memberDisappeared
> > > > INFO: Verification complete. Member
> > > >
> > disappeared[org.apache.catalina.tribes.membership.MemberImpl[tcp://{127,
> > > 0,
> > > > 1, 1}:5000,{127, 0, 1, 1},5000, alive=112037, securePort=-1, UDP
> > Port=-1,
> > > > id={-90 41 -113 110 96 -50 78 -88 -79 -103 1 61 -60 -125 75 44 },
> > > > payload={}, command={66 65 66 89 45 65 76 69 88 ...(9)}, domain={},
> ]]
> > > > Dec 16, 2013 6:44:16 PM org.apache.catalina.ha.tcp.SimpleTcpCluster
> > > > memberDisappeared
> > > > INFO: Received member
> > > >
> > disappeared:org.apache.catalina.tribes.membership.MemberImpl[tcp://{127,
> > > 0,
> > > > 1, 1}:5000,{127, 0, 1, 1},5000, alive=112037, securePort=-1, UDP
> > Port=-1,
> > > > id={-90 41 -113 110 96 -50 78 -88 -79 -103 1 61 -60 -125 75 44 },
> > > > payload={}, command={66 65 66 89 45 65 76 69 88 ...(9)}, domain={}, ]
> > > > Dec 16, 2013 6:44:22 PM org.apache.catalina.ha.tcp.SimpleTcpCluster
> > > > memberAdded
> > > > INFO: Replication member
> > > > added:org.apache.catalina.tribes.membership.MemberImpl[tcp://{127, 0,
> > 1,
> > > > 1}:5000,{127, 0, 1, 1},5000, alive=1014, securePort=-1, UDP Port=-1,
> > > id={75
> > > > 3 86 -1 25 78 67 111 -125 -65 74 58 79 -20 93 16 }, payload={},
> > > command={},
> > > > domain={}, ]
> > > > Dec 16, 2013 6:44:30 PM org.apache.catalina.ha.session.DeltaManager
> > > > waitForSendAllSessions
> > > > SEVERE: Manager [/manager]: No session state send at 12/16/13 6:43 PM
> > > > received, timing out after 60,081 ms.
> > > > Dec 16, 2013 6:44:30 PM org.apache.catalina.ha.session.DeltaManager
> > > > getAllClusterSessions
> > > > WARNING: Manager [/manager]: Drop message SESSION-GET-ALL inside
> > > > GET_ALL_SESSIONS sync phase start date 12/16/13 6:43 PM message date
> > > 1/1/70
> > > > 2:00 AM
> > > > Dec 16, 2013 6:44:30 PM org.apache.coyote.AbstractProtocol start
> > > > INFO: Starting ProtocolHandler ["http-bio-8080"]
> > > > Dec 16, 2013 6:44:30 PM org.apache.coyote.AbstractProtocol start
> > > > INFO: Starting ProtocolHandler ["ajp-bio-8009"]
> > > > Dec 16, 2013 6:44:30 PM org.apache.catalina.startup.Catalina start
> > > > INFO: Server startup in 123619 ms
> > > >
> > > >
> > > >
> > > >
> > > >
> > > > *When we try to configure the Backup manager (which is my goal
> > actually)
> > > > with the same server.xml only with backup manager tag:*
> > > > <Manager className="org.apache.catalina.ha.session.BackupManager"
> > > > expireSessionsOnShutdown="false"
> > > > notifyListenersOnReplication="true"
> > > > mapSendOptions="6"/>
> > > >
> > > >
> > > > *We get the following log (again, no replication):*
> > > >
> > > >
> > > > INFO: Cluster is about to start
> > > > Dec 16, 2013 6:56:40 PM
> > org.apache.catalina.tribes.transport.ReceiverBase
> > > > bind
> > > > INFO: Receiver Server Socket bound to:/127.0.1.1:5000
> > > > Dec 16, 2013 6:56:40 PM
> > > > org.apache.catalina.tribes.membership.McastServiceImpl setupSocket
> > > > INFO: Setting cluster mcast soTimeout to 500
> > > > Dec 16, 2013 6:56:40 PM
> > > > org.apache.catalina.tribes.membership.McastServiceImpl waitForMembers
> > > > INFO: Sleeping for 1000 milliseconds to establish cluster membership,
> > > start
> > > > level:4
> > > > Dec 16, 2013 6:56:40 PM org.apache.catalina.ha.tcp.SimpleTcpCluster
> > > > memberAdded
> > > > INFO: Replication member
> > > > added:org.apache.catalina.tribes.membership.MemberImpl[tcp://{127, 0,
> > 1,
> > > > 1}:5000,{127, 0, 1, 1},5000, alive=23027, securePort=-1, UDP Port=-1,
> > > > id={52 -40 0 -117 -60 82 71 -42 -110 21 -91 -16 88 -96 -46 -113 },
> > > > payload={}, command={}, domain={}, ]
> > > > Dec 16, 2013 6:56:41 PM org.apache.catalina.tribes.io.BufferPool
> > > > getBufferPool
> > > > INFO: Created a buffer pool with max size:104857600 bytes of
> > > > type:org.apache.catalina.tribes.io.BufferPool15Impl
> > > > Dec 16, 2013 6:56:41 PM
> > > > org.apache.catalina.tribes.membership.McastServiceImpl waitForMembers
> > > > INFO: Done sleeping, membership established, start level:4
> > > > Dec 16, 2013 6:56:41 PM
> > > > org.apache.catalina.tribes.membership.McastServiceImpl waitForMembers
> > > > INFO: Sleeping for 1000 milliseconds to establish cluster membership,
> > > start
> > > > level:8
> > > > Dec 16, 2013 6:56:42 PM
> > > > org.apache.catalina.tribes.membership.McastServiceImpl waitForMembers
> > > > INFO: Done sleeping, membership established, start level:8
> > > > Dec 16, 2013 6:56:42 PM org.apache.catalina.ha.deploy.FarmWarDeployer
> > > start
> > > > INFO: Cluster FarmWarDeployer started.
> > > > Dec 16, 2013 6:56:42 PM org.apache.catalina.startup.HostConfig
> > deployWAR
> > > > INFO: Deploying web application archive
> > > > /usr/local/tomcat7/apache-tomcat-7.0.47/webapps/HATest.war
> > > > Dec 16, 2013 6:56:43 PM
> > > > org.apache.catalina.tribes.tipis.AbstractReplicatedMap init
> > > > INFO: Initializing AbstractReplicatedMap with context
> name:/HATest-map
> > > > Dec 16, 2013 6:56:43 PM
> > > > org.apache.catalina.tribes.group.interceptors.ThroughputInterceptor
> > > report
> > > > INFO: ThroughputInterceptor Report[
> > > > Tx Msg:1 messages
> > > > Sent:0.00 MB (total)
> > > > Sent:0.00 MB (application)
> > > > Time:0.01 seconds
> > > > Tx Speed:0.09 MB/sec (total)
> > > > TxSpeed:0.09 MB/sec (application)
> > > > Error Msg:0
> > > > Rx Msg:2 messages
> > > > Rx Speed:0.00 MB/sec (since 1st msg)
> > > > Received:0.00 MB]
> > > >
> > > > Dec 16, 2013 6:56:43 PM org.apache.catalina.startup.HostConfig
> > > > deployDirectory
> > > > INFO: Deploying web application directory
> > > > /usr/local/tomcat7/apache-tomcat-7.0.47/webapps/docs
> > > > Dec 16, 2013 6:56:43 PM org.apache.catalina.startup.HostConfig
> > > > deployDirectory
> > > > INFO: Deploying web application directory
> > > > /usr/local/tomcat7/apache-tomcat-7.0.47/webapps/host-manager
> > > > Dec 16, 2013 6:56:43 PM org.apache.catalina.startup.HostConfig
> > > > deployDirectory
> > > > INFO: Deploying web application directory
> > > > /usr/local/tomcat7/apache-tomcat-7.0.47/webapps/ROOT
> > > > Dec 16, 2013 6:56:43 PM org.apache.catalina.startup.HostConfig
> > > > deployDirectory
> > > > INFO: Deploying web application directory
> > > > /usr/local/tomcat7/apache-tomcat-7.0.47/webapps/examples
> > > > Dec 16, 2013 6:56:44 PM org.apache.catalina.startup.HostConfig
> > > > deployDirectory
> > > > INFO: Deploying web application directory
> > > > /usr/local/tomcat7/apache-tomcat-7.0.47/webapps/manager
> > > > Dec 16, 2013 6:56:44 PM
> > > > org.apache.catalina.tribes.tipis.AbstractReplicatedMap init
> > > > INFO: Initializing AbstractReplicatedMap with context
> name:/manager-map
> > > > Dec 16, 2013 6:56:44 PM org.apache.coyote.AbstractProtocol start
> > > > INFO: Starting ProtocolHandler ["http-bio-8080"]
> > > > Dec 16, 2013 6:56:44 PM org.apache.coyote.AbstractProtocol start
> > > > INFO: Starting ProtocolHandler ["ajp-bio-8009"]
> > > > Dec 16, 2013 6:56:44 PM org.apache.catalina.startup.Catalina start
> > > > INFO: Server startup in 3535 ms
> > > >
> > > >
> > > >
> > > >
> > > >
> > > >
> > > > *It appears there are no severe errors on the log file with the
> backup
> > > > manager setup, but still we got no replication going.*
> > > > *Of course we added the *<distributable/>
> > > > *tag to both our web.xml of the tomcats AND for the WAR's web.xml as
> > > well.*
> > > >
> > > >
> > > > *Any ideas why this is happening? *
> > > >
> > > > Regards and many thanks,
> > > >
> > > > NGT.
> > > >
> > > > --
> > > > Keiichi.Fujino
> > >
> >
> > --
> > Keiichi.Fujino
> >
>
Re: Tomcat Clustering - when the tomcat instances are on different machines
Posted by Keiichi Fujino <kf...@apache.org>.
It seems that there is no problem.
Initialization of AbstractReplicatedMap seems to work correctly.
>
> We have 3 sessions currently: one on node-1 and 2 on node-2 but there are
> only primary sessions on each (3) and not backup sessions at all. what
> could be the problem?
>
>
How did you confirm this?
please show more detail.
> On Tue, Dec 17, 2013 at 10:25 AM, Keiichi Fujino <kf...@apache.org>
> wrote:
>
> > DeltaManager starts session sync phase by sending a SESSION-GET-ALL
> message
> > at startup.
> > DeltaManager that has received the SESSION-GET-ALL message sends all
> > session data by sending a ALL-SESSION-DATA message.
> > Then sends a SESSION-STATE-TRANSFERED message in order to notify the
> > transmission completion.
> > DeltaManager that has received the SESSION-STATE-TRANSFERED message
> > completes session sync phase.
> >
> >
> > According to this log,
> >
> >
> >
> > > Dec 16, 2013 6:43:29 PM org.apache.catalina.ha.session.DeltaManager
> > > waitForSendAllSessions
> > > SEVERE: Manager [/HATest]: No session state send at 12/16/13 6:42 PM
> > > received, timing out after 60,102 ms.
> > >
> >
> > This log means that time-out occurred in session sync phase. (Default 60
> > seconds)
> >
> > and
> >
> >
> >
> > > Dec 16, 2013 6:43:29 PM org.apache.catalina.ha.session.DeltaManager
> > > getAllClusterSessions
> > > WARNING: Manager [/HATest]: Drop message SESSION-GET-ALL inside
> > > GET_ALL_SESSIONS sync phase start date 12/16/13 6:42 PM message date
> > 1/1/70
> > > 2:00 AM
> > >
> >
> > This log means that SESSION-GET-ALL message that received during session
> > sync phase is dropped.
> >
> > Thus, It seems that two nodes were started at the same time.
> > If SESSION-GET-ALL message is dropped, SESSION-STATE-TRANSFERED message
> can
> > not be received.
> > As a result, will be time-out in session sync phase.
> >
> > You should start Tomcat in proper order (rather than simultaneously).
> >
> > Another problem.
> > In warning log, time stamp of the SESSION-GET-ALL messages that were
> > dropped has become to 1/1/70.
> > This is just a trivial bug.
> > I will fix this later.
> > That way, the correct time stamp will be output.
> >
> >
> >
> >
> > > Dec 16, 2013 6:43:29 PM org.apache.catalina.startup.HostConfig
> > > deployDirectory
> > > INFO: Deploying web application directory
> > > /usr/local/tomcat7/apache-tomcat-7.0.47/webapps/docs
> > > Dec 16, 2013 6:43:29 PM org.apache.catalina.startup.HostConfig
> > > deployDirectory
> > > INFO: Deploying web application directory
> > > /usr/local/tomcat7/apache-tomcat-7.0.47/webapps/host-manager
> > > Dec 16, 2013 6:43:29 PM org.apache.catalina.startup.HostConfig
> > > deployDirectory
> > > INFO: Deploying web application directory
> > > /usr/local/tomcat7/apache-tomcat-7.0.47/webapps/ROOT
> > > Dec 16, 2013 6:43:29 PM org.apache.catalina.startup.HostConfig
> > > deployDirectory
> > > INFO: Deploying web application directory
> > > /usr/local/tomcat7/apache-tomcat-7.0.47/webapps/examples
> > > Dec 16, 2013 6:43:30 PM org.apache.catalina.startup.HostConfig
> > > deployDirectory
> > > INFO: Deploying web application directory
> > > /usr/local/tomcat7/apache-tomcat-7.0.47/webapps/manager
> > > Dec 16, 2013 6:43:30 PM org.apache.catalina.ha.session.DeltaManager
> > > startInternal
> > > INFO: Register manager /manager to cluster element Host with name
> > localhost
> > > Dec 16, 2013 6:43:30 PM org.apache.catalina.ha.session.DeltaManager
> > > startInternal
> > > INFO: Starting clustering manager at /manager
> > > Dec 16, 2013 6:43:30 PM org.apache.catalina.ha.session.DeltaManager
> > > getAllClusterSessions
> > > INFO: Manager [/manager], requesting session state from
> > > org.apache.catalina.tribes.membership.MemberImpl[tcp://{127, 0, 1,
> > > 1}:5000,{127, 0, 1, 1},5000, alive=65057, securePort=-1, UDP Port=-1,
> > > id={-90 41 -113 110 96 -50 78 -88 -79 -103 1 61 -60 -125 75 44 },
> > > payload={}, command={}, domain={}, ]. This operation will timeout if no
> > > session state has been received within 60 seconds.
> > > Dec 16, 2013 6:44:16 PM
> > > org.apache.catalina.tribes.group.interceptors.TcpFailureDetector
> > > memberDisappeared
> > > INFO: Verification complete. Member
> > >
> disappeared[org.apache.catalina.tribes.membership.MemberImpl[tcp://{127,
> > 0,
> > > 1, 1}:5000,{127, 0, 1, 1},5000, alive=112037, securePort=-1, UDP
> Port=-1,
> > > id={-90 41 -113 110 96 -50 78 -88 -79 -103 1 61 -60 -125 75 44 },
> > > payload={}, command={66 65 66 89 45 65 76 69 88 ...(9)}, domain={}, ]]
> > > Dec 16, 2013 6:44:16 PM org.apache.catalina.ha.tcp.SimpleTcpCluster
> > > memberDisappeared
> > > INFO: Received member
> > >
> disappeared:org.apache.catalina.tribes.membership.MemberImpl[tcp://{127,
> > 0,
> > > 1, 1}:5000,{127, 0, 1, 1},5000, alive=112037, securePort=-1, UDP
> Port=-1,
> > > id={-90 41 -113 110 96 -50 78 -88 -79 -103 1 61 -60 -125 75 44 },
> > > payload={}, command={66 65 66 89 45 65 76 69 88 ...(9)}, domain={}, ]
> > > Dec 16, 2013 6:44:22 PM org.apache.catalina.ha.tcp.SimpleTcpCluster
> > > memberAdded
> > > INFO: Replication member
> > > added:org.apache.catalina.tribes.membership.MemberImpl[tcp://{127, 0,
> 1,
> > > 1}:5000,{127, 0, 1, 1},5000, alive=1014, securePort=-1, UDP Port=-1,
> > id={75
> > > 3 86 -1 25 78 67 111 -125 -65 74 58 79 -20 93 16 }, payload={},
> > command={},
> > > domain={}, ]
> > > Dec 16, 2013 6:44:30 PM org.apache.catalina.ha.session.DeltaManager
> > > waitForSendAllSessions
> > > SEVERE: Manager [/manager]: No session state send at 12/16/13 6:43 PM
> > > received, timing out after 60,081 ms.
> > > Dec 16, 2013 6:44:30 PM org.apache.catalina.ha.session.DeltaManager
> > > getAllClusterSessions
> > > WARNING: Manager [/manager]: Drop message SESSION-GET-ALL inside
> > > GET_ALL_SESSIONS sync phase start date 12/16/13 6:43 PM message date
> > 1/1/70
> > > 2:00 AM
> > > Dec 16, 2013 6:44:30 PM org.apache.coyote.AbstractProtocol start
> > > INFO: Starting ProtocolHandler ["http-bio-8080"]
> > > Dec 16, 2013 6:44:30 PM org.apache.coyote.AbstractProtocol start
> > > INFO: Starting ProtocolHandler ["ajp-bio-8009"]
> > > Dec 16, 2013 6:44:30 PM org.apache.catalina.startup.Catalina start
> > > INFO: Server startup in 123619 ms
> > >
> > >
> > >
> > >
> > >
> > > *When we try to configure the Backup manager (which is my goal
> actually)
> > > with the same server.xml only with backup manager tag:*
> > > <Manager className="org.apache.catalina.ha.session.BackupManager"
> > > expireSessionsOnShutdown="false"
> > > notifyListenersOnReplication="true"
> > > mapSendOptions="6"/>
> > >
> > >
> > > *We get the following log (again, no replication):*
> > >
> > >
> > > INFO: Cluster is about to start
> > > Dec 16, 2013 6:56:40 PM
> org.apache.catalina.tribes.transport.ReceiverBase
> > > bind
> > > INFO: Receiver Server Socket bound to:/127.0.1.1:5000
> > > Dec 16, 2013 6:56:40 PM
> > > org.apache.catalina.tribes.membership.McastServiceImpl setupSocket
> > > INFO: Setting cluster mcast soTimeout to 500
> > > Dec 16, 2013 6:56:40 PM
> > > org.apache.catalina.tribes.membership.McastServiceImpl waitForMembers
> > > INFO: Sleeping for 1000 milliseconds to establish cluster membership,
> > start
> > > level:4
> > > Dec 16, 2013 6:56:40 PM org.apache.catalina.ha.tcp.SimpleTcpCluster
> > > memberAdded
> > > INFO: Replication member
> > > added:org.apache.catalina.tribes.membership.MemberImpl[tcp://{127, 0,
> 1,
> > > 1}:5000,{127, 0, 1, 1},5000, alive=23027, securePort=-1, UDP Port=-1,
> > > id={52 -40 0 -117 -60 82 71 -42 -110 21 -91 -16 88 -96 -46 -113 },
> > > payload={}, command={}, domain={}, ]
> > > Dec 16, 2013 6:56:41 PM org.apache.catalina.tribes.io.BufferPool
> > > getBufferPool
> > > INFO: Created a buffer pool with max size:104857600 bytes of
> > > type:org.apache.catalina.tribes.io.BufferPool15Impl
> > > Dec 16, 2013 6:56:41 PM
> > > org.apache.catalina.tribes.membership.McastServiceImpl waitForMembers
> > > INFO: Done sleeping, membership established, start level:4
> > > Dec 16, 2013 6:56:41 PM
> > > org.apache.catalina.tribes.membership.McastServiceImpl waitForMembers
> > > INFO: Sleeping for 1000 milliseconds to establish cluster membership,
> > start
> > > level:8
> > > Dec 16, 2013 6:56:42 PM
> > > org.apache.catalina.tribes.membership.McastServiceImpl waitForMembers
> > > INFO: Done sleeping, membership established, start level:8
> > > Dec 16, 2013 6:56:42 PM org.apache.catalina.ha.deploy.FarmWarDeployer
> > start
> > > INFO: Cluster FarmWarDeployer started.
> > > Dec 16, 2013 6:56:42 PM org.apache.catalina.startup.HostConfig
> deployWAR
> > > INFO: Deploying web application archive
> > > /usr/local/tomcat7/apache-tomcat-7.0.47/webapps/HATest.war
> > > Dec 16, 2013 6:56:43 PM
> > > org.apache.catalina.tribes.tipis.AbstractReplicatedMap init
> > > INFO: Initializing AbstractReplicatedMap with context name:/HATest-map
> > > Dec 16, 2013 6:56:43 PM
> > > org.apache.catalina.tribes.group.interceptors.ThroughputInterceptor
> > report
> > > INFO: ThroughputInterceptor Report[
> > > Tx Msg:1 messages
> > > Sent:0.00 MB (total)
> > > Sent:0.00 MB (application)
> > > Time:0.01 seconds
> > > Tx Speed:0.09 MB/sec (total)
> > > TxSpeed:0.09 MB/sec (application)
> > > Error Msg:0
> > > Rx Msg:2 messages
> > > Rx Speed:0.00 MB/sec (since 1st msg)
> > > Received:0.00 MB]
> > >
> > > Dec 16, 2013 6:56:43 PM org.apache.catalina.startup.HostConfig
> > > deployDirectory
> > > INFO: Deploying web application directory
> > > /usr/local/tomcat7/apache-tomcat-7.0.47/webapps/docs
> > > Dec 16, 2013 6:56:43 PM org.apache.catalina.startup.HostConfig
> > > deployDirectory
> > > INFO: Deploying web application directory
> > > /usr/local/tomcat7/apache-tomcat-7.0.47/webapps/host-manager
> > > Dec 16, 2013 6:56:43 PM org.apache.catalina.startup.HostConfig
> > > deployDirectory
> > > INFO: Deploying web application directory
> > > /usr/local/tomcat7/apache-tomcat-7.0.47/webapps/ROOT
> > > Dec 16, 2013 6:56:43 PM org.apache.catalina.startup.HostConfig
> > > deployDirectory
> > > INFO: Deploying web application directory
> > > /usr/local/tomcat7/apache-tomcat-7.0.47/webapps/examples
> > > Dec 16, 2013 6:56:44 PM org.apache.catalina.startup.HostConfig
> > > deployDirectory
> > > INFO: Deploying web application directory
> > > /usr/local/tomcat7/apache-tomcat-7.0.47/webapps/manager
> > > Dec 16, 2013 6:56:44 PM
> > > org.apache.catalina.tribes.tipis.AbstractReplicatedMap init
> > > INFO: Initializing AbstractReplicatedMap with context name:/manager-map
> > > Dec 16, 2013 6:56:44 PM org.apache.coyote.AbstractProtocol start
> > > INFO: Starting ProtocolHandler ["http-bio-8080"]
> > > Dec 16, 2013 6:56:44 PM org.apache.coyote.AbstractProtocol start
> > > INFO: Starting ProtocolHandler ["ajp-bio-8009"]
> > > Dec 16, 2013 6:56:44 PM org.apache.catalina.startup.Catalina start
> > > INFO: Server startup in 3535 ms
> > >
> > >
> > >
> > >
> > >
> > >
> > > *It appears there are no severe errors on the log file with the backup
> > > manager setup, but still we got no replication going.*
> > > *Of course we added the *<distributable/>
> > > *tag to both our web.xml of the tomcats AND for the WAR's web.xml as
> > well.*
> > >
> > >
> > > *Any ideas why this is happening? *
> > >
> > > Regards and many thanks,
> > >
> > > NGT.
> > >
> > > --
> > > Keiichi.Fujino
> >
>
> --
> Keiichi.Fujino
>
Re: Tomcat Clustering - when the tomcat instances are on different machines
Posted by Nir A <ni...@netomedia.com>.
Ok , So now we started node 1 , waited until it was up and running and only
then we started node2.
There are no warnings \ errors on the log files.
Only problem is that our session's are not being replicated.
here are the logs of the catalina:
Node1:
Dec 17, 2013 10:52:21 AM org.apache.catalina.core.AprLifecycleListener init
INFO: The APR based Apache Tomcat Native library which allows optimal
performance in production environments was not found on the
java.library.path: /usr/java/packages/lib/amd64:/usr/lib/jni:/lib:/usr/lib
Dec 17, 2013 10:52:21 AM org.apache.coyote.AbstractProtocol init
INFO: Initializing ProtocolHandler ["http-bio-8080"]
Dec 17, 2013 10:52:21 AM org.apache.coyote.AbstractProtocol init
INFO: Initializing ProtocolHandler ["ajp-bio-8009"]
Dec 17, 2013 10:52:21 AM org.apache.catalina.startup.Catalina load
INFO: Initialization processed in 789 ms
Dec 17, 2013 10:52:21 AM org.apache.catalina.core.StandardService
startInternal
INFO: Starting service Catalina
Dec 17, 2013 10:52:21 AM org.apache.catalina.core.StandardEngine
startInternal
INFO: Starting Servlet Engine: Apache Tomcat/7.0.47
Dec 17, 2013 10:52:21 AM org.apache.catalina.ha.tcp.SimpleTcpCluster
startInternal
INFO: Cluster is about to start
Dec 17, 2013 10:52:21 AM org.apache.catalina.tribes.transport.ReceiverBase
bind
INFO: Receiver Server Socket bound to:/127.0.1.1:5000
Dec 17, 2013 10:52:21 AM
org.apache.catalina.tribes.membership.McastServiceImpl setupSocket
INFO: Setting cluster mcast soTimeout to 500
Dec 17, 2013 10:52:21 AM
org.apache.catalina.tribes.membership.McastServiceImpl waitForMembers
INFO: Sleeping for 1000 milliseconds to establish cluster membership, start
level:4
Dec 17, 2013 10:52:22 AM
org.apache.catalina.tribes.membership.McastServiceImpl waitForMembers
INFO: Done sleeping, membership established, start level:4
Dec 17, 2013 10:52:22 AM
org.apache.catalina.tribes.membership.McastServiceImpl waitForMembers
INFO: Sleeping for 1000 milliseconds to establish cluster membership, start
level:8
Dec 17, 2013 10:52:23 AM
org.apache.catalina.tribes.membership.McastServiceImpl waitForMembers
INFO: Done sleeping, membership established, start level:8
Dec 17, 2013 10:52:23 AM org.apache.catalina.ha.deploy.FarmWarDeployer start
INFO: Cluster FarmWarDeployer started.
Dec 17, 2013 10:52:23 AM org.apache.catalina.startup.HostConfig deployWAR
INFO: Deploying web application archive
/usr/local/tomcat7/apache-tomcat-7.0.47/webapps/HATest.war
Dec 17, 2013 10:52:24 AM
org.apache.catalina.tribes.tipis.AbstractReplicatedMap init
INFO: Initializing AbstractReplicatedMap with context name:/HATest-map
Dec 17, 2013 10:52:24 AM org.apache.catalina.startup.HostConfig
deployDirectory
INFO: Deploying web application directory
/usr/local/tomcat7/apache-tomcat-7.0.47/webapps/docs
Dec 17, 2013 10:52:24 AM org.apache.catalina.startup.HostConfig
deployDirectory
INFO: Deploying web application directory
/usr/local/tomcat7/apache-tomcat-7.0.47/webapps/host-manager
Dec 17, 2013 10:52:24 AM org.apache.catalina.startup.HostConfig
deployDirectory
INFO: Deploying web application directory
/usr/local/tomcat7/apache-tomcat-7.0.47/webapps/ROOT
Dec 17, 2013 10:52:24 AM org.apache.catalina.startup.HostConfig
deployDirectory
INFO: Deploying web application directory
/usr/local/tomcat7/apache-tomcat-7.0.47/webapps/examples
Dec 17, 2013 10:52:24 AM org.apache.catalina.startup.HostConfig
deployDirectory
INFO: Deploying web application directory
/usr/local/tomcat7/apache-tomcat-7.0.47/webapps/manager
Dec 17, 2013 10:52:25 AM
org.apache.catalina.tribes.tipis.AbstractReplicatedMap init
INFO: Initializing AbstractReplicatedMap with context name:/manager-map
Dec 17, 2013 10:52:25 AM org.apache.coyote.AbstractProtocol start
INFO: Starting ProtocolHandler ["http-bio-8080"]
Dec 17, 2013 10:52:25 AM org.apache.coyote.AbstractProtocol start
INFO: Starting ProtocolHandler ["ajp-bio-8009"]
Dec 17, 2013 10:52:25 AM org.apache.catalina.startup.Catalina start
INFO: Server startup in 3592 ms
Dec 17, 2013 10:52:42 AM org.apache.catalina.ha.tcp.SimpleTcpCluster
memberAdded
INFO: Replication member
added:org.apache.catalina.tribes.membership.MemberImpl[tcp://{127, 0, 1,
1}:5000,{127, 0, 1, 1},5000, alive=1016, securePort=-1, UDP Port=-1, id={12
109 58 47 47 -29 65 29 -113 -10 7 24 97 -113 -24 -96 }, payload={},
command={}, domain={}, ]
Dec 17, 2013 10:52:42 AM org.apache.catalina.tribes.io.BufferPool
getBufferPool
INFO: Created a buffer pool with max size:104857600 bytes of
type:org.apache.catalina.tribes.io.BufferPool15Impl
Dec 17, 2013 10:52:43 AM
org.apache.catalina.tribes.group.interceptors.ThroughputInterceptor report
INFO: ThroughputInterceptor Report[
Tx Msg:1 messages
Sent:0.00 MB (total)
Sent:0.00 MB (application)
Time:0.01 seconds
Tx Speed:0.08 MB/sec (total)
TxSpeed:0.08 MB/sec (application)
Error Msg:0
Rx Msg:2 messages
Rx Speed:0.00 MB/sec (since 1st msg)
Received:0.00 MB]
Node 2:
Dec 17, 2013 10:52:40 AM org.apache.catalina.core.AprLifecycleListener init
INFO: The APR based Apache Tomcat Native library which allows optimal
performance in production environments was not found on the
java.library.path: /usr/java/packages/lib/amd64:/usr/lib/jni:/lib:/usr/lib
Dec 17, 2013 10:52:41 AM org.apache.coyote.AbstractProtocol init
INFO: Initializing ProtocolHandler ["http-bio-8080"]
Dec 17, 2013 10:52:41 AM org.apache.coyote.AbstractProtocol init
INFO: Initializing ProtocolHandler ["ajp-bio-8009"]
Dec 17, 2013 10:52:41 AM org.apache.catalina.startup.Catalina load
INFO: Initialization processed in 785 ms
Dec 17, 2013 10:52:41 AM org.apache.catalina.core.StandardService
startInternal
INFO: Starting service Catalina
Dec 17, 2013 10:52:41 AM org.apache.catalina.core.StandardEngine
startInternal
INFO: Starting Servlet Engine: Apache Tomcat/7.0.47
Dec 17, 2013 10:52:41 AM org.apache.catalina.ha.tcp.SimpleTcpCluster
startInternal
INFO: Cluster is about to start
Dec 17, 2013 10:52:41 AM org.apache.catalina.tribes.transport.ReceiverBase
bind
INFO: Receiver Server Socket bound to:/127.0.1.1:5000
Dec 17, 2013 10:52:41 AM
org.apache.catalina.tribes.membership.McastServiceImpl setupSocket
INFO: Setting cluster mcast soTimeout to 500
Dec 17, 2013 10:52:41 AM
org.apache.catalina.tribes.membership.McastServiceImpl waitForMembers
INFO: Sleeping for 1000 milliseconds to establish cluster membership, start
level:4
Dec 17, 2013 10:52:41 AM org.apache.catalina.ha.tcp.SimpleTcpCluster
memberAdded
INFO: Replication member
added:org.apache.catalina.tribes.membership.MemberImpl[tcp://{127, 0, 1,
1}:5000,{127, 0, 1, 1},5000, alive=20048, securePort=-1, UDP Port=-1,
id={-75 -112 -71 -42 50 -11 66 22 -119 -76 81 72 -52 -92 65 110 },
payload={}, command={}, domain={}, ]
Dec 17, 2013 10:52:41 AM org.apache.catalina.tribes.io.BufferPool
getBufferPool
INFO: Created a buffer pool with max size:104857600 bytes of
type:org.apache.catalina.tribes.io.BufferPool15Impl
Dec 17, 2013 10:52:42 AM
org.apache.catalina.tribes.membership.McastServiceImpl waitForMembers
INFO: Done sleeping, membership established, start level:4
Dec 17, 2013 10:52:42 AM
org.apache.catalina.tribes.membership.McastServiceImpl waitForMembers
INFO: Sleeping for 1000 milliseconds to establish cluster membership, start
level:8
Dec 17, 2013 10:52:43 AM
org.apache.catalina.tribes.membership.McastServiceImpl waitForMembers
INFO: Done sleeping, membership established, start level:8
Dec 17, 2013 10:52:43 AM org.apache.catalina.ha.deploy.FarmWarDeployer start
INFO: Cluster FarmWarDeployer started.
Dec 17, 2013 10:52:43 AM org.apache.catalina.startup.HostConfig deployWAR
INFO: Deploying web application archive
/usr/local/tomcat7/apache-tomcat-7.0.47/webapps/HATest.war
Dec 17, 2013 10:52:43 AM
org.apache.catalina.tribes.tipis.AbstractReplicatedMap init
INFO: Initializing AbstractReplicatedMap with context name:/HATest-map
Dec 17, 2013 10:52:43 AM
org.apache.catalina.tribes.group.interceptors.ThroughputInterceptor report
INFO: ThroughputInterceptor Report[
Tx Msg:1 messages
Sent:0.00 MB (total)
Sent:0.00 MB (application)
Time:0.01 seconds
Tx Speed:0.08 MB/sec (total)
TxSpeed:0.08 MB/sec (application)
Error Msg:0
Rx Msg:2 messages
Rx Speed:0.00 MB/sec (since 1st msg)
Received:0.00 MB]
Dec 17, 2013 10:52:43 AM org.apache.catalina.startup.HostConfig
deployDirectory
INFO: Deploying web application directory
/usr/local/tomcat7/apache-tomcat-7.0.47/webapps/docs
Dec 17, 2013 10:52:43 AM org.apache.catalina.startup.HostConfig
deployDirectory
INFO: Deploying web application directory
/usr/local/tomcat7/apache-tomcat-7.0.47/webapps/host-manager
Dec 17, 2013 10:52:44 AM org.apache.catalina.startup.HostConfig
deployDirectory
INFO: Deploying web application directory
/usr/local/tomcat7/apache-tomcat-7.0.47/webapps/ROOT
Dec 17, 2013 10:52:44 AM org.apache.catalina.startup.HostConfig
deployDirectory
INFO: Deploying web application directory
/usr/local/tomcat7/apache-tomcat-7.0.47/webapps/examples
Dec 17, 2013 10:52:44 AM org.apache.catalina.startup.HostConfig
deployDirectory
INFO: Deploying web application directory
/usr/local/tomcat7/apache-tomcat-7.0.47/webapps/manager
Dec 17, 2013 10:52:44 AM
org.apache.catalina.tribes.tipis.AbstractReplicatedMap init
INFO: Initializing AbstractReplicatedMap with context name:/manager-map
Dec 17, 2013 10:52:44 AM org.apache.coyote.AbstractProtocol start
INFO: Starting ProtocolHandler ["http-bio-8080"]
Dec 17, 2013 10:52:44 AM org.apache.coyote.AbstractProtocol start
INFO: Starting ProtocolHandler ["ajp-bio-8009"]
Dec 17, 2013 10:52:44 AM org.apache.catalina.startup.Catalina start
INFO: Server startup in 3571 ms
We have 3 sessions currently: one on node-1 and 2 on node-2 but there are
only primary sessions on each (3) and not backup sessions at all. what
could be the problem?
On Tue, Dec 17, 2013 at 10:25 AM, Keiichi Fujino <kf...@apache.org> wrote:
> DeltaManager starts session sync phase by sending a SESSION-GET-ALL message
> at startup.
> DeltaManager that has received the SESSION-GET-ALL message sends all
> session data by sending a ALL-SESSION-DATA message.
> Then sends a SESSION-STATE-TRANSFERED message in order to notify the
> transmission completion.
> DeltaManager that has received the SESSION-STATE-TRANSFERED message
> completes session sync phase.
>
>
> According to this log,
>
>
>
> > Dec 16, 2013 6:43:29 PM org.apache.catalina.ha.session.DeltaManager
> > waitForSendAllSessions
> > SEVERE: Manager [/HATest]: No session state send at 12/16/13 6:42 PM
> > received, timing out after 60,102 ms.
> >
>
> This log means that time-out occurred in session sync phase. (Default 60
> seconds)
>
> and
>
>
>
> > Dec 16, 2013 6:43:29 PM org.apache.catalina.ha.session.DeltaManager
> > getAllClusterSessions
> > WARNING: Manager [/HATest]: Drop message SESSION-GET-ALL inside
> > GET_ALL_SESSIONS sync phase start date 12/16/13 6:42 PM message date
> 1/1/70
> > 2:00 AM
> >
>
> This log means that SESSION-GET-ALL message that received during session
> sync phase is dropped.
>
> Thus, It seems that two nodes were started at the same time.
> If SESSION-GET-ALL message is dropped, SESSION-STATE-TRANSFERED message can
> not be received.
> As a result, will be time-out in session sync phase.
>
> You should start Tomcat in proper order (rather than simultaneously).
>
> Another problem.
> In warning log, time stamp of the SESSION-GET-ALL messages that were
> dropped has become to 1/1/70.
> This is just a trivial bug.
> I will fix this later.
> That way, the correct time stamp will be output.
>
>
>
>
> > Dec 16, 2013 6:43:29 PM org.apache.catalina.startup.HostConfig
> > deployDirectory
> > INFO: Deploying web application directory
> > /usr/local/tomcat7/apache-tomcat-7.0.47/webapps/docs
> > Dec 16, 2013 6:43:29 PM org.apache.catalina.startup.HostConfig
> > deployDirectory
> > INFO: Deploying web application directory
> > /usr/local/tomcat7/apache-tomcat-7.0.47/webapps/host-manager
> > Dec 16, 2013 6:43:29 PM org.apache.catalina.startup.HostConfig
> > deployDirectory
> > INFO: Deploying web application directory
> > /usr/local/tomcat7/apache-tomcat-7.0.47/webapps/ROOT
> > Dec 16, 2013 6:43:29 PM org.apache.catalina.startup.HostConfig
> > deployDirectory
> > INFO: Deploying web application directory
> > /usr/local/tomcat7/apache-tomcat-7.0.47/webapps/examples
> > Dec 16, 2013 6:43:30 PM org.apache.catalina.startup.HostConfig
> > deployDirectory
> > INFO: Deploying web application directory
> > /usr/local/tomcat7/apache-tomcat-7.0.47/webapps/manager
> > Dec 16, 2013 6:43:30 PM org.apache.catalina.ha.session.DeltaManager
> > startInternal
> > INFO: Register manager /manager to cluster element Host with name
> localhost
> > Dec 16, 2013 6:43:30 PM org.apache.catalina.ha.session.DeltaManager
> > startInternal
> > INFO: Starting clustering manager at /manager
> > Dec 16, 2013 6:43:30 PM org.apache.catalina.ha.session.DeltaManager
> > getAllClusterSessions
> > INFO: Manager [/manager], requesting session state from
> > org.apache.catalina.tribes.membership.MemberImpl[tcp://{127, 0, 1,
> > 1}:5000,{127, 0, 1, 1},5000, alive=65057, securePort=-1, UDP Port=-1,
> > id={-90 41 -113 110 96 -50 78 -88 -79 -103 1 61 -60 -125 75 44 },
> > payload={}, command={}, domain={}, ]. This operation will timeout if no
> > session state has been received within 60 seconds.
> > Dec 16, 2013 6:44:16 PM
> > org.apache.catalina.tribes.group.interceptors.TcpFailureDetector
> > memberDisappeared
> > INFO: Verification complete. Member
> > disappeared[org.apache.catalina.tribes.membership.MemberImpl[tcp://{127,
> 0,
> > 1, 1}:5000,{127, 0, 1, 1},5000, alive=112037, securePort=-1, UDP Port=-1,
> > id={-90 41 -113 110 96 -50 78 -88 -79 -103 1 61 -60 -125 75 44 },
> > payload={}, command={66 65 66 89 45 65 76 69 88 ...(9)}, domain={}, ]]
> > Dec 16, 2013 6:44:16 PM org.apache.catalina.ha.tcp.SimpleTcpCluster
> > memberDisappeared
> > INFO: Received member
> > disappeared:org.apache.catalina.tribes.membership.MemberImpl[tcp://{127,
> 0,
> > 1, 1}:5000,{127, 0, 1, 1},5000, alive=112037, securePort=-1, UDP Port=-1,
> > id={-90 41 -113 110 96 -50 78 -88 -79 -103 1 61 -60 -125 75 44 },
> > payload={}, command={66 65 66 89 45 65 76 69 88 ...(9)}, domain={}, ]
> > Dec 16, 2013 6:44:22 PM org.apache.catalina.ha.tcp.SimpleTcpCluster
> > memberAdded
> > INFO: Replication member
> > added:org.apache.catalina.tribes.membership.MemberImpl[tcp://{127, 0, 1,
> > 1}:5000,{127, 0, 1, 1},5000, alive=1014, securePort=-1, UDP Port=-1,
> id={75
> > 3 86 -1 25 78 67 111 -125 -65 74 58 79 -20 93 16 }, payload={},
> command={},
> > domain={}, ]
> > Dec 16, 2013 6:44:30 PM org.apache.catalina.ha.session.DeltaManager
> > waitForSendAllSessions
> > SEVERE: Manager [/manager]: No session state send at 12/16/13 6:43 PM
> > received, timing out after 60,081 ms.
> > Dec 16, 2013 6:44:30 PM org.apache.catalina.ha.session.DeltaManager
> > getAllClusterSessions
> > WARNING: Manager [/manager]: Drop message SESSION-GET-ALL inside
> > GET_ALL_SESSIONS sync phase start date 12/16/13 6:43 PM message date
> 1/1/70
> > 2:00 AM
> > Dec 16, 2013 6:44:30 PM org.apache.coyote.AbstractProtocol start
> > INFO: Starting ProtocolHandler ["http-bio-8080"]
> > Dec 16, 2013 6:44:30 PM org.apache.coyote.AbstractProtocol start
> > INFO: Starting ProtocolHandler ["ajp-bio-8009"]
> > Dec 16, 2013 6:44:30 PM org.apache.catalina.startup.Catalina start
> > INFO: Server startup in 123619 ms
> >
> >
> >
> >
> >
> > *When we try to configure the Backup manager (which is my goal actually)
> > with the same server.xml only with backup manager tag:*
> > <Manager className="org.apache.catalina.ha.session.BackupManager"
> > expireSessionsOnShutdown="false"
> > notifyListenersOnReplication="true"
> > mapSendOptions="6"/>
> >
> >
> > *We get the following log (again, no replication):*
> >
> >
> > INFO: Cluster is about to start
> > Dec 16, 2013 6:56:40 PM org.apache.catalina.tribes.transport.ReceiverBase
> > bind
> > INFO: Receiver Server Socket bound to:/127.0.1.1:5000
> > Dec 16, 2013 6:56:40 PM
> > org.apache.catalina.tribes.membership.McastServiceImpl setupSocket
> > INFO: Setting cluster mcast soTimeout to 500
> > Dec 16, 2013 6:56:40 PM
> > org.apache.catalina.tribes.membership.McastServiceImpl waitForMembers
> > INFO: Sleeping for 1000 milliseconds to establish cluster membership,
> start
> > level:4
> > Dec 16, 2013 6:56:40 PM org.apache.catalina.ha.tcp.SimpleTcpCluster
> > memberAdded
> > INFO: Replication member
> > added:org.apache.catalina.tribes.membership.MemberImpl[tcp://{127, 0, 1,
> > 1}:5000,{127, 0, 1, 1},5000, alive=23027, securePort=-1, UDP Port=-1,
> > id={52 -40 0 -117 -60 82 71 -42 -110 21 -91 -16 88 -96 -46 -113 },
> > payload={}, command={}, domain={}, ]
> > Dec 16, 2013 6:56:41 PM org.apache.catalina.tribes.io.BufferPool
> > getBufferPool
> > INFO: Created a buffer pool with max size:104857600 bytes of
> > type:org.apache.catalina.tribes.io.BufferPool15Impl
> > Dec 16, 2013 6:56:41 PM
> > org.apache.catalina.tribes.membership.McastServiceImpl waitForMembers
> > INFO: Done sleeping, membership established, start level:4
> > Dec 16, 2013 6:56:41 PM
> > org.apache.catalina.tribes.membership.McastServiceImpl waitForMembers
> > INFO: Sleeping for 1000 milliseconds to establish cluster membership,
> start
> > level:8
> > Dec 16, 2013 6:56:42 PM
> > org.apache.catalina.tribes.membership.McastServiceImpl waitForMembers
> > INFO: Done sleeping, membership established, start level:8
> > Dec 16, 2013 6:56:42 PM org.apache.catalina.ha.deploy.FarmWarDeployer
> start
> > INFO: Cluster FarmWarDeployer started.
> > Dec 16, 2013 6:56:42 PM org.apache.catalina.startup.HostConfig deployWAR
> > INFO: Deploying web application archive
> > /usr/local/tomcat7/apache-tomcat-7.0.47/webapps/HATest.war
> > Dec 16, 2013 6:56:43 PM
> > org.apache.catalina.tribes.tipis.AbstractReplicatedMap init
> > INFO: Initializing AbstractReplicatedMap with context name:/HATest-map
> > Dec 16, 2013 6:56:43 PM
> > org.apache.catalina.tribes.group.interceptors.ThroughputInterceptor
> report
> > INFO: ThroughputInterceptor Report[
> > Tx Msg:1 messages
> > Sent:0.00 MB (total)
> > Sent:0.00 MB (application)
> > Time:0.01 seconds
> > Tx Speed:0.09 MB/sec (total)
> > TxSpeed:0.09 MB/sec (application)
> > Error Msg:0
> > Rx Msg:2 messages
> > Rx Speed:0.00 MB/sec (since 1st msg)
> > Received:0.00 MB]
> >
> > Dec 16, 2013 6:56:43 PM org.apache.catalina.startup.HostConfig
> > deployDirectory
> > INFO: Deploying web application directory
> > /usr/local/tomcat7/apache-tomcat-7.0.47/webapps/docs
> > Dec 16, 2013 6:56:43 PM org.apache.catalina.startup.HostConfig
> > deployDirectory
> > INFO: Deploying web application directory
> > /usr/local/tomcat7/apache-tomcat-7.0.47/webapps/host-manager
> > Dec 16, 2013 6:56:43 PM org.apache.catalina.startup.HostConfig
> > deployDirectory
> > INFO: Deploying web application directory
> > /usr/local/tomcat7/apache-tomcat-7.0.47/webapps/ROOT
> > Dec 16, 2013 6:56:43 PM org.apache.catalina.startup.HostConfig
> > deployDirectory
> > INFO: Deploying web application directory
> > /usr/local/tomcat7/apache-tomcat-7.0.47/webapps/examples
> > Dec 16, 2013 6:56:44 PM org.apache.catalina.startup.HostConfig
> > deployDirectory
> > INFO: Deploying web application directory
> > /usr/local/tomcat7/apache-tomcat-7.0.47/webapps/manager
> > Dec 16, 2013 6:56:44 PM
> > org.apache.catalina.tribes.tipis.AbstractReplicatedMap init
> > INFO: Initializing AbstractReplicatedMap with context name:/manager-map
> > Dec 16, 2013 6:56:44 PM org.apache.coyote.AbstractProtocol start
> > INFO: Starting ProtocolHandler ["http-bio-8080"]
> > Dec 16, 2013 6:56:44 PM org.apache.coyote.AbstractProtocol start
> > INFO: Starting ProtocolHandler ["ajp-bio-8009"]
> > Dec 16, 2013 6:56:44 PM org.apache.catalina.startup.Catalina start
> > INFO: Server startup in 3535 ms
> >
> >
> >
> >
> >
> >
> > *It appears there are no severe errors on the log file with the backup
> > manager setup, but still we got no replication going.*
> > *Of course we added the *<distributable/>
> > *tag to both our web.xml of the tomcats AND for the WAR's web.xml as
> well.*
> >
> >
> > *Any ideas why this is happening? *
> >
> > Regards and many thanks,
> >
> > NGT.
> >
> > --
> > Keiichi.Fujino
>
Re: Tomcat Clustering - when the tomcat instances are on different machines
Posted by Keiichi Fujino <kf...@apache.org>.
DeltaManager starts session sync phase by sending a SESSION-GET-ALL message
at startup.
DeltaManager that has received the SESSION-GET-ALL message sends all
session data by sending a ALL-SESSION-DATA message.
Then sends a SESSION-STATE-TRANSFERED message in order to notify the
transmission completion.
DeltaManager that has received the SESSION-STATE-TRANSFERED message
completes session sync phase.
According to this log,
> Dec 16, 2013 6:43:29 PM org.apache.catalina.ha.session.DeltaManager
> waitForSendAllSessions
> SEVERE: Manager [/HATest]: No session state send at 12/16/13 6:42 PM
> received, timing out after 60,102 ms.
>
This log means that time-out occurred in session sync phase. (Default 60
seconds)
and
> Dec 16, 2013 6:43:29 PM org.apache.catalina.ha.session.DeltaManager
> getAllClusterSessions
> WARNING: Manager [/HATest]: Drop message SESSION-GET-ALL inside
> GET_ALL_SESSIONS sync phase start date 12/16/13 6:42 PM message date 1/1/70
> 2:00 AM
>
This log means that SESSION-GET-ALL message that received during session
sync phase is dropped.
Thus, It seems that two nodes were started at the same time.
If SESSION-GET-ALL message is dropped, SESSION-STATE-TRANSFERED message can
not be received.
As a result, will be time-out in session sync phase.
You should start Tomcat in proper order (rather than simultaneously).
Another problem.
In warning log, time stamp of the SESSION-GET-ALL messages that were
dropped has become to 1/1/70.
This is just a trivial bug.
I will fix this later.
That way, the correct time stamp will be output.
> Dec 16, 2013 6:43:29 PM org.apache.catalina.startup.HostConfig
> deployDirectory
> INFO: Deploying web application directory
> /usr/local/tomcat7/apache-tomcat-7.0.47/webapps/docs
> Dec 16, 2013 6:43:29 PM org.apache.catalina.startup.HostConfig
> deployDirectory
> INFO: Deploying web application directory
> /usr/local/tomcat7/apache-tomcat-7.0.47/webapps/host-manager
> Dec 16, 2013 6:43:29 PM org.apache.catalina.startup.HostConfig
> deployDirectory
> INFO: Deploying web application directory
> /usr/local/tomcat7/apache-tomcat-7.0.47/webapps/ROOT
> Dec 16, 2013 6:43:29 PM org.apache.catalina.startup.HostConfig
> deployDirectory
> INFO: Deploying web application directory
> /usr/local/tomcat7/apache-tomcat-7.0.47/webapps/examples
> Dec 16, 2013 6:43:30 PM org.apache.catalina.startup.HostConfig
> deployDirectory
> INFO: Deploying web application directory
> /usr/local/tomcat7/apache-tomcat-7.0.47/webapps/manager
> Dec 16, 2013 6:43:30 PM org.apache.catalina.ha.session.DeltaManager
> startInternal
> INFO: Register manager /manager to cluster element Host with name localhost
> Dec 16, 2013 6:43:30 PM org.apache.catalina.ha.session.DeltaManager
> startInternal
> INFO: Starting clustering manager at /manager
> Dec 16, 2013 6:43:30 PM org.apache.catalina.ha.session.DeltaManager
> getAllClusterSessions
> INFO: Manager [/manager], requesting session state from
> org.apache.catalina.tribes.membership.MemberImpl[tcp://{127, 0, 1,
> 1}:5000,{127, 0, 1, 1},5000, alive=65057, securePort=-1, UDP Port=-1,
> id={-90 41 -113 110 96 -50 78 -88 -79 -103 1 61 -60 -125 75 44 },
> payload={}, command={}, domain={}, ]. This operation will timeout if no
> session state has been received within 60 seconds.
> Dec 16, 2013 6:44:16 PM
> org.apache.catalina.tribes.group.interceptors.TcpFailureDetector
> memberDisappeared
> INFO: Verification complete. Member
> disappeared[org.apache.catalina.tribes.membership.MemberImpl[tcp://{127, 0,
> 1, 1}:5000,{127, 0, 1, 1},5000, alive=112037, securePort=-1, UDP Port=-1,
> id={-90 41 -113 110 96 -50 78 -88 -79 -103 1 61 -60 -125 75 44 },
> payload={}, command={66 65 66 89 45 65 76 69 88 ...(9)}, domain={}, ]]
> Dec 16, 2013 6:44:16 PM org.apache.catalina.ha.tcp.SimpleTcpCluster
> memberDisappeared
> INFO: Received member
> disappeared:org.apache.catalina.tribes.membership.MemberImpl[tcp://{127, 0,
> 1, 1}:5000,{127, 0, 1, 1},5000, alive=112037, securePort=-1, UDP Port=-1,
> id={-90 41 -113 110 96 -50 78 -88 -79 -103 1 61 -60 -125 75 44 },
> payload={}, command={66 65 66 89 45 65 76 69 88 ...(9)}, domain={}, ]
> Dec 16, 2013 6:44:22 PM org.apache.catalina.ha.tcp.SimpleTcpCluster
> memberAdded
> INFO: Replication member
> added:org.apache.catalina.tribes.membership.MemberImpl[tcp://{127, 0, 1,
> 1}:5000,{127, 0, 1, 1},5000, alive=1014, securePort=-1, UDP Port=-1, id={75
> 3 86 -1 25 78 67 111 -125 -65 74 58 79 -20 93 16 }, payload={}, command={},
> domain={}, ]
> Dec 16, 2013 6:44:30 PM org.apache.catalina.ha.session.DeltaManager
> waitForSendAllSessions
> SEVERE: Manager [/manager]: No session state send at 12/16/13 6:43 PM
> received, timing out after 60,081 ms.
> Dec 16, 2013 6:44:30 PM org.apache.catalina.ha.session.DeltaManager
> getAllClusterSessions
> WARNING: Manager [/manager]: Drop message SESSION-GET-ALL inside
> GET_ALL_SESSIONS sync phase start date 12/16/13 6:43 PM message date 1/1/70
> 2:00 AM
> Dec 16, 2013 6:44:30 PM org.apache.coyote.AbstractProtocol start
> INFO: Starting ProtocolHandler ["http-bio-8080"]
> Dec 16, 2013 6:44:30 PM org.apache.coyote.AbstractProtocol start
> INFO: Starting ProtocolHandler ["ajp-bio-8009"]
> Dec 16, 2013 6:44:30 PM org.apache.catalina.startup.Catalina start
> INFO: Server startup in 123619 ms
>
>
>
>
>
> *When we try to configure the Backup manager (which is my goal actually)
> with the same server.xml only with backup manager tag:*
> <Manager className="org.apache.catalina.ha.session.BackupManager"
> expireSessionsOnShutdown="false"
> notifyListenersOnReplication="true"
> mapSendOptions="6"/>
>
>
> *We get the following log (again, no replication):*
>
>
> INFO: Cluster is about to start
> Dec 16, 2013 6:56:40 PM org.apache.catalina.tribes.transport.ReceiverBase
> bind
> INFO: Receiver Server Socket bound to:/127.0.1.1:5000
> Dec 16, 2013 6:56:40 PM
> org.apache.catalina.tribes.membership.McastServiceImpl setupSocket
> INFO: Setting cluster mcast soTimeout to 500
> Dec 16, 2013 6:56:40 PM
> org.apache.catalina.tribes.membership.McastServiceImpl waitForMembers
> INFO: Sleeping for 1000 milliseconds to establish cluster membership, start
> level:4
> Dec 16, 2013 6:56:40 PM org.apache.catalina.ha.tcp.SimpleTcpCluster
> memberAdded
> INFO: Replication member
> added:org.apache.catalina.tribes.membership.MemberImpl[tcp://{127, 0, 1,
> 1}:5000,{127, 0, 1, 1},5000, alive=23027, securePort=-1, UDP Port=-1,
> id={52 -40 0 -117 -60 82 71 -42 -110 21 -91 -16 88 -96 -46 -113 },
> payload={}, command={}, domain={}, ]
> Dec 16, 2013 6:56:41 PM org.apache.catalina.tribes.io.BufferPool
> getBufferPool
> INFO: Created a buffer pool with max size:104857600 bytes of
> type:org.apache.catalina.tribes.io.BufferPool15Impl
> Dec 16, 2013 6:56:41 PM
> org.apache.catalina.tribes.membership.McastServiceImpl waitForMembers
> INFO: Done sleeping, membership established, start level:4
> Dec 16, 2013 6:56:41 PM
> org.apache.catalina.tribes.membership.McastServiceImpl waitForMembers
> INFO: Sleeping for 1000 milliseconds to establish cluster membership, start
> level:8
> Dec 16, 2013 6:56:42 PM
> org.apache.catalina.tribes.membership.McastServiceImpl waitForMembers
> INFO: Done sleeping, membership established, start level:8
> Dec 16, 2013 6:56:42 PM org.apache.catalina.ha.deploy.FarmWarDeployer start
> INFO: Cluster FarmWarDeployer started.
> Dec 16, 2013 6:56:42 PM org.apache.catalina.startup.HostConfig deployWAR
> INFO: Deploying web application archive
> /usr/local/tomcat7/apache-tomcat-7.0.47/webapps/HATest.war
> Dec 16, 2013 6:56:43 PM
> org.apache.catalina.tribes.tipis.AbstractReplicatedMap init
> INFO: Initializing AbstractReplicatedMap with context name:/HATest-map
> Dec 16, 2013 6:56:43 PM
> org.apache.catalina.tribes.group.interceptors.ThroughputInterceptor report
> INFO: ThroughputInterceptor Report[
> Tx Msg:1 messages
> Sent:0.00 MB (total)
> Sent:0.00 MB (application)
> Time:0.01 seconds
> Tx Speed:0.09 MB/sec (total)
> TxSpeed:0.09 MB/sec (application)
> Error Msg:0
> Rx Msg:2 messages
> Rx Speed:0.00 MB/sec (since 1st msg)
> Received:0.00 MB]
>
> Dec 16, 2013 6:56:43 PM org.apache.catalina.startup.HostConfig
> deployDirectory
> INFO: Deploying web application directory
> /usr/local/tomcat7/apache-tomcat-7.0.47/webapps/docs
> Dec 16, 2013 6:56:43 PM org.apache.catalina.startup.HostConfig
> deployDirectory
> INFO: Deploying web application directory
> /usr/local/tomcat7/apache-tomcat-7.0.47/webapps/host-manager
> Dec 16, 2013 6:56:43 PM org.apache.catalina.startup.HostConfig
> deployDirectory
> INFO: Deploying web application directory
> /usr/local/tomcat7/apache-tomcat-7.0.47/webapps/ROOT
> Dec 16, 2013 6:56:43 PM org.apache.catalina.startup.HostConfig
> deployDirectory
> INFO: Deploying web application directory
> /usr/local/tomcat7/apache-tomcat-7.0.47/webapps/examples
> Dec 16, 2013 6:56:44 PM org.apache.catalina.startup.HostConfig
> deployDirectory
> INFO: Deploying web application directory
> /usr/local/tomcat7/apache-tomcat-7.0.47/webapps/manager
> Dec 16, 2013 6:56:44 PM
> org.apache.catalina.tribes.tipis.AbstractReplicatedMap init
> INFO: Initializing AbstractReplicatedMap with context name:/manager-map
> Dec 16, 2013 6:56:44 PM org.apache.coyote.AbstractProtocol start
> INFO: Starting ProtocolHandler ["http-bio-8080"]
> Dec 16, 2013 6:56:44 PM org.apache.coyote.AbstractProtocol start
> INFO: Starting ProtocolHandler ["ajp-bio-8009"]
> Dec 16, 2013 6:56:44 PM org.apache.catalina.startup.Catalina start
> INFO: Server startup in 3535 ms
>
>
>
>
>
>
> *It appears there are no severe errors on the log file with the backup
> manager setup, but still we got no replication going.*
> *Of course we added the *<distributable/>
> *tag to both our web.xml of the tomcats AND for the WAR's web.xml as well.*
>
>
> *Any ideas why this is happening? *
>
> Regards and many thanks,
>
> NGT.
>
> --
> Keiichi.Fujino