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

Garbage filter? Care to elaborate?

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

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
>

-- 
Bela Ban, JGroups lead (http://www.jgroups.org)


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