Project

General

Profile

Actions

Bug #13843

open

USB errors: slot in wrong state: 19

Added by Stephan Althaus over 2 years ago. Updated about 1 month ago.

Status:
New
Priority:
Normal
Assignee:
-
Category:
driver - device drivers
Start date:
Due date:
% Done:

0%

Estimated time:
Difficulty:
Medium
Tags:
Gerrit CR:
External Bug:

Description

Hello!

Since a few weeks i get I/O errors "failed to read cluster"
when i read my SDCard with 2 different adapters. It worked fine last
year, i think january, too.

I checked the SDCard with badblocks on a linux with the same Adapter in
a USB2 port - all went ok.
I checked the SDCard on a different OI box with the same Adapter in
a USB3 port - all went ok.

I use a fuse for the exfat filesystem, but i think it is a USB driver
bug.

What can i do to get to the root cause ?

Any hints are welcome!

Stephan

This i got this morning when i did a copy:

/home1/home/steven/Documents/Pictures/Test/2021-05-31/DS306054.ARW: I/O error
/home1/home/steven/Documents/Pictures/Test/2021-05-31/DS306055.ARW: I/O error
cp: cannot access /media/sdcard/DCIM/103MSDCF/*

steven@dell6510:~$ dmesg

May 31, 2021 at 07:18:39 AM CEST
May 31 07:18:23 dell6510 xhci: [ID 617155 kern.info] NOTICE: xhci2: endpoint is in state 3
May 31 07:18:23 dell6510 mount.exfat-fus2691: [ID 251512 user.error] failed to read cluster 0xb7f8
May 31 07:18:23 dell6510 xhci: [ID 902155 kern.info] NOTICE: xhci2: xhci stop endpoint command (2)/slot (8) in wrong state: 19
May 31 07:18:23 dell6510 xhci: [ID 617155 kern.info] NOTICE: xhci2: endpoint is in state 3
May 31 07:18:23 dell6510 xhci: [ID 902155 kern.info] NOTICE: xhci2: xhci stop endpoint command (3)/slot (8) in wrong state: 19
May 31 07:18:23 dell6510 xhci: [ID 617155 kern.info] NOTICE: xhci2: endpoint is in state 3


Files

1.patch (844 Bytes) 1.patch Gary Mills, 2023-08-21 01:30 AM
2.patch (1.38 KB) 2.patch Gary Mills, 2023-08-21 01:31 AM

Related issues

Has duplicate illumos gate - Bug #14216: Problem with USB Duplicate

Actions
Actions #1

Updated by Stephan Althaus over 2 years ago

$ sudo prtconf -dD | grep -i xhci
pci1028,7b1 (pciex8086,a12f) [Intel Corporation 100 Series/C230 Series Chipset Family USB 3.0 xHCI Controller], instance #2 (driver name: xhci)
pci1028,7b1 (pciex8086,15db) [Intel Corporation JHL6340 Thunderbolt 3 USB 3.1 Controller (C step) [Alpine Ridge 2C 2016]] (driver name: xhci)

$ mdb -ke '::prtusb'
INDEX DRIVER INST NODE GEN VID.PID PRODUCT
1 xhci 2 pci1028,7b1 3.0 0000.0000 No Product String
2 hid 39 mouse 1.1 045e.0040 Microsoft 3-Button Mouse with IntelliEye(TM)
3 usb_mid 31 device 1.1 0bf8.100c FSC KBPC PX
4 hubd 18 hub 2.0 413c.2513 No Product String
5 usb_mid 32 device 2.0 8087.0a2b No Product String
6 hubd 19 hub 2.0 413c.2513 No Product String
7 usb_mid 33 device 1.1 0a5c.5832 5880
8 scsa2usb 24 storage 3.1 0781.cfca SDDR-409

Actions #2

Updated by Stephan Althaus over 2 years ago

$ mdb ke '::xhci_device'
<--
snip --->

SANDISK - SDDR-409
Port 21 | Slot 10 | # Endpoints 01
EP Type State Head Tail
0 CONTROL Running 0xdb 0xdb

Actions #3

Updated by Stephan Althaus over 2 years ago

$ mdb ke "::prtusb -v"
<-
snip -->
INDEX DRIVER INST NODE GEN VID.PID PRODUCT
8 scsa2usb 24 storage 3.1 0781.cfca SDDR-409

Device Descriptor {
bLength = 0x12
bDescriptorType = 0x1
bcdUSB = 0x310
bDeviceClass = 0
bDeviceSubClass = 0
bDeviceProtocol = 0
bMaxPacketSize0 = 0x9
idVendor = 0x781
idProduct = 0xcfca
bcdDevice = 0x3
iManufacturer = 0x3
iProduct = 0x4
iSerialNumber = 0x2
bNumConfigurations = 0x1
}
-- Active Config Index 0
Configuration Descriptor {
bLength = 0x9
bDescriptorType = 0x2
wTotalLength = 0x2c
bNumInterfaces = 0x1
bConfigurationValue = 0x1
iConfiguration = 0x0
bmAttributes = 0x80
bMaxPower = 0x70
}
Interface Descriptor {
bLength = 0x9
bDescriptorType = 0x4
bInterfaceNumber = 0x0
bAlternateSetting = 0x0
bNumEndpoints = 0x2
bInterfaceClass = 0x8
bInterfaceSubClass = 0x6
bInterfaceProtocol = 0x50
iInterface = 0x0
}
Endpoint Descriptor {
bLength = 0x7
bDescriptorType = 0x5
bEndpointAddress = 0x81
bmAttributes = 0x2
wMaxPacketSize = 0x400
bInterval = 0x0
}
SuperSpeed Endpoint Companion Descriptor {
bLength = 0x6
bDescriptorType = 0x30
bMaxBurst = 0x4
bmAttributes = 0x0
wBytesPerInterval = 0x0
}
Endpoint Descriptor {
bLength = 0x7
bDescriptorType = 0x5
bEndpointAddress = 0x2
bmAttributes = 0x2
wMaxPacketSize = 0x400
bInterval = 0x0
}
SuperSpeed Endpoint Companion Descriptor {
bLength = 0x6
bDescriptorType = 0x30
bMaxBurst = 0x4
bmAttributes = 0x0
wBytesPerInterval = 0x0
}

Actions #4

Updated by Stephan Althaus over 2 years ago

Hello!

I would happily run some dtrace script on my laptop setup to get closer to the root cause.

May someone please provide such a script ?

Thanks!
Stephan

Actions #5

Updated by Stephan Althaus over 2 years ago

BTW, there is a small typo in
illumos-gate/usr/src/uts/common/io/usb/hcd/xhci/xhci_command.c

on line 720

xhci_log (xhcip, "!unexpected error when resetting enpoint : %d",
Actions #6

Updated by Stephan Althaus over 2 years ago

Maybe this output shows some light to developers:

./DS305964.ARW: I/O error
./DS305965.ARW: I/O error
steven@dell6510:~/tmp$ echo '::usba_debug_buf' | mdb -k
t rval: 0
s2u24:          bulk-in pipe clear stall: 0
s2u24:          bulk-out pipe clear stall: 0
usbai:  usba_req_exc_cb: scsa2usb24: ph_data=0xfffffe2cf0429a78 (ep2) state=1 wrp=0xfffffe2cde4e96b8 ref=2 reqcnt=1 cr=5
s2u24:  scsa2usb_bulk_only_handle_error: req = 0xfffffe2cde4e9748, cr = 0x5
s2u24:  scsa2usb_bulk_only_reset_recovery: scsa2usbp = 0xfffffe2cfa2ec000
s2u24:          bulk-only device-reset rval: 0
s2u24:          bulk-in pipe clear stall: 0
s2u24:          bulk-out pipe clear stall: 0
usbai:  usba_req_exc_cb: scsa2usb24: ph_data=0xfffffe2cf0429a78 (ep2) state=1 wrp=0xfffffe2cde4e96b8 ref=2 reqcnt=1 cr=5
s2u24:  scsa2usb_bulk_only_handle_error: req = 0xfffffe2cde4e9748, cr = 0x5
s2u24:  scsa2usb_bulk_only_reset_recovery: scsa2usbp = 0xfffffe2cfa2ec000
s2u24:          bulk-only device-reset rval: 0
s2u24:          bulk-in pipe clear stall: 0
s2u24:          bulk-out pipe clear stall: 0
usbai:  usba_req_exc_cb: scsa2usb24: ph_data=0xfffffe2cf0429a78 (ep2) state=1 wrp=0xfffffe2cde4e96b8 ref=2 reqcnt=1 cr=5
s2u24:  scsa2usb_bulk_only_handle_error: req = 0xfffffe2cde4e9748, cr = 0x5
s2u24:  scsa2usb_bulk_only_reset_recovery: scsa2usbp = 0xfffffe2cfa2ec000
s2u24:          bulk-only device-reset rval: 0
s2u24:          bulk-in pipe clear stall: 0
s2u24:          bulk-out pipe clear stall: 0
usbai:  usba_req_exc_cb: scsa2usb24: ph_data=0xfffffe2cf0429a78 (ep2) state=1 wrp=0xfffffe2cd03f1770 ref=2 reqcnt=1 cr=5
s2u24:  scsa2usb_bulk_only_handle_error: req = 0xfffffe2cd03f1800, cr = 0x5
s2u24:  scsa2usb_bulk_only_reset_recovery: scsa2usbp = 0xfffffe2cfa2ec000
s2u24:          bulk-only device-reset rval: 0
s2u24:          bulk-in pipe clear stall: 0
s2u24:          bulk-out pipe clear stall: 0
usbai:  usba_req_exc_cb: scsa2usb24: ph_data=0xfffffe2cf0429a78 (ep2) state=1 wrp=0xfffffe2cd1806568 ref=2 reqcnt=1 cr=5
s2u24:  scsa2usb_bulk_only_handle_error: req = 0xfffffe2cd18065f8, cr = 0x5
s2u24:  scsa2usb_bulk_only_reset_recovery: scsa2usbp = 0xfffffe2cfa2ec000
s2u24:          bulk-only device-reset rval: 0
s2u24:          bulk-in pipe clear stall: 0
s2u24:          bulk-out pipe clear stall: 0
usbai:  usba_req_exc_cb: scsa2usb24: ph_data=0xfffffe2cf0429a78 (ep2) state=1 wrp=0xfffffe2cd1806568 ref=2 reqcnt=1 cr=5
s2u24:  scsa2usb_bulk_only_handle_error: req = 0xfffffe2cd18065f8, cr = 0x5
s2u24:  scsa2usb_bulk_only_reset_recovery: scsa2usbp = 0xfffffe2cfa2ec000
s2u24:          bulk-only device-reset rval: 0
s2u24:          bulk-in pipe clear stall: 0
s2u24:          bulk-out pipe clear stall: 0
usbai:  usba_req_exc_cb: scsa2usb24: ph_data=0xfffffe2cf0429a78 (ep2) state=1 wrp=0xfffffe2cd1806568 ref=2 reqcnt=1 cr=5
s2u24:  scsa2usb_bulk_only_handle_error: req = 0xfffffe2cd18065f8, cr = 0x5
s2u24:  scsa2usb_bulk_only_reset_recovery: scsa2usbp = 0xfffffe2cfa2ec000
s2u24:          bulk-only device-reset rval: 0
s2u24:          bulk-in pipe clear stall: 0
s2u24:          bulk-out pipe clear stall: 0
usbai:  usba_req_exc_cb: scsa2usb24: ph_data=0xfffffe2cf0429a78 (ep2) state=1 wrp=0xfffffe2cd1806568 ref=2 reqcnt=1 cr=5
s2u24:  scsa2usb_bulk_only_handle_error: req = 0xfffffe2cd18065f8, cr = 0x5
s2u24:  scsa2usb_bulk_only_reset_recovery: scsa2usbp = 0xfffffe2cfa2ec000
s2u24:          bulk-only device-reset rval: 0
s2u24:          bulk-in pipe clear stall: 0
s2u24:          bulk-out pipe clear stall: 0
usbai:  usba_req_exc_cb: scsa2usb24: ph_data=0xfffffe2cf0429a78 (ep2) state=1 wrp=0xfffffe2cd1806028 ref=2 reqcnt=1 cr=5
s2u24:  scsa2usb_bulk_only_handle_error: req = 0xfffffe2cd18060b8, cr = 0x5
s2u24:  scsa2usb_bulk_only_reset_recovery: scsa2usbp = 0xfffffe2cfa2ec000
s2u24:          bulk-only device-reset rval: 0
s2u24:          bulk-in pipe clear stall: 0
s2u24:          bulk-out pipe clear stall: 0
usbai:  usba_req_exc_cb: scsa2usb24: ph_data=0xfffffe2cf0429a78 (ep2) state=1 wrp=0xfffffe2cd1806028 ref=2 reqcnt=1 cr=5
s2u24:  scsa2usb_bulk_only_handle_error: req = 0xfffffe2cd18060b8, cr = 0x5
s2u24:  scsa2usb_bulk_only_reset_recovery: scsa2usbp = 0xfffffe2cfa2ec000
s2u24:          bulk-only device-reset rval: 0
s2u24:          bulk-in pipe clear stall: 0
s2u24:          bulk-out pipe clear stall: 0
usbai:  usba_req_exc_cb: scsa2usb24: ph_data=0xfffffe2cf0429a78 (ep2) state=1 wrp=0xfffffe2cdfbfa940 ref=2 reqcnt=1 cr=5
s2u24:  scsa2usb_bulk_only_handle_error: req = 0xfffffe2cdfbfa9d0, cr = 0x5
s2u24:  scsa2usb_bulk_only_reset_recovery: scsa2usbp = 0xfffffe2cfa2ec000
s2u24:          bulk-only device-reset rval: 0
s2u24:          bulk-in pipe clear stall: 0
s2u24:          bulk-out pipe clear stall: 0
usbai:  usba_req_exc_cb: scsa2usb24: ph_data=0xfffffe2cf0429a78 (ep2) state=1 wrp=0xfffffe2cdfbfa940 ref=2 reqcnt=1 cr=5
s2u24:  scsa2usb_bulk_only_handle_error: req = 0xfffffe2cdfbfa9d0, cr = 0x5
s2u24:  scsa2usb_bulk_only_reset_recovery: scsa2usbp = 0xfffffe2cfa2ec000
s2u24:          bulk-only device-reset rval: 0
s2u24:          bulk-in pipe clear stall: 0
s2u24:          bulk-out pipe clear stall: 0
usbai:  usba_req_exc_cb: scsa2usb24: ph_data=0xfffffe2cf0429a78 (ep2) state=1 wrp=0xfffffe2cdfbfa940 ref=2 reqcnt=1 cr=5
s2u24:  scsa2usb_bulk_only_handle_error: req = 0xfffffe2cdfbfa9d0, cr = 0x5
s2u24:  scsa2usb_bulk_only_reset_recovery: scsa2usbp = 0xfffffe2cfa2ec000
s2u24:          bulk-only device-reset rval: 0
s2u24:          bulk-in pipe clear stall: 0
s2u24:          bulk-out pipe clear stall: 0
usbai:  usba_req_exc_cb: scsa2usb24: ph_data=0xfffffe2cf0429a78 (ep2) state=1 wrp=0xfffffe2cdfbfa940 ref=2 reqcnt=1 cr=5
s2u24:  scsa2usb_bulk_only_handle_error: req = 0xfffffe2cdfbfa9d0, cr = 0x5
s2u24:  scsa2usb_bulk_only_reset_recovery: scsa2usbp = 0xfffffe2cfa2ec000
s2u24:          bulk-only device-reset rval: 0
s2u24:          bulk-in pipe clear stall: 0
s2u24:          bulk-out pipe clear stall: 0
usbai:  usba_req_exc_cb: scsa2usb24: ph_data=0xfffffe2cf0429a78 (ep2) state=1 wrp=0xfffffe2cdfbfa940 ref=2 reqcnt=1 cr=5
s2u24:  scsa2usb_bulk_only_handle_error: req = 0xfffffe2cdfbfa9d0, cr = 0x5
s2u24:  scsa2usb_bulk_only_reset_recovery: scsa2usbp = 0xfffffe2cfa2ec000
s2u24:          bulk-only device-reset rval: 0
s2u24:          bulk-in pipe clear stall: 0
s2u24:          bulk-out pipe clear stall: 0
usbai:  usba_req_exc_cb: scsa2usb24: ph_data=0xfffffe2cf0429a78 (ep2) state=1 wrp=0xfffffe2cdfbfa940 ref=2 reqcnt=1 cr=5
s2u24:  scsa2usb_bulk_only_handle_error: req = 0xfffffe2cdfbfa9d0, cr = 0x5
s2u24:  scsa2usb_bulk_only_reset_recovery: scsa2usbp = 0xfffffe2cfa2ec000
s2u24:          bulk-only device-reset rval: 0
s2u24:          bulk-in pipe clear stall: 0
s2u24:          bulk-out pipe clear stall: 0
usbai:  usba_req_exc_cb: scsa2usb24: ph_data=0xfffffe2cf0429a78 (ep2) state=1 wrp=0xfffffe2cdfbfa940 ref=2 reqcnt=1 cr=5
s2u24:  scsa2usb_bulk_only_handle_error: req = 0xfffffe2cdfbfa9d0, cr = 0x5
s2u24:  scsa2usb_bulk_only_reset_recovery: scsa2usbp = 0xfffffe2cfa2ec000
s2u24:          bulk-only device-reset rval: 0
s2u24:          bulk-in pipe clear stall: 0
s2u24:          bulk-out pipe clear stall: 0
usbai:  usba_req_exc_cb: scsa2usb24: ph_data=0xfffffe2cf0429a78 (ep2) state=1 wrp=0xfffffe2cdfbfa940 ref=2 reqcnt=1 cr=5
s2u24:  scsa2usb_bulk_only_handle_error: req = 0xfffffe2cdfbfa9d0, cr = 0x5
s2u24:  scsa2usb_bulk_only_reset_recovery: scsa2usbp = 0xfffffe2cfa2ec000
s2u24:          bulk-only device-reset rval: 0
s2u24:          bulk-in pipe clear stall: 0
s2u24:          bulk-out pipe clear stall: 0
usbai:  usba_req_exc_cb: scsa2usb24: ph_data=0xfffffe2cf0429a78 (ep2) state=1 wrp=0xfffffe2cdfbfa940 ref=2 reqcnt=1 cr=5
s2u24:  scsa2usb_bulk_only_handle_error: req = 0xfffffe2cdfbfa9d0, cr = 0x5
s2u24:  scsa2usb_bulk_only_reset_recovery: scsa2usbp = 0xfffffe2cfa2ec000
s2u24:          bulk-only device-reset rval: 0
s2u24:          bulk-in pipe clear stall: 0
s2u24:          bulk-out pipe clear stall: 0
usbai:  usba_req_exc_cb: scsa2usb24: ph_data=0xfffffe2cf0429a78 (ep2) state=1 wrp=0xfffffe2cdfbfa940 ref=2 reqcnt=1 cr=5
s2u24:  scsa2usb_bulk_only_handle_error: req = 0xfffffe2cdfbfa9d0, cr = 0x5
s2u24:  scsa2usb_bulk_only_reset_recovery: scsa2usbp = 0xfffffe2cfa2ec000
s2u24:          bulk-only device-reset rval: 0
s2u24:          bulk-in pipe clear stall: 0
s2u24:          bulk-out pipe clear stall: 0
usbai:  usba_req_exc_cb: scsa2usb24: ph_data=0xfffffe2cf0429a78 (ep2) state=1 wrp=0xfffffe2cdfbfa940 ref=2 reqcnt=1 cr=5
s2u24:  scsa2usb_bulk_only_handle_error: req = 0xfffffe2cdfbfa9d0, cr = 0x5
s2u24:  scsa2usb_bulk_only_reset_recovery: scsa2usbp = 0xfffffe2cfa2ec000
s2u24:          bulk-only device-reset rval: 0
s2u24:          bulk-in pipe clear stall: 0
s2u24:          bulk-out pipe clear stall: 0
usbai:  usba_req_exc_cb: scsa2usb24: ph_data=0xfffffe2cf0429a78 (ep2) state=1 wrp=0xfffffe2cdfbfa940 ref=2 reqcnt=1 cr=5
s2u24:  scsa2usb_bulk_only_handle_error: req = 0xfffffe2cdfbfa9d0, cr = 0x5
s2u24:  scsa2usb_bulk_only_reset_recovery: scsa2usbp = 0xfffffe2cfa2ec000
s2u24:          bulk-only device-reset rval: 0
s2u24:          bulk-in pipe clear stall: 0
s2u24:          bulk-out pipe clear stall: 0
usbai:  usba_req_exc_cb: scsa2usb24: ph_data=0xfffffe2cf0429a78 (ep2) state=1 wrp=0xfffffe2cdfbfa940 ref=2 reqcnt=1 cr=5
s2u24:  scsa2usb_bulk_only_handle_error: req = 0xfffffe2cdfbfa9d0, cr = 0x5
s2u24:  scsa2usb_bulk_only_reset_recovery: scsa2usbp = 0xfffffe2cfa2ec000
s2u24:          bulk-only device-reset rval: 0
s2u24:          bulk-in pipe clear stall: 0
s2u24:          bulk-out pipe clear stall: 0
usbai:  usba_req_exc_cb: scsa2usb24: ph_data=0xfffffe2cf0429a78 (ep2) state=1 wrp=0xfffffe2cdfbfa940 ref=2 reqcnt=1 cr=5
s2u24:  scsa2usb_bulk_only_handle_error: req = 0xfffffe2cdfbfa9d0, cr = 0x5
s2u24:  scsa2usb_bulk_only_reset_recovery: scsa2usbp = 0xfffffe2cfa2ec000
s2u24:          bulk-only device-reset rval: 0
s2u24:          bulk-in pipe clear stall: 0
s2u24:          bulk-out pipe clear stall: 0
usbai:  usba_req_exc_cb: scsa2usb24: ph_data=0xfffffe2cf0429a78 (ep2) state=1 wrp=0xfffffe2cdfbfa940 ref=2 reqcnt=1 cr=5
s2u24:  scsa2usb_bulk_only_handle_error: req = 0xfffffe2cdfbfa9d0, cr = 0x5
s2u24:  scsa2usb_bulk_only_reset_recovery: scsa2usbp = 0xfffffe2cfa2ec000
s2u24:          bulk-only device-reset rval: 0
s2u24:          bulk-in pipe clear stall: 0
s2u24:          bulk-out pipe clear stall: 0
usbai:  usba_req_exc_cb: scsa2usb24: ph_data=0xfffffe2cf0429a78 (ep2) state=1 wrp=0xfffffe2cd3fb08c0 ref=2 reqcnt=1 cr=5
s2u24:  scsa2usb_bulk_only_handle_error: req = 0xfffffe2cd3fb0950, cr = 0x5
s2u24:  scsa2usb_bulk_only_reset_recovery: scsa2usbp = 0xfffffe2cfa2ec000
s2u24:          bulk-only device-reset rval: 0
s2u24:          bulk-in pipe clear stall: 0
s2u24:          bulk-out pipe clear stall: 0
usbai:  usba_req_exc_cb: scsa2usb24: ph_data=0xfffffe2cf0429a78 (ep2) state=1 wrp=0xfffffe2cd199bbb0 ref=2 reqcnt=1 cr=5
s2u24:  scsa2usb_bulk_only_handle_error: req = 0xfffffe2cd199bc40, cr = 0x5
s2u24:  scsa2usb_bulk_only_reset_recovery: scsa2usbp = 0xfffffe2cfa2ec000
s2u24:          bulk-only device-reset rval: 0
s2u24:          bulk-in pipe clear stall: 0
s2u24:          bulk-out pipe clear stall: 0
usbai:  usba_req_exc_cb: scsa2usb24: ph_data=0xfffffe2cf0429a78 (ep2) state=1 wrp=0xfffffe2cd159de08 ref=2 reqcnt=1 cr=5
s2u24:  scsa2usb_bulk_only_handle_error: req = 0xfffffe2cd159de98, cr = 0x5
s2u24:  scsa2usb_bulk_only_reset_recovery: scsa2usbp = 0xfffffe2cfa2ec000
s2u24:          bulk-only device-reset rval: 0
s2u24:          bulk-in pipe clear stall: 0
s2u24:          bulk-out pipe clear stall: 0
usbai:  usba_req_exc_cb: scsa2usb24: ph_data=0xfffffe2cf0429a78 (ep2) state=1 wrp=0xfffffe2cd159de08 ref=2 reqcnt=1 cr=5
s2u24:  scsa2usb_bulk_only_handle_error: req = 0xfffffe2cd159de98, cr = 0x5
s2u24:  scsa2usb_bulk_only_reset_recovery: scsa2usbp = 0xfffffe2cfa2ec000
s2u24:          bulk-only device-reset rval: 0
s2u24:          bulk-in pipe clear stall: 0
s2u24:          bulk-out pipe clear stall: 0
usbai:  usba_req_exc_cb: scsa2usb24: ph_data=0xfffffe2cf0429a78 (ep2) state=1 wrp=0xfffffe2cd159de08 ref=2 reqcnt=1 cr=5
s2u24:  scsa2usb_bulk_only_handle_error: req = 0xfffffe2cd159de98, cr = 0x5
s2u24:  scsa2usb_bulk_only_reset_recovery: scsa2usbp = 0xfffffe2cfa2ec000
s2u24:          bulk-only device-reset rval: 0
s2u24:          bulk-in pipe clear stall: 0
s2u24:          bulk-out pipe clear stall: 0
usbai:  usba_req_exc_cb: scsa2usb24: ph_data=0xfffffe2cf0429a78 (ep2) state=1 wrp=0xfffffe2cd13f14e8 ref=2 reqcnt=1 cr=5
s2u24:  scsa2usb_bulk_only_handle_error: req = 0xfffffe2cd13f1578, cr = 0x5
s2u24:  scsa2usb_bulk_only_reset_recovery: scsa2usbp = 0xfffffe2cfa2ec000
s2u24:          bulk-only device-reset rval: 0
s2u24:          bulk-in pipe clear stall: 0
s2u24:          bulk-out pipe clear stall: 0
usbai:  usba_req_exc_cb: scsa2usb24: ph_data=0xfffffe2cf0429a78 (ep2) state=1 wrp=0xfffffe2cde4e96b8 ref=2 reqcnt=1 cr=5
s2u24:  scsa2usb_bulk_only_handle_error: req = 0xfffffe2cde4e9748, cr = 0x5
s2u24:  scsa2usb_bulk_only_reset_recovery: scsa2usbp = 0xfffffe2cfa2ec000
s2u24:          bulk-only device-reset rval: 0
s2u24:          bulk-in pipe clear stall: 0
s2u24:          bulk-out pipe clear stall: 0
usbai:  usba_req_exc_cb: scsa2usb24: ph_data=0xfffffe2cf0429a78 (ep2) state=1 wrp=0xfffffe2cd13eb2b0 ref=2 reqcnt=1 cr=5
s2u24:  scsa2usb_bulk_only_handle_error: req = 0xfffffe2cd13eb340, cr = 0x5
s2u24:  scsa2usb_bulk_only_reset_recovery: scsa2usbp = 0xfffffe2cfa2ec000
s2u24:          bulk-only device-reset rval: 0
s2u24:          bulk-in pipe clear stall: 0
s2u24:          bulk-out pipe clear stall: 0
usbai:  usba_req_exc_cb: scsa2usb24: ph_data=0xfffffe2cf0429a78 (ep2) state=1 wrp=0xfffffe2cd13eb2b0 ref=2 reqcnt=1 cr=5
s2u24:  scsa2usb_bulk_only_handle_error: req = 0xfffffe2cd13eb340, cr = 0x5
s2u24:  scsa2usb_bulk_only_reset_recovery: scsa2usbp = 0xfffffe2cfa2ec000
s2u24:          bulk-only device-reset rval: 0
s2u24:          bulk-in pipe clear stall: 0
s2u24:          bulk-out pipe clear stall: 0
usbai:  usba_req_exc_cb: scsa2usb24: ph_data=0xfffffe2cf0429a78 (ep2) state=1 wrp=0xfffffe2cd13eb2b0 ref=2 reqcnt=1 cr=5
s2u24:  scsa2usb_bulk_only_handle_error: req = 0xfffffe2cd13eb340, cr = 0x5
s2u24:  scsa2usb_bulk_only_reset_recovery: scsa2usbp = 0xfffffe2cfa2ec000
s2u24:          bulk-only device-reset rval: 0
s2u24:          bulk-in pipe clear stall: 0
s2u24:          bulk-out pipe clear stall: 0
usbai:  usba_req_exc_cb: scsa2usb24: ph_data=0xfffffe2cf0429a78 (ep2) state=1 wrp=0xfffffe2cd199bbb0 ref=2 reqcnt=1 cr=5
s2u24:  scsa2usb_bulk_only_handle_error: req = 0xfffffe2cd199bc40, cr = 0x5
s2u24:  scsa2usb_bulk_only_reset_recovery: scsa2usbp = 0xfffffe2cfa2ec000
s2u24:          bulk-only device-reset rval: 0
s2u24:          bulk-in pipe clear stall: 0
s2u24:          bulk-out pipe clear stall: 0
usbai:  usba_req_exc_cb: scsa2usb24: ph_data=0xfffffe2cf0429a78 (ep2) state=1 wrp=0xfffffe2cdfbfa860 ref=2 reqcnt=1 cr=5
s2u24:  scsa2usb_bulk_only_handle_error: req = 0xfffffe2cdfbfa8f0, cr = 0x5
s2u24:  scsa2usb_bulk_only_reset_recovery: scsa2usbp = 0xfffffe2cfa2ec000
s2u24:          bulk-only device-reset rval: 0
s2u24:          bulk-in pipe clear stall: 0
s2u24:          bulk-out pipe clear stall: 0
xusb2:  hubd_resume_port: port=6 not suspended
xusb2:  hubd_resume_port: port=10 not suspended
xusb2:  hubd_resume_port: port=3 not suspended
xusb2:  hubd_resume_port: port=6 not suspended
xusb2:  hubd_resume_port: port=10 not suspended
xusb2:  hubd_resume_port: port=3 not suspended
xusb2:  hubd_resume_port: port=6 not suspended
xusb2:  hubd_resume_port: port=10 not suspended
xusb2:  hubd_resume_port: port=3 not suspended
hid34:  hid_pm_busy_component failed: 0
hid34:  hid_pm_busy_component failed: 0
hid34:  hid_pm_busy_component failed: 0
hid34:  hid_pm_busy_component failed: 0
hid34:  hid_pm_busy_component failed: 0
hid34:  hid_pm_busy_component failed: 0
hid34:  hid_pm_busy_component failed: 0
hid34:  hid_pm_busy_component failed: 0
xusb2:  hubd_resume_port: port=6 not suspended
xusb2:  hubd_resume_port: port=10 not suspended
xusb2:  hubd_resume_port: port=3 not suspended
hid34:  hid_pm_busy_component failed: 0
hid34:  hid_pm_busy_component failed: 0
hid34:  hid_pm_busy_component failed: 0
hid34:  hid_pm_busy_component failed: 0
hid34:  hid_pm_busy_component failed: 0
hid34:  hid_pm_busy_component failed: 0
hid34:  hid_pm_busy_component failed: 0
hid34:  hid_pm_busy_component failed: 0
hid34:  hid_pm_busy_component failed: 0
hid34:  hid_pm_busy_component failed: 0
hid34:  hid_pm_busy_component failed: 0
hid34:  hid_pm_busy_component failed: 0
hid34:  hid_pm_busy_component failed: 0
hid34:  hid_pm_busy_component failed: 0
xusb2:  hubd_resume_port: port=6 not suspended
xusb2:  hubd_resume_port: port=10 not suspended
xusb2:  hubd_resume_port: port=3 not suspended
usbai:  usba_req_exc_cb: scsa2usb24: ph_data=0xfffffe2cd66b9c10 (ep2) state=1 wrp=0xfffffe2cd0034730 ref=2 reqcnt=1 cr=5
s2u24:  scsa2usb_bulk_only_handle_error: req = 0xfffffe2cd00347c0, cr = 0x5
s2u24:  scsa2usb_bulk_only_reset_recovery: scsa2usbp = 0xfffffe2cfa2ec000
s2u24:          bulk-only device-reset rval: 0
s2u24:          bulk-in pipe clear stall: 0
s2u24:          bulk-out pipe clear stall: 0
hid34:  hid_pm_busy_component failed: 0
hid34:  hid_pm_busy_component failed: 0
xusb2:  hubd_resume_port: port=6 not suspended
xusb2:  hubd_resume_port: port=10 not suspended
xusb2:  hubd_resume_port: port=3 not suspended
hid34:  hid_pm_busy_component failed: 0
hid34:  hid_pm_busy_component failed: 0
>>>>

Actions #7

Updated by Stephan Althaus over 1 year ago

This issue related to my SDCard-Reader is solved with #14944.
However, sometimes, my mouse stops working, dmesg says:

Oct 16 13:13:58 dell7720 xhci: [ID 902155 kern.info] NOTICE: xhci2: xhci stop endpoint command (2)/slot (10) in wrong state: 19
Oct 16 13:13:58 dell7720 xhci: [ID 617155 kern.info] NOTICE: xhci2: endpoint is in state 3

Re-plug of the mouse device helps. Sometimes it is more seldom, sometimes multiple times per minute, then for hours it is ok :-/

Maybe it is related to my hardware - but linux and windows are ok ith it. Maybe they do a reset in this cases, i don't know..

I did try using the mouse behind a USB Hub connected to a USB2 slot, but then the hub gets this error :-/
Standard USB 1.0 3-button mouse btw.

Oct 16 13:14:04 dell7720 usba: [ID 912658 kern.info] USB 2.0 device (usb46d,c05b) operating at low speed (USB 1.x) on USB 3.0 root hub: mouse@4, hid33 at bus address 4
Oct 16 13:14:04 dell7720 usba: [ID 349649 kern.info] Logitech USB Optical Mouse
Oct 16 13:14:04 dell7720 genunix: [ID 936769 kern.info] hid33 is /pci@0,0/pci1028,7b1@14/mouse@4
Oct 16 13:14:04 dell7720 genunix: [ID 408114 kern.info] /pci@0,0/pci1028,7b1@14/mouse@4 (hid33) online

Actions #8

Updated by Stephan Althaus over 1 year ago

Regarded to XHCI and hotplug,
the re-connecting of mouse and keyboard works well on OI within X/mate, that is very good!

tail -f /var/adm/messages shows, that when there is the wrong state on the USB port with the mouse,
the USB port ist marked "online" automagically, but X does not get a signal that it is available again.

Does someone familiar to XHCI have a debug script to dig into this?

Oct 21 08:49:46 dell7720 last message repeated 2 times
Oct 21 08:59:47 dell7720 apcupsd1218: [ID 702911 daemon.warning] Communications with UPS lost.
Oct 21 09:05:33 dell7720 xhci: [ID 902155 kern.info] NOTICE: xhci2: xhci stop endpoint command (2)/slot (23) in wrong state: 19
Oct 21 09:05:33 dell7720 xhci: [ID 617155 kern.info] NOTICE: xhci2: endpoint is in state 3
Oct 21 09:05:34 dell7720 genunix: [ID 408114 kern.info] /pci@0,0/pci1028,7b1@14/mouse@2 (hid39) online

Actions #9

Updated by Stephan Althaus over 1 year ago

This is related to #11776, here it is not the keyboard but the mouse...
Mouse works from the start, the stops working - after re-connecting it works again.

I did not find a way to see the messages from system/hal yet.

Xorg.0.log contains this:

[ 33370.211] (II) config/hal: removing device mouse
[ 33370.212] (WW) mouse: cannot pop module 'usbms' off mouse device: Invalid argument
[ 33370.213] (II) UnloadModule: "mouse"
[ 33374.411] (II) config/hal: Adding input device mouse
[ 33374.411] (II) Using input driver 'mouse' for 'mouse'
[ 33374.411] () mouse: always reports core events
[ 33374.411] (
) Option "Protocol" "VUID"
[ 33374.411] () Option "Device" "/dev/usb/hid0"
[ 33374.411] (
) Option "StreamsModule" "usbms"
[ 33374.412] () mouse: Protocol: "VUID"
[ 33374.412] (
) mouse: always reports core events
[ 33374.412] (==) mouse: Emulate3Buttons, Emulate3Timeout: 50
[ 33374.412] () mouse: ZAxisMapping: buttons 4 and 5
[ 33374.412] (
) mouse: Buttons: 9
[ 33374.412] () Option "config_info" "hal:/org/freedesktop/Hal/devices/pci_0_0/pci1028_7b1_14/mouse_4_if0_33_logicaldev_input"
[ 33374.412] (II) XINPUT: Adding extended input device "mouse" (type: MOUSE, id 9)
[ 33374.412] (
) mouse: (accel) keeping acceleration scheme 1
[ 33374.412] () mouse: (accel) acceleration profile 0
[ 33374.412] (
) mouse: (accel) acceleration factor: 2.000
[ 33374.412] (**) mouse: (accel) acceleration threshold: 4

dbus-monitor --system shows something that i will try to examine tomorrow

  1. dbus-monitor --system|grep Hal
    string "org.freedesktop.Hal"
    string "type='signal',interface='org.freedesktop.Hal.Manager',sender='org.freedesktop.Hal',path='/org/freedesktop/Hal/Manager'"
    method call time=1666731247.518723 sender=:1.61 -> destination=org.freedesktop.Hal serial=24 path=/org/freedesktop/Hal/Manager; interface=org.freedesktop.Hal.Manager; member=FindDeviceStringMatch
    string "type='signal',interface='org.freedesktop.Hal.Manager',sender='org.freedesktop.Hal',path='/org/freedesktop/Hal/Manager'"
    signal time=1666731283.017150 sender=:1.123 -> destination=(null destination) serial=105 path=/org/freedesktop/Hal/Manager; interface=org.freedesktop.Hal.Manager; member=DeviceRemoved
Actions #10

Updated by Stephan Althaus over 1 year ago

Shortly after the mouse stops working, i have still the deive in the list of usb devices:

  1. mdb -ke '::prtusb'
    INDEX DRIVER INST NODE GEN VID.PID PRODUCT
    1 xhci 2 pci1028,7b1 3.0 0000.0000 No Product String
    2 usb_mid 57 device 2.0 1395.0099 Sennheiser PC 8.2 USB
    3 usb_mid 35 device 1.1 0bf8.100c FSC KBPC PX
    4 hubd 18 hub 2.0 413c.2513 No Product String
    5 usb_mid 32 device 2.0 8087.0a2b No Product String
    6 hubd 19 hub 2.0 413c.2134 USB2134
    7 usb_mid 33 device 1.1 0a5c.5832 5880
    8 hid 36 mouse 2.0 046d.c05b USB Optical Mouse

however, the XHCI port is stopped:

  1. mdb -ke '::xhci_device'
    Logitech - USB Optical Mouse
    Port 03 | Slot 13 | # Endpoints 02
    EP Type State Head Tail
    0 CONTROL Stopped 0x2e 0x2e
    2 INTR IN Stopped 0xd7 0xd7

dmesg says the device is "online" - that is not correct if the XHCI device is stopped..

  1. dmesg
    Oct 26 10:13:03 dell7720 xhci: [ID 902155 kern.info] NOTICE: xhci2: xhci stop endpoint command (2)/slot (13) in wrong state: 19
    Oct 26 10:13:03 dell7720 xhci: [ID 617155 kern.info] NOTICE: xhci2: endpoint is in state 3
    Oct 26 10:13:03 dell7720 genunix: [ID 408114 kern.info] /pci@0,0/pci1028,7b1@14/mouse@3 (hid36) online

Is there a way to re-activate the XHCI device in this state ? maybe automagically ?

Actions #11

Updated by Gary Mills 7 months ago

Yes, the bug is still around. On my system qtpie, which I mainly use as a NAT router, the errors appeared in /var/adm/messages appeared as soon as I started my UPS monitor service:

Jul 13 20:38:04 qtpie xhci: [ID 902155 kern.info] NOTICE: xhci0: xhci stop endpoint command (2)/slot (1) in wrong state: 19
Jul 13 20:38:04 qtpie xhci: [ID 617155 kern.info] NOTICE: xhci0: endpoint is in state 3
Jul 13 20:38:04 qtpie xhci: [ID 902155 kern.info] NOTICE: xhci0: xhci stop endpoint command (2)/slot (1) in wrong state: 19
Jul 13 20:38:04 qtpie xhci: [ID 617155 kern.info] NOTICE: xhci0: endpoint is in state 3
Jul 13 20:38:04 qtpie xhci: [ID 902155 kern.info] NOTICE: xhci0: xhci stop endpoint command (2)/slot (1) in wrong state: 19
Jul 13 20:38:04 qtpie xhci: [ID 617155 kern.info] NOTICE: xhci0: endpoint is in state 3

The cluster of messages repeated every four seconds until I disabled the service. This system only has one USB connection, not even a keyboard and a mouse. The UPS monitor uses the ugen driver. It's probably unrelated, but the daemon hung in the kernel when I disabled the service. This what I get now in a root session:

mills@qtpie:~$ mdb -ke '::prtusb'                                               
INDEX   DRIVER      INST  NODE          GEN  VID.PID     PRODUCT             
1       xhci        0     pci8086,7270  3.0  0000.0000   No Product String
2       ugen        0     input         2.0  051d.0002   Back-UPS RS 1500G FW:865.L5 .D USB FW:L5 
Actions #12

Updated by Stephan Althaus 7 months ago

i can confirm that this error is still present, with my not-so-good-working-mouse that triggers the error i had a only a few occasions today:

$ dmesg|grep state
Aug  2 14:04:35 dell7720 xhci: [ID 902155 kern.info] NOTICE: xhci2: xhci stop endpoint command (2)/slot (2) in wrong state: 19
Aug  2 14:04:35 dell7720 xhci: [ID 617155 kern.info] NOTICE: xhci2: endpoint is in state 3
Aug  2 18:48:30 dell7720 xhci: [ID 902155 kern.info] NOTICE: xhci2: xhci stop endpoint command (2)/slot (7) in wrong state: 19
Aug  2 18:48:30 dell7720 xhci: [ID 617155 kern.info] NOTICE: xhci2: endpoint is in state 3
Aug  2 20:17:05 dell7720 xhci: [ID 902155 kern.info] NOTICE: xhci2: xhci stop endpoint command (2)/slot (8) in wrong state: 19
Aug  2 20:17:05 dell7720 xhci: [ID 617155 kern.info] NOTICE: xhci2: endpoint is in state 3
Actions #13

Updated by Gary Mills 7 months ago

I now have a test system that reproduces the xhci errors that I get on my production system. The error messages come in a group within the same second, and then repeat four seconds later. They start when the service that starts the UPS daemon is enabled and end when the service is disabled. I'm willing to collect any information on the test system that might help.

With a web search, I learned that the "state" is unreliable internally, and that if you need to track state within the driver, you should be using a memory-based variable. I also learned that this bug may already be fixed in Linux and Windows.

Actions #14

Updated by Gary Mills 6 months ago

I learned a few thing by reviewing the source code of the xhci driver in illumos. All of the error messages reported by Stephan Althaus and all of the error messages reported by me were produced by the xhci_command_stop_endpoint() function. This function is called only by the xhci_endpoint_quiesce() function. Here is a typical set of error messages:

Aug  3 10:17:34 celeron xhci: [ID 902155 kern.info] NOTICE: xhci0: xhci stop endpoint command (2)/slot (4) in wrong state: 19
Aug  3 10:17:34 celeron xhci: [ID 617155 kern.info] NOTICE: xhci0: endpoint is in state 3

The first line displays the status code of the hardware, not the context state as the message suggests. 19 means "Transition from illegal ctx state". The second line displays the context state. 3 means "stopped". Of course, a transition from stopped to stopped would be illegal. That error seems to be the cause of all the problems.

Actions #15

Updated by Gary Mills 6 months ago

I now have a set of patches to xhci that fix the problem described in this bug report. The first patch corrects the problem by bypassing the xhci_command_stop_endpoint() function call when the endpoint is already in the "stopped" state. The second patch corrects the error messages that might be misleading. (The messages certainly mislead me.)

Actions #16

Updated by Robert Mustacchi 6 months ago

Just something to note, the actual error messages here while annoying, don't do anything with the actual issues that Stephan described in the opening of the ticket. These error messages are confusing and I'm sorry for sending folks down the wrong path with those things that were left over, but basically if a device isn't working for some reason, these error messages are merely symptomatic of other things and don't have anything to do with the underlying issue / device error generally speaking.

Actions #17

Updated by Gary Mills 6 months ago

I finally did a truss of the UPS monitor daemon, something I should have done before. The poll interval seems to be four seconds, corresponding exactly to the repeat interval of the error messages. All of the error messages correspond to open()/close() system calls in the daemon. There is no loop after all, just peculiar behavior of the monitor daemon and the ugen driver. Why xhci tried to stop an endpoint that was already stopped, I do not know. Here's the truss:

mills@celeron:~$ truss -d -p 2098
Base time stamp:  1693775973.2662  [ Sun Sep  3 16:19:33 CDT 2023 ]
/2:     sigtimedwait(0xFECEEFB0, 0xFECEEEA0, 0x00000000) (sleeping...)
/3:     accept(5, 0xFEBDEF90, 0xFEBDEF3C, SOV_DEFAULT, 0) (sleeping...)
/1:     read(10, 0x08047BE8, 20)        (sleeping...)
/1:      4.1546 read(10, "06\0\0\b", 20)                        = 4
/1:      4.1552 close(10)                                       = 0
/1:      4.1553 close(9)                                        = 0
/1:      4.1557 open("/dev/usb/51d.2/0/if0in1stat", O_RDWR)     = 9
/1:      4.1559 write(9, "01", 1)                               = 1
/1:      4.1565 open("/dev/usb/51d.2/0/if0in1", O_RDONLY)       = 10
/1:      4.2185 read(10, "\f d / *", 20)                        = 4
/1:      4.2189 close(10)                                       = 0
/1:      4.2191 close(9)                                        = 0
/1:      4.2194 open("/dev/usb/51d.2/0/if0in1stat", O_RDWR)     = 9
/1:      4.2196 write(9, "01", 1)                               = 1
/1:      4.2201 open("/dev/usb/51d.2/0/if0in1", O_RDONLY)       = 10
/1:      4.2825 read(10, "16\f\0\0\0", 20)                      = 5
/1:      4.2830 close(10)                                       = 0
/1:      4.2832 close(9)                                        = 0
/1:      4.2835 open("/dev/usb/51d.2/0/if0in1stat", O_RDWR)     = 9
/1:      4.2837 write(9, "01", 1)                               = 1
/1:      4.2843 open("/dev/usb/51d.2/0/if0in1", O_RDONLY)       = 10
/1:     read(10, 0x08047BE8, 20)        (sleeping...)
/1:      8.3792 read(10, "06\0\0\b", 20)                        = 4
/1:      8.3797 close(10)                                       = 0
/1:      8.3799 close(9)                                        = 0
/1:      8.3802 open("/dev/usb/51d.2/0/if0in1stat", O_RDWR)     = 9
/1:      8.3804 write(9, "01", 1)                               = 1
/1:      8.3810 open("/dev/usb/51d.2/0/if0in1", O_RDONLY)       = 10
/1:      8.4432 read(10, "\f d / *", 20)                        = 4
/1:      8.4436 close(10)                                       = 0
/1:      8.4438 close(9)                                        = 0
/1:      8.4440 open("/dev/usb/51d.2/0/if0in1stat", O_RDWR)     = 9
/1:      8.4443 write(9, "01", 1)                               = 1
/1:      8.4448 open("/dev/usb/51d.2/0/if0in1", O_RDONLY)       = 10
/1:      8.5072 read(10, "16\f\0\0\0", 20)                      = 5
/1:      8.5076 close(10)                                       = 0
/1:      8.5078 close(9)                                        = 0
/1:      8.5080 open("/dev/usb/51d.2/0/if0in1stat", O_RDWR)     = 9
/1:      8.5082 write(9, "01", 1)                               = 1
/1:      8.5088 open("/dev/usb/51d.2/0/if0in1", O_RDONLY)       = 10
/1:     read(10, 0x08047BE8, 20)        (sleeping...)
^C
Actions #18

Updated by Marcel Telka about 1 month ago

  • Has duplicate Bug #14216: Problem with USB added
Actions #19

Updated by Marcel Telka about 1 month ago

  • Category set to driver - device drivers
Actions

Also available in: Atom PDF