Re: Mass storage failure during USB2 data transfers

On Sun, 19 Aug 2007, Jan Ciger wrote:

> > If you want to gather more information about the problem, you can try
> >  using the usbmon facility.  Instructions are in the kernel source
> > file Documentation/usb/usbmon.txt.
> 
> I have done so, the report with the /var/log/messages is at:
> http://www.aaue.dk/~janoc/files/download/usb/

For your information, here is the relevant part of the log with
corresponding explanations.  This is about 99% of the way through the
log, after lots of write transfers have succeeded.

c6d38c40 2670585026 S Bo:1:005:1 -115 31 = 55534243 6a410000 00400000 00000a2a 0000bb5f 2a000020 00000000 000000
c6d38c40 2670585121 C Bo:1:005:1 0 31 >

This is the start of another write.

e1154e40 2670585126 S Bo:1:005:1 -115 8192 = ec83438d 87279fab 0b7993ac ba5f8e07 cbecd589 093dd526 aab8ffe8 5f8f1e3a
e2189840 2670585130 S Bo:1:005:1 -115 8192 = 983732df c67c07f3 9dcc9b09 31f7b570 7e470807 a1bf723d db0831a7 9ce6fa75
e1154e40 2670585622 C Bo:1:005:1 0 8192 >
e2189840 2670585625 C Bo:1:005:1 0 8192 >

These lines show 16384 total bytes of data successfully transmitted to 
the drive.

c6d38c40 2670585629 S Bi:1:005:2 -115 13 <
c6d38c40 2700581208 C Bi:1:005:2 -104 0

This is the computer waiting 30 seconds for the drive to send back a
status message indicating whether or not the write was carried out
correctly.  The drive sent no status message and eventually the
computer gave up.

f5990b40 2700581229 S Co:1:001:0 s 23 03 0004 0004 0000 0
f5990b40 2700581237 C Co:1:001:0 0 0
f5990b40 2700637091 S Ci:1:001:0 s a3 00 0000 0004 0004 4 <
f5990b40 2700637332 C Ci:1:001:0 0 4 = 03051000
f5990b40 2700693091 S Co:1:001:0 s 23 01 0014 0004 0000 0
f5990b40 2700693099 C Co:1:001:0 0 0
f5990b40 2700693113 S Co:1:000:0 s 00 05 0005 0000 0000 0
f5990b40 2700693326 C Co:1:000:0 0 0
f5990b40 2700713093 S Ci:1:005:0 s 80 06 0100 0000 0008 8 <
f5990b40 2700713323 C Ci:1:005:0 0 8 = 12010002 00000040
f5990b40 2700713328 S Ci:1:005:0 s 80 06 0100 0000 0012 18 <
f5990b40 2700727322 C Ci:1:005:0 0 18 = 12010002 00000040 9b057801 01000102 0301
f5990b40 2700727327 S Ci:1:005:0 s 80 06 0200 0000 0020 32 <
f5990b40 2700730198 C Ci:1:005:0 0 32 = 09022000 010100c0 01090400 00020806 50000705 01020002 00070582 02000200
f5990b40 2700730208 S Co:1:005:0 s 00 09 0001 0000 0000 0
f5990b40 2700730446 C Co:1:005:0 0 0
f5990b40 2700730452 S Co:1:005:0 s 01 0b 0000 0000 0000 0
f5990b40 2700730697 C Co:1:005:0 0 0

This is a standard reset sequence.  It appears to have succeeded; that 
is, the drive replied correctly to the various requests.

c6d38c40 2700739165 S Bo:1:005:1 -115 31 = 55534243 6b410000 00000000 00000600 00000000 00000000 00000000 000000
c6d38c40 2700739328 C Bo:1:005:1 0 31 >
c6d38c40 2700739360 S Bi:1:005:2 -115 13 <
c6d38c40 2710729147 C Bi:1:005:2 -104 0

This is a TEST UNIT READY command, to check whether the drive is
prepared to accept new commands following the reset.  Once again, the
drive failed to send back any status information and the computer gave 
up after 10 seconds.

f5990b40 2710729175 S Co:1:001:0 s 23 03 0004 0004 0000 0
f5990b40 2710729180 C Co:1:001:0 0 0
f5990b40 2710785096 S Ci:1:001:0 s a3 00 0000 0004 0004 4 <
f5990b40 2710785318 C Ci:1:001:0 0 4 = 03051000
f5990b40 2710841088 S Co:1:001:0 s 23 01 0014 0004 0000 0
f5990b40 2710841094 C Co:1:001:0 0 0
f5990b40 2710841105 S Co:1:000:0 s 00 05 0005 0000 0000 0
f5990b40 2710841135 C Co:1:000:0 -71 0

This is the start of another reset sequence.  Here the reset did not
succeed; the drive failed to respond at all.  The log goes on for a
while, but the rest doesn't contain anything useful.  Basically the
drive stopped communicating entirely.

> I have tried to copy an approx 700MB with an old Knoppix ISO image to
> the disk. After this error the drive was not completely blocked, but I
> have received the following after unplugging the USB cable and plugging
> it back:
> 
> usb 1-4: new high speed USB device using ehci_hcd and address 6
> usb 1-4: device not accepting address 6, error -71
> usb 1-4: new high speed USB device using ehci_hcd and address 7
> usb 1-4: device not accepting address 7, error -71
> usb 1-4: new high speed USB device using ehci_hcd and address 8
> usb 1-4: device descriptor read/64, error -71
> usb 1-4: device descriptor read/64, error -71
> usb 1-4: new high speed USB device using ehci_hcd and address 9
> usb 1-4: device descriptor read/64, error -71
> usb 1-4: device descriptor read/64, error -71
> ...
> 
> Only power-cycling the drive managed to recover it.

This clearly is a bug in the drive's USB interface.  Power-cycling the 
drive wouldn't fix a problem in the computer, and a problem in the 
computer wouldn't cause the drive to go bonkers like that.

If you want to pursue this further, you should test various vanilla 
kernels (no Mandriva changes).  Find the most recent version that 
works and the earliest version (which should be the very next one, 
obviously) that doesn't.  From there it might be possible to identify 
what change, if any, is responsible for the drive's bad behavior.

Alan Stern


-------------------------------------------------------------------------
This SF.net email is sponsored by: Splunk Inc.
Still grepping through log files to find problems?  Stop.
Now Search log events and configuration files using AJAX and a browser.
Download your FREE copy of Splunk now >>  http://get.splunk.com/
_______________________________________________
[email protected]
To unsubscribe, use the last form field at:
https://lists.sourceforge.net/lists/listinfo/linux-usb-devel