7:03 p.m.
Hi Bill,
I'm seeing a case where the client establishes a connection and sends V4
NULL request. But before ganesha processes it, the socket is closed by
TIRPC. Here is the TIRPC logs I captured. The FD 38, xprt: 0x7fbcd5b71400
is what gets destroyed soon after creation.
Any idea on why? I'm using ganesha version 2.6.5 and TIRPC 1.6.1. I can see
the same in a tcpdump. This seems to be happening with kerberos where
rpc.gssd from client talks to ganesha for authentication.
31/07/2018 12:17:16 : epoch 5b5fa0dc : testvm : nfs-ganesha-11564[svc_16]
rpc :TIRPC :F_DBG :makefd_xprt() 0x7fbcd5b71400 fd 38 xp_refs 1 af 0 port
4294967295 @ makefd_xprt:347
31/07/2018 12:17:16 : epoch 5b5fa0dc : testvm : nfs-ganesha-11564[svc_16]
rpc :TIRPC :F_DBG :svc_vc_rendezvous() 0x7fbcd5b71400 fd 38 xp_refs 1 af 10
port 44988 @ svc_vc_rendezvous:469
31/07/2018 12:17:16 : epoch 5b5fa0dc : testvm : nfs-ganesha-11564[svc_16]
rpc :TIRPC :F_DBG :svc_ref_it() 0x7fbce2455800 fd 15 xp_refs 4 af 0 port
4294967295 @ svc_vc_rendezvous:500
31/07/2018 12:17:16 : epoch 5b5fa0dc : testvm : nfs-ganesha-11564[svc_16]
nfs_rpc_dispatch_tcp_NFS :DISP :F_DBG :NFS TCP request on SVCXPRT
0x7fbcd5b71400 fd 38
31/07/2018 12:17:16 : epoch 5b5fa0dc : testvm : nfs-ganesha-11564[svc_16]
rpc :TIRPC :F_DBG :svc_rqst_evchan_reg:648 locking
31/07/2018 12:17:16 : epoch 5b5fa0dc : testvm : nfs-ganesha-11564[svc_16]
rpc :TIRPC :F_DBG :svc_rqst_hook_events: 0x7fbcd5b71400 fd 38 xp_refs 1
sr_rec 0x7fbce24eeb10 evchan 1 refcnt 4 epoll_fd 27 control fd pair (25:26)
hook
31/07/2018 12:17:16 : epoch 5b5fa0dc : testvm : nfs-ganesha-11564[svc_16]
rpc :TIRPC :F_DBG :ev_sig: fd 25 sig 0
31/07/2018 12:17:16 : epoch 5b5fa0dc : testvm : nfs-ganesha-11564[svc_16]
rpc :TIRPC :F_DBG :svc_rqst_evchan_reg:671 unlocking
@svc_rqst_evchan_reg:648
31/07/2018 12:17:16 : epoch 5b5fa0dc : testvm : nfs-ganesha-11564[svc_16]
rpc :TIRPC :F_DBG :svc_release_it() 0x7fbce2455800 fd 15 xp_refs 3 af 0
port 4294967295 @ svc_rqst_xprt_task:754
31/07/2018 12:17:16 : epoch 5b5fa0dc : testvm : nfs-ganesha-11564[svc_17]
rpc :TIRPC :F_DBG :svc_rqst_epoll_event: fd 26 wakeup (sr_rec
0x7fbce24eeb10)
31/07/2018 12:17:16 : epoch 5b5fa0dc : testvm : nfs-ganesha-11564[svc_16]
rpc :TIRPC :F_DBG :svc_destroy_it() 0x7fbcd5b71400 fd 38 xp_refs 1 af 10
port 44988 @ svc_rqst_clean_func:781
31/07/2018 12:17:16 : epoch 5b5fa0dc : testvm : nfs-ganesha-11564[svc_17]
rpc :TIRPC :F_DBG :svc_rqst_epoll_event: fd 26 after consume sig (sr_rec
0x7fbce24eeb10)
31/07/2018 12:17:16 : epoch 5b5fa0dc : testvm : nfs-ganesha-11564[svc_16]
rpc :TIRPC :F_DBG :svc_rqst_xprt_unregister:723 locking
131/07/2018 12:17:16 : epoch 5b5fa0dc : testvm : nfs-ganesha-11564[svc_17]
rpc :TIRPC :F_DBG :svc_rqst_epoll_loop: epoll_fd 27 before epoll_wait
(29000)
31/07/2018 12:17:16 : epoch 5b5fa0dc : testvm : nfs-ganesha-11564[svc_16]
rpc :TIRPC :F_DBG :svc_rqst_unhook_events: 0x7fbcd5b71400 fd 38 xp_refs 0
sr_rec 0x7fbce24eeb10 evchan 1 refcnt 4 epoll_fd 27 control fd pair (25:26)
unhook
31/07/2018 12:17:16 : epoch 5b5fa0dc : testvm : nfs-ganesha-11564[svc_16]
rpc :TIRPC :F_DBG :svc_rqst_xprt_unregister:733 unlocking
@svc_rqst_xprt_unregister:723
31/07/2018 12:17:16 : epoch 5b5fa0dc : testvm : nfs-ganesha-11564[svc_16]
rpc :TIRPC :F_DBG :svc_vc_destroy_it() 0x7fbcd5b71400 fd 38 xp_refs 0
should actually destroy things @ svc_rqst_clean_func:781
31/07/2018 12:17:16 : epoch 5b5fa0dc : testvm : nfs-ganesha-11564[svc_16]
rpc :TIRPC :F_DBG :work_pool_thread() svc_16 waiting
31/07/2018 12:17:16 : epoch 5b5fa0dc : testvm : nfs-ganesha-11564[svc_22]
rpc :TIRPC :F_DBG :work_pool_thread() svc_22 task 0x7fbcd5b71618