N5200PRO Apparently Degraded, or not?

[egd]

Hi

My N5200PRO (running firmware 2.00.04) has the following modules installed:
SYSUSER 2.00.02
SSHD 2.00.00
PERL 2.00.01
INFO 2.00.02
SQUEEZECENTER

I've not experienced a power outage or anything along those lines, but looking at Storage/ RAID status shows the array is degraded, with 2246 GB / 2698.3 GB and disks 1,3,4,5 in use. All drives are Seagate ST3750640NS (firmware 3.AE). SMART status on all drives is OK, and the SMART data for drive 2 is as follows:
Tray Number 2
Model ST3750640NS
Power On Hours 766 Hours
Temperature Celsius 41
Reallocated Sector Count 0
Current Pending Sector 0
Raw Read Error Rate 93100032
Seek Error Rate 59557445
Hardware ECC Recovered 217988170

System logs on bootup are as follows:
Information log:
2008/03/18 23:20:12 N5200PRO : User admin logged in from 192.168.168.2
2008/03/18 23:12:13 N5200PRO : N5200PRO boot
2008/03/18 23:12:12 N5200PRO : The system N5200PRO change to degrade mode.
2008/03/18 23:12:09 N5200PRO : mdadm: /dev/md1 has been started with 4 drives (out of 5).
2008/03/18 23:12:09 N5200PRO : mdadm: /dev/md1 has been started with 4 drives (out of 5).
2008/03/18 23:12:09 N5200PRO : [Disk sde] UUID[raid5;2f77bbb0:1d5631c3:133f287e:448e5df9;Sun Jul 8 11:18:51 2007]
2008/03/18 23:12:09 N5200PRO : [Disk sde] UUID[raid5;2f77bbb0:1d5631c3:133f287e:448e5df9;Sun Jul 8 11:18:51 2007]
2008/03/18 23:12:09 N5200PRO : [Disk sdd] UUID[raid5;2f77bbb0:1d5631c3:133f287e:448e5df9;Sun Jul 8 11:18:51 2007]
2008/03/18 23:12:09 N5200PRO : [Disk sdd] UUID[raid5;2f77bbb0:1d5631c3:133f287e:448e5df9;Sun Jul 8 11:18:51 2007]
2008/03/18 23:12:09 N5200PRO : [Disk sdc] UUID[raid5;2f77bbb0:1d5631c3:133f287e:448e5df9;Sun Jul 8 11:18:51 2007]
2008/03/17 22:47:14 N5200PRO : The log file has been truncated successfully.
2008/03/17 22:48:40 N5200PRO : User admin logged in from 192.168.168.2
2008/03/17 22:54:45 N5200PRO : User admin logged in from 192.168.168.2
2008/03/17 22:58:37 N5200PRO : [Disk sda] UUID[raid5;2f77bbb0:1d5631c3:133f287e:448e5df9;Sun Jul 8 11:18:51 2007]
2008/03/17 22:58:37 N5200PRO : [Disk sdb] UUID[raid5;2f77bbb0:1d5631c3:133f287e:448e5df9;Sun Jul 8 11:18:51 2007]
2008/03/17 22:58:37 N5200PRO : [Disk sdc] UUID[raid5;2f77bbb0:1d5631c3:133f287e:448e5df9;Sun Jul 8 11:18:51 2007]
2008/03/17 22:58:37 N5200PRO : [Disk sdd] UUID[raid5;2f77bbb0:1d5631c3:133f287e:448e5df9;Sun Jul 8 11:18:51 2007]
2008/03/17 22:58:37 N5200PRO : [Disk sde] UUID[raid5;2f77bbb0:1d5631c3:133f287e:448e5df9;Sun Jul 8 11:18:51 2007]
2008/03/17 22:58:37 N5200PRO : Assemble RAID [md1] from [ /dev/sda2 /dev/sdb2 /dev/sdc2 /dev/sdd2 /dev/sde2 ]
2008/03/17 22:58:37 N5200PRO : mdadm: /dev/md1 has been started with 4 drives (out of 5).
2008/03/17 22:58:41 N5200PRO : N5200PRO boot
2008/03/18 08:49:44 N5200PRO : User admin logged in from 192.168.168.2
2008/03/18 18:42:10 N5200PRO : [Disk sda] UUID[raid5;2f77bbb0:1d5631c3:133f287e:448e5df9;Sun Jul 8 11:18:51 2007]
2008/03/18 18:42:10 N5200PRO : [Disk sdb] UUID[raid5;2f77bbb0:1d5631c3:133f287e:448e5df9;Sun Jul 8 11:18:51 2007]
2008/03/18 18:42:10 N5200PRO : [Disk sdc] UUID[raid5;2f77bbb0:1d5631c3:133f287e:448e5df9;Sun Jul 8 11:18:51 2007]
2008/03/18 18:42:10 N5200PRO : [Disk sdd] UUID[raid5;2f77bbb0:1d5631c3:133f287e:448e5df9;Sun Jul 8 11:18:51 2007]
2008/03/18 18:42:10 N5200PRO : [Disk sde] UUID[raid5;2f77bbb0:1d5631c3:133f287e:448e5df9;Sun Jul 8 11:18:51 2007]
2008/03/18 18:42:10 N5200PRO : Assemble RAID [md1] from [ /dev/sda2 /dev/sdb2 /dev/sdc2 /dev/sdd2 /dev/sde2 ]
2008/03/18 18:42:10 N5200PRO : mdadm: /dev/md1 has been started with 4 drives (out of 5).
2008/03/18 18:42:14 N5200PRO : N5200PRO boot
2008/03/18 19:46:33 N5200PRO : User admin logged in from 192.168.168.2
2008/03/18 23:06:20 N5200PRO : User admin logged in from 192.168.168.2

Error log:
2008/03/18 23:12:12 N5200PRO : The system N5200PRO change to degrade mode.
2008/03/17 22:58:40 N5200PRO : The system N5200PRO change to degrade mode.
2008/03/18 18:42:13 N5200PRO : The system N5200PRO change to degrade mode.

Despite the array apparently being degraded, I am still able to enter the Module Management options.

The INFO module referred to above returns:
Device Information (INFO)

This module gives as much information for the N5200 as possible.

System Info
Firmware Version: 2.00.04
Product: n5200
Producer: THECUS
CPU: Intel(R) Celeron(R) M processor 1.50GHz
Uptime: 0 days 0:23
LoadAvg: 0.00 0.01 0.05
Fan 1 speed: 1052
Fan 2 speed: 3324
Switch Board: No
Filesystem Info: /raid/data
Size 2829339424 KB
Used 2355152576 KB
Available 474186848 KB
Percent used 83 %
Filesystem Info: /tmpfs
Size 262144 KB
Used 248 KB
Available 261896 KB
Percent used 0 %
Network Interface Info: lo
Link Status: RUNNING
Speed: Unknown
Duplex: Unknown
Addr: 127.0.0.1
BroadCast: 255.0.0.0
NetMask: Unknown
TxBytes: Unknown bytes
TxPackets: Unknown packets
RxBytes: Unknown bytes
RxPackets: Unknown packets
Network Interface Info: eth0
Link Status: RUNNING
Speed: 1000Mb/s
Duplex: Full
Addr: 192.168.168.100
BroadCast: 192.168.168.255
NetMask: 255.255.255.0
TxBytes: 1093240 bytes
TxPackets: 1689 packets
RxBytes: 308193 bytes
RxPackets: 3369 packets
Network Interface Info: eth1
Link Status: DOWN
Speed: Unknown!
Duplex: Unknown!
Addr: 192.168.2.254
BroadCast: 192.168.2.255
NetMask: 255.255.255.0
TxBytes: 0 bytes
TxPackets: 0 packets
RxBytes: 0 bytes
RxPackets: 0 packets
Network Interface Info: lt0
Link Status: DOWN
Speed: Unknown
Duplex: Unknown
Addr: Unknown
BroadCast: Unknown
NetMask: Unknown
TxBytes: Unknown bytes
TxPackets: Unknown packets
RxBytes: Unknown bytes
RxPackets: Unknown packets
Network Interface Info: ipddp0
Link Status: DOWN
Speed: Unknown
Duplex: Unknown
Addr: Unknown
BroadCast: Unknown
NetMask: Unknown
TxBytes: Unknown bytes
TxPackets: Unknown packets
RxBytes: Unknown bytes
RxPackets: Unknown packets
RAID Info: /dev/md0
Level: raid1
State: active,
Array Size: 1959424 bytes
Device Size: 1959424 bytes
Chunk Size: ERROR
Raid Devices: 5
Total Devices: 4
Active Devices: 4
Working Devices: 4
Failed Devices: 0
Spare Devices: 0
RAID Info: /dev/md1
Level: raid5
State: clean,
Array Size: 2922448128 bytes
Device Size: 730612032 bytes
Chunk Size: 64K
Raid Devices: 5
Total Devices: 4
Active Devices: 4
Working Devices: 4
Failed Devices: 0
Spare Devices: 0
Disk Info: /dev/sda
Vendor: Seagate
Model: ST3750640NS
Revision: 3.AE
Smart State: ENABLED
Smart Error Count: 0
Raw Read Error Rate: 202743680
Start/Stop Count: 229
Realloc Sector Count: 0
Power On Hours: 800 hours
Power Cycle Count: 163 cycles
Temperature: 39 celsius
Disk Info: /dev/sdb
Vendor: Seagate
Model: ST3750640NS
Revision: 3.AE
Smart State: ENABLED
Smart Error Count: 0
Raw Read Error Rate: 93100032
Start/Stop Count: 230
Realloc Sector Count: 0
Power On Hours: 766 hours
Power Cycle Count: 163 cycles
Temperature: 42 celsius
Disk Info: /dev/sdc
Vendor: Seagate
Model: ST3750640NS
Revision: 3.AE
Smart State: ENABLED
Smart Error Count: 0
Raw Read Error Rate: 195573705
Start/Stop Count: 233
Realloc Sector Count: 0
Power On Hours: 799 hours
Power Cycle Count: 163 cycles
Temperature: 41 celsius
Disk Info: /dev/sdd
Vendor: Seagate
Model: ST3750640NS
Revision: 3.AE
Smart State: ENABLED
Smart Error Count: 0
Raw Read Error Rate: 208167482
Start/Stop Count: 241
Realloc Sector Count: 0
Power On Hours: 796 hours
Power Cycle Count: 160 cycles
Temperature: 44 celsius
Disk Info: /dev/sde
Vendor: Seagate
Model: ST3750640NS
Revision: 3.AE
Smart State: ENABLED
Smart Error Count: 0
Raw Read Error Rate: 209876079
Start/Stop Count: 235
Realloc Sector Count: 0
Power On Hours: 795 hours
Power Cycle Count: 160 cycles
Temperature: 41 celsius

Under RAID configuration it shows "If you lose a hard disk, data loss will occur.(JBOD,RAID0)!" and drive 2 is not ticked in the Used or Spare columns.

What gives, what could have caused this and what is my best strategy to recover the array from here without losing data?

[egd]

dmesg dump...figured it would be useful in diagnosing the underlying issue:
f Reg initialization
/proc/mled_ctrl created
Reg :
0000 | 40 00 00 00 -- -- -- -- -- -- -- -- -- -- -- -- |@...------------
Reg :
0000 | ff 00 00 00 -- -- -- -- -- -- -- -- -- -- -- -- |....------------
usbcore: registered new driver usblp
drivers/usb/class/usblp.c: v0.13: USB Printer Device Class driver
PCI: Setting latency timer of device 0000:00:1d.7 to 64
ehci_hcd 0000:00:1d.7: Intel Corporation 82801DB/DBM (ICH4/ICH4-M) USB2 EHCI Controller
ehci_hcd 0000:00:1d.7: new USB bus registered, assigned bus number 1
ehci_hcd 0000:00:1d.7: irq 185, io mem 0xe8400000
PCI: cache line size of 32 is not supported by device 0000:00:1d.7
ehci_hcd 0000:00:1d.7: USB 2.0 initialized, EHCI 1.00, driver 10 Dec 2004
hub 1-0:1.0: USB hub found
hub 1-0:1.0: 6 ports detected
USB Universal Host Controller Interface driver v2.3
PCI: Setting latency timer of device 0000:00:1d.0 to 64
uhci_hcd 0000:00:1d.0: Intel Corporation 82801DB/DBL/DBM (ICH4/ICH4-L/ICH4-M) USB UHCI Controller #1
uhci_hcd 0000:00:1d.0: new USB bus registered, assigned bus number 2
uhci_hcd 0000:00:1d.0: irq 129, io base 0x0000e000
hub 2-0:1.0: USB hub found
hub 2-0:1.0: 2 ports detected
PCI: Setting latency timer of device 0000:00:1d.1 to 64
uhci_hcd 0000:00:1d.1: Intel Corporation 82801DB/DBL/DBM (ICH4/ICH4-L/ICH4-M) USB UHCI Controller #2
uhci_hcd 0000:00:1d.1: new USB bus registered, assigned bus number 3
uhci_hcd 0000:00:1d.1: irq 153, io base 0x0000e100
hub 3-0:1.0: USB hub found
hub 3-0:1.0: 2 ports detected
PCI: Setting latency timer of device 0000:00:1d.2 to 64
uhci_hcd 0000:00:1d.2: Intel Corporation 82801DB/DBL/DBM (ICH4/ICH4-L/ICH4-M) USB UHCI Controller #3
uhci_hcd 0000:00:1d.2: new USB bus registered, assigned bus number 4
uhci_hcd 0000:00:1d.2: irq 145, io base 0x0000e200
hub 4-0:1.0: USB hub found
hub 4-0:1.0: 2 ports detected
Initializing USB Mass Storage driver...
usbcore: registered new driver usb-storage
USB Mass Storage support registered.
zd1211 - - r83
Based on driver version 2.5.0.0
usbcore: registered new driver zd1211
ZD1211B - - r83
Based on driver version 2.5.0.0
usbcore: registered new driver zd1211b
net2280 0000:01:03.0: NetChip 2282 USB Peripheral Controller
net2280 0000:01:03.0: irq 185, pci mem e01d4000, chip rev 0101
net2280 0000:01:03.0: version: 2005 Sept 27; dma enabled
md: md driver 0.90.2 MAX_MD_DEVS=256, MD_SB_DISKS=27
md: bitmap version 3.38
md: linear personality registered as nr 1
md: raid0 personality registered as nr 2
md: raid1 personality registered as nr 3
raid5: automatically using best checksumming function: pIII_sse
pIII_sse : 3970.000 MB/sec
raid5: using function: pIII_sse (3970.000 MB/sec)
md: raid5 personality registered as nr 4
raid6: int32x1 534 MB/s
raid6: int32x2 674 MB/s
raid6: int32x4 460 MB/s
raid6: int32x8 428 MB/s
raid6: mmxx1 1711 MB/s
raid6: mmxx2 1909 MB/s
raid6: sse1x1 1250 MB/s
raid6: sse1x2 2001 MB/s
raid6: sse2x1 2086 MB/s
raid6: sse2x2 2404 MB/s
raid6: using algorithm sse2x2 (2404 MB/s)
md: raid6 personality registered as nr 8
md: raid10 personality registered as nr 9
NTFS driver 2.1.23 [Flags: R/O MODULE].
NET: Registered protocol family 5
cops.c:v0.04 6/7/98 Jay Schulist <jschlst@samba.org>
lt%d: cops at 0x240, using IRQ 5, in Dayna mode.
ipddp.c:v0.01 8/28/97 Bradford W. Johnson <johns393@maroon.tc.umn.edu>
ipddp0: Appletalk-IP Encap. mode by Bradford W. Johnson <johns393@maroon.tc.umn.edu>
NET: Registered protocol family 4
Installing knfsd (copyright (C) 1996
device-mapper: 4.4.0-ioctl (2005-01-12) initialised:
Kevin e1000_down
adapter->wol=2
e1000: eth0: e1000_watchdog_task: NIC Link is Up 1000 Mbps Full Duplex
Clear Critical Queue.
Read after write, bit[35]=0
Kevin: md_ioctl
md: md1 stopped.
md: bind<sdb2>
md: bind<sdc2>
md: bind<sda1>
md: bind<sdb1>
md: bind<sdc1>
md: bind<sdd1>
md: bind<sde1>
raid1: raid set md0 active with 5 out of 5 mirrors
md: bind<sdd2>
criticalevent_user: raid_recovery md0
md: syncing RAID array md0
md: minimum _guaranteed_ reconstruction speed: 1000 KB/sec/disc.
md: using maximum available idle IO bandwith (but not more than 200000 KB/sec) for reconstruction.
md: using 128k window, over a total of 1959424 blocks.
md: bind<sde2>
md: bind<sda2>
md: kicking non-fresh sdb2 from array!
md: unbind<sdb2>
md: export_rdev(sdb2)
raid5: device sda2 operational as raid disk 0
raid5: device sde2 operational as raid disk 4
raid5: device sdd2 operational as raid disk 3
raid5: device sdc2 operational as raid disk 2
raid5: allocated 5248kB for md1
raid5: raid level 5 set md1 active with 4 out of 5 devices, algorithm 2
RAID5 conf printout:
--- rd:5 wd:4 fd:1
disk 0, o:1, dev:sda2
disk 2, o:1, dev:sdc2
disk 3, o:1, dev:sdd2
disk 4, o:1, dev:sde2
criticalevent_user: raid_degrade md1
kjournald starting. Commit interval 5 seconds
EXT3-fs warning: maximal mount count reached, running e2fsck is recommended
EXT3 FS on dm-1, internal journal
EXT3-fs: mounted filesystem with ordered data mode.
kjournald starting. Commit interval 5 seconds
EXT3-fs warning: maximal mount count reached, running e2fsck is recommended
EXT3 FS on dm-0, internal journal
EXT3-fs: mounted filesystem with ordered data mode.
Quota Management version : 1.00.4
Adding 1959416k swap on /dev/md0. Priority:-1 extents:1
IOCTL!!![0xE0] .
MV: Issued HDIO_DRIVE_CMD here
mvSata: ATA_16 command queued in SmartATAsend
MV: HDIO_DRIVE_CMD successed
IOCTL!!![0xE3][0xF1] .
MV: Issued HDIO_DRIVE_CMD here
mvSata: ATA_16 command queued in SmartATAsend
MV: HDIO_DRIVE_CMD successed
IOCTL!!![0xE0] .
MV: Issued HDIO_DRIVE_CMD here
mvSata: ATA_16 command queued in SmartATAsend
MV: HDIO_DRIVE_CMD successed
IOCTL!!![0xE3][0xF1] .
MV: Issued HDIO_DRIVE_CMD here
mvSata: ATA_16 command queued in SmartATAsend
MV: HDIO_DRIVE_CMD successed
IOCTL!!![0xE0] .
MV: Issued HDIO_DRIVE_CMD here
mvSata: ATA_16 command queued in SmartATAsend
MV: HDIO_DRIVE_CMD successed
IOCTL!!![0xE3][0xF1] .
MV: Issued HDIO_DRIVE_CMD here
mvSata: ATA_16 command queued in SmartATAsend
Loading iSCSI transport class v1.1-648.
iscsi: registered transport (tcp)
MV: HDIO_DRIVE_CMD successed
IOCTL!!![0xE0] .
MV: Issued HDIO_DRIVE_CMD here
mvSata: ATA_16 command queued in SmartATAsend
MV: HDIO_DRIVE_CMD successed
IOCTL!!![0xE3][0xF1] .
MV: Issued HDIO_DRIVE_CMD here
mvSata: ATA_16 command queued in SmartATAsend
MV: HDIO_DRIVE_CMD successed
IOCTL!!![0xE0] .
MV: Issued HDIO_DRIVE_CMD here
mvSata: ATA_16 command queued in SmartATAsend
MV: HDIO_DRIVE_CMD successed
IOCTL!!![0xE3][0xF1] .
MV: Issued HDIO_DRIVE_CMD here
mvSata: ATA_16 command queued in SmartATAsend
MV: HDIO_DRIVE_CMD successed
iSCSI Enterprise Target Software - version 0.4.12
iotype_init(90) register fileio
iotype_init(90) register nullio
md: md0: sync done.
criticalevent_user: raid_healthy md0
RAID1 conf printout:
--- wd:5 rd:5
disk 0, wo:0, o:1, dev:sda1
disk 1, wo:0, o:1, dev:sdb1
disk 2, wo:0, o:1, dev:sdc1
disk 3, wo:0, o:1, dev:sdd1
disk 4, wo:0, o:1, dev:sde1
raid1: Disk failure on sdb1, disabling device.
Operation continuing on 4 devices
criticalevent_user: raid_degrade md0
RAID1 conf printout:
--- wd:4 rd:5
disk 0, wo:0, o:1, dev:sda1
disk 1, wo:1, o:0, dev:sdb1
disk 2, wo:0, o:1, dev:sdc1
disk 3, wo:0, o:1, dev:sdd1
disk 4, wo:0, o:1, dev:sde1
Read after write, bit[35]=1
RAID1 conf printout:
--- wd:4 rd:5
disk 0, wo:0, o:1, dev:sda1
disk 2, wo:0, o:1, dev:sdc1
disk 3, wo:0, o:1, dev:sdd1
disk 4, wo:0, o:1, dev:sde1
md: unbind<sdb1>
md: export_rdev(sdb1)

[egd]

and finally, a dump from /proc/mdstat:
root@127.0.0.1:/proc# cat mdstat
Personalities : [linear] [raid0] [raid1] [raid5] [raid6] [raid10]
md1 : active raid5 sda2[0] sde2[4] sdd2[3] sdc2[2]
2922448128 blocks level 5, 64k chunk, algorithm 2 [5/4] [U_UUU]

md0 : active raid1 sde1[4] sdd1[3] sdc1[2] sda1[0]
1959424 blocks [5/4] [U_UUU]

unused devices: <none>


How is it that SMART indicates all disks are fine yet clearly one is being ignored in the array?

[Thecus - Yvon]

Dear Sir,

Please check STORAGE->RAID->STATUS is HEALTH or not.

Yvon.

[egd]

STORAGE->RAID->STATUS is DEGRADED...as indicated in my first post in this thread...

[egd]

I've rebuilt the array by making disk 2 a spare. This immediately initiated a rebuild and the array is once again healthy. Is still doesn't answer what the hell happened to degrade it in the first place.

Can disk power down (currently set to 30 mins) have something to do with it?

[egd]

Don't know what happened to your response Yvon, but here goes again. Now that the problem has repeated itself, perhaps you will endeavour to respond...?
~~~
well, lo and behold the same bloody thing has happened again, the same channel and once again SMART stats show the drive is fine.

I have a few theories here:

• can it be that unplugging/ powering off at the wall socket of a Squeezebox that was connected to the NAS and "ON" at the time can cause a fault condition? This is what I'd done just before I noticed the array had become degraded. Seem to recall I may have done something similar the first time round too...?
• drive spin down occasionally causes the box to sh1t itself when the drives have to fire up again (I've now turned this off)?
• firmware or backplane issue?

Thoughts/ ideas?