Bug 1703423

The multiple disconnect events are due to reconnect/disconnect to glusterd (port 24007). rpc/clnt has a reconnect feature which tries to reconnect to a disconnected brick and client connection to brick is a two step process:
1. connect to glusterd, get brick port then disconnect
2. connect to brick

In this case step 1 would be successful and step 2 won't happen as glusterd wouldn't send back the brick port (as brick is dead). Nevertheless there is a chain of connect/disconnect (to glusterd) at rpc layer and these are valid steps as we need reconnection logic. However subsequent disconnect events were prevented from reaching parents of protocol/client as it remembered which was the last sent and if current event is the same as last event, it would skip notification. Before Halo replication feature - https://review.gluster.org/16177, last_sent_event for this test case would be GF_EVENT_DISCONNECT and hence subsequent disconnects were skipped notification to parent xlators. But Halo replication introduced another event GF_EVENT_CHILD_PING which gets notified to parents of protocol/client whenever there is a successful ping response. In this case, the successful ping response would be from glusterd and would change conf->last_sent_event to GF_EVENT_CHILD_PING. This made subsequent disconnect events are not skipped.

A patch to propagate GF_EVENT_CHILD_PING only after a successful handshake prevents spurious CHILD_DOWN events to afr. However, I am not sure whether this breaks Halo replication. Would request afr team members comment on the patch (I'll post shortly).

upstream patch: https://review.gluster.org/#/c/glusterfs/+/22821/

Tested with the following:

glusterfs-6.0-12.el7rhgs.x86_64
glusterfs-server-6.0-12.el7rhgs.x86_64
glusterfs-libs-6.0-12.el7rhgs.x86_64
glusterfs-fuse-6.0-12.el7rhgs.x86_64
glusterfs-api-6.0-12.el7rhgs.x86_64
glusterfs-rdma-6.0-12.el7rhgs.x86_64
glusterfs-cli-6.0-12.el7rhgs.x86_64
glusterfs-geo-replication-6.0-12.el7rhgs.x86_64
glusterfs-events-6.0-12.el7rhgs.x86_64
glusterfs-debuginfo-6.0-12.el7rhgs.x86_64
glusterfs-client-xlators-6.0-12.el7rhgs.x86_64 

The steps performed :

1.Created a replica 3 volume and started it.
2.Installed the GDB and glusterfs-debuginfo packages on the node.
3.Enter into the gdb session (gdb -p `pidof glusterfs`) and  set a break point (b __afr_handle_child_down_event)
4.Went to one of the node and killed a brick on the node (kill -9 pid)
5.The following output was seen.There was only 1 event per one disconnect and didnot see any issue that of events generating every 3 sec for one disconnect.

   (gdb) b __afr_handle_child_down_event
Breakpoint 1 at 0x7f675b62b940: file afr-common.c, line 5249.
(gdb) c
Continuing.
[Switching to Thread 0x7f675cafe700 (LWP 16524)]

Breakpoint 1, __afr_handle_child_down_event (this=this@entry=0x7f675400ffe0, child_xlator=child_xlator@entry=0x7f675400d5c0, idx=idx@entry=2, child_latency_msec=child_latency_msec@entry=-1, 
    event=event@entry=0x7f675cafcc5c, call_psh=call_psh@entry=0x7f675cafcc68, up_child=up_child@entry=0x7f675cafcc6c) at afr-common.c:5249
5249	{
.



Based on the above output moving the bug to verified state.

Since the problem described in this bug report should be
resolved in a recent advisory, it has been closed with a
resolution of ERRATA.

For information on the advisory, and where to find the updated
files, follow the link below.

If the solution does not work for you, open a new bug report.

https://access.redhat.com/errata/RHEA-2019:3249