diff --git a/.trunk/trunk.yaml b/.trunk/trunk.yaml index 099a6a4919..aec3fc6f87 100644 --- a/.trunk/trunk.yaml +++ b/.trunk/trunk.yaml @@ -158,6 +158,7 @@ lint: # 32-bit rollover. - linters: [trufflehog] paths: + - test/test_airtime/test_main.cpp - test/test_throttle/test_main.cpp - test/test_uptime_clock/test_main.cpp runtimes: diff --git a/src/airtime.cpp b/src/airtime.cpp index a9b4c7dc58..aaacefb092 100644 --- a/src/airtime.cpp +++ b/src/airtime.cpp @@ -2,62 +2,65 @@ #include "NodeDB.h" #include "UptimeClock.h" #include "configuration.h" +#include #include AirTime *airTime = NULL; -// Don't read out of this directly. Use the helper functions. +AirTime *AirTime::Held::armReentryCheck(AirTime *a) +{ +#ifdef AIRTIME_REENTRY_CHECK + // Before the lock: a nested take blocks forever, so a later check would never run. + assert(!a->reentryFlag); + a->reentryFlag = true; +#endif + return a; +} -uint32_t air_period_tx[PERIODS_TO_LOG]; -uint32_t air_period_rx[PERIODS_TO_LOG]; +AirTime::Held::~Held() +{ +#ifdef AIRTIME_REENTRY_CHECK + owner->reentryFlag = false; +#else + (void)owner; +#endif +} -void AirTime::logAirtime(reportTypes reportType, uint32_t airtime_ms) +// --- the lock-free core ------------------------------------------------------------------------- +// Every method here requires the lock, and says so in its signature. None can take it: Windows has +// no lock to reach. + +void AirTime::Windows::logAirtime(reportTypes reportType, uint32_t airtime_ms, const Held &held) { // A packet may be logged immediately after waking from light sleep. Sync first so // the packet is counted in the current wall-time bucket, not a stale awake-time bucket. - syncNow(); + syncNow(held); + // The caller logs, once the lock is released. if (reportType == TX_LOG) { - LOG_DEBUG("Packet TX: %ums", airtime_ms); this->airtimes.periodTX[0] = this->airtimes.periodTX[0] + airtime_ms; - air_period_tx[0] = air_period_tx[0] + airtime_ms; - - this->utilizationTX[this->getPeriodUtilHour()] = this->utilizationTX[this->getPeriodUtilHour()] + airtime_ms; + this->utilizationTX[this->getPeriodUtilHour(held)] += airtime_ms; } else if (reportType == RX_LOG) { - LOG_DEBUG("Packet RX: %ums", airtime_ms); this->airtimes.periodRX[0] = this->airtimes.periodRX[0] + airtime_ms; - air_period_rx[0] = air_period_rx[0] + airtime_ms; } else if (reportType == RX_ALL_LOG) { - LOG_DEBUG("Packet RX (noise?) : %ums", airtime_ms); this->airtimes.periodRX_ALL[0] = this->airtimes.periodRX_ALL[0] + airtime_ms; } // Log all airtime type for channel utilization - this->channelUtilization[this->getPeriodUtilMinute()] = channelUtilization[this->getPeriodUtilMinute()] + airtime_ms; + this->channelUtilization[this->getPeriodUtilMinute(held)] += airtime_ms; } -uint8_t AirTime::currentPeriodIndex() -{ - return ((secSinceBoot / SECONDS_PER_PERIOD) % PERIODS_TO_LOG); -} - -uint8_t AirTime::getPeriodUtilMinute() +uint8_t AirTime::Windows::getPeriodUtilMinute(const Held &) { return (secSinceBoot / 10) % CHANNEL_UTILIZATION_PERIODS; } -uint8_t AirTime::getPeriodUtilHour() +uint8_t AirTime::Windows::getPeriodUtilHour(const Held &) { return (secSinceBoot / 60) % MINUTES_IN_HOUR; } -void AirTime::airtimeRotatePeriod() -{ - // Preserve the public helper while keeping all rotation logic in one monotonic-time path. - syncNow(); -} - -void AirTime::syncNow() +void AirTime::Windows::syncNow(const Held &) { // Monotonic uptime, not RTC/network time: a user, GPS, or NTP clock change must not move // airtime accounting. Pure read; the main loop publishes the wrap carry it derives from. @@ -69,13 +72,8 @@ void AirTime::syncNow() memset(this->airtimes.periodTX, 0, sizeof(this->airtimes.periodTX)); memset(this->airtimes.periodRX, 0, sizeof(this->airtimes.periodRX)); memset(this->airtimes.periodRX_ALL, 0, sizeof(this->airtimes.periodRX_ALL)); - memset(air_period_tx, 0, sizeof(air_period_tx)); - memset(air_period_rx, 0, sizeof(air_period_rx)); this->secSinceBoot = nowSecs; - this->lastUtilPeriod = this->getPeriodUtilMinute(); - this->lastUtilPeriodTX = this->getPeriodUtilHour(); - this->airtimes.lastPeriodIndex = this->currentPeriodIndex(); firstTime = false; return; } @@ -94,27 +92,22 @@ void AirTime::syncNow() memset(this->airtimes.periodTX, 0, sizeof(this->airtimes.periodTX)); memset(this->airtimes.periodRX, 0, sizeof(this->airtimes.periodRX)); memset(this->airtimes.periodRX_ALL, 0, sizeof(this->airtimes.periodRX_ALL)); - memset(air_period_tx, 0, sizeof(air_period_tx)); - memset(air_period_rx, 0, sizeof(air_period_rx)); } else { - while (elapsedAirtimePeriods-- > 0) { - LOG_DEBUG("Rotate airtimes to a new period = %u", this->currentPeriodIndex()); + // Hand the count to runOnce() rather than tracing each crossing here: this runs under + // the lock, and a UART write would stall every other caller waiting on it. + this->rotationsPendingLog += elapsedAirtimePeriods; + for (uint32_t h = 0; h < elapsedAirtimePeriods; h++) { for (int i = PERIODS_TO_LOG - 2; i >= 0; --i) { this->airtimes.periodTX[i + 1] = this->airtimes.periodTX[i]; this->airtimes.periodRX[i + 1] = this->airtimes.periodRX[i]; this->airtimes.periodRX_ALL[i + 1] = this->airtimes.periodRX_ALL[i]; - air_period_tx[i + 1] = this->airtimes.periodTX[i]; - air_period_rx[i + 1] = this->airtimes.periodRX[i]; } this->airtimes.periodTX[0] = 0; this->airtimes.periodRX[0] = 0; this->airtimes.periodRX_ALL[0] = 0; - air_period_tx[0] = 0; - air_period_rx[0] = 0; } } - this->airtimes.lastPeriodIndex = this->currentPeriodIndex(); // Channel utilization is a rolling 60-second view split into six 10-second buckets. // Clear every bucket crossed while asleep so old airtime decays by real elapsed time. @@ -126,7 +119,6 @@ void AirTime::syncNow() this->channelUtilization[((oldSecSinceBoot / 10) + i) % CHANNEL_UTILIZATION_PERIODS] = 0; } } - this->lastUtilPeriod = this->getPeriodUtilMinute(); // TX utilization is a rolling 60-minute view used by duty-cycle checks. uint32_t elapsedUtilTXPeriods = (this->secSinceBoot / 60) - (oldSecSinceBoot / 60); @@ -137,45 +129,35 @@ void AirTime::syncNow() this->utilizationTX[((oldSecSinceBoot / 60) + i) % MINUTES_IN_HOUR] = 0; } } - this->lastUtilPeriodTX = this->getPeriodUtilHour(); } -uint32_t *AirTime::airtimeReport(reportTypes reportType) +bool AirTime::Windows::airtimeReport(reportTypes reportType, uint32_t *out, size_t count, const Held &held) { + if (!out || count > PERIODS_TO_LOG) + return false; + // Reports may be requested before runOnce() executes after wake. - syncNow(); + syncNow(held); + const uint32_t *src = nullptr; if (reportType == TX_LOG) { - return this->airtimes.periodTX; + src = this->airtimes.periodTX; } else if (reportType == RX_LOG) { - return this->airtimes.periodRX; + src = this->airtimes.periodRX; } else if (reportType == RX_ALL_LOG) { - return this->airtimes.periodRX_ALL; + src = this->airtimes.periodRX_ALL; } - return 0; + if (!src) + return false; + + memcpy(out, src, count * sizeof(*out)); + return true; } -uint8_t AirTime::getPeriodsToLog() -{ - return PERIODS_TO_LOG; -} - -uint32_t AirTime::getSecondsPerPeriod() -{ - return SECONDS_PER_PERIOD; -} - -uint32_t AirTime::getSecondsSinceBoot() -{ - // Keep HTTP/debug reporting aligned with the same monotonic clock used by the buckets. - syncNow(); - return this->secSinceBoot; -} - -float AirTime::channelUtilizationPercent() +float AirTime::Windows::channelUtilizationPercent(const Held &held) { // Gate decisions should see buckets that have decayed across light-sleep time. - syncNow(); + syncNow(held); uint32_t sum = 0; for (uint32_t i = 0; i < CHANNEL_UTILIZATION_PERIODS; i++) { @@ -185,10 +167,10 @@ float AirTime::channelUtilizationPercent() return (float(sum) / float(CHANNEL_UTILIZATION_PERIODS * 10 * 1000)) * 100; } -float AirTime::utilizationTXPercent() +float AirTime::Windows::utilizationTXPercent(const Held &held) { // Duty-cycle checks use this value, so keep it current even outside the periodic thread. - syncNow(); + syncNow(held); uint32_t sum = 0; for (uint32_t i = 0; i < MINUTES_IN_HOUR; i++) { @@ -198,33 +180,9 @@ float AirTime::utilizationTXPercent() return (float(sum) / float(MS_IN_HOUR)) * 100; } -bool AirTime::isTxAllowedChannelUtil(bool polite) -{ - uint8_t percentage = (polite ? polite_channel_util_percent : max_channel_util_percent); - if (channelUtilizationPercent() < percentage) { - return true; - } else { - LOG_WARN("Ch. util >%d%%. Skip send", percentage); - return false; - } -} - -bool AirTime::isTxAllowedAirUtil() -{ - float effectiveDutyCycle = getEffectiveDutyCycle(); - if (!config.lora.override_duty_cycle && effectiveDutyCycle < 100) { - if (utilizationTXPercent() < effectiveDutyCycle * polite_duty_cycle_percent / 100) { - return true; - } else { - LOG_WARN("TX air util. >%f%%. Skip send", effectiveDutyCycle * polite_duty_cycle_percent / 100); - return false; - } - } - return true; -} - -// Get the amount of minutes we have to be silent before we can send again -uint8_t AirTime::getSilentMinutes(float txPercent, float dutyCycle) +// Minutes we must be silent before sending again. Does not sync, and walks the ring as if the index +// were an age; both are wrong and both are pinned by characterisation tests. See airtime.h's TODO. +uint8_t AirTime::Windows::getSilentMinutes(float txPercent, float dutyCycle, const Held &) { float newTxPercent = txPercent; for (int8_t i = MINUTES_IN_HOUR - 1; i >= 0; --i) { @@ -236,10 +194,119 @@ uint8_t AirTime::getSilentMinutes(float txPercent, float dutyCycle) return MINUTES_IN_HOUR; } -AirTime::AirTime() : concurrency::OSThread("AirTime"), airtimes({}) {} +// --- the locking shell -------------------------------------------------------------------------- +// Each takes the lock exactly once and delegates. Nothing below calls another method on `this`. + +void AirTime::logAirtime(reportTypes reportType, uint32_t airtime_ms) +{ + { + Held held(this); + w.logAirtime(reportType, airtime_ms, held); + } + + // Outside the lock: DEBUG_PORT.log() blocks on a UART write, and `lock` is a plain binary + // semaphore with no priority inheritance, so holding it here would stall the radio thread. + if (reportType == TX_LOG) { + LOG_DEBUG("Packet TX: %ums", airtime_ms); + } else if (reportType == RX_LOG) { + LOG_DEBUG("Packet RX: %ums", airtime_ms); + } else if (reportType == RX_ALL_LOG) { + LOG_DEBUG("Packet RX (noise?) : %ums", airtime_ms); + } +} + +void AirTime::airtimeRotatePeriod() +{ + // Preserve the public helper while keeping all rotation logic in one monotonic-time path. + Held held(this); + w.syncNow(held); +} + +bool AirTime::airtimeReport(reportTypes reportType, uint32_t *out, size_t count) +{ + Held held(this); + return w.airtimeReport(reportType, out, count, held); +} + +uint32_t AirTime::getSecondsSinceBoot() +{ + // Keep HTTP/debug reporting aligned with the same monotonic clock used by the buckets. + Held held(this); + w.syncNow(held); + return w.secSinceBoot; +} + +float AirTime::channelUtilizationPercent() +{ + Held held(this); + return w.channelUtilizationPercent(held); +} + +float AirTime::utilizationTXPercent() +{ + Held held(this); + return w.utilizationTXPercent(held); +} + +// These lock like everything else, because they call the core rather than the public accessors. +// Both read under the lock and warn after it, for the reason logAirtime() does. +bool AirTime::isTxAllowedChannelUtil(bool polite) +{ + uint8_t percentage = (polite ? polite_channel_util_percent : max_channel_util_percent); + float utilization; + { + Held held(this); + utilization = w.channelUtilizationPercent(held); + } + + if (utilization < percentage) + return true; + LOG_WARN("Ch. util >%d%%. Skip send", percentage); + return false; +} + +bool AirTime::isTxAllowedAirUtil() +{ + float effectiveDutyCycle = getEffectiveDutyCycle(); + if (!config.lora.override_duty_cycle && effectiveDutyCycle < 100) { + float limit = effectiveDutyCycle * polite_duty_cycle_percent / 100; + float utilization; + { + Held held(this); + utilization = w.utilizationTXPercent(held); + } + + if (utilization < limit) + return true; + LOG_WARN("TX air util. >%f%%. Skip send", limit); + return false; + } + return true; +} + +uint8_t AirTime::getSilentMinutes(float txPercent, float dutyCycle) +{ + Held held(this); + return w.getSilentMinutes(txPercent, dutyCycle, held); +} + +AirTime::AirTime() : concurrency::OSThread("AirTime") {} int32_t AirTime::runOnce() { - syncNow(); + uint32_t rotations; + { + Held held(this); + w.syncNow(held); + rotations = w.rotationsPendingLog; + w.rotationsPendingLog = 0; + } + + // Outside the lock, for the reason logAirtime() gives. Any caller can cross an hour, but only + // this thread reports it, so a crossing raised elsewhere is traced at most one tick late. + if (rotations > 0) { + LOG_DEBUG("Rotate airtimes, crossed %u hour(s)", rotations); + } + return (1000 * 1); } diff --git a/src/airtime.h b/src/airtime.h index 39c1d3e03d..b1e1172a76 100644 --- a/src/airtime.h +++ b/src/airtime.h @@ -1,28 +1,79 @@ #pragma once #include "MeshRadio.h" +#include "concurrency/Lock.h" +#include "concurrency/LockGuard.h" #include "concurrency/OSThread.h" #include "configuration.h" #include #include /* - TX_LOG - Time on air this device has transmitted + AirTime records how long the radio was busy and turns that into the two + percentages the transmit gates and DeviceMetrics use. - RX_LOG - Time on air used by valid and routable mesh packets, does not include - TX air time + INPUTS - four events change this class's state: - RX_ALL_LOG - Time of all received lora packets. This includes packets that are not - for meshtastic devices. Does not include TX air time. + logAirtime(TX_LOG, ms) one per completed transmission, ours and relayed + logAirtime(RX_LOG, ms) one per well-formed reception. The interface is + promiscuous: this counts packets not addressed + to us, and every duplicate relay copy. + logAirtime(RX_ALL_LOG, ms) one per reception that could NOT be parsed - + failed CRC, truncated, region unset, collision + elapsed time Time::getUptimeSecs(), read by syncNow() on + every public entry point. The only input that + removes airtime. - Example analytics: + RX_LOG and RX_ALL_LOG are DISJOINT, and a reception logs AT MOST one of them. + RX_ALL_LOG is unparseable airtime, not a superset of RX_LOG, so the total is + TX + RX + RX_ALL - but it under-counts: five drop paths log neither. A packet + with from == 0 returns unlogged from handleReceiveInterrupt(), unlike every + neighbouring drop, and SimRadio drops a collision during transmission plus + three allocation failures. Pre-existing; see the TODO below. - TX_LOG + RX_LOG = Total air time for a particular meshtastic channel. + OUTPUTS: - TX_LOG + RX_ALL_LOG = Total air time for a particular meshtastic channel, including - other lora radios. + channelUtilizationPercent() % of the last 60s busy, all three types + utilizationTXPercent() % of the last hour we transmitted + isTxAllowedChannelUtil() gate on the former, 40% or 25% "polite" + isTxAllowedAirUtil() gate on the latter, at HALF the duty cycle + getSilentMinutes() minutes until the TX figure clears a limit. + Feeds a log line and a client notification; it + gates nothing. + airtimeReport() 8 x 1h of raw ms per type, for the HTTP report + getSecondsSinceBoot() the clock the buckets are keyed to - RX_ALL_LOG - RX_LOG = Other lora radios on our frequency channel. + The three thresholds are hard-coded members with no config binding. + + STORAGE - two orderings, easily confused: + + channelUtilization[], utilizationTX[] + Modular rings indexed by absolute uptime phase, (secs / p) % N. The + index is NOT an age; the oldest bucket is (current + 1) % N. Crossing + into a bucket zeroes it. + + airtimes.period{TX,RX,RX_ALL}[] + Shift-ordered, slot 0 newest, index IS age in hours. Slot 0 is a partial + hour; normalise it by getSecondsSinceBoot() % getSecondsPerPeriod(). + + The percentages measure wall time, not time awake. A light-sleeping node still + hears traffic, and reporting over observed time would make two nodes' + broadcast readings incomparable. + + channelUtilization spans 60s but reaches the mesh at >= 1h cadence, so remote + readings are a snapshot rather than an average. Its contention-window consumer + moves in 20-percentage-point steps, map(chanutil, 0, 100, CWmin, CWmax), so + small errors never reach the backoff. + + Rotation happens on access, not on the scheduler tick: every public method + calls syncNow() first and runOnce() only guarantees once a second. A + scheduler-driven window stops advancing during light sleep. Enforced by + test_channel_utilization_is_independent_of_scheduler_rate. + + TODO: airtime accuracy. Four known defects remain - the quantised denominator, + its sawtooth, whole-packet attribution to the completing bucket, and + getSilentMinutes() reading a modular ring as if the index were an age. Each is + pinned by a test tagged CHARACTERISATION in test/test_airtime. */ #define CHANNEL_UTILIZATION_PERIODS 6 @@ -35,16 +86,42 @@ enum reportTypes { TX_LOG, RX_LOG, RX_ALL_LOG }; -void logAirtime(reportTypes reportType, uint32_t airtime_ms); +// Arms AirTime's nested-take check. Sound only where the lock is not a real lock: the check runs +// before the take, because a nested take blocks forever and a later check would never run - so +// under preemption it would false-positive on legitimate contention and race on its own write. +// Portduino is where it earns its keep anyway; there Lock::lock() is empty, so a nested take +// succeeds silently and nothing else would notice. On an on-target test build the nesting it +// catches shows up as a hang instead. Test builds only: nothing in this tree defines DEBUG or +// NDEBUG, so either spelling would ship an abort() to every board, and nrf52_promicro_diy_tcxo +// has no flash for it. +#if defined(PIO_UNIT_TESTING) && !defined(HAS_FREE_RTOS) +#define AIRTIME_REENTRY_CHECK +#endif -uint32_t *airtimeReport(reportTypes reportType); - -// Not thread-safe: everything but getPeriodsToLog()/getSecondsPerPeriod() either rotates the -// windows via syncNow() or reads the buckets. Current callers are all on the OSThread scheduler - -// RadioLibInterface/SimRadio, RadioInterface, Router, DeviceTelemetry, ContentHandler, and the -// screen renderers. New callers must be on that thread too, or this needs a lock. -// TODO: airtime lock-guarding - serialise the above behind a lock so the contract is enforced -// rather than documented. Kept out of this PR: it is a separate concern from millis() rollover. +// Serialised behind `lock` because two FreeRTOS tasks genuinely reach this class at once on nRF52. +// NRF52Bluetooth registers its ToRadio write callback with defer == false, so a phone's packet runs +// PhoneAPI::handleToRadio -> MeshService::sendToMesh -> Router::send on the Bluefruit BLE task, +// which reads utilizationTXPercent() and getSilentMinutes() while loopTask may be inside +// logAirtime() from a reception. That is an unsynchronised read-modify-write of utilizationTX[] and +// secSinceBoot against a summing read. ESP32 hands BLE work to the main task and does not have it. +// +// Two mechanisms keep it serialised: +// +// - a lock-free inner core (Windows) holds all state and all logic. It has no lock member, and +// must never reach one through the global `airTime` - `airTime->anyPublicMethod()` from inside +// a Windows method would take a second Held and hang, because concurrency::Lock is a +// non-recursive binary semaphore taken with portMAX_DELAY. Nothing does this today; the +// AIRTIME_REENTRY_CHECK assert is the backstop, and it only builds on host test builds. +// - a private Held token takes the lock in its constructor and is the only thing that satisfies a +// core method's `const Held &`, so the lock cannot be forgotten. +// +// Every public method takes the lock exactly once and delegates, with two exceptions: the two +// constexpr accessors below touch no state and take none, and isTxAllowedAirUtil() takes it zero or +// one times, depending on whether the duty-cycle branch is entered at all. Nothing inside locks - +// that includes isTxAllowed*(), which call the core rather than the public accessors. +// +// A new write-path helper belongs to Windows or is a free function, never a method on AirTime: an +// AirTime method locks, and logAirtime() would call it while already holding the lock. class AirTime : private concurrency::OSThread { @@ -55,43 +132,85 @@ class AirTime : private concurrency::OSThread float channelUtilizationPercent(); float utilizationTXPercent(); - float UtilizationPercentTX(); - uint32_t channelUtilization[CHANNEL_UTILIZATION_PERIODS] = {0}; - uint32_t utilizationTX[MINUTES_IN_HOUR] = {0}; - + /// Compatibility shim: no caller in the tree, kept for out-of-tree ones. void airtimeRotatePeriod(); - uint8_t getPeriodsToLog(); - uint32_t getSecondsPerPeriod(); + /// Constants, not state: no lock, and usable where a constant expression is required so a + /// caller's buffer and the count it passes to airtimeReport() cannot drift apart. + static constexpr uint8_t getPeriodsToLog() { return PERIODS_TO_LOG; } + static constexpr uint32_t getSecondsPerPeriod() { return SECONDS_PER_PERIOD; } uint32_t getSecondsSinceBoot(); - uint32_t *airtimeReport(reportTypes reportType); + /// Copies `count` buckets into `out`, newest first. Copies rather than returning the array so a + /// caller cannot hold a handle to buckets that every other entry point rotates underneath it. + /// False if `out` is null, `count` exceeds the log depth, or the report type is unknown. + bool airtimeReport(reportTypes reportType, uint32_t *out, size_t count); uint8_t getSilentMinutes(float txPercent, float dutyCycle); bool isTxAllowedChannelUtil(bool polite = false); bool isTxAllowedAirUtil(); private: - bool firstTime = true; - uint8_t lastUtilPeriod = 0; - uint8_t lastUtilPeriodTX = 0; - // Time::getUptimeSecs() as of the last syncNow(); the gap since is what the windows rotate by, - // so they stay correct even if the scheduler was paused by light sleep. - uint32_t secSinceBoot = 0; + concurrency::Lock lock; + +#ifdef AIRTIME_REENTRY_CHECK + // Set for the lifetime of a Held and checked before the lock is taken, so a nested take is + // reported rather than hung at. See the macro's definition for why it is host-only. + bool reentryFlag = false; +#endif + + /// Takes `lock` for its lifetime and doubles as proof that it is held. Only AirTime can + /// construct one, so a core method taking `const Held &` cannot be called without the lock. + /// A bare LockGuard would not do: it proves only that *some* lock is held. + class Held + { + public: + explicit Held(AirTime *a) : owner(armReentryCheck(a)), guard(&a->lock) {} + ~Held(); + Held(const Held &) = delete; + Held &operator=(const Held &) = delete; + + private: + static AirTime *armReentryCheck(AirTime *a); + AirTime *owner; // declared first, so its initialiser runs before the lock is taken + concurrency::LockGuard guard; + }; + + /// All state, all logic, no lock. Cannot take one, so cannot nest. + struct Windows { + bool firstTime = true; + // Time::getUptimeSecs() as of the last syncNow(). The windows rotate by the gap since, so + // they stay correct across a paused scheduler. + uint32_t secSinceBoot = 0; + + // Modular rings: index is absolute phase, (uptime secs / period) % N, never age. + uint32_t channelUtilization[CHANNEL_UTILIZATION_PERIODS] = {0}; // 6 x 10s + uint32_t utilizationTX[MINUTES_IN_HOUR] = {0}; // 60 x 60s, our TX only + + // Hour crossings rotated but not yet traced. The core cannot log its own rotations: it + // only ever runs under the lock, and DEBUG_PORT.log() blocks on a UART write. runOnce() + // drains this and logs after releasing, so the trace costs the lock nothing. + uint32_t rotationsPendingLog = 0; + + // Shift-ordered, unlike the rings above: slot 0 is the newest hour and the index is age. + struct airtimeStruct { + uint32_t periodTX[PERIODS_TO_LOG] = {0}; // AirTime transmitted + uint32_t periodRX[PERIODS_TO_LOG] = {0}; // AirTime received and repeated (valid mesh packets) + uint32_t periodRX_ALL[PERIODS_TO_LOG] = {0}; // AirTime received regardless of validity. May be noise. + } airtimes; + + void logAirtime(reportTypes reportType, uint32_t airtime_ms, const Held &); + float channelUtilizationPercent(const Held &); + float utilizationTXPercent(const Held &); + bool airtimeReport(reportTypes reportType, uint32_t *out, size_t count, const Held &); + uint8_t getSilentMinutes(float txPercent, float dutyCycle, const Held &); + uint8_t getPeriodUtilMinute(const Held &); + uint8_t getPeriodUtilHour(const Held &); + // Advance rolling airtime windows from monotonic uptime, not from runOnce() calls. + void syncNow(const Held &); + } w; + uint8_t max_channel_util_percent = 40; uint8_t polite_channel_util_percent = 25; uint8_t polite_duty_cycle_percent = 50; // half of Duty Cycle allowance is ok for metadata - struct airtimeStruct { - uint32_t periodTX[PERIODS_TO_LOG]; // AirTime transmitted - uint32_t periodRX[PERIODS_TO_LOG]; // AirTime received and repeated (Only valid mesh packets) - uint32_t periodRX_ALL[PERIODS_TO_LOG]; // AirTime received regardless of valid mesh packet. Could include noise. - uint8_t lastPeriodIndex; - } airtimes; - - uint8_t getPeriodUtilMinute(); - uint8_t getPeriodUtilHour(); - uint8_t currentPeriodIndex(); - // Advance rolling airtime windows from monotonic uptime, not from runOnce() calls. - void syncNow(); - protected: virtual int32_t runOnce() override; }; diff --git a/src/mesh/NodeDB.cpp b/src/mesh/NodeDB.cpp index 699d2fab5e..6f87422f2c 100644 --- a/src/mesh/NodeDB.cpp +++ b/src/mesh/NodeDB.cpp @@ -3525,8 +3525,10 @@ void NodeDB::addFromContact(meshtastic_SharedContact contact) // last_heard will remain as-is (or remain 0 if this entry wasn't in the nodeDB). // If the protected cap refuses the favorite, fall back to a heard-now stamp so the // contact still isn't the first eviction victim. - if (!setProtectedFlag(info, NODEINFO_BITFIELD_IS_FAVORITE_MASK, true)) + if (!setProtectedFlag(info, NODEINFO_BITFIELD_IS_FAVORITE_MASK, true)) { + LOG_WARN(PROTECTED_CAP_WARN_FMT, "favorite", contact.node_num, MAX_NUM_NODES - 2); stampContactHeardNow(info); + } } // As the clients will begin sending the contact with DMs, we want to strictly check if the node is manually verified diff --git a/src/mesh/http/ContentHandler.cpp b/src/mesh/http/ContentHandler.cpp index 95712403ec..d6c4904b74 100644 --- a/src/mesh/http/ContentHandler.cpp +++ b/src/mesh/http/ContentHandler.cpp @@ -628,13 +628,18 @@ void handleReport(HTTPRequest *req, HTTPResponse *res) return s; }; - uint32_t *logArray; - logArray = airTime->airtimeReport(TX_LOG); - std::string txLog = arrayFromLog(logArray, airTime->getPeriodsToLog()); - logArray = airTime->airtimeReport(RX_LOG); - std::string rxLog = arrayFromLog(logArray, airTime->getPeriodsToLog()); - logArray = airTime->airtimeReport(RX_ALL_LOG); - std::string rxAllLog = arrayFromLog(logArray, airTime->getPeriodsToLog()); + // One constant sizes the buffer and the count, so they cannot drift. Buffer is per call, so a + // report that fails emits zeros rather than the previous type's data. + constexpr size_t periods = AirTime::getPeriodsToLog(); + auto reportFor = [&](reportTypes reportType) { + uint32_t logArray[periods] = {0}; + (void)airTime->airtimeReport(reportType, logArray, periods); + return arrayFromLog(logArray, (int)periods); + }; + + std::string txLog = reportFor(TX_LOG); + std::string rxLog = reportFor(RX_LOG); + std::string rxAllLog = reportFor(RX_ALL_LOG); String wifiIPString = WiFi.localIP().toString(); std::string wifiIP = wifiIPString.c_str(); diff --git a/src/platform/nrf52/main-nrf52.cpp b/src/platform/nrf52/main-nrf52.cpp index eb20844033..865e1c3633 100644 --- a/src/platform/nrf52/main-nrf52.cpp +++ b/src/platform/nrf52/main-nrf52.cpp @@ -1,3 +1,4 @@ +#include "UptimeClock.h" #include "configuration.h" #include "mesh/Throttle.h" #include @@ -296,7 +297,7 @@ void preFSBegin() if (!(NRF_POWER->RESETREAS == 0 && NRF_POWER->GPREGRET == NRF52_MAGIC_LFS_IS_CORRUPT)) return; NRF_POWER->GPREGRET = 0; - last_format_ms = millis(); + last_format_ms = Time::getMillis(); formatted_this_boot = true; InternalFS.format(); LOG_INFO("LittleFS format complete; restoring default settings"); @@ -309,8 +310,12 @@ extern "C" void lfs_assert(const char *reason) // minutes after each wrap. if (formatted_this_boot && Throttle::isWithinTimespanMs(last_format_ms, MULTIPLE_CORRUPTION_DELAY_MILLIS)) { RECORD_CRITICALERROR(meshtastic_CriticalErrorCode_FLASH_CORRUPTION_UNRECOVERABLE); - const long millis_remain = MULTIPLE_CORRUPTION_DELAY_MILLIS - (millis() - last_format_ms); - LOG_WARN("Pausing %d seconds to avoid wear on flash storage", millis_remain / 1000); + // Same clock Throttle just read, and clamped: the check above and a second, later read + // can straddle the backoff, which would wrap the remainder into a ~50-day delay(). + const uint32_t elapsed = Time::getMillis() - last_format_ms; + const uint32_t millis_remain = + elapsed < MULTIPLE_CORRUPTION_DELAY_MILLIS ? MULTIPLE_CORRUPTION_DELAY_MILLIS - elapsed : 0; + LOG_WARN("Pausing %u seconds to avoid wear on flash storage", millis_remain / 1000); delay(millis_remain); } LOG_INFO("Rebooting to format LittleFS"); diff --git a/test/test_airtime/test_main.cpp b/test/test_airtime/test_main.cpp index 97adeac0cb..6edab96fb3 100644 --- a/test/test_airtime/test_main.cpp +++ b/test/test_airtime/test_main.cpp @@ -6,21 +6,38 @@ // the rotation/decay math on top of that, including across the 32-bit millis() wrap. The wrap cases // therefore step the clock the way the main loop does - advance, then publish. #include "Arduino.h" +#include "MeshRadio.h" +#include "NodeDB.h" #include "TestUtil.h" #include "UptimeClock.h" #include "airtime.h" #include +#include #include +static meshtastic_Config_LoRaConfig_RegionCode savedRegion; +static meshtastic_Config_DeviceConfig_Role savedRole; +static bool savedOverrideDutyCycle; + void setUp(void) { // Absolute uptime assertions (e.g. getSecondsSinceBoot()) must not inherit wraps counted by // an earlier case that moved the test clock backwards via setTestMillis(). Time::resetMonotonicForTests(); + savedRegion = config.lora.region; + savedRole = config.device.role; + savedOverrideDutyCycle = config.lora.override_duty_cycle; } void tearDown(void) { Time::useRealClock(); // don't leak the fake clock into other suites + // Restore the duty-cycle globals here, not at the end of a test body: an assertion aborts the + // body via longjmp and would leak the region into every later case. initRegion() on the way + // out, because getEffectiveDutyCycle() dereferences myRegion. + config.lora.region = savedRegion; + config.device.role = savedRole; + config.lora.override_duty_cycle = savedOverrideDutyCycle; + initRegion(); } // --- first sync / immediate writes --- @@ -32,7 +49,9 @@ void test_logAirtime_writes_into_current_bucket_immediately() a.logAirtime(TX_LOG, 100); - TEST_ASSERT_EQUAL_UINT32(100, a.airtimeReport(TX_LOG)[0]); + uint32_t report[PERIODS_TO_LOG] = {0}; + TEST_ASSERT_TRUE(a.airtimeReport(TX_LOG, report, PERIODS_TO_LOG)); + TEST_ASSERT_EQUAL_UINT32(100, report[0]); } void test_getSecondsSinceBoot_tracks_elapsed_time() @@ -55,7 +74,8 @@ void test_period_rotates_after_one_hour() Time::advanceTestMillis(3600u * 1000u); // exactly one SECONDS_PER_PERIOD - uint32_t *report = a.airtimeReport(TX_LOG); + uint32_t report[PERIODS_TO_LOG] = {0}; + TEST_ASSERT_TRUE(a.airtimeReport(TX_LOG, report, PERIODS_TO_LOG)); TEST_ASSERT_EQUAL_UINT32(0, report[0]); // new period starts empty TEST_ASSERT_EQUAL_UINT32(500, report[1]); // old period shifted back one slot } @@ -70,7 +90,8 @@ void test_period_rotates_once_per_hour_crossed_while_asleep() Time::advanceTestMillis(3u * 3600u * 1000u); // 3 hours in one jump - uint32_t *report = a.airtimeReport(TX_LOG); + uint32_t report[PERIODS_TO_LOG] = {0}; + TEST_ASSERT_TRUE(a.airtimeReport(TX_LOG, report, PERIODS_TO_LOG)); TEST_ASSERT_EQUAL_UINT32(200, report[3]); TEST_ASSERT_EQUAL_UINT32(0, report[0]); TEST_ASSERT_EQUAL_UINT32(0, report[1]); @@ -87,7 +108,8 @@ void test_period_history_clears_when_asleep_longer_than_the_whole_log() Time::advanceTestMillis(9u * 3600u * 1000u); // 9 hours > PERIODS_TO_LOG (8) - uint32_t *report = a.airtimeReport(TX_LOG); + uint32_t report[PERIODS_TO_LOG] = {0}; + TEST_ASSERT_TRUE(a.airtimeReport(TX_LOG, report, PERIODS_TO_LOG)); for (uint8_t i = 0; i < a.getPeriodsToLog(); i++) { TEST_ASSERT_EQUAL_UINT32_MESSAGE(0, report[i], "stale history must be cleared, not rotated in"); } @@ -170,11 +192,1014 @@ void test_period_rotation_survives_millis_wrap() Time::advanceTestMillis(3600u * 1000u); // wraps partway through Time::serviceMonotonic(); - uint32_t *report = a.airtimeReport(TX_LOG); + uint32_t report[PERIODS_TO_LOG] = {0}; + TEST_ASSERT_TRUE(a.airtimeReport(TX_LOG, report, PERIODS_TO_LOG)); TEST_ASSERT_EQUAL_UINT32(0, report[0]); TEST_ASSERT_EQUAL_UINT32(777, report[1]); } +// --- report routing: which array each type feeds --- +// +// Asserted through the public API, not the bucket arrays: those are private. + +void test_tx_log_feeds_tx_report_and_tx_utilization() +{ + Time::setTestMillis(0); + AirTime a; + + a.logAirtime(TX_LOG, 6000); + + uint32_t report[PERIODS_TO_LOG] = {0}; + TEST_ASSERT_TRUE(a.airtimeReport(TX_LOG, report, PERIODS_TO_LOG)); + TEST_ASSERT_EQUAL_UINT32(6000, report[0]); + // TX is the only type that reaches all three stores. + TEST_ASSERT_TRUE(a.utilizationTXPercent() > 0.0f); + TEST_ASSERT_FLOAT_WITHIN(0.01f, 10.0f, a.channelUtilizationPercent()); +} + +// Duty cycle is about our own transmissions. Counting received airtime here would throttle a node +// for other people's traffic. +void test_rx_log_feeds_rx_report_but_not_tx_utilization() +{ + Time::setTestMillis(0); + AirTime a; + + a.logAirtime(RX_LOG, 6000); + + uint32_t report[PERIODS_TO_LOG] = {0}; + TEST_ASSERT_TRUE(a.airtimeReport(RX_LOG, report, PERIODS_TO_LOG)); + TEST_ASSERT_EQUAL_UINT32(6000, report[0]); + TEST_ASSERT_FLOAT_WITHIN(0.0001f, 0.0f, a.utilizationTXPercent()); + TEST_ASSERT_FLOAT_WITHIN(0.01f, 10.0f, a.channelUtilizationPercent()); +} + +void test_rx_all_log_feeds_only_the_noise_report() +{ + Time::setTestMillis(0); + AirTime a; + + a.logAirtime(RX_ALL_LOG, 6000); + + uint32_t report[PERIODS_TO_LOG] = {0}; + TEST_ASSERT_TRUE(a.airtimeReport(RX_ALL_LOG, report, PERIODS_TO_LOG)); + TEST_ASSERT_EQUAL_UINT32(6000, report[0]); + + TEST_ASSERT_TRUE(a.airtimeReport(TX_LOG, report, PERIODS_TO_LOG)); + TEST_ASSERT_EQUAL_UINT32(0, report[0]); + TEST_ASSERT_TRUE(a.airtimeReport(RX_LOG, report, PERIODS_TO_LOG)); + TEST_ASSERT_EQUAL_UINT32(0, report[0]); + TEST_ASSERT_FLOAT_WITHIN(0.0001f, 0.0f, a.utilizationTXPercent()); +} + +// The shared property: channel utilisation counts all airtime, ours and other people's. +void test_every_report_type_feeds_channel_utilization() +{ + const reportTypes types[] = {TX_LOG, RX_LOG, RX_ALL_LOG}; + for (uint8_t i = 0; i < 3; i++) { + Time::resetMonotonicForTests(); + Time::setTestMillis(0); + AirTime a; + + a.logAirtime(types[i], 6000); + + TEST_ASSERT_FLOAT_WITHIN_MESSAGE(0.01f, 10.0f, a.channelUtilizationPercent(), + "every report type must reach channelUtilization"); + } +} + +void test_report_types_do_not_cross_contaminate() +{ + Time::setTestMillis(0); + AirTime a; + + a.logAirtime(TX_LOG, 111); + + uint32_t report[PERIODS_TO_LOG] = {0}; + TEST_ASSERT_TRUE(a.airtimeReport(RX_LOG, report, PERIODS_TO_LOG)); + TEST_ASSERT_EQUAL_UINT32(0, report[0]); + TEST_ASSERT_TRUE(a.airtimeReport(RX_ALL_LOG, report, PERIODS_TO_LOG)); + TEST_ASSERT_EQUAL_UINT32(0, report[0]); +} + +// --- airtimeReport() contract --- + +void test_airtimeReport_rejects_a_null_buffer() +{ + Time::setTestMillis(0); + AirTime a; + + TEST_ASSERT_FALSE(a.airtimeReport(TX_LOG, nullptr, PERIODS_TO_LOG)); +} + +void test_airtimeReport_rejects_a_count_above_the_log_depth() +{ + Time::setTestMillis(0); + AirTime a; + + uint32_t report[PERIODS_TO_LOG + 1] = {0}; + TEST_ASSERT_FALSE(a.airtimeReport(TX_LOG, report, PERIODS_TO_LOG + 1)); +} + +void test_airtimeReport_accepts_a_partial_count() +{ + Time::setTestMillis(0); + AirTime a; + a.logAirtime(TX_LOG, 42); + + const uint32_t sentinel = 0xDEADBEEFu; + uint32_t report[PERIODS_TO_LOG]; + for (uint8_t i = 0; i < PERIODS_TO_LOG; i++) + report[i] = sentinel; + + TEST_ASSERT_TRUE(a.airtimeReport(TX_LOG, report, 2)); + + TEST_ASSERT_EQUAL_UINT32(42, report[0]); + TEST_ASSERT_EQUAL_UINT32(0, report[1]); + for (uint8_t i = 2; i < PERIODS_TO_LOG; i++) + TEST_ASSERT_EQUAL_UINT32_MESSAGE(sentinel, report[i], "a partial count must not write past it"); +} + +void test_airtimeReport_rejects_an_unknown_report_type() +{ + Time::setTestMillis(0); + AirTime a; + + uint32_t report[PERIODS_TO_LOG] = {0}; + TEST_ASSERT_FALSE(a.airtimeReport(static_cast(99), report, PERIODS_TO_LOG)); +} + +// The regression guard for the copy-out: if anyone reintroduces the array-returning form, the +// caller's buffer starts tracking the live buckets and this fails. +void test_airtimeReport_returns_a_snapshot_not_an_alias() +{ + Time::setTestMillis(0); + AirTime a; + a.logAirtime(TX_LOG, 100); + + uint32_t report[PERIODS_TO_LOG] = {0}; + TEST_ASSERT_TRUE(a.airtimeReport(TX_LOG, report, PERIODS_TO_LOG)); + TEST_ASSERT_EQUAL_UINT32(100, report[0]); + + a.logAirtime(TX_LOG, 900); + + TEST_ASSERT_EQUAL_UINT32_MESSAGE(100, report[0], "the copy must not follow the live bucket"); +} + +// --- storage conventions --- +// +// Two orderings: the report arrays are shift-ordered (slot 0 newest); channelUtilization and +// utilizationTX are modular rings indexed by uptime phase. Reading one as the other is a defect. + +void test_report_arrays_are_shift_ordered_slot_zero_newest() +{ + Time::setTestMillis(0); + AirTime a; + + a.logAirtime(TX_LOG, 100); // oldest + Time::advanceTestMillis(3600u * 1000u); + a.logAirtime(TX_LOG, 200); + Time::advanceTestMillis(3600u * 1000u); + a.logAirtime(TX_LOG, 300); // newest + + uint32_t report[PERIODS_TO_LOG] = {0}; + TEST_ASSERT_TRUE(a.airtimeReport(TX_LOG, report, PERIODS_TO_LOG)); + TEST_ASSERT_EQUAL_UINT32_MESSAGE(300, report[0], "slot 0 is the newest hour"); + TEST_ASSERT_EQUAL_UINT32(200, report[1]); + TEST_ASSERT_EQUAL_UINT32_MESSAGE(100, report[2], "index is age in hours, not ring phase"); +} + +// Slot 0 covers only the time since the last rotation; treating it as a whole hour under-reports. +// getSecondsSinceBoot() % getSecondsPerPeriod() recovers the elapsed part. +void test_report_slot_zero_is_a_partial_hour() +{ + Time::setTestMillis(0); + AirTime a; + a.logAirtime(TX_LOG, 100); + + Time::advanceTestMillis(3600u * 1000u); // rotate; slot 0 is now brand new + Time::advanceTestMillis(120u * 1000u); // and 120s into its hour + a.logAirtime(TX_LOG, 250); + + uint32_t report[PERIODS_TO_LOG] = {0}; + TEST_ASSERT_TRUE(a.airtimeReport(TX_LOG, report, PERIODS_TO_LOG)); + TEST_ASSERT_EQUAL_UINT32_MESSAGE(250, report[0], "slot 0 holds only airtime since the boundary"); + TEST_ASSERT_EQUAL_UINT32(100, report[1]); + + const uint32_t elapsedInSlotZero = a.getSecondsSinceBoot() % a.getSecondsPerPeriod(); + TEST_ASSERT_EQUAL_UINT32_MESSAGE(120, elapsedInSlotZero, "the partial-hour phase must be recoverable"); +} + +// --- first sync and seeding --- + +// The firstTime branch seeds secSinceBoot from the clock; seeding 0 would rotate 500s of empty +// windows through on first access. +void test_first_sync_seeds_from_current_uptime_not_zero() +{ + Time::setTestMillis(500u * 1000u); + AirTime a; + + TEST_ASSERT_EQUAL_UINT32(500, a.getSecondsSinceBoot()); + + a.logAirtime(RX_LOG, 6000); + TEST_ASSERT_FLOAT_WITHIN_MESSAGE(0.01f, 10.0f, a.channelUtilizationPercent(), + "no phantom decay from the pre-construction uptime"); +} + +void test_first_sync_zeroes_every_window() +{ + Time::setTestMillis(1234u * 1000u); + AirTime a; + + uint32_t report[PERIODS_TO_LOG] = {0}; + const reportTypes types[] = {TX_LOG, RX_LOG, RX_ALL_LOG}; + for (uint8_t t = 0; t < 3; t++) { + TEST_ASSERT_TRUE(a.airtimeReport(types[t], report, PERIODS_TO_LOG)); + for (uint8_t i = 0; i < PERIODS_TO_LOG; i++) + TEST_ASSERT_EQUAL_UINT32(0, report[i]); + } + TEST_ASSERT_FLOAT_WITHIN(0.0001f, 0.0f, a.channelUtilizationPercent()); + TEST_ASSERT_FLOAT_WITHIN(0.0001f, 0.0f, a.utilizationTXPercent()); +} + +void test_late_construction_does_not_backdate_airtime() +{ + Time::setTestMillis(7200u * 1000u); // two hours of uptime before AirTime exists + AirTime a; + + a.logAirtime(TX_LOG, 400); + + uint32_t report[PERIODS_TO_LOG] = {0}; + TEST_ASSERT_TRUE(a.airtimeReport(TX_LOG, report, PERIODS_TO_LOG)); + TEST_ASSERT_EQUAL_UINT32_MESSAGE(400, report[0], "airtime belongs to the current bucket, not a backdated one"); + for (uint8_t i = 1; i < PERIODS_TO_LOG; i++) + TEST_ASSERT_EQUAL_UINT32(0, report[i]); +} + +// --- sync idempotency --- + +void test_repeated_sync_within_one_second_does_not_rotate() +{ + Time::setTestMillis(0); + AirTime a; + a.logAirtime(RX_LOG, 6000); + + Time::advanceTestMillis(500); // sub-second: the nowSecs == secSinceBoot early return + for (uint8_t i = 0; i < 5; i++) { + (void)a.channelUtilizationPercent(); + (void)a.getSecondsSinceBoot(); + } + + TEST_ASSERT_FLOAT_WITHIN(0.01f, 10.0f, a.channelUtilizationPercent()); +} + +// Every public entry point syncs. Calling several in the same interval must not compound the +// rotation: two instances see identical wall time and airtime, differing only in how many entry +// points were called. +void test_rotation_is_once_per_second_regardless_of_entry_point() +{ + Time::setTestMillis(0); + AirTime oneEntryPoint; + AirTime everyEntryPoint; + + oneEntryPoint.logAirtime(RX_LOG, 6000); + everyEntryPoint.logAirtime(RX_LOG, 6000); + + Time::advanceTestMillis(20u * 1000u); // two 10s buckets crossed + + uint32_t scratch[PERIODS_TO_LOG] = {0}; + (void)everyEntryPoint.getSecondsSinceBoot(); + (void)everyEntryPoint.utilizationTXPercent(); + everyEntryPoint.airtimeRotatePeriod(); + (void)everyEntryPoint.airtimeReport(TX_LOG, scratch, PERIODS_TO_LOG); + (void)everyEntryPoint.isTxAllowedChannelUtil(); + + TEST_ASSERT_FLOAT_WITHIN_MESSAGE(0.01f, oneEntryPoint.channelUtilizationPercent(), + everyEntryPoint.channelUtilizationPercent(), + "rotation must be driven by the clock, not by the call count"); +} + +void test_period_constants_are_stable() +{ + Time::setTestMillis(0); + AirTime a; + + // Public API: ContentHandler sizes its buffer from getPeriodsToLog(). + TEST_ASSERT_EQUAL_UINT8(8, a.getPeriodsToLog()); + TEST_ASSERT_EQUAL_UINT32(3600, a.getSecondsPerPeriod()); + TEST_ASSERT_EQUAL_UINT8_MESSAGE(PERIODS_TO_LOG, a.getPeriodsToLog(), "the accessor and the macro must agree"); +} + +// ============================================================================ +// Window decay, gates, and sleep behaviour. Three kinds of test: +// +// invariant - must hold now and forever; any failure is a bug +// boundary - pins an off-by-one a refactor would silently move +// CHARACTERISATION - encodes today's wrong number. Replace it when the defect +// it describes is fixed; the tag is greppable. +// ============================================================================ + +// --- the oracle ------------------------------------------------------------- +// +// The definition the buckets approximate: airtime physically on air inside +// (now - window, now]. Assert against this rather than hand-worked constants. +// A packet is stamped with its END time, as completeSending() has it; the +// start is end - airtime. + +struct AirtimeEvent { + uint64_t endMs; + uint32_t airtimeMs; +}; + +static float expectedUtilisation(const AirtimeEvent *ev, size_t n, uint64_t nowMs, uint32_t windowMs) +{ + const uint64_t lo = (nowMs > windowMs) ? (nowMs - windowMs) : 0; + uint64_t busy = 0; + for (size_t i = 0; i < n; i++) { + const uint64_t start = (ev[i].airtimeMs < ev[i].endMs) ? (ev[i].endMs - ev[i].airtimeMs) : 0; + const uint64_t from = start > lo ? start : lo; + const uint64_t to = ev[i].endMs < nowMs ? ev[i].endMs : nowMs; + if (to > from) + busy += (to - from); + } + return (float)busy / (float)windowMs * 100.0f; +} + +// Steady load helper: logs `msPerSecond` of airtime once a second for `seconds`, +// leaving the clock exactly `seconds` later than it started. +static void logEverySecond(AirTime &a, uint32_t seconds, uint32_t msPerSecond, reportTypes type = RX_LOG) +{ + for (uint32_t i = 0; i < seconds; i++) { + a.logAirtime(type, msPerSecond); + Time::advanceTestMillis(1000); + } +} + +static char g_msg[160]; // Unity messages must outlive the assert + +// --- hourly period rotation: boundaries the first three tests miss ----------- + +// The shift loop runs PERIODS_TO_LOG-2 -> 0; an off-by-one resurrects hour-old +// data into slot 0 instead of dropping it. +void test_oldest_period_falls_off_the_end() +{ + Time::setTestMillis(0); + AirTime a; + + for (uint32_t h = 0; h < PERIODS_TO_LOG; h++) { + a.logAirtime(TX_LOG, (h + 1) * 100); + Time::advanceTestMillis(3600u * 1000u); + } + + uint32_t report[PERIODS_TO_LOG] = {0}; + TEST_ASSERT_TRUE(a.airtimeReport(TX_LOG, report, PERIODS_TO_LOG)); + // Slot 0 is the (empty) current hour; 800 was the newest logged, 100 the oldest. + TEST_ASSERT_EQUAL_UINT32(0, report[0]); + TEST_ASSERT_EQUAL_UINT32(800, report[1]); + TEST_ASSERT_EQUAL_UINT32_MESSAGE(200, report[7], "the oldest survivor sits in the last slot"); + + Time::advanceTestMillis(3600u * 1000u); + TEST_ASSERT_TRUE(a.airtimeReport(TX_LOG, report, PERIODS_TO_LOG)); + TEST_ASSERT_EQUAL_UINT32_MESSAGE(300, report[7], "one more hour drops 200 off the end"); + for (uint8_t i = 0; i < PERIODS_TO_LOG; i++) + TEST_ASSERT_NOT_EQUAL_UINT32_MESSAGE(200, report[i], "dropped data must not wrap back in"); +} + +void test_period_boundary_is_exact_at_one_hour() +{ + Time::setTestMillis(0); + AirTime a; + a.logAirtime(TX_LOG, 500); + + Time::advanceTestMillis(3599u * 1000u); + uint32_t report[PERIODS_TO_LOG] = {0}; + TEST_ASSERT_TRUE(a.airtimeReport(TX_LOG, report, PERIODS_TO_LOG)); + TEST_ASSERT_EQUAL_UINT32_MESSAGE(500, report[0], "3599s must not rotate"); + + Time::advanceTestMillis(1000); + TEST_ASSERT_TRUE(a.airtimeReport(TX_LOG, report, PERIODS_TO_LOG)); + TEST_ASSERT_EQUAL_UINT32_MESSAGE(0, report[0], "3600s rotates exactly once"); + TEST_ASSERT_EQUAL_UINT32(500, report[1]); +} + +// The >= is the seam between "rotate N times" and "wipe the lot". +void test_period_clear_boundary_is_exactly_the_log_depth() +{ + { + Time::setTestMillis(0); + AirTime shift; + shift.logAirtime(TX_LOG, 500); + Time::advanceTestMillis(7u * 3600u * 1000u); // 7 h: shift branch + uint32_t report[PERIODS_TO_LOG] = {0}; + TEST_ASSERT_TRUE(shift.airtimeReport(TX_LOG, report, PERIODS_TO_LOG)); + TEST_ASSERT_EQUAL_UINT32_MESSAGE(500, report[7], "7h shifts to the last slot"); + } + { + Time::resetMonotonicForTests(); + Time::setTestMillis(0); + AirTime wipe; + wipe.logAirtime(TX_LOG, 500); + Time::advanceTestMillis(8u * 3600u * 1000u); // 8 h: memset branch + uint32_t report[PERIODS_TO_LOG] = {0}; + TEST_ASSERT_TRUE(wipe.airtimeReport(TX_LOG, report, PERIODS_TO_LOG)); + for (uint8_t i = 0; i < PERIODS_TO_LOG; i++) + TEST_ASSERT_EQUAL_UINT32_MESSAGE(0, report[i], "8h wipes rather than rotating"); + } +} + +// --- channelUtilization: the 6 x 10 s modular ring -------------------------- + +// Airtime ages out oldest-first. The ring's index is absolute uptime phase, so +// the oldest bucket is (current + 1) % N, never index N-1 - the assumption +// getSilentMinutes() wrongly makes about the other ring. Stated as a property +// so it holds at any geometry. +void test_channel_utilization_ages_out_oldest_first() +{ + Time::setTestMillis(0); + AirTime a; + + a.logAirtime(RX_LOG, 6000); // A: 10% of the window + Time::advanceTestMillis(15u * 1000u); + a.logAirtime(RX_LOG, 3000); // B: 5%, logged later, must outlive A + + bool sawBOnly = false; + for (uint32_t t = 16; t <= 120; t++) { + Time::advanceTestMillis(1000); + const float pct = a.channelUtilizationPercent(); + // "A alone" would be 10% with B already gone: that is out-of-order ageing. + TEST_ASSERT_FALSE_MESSAGE(pct > 9.0f && pct < 11.0f && sawBOnly, "A must not outlive B"); + if (pct > 4.0f && pct < 6.0f) + sawBOnly = true; + } + TEST_ASSERT_TRUE_MESSAGE(sawBOnly, "there must be a window where only the newer airtime remains"); + TEST_ASSERT_FLOAT_WITHIN(0.01f, 0.0f, a.channelUtilizationPercent()); +} + +void test_channel_utilization_clears_only_the_buckets_crossed() +{ + Time::setTestMillis(0); + AirTime a; + + // One distinct value per 10 s bucket: 1000, 2000, ... 6000 ms. + for (uint32_t b = 0; b < 6; b++) { + a.logAirtime(RX_LOG, (b + 1) * 1000); + Time::advanceTestMillis(10u * 1000u); + } + // t = 60 s: bucket 0 has just been cleared, so 1000 is already gone. + TEST_ASSERT_FLOAT_WITHIN_MESSAGE(0.01f, (2000 + 3000 + 4000 + 5000 + 6000) / 600.0f, a.channelUtilizationPercent(), + "entering a bucket clears exactly that bucket"); + + Time::advanceTestMillis(20u * 1000u); // crosses two more + TEST_ASSERT_FLOAT_WITHIN_MESSAGE(0.01f, (4000 + 5000 + 6000) / 600.0f, a.channelUtilizationPercent(), + "20s must clear exactly two buckets, oldest first"); +} + +void test_channel_utilization_clear_boundary_is_exactly_six_periods() +{ + Time::setTestMillis(0); + AirTime a; + a.logAirtime(RX_LOG, 6000); + + Time::advanceTestMillis(59u * 1000u); + TEST_ASSERT_FLOAT_WITHIN_MESSAGE(0.01f, 10.0f, a.channelUtilizationPercent(), "59s: still inside the window"); + + Time::advanceTestMillis(1000); + TEST_ASSERT_FLOAT_WITHIN_MESSAGE(0.01f, 0.0f, a.channelUtilizationPercent(), "60s: the bucket is reused"); +} + +void test_channel_utilization_is_zero_when_nothing_logged() +{ + Time::setTestMillis(0); + AirTime a; + TEST_ASSERT_FLOAT_WITHIN(0.0001f, 0.0f, a.channelUtilizationPercent()); + Time::advanceTestMillis(3600u * 1000u); + TEST_ASSERT_FLOAT_WITHIN(0.0001f, 0.0f, a.channelUtilizationPercent()); +} + +void test_channel_utilization_decays_proportionally_across_light_sleep() +{ + Time::setTestMillis(0); + AirTime a; + AirtimeEvent ev[6]; + for (uint32_t b = 0; b < 6; b++) { + a.logAirtime(RX_LOG, 1000); + ev[b].endMs = (uint64_t)b * 10000u; + ev[b].airtimeMs = 1000; + Time::advanceTestMillis(10u * 1000u); + } + const float full = a.channelUtilizationPercent(); + TEST_ASSERT_TRUE(full > 0.0f); + + Time::advanceTestMillis(30u * 1000u); // asleep: not one call for half the window + + const float after = a.channelUtilizationPercent(); + const float truth = expectedUtilisation(ev, 6, 90000, 60000); + snprintf(g_msg, sizeof(g_msg), "before %.4f%%, after a 30s gap %.4f%%, oracle %.4f%%", full, after, truth); + TEST_ASSERT_TRUE_MESSAGE(after < full, g_msg); + // Whole buckets shed, so the survivors are exactly what was still on air in + // the last 60s. + TEST_ASSERT_FLOAT_WITHIN_MESSAGE(0.01f, truth, after, g_msg); +} + +// Hold wall time and airtime fixed, vary only how often the class is polled, +// and assert the answer does not move. Fails if rotation moves back into +// runOnce() only. +void test_channel_utilization_is_independent_of_scheduler_rate() +{ + Time::setTestMillis(0); + AirTime polledOften; + AirTime polledOnce; + + for (uint32_t s = 0; s < 45; s++) { + polledOften.logAirtime(RX_LOG, 200); + polledOnce.logAirtime(RX_LOG, 200); + Time::advanceTestMillis(1000); + (void)polledOften.channelUtilizationPercent(); // once a second + } + + snprintf(g_msg, sizeof(g_msg), "polled 45x: %.4f%%, polled once: %.4f%%", polledOften.channelUtilizationPercent(), + polledOnce.channelUtilizationPercent()); + TEST_ASSERT_FLOAT_WITHIN_MESSAGE(0.01f, polledOnce.channelUtilizationPercent(), polledOften.channelUtilizationPercent(), + g_msg); +} + +// A percentage of a fixed window cannot exceed 100. Holds for every preset +// whose packets fit inside a bucket; LONG_SLOW is characterised below. +void test_channel_utilization_never_exceeds_100_percent() +{ + Time::setTestMillis(0); + AirTime a; + + float peak = 0.0f; + for (uint32_t s = 0; s < 200; s++) { + a.logAirtime(RX_LOG, 1000); // a fully saturated channel: 1000ms of airtime per second + Time::advanceTestMillis(1000); + const float pct = a.channelUtilizationPercent(); + if (pct > peak) + peak = pct; + } + snprintf(g_msg, sizeof(g_msg), "peak reading was %.4f%%", peak); + TEST_ASSERT_TRUE_MESSAGE(peak <= 100.01f, g_msg); +} + +void test_channel_utilization_counts_each_packet_once() +{ + Time::setTestMillis(0); + AirTime a; + + a.logAirtime(TX_LOG, 1000); + a.logAirtime(RX_LOG, 2000); + a.logAirtime(RX_ALL_LOG, 3000); + + // 6000ms of the 60s window, counted once each. + TEST_ASSERT_FLOAT_WITHIN(0.01f, 10.0f, a.channelUtilizationPercent()); +} + +// CHARACTERISATION. The current bucket is zeroed on entry and fills across its +// period, so the window covers (N-1)p + phase against a denominator of Np - +// right after a boundary, 50s of coverage divided by 60s. +void test_channel_utilization_covers_less_than_its_denominator() +{ + Time::setTestMillis(0); + AirTime a; + + AirtimeEvent ev[61]; + size_t n = 0; + for (uint32_t s = 0; s < 60; s++) { + a.logAirtime(RX_LOG, 100); + ev[n].endMs = (uint64_t)s * 1000; + ev[n].airtimeMs = 100; + n++; + Time::advanceTestMillis(1000); + } + // t = 60 000 ms, phase 0: the bucket holding t=0..9 has just been reused. + const float truth = expectedUtilisation(ev, n, 60000, 60000); + const float reported = a.channelUtilizationPercent(); + + snprintf(g_msg, sizeof(g_msg), "oracle %.4f%%, reported %.4f%% (deficit %.4f pp)", truth, reported, truth - reported); + TEST_ASSERT_TRUE_MESSAGE(truth > 9.5f, g_msg); // a steady 10% load, less the event on the window edge + TEST_ASSERT_TRUE_MESSAGE(reported < truth - 1.0f, g_msg); +} + +// CHARACTERISATION. The same defect numerically: under a steady load the +// reading sweeps with position inside the current bucket instead of holding. +void test_channel_utilization_quantisation_error_by_phase() +{ + Time::setTestMillis(0); + AirTime a; + for (uint32_t s = 0; s < 60; s++) { + a.logAirtime(RX_LOG, 100); + Time::advanceTestMillis(1000); + } + + float lo = 1000.0f, hi = 0.0f; + for (uint32_t s = 0; s < 10; s++) { // one full bucket period of phases + const float pct = a.channelUtilizationPercent(); + if (pct < lo) + lo = pct; + if (pct > hi) + hi = pct; + a.logAirtime(RX_LOG, 100); + Time::advanceTestMillis(1000); + } + + snprintf(g_msg, sizeof(g_msg), "steady 10%% load reads %.4f%%..%.4f%% across bucket phase", lo, hi); + TEST_ASSERT_TRUE_MESSAGE(lo < 9.0f, g_msg); // under-reports at the start of a bucket + TEST_ASSERT_TRUE_MESSAGE(hi > 9.5f, g_msg); // recovers by the end of it + TEST_ASSERT_TRUE_MESSAGE(hi - lo > 1.0f, g_msg); // and the sawtooth is the jitter defect +} + +// CHARACTERISATION. A packet's whole airtime is credited to the bucket it +// completed in, so a bucket can hold more than its own period. LONG_SLOW at max +// payload is 14 164 ms against a 10 s bucket. +void test_channel_utilization_exceeds_100_percent_on_long_slow() +{ + Time::setTestMillis(0); + AirTime a; + + const uint32_t LONG_SLOW_MAX_MS = 14164; + float peak = 0.0f; + for (uint32_t i = 0; i < 40; i++) { + Time::advanceTestMillis(LONG_SLOW_MAX_MS); // back-to-back: the channel is 100% busy + a.logAirtime(RX_LOG, LONG_SLOW_MAX_MS); + const float pct = a.channelUtilizationPercent(); + if (pct > peak) + peak = pct; + } + + snprintf(g_msg, sizeof(g_msg), "true occupancy 100%%, peak reading %.4f%%", peak); + TEST_ASSERT_TRUE_MESSAGE(peak > 100.0f, g_msg); +} + +// --- utilizationTX: the 60 x 60 s modular ring ------------------------------ + +void test_tx_utilization_ages_out_oldest_first() +{ + Time::setTestMillis(0); + AirTime a; + + a.logAirtime(TX_LOG, 60000); // A + Time::advanceTestMillis(15u * 60u * 1000u); + a.logAirtime(TX_LOG, 30000); // B, newer and smaller + + bool sawBOnly = false; + for (uint32_t m = 16; m <= 120; m++) { + Time::advanceTestMillis(60u * 1000u); + const float pct = a.utilizationTXPercent(); + const float bOnly = 30000.0f / (60.0f * 60.0f * 1000.0f) * 100.0f; + TEST_ASSERT_FALSE_MESSAGE(sawBOnly && pct > bOnly * 1.5f, "A must not outlive B"); + if (pct > bOnly * 0.9f && pct < bOnly * 1.1f) + sawBOnly = true; + } + TEST_ASSERT_TRUE_MESSAGE(sawBOnly, "there must be a window where only the newer airtime remains"); +} + +void test_tx_utilization_clears_only_the_minutes_crossed() +{ + Time::setTestMillis(0); + AirTime a; + for (uint32_t m = 0; m < 4; m++) { + a.logAirtime(TX_LOG, (m + 1) * 1000); + Time::advanceTestMillis(60u * 1000u); + } + const float all = (1000 + 2000 + 3000 + 4000) / (float)MS_IN_HOUR * 100.0f; + TEST_ASSERT_FLOAT_WITHIN(0.001f, all, a.utilizationTXPercent()); + + Time::advanceTestMillis(56u * 60u * 1000u); // t = 60 min: the first minute-bucket is reused + const float withoutFirst = (2000 + 3000 + 4000) / (float)MS_IN_HOUR * 100.0f; + TEST_ASSERT_FLOAT_WITHIN_MESSAGE(0.001f, withoutFirst, a.utilizationTXPercent(), + "only the crossed minute buckets are cleared"); +} + +void test_tx_utilization_clear_boundary_is_exactly_sixty_minutes() +{ + Time::setTestMillis(0); + AirTime a; + a.logAirtime(TX_LOG, 36000); + + Time::advanceTestMillis(59u * 60u * 1000u); + TEST_ASSERT_TRUE_MESSAGE(a.utilizationTXPercent() > 0.0f, "59 min: still inside the hour"); + + Time::advanceTestMillis(60u * 1000u); + TEST_ASSERT_FLOAT_WITHIN_MESSAGE(0.0001f, 0.0f, a.utilizationTXPercent(), "60 min: the bucket is reused"); +} + +void test_tx_utilization_counts_only_transmissions() +{ + Time::setTestMillis(0); + AirTime a; + + a.logAirtime(RX_LOG, MS_IN_HOUR / 2); + a.logAirtime(RX_ALL_LOG, MS_IN_HOUR / 2); + TEST_ASSERT_FLOAT_WITHIN_MESSAGE(0.0001f, 0.0f, a.utilizationTXPercent(), + "received airtime must never reach the duty-cycle figure"); + + a.logAirtime(TX_LOG, 36000); + TEST_ASSERT_TRUE(a.utilizationTXPercent() > 0.0f); +} + +// CHARACTERISATION. The same quantisation defect on the hour window: 10x +// smaller because N is 60 rather than 6, but not zero. +void test_tx_utilization_quantisation_error() +{ + Time::setTestMillis(0); + AirTime a; + for (uint32_t m = 0; m < 60; m++) { + a.logAirtime(TX_LOG, 1000); + Time::advanceTestMillis(60u * 1000u); + } + // 60 000 ms of TX in the hour just elapsed = 1.6667% true. + const float truth = 60000.0f / (float)MS_IN_HOUR * 100.0f; + const float reported = a.utilizationTXPercent(); + + snprintf(g_msg, sizeof(g_msg), "true %.4f%%, reported %.4f%%", truth, reported); + TEST_ASSERT_TRUE_MESSAGE(reported < truth, g_msg); + TEST_ASSERT_TRUE_MESSAGE(reported > truth * 0.95f, g_msg); // ~1/60, not gross +} + +// --- TX gates ---------------------------------------------------------------- + +void test_isTxAllowedChannelUtil_polite_threshold_is_lower() +{ + Time::setTestMillis(0); + AirTime a; + a.logAirtime(RX_LOG, 18000); // 30% of the 60s window + + TEST_ASSERT_TRUE_MESSAGE(a.isTxAllowedChannelUtil(false), "30% is under the 40% default"); + TEST_ASSERT_FALSE_MESSAGE(a.isTxAllowedChannelUtil(true), "30% is over the 25% polite limit"); +} + +// The compare is `< percentage`, so exactly the threshold must block. +void test_isTxAllowedChannelUtil_boundary_is_exclusive() +{ + Time::setTestMillis(0); + AirTime a; + a.logAirtime(RX_LOG, 24000); // exactly 40.0% + + TEST_ASSERT_FLOAT_WITHIN(0.001f, 40.0f, a.channelUtilizationPercent()); + TEST_ASSERT_FALSE_MESSAGE(a.isTxAllowedChannelUtil(false), "exactly 40.0% must block, not allow"); +} + +void test_isTxAllowedAirUtil_allows_when_override_is_set() +{ + Time::setTestMillis(0); + config.lora.region = meshtastic_Config_LoRaConfig_RegionCode_EU_866; + config.lora.override_duty_cycle = true; + initRegion(); + AirTime a; + a.logAirtime(TX_LOG, MS_IN_HOUR); // 100% TX utilisation + + TEST_ASSERT_TRUE(a.isTxAllowedAirUtil()); + config.lora.override_duty_cycle = false; +} + +void test_isTxAllowedAirUtil_allows_when_the_region_is_unlimited() +{ + Time::setTestMillis(0); + config.lora.region = meshtastic_Config_LoRaConfig_RegionCode_US; + config.lora.override_duty_cycle = false; + initRegion(); + AirTime a; + a.logAirtime(TX_LOG, MS_IN_HOUR); + + TEST_ASSERT_TRUE_MESSAGE(getEffectiveDutyCycle() >= 100.0f, "US has no duty cycle limit"); + TEST_ASSERT_TRUE(a.isTxAllowedAirUtil()); +} + +// The polite gate is half the allowance, not the whole of it. +void test_isTxAllowedAirUtil_blocks_at_half_the_duty_cycle() +{ + Time::setTestMillis(0); + config.lora.region = meshtastic_Config_LoRaConfig_RegionCode_EU_866; + config.lora.override_duty_cycle = false; + config.device.role = meshtastic_Config_DeviceConfig_Role_CLIENT; + initRegion(); + const float duty = getEffectiveDutyCycle(); // 2.5% for a non-router on EU_866 + TEST_ASSERT_FLOAT_WITHIN(0.01f, 2.5f, duty); + + AirTime a; + // 40% of the allowance: under half, so still allowed. + a.logAirtime(TX_LOG, (uint32_t)(MS_IN_HOUR * duty / 100.0f * 0.40f)); + TEST_ASSERT_TRUE_MESSAGE(a.isTxAllowedAirUtil(), "40% of the allowance is under the polite half"); + + // Push past half. + a.logAirtime(TX_LOG, (uint32_t)(MS_IN_HOUR * duty / 100.0f * 0.30f)); + TEST_ASSERT_FALSE_MESSAGE(a.isTxAllowedAirUtil(), "70% of the allowance is over the polite half"); +} + +// Two thresholds ride on one figure: isTxAllowedAirUtil() is polite at half the +// duty cycle, while Router::send() aborts only at the whole of it. There is a +// band where the polite gate blocks and the hard gate would not - pinning it +// here means an accuracy change has to be evaluated against both. +void test_router_send_gate_uses_the_whole_duty_cycle() +{ + Time::setTestMillis(0); + config.lora.region = meshtastic_Config_LoRaConfig_RegionCode_EU_866; + config.lora.override_duty_cycle = false; + config.device.role = meshtastic_Config_DeviceConfig_Role_CLIENT; + initRegion(); + const float duty = getEffectiveDutyCycle(); + + AirTime a; + a.logAirtime(TX_LOG, (uint32_t)(MS_IN_HOUR * duty / 100.0f * 0.70f)); // 70% of the allowance + + TEST_ASSERT_FALSE_MESSAGE(a.isTxAllowedAirUtil(), "the polite gate blocks at 70% of the allowance"); + TEST_ASSERT_TRUE_MESSAGE(a.utilizationTXPercent() < duty, + "...while the figure is still under the whole duty cycle Router::send() uses"); +} + +// getEffectiveDutyCycle() special-cases EU_866 by role. Every other region - +// including EU_868, one digit away - takes the generic myRegion->dutyCycle path. +void test_effective_duty_cycle_special_case_is_eu_866_only() +{ + config.lora.region = meshtastic_Config_LoRaConfig_RegionCode_EU_866; + initRegion(); + config.device.role = meshtastic_Config_DeviceConfig_Role_CLIENT; + const float eu866Client = getEffectiveDutyCycle(); + config.device.role = meshtastic_Config_DeviceConfig_Role_ROUTER; + const float eu866Router = getEffectiveDutyCycle(); + TEST_ASSERT_FLOAT_WITHIN(0.01f, 2.5f, eu866Client); + TEST_ASSERT_FLOAT_WITHIN_MESSAGE(0.01f, 10.0f, eu866Router, "EU_866 is role-dependent"); + + config.lora.region = meshtastic_Config_LoRaConfig_RegionCode_EU_868; + initRegion(); + config.device.role = meshtastic_Config_DeviceConfig_Role_CLIENT; + const float eu868Client = getEffectiveDutyCycle(); + config.device.role = meshtastic_Config_DeviceConfig_Role_ROUTER; + const float eu868Router = getEffectiveDutyCycle(); + TEST_ASSERT_FLOAT_WITHIN_MESSAGE(0.01f, eu868Client, eu868Router, "EU_868 must NOT be role-dependent"); + + config.device.role = meshtastic_Config_DeviceConfig_Role_CLIENT; +} + +// --- getSilentMinutes() ------------------------------------------------------ + +void test_getSilentMinutes_returns_zero_when_already_under_the_limit() +{ + Time::setTestMillis(0); + AirTime a; + TEST_ASSERT_EQUAL_UINT8(0, a.getSilentMinutes(1.0f, 2.5f)); +} + +void test_getSilentMinutes_returns_a_full_hour_when_nothing_ages_out() +{ + Time::setTestMillis(0); + AirTime a; // empty ring, but told we are over the limit + TEST_ASSERT_EQUAL_UINT8_MESSAGE(60, a.getSilentMinutes(10.0f, 2.5f), "nothing to age out means the full hour"); +} + +void test_getSilentMinutes_counts_minutes_until_enough_ages_out() +{ + Time::setTestMillis(0); + AirTime a; + a.logAirtime(TX_LOG, 120000); // two minutes of TX, all of it in minute-bucket 0 + const float pct = a.utilizationTXPercent(); + TEST_ASSERT_FLOAT_WITHIN(0.0001f, 3.3333f, pct); + + // Fully determined: the walk subtracts nothing for i in 59..1, then the whole 3.3333% at i == 0, + // returning MINUTES_IN_HOUR - 1 - 0. That answer is one minute short of the truth - syncNow() + // clears bucket 0 at minute 60, not 59 - which test_getSilentMinutes_depends_on_ring_phase pins. + const uint8_t mins = a.getSilentMinutes(pct, 2.5f); + TEST_ASSERT_EQUAL_UINT8(59, mins); +} + +// CHARACTERISATION. getSilentMinutes() walks utilizationTX from index 59 down +// to 0 and returns 59 - i, treating the index as an age. That is the report +// array's convention; utilizationTX is a modular ring indexed by minute phase, +// so identical airtime gives different answers at different phases. +void test_getSilentMinutes_depends_on_ring_phase() +{ + uint8_t answers[6] = {0}; + float pcts[6] = {0}; + for (uint8_t i = 0; i < 6; i++) { + Time::resetMonotonicForTests(); + Time::setTestMillis((uint32_t)i * 10u * 60u * 1000u); // 0, 10, 20... minutes of uptime + AirTime a; + a.logAirtime(TX_LOG, 120000); + pcts[i] = a.utilizationTXPercent(); + answers[i] = a.getSilentMinutes(pcts[i], 2.5f); + } + + for (uint8_t i = 1; i < 6; i++) + TEST_ASSERT_FLOAT_WITHIN_MESSAGE(0.0001f, pcts[0], pcts[i], "the inputs must be identical"); + + bool varies = false; + for (uint8_t i = 1; i < 6; i++) + if (answers[i] != answers[0]) + varies = true; + + snprintf(g_msg, sizeof(g_msg), "same airtime, answers by phase: %u %u %u %u %u %u", answers[0], answers[1], answers[2], + answers[3], answers[4], answers[5]); + TEST_ASSERT_TRUE_MESSAGE(varies, g_msg); +} + +// --- clock robustness --------------------------------------------------------- + +// A gap longer than the window that also crosses the 49.7-day millis() wrap. +void test_survives_heavy_sleep_across_the_wrap() +{ + const uint32_t beforeWrap = 0xFFFFFFFFu - (30u * 1000u); + Time::setTestMillis(beforeWrap); + Time::serviceMonotonic(); + AirTime a; + a.logAirtime(RX_LOG, 6000); + TEST_ASSERT_TRUE(a.channelUtilizationPercent() > 0.0f); + + Time::advanceTestMillis(120u * 1000u); // wraps, and outlasts the 60s window + Time::serviceMonotonic(); + + TEST_ASSERT_FLOAT_WITHIN_MESSAGE(0.01f, 0.0f, a.channelUtilizationPercent(), + "a window that outlasts its span must be empty, wrap or not"); +} + +void test_multi_day_sleep_clears_every_window() +{ + Time::setTestMillis(0); + AirTime a; + a.logAirtime(TX_LOG, 6000); + a.logAirtime(RX_LOG, 6000); + a.logAirtime(RX_ALL_LOG, 6000); + + Time::advanceTestMillis(3u * 24u * 3600u * 1000u); // three days + Time::serviceMonotonic(); + + TEST_ASSERT_FLOAT_WITHIN(0.0001f, 0.0f, a.channelUtilizationPercent()); + TEST_ASSERT_FLOAT_WITHIN(0.0001f, 0.0f, a.utilizationTXPercent()); + uint32_t report[PERIODS_TO_LOG] = {0}; + const reportTypes types[] = {TX_LOG, RX_LOG, RX_ALL_LOG}; + for (uint8_t t = 0; t < 3; t++) { + TEST_ASSERT_TRUE(a.airtimeReport(types[t], report, PERIODS_TO_LOG)); + for (uint8_t i = 0; i < PERIODS_TO_LOG; i++) + TEST_ASSERT_EQUAL_UINT32(0, report[i]); + } +} + +// getUptimeSecs() is monotonic by construction. If it ever stops being, the +// elapsed calculation underflows to a huge value, which trips every >= branch +// and clears the windows. Benign, and pinned so a swap back to bare millis() +// fails loudly rather than corrupting buckets. +void test_backwards_uptime_degrades_safely() +{ + // Step by the wrap, which is the size the regression would actually produce: uptime falls from + // 4294967s to 0. A smaller backwards step leaves elapsedAirtimePeriods at 0, so the hourly + // report below is never reached - which is what this case used to miss. + Time::setTestMillis(UINT32_MAX); + AirTime a; + a.logAirtime(TX_LOG, 6000); + TEST_ASSERT_TRUE(a.channelUtilizationPercent() > 0.0f); + + Time::setTestMillis(0); // the wrap, as a naive millis() clock would present it + + const float pct = a.channelUtilizationPercent(); + snprintf(g_msg, sizeof(g_msg), "channel utilisation after the wrap: %.4f%%", pct); + TEST_ASSERT_FLOAT_WITHIN_MESSAGE(0.0001f, 0.0f, pct, g_msg); + + uint32_t report[PERIODS_TO_LOG] = {0}; + TEST_ASSERT_TRUE(a.airtimeReport(TX_LOG, report, PERIODS_TO_LOG)); + for (uint32_t i = 0; i < PERIODS_TO_LOG; i++) + TEST_ASSERT_EQUAL_UINT32_MESSAGE(0, report[i], "every hourly bucket clears across the wrap"); +} + +// --- the lock ---------------------------------------------------------------------------------- + +// No single public method may take the lock twice: a second Held on the same instance trips the +// re-entry assert. The calls below are sequential and each Held is destroyed before the next, so +// this catches a method re-entering itself, not two methods nesting. That is the regression guard +// for isTxAllowedChannelUtil() regaining its pre-split shape. Two of the methods called take no +// lock at all. Portduino compiles Lock::lock() to an empty body, so the assert is the only check +// that works natively; on hardware the same bug is a deadlock. +void test_no_public_method_takes_the_lock_twice() +{ + Time::setTestMillis(0); + // EU_868 explicitly, not inherited: isTxAllowedAirUtil() constructs a Held only inside its + // duty-cycle branch, so under the default US region (100%) it would return before locking and + // this test would not cover it at all. + config.lora.region = meshtastic_Config_LoRaConfig_RegionCode_EU_868; + config.lora.override_duty_cycle = false; + initRegion(); + + AirTime a; + uint32_t report[PERIODS_TO_LOG] = {0}; + + a.logAirtime(TX_LOG, 100); + a.logAirtime(RX_LOG, 100); + a.logAirtime(RX_ALL_LOG, 100); + (void)a.channelUtilizationPercent(); + (void)a.utilizationTXPercent(); + a.airtimeRotatePeriod(); + (void)a.getPeriodsToLog(); + (void)a.getSecondsPerPeriod(); + (void)a.getSecondsSinceBoot(); + (void)a.airtimeReport(TX_LOG, report, PERIODS_TO_LOG); + (void)a.getSilentMinutes(10.0f, 2.5f); + (void)a.isTxAllowedChannelUtil(false); + (void)a.isTxAllowedChannelUtil(true); + (void)a.isTxAllowedAirUtil(); + + // Reaching here without the assert firing IS the assertion; check the object still works. + TEST_ASSERT_TRUE(a.airtimeReport(TX_LOG, report, PERIODS_TO_LOG)); + TEST_ASSERT_EQUAL_UINT32(100, report[0]); +} + void setup() { initializeTestEnvironment(); @@ -190,6 +1215,66 @@ void setup() RUN_TEST(test_tx_utilization_decays_once_the_60_minute_window_passes); RUN_TEST(test_syncNow_survives_millis_wrap); RUN_TEST(test_period_rotation_survives_millis_wrap); + + // report routing + RUN_TEST(test_tx_log_feeds_tx_report_and_tx_utilization); + RUN_TEST(test_rx_log_feeds_rx_report_but_not_tx_utilization); + RUN_TEST(test_rx_all_log_feeds_only_the_noise_report); + RUN_TEST(test_every_report_type_feeds_channel_utilization); + RUN_TEST(test_report_types_do_not_cross_contaminate); + // airtimeReport() contract + RUN_TEST(test_airtimeReport_rejects_a_null_buffer); + RUN_TEST(test_airtimeReport_rejects_a_count_above_the_log_depth); + RUN_TEST(test_airtimeReport_accepts_a_partial_count); + RUN_TEST(test_airtimeReport_rejects_an_unknown_report_type); + RUN_TEST(test_airtimeReport_returns_a_snapshot_not_an_alias); + // storage conventions + RUN_TEST(test_report_arrays_are_shift_ordered_slot_zero_newest); + RUN_TEST(test_report_slot_zero_is_a_partial_hour); + // first sync and seeding + RUN_TEST(test_first_sync_seeds_from_current_uptime_not_zero); + RUN_TEST(test_first_sync_zeroes_every_window); + RUN_TEST(test_late_construction_does_not_backdate_airtime); + // sync idempotency + RUN_TEST(test_repeated_sync_within_one_second_does_not_rotate); + RUN_TEST(test_rotation_is_once_per_second_regardless_of_entry_point); + RUN_TEST(test_period_constants_are_stable); + + // --- phase 3: windows, gates, sleep --- + RUN_TEST(test_oldest_period_falls_off_the_end); + RUN_TEST(test_period_boundary_is_exact_at_one_hour); + RUN_TEST(test_period_clear_boundary_is_exactly_the_log_depth); + RUN_TEST(test_channel_utilization_ages_out_oldest_first); + RUN_TEST(test_channel_utilization_clears_only_the_buckets_crossed); + RUN_TEST(test_channel_utilization_clear_boundary_is_exactly_six_periods); + RUN_TEST(test_channel_utilization_is_zero_when_nothing_logged); + RUN_TEST(test_channel_utilization_decays_proportionally_across_light_sleep); + RUN_TEST(test_channel_utilization_is_independent_of_scheduler_rate); + RUN_TEST(test_channel_utilization_never_exceeds_100_percent); + RUN_TEST(test_channel_utilization_counts_each_packet_once); + RUN_TEST(test_channel_utilization_covers_less_than_its_denominator); + RUN_TEST(test_channel_utilization_quantisation_error_by_phase); + RUN_TEST(test_channel_utilization_exceeds_100_percent_on_long_slow); + RUN_TEST(test_tx_utilization_ages_out_oldest_first); + RUN_TEST(test_tx_utilization_clears_only_the_minutes_crossed); + RUN_TEST(test_tx_utilization_clear_boundary_is_exactly_sixty_minutes); + RUN_TEST(test_tx_utilization_counts_only_transmissions); + RUN_TEST(test_tx_utilization_quantisation_error); + RUN_TEST(test_isTxAllowedChannelUtil_polite_threshold_is_lower); + RUN_TEST(test_isTxAllowedChannelUtil_boundary_is_exclusive); + RUN_TEST(test_isTxAllowedAirUtil_allows_when_override_is_set); + RUN_TEST(test_isTxAllowedAirUtil_allows_when_the_region_is_unlimited); + RUN_TEST(test_isTxAllowedAirUtil_blocks_at_half_the_duty_cycle); + RUN_TEST(test_router_send_gate_uses_the_whole_duty_cycle); + RUN_TEST(test_effective_duty_cycle_special_case_is_eu_866_only); + RUN_TEST(test_getSilentMinutes_returns_zero_when_already_under_the_limit); + RUN_TEST(test_getSilentMinutes_returns_a_full_hour_when_nothing_ages_out); + RUN_TEST(test_getSilentMinutes_counts_minutes_until_enough_ages_out); + RUN_TEST(test_getSilentMinutes_depends_on_ring_phase); + RUN_TEST(test_survives_heavy_sleep_across_the_wrap); + RUN_TEST(test_multi_day_sleep_clears_every_window); + RUN_TEST(test_backwards_uptime_degrades_safely); + RUN_TEST(test_no_public_method_takes_the_lock_twice); exit(UNITY_END()); } diff --git a/test/test_nodedb_blocked/test_main.cpp b/test/test_nodedb_blocked/test_main.cpp index 8b35d65340..96d392cd85 100644 --- a/test/test_nodedb_blocked/test_main.cpp +++ b/test/test_nodedb_blocked/test_main.cpp @@ -181,7 +181,7 @@ static void test_eviction_preservesFavorite(void) // A node heard during this boot is newer than every persisted epoch, including valid epochs after // 2038. Ranking both domains in one uint32_t incorrectly evicts the current-boot node first. -static void test_eviction_prefers_current_boot_stamp_over_post2038_epoch(void) +static void test_eviction_prefersCurrentBootStampOverPost2038Epoch(void) { constexpr NodeNum futureDated = 0x70000001; constexpr NodeNum heardThisBoot = 0x70000002; @@ -291,7 +291,7 @@ NDB_TEST_ENTRY void setup() RUN_TEST(test_migration_carriesRoleAndProtectedIntoWarm); RUN_TEST(test_migration_carriesSignerBitThroughWarm); RUN_TEST(test_eviction_preservesFavorite); - RUN_TEST(test_eviction_prefers_current_boot_stamp_over_post2038_epoch); + RUN_TEST(test_eviction_prefersCurrentBootStampOverPost2038Epoch); RUN_TEST(test_ignored_survivesEvictionAndCleanup); RUN_TEST(test_protectedCap_refusesBeyondLimit); RUN_TEST(test_removeNodeByNum_absentNodeOnFullDb); diff --git a/test/test_packet_signing/test_main.cpp b/test/test_packet_signing/test_main.cpp index d8234290a1..3b5c70ad3d 100644 --- a/test/test_packet_signing/test_main.cpp +++ b/test/test_packet_signing/test_main.cpp @@ -417,6 +417,9 @@ void setUp(void) resetRoutingAuthEvaluationCount(); } +// Set while C14's saturated AirTime is installed; see useDutyCycleSaturatedAirTime() below. +static AirTime *c14SavedAirTime = nullptr; + void tearDown(void) { delete mockNodeDB; @@ -425,13 +428,15 @@ void tearDown(void) // Restore globals here, not at the end of a test body: an assertion aborts the body, and these // would otherwise leak into every later case. The injected clock is the one the N8-N11 - // suppression-window cases drive; the region and TX bucket are C14's duty-cycle setup. + // suppression-window cases drive; the region and the AirTime swap are C14's duty-cycle setup. Time::useRealClock(); Time::resetMonotonicForTests(); - if (airTime) - airTime->utilizationTX[0] = 0; config.lora.region = meshtastic_Config_LoRaConfig_RegionCode_US; initRegion(); + if (c14SavedAirTime) { + airTime = c14SavedAirTime; + c14SavedAirTime = nullptr; + } } // =========================================================================== @@ -1500,12 +1505,32 @@ void test_C13_failed_initial_reliable_send_does_not_retry(void) "failed interface enqueue must not leave a retransmission pending"); } +// C14 needs a node that has used its whole hourly duty-cycle allowance. Swaps in a separate AirTime +// rather than poking the global's buckets, which are private now. +// +// Deliberately NOT a scoped guard: Unity's TEST_ABORT() is longjmp, which does not run destructors +// of automatic objects, so a guard would leave `airTime` dangling into an abandoned stack frame on +// any assertion failure - and later cases dereference it (NodeInfoModule::allocReply). tearDown() +// restores the global unconditionally instead. The instance is a function-local static so it +// outlives the longjmp. +// +// Note it also parks channel utilisation at ~6000%, because logAirtime() credits that for every +// report type. C14 gates on utilizationTXPercent() alone; do not reuse this for an +// isTxAllowedChannelUtil() path, which would then pass for the wrong reason. +static void useDutyCycleSaturatedAirTime() +{ + static AirTime saturated; + c14SavedAirTime = airTime; + airTime = &saturated; + saturated.logAirtime(TX_LOG, MS_IN_HOUR); // utilizationTXPercent() sums every bucket -> 100% +} + void test_C14_duty_cycle_limited_reliable_send_remains_pending(void) { config.lora.region = meshtastic_Config_LoRaConfig_RegionCode_EU_868; config.lora.override_duty_cycle = false; initRegion(); - airTime->utilizationTX[0] = MS_IN_HOUR; + useDutyCycleSaturatedAirTime(); meshtastic_MeshPacket initial = makeDecoded(LOCAL_NODE, REMOTE_NODE, meshtastic_PortNum_ROUTING_APP, SMALL_PAYLOAD); initial.id = 0xC14C14C1; @@ -1519,7 +1544,6 @@ void test_C14_duty_cycle_limited_reliable_send_remains_pending(void) TEST_ASSERT_EQUAL_UINT32_MESSAGE(1, pipelineRouter->pendingCount(), "duty-cycle rejection must retain the retry for when airtime is available"); - airTime->utilizationTX[0] = 0; config.lora.region = meshtastic_Config_LoRaConfig_RegionCode_US; initRegion(); } diff --git a/test/test_traffic_management/test_main.cpp b/test/test_traffic_management/test_main.cpp index 0395f58309..cfe06e7f52 100644 --- a/test/test_traffic_management/test_main.cpp +++ b/test/test_traffic_management/test_main.cpp @@ -37,24 +37,26 @@ constexpr NodeNum kTargetNode = 0x33333333; // a fresh requester for their "served again" step to avoid the per-requester window masking them. constexpr NodeNum kRemoteNode2 = 0x44444444; -// Telemetry hop exhaustion is gated on channel congestion (alterReceived checks -// airTime->isTxAllowedChannelUtil/isTxAllowedAirUtil). Installs a global -// airTime reporting 100% channel utilization for the enclosing scope. -class ScopedBusyAirTime -{ - public: - ScopedBusyAirTime() : previous(airTime) - { - for (uint32_t i = 0; i < CHANNEL_UTILIZATION_PERIODS; i++) - busy.channelUtilization[i] = 10000; // 10 s of airtime per 10 s period - airTime = &busy; - } - ~ScopedBusyAirTime() { airTime = previous; } - - private: - AirTime busy; - AirTime *previous; -}; +// INERT - commented out, not deleted. TrafficManagementModule holds no reference to airTime: +// the gating this described went with exhaust_hop_telemetry / exhaust_hop_position, and +// shouldExhaustHops() is now a compare of three members nothing sets. Writing the buckets did not +// work either - the first accessor call takes AirTime's firstTime branch and memsets them, so this +// reported 0%, not 100%. A revived version must fill them via logAirtime(); they are private now. +// +// class ScopedBusyAirTime +// { +// public: +// ScopedBusyAirTime() : previous(airTime) +// { +// busy.logAirtime(RX_ALL_LOG, CHANNEL_UTILIZATION_PERIODS * 10 * 1000); // a full window +// airTime = &busy; +// } +// ~ScopedBusyAirTime() { airTime = previous; } +// +// private: +// AirTime busy; +// AirTime *previous; +// }; class MockNodeDB : public NodeDB { @@ -2307,7 +2309,7 @@ static void test_tm_nodeinfo_directResponse_fallbackUnsignedNotServed(void) */ static void test_tm_alterReceived_telemetryBroadcast_hopLimitUnchanged(void) { - ScopedBusyAirTime busyChannel; // congestion present but exhaust is disabled + // ScopedBusyAirTime busyChannel; // INERT: the module never reads airTime TrafficManagementModuleTestShim module; meshtastic_MeshPacket packet = makeDecodedPacket(meshtastic_PortNum_TELEMETRY_APP, kRemoteNode, NODENUM_BROADCAST); packet.hop_start = 5;