RIOT-OS / RIOT

RIOT - The friendly OS for IoT
https://riot-os.org
GNU Lesser General Public License v2.1
4.86k stars 1.97k forks source link

Standard output is truncated and sent to the shell input on Arduino Nano 33 BLE for the default example #20544

Open bmewen opened 4 months ago

bmewen commented 4 months ago

Description

The default example is supposed to print two lines then let the user type the commands, but on the Nano 33 BLE the two lines are not printed correctly and some characters are mixed in the shell input which imply that the user has to erase them.

Steps to reproduce the issue

With a Nano 33 BLE linked to the computer :

BOARD=arduino-nano-33-ble RIOT_TERMINAL=picocom make -C default flash term 

Note that I'm using picocom instead of pyserial which doesn't change anything to the result.

Expected results

The output is clean with the lines printed in the right order and the input is empty and let the user type his command without erasing anything.

The output is supposed to be the following one :

main(): This is RIOT! (Version : 2024-)
Welcome to RIOT!
>

Actual results

The actual output is :

Welcome to RIOT!
> mai):Th is

The first line is not printed and instead seems to be partially sent to the input of the shell.

Versions

All tests performed on a fresh master branch.

Operating System Environment

Operating System: "Ubuntu" "22.04.4 LTS (Jammy Jellyfish)" Kernel: Linux 6.5.0-26-generic x86_64 x86_64 System shell: /usr/bin/dash (probably dash) make's shell: /usr/bin/dash (probably dash)

Installed compiler toolchains

native gcc: gcc (Ubuntu 11.4.0-1ubuntu1~22.04) 11.4.0 arm-none-eabi-gcc: arm-none-eabi-gcc (15:10.3-2021.07-4) 10.3.1 20210621 (release) clang: Ubuntu clang version 14.0.0-1ubuntu1.1

Installed compiler libs

arm-none-eabi-newlib: "3.3.0"

Installed development tools

cmake: cmake version 3.22.1 doxygen: 1.9.1 git: git version 2.34.1 make: GNU Make 4.3 openocd: Open On-Chip Debugger 0.11.0 python: Python 3.12.2 python3: Python 3.12.2

maribu commented 3 months ago

Thanks for the report and sorry for the long wait.

I believe the issue you have faced is that two instances of picocom have been attached to the same TTY interface, with some chars going into one and some chars into the other.

Could you give this another spin? Ideally use the default terminal (pyterm), by not specifying RIOT_TERMINAL. That one opens the TTY interface exclusively, preventing two instances attached to the same TTY.

If you can still reproduce the issue could you try to capture the USB traffic e.g. using WireShark and confirm that the chars are already missing in the data send to the host?

bmewen commented 3 months ago

I've tried picocom and pyterm, both are giving me same result. I never used Wireshark to debug USB communication but it seems that the packets sent on both side have the same problem as those I get when using the serial terminal. From what I understand, the characters that are printed before the shell is executed seems to be partially redirected to its input.

Using my previous example : main(): This is RIOT! (Version : 2024-) is printed before the shell started and when I try to type help or any command, the first time this command will be mixed with main(): This is RIOT! (Version : 2024-)

bmewen commented 3 months ago

Here's a zip containing the Wireshark capture of the problem in the file named nano-33-ble-term-trace.pcapng. You can especially pay attention to the lines around 697 and 713 which corresponds to when the commands were typed.

I also included a typescript of terminal session so you can see exactly what happened, you can replay the script using : scriptreplay -t file.tm script.out. You will notice there that I was using pyterm as you mentionned.

The zip file : trace_and_script_33_ble.zip

bmewen commented 1 month ago

@maribu It has been a while since I last looked at this issue but it still seems to be a problem on this precise board type. I looked through multiple nrf52 boards and didn't have the problem I described in this thread. However on the nano 33 ble, even with the last RIOT version, the terminal is still not behaving correctly as described. The capture I uploaded in the last message is still relevant as the behavior I saw is the same. If you need any additional information feel free ask. Thanks in advance.

maribu commented 1 month ago

Thx for the follow up. Sadly, I won't be able to look into this issue any further due to time constraints :frowning:

crasbe commented 1 month ago

It is very odd that only the Arduino Nano 33 BLE would be affected. My suspicion was that it might be related to the bootloader, so I flashed the Arduino Nano 33 BLE bootloader to one of my nRF52840DK boards and tested it.

To flash the bootloader you have to download the "bootloader.bin" file from here: https://github.com/arduino/ArduinoCore-mbed/tree/main/bootloaders/nano33ble

Then I used nrfjprog to program the nRF52840 with the J-Link:

nrfjprog --recover && nrfjprog --chiperase --verify --program bootloader.bin && nrfjprog --pinresetenable && nrfjprog --pinreset

Unfortunately this is the output I got from the nRF52840 on the "nRF USB" port;

chris@ThinkPias:~/flashdev-riot/RIOT/examples/default$ BOARD=arduino-nano-33-ble make flash term -j12
Building application "default" for "arduino-nano-33-ble" with CPU "nrf52".

stty -F /dev/ttyACM0 raw ispeed 1200 ospeed 1200 cs8 -cstopb ignpar eol 255 eof 255
stty: /dev/ttyACM0: Eingabe-/Ausgabefehler
make: [/home/chris/flashdev-riot/RIOT/examples/default/../../Makefile.include:855: preflash] Fehler 1 (ignoriert)
sleep 1
...
*boring MAKE messages*
...
   text    data     bss     dec     hex filename
  51252     172    8516   59940    ea24 /home/chris/flashdev-riot/RIOT/examples/default/bin/arduino-nano-33-ble/default.elf
/home/chris/flashdev-riot/RIOT/dist/tools/bossa-nrf52/bossac -p /dev/ttyACM0  -e -i -w -v -b -R /home/chris/flashdev-riot/RIOT/examples/default/bin/arduino-nano-33-ble/default.bin
Device       : nRF52840-QIAA
Version      : Arduino Bootloader (SAM-BA extended) 2.0 [Arduino:IKXYZ]
Address      : 0x0
Pages        : 256
Page Size    : 4096 bytes
Total Size   : 1024KB
Planes       : 1
Lock Regions : 0
Locked       : none
Security     : false
Erase flash

Done in 0.001 seconds
Write 51424 bytes to flash (13 pages)
[==============================] 100% (13/13 pages)
Done in 2.020 seconds
Verify 51424 bytes of flash
[==============================] 100% (13/13 pages)
Verify successful
Done in 0.076 seconds
Set boot flash true
sleep 2
/home/chris/flashdev-riot/RIOT/dist/tools/pyterm/pyterm -p "/dev/ttyACM0" -b "115200"  
Twisted not available, please install it if you want to use pyterm's JSON capabilities
2024-07-03 11:55:13,844 # Connect to serial port /dev/ttyACM0
Welcome to pyterm!
Type '/exit' to exit.
2024-07-03 11:55:14,850 # RQ not implemented by driver
2024-07-03 11:55:14,851 # main(): This is RIOT! (Version: 2024.07-devel-10-g41921a-pr/littlefs_corrupted)
2024-07-03 11:55:14,852 # Welcome to RIOT!
> 

So I would like you to try to flash the Arduino Nano 33 BLE bootloader to one of your other nRF52840 boards as well and see if it works or not. Then it would be interesting to see if maybe the Arduino has a different silicon revision of the nRF52840 on it. I don't know how to check that though, but I'll try to find out and let you know.

Unfortunately I don't have an Arduino Nano 33 BLE and I don't have an old revision of the nRF52840 either. Maybe @maribu can do the same test that I did, it takes only a couple of minutes with one of his old boards.

Edit... I just saw that I did the test with my development fork, but that only has changes regarding the mtd_spi_nor subsystem, that shouldn't have any influence compared to the mainline code.

crasbe commented 1 month ago

Okay this is interesting... I just came back from lunch and wanted to print the device ID and now the error appears;

chris@ThinkPias:~/flashdev-riot/RIOT/examples/default$ BOARD=arduino-nano-33-ble make term -j12
/home/chris/flashdev-riot/RIOT/dist/tools/pyterm/pyterm -p "/dev/ttyACM0" -b "115200"  
Twisted not available, please install it if you want to use pyterm's JSON capabilities
2024-07-03 13:23:35,150 # Connect to serial port /dev/ttyACM0
Welcome to pyterm!
Type '/exit' to exit.
help
2024-07-03 13:23:40,396 # R no iplmenhelp
2024-07-03 13:23:40,396 # shell: command not found: R

It does not print anything after a reset, but it has some garbage in the buffer when I send a command.

HOWEVER! It does not happen with PuTTY on Windows (see screenshot). It only sends the data when I hit enter, but it isn't corrupted. Screenshot 2024-07-03 132753

This is good and bad, because on one hand it gives a hint about what the issue might be. But bad, because I don't know where to go from here 😅

bmewen commented 1 month ago

I also noticed that the bad behavior was not happening consistently, sometimes (I think the first time I flashed a new firmware) the observed behavior was correct exactly as you mentionned.

Enoch247 commented 1 month ago

Can you try using tinyusb instead of periph_usb and report results. To do so, add the following to your Makefile:

FEATURES_PROVIDED += tinyusb_device
USEPKG += tinyusb

you can confirm the change by doing:

$ make BOARD=arduino-nano-33-ble info-modules | grep usb
auto_init_tinyusb
periph_init_usbdev_clk
periph_usbdev_clk
stdio_tinyusb_cdc_acm  # <------- look for this line
tinyusb_class_cdc
tinyusb_common
tinyusb_contrib
tinyusb_device
tinyusb_hw
tinyusb_portable_nrf5x
bmewen commented 1 month ago

@Enoch247 your solution seems to "fix" the problem in a way as I don't have garbage anymore when I type a command but I still don't have the two first lines (This is RIOT and the other one) and also when I try to flash again my board, bossac is telling me "Device unsupported". It means that I have to manually press the reset button to put it back in flash mode. By the way, I don't know how the usb stack is related to the target device.

For the initial problem, given the results, I suppose that the problem is coming from the usual usb stack that might be too slow for this particular board type.

dylad commented 1 month ago

I don't know how the usb stack is related to the target device.

RIOT defines custom VID/PID for using USB. We do this only for convenience. In theory, user should provide its own VID/PID couple. You could check the VID/PID for USBUS and for tinyUSB. If they are different, this is probably the reason why BOSSAC complains

bmewen commented 1 month ago

I looked at the VID/PID in both riotboot Makefile and it seems that they are using the same pair which is 1209:7d00.

See :

For tinyusb : https://github.com/RIOT-OS/RIOT/blob/436b6edb694ecaffc73817c359ac31d65a09524a/pkg/tinyusb/contrib/tinyusb_descriptors.c#L102

And I guess there for usbus (not 100% sure on this one tho) : https://github.com/RIOT-OS/RIOT/blob/436b6edb694ecaffc73817c359ac31d65a09524a/sys/usb/usbus/usbus_fmt.c#L290

crasbe commented 1 month ago

Yes, lsusb confirms that too:

For periph_usb:

Bus 003 Device 006: ID 1209:7d00 Generic arduino-nano-33-ble

For tinyusb:

Bus 003 Device 009: ID 1209:7d00 Generic arduino-nano-33-ble

These are the bossac outputs when you enable the -d option for "debug":

chris@ThinkPias:~/flashdev-riot/RIOT/examples/default$ /home/chris/flashdev-riot/RIOT/dist/tools/bossa-nrf52/bossac -p /dev/ttyACM0  -e -i -w -v -b -d -R /home/chris/flashdev-riot/RIOT/examples/default/bin/arduino-nano-33-ble/default.bin
Set binary mode
version()=V#
Connected at 921600 baud
readWord(addr=0)=0x30303077
readWord(addr=0xe000ed00)=0x30303030
readWord(addr=0x400e0740)=0x23342c30
readWord(addr=0x400e0744)=0x30304577

Device unsupported

Then I reflashed the Arduino Bootloader (because I couldn't get it to program with the Reset button on the nRF52840DK) and this is the output from bossac:

chris@ThinkPias:~/flashdev-riot/RIOT/examples/default$ /home/chris/flashdev-riot/RIOT/dist/tools/bossa-nrf52/bossac -p /dev/ttyACM0  -e -i -w -v -b -d -R /home/chris/flashdev-riot/RIOT/examples/default/bin/arduino-nano-33-ble/default.bin
Set binary mode
version()=Arduino Bootloader (SAM-BA extended) 2.0 [Arduino:IKXYZ]
Connected at 921600 baud
identifyChip()=nRF52840-QIAA
write(addr=0,size=0x34)
writeWord(addr=0x30,value=0x400)
writeWord(addr=0x20,value=0)
version()=Arduino Bootloader (SAM-BA extended) 2.0 [Arduino:IKXYZ]
Device       : nRF52840-QIAA
Version      : Arduino Bootloader (SAM-BA extended) 2.0 [Arduino:IKXYZ]
Address      : 0x0
Pages        : 256
Page Size    : 4096 bytes
Total Size   : 1024KB
Planes       : 1
Lock Regions : 0
Locked       : none
Security     : false
Erase flash
chipErase(addr=0)

Done in 0.001 seconds
Write 51400 bytes to flash (13 pages)
[                              ] 0% (0/13 pages)write(addr=0x34,size=0x1000)
writeBuffer(scr_addr=0x34, dst_addr=0, size=0x1000)
[==                            ] 7% (1/13 pages)write(addr=0x34,size=0x1000)
writeBuffer(scr_addr=0x34, dst_addr=0x1000, size=0x1000)
[====                          ] 15% (2/13 pages)write(addr=0x34,size=0x1000)
writeBuffer(scr_addr=0x34, dst_addr=0x2000, size=0x1000)
[======                        ] 23% (3/13 pages)write(addr=0x34,size=0x1000)
writeBuffer(scr_addr=0x34, dst_addr=0x3000, size=0x1000)
[=========                     ] 30% (4/13 pages)write(addr=0x34,size=0x1000)
writeBuffer(scr_addr=0x34, dst_addr=0x4000, size=0x1000)
[===========                   ] 38% (5/13 pages)write(addr=0x34,size=0x1000)
writeBuffer(scr_addr=0x34, dst_addr=0x5000, size=0x1000)
[=============                 ] 46% (6/13 pages)write(addr=0x34,size=0x1000)
writeBuffer(scr_addr=0x34, dst_addr=0x6000, size=0x1000)
[================              ] 53% (7/13 pages)write(addr=0x34,size=0x1000)
writeBuffer(scr_addr=0x34, dst_addr=0x7000, size=0x1000)
[==================            ] 61% (8/13 pages)write(addr=0x34,size=0x1000)
writeBuffer(scr_addr=0x34, dst_addr=0x8000, size=0x1000)
[====================          ] 69% (9/13 pages)write(addr=0x34,size=0x1000)
writeBuffer(scr_addr=0x34, dst_addr=0x9000, size=0x1000)
[=======================       ] 76% (10/13 pages)write(addr=0x34,size=0x1000)
writeBuffer(scr_addr=0x34, dst_addr=0xa000, size=0x1000)
[=========================     ] 84% (11/13 pages)write(addr=0x34,size=0x1000)
writeBuffer(scr_addr=0x34, dst_addr=0xb000, size=0x1000)
[===========================   ] 92% (12/13 pages)write(addr=0x34,size=0x1000)
writeBuffer(scr_addr=0x34, dst_addr=0xc000, size=0x1000)
[==============================] 100% (13/13 pages)
Done in 2.022 seconds
Verify 51400 bytes of flash
checksumBuffer(start_addr=0, size=0x1000) = 983e
[==                            ] 7% (1/13 pages)checksumBuffer(start_addr=0x1000, size=0x1000) = 33da
[====                          ] 15% (2/13 pages)checksumBuffer(start_addr=0x2000, size=0x1000) = c17
[======                        ] 23% (3/13 pages)checksumBuffer(start_addr=0x3000, size=0x1000) = 8423
[=========                     ] 30% (4/13 pages)checksumBuffer(start_addr=0x4000, size=0x1000) = f82
[===========                   ] 38% (5/13 pages)checksumBuffer(start_addr=0x5000, size=0x1000) = 66fc
[=============                 ] 46% (6/13 pages)checksumBuffer(start_addr=0x6000, size=0x1000) = 3ef6
[================              ] 53% (7/13 pages)checksumBuffer(start_addr=0x7000, size=0x1000) = 8dd1
[==================            ] 61% (8/13 pages)checksumBuffer(start_addr=0x8000, size=0x1000) = ae91
[====================          ] 69% (9/13 pages)checksumBuffer(start_addr=0x9000, size=0x1000) = d335
[=======================       ] 76% (10/13 pages)checksumBuffer(start_addr=0xa000, size=0x1000) = d6b2
[=========================     ] 84% (11/13 pages)checksumBuffer(start_addr=0xb000, size=0x1000) = a443
[===========================   ] 92% (12/13 pages)checksumBuffer(start_addr=0xc000, size=0x8c8) = 53f1
[==============================] 100% (13/13 pages)
Verify successful
Done in 0.079 seconds
Set boot flash true
reset()

So what's happening here is that bossac tries to read a version (which I don't know yet how it does it) and the tinyusb program does not answer that correctly, therefore bossac can not identify the board and the operation fails.

dylad commented 1 month ago

Arduino bootloader probably have a different VID/PID couple. Maybe the issue with tinyUSB is that the device doesn't go into bootloader mode and thus is not recognized by BOSSAC.

crasbe commented 1 month ago

The defaule example compiled with tinyusb indeed does not seem to go into bootloader mode. When bossac is called, it should make the program go into bootloader mode. This should automatically change the VID/PID and the terminal shouldn't be accessible, which it is.

When there's a blank Arduino bootloader flashed and nothing else, the device has these IDs:

Bus 003 Device 033: ID 2341:005a Arduino SA Arduino Nano 33 BLE

With the periph_usb default example flashed and bossac is doing an upload, the device has the 2341:005a ID during the upload as well.

dylad commented 1 month ago

So you're probably missing usb_board_reset module with tinyUSB. This is the module that should trigger the 'reboot into bootloader' state.

bmewen commented 1 month ago

That was the problem I think, adding this module fixed this issue on my side. Thank you for the solution, as I already looked a bit at how bossac is used within RIOT I knew there was something odd about the reset not being triggered automatically but was not sure how to make it work the right way.

Also, does this means that tinyusb is missing the usb_board_reset in its own Makefile.dep as it seems to be in use in usbus ?

Unfortunately as I mentionned it does not solve entirely the problem as the first two lines that should be printed when RIOT is starting are not.

crasbe commented 1 month ago

I can confirm it works now. In the previous comment, I did not call the stty command before bossac, so the flash process would not have worked anyway. But I tried without the usb_board_reset module and it still does not work with stty and bossac. So the missing usb_board_reset module was the issue.

Also I can confirm that the output right after flashing is missing (but not truncated).

dylad commented 1 month ago

Alright we're making some progress here :) Now, regarding the missing output. You could try to increase TERM_DELAY to 3 for instance. TERM_DELAY=3 BOARD=arduino-nano-33-ble make flash term Does it happen only with picocom ? Does it also happen with pyterm ? Does it happen if you don't use make term (and manually open a terminal AFTER flashing) ?

dylad commented 1 month ago

Out of the scope of this issue, just a side note. You can also use bootloaders/riotboot_dfu as bootloader instead of the arduino bootloader. Then you can flash your board with PROGRAMMER=dfu-util FEATURES_REQUIRED=usbus_dfu make flash

bmewen commented 1 month ago

@dylad I tried to modify the TERM_DELAY in a range of 1 to 10 and i had no success with our issue. Regarding the terminal, as I said it does not matter, I've switched back to pyterm after maribu first response and I didn't notice any change. Same issue if I open a terminal with dist/tools/pyterm/pyterm -p "/dev/ttyACM0" -b "115200" after doing a simple make flash.

dylad commented 1 month ago

I don't have much idea for the remaining issue and I don't think I still have a nRF52-based board around. Perhaps I can reproduce it somehow on nRF53 ?

bmewen commented 1 month ago

I have absolutely no idea, for me nRF53 and nRF52- are two different types of chip and I don't think you can have compatibility between the two easily. I don't have myself a nRF53 board so I will not be able to help you there.

crasbe commented 1 month ago

The issue seems to be present on SAM21G microcontrollers as well: #20305