Intermittent configuration of T-Beam device

josephbu commented 2 years ago

Macbook Pro + Ubuntu 20.04 + T-Beam.

When starting nomadnet the RNode interface as configured in ~/.reticulum/config is not starting, from the logs it seems that the radio interface is not being configured correctly.

In this first log TX power mismatch is the error, and there is no Radio reporting TX power... echoed back.

[2022-04-02 12:06:14] [Verbose] AutoInterface[Default Interface] discovering peers for 1.8 seconds...
[2022-04-02 12:06:16] [Notice] Opening serial port /dev/ttyACM0...
[2022-04-02 12:06:18] [Verbose] Resetting ESP32-based device before configuration...
[2022-04-02 12:06:20] [Notice] Serial port /dev/ttyACM0 is now open
[2022-04-02 12:06:20] [Verbose] Configuring RNode interface...
[2022-04-02 12:06:20] [Verbose] Wating for radio configuration validation for RNodeInterface[RNode LoRa Interface]...
[2022-04-02 12:06:20] [Debug] RNodeInterface[RNode LoRa Interface] Radio reporting frequency is 433.775 MHz
[2022-04-02 12:06:20] [Debug] RNodeInterface[RNode LoRa Interface] Radio reporting bandwidth is 125.0 KHz
[2022-04-02 12:06:20] [Debug] RNodeInterface[RNode LoRa Interface] Radio reporting spreading factor is 8
[2022-04-02 12:06:20] [Debug] RNodeInterface[RNode LoRa Interface] Radio reporting coding rate is 5
[2022-04-02 12:06:20] [Verbose] RNodeInterface[RNode LoRa Interface] On-air bitrate is now 3.12 kbps
[2022-04-02 12:06:20] [Debug] RNodeInterface[RNode LoRa Interface] Radio reporting state is offline
[2022-04-02 12:06:20] [Error] TX power mismatch
[2022-04-02 12:06:20] [Error] Radio state mismatch
[2022-04-02 12:06:20] [Error] After configuring RNodeInterface[RNode LoRa Interface], the reported radio parameters did not match your configuration.
[2022-04-02 12:06:20] [Error] Make sure that your hardware actually supports the parameters specified in the configuration
[2022-04-02 12:06:20] [Error] Aborting RNode startup
[2022-04-02 12:06:20] [Error] The interface "RNode LoRa Interface" could not be created. Check your configuration file for errors!
[2022-04-02 12:06:20] [Error] The contained exception was: RNode interface did not pass configuration validation

In the second log from 10 seconds later Bandwidth mismatch is the error as Radio reporting bandwidth... is missing, however this time the TX Power was successfully set.

[2022-04-02 12:06:27] [Verbose] AutoInterface[Default Interface] discovering peers for 1.8 seconds...
[2022-04-02 12:06:29] [Notice] Opening serial port /dev/ttyACM0...
[2022-04-02 12:06:31] [Verbose] Resetting ESP32-based device before configuration...
[2022-04-02 12:06:34] [Notice] Serial port /dev/ttyACM0 is now open
[2022-04-02 12:06:34] [Verbose] Configuring RNode interface...
[2022-04-02 12:06:34] [Verbose] Wating for radio configuration validation for RNodeInterface[RNode LoRa Interface]...
[2022-04-02 12:06:34] [Debug] RNodeInterface[RNode LoRa Interface] Radio reporting frequency is 433.775 MHz
[2022-04-02 12:06:34] [Debug] RNodeInterface[RNode LoRa Interface] Radio reporting TX power is 7 dBm
[2022-04-02 12:06:34] [Debug] RNodeInterface[RNode LoRa Interface] Radio reporting spreading factor is 8
[2022-04-02 12:06:34] [Debug] RNodeInterface[RNode LoRa Interface] Radio reporting coding rate is 5
[2022-04-02 12:06:34] [Debug] RNodeInterface[RNode LoRa Interface] Radio reporting state is offline
[2022-04-02 12:06:34] [Error] Bandwidth mismatch
[2022-04-02 12:06:34] [Error] Radio state mismatch
[2022-04-02 12:06:34] [Error] After configuring RNodeInterface[RNode LoRa Interface], the reported radio parameters did not match your configuration.
[2022-04-02 12:06:34] [Error] Make sure that your hardware actually supports the parameters specified in the configuration
[2022-04-02 12:06:34] [Error] Aborting RNode startup
[2022-04-02 12:06:34] [Error] The interface "RNode LoRa Interface" could not be created. Check your configuration file for errors!
[2022-04-02 12:06:34] [Error] The contained exception was: RNode interface did not pass configuration validation

I am assuming that Reticulum is calling rnodeconf to configure the RNode that's defined in the config. Testing with running rnodeconf manually I also see similar intermittent results where some of the settings passed in the config string do not take effect and are not echo'ed back.

Power setting is ignored, no state echo'ed back.

$ rnodeconf /dev/ttyACM0 -T --freq 433775000 --bw 125000 --txp 7 --sf 8 --cr 5

[2022-04-02 12:32:16] Radio reporting frequency is 433.774963 MHz
[2022-04-02 12:32:16] Radio reporting bandwidth is 125.0 KHz
[2022-04-02 12:32:16] Radio reporting spreading factor is 8
[2022-04-02 12:32:16] Radio reporting coding rate is 5
[2022-04-02 12:32:17] Device set to TNC operating mode

10 seconds later, this time the bandwidth setting is ignored however the power setting sticks.

$ rnodeconf /dev/ttyACM0 -T --freq 433775000 --bw 125000 --txp 7 --sf 8 --cr 5

[2022-04-02 12:32:24] Radio reporting frequency is 433.774963 MHz
[2022-04-02 12:32:24] Radio reporting TX power is 7 dBm
[2022-04-02 12:32:24] Radio reporting spreading factor is 8
[2022-04-02 12:32:24] Radio reporting coding rate is 5
[2022-04-02 12:32:25] Device set to TNC operating mode

This T-Beam has worked ok using another other machine I'm using to get my test setup going.

However on that machine (Raspberry PI (buster) with Python3.7.3) using a T-Beam or Lora32 I also see similar where often one of the various radio config options is not applied and the setup of the RNode interface fails.

If I keep restarting nomadnet then it will work eventually.

Failed:

[2022-04-02 12:42:18] [Verbose] Configuring RNode interface...
[2022-04-02 12:42:18] [Verbose] Wating for radio configuration validation for RNodeInterface[RNode LoRa Interface]...
[2022-04-02 12:42:19] [Debug] RNodeInterface[RNode LoRa Interface] Radio reporting frequency is 433.775 MHz
[2022-04-02 12:42:19] [Debug] RNodeInterface[RNode LoRa Interface] Radio reporting bandwidth is 125.0 KHz
[2022-04-02 12:42:19] [Debug] RNodeInterface[RNode LoRa Interface] Radio reporting TX power is 7 dBm
[2022-04-02 12:42:19] [Debug] RNodeInterface[RNode LoRa Interface] Radio reporting state is offline
[2022-04-02 12:42:19] [Error] Spreading factor mismatch
[2022-04-02 12:42:19] [Error] Radio state mismatch
[2022-04-02 12:42:19] [Error] After configuring RNodeInterface[RNode LoRa Interface], the reported radio parameters did not match your configuration.

Minutes later worked ok:

[2022-04-02 12:44:09] [Verbose] Configuring RNode interface...
[2022-04-02 12:44:09] [Verbose] Wating for radio configuration validation for RNodeInterface[RNode LoRa Interface]...
[2022-04-02 12:44:10] [Debug] RNodeInterface[RNode LoRa Interface] Radio reporting frequency is 433.775 MHz
[2022-04-02 12:44:10] [Debug] RNodeInterface[RNode LoRa Interface] Radio reporting bandwidth is 125.0 KHz
[2022-04-02 12:44:10] [Debug] RNodeInterface[RNode LoRa Interface] Radio reporting TX power is 7 dBm
[2022-04-02 12:44:10] [Debug] RNodeInterface[RNode LoRa Interface] Radio reporting spreading factor is 8
[2022-04-02 12:44:10] [Debug] RNodeInterface[RNode LoRa Interface] Radio reporting coding rate is 5
[2022-04-02 12:44:10] [Verbose] RNodeInterface[RNode LoRa Interface] On-air bitrate is now 3.12 kbps
[2022-04-02 12:44:10] [Notice] RNodeInterface[RNode LoRa Interface] is configured and powered up
[2022-04-02 12:44:11] [Debug] System interfaces are ready

markqvist commented 2 years ago

Just a quick question before digging in further, when using it with Reticulum, the RNode is in "Normal (host-controlled)" mode, right? As in, it has not been set to TNC mode before being opened by Reticulum/nomadnet?

Thanks for reporting this!

markqvist commented 2 years ago

I have been trying to replicate this on macOS, and even trying several different devices I am having no luck in getting the issue to appear :(

I know this is a bit tedious, but to rule out simple causes, could you try the following:

Install the latest SiLabs USB VCP drivers for macOS from their download page.
Check that the old Apple-supplied drivers are not still conflicting with the new ones, see this forum post. In essence you probably have to unload and remove the KEXTs at /Library/Extensions/SiLabsUSBDriver.kext and /Library/Extensions/SiLabsUSBDriver64.kext.
Try another USB cable. Something reminds me that this kind of behaviour is often caused by bad cables.

Let me know!

josephbu commented 2 years ago

Apologies for not being clearer, I don't (yet) have a setup on MacOS. I'm seeing this on:

Macbook Pro + Ubuntu 20.04 Raspberry PI + Buster

The example of setting the radio into TNC mode was just a example where running rnodeconf over and over I could see that sometimes radio parameters weren't being set, and sometimes different parameters were applying or failing..

I set the radio back to host mode before trying to start up nomadnet where I see in the logs that it appears to be failing to set radio parameters.

Happy to try anything you think might be useful to debug/troubleshoot :-)

markqvist commented 2 years ago

Ah, of course! Sorry, I misunderstood those details. Just to make sure it is not something basic, could you try with another USB cable, and see if the intermittent behaviour regarding radio configuration still occurs?

If it does, I will try to compile a test version of Reticulum with slightly longer wait times for ESP32-based radio inits.

markqvist commented 2 years ago

Also, could you let me know the exact version information printed next to the SMA antenna connector on the T-Beam PCB?

markqvist / rnodeconfigutil

Intermittent configuration of T-Beam device #11