Maybe. We'll have to validate that there's no dependency on that link while it's ref'd. We may end up having to abort invalidating a directory while it has ref'd chunks, instead. Daniel On 7/10/19 6:02 PM, Frank Filz wrote:

Ah, good point.

mdcache_clean_dirent_chunks maybe needs to remove the chunks from the directory so that subsequent calls won’t unref the chunk again. It does a glist_for_each_safe assuming the chunks will be removed but you’re right, if other threads hold references to chunks, those chunks won’t actually be removed.

If we simply removed the chunk from the list, mdcache_clean_dirent_chunks would not try and unref it again, and the final unref from whichever thread was last in accessing the chunk would clean the chunk but the chunk would have already been removed from the directory list of chunks.

Frank

*From:* Rungta, Vandana [mailto:vrungta@amazon.com] *Sent:* Wednesday, July 10, 2019 2:34 PM *To:* devel@lists.nfs-ganesha.org; dang@redhat.com *Subject:* [NFS-Ganesha-Devel] Extra mdcache_lru_unref_chunk path

Thread 1 is holding a ref on the chunk and releases the content lock

Thread 2 gets the write lock and calls dirents_invalidate_all  and unrefs the chunk, will not clean the chunk so it is still hooked to the directory

Thread 3  gets the write lock and calls dirents_invalidate_all  and unrefs the chunk – this is removing the ref held by Thread 1 and will clean the chunk

Thread 1 gets the write lock and tries to unref the chunk àbut chunk is already deleted by Thread 3

Thanks,

Vandana

2.7.4 with patches.

Patches applied:

https://github.com/nfs-ganesha/nfs-ganesha/commit/c7e7d24877085dbb0424542d9d...

https://github.com/nfs-ganesha/nfs-ganesha/commit/136df4f262c3f9bc29df456eac...

https://github.com/nfs-ganesha/nfs-ganesha/commit/c98ad1e238f5db9db5ab8db8ce...

https://github.com/nfs-ganesha/nfs-ganesha/commit/f0d5b8d4f6dcce4597459c3eba...

https://github.com/nfs-ganesha/nfs-ganesha/commit/e11cd5b9f8d6ffbb46061e7cd2...

https://github.com/nfs-ganesha/nfs-ganesha/commit/5439f63b8a1e00f6ff56a4def5...

https://github.com/nfs-ganesha/nfs-ganesha/commit/e306c01685b74970ada2259f2b...

Relevant debug log messages:

svc_48 is the thread that cored

directory = 0xd873770

dirent = 0x3a6ff9c0

--> chunk with too many unrefs -> chunk = 0xd690fb0

Starting a readdir

Wed Jul 10 09:28:30 2019 UTC 23198[::ffff:10.0.138.85] [svc_48] /src/src/FSAL/Stackable_FSALs/FSAL_MDCACHE/mdcache_helpers.c:2860 :mdcache_readdir_chunked :NFS READDIR :F_DBG :NFS READDIR: FULLDEBUG: Starting chunked READDIR for 0xd873770, MDCACHE_TRUST_CONTENT true, MDCACHE_TRUST_DIR_CHUNKS true

Wed Jul 10 09:28:30 2019 UTC 23198[::ffff:10.0.138.85] [svc_48] /src/src/FSAL/Stackable_FSALs/FSAL_MDCACHE/mdcache_helpers.c:2895 :mdcache_readdir_chunked :NFS READDIR :F_DBG :NFS READDIR: FULLDEBUG: Readdir chunked next_ck=0x0 look_ck=2298289

Wed Jul 10 09:28:30 2019 UTC 23198[::ffff:10.0.138.85] [svc_48] /src/src/FSAL/Stackable_FSALs/FSAL_MDCACHE/mdcache_helpers.c:3061 :mdcache_readdir_chunked :NFS READDIR :F_DBG :NFS READDIR: FULLDEBUG: found dirent in cached chunk 0xd690fb0 dirent 0x9294be0 random.0

Wed Jul 10 09:28:30 2019 UTC 23198[::ffff:10.0.138.85] [svc_48] /src/src/FSAL/Stackable_FSALs/FSAL_MDCACHE/mdcache_helpers.c:3069 :mdcache_readdir_chunked :NFS READDIR :F_DBG :NFS READDIR: FULLDEBUG: About to read directory=0xd873770 cookie=0

Wed Jul 10 09:28:30 2019 UTC 23198[::ffff:10.0.138.85] [svc_48] /src/src/FSAL/Stackable_FSALs/FSAL_MDCACHE/mdcache_helpers.c:980 :mdcache_find_keyed_reason :INODE :F_DBG :Looking for hk=a5e560b83f87bdf1 fsal=0x7f24e080b080 key=0x86822902000000000100

Wed Jul 10 09:28:30 2019 UTC 23198[::ffff:10.0.138.85] [svc_48] /src/src/FSAL/Stackable_FSALs/FSAL_MDCACHE/mdcache_helpers.c:1018 :mdcache_find_keyed_reason :INODE :F_DBG :Found entry 0xd5651a0

Wed Jul 10 09:28:30 2019 UTC 23198[::ffff:10.0.138.85] [svc_48] /src/src/FSAL/Stackable_FSALs/FSAL_MDCACHE/mdcache_helpers.c:3235 :mdcache_readdir_chunked :NFS READDIR :F_DBG :NFS READDIR: FULLDEBUG: Setting next_ck=2298289

Wed Jul 10 09:28:30 2019 UTC 23198[::ffff:10.0.138.85] [svc_48] /src/src/FSAL/Stackable_FSALs/FSAL_MDCACHE/mdcache_handle.c:931 :mdcache_getattrs :INODE :F_DBG :attrs  obj attributes Valid Mask=0015dfce Supported Mask=0015dfee REGULAR_FILE numlinks=0x1 size=0xa19c08 mode=0755 owner=0xfffffffe group=0xfffffffe atime=Tue Aug 06 07:06:40 49523574 UTC mtime=Wed Jul 10 04:44:09 2019 UTC

Wed Jul 10 09:28:30 2019 UTC 23198[::ffff:10.0.138.85] [svc_48] /src/src/FSAL/Stackable_FSALs/FSAL_MDCACHE/mdcache_helpers.c:3275 :mdcache_readdir_chunked :NFS READDIR :F_DBG :NFS READDIR: FULLDEBUG: dirent = 0x9294be0 random.0, cb_result = DIR_CONTINUE, eod = false

Wed Jul 10 09:28:30 2019 UTC 23198[::ffff:10.0.138.85] [svc_48] /src/src/FSAL/Stackable_FSALs/FSAL_MDCACHE/mdcache_helpers.c:980 :mdcache_find_keyed_reason :INODE :F_DBG :Looking for hk=7e081c83c9ef0267 fsal=0x7f24e080b080 key=0x89822902000000000100

->mdcache_find_keyed_reason repeated pattern ......

Wed Jul 10 09:28:30 2019 UTC 23198[::ffff:10.0.138.85] [svc_48] /src/src/FSAL/Stackable_FSALs/FSAL_MDCACHE/mdcache_helpers.c:980 :mdcache_find_keyed_reason :INODE :F_DBG :Looking for hk=73c0008e99ecba6 fsal=0x7f24e080b080 key=0xd3822902000000000100

Wed Jul 10 09:28:30 2019 UTC 23198[::ffff:10.0.138.85] [svc_48] /src/src/FSAL/Stackable_FSALs/FSAL_MDCACHE/mdcache_helpers.c:1018 :mdcache_find_keyed_reason :INODE :F_DBG :Found entry 0xdb00050

Wed Jul 10 09:28:30 2019 UTC 23198[::ffff:10.0.138.85] [svc_48] /src/src/FSAL/Stackable_FSALs/FSAL_MDCACHE/mdcache_helpers.c:3235 :mdcache_readdir_chunked :NFS READDIR :F_DBG :NFS READDIR: FULLDEBUG: Setting next_ck=22982d6

Wed Jul 10 09:28:30 2019 UTC 23198[::ffff:10.0.138.85] [svc_48] /src/src/FSAL/Stackable_FSALs/FSAL_MDCACHE/mdcache_handle.c:931 :mdcache_getattrs :INODE :F_DBG :attrs  obj attributes Valid Mask=0015dfce Supported Mask=0015dfee REGULAR_FILE numlinks=0x1 size=0xa19c08 mode=0755 owner=0xfffffffe group=0xfffffffe atime=Sun Dec 15 00:03:20 49523574 UTC mtime=Sun Dec 15 00:03:20 49523574 UTC

Wed Jul 10 09:28:30 2019 UTC 23198[::ffff:10.0.138.85] [svc_48] /src/src/FSAL/Stackable_FSALs/FSAL_MDCACHE/mdcache_helpers.c:3275 :mdcache_readdir_chunked :NFS READDIR :F_DBG :NFS READDIR: FULLDEBUG: dirent = 0x3acbce10 random.79, cb_result = DIR_CONTINUE, eod = false

Wed Jul 10 09:28:30 2019 UTC 23198[::ffff:10.0.138.85] [svc_48] /src/src/FSAL/Stackable_FSALs/FSAL_MDCACHE/mdcache_helpers.c:980 :mdcache_find_keyed_reason :INODE :F_DBG :Looking for hk=c2b7f772bdd8c5c4 fsal=0x7f24e080b080 key=0xd4822902000000000100

Wed Jul 10 09:28:30 2019 UTC 23198[::ffff:10.0.138.85] [svc_48] /src/src/FSAL/Stackable_FSALs/FSAL_MDCACHE/mdcache_helpers.c:3108 :mdcache_readdir_chunked :NFS READDIR :F_DBG :NFS READDIR: FULLDEBUG: Lookup by key for random.8 failed, lookup by name now

-> releasing the content lock here, and waiting for a write lock.

svc_61 --> open2 path and gets the write lock

It goes through a invalidate directory here.

Invalidate directory -> unref's all the chunks in the directory

Wed Jul 10 09:28:30 2019 UTC 23198[::ffff:10.0.138.85] [svc_61] /opt/src/src/handle.c:471 :foo_handle_to_key :FSAL :DEBUG :Providing digest to ganesha for hashing. id=36274900, export_id=1

Wed Jul 10 09:28:30 2019 UTC 23198[::ffff:10.0.138.85] [svc_61] /src/src/FSAL/Stackable_FSALs/FSAL_MDCACHE/mdcache_helpers.c:980 :mdcache_find_keyed_reason :INODE :F_DBG :Looking for hk=c2b7f772bdd8c5c4 fsal=0x7f24e080b080 key=0xd4822902000000000100

Wed Jul 10 09:28:30 2019 UTC 23198[::ffff:10.0.138.85] [svc_61] /src/src/FSAL/Stackable_FSALs/FSAL_MDCACHE/mdcache_lru.c:559 :mdcache_lru_clean :INODE :F_DBG :Trusting op_ctx export id 1

Wed Jul 10 09:28:30 2019 UTC 23198[::ffff:10.0.138.85] [svc_61] /opt/src/src/handle.c:44 :foo_close2 :FSAL :DEBUG :Handle: 2442805 state: (nil)

Wed Jul 10 09:28:30 2019 UTC 23198[::ffff:10.0.138.85] [svc_61] /opt/src/src/handle.c:107 :foo_release :FSAL :DEBUG :fileId=2442805

Wed Jul 10 09:28:30 2019 UTC 23198[::ffff:10.0.138.85] [svc_61] /opt/src/src/handle.c:44 :foo_close2 :FSAL :DEBUG :Handle: 2442805 state: (nil)

Wed Jul 10 09:28:30 2019 UTC 23198[::ffff:10.0.138.85] [svc_61] /opt/src/src/handle.c:114 :foo_release :FSAL :DEBUG :Could not close hdl 0x0x4064e880, error Success(0)

Wed Jul 10 09:28:30 2019 UTC 23198[::ffff:10.0.138.85] [svc_61] /src/src/FSAL/Stackable_FSALs/FSAL_MDCACHE/mdcache_helpers.c:750 :mdcache_new_entry :INODE :DEBUG :Adding a REGULAR_FILE, entry=0xd86a830

Wed Jul 10 09:28:30 2019 UTC 23198[::ffff:10.0.138.85] [svc_61] /src/src/FSAL/Stackable_FSALs/FSAL_MDCACHE/mdcache_helpers.c:845 :mdcache_new_entry :INODE :F_DBG :New entry 0xd86a830 added with fh_hk.key hk=c2b7f772bdd8c5c4 fsal=0x7f24e080b080 key=0xd4822902000000000100

Wed Jul 10 09:28:30 2019 UTC 23198[::ffff:10.0.138.85] [svc_61] /src/src/FSAL/Stackable_FSALs/FSAL_MDCACHE/mdcache_handle.c:112 :mdcache_alloc_and_check_handle :INODE :F_DBG :open2 Created entry 0xd86a830 FSAL FOO for random.8

Wed Jul 10 09:28:30 2019 UTC 23198[::ffff:10.0.138.85] [svc_61] /src/src/FSAL/Stackable_FSALs/FSAL_MDCACHE/mdcache_helpers.c:1522 :mdcache_dirent_add :INODE :F_DBG :Add dir entry random.8

Wed Jul 10 09:28:30 2019 UTC 23198[::ffff:10.0.138.85] [svc_61] /src/src/FSAL/Stackable_FSALs/FSAL_MDCACHE/mdcache_avl.c:322 :mdcache_avl_insert :NFS READDIR :F_DBG :NFS READDIR: FULLDEBUG: Insert dir entry 0x364afd80 random.8

Wed Jul 10 09:28:30 2019 UTC 23198[::ffff:10.0.138.85] [svc_61] /src/src/FSAL/Stackable_FSALs/FSAL_MDCACHE/mdcache_avl.c:380 :mdcache_avl_insert :NFS READDIR :DEBUG :NFS READDIR: DEBUG: Already existent when inserting new dirent on entry=0xd873770 name=random.8

Wed Jul 10 09:28:30 2019 UTC 23198[::ffff:10.0.138.85] [svc_61] /src/src/FSAL/Stackable_FSALs/FSAL_MDCACHE/mdcache_avl.c:490 :mdcache_avl_insert :NFS READDIR :F_DBG :NFS READDIR: FULLDEBUG: Duplicate insert of random.8 v->chunk=(nil) v2->chunk=0xd690fb0

Wed Jul 10 09:28:30 2019 UTC 23198[::ffff:10.0.138.85] [svc_61] /src/src/FSAL/Stackable_FSALs/FSAL_MDCACHE/mdcache_handle.c:150 :mdcache_alloc_and_check_handle :INODE :F_DBG :open2  obj attributes Request Mask=0001dfce Valid Mask=0015dfce Supported Mask=0015dfee REGULAR_FILE numlinks=0x1 size=0x0 mode=0755 owner=0xfffffffe group=0xfffffffe atime=Thu Jan 01 00:00:00 1970 UTC mtime=Wed Jul 10 09:28:30 2019 UTC

Wed Jul 10 09:28:30 2019 UTC 23198[::ffff:10.0.138.85] [svc_61] /src/src/FSAL/fsal_helper.c:418 :open2_by_name :FSAL :F_DBG :Created entry 0xd86a868 FSAL MDCACHE for random.8

Wed Jul 10 09:28:30 2019 UTC 23198[::ffff:10.0.138.85] [svc_61] /opt/src/src/handle.c:441 :foo_handle_to_wire :FSAL :DEBUG :Providing digest to ganesha for nfs file handle. fileId=36274900, export_id=1

Wed Jul 10 09:28:30 2019 UTC 23198[::ffff:10.0.138.85] [svc_61] /opt/src/src/export.c:306 :foo_fs_supported_attrs :FSAL :DEBUG :supported attr mask=15DFEE

Wed Jul 10 09:28:30 2019 UTC 23198[::ffff:10.0.138.85] [svc_61] /opt/src/src/handle.c:776 :foo_getattrs :FSAL :DEBUG :fileId=36274821

Wed Jul 10 09:28:30 2019 UTC 23198[::ffff:10.0.138.85] [svc_61] /opt/src/src/handle.c:315 :foo_populate_attrs :FSAL :DEBUG :fileId=36274821, type=1, size=0, mode=755, owner=4294967294, group=4294967294, ctime=1205435200, atime=1205435200, mtime=1205435200

Wed Jul 10 09:28:30 2019 UTC 23198[::ffff:10.0.138.85] [svc_61] /src/src/FSAL/Stackable_FSALs/FSAL_MDCACHE/mdcache_handle.c:857 :mdcache_refresh_attrs :INODE :F_DBG :attrs  obj attributes Request Mask=0015dfce Valid Mask=0015dfce Supported Mask=0015dfee DIRECTORY numlinks=0x1 size=0x0 mode=0755 owner=0xfffffffe group=0xfffffffe atime=Wed Dec 11 09:23:20 49523574 UTC mtime=Wed Dec 11 09:23:20 49523574 UTC

Wed Jul 10 09:28:30 2019 UTC 23198[::ffff:10.0.138.85] [svc_61] /src/src/FSAL/Stackable_FSALs/FSAL_MDCACHE/mdcache_helpers.c:598 :mdcache_dirent_invalidate_all :NFS READDIR :F_DBG :NFS READDIR: FULLDEBUG: Invalidating directory for 0xd873770, clearing MDCACHE_DIR_POPULATED setting MDCACHE_TRUST_CONTENT and MDCACHE_TRUST_DIR_CHUNKS

Invalidating the dirents in the directory

Unrefs the chunk (does not clean_chunk because svc_48 has the ref )

avl_clean_trees cleans the dirents

Wed Jul 10 09:28:30 2019 UTC 23198[::ffff:10.0.138.85] [svc_61] /src/src/FSAL/Stackable_FSALs/FSAL_MDCACHE/mdcache_avl.c:612 :mdcache_avl_clean_trees :NFS READDIR :F_DBG :NFS READDIR: FULLDEBUG: Invalidate 0x399be410 random.23

Wed Jul 10 09:28:30 2019 UTC 23198[::ffff:10.0.138.85] [svc_61] /src/src/FSAL/Stackable_FSALs/FSAL_MDCACHE/mdcache_avl.c:171 :unchunk_dirent :NFS READDIR :F_DBG :NFS READDIR: FULLDEBUG: Unchunking 0x399be410 random.23

Wed Jul 10 09:28:30 2019 UTC 23198[::ffff:10.0.138.85] [svc_61] /src/src/FSAL/Stackable_FSALs/FSAL_MDCACHE/mdcache_avl.c:244 :mdcache_avl_remove :NFS READDIR :F_DBG :NFS READDIR: FULLDEBUG: Just freed dirent 0x399be410 from chunk 0xd690fb0 parent 0xd873770

-- Repeated pattern

Wed Jul 10 09:28:30 2019 UTC 23198[::ffff:10.0.138.85] [svc_61] /src/src/FSAL/Stackable_FSALs/FSAL_MDCACHE/mdcache_avl.c:612 :mdcache_avl_clean_trees :NFS READDIR :F_DBG :NFS READDIR: FULLDEBUG: Invalidate 0x39f54ba0 random.28

Wed Jul 10 09:28:30 2019 UTC 23198[::ffff:10.0.138.85] [svc_61] /src/src/FSAL/Stackable_FSALs/FSAL_MDCACHE/mdcache_avl.c:171 :unchunk_dirent :NFS READDIR :F_DBG :NFS READDIR: FULLDEBUG: Unchunking 0x39f54ba0 random.28

Wed Jul 10 09:28:30 2019 UTC 23198[::ffff:10.0.138.85] [svc_61] /src/src/FSAL/Stackable_FSALs/FSAL_MDCACHE/mdcache_avl.c:244 :mdcache_avl_remove :NFS READDIR :F_DBG :NFS READDIR: FULLDEBUG: Just freed dirent 0x39f54ba0 from chunk 0xd690fb0 parent 0xd873770

Wed Jul 10 09:28:30 2019 UTC 23198[::ffff:10.0.138.85] [svc_61] /src/src/FSAL/Stackable_FSALs/FSAL_MDCACHE/mdcache_avl.c:612 :mdcache_avl_clean_trees :NFS READDIR :F_DBG :NFS READDIR: FULLDEBUG: Invalidate 0x12fda5c0 random.2

Wed Jul 10 09:28:30 2019 UTC 23198[::ffff:10.0.138.85] [svc_61] /src/src/FSAL/Stackable_FSALs/FSAL_MDCACHE/mdcache_avl.c:171 :unchunk_dirent :NFS READDIR :F_DBG :NFS READDIR: FULLDEBUG: Unchunking 0x12fda5c0 random.2

Wed Jul 10 09:28:30 2019 UTC 23198[::ffff:10.0.138.85] [svc_61] /src/src/FSAL/Stackable_FSALs/FSAL_MDCACHE/mdcache_avl.c:244 :mdcache_avl_remove :NFS READDIR :F_DBG :NFS READDIR: FULLDEBUG: Just freed dirent 0x12fda5c0 from chunk 0xd690fb0 parent 0xd873770

svc_61 will release the lock here

svc_38 starts a READDIR on this directory and gets the write content lock and

calls dirent_invalidate_all

Wed Jul 10 09:28:30 2019 UTC 23198[none] [svc_38] /src/src/MainNFSD/nfs_rpc_dispatcher_thread.c:1332 :nfs_rpc_decode_request :DISP :DEBUG :0x35232ed0 fd 31 context 0x6bbf5b80

Wed Jul 10 09:28:30 2019 UTC 23198[none] [svc_38] /src/src/MainNFSD/nfs_worker_thread.c:713 :nfs_rpc_process_request :DISP :F_DBG :About to authenticate Prog=100003, vers=3, proc=16, xid=154636653, SVCXPRT=0x35232ed0, fd=31

Wed Jul 10 09:28:30 2019 UTC 23198[none] [svc_38] /src/src/MainNFSD/nfs_worker_thread.c:751 :nfs_rpc_process_request :DISP :F_DBG :Before SVCAUTH_CHECKSUM on SVCXPRT 0x35232ed0 fd 31

Wed Jul 10 09:28:30 2019 UTC 23198[::ffff:10.0.138.85] [svc_38] /src/src/MainNFSD/nfs_worker_thread.c:839 :nfs_rpc_process_request :DISP :DEBUG :Request from ::ffff:10.0.138.85 for Program 100003, Version 3, Function 16 has xid=154636653

Wed Jul 10 09:28:30 2019 UTC 23198[::ffff:10.0.138.85] [svc_38] /src/src/MainNFSD/nfs_worker_thread.c:856 :nfs_rpc_process_request :DISP :F_DBG :Current request is not duplicate or not cacheable.

Wed Jul 10 09:28:30 2019 UTC 23198[::ffff:10.0.138.85] [svc_38] /src/src/MainNFSD/nfs_worker_thread.c:985 :nfs_rpc_process_request :DISP :M_DBG :DISP: MID DEBUG: Found export entry for path=/integtest-fileshare-bucket-vrungta-bf88s as exportid=1

Wed Jul 10 09:28:30 2019 UTC 23198[::ffff:10.0.138.85] [svc_38] /src/src/MainNFSD/nfs_worker_thread.c:1097 :nfs_rpc_process_request :DISP :M_DBG :DISP: MID DEBUG: nfs_rpc_process_request about to call nfs_export_check_access for client ::ffff:10.0.138.85

Wed Jul 10 09:28:30 2019 UTC 23198[::ffff:10.0.138.85] [svc_38] /src/src/support/nfs_creds.c:504 :nfs_req_creds :DISP :M_DBG :DISP: MID DEBUG: AUTH_SYS creds mapped to uid=4294967294, gid=4294967294, glen=0

Wed Jul 10 09:28:30 2019 UTC 23198[::ffff:10.0.138.85] [svc_38] /src/src/Protocols/NFS/nfs3_readdir.c:144 :nfs3_readdir :NFS READDIR :DEBUG :NFS READDIR: DEBUG: REQUEST PROCESSING: Calling nfs_Readdir handle: File Handle V3: Len=16 430000010a8582290200000000010000

Wed Jul 10 09:28:30 2019 UTC 23198[::ffff:10.0.138.85] [svc_38] /opt/src/src/export.c:83 :foo_wire_to_host :FSAL :DEBUG :Setting length of digest for ganesha file handle. fh_desc length=10

Wed Jul 10 09:28:30 2019 UTC 23198[::ffff:10.0.138.85] [svc_38] /src/src/FSAL/Stackable_FSALs/FSAL_MDCACHE/mdcache_helpers.c:980 :mdcache_find_keyed_reason :INODE :F_DBG :Looking for hk=1a3aad454037de63 fsal=0x7f24e080b080 key=0x85822902000000000100

Wed Jul 10 09:28:30 2019 UTC 23198[::ffff:10.0.138.85] [svc_38] /src/src/FSAL/Stackable_FSALs/FSAL_MDCACHE/mdcache_helpers.c:1018 :mdcache_find_keyed_reason :INODE :F_DBG :Found entry 0xd873770

Wed Jul 10 09:28:30 2019 UTC 23198[::ffff:10.0.138.85] [svc_38] /src/src/Protocols/NFS/nfs3_readdir.c:183 :nfs3_readdir :NFS READDIR :DEBUG :---> NFS3_READDIR: count=16384  cookie=0 estimated_num_entries=120

Wed Jul 10 09:28:30 2019 UTC 23198[::ffff:10.0.138.85] [svc_38] /src/src/FSAL/Stackable_FSALs/FSAL_MDCACHE/mdcache_helpers.c:1228 :mdc_lookup :NFS READDIR :F_DBG :NFS READDIR: FULLDEBUG: Lookup ..

Wed Jul 10 09:28:30 2019 UTC 23198[::ffff:10.0.138.85] [svc_38] /src/src/FSAL/Stackable_FSALs/FSAL_MDCACHE/mdcache_helpers.c:1236 :mdc_lookup :NFS READDIR :F_DBG :NFS READDIR: FULLDEBUG: Lookup parent (..) of 0xd873770

Wed Jul 10 09:28:30 2019 UTC 23198[::ffff:10.0.138.85] [svc_38] /src/src/FSAL/Stackable_FSALs/FSAL_MDCACHE/mdcache_helpers.c:980 :mdcache_find_keyed_reason :INODE :F_DBG :Looking for hk=aa5216ef507b1089 fsal=0x7f24e080b080 key=0x84822902000000000100

Wed Jul 10 09:28:30 2019 UTC 23198[::ffff:10.0.138.85] [svc_38] /src/src/FSAL/Stackable_FSALs/FSAL_MDCACHE/mdcache_helpers.c:1018 :mdcache_find_keyed_reason :INODE :F_DBG :Found entry 0xd85c8e0

Wed Jul 10 09:28:30 2019 UTC 23198[::ffff:10.0.138.85] [svc_38] /opt/src/src/export.c:306 :foo_fs_supported_attrs :FSAL :DEBUG :supported attr mask=15DFEE

Wed Jul 10 09:28:30 2019 UTC 23198[::ffff:10.0.138.85] [svc_38] /src/src/FSAL/Stackable_FSALs/FSAL_MDCACHE/mdcache_handle.c:931 :mdcache_getattrs :INODE :F_DBG :attrs  obj attributes Request Mask=000006a0 Valid Mask=0015dfce Supported Mask=0015dfee DIRECTORY numlinks=0x1 size=0x0 mode=0755 owner=0xfffffffe group=0xfffffffe atime=Wed Dec 11 09:23:20 49523574 UTC mtime=Wed Dec 11 09:23:20 49523574 UTC

Wed Jul 10 09:28:30 2019 UTC 23198[::ffff:10.0.138.85] [svc_38] /src/src/FSAL/Stackable_FSALs/FSAL_MDCACHE/mdcache_handle.c:557 :mdcache_readdir :NFS READDIR :DEBUG :NFS READDIR: DEBUG: Calling mdcache_readdir_chunked whence=0

Wed Jul 10 09:28:30 2019 UTC 23198[::ffff:10.0.138.85] [svc_38] /src/src/FSAL/Stackable_FSALs/FSAL_MDCACHE/mdcache_helpers.c:2860 :mdcache_readdir_chunked :NFS READDIR :F_DBG :NFS READDIR: FULLDEBUG: Starting chunked READDIR for 0xd873770, MDCACHE_TRUST_CONTENT true, MDCACHE_TRUST_DIR_CHUNKS false

Wed Jul 10 09:28:30 2019 UTC 23198[::ffff:10.0.138.85] [svc_38] /src/src/FSAL/Stackable_FSALs/FSAL_MDCACHE/mdcache_helpers.c:2867 :mdcache_readdir_chunked :NFS READDIR :F_DBG :NFS READDIR: FULLDEBUG: Flushing invalid dirent cache

------->>>> Wed Jul 10 09:28:30 2019 UTC 23198[::ffff:10.0.138.85] [svc_38] /src/src/FSAL/Stackable_FSALs/FSAL_MDCACHE/mdcache_helpers.c:598 :mdcache_dirent_invalidate_all :NFS READDIR :F_DBG :NFS READDIR: FULLDEBUG: Invalidating directory for 0xd873770, clearing MDCACHE_DIR_POPULATED setting MDCACHE_TRUST_CONTENT and MDCACHE_TRUST_DIR_CHUNKS

Wed Jul 10 09:28:30 2019 UTC 23198[::ffff:10.0.138.85] [svc_38] /src/src/FSAL/Stackable_FSALs/FSAL_MDCACHE/mdcache_lru.c:2020 :lru_clean_chunk :INODE :F_DBG :Removing chunk 0xd690fb0

Wed Jul 10 09:28:30 2019 UTC 23198[::ffff:10.0.138.85] [svc_38] /src/src/FSAL/Stackable_FSALs/FSAL_MDCACHE/mdcache_lru.c:2065 :_mdcache_lru_unref_chunk :INODE :F_DBG :Freeing chunk 0xd690fb0

Wed Jul 10 09:28:30 2019 UTC 23198[::ffff:10.0.138.85] [svc_38] /src/src/FSAL/Stackable_FSALs/FSAL_MDCACHE/mdcache_avl.c:612 :mdcache_avl_clean_trees :NFS READDIR :F_DBG :NFS READDIR: FULLDEBUG: Invalidate 0x35d0a950 random.77

Wed Jul 10 09:28:30 2019 UTC 23198[::ffff:10.0.138.85] [svc_38] /src/src/FSAL/Stackable_FSALs/FSAL_MDCACHE/mdcache_avl.c:244 :mdcache_avl_remove :NFS READDIR :F_DBG :NFS READDIR: FULLDEBUG: Just freed dirent 0x35d0a950 from chunk (nil) parent (nil)

Wed Jul 10 09:28:30 2019 UTC 23198[::ffff:10.0.138.85] [svc_38] /src/src/FSAL/Stackable_FSALs/FSAL_MDCACHE/mdcache_helpers.c:2895 :mdcache_readdir_chunked :NFS READDIR :F_DBG :NFS READDIR: FULLDEBUG: Readdir chunked next_ck=0x0 look_ck=0

It does the unref on the chunk again.  this time it is releasing the refCount

held by svc48

svc_38 continues the readdir and when it releases the content lock -> svc48

cores.

Wed Jul 10 09:28:30 2019 UTC 23198[::ffff:10.0.138.85] [svc_38] /opt/src/src/export.c:149 :foo_fs_supports :FSAL :DEBUG :option=21

Wed Jul 10 09:28:30 2019 UTC 23198[::ffff:10.0.138.85] [svc_38] /opt/src/src/export.c:40 :fsal_option_to_name :FSAL :DEBUG :Option=21, to name=fso_whence_is_name

Wed Jul 10 09:28:30 2019 UTC 23198[::ffff:10.0.138.85] [svc_38] /opt/src/src/export.c:155 :foo_fs_supports :FSAL :DEBUG :option=21 (fso_whence_is_name), supported=0

Wed Jul 10 09:28:30 2019 UTC 23198[::ffff:10.0.138.85] [svc_38] /src/src/FSAL/Stackable_FSALs/FSAL_MDCACHE/mdcache_helpers.c:2963 :mdcache_readdir_chunked :NFS READDIR :F_DBG :NFS READDIR: FULLDEBUG: Readdir chunked about to populate chunk (nil) next_ck=0x0

The core I have in the message thread: https://lists.nfs-ganesha.org/archives/list/devel@lists.nfs-ganesha.org/thre... was with 2.7.5 with the below change already applied. The core is very reproducible. The window that is fixed by this change - does it also exist for the case where we transition to the next chunk on the last line in mdcache_readdir_chunked. Read_lock. The first chunk is populated, and we read the entries from that chunk. Then we transition to the next chunk. The next chunk is not populated, he have a ref count on the chunk, and we continue to hold the ref across the lock drop. Thanks, Vandana if (look_ck == 0 || !mdcache_avl_lookup_ck(directory, look_ck, &dirent)) { fsal_status_t status; /* This starting position isn't in our cache... * Go populate the cache and process from there. */ if (!has_write) { /* Upgrade to write lock and retry just in case * another thread managed to populate this cookie * in the meantime. */ PTHREAD_RWLOCK_unlock(&directory->content_lock); PTHREAD_RWLOCK_wrlock(&directory->content_lock); has_write = true; /* We have a ref on chunk; don't null it out */ goto again; } On 7/11/19, 8:09 AM, "Daniel Gryniewicz" <dang@redhat.com> wrote: Okay, this is a simple fix. It should not, in fact, be holding a ref across the lock drop, since we are throwing that chunk away anyway. The unref was in the wrong location. https://review.gerrithub.io/c/ffilz/nfs-ganesha/+/461446 Daniel On 7/10/19 6:02 PM, Frank Filz wrote: > Ah, good point. > > mdcache_clean_dirent_chunks maybe needs to remove the chunks from the > directory so that subsequent calls won’t unref the chunk again. It does > a glist_for_each_safe assuming the chunks will be removed but you’re > right, if other threads hold references to chunks, those chunks won’t > actually be removed. > > If we simply removed the chunk from the list, > mdcache_clean_dirent_chunks would not try and unref it again, and the > final unref from whichever thread was last in accessing the chunk would > clean the chunk but the chunk would have already been removed from the > directory list of chunks. > > Frank > > *From:* Rungta, Vandana [mailto:vrungta@amazon.com] > *Sent:* Wednesday, July 10, 2019 2:34 PM > *To:* devel@lists.nfs-ganesha.org; dang@redhat.com > *Subject:* [NFS-Ganesha-Devel] Extra mdcache_lru_unref_chunk path > > Thread 1 is holding a ref on the chunk and releases the content lock > > Thread 2 gets the write lock and calls dirents_invalidate_all and > unrefs the chunk, will not clean the chunk so it is still hooked to the > directory > > Thread 3 gets the write lock and calls dirents_invalidate_all and > unrefs the chunk – this is removing the ref held by Thread 1 and will > clean the chunk > > Thread 1 gets the write lock and tries to unref the chunk àbut chunk is > already deleted by Thread 3 > > Thanks, > > Vandana > > 2.7.4 with patches. > > Patches applied: > > https://github.com/nfs-ganesha/nfs-ganesha/commit/c7e7d24877085dbb0424542d9d... > > https://github.com/nfs-ganesha/nfs-ganesha/commit/136df4f262c3f9bc29df456eac... > > https://github.com/nfs-ganesha/nfs-ganesha/commit/c98ad1e238f5db9db5ab8db8ce... > > https://github.com/nfs-ganesha/nfs-ganesha/commit/f0d5b8d4f6dcce4597459c3eba... > > https://github.com/nfs-ganesha/nfs-ganesha/commit/e11cd5b9f8d6ffbb46061e7cd2... > > https://github.com/nfs-ganesha/nfs-ganesha/commit/5439f63b8a1e00f6ff56a4def5... > > https://github.com/nfs-ganesha/nfs-ganesha/commit/e306c01685b74970ada2259f2b... > > Relevant debug log messages: > > svc_48 is the thread that cored > > directory = 0xd873770 > > dirent = 0x3a6ff9c0 > > --> chunk with too many unrefs -> chunk = 0xd690fb0 > > Starting a readdir > > Wed Jul 10 09:28:30 2019 UTC 23198[::ffff:10.0.138.85] [svc_48] > /src/src/FSAL/Stackable_FSALs/FSAL_MDCACHE/mdcache_helpers.c:2860 > :mdcache_readdir_chunked :NFS READDIR :F_DBG :NFS READDIR: FULLDEBUG: > Starting chunked READDIR for 0xd873770, MDCACHE_TRUST_CONTENT true, > MDCACHE_TRUST_DIR_CHUNKS true > > Wed Jul 10 09:28:30 2019 UTC 23198[::ffff:10.0.138.85] [svc_48] > /src/src/FSAL/Stackable_FSALs/FSAL_MDCACHE/mdcache_helpers.c:2895 > :mdcache_readdir_chunked :NFS READDIR :F_DBG :NFS READDIR: FULLDEBUG: > Readdir chunked next_ck=0x0 look_ck=2298289 > > Wed Jul 10 09:28:30 2019 UTC 23198[::ffff:10.0.138.85] [svc_48] > /src/src/FSAL/Stackable_FSALs/FSAL_MDCACHE/mdcache_helpers.c:3061 > :mdcache_readdir_chunked :NFS READDIR :F_DBG :NFS READDIR: FULLDEBUG: > found dirent in cached chunk 0xd690fb0 dirent 0x9294be0 random.0 > > Wed Jul 10 09:28:30 2019 UTC 23198[::ffff:10.0.138.85] [svc_48] > /src/src/FSAL/Stackable_FSALs/FSAL_MDCACHE/mdcache_helpers.c:3069 > :mdcache_readdir_chunked :NFS READDIR :F_DBG :NFS READDIR: FULLDEBUG: > About to read directory=0xd873770 cookie=0 > > Wed Jul 10 09:28:30 2019 UTC 23198[::ffff:10.0.138.85] [svc_48] > /src/src/FSAL/Stackable_FSALs/FSAL_MDCACHE/mdcache_helpers.c:980 > :mdcache_find_keyed_reason :INODE :F_DBG :Looking for > hk=a5e560b83f87bdf1 fsal=0x7f24e080b080 key=0x86822902000000000100 > > Wed Jul 10 09:28:30 2019 UTC 23198[::ffff:10.0.138.85] [svc_48] > /src/src/FSAL/Stackable_FSALs/FSAL_MDCACHE/mdcache_helpers.c:1018 > :mdcache_find_keyed_reason :INODE :F_DBG :Found entry 0xd5651a0 > > Wed Jul 10 09:28:30 2019 UTC 23198[::ffff:10.0.138.85] [svc_48] > /src/src/FSAL/Stackable_FSALs/FSAL_MDCACHE/mdcache_helpers.c:3235 > :mdcache_readdir_chunked :NFS READDIR :F_DBG :NFS READDIR: FULLDEBUG: > Setting next_ck=2298289 > > Wed Jul 10 09:28:30 2019 UTC 23198[::ffff:10.0.138.85] [svc_48] > /src/src/FSAL/Stackable_FSALs/FSAL_MDCACHE/mdcache_handle.c:931 > :mdcache_getattrs :INODE :F_DBG :attrs obj attributes Valid > Mask=0015dfce Supported Mask=0015dfee REGULAR_FILE numlinks=0x1 > size=0xa19c08 mode=0755 owner=0xfffffffe group=0xfffffffe atime=Tue Aug > 06 07:06:40 49523574 UTC mtime=Wed Jul 10 04:44:09 2019 UTC > > Wed Jul 10 09:28:30 2019 UTC 23198[::ffff:10.0.138.85] [svc_48] > /src/src/FSAL/Stackable_FSALs/FSAL_MDCACHE/mdcache_helpers.c:3275 > :mdcache_readdir_chunked :NFS READDIR :F_DBG :NFS READDIR: FULLDEBUG: > dirent = 0x9294be0 random.0, cb_result = DIR_CONTINUE, eod = false > > Wed Jul 10 09:28:30 2019 UTC 23198[::ffff:10.0.138.85] [svc_48] > /src/src/FSAL/Stackable_FSALs/FSAL_MDCACHE/mdcache_helpers.c:980 > :mdcache_find_keyed_reason :INODE :F_DBG :Looking for > hk=7e081c83c9ef0267 fsal=0x7f24e080b080 key=0x89822902000000000100 > > ->mdcache_find_keyed_reason repeated pattern ...... > > Wed Jul 10 09:28:30 2019 UTC 23198[::ffff:10.0.138.85] [svc_48] > /src/src/FSAL/Stackable_FSALs/FSAL_MDCACHE/mdcache_helpers.c:980 > :mdcache_find_keyed_reason :INODE :F_DBG :Looking for hk=73c0008e99ecba6 > fsal=0x7f24e080b080 key=0xd3822902000000000100 > > Wed Jul 10 09:28:30 2019 UTC 23198[::ffff:10.0.138.85] [svc_48] > /src/src/FSAL/Stackable_FSALs/FSAL_MDCACHE/mdcache_helpers.c:1018 > :mdcache_find_keyed_reason :INODE :F_DBG :Found entry 0xdb00050 > > Wed Jul 10 09:28:30 2019 UTC 23198[::ffff:10.0.138.85] [svc_48] > /src/src/FSAL/Stackable_FSALs/FSAL_MDCACHE/mdcache_helpers.c:3235 > :mdcache_readdir_chunked :NFS READDIR :F_DBG :NFS READDIR: FULLDEBUG: > Setting next_ck=22982d6 > > Wed Jul 10 09:28:30 2019 UTC 23198[::ffff:10.0.138.85] [svc_48] > /src/src/FSAL/Stackable_FSALs/FSAL_MDCACHE/mdcache_handle.c:931 > :mdcache_getattrs :INODE :F_DBG :attrs obj attributes Valid > Mask=0015dfce Supported Mask=0015dfee REGULAR_FILE numlinks=0x1 > size=0xa19c08 mode=0755 owner=0xfffffffe group=0xfffffffe atime=Sun Dec > 15 00:03:20 49523574 UTC mtime=Sun Dec 15 00:03:20 49523574 UTC > > Wed Jul 10 09:28:30 2019 UTC 23198[::ffff:10.0.138.85] [svc_48] > /src/src/FSAL/Stackable_FSALs/FSAL_MDCACHE/mdcache_helpers.c:3275 > :mdcache_readdir_chunked :NFS READDIR :F_DBG :NFS READDIR: FULLDEBUG: > dirent = 0x3acbce10 random.79, cb_result = DIR_CONTINUE, eod = false > > Wed Jul 10 09:28:30 2019 UTC 23198[::ffff:10.0.138.85] [svc_48] > /src/src/FSAL/Stackable_FSALs/FSAL_MDCACHE/mdcache_helpers.c:980 > :mdcache_find_keyed_reason :INODE :F_DBG :Looking for > hk=c2b7f772bdd8c5c4 fsal=0x7f24e080b080 key=0xd4822902000000000100 > > Wed Jul 10 09:28:30 2019 UTC 23198[::ffff:10.0.138.85] [svc_48] > /src/src/FSAL/Stackable_FSALs/FSAL_MDCACHE/mdcache_helpers.c:3108 > :mdcache_readdir_chunked :NFS READDIR :F_DBG :NFS READDIR: FULLDEBUG: > Lookup by key for random.8 failed, lookup by name now > > -> releasing the content lock here, and waiting for a write lock. Here, is also releases it's chunk ref and NULLs out it's chunk pointer. > > svc_61 --> open2 path and gets the write lock > > It goes through a invalidate directory here. > > Invalidate directory -> unref's all the chunks in the directory > > Wed Jul 10 09:28:30 2019 UTC 23198[::ffff:10.0.138.85] [svc_61] > /opt/src/src/handle.c:471 :foo_handle_to_key :FSAL :DEBUG :Providing > digest to ganesha for hashing. id=36274900, export_id=1 > > Wed Jul 10 09:28:30 2019 UTC 23198[::ffff:10.0.138.85] [svc_61] > /src/src/FSAL/Stackable_FSALs/FSAL_MDCACHE/mdcache_helpers.c:980 > :mdcache_find_keyed_reason :INODE :F_DBG :Looking for > hk=c2b7f772bdd8c5c4 fsal=0x7f24e080b080 key=0xd4822902000000000100 > > Wed Jul 10 09:28:30 2019 UTC 23198[::ffff:10.0.138.85] [svc_61] > /src/src/FSAL/Stackable_FSALs/FSAL_MDCACHE/mdcache_lru.c:559 > :mdcache_lru_clean :INODE :F_DBG :Trusting op_ctx export id 1 > > Wed Jul 10 09:28:30 2019 UTC 23198[::ffff:10.0.138.85] [svc_61] > /opt/src/src/handle.c:44 :foo_close2 :FSAL :DEBUG :Handle: 2442805 > state: (nil) > > Wed Jul 10 09:28:30 2019 UTC 23198[::ffff:10.0.138.85] [svc_61] > /opt/src/src/handle.c:107 :foo_release :FSAL :DEBUG :fileId=2442805 > > Wed Jul 10 09:28:30 2019 UTC 23198[::ffff:10.0.138.85] [svc_61] > /opt/src/src/handle.c:44 :foo_close2 :FSAL :DEBUG :Handle: 2442805 > state: (nil) > > Wed Jul 10 09:28:30 2019 UTC 23198[::ffff:10.0.138.85] [svc_61] > /opt/src/src/handle.c:114 :foo_release :FSAL :DEBUG :Could not close hdl > 0x0x4064e880, error Success(0) > > Wed Jul 10 09:28:30 2019 UTC 23198[::ffff:10.0.138.85] [svc_61] > /src/src/FSAL/Stackable_FSALs/FSAL_MDCACHE/mdcache_helpers.c:750 > :mdcache_new_entry :INODE :DEBUG :Adding a REGULAR_FILE, entry=0xd86a830 > > Wed Jul 10 09:28:30 2019 UTC 23198[::ffff:10.0.138.85] [svc_61] > /src/src/FSAL/Stackable_FSALs/FSAL_MDCACHE/mdcache_helpers.c:845 > :mdcache_new_entry :INODE :F_DBG :New entry 0xd86a830 added with > fh_hk.key hk=c2b7f772bdd8c5c4 fsal=0x7f24e080b080 key=0xd4822902000000000100 > > Wed Jul 10 09:28:30 2019 UTC 23198[::ffff:10.0.138.85] [svc_61] > /src/src/FSAL/Stackable_FSALs/FSAL_MDCACHE/mdcache_handle.c:112 > :mdcache_alloc_and_check_handle :INODE :F_DBG :open2 Created entry > 0xd86a830 FSAL FOO for random.8 > > Wed Jul 10 09:28:30 2019 UTC 23198[::ffff:10.0.138.85] [svc_61] > /src/src/FSAL/Stackable_FSALs/FSAL_MDCACHE/mdcache_helpers.c:1522 > :mdcache_dirent_add :INODE :F_DBG :Add dir entry random.8 > > Wed Jul 10 09:28:30 2019 UTC 23198[::ffff:10.0.138.85] [svc_61] > /src/src/FSAL/Stackable_FSALs/FSAL_MDCACHE/mdcache_avl.c:322 > :mdcache_avl_insert :NFS READDIR :F_DBG :NFS READDIR: FULLDEBUG: Insert > dir entry 0x364afd80 random.8 > > Wed Jul 10 09:28:30 2019 UTC 23198[::ffff:10.0.138.85] [svc_61] > /src/src/FSAL/Stackable_FSALs/FSAL_MDCACHE/mdcache_avl.c:380 > :mdcache_avl_insert :NFS READDIR :DEBUG :NFS READDIR: DEBUG: Already > existent when inserting new dirent on entry=0xd873770 name=random.8 > > Wed Jul 10 09:28:30 2019 UTC 23198[::ffff:10.0.138.85] [svc_61] > /src/src/FSAL/Stackable_FSALs/FSAL_MDCACHE/mdcache_avl.c:490 > :mdcache_avl_insert :NFS READDIR :F_DBG :NFS READDIR: FULLDEBUG: > Duplicate insert of random.8 v->chunk=(nil) v2->chunk=0xd690fb0 > > Wed Jul 10 09:28:30 2019 UTC 23198[::ffff:10.0.138.85] [svc_61] > /src/src/FSAL/Stackable_FSALs/FSAL_MDCACHE/mdcache_handle.c:150 > :mdcache_alloc_and_check_handle :INODE :F_DBG :open2 obj attributes > Request Mask=0001dfce Valid Mask=0015dfce Supported Mask=0015dfee > REGULAR_FILE numlinks=0x1 size=0x0 mode=0755 owner=0xfffffffe > group=0xfffffffe atime=Thu Jan 01 00:00:00 1970 UTC mtime=Wed Jul 10 > 09:28:30 2019 UTC > > Wed Jul 10 09:28:30 2019 UTC 23198[::ffff:10.0.138.85] [svc_61] > /src/src/FSAL/fsal_helper.c:418 :open2_by_name :FSAL :F_DBG :Created > entry 0xd86a868 FSAL MDCACHE for random.8 > > Wed Jul 10 09:28:30 2019 UTC 23198[::ffff:10.0.138.85] [svc_61] > /opt/src/src/handle.c:441 :foo_handle_to_wire :FSAL :DEBUG :Providing > digest to ganesha for nfs file handle. fileId=36274900, export_id=1 > > Wed Jul 10 09:28:30 2019 UTC 23198[::ffff:10.0.138.85] [svc_61] > /opt/src/src/export.c:306 :foo_fs_supported_attrs :FSAL :DEBUG > :supported attr mask=15DFEE > > Wed Jul 10 09:28:30 2019 UTC 23198[::ffff:10.0.138.85] [svc_61] > /opt/src/src/handle.c:776 :foo_getattrs :FSAL :DEBUG :fileId=36274821 > > Wed Jul 10 09:28:30 2019 UTC 23198[::ffff:10.0.138.85] [svc_61] > /opt/src/src/handle.c:315 :foo_populate_attrs :FSAL :DEBUG > :fileId=36274821, type=1, size=0, mode=755, owner=4294967294, > group=4294967294, ctime=1205435200, atime=1205435200, mtime=1205435200 > > Wed Jul 10 09:28:30 2019 UTC 23198[::ffff:10.0.138.85] [svc_61] > /src/src/FSAL/Stackable_FSALs/FSAL_MDCACHE/mdcache_handle.c:857 > :mdcache_refresh_attrs :INODE :F_DBG :attrs obj attributes Request > Mask=0015dfce Valid Mask=0015dfce Supported Mask=0015dfee DIRECTORY > numlinks=0x1 size=0x0 mode=0755 owner=0xfffffffe group=0xfffffffe > atime=Wed Dec 11 09:23:20 49523574 UTC mtime=Wed Dec 11 09:23:20 > 49523574 UTC > > Wed Jul 10 09:28:30 2019 UTC 23198[::ffff:10.0.138.85] [svc_61] > /src/src/FSAL/Stackable_FSALs/FSAL_MDCACHE/mdcache_helpers.c:598 > :mdcache_dirent_invalidate_all :NFS READDIR :F_DBG :NFS READDIR: > FULLDEBUG: Invalidating directory for 0xd873770, clearing > MDCACHE_DIR_POPULATED setting MDCACHE_TRUST_CONTENT and > MDCACHE_TRUST_DIR_CHUNKS > > Invalidating the dirents in the directory > > Unrefs the chunk (does not clean_chunk because svc_48 has the ref ) svc_48 doesn't have this ref, it must be held somewhere else. > > avl_clean_trees cleans the dirents > > Wed Jul 10 09:28:30 2019 UTC 23198[::ffff:10.0.138.85] [svc_61] > /src/src/FSAL/Stackable_FSALs/FSAL_MDCACHE/mdcache_avl.c:612 > :mdcache_avl_clean_trees :NFS READDIR :F_DBG :NFS READDIR: FULLDEBUG: > Invalidate 0x399be410 random.23 > > Wed Jul 10 09:28:30 2019 UTC 23198[::ffff:10.0.138.85] [svc_61] > /src/src/FSAL/Stackable_FSALs/FSAL_MDCACHE/mdcache_avl.c:171 > :unchunk_dirent :NFS READDIR :F_DBG :NFS READDIR: FULLDEBUG: Unchunking > 0x399be410 random.23 > > Wed Jul 10 09:28:30 2019 UTC 23198[::ffff:10.0.138.85] [svc_61] > /src/src/FSAL/Stackable_FSALs/FSAL_MDCACHE/mdcache_avl.c:244 > :mdcache_avl_remove :NFS READDIR :F_DBG :NFS READDIR: FULLDEBUG: Just > freed dirent 0x399be410 from chunk 0xd690fb0 parent 0xd873770 > > -- Repeated pattern > > Wed Jul 10 09:28:30 2019 UTC 23198[::ffff:10.0.138.85] [svc_61] > /src/src/FSAL/Stackable_FSALs/FSAL_MDCACHE/mdcache_avl.c:612 > :mdcache_avl_clean_trees :NFS READDIR :F_DBG :NFS READDIR: FULLDEBUG: > Invalidate 0x39f54ba0 random.28 > > Wed Jul 10 09:28:30 2019 UTC 23198[::ffff:10.0.138.85] [svc_61] > /src/src/FSAL/Stackable_FSALs/FSAL_MDCACHE/mdcache_avl.c:171 > :unchunk_dirent :NFS READDIR :F_DBG :NFS READDIR: FULLDEBUG: Unchunking > 0x39f54ba0 random.28 > > Wed Jul 10 09:28:30 2019 UTC 23198[::ffff:10.0.138.85] [svc_61] > /src/src/FSAL/Stackable_FSALs/FSAL_MDCACHE/mdcache_avl.c:244 > :mdcache_avl_remove :NFS READDIR :F_DBG :NFS READDIR: FULLDEBUG: Just > freed dirent 0x39f54ba0 from chunk 0xd690fb0 parent 0xd873770 > > Wed Jul 10 09:28:30 2019 UTC 23198[::ffff:10.0.138.85] [svc_61] > /src/src/FSAL/Stackable_FSALs/FSAL_MDCACHE/mdcache_avl.c:612 > :mdcache_avl_clean_trees :NFS READDIR :F_DBG :NFS READDIR: FULLDEBUG: > Invalidate 0x12fda5c0 random.2 > > Wed Jul 10 09:28:30 2019 UTC 23198[::ffff:10.0.138.85] [svc_61] > /src/src/FSAL/Stackable_FSALs/FSAL_MDCACHE/mdcache_avl.c:171 > :unchunk_dirent :NFS READDIR :F_DBG :NFS READDIR: FULLDEBUG: Unchunking > 0x12fda5c0 random.2 > > Wed Jul 10 09:28:30 2019 UTC 23198[::ffff:10.0.138.85] [svc_61] > /src/src/FSAL/Stackable_FSALs/FSAL_MDCACHE/mdcache_avl.c:244 > :mdcache_avl_remove :NFS READDIR :F_DBG :NFS READDIR: FULLDEBUG: Just > freed dirent 0x12fda5c0 from chunk 0xd690fb0 parent 0xd873770 > > svc_61 will release the lock here > > svc_38 starts a READDIR on this directory and gets the write content > lock and > > calls dirent_invalidate_all > > Wed Jul 10 09:28:30 2019 UTC 23198[none] [svc_38] > /src/src/MainNFSD/nfs_rpc_dispatcher_thread.c:1332 > :nfs_rpc_decode_request :DISP :DEBUG :0x35232ed0 fd 31 context 0x6bbf5b80 > > Wed Jul 10 09:28:30 2019 UTC 23198[none] [svc_38] > /src/src/MainNFSD/nfs_worker_thread.c:713 :nfs_rpc_process_request :DISP > :F_DBG :About to authenticate Prog=100003, vers=3, proc=16, > xid=154636653, SVCXPRT=0x35232ed0, fd=31 > > Wed Jul 10 09:28:30 2019 UTC 23198[none] [svc_38] > /src/src/MainNFSD/nfs_worker_thread.c:751 :nfs_rpc_process_request :DISP > :F_DBG :Before SVCAUTH_CHECKSUM on SVCXPRT 0x35232ed0 fd 31 > > Wed Jul 10 09:28:30 2019 UTC 23198[::ffff:10.0.138.85] [svc_38] > /src/src/MainNFSD/nfs_worker_thread.c:839 :nfs_rpc_process_request :DISP > :DEBUG :Request from ::ffff:10.0.138.85 for Program 100003, Version 3, > Function 16 has xid=154636653 > > Wed Jul 10 09:28:30 2019 UTC 23198[::ffff:10.0.138.85] [svc_38] > /src/src/MainNFSD/nfs_worker_thread.c:856 :nfs_rpc_process_request :DISP > :F_DBG :Current request is not duplicate or not cacheable. > > Wed Jul 10 09:28:30 2019 UTC 23198[::ffff:10.0.138.85] [svc_38] > /src/src/MainNFSD/nfs_worker_thread.c:985 :nfs_rpc_process_request :DISP > :M_DBG :DISP: MID DEBUG: Found export entry for > path=/integtest-fileshare-bucket-vrungta-bf88s as exportid=1 > > Wed Jul 10 09:28:30 2019 UTC 23198[::ffff:10.0.138.85] [svc_38] > /src/src/MainNFSD/nfs_worker_thread.c:1097 :nfs_rpc_process_request > :DISP :M_DBG :DISP: MID DEBUG: nfs_rpc_process_request about to call > nfs_export_check_access for client ::ffff:10.0.138.85 > > Wed Jul 10 09:28:30 2019 UTC 23198[::ffff:10.0.138.85] [svc_38] > /src/src/support/nfs_creds.c:504 :nfs_req_creds :DISP :M_DBG :DISP: MID > DEBUG: AUTH_SYS creds mapped to uid=4294967294, gid=4294967294, glen=0 > > Wed Jul 10 09:28:30 2019 UTC 23198[::ffff:10.0.138.85] [svc_38] > /src/src/Protocols/NFS/nfs3_readdir.c:144 :nfs3_readdir :NFS READDIR > :DEBUG :NFS READDIR: DEBUG: REQUEST PROCESSING: Calling nfs_Readdir > handle: File Handle V3: Len=16 430000010a8582290200000000010000 > > Wed Jul 10 09:28:30 2019 UTC 23198[::ffff:10.0.138.85] [svc_38] > /opt/src/src/export.c:83 :foo_wire_to_host :FSAL :DEBUG :Setting length > of digest for ganesha file handle. fh_desc length=10 > > Wed Jul 10 09:28:30 2019 UTC 23198[::ffff:10.0.138.85] [svc_38] > /src/src/FSAL/Stackable_FSALs/FSAL_MDCACHE/mdcache_helpers.c:980 > :mdcache_find_keyed_reason :INODE :F_DBG :Looking for > hk=1a3aad454037de63 fsal=0x7f24e080b080 key=0x85822902000000000100 > > Wed Jul 10 09:28:30 2019 UTC 23198[::ffff:10.0.138.85] [svc_38] > /src/src/FSAL/Stackable_FSALs/FSAL_MDCACHE/mdcache_helpers.c:1018 > :mdcache_find_keyed_reason :INODE :F_DBG :Found entry 0xd873770 > > Wed Jul 10 09:28:30 2019 UTC 23198[::ffff:10.0.138.85] [svc_38] > /src/src/Protocols/NFS/nfs3_readdir.c:183 :nfs3_readdir :NFS READDIR > :DEBUG :---> NFS3_READDIR: count=16384 cookie=0 estimated_num_entries=120 > > Wed Jul 10 09:28:30 2019 UTC 23198[::ffff:10.0.138.85] [svc_38] > /src/src/FSAL/Stackable_FSALs/FSAL_MDCACHE/mdcache_helpers.c:1228 > :mdc_lookup :NFS READDIR :F_DBG :NFS READDIR: FULLDEBUG: Lookup .. > > Wed Jul 10 09:28:30 2019 UTC 23198[::ffff:10.0.138.85] [svc_38] > /src/src/FSAL/Stackable_FSALs/FSAL_MDCACHE/mdcache_helpers.c:1236 > :mdc_lookup :NFS READDIR :F_DBG :NFS READDIR: FULLDEBUG: Lookup parent > (..) of 0xd873770 > > Wed Jul 10 09:28:30 2019 UTC 23198[::ffff:10.0.138.85] [svc_38] > /src/src/FSAL/Stackable_FSALs/FSAL_MDCACHE/mdcache_helpers.c:980 > :mdcache_find_keyed_reason :INODE :F_DBG :Looking for > hk=aa5216ef507b1089 fsal=0x7f24e080b080 key=0x84822902000000000100 > > Wed Jul 10 09:28:30 2019 UTC 23198[::ffff:10.0.138.85] [svc_38] > /src/src/FSAL/Stackable_FSALs/FSAL_MDCACHE/mdcache_helpers.c:1018 > :mdcache_find_keyed_reason :INODE :F_DBG :Found entry 0xd85c8e0 > > Wed Jul 10 09:28:30 2019 UTC 23198[::ffff:10.0.138.85] [svc_38] > /opt/src/src/export.c:306 :foo_fs_supported_attrs :FSAL :DEBUG > :supported attr mask=15DFEE > > Wed Jul 10 09:28:30 2019 UTC 23198[::ffff:10.0.138.85] [svc_38] > /src/src/FSAL/Stackable_FSALs/FSAL_MDCACHE/mdcache_handle.c:931 > :mdcache_getattrs :INODE :F_DBG :attrs obj attributes Request > Mask=000006a0 Valid Mask=0015dfce Supported Mask=0015dfee DIRECTORY > numlinks=0x1 size=0x0 mode=0755 owner=0xfffffffe group=0xfffffffe > atime=Wed Dec 11 09:23:20 49523574 UTC mtime=Wed Dec 11 09:23:20 > 49523574 UTC > > Wed Jul 10 09:28:30 2019 UTC 23198[::ffff:10.0.138.85] [svc_38] > /src/src/FSAL/Stackable_FSALs/FSAL_MDCACHE/mdcache_handle.c:557 > :mdcache_readdir :NFS READDIR :DEBUG :NFS READDIR: DEBUG: Calling > mdcache_readdir_chunked whence=0 > > Wed Jul 10 09:28:30 2019 UTC 23198[::ffff:10.0.138.85] [svc_38] > /src/src/FSAL/Stackable_FSALs/FSAL_MDCACHE/mdcache_helpers.c:2860 > :mdcache_readdir_chunked :NFS READDIR :F_DBG :NFS READDIR: FULLDEBUG: > Starting chunked READDIR for 0xd873770, MDCACHE_TRUST_CONTENT true, > MDCACHE_TRUST_DIR_CHUNKS false > > Wed Jul 10 09:28:30 2019 UTC 23198[::ffff:10.0.138.85] [svc_38] > /src/src/FSAL/Stackable_FSALs/FSAL_MDCACHE/mdcache_helpers.c:2867 > :mdcache_readdir_chunked :NFS READDIR :F_DBG :NFS READDIR: FULLDEBUG: > Flushing invalid dirent cache > > ------->>>> Wed Jul 10 09:28:30 2019 UTC 23198[::ffff:10.0.138.85] > [svc_38] > /src/src/FSAL/Stackable_FSALs/FSAL_MDCACHE/mdcache_helpers.c:598 > :mdcache_dirent_invalidate_all :NFS READDIR :F_DBG :NFS READDIR: > FULLDEBUG: Invalidating directory for 0xd873770, clearing > MDCACHE_DIR_POPULATED setting MDCACHE_TRUST_CONTENT and > MDCACHE_TRUST_DIR_CHUNKS > > Wed Jul 10 09:28:30 2019 UTC 23198[::ffff:10.0.138.85] [svc_38] > /src/src/FSAL/Stackable_FSALs/FSAL_MDCACHE/mdcache_lru.c:2020 > :lru_clean_chunk :INODE :F_DBG :Removing chunk 0xd690fb0 > > Wed Jul 10 09:28:30 2019 UTC 23198[::ffff:10.0.138.85] [svc_38] > /src/src/FSAL/Stackable_FSALs/FSAL_MDCACHE/mdcache_lru.c:2065 > :_mdcache_lru_unref_chunk :INODE :F_DBG :Freeing chunk 0xd690fb0 > > Wed Jul 10 09:28:30 2019 UTC 23198[::ffff:10.0.138.85] [svc_38] > /src/src/FSAL/Stackable_FSALs/FSAL_MDCACHE/mdcache_avl.c:612 > :mdcache_avl_clean_trees :NFS READDIR :F_DBG :NFS READDIR: FULLDEBUG: > Invalidate 0x35d0a950 random.77 > > Wed Jul 10 09:28:30 2019 UTC 23198[::ffff:10.0.138.85] [svc_38] > /src/src/FSAL/Stackable_FSALs/FSAL_MDCACHE/mdcache_avl.c:244 > :mdcache_avl_remove :NFS READDIR :F_DBG :NFS READDIR: FULLDEBUG: Just > freed dirent 0x35d0a950 from chunk (nil) parent (nil) > > Wed Jul 10 09:28:30 2019 UTC 23198[::ffff:10.0.138.85] [svc_38] > /src/src/FSAL/Stackable_FSALs/FSAL_MDCACHE/mdcache_helpers.c:2895 > :mdcache_readdir_chunked :NFS READDIR :F_DBG :NFS READDIR: FULLDEBUG: > Readdir chunked next_ck=0x0 look_ck=0 > > It does the unref on the chunk again. this time it is releasing the > refCount > > held by svc48 > > svc_38 continues the readdir and when it releases the content lock -> svc48 > > cores. > > Wed Jul 10 09:28:30 2019 UTC 23198[::ffff:10.0.138.85] [svc_38] > /opt/src/src/export.c:149 :foo_fs_supports :FSAL :DEBUG :option=21 > > Wed Jul 10 09:28:30 2019 UTC 23198[::ffff:10.0.138.85] [svc_38] > /opt/src/src/export.c:40 :fsal_option_to_name :FSAL :DEBUG :Option=21, > to name=fso_whence_is_name > > Wed Jul 10 09:28:30 2019 UTC 23198[::ffff:10.0.138.85] [svc_38] > /opt/src/src/export.c:155 :foo_fs_supports :FSAL :DEBUG :option=21 > (fso_whence_is_name), supported=0 > > Wed Jul 10 09:28:30 2019 UTC 23198[::ffff:10.0.138.85] [svc_38] > /src/src/FSAL/Stackable_FSALs/FSAL_MDCACHE/mdcache_helpers.c:2963 > :mdcache_readdir_chunked :NFS READDIR :F_DBG :NFS READDIR: FULLDEBUG: > Readdir chunked about to populate chunk (nil) next_ck=0x0 >

Pasi, Early test results for 2.7.6 are looking good. Thanks, Vandana On 7/18/19, 3:13 AM, "Pasi Kärkkäinen" <pasik@iki.fi> wrote: Hello Rungta, On Thu, Jul 11, 2019 at 03:24:48PM +0000, Rungta, Vandana wrote: > The core I have in the message thread: https://lists.nfs-ganesha.org/archives/list/devel@lists.nfs-ganesha.org/thre... > was with 2.7.5 with the below change already applied. The core is very reproducible. > I'm curious if nfs-ganesha V2.7.6 works OK for you? Would be nice to know the test results with that version. Thanks, -- Pasi > The window that is fixed by this change - does it also exist for the case where we transition to the next chunk on the last line in mdcache_readdir_chunked. > Read_lock. The first chunk is populated, and we read the entries from that chunk. Then we transition to the next chunk. The next chunk is not populated, he have a ref count on the chunk, and we continue to hold the ref across the lock drop. > > Thanks, > Vandana > > if (look_ck == 0 || > !mdcache_avl_lookup_ck(directory, look_ck, &dirent)) { > fsal_status_t status; > /* This starting position isn't in our cache... > * Go populate the cache and process from there. > */ > if (!has_write) { > /* Upgrade to write lock and retry just in case > * another thread managed to populate this cookie > * in the meantime. > */ > PTHREAD_RWLOCK_unlock(&directory->content_lock); > PTHREAD_RWLOCK_wrlock(&directory->content_lock); > has_write = true; > /* We have a ref on chunk; don't null it out */ > goto again; > } > > > ???On 7/11/19, 8:09 AM, "Daniel Gryniewicz" <dang@redhat.com> wrote: > > Okay, this is a simple fix. It should not, in fact, be holding a ref > across the lock drop, since we are throwing that chunk away anyway. The > unref was in the wrong location. > > https://review.gerrithub.io/c/ffilz/nfs-ganesha/+/461446 > > Daniel > _______________________________________________ Devel mailing list -- devel@lists.nfs-ganesha.org To unsubscribe send an email to devel-leave@lists.nfs-ganesha.org