Hi;

I have a NFS read problem which happens simultaneously.
I try to copy a 1GB file from NFS mount point and it completes in a few seconds. After a while I try the same copy again, I get a zero byte file and my file is not copied.
Same happens when I just try to open the file.

uname -r on client:
2.6.32-279.19.1.el6.x86_64

uname -r on server:
2.6.18-128.5om

I have enabled roc and nfs debugging.
I get below error on server:
Mar 10 12:23:07 IPTV-HBCB1-1 kernel: svc: socket ffff810127ad1400 busy, not enqueued

Any ideas on how to fix this?
Regards

Server Log:
Mar 10 12:23:07 IPTV-HBCB1-1 kernel: svc: socket ffff810127ad1400 TCP data ready (svsk ffff8100a156f7c0)
Mar 10 12:23:07 IPTV-HBCB1-1 kernel: svc: socket ffff810127ad1400 served by daemon ffff8100a06c0800
Mar 10 12:23:07 IPTV-HBCB1-1 kernel: svc: server ffff8100a06c0800, socket ffff8100a156f7c0, inuse=1
Mar 10 12:23:07 IPTV-HBCB1-1 kernel: svc: tcp_recv ffff8100a156f7c0 data 1 conn 0 close 0
Mar 10 12:23:07 IPTV-HBCB1-1 kernel: svc: socket ffff8100a156f7c0 recvfrom(ffff8100a156f86c, 0) = 4
Mar 10 12:23:07 IPTV-HBCB1-1 kernel: svc: TCP record, 104 bytes
Mar 10 12:23:07 IPTV-HBCB1-1 kernel: svc: socket ffff8100a156f7c0 recvfrom(ffff8100a06a9068, 3992) = 104
Mar 10 12:23:07 IPTV-HBCB1-1 kernel: svc: TCP complete record (104 bytes)
Mar 10 12:23:07 IPTV-HBCB1-1 kernel: svc: socket ffff810127ad1400 served by daemon ffff8100a067ec00
Mar 10 12:23:07 IPTV-HBCB1-1 kernel: svc: got len=104
Mar 10 12:23:07 IPTV-HBCB1-1 kernel: svc: svc_authenticate (1)
Mar 10 12:23:07 IPTV-HBCB1-1 kernel: svc: socket ffff810127ad1400 busy, not enqueued
Mar 10 12:23:07 IPTV-HBCB1-1 kernel: svc: calling dispatcher
Mar 10 12:23:07 IPTV-HBCB1-1 kernel: nfsd_dispatch: vers 3 proc 1
Mar 10 12:23:07 IPTV-HBCB1-1 kernel: nfsd: GETATTR(3) 24: 03000001 17000000 00000001 00000024 1cae2a78 1cae2a78
Mar 10 12:23:07 IPTV-HBCB1-1 kernel: nfsd: fh_verify(24: 03000001 17000000 00000001 00000024 1cae2a78 1cae2a78)
Mar 10 12:23:07 IPTV-HBCB1-1 kernel: svc: socket ffff8100a156f7c0 sendto([ffff81007cc2f000 116... ], 116) = 116 (addr 40400a0a)
Mar 10 12:23:07 IPTV-HBCB1-1 kernel: svc: socket ffff810127ad1400 busy, not enqueued
Mar 10 12:23:07 IPTV-HBCB1-1 kernel: svc: server ffff8100a06c0800 waiting for data (to = 3600000)
Mar 10 12:23:07 IPTV-HBCB1-1 kernel: svc: server ffff8100a067ec00, socket ffff8100a156f7c0, inuse=1
Mar 10 12:23:07 IPTV-HBCB1-1 kernel: svc: tcp_recv ffff8100a156f7c0 data 1 conn 0 close 0
Mar 10 12:23:07 IPTV-HBCB1-1 kernel: svc: socket ffff8100a156f7c0 recvfrom(ffff8100a156f868, 4) = -11
Mar 10 12:23:07 IPTV-HBCB1-1 kernel: RPC: TCP recvfrom got EAGAIN
Mar 10 12:23:07 IPTV-HBCB1-1 kernel: svc: got len=-11
Mar 10 12:23:07 IPTV-HBCB1-1 kernel: svc: server ffff8100a067ec00 waiting for data (to = 3600000)
Mar 10 12:23:07 IPTV-HBCB1-1 kernel: svc: socket ffff810127ad1400 TCP data ready (svsk ffff8100a156f7c0)
Mar 10 12:23:07 IPTV-HBCB1-1 kernel: svc: socket ffff810127ad1400 served by daemon ffff8100a067ec00
Mar 10 12:23:07 IPTV-HBCB1-1 kernel: svc: server ffff8100a067ec00, socket ffff8100a156f7c0, inuse=1
Mar 10 12:23:07 IPTV-HBCB1-1 kernel: svc: tcp_recv ffff8100a156f7c0 data 1 conn 0 close 0
Mar 10 12:23:07 IPTV-HBCB1-1 kernel: svc: socket ffff8100a156f7c0 recvfrom(ffff8100a156f86c, 0) = 4
Mar 10 12:23:07 IPTV-HBCB1-1 kernel: svc: TCP record, 104 bytes
Mar 10 12:23:07 IPTV-HBCB1-1 kernel: svc: socket ffff8100a156f7c0 recvfrom(ffff8100a0681068, 3992) = 104
Mar 10 12:23:07 IPTV-HBCB1-1 kernel: svc: TCP complete record (104 bytes)
Mar 10 12:23:07 IPTV-HBCB1-1 kernel: svc: socket ffff810127ad1400 served by daemon ffff8100a06c0800
Mar 10 12:23:07 IPTV-HBCB1-1 kernel: svc: got len=104
Mar 10 12:23:07 IPTV-HBCB1-1 kernel: svc: svc_authenticate (1)
Mar 10 12:23:07 IPTV-HBCB1-1 kernel: svc: socket ffff810127ad1400 busy, not enqueued
Mar 10 12:23:07 IPTV-HBCB1-1 kernel: svc: calling dispatcher
Mar 10 12:23:07 IPTV-HBCB1-1 kernel: nfsd_dispatch: vers 3 proc 1
Mar 10 12:23:07 IPTV-HBCB1-1 kernel: nfsd: GETATTR(3) 24: 03000001 17000000 00000001 00000024 1cae2a78 1cae2a78
Mar 10 12:23:07 IPTV-HBCB1-1 kernel: nfsd: fh_verify(24: 03000001 17000000 00000001 00000024 1cae2a78 1cae2a78)
Mar 10 12:23:07 IPTV-HBCB1-1 kernel: svc: socket ffff8100a156f7c0 sendto([ffff81007da79000 116... ], 116) = 116 (addr 40400a0a)
Mar 10 12:23:07 IPTV-HBCB1-1 kernel: svc: socket ffff810127ad1400 busy, not enqueued
Mar 10 12:23:07 IPTV-HBCB1-1 kernel: svc: server ffff8100a067ec00 waiting for data (to = 3600000)
Mar 10 12:23:07 IPTV-HBCB1-1 kernel: svc: server ffff8100a06c0800, socket ffff8100a156f7c0, inuse=1
Mar 10 12:23:07 IPTV-HBCB1-1 kernel: svc: tcp_recv ffff8100a156f7c0 data 1 conn 0 close 0
Mar 10 12:23:07 IPTV-HBCB1-1 kernel: svc: socket ffff8100a156f7c0 recvfrom(ffff8100a156f868, 4) = -11
Mar 10 12:23:07 IPTV-HBCB1-1 kernel: RPC: TCP recvfrom got EAGAIN
Mar 10 12:23:07 IPTV-HBCB1-1 kernel: svc: got len=-11
Mar 10 12:23:07 IPTV-HBCB1-1 kernel: svc: server ffff8100a06c0800 waiting for data (to = 3600000)
Mar 10 12:23:07 IPTV-HBCB1-1 kernel: svc: socket ffff810127ad1400 TCP data ready (svsk ffff8100a156f7c0)
Mar 10 12:23:07 IPTV-HBCB1-1 kernel: svc: socket ffff810127ad1400 served by daemon ffff8100a06c0800
Mar 10 12:23:07 IPTV-HBCB1-1 kernel: svc: server ffff8100a06c0800, socket ffff8100a156f7c0, inuse=1
Mar 10 12:23:07 IPTV-HBCB1-1 kernel: svc: tcp_recv ffff8100a156f7c0 data 1 conn 0 close 0
Mar 10 12:23:07 IPTV-HBCB1-1 kernel: svc: socket ffff8100a156f7c0 recvfrom(ffff8100a156f86c, 0) = 4
Mar 10 12:23:07 IPTV-HBCB1-1 kernel: svc: TCP record, 108 bytes
Mar 10 12:23:07 IPTV-HBCB1-1 kernel: svc: socket ffff8100a156f7c0 recvfrom(ffff8100a06a906c, 3988) = 108
Mar 10 12:23:07 IPTV-HBCB1-1 kernel: svc: TCP complete record (108 bytes)
Mar 10 12:23:07 IPTV-HBCB1-1 kernel: svc: socket ffff810127ad1400 served by daemon ffff8100a067ec00
Mar 10 12:23:07 IPTV-HBCB1-1 kernel: svc: got len=108
Mar 10 12:23:07 IPTV-HBCB1-1 kernel: svc: svc_authenticate (1)
Mar 10 12:23:07 IPTV-HBCB1-1 kernel: svc: socket ffff810127ad1400 busy, not enqueued
Mar 10 12:23:07 IPTV-HBCB1-1 kernel: svc: calling dispatcher
Mar 10 12:23:07 IPTV-HBCB1-1 kernel: nfsd_dispatch: vers 3 proc 4
Mar 10 12:23:07 IPTV-HBCB1-1 kernel: nfsd: ACCESS(3) 24: 03000001 17000000 00000001 00000024 1cae2a78 1cae2a78 0x2d
Mar 10 12:23:07 IPTV-HBCB1-1 kernel: nfsd: fh_verify(24: 03000001 17000000 00000001 00000024 1cae2a78 1cae2a78)
Mar 10 12:23:07 IPTV-HBCB1-1 kernel: svc: socket ffff8100a156f7c0 sendto([ffff81007cc7c000 124... ], 124) = 124 (addr 40400a0a)
Mar 10 12:23:07 IPTV-HBCB1-1 kernel: svc: socket ffff810127ad1400 busy, not enqueued
Mar 10 12:23:07 IPTV-HBCB1-1 kernel: svc: server ffff8100a06c0800 waiting for data (to = 3600000)
Mar 10 12:23:07 IPTV-HBCB1-1 kernel: svc: server ffff8100a067ec00, socket ffff8100a156f7c0, inuse=1
Mar 10 12:23:07 IPTV-HBCB1-1 kernel: svc: tcp_recv ffff8100a156f7c0 data 1 conn 0 close 0
Mar 10 12:23:07 IPTV-HBCB1-1 kernel: svc: socket ffff8100a156f7c0 recvfrom(ffff8100a156f868, 4) = -11
Mar 10 12:23:07 IPTV-HBCB1-1 kernel: RPC: TCP recvfrom got EAGAIN
Mar 10 12:23:07 IPTV-HBCB1-1 kernel: svc: got len=-11
Mar 10 12:23:07 IPTV-HBCB1-1 kernel: svc: server ffff8100a067ec00 waiting for data (to = 3600000)


Client Log:
Mar 10 12:23:07 kltrbatch01 kernel: RPC: looking up Generic cred
Mar 10 12:23:07 kltrbatch01 kernel: NFS: permission(0:13/1), mask=0x1, res=0
Mar 10 12:23:07 kltrbatch01 kernel: NFS: nfs_lookup_revalidate(/Kaltura) is valid
Mar 10 12:23:07 kltrbatch01 kernel: RPC: looking up Generic cred
Mar 10 12:23:07 kltrbatch01 kernel: NFS: permission(0:13/85723100368), mask=0x1, res=0
Mar 10 12:23:07 kltrbatch01 kernel: NFS: nfs_lookup_revalidate(Kaltura/omtest) is valid
Mar 10 12:23:07 kltrbatch01 kernel: RPC: looking up Generic cred
Mar 10 12:23:07 kltrbatch01 kernel: NFS: permission(0:13/153463643104), mask=0x1, res=0
Mar 10 12:23:07 kltrbatch01 kernel: NFS: nfs_lookup_revalidate(omtest/test.mxf) is valid
Mar 10 12:23:07 kltrbatch01 kernel: NFS: revalidating (0:13/155099998840)
Mar 10 12:23:07 kltrbatch01 kernel: NFS call getattr
Mar 10 12:23:07 kltrbatch01 kernel: RPC: new task initialized, procpid 2508
Mar 10 12:23:07 kltrbatch01 kernel: RPC: allocated task ffff880433178080
Mar 10 12:23:07 kltrbatch01 kernel: RPC: 8965 __rpc_execute flags=0x80
Mar 10 12:23:07 kltrbatch01 kernel: RPC: 8965 call_start nfs3 proc GETATTR (sync)
Mar 10 12:23:07 kltrbatch01 kernel: RPC: 8965 call_reserve (status 0)
Mar 10 12:23:07 kltrbatch01 kernel: RPC: 8965 reserved req ffff880433af5400 xid 07f170cb
Mar 10 12:23:07 kltrbatch01 kernel: RPC: wake_up_next(ffff88043188c190 "xprt_sending")
Mar 10 12:23:07 kltrbatch01 kernel: RPC: 8965 call_reserveresult (status 0)
Mar 10 12:23:07 kltrbatch01 kernel: RPC: 8965 call_refresh (status 0)
Mar 10 12:23:07 kltrbatch01 kernel: RPC: 8965 looking up UNIX cred
Mar 10 12:23:07 kltrbatch01 kernel: RPC: looking up UNIX cred
Mar 10 12:23:07 kltrbatch01 kernel: RPC: 8965 refreshing UNIX cred ffff880431162500
Mar 10 12:23:07 kltrbatch01 kernel: RPC: 8965 call_refreshresult (status 0)
Mar 10 12:23:07 kltrbatch01 kernel: RPC: 8965 call_allocate (status 0)
Mar 10 12:23:07 kltrbatch01 kernel: RPC: 8965 allocated buffer of size 552 at ffff880431e0f800
Mar 10 12:23:07 kltrbatch01 kernel: RPC: 8965 call_bind (status 0)
Mar 10 12:23:07 kltrbatch01 kernel: RPC: 8965 call_connect xprt ffff88043188c000 is connected
Mar 10 12:23:07 kltrbatch01 kernel: RPC: 8965 call_transmit (status 0)
Mar 10 12:23:07 kltrbatch01 kernel: RPC: 8965 xprt_prepare_transmit
Mar 10 12:23:07 kltrbatch01 kernel: RPC: 8965 rpc_xdr_encode (status 0)
Mar 10 12:23:07 kltrbatch01 kernel: RPC: 8965 marshaling UNIX cred ffff880431162500
Mar 10 12:23:07 kltrbatch01 kernel: RPC: 8965 using AUTH_UNIX cred ffff880431162500 to wrap rpc data
Mar 10 12:23:07 kltrbatch01 kernel: RPC: 8965 xprt_transmit(108)
Mar 10 12:23:07 kltrbatch01 kernel: RPC: xs_tcp_send_request(108) = 108
Mar 10 12:23:07 kltrbatch01 kernel: RPC: 8965 xmit complete
Mar 10 12:23:07 kltrbatch01 kernel: RPC: 8965 sleep_on(queue "xprt_pending" time 4296743022)
Mar 10 12:23:07 kltrbatch01 kernel: RPC: 8965 added to queue ffff88043188c258 "xprt_pending"
Mar 10 12:23:07 kltrbatch01 kernel: RPC: 8965 setting alarm for 60000 ms
Mar 10 12:23:07 kltrbatch01 kernel: RPC: wake_up_next(ffff88043188c190 "xprt_sending")
Mar 10 12:23:07 kltrbatch01 kernel: RPC: 8965 sync task going to sleep
Mar 10 12:23:07 kltrbatch01 kernel: RPC: xs_tcp_data_ready...
Mar 10 12:23:07 kltrbatch01 kernel: RPC: xs_tcp_data_recv started
Mar 10 12:23:07 kltrbatch01 kernel: RPC: reading TCP record fragment of length 112
Mar 10 12:23:07 kltrbatch01 kernel: RPC: reading XID (4 bytes)
Mar 10 12:23:07 kltrbatch01 kernel: RPC: reading reply for XID 07f170cb
Mar 10 12:23:07 kltrbatch01 kernel: RPC: reading CALL/REPLY flag (4 bytes)
Mar 10 12:23:07 kltrbatch01 kernel: RPC: read reply XID 07f170cb
Mar 10 12:23:07 kltrbatch01 kernel: RPC: XID 07f170cb read 104 bytes
Mar 10 12:23:07 kltrbatch01 kernel: RPC: xprt = ffff88043188c000, tcp_copied = 112, tcp_offset = 112, tcp_reclen = 112
Mar 10 12:23:07 kltrbatch01 kernel: RPC: 8965 xid 07f170cb complete (112 bytes received)
Mar 10 12:23:07 kltrbatch01 kernel: RPC: 8965 __rpc_wake_up_task (now 4296743023)
Mar 10 12:23:07 kltrbatch01 kernel: RPC: 8965 disabling timer
Mar 10 12:23:07 kltrbatch01 kernel: RPC: 8965 removed from queue ffff88043188c258 "xprt_pending"
Mar 10 12:23:07 kltrbatch01 kernel: RPC: __rpc_wake_up_task done
Mar 10 12:23:07 kltrbatch01 kernel: RPC: xs_tcp_data_recv done
Mar 10 12:23:07 kltrbatch01 kernel: RPC: 8965 sync task resuming
Mar 10 12:23:07 kltrbatch01 kernel: RPC: 8965 call_status (status 112)
Mar 10 12:23:07 kltrbatch01 kernel: RPC: 8965 call_decode (status 112)
Mar 10 12:23:07 kltrbatch01 kernel: RPC: 8965 validating UNIX cred ffff880431162500
Mar 10 12:23:07 kltrbatch01 kernel: RPC: 8965 using AUTH_UNIX cred ffff880431162500 to unwrap rpc data
Mar 10 12:23:07 kltrbatch01 kernel: RPC: 8965 call_decode result 0
Mar 10 12:23:07 kltrbatch01 kernel: RPC: 8965 return 0, status 0
Mar 10 12:23:07 kltrbatch01 kernel: RPC: 8965 release task
Mar 10 12:23:07 kltrbatch01 kernel: RPC: freeing buffer of size 552 at ffff880431e0f800
Mar 10 12:23:07 kltrbatch01 kernel: RPC: 8965 release request ffff880433af5400
Mar 10 12:23:07 kltrbatch01 kernel: RPC: wake_up_next(ffff88043188c320 "xprt_backlog")
Mar 10 12:23:07 kltrbatch01 kernel: RPC: rpc_release_client(ffff88042d835e00)
Mar 10 12:23:07 kltrbatch01 kernel: RPC: 8965 freeing task
Mar 10 12:23:07 kltrbatch01 kernel: NFS reply getattr: 0
Mar 10 12:23:07 kltrbatch01 kernel: NFS: nfs_update_inode(0:13/155099998840 ct=1 info=0x7e7f)
Mar 10 12:23:07 kltrbatch01 kernel: NFS: (0:13/155099998840) revalidation complete
Mar 10 12:23:07 kltrbatch01 kernel: NFS: dentry_delete(omtest/test.mxf, 8)
Mar 10 12:23:07 kltrbatch01 kernel: RPC: looking up Generic cred
Mar 10 12:23:07 kltrbatch01 kernel: NFS: permission(0:13/1), mask=0x1, res=0
Mar 10 12:23:07 kltrbatch01 kernel: NFS: nfs_lookup_revalidate(/Kaltura) is valid
Mar 10 12:23:07 kltrbatch01 kernel: RPC: looking up Generic cred
Mar 10 12:23:07 kltrbatch01 kernel: NFS: permission(0:13/85723100368), mask=0x1, res=0
Mar 10 12:23:07 kltrbatch01 kernel: NFS: nfs_lookup_revalidate(Kaltura/omtest) is valid
Mar 10 12:23:07 kltrbatch01 kernel: RPC: looking up Generic cred
Mar 10 12:23:07 kltrbatch01 kernel: NFS: permission(0:13/153463643104), mask=0x1, res=0
Mar 10 12:23:07 kltrbatch01 kernel: NFS: nfs_lookup_revalidate(omtest/test.mxf) is valid
Mar 10 12:23:07 kltrbatch01 kernel: NFS: dentry_delete(omtest/test.mxf, 8)
Mar 10 12:23:07 kltrbatch01 kernel: RPC: looking up Generic cred
Mar 10 12:23:07 kltrbatch01 kernel: NFS: permission(0:13/1), mask=0x1, res=0
Mar 10 12:23:07 kltrbatch01 kernel: NFS: nfs_lookup_revalidate(/Kaltura) is valid
Mar 10 12:23:07 kltrbatch01 kernel: RPC: looking up Generic cred
Mar 10 12:23:07 kltrbatch01 kernel: NFS: permission(0:13/85723100368), mask=0x1, res=0
Mar 10 12:23:07 kltrbatch01 kernel: NFS: nfs_lookup_revalidate(Kaltura/omtest) is valid
Mar 10 12:23:07 kltrbatch01 kernel: RPC: looking up Generic cred
Mar 10 12:23:07 kltrbatch01 kernel: NFS: permission(0:13/1), mask=0x1, res=0
Mar 10 12:23:07 kltrbatch01 kernel: NFS: nfs_lookup_revalidate(/Kaltura) is valid
Mar 10 12:23:07 kltrbatch01 kernel: RPC: looking up Generic cred
Mar 10 12:23:07 kltrbatch01 kernel: NFS: permission(0:13/1), mask=0x1, res=0
Mar 10 12:23:07 kltrbatch01 kernel: NFS: nfs_lookup_revalidate(/Kaltura) is valid
Mar 10 12:23:07 kltrbatch01 kernel: RPC: looking up Generic cred
Mar 10 12:23:07 kltrbatch01 kernel: NFS: permission(0:13/85723100368), mask=0x1, res=0
Mar 10 12:23:07 kltrbatch01 kernel: NFS: nfs_lookup_revalidate(Kaltura/omtest) is valid
Mar 10 12:23:07 kltrbatch01 kernel: RPC: looking up Generic cred
Mar 10 12:23:07 kltrbatch01 kernel: NFS: permission(0:13/153463643104), mask=0x1, res=0
Mar 10 12:23:07 kltrbatch01 kernel: NFS: revalidating (0:13/155099998840)
Mar 10 12:23:07 kltrbatch01 kernel: NFS call getattr
Mar 10 12:23:07 kltrbatch01 kernel: RPC: new task initialized, procpid 2508
Mar 10 12:23:07 kltrbatch01 kernel: RPC: allocated task ffff880433178080
Mar 10 12:23:07 kltrbatch01 kernel: RPC: 8966 __rpc_execute flags=0x80
Mar 10 12:23:07 kltrbatch01 kernel: RPC: 8966 call_start nfs3 proc GETATTR (sync)
Mar 10 12:23:07 kltrbatch01 kernel: RPC: 8966 call_reserve (status 0)
Mar 10 12:23:07 kltrbatch01 kernel: RPC: 8966 reserved req ffff880433af5400 xid 08f170cb
Mar 10 12:23:07 kltrbatch01 kernel: RPC: wake_up_next(ffff88043188c190 "xprt_sending")
Mar 10 12:23:07 kltrbatch01 kernel: RPC: 8966 call_reserveresult (status 0)
Mar 10 12:23:07 kltrbatch01 kernel: RPC: 8966 call_refresh (status 0)
Mar 10 12:23:07 kltrbatch01 kernel: RPC: 8966 looking up UNIX cred
Mar 10 12:23:07 kltrbatch01 kernel: RPC: looking up UNIX cred
Mar 10 12:23:07 kltrbatch01 kernel: RPC: 8966 refreshing UNIX cred ffff880431162500
Mar 10 12:23:07 kltrbatch01 kernel: RPC: 8966 call_refreshresult (status 0)
Mar 10 12:23:07 kltrbatch01 kernel: RPC: 8966 call_allocate (status 0)
Mar 10 12:23:07 kltrbatch01 kernel: RPC: 8966 allocated buffer of size 552 at ffff880431e0f800
Mar 10 12:23:07 kltrbatch01 kernel: RPC: 8966 call_bind (status 0)
Mar 10 12:23:07 kltrbatch01 kernel: RPC: 8966 call_connect xprt ffff88043188c000 is connected
Mar 10 12:23:07 kltrbatch01 kernel: RPC: 8966 call_transmit (status 0)
Mar 10 12:23:07 kltrbatch01 kernel: RPC: 8966 xprt_prepare_transmit
Mar 10 12:23:07 kltrbatch01 kernel: RPC: 8966 rpc_xdr_encode (status 0)
Mar 10 12:23:07 kltrbatch01 kernel: RPC: 8966 marshaling UNIX cred ffff880431162500
Mar 10 12:23:07 kltrbatch01 kernel: RPC: 8966 using AUTH_UNIX cred ffff880431162500 to wrap rpc data
Mar 10 12:23:07 kltrbatch01 kernel: RPC: 8966 xprt_transmit(108)
Mar 10 12:23:07 kltrbatch01 kernel: RPC: xs_tcp_send_request(108) = 108
Mar 10 12:23:07 kltrbatch01 kernel: RPC: 8966 xmit complete
Mar 10 12:23:07 kltrbatch01 kernel: RPC: 8966 sleep_on(queue "xprt_pending" time 4296743024)
Mar 10 12:23:07 kltrbatch01 kernel: RPC: 8966 added to queue ffff88043188c258 "xprt_pending"
Mar 10 12:23:07 kltrbatch01 kernel: RPC: 8966 setting alarm for 60000 ms
Mar 10 12:23:07 kltrbatch01 kernel: RPC: wake_up_next(ffff88043188c190 "xprt_sending")
Mar 10 12:23:07 kltrbatch01 kernel: RPC: 8966 sync task going to sleep
Mar 10 12:23:07 kltrbatch01 kernel: RPC: xs_tcp_data_ready...
Mar 10 12:23:07 kltrbatch01 kernel: RPC: xs_tcp_data_recv started
Mar 10 12:23:07 kltrbatch01 kernel: RPC: reading TCP record fragment of length 112
Mar 10 12:23:07 kltrbatch01 kernel: RPC: reading XID (4 bytes)
Mar 10 12:23:07 kltrbatch01 kernel: RPC: reading reply for XID 08f170cb
Mar 10 12:23:07 kltrbatch01 kernel: RPC: reading CALL/REPLY flag (4 bytes)
Mar 10 12:23:07 kltrbatch01 kernel: RPC: read reply XID 08f170cb
Mar 10 12:23:07 kltrbatch01 kernel: RPC: XID 08f170cb read 104 bytes
Mar 10 12:23:07 kltrbatch01 kernel: RPC: xprt = ffff88043188c000, tcp_copied = 112, tcp_offset = 112, tcp_reclen = 112
Mar 10 12:23:07 kltrbatch01 kernel: RPC: 8966 xid 08f170cb complete (112 bytes received)
Mar 10 12:23:07 kltrbatch01 kernel: RPC: 8966 __rpc_wake_up_task (now 4296743024)
Mar 10 12:23:07 kltrbatch01 kernel: RPC: 8966 disabling timer
Mar 10 12:23:07 kltrbatch01 kernel: RPC: 8966 removed from queue ffff88043188c258 "xprt_pending"
Mar 10 12:23:07 kltrbatch01 kernel: RPC: __rpc_wake_up_task done
Mar 10 12:23:07 kltrbatch01 kernel: RPC: xs_tcp_data_recv done
Mar 10 12:23:07 kltrbatch01 kernel: RPC: 8966 sync task resuming
Mar 10 12:23:07 kltrbatch01 kernel: RPC: 8966 call_status (status 112)
Mar 10 12:23:07 kltrbatch01 kernel: RPC: 8966 call_decode (status 112)
Mar 10 12:23:07 kltrbatch01 kernel: RPC: 8966 validating UNIX cred ffff880431162500
Mar 10 12:23:07 kltrbatch01 kernel: RPC: 8966 using AUTH_UNIX cred ffff880431162500 to unwrap rpc data
Mar 10 12:23:07 kltrbatch01 kernel: RPC: 8966 call_decode result 0
Mar 10 12:23:07 kltrbatch01 kernel: RPC: 8966 return 0, status 0
Mar 10 12:23:07 kltrbatch01 kernel: RPC: 8966 release task
Mar 10 12:23:07 kltrbatch01 kernel: RPC: freeing buffer of size 552 at ffff880431e0f800
Mar 10 12:23:07 kltrbatch01 kernel: RPC: 8966 release request ffff880433af5400
Mar 10 12:23:07 kltrbatch01 kernel: RPC: wake_up_next(ffff88043188c320 "xprt_backlog")
Mar 10 12:23:07 kltrbatch01 kernel: RPC: rpc_release_client(ffff88042d835e00)
Mar 10 12:23:07 kltrbatch01 kernel: RPC: 8966 freeing task
Mar 10 12:23:07 kltrbatch01 kernel: NFS reply getattr: 0
Mar 10 12:23:07 kltrbatch01 kernel: NFS: nfs_update_inode(0:13/155099998840 ct=1 info=0x7e7f)
Mar 10 12:23:07 kltrbatch01 kernel: NFS: (0:13/155099998840) revalidation complete
Mar 10 12:23:07 kltrbatch01 kernel: NFS: nfs_lookup_revalidate(omtest/test.mxf) is valid
Mar 10 12:23:07 kltrbatch01 kernel: RPC: looking up Generic cred
Mar 10 12:23:07 kltrbatch01 kernel: NFS call access
Mar 10 12:23:07 kltrbatch01 kernel: RPC: new task initialized, procpid 2508
Mar 10 12:23:07 kltrbatch01 kernel: RPC: allocated task ffff880433178080
Mar 10 12:23:07 kltrbatch01 kernel: RPC: 8967 __rpc_execute flags=0x80
Mar 10 12:23:07 kltrbatch01 kernel: RPC: 8967 call_start nfs3 proc ACCESS (sync)
Mar 10 12:23:07 kltrbatch01 kernel: RPC: 8967 call_reserve (status 0)
Mar 10 12:23:07 kltrbatch01 kernel: RPC: 8967 reserved req ffff880433af5400 xid 09f170cb
Mar 10 12:23:07 kltrbatch01 kernel: RPC: wake_up_next(ffff88043188c190 "xprt_sending")
Mar 10 12:23:07 kltrbatch01 kernel: RPC: 8967 call_reserveresult (status 0)
Mar 10 12:23:07 kltrbatch01 kernel: RPC: 8967 call_refresh (status 0)
Mar 10 12:23:07 kltrbatch01 kernel: RPC: 8967 refreshing UNIX cred ffff880431162500
Mar 10 12:23:07 kltrbatch01 kernel: RPC: 8967 call_refreshresult (status 0)
Mar 10 12:23:07 kltrbatch01 kernel: RPC: 8967 call_allocate (status 0)
Mar 10 12:23:07 kltrbatch01 kernel: RPC: 8967 allocated buffer of size 564 at ffff880431e0f800
Mar 10 12:23:07 kltrbatch01 kernel: RPC: 8967 call_bind (status 0)
Mar 10 12:23:07 kltrbatch01 kernel: RPC: 8967 call_connect xprt ffff88043188c000 is connected
Mar 10 12:23:07 kltrbatch01 kernel: RPC: 8967 call_transmit (status 0)
Mar 10 12:23:07 kltrbatch01 kernel: RPC: 8967 xprt_prepare_transmit
Mar 10 12:23:07 kltrbatch01 kernel: RPC: 8967 rpc_xdr_encode (status 0)
Mar 10 12:23:07 kltrbatch01 kernel: RPC: 8967 marshaling UNIX cred ffff880431162500
Mar 10 12:23:07 kltrbatch01 kernel: RPC: 8967 using AUTH_UNIX cred ffff880431162500 to wrap rpc data
Mar 10 12:23:07 kltrbatch01 kernel: RPC: 8967 xprt_transmit(112)
Mar 10 12:23:07 kltrbatch01 kernel: RPC: xs_tcp_send_request(112) = 112
Mar 10 12:23:07 kltrbatch01 kernel: RPC: 8967 xmit complete
Mar 10 12:23:07 kltrbatch01 kernel: RPC: 8967 sleep_on(queue "xprt_pending" time 4296743024)
Mar 10 12:23:07 kltrbatch01 kernel: RPC: 8967 added to queue ffff88043188c258 "xprt_pending"
Mar 10 12:23:07 kltrbatch01 kernel: RPC: 8967 setting alarm for 60000 ms
Mar 10 12:23:07 kltrbatch01 kernel: RPC: wake_up_next(ffff88043188c190 "xprt_sending")
Mar 10 12:23:07 kltrbatch01 kernel: RPC: 8967 sync task going to sleep
Mar 10 12:23:07 kltrbatch01 kernel: RPC: xs_tcp_data_ready...
Mar 10 12:23:07 kltrbatch01 kernel: RPC: xs_tcp_data_recv started
Mar 10 12:23:07 kltrbatch01 kernel: RPC: reading TCP record fragment of length 120
Mar 10 12:23:07 kltrbatch01 kernel: RPC: reading XID (4 bytes)
Mar 10 12:23:07 kltrbatch01 kernel: RPC: reading reply for XID 09f170cb
Mar 10 12:23:07 kltrbatch01 kernel: RPC: reading CALL/REPLY flag (4 bytes)
Mar 10 12:23:07 kltrbatch01 kernel: RPC: read reply XID 09f170cb
Mar 10 12:23:07 kltrbatch01 kernel: RPC: XID 09f170cb read 112 bytes
Mar 10 12:23:07 kltrbatch01 kernel: RPC: xprt = ffff88043188c000, tcp_copied = 120, tcp_offset = 120, tcp_reclen = 120
Mar 10 12:23:07 kltrbatch01 kernel: RPC: 8967 xid 09f170cb complete (120 bytes received)
Mar 10 12:23:07 kltrbatch01 kernel: RPC: 8967 __rpc_wake_up_task (now 4296743025)
Mar 10 12:23:07 kltrbatch01 kernel: RPC: 8967 disabling timer
Mar 10 12:23:07 kltrbatch01 kernel: RPC: 8967 removed from queue ffff88043188c258 "xprt_pending"
Mar 10 12:23:07 kltrbatch01 kernel: RPC: __rpc_wake_up_task done
Mar 10 12:23:07 kltrbatch01 kernel: RPC: xs_tcp_data_recv done
Mar 10 12:23:07 kltrbatch01 kernel: RPC: 8967 sync task resuming
Mar 10 12:23:07 kltrbatch01 kernel: RPC: 8967 call_status (status 120)
Mar 10 12:23:07 kltrbatch01 kernel: RPC: 8967 call_decode (status 120)
Mar 10 12:23:07 kltrbatch01 kernel: RPC: 8967 validating UNIX cred ffff880431162500
Mar 10 12:23:07 kltrbatch01 kernel: RPC: 8967 using AUTH_UNIX cred ffff880431162500 to unwrap rpc data
Mar 10 12:23:07 kltrbatch01 kernel: RPC: 8967 call_decode result 0
Mar 10 12:23:07 kltrbatch01 kernel: RPC: 8967 return 0, status 0
Mar 10 12:23:07 kltrbatch01 kernel: RPC: 8967 release task
Mar 10 12:23:07 kltrbatch01 kernel: RPC: freeing buffer of size 564 at ffff880431e0f800
Mar 10 12:23:07 kltrbatch01 kernel: RPC: 8967 release request ffff880433af5400
Mar 10 12:23:07 kltrbatch01 kernel: RPC: wake_up_next(ffff88043188c320 "xprt_backlog")
Mar 10 12:23:07 kltrbatch01 kernel: RPC: rpc_release_client(ffff88042d835e00)
Mar 10 12:23:07 kltrbatch01 kernel: RPC: 8967 freeing task
Mar 10 12:23:07 kltrbatch01 kernel: NFS: nfs_update_inode(0:13/155099998840 ct=1 info=0x7e7f)
Mar 10 12:23:07 kltrbatch01 kernel: NFS reply access: 0
Mar 10 12:23:07 kltrbatch01 kernel: NFS: permission(0:13/155099998840), mask=0x24, res=0
Mar 10 12:23:07 kltrbatch01 kernel: NFS: open file(omtest/test.mxf)
Mar 10 12:23:07 kltrbatch01 kernel: RPC: looking up Generic cred
Mar 10 12:23:07 kltrbatch01 kernel: NFS: llseek file(omtest/test.mxf, 0, 1)
Mar 10 12:23:07 kltrbatch01 kernel: NFS: flush(omtest/test.mxf)
Mar 10 12:23:07 kltrbatch01 kernel: NFS: release(omtest/test.mxf)
Mar 10 12:23:07 kltrbatch01 kernel: NFS: dentry_delete(omtest/test.mxf, 8)