tinyusb icon indicating copy to clipboard operation
tinyusb copied to clipboard
verified publisher icon hathach

Plug in two devices at once, no devices found, panic

Open theosib opened this issue 1 year ago • 7 comments

Operating System

Linux

Board

Raspberry Pi Pico

Firmware

Custom firmware. You can see my whole project here: https://github.com/theosib/pico_vga/tree/main

What happened ?

TinyUSB detects no new devices when two are plugged in at once

How to reproduce ?

Plug in a keyboard and mouse simultaneously.

  • All of the details about this can be found at: https://github.com/raspberrypi/pico-sdk/issues/1680
  • Also see: https://github.com/hathach/tinyusb/issues/2555

I'm undertaking an investigation to find out why nothing happens when I plug in a keyboard and mouse at the same time. A log is attached. The logging seems to be interfering, however, with the investigation because the panic you see at the end was not occurring until I enabled debug messages. Still, hopefully there is something informative in the log. I'll keep updating this with more information.

Debug Log as txt file (LOG/CFG_TUSB_DEBUG=2)

delay 540060, 993, 536098, 83557 [0:] USBH DEVICE ATTACH hcd_port_reset hcd_port_connect_status Full Speed [0:0] Open EP0 with Size = 8 hcd_edpt_open dev_addr 0, ep_addr 0 hw_endpoint_init dev 0 ep 0 out xfer 0 dev 0 ep 0 out setup buffer @ 0x50100180 endpoint control (0x50100100) <- 0xa0000180 Get 8 byte of Device Descriptor [0:0] Get Descriptor: 80 06 00 01 00 00 08 00 hw_endpoint_init dev 0 ep 0 out xfer 0 dev 0 ep 0 out setup buffer @ 0x50100180 endpoint control (0x50100100) <- 0xa0000180 Transfer complete Sent setup packet on EP 00 with 8 bytes: OK hcd_edpt_xfer dev_addr 0, ep_addr 0x80, len 8 hw_endpoint_init dev 0 ep 0 in xfer 0 dev 0 ep 0 in setup buffer @ 0x50100180 endpoint control (0x50100100) <- 0xa0000180 Prepare BufCtrl: [0] = 0x7408 [1] = 0x0000 Buffer complete buf_status 0x00000001 Single Buffered: ep_ctrl = 0xA0000180 Sync BufCtrl: [0] = 0xe008 [1] = 0x0000 Completed transfer of 8 bytes on ep 80 Transfer complete on EP 80 with 8 bytes: OK [0:0] Control data: 0000: 12 01 00 02 09 00 00 40 |.......@| hcd_edpt_xfer dev_addr 0, ep_addr 0x0, len 0 hw_endpoint_init dev 0 ep 0 out xfer 0 dev 0 ep 0 out setup buffer @ 0x50100180 endpoint control (0x50100100) <- 0xa0000180 Prepare BufCtrl: [0] = 0xf400 [1] = 0x0000 Buffer complete buf_status 0x00000001 Single Buffered: ep_ctrl = 0xA0000180 Sync BufCtrl: [0] = 0x6000 [1] = 0x0000 Short packet on buffer 0 with 0 bytes Completed transfer of 0 bytes on ep 00 Transfer complete on EP 00 with 0 bytes: OK

Set Address = 5 [0:0] Set Address: 00 05 05 00 00 00 00 00 hw_endpoint_init dev 0 ep 0 out xfer 0 dev 0 ep 0 out setup buffer @ 0x50100180 endpoint control (0x50100100) <- 0xa0000180 Transfer complete Sent setup packet on EP 00 with 8 bytes: OK hcd_edpt_xfer dev_addr 0, ep_addr 0x80, len 0 hw_endpoint_init dev 0 ep 0 in xfer 0 dev 0 ep 0 in setup buffer @ 0x50100180 endpoint control (0x50100100) <- 0xa0000180 Prepare BufCtrl: [0] = 0x7400 [1] = 0x0000 Buffer complete buf_status 0x00000001 Single Buffered: ep_ctrl = 0xA0000180 Sync BufCtrl: [0] = 0xe000 [1] = 0x0000 Short packet on buffer 0 with 0 bytes Completed transfer of 0 bytes on ep 80 Transfer complete on EP 80 with 0 bytes: OK

hcd_device_close 0 [0:5] Open EP0 with Size = 64 hcd_edpt_open dev_addr 5, ep_addr 0 hw_endpoint_init dev 5 ep 0 out xfer 0 dev 5 ep 0 out setup buffer @ 0x50100180 endpoint control (0x50100100) <- 0xa0000180 Get Device Descriptor [0:5] Get Descriptor: 80 06 00 01 00 00 12 00 hw_endpoint_init dev 5 ep 0 out xfer 0 dev 5 ep 0 out setup buffer @ 0x50100180 endpoint control (0x50100100) <- 0xa0000180 Transfer complete Sent setup packet on EP 00 with 8 bytes: OK hcd_edpt_xfer dev_addr 5, ep_addr 0x80, len 18 hw_endpoint_init dev 5 ep 0 in xfer 0 dev 5 ep 0 in setup buffer @ 0x50100180 endpoint control (0x50100100) <- 0xa0000180 Prepare BufCtrl: [0] = 0x7412 [1] = 0x0000 Buffer complete buf_status 0x00000001 Single Buffered: ep_ctrl = 0xA0000180 Sync BufCtrl: [0] = 0xe012 [1] = 0x0000 Short packet on buffer 0 with 18 bytes Completed transfer of 18 bytes on ep 80 Transfer complete on EP 80 with 18 bytes: OK [0:5] Control data: 0000: 12 01 00 02 09 00 00 40 AC 05 06 10 15 96 01 02 |.......@........| 0010: 03 01 |..| hcd_edpt_xfer dev_addr 5, ep_addr 0x0, len 0 hw_endpoint_init dev 5 ep 0 out xfer 0 dev 5 ep 0 out setup buffer @ 0x50100180 endpoint control (0x50100100) <- 0xa0000180 Prepare BufCtrl: [0] = 0xf400 [1] = 0x0000 Buffer complete buf_status 0x00000001 Single Buffered: ep_ctrl = 0xA0000180 Sync BufCtrl: [0] = 0x6000 [1] = 0x0000 Short packet on buffer 0 with 0 bytes Completed transfer of 0 bytes on ep 00 Transfer complete on EP 00 with 0 bytes: OK

Get Configuration[0] Descriptor (9 bytes) [0:5] Get Descriptor: 80 06 00 02 00 00 09 00 hw_endpoint_init dev 5 ep 0 out xfer 0 dev 5 ep 0 out setup buffer @ 0x50100180 endpoint control (0x50100100) <- 0xa0000180 Transfer complete Sent setup packet on EP 00 with 8 bytes: OK hcd_edpt_xfer dev_addr 5, ep_addr 0x80, len 9 hw_endpoint_init dev 5 ep 0 in xfer 0 dev 5 ep 0 in setup buffer @ 0x50100180 endpoint control (0x50100100) <- 0xa0000180 Prepare BufCtrl: [0] = 0x7409 [1] = 0x0000 Buffer complete buf_status 0x00000001 Single Buffered: ep_ctrl = 0xA0000180 Sync BufCtrl: [0] = 0xe009 [1] = 0x0000 Short packet on buffer 0 with 9 bytes Completed transfer of 9 bytes on ep 80 Transfer complete on EP 80 with 9 bytes: OK [0:5] Control data: 0000: 09 02 19 00 01 01 00 A0 28 |........(| hcd_edpt_xfer dev_addr 5, ep_addr 0x0, len 0 hw_endpoint_init dev 5 ep 0 out xfer 0 dev 5 ep 0 out setup buffer @ 0x50100180 endpoint control (0x50100100) <- 0xa0000180 Prepare BufCtrl: [0] = 0xf400 [1] = 0x0000 Buffer complete buf_status 0x00000001 Single Buffered: ep_ctrl = 0xA0000180 Sync BufCtrl: [0] = 0x6000 [1] = 0x0000 Short packet on buffer 0 with 0 bytes Completed transfer of 0 bytes on ep 00 Transfer complete on EP 00 with 0 bytes: OK

Get Configuration[0] Descriptor [0:5] Get Descriptor: 80 06 00 02 00 00 19 00 hw_endpoint_init dev 5 ep 0 out xfer 0 dev 5 ep 0 out setup buffer @ 0x50100180 endpoint control (0x50100100) <- 0xa0000180 Transfer complete Sent setup packet on EP 00 with 8 bytes: OK hcd_edpt_xfer dev_addr 5, ep_addr 0x80, len 25 hw_endpoint_init dev 5 ep 0 in xfer 0 dev 5 ep 0 in setup buffer @ 0x50100180 endpoint control (0x50100100) <- 0xa0000180 Prepare BufCtrl: [0] = 0x7419 [1] = 0x0000 Buffer complete buf_status 0x00000001 Single Buffered: ep_ctrl = 0xA0000180 Sync BufCtrl: [0] = 0xe019 [1] = 0x0000 Short packet on buffer 0 with 25 bytes Completed transfer of 25 bytes on ep 80 Transfer complete on EP 80 with 25 bytes: OK [0:5] Control data: 0000: 09 02 19 00 01 01 00 A0 28 09 04 00 00 01 09 00 |........(.......| 0010: 00 00 07 05 81 03 01 00 FF |.........| hcd_edpt_xfer dev_addr 5, ep_addr 0x0, len 0 hw_endpoint_init dev 5 ep 0 out xfer 0 dev 5 ep 0 out setup buffer @ 0x50100180 endpoint control (0x50100100) <- 0xa0000180 Prepare BufCtrl: [0] = 0xf400 [1] = 0x0000 Buffer complete buf_status 0x00000001 Single Buffered: ep_ctrl = 0xA0000180 Sync BufCtrl: [0] = 0x6000 [1] = 0x0000 Short packet on buffer 0 with 0 bytes Completed transfer of 0 bytes on ep 00 Transfer complete on EP 00 with 0 bytes: OK

Set Configuration = 1 [0:5] Set Configuration: 00 09 01 00 00 00 00 00 hw_endpoint_init dev 5 ep 0 out xfer 0 dev 5 ep 0 out setup buffer @ 0x50100180 endpoint control (0x50100100) <- 0xa0000180 Transfer complete Sent setup packet on EP 00 with 8 bytes: OK hcd_edpt_xfer dev_addr 5, ep_addr 0x80, len 0 hw_endpoint_init dev 5 ep 0 in xfer 0 dev 5 ep 0 in setup buffer @ 0x50100180 endpoint control (0x50100100) <- 0xa0000180 Prepare BufCtrl: [0] = 0x7400 [1] = 0x0000 Buffer complete buf_status 0x00000001 Single Buffered: ep_ctrl = 0xA0000180 Sync BufCtrl: [0] = 0xe000 [1] = 0x0000 Short packet on buffer 0 with 0 bytes Completed transfer of 0 bytes on ep 80 Transfer complete on EP 80 with 0 bytes: OK [5] Aborted transfer on EP 01 [5] Aborted transfer on EP 81 [5] Aborted transfer on EP 02 [5] Aborted transfer on EP 82 [5] Aborted transfer on EP 03 [5] Aborted transfer on EP 83 [5] Aborted transfer on EP 04 [5] Aborted transfer on EP 84 [5] Aborted transfer on EP 05 [5] Aborted transfer on EP 85 [5] Aborted transfer on EP 06 [5] Aborted transfer on EP 86 [5] Aborted transfer on EP 07 [5] Aborted transfer on EP 87 [5] Aborted transfer on EP 08 [5] Aborted transfer on EP 88 [5] Aborted transfer on EP 09 [5] Aborted transfer on EP 89 [5] Aborted transfer on EP 0A [5] Aborted transfer on EP 8A [5] Aborted transfer on EP 0B [5] Aborted transfer on EP 8B [5] Aborted transfer on EP 0C [5] Aborted transfer on EP 8C [5] Aborted transfer on EP 0D [5] Aborted transfer on EP 8D [5] Aborted transfer on EP 0E [5] Aborted transfer on EP 8E [5] Aborted transfer on EP 0F [5] Aborted transfer on EP 8F

Device configured Parsing Configuration descriptor (wTotalLength = 25) Open EP 81 with Size = 1 hcd_edpt_open dev_addr 5, ep_addr 129 Allocate interrupt ep 0 hw_endpoint_init dev 5 ep 1 in xfer 3 dev 5 ep 1 in setup buffer @ 0x50100200 endpoint control (0x50100008) <- 0xacfe0200 HUB opened Bind EP 81 to driver id 1 HUB set config: itf = 0 [0:5] Class Request: A0 06 00 00 00 00 09 00 hw_endpoint_init dev 5 ep 0 out xfer 0 dev 5 ep 0 out setup buffer @ 0x50100180 endpoint control (0x50100100) <- 0xa0000180 Transfer complete Sent setup packet on EP 00 with 8 bytes: OK hcd_edpt_xfer dev_addr 5, ep_addr 0x80, len 9 hw_endpoint_init dev 5 ep 0 in xfer 0 dev 5 ep 0 in setup buffer @ 0x50100180 endpoint control (0x50100100) <- 0xa0000180 Prepare BufCtrl: [0] = 0x7409 [1] = 0x0000 Buffer complete buf_status 0x00000001 Single Buffered: ep_ctrl = 0xA0000180 Sync BufCtrl: [0] = 0xe009 [1] = 0x0000 Short packet on buffer 0 with 9 bytes Completed transfer of 9 bytes on ep 80 Transfer complete on EP 80 with 9 bytes: OK [0:5] Control data: 0000: 09 29 03 8D 00 32 50 04 FF |.)...2P..| hcd_edpt_xfer dev_addr 5, ep_addr 0x0, len 0 hw_endpoint_init dev 5 ep 0 out xfer 0 dev 5 ep 0 out setup buffer @ 0x50100180 endpoint control (0x50100100) <- 0xa0000180 Prepare BufCtrl: [0] = 0xf400 [1] = 0x0000 Buffer complete buf_status 0x00000001 Single Buffered: ep_ctrl = 0xA0000180 Sync BufCtrl: [0] = 0x6000 [1] = 0x0000 Short packet on buffer 0 with 0 bytes Completed transfer of 0 bytes on ep 00 Transfer complete on EP 00 with 0 bytes: OK

HUB Set Feature: PORT_POWER, addr = 5 port = 1 [0:5] Class Request: 23 03 08 00 01 00 00 00 hw_endpoint_init dev 5 ep 0 out xfer 0 dev 5 ep 0 out setup buffer @ 0x50100180 endpoint control (0x50100100) <- 0xa0000180 Transfer complete Sent setup packet on EP 00 with 8 bytes: OK hcd_edpt_xfer dev_addr 5, ep_addr 0x80, len 0 hw_endpoint_init dev 5 ep 0 in xfer 0 dev 5 ep 0 in setup buffer @ 0x50100180 endpoint control (0x50100100) <- 0xa0000180 Prepare BufCtrl: [0] = 0x7400 [1] = 0x0000 Buffer complete buf_status 0x00000001 Single Buffered: ep_ctrl = 0xA0000180 Sync BufCtrl: [0] = 0xe000 [1] = 0x0000 Short packet on buffer 0 with 0 bytes Completed transfer of 0 bytes on ep 80 Transfer complete on EP 80 with 0 bytes: OK

HUB Set Feature: PORT_POWER, addr = 5 port = 2 [0:5] Class Request: 23 03 08 00 02 00 00 00 hw_endpoint_init dev 5 ep 0 out xfer 0 dev 5 ep 0 out setup buffer @ 0x50100180 endpoint control (0x50100100) <- 0xa0000180 Transfer complete Sent setup packet on EP 00 with 8 bytes: OK hcd_edpt_xfer dev_addr 5, ep_addr 0x80, len 0 hw_endpoint_init dev 5 ep 0 in xfer 0 dev 5 ep 0 in setup buffer @ 0x50100180 endpoint control (0x50100100) <- 0xa0000180 Prepare BufCtrl: [0] = 0x7400 [1] = 0x0000 Buffer complete buf_status 0x00000001 Single Buffered: ep_ctrl = 0xA0000180 Sync BufCtrl: [0] = 0xe000 [1] = 0x0000 Short packet on buffer 0 with 0 bytes Completed transfer of 0 bytes on ep 80 Transfer complete on EP 80 with 0 bytes: OK

HUB Set Feature: PORT_POWER, addr = 5 port = 3 [0:5] Class Request: 23 03 08 00 03 00 00 00 hw_endpoint_init dev 5 ep 0 out xfer 0 dev 5 ep 0 out setup buffer @ 0x50100180 endpoint control (0x50100100) <- 0xa0000180 Transfer complete Sent setup packet on EP 00 with 8 bytes: OK hcd_edpt_xfer dev_addr 5, ep_addr 0x80, len 0 hw_endpoint_init dev 5 ep 0 in xfer 0 dev 5 ep 0 in setup buffer @ 0x50100180 endpoint control (0x50100100) <- 0xa0000180 Prepare BufCtrl: [0] = 0x7400 [1] = 0x0000

*** PANIC ***

Invalid speed

Screenshots

No response

I have checked existing issues, dicussion and documentation

  • [X] I confirm I have checked existing issues, dicussion and documentation.

theosib avatar Mar 29 '24 01:03 theosib

Those messages are a bit spammy. I reduced the debugging level to 2, and this is what I got:

[0:] USBH DEVICE ATTACH Full Speed [0:0] Open EP0 with Size = 8 Get 8 byte of Device Descriptor [0:0] Get Descriptor: 80 06 00 01 00 00 08 00 Transfer complete on EP 00 with 8 bytes: OK Buffer complete Transfer complete on EP 80 with 8 bytes: OK [0:0] Control data: 0000: 12 01 00 02 09 00 00 40 |.......@| Buffer complete Transfer complete on EP 00 with 0 bytes: OK

Set Address = 5 [0:0] Set Address: 00 05 05 00 00 00 00 00 Transfer complete on EP 00 with 8 bytes: OK Buffer complete Transfer complete on EP 80 with 0 bytes: OK

[0:5] Open EP0 with Size = 64 Get Device Descriptor [0:5] Get Descriptor: 80 06 00 01 00 00 12 00 Transfer complete on EP 00 with 8 bytes: OK Buffer complete Transfer complete on EP 80 with 18 bytes: OK [0:5] Control data: 0000: 12 01 00 02 09 00 00 40 AC 05 06 10 15 96 01 02 |.......@........| 0010: 03 01 |..| Buffer complete Transfer complete on EP 00 with 0 bytes: OK

Get Configuration[0] Descriptor (9 bytes) [0:5] Get Descriptor: 80 06 00 02 00 00 09 00 Transfer complete on EP 00 with 8 bytes: OK Buffer complete Transfer complete on EP 80 with 9 bytes: OK [0:5] Control data: 0000: 09 02 19 00 01 01 00 A0 28 |........(| Buffer complete Transfer complete on EP 00 with 0 bytes: OK

Get Configuration[0] Descriptor [0:5] Get Descriptor: 80 06 00 02 00 00 19 00 Transfer complete on EP 00 with 8 bytes: OK Buffer complete Transfer complete on EP 80 with 25 bytes: OK [0:5] Control data: 0000: 09 02 19 00 01 01 00 A0 28 09 04 00 00 01 09 00 |........(.......| 0010: 00 00 07 05 81 03 01 00 FF |.........| Buffer complete Transfer complete on EP 00 with 0 bytes: OK

Set Configuration = 1 [0:5] Set Configuration: 00 09 01 00 00 00 00 00 Transfer complete on EP 00 with 8 bytes: OK Buffer complete Transfer complete on EP 80 with 0 bytes: OK [5] Aborted transfer on EP 01 [5] Aborted transfer on EP 81 [5] Aborted transfer on EP 02 [5] Aborted transfer on EP 82 [5] Aborted transfer on EP 03 [5] Aborted transfer on EP 83 [5] Aborted transfer on EP 04 [5] Aborted transfer on EP 84 [5] Aborted transfer on EP 05 [5] Aborted transfer on EP 85 [5] Aborted transfer on EP 06 [5] Aborted transfer on EP 86 [5] Aborted transfer on EP 07 [5] Aborted transfer on EP 87 [5] Aborted transfer on EP 08 [5] Aborted transfer on EP 88 [5] Aborted transfer on EP 09 [5] Aborted transfer on EP 89 [5] Aborted transfer on EP 0A [5] Aborted transfer on EP 8A [5] Aborted transfer on EP 0B [5] Aborted transfer on EP 8B [5] Aborted transfer on EP 0C [5] Aborted transfer on EP 8C [5] Aborted transfer on EP 0D [5] Aborted transfer on EP 8D [5] Aborted transfer on EP 0E [5] Aborted transfer on EP 8E [5] Aborted transfer on EP 0F [5] Aborted transfer on EP 8F

Device configured Parsing Configuration descriptor (wTotalLength = 25) Open EP 81 with Size = 1 Allocate interrupt ep 0 HUB opened Bind EP 81 to driver id 1 HUB set config: itf = 0 [0:5] Class Request: A0 06 00 00 00 00 09 00 Transfer complete on EP 00 with 8 bytes: OK Buffer complete Transfer complete on EP 80 with 9 bytes: OK [0:5] Control data: 0000: 09 29 03 8D 00 32 50 04 FF |.)...2P..| Buffer complete Transfer complete on EP 00 with 0 bytes: OK

HUB Set Feature: PORT_POWER, addr = 5 port = 1 [0:5] Class Request: 23 03 08 00 01 00 00 00 Transfer complete on EP 00 with 8 bytes: OK Buffer complete Transfer complete on EP 80 with 0 bytes: OK

HUB Set Feature: PORT_POWER, addr = 5 port = 2 [0:5] Class Request: 23 03 08 00 02 00 00 00 Transfer complete on EP 00 with 8 bytes: OK Buffer complete Transfer complete on EP 80 with 0 bytes: OK

HUB Set Feature: PORT_POWER, addr = 5 port = 3 [0:5] Class Request: 23 03 08 00 03 00 00 00 Transfer complete on EP 00 with 8 bytes: OK

*** PANIC ***

Invalid speed

theosib avatar Mar 29 '24 01:03 theosib

The panic is coming from "hdc_rp2040.c", here:

tusb_speed_t hcd_port_speed_get(uint8_t rhport)
{
  (void) rhport;
  assert(rhport == 0);

  // TODO: Should enumval this register
  switch ( dev_speed() )
  {
    case 1:
      return TUSB_SPEED_LOW;
    case 2:
      return TUSB_SPEED_FULL;
    default:
      panic("Invalid speed\n");
      // return TUSB_SPEED_INVALID;
  }
}

The value being returned by dev_speed() is zero.

dev_speed() reads register usb_hw->sie_status, and the full value of that register is 0x40000001.

If I'm reading the docs right, this is asserting "ACK received" and "VBUS Detected". But the speed bits are reading zero, which means "disconnected."

But obviously it's not disconnected. All of those debug messages I pasted came from me plugging devices in.

theosib avatar Mar 29 '24 01:03 theosib

This can be overcome in user code. See https://github.com/UKTailwind/PicoMite/blob/main/USBKeyboard.c for how I do it. Note you MUST NOT issue any tuh_hid_send_report commands or similar in the mount callback or you will hit issues

UKTailwind avatar Mar 29 '24 09:03 UKTailwind

Can you give me a hint about how this example overcomes the problem? I've looked through the mount code, and I'm not seeing it do anything special with regard to USB. Also, my mount code doesn't send any reports.

In fact, for me, if I plug in two devices at once, the mount callback never gets called at all, so there's nothing in my mount callback that could either cause or mitigate the problem. The only indication I have that anything happens is that tuh_task() takes 500 milliseconds when I plug in. There is no other activity.

theosib avatar Mar 29 '24 13:03 theosib

I don't know anything about USB, so this is slow going for me, but it looks like the problem is being caused by an attempt to set power management on a hub, and TinyUSB may not be giving it sufficient time to complete that setup before performing further communication. I've tried putting delays in various places, but I'm stabbing randomly. If someone who knows what they're doing could give me some hints about where I might put strategic delays, that would be really helpful.

Basically, we have some hubs being set up successfully, like this:

HUB Set Feature: PORT_POWER, addr = 5 port = 2
[0:5] Class Request: 23 03 08 00 02 00 00 00 
hw_endpoint_init dev 5 ep 00 xfer 0
dev 5 ep 00 setup buffer @ 0x50100180
endpoint control (0x50100100) <- 0xa0000180
Transfer complete
Sent setup packet
on EP 00 with 8 bytes: OK
Calling hcd_edpt_xfer from usbh_control_xfer_cb B
hcd_edpt_xfer dev_addr 5, ep_addr 0x80, len 0
hw_endpoint_init dev 5 ep 80 xfer 0
dev 5 ep 80 setup buffer @ 0x50100180
endpoint control (0x50100100) <- 0xa0000180
Calling hw_endpoint_xfer_start from hcd_edpt_xfer A
  Prepare BufCtrl: [0] = 0x7400  [1] = 0x0000
Enter _hw_endpoint_buffer_control_update32
Exit _hw_endpoint_buffer_control_update32
Return to hw_endpoint_xfer_start
Calling hw_endpoint_lock_update
Done with hw_endpoint_lock_update
Return to hcd_edpt_xfer A
Calling busy-wait
Buffer complete
buf_status 0x00000001
Single Buffered: ep_ctrl = 0xA0000180
  Sync BufCtrl: [0] = 0xe000  [1] = 0x0000
  Short packet on buffer 0 with 0 bytes
Completed transfer of 0 bytes on ep 80
Transfer complete
Return from busy-wait
Return from hcd_edpt_xfer
Returning from hcd_edpt_xfer to usbh_control_xfer_cb B
on EP 80 with 0 bytes: OK

But then the last one dies when hcd_edpt_xfer tries to call need_pre right here, because need_pre is trying to find out the device speed and getting an invalid result:

    uint32_t flags = USB_SIE_CTRL_START_TRANS_BITS | SIE_CTRL_BASE |
                     (ep_dir ? USB_SIE_CTRL_RECEIVE_DATA_BITS : USB_SIE_CTRL_SEND_DATA_BITS) |
                     (need_pre(dev_addr) ? USB_SIE_CTRL_PREAMBLE_EN_BITS : 0);

And this is what I get from that:

HUB Set Feature: PORT_POWER, addr = 5 port = 3
[0:5] Class Request: 23 03 08 00 03 00 00 00 
hw_endpoint_init dev 5 ep 00 xfer 0
dev 5 ep 00 setup buffer @ 0x50100180
endpoint control (0x50100100) <- 0xa0000180
Transfer complete
Sent setup packet
on EP 00 with 8 bytes: OK
Calling hcd_edpt_xfer from usbh_control_xfer_cb B
hcd_edpt_xfer dev_addr 5, ep_addr 0x80, len 0
hw_endpoint_init dev 5 ep 80 xfer 0
dev 5 ep 80 setup buffer @ 0x50100180
endpoint control (0x50100100) <- 0xa0000180
Calling hw_endpoint_xfer_start from hcd_edpt_xfer A
  Prepare BufCtrl: [0] = 0x7400  [1] = 0x0000
Enter _hw_endpoint_buffer_control_update32
Exit _hw_endpoint_buffer_control_update32
Return to hw_endpoint_xfer_start
Calling hw_endpoint_lock_update
Done with hw_endpoint_lock_update
Return to hcd_edpt_xfer A

*** PANIC ***

Invalid speed

I'm guessing some command is being sent to the hub, and then insufficient time is being allotted for a response. But it's not clear to me where these transfers are happening or when to insert any sort of delay.

theosib avatar Mar 30 '24 15:03 theosib

It also occurred to me that perhaps the end point it's trying to get the speed for doesn't really exist, so I modified hcd_port_speed_get to return TUSB_SPEED_INVALID on an invalid speed. It got a little further and then died here:

void __tusb_irq_path_func(_hw_endpoint_buffer_control_update32)(struct hw_endpoint* ep, uint32_t and_mask,
                                                               uint32_t or_mask) {
  uint32_t value = 0;
  
  TU_LOG(3, "Enter _hw_endpoint_buffer_control_update32\r\n");
  

  if (and_mask) {
    value = *ep->buffer_control & and_mask;
  }

  if (or_mask) {
    value |= or_mask;
    if (or_mask & USB_BUF_CTRL_AVAIL) {
      if (*ep->buffer_control & USB_BUF_CTRL_AVAIL) {
        panic("ep %02X was already available", ep->ep_addr);
      }
      *ep->buffer_control = value & ~USB_BUF_CTRL_AVAIL;
      // 4.1.2.5.1 Con-current access: 12 cycles (should be good for 48*12Mhz = 576Mhz) after write to buffer control
      // Don't need delay in host mode as host is in charge
      if ( !is_host_mode()) {
        busy_wait_at_least_cycles(12);
      }
    }
  }

  *ep->buffer_control = value;

  TU_LOG(3, "Exit _hw_endpoint_buffer_control_update32\r\n");
}

It prints this:

ep 80 was already available

theosib avatar Mar 30 '24 15:03 theosib

I'm comparing the success and failure cases. The success case is when only the keyboard (with its internal hub) is plugged in, while the failure case has the mouse also plugged in. The logs are identical up to a certain point.

Everything is pretty much the same as I shared above, ending with this:

HUB Set Feature: PORT_POWER, addr = 5 port = 3
[0:5] Class Request: 23 03 08 00 03 00 00 00 
hw_endpoint_init dev 5 ep 00 xfer 0
dev 5 ep 00 setup buffer @ 0x50100180
endpoint control (0x50100100) <- 0xa0000180
Transfer complete
Sent setup packet
on EP 00 with 8 bytes: OK
Calling hcd_edpt_xfer from usbh_control_xfer_cb B
hcd_edpt_xfer dev_addr 5, ep_addr 0x80, len 0
hw_endpoint_init dev 5 ep 80 xfer 0
dev 5 ep 80 setup buffer @ 0x50100180
endpoint control (0x50100100) <- 0xa0000180
Calling hw_endpoint_xfer_start from hcd_edpt_xfer A
  Prepare BufCtrl: [0] = 0x7400  [1] = 0x0000
Enter _hw_endpoint_buffer_control_update32
Exit _hw_endpoint_buffer_control_update32
Return to hw_endpoint_xfer_start
Calling hw_endpoint_lock_update
Done with hw_endpoint_lock_update
Return to hcd_edpt_xfer A

At this point, the failure case panics due to an "Invalid speed." The success case is identical up to that point, but then it finishes with this operation as so:

Calling busy-wait
Buffer complete
buf_status 0x00000001
Single Buffered: ep_ctrl = 0xA0000180
  Sync BufCtrl: [0] = 0xe000  [1] = 0x0000
  Short packet on buffer 0 with 0 bytes
Completed transfer of 0 bytes on ep 80
Transfer complete
Return from busy-wait
Return from hcd_edpt_xfer
Returning from hcd_edpt_xfer to usbh_control_xfer_cb B
on EP 80 with 0 bytes: OK

The success case then goes on to mount that hub and so on.

  Queue EP 81 with 1 bytes ... 
Calling hcd_edpt_xfer from usbh_edpt_xfer_with_callback
hcd_edpt_xfer dev_addr 5, ep_addr 0x81, len 1
Calling hw_endpoint_xfer_start from hcd_edpt_xfer B
  Prepare BufCtrl: [0] = 0x5401  [1] = 0x0000
Enter _hw_endpoint_buffer_control_update32
Exit _hw_endpoint_buffer_control_update32
Return to hw_endpoint_xfer_start
Calling hw_endpoint_lock_update
Done with hw_endpoint_lock_update
Return to hcd_edpt_xfer B
Return from hcd_edpt_xfer
OK
HUB address = 5 is mounted
Buffer complete
...

So there's definitely a problem with handling hubs.

BTW, one time I had the same invalid speed panic with just the keyboard. I think the presence of the mouse is affecting the behavior of the hub, and TinyUSB isn't accounting for that.

theosib avatar Apr 01 '24 12:04 theosib