Keep ESP32 SDK diagnostics inside the USB session boundary

.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

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,

src/helpers/UsbLogging.cpp

@@ -7,6 +7,10 @@
 #include <stdio.h>
 
 #if MESH_ESP32_HWCDC_SESSION_GUARD
+  #include "esp_log.h"
+  #include <stdarg.h>
+  #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<bool> esp32_sdk_log_lost_chunk{false};
+static std::atomic<uint32_t> 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<const Esp32SdkLogRecord*>(context);
+  if (!canWriteEsp32SdkLog(record)) return;
+  const int available = esp32_hwcdc_session_stream.availableForWrite();
+  if (available < 0 || static_cast<size_t>(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<const uint8_t*>(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<size_t>(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<size_t>(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)

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 <stddef.h>
+#include <stdint.h>
+#include <string.h>
+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 <helpers/UsbLogging.h>
+#include <helpers/NonBlockingWriteStream.h>
+#include <helpers/ArduinoSerialInterface.h>
+#include <atomic>
+#include <cassert>
+#include <cstdarg>
+#include <cstdio>
+#include <cstring>
+#include <functional>
+#include <string>
+#include <thread>
+
+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<TaskHandle_t>(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<void()> 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<size_t>(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<const char*>(data), size);
+    capacity -= static_cast<int>(size);
+    return size;
+  }
+  size_t setRxBufferSize(size_t size) { return size; }
+  size_t setTxBufferSize(size_t size) { capacity = static_cast<int>(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<int>(sizeof(output)));
+  ++stdout_calls;Serial.output.append(output, static_cast<size_t>(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<void()> 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<bool> usb_logging_enabled{false}, usb_debug_enabled{false};
+static std::atomic<bool> usb_logging_preference_known{false};
+static std::atomic<bool> 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<bool> esp32_hwcdc_rx_queue_ready{false};
+static std::atomic<uint32_t> esp32_hwcdc_access_generation{0};
+static std::atomic<uint32_t> esp32_hwcdc_allowed_generation{0};
+static std::atomic<bool> esp32_hwcdc_tx_kick_pending{false};
+struct { void notePostCleanActivity() {} } esp32_hwcdc_self_reset_guard;
+static void noteUsbLoggingTxAttempt() {}
+static std::atomic<size_t> 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<TaskHandle_t>(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<bool> 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<TaskHandle_t>(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<TaskHandle_t>(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()

test/test_esp32_usb_serial_hygiene.py

@@ -53,6 +53,7 @@ static std::atomic<unsigned> esp32_hwcdc_allowed_generation{0};
 static std::atomic<unsigned> 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;