nfs client hanging

[Guillaume Rousse]

Guillaume Rousse a écrit :
> Given this problem only occurs for home directories for a host with a 
> very specific usage (transient ssh logins for svn commits, or web home 
> page access), I'm more and more considering an autofs issue with 
> repeated mount/umount events, rather than a pure nfs issue. With a 
> similar setup, we have no problem for long-lived mount points, such as 
> homedirs on workstations. And I just found report on autofs ML of such 
> kind of issues:
> http://linux.kernel.org/pipermail/autofs/2008-June/004814.html

With a static NFS mount, the problem still appears, but a bit 
differently, as the filer is still connected
tcp        0      0 node3.cluster.msr-inria:755 
msr-nas1.msr-inria.inri:nfs ESTABLISHED

And this time the log output is a bit different:
Jul  2 15:43:35 localhost kernel: RPC:       new task initialized, 
procpid 22288
Jul  2 15:43:35 localhost kernel: RPC:       allocated task ffff81042bc77900
Jul  2 15:43:35 localhost kernel: RPC:     0 looking up UNIX cred
Jul  2 15:43:35 localhost kernel: RPC:   491 __rpc_execute flags=0x80
Jul  2 15:43:35 localhost kernel: RPC:   491 call_start nfs4 proc 1 (sync)
Jul  2 15:43:35 localhost kernel: RPC:   491 call_reserve (status 0)
Jul  2 15:43:35 localhost kernel: RPC:   491 reserved req 
ffff810429d60e70 xid c2586af8
Jul  2 15:43:35 localhost kernel: RPC:   491 call_reserveresult (status 0)
Jul  2 15:43:35 localhost kernel: RPC:   491 call_allocate (status 0)
Jul  2 15:43:35 localhost kernel: RPC:   491 allocated buffer of size 
972 at ffff81042509d000
Jul  2 15:43:35 localhost kernel: RPC:   491 call_bind (status 0)
Jul  2 15:43:35 localhost kernel: RPC:   491 call_connect xprt 
ffff81042bd17800 is not connected
Jul  2 15:43:35 localhost kernel: RPC:   491 xprt_connect xprt 
ffff81042bd17800 is not connected
Jul  2 15:43:35 localhost kernel: RPC:   491 sleep_on(queue 
"xprt_pending" time 4311285843)
Jul  2 15:43:35 localhost kernel: RPC:   491 added to queue 
ffff81042bd179d0 "xprt_pending"
Jul  2 15:43:35 localhost kernel: RPC:   491 setting alarm for 60000 ms
Jul  2 15:43:35 localhost kernel: RPC:       xs_connect scheduled xprt 
ffff81042bd17800
Jul  2 15:43:35 localhost kernel: RPC:   491 sync task going to sleep
Jul  2 15:43:35 localhost kernel: RPC:       xs_bind4 0.0.0.0:755: ok (0)
Jul  2 15:43:35 localhost kernel: RPC:       worker connecting xprt 
ffff81042bd17800 to address: addr=193.55.250.11 port=2049 proto=tcp
Jul  2 15:43:35 localhost kernel: RPC:       ffff81042bd17800 connect 
status 115 connected 0 sock state 2
Jul  2 15:43:35 localhost kernel: RPC:       xs_tcp_state_change client 
ffff81042bd17800...
Jul  2 15:43:35 localhost kernel: RPC:       state 1 conn 0 dead 0 zapped 1
Jul  2 15:43:35 localhost kernel: RPC:   491 __rpc_wake_up_task (now 
4311285843)
Jul  2 15:43:35 localhost kernel: RPC:   491 disabling timer
Jul  2 15:43:35 localhost kernel: RPC:   491 removed from queue 
ffff81042bd179d0 "xprt_pending"
Jul  2 15:43:35 localhost kernel: RPC:       __rpc_wake_up_task done
Jul  2 15:43:35 localhost kernel: RPC:   491 sync task resuming
Jul  2 15:43:35 localhost kernel: RPC:   491 deleting timer
Jul  2 15:43:35 localhost kernel: RPC:   491 xprt_connect_status: 
connection established
Jul  2 15:43:35 localhost kernel: RPC:   491 call_connect_status (status 0)
Jul  2 15:43:35 localhost kernel: RPC:   491 call_transmit (status 0)
Jul  2 15:43:35 localhost kernel: RPC:   491 xprt_prepare_transmit
Jul  2 15:43:35 localhost kernel: RPC:   491 call_encode (status 0)
Jul  2 15:43:35 localhost kernel: RPC:   491 marshaling UNIX cred 
ffff81042ed96f00
Jul  2 15:43:35 localhost kernel: RPC:   491 using AUTH_UNIX cred 
ffff81042ed96f00 to wrap rpc data
Jul  2 15:43:35 localhost kernel: RPC:   491 xprt_transmit(140)
Jul  2 15:43:35 localhost kernel: RPC:       xs_tcp_send_request(140) = 140
Jul  2 15:43:35 localhost kernel: RPC:   491 xmit complete
Jul  2 15:43:35 localhost kernel: RPC:   491 sleep_on(queue 
"xprt_pending" time 4311285843)
Jul  2 15:43:35 localhost kernel: RPC:   491 added to queue 
ffff81042bd179d0 "xprt_pending"
Jul  2 15:43:36 localhost kernel: RPC:   491 setting alarm for 60000 ms
Jul  2 15:43:36 localhost kernel: RPC: 
wake_up_next(ffff81042bd17980 "xprt_resend")
Jul  2 15:43:36 localhost kernel: RPC: 
wake_up_next(ffff81042bd17930 "xprt_sending")
Jul  2 15:43:36 localhost kernel: RPC:   491 sync task going to sleep
Jul  2 15:43:36 localhost kernel: RPC:       xs_tcp_data_ready...
Jul  2 15:43:36 localhost kernel: RPC:       xs_tcp_data_recv started
Jul  2 15:43:36 localhost kernel: RPC:       reading TCP record fragment 
of length 228
Jul  2 15:43:36 localhost kernel: RPC:       reading XID (4 bytes)
Jul  2 15:43:36 localhost kernel: RPC:       reading reply for XID c2586af8
Jul  2 15:43:36 localhost kernel: RPC:       XID c2586af8 read 224 bytes
Jul  2 15:43:36 localhost kernel: RPC:       xprt = ffff81042bd17800, 
tcp_copied = 228, tcp_offset = 228, tcp_reclen = 228
Jul  2 15:43:36 localhost kernel: RPC:   491 xid c2586af8 complete (228 
bytes received)
Jul  2 15:43:36 localhost kernel: RPC:   491 __rpc_wake_up_task (now 
4311285843)
Jul  2 15:43:36 localhost kernel: RPC:   491 disabling timer
Jul  2 15:43:36 localhost kernel: RPC:   491 removed from queue 
ffff81042bd179d0 "xprt_pending"
Jul  2 15:43:36 localhost kernel: RPC:       __rpc_wake_up_task done
Jul  2 15:43:36 localhost kernel: RPC:       xs_tcp_data_recv done
Jul  2 15:43:36 localhost kernel: RPC:   491 sync task resuming
Jul  2 15:43:36 localhost kernel: RPC:   491 deleting timer
Jul  2 15:43:36 localhost kernel: RPC:   491 call_status (status 228)
Jul  2 15:43:36 localhost kernel: RPC:   491 call_decode (status 228)
Jul  2 15:43:36 localhost kernel: RPC:   491 validating UNIX cred 
ffff81042ed96f00
Jul  2 15:43:36 localhost kernel: RPC:   491 using AUTH_UNIX cred 
ffff81042ed96f00 to unwrap rpc data
-- 
Guillaume Rousse
Moyens Informatiques - INRIA Futurs
Tel: 01 69 35 69 62