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

Questions/problems related to using JGroups schreef op 2016-08-20 09:25:
> Garbage filter? Care to elaborate?

I made a quick protocol to filter out lock requests from members not 
present in the current view. This is fixed in 3.6.11 
(https://github.com/belaban/JGroups/pull/311) but the filter was still 
in place. The filter was placed to high (or low) in the protocol stack. 
I think the lock request messages stayed in the retransmit table on the 
node requesting the lock. Something like that, i'm not exactly sure but 
I saw lock requests getting retransmitted every time a 
MERGE_REQ/MERGE_RSP handshake was taking place. Removing the filter 
solved everything.


> 
> Hmm, I was going to reply to this, but sometimes problems tend to go
> away when you sit on them for a while! :-)

Took more then a week :/. Oh well, fixed! :)


> 
> On 20/08/16 08:22, Questions/problems related to using JGroups wrote:
>> Turns out the issue was caused by the 'garbage filter' we temporarily
>> put in place until JGroups 3.6.11 comes out. It was placed incorretly 
>> in
>> the protocol stack. Problem solved by removing the protocol completely
>> and switching to 3.6.11-SNAPSHOT.
>> 
>> Questions/problems related to using JGroups schreef op 2016-08-17 
>> 16:19:
>>> 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/ [1]
>>> 
>>> 
>>> Links:
>>> ------
>>> [1] https://www.shockmedia.nl/
>>> 
>>> ------------------------------------------------------------------------------
>>> 
>>> _______________________________________________
>>> javagroups-users mailing list
>>> [email protected]
>>> https://lists.sourceforge.net/lists/listinfo/javagroups-users
>> 
>> ------------------------------------------------------------------------------
>> _______________________________________________
>> javagroups-users mailing list
>> [email protected]
>> https://lists.sourceforge.net/lists/listinfo/javagroups-users
>> 

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