# NFS: timeouts on mount/umount

## Bircoph

NFS mount and umount works, but I get ~30 seconds timeouts and the following in the client's log:

Apr 02 17:58:51 [kernel] rpcbind: server localhost not responding, timed out

Apr 02 17:58:51 [kernel] RPC: failed to contact local rpcbind server (errno 5).

This affects only mount and umount, nfs ro access works perfectly (I do not use rw).

I see no error messages at the server side.

Please, do non send me to the FAQ, because this is not common portmap-is-not-running issue.

On the client:

$ rpcinfo -p localhost

   прог-ма верс прото   порт

    100000    2   tcp    111  portmapper

    100024    1   udp  39328  status

    100024    1   tcp  50238  status

# netstat -anpA inet | grep portmap

tcp        0      0 0.0.0.0:111             0.0.0.0:*               LISTEN     11379/portmap

udp        0      0 0.0.0.0:111             0.0.0.0:*                          11379/portmap

On the server:

$ rpcinfo -p orionis

   прог-ма верс прото   порт

    100000    2   tcp    111  portmapper

    100000    2   udp    111  portmapper

    100024    1   udp  43491  status

    100024    1   tcp  43491  status

    100005    1   udp  37118  mountd

    100005    1   tcp  37118  mountd

    100005    2   udp  37118  mountd

    100005    2   tcp  37118  mountd

    100005    3   udp  37118  mountd

    100005    3   tcp  37118  mountd

    100003    2   udp   2049  nfs

    100003    3   udp   2049  nfs

    100003    4   udp   2049  nfs

    100021    1   udp  34174  nlockmgr

    100021    3   udp  34174  nlockmgr

    100021    4   udp  34174  nlockmgr

    100021    1   tcp  34174  nlockmgr

    100021    3   tcp  34174  nlockmgr

    100021    4   tcp  34174  nlockmgr

    100003    2   tcp   2049  nfs

    100003    3   tcp   2049  nfs

    100003    4   tcp   2049  nfs

Both client and server use iptables, but it is not an issue: 

1) all necessary ports on the server are fixed and allowed for the client.

2) control check with iptables disabled on both systems produce the same result.

My client system is: Linux 2.6.28.7-yoruichi i686 AMD Athlon(tm) XP 3200+.

NFS support is compiled into the kernel.

nfs-utils-1.1.5.

rpc.statd and rpc.idmapd are running.

This problem affects both NFSv3 and NFSv4.

At this point I'm confused by the system behaviour: everything looks ok, it should work, but it doesn't work.

Here is record from /etc/fstab:

172.19.0.1:/            /mnt/orionis    nfs4            ro

And logs for umount /mnt/orionis (it was successfully mounted before) after performing on the client:

# rpcdebug -m rpc all

# rpcdebug -m nfs all

# umount /mnt/orionis

Apr 02 18:27:08 [kernel] NFS: dentry_delete(/, 4)

Apr 02 18:27:08 [kernel] --> nfs_free_server()

Apr 02 18:27:08 [kernel] RPC:       shutting down nfs client for 172.19.0.1

Apr 02 18:27:08 [kernel] RPC:       rpc_release_client(f4dc1000)

Apr 02 18:27:08 [kernel] RPC:       destroying nfs client for 172.19.0.1

Apr 02 18:27:08 [kernel] RPC:       rpc_release_client(f4dc1200)

Apr 02 18:27:08 [kernel] --> nfs_put_client({1})

Apr 02 18:27:08 [kernel] --> nfs_free_client(4)

Apr 02 18:27:08 [kernel] RPC:       shutting down nfs client for 172.19.0.1

Apr 02 18:27:08 [kernel] RPC:       rpc_release_client(f4dc1200)

Apr 02 18:27:08 [kernel] RPC:       destroying UNIX authenticator c063c2e0

Apr 02 18:27:08 [kernel] RPC:       destroying nfs client for 172.19.0.1

Apr 02 18:27:08 [kernel] RPC:       destroying transport f4c8e800

Apr 02 18:27:08 [kernel] RPC:       xs_destroy xprt f4c8e800

Apr 02 18:27:08 [kernel] RPC:       xs_close xprt f4c8e800

Apr 02 18:27:08 [kernel] RPC:       disconnected transport f4c8e800

Apr 02 18:27:08 [kernel] svc: server d30f8000, no data yet

Apr 02 18:27:08 [kernel] svc: svc_destroy(NFSv4 callback, 1)

Apr 02 18:27:08 [kernel] svc: svc_delete_xprt(f4dc1600)

Apr 02 18:27:08 [kernel] svc: svc_sock_detach(f4dc1600)

Apr 02 18:27:08 [kernel] svc: svc_sock_free(f4dc1600)

Apr 02 18:27:08 [kernel] RPC:       unregistering [1073741824, 1, ::.0.0, ''] with local rpcbind

Apr 02 18:27:08 [kernel] RPC:       set up transport to address addr=0000:0000:0000:0000:0000:0000:0000:0001 port=111 proto=udp

Apr 02 18:27:08 [kernel] RPC:       created transport f4c8f000 with 16 slots

Apr 02 18:27:08 [kernel] RPC:       creating rpcbind client for localhost (xprt f4c8f000)

Apr 02 18:27:08 [kernel] RPC:       creating UNIX authenticator for client d30eac00

Apr 02 18:27:08 [kernel] RPC:     0 looking up UNIX cred

Apr 02 18:27:08 [kernel] RPC:       looking up UNIX cred

Apr 02 18:27:08 [kernel] RPC:       allocating UNIX cred for uid 0 gid 0

Apr 02 18:27:08 [kernel] RPC:       new task initialized, procpid 12297

Apr 02 18:27:08 [kernel] RPC:       allocated task f7051aa0

Apr 02 18:27:08 [kernel] RPC:   202 __rpc_execute flags=0x280

Apr 02 18:27:08 [kernel] RPC:   202 call_start rpcbind4 proc UNSET (sync)

Apr 02 18:27:08 [kernel] RPC:   202 call_reserve (status 0)

Apr 02 18:27:08 [kernel] RPC:   202 reserved req d30f8000 xid 2d97f96e

Apr 02 18:27:08 [kernel] RPC:   202 call_reserveresult (status 0)

Apr 02 18:27:08 [kernel] RPC:   202 call_allocate (status 0)

Apr 02 18:27:08 [kernel] RPC:   202 allocated buffer of size 484 at f6605000

Apr 02 18:27:08 [kernel] RPC:   202 call_bind (status 0)

Apr 02 18:27:08 [kernel] RPC:   202 call_connect xprt f4c8f000 is not connected

Apr 02 18:27:08 [kernel] RPC:   202 xprt_connect xprt f4c8f000 is not connected

Apr 02 18:27:08 [kernel] RPC:   202 xprt_cwnd_limited cong = 0 cwnd = 256

Apr 02 18:27:08 [kernel] RPC:   202 sleep_on(queue "xprt_pending" time 3404849)

Apr 02 18:27:08 [kernel] RPC:   202 added to queue f4c8f188 "xprt_pending"

Apr 02 18:27:08 [kernel] RPC:   202 setting alarm for 5000 ms

Apr 02 18:27:08 [kernel] RPC:       xs_connect scheduled xprt f4c8f000

Apr 02 18:27:08 [kernel] RPC:   202 sync task going to sleep

Apr 02 18:27:08 [kernel] RPC:       disconnected transport f4c8f000

Apr 02 18:27:08 [kernel] RPC:   202 __rpc_wake_up_task (now 3404849)

Apr 02 18:27:08 [kernel] RPC:   202 disabling timer

Apr 02 18:27:08 [kernel] RPC:   202 removed from queue f4c8f188 "xprt_pending"

Apr 02 18:27:08 [kernel] RPC:       __rpc_wake_up_task done

Apr 02 18:27:08 [kernel] RPC:       xs_bind6 0000:0000:0000:0000:0000:0000:0000:0000:781: ok (0)

Apr 02 18:27:08 [kernel] RPC:       worker connecting xprt f4c8f000 to address: addr=0000:0000:0000:0000:0000:0000:0000:0001 port=111 proto=udp

Apr 02 18:27:08 [kernel] RPC:   202 sync task resuming

Apr 02 18:27:08 [kernel] RPC:   202 xprt_connect_status: connection broken

Apr 02 18:27:08 [kernel] RPC:   202 call_connect_status (status -107)

Apr 02 18:27:08 [kernel] RPC:   202 call_timeout (minor)

Apr 02 18:27:08 [kernel] RPC:   202 call_bind (status 0)

Apr 02 18:27:08 [kernel] RPC:   202 call_connect xprt f4c8f000 is connected

Apr 02 18:27:08 [kernel] RPC:   202 call_transmit (status 0)

Apr 02 18:27:08 [kernel] RPC:   202 xprt_prepare_transmit

Apr 02 18:27:08 [kernel] RPC:   202 rpc_xdr_encode (status 0)

Apr 02 18:27:08 [kernel] RPC:   202 marshaling UNIX cred d30df180

Apr 02 18:27:08 [kernel] RPC:   202 using AUTH_UNIX cred d30df180 to wrap rpc data

Apr 02 18:27:08 [kernel] RPC:       encoding rpcb request (1073741824, 1, ::.0.0)

Apr 02 18:27:08 [kernel] RPC:   202 xprt_transmit(156)

Apr 02 18:27:08 [kernel] RPC:       xs_udp_send_request(156) = 156

Apr 02 18:27:08 [kernel] RPC:   202 xmit complete

Apr 02 18:27:08 [kernel] RPC:   202 sleep_on(queue "xprt_pending" time 3404849)

Apr 02 18:27:08 [kernel] RPC:   202 added to queue f4c8f188 "xprt_pending"

Apr 02 18:27:08 [kernel] RPC:   202 setting alarm for 10000 ms

Apr 02 18:27:08 [kernel] RPC:   202 sync task going to sleep

Apr 02 18:27:08 [kernel] RPC:       unx_free_cred f4e95b00

Apr 02 18:27:08 [kernel] RPC:       unx_free_cred f5b7bf80

Apr 02 18:27:18 [kernel] RPC:   202 timeout

Apr 02 18:27:18 [kernel] RPC:   202 __rpc_wake_up_task (now 3407849)

Apr 02 18:27:18 [kernel] RPC:   202 disabling timer

Apr 02 18:27:18 [kernel] RPC:   202 removed from queue f4c8f188 "xprt_pending"

Apr 02 18:27:18 [kernel] RPC:       __rpc_wake_up_task done

Apr 02 18:27:18 [kernel] RPC:   202 sync task resuming

Apr 02 18:27:18 [kernel] RPC:   202 xprt_timer

Apr 02 18:27:18 [kernel] RPC:       cong 256, cwnd was 256, now 256

Apr 02 18:27:18 [kernel] RPC:       wake_up_next(f4c8f13c "xprt_resend")

Apr 02 18:27:18 [kernel] RPC:       wake_up_next(f4c8f0f0 "xprt_sending")

Apr 02 18:27:18 [kernel] RPC:   202 call_status (status -110)

Apr 02 18:27:18 [kernel] RPC:   202 call_timeout (minor)

Apr 02 18:27:18 [kernel] RPC:   202 call_bind (status 0)

Apr 02 18:27:18 [kernel] RPC:   202 call_connect xprt f4c8f000 is connected

Apr 02 18:27:18 [kernel] RPC:   202 call_transmit (status 0)

Apr 02 18:27:18 [kernel] RPC:   202 xprt_prepare_transmit

Apr 02 18:27:18 [kernel] RPC:   202 xprt_cwnd_limited cong = 0 cwnd = 256

Apr 02 18:27:18 [kernel] RPC:   202 rpc_xdr_encode (status 0)

Apr 02 18:27:18 [kernel] RPC:   202 marshaling UNIX cred d30df180

Apr 02 18:27:18 [kernel] RPC:   202 using AUTH_UNIX cred d30df180 to wrap rpc data

Apr 02 18:27:18 [kernel] RPC:       encoding rpcb request (1073741824, 1, ::.0.0)

Apr 02 18:27:18 [kernel] RPC:   202 xprt_transmit(156)

Apr 02 18:27:18 [kernel] RPC:       xs_udp_send_request(156) = 156

Apr 02 18:27:18 [kernel] RPC:   202 xmit complete

Apr 02 18:27:18 [kernel] RPC:   202 sleep_on(queue "xprt_pending" time 3407849)

Apr 02 18:27:18 [kernel] RPC:   202 added to queue f4c8f188 "xprt_pending"

Apr 02 18:27:18 [kernel] RPC:   202 setting alarm for 20000 ms

Apr 02 18:27:18 [kernel] RPC:   202 sync task going to sleep

Apr 02 18:27:38 [kernel] RPC:   202 timeout

Apr 02 18:27:38 [kernel] RPC:   202 __rpc_wake_up_task (now 3413849)

Apr 02 18:27:38 [kernel] RPC:   202 disabling timer

Apr 02 18:27:38 [kernel] RPC:   202 removed from queue f4c8f188 "xprt_pending"

Apr 02 18:27:38 [kernel] RPC:       __rpc_wake_up_task done

Apr 02 18:27:38 [kernel] RPC:   202 sync task resuming

Apr 02 18:27:38 [kernel] RPC:   202 xprt_timer

Apr 02 18:27:38 [kernel] RPC:       cong 256, cwnd was 256, now 256

Apr 02 18:27:38 [kernel] RPC:       wake_up_next(f4c8f13c "xprt_resend")

Apr 02 18:27:38 [kernel] RPC:       wake_up_next(f4c8f0f0 "xprt_sending")

Apr 02 18:27:38 [kernel] RPC:   202 call_status (status -110)

Apr 02 18:27:38 [kernel] RPC:   202 call_timeout (major)

Apr 02 18:27:38 [kernel] rpcbind: server localhost not responding, timed out

Apr 02 18:27:38 [kernel] RPC:   202 return 0, status -5

Apr 02 18:27:38 [kernel] RPC:   202 release task

Apr 02 18:27:38 [kernel] RPC:       freeing buffer of size 484 at f6605000

Apr 02 18:27:38 [kernel] RPC:   202 release request d30f8000

Apr 02 18:27:38 [kernel] RPC:       wake_up_next(f4c8f1d4 "xprt_backlog")

Apr 02 18:27:38 [kernel] RPC:   202 releasing UNIX cred d30df180

Apr 02 18:27:38 [kernel] RPC:       rpc_release_client(d30eac00)

Apr 02 18:27:38 [kernel] RPC:   202 freeing task

Apr 02 18:27:38 [kernel] RPC:       shutting down rpcbind client for localhost

Apr 02 18:27:38 [kernel] RPC:       rpc_release_client(d30eac00)

Apr 02 18:27:38 [kernel] RPC:       destroying UNIX authenticator c063c2e0

Apr 02 18:27:38 [kernel] RPC:       destroying rpcbind client for localhost

Apr 02 18:27:38 [kernel] RPC:       destroying transport f4c8f000

Apr 02 18:27:38 [kernel] RPC:       xs_destroy xprt f4c8f000

Apr 02 18:27:38 [kernel] RPC:       xs_close xprt f4c8f000

Apr 02 18:27:38 [kernel] RPC:       disconnected transport f4c8f000

Apr 02 18:27:38 [kernel] RPC: failed to contact local rpcbind server (errno 5).

Apr 02 18:27:38 [kernel] svc: __svc_unregister(NFSv4 callbackv1), error -5

Apr 02 18:27:38 [kernel] <-- nfs_free_client()

Apr 02 18:27:38 [kernel] <-- nfs_free_server()

Apr 02 18:27:38 [kernel] RPC:       unx_free_cred d30df180

And logs for mounting it again:

# mount /mnt/orionis

Apr 02 18:29:41 [kernel] NFS: nfs mount opts='clientaddr=172.19.0.3,addr=172.19.0.1'

Apr 02 18:29:41 [kernel] NFS:   parsing nfs mount option 'clientaddr=172.19.0.3'

Apr 02 18:29:41 [kernel] NFS:   parsing nfs mount option 'addr=172.19.0.1'

Apr 02 18:29:41 [kernel] NFS: parsing IPv4 address 172.19.0.1

Apr 02 18:29:41 [kernel] NFS: MNTPATH: '/'

Apr 02 18:29:41 [kernel] --> nfs4_create_server()

Apr 02 18:29:41 [kernel] --> nfs4_init_server()

Apr 02 18:29:41 [kernel] --> nfs4_set_client()

Apr 02 18:29:41 [kernel] --> nfs_get_client(172.19.0.1,v4)

Apr 02 18:29:41 [kernel] svc: initialising pool 0 for NFSv4 callback

Apr 02 18:29:41 [kernel] RPC:       unregistering [1073741824, 1, ::.0.0, ''] with local rpcbind

Apr 02 18:29:41 [kernel] RPC:       set up transport to address addr=0000:0000:0000:0000:0000:0000:0000:0001 port=111 proto=udp

Apr 02 18:29:41 [kernel] RPC:       created transport f4c8f400 with 16 slots

Apr 02 18:29:41 [kernel] RPC:       creating rpcbind client for localhost (xprt f4c8f400)

Apr 02 18:29:41 [kernel] RPC:       creating UNIX authenticator for client f4dcd400

Apr 02 18:29:41 [kernel] RPC:     0 looking up UNIX cred

Apr 02 18:29:41 [kernel] RPC:       looking up UNIX cred

Apr 02 18:29:41 [kernel] RPC:       allocating UNIX cred for uid 0 gid 0

Apr 02 18:29:41 [kernel] RPC:       new task initialized, procpid 12302

Apr 02 18:29:41 [kernel] RPC:       allocated task f7051aa0

Apr 02 18:29:41 [kernel] RPC:   203 __rpc_execute flags=0x280

Apr 02 18:29:41 [kernel] RPC:   203 call_start rpcbind4 proc UNSET (sync)

Apr 02 18:29:41 [kernel] RPC:   203 call_reserve (status 0)

Apr 02 18:29:41 [kernel] RPC:   203 reserved req d30fb000 xid b17c688a

Apr 02 18:29:41 [kernel] RPC:   203 call_reserveresult (status 0)

Apr 02 18:29:41 [kernel] RPC:   203 call_allocate (status 0)

Apr 02 18:29:41 [kernel] RPC:   203 allocated buffer of size 484 at f4db5800

Apr 02 18:29:41 [kernel] RPC:   203 call_bind (status 0)

Apr 02 18:29:41 [kernel] RPC:   203 call_connect xprt f4c8f400 is not connected

Apr 02 18:29:41 [kernel] RPC:   203 xprt_connect xprt f4c8f400 is not connected

Apr 02 18:29:41 [kernel] RPC:   203 xprt_cwnd_limited cong = 0 cwnd = 256

Apr 02 18:29:41 [kernel] RPC:   203 sleep_on(queue "xprt_pending" time 3450862)

Apr 02 18:29:41 [kernel] RPC:   203 added to queue f4c8f588 "xprt_pending"

Apr 02 18:29:41 [kernel] RPC:   203 setting alarm for 5000 ms

Apr 02 18:29:41 [kernel] RPC:       xs_connect scheduled xprt f4c8f400

Apr 02 18:29:41 [kernel] RPC:   203 sync task going to sleep

Apr 02 18:29:41 [kernel] RPC:       disconnected transport f4c8f400

Apr 02 18:29:41 [kernel] RPC:   203 __rpc_wake_up_task (now 3450862)

Apr 02 18:29:41 [kernel] RPC:   203 disabling timer

Apr 02 18:29:41 [kernel] RPC:   203 removed from queue f4c8f588 "xprt_pending"

Apr 02 18:29:41 [kernel] RPC:       __rpc_wake_up_task done

Apr 02 18:29:41 [kernel] RPC:       xs_bind6 0000:0000:0000:0000:0000:0000:0000:0000:1022: ok (0)

Apr 02 18:29:41 [kernel] RPC:       worker connecting xprt f4c8f400 to address: addr=0000:0000:0000:0000:0000:0000:0000:0001 port=111 proto=udp

Apr 02 18:29:41 [kernel] RPC:   203 sync task resuming

Apr 02 18:29:41 [kernel] RPC:   203 xprt_connect_status: connection broken

Apr 02 18:29:41 [kernel] RPC:   203 call_connect_status (status -107)

Apr 02 18:29:41 [kernel] RPC:   203 call_timeout (minor)

Apr 02 18:29:41 [kernel] RPC:   203 call_bind (status 0)

Apr 02 18:29:41 [kernel] RPC:   203 call_connect xprt f4c8f400 is connected

Apr 02 18:29:41 [kernel] RPC:   203 call_transmit (status 0)

Apr 02 18:29:41 [kernel] RPC:   203 xprt_prepare_transmit

Apr 02 18:29:41 [kernel] RPC:   203 rpc_xdr_encode (status 0)

Apr 02 18:29:41 [kernel] RPC:   203 marshaling UNIX cred d30aac00

Apr 02 18:29:41 [kernel] RPC:   203 using AUTH_UNIX cred d30aac00 to wrap rpc data

Apr 02 18:29:41 [kernel] RPC:       encoding rpcb request (1073741824, 1, ::.0.0)

Apr 02 18:29:41 [kernel] RPC:   203 xprt_transmit(156)

Apr 02 18:29:41 [kernel] RPC:       xs_udp_send_request(156) = 156

Apr 02 18:29:41 [kernel] RPC:   203 xmit complete

Apr 02 18:29:41 [kernel] RPC:   203 sleep_on(queue "xprt_pending" time 3450862)

Apr 02 18:29:41 [kernel] RPC:   203 added to queue f4c8f588 "xprt_pending"

Apr 02 18:29:41 [kernel] RPC:   203 setting alarm for 10000 ms

Apr 02 18:29:41 [kernel] RPC:   203 sync task going to sleep

Apr 02 18:29:51 [kernel] RPC:   203 timeout

Apr 02 18:29:51 [kernel] RPC:   203 __rpc_wake_up_task (now 3453862)

Apr 02 18:29:51 [kernel] RPC:   203 disabling timer

Apr 02 18:29:51 [kernel] RPC:   203 removed from queue f4c8f588 "xprt_pending"

Apr 02 18:29:51 [kernel] RPC:       __rpc_wake_up_task done

Apr 02 18:29:51 [kernel] RPC:   203 sync task resuming

Apr 02 18:29:51 [kernel] RPC:   203 xprt_timer

Apr 02 18:29:51 [kernel] RPC:       cong 256, cwnd was 256, now 256

Apr 02 18:29:51 [kernel] RPC:       wake_up_next(f4c8f53c "xprt_resend")

Apr 02 18:29:51 [kernel] RPC:       wake_up_next(f4c8f4f0 "xprt_sending")

Apr 02 18:29:51 [kernel] RPC:   203 call_status (status -110)

Apr 02 18:29:51 [kernel] RPC:   203 call_timeout (minor)

Apr 02 18:29:51 [kernel] RPC:   203 call_bind (status 0)

Apr 02 18:29:51 [kernel] RPC:   203 call_connect xprt f4c8f400 is connected

Apr 02 18:29:51 [kernel] RPC:   203 call_transmit (status 0)

Apr 02 18:29:51 [kernel] RPC:   203 xprt_prepare_transmit

Apr 02 18:29:51 [kernel] RPC:   203 xprt_cwnd_limited cong = 0 cwnd = 256

Apr 02 18:29:51 [kernel] RPC:   203 rpc_xdr_encode (status 0)

Apr 02 18:29:51 [kernel] RPC:   203 marshaling UNIX cred d30aac00

Apr 02 18:29:51 [kernel] RPC:   203 using AUTH_UNIX cred d30aac00 to wrap rpc data

Apr 02 18:29:51 [kernel] RPC:       encoding rpcb request (1073741824, 1, ::.0.0)

Apr 02 18:29:51 [kernel] RPC:   203 xprt_transmit(156)

Apr 02 18:29:51 [kernel] RPC:       xs_udp_send_request(156) = 156

Apr 02 18:29:51 [kernel] RPC:   203 xmit complete

Apr 02 18:29:51 [kernel] RPC:   203 sleep_on(queue "xprt_pending" time 3453862)

Apr 02 18:29:51 [kernel] RPC:   203 added to queue f4c8f588 "xprt_pending"

Apr 02 18:29:51 [kernel] RPC:   203 setting alarm for 20000 ms

Apr 02 18:29:51 [kernel] RPC:   203 sync task going to sleep

Apr 02 18:30:11 [kernel] RPC:   205 added to queue f4d32188 "xprt_pending"

Apr 02 18:30:11 [kernel] RPC:   205 setting alarm for 60000 ms

Apr 02 18:30:11 [kernel] RPC:       wake_up_next(f4d3213c "xprt_resend")

Apr 02 18:30:11 [kernel] RPC:       wake_up_next(f4d320f0 "xprt_sending")

Apr 02 18:30:11 [kernel] RPC:   205 sync task going to sleep

Apr 02 18:30:11 [kernel] RPC:       xs_tcp_data_ready...

Apr 02 18:30:11 [kernel] RPC:       xs_tcp_data_recv started

Apr 02 18:30:11 [kernel] RPC:       reading TCP record fragment of length 264

Apr 02 18:30:11 [kernel] RPC:       reading XID (4 bytes)

Apr 02 18:30:11 [kernel] RPC:       reading reply for XID d654b02d

Apr 02 18:30:11 [kernel] RPC:       XID d654b02d read 260 bytes

Apr 02 18:30:11 [kernel] RPC:       xprt = f4d32000, tcp_copied = 264, tcp_offset = 264, tcp_reclen = 264

Apr 02 18:30:11 [kernel] RPC:   205 xid d654b02d complete (264 bytes received)

Apr 02 18:30:11 [kernel] RPC:   205 __rpc_wake_up_task (now 3459862)

Apr 02 18:30:11 [kernel] RPC:   205 disabling timer

Apr 02 18:30:11 [kernel] RPC:   205 removed from queue f4d32188 "xprt_pending"

Apr 02 18:30:11 [kernel] RPC:       __rpc_wake_up_task done

Apr 02 18:30:11 [kernel] RPC:       xs_tcp_data_recv done

Apr 02 18:30:11 [kernel] RPC:   205 sync task resuming

Apr 02 18:30:11 [kernel] RPC:   205 call_status (status 264)

Apr 02 18:30:11 [kernel] RPC:   205 call_decode (status 264)

Apr 02 18:30:11 [kernel] RPC:   205 validating UNIX cred f4e3a200

Apr 02 18:30:11 [kernel] RPC:   205 using AUTH_UNIX cred f4e3a200 to unwrap rpc data

Apr 02 18:30:11 [kernel] decode_attr_type: type=02

Apr 02 18:30:11 [kernel] decode_attr_change: change attribute=5318178494755110912

Apr 02 18:30:11 [kernel] decode_attr_size: file size=4096

Apr 02 18:30:11 [kernel] decode_attr_fsid: fsid=(0x0/0x0)

Apr 02 18:30:11 [kernel] decode_attr_fileid: fileid=2

Apr 02 18:30:11 [kernel] decode_attr_fs_locations: fs_locations done, error = 0

Apr 02 18:30:11 [kernel] decode_attr_mode: file mode=0775

Apr 02 18:30:11 [kernel] decode_attr_nlink: nlink=9

Apr 02 18:30:11 [kernel] decode_attr_owner: uid=65534

Apr 02 18:30:11 [kernel] decode_attr_group: gid=65534

Apr 02 18:30:11 [kernel] decode_attr_rdev: rdev=(0x0:0x0)

Apr 02 18:30:11 [kernel] decode_attr_space_used: space used=4096

Apr 02 18:30:11 [kernel] decode_attr_time_access: atime=1231210863

Apr 02 18:30:11 [kernel] decode_attr_time_metadata: ctime=1238234922

Apr 02 18:30:11 [kernel] decode_attr_time_modify: mtime=1238234922

Apr 02 18:30:11 [kernel] decode_attr_mounted_on_fileid: fileid=0

Apr 02 18:30:11 [kernel] decode_getfattr: xdr returned 0

Apr 02 18:30:11 [kernel] RPC:   205 call_decode result 0

Apr 02 18:30:11 [kernel] RPC:   205 return 0, status 0

Apr 02 18:30:11 [kernel] RPC:   205 release task

Apr 02 18:30:11 [kernel] RPC:       freeing buffer of size 980 at f6606000

Apr 02 18:30:11 [kernel] RPC:   205 release request d30fc000

Apr 02 18:30:11 [kernel] RPC:       wake_up_next(f4d321d4 "xprt_backlog")

Apr 02 18:30:11 [kernel] RPC:   205 releasing UNIX cred f4e3a200

Apr 02 18:30:11 [kernel] RPC:       rpc_release_client(f4dc1600)

Apr 02 18:30:11 [kernel] RPC:   205 freeing task

Apr 02 18:30:11 [kernel] RPC:     0 looking up UNIX cred

Apr 02 18:30:11 [kernel] RPC:       looking up UNIX cred

Apr 02 18:30:11 [kernel] RPC:       new task initialized, procpid 12302

Apr 02 18:30:11 [kernel] RPC:       allocated task f7051aa0

Apr 02 18:30:11 [kernel] RPC:   206 __rpc_execute flags=0x80

Apr 02 18:30:11 [kernel] RPC:   206 call_start nfs4 proc SERVER_CAPS (sync)

Apr 02 18:30:11 [kernel] RPC:   206 call_reserve (status 0)

Apr 02 18:30:11 [kernel] RPC:   206 reserved req d30fc000 xid d754b02d

Apr 02 18:30:11 [kernel] RPC:   206 call_reserveresult (status 0)

Apr 02 18:30:11 [kernel] RPC:   206 call_allocate (status 0)

Apr 02 18:30:11 [kernel] RPC:   206 allocated buffer of size 968 at f4db7800

Apr 02 18:30:11 [kernel] RPC:   206 call_bind (status 0)

Apr 02 18:30:11 [kernel] RPC:   206 call_connect xprt f4d32000 is connected

Apr 02 18:30:11 [kernel] RPC:   206 call_transmit (status 0)

Apr 02 18:30:11 [kernel] RPC:   206 xprt_prepare_transmit

Apr 02 18:30:11 [kernel] RPC:   206 rpc_xdr_encode (status 0)

Apr 02 18:30:11 [kernel] RPC:   206 marshaling UNIX cred f4e3a200

Apr 02 18:30:11 [kernel] RPC:   206 using AUTH_UNIX cred f4e3a200 to wrap rpc data

Apr 02 18:30:11 [kernel] encode_compound: tag=

Apr 02 18:30:11 [kernel] RPC:   206 xprt_transmit(180)

Apr 02 18:30:11 [kernel] RPC:       xs_tcp_send_request(180) = 180

Apr 02 18:30:11 [kernel] RPC:   206 xmit complete

Apr 02 18:30:11 [kernel] RPC:   206 sleep_on(queue "xprt_pending" time 3459862)

Apr 02 18:30:11 [kernel] RPC:   206 added to queue f4d32188 "xprt_pending"

Apr 02 18:30:11 [kernel] RPC:   206 setting alarm for 60000 ms

Apr 02 18:30:11 [kernel] RPC:       wake_up_next(f4d3213c "xprt_resend")

Apr 02 18:30:11 [kernel] RPC:       wake_up_next(f4d320f0 "xprt_sending")

Apr 02 18:30:11 [kernel] RPC:   206 sync task going to sleep

Apr 02 18:30:11 [kernel] RPC:       xs_tcp_data_ready...

Apr 02 18:30:11 [kernel] RPC:       xs_tcp_data_recv started

Apr 02 18:30:11 [kernel] RPC:       reading TCP record fragment of length 92

Apr 02 18:30:11 [kernel] RPC:       reading XID (4 bytes)

Apr 02 18:30:11 [kernel] RPC:       reading reply for XID d754b02d

Apr 02 18:30:11 [kernel] RPC:       XID d754b02d read 88 bytes

Apr 02 18:30:11 [kernel] RPC:       xprt = f4d32000, tcp_copied = 92, tcp_offset = 92, tcp_reclen = 92

Apr 02 18:30:11 [kernel] RPC:   206 xid d754b02d complete (92 bytes received)

Apr 02 18:30:11 [kernel] RPC:   206 __rpc_wake_up_task (now 3459862)

Apr 02 18:30:11 [kernel] RPC:   206 disabling timer

Apr 02 18:30:11 [kernel] RPC:   206 removed from queue f4d32188 "xprt_pending"

Apr 02 18:30:11 [kernel] RPC:       __rpc_wake_up_task done

Apr 02 18:30:11 [kernel] RPC:       xs_tcp_data_recv done

Apr 02 18:30:11 [kernel] RPC:   206 sync task resuming

Apr 02 18:30:11 [kernel] RPC:   206 call_status (status 92)

Apr 02 18:30:11 [kernel] RPC:   206 call_decode (status 92)

Apr 02 18:30:11 [kernel] RPC:   206 validating UNIX cred f4e3a200

Apr 02 18:30:11 [kernel] decode_attr_supported: bitmask=fcffafff:00f9be3e

Apr 02 18:30:11 [kernel] decode_attr_link_support: link support=true

Apr 02 18:30:11 [kernel] decode_attr_symlink_support: symlink support=true

Apr 02 18:30:11 [kernel] decode_attr_aclsupport: ACLs supported=0

Apr 02 18:30:11 [kernel] decode_server_caps: xdr returned 0!

Apr 02 18:30:11 [kernel] RPC:   206 call_decode result 0

Apr 02 18:30:11 [kernel] RPC:   206 return 0, status 0

Apr 02 18:30:11 [kernel] RPC:   206 release task

Apr 02 18:30:11 [kernel] RPC:       freeing buffer of size 968 at f4db7800

Apr 02 18:30:11 [kernel] RPC:   206 release request d30fc000

Apr 02 18:30:11 [kernel] RPC:       wake_up_next(f4d321d4 "xprt_backlog")

Apr 02 18:30:11 [kernel] RPC:   206 releasing UNIX cred f4e3a200

Apr 02 18:30:11 [kernel] RPC:       rpc_release_client(f4dc1600)

Apr 02 18:30:11 [kernel] RPC:   206 freeing task

Apr 02 18:30:11 [kernel] RPC:     0 looking up UNIX cred

Apr 02 18:30:11 [kernel] RPC:       looking up UNIX cred

Apr 02 18:30:11 [kernel] RPC:       new task initialized, procpid 12302

Apr 02 18:30:11 [kernel] RPC:       allocated task f7051aa0

Apr 02 18:30:11 [kernel] RPC:   207 __rpc_execute flags=0x80

Apr 02 18:30:11 [kernel] RPC:   207 call_start nfs4 proc FSINFO (sync)

Apr 02 18:30:11 [kernel] RPC:   207 call_reserve (status 0)

Apr 02 18:30:11 [kernel] RPC:   207 reserved req d30fc000 xid d854b02d

Apr 02 18:30:11 [kernel] RPC:   207 call_reserveresult (status 0)

Apr 02 18:30:11 [kernel] RPC:   207 call_allocate (status 0)

Apr 02 18:30:11 [kernel] RPC:   207 allocated buffer of size 628 at f5b36000

Apr 02 18:30:11 [kernel] RPC:   207 call_bind (status 0)

Apr 02 18:30:11 [kernel] RPC:   207 call_connect xprt f4d32000 is connected

Apr 02 18:30:11 [kernel] RPC:   207 call_transmit (status 0)

Apr 02 18:30:11 [kernel] RPC:   207 xprt_prepare_transmit

Apr 02 18:30:11 [kernel] RPC:   207 rpc_xdr_encode (status 0)

Apr 02 18:30:11 [kernel] RPC:   207 marshaling UNIX cred f4e3a200

Apr 02 18:30:11 [kernel] RPC:   207 using AUTH_UNIX cred f4e3a200 to wrap rpc data

Apr 02 18:30:11 [kernel] encode_compound: tag=

Apr 02 18:30:11 [kernel] RPC:   207 xprt_transmit(184)

Apr 02 18:30:11 [kernel] RPC:       xs_tcp_send_request(184) = 184

Apr 02 18:30:11 [kernel] RPC:   207 xmit complete

Apr 02 18:30:11 [kernel] RPC:   207 sleep_on(queue "xprt_pending" time 3459862)

Apr 02 18:30:11 [kernel] RPC:   207 added to queue f4d32188 "xprt_pending"

Apr 02 18:30:11 [kernel] RPC:   207 setting alarm for 60000 ms

Apr 02 18:30:11 [kernel] RPC:       wake_up_next(f4d3213c "xprt_resend")

Apr 02 18:30:11 [kernel] RPC:       wake_up_next(f4d320f0 "xprt_sending")

Apr 02 18:30:11 [kernel] RPC:   207 sync task going to sleep

Apr 02 18:30:11 [kernel] RPC:       xs_tcp_data_ready...

Apr 02 18:30:11 [kernel] RPC:       xs_tcp_data_recv started

Apr 02 18:30:11 [kernel] RPC:       reading TCP record fragment of length 96

Apr 02 18:30:11 [kernel] RPC:       reading XID (4 bytes)

Apr 02 18:30:11 [kernel] RPC:       reading reply for XID d854b02d

Apr 02 18:30:11 [kernel] RPC:       XID d854b02d read 92 bytes

Apr 02 18:30:11 [kernel] RPC:       xprt = f4d32000, tcp_copied = 96, tcp_offset = 96, tcp_reclen = 96

Apr 02 18:30:11 [kernel] RPC:   207 xid d854b02d complete (96 bytes received)

Apr 02 18:30:11 [kernel] RPC:   207 __rpc_wake_up_task (now 3459862)

Apr 02 18:30:11 [kernel] RPC:   207 disabling timer

Apr 02 18:30:11 [kernel] RPC:   207 removed from queue f4d32188 "xprt_pending"

Apr 02 18:30:11 [kernel] RPC:       __rpc_wake_up_task done

Apr 02 18:30:11 [kernel] RPC:       xs_tcp_data_recv done

Apr 02 18:30:11 [kernel] RPC:   207 sync task resuming

Apr 02 18:30:11 [kernel] RPC:   207 call_status (status 96)

Apr 02 18:30:11 [kernel] RPC:   207 call_decode (status 96)

Apr 02 18:30:11 [kernel] RPC:   207 validating UNIX cred f4e3a200

Apr 02 18:30:11 [kernel] RPC:   207 using AUTH_UNIX cred f4e3a200 to unwrap rpc data

Apr 02 18:30:11 [kernel] decode_attr_lease_time: file size=90

Apr 02 18:30:11 [kernel] decode_attr_maxfilesize: maxfilesize=18446744073709551615

Apr 02 18:30:11 [kernel] decode_attr_maxread: maxread=131072

Apr 02 18:30:11 [kernel] decode_attr_maxwrite: maxwrite=131072

Apr 02 18:30:11 [kernel] decode_fsinfo: xdr returned 0!

Apr 02 18:30:11 [kernel] RPC:   207 call_decode result 0

Apr 02 18:30:11 [kernel] RPC:   207 return 0, status 0

Apr 02 18:30:11 [kernel] RPC:   207 release task

Apr 02 18:30:11 [kernel] RPC:       freeing buffer of size 628 at f5b36000

Apr 02 18:30:11 [kernel] RPC:   207 release request d30fc000

Apr 02 18:30:11 [kernel] RPC:       wake_up_next(f4d321d4 "xprt_backlog")

Apr 02 18:30:11 [kernel] RPC:   207 releasing UNIX cred f4e3a200

Apr 02 18:30:11 [kernel] RPC:       rpc_release_client(f4dc1600)

Apr 02 18:30:11 [kernel] RPC:   207 freeing task

Apr 02 18:30:11 [kernel] Next:

Apr 02 18:30:11 [kernel] <-- nfs4_path_walk() = 0

Apr 02 18:30:11 [kernel] Server FSID: 0:0

Apr 02 18:30:11 [kernel] Mount FH: 20

Apr 02 18:30:11 [kernel] --> nfs_probe_fsinfo()

Apr 02 18:30:11 [kernel] RPC:     0 looking up UNIX cred

Apr 02 18:30:11 [kernel] RPC:       looking up UNIX cred

Apr 02 18:30:11 [kernel] RPC:       new task initialized, procpid 12302

Apr 02 18:30:11 [kernel] RPC:       allocated task f7051aa0

Apr 02 18:30:11 [kernel] RPC:   208 __rpc_execute flags=0x80

Apr 02 18:30:11 [kernel] RPC:   208 call_start nfs4 proc SERVER_CAPS (sync)

Apr 02 18:30:11 [kernel] RPC:   208 call_reserve (status 0)

Apr 02 18:30:11 [kernel] RPC:   208 reserved req d30fc000 xid d954b02d

Apr 02 18:30:11 [kernel] RPC:   208 call_reserveresult (status 0)

Apr 02 18:30:11 [kernel] RPC:   208 call_allocate (status 0)

Apr 02 18:30:11 [kernel] RPC:   208 allocated buffer of size 968 at f5b36000

Apr 02 18:30:11 [kernel] RPC:   208 call_bind (status 0)

Apr 02 18:30:11 [kernel] RPC:   208 call_connect xprt f4d32000 is connected

Apr 02 18:30:11 [kernel] RPC:   208 call_transmit (status 0)

Apr 02 18:30:11 [kernel] RPC:   208 xprt_prepare_transmit

Apr 02 18:30:11 [kernel] RPC:   208 rpc_xdr_encode (status 0)

Apr 02 18:30:11 [kernel] RPC:   208 marshaling UNIX cred f4e3a200

Apr 02 18:30:11 [kernel] RPC:   208 using AUTH_UNIX cred f4e3a200 to wrap rpc data

Apr 02 18:30:11 [kernel] RPC:       xs_tcp_send_request(180) = 180

Apr 02 18:30:11 [kernel] RPC:   208 xmit complete

Apr 02 18:30:11 [kernel] RPC:   208 sleep_on(queue "xprt_pending" time 3459862)

Apr 02 18:30:11 [kernel] RPC:   208 added to queue f4d32188 "xprt_pending"

Apr 02 18:30:11 [kernel] RPC:   208 setting alarm for 60000 ms

Apr 02 18:30:11 [kernel] RPC:       wake_up_next(f4d3213c "xprt_resend")

Apr 02 18:30:11 [kernel] RPC:       wake_up_next(f4d320f0 "xprt_sending")

Apr 02 18:30:11 [kernel] RPC:   208 sync task going to sleep

Apr 02 18:30:11 [kernel] RPC:       xs_tcp_data_ready...

Apr 02 18:30:11 [kernel] RPC:       xs_tcp_data_recv started

Apr 02 18:30:11 [kernel] RPC:       reading TCP record fragment of length 92

Apr 02 18:30:11 [kernel] RPC:       reading XID (4 bytes)

Apr 02 18:30:11 [kernel] RPC:       reading reply for XID d954b02d

Apr 02 18:30:11 [kernel] RPC:       XID d954b02d read 88 bytes

Apr 02 18:30:11 [kernel] RPC:       xprt = f4d32000, tcp_copied = 92, tcp_offset = 92, tcp_reclen = 92

Apr 02 18:30:11 [kernel] RPC:   208 xid d954b02d complete (92 bytes received)

Apr 02 18:30:11 [kernel] RPC:   208 __rpc_wake_up_task (now 3459862)

Apr 02 18:30:11 [kernel] RPC:   208 disabling timer

Apr 02 18:30:11 [kernel] RPC:   208 removed from queue f4d32188 "xprt_pending"

Apr 02 18:30:11 [kernel] RPC:       __rpc_wake_up_task done

Apr 02 18:30:11 [kernel] RPC:       xs_tcp_data_recv done

Apr 02 18:30:11 [kernel] RPC:   208 sync task resuming

Apr 02 18:30:11 [kernel] RPC:   208 call_status (status 92)

Apr 02 18:30:11 [kernel] RPC:   208 call_decode (status 92)

Apr 02 18:30:11 [kernel] RPC:   208 validating UNIX cred f4e3a200

Apr 02 18:30:11 [kernel] RPC:   208 using AUTH_UNIX cred f4e3a200 to unwrap rpc data

Apr 02 18:30:11 [kernel] decode_attr_supported: bitmask=fcffafff:00f9be3e

Apr 02 18:30:11 [kernel] decode_attr_link_support: link support=true

Apr 02 18:30:11 [kernel] decode_attr_symlink_support: symlink support=true

Apr 02 18:30:11 [kernel] decode_attr_aclsupport: ACLs supported=0

Apr 02 18:30:11 [kernel] decode_server_caps: xdr returned 0!

Apr 02 18:30:11 [kernel] RPC:   208 call_decode result 0

Apr 02 18:30:11 [kernel] RPC:   208 return 0, status 0

Apr 02 18:30:11 [kernel] RPC:   208 release task

Apr 02 18:30:11 [kernel] RPC:       freeing buffer of size 968 at f5b36000

Apr 02 18:30:11 [kernel] RPC:   208 release request d30fc000

Apr 02 18:30:11 [kernel] RPC:       wake_up_next(f4d321d4 "xprt_backlog")

Apr 02 18:30:11 [kernel] RPC:   208 releasing UNIX cred f4e3a200

Apr 02 18:30:11 [kernel] RPC:       rpc_release_client(f4dc1600)

Apr 02 18:30:11 [kernel] RPC:   208 freeing task

Apr 02 18:30:11 [kernel] RPC:     0 looking up UNIX cred

Apr 02 18:30:11 [kernel] RPC:       looking up UNIX cred

Apr 02 18:30:11 [kernel] RPC:       new task initialized, procpid 12302

Apr 02 18:30:11 [kernel] RPC:       allocated task f7051aa0

Apr 02 18:30:11 [kernel] RPC:   209 __rpc_execute flags=0x80

Apr 02 18:30:11 [kernel] RPC:   209 call_start nfs4 proc FSINFO (sync)

Apr 02 18:30:11 [kernel] RPC:   209 call_reserve (status 0)

Apr 02 18:30:11 [kernel] RPC:   209 reserved req d30fc000 xid da54b02d

Apr 02 18:30:11 [kernel] RPC:   209 call_reserveresult (status 0)

Apr 02 18:30:11 [kernel] RPC:   209 call_allocate (status 0)

Apr 02 18:30:11 [kernel] RPC:   209 allocated buffer of size 628 at f5bb1800

Apr 02 18:30:11 [kernel] RPC:   209 call_bind (status 0)

Apr 02 18:30:11 [kernel] RPC:   209 call_connect xprt f4d32000 is connected

Apr 02 18:30:11 [kernel] RPC:   209 call_transmit (status 0)

Apr 02 18:30:11 [kernel] RPC:   209 xprt_prepare_transmit

Apr 02 18:30:11 [kernel] RPC:   209 rpc_xdr_encode (status 0)

Apr 02 18:30:11 [kernel] RPC:   209 marshaling UNIX cred f4e3a200

Apr 02 18:30:11 [kernel] RPC:   209 using AUTH_UNIX cred f4e3a200 to wrap rpc data

Apr 02 18:30:11 [kernel] encode_compound: tag=

Apr 02 18:30:11 [kernel] RPC:   209 xprt_transmit(184)

Apr 02 18:30:11 [kernel] RPC:       xs_tcp_send_request(184) = 184

Apr 02 18:30:11 [kernel] RPC:   209 xmit complete

Apr 02 18:30:11 [kernel] RPC:   209 sleep_on(queue "xprt_pending" time 3459862)

Apr 02 18:30:11 [kernel] RPC:   209 added to queue f4d32188 "xprt_pending"

Apr 02 18:30:11 [kernel] RPC:   209 setting alarm for 60000 ms

Apr 02 18:30:11 [kernel] RPC:       wake_up_next(f4d3213c "xprt_resend")

Apr 02 18:30:11 [kernel] RPC:       wake_up_next(f4d320f0 "xprt_sending")

Apr 02 18:30:11 [kernel] RPC:   209 sync task going to sleep

Apr 02 18:30:11 [kernel] RPC:       xs_tcp_data_ready...

Apr 02 18:30:11 [kernel] RPC:       xs_tcp_data_recv started

Apr 02 18:30:11 [kernel] RPC:       reading TCP record fragment of length 96

Apr 02 18:30:11 [kernel] RPC:       reading XID (4 bytes)

Apr 02 18:30:11 [kernel] RPC:       reading reply for XID da54b02d

Apr 02 18:30:11 [kernel] RPC:       XID da54b02d read 92 bytes

Apr 02 18:30:11 [kernel] RPC:       xprt = f4d32000, tcp_copied = 96, tcp_offset = 96, tcp_reclen = 96

Apr 02 18:30:11 [kernel] RPC:   209 xid da54b02d complete (96 bytes received)

Apr 02 18:30:11 [kernel] RPC:   209 __rpc_wake_up_task (now 3459862)

Apr 02 18:30:11 [kernel] RPC:   209 disabling timer

Apr 02 18:30:11 [kernel] RPC:   209 removed from queue f4d32188 "xprt_pending"

Apr 02 18:30:11 [kernel] RPC:       __rpc_wake_up_task done

Apr 02 18:30:11 [kernel] RPC:       xs_tcp_data_recv done

Apr 02 18:30:11 [kernel] RPC:   209 sync task resuming

Apr 02 18:30:11 [kernel] RPC:   209 call_status (status 96)

Apr 02 18:30:11 [kernel] RPC:   209 call_decode (status 96)

Apr 02 18:30:11 [kernel] RPC:   209 validating UNIX cred f4e3a200

Apr 02 18:30:11 [kernel] RPC:   209 using AUTH_UNIX cred f4e3a200 to unwrap rpc data

Apr 02 18:30:11 [kernel] decode_attr_lease_time: file size=90

Apr 02 18:30:11 [kernel] decode_attr_maxfilesize: maxfilesize=18446744073709551615

Apr 02 18:30:11 [kernel] decode_attr_maxread: maxread=131072

Apr 02 18:30:11 [kernel] decode_attr_maxwrite: maxwrite=131072

Apr 02 18:30:11 [kernel] decode_fsinfo: xdr returned 0!

Apr 02 18:30:11 [kernel] RPC:   209 call_decode result 0

Apr 02 18:30:11 [kernel] RPC:   209 return 0, status 0

Apr 02 18:30:11 [kernel] RPC:       xs_tcp_send_request(180) = 180

Apr 02 18:30:11 [kernel] RPC:   209 release request d30fc000

Apr 02 18:30:11 [kernel] RPC:       wake_up_next(f4d321d4 "xprt_backlog")

Apr 02 18:30:11 [kernel] RPC:   209 releasing UNIX cred f4e3a200

Apr 02 18:30:11 [kernel] RPC:       rpc_release_client(f4dc1600)

Apr 02 18:30:11 [kernel] RPC:   209 freeing task

Apr 02 18:30:11 [kernel] RPC:     0 looking up UNIX cred

Apr 02 18:30:11 [kernel] RPC:       looking up UNIX cred

Apr 02 18:30:11 [kernel] RPC:       new task initialized, procpid 12302

Apr 02 18:30:11 [kernel] RPC:       allocated task f7051aa0

Apr 02 18:30:11 [kernel] RPC:   210 __rpc_execute flags=0x80

Apr 02 18:30:11 [kernel] RPC:   210 call_start nfs4 proc PATHCONF (sync)

Apr 02 18:30:11 [kernel] RPC:   210 call_reserve (status 0)

Apr 02 18:30:11 [kernel] RPC:   210 reserved req d30fc000 xid db54b02d

Apr 02 18:30:11 [kernel] RPC:   210 call_reserveresult (status 0)

Apr 02 18:30:11 [kernel] RPC:   210 call_allocate (status 0)

Apr 02 18:30:11 [kernel] RPC:   210 allocated buffer of size 968 at f6617000

Apr 02 18:30:11 [kernel] RPC:   210 call_bind (status 0)

Apr 02 18:30:11 [kernel] RPC:   210 call_connect xprt f4d32000 is connected

Apr 02 18:30:11 [kernel] RPC:   210 call_transmit (status 0)

Apr 02 18:30:11 [kernel] RPC:   210 xprt_prepare_transmit

Apr 02 18:30:11 [kernel] RPC:   210 rpc_xdr_encode (status 0)

Apr 02 18:30:11 [kernel] RPC:   210 marshaling UNIX cred f4e3a200

Apr 02 18:30:11 [kernel] RPC:   210 using AUTH_UNIX cred f4e3a200 to wrap rpc data

Apr 02 18:30:11 [kernel] encode_compound: tag=

Apr 02 18:30:11 [kernel] RPC:   210 xprt_transmit(180)

Apr 02 18:30:11 [kernel] RPC:       xs_tcp_send_request(180) = 180

Apr 02 18:30:11 [kernel] RPC:   210 xmit complete

Apr 02 18:30:11 [kernel] RPC:   210 sleep_on(queue "xprt_pending" time 3459862)

Apr 02 18:30:11 [kernel] RPC:   210 added to queue f4d32188 "xprt_pending"

Apr 02 18:30:11 [kernel] RPC:   210 setting alarm for 60000 ms

Apr 02 18:30:11 [kernel] RPC:       wake_up_next(f4d3213c "xprt_resend")

Apr 02 18:30:11 [kernel] RPC:       wake_up_next(f4d320f0 "xprt_sending")

Apr 02 18:30:11 [kernel] RPC:   210 sync task going to sleep

Apr 02 18:30:11 [kernel] RPC:       xs_tcp_data_ready...

Apr 02 18:30:11 [kernel] RPC:       xs_tcp_data_recv started

Apr 02 18:30:11 [kernel] RPC:       reading TCP record fragment of length 76

Apr 02 18:30:11 [kernel] RPC:       reading XID (4 bytes)

Apr 02 18:30:11 [kernel] RPC:       reading reply for XID db54b02d

Apr 02 18:30:11 [kernel] RPC:       XID db54b02d read 72 bytes

Apr 02 18:30:11 [kernel] RPC:       xprt = f4d32000, tcp_copied = 76, tcp_offset = 76, tcp_reclen = 76

Apr 02 18:30:11 [kernel] RPC:   210 xid db54b02d complete (76 bytes received)

Apr 02 18:30:11 [kernel] RPC:   210 __rpc_wake_up_task (now 3459862)

Apr 02 18:30:11 [kernel] RPC:   210 disabling timer

Apr 02 18:30:11 [kernel] RPC:   210 removed from queue f4d32188 "xprt_pending"

Apr 02 18:30:11 [kernel] RPC:       __rpc_wake_up_task done

Apr 02 18:30:11 [kernel] RPC:       xs_tcp_data_recv done

Apr 02 18:30:11 [kernel] RPC:   210 sync task resuming

Apr 02 18:30:11 [kernel] RPC:   210 call_status (status 76)

Apr 02 18:30:11 [kernel] RPC:   210 call_decode (status 76)

Apr 02 18:30:11 [kernel] RPC:   210 validating UNIX cred f4e3a200

Apr 02 18:30:11 [kernel] RPC:   210 using AUTH_UNIX cred f4e3a200 to unwrap rpc data

Apr 02 18:30:11 [kernel] decode_attr_maxlink: maxlink=255

Apr 02 18:30:11 [kernel] decode_attr_maxname: maxname=255

Apr 02 18:30:11 [kernel] decode_pathconf: xdr returned 0!

Apr 02 18:30:11 [kernel] RPC:   210 call_decode result 0

Apr 02 18:30:11 [kernel] RPC:   210 return 0, status 0

Apr 02 18:30:11 [kernel] RPC:   210 release task

Apr 02 18:30:11 [kernel] RPC:       freeing buffer of size 968 at f6617000

Apr 02 18:30:11 [kernel] RPC:   210 release request d30fc000

Apr 02 18:30:11 [kernel] RPC:       wake_up_next(f4d321d4 "xprt_backlog")

Apr 02 18:30:11 [kernel] RPC:   210 releasing UNIX cred f4e3a200

Apr 02 18:30:11 [kernel] RPC:       rpc_release_client(f4dc1600)

Apr 02 18:30:11 [kernel] RPC:   210 freeing task

Apr 02 18:30:11 [kernel] <-- nfs_probe_fsinfo() = 0

Apr 02 18:30:11 [kernel] <-- nfs4_create_server() = f4dcda00

Apr 02 18:30:11 [kernel] --> nfs4_get_root()

Apr 02 18:30:11 [kernel] RPC:     0 looking up UNIX cred

Apr 02 18:30:11 [kernel] RPC:       looking up UNIX cred

Apr 02 18:30:11 [kernel] RPC:       new task initialized, procpid 12302

Apr 02 18:30:11 [kernel] RPC:       allocated task f7051aa0

Apr 02 18:30:11 [kernel] RPC:   211 __rpc_execute flags=0x80

Apr 02 18:30:11 [kernel] RPC:   211 call_start nfs4 proc SERVER_CAPS (sync)

Apr 02 18:30:11 [kernel] RPC:   211 call_reserve (status 0)

Apr 02 18:30:11 [kernel] RPC:   211 reserved req d30fc000 xid dc54b02d

Apr 02 18:30:11 [kernel] RPC:   211 call_reserveresult (status 0)

Apr 02 18:30:11 [kernel] RPC:   211 call_allocate (status 0)

Apr 02 18:30:11 [kernel] RPC:   211 allocated buffer of size 968 at f6617000

Apr 02 18:30:11 [kernel] RPC:   211 call_bind (status 0)

Apr 02 18:30:11 [kernel] RPC:   211 call_connect xprt f4d32000 is connected

Apr 02 18:30:11 [kernel] RPC:   211 call_transmit (status 0)

Apr 02 18:30:11 [kernel] RPC:   211 xprt_prepare_transmit

Apr 02 18:30:11 [kernel] RPC:   211 rpc_xdr_encode (status 0)

Apr 02 18:30:11 [kernel] RPC:   211 marshaling UNIX cred f4e3a200

Apr 02 18:30:11 [kernel] RPC:   211 using AUTH_UNIX cred f4e3a200 to wrap rpc data

Apr 02 18:30:11 [kernel] encode_compound: tag=

Apr 02 18:30:11 [kernel] RPC:   211 xprt_transmit(180)

Apr 02 18:30:11 [kernel] RPC:       xs_tcp_send_request(180) = 180

Apr 02 18:30:11 [kernel] RPC:   211 xmit complete

Apr 02 18:30:11 [kernel] RPC:   211 sleep_on(queue "xprt_pending" time 3459863)

Apr 02 18:30:11 [kernel] RPC:   211 added to queue f4d32188 "xprt_pending"

Apr 02 18:30:11 [kernel] RPC:   211 setting alarm for 60000 ms

Apr 02 18:30:11 [kernel] RPC:       wake_up_next(f4d3213c "xprt_resend")

Apr 02 18:30:11 [kernel] RPC:       wake_up_next(f4d320f0 "xprt_sending")

Apr 02 18:30:11 [kernel] RPC:   211 sync task going to sleep

Apr 02 18:30:11 [kernel] RPC:       xs_tcp_data_ready...

Apr 02 18:30:11 [kernel] RPC:       reading XID (4 bytes)

Apr 02 18:30:11 [kernel] RPC:       reading reply for XID dc54b02d

Apr 02 18:30:11 [kernel] RPC:       XID dc54b02d read 88 bytes

Apr 02 18:30:11 [kernel] RPC:       xprt = f4d32000, tcp_copied = 92, tcp_offset = 92, tcp_reclen = 92

Apr 02 18:30:11 [kernel] RPC:   211 xid dc54b02d complete (92 bytes received)

Apr 02 18:30:11 [kernel] RPC:   211 __rpc_wake_up_task (now 3459863)

Apr 02 18:30:11 [kernel] RPC:   211 disabling timer

Apr 02 18:30:11 [kernel] RPC:   211 removed from queue f4d32188 "xprt_pending"

Apr 02 18:30:11 [kernel] RPC:       __rpc_wake_up_task done

Apr 02 18:30:11 [kernel] RPC:       xs_tcp_data_recv done

Apr 02 18:30:11 [kernel] RPC:   211 sync task resuming

Apr 02 18:30:11 [kernel] RPC:   211 call_status (status 92)

Apr 02 18:30:11 [kernel] RPC:   211 call_decode (status 92)

Apr 02 18:30:11 [kernel] RPC:   211 validating UNIX cred f4e3a200

Apr 02 18:30:11 [kernel] RPC:   211 using AUTH_UNIX cred f4e3a200 to unwrap rpc data

Apr 02 18:30:11 [kernel] decode_attr_supported: bitmask=fcffafff:00f9be3e

Apr 02 18:30:11 [kernel] decode_attr_link_support: link support=true

Apr 02 18:30:11 [kernel] decode_attr_symlink_support: symlink support=true

Apr 02 18:30:11 [kernel] decode_attr_aclsupport: ACLs supported=0

Apr 02 18:30:11 [kernel] decode_server_caps: xdr returned 0!

Apr 02 18:30:11 [kernel] RPC:   211 call_decode result 0

Apr 02 18:30:11 [kernel] RPC:   211 return 0, status 0

Apr 02 18:30:11 [kernel] RPC:   211 release task

Apr 02 18:30:11 [kernel] RPC:       freeing buffer of size 968 at f6617000

Apr 02 18:30:11 [kernel] RPC:   211 release request d30fc000

Apr 02 18:30:11 [kernel] RPC:       wake_up_next(f4d321d4 "xprt_backlog")

Apr 02 18:30:11 [kernel] RPC:   211 releasing UNIX cred f4e3a200

Apr 02 18:30:11 [kernel] RPC:       rpc_release_client(f4dc1600)

Apr 02 18:30:11 [kernel] RPC:   211 freeing task

Apr 02 18:30:11 [kernel] RPC:     0 looking up UNIX cred

Apr 02 18:30:11 [kernel] RPC:       looking up UNIX cred

Apr 02 18:30:11 [kernel] RPC:       new task initialized, procpid 12302

Apr 02 18:30:11 [kernel] RPC:       allocated task f7051aa0

Apr 02 18:30:11 [kernel] RPC:   212 __rpc_execute flags=0x80

Apr 02 18:30:11 [kernel] RPC:   212 call_start nfs4 proc GETATTR (sync)

Apr 02 18:30:11 [kernel] RPC:   212 call_reserve (status 0)

Apr 02 18:30:11 [kernel] RPC:   212 reserved req d30fc000 xid dd54b02d

Apr 02 18:30:11 [kernel] RPC:   212 call_reserveresult (status 0)

Apr 02 18:30:11 [kernel] RPC:   212 call_allocate (status 0)

Apr 02 18:30:11 [kernel] RPC:   212 allocated buffer of size 968 at f6617000

Apr 02 18:30:11 [kernel] RPC:   212 call_bind (status 0)

Apr 02 18:30:11 [kernel] RPC:   212 call_connect xprt f4d32000 is connected

Apr 02 18:30:11 [kernel] RPC:   212 call_transmit (status 0)

Apr 02 18:30:11 [kernel] RPC:   212 xprt_prepare_transmit

Apr 02 18:30:11 [kernel] RPC:   212 rpc_xdr_encode (status 0)

Apr 02 18:30:11 [kernel] RPC:   212 marshaling UNIX cred f4e3a200

Apr 02 18:30:11 [kernel] RPC:   212 using AUTH_UNIX cred f4e3a200 to wrap rpc data

Apr 02 18:30:11 [kernel] encode_compound: tag=

Apr 02 18:30:11 [kernel] RPC:   212 xprt_transmit(184)

Apr 02 18:30:11 [kernel] RPC:       xs_tcp_send_request(184) = 184

Apr 02 18:30:11 [kernel] RPC:   212 xmit complete

Apr 02 18:30:11 [kernel] RPC:   212 sleep_on(queue "xprt_pending" time 3459863)

Apr 02 18:30:11 [kernel] RPC:   212 added to queue f4d32188 "xprt_pending"

Apr 02 18:30:11 [kernel] RPC:   212 setting alarm for 60000 ms

Apr 02 18:30:11 [kernel] RPC:       wake_up_next(f4d3213c "xprt_resend")

Apr 02 18:30:11 [kernel] RPC:       wake_up_next(f4d320f0 "xprt_sending")

Apr 02 18:30:11 [kernel] RPC:   212 sync task going to sleep

Apr 02 18:30:11 [kernel] RPC:       xs_tcp_data_ready...

Apr 02 18:30:11 [kernel] RPC:       xs_tcp_data_recv started

Apr 02 18:30:11 [kernel] RPC:       reading TCP record fragment of length 232

Apr 02 18:30:11 [kernel] RPC:       reading XID (4 bytes)

Apr 02 18:30:11 [kernel] RPC:       reading reply for XID dd54b02d

Apr 02 18:30:11 [kernel] RPC:       XID dd54b02d read 228 bytes

Apr 02 18:30:11 [kernel] RPC:       xprt = f4d32000, tcp_copied = 232, tcp_offset = 232, tcp_reclen = 232

Apr 02 18:30:11 [kernel] RPC:   212 xid dd54b02d complete (232 bytes received)

Apr 02 18:30:11 [kernel] RPC:   212 __rpc_wake_up_task (now 3459863)

Apr 02 18:30:11 [kernel] RPC:   212 disabling timer

Apr 02 18:30:11 [kernel] RPC:   212 removed from queue f4d32188 "xprt_pending"

Apr 02 18:30:11 [kernel] RPC:       __rpc_wake_up_task done

Apr 02 18:30:11 [kernel] RPC:       xs_tcp_data_recv done

Apr 02 18:30:11 [kernel] RPC:   212 sync task resuming

Apr 02 18:30:11 [kernel] RPC:   212 call_status (status 232)

Apr 02 18:30:11 [kernel] RPC:   212 call_decode (status 232)

Apr 02 18:30:11 [kernel] RPC:   212 validating UNIX cred f4e3a200

Apr 02 18:30:11 [kernel] RPC:   212 using AUTH_UNIX cred f4e3a200 to unwrap rpc data

Apr 02 18:30:11 [kernel] decode_attr_type: type=02

Apr 02 18:30:11 [kernel] decode_attr_change: change attribute=5318178494755110912

Apr 02 18:30:11 [kernel] decode_attr_size: file size=4096

Apr 02 18:30:11 [kernel] decode_attr_fsid: fsid=(0x0/0x0)

Apr 02 18:30:11 [kernel] decode_attr_fileid: fileid=2

Apr 02 18:30:11 [kernel] decode_attr_fs_locations: fs_locations done, error = 0

Apr 02 18:30:11 [kernel] decode_attr_mode: file mode=0775

Apr 02 18:30:11 [kernel] decode_attr_nlink: nlink=9

Apr 02 18:30:11 [kernel] decode_attr_owner: uid=65534

Apr 02 18:30:11 [kernel] decode_attr_group: gid=65534

Apr 02 18:30:11 [kernel] decode_attr_rdev: rdev=(0x0:0x0)

Apr 02 18:30:11 [kernel] decode_attr_space_used: space used=4096

Apr 02 18:30:11 [kernel] decode_attr_time_access: atime=1231210863

Apr 02 18:30:11 [kernel] decode_attr_time_metadata: ctime=1238234922

Apr 02 18:30:11 [kernel] decode_attr_time_modify: mtime=1238234922

Apr 02 18:30:11 [kernel] decode_attr_mounted_on_fileid: fileid=0

Apr 02 18:30:11 [kernel] decode_getfattr: xdr returned 0

Apr 02 18:30:11 [kernel] RPC:   212 call_decode result 0

Apr 02 18:30:11 [kernel] RPC:   212 return 0, status 0

Apr 02 18:30:11 [kernel] RPC:   212 release task

Apr 02 18:30:11 [kernel] RPC:   212 release request d30fc000

Apr 02 18:30:11 [kernel] RPC:       wake_up_next(f4d321d4 "xprt_backlog")

Apr 02 18:30:11 [kernel] RPC:   212 releasing UNIX cred f4e3a200

Apr 02 18:30:11 [kernel] RPC:       rpc_release_client(f4dc1600)

Apr 02 18:30:11 [kernel] RPC:   212 freeing task

Apr 02 18:30:11 [kernel] NFS: nfs_fhget(0:14/2 ct=1)

Apr 02 18:30:11 [kernel] <-- nfs4_get_root()

----------

## Bircoph

I found solution: replace portmap by rpcbind, the former is buggy.

My versions:

net-nds/portmap-6.0

net-nds/rpcbind-0.1.7

net-fs/nfs-utils-1.1.5-r1 (this patch: https://bugs.gentoo.org/show_bug.cgi?id=261926 for proper rpcbind deps)

----------

