XHCI issues: WD MyBook 1230 - reset SuperSpeed USB device

It's now clear that this is _not_ an XHCI issue, contrary to what=20
$SUBJECT says.

Alan,
=20
I am attaching the usbmon trace after the drive has been plugged into=

=20

the USB-2 port. Record of the drive in stall should occur around the=20
file offset 87808 (decimal). The log was done on the 3.12.7 kernel=20
without CONFIG_PM. Should I do a usbmon trace on my regular kernel wi=

th=20

CONFIG_PM as well?

No need.

=20
usb 4-1.2: new high-speed USB device number 5 using ehci-pci
usb 4-1.2: New USB device found, idVendor=3D1058, idProduct=3D1230
usb 4-1.2: New USB device strings: Mfr=3D2, Product=3D3, SerialNumber=

=3D1

usb 4-1.2: Product: My Book 1230
usb 4-1.2: Manufacturer: Western Digital
usb 4-1.2: SerialNumber: 574D43344E30323438393836
usb-storage 4-1.2:1.0: USB Mass Storage device detected
scsi6 : usb-storage 4-1.2:1.0
usbcore: registered new interface driver usb-storage
scsi 6:0:0:0: Direct-Access WD My Book 1230 1050 PQ: 0 =

ANSI: 6

scsi 6:0:0:1: Enclosure WD SES Device 1050 PQ: 0 =

ANSI: 6

sd 6:0:0:0: Attached scsi generic sg2 type 0
scsi 6:0:0:1: Attached scsi generic sg3 type 13
sd 6:0:0:0: [sdb] Spinning up disk...
.........ready
sd 6:0:0:0: [sdb] 732558336 4096-byte logical blocks: (3.00 TB/2.72 T=

iB)

sd 6:0:0:0: [sdb] Write Protect is off
sd 6:0:0:0: [sdb] Mode Sense: 53 00 10 08
sd 6:0:0:0: [sdb] No Caching mode page found
sd 6:0:0:0: [sdb] Assuming drive cache: write through
sd 6:0:0:0: [sdb] 732558336 4096-byte logical blocks: (3.00 TB/2.72 T=

iB)

sd 6:0:0:0: [sdb] No Caching mode page found
sd 6:0:0:0: [sdb] Assuming drive cache: write through
sdb: sdb1
sd 6:0:0:0: [sdb] 732558336 4096-byte logical blocks: (3.00 TB/2.72 T=

iB)

sd 6:0:0:0: [sdb] No Caching mode page found
sd 6:0:0:0: [sdb] Assuming drive cache: write through
sd 6:0:0:0: [sdb] Attached SCSI disk
usb 4-1.2: reset high-speed USB device number 5 using ehci-pci

It looks like the reset occurred because the computer sent an
ATA-passthru command to the disk, and the disk wasn't prepared to
handle it properly. The firmware crashed, requiring a reset.

If anyone can explain, the command bytes in question were:

85082e00 00000000 00000000 0000ec00

and the sense data was:

7201001d 0000000e 090c0000 00005d00 01000000 0050

I don't know what either of these means, or even what software was
responsible for sending this command. It appears to have come from
some user program, though, not the kernel. Possibly something run by=20
udev.

Alan Stern

--
To unsubscribe from this list: send the line "unsubscribe linux-scsi" i=
n
the body of a message to ***@vger.kernel.org
More majordomo info at http://vger.kernel.org/majordomo-info.html

Hannes Reinecke

2014-01-17 07:35:33 UTC

Post by Alan Stern
It's now clear that this is _not_ an XHCI issue, contrary to what=20
$SUBJECT says.
=20
=20

Alan,
I am attaching the usbmon trace after the drive has been plugged int=

o=20

the USB-2 port. Record of the drive in stall should occur around the=

=20

file offset 87808 (decimal). The log was done on the 3.12.7 kernel=20
without CONFIG_PM. Should I do a usbmon trace on my regular kernel w=

ith=20

CONFIG_PM as well?

=20
No need.
=20

usb 4-1.2: new high-speed USB device number 5 using ehci-pci
usb 4-1.2: New USB device found, idVendor=3D1058, idProduct=3D1230
usb 4-1.2: New USB device strings: Mfr=3D2, Product=3D3, SerialNumbe=

r=3D1

ANSI: 6

scsi 6:0:0:1: Enclosure WD SES Device 1050 PQ: 0=

ANSI: 6

TiB)

TiB)

sd 6:0:0:0: [sdb] No Caching mode page found
sd 6:0:0:0: [sdb] Assuming drive cache: write through
sdb: sdb1
sd 6:0:0:0: [sdb] 732558336 4096-byte logical blocks: (3.00 TB/2.72 =

TiB)

sd 6:0:0:0: [sdb] No Caching mode page found
sd 6:0:0:0: [sdb] Assuming drive cache: write through
sd 6:0:0:0: [sdb] Attached SCSI disk
usb 4-1.2: reset high-speed USB device number 5 using ehci-pci

=20
It looks like the reset occurred because the computer sent an
ATA-passthru command to the disk, and the disk wasn't prepared to
handle it properly. The firmware crashed, requiring a reset.
=20
=20
85082e00 00000000 00000000 0000ec00
=20
=20
7201001d 0000000e 090c0000 00005d00 01000000 0050
=20
I don't know what either of these means, or even what software was
responsible for sending this command. It appears to have come from
some user program, though, not the kernel. Possibly something run by=

=20

Post by Alan Stern
udev.
=20

Probably smartd.
The logic there is _less_ than perfect.
Try to disable smartd and check if the issue remains.

Cheers,

Hannes
--=20
Dr. Hannes Reinecke zSeries & Storage
***@suse.de +49 911 74053 688
SUSE LINUX Products GmbH, Maxfeldstr. 5, 90409 N=C3=BCrnberg
GF: J. Hawn, J. Guild, F. Imend=C3=B6rffer, HRB 16746 (AG N=C3=BCrnberg=
)
--
To unsubscribe from this list: send the line "unsubscribe linux-scsi" i=
n
the body of a message to ***@vger.kernel.org
More majordomo info at http://vger.kernel.org/majordomo-info.html

Douglas Gilbert

2014-01-17 20:25:30 UTC

Post by Alan Stern
It's now clear that this is _not_ an XHCI issue, contrary to what
$SUBJECT says.

Alan,
I am attaching the usbmon trace after the drive has been plugged in=

the USB-2 port. Record of the drive in stall should occur around th=

file offset 87808 (decimal). The log was done on the 3.12.7 kernel
without CONFIG_PM. Should I do a usbmon trace on my regular kernel =

with

CONFIG_PM as well?

No need.

usb 4-1.2: new high-speed USB device number 5 using ehci-pci
usb 4-1.2: New USB device found, idVendor=3D1058, idProduct=3D1230
usb 4-1.2: New USB device strings: Mfr=3D2, Product=3D3, SerialNumb=

er=3D1

0 ANSI: 6

scsi 6:0:0:1: Enclosure WD SES Device 1050 PQ: =

0 ANSI: 6

TiB)

TiB)

sd 6:0:0:0: [sdb] No Caching mode page found
sd 6:0:0:0: [sdb] Assuming drive cache: write through
sdb: sdb1
sd 6:0:0:0: [sdb] 732558336 4096-byte logical blocks: (3.00 TB/2.72=

TiB)

sd 6:0:0:0: [sdb] No Caching mode page found
sd 6:0:0:0: [sdb] Assuming drive cache: write through
sd 6:0:0:0: [sdb] Attached SCSI disk
usb 4-1.2: reset high-speed USB device number 5 using ehci-pci

SCSI ATA PASS-THROUGH(16) command issuing the
mandatory ATA command 0xec which is IDENTIFY DEVICE.
[See SAT-3 drafts for more information on the pass-through
command.]

Post by Alan Stern
7201001d 0000000e 090c0000 00005d00 01000000 0050

ATA spec says there should not (normally) be an error issued
by that command; but there was:

$ sg_decode_sense -n 7201001d 0000000e 090c0000 00005d00 01000000 0050
Descriptor format, current; Sense key: Recovered Error
Additional sense: ATA pass through information available
Descriptor type: ATA Status Return
extend=3D0 error=3D0x0 sector_count=3D0x0
lba=3D0x000000
device=3D0x0 status=3D0x50

Looks reasonable at the SCSI level, not sure about the
ATA level, perhaps others can comment.

Post by Alan Stern
I don't know what either of these means, or even what software was
responsible for sending this command. It appears to have come from
some user program, though, not the kernel. Possibly something run b=

Post by Alan Stern
udev.

Probably smartd.
The logic there is _less_ than perfect.

Guilty as charged. Silly us, fancy smartmontools issuing
mandatory ATA commands over a USB transport (MSC ?) and
expecting the device to be well-behaved :-)

Post by Hannes Reinecke
Try to disable smartd and check if the issue remains.

Probably will help. Throwing away all your USB storage
devices (apart from those that do UAS(P)) would be even
more helpful (to us).

Perhaps smartmontools could do a better job of identifying
USB connected storage devices and avoid them.

Doug Gilbert
[a smartmontools maintainer]

--
To unsubscribe from this list: send the line "unsubscribe linux-usb" in
the body of a message to majordomo-***@public.gmane.org
More majordomo info at http://vger.kernel.org/majordomo-info.html

Peter Palúch

2014-01-17 21:14:57 UTC

Gentlemen,

=46irst of all, thank you very much for looking into this issue.

Alan, for the sake of keeping the thread tidy in archives, I am not=20
going to change the $SUBJECT of this e-mail but I wholeheartedly agree=20
that this is not an xHCI issue. Mea culpa; I did not know that at the=20
time I first reported it.

Douglas, Hannes: I believe we are definitely on to something. I do _not=
_=20
run smartd but this may be caused by something in my Gnome3 GUI=20
environment. I have noticed that when I am not logged in to Gnome and=20
work just in the text console, plugging in the USB drive and accessing=20
it works without any issues. Only when I am logged into my Gnome and=20
plug the drive in, Gnome obviously tries to do something with the drive=
=20
that causes it to stall and recover in 30 seconds. I have not yet been=20
able to identify what it is.

I am not subscribed to linux-scsi mailing list so if you believe=20
anything of this is relevant please forward that mail there.

Thank you!

Best regards,
Peter

Post by Alan Stern
It's now clear that this is _not_ an XHCI issue, contrary to what
$SUBJECT says.

Alan,
I am attaching the usbmon trace after the drive has been plugged i=

nto

the USB-2 port. Record of the drive in stall should occur around t=

file offset 87808 (decimal). The log was done on the 3.12.7 kernel
without CONFIG_PM. Should I do a usbmon trace on my regular kernel=

=20

with
CONFIG_PM as well?

No need.

usb 4-1.2: new high-speed USB device number 5 using ehci-pci
usb 4-1.2: New USB device found, idVendor=3D1058, idProduct=3D1230
usb 4-1.2: New USB device strings: Mfr=3D2, Product=3D3, SerialNum=

ber=3D1

I: 6

2=20

TiB)
sd 6:0:0:0: [sdb] Write Protect is off
sd 6:0:0:0: [sdb] Mode Sense: 53 00 10 08
sd 6:0:0:0: [sdb] No Caching mode page found
sd 6:0:0:0: [sdb] Assuming drive cache: write through
sd 6:0:0:0: [sdb] 732558336 4096-byte logical blocks: (3.00 TB/2.7=

2=20

TiB)
sd 6:0:0:0: [sdb] No Caching mode page found
sd 6:0:0:0: [sdb] Assuming drive cache: write through
sdb: sdb1
sd 6:0:0:0: [sdb] 732558336 4096-byte logical blocks: (3.00 TB/2.7=

2=20

TiB)
sd 6:0:0:0: [sdb] No Caching mode page found
sd 6:0:0:0: [sdb] Assuming drive cache: write through
sd 6:0:0:0: [sdb] Attached SCSI disk
usb 4-1.2: reset high-speed USB device number 5 using ehci-pci

SCSI ATA PASS-THROUGH(16) command issuing the
mandatory ATA command 0xec which is IDENTIFY DEVICE.
[See SAT-3 drafts for more information on the pass-through
command.]

Post by Alan Stern
7201001d 0000000e 090c0000 00005d00 01000000 0050

ATA spec says there should not (normally) be an error issued
$ sg_decode_sense -n 7201001d 0000000e 090c0000 00005d00 01000000 005=

Post by Douglas Gilbert
Descriptor format, current; Sense key: Recovered Error
Additional sense: ATA pass through information available
Descriptor type: ATA Status Return
extend=3D0 error=3D0x0 sector_count=3D0x0
lba=3D0x000000
device=3D0x0 status=3D0x50
Looks reasonable at the SCSI level, not sure about the
ATA level, perhaps others can comment.

Post by Alan Stern
udev.

Probably smartd.
The logic there is _less_ than perfect.

Guilty as charged. Silly us, fancy smartmontools issuing
mandatory ATA commands over a USB transport (MSC ?) and
expecting the device to be well-behaved :-)

Post by Hannes Reinecke
Try to disable smartd and check if the issue remains.

--=20
Ing. Peter Pal=C3=BAch, Ph.D.
CCIE R&S #23527, CCIP, CCAI, Cisco Designated VIP 2011-2014 LAN & WAN

Department of InfoCom Networks
=46aculty of Management Science and Informatics, University of Zilina
Univerzitn=C3=A1 8215/1, 010 26 =C5=BDilina, Slovakia

WWW: http://www.kis.fri.uniza.sk
Tel.: +421-41-513-4325, +421-905-164432

--
To unsubscribe from this list: send the line "unsubscribe linux-usb" in
the body of a message to majordomo-***@public.gmane.org
More majordomo info at http://vger.kernel.org/majordomo-info.html

Christian Franke

2014-01-18 14:12:31 UTC

Post by Peter Palúch
Gentlemen,
First of all, thank you very much for looking into this issue.
Alan, for the sake of keeping the thread tidy in archives, I am not=20
going to change the $SUBJECT of this e-mail but I wholeheartedly agre=

e=20

Post by Peter Palúch
that this is not an xHCI issue. Mea culpa; I did not know that at the=

=20

Post by Peter Palúch
time I first reported it.
Douglas, Hannes: I believe we are definitely on to something. I do=20
_not_ run smartd but this may be caused by something in my Gnome3 GUI=

=20

Post by Peter Palúch
environment. I have noticed that when I am not logged in to Gnome and=

=20

Post by Peter Palúch
work just in the text console, plugging in the USB drive and accessin=

g=20

Post by Peter Palúch
it works without any issues. Only when I am logged into my Gnome and=20
plug the drive in, Gnome obviously tries to do something with the=20
drive that causes it to stall and recover in 30 seconds. I have not=20
yet been able to identify what it is.

Gnome disk utility?

AFAIK it relies on libatasmart. The source code of libatasmart is=20
unrelated to smartmontools.

Post by Alan Stern
It looks like the reset occurred because the computer sent an
ATA-passthru command to the disk, and the disk wasn't prepared to
handle it properly. The firmware crashed, requiring a reset.
85082e00 00000000 00000000 0000ec00

SCSI ATA PASS-THROUGH(16) command issuing the
mandatory ATA command 0xec which is IDENTIFY DEVICE.
[See SAT-3 drafts for more information on the pass-through
command.]

The above command sets CK_COND bit (CDB[2] |=3D 0x20) to request ATA=20
return descriptor.

Smartmontools never set CK_COND for IDENTIFY DEVICE. It is only set if=20
ATA output reqister values are actually needed:

# smartctl -d sat -r ioctl -i -H /dev/sdd
=2E..
REPORT-IOCTL: Device=3D/dev/sdd Command=3DIDENTIFY DEVICE
Input: FR=3D...., SC=3D0x01, LL=3D...., LM=3D...., LH=3D...., DEV=3D.=
=2E.., CMD=3D0xec IN
[ata pass-through(16): 85 08 0e 00 00 00 01 00 00 00 00 00 00 00 ec 00 =
]
=2E..
REPORT-IOCTL: Device=3D/dev/sdd Command=3DSMART STATUS CHECK
Input: FR=3D0xda, SC=3D...., LL=3D...., LM=3D0x4f, LH=3D0xc2, DEV=3D.=
=2E.., CMD=3D0xb0
[ata pass-through(16): 85 06 2c 00 da 00 00 00 00 00 4f 00 c2 00 b0 00 =
]
=2E..

Post by Alan Stern
7201001d 0000000e 090c0000 00005d00 01000000 0050

ATA spec says there should not (normally) be an error issued
$ sg_decode_sense -n 7201001d 0000000e 090c0000 00005d00 01000000 00=

Returned ATA register values look reasonable but are not needed for ATA=
=20
IDENTIFY command.

Post by Douglas Gilbert
Doug Gilbert
[a smartmontools maintainer]

Christian Franke
[a smartmontools maintainer :-]

--
To unsubscribe from this list: send the line "unsubscribe linux-scsi" i=
n
the body of a message to ***@vger.kernel.org
More majordomo info at http://vger.kernel.org/majordomo-info.html

Peter Palúch

2014-01-18 15:02:28 UTC

Christian,

Post by Peter Palúch
Douglas, Hannes: I believe we are definitely on to something. I do
_not_ run smartd but this may be caused by something in my Gnome3 GUI
environment. I have noticed that when I am not logged in to Gnome and
work just in the text console, plugging in the USB drive and
accessing it works without any issues. Only when I am logged into my
Gnome and plug the drive in, Gnome obviously tries to do something
with the drive that causes it to stall and recover in 30 seconds. I
have not yet been able to identify what it is.

Gnome disk utility?
AFAIK it relies on libatasmart. The source code of libatasmart is
unrelated to smartmontools.

I am not intentionally starting or running any disk utility when
plugging the USB disk to my notebook. I am simply logged to Gnome3, have
my terminal window open, plug in the disk - and voila, I can be sure
that within 30 seconds, I get a dmesg log about the drive being reset,
without even calling the gdisk utility I've been using earlier (note -
no change of behavior here, it was just me trying to work with the drive
right after it was recognized, which obviously coincided with some Gnome
subsystem trying to lay its hands on the drive as well - perhaps the
automount, udisksd, or something else). I will try to find out what
exactly is fired up in Gnome when I plug in the drive, and will update
this thread as soon as I have something new.

Best regards,
Peter

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

Peter Palúch

2014-01-19 00:27:41 UTC

Gentlemen,

I believe I've found the root cause of the issue.

USB is absolutely not to blame in this case. Problems were caused by th=
e=20
udisksd daemon that sent ATA IDENTIFY DEVICE pass through command with=20
the SECTOR_COUNT field set to 0 (cdb[6] =3D 0). I first noticed it when=
I=20
compared the strace output from udiskd to the strace of smartctl and=20
sg_sat_identify - both these tools set the cdb[6] to 1. After correctin=
g=20
the udiskd sources in this aspect, the problem appears to be solved.

My sincere thanks to all of you - all your suggestions and comments=20
moved me in the right direction. I will report this issue to udiskd=20
maintainers along with the (trivial) patch.

Once again, thanks!

Best regards,
Peter

=20

Post by Peter Palúch
at the time I first reported it.
Douglas, Hannes: I believe we are definitely on to something. I do=20
_not_ run smartd but this may be caused by something in my Gnome3 GU=

I=20

Post by Peter Palúch
environment. I have noticed that when I am not logged in to Gnome an=

d=20

Post by Peter Palúch
work just in the text console, plugging in the USB drive and=20
accessing it works without any issues. Only when I am logged into my=

=20

Post by Peter Palúch
Gnome and plug the drive in, Gnome obviously tries to do something=20
with the drive that causes it to stall and recover in 30 seconds. I=20
have not yet been able to identify what it is.

Gnome disk utility?
AFAIK it relies on libatasmart. The source code of libatasmart is=20
unrelated to smartmontools.

SCSI ATA PASS-THROUGH(16) command issuing the
mandatory ATA command 0xec which is IDENTIFY DEVICE.
[See SAT-3 drafts for more information on the pass-through
command.]

The above command sets CK_COND bit (CDB[2] |=3D 0x20) to request ATA=20
return descriptor.
Smartmontools never set CK_COND for IDENTIFY DEVICE. It is only set i=

f=20

Post by Christian Franke
# smartctl -d sat -r ioctl -i -H /dev/sdd
...
REPORT-IOCTL: Device=3D/dev/sdd Command=3DIDENTIFY DEVICE
Input: FR=3D...., SC=3D0x01, LL=3D...., LM=3D...., LH=3D...., DEV=3D=

=2E...,=20

Post by Christian Franke
CMD=3D0xec IN
[ata pass-through(16): 85 08 0e 00 00 00 01 00 00 00 00 00 00 00 ec 0=

0 ]

Post by Christian Franke
...
REPORT-IOCTL: Device=3D/dev/sdd Command=3DSMART STATUS CHECK
Input: FR=3D0xda, SC=3D...., LL=3D...., LM=3D0x4f, LH=3D0xc2, DEV=3D=

=2E..., CMD=3D0xb0

Post by Christian Franke
[ata pass-through(16): 85 06 2c 00 da 00 00 00 00 00 4f 00 c2 00 b0 0=

0 ]

Post by Christian Franke
...

Post by Alan Stern
7201001d 0000000e 090c0000 00005d00 01000000 0050

ATA spec says there should not (normally) be an error issued
$ sg_decode_sense -n 7201001d 0000000e 090c0000 00005d00 01000000 0=

050

Returned ATA register values look reasonable but are not needed for=20
ATA IDENTIFY command.