mount.nfs: cannot allocate memory

mount.nfs: cannot allocate memory

[Mark Lord]

I've been seeing these messages on my AMD Fusion server
running linux-3.3.7-64bit.  Does this ring any bells for anyone else?
The system is NOT low on memory.

I'm building/installing 3.4.2 now to see if it behaves any better.


[962841.265658] mount.nfs: page allocation failure: order:4, mode:0xc0d0
[962841.265674] Pid: 32116, comm: mount.nfs Not tainted 3.3.7 #2
[962841.265680] Call Trace:
[962841.265700]  [<ffffffff81079363>] ? warn_alloc_failed+0x11a/0x12d
[962841.265713]  [<ffffffff8107b904>] ? __alloc_pages_nodemask+0x6c0/0x702
[962841.265725]  [<ffffffff8114fcb8>] ? timerqueue_del+0x53/0x63
[962841.265758]  [<ffffffff8107b9ba>] ? __get_free_pages+0x10/0x3f
[962841.265805]  [<ffffffffa01ea33d>] ? nfs_idmap_new+0x28/0xde [nfs]
[962841.265836]  [<ffffffffa01c79c9>] ? nfs4_init_client+0x74/0x12a [nfs]
[962841.265863]  [<ffffffffa01c6f3b>] ? nfs_get_client+0x337/0x476 [nfs]
[962841.265874]  [<ffffffff81087ad8>] ? pcpu_alloc+0x796/0x7ad
[962841.265885]  [<ffffffff810403f7>] ? should_resched+0x5/0x23
[962841.265913]  [<ffffffffa01c70f2>] ? nfs4_set_client+0x78/0xca [nfs]
[962841.265944]  [<ffffffffa01c7b5c>] ? nfs4_create_server+0xdd/0x208 [nfs]
[962841.265956]  [<ffffffff812c0de1>] ? _cond_resched+0x7/0x1c
[962841.265990]  [<ffffffffa01cfa3c>] ? nfs4_remote_mount+0x50/0x183 [nfs]
[962841.266007]  [<ffffffff810ab334>] ? mount_fs+0xc/0xa0
[962841.266020]  [<ffffffff810bd3fd>] ? vfs_kern_mount+0x61/0xcc
[962841.266053]  [<ffffffffa01cfc3f>] ? nfs_do_root_mount+0x89/0xaa [nfs]
[962841.266088]  [<ffffffffa01d0702>] ? nfs4_try_mount.isra.27+0x4c/0x9e [nfs]
[962841.266120]  [<ffffffffa01d1145>] ? nfs_fs_mount+0x3e9/0x5ef [nfs]
[962841.266131]  [<ffffffff8114b3bc>] ? ida_get_new_above+0x176/0x198
[962841.266147]  [<ffffffff810ab334>] ? mount_fs+0xc/0xa0
[962841.266159]  [<ffffffff810bd3fd>] ? vfs_kern_mount+0x61/0xcc
[962841.266172]  [<ffffffff810bd7f0>] ? do_kern_mount+0x49/0xd8
[962841.266182]  [<ffffffff810beec8>] ? do_mount+0x630/0x695
[962841.266191]  [<ffffffff810be80a>] ? copy_mount_options+0xc3/0x126
[962841.266201]  [<ffffffff810bf00f>] ? sys_mount+0x88/0xca
[962841.266212]  [<ffffffff812c20a2>] ? system_call_fastpath+0x16/0x1b
[962841.266219] Mem-Info:
[962841.266224] DMA per-cpu:
[962841.266230] CPU    0: hi:    0, btch:   1 usd:   0
[962841.266237] CPU    1: hi:    0, btch:   1 usd:   0
[962841.266242] DMA32 per-cpu:
[962841.266248] CPU    0: hi:  186, btch:  31 usd:   0
[962841.266255] CPU    1: hi:  186, btch:  31 usd:   0
[962841.266260] Normal per-cpu:
[962841.266266] CPU    0: hi:  186, btch:  31 usd:   0
[962841.266272] CPU    1: hi:  186, btch:  31 usd: 167
[962841.266289] active_anon:60865 inactive_anon:15547 isolated_anon:0
[962841.266293]  active_file:221296 inactive_file:1249491 isolated_file:0
[962841.266297]  unevictable:0 dirty:4156 writeback:0 unstable:0
[962841.266300]  free:47696 slab_reclaimable:325469 slab_unreclaimable:6023
[962841.266304]  mapped:8585 shmem:1955 pagetables:4954 bounce:0
[962841.266327] DMA free:15904kB min:132kB low:164kB high:196kB active_anon:0kB inactive_anon:0kB
active_file:0kB inactive_file:0kB unevictable:0kB isolated(anon):0kB isolated(file):0kB
present:15648kB mlocked:0kB dirty:0kB writeback:0kB mapped:0kB shmem:0kB slab_reclaimable:0kB
slab_unreclaimable:0kB kernel_stack:0kB pagetables:0kB unstable:0kB bounce:0kB writeback_tmp:0kB
pages_scanned:0 all_unreclaimable? yes
[962841.266344] lowmem_reserve[]: 0 2603 7628 7628
[962841.266371] DMA32 free:102056kB min:23020kB low:28772kB high:34528kB active_anon:20256kB
inactive_anon:19164kB active_file:160472kB inactive_file:1952944kB unevictable:0kB
isolated(anon):0kB isolated(file):0kB present:2666288kB mlocked:0kB dirty:5804kB writeback:0kB
mapped:8052kB shmem:4192kB slab_reclaimable:400280kB slab_unreclaimable:3080kB kernel_stack:104kB
pagetables:1400kB unstable:0kB bounce:0kB writeback_tmp:0kB pages_scanned:0 all_unreclaimable? no
[962841.266391] lowmem_reserve[]: 0 0 5024 5024
[962841.266417] Normal free:72824kB min:44424kB low:55528kB high:66636kB active_anon:223204kB
inactive_anon:43024kB active_file:724712kB inactive_file:3045020kB unevictable:0kB
isolated(anon):0kB isolated(file):0kB present:5144828kB mlocked:0kB dirty:10820kB writeback:0kB
mapped:26288kB shmem:3628kB slab_reclaimable:901596kB slab_unreclaimable:21012kB kernel_stack:2640kB
pagetables:18416kB unstable:0kB bounce:0kB writeback_tmp:0kB pages_scanned:135 all_unreclaimable? no
[962841.266438] lowmem_reserve[]: 0 0 0 0
[962841.266448] DMA: 0*4kB 0*8kB 0*16kB 1*32kB 2*64kB 1*128kB 1*256kB 0*512kB 1*1024kB 1*2048kB
3*4096kB = 15904kB
[962841.266475] DMA32: 18658*4kB 2005*8kB 437*16kB 112*32kB 13*64kB 0*128kB 0*256kB 0*512kB 0*1024kB
0*2048kB 0*4096kB = 102080kB
[962841.266501] Normal: 8194*4kB 4068*8kB 395*16kB 31*32kB 3*64kB 0*128kB 0*256kB 0*512kB 0*1024kB
0*2048kB 0*4096kB = 72824kB
[962841.266526] 1472725 total pagecache pages
[962841.266532] 0 pages in swap cache
[962841.266538] Swap cache stats: add 0, delete 0, find 0/0
[962841.266544] Free swap  = 7846908kB
[962841.266549] Total swap = 7846908kB
[962841.381943] 1994736 pages RAM
[962841.381951] 53376 pages reserved
[962841.381956] 1122458 pages shared
[962841.381961] 819713 pages non-shared

Re: mount.nfs: cannot allocate memory

[Mark Lord]

On 12-06-12 06:44 PM, Mark Lord wrote:
> I've been seeing these messages on my AMD Fusion server
> running linux-3.3.7-64bit.  Does this ring any bells for anyone else?
> The system is NOT low on memory.
> 
> I'm building/installing 3.4.2 now to see if it behaves any better.
> 
> [962841.265658] mount.nfs: page allocation failure: order:4, mode:0xc0d0
> [962841.265674] Pid: 32116, comm: mount.nfs Not tainted 3.3.7 #2
> [962841.265680] Call Trace:
> [962841.265700]  [<ffffffff81079363>] ? warn_alloc_failed+0x11a/0x12d
> [962841.265713]  [<ffffffff8107b904>] ? __alloc_pages_nodemask+0x6c0/0x702
> [962841.265725]  [<ffffffff8114fcb8>] ? timerqueue_del+0x53/0x63
> [962841.265758]  [<ffffffff8107b9ba>] ? __get_free_pages+0x10/0x3f
> [962841.265805]  [<ffffffffa01ea33d>] ? nfs_idmap_new+0x28/0xde [nfs]
> [962841.265836]  [<ffffffffa01c79c9>] ? nfs4_init_client+0x74/0x12a [nfs]
> [962841.265863]  [<ffffffffa01c6f3b>] ? nfs_get_client+0x337/0x476 [nfs]
> [962841.265874]  [<ffffffff81087ad8>] ? pcpu_alloc+0x796/0x7ad
> [962841.265885]  [<ffffffff810403f7>] ? should_resched+0x5/0x23
> [962841.265913]  [<ffffffffa01c70f2>] ? nfs4_set_client+0x78/0xca [nfs]
> [962841.265944]  [<ffffffffa01c7b5c>] ? nfs4_create_server+0xdd/0x208 [nfs]
> [962841.265956]  [<ffffffff812c0de1>] ? _cond_resched+0x7/0x1c
> [962841.265990]  [<ffffffffa01cfa3c>] ? nfs4_remote_mount+0x50/0x183 [nfs]
> [962841.266007]  [<ffffffff810ab334>] ? mount_fs+0xc/0xa0
> [962841.266020]  [<ffffffff810bd3fd>] ? vfs_kern_mount+0x61/0xcc
> [962841.266053]  [<ffffffffa01cfc3f>] ? nfs_do_root_mount+0x89/0xaa [nfs]
> [962841.266088]  [<ffffffffa01d0702>] ? nfs4_try_mount.isra.27+0x4c/0x9e [nfs]
> [962841.266120]  [<ffffffffa01d1145>] ? nfs_fs_mount+0x3e9/0x5ef [nfs]
> [962841.266131]  [<ffffffff8114b3bc>] ? ida_get_new_above+0x176/0x198
> [962841.266147]  [<ffffffff810ab334>] ? mount_fs+0xc/0xa0
> [962841.266159]  [<ffffffff810bd3fd>] ? vfs_kern_mount+0x61/0xcc
> [962841.266172]  [<ffffffff810bd7f0>] ? do_kern_mount+0x49/0xd8
> [962841.266182]  [<ffffffff810beec8>] ? do_mount+0x630/0x695
> [962841.266191]  [<ffffffff810be80a>] ? copy_mount_options+0xc3/0x126
> [962841.266201]  [<ffffffff810bf00f>] ? sys_mount+0x88/0xca
> [962841.266212]  [<ffffffff812c20a2>] ? system_call_fastpath+0x16/0x1b
> [962841.266219] Mem-Info:
> [962841.266224] DMA per-cpu:
> [962841.266230] CPU    0: hi:    0, btch:   1 usd:   0
> [962841.266237] CPU    1: hi:    0, btch:   1 usd:   0
> [962841.266242] DMA32 per-cpu:
> [962841.266248] CPU    0: hi:  186, btch:  31 usd:   0
> [962841.266255] CPU    1: hi:  186, btch:  31 usd:   0
> [962841.266260] Normal per-cpu:
> [962841.266266] CPU    0: hi:  186, btch:  31 usd:   0
> [962841.266272] CPU    1: hi:  186, btch:  31 usd: 167
> [962841.266289] active_anon:60865 inactive_anon:15547 isolated_anon:0
> [962841.266293]  active_file:221296 inactive_file:1249491 isolated_file:0
> [962841.266297]  unevictable:0 dirty:4156 writeback:0 unstable:0
> [962841.266300]  free:47696 slab_reclaimable:325469 slab_unreclaimable:6023
> [962841.266304]  mapped:8585 shmem:1955 pagetables:4954 bounce:0
> [962841.266327] DMA free:15904kB min:132kB low:164kB high:196kB active_anon:0kB inactive_anon:0kB
> active_file:0kB inactive_file:0kB unevictable:0kB isolated(anon):0kB isolated(file):0kB
> present:15648kB mlocked:0kB dirty:0kB writeback:0kB mapped:0kB shmem:0kB slab_reclaimable:0kB
> slab_unreclaimable:0kB kernel_stack:0kB pagetables:0kB unstable:0kB bounce:0kB writeback_tmp:0kB
> pages_scanned:0 all_unreclaimable? yes
> [962841.266344] lowmem_reserve[]: 0 2603 7628 7628
> [962841.266371] DMA32 free:102056kB min:23020kB low:28772kB high:34528kB active_anon:20256kB
> inactive_anon:19164kB active_file:160472kB inactive_file:1952944kB unevictable:0kB
> isolated(anon):0kB isolated(file):0kB present:2666288kB mlocked:0kB dirty:5804kB writeback:0kB
> mapped:8052kB shmem:4192kB slab_reclaimable:400280kB slab_unreclaimable:3080kB kernel_stack:104kB
> pagetables:1400kB unstable:0kB bounce:0kB writeback_tmp:0kB pages_scanned:0 all_unreclaimable? no
> [962841.266391] lowmem_reserve[]: 0 0 5024 5024
> [962841.266417] Normal free:72824kB min:44424kB low:55528kB high:66636kB active_anon:223204kB
> inactive_anon:43024kB active_file:724712kB inactive_file:3045020kB unevictable:0kB
> isolated(anon):0kB isolated(file):0kB present:5144828kB mlocked:0kB dirty:10820kB writeback:0kB
> mapped:26288kB shmem:3628kB slab_reclaimable:901596kB slab_unreclaimable:21012kB kernel_stack:2640kB
> pagetables:18416kB unstable:0kB bounce:0kB writeback_tmp:0kB pages_scanned:135 all_unreclaimable? no
> [962841.266438] lowmem_reserve[]: 0 0 0 0
> [962841.266448] DMA: 0*4kB 0*8kB 0*16kB 1*32kB 2*64kB 1*128kB 1*256kB 0*512kB 1*1024kB 1*2048kB
> 3*4096kB = 15904kB
> [962841.266475] DMA32: 18658*4kB 2005*8kB 437*16kB 112*32kB 13*64kB 0*128kB 0*256kB 0*512kB 0*1024kB
> 0*2048kB 0*4096kB = 102080kB
> [962841.266501] Normal: 8194*4kB 4068*8kB 395*16kB 31*32kB 3*64kB 0*128kB 0*256kB 0*512kB 0*1024kB
> 0*2048kB 0*4096kB = 72824kB
> [962841.266526] 1472725 total pagecache pages
> [962841.266532] 0 pages in swap cache
> [962841.266538] Swap cache stats: add 0, delete 0, find 0/0
> [962841.266544] Free swap  = 7846908kB
> [962841.266549] Total swap = 7846908kB
> [962841.381943] 1994736 pages RAM
> [962841.381951] 53376 pages reserved
> [962841.381956] 1122458 pages shared
> [962841.381961] 819713 pages non-shared


Looks like an old bug, perhaps:
https://bugzilla.redhat.com/show_bug.cgi?id=593035
https://bugzilla.redhat.com/show_bug.cgi?id=728003

I wonder what the underlying cause is?
And I also wonder if the NFS code should be more clever
about handing order-4 allocation failures.

Re: mount.nfs: cannot allocate memory

[Mark Lord]

Adding Ben Hutchings to CC: as he seems to have looked into this before.

> On 12-06-12 06:44 PM, Mark Lord wrote:
>> I've been seeing these messages on my AMD Fusion server
>> running linux-3.3.7-64bit.  Does this ring any bells for anyone else?
>> The system is NOT low on memory.
>>
>> I'm building/installing 3.4.2 now to see if it behaves any better.
>>
>> [962841.265658] mount.nfs: page allocation failure: order:4, mode:0xc0d0
>> [962841.265674] Pid: 32116, comm: mount.nfs Not tainted 3.3.7 #2
>> [962841.265680] Call Trace:
>> [962841.265700]  [<ffffffff81079363>] ? warn_alloc_failed+0x11a/0x12d
>> [962841.265713]  [<ffffffff8107b904>] ? __alloc_pages_nodemask+0x6c0/0x702
>> [962841.265725]  [<ffffffff8114fcb8>] ? timerqueue_del+0x53/0x63
>> [962841.265758]  [<ffffffff8107b9ba>] ? __get_free_pages+0x10/0x3f
>> [962841.265805]  [<ffffffffa01ea33d>] ? nfs_idmap_new+0x28/0xde [nfs]
>> [962841.265836]  [<ffffffffa01c79c9>] ? nfs4_init_client+0x74/0x12a [nfs]
>> [962841.265863]  [<ffffffffa01c6f3b>] ? nfs_get_client+0x337/0x476 [nfs]
>> [962841.265874]  [<ffffffff81087ad8>] ? pcpu_alloc+0x796/0x7ad
>> [962841.265885]  [<ffffffff810403f7>] ? should_resched+0x5/0x23
>> [962841.265913]  [<ffffffffa01c70f2>] ? nfs4_set_client+0x78/0xca [nfs]
>> [962841.265944]  [<ffffffffa01c7b5c>] ? nfs4_create_server+0xdd/0x208 [nfs]
>> [962841.265956]  [<ffffffff812c0de1>] ? _cond_resched+0x7/0x1c
>> [962841.265990]  [<ffffffffa01cfa3c>] ? nfs4_remote_mount+0x50/0x183 [nfs]
>> [962841.266007]  [<ffffffff810ab334>] ? mount_fs+0xc/0xa0
>> [962841.266020]  [<ffffffff810bd3fd>] ? vfs_kern_mount+0x61/0xcc
>> [962841.266053]  [<ffffffffa01cfc3f>] ? nfs_do_root_mount+0x89/0xaa [nfs]
>> [962841.266088]  [<ffffffffa01d0702>] ? nfs4_try_mount.isra.27+0x4c/0x9e [nfs]
>> [962841.266120]  [<ffffffffa01d1145>] ? nfs_fs_mount+0x3e9/0x5ef [nfs]
>> [962841.266131]  [<ffffffff8114b3bc>] ? ida_get_new_above+0x176/0x198
>> [962841.266147]  [<ffffffff810ab334>] ? mount_fs+0xc/0xa0
>> [962841.266159]  [<ffffffff810bd3fd>] ? vfs_kern_mount+0x61/0xcc
>> [962841.266172]  [<ffffffff810bd7f0>] ? do_kern_mount+0x49/0xd8
>> [962841.266182]  [<ffffffff810beec8>] ? do_mount+0x630/0x695
>> [962841.266191]  [<ffffffff810be80a>] ? copy_mount_options+0xc3/0x126
>> [962841.266201]  [<ffffffff810bf00f>] ? sys_mount+0x88/0xca
>> [962841.266212]  [<ffffffff812c20a2>] ? system_call_fastpath+0x16/0x1b
>> [962841.266219] Mem-Info:
>> [962841.266224] DMA per-cpu:
>> [962841.266230] CPU    0: hi:    0, btch:   1 usd:   0
>> [962841.266237] CPU    1: hi:    0, btch:   1 usd:   0
>> [962841.266242] DMA32 per-cpu:
>> [962841.266248] CPU    0: hi:  186, btch:  31 usd:   0
>> [962841.266255] CPU    1: hi:  186, btch:  31 usd:   0
>> [962841.266260] Normal per-cpu:
>> [962841.266266] CPU    0: hi:  186, btch:  31 usd:   0
>> [962841.266272] CPU    1: hi:  186, btch:  31 usd: 167
>> [962841.266289] active_anon:60865 inactive_anon:15547 isolated_anon:0
>> [962841.266293]  active_file:221296 inactive_file:1249491 isolated_file:0
>> [962841.266297]  unevictable:0 dirty:4156 writeback:0 unstable:0
>> [962841.266300]  free:47696 slab_reclaimable:325469 slab_unreclaimable:6023
>> [962841.266304]  mapped:8585 shmem:1955 pagetables:4954 bounce:0
>> [962841.266327] DMA free:15904kB min:132kB low:164kB high:196kB active_anon:0kB inactive_anon:0kB
>> active_file:0kB inactive_file:0kB unevictable:0kB isolated(anon):0kB isolated(file):0kB
>> present:15648kB mlocked:0kB dirty:0kB writeback:0kB mapped:0kB shmem:0kB slab_reclaimable:0kB
>> slab_unreclaimable:0kB kernel_stack:0kB pagetables:0kB unstable:0kB bounce:0kB writeback_tmp:0kB
>> pages_scanned:0 all_unreclaimable? yes
>> [962841.266344] lowmem_reserve[]: 0 2603 7628 7628
>> [962841.266371] DMA32 free:102056kB min:23020kB low:28772kB high:34528kB active_anon:20256kB
>> inactive_anon:19164kB active_file:160472kB inactive_file:1952944kB unevictable:0kB
>> isolated(anon):0kB isolated(file):0kB present:2666288kB mlocked:0kB dirty:5804kB writeback:0kB
>> mapped:8052kB shmem:4192kB slab_reclaimable:400280kB slab_unreclaimable:3080kB kernel_stack:104kB
>> pagetables:1400kB unstable:0kB bounce:0kB writeback_tmp:0kB pages_scanned:0 all_unreclaimable? no
>> [962841.266391] lowmem_reserve[]: 0 0 5024 5024
>> [962841.266417] Normal free:72824kB min:44424kB low:55528kB high:66636kB active_anon:223204kB
>> inactive_anon:43024kB active_file:724712kB inactive_file:3045020kB unevictable:0kB
>> isolated(anon):0kB isolated(file):0kB present:5144828kB mlocked:0kB dirty:10820kB writeback:0kB
>> mapped:26288kB shmem:3628kB slab_reclaimable:901596kB slab_unreclaimable:21012kB kernel_stack:2640kB
>> pagetables:18416kB unstable:0kB bounce:0kB writeback_tmp:0kB pages_scanned:135 all_unreclaimable? no
>> [962841.266438] lowmem_reserve[]: 0 0 0 0
>> [962841.266448] DMA: 0*4kB 0*8kB 0*16kB 1*32kB 2*64kB 1*128kB 1*256kB 0*512kB 1*1024kB 1*2048kB
>> 3*4096kB = 15904kB
>> [962841.266475] DMA32: 18658*4kB 2005*8kB 437*16kB 112*32kB 13*64kB 0*128kB 0*256kB 0*512kB 0*1024kB
>> 0*2048kB 0*4096kB = 102080kB
>> [962841.266501] Normal: 8194*4kB 4068*8kB 395*16kB 31*32kB 3*64kB 0*128kB 0*256kB 0*512kB 0*1024kB
>> 0*2048kB 0*4096kB = 72824kB
>> [962841.266526] 1472725 total pagecache pages
>> [962841.266532] 0 pages in swap cache
>> [962841.266538] Swap cache stats: add 0, delete 0, find 0/0
>> [962841.266544] Free swap  = 7846908kB
>> [962841.266549] Total swap = 7846908kB
>> [962841.381943] 1994736 pages RAM
>> [962841.381951] 53376 pages reserved
>> [962841.381956] 1122458 pages shared
>> [962841.381961] 819713 pages non-shared
> 
> Looks like an old bug, perhaps:
> https://bugzilla.redhat.com/show_bug.cgi?id=593035
> https://bugzilla.redhat.com/show_bug.cgi?id=728003
> 
> I wonder what the underlying cause is?
> And I also wonder if the NFS code should be more clever
> about handing order-4 allocation failures.

More references:
http://www.mail-archive.com/debian-kernel@lists.debian.org/msg71281.html
https://bugs.launchpad.net/ubuntu/+source/linux/+bug/1004619
http://codemonkey.org.uk/2012/02/17/fedora-16-kernel-bugzilla-status-report-20120210-20120217/
https://lkml.org/lkml/2011/2/24/73

Re: mount.nfs: cannot allocate memory

[Mark Lord]

On 12-06-12 06:58 PM, Mark Lord wrote:
> Adding Ben Hutchings to CC: as he seems to have looked into this before.
> 
>> On 12-06-12 06:44 PM, Mark Lord wrote:
>>> I've been seeing these messages on my AMD Fusion server
>>> running linux-3.3.7-64bit.  Does this ring any bells for anyone else?
>>> The system is NOT low on memory.
>>>
>>> I'm building/installing 3.4.2 now to see if it behaves any better.
>>>
>>> [962841.265658] mount.nfs: page allocation failure: order:4, mode:0xc0d0
>>> [962841.265674] Pid: 32116, comm: mount.nfs Not tainted 3.3.7 #2
>>> [962841.265680] Call Trace:
>>> [962841.265700]  [<ffffffff81079363>] ? warn_alloc_failed+0x11a/0x12d
>>> [962841.265713]  [<ffffffff8107b904>] ? __alloc_pages_nodemask+0x6c0/0x702
>>> [962841.265725]  [<ffffffff8114fcb8>] ? timerqueue_del+0x53/0x63
>>> [962841.265758]  [<ffffffff8107b9ba>] ? __get_free_pages+0x10/0x3f
>>> [962841.265805]  [<ffffffffa01ea33d>] ? nfs_idmap_new+0x28/0xde [nfs]
>>> [962841.265836]  [<ffffffffa01c79c9>] ? nfs4_init_client+0x74/0x12a [nfs]
...
>> Looks like an old bug, perhaps:
>> https://bugzilla.redhat.com/show_bug.cgi?id=593035
>> https://bugzilla.redhat.com/show_bug.cgi?id=728003
>>
>> I wonder what the underlying cause is?
>> And I also wonder if the NFS code should be more clever
>> about handing order-4 allocation failures.
> 
> More references:
> http://www.mail-archive.com/debian-kernel@lists.debian.org/msg71281.html
> https://bugs.launchpad.net/ubuntu/+source/linux/+bug/1004619
> http://codemonkey.org.uk/2012/02/17/fedora-16-kernel-bugzilla-status-report-20120210-20120217/
> https://lkml.org/lkml/2011/2/24/73

Ahh.. this one seems to explain it, kind of:
   http://permalink.gmane.org/gmane.linux.nfs/41686

So in 3.3.7, I didn't have CONFIG_NFS_USE_NEW_IDMAPPER enabled,
and the kernel seems to be buggy without that.

In 3.4.2, that option has disappeared entirely,
most likely because it is now the default behaviour.  Right?

Thanks.

Re: mount.nfs: cannot allocate memory

[Dave Jones]

On Tue, Jun 12, 2012 at 06:50:46PM -0400, Mark Lord wrote:

 > Looks like an old bug, perhaps:
 > https://bugzilla.redhat.com/show_bug.cgi?id=593035
 > https://bugzilla.redhat.com/show_bug.cgi?id=728003
 > 
 > I wonder what the underlying cause is?
 > And I also wonder if the NFS code should be more clever
 > about handing order-4 allocation failures.

>From memory, I don't think we've seen new reports of this since we switched to (now dead)
CONFIG_NFS_USE_NEW_IDMAPPER=y.

	Dave

Re: mount.nfs: cannot allocate memory

[Myklebust, Trond]

[-- Warning: decoded text below may be mangled, UTF-8 assumed --]
[-- Attachment #1: Type: text/plain; charset="utf-8", Size: 2643 bytes --]

On Tue, 2012-06-12 at 19:08 -0400, Mark Lord wrote:
> On 12-06-12 06:58 PM, Mark Lord wrote:
> > Adding Ben Hutchings to CC: as he seems to have looked into this before.
> > 
> >> On 12-06-12 06:44 PM, Mark Lord wrote:
> >>> I've been seeing these messages on my AMD Fusion server
> >>> running linux-3.3.7-64bit.  Does this ring any bells for anyone else?
> >>> The system is NOT low on memory.
> >>>
> >>> I'm building/installing 3.4.2 now to see if it behaves any better.
> >>>
> >>> [962841.265658] mount.nfs: page allocation failure: order:4, mode:0xc0d0
> >>> [962841.265674] Pid: 32116, comm: mount.nfs Not tainted 3.3.7 #2
> >>> [962841.265680] Call Trace:
> >>> [962841.265700]  [<ffffffff81079363>] ? warn_alloc_failed+0x11a/0x12d
> >>> [962841.265713]  [<ffffffff8107b904>] ? __alloc_pages_nodemask+0x6c0/0x702
> >>> [962841.265725]  [<ffffffff8114fcb8>] ? timerqueue_del+0x53/0x63
> >>> [962841.265758]  [<ffffffff8107b9ba>] ? __get_free_pages+0x10/0x3f
> >>> [962841.265805]  [<ffffffffa01ea33d>] ? nfs_idmap_new+0x28/0xde [nfs]
> >>> [962841.265836]  [<ffffffffa01c79c9>] ? nfs4_init_client+0x74/0x12a [nfs]
> ...
> >> Looks like an old bug, perhaps:
> >> https://bugzilla.redhat.com/show_bug.cgi?id=593035
> >> https://bugzilla.redhat.com/show_bug.cgi?id=728003
> >>
> >> I wonder what the underlying cause is?
> >> And I also wonder if the NFS code should be more clever
> >> about handing order-4 allocation failures.
> > 
> > More references:
> > http://www.mail-archive.com/debian-kernel@lists.debian.org/msg71281.html
> > https://bugs.launchpad.net/ubuntu/+source/linux/+bug/1004619
> > http://codemonkey.org.uk/2012/02/17/fedora-16-kernel-bugzilla-status-report-20120210-20120217/
> > https://lkml.org/lkml/2011/2/24/73
> 
> Ahh.. this one seems to explain it, kind of:
>    http://permalink.gmane.org/gmane.linux.nfs/41686
> 
> So in 3.3.7, I didn't have CONFIG_NFS_USE_NEW_IDMAPPER enabled,
> and the kernel seems to be buggy without that.
> 
> In 3.4.2, that option has disappeared entirely,
> most likely because it is now the default behaviour.  Right?

Yes, but we also added some patches to Linux 3.4 in order to fix this
bug.

Please see commit d073e9b541e1ac3f52d72c3a153855d9a9ee3278 (NFSv4:
Reduce the footprint of the idmapper) and commit
685f50f9188ac1e8244d0340a9d6ea36b6136cec (NFSv4: Further reduce the
footprint of the idmapper)

Cheers
  Trond

-- 
Trond Myklebust
Linux NFS client maintainer

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

ÿôèº{.nÇ+‰·Ÿ®‰­†+%ŠËÿ±éݶ\x17¥Šwÿº{.nÇ+‰·¥Š{±þG«éÿŠ{ayº\x1dʇڙë,j\a­¢f£¢·hšïêÿ‘êçz_è®\x03(­éšŽŠÝ¢j"ú\x1a¶^[m§ÿÿ¾\a«þG«éÿ¢¸?™¨è­Ú&£ø§~á¶iO•æ¬z·švØ^\x14\x04\x1a¶^[m§ÿÿÃ\fÿ¶ìÿ¢¸?–I¥

Re: mount.nfs: cannot allocate memory

[Mark Lord]

On 12-06-12 07:28 PM, Myklebust, Trond wrote:
> On Tue, 2012-06-12 at 19:08 -0400, Mark Lord wrote:
>> On 12-06-12 06:58 PM, Mark Lord wrote:
>>> Adding Ben Hutchings to CC: as he seems to have looked into this before.
>>>
>>>> On 12-06-12 06:44 PM, Mark Lord wrote:
>>>>> I've been seeing these messages on my AMD Fusion server
>>>>> running linux-3.3.7-64bit.  Does this ring any bells for anyone else?
>>>>> The system is NOT low on memory.
>>>>>
>>>>> I'm building/installing 3.4.2 now to see if it behaves any better.
>>>>>
>>>>> [962841.265658] mount.nfs: page allocation failure: order:4, mode:0xc0d0
>>>>> [962841.265674] Pid: 32116, comm: mount.nfs Not tainted 3.3.7 #2
>>>>> [962841.265680] Call Trace:
>>>>> [962841.265700]  [<ffffffff81079363>] ? warn_alloc_failed+0x11a/0x12d
>>>>> [962841.265713]  [<ffffffff8107b904>] ? __alloc_pages_nodemask+0x6c0/0x702
>>>>> [962841.265725]  [<ffffffff8114fcb8>] ? timerqueue_del+0x53/0x63
>>>>> [962841.265758]  [<ffffffff8107b9ba>] ? __get_free_pages+0x10/0x3f
>>>>> [962841.265805]  [<ffffffffa01ea33d>] ? nfs_idmap_new+0x28/0xde [nfs]
>>>>> [962841.265836]  [<ffffffffa01c79c9>] ? nfs4_init_client+0x74/0x12a [nfs]
>> ...
>>>> Looks like an old bug, perhaps:
>>>> https://bugzilla.redhat.com/show_bug.cgi?id=593035
>>>> https://bugzilla.redhat.com/show_bug.cgi?id=728003
>>>>
>>>> I wonder what the underlying cause is?
>>>> And I also wonder if the NFS code should be more clever
>>>> about handing order-4 allocation failures.
>>>
>>> More references:
>>> http://www.mail-archive.com/debian-kernel@lists.debian.org/msg71281.html
>>> https://bugs.launchpad.net/ubuntu/+source/linux/+bug/1004619
>>> http://codemonkey.org.uk/2012/02/17/fedora-16-kernel-bugzilla-status-report-20120210-20120217/
>>> https://lkml.org/lkml/2011/2/24/73
>>
>> Ahh.. this one seems to explain it, kind of:
>>    http://permalink.gmane.org/gmane.linux.nfs/41686
>>
>> So in 3.3.7, I didn't have CONFIG_NFS_USE_NEW_IDMAPPER enabled,
>> and the kernel seems to be buggy without that.
>>
>> In 3.4.2, that option has disappeared entirely,
>> most likely because it is now the default behaviour.  Right?
> 
> Yes, but we also added some patches to Linux 3.4 in order to fix this
> bug.
> 
> Please see commit d073e9b541e1ac3f52d72c3a153855d9a9ee3278 (NFSv4:
> Reduce the footprint of the idmapper) and commit
> 685f50f9188ac1e8244d0340a9d6ea36b6136cec (NFSv4: Further reduce the
> footprint of the idmapper)

Ah, okay.  Good work, guye.

Cheers

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.

[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

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)