Any RAID gurus in here? (more RAID problems)

[jondecker76]

it was somewhere between 0630 this morning and 0900 that it locked up. My wife didn't reboot it until about 1100, which is when I was able to log into the web admin remotely and check on the status.

Any ideas off the top of your head on which log files to check?

[mikedehaan]

These should provide us with some clue.

Log messages generated during the boot process:

Code: [Select]

/var/log/dmesg
System log file:

Code: [Select]

/var/log/syslog

[jondecker76]

ok, i'll check these when I get home in about 4 more hours. I'll post back then

thanks again

[mikedehaan]

When you have a chance also check your memory usage.  I remember having a problem with the mdadm monitoring daemon where it was consuming memory until the system died.  I don't remember how exactly I fixed it, but if it appears to be your problem, I'll do some digging.

I used "top" to track memory usage and hit the "M" key to sort by memory.  mdadm should be using trivial amounts of memory (less than 1%) (0.1% on my system).

[Zaerc]

I think the problem with your array could be caused by the hard rebooting, in my experience RAID arrays do not like that at all and often have to be rebuild afterwards.  And the hard locking could be caused by some other problem not directly related to RAID.

Something you can also try is to add a line like this to /etc/syslog.conf:

Code: [Select]

*.*                             /dev/tty12
Then after the syslog deamon is restarted (/etc/init.d/sysklogd restart) it will output all kernel and system messages on tty12, so you could leave the core displaying that terminal ([Ctrl][Alt][F12]) untill it crashes.  With a bit of luck that will give some more clues.

[jondecker76]

ok, theres some interesting things in the logs..
First, syslog shows no loggin g activity after 0634 this morning, then resumes at 11:14 when my wife rebooted. Prior to locking up, there are a ton of drive errors and failing to mount...

Code: [Select]


Jul 31 06:33:58 dcerouter kernel: [ 3601.716000] hda: media error (bad sector): error=0x30 { LastFailedSense=0x03 }
Jul 31 06:33:58 dcerouter kernel: [ 3601.716000] ide: failed opcode was: unknown
Jul 31 06:34:02 dcerouter kernel: [ 3605.484000] hda: error code: 0x70  sense_key: 0x03  asc: 0x11  ascq: 0x06
Jul 31 06:34:02 dcerouter kernel: [ 3605.484000] end_request: I/O error, dev hda, sector 2031320
Jul 31 06:34:02 dcerouter kernel: [ 3605.484000] Buffer I/O error on device hda, logical block 507830
Jul 31 06:34:02 dcerouter kernel: [ 3605.484000] Buffer I/O error on device hda, logical block 507831
Jul 31 06:34:08 dcerouter kernel: [ 3612.068000] hda: media error (bad sector): status=0x51 { DriveReady SeekComplete Error }
Jul 31 06:34:08 dcerouter kernel: [ 3612.068000] hda: media error (bad sector): error=0x30 { LastFailedSense=0x03 }
Jul 31 06:34:08 dcerouter kernel: [ 3612.068000] ide: failed opcode was: unknown
Jul 31 06:34:10 dcerouter kernel: [ 3613.684000] hda: error code: 0x70  sense_key: 0x03  asc: 0x11  ascq: 0x06
Jul 31 06:34:10 dcerouter kernel: [ 3613.684000] end_request: I/O error, dev hda, sector 2031320
Jul 31 06:34:10 dcerouter kernel: [ 3613.684000] Buffer I/O error on device hda, logical block 507830
Jul 31 06:34:10 dcerouter kernel: [ 3613.684000] Buffer I/O error on device hda, logical block 507831
Jul 31 06:34:16 dcerouter kernel: [ 3619.664000] printk: 1 messages suppressed.
Jul 31 06:34:16 dcerouter kernel: [ 3619.664000] rtc: lost 27 interrupts
Jul 31 06:34:16 dcerouter kernel: [ 3620.248000] hda: media error (bad sector): status=0x51 { DriveReady SeekComplete Error }
Jul 31 06:34:16 dcerouter kernel: [ 3620.248000] hda: media error (bad sector): error=0x30 { LastFailedSense=0x03 }
Jul 31 06:34:16 dcerouter kernel: [ 3620.248000] ide: failed opcode was: unknown
Jul 31 06:34:20 dcerouter kernel: [ 3623.944000] hda: error code: 0x70  sense_key: 0x03  asc: 0x11  ascq: 0x06
Jul 31 06:34:20 dcerouter kernel: [ 3623.944000] end_request: I/O error, dev hda, sector 2031320
Jul 31 06:34:20 dcerouter kernel: [ 3623.944000] Buffer I/O error on device hda, logical block 507830
Jul 31 06:34:23 dcerouter kernel: [ 3626.916000] eth0: too many iterations (6) in nv_nic_irq.
Jul 31 06:34:24 dcerouter kernel: [ 3627.920000] eth0: too many iterations (6) in nv_nic_irq.
Jul 31 11:14:06 dcerouter kernel: [   11.036000] ext3_orphan_cleanup: deleting unreferenced inode 37453836
Jul 31 11:14:06 dcerouter kernel: [   11.036000] ext3_orphan_cleanup: deleting unreferenced inode 36438025
Jul 31 11:14:06 dcerouter kernel: [   11.036000] ext3_orphan_cleanup: deleting unreferenced inode 36438024
Jul 31 11:14:06 dcerouter kernel: [   11.036000] ext3_orphan_cleanup: deleting unreferenced inode 36438023
Jul 31 11:14:06 dcerouter kernel: [   11.036000] ext3_orphan_cleanup: deleting unreferenced inode 36438022
Jul 31 11:14:06 dcerouter kernel: [   11.036000] ext3_orphan_cleanup: deleting unreferenced inode 36438021
Jul 31 11:14:06 dcerouter kernel: [   11.036000] EXT3-fs: sda1: 6 orphan inodes deleted
Jul 31 11:14:06 dcerouter kernel: [   11.036000] EXT3-fs: recovery complete.
Jul 31 11:14:06 dcerouter kernel: [   11.040000] EXT3-fs: mounted filesystem with ordered data mode.
Jul 31 11:14:06 dcerouter kernel: [   19.396000] r8169: eth1: link up
Jul 31 11:14:06 dcerouter kernel: [   20.112000] md: md0 stopped.
Jul 31 11:14:06 dcerouter kernel: [   20.376000] md: bind<sdb>
Jul 31 11:14:06 dcerouter kernel: [   20.376000] md: bind<sdd>
Jul 31 11:14:06 dcerouter kernel: [   20.376000] md: bind<sdc>
Jul 31 11:14:06 dcerouter kernel: [   20.376000] md: kicking non-fresh sdb from array!
Jul 31 11:14:06 dcerouter kernel: [   20.376000] md: unbind<sdb>
Jul 31 11:14:06 dcerouter kernel: [   20.376000] md: export_rdev(sdb)
Jul 31 11:14:06 dcerouter kernel: [   20.476000] i2c-adapter i2c-0: nForce2 SMBus adapter at 0x4c00
Jul 31 11:14:06 dcerouter kernel: [   20.476000] i2c-adapter i2c-1: nForce2 SMBus adapter at 0x4c40
Jul 31 11:14:06 dcerouter kernel: [   20.760000] raid5: device sdc operational as raid disk 1
Jul 31 11:14:06 dcerouter kernel: [   20.760000] raid5: device sdd operational as raid disk 2
Jul 31 11:14:06 dcerouter kernel: [   20.760000] raid5: allocated 3163kB for md0
Jul 31 11:14:06 dcerouter kernel: [   20.760000] raid5: raid level 5 set md0 active with 2 out of 3 devices, algorithm 2
Jul 31 11:14:06 dcerouter kernel: [   20.760000] RAID5 conf printout:
Jul 31 11:14:06 dcerouter kernel: [   20.760000]  --- rd:3 wd:2
Jul 31 11:14:06 dcerouter kernel: [   20.760000]  disk 1, o:1, dev:sdc
Jul 31 11:14:06 dcerouter kernel: [   20.760000]  disk 2, o:1, dev:sdd
Jul 31 11:14:06 dcerouter kernel: [   20.784000] input: PC Speaker as /class/input/input3
...
...
Jul 31 11:15:36 dcerouter automount[12640]: lookup(program): lookup for 117 failed
Jul 31 11:15:36 dcerouter automount[12640]: failed to mount /mnt/device/117
Jul 31 11:15:36 dcerouter automount[12674]: lookup(program): lookup for 133 failed
Jul 31 11:15:36 dcerouter automount[12674]: failed to mount /mnt/device/133
Jul 31 11:15:38 dcerouter automount[13579]: lookup(program): lookup for 117 failed
Jul 31 11:15:38 dcerouter automount[13579]: failed to mount /mnt/device/117
Jul 31 11:15:40 dcerouter automount[13719]: lookup(program): lookup for 133 failed
Jul 31 11:15:40 dcerouter automount[13719]: failed to mount /mnt/device/133
Jul 31 11:15:41 dcerouter automount[13858]: lookup(program): lookup for 117 failed
Jul 31 11:15:41 dcerouter automount[13858]: failed to mount /mnt/device/117
Jul 31 11:15:42 dcerouter automount[13856]: lookup(program): lookup for 133 failed
Jul 31 11:15:42 dcerouter automount[13856]: failed to mount /mnt/device/133
Jul 31 11:15:42 dcerouter kernel: [  136.024000] eth0: too many iterations (6) in nv_nic_irq.
Jul 31 11:15:43 dcerouter automount[13971]: lookup(program): lookup for 117 failed
Jul 31 11:15:43 dcerouter automount[13971]: failed to mount /mnt/device/117
Jul 31 11:15:43 dcerouter kernel: [  137.024000] eth0: too many iterations (6) in nv_nic_irq.

Jul 31 11:15:53 dcerouter automount[16676]: lookup(program): lookup for 133 failed
Jul 31 11:15:53 dcerouter automount[16676]: failed to mount /mnt/device/133
Jul 31 11:15:54 dcerouter automount[16795]: lookup(program): lookup for 117 failed
Jul 31 11:15:54 dcerouter automount[16795]: failed to mount /mnt/device/117
Jul 31 11:15:55 dcerouter automount[16960]: lookup(program): lookup for 133 failed
Jul 31 11:15:55 dcerouter automount[16960]: failed to mount /mnt/device/133
Jul 31 11:15:56 dcerouter automount[17127]: lookup(program): lookup for 117 failed
Jul 31 11:15:56 dcerouter automount[17127]: failed to mount /mnt/device/117
Jul 31 11:15:57 dcerouter automount[17222]: lookup(program): lookup for 133 failed
...
...
Jul 31 11:16:47 dcerouter automount[23600]: failed to mount /mnt/device/133
Jul 31 11:16:48 dcerouter automount[23645]: lookup(program): lookup for 117 failed
Jul 31 11:16:48 dcerouter automount[23645]: failed to mount /mnt/device/117
Jul 31 11:16:49 dcerouter automount[23734]: lookup(program): lookup for 117 failed
Jul 31 11:16:49 dcerouter automount[23734]: failed to mount /mnt/device/117
Jul 31 11:16:49 dcerouter automount[23842]: lookup(program): lookup for 133 failed
Jul 31 11:16:49 dcerouter automount[23842]: failed to mount /mnt/device/133
Jul 31 11:16:50 dcerouter automount[23876]: lookup(program): lookup for 117 failed
Jul 31 11:16:50 dcerouter automount[23876]: failed to mount /mnt/device/117
...
...

Jul 31 11:21:07 dcerouter automount[9166]: failed to mount /mnt/device/133
Jul 31 11:21:08 dcerouter automount[9440]: lookup(program): lookup for 117 failed
Jul 31 11:21:08 dcerouter automount[9440]: failed to mount /mnt/device/117
Jul 31 11:21:09 dcerouter automount[9506]: lookup(program): lookup for 133 failed
Jul 31 11:21:09 dcerouter automount[9506]: failed to mount /mnt/device/133
Jul 31 11:21:10 dcerouter automount[9550]: lookup(program): lookup for 117 failed
Jul 31 11:21:10 dcerouter automount[9550]: failed to mount /mnt/device/117
Jul 31 11:21:17 dcerouter kernel: [  470.340000] rtc: lost 27 interrupts
Jul 31 11:21:19 dcerouter kernel: [  472.396000] rtc: lost 28 interrupts
Jul 31 11:21:25 dcerouter kernel: [  478.856000] eth0: too many iterations (6) in nv_nic_irq.
Jul 31 11:21:26 dcerouter kernel: [  479.852000] eth0: too many iterations (6) in nv_nic_irq.
Jul 31 11:21:49 dcerouter kernel: [  503.180000] rtc: lost 26 interrupts
Jul 31 11:22:08 dcerouter kernel: [  521.648000] rtc: lost 28 interrupts
Jul 31 11:22:10 dcerouter kernel: [  523.700000] rtc: lost 27 interrupts
Jul 31 11:22:14 dcerouter kernel: [  527.808000] rtc: lost 28 interrupts
Jul 31 11:22:18 dcerouter kernel: [  531.912000] rtc: lost 27 interrupts
Jul 31 11:22:20 dcerouter kernel: [  533.964000] rtc: lost 28 interrupts
Jul 31 11:22:22 dcerouter kernel: [  536.016000] rtc: lost 27 interrupts
Jul 31 11:22:24 dcerouter kernel: [  538.068000] rtc: lost 27 interrupts
Jul 31 11:22:49 dcerouter kernel: [  562.696000] rtc: lost 28 interrupts
Jul 31 11:22:51 dcerouter automount[13908]: lookup(program): lookup for 133 failed
Jul 31 11:22:51 dcerouter automount[13908]: failed to mount /mnt/device/133
Jul 31 11:22:52 dcerouter automount[14018]: lookup(program): lookup for 117 failed
Jul 31 11:22:52 dcerouter automount[14018]: failed to mount /mnt/device/117
Jul 31 11:22:53 dcerouter automount[14118]: lookup(program): lookup for 133 failed
Jul 31 11:22:53 dcerouter automount[14118]: failed to mount /mnt/device/133
Jul 31 11:22:54 dcerouter automount[14225]: lookup(program): lookup for 117 failed
Jul 31 11:22:54 dcerouter automount[14225]: failed to mount /mnt/device/117
Jul 31 11:22:56 dcerouter automount[14299]: lookup(program): lookup for 133 failed
Jul 31 11:22:56 dcerouter automount[14299]: failed to mount /mnt/device/133
Jul 31 11:22:57 dcerouter automount[14342]: lookup(program): lookup for 117 failed
Jul 31 11:22:57 dcerouter automount[14342]: failed to mount /mnt/device/117
Jul 31 11:22:58 dcerouter automount[14392]: lookup(program): lookup for 133 failed
Jul 31 11:22:58 dcerouter automount[14392]: failed to mount /mnt/device/133
Jul 31 11:22:59 dcerouter automount[14481]: lookup(program): lookup for 117 failed
Jul 31 11:22:59 dcerouter automount[14481]: failed to mount /mnt/device/117
Jul 31 11:23:02 dcerouter automount[14703]: lookup(program): lookup for 133 failed
Jul 31 11:23:02 dcerouter automount[14703]: failed to mount /mnt/device/133
Jul 31 11:23:03 dcerouter automount[14739]: lookup(program): lookup for 117 failed
Jul 31 11:23:03 dcerouter automount[14739]: failed to mount /mnt/device/117
Jul 31 11:23:04 dcerouter automount[14785]: lookup(program): lookup for 133 failed
Jul 31 11:23:04 dcerouter automount[14785]: failed to mount /mnt/device/133
Jul 31 11:23:05 dcerouter automount[14829]: lookup(program): lookup for 117 failed
Jul 31 11:23:05 dcerouter automount[14829]: failed to mount /mnt/device/117
Jul 31 11:23:06 dcerouter automount[14919]: lookup(program): lookup for 133 failed
Jul 31 11:23:06 dcerouter automount[14919]: failed to mount /mnt/device/133
Jul 31 11:23:07 dcerouter automount[15022]: lookup(program): lookup for 117 failed
Jul 31 11:23:07 dcerouter automount[15022]: failed to mount /mnt/device/117
Jul 31 11:23:08 dcerouter automount[15128]: lookup(program): lookup for 133 failed
Jul 31 11:23:08 dcerouter automount[15128]: failed to mount /mnt/device/133
Jul 31 11:23:08 dcerouter automount[15198]: lookup(program): lookup for 117 failed
Jul 31 11:23:08 dcerouter automount[15198]: failed to mount /mnt/device/117
Jul 31 11:23:19 dcerouter kernel: [  592.952000] eth0: too many iterations (6) in nv_nic_irq.
Jul 31 11:23:20 dcerouter kernel: [  593.952000] eth0: too many iterations (6) in nv_nic_irq.
Jul 31 11:23:21 dcerouter kernel: [  594.952000] eth0: too many iterations (6) in nv_nic_irq.
Jul 31 11:23:29 dcerouter kernel: [  602.960000] eth0: too many iterations (6) in nv_nic_irq.
Jul 31 11:23:30 dcerouter kernel: [  603.960000] eth0: too many iterations (6) in nv_nic_irq.
Jul 31 11:23:31 dcerouter kernel: [  604.964000] eth0: too many iterations (6) in nv_nic_irq.
Jul 31 11:23:36 dcerouter kernel: [  609.920000] rtc: lost 28 interrupts
Jul 31 11:23:38 dcerouter kernel: [  611.972000] rtc: lost 27 interrupts
Jul 31 11:23:40 dcerouter kernel: [  614.024000] rtc: lost 27 interrupts
Jul 31 11:23:48 dcerouter kernel: [  622.236000] rtc: lost 28 interrupts
Jul 31 11:23:53 dcerouter kernel: [  626.340000] rtc: lost 27 interrupts
Jul 31 11:23:55 dcerouter kernel: [  628.392000] rtc: lost 7 interrupts
Jul 31 11:23:57 dcerouter kernel: [  630.444000] rtc: lost 27 interrupts

dmesg shows that the sdb was kicked from the array, though i'm not sure why:

Code: [Select]

[    8.136000] Probing IDE interface ide0...
[    8.152000] sd 0:0:0:0: [sda] 976773168 512-byte hardware sectors (500108 MB)
[    8.152000] sd 0:0:0:0: [sda] Write Protect is off
[    8.152000] sd 0:0:0:0: [sda] Mode Sense: 00 3a 00 00
[    8.152000] sd 0:0:0:0: [sda] Write cache: enabled, read cache: enabled, doesn't support DPO or FUA
[    8.152000] sd 0:0:0:0: [sda] 976773168 512-byte hardware sectors (500108 MB)
[    8.152000] sd 0:0:0:0: [sda] Write Protect is off
[    8.152000] sd 0:0:0:0: [sda] Mode Sense: 00 3a 00 00
[    8.152000] sd 0:0:0:0: [sda] Write cache: enabled, read cache: enabled, doesn't support DPO or FUA
[    8.152000]  sda: sda1 sda2 < sda5 sda6 >
[    8.200000] sd 0:0:0:0: [sda] Attached SCSI disk
[    8.200000] sd 1:0:0:0: [sdb] 1953525168 512-byte hardware sectors (1000205 MB)
[    8.200000] sd 1:0:0:0: [sdb] Write Protect is off
[    8.200000] sd 1:0:0:0: [sdb] Mode Sense: 00 3a 00 00
[    8.200000] sd 1:0:0:0: [sdb] Write cache: enabled, read cache: enabled, doesn't support DPO or FUA
[    8.200000] sd 1:0:0:0: [sdb] 1953525168 512-byte hardware sectors (1000205 MB)
[    8.200000] sd 1:0:0:0: [sdb] Write Protect is off
[    8.200000] sd 1:0:0:0: [sdb] Mode Sense: 00 3a 00 00
[    8.200000] sd 1:0:0:0: [sdb] Write cache: enabled, read cache: enabled, doesn't support DPO or FUA
[    8.200000]  sdb: unknown partition table
[    8.208000] sd 1:0:0:0: [sdb] Attached SCSI disk
[    8.208000] sd 2:0:0:0: [sdc] 1953525168 512-byte hardware sectors (1000205 MB)
[    8.208000] sd 2:0:0:0: [sdc] Write Protect is off
[    8.208000] sd 2:0:0:0: [sdc] Mode Sense: 00 3a 00 00
[    8.208000] sd 2:0:0:0: [sdc] Write cache: enabled, read cache: enabled, doesn't support DPO or FUA
[    8.208000] sd 2:0:0:0: [sdc] 1953525168 512-byte hardware sectors (1000205 MB)
[    8.208000] sd 2:0:0:0: [sdc] Write Protect is off
[    8.208000] sd 2:0:0:0: [sdc] Mode Sense: 00 3a 00 00
[    8.208000] sd 2:0:0:0: [sdc] Write cache: enabled, read cache: enabled, doesn't support DPO or FUA
[    8.208000]  sdc: unknown partition table
[    8.212000] sd 2:0:0:0: [sdc] Attached SCSI disk
[    8.212000] sd 3:0:0:0: [sdd] 1953525168 512-byte hardware sectors (1000205 MB)
[    8.212000] sd 3:0:0:0: [sdd] Write Protect is off
[    8.212000] sd 3:0:0:0: [sdd] Mode Sense: 00 3a 00 00
[    8.212000] sd 3:0:0:0: [sdd] Write cache: enabled, read cache: enabled, doesn't support DPO or FUA
[    8.212000] sd 3:0:0:0: [sdd] 1953525168 512-byte hardware sectors (1000205 MB)
[    8.212000] sd 3:0:0:0: [sdd] Write Protect is off
[    8.212000] sd 3:0:0:0: [sdd] Mode Sense: 00 3a 00 00
[    8.212000] sd 3:0:0:0: [sdd] Write cache: enabled, read cache: enabled, doesn't support DPO or FUA
[    8.212000]  sdd: unknown partition table
[    8.216000] sd 3:0:0:0: [sdd] Attached SCSI disk
[    8.220000] sd 0:0:0:0: Attached scsi generic sg0 type 0
[    8.220000] sd 1:0:0:0: Attached scsi generic sg1 type 0
[    8.220000] sd 2:0:0:0: Attached scsi generic sg2 type 0
[    8.220000] sd 3:0:0:0: Attached scsi generic sg3 type 0
[    8.496000] EXT3-fs: INFO: recovery required on readonly filesystem.
[    8.496000] EXT3-fs: write access will be enabled during recovery.
[    8.872000] hda: JLMS DVD-ROM XJ-HD166, ATAPI CD/DVD-ROM drive
[    9.404000] ieee1394: Host added: ID:BUS[0-00:1023]  GUID[0011d80000d41943]
[    9.656000] hdb: SONY CD-RW/DVD-ROM CRX310EE, ATAPI CD/DVD-ROM drive
[    9.712000] ide0 at 0x1f0-0x1f7,0x3f6 on irq 14
[    9.720000] Probing IDE interface ide1...
[   10.288000] r8169 Gigabit Ethernet driver 2.2LK loaded
[   10.288000] ACPI: PCI Interrupt Link [APC2] enabled at IRQ 17
[   10.288000] ACPI: PCI Interrupt 0000:01:09.0[A] -> Link [APC2] -> GSI 17 (level, low) -> IRQ 21
[   10.288000] eth1: RTL8110s at 0xf88a6000, 00:18:f8:09:ce:90, XID 04000000 IRQ 21
[   10.296000] hda: ATAPI 48X DVD-ROM drive, 512kB Cache, UDMA(33)
[   10.296000] Uniform CD-ROM driver Revision: 3.20
[   10.296000] hdb: ATAPI 63X DVD-ROM CD-R/RW drive, 1536kB Cache, UDMA(33)
[   11.036000] kjournald starting.  Commit interval 5 seconds

[   11.036000] EXT3-fs: sda1: orphan cleanup on readonly fs
[   11.036000] ext3_orphan_cleanup: deleting unreferenced inode 37453836
[   11.036000] ext3_orphan_cleanup: deleting unreferenced inode 36438025
[   11.036000] ext3_orphan_cleanup: deleting unreferenced inode 36438024
[   11.036000] ext3_orphan_cleanup: deleting unreferenced inode 36438023
[   11.036000] ext3_orphan_cleanup: deleting unreferenced inode 36438022
[   11.036000] ext3_orphan_cleanup: deleting unreferenced inode 36438021
[   11.036000] EXT3-fs: sda1: 6 orphan inodes deleted
[   11.036000] EXT3-fs: recovery complete.
[   11.040000] EXT3-fs: mounted filesystem with ordered data mode.
[   19.396000] r8169: eth1: link up
[   20.112000] md: md0 stopped.
[   20.376000] md: bind<sdb>
[   20.376000] md: bind<sdd>
[   20.376000] md: bind<sdc>
[   20.376000] md: kicking non-fresh sdb from array!
[   20.376000] md: unbind<sdb>
[   20.376000] md: export_rdev(sdb)
[   20.476000] i2c-adapter i2c-0: nForce2 SMBus adapter at 0x4c00
[   20.476000] i2c-adapter i2c-1: nForce2 SMBus adapter at 0x4c40
[   20.760000] raid5: device sdc operational as raid disk 1
[   20.760000] raid5: device sdd operational as raid disk 2
[   20.760000] raid5: allocated 3163kB for md0
[   20.760000] raid5: raid level 5 set md0 active with 2 out of 3 devices, algorithm 2
[   20.760000] RAID5 conf printout:
[   20.760000]  --- rd:3 wd:2
[   20.760000]  disk 1, o:1, dev:sdc
[   20.760000]  disk 2, o:1, dev:sdd
[   20.784000] input: PC Speaker as /class/input/input3
[   20.936000] Linux agpgart interface v0.102 (c) Dave Jones
[   20.948000] usbcore: registered new interface driver usbserial

http://pastebin.com/m78b79e18

[jondecker76]

Some clarification:
The errors for devices 117 and 113 in the post above are to disk drives in a couple of media directors that were turned off, so those are unrelated...

Also, the important parts of syslog are:

Code: [Select]

Jul 31 11:14:06 dcerouter kernel: [    8.136000] Probing IDE interface ide0...
Jul 31 11:14:06 dcerouter kernel: [    8.152000] sd 0:0:0:0: [sda] 976773168 512-byte hardware sectors (500108 MB)
Jul 31 11:14:06 dcerouter kernel: [    8.152000] sd 0:0:0:0: [sda] Write Protect is off
Jul 31 11:14:06 dcerouter kernel: [    8.152000] sd 0:0:0:0: [sda] Mode Sense: 00 3a 00 00
Jul 31 11:14:06 dcerouter kernel: [    8.152000] sd 0:0:0:0: [sda] Write cache: enabled, read cache: enabled, doesn't support DPO or FUA
Jul 31 11:14:06 dcerouter kernel: [    8.152000] sd 0:0:0:0: [sda] 976773168 512-byte hardware sectors (500108 MB)
Jul 31 11:14:06 dcerouter kernel: [    8.152000] sd 0:0:0:0: [sda] Write Protect is off
Jul 31 11:14:06 dcerouter kernel: [    8.152000] sd 0:0:0:0: [sda] Mode Sense: 00 3a 00 00
Jul 31 11:14:06 dcerouter kernel: [    8.152000] sd 0:0:0:0: [sda] Write cache: enabled, read cache: enabled, doesn't support DPO or FUA
Jul 31 11:14:06 dcerouter kernel: [    8.152000]  sda: sda1 sda2 < sda5 sda6 >
Jul 31 11:14:06 dcerouter kernel: [    8.200000] sd 0:0:0:0: [sda] Attached SCSI disk
Jul 31 11:14:06 dcerouter kernel: [    8.200000] sd 1:0:0:0: [sdb] 1953525168 512-byte hardware sectors (1000205 MB)
Jul 31 11:14:06 dcerouter kernel: [    8.200000] sd 1:0:0:0: [sdb] Write Protect is off
Jul 31 11:14:06 dcerouter kernel: [    8.200000] sd 1:0:0:0: [sdb] Mode Sense: 00 3a 00 00
Jul 31 11:14:06 dcerouter kernel: [    8.200000] sd 1:0:0:0: [sdb] Write cache: enabled, read cache: enabled, doesn't support DPO or FUA
Jul 31 11:14:06 dcerouter kernel: [    8.200000] sd 1:0:0:0: [sdb] 1953525168 512-byte hardware sectors (1000205 MB)
Jul 31 11:14:06 dcerouter kernel: [    8.200000] sd 1:0:0:0: [sdb] Write Protect is off
Jul 31 11:14:06 dcerouter kernel: [    8.200000] sd 1:0:0:0: [sdb] Mode Sense: 00 3a 00 00
Jul 31 11:14:06 dcerouter kernel: [    8.200000] sd 1:0:0:0: [sdb] Write cache: enabled, read cache: enabled, doesn't support DPO or FUA
Jul 31 11:14:06 dcerouter kernel: [    8.200000]  sdb: unknown partition table
Jul 31 11:14:06 dcerouter kernel: [    8.208000] sd 1:0:0:0: [sdb] Attached SCSI disk
Jul 31 11:14:06 dcerouter kernel: [    8.208000] sd 2:0:0:0: [sdc] 1953525168 512-byte hardware sectors (1000205 MB)
Jul 31 11:14:06 dcerouter kernel: [    8.208000] sd 2:0:0:0: [sdc] Write Protect is off
Jul 31 11:14:06 dcerouter kernel: [    8.208000] sd 2:0:0:0: [sdc] Mode Sense: 00 3a 00 00
Jul 31 11:14:06 dcerouter kernel: [    8.208000] sd 2:0:0:0: [sdc] Write cache: enabled, read cache: enabled, doesn't support DPO or FUA
Jul 31 11:14:06 dcerouter kernel: [    8.208000] sd 2:0:0:0: [sdc] 1953525168 512-byte hardware sectors (1000205 MB)
Jul 31 11:14:06 dcerouter kernel: [    8.208000] sd 2:0:0:0: [sdc] Write Protect is off
Jul 31 11:14:06 dcerouter kernel: [    8.208000] sd 2:0:0:0: [sdc] Mode Sense: 00 3a 00 00
Jul 31 11:14:06 dcerouter kernel: [    8.208000] sd 2:0:0:0: [sdc] Write cache: enabled, read cache: enabled, doesn't support DPO or FUA
Jul 31 11:14:06 dcerouter kernel: [    8.208000]  sdc: unknown partition table
Jul 31 11:14:06 dcerouter kernel: [    8.212000] sd 2:0:0:0: [sdc] Attached SCSI disk
Jul 31 11:14:06 dcerouter kernel: [    8.212000] sd 3:0:0:0: [sdd] 1953525168 512-byte hardware sectors (1000205 MB)
Jul 31 11:14:06 dcerouter kernel: [    8.212000] sd 3:0:0:0: [sdd] Write Protect is off
Jul 31 11:14:06 dcerouter kernel: [    8.212000] sd 3:0:0:0: [sdd] Mode Sense: 00 3a 00 00
Jul 31 11:14:06 dcerouter kernel: [    8.212000] sd 3:0:0:0: [sdd] Write cache: enabled, read cache: enabled, doesn't support DPO or FUA
Jul 31 11:14:06 dcerouter kernel: [    8.212000] sd 3:0:0:0: [sdd] 1953525168 512-byte hardware sectors (1000205 MB)
Jul 31 11:14:06 dcerouter kernel: [    8.212000] sd 3:0:0:0: [sdd] Write Protect is off
Jul 31 11:14:06 dcerouter kernel: [    8.212000] sd 3:0:0:0: [sdd] Mode Sense: 00 3a 00 00
Jul 31 11:14:06 dcerouter kernel: [    8.212000] sd 3:0:0:0: [sdd] Write cache: enabled, read cache: enabled, doesn't support DPO or FUA
Jul 31 11:14:06 dcerouter kernel: [    8.212000]  sdd: unknown partition table
Jul 31 11:14:06 dcerouter kernel: [    8.216000] sd 3:0:0:0: [sdd] Attached SCSI disk
Jul 31 11:14:06 dcerouter kernel: [    8.220000] sd 0:0:0:0: Attached scsi generic sg0 type 0
Jul 31 11:14:06 dcerouter kernel: [    8.220000] sd 1:0:0:0: Attached scsi generic sg1 type 0
Jul 31 11:14:06 dcerouter kernel: [    8.220000] sd 2:0:0:0: Attached scsi generic sg2 type 0
Jul 31 11:14:06 dcerouter kernel: [    8.220000] sd 3:0:0:0: Attached scsi generic sg3 type 0
Jul 31 11:14:06 dcerouter kernel: [    8.496000] EXT3-fs: INFO: recovery required on readonly filesystem.
Jul 31 11:14:06 dcerouter kernel: [    8.496000] EXT3-fs: write access will be enabled during recovery.
Jul 31 11:14:06 dcerouter kernel: [    8.872000] hda: JLMS DVD-ROM XJ-HD166, ATAPI CD/DVD-ROM drive
Jul 31 11:14:06 dcerouter kernel: [    9.404000] ieee1394: Host added: ID:BUS[0-00:1023]  GUID[0011d80000d41943]
Jul 31 11:14:06 dcerouter kernel: [    9.656000] hdb: SONY CD-RW/DVD-ROM CRX310EE, ATAPI CD/DVD-ROM drive
Jul 31 11:14:06 dcerouter kernel: [    9.712000] ide0 at 0x1f0-0x1f7,0x3f6 on irq 14
Jul 31 11:14:06 dcerouter kernel: [    9.720000] Probing IDE interface ide1...
Jul 31 11:14:06 dcerouter kernel: [   10.288000] r8169 Gigabit Ethernet driver 2.2LK loaded
Jul 31 11:14:06 dcerouter kernel: [   10.288000] ACPI: PCI Interrupt Link [APC2] enabled at IRQ 17
Jul 31 11:14:06 dcerouter kernel: [   10.288000] ACPI: PCI Interrupt 0000:01:09.0[A] -> Link [APC2] -> GSI 17 (level, low) -> IRQ 21
Jul 31 11:14:06 dcerouter kernel: [   10.288000] eth1: RTL8110s at 0xf88a6000, 00:18:f8:09:ce:90, XID 04000000 IRQ 21
Jul 31 11:14:06 dcerouter kernel: [   10.296000] hda: ATAPI 48X DVD-ROM drive, 512kB Cache, UDMA(33)
Jul 31 11:14:06 dcerouter kernel: [   10.296000] Uniform CD-ROM driver Revision: 3.20
Jul 31 11:14:06 dcerouter kernel: [   10.296000] hdb: ATAPI 63X DVD-ROM CD-R/RW drive, 1536kB Cache, UDMA(33)
Jul 31 11:14:06 dcerouter kernel: [   11.036000] kjournald starting.  Commit interval 5 seconds
Jul 31 11:14:06 dcerouter kernel: [   11.036000] EXT3-fs: sda1: orphan cleanup on readonly fs
Jul 31 11:14:06 dcerouter kernel: [   11.036000] ext3_orphan_cleanup: deleting unreferenced inode 37453836
Jul 31 11:14:06 dcerouter kernel: [   11.036000] ext3_orphan_cleanup: deleting unreferenced inode 36438025
Jul 31 11:14:06 dcerouter kernel: [   11.036000] ext3_orphan_cleanup: deleting unreferenced inode 36438024
Jul 31 11:14:06 dcerouter kernel: [   11.036000] ext3_orphan_cleanup: deleting unreferenced inode 36438023
Jul 31 11:14:06 dcerouter kernel: [   11.036000] ext3_orphan_cleanup: deleting unreferenced inode 36438022
Jul 31 11:14:06 dcerouter kernel: [   11.036000] ext3_orphan_cleanup: deleting unreferenced inode 36438021
Jul 31 11:14:06 dcerouter kernel: [   11.036000] EXT3-fs: sda1: 6 orphan inodes deleted
Jul 31 11:14:06 dcerouter kernel: [   11.036000] EXT3-fs: recovery complete.
Jul 31 11:14:06 dcerouter kernel: [   11.040000] EXT3-fs: mounted filesystem with ordered data mode.
Jul 31 11:14:06 dcerouter kernel: [   19.396000] r8169: eth1: link up
Jul 31 11:14:06 dcerouter kernel: [   20.112000] md: md0 stopped.
Jul 31 11:14:06 dcerouter kernel: [   20.376000] md: bind<sdb>
Jul 31 11:14:06 dcerouter kernel: [   20.376000] md: bind<sdd>
Jul 31 11:14:06 dcerouter kernel: [   20.376000] md: bind<sdc>
Jul 31 11:14:06 dcerouter kernel: [   20.376000] md: kicking non-fresh sdb from array!
Jul 31 11:14:06 dcerouter kernel: [   20.376000] md: unbind<sdb>
Jul 31 11:14:06 dcerouter kernel: [   20.376000] md: export_rdev(sdb)
Jul 31 11:14:06 dcerouter kernel: [   20.476000] i2c-adapter i2c-0: nForce2 SMBus adapter at 0x4c00
Jul 31 11:14:06 dcerouter kernel: [   20.476000] i2c-adapter i2c-1: nForce2 SMBus adapter at 0x4c40
Jul 31 11:14:06 dcerouter kernel: [   20.760000] raid5: device sdc operational as raid disk 1
Jul 31 11:14:06 dcerouter kernel: [   20.760000] raid5: device sdd operational as raid disk 2
Jul 31 11:14:06 dcerouter kernel: [   20.760000] raid5: allocated 3163kB for md0
Jul 31 11:14:06 dcerouter kernel: [   20.760000] raid5: raid level 5 set md0 active with 2 out of 3 devices, algorithm 2
Jul 31 11:14:06 dcerouter kernel: [   20.760000] RAID5 conf printout:
Jul 31 11:14:06 dcerouter kernel: [   20.760000]  --- rd:3 wd:2
Jul 31 11:14:06 dcerouter kernel: [   20.760000]  disk 1, o:1, dev:sdc
Jul 31 11:14:06 dcerouter kernel: [   20.760000]  disk 2, o:1, dev:sdd


[jondecker76]

Working with some of the guys on IRC right now.. Running a badblocks test on the drive that keeps getting booted

[mikedehaan]

Any luck?

[jondecker76]

I started the badblocks scan last thursday night before going on a short vacation for the weekend. When I had come back last night, the core was locked up, so the scan never completed. I rebooted the core this morning and started a badblocks scan again - Hopefully I will have results tonight

[jondecker76]

Still no luck. Started badblocks (again) this morning at about 06:00. By 18:00, the core was dead-locked again, and the scan was not finished.

Code: [Select]

linuxmce@dcerouter:~$ sudo badblocks -vws /dev/sdb
[sudo] password for linuxmce:
Checking for bad blocks in read-write mode
From block 0 to 976762584
Testing with pattern 0xaa: done                               
Reading and comparing: done                               
Testing with pattern 0x55:        95983808/      976762583Read from remote host 192.168.80.1: Connection reset by peer
Connection to 192.168.80.1 closed.


Having over 30 hours of badblocks testing (both which crashed at different places) it is apparent that I now have a stability issue (I had used this setup based on an M2NPV-VM for 6 months with no stability issues), so I have to trace that down as well.

Regarding badblocks - I'm not quite sure how it is supposed to work. Its starting to look like it would let it run forever if I let it.. For A test, I did a check from block 900000000 to 976762584. As of this moment, here is my output at the terminal:

Code: [Select]

linuxmce@dcerouter:~$ sudo badblocks -vws /dev/sdb 976762583 900000000
[sudo] password for linuxmce:
last_block = 976762583 (976762583)
from_count = 900000000
Checking for bad blocks in read-write mode
From block 900000000 to 976762584
Testing with pattern 0xaa: 0done                               
Reading and comparing: done                               
Testing with pattern 0x55: done                               
Reading and comparing: done                               
Testing with pattern 0xff: done     
Reading and comparing:     938319152/      976762584
First it did the test with 0xAA, then with 0X55, now its on 0XFF... With this just continue forever? How will I know if it finds a problem? Checking the man page for badblocks didn't yield an answer.

Anyways, not sure where to go from here.. I have not seen any evidence that the drive is bad yet. I don't want to order another drive until I know for sure that it is bad - but as you can see I'm about 4 days into just trying to find out if there is a problem with the drive - with no luck. I still believe there is a bug in the RAID implementation

[jondecker76]

Ok, things didn't get to far on this last night..  A badblocks scan (of about 10% of the drive) did finally complete and I now know what to expect. So far, I have scanned the last 20% of the drive, 10% at a time, with no errors shown.

linuxmce@dcerouter:~$ sudo badblocks -vws /dev/sdb 976762583 900000000
[sudo] password for linuxmce:
last_block = 976762583 (976762583)
from_count = 900000000
Checking for bad blocks in read-write mode
From block 900000000 to 976762584
Testing with pattern 0xaa: 0done                               
Reading and comparing: done                               
Testing with pattern 0x55: done                               
Reading and comparing: done                               
Testing with pattern 0xff: done                               
Reading and comparing: done                               
Testing with pattern 0x00: done                               
Reading and comparing: done                               
Pass completed, 0 bad blocks found.
linuxmce@dcerouter:~$ sudo badblocks -vws /dev/sdb 900000000 800000000
[sudo] password for linuxmce:
last_block = 900000000 (900000000)
from_count = 800000000
Checking for bad blocks in read-write mode
From block 800000000 to 900000001
Testing with pattern 0xaa: done                               
Reading and comparing: done                               
Testing with pattern 0x55: done                               
Reading and comparing: done                               
Testing with pattern 0xff: done                               
Reading and comparing: done                               
Testing with pattern 0x00: done                               
Reading and comparing: done                               
Pass completed, 0 bad blocks found.
linuxmce@dcerouter:~$ Read from remote host 192.168.80.1: Connection reset by peer
Connection to 192.168.80.1 closed.

Considering that the array was just about 100% full both times I've had RAID problems, I'm still going to guess that the drive is good. I'll continue to run badblocks scans of about 10% at a time though.

Also, when I woke up this morning, the core was hard locked again. Therefore, I think its safe to say that the badblocks is not causing the crashes - rather that a full scan takes so long, that with my instability problem it just always crashes before it completes.

As far as the instability, I'm not sure where to start.. My syslog shows 2 things:
1) I am seeing very very often in the log that NETDEV WATCHDOG transmit timed out, following pages of dumped rx/tx registers:

Code: [Select]

Aug  5 05:21:28 dcerouter kernel: [46401.988000] NETDEV WATCHDOG: eth0: transmit timed out
Aug  5 05:21:28 dcerouter kernel: [46401.988000] eth0: Got tx_timeout. irq: 00000036
Aug  5 05:21:28 dcerouter kernel: [46401.988000] eth0: Ring at 1f9c0000
Aug  5 05:21:28 dcerouter kernel: [46401.988000] eth0: Dumping tx registers
Aug  5 05:21:28 dcerouter kernel: [46401.988000]   0: 00000036 000000ff 00000003 001203ca 00000000 00000000 00000000 00000000
Aug  5 05:21:28 dcerouter kernel: [46401.988000]  20: 00000000 f0000000 00000000 00000000 00000000 00000000 00000000 00000000
Aug  5 05:21:28 dcerouter kernel: [46401.988000]  40: 0420e20e 0000a455 00002e20 00000000 00000000 00000000 00000000 00000000
...
...
...

2) My log is absolutely flooded, begining to end, with failed drive mounting. Also, the drives that are failing are hard drives that are in other media directors that are offline. I can understand the failed mount (as the drive is offline), but honestly, should it be trying to mount it hundreds of times each minute, 24 hours a day?

Code: [Select]

Aug  5 05:46:10 dcerouter automount[12112]: lookup(program): lookup for 133 failed
Aug  5 05:46:10 dcerouter automount[12112]: failed to mount /mnt/device/133
Aug  5 05:46:11 dcerouter automount[12160]: lookup(program): lookup for 117 failed
Aug  5 05:46:11 dcerouter automount[12160]: failed to mount /mnt/device/117
Aug  5 05:46:12 dcerouter automount[12205]: lookup(program): lookup for 133 failed
Aug  5 05:46:12 dcerouter automount[12205]: failed to mount /mnt/device/133
Aug  5 05:46:13 dcerouter automount[12247]: lookup(program): lookup for 117 failed
Aug  5 05:46:13 dcerouter automount[12247]: failed to mount /mnt/device/117
Aug  5 05:46:15 dcerouter automount[12469]: lookup(program): lookup for 133 failed
Aug  5 05:46:15 dcerouter automount[12469]: failed to mount /mnt/device/133
Aug  5 05:46:16 dcerouter automount[12539]: lookup(program): lookup for 117 failed
Aug  5 05:46:16 dcerouter automount[12539]: failed to mount /mnt/device/117
Aug  5 05:46:16 dcerouter automount[12582]: lookup(program): lookup for 133 failed
Aug  5 05:46:16 dcerouter automount[12582]: failed to mount /mnt/device/133
Aug  5 05:46:17 dcerouter automount[12616]: lookup(program): lookup for 117 failed
Aug  5 05:46:17 dcerouter automount[12616]: failed to mount /mnt/device/117
Aug  5 05:46:19 dcerouter automount[12679]: lookup(program): lookup for 133 failed
Aug  5 05:46:19 dcerouter automount[12679]: failed to mount /mnt/device/133
Aug  5 05:46:20 dcerouter automount[12724]: lookup(program): lookup for 117 failed
Aug  5 05:46:20 dcerouter automount[12724]: failed to mount /mnt/device/117
Aug  5 05:46:21 dcerouter automount[12881]: lookup(program): lookup for 133 failed
Aug  5 05:46:21 dcerouter automount[12881]: failed to mount /mnt/device/133
Aug  5 05:46:22 dcerouter automount[12980]: lookup(program): lookup for 117 failed
Aug  5 05:46:22 dcerouter automount[12980]: failed to mount /mnt/device/117
...
...
...

Any help would be appreciated. Looks like I'm down and out until I can get this fixed, as this is a  very busy time of year for me (wake up at 0500 for work, get home at about 15:30, kids football practice starts at 1700, then we get home at 2000, then its time for showers etc, then bedtime.) so I only have about an hour or two each day to try to get things going again.

[hari]

are you using the forcedeth driver? Does the core completely lock up or does the network get stuck?
I'd try Zaerc's approach with the console logging.

best regards,
hari

[jondecker76]

Hari - now that I know the network is getting killed, it may not be a hard lockup (I thought it was, as I could not ssh into the core - but of course this would fail with no networking on the core) So I will have to look a little deeper into whether it is actually hard-locking or not. Reading a few posts on the Internet, the NETDEV WATCHDOG error does indeed kill the networking.

I'm just not sure why after 6 months of using this core I start getting this error. The only network change that has been made recently is replacing my old 8-port gigabit switch (a cheap D-Link from office max)/Belkin cheapo wireless-G router as an access point with a 24 port Netgear gigabit rackmount switch (GS524NA)/Netgear WG302 Access point. I sure hope this is not related, as the switch/access point was fairly expensive, and I need the extra ports and stability offered by the higher end equipment!

I will try Zaercs suggestion and see exactly where at in the log things are breaking

[JimmyGosling]

I don't see a GS524NA on Netgear's site, but I have the Netgear JGS524.  I think we're talking the same thing.  Mine has been running rock solid for about a year and a half now.