diff --git a/src/Dispatcher.cpp b/src/Dispatcher.cpp index 83ebf855..f0948f01 100644 --- a/src/Dispatcher.cpp +++ b/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(); } } } diff --git a/src/Dispatcher.h b/src/Dispatcher.h index b0ac0113..4228e063 100644 --- a/src/Dispatcher.h +++ b/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; diff --git a/src/helpers/radiolib/CustomLR1110.h b/src/helpers/radiolib/CustomLR1110.h index 63eac72e..191bc884 100644 --- a/src/helpers/radiolib/CustomLR1110.h +++ b/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; diff --git a/src/helpers/radiolib/CustomLR1110Wrapper.h b/src/helpers/radiolib/CustomLR1110Wrapper.h index 67e2cf96..3b6c47e5 100644 --- a/src/helpers/radiolib/CustomLR1110Wrapper.h +++ b/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(); } diff --git a/test/test_packet_manager/test_rx_reserve_packet_manager.cpp b/test/test_packet_manager/test_rx_reserve_packet_manager.cpp index 491690fa..1a2086a9 100644 --- a/test/test_packet_manager/test_rx_reserve_packet_manager.cpp +++ b/test/test_packet_manager/test_rx_reserve_packet_manager.cpp @@ -20,6 +20,11 @@ public: bool cad_enabled = false; unsigned long last_irq = 0; bool recovery_result = true; + bool send_complete = false; + bool start_success = true; + int send_finishes = 0; + uint8_t sent_raw[3][MAX_TRANS_UNIT] = {}; + int sent_len[3] = {}; int recvRaw(uint8_t* dest, int max_len) override { if (pending_rx_len == 0) return 0; @@ -30,9 +35,16 @@ public: } uint32_t getEstAirtimeFor(int) override { return 1; } float packetScore(float, int) override { return 0; } - bool startSendRaw(const uint8_t*, int) override { send_starts++; return true; } - bool isSendComplete() override { return false; } - void onSendFinished() override { } + bool startSendRaw(const uint8_t* bytes, int len) override { + if (send_starts < 3) { + sent_len[send_starts] = len; + memcpy(sent_raw[send_starts], bytes, len); + } + send_starts++; + return start_success; + } + bool isSendComplete() override { return send_complete; } + void onSendFinished() override { send_finishes++; } bool isInRecvMode() const override { return in_recv_mode; } bool isReceiving() override { return receiving; } void setCADEnabled(bool enable) override { @@ -81,9 +93,15 @@ protected: failed_packet = packet; free_count_during_failure = manager.getFreeCount(); } + void onSendComplete(mesh::Packet* packet) override { + completed_packet = packet; + completed_packets++; + } public: mesh::Packet* failed_packet = nullptr; + mesh::Packet* completed_packet = nullptr; + int completed_packets = 0; int free_count_during_failure = -1; int received_packets = 0; int forced_rx_delay = -1; @@ -591,6 +609,135 @@ TEST(Dispatcher, RadioOutsideReceiveModeEscalatesOnSecondAttempt) { EXPECT_EQ(1, radio.hard_recoveries); } +TEST(Dispatcher, TimedOutTransmitRecoversAndRetriesSamePacket) { + RxReservePacketManager manager(8, 4); + TestClock clock; + clock.now = 100; + TestRadio radio; + TestDispatcher dispatcher(radio, clock, manager); + dispatcher.begin(); + + mesh::Packet* packet = dispatcher.obtainNewPacket(); + ASSERT_NE(packet, nullptr); + packet->header = ROUTE_TYPE_DIRECT | (PAYLOAD_TYPE_RAW_CUSTOM << PH_TYPE_SHIFT); + packet->payload[0] = 0x42; + packet->payload_len = 1; + ASSERT_TRUE(dispatcher.sendPacket(packet, 0)); + + clock.now = 101; + dispatcher.loop(); + ASSERT_EQ(1, radio.send_starts); + ASSERT_EQ(0, radio.hard_recoveries); + + clock.now = 103; + dispatcher.loop(); + + EXPECT_EQ(1, radio.send_finishes); + EXPECT_EQ(1, radio.hard_recoveries); + EXPECT_EQ(nullptr, dispatcher.failed_packet); + EXPECT_EQ(7, manager.getFreeCount()); + EXPECT_TRUE(dispatcher.getErrFlags() & ERR_EVENT_RADIO_WATCHDOG); + + uint32_t wake_delay = 0; + ASSERT_TRUE(dispatcher.nextQueueWakeDelay(wake_delay)); + EXPECT_EQ(200U, wake_delay); + + clock.now = 304; + dispatcher.loop(); + ASSERT_EQ(2, radio.send_starts); + ASSERT_EQ(radio.sent_len[0], radio.sent_len[1]); + EXPECT_EQ(0, memcmp(radio.sent_raw[0], radio.sent_raw[1], radio.sent_len[0])); + + radio.send_complete = true; + clock.now = 305; + dispatcher.loop(); + + EXPECT_EQ(2, radio.send_finishes); + EXPECT_EQ(packet, dispatcher.completed_packet); + EXPECT_EQ(1, dispatcher.completed_packets); + EXPECT_EQ(nullptr, dispatcher.failed_packet); + EXPECT_EQ(8, manager.getFreeCount()); +} + +TEST(Dispatcher, SecondTimedOutTransmitFailsWithoutThirdAttempt) { + RxReservePacketManager manager(8, 4); + TestClock clock; + clock.now = 100; + TestRadio radio; + TestDispatcher dispatcher(radio, clock, manager); + dispatcher.begin(); + + mesh::Packet* packet = dispatcher.obtainNewPacket(); + ASSERT_NE(packet, nullptr); + packet->header = ROUTE_TYPE_DIRECT | (PAYLOAD_TYPE_RAW_CUSTOM << PH_TYPE_SHIFT); + packet->payload[0] = 0x43; + packet->payload_len = 1; + ASSERT_TRUE(dispatcher.sendPacket(packet, 0)); + + clock.now = 101; + dispatcher.loop(); + ASSERT_EQ(1, radio.send_starts); + + clock.now = 103; + dispatcher.loop(); + ASSERT_EQ(1, radio.hard_recoveries); + + clock.now = 304; + dispatcher.loop(); + ASSERT_EQ(2, radio.send_starts); + + clock.now = 306; + dispatcher.loop(); + + EXPECT_EQ(2, radio.send_finishes); + EXPECT_EQ(2, radio.hard_recoveries); + EXPECT_EQ(packet, dispatcher.failed_packet); + EXPECT_EQ(8, manager.getFreeCount()); + + clock.now = 1000; + dispatcher.loop(); + EXPECT_EQ(2, radio.send_starts); +} + +TEST(Dispatcher, StartFailureRetriesSamePacketWithoutApp) { + RxReservePacketManager manager(8, 4); + TestClock clock; + clock.now = 100; + TestRadio radio; + radio.start_success = false; + TestDispatcher dispatcher(radio, clock, manager); + dispatcher.begin(); + + mesh::Packet* packet = dispatcher.obtainNewPacket(); + ASSERT_NE(packet, nullptr); + packet->header = ROUTE_TYPE_DIRECT | (PAYLOAD_TYPE_RAW_CUSTOM << PH_TYPE_SHIFT); + packet->payload[0] = 0x44; + packet->payload_len = 1; + ASSERT_TRUE(dispatcher.sendPacket(packet, 0)); + + clock.now = 101; + dispatcher.loop(); + ASSERT_EQ(1, radio.send_starts); + EXPECT_EQ(nullptr, dispatcher.failed_packet); + EXPECT_EQ(7, manager.getFreeCount()); + + radio.start_success = true; + clock.now = 302; + dispatcher.loop(); + ASSERT_EQ(2, radio.send_starts); + ASSERT_EQ(radio.sent_len[0], radio.sent_len[1]); + EXPECT_EQ(0, memcmp(radio.sent_raw[0], radio.sent_raw[1], radio.sent_len[0])); + + radio.send_complete = true; + clock.now = 303; + dispatcher.loop(); + + EXPECT_EQ(packet, dispatcher.completed_packet); + EXPECT_EQ(1, dispatcher.completed_packets); + EXPECT_EQ(nullptr, dispatcher.failed_packet); + EXPECT_EQ(8, manager.getFreeCount()); +} + TEST(RxReservePacketManager, RejectedOutboundRemainsOwnedByCaller) { RxReservePacketManager manager(8, 4); mesh::Packet* held[6]; diff --git a/variants/t1000-e/target.cpp b/variants/t1000-e/target.cpp index b325c26a..0e1b33dc 100644 --- a/variants/t1000-e/target.cpp +++ b/variants/t1000-e/target.cpp @@ -71,6 +71,10 @@ bool radio_init() { radio.setRxBoostedGainMode(RX_BOOSTED_GAIN); #endif + // Reuse this board-specific reset and configuration sequence if a runtime + // TX failure requires hard LR1110 recovery. + radio_driver.setDeepInitCallback(radio_init); + return true; // success }