Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Radio parameter mismatch on lora32_v21 #39

Open
FountainOfInk opened this issue Sep 14, 2024 · 13 comments
Open

Radio parameter mismatch on lora32_v21 #39

FountainOfInk opened this issue Sep 14, 2024 · 13 comments

Comments

@FountainOfInk
Copy link

FountainOfInk commented Sep 14, 2024

Summary:

After successfully building and flashing the firmware on my lora32_v21 boards, rnsd reports that the TX power and bandwidth reported by the board does not match, and thus the RNode setup fails. This issue does not occur when using rnodeconf --autoinstall, nor when manually building and flashing markqvist's firmware. (I have noticed that sometimes it is only the TX power that is mismatched, but usually it's both the TX power and the bandwidth.)

Versions:

rns package version (from pip): 0.7.7
rnsd version: 0.7.7
rnodeconf version: 2.1.3
Repository commit hash: 2cdf2951e6f68074a7cf6b381ca22562d6101e5f

Config:

RNode config block:

  [[lora rnode1]]
    type = RNodeInterface
    interface_enabled = true
    port = /dev/ttyACM0
    frequency = 915000000
    bandwidth = 500000
    txpower = 7
    spreadingfactor = 8
    codingrate = 5

Steps to reproduce:

Clone this repository: git clone https://github.com/liberatedsystems/RNode_Firmware_CE && cd RNode_Firmware_CE/
Build and flash the firmware: make firmware-lora32_v21 && make upload-lora32_v21
Run rnsd: rnsd -v

Expected outcome:

rnsd reports no errors, and successfully brings up the RNode interface.

Example output:

[2024-09-13 17:23:06] [Notice] Opening serial port /dev/ttyACM0...
[2024-09-13 17:23:08] [Notice] Serial port /dev/ttyACM0 is now open
[2024-09-13 17:23:09] [Notice] RNodeInterface[lora rnode1] is configured and powered up
[2024-09-13 17:23:09] [Notice] Started rnsd version 0.7.7

Actual outcome:

rnsd reports that the radio parameters are mismatched, and is unable to bring up the RNode interface.

Actual output:

[2024-09-13 17:53:10] [Verbose] Bringing up system interfaces...
[2024-09-13 17:53:10] [Verbose] AutoInterface[Default Interface] discovering peers for 1.5 seconds...
[2024-09-13 17:53:11] [Notice] Opening serial port /dev/ttyACM0...
[2024-09-13 17:53:13] [Notice] Serial port /dev/ttyACM0 is now open
[2024-09-13 17:53:13] [Verbose] Configuring RNode interface...
[2024-09-13 17:53:13] [Verbose] Waiting for radio configuration validation for RNodeInterface[lora rnode1]...
[2024-09-13 17:53:14] [Verbose] RNodeInterface[lora rnode1] On-air bitrate is now 0.19 kbps
[2024-09-13 17:53:14] [Error] Bandwidth mismatch
[2024-09-13 17:53:14] [Error] TX power mismatch
[2024-09-13 17:53:14] [Error] After configuring RNodeInterface[lora rnode1], the reported radio parameters did not match your configuration.
[2024-09-13 17:53:14] [Error] Make sure that your hardware actually supports the parameters specified in the configuration
[2024-09-13 17:53:14] [Error] Aborting RNode startup
[2024-09-13 17:53:14] [Verbose] System interfaces are ready
[2024-09-13 17:53:14] [Verbose] Configuration loaded from /home/user/.reticulum/config
[2024-09-13 17:53:14] [Verbose] Loaded 82 known destination from storage
[2024-09-13 17:53:14] [Verbose] Loaded Transport Identity from storage
[2024-09-13 17:53:14] [Notice] Started rnsd version 0.7.7
@jacobeva
Copy link

Thanks for the bug report. Have you tried powering off the device completely and then connect it back to power and then try to bring it up? Is there anything showing on the display (if present)? I believe @jeremybox had a similar issue before.

If that doesn't work, I will investigate further :)

@FountainOfInk
Copy link
Author

FountainOfInk commented Sep 14, 2024

Have you tried powering off the device completely and then connect it back to power and then try to bring it up?

I exclusively power my devices via usb, since I have no batteries to connect them to. The physical power switch on them doesn't seem to do anything (on all firmwares, on all versions). I assumed this is not a bug. I power them off simply by physically connecting the usb cable (I hope this isn't bad). Is this powering it off completely? I'm not sure.

Is there anything showing on the display (if present)?

The display functions as normal prior to starting rnsd. When starting rnsd, the display switches to the normal active state (on @ XY.Zkbps, airtime X.Y%, etc.), including the waterfall.

Please tell me if I misunderstood any of your questions :)

@FountainOfInk
Copy link
Author

FountainOfInk commented Sep 14, 2024

Trying to configure the transmit power manually beforehand with rnodeconf --txp 7 /dev/ttyACM0 yields the following output from rnodeconf:

[13:36:37] Opening serial port /dev/ttyACM0...
[13:36:41] Device connected
[13:36:41] Current firmware version: 1.73
[13:36:41] Reading EEPROM...
[13:36:41] EEPROM checksum correct
[13:36:41] Device signature validated

rnsd behaves exactly the same as if this were not performed.

@jeremybox
Copy link

What is the output from a terminal when you just try to connect to the device with minicom/screen/tio or whatever terminal you like?

@FountainOfInk
Copy link
Author

@jeremybox tio /dev/ttyACM0 just outputs 'd every ~5 seconds.

@jeremybox
Copy link

one of the things I noticed with the techo stuff was it would repeat (not once every 5 second but several times a second) nonsense characters when it was unhappy and trying to initialize the radio.

adding
#define VALIDATE_FIRMWARE false

to my board config got me past the hangup initializing the radio.

@jacobeva
Copy link

jacobeva commented Sep 16, 2024

Is this powering it off completely? I'm not sure.

Yes :)

That's quite strange, it seems that the RNode is initialising but whatever bandwidth and TX power values it is returning are incorrect. This won't have anything to do with disabling firmware validation, since that definitely works fine on the ESP32.

@FountainOfInk Can you please try running rnsd again with the loglevel set to 7 in your Reticulum config file? That will give me a better idea of what's happening here. In fact, can you try doing it twice and check the output is the same each time as well?

@FountainOfInk
Copy link
Author

@jacobeva Here you go: (The first run reports a transmit power of 143dBm, and a frequency of 915mhz, and the second two report 0dBm and 0mhz.)

[2024-09-16 20:13:33] [Debug] Started shared instance interface: Shared Instance[37428]
[2024-09-16 20:13:33] [Debug] Cleaning ratchets...
[2024-09-16 20:13:33] [Extra] Cleaning resource and packet caches...
[2024-09-16 20:13:33] [Verbose] Bringing up system interfaces...
[2024-09-16 20:13:33] [Debug] Skipping disabled interface "Default Interface"
[2024-09-16 20:13:33] [Debug] Skipping disabled interface "UDP Interface"
[2024-09-16 20:13:33] [Debug] Skipping disabled interface "TCP Server Interface"
[2024-09-16 20:13:33] [Debug] Skipping disabled interface "TCP Client Interface"
[2024-09-16 20:13:33] [Debug] Skipping disabled interface "I2P"
[2024-09-16 20:13:33] [Debug] Skipping disabled interface "RNode LoRa Interface"
[2024-09-16 20:13:33] [Debug] Skipping disabled interface "Packet Radio KISS Interface"
[2024-09-16 20:13:33] [Debug] Skipping disabled interface "Packet Radio AX.25 KISS Interface"
[2024-09-16 20:13:33] [Notice] Opening serial port /dev/ttyACM0...
[2024-09-16 20:13:36] [Notice] Serial port /dev/ttyACM0 is now open
[2024-09-16 20:13:36] [Verbose] Configuring RNode interface...
[2024-09-16 20:13:36] [Verbose] Waiting for radio configuration validation for RNodeInterface[lora rnode1]...
[2024-09-16 20:13:36] [Debug] RNodeInterface[lora rnode1] Radio reporting frequency is 915.0 MHz
[2024-09-16 20:13:36] [Debug] RNodeInterface[lora rnode1] Radio reporting bandwidth is 7.8 KHz
[2024-09-16 20:13:36] [Debug] RNodeInterface[lora rnode1] Radio reporting symbol time is 0.0ms (at 0 baud)
[2024-09-16 20:13:36] [Debug] RNodeInterface[lora rnode1] Radio reporting preamble is 10 symbols (0ms)
[2024-09-16 20:13:36] [Debug] RNodeInterface[lora rnode1] Radio reporting CSMA slot time is 50ms
[2024-09-16 20:13:36] [Debug] RNodeInterface[lora rnode1] Radio reporting TX power is 143 dBm
[2024-09-16 20:13:36] [Debug] RNodeInterface[lora rnode1] Radio reporting spreading factor is 8
[2024-09-16 20:13:36] [Debug] RNodeInterface[lora rnode1] Radio reporting coding rate is 7
[2024-09-16 20:13:36] [Verbose] RNodeInterface[lora rnode1] On-air bitrate is now 0.14 kbps
[2024-09-16 20:13:36] [Debug] RNodeInterface[lora rnode1] Radio reporting symbol time is 2.05ms (at 488 baud)
[2024-09-16 20:13:36] [Debug] RNodeInterface[lora rnode1] Radio reporting preamble is 22 symbols (45ms)
[2024-09-16 20:13:36] [Debug] RNodeInterface[lora rnode1] Radio reporting CSMA slot time is 50ms
[2024-09-16 20:13:36] [Error] Bandwidth mismatch
[2024-09-16 20:13:36] [Error] TX power mismatch
[2024-09-16 20:13:36] [Error] After configuring RNodeInterface[lora rnode1], the reported radio parameters did not match your configuration.
[2024-09-16 20:13:36] [Error] Make sure that your hardware actually supports the parameters specified in the configuration
[2024-09-16 20:13:36] [Error] Aborting RNode startup
[2024-09-16 20:13:36] [Error] A serial port error occurred, the contained exception was: [Errno 9] Bad file descriptor
[2024-09-16 20:13:36] [Error] The interface RNodeInterface[lora rnode1] experienced an unrecoverable error and is now offline.
[2024-09-16 20:13:36] [Error] Reticulum will attempt to reconnect the interface periodically.
[2024-09-16 20:13:36] [Debug] Skipping disabled interface "RNS Testnet Amsterdam"
[2024-09-16 20:13:36] [Verbose] System interfaces are ready
[2024-09-16 20:13:36] [Verbose] Configuration loaded from /home/user/.reticulum/config
[2024-09-16 20:13:36] [Verbose] Loaded 103 known destination from storage
[2024-09-16 20:13:36] [Verbose] Loaded Transport Identity from storage
[2024-09-16 20:13:36] [Notice] Started rnsd version 0.7.7
[2024-09-16 20:13:41] [Verbose] Attempting to reconnect serial port /dev/ttyACM0 for RNodeInterface[lora rnode1]...
[2024-09-16 20:13:41] [Notice] Opening serial port /dev/ttyACM0...
^C
[2024-09-16 20:13:43] [Debug] Saved packet hashlist in 10.19ms
[2024-09-16 20:13:43] [Debug] Saving path table to storage...
[2024-09-16 20:13:43] [Debug] Saved 0 path table entries in 0.21ms
[2024-09-16 20:13:43] [Debug] Saving tunnel table to storage...
[2024-09-16 20:13:43] [Debug] Saved 0 tunnel table entries in 0.07ms
[2024-09-16 20:13:43] [Debug] Saving 103 known destinations to storage...
[2024-09-16 20:13:43] [Debug] Saved known destinations to storage in 1.62ms

And again:

[2024-09-16 20:15:15] [Debug] Started shared instance interface: Shared Instance[37428]
[2024-09-16 20:15:15] [Debug] Cleaning ratchets...
[2024-09-16 20:15:15] [Extra] Cleaning resource and packet caches...
[2024-09-16 20:15:15] [Verbose] Bringing up system interfaces...
[2024-09-16 20:15:15] [Debug] Skipping disabled interface "Default Interface"
[2024-09-16 20:15:15] [Debug] Skipping disabled interface "UDP Interface"
[2024-09-16 20:15:15] [Debug] Skipping disabled interface "TCP Server Interface"
[2024-09-16 20:15:15] [Debug] Skipping disabled interface "TCP Client Interface"
[2024-09-16 20:15:15] [Debug] Skipping disabled interface "I2P"
[2024-09-16 20:15:15] [Debug] Skipping disabled interface "RNode LoRa Interface"
[2024-09-16 20:15:15] [Debug] Skipping disabled interface "Packet Radio KISS Interface"
[2024-09-16 20:15:15] [Debug] Skipping disabled interface "Packet Radio AX.25 KISS Interface"
[2024-09-16 20:15:15] [Notice] Opening serial port /dev/ttyACM0...
[2024-09-16 20:15:17] [Notice] Serial port /dev/ttyACM0 is now open
[2024-09-16 20:15:17] [Verbose] Configuring RNode interface...
[2024-09-16 20:15:17] [Verbose] Waiting for radio configuration validation for RNodeInterface[lora rnode1]...
[2024-09-16 20:15:17] [Debug] RNodeInterface[lora rnode1] Radio reporting frequency is 0.0 MHz
[2024-09-16 20:15:17] [Debug] RNodeInterface[lora rnode1] Radio reporting bandwidth is 7.8 KHz
[2024-09-16 20:15:17] [Debug] RNodeInterface[lora rnode1] Radio reporting symbol time is 2.05ms (at 488 baud)
[2024-09-16 20:15:17] [Debug] RNodeInterface[lora rnode1] Radio reporting preamble is 22 symbols (45ms)
[2024-09-16 20:15:17] [Debug] RNodeInterface[lora rnode1] Radio reporting CSMA slot time is 50ms
[2024-09-16 20:15:17] [Debug] RNodeInterface[lora rnode1] Radio reporting TX power is 0 dBm
[2024-09-16 20:15:17] [Debug] RNodeInterface[lora rnode1] Radio reporting spreading factor is 8
[2024-09-16 20:15:17] [Debug] RNodeInterface[lora rnode1] Radio reporting coding rate is 7
[2024-09-16 20:15:17] [Verbose] RNodeInterface[lora rnode1] On-air bitrate is now 0.14 kbps
[2024-09-16 20:15:17] [Debug] RNodeInterface[lora rnode1] Radio reporting state is offline
[2024-09-16 20:15:18] [Error] Frequency mismatch
[2024-09-16 20:15:18] [Error] Bandwidth mismatch
[2024-09-16 20:15:18] [Error] TX power mismatch
[2024-09-16 20:15:18] [Error] Radio state mismatch
[2024-09-16 20:15:18] [Error] After configuring RNodeInterface[lora rnode1], the reported radio parameters did not match your configuration.
[2024-09-16 20:15:18] [Error] Make sure that your hardware actually supports the parameters specified in the configuration
[2024-09-16 20:15:18] [Error] Aborting RNode startup
[2024-09-16 20:15:18] [Error] A serial port error occurred, the contained exception was: [Errno 9] Bad file descriptor
[2024-09-16 20:15:18] [Error] The interface RNodeInterface[lora rnode1] experienced an unrecoverable error and is now offline.
[2024-09-16 20:15:18] [Error] Reticulum will attempt to reconnect the interface periodically.
[2024-09-16 20:15:18] [Debug] Skipping disabled interface "RNS Testnet Amsterdam"
[2024-09-16 20:15:18] [Verbose] System interfaces are ready
[2024-09-16 20:15:18] [Verbose] Configuration loaded from /home/user/.reticulum/config
[2024-09-16 20:15:18] [Verbose] Loaded 103 known destination from storage
[2024-09-16 20:15:18] [Verbose] Loaded Transport Identity from storage
[2024-09-16 20:15:18] [Notice] Started rnsd version 0.7.7
^C[2024-09-16 20:15:22] [Error] An error occurred while detaching RNodeInterface[lora rnode1]. The contained exception was: Attempting to use a port that is not open

[2024-09-16 20:15:22] [Debug] Saved packet hashlist in 0.25ms
[2024-09-16 20:15:22] [Debug] Saving path table to storage...
[2024-09-16 20:15:22] [Debug] Saved 0 path table entries in 0.23ms
[2024-09-16 20:15:22] [Debug] Saving tunnel table to storage...
[2024-09-16 20:15:22] [Debug] Saved 0 tunnel table entries in 0.11ms
[2024-09-16 20:15:22] [Debug] Saving 103 known destinations to storage...
[2024-09-16 20:15:22] [Debug] Saved known destinations to storage in 1.66ms

A third time:

[2024-09-16 20:16:03] [Debug] Started shared instance interface: Shared Instance[37428]
[2024-09-16 20:16:03] [Debug] Cleaning ratchets...
[2024-09-16 20:16:03] [Extra] Cleaning resource and packet caches...
[2024-09-16 20:16:03] [Verbose] Bringing up system interfaces...
[2024-09-16 20:16:03] [Debug] Skipping disabled interface "Default Interface"
[2024-09-16 20:16:03] [Debug] Skipping disabled interface "UDP Interface"
[2024-09-16 20:16:03] [Debug] Skipping disabled interface "TCP Server Interface"
[2024-09-16 20:16:03] [Debug] Skipping disabled interface "TCP Client Interface"
[2024-09-16 20:16:03] [Debug] Skipping disabled interface "I2P"
[2024-09-16 20:16:03] [Debug] Skipping disabled interface "RNode LoRa Interface"
[2024-09-16 20:16:03] [Debug] Skipping disabled interface "Packet Radio KISS Interface"
[2024-09-16 20:16:03] [Debug] Skipping disabled interface "Packet Radio AX.25 KISS Interface"
[2024-09-16 20:16:03] [Notice] Opening serial port /dev/ttyACM0...
[2024-09-16 20:16:05] [Notice] Serial port /dev/ttyACM0 is now open
[2024-09-16 20:16:05] [Verbose] Configuring RNode interface...
[2024-09-16 20:16:05] [Verbose] Waiting for radio configuration validation for RNodeInterface[lora rnode1]...
[2024-09-16 20:16:05] [Debug] RNodeInterface[lora rnode1] Radio reporting frequency is 0.0 MHz
[2024-09-16 20:16:05] [Debug] RNodeInterface[lora rnode1] Radio reporting bandwidth is 7.8 KHz
[2024-09-16 20:16:05] [Debug] RNodeInterface[lora rnode1] Radio reporting symbol time is 2.05ms (at 488 baud)
[2024-09-16 20:16:05] [Debug] RNodeInterface[lora rnode1] Radio reporting preamble is 22 symbols (45ms)
[2024-09-16 20:16:05] [Debug] RNodeInterface[lora rnode1] Radio reporting CSMA slot time is 50ms
[2024-09-16 20:16:05] [Debug] RNodeInterface[lora rnode1] Radio reporting TX power is 0 dBm
[2024-09-16 20:16:05] [Debug] RNodeInterface[lora rnode1] Radio reporting spreading factor is 8
[2024-09-16 20:16:05] [Debug] RNodeInterface[lora rnode1] Radio reporting coding rate is 7
[2024-09-16 20:16:05] [Verbose] RNodeInterface[lora rnode1] On-air bitrate is now 0.14 kbps
[2024-09-16 20:16:05] [Debug] RNodeInterface[lora rnode1] Radio reporting state is offline
[2024-09-16 20:16:06] [Error] Frequency mismatch
[2024-09-16 20:16:06] [Error] Bandwidth mismatch
[2024-09-16 20:16:06] [Error] TX power mismatch
[2024-09-16 20:16:06] [Error] Radio state mismatch
[2024-09-16 20:16:06] [Error] After configuring RNodeInterface[lora rnode1], the reported radio parameters did not match your configuration.
[2024-09-16 20:16:06] [Error] Make sure that your hardware actually supports the parameters specified in the configuration
[2024-09-16 20:16:06] [Error] Aborting RNode startup
[2024-09-16 20:16:06] [Error] A serial port error occurred, the contained exception was: [Errno 9] Bad file descriptor
[2024-09-16 20:16:06] [Error] The interface RNodeInterface[lora rnode1] experienced an unrecoverable error and is now offline.
[2024-09-16 20:16:06] [Error] Reticulum will attempt to reconnect the interface periodically.
[2024-09-16 20:16:06] [Debug] Skipping disabled interface "RNS Testnet Amsterdam"
[2024-09-16 20:16:06] [Verbose] System interfaces are ready
[2024-09-16 20:16:06] [Verbose] Configuration loaded from /home/user/.reticulum/config
[2024-09-16 20:16:06] [Verbose] Loaded 103 known destination from storage
[2024-09-16 20:16:06] [Verbose] Loaded Transport Identity from storage
[2024-09-16 20:16:06] [Notice] Started rnsd version 0.7.7
^C[2024-09-16 20:16:08] [Error] An error occurred while detaching RNodeInterface[lora rnode1]. The contained exception was: Attempting to use a port that is not open

[2024-09-16 20:16:08] [Debug] Saved packet hashlist in 0.2ms
[2024-09-16 20:16:08] [Debug] Saving path table to storage...
[2024-09-16 20:16:08] [Debug] Saved 0 path table entries in 0.07ms
[2024-09-16 20:16:08] [Debug] Saving tunnel table to storage...
[2024-09-16 20:16:08] [Debug] Saved 0 tunnel table entries in 0.05ms
[2024-09-16 20:16:08] [Debug] Saving 103 known destinations to storage...
[2024-09-16 20:16:08] [Debug] Saved known destinations to storage in 2.37ms

@jacobeva
Copy link

Can you please try this again now? Sorry for taking so long :)

@FountainOfInk
Copy link
Author

Aha, no worries. I tried it again, and the same issue arises, in the same way. Additionally, the display graphics seem to be corrupted now (particularly the version number and the top of the screen immediately after powering on the device.) I will probably record a video of this and create a new issue for it later.

@jacobeva
Copy link

That's interesting. I think I've seen the version number bug you're on about, I'll investigate that. Does the TX power set correctly, or does this not get set correctly when powering up also?

@FountainOfInk
Copy link
Author

The TX power follows the same pattern as it did before. Everything seems to be the same as before the commit.

@jacobeva
Copy link

Okay, that's interesting. Thanks.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

3 participants