Hello,

 

We noticed the following FATAL trace after which ganesha exited  (we are using ganesha 2.7.3 with some of our patches):

ganesha.nfsd-2609[reaper] release_openstate :STATE :FATAL :Could not complete cleanup of lock state for lock owner STATE_OPEN_OWNER_NFSV4 0x3ffea404a8a0: clientid={0x3ffcc001f960 ClientID={Epoch=0x000602e1 Counter=0x00000013} EXPIRED Client={} t_delta=113 reservations=0 refcount=4 cb_prog=1073741824 r_addr=192.168.117.159.141.56 r_netid=tcp} owner=(24:0x6f70656e2069643a000000290000000000175a07e7bb26ec) confirmed=1 seqid=1667 refcount=3
 

I replaced the exit() in Fatal() with an abort() to get a coredump to know more about this.

 

Observed the following from the coredump:

(gdb) t 1
[Switching to thread 1 (Thread 0x3fff52ffe820 (LWP 737))]
#0  0x00003fff82f99614 in .raise () from /lib64/libpthread.so.0
(gdb) bt
#0  0x00003fff82f99614 in .raise () from /lib64/libpthread.so.0
#1  0x0000000010056bec in crash_handler (signo=6, info=0x3fff52ffb478, ctx=0x3fff52ffa700) at /usr/src/debug/nfs-ganesha-2.7.3-ibm050.05FatalAbort/MainNFSD/nfs_init.c:243
#2  <signal handler called>
#3  0x00003fff82d5129c in .raise () from /lib64/libc.so.6
#4  0x00003fff82d534a8 in .abort () from /lib64/libc.so.6
#5  0x0000000010198bdc in Fatal () at /usr/src/debug/nfs-ganesha-2.7.3-ibm050.05FatalAbort/log/log_functions.c:310
#6  0x000000001019cf50 in display_log_component_level (component=COMPONENT_STATE, file=0x10221ac8 "/root/rpmbuild/BUILD/nfs-ganesha-2.7.3-ibm050.05FatalAbort/SAL/nfs4_state.c",
    line=861, function=0x10222178 <__func__.20812> "release_openstate", level=NIV_FATAL, format=0x10221fc0 "Could not complete cleanup of lock state for lock owner %s",
    arguments=0x3fff52ffbae0 "") at /usr/src/debug/nfs-ganesha-2.7.3-ibm050.05FatalAbort/log/log_functions.c:1530
#7  0x000000001019cfe4 in DisplayLogComponentLevel (component=COMPONENT_STATE, file=0x10221ac8 "/root/rpmbuild/BUILD/nfs-ganesha-2.7.3-ibm050.05FatalAbort/SAL/nfs4_state.c",
    line=861, function=0x10222178 <__func__.20812> "release_openstate", level=NIV_FATAL, format=0x10221fc0 "Could not complete cleanup of lock state for lock owner %s")
    at /usr/src/debug/nfs-ganesha-2.7.3-ibm050.05FatalAbort/log/log_functions.c:1704
#8  0x0000000010127c44 in release_openstate (owner=0x3ffeac00e730) at /usr/src/debug/nfs-ganesha-2.7.3-ibm050.05FatalAbort/SAL/nfs4_state.c:859
#9  0x000000001011f2c4 in nfs_client_id_expire (clientid=0x3ffd30004e60, make_stale=true) at /usr/src/debug/nfs-ganesha-2.7.3-ibm050.05FatalAbort/SAL/nfs4_clientid.c:1071
#10 0x00000000101326f8 in nfs_release_v4_client (ip=0x1002c4d3e26 "192.168.11.78") at /usr/src/debug/nfs-ganesha-2.7.3-ibm050.05FatalAbort/SAL/nfs4_recovery.c:805
#11 0x000000001012efac in nfs_start_grace (gsp=0x3fff52ffd908) at /usr/src/debug/nfs-ganesha-2.7.3-ibm050.05FatalAbort/SAL/nfs4_recovery.c:196
#12 0x0000000010063e44 in admin_dbus_grace (args=0x3fff52ffda20, reply=0x1002c4118e0, error=0x3fff52ffda00)
    at /usr/src/debug/nfs-ganesha-2.7.3-ibm050.05FatalAbort/MainNFSD/nfs_admin_thread.c:173
#13 0x00000000101dd77c in dbus_message_entrypoint (conn=0x1002c413790, msg=0x1002c413bd0, user_data=0x10261160 <admin_interfaces>)
    at /usr/src/debug/nfs-ganesha-2.7.3-ibm050.05FatalAbort/dbus/dbus_server.c:562
#14 0x00003fff833658c4 in ._dbus_object_tree_dispatch_and_unlock () from /lib64/libdbus-1.so.3
#15 0x00003fff83350d60 in .dbus_connection_dispatch () from /lib64/libdbus-1.so.3
#16 0x00003fff83351108 in ._dbus_connection_read_write_dispatch () from /lib64/libdbus-1.so.3
#17 0x00000000101de708 in gsh_dbus_thread (arg=0x0) at /usr/src/debug/nfs-ganesha-2.7.3-ibm050.05FatalAbort/dbus/dbus_server.c:795
#18 0x00003fff82f8c95c in .start_thread () from /lib64/libpthread.so.0
#19 0x00003fff82e33bbc in .__clone () from /lib64/libc.so.6
(gdb) f 8
#8  0x0000000010127c44 in release_openstate (owner=0x3ffeac00e730) at /usr/src/debug/nfs-ganesha-2.7.3-ibm050.05FatalAbort/SAL/nfs4_state.c:859
859                     LogFatal(COMPONENT_STATE,
 

FATAL trace was logged when ganesha was in GRACE period.

release_openstate() has a while(errcnt < STATE_ERR_MAX) loop which is working on a state=0x3ffc780103e0.  It calls 'get_state_obj_export_owner_refs(state, &obj, &export, NULL)' which returns with 'obj=NULL',  thread 10 is trying to close this 'obj' as can be seen in the backtrace for thread 10 below. But thread 10 is waiting to get a 'obj_lock' for the 'obj', but 'obj_lock' is taken by thread 215. The thread 215 is doing commit, which is probably taking time.

In release_openstate() after moving in the while(errcnt < STATE_ERR_MAX) loop for 100 iterations, the FATAL trace is logged.

 

Inside the while(errcnt < STATE_ERR_MAX) loop, we increment 'errcnt' whenever 'get_state_obj_export_owner_refs()' fails. If it fails STATE_ERR_MAX times, then we log FATAL trace. This looks suspicious as this while loop could complete very fast. Please check the same. Thank you.