System hangs when using USB 3.0 HD with on Ubuntu

Hmm, ok, I would rather figure out why 2.6.31 is hanging, since 2.6.32 does not. Can you compile the latest 2.6.31 stable tree and use netconsole to capture the crash with CONFIG_USB_XHCI_HCD_DEBUGGING and CONFIG_USB_STORAGE_DEBUG turned on? (I assume you know how to use netconsole, but if you don't, I've posted how I setup netconsole at
http://sarah.thesharps.us/2010-03-26-09-41)

I think the amount of information is fine, but I'm not sure why the device would respond with a stall to this particular command, so I'm CC'ing the USB storage list and SCSI list. Does anyone know what the third command is? The USB storage driver reports it as an "unknown command". I can see from scsi.h that 0x85 is the code for ATA_16, but I'm not sure what that command actually does.

Mar 24 18:53:36 js-workstation kernel: [  253.403792] usb-storage: Command BLANK (12 bytes)
Mar 24 18:53:36 js-workstation kernel: [  253.403794] usb-storage:  a1 08 2e 00 01 00 00 00 00 ec 00 00
Mar 24 18:53:36 js-workstation kernel: [  253.403800] usb-storage: Bulk Command S 0x43425355 T 0x2d L 512 F 128 Trg 0 LUN 0 CL 12
Mar 24 18:53:36 js-workstation kernel: [  253.403802] usb-storage: usb_stor_bulk_transfer_buf: xfer 31 bytes
Mar 24 18:53:36 js-workstation kernel: [  253.403969] usb-storage: Status code 0; transferred 31/31
Mar 24 18:53:36 js-workstation kernel: [  253.403972] usb-storage: -- transfer complete
Mar 24 18:53:36 js-workstation kernel: [  253.403973] usb-storage: Bulk command transfer result=0
Mar 24 18:53:36 js-workstation kernel: [  253.403975] usb-storage: usb_stor_bulk_transfer_sglist: xfer 512 bytes, 1 entries
Mar 24 18:53:36 js-workstation kernel: [  253.409708] usb-storage: Status code 0; transferred 512/512
Mar 24 18:53:36 js-workstation kernel: [  253.409709] usb-storage: -- transfer complete
Mar 24 18:53:36 js-workstation kernel: [  253.409710] usb-storage: Bulk data transfer result 0x0
Mar 24 18:53:36 js-workstation kernel: [  253.409711] usb-storage: Attempting to get CSW...
Mar 24 18:53:36 js-workstation kernel: [  253.409712] usb-storage: usb_stor_bulk_transfer_buf: xfer 13 bytes
Mar 24 18:53:36 js-workstation kernel: [  253.409854] usb-storage: Status code 0; transferred 13/13
Mar 24 18:53:36 js-workstation kernel: [  253.409855] usb-storage: -- transfer complete
Mar 24 18:53:36 js-workstation kernel: [  253.409856] usb-storage: Bulk status result = 0
Mar 24 18:53:36 js-workstation kernel: [  253.409858] usb-storage: Bulk Status S 0x53425355 T 0x2d R 0 Stat 0x0
Mar 24 18:53:36 js-workstation kernel: [  253.409859] usb-storage: scsi cmd done, result=0x0
Mar 24 18:53:36 js-workstation kernel: [  253.409861] usb-storage: *** thread sleeping.
Mar 24 18:53:36 js-workstation kernel: [  253.413870] usb-storage: queuecommand called
Mar 24 18:53:36 js-workstation kernel: [  253.413874] usb-storage: *** thread awakened.

Mar 24 18:53:36 js-workstation kernel: [  253.413876] usb-storage: Command (unknown command) (16 bytes)
Mar 24 18:53:36 js-workstation kernel: [  253.413877] usb-storage:  85 06 20 00 05 00 fe 00 00 00 00 00 00 40 ef 00
Mar 24 18:53:36 js-workstation kernel: [  253.413882] usb-storage: Bulk Command S 0x43425355 T 0x2e L 0 F 0 Trg 0 LUN 0 CL 16
Mar 24 18:53:36 js-workstation kernel: [  253.414229] usb-storage: Bulk Command S 0x43425355 T 0x2f L 512 F 128 Trg 0 LUN 0 CL 16
Mar 24 18:53:36 js-workstation kernel: [  253.413883] usb-storage: usb_stor_bulk_transfer_buf: xfer 31 bytes
Mar 24 18:53:36 js-workstation kernel: [  253.414031] usb-storage: Status code 0; transferred 31/31
Mar 24 18:53:36 js-workstation kernel: [  253.414032] usb-storage: -- transfer complete
Mar 24 18:53:36 js-workstation kernel: [  253.414033] usb-storage: Bulk command transfer result=0
Mar 24 18:53:36 js-workstation kernel: [  253.414034] usb-storage: Attempting to get CSW...
Mar 24 18:53:36 js-workstation kernel: [  253.414035] usb-storage: usb_stor_bulk_transfer_buf: xfer 13 bytes
Mar 24 18:53:36 js-workstation kernel: [  253.414179] usb-storage: Status code 0; transferred 13/13
Mar 24 18:53:36 js-workstation kernel: [  253.414180] usb-storage: -- transfer complete
Mar 24 18:53:36 js-workstation kernel: [  253.414181] usb-storage: Bulk status result = 0
Mar 24 18:53:36 js-workstation kernel: [  253.414182] usb-storage: Bulk Status S 0x53425355 T 0x2e R 0 Stat 0x0
Mar 24 18:53:36 js-workstation kernel: [  253.414183] usb-storage: scsi cmd done, result=0x0
Mar 24 18:53:36 js-workstation kernel: [  253.414186] usb-storage: *** thread sleeping.
Mar 24 18:53:36 js-workstation kernel: [  253.414217] usb-storage: queuecommand called
Mar 24 18:53:36 js-workstation kernel: [  253.414222] usb-storage: *** thread awakened.

Mar 24 18:53:36 js-workstation kernel: [  253.414223] usb-storage: Command (unknown command) (16 bytes)
Mar 24 18:53:36 js-workstation kernel: [  253.414224] usb-storage:  85 08 2e 00 00 00 00 00 00 00 00 00 00 40 ec 00
Mar 24 18:53:36 js-workstation kernel: [  253.414229] usb-storage: Bulk Command S 0x43425355 T 0x2f L 512 F 128 Trg 0 LUN 0 CL 16
Mar 24 18:53:36 js-workstation kernel: [  253.414230] usb-storage: usb_stor_bulk_transfer_buf: xfer 31 bytes
Mar 24 18:53:36 js-workstation kernel: [  253.414378] usb-storage: Status code 0; transferred 31/31
Mar 24 18:53:36 js-workstation kernel: [  253.414379] usb-storage: -- transfer complete
Mar 24 18:53:36 js-workstation kernel: [  253.414380] usb-storage: Bulk command transfer result=0
Mar 24 18:53:36 js-workstation kernel: [  253.414381] usb-storage: usb_stor_bulk_transfer_sglist: xfer 512 bytes, 1 entries
Mar 24 18:53:36 js-workstation kernel: [  253.414458] xhci_hcd 0000:03:00.0: WARN: Stalled endpoint
Mar 24 18:53:36 js-workstation kernel: [  253.414529] usb-storage: Status code -32; transferred 0/512
Mar 24 18:53:36 js-workstation kernel: [  253.414530] usb-storage: clearing endpoint halt for pipe 0xc0008280
Mar 24 18:53:36 js-workstation kernel: [  253.414532] usb-storage: usb_stor_control_msg: rq=01 rqtype=02 value=0000 index=81 len=0
Mar 24 18:53:36 js-workstation kernel: [  253.414894] usb-storage: usb_stor_clear_halt: result = 0
Mar 24 18:53:36 js-workstation kernel: [  253.414895] usb-storage: Bulk data transfer result 0x2
Mar 24 18:53:36 js-workstation kernel: [  253.414896] usb-storage: Attempting to get CSW...
Mar 24 18:53:36 js-workstation kernel: [  253.414897] usb-storage: usb_stor_bulk_transfer_buf: xfer 13 bytes
Mar 24 18:53:36 js-workstation kernel: [  253.414902] xhci_hcd 0000:03:00.0: WARN halted endpoint, queueing URB anyway.
Mar 24 18:53:36 js-workstation kernel: [  253.415168] usb-storage: Status code 0; transferred 13/13
Mar 24 18:53:36 js-workstation kernel: [  253.415169] usb-storage: -- transfer complete
Mar 24 18:53:36 js-workstation kernel: [  253.415170] usb-storage: Bulk status result = 0
Mar 24 18:53:36 js-workstation kernel: [  253.415171] usb-storage: Bulk Status S 0x53425355 T 0x2f R 512 Stat 0x2
Mar 24 18:53:36 js-workstation kernel: [  253.415172] usb-storage: -- transport indicates error, resetting
Mar 24 18:53:36 js-workstation kernel: [  253.415174] usb-storage: usb_stor_pre_reset
Mar 24 18:53:36 js-workstation kernel: [  253.415204] usb-storage: usb_stor_post_reset

I'm trying to figure out if this device would benefit from any USB storage quirks being set.

Sarah Sharp
--
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

ATA commands are being tunnelled through SCSI commands as defined in section 12.2 of this draft:
http://www.t10.org/cgi-bin/ac.pl?t=f&f=sat2r09.pdf
[The access control page will accept most anything in its fields.]

In the case of the SCSI ATA PASS-THROUGH 16 (i.e. ATA_16) command (opcode 85(hex) in the first byte) the tunnelled ATA command code is the second last byte (e.g. "ec" on the command that seemed to crash).

Doug Gilbert

I've got nothing. BUT, usb-storage translates the command codes to names via a table maintained by the SCSI people. If it's not in the table, then it's very likely coming from a userspace program.

Not that I'm aware of.

I find it interesting that an endpoint stalled, we cleared the endpoint, but then it is still listed as halted. That seems odd to me....

Matt

Matthew Dharm                              Home: [email protected] 
Maintainer, Linux USB Mass Storage Driver

Pitr!  That's brilliant!  Funded by Microsoft refunds.  What sweet irony!
					-- A.J.
User Friendly, 2/15/1999

Probably from gpartd trying to partition the drive.

It looks odd, but it's normal. The issue is that the xHCI hardware keeps track of whether an endpoint is halted or not, and the xHCI driver must issue a command to the xHCI hardware to reset the endpoint, separate from the control transfer to the device to clear the stall.

The xHCI's reset endpoint command hasn't completed before the URB is submitted, but once the hardware processes the command, the xHCI driver re-rings the doorbell to get the URB restarted. The rest of the log file (which I trimmed) looked fine.

Sarah

Can't be, the log I sent you was recorded by simply plugging in the drive and doing nothing else on the machine.

-Jonas
--
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

I have never heard of any kernel driver issuing either the BLANK command or an ATA_16 pass-through command. It almost certainly is a user program doing this, but I don't know which one.

Booting into a minimal userspace environment (for example, with init=/bin/bash) might prove this.

No doubt the reason the drive fails to respond is because it can't handle these commands and gets fatally confused.

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

The ATA commands seem to be:

   IDENTIFY DEVICE  (via the ATA_12 tunnel)
   SET FEATURES     (via the ATA_16 tunnel)
   IDENTIFY DEVICE  (via the ATA_16 tunnel)

The last one fails but that could be caused by
the second last one. Doesn't look like smartd.
My money would be on udev.
--
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

Doug was right. I switched into runlevel 1 and connected the drive. Same errors as before. Then, I unplugged it, stopped the udev daemon and plugged it back in. Voila, I was able to manually mount the drive with no issues.

Where do we go from here? Does anyone know how to debug udev?

-Jonas
--
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

Since this seems to have become a udev issue I'm brining the hotplug/udev list into the loop.

A brief recap for the hotplug list readers: I'm experiencing issues with a USB 3.0 hard drive (Buffalo HD-HXU3) on kernel 2.6.32.9 with udev 151. When connected the device seems to be recognized and registered with xHCI and USB core correctly but then responds to a bulk transfer with a stall. We narrowed the issue down to udev by stopping the udev daemon, connecting the device and mounting it manually. If done this way the drive works fine. However, if udevd is running the device stalls. Below is an excerpt of the conversation involving the USB core, the USB storage and the SCSI list.

Any idea what command (most likely coming from udev) could cause the drive to stall and what could be done about it?

-Jonas

More specifically, what program issues ATA-passthrough commands? And what can be done to prevent it from doing so in cases where these commands cause the device to crash?

Alan Stern

Stock udev comes with ata_id which I think may be invoked for this device (but I'm not sure). Try moving it out of the way?

On most distros, udisks (also known as DeviceKit-disks before the name was changed) is installed which runs a small program that uses libatasmart to determine if the device is SMART capable:

http://cgit.freedesktop.org/udisks/tree/src/probers/udisks-probe-ata-smart.c

and this definitely runs for this USB device assuming removable is 0 in sysfs. Perhaps http://bugs.freedesktop.org/show_bug.cgi?id%673 is related? Maybe try with the latest libatasmart?

Thanks,
David

Since the sequence of commands was IDENTIFY DEVICE, SET FEATURES then IDENTIFY DEVICE again my guess is that SET FEATURES caused the problem. Why would a program called ata_id try to change the state of the device?

The SCSI subsystem has been very careful to call the minimum number of "safe" commands when setting up storage devices. Bitter experience has taught us that when one strays beyond what another OS from Oregon does, nasty things could happen.

I also suspect udev (more likely one of its helpers) is behind a bizarre sequence of commands sent to a storage device when it is closed. These commands make smartmontools and other tools that attempt to spin down an ATA disk useless.
[As an extra note, if the device is opened O_RDONLY the "extra" commands on close() don't arrive.]

Doug Gilbert

Jonas, these sound like good things to try. Find the ata_id and udisks programs on your computer and rename them so they can't be run automatically. Then see if the problem still occurs.

More precisely, the commands were IDENTIFY DEVICE (ATA-12), SET FEATURES (ATA-16), IDENTIFY DEVICE (ATA-16). The third command was not the same as the first, so one shouldn't assume that the third should have worked merely because the first did.

In fact, I would guess that the second IDENTIFY DEVICE is what caused the problem, since the first two commands both succeeded and the third failed. If the second command was responsible for the problem, I would have expected _it_ to fail.

In fact, those three commands may have been sent by different programs. It certainly is possible that the problem is related to libatasmart.

Alan Stern

Renamed both /usr/bin/udisks and /lib/udev/ata_id but the problem still occurs.

-Jnoas

That's the commandline tool, you need to check for something like:
/usr/lib/udisks/udisks-daemon

Can you run as root:
udevadm test /sys/class/block/sd...
and post the output here. So we see what udev would run on bootup.

Thanks,
Kay

Since the drive doesn't even show up as a block device when connected to the USB 3.0 port I can't run that command for the device directly. However, what I completely forgot to mention is that the drive works just fine when connected to a USB 2.0 port. This was why I initially thought the xHCI driver is to blame, but now that we are investigating udev this does seem kind of odd to me. So, attached is the udevadm test output with the drive connected to a USB 2.0 port.

-Jonas

run_command: calling: test
udevadm_test: version 151
parse_file: reading '/lib/udev/rules.d/40-fuse-utils.rules' as rules file
parse_file: reading '/lib/udev/rules.d/40-gnupg.rules' as rules file
parse_file: reading '/lib/udev/rules.d/40-hplip.rules' as rules file
parse_file: reading '/lib/udev/rules.d/40-ia64.rules' as rules file
parse_file: reading '/lib/udev/rules.d/40-infiniband.rules' as rules file
parse_file: reading '/lib/udev/rules.d/40-isdn.rules' as rules file
parse_file: reading '/lib/udev/rules.d/40-libgphoto2-2.rules' as rules file
parse_file: reading '/lib/udev/rules.d/40-libpisock9.rules' as rules file
parse_file: reading '/lib/udev/rules.d/40-libsane.rules' as rules file
parse_file: reading '/lib/udev/rules.d/40-pilot-links.rules' as rules file
parse_file: reading '/lib/udev/rules.d/40-ppc.rules' as rules file
parse_file: reading '/lib/udev/rules.d/40-usb-media-players.rules' as rules file
parse_file: reading '/lib/udev/rules.d/40-xserver-xorg-video-intel.rules' as rules file
parse_file: reading '/lib/udev/rules.d/40-zaptel.rules' as rules file
parse_file: reading '/lib/udev/rules.d/45-fuse.rules' as rules file
parse_file: reading '/lib/udev/rules.d/45-libmtp8.rules' as rules file
parse_file: reading '/lib/udev/rules.d/50-firmware.rules' as rules file
parse_file: reading '/lib/udev/rules.d/50-udev-default.rules' as rules file
parse_file: reading '/lib/udev/rules.d/55-Argyll.rules' as rules file
parse_file: reading '/lib/udev/rules.d/55-dm.rules' as rules file
add_rule: name empty, node creation suppressed
parse_file: reading '/lib/udev/rules.d/56-hpmud_support.rules' as rules file
parse_file: reading '/lib/udev/rules.d/60-cdrom_id.rules' as rules file
parse_file: reading '/lib/udev/rules.d/60-floppy.rules' as rules file
parse_file: reading '/lib/udev/rules.d/60-persistent-alsa.rules' as rules file
parse_file: reading '/lib/udev/rules.d/60-persistent-input.rules' as rules file
parse_file: reading '/lib/udev/rules.d/60-persistent-serial.rules' as rules file
parse_file: reading '/lib/udev/rules.d/60-persistent-storage-dm.rules' as rules file
parse_file: reading '/lib/udev/rules.d/60-persistent-storage-tape.rules' as rules file
parse_file: reading '/lib/udev/rules.d/60-persistent-storage.rules' as rules file
parse_file: reading '/lib/udev/rules.d/60-persistent-v4l.rules' as rules file
parse_file: reading '/lib/udev/rules.d/61-gnome-bluetooth-rfkill.rules' as rules file
parse_file: reading '/lib/udev/rules.d/61-mobile-action.rules' as rules file
parse_file: reading '/lib/udev/rules.d/61-option-modem-modeswitch.rules' as rules file
parse_file: reading '/lib/udev/rules.d/61-persistent-storage-edd.rules' as rules file
parse_file: reading '/lib/udev/rules.d/64-device-mapper.rules' as rules file
parse_file: reading '/lib/udev/rules.d/64-xorg-xkb.rules' as rules file
parse_file: reading '/lib/udev/rules.d/65-xorg-evdev.rules' as rules file
parse_file: reading '/lib/udev/rules.d/66-xorg-synaptics.rules' as rules file
parse_file: reading '/lib/udev/rules.d/69-xorg-vmmouse.rules' as rules file
parse_file: reading '/lib/udev/rules.d/69-xserver-xorg-input-wacom.rules' as rules file
parse_file: reading '/lib/udev/rules.d/70-acl.rules' as rules file
parse_file: reading '/lib/udev/rules.d/70-hid2hci.rules' as rules file
parse_file: reading '/etc/udev/rules.d/70-persistent-cd.rules' as rules file
parse_file: reading '/etc/udev/rules.d/70-persistent-net.rules' as rules file
parse_file: reading '/lib/udev/rules.d/70-printers.rules' as rules file
parse_file: reading '/lib/udev/rules.d/75-cd-aliases-generator.rules' as rules file
parse_file: reading '/lib/udev/rules.d/75-net-description.rules' as rules file
parse_file: reading '/lib/udev/rules.d/75-persistent-net-generator.rules' as rules file
parse_file: reading '/lib/udev/rules.d/75-tty-description.rules' as rules file
parse_file: reading '/lib/udev/rules.d/77-mm-ericsson-mbm.rules' as rules file
parse_file: reading '/lib/udev/rules.d/77-mm-longcheer-port-types.rules' as rules file
parse_file: reading '/lib/udev/rules.d/77-mm-zte-port-types.rules' as rules file
parse_file: reading '/lib/udev/rules.d/78-graphics-card.rules' as rules file
parse_file: reading '/lib/udev/rules.d/78-sound-card.rules' as rules file
parse_file: reading '/lib/udev/rules.d/79-fstab_import.rules' as rules file
parse_file: reading '/lib/udev/rules.d/80-alsa.rules' as rules file
parse_file: reading '/lib/udev/rules.d/80-drivers.rules' as rules file
parse_file: reading '/lib/udev/rules.d/80-libgpod.rules' as rules file
parse_file: reading '/lib/udev/rules.d/80-udisks.rules' as rules file
parse_file: reading '/lib/udev/rules.d/85-brltty.rules' as rules file
parse_file: reading '/lib/udev/rules.d/85-console-setup.rules' as rules file
parse_file: reading '/lib/udev/rules.d/85-dmraid.rules' as rules file
parse_file: reading '/lib/udev/rules.d/85-hdparm.rules' as rules file
parse_file: reading '/lib/udev/rules.d/85-hplj10xx.rules' as rules file
parse_file: reading '/lib/udev/rules.d/85-pcmcia.rules' as rules file
parse_file: reading '/lib/udev/rules.d/85-regulatory.rules' as rules file
parse_file: reading '/lib/udev/rules.d/85-usbmuxd.rules' as rules file
parse_file: reading '/lib/udev/rules.d/90-hal.rules' as rules file
parse_file: reading '/lib/udev/rules.d/90-pulseaudio.rules' as rules file
parse_file: reading '/lib/udev/rules.d/95-keyboard-force-release.rules' as rules file
parse_file: reading '/lib/udev/rules.d/95-keymap.rules' as rules file
parse_file: reading '/lib/udev/rules.d/95-kpartx.rules' as rules file
parse_file: reading '/lib/udev/rules.d/95-udev-late.rules' as rules file
parse_file: reading '/lib/udev/rules.d/95-upower-battery-recall-dell.rules' as rules file
parse_file: reading '/lib/udev/rules.d/95-upower-battery-recall-fujitsu.rules' as rules file
parse_file: reading '/lib/udev/rules.d/95-upower-battery-recall-gateway.rules' as rules file
parse_file: reading '/lib/udev/rules.d/95-upower-battery-recall-ibm.rules' as rules file
parse_file: reading '/lib/udev/rules.d/95-upower-battery-recall-lenovo.rules' as rules file
parse_file: reading '/lib/udev/rules.d/95-upower-battery-recall-toshiba.rules' as rules file
parse_file: reading '/lib/udev/rules.d/95-upower-csr.rules' as rules file
parse_file: reading '/lib/udev/rules.d/95-upower-hid.rules' as rules file
parse_file: reading '/lib/udev/rules.d/95-upower-wup.rules' as rules file
parse_file: reading '/lib/udev/rules.d/97-bluetooth.rules' as rules file
udev_rules_new: rules use 210456 bytes tokens (17538 * 12 bytes), 33791 bytes buffer
udev_rules_new: temporary index used 55620 bytes (2781 * 20 bytes)
udev_device_new_from_syspath: device 0x7f2546c418e0 has devpath '/devices/pci0000:00/0000:00:1a.7/usb1/1-2/1-2:1.0/host24/target24:0:0/24:0:0:0/block/sdb'
udev_device_new_from_syspath: device 0x7f2546c40dc0 has devpath '/devices/pci0000:00/0000:00:1a.7/usb1/1-2/1-2:1.0/host24/target24:0:0/24:0:0:0/block/sdb'
udev_device_read_db: device 0x7f2546c40dc0 filled with db file data
udev_device_new_from_syspath: device 0x7f2546c40630 has devpath '/devices/pci0000:00/0000:00:1a.7/usb1/1-2/1-2:1.0/host24/target24:0:0/24:0:0:0'
udev_device_new_from_syspath: device 0x7f2546c41210 has devpath '/devices/pci0000:00/0000:00:1a.7/usb1/1-2/1-2:1.0/host24/target24:0:0'
udev_device_new_from_syspath: device 0x7f2546c41510 has devpath '/devices/pci0000:00/0000:00:1a.7/usb1/1-2/1-2:1.0/host24'
udev_device_new_from_syspath: device 0x7f2546c365f0 has devpath '/devices/pci0000:00/0000:00:1a.7/usb1/1-2/1-2:1.0'
udev_device_new_from_syspath: device 0x7f2546c368c0 has devpath '/devices/pci0000:00/0000:00:1a.7/usb1/1-2'
udev_device_new_from_syspath: device 0x7f2546c36bb0 has devpath '/devices/pci0000:00/0000:00:1a.7/usb1'
udev_device_new_from_syspath: device 0x7f2546c36e60 has devpath '/devices/pci0000:00/0000:00:1a.7'
udev_device_new_from_syspath: device 0x7f2546c37110 has devpath '/devices/pci0000:00'
udev_rules_apply_to_event: LINK 'block/8:16' /lib/udev/rules.d/50-udev-default.rules:3
udev_rules_apply_to_event: GROUP 6 /lib/udev/rules.d/50-udev-default.rules:77
udev_rules_apply_to_event: IMPORT 'usb_id --export /devices/pci0000:00/0000:00:1a.7/usb1/1-2/1-2:1.0/host24/target24:0:0/24:0:0:0/block/sdb' /lib/udev/rules.d/60-persistent-storage.rules:22
util_run_program: 'usb_id --export /devices/pci0000:00/0000:00:1a.7/usb1/1-2/1-2:1.0/host24/target24:0:0/24:0:0:0/block/sdb' started
util_run_program: '/lib/udev/usb_id' (stdout) 'ID_VENDOR=BUFFALO'
util_run_program: '/lib/udev/usb_id' (stdout) 'ID_VENDOR_ENC=BUFFALO\x20'
util_run_program: '/lib/udev/usb_id' (stdout) 'ID_VENDOR_ID=0411'
util_run_program: '/lib/udev/usb_id' (stdout) 'ID_MODEL=External_HDD'
util_run_program: '/lib/udev/usb_id' (stdout) 'ID_MODEL_ENC=External\x20HDD\x20\x20\x20\x20'
util_run_program: '/lib/udev/usb_id' (stdout) 'ID_MODEL_ID=0184'
util_run_program: '/lib/udev/usb_id' (stdout) 'ID_REVISION=0100'
util_run_program: '/lib/udev/usb_id' (stdout) 'ID_SERIAL=BUFFALO_External_HDD_0000010155FF-0:0'
util_run_program: '/lib/udev/usb_id' (stdout) 'ID_SERIAL_SHORT=0000010155FF'
util_run_program: '/lib/udev/usb_id' (stdout) 'ID_TYPE=disk'
util_run_program: '/lib/udev/usb_id' (stdout) 'ID_INSTANCE=0:0'
util_run_program: '/lib/udev/usb_id' (stdout) 'ID_BUS=usb'
util_run_program: '/lib/udev/usb_id' (stdout) 'ID_USB_INTERFACES=:080650:'
util_run_program: '/lib/udev/usb_id' (stdout) 'ID_USB_INTERFACE_NUM=00'
util_run_program: '/lib/udev/usb_id' (stdout) 'ID_USB_DRIVER=usb-storage'
util_run_program: 'usb_id --export /devices/pci0000:00/0000:00:1a.7/usb1/1-2/1-2:1.0/host24/target24:0:0/24:0:0:0/block/sdb' returned with exitcode 0
udev_rules_apply_to_event: LINK 'disk/by-id/usb-BUFFALO_External_HDD_0000010155FF-0:0' /lib/udev/rules.d/60-persistent-storage.rules:30
udev_rules_apply_to_event: IMPORT 'path_id /devices/pci0000:00/0000:00:1a.7/usb1/1-2/1-2:1.0/host24/target24:0:0/24:0:0:0/block/sdb' /lib/udev/rules.d/60-persistent-storage.rules:47
util_run_program: 'path_id /devices/pci0000:00/0000:00:1a.7/usb1/1-2/1-2:1.0/host24/target24:0:0/24:0:0:0/block/sdb' started
util_run_program: '/lib/udev/path_id' (stdout) 'ID_PATH=pci-0000:00:1a.7-usb-0:2:1.0-scsi-0:0:0:0'
util_run_program: 'path_id /devices/pci0000:00/0000:00:1a.7/usb1/1-2/1-2:1.0/host24/target24:0:0/24:0:0:0/block/sdb' returned with exitcode 0
udev_rules_apply_to_event: LINK 'disk/by-path/pci-0000:00:1a.7-usb-0:2:1.0-scsi-0:0:0:0' /lib/udev/rules.d/60-persistent-storage.rules:48
udev_rules_apply_to_event: IMPORT '/sbin/blkid -o udev -p /dev/sdb' /lib/udev/rules.d/60-persistent-storage.rules:60
util_run_program: '/sbin/blkid -o udev -p /dev/sdb' started
util_run_program: '/sbin/blkid' (stdout) 'ID_PART_TABLE_TYPE=dos'
util_run_program: '/sbin/blkid -o udev -p /dev/sdb' returned with exitcode 0
udev_rules_apply_to_event: IMPORT 'edd_id --export /dev/sdb' /lib/udev/rules.d/61-persistent-storage-edd.rules:8
util_run_program: 'edd_id --export /dev/sdb' started
util_run_program: '/lib/udev/edd_id' (stderr) 'no kernel EDD support'
util_run_program: 'edd_id --export /dev/sdb' returned with exitcode 2
udev_rules_apply_to_event: IMPORT 'udisks-part-id /dev/sdb' /lib/udev/rules.d/80-udisks.rules:96
util_run_program: 'udisks-part-id /dev/sdb' started
util_run_program: '/lib/udev/udisks-part-id' (stderr) 'libudev: udev_device_new_from_syspath: device 0xf2a2f0 has devpath '/devices/pci0000:00/0000:00:1a.7/usb1/1-2/1-2:1.0/host24/target24:0:0/24:0:0:0/block/sdb''
util_run_program: '/lib/udev/udisks-part-id' (stderr) 'libudev: udev_device_read_db: device 0xf2a2f0 filled with db file data'
util_run_program: '/lib/udev/udisks-part-id' (stderr) 'using device_file=/dev/sdb syspath=/sys/devices/pci0000:00/0000:00:1a.7/usb1/1-2/1-2:1.0/host24/target24:0:0/24:0:0:0/block/sdb, offset=0 ao=0 and number=0 for /dev/sdb'
util_run_program: '/lib/udev/udisks-part-id' (stderr) 'Entering MS-DOS parser (offset=0, size=1000204886016)'
util_run_program: '/lib/udev/udisks-part-id' (stderr) 'MSDOS_MAGIC found'
util_run_program: '/lib/udev/udisks-part-id' (stderr) 'looking at part 0 (offset 32256, size 1000202241024, type 0x83)'
util_run_program: '/lib/udev/udisks-part-id' (stderr) 'new part entry'
util_run_program: '/lib/udev/udisks-part-id' (stderr) 'looking at part 1 (offset 0, size 0, type 0x00)'
util_run_program: '/lib/udev/udisks-part-id' (stderr) 'new part entry'
util_run_program: '/lib/udev/udisks-part-id' (stdout) 'UDISKS_PARTITION_TABLE=1'
util_run_program: '/lib/udev/udisks-part-id' (stdout) 'UDISKS_PARTITION_TABLE_SCHEME=mbr'
util_run_program: '/lib/udev/udisks-part-id' (stderr) 'looking at part 2 (offset 0, size 0, type 0x00)'
util_run_program: '/lib/udev/udisks-part-id' (stderr) 'new part entry'
util_run_program: '/lib/udev/udisks-part-id' (stderr) 'looking at part 3 (offset 0, size 0, type 0x00)'
util_run_program: '/lib/udev/udisks-part-id' (stderr) 'new part entry'
util_run_program: '/lib/udev/udisks-part-id' (stderr) 'Exiting MS-DOS parser'
util_run_program: '/lib/udev/udisks-part-id' (stderr) 'MSDOS partition table detected'
util_run_program: '/lib/udev/udisks-part-id' (stdout) 'UDISKS_PARTITION_TABLE_COUNT=1'
util_run_program: 'udisks-part-id /dev/sdb' returned with exitcode 0
udev_rules_apply_to_event: IMPORT 'udisks-probe-ata-smart /dev/sdb' /lib/udev/rules.d/80-udisks.rules:120
util_run_program: 'udisks-probe-ata-smart /dev/sdb' started
util_run_program: '/lib/udev/udisks-probe-ata-smart' (stderr) 'libudev: udev_device_new_from_syspath: device 0x11bd790 has devpath '/devices/pci0000:00/0000:00:1a.7/usb1/1-2/1-2:1.0/host24/target24:0:0/24:0:0:0/block/sdb''
util_run_program: '/lib/udev/udisks-probe-ata-smart' (stderr) 'libudev: udev_device_read_db: '
util_run_program: '/lib/udev/udisks-probe-ata-smart' (stderr) 'device 0x11bd790 filled with db file data'
util_run_program: '/lib/udev/udisks-probe-ata-smart' (stderr) 'libudev: udev_device_new_from_syspath: device 0x11be030 has devpath '/devices/pci0000:00/0000:00:1a.7/usb1/1-2/1-2:1.0/host24/target24:0:0/24:0:0:0''
util_run_program: '/lib/udev/udisks-probe-ata-smart' (stderr) 'libudev: udev_device_new_from_syspath: device 0x11bee70 has devpath '/devices/pci0000:00/0000:00:1a.7/usb1/1-2/1-2:1.0/host24/target24:0:0''
util_run_program: '/lib/udev/udisks-probe-ata-smart' (stderr) 'libudev: udev_device_new_from_syspath: device 0x11bf1b0 has devpath '/devices/pci0000:00/0000:00:1a.7/usb1/1-2/1-2:1.0/host24''
util_run_program: '/lib/udev/udisks-probe-ata-smart' (stderr) 'libudev: udev_device_new_from_syspath: device 0x11bf4e0 has devpath '/devices/pci0000:00/0000:00:1a.7/usb1/1-2/1-2:1.0''
util_run_program: '/lib/udev/udisks-probe-ata-smart' (stderr) 'libudev: udev_device_new_from_syspath: device 0x11bf7f0 has devpath '/devices/pci0000:00/0000:00:1a.7/usb1/1-2''
util_run_program: '/lib/udev/udisks-probe-ata-smart' (stderr) 'Failed to determine if smart is available for /dev/sdb: Operation not supported'
util_run_program: 'udisks-probe-ata-smart /dev/sdb' returned with exitcode 1
udev_rules_apply_to_event: RUN '/lib/udev/hdparm' /lib/udev/rules.d/85-hdparm.rules:2
udev_rules_apply_to_event: RUN 'socket:@/org/freedesktop/hal/udev_event' /lib/udev/rules.d/90-hal.rules:2
udev_rules_apply_to_event: RUN '/sbin/modprobe -Qba dm-multipath' /lib/udev/rules.d/95-kpartx.rules:10
udev_event_execute_rules: no node name set, will use kernel supplied name 'sdb'
udev_device_update_db: created db file for '/devices/pci0000:00/0000:00:1a.7/usb1/1-2/1-2:1.0/host24/target24:0:0/24:0:0:0/block/sdb' in '/dev/.udev/db/block:sdb'
udev_node_add: creating device node '/dev/sdb', devnum=8:16, mode=0660, uid=0, gid=6
udev_node_mknod: preserve file '/dev/sdb', because it has correct dev_t
node_symlink: preserve already existing symlink '/dev/block/8:16' to '../sdb'
link_find_prioritized: found '/sys/devices/pci0000:00/0000:00:1a.7/usb1/1-2/1-2:1.0/host24/target24:0:0/24:0:0:0/block/sdb' claiming '/dev/.udev/links/disk\x2fby-id\x2fusb-BUFFALO_External_HDD_0000010155FF-0:0'
link_update: creating link '/dev/disk/by-id/usb-BUFFALO_External_HDD_0000010155FF-0:0' to '/dev/sdb'
node_symlink: preserve already existing symlink '/dev/disk/by-id/usb-BUFFALO_External_HDD_0000010155FF-0:0' to '../../sdb'
link_find_prioritized: found '/sys/devices/pci0000:00/0000:00:1a.7/usb1/1-2/1-2:1.0/host24/target24:0:0/24:0:0:0/block/sdb' claiming '/dev/.udev/links/disk\x2fby-path\x2fpci-0000:00:1a.7-usb-0:2:1.0-scsi-0:0:0:0'
link_update: creating link '/dev/disk/by-path/pci-0000:00:1a.7-usb-0:2:1.0-scsi-0:0:0:0' to '/dev/sdb'
node_symlink: preserve already existing symlink '/dev/disk/by-path/pci-0000:00:1a.7-usb-0:2:1.0-scsi-0:0:0:0' to '../../sdb'
udevadm_test: UDEV_LOG=6
udevadm_test: DEVPATH=/devices/pci0000:00/0000:00:1a.7/usb1/1-2/1-2:1.0/host24/target24:0:0/24:0:0:0/block/sdb
udevadm_test: MAJOR=8
udevadm_test: MINOR=16
udevadm_test: DEVNAME=/dev/sdb
udevadm_test: DEVTYPE=disk
udevadm_test: ACTION=add
udevadm_test: SUBSYSTEM=block
udevadm_test: DEVLINKS=/dev/block/8:16 /dev/disk/by-id/usb-BUFFALO_External_HDD_0000010155FF-0:0 /dev/disk/by-path/pci-0000:00:1a.7-usb-0:2:1.0-scsi-0:0:0:0
udevadm_test: ID_VENDOR=BUFFALO
udevadm_test: ID_VENDOR_ENC=BUFFALO\x20
udevadm_test: ID_VENDOR_ID=0411
udevadm_test: ID_MODEL=External_HDD
udevadm_test: ID_MODEL_ENC=External\x20HDD\x20\x20\x20\x20
udevadm_test: ID_MODEL_ID=0184
udevadm_test: ID_REVISION=0100
udevadm_test: ID_SERIAL=BUFFALO_External_HDD_0000010155FF-0:0
udevadm_test: ID_SERIAL_SHORT=0000010155FF
udevadm_test: ID_TYPE=disk
udevadm_test: ID_INSTANCE=0:0
udevadm_test: ID_BUS=usb
udevadm_test: ID_USB_INTERFACES=:080650:
udevadm_test: ID_USB_INTERFACE_NUM=00
udevadm_test: ID_USB_DRIVER=usb-storage
udevadm_test: ID_PATH=pci-0000:00:1a.7-usb-0:2:1.0-scsi-0:0:0:0
udevadm_test: ID_PART_TABLE_TYPE=dos
udevadm_test: UDISKS_PRESENTATION_NOPOLICY=0
udevadm_test: UDISKS_PARTITION_TABLE=1
udevadm_test: UDISKS_PARTITION_TABLE_SCHEME=mbr
udevadm_test: UDISKS_PARTITION_TABLE_COUNT=1
udevadm_test: run: '/lib/udev/hdparm'
udevadm_test: run: 'socket:@/org/freedesktop/hal/udev_event'
udevadm_test: run: '/sbin/modprobe -Qba dm-multipath'
This program is for debugging only, it does not run any program,
specified by a RUN key. It may show incorrect results, because
some values may be different, or not available at a simulation run.

That means it does not show up, or it disappears after something is trying to do something with it. If it does not appear at all, we don't need to look in userspace, I guess. :)

What are your rules trying to do with hdparm on the drive, that seems rather odd to apply to a USB device:
RUN '/lib/udev/hdparm' /lib/udev/rules.d/85-hdparm.rules:2

Kay

I assume it is there for a very brief moment but then disappears.

Why would you think so? From the hdparm man page:

"Many newer (2008 and later) USB drive enclosures now also support "SAT" (SCSI-ATA Command Translation) and therefore may also work with hdparm."

-Jonas

Actually, you hit the nail on the head Kay. I moved the hdparm rule out of the way and voilà, the drive mounts. I then manually ran hdparm on the device:

sudo hdparm --verbose /dev/sdb

/dev/sdb:

outgoing cdb:  85 08 2e 00 00 00 00 00 00 00 00 00 00 40 ec 00
SG_IO: ATA_16 status=0x0, host_status=0x7, driver_status=0x0
SG_IO: bad response (not CHECK_CONDITION)
outgoing cdb:  85 08 2e 00 00 00 00 00 00 00 00 00 00 40 a1 00
SG_IO: ATA_16 status=0x0, host_status=0x7, driver_status=0x0
SG_IO: bad response (not CHECK_CONDITION)
 HDIO_DRIVE_CMD(identify) failed: Invalid exchange
 readonly      =  0 (off)
 readahead     = 256 (on)
 geometry      = 36365/64/32, sectors = 0, start = 0

Does the command sent by hdparm look familiar? Exactly, it is the third ATA command (IDENTIFY DEVICE) we discovered earlier and caused the drive to stall.

Does anyone know why the drive would not be able to cope with this command? And also, why does it not choke on it in USB 2.0 mode but only in USB 3.0?

-Jonas

That's nice to know. Other people have been reporting similar problems. Now we can tell where they come from.

No idea. Except that it's probably not the drive's fault, but rather the fault of the USB-(S)ATA chip that controls the drive.

That's easy: It chokes in USB-2.0 mode also. But the ehci-hcd driver is able to reset the drive and recover, whereas xhci-hcd has not yet implemented reset. Hence no recovery is possible.

Alan Stern

Yes ... I think we're starting to need to get a handle on all these userspace random pokes which can disrupt (the admittedly badly written and badly tested) devices which the kernel tries so hard not to upset.

Best guess (and it's a guess only) would be that the USB bridge SAT layer doesn't implement ATA_16 and so fails in interesting ways when it comes in. Does the ATA_12 version of IDENTIFY DEVICE succeed?

James

It does. And in between the two is an ATA_16 SET FEATURES command which also (apparently) succeeds. That is, there is no error indication from the device -- but goodness knows if it actually carries out the command.

Alan Stern

Incidentally, there's a discussion of this problem with input from an engineer at the company that makes the bridge chip here:

https://bugs.launchpad.net/ubuntu/+source/linux-fsl-imx51/+bug/431963

See comment #25 and later. He claims that the ATA pass-through command contains a SECTOR COUNT field of 0 even though it asks for 512 bytes of IDENTIFY data. This invalid parameter combination causes the bridge chip to get confused, and instead of failing gracefully, it messes up the USB protocol.

Does anybody know where to find out why hdparm is sending an IDENTIFY command with invalid parameters?

Alan Stern

Hello.

IDENTIFY DEVICE command always returns 512 bytes of data, regardless
of any value in the sector count register.

IDENTIFY DEVICE command has *no* parameters.

WBR, Sergei

Alan was talking about ATA_16, which has to contain payload data in SCSI format for the encapsulation to work, so for a command that returns 512b the ATA_16 has to contain this as the data length.

Sounds like a Mark Lord problem to me ... cc added.

James

..

..

Errr.. yes and no.

Yes, because nobody else is likely to do anything about it, so I will work around the hardware bug by updating hdparm.

But no, there's no funky missing data length issue there. Just a bridge chip that doesn't understand ATA_16 commands.

Apparently it *does* understand ATA_12 commands, though, so perhaps hdparm will simply use ATA_12 for IDENTIFY from now on.

Cheers

Thanks, and welcome to my world ... the wierd antics of USB devices, plus the way they throw their toys out of the pram the moment you don't address them correctly is one of the banes of the SCSI subsystem. In general, the advice is to use the simplest possible command to achieve what you want so ATA_12 rather than ATA_16 is one of those (because most USB devices being below 2TB don't need to support 16 byte CDBs for anything else, so it's obviously something they'd forget to implement or test in their bridge chips ...). One of the consolations is that we're only on the edge ... people in the USB subsystem seem to have a much worse time of it.

You can extrapolate from this that I'm so looking forward to UAS ...

James

Did you look at this comment and the following one:

https://bugs.launchpad.net/ubuntu/+source/linux-fsl-imx51/+bug/431963#25

Is the engineer from Genesys Logic totally off-base?

Alan Stern

..

Yes. As discussed already, there is *no* sector count parameter for the (S)ATA "IDENTIFY" command. Other USB/SATA bridges handle this correctly in SAT mode, just not this specific model.

No big deal, we'll work around it.
It's low priority for me, though.

I do have a pre-release HDPARM that uses ATA_12 for IDENTIFY, as this is reported to work on this hardware, even though it is otherwise _identical_ to the command issue via ATA_16. That's another indication of a buggy/inconsistent bridge chip.

And I've also added a sector count of "1" to hdparm's IDENTIFY commands. Properly implemented hardware/software will just ignore it as usual, but this bridge might benefit from it.

Anyone want to give this second update a try?

Thanks

Sure.

-Jonas

Confirming that, what is put in the ATA_16 sector count field is what the ATA command (IDENTIFY DEVICE) expects in its count field. And according to ACS-2 (rev 2) for IDENTIFY DEVICE that is "N/A" which I would interpret as zero.

Mark Lord is the author of hdparm and I have added him to the cc list.

Using SAT that IDENTIFY DEVICE response can be obtained in one of three ways:
- the SCSI ATA PASS-THROUGH(12) command
- the SCSI ATA PASS-THROUGH(16) command
- SCSI ATA Information VPD page (89h)

The latter can be fetched via a SCSI INQUIRY command. Now vendors can screw up on any or all of the above ways. I would like to suggest to Mark to have some way of using the VPD page technique with hdparm.

The idea of SAT is to use the SCSI equivalent command and then, as a last resort, use the ATA PASS-THROUGH commands. A really good SAT implementation might block the pass-through commands (they are optional).

Doug Gilbert

Ouch. Reviewing that "N/A" in the ATA spec: it means that neither the host nor device should check that field. So it could be any value, in this case 1.

At the SCSI ATA pass-through commands need sector_count to calculate the data transfer length (sat2r09.pdf tables 109, 111 and 112) as James said.

Clear as mud, better check my code ...

Doug Gilbert

..

I'll update hdparm (version 9.29) to supply a sector count of "1" for IDENTIFY commands, just to satisfy the buggy bridge chip.

Cheers

Mark Lord
Real-Time Remedies Inc.
[email protected]

Let me know whet is in the repository and I'll give it a try.

-Jonas

..

Here's the pre-release, attached to this email.
Please do give it a try and report back.

Thanks

Mark Lord
Real-Time Remedies Inc.
[email protected]

Doesn't seem to fix it. Here's the output:

sudo ./hdparm --verbose /dev/sdb

/dev/sdb:

outgoing cdb:  85 08 2e 00 00 00 01 00 00 00 00 00 00 40 ec 00
data:  00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
SG_IO: ATA_16 status=0x0, host_status=0x0, driver_status=0x0
SG_IO: bad response (not CHECK_CONDITION)
Trying legacy HDIO_DRIVE_CMD
outgoing cdb:  85 08 2e 00 00 00 01 00 00 00 00 00 00 40 a1 00
data:  40 00 ff 3f 37 c8 10 00 00 00 00 00 3f 00 00 00
SG_IO: ATA_16 status=0x2, host_status=0x0, driver_status=0x8
SG_IO: sb[]:  72 0b 00 00 00 00 00 0e 09 0c 00 04 00 01 00 00 00 00 00 

00 40 51 00 00 00 00 00 00 00 00 00 00
SG_IO: desc[]: 09 0c 00 04 00 01 00 00 00 00 00 00
ATA_16 statQ err nsect
lbal lbam lbah dev@
I/O error, ata_op=0xa1 ata_status=0x51 ata_error=0x04
HDIO_DRIVE_CMD(identify) failed: Input/output error

  readonly      =  0 (off)
  readahead     = 256 (on)
  geometry      = 121601/255/63, sectors = 1953525168, start = 0

-Jonas

Can you acquire a usbmon trace showing what happens when you run this? Instructions are in the kernel source file Documentation/usb/usbmon.txt.

Alan Stern

Here you go:

ffff8802123996c0 4253708718 S Bo:10:002:2 -115 31 = 55534243 9c000000 00020000 80001085 082e0000 00010000 00000000 40ec00 ffff8802123996c0 4253708828 C Bo:10:002:2 0 31 > ffff8801f36c6a80 4253708841 S Bi:10:002:1 -115 512 < ffff8801f36c6a80 4253714580 C Bi:10:002:1 0 512 Z ffff8802123996c0 4253714599 S Bi:10:002:1 -115 13 < ffff8802123996c0 4253714639 C Bi:10:002:1 0 13 = 55534253 9c000000 00000000 00
ffff8802123996c0 4253714778 S Bo:10:002:2 -115 31 = 55534243 9d000000 00020000 80001085 082e0000 00010000 00000000 40a100 ffff8802123996c0 4253714813 C Bo:10:002:2 0 31 > ffff8801f36c6a80 4253714823 S Bi:10:002:1 -115 512 < ffff8801f36c6a80 4253715081 C Bi:10:002:1 -32 0 ffff8802123996c0 4253715119 S Co:10:002:0 s 02 01 0000 0081 0000 0 ffff8802123996c0 4253715383 C Co:10:002:0 0 0 ffff8802123996c0 4253715406 S Bi:10:002:1 -115 13 < ffff8802123996c0 4253715648 C Bi:10:002:1 0 13 = 55534253 9d000000 00020000 01
ffff8802123996c0 4253715661 S Bo:10:002:2 -115 31 = 55534243 9e000000 60000000 80000603 00000060 00000000 00000000 000000 ffff8802123996c0 4253715707 C Bo:10:002:2 0 31 > ffff8801f36c6a80 4253715723 S Bi:10:002:1 -115 96 < ffff8801f36c6a80 4253715763 C Bi:10:002:1 0 96 Z ffff8802123996c0 4253715779 S Bi:10:002:1 -115 13 < ffff8802123996c0 4253715819 C Bi:10:002:1 0 13 = 55534253 9e000000 00000000 00
ffff8802123996c0 4253717330 S Bo:10:002:2 -115 31 = 55534243 9f000000 00100000 80000a28 00000000 00000008 00000000 000000 ffff8802123996c0 4253717373 C Bo:10:002:2 0 31 > ffff880211ace240 4253717386 S Bi:10:002:1 -115 4096 < ffff880211ace240 4253731794 C Bi:10:002:1 0 4096 Z ffff8802123996c0 4253731815 S Bi:10:002:1 -115 13 < ffff8802123996c0 4253731854 C Bi:10:002:1 0 13 = 55534253 9f000000 00000000 00

-Jonas

That's the first command.

And it apparently succeeded. It's not clear why hdparm reports "bad response". Maybe it just doesn't like the data returned by the device.

That's the second command, now presumably specifying a sector count of 1.

It failed. But unlike your earlier experience, it didn't get a transport error. A failure is more benign than an error; in particular it doesn't call for a reset.

Here usb-storage asked the reason for the failure. Unfortunately we can't see the response. Did you run this on a computer with more than 1 GB of memory? If you did, can you boot with "mem�0M" and try again?

This is a standard READ(10) command, asking for the first 8 sectors on the disk. It succeeded.

Alan Stern

I'll have a look at this stuff next week, after the Easter holiday.

Cheers

Mark Lord
Real-Time Remedies Inc.
[email protected]

Here is the trace after limiting memory to 900M:

ffff88001fc82780 3529669229 S Bo:10:002:2 -115 31 = 55534243 ca000000 00020000 80001085 082e0000 00000000 00000000 40ec00 ffff88001fc82780 3529669272 C Bo:10:002:2 0 31 > ffff880009312840 3529669349 S Bi:10:002:1 -115 512 < ffff880009312840 3529669382 C Bi:10:002:1 -32 0 ffff88001fc82780 3529669400 S Co:10:002:0 s 02 01 0000 0081 0000 0 ffff88001fc82780 3529669680 C Co:10:002:0 0 0 ffff88001fc82780 3529669701 S Bi:10:002:1 -115 13 < ffff88001fc82780 3529669959 C Bi:10:002:1 0 13 = 55534253 ca000000 00020000 02
ffff880009312840 3529669979 S Co:10:001:0 s 23 01 0001 0002 0000 0 ffff880009312840 3529669982 C Co:10:001:0 -32 0 ffff880009312840 3529669991 S Co:10:001:0 s 23 01 0001 0002 0000 0 ffff880009312840 3529669994 C Co:10:001:0 -32 0 ffff880009312840 3529670000 S Co:10:001:0 s 23 01 0001 0002 0000 0 ffff880009312840 3529670002 C Co:10:001:0 -32 0 ffff880009312840 3529670007 S Co:10:001:0 s 23 01 0001 0002 0000 0 ffff880009312840 3529670010 C Co:10:001:0 -32 0 ffff880009312840 3529670015 S Co:10:001:0 s 23 01 0001 0002 0000 0 ffff880009312840 3529670017 C Co:10:001:0 -32 0 ffff88001c6780c0 3529670069 S Ci:10:001:0 s a3 00 0000 0002 0004 4 < ffff88001c6780c0 3529670079 C Ci:10:001:0 0 4 = 03090000 ffff88001c678d80 3530198291 S Co:10:001:0 s 23 01 0001 0002 0000 0 ffff88001c678d80 3530198297 C Co:10:001:0 -32 0 ffff88001c678d80 3530618318 S Co:10:001:0 s 23 01 0001 0002 0000 0 ffff88001c678d80 3530618323 C Co:10:001:0 -32 0 ffff88001c678d80 3531038299 S Co:10:001:0 s 23 01 0001 0002 0000 0 ffff88001c678d80 3531038305 C Co:10:001:0 -32 0 ffff88001c678d80 3531458316 S Co:10:001:0 s 23 01 0001 0002 0000 0 ffff88001c678d80 3531458322 C Co:10:001:0 -32 0 ffff88001c678d80 3531458339 S Co:10:001:0 s 23 01 0001 0002 0000 0 ffff88001c678d80 3531458342 C Co:10:001:0 -32 0 ffff8800240da900 3534018309 C Ii:10:001:1 -2:8 0 ffff8800093d9840 3534018323 S Ci:10:001:0 s a3 00 0000 0001 0004 4 < ffff8800093d9840 3534018328 C Ci:10:001:0 0 4 = 00010000 ffff8800093d9840 3534018331 S Ci:10:001:0 s a3 00 0000 0002 0004 4 < ffff8800093d9840 3534018334 C Ci:10:001:0 0 4 = 03090000 ffff8800093d9840 3534018335 S Co:10:001:0 s 23 01 0001 0002 0000 0 ffff8800093d9840 3534018338 C Co:10:001:0 -32 0 ffff8800093d9840 3534018339 S Ci:10:001:0 s a3 00 0000 0003 0004 4 < ffff8800093d9840 3534018342 C Ci:10:001:0 0 4 = 00010000 ffff8800093d9840 3534018343 S Ci:10:001:0 s a3 00 0000 0004 0004 4 < ffff8800093d9840 3534018346 C Ci:10:001:0 0 4 = 00010000 ffff8800240da900 3534018347 S Ii:10:001:1 -115:8 4 < ffff88001c678d80 3534018358 S Ci:10:001:0 s a3 00 0000 0002 0004 4 < ffff88001c678d80 3534018362 C Ci:10:001:0 0 4 = 03090000 ffff8800093d9840 3534438322 S Co:10:001:0 s 23 01 0001 0002 0000 0 ffff8800093d9840 3534438329 C Co:10:001:0 -32 0 ffff8800093d9840 3534858284 S Co:10:001:0 s 23 01 0001 0002 0000 0 ffff8800093d9840 3534858289 C Co:10:001:0 -32 0 ffff8800093d9840 3535278319 S Co:10:001:0 s 23 01 0001 0002 0000 0 ffff8800093d9840 3535278325 C Co:10:001:0 -32 0 ffff8800093d9840 3535698317 S Co:10:001:0 s 23 01 0001 0002 0000 0 ffff8800093d9840 3535698324 C Co:10:001:0 -32 0 ffff8800093d9840 3535698345 S Co:10:001:0 s 23 01 0001 0002 0000 0 ffff8800093d9840 3535698348 C Co:10:001:0 -32 0 ffff8800240da900 3538138309 C Ii:10:001:1 -2:8 0 ffff8800093d9840 3538138316 S Ci:10:001:0 s a3 00 0000 0001 0004 4 < ffff8800093d9840 3538138320 C Ci:10:001:0 0 4 = 00010000 ffff8800093d9840 3538138322 S Ci:10:001:0 s a3 00 0000 0002 0004 4 < ffff8800093d9840 3538138327 C Ci:10:001:0 0 4 = 03090000 ffff8800093d9840 3538138328 S Co:10:001:0 s 23 01 0001 0002 0000 0 ffff8800093d9840 3538138331 C Co:10:001:0 -32 0 ffff8800093d9840 3538138332 S Ci:10:001:0 s a3 00 0000 0003 0004 4 < ffff8800093d9840 3538138335 C Ci:10:001:0 0 4 = 00010000 ffff8800093d9840 3538138336 S Ci:10:001:0 s a3 00 0000 0004 0004 4 < ffff8800093d9840 3538138338 C Ci:10:001:0 0 4 = 00010000 ffff8800240da900 3538138339 S Ii:10:001:1 -115:8 4 < ffff8800093d9840 3538138347 S Ci:10:001:0 s a3 00 0000 0002 0004 4 < ffff8800093d9840 3538138349 C Ci:10:001:0 0 4 = 03090000 ffff8800093d9840 3538558292 S Co:10:001:0 s 23 01 0001 0002 0000 0 ffff8800093d9840 3538558298 C Co:10:001:0 -32 0 ffff8800093d9840 3538978287 S Co:10:001:0 s 23 01 0001 0002 0000 0 ffff8800093d9840 3538978293 C Co:10:001:0 -32 0 ffff8800093d9840 3539398284 S Co:10:001:0 s 23 01 0001 0002 0000 0 ffff8800093d9840 3539398291 C Co:10:001:0 -32 0 ffff8800093d9840 3539818282 S Co:10:001:0 s 23 01 0001 0002 0000 0 ffff8800093d9840 3539818288 C Co:10:001:0 -32 0 ffff8800093d9840 3539818308 S Co:10:001:0 s 23 01 0001 0002 0000 0 ffff8800093d9840 3539818311 C Co:10:001:0 -32 0 ffff8800240da900 3542138321 C Ii:10:001:1 -2:8 0 ffff8800093d9840 3542138328 S Ci:10:001:0 s a3 00 0000 0001 0004 4 < ffff8800093d9840 3542138332 C Ci:10:001:0 0 4 = 00010000 ffff8800093d9840 3542138334 S Ci:10:001:0 s a3 00 0000 0002 0004 4 < ffff8800093d9840 3542138337 C Ci:10:001:0 0 4 = 03090000 ffff8800093d9840 3542138339 S Co:10:001:0 s 23 01 0001 0002 0000 0 ffff8800093d9840 3542138342 C Co:10:001:0 -32 0 ffff8800093d9840 3542138345 S Ci:10:001:0 s a3 00 0000 0003 0004 4 < ffff8800093d9840 3542138348 C Ci:10:001:0 0 4 = 00010000 ffff8800093d9840 3542138349 S Ci:10:001:0 s a3 00 0000 0004 0004 4 < ffff8800093d9840 3542138352 C Ci:10:001:0 0 4 = 00010000 ffff8800240da900 3542138353 S Ii:10:001:1 -115:8 4 < ffff8800093d9840 3542138363 S Ci:10:001:0 s a3 00 0000 0002 0004 4 < ffff8800093d9840 3542138366 C Ci:10:001:0 0 4 = 03090000 ffff8800093d9840 3542558309 S Co:10:001:0 s 23 01 0001 0002 0000 0 ffff8800093d9840 3542558316 C Co:10:001:0 -32 0 ffff8800093d9840 3542978288 S Co:10:001:0 s 23 01 0001 0002 0000 0 ffff8800093d9840 3542978294 C Co:10:001:0 -32 0

-Jonas

This trace was made using the original version of hdparm, not the updated version.

Alan Stern

Argh, I'll send you the correct trace in a bit.

Here is the trace with Mark's fix:

ffff88003772c0c0 1008628966 S Bo:10:002:2 -115 31 = 55534243 95000000 00020000 80001085 082e0000 00010000 00000000 40ec00 ffff88003772c0c0 1008629074 C Bo:10:002:2 0 31 > ffff880035b1d600 1008629094 S Bi:10:002:1 -115 512 < ffff880035b1d600 1008634784 C Bi:10:002:1 0 512 Z ffff88003772c0c0 1008634827 S Bi:10:002:1 -115 13 < ffff88003772c0c0 1008634861 C Bi:10:002:1 0 13 = 55534253 95000000 00000000 00
ffff88003772c0c0 1008635021 S Bo:10:002:2 -115 31 = 55534243 96000000 00020000 80001085 082e0000 00010000 00000000 40a100 ffff88003772c0c0 1008635050 C Bo:10:002:2 0 31 > ffff880035b1d600 1008635058 S Bi:10:002:1 -115 512 < ffff880035b1d600 1008635305 C Bi:10:002:1 -32 0 ffff88003772c0c0 1008635375 S Co:10:002:0 s 02 01 0000 0081 0000 0 ffff88003772c0c0 1008635645 C Co:10:002:0 0 0 ffff88003772c0c0 1008635665 S Bi:10:002:1 -115 13 < ffff88003772c0c0 1008635910 C Bi:10:002:1 0 13 = 55534253 96000000 00020000 01
ffff88003772c0c0 1008635925 S Bo:10:002:2 -115 31 = 55534243 97000000 60000000 80000603 00000060 00000000 00000000 000000 ffff88003772c0c0 1008636017 C Bo:10:002:2 0 31 > ffff880035b1d600 1008636032 S Bi:10:002:1 -115 96 < ffff880035b1d600 1008636123 C Bi:10:002:1 0 96 Z ffff88003772c0c0 1008636137 S Bi:10:002:1 -115 13 < ffff88003772c0c0 1008636207 C Bi:10:002:1 0 13 = 55534253 97000000 00000000 00
ffff88003772c0c0 1008638008 S Bo:10:002:2 -115 31 = 55534243 98000000 00100000 80000a28 00000000 00000008 00000000 000000 ffff88003772c0c0 1008638101 C Bo:10:002:2 0 31 > ffff880008c53b40 1008638179 S Bi:10:002:1 -115 4096 < ffff880008c53b40 1008648547 C Bi:10:002:1 0 4096 Z ffff88003772c0c0 1008648627 S Bi:10:002:1 -115 13 < ffff88003772c0c0 1008648715 C Bi:10:002:1 0 13 = 55534253 98000000 00000000 00

-Jonas

This is not what I expected. What version of the kernel are you using? Those 'Z' entries should not be possible in 2.6.33 or later.

Alan Stern

I'm not using a 2.6.33 kernel. I'm using 2.6.32 (which is going to be the mainline version for Ubuntu 10.04 LTS, which is being released at the end of April).

-Jonas

Hey guys,

We are seeing the same issue with firewire & some USB 2.0 drives as
well. We are trying to figure out a good work around or fix. Tracking here:
https://bugs.launchpad.net/oem-priority/+bug/515023
and
https://bugs.launchpad.net/oem-priority/+bug/548513

Thanks,
Jerone

In that case, can you repeat the test using an EHCI controller instead of xHCI?

Alan Stern

ffff8800345dbb40 2336453775 S Bo:1:004:2 -115 31 = 55534243 95000000 00020000 80001085 082e0000 00010000 00000000 40ec00 ffff8800345dbb40 2336453948 C Bo:1:004:2 0 31 > ffff880035f30f00 2336453969 S Bi:1:004:1 -115 512 < ffff880035f30f00 2336459710 C Bi:1:004:1 0 512 = 4000ff3f 37c81000 00000000 3f000000 00000000 32534d35 394a5a30 30313237 ffff8800345dbb40 2336459731 S Bi:1:004:1 -115 13 < ffff8800345dbb40 2336459822 C Bi:1:004:1 0 13 = 55534253 95000000 00000000 00
ffff8800345dbb40 2336460054 S Bo:1:004:2 -115 31 = 55534243 96000000 00020000 80001085 082e0000 00010000 00000000 40a100 ffff8800345dbb40 2336460204 C Bo:1:004:2 0 31 > ffff880035f30f00 2336460222 S Bi:1:004:1 -115 512 < ffff880035f30f00 2336460472 C Bi:1:004:1 -32 0 ffff8800345dbb40 2336460492 S Co:1:004:0 s 02 01 0000 0081 0000 0 ffff8800345dbb40 2336460579 C Co:1:004:0 0 0 ffff8800345dbb40 2336460596 S Bi:1:004:1 -115 13 < ffff8800345dbb40 2336460711 C Bi:1:004:1 0 13 = 55534253 96000000 00020000 01
ffff8800345dbb40 2336460729 S Bo:1:004:2 -115 31 = 55534243 97000000 60000000 80000603 00000060 00000000 00000000 000000 ffff8800345dbb40 2336460823 C Bo:1:004:2 0 31 > ffff880035f30f00 2336460841 S Bi:1:004:1 -115 96 < ffff880035f30f00 2336460952 C Bi:1:004:1 0 96 = 720b0000 0000000e 090c0004 00010000 00000000 40510000 00000000 00000000 ffff8800345dbb40 2336460970 S Bi:1:004:1 -115 13 < ffff8800345dbb40 2336461086 C Bi:1:004:1 0 13 = 55534253 97000000 00000000 00
ffff8800345dbb40 2336462673 S Bo:1:004:2 -115 31 = 55534243 98000000 00100000 80000a28 00000000 00000008 00000000 000000 ffff8800345dbb40 2336462826 C Bo:1:004:2 0 31 > ffff880035f30f00 2336462844 S Bi:1:004:1 -115 4096 < ffff880035f30f00 2336474954 C Bi:1:004:1 0 4096 = fab80010 8ed0bc00 b0b80000 8ed88ec0 fbbe007c bf0006b9 0002f3a4 ea210600 ffff8800345dbb40 2336474975 S Bi:1:004:1 -115 13 < ffff8800345dbb40 2336475078 C Bi:1:004:1 0 13 = 55534253 98000000 00000000 00

Here you go.

-Jonas

Here's the sense information for the failed ATA-16 passthrough command. I can't interpret it; maybe someone else can.

Alan Stern

Descriptor sense format, sense_key«ORTED_COMMAND with no additional sense code (0x0,0x0).

It has also added an ATA Return descriptor which purports to be the ATA registers after the command is processed. That starts at the 0x09 byte. See sat2r09.pdf table 114 to decode that. Since it is an aborted command I would not take that too seriously.

It is incorrect to have an ATA Return descriptor with asc,ascq=0x0,0x0 .

Doug Gilbert

Someone should probably tell Neil Perng at Genesys Logic. Maybe Dinh Nguyen (from the launchpad entry) can provide an email address or forward this thread on?

Sarah Sharp

Why are we sure that my drive has a chip by Genesys Logic in it at all?
I know that there are disks out there with that chip and that there
are issues with it, but how did we conclude that the Buffalo drive has the same chip in it? Is there a way for me to verify what chip is used without opening the case?

-Jonas

Now that you mention it, we don't know what sort of chip you have. Only that the vendor ID is 0x0411 (MelCo., Inc.) and the product ID is 0x0184.

I don't know of any way to find out what sort of chip it is without opening the case (except perhaps by asking the manufacturer).

Alan Stern

I've just opened the case on my Buffalo hard drive, and the circuit just says Buffalo. There's an ARM chip and a winbond chip, but not much else to identify it. I'll ask around the USB-IF PIL lab to try and get a company contact.

Sarah Sharp

p.s. The Buffalo USB3 drive was much easier to open than the Dane-Elec drive (and the hard drive and board was actually secured, unlike the other drive). There's a screw on the top, and if you pry off the stickers on the bottom, there's some plastic clips holding the case together.

Buffalo is part of the MelCo Inc. holding.

The ARM chip in the Buffalo USB3 drive is the USB3-SATA bridge MB86C30A by Fujitsu:
http://www.fujitsu.com/downloads/EDG/binary/pdf/catalogs/a04000431e.pdf

My guess would be that any drive using this chip will choke on the identify command. Sarah, any chance you could get a contact at Fujitsu?

-Jonas

I'll see if I can find a contact for this. I need a couple more details so they can reproduce this. Jonas, did you ever test the Buffalo drive with Mark Lord's fix to set the sector count to "1"? Which version of hdparm were you using? Is that version just in Lucid, or is it in Karmic too?

In the meantime, can everyone confirm my summary of the behavior of the Buffalo device (not the Genesys chip)?

There seems to be an issue with how the Buffalo USB3 hard drive handles the SCSI ATA pass through commands. We found this issue when the Linux userspace program hdparm, using the Ubuntu Linux distribution. The device responds correctly to an IDENTIFY DEVICE via the ATA_12 tunnel, but it stalls when it's sent an IDENTIFY DEVICE via the ATA_16 tunnel. The command before the ATA_16 IDENTIFY DEVICE was a SET FEATURES via the ATA_16 tunnel, and it was responded to properly, so we think it should support the ATA_16 commands.

This problem makes the device unusable under the Linux 2.6.31 and 2.6.32 kernels, as they don't support configured device reset after an endpoint stall. The device works on later kernels (2.6.33 and 2.6.34) with that support.

Details
-------

The hdparm program issues the following commands, and gets the following responses:

command contents: a1 08 2e 00 01 00 00 00 00 ec 00 00 Bulk Command S 0x43425355 T 0x2d L 512 F 128 Trg 0 LUN 0 CL 12 Bulk Status S 0x53425355 T 0x2d R 0 Stat 0x0
scsi cmd done, result=0x0
(This is an IDENTIFY DEVICE via the ATA_12 tunnel)

command contents: 85 06 20 00 05 00 fe 00 00 00 00 00 00 40 ef 00 Bulk Command S 0x43425355 T 0x2e L 0 F 0 Trg 0 LUN 0 CL 16 Bulk Command S 0x43425355 T 0x2f L 512 F 128 Trg 0 LUN 0 CL 16 Bulk Status S 0x53425355 T 0x2e R 0 Stat 0x0
scsi cmd done, result=0x0
(This is a SET FEATURES via the ATA_16 tunnel)

command contents: 85 08 2e 00 00 00 00 00 00 00 00 00 00 40 ec 00 Bulk Command S 0x43425355 T 0x2f L 512 F 128 Trg 0 LUN 0 CL 16 Bulk Status S 0x53425355 T 0x2f R 512 Stat 0x2
Status code -32; transferred 0/512
clearing endpoint halt for pipe 0xc0008280
Bulk status result = 0
Bulk Status S 0x53425355 T 0x2f R 512 Stat 0x2
-- transport indicates error, resetting
(This is an IDENTIFY DEVICE via the ATA_16 tunnel)

The full log is here:
http://minilop.net/~sarah/buffalo-hd-ata-16-issue.log

The drive stalls on the last command, which is a valid ATA command. Can you confirm if your device supports the SCSI ATA pass through specification?

http://www.t10.org/cgi-bin/ac.pl?t=f&f=sat2r09.pdf

Sarah Sharp

"Stalls" isn't the right word. It responds with "Phase Error" in bCSWStatus. Less precisely but more succinctly, it returns a Phase Error.

Only when running USB 3. The devices work okay with USB 2.

This "T 0x2f" line doesn't belong here (it appears below). Copy & Paste error?

And this "Bulk Status" line doesn't belong here. Again, it appears below.

It returns an error on the last command. (It also stalls, but that's okay -- stalling an endpoint during a command is normal and it should work fine with USB 3.)

That link doesn't work. The standard is not freely available.

Alan Stern

Updated bug description below.

Updated description
-------------------

Summary:

The Buffalo USB3 hard drive fails to mount after being sent an ATA_16 IDENTIFY command. It does not fail when the device is connected via a USB 2.0 cable and the same command is sent.

Details:

There seems to be an issue with how the Buffalo USB3 hard drive handles the SCSI ATA pass through commands. We found this issue with the Linux userspace program hdparm, using the Ubuntu Linux Karmic distribution. The device responds correctly to an IDENTIFY DEVICE via the ATA_12 tunnel, but it responds with a Phase Error when it's sent an IDENTIFY DEVICE via the ATA_16 tunnel, and then stalls.

The hdparm program thinks the Phase Error is an invalid response:

sudo hdparm --verbose /dev/sdb

/dev/sdb:

outgoing cdb:  85 08 2e 00 00 00 00 00 00 00 00 00 00 40 ec 00
SG_IO: ATA_16 status=0x0, host_status=0x7, driver_status=0x0
SG_IO: bad response (not CHECK_CONDITION)
outgoing cdb:  85 08 2e 00 00 00 00 00 00 00 00 00 00 40 a1 00
SG_IO: ATA_16 status=0x0, host_status=0x7, driver_status=0x0
SG_IO: bad response (not CHECK_CONDITION)
 HDIO_DRIVE_CMD(identify) failed: Invalid exchange
 readonly      =  0 (off)
 readahead     = 256 (on)
 geometry      = 36365/64/32, sectors = 0, start = 0

Stalling on the ATA_16 IDENTIFY device is fine, but the invalid response is not.

The hard drive does not seem to work after this command is sent, and cannot be mounted. If we inhibit udev from running hdparm (by stopping the udev daemon) then the drive can be mounted successfully.

If the drive is plugged in via a USB 2.0 cable, then the drive works correctly, even though it gets issued the same commands.

The command before the ATA_16 IDENTIFY DEVICE was a SET FEATURES via the ATA_16 tunnel, and it was responded to properly, so we think it should support the ATA_16 commands.

The full kernel log is here:
http://minilop.net/~sarah/buffalo-hd-ata-16-issue.log

The ATA_12 IDENTIFY command starts at line 8816. (It says the command is a BLANK command, but it's incorrectly identified that command.)

Sarah Sharp

..

I hsven't gone away or anything -- still reading mostly every word of this thread. I haven't done anything further here because I really don't understand the whole story. Sarah's latest summary (above) helps a lot, though.

But I'm not sure what, if anything I (hdparm) can do differently to help here.

Can anyone out there send me one of these gadgets?

Oh wait.. that wouldn't be terribly useful, I suppose, since I also don't have any newfangled USB3 host gear.

Suggestions?

Mark Lord
Real-Time Remedies Inc.
[email protected]

..

Okay, apparently the shop around the corner has some $25 USB3 interface boards for PCIe, and also some for ExpressCard on my notebooks.

Now I just need one of the buggy USB3/SATA bridges to test/debug with. I'm not willing to spend much of my own money on something known to be buggy though. Anyone out there got one they could loan?

Cheers

Mark Lord
Real-Time Remedies Inc.
[email protected]

I don't like this summary. The failure to mount is caused by a defect in the earlier versions of xhci-hcd (no support for USB port reset), not by a bug in the drive. I don't recall seeing a test using the old version of hdparm and an updated xhci-hcd, but presumably such a combination would work okay.

The real problem with the Buffalo drive is that it responds with a phase error when it receives an ATA_16 IDENTIFY DEVICE command with the Sector Count field set to 0.

You should not say anything about the drive stalling. For one thing, it's misleading: The drive doesn't stall but rather it sends a STALL token to indicate that the bulk-IN endpoint is halted. For another, the STALL is sent _before_ the phase error is reported, not after. Lastly, there's absolutely nothing wrong with halting the endpoint like this; in fact, the Bulk-Only Transport specification requires it under these circumstances.

Why include two separate commands here? I thought you were interested only in the response to the ATA_16 IDENTIFY DEVICE (the first outgoing cdb above).

Again, don't mention stalling. Notice that the information from hdparm does not show the exact nature of the problem (i.e., that the drive responded with a phase error), only that a problem occurred. This makes it less useful than you might like.

First, this is true only if the drive is attached using USB 3.0. Second, after this command the drive still works fine -- xhci-hcd is what doesn't work.

Right. That's because the larger problem is in xhci-hcd, not in the drive.

This is wrong. The first command shown above is ATA_16 IDENTIFY DEVICE. The second command is ATA_16 IDENTIFY PACKET DEVICE.

To summarize: 0xef is SET FEATURES, 0xec is IDENTIFY DEVICE, and 0xa1 is IDENTIFY PACKET DEVICE. The command byte is the second-to-last in each cdb.

I just tried to view that page and got a "403 Forbidden" error. Does it contain the kernel log for the hdparm test shown above, or is it a log for a different test? My guess is that it's a different test -- you should mention that fact and describe the commands sent in the other test.

You mean IDENTIFY DEVICE. There is no ATA IDENTIFY command.

Alan Stern

I'm sorry; bear with me as this thread is long and I have little SCSI experience.

Ok, I was confused there. The buffalo drive has worked fine for me, but I've been testing with 2.6.33 and beyond. I was confused about Jonas' statement that with the latest hdparm "The good news: It doesn't crash the chip anymore. The drive is still mounted fine after executing hdparm." By that I suppose he means the drive doesn't stall on the ATA 12 IDENTIFY DEVICE command.

Ok, I'll revise that. I wish I had a convenient wiki to stick this description up, so that everyone could edit it.

Yes, I understand. I had only wanted to mention the stall in case they looked at the full kernel log file.

Ok, so I should probably just include this snippet from the original kernel log?

Mar 24 18:51:29 js-workstation kernel: [  126.731371] usb-storage: Command (unknown command) (16 bytes)
Mar 24 18:51:29 js-workstation kernel: [  126.731372] usb-storage:  85 08 2e 00 00 00 00 00 00 00 00 00 00 40 ec 00
Mar 24 18:51:29 js-workstation kernel: [  126.731378] usb-storage: Bulk Command S 0x43425355 T 0x2f L 512 F 128 Trg 0 LUN 0 CL 16
Mar 24 18:51:29 js-workstation kernel: [  126.731379] usb-storage: usb_stor_bulk_transfer_buf: xfer 31 bytes
Mar 24 18:51:29 js-workstation kernel: [  126.731543] usb-storage: Status code 0; transferred 31/31
Mar 24 18:51:29 js-workstation kernel: [  126.731544] usb-storage: -- transfer complete
Mar 24 18:51:29 js-workstation kernel: [  126.731546] usb-storage: Bulk command transfer result=0
Mar 24 18:51:29 js-workstation kernel: [  126.731547] usb-storage: usb_stor_bulk_transfer_sglist: xfer 512 bytes, 1 entries
Mar 24 18:51:29 js-workstation kernel: [  126.731719] usb-storage: Status code -32; transferred 0/512
Mar 24 18:51:29 js-workstation kernel: [  126.731723] usb-storage: clearing endpoint halt for pipe 0xc0008280
Mar 24 18:51:29 js-workstation kernel: [  126.731727] usb-storage: usb_stor_control_msg: rq
 rqtype value00 index� len=0
Mar 24 18:51:29 js-workstation kernel: [  126.732152] usb-storage: usb_stor_clear_halt: result = 0
Mar 24 18:51:29 js-workstation kernel: [  126.732153] usb-storage: Bulk data transfer result 0x2
Mar 24 18:51:29 js-workstation kernel: [  126.732154] usb-storage: Attempting to get CSW...
Mar 24 18:51:29 js-workstation kernel: [  126.732155] usb-storage: usb_stor_bulk_transfer_buf: xfer 13 bytes
Mar 24 18:51:29 js-workstation kernel: [  126.732430] usb-storage: Status code 0; transferred 13/13
Mar 24 18:51:29 js-workstation kernel: [  126.732431] usb-storage: -- transfer complete
Mar 24 18:51:29 js-workstation kernel: [  126.732432] usb-storage: Bulk status result = 0
Mar 24 18:51:29 js-workstation kernel: [  126.732434] usb-storage: Bulk Status S 0x53425355 T 0x2f R 512 Stat 0x2
Mar 24 18:51:29 js-workstation kernel: [  126.732435] usb-storage: -- transport indicates error, resetting

The important bit being that the Status in the CSW is 0x2, which drivers/usb/storage/transport.h defines as a US_BULK_STAT_PHASE.

Ok, thanks for that explanation.

I'm not sure what's up with that. The file has the same permissions as the bluetooth log file, but I can download the bluetooth log file and not the buffalo log file:

-rw-r--r-- 1 sarah sarah 10980197 2009-06-15 15:53 bluetooth-suspend-external-4.log -rw-r--r-- 1 sarah sarah 1419858 2010-04-16 11:13 buffalo-hd-ata-16-issue.log

I'll ask my "server admin" (i.e. husband) who is currently asleep about it. In the meantime, I've uploaded a tar and a zip file of the log, which I've verified you can download:

http://minilop.net/~sarah/buffalo-hd-ata-16-issue.tar.gz
http://minilop.net/~sarah/buffalo-hd-ata-16-issue.zip

It's the original kernel log Jonas sent me. This was the log from when udev was invoking hdparm automatically. Jonas didn't send a kernel log from his tests with hdparm alone. But yes, I should mention it's a different log.

He means that the drive doesn't report a phase error on the ATA_16 IDENTIFY DEVICE command, and consequently xhci-hcd doesn't have to try (and fail) to reset the port.

Yes, that would be best. You might also mention that the drive does not return a phase error when it gets an ATA_16 IDENTIFY DEVICE command with the Sector Count field set to 1.

Correct.

I was indeed able to download the zip file. How helpful it will be to the people at Buffalo is questionable, but at least they can read it if they want to.

Alan Stern

Could the people experiencing issues with this hardware, please give the attached copy of hdparm (pre-release) a go on their troublesome systems, and report back?

This version uses ATA_12 for PACKET IDENTIFY and any subsequent commands to a PACKET device (CD, DVD, TAPE, etc..), and ATA_16 for everything else.

With the caveat that the first command is nearly always an ATA_16 IDENTIFY command.

A sector count of "1" is provided for all IDENTIFY / PACKET IDENTIFY commands, or at least that's the intent of the code. :)

Thanks

Mark Lord
Real-Time Remedies Inc.
[email protected]

..

Mmm.. got that wrong, I guess.

Let's try again. Does the attached copy of hdparm work for everybody now? It uses ATA_16 by default, for everything.

And forces ATA_16 when it thinks it is talking to an ATAPI device. Plus, it uses a sector count of one (1) for all IDENTIFY commands.

Note however, that USB-SATA bridge chips from other vendors have always worked correctly without the need for the sector-count field.

Eg. The bridge that Western Digital uses in their external enclosures has no trouble following the SATA/SATL spec of "n/a" for the sector-count field.

Cheers

Mark

No, it doesn't:

/dev/sdb:

outgoing cdb:  85 08 2e 00 00 00 01 00 00 00 00 00 00 40 ec 00
data:  00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
SG_IO: ATA_16 status=0x0, host_status=0x0, driver_status=0x0
SG_IO: bad response (not CHECK_CONDITION)
Trying legacy HDIO_DRIVE_CMD
outgoing cdb:  85 08 2e 00 00 00 01 00 00 00 00 00 00 40 a1 00
data:  40 00 ff 3f 37 c8 10 00 00 00 00 00 3f 00 00 00
SG_IO: ATA_16 status=0x2, host_status=0x0, driver_status=0x8
SG_IO: sb[]:  72 0b 00 00 00 00 00 0e 09 0c 00 04 00 01 00 00 00 00 00 

00 40 51 00 00 00 00 00 00 00 00 00 00
SG_IO: desc[]: 09 0c 00 04 00 01 00 00 00 00 00 00
ATA_16 statQ err nsect
lbal lbam lbah dev@
I/O error, ata_op=0xa1 ata_status=0x51 ata_error=0x04
HDIO_DRIVE_CMD(identify) failed: Input/output error

  readonly      =  0 (off)
  readahead     = 256 (on)
  geometry      = 121601/255/63, sectors = 1953525168, start = 0

-Jonas

That line is supposed to be the data returned by the drive? It sure doesn't look right.

Jonas, can you run the same test, but this time with the drive attached to your EHCI controller, and get a usbmon log?

Alan Stern

..

Yeah, I am also curious about that,
how it works (or not) when connected via a USB2 cable instead of USB3.

Thanks

Mark Lord
Real-Time Remedies Inc.
[email protected]

Jonas,

Can you include the kernel dmesg with USB mass storage debugging turned on for this version of hdparm? I want to confirm the device is still sending a phase error to the ATA_16 IDENTIFY DEVICE command with the sector count set to 1.

Sarah Sharp

Sorry for the delay. Attached are both a USB3 and a USB2 dmesg log of running the latest version of hpdarm.

-Jonas

[  622.875394] hub 10-0:1.0: hub_suspend
[  622.875400] usb usb10: bus auto-suspend
[  622.875402] usb usb10: bus suspend fail, err -2
[  622.875403] hub 10-0:1.0: hub_resume
[  622.875410] xhci_hcd 0000:03:00.0: get port status, actual port 0 status  = 0x2a0
[  622.875412] xhci_hcd 0000:03:00.0: Get port status returned 0x100
[  622.875418] xhci_hcd 0000:03:00.0: get port status, actual port 1 status  = 0x2a0
[  622.875419] xhci_hcd 0000:03:00.0: Get port status returned 0x100
[  622.875423] xhci_hcd 0000:03:00.0: get port status, actual port 2 status  = 0x2a0
[  622.875424] xhci_hcd 0000:03:00.0: Get port status returned 0x100
[  622.875428] xhci_hcd 0000:03:00.0: get port status, actual port 3 status  = 0x2a0
[  622.875429] xhci_hcd 0000:03:00.0: Get port status returned 0x100
[  622.875434] hub 10-0:1.0: state 7 ports 4 chg 0000 evt 0000
[  625.881285] hub 10-0:1.0: hub_suspend
[  625.881291] usb usb10: bus auto-suspend
[  625.881293] usb usb10: bus suspend fail, err -2
[  625.881294] hub 10-0:1.0: hub_resume
[  625.881301] xhci_hcd 0000:03:00.0: get port status, actual port 0 status  = 0x2a0
[  625.881302] xhci_hcd 0000:03:00.0: Get port status returned 0x100
[  625.881308] xhci_hcd 0000:03:00.0: get port status, actual port 1 status  = 0x2a0
[  625.881309] xhci_hcd 0000:03:00.0: Get port status returned 0x100
[  625.881313] xhci_hcd 0000:03:00.0: get port status, actual port 2 status  = 0x2a0
[  625.881315] xhci_hcd 0000:03:00.0: Get port status returned 0x100
[  625.881319] xhci_hcd 0000:03:00.0: get port status, actual port 3 status  = 0x2a0
[  625.881320] xhci_hcd 0000:03:00.0: Get port status returned 0x100
[  625.881325] hub 10-0:1.0: state 7 ports 4 chg 0000 evt 0000
[  628.002800] usb-storage: queuecommand called
[  628.002840] usb-storage: *** thread awakened.
[  628.002846] usb-storage: Command (unknown command) (16 bytes)
[  628.002849] usb-storage:  85 08 2e 00 00 00 01 00 00 00 00 00 00 40 ec 00
[  628.002863] usb-storage: Bulk Command S 0x43425355 T 0x102 L 512 F 128 Trg 0 LUN 0 CL 16
[  628.002867] usb-storage: usb_stor_bulk_transfer_buf: xfer 31 bytes
[  628.003050] usb-storage: Status code 0; transferred 31/31
[  628.003052] usb-storage: -- transfer complete
[  628.003055] usb-storage: Bulk command transfer result=0
[  628.003058] usb-storage: usb_stor_bulk_transfer_sglist: xfer 512 bytes, 1 entries
[  628.008790] usb-storage: Status code 0; transferred 512/512
[  628.008793] usb-storage: -- transfer complete
[  628.008795] usb-storage: Bulk data transfer result 0x0
[  628.008798] usb-storage: Attempting to get CSW...
[  628.008801] usb-storage: usb_stor_bulk_transfer_buf: xfer 13 bytes
[  628.008944] usb-storage: Status code 0; transferred 13/13
[  628.008947] usb-storage: -- transfer complete
[  628.008949] usb-storage: Bulk status result = 0
[  628.008952] usb-storage: Bulk Status S 0x53425355 T 0x102 R 0 Stat 0x0
[  628.008956] usb-storage: scsi cmd done, result=0x0
[  628.008960] usb-storage: *** thread sleeping.
[  628.009083] usb-storage: queuecommand called
[  628.009124] usb-storage: *** thread awakened.
[  628.009127] usb-storage: Command (unknown command) (16 bytes)
[  628.009130] usb-storage:  85 08 2e 00 00 00 01 00 00 00 00 00 00 40 a1 00
[  628.009143] usb-storage: Bulk Command S 0x43425355 T 0x103 L 512 F 128 Trg 0 LUN 0 CL 16
[  628.009147] usb-storage: usb_stor_bulk_transfer_buf: xfer 31 bytes
[  628.009282] usb-storage: Status code 0; transferred 31/31
[  628.009285] usb-storage: -- transfer complete
[  628.009287] usb-storage: Bulk command transfer result=0
[  628.009290] usb-storage: usb_stor_bulk_transfer_sglist: xfer 512 bytes, 1 entries
[  628.009545] usb-storage: Status code -32; transferred 0/512
[  628.009549] usb-storage: clearing endpoint halt for pipe 0xc0008480
[  628.009555] usb-storage: usb_stor_control_msg: rq=01 rqtype=02 value=0000 index=81 len=0
[  628.009670] usb-storage: usb_stor_clear_halt: result = 0
[  628.009673] usb-storage: Bulk data transfer result 0x2
[  628.009675] usb-storage: Attempting to get CSW...
[  628.009678] usb-storage: usb_stor_bulk_transfer_buf: xfer 13 bytes
[  628.009780] usb-storage: Status code 0; transferred 13/13
[  628.009783] usb-storage: -- transfer complete
[  628.009785] usb-storage: Bulk status result = 0
[  628.009788] usb-storage: Bulk Status S 0x53425355 T 0x103 R 512 Stat 0x1
[  628.009791] usb-storage: -- transport indicates command failure
[  628.009794] usb-storage: -- unexpectedly short transfer
[  628.009796] usb-storage: Issuing auto-REQUEST_SENSE
[  628.009801] usb-storage: Bulk Command S 0x43425355 T 0x104 L 96 F 128 Trg 0 LUN 0 CL 6
[  628.009804] usb-storage: usb_stor_bulk_transfer_buf: xfer 31 bytes
[  628.009905] usb-storage: Status code 0; transferred 31/31
[  628.009908] usb-storage: -- transfer complete
[  628.009910] usb-storage: Bulk command transfer result=0
[  628.009913] usb-storage: usb_stor_bulk_transfer_sglist: xfer 96 bytes, 1 entries
[  628.010034] usb-storage: Status code 0; transferred 96/96
[  628.010036] usb-storage: -- transfer complete
[  628.010039] usb-storage: Bulk data transfer result 0x0
[  628.010041] usb-storage: Attempting to get CSW...
[  628.010044] usb-storage: usb_stor_bulk_transfer_buf: xfer 13 bytes
[  628.010123] usb-storage: Status code 0; transferred 13/13
[  628.010126] usb-storage: -- transfer complete
[  628.010128] usb-storage: Bulk status result = 0
[  628.010131] usb-storage: Bulk Status S 0x53425355 T 0x104 R 0 Stat 0x0
[  628.010134] usb-storage: -- Result from auto-sense is 0
[  628.010137] usb-storage: -- code: 0x72, key: 0x0, ASC: 0x0, ASCQ: 0x1
[  628.010140] usb-storage: No Sense: Filemark detected
[  628.010144] usb-storage: scsi cmd done, result=0x2
[  628.010148] usb-storage: *** thread sleeping.
[  628.011488] usb-storage: queuecommand called
[  628.011496] usb-storage: *** thread awakened.
[  628.011500] usb-storage: Command READ_10 (10 bytes)
[  628.011502] usb-storage:  28 00 00 00 00 00 00 00 08 00
[  628.011512] usb-storage: Bulk Command S 0x43425355 T 0x105 L 4096 F 128 Trg 0 LUN 0 CL 10
[  628.011515] usb-storage: usb_stor_bulk_transfer_buf: xfer 31 bytes
[  628.011654] usb-storage: Status code 0; transferred 31/31
[  628.011656] usb-storage: -- transfer complete
[  628.011659] usb-storage: Bulk command transfer result=0
[  628.011662] usb-storage: usb_stor_bulk_transfer_sglist: xfer 4096 bytes, 1 entries
[  628.015897] usb-storage: Status code 0; transferred 4096/4096
[  628.015900] usb-storage: -- transfer complete
[  628.015903] usb-storage: Bulk data transfer result 0x0
[  628.015905] usb-storage: Attempting to get CSW...
[  628.015908] usb-storage: usb_stor_bulk_transfer_buf: xfer 13 bytes
[  628.016020] usb-storage: Status code 0; transferred 13/13
[  628.016023] usb-storage: -- transfer complete
[  628.016025] usb-storage: Bulk status result = 0
[  628.016028] usb-storage: Bulk Status S 0x53425355 T 0x105 R 0 Stat 0x0
[  628.016031] usb-storage: scsi cmd done, result=0x0
[  628.016035] usb-storage: *** thread sleeping.
[  628.875336] hub 10-0:1.0: hub_suspend
[  628.875342] usb usb10: bus auto-suspend
[  628.875343] usb usb10: bus suspend fail, err -2
[  628.875344] hub 10-0:1.0: hub_resume
[  628.875351] xhci_hcd 0000:03:00.0: get port status, actual port 0 status  = 0x2a0
[  628.875353] xhci_hcd 0000:03:00.0: Get port status returned 0x100
[  628.875359] xhci_hcd 0000:03:00.0: get port status, actual port 1 status  = 0x2a0
[  628.875360] xhci_hcd 0000:03:00.0: Get port status returned 0x100
[  628.875364] xhci_hcd 0000:03:00.0: get port status, actual port 2 status  = 0x2a0
[  628.875365] xhci_hcd 0000:03:00.0: Get port status returned 0x100
[  628.875369] xhci_hcd 0000:03:00.0: get port status, actual port 3 status  = 0x2a0
[  628.875370] xhci_hcd 0000:03:00.0: Get port status returned 0x100
[  628.875375] hub 10-0:1.0: state 7 ports 4 chg 0000 evt 0000

[  296.030320] usb-storage: queuecommand called
[  296.030366] usb-storage: *** thread awakened.
[  296.030372] usb-storage: Command (unknown command) (16 bytes)
[  296.030375] usb-storage:  85 08 2e 00 00 00 01 00 00 00 00 00 00 40 ec 00
[  296.030389] usb-storage: Bulk Command S 0x43425355 T 0x102 L 512 F 128 Trg 0 LUN 0 CL 16
[  296.030393] usb-storage: usb_stor_bulk_transfer_buf: xfer 31 bytes
[  296.030401] usb 10-2: ep 0x2 - urb len = 0x1f (31), addr = 0xcf4c7000, num_trbs = 1
[  296.030405] xhci_hcd 0000:03:00.0: Endpoint state = 0x1
[  296.030410] xhci_hcd 0000:03:00.0: Ring enq = 0xcf46e4c0 (DMA)
[  296.030415] xhci_hcd 0000:03:00.0: `MEM_WRITE_DWORD(3'b000, 32'hffffc900058ac804, 32'h4, 4'hf);
[  296.030442] xhci_hcd 0000:03:00.0: op reg status = 00000008
[  296.030445] xhci_hcd 0000:03:00.0: ir set irq_pending = 00000003
[  296.030448] xhci_hcd 0000:03:00.0: Event ring dequeue ptr:
[  296.030452] xhci_hcd 0000:03:00.0: @cf439520 cf46e4b0 00000000 01000000 01048001
[  296.030457] xhci_hcd 0000:03:00.0: `MEM_WRITE_DWORD(3'b000, 32'hffffc900058ac024, 32'h8, 4'hf);
[  296.030463] xhci_hcd 0000:03:00.0: `MEM_WRITE_DWORD(3'b000, 32'hffffc900058ac620, 32'h3, 4'hf);
[  296.030469] xhci_hcd 0000:03:00.0: In xhci_handle_event
[  296.030472] xhci_hcd 0000:03:00.0: xhci_handle_event - OS owns TRB
[  296.030475] xhci_hcd 0000:03:00.0: xhci_handle_event - calling handle_tx_event
[  296.030478] xhci_hcd 0000:03:00.0: In handle_tx_event
[  296.030481] xhci_hcd 0000:03:00.0: handle_tx_event - ep index = 3
[  296.030484] xhci_hcd 0000:03:00.0: handle_tx_event - checking for list empty
[  296.030487] xhci_hcd 0000:03:00.0: handle_tx_event - getting list entry
[  296.030490] xhci_hcd 0000:03:00.0: handle_tx_event - looking for TD
[  296.030494] xhci_hcd 0000:03:00.0: handle_tx_event - found event_seg = ffff880225d66c40
[  296.030497] xhci_hcd 0000:03:00.0: Event TRB with TRB type ID 32
[  296.030500] xhci_hcd 0000:03:00.0: Offset 0x00 (buffer lo) = 0xcf46e4b0
[  296.030504] xhci_hcd 0000:03:00.0: Offset 0x04 (buffer hi) = 0x0
[  296.030507] xhci_hcd 0000:03:00.0: Offset 0x08 (transfer length) = 0x1000000
[  296.030510] xhci_hcd 0000:03:00.0: Offset 0x0C (flags) = 0x1048001
[  296.030513] xhci_hcd 0000:03:00.0: Successful bulk transfer!
[  296.030517] usb 10-2: ep 0x2 - asked for 31 bytes, 0 bytes untransferred
[  296.030521] xhci_hcd 0000:03:00.0: Ring deq = 0xcf46e4c0 (DMA)
[  296.030524] xhci_hcd 0000:03:00.0: Event ring deq = 0xcf439530 (DMA)
[  296.030531] xhci_hcd 0000:03:00.0: // Write event ring dequeue pointer, preserving EHB bit
[  296.030535] xhci_hcd 0000:03:00.0: `MEM_WRITE_DWORD(3'b000, 64'hffffc900058ac638, 64'hcf439530, 4'hf);
[  296.030539] xhci_hcd 0000:03:00.0: Giveback URB ffff8801fe851b40, len = 31, status = 0
[  296.030545] xhci_hcd 0000:03:00.0: xhci_handle_event - returned from handle_tx_event
[  296.030548] xhci_hcd 0000:03:00.0: In xhci_handle_event
[  296.030555] xhci_hcd 0000:03:00.0: `MEM_WRITE_DWORD(3'b000, 64'hffffc900058ac638, 64'hcf439538, 4'hf);
[  296.030564] usb-storage: Status code 0; transferred 31/31
[  296.030566] usb-storage: -- transfer complete
[  296.030569] usb-storage: Bulk command transfer result=0
[  296.030572] usb-storage: usb_stor_bulk_transfer_sglist: xfer 512 bytes, 1 entries
[  296.030579] xhci_hcd 0000:03:00.0: count sg list trbs: 
[  296.030583] xhci_hcd 0000:03:00.0:  sg #0: dma = 0x23bc5000, len = 0x200 (512), num_trbs = 1
[  296.030587] xhci_hcd 0000:03:00.0: 
[  296.030590] usb 10-2: ep 0x81 - urb len = 512, sglist used, num_trbs = 1
[  296.030593] xhci_hcd 0000:03:00.0: Endpoint state = 0x1
[  296.030596] xhci_hcd 0000:03:00.0: First length to xfer from 1st sglist entry = 512
[  296.030601] xhci_hcd 0000:03:00.0:  sg entry: dma = 0x23bc5000, len = 0x200 (512), 64KB boundary at 0x23bd0000, end dma = 0x23bc5200
[  296.030605] xhci_hcd 0000:03:00.0: Ring enq = 0xcf46e130 (DMA)
[  296.030611] xhci_hcd 0000:03:00.0: `MEM_WRITE_DWORD(3'b000, 32'hffffc900058ac804, 32'h3, 4'hf);
[  296.036237] xhci_hcd 0000:03:00.0: op reg status = 00000008
[  296.036240] xhci_hcd 0000:03:00.0: ir set irq_pending = 00000003
[  296.036243] xhci_hcd 0000:03:00.0: Event ring dequeue ptr:
[  296.036247] xhci_hcd 0000:03:00.0: @cf439530 cf46e120 00000000 01000000 01038001
[  296.036253] xhci_hcd 0000:03:00.0: `MEM_WRITE_DWORD(3'b000, 32'hffffc900058ac024, 32'h8, 4'hf);
[  296.036258] xhci_hcd 0000:03:00.0: `MEM_WRITE_DWORD(3'b000, 32'hffffc900058ac620, 32'h3, 4'hf);
[  296.036264] xhci_hcd 0000:03:00.0: In xhci_handle_event
[  296.036267] xhci_hcd 0000:03:00.0: xhci_handle_event - OS owns TRB
[  296.036270] xhci_hcd 0000:03:00.0: xhci_handle_event - calling handle_tx_event
[  296.036273] xhci_hcd 0000:03:00.0: In handle_tx_event
[  296.036276] xhci_hcd 0000:03:00.0: handle_tx_event - ep index = 2
[  296.036279] xhci_hcd 0000:03:00.0: handle_tx_event - checking for list empty
[  296.036283] xhci_hcd 0000:03:00.0: handle_tx_event - getting list entry
[  296.036286] xhci_hcd 0000:03:00.0: handle_tx_event - looking for TD
[  296.036289] xhci_hcd 0000:03:00.0: handle_tx_event - found event_seg = ffff880225d66e00
[  296.036293] xhci_hcd 0000:03:00.0: Event TRB with TRB type ID 32
[  296.036296] xhci_hcd 0000:03:00.0: Offset 0x00 (buffer lo) = 0xcf46e120
[  296.036299] xhci_hcd 0000:03:00.0: Offset 0x04 (buffer hi) = 0x0
[  296.036302] xhci_hcd 0000:03:00.0: Offset 0x08 (transfer length) = 0x1000000
[  296.036305] xhci_hcd 0000:03:00.0: Offset 0x0C (flags) = 0x1038001
[  296.036308] xhci_hcd 0000:03:00.0: Successful bulk transfer!
[  296.036312] usb 10-2: ep 0x81 - asked for 512 bytes, 0 bytes untransferred
[  296.036315] xhci_hcd 0000:03:00.0: Ring deq = 0xcf46e130 (DMA)
[  296.036319] xhci_hcd 0000:03:00.0: Event ring deq = 0xcf439540 (DMA)
[  296.036325] xhci_hcd 0000:03:00.0: // Write event ring dequeue pointer, preserving EHB bit
[  296.036329] xhci_hcd 0000:03:00.0: `MEM_WRITE_DWORD(3'b000, 64'hffffc900058ac638, 64'hcf439540, 4'hf);
[  296.036333] xhci_hcd 0000:03:00.0: Giveback URB ffff8801ed927000, len = 512, status = 0
[  296.036339] xhci_hcd 0000:03:00.0: xhci_handle_event - returned from handle_tx_event
[  296.036343] xhci_hcd 0000:03:00.0: In xhci_handle_event
[  296.036349] xhci_hcd 0000:03:00.0: `MEM_WRITE_DWORD(3'b000, 64'hffffc900058ac638, 64'hcf439548, 4'hf);
[  296.036361] usb-storage: Status code 0; transferred 512/512
[  296.036363] usb-storage: -- transfer complete
[  296.036366] usb-storage: Bulk data transfer result 0x0
[  296.036368] usb-storage: Attempting to get CSW...
[  296.036371] usb-storage: usb_stor_bulk_transfer_buf: xfer 13 bytes
[  296.036376] usb 10-2: ep 0x81 - urb len = 0xd (13), addr = 0xcf4c7000, num_trbs = 1
[  296.036379] xhci_hcd 0000:03:00.0: Endpoint state = 0x1
[  296.036383] xhci_hcd 0000:03:00.0: Ring enq = 0xcf46e140 (DMA)
[  296.036388] xhci_hcd 0000:03:00.0: `MEM_WRITE_DWORD(3'b000, 32'hffffc900058ac804, 32'h3, 4'hf);
[  296.036411] xhci_hcd 0000:03:00.0: op reg status = 00000008
[  296.036414] xhci_hcd 0000:03:00.0: ir set irq_pending = 00000003
[  296.036417] xhci_hcd 0000:03:00.0: Event ring dequeue ptr:
[  296.036421] xhci_hcd 0000:03:00.0: @cf439540 cf46e130 00000000 01000000 01038001
[  296.036426] xhci_hcd 0000:03:00.0: `MEM_WRITE_DWORD(3'b000, 32'hffffc900058ac024, 32'h8, 4'hf);
[  296.036432] xhci_hcd 0000:03:00.0: `MEM_WRITE_DWORD(3'b000, 32'hffffc900058ac620, 32'h3, 4'hf);
[  296.036437] xhci_hcd 0000:03:00.0: In xhci_handle_event
[  296.036440] xhci_hcd 0000:03:00.0: xhci_handle_event - OS owns TRB
[  296.036443] xhci_hcd 0000:03:00.0: xhci_handle_event - calling handle_tx_event
[  296.036446] xhci_hcd 0000:03:00.0: In handle_tx_event
[  296.036450] xhci_hcd 0000:03:00.0: handle_tx_event - ep index = 2
[  296.036453] xhci_hcd 0000:03:00.0: handle_tx_event - checking for list empty
[  296.036456] xhci_hcd 0000:03:00.0: handle_tx_event - getting list entry
[  296.036459] xhci_hcd 0000:03:00.0: handle_tx_event - looking for TD
[  296.036462] xhci_hcd 0000:03:00.0: handle_tx_event - found event_seg = ffff880225d66e00
[  296.036466] xhci_hcd 0000:03:00.0: Event TRB with TRB type ID 32
[  296.036469] xhci_hcd 0000:03:00.0: Offset 0x00 (buffer lo) = 0xcf46e130
[  296.036472] xhci_hcd 0000:03:00.0: Offset 0x04 (buffer hi) = 0x0
[  296.036475] xhci_hcd 0000:03:00.0: Offset 0x08 (transfer length) = 0x1000000
[  296.036478] xhci_hcd 0000:03:00.0: Offset 0x0C (flags) = 0x1038001
[  296.036481] xhci_hcd 0000:03:00.0: Successful bulk transfer!
[  296.036485] usb 10-2: ep 0x81 - asked for 13 bytes, 0 bytes untransferred
[  296.036488] xhci_hcd 0000:03:00.0: Ring deq = 0xcf46e140 (DMA)
[  296.036491] xhci_hcd 0000:03:00.0: Event ring deq = 0xcf439550 (DMA)
[  296.036497] xhci_hcd 0000:03:00.0: // Write event ring dequeue pointer, preserving EHB bit
[  296.036501] xhci_hcd 0000:03:00.0: `MEM_WRITE_DWORD(3'b000, 64'hffffc900058ac638, 64'hcf439550, 4'hf);
[  296.036506] xhci_hcd 0000:03:00.0: Giveback URB ffff8801fe851b40, len = 13, status = 0
[  296.036510] xhci_hcd 0000:03:00.0: xhci_handle_event - returned from handle_tx_event
[  296.036514] xhci_hcd 0000:03:00.0: In xhci_handle_event
[  296.036520] xhci_hcd 0000:03:00.0: `MEM_WRITE_DWORD(3'b000, 64'hffffc900058ac638, 64'hcf439558, 4'hf);
[  296.036529] usb-storage: Status code 0; transferred 13/13
[  296.036531] usb-storage: -- transfer complete
[  296.036533] usb-storage: Bulk status result = 0
[  296.036536] usb-storage: Bulk Status S 0x53425355 T 0x102 R 0 Stat 0x0
[  296.036540] usb-storage: scsi cmd done, result=0x0
[  296.036544] usb-storage: *** thread sleeping.
[  296.036685] usb-storage: queuecommand called
[  296.036725] usb-storage: *** thread awakened.
[  296.036729] usb-storage: Command (unknown command) (16 bytes)
[  296.036731] usb-storage:  85 08 2e 00 00 00 01 00 00 00 00 00 00 40 a1 00
[  296.036745] usb-storage: Bulk Command S 0x43425355 T 0x103 L 512 F 128 Trg 0 LUN 0 CL 16
[  296.036748] usb-storage: usb_stor_bulk_transfer_buf: xfer 31 bytes
[  296.036754] usb 10-2: ep 0x2 - urb len = 0x1f (31), addr = 0xcf4c7000, num_trbs = 1
[  296.036757] xhci_hcd 0000:03:00.0: Endpoint state = 0x1
[  296.036761] xhci_hcd 0000:03:00.0: Ring enq = 0xcf46e4d0 (DMA)
[  296.036766] xhci_hcd 0000:03:00.0: `MEM_WRITE_DWORD(3'b000, 32'hffffc900058ac804, 32'h4, 4'hf);
[  296.036792] xhci_hcd 0000:03:00.0: op reg status = 00000008
[  296.036795] xhci_hcd 0000:03:00.0: ir set irq_pending = 00000003
[  296.036798] xhci_hcd 0000:03:00.0: Event ring dequeue ptr:
[  296.036802] xhci_hcd 0000:03:00.0: @cf439550 cf46e4c0 00000000 01000000 01048001
[  296.036807] xhci_hcd 0000:03:00.0: `MEM_WRITE_DWORD(3'b000, 32'hffffc900058ac024, 32'h8, 4'hf);
[  296.036813] xhci_hcd 0000:03:00.0: `MEM_WRITE_DWORD(3'b000, 32'hffffc900058ac620, 32'h3, 4'hf);
[  296.036818] xhci_hcd 0000:03:00.0: In xhci_handle_event
[  296.036821] xhci_hcd 0000:03:00.0: xhci_handle_event - OS owns TRB
[  296.036824] xhci_hcd 0000:03:00.0: xhci_handle_event - calling handle_tx_event
[  296.036828] xhci_hcd 0000:03:00.0: In handle_tx_event
[  296.036831] xhci_hcd 0000:03:00.0: handle_tx_event - ep index = 3
[  296.036834] xhci_hcd 0000:03:00.0: handle_tx_event - checking for list empty
[  296.036837] xhci_hcd 0000:03:00.0: handle_tx_event - getting list entry
[  296.036840] xhci_hcd 0000:03:00.0: handle_tx_event - looking for TD
[  296.036843] xhci_hcd 0000:03:00.0: handle_tx_event - found event_seg = ffff880225d66c40
[  296.036847] xhci_hcd 0000:03:00.0: Event TRB with TRB type ID 32
[  296.036850] xhci_hcd 0000:03:00.0: Offset 0x00 (buffer lo) = 0xcf46e4c0
[  296.036853] xhci_hcd 0000:03:00.0: Offset 0x04 (buffer hi) = 0x0
[  296.036856] xhci_hcd 0000:03:00.0: Offset 0x08 (transfer length) = 0x1000000
[  296.036859] xhci_hcd 0000:03:00.0: Offset 0x0C (flags) = 0x1048001
[  296.036862] xhci_hcd 0000:03:00.0: Successful bulk transfer!
[  296.036866] usb 10-2: ep 0x2 - asked for 31 bytes, 0 bytes untransferred
[  296.036870] xhci_hcd 0000:03:00.0: Ring deq = 0xcf46e4d0 (DMA)
[  296.036873] xhci_hcd 0000:03:00.0: Event ring deq = 0xcf439560 (DMA)
[  296.036879] xhci_hcd 0000:03:00.0: // Write event ring dequeue pointer, preserving EHB bit
[  296.036883] xhci_hcd 0000:03:00.0: `MEM_WRITE_DWORD(3'b000, 64'hffffc900058ac638, 64'hcf439560, 4'hf);
[  296.036888] xhci_hcd 0000:03:00.0: Giveback URB ffff8801fe851b40, len = 31, status = 0
[  296.036893] xhci_hcd 0000:03:00.0: xhci_handle_event - returned from handle_tx_event
[  296.036896] xhci_hcd 0000:03:00.0: In xhci_handle_event
[  296.036903] xhci_hcd 0000:03:00.0: `MEM_WRITE_DWORD(3'b000, 64'hffffc900058ac638, 64'hcf439568, 4'hf);
[  296.036912] usb-storage: Status code 0; transferred 31/31
[  296.036915] usb-storage: -- transfer complete
[  296.036917] usb-storage: Bulk command transfer result=0
[  296.036920] usb-storage: usb_stor_bulk_transfer_sglist: xfer 512 bytes, 1 entries
[  296.036926] xhci_hcd 0000:03:00.0: count sg list trbs: 
[  296.036930] xhci_hcd 0000:03:00.0:  sg #0: dma = 0x23bc5800, len = 0x200 (512), num_trbs = 1
[  296.036933] xhci_hcd 0000:03:00.0: 
[  296.036936] usb 10-2: ep 0x81 - urb len = 512, sglist used, num_trbs = 1
[  296.036940] xhci_hcd 0000:03:00.0: Endpoint state = 0x1
[  296.036943] xhci_hcd 0000:03:00.0: First length to xfer from 1st sglist entry = 512
[  296.036948] xhci_hcd 0000:03:00.0:  sg entry: dma = 0x23bc5800, len = 0x200 (512), 64KB boundary at 0x23bd0000, end dma = 0x23bc5a00
[  296.036952] xhci_hcd 0000:03:00.0: Ring enq = 0xcf46e150 (DMA)
[  296.036957] xhci_hcd 0000:03:00.0: `MEM_WRITE_DWORD(3'b000, 32'hffffc900058ac804, 32'h3, 4'hf);
[  296.037072] xhci_hcd 0000:03:00.0: op reg status = 00000008
[  296.037076] xhci_hcd 0000:03:00.0: ir set irq_pending = 00000003
[  296.037079] xhci_hcd 0000:03:00.0: Event ring dequeue ptr:
[  296.037082] xhci_hcd 0000:03:00.0: @cf439560 cf46e140 00000000 06000200 01038001
[  296.037088] xhci_hcd 0000:03:00.0: `MEM_WRITE_DWORD(3'b000, 32'hffffc900058ac024, 32'h8, 4'hf);
[  296.037094] xhci_hcd 0000:03:00.0: `MEM_WRITE_DWORD(3'b000, 32'hffffc900058ac620, 32'h3, 4'hf);
[  296.037099] xhci_hcd 0000:03:00.0: In xhci_handle_event
[  296.037102] xhci_hcd 0000:03:00.0: xhci_handle_event - OS owns TRB
[  296.037105] xhci_hcd 0000:03:00.0: xhci_handle_event - calling handle_tx_event
[  296.037109] xhci_hcd 0000:03:00.0: In handle_tx_event
[  296.037112] xhci_hcd 0000:03:00.0: handle_tx_event - ep index = 2
[  296.037115] xhci_hcd 0000:03:00.0: handle_tx_event - checking for list empty
[  296.037118] xhci_hcd 0000:03:00.0: handle_tx_event - getting list entry
[  296.037121] xhci_hcd 0000:03:00.0: handle_tx_event - looking for TD
[  296.037125] xhci_hcd 0000:03:00.0: handle_tx_event - found event_seg = ffff880225d66e00
[  296.037128] xhci_hcd 0000:03:00.0: Event TRB with TRB type ID 32
[  296.037131] xhci_hcd 0000:03:00.0: Offset 0x00 (buffer lo) = 0xcf46e140
[  296.037134] xhci_hcd 0000:03:00.0: Offset 0x04 (buffer hi) = 0x0
[  296.037137] xhci_hcd 0000:03:00.0: Offset 0x08 (transfer length) = 0x6000200
[  296.037141] xhci_hcd 0000:03:00.0: Offset 0x0C (flags) = 0x1038001
[  296.037143] xhci_hcd 0000:03:00.0: WARN: Stalled endpoint
[  296.037148] usb 10-2: ep 0x81 - asked for 512 bytes, 512 bytes untransferred
[  296.037151] xhci_hcd 0000:03:00.0: Event ring deq = 0xcf439570 (DMA)
[  296.037158] xhci_hcd 0000:03:00.0: // Write event ring dequeue pointer, preserving EHB bit
[  296.037162] xhci_hcd 0000:03:00.0: `MEM_WRITE_DWORD(3'b000, 64'hffffc900058ac638, 64'hcf439570, 4'hf);
[  296.037166] xhci_hcd 0000:03:00.0: Giveback URB ffff8801ed927000, len = 0, status = -32
[  296.037172] xhci_hcd 0000:03:00.0: xhci_handle_event - returned from handle_tx_event
[  296.037175] xhci_hcd 0000:03:00.0: In xhci_handle_event
[  296.037182] xhci_hcd 0000:03:00.0: `MEM_WRITE_DWORD(3'b000, 64'hffffc900058ac638, 64'hcf439578, 4'hf);
[  296.037193] usb-storage: Status code -32; transferred 0/512
[  296.037196] usb-storage: clearing endpoint halt for pipe 0xc0008280
[  296.037201] usb-storage: usb_stor_control_msg: rq=01 rqtype=02 value=0000 index=81 len=0
[  296.037205] xhci_hcd 0000:03:00.0: Queueing ctrl tx for slot id 1, ep 0
[  296.037209] xhci_hcd 0000:03:00.0: Endpoint state = 0x1
[  296.037212] xhci_hcd 0000:03:00.0: Ring enq = 0xcf4399e0 (DMA)
[  296.037215] xhci_hcd 0000:03:00.0: Ring enq = 0xcf4399f0 (DMA)
[  296.037220] xhci_hcd 0000:03:00.0: `MEM_WRITE_DWORD(3'b000, 32'hffffc900058ac804, 32'h1, 4'hf);
[  296.037516] xhci_hcd 0000:03:00.0: op reg status = 00000008
[  296.037519] xhci_hcd 0000:03:00.0: ir set irq_pending = 00000003
[  296.037522] xhci_hcd 0000:03:00.0: Event ring dequeue ptr:
[  296.037526] xhci_hcd 0000:03:00.0: @cf439570 cf4399e0 00000000 01000000 01018001
[  296.037531] xhci_hcd 0000:03:00.0: `MEM_WRITE_DWORD(3'b000, 32'hffffc900058ac024, 32'h8, 4'hf);
[  296.037537] xhci_hcd 0000:03:00.0: `MEM_WRITE_DWORD(3'b000, 32'hffffc900058ac620, 32'h3, 4'hf);
[  296.037543] xhci_hcd 0000:03:00.0: In xhci_handle_event
[  296.037545] xhci_hcd 0000:03:00.0: xhci_handle_event - OS owns TRB
[  296.037549] xhci_hcd 0000:03:00.0: xhci_handle_event - calling handle_tx_event
[  296.037552] xhci_hcd 0000:03:00.0: In handle_tx_event
[  296.037555] xhci_hcd 0000:03:00.0: handle_tx_event - ep index = 0
[  296.037558] xhci_hcd 0000:03:00.0: handle_tx_event - checking for list empty
[  296.037561] xhci_hcd 0000:03:00.0: handle_tx_event - getting list entry
[  296.037564] xhci_hcd 0000:03:00.0: handle_tx_event - looking for TD
[  296.037568] xhci_hcd 0000:03:00.0: handle_tx_event - found event_seg = ffff880225d66dc0
[  296.037571] xhci_hcd 0000:03:00.0: Event TRB with TRB type ID 32
[  296.037574] xhci_hcd 0000:03:00.0: Offset 0x00 (buffer lo) = 0xcf4399e0
[  296.037577] xhci_hcd 0000:03:00.0: Offset 0x04 (buffer hi) = 0x0
[  296.037580] xhci_hcd 0000:03:00.0: Offset 0x08 (transfer length) = 0x1000000
[  296.037584] xhci_hcd 0000:03:00.0: Offset 0x0C (flags) = 0x1018001
[  296.037587] xhci_hcd 0000:03:00.0: DMA address or buffer contents= 3477314016
[  296.037591] xhci_hcd 0000:03:00.0: Successful control transfer!
[  296.037594] xhci_hcd 0000:03:00.0: Ring deq = 0xcf4399e0 (DMA)
[  296.037597] xhci_hcd 0000:03:00.0: Ring deq = 0xcf4399f0 (DMA)
[  296.037600] xhci_hcd 0000:03:00.0: Event ring deq = 0xcf439580 (DMA)
[  296.037606] xhci_hcd 0000:03:00.0: // Write event ring dequeue pointer, preserving EHB bit
[  296.037610] xhci_hcd 0000:03:00.0: `MEM_WRITE_DWORD(3'b000, 64'hffffc900058ac638, 64'hcf439580, 4'hf);
[  296.037615] xhci_hcd 0000:03:00.0: Giveback URB ffff8801fe851b40, len = 0, status = 0
[  296.037620] xhci_hcd 0000:03:00.0: xhci_handle_event - returned from handle_tx_event
[  296.037624] xhci_hcd 0000:03:00.0: In xhci_handle_event
[  296.037630] xhci_hcd 0000:03:00.0: `MEM_WRITE_DWORD(3'b000, 64'hffffc900058ac638, 64'hcf439588, 4'hf);
[  296.037640] xhci_hcd 0000:03:00.0: Queueing reset endpoint command
[  296.037644] xhci_hcd 0000:03:00.0: Command ring enq = 0xcf439040 (DMA)
[  296.037647] xhci_hcd 0000:03:00.0: Cleaning up stalled endpoint ring
[  296.037650] xhci_hcd 0000:03:00.0: Finding segment containing stopped TRB.
[  296.037653] xhci_hcd 0000:03:00.0: Finding endpoint context
[  296.037656] xhci_hcd 0000:03:00.0: Finding segment containing last TRB in TD.
[  296.037659] xhci_hcd 0000:03:00.0: New dequeue segment = ffff880225d66e00 (virtual)
[  296.037663] xhci_hcd 0000:03:00.0: New dequeue pointer = 0xcf46e150 (DMA)
[  296.037666] xhci_hcd 0000:03:00.0: Setting dequeue pointer in internal ring state.
[  296.037669] xhci_hcd 0000:03:00.0: Queueing new dequeue state
[  296.037673] xhci_hcd 0000:03:00.0: Set TR Deq Ptr cmd, new deq seg = ffff880225d66e00 (0xcf46e000 dma), new deq ptr = ffff8800cf46e150 (0xcf46e150 dma), new cycle = 1
[  296.037678] xhci_hcd 0000:03:00.0: Command ring enq = 0xcf439050 (DMA)
[  296.037681] xhci_hcd 0000:03:00.0: // Ding dong!
[  296.037686] xhci_hcd 0000:03:00.0: `MEM_WRITE_DWORD(3'b000, 32'hffffc900058ac800, 32'h0, 4'hf);
[  296.037691] usb-storage: usb_stor_clear_halt: result = 0
[  296.037694] usb-storage: Bulk data transfer result 0x2
[  296.037697] usb-storage: Attempting to get CSW...
[  296.037699] usb-storage: usb_stor_bulk_transfer_buf: xfer 13 bytes
[  296.037705] usb 10-2: ep 0x81 - urb len = 0xd (13), addr = 0xcf4c7000, num_trbs = 1
[  296.037708] xhci_hcd 0000:03:00.0: Endpoint state = 0x2
[  296.037711] xhci_hcd 0000:03:00.0: WARN halted endpoint, queueing URB anyway.
[  296.037714] xhci_hcd 0000:03:00.0: Ring enq = 0xcf46e160 (DMA)
[  296.037849] xhci_hcd 0000:03:00.0: op reg status = 00000008
[  296.037852] xhci_hcd 0000:03:00.0: ir set irq_pending = 00000003
[  296.037855] xhci_hcd 0000:03:00.0: Event ring dequeue ptr:
[  296.037859] xhci_hcd 0000:03:00.0: @cf439580 cf439030 00000000 01000000 01008401
[  296.037864] xhci_hcd 0000:03:00.0: `MEM_WRITE_DWORD(3'b000, 32'hffffc900058ac024, 32'h8, 4'hf);
[  296.037870] xhci_hcd 0000:03:00.0: `MEM_WRITE_DWORD(3'b000, 32'hffffc900058ac620, 32'h3, 4'hf);
[  296.037876] xhci_hcd 0000:03:00.0: In xhci_handle_event
[  296.037878] xhci_hcd 0000:03:00.0: xhci_handle_event - OS owns TRB
[  296.037882] xhci_hcd 0000:03:00.0: xhci_handle_event - calling handle_cmd_completion
[  296.037885] xhci_hcd 0000:03:00.0: Ignoring reset ep completion code of 1
[  296.037889] xhci_hcd 0000:03:00.0: Command ring deq = 0xcf439040 (DMA)
[  296.037892] xhci_hcd 0000:03:00.0: xhci_handle_event - returned from handle_cmd_completion
[  296.037896] xhci_hcd 0000:03:00.0: Event ring deq = 0xcf439590 (DMA)
[  296.037902] xhci_hcd 0000:03:00.0: // Write event ring dequeue pointer, preserving EHB bit
[  296.037906] xhci_hcd 0000:03:00.0: `MEM_WRITE_DWORD(3'b000, 64'hffffc900058ac638, 64'hcf439590, 4'hf);
[  296.037910] xhci_hcd 0000:03:00.0: In xhci_handle_event
[  296.037912] xhci_hcd 0000:03:00.0: xhci_handle_event - OS owns TRB
[  296.037916] xhci_hcd 0000:03:00.0: xhci_handle_event - calling handle_cmd_completion
[  296.037919] xhci_hcd 0000:03:00.0: Successful Set TR Deq Ptr cmd, deq = @cf46e151
[  296.037925] xhci_hcd 0000:03:00.0: `MEM_WRITE_DWORD(3'b000, 32'hffffc900058ac804, 32'h3, 4'hf);
[  296.037930] xhci_hcd 0000:03:00.0: Command ring deq = 0xcf439050 (DMA)
[  296.037933] xhci_hcd 0000:03:00.0: xhci_handle_event - returned from handle_cmd_completion
[  296.037937] xhci_hcd 0000:03:00.0: Event ring deq = 0xcf4395a0 (DMA)
[  296.037943] xhci_hcd 0000:03:00.0: // Write event ring dequeue pointer, preserving EHB bit
[  296.037947] xhci_hcd 0000:03:00.0: `MEM_WRITE_DWORD(3'b000, 64'hffffc900058ac638, 64'hcf4395a0, 4'hf);
[  296.037951] xhci_hcd 0000:03:00.0: In xhci_handle_event
[  296.037954] xhci_hcd 0000:03:00.0: xhci_handle_event - OS owns TRB
[  296.037957] xhci_hcd 0000:03:00.0: xhci_handle_event - calling handle_tx_event
[  296.037960] xhci_hcd 0000:03:00.0: In handle_tx_event
[  296.037963] xhci_hcd 0000:03:00.0: handle_tx_event - ep index = 2
[  296.037966] xhci_hcd 0000:03:00.0: handle_tx_event - checking for list empty
[  296.037970] xhci_hcd 0000:03:00.0: handle_tx_event - getting list entry
[  296.037973] xhci_hcd 0000:03:00.0: handle_tx_event - looking for TD
[  296.037976] xhci_hcd 0000:03:00.0: handle_tx_event - found event_seg = ffff880225d66e00
[  296.037980] xhci_hcd 0000:03:00.0: Event TRB with TRB type ID 32
[  296.037983] xhci_hcd 0000:03:00.0: Offset 0x00 (buffer lo) = 0xcf46e150
[  296.037986] xhci_hcd 0000:03:00.0: Offset 0x04 (buffer hi) = 0x0
[  296.037989] xhci_hcd 0000:03:00.0: Offset 0x08 (transfer length) = 0x1000000
[  296.037992] xhci_hcd 0000:03:00.0: Offset 0x0C (flags) = 0x1038001
[  296.037995] xhci_hcd 0000:03:00.0: Successful bulk transfer!
[  296.037999] usb 10-2: ep 0x81 - asked for 13 bytes, 0 bytes untransferred
[  296.038002] xhci_hcd 0000:03:00.0: Ring deq = 0xcf46e160 (DMA)
[  296.038005] xhci_hcd 0000:03:00.0: Event ring deq = 0xcf4395b0 (DMA)
[  296.038012] xhci_hcd 0000:03:00.0: // Write event ring dequeue pointer, preserving EHB bit
[  296.038016] xhci_hcd 0000:03:00.0: `MEM_WRITE_DWORD(3'b000, 64'hffffc900058ac638, 64'hcf4395b0, 4'hf);
[  296.038020] xhci_hcd 0000:03:00.0: Giveback URB ffff8801fe851b40, len = 13, status = 0
[  296.038025] xhci_hcd 0000:03:00.0: xhci_handle_event - returned from handle_tx_event
[  296.038029] xhci_hcd 0000:03:00.0: In xhci_handle_event
[  296.038035] xhci_hcd 0000:03:00.0: `MEM_WRITE_DWORD(3'b000, 64'hffffc900058ac638, 64'hcf4395b8, 4'hf);
[  296.038045] usb-storage: Status code 0; transferred 13/13
[  296.038048] usb-storage: -- transfer complete
[  296.038050] usb-storage: Bulk status result = 0
[  296.038053] usb-storage: Bulk Status S 0x53425355 T 0x103 R 512 Stat 0x1
[  296.038056] usb-storage: -- transport indicates command failure
[  296.038059] usb-storage: -- unexpectedly short transfer
[  296.038061] usb-storage: Issuing auto-REQUEST_SENSE
[  296.038065] usb-storage: Bulk Command S 0x43425355 T 0x104 L 96 F 128 Trg 0 LUN 0 CL 6
[  296.038069] usb-storage: usb_stor_bulk_transfer_buf: xfer 31 bytes
[  296.038074] usb 10-2: ep 0x2 - urb len = 0x1f (31), addr = 0xcf4c7000, num_trbs = 1
[  296.038077] xhci_hcd 0000:03:00.0: Endpoint state = 0x1
[  296.038081] xhci_hcd 0000:03:00.0: Ring enq = 0xcf46e4e0 (DMA)
[  296.038086] xhci_hcd 0000:03:00.0: `MEM_WRITE_DWORD(3'b000, 32'hffffc900058ac804, 32'h4, 4'hf);
[  296.038124] xhci_hcd 0000:03:00.0: op reg status = 00000008
[  296.038127] xhci_hcd 0000:03:00.0: ir set irq_pending = 00000003
[  296.038130] xhci_hcd 0000:03:00.0: Event ring dequeue ptr:
[  296.038134] xhci_hcd 0000:03:00.0: @cf4395b0 cf46e4d0 00000000 01000000 01048001
[  296.038139] xhci_hcd 0000:03:00.0: `MEM_WRITE_DWORD(3'b000, 32'hffffc900058ac024, 32'h8, 4'hf);
[  296.038145] xhci_hcd 0000:03:00.0: `MEM_WRITE_DWORD(3'b000, 32'hffffc900058ac620, 32'h3, 4'hf);
[  296.038151] xhci_hcd 0000:03:00.0: In xhci_handle_event
[  296.038154] xhci_hcd 0000:03:00.0: xhci_handle_event - OS owns TRB
[  296.038157] xhci_hcd 0000:03:00.0: xhci_handle_event - calling handle_tx_event
[  296.038160] xhci_hcd 0000:03:00.0: In handle_tx_event
[  296.038163] xhci_hcd 0000:03:00.0: handle_tx_event - ep index = 3
[  296.038166] xhci_hcd 0000:03:00.0: handle_tx_event - checking for list empty
[  296.038169] xhci_hcd 0000:03:00.0: handle_tx_event - getting list entry
[  296.038172] xhci_hcd 0000:03:00.0: handle_tx_event - looking for TD
[  296.038176] xhci_hcd 0000:03:00.0: handle_tx_event - found event_seg = ffff880225d66c40
[  296.038179] xhci_hcd 0000:03:00.0: Event TRB with TRB type ID 32
[  296.038182] xhci_hcd 0000:03:00.0: Offset 0x00 (buffer lo) = 0xcf46e4d0
[  296.038186] xhci_hcd 0000:03:00.0: Offset 0x04 (buffer hi) = 0x0
[  296.038189] xhci_hcd 0000:03:00.0: Offset 0x08 (transfer length) = 0x1000000
[  296.038192] xhci_hcd 0000:03:00.0: Offset 0x0C (flags) = 0x1048001
[  296.038195] xhci_hcd 0000:03:00.0: Successful bulk transfer!
[  296.038198] usb 10-2: ep 0x2 - asked for 31 bytes, 0 bytes untransferred
[  296.038202] xhci_hcd 0000:03:00.0: Ring deq = 0xcf46e4e0 (DMA)
[  296.038205] xhci_hcd 0000:03:00.0: Event ring deq = 0xcf4395c0 (DMA)
[  296.038212] xhci_hcd 0000:03:00.0: // Write event ring dequeue pointer, preserving EHB bit
[  296.038215] xhci_hcd 0000:03:00.0: `MEM_WRITE_DWORD(3'b000, 64'hffffc900058ac638, 64'hcf4395c0, 4'hf);
[  296.038220] xhci_hcd 0000:03:00.0: Giveback URB ffff8801fe851b40, len = 31, status = 0
[  296.038225] xhci_hcd 0000:03:00.0: xhci_handle_event - returned from handle_tx_event
[  296.038229] xhci_hcd 0000:03:00.0: In xhci_handle_event
[  296.038235] xhci_hcd 0000:03:00.0: `MEM_WRITE_DWORD(3'b000, 64'hffffc900058ac638, 64'hcf4395c8, 4'hf);
[  296.038245] usb-storage: Status code 0; transferred 31/31
[  296.038247] usb-storage: -- transfer complete
[  296.038250] usb-storage: Bulk command transfer result=0
[  296.038253] usb-storage: usb_stor_bulk_transfer_sglist: xfer 96 bytes, 1 entries
[  296.038258] xhci_hcd 0000:03:00.0: count sg list trbs: 
[  296.038263] xhci_hcd 0000:03:00.0:  sg #0: dma = 0x23bc6000, len = 0x60 (96), num_trbs = 1
[  296.038266] xhci_hcd 0000:03:00.0: 
[  296.038269] usb 10-2: ep 0x81 - urb len = 96, sglist used, num_trbs = 1
[  296.038272] xhci_hcd 0000:03:00.0: Endpoint state = 0x1
[  296.038275] xhci_hcd 0000:03:00.0: First length to xfer from 1st sglist entry = 96
[  296.038280] xhci_hcd 0000:03:00.0:  sg entry: dma = 0x23bc6000, len = 0x60 (96), 64KB boundary at 0x23bd0000, end dma = 0x23bc6060
[  296.038284] xhci_hcd 0000:03:00.0: Ring enq = 0xcf46e170 (DMA)
[  296.038289] xhci_hcd 0000:03:00.0: `MEM_WRITE_DWORD(3'b000, 32'hffffc900058ac804, 32'h3, 4'hf);
[  296.038312] xhci_hcd 0000:03:00.0: op reg status = 00000008
[  296.038315] xhci_hcd 0000:03:00.0: ir set irq_pending = 00000003
[  296.038318] xhci_hcd 0000:03:00.0: Event ring dequeue ptr:
[  296.038322] xhci_hcd 0000:03:00.0: @cf4395c0 cf46e160 00000000 01000000 01038001
[  296.038327] xhci_hcd 0000:03:00.0: `MEM_WRITE_DWORD(3'b000, 32'hffffc900058ac024, 32'h8, 4'hf);
[  296.038333] xhci_hcd 0000:03:00.0: `MEM_WRITE_DWORD(3'b000, 32'hffffc900058ac620, 32'h3, 4'hf);
[  296.038338] xhci_hcd 0000:03:00.0: In xhci_handle_event
[  296.038341] xhci_hcd 0000:03:00.0: xhci_handle_event - OS owns TRB
[  296.038344] xhci_hcd 0000:03:00.0: xhci_handle_event - calling handle_tx_event
[  296.038348] xhci_hcd 0000:03:00.0: In handle_tx_event
[  296.038351] xhci_hcd 0000:03:00.0: handle_tx_event - ep index = 2
[  296.038354] xhci_hcd 0000:03:00.0: handle_tx_event - checking for list empty
[  296.038357] xhci_hcd 0000:03:00.0: handle_tx_event - getting list entry
[  296.038360] xhci_hcd 0000:03:00.0: handle_tx_event - looking for TD
[  296.038363] xhci_hcd 0000:03:00.0: handle_tx_event - found event_seg = ffff880225d66e00
[  296.038367] xhci_hcd 0000:03:00.0: Event TRB with TRB type ID 32
[  296.038370] xhci_hcd 0000:03:00.0: Offset 0x00 (buffer lo) = 0xcf46e160
[  296.038373] xhci_hcd 0000:03:00.0: Offset 0x04 (buffer hi) = 0x0
[  296.038376] xhci_hcd 0000:03:00.0: Offset 0x08 (transfer length) = 0x1000000
[  296.038379] xhci_hcd 0000:03:00.0: Offset 0x0C (flags) = 0x1038001
[  296.038382] xhci_hcd 0000:03:00.0: Successful bulk transfer!
[  296.038386] usb 10-2: ep 0x81 - asked for 96 bytes, 0 bytes untransferred
[  296.038389] xhci_hcd 0000:03:00.0: Ring deq = 0xcf46e170 (DMA)
[  296.038392] xhci_hcd 0000:03:00.0: Event ring deq = 0xcf4395d0 (DMA)
[  296.038399] xhci_hcd 0000:03:00.0: // Write event ring dequeue pointer, preserving EHB bit
[  296.038403] xhci_hcd 0000:03:00.0: `MEM_WRITE_DWORD(3'b000, 64'hffffc900058ac638, 64'hcf4395d0, 4'hf);
[  296.038407] xhci_hcd 0000:03:00.0: Giveback URB ffff8801ed927000, len = 96, status = 0
[  296.038412] xhci_hcd 0000:03:00.0: xhci_handle_event - returned from handle_tx_event
[  296.038415] xhci_hcd 0000:03:00.0: In xhci_handle_event
[  296.038422] xhci_hcd 0000:03:00.0: `MEM_WRITE_DWORD(3'b000, 64'hffffc900058ac638, 64'hcf4395d8, 4'hf);
[  296.038431] usb-storage: Status code 0; transferred 96/96
[  296.038433] usb-storage: -- transfer complete
[  296.038436] usb-storage: Bulk data transfer result 0x0
[  296.038438] usb-storage: Attempting to get CSW...
[  296.038441] usb-storage: usb_stor_bulk_transfer_buf: xfer 13 bytes
[  296.038445] usb 10-2: ep 0x81 - urb len = 0xd (13), addr = 0xcf4c7000, num_trbs = 1
[  296.038449] xhci_hcd 0000:03:00.0: Endpoint state = 0x1
[  296.038452] xhci_hcd 0000:03:00.0: Ring enq = 0xcf46e180 (DMA)
[  296.038461] xhci_hcd 0000:03:00.0: `MEM_WRITE_DWORD(3'b000, 32'hffffc900058ac804, 32'h3, 4'hf);
[  296.038508] xhci_hcd 0000:03:00.0: op reg status = 00000008
[  296.038511] xhci_hcd 0000:03:00.0: ir set irq_pending = 00000003
[  296.038513] xhci_hcd 0000:03:00.0: Event ring dequeue ptr:
[  296.038517] xhci_hcd 0000:03:00.0: @cf4395d0 cf46e170 00000000 01000000 01038001
[  296.038523] xhci_hcd 0000:03:00.0: `MEM_WRITE_DWORD(3'b000, 32'hffffc900058ac024, 32'h8, 4'hf);
[  296.038528] xhci_hcd 0000:03:00.0: `MEM_WRITE_DWORD(3'b000, 32'hffffc900058ac620, 32'h3, 4'hf);
[  296.038534] xhci_hcd 0000:03:00.0: In xhci_handle_event
[  296.038537] xhci_hcd 0000:03:00.0: xhci_handle_event - OS owns TRB
[  296.038540] xhci_hcd 0000:03:00.0: xhci_handle_event - calling handle_tx_event
[  296.038543] xhci_hcd 0000:03:00.0: In handle_tx_event
[  296.038546] xhci_hcd 0000:03:00.0: handle_tx_event - ep index = 2
[  296.038549] xhci_hcd 0000:03:00.0: handle_tx_event - checking for list empty
[  296.038552] xhci_hcd 0000:03:00.0: handle_tx_event - getting list entry
[  296.038555] xhci_hcd 0000:03:00.0: handle_tx_event - looking for TD
[  296.038559] xhci_hcd 0000:03:00.0: handle_tx_event - found event_seg = ffff880225d66e00
[  296.038562] xhci_hcd 0000:03:00.0: Event TRB with TRB type ID 32
[  296.038565] xhci_hcd 0000:03:00.0: Offset 0x00 (buffer lo) = 0xcf46e170
[  296.038568] xhci_hcd 0000:03:00.0: Offset 0x04 (buffer hi) = 0x0
[  296.038571] xhci_hcd 0000:03:00.0: Offset 0x08 (transfer length) = 0x1000000
[  296.038575] xhci_hcd 0000:03:00.0: Offset 0x0C (flags) = 0x1038001
[  296.038578] xhci_hcd 0000:03:00.0: Successful bulk transfer!
[  296.038581] usb 10-2: ep 0x81 - asked for 13 bytes, 0 bytes untransferred
[  296.038584] xhci_hcd 0000:03:00.0: Ring deq = 0xcf46e180 (DMA)
[  296.038588] xhci_hcd 0000:03:00.0: Event ring deq = 0xcf4395e0 (DMA)
[  296.038594] xhci_hcd 0000:03:00.0: // Write event ring dequeue pointer, preserving EHB bit
[  296.038598] xhci_hcd 0000:03:00.0: `MEM_WRITE_DWORD(3'b000, 64'hffffc900058ac638, 64'hcf4395e0, 4'hf);
[  296.038602] xhci_hcd 0000:03:00.0: Giveback URB ffff8801fe851b40, len = 13, status = 0
[  296.038607] xhci_hcd 0000:03:00.0: xhci_handle_event - returned from handle_tx_event
[  296.038610] xhci_hcd 0000:03:00.0: In xhci_handle_event
[  296.038617] xhci_hcd 0000:03:00.0: `MEM_WRITE_DWORD(3'b000, 64'hffffc900058ac638, 64'hcf4395e8, 4'hf);
[  296.038625] usb-storage: Status code 0; transferred 13/13
[  296.038627] usb-storage: -- transfer complete
[  296.038630] usb-storage: Bulk status result = 0
[  296.038633] usb-storage: Bulk Status S 0x53425355 T 0x104 R 0 Stat 0x0
[  296.038636] usb-storage: -- Result from auto-sense is 0
[  296.038639] usb-storage: -- code: 0x72, key: 0x0, ASC: 0x0, ASCQ: 0x1
[  296.038642] usb-storage: No Sense: Filemark detected
[  296.038646] usb-storage: scsi cmd done, result=0x2
[  296.038650] usb-storage: *** thread sleeping.
[  296.040100] usb-storage: queuecommand called
[  296.040139] usb-storage: *** thread awakened.
[  296.040143] usb-storage: Command READ_10 (10 bytes)
[  296.040145] usb-storage:  28 00 00 00 00 00 00 00 08 00
[  296.040156] usb-storage: Bulk Command S 0x43425355 T 0x105 L 4096 F 128 Trg 0 LUN 0 CL 10
[  296.040159] usb-storage: usb_stor_bulk_transfer_buf: xfer 31 bytes
[  296.040165] usb 10-2: ep 0x2 - urb len = 0x1f (31), addr = 0xcf4c7000, num_trbs = 1
[  296.040168] xhci_hcd 0000:03:00.0: Endpoint state = 0x1
[  296.040172] xhci_hcd 0000:03:00.0: Ring enq = 0xcf46e4f0 (DMA)
[  296.040178] xhci_hcd 0000:03:00.0: `MEM_WRITE_DWORD(3'b000, 32'hffffc900058ac804, 32'h4, 4'hf);
[  296.040201] xhci_hcd 0000:03:00.0: op reg status = 00000008
[  296.040204] xhci_hcd 0000:03:00.0: ir set irq_pending = 00000003
[  296.040207] xhci_hcd 0000:03:00.0: Event ring dequeue ptr:
[  296.040211] xhci_hcd 0000:03:00.0: @cf4395e0 cf46e4e0 00000000 01000000 01048001
[  296.040216] xhci_hcd 0000:03:00.0: `MEM_WRITE_DWORD(3'b000, 32'hffffc900058ac024, 32'h8, 4'hf);
[  296.040222] xhci_hcd 0000:03:00.0: `MEM_WRITE_DWORD(3'b000, 32'hffffc900058ac620, 32'h3, 4'hf);
[  296.040228] xhci_hcd 0000:03:00.0: In xhci_handle_event
[  296.040231] xhci_hcd 0000:03:00.0: xhci_handle_event - OS owns TRB
[  296.040234] xhci_hcd 0000:03:00.0: xhci_handle_event - calling handle_tx_event
[  296.040237] xhci_hcd 0000:03:00.0: In handle_tx_event
[  296.040240] xhci_hcd 0000:03:00.0: handle_tx_event - ep index = 3
[  296.040243] xhci_hcd 0000:03:00.0: handle_tx_event - checking for list empty
[  296.040246] xhci_hcd 0000:03:00.0: handle_tx_event - getting list entry
[  296.040249] xhci_hcd 0000:03:00.0: handle_tx_event - looking for TD
[  296.040253] xhci_hcd 0000:03:00.0: handle_tx_event - found event_seg = ffff880225d66c40
[  296.040256] xhci_hcd 0000:03:00.0: Event TRB with TRB type ID 32
[  296.040259] xhci_hcd 0000:03:00.0: Offset 0x00 (buffer lo) = 0xcf46e4e0
[  296.040262] xhci_hcd 0000:03:00.0: Offset 0x04 (buffer hi) = 0x0
[  296.040266] xhci_hcd 0000:03:00.0: Offset 0x08 (transfer length) = 0x1000000
[  296.040269] xhci_hcd 0000:03:00.0: Offset 0x0C (flags) = 0x1048001
[  296.040272] xhci_hcd 0000:03:00.0: Successful bulk transfer!
[  296.040275] usb 10-2: ep 0x2 - asked for 31 bytes, 0 bytes untransferred
[  296.040279] xhci_hcd 0000:03:00.0: Ring deq = 0xcf46e4f0 (DMA)
[  296.040282] xhci_hcd 0000:03:00.0: Event ring deq = 0xcf4395f0 (DMA)
[  296.040288] xhci_hcd 0000:03:00.0: // Write event ring dequeue pointer, preserving EHB bit
[  296.040292] xhci_hcd 0000:03:00.0: `MEM_WRITE_DWORD(3'b000, 64'hffffc900058ac638, 64'hcf4395f0, 4'hf);
[  296.040297] xhci_hcd 0000:03:00.0: Giveback URB ffff8801fe851b40, len = 31, status = 0
[  296.040302] xhci_hcd 0000:03:00.0: xhci_handle_event - returned from handle_tx_event
[  296.040306] xhci_hcd 0000:03:00.0: In xhci_handle_event
[  296.040312] xhci_hcd 0000:03:00.0: `MEM_WRITE_DWORD(3'b000, 64'hffffc900058ac638, 64'hcf4395f8, 4'hf);
[  296.040322] usb-storage: Status code 0; transferred 31/31
[  296.040324] usb-storage: -- transfer complete
[  296.040326] usb-storage: Bulk command transfer result=0
[  296.040330] usb-storage: usb_stor_bulk_transfer_sglist: xfer 4096 bytes, 1 entries
[  296.040335] xhci_hcd 0000:03:00.0: count sg list trbs: 
[  296.040339] xhci_hcd 0000:03:00.0:  sg #0: dma = 0x23bc6800, len = 0x1000 (4096), num_trbs = 1
[  296.040343] xhci_hcd 0000:03:00.0: 
[  296.040346] usb 10-2: ep 0x81 - urb len = 4096, sglist used, num_trbs = 1
[  296.040349] xhci_hcd 0000:03:00.0: Endpoint state = 0x1
[  296.040352] xhci_hcd 0000:03:00.0: First length to xfer from 1st sglist entry = 4096
[  296.040357] xhci_hcd 0000:03:00.0:  sg entry: dma = 0x23bc6800, len = 0x1000 (4096), 64KB boundary at 0x23bd0000, end dma = 0x23bc7800
[  296.040361] xhci_hcd 0000:03:00.0: Ring enq = 0xcf46e190 (DMA)
[  296.040367] xhci_hcd 0000:03:00.0: `MEM_WRITE_DWORD(3'b000, 32'hffffc900058ac804, 32'h3, 4'hf);
[  296.047358] xhci_hcd 0000:03:00.0: op reg status = 00000008
[  296.047362] xhci_hcd 0000:03:00.0: ir set irq_pending = 00000003
[  296.047364] xhci_hcd 0000:03:00.0: Event ring dequeue ptr:
[  296.047368] xhci_hcd 0000:03:00.0: @cf4395f0 cf46e180 00000000 01000000 01038001
[  296.047374] xhci_hcd 0000:03:00.0: `MEM_WRITE_DWORD(3'b000, 32'hffffc900058ac024, 32'h8, 4'hf);
[  296.047380] xhci_hcd 0000:03:00.0: `MEM_WRITE_DWORD(3'b000, 32'hffffc900058ac620, 32'h3, 4'hf);
[  296.047385] xhci_hcd 0000:03:00.0: In xhci_handle_event
[  296.047388] xhci_hcd 0000:03:00.0: xhci_handle_event - OS owns TRB
[  296.047391] xhci_hcd 0000:03:00.0: xhci_handle_event - calling handle_tx_event
[  296.047394] xhci_hcd 0000:03:00.0: In handle_tx_event
[  296.047397] xhci_hcd 0000:03:00.0: handle_tx_event - ep index = 2
[  296.047400] xhci_hcd 0000:03:00.0: handle_tx_event - checking for list empty
[  296.047404] xhci_hcd 0000:03:00.0: handle_tx_event - getting list entry
[  296.047407] xhci_hcd 0000:03:00.0: handle_tx_event - looking for TD
[  296.047410] xhci_hcd 0000:03:00.0: handle_tx_event - found event_seg = ffff880225d66e00
[  296.047414] xhci_hcd 0000:03:00.0: Event TRB with TRB type ID 32
[  296.047417] xhci_hcd 0000:03:00.0: Offset 0x00 (buffer lo) = 0xcf46e180
[  296.047420] xhci_hcd 0000:03:00.0: Offset 0x04 (buffer hi) = 0x0
[  296.047423] xhci_hcd 0000:03:00.0: Offset 0x08 (transfer length) = 0x1000000
[  296.047426] xhci_hcd 0000:03:00.0: Offset 0x0C (flags) = 0x1038001
[  296.047429] xhci_hcd 0000:03:00.0: Successful bulk transfer!
[  296.047433] usb 10-2: ep 0x81 - asked for 4096 bytes, 0 bytes untransferred
[  296.047436] xhci_hcd 0000:03:00.0: Ring deq = 0xcf46e190 (DMA)
[  296.047440] xhci_hcd 0000:03:00.0: Event ring deq = 0xcf439600 (DMA)
[  296.047446] xhci_hcd 0000:03:00.0: // Write event ring dequeue pointer, preserving EHB bit
[  296.047450] xhci_hcd 0000:03:00.0: `MEM_WRITE_DWORD(3'b000, 64'hffffc900058ac638, 64'hcf439600, 4'hf);
[  296.047454] xhci_hcd 0000:03:00.0: Giveback URB ffff8801ed927000, len = 4096, status = 0
[  296.047460] xhci_hcd 0000:03:00.0: xhci_handle_event - returned from handle_tx_event
[  296.047463] xhci_hcd 0000:03:00.0: In xhci_handle_event
[  296.047470] xhci_hcd 0000:03:00.0: `MEM_WRITE_DWORD(3'b000, 64'hffffc900058ac638, 64'hcf439608, 4'hf);
[  296.047482] usb-storage: Status code 0; transferred 4096/4096
[  296.047484] usb-storage: -- transfer complete
[  296.047486] usb-storage: Bulk data transfer result 0x0
[  296.047489] usb-storage: Attempting to get CSW...
[  296.047491] usb-storage: usb_stor_bulk_transfer_buf: xfer 13 bytes
[  296.047496] usb 10-2: ep 0x81 - urb len = 0xd (13), addr = 0xcf4c7000, num_trbs = 1
[  296.047500] xhci_hcd 0000:03:00.0: Endpoint state = 0x1
[  296.047503] xhci_hcd 0000:03:00.0: Ring enq = 0xcf46e1a0 (DMA)
[  296.047508] xhci_hcd 0000:03:00.0: `MEM_WRITE_DWORD(3'b000, 32'hffffc900058ac804, 32'h3, 4'hf);
[  296.047532] xhci_hcd 0000:03:00.0: op reg status = 00000008
[  296.047535] xhci_hcd 0000:03:00.0: ir set irq_pending = 00000003
[  296.047538] xhci_hcd 0000:03:00.0: Event ring dequeue ptr:
[  296.047541] xhci_hcd 0000:03:00.0: @cf439600 cf46e190 00000000 01000000 01038001
[  296.047547] xhci_hcd 0000:03:00.0: `MEM_WRITE_DWORD(3'b000, 32'hffffc900058ac024, 32'h8, 4'hf);
[  296.047553] xhci_hcd 0000:03:00.0: `MEM_WRITE_DWORD(3'b000, 32'hffffc900058ac620, 32'h3, 4'hf);
[  296.047558] xhci_hcd 0000:03:00.0: In xhci_handle_event
[  296.047561] xhci_hcd 0000:03:00.0: xhci_handle_event - OS owns TRB
[  296.047564] xhci_hcd 0000:03:00.0: xhci_handle_event - calling handle_tx_event
[  296.047567] xhci_hcd 0000:03:00.0: In handle_tx_event
[  296.047570] xhci_hcd 0000:03:00.0: handle_tx_event - ep index = 2
[  296.047573] xhci_hcd 0000:03:00.0: handle_tx_event - checking for list empty
[  296.047576] xhci_hcd 0000:03:00.0: handle_tx_event - getting list entry
[  296.047579] xhci_hcd 0000:03:00.0: handle_tx_event - looking for TD
[  296.047583] xhci_hcd 0000:03:00.0: handle_tx_event - found event_seg = ffff880225d66e00
[  296.047586] xhci_hcd 0000:03:00.0: Event TRB with TRB type ID 32
[  296.047589] xhci_hcd 0000:03:00.0: Offset 0x00 (buffer lo) = 0xcf46e190
[  296.047592] xhci_hcd 0000:03:00.0: Offset 0x04 (buffer hi) = 0x0
[  296.047596] xhci_hcd 0000:03:00.0: Offset 0x08 (transfer length) = 0x1000000
[  296.047599] xhci_hcd 0000:03:00.0: Offset 0x0C (flags) = 0x1038001
[  296.047602] xhci_hcd 0000:03:00.0: Successful bulk transfer!
[  296.047605] usb 10-2: ep 0x81 - asked for 13 bytes, 0 bytes untransferred
[  296.047608] xhci_hcd 0000:03:00.0: Ring deq = 0xcf46e1a0 (DMA)
[  296.047611] xhci_hcd 0000:03:00.0: Event ring deq = 0xcf439610 (DMA)
[  296.047618] xhci_hcd 0000:03:00.0: // Write event ring dequeue pointer, preserving EHB bit
[  296.047622] xhci_hcd 0000:03:00.0: `MEM_WRITE_DWORD(3'b000, 64'hffffc900058ac638, 64'hcf439610, 4'hf);
[  296.047626] xhci_hcd 0000:03:00.0: Giveback URB ffff8801fe851b40, len = 13, status = 0
[  296.047631] xhci_hcd 0000:03:00.0: xhci_handle_event - returned from handle_tx_event
[  296.047634] xhci_hcd 0000:03:00.0: In xhci_handle_event
[  296.047641] xhci_hcd 0000:03:00.0: `MEM_WRITE_DWORD(3'b000, 64'hffffc900058ac638, 64'hcf439618, 4'hf);
[  296.047649] usb-storage: Status code 0; transferred 13/13
[  296.047651] usb-storage: -- transfer complete
[  296.047654] usb-storage: Bulk status result = 0
[  296.047657] usb-storage: Bulk Status S 0x53425355 T 0x105 R 0 Stat 0x0
[  296.047660] usb-storage: scsi cmd done, result=0x0
[  296.047663] usb-storage: *** thread sleeping.

..

I'm not entirely sure _what_ you were tracing here, but it appears that the ATA IDENTIFY DEVICE command (0xec) succeeded in both instances, USB2 and USB3.

Mark Lord
Real-Time Remedies Inc.
[email protected]

I would still like to see a usbmon trace of hdparm under USB-2.

Alan Stern

hdparm through USB-2:

/dev/sdb:

outgoing cdb:  85 08 2e 00 00 00 01 00 00 00 00 00 00 40 ec 00
data:  00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
SG_IO: ATA_16 status=0x0, host_status=0x0, driver_status=0x0
SG_IO: bad response (not CHECK_CONDITION)
Trying legacy HDIO_DRIVE_CMD
outgoing cdb:  85 08 2e 00 00 00 01 00 00 00 00 00 00 40 a1 00
data:  40 00 ff 3f 37 c8 10 00 00 00 00 00 3f 00 00 00
SG_IO: ATA_16 status=0x2, host_status=0x0, driver_status=0x8
SG_IO: sb[]:  72 0b 00 00 00 00 00 0e 09 0c 00 04 00 01 00 00 00 00 00 

00 40 51 00 00 00 00 00 00 00 00 00 00
SG_IO: desc[]: 09 0c 00 04 00 01 00 00 00 00 00 00
ATA_16 statQ err nsect
lbal lbam lbah dev@
I/O error, ata_op=0xa1 ata_status=0x51 ata_error=0x04
HDIO_DRIVE_CMD(identify) failed: Input/output error

  readonly      =  0 (off)
  readahead     = 256 (on)
  geometry      = 121601/255/63, sectors = 1953525168, start = 0

ffff8801f8199540 602153163 S Bo:1:003:2 -115 31 = 55534243 d4000000 00020000 80001085 082e0000 00010000 00000000 40ec00 ffff8801f8199540 602153314 C Bo:1:003:2 0 31 >
ffff8801f8184d80 602153376 S Bi:1:003:1 -115 512 < ffff8801f8184d80 602159046 C Bi:1:003:1 0 512 = 00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000 ffff8801f8199540 602159103 S Bi:1:003:1 -115 13 < ffff8801f8199540 602159156 C Bi:1:003:1 0 13 = 55534253 d4000000 00000000 00 ffff8801f8199540 602159382 S Bo:1:003:2 -115 31 = 55534243 d5000000 00020000 80001085 082e0000 00010000 00000000 40a100 ffff8801f8199540 602159536 C Bo:1:003:2 0 31 >
ffff8801f8184d80 602159594 S Bi:1:003:1 -115 512 < ffff8801f8184d80 602159791 C Bi:1:003:1 -32 0
ffff8801f8199540 602159846 S Co:1:003:0 s 02 01 0000 0081 0000 0 ffff8801f8199540 602159900 C Co:1:003:0 0 0
ffff8801f8199540 602159951 S Bi:1:003:1 -115 13 < ffff8801f8199540 602160029 C Bi:1:003:1 0 13 = 55534253 d5000000 00020000 01 ffff8801f8199540 602160100 S Bo:1:003:2 -115 31 = 55534243 d6000000 60000000 80000603 00000060 00000000 00000000 000000 ffff8801f8199540 602160159 C Bo:1:003:2 0 31 >
ffff8801f8184d80 602160201 S Bi:1:003:1 -115 96 < ffff8801f8184d80 602160276 C Bi:1:003:1 0 96 = 00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000 ffff8801f8199540 602160334 S Bi:1:003:1 -115 13 < ffff8801f8199540 602160418 C Bi:1:003:1 0 13 = 55534253 d6000000 00000000 00 ffff8801f8199540 602161915 S Bo:1:003:2 -115 31 = 55534243 d7000000 00100000 80000a28 00000000 00000008 00000000 000000 ffff8801f8199540 602162023 C Bo:1:003:2 0 31 >
ffff8801f8184d80 602162080 S Bi:1:003:1 -115 4096 < ffff8801f8184d80 602162284 C Bi:1:003:1 0 4096 = 00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000 ffff8801f8199540 602162344 S Bi:1:003:1 -115 13 < ffff8801f8199540 602162405 C Bi:1:003:1 0 13 = 55534253 d7000000 00000000 00

and hdparm through UBS-3:

/dev/sdb:

outgoing cdb:  85 08 2e 00 00 00 01 00 00 00 00 00 00 40 ec 00
data:  00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
SG_IO: ATA_16 status=0x0, host_status=0x0, driver_status=0x0
SG_IO: bad response (not CHECK_CONDITION)
Trying legacy HDIO_DRIVE_CMD
outgoing cdb:  85 08 2e 00 00 00 01 00 00 00 00 00 00 40 a1 00
data:  40 00 ff 3f 37 c8 10 00 00 00 00 00 3f 00 00 00
SG_IO: ATA_16 status=0x2, host_status=0x0, driver_status=0x8
SG_IO: sb[]:  72 0b 00 00 00 00 00 0e 09 0c 00 04 00 01 00 00 00 00 00 

00 40 51 00 00 00 00 00 00 00 00 00 00
SG_IO: desc[]: 09 0c 00 04 00 01 00 00 00 00 00 00
ATA_16 statQ err nsect
lbal lbam lbah dev@
I/O error, ata_op=0xa1 ata_status=0x51 ata_error=0x04
HDIO_DRIVE_CMD(identify) failed: Input/output error

  readonly      =  0 (off)
  readahead     = 256 (on)
  geometry      = 121601/255/63, sectors = 1953525168, start = 0

ffff8801f810c6c0 734453214 S Bo:10:002:2 -115 31 = 55534243 c4000000 00020000 80001085 082e0000 00010000 00000000 40ec00 ffff8801f810c6c0 734453421 C Bo:10:002:2 0 31 > ffff8801f810c9c0 734453512 S Bi:10:002:1 -115 512 < ffff8801f810c9c0 734459225 C Bi:10:002:1 0 512 Z ffff8801f810c6c0 734459316 S Bi:10:002:1 -115 13 < ffff8801f810c6c0 734459485 C Bi:10:002:1 0 13 = 55534253 c4000000 00000000 00
ffff8801f810c6c0 734459861 S Bo:10:002:2 -115 31 = 55534243 c5000000 00020000 80001085 082e0000 00010000 00000000 40a100 ffff8801f810c6c0 734460033 C Bo:10:002:2 0 31 > ffff8801f810c9c0 734460121 S Bi:10:002:1 -115 512 < ffff8801f810c9c0 734460395 C Bi:10:002:1 -32 0 ffff8801f810c6c0 734460482 S Co:10:002:0 s 02 01 0000 0081 0000 0 ffff8801f810c6c0 734460885 C Co:10:002:0 0 0 ffff8801f810c6c0 734461026 S Bi:10:002:1 -115 13 < ffff8801f810c6c0 734461270 C Bi:10:002:1 0 13 = 55534253 c5000000 00020000 01
ffff8801f810c6c0 734461371 S Bo:10:002:2 -115 31 = 55534243 c6000000 60000000 80000603 00000060 00000000 00000000 000000 ffff8801f810c6c0 734461560 C Bo:10:002:2 0 31 > ffff8801f810c9c0 734461649 S Bi:10:002:1 -115 96 < ffff8801f810c9c0 734461814 C Bi:10:002:1 0 96 Z ffff8801f810c6c0 734461904 S Bi:10:002:1 -115 13 < ffff8801f810c6c0 734462066 C Bi:10:002:1 0 13 = 55534253 c6000000 00000000 00
ffff8801f810c6c0 734463922 S Bo:10:002:2 -115 31 = 55534243 c7000000 00100000 80000a28 00000000 00000008 00000000 000000 ffff8801f810c6c0 734464100 C Bo:10:002:2 0 31 > ffff8801f810c9c0 734464187 S Bi:10:002:1 -115 4096 < ffff8801f810c9c0 734476632 C Bi:10:002:1 0 4096 Z ffff8801f810c6c0 734476724 S Bi:10:002:1 -115 13 < ffff8801f810c6c0 734476913 C Bi:10:002:1 0 13 = 55534253 c7000000 00000000 00

Hope this helps,
-Jonas

Hmm. I'm not sure I believe this data. For a while (starting with 2.6.33) the usbmon implementation didn't work right with EHCI -- it looked in the transfer buffer before the DMA-unmapping was done, so on a system with >= 4 GB of memory it wouldn't always see the data. The fix for this was merged only within the last week or so.

Can you repeat the USB-2.0 test but this time doing "rmmod ehci-hcd" beforehand?

Alan Stern

I could not remove that module (I assume it is compiled into the kernel) so I limited the memory the kernel can see to 1GB. You were right, now there is actually useful data in the trace. Here it is:

ffff88001bb82840 685088867 S Bo:1:003:2 -115 31 = 55534243 c9000000 00020000 80001085 082e0000 00010000 00000000 40ec00 ffff88001bb82840 685088982 C Bo:1:003:2 0 31 >
ffff88001bbc3d80 685089045 S Bi:1:003:1 -115 512 < ffff88001bbc3d80 685094708 C Bi:1:003:1 0 512 = 4000ff3f 37c81000 00000000 3f000000 00000000 32534d35 394a5a30 30313237 ffff88001bb82840 685094763 S Bi:1:003:1 -115 13 < ffff88001bb82840 685094814 C Bi:1:003:1 0 13 = 55534253 c9000000 00000000 00 ffff88001bb82840 685095024 S Bo:1:003:2 -115 31 = 55534243 ca000000 00020000 80001085 082e0000 00010000 00000000 40a100 ffff88001bb82840 685095207 C Bo:1:003:2 0 31 >
ffff88001bbc3d80 685095260 S Bi:1:003:1 -115 512 < ffff88001bbc3d80 685095457 C Bi:1:003:1 -32 0
ffff88001bb82840 685095509 S Co:1:003:0 s 02 01 0000 0081 0000 0 ffff88001bb82840 685095561 C Co:1:003:0 0 0
ffff88001bb82840 685095614 S Bi:1:003:1 -115 13 < ffff88001bb82840 685095699 C Bi:1:003:1 0 13 = 55534253 ca000000 00020000 01 ffff88001bb82840 685095768 S Bo:1:003:2 -115 31 = 55534243 cb000000 60000000 80000603 00000060 00000000 00000000 000000 ffff88001bb82840 685095817 C Bo:1:003:2 0 31 >
ffff88001bbc3d80 685095885 S Bi:1:003:1 -115 96 < ffff88001bbc3d80 685096082 C Bi:1:003:1 0 96 = 720b0000 0000000e 090c0004 00010000 00000000 40510000 00000000 00000000 ffff88001bb82840 685096136 S Bi:1:003:1 -115 13 < ffff88001bb82840 685096207 C Bi:1:003:1 0 13 = 55534253 cb000000 00000000 00 ffff88001bb82840 685097822 S Bo:1:003:2 -115 31 = 55534243 cc000000 00100000 80000a28 00000000 00000008 00000000 000000 ffff88001bb82840 685097947 C Bo:1:003:2 0 31 >
ffff880010e52a80 685098002 S Bi:1:003:1 -115 4096 < ffff880010e52a80 685106944 C Bi:1:003:1 0 4096 = fab80010 8ed0bc00 b0b80000 8ed88ec0 fbbe007c bf0006b9 0002f3a4 ea210600 ffff88001bb82840 685106999 S Bi:1:003:1 -115 13 < ffff88001bb82840 685107075 C Bi:1:003:1 0 13 = 55534253 cc000000 00000000 00

-Jonas

Great! This is just what we need.

That's an IDENTIFY DEVICE command being sent to the device, corresponding to the start of the hdparm debugging log:

	outgoing cdb:  85 08 2e 00 00 00 01 00 00 00 00 00 00 40 ec 00

These are the first 32 bytes of the reply. (If necessary we could get all 512 bytes.) But at this point the hdparm debugging log says:

	data:  00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00

That certainly seems strange. The reply data should be there.

And the status value is 0, indicating no problems. Nevertheless, hdparm reported:

	SG_IO: ATA_16 status=0x0, host_status=0x0, driver_status=0x0
	SG_IO: bad response (not CHECK_CONDITION)

Presumably this is because it saw all 0's instead of the actual data. Apart from that, it is what one would expect.

This is an IDENTIFY PACKET DEVICE command, corresponding to the next two lines in the hdparm log:

	Trying legacy HDIO_DRIVE_CMD
	outgoing cdb:  85 08 2e 00 00 00 01 00 00 00 00 00 00 40 a1 00

The device sends back no data, a Residue value of 512, and Check Condition status.

This is the REQUEST SENSE command automatically generated by the usb-storage driver.

And these are the first 32 sense data bytes. Here's what hdparm had to say:

	data:  40 00 ff 3f 37 c8 10 00 00 00 00 00 3f 00 00 00
	SG_IO: ATA_16 status=0x2, host_status=0x0, driver_status=0x8
	SG_IO: sb[]:  72 0b 00 00 00 00 00 0e 09 0c 00 04 00 01 00 00 00 00 00 
	00 40 51 00 00 00 00 00 00 00 00 00 00
	SG_IO: desc[]:  09 0c 00 04 00 01 00 00 00 00 00 00
	       ATA_16 statQ err nsect
 lbal lbam lbah dev@
	I/O error, ata_op=0xa1 ata_status=0x51 ata_error=0x04

Notice that the "data" line contains the data from the previous command! The status and sense buffer ("sb") values appear correct.

That's the status from the REQUEST SENSE.

This is a READ(10) command, asking for 8 blocks of data starting at block 0.

And that's the start of the first block of data. It looks normal enough.

So overall, something is messing up with regard to the data coming back from the device. hdparm sees the data for the first command as being the response to the second command. It could be a problem in the kernel or a problem in hdparm.

No doubt hdparm is easier to check up on. Mark, could this be some sort of simple programming error?

Alan Stern

..

The "data:" dump from "hdparm --verbose" shows the _outgoing_data buffer from just prior to command issue. In this case, that buffer is on the stack. So yes, it will often show data from the previous command,
and never from the current command.

I really ought to beef up --verbose to show the data in both directions. :)

But it is a good clue, as it shows that the data probably did make it all the way back to hdparm.

The sticky part is that hdparm explicitly asked for sense data.

But the results were marked as "no sense data". Many of the commands sent by hdparm _require_ "sense data" (ATA register values) in order to see the results. The USB driver appears to ignore that request when it sees good device status from the original command. Bug.

For "identify", we could work around that in hdparm,
but other commands would still be broken by the lack of sense data.

Cheers

Mark Lord
Real-Time Remedies Inc.
[email protected]

Mark,
Not sure if this bug got out into the wild but it
sounds close to what you are describing:

     https://bugzilla.kernel.org/show_bug.cgi?id185

Doug Gilbert

..

I don't think that is the exact issue here.
But can you send me the patch that is referred to in that bugzilla entry?

I've been noticing issues with the DSM TRIM command in newer kernels, and I wonder if this might have something to do with that.

Cheers

Mark Lord
Real-Time Remedies Inc.
[email protected]

..

Okay, I found the patch/commit, and my 2.6.32.5 kernel was missing it. Pulling down the latest 2.6.32.* tree now to see if it ever made it there.

But that patch is for libata, which is not on the pathway for this USB3 issue.

Cheers

Mark Lord
Real-Time Remedies Inc.
[email protected]

This sounds like it is a bug in the SCSI midlayer, not in usb-storage.

There is no mechanism for the midlayer to tell low-level drivers like usb-storage that sense data must be returned. The documentation in include/scsi/scsi_cmnd.h merely states that the sense buffer should be filled when CHECK CONDITION is received for the original command. Ditto for Documentation/scsi/scsi_mid_low_api.txt. Hence if sense data is needed even in the absence of CHECK CONDITION, the midlayer must explicitly send a command to retrieve it.

What mechanism does hdparm use to submit its I/O requests, and how does it indicate that it requires sense data?

Alan Stern

I don't think so ... we'll return sense if sense is present (i.e. the device returned CHECK CONDITION).

Sense data is never returned in the absence of CHECK CONDITION. This is what SAT says has to happen if you set CK_COND in ATA(12/16):

The CK_COND (Check Condition) bit may be used to request the SATL to
return a copy of ATA register information in the sense data upon command completion. If the CK_COND bit is set to one the SATL shall
return a status of CHECK CONDITION when the ATA command completes,
even if the command completes successfully, and return the ATA Normal Output fields (see ATA8-ACS) in the sense data using the ATA Return descriptor (see 12.2.6). If the CK_COND bit is set to zero, then the SATL shall terminate the command with CHECK CONDITION status only if an error occurs in processing the command. See clause 11 for a description of ATA error conditions.

James

That's right. Since the command in question did have CK_COND set, the device should have returned CHECK CONDITION status instead of GOOD status.

Therefore this indicates a bug in the device, not in the kernel. hdparm could work around it here by issuing an explicit REQUEST SENSE command, but in general it will cause trouble.

Alan Stern

On 12/05/10 02:48 PM, Alan Stern wrote:
..

..

I wonder if perhaps usb-storage could honour the flag when the device doesn't ?

Mark Lord
Real-Time Remedies Inc.
[email protected]

It could, but I'm not sure it would end up working right. That is, usb-storage could go ahead and ask for the sense data, but the data values returned by the device might not all be set correctly.

The easiest way to find out is to make a version of hdparm which does an explicit REQUEST SENSE, and then see if the end result is acceptable.

Alan Stern

The Sector Count field in the ATA PASS-THROUGH (12) or (16) CDB should be set appropriately by the Application Client as the neither the SAT bridge nor the SATA transport will interpret the ATA Command byte. Thus, for IDENTIFY (PACKET) DEVICE the Application Client should set it to 1.

Luben

Why do you say that 1 is the appropriate value? In the ATA-5 spec (which is the most recent version I have) Sector Count is listed as "na" for IDENTIFY DEVICE, which means that the content of that field is not applicable to this particular command. Hence the value shouldn't matter.

Alan Stern

Application clients should send ATA PASS-THROUGH (16) and never the 12 byte version to ATAPI devices behind a SAT bridge, whose opcode is interpreted as BLANK (as pointed out by Doug), and BLANK executed.

Luben

..

That's a nice self-proclamation.
Got a pointer to a SAT or ATA/SATA standard that says it for real?

The problem with that statement (above), becomes.. what to use for the initial IDENTIFY request, before the type of device is known?

Cheers

Mark Lord
Real-Time Remedies Inc.
[email protected]

I'm afraid it's just part of the usual standards confusion. I think what they were thinking is that no-one would use SATL with ATAPI ... although I bet someone will ...

But this isn't a userspace problem. By the time we present the device to userspace, we already know what it is ... so you can go by device type and only use ATA_12 for disk devices.

For kernel space, we never use the encapsulation commands anyway, we always go by the transport.

James

..

Did you instead mean to say "use ATA_12 for non-disk devices" ?

Mark Lord
Real-Time Remedies Inc.
[email protected]

No ... ATA_12 is opcode 0xa1 which is BLANK to MMC devices, hence we should only use it for non-mmc devices. However, the point I was making is that actually only disk devices should use ATA. ATAPI is really SCSI encapsulation over ATA, so it doesn't really make sense to send ATA over SCSI encapsulation to ATAPI devices, we should just send plain SCSI (crosses fingers and hopes MMC devices never do smart).

James

On 21/04/10 10:04 AM, James Bottomley wrote:
..

..

And most tools / programs can indeed do that.

But hdparm's mission is to ignore what the kernel thinks, and speak directly to the drive whenever possible.

Because hdparm is an important part of how we verify that the kernel is correct (or not). So I very much prefer that it continue to work out the details as much as it can without asking a possibly buggy kernel for help.

:)

That said.. what would you recommend as a way for a userspace program to figure out whether to use ATA_12 or ATA_16 to talk to a given arbitrary device name ?

I guess the info is in sysfs somewhere.

Thanks

Mark Lord
Real-Time Remedies Inc.
[email protected]

This is a bit dangerous where USB is concerned. We certainly don't have all the heuristics necessary in the kernel, but whenever anything goes wrong, we do tend to hear about it pretty quickly.

To be honest, no. For USB, All USB is SCSI or RBC command based. You don't have any idea whether it's a real SCSI device or an ATA device behind a SAT ... the only reason you assume it's ATA is because USB gadget builders tend to be cheapskates.

Only for direct interconnects. For USB most bets are off.

James

You can find out whether the device might be MMC by sending an ordinary SCSI INQUIRY command. (Or you can get the device type from the "modalias" attribute file in the device's sysfs directory, which just shows the information the kernel got when _it_ sent an INQUIRY command.) If it might be MMC, _don't_ try to use ATA_12!

The interpretation of the commands sent from hdparm is done by the device's bridge chip. In theory these chips can apply different translations depending on whether the attached drive is ATA or ATAPI. I don't know if any existing bridge chips behave this way, though -- and either way, I don't know how a program can figure out what type the drive is. Especially since the bridge chip isn't obliged to understand SAT in the first place.

Alan Stern

[Mark Lord wrote]

Some firmwares start behaving irregularly if they get INQUIRY in an order that the firmware author did not expect. (I.e. not as the very first request.) Hence use the kernel's inquiry data from sysfs whenever possible, instead of an own INQUIRY.

Stefan Richter
-===-=-=- -=-- =-=-
http://arcgraph.de/sr/

Picking up an earlier point, SCSI opcode A1h is both:
- BLANK (for optical devices: CD/DVD/BD)
- ATA PASS THROUGH (12) (for disks [both normal (SBC) and RBC])

Only SCSI primary commands (SPC) have a 1 to 1 mapping with an opcode (ignoring service actions). So debug code in the kernel can be slightly misleading when trying to decode a SCSI command opcode that is not a "primary" command.

Doug Gilbert

Actually, that's not a valid standard ... it's unratified. I know SCSI tends to follow leading edge (i.e. unratified) standards, but most SAT implementations have been following trailing edge ones ... in fact, very few people have been claiming even SAT (as opposed to SAT-2) compliance, so they more use it as a guideline.

If you want to read the doc, you have to get it from google using this search string:

+"SCSI / ATA Translation (SAT)" +"revision 09"

And you'll find that citeseer still has the pdf.

but like I said, most people treat it as advisory not mandatory.

James

I'm not sure why Alan is having problems downloading that document. To quote http://www.t10.org/drafts.htm :

"Non-T10 members will not be permitted to download
working drafts for standards that have been approved."

And since SAT-2 has not yet been approved then you just get a challenge screen asking who you are. It accepts "linux" in all its fields (or anything else you like) and then lets you download the draft.

That may change soon because SAT-2 is queued for approval with INCITS. Not to worry, the SAT-3 project has been approved but the first draft has not yet been posted. Technical work has started on SAT-3 (e.g. there are approved changes from the last month's t10 meeting).

Don't tell INCITS but existing t10 practice is that rev 0 of the following series (e.g. sat3r0.pdf) is often the same as ...

Doug Gilbert

Yes, I did try it with Mark's latest version (9.29b) which uses a sector count of "1" (version 9.29) and, in addition, uses ATA_12 (instead of ATA_16) for IDENTIFY (9.29b). The issue exists in Karmic and Lucid.

It seems the report I sent back to Mark, once I tested 9.29b, didn't go to all of you but just Mark. Here it is:

--------------------------------------------------------
The good news: It doesn't crash the chip anymore. The drive is still mounted fine after executing hdparm.

The bad news: From the hdparm output it seems like the chip still doesn't play nice.

/dev/sdb:

outgoing cdb:  a1 08 2e 00 01 00 00 00 40 ec 00 00 00 00 00 00
data:  00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
SG_IO: ATA_12 status=0x0, host_status=0x0, driver_status=0x0
SG_IO: bad response (not CHECK_CONDITION)
Trying legacy HDIO_DRIVE_CMD
outgoing cdb:  a1 08 2e 00 01 00 00 00 40 a1 00 00 00 00 00 00
data:  40 00 ff 3f 37 c8 10 00 00 00 00 00 3f 00 00 00
SG_IO: ATA_12 status=0x2, host_status=0x0, driver_status=0x8
SG_IO: sb[]:  72 0b 00 00 00 00 00 0e 09 0c 00 04 00 01 00 00 00 00 00 

00 40 51 00 00 00 00 00 00 00 00 00 00
SG_IO: desc[]: 09 0c 00 04 00 01 00 00 00 00 00 00
ATA_12 statQ err nsect
lbal lbam lbah dev@
I/O error, ata_op=0xa1 ata_status=0x51 ata_error=0x04
HDIO_DRIVE_CMD(identify) failed: Input/output error

  readonly      =  0 (off)
  readahead     = 256 (on)
  geometry      = 121601/255/63, sectors = 1953525168, start = 0

--------------------------------------------------------

I didn't get a reply from Mark on this yet. Alan, does this output mean something to you?

-Jonas

Not a lot, just that there are no more USB-level problems. Any remaining problems are higher up, at the SCSI level or hdparm application level.

Alan Stern

But there were two separate issues for two separate USB3 hard drives. Didn't your Buffalo drive need the ATA_12 IDENTIFY with the sector count set to zero? And hard drives with the Genesys drive needed the sector count set to 1?

Your original log showed something issuing an ATA_12 IDENTIFY command:

Mar 24 18:51:29 js-workstation kernel: [  126.720576] usb-storage: Command BLANK (12 bytes)
Mar 24 18:51:29 js-workstation kernel: [  126.720577] usb-storage:  a1 08 2e 00 01 00 00 00 00 ec 00 00
Mar 24 18:51:29 js-workstation kernel: [  126.720584] usb-storage: Bulk Command S 0x43425355 T 0x2d L 512 F 128 Trg 0 LUN 0 CL 12

(It says command BLANK but Douglas Gilbert said it was actually an ATA_12 command).

But the original output you posted from hdparm doesn't list that ATA_12 command:

sudo hdparm --verbose /dev/sdb

/dev/sdb:

outgoing cdb:  85 08 2e 00 00 00 00 00 00 00 00 00 00 40 ec 00 
SG_IO: ATA_16 status=0x0, host_status=0x7, driver_status=0x0
SG_IO: bad response (not CHECK_CONDITION) 
outgoing cdb:  85 08 2e 00 00 00 00 00 00 00 00 00 00 40 a1 00 
SG_IO: ATA_16 status=0x0, host_status=0x7, driver_status=0x0
SG_IO: bad response (not CHECK_CONDITION) 
 HDIO_DRIVE_CMD(identify) failed: Invalid exchange
 readonly      =  0 (off)
 readahead     = 256 (on)
 geometry      = 36365/64/32, sectors = 0, start = 0

Maybe it was issued by another userspace program? The kernel log doesn't show what the device response was, but it could be that the device actually checks the sector count of the command. Can you change the hdparam code to issue the ATA_12 command, but leave the sector count as zero?

Sarah Sharp

The xhci-hcd driver in 2.6.32 doesn't support configured device reset, but it was added in 2.6.33. So an update to a later kernel should allow the device to work in USB 3.0 mode.

Sarah Sharp

(Keeping as much as the thread since I've just added Lennart to the Cc)

As I said above, I don't think it's ata_id that is the problem - I think it's udisks-probe-ata-smart, via libatasmart, that is responsible for submitting the SET FEATURES command:

http://git.0pointer.de/?p=libatasmart.git;a=blob;f=atasmart.c;h¤b60c0eedf8e4f1ebafd932b7070c030459ef16;hb=HEAD#l2561

when it finds out that the SMART feature is available, yet not turned on. I actually don't think libatasmart has any business making such decisions on behalf of the user... Lennart, any chance we can stop libatasmart from doing this? Thanks.

Uh. I think it definitely needs to call this. I am pretty sure most USB HDDs you plug in have SMART disabled by default until libatasmart enables it. So, libatasmart would stop enabling it automatically you'd end up with no SMART at all for these devices.

Also, on my desktop here, when you reset the BIOS settings to the defaults, SMART is off. So, that means that somebody needs to enable SMART from Linux, and who should do that if not libatasmart?

if that device chokes on SETFEATURES then we might need to blacklist that, not disabled SMART for all devices right-away...

Lennart

Lennart Poettering                        Red Hat, Inc.
lennart [at] poettering [dot] net
http://0pointer.net/lennart/           GnuPG 0x1A015CC4

Actually, libatasmart does not even call SET_FEATURES. We only issue four types of commands:

IDENTIFY_DEVICE
IDENTIFY_PACKET_DEVICE
SMART
CHECK_POWER_MODE

the sources don't know about any other commands:

http://git.0pointer.de/?p=libatasmart.git;a=blob;f=atasmart.c;h¤b60c0eedf8e4f1ebafd932b7070c030459ef16;hb=HEAD#l128

So the SET_FEATURES must come from somewhere else...

Lennart

Lennart Poettering                        Red Hat, Inc.
lennart [at] poettering [dot] net
http://0pointer.net/lennart/           GnuPG 0x1A015CC4

Depends. If it's safe to enable SMART when available, sure, let's go for it. If it's not safe, we can prompt the user that SMART monitoring is available yet turned off. Much the same way we currently prompt the user when the disk is failing

http://people.freedesktop.org/~david/smart-fail-1.png

It wouldn't be much work to do this.

David

Actually, reading the source again and speaking to Lennart, I don't think libatasmart submits a SET FEATURES command. (libatasmart might be responsible for the 16-byte IDENTIFY command though)

Thanks,
David

I discovered this about two weeks ago an up-to-date Ubuntu 9.10 distro, then upgraded to 10.04 where it still existed. In order to get USB debug information I compiled my own kernel (once based off of the Ubuntu 10.04 sources and once based off of the 2.6.32.9 stable sources from kernel.org). I very much doubt that this issue does not exist on the latest 10.04 daily build.

-Jonas

On Apr 21, 2010, at 6:52, Mark Lord <[email protected]> wrote:

On 21/04/10 08:47 AM, Luben Tuikov wrote:
starts at line 8816. (It says the
command
is a BLANK command, but it's incorrectly
identified that command.)

Application clients should send ATA PASS-THROUGH (16) and never the 12 byte version to ATAPI devices behind a SAT bridge, whose opcode is interpreted as BLANK (as pointed out by Doug), and BLANK executed. ..

That's a nice self-proclamation.
Got a pointer to a SAT or ATA/SATA standard that says it for real?

If you think this is a "self-proclamation" and want a spec to spell it out, then go ahead and send ATA PT 12 to ATAPI devices behind a SAT bridge. Just make sure there is no RW media in the device. :-)

The problem with that statement (above), becomes.. what to use for the initial IDENTIFY request, before the type of device is known?

The statement above tells you: use ATA PT 16.

Luben

On Apr 21, 2010, at 7:31, Alan Stern <[email protected]> wrote:

On Wed, 21 Apr 2010, Luben Tuikov wrote:

The real problem with the Buffalo drive is that it responds with a
phase error when it receives an ATA_16 IDENTIFY DEVICE command with the
Sector Count field set to 0.

The Sector Count field in the ATA PASS-THROUGH (12) or (16) CDB should be set appropriately by the Application Client as the neither the SAT bridge nor the SATA transport will interpret the ATA Command byte. Thus, for IDENTIFY (PACKET) DEVICE the Application Client should set it to 1.

Why do you say that 1 is the appropriate value? In the ATA-5 spec (which is the most recent version I have) Sector Count is listed as "na" for IDENTIFY DEVICE, which means that the content of that field is not applicable to this particular command. Hence the value shouldn't matter.

It is needed by the transport protocol(s).

Luben

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

I don't understand; can you explain more fully? Which transport protocol(s) need to use the Sector Count? The USB transport protocol doesn't; it encodes the transfer length in a wrapper. The bridge chip should interpret the wrapper instead of looking inside the SAT command.

Alan Stern

I'm guessing Doug is out today because he didn't forward the note below. Just passing the info along...

Alan> I don't understand; can you explain more fully? Which transport Alan> protocol(s) need to use the Sector Count? The USB transport Alan> protocol doesn't; it encodes the transfer length in a wrapper. Alan> The bridge chip should interpret the wrapper instead of looking Alan> inside the SAT command.

Doug posted to the T10 list and here's what Jim Hatfield from Seagate responded:

For ATA (SATA or PATA), the Count field should NEVER be zero, because neither interface supports zero-length data transfer for any protocol (dma, pio, etc).

In ATA, 'N/A' is defined the way it is because there are some ancient implementations for which there are vendor specific differences.

Martin K. Petersen	Oracle Linux Engineering

So, if Jim is correct, then this may not be a bug in the Buffalo device? Or is the phase error in the status of the CSW still an incorrect response after a stall on what the device thinks is an invalid command?

Sarah Sharp

Sarah, _please_ forget about the stall! It's just not relevant.

Yes, a phase error is an incorrect response to an invalid command. A correct response would be to return Check Condition status together with sense data indicating: ILLEGAL REQUEST, Invalid field in CDB.

It's possible the bridge chip might not realize the command is invalid and would try to carry it out. If it did so and encountered some kind of unrecoverable internal error as a result, then a phase error would be the correct response.

Alan Stern

On Apr 21, 2010, at 9:09, Alan Stern <[email protected]> wrote:

On Wed, 21 Apr 2010, Luben Tuikov wrote:

The Sector Count field in the ATA PASS-THROUGH (12) or (16) CDB should be set appropriately by the Application Client as the neither the SAT bridge nor the SATA transport will interpret the ATA Command byte. Thus, for IDENTIFY (PACKET) DEVICE the Application Client should set it to 1.

Why do you say that 1 is the appropriate value? In the ATA-5 spec (which is the most recent version I have) Sector Count is listed as "na" for IDENTIFY DEVICE, which means that the content of that field is not applicable to this particular command. Hence the value shouldn't matter.

It is needed by the transport protocol(s).

I don't understand; can you explain more fully? Which transport protocol(s) need to use the Sector Count? The USB transport protocol doesn't; it encodes the transfer length in a wrapper. The bridge chip should interpret the wrapper instead of looking inside the SAT command.

Well BOT is the exception. In general transports aren't concerned with the size, etc of the command. They just transport the CDB. UAS for example, being in SAM-spirit transport and in this sense being mature over BOT.

The transfer length is part of the CDB, if the command is expected to transfer data and ATA PT CDBs are no exception. The transport bridge would "convert" from one transport protocol into another and it thus need to know the transfer size if any to prep the next protocol for the command. In this case this is visualized as UAS(SCSI)<-->SATA(ATA). Use BOT, wlg.

This is really the function of SAT. Unknown CDBs are treated as bi-directional to let the target determine data transfer direction if any.

Luben

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

This is somewhat off-topic, but perhaps you can help. In reading through the UAS draft specification, I didn't see any description of how disagreements over transfer lengths should be handled. Suppose the initiator thinks the CDB for a particular IN command asks for N bytes, but the target thinks the CDB asks for M bytes. What should happen if N < M or N > M? And likewise for OUT commands.

Alan Stern

Ping? Any luck reproducing the hang on 2.6.31 stable? I tried with a different unpartitioned USB 3.0 hard drive (SIIG 2.5" drive) on 2.6.31.12, but I didn't find any issues.

Sarah Sharp
--
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

I just compiled 2.6.31.12 and couldn't reproduce the hang. The behavior seems the same as in 2.6.32. I have to note though, that due to the update from Ubuntu Karmic (which used a 2.6.31 kernel) to Ubuntu Lucid a great deal of my system changed. Specifically, userspace programs will differ for sure. Unfortunately I don't have another USB 3.0 host system lying around with Karmic installed.

-Jonas
--
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