u-boot crashes if mass-storage devices are connected via USB-C

Fri Mar 3 00:47:46 CET 2023

On 2023-03-02 22:05:43 +0100, Marek Vasut wrote:
> On 3/2/23 19:51, Janne Grunau wrote:
> > On 2023-03-02 18:33:15 +0100, Marek Vasut wrote:
> > > On 3/2/23 10:14, Janne Grunau wrote:
> > > > On 2023-03-01 23:51:14 +0100, Marek Vasut wrote:
> > > > > On 3/1/23 21:34, Simon Glass wrote:
> > > > > > +Marek Vasut +Bin Meng +Mark Kettenis +Tom Rini
> > > > > > 
> > > > > > On Wed, 1 Mar 2023 at 08:12, bluetail <a-development+asahi at posteo.de> wrote:
> > > > > > > 
> > > > > > > Essentially, I connect a mass-storage device to the USB-C port of a Mac
> > > > > > > Mini 2020 (M1), and it leads to the issue in the attachment.
> > > > > > > I was able to reproduce it with Icy Box IB-3810 and ICY BOX IB-3805.
> > > > > > > Initially I thought this issue was only for some devices (also attached
> > > > > > > here) https://github.com/AsahiLinux/u-boot/issues/4 but it appears this
> > > > > > > might be a issue that is with many devices.
> > > > > > > 
> > > > > > > If you need any more information, please feel free to ask. I am very
> > > > > > > eager to have this issue fixed because it seems to be a very broad issue
> > > > > > > with mass media storage in general.
> > > > > > > uname-r returns 6.1.0-asahi-2-2-edge-ARCH
> > > > > Would it be possible to check whether current u-boot/master works any better
> > > > 
> > > > Reproduced with b0eda49bc9b0 ("Merge tag 'u-boot-at91-fixes-2023.04-a'
> > > > of https://source.denx.de/u-boot/custodians/u-boot-at91") and Icy Box
> > > > IB-3804-C31 (same design as IB-3805/IB-3810 but just a single 4 port
> > > > USB3 hub + 4 independent asmedia usb3 to sata converters).
> > > > 
> > > > | scanning bus usb at b02280000 for devices... Device NOT ready
> > > > |    Request Sense returned 02 3A 00
> > > > | Device NOT ready
> > > > |    Request Sense returned 02 3A 00
> > > > | Resetting EP 0...
> > > > | WARN halted endpoint, queueing URB anyway.
> > > > | Unexpected XHCI event TRB, skipping... (c9208350 0000010f 13000000 04008401)
> > > > | "Synchronous Abort" handler, esr 0x96000005
> > > > | elr: 000000000003934c lr : 000000000003934c (reloc)
> > > > | elr: 0000010fcd24034c lr : 0000010fcd24034c
> > > 
> > > Could you decode the trace and check where exactly this exception occurred ?
> > > 
> > > It should be enough to run "aarch64-...-objdump -lSD u-boot | less" on the
> > > U-Boot which matches the one which generated the trace, and then look up the
> > > lr/elr address in that trace. That should point you to the exact place in
> > > code where the exception occurred .
> > 
> > Slightly different binary due to unrelated chnages:
> > 
> > | scanning bus usb at 702280000 for devices... 1 USB Device(s) found
> > | scanning bus usb at b02280000 for devices... 1 USB Device(s) found
> > | scanning bus usb at f02280000 for devices... 1 USB Device(s) found
> > | scanning bus usb at 1302280000 for devices... 2 USB Device(s) found
> > | scanning bus usb at 702280000 for devices... 1 USB Device(s) found
> > | scanning bus usb at b02280000 for devices... Resetting EP 0...
> > | WARN halted endpoint, queueing URB anyway.
> > | Unexpected XHCI event TRB, skipping... (c92247b0 0000010f 13000000 02008400)
> > | "Synchronous Abort" handler, esr 0x96000005
> > | elr: 0000000000039d9c lr : 0000000000039d9c (reloc)
> > | elr: 0000010fcd240d9c lr : 0000010fcd240d9c
> > | x0 : 0000000000000000 x1 : 00000000000003e8
> > | x2 : 0000000000000040 x3 : 000000000000003f
> > | x4 : 0000010fc9223040 x5 : 0000010fc921ef90
> > | x6 : 0000000000001800 x7 : 00000000300c0300
> > | x8 : 0000000000000424 x9 : 0000000000000008
> > | x10: 00000000ffffffe8 x11: 0000000000000010
> > | x12: 0000000000010000 x13: 0000000000000001
> > | x14: 0000010fc91ba320 x15: 0000000000000021
> > | x16: 0000010fcd23addc x17: 0000000000000040
> > | x18: 0000010fc91e7d70 x19: 0000010fc9223040
> > | x20: 0000010fc9234b20 x21: 0000000000000002
> > | x22: 0000010fc9233790 x23: 0000000000000080
> > | x24: 0000000000000000 x25: 0000010fc91b9d00
> > | x26: 0000010fc91b9d00 x27: 0000010fc9233790
> > | x28: 0000000000000000 x29: 0000010fc91b99b0
> > |
> > | Code: 97ffff3c 52800401 aa1303e0 97ffffa2 (b9400c00)
> > 
> > objdump -lSD u-boot | grep -C 12 ' 39d9c'
> > 
> > | Disassembly of section .text_rest:
> > | ...
> > |    39d84:       f9400c36        ldr     x22, [x1, #24]
> > | /home/janne/src/asahi/u-boot/drivers/usb/host/xhci-ring.c:544
> > | 	xhci_queue_command(ctrl, 0, udev->slot_id, ep_index, TRB_STOP_RING);
> > |    39d88:       d2800001        mov     x1, #0x0                        // #0
> > |    39d8c:       97ffff3c        bl      39a7c <xhci_queue_command>
> > | /home/janne/src/asahi/u-boot/drivers/usb/host/xhci-ring.c:546
> > | 	event = xhci_wait_for_event(ctrl, TRB_TRANSFER);
> > |    39d90:       52800401        mov     w1, #0x20                       // #32
> > |    39d94:       aa1303e0        mov     x0, x19
> > |    39d98:       97ffffa2        bl      39c20 <xhci_wait_for_event>
> > | /home/janne/src/asahi/u-boot/drivers/usb/host/xhci-ring.c:547
> > | 	field = le32_to_cpu(event->trans_event.flags);
> > |    39d9c:       b9400c00        ldr     w0, [x0, #12]
> > | /home/janne/src/asahi/u-boot/drivers/usb/host/xhci-ring.c:548
> > | 	BUG_ON(TRB_TO_SLOT_ID(field) != udev->slot_id);
> > |    39da0:       b9494681        ldr     w1, [x20, #2372]
> > |    39da4:       6b40603f        cmp     w1, w0, lsr #24
> > |    39da8:       54000180        b.eq    39dd8 <abort_td+0x8c>  // b.none
> > | /home/janne/src/asahi/u-boot/drivers/usb/host/xhci-ring.c:548 (discriminator 1)
> > |    39dac:       90000143        adrp    x3, 61000 <crc16_tab+0x170>
> > |    39db0:       913d0863        add     x3, x3, #0xf42
> > |    39db4:       52804482        mov     w2, #0x224                      // #548
> > | /home/janne/src/asahi/u-boot/drivers/usb/host/xhci-ring.c:549 (discriminator 1)
> > | 	BUG_ON(TRB_TO_EP_INDEX(field) != ep_index);
> > |    39db8:       b0000181        adrp    x1, 6a000 <names.0+0x11cb>
> > 
> > not immediately obvious to me what's the problem. x0 looks valid before the ldr.
> 
> x0 in the splat is
> | x0 : 0000000000000000 x1 : 00000000000003e8
> so, I think xhci_wait_for_event() returns NULL .

Indeed, I confused myself earlier since I saw abort_td() finish once.  
This is clearly buggy code. 'xhci_wait_for_event(ctrl, TRB_TRANSFER);' 
returns NULL on timeouts so the event dereferencing after that needs to 
be inside an 'if (event) {}'.

This fixes not the problem as we hit now the 'BUG()' at the end of
xhci_wait_for_event() for TRB_COMPLETION:

| scanning bus usb at b02280000 for devices... Resetting EP 0...
| WARN halted endpoint, queueing URB anyway.
| Unexpected XHCI event TRB, skipping... (c92247b0 0000010f 13000000 02008400)
| XHCI timeout on event type 33... cannot recover.
| BUG at drivers/usb/host/xhci-ring.c:496/xhci_wait_for_event()!
| BUG!
| resetting ..

At least an improvement in the error reporting.

> I found this device locally:
> New USB device found, idVendor=174c, idProduct=55aa, bcdDevice= 1.00
> Product: ICY BOX IB-366StU3+B
> 
> I will see if I can reproduce the problem on iMX8MP DWC3 too, unless someone
> wants to dig into it first, which might expedite the fix.

That seems to be a different asmedia usb to sata bridge as it is only 5 
gbps instead of 10 gbps. Still worth trying.

Janne