diff --git a/.github/workflows/run-unit-tests.yml b/.github/workflows/run-unit-tests.yml index 985a5f10a..f053a53a5 100644 --- a/.github/workflows/run-unit-tests.yml +++ b/.github/workflows/run-unit-tests.yml @@ -342,6 +342,8 @@ jobs: python3 -B test/test_drv2605_power.py -v python3 -B test/test_radio_interrupt_recovery.py -v python3 -B test/test_radio_rx_activity_epoch.py -v + python3 -B test/test_esp32_radio_trace.py -v + python3 -B test/test_esp32_radio_trace_cli.py -v python3 -B test/test_forwarding_profile_timing.py -v python3 -B test/test_clock_transit_profile_timing.py -v python3 -B test/test_bridge_recovery.py -v diff --git a/docs/test-results/esp32_ble_radio2_sleep_2026-10-21.md b/docs/test-results/esp32_ble_radio2_sleep_2026-10-21.md index 59b57b9cf..e91c0fcac 100644 --- a/docs/test-results/esp32_ble_radio2_sleep_2026-10-21.md +++ b/docs/test-results/esp32_ble_radio2_sleep_2026-10-21.md @@ -460,8 +460,8 @@ The immutable receipt is `v4-a5293fa5-awake-completed.private.json` (SHA-256 The stale-IRQ regression proves a receive-path bug and the new guard repairs that case. This physical sample does not establish which historical misses encountered it or show that all scanning losses are fixed. A controlled -two-transmitter overlap diagnostic is pending; no result or cause is claimed -for that experiment here. +two-transmitter overlap diagnostic is recorded below; it does not establish a +cause for these historical misses. ### Receive activity across RX restarts @@ -485,19 +485,93 @@ ASan/UBSan variants, including reset-removal controls that reproduce the retune over a new packet for all six handlers. All 19 affected host-fixture tests and 26 interrupt-recovery, receive-contract and receive-retry checks pass. The new suite runs in the required unit-test workflow. Physical RF -validation remains pending; this proof does not attribute historical missing -nonces or establish a complete RF pass. The installed versions and packet -counts above remain unchanged. +results on the new image are recorded below. The host proof does not attribute +historical missing nonces or establish a complete RF pass. + +## RX-restart installation and overlap diagnostic + +The V4 image built from pushed source +[`e4119a120`](https://github.com/mikecarper/MeshCore/commit/e4119a1206efefc0506c12ebe529883b966784f5) +passes its capability and memory gates at 2,558,984 application bytes. Its +application SHA-256 is +`fc1a835c45ebc5e7a9fec95c757d8606e145bbc92fa8d365ba62d96a7930286d`. +The application-only installation passed full readback and checked +configuration preservation. The receipt is +`flash-v4-e4119a12-completed.private.json` (SHA-256 +`b06d8b6ef8d9df9aa881d6d1ca2f6096d19c8bcc6d4cbb2873fb20d47a9f85c5`). + +Two overlap conditions completed on this image at 80 MHz with manual CPU sleep +off. Each condition sent 20 unique primary/secondary pairs; all 40 sends +reached TX_DONE once, with zero retries or duplicate deliveries and zero SDK +counters in both conditions. + +| Condition | Primary received | Secondary received | +| --- | --- | --- | +| Radio2 scanning | 16/20 | 2/20 | +| Fixed 916 MHz, radio2 off | 0/20 (outside receive frequency) | 20/20 | + +All 20 scanner timing bounds were inconclusive. The nominal 140 ms secondary +write occurred 227.239-263.257 ms after the primary write (median 244.363 ms), +while the first counter reply confirming primary TX_DONE arrived +523.533-903.982 ms after that write. That reply bounds completion; it does not +timestamp the RF event. The controller synchronously saved the report before +the secondary write and after each counter reply, widening these bounds. +The analysis uses 101-byte wire airtimes of 397.824/652.288 ms, a complete +148.480 ms secondary preamble and a 2 ms margin. No pair proves that the whole +secondary preamble fell inside the primary payload reception. The timings +do not exclude desense or attribute historical misses. The ordinary +alternating-profile check is recorded below. + +Three earlier setup attempts sent no RF: the first two stopped before +mutation; the third encountered a pending lease, with separate V3 automatic +cleanup recovery passing. The overlap experiment completed with an +inconclusive status: neither condition has a qualified timing pair, so masking +was not demonstrated. Full restoration of all three boards passed without +errors, and a fresh MQTT PUBACK verified recovery. The final host receipt is +`/home/mesh/hwtest/esp32-radio2-pson-v3-v4-20261021/overlap-v4-e4119a12-completed.private.json` +(SHA-256 +`c1aee5132b447734df3fe9c663f4f3ae7a8b980f3165de43f96c2653d05200e1`). +No firmware qualification pass is claimed. + +## Ordinary awake check after both receive fixes + +The predeclared `e4119a120` check sent 20 new packets per profile, once each, +with the ordinary alternating schedule and no deliberate overlapping sender. +It received **17/20 primary and 18/20 secondary packets**. All 40 sends reached +TX_DONE once; duplicates, RF retries and SDK sleep calls were zero. The strict +RF result remains failed. The physical counters recorded 120 successful raw +receives: 35 owned direct packets and 85 ambient floods, with seven separate +receive errors. These totals do not identify the cause of each missing nonce. +The immutable receipt is `v4-e4119a12-awake-completed.private.json` (SHA-256 +`9f2f8acecc634ebaf7b9e9aa21e51079b9872316e571a886d3866bfedabab558`). + +That receipt also retains a cleanup failure: restoring automatic radio2 +permission was rejected while the temporary primary restore was still pending. +Fresh MQTT recovery passed. A separate guarded operation subsequently restored +automatic permission with one setter and no RF transmissions, then verified +the checked settings, credentials and channel semantics against the baseline. +Its receipt is `v4-auto-restoration-after-e411-awake.private.json` (SHA-256 +`4dbf10eeac81e8897c8a4f9fa4d7b62ac20e74c91b467a501f31fa3a1d8bd0ec`). + +Both receive defects remain proven by executed host regressions, but the +physical results show that additional losses remain. The next diagnostic +records bounded activity and transmission times on the radios themselves. +It must distinguish other-profile ownership, unresolved preamble activity, +read/rearm gaps and delays between scanner calls without treating host counter +replies as RF timestamps. No arbitrary preamble or CPU-sleep setting change +or replacement packet was used to turn a failed result into a pass. ## Final handback and limits -V3 currently runs `7d0709bf0`; V4 runs `a5293fa50`, and the peer remains on -`ebb59d48`. The completed V3 campaign and V4 scanning controls, including the -new awake run, restored their checked radio, RX power-saving, +V3 currently runs `7d0709bf0`; V4 runs `e4119a120`, and the peer remains on +`ebb59d48`. The completed earlier V3 campaign and V4 scanning controls, +including the `a5293fa50` awake run, restored their checked radio, RX power-saving, Bluetooth, WiFi, MQTT, logging, diagnostics and USB-watchdog settings, including credential digests, original radio2 automatic permission and peer power/channel state. Fresh MQTT PUBACK increases verified recovery. The fixed-tuple cleanup power failure is retained, with the later peer recovery verified separately. +Full overlap restoration is verified. The ordinary run's original cleanup +failure is retained, with its separate automatic-permission recovery verified. No nRF52 board, hub power or other firmware was changed in this task. The Bluetooth hardware checks pass. SDK light-sleep calls are observed without diff --git a/examples/companion_radio/MyMesh.cpp b/examples/companion_radio/MyMesh.cpp index 8bf593d24..6564cd307 100644 --- a/examples/companion_radio/MyMesh.cpp +++ b/examples/companion_radio/MyMesh.cpp @@ -30,6 +30,9 @@ #if defined(MESH_SOAK_DIAGNOSTICS) #include "../../tools/hil/S3SoakDiagnostics.h" #endif +#if defined(ESP32_PLATFORM) && defined(MESH_HIL_RADIO_TRACE) && MESH_HIL_RADIO_TRACE +#include +#endif #include // needed for PlatformIO #include @@ -10645,6 +10648,9 @@ bool MyMesh::handleDirectCommand(const char* command, char* reply, size_t reply_ #if defined(MESH_SOAK_DIAGNOSTICS) if (mesh::hil::handleSoakCommand(command, reply, reply_size)) return true; #endif +#if defined(ESP32_PLATFORM) && defined(MESH_HIL_RADIO_TRACE) && MESH_HIL_RADIO_TRACE + if (mesh::radiotrace::handleTraceCommand(command, reply, reply_size)) return true; +#endif #if MESH_ENABLE_ONE_KEY_DM if (strcmp(command, "get dm.one_key") == 0) { snprintf(reply, reply_size, "> %s", _prefs.one_key_dm_enabled == 1 ? "on" : "off"); diff --git a/src/helpers/radiolib/CustomSX1262.h b/src/helpers/radiolib/CustomSX1262.h index f4e40bd50..4f9bb2cd0 100644 --- a/src/helpers/radiolib/CustomSX1262.h +++ b/src/helpers/radiolib/CustomSX1262.h @@ -7,6 +7,7 @@ #include "RXPowerSaving.h" #include "SX1262ProfileSwitchState.h" #include "SX126xMorseRssi.h" +#include "ESP32RadioTrace.h" #if defined(STATION_G3_ESP32) #include #endif @@ -46,6 +47,12 @@ #endif class CustomSX1262 : public SX1262 { +#if MESH_RADIO_TRACE_ENABLED + void traceOperation(mesh::radiotrace::Reason reason) { + if (mesh::radiotrace::trace().pending()) + mesh::radiotrace::trace().operation(static_cast(this), mesh::radiotrace::nowUs(), reason); + } +#endif #if defined(SX126X_USE_REGULATOR_LDO) && SX126X_USE_REGULATOR_LDO mesh::power::RadioRegulatorState _regulator{mesh::power::REGULATOR_LDO, mesh::power::RegulatorMode::Ldo}; #else @@ -139,6 +146,9 @@ class CustomSX1262 : public SX1262 { } int16_t standby() override { +#if MESH_RADIO_TRACE_ENABLED + traceOperation(mesh::radiotrace::Reconfigure); +#endif const bool alreadyAwake = !_coldStandby && _profileSwitch.active && _profileSwitch.rxValid; if (!alreadyAwake) _profileSwitch.invalidate(); int16_t rc; @@ -163,6 +173,9 @@ class CustomSX1262 : public SX1262 { return rc; } int16_t standby(uint8_t mode) override { +#if MESH_RADIO_TRACE_ENABLED + traceOperation(mesh::radiotrace::Reconfigure); +#endif _profileSwitch.invalidate(); int16_t rc = SX1262::standby(mode); if (rc == RADIOLIB_ERR_NONE) rc = restoreTcxoAfterSleep(); @@ -175,14 +188,26 @@ class CustomSX1262 : public SX1262 { // retaining the requested warm policy for subsequent established RX. int16_t sleep() override { return sleep(true); } int16_t sleep(bool retainConfig) { +#if MESH_RADIO_TRACE_ENABLED + traceOperation(mesh::radiotrace::Recovery); +#endif _profileSwitch.invalidate(); _coldStandby = true; const int16_t rc = SX1262::standby(RADIOLIB_SX126X_STANDBY_RC); _tcxoWakePending = tcxoVoltage > 0.0f; return rc == RADIOLIB_ERR_NONE ? SX1262::sleep(retainConfig) : rc; } - int16_t reset(bool verify = true) { _profileSwitch.invalidate(); _coldStandby = true; _tcxoWakePending = false; return SX1262::reset(verify); } + int16_t reset(bool verify = true) { +#if MESH_RADIO_TRACE_ENABLED + traceOperation(mesh::radiotrace::Recovery); +#endif + _profileSwitch.invalidate(); _coldStandby = true; _tcxoWakePending = false; + return SX1262::reset(verify); + } int16_t stageMode(RadioModeType_t mode, RadioModeConfig_t* cfg) override { +#if MESH_RADIO_TRACE_ENABLED + traceOperation(mode == RADIOLIB_RADIO_MODE_TX ? mesh::radiotrace::Transmit : mesh::radiotrace::Rearm); +#endif // All ordinary RX/TX staging rebuilds hardware state. In particular TX // changes IRQ mapping, packet length and buffer contents/base settings. _profileSwitch.invalidate(); @@ -541,6 +566,11 @@ class CustomSX1262 : public SX1262 { int16_t startReceiveDutyCycle(uint32_t rxPeriod, uint32_t sleepPeriod, RadioLibIrqFlags_t irqFlags = RADIOLIB_IRQ_RX_DEFAULT_FLAGS, RadioLibIrqFlags_t irqMask = RADIOLIB_IRQ_RX_DEFAULT_MASK) { +#if MESH_RADIO_TRACE_ENABLED + const bool tracing = mesh::radiotrace::trace().pending(); + const uint64_t trace_before = tracing ? mesh::radiotrace::nowUs() : 0; + if (tracing) traceOperation(mesh::radiotrace::Rearm); +#endif _profileSwitch.invalidate(); _coldStandby = true; int16_t state = SX1262::startReceiveDutyCycle(rxPeriod, sleepPeriod, irqFlags, irqMask); @@ -554,6 +584,10 @@ class CustomSX1262 : public SX1262 { _activityAt = 0; _headerSeen = false; } +#if MESH_RADIO_TRACE_ENABLED + if (tracing) mesh::radiotrace::trace().receiveEntry(static_cast(this), + trace_before, mesh::radiotrace::nowUs(), state); +#endif return state; } @@ -619,8 +653,20 @@ class CustomSX1262 : public SX1262 { } this->mod->setRfSwitchState(this->txMode); +#if MESH_RADIO_TRACE_ENABLED + const bool tracing = mesh::radiotrace::trace().pending(); + const uint64_t trace_before = tracing ? mesh::radiotrace::nowUs() : 0; + if (tracing) mesh::radiotrace::trace().transmitLaunchBegin(static_cast(this), trace_before); +#endif int16_t state = this->setTx(RADIOLIB_SX126X_TX_TIMEOUT_NONE); +#if MESH_RADIO_TRACE_ENABLED + const uint64_t trace_after = tracing ? mesh::radiotrace::nowUs() : 0; +#endif if (state != RADIOLIB_ERR_NONE) { +#if MESH_RADIO_TRACE_ENABLED + if (tracing) mesh::radiotrace::trace().transmitLaunch(static_cast(this), + trace_before, trace_after, 0, state); +#endif this->stagedMode = RADIOLIB_RADIO_MODE_NONE; return state; } @@ -629,11 +675,21 @@ class CustomSX1262 : public SX1262 { while (isChipBusy()) { this->mod->hal->yield(); if (this->mod->hal->millis() - started >= SX126X_TX_BUSY_TIMEOUT_MS) { +#if MESH_RADIO_TRACE_ENABLED + if (tracing) mesh::radiotrace::trace().transmitLaunch(static_cast(this), + trace_before, trace_after, 0, RADIOLIB_ERR_SPI_CMD_TIMEOUT); +#endif this->stagedMode = RADIOLIB_RADIO_MODE_NONE; return RADIOLIB_ERR_SPI_CMD_TIMEOUT; } } +#if MESH_RADIO_TRACE_ENABLED + if (tracing) { + const uint64_t after = mesh::radiotrace::nowUs(); + mesh::radiotrace::trace().transmitLaunch(static_cast(this), trace_before, trace_after, after, RADIOLIB_ERR_NONE); + } +#endif this->stagedMode = RADIOLIB_RADIO_MODE_NONE; return RADIOLIB_ERR_NONE; } @@ -671,6 +727,11 @@ class CustomSX1262 : public SX1262 { #endif int16_t startReceive() override { +#if MESH_RADIO_TRACE_ENABLED + const bool tracing = mesh::radiotrace::trace().pending(); + const uint64_t trace_before = tracing ? mesh::radiotrace::nowUs() : 0; + if (tracing) traceOperation(mesh::radiotrace::Rearm); +#endif if (_profileSwitch.canResumeFast()) { // Existing continuous RX already established buffer bases and the // MeshCore IRQ map (including preamble detection). No TX/CAD/sleep/ @@ -723,6 +784,10 @@ class CustomSX1262 : public SX1262 { } _coldStandby = rc != RADIOLIB_ERR_NONE; _profileSwitch.rxResult(rc, true); +#if MESH_RADIO_TRACE_ENABLED + if (tracing) mesh::radiotrace::trace().receiveEntry(static_cast(this), + trace_before, mesh::radiotrace::nowUs(), rc); +#endif return rc; } // Make preamble detection visible to CAD while retaining RadioLib's @@ -745,11 +810,46 @@ class CustomSX1262 : public SX1262 { _profileSwitch.packetResult(rc, preambleLengthLoRa, crcTypeLoRa, implicitLen, headerType, invertIQEnabled); } +#if MESH_RADIO_TRACE_ENABLED + if (tracing) mesh::radiotrace::trace().receiveEntry(static_cast(this), + trace_before, mesh::radiotrace::nowUs(), rc); +#endif return rc; } +#if MESH_RADIO_TRACE_ENABLED + uint32_t getIrqFlags() override { + // Preserve the existing transaction and return bytes, including its + // legacy error behavior. Only the trace retains the checked SPI result; + // an unverified zero must never become an event-time lower bound. + const bool tracing = mesh::radiotrace::trace().pending(); + const uint64_t before = tracing ? mesh::radiotrace::nowUs() : 0; + uint8_t data[] = {0, 0}; + const int16_t result = this->mod->SPIreadStream(RADIOLIB_SX126X_CMD_GET_IRQ_STATUS, data, 2); + const uint32_t irq = (uint32_t(data[0]) << 8) | data[1]; + if (tracing) mesh::radiotrace::trace().irq(static_cast(this), + before, mesh::radiotrace::nowUs(), result, irq); + return irq; + } +#endif + bool isReceiving() { - if (isChipBusy()) return false; // asleep, cannot be mid-receive +#if MESH_RADIO_TRACE_ENABLED + const bool tracing = mesh::radiotrace::trace().pending(); + const uint64_t trace_before = tracing ? mesh::radiotrace::nowUs() : 0; + const auto observed = [this, tracing, trace_before](bool held, bool header, mesh::radiotrace::Reason reason) { + if (tracing) mesh::radiotrace::trace().activity(static_cast(this), + trace_before, mesh::radiotrace::nowUs(), held, header, reason); + return held; + }; +#endif + if (isChipBusy()) { +#if MESH_RADIO_TRACE_ENABLED + return observed(false, false, mesh::radiotrace::FlagsCleared); +#else + return false; // asleep, cannot be mid-receive +#endif + } uint32_t irq = getIrqFlags(); bool preamble = irq & RADIOLIB_SX126X_IRQ_PREAMBLE_DETECTED; // bit 2 @@ -760,13 +860,21 @@ class CustomSX1262 : public SX1262 { clearIrqFlags(RADIOLIB_SX126X_IRQ_PREAMBLE_DETECTED | RADIOLIB_SX126X_IRQ_HEADER_VALID | RADIOLIB_SX126X_IRQ_HEADER_ERR | RADIOLIB_SX126X_IRQ_SYNC_WORD_VALID); _activityAt = 0; _headerSeen = false; +#if MESH_RADIO_TRACE_ENABLED + return observed(false, false, mesh::radiotrace::HeaderError); +#else return false; +#endif } if (!header && _headerSeen) { // Another path consumed the header IRQ; reset only our local timer. _activityAt = 0; _headerSeen = false; +#if MESH_RADIO_TRACE_ENABLED + return observed(false, false, mesh::radiotrace::FlagsCleared); +#else return false; +#endif } if (header) { if (!_headerSeen) { _headerSeen = true; _activityAt = now; }; @@ -774,9 +882,17 @@ class CustomSX1262 : public SX1262 { MESH_DEBUG_PRINTLN("Clearing header IRQ after %ums", _maxPayloadMillis); clearIrqFlags(RADIOLIB_SX126X_IRQ_PREAMBLE_DETECTED | RADIOLIB_SX126X_IRQ_HEADER_VALID | RADIOLIB_SX126X_IRQ_HEADER_ERR | RADIOLIB_SX126X_IRQ_SYNC_WORD_VALID); _activityAt = 0; _headerSeen = false; +#if MESH_RADIO_TRACE_ENABLED + return observed(false, true, mesh::radiotrace::PayloadExpired); +#else return false; +#endif } +#if MESH_RADIO_TRACE_ENABLED + return observed(true, true, mesh::radiotrace::None); +#else return true; +#endif } if (preamble) { @@ -786,12 +902,24 @@ class CustomSX1262 : public SX1262 { _activityAt = 0; MESH_DEBUG_PRINTLN("Clearing preamble IRQ after %ums", _preambleMillis); +#if MESH_RADIO_TRACE_ENABLED + return observed(false, false, mesh::radiotrace::PreambleExpired); +#else return false; +#endif } +#if MESH_RADIO_TRACE_ENABLED + return observed(true, false, mesh::radiotrace::None); +#else return true; +#endif } _activityAt = 0; _headerSeen = false; +#if MESH_RADIO_TRACE_ENABLED + return observed(false, false, mesh::radiotrace::FlagsCleared); +#else return false; +#endif } bool canUseRxPowerSavingDutyCycle(uint32_t rx_us, uint32_t sleep_us) const { diff --git a/src/helpers/radiolib/ESP32RadioTrace.cpp b/src/helpers/radiolib/ESP32RadioTrace.cpp new file mode 100644 index 000000000..9eb32362a --- /dev/null +++ b/src/helpers/radiolib/ESP32RadioTrace.cpp @@ -0,0 +1,29 @@ +#include "ESP32RadioTrace.h" + +#if MESH_RADIO_TRACE_ENABLED +#include +#include + +namespace mesh { +namespace radiotrace { + +Trace& trace() { + static Trace value; + return value; +} + +uint64_t nowUs() { return static_cast(esp_timer_get_time()); } + +uint64_t fingerprint(const uint8_t* bytes, size_t length) { + uint8_t hash[8]; + mesh::Utils::sha256(hash, sizeof(hash), bytes, static_cast(length)); + // The schema is an integer rendered as 16 hex digits, independent of host + // endianness. It hashes complete wire bytes, including the route header. + uint64_t result = 0; + for (uint8_t value : hash) result = (result << 8) | value; + return result; +} + +} // namespace radiotrace +} // namespace mesh +#endif diff --git a/src/helpers/radiolib/ESP32RadioTrace.h b/src/helpers/radiolib/ESP32RadioTrace.h new file mode 100644 index 000000000..d0886548b --- /dev/null +++ b/src/helpers/radiolib/ESP32RadioTrace.h @@ -0,0 +1,372 @@ +#pragma once + +#if defined(ESP32_PLATFORM) && defined(MESH_HIL_RADIO_TRACE) && MESH_HIL_RADIO_TRACE +#define MESH_RADIO_TRACE_ENABLED 1 + +#include +#include + +namespace mesh { +namespace radiotrace { + +// Explicit lab builds only. No I/O, allocation, extra radio polling, or policy +// decisions occur here. Times are microseconds relative to a bounded capture. +enum class State : uint8_t { Off = 0, Armed = 1, Capturing = 2, Frozen = 3 }; +enum Reason : uint8_t { + None = 0, HeaderError = 1, PreambleExpired = 2, PayloadExpired = 3, + FlagsCleared = 4, Reconfigure = 5, ReceiveRead = 6, Rearm = 7, + Transmit = 8, Recovery = 9, CaptureEnded = 10, SpiFailure = 11, +}; +enum Flag : uint8_t { + Invalid = 1, SpiError = 2, MissingBound = 4, Interrupted = 8, + Clipped = 16, NotConfirmed = 32, RearmFailed = 64, ReadError = 128, +}; + +static constexpr uint32_t MaxCaptureMs = 180000; +static constexpr uint32_t MaxDelayMs = 180000; +static constexpr uint32_t BucketWidthUs = 3000000; +static constexpr uint16_t NoIndex = UINT16_MAX; +static constexpr uint32_t NoTime = UINT32_MAX; +#if defined(MESH_HIL_RADIO_TRACE_TX_ONLY) && MESH_HIL_RADIO_TRACE_TX_ONLY +static constexpr size_t SpanCapacity = 0, RxCapacity = 0, BucketCapacity = 0; +static constexpr const char* Marker = "MCRFTRACE1:TXONLY40"; +#else +static constexpr size_t SpanCapacity = 192, RxCapacity = 192, BucketCapacity = 64; +static constexpr const char* Marker = "MCRFTRACE1:RX192:TX40"; +#endif +static constexpr size_t TxCapacity = 40; + +struct Span { + uint32_t begin_us, header_us, end_us; + uint16_t rx_index; + uint8_t profile, reason; +}; +struct RxRecord { + uint32_t done_lo_us, done_hi_us, read_begin_us, rearm_end_us; + uint64_t hash64; + uint16_t len, span_index; + uint8_t profile, flags; + uint16_t reserved; +}; +struct TxRecord { + uint64_t hash64; + uint32_t launch_lo_us, launch_hi_us, busy_low_us; + uint32_t done_lo_us, done_hi_us, toa_us; + uint16_t len; + uint8_t profile, flags; + uint32_t spi_errors; +}; +struct Bucket { + uint32_t start_us, max_scan_gap_us, max_visit_overdue_us; + uint32_t max_scan_gap_end_us, max_visit_overdue_end_us; +}; +static_assert(sizeof(Span) == 16, "Radio trace span layout changed"); +static_assert(sizeof(RxRecord) == 32, "Radio trace RX layout changed"); +static_assert(sizeof(TxRecord) == 40, "Radio trace TX layout changed"); + +class Trace { + const void* _phy = nullptr; + uint8_t _profile = 0; + uint32_t _generation = 0; + uint32_t _seen_generation[2] = {}; + uint8_t _seen_profiles = 0; + uint16_t _hold = NoIndex, _reading = NoIndex, _sending = NoIndex; + uint16_t _last_hold = NoIndex; + bool _rx_mode = false, _rx_lo_valid = false, _rx_done = false; + bool _tx_lo_valid = false, _tx_done = false; + uint32_t _rx_lo = 0, _rx_hi = 0, _tx_lo = 0, _last_scan = NoTime; + + bool owner(const void* phy) const { return phy != nullptr && phy == _phy; } + uint32_t relative(uint64_t now) const { + return now <= epoch_us ? 0 : static_cast(now - epoch_us); + } + void resetCounters() { + span_count = rx_count = tx_count = bucket_count = 0; + span_dropped = rx_dropped = tx_dropped = spi_errors = invalidations = 0; + context_errors = max_scan_gap_us = max_visit_overdue_us = max_blackout_us = 0; + flags = 0; + _hold = _reading = _sending = _last_hold = NoIndex; + _rx_mode = false; + _rx_lo_valid = _rx_done = _tx_lo_valid = _tx_done = false; + _last_scan = NoTime; + _seen_profiles = 0; + } + void invalidate(uint8_t detail) { + ++invalidations; + flags |= uint32_t(Invalid | detail); + if (_reading != NoIndex) rx[_reading].flags |= uint8_t(Invalid | detail); + if (_sending != NoIndex) tx[_sending].flags |= uint8_t(Invalid | detail); + } + void closeHold(uint32_t when, Reason reason) { + if (_hold == NoIndex) return; + Span& span = spans[_hold]; + span.end_us = when < span.begin_us ? span.begin_us : when; + span.reason = reason; + _last_hold = _hold; + _hold = NoIndex; + } + void freeze(uint64_t when) { + const uint32_t stamp = relative(when > end_us ? end_us : when); + closeHold(stamp, CaptureEnded); + if (_sending != NoIndex) { + tx[_sending].flags |= uint8_t(Invalid | Clipped | NotConfirmed); + _sending = NoIndex; + invalidate(Clipped); + } + if (_reading != NoIndex) { + rx[_reading].flags |= uint8_t(Invalid | Clipped); + _reading = NoIndex; + invalidate(Clipped); + } + state = State::Frozen; + } + +public: + State state = State::Off; + uint32_t session = 0; + uint64_t epoch_us = 0, end_us = 0; + uint32_t span_count = 0, rx_count = 0, tx_count = 0, bucket_count = 0; + uint32_t span_dropped = 0, rx_dropped = 0, tx_dropped = 0; + uint32_t spi_errors = 0, invalidations = 0, context_errors = 0; + uint32_t max_scan_gap_us = 0, max_visit_overdue_us = 0, max_blackout_us = 0; + uint32_t flags = 0; + Span spans[SpanCapacity ? SpanCapacity : 1] = {}; + RxRecord rx[RxCapacity ? RxCapacity : 1] = {}; + TxRecord tx[TxCapacity] = {}; + Bucket buckets[BucketCapacity ? BucketCapacity : 1] = {}; + + bool pending() const { return state == State::Armed || state == State::Capturing; } + bool arm(uint64_t now, uint32_t delay_ms, uint32_t duration_ms) { + if (pending() || delay_ms > MaxDelayMs || !duration_ms || duration_ms > MaxCaptureMs) + return false; + resetCounters(); + ++session; + if (!session) ++session; + epoch_us = now + uint64_t(delay_ms) * 1000; + end_us = epoch_us + uint64_t(duration_ms) * 1000; + state = State::Armed; + return true; + } + void stop(uint64_t now) { if (pending()) freeze(now); } + bool tick(uint64_t now) { + if (!pending()) return false; + if (now >= end_us) { freeze(end_us); return false; } + if (now < epoch_us) return false; + if (state == State::Armed) { + state = State::Capturing; + // Existing activity at the boundary has no observed beginning. Subsequent + // true polls can establish a conservative, shorter ownership span. + _rx_lo_valid = _rx_done = _tx_lo_valid = _tx_done = false; + } + return true; + } + void context(const void* phy, uint8_t profile, uint32_t generation) { + if (!_phy || !pending()) _phy = phy; + if (!owner(phy)) { + if (pending()) { ++context_errors; invalidate(Interrupted); } + return; + } + if (profile > 1) { + if (pending()) { ++context_errors; invalidate(Interrupted); } + return; + } + if (pending()) { + const uint8_t bit = uint8_t(1U << profile); + // The sender-only experiment deliberately replaces its single physical + // tuple between completed transmissions. Receiver captures require a + // stable pair; neither mode permits changing an in-flight TX epoch. + if (RxCapacity && state == State::Capturing && (_seen_profiles & bit) + && _seen_generation[profile] != generation) invalidate(Interrupted); + _seen_generation[profile] = generation; + _seen_profiles |= bit; + } + if (state == State::Capturing && (profile != _profile || generation != _generation)) { + if (_hold != NoIndex) invalidate(Interrupted); + if (_sending != NoIndex) { + invalidate(Interrupted); + _tx_lo_valid = _tx_done = false; + } + closeHold(_last_scan == NoTime ? 0 : _last_scan, Reconfigure); + _rx_lo_valid = _rx_done = false; + } + _profile = profile; + _generation = generation; + } + void operation(const void* phy, uint64_t now, Reason reason) { + if (!owner(phy) || !pending()) return; + const bool capturing = tick(now); + _rx_mode = false; + _rx_lo_valid = _rx_done = false; + if (capturing) closeHold(relative(now), reason); + } + void receiveEntry(const void* phy, uint64_t before, uint64_t after, int16_t result) { + if (!owner(phy) || !pending()) return; + const bool capturing = tick(after); + _rx_mode = result == 0; + _rx_lo_valid = _rx_done = false; + if (!capturing) return; + closeHold(relative(before), Rearm); + if (_reading != NoIndex) { + RxRecord& record = rx[_reading]; + record.rearm_end_us = relative(after); + const uint32_t elapsed = record.rearm_end_us - record.read_begin_us; + if (elapsed > max_blackout_us) max_blackout_us = elapsed; + if (result != 0) record.flags |= uint8_t(Invalid | RearmFailed); + } + } + void dio(const void* phy, uint64_t before, uint64_t after, bool high) { + if (!owner(phy) || !tick(after) || high || before < epoch_us) return; + if (_sending != NoIndex && tx[_sending].launch_lo_us != NoTime && !_tx_done) { + _tx_lo = relative(before); _tx_lo_valid = true; + } + if (_rx_mode && !_rx_done) { _rx_lo = relative(before); _rx_lo_valid = true; } + } + void irq(const void* phy, uint64_t before, uint64_t after, int16_t result, uint32_t irq) { + if (!owner(phy) || !tick(after)) return; + if (result != 0) { + ++spi_errors; + invalidate(SpiError); + closeHold(relative(before), SpiFailure); + _rx_lo_valid = _tx_lo_valid = false; + return; + } + if (_sending != NoIndex && tx[_sending].launch_lo_us != NoTime && !_tx_done) { + if (irq & 1U) { + TxRecord& record = tx[_sending]; + record.done_lo_us = _tx_lo; + record.done_hi_us = relative(after); + if (!_tx_lo_valid) record.flags |= MissingBound; + _tx_done = true; + } else if (before >= epoch_us) { + _tx_lo = relative(before); + _tx_lo_valid = true; + } + } + if (_rx_mode && !_rx_done) { + if (irq & 2U) { _rx_hi = relative(after); _rx_done = true; } + else if (before >= epoch_us) { _rx_lo = relative(before); _rx_lo_valid = true; } + } + } + void activity(const void* phy, uint64_t before, uint64_t after, bool held, + bool header, Reason reason) { + if (!owner(phy) || !tick(after) || !SpanCapacity) return; + if (!held) { closeHold(relative(before), reason); return; } + if (_hold == NoIndex) { + if (span_count >= SpanCapacity) { ++span_dropped; invalidate(Clipped); return; } + _hold = static_cast(span_count++); + spans[_hold] = {relative(after), header ? relative(after) : NoTime, + NoTime, NoIndex, _profile, None}; + } else if (header && spans[_hold].header_us == NoTime) { + spans[_hold].header_us = relative(after); + } + } + uint16_t receiveRead(const void* phy, uint64_t now) { + if (!owner(phy) || !tick(now) || !RxCapacity) return NoIndex; + closeHold(relative(now), ReceiveRead); + if (rx_count >= RxCapacity) { ++rx_dropped; invalidate(Clipped); return NoIndex; } + if (_reading != NoIndex) { invalidate(Interrupted); _reading = NoIndex; } + const uint16_t index = static_cast(rx_count++); + _reading = index; + const uint16_t span = _last_hold != NoIndex && spans[_last_hold].reason == ReceiveRead + ? _last_hold : NoIndex; + rx[index] = {_rx_lo, _rx_hi, relative(now), NoTime, 0, 0, span, _profile, 0, 0}; + if (!_rx_done || !_rx_lo_valid) rx[index].flags |= MissingBound; + if (_last_hold != NoIndex && spans[_last_hold].reason == ReceiveRead) + spans[_last_hold].rx_index = index; + _last_hold = NoIndex; + _rx_lo_valid = _rx_done = false; + return index; + } + void receiveFinish(const void* phy, uint16_t index, uint64_t now, + uint64_t hash, uint16_t length, bool good) { + if (!owner(phy) || !tick(now) || index == NoIndex || index >= rx_count) return; + RxRecord& record = rx[index]; + record.hash64 = hash; + record.len = length; + if (!good) record.flags |= uint8_t(Invalid | ReadError); + if (record.rearm_end_us == NoTime) record.flags |= uint8_t(Invalid | RearmFailed); + if (_reading == index) _reading = NoIndex; + } + void transmitPrepare(const void* phy, uint64_t now, uint64_t hash, + uint16_t length, uint32_t toa) { + if (!owner(phy) || !tick(now)) return; + closeHold(relative(now), Transmit); + _rx_mode = _rx_lo_valid = _rx_done = false; + if (_sending != NoIndex) { invalidate(Interrupted); _sending = NoIndex; } + if (tx_count >= TxCapacity) { ++tx_dropped; invalidate(Clipped); return; } + _sending = static_cast(tx_count++); + tx[_sending] = {hash, NoTime, NoTime, NoTime, NoTime, NoTime, + toa, length, _profile, NotConfirmed, spi_errors}; + _tx_lo_valid = _tx_done = false; + } + void transmitLaunch(const void* phy, uint64_t before, uint64_t after, + uint64_t busy_low, int16_t result) { + if (!owner(phy) || !tick(busy_low > after ? busy_low : after) || _sending == NoIndex) return; + TxRecord& record = tx[_sending]; + record.launch_lo_us = relative(before); + record.launch_hi_us = relative(after); + record.busy_low_us = busy_low ? relative(busy_low) : NoTime; + if (result != 0) record.flags |= uint8_t(Invalid | Interrupted); + } + void transmitLaunchBegin(const void* phy, uint64_t now) { + if (!owner(phy) || !tick(now) || _sending == NoIndex) return; + tx[_sending].launch_lo_us = relative(now); + _tx_lo_valid = _tx_done = false; + } + void transmitFinish(const void* phy, uint64_t now, bool confirmed) { + if (!owner(phy) || !tick(now) || _sending == NoIndex) return; + TxRecord& record = tx[_sending]; + record.spi_errors = spi_errors - record.spi_errors; + if (confirmed && _tx_done) record.flags &= uint8_t(~NotConfirmed); + else record.flags |= uint8_t(Invalid | Interrupted | NotConfirmed); + if (!_tx_lo_valid || !_tx_done || record.launch_lo_us == NoTime + || record.launch_hi_us == NoTime || record.busy_low_us == NoTime) + record.flags |= MissingBound; + _sending = NoIndex; + _tx_lo_valid = _tx_done = false; + } + void scan(const void* phy, uint64_t now, uint64_t visit_started, uint32_t visit_us, + bool gap_sample = true) { + if (!owner(phy) || !tick(now)) return; + const uint32_t stamp = relative(now); + const uint32_t gap = !gap_sample || _last_scan == NoTime ? 0 : stamp - _last_scan; + if (gap_sample) _last_scan = stamp; + const uint64_t elapsed = now >= visit_started ? now - visit_started : 0; + const uint64_t late = visit_us && elapsed > visit_us ? elapsed - visit_us : 0; + const uint32_t overdue = late > UINT32_MAX ? UINT32_MAX : static_cast(late); + if (gap > max_scan_gap_us) max_scan_gap_us = gap; + if (overdue > max_visit_overdue_us) max_visit_overdue_us = overdue; + if (!BucketCapacity) return; + const uint32_t index = stamp / BucketWidthUs; + if (index >= BucketCapacity) { invalidate(Clipped); return; } + while (bucket_count <= index) { + buckets[bucket_count] = {bucket_count * BucketWidthUs, 0, 0, 0, 0}; + ++bucket_count; + } + Bucket& bucket = buckets[index]; + if (gap > bucket.max_scan_gap_us) { + bucket.max_scan_gap_us = gap; + bucket.max_scan_gap_end_us = stamp; + } + if (overdue > bucket.max_visit_overdue_us) { + bucket.max_visit_overdue_us = overdue; + bucket.max_visit_overdue_end_us = stamp; + } + } +}; + +static_assert(sizeof(Trace) <= 12 * 1024, "Optional radio trace exceeded its RAM budget"); +#if defined(MESH_HIL_RADIO_TRACE_TX_ONLY) && MESH_HIL_RADIO_TRACE_TX_ONLY +static_assert(sizeof(Trace) <= 3 * 1024, "Sender-only trace exceeded its RAM budget"); +#endif + +Trace& trace(); +uint64_t nowUs(); +uint64_t fingerprint(const uint8_t* bytes, size_t length); + +} // namespace radiotrace +} // namespace mesh + +#else +#define MESH_RADIO_TRACE_ENABLED 0 +#endif diff --git a/src/helpers/radiolib/ESP32RadioTraceCLI.h b/src/helpers/radiolib/ESP32RadioTraceCLI.h new file mode 100644 index 000000000..62ed0d497 --- /dev/null +++ b/src/helpers/radiolib/ESP32RadioTraceCLI.h @@ -0,0 +1,177 @@ +#pragma once + +// Local, explicitly instrumented builds only. Never write asynchronous output. +#if defined(ESP32_PLATFORM) && defined(MESH_HIL_RADIO_TRACE) && MESH_HIL_RADIO_TRACE +#include "ESP32RadioTrace.h" +#include +#include +#include + +namespace mesh { namespace radiotrace { + +inline uint64_t bootToken() { + // A capture identity, not a security token. Initialize outside radio hot paths. + static const uint64_t value = (uint64_t(esp_random()) << 32) | esp_random(); + return value; +} + +inline const char* imageMarker() { + return Marker; +} + +inline bool parseTraceNumber(const char*& value, uint32_t& out) { + if (*value < '0' || *value > '9') return false; + uint32_t result = 0; + while (*value >= '0' && *value <= '9') { + const uint32_t digit = *value++ - '0'; + if (result > (UINT32_MAX - digit) / 10) return false; + result = result * 10 + digit; + } + out = result; + return true; +} + +inline void formatTraceRecord(const Trace& capture, unsigned kind, uint32_t index, + char* reply, size_t capacity) { + const uint32_t counts[] = {capture.span_count, capture.rx_count, + capture.tx_count, capture.bucket_count}; + const size_t limits[] = {SpanCapacity, RxCapacity, TxCapacity, BucketCapacity}; + if (kind >= 4 || index >= counts[kind] || index >= limits[kind]) { + snprintf(reply, capacity, "Error: trace record unavailable"); + return; + } + if (kind == 0) { + const Span& r = capture.spans[index]; + snprintf(reply, capacity, "> span=%lu,%lu,%lu,%lu,%u,%u,%u", + (unsigned long)index, (unsigned long)r.begin_us, (unsigned long)r.header_us, + (unsigned long)r.end_us, (unsigned)r.rx_index, (unsigned)r.profile, (unsigned)r.reason); + } else if (kind == 1) { + const RxRecord& r = capture.rx[index]; + snprintf(reply, capacity, "> rx=%lu,%lu,%lu,%lu,%lu,%016llx,%u,%u,%u,%u", + (unsigned long)index, (unsigned long)r.done_lo_us, (unsigned long)r.done_hi_us, + (unsigned long)r.read_begin_us, (unsigned long)r.rearm_end_us, + (unsigned long long)r.hash64, (unsigned)r.len, (unsigned)r.span_index, + (unsigned)r.profile, (unsigned)r.flags); + } else if (kind == 2) { + const TxRecord& r = capture.tx[index]; + snprintf(reply, capacity, "> tx=%lu,%016llx,%lu,%lu,%lu,%lu,%lu,%lu,%u,%u,%u,%lu", + (unsigned long)index, (unsigned long long)r.hash64, + (unsigned long)r.launch_lo_us, (unsigned long)r.launch_hi_us, + (unsigned long)r.busy_low_us, (unsigned long)r.done_lo_us, + (unsigned long)r.done_hi_us, (unsigned long)r.toa_us, + (unsigned)r.len, (unsigned)r.profile, (unsigned)r.flags, (unsigned long)r.spi_errors); + } else { + const Bucket& r = capture.buckets[index]; + snprintf(reply, capacity, "> bucket=%lu,%lu,%lu,%lu,%lu,%lu", (unsigned long)index, + (unsigned long)r.start_us, (unsigned long)r.max_scan_gap_us, + (unsigned long)r.max_visit_overdue_us, (unsigned long)r.max_scan_gap_end_us, + (unsigned long)r.max_visit_overdue_end_us); + } +} + +inline bool handleTraceCommand(const char* command, char* reply, size_t capacity) { + if (!command || !reply || !capacity) return false; + const char* get = "get radio.trace"; + const char* set = "set radio.trace"; + const bool getter = !strncmp(command, get, strlen(get)) + && (command[strlen(get)] == 0 || command[strlen(get)] == ' '); + const bool setter = !strncmp(command, set, strlen(set)) + && (command[strlen(set)] == 0 || command[strlen(set)] == ' '); + if (!getter && !setter) return false; + const char* value = command + strlen(getter ? get : set); + if (*value == ' ') ++value; + Trace& capture = trace(); + const uint64_t now = nowUs(); + capture.tick(now); + if (getter && !*value) { + snprintf(reply, capacity, + "> rt=1 boot=%016llx session=%lu state=%u epoch=%llu end=%llu flags=%lu mode=%s", + (unsigned long long)bootToken(), (unsigned long)capture.session, + (unsigned)capture.state, (unsigned long long)capture.epoch_us, + (unsigned long long)capture.end_us, (unsigned long)capture.flags, +#if defined(MESH_HIL_RADIO_TRACE_TX_ONLY) && MESH_HIL_RADIO_TRACE_TX_ONLY + "tx"); +#else + "rx"); +#endif + return true; + } + if (getter && !strcmp(value, "marker")) { + snprintf(reply, capacity, "> %s", imageMarker()); + return true; + } + if (getter && !strncmp(value, "clock ", 6)) { + const char* nonce = value + 6; + bool valid = strlen(nonce) == 16; + for (size_t i = 0; valid && i < 16; ++i) { + const char c = nonce[i]; + valid = (c >= '0' && c <= '9') || (c >= 'a' && c <= 'f') + || (c >= 'A' && c <= 'F'); + } + if (valid) { + snprintf(reply, capacity, "> rt=1 boot=%016llx session=%lu nonce=%s us=%llu", + (unsigned long long)bootToken(), (unsigned long)capture.session, nonce, + (unsigned long long)now); + } else snprintf(reply, capacity, "Error: clock requires exactly 16 hex digits"); + return true; + } + if (getter && !strcmp(value, "stats")) { + snprintf(reply, capacity, + "> spans=%lu rx=%lu tx=%lu buckets=%lu span_drop=%lu rx_drop=%lu tx_drop=%lu", + (unsigned long)capture.span_count, (unsigned long)capture.rx_count, + (unsigned long)capture.tx_count, (unsigned long)capture.bucket_count, + (unsigned long)capture.span_dropped, (unsigned long)capture.rx_dropped, + (unsigned long)capture.tx_dropped); + return true; + } + if (getter && !strcmp(value, "gaps")) { + snprintf(reply, capacity, + "> scan=%lu overdue=%lu blackout=%lu spi_err=%lu invalid=%lu context_err=%lu", + (unsigned long)capture.max_scan_gap_us, (unsigned long)capture.max_visit_overdue_us, + (unsigned long)capture.max_blackout_us, (unsigned long)capture.spi_errors, + (unsigned long)capture.invalidations, (unsigned long)capture.context_errors); + return true; + } + if (setter && !strcmp(value, "stop")) { + capture.stop(now); + snprintf(reply, capacity, "OK - radio trace frozen"); + return true; + } + if (setter && !strncmp(value, "arm ", 4)) { + const char* argument = value + 4; + uint32_t delay = 0, duration = 0; + if (!parseTraceNumber(argument, delay) || *argument++ != ' ' + || !parseTraceNumber(argument, duration) || *argument + || delay > MaxDelayMs || !duration || duration > MaxCaptureMs) { + snprintf(reply, capacity, "Error: arm requires delay 0..180000 and duration 1..180000 ms"); + } else if (capture.state == State::Armed || capture.state == State::Capturing) { + snprintf(reply, capacity, "Error: stop the current trace before arming"); + } else if (!capture.arm(now, delay, duration)) { + snprintf(reply, capacity, "Error: radio trace could not be armed"); + } else snprintf(reply, capacity, "OK - radio trace armed session=%lu", (unsigned long)capture.session); + return true; + } + // Dump frozen RAM only, so reads cannot perturb an active capture or race it. + if (getter) { + const char* kinds[] = {"span ", "rx ", "tx ", "bucket "}; + for (unsigned kind = 0; kind < 4; ++kind) { + if (strncmp(value, kinds[kind], strlen(kinds[kind]))) continue; + const char* argument = value + strlen(kinds[kind]); + uint32_t index = 0; + if (!parseTraceNumber(argument, index) || *argument) { + snprintf(reply, capacity, "Error: trace index must be an unsigned integer"); + } else if (capture.state != State::Frozen) { + snprintf(reply, capacity, "Error: stop the trace before reading records"); + } else { + // Record formatters below are intentionally bounded to one CLI frame. + formatTraceRecord(capture, kind, index, reply, capacity); + } + return true; + } + } + snprintf(reply, capacity, "Error: use get radio.trace [clock N|stats|gaps|marker|span N|rx N|tx N|bucket N] or set radio.trace arm D T|stop"); + return true; +} + +} } +#endif diff --git a/src/helpers/radiolib/RadioLibWrappers.cpp b/src/helpers/radiolib/RadioLibWrappers.cpp index 9bd8f8ac4..bfbe9ef89 100644 --- a/src/helpers/radiolib/RadioLibWrappers.cpp +++ b/src/helpers/radiolib/RadioLibWrappers.cpp @@ -191,7 +191,15 @@ bool RadioLibWrapper::hasAssertedRadioInterrupt() const { // GPIO_IS_VALID_GPIO shifts by its argument on older IDF versions, so its // mask check must follow the range check even for an invalid/NC module pin. if (irq == RADIOLIB_NC || irq >= SOC_GPIO_PIN_COUNT || !GPIO_IS_VALID_GPIO(irq)) return false; - return module->hal->digitalRead(irq) == module->hal->GpioLevelHigh; + #if MESH_RADIO_TRACE_ENABLED + const bool tracing = mesh::radiotrace::trace().pending(); + const uint64_t before = tracing ? mesh::radiotrace::nowUs() : 0; + #endif + const bool asserted = module->hal->digitalRead(irq) == module->hal->GpioLevelHigh; + #if MESH_RADIO_TRACE_ENABLED + if (tracing) mesh::radiotrace::trace().dio(_radio, before, mesh::radiotrace::nowUs(), asserted); + #endif + return asserted; #else return false; #endif @@ -212,6 +220,9 @@ bool RadioLibWrapper::claimRadioInterrupt() { } void RadioLibWrapper::begin() { +#if MESH_RADIO_TRACE_ENABLED + mesh::radiotrace::trace().context(_radio, _active_profile, _profile_generation); +#endif #if MESH_ENABLE_TX_BEACONS if (_beacon_owned) return; #endif @@ -340,6 +351,9 @@ bool RadioLibWrapper::setTxPower(int8_t dbm) { } uint8_t RadioLibWrapper::beginReconfigure() { +#if MESH_RADIO_TRACE_ENABLED + mesh::radiotrace::trace().context(_radio, _active_profile, _profile_generation); +#endif #if MESH_ENABLE_TX_BEACONS if (_beacon_owned && !_beacon_restoring) return 2; #endif @@ -610,6 +624,9 @@ mesh::RadioParamApplyResult RadioLibWrapper::tuneProfile(uint8_t profile) { cacheParams(p.freq, p.bw, p.sf, p.cr); _active_profile = profile; _profile_generation = _profiles.generation[profile]; +#if MESH_RADIO_TRACE_ENABLED + mesh::radiotrace::trace().context(_radio, _active_profile, _profile_generation); +#endif _profile_refresh_required = false; _profile_repair_required = false; endReconfigure(resume); @@ -875,6 +892,12 @@ mesh::RadioParamApplyResult RadioLibWrapper::tryRestoreCodingRate(uint8_t cr) { } void RadioLibWrapper::serviceProfileScan() { +#if MESH_RADIO_TRACE_ENABLED + if (mesh::radiotrace::trace().pending()) { + mesh::radiotrace::trace().context(_radio, _active_profile, _profile_generation); + mesh::radiotrace::trace().scan(_radio, mesh::radiotrace::nowUs(), 0, 0); + } +#endif #if defined(NRF52_PLATFORM) _profile_idle_visit_ticks = 0; // Every deferred/restarted scan fails closed. #endif @@ -965,6 +988,10 @@ void RadioLibWrapper::serviceProfileScan() { #if defined(ESP32_PLATFORM) // Keep long visits and light-sleep elapsed time in the same 64-bit domain. const uint64_t now_us = static_cast(esp_timer_get_time()); +#if MESH_RADIO_TRACE_ENABLED + if (mesh::radiotrace::trace().pending()) + mesh::radiotrace::trace().scan(_radio, now_us, _esp32_profile_visit_started_us, visit_us, false); +#endif if (now_us < _esp32_profile_visit_started_us || now_us - _esp32_profile_visit_started_us >= visit_us) target ^= 1; #else @@ -2019,6 +2046,12 @@ bool RadioLibWrapper::serviceCarrierWave() { #endif void RadioLibWrapper::loop() { +#if MESH_RADIO_TRACE_ENABLED + if (mesh::radiotrace::trace().pending()) { + mesh::radiotrace::trace().context(_radio, _active_profile, _profile_generation); + mesh::radiotrace::trace().tick(mesh::radiotrace::nowUs()); + } +#endif #if MESH_ENABLE_TX_BEACONS if (_beacon_owned) return; #endif @@ -2334,6 +2367,11 @@ bool RadioLibWrapper::setRxPowerSaving(bool enabled, uint32_t rx_us, uint32_t sl } int RadioLibWrapper::recvRaw(uint8_t* bytes, int sz) { +#if MESH_RADIO_TRACE_ENABLED + auto& radio_trace = mesh::radiotrace::trace(); + uint16_t trace_rx = mesh::radiotrace::NoIndex; + radio_trace.context(_radio, _active_profile, _profile_generation); +#endif #if MESH_ENABLE_TX_BEACONS if (_beacon_owned) return 0; #endif @@ -2346,6 +2384,9 @@ int RadioLibWrapper::recvRaw(uint8_t* bytes, int sz) { last_radio_interrupt_millis = millis(); // ISR fired -> radio hardware is alive const bool packet_ready = isPacketReady(); if (packet_ready) { +#if MESH_RADIO_TRACE_ENABLED + if (radio_trace.pending()) trace_rx = radio_trace.receiveRead(_radio, mesh::radiotrace::nowUs()); +#endif #if defined(USE_LR2021) // The LR2021 base reader clears FIFO/IRQs while otherwise staying in // continuous RX. Freeze reception before taking length/status/FIFO @@ -2431,6 +2472,11 @@ int RadioLibWrapper::recvRaw(uint8_t* bytes, int sz) { _rx_retry_pending = true; MESH_DEBUG_PRINTLN("RadioLibWrapper: error: startReceive after packet (%d)", err); } +#if MESH_RADIO_TRACE_ENABLED + if (trace_rx != mesh::radiotrace::NoIndex) + radio_trace.receiveFinish(_radio, trace_rx, mesh::radiotrace::nowUs(), + mesh::radiotrace::fingerprint(bytes, len), static_cast(len), true); +#endif return len; } @@ -2448,6 +2494,12 @@ int RadioLibWrapper::recvRaw(uint8_t* bytes, int sz) { } startRecv(); } +#if MESH_RADIO_TRACE_ENABLED + if (trace_rx != mesh::radiotrace::NoIndex) + radio_trace.receiveFinish(_radio, trace_rx, mesh::radiotrace::nowUs(), + len > 0 ? mesh::radiotrace::fingerprint(bytes, len) : 0, + static_cast(len), len > 0); +#endif return len; } @@ -2528,12 +2580,23 @@ bool RadioLibWrapper::startSendRaw(const uint8_t* bytes, int len) { return false; } _irq_probe_failures = 0; +#if MESH_RADIO_TRACE_ENABLED + if (mesh::radiotrace::trace().pending()) { + mesh::radiotrace::trace().context(_radio, _active_profile, _profile_generation); + mesh::radiotrace::trace().transmitPrepare(_radio, mesh::radiotrace::nowUs(), + mesh::radiotrace::fingerprint(bytes, len), static_cast(len), _radio->getTimeOnAir(len)); + } +#endif int err = _radio->startTransmit((uint8_t *) bytes, len); if (err == RADIOLIB_ERR_NONE) { state = STATE_TX_WAIT; return true; } MESH_DEBUG_PRINTLN("RadioLibWrapper: error: startTransmit(%d)", err); +#if MESH_RADIO_TRACE_ENABLED + if (mesh::radiotrace::trace().pending()) + mesh::radiotrace::trace().transmitFinish(_radio, mesh::radiotrace::nowUs(), false); +#endif idle(); // trigger another startRecv() _board->onAfterTransmit(); if (err == RADIOLIB_ERR_SPI_CMD_TIMEOUT) { @@ -2556,12 +2619,20 @@ bool RadioLibWrapper::isSendComplete() { _irq_probe_failures = 0; state = STATE_IDLE; n_sent++; +#if MESH_RADIO_TRACE_ENABLED + if (mesh::radiotrace::trace().pending()) + mesh::radiotrace::trace().transmitFinish(_radio, mesh::radiotrace::nowUs(), true); +#endif return true; } return false; } void RadioLibWrapper::onSendFinished() { +#if MESH_RADIO_TRACE_ENABLED + if (mesh::radiotrace::trace().pending()) + mesh::radiotrace::trace().transmitFinish(_radio, mesh::radiotrace::nowUs(), false); +#endif _radio->finishTransmit(); // Receive has not been rearmed yet: these are completion/probe events for // the retired TX. They must not block the Dispatcher's timeout recovery. diff --git a/src/helpers/radiolib/RadioLibWrappers.h b/src/helpers/radiolib/RadioLibWrappers.h index 1ffbe269e..8d8ca2d13 100644 --- a/src/helpers/radiolib/RadioLibWrappers.h +++ b/src/helpers/radiolib/RadioLibWrappers.h @@ -10,6 +10,7 @@ #include "RadioAirtime.h" #include "RXPowerSaving.h" #include "HilTxFrequencyGuard.h" +#include "ESP32RadioTrace.h" #if defined(STATION_G3_ESP32) #include #endif diff --git a/test/fixtures/esp32_radio_trace.cpp b/test/fixtures/esp32_radio_trace.cpp new file mode 100644 index 000000000..2a4e2d8d6 --- /dev/null +++ b/test/fixtures/esp32_radio_trace.cpp @@ -0,0 +1,232 @@ +#include +#include +#include +#include +#include + +using namespace mesh::radiotrace; +static int radio; +static constexpr uint64_t Base = UINT64_C(0x100000000) + 100000; + +static void begin(Trace& t) { + t.context(&radio, 0, 7); + assert(t.arm(Base, 0, MaxCaptureMs)); + assert(t.tick(Base)); +} + +static void lifetime() { + Trace t; + assert(!t.pending() && !t.tick(Base)); + assert(!t.arm(Base, 0, 0)); + assert(!t.arm(Base, MaxDelayMs + 1, 1)); + assert(!t.arm(Base, 0, MaxCaptureMs + 1)); + assert(t.arm(Base, 10, 20)); + assert(t.session == 1 && t.state == State::Armed); + assert(!t.arm(Base, 0, 1)); + assert(!t.tick(Base + 9999)); + assert(t.tick(Base + 10000)); + assert(t.state == State::Capturing); + assert(!t.tick(Base + 30000)); + assert(t.state == State::Frozen && !t.pending()); + assert(t.arm(Base + 40000, 0, 1) && t.session == 2); + t.stop(Base + 40500); + assert(t.state == State::Frozen); + assert(t.arm(Base, 10, 10)); + t.stop(Base); + assert(t.state == State::Frozen && !t.span_count && !t.flags); +} + +static void holdsAndReceipts() { + Trace t; begin(t); + t.receiveEntry(&radio, Base, Base + 1, 0); + t.irq(&radio, Base + 10, Base + 11, 0, 0); + t.activity(&radio, Base + 20, Base + 21, true, false, None); + t.activity(&radio, Base + 30, Base + 31, true, false, None); + t.activity(&radio, Base + 40, Base + 41, true, true, None); + t.activity(&radio, Base + 50, Base + 51, true, true, None); + assert(t.span_count == 1 && t.spans[0].begin_us == 21); + assert(t.spans[0].header_us == 41 && t.spans[0].end_us == NoTime); + t.irq(&radio, Base + 60, Base + 61, 0, 2); + auto i = t.receiveRead(&radio, Base + 70); + assert(i == 0 && t.rx_count == 1); + assert(t.rx[0].done_lo_us == 10 && t.rx[0].done_hi_us == 61); + assert(t.rx[0].span_index == 0 && t.spans[0].rx_index == 0); + assert(t.spans[0].end_us == 70 && t.spans[0].reason == ReceiveRead); + t.operation(&radio, Base + 80, Rearm); + t.receiveEntry(&radio, Base + 80, Base + 90, 0); + t.receiveFinish(&radio, i, Base + 100, UINT64_C(0xaabbccddeeff1234), 101, true); + assert(t.rx[0].hash64 == UINT64_C(0xaabbccddeeff1234)); + assert(t.rx[0].len == 101 && !t.rx[0].flags); + assert(t.rx[0].rearm_end_us == 90 && t.max_blackout_us == 20); + t.activity(&radio, Base + 110, Base + 111, true, false, None); + t.activity(&radio, Base + 210, Base + 211, false, false, PreambleExpired); + assert(t.spans[1].header_us == NoTime && t.spans[1].end_us == 210); + assert(t.spans[1].reason == PreambleExpired); + t.irq(&radio, Base + 220, Base + 221, 0, 2); + i = t.receiveRead(&radio, Base + 230); + assert(t.rx[i].span_index == NoIndex); // no stale abandoned-span link + t.receiveEntry(&radio, Base + 231, Base + 235, -1); + t.receiveFinish(&radio, i, Base + 240, 0, 0, false); + assert((t.rx[i].flags & (Invalid | RearmFailed | ReadError)) == (Invalid | RearmFailed | ReadError)); +} + +static void transmitBounds() { + Trace t; begin(t); + t.transmitPrepare(&radio, Base + 10, 0x1234, 101, 397824); + t.transmitLaunch(&radio, Base + 20, Base + 30, Base + 30, 0); + t.dio(&radio, Base + 400000, Base + 400001, false); + t.irq(&radio, Base + 400010, Base + 400020, 0, 0); + t.irq(&radio, Base + 400030, Base + 400040, 0, 1); + t.dio(&radio, Base + 400050, Base + 400051, false); // cannot move a latched bound + t.irq(&radio, Base + 400060, Base + 400070, 0, 1); // retain first positive + t.transmitFinish(&radio, Base + 400080, true); + auto& r = t.tx[0]; + assert(t.tx_count == 1 && !r.flags && r.hash64 == 0x1234); + assert(r.done_lo_us == 400010 && r.done_hi_us == 400040); + assert(r.launch_lo_us == 20 && r.launch_hi_us == 30 && r.busy_low_us == 30); + assert(r.toa_us == 397824 && !r.spi_errors); + t.transmitFinish(&radio, Base + 400090, false); // normal finish cleanup is inert + assert(!r.flags); + t.transmitPrepare(&radio, Base + 500000, 0x5678, 101, 652288); + t.transmitLaunch(&radio, Base + 500001, Base + 500002, Base + 500003, 0); + t.irq(&radio, Base + 500010, Base + 500020, 0, 1); + t.transmitFinish(&radio, Base + 500030, true); + assert(t.tx[1].flags == MissingBound); // old TX cannot donate its lower bound +} + +static void spiFailure() { + Trace t; begin(t); + t.transmitPrepare(&radio, Base + 10, 1, 101, 100); + t.transmitLaunch(&radio, Base + 11, Base + 12, Base + 13, 0); + t.irq(&radio, Base + 20, Base + 21, -707, 0); + t.irq(&radio, Base + 30, Base + 31, 0, 1); + t.transmitFinish(&radio, Base + 40, true); + assert(t.spi_errors == 1 && t.invalidations == 1); + assert((t.tx[0].flags & (Invalid | SpiError | MissingBound)) == (Invalid | SpiError | MissingBound)); + assert(t.tx[0].spi_errors == 1); + Trace r; begin(r); + r.receiveEntry(&radio, Base, Base + 1, 0); + r.activity(&radio, Base + 10, Base + 11, true, false, None); + r.irq(&radio, Base + 20, Base + 21, -707, 0); + assert(r.spans[0].reason == SpiFailure && r.spans[0].end_us == 20); + r.irq(&radio, Base + 30, Base + 31, 0, 2); + auto i = r.receiveRead(&radio, Base + 40); + assert(r.rx[i].flags & MissingBound); +} + +static void interruptionsAndFreeze() { + Trace t; begin(t); + t.activity(&radio, Base + 10, Base + 11, true, true, None); + t.operation(&radio, Base + 20, Reconfigure); + assert(t.spans[0].end_us == 20 && t.spans[0].reason == Reconfigure); + t.transmitPrepare(&radio, Base + 30, 1, 101, 100); + t.stop(Base + 40); + assert(t.state == State::Frozen && (t.flags & Invalid)); + assert((t.tx[0].flags & (Invalid | Clipped | NotConfirmed)) == (Invalid | Clipped | NotConfirmed)); + const auto frozen = t; + t.activity(&radio, Base + 50, Base + 51, true, false, None); + t.irq(&radio, Base + 60, Base + 61, 0, 1); + t.transmitFinish(&radio, Base + 70, true); + assert(!std::memcmp(&frozen, &t, sizeof(t))); + Trace r; begin(r); + r.receiveEntry(&radio, Base, Base + 1, 0); + r.irq(&radio, Base + 10, Base + 11, 0, 2); + r.receiveRead(&radio, Base + 20); + r.tick(r.end_us); + assert(r.state == State::Frozen && (r.rx[0].flags & Clipped)); +} + +static void overflowAndOwnership() { + Trace t; begin(t); + for (size_t i = 0; i < SpanCapacity + 2; ++i) { + t.activity(&radio, Base + i * 10 + 1, Base + i * 10 + 2, true, false, None); + t.activity(&radio, Base + i * 10 + 3, Base + i * 10 + 4, false, false, HeaderError); + } + assert(t.span_count == SpanCapacity && t.span_dropped == 2); + assert(t.spans[0].begin_us == 2 && (t.flags & Invalid)); + Trace r; begin(r); + for (size_t i = 0; i < RxCapacity + 1; ++i) { + const auto record = r.receiveRead(&radio, Base + i * 10 + 1); + r.receiveEntry(&radio, Base + i * 10 + 2, Base + i * 10 + 3, 0); + r.receiveFinish(&radio, record, Base + i * 10 + 4, i, 101, true); + } + assert(r.rx_count == RxCapacity && r.rx_dropped == 1); + Trace s; begin(s); + for (size_t i = 0; i < TxCapacity + 1; ++i) { + s.transmitPrepare(&radio, Base + i * 10 + 1, i, 101, 100); + s.transmitFinish(&radio, Base + i * 10 + 2, false); + } + assert(s.tx_count == TxCapacity && s.tx_dropped == 1); + int other; + s.context(&other, 1, 9); + assert(s.context_errors == 1); + const auto count = s.tx_count; + s.transmitPrepare(&other, Base + 10000, 0, 101, 100); + assert(s.tx_count == count); +} + +static void scanTiming() { + Trace t; begin(t); + t.scan(&radio, Base + 10, Base, 100); + t.scan(&radio, Base + 1000, Base, 100, false); + t.scan(&radio, Base + 2010, Base + 2000, 100); + assert(t.max_scan_gap_us == 2000 && t.max_visit_overdue_us == 900); + assert(t.buckets[0].max_scan_gap_us == 2000); + assert(t.buckets[0].max_scan_gap_end_us == 2010); + assert(t.buckets[0].max_visit_overdue_end_us == 1000); + t.scan(&radio, Base + BucketWidthUs + 10, Base + BucketWidthUs, 100); + assert(t.bucket_count == 2 && t.buckets[1].start_us == BucketWidthUs); + assert(t.buckets[0].max_scan_gap_end_us == 2010); + // Expiry is exclusive, so the final valid bucket is 59 for 180 seconds. + t.scan(&radio, Base + uint64_t(MaxCaptureMs) * 1000 - 1, 0, 0); + assert(t.bucket_count == 60 && !(t.flags & Invalid)); +} + +static void epochsAndMissingLaunch() { + Trace t; begin(t); + t.transmitPrepare(&radio, Base + 10, 1, 101, 100); + t.dio(&radio, Base + 11, Base + 12, false); + t.irq(&radio, Base + 13, Base + 14, 0, 1); // previous epoch, before SetTx + t.transmitLaunchBegin(&radio, Base + 20); + t.transmitLaunch(&radio, Base + 20, Base + 21, Base + 22, 0); + t.irq(&radio, Base + 120, Base + 121, 0, 1); + t.transmitFinish(&radio, Base + 122, true); + assert(t.tx[0].done_hi_us == 121 && t.tx[0].flags == MissingBound); + t.transmitPrepare(&radio, Base + 200, 2, 101, 100); + t.irq(&radio, Base + 201, Base + 202, 0, 1); + t.transmitFinish(&radio, Base + 203, true); + assert((t.tx[1].flags & (Invalid | MissingBound | NotConfirmed)) == (Invalid | MissingBound | NotConfirmed)); + + Trace r;r.context(&radio,0,1); + assert(r.arm(Base,10,1000)); + r.receiveEntry(&radio,Base+100,Base+101,0); // establish mode while armed + r.irq(&radio,Base+10010,Base+10011,0,0); + r.irq(&radio,Base+10020,Base+10021,0,2); + auto i=r.receiveRead(&radio,Base+10030); + assert(!(r.rx[i].flags&MissingBound)); + r.receiveEntry(&radio,Base+10031,Base+10032,0); + r.receiveFinish(&radio,i,Base+10033,1,101,true); + r.stop(Base+10040); + assert(r.arm(Base+20000,0,1000)); // stale mode/bounds from old capture cannot survive + r.irq(&radio,Base+20010,Base+20011,0,0); + r.irq(&radio,Base+20020,Base+20021,0,2); + i=r.receiveRead(&radio,Base+20030); + assert(r.rx[i].flags&MissingBound); + Trace receiver;begin(receiver); + receiver.context(&radio,0,7); + receiver.context(&radio,0,8); + assert((receiver.flags&(Invalid|Interrupted))==(Invalid|Interrupted)); +} + +int main(int argc, char** argv) { + assert(argc == 2); + if (!std::strcmp(argv[1], "lifetime")) lifetime(); + else if (!std::strcmp(argv[1], "holds")) holdsAndReceipts(); + else if (!std::strcmp(argv[1], "tx")) transmitBounds(); + else if (!std::strcmp(argv[1], "spi")) spiFailure(); + else if (!std::strcmp(argv[1], "freeze")) interruptionsAndFreeze(); + else if (!std::strcmp(argv[1], "overflow")) overflowAndOwnership(); + else if (!std::strcmp(argv[1], "scan")) scanTiming(); + else if (!std::strcmp(argv[1], "epochs")) epochsAndMissingLaunch(); + else assert(false); +} diff --git a/test/test_esp32_radio_trace.py b/test/test_esp32_radio_trace.py new file mode 100644 index 000000000..452c745ca --- /dev/null +++ b/test/test_esp32_radio_trace.py @@ -0,0 +1,271 @@ +"""Execute bounded trace state and the real checked IRQ/activity hooks.""" +from pathlib import Path +import os +import subprocess +import tempfile +import unittest + +from cpp_source import body + +ROOT = Path(__file__).resolve().parents[1] + + +def compile_cpp(folder, source, name="trace", flags=()): + cpp, binary = Path(folder) / (name + ".cpp"), Path(folder) / name + cpp.write_text(source, encoding="ascii") + command = [os.environ.get("CXX", "g++"), "-std=c++17", "-O1", "-g", + "-Wall", "-Wextra", "-Werror", "-fsanitize=address,undefined", + "-fno-sanitize-recover=all", "-fno-omit-frame-pointer", "-no-pie", + "-I", str(ROOT / "src"), *flags, str(cpp), "-o", str(binary)] + result = subprocess.run(command, capture_output=True, text=True) + if result.returncode: + raise AssertionError(result.stdout + result.stderr) + return binary + + +class RadioTraceTests(unittest.TestCase): + @classmethod + def setUpClass(cls): + cls.folder = tempfile.TemporaryDirectory(prefix="mc-radio-trace-") + cls.binary = compile_cpp(cls.folder.name, + (ROOT / "test/fixtures/esp32_radio_trace.cpp").read_text(), + flags=("-DESP32_PLATFORM", "-DMESH_HIL_RADIO_TRACE=1")) + + @classmethod + def tearDownClass(cls): + cls.folder.cleanup() + + def run_case(self, name): + result = subprocess.run([str(self.binary), name], capture_output=True, text=True) + self.assertEqual(result.returncode, 0, result.stdout + result.stderr) + + def test_capture_lifetime_and_rearm(self): self.run_case("lifetime") + def test_conservative_holds_receipts_and_blackout(self): self.run_case("holds") + def test_checked_tx_event_bounds_and_first_positive(self): self.run_case("tx") + def test_failed_spi_zero_is_never_a_lower_bound(self): self.run_case("spi") + def test_clipping_and_frozen_immutability(self): self.run_case("freeze") + def test_overflow_never_overwrites_and_wrong_phy_fails_closed(self): self.run_case("overflow") + def test_scan_gap_has_an_exact_interval_and_separate_deadline(self): self.run_case("scan") + def test_capture_and_launch_epochs_cannot_reuse_old_bounds(self): self.run_case("epochs") + + def test_disabled_object_has_no_buffer_clock_hash_or_sdk_dependencies(self): + # This compiles without ESP32 SDK include paths. Both absence of the + # flag and an explicit zero must remove all implementation/dependencies. + with tempfile.TemporaryDirectory(prefix="mc-radio-trace-off-") as folder: + for index, flags in enumerate(((), ("-DESP32_PLATFORM",), + ("-DESP32_PLATFORM", "-DMESH_HIL_RADIO_TRACE=0"), + ("-DNRF52_PLATFORM", "-DMESH_HIL_RADIO_TRACE=1"))): + obj = Path(folder) / (str(index) + ".o") + result = subprocess.run([os.environ.get("CXX", "g++"), "-std=c++11", + *flags, "-c", str(ROOT / "src/helpers/radiolib/ESP32RadioTrace.cpp"), + "-o", str(obj)], capture_output=True, text=True) + self.assertEqual(result.returncode, 0, result.stderr) + symbols = subprocess.check_output(["nm", "-C", str(obj)], text=True) + self.assertNotIn("radiotrace", symbols) + self.assertNotIn("esp_timer", symbols) + self.assertNotIn("sha256", symbols) + self.assertNotIn(" U ", symbols) + + def test_tx_only_mode_has_no_receiver_capture_and_keeps_the_ram_reserve(self): + source = r''' +#include +#include +using namespace mesh::radiotrace; +int main() { + static_assert(SpanCapacity == 0 && RxCapacity == 0 && BucketCapacity == 0, "sender storage"); + static_assert(sizeof(Trace) <= 2048, "sender reserve"); + Trace t;int radio=0;t.context(&radio,0,1);assert(t.arm(100,0,1000)); + t.activity(&radio,110,111,true,false,None); + assert(t.receiveRead(&radio,120)==NoIndex); + t.scan(&radio,130,100,20); + assert(!t.span_count && !t.rx_count && !t.bucket_count); + for(unsigned i=0;i<40;++i) { + t.context(&radio,0,i+2); // physical primary is retuned to each planned tuple + t.transmitPrepare(&radio,200+i*10,i,101,100); + t.transmitLaunch(&radio,200+i*10,200+i*10,200+i*10,0); + t.dio(&radio,201+i*10,202+i*10,false); + t.irq(&radio,203+i*10,204+i*10,0,1); + t.transmitFinish(&radio,205+i*10,true); + assert(!t.tx[i].flags); + } + assert(t.tx_count==40 && !t.tx_dropped && !t.flags); + Trace interrupted;interrupted.context(&radio,0,1);assert(interrupted.arm(100,0,1000)); + interrupted.transmitPrepare(&radio,200,1,101,100); + interrupted.transmitLaunch(&radio,200,201,202,0); + interrupted.dio(&radio,203,204,false); + interrupted.context(&radio,0,2); // a live TX may never survive a tuple replacement + interrupted.irq(&radio,205,206,0,1); + interrupted.transmitFinish(&radio,207,true); + assert((interrupted.tx[0].flags&(Invalid|Interrupted|MissingBound))==(Invalid|Interrupted|MissingBound)); +} +''' + with tempfile.TemporaryDirectory(prefix="mc-radio-trace-tx-") as folder: + binary = compile_cpp(folder, source, flags=("-DESP32_PLATFORM", + "-DMESH_HIL_RADIO_TRACE=1", "-DMESH_HIL_RADIO_TRACE_TX_ONLY=1")) + result = subprocess.run([str(binary)], capture_output=True, text=True) + self.assertEqual(result.returncode, 0, result.stdout + result.stderr) + + def test_actual_irq_and_activity_hooks_preserve_transactions_and_returns(self): + chip = (ROOT / "src/helpers/radiolib/CustomSX1262.h").read_text() + irq = body(chip, "uint32_t getIrqFlags() override") + activity = body(chip, "bool isReceiving()") + source = r''' +#include +#include +#include +#define MESH_DEBUG_PRINTLN(...) ((void)0) +#define RADIOLIB_SX126X_CMD_GET_IRQ_STATUS 0x12 +#define RADIOLIB_SX126X_IRQ_PREAMBLE_DETECTED 4U +#define RADIOLIB_SX126X_IRQ_HEADER_VALID 16U +#define RADIOLIB_SX126X_IRQ_HEADER_ERR 32U +#define RADIOLIB_SX126X_IRQ_SYNC_WORD_VALID 8U +static uint64_t clock_us=1000000; +static unsigned clock_reads=0; +uint32_t millis(){return clock_us/1000;} +namespace mesh {namespace radiotrace { +Trace& trace(){static Trace t;return t;} +uint64_t nowUs(){++clock_reads;return clock_us;} +}} +struct Module { + uint32_t irq=0;unsigned reads=0,clears=0;int16_t status=0; + int16_t SPIreadStream(uint8_t command,uint8_t* data,size_t length) { + assert(command==0x12 && length==2);++reads; + // A failing transfer may have returned either zero or partial bytes. + data[0]=uint8_t(irq>>8);data[1]=uint8_t(irq);return status; + } +}; +struct PhysicalLayer {virtual uint32_t getIrqFlags()=0;virtual ~PhysicalLayer()=default;}; +struct Chip : PhysicalLayer { + Module module;Module* mod=&module; + uint32_t _activityAt=0,_preambleMillis=99,_maxPayloadMillis=1456; + bool _headerSeen=false,busy=false; + bool isChipBusy(){return busy;} + void clearIrqFlags(uint32_t bits){++module.clears;module.irq&=~bits;} + @IRQ@ + @ACTIVITY@ +}; +int main() { + using namespace mesh::radiotrace; + Chip c;trace().context(static_cast(&c),0,1); + c.module.irq=4;assert(c.isReceiving()); + c.module.irq=0;assert(!c.isReceiving()); + assert(c.module.reads==2 && !clock_reads); // runtime-off evaluates no timer args + assert(trace().arm(clock_us,0,10000)); + clock_us+=1000;c.module.irq=4;assert(c.isReceiving()); + assert(trace().span_count==1); + clock_us+=99000;assert(c.isReceiving()); + clock_us+=1000;assert(!c.isReceiving()); + assert(trace().spans[0].reason==PreambleExpired); + assert(c.module.reads==5 && c.module.clears==1); + clock_us+=1000;c.module.irq=4;assert(c.isReceiving()); + clock_us+=1000;c.module.irq=4|16;assert(c.isReceiving()); + clock_us+=1457000;assert(!c.isReceiving()); + assert(trace().spans[1].reason==PayloadExpired && c.module.clears==2); + clock_us+=1000;c.module.irq=4;assert(c.isReceiving()); + clock_us+=1000;c.module.irq=4|32;assert(!c.isReceiving()); + assert(trace().spans[2].reason==HeaderError && c.module.clears==3); + // Exactly one read occurs for the checked override, including failures, + // and its returned bytes remain the same as the legacy implementation. + auto before=c.module.reads;c.module.status=-707;c.module.irq=0x1234; + assert(c.getIrqFlags()==0x1234 && c.module.reads==before+1); + assert(trace().spi_errors==1 && (trace().flags&Invalid)); +} +'''.replace("@IRQ@", irq).replace("@ACTIVITY@", activity) + with tempfile.TemporaryDirectory(prefix="mc-radio-trace-hooks-") as folder: + binary = compile_cpp(folder, source, flags=("-DESP32_PLATFORM", "-DMESH_HIL_RADIO_TRACE=1")) + result = subprocess.run([str(binary)], capture_output=True, text=True) + self.assertEqual(result.returncode, 0, result.stdout + result.stderr) + + def test_actual_launch_success_failure_timeout_and_compiled_out_side_effects(self): + chip = (ROOT / "src/helpers/radiolib/CustomSX1262.h").read_text() + launch = body(chip, "int16_t launchMode() override") + source = r''' +#include +#include +#include +#define RADIOLIB_RADIO_MODE_TX 3 +#define RADIOLIB_RADIO_MODE_NONE 0 +#define RADIOLIB_SX126X_TX_TIMEOUT_NONE 0 +#define RADIOLIB_ERR_NONE 0 +#define RADIOLIB_ERR_SPI_CMD_TIMEOUT -707 +#define SX126X_TX_BUSY_TIMEOUT_MS 3 +using RadioLibTime_t=uint32_t; +static uint64_t clock_us=1000000; +static unsigned clock_reads=0; +#if MESH_RADIO_TRACE_ENABLED +namespace mesh {namespace radiotrace { +Trace& trace(){static Trace t;return t;} +uint64_t nowUs(){++clock_reads;return clock_us;} +}} +#endif +struct Hal { + unsigned yields=0; + uint32_t millis(){return clock_us/1000;} + void yield(){++yields;clock_us+=1000;} +}; +struct Module { + Hal hal_value;Hal* hal=&hal_value;unsigned rf_calls=0; + void setRfSwitchState(int){++rf_calls;} +}; +struct PhysicalLayer {virtual int16_t launchMode()=0;virtual ~PhysicalLayer()=default;}; +struct SX1262 : PhysicalLayer { + unsigned base_calls=0; + int16_t launchMode()override{++base_calls;return 91;} +}; +struct Chip : SX1262 { + Module module;Module* mod=&module; + int stagedMode=3,txMode=2;int16_t set_result=0; + unsigned set_calls=0,busy_reads=0,busy_loops=2; + int16_t setTx(int){++set_calls;clock_us+=37;return set_result;} + bool isChipBusy(){return ++busy_reads<=busy_loops;} + @LAUNCH@ +}; +int main() { + Chip off;assert(off.launchMode()==0); + assert(off.set_calls==1 && off.busy_reads==3 && off.module.rf_calls==1); + assert(off.module.hal->yields==2 && off.stagedMode==0 && !clock_reads); + Chip base;base.stagedMode=1;assert(base.launchMode()==91); + assert(base.base_calls==1 && !base.set_calls && !clock_reads); +#if MESH_RADIO_TRACE_ENABLED + using namespace mesh::radiotrace; + for (int test=0;test<3;++test) { + Chip c;if(test==1)c.set_result=-20;if(test==2)c.busy_loops=100; + trace().context(static_cast(&c),0,1); + assert(trace().arm(clock_us,0,1000)); + trace().transmitPrepare(static_cast(&c),clock_us,1,101,100); + const auto expected=clock_us; + const int16_t result=c.launchMode(); + auto& r=trace().tx[0]; + assert(r.launch_lo_us==expected-trace().epoch_us && r.launch_hi_us-r.launch_lo_us==37); + assert(c.set_calls==1 && c.module.rf_calls==1 && c.stagedMode==0); + if(test==0) { + assert(result==0 && r.busy_low_us-r.launch_lo_us==2037); + assert(c.busy_reads==3 && c.module.hal->yields==2); + trace().dio(static_cast(&c),clock_us+1,clock_us+2,false); + trace().irq(static_cast(&c),clock_us+3,clock_us+4,0,1); + trace().transmitFinish(static_cast(&c),clock_us+5,true); + assert(!r.flags); + } else { + assert(result==(test==1?-20:-707) && r.busy_low_us==NoTime); + assert(c.busy_reads==unsigned(test==1?0:3)); + assert(c.module.hal->yields==unsigned(test==1?0:3)); + trace().transmitFinish(static_cast(&c),clock_us+5,false); + assert((r.flags&(Invalid|Interrupted|MissingBound))==(Invalid|Interrupted|MissingBound)); + } + trace().stop(clock_us+6);clock_us+=10000; + } +#endif +} +'''.replace("@LAUNCH@", launch) + with tempfile.TemporaryDirectory(prefix="mc-radio-trace-launch-") as folder: + for value in (0, 1): + binary = compile_cpp(folder, source, name="launch" + str(value), + flags=("-DESP32_PLATFORM", "-DMESH_HIL_RADIO_TRACE=" + str(value))) + result = subprocess.run([str(binary)], capture_output=True, text=True) + self.assertEqual(result.returncode, 0, result.stdout + result.stderr) + if value == 0: + symbols = subprocess.check_output(["nm", "-C", str(binary)], text=True) + self.assertNotIn("radiotrace", symbols) + + +if __name__ == "__main__": unittest.main() diff --git a/test/test_esp32_radio_trace_cli.py b/test/test_esp32_radio_trace_cli.py new file mode 100644 index 000000000..23dda683f --- /dev/null +++ b/test/test_esp32_radio_trace_cli.py @@ -0,0 +1,174 @@ +"""Execute the opt-in local radio trace CLI without radio, USB or PlatformIO.""" +from pathlib import Path +import os +import re +import subprocess +import tempfile +import unittest + +ROOT = Path(__file__).resolve().parents[1] +HEADER = "helpers/radiolib/ESP32RadioTraceCLI.h" +HARNESS = r''' +#include +#include +#include +#include +#include +static uint64_t clock_us=1234567890123ULL; +namespace mesh { namespace radiotrace { +Trace storage; +Trace& trace() { return storage; } +uint64_t nowUs() { return clock_us; } +} } +using namespace mesh::radiotrace; +static char reply[160]; +[[maybe_unused]] static const char* command(const char* value) { + std::memset(reply,'?',sizeof(reply)); + assert(handleTraceCommand(value,reply,sizeof(reply))); + assert(std::memchr(reply,0,sizeof(reply))); + return reply; +} +[[maybe_unused]] static void error(const char* value) { + assert(!std::strncmp(command(value),"Error:",6)); +} +''' + + +class RadioTraceCliTests(unittest.TestCase): + def native(self, body, flags=("-DESP32_PLATFORM=1", "-DMESH_HIL_RADIO_TRACE=1"), harness=HARNESS): + with tempfile.TemporaryDirectory(prefix="radio-trace-cli-") as folder: + root = Path(folder) + (root / "esp_system.h").write_text( + "#include \ninline uint32_t esp_random() { return 0x12345678; }\n", encoding="ascii") + cpp, binary = root / "test.cpp", root / "test" + cpp.write_text(harness + body, encoding="ascii") + built = subprocess.run([os.environ.get("CXX", "g++"), "-std=c++17", "-Wall", "-Wextra", "-Werror", + "-fsanitize=address,undefined", "-fno-sanitize-recover=all", "-fno-pie", "-no-pie", + *flags, "-I", str(root), "-I", str(ROOT / "src"), str(cpp), "-o", str(binary)], + capture_output=True, text=True, timeout=60) + self.assertEqual(built.returncode, 0, built.stdout + built.stderr) + ran = subprocess.run([str(binary)], capture_output=True, text=True, timeout=20) + self.assertEqual(ran.returncode, 0, ran.stdout + ran.stderr) + return subprocess.check_output(["nm", "-C", str(binary)], text=True) + + def test_clock_nonce_boot_identity_and_strict_arm_lifecycle(self): + self.native(r''' +int main() { + assert(!std::strcmp(command("get radio.trace clock aBCd0123456789ef"), + "> rt=1 boot=1234567812345678 session=0 nonce=aBCd0123456789ef us=1234567890123")); + for(const char* invalid:{"", "-1", "0123456789abcde", "0123456789abcdef0", "0123456789abcdeg", "0123456789abcdef "}) { + char text[96];std::snprintf(text,sizeof(text),"get radio.trace clock %s",invalid);error(text); + } + assert(!std::strncmp(command("set radio.trace arm 50 1000"),"OK",2)); + assert(storage.session==1 && storage.state==State::Armed); + assert(storage.epoch_us==clock_us+50000 && storage.end_us==clock_us+1050000); + error("set radio.trace arm 0 100");assert(storage.session==1); + clock_us+=50000;command("get radio.trace");assert(storage.state==State::Capturing); + error("get radio.trace tx 0"); + command("set radio.trace stop");assert(storage.state==State::Frozen); + assert(!std::strncmp(command("set radio.trace arm 180000 180000"),"OK",2)); + assert(storage.session==2); + clock_us=storage.end_us;command("get radio.trace");assert(storage.state==State::Frozen); +} +''', harness="#include \n" + HARNESS) + + def test_malformed_commands_do_not_arm_or_claim_unrelated_names(self): + self.native(r''' +int main() { + for(const char* text:{"set radio.trace", "set radio.trace arm", "set radio.trace arm -1 1", + "set radio.trace arm 0 0", "set radio.trace arm 180001 1", "set radio.trace arm 0 180001", + "set radio.trace arm 4294967296 1", "set radio.trace arm 1 4294967296", + "set radio.trace arm 1", "set radio.trace arm 1 1 x", "set radio.trace arm 1 1", + "set radio.trace arm 1 1", "get radio.trace rx -1", "get radio.trace rx 4294967296", + "get radio.trace rx 0 trailing", "get radio.trace tx", "get radio.trace stats "}) { + error(text);assert(storage.session==0 && storage.state==State::Off); + } + for(const char* text:{"get radio.tracex", "set radio.traceX", "get radio", "trace"}) + assert(!handleTraceCommand(text,reply,sizeof(reply))); + assert(!handleTraceCommand(nullptr,reply,sizeof(reply))); + assert(!handleTraceCommand("get radio.trace",nullptr,sizeof(reply))); + assert(!handleTraceCommand("get radio.trace",reply,0)); +} +''', harness="#include \n" + HARNESS) + + def test_frozen_record_schema_bounds_and_frame_capacity(self): + self.native(r''' +int main() { + storage.state=State::Frozen;storage.session=UINT32_MAX; + storage.epoch_us=storage.end_us=UINT64_MAX;storage.flags=UINT32_MAX; + assert(std::strlen(command("get radio.trace")) MCRFTRACE1:RX192:TX40")); + storage.span_count=storage.rx_count=storage.tx_count=storage.bucket_count=1; + storage.spans[0]={1,UINT32_MAX,3,UINT16_MAX,1,10}; + storage.rx[0]={1,2,3,4,0xabcdef0123456789ULL,101,UINT16_MAX,1,4,0}; + storage.tx[0]={0xabcdef0123456789ULL,1,2,3,4,5,652288,101,1,4,9}; + storage.buckets[0]={3000000,12,34,56,78}; + assert(!std::strcmp(command("get radio.trace span 0"),"> span=0,1,4294967295,3,65535,1,10")); + assert(!std::strcmp(command("get radio.trace rx 0"),"> rx=0,1,2,3,4,abcdef0123456789,101,65535,1,4")); + assert(!std::strcmp(command("get radio.trace tx 0"),"> tx=0,abcdef0123456789,1,2,3,4,5,652288,101,1,4,9")); + assert(!std::strcmp(command("get radio.trace bucket 0"),"> bucket=0,3000000,12,34,56,78")); + for(const char* kind:{"span","rx","tx","bucket"}) { + char text[64];std::snprintf(text,sizeof(text),"get radio.trace %s 1",kind);error(text); + } + std::memset(storage.tx,0xff,sizeof(storage.tx));command("get radio.trace tx 0"); + assert(std::strlen(reply) MCRFTRACE1:TXONLY40")); + storage.state=State::Frozen;storage.rx_count=storage.span_count=storage.bucket_count=1; + error("get radio.trace rx 0");error("get radio.trace span 0");error("get radio.trace bucket 0"); +} +''', flags=("-DESP32_PLATFORM=1", "-DMESH_HIL_RADIO_TRACE=1", "-DMESH_HIL_RADIO_TRACE_TX_ONLY=1")) + + def test_disabled_header_has_no_trace_state_or_formatter(self): + for flags in ((), ("-DESP32_PLATFORM=1", "-DMESH_HIL_RADIO_TRACE=0")): + symbols = self.native("int main() {return 0;}\n", flags=flags, + harness=f"#include <{HEADER}>\n") + self.assertNotIn("radiotrace", symbols) + + def test_actual_direct_dispatch_excludes_lora_admin(self): + source = (ROOT / "examples/companion_radio/MyMesh.cpp").read_text() + start = source.index("bool MyMesh::handleDirectCommand(") + direct = source[start:source.index("#if MESH_ENABLE_ONE_KEY_DM", start)] + hook = re.search(r"#if defined\(ESP32_PLATFORM\) && defined\(MESH_HIL_RADIO_TRACE\) && MESH_HIL_RADIO_TRACE\n" + r" if \(mesh::radiotrace::handleTraceCommand\(command, reply, reply_size\)\) return true;\n#endif", direct) + self.assertIsNotNone(hook) + guard = re.search(r"if \(sender_timestamp == 0 && handleDirectCommand\([^\n]+", source) + self.assertIsNotNone(guard) + self.native(r''' +struct MyMesh { + bool handleDirectCommand(const char* command,char* reply,size_t reply_size) { +@HOOK@ + return false; + } + bool handleCommand(const char* command,uint32_t sender_timestamp,char* reply) { + const size_t reply_capacity=160; + @GUARD@ + return false; + } +}; +int main() { + MyMesh mesh; + assert(!mesh.handleCommand("set radio.trace arm 0 1000",1,reply)); + assert(storage.session==0); + assert(mesh.handleCommand("set radio.trace arm 0 1000",0,reply)); + assert(storage.session==1); +} +'''.replace("@HOOK@", hook.group()).replace("@GUARD@", guard.group())) + + +if __name__ == "__main__": + unittest.main()