diff --git a/.github/workflows/run-unit-tests.yml b/.github/workflows/run-unit-tests.yml index 3506bd44a..e2a8b14a9 100644 --- a/.github/workflows/run-unit-tests.yml +++ b/.github/workflows/run-unit-tests.yml @@ -317,6 +317,9 @@ jobs: python3 -B test/test_sensor_tracker_gps.py -v python3 -B test/test_sensor_tracker_sleep.py -v python3 -B test/test_power_saving_deadlines.py -v + python3 -B test/test_power_saving_diagnostics.py -v + python3 -B test/test_power_saving_role_diagnostics.py -v + python3 -B test/test_companion_power_diagnostics.py -v python3 -B test/test_esp32_scanner_power_yield.py -v python3 -B test/test_esp32_gpio_hold.py -v diff --git a/docs/cli_commands.md b/docs/cli_commands.md index 9d85c3986..8eb2ca7c1 100644 --- a/docs/cli_commands.md +++ b/docs/cli_commands.md @@ -2557,6 +2557,69 @@ binaries. Companion firmware defaults this setting to `on`. Full Companion accepts the command from its local USB terminal and exposes the same setting in WebConfig. On ESP32, it lowers the CPU clock to 80 MHz, enables idle yielding, and enables the configured GPS duty cycle. USB and each active wireless transport remain available; SenseCAP Indicator Full keeps only its selected BLE or infrastructure-WiFi secondary transport active. `set powersaving off` restores the board's normal CPU clock and disables the GPS duty cycle. This device setting is separate from LoRa RXPS (`radio.rxps`) and WiFi modem power save (`wifi.powersave`). Infrastructure uses the same commands; its hardware and active-service sleep guards determine when the node can sleep. +#### Diagnose what prevents power saving + +Companion, Repeater, Room Server and Sensor provide on-demand diagnostics: + +```text +set powersaving.diag on +get powersaving.diag +get powersaving.diag calls +get powersaving.diag time +get powersaving.diag usb.session +get powersaving.diag bridge +get powersaving.diag 3 +set powersaving.diag off +clear powersaving.diag +``` + +Diagnostics default to off and use only RAM. They do not change the saved +power-saving flag, USB/DTR behavior, radio settings, logging or bridge state, +and are lost on reboot. `on` starts a new window after `off`; repeated `on` +keeps the current window. `off` freezes the counters for later inspection. +`clear` resets them without changing whether collection is enabled. There is +no automatic diagnostic log stream or flash write. + +The default/state page shows the last actual sleep decision (`why`, `mask`), +its age, reasons seen, total blocked time and eligible time in milliseconds. +Before the first observed decision it reports `unobserved`. Pages `3` through +`8` list every reason's transition count and blocked milliseconds; use an +exact reason name for a separate readback. Role guards preserve their normal +short-circuit order, so they report the first guard actually checked that +prevented sleep, not an exhaustive simultaneous inventory. Inner board vetoes +can add another reason. Reason times can overlap; `blocked_ms` on the state +page counts their union instead of adding them twice. + +Reasons include `policy.off`, `startup`, `usb.session`, `usb.logging`, +`usb.recovery`, `wireless`, `button`, `morse`, `radio2`, `ota`, `calibration`, +`radio.watchdog`, `queue`, `retry`, `scheduled`, `serial`, `bridge`, +`bridge.cleanup`, `bridge.wake`, `network`, `mesh`, `tracker`, `board` and +`no.wake`. Not every board/role has every guard. `mesh` includes pending +protocol/storage work; `scheduled` can include a deadline too close for the +existing whole-second sleep policy. RS232 merely being compiled or saved as +enabled is not a blocker while its UART is suspended; running, cleanup and +due wake are distinguished where those guards apply. USB power from a charger +is not a host session. Logging enabled alone is not an nRF52 MCU sleep veto; +on ESP32, the existing logging and raw-console guards can veto light sleep. + +The `calls` page counts actual instrumented wait calls, returns, short returns, +board vetoes and SDK errors. `time` reports time spent inside those wait calls +in microseconds, including SDK and interrupt work, **not CPU sleep residency +or electrical current**. Returns under 100 us are marked short, not failed. +An eligible decision with many short calls can indicate wake/event activity; +an eligible ESP32 automatic-sleep path may yield without a direct instrumented +wait, so zero calls alone is not proof of a fault. `detail` records the last +board veto/error detail (SDK error code, or board-specific guard detail). +Counters saturate instead of wrapping; observation timestamps must be sampled +within one `millis()` wrap (about 49 days). + +Opening USB to read the results can itself add a host/serial blocker. For a +battery test, enable collection, close the terminal, wait, then read the +accumulated pages. Stop collection promptly if preserving that window. A meter +is still needed to diagnose radio RX current, RXPS duty cycle, FEM/LNA gain, +GPS, displays, regulator losses and other loads that can consume power even +when the MCU sleeps correctly. See [power-saving diagnostics](power_saving_diagnostics.md). + Native USB ESP32 Full Companions can also use short light-sleep intervals when the BLE/WiFi drivers, ESP-NOW, GPS UART, logging, and USB host sessions are inactive and no work is pending. Compiling those transports into Full does not diff --git a/docs/power_saving_diagnostics.md b/docs/power_saving_diagnostics.md new file mode 100644 index 000000000..d74c319b3 --- /dev/null +++ b/docs/power_saving_diagnostics.md @@ -0,0 +1,64 @@ +# Power-saving diagnostics + +Use `set powersaving.diag on` to collect the real sleep-policy decisions in +RAM, and `get powersaving.diag` to inspect them. This is available in Companion, +Repeater, Room Server and Sensor, without a separate diagnostic build. It does +not override any sleep guard. The production USB/DTR policy is unchanged. + +## Suggested test + +1. Record `get powersaving`, radio/RXPS settings, logging and bridge settings. +2. Run `set powersaving.diag on`, then close the USB terminal for the test. +3. Let the node run long enough to cover noise-floor calibration, queue work + and scheduled tasks; a one-second snapshot can be misleading. +4. Reconnect and run `set powersaving.diag off` promptly to freeze the window. +5. Read `get powersaving.diag`, `get powersaving.diag calls`, + `get powersaving.diag time` and pages `3` through `8`. +6. If necessary, clear and repeat with only one feature changed. + +Reconnecting/reading creates real USB or serial work and can affect the final +decision and counters. Prefer accumulated time over that final `why` value; +check its age. Off freezes recorded values, not the node itself. Re-enabling +after off starts a fresh window. Collection defaults off at every boot. + +## Interpreting the result + +- `policy.off`: the saved policy does not permit MCU sleep. +- `usb.session`: an actual host session or board-specific host/grace guard, + not merely USB power from a charger. +- `usb.logging`: an existing logging guard (not a blanket nRF52 veto). +- `usb.recovery`: USB recovery/watchdog work needs service. +- `bridge`, `bridge.cleanup`, `bridge.wake`: active UART/network bridge, + shutdown work or an overdue standby wake. A suspended RS232 owner is not + diagnosed as running just because its saved enabled flag is on. +- `calibration`, `radio.watchdog`: radio observation/calibration work. +- `queue`, `retry`, `scheduled`, `mesh`, `ota`, `radio2`: pending role work. +- `wireless`, `network`, `serial`, `button`, `tracker`, `morse`: a matching + existing service guard is active. +- `board`, `no.wake`: an inner board veto, SDK error or lack of a wake source. + +The role reports the first actual short-circuit blocker. It does not query +otherwise skipped hardware just to populate an exhaustive list. Board guards +may add reasons. Per-reason durations therefore are observed guard time, not +the independent energy cost of each feature. The state page's blocked time +is the union; adding per-reason totals can double-count overlap. + +`calls` and `time` instrument actual nRF52 event waits, ESP32 manual light sleep +and generic RP2040/STM32 WFI paths. ESP32 automatic power-management yields are +not direct wait calls. A return under 100 us is counted as short; it can be a +legitimate pending interrupt/event, not an SDK failure. SDK errors have their +own counter and detail. Time inside the wait includes interrupt/SDK overhead; +it is not measured sleep residency. USB debugging/SWD can alter power and +clock behavior, so compare like-for-like setups. + +These are not current measurements. Radio continuous RX, RXPS parameters, +FEM/LNA gain, GPS, displays and board regulators can explain large current +differences even with good MCU sleep. Use a current meter and matched settings +to attribute those loads. Counters are RAM-only, saturating, and consume at +most 256 bytes of collector state. Each wait-call interval must be shorter +than the 32-bit `micros()` wrap (about 71 minutes); the normal wait paths here +are much shorter. Keep gaps between policy observations below the `millis()` +wrap (about 49 days). + +See the [CLI reference](cli_commands.md#diagnose-what-prevents-power-saving) +for all page names and commands. diff --git a/examples/companion_radio/MyMesh.cpp b/examples/companion_radio/MyMesh.cpp index f88450709..ad004fffc 100644 --- a/examples/companion_radio/MyMesh.cpp +++ b/examples/companion_radio/MyMesh.cpp @@ -3798,6 +3798,7 @@ bool MyMesh::handleLocalControlCommand(const char* command, char* reply, size_t reply_size) { if (!command || !reply || reply_size == 0) return false; while (*command == ' ') command++; + if (mesh::powerdiag::handleCommand(command, reply, reply_size, millis())) return true; #if defined(OTA_RAK15002_SD_STORE) && defined(ETHERNET_USE_RAK13800) if (handleRak4631PeripheralCommand(command, reply, reply_size)) return true; #endif @@ -11587,16 +11588,21 @@ bool MyMesh::canRecoverUsbLogging() const { } bool MyMesh::hasPendingWork() const { + return pendingWorkReason() != 0; +} + +mesh::powerdiag::Mask MyMesh::pendingWorkReason() const { + using mesh::powerdiag::Reason; + using mesh::powerdiag::mask; #if COMPANION_FEATURE_READER - if (mesh::readerCommandActive()) return true; + if (mesh::readerCommandActive()) return mask(Reason::Mesh); #endif #if COMPANION_FEATURE_NOTIFICATIONS - if (_notifications.active()) return true; + if (_notifications.active()) return mask(Reason::Mesh); #endif - if (isDualRadioActive()) return true; - if (_radio_available - && (radio_driver.isWatchdogObserving() - || radio_driver.isCalibratingNoiseFloor())) return true; + if (isDualRadioActive()) return mask(Reason::DualRadio); + if (_radio_available && radio_driver.isWatchdogObserving()) return mask(Reason::RadioWatchdog); + if (_radio_available && radio_driver.isCalibratingNoiseFloor()) return mask(Reason::Calibration); #if defined(NRF52_PLATFORM) // nRF52 sleep is event-driven, so a future lazy-write deadline has no // guaranteed interrupt to wake the loop when it becomes due. Keep polling @@ -11609,38 +11615,36 @@ bool MyMesh::hasPendingWork() const { #else const bool contact_write_needs_polling = isContactWriteDue(); #endif - return (_serial != NULL && _serial->hasPendingIO()) - || (_iter_started && _serial != NULL - && _serial->isReplyRouteAvailable(_iter_reply_route)) - || hasPendingOtaApply() - || command_radio_apply_pending - || _scheduled_reboot_at != 0 - || hasPendingReqs() - || _delayed_replies.hasBinaryTrace() + if (_serial != NULL && _serial->hasPendingIO()) return mask(Reason::Serial); + if (_iter_started && _serial != NULL + && _serial->isReplyRouteAvailable(_iter_reply_route)) return mask(Reason::Serial); + if (hasPendingOtaApply()) return mask(Reason::Ota); + if (command_radio_apply_pending || _scheduled_reboot_at != 0) return mask(Reason::Scheduled); + if (hasPendingReqs() || _delayed_replies.hasBinaryTrace()) return mask(Reason::Mesh); #if COMPANION_FEATURE_TEXT_TERMINAL - || _terminal_trace_pending + if (_terminal_trace_pending) return mask(Reason::Mesh); #endif - || sign_data != NULL - || hasQueuedWorkDue() || hasRetryWorkDue() - || (saved_radio_apply_pending + if (sign_data != NULL) return mask(Reason::Mesh); + if (hasQueuedWorkDue()) return mask(Reason::Queue); + if (hasRetryWorkDue()) return mask(Reason::Retry); + if (saved_radio_apply_pending #if COMPANION_FEATURE_TEMP_RADIO // Match loop()'s restore gate: a lease-blocked rollback is not // runnable work. The lease's own timers below wake it when due. && !_temp_radio_applied && _temp_radio_set_at == 0 && _temp_radio_revert_at == 0 #endif - && (!radio_apply_retry_at || millisHasNowPassed(radio_apply_retry_at))) - || contact_write_needs_polling - || _store->contactRecoveryPending() + && (!radio_apply_retry_at || millisHasNowPassed(radio_apply_retry_at))) return mask(Reason::Scheduled); + if (contact_write_needs_polling || _store->contactRecoveryPending()) return mask(Reason::Mesh); #if defined(ESP32_PLATFORM) - || _store->hasPendingAdvertWrites() + if (_store->hasPendingAdvertWrites()) return mask(Reason::Mesh); #endif - || (emergency_client_repeat_packet != NULL - && millisHasNowPassed(emergency_client_repeat_send_at)) + if (emergency_client_repeat_packet != NULL + && millisHasNowPassed(emergency_client_repeat_send_at)) return mask(Reason::Queue); #if COMPANION_FEATURE_TEMP_RADIO - || (_temp_radio_set_at != 0 && millisHasNowPassed(_temp_radio_set_at)) + if ((_temp_radio_set_at != 0 && millisHasNowPassed(_temp_radio_set_at)) || (_temp_radio_revert_at != 0 && millisHasNowPassed(_temp_radio_revert_at)) - || (_temp_radio_retry_at != 0 && millisHasNowPassed(_temp_radio_retry_at)) + || (_temp_radio_retry_at != 0 && millisHasNowPassed(_temp_radio_retry_at))) return mask(Reason::Scheduled); #endif - ; + return 0; } diff --git a/examples/companion_radio/MyMesh.h b/examples/companion_radio/MyMesh.h index c48eb00e1..3efbc84d3 100644 --- a/examples/companion_radio/MyMesh.h +++ b/examples/companion_radio/MyMesh.h @@ -5,6 +5,7 @@ #include "AbstractUITask.h" #include "CompanionFeatures.h" #include +#include /*------------ Frame Protocol --------------*/ #define FIRMWARE_VER_CODE 14 @@ -588,6 +589,7 @@ public: #endif // To check if there is pending work + mesh::powerdiag::Mask pendingWorkReason() const; bool hasPendingWork() const; bool canRecoverUsbLogging() const; diff --git a/examples/companion_radio/main.cpp b/examples/companion_radio/main.cpp index 6792716a5..7707262e4 100644 --- a/examples/companion_radio/main.cpp +++ b/examples/companion_radio/main.cpp @@ -4209,25 +4209,33 @@ void loop() { // USB power alone (for example, a wall charger) does not inhibit sleep. // Host sessions, live logging, and button activity still need service. - bool can_sleep = the_mesh.getNodePrefs()->powersaving_enabled - && !morse_timing - && !the_mesh.hasPendingWork() - && !mesh::isUsbLoggingWatchdogArmed() - && !mesh::wireless::control().pending(); + using mesh::powerdiag::Reason; + using mesh::powerdiag::mask; + // Keep the existing short-circuit policy: report the first guard that + // actually vetoed sleep, without polling otherwise skipped peripherals. + mesh::powerdiag::Mask sleep_reason = [&]() -> mesh::powerdiag::Mask { + if (!the_mesh.getNodePrefs()->powersaving_enabled) return mask(Reason::PolicyOff); + if (morse_timing) return mask(Reason::Morse); + const auto pending = the_mesh.pendingWorkReason(); + if (pending) return pending; + if (mesh::isUsbLoggingWatchdogArmed()) return mask(Reason::UsbRecovery); + if (mesh::wireless::control().pending()) return mask(Reason::Wireless); + return 0; + }(); #if defined(ESP32_PLATFORM) && MESH_USB_LOGGING_AVAILABLE // The native-USB-only light-sleep path below bypasses ESP32Board::sleep. - can_sleep = can_sleep && !mesh::isUsbLoggingEnabled(); + if (!sleep_reason && mesh::isUsbLoggingEnabled()) sleep_reason = mask(Reason::UsbLogging); #endif #if defined(ESP32_PLATFORM) && defined(ENABLE_USB_INTERFACE) const bool usb_sleep_held = board.isUsbSleepHeld(); - can_sleep = can_sleep && !usb_sleep_held; + if (!sleep_reason && usb_sleep_held) sleep_reason = mask(Reason::UsbSession); #elif defined(NRF52_PLATFORM) - can_sleep = can_sleep && !board.isUsbHostConnected(); + if (!sleep_reason && board.isUsbHostConnected()) sleep_reason = mask(Reason::UsbSession); #endif #if defined(NRF52_PLATFORM) && defined(ETHERNET_USE_RAK13800) // Polled Ethernet has no GPIO wake for a client or parked worker. OFF also // disables its logical transport before main-thread resource release ends. - can_sleep = can_sleep && !ethernet_interface.hardwareActive(); + if (!sleep_reason && ethernet_interface.hardwareActive()) sleep_reason = mask(Reason::Network); #endif #if defined(MOMENTARY_BUTTON_WAKE_FROM_SLEEP) \ && MOMENTARY_BUTTON_WAKE_FROM_SLEEP \ @@ -4235,8 +4243,10 @@ void loop() { // GPIO wake starts the poller, but multi-click and long-press results // are due after a time interval rather than another edge. The G3 also // retains a two-minute wake interval after button activity. - can_sleep = can_sleep && !user_btn.needsPolling(); + if (!sleep_reason && user_btn.needsPolling()) sleep_reason = mask(Reason::Button); #endif + if (mesh::powerdiag::enabled()) mesh::powerdiag::decision(sleep_reason, millis()); + const bool can_sleep = sleep_reason == 0; if (can_sleep) { #if defined(NRF52_PLATFORM) board.sleep(0); // nrf ignores seconds param, sleeps whenever possible @@ -4248,9 +4258,23 @@ void loop() { // core. A short timer slice gives idle battery builds real light sleep without // delaying radio, GPS, button, or newly attached USB work by more than the // normal 10 ms loop cadence. can_sleep already proved no USB host is up. - if (!companionNativeUsbLightSleepReady() - || esp_sleep_enable_timer_wakeup(10000ULL) != ESP_OK - || esp_light_sleep_start() != ESP_OK) { + bool sleep_failed = false; + if (!companionNativeUsbLightSleepReady()) { + if (mesh::powerdiag::enabled()) mesh::powerdiag::boardVeto(Reason::Board, millis()); + sleep_failed = true; + } else { + esp_err_t error = esp_sleep_enable_timer_wakeup(10000ULL); + if (error == ESP_OK) { + if (mesh::powerdiag::enabled()) mesh::powerdiag::sleepBegin(micros()); + error = esp_light_sleep_start(); + if (mesh::powerdiag::enabled()) mesh::powerdiag::sleepEnd(micros()); + } + if (error != ESP_OK) { + if (mesh::powerdiag::enabled()) mesh::powerdiag::boardError(error, millis()); + sleep_failed = true; + } + } + if (sleep_failed) { vTaskDelay(pdMS_TO_TICKS(10)); } #elif COMPANION_IDF_PM_AVAILABLE diff --git a/examples/simple_repeater/MyMesh.cpp b/examples/simple_repeater/MyMesh.cpp index 74b3eecf5..786e712f9 100644 --- a/examples/simple_repeater/MyMesh.cpp +++ b/examples/simple_repeater/MyMesh.cpp @@ -5180,21 +5180,29 @@ uint32_t MyMesh::limitSleepToScheduledRadioWork(uint32_t sleep_secs) const { } uint32_t MyMesh::getPowerSaveSleepSeconds(uint32_t max_secs) const { - if (max_secs == 0 || hasPendingWork()) { + using mesh::powerdiag::mask; + using mesh::powerdiag::Reason; + const mesh::powerdiag::Mask pending = max_secs ? pendingWorkReason() : mask(Reason::NoWake); + if (pending) { + if (mesh::powerdiag::enabled()) mesh::powerdiag::decision(pending, millis()); return 0; } + mesh::powerdiag::Mask blocked = 0; uint32_t sleep_secs = max_secs; uint32_t queue_delay_ms; if (getNextQueueWakeDelay(queue_delay_ms)) { uint32_t queue_delay_secs = mesh::power::powerSaveSleepSeconds(queue_delay_ms); if (queue_delay_secs < sleep_secs) sleep_secs = queue_delay_secs; + if (queue_delay_secs == 0) blocked |= mask(Reason::Queue); } uint32_t retry_delay_ms; if (getNextRetryWakeDelay(retry_delay_ms)) { uint32_t retry_delay_secs = mesh::power::powerSaveSleepSeconds(retry_delay_ms); if (retry_delay_secs < sleep_secs) sleep_secs = retry_delay_secs; + if (retry_delay_secs == 0) blocked |= mask(Reason::Retry); } + const uint32_t before_scheduled = sleep_secs; sleep_secs = limitSleepToMillisTimer(next_flood_advert, sleep_secs); sleep_secs = limitSleepToMillisTimer(next_local_advert, sleep_secs); sleep_secs = limitSleepToMillisTimer(dirty_contacts_expiry, sleep_secs); @@ -5203,14 +5211,17 @@ uint32_t MyMesh::getPowerSaveSleepSeconds(uint32_t max_secs) const { sleep_secs = limitSleepToMillisTimer(next_battery_alert_check, sleep_secs); } sleep_secs = limitSleepToScheduledRadioWork(sleep_secs); + if (before_scheduled > 0 && sleep_secs == 0) blocked |= mask(Reason::Scheduled); #if defined(WITH_RS232_BRIDGE) if (bridge && rs232BridgeEnabled()) { // Floor the deadline, not ceil: the ESP32 timed-light-sleep API uses whole // seconds and must never sleep past a UART rendezvous or cleanup retry. const uint32_t bridge_sleep_secs = bridge->powerWakeDelayMs(millis()) / 1000UL; if (bridge_sleep_secs < sleep_secs) sleep_secs = bridge_sleep_secs; + if (bridge_sleep_secs == 0) blocked |= mask(Reason::BridgeWake); } #endif + if (blocked && mesh::powerdiag::enabled()) mesh::powerdiag::decision(blocked, millis()); return sleep_secs; } @@ -13907,14 +13918,22 @@ void MyMesh::serviceIdleWiFi() { #endif bool MyMesh::hasPendingWork() const { - if (isDualRadioActive()) return true; - if (hasPendingOtaApply()) return true; + return pendingWorkReason() != 0; +} + +mesh::powerdiag::Mask MyMesh::pendingWorkReason() const { + using mesh::powerdiag::mask; + using mesh::powerdiag::Reason; + // Keep the original guard order and short circuit: diagnostics must not + // probe additional hardware or change which work keeps the MCU awake. + if (isDualRadioActive()) return mask(Reason::DualRadio); + if (hasPendingOtaApply()) return mask(Reason::Ota); #if defined(ESP32_PLATFORM) - if (mesh::wifi::networkPower().foregroundActive()) return true; + if (mesh::wifi::networkPower().foregroundActive()) return mask(Reason::Network); #endif #ifdef WITH_WEBCONFIG if (isWebConfigActive() && (!mesh::wifi::networkPower().backgroundSuspended() - || _webconfig->isNetworkForegroundActive(millis()))) return true; + || _webconfig->isNetworkForegroundActive(millis()))) return mask(Reason::Network); #endif #if defined(ESP32_PLATFORM) \ && (defined(WITH_WEBCONFIG) || defined(WITH_MQTT_BRIDGE) || defined(WITH_ESPNOW_BRIDGE) \ @@ -13924,44 +13943,45 @@ bool MyMesh::hasPendingWork() const { // Cleanup may fail while the Arduino facade already reports OFF. Require // the live SDK driver to be gone before permitting manual light sleep. wifi_mode_t sdk_mode = WIFI_MODE_NULL; - if (esp_wifi_get_mode(&sdk_mode) != ESP_ERR_WIFI_NOT_INIT) return true; + if (esp_wifi_get_mode(&sdk_mode) != ESP_ERR_WIFI_NOT_INIT) return mask(Reason::Network); #endif #if defined(WITH_WEBCONFIG) || defined(ETHERNET_ENABLED) - if (_local_cli_output.busy()) return true; + if (_local_cli_output.busy()) return mask(Reason::Serial); #endif - if (deferred_cli_command.pending || pending_self_advert || _cli.hasActiveUserGpioTimer()) return true; + if (deferred_cli_command.pending || pending_self_advert || _cli.hasActiveUserGpioTimer()) return mask(Reason::Scheduled); #if defined(WITH_BRIDGE) const AbstractBridge* active_bridge = activeBridge(); if (active_bridge && active_bridge->isRunning()) { #ifdef WITH_MQTT_BRIDGE - if (active_bridge != mqtt_bridge || !mqtt_bridge->isNetworkSuspended()) return true; + if (active_bridge != mqtt_bridge || !mqtt_bridge->isNetworkSuspended()) return mask(Reason::Bridge); #else - return true; + return mask(Reason::Bridge); #endif } #ifdef WITH_MQTT_BRIDGE - if (mqtt_bridge && mqtt_bridge->isStopping()) return true; + if (mqtt_bridge && mqtt_bridge->isStopping()) return mask(Reason::BridgeCleanup); #endif #if defined(WITH_MQTT_BRIDGE) && defined(WITH_RS232_BRIDGE) - if (isRs232BridgeRunning()) return true; + if (isRs232BridgeRunning()) return mask(Reason::Bridge); #endif #if defined(WITH_RS232_BRIDGE) // A partial GPS release/claim is not a completed standby. Never allow MCU // sleep while its UART ownership remains unresolved, even if end stopped RX. - if (active_rs232_bridge_uart != 0) return true; - if (bridge && rs232BridgeEnabled() && bridge->powerWakeDelayMs(millis()) == 0) return true; + if (active_rs232_bridge_uart != 0) return mask(Reason::BridgeCleanup); + if (bridge && rs232BridgeEnabled() && bridge->powerWakeDelayMs(millis()) == 0) return mask(Reason::BridgeWake); #endif #if defined(WITH_ESPNOW_BRIDGE) \ && (defined(WITH_MQTT_BRIDGE) || defined(WITH_RS232_BRIDGE)) - if (espnow_bridge.isRunning()) return true; + if (espnow_bridge.isRunning()) return mask(Reason::Bridge); #endif #endif - if (radio_driver.isWatchdogObserving()) return true; // keep MCU awake for one radio duty cycle - if (radio_driver.isCalibratingNoiseFloor()) return true; // keep MCU awake for the noise-floor window - if (hasQueuedWorkDue() || hasRetryWorkDue()) return true; - if (isMillisTimerDue(next_flood_advert) || isMillisTimerDue(next_local_advert)) return true; - if (isMillisTimerDue(dirty_contacts_expiry)) return true; - if (isMillisTimerDue(next_recent_repeater_sweep)) return true; - if (_prefs.battery_alert_enabled && isMillisTimerDue(next_battery_alert_check)) return true; - return hasScheduledRadioWorkDue(); + if (radio_driver.isWatchdogObserving()) return mask(Reason::RadioWatchdog); + if (radio_driver.isCalibratingNoiseFloor()) return mask(Reason::Calibration); + if (hasQueuedWorkDue()) return mask(Reason::Queue); + if (hasRetryWorkDue()) return mask(Reason::Retry); + if (isMillisTimerDue(next_flood_advert) || isMillisTimerDue(next_local_advert)) return mask(Reason::Scheduled); + if (isMillisTimerDue(dirty_contacts_expiry)) return mask(Reason::Scheduled); + if (isMillisTimerDue(next_recent_repeater_sweep)) return mask(Reason::Scheduled); + if (_prefs.battery_alert_enabled && isMillisTimerDue(next_battery_alert_check)) return mask(Reason::Scheduled); + return hasScheduledRadioWorkDue() ? mask(Reason::Scheduled) : 0; } diff --git a/examples/simple_repeater/MyMesh.h b/examples/simple_repeater/MyMesh.h index 662e59373..5e32f5859 100644 --- a/examples/simple_repeater/MyMesh.h +++ b/examples/simple_repeater/MyMesh.h @@ -3,6 +3,7 @@ #include #include #include +#include #if defined(ENABLE_OTA) #include #endif @@ -1901,6 +1902,7 @@ public: // To check if there is pending work bool hasPendingWork() const; + mesh::powerdiag::Mask pendingWorkReason() const; bool setRxBoostedGain(bool enable) override; void recalibrateNoiseFloor() override { _radio->recalibrateNoiseFloor(); } diff --git a/examples/simple_repeater/main.cpp b/examples/simple_repeater/main.cpp index 104d6e080..697f228c1 100644 --- a/examples/simple_repeater/main.cpp +++ b/examples/simple_repeater/main.cpp @@ -620,18 +620,26 @@ void loop() { #ifdef HAS_EXTERNAL_WATCHDOG external_watchdog.loop(); #endif - bool can_power_save = the_mesh.getNodePrefs()->powersaving_enabled - && !morse_timing - && !board.isUsbDataConnected() - && !mesh::isUsbLoggingWatchdogArmed() - && !mesh::wireless::control().pending(); + // Report the guard that really stopped this iteration, without probing + // later guards or changing their short-circuit hardware access. + const auto sleep_guard = [](bool allowed, mesh::powerdiag::Reason reason) { + if (!allowed && mesh::powerdiag::enabled()) + mesh::powerdiag::decision(mesh::powerdiag::mask(reason), millis()); + return allowed; + }; + bool can_power_save = sleep_guard(the_mesh.getNodePrefs()->powersaving_enabled, + mesh::powerdiag::Reason::PolicyOff) + && sleep_guard(!morse_timing, mesh::powerdiag::Reason::Morse) + && sleep_guard(!board.isUsbDataConnected(), mesh::powerdiag::Reason::UsbSession) + && sleep_guard(!mesh::isUsbLoggingWatchdogArmed(), mesh::powerdiag::Reason::UsbRecovery) + && sleep_guard(!mesh::wireless::control().pending(), mesh::powerdiag::Reason::Wireless); #if defined(MOMENTARY_BUTTON_WAKE_FROM_SLEEP) \ && MOMENTARY_BUTTON_WAKE_FROM_SLEEP \ && defined(PIN_USER_BTN) && defined(DISPLAY_CLASS) // GPIO wake starts the first poll. Keep debounce and multi-click deadlines // awake too, so a release cannot strand the remaining 25/280 ms interval. // The G3 also retains its two-minute button wake interval here. - can_power_save = can_power_save && !user_btn.needsPolling(); + can_power_save = can_power_save && sleep_guard(!user_btn.needsPolling(), mesh::powerdiag::Reason::Button); #endif if (can_power_save) { uint32_t sleep_secs = the_mesh.getPowerSaveSleepSeconds(30); @@ -640,11 +648,15 @@ void loop() { #endif #if defined(NRF52_PLATFORM) if (sleep_secs > 0) { + if (mesh::powerdiag::enabled()) mesh::powerdiag::decision(0, millis()); board.sleep(0); // nrf ignores seconds param, sleeps whenever possible } #else if (sleep_secs > 0 && the_mesh.millisHasNowPassed(POWERSAVING_FIRSTSLEEP_SECS * 1000)) { // To check if it is time to sleep + if (mesh::powerdiag::enabled()) mesh::powerdiag::decision(0, millis()); board.sleep(sleep_secs); // Sleep. Wake up for scheduled jobs or when receiving a LoRa packet + } else if (sleep_secs > 0 && mesh::powerdiag::enabled()) { + mesh::powerdiag::decision(mesh::powerdiag::mask(mesh::powerdiag::Reason::Startup), millis()); } #endif } diff --git a/examples/simple_room_server/MyMesh.cpp b/examples/simple_room_server/MyMesh.cpp index 36c235566..c6feb75ff 100644 --- a/examples/simple_room_server/MyMesh.cpp +++ b/examples/simple_room_server/MyMesh.cpp @@ -4200,21 +4200,29 @@ uint32_t MyMesh::limitSleepToMillisTimer(unsigned long timestamp, uint32_t sleep } uint32_t MyMesh::getPowerSaveSleepSeconds(uint32_t max_secs) const { - if (max_secs == 0 || hasPendingWork()) { + using mesh::powerdiag::mask; + using mesh::powerdiag::Reason; + const mesh::powerdiag::Mask pending = max_secs ? pendingWorkReason() : mask(Reason::NoWake); + if (pending) { + if (mesh::powerdiag::enabled()) mesh::powerdiag::decision(pending, millis()); return 0; } + mesh::powerdiag::Mask blocked = 0; uint32_t sleep_secs = max_secs; uint32_t queue_delay_ms; if (getNextQueueWakeDelay(queue_delay_ms)) { uint32_t queue_delay_secs = mesh::power::powerSaveSleepSeconds(queue_delay_ms); if (queue_delay_secs < sleep_secs) sleep_secs = queue_delay_secs; + if (queue_delay_secs == 0) blocked |= mask(Reason::Queue); } uint32_t retry_delay_ms; if (getNextRetryWakeDelay(retry_delay_ms)) { uint32_t retry_delay_secs = mesh::power::powerSaveSleepSeconds(retry_delay_ms); if (retry_delay_secs < sleep_secs) sleep_secs = retry_delay_secs; + if (retry_delay_secs == 0) blocked |= mask(Reason::Retry); } + const uint32_t before_scheduled = sleep_secs; if (acl.getNumClients() > 0) { sleep_secs = limitSleepToMillisTimer(next_push, sleep_secs); } @@ -4228,6 +4236,8 @@ uint32_t MyMesh::getPowerSaveSleepSeconds(uint32_t max_secs) const { sleep_secs = limitSleepToMillisTimer(revert_radio_at, sleep_secs); } sleep_secs = limitSleepToMillisTimer(dirty_contacts_expiry, sleep_secs); + if (before_scheduled > 0 && sleep_secs == 0) blocked |= mask(Reason::Scheduled); + if (blocked && mesh::powerdiag::enabled()) mesh::powerdiag::decision(blocked, millis()); return sleep_secs; } @@ -4269,14 +4279,20 @@ void MyMesh::serviceIdleWiFi() { #endif bool MyMesh::hasPendingWork() const { - if (isDualRadioActive()) return true; - if (hasPendingOtaApply()) return true; + return pendingWorkReason() != 0; +} + +mesh::powerdiag::Mask MyMesh::pendingWorkReason() const { + using mesh::powerdiag::mask; + using mesh::powerdiag::Reason; + if (isDualRadioActive()) return mask(Reason::DualRadio); + if (hasPendingOtaApply()) return mask(Reason::Ota); #if defined(ESP32_PLATFORM) - if (mesh::wifi::networkPower().foregroundActive()) return true; + if (mesh::wifi::networkPower().foregroundActive()) return mask(Reason::Network); #endif #ifdef WITH_WEBCONFIG if (isWebConfigActive() && (!mesh::wifi::networkPower().backgroundSuspended() - || _webconfig->isNetworkForegroundActive(millis()))) return true; + || _webconfig->isNetworkForegroundActive(millis()))) return mask(Reason::Network); #endif #if defined(ESP32_PLATFORM) \ && (defined(WITH_WEBCONFIG) || defined(WITH_MQTT_BRIDGE) || defined(WITH_ESPNOW_BRIDGE) \ @@ -4286,34 +4302,35 @@ bool MyMesh::hasPendingWork() const { // Never sleep over an unowned driver whose cleanup failed or whose Arduino // facade no longer reflects the live SDK state. wifi_mode_t sdk_mode = WIFI_MODE_NULL; - if (esp_wifi_get_mode(&sdk_mode) != ESP_ERR_WIFI_NOT_INIT) return true; + if (esp_wifi_get_mode(&sdk_mode) != ESP_ERR_WIFI_NOT_INIT) return mask(Reason::Network); #endif #if defined(WITH_WEBCONFIG) || defined(ETHERNET_ENABLED) - if (_local_cli_output.busy()) return true; + if (_local_cli_output.busy()) return mask(Reason::Serial); #endif #if defined(WITH_BRIDGE) #ifdef WITH_MQTT_BRIDGE - if (bridge && bridge->isRunning() && !bridge->isNetworkSuspended()) return true; + if (bridge && bridge->isRunning() && !bridge->isNetworkSuspended()) return mask(Reason::Bridge); #else - if (bridge && bridge->isRunning()) return true; + if (bridge && bridge->isRunning()) return mask(Reason::Bridge); #endif #ifdef WITH_MQTT_BRIDGE - if (bridge && bridge->isStopping()) return true; + if (bridge && bridge->isStopping()) return mask(Reason::BridgeCleanup); #endif #if defined(WITH_ESPNOW_BRIDGE) - if (espnow_bridge.isRunning()) return true; + if (espnow_bridge.isRunning()) return mask(Reason::Bridge); #endif #endif - if (radio_driver.isWatchdogObserving()) return true; // keep MCU awake for one radio duty cycle - if (radio_driver.isCalibratingNoiseFloor()) return true; // keep MCU awake for the noise-floor window - if (hasQueuedWorkDue() || hasRetryWorkDue()) return true; - if (acl.getNumClients() > 0 && isMillisTimerDue(next_push)) return true; - if (isMillisTimerDue(next_flood_advert) || isMillisTimerDue(next_local_advert)) return true; + if (radio_driver.isWatchdogObserving()) return mask(Reason::RadioWatchdog); + if (radio_driver.isCalibratingNoiseFloor()) return mask(Reason::Calibration); + if (hasQueuedWorkDue()) return mask(Reason::Queue); + if (hasRetryWorkDue()) return mask(Reason::Retry); + if (acl.getNumClients() > 0 && isMillisTimerDue(next_push)) return mask(Reason::Scheduled); + if (isMillisTimerDue(next_flood_advert) || isMillisTimerDue(next_local_advert)) return mask(Reason::Scheduled); const bool radio_apply_backoff = radio_apply_retry_at && !isMillisTimerDue(radio_apply_retry_at); if (!radio_apply_backoff && (isMillisTimerDue(set_radio_at) || isMillisTimerDue(revert_radio_at) - || (saved_radio_apply_pending && !temp_radio_applied))) return true; - return isMillisTimerDue(dirty_contacts_expiry); + || (saved_radio_apply_pending && !temp_radio_applied))) return mask(Reason::Scheduled); + return isMillisTimerDue(dirty_contacts_expiry) ? mask(Reason::Scheduled) : 0; } #if defined(WITH_MQTT_NEIGHBORS) #include "helpers/MQTTMessageBuilder.h" diff --git a/examples/simple_room_server/MyMesh.h b/examples/simple_room_server/MyMesh.h index a9ef5f996..fbdad0604 100644 --- a/examples/simple_room_server/MyMesh.h +++ b/examples/simple_room_server/MyMesh.h @@ -2,6 +2,7 @@ #include // needed for PlatformIO #include +#include #include "RoomServerFeatures.h" #if defined(NRF52_PLATFORM) @@ -1043,6 +1044,7 @@ public: // To check if there is pending work bool hasPendingWork() const; + mesh::powerdiag::Mask pendingWorkReason() const; private: bool isMillisTimerDue(unsigned long timestamp) const; diff --git a/examples/simple_room_server/main.cpp b/examples/simple_room_server/main.cpp index c9fa42daa..cf4d35af1 100644 --- a/examples/simple_room_server/main.cpp +++ b/examples/simple_room_server/main.cpp @@ -397,15 +397,21 @@ void loop() { #ifdef HAS_EXTERNAL_WATCHDOG external_watchdog.loop(); #endif - bool can_power_save = the_mesh.getNodePrefs()->powersaving_enabled - && !morse_timing - && !board.isUsbDataConnected() - && !mesh::isUsbLoggingWatchdogArmed() - && !mesh::wireless::control().pending(); + const auto sleep_guard = [](bool allowed, mesh::powerdiag::Reason reason) { + if (!allowed && mesh::powerdiag::enabled()) + mesh::powerdiag::decision(mesh::powerdiag::mask(reason), millis()); + return allowed; + }; + bool can_power_save = sleep_guard(the_mesh.getNodePrefs()->powersaving_enabled, + mesh::powerdiag::Reason::PolicyOff) + && sleep_guard(!morse_timing, mesh::powerdiag::Reason::Morse) + && sleep_guard(!board.isUsbDataConnected(), mesh::powerdiag::Reason::UsbSession) + && sleep_guard(!mesh::isUsbLoggingWatchdogArmed(), mesh::powerdiag::Reason::UsbRecovery) + && sleep_guard(!mesh::wireless::control().pending(), mesh::powerdiag::Reason::Wireless); #if defined(MOMENTARY_BUTTON_WAKE_FROM_SLEEP) \ && MOMENTARY_BUTTON_WAKE_FROM_SLEEP \ && defined(PIN_USER_BTN) && defined(DISPLAY_CLASS) - can_power_save = can_power_save && !user_btn.needsPolling(); + can_power_save = can_power_save && sleep_guard(!user_btn.needsPolling(), mesh::powerdiag::Reason::Button); #endif if (can_power_save) { uint32_t sleep_secs = the_mesh.getPowerSaveSleepSeconds(30); @@ -414,11 +420,15 @@ void loop() { #endif #if defined(NRF52_PLATFORM) if (sleep_secs > 0) { + if (mesh::powerdiag::enabled()) mesh::powerdiag::decision(0, millis()); board.sleep(0); // nrf ignores seconds param, sleeps whenever possible } #else if (sleep_secs > 0 && the_mesh.millisHasNowPassed(POWERSAVING_FIRSTSLEEP_SECS * 1000)) { // To check if it is time to sleep + if (mesh::powerdiag::enabled()) mesh::powerdiag::decision(0, millis()); board.sleep(sleep_secs); // Sleep. Wake up for scheduled jobs or when receiving a LoRa packet + } else if (sleep_secs > 0 && mesh::powerdiag::enabled()) { + mesh::powerdiag::decision(mesh::powerdiag::mask(mesh::powerdiag::Reason::Startup), millis()); } #endif } diff --git a/examples/simple_sensor/SensorMesh.cpp b/examples/simple_sensor/SensorMesh.cpp index e2402693c..c441b1b12 100644 --- a/examples/simple_sensor/SensorMesh.cpp +++ b/examples/simple_sensor/SensorMesh.cpp @@ -1715,41 +1715,59 @@ uint32_t SensorMesh::limitSleepToMillisTimer(unsigned long timestamp, } bool SensorMesh::hasPendingWork() const { + return pendingWorkReason() != 0; +} + +mesh::powerdiag::Mask SensorMesh::pendingWorkReason() const { + using mesh::powerdiag::mask; + using mesh::powerdiag::Reason; #if MESH_ENABLE_SENSOR_TRACKER if (tracker.enabled && (tracker_pending || tracker_acquiring || (tracker_awake_until && !millisHasNowPassed(tracker_awake_until)) - || (!tracker_storage_fault && getRTCClock()->getCurrentTime() >= tracker_next_check))) return true; + || (!tracker_storage_fault && getRTCClock()->getCurrentTime() >= tracker_next_check))) return mask(Reason::Tracker); #endif - if (isDualRadioActive()) return true; - if (hasPendingOtaApply()) return true; - if (_cli.hasActiveUserGpioTimer()) return true; - if (radio_driver.isWatchdogObserving()) return true; - if (radio_driver.isCalibratingNoiseFloor()) return true; - if (hasQueuedWorkDue() || hasRetryWorkDue()) return true; + if (isDualRadioActive()) return mask(Reason::DualRadio); + if (hasPendingOtaApply()) return mask(Reason::Ota); + if (_cli.hasActiveUserGpioTimer()) return mask(Reason::Scheduled); + if (radio_driver.isWatchdogObserving()) return mask(Reason::RadioWatchdog); + if (radio_driver.isCalibratingNoiseFloor()) return mask(Reason::Calibration); + if (hasQueuedWorkDue()) return mask(Reason::Queue); + if (hasRetryWorkDue()) return mask(Reason::Retry); if (isMillisTimerDue(next_flood_advert) || isMillisTimerDue(next_local_advert) - || isMillisTimerDue(dirty_contacts_expiry)) return true; + || isMillisTimerDue(dirty_contacts_expiry)) return mask(Reason::Scheduled); if (num_alert_tasks > 0 - && isMillisTimerDue(alert_tasks[0]->send_expiry)) return true; + && isMillisTimerDue(alert_tasks[0]->send_expiry)) return mask(Reason::Scheduled); const bool radio_apply_backoff = radio_apply_retry_at && !millisHasNowPassed(radio_apply_retry_at); if (!radio_apply_backoff && (isMillisTimerDue(set_radio_at) || isMillisTimerDue(revert_radio_at) - || (saved_radio_apply_pending && !temp_radio_applied))) return true; + || (saved_radio_apply_pending && !temp_radio_applied))) return mask(Reason::Scheduled); uint32_t now_secs = getRTCClock()->getCurrentTime(); - return now_secs >= last_read_time + SENSOR_READ_INTERVAL_SECS; + return now_secs >= last_read_time + SENSOR_READ_INTERVAL_SECS + ? mask(Reason::Scheduled) : 0; } uint32_t SensorMesh::getPowerSaveSleepSeconds(uint32_t max_secs) const { - if (max_secs == 0 || hasPendingWork()) return 0; + using mesh::powerdiag::mask; + using mesh::powerdiag::Reason; + const mesh::powerdiag::Mask pending = max_secs ? pendingWorkReason() : mask(Reason::NoWake); + if (pending) { + if (mesh::powerdiag::enabled()) mesh::powerdiag::decision(pending, millis()); + return 0; + } + mesh::powerdiag::Mask blocked = 0; uint32_t sleep_secs = max_secs; #if MESH_ENABLE_SENSOR_TRACKER if (tracker.enabled && !tracker_storage_fault) { const uint32_t now = getRTCClock()->getCurrentTime(); - if (now >= tracker_next_check) return 0; + if (now >= tracker_next_check) { + if (mesh::powerdiag::enabled()) mesh::powerdiag::decision(mask(Reason::Tracker), millis()); + return 0; + } const uint32_t until_check = tracker_next_check - now; if (until_check < sleep_secs) sleep_secs = until_check; } @@ -1758,6 +1776,7 @@ uint32_t SensorMesh::getPowerSaveSleepSeconds(uint32_t max_secs) const { if (getNextQueueWakeDelay(wake_delay_ms)) { uint32_t wake_delay_secs = mesh::power::powerSaveSleepSeconds(wake_delay_ms); if (wake_delay_secs < sleep_secs) sleep_secs = wake_delay_secs; + if (wake_delay_secs == 0) blocked |= mask(Reason::Queue); } #if MESH_ENABLE_SENSOR_TRACKER && MESH_ENABLE_TX_BEACONS // The normal queue query omits RF maintenance while radio_available is @@ -1765,13 +1784,16 @@ uint32_t SensorMesh::getPowerSaveSleepSeconds(uint32_t max_secs) const { if (tracker.enabled && getNextBeaconWakeDelay(wake_delay_ms)) { uint32_t wake_delay_secs = mesh::power::powerSaveSleepSeconds(wake_delay_ms); if (wake_delay_secs < sleep_secs) sleep_secs = wake_delay_secs; + if (wake_delay_secs == 0) blocked |= mask(Reason::Queue); } #endif if (getNextRetryWakeDelay(wake_delay_ms)) { uint32_t wake_delay_secs = mesh::power::powerSaveSleepSeconds(wake_delay_ms); if (wake_delay_secs < sleep_secs) sleep_secs = wake_delay_secs; + if (wake_delay_secs == 0) blocked |= mask(Reason::Retry); } + const uint32_t before_scheduled = sleep_secs; sleep_secs = limitSleepToMillisTimer(next_flood_advert, sleep_secs); sleep_secs = limitSleepToMillisTimer(next_local_advert, sleep_secs); sleep_secs = limitSleepToMillisTimer(dirty_contacts_expiry, sleep_secs); @@ -1795,5 +1817,7 @@ uint32_t SensorMesh::getPowerSaveSleepSeconds(uint32_t max_secs) const { uint32_t sensor_delay = sensor_due - now_secs; if (sensor_delay < sleep_secs) sleep_secs = sensor_delay; } + if (before_scheduled > 0 && sleep_secs == 0) blocked |= mask(Reason::Scheduled); + if (blocked && mesh::powerdiag::enabled()) mesh::powerdiag::decision(blocked, millis()); return sleep_secs; } diff --git a/examples/simple_sensor/SensorMesh.h b/examples/simple_sensor/SensorMesh.h index e5c9e04ec..c19a612a2 100644 --- a/examples/simple_sensor/SensorMesh.h +++ b/examples/simple_sensor/SensorMesh.h @@ -2,6 +2,7 @@ #include // needed for PlatformIO #include +#include #include "TimeSeriesData.h" @@ -300,6 +301,7 @@ private: uint32_t limitSleepToMillisTimer(unsigned long timestamp, uint32_t sleep_secs) const; bool hasPendingWork() const; + mesh::powerdiag::Mask pendingWorkReason() const; bool region_load_active; bool telemHasChanged(ClientInfo* c); diff --git a/examples/simple_sensor/main.cpp b/examples/simple_sensor/main.cpp index b2f3d5390..bd270d057 100644 --- a/examples/simple_sensor/main.cpp +++ b/examples/simple_sensor/main.cpp @@ -342,15 +342,20 @@ void loop() { external_watchdog.loop(); #endif - bool can_power_save = (the_mesh.getNodePrefs()->powersaving_enabled - || the_mesh.isTrackerModeEnabled()) - && !morse_timing - && !board.isUsbDataConnected() - && !mesh::isUsbLoggingWatchdogArmed(); + const auto sleep_guard = [](bool allowed, mesh::powerdiag::Reason reason) { + if (!allowed && mesh::powerdiag::enabled()) + mesh::powerdiag::decision(mesh::powerdiag::mask(reason), millis()); + return allowed; + }; + bool can_power_save = sleep_guard(the_mesh.getNodePrefs()->powersaving_enabled + || the_mesh.isTrackerModeEnabled(), mesh::powerdiag::Reason::PolicyOff) + && sleep_guard(!morse_timing, mesh::powerdiag::Reason::Morse) + && sleep_guard(!board.isUsbDataConnected(), mesh::powerdiag::Reason::UsbSession) + && sleep_guard(!mesh::isUsbLoggingWatchdogArmed(), mesh::powerdiag::Reason::UsbRecovery); #if defined(MOMENTARY_BUTTON_WAKE_FROM_SLEEP) \ && MOMENTARY_BUTTON_WAKE_FROM_SLEEP \ && defined(PIN_USER_BTN) && defined(DISPLAY_CLASS) - can_power_save = can_power_save && !user_btn.needsPolling(); + can_power_save = can_power_save && sleep_guard(!user_btn.needsPolling(), mesh::powerdiag::Reason::Button); #endif if (can_power_save) { uint32_t sleep_secs = the_mesh.getPowerSaveSleepSeconds(30); @@ -360,9 +365,17 @@ void loop() { #if defined(NRF52_PLATFORM) if (sleep_secs > 0) { #if MESH_ENABLE_SENSOR_TRACKER - if (!the_mesh.isTrackerModeEnabled() || armTrackerSleepWake(sleep_secs)) board.sleep(0); - else delay(1); + if (!the_mesh.isTrackerModeEnabled() || armTrackerSleepWake(sleep_secs)) { + if (mesh::powerdiag::enabled()) mesh::powerdiag::decision(0, millis()); + board.sleep(0); + } + else { + if (mesh::powerdiag::enabled()) + mesh::powerdiag::boardVeto(mesh::powerdiag::Reason::NoWake, millis()); + delay(1); + } #else + if (mesh::powerdiag::enabled()) mesh::powerdiag::decision(0, millis()); board.sleep(0); #endif } @@ -370,7 +383,10 @@ void loop() { if (sleep_secs > 0 && the_mesh.millisHasNowPassed( POWERSAVING_FIRST_SLEEP_SECS * 1000UL)) { + if (mesh::powerdiag::enabled()) mesh::powerdiag::decision(0, millis()); board.sleep(sleep_secs); + } else if (sleep_secs > 0 && mesh::powerdiag::enabled()) { + mesh::powerdiag::decision(mesh::powerdiag::mask(mesh::powerdiag::Reason::Startup), millis()); } #endif } diff --git a/src/MeshCore.h b/src/MeshCore.h index a1888083e..5ef63efed 100644 --- a/src/MeshCore.h +++ b/src/MeshCore.h @@ -5,6 +5,10 @@ #include #include "helpers/UsbLogging.h" #include "helpers/BatteryChargeSupport.h" +#include "helpers/PowerSavingDiagnostics.h" +#if defined(ARDUINO) && (defined(RP2040_PLATFORM) || defined(STM32_PLATFORM)) +#include +#endif #define MAX_HASH_SIZE 8 #define PUB_KEY_SIZE 32 @@ -157,13 +161,24 @@ public: virtual void onBootComplete() { /* no op */ } virtual uint32_t getIRQGpio() { return -1; } // not supported. Returns DIO1 (SX1262) and DIO0 (SX127x) virtual void sleep(uint32_t secs) { - if (isRadioTestActive()) return; + if (isRadioTestActive()) { +#if defined(ARDUINO) && (defined(RP2040_PLATFORM) || defined(STM32_PLATFORM)) + if (powerdiag::enabled()) powerdiag::boardVeto(powerdiag::Reason::Board, millis(), 2); +#endif + return; + } (void)secs; #if defined(RP2040_PLATFORM) || defined(STM32_PLATFORM) // These platforms have no shared deep-sleep board implementation. WFI is // still a real CPU idle state and preserves all configured interrupt wake // sources, including the radio and USB. +#if defined(ARDUINO) + if (powerdiag::enabled()) powerdiag::sleepBegin(micros()); +#endif __asm volatile("wfi"); +#if defined(ARDUINO) + if (powerdiag::enabled()) powerdiag::sleepEnd(micros()); +#endif #endif } virtual uint32_t getGpio() { return 0; } diff --git a/src/helpers/CommonCLI.cpp b/src/helpers/CommonCLI.cpp index b3d1890e5..484ec8742 100644 --- a/src/helpers/CommonCLI.cpp +++ b/src/helpers/CommonCLI.cpp @@ -2,6 +2,7 @@ #include "CommonCLI.h" #include "PrefsSaveReplyGuard.h" #include "UsbLoggingWatchdog.h" +#include "PowerSavingDiagnostics.h" #include "HilStartupTrace.h" #include #include @@ -2963,6 +2964,7 @@ void CommonCLI::handleCommand(uint32_t sender_timestamp, char* command, char* re if (mesh::power::handleBatteryChargeCommand(*_board, command, reply, 160)) return; #endif if (mesh::handleUsbLoggingWatchdogCommand(command, reply, 160)) return; + if (mesh::powerdiag::handleCommand(command, reply, 157, millis())) return; if (handleManagementCommand(command, reply)) return; #if MESH_ENABLE_TX_BEACONS if (handleBeaconCommand(command, reply, 157)) return; diff --git a/src/helpers/ESP32Board.h b/src/helpers/ESP32Board.h index 6c07d8a6d..9858dd86d 100644 --- a/src/helpers/ESP32Board.h +++ b/src/helpers/ESP32Board.h @@ -19,6 +19,7 @@ #include "ESP32GpioHold.h" #include "UsbLogging.h" #include "UsbHostSleepPolicy.h" +#include "PowerSavingDiagnostics.h" #if defined(STATION_G3_ESP32) #include #endif @@ -127,33 +128,48 @@ public: } void sleep(uint32_t secs) override { + using mesh::powerdiag::Reason; + const bool diagnostics = mesh::powerdiag::enabled(); // Native USB loses its connection in light sleep. An enumerated host // still needs USB serviced when no terminal asserts CDC DTR (for example, // after a Pi closes its serial port). Guard every caller here. // Sample even when another blocker is active, so an open console/OTA does // not leave the last positive native USB host signal stale. const bool usb_sleep_held = isUsbSleepHeld(); - bool keep_awake = inhibit_sleep || usb_sleep_held || isRadioTestActive(); + Reason veto_reason = Reason::Board; + int32_t veto_detail = 1; // Explicit inhibit_sleep. + const auto hold = [&veto_reason, &veto_detail](bool active, Reason reason, int32_t detail = 0) { + if (active) { veto_reason = reason; veto_detail = detail; } + return active; + }; + bool keep_awake = inhibit_sleep + || hold(usb_sleep_held, Reason::UsbSession, 1) + || hold(isRadioTestActive(), Reason::Board, 2); #if !defined(ARDUINO_USB_CDC_ON_BOOT) || !ARDUINO_USB_CDC_ON_BOOT // External USB-to-UART chips cannot report host attachment here. Light // sleep loses their first input bytes; UART wake loses the wake character // too. HardwareSerial's bool reports an installed driver, not a USB host. // Keep an enabled console available even before its first command. - keep_awake = keep_awake || static_cast(Serial); + keep_awake = keep_awake || hold(static_cast(Serial), Reason::Serial); #endif #if MESH_USB_LOGGING_AVAILABLE // A live logging stream must also remain available before a host opens // it and across host disconnects. Compiled-out logging is not a blocker. - keep_awake = keep_awake || mesh::isUsbLoggingEnabled(); + keep_awake = keep_awake || hold(mesh::isUsbLoggingEnabled(), Reason::UsbLogging); #endif if (keep_awake) { + if (diagnostics) mesh::powerdiag::boardVeto(veto_reason, millis(), veto_detail); delay(1); // Keep USB and OTA tasks running. return; } + // Capture setup failures, but report them only after the wait (or veto). + // Otherwise its real elapsed time would be mislabelled as blocked time. + esp_err_t setup_error = ESP_OK; // Configure timer wakeup if (secs > 0) { - esp_sleep_enable_timer_wakeup(secs * 1000000ULL); // Wake up periodically to do scheduled jobs + const esp_err_t error = esp_sleep_enable_timer_wakeup(secs * 1000000ULL); // Wake up periodically to do scheduled jobs + if (diagnostics && error != ESP_OK) setup_error = error; } const uint32_t irqGpio = getIRQGpio(); @@ -166,7 +182,15 @@ public: #endif if (!radio_wakeup && button_gpio < 0) { if (secs > 0) { - esp_light_sleep_start(); + if (diagnostics) mesh::powerdiag::sleepBegin(micros()); + const esp_err_t error = esp_light_sleep_start(); + if (diagnostics) { + mesh::powerdiag::sleepEnd(micros()); + if (setup_error != ESP_OK) mesh::powerdiag::boardError(setup_error, millis()); + if (error != ESP_OK) mesh::powerdiag::boardError(error, millis()); + } + } else if (diagnostics) { + mesh::powerdiag::boardVeto(Reason::NoWake, millis()); } return; } @@ -178,26 +202,37 @@ public: portENTER_CRITICAL(&sleepMux); // Do not sleep over a pending packet or a press that needs polling. - if ((radio_wakeup && gpio_get_level(wakeupPin) == HIGH) - || (button_gpio >= 0 + const bool radio_pending = radio_wakeup && gpio_get_level(wakeupPin) == HIGH; + if (radio_pending || (button_gpio >= 0 && gpio_get_level((gpio_num_t)button_gpio) == USER_BTN_PRESSED)) { portEXIT_CRITICAL(&sleepMux); + if (diagnostics && setup_error != ESP_OK) mesh::powerdiag::boardError(setup_error, millis()); + if (diagnostics) mesh::powerdiag::boardVeto( + radio_pending ? Reason::Mesh : Reason::Button, millis(), + radio_pending ? static_cast(irqGpio) : button_gpio); delay(1); return; } // Configure GPIO wakeup - esp_sleep_enable_gpio_wakeup(); + const esp_err_t gpio_error = esp_sleep_enable_gpio_wakeup(); + if (diagnostics && setup_error == ESP_OK && gpio_error != ESP_OK) setup_error = gpio_error; if (radio_wakeup) { - gpio_wakeup_enable(wakeupPin, GPIO_INTR_HIGH_LEVEL); + const esp_err_t error = gpio_wakeup_enable(wakeupPin, GPIO_INTR_HIGH_LEVEL); + if (diagnostics && setup_error == ESP_OK && error != ESP_OK) setup_error = error; } if (button_gpio >= 0) { - gpio_wakeup_enable((gpio_num_t)button_gpio, + const esp_err_t error = gpio_wakeup_enable((gpio_num_t)button_gpio, USER_BTN_PRESSED == LOW ? GPIO_INTR_LOW_LEVEL : GPIO_INTR_HIGH_LEVEL); + if (diagnostics && setup_error == ESP_OK && error != ESP_OK) setup_error = error; } // MCU enters light sleep - esp_light_sleep_start(); + if (diagnostics) mesh::powerdiag::sleepBegin(micros()); + const esp_err_t sleep_error = esp_light_sleep_start(); + if (diagnostics) { + mesh::powerdiag::sleepEnd(micros()); + } // Avoid ISR flood during wakeup due to HIGH LEVEL interrupt if (radio_wakeup) { @@ -212,6 +247,10 @@ public: // Enable CPU interrupt servicing portEXIT_CRITICAL(&sleepMux); + if (diagnostics) { + if (setup_error != ESP_OK) mesh::powerdiag::boardError(setup_error, millis()); + if (sleep_error != ESP_OK) mesh::powerdiag::boardError(sleep_error, millis()); + } } uint8_t getStartupReason() const override { return startup_reason; } diff --git a/src/helpers/NRF52Board.cpp b/src/helpers/NRF52Board.cpp index ca49d7181..44729c4ed 100644 --- a/src/helpers/NRF52Board.cpp +++ b/src/helpers/NRF52Board.cpp @@ -7,6 +7,7 @@ #include "nrf52/ShutdownLeds.h" #include #include "UserGpioPinPolicy.h" +#include "PowerSavingDiagnostics.h" #include #include "ble_gap.h" @@ -497,7 +498,12 @@ bool NRF52Board::isUsbHostConnected() { } void NRF52Board::sleep(uint32_t secs) { - if (isRadioTestActive()) { delay(1); return; } + const bool diagnostics = mesh::powerdiag::enabled(); + if (isRadioTestActive()) { + if (diagnostics) mesh::powerdiag::boardVeto(mesh::powerdiag::Reason::Board, millis(), 2); + delay(1); + return; + } // Clear FPU interrupt flags to avoid insomnia // see errata 87 for details https://docs.nordicsemi.com/bundle/errata_nRF52840_Rev3/page/ERR/nRF52840/Rev3/latest/anomaly_840_87.html #if (__FPU_USED == 1) @@ -515,16 +521,23 @@ void NRF52Board::sleep(uint32_t secs) { // A single call is required here. If an interrupt arrived since the last // wait, SoftDevice returns immediately so the main loop can service the // flag or BLE queue before sleeping again. - sd_app_evt_wait(); + if (diagnostics) mesh::powerdiag::sleepBegin(micros()); + const uint32_t error = sd_app_evt_wait(); + if (diagnostics) { + mesh::powerdiag::sleepEnd(micros()); + if (error != NRF_SUCCESS) mesh::powerdiag::boardError(static_cast(error), millis()); + } } else { // SoftDevice is disabled. Match the Adafruit core's race-preserving // waitForEvent() sequence: the first WFE sleeps or consumes an already- // pending event, then SEV/WFE reliably clears the event register before // returning. SEV/WFE/WFE can erase the only GPIO edge that arrived between // the caller's predicate and here. + if (diagnostics) mesh::powerdiag::sleepBegin(micros()); __WFE(); __SEV(); __WFE(); + if (diagnostics) mesh::powerdiag::sleepEnd(micros()); } } diff --git a/src/helpers/PowerSavingDiagnostics.h b/src/helpers/PowerSavingDiagnostics.h new file mode 100644 index 000000000..4d40983b6 --- /dev/null +++ b/src/helpers/PowerSavingDiagnostics.h @@ -0,0 +1,291 @@ +#pragma once + +#include +#include +#include +#include + +namespace mesh { +namespace powerdiag { + +// Observe the actual sleep decision, never a second approximation of it. +// All calls belong to the application/CLI task, not an ISR or worker task. +enum class Reason : uint8_t { + PolicyOff, Startup, UsbSession, UsbLogging, UsbRecovery, Wireless, Button, + Morse, DualRadio, Ota, Calibration, RadioWatchdog, Queue, Retry, Scheduled, + Serial, Bridge, BridgeCleanup, BridgeWake, Network, Mesh, Tracker, Board, + NoWake, Count +}; +using Mask = uint32_t; +constexpr size_t ReasonCount = static_cast(Reason::Count); +static_assert(ReasonCount < 32, "Power-saving reasons must fit one mask"); +constexpr Mask mask(Reason reason) { + return static_cast(reason) < ReasonCount + ? Mask(1) << static_cast(reason) : 0; +} +constexpr Mask ValidMask = (Mask(1) << ReasonCount) - 1; +// This identifies a short wait call, not proof that the CPU did not sleep. +constexpr uint32_t ShortReturnMicros = 100; + +inline const char* reasonName(Reason reason) { + static const char* const names[] = { + "policy.off", "startup", "usb.session", "usb.logging", "usb.recovery", + "wireless", "button", "morse", "radio2", "ota", "calibration", + "radio.watchdog", "queue", "retry", "scheduled", "serial", "bridge", + "bridge.cleanup", "bridge.wake", "network", "mesh", "tracker", "board", + "no.wake" + }; + return static_cast(reason) < ReasonCount + ? names[static_cast(reason)] : "unknown"; +} + +struct Snapshot { + uint32_t blocked_ms[ReasonCount] = {}; + uint16_t transitions[ReasonCount] = {}; + Mask current = 0; + Mask seen = 0; + uint32_t union_blocked_ms = 0; + uint32_t eligible_ms = 0; + uint32_t last_ms = 0; + uint32_t decision_at_ms = 0; + uint32_t calls = 0; + uint32_t returns = 0; + uint32_t short_returns = 0; + uint32_t board_vetoes = 0; + uint32_t errors = 0; + uint32_t call_us = 0; + uint32_t max_call_us = 0; + uint32_t last_call_us = 0; + uint32_t call_begin_us = 0; + int32_t detail = 0; + bool enabled = false; + bool observed = false; + bool pending = false; +}; +static_assert(sizeof(Snapshot) <= 256, "Power diagnostics exceeded its RAM budget"); + +inline Snapshot& state() { + static Snapshot value; + return value; +} +inline bool enabled() { return state().enabled; } + +inline void addSaturating(uint32_t& value, uint32_t amount) { + value = amount > UINT32_MAX - value ? UINT32_MAX : value + amount; +} +inline void increment(uint32_t& value) { addSaturating(value, 1); } + +inline void account(Snapshot& value, uint32_t now_ms) { + if (value.enabled && value.observed) { + const uint32_t elapsed = now_ms - value.last_ms; + if (value.current != 0) { + addSaturating(value.union_blocked_ms, elapsed); + for (size_t i = 0; i < ReasonCount; ++i) { + if (value.current & (Mask(1) << i)) + addSaturating(value.blocked_ms[i], elapsed); + } + } else { + addSaturating(value.eligible_ms, elapsed); + } + } + value.last_ms = now_ms; +} + +// A fresh on starts a new observation window. Off freezes it, so reconnecting +// USB to inspect a battery test does not overwrite the recorded blockers. +inline void setEnabled(bool on, uint32_t now_ms) { + Snapshot& value = state(); + if (on == value.enabled) return; + if (on) { + value = Snapshot(); + value.enabled = true; + value.last_ms = now_ms; + } else { + account(value, now_ms); + value.enabled = false; + value.pending = false; + } +} +inline void reset(uint32_t now_ms) { + Snapshot& value = state(); + const bool was_enabled = value.enabled; + value = Snapshot(); + value.enabled = was_enabled; + value.last_ms = now_ms; +} + +inline void decision(Mask reasons, uint32_t now_ms) { + Snapshot& value = state(); + if (!value.enabled) return; + account(value, now_ms); + reasons &= ValidMask; + const Mask started = reasons & ~(value.observed ? value.current : 0); + for (size_t i = 0; i < ReasonCount; ++i) { + if ((started & (Mask(1) << i)) && value.transitions[i] != UINT16_MAX) + ++value.transitions[i]; + } + value.current = reasons; + value.seen |= reasons; + value.decision_at_ms = now_ms; + value.observed = true; +} + +// Instrument the actual SDK/event wait, not an outer board.sleep() which can +// decline the request or yield instead. Durations include ISR/SDK work and are +// explicitly not physical sleep residency or a current measurement. +inline void sleepBegin(uint32_t now_us) { + Snapshot& value = state(); + if (!value.enabled) return; + increment(value.calls); + value.call_begin_us = now_us; + value.pending = true; +} +inline void sleepEnd(uint32_t now_us) { + Snapshot& value = state(); + if (!value.enabled || !value.pending) return; + value.pending = false; + const uint32_t duration = now_us - value.call_begin_us; + increment(value.returns); + if (duration < ShortReturnMicros) increment(value.short_returns); + addSaturating(value.call_us, duration); + value.last_call_us = duration; + if (duration > value.max_call_us) value.max_call_us = duration; +} +inline void boardVeto(Reason reason, uint32_t now_ms, int32_t detail = 0) { + if (!enabled()) return; + increment(state().board_vetoes); + state().pending = false; + state().detail = detail; + decision(state().current | mask(reason), now_ms); +} +inline void boardError(int32_t error, uint32_t now_ms) { + if (!enabled()) return; + increment(state().errors); + state().pending = false; + state().detail = error; + decision(state().current | mask(Reason::Board), now_ms); +} +inline Snapshot snapshot(uint32_t now_ms) { + Snapshot copy = state(); + account(copy, now_ms); + return copy; +} + +inline bool whitespace(char c) { return c == ' ' || c == '\t'; } +inline const char* suffix(const char* command, const char* prefix) { + const size_t length = strlen(prefix); + if (strncmp(command, prefix, length) != 0 + || (command[length] && !whitespace(command[length]))) return nullptr; + const char* tail = command + length; + while (whitespace(*tail)) ++tail; + return tail; +} +inline bool argument(const char* text, const char* expected) { + const size_t length = strlen(expected); + if (strncmp(text, expected, length)) return false; + text += length; + while (whitespace(*text)) ++text; + return *text == 0; +} +inline Reason firstReason(Mask reasons) { + for (size_t i = 0; i < ReasonCount; ++i) + if (reasons & (Mask(1) << i)) return static_cast(i); + return Reason::Count; +} +inline void formatAge(const Snapshot& value, uint32_t now_ms, char (&age)[12]) { + if (value.observed) + snprintf(age, sizeof(age), "%lu", (unsigned long)(now_ms - value.decision_at_ms)); + else strcpy(age, "unknown"); +} + +inline void formatPage(unsigned page, char* reply, size_t capacity, + uint32_t now_ms) { + const Snapshot value = snapshot(now_ms); + if (page == 0) { + char age[12]; + formatAge(value, now_ms, age); + const char* why = value.observed + ? (value.current ? reasonName(firstReason(value.current)) : "eligible") : "unobserved"; + snprintf(reply, capacity, + "> diag=%s age_ms=%s why=%s mask=%06lx seen=%06lx blocked_ms=%lu eligible_ms=%lu", + value.enabled ? "on" : "off", age, why, (unsigned long)value.current, + (unsigned long)value.seen, (unsigned long)value.union_blocked_ms, + (unsigned long)value.eligible_ms); + } else if (page == 1) { + snprintf(reply, capacity, + "> calls=%lu returns=%lu short=%lu veto=%lu errors=%lu pending=%u", + (unsigned long)value.calls, (unsigned long)value.returns, + (unsigned long)value.short_returns, (unsigned long)value.board_vetoes, + (unsigned long)value.errors, (unsigned)value.pending); + } else if (page == 2) { + snprintf(reply, capacity, + "> call_us=%lu max_us=%lu last_us=%lu detail=%ld short_lt_us=%lu; NOT sleep residency", + (unsigned long)value.call_us, (unsigned long)value.max_call_us, + (unsigned long)value.last_call_us, (long)value.detail, + (unsigned long)ShortReturnMicros); + } else { + size_t used = 0; + const int initial = snprintf(reply, capacity, "> transitions/blocked_ms:"); + if (initial < 0 || static_cast(initial) >= capacity) return; + used = static_cast(initial); + for (size_t i = (page - 3) * 4; i < (page - 3) * 4 + 4 && i < ReasonCount; ++i) { + const int count = snprintf(reply + used, capacity - used, " %s=%u/%lu", + reasonName(static_cast(i)), (unsigned)value.transitions[i], + (unsigned long)value.blocked_ms[i]); + if (count < 0 || static_cast(count) >= capacity - used) return; + used += static_cast(count); + } + } +} + +inline bool handleCommand(const char* command, char* reply, size_t capacity, + uint32_t now_ms) { + if (!command || !reply || capacity == 0) return false; + const char* tail = suffix(command, "set powersaving.diag"); + if (tail) { + if (argument(tail, "on") || argument(tail, "off")) { + const bool on = argument(tail, "on"); + setEnabled(on, now_ms); + snprintf(reply, capacity, "OK - power diagnostics %s (RAM only; sleep policy unchanged)", + on ? "on" : "off"); + } else snprintf(reply, capacity, "Error: use set powersaving.diag on|off"); + return true; + } + tail = suffix(command, "clear powersaving.diag"); + if (tail) { + if (!*tail) { + reset(now_ms); + snprintf(reply, capacity, "OK - power diagnostics cleared; sleep policy unchanged"); + } else snprintf(reply, capacity, "Error: use clear powersaving.diag"); + return true; + } + tail = suffix(command, "get powersaving.diag"); + if (!tail) return false; + unsigned page = 0; + if (!*tail || argument(tail, "state")) page = 0; + else if (argument(tail, "calls")) page = 1; + else if (argument(tail, "time")) page = 2; + else if (*tail >= '0' && *tail <= '8' && argument(tail + 1, "")) page = *tail - '0'; + else { + for (size_t i = 0; i < ReasonCount; ++i) { + const Reason reason = static_cast(i); + if (argument(tail, reasonName(reason))) { + const Snapshot value = snapshot(now_ms); + char age[12]; + formatAge(value, now_ms, age); + snprintf(reply, capacity, "> %s active=%u seen=%u transitions=%u blocked_ms=%lu age_ms=%s", + reasonName(reason), (unsigned)((value.current & mask(reason)) != 0), + (unsigned)((value.seen & mask(reason)) != 0), (unsigned)value.transitions[i], + (unsigned long)value.blocked_ms[i], age); + return true; + } + } + snprintf(reply, capacity, "Error: get powersaving.diag [0-8|state|calls|time|reason]; reason pages 3-8"); + return true; + } + formatPage(page, reply, capacity, now_ms); + return true; +} + +} // namespace powerdiag +} // namespace mesh diff --git a/test/fixtures/advert_cache/test.cpp b/test/fixtures/advert_cache/test.cpp index 415401897..727d469a6 100644 --- a/test/fixtures/advert_cache/test.cpp +++ b/test/fixtures/advert_cache/test.cpp @@ -1,6 +1,7 @@ #include "FakeFilesystem.h" #include #include +#include #define FILESYSTEM FakeFilesystem namespace mesh { struct Utils { static void toHex(char* dest, const uint8_t* src, int length) { @@ -85,6 +86,7 @@ public: void onContactCacheFlushed(); bool flushContactsBeforeReboot(); bool hasPendingWork() const; + mesh::powerdiag::Mask pendingWorkReason() const; bool canRecoverUsbLogging() const; bool isDualRadioActive() const{return false;} bool hasOutbound() const{return false;} diff --git a/test/fixtures/espnow_runtime.cpp b/test/fixtures/espnow_runtime.cpp index 31a5d1300..063cd566d 100644 --- a/test/fixtures/espnow_runtime.cpp +++ b/test/fixtures/espnow_runtime.cpp @@ -6,6 +6,7 @@ #include #include #include +#include #include #define MESH_DEBUG_PRINTLN(...) ((void)0) @@ -80,6 +81,8 @@ public: @SERVICE@ } bool bridgesPreventSleep() const { + using mesh::powerdiag::mask; + using mesh::powerdiag::Reason; @PENDING@ return false; } diff --git a/test/fixtures/morse_main_loop.cpp b/test/fixtures/morse_main_loop.cpp index ecb3a1115..b856ab242 100644 --- a/test/fixtures/morse_main_loop.cpp +++ b/test/fixtures/morse_main_loop.cpp @@ -1,4 +1,5 @@ #include +#include #include static unsigned usb_services=0,command_services=0,transport_services=0,delays=0; struct Stream { @@ -52,6 +53,7 @@ struct Mesh { bool millisHasNowPassed(uint32_t) { return true; } bool isTrackerModeEnabled() { return false; } bool hasPendingWork() { return false; } + mesh::powerdiag::Mask pendingWorkReason() const { return 0; } void handleCommand(uint32_t,char*,char* reply) { reply[0]=0; ++command_services; } void handleUsbCommand(char*,char* reply) { reply[0]=0; ++command_services; } } the_mesh; diff --git a/test/fixtures/power_saving_diagnostics.cpp b/test/fixtures/power_saving_diagnostics.cpp new file mode 100644 index 000000000..abe46c5d5 --- /dev/null +++ b/test/fixtures/power_saving_diagnostics.cpp @@ -0,0 +1,177 @@ +#include +#include +#include +#include + +using namespace mesh::powerdiag; +extern void powerDiagnosticsOtherTranslationUnit(); + +static bool command(const char* text, char* out, uint32_t now = 0) { + return handleCommand(text, out, 157, now); +} + +int main(int argc, char** argv) { + assert(argc == 2); + state() = Snapshot(); + const char* test = argv[1]; + if (!strcmp(test, "disabled")) { + assert(!enabled()); + decision(mask(Reason::UsbSession), 10); + sleepBegin(10); sleepEnd(20); + boardVeto(Reason::Board, 20); boardError(-7, 30); + const Snapshot value = snapshot(1000); + assert(!value.observed && !value.current && !value.calls && !value.errors); + assert(!value.board_vetoes && !value.eligible_ms && !value.union_blocked_ms); + } else if (!strcmp(test, "overlap")) { + setEnabled(true, 10); + decision(mask(Reason::UsbSession) | mask(Reason::Bridge), 10); + decision(mask(Reason::Bridge), 40); + decision(mask(Reason::Bridge), 50); + decision(0, 60); + const Snapshot value = snapshot(80); + assert(value.union_blocked_ms == 50 && value.eligible_ms == 20); + assert(value.blocked_ms[(int)Reason::UsbSession] == 30); + assert(value.blocked_ms[(int)Reason::Bridge] == 50); + assert(value.transitions[(int)Reason::UsbSession] == 1); + assert(value.transitions[(int)Reason::Bridge] == 1); + assert(value.seen == (mask(Reason::UsbSession) | mask(Reason::Bridge))); + assert(state().eligible_ms == 0); // Formatting/snapshot does not mutate state. + assert(snapshot(80).eligible_ms == 20); + } else if (!strcmp(test, "freeze")) { + setEnabled(true, 0); + decision(mask(Reason::UsbSession), 0); + decision(mask(Reason::Calibration), 50); + setEnabled(false, 100); + decision(mask(Reason::Bridge), 200); + const Snapshot value = snapshot(1000); + assert(value.union_blocked_ms == 100 && value.eligible_ms == 0); + assert(value.blocked_ms[(int)Reason::UsbSession] == 50); + assert(value.blocked_ms[(int)Reason::Calibration] == 50); + assert(value.current == mask(Reason::Calibration)); + setEnabled(true, 1100); + assert(!state().observed && !state().current && !state().seen); + assert(!state().union_blocked_ms && !state().eligible_ms); + } else if (!strcmp(test, "reset")) { + setEnabled(true, 0); decision(mask(Reason::Serial), 1); + sleepBegin(1); sleepEnd(20); reset(10); + assert(enabled() && !state().observed && !state().calls && !state().seen); + decision(0, 11); assert(snapshot(20).eligible_ms == 9); + setEnabled(false, 20); reset(30); + assert(!enabled() && !state().observed && !state().eligible_ms); + } else if (!strcmp(test, "wrap")) { + setEnabled(true, UINT32_MAX - 9); + decision(mask(Reason::Queue), UINT32_MAX - 9); + decision(0, 10); + assert(state().union_blocked_ms == 20); + sleepBegin(UINT32_MAX - 49); sleepEnd(50); + assert(state().last_call_us == 100 && !state().short_returns); + sleepBegin(50); sleepEnd(149); + assert(state().short_returns == 1 && state().last_call_us == 99); + assert(state().calls == 2 && state().returns == 2 && state().call_us == 199); + } else if (!strcmp(test, "veto_error")) { + setEnabled(true, 0); decision(0, 0); + sleepBegin(1); boardVeto(Reason::BridgeCleanup, 1, 7); sleepEnd(1001); + assert(state().calls == 1 && state().returns == 0 && state().board_vetoes == 1); + assert(state().current == mask(Reason::BridgeCleanup) && state().detail == 7); + decision(0, 2); sleepBegin(2000); boardError(-17, 3); sleepEnd(3000); + assert(state().errors == 1 && state().detail == -17 && state().returns == 0); + assert(state().current == mask(Reason::Board)); + decision(0, 4); sleepBegin(4000); sleepEnd(4000); sleepEnd(5000); + assert(state().returns == 1 && state().short_returns == 1); + assert(state().call_us == 0 && state().board_vetoes == 1); + decision(0, 5); sleepBegin(5000); sleepEnd(5010); boardError(-9, 6); + // A reported API return is not a claim that its result was successful. + assert(state().returns == 2 && state().errors == 2 && state().call_us == 10); + assert(state().detail == -9 && state().current == mask(Reason::Board)); + } else if (!strcmp(test, "saturation")) { + setEnabled(true, 0); decision(mask(Reason::Board), 0); + state().union_blocked_ms = UINT32_MAX - 5; + state().blocked_ms[(int)Reason::Board] = UINT32_MAX - 5; + state().transitions[(int)Reason::Board] = UINT16_MAX; + decision(0, 10); decision(mask(Reason::Board), 11); + assert(state().union_blocked_ms == UINT32_MAX); + assert(state().blocked_ms[(int)Reason::Board] == UINT32_MAX); + assert(state().transitions[(int)Reason::Board] == UINT16_MAX); + state().calls = state().returns = state().short_returns = UINT32_MAX; + state().call_us = UINT32_MAX - 5; + sleepBegin(20); sleepEnd(30); + assert(state().calls == UINT32_MAX && state().returns == UINT32_MAX); + assert(state().short_returns == UINT32_MAX && state().call_us == UINT32_MAX); + } else if (!strcmp(test, "commands")) { + char out[157]; + assert(command("set powersaving.diag on", out, 1) && enabled()); + assert(strstr(out, "RAM only") && strstr(out, "unchanged")); + decision(mask(Reason::Calibration), 2); + assert(command("set powersaving.diag on", out, 3)); + assert(state().seen == mask(Reason::Calibration)); // Repeated on is not a clear. + assert(command("get powersaving.diag calibration", out, 5)); + assert(strstr(out, "active=1") && strstr(out, "blocked_ms=3")); + assert(command("get powersaving.diag\t calls \t", out, 5)); + assert(strstr(out, "calls=0")); + assert(command("set powersaving.diag off \t", out, 5) && !enabled()); + assert(command("clear powersaving.diag", out, 6) && !enabled()); + assert(!state().observed && !state().seen); + } else if (!strcmp(test, "strict")) { + char out[157] = "untouched"; + assert(!command("get powersaving.diagfoo", out)); + assert(!command("set powersaving.diagon", out)); + assert(!command("get powersaving", out)); + assert(!strcmp(out, "untouched")); + for (const char* text : {"set powersaving.diag", "set powersaving.diag on junk", + "set powersaving.diag 1", "clear powersaving.diag all", + "get powersaving.diag 9", "get powersaving.diag 01", + "get powersaving.diag 1junk", "get powersaving.diag state junk"}) { + assert(command(text, out)); assert(strstr(out, "Error:")); + assert(!enabled() && !state().observed && !state().calls); + } + } else if (!strcmp(test, "format")) { + char out[157]; + assert(command("get powersaving.diag", out, 100)); + assert(strstr(out, "age_ms=unknown") && strstr(out, "why=unobserved")); + assert(command("get powersaving.diag usb.session", out, 100)); + assert(strstr(out, "age_ms=unknown")); + setEnabled(true, 100); decision(mask(Reason::UsbSession), 100); + assert(command("get powersaving.diag state", out, 10000)); + assert(strstr(out, "age_ms=9900") && strstr(out, "why=usb.session")); + assert(state().decision_at_ms == 100 && state().last_ms == 100); + assert(command("get powersaving.diag time", out, 10000)); + assert(strstr(out, "NOT sleep residency")); + assert(command("get powersaving.diag 3", out, 10000)); + assert(strstr(out, "usb.session=1/9900")); + } else if (!strcmp(test, "capacity")) { + setEnabled(true, 0); decision(ValidMask, 0); + state().union_blocked_ms = state().eligible_ms = UINT32_MAX; + state().calls = state().returns = state().short_returns = UINT32_MAX; + state().board_vetoes = state().errors = UINT32_MAX; + state().call_us = state().max_call_us = state().last_call_us = UINT32_MAX; + state().detail = INT32_MIN; + for (size_t i = 0; i < ReasonCount; ++i) { + state().blocked_ms[i] = UINT32_MAX; state().transitions[i] = UINT16_MAX; + } + for (unsigned page = 0; page <= 8; ++page) { + char large[512], bounded[157]; + formatPage(page, large, sizeof(large), UINT32_MAX); + formatPage(page, bounded, sizeof(bounded), UINT32_MAX); + assert(strlen(large) < sizeof(bounded)); assert(!strcmp(large, bounded)); + } + for (size_t capacity = 1; capacity < 160; ++capacity) { + char guarded[162]; memset(guarded, '!', sizeof(guarded)); + assert(handleCommand("get powersaving.diag time", guarded + 1, capacity, 0)); + assert(guarded[0] == '!' && guarded[capacity + 1] == '!'); + assert(memchr(guarded + 1, 0, capacity)); + } + char untouched = '!'; + assert(!handleCommand("get powersaving.diag", &untouched, 0, 0)); + assert(untouched == '!'); + assert(!handleCommand(nullptr, &untouched, 1, 0)); + assert(!handleCommand("get powersaving.diag", nullptr, 1, 0)); + } else if (!strcmp(test, "shared")) { + setEnabled(true, 0); powerDiagnosticsOtherTranslationUnit(); + assert(state().current == mask(Reason::UsbRecovery)); + assert(state().transitions[(int)Reason::UsbRecovery] == 1); + } else if (!strcmp(test, "unknown_mask")) { + setEnabled(true, 0); decision(UINT32_MAX, 0); + assert(state().current == ValidMask && state().seen == ValidMask); + assert(mask(Reason::Count) == 0 && !strcmp(reasonName(Reason::Count), "unknown")); + } else assert(false); +} diff --git a/test/fixtures/power_saving_diagnostics_other.cpp b/test/fixtures/power_saving_diagnostics_other.cpp new file mode 100644 index 000000000..c139f31f3 --- /dev/null +++ b/test/fixtures/power_saving_diagnostics_other.cpp @@ -0,0 +1,5 @@ +#include + +void powerDiagnosticsOtherTranslationUnit() { + mesh::powerdiag::decision(mesh::powerdiag::mask(mesh::powerdiag::Reason::UsbRecovery), 1); +} diff --git a/test/fixtures/rs232_mqtt_runtime.cpp b/test/fixtures/rs232_mqtt_runtime.cpp index 5f495cddb..47f6e3fd6 100644 --- a/test/fixtures/rs232_mqtt_runtime.cpp +++ b/test/fixtures/rs232_mqtt_runtime.cpp @@ -6,6 +6,7 @@ #include #include #include +#include #include #include struct FakeRng { void random(uint8_t* out, size_t size) { memset(out, 0x42, size); } }; @@ -247,6 +248,8 @@ public: @SERVICE@ } bool bridgesPreventSleep() const { + using mesh::powerdiag::mask; + using mesh::powerdiag::Reason; @PENDING@ return false; } diff --git a/test/fixtures/rs232_runtime/main.cpp b/test/fixtures/rs232_runtime/main.cpp index 7f66c460c..60c069a15 100644 --- a/test/fixtures/rs232_runtime/main.cpp +++ b/test/fixtures/rs232_runtime/main.cpp @@ -4,6 +4,7 @@ #include #include #include +#include #include #include @@ -172,6 +173,8 @@ public: @SERVICE@ } bool bridgesPreventSleep() const { + using mesh::powerdiag::mask; + using mesh::powerdiag::Reason; @PENDING@ return false; } diff --git a/test/fixtures/sensor_tracker_radio_lease.cpp b/test/fixtures/sensor_tracker_radio_lease.cpp index a5f1093e4..ead9aee54 100644 --- a/test/fixtures/sensor_tracker_radio_lease.cpp +++ b/test/fixtures/sensor_tracker_radio_lease.cpp @@ -4,6 +4,7 @@ #include #include #include +#include #include #include #include @@ -143,6 +144,7 @@ public: bool isMillisTimerDue(unsigned long) const; uint32_t limitSleepToMillisTimer(unsigned long, uint32_t) const; bool hasPendingWork() const; + mesh::powerdiag::Mask pendingWorkReason() const; uint32_t getPowerSaveSleepSeconds(uint32_t) const; void loopBeforeService(); void sleepIfIdle() { @SLEEP_BLOCK@ } diff --git a/test/test_companion_contact_sleep_contract.py b/test/test_companion_contact_sleep_contract.py index 5d311800a..6671692cd 100644 --- a/test/test_companion_contact_sleep_contract.py +++ b/test/test_companion_contact_sleep_contract.py @@ -35,7 +35,7 @@ class CompanionContactSleepContractTest(unittest.TestCase): loop.index("BaseChatMesh::loop()")) self.assertIn("contactRecoveryPending() && !mesh::morseTimingActive(_radio)", loop) self.assertIn("|| _store->contactRecoveryPending()", - function_body(mesh, "bool MyMesh::hasPendingWork() const")) + function_body(mesh, "mesh::powerdiag::Mask MyMesh::pendingWorkReason() const")) reset = function_body(mesh, "bool MyMesh::resetContactsForRecovery()") self.assertNotIn("stopContactsIterator()", reset) self.assertLess(reset.index("_iter_pending_contact = ContactInfo()"), @@ -156,7 +156,7 @@ int main() { def test_initial_write_polls_but_failed_backoff_can_sleep(self): mesh = (ROOT / "examples/companion_radio/MyMesh.cpp").read_text() - body = function_body(mesh, "bool MyMesh::hasPendingWork() const") + body = function_body(mesh, "mesh::powerdiag::Mask MyMesh::pendingWorkReason() const") nrf_start = body.index("#if defined(NRF52_PLATFORM)") other_start = body.index("#else", nrf_start) @@ -175,7 +175,7 @@ int main() { other, r"contact_write_needs_polling\s*=\s*isContactWriteDue\s*\(\s*\)", ) - self.assertRegex(body, r"\|\|\s*contact_write_needs_polling") + self.assertRegex(body, r"if\s*\(\s*contact_write_needs_polling\s*\|\|") def test_contact_write_is_serviced_only_after_its_deadline(self): mesh = (ROOT / "examples/companion_radio/MyMesh.cpp").read_text() @@ -242,11 +242,13 @@ int main() { def test_main_loop_gates_sleep_on_pending_work(self): main = (ROOT / "examples/companion_radio/main.cpp").read_text() - sleep_start = main.index("bool can_sleep =") + sleep_start = main.index(" using mesh::powerdiag::Reason;") sleep_end = main.index("if (can_sleep)", sleep_start) sleep_gate = main[sleep_start:sleep_end] - self.assertIn("!the_mesh.hasPendingWork()", sleep_gate) + self.assertIn("the_mesh.pendingWorkReason()", sleep_gate) + self.assertIn("if (pending) return pending;", sleep_gate) + self.assertIn("const bool can_sleep = sleep_reason == 0;", sleep_gate) nrf52 = (ROOT / "src/helpers/NRF52Board.cpp").read_text() body = function_body(nrf52, "void NRF52Board::sleep(uint32_t secs)") @@ -255,15 +257,20 @@ int main() { def test_polled_rak_ethernet_holds_event_sleep_through_pending_off(self): main = (ROOT / "examples/companion_radio/main.cpp").read_text() - start = main.index("bool can_sleep =") + start = main.index(" using mesh::powerdiag::Reason;") gate = main[start:main.index("if (can_sleep)", start)] fixture = r''' #include +#include +uint32_t millis() { return 0; } struct Prefs { bool powersaving_enabled; }; struct Mesh { Prefs prefs; bool pending; Prefs* getNodePrefs() { return &prefs; } bool hasPendingWork() const { return pending; } + mesh::powerdiag::Mask pendingWorkReason() const { + return pending ? mesh::powerdiag::mask(mesh::powerdiag::Reason::Mesh) : 0; + } } the_mesh; struct Board { bool usb; bool isUsbHostConnected() const { return usb; } } board; struct Ethernet { bool active; bool hardwareActive() const { return active; } } ethernet_interface; @@ -300,6 +307,7 @@ int main() { subprocess.run([os.environ.get('CXX', 'g++'), '-std=c++17', '-Wall', '-Wextra', '-Werror', '-DNRF52_PLATFORM=1', *(['-DETHERNET_USE_RAK13800=1'] if ethernet else []), + '-I', str(ROOT / 'src'), str(source), '-o', str(binary)], check=True, timeout=30) subprocess.run([str(binary)], check=True, timeout=5) @@ -333,7 +341,7 @@ int main() { shutdown = function_body(mesh, "bool MyMesh::prepareForUiShutdown()") self.assertIn("_store->contactsAreVolatile() || flushContactsBeforeReboot()", shutdown) - pending = function_body(mesh, "bool MyMesh::hasPendingWork() const") + pending = function_body(mesh, "mesh::powerdiag::Mask MyMesh::pendingWorkReason() const") self.assertIn("|| _scheduled_reboot_at != 0", pending) def test_ota_apply_reboot_uses_companion_persistence_hook(self): @@ -427,9 +435,9 @@ int main() { for role_source in role_sources: role = role_source.read_text() signature = ( - "bool SensorMesh::hasPendingWork() const" + "mesh::powerdiag::Mask SensorMesh::pendingWorkReason() const" if role_source.name == "SensorMesh.cpp" - else "bool MyMesh::hasPendingWork() const" + else "mesh::powerdiag::Mask MyMesh::pendingWorkReason() const" ) has_pending_work = function_body(role, signature) self.assertIn("hasPendingOtaApply()", has_pending_work, role_source) diff --git a/test/test_companion_power_diagnostics.py b/test/test_companion_power_diagnostics.py new file mode 100644 index 000000000..7fc6fa47e --- /dev/null +++ b/test/test_companion_power_diagnostics.py @@ -0,0 +1,93 @@ +#!/usr/bin/env python3 +"""Exercise the real Companion manual sleep path with diagnostics on and off.""" + +import os +from pathlib import Path +import subprocess +import tempfile +import unittest + +ROOT = Path(__file__).resolve().parents[1] + + +class CompanionPowerDiagnosticsTests(unittest.TestCase): + def test_native_usb_wait_counts_only_the_sdk_call_and_preserves_fallback(self): + source = (ROOT / "examples/companion_radio/main.cpp").read_text(encoding="ascii") + start = source.index(" bool sleep_failed = false;") + block = source[start:source.index("#elif COMPANION_IDF_PM_AVAILABLE", start)] + code = r''' +#include +#include +#include +using mesh::powerdiag::Reason; +using esp_err_t = int; +constexpr int ESP_OK = 0; +static uint32_t clock_us = 100000; +static uint32_t millis() { return clock_us / 1000; } +static uint32_t micros() { return clock_us; } +static bool ready = true; +static int timer_error = 0, sleep_error = 0; +static unsigned ready_calls = 0, timer_calls = 0, wait_calls = 0, delay_calls = 0; +static bool companionNativeUsbLightSleepReady() { ++ready_calls; return ready; } +static int esp_sleep_enable_timer_wakeup(uint64_t us) { + assert(us == 10000); ++timer_calls; return timer_error; +} +static int esp_light_sleep_start() { ++wait_calls; clock_us += 500; return sleep_error; } +static unsigned pdMS_TO_TICKS(unsigned ms) { return ms; } +static void vTaskDelay(unsigned ms) { assert(ms == 10); ++delay_calls; clock_us += 10000; } +static void attempt() { +@BLOCK@ +} +int main() { + using namespace mesh::powerdiag; + for (bool diagnostics : {false, true}) { + for (unsigned mode = 0; mode != 4; ++mode) { + clock_us = 100000; + setEnabled(diagnostics, millis()); reset(millis()); + decision(0, millis()); + ready = mode != 1; timer_error = mode == 2 ? -2 : 0; sleep_error = mode == 3 ? -3 : 0; + ready_calls = timer_calls = wait_calls = delay_calls = 0; + attempt(); + assert(ready_calls == 1); + assert(timer_calls == (mode != 1)); + assert(wait_calls == (mode == 0 || mode == 3)); + assert(delay_calls == (mode != 0)); + const auto value = snapshot(millis()); + if (!diagnostics) { + assert(value.calls == 0 && value.errors == 0 && !value.observed); + } else { + assert(value.calls == wait_calls && value.returns == wait_calls); + assert(value.call_us == wait_calls * 500); // Never include fallback delay. + assert(value.board_vetoes == (mode == 1)); + assert(value.errors == (mode == 2 || mode == 3)); + assert(value.current == (mode ? mask(Reason::Board) : 0)); + if (mode >= 2) assert(value.detail == -static_cast(mode)); + } + } + } +} +'''.replace("@BLOCK@", block) + with tempfile.TemporaryDirectory(prefix="meshcore-companion-power-") as directory: + cpp = Path(directory) / "test.cpp" + binary = Path(directory) / "test" + cpp.write_text(code, encoding="ascii") + built = subprocess.run([ + os.environ.get("CXX", "c++"), "-std=c++17", "-Wall", "-Wextra", "-Werror", + "-fsanitize=address,undefined", "-fno-sanitize-recover=all", "-fno-pie", "-no-pie", + "-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) + result = subprocess.run([str(binary)], capture_output=True, text=True, timeout=20) + self.assertEqual(result.returncode, 0, result.stdout + result.stderr) + + def test_companion_routes_bounded_diagnostics_before_saved_settings(self): + source = (ROOT / "examples/companion_radio/MyMesh.cpp").read_text(encoding="ascii") + start = source.index("bool MyMesh::handleLocalControlCommand(") + body = source[start:source.index('if (strcmp(command, "get powersaving")', start)] + self.assertIn("mesh::powerdiag::handleCommand(command, reply, reply_size, millis())", body) + self.assertNotIn("savePrefs()", body[:body.index("mesh::powerdiag::handleCommand")]) + self.assertIn("return pendingWorkReason() != 0;", source) + + +if __name__ == "__main__": + unittest.main() diff --git a/test/test_companion_radio_settings_transaction.py b/test/test_companion_radio_settings_transaction.py index d3b8608d5..f27b411ab 100644 --- a/test/test_companion_radio_settings_transaction.py +++ b/test/test_companion_radio_settings_transaction.py @@ -234,6 +234,7 @@ SLEEP_HARNESS = r''' #include #include #include +#include static uint32_t now_ms=100; struct Serial { bool hasPendingIO() const { return false; } @@ -274,6 +275,7 @@ struct MyMesh { bool hasQueuedWorkDue() const { return false; } bool hasRetryWorkDue() const { return false; } bool hasPendingWork() const; + mesh::powerdiag::Mask pendingWorkReason() const; }; @PENDING_WORK@ int main() { @@ -326,7 +328,9 @@ int main() { class CompanionRadioSettingsTransactionTests(unittest.TestCase): def test_lease_blocked_recovery_does_not_prevent_sleep(self): text = SOURCE.read_text(encoding='utf-8') - pending = extract_braced(text, 'bool MyMesh::hasPendingWork() const') + pending = '\n'.join(extract_braced(text, signature) for signature in ( + 'bool MyMesh::hasPendingWork() const', + 'mesh::powerdiag::Mask MyMesh::pendingWorkReason() const')) harness = SLEEP_HARNESS.replace('@PENDING_WORK@', pending) header = (SOURCE.parent / 'DataStore.h').read_text(encoding='utf-8') start = header.index(' enum : uint8_t { ContactRecoveryPending') diff --git a/test/test_esp32_advert_cache.py b/test/test_esp32_advert_cache.py index 534897fbc..115b6e4a8 100644 --- a/test/test_esp32_advert_cache.py +++ b/test/test_esp32_advert_cache.py @@ -134,7 +134,9 @@ class AdvertCacheTest(unittest.TestCase): scheduling = method(mesh_source, 'void MyMesh::servicePersistence()') flush = method(mesh_source, 'bool MyMesh::flushContactsBeforeReboot()') flushed = method(mesh_source, 'void MyMesh::onContactCacheFlushed()') - work = method(mesh_source, 'bool MyMesh::hasPendingWork() const') + work = '\n'.join(method(mesh_source, signature) for signature in ( + 'bool MyMesh::hasPendingWork() const', + 'mesh::powerdiag::Mask MyMesh::pendingWorkReason() const')) recovery = method(mesh_source, 'bool MyMesh::canRecoverUsbLogging() const') # The entire production scheduling body runs below. This order check # additionally pins its call site after either serial dispatch route. diff --git a/test/test_esp32_full_power_lifecycle.py b/test/test_esp32_full_power_lifecycle.py index ec68d5628..9567a308b 100644 --- a/test/test_esp32_full_power_lifecycle.py +++ b/test/test_esp32_full_power_lifecycle.py @@ -25,6 +25,7 @@ FIXTURE = r''' #include #include #include +#include #include #include uint32_t now = 0; @@ -239,6 +240,7 @@ struct MyMesh { bool startWebConfigImpl(bool force_ap, char* reply, bool automatic_setup); bool startWebConfig(bool force_ap, char* reply); bool stopWebConfig(char* reply); bool hasPendingWork() const; uint32_t getPowerSaveSleepSeconds(uint32_t) const; + mesh::powerdiag::Mask pendingWorkReason() const; @INLINE_METHODS@ void defaults() { @DEFAULTS@ } void startupSetup() { @STARTUP@ } @@ -387,7 +389,8 @@ class ESP32FullPowerLifecycleTest(unittest.TestCase): "void MyMesh::suspendUnconfiguredSetupBridges()", "void MyMesh::serviceIdleWiFi()", "bool MyMesh::startWebConfig(", "bool MyMesh::startWebConfigImpl(", "bool MyMesh::stopWebConfig(", - "bool MyMesh::hasPendingWork() const", "uint32_t MyMesh::getPowerSaveSleepSeconds(")) + "bool MyMesh::hasPendingWork() const", "mesh::powerdiag::Mask MyMesh::pendingWorkReason() const", + "uint32_t MyMesh::getPowerSaveSleepSeconds(")) defaults_start = source.index(" // bridge defaults") defaults = source[defaults_start:source.index(" _prefs.bridge_delay", defaults_start)] startup = source[source.index(" bool start_webui = WebConfigServer::loadEnabled(false);"):] diff --git a/test/test_esp32_full_sleep.py b/test/test_esp32_full_sleep.py index 23ca06f5b..0a59dfdaa 100644 --- a/test/test_esp32_full_sleep.py +++ b/test/test_esp32_full_sleep.py @@ -99,10 +99,12 @@ int main() { #include #include #include +#include #include #include static uint32_t now = 1000; uint32_t millis() { return now; } +uint32_t micros() { return now * 1000U; } using esp_err_t = int; enum wifi_mode_t { WIFI_MODE_NULL, WIFI_MODE_STA, WIFI_MODE_AP, WIFI_MODE_APSTA }; constexpr int ESP_OK = 0, ESP_ERR_WIFI_NOT_INIT = 1, ESP_ERR_WIFI_NOT_STARTED = 2; @@ -139,6 +141,9 @@ struct Mesh { bool pending = false, dual = false; Prefs* getNodePrefs() { return &prefs; } bool hasPendingWork() const { return pending; } + mesh::powerdiag::Mask pendingWorkReason() const { + return pending ? mesh::powerdiag::mask(mesh::powerdiag::Reason::Mesh) : 0; + } bool isDualRadioActive() const { return dual; } mesh::Radio* getProfileRadio() { return &timing_radio; } } the_mesh; diff --git a/test/test_esp32_usb_sleep.py b/test/test_esp32_usb_sleep.py index 16258e86e..f037c6aa5 100644 --- a/test/test_esp32_usb_sleep.py +++ b/test/test_esp32_usb_sleep.py @@ -20,12 +20,16 @@ HARNESS = r''' #include #include #include +#include #ifndef MESH_ESP32_USB_HOST_LOSS_SLEEP_GRACE_MS #define MESH_ESP32_USB_HOST_LOSS_SLEEP_GRACE_MS 120000UL #endif static uint32_t mock_millis = 1000; static uint32_t millis() { return mock_millis; } +static uint32_t micros() { return mock_millis * 1000U; } +using esp_err_t = int; +constexpr int ESP_OK = 0; static void require(bool ok, const char* message) { if (!ok) throw std::runtime_error(message); @@ -76,8 +80,8 @@ static bool button_pressed = false; static bool press_during_sleep = false; static unsigned yield_ms = 0; static void delay(unsigned ms) { yield_ms += ms; } -static void esp_sleep_enable_timer_wakeup(uint64_t us) { timer_us = us; } -static void esp_light_sleep_start() { +static int esp_sleep_enable_timer_wakeup(uint64_t us) { timer_us = us; return ESP_OK; } +static int esp_light_sleep_start() { ++sleep_calls; if (press_during_sleep) { require(wake_levels[38] == GPIO_INTR_LOW_LEVEL, @@ -87,14 +91,16 @@ static void esp_light_sleep_start() { button_pressed = true; press_during_sleep = false; } + return ESP_OK; } -static void esp_sleep_enable_gpio_wakeup() {} +static int esp_sleep_enable_gpio_wakeup() { return ESP_OK; } static int gpio_get_level(gpio_num_t pin) { return pin == 38 ? (button_pressed ? LOW : HIGH) : (radio_irq_high ? HIGH : LOW); } -static void gpio_wakeup_enable(gpio_num_t pin, int level) { +static int gpio_wakeup_enable(gpio_num_t pin, int level) { wake_pin = pin; wake_levels.at(pin) = level; + return ESP_OK; } static void gpio_wakeup_disable(gpio_num_t pin) { restored_pin = pin; @@ -307,12 +313,16 @@ def conditional_block(source, start): V4_BUTTON_HARNESS = r''' #include #include +#include #include #include #include #include #include #include +using esp_err_t = int; +constexpr int ESP_OK = 0; +static uint32_t micros() { return millis() * 1000U; } static void require(bool ok, const char* why) { if (!ok) throw std::runtime_error(why); } @@ -336,15 +346,15 @@ static std::array wake_levels{}, restored_interrupts{}; static unsigned sleep_calls = 0; static int critical_depth = 0; static bool press_during_sleep = false, radio_irq_high = false; -static void esp_sleep_enable_timer_wakeup(uint64_t) {} -static void esp_sleep_enable_gpio_wakeup() {} +static int esp_sleep_enable_timer_wakeup(uint64_t) { return ESP_OK; } +static int esp_sleep_enable_gpio_wakeup() { return ESP_OK; } static int gpio_get_level(gpio_num_t pin) { return pin == PIN_USER_BTN ? digitalRead(pin) : (radio_irq_high ? HIGH : LOW); } -static void gpio_wakeup_enable(gpio_num_t pin, int level) { wake_levels.at(pin) = level; } +static int gpio_wakeup_enable(gpio_num_t pin, int level) { wake_levels.at(pin) = level; return ESP_OK; } static void gpio_wakeup_disable(gpio_num_t pin) { wake_levels.at(pin) = 0; } static void gpio_set_intr_type(gpio_num_t pin, int type) { restored_interrupts.at(pin) = type; } -static void esp_light_sleep_start() { +static int esp_light_sleep_start() { ++sleep_calls; if (press_during_sleep) { require(wake_levels[PIN_USER_BTN] == GPIO_INTR_LOW_LEVEL, @@ -354,6 +364,7 @@ static void esp_light_sleep_start() { g_mock_pin_levels[PIN_USER_BTN] = LOW; press_during_sleep = false; } + return ESP_OK; } #define portENTER_CRITICAL(mux) (++critical_depth) #define portEXIT_CRITICAL(mux) (--critical_depth) @@ -403,6 +414,7 @@ struct UITask { } } ui; static bool roleCanPowerSave() { + const auto sleep_guard = [](bool allowed, mesh::powerdiag::Reason) { return allowed; }; bool can_power_save = true; @ROLE_SLEEP_GUARD@ return can_power_save; @@ -539,7 +551,7 @@ class Esp32UsbSleepTest(unittest.TestCase): cases.append(("missing-flag", harness, missing, "V4 slept over an already pressed button")) cases.append(("missing-poller", harness.replace( - "can_power_save = can_power_save && !user_btn.needsPolling();", + "can_power_save = can_power_save && sleep_guard(!user_btn.needsPolling(), mesh::powerdiag::Reason::Button);", ""), defines, "role slept before button debounce completed")) cases.append(("missing-display-wake", harness.replace( "_display->wake(mesh::ui::DisplayWake::Button);", @@ -784,7 +796,12 @@ int main() { main = (ROOT / f"examples/{role}/main.cpp").read_text() guard = main.split("#if defined(MOMENTARY_BUTTON_WAKE_FROM_SLEEP)", 1)[1] guard = guard.split("#endif", 1)[0] - self.assertIn("!user_btn.needsPolling()", guard) + if role == "companion_radio": + self.assertIn("if (!sleep_reason && user_btn.needsPolling())", guard) + self.assertIn("sleep_reason = mask(Reason::Button);", guard) + self.assertIn("const bool can_sleep = sleep_reason == 0;", main) + else: + self.assertIn("sleep_guard(!user_btn.needsPolling(), mesh::powerdiag::Reason::Button)", guard) def test_button_holds_awake_for_two_minutes_and_renews_across_rollover(self): harness = r''' diff --git a/test/test_espnow_runtime.py b/test/test_espnow_runtime.py index 09902e78e..2b88174db 100644 --- a/test/test_espnow_runtime.py +++ b/test/test_espnow_runtime.py @@ -41,7 +41,7 @@ class ESPNowRuntimeTests(unittest.TestCase): implementation.index("MyMesh::servicePostMeshLoop()")) service_end = implementation.index(" if (next_flood_advert", service_start) pending_start = implementation.index("#if defined(WITH_BRIDGE)", - implementation.index("bool MyMesh::hasPendingWork()")) + implementation.index("mesh::powerdiag::Mask MyMesh::pendingWorkReason()")) pending_end = implementation.index(" if (radio_driver.isWatchdogObserving()", pending_start) commands = "\n".join(extract_braced(cli, signature) for signature in ( "void CommonCLI::handleSetCmd(", "void CommonCLI::handleGetCmd(")) diff --git a/test/test_logging_sleep_contract.py b/test/test_logging_sleep_contract.py index f03daa0c4..fba835db6 100644 --- a/test/test_logging_sleep_contract.py +++ b/test/test_logging_sleep_contract.py @@ -27,6 +27,8 @@ HARNESS = r''' #include #include #include +#include +uint32_t millis() { return 0; } #define WITH_BRIDGE 1 struct AbstractBridge { virtual bool isRunning() const = 0; }; struct MQTTBridge : AbstractBridge { @@ -64,6 +66,7 @@ struct MyMesh { uint32_t limitSleepToMillisTimer(unsigned long, uint32_t secs) const { return secs; } uint32_t limitSleepToScheduledRadioWork(uint32_t secs) const { return secs; } bool hasPendingWork() const; + mesh::powerdiag::Mask pendingWorkReason() const; uint32_t getPowerSaveSleepSeconds(uint32_t) const; }; @METHODS@ @@ -146,6 +149,7 @@ class LoggingSleepContractTest(unittest.TestCase): source = f"examples/{role}/MyMesh.cpp" methods = "\n".join(method(source, signature) for signature in ( "bool MyMesh::hasPendingWork() const", + "mesh::powerdiag::Mask MyMesh::pendingWorkReason() const", "uint32_t MyMesh::getPowerSaveSleepSeconds(uint32_t max_secs) const", )) cpp = Path(temp) / f"{role}.cpp" diff --git a/test/test_official_web_console.py b/test/test_official_web_console.py index 44974fc20..1f6e2a922 100644 --- a/test/test_official_web_console.py +++ b/test/test_official_web_console.py @@ -60,7 +60,7 @@ def firmware_harness(*, lose_sleep_guard=False, lose_crlf=False, "void sleep(uint32_t secs) override", "bool isUsbDataConnected() override", "bool isUsbHostConnected() override")) + "\n" + sleep_held if lose_raw_uart_guard: - expression = "keep_awake = keep_awake || static_cast(Serial);" + expression = "keep_awake = keep_awake || hold(static_cast(Serial), Reason::Serial);" assert expression in methods, "Missing raw UART negative-control boundary" methods = methods.replace(expression, "keep_awake = keep_awake || false;") source = source.replace("@METHODS@", methods) @@ -73,7 +73,7 @@ def firmware_harness(*, lose_sleep_guard=False, lose_crlf=False, if lose_crlf: pump = pump.replace('console.printf(" -> %s\\r\\n", reply);', 'console.printf(" -> %s\\n", reply);') - start = main.index(" bool can_power_save =") + start = main.index(" const auto sleep_guard =") end = main.index(" if (the_mesh.getNodePrefs()->reboot_interval", start) morse_declaration = " const bool morse_timing = mesh::morseTimingActive(&radio_driver);" assert morse_declaration in main[:start], "Missing live Morse ownership snapshot" diff --git a/test/test_power_saving_deadlines.py b/test/test_power_saving_deadlines.py index 2884378b7..85716f8d3 100644 --- a/test/test_power_saving_deadlines.py +++ b/test/test_power_saving_deadlines.py @@ -14,6 +14,7 @@ HARNESS = r''' #include #include #include +#include #define SENSOR_READ_INTERVAL_SECS 60 static uint32_t now_ms = 1000; uint32_t millis() { return now_ms; } @@ -33,6 +34,9 @@ struct Node { struct Clock { uint32_t getCurrentTime() const { return 100; } } clock; const Clock* getRTCClock() const { return &clock; } bool hasPendingWork() const { return pending; } + mesh::powerdiag::Mask pendingWorkReason() const { + return pending ? mesh::powerdiag::mask(mesh::powerdiag::Reason::Mesh) : 0; + } bool getNextQueueWakeDelay(uint32_t& out) const { out = queue_ms; return queue; } bool getNextRetryWakeDelay(uint32_t& out) const { out = retry_ms; return retry; } bool millisHasNowPassed(unsigned long at) const { diff --git a/test/test_power_saving_diagnostics.py b/test/test_power_saving_diagnostics.py new file mode 100644 index 000000000..631813c20 --- /dev/null +++ b/test/test_power_saving_diagnostics.py @@ -0,0 +1,86 @@ +#!/usr/bin/env python3 +"""Execute the real heap-free diagnostics collector and bounded CLI formatter.""" + +from pathlib import Path +import os +import shlex +import subprocess +import tempfile +import unittest + +ROOT = Path(__file__).resolve().parents[1] + + +class PowerSavingDiagnosticsTests(unittest.TestCase): + @classmethod + def setUpClass(cls): + cls.temp = tempfile.TemporaryDirectory(prefix="meshcore-power-diag-test-") + cls.addClassCleanup(cls.temp.cleanup) + cls.binary = Path(cls.temp.name) / "diagnostics" + result = subprocess.run( + shlex.split(os.environ.get("CXX", "g++")) + + ["-std=c++11", "-Wall", "-Wextra", "-Werror", "-pedantic", + "-I", str(ROOT / "src"), + str(ROOT / "test/fixtures/power_saving_diagnostics.cpp"), + str(ROOT / "test/fixtures/power_saving_diagnostics_other.cpp"), + "-o", str(cls.binary)], + capture_output=True, text=True, + ) + if result.returncode: + raise RuntimeError(result.stderr) + + 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_disabled_has_no_statistics_or_policy_side_effects(self): + self.run_case("disabled") + + def test_overlapping_reasons_count_union_once(self): + self.run_case("overlap") + + def test_off_freezes_and_next_on_starts_fresh(self): + self.run_case("freeze") + + def test_clear_preserves_mode_but_clears_diagnostics(self): + self.run_case("reset") + + def test_millis_and_micros_wrap_and_short_return_boundary(self): + self.run_case("wrap") + + def test_veto_cancellation_and_sdk_returns_are_distinct_from_success(self): + self.run_case("veto_error") + + def test_elapsed_counters_and_transition_counts_saturate(self): + self.run_case("saturation") + + def test_cli_commands_and_reason_queries(self): + self.run_case("commands") + + def test_invalid_commands_do_not_change_collector(self): + self.run_case("strict") + + def test_stale_snapshot_age_and_no_residency_claim(self): + self.run_case("format") + + def test_all_pages_fit_prefixed_160_byte_protocol_and_tiny_buffers(self): + self.run_case("capacity") + + def test_header_state_is_shared_across_translation_units(self): + self.run_case("shared") + + def test_unknown_mask_bits_are_not_exposed_as_real_reasons(self): + self.run_case("unknown_mask") + + def test_common_cli_routes_without_persisting_preferences(self): + source = (ROOT / "src/helpers/CommonCLI.cpp").read_text(encoding="ascii") + self.assertIn('#include "PowerSavingDiagnostics.h"', source) + self.assertEqual(source.count( + "if (mesh::powerdiag::handleCommand(command, reply, 157, millis())) return;"), 1) + handler = (ROOT / "src/helpers/PowerSavingDiagnostics.h").read_text(encoding="ascii") + self.assertNotIn("savePrefs", handler) + self.assertNotIn("#include +#include +static uint32_t millis() { return 100; } +static bool morse_timing = false, logging_armed = false; +struct Prefs { bool powersaving_enabled = true; }; +struct Mesh { + Prefs prefs; bool tracker = false; + Prefs* getNodePrefs() { return &prefs; } + bool isTrackerModeEnabled() const { return tracker; } +} the_mesh; +struct Board { + bool usb = false, charger = true; + unsigned usb_reads = 0, charger_reads = 0; + bool isUsbDataConnected() { ++usb_reads; return usb; } + bool isExternalPowered() { ++charger_reads; return charger; } +} board; +namespace mesh { +bool isUsbLoggingWatchdogArmed() { return logging_armed; } +namespace wireless { +struct Control { bool busy = false; unsigned reads = 0; + bool pending() { ++reads; return busy; } +}; +Control& control() { static Control value; return value; } +}} +static bool probe() { +@GUARD@ + return can_power_save; +} +int main() { + using namespace mesh::powerdiag; + for (unsigned flags = 0; flags != 64; ++flags) { + the_mesh.prefs.powersaving_enabled = !(flags & 1); + the_mesh.tracker = flags & 2; + morse_timing = flags & 4; + board.usb = flags & 8; + logging_armed = flags & 16; + mesh::wireless::control().busy = flags & 32; + const bool policy = the_mesh.prefs.powersaving_enabled || (@SENSOR@ && the_mesh.tracker); + const bool expected = policy && !morse_timing && !board.usb && !logging_armed + && (@SENSOR@ || !mesh::wireless::control().busy); + unsigned off_usb = 0, off_wireless = 0; + for (bool diagnostics : {false, true}) { + setEnabled(diagnostics, millis()); reset(millis()); + board.usb_reads = board.charger_reads = mesh::wireless::control().reads = 0; + assert(probe() == expected); + assert(board.charger_reads == 0); // USB power alone is not a data session. + if (!diagnostics) { + off_usb = board.usb_reads; + off_wireless = mesh::wireless::control().reads; + } else { + assert(board.usb_reads == off_usb); + assert(mesh::wireless::control().reads == off_wireless); + if (!expected) { + const Reason reason = !policy ? Reason::PolicyOff + : morse_timing ? Reason::Morse : board.usb ? Reason::UsbSession + : logging_armed ? Reason::UsbRecovery : Reason::Wireless; + assert(snapshot(millis()).current == mask(reason)); + } + } + } + } +} +'''.replace("@GUARD@", guard).replace("@SENSOR@", "true" if sensor else "false") + code = code.replace("#include ", "#include \n#include ") + self.execute(code) + + def test_repeater_actual_pending_reasons_keep_suspended_rs232_sleepable(self): + source = (ROOT / "examples/simple_repeater/MyMesh.cpp").read_text(encoding="ascii") + methods = "\n".join(extract_braced(source, signature) for signature in ( + "bool MyMesh::hasPendingWork() const", + "mesh::powerdiag::Mask MyMesh::pendingWorkReason() const", + "uint32_t MyMesh::getPowerSaveSleepSeconds(uint32_t max_secs) const", + )) + code = r''' +#include +#include +#include +#include +static uint32_t millis() { return 100; } +#define WITH_BRIDGE 1 +#define WITH_RS232_BRIDGE 1 +#define ETHERNET_ENABLED 1 +struct AbstractBridge { + bool running = false; uint32_t wake_ms = 60000; + bool isRunning() const { return running; } + uint32_t powerWakeDelayMs(uint32_t) const { return wake_ms; } +}; +struct MyMesh { + bool dual = false, ota = false, queue = false, retry = false, scheduled = false; + bool bridge_enabled = true; + bool queue_delay_set = false, retry_delay_set = false; + uint32_t queue_delay = 0, retry_delay = 0; + struct { bool busy_value = false; bool busy() const { return busy_value; } } _local_cli_output; + struct { bool pending = false; } deferred_cli_command; + struct { bool gpio = false; bool hasActiveUserGpioTimer() const { return gpio; } } _cli; + struct { bool watchdog = false, calibration = false; + bool isWatchdogObserving() const { return watchdog; } + bool isCalibratingNoiseFloor() const { return calibration; } + } radio_driver; + bool pending_self_advert = false; + struct { bool battery_alert_enabled = false; } _prefs; + unsigned long next_flood_advert = 0, next_local_advert = 0, dirty_contacts_expiry = 0; + unsigned long next_recent_repeater_sweep = 0, next_battery_alert_check = 0; + AbstractBridge uart; AbstractBridge* bridge = &uart; + uint8_t active_rs232_bridge_uart = 0; + const AbstractBridge* activeBridge() const { return bridge; } + bool rs232BridgeEnabled() const { return bridge_enabled; } + bool isDualRadioActive() const { return dual; } + bool hasPendingOtaApply() const { return ota; } + bool hasQueuedWorkDue() const { return queue; } + bool hasRetryWorkDue() const { return retry; } + bool hasScheduledRadioWorkDue() const { return scheduled; } + bool isMillisTimerDue(unsigned long value) const { return value && value <= millis(); } + bool getNextQueueWakeDelay(uint32_t& value) const { value = queue_delay; return queue_delay_set; } + bool getNextRetryWakeDelay(uint32_t& value) const { value = retry_delay; return retry_delay_set; } + uint32_t limitSleepToMillisTimer(unsigned long value, uint32_t seconds) const { + return value && value <= millis() ? 0 : seconds; + } + uint32_t limitSleepToScheduledRadioWork(uint32_t value) const { return value; } + bool hasPendingWork() const; + mesh::powerdiag::Mask pendingWorkReason() const; + uint32_t getPowerSaveSleepSeconds(uint32_t max_secs) const; +}; +@METHODS@ +int main() { + using namespace mesh::powerdiag; + for (bool diagnostics : {false, true}) { + setEnabled(diagnostics, millis()); reset(millis()); + MyMesh node; + assert(node.bridge_enabled && !node.uart.running); + assert(!node.hasPendingWork()); // Configured but suspended is not active UART ownership. + assert(node.getPowerSaveSleepSeconds(30) == 30); + auto check = [&](bool& flag, Reason why) { + flag = true; + assert(node.hasPendingWork()); + assert(node.pendingWorkReason() == mask(why)); + assert(node.getPowerSaveSleepSeconds(30) == 0); + if (diagnostics) assert(snapshot(millis()).current == mask(why)); + flag = false; + }; + check(node.dual, Reason::DualRadio); check(node.ota, Reason::Ota); + check(node._local_cli_output.busy_value, Reason::Serial); + check(node.deferred_cli_command.pending, Reason::Scheduled); + check(node.uart.running, Reason::Bridge); + node.active_rs232_bridge_uart = 1; + assert(node.pendingWorkReason() == mask(Reason::BridgeCleanup)); + node.active_rs232_bridge_uart = 0; + node.uart.wake_ms = 0; + assert(node.pendingWorkReason() == mask(Reason::BridgeWake)); + node.uart.wake_ms = 500; + assert(!node.hasPendingWork()); + assert(node.getPowerSaveSleepSeconds(30) == 0); // Whole-second bridge rendezvous floor. + if (diagnostics) assert(snapshot(millis()).current == mask(Reason::BridgeWake)); + node.uart.wake_ms = 60000; + check(node.radio_driver.watchdog, Reason::RadioWatchdog); + check(node.radio_driver.calibration, Reason::Calibration); + check(node.queue, Reason::Queue); check(node.retry, Reason::Retry); + check(node.scheduled, Reason::Scheduled); + node.queue_delay_set = true; node.queue_delay = 500; + assert(!node.hasPendingWork() && node.getPowerSaveSleepSeconds(30) == 0); + if (diagnostics) assert(snapshot(millis()).current == mask(Reason::Queue)); + node.queue_delay_set = false; node.retry_delay_set = true; node.retry_delay = 500; + assert(node.getPowerSaveSleepSeconds(30) == 0); + if (diagnostics) assert(snapshot(millis()).current == mask(Reason::Retry)); + node.retry_delay_set = false; node.dirty_contacts_expiry = millis(); + assert(node.pendingWorkReason() == mask(Reason::Scheduled)); + } +} +'''.replace("@METHODS@", methods) + self.execute(code) + + def test_nrf52_real_wait_sequence_veto_and_sdk_errors_are_observational(self): + source = (ROOT / "src/helpers/NRF52Board.cpp").read_text(encoding="ascii") + method = extract_braced(source, "void NRF52Board::sleep(uint32_t secs)") + code = r''' +#include +#include +#include +static uint32_t now_us = 1000, wait_duration = 547, sdk_error = 0; +static bool softdevice = true; +static char sequence[32] = {}; static unsigned steps = 0, yields = 0; +static uint32_t micros() { return now_us; } +static uint32_t millis() { return now_us / 1000; } +static void delay(unsigned value) { yields += value; } +constexpr uint32_t NRF_SUCCESS = 0; +namespace mesh_nrf52 { +void softdeviceIsEnabled(uint8_t& value) { value = softdevice; } +} +static uint32_t sd_app_evt_wait() { sequence[steps++] = 'A'; now_us += wait_duration; return sdk_error; } +static void __WFE() { sequence[steps++] = 'W'; now_us += 20; } +static void __SEV() { sequence[steps++] = 'S'; } +struct NRF52Board { + bool test = false; + bool isRadioTestActive() const { return test; } + void sleep(uint32_t secs); +}; +@METHOD@ +int main() { + using namespace mesh::powerdiag; + NRF52Board board; + board.sleep(0); + assert(steps == 1 && sequence[0] == 'A'); + assert(snapshot(millis()).calls == 0); + setEnabled(true, millis()); reset(millis()); + board.sleep(0); + auto value = snapshot(millis()); + assert(value.calls == 1 && value.returns == 1 && value.last_call_us == 547); + assert(value.errors == 0 && value.board_vetoes == 0); + board.test = true; + board.sleep(0); + value = snapshot(millis()); + assert(steps == 2 && yields == 1); + assert(value.calls == 1 && value.board_vetoes == 1 && value.detail == 2); + assert(value.current & mask(Reason::Board)); + board.test = false; sdk_error = 17; + board.sleep(0); + value = snapshot(millis()); + assert(value.errors == 1 && value.detail == 17 && value.calls == 2 && value.returns == 2); + softdevice = false; steps = 0; memset(sequence, 0, sizeof(sequence)); + board.sleep(0); + assert(!strcmp(sequence, "WSW")); // Do not erase a radio GPIO edge with SEV/WFE/WFE. + value = snapshot(millis()); + assert(value.calls == 3 && value.returns == 3 && value.last_call_us == 40); + assert(value.short_returns == 1); +} +'''.replace("@METHOD@", method) + self.execute(code) + + def test_esp32_real_veto_and_sdk_failure_timing_does_not_invent_blocked_residency(self): + source = (ROOT / "src/helpers/ESP32Board.h").read_text(encoding="ascii") + method = extract_braced(source, "void sleep(uint32_t secs) override") + code = r''' +#include +#include +#define ARDUINO_USB_CDC_ON_BOOT 1 +#define MESH_USB_LOGGING_AVAILABLE 1 +using esp_err_t = int; +using gpio_num_t = int; +constexpr int ESP_OK = 0, HIGH = 1, LOW = 0; +constexpr int USER_BTN_PRESSED = LOW; +constexpr int GPIO_INTR_HIGH_LEVEL = 1, GPIO_INTR_LOW_LEVEL = 2; +constexpr int GPIO_INTR_POSEDGE = 3, GPIO_INTR_DISABLE = 0; +static uint32_t now_us = 1000, sleep_duration = 7000; +static int timer_error = 0, gpio_error = 0, pin_error = 0, sleep_error = 0; +static unsigned sdk_calls = 0, yields = 0, critical_depth = 0, irq_reads = 0; +static bool radio_pending = false; +static uint32_t millis() { return now_us / 1000; } +static uint32_t micros() { return now_us; } +static void delay(unsigned ms) { yields += ms; } +static esp_err_t esp_sleep_enable_timer_wakeup(uint64_t) { return timer_error; } +static esp_err_t esp_sleep_enable_gpio_wakeup() { return gpio_error; } +static esp_err_t gpio_wakeup_enable(gpio_num_t, int) { return pin_error; } +static void gpio_wakeup_disable(gpio_num_t) {} +static void gpio_set_intr_type(gpio_num_t, int) {} +static int gpio_get_level(gpio_num_t) { ++irq_reads; return radio_pending ? HIGH : LOW; } +static esp_err_t esp_light_sleep_start() { ++sdk_calls; now_us += sleep_duration; return sleep_error; } +#define portENTER_CRITICAL(mux) (++critical_depth) +#define portEXIT_CRITICAL(mux) (--critical_depth) +namespace mesh { +static bool logging = false; +static bool isUsbLoggingEnabled() { return logging; } +} +struct MainBoard { virtual void sleep(uint32_t) = 0; }; +struct ESP32Board : MainBoard { + bool inhibit_sleep = false, usb = false, test = false; + uint32_t irq = 14; + bool isUsbSleepHeld() { return usb; } + bool isRadioTestActive() const { return test; } + uint32_t getIRQGpio() const { return irq; } +@METHOD@ +}; +int main() { + using namespace mesh::powerdiag; + ESP32Board board; + board.sleep(30); + assert(sdk_calls == 1 && snapshot(millis()).calls == 0); + setEnabled(true, millis()); reset(millis()); decision(0, millis()); + timer_error = 29; gpio_error = 31; pin_error = 33; + board.sleep(30); // Diagnostics may observe failures, never repair/change policy. + auto value = snapshot(millis()); + assert(sdk_calls == 2 && value.calls == 1 && value.returns == 1 && value.errors == 1); + assert(value.detail == 29); // First setup failure, without changing later SDK calls. + assert(value.last_call_us == 7000 && value.eligible_ms == 7); + assert(value.blocked_ms[static_cast(Reason::Board)] == 0); + assert(critical_depth == 0); + reset(millis()); decision(0, millis()); + timer_error = gpio_error = pin_error = 0; sleep_error = 41; + board.sleep(30); + value = snapshot(millis()); + assert(value.calls == 1 && value.returns == 1 && value.errors == 1 && value.detail == 41); + assert(value.eligible_ms == 7 && value.union_blocked_ms == 0); + sleep_error = 0; + auto veto = [&](Reason why, int detail) { + reset(millis()); decision(0, millis()); + const unsigned before = sdk_calls; + board.sleep(30); + const auto got = snapshot(millis()); + assert(sdk_calls == before && got.calls == 0 && got.board_vetoes == 1); + assert(got.current == mask(why) && got.detail == detail && critical_depth == 0); + }; + board.inhibit_sleep = true; veto(Reason::Board, 1); board.inhibit_sleep = false; + board.test = true; veto(Reason::Board, 2); board.test = false; + board.usb = true; veto(Reason::UsbSession, 1); board.usb = false; + mesh::logging = true; veto(Reason::UsbLogging, 0); mesh::logging = false; + radio_pending = true; veto(Reason::Mesh, 14); radio_pending = false; + reset(millis()); board.irq = static_cast(-1); + const unsigned before = sdk_calls; + board.sleep(0); + value = snapshot(millis()); + assert(sdk_calls == before && value.board_vetoes == 1 && value.current == mask(Reason::NoWake)); + assert(yields == 5 && irq_reads > 0); +} +'''.replace("@METHOD@", method) + self.execute(code) + + +if __name__ == "__main__": + unittest.main() diff --git a/test/test_rs232_heartbeat_owner.py b/test/test_rs232_heartbeat_owner.py index 7a2b9a58a..afa45aacf 100644 --- a/test/test_rs232_heartbeat_owner.py +++ b/test/test_rs232_heartbeat_owner.py @@ -19,6 +19,7 @@ HARNESS = r''' #include #include #include +#include #define WITH_BRIDGE 1 #define WITH_RS232_BRIDGE Serial2 #define WITH_RS232_BRIDGE_UART 2 @@ -162,6 +163,7 @@ struct MyMesh : Callbacks { uint32_t limitSleepToMillisTimer(unsigned long, uint32_t secs) const { return secs; } uint32_t limitSleepToScheduledRadioWork(uint32_t secs) const { return secs; } bool hasPendingWork() const; + mesh::powerdiag::Mask pendingWorkReason() const; uint32_t getPowerSaveSleepSeconds(uint32_t) const; @OWNER@ ~MyMesh() override { assert(setRs232BridgeState(false)); } @@ -297,6 +299,7 @@ class RS232HeartbeatOwnerTests(unittest.TestCase): )) sleep = "\n".join(extract_braced(implementation, signature) for signature in ( "bool MyMesh::hasPendingWork() const", + "mesh::powerdiag::Mask MyMesh::pendingWorkReason() const", "uint32_t MyMesh::getPowerSaveSleepSeconds(uint32_t max_secs) const", )) source = HARNESS.replace("@OWNER@", owner).replace("@SLEEP@", sleep) diff --git a/test/test_rs232_mqtt_runtime.py b/test/test_rs232_mqtt_runtime.py index b0247b8fe..f0454dbb0 100644 --- a/test/test_rs232_mqtt_runtime.py +++ b/test/test_rs232_mqtt_runtime.py @@ -61,7 +61,7 @@ class RS232MQTTRuntimeTests(unittest.TestCase): implementation.index("MyMesh::servicePostMeshLoop()")) service_end = implementation.index(" if (next_flood_advert", service_start) pending_start = implementation.index("#if defined(WITH_BRIDGE)", - implementation.index("bool MyMesh::hasPendingWork()")) + implementation.index("mesh::powerdiag::Mask MyMesh::pendingWorkReason()")) pending_end = implementation.index(" if (radio_driver.isWatchdogObserving()", pending_start) commands = preprocess("\n".join(extract_braced(cli, signature) for signature in ( "void CommonCLI::handleSetCmd(", "void CommonCLI::handleGetCmd("))) @@ -158,7 +158,7 @@ class RS232MQTTRuntimeTests(unittest.TestCase): boot_end = implementation.index('mesh::hilStartupTrace("mesh_bridge_ready");', boot_start) service_start = implementation.index("#if defined(WITH_MQTT_BRIDGE)\n // MQTT owns TLS", implementation.index("MyMesh::servicePostMeshLoop()")) service_end = implementation.index(" if (next_flood_advert", service_start) - pending_start = implementation.index("#if defined(WITH_BRIDGE)", implementation.index("bool MyMesh::hasPendingWork()")) + pending_start = implementation.index("#if defined(WITH_BRIDGE)", implementation.index("mesh::powerdiag::Mask MyMesh::pendingWorkReason()")) pending_end = implementation.index(" if (radio_driver.isWatchdogObserving()", pending_start) route = {} for name in ("logRx", "logTx"): diff --git a/test/test_rs232_runtime.py b/test/test_rs232_runtime.py index f53942acb..10850926c 100644 --- a/test/test_rs232_runtime.py +++ b/test/test_rs232_runtime.py @@ -228,7 +228,7 @@ class RS232RuntimeTests(unittest.TestCase): implementation.index("MyMesh::servicePostMeshLoop()")) loop_end = implementation.index(" if (next_flood_advert", loop_start) pending_start = implementation.index("#if defined(WITH_BRIDGE)", - implementation.index("bool MyMesh::hasPendingWork()")) + implementation.index("mesh::powerdiag::Mask MyMesh::pendingWorkReason()")) pending_end = implementation.index(" if (radio_driver.isWatchdogObserving()", pending_start) # Preprocess complete dispatch methods before extracting branches. # Their feature guards cross the closing braces between else-if cases. diff --git a/test/test_sensor_tracker_sleep.py b/test/test_sensor_tracker_sleep.py index f9985fbd8..a9c048435 100644 --- a/test/test_sensor_tracker_sleep.py +++ b/test/test_sensor_tracker_sleep.py @@ -18,6 +18,7 @@ DEADLINES = r''' #include #include #include +#include #define SENSOR_READ_INTERVAL_SECS 60 bool logging=false; namespace mesh {bool isUsbLoggingWatchdogArmed(){return logging;}} @@ -64,6 +65,7 @@ public: bool isMillisTimerDue(unsigned long timestamp)const; uint32_t limitSleepToMillisTimer(unsigned long timestamp,uint32_t sleep_secs)const; bool hasPendingWork()const; + mesh::powerdiag::Mask pendingWorkReason()const; uint32_t getPowerSaveSleepSeconds(uint32_t max_secs)const; #if MESH_ENABLE_SENSOR_TRACKER bool trackerNeedsRadio()const; @@ -123,6 +125,7 @@ int main(){ TIMER = r''' #include #include +#include using TimerHandle_t=void*; bool allocate=true,queue_ok=true; unsigned period_ms=0,begin_calls=0,queue_calls=0; @@ -267,7 +270,8 @@ class SensorTrackerSleepTest(unittest.TestCase): tracker = (ROOT / "examples/simple_sensor/Tracker.cpp").read_text() methods = "\n".join(extract_braced(sensor, name) for name in ( "bool SensorMesh::isMillisTimerDue(", "uint32_t SensorMesh::limitSleepToMillisTimer(", - "bool SensorMesh::hasPendingWork(", "uint32_t SensorMesh::getPowerSaveSleepSeconds(")) + "bool SensorMesh::hasPendingWork(", "mesh::powerdiag::Mask SensorMesh::pendingWorkReason(", + "uint32_t SensorMesh::getPowerSaveSleepSeconds(")) methods += "\n#if MESH_ENABLE_SENSOR_TRACKER\n" + extract_braced( tracker, "bool SensorMesh::trackerNeedsRadio(") + "\n#endif\n" for enabled in (0, 1): @@ -371,7 +375,8 @@ int main(){ sensor = sensor[:begin] + sensor[end:] methods = "\n".join(body(sensor, signature) for signature in ( "bool SensorMesh::isMillisTimerDue(", "uint32_t SensorMesh::limitSleepToMillisTimer(", - "bool SensorMesh::hasPendingWork(", "uint32_t SensorMesh::getPowerSaveSleepSeconds(")) + "bool SensorMesh::hasPendingWork(", "mesh::powerdiag::Mask SensorMesh::pendingWorkReason(", + "uint32_t SensorMesh::getPowerSaveSleepSeconds(")) methods += "\n" + "\n".join(body(tracker, signature) for signature in ( "bool SensorMesh::trackerNeedsRadio(", "void SensorMesh::wakeTrackerRadio(")) # Execute the actual wake-before-CLI order. Application sensor work diff --git a/test/test_t096_button_wake_profile.py b/test/test_t096_button_wake_profile.py index 39866d094..b2f37eb4f 100644 --- a/test/test_t096_button_wake_profile.py +++ b/test/test_t096_button_wake_profile.py @@ -63,7 +63,8 @@ class T096ButtonWakeProfileTest(unittest.TestCase): header, ) self.assertIn("defined(MOMENTARY_BUTTON_WAKE_FROM_SLEEP)", main) - self.assertIn("!user_btn.needsPolling()", main) + self.assertIn("if (!sleep_reason && user_btn.needsPolling()) sleep_reason = mask(Reason::Button);", main) + self.assertIn("const bool can_sleep = sleep_reason == 0;", main) self.assertIn("defined(MOMENTARY_BUTTON_WAKE_FROM_SLEEP)", repeater_main) self.assertIn("!user_btn.needsPolling()", repeater_main) self.assertIn("defined(MOMENTARY_BUTTON_WAKE_FROM_SLEEP)", room_main)