6:43 a.m.
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!