New: Stack trace when running smartctl on an USB disk

(switched to email. Please respond via emailed reply-to-all, not via the bugzilla web interface).

Yup, that's a bug. I assume that smartctl never recovered?

I don't know if it's a scsi bug or a usb bug. Probably the latter?

Hi, Andrew & Co.

Thanks for the confirmation.

Yes, sorry for not mentioning this explicitly. smartctl hang there and was uninterruptible. :-(

Again, just reiterating, what I said before, even though I am not sure if I can reproduce it, I will try to.

And if any further information about my hardware is needed, please, just let me know.

Thanks, Rogério Brito.

Rogério Brito : rbrito@{mackenzie,ime.usp}.br : GPG key 1024D/7C2CAEB8
http://www.ime.usp.br/~rbrito : http://meusite.mackenzie.com.br/rbrito
Projects: algorithms.berlios.de : lame.sf.net : vrms.alioth.debian.org
--
To unsubscribe from this list: send the line "unsubscribe linux-usb" in
the body of a message to [email protected]
More majordomo info at  http://vger.kernel.org/majordomo-info.html

A usbmon trace showing what happens when you plug in the drive and when you run smartctl would help.

Alan Stern

--
To unsubscribe from this list: send the line "unsubscribe linux-scsi" in the body of a message to [email protected]
More majordomo info at http://vger.kernel.org/majordomo-info.html

Hi, Alan, Andrew and others.

Well, I'll just go grab the sources to usbmon. In the mean time, I just issued the command with a freshly compiled 2.6.31-rc7 and the problem persists:

,----
| 5581 pts/1 D+ 0:00 ./smartctl -d usbcypress -a /dev/sda
`----

(And the stack traces too).

I will be replying with the usbmon trace ASAP.

Thanks, Rogério Brito.

Rogério Brito : rbrito@{mackenzie,ime.usp}.br : GPG key 1024D/7C2CAEB8
http://www.ime.usp.br/~rbrito : http://meusite.mackenzie.com.br/rbrito
Projects: algorithms.berlios.de : lame.sf.net : vrms.alioth.debian.org
--
To unsubscribe from this list: send the line "unsubscribe linux-scsi" in
the body of a message to [email protected]
More majordomo info at  http://vger.kernel.org/majordomo-info.html

Hi, it's me again.

(...)

Well, after some minutes (the time that I took to check my computer and to compose the previous message), I got two stack traces (attached to this message) and smartctl has just finished:

,----

| chagas:/tmp/sbin# ./smartctl -d usbcypress -a /dev/sda
| smartctl 5.39 2009-08-20 r2876 [x86_64-unknown-linux-gnu] (local build)
| Copyright (C) 2002-9 by Bruce Allen, http://smartmontools.sourceforge.net
| 
| === START OF INFORMATION SECTION ===
| Device Model:     [No Information Found]
| Serial Number:    [No Information Found]
| Firmware Version: [No Information Found]
| Device is:        Not in smartctl database [for details use: -P showall]
| ATA Version is:   1
| ATA Standard is:  Exact ATA specification draft version not indicated
| Local Time is:    Sat Aug 22 16:13:12 2009 BRT
| SMART is only available in ATA Version 3 Revision 3 or greater.
| We will try to proceed in spite of this.
| SMART support is: Ambiguous - ATA IDENTIFY DEVICE words 82-83 don't show if SMART supported.
| A mandatory SMART command failed: exiting. To continue, add one or more '-T permissive' options.
| chagas:/tmp/sbin#

`----

Does this help (at least a bit), before I get usbmon working? I just wanted to report something that could be an extra data point.

Regards, Rogério Brito.

Rogério Brito : rbrito@{mackenzie,ime.usp}.br : GPG key 1024D/7C2CAEB8
http://www.ime.usp.br/~rbrito : http://meusite.mackenzie.com.br/rbrito
Projects: algorithms.berlios.de : lame.sf.net : vrms.alioth.debian.org
--
To unsubscribe from this list: send the line "unsubscribe linux-usb" in
the body of a message to [email protected]
More majordomo info at  http://vger.kernel.org/majordomo-info.html

(...)

The eternal problems between humans and attachments... :-(

Regards, Rogério Brito.

Rogério Brito : rbrito@{mackenzie,ime.usp}.br : GPG key 1024D/7C2CAEB8
http://www.ime.usp.br/~rbrito : http://meusite.mackenzie.com.br/rbrito
Projects: algorithms.berlios.de : lame.sf.net : vrms.alioth.debian.org

[ 3557.766018] usb 1-1: new high speed USB device using ehci_hcd and address 2
[ 3557.880845] usb 1-1: New USB device found, idVendor=06e1, idProduct=d185
[ 3557.880852] usb 1-1: New USB device strings: Mfr=56, Product=78, SerialNumber=100
[ 3557.880856] usb 1-1: Product: USB2.0 Storage Device
[ 3557.880859] usb 1-1: Manufacturer: ADS Technologies lnc.
[ 3557.880862] usb 1-1: SerialNumber: A9EA07106E8C
[ 3557.880990] usb 1-1: configuration #1 chosen from 1 choice
[ 3557.912142] Initializing USB Mass Storage driver...
[ 3557.913540] scsi2 : SCSI emulation for USB Mass Storage devices
[ 3557.915028] usb-storage: device found at 2
[ 3557.915033] usb-storage: waiting for device to settle before scanning
[ 3557.915068] usbcore: registered new interface driver usb-storage
[ 3557.915075] USB Mass Storage support registered.
[ 3562.915318] usb-storage: device scan complete
[ 3562.915795] scsi 2:0:0:0: Direct-Access     ST375064 0A                    PQ: 0 ANSI: 0
[ 3562.951132] sd 2:0:0:0: [sda] 1465149168 512-byte logical blocks: (750 GB/698 GiB)
[ 3562.951998] sd 2:0:0:0: [sda] Write Protect is off
[ 3562.952017] sd 2:0:0:0: [sda] Mode Sense: 33 00 00 00
[ 3562.952024] sd 2:0:0:0: [sda] Assuming drive cache: write through
[ 3562.953873] sd 2:0:0:0: [sda] Assuming drive cache: write through
[ 3562.953879]  sda: sda1
[ 3562.978866] sd 2:0:0:0: [sda] Assuming drive cache: write through
[ 3562.978873] sd 2:0:0:0: [sda] Attached SCSI disk
[ 3563.422546] EXT4-fs (sda1): barriers enabled
[ 3563.451546] kjournald2 starting: pid 5527, dev sda1:8, commit interval 5 seconds
[ 3563.452641] EXT4-fs (sda1): internal journal on sda1:8
[ 3563.452649] EXT4-fs (sda1): delayed allocation enabled
[ 3563.452655] EXT4-fs: file extents enabled
[ 3563.500069] EXT4-fs: mballoc enabled
[ 3563.500103] EXT4-fs (sda1): mounted filesystem with ordered data mode
[ 4205.806025] usb 1-1: reset high speed USB device using ehci_hcd and address 2
[ 4205.920895] program smartctl is using a deprecated SCSI ioctl, please convert it to SG_IO
[ 4266.806022] usb 1-1: reset high speed USB device using ehci_hcd and address 2
[ 4327.806033] usb 1-1: reset high speed USB device using ehci_hcd and address 2
[ 4388.807021] usb 1-1: reset high speed USB device using ehci_hcd and address 2
[ 4440.168050] INFO: task smartctl:5581 blocked for more than 120 seconds.
[ 4440.168055] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[ 4440.168060] smartctl      D ffff8800014ad9c0     0  5581   2677 0x00000000
[ 4440.168068]  ffff8800681bf740 0000000000000086 0000000000000001 0000000000000001
[ 4440.168075]  00000000000109c0 000000000000c858 ffff8800681be360 ffff8800681be6d8
[ 4440.168082]  000000007c8713b0 ffff880068051d68 ffff8800681be6d8 ffff880068051d70
[ 4440.168089] Call Trace:
[ 4440.168103]  [<ffffffff812594de>] ? schedule_timeout+0x1e/0xb8
[ 4440.168138]  [<ffffffffa00482ca>] ? scsi_request_fn+0x355/0x423 [scsi_mod]
[ 4440.168146]  [<ffffffff8103ec9f>] ? del_timer+0x59/0x62
[ 4440.168152]  [<ffffffff812589ce>] ? wait_for_common+0xaa/0x10b
[ 4440.168159]  [<ffffffff81030077>] ? default_wake_function+0x0/0x9
[ 4440.168167]  [<ffffffff81107298>] ? __generic_unplug_device+0x12/0x2c
[ 4440.168173]  [<ffffffff8110a5f4>] ? blk_execute_rq+0x93/0xab
[ 4440.168178]  [<ffffffff8110a7b9>] ? blk_recount_segments+0x17/0x27
[ 4440.168184]  [<ffffffff811054c6>] ? blk_rq_bio_prep+0x39/0x69
[ 4440.168190]  [<ffffffff8110d8be>] ? sg_scsi_ioctl+0x229/0x2ad
[ 4440.168196]  [<ffffffff8110dc94>] ? scsi_cmd_ioctl+0x352/0x39e
[ 4440.168202]  [<ffffffff81069912>] ? filemap_fault+0x5e/0x36d
[ 4440.168208]  [<ffffffff8107a2a8>] ? __do_fault+0x34b/0x386
[ 4440.168214]  [<ffffffff81113b80>] ? kobject_get+0x12/0x17
[ 4440.168225]  [<ffffffffa026c7e0>] ? sd_ioctl+0x78/0xa6 [sd_mod]
[ 4440.168230]  [<ffffffff8110b509>] ? __blkdev_driver_ioctl+0x69/0x7e
[ 4440.168236]  [<ffffffff8110bd14>] ? blkdev_ioctl+0x7d2/0x806
[ 4440.168241]  [<ffffffff81069912>] ? filemap_fault+0x5e/0x36d
[ 4440.168246]  [<ffffffff8107a2a8>] ? __do_fault+0x34b/0x386
[ 4440.168254]  [<ffffffff810b6c71>] ? block_ioctl+0x38/0x3c
[ 4440.168261]  [<ffffffff810a01fa>] ? vfs_ioctl+0x21/0x6c
[ 4440.168266]  [<ffffffff810a06fe>] ? do_vfs_ioctl+0x443/0x47b
[ 4440.168272]  [<ffffffff81021e5c>] ? do_page_fault+0x1fe/0x212
[ 4440.168277]  [<ffffffff810a0773>] ? sys_ioctl+0x3d/0x5c
[ 4440.168284]  [<ffffffff8100b02b>] ? system_call_fastpath+0x16/0x1b
[ 4449.806034] usb 1-1: reset high speed USB device using ehci_hcd and address 2
[ 4510.807023] usb 1-1: reset high speed USB device using ehci_hcd and address 2
[ 4560.168054] INFO: task smartctl:5581 blocked for more than 120 seconds.
[ 4560.168060] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[ 4560.168064] smartctl      D ffff8800014ad9c0     0  5581   2677 0x00000000
[ 4560.168072]  ffff8800681bf740 0000000000000086 0000000000000001 0000000000000001
[ 4560.168080]  00000000000109c0 000000000000c858 ffff8800681be360 ffff8800681be6d8
[ 4560.168087]  000000007c8713b0 ffff880068051d68 ffff8800681be6d8 ffff880068051d70
[ 4560.168095] Call Trace:
[ 4560.168108]  [<ffffffff812594de>] ? schedule_timeout+0x1e/0xb8
[ 4560.168142]  [<ffffffffa00482ca>] ? scsi_request_fn+0x355/0x423 [scsi_mod]
[ 4560.168150]  [<ffffffff8103ec9f>] ? del_timer+0x59/0x62
[ 4560.168155]  [<ffffffff812589ce>] ? wait_for_common+0xaa/0x10b
[ 4560.168163]  [<ffffffff81030077>] ? default_wake_function+0x0/0x9
[ 4560.168171]  [<ffffffff81107298>] ? __generic_unplug_device+0x12/0x2c
[ 4560.168177]  [<ffffffff8110a5f4>] ? blk_execute_rq+0x93/0xab
[ 4560.168182]  [<ffffffff8110a7b9>] ? blk_recount_segments+0x17/0x27
[ 4560.168188]  [<ffffffff811054c6>] ? blk_rq_bio_prep+0x39/0x69
[ 4560.168194]  [<ffffffff8110d8be>] ? sg_scsi_ioctl+0x229/0x2ad
[ 4560.168200]  [<ffffffff8110dc94>] ? scsi_cmd_ioctl+0x352/0x39e
[ 4560.168206]  [<ffffffff81069912>] ? filemap_fault+0x5e/0x36d
[ 4560.168213]  [<ffffffff8107a2a8>] ? __do_fault+0x34b/0x386
[ 4560.168219]  [<ffffffff81113b80>] ? kobject_get+0x12/0x17
[ 4560.168229]  [<ffffffffa026c7e0>] ? sd_ioctl+0x78/0xa6 [sd_mod]
[ 4560.168235]  [<ffffffff8110b509>] ? __blkdev_driver_ioctl+0x69/0x7e
[ 4560.168240]  [<ffffffff8110bd14>] ? blkdev_ioctl+0x7d2/0x806
[ 4560.168246]  [<ffffffff81069912>] ? filemap_fault+0x5e/0x36d
[ 4560.168251]  [<ffffffff8107a2a8>] ? __do_fault+0x34b/0x386
[ 4560.168259]  [<ffffffff810b6c71>] ? block_ioctl+0x38/0x3c
[ 4560.168266]  [<ffffffff810a01fa>] ? vfs_ioctl+0x21/0x6c
[ 4560.168271]  [<ffffffff810a06fe>] ? do_vfs_ioctl+0x443/0x47b
[ 4560.168277]  [<ffffffff81021e5c>] ? do_page_fault+0x1fe/0x212
[ 4560.168283]  [<ffffffff810a0773>] ? sys_ioctl+0x3d/0x5c
[ 4560.168289]  [<ffffffff8100b02b>] ? system_call_fastpath+0x16/0x1b
[ 4571.806026] usb 1-1: reset high speed USB device using ehci_hcd and address 2

Hi there.

The documentation for usbmon in the kernel 2.6.31-rc7 kernel doesn't match what the kernel exposes in the debug fs tree. This patch fixes it.

---

index 6c3c625..ea05cf7 100644
@@ -33,7 +33,7 @@ if usbmon is built into the kernel.
 
 Verify that bus sockets are present.
 
-# ls /sys/kernel/debug/usbmon
+# ls /sys/kernel/debug/usb/usbmon
 0s  0u  1s  1t  1u  2s  2t  2u  3s  3t  3u  4s  4t  4u
 #
 

@@ -58,11 +58,11 @@ Bus=03 means it's bus 3.
 
 3. Start 'cat'
 
-# cat /sys/kernel/debug/usbmon/3u > /tmp/1.mon.out
+# cat /sys/kernel/debug/usb/usbmon/3u > /tmp/1.mon.out
 
 to listen on a single bus, otherwise, to listen on all buses, type:
 
-# cat /sys/kernel/debug/usbmon/0u > /tmp/1.mon.out
+# cat /sys/kernel/debug/usb/usbmon/0u > /tmp/1.mon.out
 
 This process will be reading until killed. Naturally, the output can be
 redirected to a desirable location. This is preferred, because it is going

Rogério Brito : rbrito@{mackenzie,ime.usp}.br : GPG key 1024D/7C2CAEB8
http://www.ime.usp.br/~rbrito : http://meusite.mackenzie.com.br/rbrito
Projects: algorithms.berlios.de : lame.sf.net : vrms.alioth.debian.org
--
To unsubscribe from this list: send the line "unsubscribe linux-scsi" in
the body of a message to [email protected]
More majordomo info at  http://vger.kernel.org/majordomo-info.html

...

It doesn't help. I need to see the usbmon output.

Alan Stern

--
To unsubscribe from this list: send the line "unsubscribe linux-usb" in the body of a message to [email protected] More majordomo info at http://vger.kernel.org/majordomo-info.html

Hi, Alan.

The requested trace is attached to this message. Please let me know if you need more information.

Thanks, Rogério Brito.

Rogério Brito : rbrito@{mackenzie,ime.usp}.br : GPG key 1024D/7C2CAEB8
http://www.ime.usp.br/~rbrito : http://meusite.mackenzie.com.br/rbrito
Projects: algorithms.berlios.de : lame.sf.net : vrms.alioth.debian.org

The trace shows that something (presumably smartctl) sends a command the drive doesn't understand. The drive then violates the USB mass-storage protocol, sending an invalid response. The kernel waits for a proper response but nothing more happens, so after 30 seconds the command times out and is aborted and the drive is reset. The command then gets retried, and the same thing happens again. The retries take so long that the kernel complains about smartctl being blocked for more than 120 seconds -- that's the reason for the stack dump.

So the problem has several causes. One is that the drive is buggy (it doesn't respond with an error code in the proper way when it receives a command it doesn't understand). Another is that smartctl is trying to send commands in a form the drive can't handle. Finally, there's the problem about all the retries taking too long.

Perhaps you can blame the kernel for spending too much time on retries, but the other two are the fault of the drive and smartctl.

Alan Stern

--
To unsubscribe from this list: send the line "unsubscribe linux-scsi" in the body of a message to [email protected]
More majordomo info at http://vger.kernel.org/majordomo-info.html

Hi again, Alan.

(Sorry if this message seems messed up, but I am not using my regular mailer right now, unfortunately).

Right.

I'm not with the kernel sources here (so, I can't check the code), but is there any option to be able to log such invalid responses when the kernel gets one? Perhaps the verbose USB logging does that?

Right.

Geeez, Alan, is there any vendor out there that gets the USB implementation according to the specs?

This is the 3rd USB device that I sent you some message about where the kernel moans about something that it doesn't understand (I can get you the vendor and device ids when I get home).

I will test with some other devices that I have, just to see what their response is. :-(

That's probably not smartctl, but the user (me) that is telling it to use a given command set to check if the USB adapter understands/ allows pass-thru of the SMART protocol to the drive.

Is there anything that could be done about this?

I understand the p-o-v of the kernel: some devices need a little bit more time on a retry, while others don't. There's no way to hardcode a once and for all behavior. It seems that an expensive solution to this would be to create (yet) another list of blacklisted devices (how many lists of quirks do we have in the kernel already---this is really causing some bloat, especially for some embedded devices). :-(

OTOH, creating blacklists seem to not be the adequate (let alone "right") solution (see the ASUS/it87 monitoring cause) in many situations. :-/

Thanks for your always kind messages, Rogério Brito.

There's no way to log the invalid responses because the kernel doesn't realize they are invalid. However the resets _do_ get logged; you can see them in the logs you sent.

There are some... but a lot of them mess it up. :-(

Be sure to get usbmon traces.

Yes, it's entirely possible that this adapter does not understand the pass-thru protocol you tried. Isn't there more than one such protocol?

The length of each timeout is adjustable in sysfs, but I don't remember what attribute file you need to change.

Also, you could follow the instructions in those stack dumps. They are only warnings, not errors, and you can prevent the kernel from issuing them.

You're welcome.

Alan Stern

--
To unsubscribe from this list: send the line "unsubscribe linux-scsi" in the body of a message to [email protected]
More majordomo info at http://vger.kernel.org/majordomo-info.html

The fact that you invoked:
smartctl -d usbcypress -a /dev/sda

means that the cypress chip does not comply with SAT. To find out what commands are being sent (via the SG_IO ioctl I presume) by smartctl please try adding:
'-r ioctl,3'
to the above invocation.

Doug Gilbert

Hi, People.

Please, just wait a little bit more. I'm just getting recovered from being ill (my health is not very good, unfortunately).

That with some network (and e-mail) outages made things difficult. I'm just getting back now.

I'm going to test the suggestion from Douglas right now.

Thanks, Rogério Brito.

Rogério Brito : rbrito@{mackenzie,ime.usp}.br : GPG key 1024D/7C2CAEB8
http://www.ime.usp.br/~rbrito : http://meusite.mackenzie.com.br/rbrito
Projects: algorithms.berlios.de : lame.sf.net : vrms.alioth.debian.org
--
To unsubscribe from this list: send the line "unsubscribe linux-scsi" in
the body of a message to [email protected]
More majordomo info at  http://vger.kernel.org/majordomo-info.html