Failure prints during format or mounting a usb storage device

Failure prints during format or mounting a usb storage device

[Sai Pavan Boddu]

[-- Attachment #1: Type: text/plain, Size: 2269 bytes --]

Hi,

We are seeing some errors when a usb-storage device is formatted or mounted on the guest. Below is commit I have bisected it.

**************
Errors:

/ # mount /dev/sda /mnt
[New Thread 0x7fffd4680700 (LWP 23270)]
[   33.258454] usb 2-1: reset SuperSpeed Gen 1 USB device number 2 using xhci_hcd
[   33.399528] usb 2-1: reset SuperSpeed Gen 1 USB device number 2 using xhci_hcd
[   33.544621] usb 2-1: reset SuperSpeed Gen 1 USB device number 2 using xhci_hcd
[   33.560460] sd 2:0:0:0: [sda] tag#0 FAILED Result: hostbyte=DID_ERROR driverbyte=DRIVER_OK
[   33.562405] sd 2:0:0:0: [sda] tag#0 CDB: Read(10) 28 00 00 00 10 00 00 00 01 00
[   33.563389] blk_update_request: I/O error, dev sda, sector 4096 op 0x0:(READ) flags 0x80700 phys_seg 1 prio class 0
/ # [Thread 0x7fffd4680700 (LWP 23270) exited]

================
Bisect commit :

commit 7ad3d51ebb8a522ffcad391c4bef281245739dde
Author: Paul Zimmerman <pauldzim@gmail.com>
Date:   Wed May 20 16:53:47 2020 -0700

    usb: add short-packet handling to usb-storage driver

    The dwc-hsotg (dwc2) USB host depends on a short packet to
    indicate the end of an IN transfer. The usb-storage driver
    currently doesn't provide this, so fix it.

    I have tested this change rather extensively using a PC
    emulation with xhci, ehci, and uhci controllers, and have
    not observed any regressions.

    Signed-off-by: Paul Zimmerman <pauldzim@gmail.com>
    Message-id: 20200520235349.21215-6-pauldzim@gmail.com
    Signed-off-by: Peter Maydell peter.maydell@linaro.org<mailto:peter.maydell@linaro.org>

=====================
Steps to reproduce:

  1.  x86_64-softmmu/qemu-system-x86_64 -kernel bzImage -nographic -append "console=ttyS0" -m 512M -initrd initramfs.cpio.gz -device qemu-xhci,id=xhci1 -drive file=./usb.img,if=none,id=stick
  2.  Hotplug usb-storage:
                                device_add usb-storage,bus=xhci1.0,port=1,id=usbdev1,drive=stick

  1.  Format &  mount the detected device
mkfs.vfat -F 32 /dev/sda
mount /dev/sda /mnt
You can find the similar errors mentioned above at this stage.
Test Environment:
       Host:  Ubuntu 16.04 LTS
       Guest:  kernel version: 5.4.0 & BusyBox v1.31.1

Thanks & Regards,
Sai Pavan


[-- Attachment #2: Type: text/html, Size: 8613 bytes --]

Re: Failure prints during format or mounting a usb storage device

[Paul Zimmerman]

[-- Attachment #1: Type: text/plain, Size: 2560 bytes --]

On Sat, Jul 4, 2020 at 11:21 AM Sai Pavan Boddu <saipava@xilinx.com> wrote:

> Hi,
>
>
>
> We are seeing some errors when a usb-storage device is formatted or
> mounted on the guest. Below is commit I have bisected it.
>
>
>
> **************
>
> Errors:
>
>
>
> / # mount /dev/sda /mnt
>
> [New Thread 0x7fffd4680700 (LWP 23270)]
>
> [   33.258454] usb 2-1: reset SuperSpeed Gen 1 USB device number 2 using
> xhci_hcd
>
> [   33.399528] usb 2-1: reset SuperSpeed Gen 1 USB device number 2 using
> xhci_hcd
>
> [   33.544621] usb 2-1: reset SuperSpeed Gen 1 USB device number 2 using
> xhci_hcd
>
> [   33.560460] sd 2:0:0:0: [sda] tag#0 FAILED Result: hostbyte=DID_ERROR
> driverbyte=DRIVER_OK
>
> [   33.562405] sd 2:0:0:0: [sda] tag#0 CDB: Read(10) 28 00 00 00 10 00 00
> 00 01 00
>
> [   33.563389] blk_update_request: I/O error, dev sda, sector 4096 op
> 0x0:(READ) flags 0x80700 phys_seg 1 prio class 0
>
> / # [Thread 0x7fffd4680700 (LWP 23270) exited]
>
>
>
> ================
>
> Bisect commit :
>
>
>
> commit 7ad3d51ebb8a522ffcad391c4bef281245739dde
>
> Author: Paul Zimmerman <pauldzim@gmail.com>
>
> Date:   Wed May 20 16:53:47 2020 -0700
>
>
>
>     usb: add short-packet handling to usb-storage driver
>
>
>
>     The dwc-hsotg (dwc2) USB host depends on a short packet to
>
>     indicate the end of an IN transfer. The usb-storage driver
>
>     currently doesn't provide this, so fix it.
>
>
>
>     I have tested this change rather extensively using a PC
>
>     emulation with xhci, ehci, and uhci controllers, and have
>
>     not observed any regressions.
>
>
>
>     Signed-off-by: Paul Zimmerman <pauldzim@gmail.com>
>
>     Message-id: 20200520235349.21215-6-pauldzim@gmail.com
>
>     Signed-off-by: Peter Maydell peter.maydell@linaro.org
>
>
>
> =====================
>
> Steps to reproduce:
>
>    1. x86_64-softmmu/qemu-system-x86_64 -kernel bzImage -nographic
>    -append "console=ttyS0" -m 512M -initrd initramfs.cpio.gz -device
>    qemu-xhci,id=xhci1 -drive file=./usb.img,if=none,id=stick
>    2. Hotplug usb-storage:
>
>                                 device_add
> usb-storage,bus=xhci1.0,port=1,id=usbdev1,drive=stick
>
>    1. Format &  mount the detected device
>
> mkfs.vfat -F 32 /dev/sda
> mount /dev/sda /mnt
>
> You can find the similar errors mentioned above at this stage.
>
> Test Environment:
>
>        Host:  Ubuntu 16.04 LTS
>
>        Guest:  kernel version: 5.4.0 & BusyBox v1.31.1
>
>
>
> Thanks & Regards,
>
> Sai Pavan
>
>
>
I can try to reproduce this on Monday, if no one beats me to it.

Thanks,
Paul

[-- Attachment #2: Type: text/html, Size: 5713 bytes --]

Re: Failure prints during format or mounting a usb storage device

[Paul Zimmerman]

[-- Attachment #1: Type: text/plain, Size: 3124 bytes --]

On Sat, Jul 4, 2020 at 11:24 AM Paul Zimmerman <pauldzim@gmail.com> wrote:

>
>
> On Sat, Jul 4, 2020 at 11:21 AM Sai Pavan Boddu <saipava@xilinx.com>
> wrote:
>
>> Hi,
>>
>>
>>
>> We are seeing some errors when a usb-storage device is formatted or
>> mounted on the guest. Below is commit I have bisected it.
>>
>>
>>
>> **************
>>
>> Errors:
>>
>>
>>
>> / # mount /dev/sda /mnt
>>
>> [New Thread 0x7fffd4680700 (LWP 23270)]
>>
>> [   33.258454] usb 2-1: reset SuperSpeed Gen 1 USB device number 2 using
>> xhci_hcd
>>
>> [   33.399528] usb 2-1: reset SuperSpeed Gen 1 USB device number 2 using
>> xhci_hcd
>>
>> [   33.544621] usb 2-1: reset SuperSpeed Gen 1 USB device number 2 using
>> xhci_hcd
>>
>> [   33.560460] sd 2:0:0:0: [sda] tag#0 FAILED Result: hostbyte=DID_ERROR
>> driverbyte=DRIVER_OK
>>
>> [   33.562405] sd 2:0:0:0: [sda] tag#0 CDB: Read(10) 28 00 00 00 10 00 00
>> 00 01 00
>>
>> [   33.563389] blk_update_request: I/O error, dev sda, sector 4096 op
>> 0x0:(READ) flags 0x80700 phys_seg 1 prio class 0
>>
>> / # [Thread 0x7fffd4680700 (LWP 23270) exited]
>>
>>
>>
>> ================
>>
>> Bisect commit :
>>
>>
>>
>> commit 7ad3d51ebb8a522ffcad391c4bef281245739dde
>>
>> Author: Paul Zimmerman <pauldzim@gmail.com>
>>
>> Date:   Wed May 20 16:53:47 2020 -0700
>>
>>
>>
>>     usb: add short-packet handling to usb-storage driver
>>
>>
>>
>>     The dwc-hsotg (dwc2) USB host depends on a short packet to
>>
>>     indicate the end of an IN transfer. The usb-storage driver
>>
>>     currently doesn't provide this, so fix it.
>>
>>
>>
>>     I have tested this change rather extensively using a PC
>>
>>     emulation with xhci, ehci, and uhci controllers, and have
>>
>>     not observed any regressions.
>>
>>
>>
>>     Signed-off-by: Paul Zimmerman <pauldzim@gmail.com>
>>
>>     Message-id: 20200520235349.21215-6-pauldzim@gmail.com
>>
>>     Signed-off-by: Peter Maydell peter.maydell@linaro.org
>>
>>
>>
>> =====================
>>
>> Steps to reproduce:
>>
>>    1. x86_64-softmmu/qemu-system-x86_64 -kernel bzImage -nographic
>>    -append "console=ttyS0" -m 512M -initrd initramfs.cpio.gz -device
>>    qemu-xhci,id=xhci1 -drive file=./usb.img,if=none,id=stick
>>    2. Hotplug usb-storage:
>>
>>                                 device_add
>> usb-storage,bus=xhci1.0,port=1,id=usbdev1,drive=stick
>>
>>    1. Format &  mount the detected device
>>
>> mkfs.vfat -F 32 /dev/sda
>> mount /dev/sda /mnt
>>
>> You can find the similar errors mentioned above at this stage.
>>
>> Test Environment:
>>
>>        Host:  Ubuntu 16.04 LTS
>>
>>        Guest:  kernel version: 5.4.0 & BusyBox v1.31.1
>>
>>
>>
>> Thanks & Regards,
>>
>> Sai Pavan
>>
>>
>>
> I can try to reproduce this on Monday, if no one beats me to it.
>

>
I am able to reproduce this. Despite the errors in dmesg, the drive does
end up mounting and working OK, which is probably why I didn’t spot it
during testing.
Sai, does the drive work OK for you too despite the errors?

Thanks,
Paul

[-- Attachment #2: Type: text/html, Size: 6307 bytes --]

Re: Failure prints during format or mounting a usb storage device

[Paul Zimmerman]

On 7/6/20 3:21 PM, Paul Zimmerman wrote:
> 
> On Sat, Jul 4, 2020 at 11:24 AM Paul Zimmerman <pauldzim@gmail.com <mailto:pauldzim@gmail.com>> wrote:
> 
> 
> 
>     On Sat, Jul 4, 2020 at 11:21 AM Sai Pavan Boddu <saipava@xilinx.com <mailto:saipava@xilinx.com>> wrote:
> 
>         Hi,____
> 
>         __ __
> 
>         We are seeing some errors when a usb-storage device is formatted or mounted on the guest. Below is commit I have bisected it.____
> 
>         __ __
> 
>         **************____
> 
>         Errors:____
> 
>         __ __
> 
>         / # mount /dev/sda /mnt____
> 
>         [New Thread 0x7fffd4680700 (LWP 23270)]____
> 
>         [   33.258454] usb 2-1: reset SuperSpeed Gen 1 USB device number 2 using xhci_hcd____
> 
>         [   33.399528] usb 2-1: reset SuperSpeed Gen 1 USB device number 2 using xhci_hcd____
> 
>         [   33.544621] usb 2-1: reset SuperSpeed Gen 1 USB device number 2 using xhci_hcd____
> 
>         [   33.560460] sd 2:0:0:0: [sda] tag#0 FAILED Result: hostbyte=DID_ERROR driverbyte=DRIVER_OK____
> 
>         [   33.562405] sd 2:0:0:0: [sda] tag#0 CDB: Read(10) 28 00 00 00 10 00 00 00 01 00____
> 
>         [   33.563389] blk_update_request: I/O error, dev sda, sector 4096 op 0x0:(READ) flags 0x80700 phys_seg 1 prio class 0____
> 
>         / # [Thread 0x7fffd4680700 (LWP 23270) exited]____
> 
>         __ __
> 
>         ================____
> 
>         Bisect commit :____
> 
>         __ __
> 
>         commit 7ad3d51ebb8a522ffcad391c4bef281245739dde____
> 
>         Author: Paul Zimmerman <pauldzim@gmail.com <mailto:pauldzim@gmail.com>>____
> 
>         Date:   Wed May 20 16:53:47 2020 -0700____
> 
>         __ __
> 
>              usb: add short-packet handling to usb-storage driver____
> 
>         __ __
> 
>              The dwc-hsotg (dwc2) USB host depends on a short packet to____
> 
>              indicate the end of an IN transfer. The usb-storage driver____
> 
>              currently doesn't provide this, so fix it.____
> 
>         __ __
> 
>              I have tested this change rather extensively using a PC____
> 
>              emulation with xhci, ehci, and uhci controllers, and have____
> 
>              not observed any regressions.____
> 
>         __ __
> 
>              Signed-off-by: Paul Zimmerman <pauldzim@gmail.com <mailto:pauldzim@gmail.com>>____
> 
>              Message-id: 20200520235349.21215-6-pauldzim@gmail.com <mailto:20200520235349.21215-6-pauldzim@gmail.com>____
> 
>              Signed-off-by: Peter Maydell peter.maydell@linaro.org <mailto:peter.maydell@linaro.org>____
> 
>         __ __
> 
>         =====================____
> 
>         Steps to reproduce:____
> 
>          1. x86_64-softmmu/qemu-system-x86_64 -kernel bzImage -nographic -append "console=ttyS0" -m 512M -initrd initramfs.cpio.gz -device qemu-xhci,id=xhci1 -drive file=./usb.img,if=none,id=stick____
>          2. Hotplug usb-storage:____
> 
>                                          device_add usb-storage,bus=xhci1.0,port=1,id=usbdev1,drive=stick____
> 
>          3. Format &  mount the detected device____
> 
>         mkfs.vfat -F 32 /dev/sda
>         mount /dev/sda /mnt____
> 
>         You can find the similar errors mentioned above at this stage.____
> 
>         ____
> 
>         Test Environment:____
> 
>                 Host:  Ubuntu 16.04 LTS____
> 
>                 Guest:  kernel version: 5.4.0 & BusyBox v1.31.1____
> 
>         __ __
> 
>         Thanks & Regards,____
> 
>         Sai Pavan____
> 
>         __ __
> 
>     I can try to reproduce this on Monday, if no one beats me to it.
> 
> 
> 
> I am able to reproduce this. Despite the errors in dmesg, the drive
> does end up mounting and working OK, which is probably why I didn’t
> spot it during testing. Sai, does the drive work OK for you too
> despite the errors?
> 
> Thanks,
> Paul

Gerd, do you know the purpose of the 'short_not_ok' parameter to
usb_packet_setup()? The simple patch below fixes the reported problem,
but I don't know if it could cause some other problems for XHCI.
hcd-ehci, hcd-ohci, hcd-uhci all set the parameter conditionally,
but hcd-xhci never sets it. I don't understand the purpose of the
parameter myself.

diff --git a/hw/usb/hcd-xhci.c b/hw/usb/hcd-xhci.c
index b330e36fe6..9fb96fdd66 100644
--- a/hw/usb/hcd-xhci.c
+++ b/hw/usb/hcd-xhci.c
@@ -1614,7 +1614,7 @@ static int xhci_setup_packet(XHCITransfer *xfer)
  
      xhci_xfer_create_sgl(xfer, dir == USB_TOKEN_IN); /* Also sets int_req */
  
      xhci_xfer_create_sgl(xfer, dir == USB_TOKEN_IN); /* Also sets int_req */
      usb_packet_setup(&xfer->packet, dir, ep, xfer->streamid,
-                     xfer->trbs[0].addr, false, xfer->int_req);
+                     xfer->trbs[0].addr, dir == USB_TOKEN_IN, xfer->int_req);
      usb_packet_map(&xfer->packet, &xfer->sgl);
      DPRINTF("xhci: setup packet pid 0x%x addr %d ep %d\n",
              xfer->packet.pid, ep->dev->addr, ep->nr);

Thanks,
Paul

Re: Failure prints during format or mounting a usb storage device

[Gerd Hoffmann]

  Hi,
> 
> Gerd, do you know the purpose of the 'short_not_ok' parameter to
> usb_packet_setup()?

Well, some usb host controllers have a flag in the transfer control
blocks to indicate the host controller should stop processing requests
in case of a short transfer.

The usb core uses the flag to just to that (i.e. halt the endpoint on
short transfers).  It is also checked when usb-host pipelines requests
(requests queued after a short-not-ok packet can't be pipelined because
we don't know yet whenever we should continue processing the endpoint or
not).

xhci has no such flag so the flag is never set.

> The simple patch below fixes the reported problem,
> but I don't know if it could cause some other problems for XHCI.
> hcd-ehci, hcd-ohci, hcd-uhci all set the parameter conditionally,
> but hcd-xhci never sets it. I don't understand the purpose of the
> parameter myself.
> 
> diff --git a/hw/usb/hcd-xhci.c b/hw/usb/hcd-xhci.c
> index b330e36fe6..9fb96fdd66 100644
> --- a/hw/usb/hcd-xhci.c
> +++ b/hw/usb/hcd-xhci.c
> @@ -1614,7 +1614,7 @@ static int xhci_setup_packet(XHCITransfer *xfer)
>      xhci_xfer_create_sgl(xfer, dir == USB_TOKEN_IN); /* Also sets int_req */
>      xhci_xfer_create_sgl(xfer, dir == USB_TOKEN_IN); /* Also sets int_req */
>      usb_packet_setup(&xfer->packet, dir, ep, xfer->streamid,
> -                     xfer->trbs[0].addr, false, xfer->int_req);
> +                     xfer->trbs[0].addr, dir == USB_TOKEN_IN, xfer->int_req);

I suspect this might lead to queues being halted even though they should
not.

Why does 7ad3d51ebb8a522ffcad391c4bef281245739dde look at short-not-ok?

take care,
  Gerd

Re: Failure prints during format or mounting a usb storage device

[Paul Zimmerman]

[-- Attachment #1: Type: text/plain, Size: 1984 bytes --]

On Tue, Jul 7, 2020 at 12:57 AM Gerd Hoffmann <kraxel@redhat.com> wrote:

>   Hi,
> >
> > Gerd, do you know the purpose of the 'short_not_ok' parameter to
> > usb_packet_setup()?
>
> Well, some usb host controllers have a flag in the transfer control
> blocks to indicate the host controller should stop processing requests
> in case of a short transfer.
>
> The usb core uses the flag to just to that (i.e. halt the endpoint on
> short transfers).  It is also checked when usb-host pipelines requests
> (requests queued after a short-not-ok packet can't be pipelined because
> we don't know yet whenever we should continue processing the endpoint or
> not).
>
> xhci has no such flag so the flag is never set.
>
> > The simple patch below fixes the reported problem,
> > but I don't know if it could cause some other problems for XHCI.
> > hcd-ehci, hcd-ohci, hcd-uhci all set the parameter conditionally,
> > but hcd-xhci never sets it. I don't understand the purpose of the
> > parameter myself.
> >
> > diff --git a/hw/usb/hcd-xhci.c b/hw/usb/hcd-xhci.c
> > index b330e36fe6..9fb96fdd66 100644
> > --- a/hw/usb/hcd-xhci.c
> > +++ b/hw/usb/hcd-xhci.c
> > @@ -1614,7 +1614,7 @@ static int xhci_setup_packet(XHCITransfer *xfer)
> >      xhci_xfer_create_sgl(xfer, dir == USB_TOKEN_IN); /* Also sets
> int_req */
> >      usb_packet_setup(&xfer->packet, dir, ep, xfer->streamid,
> > -                     xfer->trbs[0].addr, false, xfer->int_req);
> > +                     xfer->trbs[0].addr, dir == USB_TOKEN_IN,
> xfer->int_req);
>
> I suspect this might lead to queues being halted even though they should
> not.
>
> Why does 7ad3d51ebb8a522ffcad391c4bef281245739dde look at short-not-ok?
>

Because the patch changes dev-storage to terminate the transfer if a
short packet is received, so I figured 'short-not-ok' should affect
that behavior.

I guess instead I could add another flag that only hcd-dwc2 sets. Does
that sound OK to you?

Thanks,
Paul


> take care,
>   Gerd
>
>

[-- Attachment #2: Type: text/html, Size: 3529 bytes --]

Re: Failure prints during format or mounting a usb storage device

[Gerd Hoffmann]

  Hi,

> > Why does 7ad3d51ebb8a522ffcad391c4bef281245739dde look at short-not-ok?
> 
> Because the patch changes dev-storage to terminate the transfer if a
> short packet is received, so I figured 'short-not-ok' should affect
> that behavior.

I don't think so.  dev-storage should not need to look at short-not-ok.

> I guess instead I could add another flag that only hcd-dwc2 sets. Does
> that sound OK to you?

Sounds like that'll be another workaround.  dev-storage should not need
to know what kind of host adapter is used ...

A usb-storage transfer looks like this:

  (1) out transfer with the command (USB_MSDM_CBW)
  (2) data transfer, might be:
      - out (USB_MSDM_DATAOUT) for writes, or
      - in (USB_MSDM_DATAIN) for reads, or
      - nothing.
      depending on the scsi command.
  (3) in transfer with the status (USB_MSDM_CSW).

(1) and (3) usually fit into a single usb packet.
(2) can be multiple usb packets.

The critical case seem to be reads, i.e. we have in transfers for
both (2) and (3), and the transition from USB_MSDM_DATAIN state to
USB_MSDM_CSW state.

What is the sequence of usb packets submitted by the guest to hcd-dwc2
for reads?  Where exactly does it expect a short transfer?

take care,
  Gerd

Re: Failure prints during format or mounting a usb storage device

[Paul Zimmerman]

[-- Attachment #1: Type: text/plain, Size: 1883 bytes --]

On Wed, Jul 8, 2020 at 12:29 AM Gerd Hoffmann <kraxel@redhat.com> wrote:

>   Hi,
>
> > > Why does 7ad3d51ebb8a522ffcad391c4bef281245739dde look at short-not-ok?
> >
> > Because the patch changes dev-storage to terminate the transfer if a
> > short packet is received, so I figured 'short-not-ok' should affect
> > that behavior.
>
> I don't think so.  dev-storage should not need to look at short-not-ok.
>
> > I guess instead I could add another flag that only hcd-dwc2 sets. Does
> > that sound OK to you?
>
> Sounds like that'll be another workaround.  dev-storage should not need
> to know what kind of host adapter is used ...
>
> A usb-storage transfer looks like this:
>
>   (1) out transfer with the command (USB_MSDM_CBW)
>   (2) data transfer, might be:
>       - out (USB_MSDM_DATAOUT) for writes, or
>       - in (USB_MSDM_DATAIN) for reads, or
>       - nothing.
>       depending on the scsi command.
>   (3) in transfer with the status (USB_MSDM_CSW).
>
> (1) and (3) usually fit into a single usb packet.
> (2) can be multiple usb packets.
>
> The critical case seem to be reads, i.e. we have in transfers for
> both (2) and (3), and the transition from USB_MSDM_DATAIN state to
> USB_MSDM_CSW state.
>
> What is the sequence of usb packets submitted by the guest to hcd-dwc2
> for reads?  Where exactly does it expect a short transfer?
>

DWC2 needs a short transfer to indicate the end of all IN transfers
that are not an exact multiple of max packet size. This means that
the guest USB driver submits all read requests not with the actual
length of the read, but with a length that is rounded up to a
multiple of MPS.

IIRC, without the dev-storage patch, the very first SCSI command
would get stuck waiting for the CSW, because the CSW is not a
multiple of MPS. I will have to work on getting a debug trace for
you, I'll get back to you with that.

Thanks,
Paul

[-- Attachment #2: Type: text/html, Size: 3320 bytes --]

Re: Failure prints during format or mounting a usb storage device

[Gerd Hoffmann]

  Hi,

> IIRC, without the dev-storage patch, the very first SCSI command
> would get stuck waiting for the CSW, because the CSW is not a
> multiple of MPS. I will have to work on getting a debug trace for
> you, I'll get back to you with that.

Hmm, dev-storage should be fine with the packet being larger than
needed.  It'll actually do a short transfer then.  So I suspect the
patch just papers over the underlying issue.

Can you post a trace of this?

(dev-storage has no trace support, so I think tracing usb_dwc2* to
 stderr and enable DEBUG_MSD in dev-storage.c works best)

take care,
  Gerd

Re: Failure prints during format or mounting a usb storage device

[Paul Zimmerman]

[-- Attachment #1.1: Type: text/plain, Size: 1429 bytes --]

On Wed, Jul 8, 2020 at 3:30 AM Gerd Hoffmann <kraxel@redhat.com> wrote:

>   Hi,
>
> > IIRC, without the dev-storage patch, the very first SCSI command
> > would get stuck waiting for the CSW, because the CSW is not a
> > multiple of MPS. I will have to work on getting a debug trace for
> > you, I'll get back to you with that.
>
> Hmm, dev-storage should be fine with the packet being larger than
> needed.  It'll actually do a short transfer then.  So I suspect the
> patch just papers over the underlying issue.
>
> Can you post a trace of this?
>
> (dev-storage has no trace support, so I think tracing usb_dwc2* to
>  stderr and enable DEBUG_MSD in dev-storage.c works best)
>
> take care,
>   Gerd
>
>
Attached is the log with the dev-storage patch reverted. The full log
was *huge*, so I had to strip out a lot of the content manually.

Starting at line 1746 is the first CBW, it's for an Inquiry command.

Starting at line 1759 is the response, notice at line 1761 the MSD debug
says "Data in 64/36", which is strange. Then the MSD defers the packet,
even though the full 36 bytes has already been received.

Starting at line 1781 (I trimmed out a bunch of lines with no activity
on the MSD here) I think the guest USB driver times out the transfer and
does a reset of the MSD. Notice a few lines later the packet status
return value is USB_RET_STALL.

After this, there is no further activity on the MSD.

Thanks,
Paul

[-- Attachment #1.2: Type: text/html, Size: 4274 bytes --]

[-- Attachment #2: stderr.log.gz --]
[-- Type: application/gzip, Size: 15075 bytes --]

Re: Failure prints during format or mounting a usb storage device

[Gerd Hoffmann]

> Starting at line 1746 is the first CBW, it's for an Inquiry command.
> 
> Starting at line 1759 is the response, notice at line 1761 the MSD debug
> says "Data in 64/36", which is strange.

Not really.  First is the packet size, second is the (remaining) data
size.  Inquiry data is 36 bytes, and dwc2 uses 64 byte instead of 36
byte transfers.

> Then the MSD defers the packet, even though the full 36 bytes has
> already been received.

Yes, and this is the problem.  The condition checks whenever there is
room left in the usb packet.  But we should also check whenever there
is actually more data pending, so how about this:

    if (p->actual_length < p->iov.size && s->mode == USB_MSDM_DATAIN) {
        DPRINTF("Deferring packet %p [wait data-in]\n", p);

take care,
  Gerd

Re: Failure prints during format or mounting a usb storage device

[Paul Zimmerman]

[-- Attachment #1: Type: text/plain, Size: 1280 bytes --]

On Thu, Jul 9, 2020 at 12:57 AM Gerd Hoffmann <kraxel@redhat.com> wrote:

> > Starting at line 1746 is the first CBW, it's for an Inquiry command.
> >
> > Starting at line 1759 is the response, notice at line 1761 the MSD debug
> > says "Data in 64/36", which is strange.
>
> Not really.  First is the packet size, second is the (remaining) data
> size.  Inquiry data is 36 bytes, and dwc2 uses 64 byte instead of 36
> byte transfers.
>
> > Then the MSD defers the packet, even though the full 36 bytes has
> > already been received.
>
> Yes, and this is the problem.  The condition checks whenever there is
> room left in the usb packet.  But we should also check whenever there
> is actually more data pending, so how about this:
>
>     if (p->actual_length < p->iov.size && s->mode == USB_MSDM_DATAIN) {
>         DPRINTF("Deferring packet %p [wait data-in]\n", p);
>
> take care,
>   Gerd
>
>
Hi Gerd,

Hey, that works! But we still need to keep the rest of 7ad3d51ebb8a,
or else s->data_len eventually goes negative and we hit the assertion
on line 447 "Assertion `le32_to_cpu(s->csw.residue) == 0' failed.

But with that, hcd-dwc2 seems to work fine, and also the error
messages that Sai saw with hcd-xhci are gone.

Do you want to submit the patch for this?

Thanks,
Paul

[-- Attachment #2: Type: text/html, Size: 2726 bytes --]