3 Replies Latest reply on Mar 19, 2009 7:33 PM by dukehoops

JBC+JGroups: 2nd Tomcat hangs during startup

dukehoops Mar 19, 2009 6:08 PM

I realize this is quite likely a JGroups config problem, but thought maybe someone can clue me in here. I have 2 tomcat nodes running JBC3 w/JGroups 2.7.0GA (in invalidation async mode) using identical config. Yet node started second never fully starts up but hangs somewhere during jbc/jgroups init time w/o any error messages. Looking at the logs below could someone please offer up a clue?

multicast addr is 232.10.10.11. Both nodes are on the same host but correctly use different ports in local_addr.

Note that the 1st node seems to receive a message from the 2nd node at 14:55:28:442

JGroups config

<!--
 Default stack using IP multicasting. It is similar to the "udp"
 stack in stacks.xml, but doesn't use streaming state transfer and flushing
 author: Bela Ban
 version: $Id: udp.xml,v 1.29 2008/09/26 15:59:33 belaban Exp $
-->
<!-- mcast_addr="${jgroups.udp.mcast_addr:232.10.10.10}" -->
<config>
 <UDP
 mcast_addr="${jgroups.udp.mcast_addr:CONFIG_MULTICAST_IN_DG_PROPS}"
 mcast_port="${jgroups.udp.mcast_port:45588}"
 tos="8"
 ucast_recv_buf_size="20000000"
 ucast_send_buf_size="640000"
 mcast_recv_buf_size="25000000"
 mcast_send_buf_size="640000"
 loopback="false"
 discard_incompatible_packets="true"
 max_bundle_size="64000"
 max_bundle_timeout="30"
 ip_ttl="${jgroups.udp.ip_ttl:1}"
 enable_bundling="true"
 enable_diagnostics="true"
 thread_naming_pattern="cl"

 thread_pool.enabled="true"
 thread_pool.min_threads="2"
 thread_pool.max_threads="8"
 thread_pool.keep_alive_time="5000"
 thread_pool.queue_enabled="true"
 thread_pool.queue_max_size="10000"
 thread_pool.rejection_policy="discard"

 oob_thread_pool.enabled="true"
 oob_thread_pool.min_threads="1"
 oob_thread_pool.max_threads="8"
 oob_thread_pool.keep_alive_time="5000"
 oob_thread_pool.queue_enabled="false"
 oob_thread_pool.queue_max_size="100"
 oob_thread_pool.rejection_policy="Run"/>

 <PING timeout="2000"
 num_initial_members="3"/>
 <MERGE2 max_interval="30000"
 min_interval="10000"/>
 <FD_SOCK/>
 <FD_ALL/>
 <VERIFY_SUSPECT timeout="1500" />
 <BARRIER />
 <pbcast.NAKACK use_stats_for_retransmission="false"
 exponential_backoff="150"
 use_mcast_xmit="true" gc_lag="0"
 retransmit_timeout="50,300,600,1200"
 discard_delivered_msgs="true"/>
 <UNICAST timeout="300,600,1200"/>
 <pbcast.STABLE stability_delay="1000" desired_avg_gossip="50000"
 max_bytes="1000000"/>
 <VIEW_SYNC avg_send_interval="60000" />
 <pbcast.GMS print_local_addr="true" join_timeout="3000"
 shun="false"
 view_bundling="true"/>
 <FC max_credits="500000"
 min_threshold="0.20"/>
 <FRAG2 frag_size="60000" />
 <!--pbcast.STREAMING_STATE_TRANSFER /-->
 <pbcast.STATE_TRANSFER />
 <!-- pbcast.FLUSH /-->
</config>

Output from Node 1 (that works fine):

[3/19/09 14:54:30:222] INFO org.jboss.cache.jmx.PlatformMBeanServerRegistration - JBossCache MBeans were successfully registered to the platform mbean server.
[3/19/09 14:54:30:255] INFO org.jgroups.JChannel - JGroups version: 2.7.0.GA
[3/19/09 14:54:30:310] DEBUG org.jgroups.conf.ClassConfigurator - mapping is:
1: class org.jgroups.stack.IpAddress
2: class org.jgroups.protocols.CAUSAL$CausalHeader
3: class org.jgroups.protocols.FD$FdHeader
6: class org.jgroups.protocols.FD_SOCK$FdHeader
7: class org.jgroups.protocols.FragHeader
13: class org.jgroups.protocols.PingHeader
21: class org.jgroups.protocols.UNICAST$UnicastHeader
22: class org.jgroups.protocols.VERIFY_SUSPECT$VerifyHeader
24: class org.jgroups.protocols.pbcast.GMS$GmsHeader
25: class org.jgroups.protocols.pbcast.NakAckHeader
27: class org.jgroups.protocols.pbcast.STABLE$StableHeader
28: class org.jgroups.protocols.pbcast.STATE_TRANSFER$StateHeader
29: class org.jgroups.protocols.SMACK$SmackHeader
30: class org.jgroups.Message
31: class org.jgroups.View
32: class org.jgroups.ViewId
34: interface org.jgroups.Address
35: class org.jgroups.blocks.RequestCorrelator$Header
36: class org.jgroups.protocols.PingRsp
38: class java.util.Vector
39: class org.jgroups.protocols.pbcast.JoinRsp
40: class org.jgroups.util.Digest
41: class java.util.Hashtable
53: class org.jgroups.protocols.COMPRESS$CompressHeader
54: class org.jgroups.protocols.FC$FcHeader
56: class org.jgroups.protocols.TpHeader
57: class org.jgroups.protocols.ENCRYPT$EncryptHeader
58: class org.jgroups.protocols.SEQUENCER$SequencerHeader
59: class org.jgroups.protocols.FD_SIMPLE$FdHeader
60: class org.jgroups.protocols.VIEW_SYNC$ViewSyncHeader
61: class org.jgroups.protocols.FD_ALL$Header
62: class org.jgroups.protocols.SFC$Header
63: class org.jgroups.mux.MuxHeader
64: class org.jgroups.protocols.pbcast.FLUSH$FlushHeader
65: class org.jgroups.protocols.pbcast.STREAMING_STATE_TRANSFER$StateHeader
66: class org.jgroups.blocks.PullPushAdapter$PullHeader
67: class org.jgroups.protocols.AuthHeader

[3/19/09 14:54:30:535] DEBUG org.jgroups.protocols.pbcast.GMS - changed role to org.jgroups.protocols.pbcast.ClientGmsImpl
[3/19/09 14:54:30:557] DEBUG org.jgroups.protocols.FRAG2 - received CONFIG event: {bind_addr=nikita-wx10/172.17.50.103}
[3/19/09 14:54:30:558] DEBUG org.jgroups.protocols.UDP - received CONFIG event: {bind_addr=nikita-wx10/172.17.50.103}
[3/19/09 14:54:30:585] DEBUG org.jgroups.protocols.UDP - received CONFIG event: {frag_size=59800}
[3/19/09 14:54:30:603] TRACE org.jgroups.protocols.pbcast.STABLE - stable task started
[3/19/09 14:54:30:603] DEBUG org.jgroups.protocols.UDP - creating sockets and starting threads
[3/19/09 14:54:30:603] DEBUG org.jgroups.protocols.UDP - sockets will use interface 172.17.50.103
[3/19/09 14:54:30:606] DEBUG org.jgroups.protocols.UDP - socket information:
local_addr=172.17.50.103:54561, mcast_addr=232.10.10.11:45588, bind_addr=nikita-wx10/172.17.50.103, ttl=1
sock: bound to 172.17.50.103:54561, receive buffer size=20000000, send buffer size=640000
mcast_sock: bound to 172.17.50.103:45588, send buffer size=640000, receive buffer size=25000000
[3/19/09 14:54:30:654] TRACE org.jgroups.protocols.UDP - joined /224.0.75.75:7500 on lo
[3/19/09 14:54:30:655] TRACE org.jgroups.protocols.UDP - joined /224.0.75.75:7500 on eth4
[3/19/09 14:54:30:656] TRACE org.jgroups.blocks.MessageDispatcher$ProtocolAdapter - setting local_addr (null) to 172.17.50.103:54561
[3/19/09 14:54:30:663] DEBUG org.jgroups.protocols.UDP - created unicast receiver thread
[3/19/09 14:54:30:663] DEBUG org.jgroups.protocols.UDP - created multicast receiver thread
[3/19/09 14:54:30:665] TRACE org.jgroups.protocols.FD_SOCK - waiting for client connections on nikita-wx10/172.17.50.103:62842
[3/19/09 14:54:30:673] TRACE org.jgroups.protocols.UDP - sending msg to null, src=172.17.50.103:54561, headers are PING: [PING: type=GET_MBRS_REQ, cluster=dgEntityCacheCluster], UDP: [channel_name=dgEntityCacheCluster]
[3/19/09 14:54:30:675] TRACE org.jgroups.protocols.UDP - received (mcast) 81 bytes from 172.17.50.103:45588
[3/19/09 14:54:30:680] TRACE org.jgroups.protocols.UDP - message is [dst: <null>, src: 172.17.50.103:54561 (2 headers), size=0 bytes, flags=OOB], headers are PING: [PING: type=GET_MBRS_REQ, cluster=dgEntityCacheCluster], UDP: [channel_name=dgEntityCacheCluster]
[3/19/09 14:54:31:676] TRACE org.jgroups.protocols.UDP - sending msg to null, src=172.17.50.103:54561, headers are PING: [PING: type=GET_MBRS_REQ, cluster=dgEntityCacheCluster], UDP: [channel_name=dgEntityCacheCluster]
[3/19/09 14:54:31:676] TRACE org.jgroups.protocols.UDP - received (mcast) 81 bytes from 172.17.50.103:45588
[3/19/09 14:54:31:676] TRACE org.jgroups.protocols.UDP - message is [dst: <null>, src: 172.17.50.103:54561 (2 headers), size=0 bytes, flags=OOB], headers are PING: [PING: type=GET_MBRS_REQ, cluster=dgEntityCacheCluster], UDP: [channel_name=dgEntityCacheCluster]
[3/19/09 14:54:32:671] TRACE org.jgroups.protocols.PING - discovery took 2007 ms: responses: 0 total (0 servers (0 coord), 0 clients)
[3/19/09 14:54:32:671] DEBUG org.jgroups.protocols.pbcast.GMS - initial_mbrs are []
[3/19/09 14:54:32:671] DEBUG org.jgroups.protocols.pbcast.GMS - no initial members discovered: creating group as first member
[3/19/09 14:54:32:685] DEBUG org.jgroups.protocols.pbcast.GMS - [local_addr=172.17.50.103:54561] view is [172.17.50.103:54561|0] [172.17.50.103:54561]
[3/19/09 14:54:32:689] DEBUG org.jgroups.protocols.FD_SOCK - VIEW_CHANGE received: [172.17.50.103:54561]
[3/19/09 14:54:32:691] TRACE org.jgroups.protocols.pbcast.STABLE - resetting digest from NAKACK: [172.17.50.103:54561#0]
[3/19/09 14:54:32:691] TRACE org.jgroups.protocols.FC - new membership: [172.17.50.103:54561]
[3/19/09 14:54:32:691] TRACE org.jgroups.protocols.FC - creditors are []
[3/19/09 14:54:32:692] INFO org.jboss.cache.RPCManagerImpl - Received new cluster view: [172.17.50.103:54561|0] [172.17.50.103:54561]
[3/19/09 14:54:32:698] DEBUG org.jgroups.protocols.pbcast.GMS - 172.17.50.103:54561 changed role to org.jgroups.protocols.pbcast.CoordGmsImpl
[3/19/09 14:54:32:698] DEBUG org.jgroups.protocols.pbcast.GMS - created group (first member). My view is [172.17.50.103:54561|0], impl is org.jgroups.protocols.pbcast.CoordGmsImpl
[3/19/09 14:54:32:698] INFO org.jboss.cache.RPCManagerImpl - Cache local address is 172.17.50.103:54561
[3/19/09 14:54:32:698] INFO org.jboss.cache.RPCManagerImpl - state was retrieved successfully (in 2098 milliseconds)
[3/19/09 14:54:32:698] INFO org.jboss.cache.factories.ComponentRegistry - JBoss Cache version: JBossCache 'Naga' 3.0.3.GA
[3/19/09 14:54:32:755] INFO org.jboss.cache.jmx.PlatformMBeanServerRegistration - JBossCache MBeans were successfully registered to the platform mbean server.
[3/19/09 14:54:32:756] TRACE org.jgroups.JChannel - already connected to dgCollectionCacheCluster
[3/19/09 14:54:32:756] INFO org.jboss.cache.RPCManagerImpl - Cache local address is 172.17.50.103:54561
[3/19/09 14:54:32:756] INFO org.jboss.cache.RPCManagerImpl - state was retrieved successfully (in 0 milliseconds)
[3/19/09 14:54:32:756] INFO org.jboss.cache.factories.ComponentRegistry - JBoss Cache version: JBossCache 'Naga' 3.0.3.GA
[3/19/09 14:54:32:810] INFO org.jboss.cache.jmx.PlatformMBeanServerRegistration - JBossCache MBeans were successfully registered to the platform mbean server.
[3/19/09 14:54:32:811] TRACE org.jgroups.JChannel - already connected to dgTimestampsCacheCluster
[3/19/09 14:54:32:811] INFO org.jboss.cache.RPCManagerImpl - Cache local address is 172.17.50.103:54561
[3/19/09 14:54:32:811] INFO org.jboss.cache.RPCManagerImpl - state was retrieved successfully (in 0 milliseconds)
[3/19/09 14:54:32:811] INFO org.jboss.cache.factories.ComponentRegistry - JBoss Cache version: JBossCache 'Naga' 3.0.3.GA
[3/19/09 14:54:32:847] INFO org.jboss.cache.jmx.PlatformMBeanServerRegistration - JBossCache MBeans were successfully registered to the platform mbean server.
[3/19/09 14:54:32:847] INFO org.jboss.cache.factories.ComponentRegistry - JBoss Cache version: JBossCache 'Naga' 3.0.3.GA
[3/19/09 14:54:35:208] TRACE org.jgroups.protocols.UDP - sending msg to null, src=172.17.50.103:54561, headers are PING: [PING: type=GET_MBRS_REQ, cluster=dgEntityCacheCluster], UDP: [channel_name=dgEntityCacheCluster]
[3/19/09 14:54:35:208] TRACE org.jgroups.protocols.UDP - received (mcast) 81 bytes from 172.17.50.103:45588
[3/19/09 14:54:35:208] TRACE org.jgroups.protocols.UDP - message is [dst: <null>, src: 172.17.50.103:54561 (2 headers), size=0 bytes, flags=OOB], headers are PING: [PING: type=GET_MBRS_REQ, cluster=dgEntityCacheCluster], UDP: [channel_name=dgEntityCacheCluster]
[3/19/09 14:54:35:758] WARN org.hibernate.bytecode.cglib.BytecodeProviderImpl - The CGLIB BytecodeProvider impl is considered deprecated and not recommended for use
[3/19/09 14:54:36:209] TRACE org.jgroups.protocols.UDP - sending msg to null, src=172.17.50.103:54561, headers are PING: [PING: type=GET_MBRS_REQ, cluster=dgEntityCacheCluster], UDP: [channel_name=dgEntityCacheCluster]
[3/19/09 14:54:36:209] TRACE org.jgroups.protocols.UDP - received (mcast) 81 bytes from 172.17.50.103:45588
[3/19/09 14:54:36:209] TRACE org.jgroups.protocols.UDP - message is [dst: <null>, src: 172.17.50.103:54561 (2 headers), size=0 bytes, flags=OOB], headers are PING: [PING: type=GET_MBRS_REQ, cluster=dgEntityCacheCluster], UDP: [channel_name=dgEntityCacheCluster]
[3/19/09 14:54:37:195] TRACE org.jgroups.protocols.PING - discovery took 2003 ms: responses: 0 total (0 servers (0 coord), 0 clients)
[3/19/09 14:54:37:195] DEBUG org.jgroups.protocols.MERGE2 - 172.17.50.103:54561 is looking for merge candidates, found initial_mbrs=[[own_addr=172.17.50.103:54561, coord_addr=172.17.50.103:54561, is_server=true, is_coord=true]]
[3/19/09 14:54:37:195] TRACE org.jgroups.protocols.MERGE2 - MERGE2.FindSubgroups thread terminated (local_addr=172.17.50.103:54561)
[3/19/09 14:54:40:605] TRACE org.jgroups.protocols.pbcast.STABLE - setting latest_local_digest from NAKACK: [172.17.50.103:54561#0]
[3/19/09 14:54:40:605] TRACE org.jgroups.protocols.pbcast.STABLE - sending stable msg [172.17.50.103:54561#0]
[3/19/09 14:54:40:610] TRACE org.jgroups.protocols.pbcast.NAKACK - sending 172.17.50.103:54561#1
[3/19/09 14:54:40:611] TRACE org.jgroups.protocols.UDP - sending msg to null, src=172.17.50.103:54561, headers are STABLE: [STABLE_GOSSIP]: digest is 172.17.50.103:54561: [0 : 0 (0)], NAKACK: [MSG, seqno=1], UDP: [channel_name=dgEntityCacheCluster]
[3/19/09 14:54:40:611] TRACE org.jgroups.protocols.UDP - received (mcast) 122 bytes from 172.17.50.103:45588
[3/19/09 14:54:40:613] TRACE org.jgroups.protocols.UDP - message is [dst: <null>, src: 172.17.50.103:54561 (3 headers), size=0 bytes, flags=OOB], headers are STABLE: [STABLE_GOSSIP]: digest is 172.17.50.103:54561: [0 : 0 (0)], NAKACK: [MSG, seqno=1], UDP: [channel_name=dgEntityCacheCluster]
[3/19/09 14:54:40:613] TRACE org.jgroups.protocols.pbcast.NAKACK - [172.17.50.103:54561: received 172.17.50.103:54561#1
[3/19/09 14:54:40:613] TRACE org.jgroups.protocols.pbcast.STABLE - [172.17.50.103:54561] handling digest from 172.17.50.103:54561 (0 votes):
mine: [172.17.50.103:54561#0]
other: [172.17.50.103:54561#0]
result: [172.17.50.103:54561#0]

[3/19/09 14:54:40:613] TRACE org.jgroups.protocols.pbcast.STABLE - sending stability msg (in 17 ms) [172.17.50.103:54561#0] (copy=32850875)
[3/19/09 14:54:40:658] TRACE org.jgroups.protocols.pbcast.STABLE - sending stability msg [172.17.50.103:54561#0] (copy=32850875)
[3/19/09 14:54:40:659] TRACE org.jgroups.protocols.pbcast.NAKACK - sending 172.17.50.103:54561#2
[3/19/09 14:54:40:659] TRACE org.jgroups.protocols.UDP - sending msg to null, src=172.17.50.103:54561, headers are STABLE: [STABILITY]: digest is 172.17.50.103:54561: [0 : 0 (0)], NAKACK: [MSG, seqno=2], UDP: [channel_name=dgEntityCacheCluster]
[3/19/09 14:54:40:659] TRACE org.jgroups.protocols.UDP - received (mcast) 122 bytes from 172.17.50.103:45588
[3/19/09 14:54:40:659] TRACE org.jgroups.protocols.UDP - message is [dst: <null>, src: 172.17.50.103:54561 (3 headers), size=0 bytes, flags=OOB], headers are STABLE: [STABILITY]: digest is 172.17.50.103:54561: [0 : 0 (0)], NAKACK: [MSG, seqno=2], UDP: [channel_name=dgEntityCacheCluster]
[3/19/09 14:54:40:659] TRACE org.jgroups.protocols.pbcast.NAKACK - [172.17.50.103:54561: received 172.17.50.103:54561#2
[3/19/09 14:54:40:659] TRACE org.jgroups.protocols.pbcast.STABLE - received stability msg from 172.17.50.103:54561: [172.17.50.103:54561#0]
[3/19/09 14:54:40:659] TRACE org.jgroups.protocols.pbcast.STABLE - resetting digest from NAKACK: [172.17.50.103:54561#1]
[3/19/09 14:54:40:659] TRACE org.jgroups.protocols.pbcast.NAKACK - received stable digest 172.17.50.103:54561: [0 : 0 (0)]
[3/19/09 14:54:40:659] TRACE org.jgroups.protocols.pbcast.NAKACK - deleting msgs <= 0 from 172.17.50.103:54561
[3/19/09 14:54:59:601] TRACE org.jgroups.protocols.UDP - sending msg to null, src=172.17.50.103:54561, headers are PING: [PING: type=GET_MBRS_REQ, cluster=dgEntityCacheCluster], UDP: [channel_name=dgEntityCacheCluster]
[3/19/09 14:54:59:601] TRACE org.jgroups.protocols.UDP - received (mcast) 81 bytes from 172.17.50.103:45588
[3/19/09 14:54:59:601] TRACE org.jgroups.protocols.UDP - message is [dst: <null>, src: 172.17.50.103:54561 (2 headers), size=0 bytes, flags=OOB], headers are PING: [PING: type=GET_MBRS_REQ, cluster=dgEntityCacheCluster], UDP: [channel_name=dgEntityCacheCluster]
[3/19/09 14:55:00:602] TRACE org.jgroups.protocols.UDP - sending msg to null, src=172.17.50.103:54561, headers are PING: [PING: type=GET_MBRS_REQ, cluster=dgEntityCacheCluster], UDP: [channel_name=dgEntityCacheCluster]
[3/19/09 14:55:00:602] TRACE org.jgroups.protocols.UDP - received (mcast) 81 bytes from 172.17.50.103:45588
[3/19/09 14:55:00:602] TRACE org.jgroups.protocols.UDP - message is [dst: <null>, src: 172.17.50.103:54561 (2 headers), size=0 bytes, flags=OOB], headers are PING: [PING: type=GET_MBRS_REQ, cluster=dgEntityCacheCluster], UDP: [channel_name=dgEntityCacheCluster]
[3/19/09 14:55:01:603] TRACE org.jgroups.protocols.PING - discovery took 2002 ms: responses: 0 total (0 servers (0 coord), 0 clients)
[3/19/09 14:55:01:603] DEBUG org.jgroups.protocols.MERGE2 - 172.17.50.103:54561 is looking for merge candidates, found initial_mbrs=[[own_addr=172.17.50.103:54561, coord_addr=172.17.50.103:54561, is_server=true, is_coord=true]]
[3/19/09 14:55:01:603] TRACE org.jgroups.protocols.MERGE2 - MERGE2.FindSubgroups thread terminated (local_addr=172.17.50.103:54561)
[3/19/09 14:55:24:010] TRACE org.jgroups.protocols.UDP - sending msg to null, src=172.17.50.103:54561, headers are PING: [PING: type=GET_MBRS_REQ, cluster=dgEntityCacheCluster], UDP: [channel_name=dgEntityCacheCluster]
[3/19/09 14:55:24:017] TRACE org.jgroups.protocols.UDP - received (mcast) 81 bytes from 172.17.50.103:45588
[3/19/09 14:55:24:017] TRACE org.jgroups.protocols.UDP - message is [dst: <null>, src: 172.17.50.103:54561 (2 headers), size=0 bytes, flags=OOB], headers are PING: [PING: type=GET_MBRS_REQ, cluster=dgEntityCacheCluster], UDP: [channel_name=dgEntityCacheCluster]
[3/19/09 14:55:25:011] TRACE org.jgroups.protocols.UDP - sending msg to null, src=172.17.50.103:54561, headers are PING: [PING: type=GET_MBRS_REQ, cluster=dgEntityCacheCluster], UDP: [channel_name=dgEntityCacheCluster]
[3/19/09 14:55:25:011] TRACE org.jgroups.protocols.UDP - received (mcast) 81 bytes from 172.17.50.103:45588
[3/19/09 14:55:25:011] TRACE org.jgroups.protocols.UDP - message is [dst: <null>, src: 172.17.50.103:54561 (2 headers), size=0 bytes, flags=OOB], headers are PING: [PING: type=GET_MBRS_REQ, cluster=dgEntityCacheCluster], UDP: [channel_name=dgEntityCacheCluster]
[3/19/09 14:55:26:010] TRACE org.jgroups.protocols.PING - discovery took 2002 ms: responses: 0 total (0 servers (0 coord), 0 clients)
[3/19/09 14:55:26:010] DEBUG org.jgroups.protocols.MERGE2 - 172.17.50.103:54561 is looking for merge candidates, found initial_mbrs=[[own_addr=172.17.50.103:54561, coord_addr=172.17.50.103:54561, is_server=true, is_coord=true]]
[3/19/09 14:55:26:010] TRACE org.jgroups.protocols.MERGE2 - MERGE2.FindSubgroups thread terminated (local_addr=172.17.50.103:54561)
[3/19/09 14:55:28:442] TRACE org.jgroups.protocols.UDP - received (mcast) 81 bytes from 172.17.50.103:45588
[3/19/09 14:55:28:442] TRACE org.jgroups.protocols.UDP - message is [dst: <null>, src: 172.17.50.103:56879 (2 headers), size=0 bytes, flags=OOB], headers are PING: [PING: type=GET_MBRS_REQ, cluster=dgEntityCacheCluster], UDP: [channel_name=dgEntityCacheCluster]
[3/19/09 14:55:28:442] TRACE org.jgroups.protocols.PING - received GET_MBRS_REQ from 172.17.50.103:56879, sending response [PING: type=GET_MBRS_RSP, arg=[own_addr=172.17.50.103:54561, coord_addr=172.17.50.103:54561, is_server=true, is_coord=true]]
[3/19/09 14:55:28:443] TRACE org.jgroups.protocols.UDP - sending msg to 172.17.50.103:56879, src=172.17.50.103:54561, headers are PING: [PING: type=GET_MBRS_RSP, arg=[own_addr=172.17.50.103:54561, coord_addr=172.17.50.103:54561, is_server=true, is_coord=true]], UDP: [channel_name=dgEntityCacheCluster]
[3/19/09 14:55:28:458] TRACE org.jgroups.protocols.UDP - received (ucast) 94 bytes from 172.17.50.103:56879
[3/19/09 14:55:28:458] TRACE org.jgroups.protocols.UDP - message is [dst: 172.17.50.103:54561, src: 172.17.50.103:56879 (3 headers), size=0 bytes, flags=OOB], headers are GMS: GmsHeader[JOIN_REQ_WITH_STATE_TRANSFER], UNICAST: [UNICAST: DATA, seqno=1], UDP: [channel_name=dgEntityCacheCluster]
[3/19/09 14:55:28:459] TRACE org.jgroups.protocols.UNICAST - 172.17.50.103:54561 <-- DATA(172.17.50.103:56879: #1
[3/19/09 14:55:28:459] TRACE org.jgroups.protocols.UNICAST - 172.17.50.103:54561: created new connection for dst 172.17.50.103:56879
[3/19/09 14:55:28:482] TRACE org.jgroups.stack.AckReceiverWindow - removed OOB message with seqno=1
[3/19/09 14:55:28:482] TRACE org.jgroups.protocols.UNICAST - 172.17.50.103:54561 --> ACK(172.17.50.103:56879: #1)
[3/19/09 14:55:28:482] TRACE org.jgroups.protocols.UDP - sending msg to 172.17.50.103:56879, src=172.17.50.103:54561, headers are UNICAST: [UNICAST: ACK, seqno=1], UDP: [channel_name=dgEntityCacheCluster]
[3/19/09 14:55:28:533] TRACE org.jgroups.protocols.pbcast.GMS - processing [JOIN_WITH_STATE_TRANSFER(172.17.50.103:56879)]
[3/19/09 14:55:28:533] DEBUG org.jgroups.protocols.pbcast.GMS - new=[172.17.50.103:56879], suspected=[], leaving=[], new view: [172.17.50.103:54561|1] [172.17.50.103:54561, 172.17.50.103:56879]
[3/19/09 14:55:28:533] DEBUG org.jgroups.protocols.pbcast.STABLE - suspending message garbage collection
[3/19/09 14:55:28:535] DEBUG org.jgroups.protocols.pbcast.STABLE - resume task started, max_suspend_time=33000
[3/19/09 14:55:28:535] TRACE org.jgroups.protocols.pbcast.GMS - mcasting view {[172.17.50.103:54561|1] [172.17.50.103:54561, 172.17.50.103:56879]} (2 mbrs)

[3/19/09 14:55:28:535] TRACE org.jgroups.protocols.pbcast.NAKACK - sending 172.17.50.103:54561#3
[3/19/09 14:55:28:535] TRACE org.jgroups.protocols.UDP - sending msg to null, src=172.17.50.103:54561, headers are GMS: GmsHeader[VIEW]: view=[172.17.50.103:54561|1] [172.17.50.103:54561, 172.17.50.103:56879], NAKACK: [MSG, seqno=3], UDP: [channel_name=dgEntityCacheCluster]
[3/19/09 14:55:28:569] TRACE org.jgroups.protocols.UDP - sending 1 msgs (126 bytes (0.2% of max_bundle_size), collected in 34ms) to 1 destination(s)
[3/19/09 14:55:28:570] TRACE org.jgroups.protocols.UDP - received (mcast) 143 bytes from 172.17.50.103:45588
[3/19/09 14:55:28:570] TRACE org.jgroups.protocols.UDP - message is [dst: <null>, src: 172.17.50.103:54561 (3 headers), size=0 bytes], headers are GMS: GmsHeader[VIEW]: view=[172.17.50.103:54561|1] [172.17.50.103:54561, 172.17.50.103:56879], NAKACK: [MSG, seqno=3], UDP: [channel_name=dgEntityCacheCluster]
[3/19/09 14:55:28:570] TRACE org.jgroups.protocols.pbcast.NAKACK - [172.17.50.103:54561: received 172.17.50.103:54561#3
[3/19/09 14:55:28:570] DEBUG org.jgroups.protocols.pbcast.GMS - view=[172.17.50.103:54561|1] [172.17.50.103:54561, 172.17.50.103:56879]
[3/19/09 14:55:28:570] DEBUG org.jgroups.protocols.pbcast.GMS - [local_addr=172.17.50.103:54561] view is [172.17.50.103:54561|1] [172.17.50.103:54561, 172.17.50.103:56879]
[3/19/09 14:55:28:572] TRACE org.jgroups.protocols.VIEW_SYNC - view send task started
[3/19/09 14:55:28:572] DEBUG org.jgroups.protocols.FD_SOCK - VIEW_CHANGE received: [172.17.50.103:54561, 172.17.50.103:56879]
[3/19/09 14:55:28:579] TRACE org.jgroups.protocols.UDP - sending msg to null, src=172.17.50.103:54561, headers are FD_SOCK: I_HAVE_SOCK, mbr=172.17.50.103:54561, sock_addr=172.17.50.103:62842, UDP: [channel_name=dgEntityCacheCluster]
[3/19/09 14:55:28:580] TRACE org.jgroups.protocols.UDP - received (mcast) 87 bytes from 172.17.50.103:45588
[3/19/09 14:55:28:580] TRACE org.jgroups.protocols.UDP - message is [dst: <null>, src: 172.17.50.103:54561 (2 headers), size=0 bytes, flags=OOB], headers are FD_SOCK: I_HAVE_SOCK, mbr=172.17.50.103:54561, sock_addr=172.17.50.103:62842, UDP: [channel_name=dgEntityCacheCluster]
[3/19/09 14:55:28:581] TRACE org.jgroups.protocols.FD_SOCK - i-have-sock: 172.17.50.103:54561 --> 172.17.50.103:62842 (cache is {172.17.50.103:54561=172.17.50.103:62842})
[3/19/09 14:55:28:582] TRACE org.jgroups.protocols.FD_SOCK - pinger_thread started
[3/19/09 14:55:28:583] DEBUG org.jgroups.protocols.FD_SOCK - ping_dest is 172.17.50.103:56879, pingable_mbrs=[172.17.50.103:54561, 172.17.50.103:56879]
[3/19/09 14:55:28:583] TRACE org.jgroups.protocols.UDP - sending msg to 172.17.50.103:56879, src=172.17.50.103:54561, headers are FD_SOCK: WHO_HAS_SOCK, mbr=172.17.50.103:56879, UDP: [channel_name=dgEntityCacheCluster]
[3/19/09 14:55:28:585] TRACE org.jgroups.protocols.UDP - received (ucast) 87 bytes from 172.17.50.103:56879
[3/19/09 14:55:28:585] TRACE org.jgroups.protocols.UDP - message is [dst: 172.17.50.103:54561, src: 172.17.50.103:56879 (2 headers), size=0 bytes, flags=OOB], headers are FD_SOCK: I_HAVE_SOCK, mbr=172.17.50.103:56879, sock_addr=172.17.50.103:62882, UDP: [channel_name=dgEntityCacheCluster]
[3/19/09 14:55:28:586] TRACE org.jgroups.protocols.FD_SOCK - i-have-sock: 172.17.50.103:56879 --> 172.17.50.103:62882 (cache is {172.17.50.103:56879=172.17.50.103:62882, 172.17.50.103:54561=172.17.50.103:62842})
[3/19/09 14:55:28:590] TRACE org.jgroups.protocols.FD_SOCK - ping_dest=172.17.50.103:56879, ping_sock=Socket[addr=/172.17.50.103,port=62882,localport=62883], cache={172.17.50.103:56879=172.17.50.103:62882, 172.17.50.103:54561=172.17.50.103:62842}
[3/19/09 14:55:28:592] TRACE org.jgroups.protocols.pbcast.STABLE - resetting digest from NAKACK: [172.17.50.103:54561#3, 172.17.50.103:56879#0]
[3/19/09 14:55:28:592] TRACE org.jgroups.protocols.FC - new membership: [172.17.50.103:54561, 172.17.50.103:56879]
[3/19/09 14:55:28:592] TRACE org.jgroups.protocols.FC - creditors are []
[3/19/09 14:55:28:592] INFO org.jboss.cache.RPCManagerImpl - Received new cluster view: [172.17.50.103:54561|1] [172.17.50.103:54561, 172.17.50.103:56879]
[3/19/09 14:55:28:592] TRACE org.jgroups.protocols.pbcast.GMS - sending VIEW_ACK to 172.17.50.103:54561
[3/19/09 14:55:28:592] TRACE org.jgroups.protocols.UNICAST - 172.17.50.103:54561: created new connection for dst 172.17.50.103:54561
[3/19/09 14:55:28:594] TRACE org.jgroups.protocols.UNICAST - 172.17.50.103:54561 --> DATA(172.17.50.103:54561: #1
[3/19/09 14:55:28:595] TRACE org.jgroups.protocols.UDP - sending msg to 172.17.50.103:54561, src=172.17.50.103:54561, headers are GMS: GmsHeader[VIEW_ACK]: view=null, UNICAST: [UNICAST: DATA, seqno=1], UDP: [channel_name=dgEntityCacheCluster]
[3/19/09 14:55:28:596] TRACE org.jgroups.protocols.UDP - received (ucast) 85 bytes from 172.17.50.103:54561
[3/19/09 14:55:28:596] TRACE org.jgroups.protocols.UDP - message is [dst: 172.17.50.103:54561, src: 172.17.50.103:54561 (3 headers), size=0 bytes, flags=OOB], headers are GMS: GmsHeader[VIEW_ACK]: view=null, UNICAST: [UNICAST: DATA, seqno=1], UDP: [channel_name=dgEntityCacheCluster]
[3/19/09 14:55:28:596] TRACE org.jgroups.protocols.UNICAST - 172.17.50.103:54561 <-- DATA(172.17.50.103:54561: #1
[3/19/09 14:55:28:596] TRACE org.jgroups.stack.AckReceiverWindow - removed OOB message with seqno=1
[3/19/09 14:55:28:596] TRACE org.jgroups.protocols.UNICAST - 172.17.50.103:54561 --> ACK(172.17.50.103:54561: #1)
[3/19/09 14:55:28:596] TRACE org.jgroups.protocols.UDP - sending msg to 172.17.50.103:54561, src=172.17.50.103:54561, headers are UNICAST: [UNICAST: ACK, seqno=1], UDP: [channel_name=dgEntityCacheCluster]
[3/19/09 14:55:28:597] TRACE org.jgroups.protocols.UDP - received (ucast) 68 bytes from 172.17.50.103:54561
[3/19/09 14:55:28:597] TRACE org.jgroups.protocols.pbcast.GMS - received all ACKs (0) for [172.17.50.103:54561|1]
[3/19/09 14:55:28:598] TRACE org.jgroups.protocols.UNICAST - 172.17.50.103:54561 --> DATA(172.17.50.103:56879: #1
[3/19/09 14:55:28:598] TRACE org.jgroups.protocols.UDP - sending msg to 172.17.50.103:56879, src=172.17.50.103:54561, headers are GMS: GmsHeader[JOIN_RSP]: join_rsp=view: [172.17.50.103:54561|1] [172.17.50.103:54561, 172.17.50.103:56879], digest: 172.17.50.103:56879: [0 : 0], 172.17.50.103:54561: [0 : 2 (2)], UNICAST: [UNICAST: DATA, seqno=1], UDP: [channel_name=dgEntityCacheCluster]
[3/19/09 14:55:28:598] TRACE org.jgroups.protocols.UDP - message is [dst: 172.17.50.103:54561, src: 172.17.50.103:54561 (2 headers), size=0 bytes], headers are UNICAST: [UNICAST: ACK, seqno=1], UDP: [channel_name=dgEntityCacheCluster]
[3/19/09 14:55:28:598] TRACE org.jgroups.protocols.UNICAST - 172.17.50.103:54561 <-- ACK(172.17.50.103:54561: #1)
[3/19/09 14:55:28:603] TRACE org.jgroups.protocols.UDP - received (ucast) 68 bytes from 172.17.50.103:56879
[3/19/09 14:55:28:603] TRACE org.jgroups.protocols.UDP - message is [dst: 172.17.50.103:54561, src: 172.17.50.103:56879 (2 headers), size=0 bytes], headers are UNICAST: [UNICAST: ACK, seqno=1], UDP: [channel_name=dgEntityCacheCluster]
[3/19/09 14:55:28:603] TRACE org.jgroups.protocols.UNICAST - 172.17.50.103:54561 <-- ACK(172.17.50.103:56879: #1)
[3/19/09 14:55:28:612] TRACE org.jgroups.protocols.UDP - received (mcast) 87 bytes from 172.17.50.103:45588
[3/19/09 14:55:28:612] TRACE org.jgroups.protocols.UDP - message is [dst: <null>, src: 172.17.50.103:56879 (2 headers), size=0 bytes, flags=OOB], headers are FD_SOCK: I_HAVE_SOCK, mbr=172.17.50.103:56879, sock_addr=172.17.50.103:62882, UDP: [channel_name=dgEntityCacheCluster]
[3/19/09 14:55:28:612] TRACE org.jgroups.protocols.FD_SOCK - i-have-sock: 172.17.50.103:56879 --> 172.17.50.103:62882 (cache is {172.17.50.103:56879=172.17.50.103:62882, 172.17.50.103:54561=172.17.50.103:62842})
[3/19/09 14:55:28:613] TRACE org.jgroups.protocols.UDP - received (ucast) 70 bytes from 172.17.50.103:56879
[3/19/09 14:55:28:613] TRACE org.jgroups.protocols.UDP - message is [dst: 172.17.50.103:54561, src: 172.17.50.103:56879 (2 headers), size=0 bytes, flags=OOB], headers are FD_SOCK: GET_CACHE, UDP: [channel_name=dgEntityCacheCluster]
[3/19/09 14:55:28:613] TRACE org.jgroups.protocols.UDP - sending msg to 172.17.50.103:56879, src=172.17.50.103:54561, headers are FD_SOCK: GET_CACHE_RSP, cache={172.17.50.103:54561=172.17.50.103:62842, 172.17.50.103:56879=172.17.50.103:62882}, UDP: [channel_name=dgEntityCacheCluster]
[3/19/09 14:55:28:616] TRACE org.jgroups.protocols.UDP - received (ucast) 85 bytes from 172.17.50.103:56879
[3/19/09 14:55:28:617] TRACE org.jgroups.protocols.FD_SOCK - accepted connection from /172.17.50.103:62884
[3/19/09 14:55:28:617] TRACE org.jgroups.protocols.UDP - message is [dst: 172.17.50.103:54561, src: 172.17.50.103:56879 (3 headers), size=0 bytes, flags=OOB], headers are GMS: GmsHeader[VIEW_ACK]: view=null, UNICAST: [UNICAST: DATA, seqno=2], UDP: [channel_name=dgEntityCacheCluster]
[3/19/09 14:55:28:617] TRACE org.jgroups.protocols.UNICAST - 172.17.50.103:54561 <-- DATA(172.17.50.103:56879: #2
[3/19/09 14:55:28:617] TRACE org.jgroups.stack.AckReceiverWindow - removed OOB message with seqno=2
[3/19/09 14:55:28:617] TRACE org.jgroups.protocols.UNICAST - 172.17.50.103:54561 --> ACK(172.17.50.103:56879: #2)
[3/19/09 14:55:28:617] TRACE org.jgroups.protocols.UDP - sending msg to 172.17.50.103:56879, src=172.17.50.103:54561, headers are UNICAST: [UNICAST: ACK, seqno=2], UDP: [channel_name=dgEntityCacheCluster]
[3/19/09 14:55:28:619] TRACE org.jgroups.protocols.FD_SOCK - waiting for client connections on nikita-wx10/172.17.50.103:62842
[3/19/09 14:55:28:619] TRACE org.jgroups.protocols.pbcast.GMS - received all ACKs (0) for [172.17.50.103:54561|1]
[3/19/09 14:55:28:619] TRACE org.jgroups.protocols.pbcast.STABLE - resetting digest from NAKACK: [172.17.50.103:54561#3, 172.17.50.103:56879#0]
[3/19/09 14:55:28:619] DEBUG org.jgroups.protocols.pbcast.STABLE - resuming message garbage collection
[3/19/09 14:55:28:621] TRACE org.jgroups.protocols.UDP - received (ucast) 109 bytes from 172.17.50.103:56879
[3/19/09 14:55:28:622] TRACE org.jgroups.protocols.UDP - message is [dst: 172.17.50.103:54561, src: 172.17.50.103:56879 (3 headers), size=0 bytes], headers are STATE_TRANSFER: type=STATE_REQ, sender=172.17.50.103:56879 id=1237499728620, UNICAST: [UNICAST: DATA, seqno=3], UDP: [channel_name=dgEntityCacheCluster]
[3/19/09 14:55:28:622] TRACE org.jgroups.protocols.UNICAST - 172.17.50.103:54561 <-- DATA(172.17.50.103:56879: #3
[3/19/09 14:55:28:622] TRACE org.jgroups.stack.AckReceiverWindow - removed seqno=3
[3/19/09 14:55:28:622] TRACE org.jgroups.protocols.BARRIER - barrier was closed
[3/19/09 14:55:28:623] DEBUG org.jgroups.protocols.pbcast.STATE_TRANSFER - digest is 172.17.50.103:56879: [0 : 0 (0)], 172.17.50.103:54561: [0 : 3 (3)], getting application state
[3/19/09 14:55:28:629] TRACE org.jgroups.protocols.BARRIER - barrier was opened
[3/19/09 14:55:28:629] TRACE org.jgroups.protocols.pbcast.STATE_TRANSFER - sending state for ID=null to 172.17.50.103:56879 (16384 bytes)
[3/19/09 14:55:28:629] TRACE org.jgroups.protocols.FC - sender 172.17.50.103:56879 minus 16384 credits, 483616 remaining
[3/19/09 14:55:28:630] TRACE org.jgroups.protocols.UNICAST - 172.17.50.103:54561 --> DATA(172.17.50.103:56879: #2
[3/19/09 14:55:28:630] TRACE org.jgroups.protocols.UDP - sending msg to 172.17.50.103:56879, src=172.17.50.103:54561, headers are STATE_TRANSFER: type=STATE_RSP, sender=172.17.50.103:54561 id=0, digest=172.17.50.103:56879: [0 : 0 (0)], 172.17.50.103:54561: [0 : 3 (3)], UNICAST: [UNICAST: DATA, seqno=2], UDP: [channel_name=dgEntityCacheCluster]
[3/19/09 14:55:28:630] TRACE org.jgroups.protocols.UNICAST - 172.17.50.103:54561 --> ACK(172.17.50.103:56879: #3)
[3/19/09 14:55:28:630] TRACE org.jgroups.protocols.UDP - sending msg to 172.17.50.103:56879, src=172.17.50.103:54561, headers are UNICAST: [UNICAST: ACK, seqno=3], UDP: [channel_name=dgEntityCacheCluster]
[3/19/09 14:55:28:644] TRACE org.jgroups.protocols.UDP - received (ucast) 68 bytes from 172.17.50.103:56879
[3/19/09 14:55:28:644] TRACE org.jgroups.protocols.UDP - message is [dst: 172.17.50.103:54561, src: 172.17.50.103:56879 (2 headers), size=0 bytes], headers are UNICAST: [UNICAST: ACK, seqno=2], UDP: [channel_name=dgEntityCacheCluster]
[3/19/09 14:55:28:644] TRACE org.jgroups.protocols.UNICAST - 172.17.50.103:54561 <-- ACK(172.17.50.103:56879: #2)
[3/19/09 14:55:31:586] TRACE org.jgroups.protocols.UDP - sending msg to null, src=172.17.50.103:54561, headers are FD_ALL: heartbeat, UDP: [channel_name=dgEntityCacheCluster]
[3/19/09 14:55:31:586] TRACE org.jgroups.protocols.FD_ALL - 172.17.50.103:54561 sent heartbeat to cluster
[3/19/09 14:55:31:586] TRACE org.jgroups.protocols.UDP - received (mcast) 60 bytes from 172.17.50.103:45588
[3/19/09 14:55:31:587] TRACE org.jgroups.protocols.UDP - message is [dst: <null>, src: 172.17.50.103:54561 (2 headers), size=0 bytes, flags=OOB], headers are FD_ALL: heartbeat, UDP: [channel_name=dgEntityCacheCluster]
[3/19/09 14:55:31:593] TRACE org.jgroups.protocols.FD_ALL - checking for expired senders, table is:
172.17.50.103:56879: 3014 ms old

[3/19/09 14:55:31:616] TRACE org.jgroups.protocols.UDP - received (mcast) 60 bytes from 172.17.50.103:45588
[3/19/09 14:55:31:616] TRACE org.jgroups.protocols.UDP - message is [dst: <null>, src: 172.17.50.103:56879 (2 headers), size=0 bytes, flags=OOB], headers are FD_ALL: heartbeat, UDP: [channel_name=dgEntityCacheCluster]
[3/19/09 14:55:34:588] TRACE org.jgroups.protocols.UDP - sending msg to null, src=172.17.50.103:54561, headers are FD_ALL: heartbeat, UDP: [channel_name=dgEntityCacheCluster]
[3/19/09 14:55:34:588] TRACE org.jgroups.protocols.FD_ALL - 172.17.50.103:54561 sent heartbeat to cluster
[3/19/09 14:55:34:588] TRACE org.jgroups.protocols.UDP - received (mcast) 60 bytes from 172.17.50.103:45588
[3/19/09 14:55:34:588] TRACE org.jgroups.protocols.UDP - message is [dst: <null>, src: 172.17.50.103:54561 (2 headers), size=0 bytes, flags=OOB], headers are FD_ALL: heartbeat, UDP: [channel_name=dgEntityCacheCluster]
[3/19/09 14:55:34:594] TRACE org.jgroups.protocols.FD_ALL - checking for expired senders, table is:
172.17.50.103:56879: 2978 ms old

[3/19/09 14:55:34:617] TRACE org.jgroups.protocols.UDP - received (mcast) 60 bytes from 172.17.50.103:45588
[3/19/09 14:55:34:617] TRACE org.jgroups.protocols.UDP - message is [dst: <null>, src: 172.17.50.103:56879 (2 headers), size=0 bytes, flags=OOB], headers are FD_ALL: heartbeat, UDP: [channel_name=dgEntityCacheCluster]
[3/19/09 14:55:37:590] TRACE org.jgroups.protocols.UDP - sending msg to null, src=172.17.50.103:54561, headers are FD_ALL: heartbeat, UDP: [channel_name=dgEntityCacheCluster]
[3/19/09 14:55:37:590] TRACE org.jgroups.protocols.FD_ALL - 172.17.50.103:54561 sent heartbeat to cluster
[3/19/09 14:55:37:590] TRACE org.jgroups.protocols.UDP - received (mcast) 60 bytes from 172.17.50.103:45588
[3/19/09 14:55:37:590] TRACE org.jgroups.protocols.UDP - message is [dst: <null>, src: 172.17.50.103:54561 (2 headers), size=0 bytes, flags=OOB], headers are FD_ALL: heartbeat, UDP: [channel_name=dgEntityCacheCluster]
[3/19/09 14:55:37:595] TRACE org.jgroups.protocols.FD_ALL - checking for expired senders, table is:
172.17.50.103:56879: 2978 ms old

[3/19/09 14:55:37:619] TRACE org.jgroups.protocols.UDP - received (mcast) 60 bytes from 172.17.50.103:45588
[3/19/09 14:55:37:619] TRACE org.jgroups.protocols.UDP - message is [dst: <null>, src: 172.17.50.103:56879 (2 headers), size=0 bytes, flags=OOB], headers are FD_ALL: heartbeat, UDP: [channel_name=dgEntityCacheCluster]
[3/19/09 14:55:38:397] TRACE org.jgroups.protocols.UDP - received (mcast) 156 bytes from 172.17.50.103:45588
[3/19/09 14:55:38:397] TRACE org.jgroups.protocols.UDP - message is [dst: <null>, src: 172.17.50.103:56879 (3 headers), size=0 bytes, flags=OOB], headers are STABLE: [STABLE_GOSSIP]: digest is 172.17.50.103:56879: [0 : 0 (0)], 172.17.50.103:54561: [0 : 3 (3)], NAKACK: [MSG, seqno=1], UDP: [channel_name=dgEntityCacheCluster]
[3/19/09 14:55:38:397] TRACE org.jgroups.protocols.pbcast.NAKACK - [172.17.50.103:54561: received 172.17.50.103:56879#1
[3/19/09 14:55:38:398] TRACE org.jgroups.protocols.pbcast.STABLE - [172.17.50.103:54561] handling digest from 172.17.50.103:56879 (0 votes):
mine: [172.17.50.103:54561#3, 172.17.50.103:56879#0]
other: [172.17.50.103:54561#3, 172.17.50.103:56879#0]
result: [172.17.50.103:54561#3, 172.17.50.103:56879#0]

[3/19/09 14:55:40:592] TRACE org.jgroups.protocols.UDP - sending msg to null, src=172.17.50.103:54561, headers are FD_ALL: heartbeat, UDP: [channel_name=dgEntityCacheCluster]
[3/19/09 14:55:40:592] TRACE org.jgroups.protocols.FD_ALL - 172.17.50.103:54561 sent heartbeat to cluster
[3/19/09 14:55:40:592] TRACE org.jgroups.protocols.UDP - received (mcast) 60 bytes from 172.17.50.103:45588
[3/19/09 14:55:40:592] TRACE org.jgroups.protocols.UDP - message is [dst: <null>, src: 172.17.50.103:54561 (2 headers), size=0 bytes, flags=OOB], headers are FD_ALL: heartbeat, UDP: [channel_name=dgEntityCacheCluster]
[3/19/09 14:55:40:596] TRACE org.jgroups.protocols.FD_ALL - checking for expired senders, table is:
172.17.50.103:56879: 2977 ms old

[3/19/09 14:55:40:620] TRACE org.jgroups.protocols.UDP - received (mcast) 60 bytes from 172.17.50.103:45588
[3/19/09 14:55:40:621] TRACE org.jgroups.protocols.UDP - message is [dst: <null>, src: 172.17.50.103:56879 (2 headers), size=0 bytes, flags=OOB], headers are FD_ALL: heartbeat, UDP: [channel_name=dgEntityCacheCluster]
[3/19/09 14:55:43:595] TRACE org.jgroups.protocols.UDP - sending msg to null, src=172.17.50.103:54561, headers are FD_ALL: heartbeat, UDP: [channel_name=dgEntityCacheCluster]
[3/19/09 14:55:43:595] TRACE org.jgroups.protocols.FD_ALL - 172.17.50.103:54561 sent heartbeat to cluster
[3/19/09 14:55:43:595] TRACE org.jgroups.protocols.UDP - received (mcast) 60 bytes from 172.17.50.103:45588
[3/19/09 14:55:43:595] TRACE org.jgroups.protocols.UDP - message is [dst: <null>, src: 172.17.50.103:54561 (2 headers), size=0 bytes, flags=OOB], headers are FD_ALL: heartbeat, UDP: [channel_name=dgEntityCacheCluster]
[3/19/09 14:55:43:597] TRACE org.jgroups.protocols.FD_ALL - checking for expired senders, table is:
172.17.50.103:56879: 2976 ms old

[3/19/09 14:55:43:621] TRACE org.jgroups.protocols.UDP - received (mcast) 60 bytes from 172.17.50.103:45588
[3/19/09 14:55:43:621] TRACE org.jgroups.protocols.UDP - message is [dst: <null>, src: 172.17.50.103:56879 (2 headers), size=0 bytes, flags=OOB], headers are FD_ALL: heartbeat, UDP: [channel_name=dgEntityCacheCluster]
[3/19/09 14:55:45:388] TRACE org.jgroups.protocols.pbcast.STABLE - setting latest_local_digest from NAKACK: [172.17.50.103:54561#3, 172.17.50.103:56879#1]
[3/19/09 14:55:45:388] TRACE org.jgroups.protocols.pbcast.STABLE - sending stable msg [172.17.50.103:54561#3, 172.17.50.103:56879#1]
[3/19/09 14:55:45:388] TRACE org.jgroups.protocols.pbcast.NAKACK - sending 172.17.50.103:54561#4
[3/19/09 14:55:45:388] TRACE org.jgroups.protocols.UDP - sending msg to null, src=172.17.50.103:54561, headers are STABLE: [STABLE_GOSSIP]: digest is 172.17.50.103:56879: [0 : 1 (1)], 172.17.50.103:54561: [0 : 3 (3)], NAKACK: [MSG, seqno=4], UDP: [channel_name=dgEntityCacheCluster]
[3/19/09 14:55:45:389] TRACE org.jgroups.protocols.UDP - received (mcast) 156 bytes from 172.17.50.103:45588
[3/19/09 14:55:45:389] TRACE org.jgroups.protocols.UDP - message is [dst: <null>, src: 172.17.50.103:54561 (3 headers), size=0 bytes, flags=OOB], headers are STABLE: [STABLE_GOSSIP]: digest is 172.17.50.103:56879: [0 : 1 (1)], 172.17.50.103:54561: [0 : 3 (3)], NAKACK: [MSG, seqno=4], UDP: [channel_name=dgEntityCacheCluster]
[3/19/09 14:55:45:389] TRACE org.jgroups.protocols.pbcast.NAKACK - [172.17.50.103:54561: received 172.17.50.103:54561#4
[3/19/09 14:55:45:389] TRACE org.jgroups.protocols.pbcast.STABLE - [172.17.50.103:54561] handling digest from 172.17.50.103:54561 (1 votes):
mine: [172.17.50.103:54561#3, 172.17.50.103:56879#0]
other: [172.17.50.103:54561#3, 172.17.50.103:56879#1]
result: [172.17.50.103:54561#3, 172.17.50.103:56879#0]

[3/19/09 14:55:45:389] TRACE org.jgroups.protocols.pbcast.STABLE - sending stability msg (in 299 ms) [172.17.50.103:54561#3, 172.17.50.103:56879#0] (copy=16132954)
[3/19/09 14:55:45:689] TRACE org.jgroups.protocols.pbcast.STABLE - sending stability msg [172.17.50.103:54561#3, 172.17.50.103:56879#0] (copy=16132954)
[3/19/09 14:55:45:689] TRACE org.jgroups.protocols.pbcast.NAKACK - sending 172.17.50.103:54561#5
[3/19/09 14:55:45:689] TRACE org.jgroups.protocols.UDP - sending msg to null, src=172.17.50.103:54561, headers are STABLE: [STABILITY]: digest is 172.17.50.103:56879: [0 : 0 (1)], 172.17.50.103:54561: [0 : 3 (3)], NAKACK: [MSG, seqno=5], UDP: [channel_name=dgEntityCacheCluster]
[3/19/09 14:55:45:689] TRACE org.jgroups.protocols.UDP - received (mcast) 156 bytes from 172.17.50.103:45588
[3/19/09 14:55:45:689] TRACE org.jgroups.protocols.UDP - message is [dst: <null>, src: 172.17.50.103:54561 (3 headers), size=0 bytes, flags=OOB], headers are STABLE: [STABILITY]: digest is 172.17.50.103:56879: [0 : 0 (1)], 172.17.50.103:54561: [0 : 3 (3)], NAKACK: [MSG, seqno=5], UDP: [channel_name=dgEntityCacheCluster]
[3/19/09 14:55:45:690] TRACE org.jgroups.protocols.pbcast.NAKACK - [172.17.50.103:54561: received 172.17.50.103:54561#5
[3/19/09 14:55:45:690] TRACE org.jgroups.protocols.pbcast.STABLE - received stability msg from 172.17.50.103:54561: [172.17.50.103:54561#3, 172.17.50.103:56879#0]
[3/19/09 14:55:45:690] TRACE org.jgroups.protocols.pbcast.STABLE - resetting digest from NAKACK: [172.17.50.103:54561#4, 172.17.50.103:56879#1]
[3/19/09 14:55:45:690] TRACE org.jgroups.protocols.pbcast.NAKACK - received stable digest 172.17.50.103:56879: [0 : 0 (1)], 172.17.50.103:54561: [0 : 3 (3)]
[3/19/09 14:55:45:690] TRACE org.jgroups.protocols.pbcast.NAKACK - deleting msgs <= 0 from 172.17.50.103:56879
[3/19/09 14:55:45:690] TRACE org.jgroups.protocols.pbcast.NAKACK - deleting msgs <= 3 from 172.17.50.103:54561
[3/19/09 14:55:46:597] TRACE org.jgroups.protocols.UDP - sending msg to null, src=172.17.50.103:54561, headers are FD_ALL: heartbeat, UDP: [channel_name=dgEntityCacheCluster]
[3/19/09 14:55:46:597] TRACE org.jgroups.protocols.FD_ALL - 172.17.50.103:54561 sent heartbeat to cluster
[3/19/09 14:55:46:597] TRACE org.jgroups.protocols.UDP - received (mcast) 60 bytes from 172.17.50.103:45588
[3/19/09 14:55:46:597] TRACE org.jgroups.protocols.UDP - message is [dst: <null>, src: 172.17.50.103:54561 (2 headers), size=0 bytes, flags=OOB], headers are FD_ALL: heartbeat, UDP: [channel_name=dgEntityCacheCluster]
[3/19/09 14:55:46:599] TRACE org.jgroups.protocols.FD_ALL - checking for expired senders, table is:
172.17.50.103:56879: 2978 ms old

[3/19/09 14:55:46:623] TRACE org.jgroups.protocols.UDP - received (mcast) 60 bytes from 172.17.50.103:45588
[3/19/09 14:55:46:623] TRACE org.jgroups.protocols.UDP - message is [dst: <null>, src: 172.17.50.103:56879 (2 headers), size=0 bytes, flags=OOB], headers are FD_ALL: heartbeat, UDP: [channel_name=dgEntityCacheCluster]
[3/19/09 14:55:48:415] TRACE org.jgroups.protocols.UDP - sending msg to null, src=172.17.50.103:54561, headers are PING: [PING: type=GET_MBRS_REQ, cluster=dgEntityCacheCluster], UDP: [channel_name=dgEntityCacheCluster]
[3/19/09 14:55:48:415] TRACE org.jgroups.protocols.UDP - received (mcast) 81 bytes from 172.17.50.103:45588
[3/19/09 14:55:48:415] TRACE org.jgroups.protocols.UDP - message is [dst: <null>, src: 172.17.50.103:54561 (2 headers), size=0 bytes, flags=OOB], headers are PING: [PING: type=GET_MBRS_REQ, cluster=dgEntityCacheCluster], UDP: [channel_name=dgEntityCacheCluster]
[3/19/09 14:55:48:416] TRACE org.jgroups.protocols.UDP - received (ucast) 80 bytes from 172.17.50.103:56879
[3/19/09 14:55:48:416] TRACE org.jgroups.protocols.UDP - message is [dst: 172.17.50.103:54561, src: 172.17.50.103:56879 (2 headers), size=0 bytes, flags=OOB], headers are PING: [PING: type=GET_MBRS_RSP, arg=[own_addr=172.17.50.103:56879, coord_addr=172.17.50.103:54561, is_server=true, is_coord=false]], UDP: [channel_name=dgEntityCacheCluster]
[3/19/09 14:55:48:416] TRACE org.jgroups.protocols.PING - received GET_MBRS_RSP, rsp=[own_addr=172.17.50.103:56879, coord_addr=172.17.50.103:54561, is_server=true, is_coord=false]
[3/19/09 14:55:49:416] TRACE org.jgroups.protocols.UDP - sending msg to null, src=172.17.50.103:54561, headers are PING: [PING: type=GET_MBRS_REQ, cluster=dgEntityCacheCluster], UDP: [channel_name=dgEntityCacheCluster]
[3/19/09 14:55:49:416] TRACE org.jgroups.protocols.UDP - received (mcast) 81 bytes from 172.17.50.103:45588
[3/19/09 14:55:49:416] TRACE org.jgroups.protocols.UDP - message is [dst: <null>, src: 172.17.50.103:54561 (2 headers), size=0 bytes, flags=OOB], headers are PING: [PING: type=GET_MBRS_REQ, cluster=dgEntityCacheCluster], UDP: [channel_name=dgEntityCacheCluster]
[3/19/09 14:55:49:417] TRACE org.jgroups.protocols.UDP - received (ucast) 80 bytes from 172.17.50.103:56879
[3/19/09 14:55:49:417] TRACE org.jgroups.protocols.UDP - message is [dst: 172.17.50.103:54561, src: 172.17.50.103:56879 (2 headers), size=0 bytes, flags=OOB], headers are PING: [PING: type=GET_MBRS_RSP, arg=[own_addr=172.17.50.103:56879, coord_addr=172.17.50.103:54561, is_server=true, is_coord=false]], UDP: [channel_name=dgEntityCacheCluster]
[3/19/09 14:55:49:417] TRACE org.jgroups.protocols.PING - received GET_MBRS_RSP, rsp=[own_addr=172.17.50.103:56879, coord_addr=172.17.50.103:54561, is_server=true, is_coord=false]
[3/19/09 14:55:49:598] TRACE org.jgroups.protocols.UDP - sending msg to null, src=172.17.50.103:54561, headers are FD_ALL: heartbeat, UDP: [channel_name=dgEntityCacheCluster]
[3/19/09 14:55:49:598] TRACE org.jgroups.protocols.FD_ALL - 172.17.50.103:54561 sent heartbeat to cluster
[3/19/09 14:55:49:598] TRACE org.jgroups.protocols.UDP - received (mcast) 60 bytes from 172.17.50.103:45588
[3/19/09 14:55:49:598] TRACE org.jgroups.protocols.UDP - message is [dst: <null>, src: 172.17.50.103:54561 (2 headers), size=0 bytes, flags=OOB], headers are FD_ALL: heartbeat, UDP: [channel_name=dgEntityCacheCluster]
[3/19/09 14:55:49:600] TRACE org.jgroups.protocols.FD_ALL - checking for expired senders, table is:
172.17.50.103:56879: 2977 ms old

[3/19/09 14:55:49:624] TRACE org.jgroups.protocols.UDP - received (mcast) 60 bytes from 172.17.50.103:45588
[3/19/09 14:55:49:624] TRACE org.jgroups.protocols.UDP - message is [dst: <null>, src: 172.17.50.103:56879 (2 headers), size=0 bytes, flags=OOB], headers are FD_ALL: heartbeat, UDP: [channel_name=dgEntityCacheCluster]
[3/19/09 14:55:50:417] TRACE org.jgroups.protocols.PING - discovery took 2002 ms: responses: 1 total (1 servers (0 coord), 0 clients)
[3/19/09 14:55:50:417] DEBUG org.jgroups.protocols.MERGE2 - 172.17.50.103:54561 is looking for merge candidates, found initial_mbrs=[[own_addr=172.17.50.103:56879, coord_addr=172.17.50.103:54561, is_server=true, is_coord=false], [own_addr=172.17.50.103:54561, coord_addr=172.17.50.103:54561, is_server=true, is_coord=true]]
[3/19/09 14:55:50:417] TRACE org.jgroups.protocols.MERGE2 - MERGE2.FindSubgroups thread terminated (local_addr=172.17.50.103:54561)
[3/19/09 14:55:52:600] TRACE org.jgroups.protocols.UDP - sending msg to null, src=172.17.50.103:54561, headers are FD_ALL: heartbeat, UDP: [channel_name=dgEntityCacheCluster]
[3/19/09 14:55:52:600] TRACE org.jgroups.protocols.FD_ALL - 172.17.50.103:54561 sent heartbeat to cluster
[3/19/09 14:55:52:600] TRACE org.jgroups.protocols.UDP - received (mcast) 60 bytes from 172.17.50.103:45588
[3/19/09 14:55:52:600] TRACE org.jgroups.protocols.FD_ALL - checking for expired senders, table is:
172.17.50.103:56879: 2976 ms old

[3/19/09 14:55:52:600] TRACE org.jgroups.protocols.UDP - message is [dst: <null>, src: 172.17.50.103:54561 (2 headers), size=0 bytes, flags=OOB], headers are FD_ALL: heartbeat, UDP: [channel_name=dgEntityCacheCluster]
[3/19/09 14:55:52:625] TRACE org.jgroups.protocols.UDP - received (mcast) 60 bytes from 172.17.50.103:45588
[3/19/09 14:55:52:626] TRACE org.jgroups.protocols.UDP - message is [dst: <null>, src: 172.17.50.103:56879 (2 headers), size=0 bytes, flags=OOB], headers are FD_ALL: heartbeat, UDP: [channel_name=dgEntityCacheCluster]

Output from Node 2 (that hangs)

[3/19/09 14:55:28:074] INFO org.jboss.cache.jmx.PlatformMBeanServerRegistration - JBossCache MBeans were successfully registered to the platform mbean server.
[3/19/09 14:55:28:099] INFO org.jgroups.JChannel - JGroups version: 2.7.0.GA
[3/19/09 14:55:28:147] DEBUG org.jgroups.conf.ClassConfigurator - mapping is:
1: class org.jgroups.stack.IpAddress
2: class org.jgroups.protocols.CAUSAL$CausalHeader
3: class org.jgroups.protocols.FD$FdHeader
6: class org.jgroups.protocols.FD_SOCK$FdHeader
7: class org.jgroups.protocols.FragHeader
13: class org.jgroups.protocols.PingHeader
21: class org.jgroups.protocols.UNICAST$UnicastHeader
22: class org.jgroups.protocols.VERIFY_SUSPECT$VerifyHeader
24: class org.jgroups.protocols.pbcast.GMS$GmsHeader
25: class org.jgroups.protocols.pbcast.NakAckHeader
27: class org.jgroups.protocols.pbcast.STABLE$StableHeader
28: class org.jgroups.protocols.pbcast.STATE_TRANSFER$StateHeader
29: class org.jgroups.protocols.SMACK$SmackHeader
30: class org.jgroups.Message
31: class org.jgroups.View
32: class org.jgroups.ViewId
34: interface org.jgroups.Address
35: class org.jgroups.blocks.RequestCorrelator$Header
36: class org.jgroups.protocols.PingRsp
38: class java.util.Vector
39: class org.jgroups.protocols.pbcast.JoinRsp
40: class org.jgroups.util.Digest
41: class java.util.Hashtable
53: class org.jgroups.protocols.COMPRESS$CompressHeader
54: class org.jgroups.protocols.FC$FcHeader
56: class org.jgroups.protocols.TpHeader
57: class org.jgroups.protocols.ENCRYPT$EncryptHeader
58: class org.jgroups.protocols.SEQUENCER$SequencerHeader
59: class org.jgroups.protocols.FD_SIMPLE$FdHeader
60: class org.jgroups.protocols.VIEW_SYNC$ViewSyncHeader
61: class org.jgroups.protocols.FD_ALL$Header
62: class org.jgroups.protocols.SFC$Header
63: class org.jgroups.mux.MuxHeader
64: class org.jgroups.protocols.pbcast.FLUSH$FlushHeader
65: class org.jgroups.protocols.pbcast.STREAMING_STATE_TRANSFER$StateHeader
66: class org.jgroups.blocks.PullPushAdapter$PullHeader
67: class org.jgroups.protocols.AuthHeader

[3/19/09 14:55:28:336] DEBUG org.jgroups.protocols.pbcast.GMS - changed role to org.jgroups.protocols.pbcast.ClientGmsImpl
[3/19/09 14:55:28:353] DEBUG org.jgroups.protocols.FRAG2 - received CONFIG event: {bind_addr=nikita-wx10/172.17.50.103}
[3/19/09 14:55:28:353] DEBUG org.jgroups.protocols.UDP - received CONFIG event: {bind_addr=nikita-wx10/172.17.50.103}
[3/19/09 14:55:28:379] DEBUG org.jgroups.protocols.UDP - received CONFIG event: {frag_size=59800}
[3/19/09 14:55:28:393] TRACE org.jgroups.protocols.pbcast.STABLE - stable task started
[3/19/09 14:55:28:393] DEBUG org.jgroups.protocols.UDP - creating sockets and starting threads
[3/19/09 14:55:28:393] DEBUG org.jgroups.protocols.UDP - sockets will use interface 172.17.50.103
[3/19/09 14:55:28:395] DEBUG org.jgroups.protocols.UDP - socket information:
local_addr=172.17.50.103:56879, mcast_addr=232.10.10.11:45588, bind_addr=nikita-wx10/172.17.50.103, ttl=1
sock: bound to 172.17.50.103:56879, receive buffer size=20000000, send buffer size=640000
mcast_sock: bound to 172.17.50.103:45588, send buffer size=640000, receive buffer size=25000000
[3/19/09 14:55:28:431] TRACE org.jgroups.protocols.UDP - joined /224.0.75.75:7500 on lo
[3/19/09 14:55:28:431] TRACE org.jgroups.protocols.UDP - joined /224.0.75.75:7500 on eth4
[3/19/09 14:55:28:432] TRACE org.jgroups.blocks.MessageDispatcher$ProtocolAdapter - setting local_addr (null) to 172.17.50.103:56879
[3/19/09 14:55:28:435] DEBUG org.jgroups.protocols.UDP - created unicast receiver thread
[3/19/09 14:55:28:435] DEBUG org.jgroups.protocols.UDP - created multicast receiver thread
[3/19/09 14:55:28:436] TRACE org.jgroups.protocols.FD_SOCK - waiting for client connections on nikita-wx10/172.17.50.103:62882
[3/19/09 14:55:28:440] TRACE org.jgroups.protocols.UDP - sending msg to null, src=172.17.50.103:56879, headers are PING: [PING: type=GET_MBRS_REQ, cluster=dgEntityCacheCluster], UDP: [channel_name=dgEntityCacheCluster]
[3/19/09 14:55:28:442] TRACE org.jgroups.protocols.UDP - received (mcast) 81 bytes from 172.17.50.103:45588
[3/19/09 14:55:28:443] TRACE org.jgroups.protocols.UDP - received (ucast) 80 bytes from 172.17.50.103:54561
[3/19/09 14:55:28:447] TRACE org.jgroups.protocols.UDP - message is [dst: <null>, src: 172.17.50.103:56879 (2 headers), size=0 bytes, flags=OOB], headers are PING: [PING: type=GET_MBRS_REQ, cluster=dgEntityCacheCluster], UDP: [channel_name=dgEntityCacheCluster]
[3/19/09 14:55:28:449] TRACE org.jgroups.protocols.UDP - message is [dst: 172.17.50.103:56879, src: 172.17.50.103:54561 (2 headers), size=0 bytes, flags=OOB], headers are PING: [PING: type=GET_MBRS_RSP, arg=[own_addr=172.17.50.103:54561, coord_addr=172.17.50.103:54561, is_server=true, is_coord=true]], UDP: [channel_name=dgEntityCacheCluster]
[3/19/09 14:55:28:449] TRACE org.jgroups.protocols.PING - received GET_MBRS_RSP, rsp=[own_addr=172.17.50.103:54561, coord_addr=172.17.50.103:54561, is_server=true, is_coord=true]
[3/19/09 14:55:28:450] TRACE org.jgroups.protocols.PING - discovery took 14 ms: responses: 1 total (1 servers (1 coord), 0 clients)
[3/19/09 14:55:28:450] DEBUG org.jgroups.protocols.pbcast.GMS - initial_mbrs are [[own_addr=172.17.50.103:54561, coord_addr=172.17.50.103:54561, is_server=true, is_coord=true]]
[3/19/09 14:55:28:450] DEBUG org.jgroups.protocols.pbcast.GMS - election results: {172.17.50.103:54561=1}
[3/19/09 14:55:28:450] DEBUG org.jgroups.protocols.pbcast.GMS - sending handleJoin(172.17.50.103:56879) to 172.17.50.103:54561
[3/19/09 14:55:28:451] TRACE org.jgroups.protocols.UNICAST - 172.17.50.103:56879: created new connection for dst 172.17.50.103:54561
[3/19/09 14:55:28:456] TRACE org.jgroups.protocols.UNICAST - 172.17.50.103:56879 --> DATA(172.17.50.103:54561: #1
[3/19/09 14:55:28:457] TRACE org.jgroups.protocols.UDP - sending msg to 172.17.50.103:54561, src=172.17.50.103:56879, headers are GMS: GmsHeader[JOIN_REQ_WITH_STATE_TRANSFER], UNICAST: [UNICAST: DATA, seqno=1], UDP: [channel_name=dgEntityCacheCluster]
[3/19/09 14:55:28:482] TRACE org.jgroups.protocols.UDP - received (ucast) 68 bytes from 172.17.50.103:54561
[3/19/09 14:55:28:483] TRACE org.jgroups.protocols.UDP - message is [dst: 172.17.50.103:56879, src: 172.17.50.103:54561 (2 headers), size=0 bytes], headers are UNICAST: [UNICAST: ACK, seqno=1], UDP: [channel_name=dgEntityCacheCluster]
[3/19/09 14:55:28:485] TRACE org.jgroups.protocols.UNICAST - 172.17.50.103:56879 <-- ACK(172.17.50.103:54561: #1)
[3/19/09 14:55:28:570] TRACE org.jgroups.protocols.UDP - received (mcast) 143 bytes from 172.17.50.103:45588
[3/19/09 14:55:28:575] TRACE org.jgroups.protocols.UDP - message is [dst: <null>, src: 172.17.50.103:54561 (3 headers), size=0 bytes], headers are GMS: GmsHeader[VIEW]: view=[172.17.50.103:54561|1] [172.17.50.103:54561, 172.17.50.103:56879], NAKACK: [MSG, seqno=3], UDP: [channel_name=dgEntityCacheCluster]
[3/19/09 14:55:28:576] TRACE org.jgroups.protocols.pbcast.NAKACK - message was discarded (not yet server)
[3/19/09 14:55:28:580] TRACE org.jgroups.protocols.UDP - received (mcast) 87 bytes from 172.17.50.103:45588
[3/19/09 14:55:28:581] TRACE org.jgroups.protocols.UDP - message is [dst: <null>, src: 172.17.50.103:54561 (2 headers), size=0 bytes, flags=OOB], headers are FD_SOCK: I_HAVE_SOCK, mbr=172.17.50.103:54561, sock_addr=172.17.50.103:62842, UDP: [channel_name=dgEntityCacheCluster]
[3/19/09 14:55:28:581] TRACE org.jgroups.protocols.FD_SOCK - i-have-sock: 172.17.50.103:54561 --> 172.17.50.103:62842 (cache is {172.17.50.103:54561=172.17.50.10

1. Re: JBC+JGroups: 2nd Tomcat hangs during startup

brian.stansberry Mar 19, 2009 6:22 PM (in response to dukehoops)

Recommend you post on javagroups-users@lists.sourceforge.net where the JGroups guys can see this.
Actions
2. Re: JBC+JGroups: 2nd Tomcat hangs during startup

dukehoops Mar 19, 2009 6:34 PM (in response to dukehoops)

Will do. FWIW: the main thread is waiting here:
org.jboss.cache.remoting.jgroups.ChannelMessageListener.waitForState(ChannelMessageListener.java:99)

If I interrupt it, isStateSet is still false, so it enters wait() again. Here's the thread dump:

"main" prio=6 tid=0x013bc000 nid=0x1218 in Object.wait() [0x0011c000..0x0011fe24]
java.lang.Thread.State: WAITING (on object monitor)
at java.lang.Object.wait(Native Method)
- waiting on <0x41222c58> (a java.lang.Object)
at java.lang.Object.wait(Object.java:485)
at org.jboss.cache.remoting.jgroups.ChannelMessageListener.waitForState(ChannelMessageListener.java:99)
- locked <0x41222c58> (a java.lang.Object)
at org.jboss.cache.RPCManagerImpl.start(RPCManagerImpl.java:248)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
at java.lang.reflect.Method.invoke(Method.java:597)
at org.jboss.cache.util.reflect.ReflectionUtil.invokeAccessibly(ReflectionUtil.java:144)
at org.jboss.cache.factories.ComponentRegistry$PrioritizedMethod.invoke(ComponentRegistry.java:883)
at org.jboss.cache.factories.ComponentRegistry.internalStart(ComponentRegistry.java:680)
at org.jboss.cache.factories.ComponentRegistry.start(ComponentRegistry.java:561)
at org.jboss.cache.invocation.CacheInvocationDelegate.start(CacheInvocationDelegate.java:301)
at org.jboss.cache.DefaultCacheFactory.createCache(DefaultCacheFactory.java:119)
at com.doppelganger.framework.cache.DGCacheInstanceManagerBean.afterPropertiesSet(DGCacheInstanceManagerBean.java:96)
Actions
3. Re: JBC+JGroups: 2nd Tomcat hangs during startup

dukehoops Mar 19, 2009 7:33 PM (in response to dukehoops)

Looks like Brian answered this question here:
http://www.jboss.org/index.html?module=bb&op=viewtopic&t=152642

If using multiple cache instances, each instance needs a dedicated JChannel
Actions

Go to original post