Re: Trouble with Intenso FlashLine 32GB USB stick on Kernel 4.14

Re: Trouble with Intenso FlashLine 32GB USB stick on Kernel 4.14

[gregkh]

On Wed, Mar 16, 2022 at 01:39:57PM +0000, Schmid, Carsten wrote:
> Hi Greg, Mathias,
> 
> i have a USB stick that - when plugged in - forces a USB storage hang message.
> Prior to that message i can see USBDEVFS_CONTROL timeout messages.
> (BTW the stick works fine on a desktop system with a recent kernel)
> The stick is having  a USB-C connector, and is connected to a USB2 port through an adapter (that i also used on the Desktop system for a quick check, and it worked there on a USB2 port)
> 
> I built a reproducer and collected traces (see attachment).
> As there is no MAINTAINER given for drivers/usb/core, i send that to you and the USB mailing list to ask someone to look into that.
> 
> >From the kernel's dmesg, these are the entries when trace has been recorded.
> 
> [159909.172301] usb 1-1: new high-speed USB device number 13 using xhci_hcd
> [159909.314291] usb 1-1: New USB device found, idVendor=058f, idProduct=6387
> [159909.314299] usb 1-1: New USB device strings: Mfr=1, Product=2, SerialNumber=3
> [159909.314303] usb 1-1: Product: Intenso Flash Line
> [159909.314306] usb 1-1: Manufacturer: ALCOR
> [159909.314310] usb 1-1: SerialNumber: E13DF681
> [159909.317093] usb-storage 1-1:1.0: USB Mass Storage device detected
> [159909.319468] scsi host2: usb-storage 1-1:1.0
> [159909.614535] usb 1-1: usbfs: USBDEVFS_CONTROL failed cmd NmeDefaultPrio rqt 192 rq 51 len 2 ret -110
> [159909.665513] usb 1-1: usbfs: USBDEVFS_CONTROL failed cmd NmeDefaultPrio rqt 192 rq 51 len 2 ret -110
> [159909.729510] usb 1-1: usbfs: USBDEVFS_CONTROL failed cmd NmeDefaultPrio rqt 192 rq 51 len 2 ret -110
> [159909.780610] usb 1-1: usbfs: USBDEVFS_CONTROL failed cmd NmeDefaultPrio rqt 192 rq 51 len 2 ret -110

Why is usbfs being used for a storage device?  What userspace program do
you have that is poking at the device?

> [159928.908633] INFO: task usb-storage:31868 blocked for more than 10 seconds.
> [159928.908638]       Tainted: P     U     O    4.14.244-apl #1
> [159928.908638] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
> [159928.908640] usb-storage     D    0 31868      2 0x80000080
> [159928.908644] Call Trace:
> [159928.908657]  __schedule+0x1c2/0x7b0
> [159928.908659]  schedule+0x2e/0x90
> [159928.908661]  schedule_timeout+0x230/0x470
> [159928.908672]  ? usb_hcd_submit_urb+0x98/0xbc0 [usbcore]
> [159928.908674]  ? schedule_timeout+0x230/0x470
> [159928.908679]  ? usb_hcd_submit_urb+0x98/0xbc0 [usbcore]
> [159928.908681]  ? __switch_to_asm+0x35/0x70
> [159928.908683]  ? __switch_to_asm+0x41/0x70
> [159928.908684]  ? __switch_to_asm+0x35/0x70
> [159928.908685]  ? __switch_to_asm+0x41/0x70
> [159928.908687]  wait_for_common+0xb5/0x170
> [159928.908689]  ? wait_for_common+0xb5/0x170
> [159928.908692]  ? wake_up_q+0x80/0x80
> [159928.908694]  wait_for_completion+0x18/0x20
> [159928.908699]  usb_sg_wait+0x114/0x170 [usbcore]
> [159928.908706]  usb_stor_bulk_transfer_sglist.part.3+0x62/0xb0 [usb_storage]
> [159928.908708]  usb_stor_bulk_srb+0x46/0x80 [usb_storage]
> [159928.908711]  usb_stor_Bulk_transport+0x123/0x390 [usb_storage]
> [159928.908712]  ? __switch_to_asm+0x35/0x70
> [159928.908714]  ? __switch_to_asm+0x41/0x70
> [159928.908716]  usb_stor_invoke_transport+0x3c/0x530 [usb_storage]
> [159928.908718]  ? wait_for_common+0xb5/0x170
> [159928.908720]  ? wait_for_common+0x149/0x170
> [159928.908722]  ? wake_up_q+0x80/0x80
> [159928.908724]  usb_stor_transparent_scsi_command+0x9/0x10 [usb_storage]
> [159928.908726]  usb_stor_control_thread+0x1eb/0x2d0 [usb_storage]
> [159928.908729]  kthread+0x122/0x140
> [159928.908732]  ? fill_inquiry_response+0x20/0x20 [usb_storage]
> [159928.908733]  ? kthread_create_on_node+0x60/0x60
> [159928.908735]  ret_from_fork+0x35/0x40
> [159931.594483] usb 1-1: reset high-speed USB device number 13 using xhci_hcd
> 
> Anyone from USB who can help with that?

4.14 is really old.  Does 5.16 resolve this?

thanks,

greg k-h

RE: Trouble with Intenso FlashLine 32GB USB stick on Kernel 4.14

[Schmid, Carsten]

>> [159909.614535] usb 1-1: usbfs: USBDEVFS_CONTROL failed cmd NmeDefaultPrio rqt 192 rq 51 len 2 ret -110
>> [159909.665513] usb 1-1: usbfs: USBDEVFS_CONTROL failed cmd NmeDefaultPrio rqt 192 rq 51 len 2 ret -110
>> [159909.729510] usb 1-1: usbfs: USBDEVFS_CONTROL failed cmd NmeDefaultPrio rqt 192 rq 51 len 2 ret -110
>> [159909.780610] usb 1-1: usbfs: USBDEVFS_CONTROL failed cmd NmeDefaultPrio rqt 192 rq 51 len 2 ret -110
>
> Why is usbfs being used for a storage device?  What userspace program do
> you have that is poking at the device?

Need to ask the userspace maintainers in that project, thanks for the hint.

>> [159928.908633] INFO: task usb-storage:31868 blocked for more than 10 seconds.
>> [159928.908735]  ret_from_fork+0x35/0x40
>> [159931.594483] usb 1-1: reset high-speed USB device number 13 using xhci_hcd
>>
>> Anyone from USB who can help with that?
>
> 4.14 is really old.  Does 5.16 resolve this?
>
Recent Desktop Ubuntu 2104 doesn't show this (kernel 5.4).
In this project, we can't move from 4.14, unfortunately (i'm at 4.14.244 here).

Thanks

Carsten


-----------------
Siemens Electronic Design Automation GmbH; Anschrift: Arnulfstraße 201, 80634 München; Gesellschaft mit beschränkter Haftung; Geschäftsführer: Thomas Heurung, Frank Thürauf; Sitz der Gesellschaft: München; Registergericht München, HRB 106955

Re: Trouble with Intenso FlashLine 32GB USB stick on Kernel 4.14

[gregkh]

On Wed, Mar 16, 2022 at 02:11:47PM +0000, Schmid, Carsten wrote:
> >> [159909.614535] usb 1-1: usbfs: USBDEVFS_CONTROL failed cmd NmeDefaultPrio rqt 192 rq 51 len 2 ret -110
> >> [159909.665513] usb 1-1: usbfs: USBDEVFS_CONTROL failed cmd NmeDefaultPrio rqt 192 rq 51 len 2 ret -110
> >> [159909.729510] usb 1-1: usbfs: USBDEVFS_CONTROL failed cmd NmeDefaultPrio rqt 192 rq 51 len 2 ret -110
> >> [159909.780610] usb 1-1: usbfs: USBDEVFS_CONTROL failed cmd NmeDefaultPrio rqt 192 rq 51 len 2 ret -110
> >
> > Why is usbfs being used for a storage device?  What userspace program do
> > you have that is poking at the device?
> 
> Need to ask the userspace maintainers in that project, thanks for the hint.
> 
> >> [159928.908633] INFO: task usb-storage:31868 blocked for more than 10 seconds.
> >> [159928.908735]  ret_from_fork+0x35/0x40
> >> [159931.594483] usb 1-1: reset high-speed USB device number 13 using xhci_hcd
> >>
> >> Anyone from USB who can help with that?
> >
> > 4.14 is really old.  Does 5.16 resolve this?
> >
> Recent Desktop Ubuntu 2104 doesn't show this (kernel 5.4).
> In this project, we can't move from 4.14, unfortunately (i'm at 4.14.244 here).

Then try using 'git bisect' to track down where the issue gets fixed?

thanks,

greg k-h

Re: Trouble with Intenso FlashLine 32GB USB stick on Kernel 4.14

[Alan Stern]

On Wed, Mar 16, 2022 at 02:57:22PM +0100, gregkh@linuxfoundation.org wrote:
> On Wed, Mar 16, 2022 at 01:39:57PM +0000, Schmid, Carsten wrote:
> > Hi Greg, Mathias,
> > 
> > i have a USB stick that - when plugged in - forces a USB storage hang message.
> > Prior to that message i can see USBDEVFS_CONTROL timeout messages.
> > (BTW the stick works fine on a desktop system with a recent kernel)
> > The stick is having  a USB-C connector, and is connected to a USB2 port through an adapter (that i also used on the Desktop system for a quick check, and it worked there on a USB2 port)
> > 
> > I built a reproducer and collected traces (see attachment).
> > As there is no MAINTAINER given for drivers/usb/core, i send that to you and the USB mailing list to ask someone to look into that.
> > 
> > >From the kernel's dmesg, these are the entries when trace has been recorded.
> > 
> > [159909.172301] usb 1-1: new high-speed USB device number 13 using xhci_hcd
> > [159909.314291] usb 1-1: New USB device found, idVendor=058f, idProduct=6387
> > [159909.314299] usb 1-1: New USB device strings: Mfr=1, Product=2, SerialNumber=3
> > [159909.314303] usb 1-1: Product: Intenso Flash Line
> > [159909.314306] usb 1-1: Manufacturer: ALCOR
> > [159909.314310] usb 1-1: SerialNumber: E13DF681
> > [159909.317093] usb-storage 1-1:1.0: USB Mass Storage device detected
> > [159909.319468] scsi host2: usb-storage 1-1:1.0
> > [159909.614535] usb 1-1: usbfs: USBDEVFS_CONTROL failed cmd NmeDefaultPrio rqt 192 rq 51 len 2 ret -110
> > [159909.665513] usb 1-1: usbfs: USBDEVFS_CONTROL failed cmd NmeDefaultPrio rqt 192 rq 51 len 2 ret -110
> > [159909.729510] usb 1-1: usbfs: USBDEVFS_CONTROL failed cmd NmeDefaultPrio rqt 192 rq 51 len 2 ret -110
> > [159909.780610] usb 1-1: usbfs: USBDEVFS_CONTROL failed cmd NmeDefaultPrio rqt 192 rq 51 len 2 ret -110
> 
> Why is usbfs being used for a storage device?  What userspace program do
> you have that is poking at the device?

The name of the program is mentioned right in the error message (the 
"cmd" item): NmeDefaultPrio.  Don't know what package that program 
belongs to.

Alan Stern

RE: Trouble with Intenso FlashLine 32GB USB stick on Kernel 4.14

[Schmid, Carsten]

>>> [159909.780610] usb 1-1: usbfs: USBDEVFS_CONTROL failed cmd NmeDefaultPrio rqt 192 rq 51 len 2 ret -110
>>
>> Why is usbfs being used for a storage device?  What userspace program do
>> you have that is poking at the device?
>
> The name of the program is mentioned right in the error message (the
> "cmd" item): NmeDefaultPrio.  Don't know what package that program
> belongs to.
>
> Alan Stern
Aaah, thanks for the hint. Will check where that belongs to and contact the people who did it.

Thanks
Carsten
-----------------
Siemens Electronic Design Automation GmbH; Anschrift: Arnulfstraße 201, 80634 München; Gesellschaft mit beschränkter Haftung; Geschäftsführer: Thomas Heurung, Frank Thürauf; Sitz der Gesellschaft: München; Registergericht München, HRB 106955