Describe the bug
While testing my modified CANbardo board, I've found that when speaking to it directly via the gs_usb protocol (i.e. not via SocketCAN) that if I send packets too fast, then the frames are either queued a 0 inner length, or not queued at all!
I've isolated the behavior to just my CANbardo boards, which are also the only Atmel-bearing CAN<->USB boards I have.
(I've tested both the RH02 and RH02 Plus boards I PR'd earlier, in addition to a FYSETC UCAN. All those use varying flavors of STM32, but most importantly, they don't exhibit any of the incorrect behaviors described in this issue.)
Additionally, this happens with both USB High-Speed and Full-Speed. The CANbardo is my only high-speed-capable CAN adapter, the others mentioned are all full-speed only. I tested disabling High-Speed with the following placed into app/boards/canbardo_same70n20b.conf:
CONFIG_USBD_MAX_SPEED_HIGH=n
CONFIG_UDC_DRIVER_HIGH_SPEED_SUPPORT_ENABLED=n
This made it report as a Full-Speed device, but the issue still remained.
I'm unaware if this is a regression.
To Reproduce
west build -p always -b canbardo --sysbuild cannectivity/app/west flash- Connect another adapter/device to ack and print received messages, open with
candump or similar. (I used an external Raspi with an RH02)
- Run provided sample application to connect to CANbardo to send frames and try to receive TX Echos.
- Observe missing packets.
gs_usb_cannectivity_too_fast_tx_stuck.zip (Test app with Rust and C version)
Included is a one-file Rust program to connect to the adapter with nusb and try to send/receive frames. Additionally included is a C version utilizing libusb. Lastly is a Bash script to send frames via SocketCAN with cansend.
If you have the Rust toolchain installed (if not, rustup is easy to use!) the example app can be ran with cargo run and you can append --release to build with optimizations. I don't have a similar setup for the C version (distributing C apps with dependencies is a pain), but all it depends on is libusb, so I trust you to be able to handle that if you wish to validate with that. (But I will note that I experienced identical behaviors with the Rust and C versions, the behaviors always follow the board.)
Expected behavior
All valid packets sent to an idle adapter should be properly parsed, sent on the CAN bus, and confirmed via a TX Echo frame.
A successful (errno=0) Bulk transfer to the device should indicate that the adapter had room for the frame and will try to send it.
CAN Logs (as received)
All logs shown will be after trying to send 5 frames, and then receive echos for those 5 frames.
The frame's payload are always the bytes 0x0..=0x7 (0 thru and including 7), and the CAN ID increments by one with each sent frame.
(With these test apps, Frames are sent as fast as possible, but each Bulk Transfer voluntarily blocks until its completion result arrives.)
CANbardo:
Rust example (Linux):
$ candump can0 -H -tz
(000.000000) can0 000 [8] 00 01 02 03 04 05 06 07
(000.001220) can0 002 [8] 00 01 02 03 04 05 06 07
(000.002450) can0 004 [8] 00 01 02 03 04 05 06 07
Rust example (Windows):
$ candump can0 -H -tz
(000.000000) can0 000 [8] 00 01 02 03 04 05 06 07
(000.001220) can0 001 [8] 00 01 02 03 04 05 06 07
SocketCAN:
$ candump can0 -H -tz
(000.000000) can0 000 [8] 00 01 02 03 04 05 06 07
(000.001720) can0 001 [8] 00 01 02 03 04 05 06 07
(000.002980) can0 002 [8] 00 01 02 03 04 05 06 07
(000.004680) can0 003 [8] 00 01 02 03 04 05 06 07
(000.006430) can0 004 [8] 00 01 02 03 04 05 06 07
STM32:
Rust example (Windows):
$ candump can0 -H -tz
(000.000000) can0 000 [8] 00 01 02 03 04 05 06 07
(000.001220) can0 001 [8] 00 01 02 03 04 05 06 07
(000.002440) can0 002 [8] 00 01 02 03 04 05 06 07
(000.003660) can0 003 [8] 00 01 02 03 04 05 06 07
(000.004890) can0 004 [8] 00 01 02 03 04 05 06 07
Rust example (Linux):
$ candump can0 -H -tz
(000.000000) can0 000 [8] 00 01 02 03 04 05 06 07
(000.001220) can0 001 [8] 00 01 02 03 04 05 06 07
(000.002440) can0 002 [8] 00 01 02 03 04 05 06 07
(000.003660) can0 003 [8] 00 01 02 03 04 05 06 07
(000.004890) can0 004 [8] 00 01 02 03 04 05 06 07
Note how SocketCAN sent all frames without issue on CANbardo!
Logs and console output
There are two ways this issue manifests: Truncating frames to 0 length, and dropping frames entirely.
Truncating:
(the frames with IDs 1 and 2 were truncated by the device, but the PC side still received errno=0)
[00:01:55.881,000] <dbg> led.cannectivity_led_event: channel 0 started
[00:01:55.882,000] <dbg> gs_usb.gs_usb_request: request complete for ep 0x02 (err 0)
[00:01:55.882,000] <dbg> gs_usb.gs_usb_request: request complete for ep 0x02 (err 0)
[00:01:55.882,000] <dbg> gs_usb.gs_usb_request: request complete for ep 0x02 (err 0)
[00:01:55.882,000] <dbg> gs_usb.gs_usb_tx_thread: TX host frame
00 00 00 00 00 00 00 00 08 00 00 00 00 01 02 03 |........ ........
04 05 06 07 |....
[00:01:55.882,000] <dbg> gs_usb.gs_usb_request: request complete for ep 0x02 (err 0)
[00:01:55.882,000] <dbg> gs_usb.gs_usb_request: request complete for ep 0x02 (err 0)
[00:01:55.882,000] <dbg> gs_usb.gs_usb_tx_thread: TX host frame
[00:01:55.882,000] <err> gs_usb: TX host frame contains no header (0 < 12)
[00:01:55.882,000] <dbg> gs_usb.gs_usb_tx_thread: TX host frame
[00:01:55.882,000] <err> gs_usb: TX host frame contains no header (0 < 12)
[00:01:55.883,000] <dbg> gs_usb.gs_usb_tx_thread: TX host frame
03 03 03 03 03 00 00 00 08 00 00 00 00 01 02 03 |........ ........
04 05 06 07
Dropping:
(the frames with IDs 1 and 3 were dropped by the device, but the PC side still received errno=0)
[00:07:24.465,000] <dbg> led.cannectivity_led_event: channel 0 started
[00:07:24.465,000] <dbg> gs_usb.gs_usb_request: request complete for ep 0x02 (err 0)
[00:07:24.466,000] <dbg> gs_usb.gs_usb_request: request complete for ep 0x02 (err 0)
[00:07:24.466,000] <dbg> gs_usb.gs_usb_request: request complete for ep 0x02 (err 0)
[00:07:24.466,000] <dbg> gs_usb.gs_usb_tx_thread: TX host frame
00 00 00 00 00 00 00 00 08 00 00 00 00 01 02 03 |........ ........
04 05 06 07 |....
[00:07:24.466,000] <dbg> gs_usb.gs_usb_tx_thread: TX host frame
02 02 02 02 02 00 00 00 08 00 00 00 00 01 02 03 |........ ........
04 05 06 07 |....
[00:07:24.466,000] <dbg> gs_usb.gs_usb_tx_thread: TX host frame
04 04 04 04 04 00 00 00 08 00 00 00 00 01 02 03 |........ ........
04 05 06 07 |....
[00:07:24.467,000] <dbg> gs_usb.gs_usb_can_tx_callback: TX done
Environment
- Target board: CANbardo
- OS: Windows 11, Arch Linux (Kernel 7.1)
- Toolchain: Zephyr SDK 1.0.1 (I think)
- CANnectivity Git commit SHA:
b665df14d6070ed5841170572bc8240bed7093f8
- Zephyr RTOS Git commit SHA:
371514587b98df907af26c5fdc8f2be93cb09288
Additional context
This smells like an issue with the Atmel/SAM USB driver to me at first glance, and I'll summarize why:
- Happens regardless of OS.
- Happens ONLY on CANnectivity-running boards with SAM chips (I only have the CANbardo to test with)
a. I also have the candleLight firmware on some of my STM32 boards, and they also can handle these packets without issue.
- Happens ONLY if sending VERY QUICKLY.
- Happens regardless of using High-Speed/Full-Speed.
- Happens regardless of building with/without debug logs.
- Happens regardless of extra delays placed after connecting to device.
- Happens regardless of extra delays placed after sending each bReq.
To expand on point 3, if I simply add a 1ms delay after submitting the frame to my PC's USB stack, the issue seems to disappear. Yes, you read that right.
Plus, if you look at the successful SocketCAN attempt, there is a measurably longer delay between each packet than the example programs that speak gs_usb directly.
With all of these combined, and especially the time-related component here, it really smells like some USB-originating IRQ is stomping over an already-running USB ISR?
I'll look into it myself a little more, it's possible that the issue is originating over on the Zephyr/HAL side. Before I delve into that, I wanted to make sure that I'm not missing something simple and ask y'all if this is a known limitation or if this is a freshly-uncovered bug.
Thanks in advance!
Describe the bug
While testing my modified CANbardo board, I've found that when speaking to it directly via the
gs_usbprotocol (i.e. not via SocketCAN) that if I send packets too fast, then the frames are either queued a0inner length, or not queued at all!I've isolated the behavior to just my CANbardo boards, which are also the only Atmel-bearing CAN<->USB boards I have.
(I've tested both the RH02 and RH02 Plus boards I PR'd earlier, in addition to a FYSETC UCAN. All those use varying flavors of STM32, but most importantly, they don't exhibit any of the incorrect behaviors described in this issue.)
Additionally, this happens with both USB High-Speed and Full-Speed. The CANbardo is my only high-speed-capable CAN adapter, the others mentioned are all full-speed only. I tested disabling High-Speed with the following placed into
app/boards/canbardo_same70n20b.conf:This made it report as a Full-Speed device, but the issue still remained.
I'm unaware if this is a regression.
To Reproduce
west build -p always -b canbardo --sysbuild cannectivity/app/west flashcandumpor similar. (I used an external Raspi with an RH02)gs_usb_cannectivity_too_fast_tx_stuck.zip (Test app with Rust and C version)
Included is a one-file Rust program to connect to the adapter with nusb and try to send/receive frames. Additionally included is a C version utilizing libusb. Lastly is a Bash script to send frames via SocketCAN with
cansend.If you have the Rust toolchain installed (if not,
rustupis easy to use!) the example app can be ran withcargo runand you can append--releaseto build with optimizations. I don't have a similar setup for the C version (distributing C apps with dependencies is a pain), but all it depends on islibusb, so I trust you to be able to handle that if you wish to validate with that. (But I will note that I experienced identical behaviors with the Rust and C versions, the behaviors always follow the board.)Expected behavior
All valid packets sent to an idle adapter should be properly parsed, sent on the CAN bus, and confirmed via a TX Echo frame.
A successful (errno=0) Bulk transfer to the device should indicate that the adapter had room for the frame and will try to send it.
CAN Logs (as received)
All logs shown will be after trying to send 5 frames, and then receive echos for those 5 frames.
The frame's payload are always the bytes
0x0..=0x7(0 thru and including 7), and the CAN ID increments by one with each sent frame.(With these test apps, Frames are sent as fast as possible, but each Bulk Transfer voluntarily blocks until its completion result arrives.)
CANbardo:
STM32:
Note how SocketCAN sent all frames without issue on CANbardo!
Logs and console output
There are two ways this issue manifests: Truncating frames to 0 length, and dropping frames entirely.
Truncating:
(the frames with IDs
1and2were truncated by the device, but the PC side still received errno=0)Dropping:
(the frames with IDs
1and3were dropped by the device, but the PC side still received errno=0)Environment
b665df14d6070ed5841170572bc8240bed7093f8371514587b98df907af26c5fdc8f2be93cb09288Additional context
This smells like an issue with the Atmel/SAM USB driver to me at first glance, and I'll summarize why:
a. I also have the candleLight firmware on some of my STM32 boards, and they also can handle these packets without issue.
To expand on point 3, if I simply add a 1ms delay after submitting the frame to my PC's USB stack, the issue seems to disappear. Yes, you read that right.
Plus, if you look at the successful SocketCAN attempt, there is a measurably longer delay between each packet than the example programs that speak
gs_usbdirectly.With all of these combined, and especially the time-related component here, it really smells like some USB-originating IRQ is stomping over an already-running USB ISR?
I'll look into it myself a little more, it's possible that the issue is originating over on the Zephyr/HAL side. Before I delve into that, I wanted to make sure that I'm not missing something simple and ask y'all if this is a known limitation or if this is a freshly-uncovered bug.
Thanks in advance!