SIGABRT in nfs4_op_close in PTHREAD_MUTEX_lock(&open_owner->so_mutex)

[drieber]

We are very frequently seeing the following crash when our ganesha server is under heavy load:

E0716 10:41:43.118452 8265077 state_misc.c:927] [ COMPONENT_STATE : dec_state_owner_ref (NIV_CRIT) ] Unexpected owner {Invalid owner 0x130a5d870}, type {127695696}
E0716 10:41:43.118836 8265077 nfs4_op_close.c:230] [ COMPONENT_RW_LOCK : nfs4_op_close (NIV_CRIT) ] Error 22, acquiring mutex 0x130a5d888 (&open_owner->so_mutex) at third_party/nfs_ganesha/src/Protocols/NFS/nfs4_o\
p_close.c:230

Above you can see dec_state_owner_ref is acting on an invalid owner because type has an invalid value (corrupt memory? thread safety issue?).

Sometimes we see this instead:

E0726 19:41:39.643897 2938418 state_misc.c:927] [ COMPONENT_STATE : dec_state_owner_ref (NIV_CRIT) ] Unexpected owner {Invalid owner 0x10922da30}, type {0}
E0726 19:41:39.644877 2938418 nfs4_op_close.c:230] [ COMPONENT_RW_LOCK : nfs4_op_close (NIV_CRIT) ] Error 22, acquiring mutex 0x10922da48 (&open_owner->so_mutex) at third_party/nfs_ganesha/src/Protocols/NFS/nfs4_o\
p_close.c:230

It is very similar to the previous case but here the log says owner's type is zero.

Our setup is this:

• ganesha V5.9 + a few patches
• We only use NFSv4
• Custom FSAL (largely based on FSAL_VFS)
• The client and server are on the same machine, so there is a single client! The mount uses TCP & localhost.
• When we see the above crash there is a single process doing open/close with very high parallelism.
• The system runs on macOS
• We run with Dir_Chunk = 0 and Attr_Expiration_Time = 0.

Our patches include:

• A change equivalent to https://gerrithub.io/c/ffilz/nfs-ganesha/+/1198233
• A local backport of https://github.com/nfs-ganesha/nfs-ganesha/commit/3feb078c39e4777acf860fb0efea56f50eebcca1 on top of V5.9
• A few unrelated small changes

[drieber]

Please note we are also frequently seeing https://github.com/nfs-ganesha/nfs-ganesha/issues/1156, but as far as I can tell on a given run we see either this bug (Error 22, acquiring mutex 0x130a5d888), or the deadlock in fsal_start_fd_work (issue 1156), but never both at the same time.

[drieber]

Here is a stack trace:

Thread 160 Crashed:
0   libsystem_kernel.dylib                 0x182276a60 __pthread_kill + 8
1   libsystem_pthread.dylib                0x1822aec20 pthread_kill + 288
2   libsystem_c.dylib                      0x1821bba30 abort + 180
3   srcfsd_darwin                          0x102e02060 nfs4_op_close + 2112
4   srcfsd_darwin                          0x102df1d1c process_one_op + 848
5   srcfsd_darwin                          0x102df2a88 nfs4_Compound + 1160
6   srcfsd_darwin                          0x102ddf874 nfs_rpc_process_request + 2240
7   srcfsd_darwin                          0x102edf914 svc_request + 60
8   srcfsd_darwin                          0x102ee16c8 svc_vc_recv + 1268
9   srcfsd_darwin                          0x102edf80c svc_rqst_xprt_task_recv + 92
10  srcfsd_darwin                          0x102ede224 svc_rqst_epoll_loop + 720
11  srcfsd_darwin                          0x102ee4808 work_pool_thread + 452
12  libsystem_pthread.dylib                0x1822aef94 _pthread_start + 136
13  libsystem_pthread.dylib                0x1822a9d34 thread_start + 8

The crash happens here: https://github.com/nfs-ganesha/nfs-ganesha/blob/next/src/Protocols/NFS/nfs4_op_close.c#L230

Here is a snippet of logs with FULL_DEBUG for COMPONENT_STATE:

I0731 14:20:55.047438   52104 nfs4_state_id.c:1157] [ COMPONENT_STATE : nfs4_Check_Stateid (NIV_FULL_DEBUG) ] Check READ stateid found valid stateid OTHER=0x010000008ca5aa6622d00500 {{CLIENTID Epoch=0x66aaa58c Counter=0x00000001} StateIdCounter=0x0005d022} seqid=1 - 0x113a8a700
I0731 14:20:55.047446   52104 state_misc.c:913] [ COMPONENT_STATE : dec_state_owner_ref (NIV_FULL_DEBUG) ] Decrement refcount now=3 {STATE_OPEN_OWNER_NFSV4 0x1138c8e70: clientid={0x10b1d4400 ClientID={Epoch=0x66aaa58c Counter=0x00000001} CONFIRMED Client={0x600001b1b230 name=(58:0x01000000bcd0745295bb100224ba7f00000100000000000000003132372e302e302e313a2f002f566f6c756d65732f676f6f676c652f73726300) refcount=1} t_delta=0 reservations=2 refcount=2 cb_prog=0 r_addr= r_netid=-} owner=(4:0x00013d72) confirmed=1 seqid=761940 refcount=4}
I0731 14:20:55.047451   52104 sal_functions.h:417] [ COMPONENT_STATE : inc_state_t_ref (NIV_FULL_DEBUG) ] State 0x113a8a700 refcount now 3
I0731 14:20:55.047411   52097 state_misc.c:802] [ COMPONENT_STATE : inc_state_owner_ref (NIV_FULL_DEBUG) ] Increment refcount now=3 {STATE_OPEN_OWNER_NFSV4 0x1138c8e70: clientid={0x10b1d4400 ClientID={Epoch=0x66aaa58c Counter=0x00000001} CONFIRMED Client={0x600001b1b230 name=(58:0x01000000bcd0745295bb100224ba7f00000100000000000000003132372e302e302e313a2f002f566f6c756d65732f676f6f676c652f73726300) refcount=1} t_delta=0 reservations=1 refcount=2 cb_prog=0 r_addr= r_netid=-} owner=(4:0x00013d72) confirmed=1 seqid=761940 refcount=2}
I0731 14:20:55.047482   52104 state_misc.c:802] [ COMPONENT_STATE : inc_state_owner_ref (NIV_FULL_DEBUG) ] Increment refcount now=4 {STATE_OPEN_OWNER_NFSV4 0x1138c8e70: clientid={0x10b1d4400 ClientID={Epoch=0x66aaa58c Counter=0x00000001} CONFIRMED Client={0x600001b1b230 name=(58:0x01000000bcd0745295bb100224ba7f00000100000000000000003132372e302e302e313a2f002f566f6c756d65732f676f6f676c652f73726300) refcount=1} t_delta=0 reservations=2 refcount=2 cb_prog=0 r_addr= r_netid=-} owner=(4:0x00013d72) confirmed=1 seqid=761940 refcount=3}
I0731 14:20:55.047497   52104 commonlib.c:2703] [ COMPONENT_FSAL : fsal_start_io (NIV_FULL_DEBUG) ] state_fd->openflags = 1 openflags = 1
I0731 14:20:55.047503   52104 commonlib.c:2326] [ COMPONENT_FSAL : wait_to_start_io (NIV_FULL_DEBUG) ] 0x113a8a7f8 try io_work = 1 fd_work = 0
I0731 14:20:55.047507   52104 commonlib.c:2452] [ COMPONENT_FSAL : wait_to_start_io (NIV_FULL_DEBUG) ] Open mode = 1, desired mode = 1
I0731 14:20:55.047512   52104 commonlib.c:2720] [ COMPONENT_FSAL : fsal_start_io (NIV_FULL_DEBUG) ] Use state_fd 0x113a8a7f8
I0731 14:20:55.047594   52104 commonlib.c:2912] [ COMPONENT_FSAL : fsal_complete_io (NIV_FULL_DEBUG) ] 0x113a8a7f8 done io_work (-1) = 0 fd_work = 0
I0731 14:20:55.047606   52104 nfs4_state_id.c:509] [ COMPONENT_STATE : dec_nfs4_state_ref (NIV_FULL_DEBUG) ] Decrement refcount now=2 {STATE 0x113a8a700 OTHER=0x010000008ca5aa6622d00500 {{CLIENTID Epoch=0x66aaa58c Counter=0x00000001} StateIdCounter=0x0005d022} obj=0x113a8a788 type=SHARE seqid=1 owner={STATE_OPEN_OWNER_NFSV4 0x1138c8e70: clientid={0x10b1d4400 ClientID={Epoch=0x66aaa58c Counter=0x00000001} CONFIRMED Client={0x600001b1b230 name=(58:0x01000000bcd0745295bb100224ba7f00000100000000000000003132372e302e302e313a2f002f566f6c756d65732f676f6f676c652f73726300) refcount=1} t_delta=0 reservations=2 refcount=2 cb_prog=0 r_addr= r_netid=-} owner=(4:0x00013d72) confirmed=1 seqid=761940 refcount=4} refccount=3}
I0731 14:20:55.047489   52097 nfs4_owner.c:739] [ COMPONENT_STATE : Check_nfs4_seqid (NIV_FULL_DEBUG) ] CLOSE: Check {STATE_OPEN_OWNER_NFSV4 0x1138c8e70: clientid={0x10b1d4400 ClientID={Epoch=0x66aaa58c Counter=0x00000001} CONFIRMED Client={0x600001b1b230 name=(58:0x01000000bcd0745295bb100224ba7f00000100000000000000003132372e302e302e313a2f002f566f6c756d65732f676f6f676c652f73726300) refcount=1} t_delta=0 reservations=2 refcount=2 cb_prog=0 r_addr= r_netid=-} owner=(4:0x00013d72) confirmed=1 seqid=761940 refcount=4} next 761941 req seqid 761941
I0731 14:20:55.047631   52097 nfs4_state_id.c:1237] [ COMPONENT_STATE : update_stateid (NIV_DEBUG) ] Update CLOSE stateid to OTHER=0x010000008ca5aa661ed00500 {{CLIENTID Epoch=0x66aaa58c Counter=0x00000001} StateIdCounter=0x0005d01e} seqid=2 for response
I0731 14:20:55.047645   47616 commonlib.c:2966] [ COMPONENT_FSAL : fsal_start_fd_work (NIV_FULL_DEBUG) ] 0x12650dd88 try fd work - io_work = 0 fd_work = 1
I0731 14:20:55.047656   52097 nfs4_state.c:365] [ COMPONENT_STATE : _state_del_locked (NIV_FULL_DEBUG) ] Deleting STATE 0x124449cb0 OTHER=0x010000008ca5aa661ed00500 {{CLIENTID Epoch=0x66aaa58c Counter=0x00000001} StateIdCounter=0x0005d01e} obj=0x124449d38 type=SHARE seqid=2 owner={STATE_OPEN_OWNER_NFSV4 0x1138c8e70: clientid={0x10b1d4400 ClientID={Epoch=0x66aaa58c Counter=0x00000001} CONFIRMED Client={0x600001b1b230 name=(58:0x01000000bcd0745295bb100224ba7f00000100000000000000003132372e302e302e313a2f002f566f6c756d65732f676f6f676c652f73726300) refcount=1} t_delta=0 reservations=2 refcount=2 cb_prog=0 r_addr= r_netid=-} owner=(4:0x00013d72) confirmed=1 seqid=761940 refcount=3} refccount=2
I0731 14:20:55.047615   52104 state_misc.c:913] [ COMPONENT_STATE : dec_state_owner_ref (NIV_FULL_DEBUG) ] Decrement refcount now=3 {STATE_OPEN_OWNER_NFSV4 0x1138c8e70: clientid={0x10b1d4400 ClientID={Epoch=0x66aaa58c Counter=0x00000001} CONFIRMED Client={0x600001b1b230 name=(58:0x01000000bcd0745295bb100224ba7f00000100000000000000003132372e302e302e313a2f002f566f6c756d65732f676f6f676c652f73726300) refcount=1} t_delta=0 reservations=2 refcount=2 cb_prog=0 r_addr= r_netid=-} owner=(4:0x00013d72) confirmed=1 seqid=761940 refcount=4}
I0731 14:20:55.047704   52104 nfs4_state_id.c:509] [ COMPONENT_STATE : dec_nfs4_state_ref (NIV_FULL_DEBUG) ] Decrement refcount now=1 {STATE 0x113a8a700 OTHER=0x010000008ca5aa6622d00500 {{CLIENTID Epoch=0x66aaa58c Counter=0x00000001} StateIdCounter=0x0005d022} obj=0x113a8a788 type=SHARE seqid=1 owner={STATE_OPEN_OWNER_NFSV4 0x1138c8e70: clientid={0x10b1d4400 ClientID={Epoch=0x66aaa58c Counter=0x00000001} CONFIRMED Client={0x600001b1b230 name=(58:0x01000000bcd0745295bb100224ba7f00000100000000000000003132372e302e302e313a2f002f566f6c756d65732f676f6f676c652f73726300) refcount=1} t_delta=0 reservations=2 refcount=2 cb_prog=0 r_addr= r_netid=-} owner=(4:0x00013d72) confirmed=1 seqid=761940 refcount=2} refccount=2}
I0731 14:20:55.047684   52097 state_misc.c:913] [ COMPONENT_STATE : dec_state_owner_ref (NIV_FULL_DEBUG) ] Decrement refcount now=2 {STATE_OPEN_OWNER_NFSV4 0x1138c8e70: clientid={0x10b1d4400 ClientID={Epoch=0x66aaa58c Counter=0x00000001} CONFIRMED Client={0x600001b1b230 name=(58:0x01000000bcd0745295bb100224ba7f00000100000000000000003132372e302e302e313a2f002f566f6c756d65732f676f6f676c652f73726300) refcount=1} t_delta=0 reservations=2 refcount=2 cb_prog=0 r_addr= r_netid=-} owner=(4:0x00013d72) confirmed=1 seqid=761940 refcount=3}
I0731 14:20:55.047742   52097 commonlib.c:1269] [ COMPONENT_FSAL : update_share_counters (NIV_FULL_DEBUG) ] share counter: access_read 0, access_write 0, deny_read 0, deny_write 0, deny_write_v4 0
I0731 14:20:55.047762   52097 commonlib.c:2966] [ COMPONENT_FSAL : fsal_start_fd_work (NIV_FULL_DEBUG) ] 0x124449da8 try fd work - io_work = 0 fd_work = 1
I0731 14:20:55.047780   52097 commonlib.c:3015] [ COMPONENT_FSAL : fsal_complete_fd_work (NIV_FULL_DEBUG) ] 0x124449da8 done fd work io_work = 0 fd_work = 0
I0731 14:20:55.047788   52097 nfs4_state_id.c:509] [ COMPONENT_STATE : dec_nfs4_state_ref (NIV_FULL_DEBUG) ] Decrement refcount now=1 {STATE 0x124449cb0 OTHER=0x010000008ca5aa661ed00500 {{CLIENTID Epoch=0x66aaa58c Counter=0x00000001} StateIdCounter=0x0005d01e} obj=0x124449d38 type=SHARE seqid=2 owner={<NULL>} refccount=2}
I0731 14:20:55.047794   52097 nfs4_owner.c:652] [ COMPONENT_STATE : Copy_nfs4_state_req (NIV_FULL_DEBUG) ] CLOSE: saving response 0x1138c8e70 so_seqid 761940 new seqid 761941
I0731 14:20:55.047662   47616 commonlib.c:3015] [ COMPONENT_FSAL : fsal_complete_fd_work (NIV_FULL_DEBUG) ] 0x12650dd88 done fd work io_work = 0 fd_work = 0
I0731 14:20:55.047804   52097 state_misc.c:913] [ COMPONENT_STATE : dec_state_owner_ref (NIV_FULL_DEBUG) ] Decrement refcount now=1 {STATE_OPEN_OWNER_NFSV4 0x1138c8e70: clientid={0x10b1d4400 ClientID={Epoch=0x66aaa58c Counter=0x00000001} CONFIRMED Client={0x600001b1b230 name=(58:0x01000000bcd0745295bb100224ba7f00000100000000000000003132372e302e302e313a2f002f566f6c756d65732f676f6f676c652f73726300) refcount=1} t_delta=0 reservations=1 refcount=2 cb_prog=0 r_addr= r_netid=-} owner=(4:0x00013d72) confirmed=1 seqid=761941 refcount=2}
I0731 14:20:55.047809   47616 commonlib.c:2966] [ COMPONENT_FSAL : fsal_start_fd_work (NIV_FULL_DEBUG) ] 0x12650dd88 try fd work - io_work = 0 fd_work = 1
I0731 14:20:55.047816   52097 nfs4_state_id.c:519] [ COMPONENT_STATE : dec_nfs4_state_ref (NIV_FULL_DEBUG) ] Deleted STATE 0x124449cb0 OTHER=0x010000008ca5aa661ed00500 {{CLIENTID Epoch=0x66aaa58c Counter=0x00000001} StateIdCounter=0x0005d01e} obj=0x124449d38 type=SHARE seqid=2 owner={<NULL>} refccount=1
I0731 14:20:55.047819   47616 commonlib.c:3015] [ COMPONENT_FSAL : fsal_complete_fd_work (NIV_FULL_DEBUG) ] 0x12650dd88 done fd work io_work = 0 fd_work = 0
I0731 14:20:55.049349   47616 nfs4_op_open.c:1259] [ COMPONENT_STATE : nfs4_op_open (NIV_DEBUG) ] Entering NFS v4 OPEN handler -----------------------------
I0731 14:20:55.049367   47616 nfs4_op_open.c:1267] [ COMPONENT_STATE : nfs4_op_open (NIV_FULL_DEBUG) ] OPEN: Claim type = 0, Open Type = 0, Share Deny = 0, Share Access = 1
I0731 14:20:55.049373   47616 nfs4_op_open.c:1319] [ COMPONENT_STATE : nfs4_op_open (NIV_DEBUG) ] OPEN Client id = 66aaa58c00000001
I0731 14:20:55.049384   47616 nfs4_owner.c:453] [ COMPONENT_STATE : create_nfs4_owner (NIV_FULL_DEBUG) ] Key=STATE_OPEN_OWNER_NFSV4 0x309699660: clientid={0x10b1d4400 ClientID={Epoch=0x66aaa58c Counter=0x00000001} CONFIRMED Client={0x600001b1b230 name=(58:0x01000000bcd0745295bb100224ba7f00000100000000000000003132372e302e302e313a2f002f566f6c756d65732f676f6f676c652f73726300) refcount=1} t_delta=0 reservations=1 refcount=3 cb_prog=0 r_addr= r_netid=-} owner=(4:0x00013d72) confirmed=0 seqid=0 refcount=1
I0731 14:20:55.049393   47616 state_misc.c:1064] [ COMPONENT_STATE : get_state_owner (NIV_FULL_DEBUG) ] Find {STATE_OPEN_OWNER_NFSV4 0x309699660: clientid={0x10b1d4400 ClientID={Epoch=0x66aaa58c Counter=0x00000001} CONFIRMED Client={0x600001b1b230 name=(58:0x01000000bcd0745295bb100224ba7f00000100000000000000003132372e302e302e313a2f002f566f6c756d65732f676f6f676c652f73726300) refcount=1} t_delta=0 reservations=1 refcount=3 cb_prog=0 r_addr= r_netid=-} owner=(4:0x00013d72) confirmed=0 seqid=0 refcount=1}
I0731 14:20:55.049403   47616 state_misc.c:1117] [ COMPONENT_STATE : get_state_owner (NIV_FULL_DEBUG) ] Found {STATE_OPEN_OWNER_NFSV4 0x309699660: clientid={0x10b1d4400 ClientID={Epoch=0x66aaa58c Counter=0x00000001} CONFIRMED Client={0x600001b1b230 name=(58:0x01000000bcd0745295bb100224ba7f00000100000000000000003132372e302e302e313a2f002f566f6c756d65732f676f6f676c652f73726300) refcount=1} t_delta=0 reservations=1 refcount=3 cb_prog=0 r_addr= r_netid=-} owner=(4:0x00013d72) confirmed=0 seqid=0 refcount=1STATE_OPEN_OWNER_NFSV4 0x1138c8e70: clientid={0x10b1d4400 ClientID={Epoch=0x66aaa58c Counter=0x00000001} CONFIRMED Client={0x600001b1b230 name=(58:0x01000000bcd0745295bb100224ba7f00000100000000000000003132372e302e302e313a2f002f566f6c756d65732f676f6f676c652f73726300) refcount=1} t_delta=0 reservations=1 refcount=3 cb_prog=0 r_addr= r_netid=-} owner=(4:0x00013d72) confirmed=1 seqid=761941 refcount=2} refcount now=2
I0731 14:20:55.049411   47616 nfs4_owner.c:500] [ COMPONENT_STATE : create_nfs4_owner (NIV_DEBUG) ] Previously known owner {STATE_OPEN_OWNER_NFSV4 0x1138c8e70: clientid={0x10b1d4400 ClientID={Epoch=0x66aaa58c Counter=0x00000001} CONFIRMED Client={0x600001b1b230 name=(58:0x01000000bcd0745295bb100224ba7f00000100000000000000003132372e302e302e313a2f002f566f6c756d65732f676f6f676c652f73726300) refcount=1} t_delta=0 reservations=1 refcount=3 cb_prog=0 r_addr= r_netid=-} owner=(4:0x00013d72) confirmed=1 seqid=761941 refcount=2} is being reused
I0731 14:20:55.049419   47616 nfs4_op_open.c:234] [ COMPONENT_STATE : open4_open_owner (NIV_FULL_DEBUG) ] Open: STATE_OPEN_OWNER_NFSV4 0x1138c8e70: clientid={0x10b1d4400 ClientID={Epoch=0x66aaa58c Counter=0x00000001} CONFIRMED Client={0x600001b1b230 name=(58:0x01000000bcd0745295bb100224ba7f00000100000000000000003132372e302e302e313a2f002f566f6c756d65732f676f6f676c652f73726300) refcount=1} t_delta=0 reservations=1 refcount=3 cb_prog=0 r_addr= r_netid=-} owner=(4:0x00013d72) confirmed=1 seqid=761941 refcount=2
I0731 14:20:55.049428   47616 nfs4_owner.c:739] [ COMPONENT_STATE : Check_nfs4_seqid (NIV_FULL_DEBUG) ] OPEN: Check {STATE_OPEN_OWNER_NFSV4 0x1138c8e70: clientid={0x10b1d4400 ClientID={Epoch=0x66aaa58c Counter=0x00000001} CONFIRMED Client={0x600001b1b230 name=(58:0x01000000bcd0745295bb100224ba7f00000100000000000000003132372e302e302e313a2f002f566f6c756d65732f676f6f676c652f73726300) refcount=1} t_delta=0 reservations=1 refcount=3 cb_prog=0 r_addr= r_netid=-} owner=(4:0x00013d72) confirmed=1 seqid=761941 refcount=2} next 761942 req seqid 761942
I0731 14:20:55.049651   47616 commonlib.c:2966] [ COMPONENT_FSAL : fsal_start_fd_work (NIV_FULL_DEBUG) ] 0x120330298 try fd work - io_work = 0 fd_work = 1
I0731 14:20:55.049665   47616 commonlib.c:3015] [ COMPONENT_FSAL : fsal_complete_fd_work (NIV_FULL_DEBUG) ] 0x120330298 done fd work io_work = 0 fd_work = 0
I0731 14:20:55.049670   47616 commonlib.c:2966] [ COMPONENT_FSAL : fsal_start_fd_work (NIV_FULL_DEBUG) ] 0x120330298 try fd work - io_work = 0 fd_work = 1
I0731 14:20:55.049675   47616 commonlib.c:3015] [ COMPONENT_FSAL : fsal_complete_fd_work (NIV_FULL_DEBUG) ] 0x120330298 done fd work io_work = 0 fd_work = 0
I0731 14:20:55.049694   47616 nfs4_state_id.c:703] [ COMPONENT_STATE : nfs4_State_Get_Obj (NIV_DEBUG) ] HashTable_Get returned 2
I0731 14:20:55.049700   47616 nfs4_op_open.c:989] [ COMPONENT_STATE : open4_ex (NIV_FULL_DEBUG) ] Calling open2 for (null)
I0731 14:20:55.049705   47616 fsal_helper.c:1607] [ COMPONENT_FSAL : fsal_open2 (NIV_FULL_DEBUG) ] attrs  set attributes No attributes
I0731 14:20:55.049710   47616 fsal_helper.c:173] [ COMPONENT_FSAL : fsal_check_create_owner (NIV_FULL_DEBUG) ] attr->owner 0 caller_uid 81266 attr->group 0 caller_gid 89939
I0731 14:20:55.049804   47616 commonlib.c:2966] [ COMPONENT_FSAL : fsal_start_fd_work (NIV_FULL_DEBUG) ] 0x12524c1c8 try fd work - io_work = 0 fd_work = 1
I0731 14:20:55.049844   47616 commonlib.c:1813] [ COMPONENT_FSAL : insert_fd_lru (NIV_FULL_DEBUG) ] Inserting fsal_fd(0x12524c1c8) to fd_lru for type(2) count(0/380962/0)
I0731 14:20:55.049906   47616 commonlib.c:1269] [ COMPONENT_FSAL : update_share_counters (NIV_FULL_DEBUG) ] share counter: access_read 1, access_write 0, deny_read 0, deny_write 0, deny_write_v4 0
I0731 14:20:55.049911   47616 commonlib.c:3015] [ COMPONENT_FSAL : fsal_complete_fd_work (NIV_FULL_DEBUG) ] 0x12524c1c8 done fd work io_work = 0 fd_work = 0
I0731 14:20:55.049917   47616 nfs4_op_open.c:1072] [ COMPONENT_STATE : open4_ex (NIV_FULL_DEBUG) ] Creating new state access=1 deny=0 access_prev=2 deny_prev=1
I0731 14:20:55.049922   47616 nfs4_state.c:107] [ COMPONENT_STATE : _state_add_impl (NIV_FULL_DEBUG) ] pnew_state=STATE 0x12524c0d0 OTHER=0x000000000000000000000000 {{CLIENTID Epoch=0x00000000 Counter=0x00000000} State...
I0731 14:20:55.049928   47616 nfs4_state.c:164] [ COMPONENT_STATE : _state_add_impl (NIV_FULL_DEBUG) ] About to call nfs4_State_Set for OTHER=0x010000008ca5aa6623d00500 {{CLIENTID Epoch=0x66aaa58c Counter=0x00000001} StateIdCounter=0x0005d023}
I0731 14:20:55.049937   47616 state_misc.c:802] [ COMPONENT_STATE : inc_state_owner_ref (NIV_FULL_DEBUG) ] Increment refcount now=3 {STATE_OPEN_OWNER_NFSV4 0x1138c8e70: clientid={0x10b1d4400 ClientID={Epoch=0x66aaa58c Counter=0x00000001} CONFIRMED Client={0x600001b1b230 name=(58:0x01000000bcd0745295bb100224ba7f00000100000000000000003132372e302e302e313a2f002f566f6c756d65732f676f6f676c652f73726300) refcount=1} t_delta=0 reservations=1 refcount=3 cb_prog=0 r_addr= r_netid=-} owner=(4:0x00013d72) confirmed=1 seqid=761941 refcount=2}
I0731 14:20:55.049942   47616 nfs4_state.c:258] [ COMPONENT_STATE : _state_add_impl (NIV_FULL_DEBUG) ] Add State: 0x12524c0d0: OTHER=0x010000008ca5aa6623d00500 {{CLIENTID Epoch=0x66aaa58c Counter=0x00000001} StateIdCounter=0x0005d023}
I0731 14:20:55.049947   47616 nfs4_op_open.c:577] [ COMPONENT_STATE : do_delegation (NIV_FULL_DEBUG) ] Delegation type not supported.
I0731 14:20:55.049951   47616 nfs4_op_open.c:1417] [ COMPONENT_STATE : nfs4_op_open (NIV_FULL_DEBUG) ] NFS4 OPEN returning NFS4_OK
I0731 14:20:55.049971   47616 nfs4_state_id.c:1237] [ COMPONENT_STATE : update_stateid (NIV_DEBUG) ] Update OPEN stateid to OTHER=0x010000008ca5aa6623d00500 {{CLIENTID Epoch=0x66aaa58c Counter=0x00000001} StateIdCounter=0x0005d023} seqid=1 for response
I0731 14:20:55.049976   47616 nfs4_owner.c:652] [ COMPONENT_STATE : Copy_nfs4_state_req (NIV_FULL_DEBUG) ] OPEN: saving response 0x1138c8e70 so_seqid 761941 new seqid 761942
I0731 14:20:55.050000   47616 nfs4_state_id.c:509] [ COMPONENT_STATE : dec_nfs4_state_ref (NIV_FULL_DEBUG) ] Decrement refcount now=1 {STATE 0x12524c0d0 OTHER=0x010000008ca5aa6623d00500 {{CLIENTID Epoch=0x66aaa58c Counter=0x00000001} StateIdCounter=0x0005d023} obj=0x12524c158 type=SHARE seqid=1 owner={STATE_OPEN_OWNER_NFSV4 0x1138c8e70: clientid={0x10b1d4400 ClientID={Epoch=0x66aaa58c Counter=0x00000001} CONFIRMED Client={0x600001b1b230 name=(58:0x01000000bcd0745295bb100224ba7f00000100000000000000003132372e302e302e313a2f002f566f6c756d65732f676f6f676c652f73726300) refcount=1} t_delta=0 reservations=0 refcount=3 cb_prog=0 r_addr= r_netid=-} owner=(4:0x00013d72) confirmed=1 seqid=761942 refcount=3} refccount=2}
I0731 14:20:55.050038   47616 state_misc.c:913] [ COMPONENT_STATE : dec_state_owner_ref (NIV_FULL_DEBUG) ] Decrement refcount now=2 {STATE_OPEN_OWNER_NFSV4 0x1138c8e70: clientid={0x10b1d4400 ClientID={Epoch=0x66aaa58c Counter=0x00000001} CONFIRMED Client={0x600001b1b230 name=(58:0x01000000bcd0745295bb100224ba7f00000100000000000000003132372e302e302e313a2f002f566f6c756d65732f676f6f676c652f73726300) refcount=1} t_delta=0 reservations=0 refcount=3 cb_prog=0 r_addr= r_netid=-} owner=(4:0x00013d72) confirmed=1 seqid=761942 refcount=3}
I0731 14:20:55.050840   52096 nfs4_state_id.c:837] [ COMPONENT_STATE : nfs4_Check_Stateid (NIV_FULL_DEBUG) ] Check READ stateid flags ALL_0 ALL_1 CURRENT
I0731 14:20:55.050858   52096 sal_functions.h:417] [ COMPONENT_STATE : inc_state_t_ref (NIV_FULL_DEBUG) ] State 0x12524c0d0 refcount now 2
I0731 14:20:55.050863   52096 nfs4_state.c:606] [ COMPONENT_STATE : get_state_obj_export_owner_refs (NIV_FULL_DEBUG) ] state 0x12524c0d0 state_obj 0x12524c158 state_export 0x145609c10 state_owner 0x1138c8e70
I0731 14:20:55.050873   52096 state_misc.c:802] [ COMPONENT_STATE : inc_state_owner_ref (NIV_FULL_DEBUG) ] Increment refcount now=3 {STATE_OPEN_OWNER_NFSV4 0x1138c8e70: clientid={0x10b1d4400 ClientID={Epoch=0x66aaa58c Counter=0x00000001} CONFIRMED Client={0x600001b1b230 name=(58:0x01000000bcd0745295bb100224ba7f00000100000000000000003132372e302e302e313a2f002f566f6c756d65732f676f6f676c652f73726300) refcount=1} t_delta=0 reservations=0 refcount=2 cb_prog=0 r_addr= r_netid=-} owner=(4:0x00013d72) confirmed=1 seqid=761942 refcount=2}
I0731 14:20:55.050878   52096 nfs4_state_id.c:1157] [ COMPONENT_STATE : nfs4_Check_Stateid (NIV_FULL_DEBUG) ] Check READ stateid found valid stateid OTHER=0x010000008ca5aa6623d00500 {{CLIENTID Epoch=0x66aaa58c Counter=0x00000001} StateIdCounter=0x0005d023} seqid=1 - 0x12524c0d0
I0731 14:20:55.050887   52096 state_misc.c:913] [ COMPONENT_STATE : dec_state_owner_ref (NIV_FULL_DEBUG) ] Decrement refcount now=2 {STATE_OPEN_OWNER_NFSV4 0x1138c8e70: clientid={0x10b1d4400 ClientID={Epoch=0x66aaa58c Counter=0x00000001} CONFIRMED Client={0x600001b1b230 name=(58:0x01000000bcd0745295bb100224ba7f00000100000000000000003132372e302e302e313a2f002f566f6c756d65732f676f6f676c652f73726300) refcount=1} t_delta=0 reservations=1 refcount=2 cb_prog=0 r_addr= r_netid=-} owner=(4:0x00013d72) confirmed=1 seqid=761942 refcount=3}
I0731 14:20:55.050891   52096 sal_functions.h:417] [ COMPONENT_STATE : inc_state_t_ref (NIV_FULL_DEBUG) ] State 0x12524c0d0 refcount now 3
I0731 14:20:55.050930   52096 state_misc.c:802] [ COMPONENT_STATE : inc_state_owner_ref (NIV_FULL_DEBUG) ] Increment refcount now=3 {STATE_OPEN_OWNER_NFSV4 0x1138c8e70: clientid={0x10b1d4400 ClientID={Epoch=0x66aaa58c Counter=0x00000001} CONFIRMED Client={0x600001b1b230 name=(58:0x01000000bcd0745295bb100224ba7f00000100000000000000003132372e302e302e313a2f002f566f6c756d65732f676f6f676c652f73726300) refcount=1} t_delta=0 reservations=1 refcount=2 cb_prog=0 r_addr= r_netid=-} owner=(4:0x00013d72) confirmed=1 seqid=761942 refcount=2}
I0731 14:20:55.050937   52096 commonlib.c:2703] [ COMPONENT_FSAL : fsal_start_io (NIV_FULL_DEBUG) ] state_fd->openflags = 1 openflags = 1
I0731 14:20:55.050942   52096 commonlib.c:2326] [ COMPONENT_FSAL : wait_to_start_io (NIV_FULL_DEBUG) ] 0x12524c1c8 try io_work = 1 fd_work = 0
I0731 14:20:55.050946   52096 commonlib.c:2452] [ COMPONENT_FSAL : wait_to_start_io (NIV_FULL_DEBUG) ] Open mode = 1, desired mode = 1
I0731 14:20:55.050950   52096 commonlib.c:2720] [ COMPONENT_FSAL : fsal_start_io (NIV_FULL_DEBUG) ] Use state_fd 0x12524c1c8
I0731 14:20:55.050981   52096 commonlib.c:2912] [ COMPONENT_FSAL : fsal_complete_io (NIV_FULL_DEBUG) ] 0x12524c1c8 done io_work (-1) = 0 fd_work = 0
I0731 14:20:55.050994   52096 nfs4_state_id.c:509] [ COMPONENT_STATE : dec_nfs4_state_ref (NIV_FULL_DEBUG) ] Decrement refcount now=2 {STATE 0x12524c0d0 OTHER=0x010000008ca5aa6623d00500 {{CLIENTID Epoch=0x66aaa58c Counter=0x00000001} StateIdCounter=0x0005d023} obj=0x12524c158 type=SHARE seqid=1 owner={STATE_OPEN_OWNER_NFSV4 0x1138c8e70: clientid={0x10b1d4400 ClientID={Epoch=0x66aaa58c Counter=0x00000001} CONFIRMED Client={0x600001b1b230 name=(58:0x01000000bcd0745295bb100224ba7f00000100000000000000003132372e302e302e313a2f002f566f6c756d65732f676f6f676c652f73726300) refcount=1} t_delta=0 reservations=1 refcount=2 cb_prog=0 r_addr= r_netid=-} owner=(4:0x00013d72) confirmed=1 seqid=761942 refcount=3} refccount=3}
I0731 14:20:55.051002   52096 state_misc.c:913] [ COMPONENT_STATE : dec_state_owner_ref (NIV_FULL_DEBUG) ] Decrement refcount now=2 {STATE_OPEN_OWNER_NFSV4 0x1138c8e70: clientid={0x10b1d4400 ClientID={Epoch=0x66aaa58c Counter=0x00000001} CONFIRMED Client={0x600001b1b230 name=(58:0x01000000bcd0745295bb100224ba7f00000100000000000000003132372e302e302e313a2f002f566f6c756d65732f676f6f676c652f73726300) refcount=1} t_delta=0 reservations=1 refcount=2 cb_prog=0 r_addr= r_netid=-} owner=(4:0x00013d72) confirmed=1 seqid=761942 refcount=3}
I0731 14:20:55.051011   52096 nfs4_state_id.c:509] [ COMPONENT_STATE : dec_nfs4_state_ref (NIV_FULL_DEBUG) ] Decrement refcount now=1 {STATE 0x12524c0d0 OTHER=0x010000008ca5aa6623d00500 {{CLIENTID Epoch=0x66aaa58c Counter=0x00000001} StateIdCounter=0x0005d023} obj=0x12524c158 type=SHARE seqid=1 owner={STATE_OPEN_OWNER_NFSV4 0x1138c8e70: clientid={0x10b1d4400 ClientID={Epoch=0x66aaa58c Counter=0x00000001} CONFIRMED Client={0x600001b1b230 name=(58:0x01000000bcd0745295bb100224ba7f00000100000000000000003132372e302e302e313a2f002f566f6c756d65732f676f6f676c652f73726300) refcount=1} t_delta=0 reservations=1 refcount=2 cb_prog=0 r_addr= r_netid=-} owner=(4:0x00013d72) confirmed=1 seqid=761942 refcount=2} refccount=2}
I0731 14:20:55.051191   52097 nfs4_op_close.c:167] [ COMPONENT_STATE : nfs4_op_close (NIV_DEBUG) ] Entering NFS v4 CLOSE handler ----------------------------
I0731 14:20:55.051209   52097 nfs4_state_id.c:837] [ COMPONENT_STATE : nfs4_Check_Stateid (NIV_FULL_DEBUG) ] Check CLOSE stateid flags CLOSE_40
I0731 14:20:55.051216   52097 sal_functions.h:417] [ COMPONENT_STATE : inc_state_t_ref (NIV_FULL_DEBUG) ] State 0x12523dce0 refcount now 2
I0731 14:20:55.051254   52097 nfs4_state.c:606] [ COMPONENT_STATE : get_state_obj_export_owner_refs (NIV_FULL_DEBUG) ] state 0x12523dce0 state_obj 0x12523dd68 state_export 0x145609c10 state_owner 0x1138c8e70
I0731 14:20:55.051289   52097 state_misc.c:802] [ COMPONENT_STATE : inc_state_owner_ref (NIV_FULL_DEBUG) ] Increment refcount now=3 {STATE_OPEN_OWNER_NFSV4 0x1138c8e70: clientid={0x10b1d4400 ClientID={Epoch=0x66aaa58c Counter=0x00000001} CONFIRMED Client={0x600001b1b230 name=(58:0x01000000bcd0745295bb100224ba7f00000100000000000000003132372e302e302e313a2f002f566f6c756d65732f676f6f676c652f73726300) refcount=1} t_delta=0 reservations=0 refcount=2 cb_prog=0 r_addr= r_netid=-} owner=(4:0x00013d72) confirmed=1 seqid=761942 refcount=2}
I0731 14:20:55.051306   52097 nfs4_state_id.c:1157] [ COMPONENT_STATE : nfs4_Check_Stateid (NIV_FULL_DEBUG) ] Check CLOSE stateid found valid stateid OTHER=0x010000008ca5aa6621d00500 {{CLIENTID Epoch=0x66aaa58c Counter=0x00000001} StateIdCounter=0x0005d021} seqid=1 - 0x12523dce0
I0731 14:20:55.051316   52097 state_misc.c:913] [ COMPONENT_STATE : dec_state_owner_ref (NIV_FULL_DEBUG) ] Decrement refcount now=2 {STATE_OPEN_OWNER_NFSV4 0x1138c8e70: clientid={0x10b1d4400 ClientID={Epoch=0x66aaa58c Counter=0x00000001} CONFIRMED Client={0x600001b1b230 name=(58:0x01000000bcd0745295bb100224ba7f00000100000000000000003132372e302e302e313a2f002f566f6c756d65732f676f6f676c652f73726300) refcount=1} t_delta=0 reservations=1 refcount=2 cb_prog=0 r_addr= r_netid=-} owner=(4:0x00013d72) confirmed=1 seqid=761942 refcount=3}
I0731 14:20:55.051322   52097 nfs4_state.c:606] [ COMPONENT_STATE : get_state_obj_export_owner_refs (NIV_FULL_DEBUG) ] state 0x12523dce0 state_obj 0x12523dd68 state_export 0x145609c10 state_owner 0x1138c8e70
I0731 14:20:55.051331   52097 state_misc.c:802] [ COMPONENT_STATE : inc_state_owner_ref (NIV_FULL_DEBUG) ] Increment refcount now=3 {STATE_OPEN_OWNER_NFSV4 0x1138c8e70: clientid={0x10b1d4400 ClientID={Epoch=0x66aaa58c Counter=0x00000001} CONFIRMED Client={0x600001b1b230 name=(58:0x01000000bcd0745295bb100224ba7f00000100000000000000003132372e302e302e313a2f002f566f6c756d65732f676f6f676c652f73726300) refcount=1} t_delta=0 reservations=1 refcount=2 cb_prog=0 r_addr= r_netid=-} owner=(4:0x00013d72) confirmed=1 seqid=761942 refcount=2}
I0731 14:20:55.051339   52097 nfs4_owner.c:739] [ COMPONENT_STATE : Check_nfs4_seqid (NIV_FULL_DEBUG) ] CLOSE: Check {STATE_OPEN_OWNER_NFSV4 0x1138c8e70: clientid={0x10b1d4400 ClientID={Epoch=0x66aaa58c Counter=0x00000001} CONFIRMED Client={0x600001b1b230 name=(58:0x01000000bcd0745295bb100224ba7f00000100000000000000003132372e302e302e313a2f002f566f6c756d65732f676f6f676c652f73726300) refcount=1} t_delta=0 reservations=1 refcount=2 cb_prog=0 r_addr= r_netid=-} owner=(4:0x00013d72) confirmed=1 seqid=761942 refcount=3} next 761943 req seqid 761943
I0731 14:20:55.051345   52097 nfs4_state_id.c:1237] [ COMPONENT_STATE : update_stateid (NIV_DEBUG) ] Update CLOSE stateid to OTHER=0x010000008ca5aa6621d00500 {{CLIENTID Epoch=0x66aaa58c Counter=0x00000001} StateIdCounter=0x0005d021} seqid=2 for response
I0731 14:20:55.051359   52097 nfs4_state.c:365] [ COMPONENT_STATE : _state_del_locked (NIV_FULL_DEBUG) ] Deleting STATE 0x12523dce0 OTHER=0x010000008ca5aa6621d00500 {{CLIENTID Epoch=0x66aaa58c Counter=0x00000001} StateIdCounter=0x0005d021} obj=0x12523dd68 type=SHARE seqid=2 owner={STATE_OPEN_OWNER_NFSV4 0x1138c8e70: clientid={0x10b1d4400 ClientID={Epoch=0x66aaa58c Counter=0x00000001} CONFIRMED Client={0x600001b1b230 name=(58:0x01000000bcd0745295bb100224ba7f00000100000000000000003132372e302e302e313a2f002f566f6c756d65732f676f6f676c652f73726300) refcount=1} t_delta=0 reservations=1 refcount=2 cb_prog=0 r_addr= r_netid=-} owner=(4:0x00013d72) confirmed=1 seqid=761942 refcount=3} refccount=2
I0731 14:20:55.051367   52097 state_misc.c:913] [ COMPONENT_STATE : dec_state_owner_ref (NIV_FULL_DEBUG) ] Decrement refcount now=2 {STATE_OPEN_OWNER_NFSV4 0x1138c8e70: clientid={0x10b1d4400 ClientID={Epoch=0x66aaa58c Counter=0x00000001} CONFIRMED Client={0x600001b1b230 name=(58:0x01000000bcd0745295bb100224ba7f00000100000000000000003132372e302e302e313a2f002f566f6c756d65732f676f6f676c652f73726300) refcount=1} t_delta=0 reservations=1 refcount=2 cb_prog=0 r_addr= r_netid=-} owner=(4:0x00013d72) confirmed=1 seqid=761942 refcount=3}
I0731 14:20:55.051373   52097 commonlib.c:1269] [ COMPONENT_FSAL : update_share_counters (NIV_FULL_DEBUG) ] share counter: access_read 0, access_write 0, deny_read 0, deny_write 0, deny_write_v4 0
I0731 14:20:55.051378   52097 commonlib.c:2966] [ COMPONENT_FSAL : fsal_start_fd_work (NIV_FULL_DEBUG) ] 0x12523ddd8 try fd work - io_work = 0 fd_work = 1
I0731 14:20:55.051392   52097 commonlib.c:3015] [ COMPONENT_FSAL : fsal_complete_fd_work (NIV_FULL_DEBUG) ] 0x12523ddd8 done fd work io_work = 0 fd_work = 0
I0731 14:20:55.051399   52097 nfs4_state_id.c:509] [ COMPONENT_STATE : dec_nfs4_state_ref (NIV_FULL_DEBUG) ] Decrement refcount now=1 {STATE 0x12523dce0 OTHER=0x010000008ca5aa6621d00500 {{CLIENTID Epoch=0x66aaa58c Counter=0x00000001} StateIdCounter=0x0005d021} obj=0x12523dd68 type=SHARE seqid=2 owner={<NULL>} refccount=2}
I0731 14:20:55.051404   52097 nfs4_owner.c:652] [ COMPONENT_STATE : Copy_nfs4_state_req (NIV_FULL_DEBUG) ] CLOSE: saving response 0x1138c8e70 so_seqid 761942 new seqid 761943
I0731 14:20:55.051412   52097 state_misc.c:913] [ COMPONENT_STATE : dec_state_owner_ref (NIV_FULL_DEBUG) ] Decrement refcount now=1 {STATE_OPEN_OWNER_NFSV4 0x1138c8e70: clientid={0x10b1d4400 ClientID={Epoch=0x66aaa58c Counter=0x00000001} CONFIRMED Client={0x600001b1b230 name=(58:0x01000000bcd0745295bb100224ba7f00000100000000000000003132372e302e302e313a2f002f566f6c756d65732f676f6f676c652f73726300) refcount=1} t_delta=0 reservations=1 refcount=2 cb_prog=0 r_addr= r_netid=-} owner=(4:0x00013d72) confirmed=1 seqid=761943 refcount=2}
I0731 14:20:55.051418   52097 nfs4_state_id.c:519] [ COMPONENT_STATE : dec_nfs4_state_ref (NIV_FULL_DEBUG) ] Deleted STATE 0x12523dce0 OTHER=0x010000008ca5aa6621d00500 {{CLIENTID Epoch=0x66aaa58c Counter=0x00000001} StateIdCounter=0x0005d021} obj=0x12523dd68 type=SHARE seqid=2 owner={<NULL>} refccount=1
I0731 14:20:55.052358   52097 nfs4_op_open.c:1259] [ COMPONENT_STATE : nfs4_op_open (NIV_DEBUG) ] Entering NFS v4 OPEN handler -----------------------------
I0731 14:20:55.052375   52097 nfs4_op_open.c:1267] [ COMPONENT_STATE : nfs4_op_open (NIV_FULL_DEBUG) ] OPEN: Claim type = 0, Open Type = 0, Share Deny = 0, Share Access = 1
I0731 14:20:55.052379   52097 nfs4_op_open.c:1319] [ COMPONENT_STATE : nfs4_op_open (NIV_DEBUG) ] OPEN Client id = 66aaa58c00000001
I0731 14:20:55.052389   52097 nfs4_owner.c:453] [ COMPONENT_STATE : create_nfs4_owner (NIV_FULL_DEBUG) ] Key=STATE_OPEN_OWNER_NFSV4 0x338c55660: clientid={0x10b1d4400 ClientID={Epoch=0x66aaa58c Counter=0x00000001} CONFIRMED Client={0x600001b1b230 name=(58:0x01000000bcd0745295bb100224ba7f00000100000000000000003132372e302e302e313a2f002f566f6c756d65732f676f6f676c652f73726300) refcount=1} t_delta=0 reservations=1 refcount=3 cb_prog=0 r_addr= r_netid=-} owner=(4:0x00013d72) confirmed=0 seqid=0 refcount=1
I0731 14:20:55.052450   52097 state_misc.c:1064] [ COMPONENT_STATE : get_state_owner (NIV_FULL_DEBUG) ] Find {STATE_OPEN_OWNER_NFSV4 0x338c55660: clientid={0x10b1d4400 ClientID={Epoch=0x66aaa58c Counter=0x00000001} CONFIRMED Client={0x600001b1b230 name=(58:0x01000000bcd0745295bb100224ba7f00000100000000000000003132372e302e302e313a2f002f566f6c756d65732f676f6f676c652f73726300) refcount=1} t_delta=0 reservations=1 refcount=3 cb_prog=0 r_addr= r_netid=-} owner=(4:0x00013d72) confirmed=0 seqid=0 refcount=1}
I0731 14:20:55.052405   52096 commonlib.c:2966] [ COMPONENT_FSAL : fsal_start_fd_work (NIV_FULL_DEBUG) ] 0x113805cc8 try fd work - io_work = 0 fd_work = 1
I0731 14:20:55.052507   52096 commonlib.c:3015] [ COMPONENT_FSAL : fsal_complete_fd_work (NIV_FULL_DEBUG) ] 0x113805cc8 done fd work io_work = 0 fd_work = 0
I0731 14:20:55.052514   52096 commonlib.c:2966] [ COMPONENT_FSAL : fsal_start_fd_work (NIV_FULL_DEBUG) ] 0x113805cc8 try fd work - io_work = 0 fd_work = 1
I0731 14:20:55.052519   52096 commonlib.c:3015] [ COMPONENT_FSAL : fsal_complete_fd_work (NIV_FULL_DEBUG) ] 0x113805cc8 done fd work io_work = 0 fd_work = 0
I0731 14:20:55.052538   52097 state_misc.c:1117] [ COMPONENT_STATE : get_state_owner (NIV_FULL_DEBUG) ] Found {STATE_OPEN_OWNER_NFSV4 0x338c55660: clientid={0x10b1d4400 ClientID={Epoch=0x66aaa58c Counter=0x00000001} CONFIRMED Client={0x600001b1b230 name=(58:0x01000000bcd0745295bb100224ba7f00000100000000000000003132372e302e302e313a2f002f566f6c756d65732f676f6f676c652f73726300) refcount=1} t_delta=0 reservations=1 refcount=3 cb_prog=0 r_addr= r_netid=-} owner=(4:0x00013d72) confirmed=0 seqid=0 refcount=1STATE_OPEN_OWNER_NFSV4 0x1138c8e70: clientid={0x10b1d4400 ClientID={Epoch=0x66aaa58c Counter=0x00000001} CONFIRMED Client={0x600001b1b230 name=(58:0x01000000bcd0745295bb100224ba7f00000100000000000000003132372e302e302e313a2f002f566f6c756d65732f676f6f676c652f73726300) refcount=1} t_delta=0 reservations=1 refcount=3 cb_prog=0 r_addr= r_netid=-} owner=(4:0x00013d72) confirmed=1 seqid=761943 refcount=2} refcount now=2
I0731 14:20:55.052555   52097 nfs4_owner.c:500] [ COMPONENT_STATE : create_nfs4_owner (NIV_DEBUG) ] Previously known owner {STATE_OPEN_OWNER_NFSV4 0x1138c8e70: clientid={0x10b1d4400 ClientID={Epoch=0x66aaa58c Counter=0x00000001} CONFIRMED Client={0x600001b1b230 name=(58:0x01000000bcd0745295bb100224ba7f00000100000000000000003132372e302e302e313a2f002f566f6c756d65732f676f6f676c652f73726300) refcount=1} t_delta=0 reservations=1 refcount=3 cb_prog=0 r_addr= r_netid=-} owner=(4:0x00013d72) confirmed=1 seqid=761943 refcount=2} is being reused
I0731 14:20:55.052593   52097 nfs4_op_open.c:234] [ COMPONENT_STATE : open4_open_owner (NIV_FULL_DEBUG) ] Open: STATE_OPEN_OWNER_NFSV4 0x1138c8e70: clientid={0x10b1d4400 ClientID={Epoch=0x66aaa58c Counter=0x00000001} CONFIRMED Client={0x600001b1b230 name=(58:0x01000000bcd0745295bb100224ba7f00000100000000000000003132372e302e302e313a2f002f566f6c756d65732f676f6f676c652f73726300) refcount=1} t_delta=0 reservations=1 refcount=3 cb_prog=0 r_addr= r_netid=-} owner=(4:0x00013d72) confirmed=1 seqid=761943 refcount=2
I0731 14:20:55.052638   52097 nfs4_owner.c:739] [ COMPONENT_STATE : Check_nfs4_seqid (NIV_FULL_DEBUG) ] OPEN: Check {STATE_OPEN_OWNER_NFSV4 0x1138c8e70: clientid={0x10b1d4400 ClientID={Epoch=0x66aaa58c Counter=0x00000001} CONFIRMED Client={0x600001b1b230 name=(58:0x01000000bcd0745295bb100224ba7f00000100000000000000003132372e302e302e313a2f002f566f6c756d65732f676f6f676c652f73726300) refcount=1} t_delta=0 reservations=1 refcount=3 cb_prog=0 r_addr= r_netid=-} owner=(4:0x00013d72) confirmed=1 seqid=761943 refcount=2} next 761944 req seqid 761944
I0731 14:20:55.052735   52097 commonlib.c:2966] [ COMPONENT_FSAL : fsal_start_fd_work (NIV_FULL_DEBUG) ] 0x113cf2d18 try fd work - io_work = 0 fd_work = 1
I0731 14:20:55.052743   52097 commonlib.c:3015] [ COMPONENT_FSAL : fsal_complete_fd_work (NIV_FULL_DEBUG) ] 0x113cf2d18 done fd work io_work = 0 fd_work = 0
I0731 14:20:55.052749   52097 commonlib.c:2966] [ COMPONENT_FSAL : fsal_start_fd_work (NIV_FULL_DEBUG) ] 0x113cf2d18 try fd work - io_work = 0 fd_work = 1
I0731 14:20:55.052753   52097 commonlib.c:3015] [ COMPONENT_FSAL : fsal_complete_fd_work (NIV_FULL_DEBUG) ] 0x113cf2d18 done fd work io_work = 0 fd_work = 0
I0731 14:20:55.052773   52097 nfs4_state_id.c:703] [ COMPONENT_STATE : nfs4_State_Get_Obj (NIV_DEBUG) ] HashTable_Get returned 2
I0731 14:20:55.052779   52097 nfs4_op_open.c:989] [ COMPONENT_STATE : open4_ex (NIV_FULL_DEBUG) ] Calling open2 for (null)
I0731 14:20:55.052784   52097 fsal_helper.c:1607] [ COMPONENT_FSAL : fsal_open2 (NIV_FULL_DEBUG) ] attrs  set attributes No attributes
I0731 14:20:55.052789   52097 fsal_helper.c:173] [ COMPONENT_FSAL : fsal_check_create_owner (NIV_FULL_DEBUG) ] attr->owner 0 caller_uid 81266 attr->group 0 caller_gid 89939
I0731 14:20:55.052803   52097 commonlib.c:2966] [ COMPONENT_FSAL : fsal_start_fd_work (NIV_FULL_DEBUG) ] 0x11081f048 try fd work - io_work = 0 fd_work = 1
I0731 14:20:55.052837   52097 commonlib.c:1813] [ COMPONENT_FSAL : insert_fd_lru (NIV_FULL_DEBUG) ] Inserting fsal_fd(0x11081f048) to fd_lru for type(2) count(0/380963/0)
I0731 14:20:55.052885   52097 commonlib.c:1269] [ COMPONENT_FSAL : update_share_counters (NIV_FULL_DEBUG) ] share counter: access_read 1, access_write 0, deny_read 0, deny_write 0, deny_write_v4 0
I0731 14:20:55.052913   52097 commonlib.c:3015] [ COMPONENT_FSAL : fsal_complete_fd_work (NIV_FULL_DEBUG) ] 0x11081f048 done fd work io_work = 0 fd_work = 0
I0731 14:20:55.052926   52097 nfs4_op_open.c:1072] [ COMPONENT_STATE : open4_ex (NIV_FULL_DEBUG) ] Creating new state access=1 deny=0 access_prev=2 deny_prev=1
I0731 14:20:55.052933   52097 nfs4_state.c:107] [ COMPONENT_STATE : _state_add_impl (NIV_FULL_DEBUG) ] pnew_state=STATE 0x11081ef50 OTHER=0x000000000000000000000000 {{CLIENTID Epoch=0x00000000 Counter=0x00000000} State...
I0731 14:20:55.052938   52097 nfs4_state.c:164] [ COMPONENT_STATE : _state_add_impl (NIV_FULL_DEBUG) ] About to call nfs4_State_Set for OTHER=0x010000008ca5aa6624d00500 {{CLIENTID Epoch=0x66aaa58c Counter=0x00000001} StateIdCounter=0x0005d024}
I0731 14:20:55.052948   52097 state_misc.c:802] [ COMPONENT_STATE : inc_state_owner_ref (NIV_FULL_DEBUG) ] Increment refcount now=3 {STATE_OPEN_OWNER_NFSV4 0x1138c8e70: clientid={0x10b1d4400 ClientID={Epoch=0x66aaa58c Counter=0x00000001} CONFIRMED Client={0x600001b1b230 name=(58:0x01000000bcd0745295bb100224ba7f00000100000000000000003132372e302e302e313a2f002f566f6c756d65732f676f6f676c652f73726300) refcount=1} t_delta=0 reservations=1 refcount=3 cb_prog=0 r_addr= r_netid=-} owner=(4:0x00013d72) confirmed=1 seqid=761943 refcount=2}
I0731 14:20:55.052953   52097 nfs4_state.c:258] [ COMPONENT_STATE : _state_add_impl (NIV_FULL_DEBUG) ] Add State: 0x11081ef50: OTHER=0x010000008ca5aa6624d00500 {{CLIENTID Epoch=0x66aaa58c Counter=0x00000001} StateIdCounter=0x0005d024}
I0731 14:20:55.052958   52097 nfs4_op_open.c:577] [ COMPONENT_STATE : do_delegation (NIV_FULL_DEBUG) ] Delegation type not supported.
I0731 14:20:55.052962   52097 nfs4_op_open.c:1417] [ COMPONENT_STATE : nfs4_op_open (NIV_FULL_DEBUG) ] NFS4 OPEN returning NFS4_OK
I0731 14:20:55.052977   52097 nfs4_state_id.c:1237] [ COMPONENT_STATE : update_stateid (NIV_DEBUG) ] Update OPEN stateid to OTHER=0x010000008ca5aa6624d00500 {{CLIENTID Epoch=0x66aaa58c Counter=0x00000001} StateIdCounter=0x0005d024} seqid=1 for response
I0731 14:20:55.052983   52097 nfs4_owner.c:652] [ COMPONENT_STATE : Copy_nfs4_state_req (NIV_FULL_DEBUG) ] OPEN: saving response 0x1138c8e70 so_seqid 761943 new seqid 761944
I0731 14:20:55.052993   52097 nfs4_state_id.c:509] [ COMPONENT_STATE : dec_nfs4_state_ref (NIV_FULL_DEBUG) ] Decrement refcount now=1 {STATE 0x11081ef50 OTHER=0x010000008ca5aa6624d00500 {{CLIENTID Epoch=0x66aaa58c Counter=0x00000001} StateIdCounter=0x0005d024} obj=0x11081efd8 type=SHARE seqid=1 owner={STATE_OPEN_OWNER_NFSV4 0x1138c8e70: clientid={0x10b1d4400 ClientID={Epoch=0x66aaa58c Counter=0x00000001} CONFIRMED Client={0x600001b1b230 name=(58:0x01000000bcd0745295bb100224ba7f00000100000000000000003132372e302e302e313a2f002f566f6c756d65732f676f6f676c652f73726300) refcount=1} t_delta=0 reservations=0 refcount=3 cb_prog=0 r_addr= r_netid=-} owner=(4:0x00013d72) confirmed=1 seqid=761944 refcount=3} refccount=2}
I0731 14:20:55.053001   52097 state_misc.c:913] [ COMPONENT_STATE : dec_state_owner_ref (NIV_FULL_DEBUG) ] Decrement refcount now=2 {STATE_OPEN_OWNER_NFSV4 0x1138c8e70: clientid={0x10b1d4400 ClientID={Epoch=0x66aaa58c Counter=0x00000001} CONFIRMED Client={0x600001b1b230 name=(58:0x01000000bcd0745295bb100224ba7f00000100000000000000003132372e302e302e313a2f002f566f6c756d65732f676f6f676c652f73726300) refcount=1} t_delta=0 reservations=0 refcount=3 cb_prog=0 r_addr= r_netid=-} owner=(4:0x00013d72) confirmed=1 seqid=761944 refcount=3}
I0731 14:20:55.053871   47616 commonlib.c:2966] [ COMPONENT_FSAL : fsal_start_fd_work (NIV_FULL_DEBUG) ] 0x1263d1198 try fd work - io_work = 0 fd_work = 1
I0731 14:20:55.053886   47616 commonlib.c:3015] [ COMPONENT_FSAL : fsal_complete_fd_work (NIV_FULL_DEBUG) ] 0x1263d1198 done fd work io_work = 0 fd_work = 0
I0731 14:20:55.053891   47616 commonlib.c:2966] [ COMPONENT_FSAL : fsal_start_fd_work (NIV_FULL_DEBUG) ] 0x1263d1198 try fd work - io_work = 0 fd_work = 1
I0731 14:20:55.053895   47616 commonlib.c:3015] [ COMPONENT_FSAL : fsal_complete_fd_work (NIV_FULL_DEBUG) ] 0x1263d1198 done fd work io_work = 0 fd_work = 0
I0731 14:20:55.053973   52097 nfs4_state_id.c:837] [ COMPONENT_STATE : nfs4_Check_Stateid (NIV_FULL_DEBUG) ] Check READ stateid flags ALL_0 ALL_1 CURRENT
I0731 14:20:55.053985   52097 sal_functions.h:417] [ COMPONENT_STATE : inc_state_t_ref (NIV_FULL_DEBUG) ] State 0x11081ef50 refcount now 2
I0731 14:20:55.053990   52097 nfs4_state.c:606] [ COMPONENT_STATE : get_state_obj_export_owner_refs (NIV_FULL_DEBUG) ] state 0x11081ef50 state_obj 0x11081efd8 state_export 0x145609c10 state_owner 0x1138c8e70
I0731 14:20:55.053999   52097 state_misc.c:802] [ COMPONENT_STATE : inc_state_owner_ref (NIV_FULL_DEBUG) ] Increment refcount now=3 {STATE_OPEN_OWNER_NFSV4 0x1138c8e70: clientid={0x10b1d4400 ClientID={Epoch=0x66aaa58c Counter=0x00000001} CONFIRMED Client={0x600001b1b230 name=(58:0x01000000bcd0745295bb100224ba7f00000100000000000000003132372e302e302e313a2f002f566f6c756d65732f676f6f676c652f73726300) refcount=1} t_delta=0 reservations=0 refcount=2 cb_prog=0 r_addr= r_netid=-} owner=(4:0x00013d72) confirmed=1 seqid=761944 refcount=2}
I0731 14:20:55.054004   52097 nfs4_state_id.c:1157] [ COMPONENT_STATE : nfs4_Check_Stateid (NIV_FULL_DEBUG) ] Check READ stateid found valid stateid OTHER=0x010000008ca5aa6624d00500 {{CLIENTID Epoch=0x66aaa58c Counter=0x00000001} StateIdCounter=0x0005d024} seqid=1 - 0x11081ef50
I0731 14:20:55.054013   52097 state_misc.c:913] [ COMPONENT_STATE : dec_state_owner_ref (NIV_FULL_DEBUG) ] Decrement refcount now=2 {STATE_OPEN_OWNER_NFSV4 0x1138c8e70: clientid={0x10b1d4400 ClientID={Epoch=0x66aaa58c Counter=0x00000001} CONFIRMED Client={0x600001b1b230 name=(58:0x01000000bcd0745295bb100224ba7f00000100000000000000003132372e302e302e313a2f002f566f6c756d65732f676f6f676c652f73726300) refcount=1} t_delta=0 reservations=1 refcount=2 cb_prog=0 r_addr= r_netid=-} owner=(4:0x00013d72) confirmed=1 seqid=761944 refcount=3}
I0731 14:20:55.054017   52097 sal_functions.h:417] [ COMPONENT_STATE : inc_state_t_ref (NIV_FULL_DEBUG) ] State 0x11081ef50 refcount now 3
I0731 14:20:55.054048   52097 state_misc.c:802] [ COMPONENT_STATE : inc_state_owner_ref (NIV_FULL_DEBUG) ] Increment refcount now=3 {STATE_OPEN_OWNER_NFSV4 0x1138c8e70: clientid={0x10b1d4400 ClientID={Epoch=0x66aaa58c Counter=0x00000001} CONFIRMED Client={0x600001b1b230 name=(58:0x01000000bcd0745295bb100224ba7f00000100000000000000003132372e302e302e313a2f002f566f6c756d65732f676f6f676c652f73726300) refcount=1} t_delta=0 reservations=1 refcount=2 cb_prog=0 r_addr= r_netid=-} owner=(4:0x00013d72) confirmed=1 seqid=761944 refcount=2}
I0731 14:20:55.054054   52097 commonlib.c:2703] [ COMPONENT_FSAL : fsal_start_io (NIV_FULL_DEBUG) ] state_fd->openflags = 1 openflags = 1
I0731 14:20:55.054059   52097 commonlib.c:2326] [ COMPONENT_FSAL : wait_to_start_io (NIV_FULL_DEBUG) ] 0x11081f048 try io_work = 1 fd_work = 0
I0731 14:20:55.054063   52097 commonlib.c:2452] [ COMPONENT_FSAL : wait_to_start_io (NIV_FULL_DEBUG) ] Open mode = 1, desired mode = 1
I0731 14:20:55.054068   52097 commonlib.c:2720] [ COMPONENT_FSAL : fsal_start_io (NIV_FULL_DEBUG) ] Use state_fd 0x11081f048
I0731 14:20:55.054125   47616 nfs4_op_close.c:167] [ COMPONENT_STATE : nfs4_op_close (NIV_DEBUG) ] Entering NFS v4 CLOSE handler ----------------------------
I0731 14:20:55.054132   47616 nfs4_state_id.c:837] [ COMPONENT_STATE : nfs4_Check_Stateid (NIV_FULL_DEBUG) ] Check CLOSE stateid flags CLOSE_40
I0731 14:20:55.054139   47616 sal_functions.h:417] [ COMPONENT_STATE : inc_state_t_ref (NIV_FULL_DEBUG) ] State 0x113a8a700 refcount now 2
I0731 14:20:55.054143   47616 nfs4_state.c:606] [ COMPONENT_STATE : get_state_obj_export_owner_refs (NIV_FULL_DEBUG) ] state 0x113a8a700 state_obj 0x113a8a788 state_export 0x145609c10 state_owner 0x1138c8e70
I0731 14:20:55.054154   47616 state_misc.c:802] [ COMPONENT_STATE : inc_state_owner_ref (NIV_FULL_DEBUG) ] Increment refcount now=4 {STATE_OPEN_OWNER_NFSV4 0x1138c8e70: clientid={0x10b1d4400 ClientID={Epoch=0x66aaa58c Counter=0x00000001} CONFIRMED Client={0x600001b1b230 name=(58:0x01000000bcd0745295bb100224ba7f00000100000000000000003132372e302e302e313a2f002f566f6c756d65732f676f6f676c652f73726300) refcount=1} t_delta=0 reservations=1 refcount=2 cb_prog=0 r_addr= r_netid=-} owner=(4:0x00013d72) confirmed=1 seqid=761944 refcount=3}
I0731 14:20:55.054159   47616 nfs4_state_id.c:1157] [ COMPONENT_STATE : nfs4_Check_Stateid (NIV_FULL_DEBUG) ] Check CLOSE stateid found valid stateid OTHER=0x010000008ca5aa6622d00500 {{CLIENTID Epoch=0x66aaa58c Counter=0x00000001} StateIdCounter=0x0005d022} seqid=1 - 0x113a8a700
I0731 14:20:55.054167   47616 state_misc.c:913] [ COMPONENT_STATE : dec_state_owner_ref (NIV_FULL_DEBUG) ] Decrement refcount now=3 {STATE_OPEN_OWNER_NFSV4 0x1138c8e70: clientid={0x10b1d4400 ClientID={Epoch=0x66aaa58c Counter=0x00000001} CONFIRMED Client={0x600001b1b230 name=(58:0x01000000bcd0745295bb100224ba7f00000100000000000000003132372e302e302e313a2f002f566f6c756d65732f676f6f676c652f73726300) refcount=1} t_delta=0 reservations=2 refcount=2 cb_prog=0 r_addr= r_netid=-} owner=(4:0x00013d72) confirmed=1 seqid=761944 refcount=4}
I0731 14:20:55.054143   52097 commonlib.c:2912] [ COMPONENT_FSAL : fsal_complete_io (NIV_FULL_DEBUG) ] 0x11081f048 done io_work (-1) = 0 fd_work = 0
I0731 14:20:55.054171   47616 nfs4_state.c:606] [ COMPONENT_STATE : get_state_obj_export_owner_refs (NIV_FULL_DEBUG) ] state 0x113a8a700 state_obj 0x113a8a788 state_export 0x145609c10 state_owner 0x1138c8e70
I0731 14:20:55.054188   52097 nfs4_state_id.c:509] [ COMPONENT_STATE : dec_nfs4_state_ref (NIV_FULL_DEBUG) ] Decrement refcount now=2 {STATE 0x11081ef50 OTHER=0x010000008ca5aa6624d00500 {{CLIENTID Epoch=0x66aaa58c Counter=0x00000001} StateIdCounter=0x0005d024} obj=0x11081efd8 type=SHARE seqid=1 owner={STATE_OPEN_OWNER_NFSV4 0x1138c8e70: clientid={0x10b1d4400 ClientID={Epoch=0x66aaa58c Counter=0x00000001} CONFIRMED Client={0x600001b1b230 name=(58:0x01000000bcd0745295bb100224ba7f00000100000000000000003132372e302e302e313a2f002f566f6c756d65732f676f6f676c652f73726300) refcount=1} t_delta=0 reservations=2 refcount=2 cb_prog=0 r_addr= r_netid=-} owner=(4:0x00013d72) confirmed=1 seqid=761944 refcount=3} refccount=3}
I0731 14:20:55.054202   52097 state_misc.c:913] [ COMPONENT_STATE : dec_state_owner_ref (NIV_FULL_DEBUG) ] Decrement refcount now=3 {STATE_OPEN_OWNER_NFSV4 0x1138c8e70: clientid={0x10b1d4400 ClientID={Epoch=0x66aaa58c Counter=0x00000001} CONFIRMED Client={0x600001b1b230 name=(58:0x01000000bcd0745295bb100224ba7f00000100000000000000003132372e302e302e313a2f002f566f6c756d65732f676f6f676c652f73726300) refcount=1} t_delta=0 reservations=2 refcount=2 cb_prog=0 r_addr= r_netid=-} owner=(4:0x00013d72) confirmed=1 seqid=761944 refcount=4}
I0731 14:20:55.054212   52097 nfs4_state_id.c:509] [ COMPONENT_STATE : dec_nfs4_state_ref (NIV_FULL_DEBUG) ] Decrement refcount now=1 {STATE 0x11081ef50 OTHER=0x010000008ca5aa6624d00500 {{CLIENTID Epoch=0x66aaa58c Counter=0x00000001} StateIdCounter=0x0005d024} obj=0x11081efd8 type=SHARE seqid=1 owner={STATE_OPEN_OWNER_NFSV4 0x1138c8e70: clientid={0x10b1d4400 ClientID={Epoch=0x66aaa58c Counter=0x00000001} CONFIRMED Client={0x600001b1b230 name=(58:0x01000000bcd0745295bb100224ba7f00000100000000000000003132372e302e302e313a2f002f566f6c756d65732f676f6f676c652f73726300) refcount=1} t_delta=0 reservations=2 refcount=2 cb_prog=0 r_addr= r_netid=-} owner=(4:0x00013d72) confirmed=1 seqid=761944 refcount=3} refccount=2}
I0731 14:20:55.054190   47616 state_misc.c:802] [ COMPONENT_STATE : inc_state_owner_ref (NIV_FULL_DEBUG) ] Increment refcount now=4 {STATE_OPEN_OWNER_NFSV4 0x1138c8e70: clientid={0x10b1d4400 ClientID={Epoch=0x66aaa58c Counter=0x00000001} CONFIRMED Client={0x600001b1b230 name=(58:0x01000000bcd0745295bb100224ba7f00000100000000000000003132372e302e302e313a2f002f566f6c756d65732f676f6f676c652f73726300) refcount=1} t_delta=0 reservations=2 refcount=2 cb_prog=0 r_addr= r_netid=-} owner=(4:0x00013d72) confirmed=1 seqid=761944 refcount=3}
I0731 14:20:55.054270   47616 nfs4_owner.c:739] [ COMPONENT_STATE : Check_nfs4_seqid (NIV_FULL_DEBUG) ] CLOSE: Check {STATE_OPEN_OWNER_NFSV4 0x1138c8e70: clientid={0x10b1d4400 ClientID={Epoch=0x66aaa58c Counter=0x00000001} CONFIRMED Client={0x600001b1b230 name=(58:0x01000000bcd0745295bb100224ba7f00000100000000000000003132372e302e302e313a2f002f566f6c756d65732f676f6f676c652f73726300) refcount=1} t_delta=0 reservations=1 refcount=2 cb_prog=0 r_addr= r_netid=-} owner=(4:0x00013d72) confirmed=1 seqid=761944 refcount=3} next 761945 req seqid 761945
I0731 14:20:55.054318   47616 nfs4_state_id.c:1237] [ COMPONENT_STATE : update_stateid (NIV_DEBUG) ] Update CLOSE stateid to OTHER=0x010000008ca5aa6622d00500 {{CLIENTID Epoch=0x66aaa58c Counter=0x00000001} StateIdCounter=0x0005d022} seqid=2 for response
I0731 14:20:55.054331   47616 nfs4_state.c:365] [ COMPONENT_STATE : _state_del_locked (NIV_FULL_DEBUG) ] Deleting STATE 0x113a8a700 OTHER=0x010000008ca5aa6622d00500 {{CLIENTID Epoch=0x66aaa58c Counter=0x00000001} StateIdCounter=0x0005d022} obj=0x113a8a788 type=SHARE seqid=2 owner={STATE_OPEN_OWNER_NFSV4 0x1138c8e70: clientid={0x10b1d4400 ClientID={Epoch=0x66aaa58c Counter=0x00000001} CONFIRMED Client={0x600001b1b230 name=(58:0x01000000bcd0745295bb100224ba7f00000100000000000000003132372e302e302e313a2f002f566f6c756d65732f676f6f676c652f73726300) refcount=1} t_delta=0 reservations=1 refcount=2 cb_prog=0 r_addr= r_netid=-} owner=(4:0x00013d72) confirmed=1 seqid=761944 refcount=3} refccount=2
I0731 14:20:55.054340   47616 state_misc.c:913] [ COMPONENT_STATE : dec_state_owner_ref (NIV_FULL_DEBUG) ] Decrement refcount now=2 {STATE_OPEN_OWNER_NFSV4 0x1138c8e70: clientid={0x10b1d4400 ClientID={Epoch=0x66aaa58c Counter=0x00000001} CONFIRMED Client={0x600001b1b230 name=(58:0x01000000bcd0745295bb100224ba7f00000100000000000000003132372e302e302e313a2f002f566f6c756d65732f676f6f676c652f73726300) refcount=1} t_delta=0 reservations=1 refcount=2 cb_prog=0 r_addr= r_netid=-} owner=(4:0x00013d72) confirmed=1 seqid=761944 refcount=3}
I0731 14:20:55.054345   47616 commonlib.c:1269] [ COMPONENT_FSAL : update_share_counters (NIV_FULL_DEBUG) ] share counter: access_read 0, access_write 0, deny_read 0, deny_write 0, deny_write_v4 0
I0731 14:20:55.054349   47616 commonlib.c:2966] [ COMPONENT_FSAL : fsal_start_fd_work (NIV_FULL_DEBUG) ] 0x113a8a7f8 try fd work - io_work = 0 fd_work = 1
I0731 14:20:55.054407   47616 commonlib.c:3015] [ COMPONENT_FSAL : fsal_complete_fd_work (NIV_FULL_DEBUG) ] 0x113a8a7f8 done fd work io_work = 0 fd_work = 0
I0731 14:20:55.054414   47616 nfs4_state_id.c:509] [ COMPONENT_STATE : dec_nfs4_state_ref (NIV_FULL_DEBUG) ] Decrement refcount now=1 {STATE 0x113a8a700 OTHER=0x010000008ca5aa6622d00500 {{CLIENTID Epoch=0x66aaa58c Counter=0x00000001} StateIdCounter=0x0005d022} obj=0x113a8a788 type=SHARE seqid=2 owner={<NULL>} refccount=2}
I0731 14:20:55.054420   47616 nfs4_owner.c:652] [ COMPONENT_STATE : Copy_nfs4_state_req (NIV_FULL_DEBUG) ] CLOSE: saving response 0x1138c8e70 so_seqid 761944 new seqid 761945
I0731 14:20:55.054428   47616 state_misc.c:913] [ COMPONENT_STATE : dec_state_owner_ref (NIV_FULL_DEBUG) ] Decrement refcount now=1 {STATE_OPEN_OWNER_NFSV4 0x1138c8e70: clientid={0x10b1d4400 ClientID={Epoch=0x66aaa58c Counter=0x00000001} CONFIRMED Client={0x600001b1b230 name=(58:0x01000000bcd0745295bb100224ba7f00000100000000000000003132372e302e302e313a2f002f566f6c756d65732f676f6f676c652f73726300) refcount=1} t_delta=0 reservations=1 refcount=2 cb_prog=0 r_addr= r_netid=-} owner=(4:0x00013d72) confirmed=1 seqid=761945 refcount=2}
I0731 14:20:55.054433   47616 nfs4_state_id.c:519] [ COMPONENT_STATE : dec_nfs4_state_ref (NIV_FULL_DEBUG) ] Deleted STATE 0x113a8a700 OTHER=0x010000008ca5aa6622d00500 {{CLIENTID Epoch=0x66aaa58c Counter=0x00000001} StateIdCounter=0x0005d022} obj=0x113a8a788 type=SHARE seqid=2 owner={<NULL>} refccount=1
I0731 14:20:55.056245   52104 nfs4_op_close.c:167] [ COMPONENT_STATE : nfs4_op_close (NIV_DEBUG) ] Entering NFS v4 CLOSE handler ----------------------------
I0731 14:20:55.056262   52104 nfs4_state_id.c:837] [ COMPONENT_STATE : nfs4_Check_Stateid (NIV_FULL_DEBUG) ] Check CLOSE stateid flags CLOSE_40
I0731 14:20:55.056269   52104 sal_functions.h:417] [ COMPONENT_STATE : inc_state_t_ref (NIV_FULL_DEBUG) ] State 0x11081ef50 refcount now 2
I0731 14:20:55.056360   52104 nfs4_state.c:606] [ COMPONENT_STATE : get_state_obj_export_owner_refs (NIV_FULL_DEBUG) ] state 0x11081ef50 state_obj 0x11081efd8 state_export 0x145609c10 state_owner 0x1138c8e70
I0731 14:20:55.056374   52104 state_misc.c:802] [ COMPONENT_STATE : inc_state_owner_ref (NIV_FULL_DEBUG) ] Increment refcount now=2 {STATE_OPEN_OWNER_NFSV4 0x1138c8e70: clientid={0x10b1d4400 ClientID={Epoch=0x66aaa58c Counter=0x00000001} CONFIRMED Client={0x600001b1b230 name=(58:0x01000000bcd0745295bb100224ba7f00000100000000000000003132372e302e302e313a2f002f566f6c756d65732f676f6f676c652f73726300) refcount=1} t_delta=0 reservations=0 refcount=2 cb_prog=0 r_addr= r_netid=-} owner=(4:0x00013d72) confirmed=1 seqid=761945 refcount=1}
I0731 14:20:55.056379   52104 nfs4_state_id.c:1157] [ COMPONENT_STATE : nfs4_Check_Stateid (NIV_FULL_DEBUG) ] Check CLOSE stateid found valid stateid OTHER=0x010000008ca5aa6624d00500 {{CLIENTID Epoch=0x66aaa58c Counter=0x00000001} StateIdCounter=0x0005d024} seqid=1 - 0x11081ef50
I0731 14:20:55.056387   52104 state_misc.c:913] [ COMPONENT_STATE : dec_state_owner_ref (NIV_FULL_DEBUG) ] Decrement refcount now=1 {STATE_OPEN_OWNER_NFSV4 0x1138c8e70: clientid={0x10b1d4400 ClientID={Epoch=0x66aaa58c Counter=0x00000001} CONFIRMED Client={0x600001b1b230 name=(58:0x01000000bcd0745295bb100224ba7f00000100000000000000003132372e302e302e313a2f002f566f6c756d65732f676f6f676c652f73726300) refcount=1} t_delta=0 reservations=1 refcount=2 cb_prog=0 r_addr= r_netid=-} owner=(4:0x00013d72) confirmed=1 seqid=761945 refcount=2}
I0731 14:20:55.056391   52104 nfs4_state.c:606] [ COMPONENT_STATE : get_state_obj_export_owner_refs (NIV_FULL_DEBUG) ] state 0x11081ef50 state_obj 0x11081efd8 state_export 0x145609c10 state_owner 0x1138c8e70
I0731 14:20:55.056399   52104 state_misc.c:802] [ COMPONENT_STATE : inc_state_owner_ref (NIV_FULL_DEBUG) ] Increment refcount now=2 {STATE_OPEN_OWNER_NFSV4 0x1138c8e70: clientid={0x10b1d4400 ClientID={Epoch=0x66aaa58c Counter=0x00000001} CONFIRMED Client={0x600001b1b230 name=(58:0x01000000bcd0745295bb100224ba7f00000100000000000000003132372e302e302e313a2f002f566f6c756d65732f676f6f676c652f73726300) refcount=1} t_delta=0 reservations=1 refcount=2 cb_prog=0 r_addr= r_netid=-} owner=(4:0x00013d72) confirmed=1 seqid=761945 refcount=1}
I0731 14:20:55.056415   52104 nfs4_owner.c:739] [ COMPONENT_STATE : Check_nfs4_seqid (NIV_FULL_DEBUG) ] CLOSE: Check {STATE_OPEN_OWNER_NFSV4 0x1138c8e70: clientid={0x10b1d4400 ClientID={Epoch=0x66aaa58c Counter=0x00000001} CONFIRMED Client={0x600001b1b230 name=(58:0x01000000bcd0745295bb100224ba7f00000100000000000000003132372e302e302e313a2f002f566f6c756d65732f676f6f676c652f73726300) refcount=1} t_delta=0 reservations=1 refcount=2 cb_prog=0 r_addr= r_netid=-} owner=(4:0x00013d72) confirmed=1 seqid=761945 refcount=2} next 761946 req seqid 761946
I0731 14:20:55.056489   52098 commonlib.c:2966] [ COMPONENT_FSAL : fsal_start_fd_work (NIV_FULL_DEBUG) ] 0x1228ec998 try fd work - io_work = 0 fd_work = 1
I0731 14:20:55.056500   52098 commonlib.c:3015] [ COMPONENT_FSAL : fsal_complete_fd_work (NIV_FULL_DEBUG) ] 0x1228ec998 done fd work io_work = 0 fd_work = 0
I0731 14:20:55.056506   52098 commonlib.c:2966] [ COMPONENT_FSAL : fsal_start_fd_work (NIV_FULL_DEBUG) ] 0x1228ec998 try fd work - io_work = 0 fd_work = 1
I0731 14:20:55.056512   52098 commonlib.c:3015] [ COMPONENT_FSAL : fsal_complete_fd_work (NIV_FULL_DEBUG) ] 0x1228ec998 done fd work io_work = 0 fd_work = 0
I0731 14:20:55.056440   52104 nfs4_state_id.c:1237] [ COMPONENT_STATE : update_stateid (NIV_DEBUG) ] Update CLOSE stateid to OTHER=0x010000008ca5aa6624d00500 {{CLIENTID Epoch=0x66aaa58c Counter=0x00000001} StateIdCounter=0x0005d024} seqid=2 for response
I0731 14:20:55.056634   52104 nfs4_state.c:365] [ COMPONENT_STATE : _state_del_locked (NIV_FULL_DEBUG) ] Deleting STATE 0x11081ef50 OTHER=0x010000008ca5aa6624d00500 {{CLIENTID Epoch=0x66aaa58c Counter=0x00000001} StateIdCounter=0x0005d024} obj=0x11081efd8 type=SHARE seqid=2 owner={STATE_OPEN_OWNER_NFSV4 0x1138c8e70: clientid={0x10b1d4400 ClientID={Epoch=0x66aaa58c Counter=0x00000001} CONFIRMED Client={0x600001b1b230 name=(58:0x01000000bcd0745295bb100224ba7f00000100000000000000003132372e302e302e313a2f002f566f6c756d65732f676f6f676c652f73726300) refcount=1} t_delta=0 reservations=1 refcount=2 cb_prog=0 r_addr= r_netid=-} owner=(4:0x00013d72) confirmed=1 seqid=761945 refcount=2} refccount=2
I0731 14:20:55.056675   52104 state_misc.c:913] [ COMPONENT_STATE : dec_state_owner_ref (NIV_FULL_DEBUG) ] Decrement refcount now=1 {STATE_OPEN_OWNER_NFSV4 0x1138c8e70: clientid={0x10b1d4400 ClientID={Epoch=0x66aaa58c Counter=0x00000001} CONFIRMED Client={0x600001b1b230 name=(58:0x01000000bcd0745295bb100224ba7f00000100000000000000003132372e302e302e313a2f002f566f6c756d65732f676f6f676c652f73726300) refcount=1} t_delta=0 reservations=1 refcount=2 cb_prog=0 r_addr= r_netid=-} owner=(4:0x00013d72) confirmed=1 seqid=761945 refcount=2}
I0731 14:20:55.056711   52104 commonlib.c:1269] [ COMPONENT_FSAL : update_share_counters (NIV_FULL_DEBUG) ] share counter: access_read 0, access_write 0, deny_read 0, deny_write 0, deny_write_v4 0
I0731 14:20:55.056718   52104 commonlib.c:2966] [ COMPONENT_FSAL : fsal_start_fd_work (NIV_FULL_DEBUG) ] 0x11081f048 try fd work - io_work = 0 fd_work = 1
I0731 14:20:55.056730   52104 commonlib.c:3015] [ COMPONENT_FSAL : fsal_complete_fd_work (NIV_FULL_DEBUG) ] 0x11081f048 done fd work io_work = 0 fd_work = 0
I0731 14:20:55.056736   52104 nfs4_state_id.c:509] [ COMPONENT_STATE : dec_nfs4_state_ref (NIV_FULL_DEBUG) ] Decrement refcount now=1 {STATE 0x11081ef50 OTHER=0x010000008ca5aa6624d00500 {{CLIENTID Epoch=0x66aaa58c Counter=0x00000001} StateIdCounter=0x0005d024} obj=0x11081efd8 type=SHARE seqid=2 owner={<NULL>} refccount=2}
I0731 14:20:55.056766   52104 nfs4_owner.c:652] [ COMPONENT_STATE : Copy_nfs4_state_req (NIV_FULL_DEBUG) ] CLOSE: saving response 0x1138c8e70 so_seqid 761945 new seqid 761946
I0731 14:20:55.056829   52104 state_misc.c:966] [ COMPONENT_STATE : dec_state_owner_ref (NIV_FULL_DEBUG) ] Free {STATE_OPEN_OWNER_NFSV4 0x1138c8e70: clientid={0x10b1d4400 ClientID={Epoch=0x66aaa58c Counter=0x00000001} CONFIRMED Client={0x600001b1b230 name=(58:0x01000000bcd0745295bb100224ba7f00000100000000000000003132372e302e302e313a2f002f566f6c756d65732f676f6f676c652f73726300) refcount=1} t_delta=0 reservations=1 refcount=2 cb_prog=0 r_addr= r_netid=-} owner=(4:0x00013d72) confirmed=1 seqid=761946 refcount=1}
I0731 14:20:55.056891   52104 nfs4_state_id.c:519] [ COMPONENT_STATE : dec_nfs4_state_ref (NIV_FULL_DEBUG) ] Deleted STATE 0x11081ef50 OTHER=0x010000008ca5aa6624d00500 {{CLIENTID Epoch=0x66aaa58c Counter=0x00000001} StateIdCounter=0x0005d024} obj=0x11081efd8 type=SHARE seqid=2 owner={<NULL>} refccount=1
I0731 14:20:55.057435   47616 commonlib.c:2966] [ COMPONENT_FSAL : fsal_start_fd_work (NIV_FULL_DEBUG) ] 0x110d8a618 try fd work - io_work = 0 fd_work = 1
I0731 14:20:55.057445   47616 commonlib.c:3015] [ COMPONENT_FSAL : fsal_complete_fd_work (NIV_FULL_DEBUG) ] 0x110d8a618 done fd work io_work = 0 fd_work = 0
I0731 14:20:55.057450   47616 commonlib.c:2966] [ COMPONENT_FSAL : fsal_start_fd_work (NIV_FULL_DEBUG) ] 0x110d8a618 try fd work - io_work = 0 fd_work = 1
I0731 14:20:55.057455   47616 commonlib.c:3015] [ COMPONENT_FSAL : fsal_complete_fd_work (NIV_FULL_DEBUG) ] 0x110d8a618 done fd work io_work = 0 fd_work = 0
I0731 14:20:55.057518   52104 commonlib.c:2966] [ COMPONENT_FSAL : fsal_start_fd_work (NIV_FULL_DEBUG) ] 0x1155b0e98 try fd work - io_work = 0 fd_work = 1
I0731 14:20:55.057528   52104 commonlib.c:3015] [ COMPONENT_FSAL : fsal_complete_fd_work (NIV_FULL_DEBUG) ] 0x1155b0e98 done fd work io_work = 0 fd_work = 0
I0731 14:20:55.057532   52104 commonlib.c:2966] [ COMPONENT_FSAL : fsal_start_fd_work (NIV_FULL_DEBUG) ] 0x1155b0e98 try fd work - io_work = 0 fd_work = 1
I0731 14:20:55.057537   52104 commonlib.c:3015] [ COMPONENT_FSAL : fsal_complete_fd_work (NIV_FULL_DEBUG) ] 0x1155b0e98 done fd work io_work = 0 fd_work = 0
I0731 14:20:55.058638   47616 commonlib.c:2966] [ COMPONENT_FSAL : fsal_start_fd_work (NIV_FULL_DEBUG) ] 0x110bee748 try fd work - io_work = 0 fd_work = 1
I0731 14:20:55.058657   47616 commonlib.c:3015] [ COMPONENT_FSAL : fsal_complete_fd_work (NIV_FULL_DEBUG) ] 0x110bee748 done fd work io_work = 0 fd_work = 0
I0731 14:20:55.058663   47616 commonlib.c:2966] [ COMPONENT_FSAL : fsal_start_fd_work (NIV_FULL_DEBUG) ] 0x110bee748 try fd work - io_work = 0 fd_work = 1
I0731 14:20:55.058669   47616 commonlib.c:3015] [ COMPONENT_FSAL : fsal_complete_fd_work (NIV_FULL_DEBUG) ] 0x110bee748 done fd work io_work = 0 fd_work = 0
I0731 14:20:55.058971   52098 commonlib.c:2966] [ COMPONENT_FSAL : fsal_start_fd_work (NIV_FULL_DEBUG) ] 0x1257b2318 try fd work - io_work = 0 fd_work = 1
I0731 14:20:55.058984   52098 commonlib.c:3015] [ COMPONENT_FSAL : fsal_complete_fd_work (NIV_FULL_DEBUG) ] 0x1257b2318 done fd work io_work = 0 fd_work = 0
I0731 14:20:55.058990   52098 commonlib.c:2966] [ COMPONENT_FSAL : fsal_start_fd_work (NIV_FULL_DEBUG) ] 0x1257b2318 try fd work - io_work = 0 fd_work = 1
I0731 14:20:55.058995   52098 commonlib.c:3015] [ COMPONENT_FSAL : fsal_complete_fd_work (NIV_FULL_DEBUG) ] 0x1257b2318 done fd work io_work = 0 fd_work = 0
I0731 14:20:55.059244   52104 nfs4_op_close.c:167] [ COMPONENT_STATE : nfs4_op_close (NIV_DEBUG) ] Entering NFS v4 CLOSE handler ----------------------------
I0731 14:20:55.059255   52104 nfs4_state_id.c:837] [ COMPONENT_STATE : nfs4_Check_Stateid (NIV_FULL_DEBUG) ] Check CLOSE stateid flags CLOSE_40
I0731 14:20:55.059265   52104 sal_functions.h:417] [ COMPONENT_STATE : inc_state_t_ref (NIV_FULL_DEBUG) ] State 0x12524c0d0 refcount now 2
I0731 14:20:55.059273   52104 nfs4_state.c:606] [ COMPONENT_STATE : get_state_obj_export_owner_refs (NIV_FULL_DEBUG) ] state 0x12524c0d0 state_obj 0x12524c158 state_export 0x145609c10 state_owner 0x1138c8e70
I0731 14:20:55.059278   52104 state_misc.c:802] [ COMPONENT_STATE : inc_state_owner_ref (NIV_FULL_DEBUG) ] Increment refcount now=1 {STATE_LOCK_OWNER_UNKNOWN powner=0x1138c8e70: refcount=0}
I0731 14:20:55.059283   52104 nfs4_state_id.c:1157] [ COMPONENT_STATE : nfs4_Check_Stateid (NIV_FULL_DEBUG) ] Check CLOSE stateid found valid stateid OTHER=0x010000008ca5aa6623d00500 {{CLIENTID Epoch=0x66aaa58c Counter=0x00000001} StateIdCounter=0x0005d023} seqid=1 - 0x12524c0d0
E0731 14:20:55.059287   52104 state_misc.c:927] [ COMPONENT_STATE : dec_state_owner_ref (NIV_CRIT) ] Unexpected owner {STATE_LOCK_OWNER_UNKNOWN powner=0x1138c8e70: refcount=1}, type {0}
I0731 14:20:55.059292   52104 nfs4_state.c:606] [ COMPONENT_STATE : get_state_obj_export_owner_refs (NIV_FULL_DEBUG) ] state 0x12524c0d0 state_obj 0x12524c158 state_export 0x145609c10 state_owner 0x1138c8e70
I0731 14:20:55.059296   52104 state_misc.c:802] [ COMPONENT_STATE : inc_state_owner_ref (NIV_FULL_DEBUG) ] Increment refcount now=1 {STATE_LOCK_OWNER_UNKNOWN powner=0x1138c8e70: refcount=0}
E0731 14:20:55.059306   52104 nfs4_op_close.c:230] [ COMPONENT_RW_LOCK : nfs4_op_close (NIV_CRIT) ] Error 22, acquiring mutex 0x1138c8e88 (&open_owner->so_mutex) at third_party/nfs_ganesha/current/src/Protocols/NFS/nfs4_op_close.c:230

[spectral54]

I didn't add a link to this issue in https://review.gerrithub.io/c/ffilz/nfs-ganesha/+/1199063, I'm not sure what the convention is for linking from a change to an issue report. This issue is definitely related to that change, however.

In this particular case that we have the log snippet for, 3.9 million lines earlier, there was a missed increment of the state owner refcount during an Open call due to a Read call on another thread adjusting the refcount at exactly the wrong time. A few minutes later, everything gets closed, and as we try to close the final state, we discover that the state owner was deleted on the penultimate state deletion (since its refcount was 1 less than it should have been), and crash.

[drieber]

I did local testing and I can confirm that https://review.gerrithub.io/c/ffilz/nfs-ganesha/+/1199063 fixes this issue for us.

[ffilz]

Do you feel like we can close this? If you prefer, we can delay until V6.0 is tagged.

[drieber]

We can close it now.