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