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

Like all ALL_CAPS() calls in ntirpc, AUTH_WRAP() is a call through a function pointer, in this case the wrap() call for the auth_none set. All it does is call the higher level's encode function, in this case xdr_COMPOUND4res_extended(). So there was an XDR encoding failure. Something must be wrong with the results array, would be my guess? Unfortunately, XDR encoding has no debug output, and only returns a bool, so there's no hints as to what failed to encode. Daniel On 3/15/21 3:25 PM, Jeff Layton wrote: > 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! >