Bug 1804164

Description of problem:
With granular-entry-heal is enabled on the volume, when one of the brick goes down and triggering heal, results in clearing entries of parent directory, which finally results in volume heal info entries, when all the bricks are up

.prob* file is found in one brick and missing on other 2 bricks

Version-Release number of selected component (if applicable):

RHGS 3.5.1 (6.0-28)
RHVH-4.3.8


Steps to Reproduce:
1.Create a VM 
2.Run I/O in the background  
3.while running the I/O kill one engine brick 
4. wait for 10 minutes 
5. restart glusterd 

Actual results:
.prob missing on 2 brick

Expected results:
There should be no heal pending in the engine and .prob file should be present on all the engine brick

Additional info:

[node1.example.com ~]# ls /gluster_bricks/engine/engine/ -a
.  ..  faf5b9c4-04b0-4ec2-9743-afa5207966fc  .glusterfs  .prob-ddb8b8b6-f2bd-42f1-b1b2-f8106ac78a0a  .shard

[node2.example.com ~]# ls /gluster_bricks/engine/engine/ -a
.  ..  faf5b9c4-04b0-4ec2-9743-afa5207966fc  .glusterfs  .shard

[node3.example.com ~]# ls /gluster_bricks/engine/engine/ -a
.  ..  faf5b9c4-04b0-4ec2-9743-afa5207966fc  .glusterfs  .shard

--- Additional comment from milind on 2020-01-20 05:10:34 UTC ---

sosreport: http://rhsqe-repo.lab.eng.blr.redhat.com/sosreports/milind/1792821/

--- Additional comment from Sahina Bose on 2020-01-23 09:48:16 UTC ---

Ravi, what's next step on this bug?

--- Additional comment from Ravishankar N on 2020-01-24 12:40:44 UTC ---

On looking at the setup we found that the entry was not getting healed because the parent dir did not have any entry pending xattrs. The test (thanks Sas for the info) that writes to the prob file apparently unlinks the file before continuing to write to it, so maybe the expected result is that the file be _removed_ from all bricks, not that it is present on them:
------------------------
f = os.open(path, os.O_WRONLY | os.O_DIRECT | os.O_DSYNC | os.O_CREAT | os.O_EXCL, stat.S_IRUSR | stat.S_IWUSR)
#time.sleep(20)
os.unlink(path)

#time.sleep(20)
m = mmap.mmap(-1, 1024)
s = b' ' * 1024

m.write(s)
os.write(f, m)
os.close(f)
------------------------
So it looks like one of the bricks (engine-client-0) was killed at the time of unlink of the prob file so the unlink did not go through on it. But AFR should have marked pending xattrs during post-op on the good bricks (so that selfheal later on removes the prob file from this brick also). I do not see any network errors on the client log which can explain a post-op failure, so I'm not sure what happened here. We need to see if this can be consistently recreated. Leaving a need-info on Milind for the same. We need the exact time the killing and restating of the bricks happen to correlate it with the log.

--- Additional comment from milind on 2020-01-27 05:55:01 UTC ---

1. create a VM  after the VM is created it will be shutdown
2. start the VM .  While starting the vm ".probe*"  will be created under all the nodes "/gluster_bricks/engine/engine/"
3. After the creation of ".probe*"  file kill one brick of the engine
4. restart glusterd after 10 minutes

New sos-report is available here http://rhsqe-repo.lab.eng.blr.redhat.com/sosreports/milind/1792821/newSos/

brick killing time in rhsqa-grafton1.lab.eng.blr.redhat.com : 8:25 PM 26-jan-2020
restart glusterd time rhsqa-grafton1.lab.eng.blr.redhat.com : 8:35 PM 26-jan-2020

--- Additional comment from milind on 2020-01-29 04:13:38 UTC ---

latest sos-report with TRACE log : http://rhsqe-repo.lab.eng.blr.redhat.com/sosreports/milind/1792821/29-jan-2020/

brick killing time in rhsqa-grafton1.lab.eng.blr.redhat.com : 2:13 PM 27-jan-2020
restart glusterd time rhsqa-grafton1.lab.eng.blr.redhat.com : 2:25 PM 27-jan-2020

--- Additional comment from Ravishankar N on 2020-01-29 11:23:54 UTC ---

Some notes:

I was trying to recreate the issue locally on a 1x3 volume with the same volume options set as with an RHHI setup, using the python test in comment#3, i.e.
------------------------------------------------------------------------------------------------------------------------------------------------------------
import mmap
import os
import stat
#import time
path = "/mnt/fuse_mnt/probe_test"
f = os.open(path, os.O_WRONLY | os.O_DIRECT | os.O_DSYNC | os.O_CREAT | os.O_EXCL, stat.S_IRUSR | stat.S_IWUSR)
#time.sleep(20)
os.unlink(path)
#time.sleep(20)
m = mmap.mmap(-1, 1024)
s = b' ' * 1024
m.write(s)
os.write(f, m)
os.close(f)
------------------------------------------------------------------------------------------------------------------------------------------------------------
I killed the 1st brick manually after the creat and before the unlink. When I executed the os.write, I got the following error:
>>> os.write(f, m)
Traceback (most recent call last):
  File "<stdin>", line 1, in <module>
FileNotFoundError: [Errno 2] No such file or directory
>>> os.close(f)
>>>


The mount log contained the following errors. Not sure if this is expected behaviour as the test passed without sharding enabled.

[2020-01-29 10:41:48.849784] W [MSGID: 114031] [client-rpc-fops_v2.c:2630:client4_0_lookup_cbk] 0-testvol-client-2: remote operation failed. Path: <gfid:d1e3ee1e-d0be-47fd-a883-265e655fa6f3> (d1e3ee1e-d0be-47fd-a883-265e655fa6f3) [No such file or directory]
[2020-01-29 10:41:48.849784] W [MSGID: 114031] [client-rpc-fops_v2.c:2630:client4_0_lookup_cbk] 0-testvol-client-1: remote operation failed. Path: <gfid:d1e3ee1e-d0be-47fd-a883-265e655fa6f3> (d1e3ee1e-d0be-47fd-a883-265e655fa6f3) [No such file or directory]
[2020-01-29 10:41:48.849986] E [MSGID: 133001] [shard.c:1534:shard_lookup_base_file_cbk] 0-testvol-shard: Lookup on base file failed : d1e3ee1e-d0be-47fd-a883-265e655fa6f3 [No such file or directory]
[2020-01-29 10:41:48.850068] W [fuse-bridge.c:2992:fuse_writev_cbk] 0-glusterfs-fuse: 65: WRITE => -1 gfid=d1e3ee1e-d0be-47fd-a883-265e655fa6f3 fd=0x7f91800028b8 (No such file or directory)
[2020-01-29 10:41:48.851647] W [MSGID: 114031] [client-rpc-fops_v2.c:2630:client4_0_lookup_cbk] 0-testvol-client-1: remote operation failed. Path: <gfid:d1e3ee1e-d0be-47fd-a883-265e655fa6f3> (d1e3ee1e-d0be-47fd-a883-265e655fa6f3) [No such file or directory]
[2020-01-29 10:41:48.851793] W [MSGID: 114031] [client-rpc-fops_v2.c:2630:client4_0_lookup_cbk] 0-testvol-client-2: remote operation failed. Path: <gfid:d1e3ee1e-d0be-47fd-a883-265e655fa6f3> (d1e3ee1e-d0be-47fd-a883-265e655fa6f3) [No such file or directory]
[2020-01-29 10:41:48.851859] E [MSGID: 133001] [shard.c:1534:shard_lookup_base_file_cbk] 0-testvol-shard: Lookup on base file failed : d1e3ee1e-d0be-47fd-a883-265e655fa6f3 [No such file or directory]
[2020-01-29 10:41:48.851912] W [fuse-bridge.c:1247:fuse_truncate_cbk] 0-glusterfs-fuse: 66: FTRUNCATE() ERR => -1 (No such file or directory)

------------------------------------------------------------------------------------------------------------------------------------------------------------
Nevertheless, AFR xattrs were set correctly on the parent dir , i.e. '/' and heal removed the file from the 1st brick when it was brought online, as expected.
glustershd.log:
[2020-01-29 10:42:59.413282] W [MSGID: 108015] [afr-self-heal-entry.c:51:afr_selfheal_entry_delete] 0-testvol-replicate-0: expunging file 00000000-0000-0000-0000-000000000001/probe_test (d1e3ee1e-d0be-47fd-a883-265e655fa6f3) on testvol-client-0
[2020-01-29 10:42:59.417843] I [MSGID: 108026] [afr-self-heal-common.c:1747:afr_log_selfheal] 0-testvol-replicate-0: Completed entry selfheal on 00000000-0000-0000-0000-000000000001. sources=[1] 2  sinks=0

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

--- Additional comment from SATHEESARAN on 2020-02-10 07:09:33 UTC ---

I have also seen the same behavior when upgrading from RHV 4.2.8 to RHV 4.3.8
and also from RHV 4.3.7 to RHV 4.3.8

During this upgrade, one of the bricks were killed, and gluster software was upgraded from RHGS 3.4.4 ( gluster-3.12.2-47.5 ) to RHGS 3.5.1 ( gluster-6.0-29 )

After upgrading one of the node, the he.metadata and he.lockspace files were shown are pending to heal and
that continued forever. On checking for its GFID, then it was mismatching with the same file on other 2 bricks,
but self-heal was not happening though, as the changelog entry was missing in the parent directory.

--- Additional comment from Ravishankar N on 2020-02-10 07:30:02 UTC ---

So I am able to reproduce the issue fairly consistently. 
1. Create a 1x3 volume with RHHI options enabled.
2. Create and write to a file from the mount.
3. Bring one brick down, delete and re-create the file so that there is pending (granular) entry heal.
4. With the brick still down, launch the index heal.
xat
Even though there is nothing to be healed (since the sink brick is still down), index heal seems to be doing a no-op and resetting parent dir's afr changelog xattrs, which is why the entry never gets healed. 
In the QE setup also, this race is what is happening. Even before the upgraded node comes online, the shd does the entry heal described above. We can see messages like these in the shd log where there is no 'source' and the good bricks are 'sinks':
[2020-02-10 05:57:55.847756] I [MSGID: 108026] [afr-self-heal-common.c:1750:afr_log_selfheal] 0-testvol-replicate-0: Completed entry selfheal on 77dd5a45-dbf5-4592-b31b-b440382302e9. sources= sinks=0 2

I need to check where the bug is in the code, if it is specific to granular entry heal and how to fix it.

--- Additional comment from Ravishankar N on 2020-02-11 11:41:54 UTC ---

(In reply to Ravishankar N from comment #8)
> I need to check where the bug is in the code, if it is specific to granular
> entry heal and how to fix it.

So the gfid split-brain will happen only if granular-entry heal is enabled, but even otherwise, even if only two good bricks are up, spurious entry heals are triggered continuously leading to multiple unnecessary network ops. I'm sending a fix upstream for review.

--- Additional comment from Ravishankar N on 2020-02-11 11:53:07 UTC ---

Upstream patch: https://review.gluster.org/#/c/glusterfs/+/24109/