Bug 1166575

Summary: [USS]: ls on absolute path for a file in snap world fails but relative path works
Product: [Red Hat Storage] Red Hat Gluster Storage Reporter: Rahul Hinduja <rhinduja>
Component: snapshotAssignee: Sachin Pandit <spandit>
Status: CLOSED WORKSFORME QA Contact: storage-qa-internal <storage-qa-internal>
Severity: urgent Docs Contact:
Priority: urgent    
Version: unspecifiedCC: asengupt, nsathyan, rcyriac, rhs-bugs, senaik, spandit, storage-qa-internal, vagarwal
Target Milestone: ---   
Target Release: ---   
Hardware: x86_64   
OS: Linux   
Whiteboard: USS
Fixed In Version: Doc Type: Bug Fix
Doc Text:
Story Points: ---
Clone Of: Environment:
Last Closed: 2015-04-30 07:56:00 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 Rahul Hinduja 2014-11-21 09:26:34 UTC
Description of problem:
=======================

For a file "courier.pp", if ls is performed for its absolute path it fails as:

[root@wingo modules]# ls -lrt /mnt/vol0/a/b/.snaps/snap2/etc.1/selinux/targeted/modules/active/modules/courier.pp
ls: cannot access /mnt/vol0/a/b/.snaps/snap2/etc.1/selinux/targeted/modules/active/modules/courier.pp: No such file or directory


But when cd to the parent directory of "courier.pp" and did ls, it works as:

[root@wingo modules]# cd /mnt/vol0/a/b/.snaps/snap2/etc.1/selinux/targeted/modules/active/modules/
[root@wingo modules]# ls -lrt courier.pp
-rw-------. 1 root root 13705 Nov 21  2014 courier.pp
[root@wingo modules]# 

[root@wingo ~]# ls -lrt /mnt/vol0/a/b/.snaps/snap2/etc.1/selinux/targeted/modules/active/modules/ | grep courier.pp
-rw-------. 1 root root 13705 Nov 21  2014 courier.pp
[root@wingo ~]# 



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

glusterfs-3.6.0.33-1.el6rhs.x86_64


Steps to Reproduce:
===================
1. Create 4 node cluster
2. Create a volume (2x2)
3. Mount the volume on a client (Fuse and NFS)
4. Create Nested directory from fuse mount (a/b)
5. Create Nested directory from nfs mount (c/d)
6. From fuse mount perform following:

cd a/b
cp -rvf /etc/host* .
cp -rvf /etc .
cd ..
cp -rvf /etc/* .

7. From NFS mount perform following:

mkdir -p c/d
cd c/d/
cp -rvf /etc/host* .
cd ..
cp -rvf /etc/* .
cd d
cp -rvf /etc .

8. Create a snapshot of a volume snap1
9. From fuse mount perform following:

cd a/b
cp -rvf /etc etc.1
cd ..
cp -rvf /etc etc.1

10. From NFS mount perform the following:

cd c/d
cp -rvf /etc .
cp -rvf /etc etc.1
cd ..
cp -rvf /etc etc.1

11. Create another snapshot of a volume snap2
12. Enable USS for a volume
13. From the fuse client do ls using absolute path

[root@wingo modules]# ls -lrt /mnt/vol0/a/b/.snaps/snap2/etc.1/selinux/targeted/modules/active/modules/courier.pp"

14. From the fuse client do ls from the parent directory of the file

[root@wingo modules]# cd /mnt/vol0/a/b/.snaps/snap2/etc.1/selinux/targeted/modules/active/modules/
[root@wingo modules]# ls -lrt courier.pp
-rw-------. 1 root root 13705 Nov 21  2014 courier.pp
[root@wingo modules]# 


Note: I have millions file and this I found on one file of 4 files, there could be others too having same issue as logs suggest "inode context null" for different gfids.

Actual results:
===============

ls using absolute path failed (step 13) and ls from the parent directory worked (step14)


Expected results:
=================

ls should be successful from absolute path too


Additional info:
================

Logs:
=====

snapd logs reports:
===================

[root@inception ~]# tail -5 /var/log/glusterfs/snaps/vol0/snapd.log 
[2014-11-21 09:22:12.219777] W [dict.c:1352:dict_get_with_ref] (-->/usr/lib64/libglusterfs.so.0(default_lookup_resume+0x12c) [0x3d6d4273dc] (-->/usr/lib64/glusterfs/3.6.0.33/xlator/features/snapview-server.so(svs_lookup+0x2e3) [0x7fd86c344f23] (-->/usr/lib64/libglusterfs.so.0(dict_get_str_boolean+0x1f) [0x3d6d41acbf]))) 0-dict: dict OR key (entry-point) is NULL
[2014-11-21 09:22:12.226374] W [dict.c:1352:dict_get_with_ref] (-->/usr/lib64/libglusterfs.so.0(default_lookup_resume+0x12c) [0x3d6d4273dc] (-->/usr/lib64/glusterfs/3.6.0.33/xlator/features/snapview-server.so(svs_lookup+0x2e3) [0x7fd86c344f23] (-->/usr/lib64/libglusterfs.so.0(dict_get_str_boolean+0x1f) [0x3d6d41acbf]))) 0-dict: dict OR key (entry-point) is NULL
[2014-11-21 09:22:12.233003] W [dict.c:1352:dict_get_with_ref] (-->/usr/lib64/libglusterfs.so.0(default_lookup_resume+0x12c) [0x3d6d4273dc] (-->/usr/lib64/glusterfs/3.6.0.33/xlator/features/snapview-server.so(svs_lookup+0x2e3) [0x7fd86c344f23] (-->/usr/lib64/libglusterfs.so.0(dict_get_str_boolean+0x1f) [0x3d6d41acbf]))) 0-dict: dict OR key (entry-point) is NULL
[2014-11-21 09:22:12.238769] W [dict.c:1352:dict_get_with_ref] (-->/usr/lib64/libglusterfs.so.0(default_lookup_resume+0x12c) [0x3d6d4273dc] (-->/usr/lib64/glusterfs/3.6.0.33/xlator/features/snapview-server.so(svs_lookup+0x2e3) [0x7fd86c344f23] (-->/usr/lib64/libglusterfs.so.0(dict_get_str_boolean+0x1f) [0x3d6d41acbf]))) 0-dict: dict OR key (entry-point) is NULL
[2014-11-21 09:22:12.245301] W [dict.c:1352:dict_get_with_ref] (-->/usr/lib64/libglusterfs.so.0(default_lookup_resume+0x12c) [0x3d6d4273dc] (-->/usr/lib64/glusterfs/3.6.0.33/xlator/features/snapview-server.so(svs_lookup+0x2e3) [0x7fd86c344f23] (-->/usr/lib64/libglusterfs.so.0(dict_get_str_boolean+0x1f) [0x3d6d4[root@inception ~]# 



snap server logs reports:
=========================

[root@inception ~]# tail -10 /var/log/glusterfs/snaps/vol0/snap2-f677b8f8-3e2d-473c-b8ab-c066fe04d55c.log 
[2014-11-21 07:25:16.469133] E [io-cache.c:564:ioc_open_cbk] 1-2548f1fd02e24894aeceb6f47151fc41-io-cache: inode context is NULL (5f7750b5-f2d7-415d-8e84-81d401906d79)
[2014-11-21 07:25:16.472987] E [io-cache.c:564:ioc_open_cbk] 1-2548f1fd02e24894aeceb6f47151fc41-io-cache: inode context is NULL (f647e7e6-195e-4ea8-86bc-cbb534673a82)
[2014-11-21 07:25:16.477776] E [io-cache.c:564:ioc_open_cbk] 1-2548f1fd02e24894aeceb6f47151fc41-io-cache: inode context is NULL (43638e18-d05f-4e07-b5d8-7e26b13dda55)
[2014-11-21 07:25:16.482695] E [io-cache.c:564:ioc_open_cbk] 1-2548f1fd02e24894aeceb6f47151fc41-io-cache: inode context is NULL (342a65df-b4cc-4e10-ae77-82f5007e1fa0)
[2014-11-21 07:25:16.487381] E [io-cache.c:564:ioc_open_cbk] 1-2548f1fd02e24894aeceb6f47151fc41-io-cache: inode context is NULL (592a2a8b-fb11-4859-997b-3d1136cc2098)
[2014-11-21 07:25:16.492010] E [io-cache.c:564:ioc_open_cbk] 1-2548f1fd02e24894aeceb6f47151fc41-io-cache: inode context is NULL (bbf8fccc-f8df-4881-8cd2-2b64ac3bfffa)
[2014-11-21 07:25:16.496989] E [io-cache.c:564:ioc_open_cbk] 1-2548f1fd02e24894aeceb6f47151fc41-io-cache: inode context is NULL (1967b05a-4553-41ce-9cb1-13ba9f40e530)
[2014-11-21 07:25:16.501682] E [io-cache.c:564:ioc_open_cbk] 1-2548f1fd02e24894aeceb6f47151fc41-io-cache: inode context is NULL (49005e1f-43d6-4472-a2c4-da5ef3765022)
[2014-11-21 07:26:44.717296] E [snapview-server.c:298:svs_lookup_entry] 0-vol0-snapview-server: failed to do lookup and get the handle for entry courier.pp: (path: <gfid:87b274ab-489d-4bce-9988-a10e7b8c7a1f>/.snaps/snap2/etc.1/selinux/targeted/modules/active/modules/courier.pp:)
[2014-11-21 07:26:44.719509] E [snapview-server.c:298:svs_lookup_entry] 0-vol0-snapview-server: failed to do lookup and get the handle for entry courier.pp: (path: <gfid:87b274ab-489d-4bce-9988-a10e7b8c7a1f>/.snaps/snap2/etc.1/selinux/targeted/modules/active/modules/courier.pp:)
[root@inception ~]#

Comment 1 Rahul Hinduja 2014-11-21 09:30:37 UTC
From the fuse logs, found this: 

[2014-11-20 19:52:50.357467] C [inode.c:217:__is_dentry_cyclic] 0-meta-autoload/inode: detected cyclic loop formation during inode linkage. inode (00000000-0000-0000-0000-000000000001) linking under itself as courier.pp
[2014-11-20 19:52:50.357553] W [inode.c:911:inode_lookup] (-->/usr/lib64/glusterfs/3.6.0.33/xlator/debug/io-stats.so(io_stats_lookup_cbk+0x113) [0x7f7cb5749e73] (-->/usr/lib64/glusterfs/3.6.0.33/xlator/mount/fuse.so(+0x1ef7d) [0x7f7cb9b01f7d] (-->/usr/lib64/glusterfs/3.6.0.33/xlator/mount/fuse.so(+0x1eb2e) [0x7f7cb9b01b2e]))) 0-fuse: inode not found
[2014-11-20 19:53:22.949826] E [snapview-client.c:170:svc_lookup_cbk] 2-vol0-snapview-client: Lookup on normal graph failed with error Stale file handle
[2014-11-20 19:53:22.950475] W [inode.c:165:__foreach_ancestor_dentry] 0-fuse: per dentry fn returned 1
[2014-11-20 19:53:22.950501] C [inode.c:217:__is_dentry_cyclic] 0-meta-autoload/inode: detected cyclic loop formation during inode linkage. inode (00000000-0000-0000-0000-000000000001) linking under itself as courier.pp
[2014-11-20 19:53:22.950588] W [inode.c:911:inode_lookup] (-->/usr/lib64/glusterfs/3.6.0.33/xlator/debug/io-stats.so(io_stats_lookup_cbk+0x113) [0x7f7cb5749e73] (-->/usr/lib64/glusterfs/3.6.0.33/xlator/mount/fuse.so(+0x1ef7d) [0x7f7cb9b01f7d] (-->/usr/lib64/glusterfs/3.6.0.33/xlator/mount/fuse.so(+0x1eb2e) [0x7f7cb9b01b2e]))) 0-fuse: inode not found
[2014-11-20 19:53:22.951496] E [snapview-client.c:170:svc_lookup_cbk] 2-vol0-snapview-client: Lookup on normal graph failed with error Stale file handle
[2014-11-20 19:53:22.952011] W [inode.c:165:__foreach_ancestor_dentry] 0-fuse: per dentry fn returned 1
[2014-11-20 19:53:22.952052] C [inode.c:217:__is_dentry_cyclic] 0-meta-autoload/inode: detected cyclic loop formation during inode linkage. inode (00000000-0000-0000-0000-000000000001) linking under itself as courier.pp

Comment 5 Sachin Pandit 2014-12-01 06:09:58 UTC
I tried to reproduce this issue using the latest downstream code base, and I could not hit it. I'll try this with the latest build and see if it can be reproduced. I'll change the status of the bug accordingly after testing with latest RPMs

Comment 7 senaik 2015-04-30 07:56:00 UTC
Version : gluster --version
glusterfs 3.7.0alpha0 built on Apr 28 2015 

Works in the current build. Will re-open the bug if the issue is seen again