Serialise AirTime behind a lock, and stop handing out its buckets - #11362
Draft
NomDeTom wants to merge 56 commits into
Draft
Serialise AirTime behind a lock, and stop handing out its buckets#11362NomDeTom wants to merge 56 commits into
NomDeTom wants to merge 56 commits into
Conversation
src/UptimeClock.{h,cpp} shipped without a dedicated test suite. Port the six
tests from the monotonic-time branch (test/test_time), retargeted to the
renamed header.
The wrap test crosses 0xFFFFFFFF via advanceTestMillis() rather than a second
setTestMillis(): setTestMillis() sets clockSourceChanged, which makes
getMillis64() rebase its accumulator and swallow the wrap.
Resolves the "FIXME, handle 51 day rolloever here!!!" in NextHopRouter::doRetransmissions() by switching the retransmission-due comparison from plain unsigned <= to a signed-difference cast. The previous p.nextTxMsec <= now comparison silently breaks across the ~49.7 day millis() wraparound: pending retransmissions either stall for the remainder of the wrap window, or all fire simultaneously at the rollover boundary. Long-running router/infrastructure nodes do hit this in practice. The replacement (int32_t)(p.nextTxMsec - now) <= 0 is the standard Arduino/embedded idiom for rollover-safe deadline checks and behaves identically to the original for any non-wrap timing.
…ransmit check Review feedback from @Copilot on PR meshtastic#10227: casting a uint32_t subtraction to int32_t is implementation-defined in C++ when the unsigned value exceeds INT32_MAX (even though it works on typical two's-complement targets). Switch to the fully well-defined unsigned half-range form: nextTxMsec is in the past-or-equal iff (now - nextTxMsec) has not wrapped past 2^31 ms. Future offsets < 2^31 ms wrap into the top half and read as 'not yet'. Same semantics as the signed-cast version on every two's-complement platform we care about, but portable to any conforming C++ impl.
… inverts test_C3_invalid_repeated_packet_cannot_ack_or_change_retry_state parked a pending packet at nextTxMsec = UINT32_MAX to mean "never retransmit", then asserted that a rejected repeated packet leaves the retry state untouched. NextHopRouter::doRetransmissions() now tests whether a retransmit is due with an unsigned half-range compare, (uint32_t)(now - nextTxMsec) < 0x80000000u, so that retransmission timing survives the ~49.7 day millis() wrap. Under it now - 0xFFFFFFFF == now + 1, a small positive delta, so UINT32_MAX reads as ~1ms in the past: the retransmit fires and rewrites nextTxMsec, and the test failed with "Expected 4294967295 Was 6247". Use a representable future time instead. Production is unaffected either way - nextTxMsec is only ever written as millis() + d, and UINT32_MAX came from the test harness alone - so the sentinel is what needs to go, not the comparison. Special-casing UINT32_MAX in the retransmit path would keep a value that reads as "expired" under any wrap-correct compare. The value is held in a local because millis() advances across runPipelineIngress(), so recomputing it at the assertion would compare against a different number. Reported upstream on meshtastic#10227, whose branch predates this test.
Throttle backs ~94 call sites, which makes it the highest-leverage place in the tree to put the clock seam: reading Time::getMillis() instead of millis() in its three call sites turns all of them into time-injectable code at once, without touching any of them. The 32-bit millis() wrap is not otherwise reachable from a native test. The read is behaviour-preserving - Time::getMillis() returns millis() unless a test injects a clock - and the full native suite passes with it live. Also add hasElapsed(), the complement of isWithinTimespanMs(), because 51 of the 94 call sites are spelled !isWithinTimespanMs and read poorly. Its boundary is inclusive (>=) since isWithinTimespanMs uses <; both are documented. It deliberately does not treat lastExecutionMs == 0 as "never run": call sites pair that test with the interval check themselves, and absorbing a sentinel into the one helper every module depends on is exactly the value-overloading hazard being removed elsewhere. Migrating the existing !isWithinTimespanMs sites is cosmetic and deliberately left out of this commit. test/test_throttle/ covers window semantics, both boundaries, the complement identity, execute()'s first-run and throttled paths, and - the point of the exercise - a window opened before the wrap closing correctly after it, including at the 24h interval that is the longest in the tree.
Two deadline variables encoded "inactive" as a magic value that only reads as "never" because the comparison against it is a naive millis() compare. Under any rollover-correct comparison both invert to "expired ~49 days ago", so they have to be untangled before those comparisons can be fixed. Power::reboot() set rebootAtMsec = -1 on platforms with no reboot implementation, intending "never fire". Every reader already treats 0 as the disarm value - powerCommandsCheck() tests `if (rebootAtMsec && ...)`, and AdminModule writes 0 to cancel - so -1 was both wrong and unnecessary. Use 0. Left as UINT32_MAX it would reboot-loop the moment the comparison is corrected. ExternalNotificationModule's nag window compared against nagCycleCutoff, which holds UINT32_MAX once stopped and 1 at boot. isNagging is the real armed flag, so test it first and short-circuit: a disarmed cutoff can no longer reach the arithmetic, while an idle module still takes the same sleep path that the boot-time value of 1 was relying on. Note this fixes the sentinel only. The comparison itself is still a naive `nagCycleCutoff < millis()` and remains on the list to convert.
Roughly 20 sites compared against millis() directly - `millis() > deadline`, `deadline < millis()`, `last + interval < millis()`. All of them break for about 24 days after the 32-bit millis() wrap: depending on which side of the wrap each value sits, the action either stalls for weeks or fires immediately and repeatedly. The longest affected interval is the 12 hour NTP renewal, a ~50x margin against the wrap, so none of these needed the range - only the correct comparison. Add Throttle::deadlinePassed(deadlineMs) for sites that store an absolute deadline they cannot re-express as "interval since an event". It uses the same unsigned half-range test as NextHopRouter::doRetransmissions() rather than introducing a competing signed-cast idiom, and unlike the signed cast it is defined for every input. Sites that do store an event use the existing isWithinTimespanMs / hasElapsed. Nothing gained new state. Because both helpers read Time::getMillis(), every converted site is now reachable from a native test that drives the clock across the wrap; the comparison itself is covered directly in test/test_throttle/. Sentinel handling is the reason this could not be a mechanical rewrite. The disarm convention is not uniform: 0 means "inactive" for rebootAtMsec, shutdownAtMsec, alertBannerUntil, fixHoldEnds, suppressUntilMs and touchResumeBlockUntilMs; 0 means "due now" for ntp_renew, which is forced to 0 at link-up; UINT32_MAX means "inactive" for nagCycleCutoff; and alertBannerUntil == 0 in isOverlayBannerShowing() means "show indefinitely". Every inactive marker is arithmetically far in the past, so a correct comparison fires on it - each site tests its sentinel before the arithmetic, and keeps the meaning it had. Two sites carried a second bug found on the way: BME680Sensor tested (stateUpdateCounter * STATE_SAVE_PERIOD) < millis(). With a 6 hour period and a uint16_t counter that product overflows uint32_t after about 198 saves, independently of the millis() wrap. It now measures the interval since the last save. EInkDynamicDisplay had `if (previousRunMs > millis()) return;` as a millis() overflow guard, which skipped rate limiting entirely for the whole post-wrap period - the bug it meant to prevent. Every check below it already goes through Throttle, so the guard is removed rather than fixed. MotionSensor's calibration countdown is converted to a signed delta rather than deadlinePassed, because it needs the remaining magnitude and not a boolean; that matches the already-correct check in the same file.
getMillis64() had exactly one caller and no callers in tests. It also carried obligations that made it the wrong shape for this firmware: a wrap accumulator in mutable statics, which is not ISR-safe, and which must be polled at least once every ~49.7 days or it silently misses a wrap and returns a time ~49 days short. Its one caller only wanted to know whether a 12 hour suppression window had elapsed - which Throttle answers correctly across the wrap without any accumulator. NodeInfoModule now stores Time::getMillis() in lastNodeInfoSeen and tests the window with Throttle::isWithinTimespanMs, so the map holds milliseconds rather than seconds derived from a 64-bit read. USERPREFS_NODEINFO_REPLY_SUPPRESS_SECS is user-overridable and now feeds a multiply by 1000, so a static_assert rejects any value too large to express in milliseconds instead of letting it wrap. clockSourceChanged goes too. It existed solely to rebase getMillis64()'s accumulator when a test swapped clock sources, and it made the wrap untestable through the injection API: setTestMillis() set the flag, so a wrap crossed by two setTestMillis() calls was swallowed. With the accumulator gone the flag has nothing to rebase, and the injection API is a plain settable clock. The three getMillis64 tests are dropped as they no longer describe anything. One test replaces them, pinning that advanceTestMillis() wraps past 0xFFFFFFFF rather than saturating, since the Throttle wrap tests rely on it. Also fix eviction in pruneLastNodeInfoCache(): it picked the entry with the smallest stored stamp, which is the wrong victim once some stamps sit on the far side of the wrap. It now evicts the largest elapsed time.
Fixing the existing sites does not stop the next one being added. The millis-deadline-check job rejects millis() placed directly next to a comparison operator, in either order, anywhere in src/. It lives in test_native.yml alongside suite-count-check, which sets the precedent for a repo-hygiene guard that CI enforces and bin/run-tests.sh does not. The correct idioms all subtract before comparing, so none of them match the pattern. Line comments are stripped first, so documentation is free to name the broken form - as the guard's own comment and the coding conventions both do. Writing the check before finishing the sweep turned out to be worth it: it found roughly 14 sites that a by-hand audit of deadline variables had missed, including two extra nagCycleCutoff compares, both boot-screen timeouts, and a 6 hour sensor save interval that was also overflowing a uint32_t multiply. .github/millis-deadline-allowlist.txt covers the cases that are genuinely not deadline tests. Both current entries are uptime thresholds - "has the device been up N ms" - with no stored deadline and no event to measure from: a 30s button holdoff against phantom shutdown from floating pins, and a 10s window for the OEM boot logo. Each re-crosses its threshold once per wrap, which is harmless for boot-holdoff logic and not worth new state to avoid. Entries are keyed on file plus exact source text, without line numbers, so an edit above an entry does not silently invalidate it. Locally the guard reports 19 matches before the sweep and 2 after, both allowlisted. The Throttle bullet in the coding conventions is rewritten from "prefer Throttle for rate limiting" to "never compare against millis() directly", lists all four helpers with when to use which, names the CI guard, and documents the sentinel hazard with the rebootAtMsec = -1 case that would have become a reboot loop. Mirrored into AGENTS.md; CLAUDE.md gets a pointer row.
The comments added with the millis() rollover fixes carried too much of the investigation that produced them: how many sites were found, which document recorded them, what the old code used to do. That belongs in the commit history, not in the source, and some of it was already stale - Power::reboot() still described the check it disarms as "a naive millis() > deadline" when that comparison had been fixed in the same series. What stays is the non-obvious part at each site: which sentinel value the variable overloads and what it means there, since that differs between call sites and is what a correct comparison gets wrong. 0 means "not scheduled" for rebootAtMsec, "renew now" for ntp_renew, and "show indefinitely" in isOverlayBannerShowing(). Exposition is kept where it earns its place: the Throttle helpers, the uptime clock's note on why there is no 64-bit variant, and the tests. The Throttle docs lose only the site count and the "longest interval in the firmware" statistic, both of which would age badly; the range trade-off between the two forms is what a caller actually needs. Comments only - no code changed, verified by diff.
- BME680Sensor: checkpoint lastStateSaveMs after a successful write instead of at the interval test. The first save (IAQ accuracy >= 2) left it at 0, timing the next save from boot, and stamping before the write deferred the retry a full period when the write failed. Reads Time::getMillis(), the same clock Throttle compares against. - Throttle: add deadlinePassedAt(now, deadline) for loops that snapshot the clock once and test many deadlines; deadlinePassed() now delegates to it. NextHopRouter::doRetransmissions() uses it, replacing the inline half-range compare adopted from meshtastic#10227 (nightjoker7) - same arithmetic, credited at the call site - and takes its snapshot from Time::getMillis() so setNextTx() deadlines and the due test cannot diverge under an injected test clock. - test_native.yml: set -euo pipefail in the millis-deadline guard, matching the sibling suite-count job. Without -e a partially failed scan could report "no violations" from truncated output. - test_packet_signing: build the not-due deadline from Time::getMillis() rather than millis(), so the test and the router read one clock. - test_throttle: cover deadlinePassedAt(), and correct a wrapped-value comment (0xFFFFFF00 + 400 is 0x00000090, not 0x00000094). Two review comments were declined: the AirTime mutex (every airTime-> caller runs in the single cooperative loop, WebServerThread included) and the MotionSensor 0-sentinel countdown (the calibration frame is only installed while a window is open). clod helped out here
The comments and agent docs said a bare `millis() > deadline` "breaks for ~24 days after the wrap". That figure belongs to the fix, not the bug: it is the half-range limit of deadlinePassed(), which reads deadlines more than 2^31 ms ahead as already passed, and the range over which a UINT32_MAX sentinel reads as passed. The naive compare's actual failure is an inversion lasting only while the deadline sits on the far side of the wrap, so it is bounded by the interval: the action fires immediately and loses its wait, or blocks for about the wait it should have performed - days for the nRF52 flash-corruption backoff, one skipped cycle for a seconds-long retransmit timer. Comments and docs only; the ~24.8 day statements that correctly describe deadlinePassed()'s own range are left as they were. clod helped out here
Time::getMillisMonotonic() is the getMillis64() shape - a 32-bit wrap counter carried across reads - promoted to the shared timebase, with Time::getUptimeSecs() as the derived whole-seconds view. This deliberately reverses the earlier removal of getMillis64(), and the distinction matters: removal was right for a lazily-read accumulator with one rare caller, where a 49.7-day gap between reads silently swallowed a wrap. Here every read is the poll and AirTime::runOnce() guarantees one per second; the missed-wrap contract is pinned by a test rather than left as a footnote. Three private wrap counters collapse into it: - AirTime::syncNow() takes its seconds from Time::getUptimeSecs() and drops its lastSyncMsec checkpoint; window rotation is unchanged. - DeviceTelemetryModule loses refreshUptime()/uptimeWrapCount/uptimeLastMs; uptime_seconds comes from Time::getUptimeSecs(), which also removes the 0.296s-per-wrap truncation of (0xFFFFFFFF / 1000) * wraps. Its two interval checks move to Throttle::hasElapsed(). - HostMetricsModule's copies of those members were never read (its uptime comes from /proc/uptime) - deleted. Not ISR-safe (unguarded mutable carry): ISRs keep using getMillis(), which stays a pure read. Audited: no interrupt-context file reads getTime(), getValidTime(), or the new accessors. test/native-suite-count 44 -> 45: the bump for test_uptime_clock was lost in a branch history rewrite, leaving every later value off by one - run-tests.sh reports AMBER and CI's suite-count-check fails on the current push until this correction.
getTime() computed elapsed-since-time-set as a 32-bit millis() delta, so a node that took time once and stayed up past 49.7 days reported a wall clock one full cycle in the past - and last_heard, rx_time, message and position stamps all inherited it. The anchor is now the 64-bit monotonic count (timeStartMsec -> timeStartMs64) and the elapsed term is computed in 64-bit, so the wall clock is exact at any uptime. All six anchor writers follow: the five hardware-RTC read branches and perhapsSetRTC(), which keeps a truncated 32-bit copy of the same instant for its Throttle-checked rate-limit stamps. The test seams anchor the same way. Two native regression tests drive getTime() across the wrap through the Time seam - one anchored before the wrap and read after it, one anchored after a counted wrap - with the test epoch derived from BUILD_EPOCH so the plausibility window cannot rot as the build date advances.
computeRxTimeStamp() stamped Time::getMillis() when the clock was untrusted, and reconcilePendingRxTimes() back-calculated with a 32-bit millis() delta - correct within one wrap, but a placeholder older than 49.7 days aliased to a small elapsed value and reconciled to a plausible-but-wrong recent epoch: the exact failure has_rx_time exists to prevent, reachable by an ordinary unattended router whose phone connects two months in. The placeholder is now Time::getUptimeSecs(). Both stamps come off the monotonic counter, so the elapsed term is exact at any age and the aliasing window is gone outright rather than widened. If elapsed somehow exceeds the epoch itself, the packet stays un-dated (absent, never wrong) instead of clamping to a pre-1970 value. Defence in depth: a placeholder that leaks needs ~50 years of uptime to cross MIN_PLAUSIBLE_EPOCH, where milliseconds took 18.3 days. The stream-API reconciliation tests keep their scenarios with the placeholder unit switched, and ScopedTimeFixture resets the monotonic carry so uptime seconds are deterministic per case.
A node first heard while the wall clock was untrusted got no last_heard at all, and nothing backfilled it once time arrived - the phone showed "Last heard: unknown" for a node it had just announced. The arrival instant now waits in a RAM-only sidecar (NodeNum -> uptime seconds, 32 slots, reuse-oldest - the RouteHealth shape) and is converted to a real epoch on the clock-becoming-trusted transition, beside the existing rx_time reconciliation. last_heard itself never holds anything but a real epoch or 0: it persists to flash and the warm tier, where an uptime-relative value would be meaningless after reboot. The sidecar's write sites are updateFrom()'s no-trusted-clock path (the rx_time placeholder already carries the arrival instant, so this is a store, not a second clock read) and addFromContact's anti-eviction stamps, which previously wrote a bare getTime() - boot-relative seconds on a clockless node, the exact value lastHeardIsWallClock() exists to catch. Eviction ranking honours the stamps: heard-this-boot outranks every stored epoch, ordered among themselves, so a stamped contact is not the first victim. PhoneAPI re-reads last_heard at nodeinfo send time: a record prefetched before the clock became trusted can carry 0 while the store has since been backfilled, and re-reading at the pop makes handshake ordering (time-set vs node-list download) irrelevant. Backfill never moves last_heard backwards and skips the pathological elapsed-exceeds-epoch case. A node evicted to the warm tier before time arrives is still absorbed with last_heard 0 - same as before, bounded to the untrusted window.
The conventions bullet asserted there is deliberately no 64-bit millis; the monotonic uptime clock restored for timestamps changes that contract. State the split explicitly: Throttle for deadlines and intervals (no carry state), Time::getMillisMonotonic()/getUptimeSecs() for timestamps, polled by construction and not ISR-safe.
getMillisMonotonic() was a read-modify-write on two unguarded statics, and it is reached off the main loop: the nRF52 Bluefruit task via onFromRadioAuthorize() -> PhoneAPI::getFromRadio -> getValidTime(), and the portduino civetweb workers via the same path. Two readers interleaving inside the wrap window could each increment the carry, putting every uptime and wall-clock reading 2^32 ms ahead for the rest of the boot - a permanent ~49.7 day jump in rx_time, last_heard and ClientNotification.time. Readers no longer write. serviceMonotonic() publishes a snapshot behind a seqlock and is the only writer; a reader adds its own unsigned elapsed time to that snapshot, which is exact across the wrap, so it never inspects the boundary and cannot miscount it. The main loop publishes every iteration, so the once-per-49.7-days obligation now has the whole window of margin instead of resting on an instruction-wide race. AirTime was the guaranteed poller and is now a pure reader, so the two airtime wrap tests step the clock the way loop() does. The test clock itself is atomic so a suite can drive it from one thread while others read.
The rollover sweep guarded the hold re-arm with `fixHoldEnds != 0 &&`, which reads like the sentinel rule but inverts this site. The comparison it replaced, `(fixHoldEnds + GPS_THREAD_INTERVAL) < millis()`, was always true when nothing was armed - that was the point, since 0 means "not holding" and so is a reason to arm. With the guard, a publish that cleared the hold without sleeping (the `shouldPublish && !tooLong && !holdExpired` path, which does not call down()) left hasValidLocation set and prev_fixQual non-zero, so no disjunct held: nothing re-armed, nothing published, and the receiver stayed powered at the 200ms poll until searchedTooLong() fired. State the question positively instead. fixHoldInForce() is the only place the sentinel is interpreted, and both of runOnce()'s decisions derive from it - the asymmetry is now visible rather than implied, since arming does not require a prior hold but expiring does. Its `!= 0` test is not redundant with the arithmetic: deadlinePassed() is an unsigned half-range test, so past 2^31 ms of uptime the sentinel reads as a deadline ~24.9 days in the future. Kept beside its caller rather than in a header; the native test build compiles GPS.cpp, so the suite declares the prototypes. Also converts the getACK() wait to isWithinTimespanMs(start, interval): it has both the start instant and the interval in hand, which gives the full 49.7-day range instead of 24.8 days ahead, and takes its anchor from Time::getMillis() so the wait is injectable.
The 12h reply-suppression stamp regressed from wrap-immune 64-bit seconds to raw 32-bit milliseconds, and pruneLastNodeInfoCache() evicts only by node count and DB membership - never by age. A stable mesh under the node cap therefore keeps every stamp indefinitely, and once uptime passes 49.7 days an old one aliases back into the window: `now - stamp` computes as ~0 and a legitimate NodeInfo request goes unanswered for up to 12h. It self-heals and repeats once per wrap cycle. Store Time::getUptimeSecs() instead, which does not wrap for 136 years, and drop the millisecond conversion the previous shape needed. Entries past the window are now evicted too: they can only ever decide "don't suppress". N8-N11 cover the window from both sides, and N10 pins the regression - it needs a full 2^32 ms of uptime to elapse, not merely a crossing of the boundary, because that is when a millisecond stamp reads as "answered this instant". tearDown() now restores the injected clock and C14's region and TX bucket. A failing assertion aborts the test body, so restoring at the end of it leaked that state into every later case.
Two rules the preceding three commits changed. The monotonic clock is no longer maintained by whoever happens to read it: serviceMonotonic() is the only writer, readers are pure, and calling it from anywhere but the main loop reintroduces the double-count. The sentinel guidance gained the half it was missing. It named UINT32_MAX as a sentinel while prescribing an idiom that only covers 0, and it assumed the sentinel always means "suppress" - at the GPS fix-hold site it meant "fire", which is how that regression passed review looking like the rule.
holdJustExpired() gives the second reading of the fixHoldEnds sentinel a name beside the first, so both are pinned by test/test_gps_fix_hold/ and neither can be respelled at the call site. The old inline form could not be tested: written as a literal, its guard folds at compile time and the assertion asserts nothing. The arm site used bare millis() while the evaluation reads the Throttle clock; same value in production, but it kept that write out of reach of Time::setTestMillis(). Remap a deadline that lands on 0, which would otherwise read as no hold at all.
getMillisMonotonic() and serviceMonotonic() carried byte-identical wrap arithmetic. A one-sided edit to either would drift the published carry from what readers report, so keep one copy.
* fix(time): avoid blocking monotonic readers * test(time): make paused-publisher check deterministic * fix(time): address review portability gaps
EvictionRecency{} is {0, false}, which evictionRecencyOlder() ranks as older than
every candidate: without the oldestIndex/oldestBoringIndex guards nothing would
ever be selected and a full node DB would stop evicting entirely.
Init to the genuine maximum instead, so the sentinel is correct on its own. The
index guards stay: two independent reasons the scan is right beats one.
The guard was widened to cover Time::getMillis() and unqualified getMillis(), and renamed to suit. Upstream branch protection matches required checks by name, so a rename means the old name never reports and merges block on a check that will never arrive. Widen the guard, keep the name; the descriptive text carries the broader scope.
Upstream meshtastic#11293 added test_nmea_wpl and took develop's count to 43; this branch had independently reached 46. Merging develop resolved the counter textually, keeping 46, while the directory set became the union of both sides at 47. The suite-count CI gate fails on the mismatch, and it gates the native test jobs, so the tests themselves were being skipped.
The concurrent-reader case started at 0xFFFFF000, leaving 0x1000 to the wrap, so the 0x800 advance annotated "cross the wrap" fell short and the wrap actually happened during the following 60s advance. Start at 0xFFFFF800 instead, so the first advance lands exactly on the wrap while the readers are running and the second is the ordinary time after it - the shape both comments already described. Total elapsed is unchanged, so the closing assertion still holds.
…nion on my belt, which was the style at the time.
The HAS_I2S_SPEAKER_NRF52 RTTTL block arrived from develop with a raw nagCycleCutoff >= millis(), which the deadline guard rejects. Use the same Throttle::deadlinePassed() form as the two sibling paths in this function.
preFSBegin() runs in the first millisecond of boot, so millis() can legitimately return 0 there. Both readers of last_format_ms treated 0 as "nothing formatted this boot", which would skip the repeat-corruption escalation and let a dead flash reformat-loop instead of reporting FLASH_CORRUPTION_UNRECOVERABLE.
The two constant getters are not constrained, and getSilentMinutes() reads the buckets without rotating them, so "the accessors mutate" was not accurate.
airtimeReport() returned a pointer into the rotating bucket arrays, so the caller held a handle to state that logAirtime() and every accessor mutate underneath it. Copy into a caller-supplied buffer instead, and report failure for a null buffer, a count past the log depth, or an unknown report type. ContentHandler owns its buffer and hoists getPeriodsToLog() out of the three calls that repeated it.
Half of AirTime's surface had no tests: which store each report type feeds, what airtimeReport() does when misused, how the first sync seeds itself, and whether calling several entry points in one interval compounds the rotation. Eighteen tests, asserted through the public API rather than the public bucket arrays - those arrays are meant to become private, and a test that reads them would have to be rewritten rather than pinning a contract. Two of them state a convention that was never written down: the report arrays are shift-ordered with slot 0 newest, and slot 0 covers only the time since the last rotation. channelUtilization and utilizationTX use the opposite convention - a modular ring indexed by uptime phase - and reading one as if it were the other is a defect that has already happened once.
Thirty-three tests in three kinds. Invariants must hold forever; boundaries pin
off-by-ones a refactor would move; five characterisations encode today's wrong
numbers, each tagged with the phase that will flip it.
Readings are asserted against an event-log oracle - airtime physically on air
inside (now - window, now], computed from a list of completed packets - rather
than against hand-worked constants, so a test states "this matches the
definition" instead of "this looked right when I wrote it".
The characterisations, all measured rather than assumed:
- the window covers (N-1)p + phase but divides by Np, so a steady 10% load
reads 8.33% right after a bucket boundary -> phase 5
- the same load sweeps across bucket phase instead of holding -> phase 5
- the hour window carries the same defect, 10x smaller -> phase 5
- a packet longer than its bucket is credited whole to the bucket
it completed in, so a saturated LONG_SLOW channel reads >100% -> phase 4b
- getSilentMinutes() reads a modular ring as if the index were an
age, so identical airtime gives different answers by phase -> phase 6
Two tests needed correcting during the write, both my expectations rather than
the code: a six-bucket ring sheds whole buckets, so a 30s gap drops three of
five survivors and not "half"; and the oracle sees 59 completions in a 60s
window, not 60, because the one on the lower edge is outside it.
Not written: the planned RX_LOG/RX_ALL_LOG disjointness test. That is a
property of the two radio drivers, which choose one or the other per packet -
it is not observable from AirTime, which records what it is told. The
AirTime-side half is already covered by the routing tests.
None of this was reachable:
air_period_tx / air_period_rx file-scope mirrors of airtimes.periodTX/RX,
accumulated, rotated and memset in lockstep
with them but never read out or serialised.
Orphaned when meshtastic#2552 re-pointed the writes at
bare globals instead of deleting them.
lastUtilPeriod, lastUtilPeriodTX written on every sync, read nowhere
airtimes.lastPeriodIndex written on every rotation, read nowhere
currentPeriodIndex() computes (secs / 3600) % 8 - a modular-ring
index for the one array that is shift-ordered
rather than a ring. Its only two uses were the
dead field above and a log line. It is the
fossil of the same confusion that makes
getSilentMinutes() wrong.
UtilizationPercentTX() declared, never defined
free logAirtime()/airtimeReport() declared, never defined; the latter still
carried the array-returning signature the
previous commit removed, so it actively misled
Also fixes the rotation log line, which read currentPeriodIndex() from inside
the loop although the index is advanced before it - on a multi-hour wake it
printed the same final value once per rotation. It now reports which of the
crossed hours is being rotated.
airtimeRotatePeriod() is kept: it has no caller in the tree either, but unlike
the above it is a defined public method, so out-of-tree callers are plausible.
Measured, not estimated: sizeof(AirTime) 464 -> 456 B, plus 64 B of globals, so
-72 B of static RAM. Padding accounts for the difference from the 66 B the plan
predicted by counting declared bytes.
The whole point of writing the tests first: the suite is green here with zero
test changes.
Comments only, but four of the things they replace were false. The header's example analytics claimed RX_ALL_LOG was "all received lora packets" and offered "RX_ALL_LOG - RX_LOG = other lora radios". Both radio drivers pick exactly one of the two per packet, so they are disjoint: RX_ALL_LOG is airtime we could not parse, the subtraction can go negative, and the total is TX + RX + RX_ALL. Replaced with the actual contract - four inputs, eight outputs, the window each spans, and the fact that the three thresholds are hard-coded members rather than the settings they look like. Names the two storage conventions on their declarations, because mixing them up is what makes getSilentMinutes() wrong: channelUtilization and utilizationTX are modular rings indexed by uptime phase, where the oldest bucket is (current + 1) % N; airtimes.period* is shift-ordered with slot 0 newest, where the index IS an age and slot 0 is a partial hour. Defines the measurement as wall time rather than awake time, and says why: a sleeping node still hears traffic, and per-node redefinition would make two broadcast readings incomparable. Records that the 60s figure is published to the mesh at >= 1h cadence, so what other nodes see is a snapshot - at LONG_FAST and 1% occupancy it reads exactly 0 in about 44% of reports - and that the contention window it feeds moves in 20-percentage-point steps, so small errors never reach the backoff. Finally, states that rotation happens on access rather than on the scheduler tick, names the test that enforces it, and leaves a TODO pointing at the plan phases that fix the characterised accuracy defects.
Two mechanisms solving different halves. A lock-free inner core (Windows) holds all state and all logic; it has no lock and no way to reach one, so nesting is impossible by construction. A private Held token takes the lock in its own constructor and is the only thing that can be passed where a core method demands one, so the lock cannot be forgotten either. The rule is now uniform with no exceptions to remember: every public method takes the lock once and delegates. In particular isTxAllowed*() lock like everything else - before the split they could not, because they called the public accessors and the lock is not recursive. That asymmetry was the foot-gun the previous design documented in prose and hoped nobody would trip. getPeriodsToLog()/getSecondsPerPeriod() still take no lock; they return compile-time constants and touch no state. channelUtilization[] and utilizationTX[] were public, so the lock was bypassable at compile time. They move into the private core. Four test sites reached in; all four now use logAirtime() plus the virtual clock, and no new test seam was needed. Nothing in src/ was affected. The re-entry assert is guarded on PIO_UNIT_TESTING, so it exists in test builds only. The design sketched #ifdef DEBUG, but nothing in this tree defines DEBUG or NDEBUG, so either spelling ships the assert to every board - and nrf52_promicro_diy_tcxo has ~128 bytes of headroom under its 0xEA000 warm-store cap, which the assert's strings and abort path overrun. It would have worked on hardware, since the check runs in Held's owner initialiser and so precedes the blocking take; the objection is that abort()ing a live mesh node is a poor trade for a bug never seen in the field. Native tests are where it earns its keep anyway: Portduino compiles Lock::lock() to an empty body, so a nested take there succeeds silently and nothing else would notice. Also comments out ScopedBusyAirTime in test_traffic_management. It is inert twice over: the module holds no reference to airTime at all since hop exhaustion was shelved, and the fixture never worked anyway - writing the buckets on a fresh AirTime is undone by the first accessor call, which takes the firstTime branch and memsets them. It reported 0%, not the 100% it claimed. Left in place, commented, with both reasons recorded. Cost on the tightest board in the tree, nrf52_promicro_diy_tcxo: the six phases together add 96 bytes of flash, leaving it 32 bytes clear of the warm-store guard. RAM is 72 bytes lower from the dead-state removal. Suite green at 47/47, with test_airtime unedited apart from the added nesting test.
LOG_DEBUG compiles to nothing under DEBUG_MUTE, so the counter's only read disappeared with it and the tally became write-only. It does not warn today - this build has -Wunused-but-set-variable on, and it fires for other locals, but not for one that is only initialised and never read - so it was latent rather than broken: a stricter flag or -Werror would have failed muted builds only. Using the loop variable removes the class of problem, since the loop condition reads it, and drops the elapsedAirtimePeriods-- mutation as a side benefit. Same iteration count, same output. Found by compiling nrf52_promicro_diy_tcxo with -D DEBUG_MUTE, which is worth recording for its own sake: muting logs takes that image from 802 784 to 673 416 bytes, 98.5% to 82.6% of flash. Logging is 16% of the largest nrf52 image, and its 32 bytes of warm-store headroom are a logging-verbosity question rather than a code-size one.
Comment-only: with comments stripped, all five files are byte-identical to the previous commit. Removed the references to the planning notes. Those documents are working material and will go stale; the code should not depend on them. The five CHARACTERISATION tags now describe the defect they pin and stop there, and the accuracy TODO names the four defects and points at the tests instead of a plan file. Also removed, as noise rather than information: - comparisons against pre-meshtastic#11291 behaviour, which nobody reading this needs - a comment describing the lock restructure as future work, written before it landed - speculation ("plausible", "worth pinning so a future...") - an aside arguing with an arithmetic slip made while writing the test Kept the mechanical facts that are slow to re-derive: the two storage orderings and which array uses which, RX_LOG/RX_ALL_LOG disjointness, the locking rule and the addSpanned() constraint that protects it, why the re-entry assert is test-only, and the concrete numbers - (N-1)p + phase, 14 164 ms, the 20 pp contention-window steps. Net 16 comment lines out of src/, 33 out of test/.
PIO_UNIT_TESTING is injected by PlatformIO purely on BUILD_TYPE, with no platform check, so it is defined on an on-target `pio test` run too. The check arms before the lock is taken - a nested take blocks forever, so a later check would never run - which under preemption false-positives on legitimate contention and races on its own write. Derive AIRTIME_REENTRY_CHECK once from PIO_UNIT_TESTING && !HAS_FREE_RTOS and use it at all three sites. Had the three conditions ever diverged, an on-target test build would fail to compile on a member the header no longer declares.
DEBUG_PORT.log() blocks on a UART write, and `lock` is a plain binary
semaphore with no priority inheritance, so holding it across a log call
lets the main thread stall the radio thread in getTxDelayMsec().
Move logAirtime()'s LOG_DEBUG into the shell, after the Held scope
closes; the shell already has both arguments, so nothing has to be
passed back out of the core. isTxAllowed{ChannelUtil,AirUtil} read into
a local under the lock and warn after it. The log bodies are braced
because LOG_DEBUG compiles away under DEBUG_MUTE and a bare `if (x) ;`
trips -Wempty-body.
Fold the two doubled index calls into `+=` while touching the lines.
handleReport() reused one array across the three airtimeReport() calls and ignored the bool. A failed report would have left the previous type's data in place and emitted it under the next type's key. Build each through a lambda whose buffer is zeroed per call, so a failure emits zeros. Unreachable today - the count is always PERIODS_TO_LOG and the type is always valid - but the old shape only read as correct by accident.
Contributor
|
Important Review skippedDraft detected. Please check the settings in the CodeRabbit UI or the ⚙️ Run configurationConfiguration used: Path: .coderabbit.yaml Review profile: CHILL Plan: Pro Plus Run ID: You can disable this status message by setting the Use the checkbox below for a quick retry:
Thanks for using CodeRabbit! It's free for OSS, and your support helps us grow. If you like it, consider giving us a shout-out. Comment |
Contributor
⚡ Try this PR in the Web FlasherNote Building this pull request… the flash button, badges and supported-board |
The header sold the lock as mechanism without naming a second thread, which
invites the reasonable objection that this is a cooperative OSThread codebase.
There is a real race and it is nRF52-only: NRF52Bluetooth registers its ToRadio
write callback with defer == false, so a phone's packet runs handleToRadio ->
sendToMesh -> Router::send on the Bluefruit BLE task, reading
utilizationTXPercent() and getSilentMinutes() while loopTask may be inside
logAirtime(). ESP32 hands BLE work to the main task and does not have it.
Three claims in the header were wrong or overstated:
- "nesting is impossible by construction" - Windows is a nested class with an
enclosing class's access rights, and `extern AirTime *airTime` is in the
same header, so airTime->anyPublicMethod() from inside it is well-formed
and would hang. Nothing does it; the assert is the backstop. Say that
instead, because the comment below instructs contributors to add helpers
to Windows on the strength of the guarantee.
- "every public method takes the lock exactly once" - two constant accessors
take none and isTxAllowedAirUtil() takes it zero or one times. State the
exceptions where the invariant is stated, not only at the definitions.
- "both radio drivers pick exactly one per packet" - five drop paths log
neither. At most one. Recorded against plan4 rather than fixed here: it
changes a telemetry value.
getPeriodsToLog()/getSecondsPerPeriod() become static constexpr, which removes
them from the locking claim structurally and lets ContentHandler size its
buffer and its count from one constant.
Tests:
- C14's saturated AirTime is installed by a helper and restored in tearDown.
Unity's TEST_ABORT() is longjmp and does not run destructors of automatic
objects, so the scoped guard it replaces would leave airTime dangling into
an abandoned frame on any assertion failure - and the same commit that
added it removed the tearDown reset that did cover that.
- test_getSilentMinutes_counts_minutes_until_enough_ages_out asserted only
`mins <= 60`, which neither return path can violate. The answer is 59.
- test_backwards_uptime_degrades_safely stepped 600s -> 60s, which leaves
elapsedAirtimePeriods at 0, so it never reached the hourly-report branch
its own comment describes. Step by the wrap instead and assert the exact
figures.
- test_airtime leaked EU_868 out of the duty-cycle case into every later one,
and the reentry test's isTxAllowedAirUtil() coverage depended on it.
Restore the region in tearDown and set it explicitly where it is wanted.
- Rename that test to what it can actually check: no single method takes the
lock twice. The calls are sequential, so it cannot catch two methods
nesting.
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
5 participants
Add this suggestion to a batch that can be applied as a single commit.This suggestion is invalid because no changes were made to the code.Suggestions cannot be applied while the pull request is closed.Suggestions cannot be applied while viewing a subset of changes.Only one suggestion per line can be applied in a batch.Add this suggestion to a batch that can be applied as a single commit.Applying suggestions on deleted lines is not supported.You must change the existing code in this line in order to create a valid suggestion.Outdated suggestions cannot be applied.This suggestion has been applied or marked resolved.Suggestions cannot be applied from pending reviews.Suggestions cannot be applied on multi-line comments.Suggestions cannot be applied while the pull request is queued to merge.Suggestion cannot be applied right now. Please check back later.
On nRF52,
NRF52Bluetooth::setupMeshService()registers the ToRadio write callback withdefer == false— "we can safely run in the BLE context" — so a packet arriving from a phone runsPhoneAPI::handleToRadio()→MeshService::sendToMesh()→Router::send()directly on the Bluefruit"BLE"task atTASK_PRIO_HIGH.Router::send()readsairTime->utilizationTXPercent()andairTime->getSilentMinutes(). Meanwhile loopTask can be insideRadioLibInterface::handleReceiveInterrupt()callingairTime->logAirtime(RX_LOG, …). That is an unsynchronised read-modify-write ofutilizationTX[]andsecSinceBootagainst a summing read, across two FreeRTOS tasks at unequal priority, andHAS_FREE_RTOSis defined forARDUINO_NRF52_ADAFRUIT. This is not the cooperative-OSThread situationNimbleBluetooth.cppdescribes for ESP32, where BLE work is handed to the main task — nRF52 does no such hand-off, which is exactly why it needs the lock.This PR puts every public method behind a single
concurrency::Lockand moves all state and logic into a private inner struct whose methods each require aconst Held &— a token onlyAirTimecan construct, and only by taking the lock. That token is a deliberate departure from the houseLockGuard-at-top-of-method style used in ~32 other files, and it earns its place here for one reason:AirTime's entry points call each other.isTxAllowedChannelUtil()used to call the publicchannelUtilizationPercent(), andlogAirtime()callssyncNow(); with a plain guard, any of those becoming a public call again is a silent deadlock, becauseconcurrency::Lockis a non-recursive binary semaphore taken withportMAX_DELAY. The token makes "forgot to lock" unrepresentable and "locked twice" a compile-time shape rather than a runtime hang. NodeDB'ssatelliteMutex, by contrast, guards leaf accessors that never re-enter, which is why comments suffice there.airtimeReport()changes signature, and that is a fix rather than an API tidy: it used to return auint32_t *intoairtimes.period*[], and every other entry point'ssyncNow()can rotate those buckets underneath the caller —ContentHandler::handleReport()held that pointer across three serialisation steps. It now copies into a caller-supplied buffer and returnsbool.channelUtilization[]andutilizationTX[]also move from public members to private state — a breaking change for out-of-tree code touching them directly;airtimeRotatePeriod()is kept as a shim for the same reason. Dead members go too: the write-onlyair_period_tx/rxglobals orphaned when #2552 dropped theMyNodeInfofields they backed, the declared-but-undefinedUtilizationPercentTX()and two free-function declarations, andlastUtilPeriod,lastUtilPeriodTX,lastPeriodIndexandcurrentPeriodIndex(), none of which was ever read.No telemetry value changes. The new
test/test_airtimesuite (63 cases) covers window decay, the TX gates, sleep andmillis()-wrap behaviour, the report API and the log-dispatch contract. Five known accuracy defects are measured and pinned asCHARACTERISATIONtests rather than fixed — the quantised denominator and its sawtooth, whole-packet attribution to the completing bucket, andgetSilentMinutes()reading a modular ring as though the index encoded age. Each is recorded inairtime.h's TODO and fixed in a follow-up PR, so this one stays reviewable as pure structure.Two things a reviewer should know
The test suite proves structure, not mutual exclusion.
concurrency::Lockcompiles to four empty bodies outsideHAS_FREE_RTOS, so on Portduino the lock provides no protection and no native test can demonstrate the race is fixed. What the suite does check is the shape the safety rests on:test_no_public_method_takes_the_lock_twicewalks every entry point with a host-only re-entry assert armed, which catches a method re-entering itself — the failure that would be a silent hang on hardware. The safety argument is compile-time and by inspection; the tests protect the inspection from rotting.test_packet_signingfails B11 and B12 under-e coverage; not caused by this PR, and fixed separately. Both reproduce identically on the base branch (time-handling@92cb34456): 2 failed / 73 succeeded, same two cases. They run atRUN_TEST#2098-2099, before the only case this PR touches in that file (C14, #2116). Note they pass under-e native— the difference is the coverage env's ASan/gcov build, which is what CI runs.Changed functions
src/airtime.hclass AirTime— gainsconcurrency::Lock lock, the privateHeldtoken class, and the privateWindowsstruct holding all stateAirTime::Held::Held/~Held/armReentryCheck— new; takes the lock and doubles as proof it is heldAIRTIME_REENTRY_CHECK— new macro,PIO_UNIT_TESTING && !HAS_FREE_RTOS; arms the host-only nested-take assertairtimeReport()— signature change:uint32_t *(reportTypes)→bool(reportTypes, uint32_t *, size_t)getPeriodsToLog()/getSecondsPerPeriod()— nowstatic constexpr, so a caller's buffer and the count it passes can be tied to one constant.airTime->getPeriodsToLog()still compiles; taking the member's address no longer doesUtilizationPercentTX(),currentPeriodIndex(), the publicchannelUtilization[]andutilizationTX[],lastUtilPeriod,lastUtilPeriodTX,airtimeStruct::lastPeriodIndex, and the freelogAirtime()/airtimeReport()declarationssrc/airtime.cppAirTime::logAirtime— now a locking shell; logs after releasing, becauseDEBUG_PORT.log()blocks on a UART write and the lock has no priority inheritanceAirTime::Windows::logAirtime— the former body, minus theLOG_DEBUGcallsAirTime::Windows::syncNow— unchanged logic; rotation counted by the loop variable soDEBUG_MUTEcannot leave a write-only tallyAirTime::Windows::airtimeReport— copies out, validatesoutandcountAirTime::Windows::channelUtilizationPercent,utilizationTXPercent,getSilentMinutes,getPeriodUtilMinute,getPeriodUtilHour— moved into the core, each requiringconst Held &AirTime::isTxAllowedChannelUtil,AirTime::isTxAllowedAirUtil— call the core, not the public accessors, and warn outside the lockAirTime::channelUtilizationPercent,utilizationTXPercent,getSecondsSinceBoot,getSilentMinutes,airtimeRotatePeriod,runOnce— thin locking shellssrc/mesh/http/ContentHandler.cpphandleReport()— uses the copy-out API via areportFor()lambda whose buffer and count both come fromAirTime::getPeriodsToLog()Tests
test/test_airtime/test_main.cpp— new suite, 63 cases.setUp/tearDownsnapshot and restore the region, role andoverride_duty_cycleso a duty-cycle case cannot leak its region into later ones;test_no_public_method_takes_the_lock_twicesets EU_868 explicitly rather than inheriting it, sinceisTxAllowedAirUtil()only locks inside its duty-cycle branchtest/test_packet_signing/test_main.cpp— C14's saturatedAirTimeis installed by a helper and restored intearDown(), not by a scoped guard: Unity'sTEST_ABORT()islongjmpand does not run destructors of automatic objectstest/test_traffic_management/test_main.cpp—ScopedBusyAirTimeretired; it was inert (shouldExhaustHops()reads members nothing sets to true)🤝 Attestations