With Ganesha 2.5, one of the customer is facing an issue, where ls returns
nothing (NOENT error). "ls" on specific file from that directory works
well.
After enabling Ganesha traces seems like lookup is failing in mdc_lookup.
See below:
----------------
2018-02-14 01:02:41 : epoch 001900e2 : apocnfs4 :
ganesha.nfsd-18846[work-100] nfs4_Compound :NFS4 :DEBUG :Request 2: opcode
15 is OP_LOOKUP
2018-02-14 01:02:41 : epoch 001900e2 : apocnfs4 :
ganesha.nfsd-18846[work-100] nfs4_Compound :NFS4 :M_DBG :NFS4: MID DEBUG:
Check export perms export = 000001e0 req = 00000080
2018-02-14 01:02:41 : epoch 001900e2 : apocnfs4 :
ganesha.nfsd-18846[work-100] nfs4_Is_Fh_Invalid :FH :F_DBG :NFS4 Handle
(53:0x430000323030000a0002002800c0a804af4eb847a00200000200000000030000000000000000000000010000000300000000000000)
2018-02-14 01:02:41 : epoch 001900e2 : apocnfs4 :
ganesha.nfsd-18846[work-100] nfs4_Is_Fh_Invalid :FH :F_DBG :NFS4 Handle 0x0
export id 50
2018-02-14 01:02:41 : epoch 001900e2 : apocnfs4 :
ganesha.nfsd-18846[work-100] :NFS4 :DEBUG :name=libiconv.a
2018-02-14 01:02:41 : epoch 001900e2 : apocnfs4 :
ganesha.nfsd-18846[work-100] mdcache_getattrs :RW LOCK :F_DBG :Got read
lock on 0x1014150 (&entry->attr_lock) at
/home/ppsbld/tac500.171206.165205/tac500.ganesha-rpmdir/BUILD/nfs-ganesha-2.5.3-ibm011.00-0.1.1-Source/FSAL/Stackable_FSALs/FSAL_MDCACHE/mdcache_handle.c:1214
2018-02-14 01:02:41 : epoch 001900e2 : apocnfs4 :
ganesha.nfsd-18846[work-100] nfs4_acl_entry_inc_ref :RW LOCK :F_DBG :Got
write lock on 0x3fda110 (&acl->lock) at
/home/ppsbld/tac500.171206.165205/tac500.ganesha-rpmdir/BUILD/nfs-ganesha-2.5.3-ibm011.00-0.1.1-Source/support/nfs4_acls.c:89
2018-02-14 01:02:41 : epoch 001900e2 : apocnfs4 :
ganesha.nfsd-18846[work-100] nfs4_acl_entry_inc_ref :NFS4 ACL :DEBUG :(acl,
ref) = (0x3fda100, 3)
2018-02-14 01:02:41 : epoch 001900e2 : apocnfs4 :
ganesha.nfsd-18846[work-100] nfs4_acl_entry_inc_ref :RW LOCK :F_DBG
:Unlocked 0x3fda110 (&acl->lock) at
/home/ppsbld/tac500.171206.165205/tac500.ganesha-rpmdir/BUILD/nfs-ganesha-2.5.3-ibm011.00-0.1.1-Source/support/nfs4_acls.c:92
2018-02-14 01:02:41 : epoch 001900e2 : apocnfs4 :
ganesha.nfsd-18846[work-100] mdcache_getattrs :RW LOCK :F_DBG :Unlocked
0x1014150 (&entry->attr_lock) at
/home/ppsbld/tac500.171206.165205/tac500.ganesha-rpmdir/BUILD/nfs-ganesha-2.5.3-ibm011.00-0.1.1-Source/FSAL/Stackable_FSALs/FSAL_MDCACHE/mdcache_handle.c:1250
2018-02-14 01:02:41 : epoch 001900e2 : apocnfs4 :
ganesha.nfsd-18846[work-100] mdcache_getattrs :INODE :F_DBG :attrs obj
attributes Request Mask=000006a0 Valid Mask=0005dfee Supported
Mask=0195dffe DIRECTORY numlinks=0xf size=0x8000 mode=0775 owner=0x0
group=0x0 atime=2018-02-14 00:45:57 mtime=2018-02-13 23:14:28
2018-02-14 01:02:41 : epoch 001900e2 : apocnfs4 :
ganesha.nfsd-18846[work-100] fsal_check_access_acl :NFS4 ACL :F_DBG :file
acl=0x3fda100, file uid=0, file gid=0,
2018-02-14 01:02:41 : epoch 001900e2 : apocnfs4 :
ganesha.nfsd-18846[work-100] fsal_check_access_acl :NFS4 ACL :F_DBG :user
uid=4294967294, user gid= 4294967294, v4mask=0x000020 EXECUTE
2018-02-14 01:02:41 : epoch 001900e2 : apocnfs4 :
ganesha.nfsd-18846[work-100] fsal_check_access_acl :NFS4 ACL :F_DBG :ace
numnber: 1 ace type 0x0 perm 0x1E01FF flag 0x0 who 1
2018-02-14 01:02:41 : epoch 001900e2 : apocnfs4 :
ganesha.nfsd-18846[work-100] fsal_check_access_acl :NFS4 ACL :F_DBG :allow
or deny
2018-02-14 01:02:41 : epoch 001900e2 : apocnfs4 :
ganesha.nfsd-18846[work-100] fsal_check_ace_matches :NFS4 ACL :F_DBG
:result: 0, cause: , flag: 0x0, who: 1
2018-02-14 01:02:41 : epoch 001900e2 : apocnfs4 :
ganesha.nfsd-18846[work-100] fsal_check_ace_applicable :NFS4 ACL :F_DBG
:Not applicable to given user
2018-02-14 01:02:41 : epoch 001900e2 : apocnfs4 :
ganesha.nfsd-18846[work-100] fsal_check_access_acl :NFS4 ACL :F_DBG :ace
numnber: 2 ace type 0x0 perm 0x1200EF flag 0x0 who 2
2018-02-14 01:02:41 : epoch 001900e2 : apocnfs4 :
ganesha.nfsd-18846[work-100] fsal_check_access_acl :NFS4 ACL :F_DBG :allow
or deny
2018-02-14 01:02:41 : epoch 001900e2 : apocnfs4 :
ganesha.nfsd-18846[work-100] fsal_check_ace_matches :NFS4 ACL :F_DBG
:result: 0, cause: , flag: 0x0, who: 2
2018-02-14 01:02:41 : epoch 001900e2 : apocnfs4 :
ganesha.nfsd-18846[work-100] fsal_check_ace_applicable :NFS4 ACL :F_DBG
:Not applicable to given user
2018-02-14 01:02:41 : epoch 001900e2 : apocnfs4 :
ganesha.nfsd-18846[work-100] fsal_check_access_acl :NFS4 ACL :F_DBG :ace
numnber: 3 ace type 0x0 perm 0x1200A9 flag 0x40 who 1035
2018-02-14 01:02:41 : epoch 001900e2 : apocnfs4 :
ganesha.nfsd-18846[work-100] fsal_check_access_acl :NFS4 ACL :F_DBG :allow
or deny
2018-02-14 01:02:41 : epoch 001900e2 : apocnfs4 :
ganesha.nfsd-18846[work-100] fsal_check_ace_matches :NFS4 ACL :F_DBG
:result: 0, cause: , flag: 0x40, who: 1035
2018-02-14 01:02:41 : epoch 001900e2 : apocnfs4 :
ganesha.nfsd-18846[work-100] fsal_check_ace_applicable :NFS4 ACL :F_DBG
:Not applicable to given user
2018-02-14 01:02:41 : epoch 001900e2 : apocnfs4 :
ganesha.nfsd-18846[work-100] fsal_check_access_acl :NFS4 ACL :F_DBG :ace
numnber: 4 ace type 0x0 perm 0x1200A9 flag 0x0 who 3
2018-02-14 01:02:41 : epoch 001900e2 : apocnfs4 :
ganesha.nfsd-18846[work-100] fsal_check_access_acl :NFS4 ACL :F_DBG :allow
or deny
2018-02-14 01:02:41 : epoch 001900e2 : apocnfs4 :
ganesha.nfsd-18846[work-100] fsal_check_ace_matches :NFS4 ACL :F_DBG
:result: 1, cause: special everyone, flag: 0x0, who: 3
2018-02-14 01:02:41 : epoch 001900e2 : apocnfs4 :
ganesha.nfsd-18846[work-100] fsal_check_ace_applicable :NFS4 ACL :F_DBG
:Applicable, flag=0X0
2018-02-14 01:02:41 : epoch 001900e2 : apocnfs4 :
ganesha.nfsd-18846[work-100] fsal_check_access_acl :NFS4 ACL :F_DBG :allow
perm 0x1200A9 remainingPerms 0x20
2018-02-14 01:02:41 : epoch 001900e2 : apocnfs4 :
ganesha.nfsd-18846[work-100] fsal_print_access_by_acl :NFS4 ACL :F_DBG
:access granted uid 4294967294 gid 4294967294 Access req:0x000020 EXECUTE
2018-02-14 01:02:41 : epoch 001900e2 : apocnfs4 :
ganesha.nfsd-18846[work-100] fsal_check_access_acl :NFS4 ACL :F_DBG :access
granted
2018-02-14 01:02:41 : epoch 001900e2 : apocnfs4 :
ganesha.nfsd-18846[work-100] nfs4_acl_release_entry :RW LOCK :F_DBG :Got
write lock on 0x3fda110 (&acl->lock) at
/home/ppsbld/tac500.171206.165205/tac500.ganesha-rpmdir/BUILD/nfs-ganesha-2.5.3-ibm011.00-0.1.1-Source/support/nfs4_acls.c:190
2018-02-14 01:02:41 : epoch 001900e2 : apocnfs4 :
ganesha.nfsd-18846[work-100] nfs4_acl_entry_dec_ref :NFS4 ACL :DEBUG :(acl,
ref) = (0x3fda100, 2)
2018-02-14 01:02:41 : epoch 001900e2 : apocnfs4 :
ganesha.nfsd-18846[work-100] nfs4_acl_release_entry :RW LOCK :F_DBG
:Unlocked 0x3fda110 (&acl->lock) at
/home/ppsbld/tac500.171206.165205/tac500.ganesha-rpmdir/BUILD/nfs-ganesha-2.5.3-ibm011.00-0.1.1-Source/support/nfs4_acls.c:193
2018-02-14 01:02:41 : epoch 001900e2 : apocnfs4 :
ganesha.nfsd-18846[work-100] mdc_lookup :INODE :F_DBG :Lookup libiconv.a
2018-02-14 01:02:41 : epoch 001900e2 : apocnfs4 :
ganesha.nfsd-18846[work-100] mdc_lookup :RW LOCK :F_DBG :Got read lock on
0x1014588 (&mdc_parent->content_lock) at
/home/ppsbld/tac500.171206.165205/tac500.ganesha-rpmdir/BUILD/nfs-ganesha-2.5.3-ibm011.00-0.1.1-Source/FSAL/Stackable_FSALs/FSAL_MDCACHE/mdcache_helpers.c:1202
2018-02-14 01:02:41 : epoch 001900e2 : apocnfs4 :
ganesha.nfsd-18846[work-100] mdc_try_get_cached :INODE :F_DBG :Look in
cache libiconv.a, trust content yes
2018-02-14 01:02:41 : epoch 001900e2 : apocnfs4 :
ganesha.nfsd-18846[work-100] mdcache_avl_qp_lookup_s :INODE :F_DBG :Lookup
libiconv.a
2018-02-14 01:02:41 : epoch 001900e2 : apocnfs4 :
ganesha.nfsd-18846[work-100] mdcache_avl_qp_lookup_s :INODE :F_DBG :entry
not found at j=1 (libiconv.a)
2018-02-14 01:02:41 : epoch 001900e2 : apocnfs4 :
ganesha.nfsd-18846[work-100] mdc_try_get_cached :INODE :F_DBG
:mdcache_avl_qp_lookup_s libiconv.a failed trust negative no
2018-02-14 01:02:41 : epoch 001900e2 : apocnfs4 :
ganesha.nfsd-18846[work-100] mdc_lookup :RW LOCK :F_DBG :Unlocked 0x1014588
(&mdc_parent->content_lock) at
/home/ppsbld/tac500.171206.165205/tac500.ganesha-rpmdir/BUILD/nfs-ganesha-2.5.3-ibm011.00-0.1.1-Source/FSAL/Stackable_FSALs/FSAL_MDCACHE/mdcache_helpers.c:1254
2018-02-14 01:02:41 : epoch 001900e2 : apocnfs4 :
ganesha.nfsd-18846[work-100] mdc_lookup :INODE :F_DBG :Try again libiconv.a
2018-02-14 01:02:41 : epoch 001900e2 : apocnfs4 :
ganesha.nfsd-18846[work-100] mdc_lookup :RW LOCK :F_DBG :Got write lock on
0x1014588 (&mdc_parent->content_lock) at
/home/ppsbld/tac500.171206.165205/tac500.ganesha-rpmdir/BUILD/nfs-ganesha-2.5.3-ibm011.00-0.1.1-Source/FSAL/Stackable_FSALs/FSAL_MDCACHE/mdcache_helpers.c:1258
2018-02-14 01:02:41 : epoch 001900e2 : apocnfs4 :
ganesha.nfsd-18846[work-100] mdc_try_get_cached :INODE :F_DBG :Look in
cache libiconv.a, trust content yes
2018-02-14 01:02:41 : epoch 001900e2 : apocnfs4 :
ganesha.nfsd-18846[work-100] mdcache_avl_qp_lookup_s :INODE :F_DBG :Lookup
libiconv.a
2018-02-14 01:02:41 : epoch 001900e2 : apocnfs4 :
ganesha.nfsd-18846[work-100] mdcache_avl_qp_lookup_s :INODE :F_DBG :entry
not found at j=1 (libiconv.a)
2018-02-14 01:02:41 : epoch 001900e2 : apocnfs4 :
ganesha.nfsd-18846[work-100] mdc_try_get_cached :INODE :F_DBG
:mdcache_avl_qp_lookup_s libiconv.a failed trust negative no
2018-02-14 01:02:41 : epoch 001900e2 : apocnfs4 :
ganesha.nfsd-18846[work-100] mdc_lookup :INODE :DEBUG :Cache Miss detected
for libiconv.a
2018-02-14 01:02:41 : epoch 001900e2 : apocnfs4 :
ganesha.nfsd-18846[work-100] fsal_internal_get_handle_at :FSAL :F_DBG
:Lookup handle at 55 for libiconv.a
2018-02-14 01:02:41 : epoch 001900e2 : apocnfs4 :
ganesha.nfsd-18846[work-100] fsal_internal_get_handle_at :FSAL :F_DBG
:OPENHANDLE_NAME_TO_HANDLE returned errno=2
2018-02-14 01:02:41 : epoch 001900e2 : apocnfs4 :
ganesha.nfsd-18846[work-100] mdc_lookup_uncached :INODE :DEBUG :lookup
libiconv.a failed with No such file or directory
2018-02-14 01:02:41 : epoch 001900e2 : apocnfs4 :
ganesha.nfsd-18846[work-100] mdc_lookup :RW LOCK :F_DBG :Unlocked 0x1014588
(&mdc_parent->content_lock) at
/home/ppsbld/tac500.171206.165205/tac500.ganesha-rpmdir/BUILD/nfs-ganesha-2.5.3-ibm011.00-0.1.1-Source/FSAL/Stackable_FSALs/FSAL_MDCACHE/mdcache_helpers.c:1309
2018-02-14 01:02:41 : epoch 001900e2 : apocnfs4 :
ganesha.nfsd-18846[work-100] LogCompoundFH :FH :F_DBG :Current FH File
Handle V4: Len=53
430000323030000a0002002800c0a804af4eb847a00200000200000000030000000000000000000000010000000300000000000000
2018-02-14 01:02:41 : epoch 001900e2 : apocnfs4 :
ganesha.nfsd-18846[work-100] LogCompoundFH :FH :F_DBG :Saved FH File
Handle V4: Len=0 <null>
2018-02-14 01:02:41 : epoch 001900e2 : apocnfs4 :
ganesha.nfsd-18846[work-100] nfs4_Compound :NFS4 :DEBUG :Status of
OP_LOOKUP in position 2 = NFS4ERR_NOENT
2018-02-14 01:02:41 : epoch 001900e2 : apocnfs4 :
ganesha.nfsd-18846[work-100] nfs4_Compound :NFS4 :DEBUG :End status =
NFS4ERR_NOENT lastindex = 2
----------------
What I think is in mdc_lookup, subcall to FSAL needs to be made if there is
nothing in the cache. For the same I have posted patch
https://review.gerrithub.io/#/c/400037/
Let me know, how to fix this issue?
--
with regards,
Sachin Punadikar
------------------------------------------------------------------------------
Check out the vibrant tech community on one of the world's most
engaging tech sites, Slashdot.org! http://sdm.link/slashdot
_______________________________________________
Nfs-ganesha-devel mailing list
Nfs-ganesha-devel@lists.sourceforge.net
https://lists.sourceforge.net/lists/listinfo/nfs-ganesha-devel
