Plug in two devices at once, no devices found, panic about tinyusb HOT 7 OPEN

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

from tinyusb.

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.

from tinyusb.

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

from tinyusb.

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.

from tinyusb.

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.

from tinyusb.

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

from tinyusb.

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.

from tinyusb.