diff --git a/.github/workflows/run-unit-tests.yml b/.github/workflows/run-unit-tests.yml index d689703f3..e26814d8a 100644 --- a/.github/workflows/run-unit-tests.yml +++ b/.github/workflows/run-unit-tests.yml @@ -872,6 +872,7 @@ jobs: 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_esp32_sdk_logging.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/docs/usb_logging_watchdog.md b/docs/usb_logging_watchdog.md index 0d5ddf124..291abf888 100644 --- a/docs/usb_logging_watchdog.md +++ b/docs/usb_logging_watchdog.md @@ -68,6 +68,13 @@ full logging endpoint drops diagnostic output without falling back to the control port. Explicit framework UART and RTT logger selections keep their existing destinations. +On ESP32 USB-Serial/JTAG builds, ESP-IDF diagnostics also follow both +`usb.logging` and `usb.debug`. Driver tasks submit bounded text; the USB owner +emits it through the same session and writer guards as functional output. +Logging-off, host changes and congestion discard pending diagnostics instead +of falling back to the raw SDK console. Fragmented diagnostics from concurrent +SDK tasks remain best effort. UART and native TinyUSB routes are unchanged. + ## Recovery timing and safety For a physical host/reader outage, or pending TX with no real completion, diff --git a/src/helpers/UsbLogging.cpp b/src/helpers/UsbLogging.cpp index 8a4376f56..f5e01fd63 100644 --- a/src/helpers/UsbLogging.cpp +++ b/src/helpers/UsbLogging.cpp @@ -7,6 +7,10 @@ #include #if MESH_ESP32_HWCDC_SESSION_GUARD + #include "esp_log.h" + #include + #include "freertos/FreeRTOS.h" + #include "freertos/task.h" #include "esp_idf_version.h" #include "hal/usb_serial_jtag_ll.h" #include "esp_arduino_version.h" @@ -531,6 +535,163 @@ static AtomicWholeRecordNonBlockingStream<11> static AtomicWholeRecordNonBlockingStream<640> guarded_esp32_hwcdc_logging_port( guarded_esp32_hwcdc_port); +// ESP-IDF logs use vprintf/stdout, independently of Arduino's putc2 hook. +// In the pinned SDK stdout also writes to USB-Serial/JTAG, so disabling +// Serial.setDebugOutput() alone cannot protect a Binary Companion stream. +// SDK tasks only offer one bounded record. The USB owner emits or drops it +// before dispatching more protocol input, through the existing writer gate. +// This is best effort ASCII diagnostics: competing fragmented lines or a full +// slot can be discarded through the next newline. Never fall back to the +// unguarded SDK console or retain a transport retry for another host. +#if MESH_USB_LOGGING_AVAILABLE +struct Esp32SdkLogRecord { + char data[640]; + size_t size = 0; + uint32_t session = 0; + uint32_t epoch = 0; + TaskHandle_t producer = nullptr; + bool ready = false; + bool discarding = false; +}; +static Esp32SdkLogRecord esp32_sdk_log_record; +static std::atomic_flag esp32_sdk_log_busy = ATOMIC_FLAG_INIT; +static std::atomic esp32_sdk_log_lost_chunk{false}; +static std::atomic esp32_sdk_log_epoch{0}; +static TaskHandle_t esp32_sdk_log_owner = nullptr; + +static bool canWriteEsp32SdkLog(const Esp32SdkLogRecord& record) { + return isUsbDebugLoggingEnabled() && canAccessEsp32Hwcdc(nullptr) + && record.session == esp32_hwcdc_access_generation.load(std::memory_order_acquire) + && record.epoch == esp32_sdk_log_epoch.load(std::memory_order_acquire); +} + +static void clearEsp32SdkLogRecord(bool discard_incomplete) { + auto& record = esp32_sdk_log_record; + record.discarding = discard_incomplete && + (record.discarding || (record.size != 0 && !record.ready)); + record.size = 0; + record.ready = false; + record.producer = nullptr; +} +#endif + +static void invalidateEsp32SdkLogging() { +#if MESH_USB_LOGGING_AVAILABLE + // An off/on pair before the next loop must not revive an older record. + esp32_sdk_log_epoch.fetch_add(1, std::memory_order_acq_rel); + if (!esp32_sdk_log_busy.test_and_set(std::memory_order_acquire)) { + clearEsp32SdkLogRecord(true); + esp32_sdk_log_busy.clear(std::memory_order_release); + } +#endif +} + +#if MESH_USB_LOGGING_AVAILABLE +static void writeEsp32SdkLogRecord(void* context) { + const auto& record = *static_cast(context); + if (!canWriteEsp32SdkLog(record)) return; + const int available = esp32_hwcdc_session_stream.availableForWrite(); + if (available < 0 || static_cast(available) < record.size) return; + if (!canWriteEsp32SdkLog(record)) return; + // The gate excludes every other application writer, and the ISR can only + // free TX capacity. Once admitted, this whole record finishes before this + // same USB owner can handle an ASCII/Binary protocol change. + (void)esp32_hwcdc_session_stream.write( + reinterpret_cast(record.data), record.size); +} +#endif + +static int writeEsp32SdkLog(const char* format, va_list args) { +#if MESH_USB_LOGGING_AVAILABLE + if (format == nullptr || xPortInIsrContext() + || !isUsbDebugLoggingEnabled()) return 0; + // No wait, heap allocation or USB write from an SDK task. Formatting under + // this try gate also rejects recursion and concurrent diagnostic producers. + if (esp32_sdk_log_busy.test_and_set(std::memory_order_acquire)) { + esp32_sdk_log_lost_chunk.store(true, std::memory_order_release); + return 0; + } + auto& record = esp32_sdk_log_record; + if (esp32_sdk_log_lost_chunk.exchange(false, std::memory_order_acq_rel)) { + clearEsp32SdkLogRecord(false); + record.discarding = true; + } + if ((record.size != 0 || record.discarding) && !canWriteEsp32SdkLog(record)) + clearEsp32SdkLogRecord(true); + const TaskHandle_t producer = xTaskGetCurrentTaskHandle(); + if (record.ready || (record.producer != nullptr && record.producer != producer)) { + esp32_sdk_log_lost_chunk.store(true, std::memory_order_release); + esp32_sdk_log_busy.clear(std::memory_order_release); + return 0; + } + if (record.size == 0) { + record.session = esp32_hwcdc_access_generation.load(std::memory_order_acquire); + record.epoch = esp32_sdk_log_epoch.load(std::memory_order_acquire); + record.producer = producer; + } + // WiFi emits prefix, body and newline in separate SDK calls. Assemble them + // without exposing an incomplete line or mixing a different task's line. + const size_t offset = record.discarding ? 0 : record.size; + const int length = vsnprintf(record.data + offset, + sizeof(record.data) - offset, format, args); + const bool fits = length >= 0 + && static_cast(length) < sizeof(record.data) - offset; + const bool newline = fits && length > 0 && record.data[offset + length - 1] == '\n'; + if (!canWriteEsp32SdkLog(record) || record.discarding || !fits) { + record.size = 0; + record.ready = false; + // An oversized/in-flight old line is consumed through its next newline, + // including its separately formatted suffix, before accepting a new one. + record.discarding = !newline; + if (!record.discarding) record.producer = nullptr; + } else { + record.size += static_cast(length); + record.ready = newline; + if (record.size == 0) record.producer = nullptr; + } + esp32_sdk_log_busy.clear(std::memory_order_release); + return length > 0 ? length : 0; +#else + // Near-budget roles which compile diagnostics out need neither a buffer nor + // a formatter. The SDK's secondary console still must not leak raw bytes. + (void)format; + (void)args; + return 0; +#endif +} + +static void serviceEsp32SdkLogging() { +#if MESH_USB_LOGGING_AVAILABLE + if (xPortInIsrContext() || xTaskGetCurrentTaskHandle() != esp32_sdk_log_owner + || esp32_sdk_log_busy.test_and_set(std::memory_order_acquire)) return; + auto& record = esp32_sdk_log_record; + if (esp32_sdk_log_lost_chunk.exchange(false, std::memory_order_acq_rel)) { + clearEsp32SdkLogRecord(false); + record.discarding = true; + } + if ((record.size != 0 || record.discarding) && !canWriteEsp32SdkLog(record)) + clearEsp32SdkLogRecord(true); + if (record.ready) { + (void)guarded_esp32_hwcdc_port.tryRunExclusive( + writeEsp32SdkLogRecord, &record); + // One owner-loop attempt only. Congestion/session changes drop a record; + // no suffix or retry can cross a later host or protocol boundary. + clearEsp32SdkLogRecord(false); + } + esp32_sdk_log_busy.clear(std::memory_order_release); +#endif +} + +static void installEsp32SdkLogging() { + static bool installed = false; // Called only by the setup/USB owner. + if (installed) return; +#if MESH_USB_LOGGING_AVAILABLE + esp32_sdk_log_owner = xTaskGetCurrentTaskHandle(); +#endif + esp_log_set_vprintf(writeEsp32SdkLog); + installed = true; +} + static void serviceEsp32HwcdcTxKickExclusive(void*) { if (!esp32_hwcdc_tx_kick_pending.load(std::memory_order_acquire) || !canAccessEsp32Hwcdc(nullptr)) { @@ -1094,11 +1255,17 @@ bool isUsbDebugEnabled() { void setUsbDebugEnabled(bool enabled) { usb_debug_enabled.store(enabled, std::memory_order_relaxed); +#if MESH_ESP32_HWCDC_SESSION_GUARD + if (!enabled) invalidateEsp32SdkLogging(); +#endif setPlatformDebugOutputEnabled(isUsbDebugLoggingEnabled()); } void setUsbLoggingEnabled(bool enabled) { usb_logging_enabled.store(enabled, std::memory_order_relaxed); +#if MESH_ESP32_HWCDC_SESSION_GUARD + if (!enabled) invalidateEsp32SdkLogging(); +#endif if (!enabled) { clearUsbLoggingClientActivity(); usb_logging_tx_waiting.store(false, std::memory_order_release); @@ -1135,6 +1302,9 @@ void setUsbCompanionTxBufferCapacity(size_t capacity) { void prepareUsbLoggingPort() { #if MESH_ESP32_HWCDC_SESSION_GUARD + // Install before board/wireless startup, including any asynchronous WiFi + // diagnostics which arrive after a later WiFi shutdown has completed. + installEsp32SdkLogging(); // The SDK's 256-byte default can lose the CR of an oversized ASCII setter // before the Companion's line-length check can reject it. Retain an // oversized command and exceed the terminal's 542-byte line buffer so @@ -1227,6 +1397,7 @@ void serviceUsbLoggingPort() { #if MESH_ESP32_TINYUSB_NONBLOCKING serviceEsp32TinyUsbPorts(); #elif MESH_ESP32_HWCDC_SESSION_GUARD + serviceEsp32SdkLogging(); serviceEsp32HwcdcTxKick(); #endif #if defined(MESH_DUAL_CDC_LOGGING) diff --git a/test/test_esp32_sdk_logging.py b/test/test_esp32_sdk_logging.py new file mode 100644 index 000000000..b9006b55c --- /dev/null +++ b/test/test_esp32_sdk_logging.py @@ -0,0 +1,447 @@ +"""Run the actual SDK sink, native-USB guard and Companion frame writer.""" +from pathlib import Path +import os +import shutil +import subprocess +import tempfile +import unittest + +from cpp_source import body +from test_serial_wifi_sessions import SANITIZER_FLAGS + + +ROOT = Path(__file__).resolve().parents[1] +ARDUINO = r''' +#pragma once +#include +#include +#include +inline uint32_t millis() { return 100; } +class Stream { + public: + virtual ~Stream() = default; + virtual int available() { return 0; } + virtual int read() { return -1; } + virtual int peek() { return -1; } + virtual void flush() {} + virtual int availableForWrite() { return 0; } + virtual size_t write(uint8_t value) { return write(&value, 1); } + virtual size_t write(const uint8_t*, size_t) = 0; +}; +''' + +RUNTIME = r''' +#include +#include +#include +#include +#include +#include +#include +#include +#include +#include +#include + +static thread_local bool in_isr = false; +static bool xPortInIsrContext() { return in_isr; } +using TaskHandle_t = void*; +static thread_local TaskHandle_t current_task = reinterpret_cast(2); +static TaskHandle_t xTaskGetCurrentTaskHandle() { return current_task; } +static unsigned sdk_installs = 0, stdout_calls = 0; +static bool wireless_started = false; +static int emit_sdk(const char* format, ...); +struct SerialMock : Stream { + int capacity = 4096; + unsigned writes = 0, debug_changes = 0; + bool debug = false; + std::string output; + std::function on_capacity, on_write; + int availableForWrite() override { + if (on_capacity) { + const auto run = std::move(on_capacity);on_capacity = nullptr;run(); + } + return capacity; + } + size_t write(const uint8_t* data, size_t size) override { + assert(size <= static_cast(capacity) && "SDK sink must never wait"); + if (on_write) { + const auto run = std::move(on_write);on_write = nullptr;run(); + } + ++writes;output.append(reinterpret_cast(data), size); + capacity -= static_cast(size); + return size; + } + size_t setRxBufferSize(size_t size) { return size; } + size_t setTxBufferSize(size_t size) { capacity = static_cast(size);return size; } + void setTxTimeoutMs(unsigned value) { assert(value == 5); } + void setDebugOutput(bool value) { ++debug_changes;debug = value; } + void clear() { assert(!on_capacity && !on_write);capacity = 4096;writes = 0;output.clear(); } +} Serial; +using vprintf_like_t = int (*)(const char*, va_list); +static int sdk_stdout(const char* format, va_list args) { + // The pinned SDK console has secondary USB_SERIAL_JTAG enabled. Its VFS + // writer bypasses Arduino's setDebugOutput(false) and all protocol guards. + char output[1024]; + const int length = vsnprintf(output, sizeof(output), format, args); + assert(length >= 0 && length < static_cast(sizeof(output))); + ++stdout_calls;Serial.output.append(output, static_cast(length)); + return length; +} +static vprintf_like_t sdk_sink = sdk_stdout; +static vprintf_like_t esp_log_set_vprintf(vprintf_like_t next) { + assert(!wireless_started && "SDK sink must be installed before WiFi startup"); + ++sdk_installs;const auto previous = sdk_sink;sdk_sink = next;return previous; +} +static int emit_sdk(const char* format, ...) { + va_list args;va_start(args, format); + const int result = sdk_sink(format, args); + va_end(args);return result; +} +static std::function during_format; +static unsigned formatter_calls = 0; +static int sdk_format(char* dest, size_t size, const char* format, va_list args) { + ++formatter_calls; + if (during_format) { + const auto run = std::move(during_format);during_format = nullptr;run(); + } + return vsnprintf(dest, size, format, args); +} + +namespace mesh { +static std::atomic usb_logging_enabled{false}, usb_debug_enabled{false}; +static std::atomic usb_logging_preference_known{false}; +static std::atomic usb_logging_tx_waiting{false}; +@GATES@ +static void clearUsbLoggingClientActivity() {} +#if MESH_ESP32_HWCDC_SESSION_GUARD +static void invalidateEsp32SdkLogging(); +#endif +@PLATFORM_DEBUG@ +@SETTERS@ +#if MESH_ESP32_HWCDC_SESSION_GUARD +static std::atomic esp32_hwcdc_rx_queue_ready{false}; +static std::atomic esp32_hwcdc_access_generation{0}; +static std::atomic esp32_hwcdc_allowed_generation{0}; +static std::atomic esp32_hwcdc_tx_kick_pending{false}; +struct { void notePostCleanActivity() {} } esp32_hwcdc_self_reset_guard; +static void noteUsbLoggingTxAttempt() {} +static std::atomic esp32_hwcdc_tx_buffer_capacity{0}; +@ACCESS@ +#define vsnprintf sdk_format +@BACKEND@ +#undef vsnprintf +#endif +@CAPACITY@ +@PREPARE@ +} + +static constexpr char late_probe[] = + "E (2905571) wifi:timeout when WiFi un-init, type=4\r\n"; +static void late_wifi_probe() { + // Exact pinned WiFi logger shape: prefix, body and newline are three calls. + emit_sdk("E (%u) wifi:", 2905571U); + emit_sdk("%s, type=%d", "timeout when WiFi un-init", 4); + emit_sdk("\r\n"); +} + +int main(int argc, char** argv) { + assert(argc == 2);const std::string scenario = argv[1]; + current_task = reinterpret_cast(1); + mesh::prepareUsbLoggingPort(); + mesh::setUsbDebugEnabled(true); + mesh::setUsbLoggingEnabled(false); + assert(!Serial.debug); + wireless_started = true; +#if !MESH_ESP32_HWCDC_SESSION_GUARD + assert(scenario == "scope" && sdk_installs == 0); + late_wifi_probe(); + assert(stdout_calls == 3 && Serial.output == late_probe); + std::puts("PASS: unrelated SDK logger is unchanged"); +#else +#if !MESH_USB_LOGGING_AVAILABLE + assert(scenario == "compiled-out"); + mesh::setUsbLoggingEnabled(true);late_wifi_probe(); + mesh::serviceEsp32SdkLogging(); + assert(Serial.output.empty() && !formatter_calls && !stdout_calls); + std::puts("PASS: compiled-out SDK logs use no formatter or buffer");return 0; +#else + if (scenario == "binary-late") { + ArduinoSerialInterface companion; + companion.begin(mesh::guarded_esp32_hwcdc_port); + companion.enableFlowControl(true);companion.enable(); + const uint8_t reply[] = {0, 7, 9}; + const std::string framed(">\x03\x00\x00\x07\x09", 6); + assert(companion.writeFrame(reply, sizeof(reply)) == sizeof(reply)); + assert(Serial.output == framed && !companion.hasPendingIO()); + // Reproduce the captured race: a complete valid response is followed by + // an asynchronous WiFi timer log after its successful shutdown command. + std::thread timer(late_wifi_probe);timer.join(); + mesh::serviceEsp32SdkLogging(); + assert(Serial.output == framed + && "SDK diagnostics must not append to Binary Companion"); + assert(companion.writeFrame(reply, sizeof(reply)) == sizeof(reply)); + assert(Serial.output == framed + framed && !stdout_calls); + } else { + assert(sdk_installs == 1); + // Setup retries do not replace a caller's selected sink repeatedly. + mesh::installEsp32SdkLogging();assert(sdk_installs == 1); + if (scenario == "gates") { + mesh::setUsbDebugEnabled(false);mesh::setUsbLoggingEnabled(true); + late_wifi_probe();mesh::serviceEsp32SdkLogging();assert(Serial.output.empty()); + mesh::setUsbDebugEnabled(true);mesh::setUsbLoggingEnabled(false); + late_wifi_probe();mesh::serviceEsp32SdkLogging();assert(Serial.output.empty()); + mesh::setUsbLoggingEnabled(true);late_wifi_probe(); + assert(Serial.output.empty());mesh::serviceEsp32SdkLogging(); + assert(Serial.output == late_probe);Serial.clear(); + in_isr = true;late_wifi_probe();in_isr = false; + mesh::serviceEsp32SdkLogging(); + assert(Serial.output.empty()); + mesh::esp32_hwcdc_access_generation.fetch_add(1); + late_wifi_probe();mesh::serviceEsp32SdkLogging();assert(Serial.output.empty()); + mesh::esp32_hwcdc_allowed_generation.store(1); + late_wifi_probe();mesh::serviceEsp32SdkLogging();assert(Serial.output == late_probe); + } else if (scenario == "bounded") { + mesh::setUsbLoggingEnabled(true); + Serial.capacity = sizeof(late_probe) - 2; + late_wifi_probe();mesh::serviceEsp32SdkLogging(); + assert(Serial.output.empty() && !Serial.writes); + Serial.capacity = 4096; + mesh::serviceEsp32SdkLogging();assert(Serial.output.empty()); + const std::string maximum = std::string(638, 'x') + '\n'; + const std::string oversized = std::string(639, 'y') + '\n'; + assert(emit_sdk("%s", maximum.c_str()) == 639); + mesh::serviceEsp32SdkLogging(); + assert(Serial.output == maximum && Serial.writes == 1);Serial.clear(); + assert(emit_sdk("%s", oversized.c_str()) == 640); + mesh::serviceEsp32SdkLogging(); + assert(Serial.output.empty() && !Serial.writes); + emit_sdk("\n"); // Consume the overlong line through a known boundary. + assert(emit_sdk("") == 0 && emit_sdk(nullptr) == 0); + late_wifi_probe();mesh::serviceEsp32SdkLogging();assert(Serial.output == late_probe); + } else if (scenario == "gate-during-capacity") { + mesh::setUsbLoggingEnabled(true); + Serial.on_capacity = [] { mesh::setUsbLoggingEnabled(false); }; + late_wifi_probe();mesh::serviceEsp32SdkLogging(); + assert(Serial.output.empty() && !Serial.writes); + mesh::setUsbLoggingEnabled(true);late_wifi_probe();mesh::serviceEsp32SdkLogging(); + assert(Serial.output == late_probe); + } else if (scenario == "reset-during-capacity") { + mesh::setUsbLoggingEnabled(true); + Serial.on_capacity = [] { mesh::esp32_hwcdc_access_generation.fetch_add(1); }; + late_wifi_probe();mesh::serviceEsp32SdkLogging(); + assert(Serial.output.empty() && !Serial.writes); + mesh::esp32_hwcdc_allowed_generation.store(1); + late_wifi_probe();mesh::serviceEsp32SdkLogging();assert(Serial.output == late_probe); + } else if (scenario == "reentrant") { + mesh::setUsbLoggingEnabled(true); + during_format = [] { late_wifi_probe(); }; + late_wifi_probe();assert(Serial.output.empty());mesh::serviceEsp32SdkLogging(); + assert(Serial.output.empty()); + late_wifi_probe();mesh::serviceEsp32SdkLogging(); + assert(Serial.output == late_probe && Serial.writes == 1);Serial.clear(); + Serial.on_write = [] { late_wifi_probe(); }; + late_wifi_probe();mesh::serviceEsp32SdkLogging(); + assert(Serial.output == late_probe && Serial.writes == 1); + } else if (scenario == "concurrent") { + mesh::setUsbLoggingEnabled(true); + std::atomic writing{false}, second_finished{false}; + during_format = [&] { + writing.store(true); + while (!second_finished.load()) std::this_thread::yield(); + }; + std::thread first(late_wifi_probe); + std::thread second([&] { + current_task = reinterpret_cast(3); + while (!writing.load()) std::this_thread::yield(); + late_wifi_probe();second_finished.store(true); + }); + first.join();second.join(); + assert(Serial.output.empty());mesh::serviceEsp32SdkLogging(); + assert(Serial.output.empty()); + late_wifi_probe();mesh::serviceEsp32SdkLogging(); + assert(Serial.output == late_probe && Serial.writes == 1); + } else if (scenario == "owner") { + mesh::setUsbLoggingEnabled(true); + std::thread timer(late_wifi_probe);timer.join(); + std::thread other([] { mesh::serviceEsp32SdkLogging(); });other.join(); + assert(Serial.output.empty());mesh::serviceEsp32SdkLogging(); + assert(Serial.output == late_probe); + } else if (scenario == "epochs") { + mesh::setUsbLoggingEnabled(true); + late_wifi_probe();mesh::setUsbLoggingEnabled(false);mesh::setUsbLoggingEnabled(true); + mesh::serviceEsp32SdkLogging();assert(Serial.output.empty()); + late_wifi_probe();mesh::setUsbDebugEnabled(false);mesh::setUsbDebugEnabled(true); + mesh::serviceEsp32SdkLogging();assert(Serial.output.empty()); + late_wifi_probe();mesh::esp32_hwcdc_access_generation.fetch_add(1); + mesh::esp32_hwcdc_allowed_generation.store(1); + mesh::serviceEsp32SdkLogging();assert(Serial.output.empty()); + late_wifi_probe();mesh::serviceEsp32SdkLogging();assert(Serial.output == late_probe); + } else if (scenario == "format-epochs") { + mesh::setUsbLoggingEnabled(true); + during_format = [] { mesh::setUsbLoggingEnabled(false);mesh::setUsbLoggingEnabled(true); }; + late_wifi_probe();mesh::serviceEsp32SdkLogging();assert(Serial.output.empty()); + during_format = [] { mesh::esp32_hwcdc_access_generation.fetch_add(1); + mesh::esp32_hwcdc_allowed_generation.store(1); }; + late_wifi_probe();mesh::serviceEsp32SdkLogging();assert(Serial.output.empty()); + late_wifi_probe();mesh::serviceEsp32SdkLogging();assert(Serial.output == late_probe); + } else if (scenario == "partial") { + mesh::setUsbLoggingEnabled(true); + emit_sdk("E (%u) wifi:", 2905571U);mesh::serviceEsp32SdkLogging(); + assert(Serial.output.empty()); + emit_sdk("timeout when WiFi un-init, type=%d", 4);mesh::serviceEsp32SdkLogging(); + assert(Serial.output.empty()); + emit_sdk("\r\n");mesh::serviceEsp32SdkLogging(); + assert(Serial.output == late_probe); + } else if (scenario == "lost-chunk") { + mesh::setUsbLoggingEnabled(true); + emit_sdk("E (%u) wifi:", 2905571U); + assert(!mesh::esp32_sdk_log_busy.test_and_set()); + emit_sdk("timeout when WiFi un-init, type=%d", 4); // Owner has the slot. + mesh::esp32_sdk_log_busy.clear(); + emit_sdk("\r\n");mesh::serviceEsp32SdkLogging();assert(Serial.output.empty()); + late_wifi_probe();mesh::serviceEsp32SdkLogging();assert(Serial.output == late_probe); + } else if (scenario == "stale-producer") { + mesh::setUsbLoggingEnabled(true); + during_format = [] { mesh::setUsbLoggingEnabled(false);mesh::setUsbLoggingEnabled(true); }; + emit_sdk("prefix without newline"); + // The original task never finishes its old line. A different producer + // must recover at a newline rather than remain locked out forever. + std::thread other([] { current_task = reinterpret_cast(3); + emit_sdk("\n");late_wifi_probe(); });other.join(); + mesh::serviceEsp32SdkLogging();assert(Serial.output == late_probe); + } else if (scenario == "shared-writer") { + mesh::setUsbLoggingEnabled(true); + ArduinoSerialInterface companion; + companion.begin(mesh::guarded_esp32_hwcdc_port); + companion.enableFlowControl(true);companion.enable(); + const uint8_t reply[] = {0, 7, 9}; + const std::string framed(">\x03\x00\x00\x07\x09", 6); + Serial.on_capacity = [&] { + assert(companion.writeFrame(reply, sizeof(reply)) == sizeof(reply)); + assert(companion.hasPendingIO() && Serial.output.empty()); + }; + late_wifi_probe();mesh::serviceEsp32SdkLogging();assert(Serial.output == late_probe); + mesh::setUsbLoggingEnabled(false); + companion.loop();assert(!companion.hasPendingIO()); + assert(Serial.output == std::string(late_probe) + framed); + } else assert(false); + assert(!stdout_calls && !Serial.debug); + } + std::puts("PASS: SDK sink and actual USB/Companion writer"); +#endif +#endif +} +''' + + +class Esp32SdkLoggingTests(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.temp = tempfile.TemporaryDirectory(prefix='meshcore-sdk-logging-') + cls.addClassCleanup(cls.temp.cleanup) + cls.folder = Path(cls.temp.name) + (cls.folder / 'Arduino.h').write_text(ARDUINO, encoding='ascii') + cls.source = (ROOT / 'src/helpers/UsbLogging.cpp').read_text() + start = cls.source.index('class Esp32HwcdcSessionStream :') + stop = cls.source.index('static void serviceEsp32HwcdcTxKickExclusive(', start) + cls.parts = { + 'GATES': '\n'.join(body(cls.source, signature) for signature in ( + 'bool isUsbLoggingEnabled()', 'bool isUsbDebugEnabled()')), + 'PLATFORM_DEBUG': body(cls.source, 'static void setPlatformDebugOutputEnabled('), + 'SETTERS': '\n'.join(body(cls.source, signature) for signature in ( + 'void setUsbDebugEnabled(', 'void setUsbLoggingEnabled(')), + 'ACCESS': body(cls.source, 'static bool canAccessEsp32Hwcdc('), + 'BACKEND': cls.source[start:stop], + 'CAPACITY': body(cls.source, 'void setUsbCompanionTxBufferCapacity('), + 'PREPARE': body(cls.source, 'void prepareUsbLoggingPort()'), + } + cls.current = cls.compile('current') + + @classmethod + def compile(cls, suffix, legacy=False, mode=1, cdc=1, logging=True): + rendered = RUNTIME + parts = dict(cls.parts) + if legacy: + original = ' installEsp32SdkLogging();\n' + assert parts['PREPARE'].count(original) == 1 + parts['PREPARE'] = parts['PREPARE'].replace(original, '') + for name, text in parts.items(): + rendered = rendered.replace('@' + name + '@', text) + source = cls.folder / (suffix + '.cpp') + source.write_text(rendered, encoding='ascii') + binary = cls.folder / suffix + result = subprocess.run([ + cls.compiler, '-std=c++17', '-Wall', '-Wextra', '-Werror', + '-Wno-unused-function', '-Wno-unused-variable', '-pthread', + *SANITIZER_FLAGS, '-DARDUINO', '-DESP32', '-DESP32_PLATFORM', + f'-DARDUINO_USB_MODE={mode}', f'-DARDUINO_USB_CDC_ON_BOOT={cdc}', + '-DMESH_DEBUG=1', f'-I{cls.folder}', f'-I{ROOT / "src"}', + *([] if logging else ['-DMESH_USB_LOGGING_DISABLED=1']), + str(source), str(ROOT / 'src/helpers/ArduinoSerialInterface.cpp'), + '-o', str(binary)], capture_output=True, text=True, timeout=60) + if result.returncode: + raise AssertionError(result.stdout + result.stderr) + return binary + + def test_actual_sink_preserves_binary_gates_bounds_sessions_and_concurrent_writers(self): + for scenario in ('binary-late', 'gates', 'bounded', 'gate-during-capacity', + 'reset-during-capacity', 'reentrant', 'concurrent', 'owner', + 'epochs', 'format-epochs', 'partial', 'lost-chunk', + 'stale-producer', 'shared-writer'): + with self.subTest(scenario=scenario): + result = subprocess.run([str(self.current), scenario], capture_output=True, + text=True, timeout=10) + self.assertEqual(result.returncode, 0, result.stdout + result.stderr) + self.assertIn('PASS: SDK sink', result.stdout) + + def test_original_arduino_debug_hook_deterministically_corrupts_binary_tail(self): + original = self.compile('original', legacy=True) + result = subprocess.run([str(original), 'binary-late'], capture_output=True, + text=True, timeout=10) + self.assertNotEqual(result.returncode, 0) + self.assertIn('SDK diagnostics must not append to Binary Companion', result.stderr) + self.assertNotIn('AddressSanitizer:', result.stderr) + self.assertNotIn('runtime error:', result.stderr) + + def test_uart_and_tinyusb_console_routes_are_unchanged(self): + for name, mode, cdc in (('uart', 1, 0), ('tinyusb', 0, 1)): + with self.subTest(console=name): + binary = self.compile(name, mode=mode, cdc=cdc) + result = subprocess.run([str(binary), 'scope'], capture_output=True, + text=True, timeout=10) + self.assertEqual(result.returncode, 0, result.stdout + result.stderr) + self.assertIn('unrelated SDK logger is unchanged', result.stdout) + + def test_compiled_out_diagnostics_install_constant_drop_without_buffer(self): + binary = self.compile('compiled-out', logging=False) + result = subprocess.run([str(binary), 'compiled-out'], capture_output=True, + text=True, timeout=10) + self.assertEqual(result.returncode, 0, result.stdout + result.stderr) + self.assertIn('no formatter or buffer', result.stdout) + nm = shutil.which('nm') + if nm: + symbols = subprocess.run([nm, '-C', str(binary)], capture_output=True, + text=True, check=True).stdout + self.assertNotIn('esp32_sdk_log_record', symbols) + + def test_all_native_usb_roles_install_before_board_or_wifi_start(self): + for role in ('companion_radio', 'simple_repeater', 'simple_room_server', 'simple_sensor'): + with self.subTest(role=role): + source = (ROOT / 'examples' / role / 'main.cpp').read_text() + setup = source[source.index('void setup() {'):] + self.assertLess(setup.index('mesh::prepareUsbLoggingPort();'), + setup.index('board.begin();')) + self.assertLess(self.parts['PREPARE'].index('installEsp32SdkLogging();'), + self.parts['PREPARE'].index('Serial.setRxBufferSize(')) + service = body(self.source, 'void serviceUsbLoggingPort()') + self.assertIn('serviceEsp32SdkLogging();', service) + self.assertLess(service.index('serviceEsp32SdkLogging();'), + service.index('serviceEsp32HwcdcTxKick();')) + + +if __name__ == '__main__': + unittest.main() diff --git a/test/test_esp32_usb_serial_hygiene.py b/test/test_esp32_usb_serial_hygiene.py index 375319c32..0a24ca7e5 100644 --- a/test/test_esp32_usb_serial_hygiene.py +++ b/test/test_esp32_usb_serial_hygiene.py @@ -53,6 +53,7 @@ static std::atomic esp32_hwcdc_allowed_generation{0}; static std::atomic esp32_hwcdc_access_generation{0}; static size_t tx_capacity=0; static void setUsbCompanionTxBufferCapacity(size_t capacity) { tx_capacity=capacity; } +static void installEsp32SdkLogging() {} struct SerialMock { bool live=false, fail_rx=false; size_t rx=0, rx_calls=0, tx=0, timeout=0;