Crash with Mac client about nfs-ganesha HOT 12 CLOSED

What version of Ganesha is this? Also, can you get a tcpdump trace (binary with complete packets) including the request that causes the failure? From the stack backtrace, this is in a code path executed for every operation. What else was going on?

from nfs-ganesha.

We have been seeing the same issue, a Mac client mounting with nfsv4. Just copying 4 files in to the system seems to trigger a trap taking a reference on the exp->fullpath RCU string. I have seen it where the reference count is 0 and in another case the string has been freed and replaced by other content - the refcount itself appears to have been overwritten by a string.

(gdb) print *exp
$1 = {
  exp_list = {
    next = 0x7f47bc22fc40,
    prev = 0x7f47be365fb0 <exportlist>
  },
  node_k = {
    left = 0x7f47bc22fc50,
    right = 0x0,
    parent = 1
  },
  exp_state_list = {
    next = 0x7f47b544f1a0,
    prev = 0x7f47b544f320
  },
  exp_lock_list = {
    next = 0x7f47bc22fa78,
    prev = 0x7f47bc22fa78
  },
  exp_nlm_share_list = {
    next = 0x7f47bc22fa88,
    prev = 0x7f47bc22fa88
  },
  exp_root_list = {
    next = 0x7f47ba9c0520,
    prev = 0x7f47ba9c0520
  },
  exp_work = {
    next = 0x0,
    prev = 0x0
  },
  mounted_exports_list = {
    next = 0x7f47bc22fab8,
    prev = 0x7f47bc22fab8
  },
  mounted_exports_node = {
    next = 0x7f47bc22fcb8,
    prev = 0x7f47bc22fcb8
  },
  exp_root_obj = 0x7f47ba9c0238,
  config_gen = 1,
  clients = {
    next = 0x7f47bc22fae8,
    prev = 0x7f47bc22fae8
  },
  exp_junction_obj = 0x7f47ba9bf838,
  exp_parent_exp = 0x7f47bc22fc40,
  fsal_export = 0x7f47bc232000,
  fullpath = 0x7f47bc2124a0,
  pseudopath = 0x7f47bc212490,
  cfg_fullpath = 0x7f47bc208268 "/nfs1",
  cfg_pseudopath = 0x7f47bc208270 "/nfs1",
  FS_tag = 0x0,
  exp_mounted_on_file_id = 1,
  MaxRead = 67108864,
  MaxWrite = 67108864,
  PrefRead = 67108864,
  PrefWrite = 67108864,
  PrefReaddir = 16384,
  MaxOffsetWrite = 9223372036854775807,
  MaxOffsetRead = 9223372036854775807,
  filesystem_id = {
    major = 666,
    minor = 666
  },
  refcnt = 4,
  exp_lock = {
    __data = {
      __readers = 1,
      __writers = 0,
      __wrphase_futex = 1,
      __writers_futex = 0,
      __pad3 = 0,
      __pad4 = 0,
      __cur_writer = 0,
      __shared = 0,
      __rwelision = 0 '\000',
      __pad1 = "\000\000\000\000\000\000",
      __pad2 = 0,
      __flags = 0
    },
    __size = "\001\000\000\000\000\000\000\000\001", '\000' <repeats 46 times>,
    __align = 1
  },
  export_perms = {
    anonymous_uid = 4294967294,
    anonymous_gid = 4294967294,
    expire_time_attr = 60,
    options = 53490146,
    set = 480
  },
  last_update = {
    tv_sec = 1698144422,
    tv_nsec = 460206919
  },
  options = 0,
  options_set = 0,
  export_id = 77,
  export_status = 0 '\000',
  has_pnfs_ds = false,
  is_mounted = true,
  update_prune_unmount = false,
  update_remount = false
}
(gdb) print *exp->fullpath
$2 = {
  gr_ref = {
    refcount = 0
  },
  gr_val = 0x7f47bc2124a8 "/nfs1"
}

All the other RCU variables seem to have a ref count.

The sequence here was start ganesha (5.5.3) with one export defined, issue a mount command from the Mac:

mount -t nfs -o vers=4,namedattr vsop-nfs:/ mnt

and copy a dir with a handful of files in it:

cp -r doc/ mnt/nfs1

It crashes very quickly.

I cannot find how the reference count is going missing.

I found what might a ref count leak going the other direction, I suspect there is a missing put, but this is something different.

--- a/src/support/export_mgr.c
+++ b/src/support/export_mgr.c
@@ -427,6 +427,8 @@ struct gsh_export *get_gsh_export_by_path_locked(char *path,
                                break;
                        }
                }
+
+               gsh_refstr_put(ref_fullpath);
        }

        if (ret_exp != NULL)

The Mac here is running Sonoma, so the most recent version of Mac OS.

Here is a tar file containing a tcp dump of the whole sequence from mount to loss of connection (ganesha crash). I have seen this happen in different calls, the last one here was a close, but last time it was an access call.

nfs.tgz

from nfs-ganesha.

I should add that the tcpdump capture here was performed on the server end, but not under normal conditions, I am 4000 miles from the server this week, so there are some tcp glitches in there.

from nfs-ganesha.

Do you have a stack back trace of your crash? The above stack back trace doesn't quite make sense (set_op_context_export_fsal_no_release (exp=0x7f707dac1348, fsal_exp=0x7f707da41000, pds=0x0, discard_refstr=true)
at /home/vic/Sources/nfs-ganesha/src/FSAL/commonlib.c:3041 is a call to gsh_refstr_put).

From the tcpdump trace, I see RELEASE_LOCKOWNER and then a CLOSE without a response. I assume the CLOSE is where the crash happened, I'm wondering if RELEASE_LOCKOWNER is the path where the extra put occurred.

from nfs-ganesha.

My mistake, I thought I put it in there, but clearly not:

__pthread_kill_implementation (no_tid=0, signo=6, threadid=139980347274816) at ./nptl/pthread_kill.c:44
44	./nptl/pthread_kill.c: No such file or directory.
(gdb) bt
#0  __pthread_kill_implementation (no_tid=0, signo=6, threadid=139980347274816) at ./nptl/pthread_kill.c:44
#1  __pthread_kill_internal (signo=6, threadid=139980347274816) at ./nptl/pthread_kill.c:78
#2  __GI___pthread_kill (threadid=139980347274816, signo=signo@entry=6) at ./nptl/pthread_kill.c:89
#3  0x00007f4fc0260476 in __GI_raise (sig=sig@entry=6) at ../sysdeps/posix/raise.c:26
#4  0x00007f4fc02467f3 in __GI_abort () at ./stdlib/abort.c:79
#5  0x00007f4fc0744245 in gsh_refstr_get (gr=<optimized out>) at /context/src/include/gsh_refstr.h:102
#6  set_op_context_export_fsal_no_release (exp=0x7f4fbe62fa40, fsal_exp=0x7f4fbe632000, pds=0x0, discard_refstr=<optimized out>)
    at /context/src/FSAL/commonlib.c:3064
#7  0x00007f4fc07e54dd in nfs4_mds_putfh (data=data@entry=0x7f4fb6619300) at /context/src/Protocols/NFS/nfs4_op_putfh.c:175
#8  0x00007f4fc07e5aa8 in nfs4_op_putfh (op=0x7f4fb66051c0, data=0x7f4fb6619300, resp=0x7f4fb6628200) at /context/src/Protocols/NFS/nfs4_op_putfh.c:282
#9  0x00007f4fc07d6244 in process_one_op (data=data@entry=0x7f4fb6619300, status=status@entry=0x7f4fb6dfbdbc)
    at /context/src/Protocols/NFS/nfs4_Compound.c:923
#10 0x00007f4fc07d75c8 in nfs4_Compound (arg=0x7f4fb663c830, req=0x7f4fb663c000, res=<optimized out>) at /context/src/Protocols/NFS/nfs4_Compound.c:1391
#11 0x00007f4fc077066e in nfs_rpc_process_request (reqdata=0x7f4fb663c000, retry=<optimized out>) at /context/src/MainNFSD/nfs_worker_thread.c:1539
#12 0x00007f4fc01f9c9f in svc_request (xprt=0x7f4fbe7ed200, xdrs=<optimized out>) at /context/src/libntirpc/src/svc_rqst.c:1202
#13 0x00007f4fc01f789a in svc_rqst_xprt_task_recv (wpe=<optimized out>) at /context/src/libntirpc/src/svc_rqst.c:1183
#14 0x00007f4fc01f8290 in svc_rqst_epoll_loop (wpe=0x7f4fbe7ebb18) at /context/src/libntirpc/src/svc_rqst.c:1564
#15 0x00007f4fc02037b8 in work_pool_thread (arg=0x7f4fb5c0f0a0) at /context/src/libntirpc/src/work_pool.c:183
#16 0x00007f4fc02b2b43 in start_thread (arg=<optimized out>) at ./nptl/pthread_create.c:442
#17 0x00007f4fc0344a00 in clone3 () at ../sysdeps/unix/sysv/linux/x86_64/clone3.S:81

The release_lockowner does seem to be a common factor in the times I have looked at the op sequence, seems to be the way the Mac does things.

from nfs-ganesha.

OK, I'm going to continue auditing the get and put of references. Clearly we have some mismatches. There aren't that many, so it should be possible to find this by code inspection.

from nfs-ganesha.

This issue is occurring for me as well, but the following patch seems to resolve it:

--- a/src/FSAL/commonlib.c
+++ b/src/FSAL/commonlib.c
@@ -3159,6 +3159,8 @@ void save_op_context_export_and_clear(struct saved_export_context *saved)
        op_ctx->ctx_export = NULL;
        op_ctx->fsal_export = NULL;
        op_ctx->ctx_pnfs_ds = NULL;
+       op_ctx->ctx_fullpath = gsh_refstr_get(no_export);
+       op_ctx->ctx_pseudopath = gsh_refstr_get(no_export);
 }

 void restore_op_context_export(struct saved_export_context *saved)

As has been mentioned, the problem is with RELEASE_LOCKOWNER and reference counting.

Without the above patch, when release_lock_owner calls save_op_context_export_and_clear, the ctx_fullpath and ctx_pseudopath fields would be left pointing at the old values, despite ctx_export and others being set to NULL. This ultimately leads to an extra gsh_refstr_put call from restore_op_context_export.

from nfs-ganesha.

from nfs-ganesha.

Looks like a good fix, will work in the new year to get that submitted and merged. If someone wants to submit via gerrithub that would be helpful otherwise I can do it.

from nfs-ganesha.

Just noticed this got fixed in 0ae55ef. Thanks!

from nfs-ganesha.

Did you verify? If so, please close.

from nfs-ganesha.

Yeah, I tested it and the crash no longer occurs. I don't seem to have permission to close the issue though.

from nfs-ganesha.