nfs client hanging
Guillaume Rousse
Guillaume.Rousse at inria.fr
Fri Jun 6 07:03:53 EDT 2008
Hello list.
I've got some strange NFS 4 hanging issues between a linux 2.6.24
client, using nfs-utils 1.1.1 (all nfs4 patches applied), and a netapp
filer. Here is a debug output produced with all nfs and rpc flags
applied on the client, when trying to access the mount point:
Jun 6 12:59:17 etoile kernel: NFS: revalidating (0:16/100)
Jun 6 12:59:17 etoile kernel: RPC: new task initialized, procpid
25900
Jun 6 12:59:17 etoile kernel: RPC: allocated task e65ccc00
Jun 6 12:59:17 etoile kernel: RPC: 0 looking up UNIX cred
Jun 6 12:59:17 etoile kernel: RPC: 29622 __rpc_execute flags=0x80
Jun 6 12:59:17 etoile kernel: RPC: 29622 call_start nfs4 proc 1 (sync)
Jun 6 12:59:17 etoile kernel: RPC: 29622 call_reserve (status 0)
Jun 6 12:59:17 etoile kernel: RPC: 29622 reserved req cf4da264 xid 1dc69423
Jun 6 12:59:17 etoile kernel: RPC: 29622 call_reserveresult (status 0)
Jun 6 12:59:17 etoile kernel: RPC: 29622 call_allocate (status 0)
Jun 6 12:59:17 etoile kernel: RPC: 29622 allocated buffer of size 968
at e04bb800
Jun 6 12:59:17 etoile kernel: RPC: 29622 call_bind (status 0)
Jun 6 12:59:18 etoile kernel: RPC: 29622 call_connect xprt ee4e6c00 is
not connected
Jun 6 12:59:18 etoile kernel: RPC: 29622 xprt_connect xprt ee4e6c00 is
not connected
Jun 6 12:59:18 etoile kernel: RPC: 29622 sleep_on(queue "xprt_pending"
time 24021034)
Jun 6 12:59:18 etoile kernel: RPC: 29622 added to queue ee4e6d38
"xprt_pending"
Jun 6 12:59:18 etoile kernel: RPC: 29622 setting alarm for 60000 ms
Jun 6 12:59:18 etoile kernel: RPC: xs_connect scheduled xprt ee4e6c00
Jun 6 12:59:18 etoile kernel: RPC: 29622 sync task going to sleep
Jun 6 12:59:18 etoile kernel: RPC: xs_bind4 0.0.0.0:1021: ok (0)
Jun 6 12:59:18 etoile kernel: RPC: worker connecting xprt
ee4e6c00 to address: addr=193.55.250.11 port=2049 proto=tcp
Jun 6 12:59:18 etoile kernel: RPC: ee4e6c00 connect status 115
connected 0 sock state 2
Jun 6 12:59:18 etoile kernel: RPC: xs_tcp_state_change client
ee4e6c00...
Jun 6 12:59:18 etoile kernel: RPC: state 1 conn 0 dead 0 zapped 1
Jun 6 12:59:18 etoile kernel: RPC: 29622 __rpc_wake_up_task (now 24021039)
Jun 6 12:59:18 etoile kernel: RPC: 29622 disabling timer
Jun 6 12:59:18 etoile kernel: RPC: 29622 removed from queue ee4e6d38
"xprt_pending"
Jun 6 12:59:18 etoile kernel: RPC: __rpc_wake_up_task done
Jun 6 12:59:18 etoile kernel: RPC: 29622 sync task resuming
Jun 6 12:59:18 etoile kernel: RPC: 29622 deleting timer
Jun 6 12:59:18 etoile kernel: RPC: 29622 xprt_connect_status:
connection established
Jun 6 12:59:18 etoile kernel: RPC: 29622 call_connect_status (status 0)
Jun 6 12:59:18 etoile kernel: RPC: 29622 call_transmit (status 0)
Jun 6 12:59:18 etoile kernel: RPC: 29622 xprt_prepare_transmit
Jun 6 12:59:18 etoile kernel: RPC: 29622 call_encode (status 0)
Jun 6 12:59:18 etoile kernel: RPC: 29622 marshaling UNIX cred e11a7300
Jun 6 12:59:18 etoile kernel: RPC: 29622 using AUTH_UNIX cred e11a7300
to wrap rpc data
Jun 6 12:59:18 etoile kernel: encode_compound: tag=
Jun 6 12:59:18 etoile kernel: RPC: 29622 xprt_transmit(160)
Jun 6 12:59:18 etoile kernel: RPC: xs_tcp_send_request(160) = 160
Jun 6 12:59:18 etoile kernel: RPC: xs_tcp_data_ready...
Jun 6 12:59:18 etoile kernel: RPC: xs_tcp_data_recv started
Jun 6 12:59:18 etoile kernel: RPC: reading TCP record fragment of
length 228
Jun 6 12:59:18 etoile kernel: RPC: reading XID (4 bytes)
Jun 6 12:59:18 etoile kernel: RPC: reading reply for XID 1dc69423
Jun 6 12:59:19 etoile kernel: RPC: XID 1dc69423 read 224 bytes
Jun 6 12:59:19 etoile kernel: RPC: xprt = ee4e6c00, tcp_copied =
228, tcp_offset = 228, tcp_reclen = 228
Jun 6 12:59:19 etoile kernel: RPC: 29622 xid 1dc69423 complete (228
bytes received)
Jun 6 12:59:19 etoile kernel: RPC: xs_tcp_data_recv done
Jun 6 12:59:19 etoile kernel: RPC: 29622 xmit complete
Jun 6 12:59:19 etoile kernel: RPC: wake_up_next(ee4e6d0c
"xprt_resend")
Jun 6 12:59:19 etoile kernel: RPC: wake_up_next(ee4e6ce0
"xprt_sending")
Jun 6 12:59:19 etoile kernel: RPC: 29622 call_status (status 228)
Jun 6 12:59:19 etoile kernel: RPC: 29622 call_decode (status 228)
Jun 6 12:59:19 etoile kernel: RPC: 29622 validating UNIX cred e11a7300
Jun 6 12:59:19 etoile kernel: RPC: 29622 using AUTH_UNIX cred e11a7300
to unwrap rpc data
Jun 6 12:59:19 etoile kernel: decode_attr_type: type=02
Jun 6 12:59:19 etoile kernel: decode_attr_change: change
attribute=1302175363659396088
Jun 6 12:59:19 etoile kernel: decode_attr_size: file size=4096
Jun 6 12:59:19 etoile kernel: decode_attr_fsid: fsid=(0x235d83/0x0)
Jun 6 12:59:19 etoile kernel: decode_attr_fileid: fileid=100
Jun 6 12:59:19 etoile kernel: decode_attr_fs_locations: fs_locations
done, error = 0
Jun 6 12:59:19 etoile kernel: decode_attr_mode: file mode=0755
Jun 6 12:59:19 etoile kernel: decode_attr_nlink: nlink=15
Jun 6 12:59:26 etoile kernel: NFS: revalidating (0:17/64)
Jun 6 12:59:26 etoile kernel: NFS call getattr
Jun 6 12:59:26 etoile kernel: RPC: new task initialized, procpid
25931
Jun 6 12:59:26 etoile kernel: RPC: allocated task e1515a00
Jun 6 12:59:26 etoile kernel: RPC: 0 looking up UNIX cred
Jun 6 12:59:26 etoile kernel: RPC: 29623 __rpc_execute flags=0x80
Jun 6 12:59:26 etoile kernel: RPC: 29623 call_start nfs3 proc 1 (sync)
Jun 6 12:59:26 etoile kernel: RPC: 29623 call_reserve (status 0)
Jun 6 12:59:26 etoile kernel: RPC: 29623 reserved req e0541264 xid 36003cd5
Jun 6 12:59:26 etoile kernel: RPC: 29623 call_reserveresult (status 0)
Jun 6 12:59:26 etoile kernel: RPC: 29623 call_allocate (status 0)
Jun 6 12:59:26 etoile kernel: RPC: 29623 allocated buffer of size 548
at c2935000
Jun 6 12:59:26 etoile kernel: RPC: 29623 call_bind (status 0)
Jun 6 12:59:26 etoile kernel: RPC: 29623 call_connect xprt c597fc00 is
connected
Jun 6 12:59:26 etoile kernel: RPC: 29623 call_transmit (status 0)
Jun 6 12:59:26 etoile kernel: RPC: 29623 xprt_prepare_transmit
Jun 6 12:59:26 etoile kernel: RPC: 29623 call_encode (status 0)
Jun 6 12:59:26 etoile kernel: RPC: 29623 marshaling UNIX cred e11a7300
Jun 6 12:59:26 etoile kernel: RPC: 29623 using AUTH_UNIX cred e11a7300
to wrap rpc data
Jun 6 12:59:26 etoile kernel: RPC: 29623 xprt_transmit(132)
Jun 6 12:59:26 etoile kernel: RPC: xs_tcp_send_request(132) = 132
Jun 6 12:59:26 etoile kernel: RPC: xs_tcp_data_ready...
Jun 6 12:59:26 etoile kernel: RPC: xs_tcp_data_recv started
Jun 6 12:59:26 etoile kernel: RPC: reading TCP record fragment of
length 112
Jun 6 12:59:26 etoile kernel: RPC: reading XID (4 bytes)
Jun 6 12:59:26 etoile kernel: RPC: reading reply for XID 36003cd5
Jun 6 12:59:27 etoile kernel: RPC: XID 36003cd5 read 108 bytes
Jun 6 12:59:27 etoile kernel: RPC: xprt = c597fc00, tcp_copied =
112, tcp_offset = 112, tcp_reclen = 112
Jun 6 12:59:27 etoile kernel: RPC: 29623 xid 36003cd5 complete (112
bytes received)
Jun 6 12:59:27 etoile kernel: RPC: xs_tcp_data_recv done
Jun 6 12:59:27 etoile kernel: RPC: 29623 xmit complete
Jun 6 12:59:27 etoile kernel: RPC: wake_up_next(c597fd0c
"xprt_resend")
Jun 6 12:59:27 etoile kernel: RPC: wake_up_next(c597fce0
"xprt_sending")
Jun 6 12:59:27 etoile kernel: RPC: 29623 call_status (status 112)
Jun 6 12:59:27 etoile kernel: RPC: 29623 call_decode (status 112)
Jun 6 12:59:27 etoile kernel: RPC: 29623 validating UNIX cred e11a7300
Jun 6 12:59:27 etoile kernel: RPC: 29623 using AUTH_UNIX cred e11a7300
to unwrap rpc data
Jun 6 12:59:27 etoile kernel: RPC: 29623 call_decode result 0
Jun 6 12:59:27 etoile kernel: RPC: 29623 return 0, status 0
Jun 6 12:59:27 etoile kernel: RPC: 29623 release task
Jun 6 12:59:27 etoile kernel: RPC: freeing buffer of size 548 at
c2935000
Jun 6 12:59:27 etoile kernel: RPC: 29623 release request e0541264
Jun 6 12:59:27 etoile kernel: RPC: wake_up_next(c597fd64
"xprt_backlog")
Jun 6 12:59:27 etoile kernel: RPC: 29623 releasing UNIX cred e11a7300
Jun 6 12:59:27 etoile kernel: RPC: rpc_release_client(e1515b00)
Jun 6 12:59:27 etoile kernel: NFS reply getattr: 0
Jun 6 12:59:27 etoile kernel: NFS: nfs_update_inode(0:17/64 ct=2 info=0x6)
Jun 6 12:59:27 etoile kernel: NFS: (0:17/64) revalidation complete
Jun 6 12:59:27 etoile kernel: RPC: 29623 freeing task
Jun 6 12:59:27 etoile kernel: NFS call fsstat
Jun 6 12:59:27 etoile kernel: RPC: new task initialized, procpid
25931
Jun 6 12:59:27 etoile kernel: RPC: allocated task f6de4500
Jun 6 12:59:27 etoile kernel: RPC: 0 looking up UNIX cred
Jun 6 12:59:27 etoile kernel: RPC: 29624 __rpc_execute flags=0x80
Jun 6 12:59:27 etoile kernel: RPC: 29624 call_start nfs3 proc 18 (sync)
Jun 6 12:59:27 etoile kernel: RPC: 29624 call_reserve (status 0)
Jun 6 12:59:28 etoile kernel: RPC: 29624 reserved req e0541264 xid 37003cd5
Jun 6 12:59:28 etoile kernel: RPC: 29624 call_reserveresult (status 0)
Jun 6 12:59:28 etoile kernel: RPC: 29624 call_allocate (status 0)
Jun 6 12:59:28 etoile kernel: RPC: 29624 allocated buffer of size 604
at c2935000
Jun 6 12:59:28 etoile kernel: RPC: 29624 call_bind (status 0)
Jun 6 12:59:28 etoile kernel: RPC: 29624 call_connect xprt c597fc00 is
connected
Jun 6 12:59:28 etoile kernel: RPC: 29624 call_transmit (status 0)
Jun 6 12:59:28 etoile kernel: RPC: 29624 xprt_prepare_transmit
Jun 6 12:59:28 etoile kernel: RPC: 29624 call_encode (status 0)
Jun 6 12:59:28 etoile kernel: RPC: 29624 marshaling UNIX cred e11a7300
Jun 6 12:59:28 etoile kernel: RPC: 29624 using AUTH_UNIX cred e11a7300
to wrap rpc data
Jun 6 12:59:28 etoile kernel: RPC: 29624 xprt_transmit(132)
Jun 6 12:59:28 etoile kernel: RPC: xs_tcp_send_request(132) = 132
Jun 6 12:59:28 etoile kernel: RPC: xs_tcp_data_ready...
Jun 6 12:59:28 etoile kernel: RPC: xs_tcp_data_recv started
Jun 6 12:59:28 etoile kernel: RPC: reading TCP record fragment of
length 168
Jun 6 12:59:28 etoile kernel: RPC: reading XID (4 bytes)
Jun 6 12:59:28 etoile kernel: RPC: reading reply for XID 37003cd5
Jun 6 12:59:28 etoile kernel: RPC: XID 37003cd5 read 164 bytes
Jun 6 12:59:28 etoile kernel: RPC: xprt = c597fc00, tcp_copied =
168, tcp_offset = 168, tcp_reclen = 168
Jun 6 12:59:28 etoile kernel: RPC: 29624 xid 37003cd5 complete (168
bytes received)
Jun 6 12:59:28 etoile kernel: RPC: xs_tcp_data_recv done
Jun 6 12:59:28 etoile kernel: RPC: 29624 xmit complete
Jun 6 12:59:28 etoile kernel: RPC: wake_up_next(c597fd0c
"xprt_resend")
Jun 6 12:59:28 etoile kernel: RPC: wake_up_next(c597fce0
"xprt_sending")
Jun 6 12:59:28 etoile kernel: RPC: 29624 call_status (status 168)
Jun 6 12:59:28 etoile kernel: RPC: 29624 call_decode (status 168)
Jun 6 12:59:28 etoile kernel: RPC: 29624 validating UNIX cred e11a7300
Jun 6 12:59:28 etoile kernel: RPC: 29624 using AUTH_UNIX cred e11a7300
to unwrap rpc data
Jun 6 12:59:28 etoile kernel: RPC: 29624 call_decode result 0
Jun 6 12:59:28 etoile kernel: RPC: 29624 return 0, status 0
Jun 6 12:59:28 etoile kernel: RPC: 29624 release task
Jun 6 12:59:28 etoile kernel: RPC: freeing buffer of size 604 at
c2935000
Jun 6 12:59:28 etoile kernel: RPC: 29624 release request e0541264
Jun 6 12:59:28 etoile kernel: RPC: wake_up_next(c597fd64
"xprt_backlog")
Jun 6 12:59:28 etoile kernel: RPC: 29624 releasing UNIX cred e11a7300
Jun 6 12:59:28 etoile kernel: RPC: rpc_release_client(e1515b00)
Jun 6 12:59:28 etoile kernel: NFS reply statfs: 0
Jun 6 12:59:29 etoile kernel: RPC: 29624 freeing task
Jun 6 12:59:36 etoile kernel: svc_age_temp_sockets
Despite the mount uses hard,intr options, I can't interrupt commands
such as ls, and I have to reboot the client. Other, such as rpm trying
to stat() the mount point, can, however.
Any idea of what's happening ?
--
Guillaume Rousse
Moyens Informatiques - INRIA Futurs
Tel: 01 69 35 69 62
More information about the NFSv4
mailing list