ata5.01: failed command: WRITE DMA EXT

Last night I was using Midnight Commander to move files from one EXT4 formatted drive to another in my HP Microserver. I had used ssh to log into the Microserver and launched MC as root. All was going as expected when MC suddenly complained that it could not delete a file on the source drive. I told it to ignore the problem and skip all moves going forward and the "copying" continued. I checked the drive was correctly mounted and thereafter figured it was time to have a look at the kernel log. It revealed the following:

Code:

Nov 16 04:51:27 audioserv1 kernel: [ 22.674923] NFSD: Using /var/lib/nfs/v4recovery as the NFSv4 state recovery directory Nov 16 04:51:27 audioserv1 kernel: [ 22.676468] NFSD: starting 90-second grace period Nov 17 00:52:41 audioserv1 kernel: [72068.492320] ata5.01: exception Emask 0x0 SAct 0x0 SErr 0x0 action 0x6 Nov 17 00:52:41 audioserv1 kernel: [72068.492457] ata5.01: BMDMA stat 0x4 Nov 17 00:52:41 audioserv1 kernel: [72068.492528] ata5.01: failed command: WRITE DMA EXT Nov 17 00:52:41 audioserv1 kernel: [72068.492629] ata5.01: cmd 35/00:08:18:08:80/00:00:e5:00:00/f0 tag 0 dma 4096 out Nov 17 00:52:41 audioserv1 kernel: [72068.492629] res 51/84:01:1f:08:80/84:00:e5:00:00/f0 Emask 0x10 (ATA bus error) Nov 17 00:52:41 audioserv1 kernel: [72068.492905] ata5.01: status: { DRDY ERR } Nov 17 00:52:41 audioserv1 kernel: [72068.492981] ata5.01: error: { ICRC ABRT } Nov 17 00:52:41 audioserv1 kernel: [72068.493119] ata5: soft resetting link Nov 17 00:52:41 audioserv1 kernel: [72068.679487] ata5.01: configured for UDMA/33 Nov 17 00:52:41 audioserv1 kernel: [72068.679521] sd 5:0:1:0: >[sde] Nov 17 00:52:41 audioserv1 kernel: [72068.679525] Result: hostbyte=DID_OK driverbyte=DRIVER_SENSE Nov 17 00:52:41 audioserv1 kernel: [72068.679531] sd 5:0:1:0: >[sde] Nov 17 00:52:41 audioserv1 kernel: [72068.679534] Sense Key : Aborted Command [current] [descriptor] Nov 17 00:52:41 audioserv1 kernel: [72068.679541] Descriptor sense data with sense descriptors (in hex): Nov 17 00:52:41 audioserv1 kernel: [72068.679545] 72 0b 47 00 00 00 00 0c 00 0a 80 00 00 00 00 00 Nov 17 00:52:41 audioserv1 kernel: [72068.679563] e5 80 08 1f Nov 17 00:52:41 audioserv1 kernel: [72068.679572] sd 5:0:1:0: >[sde] Nov 17 00:52:41 audioserv1 kernel: [72068.679578] Add. Sense: Scsi parity error Nov 17 00:52:41 audioserv1 kernel: [72068.679584] sd 5:0:1:0: >[sde] CDB: Nov 17 00:52:41 audioserv1 kernel: [72068.679586] Write(10): 2a 00 e5 80 08 18 00 00 08 00 Nov 17 00:52:41 audioserv1 kernel: [72068.679602] end_request: I/O error, dev sde, sector 3850373144 Nov 17 00:52:41 audioserv1 kernel: [72068.679723] Buffer I/O error on device sde1, logical block 481296387 Nov 17 00:52:41 audioserv1 kernel: [72068.679840] lost page write due to I/O error on sde1 Nov 17 00:52:41 audioserv1 kernel: [72068.679866] ata5: EH complete Nov 17 01:12:02 audioserv1 kernel: [73228.771110] ata5.01: exception Emask 0x0 SAct 0x0 SErr 0x0 action 0x6 Nov 17 01:12:02 audioserv1 kernel: [73228.771220] ata5.01: BMDMA stat 0x4 Nov 17 01:12:02 audioserv1 kernel: [73228.771278] ata5.01: failed command: WRITE DMA EXT Nov 17 01:12:02 audioserv1 kernel: [73228.771360] ata5.01: cmd 35/00:10:10:ee:44/00:01:74:00:00/f0 tag 0 dma 139264 out Nov 17 01:12:02 audioserv1 kernel: [73228.771360] res 51/84:b1:6f:ee:44/84:00:74:00:00/f0 Emask 0x10 (ATA bus error) Nov 17 01:12:02 audioserv1 kernel: [73228.771600] ata5.01: status: { DRDY ERR } Nov 17 01:12:02 audioserv1 kernel: [73228.771664] ata5.01: error: { ICRC ABRT } Nov 17 01:12:02 audioserv1 kernel: [73228.771782] ata5: soft resetting link Nov 17 01:12:02 audioserv1 kernel: [73228.958890] ata5.01: configured for UDMA/33 Nov 17 01:12:02 audioserv1 kernel: [73228.958934] sd 5:0:1:0: >[sde] Nov 17 01:12:02 audioserv1 kernel: [73228.958938] Result: hostbyte=DID_OK driverbyte=DRIVER_SENSE Nov 17 01:12:02 audioserv1 kernel: [73228.958944] sd 5:0:1:0: >[sde] Nov 17 01:12:02 audioserv1 kernel: [73228.958947] Sense Key : Aborted Command [current] [descriptor] Nov 17 01:12:02 audioserv1 kernel: [73228.958954] Descriptor sense data with sense descriptors (in hex): Nov 17 01:12:02 audioserv1 kernel: [73228.958958] 72 0b 47 00 00 00 00 0c 00 0a 80 00 00 00 00 00 Nov 17 01:12:02 audioserv1 kernel: [73228.958976] 74 44 ee 6f Nov 17 01:12:02 audioserv1 kernel: [73228.958985] sd 5:0:1:0: >[sde] Nov 17 01:12:02 audioserv1 kernel: [73228.958991] Add. Sense: Scsi parity error Nov 17 01:12:02 audioserv1 kernel: [73228.958997] sd 5:0:1:0: >[sde] CDB: Nov 17 01:12:02 audioserv1 kernel: [73228.958999] Write(10): 2a 00 74 44 ee 10 00 01 10 00 Nov 17 01:12:02 audioserv1 kernel: [73228.959015] end_request: I/O error, dev sde, sector 1950674448 Nov 17 01:12:02 audioserv1 kernel: [73228.959180] ata5: EH complete Nov 17 01:12:02 audioserv1 kernel: [73228.959281] Aborting journal on device sde1-8. Nov 17 01:12:02 audioserv1 kernel: [73228.984483] EXT4-fs error (device sde1): ext4_journal_start_sb:370: Detected aborted journal Nov 17 01:12:02 audioserv1 kernel: [73228.984665] EXT4-fs (sde1): Remounting filesystem read-only

I stopped the copy/ move, shut down the Microserver, reseated all the drives and booted it again. The server paused on boot, unable to mount the drive in question. I skipped it and reviewed dmesg:

Code:

[ 10.548146] ata5.01: exception Emask 0x0 SAct 0x0 SErr 0x0 action 0x6 [ 10.548262] ata5.01: BMDMA stat 0x4 [ 10.548323] ata5.01: failed command: WRITE DMA [ 10.548402] ata5.01: cmd ca/00:10:a0:0a:00/00:00:00:00:00/f0 tag 0 dma 8192 out [ 10.548402] res 51/84:01:af:0a:00/00:00:00:00:00/f0 Emask 0x10 (ATA bus error) [ 10.548667] ata5.01: status: { DRDY ERR } [ 10.548735] ata5.01: error: { ICRC ABRT } [ 10.548822] ata5: soft resetting link [ 10.737108] ata5.01: configured for UDMA/33 [ 10.737126] sd 5:0:1:0: >[sde] [ 10.737128] Result: hostbyte=DID_OK driverbyte=DRIVER_SENSE [ 10.737131] sd 5:0:1:0: >[sde] [ 10.737132] Sense Key : Aborted Command [current] [descriptor] [ 10.737135] Descriptor sense data with sense descriptors (in hex): [ 10.737136] 72 0b 47 00 00 00 00 0c 00 0a 80 00 00 00 00 00 [ 10.737143] 00 00 0a af [ 10.737146] sd 5:0:1:0: >[sde] [ 10.737149] Add. Sense: Scsi parity error [ 10.737151] sd 5:0:1:0: >[sde] CDB: [ 10.737152] Write(10): 2a 00 00 00 0a a0 00 00 10 00 [ 10.737158] end_request: I/O error, dev sde, sector 2720 [ 10.737253] Buffer I/O error on device sde1, logical block 84 [ 10.737348] lost page write due to I/O error on sde1 [ 10.737354] Buffer I/O error on device sde1, logical block 85 [ 10.737449] lost page write due to I/O error on sde1 [ 10.737461] ata5: EH complete [ 12.111656] ata5.01: exception Emask 0x0 SAct 0x0 SErr 0x0 action 0x6 [ 12.111785] ata5.01: BMDMA stat 0x4 [ 12.111846] ata5.01: failed command: WRITE DMA EXT [ 12.111929] ata5.01: cmd 35/00:00:80:08:00/00:02:a0:00:00/f0 tag 0 dma 262144 out [ 12.111929] res 51/84:71:0f:0a:00/84:00:a0:00:00/f0 Emask 0x10 (ATA bus error) [ 12.112171] ata5.01: status: { DRDY ERR } [ 12.112238] ata5.01: error: { ICRC ABRT } [ 12.112361] ata5: soft resetting link [ 12.300334] ata5.01: configured for UDMA/33 [ 12.300366] sd 5:0:1:0: >[sde] [ 12.300367] Result: hostbyte=DID_OK driverbyte=DRIVER_SENSE [ 12.300369] sd 5:0:1:0: >[sde] [ 12.300371] Sense Key : Aborted Command [current] [descriptor] [ 12.300373] Descriptor sense data with sense descriptors (in hex): [ 12.300374] 72 0b 47 00 00 00 00 0c 00 0a 80 00 00 00 00 00 [ 12.300381] a0 00 0a 0f [ 12.300384] sd 5:0:1:0: >[sde] [ 12.300387] Add. Sense: Scsi parity error [ 12.300389] sd 5:0:1:0: >[sde] CDB: [ 12.300390] Write(10): 2a 00 a0 00 08 80 00 02 00 00 [ 12.300396] end_request: I/O error, dev sde, sector 2684356736 [ 12.300499] Buffer I/O error on device sde1, logical block 335544336 [ 12.300603] lost page write due to I/O error on sde1 [ 12.300609] Buffer I/O error on device sde1, logical block 335544337 [ 12.300712] lost page write due to I/O error on sde1 [ 12.300714] Buffer I/O error on device sde1, logical block 335544338 [ 12.300817] lost page write due to I/O error on sde1 [ 12.300820] Buffer I/O error on device sde1, logical block 335544339 [ 12.300923] lost page write due to I/O error on sde1 [ 12.300925] Buffer I/O error on device sde1, logical block 335544340 [ 12.301028] lost page write due to I/O error on sde1 [ 12.301081] ata5: EH complete [ 12.345041] tg3 0000:02:00.0: >em1: Link is up at 1000 Mbps, full duplex [ 12.345046] tg3 0000:02:00.0: >em1: Flow control is on for TX and on for RX [ 12.345535] IPv6: ADDRCONF(NETDEV_CHANGE): em1: link becomes ready [ 14.736715] ata5.01: exception Emask 0x0 SAct 0x0 SErr 0x0 action 0x6 [ 14.736831] ata5.01: BMDMA stat 0x4 [ 14.736892] ata5.01: failed command: WRITE DMA EXT [ 14.736977] ata5.01: cmd 35/00:08:c0:0e:00/00:00:dc:00:00/f0 tag 0 dma 4096 out [ 14.736977] res 51/84:01:c7:0e:00/84:00:dc:00:00/f0 Emask 0x10 (ATA bus error) [ 14.737222] ata5.01: status: { DRDY ERR } [ 14.737289] ata5.01: error: { ICRC ABRT } [ 14.737412] ata5: soft resetting link [ 14.923043] ata5.01: configured for UDMA/33 [ 14.923062] sd 5:0:1:0: >[sde] [ 14.923064] Result: hostbyte=DID_OK driverbyte=DRIVER_SENSE [ 14.923066] sd 5:0:1:0: >[sde] [ 14.923067] Sense Key : Aborted Command [current] [descriptor] [ 14.923070] Descriptor sense data with sense descriptors (in hex): [ 14.923071] 72 0b 47 00 00 00 00 0c 00 0a 80 00 00 00 00 00 [ 14.923078] dc 00 0e c7 [ 14.923081] sd 5:0:1:0: >[sde] [ 14.923084] Add. Sense: Scsi parity error [ 14.923086] sd 5:0:1:0: >[sde] CDB: [ 14.923087] Write(10): 2a 00 dc 00 0e c0 00 00 08 00 [ 14.923093] end_request: I/O error, dev sde, sector 3690991296 [ 14.923196] quiet_error: 59 callbacks suppressed [ 14.923198] Buffer I/O error on device sde1, logical block 461373656 [ 14.923301] lost page write due to I/O error on sde1 [ 14.923317] ata5: EH complete [ 15.069382] ata5.01: limiting speed to UDMA/25:PIO4 [ 15.069388] ata5.01: exception Emask 0x0 SAct 0x0 SErr 0x0 action 0x6 [ 15.069500] ata5.01: BMDMA stat 0x4 [ 15.069561] ata5.01: failed command: WRITE DMA EXT [ 15.069645] ata5.01: cmd 35/00:00:08:10:c0/00:02:dc:00:00/f0 tag 0 dma 262144 out [ 15.069645] res 51/84:a1:67:10:c0/84:01:dc:00:00/f0 Emask 0x10 (ATA bus error) [ 15.069892] ata5.01: status: { DRDY ERR } [ 15.069960] ata5.01: error: { ICRC ABRT } [ 15.070082] ata5: soft resetting link [ 15.254889] ata5.01: configured for UDMA/25 [ 15.254922] sd 5:0:1:0: >[sde] [ 15.254924] Result: hostbyte=DID_OK driverbyte=DRIVER_SENSE [ 15.254926] sd 5:0:1:0: >[sde] [ 15.254927] Sense Key : Aborted Command [current] [descriptor] [ 15.254930] Descriptor sense data with sense descriptors (in hex): [ 15.254931] 72 0b 47 00 00 00 00 0c 00 0a 80 00 00 00 00 00 [ 15.254937] dc c0 10 67 [ 15.254940] sd 5:0:1:0: >[sde] [ 15.254943] Add. Sense: Scsi parity error [ 15.254945] sd 5:0:1:0: >[sde] CDB: [ 15.254946] Write(10): 2a 00 dc c0 10 08 00 02 00 00 [ 15.254952] end_request: I/O error, dev sde, sector 3703574536 [ 15.255054] Buffer I/O error on device sde1, logical block 462946561 [ 15.255158] lost page write due to I/O error on sde1 [ 15.255164] Buffer I/O error on device sde1, logical block 462946562 [ 15.255267] lost page write due to I/O error on sde1 [ 15.255269] Buffer I/O error on device sde1, logical block 462946563 [ 15.255372] lost page write due to I/O error on sde1 [ 15.255374] Buffer I/O error on device sde1, logical block 462946564 [ 15.258621] lost page write due to I/O error on sde1 [ 15.258623] Buffer I/O error on device sde1, logical block 462946565 [ 15.261793] lost page write due to I/O error on sde1 [ 15.261796] Buffer I/O error on device sde1, logical block 462946566 [ 15.264850] lost page write due to I/O error on sde1 [ 15.264853] Buffer I/O error on device sde1, logical block 462946567 [ 15.267944] lost page write due to I/O error on sde1 [ 15.267946] Buffer I/O error on device sde1, logical block 462946568 [ 15.270919] lost page write due to I/O error on sde1 [ 15.270921] Buffer I/O error on device sde1, logical block 462946569 [ 15.273780] lost page write due to I/O error on sde1 [ 15.273831] ata5: EH complete [ 15.274772] ata5.01: exception Emask 0x0 SAct 0x0 SErr 0x0 action 0x6 [ 15.277770] ata5.01: BMDMA stat 0x4 [ 15.280749] ata5.01: failed command: WRITE DMA EXT [ 15.283721] ata5.01: cmd 35/00:80:08:12:c0/00:01:dc:00:00/f0 tag 0 dma 196608 out [ 15.283721] res 51/84:41:47:12:c0/84:01:dc:00:00/f0 Emask 0x10 (ATA bus error) [ 15.289666] ata5.01: status: { DRDY ERR } [ 15.292633] ata5.01: error: { ICRC ABRT } [ 15.295602] ata5: soft resetting link [ 15.482769] ata5.01: configured for UDMA/25 [ 15.482799] sd 5:0:1:0: >[sde] [ 15.482801] Result: hostbyte=DID_OK driverbyte=DRIVER_SENSE [ 15.482803] sd 5:0:1:0: >[sde] [ 15.482804] Sense Key : Aborted Command [current] [descriptor] [ 15.482806] Descriptor sense data with sense descriptors (in hex): [ 15.482808] 72 0b 47 00 00 00 00 0c 00 0a 80 00 00 00 00 00 [ 15.482814] dc c0 12 47 [ 15.482817] sd 5:0:1:0: >[sde] [ 15.482820] Add. Sense: Scsi parity error [ 15.482822] sd 5:0:1:0: >[sde] CDB: [ 15.482823] Write(10): 2a 00 dc c0 12 08 00 01 80 00 [ 15.482829] end_request: I/O error, dev sde, sector 3703575048 [ 15.485865] ata5: EH complete [ 17.925438] ata5.01: exception Emask 0x0 SAct 0x0 SErr 0x0 action 0x6 [ 17.928498] ata5.01: BMDMA stat 0x4 [ 17.931517] ata5.01: failed command: WRITE DMA EXT [ 17.934551] ata5.01: cmd 35/00:08:00:08:80/00:00:e7:00:00/f0 tag 0 dma 4096 out [ 17.934551] res 51/84:01:07:08:80/84:00:e7:00:00/f0 Emask 0x10 (ATA bus error) [ 17.940667] ata5.01: status: { DRDY ERR } [ 17.943706] ata5.01: error: { ICRC ABRT } [ 17.946772] ata5: soft resetting link [ 18.133458] ata5.01: configured for UDMA/25 [ 18.133476] sd 5:0:1:0: >[sde] [ 18.133478] Result: hostbyte=DID_OK driverbyte=DRIVER_SENSE [ 18.133480] sd 5:0:1:0: >[sde] [ 18.133481] Sense Key : Aborted Command [current] [descriptor] [ 18.133484] Descriptor sense data with sense descriptors (in hex): [ 18.133485] 72 0b 47 00 00 00 00 0c 00 0a 80 00 00 00 00 00 [ 18.133491] e7 80 08 07 [ 18.133494] sd 5:0:1:0: >[sde] [ 18.133498] Add. Sense: Scsi parity error [ 18.133499] sd 5:0:1:0: >[sde] CDB: [ 18.133500] Write(10): 2a 00 e7 80 08 00 00 00 08 00 [ 18.133506] end_request: I/O error, dev sde, sector 3883927552 [ 18.136498] ata5: EH complete [ 18.197443] JBD2: recovery failed [ 18.197451] EXT4-fs (sde1): error loading journal

Running sudo smartctl -a /dev/sde returns:

Code:

smartctl 5.43 2012-06-30 r3573 [x86_64-linux-3.5.0-17-generic] (local build) Copyright (C) 2002-12 by Bruce Allen, http://smartmontools.sourceforge.net === START OF INFORMATION SECTION === Model Family: Seagate Barracuda Green (Adv. Format) Device Model: ST2000DL003-9VT166 Serial Number: 6YD0409P LU WWN Device Id: 5 000c50 032f01d01 Firmware Version: CC32 User Capacity: 2*000*398*934*016 bytes [2,00 TB] 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 4 Local Time is: Sun Nov 17 07:37:09 2013 SAST 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: (0x82) Offline data collection activity was completed without error. Auto Offline Data Collection: Enabled. Self-test execution status: ( 0) The previous self-test routine completed without error or no self-test has ever been run. Total time to complete Offline data collection: ( 623) 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: ( 1) minutes. Extended self-test routine recommended polling time: ( 353) minutes. Conveyance self-test routine recommended polling time: ( 2) minutes. SCT capabilities: (0x30b7) SCT Status supported. SCT Feature Control supported. SCT Data Table supported. SMART Attributes Data Structure revision number: 10 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 109 099 006 Pre-fail Always - 24403504 3 Spin_Up_Time 0x0003 092 092 000 Pre-fail Always - 0 4 Start_Stop_Count 0x0032 100 100 020 Old_age Always - 601 5 Reallocated_Sector_Ct 0x0033 100 100 036 Pre-fail Always - 0 7 Seek_Error_Rate 0x000f 077 060 030 Pre-fail Always - 51510415 9 Power_On_Hours 0x0032 089 089 000 Old_age Always - 9948 10 Spin_Retry_Count 0x0013 100 100 097 Pre-fail Always - 0 12 Power_Cycle_Count 0x0032 100 100 020 Old_age Always - 600 183 Runtime_Bad_Block 0x0032 100 100 000 Old_age Always - 0 184 End-to-End_Error 0x0032 100 100 099 Old_age Always - 0 187 Reported_Uncorrect 0x0032 100 100 000 Old_age Always - 0 188 Command_Timeout 0x0032 100 100 000 Old_age Always - 2 189 High_Fly_Writes 0x003a 097 097 000 Old_age Always - 3 190 Airflow_Temperature_Cel 0x0022 068 062 045 Old_age Always - 32 (Min/Max 23/32) 191 G-Sense_Error_Rate 0x0032 100 100 000 Old_age Always - 0 192 Power-Off_Retract_Count 0x0032 100 100 000 Old_age Always - 244 193 Load_Cycle_Count 0x0032 100 100 000 Old_age Always - 601 194 Temperature_Celsius 0x0022 032 040 000 Old_age Always - 32 (0 11 0 0 0) 195 Hardware_ECC_Recovered 0x001a 029 004 000 Old_age Always - 24403504 197 Current_Pending_Sector 0x0012 100 100 000 Old_age Always - 0 198 Offline_Uncorrectable 0x0010 100 100 000 Old_age Offline - 0 199 UDMA_CRC_Error_Count 0x003e 200 200 000 Old_age Always - 9 240 Head_Flying_Hours 0x0000 100 253 000 Old_age Offline - 39895951222517 241 Total_LBAs_Written 0x0000 100 253 000 Old_age Offline - 2397132274 242 Total_LBAs_Read 0x0000 100 253 000 Old_age Offline - 2884666216 SMART Error Log Version: 1 No Errors Logged SMART Self-test log structure revision number 1 No self-tests have been logged. [To run self-tests, use: smartctl -t] SMART Selective self-test log data structure revision number 1 SPAN MIN_LBA MAX_LBA CURRENT_TEST_STATUS 1 0 0 Not_testing 2 0 0 Not_testing 3 0 0 Not_testing 4 0 0 Not_testing 5 0 0 Not_testing Selective self-test flags (0x0): After scanning selected spans, do NOT read-scan remainder of disk. If Selective self-test is pending on power-up, resume after 0 minute delay.

So, the drive appears to be fine - am I correct in assuming the Microserver is faulty?

Solved. It was a loose SATA cable.