mount.nfs: cannot allocate memory.

mount.nfs: cannot allocate memory.

[Paweł Sikora]

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

Re: mount.nfs: cannot allocate memory.

[Steve Dickson]

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.

Re: mount.nfs: cannot allocate memory.

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

Re: mount.nfs: cannot allocate memory.

[fanchaoting]

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 majordomo@vger.kernel.org
> More majordomo info at  http://vger.kernel.org/majordomo-info.html
> 

Re: mount.nfs: cannot allocate memory.

[Paweł Sikora]

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));
(...)

Re: mount.nfs: cannot allocate memory.

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

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

Re: mount.nfs: cannot allocate memory.

[Steve Dickson]

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.

Re: mount.nfs: cannot allocate memory.

[Paweł Sikora]

[-- Attachment #1: Type: text/plain, Size: 2661 bytes --]

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.

[-- Attachment #2: nfs.txt --]
[-- Type: text/plain, Size: 12447 bytes --]

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

Re: mount.nfs: cannot allocate memory.

[Paweł Sikora]

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

Re: mount.nfs: cannot allocate memory.

[J. Bruce Fields]

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 majordomo@vger.kernel.org
> More majordomo info at  http://vger.kernel.org/majordomo-info.html

Re: mount.nfs: cannot allocate memory.

[Paweł Sikora]

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

Re: mount.nfs: cannot allocate memory.

[J. Bruce Fields]

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.

Re: mount.nfs: cannot allocate memory.

[Paweł Sikora]

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?

Re: mount.nfs: cannot allocate memory.

[J. Bruce Fields]

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.

Re: mount.nfs: cannot allocate memory.

[Paweł Sikora]

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)

Re: mount.nfs: cannot allocate memory.

[Myklebust, Trond]

[-- Attachment #1: Type: text/plain, Size: 2266 bytes --]

On Wed, 2013-01-16 at 14:39 -0500, 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.

Yes. The ENOMEM is a red herring. It turns out that there is a bug in
nfs_xdev_mount that converts all errors from clone_server() into
ENOMEM...

The attached patch should fix it.

-- 
Trond Myklebust
Linux NFS client maintainer

NetApp
Trond.Myklebust@netapp.com
www.netapp.com

[-- Warning: decoded text below may be mangled, UTF-8 assumed --]
[-- Attachment #2: 0001-NFS-Fix-error-reporting-in-nfs_xdev_mount.patch --]
[-- Type: text/x-patch; name="0001-NFS-Fix-error-reporting-in-nfs_xdev_mount.patch", Size: 1868 bytes --]

From e718276d2a1704ac540f5037efac4ee55c2e6220 Mon Sep 17 00:00:00 2001
From: Trond Myklebust <Trond.Myklebust@netapp.com>
Date: Wed, 16 Jan 2013 15:05:44 -0500
Subject: [PATCH] NFS: Fix error reporting in nfs_xdev_mount

Currently, nfs_xdev_mount converts all errors from clone_server() to
ENOMEM. Fix that.
Also ensure that if nfs_fs_mount_common() returns an error, we
don't dprintk(0)...

Signed-off-by: Trond Myklebust <Trond.Myklebust@netapp.com>
---
 fs/nfs/super.c | 22 +++++++++-------------
 1 file changed, 9 insertions(+), 13 deletions(-)

diff --git a/fs/nfs/super.c b/fs/nfs/super.c
index 72cd2d2..befbae0 100644
--- a/fs/nfs/super.c
+++ b/fs/nfs/super.c
@@ -2540,27 +2540,23 @@ nfs_xdev_mount(struct file_system_type *fs_type, int flags,
 	struct nfs_server *server;
 	struct dentry *mntroot = ERR_PTR(-ENOMEM);
 	struct nfs_subversion *nfs_mod = NFS_SB(data->sb)->nfs_client->cl_nfs_mod;
-	int error;
 
-	dprintk("--> nfs_xdev_mount_common()\n");
+	dprintk("--> nfs_xdev_mount()\n");
 
 	mount_info.mntfh = mount_info.cloned->fh;
 
 	/* create a new volume representation */
 	server = nfs_mod->rpc_ops->clone_server(NFS_SB(data->sb), data->fh, data->fattr, data->authflavor);
-	if (IS_ERR(server)) {
-		error = PTR_ERR(server);
-		goto out_err;
-	}
 
-	mntroot = nfs_fs_mount_common(server, flags, dev_name, &mount_info, nfs_mod);
-	dprintk("<-- nfs_xdev_mount_common() = 0\n");
-out:
-	return mntroot;
+	if (IS_ERR(server))
+		mntroot = ERR_CAST(server);
+	else
+		mntroot = nfs_fs_mount_common(server, flags,
+				dev_name, &mount_info, nfs_mod);
 
-out_err:
-	dprintk("<-- nfs_xdev_mount_common() = %d [error]\n", error);
-	goto out;
+	dprintk("<-- nfs_xdev_mount() = %ld\n",
+			IS_ERR(mntroot) ? PTR_ERR(mntroot) : 0L);
+	return mntroot;
 }
 
 #if IS_ENABLED(CONFIG_NFS_V4)
-- 
1.7.11.7