Re: [jgroups-dev] MERGE2 timeout after network lost and restored
Bela Ban <[email protected]> Fri, 03 Feb 2012 09:04:23 +0100
| Newsgroups | gmane.comp.java.javagroups.devel |
|---|---|
| Message-ID | <[email protected]> |
I see you're using the Multiplexer, which - together with FLUSH - led to
a lot of problems, so I later pulled Multiplexer.
I suggest upgrade to a more recent version, if you can. I see you use
HA-JDBC, it should be simple to upgrade (although this probably requires
some code changes).
If you're stuck on 2.6.x, try commenting FLUSH and see whether the
merges succeed. We've had a number of problems with the MERGE2+FLUSH
combo, which were fixed some time ago (definitely after 2.6.x).
I dramatically improved merging in 2.8 (IIRC), to handle asymmetric
merges. And I recently (3.0.x) added MERGE3 to better serve merging in
large clusters.
OK, I took a quick look at HA-JDBC and it does support JGroups 3.0.0 in
trunk, so perhaps you can take a look at using the latest HA-JDBC ?
Cheers,
On 2/2/12 9:53 PM, Justin Cranford wrote:
>
>
>
>
> Hi, I am using jGroups 2.6.15.GA with HA-JDBC 2.0.15. That version of HA-JDBC was bundled with jGroups 2.6.7, but I updated to jGroups 2.6.15. I upgraded from jGroups 2.6.7 to 2.6.15 because I was having issues with NACACK rejecting each other's messages after network is lost and then restored. The upgrade seems to fix that, but I am stuck on MERGE timeout in one of the two servers. The message I get is "At 10.20.0.130:7900 cancelling merge due to timer timeout (60000 ms)". The servers each have a Tomcat application and a MySQL database, and a hub sits between them. I performed the following to reproduce the issue: 1) Start server 1 and let it settle2) Start server 2 and let both form a cluster3) Cut power to hub between the servers to isolate them, and let them settle4) Restore power to
hub, server 1 is not merge leader, and responds to VIEW_CHANGE from server 2, but times out even with large MERGE2 merge_timeout="60000" jGroups 2.6.15 is used only by HA-JDBC which appears
to store very actual data. I only see "mycluster-lock" and "mycluster-state" in the jGroups DEBUG log messages when server 1 attempts the merge. My jgroups configuration is first, followed by server 1 DEBUG log messages from jGroups 2.6.15. *** jGroups configuration ***<protocol_stacks>
> <stack name="tcp-sync" description="TCP and TCP PING when IP multicast not available.">
> <config>
> <TCP start_port="7900"
> enable_diagnostics="false"
> loopback="true"
> discard_incompatible_packets="true"
> recv_buf_size="20000000" send_buf_size="640000"
> enable_bundling="true" max_bundle_size="64000" max_bundle_timeout="3"
> use_incoming_packet_handler="true"
> use_send_queues="false"
> sock_conn_timeout="1000"
> skip_suspected_members="true"
> thread_pool.enabled="true" thread_pool.keep_alive_time="30000"
> thread_pool.min_threads="5" thread_pool.max_threads="25"
> thread_pool.queue_enabled="false" thread_pool.queue_max_size="100"
> thread_pool.rejection_policy="run"
> oob_thread_pool.enabled="true" oob_thread_pool.keep_alive_time="30000"
> oob_thread_pool.min_threads="1" oob_thread_pool.max_threads="8"
> oob_thread_pool.queue_enabled="false" oob_thread_pool.queue_max_size="100"
> oob_thread_pool.rejection_policy="run"
> />
> <TCPPING timeout="4000" port_range="1" num_initial_members="2" initial_hosts="${jgroups.tcpping.initial_hosts:10.20.0.130[7900],10.20.0.102[7900]}"/>
> <MERGE2 max_interval="70000" min_interval="65000"/>
> <FD_SOCK start_port="7901" keep_alive="false"/>
> <FD timeout="4000" max_tries="3" shun="false"/>
> <VERIFY_SUSPECT timeout="1500"/>
> <BARRIER/>
> <pbcast.NAKACK use_mcast_xmit="false" gc_lag="0" retransmit_timeout="300,600,1200,2400" discard_delivered_msgs="false"/>
> <pbcast.STABLE stability_delay="1000" desired_avg_gossip="50000" max_bytes="400000"/>
> <VIEW_SYNC avg_send_interval="60000"/>
> <pbcast.GMS print_local_addr="true" join_timeout="60000" merge_timeout="60000" shun="false" view_bundling="true"/>
> <pbcast.STREAMING_STATE_TRANSFER/>
> <pbcast.FLUSH timeout="0"/>
> </config>
> </stack>
> </protocol_stacks> *** SERVER 1 ALREADY STARTED. THESE ARE SERVER 1 LOG MESSAGES RESPONDING TO STARTUP OF SERVER 2 *** DEBUG [2012/02/02 15:03:06.431][ViewHandler,tcp-sync,10.20.0.130:7900](CoordGmsImpl.java:393) new=[10.20.0.102:7900], suspected=[], leaving=[], new view: [10.20.0.130:7900|1] [10.20.0.130:7900, 10.20.0.102:7900]
> DEBUG [2012/02/02 15:03:06.432][ViewHandler,tcp-sync,10.20.0.130:7900](FLUSH.java:219) Received Event[type=SUSPEND, arg=[10.20.0.130:7900, 10.20.0.102:7900]] at 10.20.0.130:7900. Running FLUSH...
> DEBUG [2012/02/02 15:03:06.433][ViewHandler,tcp-sync,10.20.0.130:7900](FLUSH.java:658) Flush coordinator 10.20.0.130:7900 is starting FLUSH with participants [10.20.0.130:7900]
> DEBUG [2012/02/02 15:03:06.433][Incoming-5,tcp-sync,10.20.0.130:7900](FLUSH.java:726) Received START_FLUSH at 10.20.0.130:7900 responded with FLUSH_COMPLETED to 10.20.0.130:7900
> DEBUG [2012/02/02 15:03:06.433][Incoming-2,tcp-sync,10.20.0.130:7900](FLUSH.java:745) At 10.20.0.130:7900 FLUSH_COMPLETED from 10.20.0.130:7900,completed true,flushMembers [10.20.0.130:7900],flushCompleted [10.20.0.130:7900]
> DEBUG [2012/02/02 15:03:06.434][Incoming-2,tcp-sync,10.20.0.130:7900](FLUSH.java:780) All FLUSH_COMPLETED received at 10.20.0.130:7900
> DEBUG [2012/02/02 15:03:06.434][ViewHandler,tcp-sync,10.20.0.130:7900](STABLE.java:188) suspending message garbage collection
> DEBUG [2012/02/02 15:03:06.435][ViewHandler,tcp-sync,10.20.0.130:7900](STABLE.java:474) resume task started, max_suspend_time=33000
> DEBUG [2012/02/02 15:03:06.436][Incoming-2,tcp-sync,10.20.0.130:7900](CoordGmsImpl.java:458) view=[10.20.0.130:7900|1] [10.20.0.130:7900, 10.20.0.102:7900]
> DEBUG [2012/02/02 15:03:06.436][Incoming-2,tcp-sync,10.20.0.130:7900](GMS.java:478) [local_addr=10.20.0.130:7900] view is [10.20.0.130:7900|1] [10.20.0.130:7900, 10.20.0.102:7900]
> DEBUG [2012/02/02 15:03:06.437][Timer-2,tcp-sync,10.20.0.130:7900](FD_SOCK.java:337) VIEW_CHANGE received: [10.20.0.130:7900, 10.20.0.102:7900]
> DEBUG [2012/02/02 15:03:06.438][FD_SOCK pinger,tcp-sync,10.20.0.130:7900](FD_SOCK.java:619) first member; cache is empty
> DEBUG [2012/02/02 15:03:06.439][FD_SOCK pinger,tcp-sync,10.20.0.130:7900](FD_SOCK.java:398) determinePingDest()=10.20.0.102:7900
> DEBUG [2012/02/02 15:03:06.439][Incoming-2,tcp-sync,10.20.0.130:7900](FLUSH.java:598) Installing view at 10.20.0.130:7900 view is [10.20.0.130:7900|1] [10.20.0.130:7900, 10.20.0.102:7900]
> DEBUG [2012/02/02 15:03:06.587][FD_SOCK pinger,tcp-sync,10.20.0.130:7900](FD_SOCK.java:418) ping_dest=10.20.0.102:7900, ping_sock=Socket[addr=/10.20.0.102,port=7901,localport=22994], cache={10.20.0.130:7900=10.20.0.130:7901, 10.20.0.102:7900=10.20.0.102:7901}
> DEBUG [2012/02/02 15:03:06.782][ViewHandler,tcp-sync,10.20.0.130:7900](STABLE.java:204) resuming message garbage collection
> DEBUG [2012/02/02 15:03:06.783][ViewHandler,tcp-sync,10.20.0.130:7900](GMS.java:691) 10.20.0.130:7900 sending RESUME event
> DEBUG [2012/02/02 15:03:06.783][Incoming-2,tcp-sync,10.20.0.130:7900](FLUSH.java:622) At 10.20.0.130:7900 received STOP_FLUSH, unblocking FLUSH.down() and sending UNBLOCK up
> DEBUG [2012/02/02 15:03:06.783][ViewHandler,tcp-sync,10.20.0.130:7900](FLUSH.java:673) Received RESUME at 10.20.0.130:7900, sent STOP_FLUSH to all
> DEBUG [2012/02/02 15:03:06.987][Incoming-2,tcp-sync,10.20.0.130:7900](FLUSH.java:726) Received START_FLUSH at 10.20.0.130:7900 responded with FLUSH_COMPLETED to 10.20.0.102:7900
> DEBUG [2012/02/02 15:03:06.999][Incoming-2,tcp-sync,10.20.0.130:7900](FLUSH.java:622) At 10.20.0.130:7900 received STOP_FLUSH, unblocking FLUSH.down() and sending UNBLOCK up
> DEBUG [2012/02/02 15:03:07.004][Incoming-2,tcp-sync,10.20.0.130:7900](FLUSH.java:726) Received START_FLUSH at 10.20.0.130:7900 responded with FLUSH_COMPLETED to 10.20.0.102:7900
> DEBUG [2012/02/02 15:03:07.014][Incoming-2,tcp-sync,10.20.0.130:7900](FLUSH.java:622) At 10.20.0.130:7900 received STOP_FLUSH, unblocking FLUSH.down() and sending UNBLOCK up
> DEBUG [2012/02/02 15:03:10.439][Timer-4,tcp-sync,10.20.0.130:7900](FD.java:524) sending are-you-alive msg to 10.20.0.102:7900 (own address=10.20.0.130:7900)
> DEBUG [2012/02/02 15:03:14.440][Timer-3,tcp-sync,10.20.0.130:7900](FD.java:524) sending are-you-alive msg to 10.20.0.102:7900 (own address=10.20.0.130:7900)
> DEBUG [2012/02/02 15:03:18.442][Timer-3,tcp-sync,10.20.0.130:7900](FD.java:524) sending are-you-alive msg to 10.20.0.102:7900 (own address=10.20.0.130:7900)
> DEBUG [2012/02/02 15:03:22.443][Timer-3,tcp-sync,10.20.0.130:7900](FD.java:524) sending are-you-alive msg to 10.20.0.102:7900 (own address=10.20.0.130:7900)
> DEBUG [2012/02/02 15:03:26.444][Timer-1,tcp-sync,10.20.0.130:7900](FD.java:524) sending are-you-alive msg to 10.20.0.102:7900 (own address=10.20.0.130:7900)
> *** SERVER 1 LOG MESSAGES RESPONDING TO HUB POWER BEING TURNED OFF *** DEBUG [2012/02/02 15:03:30.445][Timer-4,tcp-sync,10.20.0.130:7900](FD.java:524) sending are-you-alive msg to 10.20.0.102:7900 (own address=10.20.0.130:7900)
> DEBUG [2012/02/02 15:03:30.445][Timer-4,tcp-sync,10.20.0.130:7900](FD.java:550) heartbeat missing from 10.20.0.102:7900 (number=0)
> DEBUG [2012/02/02 15:03:34.446][Timer-4,tcp-sync,10.20.0.130:7900](FD.java:524) sending are-you-alive msg to 10.20.0.102:7900 (own address=10.20.0.130:7900)
> DEBUG [2012/02/02 15:03:34.446][Timer-4,tcp-sync,10.20.0.130:7900](FD.java:550) heartbeat missing from 10.20.0.102:7900 (number=1)
> DEBUG [2012/02/02 15:03:38.448][Timer-3,tcp-sync,10.20.0.130:7900](FD.java:524) sending are-you-alive msg to 10.20.0.102:7900 (own address=10.20.0.130:7900)
> DEBUG [2012/02/02 15:03:38.448][Timer-3,tcp-sync,10.20.0.130:7900](FD.java:550) heartbeat missing from 10.20.0.102:7900 (number=2)
> DEBUG [2012/02/02 15:03:42.449][Timer-3,tcp-sync,10.20.0.130:7900](FD.java:524) sending are-you-alive msg to 10.20.0.102:7900 (own address=10.20.0.130:7900)
> DEBUG [2012/02/02 15:03:42.449][Timer-3,tcp-sync,10.20.0.130:7900](FD.java:536) [10.20.0.130:7900]: received no heartbeat ack from 10.20.0.102:7900 for 4 times (16000 milliseconds), suspecting it
> DEBUG [2012/02/02 15:03:42.451][Timer-4,tcp-sync,10.20.0.130:7900](FD.java:685) broadcasting SUSPECT message [suspected_mbrs=[10.20.0.102:7900]] to group
> DEBUG [2012/02/02 15:03:43.951][VERIFY_SUSPECT.TimerThread,tcp-sync,10.20.0.130:7900](FLUSH.java:861) Suspect is 10.20.0.102:7900,completed false, flushOkSet {} flushMembers []
> DEBUG [2012/02/02 15:03:43.951][VERIFY_SUSPECT.TimerThread,tcp-sync,10.20.0.130:7900](RequestCorrelator.java:439) suspect=10.20.0.102:7900
> DEBUG [2012/02/02 15:03:43.951][VERIFY_SUSPECT.TimerThread,tcp-sync,10.20.0.130:7900](RequestCorrelator.java:439) suspect=10.20.0.102:7900
> DEBUG [2012/02/02 15:03:44.002][ViewHandler,tcp-sync,10.20.0.130:7900](CoordGmsImpl.java:393) new=[], suspected=[10.20.0.102:7900], leaving=[], new view: [10.20.0.130:7900|2] [10.20.0.130:7900]
> DEBUG [2012/02/02 15:03:44.002][ViewHandler,tcp-sync,10.20.0.130:7900](FLUSH.java:219) Received Event[type=SUSPEND, arg=[10.20.0.130:7900]] at 10.20.0.130:7900. Running FLUSH...
> DEBUG [2012/02/02 15:03:44.002][ViewHandler,tcp-sync,10.20.0.130:7900](FLUSH.java:658) Flush coordinator 10.20.0.130:7900 is starting FLUSH with participants [10.20.0.130:7900]
> DEBUG [2012/02/02 15:03:44.002][Incoming-2,tcp-sync,10.20.0.130:7900](FLUSH.java:726) Received START_FLUSH at 10.20.0.130:7900 responded with FLUSH_COMPLETED to 10.20.0.130:7900
> DEBUG [2012/02/02 15:03:44.003][Incoming-5,tcp-sync,10.20.0.130:7900](FLUSH.java:745) At 10.20.0.130:7900 FLUSH_COMPLETED from 10.20.0.130:7900,completed true,flushMembers [10.20.0.130:7900],flushCompleted [10.20.0.130:7900]
> DEBUG [2012/02/02 15:03:44.003][Incoming-5,tcp-sync,10.20.0.130:7900](FLUSH.java:780) All FLUSH_COMPLETED received at 10.20.0.130:7900
> DEBUG [2012/02/02 15:03:44.004][Incoming-2,tcp-sync,10.20.0.130:7900](CoordGmsImpl.java:458) view=[10.20.0.130:7900|2] [10.20.0.130:7900]
> DEBUG [2012/02/02 15:03:44.004][Incoming-2,tcp-sync,10.20.0.130:7900](GMS.java:478) [local_addr=10.20.0.130:7900] view is [10.20.0.130:7900|2] [10.20.0.130:7900]
> DEBUG [2012/02/02 15:03:44.004][Incoming-2,tcp-sync,10.20.0.130:7900](NAKACK.java:1200) removing 10.20.0.102:7900 from xmit_table (not member anymore)
> DEBUG [2012/02/02 15:03:44.005][Timer-3,tcp-sync,10.20.0.130:7900](FD_SOCK.java:337) VIEW_CHANGE received: [10.20.0.130:7900]
> DEBUG [2012/02/02 15:03:44.007][Incoming-2,tcp-sync,10.20.0.130:7900](FLUSH.java:598) Installing view at 10.20.0.130:7900 view is [10.20.0.130:7900|2] [10.20.0.130:7900]
> DEBUG [2012/02/02 15:03:44.007][ViewHandler,tcp-sync,10.20.0.130:7900](GMS.java:691) 10.20.0.130:7900 sending RESUME event
> DEBUG [2012/02/02 15:03:44.007][ViewHandler,tcp-sync,10.20.0.130:7900](FLUSH.java:673) Received RESUME at 10.20.0.130:7900, sent STOP_FLUSH to all
> DEBUG [2012/02/02 15:03:44.007][Incoming-2,tcp-sync,10.20.0.130:7900](FLUSH.java:622) At 10.20.0.130:7900 received STOP_FLUSH, unblocking FLUSH.down() and sending UNBLOCK up
> DEBUG [2012/02/02 15:03:45.006][FD_SOCK pinger,tcp-sync,10.20.0.130:7900](FD_SOCK.java:467) socket to null was reset
> DEBUG [2012/02/02 15:03:45.006][FD_SOCK pinger,tcp-sync,10.20.0.130:7900](FD_SOCK.java:447) pinger thread terminated *** SERVER 1 LOG MESSAGES RESPONDING TO HUB BEGIN TURNED ON AGAIN *** DEBUG [2012/02/02 15:08:13.497][Timer-4,tcp-sync,10.20.0.130:7900](MERGE2.java:212) 10.20.0.130:7900 found multiple coordinators: [10.20.0.102:7900, 10.20.0.130:7900]; sending up MERGE event
> DEBUG [2012/02/02 15:08:13.548][ViewHandler,tcp-sync,10.20.0.130:7900](CoordGmsImpl.java:154) Determining merge leader from coordinators: [10.20.0.102:7900, 10.20.0.130:7900]
> DEBUG [2012/02/02 15:08:13.548][ViewHandler,tcp-sync,10.20.0.130:7900](CoordGmsImpl.java:161) I (10.20.0.130:7900) am not the merge leader, waiting for merge leader (10.20.0.102:7900) to initiate merge
> DEBUG [2012/02/02 15:08:24.646][OOB-7,tcp-sync,10.20.0.130:7900](STABLE.java:188) suspending message garbage collection
> DEBUG [2012/02/02 15:08:24.646][OOB-7,tcp-sync,10.20.0.130:7900](STABLE.java:474) resume task started, max_suspend_time=200000
> DEBUG [2012/02/02 15:08:24.647][OOB-7,tcp-sync,10.20.0.130:7900](GMS.java:763) Merge participant 10.20.0.130:7900 got merge request from 10.20.0.102:7900
> DEBUG [2012/02/02 15:08:24.647][OOB-7,tcp-sync,10.20.0.130:7900](CoordGmsImpl.java:185) Suspending view handler at 10.20.0.130:7900
> DEBUG [2012/02/02 15:08:24.647][OOB-7,tcp-sync,10.20.0.130:7900](GMS.java:1345) suspended ViewHandler at 10.20.0.130:7900
> DEBUG [2012/02/02 15:08:24.666][OOB-7,tcp-sync,10.20.0.130:7900](CoordGmsImpl.java:190) 10.20.0.130:7900 got merge request from 10.20.0.102:7900, merge_id=[10.20.0.102:7900|1328213255972]
> DEBUG [2012/02/02 15:08:24.667][OOB-7,tcp-sync,10.20.0.130:7900](FLUSH.java:219) Received Event[type=SUSPEND, arg=[10.20.0.130:7900]] at 10.20.0.130:7900. Running FLUSH...
> DEBUG [2012/02/02 15:08:24.667][OOB-7,tcp-sync,10.20.0.130:7900](FLUSH.java:658) Flush coordinator 10.20.0.130:7900 is starting FLUSH with participants [10.20.0.130:7900]
> DEBUG [2012/02/02 15:08:24.667][Incoming-5,tcp-sync,10.20.0.130:7900](FLUSH.java:745) At 10.20.0.130:7900 FLUSH_COMPLETED from 10.20.0.130:7900,completed true,flushMembers [10.20.0.130:7900],flushCompleted [10.20.0.130:7900]
> DEBUG [2012/02/02 15:08:24.667][Incoming-2,tcp-sync,10.20.0.130:7900](FLUSH.java:726) Received START_FLUSH at 10.20.0.130:7900 responded with FLUSH_COMPLETED to 10.20.0.130:7900
> DEBUG [2012/02/02 15:08:24.668][OOB-7,tcp-sync,10.20.0.130:7900](CoordGmsImpl.java:726) response=GmsHeader[MERGE_RSP]: view=[10.20.0.130:7900|2] [10.20.0.130:7900], digest=10.20.0.130:7900: [22 : 26 (26)], merge_rejected=false, merge_id=[10.20.0.102:7900|1328213255972]
> DEBUG [2012/02/02 15:08:24.668][Incoming-5,tcp-sync,10.20.0.130:7900](FLUSH.java:780) All FLUSH_COMPLETED received at 10.20.0.130:7900
> DEBUG [2012/02/02 15:08:24.669][OOB-7,tcp-sync,10.20.0.130:7900](CoordGmsImpl.java:206) 10.20.0.130:7900 responded to 10.20.0.102:7900, merge_id=[10.20.0.102:7900|1328213255972]
> WARN [2012/02/02 15:08:24.676][Incoming-5,tcp-sync,10.20.0.130:7900](NAKACK.java:834) 10.20.0.130:7900] discarded message from non-member 10.20.0.102:7900, my view is [10.20.0.130:7900|2] [10.20.0.130:7900]
> WARN [2012/02/02 15:08:24.877][OOB-9,tcp-sync,10.20.0.130:7900](NAKACK.java:834) 10.20.0.130:7900] discarded message from non-member 10.20.0.102:7900, my view is [10.20.0.130:7900|2] [10.20.0.130:7900]
> DEBUG [2012/02/02 15:08:24.879][Incoming-2,tcp-sync,10.20.0.130:7900](CoordGmsImpl.java:456) view=MergeView::[10.20.0.102:7900|3] [10.20.0.102:7900, 10.20.0.130:7900], subgroups=[[10.20.0.102:7900|2] [10.20.0.102:7900], [10.20.0.130:7900|2] [10.20.0.130:7900]], digest=10.20.0.130:7900: [22 : 26 (26)], 10.20.0.102:7900: [15 : 19 (19)]
> ERROR [2012/02/02 15:08:24.880][Incoming-2,tcp-sync,10.20.0.130:7900](NAKACK.java:1377) sender 10.20.0.102:7900 not found in xmit_table
> ERROR [2012/02/02 15:08:24.880][Incoming-2,tcp-sync,10.20.0.130:7900](NAKACK.java:1227) range is null
> DEBUG [2012/02/02 15:08:24.880][Incoming-2,tcp-sync,10.20.0.130:7900](NAKACK.java:1309) existing digest: 10.20.0.130:7900: [22 : 27 (27)]
> new digest: 10.20.0.130:7900: [22 : 26 (26)], 10.20.0.102:7900: [15 : 19 (19)]
> resulting digest: 10.20.0.130:7900: [22 : 27 (27)], 10.20.0.102:7900: [15 : 19 (19)]
> DEBUG [2012/02/02 15:08:24.881][Incoming-2,tcp-sync,10.20.0.130:7900](GMS.java:478) [local_addr=10.20.0.130:7900] view is MergeView::[10.20.0.102:7900|3] [10.20.0.102:7900, 10.20.0.130:7900], subgroups=[[10.20.0.102:7900|2] [10.20.0.102:7900], [10.20.0.130:7900|2] [10.20.0.130:7900]]
> DEBUG [2012/02/02 15:08:24.881][Timer-4,tcp-sync,10.20.0.130:7900](FD_SOCK.java:337) VIEW_CHANGE received: [10.20.0.102:7900, 10.20.0.130:7900]
> DEBUG [2012/02/02 15:08:24.882][FD_SOCK pinger,tcp-sync,10.20.0.130:7900](FD_SOCK.java:398) determinePingDest()=10.20.0.102:7900
> DEBUG [2012/02/02 15:08:24.883][OOB-9,tcp-sync,10.20.0.130:7900](Multiplexer.java:837) 10.20.0.130:7900 received service response: 10.20.0.130:7900([mycluster-lock, mycluster-state])
> DEBUG [2012/02/02 15:08:25.081][FD_SOCK pinger,tcp-sync,10.20.0.130:7900](FD_SOCK.java:418) ping_dest=10.20.0.102:7900, ping_sock=Socket[addr=/10.20.0.102,port=7901,localport=23108], cache={10.20.0.130:7900=10.20.0.130:7901, 10.20.0.102:7900=10.20.0.102:7901}
> DEBUG [2012/02/02 15:08:25.279][OOB-7,tcp-sync,10.20.0.130:7900](Multiplexer.java:795) 10.20.0.130:7900 got service merged from 10.20.0.102:7900 merged so far [10.20.0.102:7900] view is 2
> DEBUG [2012/02/02 15:08:25.279][OOB-10,tcp-sync,10.20.0.130:7900](Multiplexer.java:837) 10.20.0.130:7900 received service response: 10.20.0.102:7900([mycluster-lock, mycluster-state])
> DEBUG [2012/02/02 15:08:25.279][OOB-9,tcp-sync,10.20.0.130:7900](Multiplexer.java:795) 10.20.0.130:7900 got service merged from 10.20.0.102:7900 merged so far [10.20.0.102:7900] view is 2
> DEBUG [2012/02/02 15:08:25.280][OOB-10,tcp-sync,10.20.0.130:7900](Multiplexer.java:847) 10.20.0.130:7900 sent service merged [10.20.0.102:7900, 10.20.0.130:7900] view is [10.20.0.102:7900, 10.20.0.130:7900]
> DEBUG [2012/02/02 15:08:25.280][OOB-9,tcp-sync,10.20.0.130:7900](Multiplexer.java:795) 10.20.0.130:7900 got service merged from 10.20.0.130:7900 merged so far [10.20.0.102:7900, 10.20.0.130:7900] view is 2
> DEBUG [2012/02/02 15:08:25.382][Incoming-2,tcp-sync,10.20.0.130:7900](Multiplexer.java:965) At 10.20.0.130:7900 emitting views to MuxChannels {10.20.0.102:7900=[mycluster-lock, mycluster-state], 10.20.0.130:7900=[mycluster-lock, mycluster-state]}
> DEBUG [2012/02/02 15:08:25.384][Incoming-2,tcp-sync,10.20.0.130:7900](FLUSH.java:598) Installing view at 10.20.0.130:7900 view is MergeView::[10.20.0.102:7900|3] [10.20.0.102:7900, 10.20.0.130:7900], subgroups=[[10.20.0.102:7900|2] [10.20.0.102:7900], [10.20.0.130:7900|2] [10.20.0.130:7900]]
> DEBUG [2012/02/02 15:08:25.386][Incoming-2,tcp-sync,10.20.0.130:7900](GMS.java:225) 10.20.0.130:7900 changed role to org.jgroups.protocols.pbcast.ParticipantGmsImpl
> DEBUG [2012/02/02 15:08:25.386][Incoming-5,tcp-sync,10.20.0.130:7900](STABLE.java:204) resuming message garbage collection
> DEBUG [2012/02/02 15:08:25.884][Incoming-5,tcp-sync,10.20.0.130:7900](Multiplexer.java:837) 10.20.0.130:7900 received service response: 10.20.0.102:7900([mycluster-lock, mycluster-state])
> DEBUG [2012/02/02 15:08:25.885][Incoming-5,tcp-sync,10.20.0.130:7900](ParticipantGmsImpl.java:148) view=MergeView::[10.20.0.102:7900|3] [10.20.0.102:7900, 10.20.0.130:7900], subgroups=[[10.20.0.102:7900|2] [10.20.0.102:7900], [10.20.0.130:7900|2] [10.20.0.130:7900]]
> DEBUG [2012/02/02 15:08:25.886][Incoming-5,tcp-sync,10.20.0.130:7900](FLUSH.java:622) At 10.20.0.130:7900 received STOP_FLUSH, unblocking FLUSH.down() and sending UNBLOCK up
> DEBUG [2012/02/02 15:08:28.882][Timer-3,tcp-sync,10.20.0.130:7900](FD.java:524) sending are-you-alive msg to 10.20.0.102:7900 (own address=10.20.0.130:7900)
> DEBUG [2012/02/02 15:08:32.884][Timer-3,tcp-sync,10.20.0.130:7900](FD.java:524) sending are-you-alive msg to 10.20.0.102:7900 (own address=10.20.0.130:7900)
> DEBUG [2012/02/02 15:08:36.885][Timer-3,tcp-sync,10.20.0.130:7900](FD.java:524) sending are-you-alive msg to 10.20.0.102:7900 (own address=10.20.0.130:7900)
> DEBUG [2012/02/02 15:08:40.886][Timer-4,tcp-sync,10.20.0.130:7900](FD.java:524) sending are-you-alive msg to 10.20.0.102:7900 (own address=10.20.0.130:7900)
> DEBUG [2012/02/02 15:08:44.887][Timer-3,tcp-sync,10.20.0.130:7900](FD.java:524) sending are-you-alive msg to 10.20.0.102:7900 (own address=10.20.0.130:7900)
> DEBUG [2012/02/02 15:08:48.888][Timer-3,tcp-sync,10.20.0.130:7900](FD.java:524) sending are-you-alive msg to 10.20.0.102:7900 (own address=10.20.0.130:7900)
> DEBUG [2012/02/02 15:08:52.890][Timer-3,tcp-sync,10.20.0.130:7900](FD.java:524) sending are-you-alive msg to 10.20.0.102:7900 (own address=10.20.0.130:7900)
> DEBUG [2012/02/02 15:08:56.891][Timer-3,tcp-sync,10.20.0.130:7900](FD.java:524) sending are-you-alive msg to 10.20.0.102:7900 (own address=10.20.0.130:7900)
> DEBUG [2012/02/02 15:09:00.892][Timer-3,tcp-sync,10.20.0.130:7900](FD.java:524) sending are-you-alive msg to 10.20.0.102:7900 (own address=10.20.0.130:7900)
> DEBUG [2012/02/02 15:09:04.893][Timer-3,tcp-sync,10.20.0.130:7900](FD.java:524) sending are-you-alive msg to 10.20.0.102:7900 (own address=10.20.0.130:7900)
> DEBUG [2012/02/02 15:09:08.895][Timer-3,tcp-sync,10.20.0.130:7900](FD.java:524) sending are-you-alive msg to 10.20.0.102:7900 (own address=10.20.0.130:7900)
> DEBUG [2012/02/02 15:09:12.896][Timer-4,tcp-sync,10.20.0.130:7900](FD.java:524) sending are-you-alive msg to 10.20.0.102:7900 (own address=10.20.0.130:7900)
> DEBUG [2012/02/02 15:09:16.897][Timer-4,tcp-sync,10.20.0.130:7900](FD.java:524) sending are-you-alive msg to 10.20.0.102:7900 (own address=10.20.0.130:7900)
> DEBUG [2012/02/02 15:09:20.898][Timer-4,tcp-sync,10.20.0.130:7900](FD.java:524) sending are-you-alive msg to 10.20.0.102:7900 (own address=10.20.0.130:7900)
> DEBUG [2012/02/02 15:09:24.668][Timer-4,tcp-sync,10.20.0.130:7900](CoordGmsImpl.java:889) At 10.20.0.130:7900 cancelling merge due to timer timeout (60000 ms)
> DEBUG [2012/02/02 15:09:24.668][Timer-4,tcp-sync,10.20.0.130:7900](CoordGmsImpl.java:308) cancelling merge (merge_id=[10.20.0.102:7900|1328213255972])
> DEBUG [2012/02/02 15:09:24.899][Timer-1,tcp-sync,10.20.0.130:7900](FD.java:524) sending are-you-alive msg to 10.20.0.102:7900 (own address=10.20.0.130:7900)
> DEBUG [2012/02/02 15:09:28.901][Timer-3,tcp-sync,10.20.0.130:7900](FD.java:524) sending are-you-alive msg to 10.20.0.102:7900 (own address=10.20.0.130:7900)
> DEBUG [2012/02/02 15:09:32.902][Timer-3,tcp-sync,10.20.0.130:7900](FD.java:524) sending are-you-alive msg to 10.20.0.102:7900 (own address=10.20.0.130:7900)
> DEBUG [2012/02/02 15:09:36.903][Timer-4,tcp-sync,10.20.0.130:7900](FD.java:524) sending are-you-alive msg to 10.20.0.102:7900 (own address=10.20.0.130:7900)
> DEBUG [2012/02/02 15:09:40.904][Timer-4,tcp-sync,10.20.0.130:7900](FD.java:524) sending are-you-alive msg to 10.20.0.102:7900 (own address=10.20.0.130:7900)
> *** SERVER 2 IS ALIVE, BUT MERGE FAILED ON SERVER 1 DUE TO CoordGmsImpl TIMEOUT, MERGE ATTEMPTS KEEP COMING WITH SAME RESULT ***
>
>
>
> ------------------------------------------------------------------------------
> Try before you buy = See our experts in action!
> The most comprehensive online learning library for Microsoft developers
> is just $99.99! Visual Studio, SharePoint, SQL - plus HTML5, CSS3, MVC3,
> Metro Style Apps, more. Free future releases when you subscribe now!
> http://p.sf.net/sfu/learndevnow-dev2
>
>
>
> _______________________________________________
> Javagroups-development mailing list
>
--
Bela Ban
Lead JGroups (http://www.jgroups.org)
JBoss / Red Hat
------------------------------------------------------------------------------
Try before you buy = See our experts in action!
The most comprehensive online learning library for Microsoft developers
is just $99.99! Visual Studio, SharePoint, SQL - plus HTML5, CSS3, MVC3,
Metro Style Apps, more. Free future releases when you subscribe now!
http://p.sf.net/sfu/learndevnow-dev2
_______________________________________________
Javagroups-development mailing list