[jgroups-users] Split cluster not merging properly after heavy load

Hello,

I have a strange problem when in some (rare) conditions a split cluster won't merge any more. I have traced it down to MERGE_RSP from the cluster/node that's not the merge leader not getting to the merge leader. The problem is hard to reproduce but I'll do my best to describe the situation.

Set-up: two node cluster (lets call them node1 and node2). I start our application (using TCP with MPING discovery) on node2 later on node1. Both nodes find each other (this never fails) and form one cluster. On node2 I start a heavy stress test (linux: stress --io 64 --hdd 64) and wait until the cluster splits. The split is caused by very long garbage collect cycles, caused by the stress test. When the cluster split I stop the stress test.

Once in a while the clusters aren't able to merge any more. As far as I can tell this is happening when node1 is the merge leader, but i'm not 100% certain of this. I enabled tracelogging and put some extra log statements to track down this bug. On node one I see the following relevant log statements (sending MERGE_REQ is a log statement I added myself in Merger#getMergeDataFromSubgroupCoordinators):

node1=bramws
node2=testnode2

14:45:30.755 680842 [ViewHandler,bram,bramws-60382] DEBUG org.jgroups.protocols.pbcast.GMS - bramws-60382: I will be the merge leader. Starting the merge task. Views: {bramws-60382=MergeView::[bramws-60382|10] (1) [bramws-60382], 1 subgroups: [bramws-60382|9] (1) [bramws-60382], testnode2-33255=[testnode2-33255|2] (1) [testnode2-33255]}
14:45:30.758 680845 [MergeTask,bram,bramws-60382] DEBUG org.jgroups.protocols.pbcast.STABLE - suspending message garbage collection
14:45:30.760 680847 [MergeTask,bram,bramws-60382] DEBUG org.jgroups.protocols.pbcast.STABLE - bramws-60382: resume task started, max_suspend_time=220000
14:45:30.760 680847 [MergeTask,bram,bramws-60382] DEBUG org.jgroups.protocols.pbcast.GMS - bramws-60382: merge task bramws-60382::9 started with 2 participants
14:45:30.760 680847 [MergeTask,bram,bramws-60382] TRACE org.jgroups.protocols.pbcast.GMS - bramws-60382: sending MERGE_REQ to [bramws-60382, testnode2-33255]

On node2 I see the following relevent stuff:

14:45:30.762 703525 [Incoming-1,bram,testnode2-33255] TRACE org.jgroups.protocols.UNICAST3 - testnode2-33255 <-- DATA(bramws-60382: #1, conn_id=10, first)
14:45:30.762 703525 [Incoming-1,bram,testnode2-33255] TRACE org.jgroups.protocols.UNICAST3 - testnode2-33255: conn_id=10 != 9; resetting receiver window
14:45:30.762 703525 [Incoming-1,bram,testnode2-33255] TRACE org.jgroups.protocols.UNICAST3 - testnode2-33255: created receiver window for bramws-60382 at seqno=#1 for conn-id=10
14:45:30.762 703525 [Incoming-1,bram,testnode2-33255] TRACE org.jgroups.protocols.UNICAST3 - testnode2-33255: delivering bramws-60382#1
14:45:30.762 703525 [Incoming-1,bram,testnode2-33255] INFO n.s.c.c.c.NodeAuthenticatorImpl - Successfully authenticated node 1 with address bramws-60382.
14:45:30.762 703525 [Incoming-1,bram,testnode2-33255] DEBUG org.jgroups.protocols.pbcast.GMS - Received MERGE_REQ from bramws-60382
14:45:30.762 703525 [Incoming-1,bram,testnode2-33255] DEBUG org.jgroups.protocols.pbcast.GMS - Handling merge request
14:45:30.762 703525 [Incoming-1,bram,testnode2-33255] DEBUG org.jgroups.protocols.pbcast.STABLE - suspending message garbage collection
14:45:30.762 703525 [Incoming-1,bram,testnode2-33255] DEBUG org.jgroups.protocols.pbcast.STABLE - testnode2-33255: resume task started, max_suspend_time=220000
14:45:30.762 703525 [Incoming-1,bram,testnode2-33255] TRACE org.jgroups.protocols.pbcast.GMS - testnode2-33255: got merge request from bramws-60382, merge_id=bramws-60382::9, mbrs=[testnode2-33255]
14:45:30.763 703526 [Incoming-1,bram,testnode2-33255] DEBUG org.jgroups.protocols.pbcast.GMS - Sent merge response to 'bramws-60382' for merge 'bramws-60382::9' with view '[testnode2-33255|2] (1) [testnode2-33255]'
14:45:30.763 703526 [Incoming-1,bram,testnode2-33255] TRACE org.jgroups.protocols.UNICAST3 - testnode2-33255 --> DATA(bramws-60382: #1786, conn_id=1)

This should mean the MERGE_RSP is sent back to node1 however, node1 never seems to receive this causing the merge to fail:

....
14:45:30.761 680848 [Incoming-2,bram,bramws-60382] DEBUG org.jgroups.protocols.pbcast.GMS - Received MERGE_REQ from bramws-60382
...
14:45:35.763 685850 [MergeTask,bram,bramws-60382] TRACE org.jgroups.protocols.pbcast.GMS - bramws-60382: collected 1 merge response(s) in 5003 ms
14:45:35.763 685850 [MergeTask,bram,bramws-60382] DEBUG org.jgroups.protocols.pbcast.GMS - bramws-60382: merge leader bramws-60382 did not get responses from all 2 partition coordinators; missing responses from 1 members, removing them from the merge

The above sequence keeps repeating itself, I have to restart the application to form one cluster again. Enabling trace logging adds allot of stuff to the logs. Is there something I can look for? I can see traffic is received from node2 on node1, I have a (temp) custom filter in place to filter out locking requests from nodes not present in the current view to prevent deadlocks. Log from node1 showing incoming traffic from node2:

14:45:35.628 685715 [Incoming-2,bram,bramws-60382] ERROR n.s.c.j.p.g.GarbageFilterProtocol - Got message from 'shockvm-tn3-33255' with headers 'CENTRAL_LOCK: [LockingHeader], UNICAST3: DATA, seqno=1741, conn_id=1, first, 1201: [ApplicationVersionHeader]' but source not known in our view - dropping message

Its very hard to reproduce this bug and its basically just restarting the application and running the stress test over and over until I hit the bug.

-- 
Met vriendelijke groet / Kind regards,
Bram Klein Gunnewiek | Shock Media B.V.

Tel: +31 (0)546 - 714360
Fax: +31 (0)546 - 714361
Web: https://www.shockmedia.nl/

------------------------------------------------------------------------------

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