Route nRF52 framework diagnostics through USB logging policy

docs/usb_logging_watchdog.md

@@ -60,6 +60,14 @@ configuration still use primary CDC (`*-if00`), whose stats queries do not
 prove a logging reader. Existing single-port bridges needing identity/CLI
 replies still require separate control-port support.
 
+The default nRF52 framework logger follows the same runtime USB logging and
+debug settings. Bluefruit flash-event diagnostics use the selected bounded
+logging stream, including dedicated CDC on Full Companion, so saving contacts
+does not insert ASCII into the primary Companion protocol. A disconnected or
+full logging endpoint drops diagnostic output without falling back to the
+control port. Explicit framework UART and RTT logger selections keep their
+existing destinations.
+
 ## Recovery timing and safety
 
 For a physical host/reader outage, or pending TX with no real completion,

scripts/nrf52_loop_stack_fix.py

@@ -1,10 +1,14 @@
-"""Make the nRF52 core's loop task use the configured stack even under LTO.
+"""Apply MeshCore's loop-stack and diagnostic-output policy to the nRF52 core.
 
 GNU --wrap only redirects undefined references. The pinned core and FreeRTOS
 share an LTO graph, so its xTaskCreate call can bind directly to the real
 function and silently retain the framework's 4 KiB stack. Explicitly route
 only the core loop-task call through MeshCore's existing stack policy in a
-private build copy. Never edit the shared framework package.
+private build copy. Retarget the default framework printf logger through
+MeshCore's bounded, runtime-selected diagnostic stream: raw Serial writes
+otherwise corrupt the Companion protocol, including on dual-CDC hardware.
+Explicit UART/RTT loggers retain their framework behavior. Never edit the
+shared framework package.
 """
 
 from pathlib import Path
@@ -19,6 +23,34 @@ DECLARATION = """extern "C" BaseType_t __wrap_xTaskCreate(
 
 """
 LOOP_STACK = "#define LOOP_STACK_SZ       (256*4)"
+LOGGER_ENTRY = "// nanolib printf() retarget\n"
+LOGGER_DECLARATION = """// MeshCore routes default framework diagnostics without borrowing CDC0.
+size_t meshNrf52FrameworkDebugWrite(const void* data, size_t size)
+    __attribute__((weak));
+
+"""
+OLD_LOGGER = """#else
+  if ( Serial )
+  {
+    ret = Serial.write((const uint8_t *) buf, count);
+  }
+#endif
+
+  return (int) ret;
+"""
+LOGGER = """#else
+  if ( meshNrf52FrameworkDebugWrite )
+  {
+    ret = meshNrf52FrameworkDebugWrite(buf, count);
+  }
+  else if ( Serial )
+  {
+    ret = Serial.write((const uint8_t *) buf, count);
+  }
+#endif
+
+  return (int) ret;
+"""
 
 
 def patched_source(source):
@@ -36,14 +68,29 @@ def patched_source(source):
         OLD_LOOP_CREATE, LOOP_CREATE)
 
 
+def patched_logging_source(source):
+    source = source.replace("\r\n", "\n")
+    if (source.count(LOGGER) == 1 and source.count(LOGGER_DECLARATION) == 1
+            and OLD_LOGGER not in source and source.count(LOGGER_ENTRY) == 1):
+        return source
+    if (source.count(OLD_LOGGER) != 1 or source.count(LOGGER_ENTRY) != 1
+            or LOGGER in source or LOGGER_DECLARATION in source):
+        raise RuntimeError(
+            "nRF52 framework logging fix: unrecognized printf retarget; review "
+            "the framework update before building (shared SDK not modified)"
+        )
+    return source.replace(LOGGER_ENTRY, LOGGER_DECLARATION + LOGGER_ENTRY).replace(
+        OLD_LOGGER, LOGGER)
+
+
 def replace_core(build_env, node):
     source = Path(node.srcnode().get_abspath())
-    patched = patched_source(source.read_text(encoding="utf-8"))
+    patched = patched_logging_source(patched_source(source.read_text(encoding="utf-8")))
     destination = Path(build_env.subst("$BUILD_DIR")) / "patched-nrf52-core" / "main.cpp"
     destination.parent.mkdir(parents=True, exist_ok=True)
     if not destination.exists() or destination.read_text(encoding="utf-8") != patched:
         destination.write_text(patched, encoding="utf-8")
-    print("nRF52 loop stack: explicit LTO-safe core task policy enabled")
+    print("nRF52 core: LTO-safe loop stack and routed framework diagnostics enabled")
     return build_env.File(str(destination))
 
 

src/helpers/UsbLogging.cpp

@@ -1836,6 +1836,21 @@ bool isUsbLoggingTransportRecoveryPending() {
 
 }  // namespace mesh
 
+#if defined(NRF52_PLATFORM)
+// The framework's LOG_LV1/PRINTF path otherwise writes straight to Serial,
+// bypassing both the saved debug setting and Full Companion's separate CDC1.
+// The private core retarget calls this only for its default USB logger.
+extern "C" size_t meshNrf52FrameworkDebugWrite(const void* data, size_t size) {
+  if (data == nullptr || size == 0) return 0;
+  // Diagnostics are best effort. Consume disabled/backpressured records so
+  // libc never retries them later in a different protocol/host session.
+  if (!isInISR()) {
+    (void)mesh::usbDebugPort().write(static_cast<const uint8_t*>(data), size);
+  }
+  return size;
+}
+#endif
+
 #if MESH_ESP32_HWCDC_SESSION_GUARD
 // Capture startup at the actual hardware reset, not when the finite framework
 // event queue eventually delivers it. A delayed initial enumeration event

test/test_nrf52_framework_logging.py

@@ -0,0 +1,250 @@
+"""Reproduce framework flash-event text corrupting the Companion USB stream."""
+
+import importlib.util
+from pathlib import Path
+import shutil
+import subprocess
+import tempfile
+import unittest
+
+from test_replay_reset_integration import extract_braced
+
+
+ROOT = Path(__file__).resolve().parents[1]
+SPEC = importlib.util.spec_from_file_location(
+    "nrf52_core_fix", ROOT / "scripts/nrf52_loop_stack_fix.py")
+FIX = importlib.util.module_from_spec(SPEC)
+SPEC.loader.exec_module(FIX)
+
+# The pinned Adafruit core's printf retarget, including its explicit non-USB
+# logger branches. The runtime test executes the production patch against it.
+CORE_LOGGER = """// nanolib printf() retarget
+// Logger 0: Serial (CDC), 1 Serial1 (UART), 2 Segger RTT
+int _write (int fd, const void *buf, size_t count)
+{
+  (void) fd;
+
+  size_t ret = 0;
+
+#if CFG_LOGGER == 2 || CFG_SYSVIEW
+  SEGGER_RTT_Write(0, buf, count);
+  ret = count;
+
+#elif CFG_LOGGER == 1
+  if ( Serial1 )
+  {
+    ret = Serial1.write((const uint8_t *) buf, count);
+  }
+
+#else
+  if ( Serial )
+  {
+    ret = Serial.write((const uint8_t *) buf, count);
+  }
+#endif
+
+  return (int) ret;
+}
+"""
+
+ARDUINO = """#pragma once
+#include <cstddef>
+#include <cstdint>
+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 byte) { return write(&byte, 1); }
+  virtual size_t write(const uint8_t*, size_t) = 0;
+};
+"""
+
+RUNTIME = r'''
+#include <atomic>
+#include <cassert>
+#include <cstring>
+#include <helpers/NonBlockingWriteStream.h>
+struct FakeSerial : Stream {
+  bool connected = true;
+  int capacity = 4096;
+  unsigned bytes = 0, calls = 0;
+  explicit operator bool() const { return connected; }
+  int availableForWrite() override { return connected ? capacity : 0; }
+  size_t write(const uint8_t*, size_t size) override {
+    ++calls; bytes += size; return size;
+  }
+};
+static FakeSerial Serial, Serial1, dedicated;
+static unsigned rtt_bytes = 0;
+static void SEGGER_RTT_Write(unsigned, const void*, size_t size) { rtt_bytes += size; }
+static bool in_isr = false;
+static bool isInISR() { return in_isr; }
+namespace mesh {
+static bool logging = true, debug = true, packet_stream = false;
+static bool dedicated_usb_logging_port_started = true;
+static std::atomic<bool> dedicated_usb_logging_port_connected{true};
+static bool isUsbLoggingEnabled() { return logging; }
+static bool isUsbDebugEnabled() { return debug; }
+static bool isUsbLoggingPacketStream() { return packet_stream; }
+@DEBUG_GATE@
+class NullStream : public Stream {
+ public:
+  size_t write(const uint8_t*, size_t size) override { return size; }
+};
+static NullStream null_usb_logging_stream;
+static WholeRecordNonBlockingStream<640> nonblocking_primary_usb_logging_port(Serial);
+static WholeRecordNonBlockingStream<640> nonblocking_dedicated_usb_logging_port(dedicated);
+@LOGGING_PORT@
+@DEBUG_PORT@
+}
+@HOOK@
+extern "C" {
+@CORE@
+}
+static void clear_output() {
+  Serial.bytes = Serial.calls = Serial1.bytes = Serial1.calls = 0;
+  dedicated.bytes = dedicated.calls = rtt_bytes = 0;
+}
+static const char flash_event[] = "[SOC   ] NRF_EVT_FLASH_OPERATION_SUCCESS\r\n";
+static void emit_contact_save_and_delete_events() {
+  static_assert(sizeof(flash_event) - 1 == 42, "Real captured event length");
+  for (unsigned i = 0; i < 48; ++i) {
+    assert(_write(1, flash_event, sizeof(flash_event) - 1) == 42);
+  }
+}
+int main() {
+  emit_contact_save_and_delete_events();
+#if CFG_LOGGER == 2 || CFG_SYSVIEW
+  assert(rtt_bytes == 2016 && Serial.bytes == 0 && dedicated.bytes == 0);
+#elif CFG_LOGGER == 1
+  assert(Serial1.bytes == 2016 && Serial.bytes == 0 && dedicated.bytes == 0);
+#elif !PATCHED || !WITH_HOOK
+  // Reproduce the complete 2016-byte corruption seen on the RAK4631.
+  assert(Serial.bytes == 2016 && dedicated.bytes == 0);
+#else
+  #if defined(MESH_DUAL_CDC_LOGGING)
+    assert(Serial.bytes == 0 && dedicated.bytes == 2016);
+  #else
+    // A logging-only/ASCII single-CDC role retains its selected primary route.
+    assert(Serial.bytes == 2016 && dedicated.bytes == 0);
+  #endif
+  clear_output();
+  mesh::debug = false;
+  emit_contact_save_and_delete_events();
+  assert(Serial.bytes == 0 && dedicated.bytes == 0);
+  mesh::debug = true;
+  mesh::logging = false;
+  emit_contact_save_and_delete_events();
+  assert(Serial.bytes == 0 && dedicated.bytes == 0);
+  mesh::logging = true;
+  in_isr = true;
+  emit_contact_save_and_delete_events();
+  assert(Serial.bytes == 0 && dedicated.bytes == 0);
+  in_isr = false;
+  Serial.capacity = dedicated.capacity = 0;
+  emit_contact_save_and_delete_events();
+  assert(Serial.calls == 0 && dedicated.calls == 0); // No retry/wait on a full FIFO.
+  Serial.capacity = dedicated.capacity = 4096;
+  #if defined(MESH_DUAL_CDC_LOGGING)
+    mesh::dedicated_usb_logging_port_connected.store(false);
+    emit_contact_save_and_delete_events();
+    assert(Serial.bytes == 0 && dedicated.bytes == 0); // Never fall back to CDC0.
+    mesh::dedicated_usb_logging_port_connected.store(true);
+    mesh::packet_stream = true;
+    emit_contact_save_and_delete_events();
+    assert(Serial.bytes == 2016 && dedicated.bytes == 0); // Explicit primary logging.
+    clear_output();
+    mesh::packet_stream = false;
+  #endif
+  // Dropped records report consumed; later enabling debug remains usable.
+  emit_contact_save_and_delete_events();
+  #if defined(MESH_DUAL_CDC_LOGGING)
+    assert(Serial.bytes == 0 && dedicated.bytes == 2016);
+  #else
+    assert(Serial.bytes == 2016 && dedicated.bytes == 0);
+  #endif
+  assert(_write(1, nullptr, 42) == 0);
+  assert(_write(1, flash_event, 0) == 0);
+#endif
+}
+'''
+
+
+class Nrf52FrameworkLoggingTest(unittest.TestCase):
+    def test_retarget_is_idempotent_and_rejects_changed_or_partial_core(self):
+        patched = FIX.patched_logging_source(CORE_LOGGER.replace("\n", "\r\n"))
+        self.assertEqual(FIX.patched_logging_source(patched), patched)
+        for source in (
+            CORE_LOGGER.replace("ret = Serial.write", "ret = another_writer"),
+            CORE_LOGGER.replace(FIX.OLD_LOGGER, FIX.LOGGER),
+            FIX.LOGGER_DECLARATION + CORE_LOGGER,
+            CORE_LOGGER + CORE_LOGGER,
+        ):
+            with self.subTest(source=source), self.assertRaises(RuntimeError):
+                FIX.patched_logging_source(source)
+
+    def test_existing_private_core_copy_keeps_both_policies(self):
+        source = (FIX.LOOP_STACK + "\n" + FIX.OLD_LOOP_CREATE + "\n" + CORE_LOGGER)
+        patched = FIX.patched_logging_source(FIX.patched_source(source))
+        self.assertIn(FIX.LOOP_CREATE, patched)
+        self.assertIn(FIX.LOGGER, patched)
+        self.assertEqual(FIX.patched_source(patched), patched)
+        self.assertEqual(FIX.patched_logging_source(patched), patched)
+        script = (ROOT / "scripts/nrf52_loop_stack_fix.py").read_text()
+        self.assertIn("patched_logging_source(patched_source(", script)
+
+    @unittest.skipUnless(shutil.which("c++"), "native C++ compiler unavailable")
+    def test_flash_event_corruption_then_routing_gates_and_bounded_output(self):
+        source = (ROOT / "src/helpers/UsbLogging.cpp").read_text()
+        header = (ROOT / "src/helpers/UsbLogging.h").read_text()
+        parts = {
+            "DEBUG_GATE": extract_braced(header, "inline bool isUsbDebugLoggingEnabled("),
+            "LOGGING_PORT": extract_braced(source, "Stream& usbLoggingPort("),
+            "DEBUG_PORT": extract_braced(source, "Stream& usbDebugPort("),
+        }
+        hook = extract_braced(source, 'extern "C" size_t meshNrf52FrameworkDebugWrite(')
+        # Keep the hook architecture-scoped; unrelated ESP output is unchanged.
+        self.assertIn('#if defined(NRF52_PLATFORM)\n// The framework', source)
+        with tempfile.TemporaryDirectory(prefix="meshcore-framework-log-") as temp:
+            work = Path(temp)
+            (work / "Arduino.h").write_text(ARDUINO)
+            for patched, with_hook, dual, logger, sysview in (
+                (False, True, True, 0, 0),
+                (True, True, True, 0, 0),
+                (True, True, False, 0, 0),
+                (True, False, True, 0, 0),
+                (True, True, True, 1, 0),
+                (True, True, True, 2, 0),
+                (True, True, True, 0, 1),
+            ):
+                with self.subTest(patched=patched, hook=with_hook, dual=dual,
+                                  logger=logger, sysview=sysview):
+                    generated = RUNTIME
+                    for key, value in parts.items():
+                        generated = generated.replace("@" + key + "@", value)
+                    generated = generated.replace("@HOOK@", hook if with_hook else "")
+                    generated = generated.replace("@CORE@", FIX.patched_logging_source(CORE_LOGGER)
+                                                  if patched else CORE_LOGGER)
+                    (work / "main.cpp").write_text(generated)
+                    flags = [f"-DPATCHED={int(patched)}", f"-DWITH_HOOK={int(with_hook)}",
+                             f"-DCFG_LOGGER={logger}", f"-DCFG_SYSVIEW={sysview}",
+                             "-DNRF52_PLATFORM=1"]
+                    if dual:
+                        flags.append("-DMESH_DUAL_CDC_LOGGING=1")
+                    built = subprocess.run([
+                        "c++", "-std=c++17", "-O2", "-flto", "-flto-partition=one",
+                        "-fno-semantic-interposition", "-I" + str(work),
+                        "-I" + str(ROOT / "src"), *flags, str(work / "main.cpp"),
+                        "-o", str(work / "test"),
+                    ], text=True, capture_output=True)
+                    self.assertEqual(built.returncode, 0, built.stderr)
+                    run = subprocess.run([str(work / "test")], text=True, capture_output=True, timeout=5)
+                    self.assertEqual(run.returncode, 0, run.stderr)
+
+
+if __name__ == "__main__":
+    unittest.main()