RFM95 throws -16 error on standby after an hour

[jp-bennett]

I have encountered the weirdest problems with a particular arrangement, in the Meshtastic code. We're using RadioLib 6.5.0, but I believe this issue happens with 6.4.0, too. I have an Adafruit LoRa Radio Bonnet, running the RFM95, on a Raspberry Pi 5. We use it with LoRa, and everything seems to work, for the first hour+. Then, at nearly the same amount of runtime each time, the hat throws a -16 when calling standby(). I have no idea why everything works for the first 4200 seconds. I've run the code with RadioLib Debug turned on. Looks like I also managed to catch a malformed packet, failing with error -7, which is a second issue I'm trying to track down when using these radios with native Linux. Anyway, any suggestions as to what's going on would be appreciated:

RLB_SPI: R      1       8D
RLB_SPI: R      1       8D
RLB_SPI: W      1       89
RLB_SPI: R      1       89
RLB_SPI: R      1       89
RLB_SPI: R      1       89
RLB_SPI: W      1       89
RLB_SPI: R      1       89
RLB_SPI: R      1       89
RLB_SPI: R      24      0
RLB_SPI: R      40      0
RLB_SPI: W      40      0
RLB_SPI: R      40      0
RLB_SPI: R      1       89
RLB_SPI: W      12      FF
RLB_SPI: R      F       0
RLB_SPI: W      F       0
RLB_SPI: R      F       0
RLB_SPI: R      D       29
RLB_SPI: W      D       0
RLB_SPI: R      D       0
RLB_SPI: R      1       89
RLB_SPI: R      1       89
RLB_SPI: W      1       8D
RLB_SPI: R      1       89
RLB_SPI: R      1       8D
DEBUG | 23:04:11 4237 [Router] Found existing packet record for fr=0x7c5cc314,to=0xffffffff,id=0xda1427f
DEBUG | 23:04:11 4237 [Router] Found existing packet record for fr=0x7c5cc314,to=0xffffffff,id=0xda1427f
DEBUG | 23:04:11 4237 [Router] Add packet record (id=0x0da1427f fr=0x14 to=0xff, WantAck=0, HopLim=1 Ch=0x8 encrypted rxSNR=10.25 rxRSSI=-59)
DEBUG | 23:04:11 4237 [Router] Ignoring incoming msg, because we've already seen it (id=0x0da1427f fr=0x14 to=0xff, WantAck=0, HopLim=1 Ch=0x8 encrypted rxSNR=10.25 rxRSSI=-59)
DEBUG | 23:04:11 4237 [Router] cancelSending id=0xda1427f, removed=1
DEBUG | 23:04:11 4237 [Router] Incoming message was filtered 0x7c5cc314
RLB_SPI: R      1       8D
RLB_SPI: R      13      42
DEBUG | 23:05:58 4345 [RadioIf] (bw=250, sf=11, cr=4/5) packet symLen=8 ms, payloadSize=66, time 722 ms
RLB_SPI: R      1       8D
RLB_SPI: R      1       8D
RLB_SPI: R      13      42
RLB_SPI: R      12      70
RLB_SPI: R      0       FF      FF      FF      FF      72      BA      2F      79      69      45      8B      6B  63       8       0       0       F2      D3      47      65      4C      AE      E9      4F      53      EB      51  48       A5      A8      48      85      7E      EF      23      E9      92      C8      75      AA      EF      CB  F9       4D      F7      A2      67      6A      5F      E9      D8      2D      B       27      C0      8A      71  CC       A6      9       B2      86      75      11      4F      3B
RLB_SPI: R      1       8D
RLB_SPI: W      12      FF
ERROR | 23:05:58 4345 [RadioIf] ignoring received packet due to error=-7
DEBUG | 23:05:58 4345 [RadioIf] AirTime - Packet received (noise?) : 722ms
RLB_SPI: R      1       8D
RLB_SPI: R      1       8D
RLB_SPI: W      1       89
RLB_SPI: 
RLB_SPI: address:       0x1
RLB_SPI: bits:          2 0
RLB_SPI: value:         0x1
RLB_SPI: current:       0x8D
RLB_SPI: mask:          0x7
RLB_SPI: new:           0x89
RLB_SPI: read:          0x0
ERROR | 23:05:58 4345 [RadioIf] Radiolib error -16 when attempting RF95 standby!
program: src/mesh/RF95Interface.cpp:175: virtual void RF95Interface::setStandby(): Assertion `err == RADIOLIB_ERR_NONE' failed.
Aborted

[jgromes]

Hmm, interesting. It looks like for the final read that caused the failed check, the value read from the SPI was 0x00. I'm wondering if the SPI got shut down for whatever reason? I happen to have an SX1276 connected via SPI on RPi 3, so I can try to replicate the problem. What are you using as the HAL?

[jp-bennett]

Our HAL is interesting. It's a derivative of the ArduoinoHal (https://github.com/meshtastic/firmware/blob/master/src/mesh/RadioLibInterface.h), then running through Portduino to make it run on the Pi. (https://github.com/meshtastic/framework-portduino/blob/master/cores/portduino/linux/LinuxHardwareSPI.cpp)

What's weird is that other hats don't have this behavior, and this model is doing this on a couple different Pis. I would call it bad hardware, but it's weird that it works for so long before falling off the bus. And it's reliably at about 4300 seconds. I believe flicking the reset line does get it working again.

And also weird but notable, my other hats, like the waveshare sx126x lorawan hat, is an sx1262, and will hapily run indefinitely. (Though these are triggering the -7 CRC error, mysteriously)

[jgromes]

then running through Portduino to make it run on the Pi

Seems unnecessarily complicated, see https://github.com/jgromes/RadioLib/blob/master/examples/NonArduino/Raspberry/PiHal.h - just a suggestion though ;)

I set up an SX1278 with my RPi and will leave it running for a bit, we'll see what happens.

And also weird but notable, my other hats, like the waveshare sx126x lorawan hat, is an sx1262, and will hapily run indefinitely.

The SX126x has a different SPI interface than the SX127x and should never throw the -16 error. But still seems to go against my original "SPI getting shut down" since that would be happening too, just with a different error.

[jp-bennett]

Seems unnecessarily complicated, see https://github.com/jgromes/RadioLib/blob/master/examples/NonArduino/Raspberry/PiHal.h - just a suggestion though ;)

When I first got Meshtastic working with real hardware on Native Linux, we used a custom HAL based on that code. The advantage of using the Portduino layer is that other libraries/hardware can use it. Though now that you mention it, trying out the more direct HAL might be a good sanity test.

[jgromes]

Unfortunately I was not able to replicate this issue, I had the Raspberry Pi example running for 2+ hours without any errors. The example jsut transmits, but standby does get requested during transmission. I guess I could set up meshtastic on my device, but right now I'm trying to focus on finishing up other things, e.g. the LR11x0 driver ;)

[ufsm-barriquello]

I had the same error. Strangely the log skipped output number 80 and tried to print output 81. Also it was just before "sending packet to mesh" instead of "sending packet to phone".

INFO | ???:??:?? 4367 getFromRadio=STATE_SEND_PACKETS
INFO | ???:??:?? 4425 [DeviceTelemetryModule] (Sending): air_util_tx=0.015444, channel_utilization=0.000000, battery_level=0, voltage=0.000000, uptime=4425
INFO | ???:??:?? 4425 [DeviceTelemetryModule] Sending packet to phone
INFO | ???:??:?? 4425 Telling client we have new packets 78
INFO | ???:??:?? 4427 getFromRadio=STATE_SEND_PACKETS
INFO | ???:??:?? 4485 [DeviceTelemetryModule] (Sending): air_util_tx=0.015444, channel_utilization=0.000000, battery_level=0, voltage=0.000000, uptime=4485
INFO | ???:??:?? 4485 [DeviceTelemetryModule] Sending packet to phone
INFO | ???:??:?? 4485 Telling client we have new packets 79
INFO | ???:??:?? 4487 getFromRadio=STATE_SEND_PACKETS
INFO | ???:??:?? 4545 [DeviceTelemetryModule] (Sending): air_util_tx=0.011583, channel_utilization=0.000000, battery_level=0, voltage=0.000000, uptime=4545
INFO | ???:??:?? 4545 [DeviceTelemetryModule] Sending packet to mesh
INFO | ???:??:?? 4545 Telling client we have new packets 81
ERROR | ???:??:?? 4545 [RadioIf] Radiolib error -16 when attempting RF95 standby!
program: src/mesh/RF95Interface.cpp:175: virtual void RF95Interface::setStandby(): Assertion `err == RADIOLIB_ERR_NONE' failed.
Aborted

[malaiwah]

I do experience the same issue with Meshtastic on Portduino as well -- it seems always around the same 70 minutes mark (4200 seconds). Raspberry 3, Debian, same Adafruit Hat.

Jun 06 10:36:01 meshpi meshtasticd[9017]: DEBUG | 09:36:00 4139 [Router] Module 'PowerTelemetry' considered
Jun 06 10:36:01 meshpi meshtasticd[9017]: DEBUG | 09:36:00 4139 [Router] Module 'routing' wantsPacket=1
Jun 06 10:36:01 meshpi meshtasticd[9017]: INFO  | 09:36:00 4139 [Router] Received routing from=0xe2e1d99c, id=0x4ca78bc8, portnum=67, payloadlen=19
Jun 06 10:36:01 meshpi meshtasticd[9017]: DEBUG | 09:36:00 4139 [Router] Routing sniffing (id=0x4ca78bc8 fr=0x9c to=0xff, WantAck=0, HopLim=4 Ch=0x0 Portnum=67 rxtime=1717666560 rxSNR=11.75 rxRSSI=-82 hopStart=4)
Jun 06 10:36:01 meshpi meshtasticd[9017]: INFO  | 09:36:00 4139 [Router] Rebroadcasting received floodmsg to neighbors
Jun 06 10:36:01 meshpi meshtasticd[9017]: DEBUG | 09:36:00 4139 [Router] Expanding short PSK #1
Jun 06 10:36:01 meshpi meshtasticd[9017]: DEBUG | 09:36:00 4139 [Router] Using AES128 key!
Jun 06 10:36:01 meshpi meshtasticd[9017]: DEBUG | 09:36:00 4139 [Router] Installing AES128 key!
Jun 06 10:39:37 meshpi meshtasticd[9017]: DEBUG | 09:36:00 4139 [Router] enqueuingmeshtasticd: src/mesh/RF95Interface.cpp:194: virtual void RF95Interface::setStandby(): Assertion `err == RADIOLIB_ERR_NONE' failed.
Jun 06 10:39:37 meshpi systemd[1]: meshtasticd.service: Main process exited, code=killed, status=6/ABRT
Jun 06 10:39:37 meshpi systemd[1]: meshtasticd.service: Failed with result 'signal'.
Jun 06 10:39:37 meshpi systemd[1]: meshtasticd.service: Consumed 32.926s CPU time.
Jun 06 10:39:42 meshpi systemd[1]: meshtasticd.service: Scheduled restart job, restart counter is at 17.
Jun 06 10:39:42 meshpi systemd[1]: Stopped meshtasticd.service - Meshtastic Native Daemon.
Jun 06 10:39:42 meshpi systemd[1]: meshtasticd.service: Consumed 32.926s CPU time.
Jun 06 10:39:42 meshpi systemd[1]: Started meshtasticd.service - Meshtastic Native Daemon.
Jun 06 10:39:42 meshpi meshtasticd[9115]: Portduino is starting, HWID=1, VFS root at /root/.portduino/default
Jun 06 10:39:42 meshpi meshtasticd[9115]: Setting up Meshtastic on Portduino...
Jun 06 10:39:42 meshpi meshtasticd[9115]: Using /etc/meshtasticd/config.yaml as config file
Jun 06 10:39:42 meshpi meshtasticd[9115]: INFO  | ??:??:?? 0
Jun 06 10:39:42 meshpi meshtasticd[9115]:
Jun 06 10:39:42 meshpi meshtasticd[9115]: //\ E S H T /\ S T / C
Jun 06 10:39:42 meshpi meshtasticd[9115]:

[...]

Jun 06 10:39:42 meshpi meshtasticd[9115]: INFO  | ??:??:?? 0 Meshtastic hwvendor=37, swver=2.3.11.2740a56

[...]

$ dpkg -l meshtasticd
Desired=Unknown/Install/Remove/Purge/Hold
| Status=Not/Inst/Conf-files/Unpacked/halF-conf/Half-inst/trig-aWait/Trig-pend
|/ Err?=(none)/Reinst-required (Status,Err: uppercase=bad)
||/ Name           Version        Architecture Description
+++-==============-==============-============-=================================
ii  meshtasticd    2.3.11.2740a56 arm64        Native Linux Meshtastic binary.

[...]

Jun 06 11:51:47 meshpi meshtasticd[9115]: INFO  | 10:51:16 4294 [Routermeshtasticd: src/mesh/RF95Interface.cpp:194: virtual void RF95Interface::setStandby(): Assertion `err == RADIOLIB_>
Jun 06 13:03:32 meshpi meshtasticd[9206]: DEBUG | 12:02:47meshtasticd: src/mesh/RF95Interface.cpp:194: virtual void RF95Interface::setStandby(): Assertion `err == RADIOLIB_ERR_NONE' fai>
Jun 06 14:16:29 meshpi meshtasticd[9313]: DEBUG | 13:14:28 4250 [Router] Module 'positimeshtasticd: src/mesh/RF95Interface.cpp:194: virtual void RF95Interface::setStandby(): Assertion `>

[malaiwah]

Looks like I also managed to catch a malformed packet, failing with error -7, which is a second issue I'm trying to track down when using these radios with native Linux.

Just so you know, I have the malformed packets (-7) as well from time to time.