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(a)lists.nfs-ganesha.org; dang(a)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/c7e7d24877085dbb0424542... https://github.com/nfs-ganesha/nfs-ganesha/commit/136df4f262c3f9bc29df456... https://github.com/nfs-ganesha/nfs-ganesha/commit/c98ad1e238f5db9db5ab8db... https://github.com/nfs-ganesha/nfs-ganesha/commit/f0d5b8d4f6dcce4597459c3... https://github.com/nfs-ganesha/nfs-ganesha/commit/e11cd5b9f8d6ffbb46061e7... https://github.com/nfs-ganesha/nfs-ganesha/commit/5439f63b8a1e00f6ff56a4d... https://github.com/nfs-ganesha/nfs-ganesha/commit/e306c01685b74970ada2259... 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

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(a)lists.nfs-ganesha.org; dang(a)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/c7e7d24877085dbb0424542... https://github.com/nfs-ganesha/nfs-ganesha/commit/136df4f262c3f9bc29df456... https://github.com/nfs-ganesha/nfs-ganesha/commit/c98ad1e238f5db9db5ab8db... https://github.com/nfs-ganesha/nfs-ganesha/commit/f0d5b8d4f6dcce4597459c3... https://github.com/nfs-ganesha/nfs-ganesha/commit/e11cd5b9f8d6ffbb46061e7... https://github.com/nfs-ganesha/nfs-ganesha/commit/5439f63b8a1e00f6ff56a4d... https://github.com/nfs-ganesha/nfs-ganesha/commit/e306c01685b74970ada2259... 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/t... 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(a)redhat.com&gt; 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