Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

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

Open
1 task done
theosib opened this issue Mar 29, 2024 · 7 comments
Open
1 task done

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

theosib opened this issue Mar 29, 2024 · 7 comments
Labels
Bug 🐞

Comments

@theosib
Copy link

theosib commented Mar 29, 2024

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.

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

  • I confirm I have checked existing issues, dicussion and documentation.
@theosib
Copy link
Author

theosib commented Mar 29, 2024

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
Copy link
Author

theosib commented Mar 29, 2024 •
edited

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 theosib mentioned this issue Mar 29, 2024
Open
@UKTailwind
Copy link

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

@theosib
Copy link
Author

theosib commented Mar 29, 2024 •
edited

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 theosib mentioned this issue Mar 29, 2024
Closed
1 task
@theosib
Copy link
Author

theosib commented Mar 30, 2024 •
edited

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
Copy link
Author

theosib commented Mar 30, 2024

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
Copy link
Author

theosib commented Apr 1, 2024

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.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
Bug 🐞
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
2 participants
@theosib @UKTailwind