On Sep 7, 2007, at 7:17 AM, Herbert Poetzl wrote:
> On Fri, Sep 07, 2007 at 08:20:21AM +0200, Daniel Hokka Zakrisson
> wrote:
>
>> Herbert Poetzl wrote:
>>
>>> yeah, please provide the following debug info:
>>>
>>> - complete rpc and nfs(d) debug output for all
>>> cases, i.e. root/user on host/guest
>>> - Linux-VServer debug dmesg output
>>>
>>> we know that the subtree checks (depending on
>>> the nfs version) cause some issues, and I think
>>> we can fix them with sufficient data ...
>>>
>>
>> Didn't we come to the conclusion that this problem was due to the
>> extra vx_capable in vfs_kern_mount when this was discussed on IRC,
>> which ought to be just vx_ccaps?
>>
>
> should be easy to test, in this case 2.3.0.19
> should not have this issue at all, no?
>
> but I would guess some problems with subtree
> mounts ove NFS will still remain ...
>
> anyway, maybe Dallas can test that too?
>
This .snapshot 'operation not permitted' happens on the host as well
as the guest so I have done some testing on a host with nothing else
running on it and no guests set up. I enabled debugging in the
VServer kernel but didn't see any applicable messages in dmesg. Is
there something else I should do with that?
I was unable to locate a 2.3.0.19 patch, but I did try the latest
2.3.0.18 on a 2.6.22.6 kernel with no other patches and saw the same
behavior as with the older kernel (2.6.19.7) and vserver patch
(patch-2.6.19.7-vs2.2.0-grsec2.1.10-20070402.diff) we're using in
production.
Here are my test cases with associated NFS client and RPC debug output.
1. Non-root user attempting to "cd /mnt/vservers/.snapshot".
Resulted in "Operation not permitted"
NFS: revalidating (0:10/6908959)
NFS call getattr
RPC: new task initialized, procpid 4360
RPC: allocated task f7f8cd40
RPC: 0 looking up UNIX cred
RPC: gc'ing RPC credentials for auth c0722b80
RPC: 22 __rpc_execute flags=0x80
RPC: 22 call_start nfs3 proc 1 (sync)
RPC: 22 call_reserve (status 0)
RPC: 22 reserved req f7e84000 xid 5200ee57
RPC: 22 call_reserveresult (status 0)
RPC: 22 call_allocate (status 0)
RPC: 22 allocated buffer of size 548 at f6d1a800
RPC: 22 call_bind (status 0)
RPC: 22 call_connect xprt f7ea0800 is connected
RPC: 22 call_transmit (status 0)
RPC: 22 xprt_prepare_transmit
RPC: 22 call_encode (status 0)
RPC: 22 marshaling UNIX cred f7f7a840
RPC: 22 using AUTH_UNIX cred f7f7a840 to wrap rpc data
RPC: 22 xprt_transmit(124)
RPC: xs_tcp_send_request(124) = 124
RPC: xs_tcp_data_ready...
RPC: xs_tcp_data_recv started
RPC: reading TCP record fragment of length 112
RPC: reading XID (4 bytes)
RPC: reading reply for XID 5200ee57
RPC: XID 5200ee57 read 108 bytes
RPC: xprt = f7ea0800, tcp_copied = 112, tcp_offset = 112,
tcp_reclen = 112
RPC: 22 xid 5200ee57 complete (112 bytes received)
RPC: xs_tcp_data_recv done
RPC: 22 xmit complete
RPC: wake_up_next(f7ea090c "xprt_resend")
RPC: wake_up_next(f7ea08e0 "xprt_sending")
RPC: 22 call_status (status 112)
RPC: 22 call_decode (status 112)
RPC: 22 validating UNIX cred f7f7a840
RPC: 22 using AUTH_UNIX cred f7f7a840 to unwrap rpc data
RPC: 22 call_decode result 0
RPC: 22 return 0, status 0
RPC: 22 release task
RPC: freeing buffer of size 548 at f6d1a800
RPC: 22 release request f7e84000
RPC: wake_up_next(f7ea0964 "xprt_backlog")
RPC: 22 releasing UNIX cred f7f7a840
RPC: rpc_release_client(f79dfec0, 1)
NFS reply getattr: 0
NFS: nfs_update_inode(0:10/6908959 ct=1 info=0x6)
NFS: (0:10/6908959) revalidation complete
RPC: 22 freeing task
RPC: looking up UNIX cred
NFS call access
RPC: new task initialized, procpid 4360
RPC: allocated task f7f8cd40
RPC: 0 holding UNIX cred f7f7a840
RPC: 23 __rpc_execute flags=0x80
RPC: 23 call_start nfs3 proc 4 (sync)
RPC: 23 call_reserve (status 0)
RPC: 23 reserved req f7e84000 xid 5300ee57
RPC: 23 call_reserveresult (status 0)
RPC: 23 call_allocate (status 0)
RPC: 23 allocated buffer of size 560 at f6d1a800
RPC: 23 call_bind (status 0)
RPC: 23 call_connect xprt f7ea0800 is connected
RPC: 23 call_transmit (status 0)
RPC: 23 xprt_prepare_transmit
RPC: 23 call_encode (status 0)
RPC: 23 marshaling UNIX cred f7f7a840
RPC: 23 using AUTH_UNIX cred f7f7a840 to wrap rpc data
RPC: 23 xprt_transmit(128)
RPC: xs_tcp_send_request(128) = 128
RPC: xs_tcp_data_ready...
RPC: xs_tcp_data_recv started
RPC: reading TCP record fragment of length 120
RPC: reading XID (4 bytes)
RPC: reading reply for XID 5300ee57
RPC: XID 5300ee57 read 116 bytes
RPC: xprt = f7ea0800, tcp_copied = 120, tcp_offset = 120,
tcp_reclen = 120
RPC: 23 xid 5300ee57 complete (120 bytes received)
RPC: xs_tcp_data_recv done
RPC: 23 xmit complete
RPC: wake_up_next(f7ea090c "xprt_resend")
RPC: wake_up_next(f7ea08e0 "xprt_sending")
RPC: 23 call_status (status 120)
RPC: 23 call_decode (status 120)
RPC: 23 validating UNIX cred f7f7a840
RPC: 23 using AUTH_UNIX cred f7f7a840 to unwrap rpc data
RPC: 23 call_decode result 0
RPC: 23 return 0, status 0
RPC: 23 release task
RPC: freeing buffer of size 560 at f6d1a800
RPC: 23 release request f7e84000
RPC: wake_up_next(f7ea0964 "xprt_backlog")
RPC: 23 releasing UNIX cred f7f7a840
RPC: rpc_release_client(f79dfec0, 1)
NFS: nfs_update_inode(0:10/6908959 ct=1 info=0x6)
NFS reply access: 0
NFS: permission(0:10/6908959), mask=0x1, res=0
NFS: revalidating (0:10/67)
NFS call getattr
RPC: 23 freeing task
RPC: new task initialized, procpid 4360
RPC: allocated task f7f8cd40
RPC: 0 looking up UNIX cred
RPC: 24 __rpc_execute flags=0x80
RPC: 24 call_start nfs3 proc 1 (sync)
RPC: 24 call_reserve (status 0)
RPC: 24 reserved req f7e84000 xid 5400ee57
RPC: 24 call_reserveresult (status 0)
RPC: 24 call_allocate (status 0)
RPC: 24 allocated buffer of size 548 at f6d1a800
RPC: 24 call_bind (status 0)
RPC: 24 call_connect xprt f7ea0800 is connected
RPC: 24 call_transmit (status 0)
RPC: 24 xprt_prepare_transmit
RPC: 24 call_encode (status 0)
RPC: 24 marshaling UNIX cred f7f7a840
RPC: 24 using AUTH_UNIX cred f7f7a840 to wrap rpc data
RPC: 24 xprt_transmit(124)
RPC: xs_tcp_send_request(124) = 124
RPC: xs_tcp_data_ready...
RPC: xs_tcp_data_recv started
RPC: reading TCP record fragment of length 112
RPC: reading XID (4 bytes)
RPC: reading reply for XID 5400ee57
RPC: XID 5400ee57 read 108 bytes
RPC: xprt = f7ea0800, tcp_copied = 112, tcp_offset = 112,
tcp_reclen = 112
RPC: 24 xid 5400ee57 complete (112 bytes received)
RPC: xs_tcp_data_recv done
RPC: 24 xmit complete
RPC: wake_up_next(f7ea090c "xprt_resend")
RPC: wake_up_next(f7ea08e0 "xprt_sending")
RPC: 24 call_status (status 112)
RPC: 24 call_decode (status 112)
RPC: 24 validating UNIX cred f7f7a840
RPC: 24 using AUTH_UNIX cred f7f7a840 to unwrap rpc data
RPC: 24 call_decode result 0
RPC: 24 return 0, status 0
RPC: 24 release task
RPC: freeing buffer of size 548 at f6d1a800
RPC: 24 release request f7e84000
RPC: wake_up_next(f7ea0964 "xprt_backlog")
RPC: 24 releasing UNIX cred f7f7a840
RPC: rpc_release_client(f79dfec0, 1)
NFS reply getattr: 0
NFS: nfs_update_inode(0:10/67 ct=1 info=0x6)
NFS: (0:10/67) revalidation complete
NFS: nfs_lookup_revalidate(/.snapshot) is valid
RPC: 24 freeing task
--> nfs_follow_mountpoint()
nfs_follow_mountpoint: enter
NFS call lookup .snapshot
RPC: new task initialized, procpid 4360
RPC: allocated task f7f8cd40
RPC: 0 looking up UNIX cred
RPC: 25 __rpc_execute flags=0x80
RPC: 25 call_start nfs3 proc 3 (sync)
RPC: 25 call_reserve (status 0)
RPC: 25 reserved req f7e84000 xid 5500ee57
RPC: 25 call_reserveresult (status 0)
RPC: 25 call_allocate (status 0)
RPC: 25 allocated buffer of size 964 at f6d1a800
RPC: 25 call_bind (status 0)
RPC: 25 call_connect xprt f7ea0800 is connected
RPC: 25 call_transmit (status 0)
RPC: 25 xprt_prepare_transmit
RPC: 25 call_encode (status 0)
RPC: 25 marshaling UNIX cred f7f7a840
RPC: 25 using AUTH_UNIX cred f7f7a840 to wrap rpc data
RPC: 25 xprt_transmit(140)
RPC: xs_tcp_send_request(140) = 140
RPC: xs_tcp_data_ready...
RPC: xs_tcp_data_recv started
RPC: reading TCP record fragment of length 240
RPC: reading XID (4 bytes)
RPC: reading reply for XID 5500ee57
RPC: XID 5500ee57 read 236 bytes
RPC: xprt = f7ea0800, tcp_copied = 240, tcp_offset = 240,
tcp_reclen = 240
RPC: 25 xid 5500ee57 complete (240 bytes received)
RPC: xs_tcp_data_recv done
RPC: 25 xmit complete
RPC: wake_up_next(f7ea090c "xprt_resend")
RPC: wake_up_next(f7ea08e0 "xprt_sending")
RPC: 25 call_status (status 240)
RPC: 25 call_decode (status 240)
RPC: 25 validating UNIX cred f7f7a840
RPC: 25 using AUTH_UNIX cred f7f7a840 to unwrap rpc data
RPC: 25 call_decode result 0
RPC: 25 return 0, status 0
RPC: 25 release task
RPC: freeing buffer of size 964 at f6d1a800
RPC: 25 release request f7e84000
RPC: wake_up_next(f7ea0964 "xprt_backlog")
RPC: 25 releasing UNIX cred f7f7a840
RPC: rpc_release_client(f79dfec0, 1)
NFS reply lookup: 0
NFS: nfs_update_inode(0:10/6908959 ct=1 info=0x6)
--> nfs_do_submount()
nfs_do_submount: submounting on /.snapshot
RPC: 25 freeing task
nfs_do_submount: done
<-- nfs_do_submount() = ffffffff
nfs_follow_mountpoint: done, returned -1
<-- nfs_follow_mountpoint() = -1
NFS: dentry_delete(/.snapshot, 8)
RPC: looking up UNIX cred
NFS: permission(0:10/6908959), mask=0x1, res=0
NFS: nfs_lookup_revalidate(/.snapshot) is valid
--> nfs_follow_mountpoint()
nfs_follow_mountpoint: enter
NFS call lookup .snapshot
RPC: new task initialized, procpid 4360
RPC: allocated task f7f8cd40
RPC: 0 looking up UNIX cred
RPC: 26 __rpc_execute flags=0x80
RPC: 26 call_start nfs3 proc 3 (sync)
RPC: 26 call_reserve (status 0)
RPC: 26 reserved req f7e84000 xid 5600ee57
RPC: 26 call_reserveresult (status 0)
RPC: 26 call_allocate (status 0)
RPC: 26 allocated buffer of size 964 at f6d1a800
RPC: 26 call_bind (status 0)
RPC: 26 call_connect xprt f7ea0800 is connected
RPC: 26 call_transmit (status 0)
RPC: 26 xprt_prepare_transmit
RPC: 26 call_encode (status 0)
RPC: 26 marshaling UNIX cred f7f7a840
RPC: 26 using AUTH_UNIX cred f7f7a840 to wrap rpc data
RPC: 26 xprt_transmit(140)
RPC: xs_tcp_send_request(140) = 140
RPC: xs_tcp_data_ready...
RPC: xs_tcp_data_recv started
RPC: reading TCP record fragment of length 240
RPC: reading XID (4 bytes)
RPC: reading reply for XID 5600ee57
RPC: XID 5600ee57 read 236 bytes
RPC: xprt = f7ea0800, tcp_copied = 240, tcp_offset = 240,
tcp_reclen = 240
RPC: 26 xid 5600ee57 complete (240 bytes received)
RPC: xs_tcp_data_recv done
RPC: 26 xmit complete
RPC: wake_up_next(f7ea090c "xprt_resend")
RPC: wake_up_next(f7ea08e0 "xprt_sending")
RPC: 26 call_status (status 240)
RPC: 26 call_decode (status 240)
RPC: 26 validating UNIX cred f7f7a840
RPC: 26 using AUTH_UNIX cred f7f7a840 to unwrap rpc data
RPC: 26 call_decode result 0
RPC: 26 return 0, status 0
RPC: 26 release task
RPC: freeing buffer of size 964 at f6d1a800
RPC: 26 release request f7e84000
RPC: wake_up_next(f7ea0964 "xprt_backlog")
RPC: 26 releasing UNIX cred f7f7a840
RPC: rpc_release_client(f79dfec0, 1)
NFS reply lookup: 0
NFS: nfs_update_inode(0:10/6908959 ct=1 info=0x6)
--> nfs_do_submount()
nfs_do_submount: submounting on /.snapshot
RPC: 26 freeing task
nfs_do_submount: done
<-- nfs_do_submount() = ffffffff
nfs_follow_mountpoint: done, returned -1
<-- nfs_follow_mountpoint() = -1
NFS: dentry_delete(/.snapshot, 8)
RPC: looking up UNIX cred
NFS: permission(0:10/6908959), mask=0x1, res=0
NFS: nfs_lookup_revalidate(/.snapshot) is valid
--> nfs_follow_mountpoint()
nfs_follow_mountpoint: enter
NFS call lookup .snapshot
RPC: new task initialized, procpid 4360
RPC: allocated task f7f8cd40
RPC: 0 looking up UNIX cred
RPC: 27 __rpc_execute flags=0x80
RPC: 27 call_start nfs3 proc 3 (sync)
RPC: 27 call_reserve (status 0)
RPC: 27 reserved req f7e84000 xid 5700ee57
RPC: 27 call_reserveresult (status 0)
RPC: 27 call_allocate (status 0)
RPC: 27 allocated buffer of size 964 at f6d1a800
RPC: 27 call_bind (status 0)
RPC: 27 call_connect xprt f7ea0800 is connected
RPC: 27 call_transmit (status 0)
RPC: 27 xprt_prepare_transmit
RPC: 27 call_encode (status 0)
RPC: 27 marshaling UNIX cred f7f7a840
RPC: 27 using AUTH_UNIX cred f7f7a840 to wrap rpc data
RPC: 27 xprt_transmit(140)
RPC: xs_tcp_send_request(140) = 140
RPC: xs_tcp_data_ready...
RPC: xs_tcp_data_recv started
RPC: reading TCP record fragment of length 240
RPC: reading XID (4 bytes)
RPC: reading reply for XID 5700ee57
RPC: XID 5700ee57 read 236 bytes
RPC: xprt = f7ea0800, tcp_copied = 240, tcp_offset = 240,
tcp_reclen = 240
RPC: 27 xid 5700ee57 complete (240 bytes received)
RPC: xs_tcp_data_recv done
RPC: 27 xmit complete
RPC: wake_up_next(f7ea090c "xprt_resend")
RPC: wake_up_next(f7ea08e0 "xprt_sending")
RPC: 27 call_status (status 240)
RPC: 27 call_decode (status 240)
RPC: 27 validating UNIX cred f7f7a840
RPC: 27 using AUTH_UNIX cred f7f7a840 to unwrap rpc data
RPC: 27 call_decode result 0
RPC: 27 return 0, status 0
RPC: 27 release task
RPC: freeing buffer of size 964 at f6d1a800
RPC: 27 release request f7e84000
RPC: wake_up_next(f7ea0964 "xprt_backlog")
RPC: 27 releasing UNIX cred f7f7a840
RPC: rpc_release_client(f79dfec0, 1)
NFS reply lookup: 0
NFS: nfs_update_inode(0:10/6908959 ct=1 info=0x6)
--> nfs_do_submount()
nfs_do_submount: submounting on /.snapshot
RPC: 27 freeing task
nfs_do_submount: done
<-- nfs_do_submount() = ffffffff
nfs_follow_mountpoint: done, returned -1
<-- nfs_follow_mountpoint() = -1
NFS: dentry_delete(/.snapshot, 8)
2. Root user attempting to "cd /mnt/vservers/.snapshot". Succeeded.
NFS: revalidating (0:10/6908959)
NFS call getattr
RPC: new task initialized, procpid 3524
RPC: allocated task f7f8c2c0
RPC: 0 looking up UNIX cred
RPC: gc'ing RPC credentials for auth c0722b80
RPC: allocating UNIX cred for uid 0 gid 0
RPC: 28 __rpc_execute flags=0x80
RPC: 28 call_start nfs3 proc 1 (sync)
RPC: 28 call_reserve (status 0)
RPC: 28 reserved req f7e84000 xid 5800ee57
RPC: 28 call_reserveresult (status 0)
RPC: 28 call_allocate (status 0)
RPC: 28 allocated buffer of size 548 at f6ccb800
RPC: 28 call_bind (status 0)
RPC: 28 call_connect xprt f7ea0800 is connected
RPC: 28 call_transmit (status 0)
RPC: 28 xprt_prepare_transmit
RPC: 28 call_encode (status 0)
RPC: 28 marshaling UNIX cred f746e440
RPC: 28 using AUTH_UNIX cred f746e440 to wrap rpc data
RPC: 28 xprt_transmit(120)
RPC: xs_tcp_send_request(120) = 120
RPC: xs_tcp_data_ready...
RPC: xs_tcp_data_recv started
RPC: reading TCP record fragment of length 112
RPC: reading XID (4 bytes)
RPC: reading reply for XID 5800ee57
RPC: XID 5800ee57 read 108 bytes
RPC: xprt = f7ea0800, tcp_copied = 112, tcp_offset = 112,
tcp_reclen = 112
RPC: 28 xid 5800ee57 complete (112 bytes received)
RPC: xs_tcp_data_recv done
RPC: 28 xmit complete
RPC: wake_up_next(f7ea090c "xprt_resend")
RPC: wake_up_next(f7ea08e0 "xprt_sending")
RPC: 28 call_status (status 112)
RPC: 28 call_decode (status 112)
RPC: 28 validating UNIX cred f746e440
RPC: 28 using AUTH_UNIX cred f746e440 to unwrap rpc data
RPC: 28 call_decode result 0
RPC: 28 return 0, status 0
RPC: 28 release task
RPC: freeing buffer of size 548 at f6ccb800
RPC: 28 release request f7e84000
RPC: wake_up_next(f7ea0964 "xprt_backlog")
RPC: 28 releasing UNIX cred f746e440
RPC: rpc_release_client(f79dfec0, 1)
NFS reply getattr: 0
NFS: nfs_update_inode(0:10/6908959 ct=1 info=0x6)
NFS: (0:10/6908959) revalidation complete
RPC: 28 freeing task
RPC: looking up UNIX cred
NFS call access
RPC: new task initialized, procpid 3524
RPC: allocated task f7f8c2c0
RPC: 0 holding UNIX cred f746e440
RPC: 29 __rpc_execute flags=0x80
RPC: 29 call_start nfs3 proc 4 (sync)
RPC: 29 call_reserve (status 0)
RPC: 29 reserved req f7e84000 xid 5900ee57
RPC: 29 call_reserveresult (status 0)
RPC: 29 call_allocate (status 0)
RPC: 29 allocated buffer of size 560 at f6ccb800
RPC: 29 call_bind (status 0)
RPC: 29 call_connect xprt f7ea0800 is connected
RPC: 29 call_transmit (status 0)
RPC: 29 xprt_prepare_transmit
RPC: 29 call_encode (status 0)
RPC: 29 marshaling UNIX cred f746e440
RPC: 29 using AUTH_UNIX cred f746e440 to wrap rpc data
RPC: 29 xprt_transmit(124)
RPC: xs_tcp_send_request(124) = 124
RPC: xs_tcp_data_ready...
RPC: xs_tcp_data_recv started
RPC: reading TCP record fragment of length 120
RPC: reading XID (4 bytes)
RPC: reading reply for XID 5900ee57
RPC: XID 5900ee57 read 116 bytes
RPC: xprt = f7ea0800, tcp_copied = 120, tcp_offset = 120,
tcp_reclen = 120
RPC: 29 xid 5900ee57 complete (120 bytes received)
RPC: xs_tcp_data_recv done
RPC: 29 xmit complete
RPC: wake_up_next(f7ea090c "xprt_resend")
RPC: wake_up_next(f7ea08e0 "xprt_sending")
RPC: 29 call_status (status 120)
RPC: 29 call_decode (status 120)
RPC: 29 validating UNIX cred f746e440
RPC: 29 using AUTH_UNIX cred f746e440 to unwrap rpc data
RPC: 29 call_decode result 0
RPC: 29 return 0, status 0
RPC: 29 release task
RPC: freeing buffer of size 560 at f6ccb800
RPC: 29 release request f7e84000
RPC: wake_up_next(f7ea0964 "xprt_backlog")
RPC: 29 releasing UNIX cred f746e440
RPC: rpc_release_client(f79dfec0, 1)
NFS: nfs_update_inode(0:10/6908959 ct=1 info=0x6)
NFS reply access: 0
NFS: permission(0:10/6908959), mask=0x1, res=0
RPC: 29 freeing task
NFS: revalidating (0:10/67)
NFS call getattr
RPC: new task initialized, procpid 3524
RPC: allocated task f7f8c2c0
RPC: 0 looking up UNIX cred
RPC: 30 __rpc_execute flags=0x80
RPC: 30 call_start nfs3 proc 1 (sync)
RPC: 30 call_reserve (status 0)
RPC: 30 reserved req f7e84000 xid 5a00ee57
RPC: 30 call_reserveresult (status 0)
RPC: 30 call_allocate (status 0)
RPC: 30 allocated buffer of size 548 at f6ccb800
RPC: 30 call_bind (status 0)
RPC: 30 call_connect xprt f7ea0800 is connected
RPC: 30 call_transmit (status 0)
RPC: 30 xprt_prepare_transmit
RPC: 30 call_encode (status 0)
RPC: 30 marshaling UNIX cred f746e440
RPC: 30 using AUTH_UNIX cred f746e440 to wrap rpc data
RPC: 30 xprt_transmit(120)
RPC: xs_tcp_send_request(120) = 120
RPC: xs_tcp_data_ready...
RPC: xs_tcp_data_recv started
RPC: reading TCP record fragment of length 112
RPC: reading XID (4 bytes)
RPC: reading reply for XID 5a00ee57
RPC: XID 5a00ee57 read 108 bytes
RPC: xprt = f7ea0800, tcp_copied = 112, tcp_offset = 112,
tcp_reclen = 112
RPC: 30 xid 5a00ee57 complete (112 bytes received)
RPC: xs_tcp_data_recv done
RPC: 30 xmit complete
RPC: wake_up_next(f7ea090c "xprt_resend")
RPC: wake_up_next(f7ea08e0 "xprt_sending")
RPC: 30 call_status (status 112)
RPC: 30 call_decode (status 112)
RPC: 30 validating UNIX cred f746e440
RPC: 30 using AUTH_UNIX cred f746e440 to unwrap rpc data
RPC: 30 call_decode result 0
RPC: 30 return 0, status 0
RPC: 30 release task
RPC: freeing buffer of size 548 at f6ccb800
RPC: 30 release request f7e84000
RPC: wake_up_next(f7ea0964 "xprt_backlog")
RPC: 30 releasing UNIX cred f746e440
RPC: rpc_release_client(f79dfec0, 1)
NFS reply getattr: 0
NFS: nfs_update_inode(0:10/67 ct=1 info=0x6)
NFS: (0:10/67) revalidation complete
NFS: nfs_lookup_revalidate(/.snapshot) is valid
RPC: 30 freeing task
--> nfs_follow_mountpoint()
nfs_follow_mountpoint: enter
NFS call lookup .snapshot
RPC: new task initialized, procpid 3524
RPC: allocated task f7f8c2c0
RPC: 0 looking up UNIX cred
RPC: 31 __rpc_execute flags=0x80
RPC: 31 call_start nfs3 proc 3 (sync)
RPC: 31 call_reserve (status 0)
RPC: 31 reserved req f7e84000 xid 5b00ee57
RPC: 31 call_reserveresult (status 0)
RPC: 31 call_allocate (status 0)
RPC: 31 allocated buffer of size 964 at f6ccb800
RPC: 31 call_bind (status 0)
RPC: 31 call_connect xprt f7ea0800 is connected
RPC: 31 call_transmit (status 0)
RPC: 31 xprt_prepare_transmit
RPC: 31 call_encode (status 0)
RPC: 31 marshaling UNIX cred f746e440
RPC: 31 using AUTH_UNIX cred f746e440 to wrap rpc data
RPC: 31 xprt_transmit(136)
RPC: xs_tcp_send_request(136) = 136
RPC: xs_tcp_data_ready...
RPC: xs_tcp_data_recv started
RPC: reading TCP record fragment of length 240
RPC: reading XID (4 bytes)
RPC: reading reply for XID 5b00ee57
RPC: XID 5b00ee57 read 236 bytes
RPC: xprt = f7ea0800, tcp_copied = 240, tcp_offset = 240,
tcp_reclen = 240
RPC: 31 xid 5b00ee57 complete (240 bytes received)
RPC: xs_tcp_data_recv done
RPC: 31 xmit complete
RPC: wake_up_next(f7ea090c "xprt_resend")
RPC: wake_up_next(f7ea08e0 "xprt_sending")
RPC: 31 call_status (status 240)
RPC: 31 call_decode (status 240)
RPC: 31 validating UNIX cred f746e440
RPC: 31 using AUTH_UNIX cred f746e440 to unwrap rpc data
RPC: 31 call_decode result 0
RPC: 31 return 0, status 0
RPC: 31 release task
RPC: freeing buffer of size 964 at f6ccb800
RPC: 31 release request f7e84000
RPC: wake_up_next(f7ea0964 "xprt_backlog")
RPC: 31 releasing UNIX cred f746e440
RPC: rpc_release_client(f79dfec0, 1)
NFS reply lookup: 0
NFS: nfs_update_inode(0:10/6908959 ct=1 info=0x6)
--> nfs_do_submount()
nfs_do_submount: submounting on /.snapshot
RPC: 31 freeing task
--> nfs_xdev_get_sb()
--> nfs_clone_server(,696c1f:0,)
--> nfs_probe_fsinfo()
NFS call fsinfo
RPC: new task initialized, procpid 3524
RPC: allocated task f7f8c2c0
RPC: 0 looking up UNIX cred
RPC: 32 __rpc_execute flags=0x680
RPC: 32 call_start nfs3 proc 19 (sync)
RPC: 32 call_reserve (status 0)
RPC: 32 reserved req f7e84000 xid 5c00ee57
RPC: 32 call_reserveresult (status 0)
RPC: 32 call_allocate (status 0)
RPC: 32 allocated buffer of size 600 at f6ccb800
RPC: 32 call_bind (status 0)
RPC: 32 call_connect xprt f7ea0800 is connected
RPC: 32 call_transmit (status 0)
RPC: 32 xprt_prepare_transmit
RPC: 32 call_encode (status 0)
RPC: 32 marshaling UNIX cred f746e440
RPC: 32 using AUTH_UNIX cred f746e440 to wrap rpc data
RPC: 32 xprt_transmit(120)
RPC: xs_tcp_send_request(120) = 120
RPC: xs_tcp_data_ready...
RPC: xs_tcp_data_recv started
RPC: reading TCP record fragment of length 164
RPC: reading XID (4 bytes)
RPC: reading reply for XID 5c00ee57
RPC: XID 5c00ee57 read 160 bytes
RPC: xprt = f7ea0800, tcp_copied = 164, tcp_offset = 164,
tcp_reclen = 164
RPC: 32 xid 5c00ee57 complete (164 bytes received)
RPC: xs_tcp_data_recv done
RPC: 32 xmit complete
RPC: wake_up_next(f7ea090c "xprt_resend")
RPC: wake_up_next(f7ea08e0 "xprt_sending")
RPC: 32 call_status (status 164)
RPC: 32 call_decode (status 164)
RPC: 32 validating UNIX cred f746e440
RPC: 32 using AUTH_UNIX cred f746e440 to unwrap rpc data
RPC: 32 call_decode result 0
RPC: 32 return 0, status 0
RPC: 32 release task
RPC: freeing buffer of size 600 at f6ccb800
RPC: 32 release request f7e84000
RPC: wake_up_next(f7ea0964 "xprt_backlog")
RPC: 32 releasing UNIX cred f746e440
RPC: rpc_release_client(f7b22280, 1)
NFS reply fsinfo: 0
NFS call pathconf
RPC: new task initialized, procpid 3524
RPC: allocated task f7f8c380
RPC: 32 freeing task
RPC: 0 looking up UNIX cred
RPC: 33 __rpc_execute flags=0x80
RPC: 33 call_start nfs3 proc 20 (sync)
RPC: 33 call_reserve (status 0)
RPC: 33 reserved req f7e84000 xid 5d00ee57
RPC: 33 call_reserveresult (status 0)
RPC: 33 call_allocate (status 0)
RPC: 33 allocated buffer of size 576 at f6ccb800
RPC: 33 call_bind (status 0)
RPC: 33 call_connect xprt f7ea0800 is connected
RPC: 33 call_transmit (status 0)
RPC: 33 xprt_prepare_transmit
RPC: 33 call_encode (status 0)
RPC: 33 marshaling UNIX cred f746e440
RPC: 33 using AUTH_UNIX cred f746e440 to wrap rpc data
RPC: 33 xprt_transmit(120)
RPC: xs_tcp_send_request(120) = 120
RPC: xs_tcp_data_ready...
RPC: xs_tcp_data_recv started
RPC: reading TCP record fragment of length 140
RPC: reading XID (4 bytes)
RPC: reading reply for XID 5d00ee57
RPC: XID 5d00ee57 read 136 bytes
RPC: xprt = f7ea0800, tcp_copied = 140, tcp_offset = 140,
tcp_reclen = 140
RPC: 33 xid 5d00ee57 complete (140 bytes received)
RPC: xs_tcp_data_recv done
RPC: 33 xmit complete
RPC: wake_up_next(f7ea090c "xprt_resend")
RPC: wake_up_next(f7ea08e0 "xprt_sending")
RPC: 33 call_status (status 140)
RPC: 33 call_decode (status 140)
RPC: 33 validating UNIX cred f746e440
RPC: 33 using AUTH_UNIX cred f746e440 to unwrap rpc data
RPC: 33 call_decode result 0
RPC: 33 return 0, status 0
RPC: 33 release task
RPC: freeing buffer of size 576 at f6ccb800
RPC: 33 release request f7e84000
RPC: wake_up_next(f7ea0964 "xprt_backlog")
RPC: 33 releasing UNIX cred f746e440
RPC: rpc_release_client(f79a82c0, 1)
NFS reply pathconf: 0
<-- nfs_probe_fsinfo() = 0
Cloned FSID: 696c1f:0
<-- nfs_clone_server() = f7193c80
RPC: 33 freeing task
NFS: nfs_fhget(0:12/0 ct=1)
do_proc_get_root: call fsinfo
RPC: new task initialized, procpid 3524
RPC: allocated task f7f8c380
RPC: 0 looking up UNIX cred
RPC: 34 __rpc_execute flags=0x80
RPC: 34 call_start nfs3 proc 19 (sync)
RPC: 34 call_reserve (status 0)
RPC: 34 reserved req f7e84000 xid 5e00ee57
RPC: 34 call_reserveresult (status 0)
RPC: 34 call_allocate (status 0)
RPC: 34 allocated buffer of size 600 at f6ccb800
RPC: 34 call_bind (status 0)
RPC: 34 call_connect xprt f7ea0800 is connected
RPC: 34 call_transmit (status 0)
RPC: 34 xprt_prepare_transmit
RPC: 34 call_encode (status 0)
RPC: 34 marshaling UNIX cred f746e440
RPC: 34 using AUTH_UNIX cred f746e440 to wrap rpc data
RPC: 34 xprt_transmit(120)
RPC: xs_tcp_send_request(120) = 120
RPC: xs_tcp_data_ready...
RPC: xs_tcp_data_recv started
RPC: reading TCP record fragment of length 164
RPC: reading XID (4 bytes)
RPC: reading reply for XID 5e00ee57
RPC: XID 5e00ee57 read 160 bytes
RPC: xprt = f7ea0800, tcp_copied = 164, tcp_offset = 164,
tcp_reclen = 164
RPC: 34 xid 5e00ee57 complete (164 bytes received)
RPC: xs_tcp_data_recv done
RPC: 34 xmit complete
RPC: wake_up_next(f7ea090c "xprt_resend")
RPC: wake_up_next(f7ea08e0 "xprt_sending")
RPC: 34 call_status (status 164)
RPC: 34 call_decode (status 164)
RPC: 34 validating UNIX cred f746e440
RPC: 34 using AUTH_UNIX cred f746e440 to unwrap rpc data
RPC: 34 call_decode result 0
RPC: 34 return 0, status 0
RPC: 34 release task
RPC: freeing buffer of size 600 at f6ccb800
RPC: 34 release request f7e84000
RPC: wake_up_next(f7ea0964 "xprt_backlog")
RPC: 34 releasing UNIX cred f746e440
RPC: rpc_release_client(f79a82c0, 1)
do_proc_get_root: reply fsinfo: 0
NFS: nfs_fhget(0:12/67 ct=1)
<-- nfs_xdev_get_sb() = 0
nfs_do_submount: done
RPC: 34 freeing task
<-- nfs_do_submount() = f7464940
nfs_follow_mountpoint: done, returned 0
<-- nfs_follow_mountpoint() = 0
RPC: looking up UNIX cred
NFS: permission(0:10/6908959), mask=0x1, res=0
NFS: nfs_lookup_revalidate(/.snapshot) is valid
RPC: looking up UNIX cred
NFS call access
RPC: new task initialized, procpid 3524
RPC: allocated task f7f8c380
RPC: 0 holding UNIX cred f746e440
RPC: 35 __rpc_execute flags=0x80
RPC: 35 call_start nfs3 proc 4 (sync)
RPC: 35 call_reserve (status 0)
RPC: 35 reserved req f7e84000 xid 5f00ee57
RPC: 35 call_reserveresult (status 0)
RPC: 35 call_allocate (status 0)
RPC: 35 allocated buffer of size 560 at f6ccb800
RPC: 35 call_bind (status 0)
RPC: 35 call_connect xprt f7ea0800 is connected
RPC: 35 call_transmit (status 0)
RPC: 35 xprt_prepare_transmit
RPC: 35 call_encode (status 0)
RPC: 35 marshaling UNIX cred f746e440
RPC: 35 using AUTH_UNIX cred f746e440 to wrap rpc data
RPC: 35 xprt_transmit(124)
RPC: xs_tcp_send_request(124) = 124
RPC: xs_tcp_data_ready...
RPC: xs_tcp_data_recv started
RPC: reading TCP record fragment of length 120
RPC: reading XID (4 bytes)
RPC: reading reply for XID 5f00ee57
RPC: XID 5f00ee57 read 116 bytes
RPC: xprt = f7ea0800, tcp_copied = 120, tcp_offset = 120,
tcp_reclen = 120
RPC: 35 xid 5f00ee57 complete (120 bytes received)
RPC: xs_tcp_data_recv done
RPC: 35 xmit complete
RPC: wake_up_next(f7ea090c "xprt_resend")
RPC: wake_up_next(f7ea08e0 "xprt_sending")
RPC: 35 call_status (status 120)
RPC: 35 call_decode (status 120)
RPC: 35 validating UNIX cred f746e440
RPC: 35 using AUTH_UNIX cred f746e440 to unwrap rpc data
RPC: 35 call_decode result 0
RPC: 35 return 0, status 0
RPC: 35 release task
RPC: freeing buffer of size 560 at f6ccb800
RPC: 35 release request f7e84000
RPC: wake_up_next(f7ea0964 "xprt_backlog")
RPC: 35 releasing UNIX cred f746e440
RPC: rpc_release_client(f79a82c0, 1)
NFS: nfs_update_inode(0:12/67 ct=1 info=0x6)
NFS reply access: 0
NFS: permission(0:12/67), mask=0x1, res=0
RPC: 35 freeing task
I hope that helps!
Dallas
> best,
> Herbert
>
>
>>> TIA,
>>> Herbert
>>>
>>>
>>>> Thanks!
>>>> Dallas
>>>>
>>
Received on Wed Sep 12 02:37:04 2007