Issue with reading USB serial

[psobiech]

Hi,
first of all, I am quite new to Rust, so bear with me. I do seem to have some problems running the template. I am using teensy41.

I created my project using the generator, and after flashing I do seem to be unable to properly open the usb serial port (the led is properly blinking and I can change the frequency of the blink in the code).
cargo generate --git https://github.com/mciantyre/teensy4-rs-template --name cando

When connecting/restarting the device I get the following in dmesg (same in kernel 5.15 an 6.1, I dont see any warnings in dmesg for teensyduino):

[14381.187982] usb 1-4: new high-speed USB device number 35 using xhci_hcd
[14381.332880] usb 1-4: config 1 interface 0 altsetting 0 endpoint 0x81 has an invalid bInterval 255, changing to 11
[14381.332883] usb 1-4: config 1 interface 1 altsetting 0 bulk endpoint 0x82 has invalid maxpacket 64
[14381.332884] usb 1-4: config 1 interface 1 altsetting 0 bulk endpoint 0x1 has invalid maxpacket 64
[14381.333211] usb 1-4: New USB device found, idVendor=5824, idProduct=27dd, bcdDevice= 0.10
[14381.333214] usb 1-4: New USB device strings: Mfr=0, Product=2, SerialNumber=0
[14381.333215] usb 1-4: Product: imxrt-log
[14381.335321] cdc_acm 1-4:1.0: ttyACM0: USB ACM device

Trying picocom or screen, results in a freeze usually (with no output at all, I need to kill them, cannot exit normally). Also I don't see any output in Arduino IDE serial monitor. Once or twice it properly started showing the output.

I do see some output if i disconnect the usb cable and picocom errors out. Exmaple (there was no output until the cable was unplugged):

I know that baud should not matter in usb native mode, but I had tried with multiple baud rates nonetheless, without success.

If I flash Teensyduino everything works correctly. Is there a special command needed to open serial?

EDIT:
I actually adjusted locally MAX_PACKET_SIZE to 512 (in usbd.rs) and maxpacket warnings from dmesg are gone, but the behavior is the same.

EDIT2:
It does seem to work fine from Windows + PuTTY...

EDIT3:
I had some problems enumerating the device on Windows, it seems I do need to have the MAX_PACKET_SIZE = 512 for it to work. On Linux I saw that every time the device is connected mtp-probe is doing something with it, so I removed libmtp, now I do seem to have a better chance of connecting to serial. But when it IS working, it seems to skip some lines (on windows it does not skip anything):

[INFO cando]: Hello from the USB logger! The count is 92
[INFO cando]: Hello from the USB logger! The count is 94
[INFO cando]: Hello from the USB logger! The count is 96
[INFO cando]: Hello from the USB logger! The count is 99
[INFO cando]: Hello from the USB logger! The count is 103
[INFO cando]: Hello from the USB logger! The count is 105
[INFO cando]: Hello from the USB logger! The count is 108

But when I type/send any character, minicom just freezes again.

[mciantyre]

Thanks for sharing these findings. I'm particularly interested in your observations on Windows; they should help us with #126. Generally, I wouldn't be surprised if our driver isn't configured properly.

The Linux issues are new to me. I'll see if I can reproduce this myself when I get some time. In the mean time, here's a few things I'm curious about.

• I was able to reproduce an equivalent "an invalid bInterval 255" warning on my development host (although things tends to work for me). We should be able to resolve that warning by playing with the usbd-serial crate implementation. If you add this to the bottom of your Cargo.toml then rebuild, I hope that the "invalid bInterval" warning goes away.

  [patch.crates-io.usbd-serial]
  git = "https://github.com/mciantyre/usbd-serial"

  If you're curious, here is what I changed.

• Good idea to play with the USB bulk endpoint max packet size (MPS). Just as a hint: you can change that at build time using an environment variable. That's documented here. From the command line,

  IMXRT_LOG_USB_BULK_MPS=512 cargo build [...]

  should produce the same effect as hard-coding 512 into the usbd.rs module.

• What happens if we force a full-speed USB device, instead of permitting a high-speed USB device? Note that usbd-serial should be standard (not my patch), and the bulk endpoint MPS should remain 64 bytes large.

  IMXRT_LOG_USB_SPEED=FULL cargo build [...]

• Does the situation improve if you change bcdUSB? See the workaround discussed in USB logging: USB device not recognized on Windows #126.

[psobiech]

First of all thank you for your time :-)

1. Like you said usbd-serial solves the bInterval 255 warning
2. I did not know I can pass env variables, pretty handy, this solves the maxpacket 64 issue
3. Enabling USB FS = no dmesg errors, but same issues

[23727.395130] usb 1-5: new full-speed USB device number 43 using xhci_hcd
[23727.536820] usb 1-5: New USB device found, idVendor=5824, idProduct=27dd, bcdDevice= 0.10
[23727.536823] usb 1-5: New USB device strings: Mfr=0, Product=2, SerialNumber=0
[23727.536824] usb 1-5: Product: imxrt-log
[23727.539087] cdc_acm 1-5:1.0: ttyACM0: USB ACM device

Since by using 1+2 we solved the warnings, I think its safe to assume, that my issue is not related to the warnings.
I just noticed, that I need to run teensy_loader_cli twice to flash my device (after issuing a reset), so I think there is still something that is writing to serial after i connect the device.
This would be in line with the behavior that when I can get it to randomly to work and send any character it freezes again. So if there is something that is sending a characters on 'init' that would cause the issue.

With regards to #126:

1. imxrt-usbd - it does produce the same 3 warnings (bInterval + 2 maxpackets) as above, but serial and the echo IS working 👯 . So there is something we do better here :)
   
2. imxrt-hal - has only warning of bInterval 255, but it has the same behaviour as the original example

This makes me believe there is something with consuming input in our original and imxrt-hal example and there is something still on my system "checking" the CDC device on connection.

One thing of note, I had the best success with minicom, when I open the minicom, then replug the device so minicom auto reconnects by itself. After it successfully "initializes" i can switch between screen, picocom and minicom until I reset the device.
If I connect the device and then open minicom, it will not be able to initialize.
Also when I get it to work as above, type a character (it freezes) and disconnect the device, i get the following in dmesg (the line appears for each character i had sent):

[25437.090087] usb 1-5: USB disconnect, device number 75
[25437.090340] cdc_acm 1-5:1.1: acm_start_wb - usb_submit_urb(write bulk) failed: -19
[25438.071601] usb 1-5: new high-speed USB device number 76 using xhci_hcd

EDIT1:
Changing the bcdUSB 2.1 from 0x10 to 0x00 (2.0) does not change anything for me besides removing the bInterval 255 warning (the other 2 are still present), but the serial does not initialize properly.

I think MAX_PACKET_SIZE=512 became the mandatory for 2.1, so both solutions fix windows enumeration issues. But I think it might be mandatory for all USB HS: https://wiki.osdev.org/Universal_Serial_Bus#Maximum_Data_Payload_Size_2

EDIT2: Corresponding Teensyduino code (seems for HS they are setting mps to 512): https://github.com/PaulStoffregen/cores/blob/master/teensy4/usb_serial.c#L103
https://github.com/PaulStoffregen/cores/blob/2dbb6f6c58f3d8e1272286daba3f3b094893c5b3/teensy4/usb_desc.h#L133

[mciantyre]

Thank you for your time too! Your hints and research are helpful; I'm learning lots here.

I think MAX_PACKET_SIZE=512 became the mandatory for 2.1, so both solutions fix windows enumeration issues. But I think it might be mandatory for all USB HS.

Ahh, I had been interpreting all my previous research (admittedly, not from the standards documents) as

if (speed == High) { assert!(bulk_mps <= 512); }

But it's actually

if (speed == High) { assert!(bulk_mps == 512); }

Thanks for sharing this. With this in mind, we'll likely need to couple the speed to the MPS buffer sizes in imxrt-log.

[psobiech]

Glad I was able to help ;-)

[mciantyre]

Update for future readers: The patch described below is available in 0.1.1 of imxrt-log.

I reproduced some of these logging issues on a Linux host (5.15 kernel). I use screen to visualize the logging output. Similar to you, I would see infrequent, inconsistent output (like what's depicted in the image). I would also have issues disconnecting.

I'm noticing much better behavior with this commit in the imxrt-log package. @psobiech, if you have time, could you give this a try on your end? Add the following to the bottom of your project's Cargo.toml, and your project should automatically pick up the patch.

[patch.crates-io.imxrt-log]
git = "https://github.com/mciantyre/imxrt-hal"
branch = "log-fixes"

Some extra notes:

• The patch seems to work even when SPEED=HIGH and BULK_MPS=64. It also works when setting BULK_MPS=512.
• The patch seems to work no matter the "invalid bInterval 255" warning. There shouldn't be a need to apply the usbd-serial patch.

[psobiech]

Thank you so much, yes, after this change it no longer freezes when I send some data after I connect 👍🏻 and the output is consistent.

But I do still need to open minicom first and then cycle the device to see the output. It does not work if I open the serial connection after device connects. I do think its something on my machine that is sending some superfluous data when device connects (if minicom is connected its just 'faster' to take the tty) but I don't see anything in udev (I removed all android/modem related udev rules).

The teensyduino and usbd serial example (https://github.com/imxrt-rs/imxrt-usbd/blob/master/examples/teensy4/src/serial.rs) are working for me without issues most of the time.

Maybe, we are missing read_packet(&mut []).ok(); or draining some read buffers even earlier in the connection process?

EDIT1: Actually I did more tests and after your recent changes and it seems that if I am fast (before the counter 5 is logged), then I can connect now 100% of the time! If I wait before I run my connection, then I cannot connect. We do seem to have some race condition here.

EDIT2: imxrt-usbd serial example has the same issue, that it works If i connect ASAP, if I wait it freezes - no echo is sent.

EDIT3: Just to be sure, I checked with teensyduino and it does work 100% of the time not matter If I wait or not

[mciantyre]

At this point, I can't reproduce any more issues on my Linux setup (Raspberry Pi, nearly stock bullseye install). I'm building the teensy4-rs-template project with the above patch. And I'm testing with both screen (4.08.00) and minicom (2.8). No matter the tool, I can connect whenever, disconnect whenever, mash keys on the keyboard while connected, then disconnect and reconnect again. I can't freeze it. If there's a way to reproduce your full setup on a Raspberry Pi, I'd be happy to give it a shot.

Unlike the Teensyduino SDK, we're not in full control of the USB stack. The usb-device package and its supporting class drivers hide configurations from us. We're also stressing the ecosystem; high-speed devices aren't officially supported. We likely need more tuning in imxrt-log, imxrt-usbd, and throughout the dependency chain.

I'll release that imxrt-log patch in the next few days. I'll also queue up a fix for the high-speed bulk endpoint MPS, though I'll probably release that as a breaking change.