Repairing Turbo

Wednesday, May 9, 2018

Turbo is exhibiting a variety of weird symptoms. It has been ongoing for a while, initially with USB disconnects on the Terramaster array.

Today, I purchased a new USB-C cable to see if it helped. It did not. I connected the boot disk of Shuttle, and it disconnected after a couple of hours as well, so the problem seems to be with Turbo, not with the disk array (although it may be caused by the disk array, since it was connected at the time).

With enoug persistence, I managed to copy the Win10-turbo disk to io (in storage-pool), which means that io (my personal NAS) is for now quite low on free disk space, but that's OK if only temporary. I copied the storage for key pet VMs to the primary disk of Turbo, under /home/save, which means that the primary disk is now also low on disk space (a situation I try to avoid by using the external array to start with).

USB resets during disk operations

Of note: when things go well, disk transfer rates start at 280MB/s, before slowly going down until they reach approx. 80-90MB/s. However, when disk don't go well, I see things like: 

[46820.452232] sd 11:0:0:0: [sdc] tag#27 uas_zap_pending 0 uas-tag 28 inflight: CMD
[46820.452523] sd 11:0:0:0: [sdc] tag#27 CDB: Read(16) 88 00 00 00 00 00 26 bd 13 40 00 00 00 20 00 00
[46820.452811] sd 11:0:0:0: [sdc] tag#28 uas_zap_pending 0 uas-tag 29 inflight: CMD
[46820.453103] sd 11:0:0:0: [sdc] tag#28 CDB: Read(16) 88 00 00 00 00 00 27 14 17 68 00 00 03 a8 00 00
[46820.453419] sd 11:0:0:0: [sdc] tag#29 uas_zap_pending 0 uas-tag 30 inflight: CMD
[46820.453737] sd 11:0:0:0: [sdc] tag#29 CDB: Read(16) 88 00 00 00 00 00 27 14 1b 10 00 00 01 70 00 00
[46820.558106] usb 4-5: reset SuperSpeed USB device number 3 using xhci_hcd
[46820.571890] scsi host11: uas_eh_bus_reset_handler success

and when that happens, transfer rates are closer to 2MB/s, sometimes vas low as 50KB/s!!! Interestingly, if I leave dd running, then the "bad" situation persists forever. If I interrupt dd and start a new one after a reset message, performance goes back to normal.

I also noticed that this seems to happen when the external disk goes to sleep. Bad timeout value when waking up a sleeping disk?

systemd crashing

Also, not sure if related, very annoying issue since I upgrade to Fedora 28: 

[47172.130633] systemd-journald[667]: Failed to send WATCHDOG=1 notification message: Transport endpoint is not connected

Also had bus errors in systemd. Not too good when this happens.

NIC state changes

I also occasionally see messages like this: 

[   69.165269] br-1ea4a1b6442c: port 1(vethfbf8bb6) entered blocking state
[   69.165342] br-1ea4a1b6442c: port 1(vethfbf8bb6) entered forwarding state
[   69.165454] br-1ea4a1b6442c: port 1(vethfbf8bb6) entered disabled state
[   69.265590] br-1ea4a1b6442c: port 2(veth410874b) entered blocking state
[   69.265666] br-1ea4a1b6442c: port 2(veth410874b) entered disabled state
[   69.265774] device veth410874b entered promiscuous mode
[   69.265910] IPv6: ADDRCONF(NETDEV_UP): veth410874b: link is not ready
[   69.265972] br-1ea4a1b6442c: port 2(veth410874b) entered blocking state
[   69.266030] br-1ea4a1b6442c: port 2(veth410874b) entered forwarding state
[   69.266120] IPv6: ADDRCONF(NETDEV_CHANGE): br-1ea4a1b6442c: link becomes ready
[   69.266241] br-1ea4a1b6442c: port 2(veth410874b) entered disabled state
[   70.635301] eth0: renamed from veth15d2618
[   70.647289] IPv6: ADDRCONF(NETDEV_CHANGE): veth410874b: link becomes ready
[   70.647390] br-1ea4a1b6442c: port 2(veth410874b) entered blocking state
[   70.647463] br-1ea4a1b6442c: port 2(veth410874b) entered forwarding state
[   70.671265] eth0: renamed from veth8f49927
[   70.683415] IPv6: ADDRCONF(NETDEV_CHANGE): vethfbf8bb6: link becomes ready
[   70.683629] br-1ea4a1b6442c: port 1(vethfbf8bb6) entered blocking state
[   70.683807] br-1ea4a1b6442c: port 1(vethfbf8bb6) entered forwarding state
[   73.590540] tun: Universal TUN/TAP device driver, 1.6
[   73.591917] virbr0: port 1(virbr0-nic) entered blocking state
[   73.592100] virbr0: port 1(virbr0-nic) entered disabled state
[   73.592327] device virbr0-nic entered promiscuous mode
[   73.864063] virbr0: port 1(virbr0-nic) entered blocking state
[   73.864249] virbr0: port 1(virbr0-nic) entered listening state
[   74.039985] virbr0: port 1(virbr0-nic) entered disabled state

What does that mean? Is there also a problem with my NIC?

USB disconnect

Here is a typical fast USB disconnect / reconnect: 

[ 1265.265728] xhci_hcd 0000:00:14.0: Cannot set link state.
[ 1265.265912] usb usb4-port5: cannot disable (err = -32)
[ 1265.266115] usb 4-5: USB disconnect, device number 2
[ 1265.270688] sd 10:0:0:0: [sdb] Synchronizing SCSI cache
[ 1265.390650] sd 10:0:0:0: [sdb] Synchronize Cache(10) failed: Result: hostbyte=DID_ERROR driverbyte=DRIVER_OK
[ 1271.250163] usb 4-5: new SuperSpeed USB device number 3 using xhci_hcd
[ 1271.263007] usb 4-5: New USB device found, idVendor=152d, idProduct=0567
[ 1271.263185] usb 4-5: New USB device strings: Mfr=1, Product=2, SerialNumber=3
[ 1271.263362] usb 4-5: Product: TerraMaster_DAS
[ 1271.263531] usb 4-5: Manufacturer: JMicron
[ 1271.263700] usb 4-5: SerialNumber: 201609040218
[ 1271.267051] scsi host11: uas
[ 1271.267784] scsi 11:0:0:0: Direct-Access     JMicron  H/W RAID5        0103 PQ: 0 ANSI: 6
[ 1271.362782] sd 11:0:0:0: [sdc] Spinning up disk...
[ 1271.362791] sd 11:0:0:0: Attached scsi generic sg2 type 0
[ 1272.426224] .
[ 1272.426312] ready
[ 1272.427167] sd 11:0:0:0: [sdc] 23441702912 512-byte logical blocks: (12.0 TB/10.9 TiB)
[ 1272.427445] sd 11:0:0:0: [sdc] 4096-byte physical blocks
[ 1272.427775] sd 11:0:0:0: [sdc] Write Protect is off
[ 1272.427931] sd 11:0:0:0: [sdc] Mode Sense: 53 00 00 08
[ 1272.428228] sd 11:0:0:0: [sdc] Disabling FUA
[ 1272.428384] sd 11:0:0:0: [sdc] Write cache: enabled, read cache: enabled, doesn't support DPO or FUA
[ 1272.487032]  sdc: sdc1 sdc2 sdc3 sdc4
[ 1272.488829] sd 11:0:0:0: [sdc] Attached SCSI disk
[root@turbo ~]#

I improved things quite a bit when this happens by having an fstab entry that accessed the disk by UUID instead of as /dev/sdb (which changes in that case).

Drive going bad?

I split the RAID array and decided to go for software RAID instead. Rebuilding the array shows that the issue may be with my disk: 

[21038.368142] sd 11:0:0:2: [sde] tag#10 uas_eh_abort_handler 0 uas-tag 11 inflight: CMD IN
[21038.368448] sd 11:0:0:2: [sde] tag#10 CDB: Read(16) 88 00 00 00 00 00 2a e2 09 e0 00 00 00 08 00 00
[21039.328224] sd 11:0:0:2: [sde] tag#11 uas_eh_abort_handler 0 uas-tag 12 inflight: CMD IN
[21039.328514] sd 11:0:0:2: [sde] tag#11 CDB: Read(16) 88 00 00 00 00 00 2a e2 09 e8 00 00 00 08 00 00
[21040.352293] sd 11:0:0:2: [sde] tag#12 uas_eh_abort_handler 0 uas-tag 13 inflight: CMD IN
[21040.352587] sd 11:0:0:2: [sde] tag#12 CDB: Read(16) 88 00 00 00 00 00 2a e2 09 f0 00 00 00 08 00 00
[21043.360529] sd 11:0:0:2: [sde] tag#13 uas_eh_abort_handler 0 uas-tag 14 inflight: CMD IN
[21043.360827] sd 11:0:0:2: [sde] tag#13 CDB: Read(16) 88 00 00 00 00 00 2a e2 09 f8 00 00 00 08 00 00
[21044.320614] sd 11:0:0:2: [sde] tag#15 uas_eh_abort_handler 0 uas-tag 16 inflight: CMD IN
[21044.320915] sd 11:0:0:2: [sde] tag#15 CDB: Read(16) 88 00 00 00 00 00 2a e2 0a 08 00 00 00 08 00 00
[21044.321217] sd 11:0:0:2: [sde] tag#14 uas_eh_abort_handler 0 uas-tag 15 inflight: CMD IN
[21044.321495] sd 11:0:0:2: [sde] tag#14 CDB: Read(16) 88 00 00 00 00 00 2a e2 0a 00 00 00 00 08 00 00
[21045.344685] sd 11:0:0:2: [sde] tag#16 uas_eh_abort_handler 0 uas-tag 17 inflight: CMD IN
[21045.344991] sd 11:0:0:2: [sde] tag#16 CDB: Read(16) 88 00 00 00 00 00 2a e2 0a 10 00 00 00 08 00 00
[21048.352927] sd 11:0:0:2: [sde] tag#17 uas_eh_abort_handler 0 uas-tag 18 inflight: CMD IN
[21048.355813] sd 11:0:0:2: [sde] tag#17 CDB: Read(16) 88 00 00 00 00 00 2a e2 0a 18 00 00 00 08 00 00
[21060.129865] sd 11:0:0:4: [sdg] tag#2 uas_eh_abort_handler 0 uas-tag 3 inflight: CMD
[21060.130184] sd 11:0:0:4: [sdg] tag#2 CDB: Synchronize Cache(10) 35 00 00 00 00 00 00 00 00 00
[21060.130481] sd 11:0:0:1: [sdd] tag#1 uas_eh_abort_handler 0 uas-tag 2 inflight: CMD
[21060.130775] sd 11:0:0:1: [sdd] tag#1 CDB: Synchronize Cache(10) 35 00 00 00 00 00 00 00 00 00
[21064.226192] sd 11:0:0:0: [sdc] tag#4 uas_eh_abort_handler 0 uas-tag 5 inflight: CMD
[21064.226510] sd 11:0:0:0: [sdc] tag#4 CDB: Synchronize Cache(10) 35 00 00 00 00 00 00 00 00 00
[21064.226805] sd 11:0:0:3: [sdf] tag#3 uas_eh_abort_handler 0 uas-tag 4 inflight: CMD
[21064.227099] sd 11:0:0:3: [sdf] tag#3 CDB: Synchronize Cache(10) 35 00 00 00 00 00 00 00 00 00
[21064.738230] sd 11:0:0:2: [sde] tag#6 uas_eh_abort_handler 0 uas-tag 7 inflight: CMD
[21064.738551] sd 11:0:0:2: [sde] tag#6 CDB: Synchronize Cache(10) 35 00 00 00 00 00 00 00 00 00
[21064.738892] scsi host11: uas_eh_bus_reset_handler start
[21064.847552] usb 4-5: reset SuperSpeed USB device number 6 using xhci_hcd
[21064.861423] scsi host11: uas_eh_bus_reset_handler success
[21079.628077] sd 11:0:0:2: [sde] tag#8 FAILED Result: hostbyte=DID_OK driverbyte=DRIVER_SENSE
[21079.628407] sd 11:0:0:2: [sde] tag#8 Sense Key : Medium Error [current]
[21079.628592] sd 11:0:0:2: [sde] tag#8 Add. Sense: Unrecovered read error
[21079.628776] sd 11:0:0:2: [sde] tag#8 CDB: Read(16) 88 00 00 00 00 00 2a e2 6f d0 00 00 00 08 00 00
[21079.629072] blk_update_request: critical medium error, dev sde, sector 719482832
[21079.629367] md/raid:md0: read error not correctable (sector 719482832 on sde).
[21086.188334] sd 11:0:0:2: [sde] tag#21 FAILED Result: hostbyte=DID_OK driverbyte=DRIVER_SENSE
[21086.188638] sd 11:0:0:2: [sde] tag#21 Sense Key : Medium Error [current]
[21086.188825] sd 11:0:0:2: [sde] tag#21 Add. Sense: Unrecovered read error
[21086.189009] sd 11:0:0:2: [sde] tag#21 CDB: Read(16) 88 00 00 00 00 00 2a e2 70 38 00 00 00 08 00 00
[21086.189305] blk_update_request: critical medium error, dev sde, sector 719482936
[21086.189601] md/raid:md0: read error not correctable (sector 719482936 on sde).
[21098.630740] sd 11:0:0:2: [sde] tag#10 FAILED Result: hostbyte=DID_OK driverbyte=DRIVER_SENSE
[21098.631060] sd 11:0:0:2: [sde] tag#10 Sense Key : Medium Error [current]
[21098.631229] sd 11:0:0:2: [sde] tag#10 Add. Sense: Unrecovered read error
[21098.631398] sd 11:0:0:2: [sde] tag#10 CDB: Read(16) 88 00 00 00 00 00 2a e2 7d 00 00 00 00 08 00 00
[21098.631679] blk_update_request: critical medium error, dev sde, sector 719486208
[21098.631958] md/raid:md0: read error not correctable (sector 719486208 on sde).
[21111.163752] sd 11:0:0:2: [sde] tag#12 FAILED Result: hostbyte=DID_OK driverbyte=DRIVER_SENSE
[21111.164077] sd 11:0:0:2: [sde] tag#12 Sense Key : Medium Error [current]
[21111.164248] sd 11:0:0:2: [sde] tag#12 Add. Sense: Unrecovered read error
[21111.164416] sd 11:0:0:2: [sde] tag#12 CDB: Read(16) 88 00 00 00 00 00 2a e9 33 30 00 00 04 00 00 00
[21111.164702] blk_update_request: critical medium error, dev sde, sector 719926064
[21111.164981] md/raid:md0: read error not correctable (sector 719926064 on sde).
[21111.165261] md/raid:md0: read error not correctable (sector 719926072 on sde).
[21111.165542] md/raid:md0: read error not correctable (sector 719926080 on sde).
[21111.165819] md/raid:md0: read error not correctable (sector 719926088 on sde).
[21111.166111] md/raid:md0: read error not correctable (sector 719926096 on sde).
[21111.166389] md/raid:md0: read error not correctable (sector 719926104 on sde).

What is interesting is that /dev/sde is the third disk, and when I had failures with the RAID array, it was always rebuilding the fourth disk, not the third one.

To see what is happening with the disk array rebuild, I'm using 

watch cat /proc/mdstat

Also, I'm watching the system with xosview, and disk activity goes from 240MB/s down to 0 on occasions. CPU utilization is at a few percents, so rebuilding the array does not take a toll on CPU, which I hope means the cost of doing I/Os will be low as well.

Analyzing the disk

Using smartctl (from package smartmontools) shows: 

[root@turbo save]# smartctl -a /dev/sde
smartctl 6.6 2017-11-05 r4594 [x86_64-linux-4.12.9-300.fc26.x86_64] (local build)
Copyright (C) 2002-17, Bruce Allen, Christian Franke, www.smartmontools.org



=== START OF INFORMATION SECTION ===
Model Family:     Seagate Barracuda 7200.14 (AF)
Device Model:     ST3000DM001-1CH166
Serial Number:    Z1F2CKP6
LU WWN Device Id: 5 000c50 04fd4343b
Firmware Version: CC26
User Capacity:    3,000,592,982,016 bytes [3.00 TB]
Sector Sizes:     512 bytes logical, 4096 bytes physical
Rotation Rate:    7200 rpm
Form Factor:      3.5 inches
Device is:        In smartctl database [for details use: -P show]
ATA Version is:   ATA8-ACS T13/1699-D revision 4
SATA Version is:  SATA 3.0, 6.0 Gb/s (current: 3.0 Gb/s)
Local Time is:    Thu May 10 08:36:46 2018 CEST
SMART support is: Available - device has SMART capability.
SMART support is: Enabled

And then a bunch of things: 

SMART overall-health self-assessment test result: PASSED
Warning: This result is based on an Attribute check.

Details: 

General SMART Values:
Offline data collection status:  (0x00)	Offline data collection activity
					was never started.
					Auto Offline Data Collection: Disabled.
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: 		(  584) seconds.
Offline data collection
capabilities: 			 (0x73) SMART execute Offline immediate.
					Auto Offline data collection on/off support.
					Suspend Offline collection upon new
					command.
					No 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: 	 ( 334) minutes.
Conveyance self-test routine
recommended polling time: 	 (   2) minutes.
SCT capabilities: 	       (0x3085)	SCT Status 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   112   087   006    Pre-fail  Always       -       151561524
  3 Spin_Up_Time            0x0003   097   094   000    Pre-fail  Always       -       0
  4 Start_Stop_Count        0x0032   091   091   020    Old_age   Always       -       9876
  5 Reallocated_Sector_Ct   0x0033   089   089   010    Pre-fail  Always       -       14052
  7 Seek_Error_Rate         0x000f   067   060   030    Pre-fail  Always       -       559042514710
  9 Power_On_Hours          0x0032   078   078   000    Old_age   Always       -       19356
 10 Spin_Retry_Count        0x0013   100   100   097    Pre-fail  Always       -       0
 12 Power_Cycle_Count       0x0032   100   100   020    Old_age   Always       -       105
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   001   001   000    Old_age   Always       -       802
188 Command_Timeout         0x0032   100   097   000    Old_age   Always       -       28 30 285
189 High_Fly_Writes         0x003a   001   001   000    Old_age   Always       -       112
190 Airflow_Temperature_Cel 0x0022   059   050   045    Old_age   Always       -       41 (Min/Max 37/41 #1)
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       -       93
193 Load_Cycle_Count        0x0032   092   092   000    Old_age   Always       -       17505
194 Temperature_Celsius     0x0022   041   050   000    Old_age   Always       -       41 (128 0 0 0 0)
197 Current_Pending_Sector  0x0012   041   017   000    Old_age   Always       -       9740
198 Offline_Uncorrectable   0x0010   041   017   000    Old_age   Offline      -       9740
199 UDMA_CRC_Error_Count    0x003e   200   200   000    Old_age   Always       -       0
240 Head_Flying_Hours       0x0000   100   253   000    Old_age   Offline      -       11070h+55m+31.254s
241 Total_LBAs_Written      0x0000   100   253   000    Old_age   Offline      -       77394455013
242 Total_LBAs_Read         0x0000   100   253   000    Old_age   Offline      -       51535486813

Error log section: 

SMART Error Log Version: 1
ATA Error Count: 1542 (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 1542 occurred at disk power-on lifetime: 19355 hours (806 days + 11 hours)
  When the command that caused the error occurred, the device was active or idle.


  After command completion occurred, registers were:
  ER ST SC SN CL CH DH
  -- -- -- -- -- -- --
  40 51 00 ff ff ff 0f  Error: UNC at LBA = 0x0fffffff = 268435455

  Commands leading to the command that caused the error were:
  CR FR SC SN CL CH DH DC   Powered_Up_Time  Command/Feature_Name
  -- -- -- -- -- -- -- --  ----------------  --------------------
  25 00 08 ff ff ff 4f 00      07:24:57.043  READ DMA EXT
  25 00 08 ff ff ff 4f 00      07:24:57.037  READ DMA EXT
  25 00 08 ff ff ff 4f 00      07:24:57.034  READ DMA EXT
  25 00 08 ff ff ff 4f 00      07:24:57.030  READ DMA EXT
  25 00 08 ff ff ff 4f 00      07:24:57.026  READ DMA EXT


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


  After command completion occurred, registers were:
  ER ST SC SN CL CH DH
  -- -- -- -- -- -- --
  40 51 00 ff ff ff 0f  Error: UNC at LBA = 0x0fffffff = 268435455

  Commands leading to the command that caused the error were:
  CR FR SC SN CL CH DH DC   Powered_Up_Time  Command/Feature_Name
  -- -- -- -- -- -- -- --  ----------------  --------------------
  25 00 08 ff ff ff 4f 00      07:24:57.043  READ DMA EXT
  25 00 08 ff ff ff 4f 00      07:24:57.037  READ DMA EXT
  25 00 08 ff ff ff 4f 00      07:24:57.034  READ DMA EXT
  25 00 08 ff ff ff 4f 00      07:24:57.030  READ DMA EXT
  25 00 08 ff ff ff 4f 00      07:24:57.026  READ DMA EXT


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


  After command completion occurred, registers were:
  ER ST SC SN CL CH DH
  -- -- -- -- -- -- --
  40 51 00 ff ff ff 0f  Error: UNC at LBA = 0x0fffffff = 268435455

  Commands leading to the command that caused the error were:
  CR FR SC SN CL CH DH DC   Powered_Up_Time  Command/Feature_Name
  -- -- -- -- -- -- -- --  ----------------  --------------------
  25 00 08 ff ff ff 4f 00      07:24:56.334  READ DMA EXT
  25 00 08 ff ff ff 4f 00      07:24:56.329  READ DMA EXT
  25 00 08 ff ff ff 4f 00      07:24:56.324  READ DMA EXT
  25 00 08 ff ff ff 4f 00      07:24:56.320  READ DMA EXT
  25 00 08 ff ff ff 4f 00      07:24:56.317  READ DMA EXT


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


  After command completion occurred, registers were:
  ER ST SC SN CL CH DH
  -- -- -- -- -- -- --
  40 51 00 ff ff ff 0f  Error: UNC at LBA = 0x0fffffff = 268435455

  Commands leading to the command that caused the error were:
  CR FR SC SN CL CH DH DC   Powered_Up_Time  Command/Feature_Name
  -- -- -- -- -- -- -- --  ----------------  --------------------
  25 00 08 ff ff ff 4f 00      07:24:56.334  READ DMA EXT
  25 00 08 ff ff ff 4f 00      07:24:56.329  READ DMA EXT
  25 00 08 ff ff ff 4f 00      07:24:56.324  READ DMA EXT
  25 00 08 ff ff ff 4f 00      07:24:56.320  READ DMA EXT
  25 00 08 ff ff ff 4f 00      07:24:56.317  READ DMA EXT


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


  After command completion occurred, registers were:
  ER ST SC SN CL CH DH
  -- -- -- -- -- -- --
  40 51 00 ff ff ff 0f  Error: UNC at LBA = 0x0fffffff = 268435455

  Commands leading to the command that caused the error were:
  CR FR SC SN CL CH DH DC   Powered_Up_Time  Command/Feature_Name
  -- -- -- -- -- -- -- --  ----------------  --------------------
  25 00 08 ff ff ff 4f 00      07:24:53.387  READ DMA EXT
  25 00 08 ff ff ff 4f 00      07:24:53.383  READ DMA EXT
  25 00 08 ff ff ff 4f 00      07:24:53.379  READ DMA EXT
  25 00 08 ff ff ff 4f 00      07:24:53.375  READ DMA EXT
  25 00 08 ff ff ff 4f 00      07:24:53.371  READ DMA EXT


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.

Running a long test with smartctl --test=long /dev/sde. Result is: 

Please wait 334 minutes for test to complete.
Test will complete after Thu May 10 14:18:54 2018

So I will know this afternoon how bad my drive feels.

Interstingly, running SMART test on other disks, I get conflicting results between two Western Digital "Red" disks. One, /dev/sdd, has SMART support: 

Model Family:     Western Digital Red
Device Model:     WDC WD30EFRX-68EUZN0
Serial Number:    WD-WCC4N4RJ8R7K
LU WWN Device Id: 5 0014ee 262249d35
Firmware Version: 82.00A82
User Capacity:    3,000,592,982,016 bytes [3.00 TB]
Sector Sizes:     512 bytes logical, 4096 bytes physical
Rotation Rate:    5400 rpm
Device is:        In smartctl database [for details use: -P show]
ATA Version is:   ACS-2 (minor revision not indicated)
SATA Version is:  SATA 3.0, 6.0 Gb/s (current: 3.0 Gb/s)
Local Time is:    Thu May 10 08:48:35 2018 CEST
SMART support is: Available - device has SMART capability.
SMART support is: Enabled

However, /dev/sdc does not. 

Model Family:     Western Digital Red
Device Model:     WDC WD30EFRX-68EUZN0
Serial Number:    WD-WCC4N6YLJV5U
Firmware Version: 0962
User Capacity:    3,000,592,982,016 bytes [3.00 TB]
Sector Size:      512 bytes logical/physical
Device is:        In smartctl database [for details use: -P show]
ATA Version is:   ATA/ATAPI-7 (minor revision not indicated)
Local Time is:    Thu May 10 08:50:29 2018 CEST
SMART support is: Available - device has SMART capability.
SMART support is: Enabled

As far as I recall, I purchased the two disks at the same time from the same vendor. They have the same "Model family" and same device model, but the firmware is different. Weird.

In terms of power-on hours, I get:

  • 11896 for /dev/sdg
  • 11919 for /dev/sdf
  • 19356 for /dev/sde
  • 11820 for /dev/sdd
  • Unreadable for /dev/sdc
So that would mean that most disks are 1.3 years old, but the one that seems to be misbehaving would be 2.2 years old. Strange.

Terramaster hardware RAID: Nack

The conclusion of the above is that I should not use the Terramaster RAID controller for Linux. It misbehaves when one of the disks is bordernline, and even the proprietary software does not correclty report the root cause.

Here, the faulty drive is the 2 years old one. The front-panel lights, when they turned red, always blamed another disk (disk #4 and not disk #3 in the array). The software used for reconstruction also gave no indication of impending disk failure, which seems blatantly obvious.

Another lesson learned in the process is that USB disk reset is Linux way of telling you that the disk is going bad. Since I also saw that on another disk a couple of days ago, now I'm concerned about that disk (it's pretty old too)...

Some errors are still quite strange, e.g.: 

[40238.888972] pool[20553]: segfault at 8 ip 00007f585bdf7249 sp 00007f58370ffbc0 error 4 in libc-2.27.so[7f585bd74000+1b5000]

Red Skin Cat

Daily rants and notes about my work on Spice at Red Hat

May 2018
Sun Mon Tue Wed Thu Fri Sat
1 2 3 4 5
6 7 8 9 10 11 12
13 14 15 16 17 18 19
20 21 22 23 24 25 26
27 28 29 30 31
Apr  Jun
RSS

Links

This is the work blog of Christophe de Dinechin for Red Hat. Think of it as a public lab book.

This should not be particularly interesting except to myself. It's really more intended as a set of personal notes, so there is no formatting whatsoever. I type tings as I go along during the day. All you'll find here are things like stack traces, Linux commands I want to remember or bugzilla links I want to be able to return to.

If you want to read stuff about my work at Red Hat that I believe is more interesting to the general public, you will find it on A Spice Odyssey. If you want to read my rants about everything else, go to Grenouille Bouillie. This is about as much advertisement as you will find on this site.

2016-2018 - Christophe de Dinechin

All views expressed on this blog are strictly personal. This blog does not represent the views of my employer, nor mine for that matter. This blog is provided as-is, without warrrany of any kind, express or implied, in particular regarding accuracy or interest of the content. The contents of this blog is distributed under a Creative Commons BY-SA 4.0 license .