raid1 issue after disk failure: both disks of the array are still active

DISCUSSION Niccolò Belli 6 participants 27 messages Sep 13, 2012 – Sep 17, 2012 2 messages not in the archive MD RAID

Share & tools

Niccolò Belli

author

2012-09-13 10:01 UTC #0 lore raw

Hi,
I have a raid1 array with two disks, distro is Squeeze amd64. /dev/sda is slowly dying, here is a snippet of "smartctl -a /dev/sda":

197 Current_Pending_Sector 0x0012 100 100 000 Old_age Always
- 2
198 Offline_Uncorrectable 0x0030 100 100 000 Old_age Offline
- 1

The bad sector is in the second half-MB of the disk, in fact with "dd if=/dev/sda1 of=/dev/null bs=524228 count=1 skip=1" I get this output in /var/log/syslog:

root@asterisk:~# dd if=/dev/sda1 of=/dev/null bs=524228 count=1 skip=1
0+1 record dentro
0+1 record fuori
430140 byte (430 kB) copiati, 11,7265 s, 36,7 kB/s

Sep 12 22:15:02 asterisk kernel: [ 8921.561978] dd: sending ioctl 80306d02 to a partition!
Sep 12 22:15:02 asterisk kernel: [ 8921.561986] dd: sending ioctl 80306d02 to a partition!
Sep 12 22:15:03 asterisk kernel: [ 8922.529099] ata3.00: exception Emask 0x0 SAct 0x0 SErr 0x0 action 0x0
Sep 12 22:15:03 asterisk kernel: [ 8922.531774] ata3.00: BMDMA stat 0x44
Sep 12 22:15:03 asterisk kernel: [ 8922.533547] ata3.00: failed command: READ DMA
Sep 12 22:15:03 asterisk kernel: [ 8922.535313] ata3.00: cmd c8/00:08:48:0f:00/00:00:00:00:00/e0 tag 0 dma 4096 in
Sep 12 22:15:03 asterisk kernel: [ 8922.535316]          res 51/40:00:48:0f:00/40:00:00:00:00/e0 Emask 0x9 (media error)
Sep 12 22:15:03 asterisk kernel: [ 8922.538891] ata3.00: status: { DRDY ERR }
Sep 12 22:15:03 asterisk kernel: [ 8922.540675] ata3.00: error: { UNC }
Sep 12 22:15:04 asterisk kernel: [ 8923.508206] ata3.00: configured for UDMA/133
Sep 12 22:15:04 asterisk kernel: [ 8923.508220] ata3: EH complete
Sep 12 22:15:05 asterisk kernel: [ 8924.469512] ata3.00: exception Emask 0x0 SAct 0x0 SErr 0x0 action 0x0
Sep 12 22:15:05 asterisk kernel: [ 8924.472323] ata3.00: BMDMA stat 0x44
Sep 12 22:15:05 asterisk kernel: [ 8924.475260] ata3.00: failed command: READ DMA
Sep 12 22:15:05 asterisk kernel: [ 8924.477023] ata3.00: cmd c8/00:08:48:0f:00/00:00:00:00:00/e0 tag 0 dma 4096 in
Sep 12 22:15:05 asterisk kernel: [ 8924.477025]          res 51/40:00:48:0f:00/40:00:00:00:00/e0 Emask 0x9 (media error)
Sep 12 22:15:05 asterisk kernel: [ 8924.480595] ata3.00: status: { DRDY ERR }
Sep 12 22:15:05 asterisk kernel: [ 8924.482370] ata3.00: error: { UNC }
Sep 12 22:15:06 asterisk kernel: [ 8925.452209] ata3.00: configured for UDMA/133
Sep 12 22:15:06 asterisk kernel: [ 8925.452224] ata3: EH complete
Sep 12 22:15:07 asterisk kernel: [ 8926.418504] ata3.00: exception Emask 0x0 SAct 0x0 SErr 0x0 action 0x0
Sep 12 22:15:07 asterisk kernel: [ 8926.420741] ata3.00: BMDMA stat 0x44
Sep 12 22:15:07 asterisk kernel: [ 8926.422486] ata3.00: failed command: READ DMA
Sep 12 22:15:07 asterisk kernel: [ 8926.424279] ata3.00: cmd c8/00:08:48:0f:00/00:00:00:00:00/e0 tag 0 dma 4096 in
Sep 12 22:15:07 asterisk kernel: [ 8926.424281]          res 51/40:00:48:0f:00/40:00:00:00:00/e0 Emask 0x9 (media error)
Sep 12 22:15:07 asterisk kernel: [ 8926.427861] ata3.00: status: { DRDY ERR }
Sep 12 22:15:07 asterisk kernel: [ 8926.429660] ata3.00: error: { UNC }
Sep 12 22:15:08 asterisk kernel: [ 8927.396270] ata3.00: configured for UDMA/133
Sep 12 22:15:08 asterisk kernel: [ 8927.396285] ata3: EH complete
Sep 12 22:15:09 asterisk kernel: [ 8928.359173] ata3.00: exception Emask 0x0 SAct 0x0 SErr 0x0 action 0x0
Sep 12 22:15:09 asterisk kernel: [ 8928.361647] ata3.00: BMDMA stat 0x44
Sep 12 22:15:09 asterisk kernel: [ 8928.364273] ata3.00: failed command: READ DMA
Sep 12 22:15:09 asterisk kernel: [ 8928.366028] ata3.00: cmd c8/00:08:48:0f:00/00:00:00:00:00/e0 tag 0 dma 4096 in
Sep 12 22:15:09 asterisk kernel: [ 8928.366030]          res 51/40:00:48:0f:00/40:00:00:00:00/e0 Emask 0x9 (media error)
Sep 12 22:15:09 asterisk kernel: [ 8928.369643] ata3.00: status: { DRDY ERR }
Sep 12 22:15:09 asterisk kernel: [ 8928.371420] ata3.00: error: { UNC }
Sep 12 22:15:10 asterisk kernel: [ 8929.340218] ata3.00: configured for UDMA/133
Sep 12 22:15:10 asterisk kernel: [ 8929.340233] ata3: EH complete
Sep 12 22:15:11 asterisk kernel: [ 8930.332648] ata3.00: exception Emask 0x0 SAct 0x0 SErr 0x0 action 0x0
Sep 12 22:15:11 asterisk kernel: [ 8930.334453] ata3.00: BMDMA stat 0x44
Sep 12 22:15:11 asterisk kernel: [ 8930.336245] ata3.00: failed command: READ DMA
Sep 12 22:15:11 asterisk kernel: [ 8930.337995] ata3.00: cmd c8/00:08:48:0f:00/00:00:00:00:00/e0 tag 0 dma 4096 in
Sep 12 22:15:11 asterisk kernel: [ 8930.337998]          res 51/40:00:48:0f:00/40:00:00:00:00/e0 Emask 0x9 (media error)
Sep 12 22:15:11 asterisk kernel: [ 8930.341583] ata3.00: status: { DRDY ERR }
Sep 12 22:15:11 asterisk kernel: [ 8930.343360] ata3.00: error: { UNC }
Sep 12 22:15:12 asterisk kernel: [ 8931.344205] ata3.00: configured for UDMA/133
Sep 12 22:15:12 asterisk kernel: [ 8931.344220] ata3: EH complete
Sep 12 22:15:13 asterisk kernel: [ 8932.306376] ata3.00: exception Emask 0x0 SAct 0x0 SErr 0x0 action 0x0
Sep 12 22:15:13 asterisk kernel: [ 8932.308201] ata3.00: BMDMA stat 0x44
Sep 12 22:15:13 asterisk kernel: [ 8932.309948] ata3.00: failed command: READ DMA
Sep 12 22:15:13 asterisk kernel: [ 8932.311695] ata3.00: cmd c8/00:08:48:0f:00/00:00:00:00:00/e0 tag 0 dma 4096 in
Sep 12 22:15:13 asterisk kernel: [ 8932.311697]          res 51/40:00:48:0f:00/40:00:00:00:00/e0 Emask 0x9 (media error)
Sep 12 22:15:13 asterisk kernel: [ 8932.315262] ata3.00: status: { DRDY ERR }
Sep 12 22:15:13 asterisk kernel: [ 8932.317070] ata3.00: error: { UNC }
Sep 12 22:15:14 asterisk kernel: [ 8933.284204] ata3.00: configured for UDMA/133
Sep 12 22:15:14 asterisk kernel: [ 8933.284234] sd 2:0:0:0: [sda] Unhandled sense code
Sep 12 22:15:14 asterisk kernel: [ 8933.284237] sd 2:0:0:0: [sda] Result: hostbyte=DID_OK driverbyte=DRIVER_SENSE
Sep 12 22:15:14 asterisk kernel: [ 8933.284241] sd 2:0:0:0: [sda]  Sense Key : Medium Error [current] [descriptor]
Sep 12 22:15:14 asterisk kernel: [ 8933.284246] Descriptor sense data with sense descriptors (in hex):
Sep 12 22:15:14 asterisk kernel: [ 8933.284248]         72 03 11 04 00 00 00 0c 00 0a 80 00 00 00 00 00
Sep 12 22:15:14 asterisk kernel: [ 8933.284256]         00 00 0f 48
Sep 12 22:15:14 asterisk kernel: [ 8933.284260] sd 2:0:0:0: [sda]  Add. Sense: Unrecovered read error - auto reallocate failed
Sep 12 22:15:14 asterisk kernel: [ 8933.284267] sd 2:0:0:0: [sda] CDB: Read(10): 28 00 00 00 0f 48 00 00 08 00
Sep 12 22:15:14 asterisk kernel: [ 8933.284274] end_request: I/O error, dev sda, sector 3912
Sep 12 22:15:14 asterisk kernel: [ 8933.286065] Buffer I/O error on device sda1, logical block 233
Sep 12 22:15:14 asterisk kernel: [ 8933.287889] ata3: EH complete

*Why doesn't it fail the first hard disk of the array!!??*

root@asterisk:~# cat /proc/mdstat
Personalities : [raid1]
md1 : active raid1 sda2[0] sdb2[1]
      949236 blocks super 1.2 [2/2] [UU]

md0 : active raid1 sda1[0] sdb1[1]

      311619448 blocks super 1.2 [2/2] [UU]

unused devices: <none>

root@asterisk:~# mdadm --detail /dev/md0
/dev/md0:
        Version : 1.2
  Creation Time : Fri Jun 15 22:45:13 2012
     Raid Level : raid1
     Array Size : 311619448 (297.18 GiB 319.10 GB)
  Used Dev Size : 311619448 (297.18 GiB 319.10 GB)
   Raid Devices : 2
  Total Devices : 2
    Persistence : Superblock is persistent

Update Time : Wed Sep 12 22:07:58 2012
State : clean
Active Devices : 2
Working Devices : 2
Failed Devices : 0
Spare Devices : 0

Name : asterisk:0 (local to host asterisk) UUID : cea0c4c3:181e2ee3:e4d1f3c0:1008ea62
Events : 68

Number Major Minor RaidDevice State
0 8 1 0 active sync /dev/sda1
1 8 17 1 active sync /dev/sdb1

As you can see the firmware of the hard disk reports a read error and linux still doesn't fail the drive: this is the best way to corrupt data As far as I know it should fail the bad drive or at least try to resync it allowing the firmware to reallocate the bad sectors on write.

I really want to understand how raid1 is expected to work, I simply cannot trust something like this. I'd like to take advantage of the failure to learn something about linux's raid1 behavior.

Thanks,
Niccolò

More info about the failed disk:

root@asterisk:~# smartctl -a /dev/sda
smartctl 5.41 2011-06-09 r3365 [x86_64-linux-3.2.0-2-amd64] (local build)
Copyright (C) 2002-11 by Bruce Allen, http://smartmontools.sourceforge.net

=== START OF INFORMATION SECTION ===

Model Family:     SAMSUNG SpinPoint F1 DT
Device Model:     SAMSUNG HD322HJ
Serial Number:    S17AJDWQ402689
LU WWN Device Id: 5 0000f0 003046298
Firmware Version: 1AC01110
User Capacity:    320,072,933,376 bytes [320 GB]
Sector Size:      512 bytes logical/physical
Device is:        In smartctl database [for details use: -P show]
ATA Version is:   8
ATA Standard is:  ATA-8-ACS revision 3b
Local Time is:    Wed Sep 12 22:27:56 2012 CEST
SMART support is: Available - device has SMART capability.
SMART support is: Enabled

=== START OF READ SMART DATA SECTION ===
SMART overall-health self-assessment test result: PASSED

General SMART Values:
Offline data collection status: (0x00) Offline data collection activity
was never started.
Auto Offline Data Collection:
Disabled.
Self-test execution status: ( 114) The previous self-test completed having
the read element of the test
failed.
Total time to complete Offline
data collection: ( 3888) seconds.
Offline data collection
capabilities: (0x7b) SMART execute Offline immediate.
Auto Offline data collection
on/off support.
Suspend Offline collection upon new command.
Offline surface scan supported. Self-test supported. Conveyance Self-test supported. Selective Self-test supported.
SMART capabilities: (0x0003) Saves SMART data before entering
power-saving mode. Supports SMART auto save timer.
Error logging capability: (0x01) Error logging supported.
General Purpose Logging supported.
Short self-test routine
recommended polling time: ( 2) minutes.
Extended self-test routine
recommended polling time: ( 66) minutes.
Conveyance self-test routine

recommended polling time:        (   8) minutes.
SCT capabilities:              (0x003f) SCT Status supported.

SCT Error Recovery Control
supported.
SCT Feature Control supported. SCT Data Table supported.

SMART Attributes Data Structure revision number: 16 Vendor Specific SMART Attributes with Thresholds:

ID# ATTRIBUTE_NAME          FLAG     VALUE WORST THRESH TYPE UPDATED WHEN_FAILED RAW_VALUE
  1 Raw_Read_Error_Rate     0x000f   099   099   051    Pre-fail Always

- 428
3 Spin_Up_Time 0x0007 094 094 011 Pre-fail Always
- 2810
4 Start_Stop_Count 0x0032 099 099 000 Old_age Always
- 1077
5 Reallocated_Sector_Ct 0x0033 100 100 010 Pre-fail Always
- 0
7 Seek_Error_Rate 0x000f 253 253 051 Pre-fail Always
- 0
8 Seek_Time_Performance 0x0025 100 100 015 Pre-fail
Offline - 9666
9 Power_On_Hours 0x0032 098 098 000 Old_age Always
- 8915
10 Spin_Retry_Count 0x0033 100 100 051 Pre-fail Always
- 0
11 Calibration_Retry_Count 0x0012 100 100 000 Old_age Always
- 0
12 Power_Cycle_Count 0x0032 099 099 000 Old_age Always
- 1077
13 Read_Soft_Error_Rate 0x000e 099 099 000 Old_age Always
- 400
183 Runtime_Bad_Block 0x0032 100 100 000 Old_age Always
- 0
184 End-to-End_Error 0x0033 100 100 099 Pre-fail Always
- 0
187 Reported_Uncorrect 0x0032 100 100 000 Old_age Always
- 400
188 Command_Timeout 0x0032 100 100 000 Old_age Always
- 0
190 Airflow_Temperature_Cel 0x0022 063 055 000 Old_age Always
- 37 (Min/Max 28/45)
194 Temperature_Celsius 0x0022 063 054 000 Old_age Always
- 37 (Min/Max 28/46)
195 Hardware_ECC_Recovered 0x001a 100 100 000 Old_age Always
- 355155576
196 Reallocated_Event_Count 0x0032 100 100 000 Old_age Always
- 0
197 Current_Pending_Sector 0x0012 100 100 000 Old_age Always
- 2
198 Offline_Uncorrectable 0x0030 100 100 000 Old_age Offline
- 1
199 UDMA_CRC_Error_Count 0x003e 100 100 000 Old_age Always
- 0
200 Multi_Zone_Error_Rate 0x000a 100 100 000 Old_age Always
- 0
201 Soft_Read_Error_Rate 0x000a 096 096 000 Old_age Always
- 361

SMART Error Log Version: 1
ATA Error Count: 173 (device log contains only the most recent five errors)
CR = Command Register [HEX]
FR = Features Register [HEX]
SC = Sector Count Register [HEX]
SN = Sector Number Register [HEX]
CL = Cylinder Low Register [HEX]
CH = Cylinder High Register [HEX]
DH = Device/Head Register [HEX]
DC = Device Command Register [HEX]
ER = Error register [HEX]
ST = Status register [HEX]
Powered_Up_Time is measured from power on, and printed as DDd+hh:mm:SS.sss where DD=days, hh=hours, mm=minutes,
SS=sec, and sss=millisec. It "wraps" after 49.710 days.

Error 173 occurred at disk power-on lifetime: 0 hours (0 days + 0 hours)
When the command that caused the error occurred, the device was
active or idle.