[NFS-Ganesha-Devel] TIRPC SVCAUTH_WRAP error in removexattr code

I recently submitted some patches to clean up the xattr handling support for v4.2+, and discovered that there are xattr tests in pynfs! I tested against them and XATT8 failed, with the server timing out on the reply. Here's an excerpt from NIV_FULL_DEBUG run (sans some too- chatty debug messages that I disabled in the dbus code): 15/03/2021 15:17:32 : epoch 604fb2c8 : tleilax.poochiereds.net : ganesha.nfsd-309231[svc_3] process_one_op :NFS4 :DEBUG :Request 2: opcode 75 is OP_REMOVEXATTR 15/03/2021 15:17:32 : epoch 604fb2c8 : tleilax.poochiereds.net : ganesha.nfsd-309231[svc_3] check_resp_room :NFS4 :F_DBG :Status of OP_REMOVEXATTR in position 2 is ok so far, op response size = 32 total response size would be = 128 out of max 8192/8192 15/03/2021 15:17:32 : epoch 604fb2c8 : tleilax.poochiereds.net : ganesha.nfsd-309231[svc_3] nfs4_op_removexattr :NFS4 :DEBUG :RemoveXattr len 10 name: user.attr1 15/03/2021 15:17:32 : epoch 604fb2c8 : tleilax.poochiereds.net : ganesha.nfsd-309231[svc_3] nfs4_Is_Fh_Invalid :FH :F_DBG :NFS4 Handle (29:0x43000064187e06000000010000feffffffffffffff0200000000000000) 15/03/2021 15:17:32 : epoch 604fb2c8 : tleilax.poochiereds.net : ganesha.nfsd-309231[svc_3] mdcache_getattrs :RW LOCK :F_DBG :Got read lock on 0x7f9120014730 (&entry->attr_lock) at /home/jlayton/git/ganesha/src/FSAL/Stackable_FSALs/FSAL_MDCACHE/mdcache_handle.c: 937 15/03/2021 15:17:32 : epoch 604fb2c8 : tleilax.poochiereds.net : ganesha.nfsd-309231[svc_3] mdcache_getattrs :RW LOCK :F_DBG :Unlocked 0x7f9120014730 (&entry->attr_lock) at /home/jlayton/git/ganesha/src/FSAL/Stackable_FSALs/FSAL_MDCACHE/mdcache_handle.c:945 15/03/2021 15:17:32 : epoch 604fb2c8 : tleilax.poochiereds.net : ganesha.nfsd-309231[svc_3] mdcache_getattrs :RW LOCK :F_DBG :Got write lock on 0x7f9120014730 (&entry->attr_lock) at /home/jlayton/git/ganesha/src/FSAL/Stackable_FSALs/FSAL_MDCACHE/mdcache_handle.c :946 15/03/2021 15:17:32 : epoch 604fb2c8 : tleilax.poochiereds.net : ganesha.nfsd-309231[svc_3] mdcache_refresh_attrs :INODE :F_DBG :attrs obj attributes Request Mask=0111dfce Valid Mask=0011ffce Supported Mask=0311dfee REGULAR_FILE numlinks=0x1 size=0x0 mode=0644 owner=0x115f group=0x115f atime=15/03/2021 15:17:32 mtime=15/03/2021 15:17:32 15/03/2021 15:17:32 : epoch 604fb2c8 : tleilax.poochiereds.net : ganesha.nfsd-309231[svc_3] mdcache_getattrs :RW LOCK :F_DBG :Unlocked 0x7f9120014730 (&entry->attr_lock) at /home/jlayton/git/ganesha/src/FSAL/Stackable_FSALs/FSAL_MDCACHE/mdcache_handle.c:976 15/03/2021 15:17:32 : epoch 604fb2c8 : tleilax.poochiereds.net : ganesha.nfsd-309231[svc_3] mdcache_getattrs :INODE :F_DBG :attrs obj attributes Request Mask=00100000 Valid Mask=0011ffce Supported Mask=0311dfee REGULAR_FILE numlinks=0x1 size=0x0 mode=0644 owner =0x115f group=0x115f atime=15/03/2021 15:17:32 mtime=15/03/2021 15:17:32 15/03/2021 15:17:32 : epoch 604fb2c8 : tleilax.poochiereds.net : ganesha.nfsd-309231[svc_3] mdcache_getattrs :RW LOCK :F_DBG :Got read lock on 0x7f9120014730 (&entry->attr_lock) at /home/jlayton/git/ganesha/src/FSAL/Stackable_FSALs/FSAL_MDCACHE/mdcache_handle.c: 937 15/03/2021 15:17:32 : epoch 604fb2c8 : tleilax.poochiereds.net : ganesha.nfsd-309231[svc_3] mdcache_getattrs :RW LOCK :F_DBG :Unlocked 0x7f9120014730 (&entry->attr_lock) at /home/jlayton/git/ganesha/src/FSAL/Stackable_FSALs/FSAL_MDCACHE/mdcache_handle.c:945 15/03/2021 15:17:32 : epoch 604fb2c8 : tleilax.poochiereds.net : ganesha.nfsd-309231[svc_3] mdcache_getattrs :RW LOCK :F_DBG :Got write lock on 0x7f9120014730 (&entry->attr_lock) at /home/jlayton/git/ganesha/src/FSAL/Stackable_FSALs/FSAL_MDCACHE/mdcache_handle.c :946 15/03/2021 15:17:32 : epoch 604fb2c8 : tleilax.poochiereds.net : ganesha.nfsd-309231[svc_3] mdcache_refresh_attrs :INODE :F_DBG :attrs obj attributes Request Mask=0111dfce Valid Mask=0011ffce Supported Mask=0311dfee REGULAR_FILE numlinks=0x1 size=0x0 mode=0644 owner=0x115f group=0x115f atime=15/03/2021 15:17:32 mtime=15/03/2021 15:17:32 15/03/2021 15:17:32 : epoch 604fb2c8 : tleilax.poochiereds.net : ganesha.nfsd-309231[svc_3] mdcache_getattrs :RW LOCK :F_DBG :Unlocked 0x7f9120014730 (&entry->attr_lock) at /home/jlayton/git/ganesha/src/FSAL/Stackable_FSALs/FSAL_MDCACHE/mdcache_handle.c:976 15/03/2021 15:17:32 : epoch 604fb2c8 : tleilax.poochiereds.net : ganesha.nfsd-309231[svc_3] mdcache_getattrs :INODE :F_DBG :attrs obj attributes Request Mask=00100000 Valid Mask=0011ffce Supported Mask=0311dfee REGULAR_FILE numlinks=0x1 size=0x0 mode=0644 owner =0x115f group=0x115f atime=15/03/2021 15:17:32 mtime=15/03/2021 15:17:32 15/03/2021 15:17:32 : epoch 604fb2c8 : tleilax.poochiereds.net : ganesha.nfsd-309231[svc_3] complete_op :NFS4 :F_DBG :Current FH Len=29 0x70cd004c917f0000000000000000000000000000000000000000000000 15/03/2021 15:17:32 : epoch 604fb2c8 : tleilax.poochiereds.net : ganesha.nfsd-309231[svc_3] complete_op :NFS4 :F_DBG :Saved FH Len=0 (EMPTY) 15/03/2021 15:17:32 : epoch 604fb2c8 : tleilax.poochiereds.net : ganesha.nfsd-309231[svc_3] complete_op :NFS4 :DEBUG :Status of OP_REMOVEXATTR in position 2 = NFS4_OK, op response size is 32 total response size is 120 15/03/2021 15:17:32 : epoch 604fb2c8 : tleilax.poochiereds.net : ganesha.nfsd-309231[svc_3] complete_nfs4_compound :RW LOCK :F_DBG :Acquired mutex 0x7f914c0166e0 (&data->preserved_clientid->cid_mutex) at /home/jlayton/git/ganesha/src/Protocols/NFS/nfs4_Compound. c:1044 15/03/2021 15:17:32 : epoch 604fb2c8 : tleilax.poochiereds.net : ganesha.nfsd-309231[svc_3] update_lease :CLIENT ID :F_DBG :Update Lease 0x7f914c016660 ClientID={Epoch=0x604fb2c8 Counter=0x00000002} CONFIRMED Client={0x7f914c00f2e0 name=(16:XATT8_1615835852) ref count=1} t_delta=0 reservations=0 refcount=3 15/03/2021 15:17:32 : epoch 604fb2c8 : tleilax.poochiereds.net : ganesha.nfsd-309231[svc_3] complete_nfs4_compound :RW LOCK :F_DBG :Released mutex 0x7f914c0166e0 (&data->preserved_clientid->cid_mutex) at /home/jlayton/git/ganesha/src/Protocols/NFS/nfs4_Compound. c:1048 15/03/2021 15:17:32 : epoch 604fb2c8 : tleilax.poochiereds.net : ganesha.nfsd-309231[svc_3] _mdcache_lru_unref :RW LOCK :F_DBG :Acquired mutex 0x7f919ced6fe0 (&(qlane)->mtx) at /home/jlayton/git/ganesha/src/FSAL/Stackable_FSALs/FSAL_MDCACHE/mdcache_lru.c:2036 15/03/2021 15:17:32 : epoch 604fb2c8 : tleilax.poochiereds.net : ganesha.nfsd-309231[svc_3] _mdcache_lru_unref :RW LOCK :F_DBG :Released mutex 0x7f919ced6fe0 (&(qlane)->mtx) at /home/jlayton/git/ganesha/src/FSAL/Stackable_FSALs/FSAL_MDCACHE/mdcache_lru.c:2043 15/03/2021 15:17:32 : epoch 604fb2c8 : tleilax.poochiereds.net : ganesha.nfsd-309231[svc_3] compound_data_Free :RW LOCK :F_DBG :Released mutex 0x7f9120011fe8 (&slot->lock) at /home/jlayton/git/ganesha/src/Protocols/NFS/nfs4_Compound.c:1453 15/03/2021 15:17:32 : epoch 604fb2c8 : tleilax.poochiereds.net : ganesha.nfsd-309231[svc_3] clear_op_context_export_impl :EXPORT :F_DBG :put export ref for id 100 /, refcount = 1 15/03/2021 15:17:32 : epoch 604fb2c8 : tleilax.poochiereds.net : ganesha.nfsd-309231[svc_3] complete_request :DISP :F_DBG :Before svc_sendreply on socket 35 15/03/2021 15:17:32 : epoch 604fb2c8 : tleilax.poochiereds.net : ganesha.nfsd-309231[svc_3] rpc :TIRPC :F_DBG :xdr_ioq_uv_create() uv 0x7f914c00cd70 size 8192 15/03/2021 15:17:32 : epoch 604fb2c8 : tleilax.poochiereds.net : ganesha.nfsd-309231[svc_3] rpc :TIRPC :F_DBG :xdr_ioq_reset() xioq 0x7f914c0174d0 head 0x7f914c017650 wh_pos 0 15/03/2021 15:17:32 : epoch 604fb2c8 : tleilax.poochiereds.net : ganesha.nfsd-309231[svc_3] rpc :TIRPC :F_DBG :xdr_reply_encode:93 ACCEPTED INLINE 15/03/2021 15:17:32 : epoch 604fb2c8 : tleilax.poochiereds.net : ganesha.nfsd-309231[svc_3] rpc :TIRPC :F_DBG :xdr_reply_encode:109 SUCCESS 15/03/2021 15:17:32 : epoch 604fb2c8 : tleilax.poochiereds.net : ganesha.nfsd-309231[svc_3] rpc :TIRPC :F_DBG :svc_vc_reply: 0x7f9148000e20 fd 35 SVCAUTH_WRAP failed (will set dead) 15/03/2021 15:17:32 : epoch 604fb2c8 : tleilax.poochiereds.net : ganesha.nfsd-309231[svc_3] complete_request :DISP :DEBUG :NFS DISPATCHER: FAILURE: Error while calling svc_sendreply on a new request. rpcxid=185455221 socket=35 function:NFS4_COMP client:::ffff:192.168.1.3 program:100003 nfs version:4 proc:1 errno: 0 15/03/2021 15:17:32 : epoch 604fb2c8 : tleilax.poochiereds.net : ganesha.nfsd-309231[svc_3] rpc :TIRPC :F_DBG :svc_destroy_it() 0x7f9148000e20 fd 35 fd_send -1 xp_refcnt 4 af 10 port 42712 @complete_request:801 15/03/2021 15:17:32 : epoch 604fb2c8 : tleilax.poochiereds.net : ganesha.nfsd-309231[svc_3] rpc :TIRPC :F_DBG :svc_rqst_xprt_unregister:1146 locking 15/03/2021 15:17:32 : epoch 604fb2c8 : tleilax.poochiereds.net : ganesha.nfsd-309231[svc_3] rpc :TIRPC :F_DBG :svc_rqst_xprt_unregister:1151 unlocking @svc_rqst_xprt_unregister:1146 15/03/2021 15:17:32 : epoch 604fb2c8 : tleilax.poochiereds.net : ganesha.nfsd-309231[svc_3] rpc :TIRPC :F_DBG :svc_rqst_unhook_events: xprt 0x7f9148000e20 fd 35 ev_flags ADDED_RECV INITIALIZED CLOSE DESTROYING It looks like it all works, until we hit the SVCAUTH_WRAP failure...which is odd because this run is using AUTH_SYS, so you'd think that would be a no-op? In any case, I could use some help deciphering this log. What happened? TIA! -- Jeff Layton <jlayton(a)poochiereds.net&gt;