3:17 a.m.
Hi experts,
I create VFS export in ganesha server. My client is ubuntu-12.04 and its kernel is 3.2.0.
I tried to read a file in the client, such as
root@vagrant:~# cat /mnt/vfs/1.txt
cat: /mnt/vfs/1.txt: Input/output error
Below is the kernel log. It seems that print_overflow_msg() is called.
[ 86.107842] RPC: 15 call_start nfs4 proc OPEN (async)
[ 86.107843] RPC: 15 call_reserve (status 0)
[ 86.107846] RPC: 15 reserved req ffff88003ccf9e00 xid 26da5a05
[ 86.107848] RPC: wake_up_next(ffff88003a205990 "xprt_sending")
[ 86.107850] RPC: 15 call_reserveresult (status 0)
[ 86.107852] RPC: 15 call_refresh (status 0)
[ 86.107855] RPC: 15 refreshing UNIX cred ffff880039b35c00
[ 86.107856] RPC: 15 call_refreshresult (status 0)
[ 86.107858] RPC: 15 call_allocate (status 0)
[ 86.107860] RPC: 15 allocated buffer of size 2536 at ffff88003b3d9000
[ 86.107861] RPC: 15 call_bind (status 0)
[ 86.107863] RPC: 15 call_connect xprt ffff88003a205800 is connected
[ 86.107864] RPC: 15 call_transmit (status 0)
[ 86.107865] RPC: 15 xprt_prepare_transmit
[ 86.107866] RPC: 15 rpc_xdr_encode (status 0)
[ 86.107867] RPC: 15 marshaling UNIX cred ffff880039b35c00
[ 86.107869] RPC: 15 using AUTH_UNIX cred ffff880039b35c00 to wrap rpc data
[ 86.107870] encode_compound: tag=
[ 86.107872] encode_sequence: sessionid=2:1564646257:2:0 seqid=12 slotid=0 max_slotid=0
cache_this=1
[ 86.107874] RPC: 15 xprt_transmit(268)
[ 86.107980] RPC: xs_tcp_send_request(268) = 268
[ 86.107981] RPC: 15 xmit complete
[ 86.107983] RPC: 15 sleep_on(queue "xprt_pending" time 4294912605)
[ 86.107985] RPC: 15 added to queue ffff88003a205a58 "xprt_pending"
[ 86.107986] RPC: 15 setting alarm for 60000 ms
[ 86.107988] RPC: wake_up_next(ffff88003a205990 "xprt_sending")
[ 86.112120] RPC: xs_tcp_data_ready...
[ 86.112123] RPC: xs_tcp_data_recv started
[ 86.112125] RPC: reading TCP record fragment of length 536
[ 86.112126] RPC: reading XID (4 bytes)
[ 86.112128] RPC: reading reply for XID 26da5a05
[ 86.112129] RPC: reading CALL/REPLY flag (4 bytes)
[ 86.112131] RPC: read reply XID 26da5a05
[ 86.112132] RPC: XID 26da5a05 read 528 bytes
[ 86.112134] RPC: xprt = ffff88003a205800, tcp_copied = 536, tcp_offset = 536,
tcp_reclen = 536
[ 86.112136] RPC: 15 xid 26da5a05 complete (536 bytes received)
[ 86.112138] RPC: 15 __rpc_wake_up_task (now 4294912606)
[ 86.112139] RPC: 15 disabling timer
[ 86.112141] RPC: 15 removed from queue ffff88003a205a58 "xprt_pending"
[ 86.112145] RPC: __rpc_wake_up_task done
[ 86.112146] RPC: xs_tcp_data_recv done
[ 86.113873] RPC: 15 __rpc_execute flags=0x881
[ 86.113875] RPC: 15 call_status (status 536)
[ 86.113877] RPC: 15 call_decode (status 536)
[ 86.113879] RPC: 15 validating UNIX cred ffff880039b35c00
[ 86.113881] RPC: 15 using AUTH_UNIX cred ffff880039b35c00 to unwrap rpc data
[ 86.113886] nfs: decode_opaque_inline: prematurely hit end of receive buffer. Remaining
buffer length is 87 words.
[ 86.113888] RPC: 15 call_decode result -5
[ 86.113890] nfs41_sequence_done: Error 0 free the slot
[ 86.113891] nfs4_free_slot: free_slotid 0 highest_used_slotid -1
[ 86.113893] RPC: wake_up_next(ffff88003cdf1860 "ForeChannel Slot
table")
[ 86.113894] RPC: 15 return 0, status -5
[ 86.113895] RPC: 15 release task
[ 86.113898] RPC: freeing buffer of size 2536 at ffff88003b3d9000
[ 86.113900] RPC: 15 release request ffff88003ccf9e00
[ 86.113901] RPC: wake_up_next(ffff88003a205b20 "xprt_backlog")
[ 86.113903] RPC: rpc_release_client(ffff88003bd98a00)
[ 86.113909] RPC: 15 freeing task
[ 86.113914] NFS: dentry_delete(//1.txt, c)
It seems only happen on Linux kernel 3.x rather than 4.x. I debug the issue, I found the
issue is in the xdr_open_delegation4(). When the delegation_type is
OPEN_DELEGATE_NONE_EXT, the problem happened. If it is OPEN_DELEGATE_NONE, it the problem
is gone. I don't know what's the difference between them. Is this a ganesha bug or
old Linux kernel bug?
Thanks,
Marvin