[jgroups-users] JGroups failing to give up on crashed coordinator

This is on 3.6.4 final.

This problem originally occurred as a coincidence with suspect hardware but
it is  reproducible by resetting/cycling power on multiple nodes including
the coordinator in quick succession.   If I reset only the coordinator or
if I reset a group of nodes not including the coordinator I don't have a
problem.  It also doesn't happen when I killed the software processes but
don't reset the hardware so the actual loss of the wireless network
destination is an important contributor to the problem. My expectation
would be that JGroups would install a new view without the crashed nodes or
even a view containing just the individual nodes.  As best as I can tell
the nodes in this stuck state are creating a self-perpetuating network
problem that never clears most likely due to the resulting traffic storm (I
see a huge spike in network layer packet retransmissions -- to as much as
50% of all traffic).  If I subsequently stop JGroups on all nodes I can
then restart with no problems.

I have included some logs captured  on node 11 well after the resets
occurred.  In this case it was node 7,13, and 14 that I reset where 7 was
coordinator, node 14 was the next node in the view, node 13 was in about
the middle, and node 11 was near the end.   I have a log in the suspect
callback that does not ever get generated in this scenario.  What really
bothers me is the FD_SOCK unsuspecting the crashed nodes even though they
have completely power cycled.  I tried removing FD_SOCK and VERIFY and
playing with a bunch of other settings but it made no difference.  Only
some of the nodes get stuck like this, others form a new view and continue
on.  On the ones that get stuck I can't successfully ping the other nodes
manually or do any networking with them, I have to use a directly connected
console and can't use probe.

If I can't make JGroups recover from this I'd at least like to detect it so
I can do a software controlled restart.  Since I'm not getting the suspect
callbacks  I looking into using the Timeout exceptions to give me a hint
that something is very wrong.

Trimmed logs:
01-24 18:30:54.521 D/FD_ALL  ( 1779): haven't received a heartbeat from
node7 for 109154 ms, adding it to suspect list
01-24 18:30:54.531 D/FD_ALL  ( 1779): haven't received a heartbeat from
node13 for 100631 ms, adding it to suspect list
01-24 18:30:54.531 D/FD_ALL  ( 1779): haven't received a heartbeat from
node14 for 92126 ms, adding it to suspect list
01-24 18:30:54.921 W/RSVP    ( 1779): JGRP000052: message ran into a
timeout, missing acks: 115=(12) node7, node14, node8, node9, node4, node13,
node5, node2, node10, node12, node1, node3
01-24 18:30:54.931 W/NAKACK2 ( 1779): JGRP000011: node11: dropped message 2
from non-member b803c331-d782-68ff-3816-408b7a1aa6cb (view=[node7|26] (13)
[node7, node14, node8, node9, node4, node13, node5, node2, node10, node11,
node12, node1, node3])
01-24 18:30:56.531 D/FD_ALL  ( 1779): haven't received a heartbeat from
node7 for 111155 ms, adding it to suspect list
01-24 18:30:56.531 D/FD_ALL  ( 1779): haven't received a heartbeat from
node13 for 102632 ms, adding it to suspect list
01-24 18:30:56.531 D/FD_ALL  ( 1779): haven't received a heartbeat from
node14 for 94127 ms, adding it to suspect list
01-24 18:30:57.181 E/AppManager( 1779): org.jgroups.TimeoutException:
TimeoutException
01-24 18:30:57.181 E/AppManager( 1779): at
org.jgroups.util.Promise._getResultWithTimeout(Promise.java:146)
01-24 18:30:57.181 E/AppManager( 1779): at
org.jgroups.util.Promise.getResultWithTimeout(Promise.java:38)
01-24 18:30:57.181 E/AppManager( 1779): at
org.jgroups.util.AckCollector.waitForAllAcks(AckCollector.java:93)
01-24 18:30:57.181 E/AppManager( 1779): at
org.jgroups.protocols.RSVP$Entry.block(RSVP.java:326)
01-24 18:30:57.181 E/AppManager( 1779): at
org.jgroups.protocols.RSVP.down(RSVP.java:128)
01-24 18:30:57.181 E/AppManager( 1779): at
org.jgroups.protocols.pbcast.STABLE.down(STABLE.java:347)
01-24 18:30:57.181 E/AppManager( 1779): at
org.jgroups.protocols.pbcast.GMS.down(GMS.java:1119)
01-24 18:30:57.181 E/AppManager( 1779): at
org.jgroups.protocols.pbcast.StreamingStateTransfer.down(StreamingStateTransfer.java:184)
01-24 18:30:57.181 E/AppManager( 1779): at
org.jgroups.stack.ProtocolStack.down(ProtocolStack.java:1038)
01-24 18:30:57.181 E/AppManager( 1779): at
org.jgroups.JChannel.down(JChannel.java:791)
01-24 18:30:57.181 E/AppManager( 1779): at
org.jgroups.blocks.MessageDispatcher$ProtocolAdapter.down(MessageDispatcher.java:693)
01-24 18:30:57.181 E/AppManager( 1779): at
org.jgroups.blocks.RequestCorrelator.sendRequest(RequestCorrelator.java:175)
01-24 18:30:57.181 E/AppManager( 1779): at
org.jgroups.blocks.mux.MuxRequestCorrelator.sendRequest(MuxRequestCorrelator.java:33)
01-24 18:30:57.181 E/AppManager( 1779): at
org.jgroups.blocks.GroupRequest.sendRequest(GroupRequest.java:360)
01-24 18:30:57.181 E/AppManager( 1779): at
org.jgroups.blocks.GroupRequest.sendRequest(GroupRequest.java:103)
01-24 18:30:57.181 E/AppManager( 1779): at
org.jgroups.blocks.Request.execute(Request.java:83)
01-24 18:30:57.181 E/AppManager( 1779): at
org.jgroups.blocks.MessageDispatcher.cast(MessageDispatcher.java:367)
01-24 18:30:57.181 E/AppManager( 1779): at
org.jgroups.blocks.mux.MuxRpcDispatcher.cast(MuxRpcDispatcher.java:95)
01-24 18:30:57.181 E/AppManager( 1779): at
org.jgroups.blocks.MessageDispatcher.cast(MessageDispatcher.java:373)
01-24 18:30:57.181 E/AppManager( 1779): at
org.jgroups.blocks.MessageDispatcher.castMessage(MessageDispatcher.java:258)
01-24 18:30:57.181 E/AppManager( 1779): at
org.jgroups.blocks.RpcDispatcher.callRemoteMethods(RpcDispatcher.java:159)
01-24 18:30:58.531 D/FD_ALL  ( 1779): haven't received a heartbeat from
node7 for 113158 ms, adding it to suspect list
01-24 18:30:58.531 D/FD_ALL  ( 1779): haven't received a heartbeat from
node13 for 104635 ms, adding it to suspect list
01-24 18:30:58.531 D/FD_ALL  ( 1779): haven't received a heartbeat from
node14 for 96130 ms, adding it to suspect list
01-24 18:30:58.681 W/RSVP    ( 1779): JGRP000052: message ran into a
timeout, missing acks: 117=(12) node7, node14, node8, node9, node4, node13,
node5, node2, node10, node12, node1, node3
01-24 18:30:58.681 W/RSVP    ( 1779): JGRP000052: message ran into a
timeout, missing acks: 118=(12) node7, node14, node8, node9, node4, node13,
node5, node2, node10, node12, node1, node3
01-24 18:30:59.941 W/RSVP    ( 1779): JGRP000052: message ran into a
timeout, missing acks: 119=(12) node7, node14, node8, node9, node4, node13,
node5, node2, node10, node12, node1, node3
01-24 18:31:00.531 D/FD_ALL  ( 1779): haven't received a heartbeat from
node7 for 115159 ms, adding it to suspect list
01-24 18:31:00.531 D/FD_ALL  ( 1779): haven't received a heartbeat from
node13 for 106636 ms, adding it to suspect list
01-24 18:31:00.531 D/FD_ALL  ( 1779): haven't received a heartbeat from
node14 for 98131 ms, adding it to suspect list
01-24 18:31:00.691 W/RSVP    ( 1779): JGRP000052: message ran into a
timeout, missing acks: 120=(12) node7, node14, node8, node9, node4, node13,
node5, node2, node10, node12, node1, node3
01-24 18:31:00.691 W/RSVP    ( 1779): JGRP000052: message ran into a
timeout, missing acks: 121=(12) node7, node14, node8, node9, node4, node13,
node5, node2, node10, node12, node1, node3


And later on
01-24 18:31:35.111 D/FD_SOCK ( 1779): node11: unsuspecting node13
01-24 18:31:35.141 D/FD_SOCK ( 1779): node11: unsuspecting node14


This is what the stack looks like and it seems to work pretty well most of
the time.  I've tried varying timeouts, removing VERIFY and FD_SOCK,
increasing bundle and frag sizes and nothing seems to prevent this.  I've
run with abort as the rejection policy to see if maybe I'm overflowing my
queues but I never saw an abort.

<!--
  Stack which matches the one setup programmatically.
  Variable substitution is used for cluster/node specific bind address/port
values.
-->

<config xmlns="urn:org:jgroups"
        xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
        xsi:schemaLocation="urn:org:jgroups
http://www.jgroups.org/schema/jgroups.xsd">
    <UDP
        enable_diagnostics="true"
        ip_mcast="true"
        ip_ttl="8"
        tos="8"
        mcast_port="${jgroups.udp.mcast_port:45588}"
        bind_addr="${jgroups.udp.bind_addr:127.0.0.1}"
        bind_port="0"

        ucast_recv_buf_size="200000"
        ucast_send_buf_size="200000"
        mcast_recv_buf_size="200000"
        mcast_send_buf_size="200000"

        max_bundle_size="1400"
        max_bundle_timeout="25"

        thread_naming_pattern="pcl"

        thread_pool_enabled="true"
        thread_pool_min_threads="1"
        thread_pool_max_threads="16"
        thread_pool_keep_alive_time="10000"
        thread_pool_queue_enabled="true"
        thread_pool_queue_max_size="50"
        thread_pool_rejection_policy="discard"

        internal_thread_pool_enabled="true"
        internal_thread_pool_min_threads="2"
        internal_thread_pool_max_threads="16"
        internal_thread_pool_keep_alive_time="10000"
        internal_thread_pool_queue_enabled="true"
        internal_thread_pool_queue_max_size="50"
        internal_thread_pool_rejection_policy="discard"

        oob_thread_pool_enabled="true"
        oob_thread_pool_min_threads="1"
        oob_thread_pool_max_threads="32"
        oob_thread_pool_keep_alive_time="10000"
        oob_thread_pool_queue_enabled="true"
        oob_thread_pool_queue_max_size="50"
        oob_thread_pool_rejection_policy="discard"

        timer_type="new3"
        timer_min_threads="2"
        timer_max_threads="8"
        timer_keep_alive_time="3000"
        timer_queue_max_size="50"
        timer_rejection_policy="discard"
    />
    <PING />
    <MERGE3
        min_interval="2500"
        max_interval="5000"
        check_interval="16000"
    />
    <FD_SOCK
         bind_addr="${jgroups.udp.bind_addr:127.0.0.1}"
    />
    <FD_ALL
       interval="3000"
       timeout="10000"
       msg_counts_as_heartbeat="false"
    />
    <VERIFY_SUSPECT
        timeout="1500"
        use_mcast_rsps="false"
    />
    <BARRIER />
    <pbcast.NAKACK2
        xmit_interval="500"
        xmit_table_num_rows="100"
        xmit_table_msgs_per_row="2000"
        xmit_table_max_compaction_time="30000"
        max_msg_batch_size="500"
        use_mcast_xmit="false"
        discard_delivered_msgs="true"
    />
    <UNICAST3
        conn_expiry_timeout="0"
        xmit_interval="500"
        xmit_table_num_rows="100"
        xmit_table_msgs_per_row="2000"
        xmit_table_max_compaction_time="60000"
        max_msg_batch_size="500"
    />
    <FRAG2
        frag_size="1250"
    />
    <RSVP
        ack_on_delivery="false"
        resend_interval="250"
        timeout="5000"
        throw_exception_on_timeout="true"
    />
    <pbcast.STABLE
        stability_delay="1000"
        desired_avg_gossip="15000"
        max_bytes="4M"
        send_stable_msgs_to_coord_only="false"
    />
    <pbcast.GMS
        max_join_attempts="100000"
        print_local_addr="true"
        view_bundling="true"
        join_timeout="15000"
        leave_timeout="15000"
        use_flush_if_present="true"
        use_merger2="true"
        print_physical_addrs="true"
        view_ack_collection_timeout="10000"
        merge_timeout="10000"
    />
    <pbcast.STATE
       buffer_size="10000"
       max_pool="5"
       pool_thread_keep_alive="10000"
    />
</config>

Any ideas?

Thanks,
JT

------------------------------------------------------------------------------
Site24x7 APM Insight: Get Deep Visibility into Application Performance
APM + Mobile APM + RUM: Monitor 3 App instances at just $35/Month
Monitor end-to-end web transactions and take corrective actions now
Troubleshoot faster and improve end-user experience. Signup Now!
http://pubads.g.doubleclick.net/gampad/clk?id=267308311&iu=/4140

_______________________________________________
javagroups-users mailing list
[email protected]
https://lists.sourceforge.net/lists/listinfo/javagroups-users