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

net_lwip_webserver reaches "endpoint busy" race condition on STM32F411DISCO #884

Closed
kamathba opened this issue Jun 8, 2021 · 7 comments
Closed

net_lwip_webserver reaches "endpoint busy" race condition on STM32F411DISCO #884

kamathba opened this issue Jun 8, 2021 · 7 comments
Labels
Bug 🐞

Comments

@kamathba
Copy link

kamathba commented Jun 8, 2021 •
edited
Loading

Set Up
Compile the example: make DEBUG=1 BOARD=stm32f411disco all

  • Ubuntu 20.04.2 LTS
  • STM32F411DISCO
  • master (1b84739)
  • Firmware e.g examples/device/net_lwip_webserver

Describe The Bug

I reach the following assert when connecting to my host pc over usb:

usbd_edpt_xfer (rhport=rhport@entry=0 '\000', ep_addr=129 '\201', buffer=buffer@entry=0x2000001c <ndis_report> "\001", total_bytes=<optimized out>)
    at /home/bkamath/.dev/fb/tinyusb/src/device/usbd.c:1249
1249	  TU_ASSERT(_usbd_dev.ep_status[epnum][dir].busy == 0);

With the following backtrace:

#0  usbd_edpt_xfer (rhport=rhport@entry=0 '\000', ep_addr=129 '\201', buffer=buffer@entry=0x2000001c <ndis_report> "\001", total_bytes=<optimized out>)
    at /home/bkamath/.dev/fb/tinyusb/src/device/usbd.c:1249
#1  0x080014bc in netd_report (buf=buf@entry=0x2000001c <ndis_report> "\001", len=len@entry=8) at /home/bkamath/.dev/fb/tinyusb/src/class/net/net_device.c:122
#2  0x08001526 in rndis_report () at /home/bkamath/.dev/fb/tinyusb/lib/networking/rndis_reports.c:81
#3  0x080015e6 in rndis_query_cmplt32 (status=status@entry=0, data=data@entry=0) at /home/bkamath/.dev/fb/tinyusb/lib/networking/rndis_reports.c:94
#4  0x08002298 in rndis_query () at /home/bkamath/.dev/fb/tinyusb/lib/networking/rndis_reports.c:127
#5  0x0800245c in rndis_class_set_handler (data=data@entry=0x20001f6c <notify> "\004", size=<optimized out>) at /home/bkamath/.dev/fb/tinyusb/lib/networking/rndis_reports.c:267
#6  0x08003306 in netd_control_xfer_cb (rhport=<optimized out>, stage=<optimized out>, request=0x20000068 <_ctrl_xfer>) at /home/bkamath/.dev/fb/tinyusb/src/class/net/net_device.c:339
#7  0x080016e8 in usbd_control_xfer_cb (rhport=<optimized out>, ep_addr=<optimized out>, result=<optimized out>, xferred_bytes=32) at /home/bkamath/.dev/fb/tinyusb/src/device/usbd_control.c:209
#8  0x080036a4 in tud_task () at /home/bkamath/.dev/fb/tinyusb/src/device/usbd.c:545
#9  0x0800a246 in main () at /home/bkamath/.dev/fb/tinyusb/examples/device/net_lwip_webserver/src/main.c:237

I'm not super familiar with the code-base yet, so I'm not sure if this is just some sort of RTOS/platform issue, or the net_device code not meeting the pre-conditions for calling usbd_edpt_xfer inside of netd_report.

Not sure if it's helpful, but this is what my dmesg output looks like on the host side:

[ 2895.868565] usb 1-1.1.2: USB disconnect, device number 27
[ 2896.618695] usb 1-1.1.2: new full-speed USB device number 28 using xhci_hcd
[ 2896.737422] usb 1-1.1.2: New USB device found, idVendor=cafe, idProduct=4020, bcdDevice= 1.01
[ 2896.737424] usb 1-1.1.2: New USB device strings: Mfr=1, Product=2, SerialNumber=3
[ 2896.737425] usb 1-1.1.2: Product: TinyUSB Device
[ 2896.737426] usb 1-1.1.2: Manufacturer: TinyUSB
[ 2896.737426] usb 1-1.1.2: SerialNumber: 123456
[ 2901.925172] rndis_host 1-1.1.2:1.0: RNDIS_MSG_QUERY(0x00010202) failed, -110
[ 2907.044517] rndis_host 1-1.1.2:1.0: RNDIS_MSG_QUERY(0x01010101) failed, -110
[ 2907.044524] rndis_host 1-1.1.2:1.0: rndis get ethaddr, -110

To Reproduce

Build example and connect to a linux machine.

Log

USBD init
NET init
USBD Bus Reset : Full Speed

USBD Setup Received 80 06 00 01 00 00 40 00 
  Get Descriptor Device
  Queue EP 80 with 18 bytes ... OK
USBD Xfer Complete on EP 80 with 18 bytes
  Queue EP 00 with 0 bytes ... OK
USBD Xfer Complete on EP 00 with 0 bytes
USBD Bus Reset : Full Speed

USBD Setup Received 00 05 33 00 00 00 00 00 
  Set Address
USBD Xfer Complete on EP 80 with 0 bytes

USBD Setup Received 80 06 00 01 00 00 12 00 
  Get Descriptor Device
  Queue EP 80 with 18 bytes ... OK
USBD Xfer Complete on EP 80 with 18 bytes
  Queue EP 00 with 0 bytes ... OK
USBD Xfer Complete on EP 00 with 0 bytes

USBD Setup Received 80 06 00 06 00 00 0A 00 
  Get Descriptor Device Qualifier
  Stall EP0

USBD Setup Received 80 06 00 06 00 00 0A 00 
  Get Descriptor Device Qualifier
  Stall EP0

USBD Setup Received 80 06 00 06 00 00 0A 00 
  Get Descriptor Device Qualifier
  Stall EP0

USBD Setup Received 80 06 00 02 00 00 09 00 
  Get Descriptor Configuration[0]
  Queue EP 80 with 9 bytes ... OK
USBD Xfer Complete on EP 80 with 9 bytes
  Queue EP 00 with 0 bytes ... OK
USBD Xfer Complete on EP 00 with 0 bytes

USBD Setup Received 80 06 00 02 00 00 4B 00 
  Get Descriptor Configuration[0]
  Queue EP 80 with 64 bytes ... OK
USBD Xfer Complete on EP 80 with 64 bytes
  Queue EP 80 with 11 bytes ... OK
USBD Xfer Complete on EP 80 with 11 bytes
  Queue EP 00 with 0 bytes ... OK
USBD Xfer Complete on EP 00 with 0 bytes

USBD Setup Received 80 06 01 02 00 00 09 00 
  Get Descriptor Configuration[1]
  Queue EP 80 with 9 bytes ... OK
USBD Xfer Complete on EP 80 with 9 bytes
  Queue EP 00 with 0 bytes ... OK
USBD Xfer Complete on EP 00 with 0 bytes

USBD Setup Received 80 06 01 02 00 00 58 00 
  Get Descriptor Configuration[1]
  Queue EP 80 with 64 bytes ... OK
USBD Xfer Complete on EP 80 with 64 bytes
  Queue EP 80 with 24 bytes ... OK
USBD Xfer Complete on EP 80 with 24 bytes
  Queue EP 00 with 0 bytes ... OK
USBD Xfer Complete on EP 00 with 0 bytes

USBD Setup Received 80 06 00 03 00 00 FF 00 
  Get Descriptor String[0]
  Queue EP 80 with 4 bytes ... OK
USBD Xfer Complete on EP 80 with 4 bytes
  Queue EP 00 with 0 bytes ... OK
USBD Xfer Complete on EP 00 with 0 bytes

USBD Setup Received 80 06 02 03 09 04 FF 00 
  Get Descriptor String[2]
  Queue EP 80 with 30 bytes ... OK
USBD Xfer Complete on EP 80 with 30 bytes
  Queue EP 00 with 0 bytes ... OK
USBD Xfer Complete on EP 00 with 0 bytes

USBD Setup Received 80 06 01 03 09 04 FF 00 
  Get Descriptor String[1]
  Queue EP 80 with 16 bytes ... OK
USBD Xfer Complete on EP 80 with 16 bytes
  Queue EP 00 with 0 bytes ... OK
USBD Xfer Complete on EP 00 with 0 bytes

USBD Setup Received 80 06 03 03 09 04 FF 00 
  Get Descriptor String[3]
  Queue EP 80 with 14 bytes ... OK
USBD Xfer Complete on EP 80 with 14 bytes
  Queue EP 00 with 0 bytes ... OK
USBD Xfer Complete on EP 00 with 0 bytes

USBD Setup Received 00 09 01 00 00 00 00 00 
  Set Configuration
  Open EP 81 with Size = 8
  Open EP 82 with Size = 64
  Open EP 02 with Size = 64
  Queue EP 02 with 1602 bytes ... OK
  NET opened
  Queue EP 80 with 0 bytes ... OK
USBD Xfer Complete on EP 80 with 0 bytes

USBD Setup Received 80 06 04 03 09 04 FF 00 
  Get Descriptor String[4]
  Queue EP 80 with 52 bytes ... OK
USBD Xfer Complete on EP 80 with 52 bytes
  Queue EP 00 with 0 bytes ... OK
USBD Xfer Complete on EP 00 with 0 bytes

USBD Setup Received 21 00 00 00 00 00 18 00 
  NET control request
  Queue EP 00 with 24 bytes ... OK
USBD Xfer Complete on EP 00 with 24 bytes
  NET control complete
  Queue EP 81 with 8 bytes ... OK
  Queue EP 80 with 0 bytes ... OK
USBD Xfer Complete on EP 80 with 0 bytes

USBD Setup Received A1 01 00 00 00 00 01 04 
  NET control request
  Queue EP 80 with 52 bytes ... OK
USBD Xfer Complete on EP 80 with 52 bytes
  NET control complete
  Queue EP 00 with 0 bytes ... OK
USBD Xfer Complete on EP 00 with 0 bytes

USBD Setup Received 21 00 00 00 00 00 20 00 
  NET control request
  Queue EP 00 with 32 bytes ... OK
USBD Xfer Complete on EP 00 with 32 bytes
  NET control complete
  Queue EP 81 with 8 bytes ... usbd_edpt_xfer 1249: assert failed
@kamathba
Copy link
Author

kamathba commented Jun 8, 2021

Found issue #289 after posting this. It (along with a few of the MRs) have a fair amount of discussion, I'm not positive this isn't a duplicate.

@hathach
Copy link
Owner

hathach commented Jun 14, 2021

thanks for the issue, I also encouter the ASSERT with 0x81 endpoint, however, it seems to be "normal" since currently the net driver doesn't check the busy state of the notification endpoint and can send one while previous one doesn't received by host yet. This will be fixed later but in general it does affect the example as this also appear on other working MCUs as well.

@kamathba
Copy link
Author

Thanks for confirming. What would be the correct way to handle this at the application layer if I wanted to work around it? Do I need to make it more into a queue + state machine? Or can I just not send if the endpoint is busy (will the host eventually retry)?

Happy to make a PR if I can understand the problem well enough.

@majbthrd
Copy link
Collaborator

majbthrd commented Aug 1, 2021

Alas, this seems to be a "feature" of the RNDIS driver bundled into recent Linux distributions. This newer Linux RNDIS driver fires off a bunch of RNDIS queries (via EP0) without first reading the notification EP response to the query/queries that it already sent. D'oh.

The workaround that I’m tempted to submit as a PR would be to add an if-busy check to netd_report() in ./src/class/net/net_device.c:

void netd_report(uint8_t *buf, uint16_t len)
{
  // skip if previous report not yet acknowledged by host
  if ( usbd_edpt_busy(TUD_OPT_RHPORT, _netd_itf.ep_notif) ) return;
  usbd_edpt_xfer(TUD_OPT_RHPORT, _netd_itf.ep_notif, buf, len);
}

@majbthrd
Copy link
Collaborator

I believe this issue can be closed. The above code was included in PR #1107.

@kamathba
Copy link
Author

This does seem to be resolved on the latest master. Webserver is functional and original problem can't be reproduced.

[ 1518.835363] usb 1-1.1.1: new full-speed USB device number 15 using xhci_hcd
[ 1518.949582] usb 1-1.1.1: New USB device found, idVendor=cafe, idProduct=4020, bcdDevice= 1.01
[ 1518.949585] usb 1-1.1.1: New USB device strings: Mfr=1, Product=2, SerialNumber=3
[ 1518.949586] usb 1-1.1.1: Product: TinyUSB Device
[ 1518.949587] usb 1-1.1.1: Manufacturer: TinyUSB
[ 1518.949588] usb 1-1.1.1: SerialNumber: 123456
[ 1518.987063] rndis_host 1-1.1.1:1.0 usb0: register 'rndis_host' at usb-0000:00:14.0-1.1.1, RNDIS device, 6a:51:1a:73:45:6e
[ 1518.989784] usbcore: registered new interface driver rndis_host

@hathach
Copy link
Owner

hathach commented Oct 24, 2021

great, thank you everyone 👍

@hathach hathach closed this as completed Oct 24, 2021
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
3 participants
@hathach @kamathba @majbthrd