From 2a3b7e3d3e5ed29f26983e62dce5611b5a4f31dd Mon Sep 17 00:00:00 2001 From: mikecarper Date: Sat, 3 Oct 2026 18:22:32 -0700 Subject: [PATCH] Keep USB watchdog snapshots coherent and fail-safe --- docs/usb_logging_watchdog.md | 8 ++ src/helpers/UsbLoggingWatchdog.cpp | 89 ++++++++------ .../test_usb_logging_watchdog_runtime.cpp | 12 +- test/test_usb_logging_watchdog_runtime.py | 115 ++++++++++++++++++ 4 files changed, 188 insertions(+), 36 deletions(-) diff --git a/docs/usb_logging_watchdog.md b/docs/usb_logging_watchdog.md index de88cb1a9..5f670fd85 100644 --- a/docs/usb_logging_watchdog.md +++ b/docs/usb_logging_watchdog.md @@ -161,6 +161,14 @@ Python and browser decoders retain released MGR1 support; older decoder copies must be updated to read MGR2. Events appear on the normal management schedule, not as immediate alerts. Reading status does not renew the logging-client lease. +Concurrent readers receive one coherent status publication, including its tier, +counters, and latest event. Reads never wait for a writer. If three bounded +attempts cannot obtain a snapshot, status conservatively reports deferred +recovery and no verified persistence, ages, counters, or event. It preserves +published hardware/logging/mode intent and protects a possibly active reader. +This temporary fallback cannot authorize a reset. The separate awake hint keeps +an already durable watchdog policy serviced while publication is busy. + ## Verification The two qualification stages below precede the subsequent upstream USB/GPS diff --git a/src/helpers/UsbLoggingWatchdog.cpp b/src/helpers/UsbLoggingWatchdog.cpp index 9138af892..4334cd1f5 100644 --- a/src/helpers/UsbLoggingWatchdog.cpp +++ b/src/helpers/UsbLoggingWatchdog.cpp @@ -108,22 +108,24 @@ void publish(const UsbLoggingObservation& observation) { | (policy.deferred() || backend_deferred ? 128U : 0U) | (persistence_ready ? 256U : 0U) | (config.mode == 2 ? 512U : 0U) | (reader_seen ? 1024U : 0U) | (logger_active ? 2048U : 0U); + // Bracket the entire status, not just its event. A counter/tier read from + // one publication must never be paired with another event's journal. + status_event_guard.fetch_add(1); status_stage_step.store(uint32_t(policy.stage()) | (uint32_t(config.step) << 8)); status_retry.store(Policy::intervalMs(config.step) / 1000); status_inactive.store(policy.inactiveSeconds()); status_recoveries.store(config.recoveries); status_reboots.store(config.reboots); status_auto_seconds.store(auto_arm.connectedSeconds()); - // A bounded sequence guard prevents mixing fields from different events. - // All words are atomic, and seq_cst keeps the guard around their publication. - status_event_guard.fetch_add(1); + // Every shared word remains atomic: the sequence guard alone would not make + // concurrent non-atomic reads/writes legal in the C++ memory model. status_event_code.store(config.last_event.reasons | (uint32_t(config.last_event.action) << 4) | (config.last_event.persisted ? 128U : 0U)); status_event_epoch.store(config.last_event.epoch); status_event_uptime.store(config.last_event.uptime_seconds); status_event_sequence.store(config.last_event.sequence); - status_event_guard.fetch_add(1); status_flags.store(flags, std::memory_order_release); + status_event_guard.fetch_add(1); } ReadResult readImage(const char* path, uint8_t* image, size_t* read_size = nullptr) { @@ -206,31 +208,31 @@ bool keyMatches(const char* command, const char* key) { } // namespace UsbLoggingStatus usbLoggingStatus() { - UsbLoggingStatus status; - const uint32_t flags = status_flags.load(std::memory_order_acquire); - const uint32_t stage_step = status_stage_step.load(); - status.supported = flags & 1U; - status.logging_enabled = flags & 2U; - status.watchdog_enabled = flags & 4U; - status.host_connected = flags & 8U; - status.reader_connected = flags & 16U; - status.stalled = flags & 32U; - status.recovering = flags & 64U; - status.recovery_deferred = flags & 128U; - status.persistence_ready = flags & 256U; - status.watchdog_auto = flags & 512U; - status.logger_active = flags & 2048U; - status.stage = stage_step & 0xff; - status.backoff_step = (stage_step >> 8) & 0xff; - status.retry_seconds = status_retry.load(); - status.inactive_seconds = status_inactive.load(); - status.recovery_count = status_recoveries.load(); - status.reboot_count = status_reboots.load(); - status.auto_connected_seconds = status_auto_seconds.load(); for (uint8_t attempt = 0; attempt < 3; ++attempt) { const uint32_t before = status_event_guard.load(); if (before & 1U) continue; - Event event; + UsbLoggingStatus status; + const uint32_t flags = status_flags.load(std::memory_order_acquire); + const uint32_t stage_step = status_stage_step.load(); + status.supported = flags & 1U; + status.logging_enabled = flags & 2U; + status.watchdog_enabled = flags & 4U; + status.host_connected = flags & 8U; + status.reader_connected = flags & 16U; + status.stalled = flags & 32U; + status.recovering = flags & 64U; + status.recovery_deferred = flags & 128U; + status.persistence_ready = flags & 256U; + status.watchdog_auto = flags & 512U; + status.logger_active = flags & 2048U; + status.stage = stage_step & 0xff; + status.backoff_step = (stage_step >> 8) & 0xff; + status.retry_seconds = status_retry.load(); + status.inactive_seconds = status_inactive.load(); + status.recovery_count = status_recoveries.load(); + status.reboot_count = status_reboots.load(); + status.auto_connected_seconds = status_auto_seconds.load(); + auto& event = status.last_event; const uint32_t code = status_event_code.load(); event.reasons = code & 15U; event.action = (code >> 4) & 7U; @@ -238,21 +240,38 @@ UsbLoggingStatus usbLoggingStatus() { event.epoch = status_event_epoch.load(); event.uptime_seconds = status_event_uptime.load(); event.sequence = status_event_sequence.load(); - if (before == status_event_guard.load()) { - status.last_event = event; - break; - } + if (before == status_event_guard.load()) return status; } + // A writer may be preempted, so retries must stay bounded. This is an + // unavailable/conservative snapshot, not fresh physical measurements. + // Keep published hardware/logging/mode intent; never pretend unsupported. + // A possibly live reader must still protect functional CLI work. No durable + // authorization or event is claimed until a coherent snapshot is available. + UsbLoggingStatus status; + const uint32_t flags = status_flags.load(std::memory_order_acquire); + status.supported = flags & 1U; + status.logging_enabled = flags & 2U; + status.watchdog_enabled = flags & 4U; + status.watchdog_auto = flags & 512U; + status.reader_connected = true; + status.recovery_deferred = true; + status.backoff_step = Policy::MAX_STEP; + status.retry_seconds = Policy::MAX_MS / 1000; return status; } bool isUsbLoggingWatchdogArmed() { if (isUsbLoggingTransportRecoveryPending()) return true; - const auto status = usbLoggingStatus(); - const bool seen = status_flags.load(std::memory_order_acquire) & 1024U; - return status.supported && status.logging_enabled - && (status.watchdog_enabled || (status.watchdog_auto && seen && status.stage < 2)) - && status.persistence_ready; + // This is only an awake/service hint, never reset authorization. Keep a + // previously durable policy awake if publication is busy; falling back to + // an unavailable snapshot here could allow sleep to restart its deadline. + const uint32_t before = status_event_guard.load(); + const uint32_t flags = status_flags.load(std::memory_order_acquire); + const uint32_t stage = status_stage_step.load() & 0xffU; + const bool busy = (before & 1U) || before != status_event_guard.load(); + const bool ready = (flags & (1U | 2U | 256U)) == (1U | 2U | 256U); + return ready && ((flags & 4U) + || ((flags & 512U) && (flags & 1024U) && (busy || stage < 2))); } void loadUsbLoggingWatchdog(FILESYSTEM* fs, bool durable, uint32_t (*epoch_seconds)()) { diff --git a/test/fixtures/usb_logging_watchdog/test_usb_logging_watchdog_runtime.cpp b/test/fixtures/usb_logging_watchdog/test_usb_logging_watchdog_runtime.cpp index 72b06665c..41a2a79e0 100644 --- a/test/fixtures/usb_logging_watchdog/test_usb_logging_watchdog_runtime.cpp +++ b/test/fixtures/usb_logging_watchdog/test_usb_logging_watchdog_runtime.cpp @@ -1011,10 +1011,20 @@ static void check_event_snapshot_is_coherent_with_concurrent_readers() { std::atomic snapshots{0}; std::thread reader([&] { while (running.load()) { - const auto event = mesh::usbLoggingStatus().last_event; + const auto status = mesh::usbLoggingStatus(); + const auto event = status.last_event; if (event.sequence) { + assert(status.persistence_ready && status.watchdog_enabled); + assert(status.recovery_count == event.sequence); + assert(status.backoff_step == 0 && status.retry_seconds == 3600); assert(event.epoch == 2000000000U + event.sequence); assert(event.action == Event::SOFT_RECOVERY && event.reasons == 3 && event.persisted); + } else if (!status.persistence_ready) { + // A bounded busy-reader fallback has no mixed partial journal/tier. + assert(status.supported && status.logging_enabled && status.watchdog_enabled); + assert(status.reader_connected && !status.stalled && status.recovery_deferred); + assert(status.backoff_step == 8 && status.retry_seconds == 604800); + assert(!status.recovery_count && !status.reboot_count && !status.auto_connected_seconds); } ++snapshots; } diff --git a/test/test_usb_logging_watchdog_runtime.py b/test/test_usb_logging_watchdog_runtime.py index 4a3cdacc7..dce997db8 100644 --- a/test/test_usb_logging_watchdog_runtime.py +++ b/test/test_usb_logging_watchdog_runtime.py @@ -6,12 +6,127 @@ import subprocess import tempfile import unittest +from test_radio_receive_contract import method + ROOT = Path(__file__).resolve().parents[1] FIXTURE = ROOT / 'test' / 'fixtures' / 'usb_logging_watchdog' class UsbLoggingWatchdogRuntimeTest(unittest.TestCase): + def test_busy_snapshot_protects_commands_and_keeps_durable_policy_awake(self): + compiler = os.environ.get('CXX') or shutil.which('g++') or shutil.which('clang++') + if compiler is None: + self.skipTest('a host C++17 compiler is required') + callback = method((ROOT / 'examples/simple_sensor/main.cpp').read_text(), + 'static bool usbLoggingRecoverySafe(void*)') + harness = r''' +#include +#include +#include +#include +#include +#include + +static mesh::UsbLoggingObservation observation{true, false, false, false, 0}; +static bool pending_attach = false; +static bool logger_active = false; +namespace mesh { +bool isUsbLoggingEnabled() { return true; } +bool isUsbLoggingClientActive() { return logger_active; } +void clearUsbLoggingClientActivity() {} +bool isUsbLoggingTransportRecoveryPending() { return pending_attach; } +UsbLoggingObservation observeUsbLoggingTransport() { return observation; } +UsbLoggingRecoveryResult recoverUsbLoggingTransport(uint8_t) { + return UsbLoggingRecoveryResult::Attempted; +} +void probeUsbLoggingTransport() {} +} +struct Board { + bool isOTAUpdateRunning() const { return false; } + bool isRadioTestActive() const { return false; } +} board; +struct Radio { + bool isWatchdogObserving() const { return false; } + bool isCalibratingNoiseFloor() const { return false; } +} radio_driver; +struct Mesh { bool canRecoverUsbLogging() const { return true; } } the_mesh; +static char command[32] = {}; +@CALLBACK@ + +int main() { + fs::FS fs; + fs::stat_filesystem = &fs; + mesh::loadUsbLoggingWatchdog(&fs); + char reply[160]; + assert(mesh::handleUsbLoggingWatchdogCommand("set usb.watchdog on", reply, sizeof(reply))); + assert(!std::strcmp(reply, "OK - USB watchdog on (saved)")); + for (uint32_t now : {0U, 300000U, 360000U}) { + mock_watchdog_millis = now; + assert(!mesh::serviceUsbLoggingWatchdog(usbLoggingRecoverySafe)); + } + assert(mesh::usbLoggingStatus().stage == 2); + const auto writes = fs.write_opens; + // Simulate a publisher preempted while the real status getter is called. + // No test hook or substituted getter is used; all atomic words are real. + mesh::status_event_guard.fetch_add(1); + const auto busy = mesh::usbLoggingStatus(); + assert(busy.supported && busy.logging_enabled && busy.watchdog_enabled && !busy.watchdog_auto); + assert(busy.reader_connected && !busy.stalled && busy.recovery_deferred && !busy.persistence_ready); + assert(busy.backoff_step == 8 && busy.retry_seconds == 604800); + assert(!busy.recovery_count && !busy.reboot_count && !busy.inactive_seconds); + assert(!busy.auto_connected_seconds && !busy.last_event.sequence); + assert(mesh::isUsbLoggingWatchdogArmed()); // Awake hint is not reset authority. + std::strcpy(command, "stats-core"); + assert(!usbLoggingRecoverySafe(nullptr)); // Execute the actual sensor veto. + mock_watchdog_millis = 3600000; + assert(!mesh::serviceUsbLoggingWatchdog(usbLoggingRecoverySafe)); + assert(fs.write_opens == writes); // No new tier/journal/reset authorization. + mesh::status_event_guard.fetch_add(1); + assert(mesh::usbLoggingStatus().persistence_ready); + assert(mesh::handleUsbLoggingWatchdogCommand("set usb.watchdog off", reply, sizeof(reply))); + mesh::status_event_guard.fetch_add(1); + assert(!mesh::isUsbLoggingWatchdogArmed()); + pending_attach = true; + assert(mesh::isUsbLoggingWatchdogArmed()); // Finish USB reattach even in Off. + mesh::status_event_guard.fetch_add(1); + pending_attach = false; + command[0] = 0; + assert(mesh::handleUsbLoggingWatchdogCommand("set usb.watchdog auto", reply, sizeof(reply))); + observation = {true, true, true, false, 1}; + logger_active = true; + assert(!mesh::serviceUsbLoggingWatchdog(usbLoggingRecoverySafe)); + assert(mesh::isUsbLoggingWatchdogArmed()); // Auto has observed a logging client. + observation = {true, false, false, false, 1}; + logger_active = false; + for (uint32_t now : {3600001U, 3900001U, 3960001U}) { + mock_watchdog_millis = now; + assert(!mesh::serviceUsbLoggingWatchdog(usbLoggingRecoverySafe)); + } + assert(mesh::usbLoggingStatus().stage == 2); + assert(!mesh::isUsbLoggingWatchdogArmed()); // Auto completed USB-only attempts. + mesh::status_event_guard.fetch_add(1); + assert(mesh::usbLoggingStatus().watchdog_auto); + assert(mesh::isUsbLoggingWatchdogArmed()); // Busy Auto publication stays awake. + mesh::status_event_guard.fetch_add(1); +} +'''.replace('@CALLBACK@', callback) + sanitizer_flags = [] if os.name == 'nt' else [ + '-fsanitize=address,undefined', '-fno-sanitize-recover=all', '-fno-pie', '-no-pie'] + with tempfile.TemporaryDirectory(prefix='usb-watchdog-snapshot-') as directory: + source = Path(directory) / 'snapshot.cpp' + source.write_text(harness, encoding='ascii') + binary = Path(directory) / 'snapshot.exe' + built = subprocess.run([ + compiler, '-std=c++17', '-Wall', '-Wextra', '-Werror', '-pthread', + *sanitizer_flags, '-DARDUINO', '-DESP32', '-DESP32_PLATFORM', + '-DARDUINO_USB_MODE=0', '-DARDUINO_USB_CDC_ON_BOOT=1', + '-I' + str(FIXTURE / 'mocks'), '-I' + str(ROOT / 'src'), + str(source), '-o', str(binary)], capture_output=True, text=True, timeout=60) + self.assertEqual(built.returncode, 0, built.stderr) + tested = subprocess.run([str(binary)], capture_output=True, text=True, timeout=10) + self.assertEqual(tested.returncode, 0, tested.stderr) + def test_production_runtime_and_persistence(self): compiler = os.environ.get('CXX') or shutil.which('g++') or shutil.which('clang++') if compiler is None: