Bug 1342456

Summary:	Multiple Error Messages on Brick while deleting messages "0-hetzer-posix: listxattr failed"
Product:	[Community] GlusterFS	Reporter:	Karan Sandha <ksandha>
Component:	posix	Assignee:	Ravishankar N <ravishankar>
Status:	CLOSED NOTABUG	QA Contact:
Severity:	medium	Docs Contact:
Priority:	unspecified
Version:	mainline	CC:	bugs, ravishankar
Target Milestone:	---	Keywords:	Triaged
Target Release:	---
Hardware:	All
OS:	Unspecified
Whiteboard:
Fixed In Version:		Doc Type:	If docs needed, set a value
Doc Text:		Story Points:	---
Clone Of:		Environment:
Last Closed:	2016-06-24 09:30:03 UTC	Type:	Bug
Regression:	---	Mount Type:	---
Documentation:	---	CRM:
Verified Versions:		Category:	---
oVirt Team:	---	RHEL 7.3 requirements from Atomic Host:
Cloudforms Team:	---	Target Upstream Version:
Embargoed:

Description Karan Sandha 2016-06-03 10:09:41 UTC

Description of problem:
Multiple error where seen in brick logs while deleting files from mount point.

2016-06-03 09:45:39.306071] E [MSGID: 113001] [posix.c:4580:posix_getxattr] 0-hetzer-posix: listxattr failed on /rhs/brick1/hetzer/.glusterfs/8c/86/8c863c73-040c-4400-997c-89e36cf50a31 [No such file or directory]

[2016-06-03 09:45:39.408789] E [MSGID: 113039] [posix.c:2996:posix_open] 0-hetzer-posix: open on /rhs/brick1/hetzer/.glusterfs/3d/7d/3d7d3649-1219-4c5c-b5a5-428b6cd26be3, flags: 2 [No such file or directory]

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


How reproducible:
2/2

Steps to Reproduce:
1. Create a 1x3 volume "hetzer" and mount using fuse on client /mnt/hetzer (10.70.42.93)
2. Create 10000+ files on client using dd if=/dev/urandom of=hetzer$i count=4 bs=4K
3. Start Deleting the files from the mount point 
4. tailf /var/log/glusterfs/bricks/rhs-brick1-hetzer.log You will start observing multiple ERROR logs.
Actual results:
[root@dhcp43-192 ~]# tailf /var/log/glusterfs/bricks/rhs-brick1-hetzer.log 
[2016-06-03 09:43:38.772900] E [MSGID: 113001] [posix.c:4580:posix_getxattr] 0-hetzer-posix: listxattr failed on /rhs/brick1/hetzer/.glusterfs/fa/12/fa12d0fe-a3df-455e-b9c9-d9247441e87c [No such file or directory]
[2016-06-03 09:43:39.220863] E [MSGID: 113039] [posix.c:2996:posix_open] 0-hetzer-posix: open on /rhs/brick1/hetzer/.glusterfs/5b/f0/5bf085af-bdc3-4dd5-adf8-6b4d6a27ab23, flags: 2 [No such file or directory]
[2016-06-03 09:43:39.661004] E [MSGID: 113039] [posix.c:2996:posix_open] 0-hetzer-posix: open on /rhs/brick1/hetzer/.glusterfs/ee/9f/ee9f4227-f9c4-4bd9-bf97-f50f39d1b51b, flags: 2 [No such file or directory]
[2016-06-03 09:43:40.190877] E [MSGID: 113039] [posix.c:2996:posix_open] 0-hetzer-posix: open on /rhs/brick1/hetzer/.glusterfs/1a/56/1a56aa12-09f5-4557-a1e0-95ce954eee88, flags: 2 [No such file or directory]
[2016-06-03 09:43:40.661664] E [MSGID: 113039] [posix.c:2996:posix_open] 0-hetzer-posix: open on /rhs/brick1/hetzer/.glusterfs/e2/63/e2639169-8baf-4dfe-bc4f-85d0d5f5473e, flags: 2 [No such file or directory]
[2016-06-03 09:43:40.726440] E [MSGID: 113039] [posix.c:2996:posix_open] 0-hetzer-posix: open on /rhs/brick1/hetzer/.glusterfs/7a/f2/7af2d2aa-9eda-477e-b5e5-51b3739ecc79, flags: 2 [No such file or directory]
[2016-06-03 09:43:40.842362] E [MSGID: 113039] [posix.c:2996:posix_open] 0-hetzer-posix: open on /rhs/brick1/hetzer/.glusterfs/d8/18/d81885a0-9b67-441e-92f6-ef6195f6bf2c, flags: 2 [No such file or directory]
[2016-06-03 09:43:40.914340] E [MSGID: 113001] [posix.c:4580:posix_getxattr] 0-hetzer-posix: listxattr failed on /rhs/brick1/hetzer/.glusterfs/66/c3/66c3ccdb-8761-417f-8787-dc24479610e1 [No such file or directory]
[2016-06-03 09:43:43.527469] E [MSGID: 113039] [posix.c:2996:posix_open] 0-hetzer-posix: open on /rhs/brick1/hetzer/.glusterfs/66/72/6672e39d-3930-4951-a9bb-a40ef97cbc39, flags: 2 [No such file or directory]
[2016-06-03 09:43:44.987881] E [MSGID: 113039] [posix.c:2996:posix_open] 0-hetzer-posix: open on /rhs/brick1/hetzer/.glusterfs/95/d6/95d6291b-4992-44b7-b235-f5dcba8faf30, flags: 2 [No such file or directory]
[2016-06-03 09:43:47.342075] E [MSGID: 113039] [posix.c:2996:posix_open] 0-hetzer-posix: open on /rhs/brick1/hetzer/.glusterfs/7a/63/7a63be79-d699-4081-abc9-1b94de480198, flags: 2 [No such file or directory]
[2016-06-03 09:43:48.338046] E [MSGID: 113039] [posix.c:2996:posix_open] 0-hetzer-posix: open on /rhs/brick1/hetzer/.

Expected results:
No error Messages should be observed.

Additional info:

Comment 1 Ravishankar N 2016-06-24 09:30:03 UTC

This is expected behaviour. I was not able to re-create the issue only when when there were pending heals like so:
1. Create arbiter volume and fuse mount it.
2. Kill brick 2.
3. Create files from the mount:
for (( i=1;i<=5000;i++ )) 
do 
dd if=/dev/urandom of=file$i bs=1024 count=1
done
4. Bring down brick 1, then brick up brick 2
5. Trigger index heal, let entry+mdata selfheal complete from b3 to b2.
6. rm -rf * from mount
7. Bring back b1, trigger index heal.

On the brick log of b1:
[2016-06-24 08:45:16.075282] E [MSGID: 113039] [posix.c:2996:posix_open] 0-testvol-posix: open on /brick/brick1/.glusterfs/6a/af/6aafcff2-a985-4bdd-a8b1-9d148c5c5aeb, flags: 2 [No such file or directory]
[2016-06-24 08:45:16.113140] E [MSGID: 113039] [posix.c:2996:posix_open] 0-testvol-posix: open on /brick/brick1/.glusterfs/96/db/96dbe3d6-754a-464c-83c0-b8c361dc6ffe, flags: 2 [No such file or directory]
[2016-06-24 08:45:16.157489] E [MSGID: 113039] [posix.c:2996:posix_open] 0-testvol-posix: open on /brick/brick1/.glusterfs/7d/4c/7d4cf39a-ab4d-414b-a19c-35377e3d1fa0, flags: 2 [No such file or directory]
[2016-06-24 08:45:16.214219] E [MSGID: 113039] [posix.c:2996:posix_open] 0-testvol-posix: open on /brick/brick1/.glusterfs/c1/16/c116fa0d-7362-4adb-a4fa-b2b18f082f8c, flags: 2 [No such file or directory]
[2016-06-24 08:45:16.222572] E [MSGID: 113039] [posix.c:2996:posix_open] 0-testvol-posix: open on /brick/brick1/.glusterfs/79/99/7999afbe-5320-4f2c-b328-67553cfe2e17, flags: 2 [No such file or directory]
[2016-06-24 08:45:16.261584] E [MSGID: 113039] [posix.c:2996:posix_open] 0-testvol-posix: open on /brick/brick1/.glusterfs/0b/bc/0bbc4225-c4d2-45ee-be30-77217d0dc7bf, flags: 2 [No such file or directory]
[2016-06-24 08:45:16.284752] E [MSGID: 113039] [posix.c:2996:posix_open] 0-testvol-posix: open on /brick/brick1/.glusterfs/4d/89/4d89366d-7c49-421c-8887-f488447c1773, flags: 2 [No such file or directory]
[2016-06-24 08:45:16.313496] E [MSGID: 113039] [posix.c:2996:posix_open] 0-testvol-posix: open on /brick/brick1/.glusterfs/d1/37/d137264b-8026-43f4-9b95-6cfec3abb01e, flags: 2 [No such file or directory]
[2016-06-24 08:45:16.328231] E [MSGID: 113039] [posix.c:2996:posix_open] 0-testvol-posix: open on /brick/brick1/.glusterfs/88/4b/884bfd72-13c7-45a7-b023-272ce8487147, flags: 2 [No such file or directory]
[2016-06-24 08:45:16.349531] E [MSGID: 113039] [posix.c:2996:posix_open] 0-testvol-posix: open on /brick/brick1/.glusterfs/e9/c9/e9c9d070-97b4-432e-91dc-2ff94e1672f6, flags: 2 [No such file or directory]
[2016-06-24 08:45:16.355774] E [MSGID: 113039] [posix.c:2996:posix_open] 0-testvol-posix: open on /brick/brick1/.glusterfs/95/5e/955eedd0-afe7-4da4-a9f1-ef0367df6f9f, flags: 2 [No such file or directory]
[2016-06-24 08:45:16.397479] E [MSGID: 113039] [posix.c:2996:posix_open] 0-testvol-posix: open on /brick/brick1/.glusterfs/49/df/49dffa95-31c0-4f0c-b726-bdf1414fd863, flags: 2 [No such file or directory]
[2016-06-24 08:45:16.419454] E [MSGID: 113039] [posix.c:2996:posix_open] 0-testvol-posix: open on /brick/brick1/.glusterfs/56/3d/563de313-589c-4899-accc-a729e458800e, flags: 2 [No such file or directory]
[2016-06-24 08:45:16.442720] E [MSGID: 113039] [posix.c:2996:posix_open] 0-testvol-posix: open on /brick/brick1/.glusterfs/50/5f/505fcdc9-1f64-452e-91d1-fb13d86fab60, flags: 2 [No such file or directory]
[2016-06-24 08:45:16.465462] E [MSGID: 113039] [posix.c:2996:posix_open] 0-testvol-posix: open on /brick/brick1/.glusterfs/98/08/9808ceaf-5b89-43c8-8ff5-902612336ba0, flags: 2 [No such file or directory]
[2016-06-24 08:45:16.536507] E [MSGID: 113039] [posix.c:2996:posix_open] 0-testvol-posix: open on /brick/brick1/.glusterfs/a4/05/a405557e-ac15-41e5-8cd0-965780ce2f99, flags: 2 [No such file or directory]
[2016-06-24 08:45:16.574764] E [MSGID: 113039] [posix.c:2996:posix_open] 0-testvol-posix: open on /brick/brick1/.glusterfs/a7/cc/a7cc12a0-964f-4402-96a7-562df287c3d8, flags: 2 [No such file or directory]
[2016-06-24 08:45:16.583749] E [MSGID: 113039] [posix.c:2996:posix_open] 0-testvol-posix: open on /brick/brick1/.glusterfs/f9/77/f97750b2-0598-483b-9156-02681ecc6f9f, flags: 2 [No such file or directory]
[2016-06-24 08:45:16.622311] E [MSGID: 113039] [posix.c:2996:posix_open] 0-testvol-posix: open on /brick/brick1/.glusterfs/59/2c/592c2ff1-fe57-4b59-a852-54b2df6e9427, flags: 2 [No such file or directory]
-----------------------------------------------------------------------------
RCA: This is basically a race between entry heal and data heal. When b1 comes back up, entry selfheal expunges all files in it. In the mean time, the gfid indices inside brick1/.glusterfs/indices/xattrop also get processed. If the entry heal had already expunged the file, the stale index is removed, Otherwise, it will proceed to self-heal code-path, which tries to lookup, open (data self-heal) etc, which will fail at various points depending on when the entry self-heal purges



Closing the BZ as NOTABUG. Karan, if you are able to hit the issue when doing rm -rf when there are no pending heals, feel free to re-open the BZ.

Comment 2 Ravishankar N 2016-06-24 09:31:04 UTC

(In reply to Ravishankar N from comment #1)
> This is expected behaviour. I was not able to re-create the issue only when

typo. I meant "I was able to re-create only when"