Add opt-in nRF52 Bluetooth event diagnostics and USB capture

.github/workflows/run-unit-tests.yml

@@ -252,6 +252,8 @@ jobs:
           python3 -B test/test_cascade_release_package.py
           python3 -B test/test_t096_full_memory.py
           python3 -B test/test_nrf52_ble_startup.py
+          python3 -B test/test_nrf52_ble_trace.py
+          python3 -B test/test_nrf52_ble_debug_tools.py
           python3 -B test/test_nrf52_usb_power.py
           python3 -B test/test_shared_mota_queue.py
 

docs/nrf52_bluetooth_debug.md

@@ -0,0 +1,96 @@
+# nRF52 Companion Bluetooth diagnostic firmware
+
+The T1000-E diagnostic image is Full Companion firmware with the normal radio,
+sensor, pairing and recovery settings. Diagnostics are enabled with
+MESH_NRF52_BLE_TRACE=1. Ordinary builds compile them out. Diagnostic builds
+reserve about 6.3 KB of RAM for a 256-event ring and counters.
+
+The trace records connection timing, security results, UART notification
+subscriptions, app receive/transmit lengths, queue overflow, local disconnect
+requests and each recovery trigger. It brackets Bluefruit's real event
+dispatcher so a handler that stalls can be distinguished from an event that
+never reached the framework. Maximum dispatch duration and Companion loop
+gaps are also reported. Callbacks write bounded RAM records without serial
+printing or allocation. PINs, keys, peer addresses and message contents are
+not stored.
+
+## Capture a phone failure
+
+1. Install the diagnostic UF2 for your exact board, or use its application DFU
+   ZIP. This does not require replacing the bootloader.
+2. Connect with the phone normally and reproduce the failure. Keep the node
+   powered. Do not forget the Bluetooth device, reboot, or factory reset
+   before collecting the trace.
+3. Connect the node's USB cable to a computer and close other serial clients.
+   Install Python and pyserial if needed.
+4. Export the diagnostic report:
+
+   ~~~sh
+   python3 scripts/capture_nrf52_ble_debug.py --port /dev/ttyACM0 --output bluetooth-report.json
+   ~~~
+
+   On Windows use the correct COM port instead of /dev/ttyACM0. The exporter
+   enters the Full Companion USB terminal at 115200 baud, reads diagnostics,
+   then returns it to binary mode. It does not reset or change settings.
+5. Send the JSON report with the approximate failure time and what the phone
+   displayed. Export soon after failure because old events roll out of the
+   ring. Reboot or loss of power clears the RAM history.
+
+If the Pi's attached T1000-E is used, its serial identity is
+34A9141999729D5D. Identify the physical board before flashing; an upstream
+application may have the misleading USB product name T1000-E-BOOT.
+
+## Manual USB commands
+
+- get bluetooth.trace: format, latest sequence, capacity and dropped writes.
+- get bluetooth.trace.state: advertising, connection, security, UART
+  notification state, MTU, app traffic and queues.
+- get bluetooth.trace.stats: cumulative connects, disconnects, secured
+  sessions, RX/TX operations and last disconnect reason/time.
+- get bluetooth.trace.timing: uptime, maximum loop gap, maximum stack
+  dispatch time and any currently executing event.
+- get bluetooth.trace N: one record by sequence.
+
+The debug commands are restricted to local Companion transport requests and
+are not exposed through remote mesh management. Replies and raw records are
+decoded by the exporter. Sequence gaps and overwritten records are reported.
+Diagnostic contention is counted and dropped rather than blocking BLE.
+
+## Reading the result
+
+| Evidence | Stage identified |
+| --- | --- |
+| No stack connection event; advertising remains active | Connection has not reached the application's Bluetooth event layer. |
+| Connection but security error or timeout | Pairing or encryption setup. |
+| Secured link but UART notifications disabled | Notification subscription or restoration. |
+| Secured link with no app RX; secured_no_app_watchdog | App never opened its Companion UART session; the 15-second recovery fired. |
+| App RX followed by blocked/partial TX | Reply delivery; the report identifies the queue/watchdog result. |
+| Dispatch entry with no matching exit and increasing age | Software stack handler may be stuck; correlate with a later snapshot. |
+
+Reason 0x08 is connection timeout, 0x16 is local termination and 0x3e
+is connection establishment failure. Do not confuse decimal 22 (0x16)
+with hexadecimal 0x22 (link-layer response timeout).
+
+The report can identify the failing software stage, but cannot guarantee the
+physical cause. No connection event alone cannot separate a central
+controller problem, RF interference and a peripheral controller problem.
+Dispatch timing starts after the SoftDevice delivers an event; it does not
+measure radio interrupt latency. A bench failure is not proof of the same
+failure on an iPhone. Use the diagnostic image on the affected node.
+
+## Build
+
+Run one PlatformIO command at a time in this checkout:
+
+~~~sh
+PLATFORMIO_BUILD_FLAGS='-DMESH_NRF52_BLE_TRACE=1 -DBLE_DEBUG_LOGGING=0 -g3' \
+OUTPUT_DIR=out/t1000e-ble-debug \
+bash build.sh build-firmware t1000e_companion_radio_full \
+  --firmware-version v1.18.0.1-halo-keymind-cascade-dev-ble-debug --full
+~~~
+
+The Bluefruit dispatch hooks are applied to private build copies of framework
+sources. The shared PlatformIO framework cache is not modified. Retain the
+ELF alongside the UF2/ZIP for future SWD inspection if hardware access becomes
+available. Do not halt the CPU during a Bluetooth connection: that disrupts
+SoftDevice radio timing and invalidates the test.

examples/companion_radio/MyMesh.cpp

@@ -29,6 +29,7 @@
 #endif
 #if defined(NRF52_PLATFORM)
 #include <helpers/nrf52/RamFallbackFileSystem.h>
+#include <helpers/nrf52/BleDebugTrace.h>
 #endif
 #if defined(ENABLE_OTA)
 #include <helpers/ota/OtaContext.h>
@@ -9401,6 +9402,11 @@ bool MyMesh::handleCommand(const char* command, uint32_t sender_timestamp,
                                                reply_capacity)) return true;
 #endif
 
+#if defined(MESH_NRF52_BLE_TRACE) && MESH_NRF52_BLE_TRACE
+  if (sender_timestamp == 0
+      && meshBleTraceCommand(command, reply, reply_capacity)) return true;
+#endif
+
   if (_radio_profiles.handle(command, reply, reply_capacity, sender_timestamp != 0)) return true;
   if (!strncmp(command, "set tempradio ", 14)) command += 4;
   if (!strcmp(command, "get tempradio")) command += 4;

scripts/capture_nrf52_ble_debug.py

@@ -0,0 +1,169 @@
+#!/usr/bin/env python3
+"""Export an opt-in nRF52 Companion BLE trace over USB, without resetting it.
+
+Install pyserial, keep the node powered after a failed phone connection, and
+run with --port <serial-port> --output <file.json>. No pairing keys, PINs,
+peer addresses or application payloads are requested or saved.
+"""
+
+import argparse
+from datetime import datetime, timezone
+import json
+from pathlib import Path
+import re
+import time
+
+
+EVENTS = {
+    0x10: "link_connected", 0x11: "link_disconnected", 0x12: "connection_parameters",
+    0x13: "security_parameters_requested", 0x14: "stored_security_requested",
+    0x15: "passkey_display_event", 0x17: "authentication_key_requested",
+    0x18: "secure_connections_key_requested", 0x19: "authentication_result",
+    0x1A: "security_updated", 0x1B: "gap_timeout", 0x1F: "parameter_update_requested",
+    0x21: "phy_update_requested", 0x22: "phy_updated", 0x23: "data_length_requested",
+    0x24: "data_length_updated", 0x26: "advertising_terminated",
+    0x50: "attribute_write", 0x51: "attribute_authorization_requested",
+    0x52: "system_attributes_missing", 0x55: "mtu_requested", 0x56: "att_timeout",
+    0x57: "notification_transmitted",
+    0xF000: "firmware_start", 0xF001: "connect_callback", 0xF002: "disconnect_callback",
+    0xF003: "security_callback", 0xF004: "pairing_prompt", 0xF005: "pairing_complete",
+    0xF006: "secured_link_accepted", 0xF010: "preferred_parameters_result",
+    0xF011: "parameter_request_result", 0xF012: "advertising_start_result",
+    0xF013: "local_disconnect_request_result", 0xF020: "tx_recovery_started",
+    0xF021: "security_watchdog", 0xF022: "secured_no_app_watchdog",
+    0xF023: "advertising_watchdog", 0xF030: "uart_rx_callback",
+    0xF024: "command_reply_watchdog", 0xF025: "partial_uart_frame_recovery",
+    0xF031: "uart_tx_attempt", 0xF033: "tx_queue_full", 0xF034: "rx_queue_full",
+    0xF035: "uart_fifo_overflow", 0xF040: "uart_subscription_changed",
+    0xF041: "ram_subscription_restore_result", 0xF042: "ram_subscription_capture_result",
+}
+REASONS = {
+    0x05: "authentication_failure", 0x06: "pin_or_key_missing",
+    0x08: "connection_timeout", 0x13: "remote_user_terminated",
+    0x16: "local_host_terminated", 0x22: "link_layer_response_timeout",
+    0x3D: "mic_failure", 0x3E: "connection_failed_to_establish",
+}
+
+
+def decode_record(sequence, ms, event, handle, detail, extra):
+    record = dict(sequence=sequence, uptime_ms=ms, event=hex(event), handle=handle,
+                  detail=detail, extra=extra)
+    if 0xE000 <= event <= 0xE0FF or 0xE100 <= event <= 0xE1FF:
+        raw = event & 0xFF
+        record.update(name="dispatch_enter" if event < 0xE100 else "dispatch_exit",
+                      stack_event=EVENTS.get(raw, hex(raw)))
+        if event >= 0xE100:
+            record["duration_us"] = detail
+        return record
+    record["name"] = EVENTS.get(event, "unknown_event")
+    if event in (0x10, 0x12):
+        record.update(min_interval_ms=(detail & 0xFFFF) * 1.25,
+                      max_interval_ms=(detail >> 16) * 1.25,
+                      latency=extra & 0xFFFF, supervision_timeout_ms=(extra >> 16) * 10)
+    elif event in (0x11, 0xF002):
+        record.update(reason_hex=hex(detail), reason=REASONS.get(detail, "unknown_reason"))
+    elif event == 0x19:
+        record.update(authentication_status=detail, error_source=extra & 3,
+                      bonded=bool(extra & 0x100), secure_connections=bool(extra & 0x200))
+    elif event == 0x1A:
+        record.update(security_mode=detail & 0xFF, security_level=detail >> 8,
+                      encryption_key_bytes=extra)
+    elif event == 0x50:
+        record.update(attribute_handle=detail & 0xFFFF, length=detail >> 16,
+                      operation=extra & 0xFF, is_subscription=bool(extra & 0x100))
+        if extra & 0x100:
+            record["subscription_bits"] = extra >> 16
+    elif event == 0xF031:
+        record.update(requested_bytes=detail, accepted_bytes=extra)
+    elif event == 0xF006:
+        record.update(bonded=bool(detail), uart_notifications_enabled=bool(extra))
+    elif event == 0xF000:
+        record.update(reset_reason_hex=hex(detail), ble_tx_dbm=extra if extra < 128 else extra - 2**32)
+    return record
+
+
+def values(reply):
+    return {key: int(value) for key, value in re.findall(r"([a-z_]+)=(\d+)", reply)}
+
+
+class Terminal:
+    def __init__(self, port):
+        self.port = port
+
+    def read_prompt(self, timeout=3, expected=None):
+        result = bytearray()
+        deadline = time.monotonic() + timeout
+        while time.monotonic() < deadline:
+            result.extend(self.port.read(self.port.in_waiting or 1))
+            echoed = None if expected is None else re.search(
+                rb"(?:^|\n)(?:> )?" + re.escape(expected.encode("ascii")) + rb"\r?\n", result)
+            if result.endswith(b"\n> ") and (expected is None or echoed):
+                # Ignore any delayed welcome banner from entering terminal mode.
+                return result[echoed.start() if echoed else 0:].decode("ascii", errors="replace")
+            if len(result) > 16384:
+                raise RuntimeError("Unexpectedly large USB terminal response")
+        raise TimeoutError("No USB terminal prompt; close other serial clients")
+
+    def command(self, command):
+        self.port.write(command.encode("ascii") + b"\r")
+        return self.read_prompt(expected=command)
+
+
+def export(port_name):
+    import serial
+    started = time.monotonic()
+    result = {"captured_utc": datetime.now(timezone.utc).isoformat(),
+              "commands": {}, "records": [], "unavailable_sequences": []}
+    with serial.Serial(port_name, 115200, timeout=0.05) as port:
+        port.dtr = True
+        terminal = Terminal(port)
+        port.reset_input_buffer()
+        port.write(b"+++MESHCORE-TERM-START\r")
+        try:
+            terminal.read_prompt()
+            for command in ("ver", "get radio", "get tx", "get bluetooth.trace.state",
+                            "get bluetooth.trace.stats", "get bluetooth.trace.timing",
+                            "get bluetooth.trace"):
+                result["commands"][command] = terminal.command(command)
+            head = values(result["commands"]["get bluetooth.trace"])
+            if head.get("format") != 2 or head.get("capacity") != 256:
+                raise RuntimeError("This device does not have the format-2 diagnostic firmware")
+            result["trace"] = head
+            for sequence in range(max(1, head["next"] - head["capacity"] + 1), head["next"] + 1):
+                reply = terminal.command("get bluetooth.trace " + str(sequence))
+                match = re.search(r"> (\d+),(\d+),0x([0-9a-fA-F]+),(\d+),(\d+),(\d+)", reply)
+                if match is None:
+                    result["unavailable_sequences"].append(sequence)
+                    continue
+                fields = [int(value, 16 if index == 2 else 10)
+                          for index, value in enumerate(match.groups())]
+                if fields[0] != sequence:
+                    raise RuntimeError("Mismatched trace sequence")
+                result["records"].append(decode_record(*fields))
+            result["state_after"] = terminal.command("get bluetooth.trace.state")
+        finally:
+            port.write(b"+++MESHCORE-TERM-STOP\r")
+    result["export_seconds"] = round(time.monotonic() - started, 3)
+    result["limitations"] = [
+        "RAM history is lost on power loss or reboot; export before restarting the node.",
+        "Old records roll out after 256 events; unavailable sequences are reported.",
+        "Dispatch timing measures software handling after the SoftDevice delivers an event, not radio ISR latency.",
+        "No connection events cannot alone distinguish the host, RF path and peripheral controller.",
+    ]
+    return result
+
+
+def main():
+    parser = argparse.ArgumentParser(description=__doc__)
+    parser.add_argument("--port", required=True, help="USB serial device or COM port")
+    parser.add_argument("--output", required=True, type=Path)
+    args = parser.parse_args()
+    result = export(args.port)
+    args.output.parent.mkdir(parents=True, exist_ok=True)
+    args.output.write_text(json.dumps(result, indent=2, ensure_ascii=True) + "\n", encoding="ascii")
+    print("Saved %d events to %s" % (len(result["records"]), args.output))
+    print(result["commands"]["get bluetooth.trace.stats"].strip())
+
+
+if __name__ == "__main__":
+    main()

scripts/nrf52_ble_cccd_fix.py

@@ -85,6 +85,32 @@ def patched_bluefruit_source(source):
     return source.replace(OLD_BEGIN, FIXED_BEGIN)
 
 
+def patched_trace_source(source):
+    """Bracket real BLE dispatch in diagnostic builds, including stuck handlers."""
+    include = '#include "bluefruit.h"\n'
+    entry = 'void AdafruitBluefruit::_ble_handler(ble_evt_t* evt)\n{\n'
+    exit_marker = '  if (_event_cb) _event_cb(evt);\n'
+    marker = '// MeshCore diagnostic dispatch trace'
+    if marker in source:
+        return source
+    if any(source.count(value) != 1 for value in (include, entry, exit_marker)):
+        raise RuntimeError("nRF52 BLE trace: unrecognized event dispatcher")
+    source = source.replace(include, include + '''
+#if defined(MESH_NRF52_BLE_TRACE) && MESH_NRF52_BLE_TRACE
+#include <helpers/nrf52/BleDebugTrace.h>
+#endif
+''')
+    source = source.replace(entry, entry + '''  // MeshCore diagnostic dispatch trace
+#if defined(MESH_NRF52_BLE_TRACE) && MESH_NRF52_BLE_TRACE
+  meshBleTraceDispatchEnter(evt->header.evt_id, evt->evt.common_evt.conn_handle);
+#endif
+''')
+    return source.replace(exit_marker, exit_marker + '''#if defined(MESH_NRF52_BLE_TRACE) && MESH_NRF52_BLE_TRACE
+  meshBleTraceDispatchExit(evt->header.evt_id, evt->evt.common_evt.conn_handle);
+#endif
+''')
+
+
 def replace_framework_source(build_env, node):
     source = Path(node.srcnode().get_abspath())
     if source.name not in ("BLEGatt.cpp", "BLEConnection.cpp", "bluefruit.cpp") or source.parent.name != "src":
@@ -96,6 +122,9 @@ def replace_framework_source(build_env, node):
         patched = patched_connection_source(original)
     else:
         patched = patched_bluefruit_source(original)
+        if "MESH_NRF52_BLE_TRACE" in str(build_env.get("CPPDEFINES", [])):
+            patched = patched_trace_source(patched)
+            build_env.AppendUnique(CPPPATH=[build_env.subst("$PROJECT_DIR/src")])
     build_env.AppendUnique(CPPPATH=[str(source.parent)])
     destination = Path(build_env.subst("$BUILD_DIR")) / "patched-nrf52-ble" / source.name
     destination.parent.mkdir(parents=True, exist_ok=True)

src/helpers/nrf52/BleDebugTrace.h

@@ -0,0 +1,140 @@
+#pragma once
+
+// Opt-in, bounded USB/SWD-readable diagnostics. Callbacks only write RAM;
+// no serial I/O, allocation, PINs, keys, peer addresses or payloads are saved.
+#if defined(MESH_NRF52_BLE_TRACE) && MESH_NRF52_BLE_TRACE
+#include <Arduino.h>
+#include <atomic>
+#include <errno.h>
+#include <stdio.h>
+#include <stdlib.h>
+#include <string.h>
+
+static constexpr uint32_t MESH_BLE_TRACE_CAPACITY = 256;
+struct MeshBleTraceRecord {
+  uint32_t sequence, ms, event, handle, detail, extra;
+};
+struct MeshBleTraceSlot {
+  // Sequentially consistent fields make the before/after sequence check
+  // valid across tasks, including a reader racing with ring wraparound.
+  std::atomic<uint32_t> sequence{0}, ms{0}, event{0}, handle{0}, detail{0}, extra{0};
+};
+struct MeshBleTraceBuffer {
+  uint32_t magic = 0x424c4554, capacity = MESH_BLE_TRACE_CAPACITY;
+  std::atomic<uint32_t> next{0}, dropped{0};
+  std::atomic_flag writer = ATOMIC_FLAG_INIT;
+  MeshBleTraceSlot records[MESH_BLE_TRACE_CAPACITY];
+  std::atomic<uint32_t> dispatch_event{0}, dispatch_started{0}, max_dispatch_us{0};
+  std::atomic<uint32_t> connects{0}, disconnects{0}, secured{0}, rx{0}, tx{0};
+  std::atomic<uint32_t> last_reason{0}, last_disconnect_ms{0}, max_loop_gap_ms{0};
+};
+extern "C" { extern MeshBleTraceBuffer mesh_ble_trace; }
+void meshBleTraceState(char* reply, size_t capacity);
+static inline void meshBleTraceMax(std::atomic<uint32_t>& value, uint32_t sample) {
+  uint32_t old = value.load(std::memory_order_relaxed);
+  while (sample > old && !value.compare_exchange_weak(old, sample,
+                                                        std::memory_order_relaxed)) {}
+}
+static inline void meshBleTrace(uint32_t event, uint32_t handle = 0xffff,
+                                uint32_t detail = 0, uint32_t extra = 0) {
+  // Never wait for a lower-priority writer: count contention instead. The
+  // BLE worker must not be blocked by a USB reader or another diagnostic.
+  if (mesh_ble_trace.writer.test_and_set(std::memory_order_acquire)) {
+    mesh_ble_trace.dropped.fetch_add(1, std::memory_order_relaxed);
+    return;
+  }
+  const uint32_t sequence = mesh_ble_trace.next.load(std::memory_order_relaxed) + 1;
+  auto& record = mesh_ble_trace.records[(sequence - 1) % MESH_BLE_TRACE_CAPACITY];
+  record.sequence.store(0);
+  record.ms.store(millis());
+  record.event.store(event);
+  record.handle.store(handle);
+  record.detail.store(detail);
+  record.extra.store(extra);
+  record.sequence.store(sequence);
+  mesh_ble_trace.next.store(sequence, std::memory_order_release);
+  mesh_ble_trace.writer.clear(std::memory_order_release);
+}
+static inline bool meshBleTraceRead(uint32_t sequence, MeshBleTraceRecord& r) {
+  if (!sequence) return false;
+  const auto& s = mesh_ble_trace.records[(sequence - 1) % MESH_BLE_TRACE_CAPACITY];
+  r.sequence = s.sequence.load();
+  r.ms = s.ms.load(); r.event = s.event.load(); r.handle = s.handle.load();
+  r.detail = s.detail.load(); r.extra = s.extra.load();
+  return r.sequence == sequence && s.sequence.load() == sequence;
+}
+static inline void meshBleTraceDispatchEnter(uint32_t event, uint32_t handle) {
+  mesh_ble_trace.dispatch_started.store(micros(), std::memory_order_relaxed);
+  mesh_ble_trace.dispatch_event.store(event, std::memory_order_release);
+  meshBleTrace(0xe000 | event, handle);
+}
+static inline void meshBleTraceDispatchExit(uint32_t event, uint32_t handle) {
+  const uint32_t elapsed = micros() - mesh_ble_trace.dispatch_started.load(
+                                                        std::memory_order_relaxed);
+  meshBleTraceMax(mesh_ble_trace.max_dispatch_us, elapsed);
+  meshBleTrace(0xe100 | event, handle, elapsed);
+  mesh_ble_trace.dispatch_event.store(0, std::memory_order_release);
+}
+static inline bool meshBleTraceCommand(const char* command, char* reply,
+                                       size_t capacity) {
+  if (!strcmp(command, "get bluetooth.trace.state")) {
+    meshBleTraceState(reply, capacity);
+    return true;
+  }
+  if (!strcmp(command, "get bluetooth.trace.stats")) {
+    snprintf(reply, capacity,
+        "> connects=%lu,disconnects=%lu,secured=%lu,rx=%lu,tx=%lu,reason=%lu,disconnect_ms=%lu",
+        (unsigned long)mesh_ble_trace.connects.load(),
+        (unsigned long)mesh_ble_trace.disconnects.load(),
+        (unsigned long)mesh_ble_trace.secured.load(),
+        (unsigned long)mesh_ble_trace.rx.load(), (unsigned long)mesh_ble_trace.tx.load(),
+        (unsigned long)mesh_ble_trace.last_reason.load(),
+        (unsigned long)mesh_ble_trace.last_disconnect_ms.load());
+    return true;
+  }
+  if (!strcmp(command, "get bluetooth.trace.timing")) {
+    const uint32_t event = mesh_ble_trace.dispatch_event.load(std::memory_order_acquire);
+    snprintf(reply, capacity,
+        "> uptime_ms=%lu,max_loop_gap_ms=%lu,max_dispatch_us=%lu,dispatch_event=%lu,dispatch_age_us=%lu",
+        (unsigned long)millis(), (unsigned long)mesh_ble_trace.max_loop_gap_ms.load(),
+        (unsigned long)mesh_ble_trace.max_dispatch_us.load(), (unsigned long)event,
+        (unsigned long)(event ? micros() - mesh_ble_trace.dispatch_started.load() : 0));
+    return true;
+  }
+  const char* prefix = "get bluetooth.trace";
+  const size_t length = strlen(prefix);
+  if (strncmp(command, prefix, length)
+      || (command[length] && command[length] != ' ')) return false;
+  if (!command[length]) {
+    snprintf(reply, capacity, "> next=%lu,capacity=%lu,dropped=%lu,format=2",
+             (unsigned long)mesh_ble_trace.next.load(std::memory_order_acquire),
+             (unsigned long)mesh_ble_trace.capacity,
+             (unsigned long)mesh_ble_trace.dropped.load());
+    return true;
+  }
+  const char* value = command + length + 1;
+  char* end = nullptr;
+  errno = 0;
+  const unsigned long sequence = strtoul(value, &end, 10);
+  if (*value < '0' || *value > '9' || *end || sequence == 0
+      || sequence > UINT32_MAX || errno == ERANGE) {
+    snprintf(reply, capacity, "Error: use get bluetooth.trace <sequence>");
+    return true;
+  }
+  MeshBleTraceRecord r;
+  if (!meshBleTraceRead((uint32_t)sequence, r)) {
+    snprintf(reply, capacity, "Error: trace record unavailable");
+  } else {
+    snprintf(reply, capacity, "> %lu,%lu,0x%04lx,%lu,%lu,%lu",
+        (unsigned long)r.sequence, (unsigned long)r.ms,
+        (unsigned long)r.event, (unsigned long)r.handle,
+        (unsigned long)r.detail, (unsigned long)r.extra);
+  }
+  return true;
+}
+#else
+#define meshBleTrace(...) do {} while (0)
+#define meshBleTraceMax(...) do {} while (0)
+#define meshBleTraceDispatchEnter(...) do {} while (0)
+#define meshBleTraceDispatchExit(...) do {} while (0)
+#endif

src/helpers/nrf52/SerialBLEInterface.cpp

@@ -2,12 +2,19 @@
 #include "../BluetoothMac.h"
 #include "../CompanionFrameQueue.h"
 #include "SoftDeviceState.h"
+#include "BleDebugTrace.h"
 #include <stdio.h>
 #include <string.h>
 #include "ble_gap.h"
 #include "ble_hci.h"
 #include <utility/bonding.h>
 
+#if defined(MESH_NRF52_BLE_TRACE) && MESH_NRF52_BLE_TRACE
+extern "C" {
+__attribute__((used, externally_visible)) MeshBleTraceBuffer mesh_ble_trace;
+}
+#endif
+
 // Magic numbers came from actual testing
 #define BLE_HEALTH_CHECK_INTERVAL  10000  // Advertising watchdog check every 10 seconds
 #define BLE_RETRY_THROTTLE_MS      250    // Throttle retries to 250ms when queue buildup detected
@@ -30,6 +37,25 @@
 
 static SerialBLEInterface* instance = nullptr;
 
+#if defined(MESH_NRF52_BLE_TRACE) && MESH_NRF52_BLE_TRACE
+void SerialBLEInterface::formatDebugState(char* reply, size_t capacity) {
+  snprintf(reply, capacity,
+      "> enabled=%u,ready=%u,handle=%u,secured=%u,adv=%u,conn=%u,data=%u,txq=%u,rxq=%u,recovery=%u,notify=%u,mtu=%u",
+      (unsigned)_isEnabled, (unsigned)_begin_ready, (unsigned)_conn_handle,
+      (unsigned)_isDeviceConnected, (unsigned)Bluefruit.Advertising.isRunning(),
+      (unsigned)Bluefruit.connected(),
+      (unsigned)_companionDataSeen.load(std::memory_order_acquire),
+      (unsigned)send_queue_len, (unsigned)recv_queue_len,
+      (unsigned)_tx_disconnect_recovery.pending(),
+      (unsigned)(_conn_handle != BLE_CONN_HANDLE_INVALID && bleuart.notifyEnabled(_conn_handle)),
+      (unsigned)_debug_mtu.load());
+}
+void meshBleTraceState(char* reply, size_t capacity) {
+  if (instance) instance->formatDebugState(reply, capacity);
+  else snprintf(reply, capacity, "> Bluetooth not initialized");
+}
+#endif
+
 static bool formatDeviceName(char* dest, size_t capacity,
                              const char* prefix, const char* name) {
   if (dest == nullptr || capacity == 0 || prefix == nullptr || name == nullptr) {
@@ -103,6 +129,7 @@ bool mesh_nrf52_restore_ram_cccd(uint16_t handle,
   const uint32_t status = sd_ble_gatts_sys_attr_set(
       handle, cccd_ram_cache.attrs, cccd_ram_cache.length,
       CCCD_SYS_ATTR_FLAGS);
+  meshBleTrace(0xf041, handle, status, cccd_ram_cache.length);
   if (status != NRF_SUCCESS) {
     BLE_DEBUG_PRINTLN("CCCD RAM initialization failed: %lu",
                       (unsigned long)status);
@@ -122,6 +149,7 @@ static void captureCccdInRam(uint16_t handle, const ble_gap_addr_t& peer) {
   // Retain a local reload barrier in addition to the global SVC ABI guard.
   // The original SDK wrapper does not declare writes through this pointer.
   __asm__ __volatile__("" ::: "memory");
+  meshBleTrace(0xf042, handle, status, length);
   if (status != NRF_SUCCESS || length == 0
       || length > CCCD_RAM_CACHE_MAX) {
     BLE_DEBUG_PRINTLN("CCCD RAM capture: status=%lu len=%u",
@@ -146,6 +174,10 @@ static bool isBondAuthenticationFailure(uint8_t reason) {
 }
 
 void SerialBLEInterface::onConnect(uint16_t connection_handle) {
+  meshBleTrace(0xf001, connection_handle);
+#if defined(MESH_NRF52_BLE_TRACE) && MESH_NRF52_BLE_TRACE
+  mesh_ble_trace.connects.fetch_add(1);
+#endif
   BLE_DEBUG_PRINTLN("SerialBLEInterface: connected handle=0x%04X", connection_handle);
   if (instance) {
     instance->_pairingRequestPending.store(false, std::memory_order_release);
@@ -162,6 +194,12 @@ void SerialBLEInterface::onConnect(uint16_t connection_handle) {
 }
 
 void SerialBLEInterface::onDisconnect(uint16_t connection_handle, uint8_t reason) {
+  meshBleTrace(0xf002, connection_handle, reason);
+#if defined(MESH_NRF52_BLE_TRACE) && MESH_NRF52_BLE_TRACE
+  mesh_ble_trace.disconnects.fetch_add(1);
+  mesh_ble_trace.last_reason.store(reason);
+  mesh_ble_trace.last_disconnect_ms.store(millis());
+#endif
   BLE_DEBUG_PRINTLN("SerialBLEInterface: disconnected handle=0x%04X reason=%u", connection_handle, reason);
   if (instance) {
     if (instance->_conn_handle == connection_handle) {
@@ -215,6 +253,7 @@ size_t SerialBLEInterface::sendMotaRequest(void* context,
 #endif
 
 void SerialBLEInterface::onSecured(uint16_t connection_handle) {
+  meshBleTrace(0xf003, connection_handle);
   BLE_DEBUG_PRINTLN("SerialBLEInterface: onSecured handle=0x%04X", connection_handle);
   if (instance) {
     if (instance->isValidConnection(connection_handle, true)) {
@@ -234,6 +273,11 @@ void SerialBLEInterface::onSecured(uint16_t connection_handle) {
       }
 
       instance->_isDeviceConnected = true;
+#if defined(MESH_NRF52_BLE_TRACE) && MESH_NRF52_BLE_TRACE
+      mesh_ble_trace.secured.fetch_add(1);
+      meshBleTrace(0xf006, connection_handle, conn->bonded(),
+                   instance->bleuart.notifyEnabled(connection_handle));
+#endif
       if (conn->bonded()) {
         instance->noteSuccessfulConnection(conn->getPeerAddr());
       } else {
@@ -255,6 +299,8 @@ void SerialBLEInterface::onSecured(uint16_t connection_handle) {
       conn_params.conn_sup_timeout = BLE_CONN_SUP_TIMEOUT;
       
       uint32_t err_code = sd_ble_gap_conn_param_update(connection_handle, &conn_params);
+      meshBleTrace(0xf011, connection_handle, err_code,
+                   BLE_SLAVE_LATENCY | (BLE_CONN_SUP_TIMEOUT << 16));
       if (err_code == NRF_SUCCESS) {
         BLE_DEBUG_PRINTLN("Connection parameter update requested: %u-%ums interval, latency=%u, %ums timeout",
                          conn_params.min_conn_interval * 5 / 4,  // convert to ms (1.25ms units)
@@ -271,6 +317,7 @@ void SerialBLEInterface::onSecured(uint16_t connection_handle) {
 }
 
 bool SerialBLEInterface::onPairingPasskey(uint16_t connection_handle, uint8_t const passkey[6], bool match_request) {
+  meshBleTrace(0xf004, connection_handle, match_request);
   (void)passkey;
   BLE_DEBUG_PRINTLN("SerialBLEInterface: pairing passkey request match=%d", match_request);
   if (instance && instance->isValidConnection(connection_handle)) {
@@ -280,6 +327,7 @@ bool SerialBLEInterface::onPairingPasskey(uint16_t connection_handle, uint8_t co
 }
 
 void SerialBLEInterface::onPairingComplete(uint16_t connection_handle, uint8_t auth_status) {
+  meshBleTrace(0xf005, connection_handle, auth_status);
   BLE_DEBUG_PRINTLN("SerialBLEInterface: pairing complete handle=0x%04X status=%u", connection_handle, auth_status);
   if (instance) {
     if (instance->isValidConnection(connection_handle)) {
@@ -313,8 +361,73 @@ void SerialBLEInterface::onPairingComplete(uint16_t connection_handle, uint8_t a
 }
 
 void SerialBLEInterface::onBLEEvent(ble_evt_t* evt) {
+#if defined(MESH_NRF52_BLE_TRACE) && MESH_NRF52_BLE_TRACE
+  uint32_t detail = 0, extra = 0;
+  const ble_gap_conn_params_t* params = nullptr;
+  if (evt->header.evt_id == BLE_GAP_EVT_CONNECTED) {
+    params = &evt->evt.gap_evt.params.connected.conn_params;
+  } else if (evt->header.evt_id == BLE_GAP_EVT_CONN_PARAM_UPDATE) {
+    params = &evt->evt.gap_evt.params.conn_param_update.conn_params;
+  } else if (evt->header.evt_id == BLE_GAP_EVT_DISCONNECTED) {
+    detail = evt->evt.gap_evt.params.disconnected.reason;
+  } else if (evt->header.evt_id == BLE_GAP_EVT_ADV_SET_TERMINATED) {
+    detail = evt->evt.gap_evt.params.adv_set_terminated.reason;
+  }
+  if (evt->header.evt_id == BLE_GAP_EVT_AUTH_STATUS) {
+    const auto& auth = evt->evt.gap_evt.params.auth_status;
+    detail = auth.auth_status;
+    extra = auth.error_src | (auth.bonded << 8) | (auth.lesc << 9);
+  } else if (evt->header.evt_id == BLE_GAP_EVT_CONN_SEC_UPDATE) {
+    const auto& sec = evt->evt.gap_evt.params.conn_sec_update.conn_sec;
+    detail = sec.sec_mode.sm | (sec.sec_mode.lv << 8);
+    extra = sec.encr_key_size;
+  } else if (evt->header.evt_id == BLE_GAP_EVT_TIMEOUT) {
+    detail = evt->evt.gap_evt.params.timeout.src;
+  } else if (evt->header.evt_id == BLE_GATTS_EVT_WRITE) {
+    const auto& write = evt->evt.gatts_evt.params.write;
+    detail = write.handle | (write.len << 16);
+    extra = write.op;
+    if (write.uuid.type == BLE_UUID_TYPE_BLE
+        && write.uuid.uuid == BLE_UUID_DESCRIPTOR_CLIENT_CHAR_CONFIG) {
+      extra |= 0x100;
+      // Only a descriptor's public subscription bits; never characteristic data.
+      if (write.len == 2) extra |= (write.data[0] | (write.data[1] << 8)) << 16;
+    }
+  } else if (evt->header.evt_id == BLE_GATTS_EVT_EXCHANGE_MTU_REQUEST) {
+    detail = evt->evt.gatts_evt.params.exchange_mtu_request.client_rx_mtu;
+  } else if (evt->header.evt_id == BLE_GATTS_EVT_HVN_TX_COMPLETE) {
+    detail = evt->evt.gatts_evt.params.hvn_tx_complete.count;
+  } else if (evt->header.evt_id == BLE_GATTS_EVT_TIMEOUT) {
+    detail = evt->evt.gatts_evt.params.timeout.src;
+  } else if (evt->header.evt_id == BLE_GAP_EVT_PHY_UPDATE) {
+    const auto& phy = evt->evt.gap_evt.params.phy_update;
+    detail = phy.status;
+    extra = phy.tx_phy | (phy.rx_phy << 8);
+  } else if (evt->header.evt_id == BLE_GAP_EVT_DATA_LENGTH_UPDATE) {
+    const auto& data = evt->evt.gap_evt.params.data_length_update.effective_params;
+    detail = data.max_tx_octets | (data.max_rx_octets << 16);
+    extra = data.max_tx_time_us | (data.max_rx_time_us << 16);
+  }
+  if (params) {
+    detail = params->min_conn_interval | (params->max_conn_interval << 16);
+    extra = params->slave_latency | (params->conn_sup_timeout << 16);
+  }
+  meshBleTrace(evt->header.evt_id, evt->evt.common_evt.conn_handle, detail, extra);
+#else
+  meshBleTrace(evt->header.evt_id, evt->evt.common_evt.conn_handle);
+#endif
   if (!instance) return;
 
+#if defined(MESH_NRF52_BLE_TRACE) && MESH_NRF52_BLE_TRACE
+  if (evt->header.evt_id == BLE_GAP_EVT_CONNECTED
+      || evt->header.evt_id == BLE_GATTS_EVT_EXCHANGE_MTU_REQUEST) {
+    BLEConnection* conn = Bluefruit.Connection(evt->evt.common_evt.conn_handle);
+    instance->_debug_mtu.store(conn ? conn->getMtu() : 0);
+  } else if (evt->header.evt_id == BLE_GAP_EVT_DISCONNECTED) {
+    instance->_debug_mtu.store(0);
+  }
+#endif
+
   if (evt->header.evt_id == BLE_GAP_EVT_CONNECTED) {
     ble_gap_evt_connected_t const* connected = &evt->evt.gap_evt.params.connected;
     if (connected->role == BLE_GAP_ROLE_PERIPH) {
@@ -542,7 +655,9 @@ bool SerialBLEInterface::advertisingAllowed() const {
 
 bool SerialBLEInterface::startAdvertising(const char* failure_cause) {
   if (!advertisingAllowed()) return false;
-  if (Bluefruit.Advertising.start(0)) return true;
+  const bool started = Bluefruit.Advertising.start(0);
+  meshBleTrace(0xf012, 0xffff, started, _bonded_only);
+  if (started) return true;
   if (_bonded_only) requestBondedOnlyRecovery(failure_cause);
   return false;
 }
@@ -561,6 +676,7 @@ bool SerialBLEInterface::begin(const char* prefix, const char* name,
   _begin_attempted = true;
   _begin_failure[0] = 0;
   instance = this;
+  meshBleTrace(0xf000, 0xffff, NRF_POWER->RESETREAS, BLE_TX_POWER);
   _successfulConnectionPending.store(false, std::memory_order_release);
   _successfulConnectionStarted.store(0, std::memory_order_relaxed);
   _companionDataSeen.store(false, std::memory_order_release);
@@ -655,6 +771,7 @@ bool SerialBLEInterface::begin(const char* prefix, const char* name,
   ppcp_params.conn_sup_timeout = BLE_CONN_SUP_TIMEOUT;
   
   uint32_t err_code = sd_ble_gap_ppcp_set(&ppcp_params);
+  meshBleTrace(0xf010, 0xffff, err_code);
   if (err_code == NRF_SUCCESS) {
     BLE_DEBUG_PRINTLN("PPCP set: %u-%ums interval, latency=%u, %ums timeout",
                      ppcp_params.min_conn_interval * 5 / 4,  // convert to ms (1.25ms units)
@@ -691,6 +808,10 @@ bool SerialBLEInterface::begin(const char* prefix, const char* name,
     return false;
   }
   bleuart.setRxCallback(onBleUartRX);
+#if defined(MESH_NRF52_BLE_TRACE) && MESH_NRF52_BLE_TRACE
+  bleuart.setNotifyCallback(onBleUartNotify);
+  bleuart.setRxOverflowCallback(onBleUartOverflow);
+#endif
 
   // Register the legacy DFU service before the optional mOTA service. A
   // fielded SoftDevice has a fixed GATT table: reserve the ordinary Companion
@@ -934,6 +1055,7 @@ void SerialBLEInterface::serviceTxRecovery(uint32_t now) {
 
   const uint32_t result = sd_ble_gap_disconnect(
       _conn_handle, BLE_HCI_REMOTE_USER_TERMINATED_CONNECTION);
+  meshBleTrace(0xf013, _conn_handle, result, 1);
   if (result == NRF_SUCCESS) {
     BLE_DEBUG_PRINTLN("SerialBLEInterface: stalled TX disconnect requested");
   } else if (result == NRF_ERROR_INVALID_STATE) {
@@ -946,6 +1068,7 @@ void SerialBLEInterface::serviceTxRecovery(uint32_t now) {
 }
 
 void SerialBLEInterface::recoverStalledTx(const char* cause) {
+  meshBleTrace(0xf020, _conn_handle, send_queue_len, recv_queue_len);
   if (_tx_disconnect_recovery.pending()) return;
 
   BLE_DEBUG_PRINTLN("SerialBLEInterface: %s; forcing reconnect", cause);
@@ -1000,7 +1123,9 @@ void SerialBLEInterface::enable() {
 
 void SerialBLEInterface::disconnect() {
   if (_conn_handle != BLE_CONN_HANDLE_INVALID) {
-    sd_ble_gap_disconnect(_conn_handle, BLE_HCI_REMOTE_USER_TERMINATED_CONNECTION);
+    const uint32_t result = sd_ble_gap_disconnect(_conn_handle, BLE_HCI_REMOTE_USER_TERMINATED_CONNECTION);
+    meshBleTrace(0xf013, _conn_handle, result, 0);
+    (void)result;
   }
 }
 
@@ -1022,6 +1147,11 @@ void SerialBLEInterface::disable() {
 
 void SerialBLEInterface::loop() {
   const uint32_t now = (uint32_t)millis();
+#if defined(MESH_NRF52_BLE_TRACE) && MESH_NRF52_BLE_TRACE
+  if (_debug_last_loop_ms) meshBleTraceMax(mesh_ble_trace.max_loop_gap_ms,
+                                          now - _debug_last_loop_ms);
+  _debug_last_loop_ms = now;
+#endif
   serviceBondedOnlyTransition();
   if (_tx_disconnect_recovery.pending()) {
     serviceTxRecovery(now);
@@ -1034,6 +1164,7 @@ void SerialBLEInterface::loop() {
       // Keep the two-minute PIN-entry window, but do not let an unfinished
       // security exchange occupy the only BLE connection indefinitely.
       BLE_DEBUG_PRINTLN("SerialBLEInterface: security setup timed out");
+      meshBleTrace(0xf021, _conn_handle);
       _security_timer.cancel();
       disconnect();
     }
@@ -1043,6 +1174,7 @@ void SerialBLEInterface::loop() {
                    now, BLE_COMPANION_START_TIMEOUT_MS)) {
       // iOS can report a secured BLE link while the app never establishes its
       // UART session. Release that occupied link so the app can reconnect.
+      meshBleTrace(0xf022, _conn_handle);
       recoverStalledTx("no Companion data after secured BLE connection");
     }
     return;
@@ -1053,6 +1185,7 @@ void SerialBLEInterface::loop() {
     _last_health_check = now;
     if (!isAdvertising()) {
       BLE_DEBUG_PRINTLN("SerialBLEInterface: advertising watchdog restarting");
+      meshBleTrace(0xf023);
       startAdvertising("advertising watchdog restart failed");
     }
   }
@@ -1068,6 +1201,7 @@ size_t SerialBLEInterface::writeFrame(const uint8_t src[], size_t len) {
   if (connected && len > 0) {
     if (!mesh::enqueueCompanionFrame(send_queue, send_queue_len, FRAME_QUEUE_SIZE,
                                      src, len)) {
+      meshBleTrace(0xf033, _conn_handle, send_queue_len, len);
       BLE_DEBUG_PRINTLN("writeFrame(), send_queue is full!");
       return 0;
     }
@@ -1100,6 +1234,10 @@ size_t SerialBLEInterface::checkRecvFrame(uint8_t dest[]) {
             frame_to_send.buf, frame_to_send.len);
 
         size_t written = writeBleUartFrame(frame_to_send);
+        meshBleTrace(0xf031, _conn_handle, frame_to_send.len, written);
+#if defined(MESH_NRF52_BLE_TRACE) && MESH_NRF52_BLE_TRACE
+        if (written) mesh_ble_trace.tx.fetch_add(1);
+#endif
         if (written == frame_to_send.len) {
           BLE_DEBUG_PRINTLN("writeBytes: sz=%u, hdr=%u", (unsigned)frame_to_send.len, (unsigned)frame_to_send.buf[0]);
           _last_retry_attempt = 0;
@@ -1112,6 +1250,7 @@ size_t SerialBLEInterface::checkRecvFrame(uint8_t dest[]) {
           // The app cannot recover framing after receiving only part of one
           // protocol frame. Reconnect instead of following it with another
           // frame on the same BLE UART stream.
+          meshBleTrace(0xf025, _conn_handle, written, frame_to_send.len);
           recoverStalledTx("partial BLE UART frame");
           return 0;
         } else {
@@ -1125,6 +1264,7 @@ size_t SerialBLEInterface::checkRecvFrame(uint8_t dest[]) {
             _last_retry_attempt = now;
             if (delivery_required) {
               if (_tx_stall_watchdog.noteBlocked((uint32_t)now)) {
+                meshBleTrace(0xf024, _conn_handle);
                 recoverStalledTx("command reply blocked for 10 seconds");
                 return 0;
               }
@@ -1160,6 +1300,8 @@ void SerialBLEInterface::onBleUartRX(uint16_t conn_handle) {
     return;
   }
   
+  meshBleTrace(0xf030, conn_handle, instance->bleuart.available(),
+               instance->isConnected());
   if (instance->_conn_handle != conn_handle || !instance->isConnected()) {
     while (instance->bleuart.available() > 0) {
       instance->bleuart.read();
@@ -1172,6 +1314,7 @@ void SerialBLEInterface::onBleUartRX(uint16_t conn_handle) {
       while (instance->bleuart.available() > 0) {
         instance->bleuart.read();
       }
+      meshBleTrace(0xf034, conn_handle, instance->recv_queue_len);
       BLE_DEBUG_PRINTLN("onBleUartRX: recv queue full, dropping data");
       break;
     }
@@ -1192,11 +1335,23 @@ void SerialBLEInterface::onBleUartRX(uint16_t conn_handle) {
     instance->recv_queue[instance->recv_queue_len].len = read_len;
     instance->bleuart.readBytes(instance->recv_queue[instance->recv_queue_len].buf, read_len);
     instance->recv_queue_len++;
+#if defined(MESH_NRF52_BLE_TRACE) && MESH_NRF52_BLE_TRACE
+    mesh_ble_trace.rx.fetch_add(1);
+#endif
     instance->_companionDataSeen.store(true, std::memory_order_release);
     instance->_companion_start_timer.cancel();
   }
 }
 
+#if defined(MESH_NRF52_BLE_TRACE) && MESH_NRF52_BLE_TRACE
+void SerialBLEInterface::onBleUartNotify(uint16_t handle, bool enabled) {
+  meshBleTrace(0xf040, handle, enabled);
+}
+void SerialBLEInterface::onBleUartOverflow(uint16_t handle, uint16_t leftover) {
+  meshBleTrace(0xf035, handle, leftover);
+}
+#endif
+
 bool SerialBLEInterface::isConnected() const {
   return !_tx_disconnect_recovery.pending() && _isDeviceConnected &&
          Bluefruit.connected() > 0;

src/helpers/nrf52/SerialBLEInterface.h

@@ -66,6 +66,12 @@ class SerialBLEInterface : public BaseSerialInterface {
   bool _begin_ready = false;
   char _begin_failure[96] = {};
   char _active_name[48] = {};
+#if defined(MESH_NRF52_BLE_TRACE) && MESH_NRF52_BLE_TRACE
+  uint32_t _debug_last_loop_ms = 0;
+  std::atomic<uint32_t> _debug_mtu{0};
+  static void onBleUartNotify(uint16_t handle, bool enabled);
+  static void onBleUartOverflow(uint16_t handle, uint16_t leftover);
+#endif
   bool _isDeviceConnected;
   uint16_t _conn_handle;
   unsigned long _last_health_check;
@@ -173,6 +179,9 @@ public:
   // Kept after a failed begin so a normal Companion terminal can report the
   // cause even when early USB logging was not available.
   const char* beginFailure() const { return _begin_failure; }
+#if defined(MESH_NRF52_BLE_TRACE) && MESH_NRF52_BLE_TRACE
+  void formatDebugState(char* reply, size_t capacity);
+#endif
 
   void disconnect();
   void loop() override;

test/test_nrf52_ble_debug_tools.py

@@ -0,0 +1,126 @@
+"""Exercise diagnostic dispatch bracketing and the exported event decoder."""
+from importlib.util import module_from_spec, spec_from_file_location
+from pathlib import Path
+import subprocess
+import tempfile
+import unittest
+
+ROOT = Path(__file__).resolve().parents[1]
+
+
+def load(name, path):
+    spec = spec_from_file_location(name, ROOT / path)
+    module = module_from_spec(spec)
+    spec.loader.exec_module(module)
+    return module
+
+
+patcher = load("ble_patcher", "scripts/nrf52_ble_cccd_fix.py")
+capture = load("ble_capture", "scripts/capture_nrf52_ble_debug.py")
+
+
+class BleDebugToolsTest(unittest.TestCase):
+    def test_dispatch_brackets_real_callback_and_measures_duration(self):
+        source = '''#include "bluefruit.h"
+void AdafruitBluefruit::_ble_handler(ble_evt_t* evt)
+{
+  if (_event_cb) _event_cb(evt);
+}
+'''
+        patched = patcher.patched_trace_source(source)
+        self.assertEqual(patcher.patched_trace_source(patched), patched)
+        with self.assertRaises(RuntimeError):
+            patcher.patched_trace_source("changed SDK dispatcher")
+        with tempfile.TemporaryDirectory() as directory:
+            work = Path(directory)
+            (work / "Arduino.h").write_text(
+                "#include <stdint.h>\n#include <stddef.h>\n"
+                "extern uint32_t fake_us;\n"
+                "inline uint32_t millis(){return 1234;}\n"
+                "inline uint32_t micros(){return fake_us;}\n")
+            (work / "bluefruit.h").write_text('''
+#pragma once
+#include <stdint.h>
+struct ble_evt_t {
+  struct {uint16_t evt_id;} header;
+  struct {struct {uint16_t conn_handle;} common_evt;} evt;
+};
+class AdafruitBluefruit {
+public:
+  void (*_event_cb)(ble_evt_t*) = nullptr;
+  void _ble_handler(ble_evt_t*);
+};
+''')
+            (work / "dispatch.cpp").write_text(patched + '''
+#include <cassert>
+#include <helpers/nrf52/BleDebugTrace.h>
+uint32_t fake_us = 100;
+#if MESH_NRF52_BLE_TRACE
+extern "C" { MeshBleTraceBuffer mesh_ble_trace; }
+void meshBleTraceState(char*,size_t) {}
+#endif
+bool callback_ran = false;
+void callback(ble_evt_t* evt) {
+  callback_ran = true;
+#if MESH_NRF52_BLE_TRACE
+  assert(mesh_ble_trace.dispatch_event.load() == evt->header.evt_id);
+  meshBleTrace(0xf003, evt->evt.common_evt.conn_handle);
+#endif
+  fake_us += 50;
+}
+int main() {
+  AdafruitBluefruit bluefruit;
+  bluefruit._event_cb = callback;
+  ble_evt_t evt = {{0x10},{{7}}};
+  bluefruit._ble_handler(&evt);
+  assert(callback_ran);
+#if MESH_NRF52_BLE_TRACE
+  MeshBleTraceRecord r;
+  assert(meshBleTraceRead(1,r) && r.event == 0xe010);
+  assert(meshBleTraceRead(2,r) && r.event == 0xf003);
+  assert(meshBleTraceRead(3,r) && r.event == 0xe110 && r.detail == 50);
+  assert(mesh_ble_trace.dispatch_event.load() == 0);
+  assert(mesh_ble_trace.max_dispatch_us.load() == 50);
+#endif
+}
+''')
+            for enabled in (0, 1):
+                binary = work / ("dispatch-" + str(enabled))
+                subprocess.run(["c++", "-std=c++17",
+                    "-DMESH_NRF52_BLE_TRACE=" + str(enabled), "-I" + str(work),
+                    "-I" + str(ROOT / "src"), str(work / "dispatch.cpp"),
+                    "-o", str(binary)], check=True, capture_output=True)
+                subprocess.run([str(binary)], check=True, capture_output=True)
+
+    def test_reasons_security_subscription_and_timing_decode(self):
+        local = capture.decode_record(1, 10, 0xF002, 0, 22, 0)
+        self.assertEqual(local["reason"], "local_host_terminated")
+        timeout = capture.decode_record(2, 20, 0x11, 0, 8, 0)
+        self.assertEqual(timeout["reason"], "connection_timeout")
+        connected = capture.decode_record(3, 30, 0x10, 0, 12 | (24 << 16), 4 | (200 << 16))
+        self.assertEqual(connected["supervision_timeout_ms"], 2000)
+        self.assertEqual(connected["min_interval_ms"], 15)
+        secure = capture.decode_record(4, 40, 0x19, 0, 0, 0x302)
+        self.assertTrue(secure["bonded"] and secure["secure_connections"])
+        self.assertEqual(secure["error_source"], 2)
+        cccd = capture.decode_record(5, 50, 0x50, 0, 7 | (2 << 16), 1 | 0x100 | (1 << 16))
+        self.assertTrue(cccd["is_subscription"])
+        self.assertEqual(cccd["subscription_bits"], 1)
+        self.assertNotIn("payload", cccd)
+        self.assertEqual(capture.values("> next=9,capacity=256,dropped=0,format=2")["format"], 2)
+
+    def test_terminal_ignores_delayed_banner_before_command_echo(self):
+        class Port:
+            in_waiting = 0
+            def __init__(self):
+                self.chunks = iter([b"\r\nWELCOME private-banner\r\n> ",
+                                    b"ver\r\nCompanion debug\r\n> "])
+            def read(self, _):
+                return next(self.chunks)
+        reply = capture.Terminal(Port()).read_prompt(expected="ver")
+        self.assertNotIn("private-banner", reply)
+        self.assertIn("Companion debug", reply)
+
+
+if __name__ == "__main__":
+    unittest.main()

test/test_nrf52_ble_reconnect_watchdog.py

@@ -22,6 +22,7 @@ HARNESS = r'''
 #define BLE_COMPANION_START_TIMEOUT_MS 15000
 #define BLE_CONN_HANDLE_INVALID 0xffff
 #define BLE_DEBUG_PRINTLN(...) do {} while (0)
+#include <helpers/nrf52/BleDebugTrace.h>
 
 static uint32_t current_millis;
 uint32_t millis() { return current_millis; }

test/test_nrf52_ble_startup.py

@@ -30,6 +30,7 @@ HARNESS = r'''
 #include <helpers/BluetoothMac.h>
 #include <helpers/BleMotaProtocol.h>
 #include <helpers/nrf52/SecuritySessionTimer.h>
+#include <helpers/nrf52/BleDebugTrace.h>
 #ifndef COMPANION_FEATURE_BLE_MOTA_SOURCE
 #define COMPANION_FEATURE_BLE_MOTA_SOURCE 1
 #endif

test/test_nrf52_ble_trace.py

@@ -0,0 +1,120 @@
+#!/usr/bin/env python3
+"""Check the debug reader's bounds and its disabled production behavior."""
+from pathlib import Path
+import subprocess
+import tempfile
+import unittest
+
+ROOT = Path(__file__).resolve().parents[1]
+
+class BleTraceTest(unittest.TestCase):
+    def test_debug_records_are_bounded_and_disabled_calls_have_no_effect(self):
+        with tempfile.TemporaryDirectory() as directory:
+            work = Path(directory)
+            (work / 'Arduino.h').write_text(
+                '#include <stdint.h>\n#include <stddef.h>\n'
+                'inline uint32_t millis() { return 1234; }\ninline uint32_t micros() { return 4567; }\n')
+            source = work / 'trace.cpp'
+            source.write_text(r'''
+#include <cassert>
+#include <cstring>
+#include <helpers/nrf52/BleDebugTrace.h>
+#if MESH_NRF52_BLE_TRACE
+extern "C" { MeshBleTraceBuffer mesh_ble_trace; }
+void meshBleTraceState(char* reply, size_t capacity) {
+  snprintf(reply,capacity,"> state");
+}
+int main() {
+  char reply[160];
+  assert(!meshBleTraceCommand("get radio",reply,sizeof(reply)));
+  meshBleTrace(0xf002,0,0x16);
+  assert(meshBleTraceCommand("get bluetooth.trace 1",reply,sizeof(reply)));
+  assert(!strcmp(reply,"> 1,1234,0xf002,0,22,0"));
+  for(const char* command:{"get bluetooth.trace 0", "get bluetooth.trace -1",
+      "get bluetooth.trace 1 extra", "get bluetooth.trace 4294967296"}) {
+    assert(meshBleTraceCommand(command,reply,sizeof(reply)));
+    assert(!strncmp(reply,"Error:",6));
+  }
+  for(int i=0;i<256;++i)meshBleTrace(0x10);
+  assert(meshBleTraceCommand("get bluetooth.trace 1",reply,sizeof(reply)));
+  assert(!strcmp(reply,"Error: trace record unavailable"));
+  assert(meshBleTraceCommand("get bluetooth.trace 257",reply,sizeof(reply)));
+  assert(!strcmp(reply,"> 257,1234,0x0010,65535,0,0"));
+  assert(meshBleTraceCommand("get bluetooth.trace.state",reply,sizeof(reply)));
+  assert(!strcmp(reply,"> state"));
+  meshBleTraceDispatchEnter(0x10,0);
+  assert(mesh_ble_trace.dispatch_event.load()==0x10);
+  meshBleTraceDispatchExit(0x10,0);
+  assert(mesh_ble_trace.dispatch_event.load()==0);
+  mesh_ble_trace.writer.test_and_set();
+  meshBleTrace(0x10);
+  mesh_ble_trace.writer.clear();
+  assert(mesh_ble_trace.dropped.load()==1);
+  assert(mesh_ble_trace.next.load()==259);
+  assert(meshBleTraceCommand("get bluetooth.trace.timing",reply,sizeof(reply)));
+  assert(strstr(reply,"dispatch_event=0"));
+  char tiny[5] = {};
+  assert(meshBleTraceCommand("get bluetooth.trace",tiny,sizeof(tiny)));
+  assert(tiny[4]==0);
+}
+#else
+int main() {
+  int side_effect = 0;
+  meshBleTrace(++side_effect);
+  meshBleTraceMax(++side_effect,++side_effect);
+  meshBleTraceDispatchEnter(++side_effect,++side_effect);
+  meshBleTraceDispatchExit(++side_effect,++side_effect);
+  assert(side_effect==0);
+}
+#endif
+''')
+            for enabled in (0, 1):
+                binary = work / f'trace-{enabled}'
+                subprocess.run(['c++','-std=c++17','-include','initializer_list',
+                    f'-DMESH_NRF52_BLE_TRACE={enabled}', '-I'+str(work),
+                    '-I'+str(ROOT/'src'), str(source), '-o', str(binary)],
+                    check=True, capture_output=True)
+                subprocess.run([str(binary)],check=True,capture_output=True)
+
+    def test_concurrent_reader_never_accepts_mixed_records(self):
+        with tempfile.TemporaryDirectory() as directory:
+            work = Path(directory)
+            (work / 'Arduino.h').write_text(
+                '#include <stdint.h>\n#include <stddef.h>\n'
+                'inline uint32_t millis(){return 1234;}\n'
+                'inline uint32_t micros(){return 4567;}\n')
+            source = work / 'race.cpp'
+            source.write_text(r'''
+#include <cassert>
+#include <thread>
+#include <helpers/nrf52/BleDebugTrace.h>
+extern "C" { MeshBleTraceBuffer mesh_ble_trace; }
+void meshBleTraceState(char*,size_t) {}
+int main() {
+  std::atomic<bool> done{false};
+  std::thread writer([&]{
+    for(uint32_t i=1;i<100000;++i)meshBleTrace(i,i^0x12345678,i*3,i*7);
+    done.store(true);
+  });
+  do {
+    uint32_t next=mesh_ble_trace.next.load();
+    MeshBleTraceRecord r;
+    for(uint32_t i=(next>256?next-255:1);i<=next;++i) {
+      if(meshBleTraceRead(i,r)) {
+        assert(r.handle==(r.event^0x12345678));
+        assert(r.detail==r.event*3 && r.extra==r.event*7);
+      }
+    }
+  } while(!done.load());
+  writer.join();
+}
+''')
+            binary = work / 'race'
+            subprocess.run(['c++','-std=c++17','-O2','-pthread',
+                '-DMESH_NRF52_BLE_TRACE=1', '-I'+str(work),
+                '-I'+str(ROOT/'src'), str(source), '-o', str(binary)],
+                check=True,capture_output=True)
+            subprocess.run([str(binary)],check=True,capture_output=True)
+
+if __name__ == '__main__':
+    unittest.main()