2:25 p.m.
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>
3:33 p.m.
I'm confused what could be going on there too, if this isn't RPCSEC_GSS.
Matt
On Mon, Mar 15, 2021 at 3:26 PM Jeff Layton <jlayton(a)poochiereds.net> 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!
--
Jeff Layton <jlayton(a)poochiereds.net>
_______________________________________________
Devel mailing list -- devel(a)lists.nfs-ganesha.org
To unsubscribe send an email to devel-leave(a)lists.nfs-ganesha.org
--
Matt Benjamin
Red Hat, Inc.
315 West Huron Street, Suite 140A
Ann Arbor, Michigan 48103
http://www.redhat.com/en/technologies/storage
tel. 734-821-5101
fax. 734-769-8938
cel. 734-216-5309
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!
6:48 a.m.
I should have asked, what FSAL is providing the xattrs?
Matt
On Tue, Mar 16, 2021 at 7:46 AM Daniel Gryniewicz <dang(a)redhat.com> wrote:
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!
>
_______________________________________________
Devel mailing list -- devel(a)lists.nfs-ganesha.org
To unsubscribe send an email to devel-leave(a)lists.nfs-ganesha.org
--
Matt Benjamin
Red Hat, Inc.
315 West Huron Street, Suite 140A
Ann Arbor, Michigan 48103
http://www.redhat.com/en/technologies/storage
tel. 734-821-5101
fax. 734-769-8938
cel. 734-216-5309
7 a.m.
New subject: TIRPC SVCAUTH_WRAP error in removexattr code
On Tue, 2021-03-16 at 07:48 -0400, Matt Benjamin wrote:
I should have asked, what FSAL is providing the xattrs?
FSAL_CEPH. I have a patch series that fixes the draft xattr support in
ganesha to comply with the standard, and adds support to FSAL_CEPH as
well.
On Tue, Mar 16, 2021 at 7:46 AM Daniel Gryniewicz <dang(a)redhat.com> wrote:
>
> 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.
>
Ok, I'll have to do a bit of poking around with the debugger, I guess.
Thanks!
> 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!
> >
> _______________________________________________
> Devel mailing list -- devel(a)lists.nfs-ganesha.org
> To unsubscribe send an email to devel-leave(a)lists.nfs-ganesha.org
--
Jeff Layton <jlayton(a)poochiereds.net>
11:02 a.m.
Thanks for the pointers, I found it. I had missed setting ->resop in
nfs4_op_removexattr. It was set to 0, and encoding the op would (of
course) fail.
Fixed in latest pile, plus a few other bugs. The ceph+xattr series now
passes the xattr tests in pynfs, aside from XATT8, where removexattr
returns NFS4_OK instead of NFS4ERR_NOXATTR on a non-existent xattr. I
suspect this is a Ceph MDS bug, but I'm working to confirm it now.
Thanks!
Jeff
On Tue, 2021-03-16 at 07:43 -0400, Daniel Gryniewicz wrote:
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!
>
--
Jeff Layton <jlayton(a)poochiereds.net>
1137
days inactive
1138
days old
5 comments
3 participants
participants (3)
-
Daniel Gryniewicz -
Jeff Layton -
Matt Benjamin