diff --git a/docs/cli_commands.md b/docs/cli_commands.md index 66a9b77afe..c8a58da548 100644 --- a/docs/cli_commands.md +++ b/docs/cli_commands.md @@ -133,27 +133,80 @@ This document provides an overview of CLI commands that can be sent to MeshCore ### Clear Stats **Usage:** `clear stats` +Clears the node's runtime counters, including packet totals, radio counters, duplicate counters, error flags, and MAC/CAD diagnostic counters. It does not erase stored packet logs or change configuration. + --- ### System Stats - Battery, Uptime, Queue Length and Debug Flags **Usage:** - `stats-core` -**Serial Only:** Yes +**Serial Only:** No + +Returns JSON with: +- `battery_mv`: current board battery reading in millivolts +- `uptime_secs`: node uptime in seconds +- `errors`: dispatcher error bitmask +- `queue_len`: total queued outbound packets --- ### Radio Stats - Noise floor, Last RSSI/SNR, Airtime, Receive errors **Usage:** `stats-radio` -**Serial Only:** Yes +**Serial Only:** No + +Returns JSON with: +- `noise_floor`: current radio noise floor estimate in dBm +- `last_rssi`: RSSI from the most recent received packet +- `last_snr`: SNR from the most recent received packet +- `tx_air_secs`: accumulated transmit airtime in seconds +- `rx_air_secs`: accumulated receive airtime estimate in seconds --- ### Packet stats - Packet counters: Received, Sent **Usage:** `stats-packets` -**Serial Only:** Yes +**Serial Only:** No + +Returns JSON with: +- `recv` / `sent`: radio driver packet totals +- `flood_tx` / `direct_tx`: dispatcher transmit totals by route type +- `flood_rx` / `direct_rx`: dispatcher receive totals by route type +- `recv_errors`: radio driver receive error count + +--- + +### MAC CAD stats - CAD deferral and timeout counters +**Usage:** `stats-mac-cad` + +**Serial Only:** No + +Returns JSON with: +- `busy`: local radio/CAD busy deferrals before the timeout threshold +- `timeouts`: times local CAD busy state exceeded the maximum busy duration +- `forced_tx`: CAD timeout events that force-transmitted because fail-open mode was selected +- `deferred_tx`: CAD timeout events that deferred and retried later +- `dropped_tx`: packets dropped after CAD timeout policy +- `expired_tx`: packets dropped because the maximum CAD deferral age or timeout count was reached + +--- + +### MAC TX stats - TX, retransmit and queue counters +**Usage:** `stats-mac-tx` + +**Serial Only:** No + +Returns JSON with: +- `started`: transmit attempts started by the dispatcher +- `completed`: transmit completions reported by the radio +- `start_fail`: transmit attempts that failed to start +- `timeouts`: transmit operations that timed out +- `rx_delay`: received packets delayed before local processing +- `retransmits`: packets scheduled for retransmit or forward +- `pool_full`: packet allocation failures caused by pool exhaustion +- `bad_queue`: invalid queued packets dropped before transmit --- @@ -512,6 +565,48 @@ This document provides an overview of CLI commands that can be sent to MeshCore --- +#### View or change CAD timeout policy +**Usage:** +- `get cad.timeout.policy` +- `set cad.timeout.policy ` + +**Parameters:** +- `policy`: `defer`, `drop`, or `force` + +**Default:** `defer` + +**Note:** CAD means Channel Activity Detection. When the radio reports the channel busy for longer than the CAD timeout, `defer` keeps the queued packet and retries later, `drop` removes the next due packet, and `force` preserves the older fail-open behaviour of transmitting anyway. `force` should only be used for diagnostics or radio-state fallback because it can worsen congestion. + +--- + +#### View or change maximum CAD deferral age +**Usage:** +- `get cad.max.defer` +- `set cad.max.defer ` + +**Parameters:** +- `seconds`: Maximum total age of the currently CAD-deferred packet, from 0 to 3600. `0` disables the age limit. + +**Default:** `30` + +**Note:** This prevents a packet from remaining queued indefinitely when the local radio keeps reporting the channel as busy. When the limit is reached, the next due packet is dropped and the `stats-mac` `ce` counter is incremented. + +--- + +#### View or change maximum CAD timeout count +**Usage:** +- `get cad.max.timeouts` +- `set cad.max.timeouts ` + +**Parameters:** +- `count`: Maximum number of CAD timeout cycles allowed for the currently deferred packet, from 0 to 255. `0` disables the count limit. + +**Default:** `3` + +**Note:** With the default CAD timeout of about 4 seconds, a value of `3` means a packet can survive roughly three confirmed busy timeout cycles before it is dropped. The age and count limits are both active; whichever limit is reached first wins. + +--- + #### [Experimental] View or change the processing delay for received traffic **Usage:** - `get rxdelay` diff --git a/examples/simple_repeater/MyMesh.cpp b/examples/simple_repeater/MyMesh.cpp index 096907494b..2c4a4d370a 100644 --- a/examples/simple_repeater/MyMesh.cpp +++ b/examples/simple_repeater/MyMesh.cpp @@ -535,6 +535,32 @@ void MyMesh::logTxFail(mesh::Packet *pkt, int len) { } } +void MyMesh::logMacEvent(const char* event, mesh::Packet* pkt, int len, uint8_t priority, + uint32_t delay_millis, uint32_t airtime_millis, uint32_t value) { + if (_logging) { + File f = openAppend(PACKET_LOG_FILE); + if (f) { + f.print(getLogDateTime()); + f.printf(": MAC, ms=%lu event=%s len=%d pri=%u delay=%lu airtime=%lu value=%lu q=%d free=%d nf=%d rssi=%d snr=%d", + _ms->getMillis(), event, len, (uint32_t)priority, (unsigned long)delay_millis, + (unsigned long)airtime_millis, (unsigned long)value, + _mgr->getOutboundTotal(), _mgr->getFreeCount(), (int)_radio->getNoiseFloor(), + (int)radio_driver.getLastRSSI(), (int)(radio_driver.getLastSNR() * 4)); + + if (pkt) { + uint8_t packet_hash[MAX_HASH_SIZE]; + pkt->calculatePacketHash(packet_hash); + f.printf(" type=%d route=%s payload_len=%d path_count=%d path_hash_size=%d hash=", + pkt->getPayloadType(), pkt->isRouteDirect() ? "D" : "F", pkt->payload_len, + pkt->getPathHashCount(), pkt->getPathHashSize()); + mesh::Utils::printHex(f, packet_hash, 4); + } + f.printf("\n"); + f.close(); + } + } +} + int MyMesh::calcRxDelay(float score, uint32_t air_time) const { if (_prefs.rx_delay_base <= 0.0f) return 0; return (int)((pow(_prefs.rx_delay_base, 0.85f - score) - 1.0) * air_time); @@ -893,6 +919,9 @@ MyMesh::MyMesh(mesh::MainBoard &board, mesh::Radio &radio, mesh::MillisecondCloc _prefs.flood_max_unscoped = 64; _prefs.flood_max_advert = 8; _prefs.interference_threshold = 0; // disabled + _prefs.cad_timeout_policy = CAD_TIMEOUT_DEFER; + _prefs.cad_max_defer_secs = DEFAULT_CAD_MAX_DEFER_SECS; + _prefs.cad_max_timeouts = DEFAULT_CAD_MAX_TIMEOUTS; // bridge defaults _prefs.bridge_enabled = 1; // enabled @@ -1152,6 +1181,14 @@ void MyMesh::formatPacketStatsReply(char *reply) { getNumRecvFlood(), getNumRecvDirect()); } +void MyMesh::formatMacCadStatsReply(char *reply) { + StatsFormatHelper::formatMacCadStats(reply, getMacStats()); +} + +void MyMesh::formatMacTxStatsReply(char *reply) { + StatsFormatHelper::formatMacTxStats(reply, getMacStats()); +} + void MyMesh::saveIdentity(const mesh::LocalIdentity &new_id) { #if defined(NRF52_PLATFORM) || defined(STM32_PLATFORM) IdentityStore store(*_fs, ""); diff --git a/examples/simple_repeater/MyMesh.h b/examples/simple_repeater/MyMesh.h index 7597c6c6f6..714143b112 100644 --- a/examples/simple_repeater/MyMesh.h +++ b/examples/simple_repeater/MyMesh.h @@ -142,6 +142,8 @@ class MyMesh : public mesh::Mesh, public CommonCLICallbacks { void logRx(mesh::Packet* pkt, int len, float score) override; void logTx(mesh::Packet* pkt, int len) override; void logTxFail(mesh::Packet* pkt, int len) override; + void logMacEvent(const char* event, mesh::Packet* pkt, int len, uint8_t priority, + uint32_t delay_millis, uint32_t airtime_millis, uint32_t value) override; int calcRxDelay(float score, uint32_t air_time) const override; uint32_t getRetransmitDelay(const mesh::Packet* packet) override; @@ -153,6 +155,15 @@ class MyMesh : public mesh::Mesh, public CommonCLICallbacks { int getAGCResetInterval() const override { return ((int)_prefs.agc_reset_interval) * 4000; // milliseconds } + uint8_t getCADTimeoutPolicy() const override { + return _prefs.cad_timeout_policy; + } + uint32_t getCADMaxDeferralMs() const override { + return ((uint32_t)_prefs.cad_max_defer_secs) * 1000UL; + } + uint8_t getCADMaxTimeouts() const override { + return _prefs.cad_max_timeouts; + } uint8_t getExtraAckTransmitCount() const override { return _prefs.multi_acks; } @@ -214,6 +225,8 @@ class MyMesh : public mesh::Mesh, public CommonCLICallbacks { void formatStatsReply(char *reply) override; void formatRadioStatsReply(char *reply) override; void formatPacketStatsReply(char *reply) override; + void formatMacCadStatsReply(char *reply) override; + void formatMacTxStatsReply(char *reply) override; void startRegionsLoad() override; bool saveRegions() override; void onDefaultRegionChanged(const RegionEntry* r) override; diff --git a/examples/simple_room_server/MyMesh.cpp b/examples/simple_room_server/MyMesh.cpp index 98b22fdb72..a6e899e75b 100644 --- a/examples/simple_room_server/MyMesh.cpp +++ b/examples/simple_room_server/MyMesh.cpp @@ -650,6 +650,9 @@ MyMesh::MyMesh(mesh::MainBoard &board, mesh::Radio &radio, mesh::MillisecondCloc _prefs.flood_max_unscoped = 64; _prefs.flood_max_advert = 8; _prefs.interference_threshold = 0; // disabled + _prefs.cad_timeout_policy = CAD_TIMEOUT_DEFER; + _prefs.cad_max_defer_secs = DEFAULT_CAD_MAX_DEFER_SECS; + _prefs.cad_max_timeouts = DEFAULT_CAD_MAX_TIMEOUTS; #ifdef ROOM_PASSWORD StrHelper::strncpy(_prefs.guest_password, ROOM_PASSWORD, sizeof(_prefs.guest_password)); #endif diff --git a/examples/simple_room_server/MyMesh.h b/examples/simple_room_server/MyMesh.h index 5277ddad61..c7d77e509d 100644 --- a/examples/simple_room_server/MyMesh.h +++ b/examples/simple_room_server/MyMesh.h @@ -147,6 +147,15 @@ class MyMesh : public mesh::Mesh, public CommonCLICallbacks { int getAGCResetInterval() const override { return ((int)_prefs.agc_reset_interval) * 4000; // milliseconds } + uint8_t getCADTimeoutPolicy() const override { + return _prefs.cad_timeout_policy; + } + uint32_t getCADMaxDeferralMs() const override { + return ((uint32_t)_prefs.cad_max_defer_secs) * 1000UL; + } + uint8_t getCADMaxTimeouts() const override { + return _prefs.cad_max_timeouts; + } uint8_t getExtraAckTransmitCount() const override { return _prefs.multi_acks; } diff --git a/examples/simple_sensor/SensorMesh.cpp b/examples/simple_sensor/SensorMesh.cpp index 879fcbf026..d673e18d54 100644 --- a/examples/simple_sensor/SensorMesh.cpp +++ b/examples/simple_sensor/SensorMesh.cpp @@ -726,6 +726,9 @@ SensorMesh::SensorMesh(mesh::MainBoard& board, mesh::Radio& radio, mesh::Millise _prefs.disable_fwd = true; _prefs.flood_max = 64; _prefs.interference_threshold = 0; // disabled + _prefs.cad_timeout_policy = CAD_TIMEOUT_DEFER; + _prefs.cad_max_defer_secs = DEFAULT_CAD_MAX_DEFER_SECS; + _prefs.cad_max_timeouts = DEFAULT_CAD_MAX_TIMEOUTS; // GPS defaults _prefs.gps_enabled = 0; diff --git a/examples/simple_sensor/SensorMesh.h b/examples/simple_sensor/SensorMesh.h index c9f135f65e..86bfa44a4f 100644 --- a/examples/simple_sensor/SensorMesh.h +++ b/examples/simple_sensor/SensorMesh.h @@ -121,6 +121,15 @@ class SensorMesh : public mesh::Mesh, public CommonCLICallbacks { uint32_t getDirectRetransmitDelay(const mesh::Packet* packet) override; int getInterferenceThreshold() const override; int getAGCResetInterval() const override; + uint8_t getCADTimeoutPolicy() const override { + return _prefs.cad_timeout_policy; + } + uint32_t getCADMaxDeferralMs() const override { + return ((uint32_t)_prefs.cad_max_defer_secs) * 1000UL; + } + uint8_t getCADMaxTimeouts() const override { + return _prefs.cad_max_timeouts; + } void onAnonDataRecv(mesh::Packet* packet, const uint8_t* secret, const mesh::Identity& sender, uint8_t* data, size_t len) override; int searchPeersByHash(const uint8_t* hash) override; void getPeerSharedSecret(uint8_t* dest_secret, int peer_idx) override; diff --git a/src/Dispatcher.cpp b/src/Dispatcher.cpp index 9d7a11131d..f92198c309 100644 --- a/src/Dispatcher.cpp +++ b/src/Dispatcher.cpp @@ -19,6 +19,10 @@ namespace mesh { void Dispatcher::begin() { n_sent_flood = n_sent_direct = 0; n_recv_flood = n_recv_direct = 0; + memset(&mac_stats, 0, sizeof(mac_stats)); + cad_defer_packet = NULL; + cad_defer_start = 0; + cad_defer_timeouts = 0; _err_flags = 0; radio_nonrx_start = _ms->getMillis(); @@ -105,6 +109,8 @@ void Dispatcher::loop() { } _radio->onSendFinished(); + mac_stats.tx_done++; + logMacEvent("tx_done", outbound, 2 + outbound->getPathByteLen() + outbound->payload_len, 0, 0, t, tx_budget_ms); logTx(outbound, 2 + outbound->getPathByteLen() + outbound->payload_len); if (outbound->isRouteFlood()) { n_sent_flood++; @@ -117,6 +123,8 @@ void Dispatcher::loop() { MESH_DEBUG_PRINTLN("%s Dispatcher::loop(): WARNING: outbound packed send timed out!", getLogDateTime()); _radio->onSendFinished(); + mac_stats.tx_timeout++; + logMacEvent("tx_timeout", outbound, 2 + outbound->getPathByteLen() + outbound->payload_len, 0, 0, 0, 0); logTxFail(outbound, 2 + outbound->getPathByteLen() + outbound->payload_len); releasePacket(outbound); // return to pool @@ -138,6 +146,7 @@ void Dispatcher::loop() { { Packet* pkt = _mgr->getNextInbound(_ms->getMillis()); if (pkt) { + logMacEvent("rx_delay_done", pkt, pkt->getRawLength(), 0, 0, _radio->getEstAirtimeFor(pkt->getRawLength()), 0); processRecvPacket(pkt); } } @@ -199,6 +208,7 @@ void Dispatcher::checkRecv() { pkt = _mgr->allocNew(); if (pkt == NULL) { + mac_stats.pool_full++; MESH_DEBUG_PRINTLN("%s Dispatcher::checkRecv(): WARNING: received data, no unused packets available!", getLogDateTime()); } else { if (tryParsePacket(pkt, raw, len)) { @@ -248,6 +258,8 @@ void Dispatcher::checkRecv() { if (_delay > MAX_RX_DELAY_MILLIS) { _delay = MAX_RX_DELAY_MILLIS; } + mac_stats.rx_delay++; + logMacEvent("rx_delay", pkt, pkt->getRawLength(), 0, _delay, air_time, (uint32_t)(score * 1000)); _mgr->queueInbound(pkt, futureMillis(_delay)); // add to delayed inbound queue } } else { @@ -267,6 +279,8 @@ void Dispatcher::processRecvPacket(Packet* pkt) { uint8_t priority = (action >> 24) - 1; uint32_t _delay = action & 0xFFFFFF; + mac_stats.retransmit++; + logMacEvent("retransmit", pkt, pkt->getRawLength(), priority, _delay, _radio->getEstAirtimeFor(pkt->getRawLength()), 0); _mgr->queueOutbound(pkt, priority, futureMillis(_delay)); } } @@ -286,18 +300,73 @@ void Dispatcher::checkSend() { if (!millisHasNowPassed(next_tx_time)) return; if (_radio->isReceiving()) { + Packet* pending = _mgr->peekNextOutbound(_ms->getMillis()); + if (pending != cad_defer_packet) { + cad_defer_packet = pending; + cad_defer_start = pending ? _ms->getMillis() : 0; + cad_defer_timeouts = 0; + } if (cad_busy_start == 0) { cad_busy_start = _ms->getMillis(); // record when CAD busy state started } if (_ms->getMillis() - cad_busy_start > getCADFailMaxDuration()) { _err_flags |= ERR_EVENT_CAD_TIMEOUT; + mac_stats.cad_timeout++; MESH_DEBUG_PRINTLN("%s Dispatcher::checkSend(): CAD busy max duration reached!", getLogDateTime()); - // channel activity has gone on too long... (Radio might be in a bad state) - // force the pending transmit below... + uint32_t busy_duration = _ms->getMillis() - cad_busy_start; + uint8_t policy = getCADTimeoutPolicy(); + if (policy == CAD_TIMEOUT_POLICY_DROP) { + Packet* dropped = _mgr->getNextOutbound(_ms->getMillis()); + mac_stats.cad_dropped_tx++; + logMacEvent("cad_drop", dropped, dropped ? dropped->getRawLength() : 0, 0, 0, 0, busy_duration); + if (dropped) { + releasePacket(dropped); + } + cad_defer_packet = NULL; + cad_defer_start = 0; + cad_defer_timeouts = 0; + cad_busy_start = 0; + next_tx_time = futureMillis(getCADFailRetryDelay()); + return; + } else if (policy == CAD_TIMEOUT_POLICY_FORCE) { + mac_stats.cad_forced_tx++; + logMacEvent("cad_force", pending, pending ? pending->getRawLength() : 0, 0, 0, 0, busy_duration); + // Explicit fail-open mode: transmit below even though local CAD still reports busy. + } else { + uint32_t retry_delay = getCADFailRetryDelay(); + cad_defer_timeouts++; + uint32_t max_deferral_ms = getCADMaxDeferralMs(); + uint8_t max_timeouts = getCADMaxTimeouts(); + bool age_expired = max_deferral_ms > 0 && cad_defer_start > 0 && _ms->getMillis() - cad_defer_start >= max_deferral_ms; + bool count_expired = max_timeouts > 0 && cad_defer_timeouts >= max_timeouts; + if (age_expired || count_expired) { + Packet* expired = _mgr->getNextOutbound(_ms->getMillis()); + mac_stats.cad_dropped_tx++; + mac_stats.cad_expired_tx++; + logMacEvent("cad_expire", expired, expired ? expired->getRawLength() : 0, 0, retry_delay, 0, busy_duration); + if (expired) { + releasePacket(expired); + } + cad_defer_packet = NULL; + cad_defer_start = 0; + cad_defer_timeouts = 0; + cad_busy_start = 0; + next_tx_time = futureMillis(retry_delay); + return; + } + mac_stats.cad_deferred_tx++; + logMacEvent("cad_defer", pending, pending ? pending->getRawLength() : 0, 0, retry_delay, 0, busy_duration); + cad_busy_start = 0; + next_tx_time = futureMillis(retry_delay); + return; + } } else { - next_tx_time = futureMillis(getCADFailRetryDelay()); + uint32_t retry_delay = getCADFailRetryDelay(); + mac_stats.cad_busy++; + logMacEvent("cad_busy", pending, pending ? pending->getRawLength() : 0, 0, retry_delay, 0, _ms->getMillis() - cad_busy_start); + next_tx_time = futureMillis(retry_delay); return; } } @@ -305,6 +374,11 @@ void Dispatcher::checkSend() { outbound = _mgr->getNextOutbound(_ms->getMillis()); if (outbound) { + if (outbound == cad_defer_packet) { + cad_defer_packet = NULL; + cad_defer_start = 0; + cad_defer_timeouts = 0; + } int len = 0; uint8_t raw[MAX_TRANS_UNIT]; @@ -318,6 +392,8 @@ void Dispatcher::checkSend() { 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); + mac_stats.invalid_queue++; + logMacEvent("invalid_queue", outbound, len + outbound->payload_len, 0, 0, 0, 0); _mgr->free(outbound); outbound = NULL; } else { @@ -329,12 +405,16 @@ void Dispatcher::checkSend() { if (!success) { MESH_DEBUG_PRINTLN("%s Dispatcher::loop(): ERROR: send start failed!", getLogDateTime()); + mac_stats.tx_start_fail++; + logMacEvent("tx_start_fail", outbound, outbound->getRawLength(), 0, 0, max_airtime, 0); logTxFail(outbound, outbound->getRawLength()); releasePacket(outbound); // return to pool outbound = NULL; return; } + mac_stats.tx_start++; + logMacEvent("tx_start", outbound, len, 0, 0, max_airtime, tx_budget_ms); outbound_expiry = futureMillis(max_airtime); #if MESH_PACKET_LOGGING @@ -356,6 +436,7 @@ Packet* Dispatcher::obtainNewPacket() { auto pkt = _mgr->allocNew(); // TODO: zero out all fields if (pkt == NULL) { _err_flags |= ERR_EVENT_FULL; + mac_stats.pool_full++; } else { pkt->payload_len = pkt->path_len = 0; pkt->_snr = 0; @@ -370,8 +451,11 @@ void Dispatcher::releasePacket(Packet* packet) { void Dispatcher::sendPacket(Packet* packet, uint8_t priority, uint32_t delay_millis) { if (!Packet::isValidPathLen(packet->path_len) || packet->payload_len > MAX_PACKET_PAYLOAD) { MESH_DEBUG_PRINTLN("%s Dispatcher::sendPacket(): ERROR: invalid packet... path_len=%d, payload_len=%d", getLogDateTime(), (uint32_t) packet->path_len, (uint32_t) packet->payload_len); + mac_stats.invalid_queue++; + logMacEvent("invalid_queue", packet, packet->getRawLength(), priority, delay_millis, 0, 0); _mgr->free(packet); } else { + logMacEvent("queue_tx", packet, packet->getRawLength(), priority, delay_millis, _radio->getEstAirtimeFor(packet->getRawLength()), _mgr->getOutboundTotal()); _mgr->queueOutbound(packet, priority, futureMillis(delay_millis)); } } @@ -386,4 +470,4 @@ unsigned long Dispatcher::futureMillis(int millis_from_now) const { return _ms->getMillis() + millis_from_now; } -} \ No newline at end of file +} diff --git a/src/Dispatcher.h b/src/Dispatcher.h index dd032f130d..1531fd8aac 100644 --- a/src/Dispatcher.h +++ b/src/Dispatcher.h @@ -89,6 +89,7 @@ class PacketManager { virtual void queueOutbound(Packet* packet, uint8_t priority, uint32_t scheduled_for) = 0; virtual Packet* getNextOutbound(uint32_t now) = 0; // by priority + virtual Packet* peekNextOutbound(uint32_t now) { return NULL; } virtual int getOutboundCount(uint32_t now) const = 0; virtual int getOutboundTotal() const = 0; virtual int getFreeCount() const = 0; @@ -109,6 +110,33 @@ typedef uint32_t DispatcherAction; #define ERR_EVENT_CAD_TIMEOUT (1 << 1) #define ERR_EVENT_STARTRX_TIMEOUT (1 << 2) +#define CAD_TIMEOUT_POLICY_DEFER 0 +#define CAD_TIMEOUT_POLICY_DROP 1 +#define CAD_TIMEOUT_POLICY_FORCE 2 + +// Keep CAD deferral fail-closed by default. A CAD timeout is currently about +// four seconds, so three timeout cycles drops a packet after repeated confirmed +// busy radio state; the age limit is a guard for jitter and priority changes. +#define DEFAULT_CAD_MAX_DEFER_SECS 30 +#define DEFAULT_CAD_MAX_TIMEOUTS 3 + +struct MacStats { + uint32_t cad_busy; + uint32_t cad_timeout; + uint32_t cad_forced_tx; + uint32_t cad_deferred_tx; + uint32_t cad_dropped_tx; + uint32_t cad_expired_tx; + uint32_t tx_start; + uint32_t tx_done; + uint32_t tx_start_fail; + uint32_t tx_timeout; + uint32_t rx_delay; + uint32_t retransmit; + uint32_t pool_full; + uint32_t invalid_queue; +}; + /** * \brief The low-level task that manages detecting incoming Packets, and the queueing * and scheduling of outbound Packets. @@ -126,6 +154,10 @@ class Dispatcher { unsigned long tx_budget_ms; unsigned long last_budget_update; unsigned long duty_cycle_window_ms; + Packet* cad_defer_packet; + unsigned long cad_defer_start; + uint8_t cad_defer_timeouts; + MacStats mac_stats; void processRecvPacket(Packet* pkt); void updateTxBudget(); @@ -159,12 +191,17 @@ class Dispatcher { virtual void logRx(Packet* packet, int len, float score) { } // hooks for custom logging virtual void logTx(Packet* packet, int len) { } virtual void logTxFail(Packet* packet, int len) { } + virtual void logMacEvent(const char* event, Packet* packet, int len, uint8_t priority, + uint32_t delay_millis, uint32_t airtime_millis, uint32_t value) { } virtual const char* getLogDateTime() { return ""; } virtual float getAirtimeBudgetFactor() const; virtual int calcRxDelay(float score, uint32_t air_time) const; virtual uint32_t getCADFailRetryDelay() const; virtual uint32_t getCADFailMaxDuration() const; + virtual uint8_t getCADTimeoutPolicy() const { return CAD_TIMEOUT_POLICY_DEFER; } + virtual uint32_t getCADMaxDeferralMs() const { return DEFAULT_CAD_MAX_DEFER_SECS * 1000UL; } + virtual uint8_t getCADMaxTimeouts() const { return DEFAULT_CAD_MAX_TIMEOUTS; } virtual int getInterferenceThreshold() const { return 0; } // disabled by default virtual int getAGCResetInterval() const { return 0; } // disabled by default virtual unsigned long getDutyCycleWindowMs() const { return 3600000; } @@ -184,8 +221,10 @@ class Dispatcher { uint32_t getNumSentDirect() const { return n_sent_direct; } uint32_t getNumRecvFlood() const { return n_recv_flood; } uint32_t getNumRecvDirect() const { return n_recv_direct; } + const MacStats& getMacStats() const { return mac_stats; } void resetStats() { n_sent_flood = n_sent_direct = n_recv_flood = n_recv_direct = 0; + memset(&mac_stats, 0, sizeof(mac_stats)); _err_flags = 0; } diff --git a/src/helpers/CommonCLI.cpp b/src/helpers/CommonCLI.cpp index b78ad6ebd6..1d6466018f 100644 --- a/src/helpers/CommonCLI.cpp +++ b/src/helpers/CommonCLI.cpp @@ -27,6 +27,33 @@ static bool isValidName(const char *n) { return true; } +static const char* cadTimeoutPolicyToString(uint8_t policy) { + switch (policy) { + case CAD_TIMEOUT_DROP: + return "drop"; + case CAD_TIMEOUT_FORCE: + return "force"; + default: + return "defer"; + } +} + +static bool parseCADTimeoutPolicy(const char* value, uint8_t& policy) { + if (strcmp(value, "defer") == 0) { + policy = CAD_TIMEOUT_DEFER; + return true; + } + if (strcmp(value, "drop") == 0) { + policy = CAD_TIMEOUT_DROP; + return true; + } + if (strcmp(value, "force") == 0) { + policy = CAD_TIMEOUT_FORCE; + return true; + } + return false; +} + void CommonCLI::loadPrefs(FILESYSTEM* fs) { if (fs->exists("/com_prefs")) { loadPrefsInt(fs, "/com_prefs"); // new filename @@ -91,7 +118,10 @@ void CommonCLI::loadPrefsInt(FILESYSTEM* fs, const char* filename) { file.read((uint8_t *)&_prefs->rx_boosted_gain, sizeof(_prefs->rx_boosted_gain)); // 290 file.read((uint8_t *)&_prefs->flood_max_unscoped, sizeof(_prefs->flood_max_unscoped)); // 291 file.read((uint8_t *)&_prefs->flood_max_advert, sizeof(_prefs->flood_max_advert)); // 292 - // next: 293 + file.read((uint8_t *)&_prefs->cad_timeout_policy, sizeof(_prefs->cad_timeout_policy)); // 293 + file.read((uint8_t *)&_prefs->cad_max_defer_secs, sizeof(_prefs->cad_max_defer_secs)); // 294 + file.read((uint8_t *)&_prefs->cad_max_timeouts, sizeof(_prefs->cad_max_timeouts)); // 296 + // next: 297 // sanitise bad pref values _prefs->rx_delay_base = constrain(_prefs->rx_delay_base, 0, 20.0f); @@ -121,6 +151,9 @@ void CommonCLI::loadPrefsInt(FILESYSTEM* fs, const char* filename) { // sanitise settings _prefs->rx_boosted_gain = constrain(_prefs->rx_boosted_gain, 0, 1); // boolean + _prefs->cad_timeout_policy = constrain(_prefs->cad_timeout_policy, CAD_TIMEOUT_DEFER, CAD_TIMEOUT_FORCE); + _prefs->cad_max_defer_secs = constrain(_prefs->cad_max_defer_secs, 0, 3600); + _prefs->cad_max_timeouts = constrain(_prefs->cad_max_timeouts, 0, 255); file.close(); } @@ -184,7 +217,10 @@ void CommonCLI::savePrefs(FILESYSTEM* fs) { file.write((uint8_t *)&_prefs->rx_boosted_gain, sizeof(_prefs->rx_boosted_gain)); // 290 file.write((uint8_t *)&_prefs->flood_max_unscoped, sizeof(_prefs->flood_max_unscoped)); // 291 file.write((uint8_t *)&_prefs->flood_max_advert, sizeof(_prefs->flood_max_advert)); // 292 - // next: 293 + file.write((uint8_t *)&_prefs->cad_timeout_policy, sizeof(_prefs->cad_timeout_policy)); // 293 + file.write((uint8_t *)&_prefs->cad_max_defer_secs, sizeof(_prefs->cad_max_defer_secs)); // 294 + file.write((uint8_t *)&_prefs->cad_max_timeouts, sizeof(_prefs->cad_max_timeouts)); // 296 + // next: 297 file.close(); } @@ -467,12 +503,16 @@ void CommonCLI::handleCommand(uint32_t sender_timestamp, char* command, char* re } else if (sender_timestamp == 0 && memcmp(command, "log", 3) == 0) { _callbacks->dumpLogFile(); strcpy(reply, " EOF"); - } else if (sender_timestamp == 0 && memcmp(command, "stats-packets", 13) == 0 && (command[13] == 0 || command[13] == ' ')) { + } else if (memcmp(command, "stats-packets", 13) == 0 && (command[13] == 0 || command[13] == ' ')) { _callbacks->formatPacketStatsReply(reply); - } else if (sender_timestamp == 0 && memcmp(command, "stats-radio", 11) == 0 && (command[11] == 0 || command[11] == ' ')) { + } else if (memcmp(command, "stats-radio", 11) == 0 && (command[11] == 0 || command[11] == ' ')) { _callbacks->formatRadioStatsReply(reply); - } else if (sender_timestamp == 0 && memcmp(command, "stats-core", 10) == 0 && (command[10] == 0 || command[10] == ' ')) { + } else if (memcmp(command, "stats-core", 10) == 0 && (command[10] == 0 || command[10] == ' ')) { _callbacks->formatStatsReply(reply); + } else if (memcmp(command, "stats-mac-cad", 13) == 0 && (command[13] == 0 || command[13] == ' ')) { + _callbacks->formatMacCadStatsReply(reply); + } else if (memcmp(command, "stats-mac-tx", 12) == 0 && (command[12] == 0 || command[12] == ' ')) { + _callbacks->formatMacTxStatsReply(reply); } else { strcpy(reply, "Unknown command"); } @@ -648,6 +688,33 @@ void CommonCLI::handleSetCmd(uint32_t sender_timestamp, char* command, char* rep } else { strcpy(reply, "Error, must be 0-2"); } + } else if (memcmp(config, "cad.timeout.policy ", 19) == 0) { + uint8_t policy; + if (parseCADTimeoutPolicy(&config[19], policy)) { + _prefs->cad_timeout_policy = policy; + savePrefs(); + strcpy(reply, "OK"); + } else { + strcpy(reply, "Error, must be defer, drop, or force"); + } + } else if (memcmp(config, "cad.max.defer ", 14) == 0) { + uint16_t seconds = _atoi(&config[14]); + if (seconds <= 3600) { + _prefs->cad_max_defer_secs = seconds; + savePrefs(); + strcpy(reply, "OK"); + } else { + strcpy(reply, "Error, must be 0-3600"); + } + } else if (memcmp(config, "cad.max.timeouts ", 17) == 0) { + uint16_t count = _atoi(&config[17]); + if (count <= 255) { + _prefs->cad_max_timeouts = (uint8_t)count; + savePrefs(); + strcpy(reply, "OK"); + } else { + strcpy(reply, "Error, must be 0-255"); + } } else if (memcmp(config, "owner.info ", 11) == 0) { config += 11; char *dp = _prefs->owner_info; @@ -822,6 +889,12 @@ void CommonCLI::handleGetCmd(uint32_t sender_timestamp, char* command, char* rep sprintf(reply, "> %d", (uint32_t)_prefs->flood_max); } else if (memcmp(config, "direct.txdelay", 14) == 0) { sprintf(reply, "> %s", StrHelper::ftoa(_prefs->direct_tx_delay_factor)); + } else if (memcmp(config, "cad.timeout.policy", 18) == 0) { + sprintf(reply, "> %s", cadTimeoutPolicyToString(_prefs->cad_timeout_policy)); + } else if (memcmp(config, "cad.max.defer", 13) == 0) { + sprintf(reply, "> %u", (uint32_t)_prefs->cad_max_defer_secs); + } else if (memcmp(config, "cad.max.timeouts", 16) == 0) { + sprintf(reply, "> %u", (uint32_t)_prefs->cad_max_timeouts); } else if (memcmp(config, "owner.info", 10) == 0) { auto start = reply; *reply++ = '>'; diff --git a/src/helpers/CommonCLI.h b/src/helpers/CommonCLI.h index b509c2b31a..9b3f5089f3 100644 --- a/src/helpers/CommonCLI.h +++ b/src/helpers/CommonCLI.h @@ -5,6 +5,7 @@ #include #include #include +#include #if defined(WITH_RS232_BRIDGE) || defined(WITH_ESPNOW_BRIDGE) #define WITH_BRIDGE @@ -19,6 +20,10 @@ #define LOOP_DETECT_MODERATE 2 #define LOOP_DETECT_STRICT 3 +#define CAD_TIMEOUT_DEFER CAD_TIMEOUT_POLICY_DEFER +#define CAD_TIMEOUT_DROP CAD_TIMEOUT_POLICY_DROP +#define CAD_TIMEOUT_FORCE CAD_TIMEOUT_POLICY_FORCE + struct NodePrefs { // persisted to file float airtime_factor; char node_name[32]; @@ -63,6 +68,9 @@ struct NodePrefs { // persisted to file uint8_t rx_boosted_gain; // power settings uint8_t path_hash_mode; // which path mode to use when sending uint8_t loop_detect; + uint8_t cad_timeout_policy; + uint16_t cad_max_defer_secs; + uint8_t cad_max_timeouts; }; class CommonCLICallbacks { @@ -86,6 +94,12 @@ class CommonCLICallbacks { virtual void formatStatsReply(char *reply) = 0; virtual void formatRadioStatsReply(char *reply) = 0; virtual void formatPacketStatsReply(char *reply) = 0; + virtual void formatMacCadStatsReply(char *reply) { + strcpy(reply, "unsupported"); + } + virtual void formatMacTxStatsReply(char *reply) { + strcpy(reply, "unsupported"); + } virtual mesh::LocalIdentity& getSelfId() = 0; virtual void saveIdentity(const mesh::LocalIdentity& new_id) = 0; virtual void clearStats() = 0; diff --git a/src/helpers/StaticPoolPacketManager.cpp b/src/helpers/StaticPoolPacketManager.cpp index b8926df0cc..a9cefbba13 100644 --- a/src/helpers/StaticPoolPacketManager.cpp +++ b/src/helpers/StaticPoolPacketManager.cpp @@ -43,6 +43,19 @@ mesh::Packet* PacketQueue::get(uint32_t now) { return top; } +mesh::Packet* PacketQueue::peek(uint32_t now) const { + uint8_t min_pri = 0xFF; + int best_idx = -1; + for (int j = 0; j < _num; j++) { + if ((int32_t)(_schedule_table[j] - now) > 0) continue; // scheduled for future... ignore for now + if (_pri_table[j] < min_pri) { // select most important priority amongst non-future entries + min_pri = _pri_table[j]; + best_idx = j; + } + } + return best_idx < 0 ? NULL : _table[best_idx]; +} + mesh::Packet* PacketQueue::removeByIdx(int i) { if (i >= _num) return NULL; // invalid index @@ -95,6 +108,10 @@ mesh::Packet* StaticPoolPacketManager::getNextOutbound(uint32_t now) { return send_queue.get(now); } +mesh::Packet* StaticPoolPacketManager::peekNextOutbound(uint32_t now) { + return send_queue.peek(now); +} + int StaticPoolPacketManager::getOutboundCount(uint32_t now) const { return send_queue.countBefore(now); } diff --git a/src/helpers/StaticPoolPacketManager.h b/src/helpers/StaticPoolPacketManager.h index 59715b4e01..5c41826619 100644 --- a/src/helpers/StaticPoolPacketManager.h +++ b/src/helpers/StaticPoolPacketManager.h @@ -11,6 +11,7 @@ class PacketQueue { public: PacketQueue(int max_entries); mesh::Packet* get(uint32_t now); + mesh::Packet* peek(uint32_t now) const; bool add(mesh::Packet* packet, uint8_t priority, uint32_t scheduled_for); int count() const { return _num; } int countBefore(uint32_t now) const; @@ -28,6 +29,7 @@ class StaticPoolPacketManager : public mesh::PacketManager { void free(mesh::Packet* packet) override; void queueOutbound(mesh::Packet* packet, uint8_t priority, uint32_t scheduled_for) override; mesh::Packet* getNextOutbound(uint32_t now) override; + mesh::Packet* peekNextOutbound(uint32_t now) override; int getOutboundCount(uint32_t now) const override; int getOutboundTotal() const override; int getFreeCount() const override; @@ -35,4 +37,4 @@ class StaticPoolPacketManager : public mesh::PacketManager { mesh::Packet* removeOutboundByIdx(int i) override; void queueInbound(mesh::Packet* packet, uint32_t scheduled_for) override; mesh::Packet* getNextInbound(uint32_t now) override; -}; \ No newline at end of file +}; diff --git a/src/helpers/StatsFormatHelper.h b/src/helpers/StatsFormatHelper.h index bf619133e9..616615b1f7 100644 --- a/src/helpers/StatsFormatHelper.h +++ b/src/helpers/StatsFormatHelper.h @@ -1,6 +1,7 @@ #pragma once #include "Mesh.h" +#include class StatsFormatHelper { public: @@ -52,4 +53,30 @@ class StatsFormatHelper { driver.getPacketsRecvErrors() ); } + + static void formatMacCadStats(char* reply, const mesh::MacStats& stats) { + sprintf(reply, + "{\"busy\":%u,\"timeouts\":%u,\"forced_tx\":%u,\"deferred_tx\":%u,\"dropped_tx\":%u,\"expired_tx\":%u}", + stats.cad_busy, + stats.cad_timeout, + stats.cad_forced_tx, + stats.cad_deferred_tx, + stats.cad_dropped_tx, + stats.cad_expired_tx + ); + } + + static void formatMacTxStats(char* reply, const mesh::MacStats& stats) { + sprintf(reply, + "{\"started\":%u,\"completed\":%u,\"start_fail\":%u,\"timeouts\":%u,\"rx_delay\":%u,\"retransmits\":%u,\"pool_full\":%u,\"bad_queue\":%u}", + stats.tx_start, + stats.tx_done, + stats.tx_start_fail, + stats.tx_timeout, + stats.rx_delay, + stats.retransmit, + stats.pool_full, + stats.invalid_queue + ); + } }; diff --git a/test/test_static_pool_packet_manager/test_peek.cpp b/test/test_static_pool_packet_manager/test_peek.cpp new file mode 100644 index 0000000000..170b17dcfe --- /dev/null +++ b/test/test_static_pool_packet_manager/test_peek.cpp @@ -0,0 +1,50 @@ +#include + +#include "helpers/StaticPoolPacketManager.h" + +// The native test environment only builds selected src files. Include this small +// implementation directly so the test can exercise queue ordering without +// widening the PlatformIO test build filter. +#include "../../src/helpers/StaticPoolPacketManager.cpp" + +namespace mesh { +Packet::Packet() { + header = 0; + path_len = 0; + payload_len = 0; +} +} + +TEST(PacketQueue, PeekReturnsBestDuePacketWithoutRemovingIt) { + PacketQueue queue(4); + mesh::Packet* low_priority = reinterpret_cast(0x01); + mesh::Packet* high_priority = reinterpret_cast(0x02); + mesh::Packet* future = reinterpret_cast(0x03); + + ASSERT_TRUE(queue.add(low_priority, 5, 100)); + ASSERT_TRUE(queue.add(high_priority, 1, 100)); + ASSERT_TRUE(queue.add(future, 0, 200)); + + EXPECT_EQ(high_priority, queue.peek(100)); + EXPECT_EQ(3, queue.count()); + + EXPECT_EQ(high_priority, queue.get(100)); + EXPECT_EQ(2, queue.count()); + EXPECT_EQ(low_priority, queue.peek(100)); +} + +TEST(PacketQueue, PeekIgnoresFuturePackets) { + PacketQueue queue(2); + mesh::Packet* future = reinterpret_cast(0x01); + + ASSERT_TRUE(queue.add(future, 0, 200)); + + EXPECT_EQ(nullptr, queue.peek(100)); + EXPECT_EQ(future, queue.peek(200)); + EXPECT_EQ(1, queue.count()); +} + +int main(int argc, char **argv) { + ::testing::InitGoogleTest(&argc, argv); + return RUN_ALL_TESTS(); +}