Hi,
with the latest nfs-1.2.7/kernel-3.7.1 tools i've noticed an error during autofs mounting.
reduced testcase shows that mount.nfs with 'vers=4' has a problem:
[root@chufu ~]# mount.nfs -v -o vers=4 192.168.2.100:/home/atest/farm-local /mnt
mount.nfs: timeout set for Thu Jan 3 10:22:00 2013
mount.nfs: trying text-based options 'vers=4,addr=192.168.2.100,clientaddr=192.168.2.103'
mount.nfs: mount(2): Cannot allocate memory
mount.nfs: Cannot allocate memory
while the vers=3 works fine:
[root@chufu ~]# mount.nfs -v -o vers=3 192.168.2.100:/home/atest/farm-local /mnt
mount.nfs: timeout set for Thu Jan 3 10:22:04 2013
mount.nfs: trying text-based options 'vers=3,addr=192.168.2.100'
mount.nfs: prog 100003, trying vers=3, prot=6
mount.nfs: trying 192.168.2.100 prog 100003 vers 3 prot TCP port 2049
mount.nfs: prog 100005, trying vers=3, prot=17
mount.nfs: trying 192.168.2.100 prog 100005 vers 3 prot UDP port 42412
no obvious errors in logs on nfs server/client side :(
i can provide more info if you need to diagnose this issue.
BR,
Paweł.
On Wed, Jan 16, 2013 at 10:18:51PM +0100, Paweł Sikora wrote:
> On Wednesday 16 of January 2013 15:15:10 J. Bruce Fields wrote:
> > On Wed, Jan 16, 2013 at 09:07:45PM +0100, Paweł Sikora wrote:
> > > On Wednesday 16 of January 2013 14:39:32 J. Bruce Fields wrote:
> > > > On Wed, Jan 16, 2013 at 08:03:14PM +0100, Paweł Sikora wrote:
> > > > > [259176.973751] NFS: nfs mount opts='soft,addr=10.0.2.28,vers=3,proto=tcp,mountvers=3,mountproto=udp,mountport=50252'
> > > > > [259176.973757] NFS: parsing nfs mount option 'soft'
> > > > > [259176.973759] NFS: parsing nfs mount option 'addr=10.0.2.28'
> > > > > [259176.973765] NFS: parsing nfs mount option 'vers=3'
> > > > > [259176.973769] NFS: parsing nfs mount option 'proto=tcp'
> > > > > [259176.973772] NFS: parsing nfs mount option 'mountvers=3'
> > > > > [259176.973776] NFS: parsing nfs mount option 'mountproto=udp'
> > > > > [259176.973779] NFS: parsing nfs mount option 'mountport=50252'
> > > > > [259176.973784] NFS: MNTPATH: '/R10'
> > > > > [259176.973788] NFS: sending MNT request for nexus:/R10
> > > > > [259176.974620] NFS: received 1 auth flavors
> > > > > [259176.974623] NFS: auth flavor[0]: 1
> > > > > [259176.974640] NFS: MNT request succeeded
> > > > > [259176.974643] NFS: using auth flavor 1
> > > > > [259176.974688] --> nfs_init_server()
> > > > > [259176.974691] --> nfs_get_client(nexus,v3)
> > > > > [259176.974698] NFS: get client cookie (0xffff88021146f800/0xffff8800ceb06640)
> > > > > [259176.975704] <-- nfs_init_server() = 0 [new ffff88021146f800]
> > > > > [259176.975708] --> nfs_probe_fsinfo()
> > > > > [259176.975711] NFS call fsinfo
> > > > > [259176.975959] NFS reply fsinfo: -116
> > > >
> > > > That's ESTALE. Might be interesting to see the network traffic between
> > > > client and server.
> > >
> > > here's the tcpdump result: http://pluto.agmk.net/kernel/nfs.mount.estale.dump
> >
> > On just a very quick skim (you may want to verify to see I've got it
> > right), frame 30 shows the server returning a filehandle in a MNT reply,
> > then frame 48 shows the same client that got that MNT reply using the
> > same filehandle in an FSINFO reply, and getting an NFS3ERR_STALE
> > response.
> >
> > Offhand seems like a server bug. Might conceivably happen if there was
> > some confusion whether the client was authorized to access that export?
>
> i have such nfs problems with only one server which have complicated exports/local-binds:
>
> fstab:
>
> /dev/md0 / ext3 defaults 1 1
> /dev/md1 /R0 ext4 defaults,noatime 1 2
> /dev/md2 /R10 ext4 defaults,noatime 1 2
> /home /remote/nexus/home none bind
> /R0/atest_home /home/atest none bind
> /R0/farm/ftp /var/lib/ftp none bind
> /R0 /remote/nexus/R0 none bind
> /R10 /remote/nexus/R10 none bind
>
> exports:
>
> /home *(rw,sync,no_wdelay,no_subtree_check,no_root_squash,insecure_locks,nohide)
> /R0 *(rw,async,no_wdelay,no_subtree_check,no_root_squash,insecure_locks,nohide,crossmnt)
> /R0/farm/ftp *(rw,async,no_wdelay,no_subtree_check,no_root_squash,insecure_locks,nohide,crossmnt)
> /R10 *(rw,sync,no_wdelay,no_subtree_check,no_root_squash,insecure_locks,nohide,crossmnt)
> /R10/farm *(rw,sync,no_wdelay,no_subtree_check,no_root_squash,insecure_locks,nohide,crossmnt)
> /R10/farm/sources *(rw,sync,no_wdelay,no_subtree_check,no_root_squash,insecure_locks,nohide,crossmnt)
> /R10/farm/soft *(rw,sync,no_wdelay,no_subtree_check,no_root_squash,insecure_locks,nohide,crossmnt)
>
> and finally, the /R0/farm contains cross symlinks to R10 via binded dirs:
>
> soft -> /remote/nexus/R10/farm/soft
> sources -> /remote/nexus/R10/farm/sources
>
>
> maybe this crappy setup exposes some bug on the server side?
So in the above setup, /R0 and /remote/nexus/R0, for example, both point
to the same superblock.
The filehandle contains only a reference to the superblock, with no
information about how it was arrived at. When nfsd gets the filehandle
it's resolved in two steps:
- first it asks mountd to tell it a path for the given
filehandle data
- then it asks mountd for export options for that path
You can see the former in /proc/net/rpc/nfsd.fh/content, and the latter
in /proc/net/rpc/nfsd.export/content, so it might be interesting to
compare those two after a success and after a failure.
Since there are multiple possible paths that each filehandle could be
mapped to, I suspect the outcome depends on which mountd chooses, which
could be random. But I don't immediately see how that's causing the
problem, since all your exports have the same option.
By the way, exporting subdirectories of / isn't generally recommended,
since in practice that makes it possible for a malicious host on the
network to access all of /. If you must do that, turn on subtree_check.
(But that may cause other problems.)
--b.
On 05/01/13 05:08, Paweł Sikora wrote:
> On Thursday 03 of January 2013 09:42:01 Steve Dickson wrote:
>>
>> On 03/01/13 04:27, Paweł Sikora wrote:
>>> Hi,
>>>
>>> with the latest nfs-1.2.7/kernel-3.7.1 tools i've noticed an error during autofs mounting.
>>> reduced testcase shows that mount.nfs with 'vers=4' has a problem:
>>>
>>> [root@chufu ~]# mount.nfs -v -o vers=4 192.168.2.100:/home/atest/farm-local /mnt
>>> mount.nfs: timeout set for Thu Jan 3 10:22:00 2013
>>> mount.nfs: trying text-based options 'vers=4,addr=192.168.2.100,clientaddr=192.168.2.103'
>>> mount.nfs: mount(2): Cannot allocate memory
>>> mount.nfs: Cannot allocate memory
>>>
>>> while the vers=3 works fine:
>>>
>>> [root@chufu ~]# mount.nfs -v -o vers=3 192.168.2.100:/home/atest/farm-local /mnt
>>> mount.nfs: timeout set for Thu Jan 3 10:22:04 2013
>>> mount.nfs: trying text-based options 'vers=3,addr=192.168.2.100'
>>> mount.nfs: prog 100003, trying vers=3, prot=6
>>> mount.nfs: trying 192.168.2.100 prog 100003 vers 3 prot TCP port 2049
>>> mount.nfs: prog 100005, trying vers=3, prot=17
>>> mount.nfs: trying 192.168.2.100 prog 100005 vers 3 prot UDP port 42412
>>>
>>> no obvious errors in logs on nfs server/client side :(
>>> i can provide more info if you need to diagnose this issue.
>>
>> Please set the kernel debugging with 'rpcdebug -m nfs -s mount' then post the out put found in /var/log/messages.
>
> [root@pawels ~]# mount.nfs -v -o vers=4 192.168.2.100:/home/atest/farm-local /mnt
>
> mount.nfs: timeout set for Sat Jan 5 11:08:42 2013
> mount.nfs: trying text-based options 'vers=4,addr=192.168.2.100,clientaddr=10.0.2.35'
> mount.nfs: mount(2): Cannot allocate memory
> mount.nfs: Cannot allocate memory
>
> [root@pawels ~]# dmesg|tail
>
> [ 4187.654183] NFS: nfs mount opts='vers=4,addr=192.168.2.100,clientaddr=10.0.2.35'
> [ 4187.654188] NFS: parsing nfs mount option 'vers=4'
> [ 4187.654193] NFS: parsing nfs mount option 'addr=192.168.2.100'
> [ 4187.654198] NFS: parsing nfs mount option 'clientaddr=10.0.2.35'
> [ 4187.654204] NFS: MNTPATH: '/home/atest/farm-local'
> [ 4187.654206] --> nfs4_try_mount()
> [ 4187.975255] <-- nfs4_try_mount() = -12 [error]
>
Hmm... it appears to me that the kernel modules are not be loaded...
What does 'lsmod | grep nfs' show, anything?
steved.
On Wednesday 16 of January 2013 14:39:32 J. Bruce Fields wrote:
> On Wed, Jan 16, 2013 at 08:03:14PM +0100, Paweł Sikora wrote:
> > [259176.973751] NFS: nfs mount opts='soft,addr=10.0.2.28,vers=3,proto=tcp,mountvers=3,mountproto=udp,mountport=50252'
> > [259176.973757] NFS: parsing nfs mount option 'soft'
> > [259176.973759] NFS: parsing nfs mount option 'addr=10.0.2.28'
> > [259176.973765] NFS: parsing nfs mount option 'vers=3'
> > [259176.973769] NFS: parsing nfs mount option 'proto=tcp'
> > [259176.973772] NFS: parsing nfs mount option 'mountvers=3'
> > [259176.973776] NFS: parsing nfs mount option 'mountproto=udp'
> > [259176.973779] NFS: parsing nfs mount option 'mountport=50252'
> > [259176.973784] NFS: MNTPATH: '/R10'
> > [259176.973788] NFS: sending MNT request for nexus:/R10
> > [259176.974620] NFS: received 1 auth flavors
> > [259176.974623] NFS: auth flavor[0]: 1
> > [259176.974640] NFS: MNT request succeeded
> > [259176.974643] NFS: using auth flavor 1
> > [259176.974688] --> nfs_init_server()
> > [259176.974691] --> nfs_get_client(nexus,v3)
> > [259176.974698] NFS: get client cookie (0xffff88021146f800/0xffff8800ceb06640)
> > [259176.975704] <-- nfs_init_server() = 0 [new ffff88021146f800]
> > [259176.975708] --> nfs_probe_fsinfo()
> > [259176.975711] NFS call fsinfo
> > [259176.975959] NFS reply fsinfo: -116
>
> That's ESTALE. Might be interesting to see the network traffic between
> client and server.
here's the tcpdump result: http://pluto.agmk.net/kernel/nfs.mount.estale.dump
On Wednesday 16 of January 2013 15:15:10 J. Bruce Fields wrote:
> On Wed, Jan 16, 2013 at 09:07:45PM +0100, Paweł Sikora wrote:
> > On Wednesday 16 of January 2013 14:39:32 J. Bruce Fields wrote:
> > > On Wed, Jan 16, 2013 at 08:03:14PM +0100, Paweł Sikora wrote:
> > > > [259176.973751] NFS: nfs mount opts='soft,addr=10.0.2.28,vers=3,proto=tcp,mountvers=3,mountproto=udp,mountport=50252'
> > > > [259176.973757] NFS: parsing nfs mount option 'soft'
> > > > [259176.973759] NFS: parsing nfs mount option 'addr=10.0.2.28'
> > > > [259176.973765] NFS: parsing nfs mount option 'vers=3'
> > > > [259176.973769] NFS: parsing nfs mount option 'proto=tcp'
> > > > [259176.973772] NFS: parsing nfs mount option 'mountvers=3'
> > > > [259176.973776] NFS: parsing nfs mount option 'mountproto=udp'
> > > > [259176.973779] NFS: parsing nfs mount option 'mountport=50252'
> > > > [259176.973784] NFS: MNTPATH: '/R10'
> > > > [259176.973788] NFS: sending MNT request for nexus:/R10
> > > > [259176.974620] NFS: received 1 auth flavors
> > > > [259176.974623] NFS: auth flavor[0]: 1
> > > > [259176.974640] NFS: MNT request succeeded
> > > > [259176.974643] NFS: using auth flavor 1
> > > > [259176.974688] --> nfs_init_server()
> > > > [259176.974691] --> nfs_get_client(nexus,v3)
> > > > [259176.974698] NFS: get client cookie (0xffff88021146f800/0xffff8800ceb06640)
> > > > [259176.975704] <-- nfs_init_server() = 0 [new ffff88021146f800]
> > > > [259176.975708] --> nfs_probe_fsinfo()
> > > > [259176.975711] NFS call fsinfo
> > > > [259176.975959] NFS reply fsinfo: -116
> > >
> > > That's ESTALE. Might be interesting to see the network traffic between
> > > client and server.
> >
> > here's the tcpdump result: http://pluto.agmk.net/kernel/nfs.mount.estale.dump
>
> On just a very quick skim (you may want to verify to see I've got it
> right), frame 30 shows the server returning a filehandle in a MNT reply,
> then frame 48 shows the same client that got that MNT reply using the
> same filehandle in an FSINFO reply, and getting an NFS3ERR_STALE
> response.
>
> Offhand seems like a server bug. Might conceivably happen if there was
> some confusion whether the client was authorized to access that export?
i have such nfs problems with only one server which have complicated exports/local-binds:
fstab:
/dev/md0 / ext3 defaults 1 1
/dev/md1 /R0 ext4 defaults,noatime 1 2
/dev/md2 /R10 ext4 defaults,noatime 1 2
/home /remote/nexus/home none bind
/R0/atest_home /home/atest none bind
/R0/farm/ftp /var/lib/ftp none bind
/R0 /remote/nexus/R0 none bind
/R10 /remote/nexus/R10 none bind
exports:
/home *(rw,sync,no_wdelay,no_subtree_check,no_root_squash,insecure_locks,nohide)
/R0 *(rw,async,no_wdelay,no_subtree_check,no_root_squash,insecure_locks,nohide,crossmnt)
/R0/farm/ftp *(rw,async,no_wdelay,no_subtree_check,no_root_squash,insecure_locks,nohide,crossmnt)
/R10 *(rw,sync,no_wdelay,no_subtree_check,no_root_squash,insecure_locks,nohide,crossmnt)
/R10/farm *(rw,sync,no_wdelay,no_subtree_check,no_root_squash,insecure_locks,nohide,crossmnt)
/R10/farm/sources *(rw,sync,no_wdelay,no_subtree_check,no_root_squash,insecure_locks,nohide,crossmnt)
/R10/farm/soft *(rw,sync,no_wdelay,no_subtree_check,no_root_squash,insecure_locks,nohide,crossmnt)
and finally, the /R0/farm contains cross symlinks to R10 via binded dirs:
soft -> /remote/nexus/R10/farm/soft
sources -> /remote/nexus/R10/farm/sources
maybe this crappy setup exposes some bug on the server side?
On Wed, 2013-01-16 at 14:39 -0500, J. Bruce Fields wrote:
+AD4- On Wed, Jan 16, 2013 at 08:03:14PM +-0100, Pawe+AUI- Sikora wrote:
+AD4- +AD4- +AFs-259176.973751+AF0- NFS: nfs mount opts+AD0-'soft,addr+AD0-10.0.2.28,vers+AD0-3,proto+AD0-tcp,mountvers+AD0-3,mountproto+AD0-udp,mountport+AD0-50252'
+AD4- +AD4- +AFs-259176.973757+AF0- NFS: parsing nfs mount option 'soft'
+AD4- +AD4- +AFs-259176.973759+AF0- NFS: parsing nfs mount option 'addr+AD0-10.0.2.28'
+AD4- +AD4- +AFs-259176.973765+AF0- NFS: parsing nfs mount option 'vers+AD0-3'
+AD4- +AD4- +AFs-259176.973769+AF0- NFS: parsing nfs mount option 'proto+AD0-tcp'
+AD4- +AD4- +AFs-259176.973772+AF0- NFS: parsing nfs mount option 'mountvers+AD0-3'
+AD4- +AD4- +AFs-259176.973776+AF0- NFS: parsing nfs mount option 'mountproto+AD0-udp'
+AD4- +AD4- +AFs-259176.973779+AF0- NFS: parsing nfs mount option 'mountport+AD0-50252'
+AD4- +AD4- +AFs-259176.973784+AF0- NFS: MNTPATH: '/R10'
+AD4- +AD4- +AFs-259176.973788+AF0- NFS: sending MNT request for nexus:/R10
+AD4- +AD4- +AFs-259176.974620+AF0- NFS: received 1 auth flavors
+AD4- +AD4- +AFs-259176.974623+AF0- NFS: auth flavor+AFs-0+AF0-: 1
+AD4- +AD4- +AFs-259176.974640+AF0- NFS: MNT request succeeded
+AD4- +AD4- +AFs-259176.974643+AF0- NFS: using auth flavor 1
+AD4- +AD4- +AFs-259176.974688+AF0- --+AD4- nfs+AF8-init+AF8-server()
+AD4- +AD4- +AFs-259176.974691+AF0- --+AD4- nfs+AF8-get+AF8-client(nexus,v3)
+AD4- +AD4- +AFs-259176.974698+AF0- NFS: get client cookie (0xffff88021146f800/0xffff8800ceb06640)
+AD4- +AD4- +AFs-259176.975704+AF0- +ADw--- nfs+AF8-init+AF8-server() +AD0- 0 +AFs-new ffff88021146f800+AF0-
+AD4- +AD4- +AFs-259176.975708+AF0- --+AD4- nfs+AF8-probe+AF8-fsinfo()
+AD4- +AD4- +AFs-259176.975711+AF0- NFS call fsinfo
+AD4- +AD4- +AFs-259176.975959+AF0- NFS reply fsinfo: -116
+AD4-
+AD4- That's ESTALE. Might be interesting to see the network traffic between
+AD4- client and server.
Yes. The ENOMEM is a red herring. It turns out that there is a bug in
nfs+AF8-xdev+AF8-mount that converts all errors from clone+AF8-server() into
ENOMEM...
The attached patch should fix it.
--
Trond Myklebust
Linux NFS client maintainer
NetApp
Trond.Myklebust+AEA-netapp.com
http://www.netapp.com
On Wed, Jan 16, 2013 at 09:07:45PM +0100, Paweł Sikora wrote:
> On Wednesday 16 of January 2013 14:39:32 J. Bruce Fields wrote:
> > On Wed, Jan 16, 2013 at 08:03:14PM +0100, Paweł Sikora wrote:
> > > [259176.973751] NFS: nfs mount opts='soft,addr=10.0.2.28,vers=3,proto=tcp,mountvers=3,mountproto=udp,mountport=50252'
> > > [259176.973757] NFS: parsing nfs mount option 'soft'
> > > [259176.973759] NFS: parsing nfs mount option 'addr=10.0.2.28'
> > > [259176.973765] NFS: parsing nfs mount option 'vers=3'
> > > [259176.973769] NFS: parsing nfs mount option 'proto=tcp'
> > > [259176.973772] NFS: parsing nfs mount option 'mountvers=3'
> > > [259176.973776] NFS: parsing nfs mount option 'mountproto=udp'
> > > [259176.973779] NFS: parsing nfs mount option 'mountport=50252'
> > > [259176.973784] NFS: MNTPATH: '/R10'
> > > [259176.973788] NFS: sending MNT request for nexus:/R10
> > > [259176.974620] NFS: received 1 auth flavors
> > > [259176.974623] NFS: auth flavor[0]: 1
> > > [259176.974640] NFS: MNT request succeeded
> > > [259176.974643] NFS: using auth flavor 1
> > > [259176.974688] --> nfs_init_server()
> > > [259176.974691] --> nfs_get_client(nexus,v3)
> > > [259176.974698] NFS: get client cookie (0xffff88021146f800/0xffff8800ceb06640)
> > > [259176.975704] <-- nfs_init_server() = 0 [new ffff88021146f800]
> > > [259176.975708] --> nfs_probe_fsinfo()
> > > [259176.975711] NFS call fsinfo
> > > [259176.975959] NFS reply fsinfo: -116
> >
> > That's ESTALE. Might be interesting to see the network traffic between
> > client and server.
>
> here's the tcpdump result: http://pluto.agmk.net/kernel/nfs.mount.estale.dump
On just a very quick skim (you may want to verify to see I've got it
right), frame 30 shows the server returning a filehandle in a MNT reply,
then frame 48 shows the same client that got that MNT reply using the
same filehandle in an FSINFO reply, and getting an NFS3ERR_STALE
response.
Offhand seems like a server bug. Might conceivably happen if there was
some confusion whether the client was authorized to access that export?
--b.
On Thursday 17 of January 2013 08:49:59 J. Bruce Fields wrote:
> On Wed, Jan 16, 2013 at 10:18:51PM +0100, Paweł Sikora wrote:
> > On Wednesday 16 of January 2013 15:15:10 J. Bruce Fields wrote:
> > > On Wed, Jan 16, 2013 at 09:07:45PM +0100, Paweł Sikora wrote:
> > > > On Wednesday 16 of January 2013 14:39:32 J. Bruce Fields wrote:
> > > > > On Wed, Jan 16, 2013 at 08:03:14PM +0100, Paweł Sikora wrote:
> > > > > > [259176.973751] NFS: nfs mount opts='soft,addr=10.0.2.28,vers=3,proto=tcp,mountvers=3,mountproto=udp,mountport=50252'
> > > > > > [259176.973757] NFS: parsing nfs mount option 'soft'
> > > > > > [259176.973759] NFS: parsing nfs mount option 'addr=10.0.2.28'
> > > > > > [259176.973765] NFS: parsing nfs mount option 'vers=3'
> > > > > > [259176.973769] NFS: parsing nfs mount option 'proto=tcp'
> > > > > > [259176.973772] NFS: parsing nfs mount option 'mountvers=3'
> > > > > > [259176.973776] NFS: parsing nfs mount option 'mountproto=udp'
> > > > > > [259176.973779] NFS: parsing nfs mount option 'mountport=50252'
> > > > > > [259176.973784] NFS: MNTPATH: '/R10'
> > > > > > [259176.973788] NFS: sending MNT request for nexus:/R10
> > > > > > [259176.974620] NFS: received 1 auth flavors
> > > > > > [259176.974623] NFS: auth flavor[0]: 1
> > > > > > [259176.974640] NFS: MNT request succeeded
> > > > > > [259176.974643] NFS: using auth flavor 1
> > > > > > [259176.974688] --> nfs_init_server()
> > > > > > [259176.974691] --> nfs_get_client(nexus,v3)
> > > > > > [259176.974698] NFS: get client cookie (0xffff88021146f800/0xffff8800ceb06640)
> > > > > > [259176.975704] <-- nfs_init_server() = 0 [new ffff88021146f800]
> > > > > > [259176.975708] --> nfs_probe_fsinfo()
> > > > > > [259176.975711] NFS call fsinfo
> > > > > > [259176.975959] NFS reply fsinfo: -116
> > > > >
> > > > > That's ESTALE. Might be interesting to see the network traffic between
> > > > > client and server.
> > > >
> > > > here's the tcpdump result: http://pluto.agmk.net/kernel/nfs.mount.estale.dump
> > >
> > > On just a very quick skim (you may want to verify to see I've got it
> > > right), frame 30 shows the server returning a filehandle in a MNT reply,
> > > then frame 48 shows the same client that got that MNT reply using the
> > > same filehandle in an FSINFO reply, and getting an NFS3ERR_STALE
> > > response.
> > >
> > > Offhand seems like a server bug. Might conceivably happen if there was
> > > some confusion whether the client was authorized to access that export?
> >
> > i have such nfs problems with only one server which have complicated exports/local-binds:
> >
> > fstab:
> >
> > /dev/md0 / ext3 defaults 1 1
> > /dev/md1 /R0 ext4 defaults,noatime 1 2
> > /dev/md2 /R10 ext4 defaults,noatime 1 2
> > /home /remote/nexus/home none bind
> > /R0/atest_home /home/atest none bind
> > /R0/farm/ftp /var/lib/ftp none bind
> > /R0 /remote/nexus/R0 none bind
> > /R10 /remote/nexus/R10 none bind
> >
> > exports:
> >
> > /home *(rw,sync,no_wdelay,no_subtree_check,no_root_squash,insecure_locks,nohide)
> > /R0 *(rw,async,no_wdelay,no_subtree_check,no_root_squash,insecure_locks,nohide,crossmnt)
> > /R0/farm/ftp *(rw,async,no_wdelay,no_subtree_check,no_root_squash,insecure_locks,nohide,crossmnt)
> > /R10 *(rw,sync,no_wdelay,no_subtree_check,no_root_squash,insecure_locks,nohide,crossmnt)
> > /R10/farm *(rw,sync,no_wdelay,no_subtree_check,no_root_squash,insecure_locks,nohide,crossmnt)
> > /R10/farm/sources *(rw,sync,no_wdelay,no_subtree_check,no_root_squash,insecure_locks,nohide,crossmnt)
> > /R10/farm/soft *(rw,sync,no_wdelay,no_subtree_check,no_root_squash,insecure_locks,nohide,crossmnt)
> >
> > and finally, the /R0/farm contains cross symlinks to R10 via binded dirs:
> >
> > soft -> /remote/nexus/R10/farm/soft
> > sources -> /remote/nexus/R10/farm/sources
> >
> >
> > maybe this crappy setup exposes some bug on the server side?
>
> So in the above setup, /R0 and /remote/nexus/R0, for example, both point
> to the same superblock.
>
> The filehandle contains only a reference to the superblock, with no
> information about how it was arrived at. When nfsd gets the filehandle
> it's resolved in two steps:
>
> - first it asks mountd to tell it a path for the given
> filehandle data
> - then it asks mountd for export options for that path
>
> You can see the former in /proc/net/rpc/nfsd.fh/content, and the latter
> in /proc/net/rpc/nfsd.export/content, so it might be interesting to
> compare those two after a success and after a failure.
>
> Since there are multiple possible paths that each filehandle could be
> mapped to, I suspect the outcome depends on which mountd chooses, which
> could be random. But I don't immediately see how that's causing the
> problem, since all your exports have the same option.
before failing mount attempt i see such values on the server side:
[root@nexus ~]# ./nfs_debug.sh
+ cat /proc/net/rpc/nfsd.fh/content
#domain fsidtype fsid [path]
* 6 0x40694572b34adc7d7535a982d692a864 /R10
* 1 0x00000000 /
* 6 0x0f5a4f040e452cbc5ba412a3a206b7c3 /R0
# * 6 0xa75dfe547f9b43ac0000000000000000
# * 6 0xf0ec5c351974d8650000000000000000
+ cat /proc/net/rpc/nfsd.export/content
#path domain(flags)
/ *(ro,no_root_squash,sync,no_wdelay,no_subtree_check,v4root,fsid=0,uuid=44053428:4cfdc05e:00000000:00000000)
/R0 *(rw,no_root_squash,sync,wdelay,nohide,crossmnt,no_subtree_check,insecure_locks,uuid=044f5a0f:bc2c450e:a312a45b:c3b706a2)
/R10 *(rw,no_root_squash,sync,wdelay,nohide,crossmnt,no_subtree_check,insecure_locks,uuid=72456940:7ddc4ab3:82a93575:64a892d6)
after R0 mount attempt there're two entries for R0 with different uuids. is it correct behaviour?
[root@nexus ~]# ./nfs_debug.sh
+ cat /proc/net/rpc/nfsd.fh/content
#domain fsidtype fsid [path]
* 6 0x40694572b34adc7d7535a982d692a864 /R10
* 1 0x00000000 /
* 6 0x0f5a4f040e452cbc5ba412a3a206b7c3 /R0
# * 6 0xa75dfe547f9b43ac0000000000000000
# * 6 0xf0ec5c351974d8650000000000000000
+ cat /proc/net/rpc/nfsd.export/content
#path domain(flags)
/ *(ro,no_root_squash,sync,no_wdelay,no_subtree_check,v4root,fsid=0,uuid=44053428:4cfdc05e:00000000:00000000)
/R0 *(rw,no_root_squash,sync,wdelay,nohide,crossmnt,no_subtree_check,insecure_locks,uuid=044f5a0f:bc2c450e:a312a45b:c3b706a2)
/R0 *(rw,no_root_squash,sync,wdelay,nohide,crossmnt,no_subtree_check,insecure_locks,uuid=54fe5da7:ac439b7f:00000000:00000000)
/R10 *(rw,no_root_squash,sync,wdelay,nohide,crossmnt,no_subtree_check,insecure_locks,uuid=72456940:7ddc4ab3:82a93575:64a892d6)
On Wed, Jan 16, 2013 at 08:03:14PM +0100, Paweł Sikora wrote:
> [259176.973751] NFS: nfs mount opts='soft,addr=10.0.2.28,vers=3,proto=tcp,mountvers=3,mountproto=udp,mountport=50252'
> [259176.973757] NFS: parsing nfs mount option 'soft'
> [259176.973759] NFS: parsing nfs mount option 'addr=10.0.2.28'
> [259176.973765] NFS: parsing nfs mount option 'vers=3'
> [259176.973769] NFS: parsing nfs mount option 'proto=tcp'
> [259176.973772] NFS: parsing nfs mount option 'mountvers=3'
> [259176.973776] NFS: parsing nfs mount option 'mountproto=udp'
> [259176.973779] NFS: parsing nfs mount option 'mountport=50252'
> [259176.973784] NFS: MNTPATH: '/R10'
> [259176.973788] NFS: sending MNT request for nexus:/R10
> [259176.974620] NFS: received 1 auth flavors
> [259176.974623] NFS: auth flavor[0]: 1
> [259176.974640] NFS: MNT request succeeded
> [259176.974643] NFS: using auth flavor 1
> [259176.974688] --> nfs_init_server()
> [259176.974691] --> nfs_get_client(nexus,v3)
> [259176.974698] NFS: get client cookie (0xffff88021146f800/0xffff8800ceb06640)
> [259176.975704] <-- nfs_init_server() = 0 [new ffff88021146f800]
> [259176.975708] --> nfs_probe_fsinfo()
> [259176.975711] NFS call fsinfo
> [259176.975959] NFS reply fsinfo: -116
That's ESTALE. Might be interesting to see the network traffic between
client and server.
--b.
> [259176.975963] NFS call fsinfo
> [259176.976182] NFS reply fsinfo: -116
> [259176.976184] nfs_probe_fsinfo: error = 116
> [259176.976186] --> nfs_free_server()
> [259176.976282] --> nfs_put_client({1})
> [259176.976285] --> nfs_free_client(3)
> [259176.976287] NFS: releasing client cookie (0xffff88021146f800/0xffff8800ceb06640)
> [259176.976308] <-- nfs_free_client()
> [259176.976322] <-- nfs_free_server()
>
> --
> To unsubscribe from this list: send the line "unsubscribe linux-nfs" in
> the body of a message to [email protected]
> More majordomo info at http://vger.kernel.org/majordomo-info.html
On Friday 04 of January 2013 14:03:52 fanchaoting wrote:
> Paweł Sikora 写道:
> > On Thursday 03 of January 2013 09:42:01 Steve Dickson wrote:
> >> On 03/01/13 04:27, Paweł Sikora wrote:
> >>> Hi,
> >>>
> >>> with the latest nfs-1.2.7/kernel-3.7.1 tools i've noticed an error during autofs mounting.
> >>> reduced testcase shows that mount.nfs with 'vers=4' has a problem:
> >>>
> >>> [root@chufu ~]# mount.nfs -v -o vers=4 192.168.2.100:/home/atest/farm-local /mnt
> >>> mount.nfs: timeout set for Thu Jan 3 10:22:00 2013
> >>> mount.nfs: trying text-based options 'vers=4,addr=192.168.2.100,clientaddr=192.168.2.103'
> >>> mount.nfs: mount(2): Cannot allocate memory
> >>> mount.nfs: Cannot allocate memory
> >>>
> >>> while the vers=3 works fine:
> >>>
> >>> [root@chufu ~]# mount.nfs -v -o vers=3 192.168.2.100:/home/atest/farm-local /mnt
> >>> mount.nfs: timeout set for Thu Jan 3 10:22:04 2013
> >>> mount.nfs: trying text-based options 'vers=3,addr=192.168.2.100'
> >>> mount.nfs: prog 100003, trying vers=3, prot=6
> >>> mount.nfs: trying 192.168.2.100 prog 100003 vers 3 prot TCP port 2049
> >>> mount.nfs: prog 100005, trying vers=3, prot=17
> >>> mount.nfs: trying 192.168.2.100 prog 100005 vers 3 prot UDP port 42412
> >>>
> >>> no obvious errors in logs on nfs server/client side :(
> >>> i can provide more info if you need to diagnose this issue.
> >> Please set the kernel debugging with 'rpcdebug -m nfs -s mount' then post the out put found in /var/log/messages.
> >>
> >
> > rpcdebug can't find the /proc/sys/sunrpc/nfs_debug file in my system. how can i enable it?
> >
> Hi, I found that the upstream kernel didn't create /proc/sys/sunrpc/nfs_debug default,
> if you want to debug rpc,you should set CONFIG_SUNRPC_DEBUG = y.
>
> #cat .config
> .............................
> CONFIG_SUNRPC_BACKCHANNEL=y
> CONFIG_SUNRPC_XPRT_RDMA=m
> CONFIG_RPCSEC_GSS_KRB5=m
> CONFIG_SUNRPC_DEBUG=y <-----CONFIG_SUNRPC_DEBUG = y
> CONFIG_CEPH_FS=m
> CONFIG_CIFS=m
>
> .......................
ok, i'll rebuild kernel from .src.rpm and post results.
btw. i've noticed an oops few moments ago:
[190621.337772] ------------[ cut here ]------------
[190621.337884] kernel BUG at /tmp/B.022a7882-ed62-4d8c-bd20-9208f32f5df6/BUILD/kernel-3.7.1/linux-3.7/net/sunrpc/svc.c:559!
[190621.338026] invalid opcode: 0000 [#1] SMP
[190621.338228] Modules linked in: nfsv3 nfsv4 nfs dns_resolver fscache fuse nfsd auth_rpcgss nfs_acl lockd sunrpc ipmi_si ipmi_devintf ipmi_msghandler sch_sfq xt_nat iptable_nat nf_conntrack_ipv4 nf_defrag_ipv4 nf_nat_ipv4 nf_nat nf_conntrack iptable_filter xt_TCPMSS xt_tcpudp iptable_mangle ip_tables ip6table_filter ip6_tables x_tables quota_v2 quota_tree ext4 crc16 jbd2 raid10 raid0 dm_mod autofs4 dummy ide_cd_mod cdrom ata_generic pata_acpi pata_atiixp ide_pci_generic kvm_amd kvm igb sp5100_tco ptp pps_core dca psmouse atiixp joydev hid_generic amd64_edac_mod edac_core k10temp i2c_piix4 ide_core serio_raw i2c_core evdev pcspkr microcode hwmon edac_mce_amd processor button ext3 mbcache jbd sd_mod crc_t10dif raid1 md_mod ahci libahci libata scsi_mod usbhid hid ohci_hcd ehci_hcd usbcore usb_common
[190621.343769] CPU 5
[190621.343834] Pid: 11360, xid: #0, comm: mount.nfs Not tainted 3.7.1-2 #1 Supermicro H8DGU/H8DGU
[190621.344046] RIP: 0010:[<ffffffffa04d8df2>] [<ffffffffa04d8df2>] svc_destroy+0x102/0x110 [sunrpc]
[190621.344260] RSP: 0018:ffff880461201898 EFLAGS: 00010202
[190621.344359] RAX: ffff8803c7158c38 RBX: ffff8803c7158c00 RCX: 00000000000000c3
[190621.344492] RDX: ffff88080a0b16c8 RSI: 0000000000000286 RDI: 0000000000000286
[190621.344623] RBP: ffff8804612018a8 R08: 00000000000168c0 R09: ffff88080fc568c0
[190621.344755] R10: ffffea000ccf0e00 R11: ffffffffa04d8eb6 R12: ffff880333c3e000
[190621.344884] R13: ffff8807dc8e3f80 R14: ffff8803c7158c00 R15: ffff880461201ae0
[190621.345014] FS: 00007fc0e6d71800(0000) GS:ffff88080fc40000(0000) knlGS:00000000f75b76c0
[190621.345183] CS: 0010 DS: 0000 ES: 0000 CR0: 000000008005003b
[190621.345326] CR2: 00000000021cc000 CR3: 00000007db49c000 CR4: 00000000000007e0
[190621.345468] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
[190621.345598] DR3: 0000000000000000 DR6: 00000000ffff0ff0 DR7: 0000000000000400
[190621.345732] Process mount.nfs (pid: 11360, threadinfo ffff880461200000, task ffff88080914e120)
[190621.345866] Stack:
[190621.345952] ffff880333c3e000 ffff8807dc8e3f84 ffff8804612018d8 ffffffffa04d8ec3
[190621.346300] 0000000000000000 0000000000000000 ffffffff81865400 ffff88021a444400
[190621.346665] ffff880461201908 ffffffffa058b275 0000000000000000 ffff88021a444400
[190621.347011] Call Trace:
[190621.348601] [<ffffffffa04d8ec3>] svc_exit_thread+0xc3/0xd0 [sunrpc]
[190621.348714] [<ffffffffa058b275>] nfs_callback_down+0x65/0xa0 [nfsv4]
[190621.348821] [<ffffffffa058cbe7>] nfs4_free_client+0x37/0xa0 [nfsv4]
[190621.348935] [<ffffffffa054337e>] nfs_put_client+0xfe/0x110 [nfs]
[190621.349039] [<ffffffffa058cd88>] nfs4_init_client+0x138/0x1c0 [nfsv4]
[190621.349148] [<ffffffff8127f7bf>] ? idr_get_new_above_int+0x3f/0x50
[190621.349257] [<ffffffffa04d67ff>] ? rpc_init_wait_queue+0x5f/0x90 [sunrpc]
[190621.349364] [<ffffffffa058cae4>] ? nfs4_alloc_client+0xf4/0x1c0 [nfsv4]
[190621.349471] [<ffffffffa0543969>] nfs_get_client+0x269/0x2b0 [nfs]
[190621.349576] [<ffffffffa058c9c9>] nfs4_set_client.isra.10+0x69/0x90 [nfsv4]
[190621.349684] [<ffffffffa058d1d3>] nfs4_create_server+0xc3/0x2f0 [nfsv4]
[190621.349790] [<ffffffffa05886d4>] nfs4_remote_mount+0x34/0x70 [nfsv4]
[190621.349894] [<ffffffff8117e51f>] mount_fs+0x3f/0x230
[190621.349992] [<ffffffff8113afbb>] ? __alloc_percpu+0xb/0x10
[190621.350093] [<ffffffff81198842>] vfs_kern_mount+0xd2/0x170
[190621.350195] [<ffffffffa058865c>] nfs_do_root_mount+0x8c/0xd0 [nfsv4]
[190621.350301] [<ffffffffa058897b>] nfs4_try_mount+0x3b/0x60 [nfsv4]
[190621.350409] [<ffffffffa054dfa9>] nfs_fs_mount+0x499/0xa20 [nfs]
[190621.350516] [<ffffffffa054b730>] ? nfs_clone_super+0x140/0x140 [nfs]
[190621.350622] [<ffffffffa054b5d0>] ? nfs_clone_sb_security+0x60/0x60 [nfs]
[190621.350726] [<ffffffff8117e51f>] mount_fs+0x3f/0x230
[190621.350823] [<ffffffff8113afbb>] ? __alloc_percpu+0xb/0x10
[190621.350922] [<ffffffff81198842>] vfs_kern_mount+0xd2/0x170
[190621.351021] [<ffffffff81198d5f>] do_kern_mount+0x4f/0x100
[190621.351120] [<ffffffff8119a807>] do_mount+0x2e7/0xa10
[190621.351218] [<ffffffff8119a395>] ? copy_mount_options+0x35/0x180
[190621.351319] [<ffffffff8119afb9>] sys_mount+0x89/0xd0
[190621.351418] [<ffffffff814e8229>] system_call_fastpath+0x16/0x1b
[190621.351518] Code: 00 eb 97 66 0f 1f 44 00 00 e8 8b 14 00 00 48 83 c4 08 5b 5d c3 48 89 fe 31 c0 48 c7 c7 38 be 4e a0 e8 8a eb ff e0 e9 23 ff ff ff <0f> 0b 0f 0b 66 2e 0f 1f 84 00 00 00 00 00 55 48 89 e5 41 56 41
[190621.355336] RIP [<ffffffffa04d8df2>] svc_destroy+0x102/0x110 [sunrpc]
[190621.355517] RSP <ffff880461201898>
[190621.355630] ---[ end trace c243ff3a21205483 ]---
(...)
/*
* The last user is gone and thus all sockets have to be destroyed to
* the point. Check this.
*/
BUG_ON(!list_empty(&serv->sv_permsocks));
svc.c:559: BUG_ON(!list_empty(&serv->sv_tempsocks));
(...)
Paweł Sikora 写道:
> On Thursday 03 of January 2013 09:42:01 Steve Dickson wrote:
>> On 03/01/13 04:27, Paweł Sikora wrote:
>>> Hi,
>>>
>>> with the latest nfs-1.2.7/kernel-3.7.1 tools i've noticed an error during autofs mounting.
>>> reduced testcase shows that mount.nfs with 'vers=4' has a problem:
>>>
>>> [root@chufu ~]# mount.nfs -v -o vers=4 192.168.2.100:/home/atest/farm-local /mnt
>>> mount.nfs: timeout set for Thu Jan 3 10:22:00 2013
>>> mount.nfs: trying text-based options 'vers=4,addr=192.168.2.100,clientaddr=192.168.2.103'
>>> mount.nfs: mount(2): Cannot allocate memory
>>> mount.nfs: Cannot allocate memory
>>>
>>> while the vers=3 works fine:
>>>
>>> [root@chufu ~]# mount.nfs -v -o vers=3 192.168.2.100:/home/atest/farm-local /mnt
>>> mount.nfs: timeout set for Thu Jan 3 10:22:04 2013
>>> mount.nfs: trying text-based options 'vers=3,addr=192.168.2.100'
>>> mount.nfs: prog 100003, trying vers=3, prot=6
>>> mount.nfs: trying 192.168.2.100 prog 100003 vers 3 prot TCP port 2049
>>> mount.nfs: prog 100005, trying vers=3, prot=17
>>> mount.nfs: trying 192.168.2.100 prog 100005 vers 3 prot UDP port 42412
>>>
>>> no obvious errors in logs on nfs server/client side :(
>>> i can provide more info if you need to diagnose this issue.
>> Please set the kernel debugging with 'rpcdebug -m nfs -s mount' then post the out put found in /var/log/messages.
>>
>
> rpcdebug can't find the /proc/sys/sunrpc/nfs_debug file in my system. how can i enable it?
>
Hi, I found that the upstream kernel didn't create /proc/sys/sunrpc/nfs_debug default,
if you want to debug rpc,you should set CONFIG_SUNRPC_DEBUG = y.
#cat .config
.............................
CONFIG_SUNRPC_BACKCHANNEL=y
CONFIG_SUNRPC_XPRT_RDMA=m
CONFIG_RPCSEC_GSS_KRB5=m
CONFIG_SUNRPC_DEBUG=y <-----CONFIG_SUNRPC_DEBUG = y
CONFIG_CEPH_FS=m
CONFIG_CIFS=m
.......................
> --
> To unsubscribe from this list: send the line "unsubscribe linux-nfs" in
> the body of a message to [email protected]
> More majordomo info at http://vger.kernel.org/majordomo-info.html
>
[root@pawels ~]# rpcdebug -m nfs -s all
nfs vfs dircache lookupcache pagecache proc xdr file root callback client mount fscache pnfs pnfs_ld state
[root@pawels ~]# lsmod|grep nfs
nfsv4 150390 0
nfsv3 39327 0
nfs 168978 2 nfsv3,nfsv4
dns_resolver 13064 1 nfs
fscache 46138 1 nfs
nfsd 273079 13
auth_rpcgss 40327 2 nfsd,nfsv4
nfs_acl 12742 2 nfsd,nfsv3
lockd 89142 3 nfs,nfsd,nfsv3
sunrpc 245986 153 nfs,nfsd,auth_rpcgss,lockd,nfsv3,nfsv4,nfs_acl
[root@pawels ~]# mount.nfs -v 192.168.2.100:/home/atest/farm-local /mnt
mount.nfs: timeout set for Wed Jan 9 15:19:14 2013
mount.nfs: trying text-based options 'vers=4,addr=192.168.2.100,clientaddr=10.0.2.35'
mount.nfs: mount(2): Cannot allocate memory
mount.nfs: Cannot allocate memory
[364653.942259] NFS: nfs mount opts='vers=4,addr=192.168.2.100,clientaddr=10.0.2.35'
[364653.942265] NFS: parsing nfs mount option 'vers=4'
[364653.942270] NFS: parsing nfs mount option 'addr=192.168.2.100'
[364653.942275] NFS: parsing nfs mount option 'clientaddr=10.0.2.35'
[364653.942280] NFS: MNTPATH: '/home/atest/farm-local'
[364653.942282] --> nfs4_try_mount()
[364653.942289] --> nfs4_create_server()
[364653.942315] --> nfs4_init_server()
[364653.942317] --> nfs4_set_client()
[364653.942319] --> nfs_get_client(192.168.2.100,v4)
[364653.942326] NFS: get client cookie (0xffff880099f63c00/0xffff8802099b90a0)
[364654.109249] nfs_callback_create_svc: service created
[364654.109254] NFS: create per-net callback data; net=ffffffff81865400
[364654.109280] NFS: Callback listener port = 56756 (af 2, net ffffffff81865400)
[364654.109292] NFS: Callback listener port = 47890 (af 10, net ffffffff81865400)
[364654.109600] nfs_callback_up: service started
[364654.109605] NFS: nfs4_discover_server_trunking: testing '192.168.2.100'
[364654.109612] NFS call setclientid auth=UNIX, 'Linux NFSv4.0 10.0.2.35/192.168.2.100 tcp'
[364654.180335] NFS reply setclientid: 0
[364654.180343] NFS call setclientid_confirm auth=UNIX, (client ID 7c7eed5002000000)
[364654.256157] decode_attr_lease_time: file size=90
[364654.256160] decode_attr_maxfilesize: maxfilesize=0
[364654.256162] decode_attr_maxread: maxread=1024
[364654.256163] decode_attr_maxwrite: maxwrite=1024
[364654.256164] decode_attr_time_delta: time_delta=0 0
[364654.256166] decode_attr_pnfstype: bitmap is 0
[364654.256167] decode_attr_layout_blksize: bitmap is 0
[364654.256169] decode_fsinfo: xdr returned 0!
[364654.256176] NFS reply setclientid_confirm: 0
[364654.256178] --> nfs_put_client({2})
[364654.256180] NFS: <-- nfs40_walk_client_list using nfs_client = ffff880099f63c00 ({1})
[364654.256183] nfs4_schedule_state_renewal: requeueing work. Lease period = 60
[364654.256186] NFS: nfs4_discover_server_trunking: status = 0
[364654.256188] <-- nfs4_set_client() = 0 [new ffff880099f63c00]
[364654.256214] <-- nfs4_init_server() = 0
[364654.256216] --> nfs4_get_rootfh()
[364654.314209] decode_attr_type: type=040000
[364654.314213] decode_attr_change: change attribute=5831456116311064576
[364654.314215] decode_attr_size: file size=4096
[364654.314217] decode_attr_fsid: fsid=(0x0/0x0)
[364654.314218] decode_attr_fileid: fileid=2
[364654.314221] decode_attr_fs_locations: fs_locations done, error = 0
[364654.314222] decode_attr_mode: file mode=0755
[364654.314224] decode_attr_nlink: nlink=28
[364654.314227] decode_attr_owner: uid=0
[364654.314229] decode_attr_group: gid=0
[364654.314230] decode_attr_rdev: rdev=(0x0:0x0)
[364654.314232] decode_attr_space_used: space used=4096
[364654.314234] decode_attr_time_access: atime=1357741696
[364654.314236] decode_attr_time_metadata: ctime=1357741681
[364654.314237] decode_attr_time_modify: mtime=1357741681
[364654.314239] decode_attr_mounted_on_fileid: fileid=0
[364654.314240] decode_getfattr_attrs: xdr returned 0
[364654.314243] decode_getfattr_generic: xdr returned 0
[364654.378213] decode_attr_supported: bitmask=fdffafff:00f9be3e:00000000
[364654.378218] decode_attr_fh_expire_type: expire type=0x0
[364654.378220] decode_attr_link_support: link support=true
[364654.378221] decode_attr_symlink_support: symlink support=true
[364654.378223] decode_attr_aclsupport: ACLs supported=0
[364654.378225] decode_server_caps: xdr returned 0!
[364654.447161] decode_attr_lease_time: file size=90
[364654.447166] decode_attr_maxfilesize: maxfilesize=18446744073709551615
[364654.447168] decode_attr_maxread: maxread=1048576
[364654.447170] decode_attr_maxwrite: maxwrite=1048576
[364654.447173] decode_attr_time_delta: time_delta=1 0
[364654.447175] decode_attr_pnfstype: bitmap is 0
[364654.447177] decode_attr_layout_blksize: bitmap is 0
[364654.447179] decode_fsinfo: xdr returned 0!
[364654.447188] <-- nfs4_get_rootfh() = 0
[364654.447190] Server FSID: 0:0
[364654.447192] Mount FH: 8
[364654.447194] --> nfs_probe_fsinfo()
[364654.521091] decode_attr_supported: bitmask=fdffafff:00f9be3e:00000000
[364654.521094] decode_attr_fh_expire_type: expire type=0x0
[364654.521096] decode_attr_link_support: link support=true
[364654.521098] decode_attr_symlink_support: symlink support=true
[364654.521099] decode_attr_aclsupport: ACLs supported=0
[364654.521101] decode_server_caps: xdr returned 0!
[364654.583056] decode_attr_lease_time: file size=90
[364654.583058] decode_attr_maxfilesize: maxfilesize=18446744073709551615
[364654.583060] decode_attr_maxread: maxread=1048576
[364654.583061] decode_attr_maxwrite: maxwrite=1048576
[364654.583063] decode_attr_time_delta: time_delta=1 0
[364654.583064] decode_attr_pnfstype: bitmap is 0
[364654.583066] decode_attr_layout_blksize: bitmap is 0
[364654.583067] decode_fsinfo: xdr returned 0!
[364654.658078] decode_attr_maxlink: maxlink=255
[364654.658082] decode_attr_maxname: maxname=255
[364654.658083] decode_pathconf: xdr returned 0!
[364654.658090] <-- nfs_probe_fsinfo() = 0
[364654.658093] <-- nfs4_create_server() = ffff880209d86800
[364654.658183] NFS: get superblock cookie (0xffff880209d86800/0xffff880211934690)
[364654.723023] decode_attr_supported: bitmask=fdffafff:00f9be3e:00000000
[364654.723026] decode_attr_fh_expire_type: expire type=0x0
[364654.723028] decode_attr_link_support: link support=true
[364654.723030] decode_attr_symlink_support: symlink support=true
[364654.723031] decode_attr_aclsupport: ACLs supported=0
[364654.723033] decode_server_caps: xdr returned 0!
[364654.801009] decode_attr_type: type=040000
[364654.801013] decode_attr_change: change attribute=5831456116311064576
[364654.801015] decode_attr_size: file size=4096
[364654.801016] decode_attr_fsid: fsid=(0x0/0x0)
[364654.801018] decode_attr_fileid: fileid=2
[364654.801020] decode_attr_fs_locations: fs_locations done, error = 0
[364654.801022] decode_attr_mode: file mode=0755
[364654.801024] decode_attr_nlink: nlink=28
[364654.801027] decode_attr_owner: uid=0
[364654.801028] decode_attr_group: gid=0
[364654.801030] decode_attr_rdev: rdev=(0x0:0x0)
[364654.801032] decode_attr_space_used: space used=4096
[364654.801034] decode_attr_time_access: atime=1357741696
[364654.801035] decode_attr_time_metadata: ctime=1357741681
[364654.801037] decode_attr_time_modify: mtime=1357741681
[364654.801038] decode_attr_mounted_on_fileid: fileid=0
[364654.801040] decode_getfattr_attrs: xdr returned 0
[364654.801042] decode_getfattr_generic: xdr returned 0
[364654.801056] NFS: nfs_fhget(0:26/2 fh_crc=0x62d40c52 ct=1)
[364654.864173] decode_attr_type: type=00
[364654.864177] decode_attr_change: change attribute=5831456116311064576
[364654.864179] decode_attr_size: file size=4096
[364654.864180] decode_attr_fsid: fsid=(0x0/0x0)
[364654.864182] decode_attr_fileid: fileid=0
[364654.864184] decode_attr_fs_locations: fs_locations done, error = 0
[364654.864186] decode_attr_mode: file mode=00
[364654.864187] decode_attr_nlink: nlink=1
[364654.864189] decode_attr_owner: uid=-2
[364654.864191] decode_attr_group: gid=-2
[364654.864192] decode_attr_rdev: rdev=(0x0:0x0)
[364654.864194] decode_attr_space_used: space used=0
[364654.864196] decode_attr_time_access: atime=0
[364654.864197] decode_attr_time_metadata: ctime=1357741681
[364654.864199] decode_attr_time_modify: mtime=1357741681
[364654.864201] decode_attr_mounted_on_fileid: fileid=0
[364654.864202] decode_getfattr_attrs: xdr returned 0
[364654.864204] decode_getfattr_generic: xdr returned 0
[364654.864213] NFS: nfs_update_inode(0:26/2 fh_crc=0x62d40c52 ct=2 info=0x26040)
[364654.864218] NFS: permission(0:26/2), mask=0x1, res=0
[364654.864222] NFS: permission(0:26/2), mask=0x1, res=0
[364654.864226] NFS: lookup(/home)
[364654.864229] NFS call lookup home
[364654.941877] decode_attr_type: type=040000
[364654.941881] decode_attr_change: change attribute=5787575346372492205
[364654.941883] decode_attr_size: file size=4096
[364654.941885] decode_attr_fsid: fsid=(0xdb103cf865ee4fc9/0x80976379169865f6)
[364654.941887] decode_attr_fileid: fileid=2
[364654.941889] decode_attr_fs_locations: fs_locations done, error = 0
[364654.941891] decode_attr_mode: file mode=0755
[364654.941892] decode_attr_nlink: nlink=7
[364654.941894] decode_attr_owner: uid=0
[364654.941896] decode_attr_group: gid=0
[364654.941898] decode_attr_rdev: rdev=(0x0:0x0)
[364654.941900] decode_attr_space_used: space used=4096
[364654.941901] decode_attr_time_access: atime=1346069707
[364654.941903] decode_attr_time_metadata: ctime=1347524893
[364654.941905] decode_attr_time_modify: mtime=1347524893
[364654.941906] decode_attr_mounted_on_fileid: fileid=0
[364654.941908] decode_getfattr_attrs: xdr returned 0
[364654.941910] decode_getfattr_generic: xdr returned 0
[364654.941916] NFS reply lookup: 0
[364654.941923] NFS: nfs_fhget(0:26/2 fh_crc=0x58dab32e ct=1)
[364654.941927] --> nfs_d_automount()
[364654.941930] nfs_d_automount: enter
[364654.941954] NFS call lookup home
[364655.015886] decode_attr_type: type=040000
[364655.015890] decode_attr_change: change attribute=5787575346372492205
[364655.015892] decode_attr_size: file size=4096
[364655.015894] decode_attr_fsid: fsid=(0xdb103cf865ee4fc9/0x80976379169865f6)
[364655.015895] decode_attr_fileid: fileid=2
[364655.015897] decode_attr_fs_locations: fs_locations done, error = 0
[364655.015899] decode_attr_mode: file mode=0755
[364655.015901] decode_attr_nlink: nlink=7
[364655.015903] decode_attr_owner: uid=0
[364655.015904] decode_attr_group: gid=0
[364655.015906] decode_attr_rdev: rdev=(0x0:0x0)
[364655.015908] decode_attr_space_used: space used=4096
[364655.015910] decode_attr_time_access: atime=1346069707
[364655.015911] decode_attr_time_metadata: ctime=1347524893
[364655.015913] decode_attr_time_modify: mtime=1347524893
[364655.015915] decode_attr_mounted_on_fileid: fileid=0
[364655.015916] decode_getfattr_attrs: xdr returned 0
[364655.015918] decode_getfattr_generic: xdr returned 0
[364655.015924] NFS reply lookup: 0
[364655.015928] --> nfs_do_submount()
[364655.015930] nfs_do_submount: submounting on /home
[364655.015947] --> nfs_xdev_mount_common()
[364655.015949] --> nfs_clone_server(,db103cf865ee4fc9:80976379169865f6,)
[364655.015986] --> nfs_probe_fsinfo()
[364655.085984] nfs_probe_fsinfo: error = 116
[364655.085988] --> nfs_free_server()
[364655.107578] --> nfs_put_client({2})
[364655.107597] <-- nfs_free_server()
[364655.107599] <-- nfs_clone_server() = error -116
[364655.107600] <-- nfs_xdev_mount_common() = -116 [error]
[364655.107607] nfs_do_submount: done
[364655.107609] <-- nfs_do_submount() = fffffffffffffff4
[364655.107619] <-- nfs_d_automount(): error -12
[364655.107622] NFS: dentry_delete(/home, 2008c)
[364655.107739] NFS: clear cookie (0xffff8800b0163468/0x (null))
[364655.107742] NFS: clear cookie (0xffff8800b0163870/0x (null))
[364655.107826] NFS: releasing superblock cookie (0xffff880209d86800/0xffff880211934690)
[364655.107829] --> nfs_free_server()
[364655.107874] --> nfs_put_client({1})
[364655.107881] NFS: destroy per-net callback data; net=ffffffff81865400
[364655.107960] nfs_callback_down: service stopped
[364655.107972] nfs_callback_down: service destroyed
[364655.107979] --> nfs_free_client(4)
[364655.107981] NFS: releasing client cookie (0xffff880099f63c00/0xffff8802099b90a0)
[364655.108012] <-- nfs_free_client()
[364655.108028] <-- nfs_free_server()
[364655.108041] <-- nfs4_try_mount() = -12 [error]
On Thursday 03 of January 2013 09:42:01 Steve Dickson wrote:
>
> On 03/01/13 04:27, Paweł Sikora wrote:
> > Hi,
> >
> > with the latest nfs-1.2.7/kernel-3.7.1 tools i've noticed an error during autofs mounting.
> > reduced testcase shows that mount.nfs with 'vers=4' has a problem:
> >
> > [root@chufu ~]# mount.nfs -v -o vers=4 192.168.2.100:/home/atest/farm-local /mnt
> > mount.nfs: timeout set for Thu Jan 3 10:22:00 2013
> > mount.nfs: trying text-based options 'vers=4,addr=192.168.2.100,clientaddr=192.168.2.103'
> > mount.nfs: mount(2): Cannot allocate memory
> > mount.nfs: Cannot allocate memory
> >
> > while the vers=3 works fine:
> >
> > [root@chufu ~]# mount.nfs -v -o vers=3 192.168.2.100:/home/atest/farm-local /mnt
> > mount.nfs: timeout set for Thu Jan 3 10:22:04 2013
> > mount.nfs: trying text-based options 'vers=3,addr=192.168.2.100'
> > mount.nfs: prog 100003, trying vers=3, prot=6
> > mount.nfs: trying 192.168.2.100 prog 100003 vers 3 prot TCP port 2049
> > mount.nfs: prog 100005, trying vers=3, prot=17
> > mount.nfs: trying 192.168.2.100 prog 100005 vers 3 prot UDP port 42412
> >
> > no obvious errors in logs on nfs server/client side :(
> > i can provide more info if you need to diagnose this issue.
>
> Please set the kernel debugging with 'rpcdebug -m nfs -s mount' then post the out put found in /var/log/messages.
>
rpcdebug can't find the /proc/sys/sunrpc/nfs_debug file in my system. how can i enable it?
On Thursday 03 of January 2013 09:42:01 Steve Dickson wrote:
>
> On 03/01/13 04:27, Paweł Sikora wrote:
> > Hi,
> >
> > with the latest nfs-1.2.7/kernel-3.7.1 tools i've noticed an error during autofs mounting.
> > reduced testcase shows that mount.nfs with 'vers=4' has a problem:
> >
> > [root@chufu ~]# mount.nfs -v -o vers=4 192.168.2.100:/home/atest/farm-local /mnt
> > mount.nfs: timeout set for Thu Jan 3 10:22:00 2013
> > mount.nfs: trying text-based options 'vers=4,addr=192.168.2.100,clientaddr=192.168.2.103'
> > mount.nfs: mount(2): Cannot allocate memory
> > mount.nfs: Cannot allocate memory
> >
> > while the vers=3 works fine:
> >
> > [root@chufu ~]# mount.nfs -v -o vers=3 192.168.2.100:/home/atest/farm-local /mnt
> > mount.nfs: timeout set for Thu Jan 3 10:22:04 2013
> > mount.nfs: trying text-based options 'vers=3,addr=192.168.2.100'
> > mount.nfs: prog 100003, trying vers=3, prot=6
> > mount.nfs: trying 192.168.2.100 prog 100003 vers 3 prot TCP port 2049
> > mount.nfs: prog 100005, trying vers=3, prot=17
> > mount.nfs: trying 192.168.2.100 prog 100005 vers 3 prot UDP port 42412
> >
> > no obvious errors in logs on nfs server/client side :(
> > i can provide more info if you need to diagnose this issue.
>
> Please set the kernel debugging with 'rpcdebug -m nfs -s mount' then post the out put found in /var/log/messages.
[root@pawels ~]# mount.nfs -v -o vers=4 192.168.2.100:/home/atest/farm-local /mnt
mount.nfs: timeout set for Sat Jan 5 11:08:42 2013
mount.nfs: trying text-based options 'vers=4,addr=192.168.2.100,clientaddr=10.0.2.35'
mount.nfs: mount(2): Cannot allocate memory
mount.nfs: Cannot allocate memory
[root@pawels ~]# dmesg|tail
[ 4187.654183] NFS: nfs mount opts='vers=4,addr=192.168.2.100,clientaddr=10.0.2.35'
[ 4187.654188] NFS: parsing nfs mount option 'vers=4'
[ 4187.654193] NFS: parsing nfs mount option 'addr=192.168.2.100'
[ 4187.654198] NFS: parsing nfs mount option 'clientaddr=10.0.2.35'
[ 4187.654204] NFS: MNTPATH: '/home/atest/farm-local'
[ 4187.654206] --> nfs4_try_mount()
[ 4187.975255] <-- nfs4_try_mount() = -12 [error]
On 03/01/13 04:27, Paweł Sikora wrote:
> Hi,
>
> with the latest nfs-1.2.7/kernel-3.7.1 tools i've noticed an error during autofs mounting.
> reduced testcase shows that mount.nfs with 'vers=4' has a problem:
>
> [root@chufu ~]# mount.nfs -v -o vers=4 192.168.2.100:/home/atest/farm-local /mnt
> mount.nfs: timeout set for Thu Jan 3 10:22:00 2013
> mount.nfs: trying text-based options 'vers=4,addr=192.168.2.100,clientaddr=192.168.2.103'
> mount.nfs: mount(2): Cannot allocate memory
> mount.nfs: Cannot allocate memory
>
> while the vers=3 works fine:
>
> [root@chufu ~]# mount.nfs -v -o vers=3 192.168.2.100:/home/atest/farm-local /mnt
> mount.nfs: timeout set for Thu Jan 3 10:22:04 2013
> mount.nfs: trying text-based options 'vers=3,addr=192.168.2.100'
> mount.nfs: prog 100003, trying vers=3, prot=6
> mount.nfs: trying 192.168.2.100 prog 100003 vers 3 prot TCP port 2049
> mount.nfs: prog 100005, trying vers=3, prot=17
> mount.nfs: trying 192.168.2.100 prog 100005 vers 3 prot UDP port 42412
>
> no obvious errors in logs on nfs server/client side :(
> i can provide more info if you need to diagnose this issue.
Please set the kernel debugging with 'rpcdebug -m nfs -s mount' then post the out put found in /var/log/messages.
steved.
On Wednesday 09 of January 2013 18:44:50 Paweł Sikora wrote:
> On Monday 07 of January 2013 09:47:09 Steve Dickson wrote:
> >
> > On 05/01/13 05:08, Paweł Sikora wrote:
> > > On Thursday 03 of January 2013 09:42:01 Steve Dickson wrote:
> > >>
> > >> On 03/01/13 04:27, Paweł Sikora wrote:
> > >>> Hi,
> > >>>
> > >>> with the latest nfs-1.2.7/kernel-3.7.1 tools i've noticed an error during autofs mounting.
> > >>> reduced testcase shows that mount.nfs with 'vers=4' has a problem:
> > >>>
> > >>> [root@chufu ~]# mount.nfs -v -o vers=4 192.168.2.100:/home/atest/farm-local /mnt
> > >>> mount.nfs: timeout set for Thu Jan 3 10:22:00 2013
> > >>> mount.nfs: trying text-based options 'vers=4,addr=192.168.2.100,clientaddr=192.168.2.103'
> > >>> mount.nfs: mount(2): Cannot allocate memory
> > >>> mount.nfs: Cannot allocate memory
> > >>>
> > >>> while the vers=3 works fine:
> > >>>
> > >>> [root@chufu ~]# mount.nfs -v -o vers=3 192.168.2.100:/home/atest/farm-local /mnt
> > >>> mount.nfs: timeout set for Thu Jan 3 10:22:04 2013
> > >>> mount.nfs: trying text-based options 'vers=3,addr=192.168.2.100'
> > >>> mount.nfs: prog 100003, trying vers=3, prot=6
> > >>> mount.nfs: trying 192.168.2.100 prog 100003 vers 3 prot TCP port 2049
> > >>> mount.nfs: prog 100005, trying vers=3, prot=17
> > >>> mount.nfs: trying 192.168.2.100 prog 100005 vers 3 prot UDP port 42412
> > >>>
> > >>> no obvious errors in logs on nfs server/client side :(
> > >>> i can provide more info if you need to diagnose this issue.
> > >>
> > >> Please set the kernel debugging with 'rpcdebug -m nfs -s mount' then post the out put found in /var/log/messages.
> > >
> > > [root@pawels ~]# mount.nfs -v -o vers=4 192.168.2.100:/home/atest/farm-local /mnt
> > >
> > > mount.nfs: timeout set for Sat Jan 5 11:08:42 2013
> > > mount.nfs: trying text-based options 'vers=4,addr=192.168.2.100,clientaddr=10.0.2.35'
> > > mount.nfs: mount(2): Cannot allocate memory
> > > mount.nfs: Cannot allocate memory
> > >
> > > [root@pawels ~]# dmesg|tail
> > >
> > > [ 4187.654183] NFS: nfs mount opts='vers=4,addr=192.168.2.100,clientaddr=10.0.2.35'
> > > [ 4187.654188] NFS: parsing nfs mount option 'vers=4'
> > > [ 4187.654193] NFS: parsing nfs mount option 'addr=192.168.2.100'
> > > [ 4187.654198] NFS: parsing nfs mount option 'clientaddr=10.0.2.35'
> > > [ 4187.654204] NFS: MNTPATH: '/home/atest/farm-local'
> > > [ 4187.654206] --> nfs4_try_mount()
> > > [ 4187.975255] <-- nfs4_try_mount() = -12 [error]
> > >
> > Hmm... it appears to me that the kernel modules are not be loaded...
> > What does 'lsmod | grep nfs' show, anything?
> >
> > steved.
>
> in fact, all modules are automatically loaded by kernel. better log attached.
with forced vers=3 the mount fails sometimes too :(
i've no idea where's the problem :(
# mount.nfs -v nexus:/R10 /mnt -o "rw,soft,vers=3"
mount.nfs: timeout set for Wed Jan 16 19:56:43 2013
mount.nfs: trying text-based options 'soft,vers=3,addr=10.0.2.28'
mount.nfs: prog 100003, trying vers=3, prot=6
mount.nfs: trying 10.0.2.28 prog 100003 vers 3 prot TCP port 2049
mount.nfs: prog 100005, trying vers=3, prot=17
mount.nfs: trying 10.0.2.28 prog 100005 vers 3 prot UDP port 50252
mount.nfs: mount(2): Stale NFS file handle
^C
[259176.973751] NFS: nfs mount opts='soft,addr=10.0.2.28,vers=3,proto=tcp,mountvers=3,mountproto=udp,mountport=50252'
[259176.973757] NFS: parsing nfs mount option 'soft'
[259176.973759] NFS: parsing nfs mount option 'addr=10.0.2.28'
[259176.973765] NFS: parsing nfs mount option 'vers=3'
[259176.973769] NFS: parsing nfs mount option 'proto=tcp'
[259176.973772] NFS: parsing nfs mount option 'mountvers=3'
[259176.973776] NFS: parsing nfs mount option 'mountproto=udp'
[259176.973779] NFS: parsing nfs mount option 'mountport=50252'
[259176.973784] NFS: MNTPATH: '/R10'
[259176.973788] NFS: sending MNT request for nexus:/R10
[259176.974620] NFS: received 1 auth flavors
[259176.974623] NFS: auth flavor[0]: 1
[259176.974640] NFS: MNT request succeeded
[259176.974643] NFS: using auth flavor 1
[259176.974688] --> nfs_init_server()
[259176.974691] --> nfs_get_client(nexus,v3)
[259176.974698] NFS: get client cookie (0xffff88021146f800/0xffff8800ceb06640)
[259176.975704] <-- nfs_init_server() = 0 [new ffff88021146f800]
[259176.975708] --> nfs_probe_fsinfo()
[259176.975711] NFS call fsinfo
[259176.975959] NFS reply fsinfo: -116
[259176.975963] NFS call fsinfo
[259176.976182] NFS reply fsinfo: -116
[259176.976184] nfs_probe_fsinfo: error = 116
[259176.976186] --> nfs_free_server()
[259176.976282] --> nfs_put_client({1})
[259176.976285] --> nfs_free_client(3)
[259176.976287] NFS: releasing client cookie (0xffff88021146f800/0xffff8800ceb06640)
[259176.976308] <-- nfs_free_client()
[259176.976322] <-- nfs_free_server()