Fix LR11x0 and LR2021 packet loss when a stale SPI reply is read as the length

[fkallay1]

Type: bug

Symptom

On an LR2021 repeater, the raw receive log occasionally reported a length of 4 for
frames that were 38, 50, 126 or 133 bytes long - always exactly 4, regardless of the
real length. The frames were then rejected as corrupt and never reached the mesh
layer. A second repeater on the same channel, an SX1262 board, logged the same frames
with correct lengths at the same moment, so it was not an RF problem.

It came in bursts. When several repeaters re-flood the same packet at once and the
chip is busy, roughly a third of the frames were lost this way. In quiet periods it
did not happen for hours.

The loss is silent: readData() returns success, so it is not counted as a receive
error, only as a frame that was received and then thrown away.

Cause

On the LR11x0 and LR2021 families a read command is two SPI transactions
(LRxxxx::SPIcommand()): send the opcode, then read the reply.
Module::SPItransferStream() waits delayMicroseconds(1) after the first
transaction and then polls BUSY for a low level - so if BUSY has not risen within
that microsecond, the wait is skipped and the reply is read before the chip has
prepared it.

The chip then sends its default [stat 2B][irq 4B] stream, and the length is parsed
straight out of that. The status byte is valid, so nothing reports an error.

On LR2021 the length is built from two bytes, so getRxPktLength() returns
irq[31:16]. With RX_DONE (bit 18) set that is exactly 4 - the observed value. With
TX_DONE or CRC_ERROR also set it becomes 12 or 68, which is plausible enough to pass
as a real length and produce a garbage packet instead of an obviously short one.

On LR11x0 the length is a single byte, so getRxBufferStatus() returns irq[31:24],
and every RX-relevant flag of that family lives in the two low bytes - so the length
comes back as 0. recvRaw() skips the packet on its len > 0 test, and the frame
is dropped when Rx is re-armed. No log line, no error counter, nothing but a gap in
the isr versus recv counts.

getIrqStatus() cannot be caught by this race, because it is that default stream.
That also makes the top bytes of the IRQ word an exact fingerprint of a stale reply,
which is what the fix uses.

Fix

The chip already says whether a reply is on its way: the command status field of stat1
is CMD_DAT ("successfully processed, data is being transmitted") for the read half of
a get, and CMD_OK ("nothing to collect") when the status stream comes back instead.
RadioLib consumes that byte internally and only rejects CMD_FAIL and CMD_PERR, so
the distinction is lost. Reading the length here directly keeps the status byte visible

• the same trick LRxxxx::getIrqStatus uses to read the IRQ word - and the length is
  trusted only when the status says the reply is ours. The Rx FIFO is still intact at that
  point, so re-reading recovers the frame; if it never settles, the plain library read is
  used so this can never end up worse.

Keeping the status byte is the only part that needs care. Setting the status width to 0
tells the transfer layer there is nothing to strip, so the whole reply lands in our own
buffer:

mod->SPIwriteStream(RADIOLIB_LR2021_CMD_GET_RX_PKT_LENGTH, NULL, 0, wait, false);
mod->spiConfig.widths[RADIOLIB_MODULE_SPI_WIDTH_STATUS] = Module::BITS_0;
mod->spiConfig.widths[RADIOLIB_MODULE_SPI_WIDTH_CMD]    = Module::BITS_0;
mod->SPIreadStream(RADIOLIB_LRXXXX_CMD_NOP, buff, sizeof(buff), wait, false);
// buff[0..1] = status word, buff[2..3] = the length

The guard itself is then just the status test:

size_t getPacketLength(bool update = true) override {
  uint8_t  stat = 0;
  uint16_t val  = 0;
  for (int i = 0; i < 3; i++) {
    readRxPktLenWithStatus(true, &stat, &val);
    if ((stat & 0x0E) == RADIOLIB_LRXXXX_STAT_1_CMD_DAT) return val;
  }
  return LR2021::getPacketLength(update);   // never worse than the plain read
}

An earlier version of this compared the returned length against irq[31:16] instead,
which needs no status byte. That turned out to misfire: 68 is both a common frame length
here and what irq[31:16] reads when RX_DONE and CRC_ERROR are set together, so it
flagged genuine frames. The status reported CMD_DAT on exactly those, which is why it
decides now.

On LR11x0 the same check applies, for the same reason. The first version of this used
len == 0 && RX_DONE there instead, on the assumption that a zero length is unambiguous
on that family. Hardware says otherwise: on a T1000-E that state occurs 25 times in three
minutes, roughly one per two and a half received frames, and re-reading recovers nothing
in any of them - 0 out of 25. So the zero is usually honest, and only the status can tell
it apart from a stale reply. The existing len == 0 && HEADER_ERR handling is left
untouched.

Both overrides use only public API and protected members of the base class, so no
RADIOLIB_GODMODE is needed.

What this does not cover

This guards the path through recvRaw(). LR11x0::readData() reads the length and
the buffer offset again through the two-argument
getPacketLength(bool update, uint8_t* offset), which is not virtual and therefore
cannot be intercepted from a subclass. If the race is lost there, the payload comes
out empty, or shifted by a bogus offset - which may well be the "packets shifted"
symptom the existing comment in CustomLR1110::getPacketLength() refers to.

The same race also affects every other read on these chips - getRSSI(), getSNR(),
getRssiInst(), getVbat(), getTemp() - so a wrong RSSI or SNR can reach
packetScore() without any indication. Those cannot be guarded from here either,
because a wrong RSSI has no fingerprint to test against. A proper fix belongs in the
driver's transport layer.

That part has been reported to RadioLib as an issue
(jgromes/RadioLib#1857), with the reproduction and the
measurements above - not as a patch, since where the check belongs is a decision about
the transport layer of the whole LR11x0/LR2021 family. If the driver starts rejecting a
reply whose status is not CMD_DAT, every get command is covered at once and this guard
becomes redundant. It would still be harmless - our own read never goes through
SPIcommand() - so it can simply be dropped then, though not before the pinned RadioLib
is bumped: the pin currently sits on a commit that predates any such fix, so a driver-side
fix changes nothing here until then. Until that happens this guard is what actually keeps
the frames.

Affected boards

LR2021: meshtracker_x1, meshnology_w12.

LR11x0: t1000-e, wio_wm1110, thinknode_m3, thinknode_m7, thinknode_m9,
minewsemi_me25ls01.

Testing

LR2021 on hardware: Seeed XIAO nRF52840 with a NiceRF LoRa2021 module, 869.618 MHz,
SF7, BW 62.5, in a live mesh with several repeaters, against a second receiver (SX1262)
on the same channel as a reference.

The failure is a timing race, so rather than wait for it, it was forced: a debug build
skips the BUSY wait on every fourth length read, in the real receive path.

• 11 of 11 sabotaged reads returned exactly 4 - the original symptom - and every one of
  them reported CMD_OK.
• The re-read returned the true length every time (63, 65, 67, 73, ...).
• Over the same window the node logged the same frames as the reference receiver, with
  no bogus lengths and no receive errors, although a quarter of its length reads had
  been broken on purpose.
• On genuine frames whose length happened to equal irq[31:16], the status reported
  CMD_DAT and the guard correctly stayed out of the way.

LR11x0 verified on hardware as well, on a Seeed T1000-E on the same channel, the same
way - the BUSY wait skipped on every fourth length read:

• 4 of 4 sabotaged reads came back as 0 and reported CMD_OK; the re-read returned the
  true length each time, recovering 84, 20 and 196 byte frames.
• Genuine reads reporting a length of 0 - 25 of them in three minutes, with the IRQ word
  at 0x38, 0x78 (header error) or 0xB8 (CRC error) - all reported CMD_DAT, and a probe
  doing three extra reads on each recovered nothing. That is what ruled out the
  value-based rule for this family.

Builds clean: t1000e_repeater, wio_wm1110_repeater, MeshTracker_X1_repeater.

[fkallay1]

Updated after testing this on an LR11x0 board as well, and it changed the LR11x0 half of
the patch - worth flagging rather than leaving it in the force-push.

The first version guarded LR11x0 with len == 0 && RX_DONE, on the assumption that a
zero length cannot be genuine there, so no status byte was needed. That assumption does
not hold. On a T1000-E that state occurs 25 times in three minutes, roughly one per two
and a half received frames, with the IRQ word reading 0x38, 0x78 (header error) or 0xB8
(CRC error). A probe doing three extra reads on each of them recovered nothing, 0 out of
25 - so the zero is usually honest, and the old rule would have burned three SPI reads
every time without saving a frame.

Both chips now use the same check, and it holds on both: with the BUSY wait skipped on
purpose, 4 of 4 sabotaged reads on the T1000-E came back as 0 reporting CMD_OK and the
retry recovered 84, 20 and 196 byte frames, while the genuine zeros above all reported
CMD_DAT. Same shape as the 11 of 11 measured on LR2021.

t1000e_repeater and MeshTracker_X1_repeater build clean.

[oltaco]

Nice work, have you opened an issue/PR at RadioLib?

edit: I see you've already brought it to @jgromes attention (jgromes/RadioLib#1857) and it looks like a fix is already in the works upstream (jgromes/RadioLib#1858).

It's probably best to just wait for a fix to land upstream in RadioLib rather than papering over the issue down here. I guess it applies to more than just this command anyway.

[fkallay1]

Yes — jgromes/RadioLib#1857. The description mentioned it only in words, which was not much use; I have put the link in there as well.

jgromes agreed and put the cause more sharply than I had: the read transaction does not wait for BUSY between sending the opcode and reading the reply, which the LR1110 datasheet requires. He has pushed a candidate fix to the 1857-lrxxxx-read-busy branch and asked me to verify it on hardware without the SPI sabotage the measurements used. I will report back there once it has run in a live mesh.

What that means for this PR is in the description already: the proper fix belongs in the driver's transport layer, and once it lands this guard becomes redundant and can be dropped — but not before the pinned RadioLib commit is moved past it, and the pin currently sits on 11 July.