diff --git a/components/bt/common/ble_log/README.md b/components/bt/common/ble_log/README.md index eb049112cde..bc9b25f2058 100644 --- a/components/bt/common/ble_log/README.md +++ b/components/bt/common/ble_log/README.md @@ -1,495 +1,216 @@ -# BLE Log Module +# BLE Log -A high-performance, modular Bluetooth logging system that provides real-time log capture and asynchronous transmission capabilities for the ESP-IDF Bluetooth stack. +BLE Log is an asynchronous binary logging transport for Bluetooth controller, +Host HCI, application, and compressed logs. -## Table of Contents +## Architecture -- [Overview](#overview) -- [Architecture Design](#architecture-design) -- [Features](#features) -- [Quick Start](#quick-start) -- [Configuration Options](#configuration-options) -- [API Reference](#api-reference) -- [Usage Examples](#usage-examples) -- [Performance & Memory Optimization](#performance--memory-optimization) -- [Troubleshooting](#troubleshooting) -- [Important Notes](#important-notes) - -## Overview - -The BLE Log module is an efficient logging system specifically designed for the ESP-IDF Bluetooth stack, supporting real-time log capture, multi-source log collection, and various transmission methods. This module has been refactored with a modular design, featuring high-concurrency processing capabilities and low-latency characteristics. - -### Main Components - -- **BLE Log Core** (`ble_log.c`): Module core responsible for initialization and coordination of sub-modules -- **Runtime Manager** (`ble_log_rt.c`): One-shot ESP Timer dispatch for log transmission scheduling -- **Log Buffer Manager** (`ble_log_lbm.c`): Log buffer management supporting multiple locking mechanisms -- **Peripheral Interface** (`ble_log_prph_*.c`): Peripheral interface abstraction layer supporting various transmission methods -- **Timestamp Sync** (`ble_log_ts.c`): Timestamp synchronization module -- **Utility** (`ble_log_util.c`): Common utility functions - -## Features - -### Core Functionality - -- **Multi-source Log Collection**: Supports multiple log sources including Link Layer, Host, HCI, UART redirection, etc. -- **High Concurrency Processing**: Uses atomic and spin lock mechanisms for multi-task concurrent writing -- **Real-time Transmission**: Asynchronous transmission through ESP Timer task dispatch -- **Data Integrity**: Checksum mechanism ensures data integrity (always enabled) -- **Multi-buffer Transport**: Each LBM manages multiple transport buffers (default 4) for improved throughput over the legacy ping-pong design -- **Cross-pool Buffer Fallback**: LBM acquire attempts all atomic LBMs before falling back to spinlock LBMs, improving buffer availability under contention - -### Advanced Features - -- **UART Redirection**: When using UART DMA on PORT 0, UART output (including `esp_rom_printf`) is transparently redirected through the async log pipeline -- **Timestamp Synchronization**: Supports timestamp synchronization with external devices (optional) -- **Enhanced Statistics**: Detailed logging statistics including written/lost frame and byte counts (always enabled) -- **Buffer Utilization Reporting**: Per-LBM buffer utilization and inflight peak tracking for diagnostics -- **Link Layer Integration**: Deep integration with ESP-IDF Bluetooth Link Layer -- **Multiple Transmission Methods**: Supports SPI Master DMA, UART DMA, and Dummy transmission - -### Performance Features - -- **IRAM Optimization**: Critical path code runs in IRAM ensuring low latency -- **Lock-free Design**: Most operations use atomic operations reducing lock contention -- **Buffer Reuse**: Intelligent buffer management reduces memory allocation overhead - -## Quick Start - -### 1. Enable Module - -Enable the BLE Log module in `menuconfig`: - -``` -Component config → Bluetooth → Enable BT Log Async Output (Dev Only) +```mermaid +flowchart TD + A[Public and LL writers] --> P[Unified bitmap pool] + C[Compression encoder] --> P + S[Internal snapshot] --> I[Fixed internal transport] + R[UART0 redirection] --> D[Redirection transports] + P --> Q[ESP Timer runtime queue] + I --> Q + D --> Q + Q --> X[Peripheral DMA] ``` -### 2. Basic Configuration +The shared pool contains `CONFIG_BLE_LOG_POOL_TRANS_CNT` transports. The last +`CONFIG_BLE_LOG_POOL_NON_YIELD_RESERVE_CNT` transports are reserved for ISR and +other contexts that cannot yield. Ordinary public writes are non-blocking. +Only the ordinary controller LL task path waits for a shared transport. + +The Internal Snapshot and UART0 redirection transports are not members of the +bitmap pool. + +## Runtime dispatch + +Sealed transports enter one bounded queue. The first submission anchors a +one-shot ESP Timer deadline at 1 ms; later submissions do not move it. Each +callback drains the queue depth captured at entry and schedules another fixed +defer only for arrivals left behind, so it does not continuously monopolize +the shared ESP Timer task. + +## Version 7 frame + +All multi-byte fields use the target's little-endian representation. + +```text +offset size field +0 2 payload length +2 4 frame_meta +6 N payload +6 + N 4 checksum +``` + +`frame_meta` is: + +```text +bits 0..6 base source +bit 7 NON_YIELD +bits 8..31 sequence number, low 24 bits +``` + +The checksum is `ble_log_fast_checksum()` over the six-byte header and exactly +`payload length` bytes. It excludes the checksum field and peripheral-only DMA +padding. + +Core frames begin their payload with: + +```text +[4-byte low32 esp_timer_get_time() microseconds][source payload] +``` + +The timestamp is captured at API entry before any pool or UART0 redirection +mutex wait. It wraps approximately every 71.6 minutes and must be unwrapped +modulo 2^32 by the receiver. UART0 redirection retains its extension-specific +stream aggregation while using the same ESP Timer timestamp semantics. + +### Sources + +The public `ble_log_src_t` ABI is frozen and its values are the on-wire +source IDs of protocol v7 frames — the frame source byte carries the enum +value directly, so existing decoders keep working: + +```text +0 INTERNAL +1 CUSTOM +2 LL_TASK +3 LL_HCI +4 LL_ISR +5 HOST +6 HCI +7 ENCODE +8 REDIR extension +``` + +All non-INTERNAL sources share one 24-bit Global SN: it is consumed at API +entry, so it totally orders log attempts — including equal-timestamp records +from different sources — and every lost or rejected attempt leaves a gap +in the sequence. Internal Snapshot frames carry their own separate +sequence; a gap there counts skipped snapshots. Neither sequence is reset. +Actual ISR and critical-section records carry `NON_YIELD` in source bit 7. + +Controller-side HCI records are not emitted by BLE Log, and the controller no +longer maintains its own internal LL HCI log. Host-side Bluedroid and NimBLE +HCI capture (`CONFIG_BLE_LOG_HCI_LOG_ENABLED`) is the single HCI logging +switch and the authoritative `HCI` stream for both Host and Controller +traffic. Its direction bit continues to use HCI payload byte 0 bit 7; this is +independent of the source metadata bit. + +## Internal Snapshot + +All BLE Log-owned Internal information is emitted as one fixed-layout frame +from one dedicated 148-byte transport. Its logical frame length is 148 bytes. + +The snapshot contains: + +- reason flags (`INIT`, `PERIODIC`, `FLUSH`, `TS_VALID`); +- the complete 58-byte build, library, chip, and protocol version block; +- the LC clock, ESP Timer, and FreeRTOS tick samples captured together with + the GPIO sync level; +- pool count, reserve count, current inflight count, and inflight peak; +- compact statistics for `CUSTOM` through `ENCODE` (one slot per public + source in that range, `HOST` included). + +A skipped periodic snapshot burns one snapshot SN instead: the gap in the +snapshot sequence is the loss signal, and it is visible directly in the +frame header without a dedicated payload field. + +Each source statistic contains only: ```c -#include "ble_log.h" +uint32_t written_frame_cnt; +uint32_t lost_frame_cnt; +``` -void app_main() { - // Initialize BLE Log module - if (!ble_log_init()) { - ESP_LOGE(TAG, "Failed to initialize BLE Log"); - return; - } - - // Write log data - uint8_t data[] = {0x01, 0x02, 0x03, 0x04}; - ble_log_write_hex(BLE_LOG_SRC_CUSTOM, data, sizeof(data)); - - // End session and flush buffers - ble_log_flush(); - - // Cleanup resources - ble_log_deinit(); +Successful counts are incremented only after a complete frame is committed to +a transport; they do not imply confirmed physical TX. Core counts and the pool +peak restart after a completed FLUSH; the Global SN and the snapshot +sequence remain continuous. A busy periodic Internal +transport is never overwritten; that snapshot is skipped and counted. Required +INIT and FLUSH snapshots use a bounded task-context wait. + +The snapshot is not an Anchor: it does not seal the shared pool and does not +define a Log Segment boundary. + +## Public API + +```c +bool ble_log_init(void); +void ble_log_deinit(void); +bool ble_log_enable(bool enable); +void ble_log_flush(void); +bool ble_log_write_hex(ble_log_src_t source, const uint8_t *data, size_t len); +uint8_t *ble_log_claim(ble_log_src_t source, size_t maximum, uint32_t *handle); +void ble_log_commit(uint32_t handle, size_t actual_len); +void ble_log_write_hex_ll(uint32_t len, const uint8_t *data, + uint32_t append_len, const uint8_t *append, + uint32_t flags); +``` + +`ble_log_flush()` is an ordinary FreeRTOS task API. Do not call it from an ISR, +critical section, or the shared ESP Timer task. + +A public or LL record that cannot fit completely in one pool transport is +rejected and counted as lost; BLE Log never emits a truncated record. + +## Compression direct write + +Compression encoders write directly into shared-pool storage: + +```c +uint32_t handle; +uint8_t *payload = ble_log_claim(BLE_LOG_SRC_ENCODE, maximum, &handle); +if (payload) { + size_t encoded = encode(payload, maximum); + ble_log_commit(handle, encoded); } ``` -### 3. Link Layer Integration +`ble_log_claim()` reserves the hidden frame header, ESP Timer timestamp, and +checksum. Every successful claim must be committed exactly once before +`ble_log_deinit()`; `ble_log_commit(handle, 0)` cancels it. Handles include a +transport generation so a stale handle cannot commit a later claim in the same +lifecycle. -When `CONFIG_BLE_LOG_LL_ENABLED` is enabled, Link Layer logs are automatically integrated: +Mesh, ISO, Bluedroid, and NimBLE compression no longer allocate three static +payload buffers per channel. Each logical compression source uses a non-blocking +trylock so its task-switch state follows commit order; a contending record is +canceled and counted as lost. -```c -// Link Layer logs will automatically call this function -void ble_log_write_hex_ll(uint32_t len, const uint8_t *addr, - uint32_t len_append, const uint8_t *addr_append, - uint32_t flag); +## Configuration + +| Option | Default | Meaning | +| --- | ---: | --- | +| `CONFIG_BLE_LOG_ENABLED` | n | Enable BLE Log | +| `CONFIG_BLE_LOG_POOL_TRANS_CNT` | 8 | Unified pool transport count, range 2..32 | +| `CONFIG_BLE_LOG_POOL_NON_YIELD_RESERVE_CNT` | 1 | ISR/critical reserve count | +| `CONFIG_BLE_LOG_POOL_TRANS_SIZE` | 640 | Bytes per shared transport; SPI builds require a multiple of four | +| `CONFIG_BLE_LOG_LL_ENABLED` | target dependent | Controller LL logging | +| `CONFIG_BLE_LOG_HCI_LOG_ENABLED` | target dependent | Host-side HCI capture | +| `CONFIG_BLE_LOG_TS_ENABLED` | n | GPIO/LC timestamp synchronization | + +Old multi-LBM sizing options remain hidden only so existing sdkconfig files can +be parsed; they no longer control allocation. + +## Validation apps + +```bash +. ./export.sh +cd components/bt/common/ble_log/test_apps/ble_log_test +idf.py build + +cd ../ble_log_rt_test +idf.py build + +cd ../ble_log_perf_test +idf.py build ``` -## Configuration Options - -### Basic Configuration - -| Configuration | Default | Description | -|---------------|---------|-------------| -| `CONFIG_BLE_LOG_ENABLED` | n | Enable BT Log Async Output | -| `CONFIG_BLE_LOG_LBM_TRANS_BUF_SIZE` | 2048 | Total buffer memory per common LBM (bytes). Divided equally among `BLE_LOG_TRANS_BUF_CNT` (4) internal transport buffers. | -| `CONFIG_BLE_LOG_LBM_ATOMIC_LOCK_TASK_CNT` | 2 | Number of atomic lock LBMs for task context | -| `CONFIG_BLE_LOG_LBM_ATOMIC_LOCK_ISR_CNT` | 1 | Number of atomic lock LBMs for ISR context | - -### Link Layer Configuration - -| Configuration | Default | Description | -|---------------|---------|-------------| -| `CONFIG_BLE_LOG_LL_ENABLED` | y | Enable Link Layer logging | -| `CONFIG_BLE_LOG_LBM_LL_TRANS_BUF_SIZE` | 2048 | Total buffer memory per Link Layer LBM (bytes). Divided equally among `BLE_LOG_TRANS_BUF_CNT` (4) internal transport buffers. | - -### Other Features - -| Configuration | Default | Description | -|---------------|---------|-------------| -| `CONFIG_BLE_LOG_TS_ENABLED` | n | Enable timestamp synchronization | -| `CONFIG_BLE_LOG_HOST_HCI_LOG_ENABLED` | n | Enable BLE Host side HCI logging | - -> **Note**: Payload checksum and enhanced statistics are now always enabled and no longer have separate Kconfig options. - -### Transport Method Configuration - -| Transport | Configuration | Description | -|-----------|---------------|-------------| -| Dummy | `CONFIG_BLE_LOG_PRPH_DUMMY` | Debug dummy transport (default unless `SOC_UHCI_SUPPORTED`) | -| SPI Master DMA | `CONFIG_BLE_LOG_PRPH_SPI_MASTER_DMA` | SPI DMA transport | -| UART DMA | `CONFIG_BLE_LOG_PRPH_UART_DMA` | UART DMA transport (default when `SOC_UHCI_SUPPORTED`). Default baud rate: 3000000. | - -### Deprecated / Removed - -| Module | Status | Notes | -|--------|--------|-------| -| Legacy SPI Log Output | Deprecated | Moved to `deprecated/` directory. Use BT Log Async Output instead. A separate Kconfig menu "Legacy SPI Log Output" is available for backward compatibility. | -| UHCI Out | Removed | The standalone UHCI Out module (`ble_log_uhci_out.c`) has been removed. UART DMA transport under the main BLE Log peripheral interface replaces it. | - -## API Reference - -### Core API - -#### `bool ble_log_init(void)` - -Initialize the BLE Log module. - -**Return Value**: -- `true`: Initialization successful -- `false`: Initialization failed - -**Note**: Must be called before using any other APIs. - -#### `void ble_log_deinit(void)` - -Cleanup the BLE Log module and release all resources. - -**Note**: -- All pending logs will be lost after calling this function -- Peripheral interface will be cleaned up first to avoid DMA transmission issues during memory release -- This function may run concurrently with BLE Log write APIs. New writes are - rejected after shutdown begins, and deinit waits for in-progress writers - before releasing their buffers. - -#### `bool ble_log_write_hex(ble_log_src_t src_code, const uint8_t *addr, size_t len)` - -Write hexadecimal log data. - -**Parameters**: -- `src_code`: Log source code -- `addr`: Data pointer -- `len`: Data length - -**Return Value**: -- `true`: Write successful -- `false`: Write failed (module not initialized or insufficient buffer) - -#### `void ble_log_flush(void)` - -End the current logging session and flush pending logs immediately. - -This API temporarily suspends ordinary log writes, waits for in-progress -writers to exit, emits a final statistics internal frame, flushes pending -transport buffers, resets statistics, and then restores the enable state that -was in effect before the call. - -**Note**: This operation is blocking and must run in an ordinary caller-owned -FreeRTOS task. Do not call it from an ISR or a system callback such as an ESP -Timer callback. If BLE Log was enabled before the call, it remains enabled -after the flush completes. - -#### `void ble_log_dump_to_console(void)` - -Output all buffer contents to console in hexadecimal format for debugging. - -### Log Source Types - -```c -typedef enum { - BLE_LOG_SRC_INTERNAL = 0, // Internal system logs - BLE_LOG_SRC_CUSTOM, // User-defined logs - BLE_LOG_SRC_LL_TASK, // Link Layer task logs - BLE_LOG_SRC_LL_HCI, // Link Layer HCI logs - BLE_LOG_SRC_LL_ISR, // Link Layer interrupt logs - BLE_LOG_SRC_HOST, // Host layer logs - BLE_LOG_SRC_HCI, // HCI layer logs - BLE_LOG_SRC_ENCODE, // Encoding layer logs - BLE_LOG_SRC_REDIR, // UART redirection (PORT 0 only) - BLE_LOG_SRC_MAX, -} ble_log_src_t; -``` - -### HCI Log Macro - -```c -#define ble_log_write_hci(direction, data, len) -``` - -Writes an HCI packet with direction encoding. `direction` is `BLE_LOG_HCI_DOWNSTREAM` (0) or `BLE_LOG_HCI_UPSTREAM` (1). Direction is encoded in the MSB of the first byte (HCI type). - -### Link Layer API (Conditional Compilation) - -#### `void ble_log_write_hex_ll(uint32_t len, const uint8_t *addr, uint32_t len_append, const uint8_t *addr_append, uint32_t flag)` - -Link Layer dedicated log writing interface. - -**Parameters**: -- `len`: Main data length -- `addr`: Main data pointer -- `len_append`: Append data length -- `addr_append`: Append data pointer -- `flag`: Log flag bits - -**Flag Definitions**: -```c -enum { - BLE_LOG_LL_FLAG_CONTINUE = 0, - BLE_LOG_LL_FLAG_END, - BLE_LOG_LL_FLAG_TASK, - BLE_LOG_LL_FLAG_ISR, - BLE_LOG_LL_FLAG_HCI, - BLE_LOG_LL_FLAG_RAW, - BLE_LOG_LL_FLAG_OMDATA, - BLE_LOG_LL_FLAG_HCI_UPSTREAM, -}; -``` - -### Timestamp Synchronization API (Conditional Compilation) - -#### `bool ble_log_sync_enable(bool enable)` - -Enable or disable timestamp synchronization functionality. - -**Parameters**: -- `enable`: true to enable, false to disable - -**Return Value**: -- `true`: Operation successful -- `false`: Operation failed (module not initialized) - -## Usage Examples - -### Example 1: Basic Logging - -```c -#include "ble_log.h" - -void example_basic_logging() { - // Initialize - if (!ble_log_init()) { - printf("BLE Log init failed\n"); - return; - } - - // Log some example data - uint8_t hci_cmd[] = {0x01, 0x03, 0x0C, 0x00}; // HCI Reset Command - ble_log_write_hex(BLE_LOG_SRC_HCI, hci_cmd, sizeof(hci_cmd)); - - uint8_t host_data[] = {0x02, 0x00, 0x20, 0x0B, 0x00, 0x07, 0x00, 0x04, 0x00, 0x10, 0x01, 0x00, 0xFF, 0xFF, 0x00, 0x28}; - ble_log_write_hex(BLE_LOG_SRC_HOST, host_data, sizeof(host_data)); - - // End session and flush buffers - ble_log_flush(); - - // Cleanup - ble_log_deinit(); -} -``` - -### Example 2: ISR Context Logging - -```c -void IRAM_ATTR some_isr_handler() { - uint8_t isr_data[] = {0xDE, 0xAD, 0xBE, 0xEF}; - - // Safe to write logs in ISR context - ble_log_write_hex(BLE_LOG_SRC_LL_ISR, isr_data, sizeof(isr_data)); -} -``` - -### Example 3: Logging with Timestamp Synchronization - -```c -void example_with_timestamp_sync() { - if (!ble_log_init()) { - return; - } - - #if CONFIG_BLE_LOG_TS_ENABLED - // Enable timestamp synchronization - ble_log_sync_enable(true); - #endif - - // Log data... - uint8_t data[] = {0x01, 0x02, 0x03}; - ble_log_write_hex(BLE_LOG_SRC_CUSTOM, data, sizeof(data)); - - // Timestamp information will be automatically included in logs - - ble_log_deinit(); -} -``` - -### Example 4: Performance Testing - -```c -void example_performance_test() { - if (!ble_log_init()) { - return; - } - - uint8_t test_data[100]; - for (int i = 0; i < 100; i++) { - test_data[i] = i; - } - - uint32_t start_time = esp_timer_get_time(); - - // Send 1000 logs - for (int i = 0; i < 1000; i++) { - ble_log_write_hex(BLE_LOG_SRC_CUSTOM, test_data, sizeof(test_data)); - } - - // End session and flush buffers - ble_log_flush(); - uint32_t end_time = esp_timer_get_time(); - - printf("Time to write 1000 logs: %lu us\n", end_time - start_time); - - ble_log_deinit(); -} -``` - -## Performance & Memory Optimization - -### Memory Usage Estimation - -Each LBM's total buffer memory is configured directly via Kconfig. The configured value is divided equally among `BLE_LOG_TRANS_BUF_CNT` (currently 4) internal transport buffers. - -Memory usage under default configuration: - -``` -Common Pool: - LBM count = Atomic Task (2) + Atomic ISR (1) + Spinlock (2) = 5 - Total = 5 × BLE_LOG_LBM_TRANS_BUF_SIZE = 5 × 2048 = 10240 bytes - -Link Layer Pool (when CONFIG_BLE_LOG_LL_ENABLED): - LBM count = 2 (LL task + LL HCI) - Total = 2 × BLE_LOG_LBM_LL_TRANS_BUF_SIZE = 2 × 2048 = 4096 bytes - -Statistics (always enabled): - Total = BLE_LOG_SRC_MAX × sizeof(ble_log_stat_mgr_t) = 9 × 20 = 180 bytes - -UART Redirect (when UART DMA on PORT 0): - Additional BLE_LOG_TRANS_BUF_CNT (4) transport buffers -``` - -### Performance Optimization Recommendations - -1. **Adjust LBM Count**: Adjust atomic lock LBM count based on concurrency requirements -2. **Buffer Size**: Adjust total buffer memory per LBM based on log volume; must be a multiple of `BLE_LOG_TRANS_BUF_CNT` (4) -3. **Transport Method**: Choose optimal transport method based on hardware (UART DMA is default on supported SoCs) - -### Real-time Considerations - -- Critical code paths are marked with `BLE_LOG_IRAM_ATTR` and run in IRAM -- Atomic operations avoid lock contention -- Multi-buffer transport ensures continuous writing even when some buffers are in-flight - -## Troubleshooting - -### Common Issues - -#### 1. Initialization Failure - -**Symptoms**: `ble_log_init()` returns `false` - -**Possible Causes**: -- Insufficient memory -- Peripheral configuration error -- Duplicate initialization - -**Solutions**: -```c -// Check available memory -printf("Free heap: %d bytes\n", esp_get_free_heap_size()); - -// Ensure initialization only happens once -static bool initialized = false; -if (!initialized) { - initialized = ble_log_init(); -} -``` - -#### 2. Log Loss - -**Symptoms**: Some logs don't appear in output - -**Possible Causes**: -- Buffer overflow -- Transmission speed can't keep up with write speed -- Module not properly initialized - -**Solutions**: -```c -// Enhanced statistics are always enabled — check written/lost frame -// and byte counts in the log stream output - -// Increase total buffer memory per LBM -// CONFIG_BLE_LOG_LBM_TRANS_BUF_SIZE=4096 - -// Increase atomic lock LBM count -// CONFIG_BLE_LOG_LBM_ATOMIC_LOCK_TASK_CNT=4 -``` - -#### 3. Performance Issues - -**Symptoms**: System response becomes slow - -**Possible Causes**: -- Transmission bottleneck -- Lock contention - -**Solutions**: -```c -// Use faster transmission method -// CONFIG_BLE_LOG_PRPH_UART_DMA=y (default on SOC_UHCI_SUPPORTED targets) - -// Increase baud rate (default is now 3000000) -// CONFIG_BLE_LOG_PRPH_UART_DMA_BAUD_RATE=3000000 -``` - -### Debugging Techniques - -#### 1. Use Dummy Transport for Debugging - -```c -// Select Dummy transport in menuconfig -// Then use dump function to view buffer contents -ble_log_dump_to_console(); -``` - -#### 2. Check Enhanced Statistics - -```c -// Enhanced statistics are always enabled -// Written/lost frame and byte counts are automatically output to logs -``` - -#### 3. Monitor Memory Usage - -```c -void monitor_memory() { - printf("Free heap before init: %d\n", esp_get_free_heap_size()); - ble_log_init(); - printf("Free heap after init: %d\n", esp_get_free_heap_size()); -} -``` - -## Important Notes - -### Buffer Size Constraints - -- `CONFIG_BLE_LOG_LBM_TRANS_BUF_SIZE` and `CONFIG_BLE_LOG_LBM_LL_TRANS_BUF_SIZE` must be multiples of `BLE_LOG_TRANS_BUF_CNT` (currently 4) -- The per-buffer size (total ÷ 4) must be at least large enough to hold one frame overhead (`BLE_LOG_FRAME_OVERHEAD`) -- `BLE_LOG_TRANS_BUF_CNT` must be a power of 2 - -### Migration from Legacy Modules - -- **UHCI Out**: The standalone `ble_log_uhci_out` module has been removed. Use the UART DMA peripheral transport (`CONFIG_BLE_LOG_PRPH_UART_DMA`) instead. -- **SPI Out**: The legacy SPI log output has been moved to `deprecated/`. A separate Kconfig menu "Legacy SPI Log Output (Deprecated)" is available for backward compatibility, but new projects should use BT Log Async Output with the SPI Master DMA peripheral transport. +`ble_log_test` validates golden v7 bytes, the consolidated Internal Snapshot, +source/HCI metadata, pool exhaustion and reserve use, snapshot busy loss, +stale claims, and enable/disable/deinit races. `ble_log_rt_test` covers batched +dispatch, timer behavior, inflight statistics, and repeated deinit races. diff --git a/components/bt/common/ble_log/extension/log_compression/ble_log_compression.c b/components/bt/common/ble_log/extension/log_compression/ble_log_compression.c index 908f80289c1..8eaef8661b0 100644 --- a/components/bt/common/ble_log/extension/log_compression/ble_log_compression.c +++ b/components/bt/common/ble_log/extension/log_compression/ble_log_compression.c @@ -11,12 +11,27 @@ #include "freertos/FreeRTOS.h" #include "freertos/task.h" #include "sdkconfig.h" +#include "ble_log_lbm_v2.h" #include "ble_log_util.h" #include "log_compression/utils.h" #if CONFIG_BLE_COMPRESSED_LOG_ENABLE -#define BLE_CP_DROP_LOG_PERIOD 256U +#if CONFIG_BLE_MESH_COMPRESSED_LOG_ENABLE +_Static_assert(CONFIG_BLE_MESH_COMPRESSED_LOG_BUFFER_LEN <= + BLE_LOG_MAX_PAYLOAD_LEN - sizeof(uint32_t), + "Mesh compressed log record exceeds one BLE Log transport"); +#endif +#if CONFIG_BLE_ISO_COMPRESSED_LOG_ENABLE +_Static_assert(CONFIG_BLE_ISO_COMPRESSED_LOG_BUFFER_LEN <= + BLE_LOG_MAX_PAYLOAD_LEN - sizeof(uint32_t), + "ISO compressed log record exceeds one BLE Log transport"); +#endif +#if CONFIG_BLE_HOST_COMPRESSED_LOG_ENABLE +_Static_assert(CONFIG_BLE_HOST_COMPRESSED_LOG_BUFFER_LEN <= + BLE_LOG_MAX_PAYLOAD_LEN - sizeof(uint32_t), + "Host compressed log record exceeds one BLE Log transport"); +#endif #define BLE_CP_TRY_PUSH(expr) do { \ if ((expr) != 0) { \ @@ -24,61 +39,39 @@ } \ } while (0) -#define BUF_NAME(name, idx) name##_buffer##idx -#define BUF_MGMT_NAME(name) name##_log_buffer_mgmt - -#define DECL_BUF_OP(name, len, idx) \ - static uint8_t BUF_NAME(name, idx)[len]; - -#define INIT_MAP_OP(name, _, buffer_idx) \ - {.busy = 0, \ - .idx = 0, \ - .buffer = BUF_NAME(name, buffer_idx), \ - .len = sizeof(BUF_NAME(name, buffer_idx))}, - -#define DECLARE_BUFFERS(NAME, BUF_LEN, BUF_CNT) \ - FOR_EACH_IDX(DECL_BUF_OP, NAME, BUF_LEN, GEN_INDEX(BUF_CNT)); - -#define INIT_BUFFER_MGMT(NAME, BUF_CNT) \ - ble_cp_log_buffer_mgmt_t BUF_MGMT_NAME(NAME)[BUF_CNT] = { \ - FOR_EACH_IDX(INIT_MAP_OP, NAME, 0, GEN_INDEX(BUF_CNT)) \ - }; - #if CONFIG_BLE_MESH_COMPRESSED_LOG_ENABLE -DECLARE_BUFFERS(mesh, CONFIG_BLE_MESH_COMPRESSED_LOG_BUFFER_LEN, LOG_CP_MAX_LOG_BUFFER_USED_SIMU); -INIT_BUFFER_MGMT(mesh, LOG_CP_MAX_LOG_BUFFER_USED_SIMU); char * mesh_last_task_handle = NULL; +static ble_log_atomic_lock_t mesh_source_lock; #endif #if CONFIG_BLE_ISO_COMPRESSED_LOG_ENABLE -/* The BLE_ISO buffer is shared by every source compiled into the unified - * ISO channel: esp_ble_iso, esp_ble_audio (and future ISO consumers, e.g. - * HID-over-ISO), as well as the AUDIO_LIB runtime callback (prebuilt - * libble_audio.a, source code 5) — they all funnel here. */ -DECLARE_BUFFERS(iso, CONFIG_BLE_ISO_COMPRESSED_LOG_BUFFER_LEN, LOG_CP_MAX_LOG_BUFFER_USED_SIMU); -INIT_BUFFER_MGMT(iso, LOG_CP_MAX_LOG_BUFFER_USED_SIMU); char * iso_last_task_handle = NULL; +static ble_log_atomic_lock_t iso_source_lock; #endif #if CONFIG_BLE_HOST_COMPRESSED_LOG_ENABLE && CONFIG_BT_BLUEDROID_ENABLED -DECLARE_BUFFERS(host, CONFIG_BLE_HOST_COMPRESSED_LOG_BUFFER_LEN, LOG_CP_MAX_LOG_BUFFER_USED_SIMU); -INIT_BUFFER_MGMT(host, LOG_CP_MAX_LOG_BUFFER_USED_SIMU); char * host_last_task_handle = NULL; +static ble_log_atomic_lock_t host_source_lock; #endif #if CONFIG_BLE_HOST_COMPRESSED_LOG_ENABLE && CONFIG_BT_NIMBLE_ENABLED -DECLARE_BUFFERS(nimble, CONFIG_BLE_HOST_COMPRESSED_LOG_BUFFER_LEN, LOG_CP_MAX_LOG_BUFFER_USED_SIMU); -INIT_BUFFER_MGMT(nimble, LOG_CP_MAX_LOG_BUFFER_USED_SIMU); char * nimble_last_task_handle = NULL; +static ble_log_atomic_lock_t nimble_source_lock; +#endif + +#if CONFIG_BLE_LOG_PRPH_TEST +extern void ble_log_test_compression_after_lock_hook(uint8_t source) +__attribute__((weak)); #endif /* The maximum number of supported parameters is 64 */ #define LOG_HEADER(log_type, info) ((log_type << 6) | (info & 0x3f)) -int ble_compressed_log_cb_get(uint8_t source, ble_cp_log_buffer_mgmt_t **mgmt) +int ble_compressed_log_cb_get(uint8_t source, ble_cp_log_buffer_mgmt_t *mgmt) { - ble_cp_log_buffer_mgmt_t *buffer_mgmt = NULL; char ** last_handle = NULL; + ble_log_atomic_lock_t *source_lock = NULL; + uint16_t claim_len = 0; char * cur_handle = pcTaskGetName(NULL); switch (source) @@ -86,25 +79,28 @@ int ble_compressed_log_cb_get(uint8_t source, ble_cp_log_buffer_mgmt_t **mgmt) #if CONFIG_BLE_MESH_COMPRESSED_LOG_ENABLE case BLE_COMPRESSED_LOG_OUT_SOURCE_MESH: case BLE_COMPRESSED_LOG_OUT_SOURCE_MESH_LIB: - buffer_mgmt = BUF_MGMT_NAME(mesh); last_handle = &mesh_last_task_handle; + source_lock = &mesh_source_lock; + claim_len = CONFIG_BLE_MESH_COMPRESSED_LOG_BUFFER_LEN; break; #endif #if CONFIG_BLE_ISO_COMPRESSED_LOG_ENABLE case BLE_COMPRESSED_LOG_OUT_SOURCE_ISO: case BLE_COMPRESSED_LOG_OUT_SOURCE_AUDIO_LIB: - buffer_mgmt = BUF_MGMT_NAME(iso); last_handle = &iso_last_task_handle; + source_lock = &iso_source_lock; + claim_len = CONFIG_BLE_ISO_COMPRESSED_LOG_BUFFER_LEN; break; #endif #if CONFIG_BLE_HOST_COMPRESSED_LOG_ENABLE && (CONFIG_BT_BLUEDROID_ENABLED || CONFIG_BT_NIMBLE_ENABLED) case BLE_COMPRESSED_LOG_OUT_SOURCE_HOST: + claim_len = CONFIG_BLE_HOST_COMPRESSED_LOG_BUFFER_LEN; #if CONFIG_BT_BLUEDROID_ENABLED - buffer_mgmt = BUF_MGMT_NAME(host); last_handle = &host_last_task_handle; + source_lock = &host_source_lock; #elif CONFIG_BT_NIMBLE_ENABLED - buffer_mgmt = BUF_MGMT_NAME(nimble); last_handle = &nimble_last_task_handle; + source_lock = &nimble_source_lock; #endif break; #endif @@ -113,37 +109,59 @@ int ble_compressed_log_cb_get(uint8_t source, ble_cp_log_buffer_mgmt_t **mgmt) return -1; } - for (int i = 0; i < LOG_CP_MAX_LOG_BUFFER_USED_SIMU; i++) { - if (ble_log_cas_acquire(&(buffer_mgmt[i].busy))) { - *mgmt = &buffer_mgmt[i]; - if (ble_log_cp_push_u8(*mgmt, source) != 0) { - (*mgmt)->idx = 0; - ble_log_cas_release(&((*mgmt)->busy)); - return -1; - } - if (*last_handle == NULL || - *last_handle != cur_handle) { - if (ble_log_cp_push_u8(*mgmt, LOG_HEADER(LOG_TYPE_INFO, LOG_TYPE_INFO_TASK_SWITCH)) != 0) { - (*mgmt)->idx = 0; - ble_log_cas_release(&((*mgmt)->busy)); - return -1; - } - *last_handle = cur_handle; - } - return 0; - } + mgmt->len = claim_len; + mgmt->idx = 0; + mgmt->source_lock = source_lock; + mgmt->last_task_handle = last_handle; + mgmt->current_task_handle = cur_handle; + mgmt->task_switched = false; + mgmt->buffer = ble_log_claim(BLE_LOG_SRC_ENCODE, claim_len, &mgmt->handle); + if (!mgmt->buffer) { + return -1; } + if (!BLE_LOG_CAS_ACQUIRE(source_lock)) { + ble_log_commit(mgmt->handle, 0); + return -1; + } +#if CONFIG_BLE_LOG_PRPH_TEST + if (ble_log_test_compression_after_lock_hook) { + ble_log_test_compression_after_lock_hook(source); + } +#endif - return -1; + if (ble_log_cp_push_u8(mgmt, source) != 0) { + ble_log_commit(mgmt->handle, 0); + BLE_LOG_CAS_RELEASE(source_lock); + return -1; + } + char *previous_handle = __atomic_load_n(last_handle, __ATOMIC_RELAXED); + if (previous_handle == NULL || previous_handle != cur_handle) { + if (ble_log_cp_push_u8( + mgmt, LOG_HEADER(LOG_TYPE_INFO, LOG_TYPE_INFO_TASK_SWITCH)) != 0) { + ble_log_commit(mgmt->handle, 0); + BLE_LOG_CAS_RELEASE(source_lock); + return -1; + } + mgmt->task_switched = true; + } + return 0; } -static inline int ble_compressed_log_buffer_free(ble_cp_log_buffer_mgmt_t *mgmt) +static inline int ble_compressed_log_commit(ble_cp_log_buffer_mgmt_t *mgmt) { -#if BLE_LOG_CP_CONTENT_CHECK_ENABLE - memset(mgmt->buffer, BLE_LOG_CP_CONTENT_CHECK_VAL, mgmt->idx); -#endif - mgmt->idx = 0; - ble_log_cas_release(&mgmt->busy); + ble_log_commit(mgmt->handle, mgmt->idx); + if (mgmt->task_switched) { + __atomic_store_n(mgmt->last_task_handle, mgmt->current_task_handle, + __ATOMIC_RELAXED); + } + BLE_LOG_CAS_RELEASE(mgmt->source_lock); + return 0; +} + +static inline int ble_compressed_log_abort(ble_cp_log_buffer_mgmt_t *mgmt) +{ + ble_log_commit(mgmt->handle, 0); + BLE_LOG_CAS_RELEASE(mgmt->source_lock); return 0; } @@ -287,76 +305,72 @@ int ble_log_compressed_hex_print_internal(ble_cp_log_buffer_mgmt_t *mgmt, uint32 int ble_log_compressed_hex_printv(uint8_t source, uint32_t log_index, size_t args_cnt, va_list args) { - ble_cp_log_buffer_mgmt_t *mgmt = NULL; + ble_cp_log_buffer_mgmt_t mgmt; if (ble_compressed_log_cb_get(source, &mgmt)) { return 0; } - if (ble_log_compressed_hex_print_internal(mgmt, log_index, args_cnt, args) != 0) { - ble_compressed_log_buffer_free(mgmt); + if (ble_log_compressed_hex_print_internal(&mgmt, log_index, args_cnt, args) != 0) { + ble_compressed_log_abort(&mgmt); return 0; } - ble_compressed_log_output(source, mgmt->buffer, mgmt->idx); - ble_compressed_log_buffer_free(mgmt); + ble_compressed_log_commit(&mgmt); return 0; } int ble_log_compressed_hex_print(uint8_t source, uint32_t log_index, size_t args_cnt, ...) { - ble_cp_log_buffer_mgmt_t *mgmt = NULL; + ble_cp_log_buffer_mgmt_t mgmt; if (ble_compressed_log_cb_get(source, &mgmt)) { return 0; } if (args_cnt == 0) { - if (ble_log_cp_push_u8(mgmt, LOG_HEADER(LOG_TYPE_HEX_ARGS, 0)) != 0 || - ble_log_cp_push_u16(mgmt, log_index) != 0) { - ble_compressed_log_buffer_free(mgmt); + if (ble_log_cp_push_u8(&mgmt, LOG_HEADER(LOG_TYPE_HEX_ARGS, 0)) != 0 || + ble_log_cp_push_u16(&mgmt, log_index) != 0) { + ble_compressed_log_abort(&mgmt); return 0; } } else { va_list args; va_start(args, args_cnt); - if (ble_log_compressed_hex_print_internal(mgmt, log_index, args_cnt, args) != 0) { + if (ble_log_compressed_hex_print_internal(&mgmt, log_index, args_cnt, args) != 0) { va_end(args); - ble_compressed_log_buffer_free(mgmt); + ble_compressed_log_abort(&mgmt); return 0; } va_end(args); } - ble_compressed_log_output(source, mgmt->buffer, mgmt->idx); - ble_compressed_log_buffer_free(mgmt); + ble_compressed_log_commit(&mgmt); return 0; } int ble_log_compressed_hex_print_buf(uint8_t source, uint32_t log_index, uint8_t buf_idx, const uint8_t *buf, size_t len) { - ble_cp_log_buffer_mgmt_t *mgmt = NULL; + ble_cp_log_buffer_mgmt_t mgmt; if (ble_compressed_log_cb_get(source, &mgmt)) { return 0; } if (buf == NULL) { - ble_log_cp_push_u8(mgmt, LOG_HEADER(LOG_TYPE_INFO, LOG_TYPE_INFO_NULL_BUF)); - ble_log_cp_push_u16(mgmt, log_index); - ble_compressed_log_output(source, mgmt->buffer, mgmt->idx); - ble_compressed_log_buffer_free(mgmt); + ble_log_cp_push_u8(&mgmt, LOG_HEADER(LOG_TYPE_INFO, LOG_TYPE_INFO_NULL_BUF)); + ble_log_cp_push_u16(&mgmt, log_index); + ble_compressed_log_commit(&mgmt); return 0; } - if (ble_log_cp_push_u8(mgmt, LOG_HEADER(LOG_TYPE_HEX_BUF, buf_idx)) != 0 || - ble_log_cp_push_u16(mgmt, log_index) != 0 || - ble_log_cp_push_u16(mgmt, (uint16_t)len) != 0 || - ble_log_cp_push_buf(mgmt, buf, (uint16_t)len) != 0) { - ble_compressed_log_buffer_free(mgmt); + if (ble_log_cp_push_u8(&mgmt, LOG_HEADER(LOG_TYPE_HEX_BUF, buf_idx)) != 0 || + ble_log_cp_push_u16(&mgmt, log_index) != 0 || + ble_log_cp_push_u16(&mgmt, (uint16_t)len) != 0 || + ble_log_cp_push_buf(&mgmt, buf, (uint16_t)len) != 0) { + ble_compressed_log_abort(&mgmt); return 0; } - ble_compressed_log_output(source, mgmt->buffer, mgmt->idx); - ble_compressed_log_buffer_free(mgmt); + ble_compressed_log_commit(&mgmt); return 0; } #endif /* CONFIG_BLE_COMPRESSED_LOG_ENABLE */ diff --git a/components/bt/common/ble_log/extension/log_compression/include/log_compression/utils.h b/components/bt/common/ble_log/extension/log_compression/include/log_compression/utils.h index 6197b1d6e0f..fe35e793ff3 100644 --- a/components/bt/common/ble_log/extension/log_compression/include/log_compression/utils.h +++ b/components/bt/common/ble_log/extension/log_compression/include/log_compression/utils.h @@ -10,49 +10,6 @@ #include #include -#ifndef CONCAT -#define CONCAT(a, b) a##b -#endif - -#ifndef _CONCAT -#define _CONCAT(a, b) CONCAT(a, b) -#endif - -#define _0 0 -#define _1 1 -#define _2 2 -#define _3 3 -#define _4 4 -#define _5 5 -#define _6 6 -#define _7 7 -#define _8 8 -#define _9 9 - -#define __COUNT_ARGS(_0, _1, _2, _3, _4, _5, _6, _7, _8, _9, _10, _11, _12, _n, X...) _n -#define COUNT_ARGS(X...) __COUNT_ARGS(, ##X, 12, 11, 10, 9, 8, 7, 6, 5, 4, 3, 2, 1, 0) - -#ifndef FOR_EACH_IDX -#define FOR_EACH_IDX(macro, name, len, ...) \ - _CONCAT(_FOR_EACH_, COUNT_ARGS(__VA_ARGS__))(macro, name, len, __VA_ARGS__) -#endif - -#define _FOR_EACH_0(m, n, l, ...) -#define _FOR_EACH_1(m, n, l, i1, ...) m(n, l, i1) -#define _FOR_EACH_2(m, n, l, i1, ...) m(n, l, i1) _FOR_EACH_1(m, n, l, __VA_ARGS__) -#define _FOR_EACH_3(m, n, l, i1, ...) m(n, l, i1) _FOR_EACH_2(m, n, l, __VA_ARGS__) -#define _FOR_EACH_4(m, n, l, i1, ...) m(n, l, i1) _FOR_EACH_3(m, n, l, __VA_ARGS__) -#define _FOR_EACH_5(m, n, l, i1, ...) m(n, l, i1) _FOR_EACH_4(m, n, l, __VA_ARGS__) - -#define _GEN_INDEX_0() -#define _GEN_INDEX_1() _0 -#define _GEN_INDEX_2() _0, _1 -#define _GEN_INDEX_3() _0, _1, _2 -#define _GEN_INDEX_4() _0, _1, _2, _3 -#define _GEN_INDEX_5() _0, _1, _2, _3, _4 -#define GEN_INDEX(n) _CONCAT(_GEN_INDEX_, n)() - - enum { BLE_COMPRESSED_LOG_OUT_SOURCE_HOST, BLE_COMPRESSED_LOG_OUT_SOURCE_MESH, @@ -72,9 +29,6 @@ enum { ARG_SIZE_TYPE_MAX, }; -/* The maximum number of buffers used simultaneously */ -#define LOG_CP_MAX_LOG_BUFFER_USED_SIMU 3 - #define LOG_TYPE_ZERO_ARGS 0 #define LOG_TYPE_HEX_ARGS 1 #define LOG_TYPE_HEX_BUF 2 @@ -87,32 +41,22 @@ enum { #define LOG_TYPE_INFO_TASK_SWITCH 2 typedef struct { - volatile bool busy; - uint8_t *buffer; - uint16_t idx; - uint16_t len; + uint8_t *buffer; /* claim() payload pointer */ + uint16_t idx; /* bytes written so far */ + uint16_t len; /* claimed capacity (max_len) */ + uint32_t handle; /* claim handle for commit/abort */ + volatile uint32_t *source_lock; + char **last_task_handle; + char *current_task_handle; + bool task_switched; } ble_cp_log_buffer_mgmt_t; -#define CONTENT_CHECK(idx, buf, except_val, len) -#define LENGTH_CHECK(idx, pbuffer_mgmt) do ( if(unlikely((idx) > (pbuffer_mgmt->len))) assert(0 && "Maximum log buffer length exceeded");) while(0) - -#define BLE_LOG_CP_CONTENT_CHECK_ENABLE 0 -#define BLE_LOG_CP_CONTENT_CHECK_VAL 0x00 - static inline int ble_log_cp_buffer_safe_check(ble_cp_log_buffer_mgmt_t *pbuf_mgmt, uint16_t write_len) { if ((pbuf_mgmt->idx + write_len) > pbuf_mgmt->len) { printf("Maximum length of buffer(%p) idx %d write_len %d exceed\n", pbuf_mgmt, pbuf_mgmt->idx, write_len); return -1; } -#if BLE_LOG_CP_CONTENT_CHECK_ENABLE - for (int i = pbuf_mgmt->idx; i < pbuf_mgmt->idx + write_len; i++) { - if (pbuf_mgmt->buffer[i] != BLE_LOG_CP_CONTENT_CHECK_VAL) { - printf("The value(%02x) in the buffer does not match the expected(%02x)\n", pbuf_mgmt->buffer[i], BLE_LOG_CP_CONTENT_CHECK_VAL); - return -1; - } - } -#endif return 0; } @@ -182,17 +126,4 @@ static inline int ble_log_cp_update_half_byte(ble_cp_log_buffer_mgmt_t *pbuf_mgm return 0; } -static inline int ble_log_cp_buffer_print(ble_cp_log_buffer_mgmt_t *pbuf_mgmt) -{ - for (size_t i = 0; i < pbuf_mgmt->idx; i++) { - printf("%02x ", pbuf_mgmt->buffer[i]); - } - printf("\n"); - return 0; -} - -static inline int ble_compressed_log_output(uint8_t source, uint8_t *data, uint16_t len) -{ - return ble_log_write_hex(BLE_LOG_SRC_ENCODE, data, len); -} #endif /* _BLE_LOG_COMPRESSION_UTILS_H */ diff --git a/components/bt/common/ble_log/src/ble_log_lbm_v2.c b/components/bt/common/ble_log/src/ble_log_lbm_v2.c index 9306da8ea8a..a52039fb04a 100644 --- a/components/bt/common/ble_log/src/ble_log_lbm_v2.c +++ b/components/bt/common/ble_log/src/ble_log_lbm_v2.c @@ -33,7 +33,7 @@ #define BLE_LOG_WAIT_TIMEOUT_TICKS pdMS_TO_TICKS(1000) /* Single-instruction clock read; a function would add an IRAM call site. */ -#define ble_log_timestamp_now() ((uint32_t)esp_timer_get_time()) +#define BLE_LOG_TIMESTAMP_NOW() ((uint32_t)esp_timer_get_time()) /* ------------------------------- */ /* Global Pool Context */ @@ -196,7 +196,7 @@ ble_log_pool_publish_open_and_unlock(ble_log_prph_trans_t *trans) BLE_LOG_ATOMIC_STORE_RELAXED(trans->state, BLE_LOG_TRANS_STATE_OPEN); /* The following lock release publishes both state and frame data. */ __atomic_fetch_or(&g_pool.open_bitmap, BIT(trans->id), __ATOMIC_RELAXED); - ble_log_cas_release(&trans->atomic_lock); + BLE_LOG_CAS_RELEASE(&trans->atomic_lock); ble_log_pool_notify_waiter(trans->id); } @@ -253,7 +253,7 @@ BLE_LOG_IRAM_ATTR void ble_log_pool_seal_and_send(ble_log_prph_trans_t *trans) /* Release the lock BEFORE submitting. The buffer is now in no bitmap and * is SENDING, so no other writer can find it. */ - ble_log_cas_release(&trans->atomic_lock); + BLE_LOG_CAS_RELEASE(&trans->atomic_lock); ble_log_rt_submit_trans(trans); } @@ -281,12 +281,12 @@ ble_log_prph_trans_t *ble_log_pool_try_claim_from(volatile uint32_t *bitmap, } ble_log_prph_trans_t *trans = g_pool.trans[id]; - if (!ble_log_cas_acquire(&trans->atomic_lock)) { + if (!BLE_LOG_CAS_ACQUIRE(&trans->atomic_lock)) { continue; } if (BLE_LOG_ATOMIC_LOAD_RELAXED(trans->state) != expected_state) { /* The bitmap is only a hint; another owner may have changed state. */ - ble_log_cas_release(&trans->atomic_lock); + BLE_LOG_CAS_RELEASE(&trans->atomic_lock); continue; } @@ -323,7 +323,7 @@ ble_log_prph_trans_t *ble_log_pool_try_claim_available(uint32_t frame_len, bool uint8_t open_id = (uint8_t)BLE_LOG_ATOMIC_LOAD_RELAXED(g_pool.open_cursor); if (open_domain & BIT(open_id)) { ble_log_prph_trans_t *open_trans = g_pool.trans[open_id]; - if (ble_log_cas_acquire(&open_trans->atomic_lock)) { + if (BLE_LOG_CAS_ACQUIRE(&open_trans->atomic_lock)) { if (BLE_LOG_ATOMIC_LOAD_RELAXED(open_trans->state) == BLE_LOG_TRANS_STATE_OPEN) { if (BLE_LOG_TRANS_FREE_SPACE(open_trans) >= frame_len) { ble_log_pool_bitmap_clear(&g_pool.open_bitmap, open_id); @@ -331,7 +331,7 @@ ble_log_prph_trans_t *ble_log_pool_try_claim_available(uint32_t frame_len, bool } ble_log_pool_seal_and_send(open_trans); /* releases the lock */ } else { - ble_log_cas_release(&open_trans->atomic_lock); + BLE_LOG_CAS_RELEASE(&open_trans->atomic_lock); } } } @@ -479,7 +479,7 @@ uint8_t *ble_log_claim(ble_log_src_t src_code, size_t max_len, uint32_t *handle) uint32_t frame_sn = BLE_LOG_GET_GLOBAL_SN(); /* The timestamp is the log occurrence time, before pool contention. */ - uint32_t timestamp = ble_log_timestamp_now(); + uint32_t timestamp = BLE_LOG_TIMESTAMP_NOW(); bool non_yield = !xPortCanYield() || xTaskGetSchedulerState() != taskSCHEDULER_RUNNING; size_t payload_capacity = sizeof(timestamp) + max_len; @@ -535,7 +535,7 @@ void ble_log_commit(uint32_t handle, size_t actual_len) if (trans->pos == 0) { BLE_LOG_ATOMIC_STORE_RELEASE(trans->state, BLE_LOG_TRANS_STATE_FREE); ble_log_pool_bitmap_set(&g_pool.free_bitmap, trans->id); - ble_log_cas_release(&trans->atomic_lock); + BLE_LOG_CAS_RELEASE(&trans->atomic_lock); ble_log_pool_notify_waiter(trans->id); } else { ble_log_pool_publish_open_and_unlock(trans); @@ -835,15 +835,15 @@ bool ble_log_internal_snapshot(uint16_t reason_flags, /* Capture the complete occurrence sample before any dedicated-buffer * drain or wait. Without a TS sync sample, esp_ts comes from the frame * timestamp and os_ts from the current tick. */ - uint32_t timestamp = ts_info ? ts_info->esp_ts : ble_log_timestamp_now(); + uint32_t timestamp = ts_info ? ts_info->esp_ts : BLE_LOG_TIMESTAMP_NOW(); TickType_t start_tick = xTaskGetTickCount(); for (;;) { - if (ble_log_cas_acquire(&internal_trans->atomic_lock)) { + if (BLE_LOG_CAS_ACQUIRE(&internal_trans->atomic_lock)) { if (BLE_LOG_ATOMIC_LOAD_RELAXED(internal_trans->state) == BLE_LOG_TRANS_STATE_FREE) { break; } - ble_log_cas_release(&internal_trans->atomic_lock); + BLE_LOG_CAS_RELEASE(&internal_trans->atomic_lock); } if (!required || (xTaskGetTickCount() - start_tick) >= BLE_LOG_WAIT_TIMEOUT_TICKS) { @@ -885,7 +885,7 @@ bool ble_log_internal_snapshot(uint16_t reason_flags, internal_trans->pos = BLE_LOG_INTERNAL_FRAME_LEN; BLE_LOG_ATOMIC_STORE_RELAXED(internal_trans->state, BLE_LOG_TRANS_STATE_SENDING); - ble_log_cas_release(&internal_trans->atomic_lock); + BLE_LOG_CAS_RELEASE(&internal_trans->atomic_lock); ble_log_rt_submit_trans(internal_trans); BLE_LOG_REF_COUNT_RELEASE(&lbm_ref_count); return true; @@ -905,14 +905,14 @@ BLE_LOG_STATIC bool ble_log_pool_flush_all_trans(void) * current frame copy. Seal every remaining OPEN transport. */ for (int id = 0; id < BLE_LOG_POOL_TRANS_CNT; id++) { ble_log_prph_trans_t *trans = g_pool.trans[id]; - while (!ble_log_cas_acquire(&trans->atomic_lock)) { + while (!BLE_LOG_CAS_ACQUIRE(&trans->atomic_lock)) { } if (BLE_LOG_ATOMIC_LOAD_RELAXED(trans->state) == BLE_LOG_TRANS_STATE_OPEN && trans->pos > 0) { ble_log_pool_bitmap_clear(&g_pool.open_bitmap, id); ble_log_pool_seal_and_send(trans); /* releases the lock */ } else { - ble_log_cas_release(&trans->atomic_lock); + BLE_LOG_CAS_RELEASE(&trans->atomic_lock); } } @@ -941,14 +941,14 @@ void ble_log_lbm_flush_open_transports(void) continue; } ble_log_prph_trans_t *trans = g_pool.trans[id]; - if (!ble_log_cas_acquire(&trans->atomic_lock)) { + if (!BLE_LOG_CAS_ACQUIRE(&trans->atomic_lock)) { continue; } if (BLE_LOG_ATOMIC_LOAD_RELAXED(trans->state) == BLE_LOG_TRANS_STATE_OPEN && trans->pos > 0) { ble_log_pool_seal_and_send(trans); } else { - ble_log_cas_release(&trans->atomic_lock); + BLE_LOG_CAS_RELEASE(&trans->atomic_lock); } } @@ -1096,7 +1096,7 @@ bool ble_log_write_hex(ble_log_src_t src_code, const uint8_t *addr, size_t len) bool is_isr = BLE_LOG_IN_ISR(); bool can_yield = !is_isr && xPortCanYield() && xTaskGetSchedulerState() == taskSCHEDULER_RUNNING; - uint32_t timestamp = ble_log_timestamp_now(); + uint32_t timestamp = BLE_LOG_TIMESTAMP_NOW(); size_t payload_len = sizeof(timestamp) + len; ble_log_prph_trans_t *trans = ble_log_pool_acquire(payload_len, !can_yield, false); diff --git a/components/bt/common/ble_log/src/internal_include/ble_log_util.h b/components/bt/common/ble_log/src/internal_include/ble_log_util.h index 260cd6851ac..e12787523b5 100644 --- a/components/bt/common/ble_log/src/internal_include/ble_log_util.h +++ b/components/bt/common/ble_log/src/internal_include/ble_log_util.h @@ -80,9 +80,9 @@ extern void esp_panic_handler_feed_wdts(void); /* INLINE */ /* Compare-and-swap lock as macros: single-instruction acquire/release used * from several IRAM sites; a function would add an IRAM call site each. */ -#define ble_log_cas_acquire(cas_lock) \ +#define BLE_LOG_CAS_ACQUIRE(cas_lock) \ (__atomic_exchange_n((cas_lock), 1, __ATOMIC_ACQUIRE) == 0) -#define ble_log_cas_release(cas_lock) \ +#define BLE_LOG_CAS_RELEASE(cas_lock) \ __atomic_store_n((cas_lock), 0, __ATOMIC_RELEASE) #define BLE_LOG_VERSION (7) diff --git a/components/bt/common/ble_log/test_apps/ble_log_perf_test/README.md b/components/bt/common/ble_log/test_apps/ble_log_perf_test/README.md index de7c10477f3..50fd303a5ec 100644 --- a/components/bt/common/ble_log/test_apps/ble_log_perf_test/README.md +++ b/components/bt/common/ble_log/test_apps/ble_log_perf_test/README.md @@ -28,9 +28,11 @@ Runtime dispatch behavior and latency are covered by the sibling - `throughput`: fixed 32B / 64B / 128B / mixed 8-64B payload profiles, each at 2 Mbps, 20 Mbps, and unlimited link. Runs 3 write_hex writers + LL task + LL HCI + compressed writer + 1 kHz ISR writer concurrently. -- `write_hex cycles`: single writer, no link cap, payload 8/32/64/128 B. +- `write_hex cycles`: single writer, no link cap, payload 8/32/64/128 B. The + scheduler remains active during each measured call, followed by an unmeasured + one-tick pacing delay so the no-loss profile does not become a saturation test. - `write_hex drop path cycles`: saturated 2 Mbps link, measures the cost of a - failed (dropped) write. + failed (dropped) write without the no-loss pacing delay. - `write_hex_ll cycles`: payload 8/32/64/128 B; plus a 32+32 B append case. - `compressed write cycles`: workload matrix of the compressed entry points — U32 args (0/1/2/mixed), U64 values (full 8B / leading-zero LZ / zero), diff --git a/components/bt/common/ble_log/test_apps/ble_log_perf_test/main/test_ble_log_main.c b/components/bt/common/ble_log/test_apps/ble_log_perf_test/main/test_ble_log_main.c index 3437fed856c..2642e629c31 100644 --- a/components/bt/common/ble_log/test_apps/ble_log_perf_test/main/test_ble_log_main.c +++ b/components/bt/common/ble_log/test_apps/ble_log_perf_test/main/test_ble_log_main.c @@ -10,7 +10,7 @@ #include "unity_test_runner.h" #include "ble_log.h" -#include "ble_log_lbm.h" +#include "ble_log_lbm_v2.h" #include "test_ble_log_main.h" bool test_ble_log_walk_frames(const uint8_t *data, size_t len, @@ -35,8 +35,10 @@ bool test_ble_log_walk_frames(const uint8_t *data, size_t len, } if (observer) { + uint8_t source_meta = head.frame_meta & 0xff; test_ble_log_frame_t frame = { - .src = head.frame_meta & 0xff, + .src = BLE_LOG_SRC_ID(source_meta), + .source_meta = source_meta, .sn = head.frame_meta >> 8, .payload = data + offset + BLE_LOG_FRAME_HEAD_LEN, .payload_len = head.length, diff --git a/components/bt/common/ble_log/test_apps/ble_log_perf_test/main/test_ble_log_perf.c b/components/bt/common/ble_log/test_apps/ble_log_perf_test/main/test_ble_log_perf.c index 202c3f8e9a4..5679d0e24df 100644 --- a/components/bt/common/ble_log/test_apps/ble_log_perf_test/main/test_ble_log_perf.c +++ b/components/bt/common/ble_log/test_apps/ble_log_perf_test/main/test_ble_log_perf.c @@ -12,7 +12,7 @@ #include #include "ble_log.h" -#include "ble_log_lbm.h" +#include "ble_log_lbm_v2.h" #include "ble_log_prph_test.h" #include "log_compression/utils.h" #include "esp_cpu.h" @@ -125,7 +125,7 @@ typedef struct { uint32_t ll_flag; /* UINT32_MAX: use ble_log_write_hex */ bool compressed; /* call ble_log_compressed_hex_print instead */ bool record_cycles; - bool isolate_write; /* vTaskSuspendAll around the timed write */ + bool pace_after_write; /* one tick outside a no-loss timed call */ const uint8_t *ll_append; /* write_hex_ll append part */ size_t ll_append_len; const perf_compress_cfg_t *compress_cfg; @@ -174,7 +174,6 @@ typedef struct { bool compress; bool isr; bool measure_cycles; - bool isolate_write; bool expect_no_loss; const uint8_t *ll_append; size_t ll_append_len; @@ -316,8 +315,7 @@ static void print_run_separator(const char *tag, const perf_run_cfg_t *cfg) tag, (unsigned)cfg->run_idx, (unsigned)cfg->run_total, cfg->mode_name, cfg->profile_name); print_link(cfg->bytes_per_second); - printf(" isolate=%s ============\n", - cfg->isolate_write ? "sched" : "none"); + printf(" isolate=none ============\n"); } /* ---------------- */ @@ -349,9 +347,6 @@ static void perf_writer_task(void *arg) size_t payload_len = w->profile[frame_index % w->profile_count]; memcpy(payload, &frame_index, sizeof(frame_index)); - if (w->isolate_write) { - vTaskSuspendAll(); - } uint32_t start_cycles = w->record_cycles ? esp_cpu_get_cycle_count() : 0; bool ok; @@ -427,9 +422,6 @@ static void perf_writer_task(void *arg) if (w->record_cycles) { write_cycles = esp_cpu_get_cycle_count() - start_cycles; } - if (w->isolate_write) { - xTaskResumeAll(); - } if (ok) { w->cycles->ok_frames++; @@ -443,7 +435,14 @@ static void perf_writer_task(void *arg) } } frame_index++; - taskYIELD(); + if (w->pace_after_write) { + /* Cycle profiles measure one production-semantics call, then + * yield enough time for deferred dispatch and sink recycling. + * Throughput and explicit drop profiles remain unpaced. */ + vTaskDelay(1); + } else { + taskYIELD(); + } } xSemaphoreGive(w->done); @@ -485,21 +484,21 @@ static void observe_perf_frame(const test_ble_log_frame_t *frame, void *ctx) sink->frames_by_src[frame->src]++; } - /* Capture enhanced statistics records (written/lost per source). - * Frames carry a 4-byte os_timestamp prefix before the record. */ if (frame->src == BLE_LOG_SRC_INTERNAL && - frame->payload_len == sizeof(uint32_t) + sizeof(ble_log_enh_stat_t) && - frame->payload[sizeof(uint32_t)] == BLE_LOG_INT_SRC_ENH_STAT) { - ble_log_enh_stat_t stat; - memcpy(&stat, frame->payload + sizeof(uint32_t), sizeof(stat)); - if (stat.src_code < BLE_LOG_SRC_MAX) { - sink->stat_written[stat.src_code] = stat.written_frame_cnt; - sink->stat_lost[stat.src_code] = stat.lost_frame_cnt; + frame->payload_len == sizeof(uint32_t) + + sizeof(ble_log_internal_snapshot_t)) { + ble_log_internal_snapshot_t snapshot; + memcpy(&snapshot, frame->payload + sizeof(uint32_t), sizeof(snapshot)); + if (snapshot.int_src_code != BLE_LOG_INT_SRC_SNAPSHOT) { + return; } - } else if (frame->src == BLE_LOG_SRC_INTERNAL && - frame->payload_len == sizeof(uint32_t) + sizeof(ble_log_final_stat_t) && - frame->payload[sizeof(uint32_t)] == BLE_LOG_INT_SRC_FINAL_STAT) { - sink->stat_final_seen = true; + for (int i = 0; i < BLE_LOG_SRC_CORE_COUNT; i++) { + int src = BLE_LOG_SRC_CORE_FIRST + i; + sink->stat_written[src] = snapshot.stats[i].written_frame_cnt; + sink->stat_lost[src] = snapshot.stats[i].lost_frame_cnt; + } + sink->stat_final_seen = + (snapshot.reason_flags & BLE_LOG_SNAPSHOT_REASON_FLUSH) != 0; } } @@ -541,7 +540,7 @@ static void fill_writer(perf_writer_t *w, const char *name, ble_log_src_t src, w->ll_flag = ll_flag; w->compressed = compressed; w->record_cycles = cfg->measure_cycles; - w->isolate_write = cfg->isolate_write; + w->pace_after_write = cfg->measure_cycles && cfg->expect_no_loss; w->ll_append = cfg->ll_append; w->ll_append_len = cfg->ll_append_len; w->compress_cfg = cfg->compress_cfg; @@ -651,8 +650,8 @@ static void run_perf_case(const perf_run_cfg_t *cfg) } if (ll_hci) { - fill_writer(&writers[writer_count], "write_hex_ll_hci", BLE_LOG_SRC_LL_HCI, - BIT(BLE_LOG_LL_FLAG_HCI), false, cfg, &ll_hci_cycles, start); + fill_writer(&writers[writer_count], "write_hex_hci", BLE_LOG_SRC_HCI, + UINT32_MAX, false, cfg, &ll_hci_cycles, start); TEST_ASSERT_EQUAL(pdPASS, xTaskCreatePinnedToCore(perf_writer_task, "perf_hci", PERF_WRITER_STACK_SIZE, @@ -744,6 +743,8 @@ static void run_perf_case(const perf_run_cfg_t *cfg) } sink.stop = true; TEST_ASSERT_EQUAL(pdTRUE, xSemaphoreTake(sink.done, pdMS_TO_TICKS(1000))); + TEST_ASSERT_TRUE_MESSAGE(sink.stat_final_seen, + "Final statistics snapshot was not received"); uint8_t discard[BLE_LOG_TRANS_SIZE]; while (ble_log_prph_test_read(discard, sizeof(discard), 0, 0, NULL)) { @@ -753,12 +754,12 @@ static void run_perf_case(const perf_run_cfg_t *cfg) printf("BLE_LOG_PERF mode=%s profile=%s payload=%uB ", cfg->mode_name, cfg->profile_name, cfg->profile[0]); print_link(cfg->bytes_per_second); - printf(" isolate=%s duration=%" PRIu64 " ms\n", - cfg->isolate_write ? "sched" : "none", elapsed_us / 1000); + printf(" isolate=none duration=%" PRIu64 " ms\n", elapsed_us / 1000); printf("BLE_LOG_PERF flush=%" PRIu32 " cycles\n", flush_cycles); uint64_t ok_total = 0; uint64_t failed_total = 0; + uint64_t custom_failed_total = 0; for (i = 0; i < cfg->custom_writer_count; i++) { char name[32]; snprintf(name, sizeof(name), "write_hex%" PRIu32, i); @@ -769,6 +770,7 @@ static void run_perf_case(const perf_run_cfg_t *cfg) } ok_total += custom_cycles[i].ok_frames; failed_total += custom_cycles[i].failed_frames; + custom_failed_total += custom_cycles[i].failed_frames; } #if CONFIG_BLE_LOG_LL_ENABLED if (ll_task) { @@ -782,9 +784,9 @@ static void run_perf_case(const perf_run_cfg_t *cfg) } if (ll_hci) { if (cfg->measure_cycles) { - print_cycles("write_hex_ll_hci", &ll_hci_cycles, true); + print_cycles("write_hex_hci", &ll_hci_cycles, false); } else { - print_writer_counts("write_hex_ll_hci", &ll_hci_cycles); + print_writer_counts("write_hex_hci", &ll_hci_cycles); } ok_total += ll_hci_cycles.ok_frames; failed_total += ll_hci_cycles.failed_frames; @@ -827,10 +829,12 @@ static void run_perf_case(const perf_run_cfg_t *cfg) } } #endif + uint64_t ll_frames = sink.frames_by_src[BLE_LOG_SRC_LL_TASK] + + sink.frames_by_src[BLE_LOG_SRC_LL_HCI] + + sink.frames_by_src[BLE_LOG_SRC_LL_ISR]; uint64_t sink_frames = sink.frames_by_src[BLE_LOG_SRC_CUSTOM] + - sink.frames_by_src[BLE_LOG_SRC_LL_TASK] + - sink.frames_by_src[BLE_LOG_SRC_LL_HCI] + - sink.frames_by_src[BLE_LOG_SRC_LL_ISR] + + ll_frames + + sink.frames_by_src[BLE_LOG_SRC_HCI] + sink.frames_by_src[BLE_LOG_SRC_ENCODE]; printf("BLE_LOG_PERF total ok=%" PRIu64 " failed=%" PRIu64 " sink_frames=%" PRIu64 " sink_bytes=%" PRIu64 @@ -840,19 +844,21 @@ static void run_perf_case(const perf_run_cfg_t *cfg) if (!cfg->measure_cycles) { print_throughput(sink.transport_bytes, elapsed_us, cfg->bytes_per_second); } - printf("BLE_LOG_PERF stat written=[custom=%" PRIu64 " ll_task=%" PRIu64 - " ll_hci=%" PRIu64 " ll_isr=%" PRIu64 " encode=%" PRIu64 - "] lost=[custom=%" PRIu64 " ll_task=%" PRIu64 " ll_hci=%" PRIu64 - " ll_isr=%" PRIu64 " encode=%" PRIu64 "]\n", + printf("BLE_LOG_PERF stat written=[custom=%" PRIu64 " ll=%" PRIu64 + " hci=%" PRIu64 " encode=%" PRIu64 + "] lost=[custom=%" PRIu64 " ll=%" PRIu64 + " hci=%" PRIu64 " encode=%" PRIu64 "]\n", sink.stat_written[BLE_LOG_SRC_CUSTOM], - sink.stat_written[BLE_LOG_SRC_LL_TASK], - sink.stat_written[BLE_LOG_SRC_LL_HCI], + sink.stat_written[BLE_LOG_SRC_LL_TASK] + + sink.stat_written[BLE_LOG_SRC_LL_HCI] + sink.stat_written[BLE_LOG_SRC_LL_ISR], + sink.stat_written[BLE_LOG_SRC_HCI], sink.stat_written[BLE_LOG_SRC_ENCODE], sink.stat_lost[BLE_LOG_SRC_CUSTOM], - sink.stat_lost[BLE_LOG_SRC_LL_TASK], - sink.stat_lost[BLE_LOG_SRC_LL_HCI], + sink.stat_lost[BLE_LOG_SRC_LL_TASK] + + sink.stat_lost[BLE_LOG_SRC_LL_HCI] + sink.stat_lost[BLE_LOG_SRC_LL_ISR], + sink.stat_lost[BLE_LOG_SRC_HCI], sink.stat_lost[BLE_LOG_SRC_ENCODE]); print_run_separator("END", cfg); @@ -862,13 +868,19 @@ static void run_perf_case(const perf_run_cfg_t *cfg) TEST_ASSERT_GREATER_THAN_UINT64(0, ok_total); if (cfg->expect_no_loss) { TEST_ASSERT_EQUAL_UINT64(0, failed_total); - TEST_ASSERT_EQUAL_UINT64(0, sink.stat_lost[BLE_LOG_SRC_CUSTOM]); - TEST_ASSERT_EQUAL_UINT64(0, sink.stat_lost[BLE_LOG_SRC_LL_TASK]); - TEST_ASSERT_EQUAL_UINT64(0, sink.stat_lost[BLE_LOG_SRC_LL_HCI]); - TEST_ASSERT_EQUAL_UINT64(0, sink.stat_lost[BLE_LOG_SRC_LL_ISR]); - TEST_ASSERT_EQUAL_UINT64(0, sink.stat_lost[BLE_LOG_SRC_ENCODE]); + for (int i = 0; i < BLE_LOG_SRC_CORE_COUNT; i++) { + TEST_ASSERT_EQUAL_UINT64(0, + sink.stat_lost[BLE_LOG_SRC_CORE_FIRST + i]); + } } else if (sink.stat_final_seen) { - TEST_ASSERT_EQUAL_UINT64(failed_total, sink.stat_lost[BLE_LOG_SRC_CUSTOM]); + TEST_ASSERT_EQUAL_UINT64(custom_failed_total, + sink.stat_lost[BLE_LOG_SRC_CUSTOM]); +#if CONFIG_BLE_LOG_LL_ENABLED + if (ll_hci) { + TEST_ASSERT_EQUAL_UINT64(ll_hci_cycles.failed_frames, + sink.stat_lost[BLE_LOG_SRC_HCI]); + } +#endif #if CONFIG_BLE_COMPRESSED_LOG_ENABLE if (compress) { /* Every hex_print call reaches write_hex(ENCODE) exactly once; @@ -934,7 +946,6 @@ static void run_cycle_case(const char *name, const uint16_t *profile, size_t cou .ll_hci = ll_hci, .compress = compress_cfg != NULL, .measure_cycles = true, - .isolate_write = true, .expect_no_loss = true, .compress_cfg = compress_cfg, }; @@ -982,7 +993,6 @@ TEST_CASE("BLE Log write_hex drop path cycles (link=2Mbps)", "[ble_log][perf][cy .bytes_per_second = PERF_LINK_2MBPS_BPS, .custom_writer_count = 1, .measure_cycles = true, - .isolate_write = true, }; run_perf_case(&cfg); } @@ -1011,7 +1021,6 @@ TEST_CASE("BLE Log write_hex_ll append cycles (32+32B)", "[ble_log][perf][cycle] .custom_writer_count = 0, .ll_task = true, .measure_cycles = true, - .isolate_write = true, .expect_no_loss = true, .ll_append = append_buf, .ll_append_len = 32, diff --git a/components/bt/common/ble_log/test_apps/ble_log_rt_test/README.md b/components/bt/common/ble_log/test_apps/ble_log_rt_test/README.md index 75af9d61753..7f729f03b65 100644 --- a/components/bt/common/ble_log/test_apps/ble_log_rt_test/README.md +++ b/components/bt/common/ble_log/test_apps/ble_log_rt_test/README.md @@ -19,12 +19,12 @@ the hand-over time, so dispatch latency is measured without a real link. - `runtime` regressions: shared ESP Timer task fairness, periodic timestamp delivery without light-sleep wakeups, ISR-only submission delivery, consumer-independent receipt timing, extra-marker detection, exact 1 ms - first-submission defer scheduling, full task-pool snapshot dispatch, deinit + first-submission defer scheduling, full shared-pool snapshot dispatch, deinit racing submissions (SMP-pinned writer, failure-safe recovery), bounded inflight-peak statistics, and monotonic millisecond waits at both supported tick rates. -The first-deadline and full task-pool regressions require dispatch exclusion +The first-deadline and full shared-pool regressions require dispatch exclusion while enqueueing, so they run on single-core builds only (they are ignored on SMP targets). The deinit-race regression pins its writer to the other core on SMP. diff --git a/components/bt/common/ble_log/test_apps/ble_log_rt_test/main/test_ble_log_main.c b/components/bt/common/ble_log/test_apps/ble_log_rt_test/main/test_ble_log_main.c index bdb96ad8ae9..c8281ff6662 100644 --- a/components/bt/common/ble_log/test_apps/ble_log_rt_test/main/test_ble_log_main.c +++ b/components/bt/common/ble_log/test_apps/ble_log_rt_test/main/test_ble_log_main.c @@ -10,7 +10,7 @@ #include "unity_test_runner.h" #include "ble_log.h" -#include "ble_log_lbm.h" +#include "ble_log_lbm_v2.h" #include "ble_log_prph_test.h" #include "test_ble_log_main.h" @@ -36,8 +36,10 @@ bool test_ble_log_walk_frames(const uint8_t *data, size_t len, } if (observer) { + uint8_t source_meta = head.frame_meta & 0xff; test_ble_log_frame_t frame = { - .src = head.frame_meta & 0xff, + .src = BLE_LOG_SRC_ID(source_meta), + .source_meta = source_meta, .sn = head.frame_meta >> 8, .payload = data + offset + BLE_LOG_FRAME_HEAD_LEN, .payload_len = head.length, diff --git a/components/bt/common/ble_log/test_apps/ble_log_rt_test/main/test_ble_log_runtime.c b/components/bt/common/ble_log/test_apps/ble_log_rt_test/main/test_ble_log_runtime.c index 1f1791d1c53..1cc8286e3a5 100644 --- a/components/bt/common/ble_log/test_apps/ble_log_rt_test/main/test_ble_log_runtime.c +++ b/components/bt/common/ble_log/test_apps/ble_log_rt_test/main/test_ble_log_runtime.c @@ -12,7 +12,7 @@ #include #include "ble_log.h" -#include "ble_log_lbm.h" +#include "ble_log_lbm_v2.h" #include "ble_log_prph_test.h" #include "ble_log_rt.h" #include "esp_timer.h" @@ -24,7 +24,6 @@ #define RT_SAMPLE_COUNT (32) #define RT_BURST_SIZE (4) -#define RT_TASK_POOL_TRANS_COUNT ((BLE_LOG_LBM_ATOMIC_TASK_CNT + 1) * BLE_LOG_TRANS_BUF_CNT) #define RT_READ_TIMEOUT_MS (100) #define RT_QUIET_TIMEOUT_MS (10) #define RT_QUIET_DRAIN_DEADLINE_MS (2000) @@ -37,7 +36,7 @@ #define RT_CONSUMER_DELAY_MS (30) #define RT_RECEIVE_MAX_LATENCY_US (10000) #define RT_BURST_SPAN_MAX_US (500) -#define RT_PEAK_WRITES (8) +#define RT_PEAK_WRITES (BLE_LOG_POOL_SHARED_CNT) #define RT_DEINIT_ROUNDS (200) #define RT_JOIN_TIMEOUT_MS (5000) @@ -100,9 +99,14 @@ static void observe_runtime_marker(const test_ble_log_frame_t *frame, void *ctx) { rt_marker_observer_t *observer = ctx; if (frame->src == BLE_LOG_SRC_INTERNAL && - frame->payload_len > sizeof(uint32_t) && - frame->payload[sizeof(uint32_t)] == BLE_LOG_INT_SRC_TS) { - observer->ts_count++; + frame->payload_len == sizeof(uint32_t) + + sizeof(ble_log_internal_snapshot_t)) { + ble_log_internal_snapshot_t snapshot; + memcpy(&snapshot, frame->payload + sizeof(uint32_t), sizeof(snapshot)); + if (snapshot.int_src_code == BLE_LOG_INT_SRC_SNAPSHOT && + (snapshot.reason_flags & BLE_LOG_SNAPSHOT_REASON_TS_VALID)) { + observer->ts_count++; + } } if (frame->src != BLE_LOG_SRC_CUSTOM || @@ -275,18 +279,21 @@ static void observe_buf_util(const test_ble_log_frame_t *frame, void *ctx) { rt_peak_observer_t *observer = ctx; if (frame->src != BLE_LOG_SRC_INTERNAL || - frame->payload_len < sizeof(uint32_t) + sizeof(ble_log_buf_util_t) || - frame->payload[sizeof(uint32_t)] != BLE_LOG_INT_SRC_BUF_UTIL) { + frame->payload_len != sizeof(uint32_t) + + sizeof(ble_log_internal_snapshot_t)) { return; } - ble_log_buf_util_t util; - memcpy(&util, frame->payload + sizeof(uint32_t), sizeof(util)); - observer->buf_util_frames++; - if (util.inflight_peak > observer->max_inflight_peak) { - observer->max_inflight_peak = util.inflight_peak; + ble_log_internal_snapshot_t snapshot; + memcpy(&snapshot, frame->payload + sizeof(uint32_t), sizeof(snapshot)); + if (snapshot.int_src_code != BLE_LOG_INT_SRC_SNAPSHOT) { + return; } - if (util.inflight_peak > util.trans_cnt) { + observer->buf_util_frames++; + if (snapshot.pool.inflight_peak > observer->max_inflight_peak) { + observer->max_inflight_peak = snapshot.pool.inflight_peak; + } + if (snapshot.pool.inflight_peak > snapshot.pool.trans_cnt) { observer->over_limit = true; } } @@ -654,7 +661,7 @@ TEST_CASE("BLE Log runtime dispatch latency", "[ble_log][runtime][perf][ignore]" print_latency_stats("burst_last", RT_BURST_SIZE, s_burst_last_latency_us); } -TEST_CASE("BLE Log runtime drains the full task pool in one batch", +TEST_CASE("BLE Log runtime drains the full shared pool in one batch", "[ble_log][runtime][ignore]") { #if !CONFIG_FREERTOS_UNICORE @@ -666,8 +673,8 @@ TEST_CASE("BLE Log runtime drains the full task pool in one batch", TEST_ASSERT_TRUE(ble_log_enable(true)); - /* Flush from this ordinary test task so every task-pool transport is free - * before constructing the callback-entry snapshot. */ + /* Flush from this ordinary test task so every shared-pool transport is + * free before constructing the callback-entry snapshot. */ ble_log_prph_test_set_auto_recycle_hook(noop_callback, NULL); ble_log_flush(); ble_log_prph_test_set_auto_recycle_hook(NULL, NULL); @@ -678,15 +685,15 @@ TEST_CASE("BLE Log runtime drains the full task pool in one batch", * without an artificial item cap. */ bool wrote = true; vTaskSuspendAll(); - for (uint32_t i = 0; i < RT_TASK_POOL_TRANS_COUNT; i++) { + for (uint32_t i = 0; i < BLE_LOG_POOL_SHARED_CNT; i++) { prepare_payload(base_seq + i); wrote = wrote && ble_log_write_hex(BLE_LOG_SRC_CUSTOM, s_payload, sizeof(s_payload)); } (void)xTaskResumeAll(); - TEST_ASSERT_TRUE_MESSAGE(wrote, "Full task-pool enqueue failed"); + TEST_ASSERT_TRUE_MESSAGE(wrote, "Full shared-pool enqueue failed"); - for (uint32_t i = 0; i < RT_TASK_POOL_TRANS_COUNT; i++) { + for (uint32_t i = 0; i < BLE_LOG_POOL_SHARED_CNT; i++) { uint32_t received_seq; int64_t received_at_us; TEST_ASSERT_TRUE_MESSAGE(read_runtime_marker(&received_seq, NULL, @@ -722,10 +729,18 @@ TEST_CASE("BLE Log LBM inflight peak stays bounded under bursts", TEST_ASSERT_TRUE(write_runtime_marker(seq, NULL)); } - /* Snapshot the recorded peaks. A full marker forces the partial BUF_UTIL - * transport to roll over through the normal LBM submission path. */ - ble_log_write_buf_util(); - TEST_ASSERT_TRUE(write_runtime_marker(UINT32_C(0x81000), NULL)); + /* Recycle the burst after its peak has been recorded. A runtime hook may + * also have occupied the dedicated Internal transport, so drain twice. */ + for (int round = 0; round < 2; round++) { + TEST_ASSERT_TRUE(ble_log_rt_drain()); + while (ble_log_prph_test_read(s_capture, sizeof(s_capture), + 0, 0, NULL) > 0) { + } + } + + /* Snapshot the retained peak through the dedicated Internal transport. */ + TEST_ASSERT_TRUE(ble_log_internal_snapshot( + BLE_LOG_SNAPSHOT_REASON_PERIODIC, NULL, true)); TEST_ASSERT_TRUE(ble_log_rt_drain()); const int64_t deadline_us = esp_timer_get_time() + @@ -747,7 +762,7 @@ TEST_CASE("BLE Log LBM inflight peak stays bounded under bursts", TEST_ASSERT_GREATER_THAN_UINT32_MESSAGE( 0, observer.buf_util_frames, - "No BUF_UTIL snapshots observed after flush"); + "No Internal utilization snapshot observed"); TEST_ASSERT_FALSE_MESSAGE(observer.over_limit, "inflight_peak exceeded the LBM transport count"); TEST_ASSERT_GREATER_THAN_UINT32_MESSAGE( @@ -763,6 +778,7 @@ TEST_CASE("BLE Log runtime survives deinit racing submissions", "[ble_log][runtime][ignore]") { rt_deinit_writer_ctx_t *ctx = &s_deinit_race; + TaskHandle_t writer_task = NULL; bool reinit_ok = true; memset(ctx, 0, sizeof(*ctx)); prepare_payload(UINT32_C(0x70000)); @@ -770,13 +786,14 @@ TEST_CASE("BLE Log runtime survives deinit racing submissions", #if CONFIG_FREERTOS_UNICORE BaseType_t task_created = xTaskCreate( deinit_writer_task, "ble_log_deinit_wr", 4096, ctx, - uxTaskPriorityGet(NULL), NULL); + uxTaskPriorityGet(NULL), &writer_task); #else /* Pin the writer away from this core so submissions run concurrently * with deinit instead of alternating at yield points. */ BaseType_t task_created = xTaskCreatePinnedToCore( deinit_writer_task, "ble_log_deinit_wr", 4096, ctx, - uxTaskPriorityGet(NULL), NULL, (xPortGetCoreID() == 0) ? 1 : 0); + uxTaskPriorityGet(NULL), &writer_task, + (xPortGetCoreID() == 0) ? 1 : 0); #endif TEST_ASSERT_EQUAL_MESSAGE(pdPASS, task_created, "Writer task create failed"); @@ -786,8 +803,8 @@ TEST_CASE("BLE Log runtime survives deinit racing submissions", taskYIELD(); } - /* Stop the writer and join with a bound before touching ctx or asserting: - * a unity longjmp past a live writer would leave it on a dead stack. */ + /* Stop the writer and join with a bound before asserting so a Unity + * longjmp cannot leak the writer into later tests. */ __atomic_store_n(&ctx->stop, true, __ATOMIC_RELEASE); const int64_t join_deadline_us = esp_timer_get_time() + (int64_t)RT_JOIN_TIMEOUT_MS * 1000; @@ -799,6 +816,11 @@ TEST_CASE("BLE Log runtime survives deinit racing submissions", vTaskDelay(join_ticks); } + bool writer_exited = __atomic_load_n(&ctx->exited, __ATOMIC_ACQUIRE); + if (!writer_exited && writer_task) { + vTaskDelete(writer_task); + } + /* Recover module state before any assertion can abort the test: a * failed re-init leaves the module deinit-ed and tearDown does not * restore it, which would cascade into every later test. */ @@ -806,9 +828,8 @@ TEST_CASE("BLE Log runtime survives deinit racing submissions", bool recovered = ble_log_init(); reinit_ok = reinit_ok && recovered; - TEST_ASSERT_TRUE_MESSAGE( - __atomic_load_n(&ctx->exited, __ATOMIC_ACQUIRE), - "Writer task did not exit after stop"); + TEST_ASSERT_TRUE_MESSAGE(writer_exited, + "Writer task did not exit after stop"); TEST_ASSERT_TRUE_MESSAGE(reinit_ok, "BLE Log re-init failed during the race"); TEST_ASSERT_GREATER_THAN_UINT32_MESSAGE( RT_DEINIT_ROUNDS, ctx->attempts, diff --git a/components/bt/common/ble_log/test_apps/ble_log_test/README.md b/components/bt/common/ble_log/test_apps/ble_log_test/README.md index 251e6e27533..47b48cf12a2 100644 --- a/components/bt/common/ble_log/test_apps/ble_log_test/README.md +++ b/components/bt/common/ble_log/test_apps/ble_log_test/README.md @@ -7,12 +7,15 @@ | Supported Targets | | ----------------- | -This test app verifies the BLE Log runtime behaviour on target, using the -in-memory test peripheral (`CONFIG_BLE_LOG_PRPH_TEST=y`) to capture the -transport stream written by the runtime dispatch hook. +This app uses the in-memory test peripheral (`CONFIG_BLE_LOG_PRPH_TEST=y`) to +validate the BLE Log transport on target. -Currently covered: +It covers: -- `BLE_LOG_INT_SRC_VERSION_INFO` frame: BLE Log version, ESP-IDF build commit, - controller lib commit, btdm_common lib commit, BLE Mesh and BLE Audio lib - commits, chip model and chip revision +- literal protocol-v7 framing and fixed Internal Snapshot ABI; +- build, library, chip, and protocol versions inside the snapshot; +- task and `NON_YIELD` source metadata plus HCI direction encoding; +- direct compression claim/commit, stale handles, and per-source serialization; +- oversized-record rejection, flush sequence continuity, pool exhaustion, and non-yield reserve use; +- periodic snapshot busy/loss behavior; +- enable, disable, parked-writer, and deinit races. diff --git a/components/bt/common/ble_log/test_apps/ble_log_test/main/test_ble_log_main.c b/components/bt/common/ble_log/test_apps/ble_log_test/main/test_ble_log_main.c index 3437fed856c..2642e629c31 100644 --- a/components/bt/common/ble_log/test_apps/ble_log_test/main/test_ble_log_main.c +++ b/components/bt/common/ble_log/test_apps/ble_log_test/main/test_ble_log_main.c @@ -10,7 +10,7 @@ #include "unity_test_runner.h" #include "ble_log.h" -#include "ble_log_lbm.h" +#include "ble_log_lbm_v2.h" #include "test_ble_log_main.h" bool test_ble_log_walk_frames(const uint8_t *data, size_t len, @@ -35,8 +35,10 @@ bool test_ble_log_walk_frames(const uint8_t *data, size_t len, } if (observer) { + uint8_t source_meta = head.frame_meta & 0xff; test_ble_log_frame_t frame = { - .src = head.frame_meta & 0xff, + .src = BLE_LOG_SRC_ID(source_meta), + .source_meta = source_meta, .sn = head.frame_meta >> 8, .payload = data + offset + BLE_LOG_FRAME_HEAD_LEN, .payload_len = head.length, diff --git a/components/bt/common/ble_log/test_apps/ble_log_test/main/test_ble_log_rt.c b/components/bt/common/ble_log/test_apps/ble_log_test/main/test_ble_log_rt.c index 6f1ecb2e182..9fb3d2167d6 100644 --- a/components/bt/common/ble_log/test_apps/ble_log_test/main/test_ble_log_rt.c +++ b/components/bt/common/ble_log/test_apps/ble_log_test/main/test_ble_log_rt.c @@ -16,9 +16,13 @@ #include "unity.h" #include "ble_log.h" +#include "ble_log_lbm_v2.h" #include "ble_log_prph_test.h" #include "ble_log_rt.h" #include "test_ble_log_main.h" +#if CONFIG_BLE_HOST_COMPRESSED_LOG_ENABLE +#include "log_compression/utils.h" +#endif #if !CONFIG_BLE_LOG_PRPH_TEST #error "BLE Log test app requires CONFIG_BLE_LOG_PRPH_TEST" @@ -35,6 +39,8 @@ #define TEST_READ_BUF_SIZE (4096) #define TEST_READER_STACK_SIZE (3072) #define TEST_READER_PRIO (2) +#define TEST_LIFECYCLE_STACK_SIZE (2048) +#define TEST_LIFECYCLE_PRIO (3) typedef struct { size_t version_info_count; @@ -49,6 +55,65 @@ typedef struct { } reader_ctx_t; static uint8_t s_read_buf[TEST_READ_BUF_SIZE]; +static bool s_claim_hook_armed; +static uint32_t s_stale_claim_handle; +static volatile bool s_enable_hook_armed; +static SemaphoreHandle_t s_enable_hook_entered; +static SemaphoreHandle_t s_enable_hook_continue; +static volatile bool s_disable_hook_armed; +static SemaphoreHandle_t s_disable_hook_entered; +static SemaphoreHandle_t s_disable_hook_continue; +#if CONFIG_BLE_HOST_COMPRESSED_LOG_ENABLE +static volatile bool s_compression_hook_armed; +static SemaphoreHandle_t s_compression_hook_entered; +static SemaphoreHandle_t s_compression_hook_continue; +#endif + +void ble_log_test_claim_pre_publish_hook(void); +void ble_log_test_enable_before_lifecycle_lock_hook(void); +void ble_log_test_disable_before_wake_hook(void); +#if CONFIG_BLE_HOST_COMPRESSED_LOG_ENABLE +void ble_log_test_compression_after_lock_hook(uint8_t source); +extern int ble_log_compressed_hex_print(uint8_t source, uint32_t log_index, + size_t args_cnt, ...); +#endif + +void ble_log_test_claim_pre_publish_hook(void) +{ + if (s_claim_hook_armed) { + /* A valid length exercises the state check on the still-OPEN + * transport: a deleted check would frame stale claim metadata + * (duplicate SN) on the wire. */ + ble_log_commit(s_stale_claim_handle, 1); + } +} + +void ble_log_test_enable_before_lifecycle_lock_hook(void) +{ + if (s_enable_hook_armed) { + xSemaphoreGive(s_enable_hook_entered); + xSemaphoreTake(s_enable_hook_continue, portMAX_DELAY); + } +} + +void ble_log_test_disable_before_wake_hook(void) +{ + if (s_disable_hook_armed) { + xSemaphoreGive(s_disable_hook_entered); + xSemaphoreTake(s_disable_hook_continue, portMAX_DELAY); + } +} + +#if CONFIG_BLE_HOST_COMPRESSED_LOG_ENABLE +void ble_log_test_compression_after_lock_hook(uint8_t source) +{ + if (s_compression_hook_armed && + source == BLE_COMPRESSED_LOG_OUT_SOURCE_HOST) { + xSemaphoreGive(s_compression_hook_entered); + xSemaphoreTake(s_compression_hook_continue, portMAX_DELAY); + } +} +#endif /* A commit field is hex characters, zero-padded after a shorter value; * anything else (garbage, non-hex, zeros after data) is invalid. */ @@ -83,14 +148,19 @@ static bool commit_is_zero(const uint8_t *commit, size_t len) static void capture_version_info_frame(const test_ble_log_frame_t *frame, void *ctx) { version_capture_t *capture = ctx; - /* Every frame payload starts with a 4-byte timestamp prefix */ + if (frame->payload_len < sizeof(uint32_t)) { + return; + } const uint8_t *record = frame->payload + sizeof(uint32_t); size_t record_len = frame->payload_len - sizeof(uint32_t); if (frame->src == BLE_LOG_SRC_INTERNAL && - record_len == sizeof(ble_log_version_info_t) && - record[0] == BLE_LOG_INT_SRC_VERSION_INFO) { - memcpy(&capture->version_info, record, sizeof(capture->version_info)); + record_len == sizeof(ble_log_internal_snapshot_t) && + record[0] == BLE_LOG_INT_SRC_SNAPSHOT) { + ble_log_internal_snapshot_t snapshot; + memcpy(&snapshot, record, sizeof(snapshot)); + memcpy(&capture->version_info, &snapshot.version_info, + sizeof(capture->version_info)); capture->version_info_count++; } } @@ -114,6 +184,72 @@ static void test_reader_task(void *arg) vTaskDelete(NULL); } +typedef struct { + size_t count; + test_ble_log_frame_t frame; +} golden_capture_t; + +static void capture_golden_frame(const test_ble_log_frame_t *frame, void *ctx) +{ + golden_capture_t *capture = ctx; + capture->frame = *frame; + capture->count++; +} + +TEST_CASE("BLE Log v7 framing matches golden bytes", "[ble_log][wire]") +{ + static const uint8_t golden_frame[] = { + 0x05, 0x00, 0x87, 0xde, 0xc0, 0x00, + 0x78, 0x56, 0x34, 0x12, 0xab, + 0xf1, 0x12, 0x54, 0x88, + }; + static const uint8_t golden_payload[] = { + 0x78, 0x56, 0x34, 0x12, 0xab, + }; + + TEST_ASSERT_EQUAL_UINT8(7, BLE_LOG_VERSION); + TEST_ASSERT_EQUAL_HEX8(0x80, BLE_LOG_SRC_FLAG_NON_YIELD); + TEST_ASSERT_EQUAL_UINT8(1, BLE_LOG_SRC_CORE_FIRST); + TEST_ASSERT_EQUAL_UINT8(7, BLE_LOG_SRC_CORE_COUNT); + TEST_ASSERT_EQUAL_UINT8(7, BLE_LOG_SRC_ENCODE); + TEST_ASSERT_EQUAL_UINT8(7, BLE_LOG_INT_SRC_VERSION_INFO); + TEST_ASSERT_EQUAL_UINT8(8, BLE_LOG_INT_SRC_SNAPSHOT); + TEST_ASSERT_EQUAL_size_t(8, sizeof(ble_log_source_stat_t)); + TEST_ASSERT_EQUAL_size_t(134, sizeof(ble_log_internal_snapshot_t)); + TEST_ASSERT_EQUAL_size_t( + 4, offsetof(ble_log_internal_snapshot_t, version_info)); + TEST_ASSERT_EQUAL_size_t( + 62, offsetof(ble_log_internal_snapshot_t, ts.lc_ts)); + TEST_ASSERT_EQUAL_size_t( + 66, offsetof(ble_log_internal_snapshot_t, ts.esp_ts)); + TEST_ASSERT_EQUAL_size_t( + 70, offsetof(ble_log_internal_snapshot_t, ts.os_ts)); + TEST_ASSERT_EQUAL_size_t( + 78, offsetof(ble_log_internal_snapshot_t, stats)); + TEST_ASSERT_EQUAL_UINT32(148, BLE_LOG_INTERNAL_FRAME_LEN); +#if CONFIG_BLE_LOG_LL_ENABLED + TEST_ASSERT_EQUAL_UINT8(4, BLE_LOG_LL_FLAG_HCI); + TEST_ASSERT_EQUAL_UINT8(7, BLE_LOG_LL_FLAG_HCI_UPSTREAM); +#endif + TEST_ASSERT_EQUAL_HEX32( + 0x00c0de87, BLE_LOG_MAKE_FRAME_META(0x87, 0x00c0de)); + TEST_ASSERT_EQUAL_HEX32( + 0x00000007, BLE_LOG_MAKE_FRAME_META(0x07, 0x01000000)); + + golden_capture_t capture = {0}; + TEST_ASSERT_TRUE(test_ble_log_walk_frames(golden_frame, + sizeof(golden_frame), + capture_golden_frame, + &capture)); + TEST_ASSERT_EQUAL_size_t(1, capture.count); + TEST_ASSERT_EQUAL_UINT8(BLE_LOG_SRC_ENCODE, capture.frame.src); + TEST_ASSERT_EQUAL_HEX8(0x87, capture.frame.source_meta); + TEST_ASSERT_EQUAL_HEX32(0x00c0de, capture.frame.sn); + TEST_ASSERT_EQUAL_size_t(sizeof(golden_payload), capture.frame.payload_len); + TEST_ASSERT_EQUAL_MEMORY(golden_payload, capture.frame.payload, + sizeof(golden_payload)); +} + TEST_CASE("BLE Log runtime hook reports build and chip versions", "[ble_log]") { static const uint8_t payload[TEST_PAYLOAD_LEN] = {0}; @@ -128,12 +264,8 @@ TEST_CASE("BLE Log runtime hook reports build and chip versions", "[ble_log]") TEST_READER_PRIO, &reader)); TEST_ASSERT_TRUE(ble_log_enable(true)); - /* Transports are auto-submitted once full, which arms the defer alarm; - * after the throttle window elapses, a hook pass writes the version frame - * into the LBM and a later transport carries it out. ble_log_flush() - * cannot be used here: it disables the module while waiting for the - * transports to drain, so the hook frame written during the flush window - * would be dropped. */ + /* A hook pass submits one consolidated Internal Snapshot containing the + * version, statistics, utilization, and optional TS sample. */ for (int round = 0; round < TEST_MAX_ROUNDS && ctx.capture.version_info_count == 0; round++) { vTaskDelay(pdMS_TO_TICKS(TEST_HOOK_SETTLE_MS)); for (int i = 0; i < TEST_WRITES_PER_ROUND; i++) { @@ -187,3 +319,765 @@ TEST_CASE("BLE Log runtime hook reports build and chip versions", "[ble_log]") vSemaphoreDelete(ctx.done); } + +typedef struct { + bool task_frame; + bool non_yield_frame; + bool hci_downstream_frame; + bool hci_upstream_frame; + bool claimed_frame; + bool stale_protected_frame; + int encode_frame_cnt; +} frame_meta_capture_t; + +static void capture_frame_meta(const test_ble_log_frame_t *frame, void *ctx) +{ + frame_meta_capture_t *capture = ctx; + if (frame->src == BLE_LOG_SRC_ENCODE) { + capture->encode_frame_cnt++; + } + if (frame->payload_len < sizeof(uint32_t) + 1) { + return; + } + + uint8_t marker = frame->payload[sizeof(uint32_t)]; + if (frame->src == BLE_LOG_SRC_CUSTOM && marker == 0x11) { + capture->task_frame = !BLE_LOG_SRC_IS_NON_YIELD(frame->source_meta); + } else if (frame->src == BLE_LOG_SRC_CUSTOM && marker == 0x22) { + capture->non_yield_frame = + BLE_LOG_SRC_IS_NON_YIELD(frame->source_meta); + } else if (frame->src == BLE_LOG_SRC_HCI && marker == 0x01) { + capture->hci_downstream_frame = true; + } else if (frame->src == BLE_LOG_SRC_HCI && marker == 0x82) { + capture->hci_upstream_frame = true; + } else if (frame->src == BLE_LOG_SRC_ENCODE && marker == 0x33) { + capture->claimed_frame = true; + } else if (frame->src == BLE_LOG_SRC_ENCODE && marker == 0x44) { + capture->stale_protected_frame = true; + } +} + +TEST_CASE("BLE Log marks non-yield context and commits claimed payload", + "[ble_log][lbm]") +{ + const uint8_t task_marker = 0x11; + const uint8_t critical_marker = 0x22; + TEST_ASSERT_TRUE(ble_log_enable(true)); + ble_log_lbm_flush_open_trans(); + for (int round = 0; round < 2; round++) { + TEST_ASSERT_TRUE(ble_log_rt_drain()); + while (ble_log_prph_test_read(s_read_buf, sizeof(s_read_buf), + 0, 0, NULL) > 0) { + } + } + TEST_ASSERT_TRUE(ble_log_write_hex(BLE_LOG_SRC_CUSTOM, + &task_marker, sizeof(task_marker))); + + portMUX_TYPE mux = portMUX_INITIALIZER_UNLOCKED; + portENTER_CRITICAL(&mux); + bool critical_written = ble_log_write_hex(BLE_LOG_SRC_CUSTOM, + &critical_marker, + sizeof(critical_marker)); + portEXIT_CRITICAL(&mux); + TEST_ASSERT_TRUE(critical_written); + + uint8_t hci_type = 0x81; + ble_log_write_hci(BLE_LOG_HCI_DOWNSTREAM, &hci_type, sizeof(hci_type)); + TEST_ASSERT_EQUAL_HEX8(0x81, hci_type); + hci_type = 0x02; + ble_log_write_hci(BLE_LOG_HCI_UPSTREAM, &hci_type, sizeof(hci_type)); + TEST_ASSERT_EQUAL_HEX8(0x02, hci_type); + /* The HCI macro requires one writable type byte. Exercise invalid public + * input at the validating API instead. */ + TEST_ASSERT_FALSE(ble_log_write_hex(BLE_LOG_SRC_HCI, NULL, 1)); + + uint32_t handle; + uint8_t *claimed = ble_log_claim(BLE_LOG_SRC_ENCODE, 8, &handle); + TEST_ASSERT_NOT_NULL(claimed); + claimed[0] = 0x33; + ble_log_commit(handle, 1); + + /* Invoke the stale commit immediately before the next claim publishes + * CLAIMED. It must see the prior OPEN state and leave the new claim + * intact. */ + s_stale_claim_handle = handle; + s_claim_hook_armed = true; + uint32_t fresh_handle; + claimed = ble_log_claim(BLE_LOG_SRC_ENCODE, 8, &fresh_handle); + s_claim_hook_armed = false; + TEST_ASSERT_NOT_NULL(claimed); + TEST_ASSERT_NOT_EQUAL(handle, fresh_handle); + /* The fresh claim is published: the same stale handle must now be + * rejected by the generation check instead. A zero length mirrors a + * stale abort, which would otherwise consume the fresh claim. */ + ble_log_commit(s_stale_claim_handle, 0); + claimed[0] = 0x44; + ble_log_commit(fresh_handle, 1); + + ble_log_lbm_flush_open_transports(); + TEST_ASSERT_TRUE(ble_log_rt_drain()); + + frame_meta_capture_t capture = {0}; + for (int i = 0; i < BLE_LOG_TRANS_TOTAL_CNT; i++) { + size_t len = ble_log_prph_test_read(s_read_buf, sizeof(s_read_buf), + pdMS_TO_TICKS(TEST_READ_TIMEOUT_MS), + 0, NULL); + if (!len) { + break; + } + TEST_ASSERT_TRUE(test_ble_log_walk_frames(s_read_buf, len, + capture_frame_meta, + &capture)); + } + + TEST_ASSERT_TRUE(capture.task_frame); + TEST_ASSERT_TRUE(capture.non_yield_frame); + TEST_ASSERT_TRUE(capture.hci_downstream_frame); + TEST_ASSERT_TRUE(capture.hci_upstream_frame); + TEST_ASSERT_TRUE(capture.claimed_frame); + TEST_ASSERT_TRUE(capture.stale_protected_frame); + /* Exactly the two committed claims: a stale commit that slipped past + * the state or generation check would add or consume an ENCODE frame. */ + TEST_ASSERT_EQUAL(2, capture.encode_frame_cnt); +} + +#if CONFIG_BLE_HOST_COMPRESSED_LOG_ENABLE +#define TEST_CP_INDEX_FIRST UINT16_C(0x601) +#define TEST_CP_INDEX_DROPPED UINT16_C(0x602) +#define TEST_CP_INDEX_SECOND UINT16_C(0x603) +#define TEST_CP_TASK_SWITCH UINT8_C(0xc2) +#define TEST_CP_ZERO_ARGS UINT8_C(0x40) + +typedef struct { + bool first_found; + uint32_t first_sn; + bool dropped_found; + bool second_found; + bool second_switched; + uint32_t second_sn; + bool third_found; + bool third_switched; + uint32_t third_sn; +} compression_capture_t; + +typedef struct { + SemaphoreHandle_t committed; + SemaphoreHandle_t exit; + SemaphoreHandle_t exited; +} compression_writer_ctx_t; + +static void capture_compressed_frame(const test_ble_log_frame_t *frame, + void *ctx) +{ + compression_capture_t *capture = ctx; + if (frame->src != BLE_LOG_SRC_ENCODE || + frame->payload_len < sizeof(uint32_t) + 4) { + return; + } + + const uint8_t *record = frame->payload + sizeof(uint32_t); + size_t offset = 0; + if (record[offset++] != BLE_COMPRESSED_LOG_OUT_SOURCE_HOST) { + return; + } + size_t record_len = frame->payload_len - sizeof(uint32_t); + bool switched = record[offset] == TEST_CP_TASK_SWITCH; + offset += switched; + if (record_len - offset < 3 || record[offset++] != TEST_CP_ZERO_ARGS) { + return; + } + uint16_t log_index; + memcpy(&log_index, record + offset, sizeof(log_index)); + + if (log_index == TEST_CP_INDEX_FIRST) { + capture->first_found = true; + capture->first_sn = frame->sn; + } else if (log_index == TEST_CP_INDEX_DROPPED) { + capture->dropped_found = true; + } else if (log_index == TEST_CP_INDEX_SECOND) { + capture->second_found = true; + capture->second_switched = switched; + capture->second_sn = frame->sn; + } else if (log_index == TEST_CP_INDEX_SECOND + 1) { + capture->third_found = true; + capture->third_switched = switched; + capture->third_sn = frame->sn; + } +} + +static void compression_writer_task(void *arg) +{ + compression_writer_ctx_t *ctx = arg; + ble_log_compressed_hex_print(BLE_COMPRESSED_LOG_OUT_SOURCE_HOST, + TEST_CP_INDEX_SECOND, 0); + xSemaphoreGive(ctx->committed); + xSemaphoreTake(ctx->exit, portMAX_DELAY); + xSemaphoreGive(ctx->exited); + vTaskDelete(NULL); +} + +TEST_CASE("BLE Log serializes task context per compression source", + "[ble_log][compression]") +{ + TEST_ASSERT_TRUE(ble_log_enable(true)); + ble_log_lbm_flush_open_transports(); + for (int round = 0; round < 2; round++) { + TEST_ASSERT_TRUE(ble_log_rt_drain()); + while (ble_log_prph_test_read(s_read_buf, sizeof(s_read_buf), + 0, 0, NULL) > 0) { + } + } + + ble_log_compressed_hex_print(BLE_COMPRESSED_LOG_OUT_SOURCE_HOST, + TEST_CP_INDEX_FIRST, 0); + + s_compression_hook_entered = xSemaphoreCreateBinary(); + s_compression_hook_continue = xSemaphoreCreateBinary(); + compression_writer_ctx_t writer = { + .committed = xSemaphoreCreateBinary(), + .exit = xSemaphoreCreateBinary(), + .exited = xSemaphoreCreateBinary(), + }; + TEST_ASSERT_NOT_NULL(s_compression_hook_entered); + TEST_ASSERT_NOT_NULL(s_compression_hook_continue); + TEST_ASSERT_NOT_NULL(writer.committed); + TEST_ASSERT_NOT_NULL(writer.exit); + TEST_ASSERT_NOT_NULL(writer.exited); + + s_compression_hook_armed = true; + TEST_ASSERT_EQUAL( + pdTRUE, + xTaskCreate(compression_writer_task, "ble_log_cp", + TEST_LIFECYCLE_STACK_SIZE, &writer, + TEST_LIFECYCLE_PRIO, NULL)); + TEST_ASSERT_TRUE(xSemaphoreTake(s_compression_hook_entered, + pdMS_TO_TICKS(1000))); + + /* This call claims pool space but fails the per-source trylock. It must + * cancel immediately, count one lost ENCODE SN, and leave task state to + * the lock owner. */ + ble_log_compressed_hex_print(BLE_COMPRESSED_LOG_OUT_SOURCE_HOST, + TEST_CP_INDEX_DROPPED, 0); + xSemaphoreGive(s_compression_hook_continue); + TEST_ASSERT_TRUE(xSemaphoreTake(writer.committed, + pdMS_TO_TICKS(1000))); + s_compression_hook_armed = false; + + ble_log_compressed_hex_print(BLE_COMPRESSED_LOG_OUT_SOURCE_HOST, + TEST_CP_INDEX_SECOND + 1, 0); + xSemaphoreGive(writer.exit); + TEST_ASSERT_TRUE(xSemaphoreTake(writer.exited, pdMS_TO_TICKS(1000))); + + ble_log_lbm_flush_open_transports(); + TEST_ASSERT_TRUE(ble_log_rt_drain()); + compression_capture_t capture = {0}; + for (int i = 0; i < BLE_LOG_TRANS_TOTAL_CNT; i++) { + size_t len = ble_log_prph_test_read( + s_read_buf, sizeof(s_read_buf), pdMS_TO_TICKS(TEST_READ_TIMEOUT_MS), + 0, NULL); + if (!len) { + break; + } + TEST_ASSERT_TRUE(test_ble_log_walk_frames( + s_read_buf, len, capture_compressed_frame, &capture)); + } + + TEST_ASSERT_TRUE(capture.first_found); + TEST_ASSERT_FALSE(capture.dropped_found); + TEST_ASSERT_TRUE(capture.second_found); + TEST_ASSERT_TRUE(capture.second_switched); + TEST_ASSERT_TRUE(capture.third_found); + TEST_ASSERT_TRUE(capture.third_switched); + /* The blocked writer claims its SN before taking the compression lock; + * the rejected contender burns the following SN. */ + TEST_ASSERT_EQUAL_HEX32((capture.first_sn + 1) & 0x00ffffffU, + capture.second_sn); + TEST_ASSERT_EQUAL_HEX32((capture.second_sn + 2) & 0x00ffffffU, + capture.third_sn); + + vSemaphoreDelete(writer.committed); + vSemaphoreDelete(writer.exit); + vSemaphoreDelete(writer.exited); + vSemaphoreDelete(s_compression_hook_entered); + vSemaphoreDelete(s_compression_hook_continue); + s_compression_hook_entered = NULL; + s_compression_hook_continue = NULL; +} +#endif /* CONFIG_BLE_HOST_COMPRESSED_LOG_ENABLE */ + +typedef struct { + ble_log_src_t src; + uint8_t marker; + bool found; + uint32_t sn; +} sequence_capture_t; + +typedef struct { + sequence_capture_t *captures; + size_t count; +} sequence_capture_set_t; + +static void capture_sequence_frame(const test_ble_log_frame_t *frame, void *ctx) +{ + sequence_capture_set_t *set = ctx; + bool is_ll = frame->src == BLE_LOG_SRC_LL_TASK || + frame->src == BLE_LOG_SRC_LL_ISR; + size_t marker_offset = is_ll ? 0 : sizeof(uint32_t); + /* LL payloads already carry the controller's LC timestamp; unlike the + * other sources, they must not gain an ESP timestamp prefix. */ + if (frame->payload_len != marker_offset + 1) { + return; + } + + uint8_t marker = frame->payload[marker_offset]; + for (size_t i = 0; i < set->count; i++) { + sequence_capture_t *capture = &set->captures[i]; + if (frame->src == capture->src && marker == capture->marker) { + capture->found = true; + capture->sn = frame->sn; + } + } +} + +static void read_sequence_frames(sequence_capture_t *captures, size_t count) +{ + sequence_capture_set_t set = { + .captures = captures, + .count = count, + }; + for (int i = 0; i < BLE_LOG_TRANS_TOTAL_CNT; i++) { + size_t len = ble_log_prph_test_read( + s_read_buf, sizeof(s_read_buf), pdMS_TO_TICKS(TEST_READ_TIMEOUT_MS), + 0, NULL); + if (!len) { + break; + } + TEST_ASSERT_TRUE(test_ble_log_walk_frames( + s_read_buf, len, capture_sequence_frame, &set)); + } +} + +static void auto_recycle_noop(void *ctx) +{ + (void)ctx; +} + +TEST_CASE("BLE Log preserves LL payload and rejects oversized records", + "[ble_log][lbm][wire]") +{ + enum { + CUSTOM_BEFORE, + CUSTOM_OVERSIZED, + CUSTOM_AFTER, +#if CONFIG_BLE_LOG_LL_ENABLED + LL_BEFORE, + LL_PRIMARY_OVERSIZED, + LL_APPEND_OVERSIZED, + LL_AFTER, +#endif + SEQUENCE_CAPTURE_COUNT, + }; + static uint8_t custom_oversized_payload[ + BLE_LOG_MAX_PAYLOAD_LEN - sizeof(uint32_t) + 1]; +#if CONFIG_BLE_LOG_LL_ENABLED + static uint8_t ll_oversized_payload[BLE_LOG_MAX_PAYLOAD_LEN + 1]; + static uint8_t ll_oversized_append[BLE_LOG_MAX_PAYLOAD_LEN]; +#endif + const uint8_t custom_before = 0x61; + const uint8_t custom_oversized = 0x62; + const uint8_t custom_after = 0x63; +#if CONFIG_BLE_LOG_LL_ENABLED + const uint8_t ll_before = 0x64; + const uint8_t ll_primary_oversized = 0x65; + const uint8_t ll_append_oversized = 0x66; + const uint8_t ll_after = 0x67; +#endif + sequence_capture_t captures[SEQUENCE_CAPTURE_COUNT] = { + [CUSTOM_BEFORE] = {.src = BLE_LOG_SRC_CUSTOM, .marker = custom_before}, + [CUSTOM_OVERSIZED] = { + .src = BLE_LOG_SRC_CUSTOM, + .marker = custom_oversized, + }, + [CUSTOM_AFTER] = {.src = BLE_LOG_SRC_CUSTOM, .marker = custom_after}, +#if CONFIG_BLE_LOG_LL_ENABLED + [LL_BEFORE] = {.src = BLE_LOG_SRC_LL_TASK, .marker = ll_before}, + [LL_PRIMARY_OVERSIZED] = { + .src = BLE_LOG_SRC_LL_TASK, + .marker = ll_primary_oversized, + }, + [LL_APPEND_OVERSIZED] = { + .src = BLE_LOG_SRC_LL_TASK, + .marker = ll_append_oversized, + }, + [LL_AFTER] = {.src = BLE_LOG_SRC_LL_TASK, .marker = ll_after}, +#endif + }; + + TEST_ASSERT_TRUE(ble_log_enable(true)); + ble_log_lbm_flush_open_transports(); + for (int round = 0; round < 2; round++) { + TEST_ASSERT_TRUE(ble_log_rt_drain()); + while (ble_log_prph_test_read(s_read_buf, sizeof(s_read_buf), + 0, 0, NULL) > 0) { + } + } + + TEST_ASSERT_TRUE(ble_log_write_hex(BLE_LOG_SRC_CUSTOM, + &custom_before, sizeof(custom_before))); + memset(custom_oversized_payload, 0, sizeof(custom_oversized_payload)); + custom_oversized_payload[0] = custom_oversized; + TEST_ASSERT_FALSE(ble_log_write_hex(BLE_LOG_SRC_CUSTOM, + custom_oversized_payload, + sizeof(custom_oversized_payload))); + TEST_ASSERT_TRUE(ble_log_write_hex(BLE_LOG_SRC_CUSTOM, + &custom_after, sizeof(custom_after))); + +#if CONFIG_BLE_LOG_LL_ENABLED + ble_log_write_hex_ll(sizeof(ll_before), &ll_before, 0, NULL, + BIT(BLE_LOG_LL_FLAG_TASK)); + memset(ll_oversized_payload, 0, sizeof(ll_oversized_payload)); + ll_oversized_payload[0] = ll_primary_oversized; + ble_log_write_hex_ll(sizeof(ll_oversized_payload), ll_oversized_payload, + 0, NULL, BIT(BLE_LOG_LL_FLAG_TASK)); + memset(ll_oversized_append, 0, sizeof(ll_oversized_append)); + ble_log_write_hex_ll(sizeof(ll_append_oversized), &ll_append_oversized, + sizeof(ll_oversized_append), ll_oversized_append, + BIT(BLE_LOG_LL_FLAG_TASK)); + ble_log_write_hex_ll(sizeof(ll_after), &ll_after, 0, NULL, + BIT(BLE_LOG_LL_FLAG_TASK)); +#endif + + ble_log_lbm_flush_open_transports(); + TEST_ASSERT_TRUE(ble_log_rt_drain()); + read_sequence_frames(captures, SEQUENCE_CAPTURE_COUNT); + + TEST_ASSERT_TRUE(captures[CUSTOM_BEFORE].found); + TEST_ASSERT_FALSE(captures[CUSTOM_OVERSIZED].found); + TEST_ASSERT_TRUE(captures[CUSTOM_AFTER].found); + TEST_ASSERT_EQUAL_HEX32( + (captures[CUSTOM_BEFORE].sn + 2) & 0x00ffffffU, + captures[CUSTOM_AFTER].sn); +#if CONFIG_BLE_LOG_LL_ENABLED + TEST_ASSERT_TRUE(captures[LL_BEFORE].found); + TEST_ASSERT_FALSE(captures[LL_PRIMARY_OVERSIZED].found); + TEST_ASSERT_FALSE(captures[LL_APPEND_OVERSIZED].found); + TEST_ASSERT_TRUE(captures[LL_AFTER].found); + TEST_ASSERT_EQUAL_HEX32( + (captures[LL_BEFORE].sn + 3) & 0x00ffffffU, + captures[LL_AFTER].sn); +#endif +} + +TEST_CASE("BLE Log flush preserves source-local sequence continuity", + "[ble_log][wire]") +{ + const uint8_t before_marker = 0x71; + const uint8_t after_marker = 0x72; + TEST_ASSERT_TRUE(ble_log_enable(true)); + ble_log_lbm_flush_open_transports(); + for (int round = 0; round < 2; round++) { + TEST_ASSERT_TRUE(ble_log_rt_drain()); + while (ble_log_prph_test_read(s_read_buf, sizeof(s_read_buf), + 0, 0, NULL) > 0) { + } + } + + TEST_ASSERT_TRUE(ble_log_write_hex(BLE_LOG_SRC_CUSTOM, + &before_marker, sizeof(before_marker))); + ble_log_lbm_flush_open_transports(); + TEST_ASSERT_TRUE(ble_log_rt_drain()); + sequence_capture_t before = { + .src = BLE_LOG_SRC_CUSTOM, + .marker = before_marker, + }; + read_sequence_frames(&before, 1); + TEST_ASSERT_TRUE(before.found); + + /* The test peripheral normally recycles only when read. Auto-recycle lets + * synchronous flush observe completion without a second reader task. */ + ble_log_prph_test_set_auto_recycle_hook(auto_recycle_noop, NULL); + ble_log_flush(); + ble_log_prph_test_set_auto_recycle_hook(NULL, NULL); + + TEST_ASSERT_TRUE(ble_log_write_hex(BLE_LOG_SRC_CUSTOM, + &after_marker, sizeof(after_marker))); + ble_log_lbm_flush_open_transports(); + TEST_ASSERT_TRUE(ble_log_rt_drain()); + sequence_capture_t after = { + .src = BLE_LOG_SRC_CUSTOM, + .marker = after_marker, + }; + read_sequence_frames(&after, 1); + TEST_ASSERT_TRUE(after.found); + TEST_ASSERT_EQUAL_HEX32((before.sn + 1) & 0x00ffffffU, after.sn); +} + +#define SNAPSHOT_CAPTURE_MAX 8 + +typedef struct { + uint32_t sn[SNAPSHOT_CAPTURE_MAX]; + int count; +} snapshot_capture_t; + +static void capture_snapshot_loss(const test_ble_log_frame_t *frame, void *ctx) +{ + snapshot_capture_t *capture = ctx; + if (frame->src != BLE_LOG_SRC_INTERNAL || + frame->payload_len != sizeof(uint32_t) + + sizeof(ble_log_internal_snapshot_t)) { + return; + } + + ble_log_internal_snapshot_t snapshot; + memcpy(&snapshot, frame->payload + sizeof(uint32_t), sizeof(snapshot)); + if (snapshot.int_src_code == BLE_LOG_INT_SRC_SNAPSHOT && + (snapshot.reason_flags & BLE_LOG_SNAPSHOT_REASON_PERIODIC) && + capture->count < SNAPSHOT_CAPTURE_MAX) { + capture->sn[capture->count++] = frame->sn; + } +} + +TEST_CASE("BLE Log periodic snapshot fails fast while its transport is busy", + "[ble_log][lbm]") +{ + TEST_ASSERT_TRUE(ble_log_enable(true)); + ble_log_lbm_flush_open_transports(); + for (int round = 0; round < 2; round++) { + TEST_ASSERT_TRUE(ble_log_rt_drain()); + while (ble_log_prph_test_read(s_read_buf, sizeof(s_read_buf), + 0, 0, NULL) > 0) { + } + } + + TEST_ASSERT_TRUE(ble_log_enable(false)); + TEST_ASSERT_FALSE(ble_log_internal_snapshot( + BLE_LOG_SNAPSHOT_REASON_PERIODIC, NULL, false)); + TEST_ASSERT_TRUE(ble_log_enable(true)); + + TEST_ASSERT_TRUE(ble_log_internal_snapshot( + BLE_LOG_SNAPSHOT_REASON_PERIODIC, NULL, false)); + TEST_ASSERT_FALSE(ble_log_internal_snapshot( + BLE_LOG_SNAPSHOT_REASON_PERIODIC, NULL, false)); + TEST_ASSERT_TRUE(ble_log_rt_drain()); + TEST_ASSERT_GREATER_THAN_size_t( + 0, ble_log_prph_test_read(s_read_buf, sizeof(s_read_buf), + pdMS_TO_TICKS(TEST_READ_TIMEOUT_MS), 0, NULL)); + + TEST_ASSERT_TRUE(ble_log_internal_snapshot( + BLE_LOG_SNAPSHOT_REASON_PERIODIC, NULL, false)); + TEST_ASSERT_TRUE(ble_log_rt_drain()); + + snapshot_capture_t capture = {0}; + for (int i = 0; i < BLE_LOG_TRANS_TOTAL_CNT; i++) { + size_t len = ble_log_prph_test_read( + s_read_buf, sizeof(s_read_buf), pdMS_TO_TICKS(TEST_READ_TIMEOUT_MS), + 0, NULL); + if (!len) { + break; + } + TEST_ASSERT_TRUE(test_ble_log_walk_frames( + s_read_buf, len, capture_snapshot_loss, &capture)); + } + /* The busy periodic attempt burned one snapshot SN: the gap in the + * snapshot sequence is the loss signal. */ + TEST_ASSERT_GREATER_OR_EQUAL_INT(2, capture.count); + bool gap_seen = false; + for (int i = 1; i < capture.count; i++) { + if (((capture.sn[i] - capture.sn[i - 1]) & 0x00ffffffU) >= 2) { + gap_seen = true; + } + } + TEST_ASSERT_TRUE(gap_seen); +} + +#if CONFIG_BLE_LOG_LL_ENABLED +typedef struct { + SemaphoreHandle_t started; + SemaphoreHandle_t done; +} waiter_ctx_t; + +typedef struct { + SemaphoreHandle_t done; + bool result; +} enable_ctx_t; + +typedef struct { + SemaphoreHandle_t started; + SemaphoreHandle_t done; +} deinit_ctx_t; + +static void blocked_ll_writer_task(void *arg) +{ + waiter_ctx_t *ctx = arg; + static const uint8_t marker = 0x55; + xSemaphoreGive(ctx->started); + ble_log_write_hex_ll(sizeof(marker), &marker, 0, NULL, + BIT(BLE_LOG_LL_FLAG_TASK)); + xSemaphoreGive(ctx->done); + vTaskDelete(NULL); +} + +static void racing_enable_task(void *arg) +{ + enable_ctx_t *ctx = arg; + ctx->result = ble_log_enable(true); + xSemaphoreGive(ctx->done); + vTaskDelete(NULL); +} + +static void racing_disable_task(void *arg) +{ + enable_ctx_t *ctx = arg; + ctx->result = ble_log_enable(false); + xSemaphoreGive(ctx->done); + vTaskDelete(NULL); +} + +static void lifecycle_deinit_task(void *arg) +{ + deinit_ctx_t *ctx = arg; + xSemaphoreGive(ctx->started); + ble_log_deinit(); + xSemaphoreGive(ctx->done); + vTaskDelete(NULL); +} + +TEST_CASE("BLE Log deinit closes a parked LL writer before racing enable", + "[ble_log][lbm]") +{ + static const uint8_t full_payload[ + BLE_LOG_MAX_PAYLOAD_LEN - sizeof(uint32_t)] = {0}; + + TEST_ASSERT_TRUE(ble_log_enable(true)); + ble_log_lbm_flush_open_transports(); + TEST_ASSERT_TRUE(ble_log_rt_drain()); + while (ble_log_prph_test_read(s_read_buf, sizeof(s_read_buf), 0, 0, NULL) > 0) { + } + TEST_ASSERT_TRUE(ble_log_rt_drain()); + while (ble_log_prph_test_read(s_read_buf, sizeof(s_read_buf), 0, 0, NULL) > 0) { + } + + /* Keep every task-usable transport SENDING in the test peripheral. */ + for (int i = 0; i < BLE_LOG_POOL_SHARED_CNT; i++) { + TEST_ASSERT_TRUE(ble_log_write_hex(BLE_LOG_SRC_CUSTOM, full_payload, + sizeof(full_payload))); + } + static const uint8_t reserve_marker = 0x56; + TEST_ASSERT_FALSE(ble_log_write_hex(BLE_LOG_SRC_CUSTOM, + &reserve_marker, + sizeof(reserve_marker))); + uint32_t exhausted_handle; + TEST_ASSERT_NULL(ble_log_claim(BLE_LOG_SRC_ENCODE, 1, + &exhausted_handle)); + + portMUX_TYPE reserve_mux = portMUX_INITIALIZER_UNLOCKED; + portENTER_CRITICAL(&reserve_mux); + bool reserve_written = ble_log_write_hex(BLE_LOG_SRC_CUSTOM, + &reserve_marker, + sizeof(reserve_marker)); + portEXIT_CRITICAL(&reserve_mux); + TEST_ASSERT_TRUE(reserve_written); + + waiter_ctx_t waiter = { + .started = xSemaphoreCreateBinary(), + .done = xSemaphoreCreateBinary(), + }; + TEST_ASSERT_NOT_NULL(waiter.started); + TEST_ASSERT_NOT_NULL(waiter.done); + TEST_ASSERT_EQUAL(pdTRUE, + xTaskCreate(blocked_ll_writer_task, "ble_log_wait", + TEST_LIFECYCLE_STACK_SIZE, &waiter, + TEST_LIFECYCLE_PRIO, NULL)); + TEST_ASSERT_TRUE(xSemaphoreTake(waiter.started, pdMS_TO_TICKS(1000))); + vTaskDelay(1); + TEST_ASSERT_EQUAL(pdFALSE, xSemaphoreTake(waiter.done, 0)); + + s_enable_hook_entered = xSemaphoreCreateBinary(); + s_enable_hook_continue = xSemaphoreCreateBinary(); + TEST_ASSERT_NOT_NULL(s_enable_hook_entered); + TEST_ASSERT_NOT_NULL(s_enable_hook_continue); + s_enable_hook_armed = true; + + enable_ctx_t enabler = { + .done = xSemaphoreCreateBinary(), + }; + TEST_ASSERT_NOT_NULL(enabler.done); + TEST_ASSERT_EQUAL(pdTRUE, + xTaskCreate(racing_enable_task, "ble_log_enable", + TEST_LIFECYCLE_STACK_SIZE, &enabler, + TEST_LIFECYCLE_PRIO, NULL)); + TEST_ASSERT_TRUE(xSemaphoreTake(s_enable_hook_entered, + pdMS_TO_TICKS(1000))); + + /* The enable task is paused immediately before the lifecycle lock. Close + * and destroy the module, then let enable perform its locked recheck. */ + ble_log_deinit(); + TEST_ASSERT_TRUE(xSemaphoreTake(waiter.done, pdMS_TO_TICKS(1000))); + xSemaphoreGive(s_enable_hook_continue); + TEST_ASSERT_TRUE(xSemaphoreTake(enabler.done, pdMS_TO_TICKS(1000))); + s_enable_hook_armed = false; + TEST_ASSERT_FALSE(enabler.result); + + vSemaphoreDelete(waiter.started); + vSemaphoreDelete(waiter.done); + vSemaphoreDelete(enabler.done); + vSemaphoreDelete(s_enable_hook_entered); + vSemaphoreDelete(s_enable_hook_continue); + s_enable_hook_entered = NULL; + s_enable_hook_continue = NULL; + + TEST_ASSERT_TRUE(ble_log_init()); +} + +TEST_CASE("BLE Log disable keeps waiter semaphore alive during deinit", + "[ble_log][lbm]") +{ + TEST_ASSERT_TRUE(ble_log_enable(true)); + s_disable_hook_entered = xSemaphoreCreateBinary(); + s_disable_hook_continue = xSemaphoreCreateBinary(); + TEST_ASSERT_NOT_NULL(s_disable_hook_entered); + TEST_ASSERT_NOT_NULL(s_disable_hook_continue); + s_disable_hook_armed = true; + + enable_ctx_t disabler = { + .done = xSemaphoreCreateBinary(), + }; + deinit_ctx_t deinit = { + .started = xSemaphoreCreateBinary(), + .done = xSemaphoreCreateBinary(), + }; + TEST_ASSERT_NOT_NULL(disabler.done); + TEST_ASSERT_NOT_NULL(deinit.started); + TEST_ASSERT_NOT_NULL(deinit.done); + + TEST_ASSERT_EQUAL(pdTRUE, + xTaskCreate(racing_disable_task, "ble_log_disable", + TEST_LIFECYCLE_STACK_SIZE, &disabler, + TEST_LIFECYCLE_PRIO, NULL)); + TEST_ASSERT_TRUE(xSemaphoreTake(s_disable_hook_entered, + pdMS_TO_TICKS(1000))); + TEST_ASSERT_EQUAL(pdTRUE, + xTaskCreate(lifecycle_deinit_task, "ble_log_deinit", + TEST_LIFECYCLE_STACK_SIZE, &deinit, + TEST_LIFECYCLE_PRIO, NULL)); + TEST_ASSERT_TRUE(xSemaphoreTake(deinit.started, pdMS_TO_TICKS(1000))); + TEST_ASSERT_EQUAL(pdFALSE, + xSemaphoreTake(deinit.done, pdMS_TO_TICKS(20))); + + xSemaphoreGive(s_disable_hook_continue); + TEST_ASSERT_TRUE(xSemaphoreTake(disabler.done, pdMS_TO_TICKS(1000))); + TEST_ASSERT_TRUE(xSemaphoreTake(deinit.done, pdMS_TO_TICKS(1000))); + s_disable_hook_armed = false; + TEST_ASSERT_TRUE(disabler.result); + + vSemaphoreDelete(disabler.done); + vSemaphoreDelete(deinit.started); + vSemaphoreDelete(deinit.done); + vSemaphoreDelete(s_disable_hook_entered); + vSemaphoreDelete(s_disable_hook_continue); + s_disable_hook_entered = NULL; + s_disable_hook_continue = NULL; + + TEST_ASSERT_TRUE(ble_log_init()); +} +#endif /* CONFIG_BLE_LOG_LL_ENABLED */