Subject: Re: [vserver] problem accessing NetApp Filer snapshot
From: Dallas Kashuba <dallas@dreamhost.com>
Date: Tue, 11 Sep 2007 18:36:23 -0700

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
>>>>
>>