Crash in mdc_lookup_uncached with a bad name pointer
Hello, We are seeing the following crash with NFS Ganesha 2.7.1 – we crash further in our fsal module’s lookup method trying to use the “name” which has an invalid pointer. This has the following 3 patches applied to NFS Ganesha 2.7.1 https://github.com/nfs-ganesha/nfs-ganesha/commit/654dd706d22663c6ae6029e0c8... https://github.com/nfs-ganesha/nfs-ganesha/commit/5dc6a70ed42275a4f6772b9802... The most recent patch to not return dead hash entries: https://github.com/nfs-ganesha/nfs-ganesha/commit/25320e6544f6c5a045f20c5144... The workload: Concurrent access from multiple threads. 1 thread continuously (in a loop) running python os.walk (i.e., readdir) of the entire filesystem, roughly ~5M files total. 5 more threads are writing a few thousand files each. When the writes complete, a single thread verifies written content, then deletes it. Then the writes repeat again. This is the same workload that causes our OOM issue. https://lists.nfs-ganesha.org/archives/list/devel@lists.nfs-ganesha.org/thre... #5 0x00007f6acd6a1dca in foo_lookup (parent=0x6fe2e420, name=0xa0 <Address 0xa0 out of bounds>, handle=0x7f6abf3255a8, attrs_out=0x7f6abf3254a0) at /opt/src/src/handle.c:364 #6 0x000000000053a7a6 in mdc_lookup_uncached (mdc_parent=0x291a4ba0, name=0xa0 <Address 0xa0 out of bounds>, new_entry=0x7f6abf325728, attrs_out=0x0) at /src/src/FSAL/Stackable_FSALs/FSAL_MDCACHE/mdcache_helpers.c:1293 #7 0x0000000000541344 in mdcache_readdir_chunked (directory=0x291a4ba0, whence=0, dir_state=0x7f6abf325900, cb=0x43217c <populate_dirent>, attrmask=122830, eod_met=0x7f6abf325ffb) at /src/src/FSAL/Stackable_FSALs/FSAL_MDCACHE/mdcache_helpers.c:3065 #8 0x000000000052e8c3 in mdcache_readdir (dir_hdl=0x291a4bd8, whence=0x7f6abf3258e0, dir_state=0x7f6abf325900, cb=0x43217c <populate_dirent>, attrmask=122830, eod_met=0x7f6abf325ffb) at /src/src/FSAL/Stackable_FSALs/FSAL_MDCACHE/mdcache_handle.c:559 #9 0x0000000000432a76 in fsal_readdir (directory=0x291a4bd8, cookie=0, nbfound=0x7f6abf325ffc, eod_met=0x7f6abf325ffb, attrmask=122830, cb=0x492018 <nfs3_readdirplus_callback>, opaque=0x7f6abf325fb0) at /src/src/FSAL/fsal_helper.c:1158 #10 0x0000000000491e71 in nfs3_readdirplus (arg=0x10704818, req=0x10704110, res=0x3103f090) at /src/src/Protocols/NFS/nfs3_readdirplus.c:310 #11 0x00000000004574d1 in nfs_rpc_process_request (reqdata=0x10704110) at /src/src/MainNFSD/nfs_worker_thread.c:1329 #12 0x0000000000457c90 in nfs_rpc_valid_NFS (req=0x10704110) at /src/src/MainNFSD/nfs_worker_thread.c:1549 #13 0x00007f6ad115ce75 in svc_vc_decode (req=0x10704110) at /src/src/libntirpc/src/svc_vc.c:825 ---Type <return> to continue, or q <return> to quit--- #14 0x000000000044a688 in nfs_rpc_decode_request (xprt=0x18390200, xdrs=0x174943c0) at /src/src/MainNFSD/nfs_rpc_dispatcher_thread.c:1341 #15 0x00007f6ad115cd86 in svc_vc_recv (xprt=0x18390200) at /src/src/libntirpc/src/svc_vc.c:798 #16 0x00007f6ad11594d3 in svc_rqst_xprt_task (wpe=0x18390418) at /src/src/libntirpc/src/svc_rqst.c:767 #17 0x00007f6ad115994d in svc_rqst_epoll_events (sr_rec=0x2779260, n_events=1) at /src/src/libntirpc/src/svc_rqst.c:939 #18 0x00007f6ad1159be2 in svc_rqst_epoll_loop (sr_rec=0x2779260) at /src/src/libntirpc/src/svc_rqst.c:1012 #19 0x00007f6ad1159c95 in svc_rqst_run_task (wpe=0x2779260) at /src/src/libntirpc/src/svc_rqst.c:1048 #20 0x00007f6ad11625f6 in work_pool_thread (arg=0x3b5d170) at /src/src/libntirpc/src/work_pool.c:181 #21 0x00007f6ad0169de5 in start_thread () from /lib64/libpthread.so.0 #22 0x00007f6acfa71bad in clone () from /lib64/libc.so.6 (gdb) select-frame 7 (gdb) info locals status = {major = ERR_FSAL_INVAL, minor = 0} cb_result = DIR_CONTINUE entry = 0x0 attrs = {request_mask = 122830, valid_mask = 1433550, supported = 1433582, type = REGULAR_FILE, filesize = 1024, fsid = {major = 0, minor = 0}, acl = 0x0, fileid = 47680710, mode = 438, numlinks = 1, owner = 65534, group = 65534, rawdev = {major = 0, minor = 0}, atime = {tv_sec = 1548784955, tv_nsec = 582000000}, creation = { tv_sec = 0, tv_nsec = 0}, ctime = {tv_sec = 1548784955, tv_nsec = 582000000}, mtime = {tv_sec = 1548784955, tv_nsec = 582000000}, chgtime = {tv_sec = 1548784955, tv_nsec = 582000000}, spaceused = 1024, change = 1548784955582, generation = 0, expire_time_attr = 60, fs_locations = 0x0} dirent = 0x5296230 has_write = true set_first_ck = false next_ck = 2419507 look_ck = 2419507 chunk = 0x156d7240 first_pass = true eod = false reload_chunk = false __func__ = "mdcache_readdir_chunked" __PRETTY_FUNCTION__ = "mdcache_readdir_chunked" (gdb) status = {major = ERR_FSAL_INVAL, minor = 0} cb_result = DIR_CONTINUE entry = 0x0 attrs = {request_mask = 122830, valid_mask = 1433550, supported = 1433582, type = REGULAR_FILE, filesize = 1024, fsid = {major = 0, minor = 0}, acl = 0x0, fileid = 47680710, mode = 438, numlinks = 1, owner = 65534, group = 65534, rawdev = {major = 0, minor = 0}, atime = {tv_sec = 1548784955, tv_nsec = 582000000}, creation = { tv_sec = 0, tv_nsec = 0}, ctime = {tv_sec = 1548784955, tv_nsec = 582000000}, mtime = {tv_sec = 1548784955, tv_nsec = 582000000}, chgtime = {tv_sec = 1548784955, tv_nsec = 582000000}, spaceused = 1024, change = 1548784955582, generation = 0, expire_time_attr = 60, fs_locations = 0x0} dirent = 0x5296230 has_write = true set_first_ck = false next_ck = 2419507 look_ck = 2419507 chunk = 0x156d7240 first_pass = true eod = false reload_chunk = false __func__ = "mdcache_readdir_chunked" __PRETTY_FUNCTION__ = "mdcache_readdir_chunked" (gdb) print *dirent $1 = {chunk_list = {next = 0x0, prev = 0xa1}, chunk = 0x3018770, node_name = { left = 0x7f6acfd39848 <main_arena+232>, right = 0x0, parent = 0}, node_ck = {left = 0x5296258, right = 0x0, parent = 0}, node_sorted = {left = 0xffffffff, right = 0x0, parent = 0}, ck = 0, eod = false, namehash = 8192, ckey = {hk = 1056768, fsal = 0x0, kv = {addr = 0x0, len = 134650068}}, flags = 0, name = 0xa0 <Address 0xa0 out of bounds>, name_buffer = 0x52962d8 " "} (gdb) print dirent.name $3 = 0xa0 <Address 0xa0 out of bounds> (gdb) print *0x52962d8 $4 = 32 (gdb) print dirent.name_buffer $5 = 0x52962d8 " " (gdb) print *dirent.name_buffer $6 = 32 ' ' (gdb) print *chunk $7 = {chunks = {next = 0x291a4e28, prev = 0x291a4e28}, dirents = {next = 0x2ed8c060, prev = 0x48ff2870}, parent = 0x291a4ba0, chunk_lru = {q = {next = 0x7e1c00 <CHUNK_LRU+1792>, prev = 0x4d6f5c88}, qid = LRU_ENTRY_L1, refcnt = 0, flags = 0, lane = 8, cf = 0}, reload_ck = 0, next_ck = 0, num_entries = 2500}
This is a corrupted dirent. The chunk looks okay, so it's likely not a corrupted chunk. This means the locking is likely okay... I'm not seeing anything obvious. Frank, so you see anything? On Tue, Jan 29, 2019 at 4:31 PM Rungta, Vandana <vrungta@amazon.com> wrote:
Hello,
We are seeing the following crash with NFS Ganesha 2.7.1 – we crash further in our fsal module’s lookup method trying to use the “name” which has an invalid pointer.
This has the following 3 patches applied to NFS Ganesha 2.7.1
https://github.com/nfs-ganesha/nfs-ganesha/commit/654dd706d22663c6ae6029e0c8...
https://github.com/nfs-ganesha/nfs-ganesha/commit/5dc6a70ed42275a4f6772b9802...
The most recent patch to not return dead hash entries:
https://github.com/nfs-ganesha/nfs-ganesha/commit/25320e6544f6c5a045f20c5144...
The workload:
Concurrent access from multiple threads. 1 thread continuously (in a loop) running python os.walk (i.e., readdir) of the entire filesystem, roughly ~5M files total. 5 more threads are writing a few thousand files each. When the writes complete, a single thread verifies written content, then deletes it. Then the writes repeat again.
This is the same workload that causes our OOM issue.
https://lists.nfs-ganesha.org/archives/list/devel@lists.nfs-ganesha.org/thre...
#5 0x00007f6acd6a1dca in foo_lookup (parent=0x6fe2e420, name=0xa0 <Address 0xa0 out of bounds>,
handle=0x7f6abf3255a8, attrs_out=0x7f6abf3254a0) at /opt/src/src/handle.c:364
#6 0x000000000053a7a6 in mdc_lookup_uncached (mdc_parent=0x291a4ba0, name=0xa0 <Address 0xa0 out of bounds>,
new_entry=0x7f6abf325728, attrs_out=0x0) at /src/src/FSAL/Stackable_FSALs/FSAL_MDCACHE/mdcache_helpers.c:1293
#7 0x0000000000541344 in mdcache_readdir_chunked (directory=0x291a4ba0, whence=0, dir_state=0x7f6abf325900,
cb=0x43217c <populate_dirent>, attrmask=122830, eod_met=0x7f6abf325ffb)
at /src/src/FSAL/Stackable_FSALs/FSAL_MDCACHE/mdcache_helpers.c:3065
#8 0x000000000052e8c3 in mdcache_readdir (dir_hdl=0x291a4bd8, whence=0x7f6abf3258e0, dir_state=0x7f6abf325900,
cb=0x43217c <populate_dirent>, attrmask=122830, eod_met=0x7f6abf325ffb)
at /src/src/FSAL/Stackable_FSALs/FSAL_MDCACHE/mdcache_handle.c:559
#9 0x0000000000432a76 in fsal_readdir (directory=0x291a4bd8, cookie=0, nbfound=0x7f6abf325ffc,
eod_met=0x7f6abf325ffb, attrmask=122830, cb=0x492018 <nfs3_readdirplus_callback>, opaque=0x7f6abf325fb0)
at /src/src/FSAL/fsal_helper.c:1158
#10 0x0000000000491e71 in nfs3_readdirplus (arg=0x10704818, req=0x10704110, res=0x3103f090)
at /src/src/Protocols/NFS/nfs3_readdirplus.c:310
#11 0x00000000004574d1 in nfs_rpc_process_request (reqdata=0x10704110) at /src/src/MainNFSD/nfs_worker_thread.c:1329
#12 0x0000000000457c90 in nfs_rpc_valid_NFS (req=0x10704110) at /src/src/MainNFSD/nfs_worker_thread.c:1549
#13 0x00007f6ad115ce75 in svc_vc_decode (req=0x10704110) at /src/src/libntirpc/src/svc_vc.c:825
---Type <return> to continue, or q <return> to quit---
#14 0x000000000044a688 in nfs_rpc_decode_request (xprt=0x18390200, xdrs=0x174943c0)
at /src/src/MainNFSD/nfs_rpc_dispatcher_thread.c:1341
#15 0x00007f6ad115cd86 in svc_vc_recv (xprt=0x18390200) at /src/src/libntirpc/src/svc_vc.c:798
#16 0x00007f6ad11594d3 in svc_rqst_xprt_task (wpe=0x18390418) at /src/src/libntirpc/src/svc_rqst.c:767
#17 0x00007f6ad115994d in svc_rqst_epoll_events (sr_rec=0x2779260, n_events=1)
at /src/src/libntirpc/src/svc_rqst.c:939
#18 0x00007f6ad1159be2 in svc_rqst_epoll_loop (sr_rec=0x2779260) at /src/src/libntirpc/src/svc_rqst.c:1012
#19 0x00007f6ad1159c95 in svc_rqst_run_task (wpe=0x2779260) at /src/src/libntirpc/src/svc_rqst.c:1048
#20 0x00007f6ad11625f6 in work_pool_thread (arg=0x3b5d170) at /src/src/libntirpc/src/work_pool.c:181
#21 0x00007f6ad0169de5 in start_thread () from /lib64/libpthread.so.0
#22 0x00007f6acfa71bad in clone () from /lib64/libc.so.6
(gdb) select-frame 7
(gdb) info locals
status = {major = ERR_FSAL_INVAL, minor = 0}
cb_result = DIR_CONTINUE
entry = 0x0
attrs = {request_mask = 122830, valid_mask = 1433550, supported = 1433582, type = REGULAR_FILE, filesize = 1024,
fsid = {major = 0, minor = 0}, acl = 0x0, fileid = 47680710, mode = 438, numlinks = 1, owner = 65534,
group = 65534, rawdev = {major = 0, minor = 0}, atime = {tv_sec = 1548784955, tv_nsec = 582000000}, creation = {
tv_sec = 0, tv_nsec = 0}, ctime = {tv_sec = 1548784955, tv_nsec = 582000000}, mtime = {tv_sec = 1548784955,
tv_nsec = 582000000}, chgtime = {tv_sec = 1548784955, tv_nsec = 582000000}, spaceused = 1024,
change = 1548784955582, generation = 0, expire_time_attr = 60, fs_locations = 0x0}
dirent = 0x5296230
has_write = true
set_first_ck = false
next_ck = 2419507
look_ck = 2419507
chunk = 0x156d7240
first_pass = true
eod = false
reload_chunk = false
__func__ = "mdcache_readdir_chunked"
__PRETTY_FUNCTION__ = "mdcache_readdir_chunked"
(gdb)
status = {major = ERR_FSAL_INVAL, minor = 0}
cb_result = DIR_CONTINUE
entry = 0x0
attrs = {request_mask = 122830, valid_mask = 1433550, supported = 1433582, type = REGULAR_FILE, filesize = 1024,
fsid = {major = 0, minor = 0}, acl = 0x0, fileid = 47680710, mode = 438, numlinks = 1, owner = 65534,
group = 65534, rawdev = {major = 0, minor = 0}, atime = {tv_sec = 1548784955, tv_nsec = 582000000}, creation = {
tv_sec = 0, tv_nsec = 0}, ctime = {tv_sec = 1548784955, tv_nsec = 582000000}, mtime = {tv_sec = 1548784955,
tv_nsec = 582000000}, chgtime = {tv_sec = 1548784955, tv_nsec = 582000000}, spaceused = 1024,
change = 1548784955582, generation = 0, expire_time_attr = 60, fs_locations = 0x0}
dirent = 0x5296230
has_write = true
set_first_ck = false
next_ck = 2419507
look_ck = 2419507
chunk = 0x156d7240
first_pass = true
eod = false
reload_chunk = false
__func__ = "mdcache_readdir_chunked"
__PRETTY_FUNCTION__ = "mdcache_readdir_chunked"
(gdb) print *dirent
$1 = {chunk_list = {next = 0x0, prev = 0xa1}, chunk = 0x3018770, node_name = {
left = 0x7f6acfd39848 <main_arena+232>, right = 0x0, parent = 0}, node_ck = {left = 0x5296258, right = 0x0,
parent = 0}, node_sorted = {left = 0xffffffff, right = 0x0, parent = 0}, ck = 0, eod = false, namehash = 8192,
ckey = {hk = 1056768, fsal = 0x0, kv = {addr = 0x0, len = 134650068}}, flags = 0,
name = 0xa0 <Address 0xa0 out of bounds>, name_buffer = 0x52962d8 " "}
(gdb) print dirent.name
$3 = 0xa0 <Address 0xa0 out of bounds>
(gdb) print *0x52962d8
$4 = 32
(gdb) print dirent.name_buffer
$5 = 0x52962d8 " "
(gdb) print *dirent.name_buffer
$6 = 32 ' '
(gdb) print *chunk
$7 = {chunks = {next = 0x291a4e28, prev = 0x291a4e28}, dirents = {next = 0x2ed8c060, prev = 0x48ff2870},
parent = 0x291a4ba0, chunk_lru = {q = {next = 0x7e1c00 <CHUNK_LRU+1792>, prev = 0x4d6f5c88}, qid = LRU_ENTRY_L1,
refcnt = 0, flags = 0, lane = 8, cf = 0}, reload_ck = 0, next_ck = 0, num_entries = 2500}
_______________________________________________ Devel mailing list -- devel@lists.nfs-ganesha.org To unsubscribe send an email to devel-leave@lists.nfs-ganesha.org
FYI - saw the same crash on a 2nd server (V2.7.1 with the 3 patches mentioned above applied) also. (Previous was with linux client, this with a windows client) #6 0x000000000053a7a6 in mdc_lookup_uncached (mdc_parent=0x1798b1f0, name=0xd8acb906961da655 <Address 0xd8acb906961da655 out of bounds>, new_entry=0x7f53517b8728, attrs_out=0x0) at /src/src/FSAL/Stackable_FSALs/FSAL_MDCACHE/mdcache_helpers.c:1293 #7 0x0000000000541344 in mdcache_readdir_chunked (directory=0x1798b1f0, whence=0, dir_state=0x7f53517b8900, cb=0x43217c <populate_dirent>, attrmask=122830, eod_met=0x7f53517b8ffb) at /src/src/FSAL/Stackable_FSALs/FSAL_MDCACHE/mdcache_helpers.c:3065 #8 0x000000000052e8c3 in mdcache_readdir (dir_hdl=0x1798b228, whence=0x7f53517b88e0, dir_state=0x7f53517b8900, cb=0x43217c <populate_dirent>, attrmask=122830, eod_met=0x7f53517b8ffb) at /src/src/FSAL/Stackable_FSALs/FSAL_MDCACHE/mdcache_handle.c:559 (gdb) print *dirent $2 = {chunk_list = {next = 0x0, prev = 0x21}, chunk = 0x45d8c2f0, node_name = {left = 0x45d6b4b0, right = 0x20, parent = 208}, node_ck = {left = 0x3ea029d0, right = 0x3ea02370, parent = 361214416}, node_sorted = { left = 0x3eaeaed8, right = 0x3eac72b8, parent = 425745178}, ck = 1050680912, eod = 112, namehash = 1051256690, ckey = {hk = 0, fsal = 0x0, kv = {addr = 0x0, len = 54233482}}, flags = 0, name = 0xd8acb906961da655 <Address 0xd8acb906961da655 out of bounds>, name_buffer = 0x3ea02938 "'\325\026\017\223<\202\232 \355PYS\177"} (gdb) print *chunk $3 = {chunks = {next = 0x1798b478, prev = 0x1798b478}, dirents = {next = 0x4fdc0f70, prev = 0x4fe56130}, parent = 0x1798b1f0, chunk_lru = {q = {next = 0x7e1520 <CHUNK_LRU+32>, prev = 0x4d94f7f8}, qid = LRU_ENTRY_L2, refcnt = 0, flags = 0, lane = 0, cf = 0}, reload_ck = 0, next_ck = 0, num_entries = 2500}
I have seen this crash multiple times after applying the memory fix (was seeing it before the memory fix also) One thing that is consistent is right before the crash I see that our fsal returns an error from readdir. Error 151 ERR_FSAL_STALE. I have full logs with COMPONENT_INODE_CACHE and COMPONENT_NFS_READDIR enabled for full debug. 20 minutes of log is about 50 MB compressed. 2.5 minutes of log is about 7.8MB compressed. Please let me know if you would like to see the logs and where I can upload it. Is there a potential race condition between the following paths: Path1: mdcache_populate_dir_chunk calls sub_handle->readdir() which calls lru_remove_chunk when readdir returns an error. lru_remove_chunk -> lru_clean_chunk -> mdcache_clean_dirent_chunk where it is cleaning/freeing the dirents from the chunk Path2: mdcache_readdir_chunked -> the for loop that gets the dirents for the chunk. dirent = glist_next_entry(&chunk->dirents, mdcache_dir_entry_t, chunk_list, &dirent->chunk_list) The dirent from Path2 seems to be corrupt or free when we core. Backtrace is similar to that reported earlier, except here the dirent pointer is bad. Reproducible. [Thread debugging using libthread_db enabled] Using host libthread_db library "/lib64/libthread_db.so.1". Core was generated by `bin/ganesha.nfsd -f etc/ganesha/ganesha.conf -p var/run/ganesha.pid -F'. Program terminated with signal 11, Segmentation fault. #0 0x0000000000540e42 in mdcache_readdir_chunked (directory=0x80cb4d0, whence=0, dir_state=0x7fa68be22900, cb=0x43217c <populate_dirent>, attrmask=122830, eod_met=0x7fa68be22ffb) at /src/src/FSAL/Stackable_FSALs/FSAL_MDCACHE/mdcache_helpers.c:2993 2993 /src/src/FSAL/Stackable_FSALs/FSAL_MDCACHE/mdcache_helpers.c: No such file or directory. Missing separate debuginfos, use: debuginfo-install sgw-nfs-ganesha-2.0.22.0-1.x86_64 (gdb) bt #0 0x0000000000540e42 in mdcache_readdir_chunked (directory=0x80cb4d0, whence=0, dir_state=0x7fa68be22900, cb=0x43217c <populate_dirent>, attrmask=122830, eod_met=0x7fa68be22ffb) at /src/src/FSAL/Stackable_FSALs/FSAL_MDCACHE/mdcache_helpers.c:2993 #1 0x000000000052e8c3 in mdcache_readdir (dir_hdl=0x80cb508, whence=0x7fa68be228e0, dir_state=0x7fa68be22900, cb=0x43217c <populate_dirent>, attrmask=122830, eod_met=0x7fa68be22ffb) at /src/src/FSAL/Stackable_FSALs/FSAL_MDCACHE/mdcache_handle.c:559 #2 0x0000000000432a76 in fsal_readdir (directory=0x80cb508, cookie=0, nbfound=0x7fa68be22ffc, eod_met=0x7fa68be22ffb, attrmask=122830, cb=0x492018 <nfs3_readdirplus_callback>, opaque=0x7fa68be22fb0) at /src/src/FSAL/fsal_helper.c:1158 #3 0x0000000000491e71 in nfs3_readdirplus (arg=0x37200f38, req=0x37200830, res=0x38040410) at /src/src/Protocols/NFS/nfs3_readdirplus.c:310 #4 0x00000000004574d1 in nfs_rpc_process_request (reqdata=0x37200830) at /src/src/MainNFSD/nfs_worker_thread.c:1329 #5 0x0000000000457c90 in nfs_rpc_valid_NFS (req=0x37200830) at /src/src/MainNFSD/nfs_worker_thread.c:1549 #6 0x00007fa693fdbe75 in svc_vc_decode (req=0x37200830) at /src/src/libntirpc/src/svc_vc.c:825 #7 0x000000000044a688 in nfs_rpc_decode_request (xprt=0xaa7ce0, xdrs=0x39c31170) at /src/src/MainNFSD/nfs_rpc_dispatcher_thread.c:1341 #8 0x00007fa693fdbd86 in svc_vc_recv (xprt=0xaa7ce0) at /src/src/libntirpc/src/svc_vc.c:798 #9 0x00007fa693fd84d3 in svc_rqst_xprt_task (wpe=0xaa7ef8) at /src/src/libntirpc/src/svc_rqst.c:767 #10 0x00007fa693fd894d in svc_rqst_epoll_events (sr_rec=0xa88260, n_events=1) at /src/src/libntirpc/src/svc_rqst.c:939 #11 0x00007fa693fd8be2 in svc_rqst_epoll_loop (sr_rec=0xa88260) at /src/src/libntirpc/src/svc_rqst.c:1012 #12 0x00007fa693fd8c95 in svc_rqst_run_task (wpe=0xa88260) at /src/src/libntirpc/src/svc_rqst.c:1048 #13 0x00007fa693fe15f6 in work_pool_thread (arg=0x679a6bd0) at /src/src/libntirpc/src/work_pool.c:181 #14 0x00007fa692fe8de5 in start_thread () from /lib64/libpthread.so.0 #15 0x00007fa6928f0bad in clone () from /lib64/libc.so.6 (gdb) print dirent $1 = (mdcache_dir_entry_t *) 0x594f20325e0a0d33 (gdb) print *dirent Cannot access memory at address 0x594f20325e0a0d33 (gdb) info locals status = {major = ERR_FSAL_NO_ERROR, minor = 0} cb_result = DIR_CONTINUE entry = 0x0 attrs = {request_mask = 122830, valid_mask = 1433550, supported = 1433582, type = REGULAR_FILE, filesize = 1024, fsid = {major = 0, minor = 0}, acl = 0x0, fileid = 12545799, mode = 438, numlinks = 1, owner = 65534, group = 65534, rawdev = {major = 0, minor = 0}, atime = {tv_sec = 1549408822, tv_nsec = 147000000}, creation = {tv_sec = 0, tv_nsec = 0}, ctime = {tv_sec = 1549408822, tv_nsec = 147000000}, mtime = {tv_sec = 1549408822, tv_nsec = 147000000}, chgtime = {tv_sec = 1549408822, tv_nsec = 147000000}, spaceused = 1024, change = 1549408822147, generation = 0, expire_time_attr = 60, fs_locations = 0x0} dirent = 0x594f20325e0a0d33 has_write = true set_first_ck = false next_ck = 1830007 look_ck = 1830007 chunk = 0x6f70300 first_pass = true eod = false reload_chunk = false __func__ = "mdcache_readdir_chunked" __PRETTY_FUNCTION__ = "mdcache_readdir_chunked" (gdb) info args directory = 0x80cb4d0 whence = 0 dir_state = 0x7fa68be22900 cb = 0x43217c <populate_dirent> attrmask = 122830 eod_met = 0x7fa68be22ffb (gdb) Different Backtrace -- with name being bad #5 0x00007fbb08ab9c97 in foo_lookup (parent=0x38001a80, name=0xb707a0 <Address 0xb707a0 out of bounds>, handle=0x7fbb071045a8, attrs_out=0x7fbb071044a0) at /opt/src/src/handle.c:348 #6 0x000000000053a7a6 in mdc_lookup_uncached (mdc_parent=0x20bb8e00, name=0xb707a0 <Address 0xb707a0 out of bounds>, new_entry=0x7fbb07104728, attrs_out=0x0) at /src/src/FSAL/Stackable_FSALs/FSAL_MDCACHE/mdcache_helpers.c:1293 #7 0x0000000000541344 in mdcache_readdir_chunked (directory=0x20bb8e00, whence=0, dir_state=0x7fbb07104900, cb=0x43217c <populate_dirent>, attrmask=122830, eod_met=0x7fbb07104ffb) at /src/src/FSAL/Stackable_FSALs/FSAL_MDCACHE/mdcache_helpers.c:3065 #8 0x000000000052e8c3 in mdcache_readdir (dir_hdl=0x20bb8e38, whence=0x7fbb071048e0, dir_state=0x7fbb07104900, cb=0x43217c <populate_dirent>, attrmask=122830, eod_met=0x7fbb07104ffb) at /src/src/FSAL/Stackable_FSALs/FSAL_MDCACHE/mdcache_handle.c:559 #9 0x0000000000432a76 in fsal_readdir (directory=0x20bb8e38, cookie=0, nbfound=0x7fbb07104ffc, eod_met=0x7fbb07104ffb, attrmask=122830, cb=0x492018 <nfs3_readdirplus_callback>, opaque=0x7fbb07104fb0) at /src/src/FSAL/fsal_helper.c:1158 #10 0x0000000000491e71 in nfs3_readdirplus (arg=0x1acd5b68, req=0x1acd5460, res=0x3f538be0) at /src/src/Protocols/NFS/nfs3_readdirplus.c:310 #11 0x00000000004574d1 in nfs_rpc_process_request (reqdata=0x1acd5460) at /src/src/MainNFSD/nfs_worker_thread.c:1329
From the log right before the crash: Searching for directory and chunk Tue Feb 05 23:20:17 2019 UTC 24320[::ffff:10.0.136.88] [svc_33] /src/src/FSAL/Stackable_FSALs/FSAL_MDCACHE/mdcache_helpers.c:930 :mdcache_find_keyed_reason :INODE :F_DBG :Found entry 0x80cb4d0 Tue Feb 05 23:20:17 2019 UTC 24320[::ffff:10.0.136.88] [svc_56] /src/src/FSAL/Stackable_FSALs/FSAL_MDCACHE/mdcache_helpers.c:930 :mdcache_find_keyed_reason :INODE :F_DBG :Found entry 0x80cb4d0 Tue Feb 05 23:20:17 2019 UTC 24320[::ffff:10.0.136.88] [svc_56] /src/src/FSAL/Stackable_FSALs/FSAL_MDCACHE/mdcache_helpers.c:1150 :mdc_lookup :NFS READDIR :F_DBG :NFS READDIR: FULLDEBUG: Lookup parent (..) of 0x80cb4d0 Tue Feb 05 23:20:17 2019 UTC 24320[::ffff:10.0.136.88] [svc_56] /src/src/FSAL/Stackable_FSALs/FSAL_MDCACHE/mdcache_helpers.c:2778 :mdcache_readdir_chunked :NFS READDIR :F_DBG :NFS READDIR: FULLDEBUG: Starting chunked READDIR for 0x80cb4d0, MDCACHE_TRUST_CONTENT true, MDCACHE_TRUST_DIR_CHUNKS true Tue Feb 05 23:20:17 2019 UTC 24320[::ffff:10.0.136.88] [svc_56] /src/src/FSAL/Stackable_FSALs/FSAL_MDCACHE/mdcache_helpers.c:2969 :mdcache_readdir_chunked :NFS READDIR :F_DBG :NFS READDIR: FULLDEBUG: found dirent in cached chunk 0x6f70300 dirent 0x39c62a80 key-file-5m-0 Tue Feb 05 23:20:17 2019 UTC 24320[::ffff:10.0.136.88] [svc_56] /src/src/FSAL/Stackable_FSALs/FSAL_MDCACHE/mdcache_helpers.c:2977 :mdcache_readdir_chunked :NFS READDIR :F_DBG :NFS READDIR: FULLDEBUG: About to read directory=0x80cb4d0 cookie=0 Tue Feb 05 23:20:17 2019 UTC 24320[::ffff:10.0.136.88] [svc_56] /src/src/FSAL/Stackable_FSALs/FSAL_MDCACHE/mdcache_helpers.c:2969 :mdcache_readdir_chunked :NFS READDIR :F_DBG :NFS READDIR: FULLDEBUG: found dirent in cached chunk 0x6f70300 dirent 0x39c62a80 key-file-5m-0 Tue Feb 05 23:20:17 2019 UTC 24320[::ffff:10.0.136.88] [svc_56] /src/src/FSAL/Stackable_FSALs/FSAL_MDCACHE/mdcache_helpers.c:2977 :mdcache_readdir_chunked :NFS READDIR :F_DBG :NFS READDIR: FULLDEBUG: About to read directory=0x80cb4d0 cookie=0 Tue Feb 05 23:20:24 2019 UTC 24320[::ffff:10.0.136.88] [svc_56] /src/src/FSAL/Stackable_FSALs/FSAL_MDCACHE/mdcache_avl.c:381 :mdcache_avl_insert :NFS READDIR :DEBUG :NFS READDIR: DEBUG: Already existent when inserting new dirent on entry=0x80cb4d0 name=key-file-5m-0 Tue Feb 05 23:20:24 2019 UTC 24320[::ffff:10.0.136.88] [svc_56] /src/src/FSAL/Stackable_FSALs/FSAL_MDCACHE/mdcache_avl.c:245 :mdcache_avl_remove :NFS READDIR :F_DBG :NFS READDIR: FULLDEBUG: Just freed dirent 0x39c62a80 from chunk 0x6f70300 parent 0x80cb4d0 Tue Feb 05 23:20:24 2019 UTC 24320[::ffff:10.0.136.88] [svc_56] /src/src/FSAL/Stackable_FSALs/FSAL_MDCACHE/mdcache_helpers.c:1702 :place_new_dirent :NFS READDIR :F_DBG :NFS READDIR: FULLDEBUG: Could not add key-file-5m-0 to chunk for directory 0x80cb4d0, compute_readdir_cookie failed Tue Feb 05 23:20:24 2019 UTC 24320[::ffff:10.0.136.88] [svc_56] /src/src/FSAL/Stackable_FSALs/FSAL_MDCACHE/mdcache_helpers.c:2049 :place_new_dirent :NFS READDIR :F_DBG :NFS READDIR: FULLDEBUG: Entry 0x80cb4d0 clearing MDCACHE_DIR_POPULATED, MDCACHE_TRUST_DIR_CHUNKS
Maybe this piece of the log maybe more useful: 0x39c62a80 is freed, but mdcache_readdir_chunked still has a pointer to it? Tue Feb 05 23:20:17 2019 UTC 24320[::ffff:10.0.136.88] [svc_56] /src/src/Protocols/NFS/nfs3_readdirplus.c:151 :nfs3_readdirplus :NFS READDIR :DEBUG :NFS READDIR: DEBUG: REQUEST PROCESSING: Calling NFS3_READDIRPLUS handle: File Handle V3: Len=16 430000010a5c00000000000000010000 Tue Feb 05 23:20:17 2019 UTC 24320[::ffff:10.0.136.88] [svc_56] /src/src/Protocols/NFS/nfs3_readdirplus.c:183 :nfs3_readdirplus :NFS READDIR :DEBUG :NFS3_READDIRPLUS: dircount=16384 begin_cookie=0 estimated_num_entries=50, mem_left=14625 Tue Feb 05 23:20:17 2019 UTC 24320[::ffff:10.0.136.88] [svc_56] /src/src/FSAL/Stackable_FSALs/FSAL_MDCACHE/mdcache_helpers.c:892 :mdcache_find_keyed_reason :INODE :F_DBG :Looking for hk=cb4fc9bfcd8aca61 fsal=0x7fa690762d20 key=0x5c000000000000000100 Tue Feb 05 23:20:17 2019 UTC 24320[::ffff:10.0.136.88] [svc_56] /src/src/FSAL/Stackable_FSALs/FSAL_MDCACHE/mdcache_helpers.c:930 :mdcache_find_keyed_reason :INODE :F_DBG :Found entry 0x80cb4d0 Tue Feb 05 23:20:17 2019 UTC 24320[::ffff:10.0.136.88] [svc_56] /src/src/FSAL/Stackable_FSALs/FSAL_MDCACHE/mdcache_handle.c:927 :mdcache_getattrs :INODE :F_DBG :attrs obj attributes Request Mask=0001dfce Valid Mask=0015dfce Supported Mask=0015dfee DIRECTORY numlinks=0x1 size=0x0 mode=0777 owner=0xfffe group=0xfffe atime=Tue Feb 05 09:58:19 2019 UTC mtime=Tue Feb 05 09:58:19 2019 UTC Tue Feb 05 23:20:17 2019 UTC 24320[::ffff:10.0.136.88] [svc_56] /src/src/Protocols/NFS/nfs3_readdirplus.c:436 :nfs3_readdirplus_callback :NFS READDIR :DEBUG :Callback for . cookie 1 Tue Feb 05 23:20:17 2019 UTC 24320[::ffff:10.0.136.88] [svc_56] /src/src/FSAL/Stackable_FSALs/FSAL_MDCACHE/mdcache_helpers.c:1140 :mdc_lookup :NFS READDIR :F_DBG :NFS READDIR: FULLDEBUG: Lookup .. Tue Feb 05 23:20:17 2019 UTC 24320[::ffff:10.0.136.88] [svc_56] /src/src/FSAL/Stackable_FSALs/FSAL_MDCACHE/mdcache_helpers.c:1150 :mdc_lookup :NFS READDIR :F_DBG :NFS READDIR: FULLDEBUG: Lookup parent (..) of 0x80cb4d0 Tue Feb 05 23:20:17 2019 UTC 24320[::ffff:10.0.136.88] [svc_56] /src/src/FSAL/Stackable_FSALs/FSAL_MDCACHE/mdcache_helpers.c:892 :mdcache_find_keyed_reason :INODE :F_DBG :Looking for hk=bdca7caa2ce92921 fsal=0x7fa690762d20 key=0x02000000000000000100 Tue Feb 05 23:20:17 2019 UTC 24320[::ffff:10.0.136.88] [svc_56] /src/src/FSAL/Stackable_FSALs/FSAL_MDCACHE/mdcache_helpers.c:930 :mdcache_find_keyed_reason :INODE :F_DBG :Found entry 0xab4200 Tue Feb 05 23:20:17 2019 UTC 24320[::ffff:10.0.136.88] [svc_56] /src/src/FSAL/Stackable_FSALs/FSAL_MDCACHE/mdcache_handle.c:927 :mdcache_getattrs :INODE :F_DBG :attrs obj attributes Request Mask=0001dfce Valid Mask=0015dfce Supported Mask=0015dfee DIRECTORY numlinks=0x1 size=0x0 mode=0777 owner=0xfffe group=0xfffe atime=Tue Feb 05 09:56:32 2019 UTC mtime=Tue Feb 05 09:56:32 2019 UTC Tue Feb 05 23:20:17 2019 UTC 24320[::ffff:10.0.136.88] [svc_56] /src/src/Protocols/NFS/nfs3_readdirplus.c:436 :nfs3_readdirplus_callback :NFS READDIR :DEBUG :Callback for .. cookie 2 Tue Feb 05 23:20:17 2019 UTC 24320[::ffff:10.0.136.88] [svc_56] /src/src/Protocols/NFS/nfs3_readdirplus.c:307 :nfs3_readdirplus :NFS READDIR :DEBUG :Readdirplus3 -> Call to fsal_readdir, cookie=0 Tue Feb 05 23:20:17 2019 UTC 24320[::ffff:10.0.136.88] [svc_56] /src/src/FSAL/Stackable_FSALs/FSAL_MDCACHE/mdcache_handle.c:853 :mdcache_refresh_attrs :INODE :F_DBG :attrs obj attributes Request Mask=0015dfee Valid Mask=0015dfce Supported Mask=0015dfee DIRECTORY numlinks=0x1 size=0x0 mode=0777 owner=0xfffe group=0xfffe atime=Tue Feb 05 09:58:19 2019 UTC mtime=Tue Feb 05 09:58:19 2019 UTC Tue Feb 05 23:20:17 2019 UTC 24320[::ffff:10.0.136.88] [svc_56] /src/src/FSAL/Stackable_FSALs/FSAL_MDCACHE/mdcache_handle.c:927 :mdcache_getattrs :INODE :F_DBG :attrs obj attributes Request Mask=000006a0 Valid Mask=0015dfce Supported Mask=0015dfee DIRECTORY numlinks=0x1 size=0x0 mode=0777 owner=0xfffe group=0xfffe atime=Tue Feb 05 09:58:19 2019 UTC mtime=Tue Feb 05 09:58:19 2019 UTC Tue Feb 05 23:20:17 2019 UTC 24320[::ffff:10.0.136.88] [svc_56] /src/src/FSAL/Stackable_FSALs/FSAL_MDCACHE/mdcache_handle.c:927 :mdcache_getattrs :INODE :F_DBG :attrs obj attributes Request Mask=000006a0 Valid Mask=0015dfce Supported Mask=0015dfee DIRECTORY numlinks=0x1 size=0x0 mode=0777 owner=0xfffe group=0xfffe atime=Tue Feb 05 09:58:19 2019 UTC mtime=Tue Feb 05 09:58:19 2019 UTC Tue Feb 05 23:20:17 2019 UTC 24320[::ffff:10.0.136.88] [svc_56] /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 Tue Feb 05 23:20:17 2019 UTC 24320[::ffff:10.0.136.88] [svc_56] /src/src/FSAL/Stackable_FSALs/FSAL_MDCACHE/mdcache_helpers.c:2778 :mdcache_readdir_chunked :NFS READDIR :F_DBG :NFS READDIR: FULLDEBUG: Starting chunked READDIR for 0x80cb4d0, MDCACHE_TRUST_CONTENT true, MDCACHE_TRUST_DIR_CHUNKS true Tue Feb 05 23:20:17 2019 UTC 24320[::ffff:10.0.136.88] [svc_56] /src/src/FSAL/Stackable_FSALs/FSAL_MDCACHE/mdcache_helpers.c:2812 :mdcache_readdir_chunked :NFS READDIR :F_DBG :NFS READDIR: FULLDEBUG: Readdir chunked next_ck=0x0 look_ck=1bec77 Tue Feb 05 23:20:17 2019 UTC 24320[::ffff:10.0.136.88] [svc_56] /src/src/FSAL/Stackable_FSALs/FSAL_MDCACHE/mdcache_helpers.c:2969 :mdcache_readdir_chunked :NFS READDIR :F_DBG :NFS READDIR: FULLDEBUG: found dirent in cached chunk 0x6f70300 dirent 0x39c62a80 key-file-5m-0 Tue Feb 05 23:20:17 2019 UTC 24320[::ffff:10.0.136.88] [svc_56] /src/src/FSAL/Stackable_FSALs/FSAL_MDCACHE/mdcache_helpers.c:2977 :mdcache_readdir_chunked :NFS READDIR :F_DBG :NFS READDIR: FULLDEBUG: About to read directory=0x80cb4d0 cookie=0 Tue Feb 05 23:20:17 2019 UTC 24320[::ffff:10.0.136.88] [svc_56] /src/src/FSAL/Stackable_FSALs/FSAL_MDCACHE/mdcache_helpers.c:892 :mdcache_find_keyed_reason :INODE :F_DBG :Looking for hk=39db57ea4d9d4b74 fsal=0x7fa690762d20 key=0x74ec1b00000000000100 Tue Feb 05 23:20:17 2019 UTC 24320[::ffff:10.0.136.88] [svc_56] /src/src/FSAL/Stackable_FSALs/FSAL_MDCACHE/mdcache_helpers.c:3007 :mdcache_readdir_chunked :NFS READDIR :F_DBG :NFS READDIR: FULLDEBUG: Lookup by key for key-file-5m-0 failed, lookup by name now Tue Feb 05 23:20:17 2019 UTC 24320[::ffff:10.0.136.88] [svc_56] /src/src/FSAL/Stackable_FSALs/FSAL_MDCACHE/mdcache_helpers.c:2812 :mdcache_readdir_chunked :NFS READDIR :F_DBG :NFS READDIR: FULLDEBUG: Readdir chunked next_ck=0x0 look_ck=1bec77 Tue Feb 05 23:20:17 2019 UTC 24320[::ffff:10.0.136.88] [svc_56] /src/src/FSAL/Stackable_FSALs/FSAL_MDCACHE/mdcache_helpers.c:2969 :mdcache_readdir_chunked :NFS READDIR :F_DBG :NFS READDIR: FULLDEBUG: found dirent in cached chunk 0x6f70300 dirent 0x39c62a80 key-file-5m-0 Tue Feb 05 23:20:17 2019 UTC 24320[::ffff:10.0.136.88] [svc_56] /src/src/FSAL/Stackable_FSALs/FSAL_MDCACHE/mdcache_helpers.c:2977 :mdcache_readdir_chunked :NFS READDIR :F_DBG :NFS READDIR: FULLDEBUG: About to read directory=0x80cb4d0 cookie=0 Tue Feb 05 23:20:17 2019 UTC 24320[::ffff:10.0.136.88] [svc_56] /src/src/FSAL/Stackable_FSALs/FSAL_MDCACHE/mdcache_helpers.c:892 :mdcache_find_keyed_reason :INODE :F_DBG :Looking for hk=39db57ea4d9d4b74 fsal=0x7fa690762d20 key=0x74ec1b00000000000100 Tue Feb 05 23:20:17 2019 UTC 24320[::ffff:10.0.136.88] [svc_56] /src/src/FSAL/Stackable_FSALs/FSAL_MDCACHE/mdcache_helpers.c:3007 :mdcache_readdir_chunked :NFS READDIR :F_DBG :NFS READDIR: FULLDEBUG: Lookup by key for key-file-5m-0 failed, lookup by name now Tue Feb 05 23:20:24 2019 UTC 24320[::ffff:10.0.136.88] [svc_56] /src/src/FSAL/Stackable_FSALs/FSAL_MDCACHE/mdcache_helpers.c:892 :mdcache_find_keyed_reason :INODE :F_DBG :Looking for hk=3d259480a5e679c3 fsal=0x7fa690762d20 key=0x076fbf00000000000100 Tue Feb 05 23:20:24 2019 UTC 24320[::ffff:10.0.136.88] [svc_56] /src/src/FSAL/Stackable_FSALs/FSAL_MDCACHE/mdcache_lru.c:558 :mdcache_lru_clean :INODE :F_DBG :Trusting op_ctx export id 1 Tue Feb 05 23:20:24 2019 UTC 24320[::ffff:10.0.136.88] [svc_56] /src/src/FSAL/Stackable_FSALs/FSAL_MDCACHE/mdcache_helpers.c:662 :mdcache_new_entry :INODE :DEBUG :Adding a REGULAR_FILE, entry=0x1d6b4a10 Tue Feb 05 23:20:24 2019 UTC 24320[::ffff:10.0.136.88] [svc_56] /src/src/FSAL/Stackable_FSALs/FSAL_MDCACHE/mdcache_helpers.c:757 :mdcache_new_entry :INODE :F_DBG :New entry 0x1d6b4a10 added with fh_hk.key hk=3d259480a5e679c3 fsal=0x7fa690762d20 key=0x076fbf00000000000100 Tue Feb 05 23:20:24 2019 UTC 24320[::ffff:10.0.136.88] [svc_56] /src/src/FSAL/Stackable_FSALs/FSAL_MDCACHE/mdcache_handle.c:112 :mdcache_alloc_and_check_handle :INODE :F_DBG :lookup Created entry 0x1d6b4a10 FSAL FOO for key-file-5m-0 Tue Feb 05 23:20:24 2019 UTC 24320[::ffff:10.0.136.88] [svc_56] /src/src/FSAL/Stackable_FSALs/FSAL_MDCACHE/mdcache_helpers.c:1446 :mdcache_dirent_add :INODE :F_DBG :Add dir entry key-file-5m-0 Tue Feb 05 23:20:24 2019 UTC 24320[::ffff:10.0.136.88] [svc_56] /src/src/FSAL/Stackable_FSALs/FSAL_MDCACHE/mdcache_avl.c:323 :mdcache_avl_insert :NFS READDIR :F_DBG :NFS READDIR: FULLDEBUG: Insert dir entry 0x39cec330 key-file-5m-0 Tue Feb 05 23:20:24 2019 UTC 24320[::ffff:10.0.136.88] [svc_56] /src/src/FSAL/Stackable_FSALs/FSAL_MDCACHE/mdcache_avl.c:381 :mdcache_avl_insert :NFS READDIR :DEBUG :NFS READDIR: DEBUG: Already existent when inserting new dirent on entry=0x80cb4d0 name=key-file-5m-0 Tue Feb 05 23:20:24 2019 UTC 24320[::ffff:10.0.136.88] [svc_56] /src/src/FSAL/Stackable_FSALs/FSAL_MDCACHE/mdcache_avl.c:402 :mdcache_avl_insert :NFS READDIR :F_DBG :NFS READDIR: FULLDEBUG: Keys for key-file-5m-0 don't match v=hk=3d259480a5e679c3 fsal=0x7fa690762d20 key=0x076fbf00000000000100 v2=hk=39db57ea4d9d4b74 fsal=0x7fa690762d20 key=0x74ec1b00000000000100 Tue Feb 05 23:20:24 2019 UTC 24320[::ffff:10.0.136.88] [svc_56] /src/src/FSAL/Stackable_FSALs/FSAL_MDCACHE/mdcache_avl.c:167 :unchunk_dirent :NFS READDIR :F_DBG :NFS READDIR: FULLDEBUG: Unchunking 0x39c62a80 key-file-5m-0 Tue Feb 05 23:20:24 2019 UTC 24320[::ffff:10.0.136.88] [svc_56] /src/src/FSAL/Stackable_FSALs/FSAL_MDCACHE/mdcache_avl.c:245 :mdcache_avl_remove :NFS READDIR :F_DBG :NFS READDIR: FULLDEBUG: Just freed dirent 0x39c62a80 from chunk 0x6f70300 parent 0x80cb4d0 Tue Feb 05 23:20:24 2019 UTC 24320[::ffff:10.0.136.88] [svc_56] /src/src/FSAL/Stackable_FSALs/FSAL_MDCACHE/mdcache_avl.c:369 :mdcache_avl_insert :NFS READDIR :F_DBG :NFS READDIR: FULLDEBUG: Inserted dirent key-file-5m-0 with ckey hk=3d259480a5e679c3 fsal=0x7fa690762d20 key=0x076fbf00000000000100 Tue Feb 05 23:20:24 2019 UTC 24320[::ffff:10.0.136.88] [svc_56] /src/src/FSAL/Stackable_FSALs/FSAL_MDCACHE/mdcache_helpers.c:1702 :place_new_dirent :NFS READDIR :F_DBG :NFS READDIR: FULLDEBUG: Could not add key-file-5m-0 to chunk for directory 0x80cb4d0, compute_readdir_cookie failed Tue Feb 05 23:20:24 2019 UTC 24320[::ffff:10.0.136.88] [svc_56] /src/src/FSAL/Stackable_FSALs/FSAL_MDCACHE/mdcache_helpers.c:2049 :place_new_dirent :NFS READDIR :F_DBG :NFS READDIR: FULLDEBUG: Entry 0x80cb4d0 clearing MDCACHE_DIR_POPULATED, MDCACHE_TRUST_DIR_CHUNKS Tue Feb 05 23:20:24 2019 UTC 24320[::ffff:10.0.136.88] [svc_56] /src/src/FSAL/Stackable_FSALs/FSAL_MDCACHE/mdcache_helpers.c:3112 :mdcache_readdir_chunked :NFS READDIR :F_DBG :NFS READDIR: FULLDEBUG: Setting next_ck=1bec77 Tue Feb 05 23:20:24 2019 UTC 24320[::ffff:10.0.136.88] [svc_56] /src/src/FSAL/Stackable_FSALs/FSAL_MDCACHE/mdcache_handle.c:927 :mdcache_getattrs :INODE :F_DBG :attrs obj attributes Request Mask=0001dfce Valid Mask=0015dfce Supported Mask=0015dfee REGULAR_FILE numlinks=0x1 size=0x400 mode=0666 owner=0xfffe group=0xfffe atime=Tue Feb 05 23:20:22 2019 UTC mtime=Tue Feb 05 23:20:22 2019 UTC Tue Feb 05 23:20:24 2019 UTC 24320[::ffff:10.0.136.88] [svc_56] /src/src/Protocols/NFS/nfs3_readdirplus.c:436 :nfs3_readdirplus_callback :NFS READDIR :DEBUG :Callback for key-file-5m-0 cookie 1830007 Tue Feb 05 23:20:24 2019 UTC 24320[::ffff:10.0.136.88] [svc_56] /src/src/FSAL/Stackable_FSALs/FSAL_MDCACHE/mdcache_helpers.c:3151 :mdcache_readdir_chunked :NFS READDIR :F_DBG :NFS READDIR: FULLDEBUG: dirent = 0x39c62a80 key-file-5m-0, cb_result = DIR_CONTINUE, eod = false
I think the issue is that dirent pointer can be freed in mdc_lookup_uncached (when there is an existing non-matching stale entry ) , making the local dirent pointer in mdc_readdir_chunked stale. Further distillation of the logs above: nfs3_readdirplus.c:307 :nfs3_readdirplus :NFS READDIR :DEBUG :Readdirplus3 -> Call to fsal_readdir, cookie=0 Readdir for directory -- 0x80cb4d0 mdcache_handle.c:557 :mdcache_readdir :NFS READDIR :DEBUG :NFS READDIR: DEBUG: Calling mdcache_readdir_chunked whence=0 mdcache_helpers.c:2778 :mdcache_readdir_chunked :NFS READDIR :F_DBG :NFS READDIR: FULLDEBUG: Starting chunked READDIR for 0x80cb4d0, MDCACHE_TRUST_CONTENT true, MDCACHE_TRUST_DIR_CHUNKS true mdcache_helpers.c:2812 :mdcache_readdir_chunked :NFS READDIR :F_DBG :NFS READDIR: FULLDEBUG: Readdir chunked next_ck=0x0 look_ck=1bec77 Found the dirent 0x39c62a80 in cache for the first file in the 0x80cb4d0 -- key-file-5m-0 mdcache_helpers.c:2969 :mdcache_readdir_chunked :NFS READDIR :F_DBG :NFS READDIR: FULLDEBUG: found dirent in cached chunk 0x6f70300 dirent 0x39c62a80 key-file-5m-0 mdcache_helpers.c:2977 :mdcache_readdir_chunked :NFS READDIR :F_DBG :NFS READDIR: FULLDEBUG: About to read directory=0x80cb4d0 cookie=0 Find the real entry using lookup by key mdcache_helpers.c:892 :mdcache_find_keyed_reason :INODE :F_DBG :Looking for hk=39db57ea4d9d4b74 fsal=0x7fa690762d20 key=0x74ec1b00000000000100 mdcache_helpers.c:3007 :mdcache_readdir_chunked :NFS READDIR :F_DBG :NFS READDIR: FULLDEBUG: Lookup by key for key-file-5m-0 failed, lookup by name now mdcache_helpers.c:2812 :mdcache_readdir_chunked :NFS READDIR :F_DBG :NFS READDIR: FULLDEBUG: Readdir chunked next_ck=0x0 look_ck=1bec77 mdcache_helpers.c:2969 :mdcache_readdir_chunked :NFS READDIR :F_DBG :NFS READDIR: FULLDEBUG: found dirent in cached chunk 0x6f70300 dirent 0x39c62a80 key-file-5m-0 mdcache_helpers.c:2977 :mdcache_readdir_chunked :NFS READDIR :F_DBG :NFS READDIR: FULLDEBUG: About to read directory=0x80cb4d0 cookie=0 mdcache_helpers.c:892 :mdcache_find_keyed_reason :INODE :F_DBG :Looking for hk=39db57ea4d9d4b74 fsal=0x7fa690762d20 key=0x74ec1b00000000000100 mdcache_helpers.c:3007 :mdcache_readdir_chunked :NFS READDIR :F_DBG :NFS READDIR: FULLDEBUG: Lookup by key for key-file-5m-0 failed, lookup by name now mdcache_helpers.c:892 :mdcache_find_keyed_reason :INODE :F_DBG :Looking for hk=3d259480a5e679c3 fsal=0x7fa690762d20 key=0x076fbf00000000000100 Lookup by dirent->key failed for the actual entry. Call mdc_lookup_uncached to lookup by name -- key-file-5m-0 mdcache_lru.c:558 :mdcache_lru_clean :INODE :F_DBG :Trusting op_ctx export id 1 mdcache_helpers.c:662 :mdcache_new_entry :INODE :DEBUG :Adding a REGULAR_FILE, entry=0x1d6b4a10 mdcache_helpers.c:757 :mdcache_new_entry :INODE :F_DBG :New entry 0x1d6b4a10 added with fh_hk.key hk=3d259480a5e679c3 fsal=0x7fa690762d20 key=0x076fbf00000000000100 mdcache_handle.c:112 :mdcache_alloc_and_check_handle :INODE :F_DBG :lookup Created entry 0x1d6b4a10 FSAL FOO for key-file-5m-0 mdcache_helpers.c:1446 :mdcache_dirent_add :INODE :F_DBG :Add dir entry key-file-5m-0 mdcache_avl.c:323 :mdcache_avl_insert :NFS READDIR :F_DBG :NFS READDIR: FULLDEBUG: Insert dir entry 0x39cec330 key-file-5m-0 mdcache_avl.c:381 :mdcache_avl_insert :NFS READDIR :DEBUG :NFS READDIR: DEBUG: Already existent when inserting new dirent on entry=0x80cb4d0 name=key-file-5m-0 New entry created 0x1d6b4a10, new dir entry: 0x39cec330 key-file-5m-0 mdcache_avl.c:402 :mdcache_avl_insert :NFS READDIR :F_DBG :NFS READDIR: FULLDEBUG: Keys for key-file-5m-0 don't match v=hk=3d259480a5e679c3 fsal=0x7fa690762d20 key=0x076fbf00000000000100 v2=hk=39db57ea4d9d4b74 fsal=0x7fa690762d20 key=0x74ec1b00000000000100 mdcache_avl.c:167 :unchunk_dirent :NFS READDIR :F_DBG :NFS READDIR: FULLDEBUG: Unchunking 0x39c62a80 key-file-5m-0 mdcache_avl.c:245 :mdcache_avl_remove :NFS READDIR :F_DBG :NFS READDIR: FULLDEBUG: Just freed dirent 0x39c62a80 from chunk 0x6f70300 parent 0x80cb4d0 mdcache_avl.c:369 :mdcache_avl_insert :NFS READDIR :F_DBG :NFS READDIR: FULLDEBUG: Inserted dirent key-file-5m-0 with ckey hk=3d259480a5e679c3 fsal=0x7fa690762d20 key=0x076fbf00000000000100 dirent 0x39c62a80 freed, new 0x39cec330 added mdcache_helpers.c:1702 :place_new_dirent :NFS READDIR :F_DBG :NFS READDIR: FULLDEBUG: Could not add key-file-5m-0 to chunk for directory 0x80cb4d0, compute_readdir_cookie failed mdcache_helpers.c:2049 :place_new_dirent :NFS READDIR :F_DBG :NFS READDIR: FULLDEBUG: Entry 0x80cb4d0 clearing MDCACHE_DIR_POPULATED, MDCACHE_TRUST_DIR_CHUNKS Back to readdir_chunked -- local dirent pointer still is 0x39c62a80, but it has been freed from the chunk. mdcache_helpers.c:3112 :mdcache_readdir_chunked :NFS READDIR :F_DBG :NFS READDIR: FULLDEBUG: Setting next_ck=1bec77 nfs3_readdirplus.c:436 :nfs3_readdirplus_callback :NFS READDIR :DEBUG :Callback for key-file-5m-0 cookie 1830007 mdcache_helpers.c:3151 :mdcache_readdir_chunked :NFS READDIR :F_DBG :NFS READDIR: FULLDEBUG: dirent = 0x39c62a80 key-file-5m-0, cb_result = DIR_CONTINUE, eod = false
participants (3)
-
Daniel Gryniewicz -
Rungta, Vandana -
vrungta＠amazon.com