diff --git a/.github/workflows/run-unit-tests.yml b/.github/workflows/run-unit-tests.yml index 35187307a..ee7833170 100644 --- a/.github/workflows/run-unit-tests.yml +++ b/.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 diff --git a/docs/nrf52_bluetooth_debug.md b/docs/nrf52_bluetooth_debug.md new file mode 100644 index 000000000..7331dc50e --- /dev/null +++ b/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. diff --git a/examples/companion_radio/MyMesh.cpp b/examples/companion_radio/MyMesh.cpp index 4da8506ec..d3e9342d1 100644 --- a/examples/companion_radio/MyMesh.cpp +++ b/examples/companion_radio/MyMesh.cpp @@ -29,6 +29,7 @@ #endif #if defined(NRF52_PLATFORM) #include +#include #endif #if defined(ENABLE_OTA) #include @@ -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; diff --git a/scripts/capture_nrf52_ble_debug.py b/scripts/capture_nrf52_ble_debug.py new file mode 100644 index 000000000..a49eb7aca --- /dev/null +++ b/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 --output . 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() diff --git a/scripts/nrf52_ble_cccd_fix.py b/scripts/nrf52_ble_cccd_fix.py index 15c75aaea..c1c4cd7c2 100644 --- a/scripts/nrf52_ble_cccd_fix.py +++ b/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 +#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) diff --git a/src/helpers/nrf52/BleDebugTrace.h b/src/helpers/nrf52/BleDebugTrace.h new file mode 100644 index 000000000..acfedae81 --- /dev/null +++ b/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 +#include +#include +#include +#include +#include + +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 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 next{0}, dropped{0}; + std::atomic_flag writer = ATOMIC_FLAG_INIT; + MeshBleTraceSlot records[MESH_BLE_TRACE_CAPACITY]; + std::atomic dispatch_event{0}, dispatch_started{0}, max_dispatch_us{0}; + std::atomic connects{0}, disconnects{0}, secured{0}, rx{0}, tx{0}; + std::atomic 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& 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 "); + 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 diff --git a/src/helpers/nrf52/SerialBLEInterface.cpp b/src/helpers/nrf52/SerialBLEInterface.cpp index af99def87..2d5191500 100644 --- a/src/helpers/nrf52/SerialBLEInterface.cpp +++ b/src/helpers/nrf52/SerialBLEInterface.cpp @@ -2,12 +2,19 @@ #include "../BluetoothMac.h" #include "../CompanionFrameQueue.h" #include "SoftDeviceState.h" +#include "BleDebugTrace.h" #include #include #include "ble_gap.h" #include "ble_hci.h" #include +#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; diff --git a/src/helpers/nrf52/SerialBLEInterface.h b/src/helpers/nrf52/SerialBLEInterface.h index d63392d89..1f77ec301 100644 --- a/src/helpers/nrf52/SerialBLEInterface.h +++ b/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 _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; diff --git a/test/test_nrf52_ble_debug_tools.py b/test/test_nrf52_ble_debug_tools.py new file mode 100644 index 000000000..795de2c9e --- /dev/null +++ b/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 \n#include \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 +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 +#include +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() diff --git a/test/test_nrf52_ble_reconnect_watchdog.py b/test/test_nrf52_ble_reconnect_watchdog.py index db8dec463..1a6080ef3 100644 --- a/test/test_nrf52_ble_reconnect_watchdog.py +++ b/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 static uint32_t current_millis; uint32_t millis() { return current_millis; } diff --git a/test/test_nrf52_ble_startup.py b/test/test_nrf52_ble_startup.py index 1c228778f..6828e1239 100644 --- a/test/test_nrf52_ble_startup.py +++ b/test/test_nrf52_ble_startup.py @@ -30,6 +30,7 @@ HARNESS = r''' #include #include #include +#include #ifndef COMPANION_FEATURE_BLE_MOTA_SOURCE #define COMPANION_FEATURE_BLE_MOTA_SOURCE 1 #endif diff --git a/test/test_nrf52_ble_trace.py b/test/test_nrf52_ble_trace.py new file mode 100644 index 000000000..e5b3afcc7 --- /dev/null +++ b/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 \n#include \n' + 'inline uint32_t millis() { return 1234; }\ninline uint32_t micros() { return 4567; }\n') + source = work / 'trace.cpp' + source.write_text(r''' +#include +#include +#include +#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 \n#include \n' + 'inline uint32_t millis(){return 1234;}\n' + 'inline uint32_t micros(){return 4567;}\n') + source = work / 'race.cpp' + source.write_text(r''' +#include +#include +#include +extern "C" { MeshBleTraceBuffer mesh_ble_trace; } +void meshBleTraceState(char*,size_t) {} +int main() { + std::atomic 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()