Bug 1285237 - nfs-ganesha+data tiering: posix compliance tests gets stuck at rename test [NEEDINFO]
nfs-ganesha+data tiering: posix compliance tests gets stuck at rename test
Status: ON_QA
Product: Red Hat Gluster Storage
Classification: Red Hat
Component: tier (Show other bugs)
3.1
x86_64 Linux
unspecified Severity urgent
: ---
: ---
Assigned To: Mohammed Rafi KC
Sweta Anandpara
tier-fuse-nfs-samba
: ZStream
Depends On: 1276227
Blocks:
  Show dependency treegraph
 
Reported: 2015-11-25 04:36 EST by Saurabh
Modified: 2017-10-11 03:40 EDT (History)
16 users (show)

See Also:
Fixed In Version: glusterfs-3.7.9-1
Doc Type: Bug Fix
Doc Text:
Story Points: ---
Clone Of:
Environment:
Last Closed:
Type: Bug
Regression: ---
Mount Type: ---
Documentation: ---
CRM:
Verified Versions:
Category: ---
oVirt Team: ---
RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: ---
rkavunga: needinfo? (sraj)


Attachments (Terms of Use)

  None (edit)
Description Saurabh 2015-11-25 04:36:49 EST
Description of problem:
While executing the posix compliance the execution gets stuck for a rename test.


Version-Release number of selected component (if applicable):
glusterfs-3.7.5-7.el7rhgs.x86_64
nfs-ganesha-2.2.0-11.el7rhgs.x86_64

How reproducible:
always

Steps to Reproduce:
1. time prove -r /opt/qa/tools/pjd-fstest-20080816/tests/


Actual results:
ganesha-gfapi.log
[2015-11-25 17:06:20.807343] E [glfs-handleops.c:1789:glfs_h_poll_cache_invalidation] (-->/usr/lib64/ganesha/libfsalgluster.so(GLUSTERFSAL_UP_Thread+0xc3) [0x7f1ee0107ec3] -->/lib64/libgfapi.so.0(glfs_h_poll_upcall+0x190) [0x7f1edfcefb50] -->/lib64/libgfapi.so.0(+0x188bc) [0x7f1edfcef8bc] ) 0-glfs_h_poll_cache_invalidation: invalid argument: object [Invalid argument]
[2015-11-25 17:06:20.807358] W [MSGID: 104047] [glfs-handleops.c:1944:pub_glfs_h_poll_upcall] 0-meta-autoload: handle creation of 00000000-0000-0000-0000-000000000000 failed [Invalid argument]
[2015-11-25 17:06:21.807691] E [dht-helper.c:598:dht_subvol_get_hashed] (-->/lib64/libglusterfs.so.0(default_lookup+0x5b) [0x7f1edfa3674b] -->/usr/lib64/glusterfs/3.7.5/xlator/cluster/distribute.so(dht_lookup+0xa81) [0x7f1ecf371871] -->/usr/lib64/glusterfs/3.7.5/xlator/cluster/distribute.so(dht_subvol_get_hashed+0x1c8) [0x7f1ecf33b7b8] ) 0-vol2-tier-dht: invalid argument: loc->parent [Invalid argument]
[2015-11-25 17:06:21.807825] E [dht-helper.c:598:dht_subvol_get_hashed] (-->/usr/lib64/glusterfs/3.7.5/xlator/cluster/distribute.so(dht_lookup+0xf8c) [0x7f1ecf371d7c] -->/usr/lib64/glusterfs/3.7.5/xlator/cluster/distribute.so(dht_lookup+0xa81) [0x7f1ecf371871] -->/usr/lib64/glusterfs/3.7.5/xlator/cluster/distribute.so(dht_subvol_get_hashed+0x1c8) [0x7f1ecf33b7b8] ) 0-vol2-cold-dht: invalid argument: loc->parent [Invalid argument]
[2015-11-25 17:06:21.808312] E [dht-helper.c:598:dht_subvol_get_hashed] (-->/usr/lib64/glusterfs/3.7.5/xlator/cluster/distribute.so(dht_lookup+0xf8c) [0x7f1ecf371d7c] -->/usr/lib64/glusterfs/3.7.5/xlator/cluster/distribute.so(dht_lookup+0xa81) [0x7f1ecf371871] -->/usr/lib64/glusterfs/3.7.5/xlator/cluster/distribute.so(dht_subvol_get_hashed+0x1c8) [0x7f1ecf33b7b8] ) 0-vol2-hot-dht: invalid argument: loc->parent [Invalid argument]
[2015-11-25 17:06:21.808598] W [MSGID: 114031] [client-rpc-fops.c:2974:client3_3_lookup_cbk] 0-vol2-client-2: remote operation failed. Path: (null) (00000000-0000-0000-0000-000000000000) [Invalid argument]
[2015-11-25 17:06:21.808717] W [MSGID: 114031] [client-rpc-fops.c:2974:client3_3_lookup_cbk] 0-vol2-client-1: remote operation failed. Path: (null) (00000000-0000-0000-0000-000000000000) [Invalid argument]
[2015-11-25 17:06:21.808737] W [MSGID: 114031] [client-rpc-fops.c:2974:client3_3_lookup_cbk] 0-vol2-client-0: remote operation failed. Path: (null) (00000000-0000-0000-0000-000000000000) [Invalid argument]
The message "W [MSGID: 114031] [client-rpc-fops.c:2974:client3_3_lookup_cbk] 0-vol2-client-5: remote operation failed. Path: (null) (00000000-0000-0000-0000-000000000000) [Invalid argument]" repeated 2 times between [2015-11-25 17:06:19.805201] and [2015-11-25 17:06:21.809094]
[2015-11-25 17:06:21.809285] W [MSGID: 114031] [client-rpc-fops.c:2974:client3_3_lookup_cbk] 0-vol2-client-4: remote operation failed. Path: (null) (00000000-0000-0000-0000-000000000000) [Invalid argument]
[2015-11-25 17:06:21.809422] W [MSGID: 104011] [glfs-handleops.c:1291:pub_glfs_h_create_from_handle] 0-meta-autoload: inode refresh of 00000000-0000-0000-0000-000000000000 failed: Invalid argument [Invalid argument]
[2015-11-25 17:06:21.809507] E [glfs-handleops.c:1789:glfs_h_poll_cache_invalidation] (-->/usr/lib64/ganesha/libfsalgluster.so(GLUSTERFSAL_UP_Thread+0xc3) [0x7f1ee0107ec3] -->/lib64/libgfapi.so.0(glfs_h_poll_upcall+0x190) [0x7f1edfcefb50] -->/lib64/libgfapi.so.0(+0x188bc) [0x7f1edfcef8bc] ) 0-glfs_h_poll_cache_invalidation: invalid argument: object [Invalid argument]
[2015-11-25 17:06:21.809578] W [MSGID: 104047] [glfs-handleops.c:1944:pub_glfs_h_poll_upcall] 0-meta-autoload: handle creation of 00000000-0000-0000-0000-000000000000 failed [Invalid argument]


Expected results:
the posix compliance testsuite should finish successfully without getting stuck

Additional info:
Comment 2 Soumya Koduri 2015-11-25 05:54:09 EST
Please provide the pkt trace captured and the logs -ganesha/ganesha-gfapi.log, sosreport.
Comment 3 Soumya Koduri 2015-12-02 05:34:05 EST
I could consistently reproduce this issue.

For some reason, as part tests/rename/10.t , mknod()-> glfs_h_mknod() fails with
EEXIST error. In NFS-Ganesha, on receiving this error, does a lookup of the object for which it receives ENOENT. Since it is in inconsistent state, it keeps retrying the fop resulting in hang on the client side.
Comment 4 Soumya Koduri 2015-12-07 03:09:02 EST
This seem to be an issue with dht-tier. For every file creation, dht-tier seem to be creating linked files on cold tier first and then actual files on hot-tier. If for any reason actual file creation fails, linked files are not deleted from the cold tier (as can be seen below)

# ls -ltr /bricks/xfs_brick/b*/dir_tmp/fstest_3e00dbbaaeb95ee267e1a3b59a821b34/fstest_dc09c43ca69e030460a777fac05f25d7
/bricks/xfs_brick/b2-tier/dir_tmp/fstest_3e00dbbaaeb95ee267e1a3b59a821b34/fstest_dc09c43ca69e030460a777fac05f25d7:
total 0

/bricks/xfs_brick/b1-tier/dir_tmp/fstest_3e00dbbaaeb95ee267e1a3b59a821b34/fstest_dc09c43ca69e030460a777fac05f25d7:
total 0

/bricks/xfs_brick/b2/dir_tmp/fstest_3e00dbbaaeb95ee267e1a3b59a821b34/fstest_dc09c43ca69e030460a777fac05f25d7:
total 0
---------T 2 root root 0 Dec  7 13:18 fstest_cbf533920c1896845883fb493fce0d06

/bricks/xfs_brick/b1/dir_tmp/fstest_3e00dbbaaeb95ee267e1a3b59a821b34/fstest_dc09c43ca69e030460a777fac05f25d7:
total 0
---------T 2 root root 0 Dec  7 13:18 fstest_cbf533920c1896845883fb493fce0d06


This led to the inconsistent behaviour seen by the nfs-ganesha (mentioned in the above comment). 
Exclusive file creation with the same file path shall result in ERR_EXISTS error since linked files are present and LOOKUP shall fail with EINVAL error since the actual files are missing.

]# ls fstest_3e00dbbaaeb95ee267e1a3b59a821b34/fstest_dc09c43ca69e030460a777fac05f25d7/fstest_cbf533920c1896845883fb493fce0d06
ls: cannot access fstest_3e00dbbaaeb95ee267e1a3b59a821b34/fstest_dc09c43ca69e030460a777fac05f25d7/fstest_cbf533920c1896845883fb493fce0d06: No such file or directory

# mkfifo fstest_3e00dbbaaeb95ee267e1a3b59a821b34/fstest_dc09c43ca69e030460a777fac05f25d7/fstest_cbf533920c1896845883fb493fce0d06
mkfifo: cannot create fifo `fstest_3e00dbbaaeb95ee267e1a3b59a821b34/fstest_dc09c43ca69e030460a777fac05f25d7/fstest_cbf533920c1896845883fb493fce0d06': File exists


This seem to be known issue with tiering. Request Rafi/Nithya to mark this bug duplicate (if any present already)
Comment 7 Niels de Vos 2015-12-21 09:29:34 EST
Sounds like the root cause is addressed with bug 1291212?

Jiffin, what do you thinks?
Comment 8 Jiffin 2015-12-22 01:42:31 EST
@Niels

It's not related to BZ1291212
Comment 11 Jiffin 2016-04-26 13:05:02 EDT
I tested the bug in upstream 3.7.9 and didn't hit the issue on nfsv4 mount.

on the server
---------------

gluster v info vol 

Volume Name: vol
Type: Tier
Volume ID: 6bd03c40-4a6e-4beb-847f-29fba87132fb
Status: Started
Number of Bricks: 4
Transport-type: tcp
Hot Tier :
Hot Tier Type : Replicate
Number of Bricks: 1 x 2 = 2
Brick1: 10.70.43.7:/brick1/volhh2
Brick2: 10.70.43.58:/brick1/volhh1
Cold Tier:
Cold Tier Type : Replicate
Number of Bricks: 1 x 2 = 2
Brick3: 10.70.43.58:/brick1/vol
Brick4: 10.70.43.7:/brick1/vol
Options Reconfigured:
performance.readdir-ahead: on
nfs.disable: on
features.cache-invalidation: on
ganesha.enable: on
features.ctr-enabled: on
cluster.tier-mode: cache
nfs-ganesha: enable
cluster.enable-shared-storage: enable

on the client
--------------------------------------
mount

10.70.43.58:/vol on /mnt/nfs/1 type nfs4 (rw,relatime,vers=4.0,rsize=1048576,wsize=1048576,namlen=255,hard,proto=tcp,port=0,timeo=600,retrans=2,sec=sys,clientaddr=10.70.43.92,local_lock=none,addr=10.70.43.58)

I only executed rename test suite in posix compliance test
output of the test

Changing to the specified mountpoint
/mnt/nfs/1/run14744
executing posix_compliance
start: 22:26:22

real	0m17.735s
user	0m1.191s
sys	0m3.230s
/export//opt/qa/tools/posix-testsuite/tests/rename/00.t .. ok
/export//opt/qa/tools/posix-testsuite/tests/rename/01.t .. ok
/export//opt/qa/tools/posix-testsuite/tests/rename/02.t .. ok
/export//opt/qa/tools/posix-testsuite/tests/rename/03.t .. ok
/export//opt/qa/tools/posix-testsuite/tests/rename/04.t .. ok
/export//opt/qa/tools/posix-testsuite/tests/rename/05.t .. ok
/export//opt/qa/tools/posix-testsuite/tests/rename/06.t .. ok
/export//opt/qa/tools/posix-testsuite/tests/rename/07.t .. ok
/export//opt/qa/tools/posix-testsuite/tests/rename/08.t .. ok
/export//opt/qa/tools/posix-testsuite/tests/rename/09.t .. ok
/export//opt/qa/tools/posix-testsuite/tests/rename/10.t .. ok
/export//opt/qa/tools/posix-testsuite/tests/rename/11.t .. ok
/export//opt/qa/tools/posix-testsuite/tests/rename/12.t .. ok
/export//opt/qa/tools/posix-testsuite/tests/rename/13.t .. ok
/export//opt/qa/tools/posix-testsuite/tests/rename/14.t .. ok
/export//opt/qa/tools/posix-testsuite/tests/rename/15.t .. ok
/export//opt/qa/tools/posix-testsuite/tests/rename/16.t .. ok
/export//opt/qa/tools/posix-testsuite/tests/rename/17.t .. ok
/export//opt/qa/tools/posix-testsuite/tests/rename/18.t .. ok
/export//opt/qa/tools/posix-testsuite/tests/rename/19.t .. ok
/export//opt/qa/tools/posix-testsuite/tests/rename/20.t .. ok
All tests successful.
Files=21, Tests=479, 17 wallclock secs ( 0.39 usr  0.05 sys +  1.58 cusr  6.58 csys =  8.60 CPU)
Result: PASS
/export//opt/qa/tools/posix-testsuite/tests/rename/00.t .. ok
/export//opt/qa/tools/posix-testsuite/tests/rename/01.t .. ok
/export//opt/qa/tools/posix-testsuite/tests/rename/02.t .. ok
/export//opt/qa/tools/posix-testsuite/tests/rename/03.t .. ok
/export//opt/qa/tools/posix-testsuite/tests/rename/04.t .. ok
/export//opt/qa/tools/posix-testsuite/tests/rename/05.t .. ok
/export//opt/qa/tools/posix-testsuite/tests/rename/06.t .. ok
/export//opt/qa/tools/posix-testsuite/tests/rename/07.t .. ok
/export//opt/qa/tools/posix-testsuite/tests/rename/08.t .. ok
/export//opt/qa/tools/posix-testsuite/tests/rename/09.t .. ok
/export//opt/qa/tools/posix-testsuite/tests/rename/10.t .. ok
/export//opt/qa/tools/posix-testsuite/tests/rename/11.t .. ok
/export//opt/qa/tools/posix-testsuite/tests/rename/12.t .. ok
/export//opt/qa/tools/posix-testsuite/tests/rename/13.t .. ok
/export//opt/qa/tools/posix-testsuite/tests/rename/14.t .. ok
/export//opt/qa/tools/posix-testsuite/tests/rename/15.t .. ok
/export//opt/qa/tools/posix-testsuite/tests/rename/16.t .. ok
/export//opt/qa/tools/posix-testsuite/tests/rename/17.t .. ok
/export//opt/qa/tools/posix-testsuite/tests/rename/18.t .. ok
/export//opt/qa/tools/posix-testsuite/tests/rename/19.t .. ok
/export//opt/qa/tools/posix-testsuite/tests/rename/20.t .. ok
All tests successful.
Files=21, Tests=479, 17 wallclock secs ( 0.23 usr  0.04 sys +  0.88 cusr  3.17 csys =  4.32 CPU)
Result: PASS
end: 22:26:41
removed posix compliance directories
1
Total 1 tests were successful
Switching over to the previous working directory
Removing /mnt/nfs/1//run14744/
Comment 12 Mohammed Rafi KC 2016-04-28 05:49:27 EDT
This issue was reported long back. After that, quite number of patches went to code base.

Based on comment4 and comment11, the issue could have fixed with patch http://review.gluster.org/#/c/12829/

Shashank,
Can you please try out this in the latest build ?

Note You need to log in before you can comment on or make changes to this bug.