Hi,
On Thu, 16 Nov 2017 14:42:51 -0500 (EST)
Alan Stern <stern@xxxxxxxxxxxxxxxxxxx> wrote:
> On Wed, 15 Nov 2017, Jérôme Carretero wrote:
>
> > I performed an usbmon capture extract, centered around the event
> > (there was a few hundred MBs written for this to happen):
> >
> > Nov 15 22:16:33 Bidule kernel: usb 6-4.3.2.1: reset SuperSpeed USB
> > device number 8 using xhci_hcd
> >
> > I can see that the computer is sending a write request, and sees a
> > -EPROTO in answer (capture in attachment), so scratch the timeout
> > issue (and actually when thinking about it, this matches what UAS
> > was saying, except that UAS was taking ages to recover).
> >
> > Looked for EPROTO in the usb code, and found a dynamic debug printf
> > in XHCI; after enabling it:
> >
> > Nov 15 22:45:03 Bidule kernel: xhci_hcd 0000:07:00.0: Transfer
> > error for slot 13 ep 3 on endpoint Nov 15 22:45:03 Bidule kernel:
> > xhci_hcd 0000:07:00.0: Transfer error for slot 12 ep 3 on endpoint
> > Nov 15 22:45:03 Bidule kernel: usb 6-4.3.3.1: reset SuperSpeed USB
> > device number 9 using xhci_hcd Nov 15 22:45:03 Bidule kernel: usb
> > 6-4.3.2.1: reset SuperSpeed USB device number 8 using xhci_hcd
> >
> > First, I understand that a bad USB device could poison the kernel
> > log, but shouldn't that xhci_dbg() (and others eg. babble) be at
> > least an xhci_info() (I saw 2a9227a5)?
>
> I suspect that if every USB error got printed in the kernel log,
> people would be upset at how much useless information was added.
So it turns out that one of the 2 drives that produced most of these
errors died overnight (the kernel first reported failure at READ DMA
EXT, SMART seeing 6k Current_Pending_Sector / Offline_Uncorrectable,
then the drive just lost it and wouldn't even complete USB enumeration
now.
IMHO too much information is perhaps better than not enough, and I bet
that people would reconsider purchasing low-quality hardware if they
noticed these (unless they can happen for no reason).
>
> > Then... I don't know enough to attribute the issue the upstream USB
> > hub(s) or the drive endpoint not behaving properly, or the
> > kernel... what should I do with these messages?
>
> Here's the error:
>
> b5251480 0.505661 S Bo:6:008:2 -115 196608 = 540a2813 1a33dd99
> ab76840c bf72fc6b 60f9fcaf 4d61822c c007ff4e ab72d022 b5251480
> 0.506280 C Bo:6:008:2 -71 86016 >
Out of curiosity, which tool produced this condensed output?
> This means the kernel tried to write 196608 bytes to the drive. After
> 86016 had been transferred, the drive did not reply correctly to the
> next output transaction, causing the kernel to perform a reset.
> That's what happened, according to the viewpoint of the xhci-hcd
> driver.
>
> In theory it's possible that the drive did respond correctly and the
> information get messed up on the USB cable or on the computer's end.
Wow, that sucks.
I had a mental image where the transactions used FEC and it would be
obviously possible to differentiate between cable/hub/endpoint errors.
> Since we can't see what signals were actually sent on the USB bus,
> there's no way to be certain. But it seems most likely that the drive
> (or rather, its USB interface) was at fault.
I would speculate (with high confidence) that the drive itself is doing
unexpected stuff, because of that bugzilla issue showing that these SMR
drives also behave strangely when connected on SATA.
I have had in circulation 10 of these 8 TB SMR drives, 1 SATA and 9 USB,
and all of them are generating unexpected kernel logging to some
extent, when subject to write-intensive loads.
2 from 2015 and SMART says they're all good; the rest since 10 days
ago, one was DOA (very early SMART bad sectors) and tonight's failure
has an S/N consecutive to that first DOA one, which smells a little.
> > I'm still filling the drives, will perform a scrub after, to see if
> > the issue causes data loss...
To be continued... since it looks like there's no fundamental issue
with the kernel itself and this is turning into a rant on hardware,
I'll just direct follow-up e-mails to the ML only, tell me if you want
to stay in CC.
Thanks again,
--
Jérôme
=== START OF INFORMATION SECTION ===
Device Model: ST8000DM004-2CX188
Serial Number: XXXXXXXX
LU WWN Device Id: XXXXXXXXXXXXXXXXXX
Firmware Version: 0001
User Capacity: 8,001,563,222,016 bytes [8.00 TB]
Sector Sizes: 512 bytes logical, 4096 bytes physical
Rotation Rate: 5425 rpm
Device is: Not in smartctl database [for details use: -P showall]
ATA Version is: ACS-3 T13/2161-D revision 5
SATA Version is: SATA 3.1, 6.0 Gb/s (current: 3.0 Gb/s)
Local Time is: Thu Nov 16 23:36:32 2017 EST
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
See vendor-specific Attribute list for marginal Attributes.
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: ( 0) 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: ( 951) minutes.
Conveyance self-test routine
recommended polling time: ( 2) minutes.
SCT capabilities: (0x30a5) SCT Status 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 058 049 006 Pre-fail Always - 179381080
3 Spin_Up_Time 0x0003 093 093 000 Pre-fail Always - 0
4 Start_Stop_Count 0x0032 100 100 020 Old_age Always - 38
5 Reallocated_Sector_Ct 0x0033 099 099 010 Pre-fail Always - 0
7 Seek_Error_Rate 0x000f 074 060 045 Pre-fail Always - 23699800
9 Power_On_Hours 0x0032 100 100 000 Old_age Always - 189 (82 112 0)
10 Spin_Retry_Count 0x0013 100 100 097 Pre-fail Always - 0
12 Power_Cycle_Count 0x0032 100 100 020 Old_age Always - 38
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 084 084 000 Old_age Always - 16
188 Command_Timeout 0x0032 099 092 000 Old_age Always - 115965888471
189 High_Fly_Writes 0x003a 100 100 000 Old_age Always - 0
190 Airflow_Temperature_Cel 0x0022 051 040 040 Old_age Always In_the_past 49 (Min/Max 37/50)
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 - 66
193 Load_Cycle_Count 0x0032 100 100 000 Old_age Always - 55
194 Temperature_Celsius 0x0022 049 060 000 Old_age Always - 49 (0 19 0 0 0)
195 Hardware_ECC_Recovered 0x001a 083 065 000 Old_age Always - 179381080
197 Current_Pending_Sector 0x0012 081 081 000 Old_age Always - 6264
198 Offline_Uncorrectable 0x0010 081 081 000 Old_age Offline - 6264
199 UDMA_CRC_Error_Count 0x003e 200 200 000 Old_age Always - 0
240 Head_Flying_Hours 0x0000 100 253 000 Old_age Offline - 129 (54 58 0)
241 Total_LBAs_Written 0x0000 100 253 000 Old_age Offline - 5193420925
242 Total_LBAs_Read 0x0000 100 253 000 Old_age Offline - 4503355540
SMART Error Log Version: 1
ATA Error Count: 16 (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 16 occurred at disk power-on lifetime: 187 hours (7 days + 19 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 d5 80 ff ff ff 4f 00 4d+03:49:10.331 READ DMA EXT
25 d5 80 ff ff ff 4f 00 4d+03:49:10.330 READ DMA EXT
25 d5 80 ff ff ff 4f 00 4d+03:49:10.329 READ DMA EXT
25 d5 80 ff ff ff 4f 00 4d+03:49:10.328 READ DMA EXT
25 d5 80 ff ff ff 4f 00 4d+03:49:10.066 READ DMA EXT
Error 15 occurred at disk power-on lifetime: 187 hours (7 days + 19 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 d5 80 ff ff ff 4f 00 4d+03:49:03.920 READ DMA EXT
25 d5 08 ff ff ff 4f 00 4d+03:49:03.907 READ DMA EXT
25 d5 80 ff ff ff 4f 00 4d+03:49:03.899 READ DMA EXT
25 d5 80 ff ff ff 4f 00 4d+03:49:03.635 READ DMA EXT
25 d5 80 ff ff ff 4f 00 4d+03:49:03.633 READ DMA EXT
Error 14 occurred at disk power-on lifetime: 187 hours (7 days + 19 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 d5 80 ff ff ff 4f 00 4d+03:47:44.792 READ DMA EXT
25 d5 80 ff ff ff 4f 00 4d+03:47:44.789 READ DMA EXT
25 d5 80 ff ff ff 4f 00 4d+03:47:44.780 READ DMA EXT
25 d5 80 ff ff ff 4f 00 4d+03:47:44.779 READ DMA EXT
25 d5 80 ff ff ff 4f 00 4d+03:47:44.756 READ DMA EXT
Error 13 occurred at disk power-on lifetime: 145 hours (6 days + 1 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 d5 80 ff ff ff 4f 00 2d+10:36:05.555 READ DMA EXT
25 d5 38 ff ff ff 4f 00 2d+10:36:05.548 READ DMA EXT
25 d5 10 ff ff ff 4f 00 2d+10:36:05.547 READ DMA EXT
25 d5 80 ff ff ff 4f 00 2d+10:36:05.532 READ DMA EXT
25 d5 80 ff ff ff 4f 00 2d+10:36:05.479 READ DMA EXT
Error 12 occurred at disk power-on lifetime: 145 hours (6 days + 1 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 d5 80 ff ff ff 4f 00 2d+10:36:00.813 READ DMA EXT
25 d5 80 ff ff ff 4f 00 2d+10:36:00.800 READ DMA EXT
25 d5 80 ff ff ff 4f 00 2d+10:36:00.714 READ DMA EXT
25 d5 80 ff ff ff 4f 00 2d+10:36:00.627 READ DMA EXT
25 d5 80 00 4d 72 4c 00 2d+10:36:00.547 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.
