[NFS-Ganesha-Devel] Re: Extra mdcache_lru_unref_chunk path

11 Jul 2019

      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
    >