NETGEAR ReadyNAS

by **pkchrisjohnson** » Sun Aug 05, 2012 11:06 pm

I have a ReadyNas Ultra 4 with 3 disks. I have a USB enclosure with two disks (as one volume) plugged into the back USB port and I have FrontView set to backup one of the volumes "Backup" on my NAS nightly with an incremental backup. This was working fine until about a month ago when the backup started failing every night. The error that I get is this:

Error encountered copying data from source path ==> /USB_HDD_3/ due to unknown reason. Please see log.

I assumed that I was loosing the backup drive, and quickly ran a check of the volume using the built in tools. Some errors were found, but FrontView said that it corrected them. Backups still failed. I then assumed that there were deeper drive issues and pulled out SpinRite to run a deep analysis. 80+ hours later, no errors found after a scan of the whole spanned volume. In between, I also tried completely formatting the drive and starting from scratch with an EXT3 volume, formatted through FrontView. No dice there either. So the external USB Drive does not appear to be bad.

The backup doesn't fail immediately, either. It takes a few hours (~3) to hit the problem and then stop.

I decided to start digging in the logs. First the backup logs:

Code: Select all: Backup failed. Sun Aug 5 09:28:12 PDT 2012. Reason for failure: Error encountered copying data from source path ==> /USB_HDD_3/ due to unknown reason. Please see log.

This is the same error every time, but the logs for each of the past few days stop at different files each time. And the logs appear as though the get cut off mid line, like this example:

Code: Select all: `./Pictures/Personal/2012/2012 - 04 Paris/Paris_CJ-20120411-1833.xmp' -> `/USB_HDD_3/Pictures/Personal/2012/2012 - 04 Paris/Paris_CJ-20120411-1833.xmp' `./Pictures/Personal/2012/2012 - 04 Paris/Paris_CJ-20120408-0594.xmp' -> `/USB_HDD_3/Pictures/Personal/2012/2012 - 04 Paris/Paris_CJ-20120408-0594.xmp' `./Pictures/Personal/2012/2012 - 04 Paris/Paris_CJ-20120410-1539.JPG' -> `/USB_HDD_3/Pictures/Personal/2012/2012 - 04 Paris/Paris_CJ-20120410-1539.JPG' `./Pictures/Personal/2012/2012 - 04 Paris/Paris_CJ-20120410-1022.JPG' -> `/USB_HDD_3/Pictures/Personal/2012/2012 - 04 Paris/Paris_CJ-20120410-1022.JPG' `./Pictures/Personal/2012/2012 - 04 Paris/Paris_CJ-20120408-0552.xmp' -> `/USB_HDD_3/Pictures/Personal/2 Backup failed. Sat Aug 4 09:06:40 PDT 2012. Reason for failure: Error encountered copying data from source path ==> /USB_HDD_3/ due to unknown reason. Please see log.

So I dug in a different set of logs, the system log. What I find is that at some point around the 3 hour mark in the backup job (each and every time), something happens that generates a large amount of log information in a single second of time, and then, a few seconds later, the backup fails. This is an example of those bits from the system log:

Code: Select all: Aug 5 09:28:11 bach kernel: leafp2p invoked oom-killer: gfp_mask=0x201da, order=0, oom_adj=0, oom_score_adj=0 Aug 5 09:28:11 bach kernel: Pid: 2817, comm: leafp2p Tainted: P 2.6.37.6.RNx86_64.2.4 #1 Aug 5 09:28:11 bach kernel: Call Trace: Aug 5 09:28:11 bach kernel: [<ffffffff8807eeaf>] dump_header+0x6f/0x190 Aug 5 09:28:11 bach kernel: [<ffffffff8808ee2a>] ? wait_iff_congested+0xba/0x120 Aug 5 09:28:11 bach kernel: [<ffffffff8804d500>] ? autoremove_wake_function+0x0/0x40 Aug 5 09:28:11 bach kernel: [<ffffffff8807f3be>] oom_kill_process+0x27e/0x290 Aug 5 09:28:11 bach kernel: [<ffffffff8807f61e>] out_of_memory+0x24e/0x300 Aug 5 09:28:11 bach kernel: [<ffffffff880825a3>] __alloc_pages_nodemask+0x5f3/0x610 Aug 5 09:28:11 bach kernel: [<ffffffff88084c47>] __do_page_cache_readahead+0xe7/0x220 Aug 5 09:28:11 bach kernel: [<ffffffff88084d9c>] ra_submit+0x1c/0x20 Aug 5 09:28:11 bach kernel: [<ffffffff8807e319>] filemap_fault+0x3b9/0x3c0 Aug 5 09:28:11 bach kernel: [<ffffffff88092da0>] __do_fault+0x50/0x490 Aug 5 09:28:11 bach kernel: [<ffffffff88002bce>] ? apic_timer_interrupt+0xe/0x20 Aug 5 09:28:11 bach kernel: [<ffffffff88094f8c>] handle_mm_fault+0x1ac/0x840 Aug 5 09:28:11 bach kernel: [<ffffffff88051051>] ? hrtimer_try_to_cancel+0x41/0x80 Aug 5 09:28:11 bach kernel: [<ffffffff88020139>] do_page_fault+0x139/0x420 Aug 5 09:28:11 bach kernel: [<ffffffff8805145e>] ? hrtimer_nanosleep+0x9e/0x120 Aug 5 09:28:11 bach kernel: [<ffffffff88050970>] ? hrtimer_wakeup+0x0/0x30 Aug 5 09:28:11 bach kernel: [<ffffffff885b479f>] page_fault+0x1f/0x30 Aug 5 09:28:11 bach kernel: Mem-Info: Aug 5 09:28:11 bach kernel: DMA per-cpu: Aug 5 09:28:11 bach kernel: CPU 0: hi: 0, btch: 1 usd: 0 Aug 5 09:28:11 bach kernel: CPU 1: hi: 0, btch: 1 usd: 0 Aug 5 09:28:11 bach kernel: DMA32 per-cpu: Aug 5 09:28:11 bach kernel: CPU 0: hi: 186, btch: 31 usd: 70 Aug 5 09:28:11 bach kernel: CPU 1: hi: 186, btch: 31 usd: 124 Aug 5 09:28:11 bach kernel: active_anon:88528 inactive_anon:88589 isolated_anon:0 Aug 5 09:28:11 bach kernel: active_file:8187 inactive_file:8166 isolated_file:352 Aug 5 09:28:11 bach kernel: unevictable:381 dirty:0 writeback:0 unstable:0 Aug 5 09:28:11 bach kernel: free:5061 slab_reclaimable:5675 slab_unreclaimable:4323 Aug 5 09:28:11 bach kernel: mapped:137 shmem:13 pagetables:836 bounce:0 Aug 5 09:28:11 bach kernel: DMA free:4184kB min:248kB low:308kB high:372kB active_anon:5084kB inactive_anon:5280kB active_file:456kB inactive_file:452kB unevictable:0kB isolated(anon):0kB isolated(file):0kB present:15680kB mlocked:0kB dirty:0kB writeback:0kB mapped:4kB shmem:0kB slab_reclaimable:392kB slab_unreclaimable:0kB kernel_stack:0kB pagetables:16kB unstable:0kB bounce:0kB writeback_tmp:0kB pages_scanned:1795 all_unreclaimable? no Aug 5 09:28:11 bach kernel: lowmem_reserve[]: 0 985 985 985 Aug 5 09:28:11 bach kernel: DMA32 free:16060kB min:16132kB low:20164kB high:24196kB active_anon:349028kB inactive_anon:349076kB active_file:32292kB inactive_file:32084kB unevictable:1524kB isolated(anon):0kB isolated(file):1536kB present:1008672kB mlocked:0kB dirty:0kB writeback:0kB mapped:544kB shmem:52kB slab_reclaimable:22308kB slab_unreclaimable:17292kB kernel_stack:880kB pagetables:3328kB unstable:0kB bounce:0kB writeback_tmp:0kB pages_scanned:109525 all_unreclaimable? yes Aug 5 09:28:11 bach kernel: lowmem_reserve[]: 0 0 0 0 Aug 5 09:28:11 bach kernel: DMA: 50*4kB 0*8kB 3*16kB 2*32kB 1*64kB 2*128kB 2*256kB 0*512kB 1*1024kB 1*2048kB 0*4096kB = 4216kB Aug 5 09:28:11 bach kernel: DMA32: 1727*4kB 157*8kB 22*16kB 16*32kB 10*64kB 6*128kB 4*256kB 1*512kB 0*1024kB 0*2048kB 1*4096kB = 16068kB Aug 5 09:28:11 bach kernel: 24397 total pagecache pages Aug 5 09:28:11 bach kernel: 7268 pages in swap cache Aug 5 09:28:11 bach kernel: Swap cache stats: add 979679, delete 972411, find 135337/162625 Aug 5 09:28:11 bach kernel: Free swap = 0kB Aug 5 09:28:11 bach kernel: Total swap = 524272kB Aug 5 09:28:11 bach kernel: 259744 pages RAM Aug 5 09:28:11 bach kernel: 6516 pages reserved Aug 5 09:28:11 bach kernel: 21595 pages shared Aug 5 09:28:11 bach kernel: 226536 pages non-shared Aug 5 09:28:11 bach kernel: [ pid ] uid tgid total_vm rss cpu oom_adj oom_score_adj name Aug 5 09:28:11 bach kernel: [ 785] 0 785 450 90 1 0 0 ifplugd Aug 5 09:28:11 bach kernel: [ 904] 0 904 586 2 0 -17 -1000 udevd Aug 5 09:28:11 bach kernel: [ 1852] 0 1852 424 11 1 0 0 acpid Aug 5 09:28:11 bach kernel: [ 1858] 0 1858 422 2 1 0 0 raidard Aug 5 09:28:11 bach kernel: [ 1895] 0 1895 1365 0 1 0 0 sshd Aug 5 09:28:11 bach kernel: [ 1991] 0 1991 633 0 0 0 0 quota_nld Aug 5 09:28:11 bach kernel: [ 1996] 1 1996 453 0 1 0 0 portmap Aug 5 09:28:11 bach kernel: [ 2041] 0 2041 437 23 1 0 0 syslogd Aug 5 09:28:11 bach kernel: [ 2054] 0 2054 489 0 0 0 0 atd Aug 5 09:28:11 bach kernel: [ 2059] 0 2059 425 6 0 0 0 klogd Aug 5 09:28:11 bach kernel: [ 2072] 0 2072 940 37 1 0 0 cupsd Aug 5 09:28:11 bach kernel: [ 2077] 21 2077 688 1 1 0 0 dbus-daemon Aug 5 09:28:11 bach kernel: [ 2079] 0 2079 494 26 1 0 0 cron Aug 5 09:28:11 bach kernel: [ 2114] 0 2114 3731 50 1 0 0 smbd Aug 5 09:28:11 bach kernel: [ 2115] 0 2115 3728 0 1 0 0 smbd Aug 5 09:28:11 bach kernel: [ 2549] 0 2549 431 5 0 0 0 ifplugd Aug 5 09:28:11 bach kernel: [ 2690] 0 2690 431 8 0 0 0 ifplugd Aug 5 09:28:11 bach kernel: [ 2737] 0 2737 13025 5565 1 0 0 minidlna Aug 5 09:28:11 bach kernel: [ 2748] 0 2748 534 0 0 0 0 cnid_metad Aug 5 09:28:11 bach kernel: [ 2751] 0 2751 531 21 1 0 0 chronyd Aug 5 09:28:11 bach kernel: [ 2769] 0 2769 1779 50 1 0 0 afpd Aug 5 09:28:11 bach kernel: [ 2783] 0 2783 1201 0 0 0 0 leafp2p.sh Aug 5 09:28:11 bach kernel: [ 2784] 0 2784 9083 102 0 0 0 leafp2p Aug 5 09:28:11 bach kernel: [ 2844] 0 2844 3976 9 1 0 0 mt-daapd Aug 5 09:28:11 bach kernel: [ 2873] 0 2873 431 5 1 0 0 ifplugd Aug 5 09:28:11 bach kernel: [ 2906] 0 2906 2227 59 0 0 0 nmbd Aug 5 09:28:11 bach kernel: [ 2957] 0 2957 603 123 0 0 0 monitor_enclosu Aug 5 09:28:11 bach kernel: [ 3181] 98 3181 481 11 1 -17 -1000 hidups Aug 5 09:28:11 bach kernel: [ 3215] 98 3215 483 11 1 -17 -1000 upsd Aug 5 09:28:11 bach kernel: [ 3228] 0 3228 440 12 1 -17 -1000 upsmon Aug 5 09:28:11 bach kernel: [ 3250] 20 3250 711 30 1 0 0 avahi-daemon Aug 5 09:28:11 bach kernel: [ 3254] 0 3254 425 2 1 0 0 getty Aug 5 09:28:11 bach kernel: [19348] 0 19348 9072 4348 1 0 0 apache-ssl Aug 5 09:28:11 bach kernel: [19373] 0 19373 424 15 1 0 0 upnpd Aug 5 09:28:11 bach kernel: [19375] 0 19375 444 22 0 0 0 lld2d Aug 5 09:28:11 bach kernel: [19385] 98 19385 9072 4347 1 0 0 apache-ssl Aug 5 09:28:11 bach kernel: [19392] 0 19392 1055 24 1 0 0 rsync Aug 5 09:28:11 bach kernel: [19418] 0 19418 1201 21 1 0 0 remote.sh Aug 5 09:28:11 bach kernel: [19420] 0 19420 1262 18 1 0 0 remote Aug 5 09:28:11 bach kernel: [18448] 0 18448 659 29 1 0 0 cron Aug 5 09:28:11 bach kernel: [18449] 0 18449 625 18 1 0 0 sh Aug 5 09:28:11 bach kernel: [18450] 0 18450 4576 3652 1 0 0 backup Aug 5 09:28:11 bach kernel: [18465] 0 18465 653 59 0 0 0 sh Aug 5 09:28:11 bach kernel: [18495] 0 18495 280504 155383 0 0 0 cp Aug 5 09:28:11 bach kernel: Out of memory: Kill process 18495 (cp) score 696 or sacrifice child Aug 5 09:28:11 bach kernel: Killed process 18495 (cp) total-vm:1122016kB, anon-rss:621532kB, file-rss:0kB Aug 5 09:28:15 bach RAIDiator: Error encountered copying data from source path ==> /USB_HDD_3/ due to unknown reason. Please see log. [Job 001]

So what do I do? My NAS seems to be working, but I like to have it backed up just in case and I am pretty tired of seeing the error in my inbox every morning. Let me know what other information I can provide.

by **de niro** » Mon Aug 06, 2012 2:29 am

Aug 5 09:28:11 bach kernel: [18495] 0 18495 280504 155383 0 0 0 cp --------->backup process
Aug 5 09:28:11 bach kernel: Out of memory: Kill process 18495 (cp) score 696 or sacrifice child
Aug 5 09:28:11 bach kernel: Killed process 18495 (cp) total-vm:1122016kB, anon-rss:621532kB, file-rss:0kB

System killed backup process while out of memory occurs,can you disable Readynas remote addon and replicate(if you are using) then test again?I suppose that you have to upgrade RAM to get more free memory space.

Aug 5 09:28:11 bach kernel: leafp2p invoked oom-killer: gfp_mask=0x201da, order=0, oom_adj=0, oom_score_adj=0 ---->remote component
Aug 5 09:28:11 bach kernel: Pid: 2817, comm: leafp2p Tainted: P 2.6.37.6.RNx86_64.2.4 #1

by **evan** » Mon Aug 06, 2012 7:25 pm

I see "out of memory" in your log, could you download logs from Frontview and sent to me, I need to check which process cause out of memory.

by **pkchrisjohnson** » Mon Aug 06, 2012 8:46 pm

Which logs do you want and how do I send them to you? I have attached the relevant portions of my logs below. Do you need more?

I went ahead and tried disabling the ReadyNas Remote add-on and tried to run the backup when I got back from work (at 17:09:53). The backup still failed (20:05:15) and this is what I see from the sys log tonight:

Code: Select all: Aug 6 17:09:53 bach RAIDiator: Backup button jobs started. Aug 6 20:05:15 bach kernel: apache-ssl invoked oom-killer: gfp_mask=0x201da, order=0, oom_adj=0, oom_score_adj=0 Aug 6 20:05:15 bach kernel: Pid: 735, comm: apache-ssl Tainted: P 2.6.37.6.RNx86_64.2.4 #1 Aug 6 20:05:15 bach kernel: Call Trace: Aug 6 20:05:15 bach kernel: [<ffffffff8807eeaf>] dump_header+0x6f/0x190 Aug 6 20:05:15 bach kernel: [<ffffffff8808ee2a>] ? wait_iff_congested+0xba/0x120 Aug 6 20:05:15 bach kernel: [<ffffffff8804d500>] ? autoremove_wake_function+0x0/0x40 Aug 6 20:05:15 bach kernel: [<ffffffff8807f3be>] oom_kill_process+0x27e/0x290 Aug 6 20:05:15 bach kernel: [<ffffffff8807f61e>] out_of_memory+0x24e/0x300 Aug 6 20:05:15 bach kernel: [<ffffffff880825a3>] __alloc_pages_nodemask+0x5f3/0x610 Aug 6 20:05:15 bach kernel: [<ffffffff88084c47>] __do_page_cache_readahead+0xe7/0x220 Aug 6 20:05:15 bach kernel: [<ffffffff88084d9c>] ra_submit+0x1c/0x20 Aug 6 20:05:15 bach kernel: [<ffffffff8807e319>] filemap_fault+0x3b9/0x3c0 Aug 6 20:05:15 bach kernel: [<ffffffff88092da0>] __do_fault+0x50/0x490 Aug 6 20:05:15 bach kernel: [<ffffffff88094f8c>] handle_mm_fault+0x1ac/0x840 Aug 6 20:05:15 bach kernel: [<ffffffff8803783d>] ? sys_wait4+0xad/0xf0 Aug 6 20:05:15 bach kernel: [<ffffffff88020139>] do_page_fault+0x139/0x420 Aug 6 20:05:15 bach kernel: [<ffffffff880556ae>] ? ktime_get_ts+0x9e/0xd0 Aug 6 20:05:15 bach kernel: [<ffffffff880e99ae>] ? poll_select_copy_remaining+0xce/0x120 Aug 6 20:05:15 bach kernel: [<ffffffff885b479f>] page_fault+0x1f/0x30 Aug 6 20:05:15 bach kernel: Mem-Info: Aug 6 20:05:15 bach kernel: DMA per-cpu: Aug 6 20:05:15 bach kernel: CPU 0: hi: 0, btch: 1 usd: 0 Aug 6 20:05:15 bach kernel: CPU 1: hi: 0, btch: 1 usd: 0 Aug 6 20:05:15 bach kernel: DMA32 per-cpu: Aug 6 20:05:15 bach kernel: CPU 0: hi: 186, btch: 31 usd: 0 Aug 6 20:05:15 bach kernel: CPU 1: hi: 186, btch: 31 usd: 0 Aug 6 20:05:15 bach kernel: active_anon:89117 inactive_anon:89162 isolated_anon:0 Aug 6 20:05:15 bach kernel: active_file:7617 inactive_file:7589 isolated_file:608 Aug 6 20:05:15 bach kernel: unevictable:382 dirty:0 writeback:0 unstable:0 Aug 6 20:05:15 bach kernel: free:5078 slab_reclaimable:5478 slab_unreclaimable:4335 Aug 6 20:05:15 bach kernel: mapped:99 shmem:2 pagetables:845 bounce:0 Aug 6 20:05:15 bach kernel: DMA free:4172kB min:248kB low:308kB high:372kB active_anon:5284kB inactive_anon:5360kB active_file:416kB inactive_file:408kB unevictable:0kB isolated(anon):0kB isolated(file):0kB present:15680kB mlocked:0kB dirty:0kB writeback:0kB mapped:4kB shmem:0kB slab_reclaimable:188kB slab_unreclaimable:0kB kernel_stack:0kB pagetables:16kB unstable:0kB bounce:0kB writeback_tmp:0kB pages_scanned:1411 all_unreclaimable? no Aug 6 20:05:15 bach kernel: lowmem_reserve[]: 0 985 985 985 Aug 6 20:05:15 bach kernel: DMA32 free:16140kB min:16132kB low:20164kB high:24196kB active_anon:351184kB inactive_anon:351288kB active_file:30152kB inactive_file:29948kB unevictable:1528kB isolated(anon):0kB isolated(file):2304kB present:1008672kB mlocked:0kB dirty:0kB writeback:0kB mapped:392kB shmem:8kB slab_reclaimable:21724kB slab_unreclaimable:17340kB kernel_stack:880kB pagetables:3364kB unstable:0kB bounce:0kB writeback_tmp:0kB pages_scanned:99582 all_unreclaimable? no Aug 6 20:05:15 bach kernel: lowmem_reserve[]: 0 0 0 0 Aug 6 20:05:15 bach kernel: DMA: 43*4kB 0*8kB 6*16kB 4*32kB 1*64kB 1*128kB 0*256kB 1*512kB 1*1024kB 1*2048kB 0*4096kB = 4172kB Aug 6 20:05:15 bach kernel: DMA32: 1627*4kB 198*8kB 11*16kB 8*32kB 7*64kB 8*128kB 4*256kB 2*512kB 0*1024kB 0*2048kB 1*4096kB = 16140kB Aug 6 20:05:15 bach kernel: 29067 total pagecache pages Aug 6 20:05:15 bach kernel: 12869 pages in swap cache Aug 6 20:05:15 bach kernel: Swap cache stats: add 1624897, delete 1612028, find 317516/365144 Aug 6 20:05:15 bach kernel: Free swap = 0kB Aug 6 20:05:15 bach kernel: Total swap = 524272kB Aug 6 20:05:15 bach kernel: 259744 pages RAM Aug 6 20:05:15 bach kernel: 6516 pages reserved Aug 6 20:05:15 bach kernel: 16915 pages shared Aug 6 20:05:15 bach kernel: 231674 pages non-shared Aug 6 20:05:15 bach kernel: [ pid ] uid tgid total_vm rss cpu oom_adj oom_score_adj name Aug 6 20:05:15 bach kernel: [ 785] 0 785 450 90 1 0 0 ifplugd Aug 6 20:05:15 bach kernel: [ 904] 0 904 586 1 0 -17 -1000 udevd Aug 6 20:05:15 bach kernel: [ 1852] 0 1852 424 0 1 0 0 acpid Aug 6 20:05:15 bach kernel: [ 1858] 0 1858 422 0 0 0 0 raidard Aug 6 20:05:15 bach kernel: [ 1895] 0 1895 1365 0 1 0 0 sshd Aug 6 20:05:15 bach kernel: [ 1991] 0 1991 633 0 0 0 0 quota_nld Aug 6 20:05:15 bach kernel: [ 1996] 1 1996 453 0 1 0 0 portmap Aug 6 20:05:15 bach kernel: [ 2041] 0 2041 437 16 0 0 0 syslogd Aug 6 20:05:15 bach kernel: [ 2054] 0 2054 489 0 1 0 0 atd Aug 6 20:05:15 bach kernel: [ 2059] 0 2059 425 2 0 0 0 klogd Aug 6 20:05:15 bach kernel: [ 2072] 0 2072 940 32 1 0 0 cupsd Aug 6 20:05:15 bach kernel: [ 2077] 21 2077 688 0 1 0 0 dbus-daemon Aug 6 20:05:15 bach kernel: [ 2079] 0 2079 494 20 1 0 0 cron Aug 6 20:05:15 bach kernel: [ 2114] 0 2114 3731 43 1 0 0 smbd Aug 6 20:05:15 bach kernel: [ 2115] 0 2115 3728 0 1 0 0 smbd Aug 6 20:05:15 bach kernel: [ 2549] 0 2549 431 5 0 0 0 ifplugd Aug 6 20:05:15 bach kernel: [ 2690] 0 2690 431 5 1 0 0 ifplugd Aug 6 20:05:15 bach kernel: [ 2737] 0 2737 12993 24 0 0 0 minidlna Aug 6 20:05:15 bach kernel: [ 2748] 0 2748 534 0 0 0 0 cnid_metad Aug 6 20:05:15 bach kernel: [ 2751] 0 2751 531 17 1 0 0 chronyd Aug 6 20:05:15 bach kernel: [ 2769] 0 2769 1779 0 1 0 0 afpd Aug 6 20:05:15 bach kernel: [ 2783] 0 2783 1201 0 0 0 0 leafp2p.sh Aug 6 20:05:15 bach kernel: [ 2784] 0 2784 9083 29 0 0 0 leafp2p Aug 6 20:05:15 bach kernel: [ 2844] 0 2844 3976 8 0 0 0 mt-daapd Aug 6 20:05:15 bach kernel: [ 2873] 0 2873 431 5 0 0 0 ifplugd Aug 6 20:05:15 bach kernel: [ 2906] 0 2906 2227 42 0 0 0 nmbd Aug 6 20:05:15 bach kernel: [ 2957] 0 2957 603 101 0 0 0 monitor_enclosu Aug 6 20:05:15 bach kernel: [ 3181] 98 3181 481 10 1 -17 -1000 hidups Aug 6 20:05:15 bach kernel: [ 3215] 98 3215 483 11 1 -17 -1000 upsd Aug 6 20:05:15 bach kernel: [ 3228] 0 3228 440 14 0 -17 -1000 upsmon Aug 6 20:05:15 bach kernel: [ 3250] 20 3250 711 26 0 0 0 avahi-daemon Aug 6 20:05:15 bach kernel: [ 3254] 0 3254 425 1 1 0 0 getty Aug 6 20:05:15 bach kernel: [19373] 0 19373 424 7 1 0 0 upnpd Aug 6 20:05:15 bach kernel: [19375] 0 19375 444 17 1 0 0 lld2d Aug 6 20:05:15 bach kernel: [19392] 0 19392 1055 0 1 0 0 rsync Aug 6 20:05:15 bach kernel: [ 5753] 0 5753 4041 75 1 0 0 smbd Aug 6 20:05:15 bach kernel: [ 735] 0 735 8552 12 1 0 0 apache-ssl Aug 6 20:05:15 bach kernel: [ 6058] 98 6058 9021 318 0 0 0 apache-ssl Aug 6 20:05:15 bach kernel: [16988] 98 16988 8573 15 0 0 0 apache-ssl Aug 6 20:05:15 bach kernel: [24725] 0 24725 733 2 1 0 0 gpio.agent Aug 6 20:05:15 bach kernel: [24732] 0 24732 419 9 1 0 0 blink_backup_le Aug 6 20:05:15 bach kernel: [24741] 0 24741 703 0 1 0 0 sh Aug 6 20:05:15 bach kernel: [24742] 0 24742 4576 2 0 0 0 backup Aug 6 20:05:15 bach kernel: [24757] 0 24757 710 2 1 0 0 sh Aug 6 20:05:15 bach kernel: [24787] 0 24787 274656 164795 0 0 0 cp Aug 6 20:05:15 bach kernel: Out of memory: Kill process 24787 (cp) score 680 or sacrifice child Aug 6 20:05:15 bach kernel: Killed process 24787 (cp) total-vm:1098624kB, anon-rss:659180kB, file-rss:0kB Aug 6 20:05:15 bach kernel: cp: page allocation failure. order:0, mode:0x201da Aug 6 20:05:15 bach kernel: Pid: 24787, comm: cp Tainted: P 2.6.37.6.RNx86_64.2.4 #1 Aug 6 20:05:15 bach kernel: Call Trace: Aug 6 20:05:15 bach kernel: [<ffffffff88082508>] __alloc_pages_nodemask+0x558/0x610 Aug 6 20:05:15 bach kernel: [<ffffffff88084c47>] __do_page_cache_readahead+0xe7/0x220 Aug 6 20:05:15 bach kernel: [<ffffffff8807d7c0>] ? sync_page_killable+0x0/0x40 Aug 6 20:05:15 bach kernel: [<ffffffff88084d9c>] ra_submit+0x1c/0x20 Aug 6 20:05:15 bach kernel: [<ffffffff8807e319>] filemap_fault+0x3b9/0x3c0 Aug 6 20:05:15 bach kernel: [<ffffffff88092da0>] __do_fault+0x50/0x490 Aug 6 20:05:15 bach kernel: [<ffffffff88094f8c>] handle_mm_fault+0x1ac/0x840 Aug 6 20:05:15 bach kernel: [<ffffffff880ae251>] ? do_sync_read+0xd1/0x110 Aug 6 20:05:15 bach kernel: [<ffffffff88020139>] do_page_fault+0x139/0x420 Aug 6 20:05:15 bach kernel: [<ffffffff880bfdb6>] ? dput+0x26/0x130 Aug 6 20:05:15 bach kernel: [<ffffffff880dd2d4>] ? __fsnotify_parent+0xc4/0x110 Aug 6 20:05:15 bach kernel: [<ffffffff880aeabd>] ? vfs_read+0x12d/0x170 Aug 6 20:05:15 bach kernel: [<ffffffff885b479f>] page_fault+0x1f/0x30 Aug 6 20:05:15 bach kernel: Mem-Info: Aug 6 20:05:15 bach kernel: DMA per-cpu: Aug 6 20:05:15 bach kernel: CPU 0: hi: 0, btch: 1 usd: 0 Aug 6 20:05:15 bach kernel: CPU 1: hi: 0, btch: 1 usd: 0 Aug 6 20:05:15 bach kernel: DMA32 per-cpu: Aug 6 20:05:15 bach kernel: CPU 0: hi: 186, btch: 31 usd: 0 Aug 6 20:05:15 bach kernel: CPU 1: hi: 186, btch: 31 usd: 0 Aug 6 20:05:15 bach kernel: active_anon:89117 inactive_anon:89162 isolated_anon:0 Aug 6 20:05:15 bach kernel: active_file:7601 inactive_file:7605 isolated_file:608 Aug 6 20:05:15 bach kernel: unevictable:382 dirty:0 writeback:0 unstable:0 Aug 6 20:05:15 bach kernel: free:5078 slab_reclaimable:5478 slab_unreclaimable:4335 Aug 6 20:05:15 bach kernel: mapped:99 shmem:2 pagetables:845 bounce:0 Aug 6 20:05:15 bach kernel: DMA free:4172kB min:248kB low:308kB high:372kB active_anon:5284kB inactive_anon:5360kB active_file:420kB inactive_file:404kB unevictable:0kB isolated(anon):0kB isolated(file):0kB present:15680kB mlocked:0kB dirty:0kB writeback:0kB mapped:4kB shmem:0kB slab_reclaimable:188kB slab_unreclaimable:0kB kernel_stack:0kB pagetables:16kB unstable:0kB bounce:0kB writeback_tmp:0kB pages_scanned:0 all_unreclaimable? no Aug 6 20:05:15 bach kernel: lowmem_reserve[]: 0 985 985 985 Aug 6 20:05:15 bach kernel: DMA32 free:16140kB min:16132kB low:20164kB high:24196kB active_anon:351184kB inactive_anon:351288kB active_file:29984kB inactive_file:30016kB unevictable:1528kB isolated(anon):0kB isolated(file):2432kB present:1008672kB mlocked:0kB dirty:0kB writeback:0kB mapped:392kB shmem:8kB slab_reclaimable:21724kB slab_unreclaimable:17340kB kernel_stack:880kB pagetables:3364kB unstable:0kB bounce:0kB writeback_tmp:0kB pages_scanned:320 all_unreclaimable? no Aug 6 20:05:15 bach kernel: lowmem_reserve[]: 0 0 0 0 Aug 6 20:05:15 bach kernel: DMA: 43*4kB 0*8kB 6*16kB 4*32kB 1*64kB 1*128kB 0*256kB 1*512kB 1*1024kB 1*2048kB 0*4096kB = 4172kB Aug 6 20:05:15 bach kernel: DMA32: 1627*4kB 198*8kB 11*16kB 8*32kB 7*64kB 8*128kB 4*256kB 2*512kB 0*1024kB 0*2048kB 1*4096kB = 16140kB Aug 6 20:05:15 bach kernel: 29067 total pagecache pages Aug 6 20:05:15 bach kernel: 12869 pages in swap cache Aug 6 20:05:15 bach kernel: Swap cache stats: add 1624897, delete 1612028, find 317516/365145 Aug 6 20:05:15 bach kernel: Free swap = 0kB Aug 6 20:05:15 bach kernel: Total swap = 524272kB Aug 6 20:05:15 bach kernel: 259744 pages RAM Aug 6 20:05:15 bach kernel: 6516 pages reserved Aug 6 20:05:15 bach kernel: 16877 pages shared Aug 6 20:05:15 bach kernel: 231674 pages non-shared Aug 6 20:05:17 bach RAIDiator: Error encountered copying data from source path ==> /USB_HDD_3/ due to unknown reason. Please see log. [Job 001]

And again from the backup log:

Code: Select all: `./Pictures/Personal/2012/2012 - 04 Paris/Paris_CJ-20120409-0836.xmp' -> `/USB_HDD_3/Pictures/Personal/2012/2012 - 04 Paris/Paris_CJ-20120409-0836.xmp' `./Pictures/Personal/2012/2012 - 04 Paris/Paris_CJ-20120412-2358.xmp' -> `/USB_HDD_3/Pictures/Personal/2012/2012 - 04 Paris/Paris_CJ-20120412-2358.xmp' `./Pictures/Personal/2012/2012 - 04 Paris/Paris_CJ-20120410-1428.xmp' -> `/USB_HDD_3/Pictures/Personal/2012/2012 - 04 Paris/Paris_CJ-20120410-1428.xmp' `./Pictures/Personal/2012/2012 - 04 Paris/Paris_CJ-20120410-1184.xmp' -> ` Backup failed. Mon Aug 6 20:05:15 PDT 2012. Reason for failure: Error encountered copying data from source path ==> /USB_HDD_3/ due to unknown reason. Please see log.

by **evan** » Wed Aug 08, 2012 6:43 pm

Hi pkchrisjohnson
Which version is RAIDiator on your ReadyNAS?
It looks like it's cp that's eating up all his memory.
We did update to a newer version of coreutils (which includes cp) in 4.2.21, to fix an OOM issue that a customer found while using Replicate.
If the issue still exist on 4.2.21, could we try a local update on the your box, we can try a newer upstream version of coreutils to see if the issue has somehow been fixed already.

by **pkchrisjohnson** » Wed Aug 08, 2012 7:21 pm

My version is 4.2.21. Feel free to email me the newer firmware. The email that I used to send the logs will be just fine. Thanks!

by **Ki-Adi-Mundi** » Tue Aug 14, 2012 2:56 am

Hi pkchrisjohnson,
this may be not easy for us to reproduce. so I want some info from you. how many file do you backup to usb ?
the capacity is big or many folder levels ?
what's the difference between this backup job work and not work for you ? the files you need to backup to usb increased much a month ago ? or you upgrade firmware or install some addons ?

by **pkchrisjohnson** » Tue Aug 14, 2012 4:28 pm

There is about a terabyte of data that I backup to the external drive. The external drive has about 1.5TB of space on it...so plenty of room.

I don't know how to describe "many folder levels" or even what that means. I am backing up data, there are lots of files and folders and the structure is somewhat complex. But, this should not matter.

I have not significantly increased the number of files or the complexity of the folder structure since this thing started failing. As a matter of fact, I have tried to delete a bunch of stuff that I no longer needed to backup anymore and that did not change the outcome.

I have not installed any new add-ons, and like I said before, I uninstalled the only add-on that was really on. No change.

I update my firmware whenever there is a new version, and it seems like this started after the last firmware update I did, but I don't really remember.

by **naslover2** » Fri Aug 17, 2012 2:36 pm

Wow - I'm having a similar problem!

ReadyNAS NV+ using 4 x 1.5TB Drives (on the HCL) with upgraded RAM 1GB (also on HCL) with 4.1.9. Recently, I decided that since I'm NOT having any problems with my ReadyNAS, maybe it's time I back it up.

I bought a USB 3.0 3TB External "Desktop" Drive from a national retailer (yes, I know my NAS is USB 1.1). I went into FrontView to format the drive as EXT3 and also set USB writes to be fast (meaning I need to dismount the drive, before I disconnect). After formatting the drive and noticing FrontView does not properly size the drive after the format (740GB), I decided to try EaseUS Partition Master (on Windows) to format for EXT2 (not needing any journaling for my backup). When I plug it back in to the ReadyNAS, it is correctly recognized with a size of 2.7TB.

I am backing up my whole ReadyNAS. The structure of the RAID has long folder/filename combinations of 160 charatcers (+/-). The drive begins to backup and then randomly will stop (sometimes after a few hours, where I have seen pretty decent speeds of almost 1GB/min!). The error log seems to indicate that the drive is no longer available (this is a new drive, new cables, secure power, should not be any issue). If I unplug from the USB and plug back in, sometimes the NAS will recognize the drive and I can continue. Other times like now, once the backup fails, FrontView becomes unavailable, however the volume is still accessible from Windows. The power button works and although "Shutting down" appears on the display, it does not shutdown properly as evidenced by the FS Check upon reboot and the subsequent RAID re-sync.

I then check the external drive using FrontView's tools and it find and corrects any errors.

I try the whole process again and I get into an endless loop. I'm beginning to wonder if I should back the NAS up through the network.

Thanks for any help.

by **steveoelliott** » Tue Sep 04, 2012 2:42 am

I have exactly the same problem!!!

Have raised a support case: 19355936.

Is there a solution available?

by **evan** » Tue Sep 04, 2012 11:18 am

Yes, we are trying to reproduce the issue in local.
You may use rsync to backup, it don't use cp process.
1, Enable Rsync in Servers/Standart Files Protocals
2, Open share list, enable Read/Write in Rsync of USB Share.
3, Add a backup job, set source as remote rsync, input your NAS's IP in Host and Path is USB folder name.
4, Set destination as a share folder.

If you have any questions, please let me know.

by **steveoelliott** » Tue Sep 04, 2012 11:43 am

Thanks... I will consider your workaround as an interim option. Although in experience rsync does tend to be a lot slower especially for shares like the one I am backing up which is >140GB with lots of small files etc.

Do you have an ETA on your repro efforts? If you need any details / assistance from me, please let me know.

Should I let the support agent know you are working on this or have you already reached out to them?

by **steveoelliott** » Wed Sep 12, 2012 6:15 am

Just recieved an update from Netgear support...

Engineering have identified root cause and are working on a fix. Apparently it has something to do with the new cp package in 4.2.21.

by **steveoelliott** » Wed Sep 19, 2012 3:12 am

Any updates???

by **evan** » Wed Sep 19, 2012 10:44 am

We find the root cause, the issue will be fixed on 4.2.23.

NETGEAR ReadyNAS

Frontview Backup -> USB Disk Failing Daily

Frontview Backup -> USB Disk Failing Daily

Re: Frontview Backup -> USB Disk Failing Daily

Re: Frontview Backup -> USB Disk Failing Daily

Re: Frontview Backup -> USB Disk Failing Daily

Re: Frontview Backup -> USB Disk Failing Daily

Re: Frontview Backup -> USB Disk Failing Daily

Re: Frontview Backup -> USB Disk Failing Daily

Re: Frontview Backup -> USB Disk Failing Daily

Re: Frontview Backup -> USB Disk Failing Daily

Re: Frontview Backup -> USB Disk Failing Daily

Re: Frontview Backup -> USB Disk Failing Daily

Re: Frontview Backup -> USB Disk Failing Daily

Re: Frontview Backup -> USB Disk Failing Daily

Re: Frontview Backup -> USB Disk Failing Daily

Re: Frontview Backup -> USB Disk Failing Daily

Who is online