Recover and retry stalled LR1110 transmissions

src/Dispatcher.cpp

@@ -39,6 +39,9 @@ void Dispatcher::begin() {
   n_sent_flood = n_sent_direct = 0;
   n_recv_flood = n_recv_direct = 0;
   _err_flags = 0;
+  outbound_radio_retry_at = 0;
+  outbound_radio_retry_pending = false;
+  outbound_radio_retry_used = false;
   radio_nonrx_start = _ms->getMillis();
 
   duty_cycle_window_ms = getDutyCycleWindowMs();
@@ -90,6 +93,91 @@ void Dispatcher::restoreOutboundTxOverrides() {
   }
 }
 
+bool Dispatcher::startOutboundTransmit() {
+  if (outbound == NULL) return false;
+
+  int len = 0;
+  uint8_t raw[MAX_TRANS_UNIT];
+
+  raw[len++] = outbound->header;
+  if (outbound->hasTransportCodes()) {
+    memcpy(&raw[len], &outbound->transport_codes[0], 2); len += 2;
+    memcpy(&raw[len], &outbound->transport_codes[1], 2); len += 2;
+  }
+  raw[len++] = outbound->path_len;
+  len += Packet::writePath(&raw[len], outbound->path, outbound->path_len);
+
+  if (len + outbound->payload_len > MAX_TRANS_UNIT) {
+    MESH_DEBUG_PRINTLN("%s Dispatcher::startOutboundTransmit(): FATAL: Invalid packet queued... too long, len=%d",
+                       getLogDateTime(), len + outbound->payload_len);
+    return false;
+  }
+  memcpy(&raw[len], outbound->payload, outbound->payload_len);
+  len += outbound->payload_len;
+
+  uint32_t max_airtime = _radio->getEstAirtimeFor(len) * 3 / 2;
+  outbound_restore_cr = 0;
+  outbound_restore_preamble_len = 0;
+  uint8_t default_cr = getDefaultTxCodingRate();
+  bool is_retry = outbound->tx_cr >= 4 && outbound->tx_cr <= 8;
+  if (outbound->tx_cr >= 4 && outbound->tx_cr <= 8
+      && default_cr >= 4 && default_cr <= 8
+      && outbound->tx_cr != default_cr) {
+    if (_radio->setCodingRate(outbound->tx_cr)) {
+      outbound_restore_cr = default_cr;
+      max_airtime = _radio->getEstAirtimeFor(len) * 3 / 2;
+    } else {
+      MESH_DEBUG_PRINTLN("%s Dispatcher::startOutboundTransmit(): WARN: failed to set packet CR%d",
+                         getLogDateTime(), (uint32_t)outbound->tx_cr);
+    }
+  }
+  if (is_retry) {
+    uint16_t default_preamble_len = _radio->getDefaultPreambleLength();
+    if (default_preamble_len != 32 && _radio->setPreambleLength(32)) {
+      outbound_restore_preamble_len = default_preamble_len;
+      max_airtime = _radio->getEstAirtimeFor(len) * 3 / 2;
+    }
+  }
+
+  outbound_start = _ms->getMillis();
+  if (!_radio->startSendRaw(raw, len)) {
+    MESH_DEBUG_PRINTLN("%s Dispatcher::startOutboundTransmit(): ERROR: send start failed!",
+                       getLogDateTime());
+    restoreOutboundTxOverrides();
+    return false;
+  }
+  outbound_expiry = futureMillis(max_airtime);
+
+#if MESH_PACKET_LOGGING
+  logPacketStart("TX", outbound, len);
+  logPacketEnd(outbound);
+#endif
+  return true;
+}
+
+bool Dispatcher::scheduleOutboundRadioRetry() {
+  if (outbound == NULL || outbound_radio_retry_used) return false;
+
+  outbound_radio_retry_used = true;
+  outbound_radio_retry_pending = true;
+  outbound_radio_retry_at = futureMillis(getCADFailRetryDelay());
+  MESH_DEBUG_PRINTLN("%s Dispatcher: retrying packet once after radio fault",
+                     getLogDateTime());
+  return true;
+}
+
+void Dispatcher::failOutboundTransmit() {
+  if (outbound == NULL) return;
+
+  restoreOutboundTxOverrides();
+  logTxFail(outbound, outbound->getRawLength());
+  onSendFail(outbound);
+  releasePacket(outbound);
+  outbound = NULL;
+  outbound_radio_retry_pending = false;
+  outbound_radio_retry_used = false;
+}
+
 int Dispatcher::calcRxDelay(float score, uint32_t air_time) const {
   return (int) ((powf(10.0f, 0.85f - score) - 1.0f) * air_time);
 }
@@ -137,8 +225,13 @@ bool Dispatcher::getNextQueueWakeDelay(uint32_t& delay_millis) const {
   uint32_t shortest_delay = 0;
 
   if (outbound != NULL) {
-    // TX completion/timeout still needs the normal fast lifecycle path.
-    delay_millis = 0;
+    if (outbound_radio_retry_pending) {
+      int32_t signed_retry_delay = (int32_t)(outbound_radio_retry_at - now);
+      delay_millis = signed_retry_delay > 0 ? (uint32_t)signed_retry_delay : 0;
+    } else {
+      // TX completion/timeout still needs the normal fast lifecycle path.
+      delay_millis = 0;
+    }
     return true;
   }
 
@@ -266,8 +359,21 @@ void Dispatcher::loop() {
 #endif
   }
 
-  if (outbound) {  // waiting for outbound send to be completed
-    if (_radio->isSendComplete()) {
+  if (outbound) {  // waiting for outbound send to complete, or for its one radio retry
+    if (outbound_radio_retry_pending) {
+      if (!millisHasNowPassed(outbound_radio_retry_at)) return;
+
+      outbound_radio_retry_pending = false;
+      if (!allowPacketTransmit(outbound)) {
+        MESH_DEBUG_PRINTLN("%s Dispatcher::loop(): radio retry packet no longer allowed, type=%u",
+                           getLogDateTime(), (uint32_t)outbound->getPayloadType());
+        failOutboundTransmit();
+      } else if (!startOutboundTransmit()) {
+        failOutboundTransmit();
+      } else {
+        return;
+      }
+    } else if (_radio->isSendComplete()) {
       long t = _ms->getMillis() - outbound_start;
       total_air_time += t;
       //Serial.print("  airtime="); Serial.println(t);
@@ -304,16 +410,21 @@ void Dispatcher::loop() {
       }
       releasePacket(outbound);  // return to pool
       outbound = NULL;
+      outbound_radio_retry_pending = false;
+      outbound_radio_retry_used = false;
     } else if (millisHasNowPassed(outbound_expiry)) {
       MESH_DEBUG_PRINTLN("%s Dispatcher::loop(): WARNING: outbound packed send timed out!", getLogDateTime());
 
       _radio->onSendFinished();
       restoreOutboundTxOverrides();
-      logTxFail(outbound, 2 + outbound->getPathByteLen() + outbound->payload_len);
-      onSendFail(outbound);
-
-      releasePacket(outbound);  // return to pool
-      outbound = NULL;
+      _err_flags |= ERR_EVENT_RADIO_WATCHDOG;
+      const bool recovered = _radio->recoverRadio(true);
+      if (!recovered) {
+        MESH_DEBUG_PRINTLN("%s Dispatcher::loop(): WARNING: hard radio recovery after TX timeout failed!",
+                           getLogDateTime());
+      }
+      if (recovered && scheduleOutboundRadioRetry()) return;
+      failOutboundTransmit();
     } else {
       return;  // can't do any more radio activity until send is complete or timed out
     }
@@ -558,74 +669,29 @@ void Dispatcher::checkSend() {
 
   outbound = _mgr->getNextOutbound(_ms->getMillis());
   if (outbound) {
+    outbound_radio_retry_pending = false;
+    outbound_radio_retry_used = false;
+
     if (!allowPacketTransmit(outbound)) {
       MESH_DEBUG_PRINTLN("%s Dispatcher::checkSend(): packet no longer allowed, type=%u", getLogDateTime(),
                          (uint32_t)outbound->getPayloadType());
-      onSendFail(outbound);
-      releasePacket(outbound);
-      outbound = NULL;
+      failOutboundTransmit();
       return;
     }
 
-    int len = 0;
-    uint8_t raw[MAX_TRANS_UNIT];
-
-    raw[len++] = outbound->header;
-    if (outbound->hasTransportCodes()) {
-      memcpy(&raw[len], &outbound->transport_codes[0], 2); len += 2;
-      memcpy(&raw[len], &outbound->transport_codes[1], 2); len += 2;
+    if (outbound->getRawLength() > MAX_TRANS_UNIT) {
+      MESH_DEBUG_PRINTLN("%s Dispatcher::checkSend(): FATAL: Invalid packet queued... too long, len=%d",
+                         getLogDateTime(), outbound->getRawLength());
+      failOutboundTransmit();
+      return;
     }
-    raw[len++] = outbound->path_len;
-    len += Packet::writePath(&raw[len], outbound->path, outbound->path_len);
 
-    if (len + outbound->payload_len > MAX_TRANS_UNIT) {
-      MESH_DEBUG_PRINTLN("%s Dispatcher::checkSend(): FATAL: Invalid packet queued... too long, len=%d", getLogDateTime(), len + outbound->payload_len);
-      onSendFail(outbound);
-      releasePacket(outbound);
-      outbound = NULL;
-    } else {
-      memcpy(&raw[len], outbound->payload, outbound->payload_len); len += outbound->payload_len;
-
-      uint32_t max_airtime = _radio->getEstAirtimeFor(len)*3/2;
-      outbound_restore_cr = 0;
-      outbound_restore_preamble_len = 0;
-      uint8_t default_cr = getDefaultTxCodingRate();
-      bool is_retry = outbound->tx_cr >= 4 && outbound->tx_cr <= 8;
-      if (outbound->tx_cr >= 4 && outbound->tx_cr <= 8 && default_cr >= 4 && default_cr <= 8
-          && outbound->tx_cr != default_cr) {
-        if (_radio->setCodingRate(outbound->tx_cr)) {
-          outbound_restore_cr = default_cr;
-          max_airtime = _radio->getEstAirtimeFor(len)*3/2;
-        } else {
-          MESH_DEBUG_PRINTLN("%s Dispatcher::checkSend(): WARN: failed to set packet CR%d", getLogDateTime(), (uint32_t)outbound->tx_cr);
-        }
-      }
-      if (is_retry) {
-        uint16_t default_preamble_len = _radio->getDefaultPreambleLength();
-        if (default_preamble_len != 32 && _radio->setPreambleLength(32)) {
-          outbound_restore_preamble_len = default_preamble_len;
-          max_airtime = _radio->getEstAirtimeFor(len)*3/2;
-        }
-      }
-      outbound_start = _ms->getMillis();
-      bool success = _radio->startSendRaw(raw, len);
-      if (!success) {
-        MESH_DEBUG_PRINTLN("%s Dispatcher::loop(): ERROR: send start failed!", getLogDateTime());
-
-        restoreOutboundTxOverrides();
-        logTxFail(outbound, outbound->getRawLength());
-        onSendFail(outbound);
-  
-        releasePacket(outbound);  // return to pool
-        outbound = NULL;
-        return;
-      }
-      outbound_expiry = futureMillis(max_airtime);
-
-    #if MESH_PACKET_LOGGING
-      logPacketStart("TX", outbound, len);
-      logPacketEnd(outbound);
-    #endif
+    if (!startOutboundTransmit()) {
+      // RadioLib performs its radio-specific cleanup (including LR1110 hard
+      // recovery for a stuck BUSY command) before returning false. Retain the
+      // packet and let the firmware make one fresh start without app help.
+      if (scheduleOutboundRadioRetry()) return;
+      failOutboundTransmit();
     }
   }
 }

src/Dispatcher.h

@@ -225,6 +225,7 @@ typedef uint32_t  DispatcherAction;
 class Dispatcher {
   Packet* outbound;  // current outbound packet
   unsigned long outbound_expiry, outbound_start, total_air_time, rx_air_time;
+  unsigned long outbound_radio_retry_at;
   unsigned long last_observed_radio_irq;
 #ifdef RADIO_LIVENESS_SOFT_ONLY
   unsigned long last_radio_activity_ms;
@@ -238,6 +239,8 @@ class Dispatcher {
   unsigned long radio_nonrx_start;
   unsigned long next_floor_calib_time, next_agc_reset_time;
   bool  prev_isrecv_mode;
+  bool  outbound_radio_retry_pending;
+  bool  outbound_radio_retry_used;
 #ifndef RADIO_LIVENESS_SOFT_ONLY
   bool  nonrx_soft_recovery_attempted;
 #endif
@@ -249,6 +252,9 @@ class Dispatcher {
 
   void processRecvPacket(Packet* pkt);
   void releaseDroppedOutbound();
+  bool startOutboundTransmit();
+  bool scheduleOutboundRadioRetry();
+  void failOutboundTransmit();
   void restoreOutboundTxOverrides();
   void updateTxBudget();
 
@@ -262,6 +268,9 @@ protected:
     : _radio(&radio), _ms(&ms), _mgr(&mgr)
   {
     outbound = NULL;
+    outbound_radio_retry_at = 0;
+    outbound_radio_retry_pending = false;
+    outbound_radio_retry_used = false;
     outbound_restore_preamble_len = 0;
     outbound_restore_cr = 0;
     total_air_time = rx_air_time = 0;

src/helpers/radiolib/CustomLR1110.h

@@ -4,6 +4,10 @@
 #include "MeshCore.h"
 #include "LR1110RxRecovery.h"
 
+#ifndef LR11X0_TX_BUSY_TIMEOUT_MS
+#define LR11X0_TX_BUSY_TIMEOUT_MS 1000UL
+#endif
+
 class CustomLR1110 : public LR1110 {
   uint32_t _preambleMillis = 66;
   uint32_t _maxPayloadMillis = 3934;
@@ -14,6 +18,34 @@ class CustomLR1110 : public LR1110 {
   public:
     CustomLR1110(Module *mod) : LR1110(mod) { }
 
+    // RadioLib waits without a deadline for BUSY to fall after SetTx. Bound
+    // that wait so a failed LR1110 transition can reach the wrapper's hard
+    // recovery path instead of hanging the firmware indefinitely.
+    int16_t launchMode() override {
+      if (this->stagedMode != RADIOLIB_RADIO_MODE_TX) {
+        return LR1110::launchMode();
+      }
+
+      this->mod->setRfSwitchState(this->txMode);
+      int16_t state = this->setTx(RADIOLIB_LR11X0_TX_TIMEOUT_NONE);
+      if (state != RADIOLIB_ERR_NONE) {
+        this->stagedMode = RADIOLIB_RADIO_MODE_NONE;
+        return state;
+      }
+
+      const uint32_t started = this->mod->hal->millis();
+      while (isChipBusy()) {
+        this->mod->hal->yield();
+        if (this->mod->hal->millis() - started >= LR11X0_TX_BUSY_TIMEOUT_MS) {
+          this->stagedMode = RADIOLIB_RADIO_MODE_NONE;
+          return RADIOLIB_ERR_SPI_CMD_TIMEOUT;
+        }
+      }
+
+      this->stagedMode = RADIOLIB_RADIO_MODE_NONE;
+      return RADIOLIB_ERR_NONE;
+    }
+
     int16_t recoverReceivePath() {
       _activityAt = 0;
       _headerSeen = false;

src/helpers/radiolib/CustomLR1110Wrapper.h

@@ -9,8 +9,14 @@
 #endif
 
 class CustomLR1110Wrapper : public RadioLibWrapper {
+  using DeepInitCallback = bool (*)();
+  DeepInitCallback _deep_init;
+
 public:
-  CustomLR1110Wrapper(CustomLR1110& radio, mesh::MainBoard& board) : RadioLibWrapper(radio, board) { }
+  CustomLR1110Wrapper(CustomLR1110& radio, mesh::MainBoard& board)
+      : RadioLibWrapper(radio, board), _deep_init(NULL) { }
+
+  void setDeepInitCallback(DeepInitCallback callback) { _deep_init = callback; }
 
   void powerOff() { _radio->standby(); _radio->sleep(); }
 
@@ -110,6 +116,11 @@ protected:
     return _radio->startReceive();
   }
 
+  bool radioDeepInit() override {
+    return _deep_init != NULL && _deep_init();
+  }
+  bool supportsRadioDeepInit() const override { return _deep_init != NULL; }
+
 public:
   uint8_t getSpreadingFactor() const override { return ((CustomLR1110 *)_radio)->getSpreadingFactor(); }