Crash/hung task in usb-storage thread

Crash/hung task in usb-storage thread

[Schmid, Carsten]

Hi USB maintainers,

we recently have seen a problem with usb-storage when trying to read from a device.
This happened on a 4.14.86 kernel.

The kernel's dmesg shows: (log has been submitted via DLT)
1200.862250 kernel: usb 1-3.1: reset high-speed USB device number 10 using xhci_hcd
1285.466289 kernel: usb 1-3.1: reset high-speed USB device number 10 using xhci_hcd
1291.911286 kernel: usb-storage: Error in queuecommand_lck: us->srb = ffff9d66b02e3528
1292.018079 kernel: usb-storage: Error in queuecommand_lck: us->srb = ffff9d66b02e3528
1292.043073 kernel: usb-storage: Error in queuecommand_lck: us->srb = ffff9d66b02e3528
1292.069078 kernel: usb-storage: Error in queuecommand_lck: us->srb = ffff9d66b02e3528
1292.093066 kernel: usb-storage: Error in queuecommand_lck: us->srb = ffff9d66b02e3528

These messages continue until the hung task mechanism steps in:
1472.135076 kernel: usb-storage: Error in queuecommand_lck: us->srb = ffff9d66b02e3528
1472.135628 kernel: INFO: task usb-storage:7930 blocked for more than 120 seconds.
1472.135633 kernel: Tainted: P U W O 4.14.86-apl #1
1472.135634 kernel: "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
1472.135637 kernel: usb-storage D 0 7930 2 0x80000080
1472.135642 kernel: Call Trace:
1472.135656 kernel: __schedule+0x1c2/0x7b0
1472.135661 kernel: schedule+0x2e/0x90
1472.135664 kernel: schedule_timeout+0x230/0x470
1472.135678 kernel: ? usb_hcd_submit_urb+0x98/0xba0 [usbcore]
1472.135719 kernel: ? schedule_timeout+0x230/0x470
1472.135728 kernel: ? usb_hcd_submit_urb+0x98/0xba0 [usbcore]
1472.135731 kernel: ? __switch_to_asm+0x40/0x70
1472.135733 kernel: ? __switch_to_asm+0x34/0x70
1472.135735 kernel: ? __switch_to_asm+0x40/0x70
1472.135737 kernel: ? __switch_to_asm+0x34/0x70
1472.135741 kernel: wait_for_common+0xb5/0x170
1472.135744 kernel: ? wait_for_common+0xb5/0x170
1472.135748 kernel: ? wake_up_q+0x80/0x80
1472.135752 kernel: wait_for_completion+0x18/0x20
1472.135760 kernel: usb_sg_wait+0x114/0x170 [usbcore]
1472.135946 kernel: usb_stor_bulk_transfer_sglist.part.3+0x62/0xb0 [usb_storage]
1472.135951 kernel: usb_stor_bulk_srb+0x46/0x80 [usb_storage]
1472.135955 kernel: usb_stor_Bulk_transport+0x123/0x390 [usb_storage]
1472.135960 kernel: usb_stor_invoke_transport+0x3c/0x520 [usb_storage]
1472.135965 kernel: ? wait_for_common+0xb5/0x170
1472.135968 kernel: ? wait_for_common+0x149/0x170
1472.135971 kernel: ? wake_up_q+0x80/0x80
1472.135975 kernel: usb_stor_transparent_scsi_command+0x9/0x10 [usb_storage]
1472.135979 kernel: usb_stor_control_thread+0x1eb/0x2d0 [usb_storage]
1472.135984 kernel: kthread+0x122/0x140
1472.135988 kernel: ? fill_inquiry_response+0x20/0x20 [usb_storage]
1472.135991 kernel: ? kthread_create_on_node+0x60/0x60
1472.135994 kernel: ret_from_fork+0x35/0x40
1472.163072 kernel: usb-storage: Error in queuecommand_lck: us->srb = ffff9d66b02e3528

There has been a similar bug being fixed in 3.17 kernel series, maybe the bug has been re-introduced?
https://bugzilla.kernel.org/show_bug.cgi?id=88341

As USB seems to be the causing subsystem, i submit this query here.

Any idea what could cause this?


Best regards
Carsten

Re: Crash/hung task in usb-storage thread

[Greg KH]

On Thu, May 23, 2019 at 11:57:06AM +0000, Schmid, Carsten wrote:
> Hi USB maintainers,
> 
> we recently have seen a problem with usb-storage when trying to read from a device.
> This happened on a 4.14.86 kernel.

Wow that's an old kernel.

> 
> The kernel's dmesg shows: (log has been submitted via DLT)
> 1200.862250 kernel: usb 1-3.1: reset high-speed USB device number 10 using xhci_hcd
> 1285.466289 kernel: usb 1-3.1: reset high-speed USB device number 10 using xhci_hcd
> 1291.911286 kernel: usb-storage: Error in queuecommand_lck: us->srb = ffff9d66b02e3528
> 1292.018079 kernel: usb-storage: Error in queuecommand_lck: us->srb = ffff9d66b02e3528
> 1292.043073 kernel: usb-storage: Error in queuecommand_lck: us->srb = ffff9d66b02e3528
> 1292.069078 kernel: usb-storage: Error in queuecommand_lck: us->srb = ffff9d66b02e3528
> 1292.093066 kernel: usb-storage: Error in queuecommand_lck: us->srb = ffff9d66b02e3528
> 
> These messages continue until the hung task mechanism steps in:
> 1472.135076 kernel: usb-storage: Error in queuecommand_lck: us->srb = ffff9d66b02e3528
> 1472.135628 kernel: INFO: task usb-storage:7930 blocked for more than 120 seconds.
> 1472.135633 kernel: Tainted: P U W O 4.14.86-apl #1
> 1472.135634 kernel: "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
> 1472.135637 kernel: usb-storage D 0 7930 2 0x80000080
> 1472.135642 kernel: Call Trace:
> 1472.135656 kernel: __schedule+0x1c2/0x7b0
> 1472.135661 kernel: schedule+0x2e/0x90
> 1472.135664 kernel: schedule_timeout+0x230/0x470
> 1472.135678 kernel: ? usb_hcd_submit_urb+0x98/0xba0 [usbcore]
> 1472.135719 kernel: ? schedule_timeout+0x230/0x470
> 1472.135728 kernel: ? usb_hcd_submit_urb+0x98/0xba0 [usbcore]
> 1472.135731 kernel: ? __switch_to_asm+0x40/0x70
> 1472.135733 kernel: ? __switch_to_asm+0x34/0x70
> 1472.135735 kernel: ? __switch_to_asm+0x40/0x70
> 1472.135737 kernel: ? __switch_to_asm+0x34/0x70
> 1472.135741 kernel: wait_for_common+0xb5/0x170
> 1472.135744 kernel: ? wait_for_common+0xb5/0x170
> 1472.135748 kernel: ? wake_up_q+0x80/0x80
> 1472.135752 kernel: wait_for_completion+0x18/0x20
> 1472.135760 kernel: usb_sg_wait+0x114/0x170 [usbcore]
> 1472.135946 kernel: usb_stor_bulk_transfer_sglist.part.3+0x62/0xb0 [usb_storage]
> 1472.135951 kernel: usb_stor_bulk_srb+0x46/0x80 [usb_storage]
> 1472.135955 kernel: usb_stor_Bulk_transport+0x123/0x390 [usb_storage]
> 1472.135960 kernel: usb_stor_invoke_transport+0x3c/0x520 [usb_storage]
> 1472.135965 kernel: ? wait_for_common+0xb5/0x170
> 1472.135968 kernel: ? wait_for_common+0x149/0x170
> 1472.135971 kernel: ? wake_up_q+0x80/0x80
> 1472.135975 kernel: usb_stor_transparent_scsi_command+0x9/0x10 [usb_storage]
> 1472.135979 kernel: usb_stor_control_thread+0x1eb/0x2d0 [usb_storage]
> 1472.135984 kernel: kthread+0x122/0x140
> 1472.135988 kernel: ? fill_inquiry_response+0x20/0x20 [usb_storage]
> 1472.135991 kernel: ? kthread_create_on_node+0x60/0x60
> 1472.135994 kernel: ret_from_fork+0x35/0x40
> 1472.163072 kernel: usb-storage: Error in queuecommand_lck: us->srb = ffff9d66b02e3528
> 
> There has been a similar bug being fixed in 3.17 kernel series, maybe the bug has been re-introduced?
> https://bugzilla.kernel.org/show_bug.cgi?id=88341
> 
> As USB seems to be the causing subsystem, i submit this query here.
> 
> Any idea what could cause this?

Can you reproduce this on a "clean" 5.1 kernel release?

thanks,

greg k-h

AW: Crash/hung task in usb-storage thread

[Schmid, Carsten]

> Wow that's an old kernel.
Indeed. Long running project.

> Can you reproduce this on a "clean" 5.1 kernel release?
As this is an automotive embedded target, we currently have 4.14.102 as the newest custom kernel.
Porting a 5.1 will take a lot of effort.

Anyway, thanks for quick response.
I'll check what to do next internally.

Carsten

Re: Crash/hung task in usb-storage thread

[Greg KH]

On Thu, May 23, 2019 at 12:16:59PM +0000, Schmid, Carsten wrote:
> > Wow that's an old kernel.
> Indeed. Long running project.
> 
> > Can you reproduce this on a "clean" 5.1 kernel release?
> As this is an automotive embedded target, we currently have 4.14.102 as the newest custom kernel.

4.14.102 is still old.

> Porting a 5.1 will take a lot of effort.

Then that implies you have an SoC with a few million lines of code added
to the kernel, right?  Nothing we can do here about that mess, you need
to go ask for support from the vendor that is forcing you to use that
kernel, sorry :(

good luck!

greg k-h

AW: Crash/hung task in usb-storage thread

[Schmid, Carsten]

> > > Wow that's an old kernel.
> > Indeed. Long running project.
> > 
> > > Can you reproduce this on a "clean" 5.1 kernel release?
> > As this is an automotive embedded target, we currently have 4.14.102 as the newest custom kernel.
>
> 4.14.102 is still old.
I agree

> > Porting a 5.1 will take a lot of effort.
>
> Then that implies you have an SoC with a few million lines of code added
> to the kernel, right?  Nothing we can do here about that mess, you need
> to go ask for support from the vendor that is forcing you to use that
> kernel, sorry :(
>

Well its at least an x86-64 based SoC.
I'll contact the vendor for sure.

> good luck!
Thanks. Will need it. ;-)

Carsten

Re: Crash/hung task in usb-storage thread

[Greg KH]

On Thu, May 23, 2019 at 12:30:06PM +0000, Schmid, Carsten wrote:
> > > > Wow that's an old kernel.
> > > Indeed. Long running project.
> > > 
> > > > Can you reproduce this on a "clean" 5.1 kernel release?
> > > As this is an automotive embedded target, we currently have 4.14.102 as the newest custom kernel.
> >
> > 4.14.102 is still old.
> I agree
> 
> > > Porting a 5.1 will take a lot of effort.
> >
> > Then that implies you have an SoC with a few million lines of code added
> > to the kernel, right?  Nothing we can do here about that mess, you need
> > to go ask for support from the vendor that is forcing you to use that
> > kernel, sorry :(
> >
> 
> Well its at least an x86-64 based SoC.

An x86 SoC should work on 5.1, what is missing there to keep it from
functioning?  Why hasn't it already been updated to 4.19.y?

thanks,

greg k-h

AW: Crash/hung task in usb-storage thread

[Schmid, Carsten]

> > >
> > > 4.14.102 is still old.
> > I agree
> >
> > > > Porting a 5.1 will take a lot of effort.
> > >
> > > Then that implies you have an SoC with a few million lines of code added
> > > to the kernel, right?  Nothing we can do here about that mess, you need
> > > to go ask for support from the vendor that is forcing you to use that
> > > kernel, sorry :(
> > >
> >
> > Well its at least an x86-64 based SoC.
> 
> An x86 SoC should work on 5.1, what is missing there to keep it from
> functioning?  Why hasn't it already been updated to 4.19.y?
> 
> thanks,
> 
> greg k-h
- Long term stabilisation of product.
- Concerns a product update - already in production
- A big bunch of testing done on the product
- Bug occurence currently "once" - no reproduction
Hard work.

Best regards
Carsten

Re: Crash/hung task in usb-storage thread

[Greg KH]

On Thu, May 23, 2019 at 01:16:12PM +0000, Schmid, Carsten wrote:
> > > >
> > > > 4.14.102 is still old.
> > > I agree
> > >
> > > > > Porting a 5.1 will take a lot of effort.
> > > >
> > > > Then that implies you have an SoC with a few million lines of code added
> > > > to the kernel, right?  Nothing we can do here about that mess, you need
> > > > to go ask for support from the vendor that is forcing you to use that
> > > > kernel, sorry :(
> > > >
> > >
> > > Well its at least an x86-64 based SoC.
> > 
> > An x86 SoC should work on 5.1, what is missing there to keep it from
> > functioning?  Why hasn't it already been updated to 4.19.y?
> > 
> > thanks,
> > 
> > greg k-h
> - Long term stabilisation of product.
> - Concerns a product update - already in production

So, you have a huge list of known bugs/vulnerabilities in that device
now, yet they refuse to update.  Not good :(

Best of luck,

greg k-h

Re: Crash/hung task in usb-storage thread

[Alan Stern]

On Thu, 23 May 2019, Schmid, Carsten wrote:

> Hi USB maintainers,
> 
> we recently have seen a problem with usb-storage when trying to read from a device.
> This happened on a 4.14.86 kernel.
> 
> The kernel's dmesg shows: (log has been submitted via DLT)
> 1200.862250 kernel: usb 1-3.1: reset high-speed USB device number 10 using xhci_hcd
> 1285.466289 kernel: usb 1-3.1: reset high-speed USB device number 10 using xhci_hcd
> 1291.911286 kernel: usb-storage: Error in queuecommand_lck: us->srb = ffff9d66b02e3528
> 1292.018079 kernel: usb-storage: Error in queuecommand_lck: us->srb = ffff9d66b02e3528
> 1292.043073 kernel: usb-storage: Error in queuecommand_lck: us->srb = ffff9d66b02e3528
> 1292.069078 kernel: usb-storage: Error in queuecommand_lck: us->srb = ffff9d66b02e3528
> 1292.093066 kernel: usb-storage: Error in queuecommand_lck: us->srb = ffff9d66b02e3528

Since there haven't been any substantive change to usb-storage since 
4.14 was released, there's a good chance this is a problem with 
xhci-hcd.

Is this problem repeatable?  Can you collect a usbmon trace showing 
what happens when the problem occurs?

> There has been a similar bug being fixed in 3.17 kernel series, maybe the bug has been re-introduced?
> https://bugzilla.kernel.org/show_bug.cgi?id=88341

That is _extremely_ unlikely.

> As USB seems to be the causing subsystem, i submit this query here.
> 
> Any idea what could cause this?

The particular error message you got means that the SCSI layer asked 
usb-storage to send a command to the device before the previous command 
was completed.  But without more information there's no way to tell why 
it did this.

Alan Stern

AW: Crash/hung task in usb-storage thread

[Schmid, Carsten]

> On Thu, 23 May 2019, Schmid, Carsten wrote:
> 
> > Hi USB maintainers,
> >
> > we recently have seen a problem with usb-storage when trying to read
> from a device.
> > This happened on a 4.14.86 kernel.
> >
> > The kernel's dmesg shows: (log has been submitted via DLT)
> > 1200.862250 kernel: usb 1-3.1: reset high-speed USB device number 10
> using xhci_hcd
> > 1285.466289 kernel: usb 1-3.1: reset high-speed USB device number 10
> using xhci_hcd
> > 1291.911286 kernel: usb-storage: Error in queuecommand_lck: us->srb =
> ffff9d66b02e3528
> > 1292.018079 kernel: usb-storage: Error in queuecommand_lck: us->srb =
> ffff9d66b02e3528
> > 1292.043073 kernel: usb-storage: Error in queuecommand_lck: us->srb =
> ffff9d66b02e3528
> > 1292.069078 kernel: usb-storage: Error in queuecommand_lck: us->srb =
> ffff9d66b02e3528
> > 1292.093066 kernel: usb-storage: Error in queuecommand_lck: us->srb =
> ffff9d66b02e3528
> 
> Since there haven't been any substantive change to usb-storage since
> 4.14 was released, there's a good chance this is a problem with
> xhci-hcd.
> 
> Is this problem repeatable?  Can you collect a usbmon trace showing
> what happens when the problem occurs?
> 
Unfortunately this happened in the field on a test drive.
I don't have access to the device.
So, no, can't be reproduced by now.

> > There has been a similar bug being fixed in 3.17 kernel series, maybe the
> bug has been re-introduced?
> > https://bugzilla.kernel.org/show_bug.cgi?id=88341
> 
> That is _extremely_ unlikely.
> 
Looked into the history of that bug report.
Strange: no fix is menioned.
Reported: 2014-17-11
Remark on 2019-02-26
No hint to a real fix.
It simply disappeared ...

> > As USB seems to be the causing subsystem, i submit this query here.
> >
> > Any idea what could cause this?
> 
> The particular error message you got means that the SCSI layer asked
> usb-storage to send a command to the device before the previous command
> was completed.  But without more information there's no way to tell why
> it did this.
> 
> Alan Stern
That's at least a hint i can forward to the vendor.

Thanks Alan, 
Carsten

Re: Crash/hung task in usb-storage thread

[Greg KH]

On Fri, May 24, 2019 at 01:33:14PM +0000, Schmid, Carsten wrote:
> > On Thu, 23 May 2019, Schmid, Carsten wrote:
> > 
> > > Hi USB maintainers,
> > >
> > > we recently have seen a problem with usb-storage when trying to read
> > from a device.
> > > This happened on a 4.14.86 kernel.
> > >
> > > The kernel's dmesg shows: (log has been submitted via DLT)
> > > 1200.862250 kernel: usb 1-3.1: reset high-speed USB device number 10
> > using xhci_hcd
> > > 1285.466289 kernel: usb 1-3.1: reset high-speed USB device number 10
> > using xhci_hcd
> > > 1291.911286 kernel: usb-storage: Error in queuecommand_lck: us->srb =
> > ffff9d66b02e3528
> > > 1292.018079 kernel: usb-storage: Error in queuecommand_lck: us->srb =
> > ffff9d66b02e3528
> > > 1292.043073 kernel: usb-storage: Error in queuecommand_lck: us->srb =
> > ffff9d66b02e3528
> > > 1292.069078 kernel: usb-storage: Error in queuecommand_lck: us->srb =
> > ffff9d66b02e3528
> > > 1292.093066 kernel: usb-storage: Error in queuecommand_lck: us->srb =
> > ffff9d66b02e3528
> > 
> > Since there haven't been any substantive change to usb-storage since
> > 4.14 was released, there's a good chance this is a problem with
> > xhci-hcd.
> > 
> > Is this problem repeatable?  Can you collect a usbmon trace showing
> > what happens when the problem occurs?
> > 
> Unfortunately this happened in the field on a test drive.
> I don't have access to the device.
> So, no, can't be reproduced by now.
> 
> > > There has been a similar bug being fixed in 3.17 kernel series, maybe the
> > bug has been re-introduced?
> > > https://bugzilla.kernel.org/show_bug.cgi?id=88341
> > 
> > That is _extremely_ unlikely.
> > 
> Looked into the history of that bug report.
> Strange: no fix is menioned.
> Reported: 2014-17-11
> Remark on 2019-02-26
> No hint to a real fix.
> It simply disappeared ...

We do not track USB bugs in bugzilla.kernel.org, so NEVER treat that as
the state of anything with regards to USB and Linux, sorry.  Ask here on
the mailing list instead.

The fact that nothing else is shown on that bug is to be expected, and
is normal.

thanks,

greg k-h

Re: AW: Crash/hung task in usb-storage thread

[Alan Stern]

On Fri, 24 May 2019, Schmid, Carsten wrote:

> > On Thu, 23 May 2019, Schmid, Carsten wrote:
> > 
> > > Hi USB maintainers,
> > >
> > > we recently have seen a problem with usb-storage when trying to read
> > from a device.
> > > This happened on a 4.14.86 kernel.
> > >
> > > The kernel's dmesg shows: (log has been submitted via DLT)
> > > 1200.862250 kernel: usb 1-3.1: reset high-speed USB device number 10
> > using xhci_hcd
> > > 1285.466289 kernel: usb 1-3.1: reset high-speed USB device number 10
> > using xhci_hcd
> > > 1291.911286 kernel: usb-storage: Error in queuecommand_lck: us->srb =
> > ffff9d66b02e3528
> > > 1292.018079 kernel: usb-storage: Error in queuecommand_lck: us->srb =
> > ffff9d66b02e3528
> > > 1292.043073 kernel: usb-storage: Error in queuecommand_lck: us->srb =
> > ffff9d66b02e3528
> > > 1292.069078 kernel: usb-storage: Error in queuecommand_lck: us->srb =
> > ffff9d66b02e3528
> > > 1292.093066 kernel: usb-storage: Error in queuecommand_lck: us->srb =
> > ffff9d66b02e3528
> > 
> > Since there haven't been any substantive change to usb-storage since
> > 4.14 was released, there's a good chance this is a problem with
> > xhci-hcd.
> > 
> > Is this problem repeatable?  Can you collect a usbmon trace showing
> > what happens when the problem occurs?
> > 
> Unfortunately this happened in the field on a test drive.
> I don't have access to the device.
> So, no, can't be reproduced by now.
> 
> > > There has been a similar bug being fixed in 3.17 kernel series, maybe the
> > bug has been re-introduced?
> > > https://bugzilla.kernel.org/show_bug.cgi?id=88341
> > 
> > That is _extremely_ unlikely.
> > 
> Looked into the history of that bug report.
> Strange: no fix is menioned.
> Reported: 2014-17-11
> Remark on 2019-02-26
> No hint to a real fix.
> It simply disappeared ...
> 
> > > As USB seems to be the causing subsystem, i submit this query here.
> > >
> > > Any idea what could cause this?
> > 
> > The particular error message you got means that the SCSI layer asked
> > usb-storage to send a command to the device before the previous command
> > was completed.  But without more information there's no way to tell why
> > it did this.
> > 
> > Alan Stern
> That's at least a hint i can forward to the vendor.

A more detailed look through the email archives and git log finds the 
following two commits, either of which might be relevant:

	511833acfc06 ("SCSI: fix regression in scsi_send_eh_cmnd()")
	f45681f9beca ("USB: Add quirk to support DJI CineSSD")

For the second commit, it might be that your storage device requires 
the US_FL_NO_ATA_1X quirk in unusual_devs.h.

Alan Stern

AW: AW: Crash/hung task in usb-storage thread

[Schmid, Carsten]

> A more detailed look through the email archives and git log finds the
> following two commits, either of which might be relevant:
> 
> 	511833acfc06 ("SCSI: fix regression in scsi_send_eh_cmnd()")
> 	f45681f9beca ("USB: Add quirk to support DJI CineSSD")
> 
> For the second commit, it might be that your storage device requires
> the US_FL_NO_ATA_1X quirk in unusual_devs.h.
> 
> Alan Stern

Hi Alan,
both patches are present in our 4.14.86.
And, additionally, we disabled lpm for hotpluggable devices.

Seems we need to find out the device's ID and add a patch similar to the DJI quirk.

Could be a path to follow up.

Thanks,
Carsten