From 7278eacb9131d613da719fee814fefcdad3adf23 Mon Sep 17 00:00:00 2001 From: mikecarper Date: Tue, 20 Oct 2026 17:32:12 -0700 Subject: [PATCH] fix: preserve HWCDC logging lease across transient USB status --- .github/workflows/run-unit-tests.yml | 1 + src/helpers/UsbLogging.cpp | 29 +- .../usb_logging_watchdog/hwcdc_backend.cpp | 8 +- test/test_usb_logging_hwcdc_presence.py | 255 ++++++++++++++++++ 4 files changed, 288 insertions(+), 5 deletions(-) create mode 100644 test/test_usb_logging_hwcdc_presence.py diff --git a/.github/workflows/run-unit-tests.yml b/.github/workflows/run-unit-tests.yml index a6810b340..2e59841f4 100644 --- a/.github/workflows/run-unit-tests.yml +++ b/.github/workflows/run-unit-tests.yml @@ -830,6 +830,7 @@ jobs: python3 -B test/test_usb_logging_client_activity.py python3 -B test/test_usb_logging_watchdog_runtime.py python3 -B test/test_usb_logging_hwcdc_watchdog.py -v + python3 -B test/test_usb_logging_hwcdc_presence.py -v python3 -B test/test_usb_logging_watchdog_roles.py python3 -B test/test_nrf52_usb_console.py python3 -B test/test_esp32_tinyusb_nonblocking.py diff --git a/src/helpers/UsbLogging.cpp b/src/helpers/UsbLogging.cpp index 92182e0f0..8a4376f56 100644 --- a/src/helpers/UsbLogging.cpp +++ b/src/helpers/UsbLogging.cpp @@ -1712,8 +1712,33 @@ UsbLoggingObservation observeUsbLoggingTransport() { #elif MESH_ESP32_HWCDC_SESSION_GUARD result.supported = true; if (xPortInIsrContext()) return result; - result.host_connected = Serial.isPlugged(); - result.reader_connected = result.host_connected && bool(Serial); + // The SDK's five-millisecond SOF sample can briefly go low on a healthy + // connection. Do not let one such sample revoke a fifteen-minute stats + // lease and provoke USB recovery five minutes later. Match the primary + // session's 100 ms host-loss edge; actual BUS_RESET still revokes the lease + // immediately in handleEsp32HwcdcEvent(). Only the application loop/CLI + // samples this state, after the ISR guard above. + static bool host_seen = false, loss_pending = false; + static uint32_t loss_at = 0; + const uint32_t now = millis(); + if (Serial.isPlugged()) { + host_seen = true; + loss_pending = false; + } else if (host_seen) { + if (!loss_pending) { + loss_pending = true; + loss_at = now; + } else if (uint32_t(now - loss_at) >= 100) { + host_seen = false; + loss_pending = false; + } + } + result.host_connected = host_seen; + // HWCDC has no DTR/open-reader signal. Its bool operator is an RX/TX + // heuristic which can remain false after a transient SOF gap. Physical + // presence, real TX completion/stalls and the separate stats lease are the + // available evidence; this does not claim that a host process is reading. + result.reader_connected = result.host_connected; const size_t capacity = esp32_hwcdc_tx_buffer_capacity.load(std::memory_order_acquire); result.pending = usb_logging_tx_waiting.load(std::memory_order_acquire) || (capacity != 0 && Serial.availableForWrite() < int(capacity)) diff --git a/test/fixtures/usb_logging_watchdog/hwcdc_backend.cpp b/test/fixtures/usb_logging_watchdog/hwcdc_backend.cpp index 4f960b449..cc10271f9 100644 --- a/test/fixtures/usb_logging_watchdog/hwcdc_backend.cpp +++ b/test/fixtures/usb_logging_watchdog/hwcdc_backend.cpp @@ -323,10 +323,12 @@ int main(int argc, char** argv) { assert(!f.run(0) && !f.run(1)); mesh::host_connected = mesh::reader_connected = false; assert(!f.run(2)); - assert(!f.run(2 + Policy::EARLY_RECOVERY_MS)); - assert(!f.run(2 + Policy::EARLY_RECOVERY_MS + Policy::RECOVERY_GRACE_MS)); + assert(!f.run(101)); + assert(!f.run(102)); // HWCDC requires a 100 ms observed physical loss. + assert(!f.run(102 + Policy::EARLY_RECOVERY_MS)); + assert(!f.run(102 + Policy::EARLY_RECOVERY_MS + Policy::RECOVERY_GRACE_MS)); assert(mesh::usbLoggingStatus().stage == 2 && mesh::detach_calls == 1); - assert(!f.run(2 + deadline + Policy::RECOVERY_GRACE_MS)); + assert(!f.run(102 + deadline + Policy::RECOVERY_GRACE_MS)); assert(mesh::usbLoggingStatus().watchdog_auto && !mesh::usbLoggingStatus().reboot_count); } else if (scenario == "journal-fail") { Fixture f(1, step); diff --git a/test/test_usb_logging_hwcdc_presence.py b/test/test_usb_logging_hwcdc_presence.py new file mode 100644 index 000000000..e86dcc7a5 --- /dev/null +++ b/test/test_usb_logging_hwcdc_presence.py @@ -0,0 +1,255 @@ +"""Real HWCDC ISR, stats lease and watchdog runtime across idle/SOF gaps.""" +from pathlib import Path +import os +import shutil +import subprocess +import tempfile +import unittest + +from cpp_source import body +import test_hwcdc_tx_backport as backport +from test_serial_wifi_sessions import SANITIZER_FLAGS + +ROOT = Path(__file__).resolve().parents[1] +FIXTURE = ROOT / 'test/fixtures/usb_logging_watchdog' + +HARNESS = r''' +#include +#include +#include +#include +#include +#include +#include +#include +#include +#include +#include +#define portENTER_CRITICAL(m) portENTER_CRITICAL_SAFE(m) +#define portEXIT_CRITICAL(m) portEXIT_CRITICAL_SAFE(m) +using esp_event_base_t = int; +static bool in_isr = false; +static bool xPortInIsrContext() { return in_isr; } +namespace mesh { +static bool logging_enabled = true; +static unsigned bool_samples = 0, probes = 0; +static std::vector recoveries; +bool isUsbLoggingEnabled() { return logging_enabled; } +bool isUsbLoggingTransportRecoveryPending() { return false; } +void probeUsbLoggingTransport() { ++probes; } // Enqueue is not completion. +UsbLoggingRecoveryResult recoverUsbLoggingTransport(uint8_t stage) { + recoveries.push_back(stage); + return UsbLoggingRecoveryResult::Attempted; +} +static std::atomic usb_logging_tx_progress{0}; +static std::atomic usb_logging_tx_waiting{false}; +static std::atomic esp32_hwcdc_tx_buffer_capacity{4096}; +static std::atomic esp32_hwcdc_access_generation{0}; +static std::atomic esp32_hwcdc_bus_reset_generation{0}; +static std::atomic esp32_hwcdc_startup_pending{false}; +static std::atomic esp32_hwcdc_tx_kick_pending{false}; +static std::atomic esp32_hwcdc_tx_primed{false}; +static UsbSelfResetBurstGuard esp32_hwcdc_self_reset_guard; +static portMUX_TYPE esp32_hwcdc_session_mux; +static void noteUsbLoggingTxComplete() { + ++usb_logging_tx_progress; + usb_logging_tx_waiting.store(false); +} +struct SerialMock { + bool isPlugged() { return HWCDC::isPlugged(); } + explicit operator bool() { ++bool_samples; return HWCDC::isCDC_Connected(); } + int availableForWrite() { + unsigned waiting = 0; + vRingbufferGetInfo(&ring, nullptr, nullptr, nullptr, nullptr, &waiting); + return 4096 - waiting; + } + void setDebugOutput(bool) {} +} Serial; +@OBSERVATION@ +@EVENT@ +} // namespace mesh + +static bool safe(void*) { return true; } +int main(int argc, char** argv) { + assert(argc == 4); + const std::string scenario = argv[1]; + const uint8_t mode = uint8_t(std::strtoul(argv[2], nullptr, 10)); + const uint32_t origin = uint32_t(std::strtoull(argv[3], nullptr, 10)); + reset(); + fs::FS fs; + fs::stat_filesystem = &fs; + std::vector image(33, 0); + image[0] = 'U'; image[1] = 'W'; image[2] = 2; image[4] = mode; + mesh::storage::writeLE32(image.data() + 29, + mesh::storage::updateCRC32(0xffffffffU, image.data(), 29) ^ 0xffffffffU); + fs.files["/usb_wdg"] = image; + mock_watchdog_millis = origin; + mesh::loadUsbLoggingWatchdog(&fs); + const auto run = [&](uint32_t elapsed) { + mock_watchdog_millis = origin + elapsed; + return mesh::serviceUsbLoggingWatchdog(safe); + }; + + // Before the first physical positive, neither startup nor an ISR sample + // may manufacture host/reader presence or seed debounce state. + assert(!mesh::observeUsbLoggingTransport().host_connected); + plugged = true; in_isr = true; + assert(!mesh::observeUsbLoggingTransport().host_connected); + in_isr = false; plugged = false; + assert(!mesh::observeUsbLoggingTransport().host_connected); + plugged = true; + intr_status = USB_SERIAL_JTAG_INTR_SERIAL_OUT_RECV_PKT; + hw_cdc_isr_handler(nullptr); // The real pinned ISR establishes RX activity. + assert(connected); + mesh::noteUsbLoggingStatsCommand("stats-core"); + assert(!run(0) && !run(1)); + assert(mesh::usbLoggingStatus().logger_active); + + if (scenario == "idle-sof" || scenario == "idle-bool") { + mock_watchdog_millis = origin + 1000; + plugged = false; + assert(!HWCDC::isCDC_Connected()); // Actual SDK heuristic loses connected. + if (scenario == "idle-bool") plugged = true; + assert(!run(1000)); + assert(mesh::isUsbLoggingClientActive() + && "transient HWCDC observation must preserve the stats lease"); + assert(mesh::usbLoggingStatus().host_connected + && mesh::usbLoggingStatus().reader_connected); + if (scenario == "idle-sof") { + assert(!run(1099)); // A real loss has not yet reached the 100 ms edge. + plugged = true; + } + assert(!run(1100)); + assert(!run(600000)); + assert(mesh::recoveries.empty() && !fs.writes); + assert(mesh::usbLoggingStatus().logger_active); + assert(mesh::bool_samples == 0 && "HWCDC bool is not an open-reader signal"); + + // Exact fifteen-minute expiry still requests USB-only repair five minutes + // later. Missing stats on a healthy physical endpoint cannot reboot On. + assert(!run(899999) && mesh::isUsbLoggingClientActive()); + assert(!run(900000) && !mesh::isUsbLoggingClientActive()); + assert(!run(1199999) && mesh::recoveries.empty()); + assert(!run(1200000) && mesh::recoveries == std::vector{1}); + assert(!run(1260000) && mesh::recoveries == (std::vector{1, 2})); + assert(mesh::usbLoggingStatus().last_event.reasons + == mesh::UsbLoggingWatchdogEvent::CLIENT_INACTIVE); + assert(!run(3600000) && !mesh::usbLoggingStatus().reboot_count); + } else if (scenario == "unplug") { + plugged = false; + assert(!run(1000) && mesh::isUsbLoggingClientActive()); + assert(!run(1099) && mesh::isUsbLoggingClientActive()); + assert(!run(1100) && !mesh::isUsbLoggingClientActive()); + assert(!mesh::usbLoggingStatus().host_connected + && !mesh::usbLoggingStatus().reader_connected); + assert(!run(301099) && mesh::recoveries.empty()); + assert(!run(301100) && mesh::recoveries == std::vector{1}); + assert(!run(361100) && mesh::recoveries == (std::vector{1, 2})); + assert(run(3601100) == (mode == 1)); + assert(mesh::usbLoggingStatus().reboot_count == (mode == 1 ? 1U : 0U)); + plugged = true; + assert(!run(3601101)); + assert(mesh::usbLoggingStatus().host_connected); + assert(!mesh::isUsbLoggingClientActive()); // Replug never renews the lease. + } else if (scenario == "bus-reset") { + mock_watchdog_millis = origin + 1000; + intr_status = USB_SERIAL_JTAG_INTR_BUS_RESET; + hw_cdc_isr_handler(nullptr); + assert(!connected); + mesh::handleEsp32HwcdcEvent(nullptr, 0, ARDUINO_HW_CDC_BUS_RESET_EVENT, nullptr); + assert(!mesh::isUsbLoggingClientActive()); // No debounce of real reset. + assert(mesh::esp32_hwcdc_bus_reset_generation.load() == 1); + assert(mesh::esp32_hwcdc_access_generation.load() == 1); + assert(!mesh_hwcdc_tx_allowed); + } else if (scenario == "stall") { + ring.data.push_back({1, 2, 3}); + pulse(); // Actual ISR stages an unacknowledged FIFO; no later host ACK. + assert(meshEsp32HwcdcTxPending()); + assert(!run(1000)); + assert(!run(31000) && mesh::usbLoggingStatus().stalled); + assert(!run(301000) && mesh::recoveries == std::vector{1}); + assert(!run(361000) && mesh::recoveries == (std::vector{1, 2})); + assert(run(3601000) == (mode == 1)); + assert(mesh::usbLoggingStatus().reboot_count == (mode == 1 ? 1U : 0U)); + } else assert(false); + std::puts("PASS: HWCDC presence, real stats lease and runtime"); +} +''' + + +class HwcdcPresenceTests(unittest.TestCase): + @classmethod + def setUpClass(cls): + cls.compiler = os.environ.get('CXX') or shutil.which('g++') or shutil.which('clang++') + if cls.compiler is None: + raise unittest.SkipTest('host C++17 compiler required') + cls.directory = tempfile.TemporaryDirectory(prefix='meshcore-hwcdc-presence-') + cls.addClassCleanup(cls.directory.cleanup) + cls.folder = Path(cls.directory.name) + source = (ROOT / 'src/helpers/UsbLogging.cpp').read_text() + cls.observation = body(source, 'UsbLoggingObservation observeUsbLoggingTransport()') + cls.event = body(source, 'static void handleEsp32HwcdcEvent(') + cls.current = cls.compile_backend(cls.observation, 'current') + + @classmethod + def compile_backend(cls, observation, suffix): + prefix = backport.BackportTest().harness().split('int main(){', 1)[0] + source = cls.folder / (suffix + '.cpp') + source.write_text(prefix + HARNESS.replace('@OBSERVATION@', observation) + .replace('@EVENT@', cls.event), encoding='ascii') + runtime = cls.folder / 'UsbLoggingWatchdog.cpp' + shutil.copyfile(ROOT / 'src/helpers/UsbLoggingWatchdog.cpp', runtime) + binary = cls.folder / suffix + result = subprocess.run([ + cls.compiler, '-std=c++17', '-Wall', '-Wextra', '-Werror', + '-Wno-unused-function', '-Wno-unused-parameter', '-Wno-sign-compare', + '-pthread', *SANITIZER_FLAGS, '-DARDUINO', '-DESP32', '-DESP32_PLATFORM', + '-DARDUINO_USB_MODE=1', '-DARDUINO_USB_CDC_ON_BOOT=1', + '-DMESH_HWCDC_PINNED_TX_BACKPORT=1', + f'-I{FIXTURE / "mocks"}', f'-I{ROOT / "src/helpers"}', f'-I{ROOT / "src"}', + str(runtime), str(ROOT / 'src/helpers/UsbLoggingClientActivity.cpp'), + str(source), '-o', str(binary)], capture_output=True, text=True, timeout=60) + if result.returncode: + raise AssertionError(result.stdout + result.stderr) + return binary + + def run_cases(self, scenarios, binary=None, negative=False): + for mode in (1, 2): + for origin in (0, 0xffffffff - 1050): + for scenario in scenarios: + with self.subTest(mode=mode, origin=origin, scenario=scenario): + result = subprocess.run([str(binary or self.current), scenario, + str(mode), str(origin)], capture_output=True, + text=True, timeout=10) + if negative: + self.assertNotEqual(result.returncode, 0) + self.assertIn('transient HWCDC observation must preserve the stats lease', + result.stderr) + self.assertNotIn('AddressSanitizer:', result.stderr) + self.assertNotIn('runtime error:', result.stderr) + else: + self.assertEqual(result.returncode, 0, result.stdout + result.stderr) + self.assertIn('PASS: HWCDC presence', result.stdout) + + def test_idle_transients_preserve_lease_but_real_expiry_repairs_only_usb(self): + self.run_cases(('idle-sof', 'idle-bool')) + + def test_sustained_unplug_and_actual_bus_reset_invalidate_lease(self): + self.run_cases(('unplug', 'bus-reset')) + + def test_actual_isr_unacknowledged_fifo_remains_a_physical_stall(self): + self.run_cases(('stall',)) + + def test_original_raw_hwcdc_presence_negative_control(self): + start = self.observation.index(' // The SDK\'s five-millisecond SOF sample') + end = self.observation.index(' const size_t capacity', start) + original = self.observation[:start] + ( + ' result.host_connected = Serial.isPlugged();\n' + ' result.reader_connected = result.host_connected && bool(Serial);\n' + ) + self.observation[end:] + binary = self.compile_backend(original, 'original') + self.run_cases(('idle-sof', 'idle-bool'), binary, negative=True) + + +if __name__ == '__main__': + unittest.main()