3:21 p.m.
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/654dd706d22663c6ae6029e...
https://github.com/nfs-ganesha/nfs-ganesha/commit/5dc6a70ed42275a4f6772b9...
The most recent patch to not return dead hash entries:
https://github.com/nfs-ganesha/nfs-ganesha/commit/25320e6544f6c5a045f20c5...
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/t...
#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}
8:31 a.m.
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(a)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/654dd706d22663c6ae6029e...
>
>
>
>
https://github.com/nfs-ganesha/nfs-ganesha/commit/5dc6a70ed42275a4f6772b9...
>
>
>
> The most recent patch to not return dead hash entries:
>
>
https://github.com/nfs-ganesha/nfs-ganesha/commit/25320e6544f6c5a045f20c5...
>
>
>
>
>
> 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/t...
>
>
>
>
>
> #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(a)lists.nfs-ganesha.org
> To unsubscribe send an email to devel-leave(a)lists.nfs-ganesha.org
11:15 a.m.
New subject: Crash in mdc_lookup_uncached with a bad name pointer
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}
7:34 p.m.
New subject: Crash in mdc_lookup_uncached with a bad name pointer
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
8:14 a.m.
New subject: Crash in mdc_lookup_uncached with a bad name pointer
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
12:28 p.m.
New subject: Crash in mdc_lookup_uncached with a bad name pointer
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
5:18 p.m.
New subject: Crash in mdc_lookup_uncached with a bad name pointer
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
1911
days inactive
1919
days old
6 comments
3 participants
participants (3)
-
Daniel Gryniewicz -
Rungta, Vandana -
vrungta＠amazon.com