Delayed/stalled transfer in USB_CDC_ACM sample when using USBD_NEXT

[Shane-KBT]

Describe the bug

I'm using Zephyr (NCS) on a custom nRF52833 board, and am using the USB CDC ACM driver in the USBD_NEXT stack. I have my own binary packet protocol going over the virtual com port (working from Linux and Windows), but I notices that once in a while I'd not get a response to a request sent over the com port. Digging in, I found that the responses (TX from the nRF52833) were not being received by the host and when that happened, the last write to the CDC TX ringbuf was always a multiple of 64.

Anyway, to determine if this is an issue in my code vs. the USBD_NEXT code, I went back to the USB_CDC_ACM sample:

To Reproduce

My apologies for not doing this CLI style. I did this in VS Code using the nRF Connect extension:

• Select "Create a new application'
• Select 'Copy a sample"
• Select the nRF Connect SDK v2.8.0
• Select the 'CDC ACM USB' sample
• Pick a directory to copy the sample to
• The Open in new window (not really relevant)
• Then 'Add build Configuration'
• Select the nrf52833dk/nrf52833 board target (problem shows up on this for me as well)
• Select the 'usbd_next_prj.conf' as the base configuration file
• Build!
• Load onto target (flash, J-Link debug, O-zone whatever)

All the above could probably be done more simply via CLI, but that should give the basic idea. It's just the CDC ACM USB sample using the USBD NEXT configuration on an nRF52833 board, and it only uses the USB pins, which should work on any board that has a USB interface connected to the nRF52833.

Expected behavior

Now to demonstrate the problem:

The sample simply echoes whatever is received by the nRF52833 back to the host. To get it to transmit a "chunk" that is a multiple of 64 bytes, we just need to send a multiple of 64 bytes. So I just used Putty to open the COM port and then:

• send '1234567890123456789012345678901234567890123456789012345678901234' (not including the quotes) - (NOTE: I'm using copy/paste so this sends as one packet)
• see that nothing is sent back
• send anything else (press a key)
• see the 64 bytes above + the extra byte/key come back.

I then instrumented the interrupt handler to and enabled more debugging output from the USB transactions (logging via RTT in my case) with:

CONFIG_UDC_DRIVER_LOG_LEVEL_INF=y CONFIG_USBD_LOG_LEVEL_INF=y CONFIG_NRF_USBD_COMMON_LOG_LEVEL_INF=y

It turns out that the 64 byte packet at RX isn't being received by the interrupt handler. So, I then repeated the TX part of the handler to look like this:

        send_len = uart_fifo_fill(dev, buffer, rb_len);
        LOG_ERR("TX:%d", send_len);
        if (send_len < rb_len) {
            LOG_ERR("Drop %d bytes", rb_len - send_len);
        }

        send_len = uart_fifo_fill(dev, buffer, rb_len);
        LOG_ERR("TX:%d", send_len);
        if (send_len < rb_len) {
            LOG_ERR("Drop %d bytes", rb_len - send_len);
        }

With that, I can send 32 bytes and the USB CDC layer should then return a 64 byte response. So I then:

• send '12345678901234567890123456789012' (or any 32 bytes)
• witness no response, until
• send anything else
• see the 32 bytes echoed back (x2) + the extra byte (x2)

Logs and console output

The interesting bit here is that the debug logs show that the 32 bytes are received when sent, and the TX should have happened:

[00:29:25.112,579] \033[0m<inf> usbd_cdc_acm: 
                                       31 32 33 34 35 36 37 38  39 30 31 32 33 34 35 36 |12345678 90123456
                                       37 38 39 30 31 32 33 34  35 36 37 38 39 30 31 32 |78901234 56789012\033[0m
[00:29:25.112,670] \033[0m<inf> usbd_cdc_acm: UART dev 0xd2f0 size 64 length 32\033[0m
[00:29:25.112,670] \033[1;31m<err> cdc_acm_echo: RX:32\033[0m
[00:29:25.112,701] \033[0m<inf> usbd_cdc_acm: tx_en: trigger irq_cb_work\033[0m
[00:29:25.112,731] \033[0m<inf> usbd_cdc_acm: UART dev 0xd2f0, len 32, remaining space 992\033[0m
[00:29:25.112,731] \033[1;31m<err> cdc_acm_echo: TX:32\033[0m
[00:29:25.112,762] \033[0m<inf> usbd_cdc_acm: UART dev 0xd2f0, len 32, remaining space 960\033[0m
[00:29:25.112,762] \033[1;31m<err> cdc_acm_echo: TX:32\033[0m
[00:29:25.112,792] \033[1;31m<err> cdc_acm_echo: Ring buffer empty, disable TX IRQ\033[0m

But nothing shows up in Putty until I send something more..

I believe this is likely a ZLP handling issue in the UDC area of the USBD_NEXT stack, but haven't fully dug into that.

NOTE: if I use the "old" USB stack, everything works as expected. However, I wanted to use USBD_NEXT because it reports more events around the state of the USB connection. For now though I think I'll use the old stack to get along.

BTW: a solution like "don't write a multiple of 64 bytes" to the uart_fifo_fill() function isn't very good here--what really matters is the size that the driver send to the USB peripheral from it's ringbuffer, not what the application writes--the app code has no (or shoudn't have) knowledge of the CDC drivers ringbuffer state.

Impact

I'm not sure if this is an issue in the Zerphyr USB (next) stack, the CDC ACM driver, or perhaps the platform specific USB controller driver, but since the same driver is used for the "old" USB stack, I'd think it's in the Zephyr side of things.

For me, this means the CDC ACM driver in the USBD NEXT stack is non-workable, and perhaps anything in the USBD NEXT stack will also fail if the maximum packet size on USB is hit exactly (which should have a ZLP afterwards, right?).

Luckily, I can probably use the old stack and driver instead, so the impact isn't too earth shattering.

Environment (please complete the following information):

• OS: Windows 11
• Toolchain: nRF Connect SDK v2.8.0-a2386bfc8401, Zephyr OS v3.7.99-0bc3393fb112
• Commit SHA or Version used (see above)

Issue also as present in v2.70 (which is why I moved to v2.8.0 hoping it might have been fixed)

Additional context

[github-actions[bot]]

Hi @Shane-KBT! We appreciate you submitting your first issue for our open-source project. 🌟

Even though I'm a bot, I can assure you that the whole community is genuinely grateful for your time and effort. 🤖💙

[jfischer-no]

Looks like your host OS is broken, please try out https://github.com/zephyrproject-rtos/zephyr/pull/79193. I think you do not see this issue with legacy stack because of
https://github.com/zephyrproject-rtos/zephyr/blob/318492b5bf2c348cf4bc6086e4edcd7294201e8f/subsys/usb/device/class/cdc_acm.c#L288-L290 IMO host OS should not make any assumptions based on transaction size, last transaction with the size of MPS does not mean there will be another. There is no requirement to use ZLP in bulk transfers or in CDC ACM, also from CDC spec "The data is always a byte stream. The Data Class does not define the format of the stream, unless a protocol data wrapper is used."

[Shane-KBT]

Thanks for the quick response and the pointer to the potential fix #79193! I'll give that a shot.

I do realize that MS/Windows may not exactly follow the specs (or may interpret them differently), but being such a popular platform, I would expect that Zephyr's CDC ACM implementation would work properly out of the box since MS's implementation basically becomes a de-facto standard due to its broad use. Indeed, I assume that's why that "len -= 1;" is in the prior implementation. So, I'm liking the approach in #79193, where it modifies the default behavior and can be turned off if desired.

Thanks again, and I'll report back after I do some testing of that proposed patch...

[Shane-KBT]

Yep, the approach in #79193 seems to do the trick! I'll close this issue...

[jfischer-no]

Not resolved.