From 23d4c90c6dcdf13247906759bba06f33b2d9df1d Mon Sep 17 00:00:00 2001 From: Zhou Xiao Date: Tue, 8 Jul 2025 13:15:00 +0800 Subject: [PATCH 01/14] change(ble): updated ble log spi out ts sync module * use freertos ts instead of esp ts for better performance * enable ts sync sleep support by default * use esp ts as fallback of lc time getter (cherry picked from commit 56e42be85954bf737cd11fbc7bbbb2300750b64b) Co-authored-by: Zhou Xiao --- components/bt/common/Kconfig.in | 2 +- .../bt/common/ble_log/ble_log_spi_out.c | 21 +++++++++++-------- 2 files changed, 13 insertions(+), 10 deletions(-) diff --git a/components/bt/common/Kconfig.in b/components/bt/common/Kconfig.in index ff1947a326..e2052553d6 100644 --- a/components/bt/common/Kconfig.in +++ b/components/bt/common/Kconfig.in @@ -105,7 +105,7 @@ config BT_BLE_LOG_SPI_OUT_SYNC_IO_NUM config BT_BLE_LOG_SPI_OUT_TS_SYNC_SLEEP_SUPPORT bool "Enable ble log & logic analyzer log time sync sleep support" depends on BT_BLE_LOG_SPI_OUT_LL_ENABLED - default n + default y help Enable ble log & logic analyzer log time sync sleep support diff --git a/components/bt/common/ble_log/ble_log_spi_out.c b/components/bt/common/ble_log/ble_log_spi_out.c index 3ee7f5119f..2fa4b966b1 100644 --- a/components/bt/common/ble_log/ble_log_spi_out.c +++ b/components/bt/common/ble_log/ble_log_spi_out.c @@ -40,7 +40,8 @@ #define SPI_OUT_MALLOC(size) heap_caps_malloc(size, MALLOC_CAP_INTERNAL | MALLOC_CAP_8BIT) #if SPI_OUT_TS_SYNC_ENABLED -#define SPI_OUT_TS_SYNC_TIMEOUT (1000 * 1000) +#define SPI_OUT_TS_SYNC_TIMEOUT_MS (1000) +#define SPI_OUT_TS_SYNC_TIMEOUT_US (SPI_OUT_TS_SYNC_TIMEOUT_MS * 1000) #endif // SPI_OUT_TS_SYNC_ENABLED // Queue size defines @@ -90,7 +91,7 @@ typedef struct { typedef struct { uint8_t io_level; uint32_t lc_ts; - uint32_t esp_ts; + uint32_t os_ts; } __attribute__((packed)) ts_sync_data_t; // Private enums @@ -127,6 +128,7 @@ static bool spi_out_inited = false; static bool spi_out_enabled = false; static spi_device_handle_t spi_handle = NULL; static uint32_t last_tx_done_ts = 0; +static uint32_t last_tx_done_os_ts = 0; static bool ul_log_inited = false; static SemaphoreHandle_t ul_log_mutex = NULL; @@ -217,7 +219,7 @@ extern uint32_t r_ble_lll_timer_current_tick_get(void); extern uint32_t r_os_cputime_get32(void); #define SPI_OUT_GET_LC_TIME r_os_cputime_get32() #else -#define SPI_OUT_GET_LC_TIME 0 +#define SPI_OUT_GET_LC_TIME esp_timer_get_time() #endif #if !SPI_OUT_TS_SYNC_SLEEP_SUPPORT @@ -272,6 +274,7 @@ static void spi_out_deinit_trans(spi_out_trans_cb_t **trans_cb) IRAM_ATTR static void spi_out_tx_done_cb(spi_transaction_t *ret_trans) { last_tx_done_ts = esp_timer_get_time(); + last_tx_done_os_ts = pdTICKS_TO_MS(xTaskGetTickCountFromISR()); spi_out_trans_cb_t *trans_cb = (spi_out_trans_cb_t *)ret_trans->user; trans_cb->length = 0; trans_cb->flag = TRANS_CB_FLAG_AVAILABLE; @@ -577,8 +580,8 @@ static void spi_out_ul_log_write(uint8_t source, const uint8_t *addr, uint16_t l bool need_append; if (spi_out_log_cb_check_trans(ul_log_cb, total_len, &need_append)) { if (with_ts) { - uint32_t esp_ts = esp_timer_get_time(); - need_append |= spi_out_log_cb_write(ul_log_cb, (const uint8_t *)&esp_ts, + uint32_t os_ts = pdTICKS_TO_MS(xTaskGetTickCount()); + need_append |= spi_out_log_cb_write(ul_log_cb, (const uint8_t *)&os_ts, sizeof(uint32_t), addr, len, source, true); } else { need_append |= spi_out_log_cb_write(ul_log_cb, addr, len, NULL, 0, source, true); @@ -757,7 +760,7 @@ static void spi_out_ts_sync_enable(bool enable) // Start timestamp sync timer if (ts_sync_timer) { if (!esp_timer_is_active(ts_sync_timer)) { - esp_timer_start_periodic(ts_sync_timer, SPI_OUT_TS_SYNC_TIMEOUT); + esp_timer_start_periodic(ts_sync_timer, SPI_OUT_TS_SYNC_TIMEOUT_US); } } #endif // !SPI_OUT_TS_SYNC_SLEEP_SUPPORT @@ -793,8 +796,8 @@ static void spi_out_ts_sync_toggle(void) // Set sync IO level gpio_set_level(SPI_OUT_SYNC_IO_NUM, (uint32_t)ts_sync_data.io_level); - // Get ESP timestamp - ts_sync_data.esp_ts = esp_timer_get_time(); + // Get OS timestamp + ts_sync_data.os_ts = pdTICKS_TO_MS(xTaskGetTickCountFromISR()); portEXIT_CRITICAL(&spinlock); // Exit critical } @@ -1058,7 +1061,7 @@ IRAM_ATTR void ble_log_spi_out_ll_write(uint32_t len, const uint8_t *addr, uint3 #if SPI_OUT_TS_SYNC_SLEEP_SUPPORT if (ts_sync_inited && ts_sync_enabled) { - if (last_tx_done_ts >= (SPI_OUT_TS_SYNC_TIMEOUT + ts_sync_data.esp_ts)) { + if (last_tx_done_os_ts >= (SPI_OUT_TS_SYNC_TIMEOUT_MS + ts_sync_data.os_ts)) { if (spi_out_log_cb_check_trans(ll_task_log_cb, sizeof(ts_sync_data_t), &need_append)) { spi_out_ts_sync_toggle(); spi_out_log_cb_write(ll_task_log_cb, (const uint8_t *)&ts_sync_data, From db90e638841cd546a35ec0ca66a1672018353694 Mon Sep 17 00:00:00 2001 From: Zhou Xiao Date: Tue, 8 Jul 2025 13:15:03 +0800 Subject: [PATCH 02/14] change(ble): implemented log module template (cherry picked from commit 8b2c176eff241a16381cfe7a95c551dd9212304a) Co-authored-by: Zhou Xiao --- .../bt/common/ble_log/ble_log_spi_out.c | 84 +++++++++++++++++++ 1 file changed, 84 insertions(+) diff --git a/components/bt/common/ble_log/ble_log_spi_out.c b/components/bt/common/ble_log/ble_log_spi_out.c index 2fa4b966b1..12fe2a3be5 100644 --- a/components/bt/common/ble_log/ble_log_spi_out.c +++ b/components/bt/common/ble_log/ble_log_spi_out.c @@ -232,6 +232,90 @@ static int spi_out_le_audio_log_init(void); static void spi_out_le_audio_log_deinit(void); #endif // SPI_OUT_LE_AUDIO_ENABLED +// Private templates +#define IF_1(...) __VA_ARGS__ +#define IF_0(...) + +#define LOG_MODULE_INIT_FLAG(ID) (ID##_log_inited) +#define LOG_MODULE_CB(ID) (ID##_log_cb) +#define LOG_MODULE_MUTEX(ID) (ID##_log_mutex) +#define LOG_MODULE_STR_BUF(ID) (ID##_log_str_buf) +#define LOG_MODULE_INIT(ID) (spi_out_##ID##_log_init) +#define LOG_MODULE_DEINIT(ID) (spi_out_##ID##_log_deinit) +#define LOG_MODULE_FLUSH(ID) (spi_out_##ID##_log_flush) + +#define DECLARE_LOG_MODULE(ID, TYPE, BUF_SIZE, USE_MUTEX, USE_STR) \ + static bool LOG_MODULE_INIT_FLAG(ID) = false; \ + static spi_out_log_cb_t *LOG_MODULE_CB(ID) = NULL; \ + IF_##USE_MUTEX(static SemaphoreHandle_t LOG_MODULE_MUTEX(ID) = NULL;) \ + IF_##USE_STR(static uint8_t *LOG_MODULE_STR_BUF(ID) = NULL;) \ + \ + static int LOG_MODULE_INIT(ID)(void); \ + static void LOG_MODULE_DEINIT(ID)(void); \ + static void LOG_MODULE_FLUSH(ID)(void); \ + \ + static int LOG_MODULE_INIT(ID)(void) { \ + if (LOG_MODULE_INIT_FLAG(ID)) { \ + return 0; \ + } \ + IF_##USE_MUTEX( \ + LOG_MODULE_MUTEX(ID) = xSemaphoreCreateMutex(); \ + if (!LOG_MODULE_MUTEX(ID)) { \ + goto failed; \ + } \ + ) \ + IF_##USE_STR( \ + LOG_MODULE_STR_BUF(ID) = (uint8_t *)SPI_OUT_MALLOC(SPI_OUT_LOG_STR_BUF_SIZE); \ + if (!LOG_MODULE_STR_BUF(ID)) { \ + goto failed; \ + } \ + ) \ + if (spi_out_log_cb_init(&LOG_MODULE_CB(ID), BUF_SIZE, TYPE) != 0) { \ + goto failed; \ + } \ + LOG_MODULE_INIT_FLAG(ID) = true; \ + return 0; \ + failed: \ + LOG_MODULE_DEINIT(ID)(); \ + return -1; \ + } \ + static void LOG_MODULE_DEINIT(ID)(void) { \ + LOG_MODULE_INIT_FLAG(ID) = false; \ + IF_##USE_MUTEX( \ + if (!LOG_MODULE_MUTEX(ID)) { \ + return; \ + } \ + xSemaphoreTake(LOG_MODULE_MUTEX(ID), portMAX_DELAY); \ + ) \ + IF_##USE_STR( \ + if (LOG_MODULE_STR_BUF(ID)) { \ + free(LOG_MODULE_STR_BUF(ID)); \ + LOG_MODULE_STR_BUF(ID) = NULL; \ + } \ + ) \ + spi_out_log_cb_deinit(&LOG_MODULE_CB(ID)); \ + \ + IF_##USE_MUTEX( \ + xSemaphoreGive(LOG_MODULE_MUTEX(ID)); \ + vSemaphoreDelete(LOG_MODULE_MUTEX(ID)); \ + LOG_MODULE_MUTEX(ID) = NULL; \ + ) \ + } \ + static void LOG_MODULE_FLUSH(ID)(void) { \ + if (!LOG_MODULE_INIT_FLAG(ID)) { \ + return; \ + } \ + IF_##USE_MUTEX( \ + xSemaphoreTake(LOG_MODULE_MUTEX(ID), portMAX_DELAY); \ + ) \ + spi_out_log_cb_write_loss(LOG_MODULE_CB(ID)); \ + spi_out_log_cb_flush_trans(LOG_MODULE_CB(ID)); \ + spi_out_log_cb_append_trans(LOG_MODULE_CB(ID)); \ + IF_##USE_MUTEX( \ + xSemaphoreGive(LOG_MODULE_MUTEX(ID)); \ + ) \ + } \ + // Private functions static int spi_out_init_trans(spi_out_trans_cb_t **trans_cb, uint16_t buf_size) { From 1da626b0a7b40dbc19b9fb968d97ceb74ea3ec85 Mon Sep 17 00:00:00 2001 From: Zhou Xiao Date: Tue, 8 Jul 2025 13:15:05 +0800 Subject: [PATCH 03/14] change(ble): replaced le audio log codes with template (cherry picked from commit feaee0a6fee8e65c420cf4852a2edd00aa740286) Co-authored-by: Zhou Xiao --- .../bt/common/ble_log/ble_log_spi_out.c | 88 ++++++++----------- 1 file changed, 36 insertions(+), 52 deletions(-) diff --git a/components/bt/common/ble_log/ble_log_spi_out.c b/components/bt/common/ble_log/ble_log_spi_out.c index 12fe2a3be5..2a0a002cc8 100644 --- a/components/bt/common/ble_log/ble_log_spi_out.c +++ b/components/bt/common/ble_log/ble_log_spi_out.c @@ -54,8 +54,15 @@ #define SPI_OUT_LL_QUEUE_SIZE (0) #endif // SPI_OUT_LL_ENABLED +#if SPI_OUT_LE_AUDIO_ENABLED +#define SPI_OUT_LE_AUDIO_QUEUE_SIZE (SPI_OUT_PING_PONG_BUF_CNT) +#else +#define SPI_OUT_LE_AUDIO_QUEUE_SIZE (0) +#endif // SPI_OUT_LE_AUDIO_ENABLED + #define SPI_OUT_SPI_MASTER_QUEUE_SIZE (SPI_OUT_UL_QUEUE_SIZE +\ - SPI_OUT_LL_QUEUE_SIZE) + SPI_OUT_LL_QUEUE_SIZE +\ + SPI_OUT_LE_AUDIO_QUEUE_SIZE) // Private typedefs typedef struct { @@ -157,11 +164,6 @@ static esp_timer_handle_t ts_sync_timer = NULL; static esp_timer_handle_t flush_timer = NULL; #endif // SPI_OUT_FLUSH_TIMER_ENABLED -#if SPI_OUT_LE_AUDIO_ENABLED -static bool le_audio_log_inited = false; -static spi_out_log_cb_t *le_audio_log_cb = NULL; -#endif // SPI_OUT_LE_AUDIO_ENABLED - // Extern function declarations extern void esp_panic_handler_feed_wdts(void); @@ -227,11 +229,6 @@ static void esp_timer_cb_ts_sync(void); #endif // !SPI_OUT_TS_SYNC_SLEEP_SUPPORT #endif // SPI_OUT_TS_SYNC_ENABLED -#if SPI_OUT_LE_AUDIO_ENABLED -static int spi_out_le_audio_log_init(void); -static void spi_out_le_audio_log_deinit(void); -#endif // SPI_OUT_LE_AUDIO_ENABLED - // Private templates #define IF_1(...) __VA_ARGS__ #define IF_0(...) @@ -316,6 +313,10 @@ static void spi_out_le_audio_log_deinit(void); ) \ } \ +#if SPI_OUT_LE_AUDIO_ENABLED +DECLARE_LOG_MODULE(le_audio, LOG_CB_TYPE_LE_AUDIO, SPI_OUT_LE_AUDIO_BUF_SIZE, 0, 0) +#endif // SPI_OUT_LE_AUDIO_ENABLED + // Private functions static int spi_out_init_trans(spi_out_trans_cb_t **trans_cb, uint16_t buf_size) { @@ -583,6 +584,10 @@ static void spi_out_log_flush(void) SPI_OUT_LL_PUT_EV; } #endif // SPI_OUT_LL_ENABLED + +#if SPI_OUT_LE_AUDIO_ENABLED + LOG_MODULE_FLUSH(le_audio)(); +#endif // SPI_OUT_LE_AUDIO_ENABLED } #if SPI_OUT_FLUSH_TIMER_ENABLED @@ -899,40 +904,6 @@ static void esp_timer_cb_ts_sync(void) #endif // !SPI_OUT_TS_SYNC_SLEEP_SUPPORT #endif // SPI_OUT_TS_SYNC_ENABLED -#if SPI_OUT_LE_AUDIO_ENABLED -static int spi_out_le_audio_log_init(void) -{ - if (le_audio_log_inited) { - return 0; - } - - // Initialize log control blocks for controller task & ISR logs - if (spi_out_log_cb_init(&le_audio_log_cb, SPI_OUT_LE_AUDIO_BUF_SIZE, LOG_CB_TYPE_LE_AUDIO) != 0) { - ESP_LOGE(BLE_LOG_TAG, "Failed to initialize log control blocks for LE audio!"); - return -1; - } - - // Initialization done - ESP_LOGI(BLE_LOG_TAG, "Succeeded to initialize log control blocks for LE Audio!"); - le_audio_log_inited = true; - return 0; -} - -static void spi_out_le_audio_log_deinit(void) -{ - if (!le_audio_log_inited) { - return; - } - - spi_out_log_cb_deinit(&le_audio_log_cb); - - // Deinitialization done - ESP_LOGI(BLE_LOG_TAG, "Succeeded to deinitialize LE audio log!"); - le_audio_log_inited = false; - return; -} -#endif // SPI_OUT_LE_AUDIO_ENABLED - // Public functions int ble_log_spi_out_init(void) { @@ -988,7 +959,7 @@ int ble_log_spi_out_init(void) #endif // SPI_OUT_TS_SYNC_ENABLED #if SPI_OUT_LE_AUDIO_ENABLED - if (spi_out_le_audio_log_init() != 0) { + if (LOG_MODULE_INIT(le_audio)() != 0) { goto le_audio_init_failed; } #endif // SPI_OUT_LE_AUDIO_ENABLED @@ -1018,7 +989,7 @@ int ble_log_spi_out_init(void) timer_init_failed: #endif // SPI_OUT_FLUSH_TIMER_ENABLED #if SPI_OUT_LE_AUDIO_ENABLED - spi_out_le_audio_log_deinit(); + LOG_MODULE_DEINIT(le_audio)(); le_audio_init_failed: #endif // SPI_OUT_LE_AUDIO_ENABLED #if SPI_OUT_TS_SYNC_ENABLED @@ -1065,6 +1036,10 @@ void ble_log_spi_out_deinit(void) spi_out_ts_sync_deinit(); #endif // SPI_OUT_TS_SYNC_ENABLED +#if SPI_OUT_LE_AUDIO_ENABLED + LOG_MODULE_DEINIT(le_audio)(); +#endif // SPI_OUT_LE_AUDIO_ENABLED + #if SPI_OUT_LL_ENABLED spi_out_ll_log_deinit(); #endif // SPI_OUT_LL_ENABLED @@ -1289,6 +1264,15 @@ void ble_log_spi_out_dump_all(void) spi_out_log_cb_dump(ul_log_cb); esp_rom_printf("\n:UL_LOG_DUMP_END]\n\n"); } + +#if SPI_OUT_LE_AUDIO_ENABLED + if (LOG_MODULE_INIT_FLAG(le_audio)) { + esp_rom_printf("[LE_AUDIO_LOG_DUMP_START:\n"); + spi_out_log_cb_dump(LOG_MODULE_CB(le_audio)); + esp_rom_printf("\n:LE_AUDIO_LOG_DUMP_END]\n\n"); + } +#endif // SPI_OUT_LE_AUDIO_ENABLED + portEXIT_CRITICAL_SAFE(&spinlock); } @@ -1315,19 +1299,19 @@ void ble_log_spi_out_flush(void) #if CONFIG_BT_BLE_LOG_SPI_OUT_LE_AUDIO_ENABLED IRAM_ATTR void ble_log_spi_out_le_audio_write(const uint8_t *addr, uint16_t len) { - if (!le_audio_log_inited) { + if (!LOG_MODULE_INIT_FLAG(le_audio)) { return; } bool need_append; - if (spi_out_log_cb_check_trans(le_audio_log_cb, len, &need_append)) { - need_append |= spi_out_log_cb_write(le_audio_log_cb, addr, len, NULL, 0, + if (spi_out_log_cb_check_trans(LOG_MODULE_CB(le_audio), len, &need_append)) { + need_append |= spi_out_log_cb_write(LOG_MODULE_CB(le_audio), addr, len, NULL, 0, BLE_LOG_SPI_OUT_SOURCE_LE_AUDIO, false); } if (need_append) { - spi_out_log_cb_append_trans(le_audio_log_cb); + spi_out_log_cb_append_trans(LOG_MODULE_CB(le_audio)); } - spi_out_log_cb_write_loss(le_audio_log_cb); + spi_out_log_cb_write_loss(LOG_MODULE_CB(le_audio)); return; } #endif // CONFIG_BT_BLE_LOG_SPI_OUT_LE_AUDIO_ENABLED From d086865c1fdc55e901c241bdd44bb0d5c447ee16 Mon Sep 17 00:00:00 2001 From: Zhou Xiao Date: Tue, 8 Jul 2025 13:15:07 +0800 Subject: [PATCH 04/14] change(ble): replaced ul log codes with template (cherry picked from commit d353bf280257b8e1f9e34b6d676f5a8af2eb2245) Co-authored-by: Zhou Xiao --- .../bt/common/ble_log/ble_log_spi_out.c | 185 +++++++----------- 1 file changed, 74 insertions(+), 111 deletions(-) diff --git a/components/bt/common/ble_log/ble_log_spi_out.c b/components/bt/common/ble_log/ble_log_spi_out.c index 2a0a002cc8..b7da6ec434 100644 --- a/components/bt/common/ble_log/ble_log_spi_out.c +++ b/components/bt/common/ble_log/ble_log_spi_out.c @@ -36,7 +36,7 @@ #define SPI_OUT_FRAME_OVERHEAD (8) #define SPI_OUT_PACKET_LOSS_FRAME_SIZE (6) #define SPI_OUT_TRANS_ITVL_MIN_US (30) -#define SPI_OUT_UL_LOG_STR_BUF_SIZE (100) +#define SPI_OUT_LOG_STR_BUF_SIZE (100) #define SPI_OUT_MALLOC(size) heap_caps_malloc(size, MALLOC_CAP_INTERNAL | MALLOC_CAP_8BIT) #if SPI_OUT_TS_SYNC_ENABLED @@ -137,11 +137,6 @@ static spi_device_handle_t spi_handle = NULL; static uint32_t last_tx_done_ts = 0; static uint32_t last_tx_done_os_ts = 0; -static bool ul_log_inited = false; -static SemaphoreHandle_t ul_log_mutex = NULL; -static spi_out_log_cb_t *ul_log_cb = NULL; -static uint8_t *ul_log_str_buf = NULL; - #if SPI_OUT_LL_ENABLED static bool ll_log_inited = false; static spi_out_log_cb_t *ll_task_log_cb = NULL; @@ -185,10 +180,10 @@ static void spi_out_log_cb_write_loss(spi_out_log_cb_t *log_cb); static void spi_out_log_cb_dump(spi_out_log_cb_t *log_cb); static void spi_out_log_flush(void); -static int spi_out_ul_log_init(void); -static void spi_out_ul_log_deinit(void); -static void spi_out_ul_log_write(uint8_t source, const uint8_t *addr, uint16_t len, bool with_ts); -static bool spi_out_ul_log_printf(uint8_t source, const char *format, va_list args, int offset); +static inline spi_out_log_cb_t *spi_out_get_log_cb(uint8_t source); +static inline uint8_t *spi_out_get_str_buf(uint8_t source); +static void spi_out_log_write(uint8_t source, const uint8_t *addr, uint16_t len, bool with_ts); +static bool spi_out_log_printf(uint8_t source, const char *format, va_list args, int offset); #if SPI_OUT_LL_ENABLED static int spi_out_ll_log_init(void); @@ -313,6 +308,8 @@ static void esp_timer_cb_ts_sync(void); ) \ } \ +DECLARE_LOG_MODULE(ul, LOG_CB_TYPE_UL, SPI_OUT_UL_TASK_BUF_SIZE, 1, 1) + #if SPI_OUT_LE_AUDIO_ENABLED DECLARE_LOG_MODULE(le_audio, LOG_CB_TYPE_LE_AUDIO, SPI_OUT_LE_AUDIO_BUF_SIZE, 0, 0) #endif // SPI_OUT_LE_AUDIO_ENABLED @@ -572,11 +569,7 @@ static void spi_out_log_cb_dump(spi_out_log_cb_t *log_cb) static void spi_out_log_flush(void) { - // Flush ul log - xSemaphoreTake(ul_log_mutex, portMAX_DELAY); - spi_out_log_cb_flush_trans(ul_log_cb); - spi_out_log_cb_append_trans(ul_log_cb); - xSemaphoreGive(ul_log_mutex); + LOG_MODULE_FLUSH(ul)(); #if SPI_OUT_LL_ENABLED if (esp_bt_controller_get_status() >= ESP_BT_CONTROLLER_STATUS_INITED) { @@ -599,105 +592,63 @@ static void esp_timer_cb_log_flush(void) } #endif // SPI_OUT_FLUSH_TIMER_ENABLED -static int spi_out_ul_log_init(void) +static inline spi_out_log_cb_t *spi_out_get_log_cb(uint8_t source) { - if (ul_log_inited) { - return 0; + spi_out_log_cb_t *log_cb; + switch (source) { + default: + log_cb = LOG_MODULE_CB(ul); } - - // Initialize mutex - ul_log_mutex = xSemaphoreCreateMutex(); - if (!ul_log_mutex) { - ESP_LOGE(BLE_LOG_TAG, "Failed to create mutex for upper layer task log!"); - goto mutex_init_failed; - } - - // Initialize string buffer - ul_log_str_buf = (uint8_t *)SPI_OUT_MALLOC(SPI_OUT_UL_LOG_STR_BUF_SIZE); - if (!ul_log_str_buf) { - ESP_LOGE(BLE_LOG_TAG, "Failed to initialize string buffer for upper layer task log!"); - goto str_buf_init_failed; - } - - // Initialize log control block - if (spi_out_log_cb_init(&ul_log_cb, SPI_OUT_UL_TASK_BUF_SIZE, LOG_CB_TYPE_UL) != 0) { - ESP_LOGE(BLE_LOG_TAG, "Failed to initialize log control blocks for upper layer task log!"); - goto log_cb_init_failed; - } - - // Initialization done - ESP_LOGI(BLE_LOG_TAG, "Succeeded to initialize upper layer task log!"); - ul_log_inited = true; - return 0; - -log_cb_init_failed: - if (ul_log_str_buf) { - free(ul_log_str_buf); - ul_log_str_buf = NULL; - } -str_buf_init_failed: - vSemaphoreDelete(ul_log_mutex); -mutex_init_failed: - return -1; + return log_cb; } -static void spi_out_ul_log_deinit(void) +static inline uint8_t *spi_out_get_str_buf(uint8_t source) { - if (!ul_log_inited) { - return; + uint8_t *str_buf; + switch (source) { + default: + str_buf = LOG_MODULE_STR_BUF(ul); } - ul_log_inited = false; - - xSemaphoreTake(ul_log_mutex, portMAX_DELAY); - if (ul_log_str_buf) { - free(ul_log_str_buf); - ul_log_str_buf = NULL; - } - spi_out_log_cb_deinit(&ul_log_cb); - xSemaphoreGive(ul_log_mutex); - - vSemaphoreDelete(ul_log_mutex); - ul_log_mutex = NULL; - - ESP_LOGI(BLE_LOG_TAG, "Succeeded to deinitialize upper layer log!"); - return; + return str_buf; } -static void spi_out_ul_log_write(uint8_t source, const uint8_t *addr, uint16_t len, bool with_ts) +static void spi_out_log_write(uint8_t source, const uint8_t *addr, uint16_t len, bool with_ts) { uint16_t total_len = with_ts? (len + sizeof(uint32_t)): len; bool need_append; - if (spi_out_log_cb_check_trans(ul_log_cb, total_len, &need_append)) { + spi_out_log_cb_t *log_cb = spi_out_get_log_cb(source); + if (spi_out_log_cb_check_trans(log_cb, total_len, &need_append)) { if (with_ts) { uint32_t os_ts = pdTICKS_TO_MS(xTaskGetTickCount()); - need_append |= spi_out_log_cb_write(ul_log_cb, (const uint8_t *)&os_ts, + need_append |= spi_out_log_cb_write(log_cb, (const uint8_t *)&os_ts, sizeof(uint32_t), addr, len, source, true); } else { - need_append |= spi_out_log_cb_write(ul_log_cb, addr, len, NULL, 0, source, true); + need_append |= spi_out_log_cb_write(log_cb, addr, len, NULL, 0, source, true); } } if (need_append) { - spi_out_log_cb_append_trans(ul_log_cb); + spi_out_log_cb_append_trans(log_cb); } - spi_out_log_cb_write_loss(ul_log_cb); + spi_out_log_cb_write_loss(log_cb); } -static bool spi_out_ul_log_printf(uint8_t source, const char *format, va_list args, int offset) +static bool spi_out_log_printf(uint8_t source, const char *format, va_list args, int offset) { - int len = vsnprintf((char *)(ul_log_str_buf + offset), - SPI_OUT_UL_LOG_STR_BUF_SIZE - offset, format, args); + uint8_t *str_buf = spi_out_get_str_buf(source); + int len = vsnprintf((char *)(str_buf + offset), + SPI_OUT_LOG_STR_BUF_SIZE - offset, format, args); if (len < 0) { return false; } len += offset; // Truncate string if overflowed - if (len >= SPI_OUT_UL_LOG_STR_BUF_SIZE) { - len = SPI_OUT_UL_LOG_STR_BUF_SIZE - 1; - ul_log_str_buf[len] = '\0'; + if (len >= SPI_OUT_LOG_STR_BUF_SIZE) { + len = SPI_OUT_LOG_STR_BUF_SIZE - 1; + str_buf[len] = '\0'; } - spi_out_ul_log_write(source, ul_log_str_buf, len, true); + spi_out_log_write(source, str_buf, len, true); return true; } @@ -754,6 +705,10 @@ static void spi_out_ll_log_deinit(void) // Context: LL task static void spi_out_ll_log_flush(void) { + if (!ll_log_inited) { + return; + } + // Flush task log and hci log buffer spi_out_log_cb_flush_trans(ll_task_log_cb); spi_out_log_cb_flush_trans(ll_hci_log_cb); @@ -942,7 +897,7 @@ int ble_log_spi_out_init(void) goto spi_device_add_failed; } - if (spi_out_ul_log_init() != 0) { + if (LOG_MODULE_INIT(ul)() != 0) { goto ul_log_init_failed; } @@ -1000,7 +955,7 @@ ts_sync_init_failed: spi_out_ll_log_deinit(); ll_log_init_failed: #endif // SPI_OUT_LL_ENABLED - spi_out_ul_log_deinit(); + LOG_MODULE_DEINIT(ul)(); ul_log_init_failed: spi_bus_remove_device(spi_handle); spi_handle = NULL; @@ -1017,6 +972,10 @@ void ble_log_spi_out_deinit(void) return; } + // Reset init flag + spi_out_inited = false; + spi_out_enabled = false; + #if SPI_OUT_FLUSH_TIMER_ENABLED esp_timer_stop(flush_timer); esp_timer_delete(flush_timer); @@ -1044,11 +1003,7 @@ void ble_log_spi_out_deinit(void) spi_out_ll_log_deinit(); #endif // SPI_OUT_LL_ENABLED - spi_out_ul_log_deinit(); - - // Reset init flag - spi_out_inited = false; - spi_out_enabled = false; + LOG_MODULE_DEINIT(ul)(); } #if SPI_OUT_TS_SYNC_ENABLED @@ -1156,19 +1111,19 @@ IRAM_ATTR void ble_log_spi_out_ll_log_ev_proc(void) int ble_log_spi_out_write(uint8_t source, const uint8_t *addr, uint16_t len) { - if (!ul_log_inited) { + if (!LOG_MODULE_INIT_FLAG(ul)) { return -1; } - xSemaphoreTake(ul_log_mutex, portMAX_DELAY); - spi_out_ul_log_write(source, addr, len, false); - xSemaphoreGive(ul_log_mutex); + xSemaphoreTake(LOG_MODULE_MUTEX(ul), portMAX_DELAY); + spi_out_log_write(source, addr, len, false); + xSemaphoreGive(LOG_MODULE_MUTEX(ul)); return 0; } int ble_log_spi_out_printf(uint8_t source, const char *format, ...) { - if (!ul_log_inited) { + if (!LOG_MODULE_INIT_FLAG(ul)) { return -1; } @@ -1183,9 +1138,9 @@ int ble_log_spi_out_printf(uint8_t source, const char *format, ...) va_list args_copy; va_copy(args_copy, args); - xSemaphoreTake(ul_log_mutex, portMAX_DELAY); - bool ret = spi_out_ul_log_printf(source, format, args_copy, 0); - xSemaphoreGive(ul_log_mutex); + xSemaphoreTake(LOG_MODULE_MUTEX(ul), portMAX_DELAY); + bool ret = spi_out_log_printf(source, format, args_copy, 0); + xSemaphoreGive(LOG_MODULE_MUTEX(ul)); va_end(args_copy); va_end(args); @@ -1194,7 +1149,7 @@ int ble_log_spi_out_printf(uint8_t source, const char *format, ...) int ble_log_spi_out_printf_enh(uint8_t source, uint8_t level, const char *tag, const char *format, ...) { - if (!ul_log_inited) { + if (!LOG_MODULE_INIT_FLAG(ul)) { return -1; } @@ -1210,15 +1165,15 @@ int ble_log_spi_out_printf_enh(uint8_t source, uint8_t level, const char *tag, c // Create log prefix in the format: "[level][tag] " bool ret = false; - xSemaphoreTake(ul_log_mutex, portMAX_DELAY); - int prefix_len = snprintf((char *)ul_log_str_buf, SPI_OUT_UL_LOG_STR_BUF_SIZE, + xSemaphoreTake(LOG_MODULE_MUTEX(ul), portMAX_DELAY); + int prefix_len = snprintf((char *)LOG_MODULE_STR_BUF(ul), SPI_OUT_LOG_STR_BUF_SIZE, "[%d][%s]", level, tag? tag: "NULL"); - if ((prefix_len < 0) || (prefix_len >= SPI_OUT_UL_LOG_STR_BUF_SIZE)) { + if ((prefix_len < 0) || (prefix_len >= SPI_OUT_LOG_STR_BUF_SIZE)) { goto exit; } - ret = spi_out_ul_log_printf(source, format, args_copy, prefix_len); + ret = spi_out_log_printf(source, format, args_copy, prefix_len); exit: - xSemaphoreGive(ul_log_mutex); + xSemaphoreGive(LOG_MODULE_MUTEX(ul)); va_end(args_copy); va_end(args); return ret? 0: -1; @@ -1226,18 +1181,22 @@ exit: int ble_log_spi_out_write_with_ts(uint8_t source, const uint8_t *addr, uint16_t len) { - if (!ul_log_inited) { + if (!LOG_MODULE_INIT_FLAG(ul)) { return -1; } - xSemaphoreTake(ul_log_mutex, portMAX_DELAY); - spi_out_ul_log_write(source, addr, len, true); - xSemaphoreGive(ul_log_mutex); + xSemaphoreTake(LOG_MODULE_MUTEX(ul), portMAX_DELAY); + spi_out_log_write(source, addr, len, true); + xSemaphoreGive(LOG_MODULE_MUTEX(ul)); return 0; } void ble_log_spi_out_dump_all(void) { + if (!spi_out_inited) { + return; + } + portMUX_TYPE spinlock = portMUX_INITIALIZER_UNLOCKED; portENTER_CRITICAL_SAFE(&spinlock); @@ -1258,10 +1217,10 @@ void ble_log_spi_out_dump_all(void) } #endif // SPI_OUT_LL_ENABLED - if (ul_log_inited) { + if (LOG_MODULE_INIT_FLAG(ul)) { // Dump upper layer log buffer esp_rom_printf("[UL_LOG_DUMP_START:\n"); - spi_out_log_cb_dump(ul_log_cb); + spi_out_log_cb_dump(LOG_MODULE_CB(ul)); esp_rom_printf("\n:UL_LOG_DUMP_END]\n\n"); } @@ -1278,6 +1237,10 @@ void ble_log_spi_out_dump_all(void) void ble_log_spi_out_enable(bool enable) { + if (!spi_out_inited) { + return; + } + spi_out_enabled = enable; if (!enable) { From b073f02a0576251af0f19f081b38738434025612 Mon Sep 17 00:00:00 2001 From: Zhou Xiao Date: Tue, 8 Jul 2025 13:15:10 +0800 Subject: [PATCH 05/14] feat(ble): support host & hci log module (cherry picked from commit dd4cbe5e001aa9c89d45ce6bd72822f80f220e89) Co-authored-by: Zhou Xiao --- components/bt/common/Kconfig.in | 16 ++ .../bt/common/ble_log/ble_log_spi_out.c | 252 ++++++++++-------- .../ble_log/include/ble_log/ble_log_spi_out.h | 23 +- .../bt/host/bluedroid/api/esp_bluedroid_hci.c | 2 +- .../common/include/common/bt_trace.h | 18 +- components/bt/host/bluedroid/hci/hci_hal_h4.c | 2 +- .../host/nimble/esp-hci/src/esp_nimble_hci.c | 4 +- 7 files changed, 188 insertions(+), 129 deletions(-) diff --git a/components/bt/common/Kconfig.in b/components/bt/common/Kconfig.in index e2052553d6..fa2824e3dc 100644 --- a/components/bt/common/Kconfig.in +++ b/components/bt/common/Kconfig.in @@ -27,6 +27,14 @@ config BT_BLE_LOG_SPI_OUT_HCI_ENABLED help Enable logging of HCI packets to the SPI bus when BLE SPI log output is enabled. +config BT_BLE_LOG_SPI_OUT_HCI_BUF_SIZE + int "SPI transaction buffer size for HCI logs" + depends on BT_BLE_LOG_SPI_OUT_HCI_ENABLED + default 1024 + help + SPI transaction buffer size for HCI logs. + There will be 2 SPI DMA buffers with the same size. + config BT_BLE_LOG_SPI_OUT_HOST_ENABLED bool "Enable Host log output to SPI" depends on BT_BLE_LOG_SPI_OUT_ENABLED @@ -35,6 +43,14 @@ config BT_BLE_LOG_SPI_OUT_HOST_ENABLED This configuration applies to the logs of both Bluedroid Host and NimBLE Host. When BLE SPI log output is enabled, this option allows host logs to be transmitted via SPI. +config BT_BLE_LOG_SPI_OUT_HOST_BUF_SIZE + int "SPI transaction buffer size for host logs" + depends on BT_BLE_LOG_SPI_OUT_HOST_ENABLED + default 1024 + help + SPI transaction buffer size for host logs. + There will be 2 SPI DMA buffers with the same size. + config BT_BLE_LOG_SPI_OUT_LL_ENABLED bool "Enable Controller log output to SPI" depends on BT_BLE_LOG_SPI_OUT_ENABLED diff --git a/components/bt/common/ble_log/ble_log_spi_out.c b/components/bt/common/ble_log/ble_log_spi_out.c index b7da6ec434..5731f851f0 100644 --- a/components/bt/common/ble_log/ble_log_spi_out.c +++ b/components/bt/common/ble_log/ble_log_spi_out.c @@ -26,6 +26,10 @@ #define SPI_OUT_FLUSH_TIMEOUT_US (CONFIG_BT_BLE_LOG_SPI_OUT_FLUSH_TIMEOUT * 1000) #define SPI_OUT_LE_AUDIO_ENABLED CONFIG_BT_BLE_LOG_SPI_OUT_LE_AUDIO_ENABLED #define SPI_OUT_LE_AUDIO_BUF_SIZE CONFIG_BT_BLE_LOG_SPI_OUT_LE_AUDIO_BUF_SIZE +#define SPI_OUT_HOST_ENABLED CONFIG_BT_BLE_LOG_SPI_OUT_HOST_ENABLED +#define SPI_OUT_HOST_BUF_SIZE CONFIG_BT_BLE_LOG_SPI_OUT_HOST_BUF_SIZE +#define SPI_OUT_HCI_ENABLED CONFIG_BT_BLE_LOG_SPI_OUT_HCI_ENABLED +#define SPI_OUT_HCI_BUF_SIZE CONFIG_BT_BLE_LOG_SPI_OUT_HCI_BUF_SIZE // Private defines #define BLE_LOG_TAG "BLE_LOG" @@ -60,9 +64,23 @@ #define SPI_OUT_LE_AUDIO_QUEUE_SIZE (0) #endif // SPI_OUT_LE_AUDIO_ENABLED +#if SPI_OUT_HOST_ENABLED +#define SPI_OUT_HOST_QUEUE_SIZE (SPI_OUT_PING_PONG_BUF_CNT) +#else +#define SPI_OUT_HOST_QUEUE_SIZE (0) +#endif // SPI_OUT_HOST_ENABLED + +#if SPI_OUT_HCI_ENABLED +#define SPI_OUT_HCI_QUEUE_SIZE (SPI_OUT_PING_PONG_BUF_CNT) +#else +#define SPI_OUT_HCI_QUEUE_SIZE (0) +#endif // SPI_OUT_HCI_ENABLED + #define SPI_OUT_SPI_MASTER_QUEUE_SIZE (SPI_OUT_UL_QUEUE_SIZE +\ SPI_OUT_LL_QUEUE_SIZE +\ - SPI_OUT_LE_AUDIO_QUEUE_SIZE) + SPI_OUT_LE_AUDIO_QUEUE_SIZE +\ + SPI_OUT_HOST_QUEUE_SIZE +\ + SPI_OUT_HCI_QUEUE_SIZE) // Private typedefs typedef struct { @@ -114,6 +132,8 @@ enum { LOG_CB_TYPE_LL_ISR, LOG_CB_TYPE_LL_HCI, LOG_CB_TYPE_LE_AUDIO, + LOG_CB_TYPE_HOST, + LOG_CB_TYPE_HCI, }; enum { @@ -123,6 +143,7 @@ enum { LL_LOG_FLAG_ISR, LL_LOG_FLAG_HCI, LL_LOG_FLAG_RAW, + LL_LOG_FLAG_HCI_UPSTREAM, }; enum { @@ -180,10 +201,9 @@ static void spi_out_log_cb_write_loss(spi_out_log_cb_t *log_cb); static void spi_out_log_cb_dump(spi_out_log_cb_t *log_cb); static void spi_out_log_flush(void); -static inline spi_out_log_cb_t *spi_out_get_log_cb(uint8_t source); -static inline uint8_t *spi_out_get_str_buf(uint8_t source); -static void spi_out_log_write(uint8_t source, const uint8_t *addr, uint16_t len, bool with_ts); -static bool spi_out_log_printf(uint8_t source, const char *format, va_list args, int offset); +static void spi_out_write_hex(spi_out_log_cb_t *log_cb, uint8_t source, + const uint8_t *addr, uint16_t len, bool with_ts); +static int spi_out_write_str(uint8_t *str_buf, const char *format, va_list args, int offset); #if SPI_OUT_LL_ENABLED static int spi_out_ll_log_init(void); @@ -314,6 +334,14 @@ DECLARE_LOG_MODULE(ul, LOG_CB_TYPE_UL, SPI_OUT_UL_TASK_BUF_SIZE, 1, 1) DECLARE_LOG_MODULE(le_audio, LOG_CB_TYPE_LE_AUDIO, SPI_OUT_LE_AUDIO_BUF_SIZE, 0, 0) #endif // SPI_OUT_LE_AUDIO_ENABLED +#if SPI_OUT_HOST_ENABLED +DECLARE_LOG_MODULE(host, LOG_CB_TYPE_HOST, SPI_OUT_HOST_BUF_SIZE, 0, 1) +#endif // SPI_OUT_HOST_ENABLED + +#if SPI_OUT_HCI_ENABLED +DECLARE_LOG_MODULE(hci, LOG_CB_TYPE_HCI, SPI_OUT_HCI_BUF_SIZE, 0, 0) +#endif // SPI_OUT_HCI_ENABLED + // Private functions static int spi_out_init_trans(spi_out_trans_cb_t **trans_cb, uint16_t buf_size) { @@ -581,6 +609,14 @@ static void spi_out_log_flush(void) #if SPI_OUT_LE_AUDIO_ENABLED LOG_MODULE_FLUSH(le_audio)(); #endif // SPI_OUT_LE_AUDIO_ENABLED + +#if SPI_OUT_HOST_ENABLED + LOG_MODULE_FLUSH(host)(); +#endif // SPI_OUT_HOST_ENABLED + +#if SPI_OUT_HCI_ENABLED + LOG_MODULE_FLUSH(hci)(); +#endif // SPI_OUT_HCI_ENABLED } #if SPI_OUT_FLUSH_TIMER_ENABLED @@ -592,31 +628,11 @@ static void esp_timer_cb_log_flush(void) } #endif // SPI_OUT_FLUSH_TIMER_ENABLED -static inline spi_out_log_cb_t *spi_out_get_log_cb(uint8_t source) -{ - spi_out_log_cb_t *log_cb; - switch (source) { - default: - log_cb = LOG_MODULE_CB(ul); - } - return log_cb; -} - -static inline uint8_t *spi_out_get_str_buf(uint8_t source) -{ - uint8_t *str_buf; - switch (source) { - default: - str_buf = LOG_MODULE_STR_BUF(ul); - } - return str_buf; -} - -static void spi_out_log_write(uint8_t source, const uint8_t *addr, uint16_t len, bool with_ts) +static void spi_out_write_hex(spi_out_log_cb_t *log_cb, uint8_t source, + const uint8_t *addr, uint16_t len, bool with_ts) { uint16_t total_len = with_ts? (len + sizeof(uint32_t)): len; bool need_append; - spi_out_log_cb_t *log_cb = spi_out_get_log_cb(source); if (spi_out_log_cb_check_trans(log_cb, total_len, &need_append)) { if (with_ts) { uint32_t os_ts = pdTICKS_TO_MS(xTaskGetTickCount()); @@ -632,24 +648,19 @@ static void spi_out_log_write(uint8_t source, const uint8_t *addr, uint16_t len, spi_out_log_cb_write_loss(log_cb); } -static bool spi_out_log_printf(uint8_t source, const char *format, va_list args, int offset) +static int spi_out_write_str(uint8_t *str_buf, const char *format, va_list args, int offset) { - uint8_t *str_buf = spi_out_get_str_buf(source); - int len = vsnprintf((char *)(str_buf + offset), - SPI_OUT_LOG_STR_BUF_SIZE - offset, format, args); + int len = vsnprintf((char *)(str_buf + offset), SPI_OUT_LOG_STR_BUF_SIZE - offset, format, args); if (len < 0) { - return false; + return 0; } len += offset; - // Truncate string if overflowed if (len >= SPI_OUT_LOG_STR_BUF_SIZE) { len = SPI_OUT_LOG_STR_BUF_SIZE - 1; str_buf[len] = '\0'; } - - spi_out_log_write(source, str_buf, len, true); - return true; + return len; } #if SPI_OUT_LL_ENABLED @@ -919,6 +930,18 @@ int ble_log_spi_out_init(void) } #endif // SPI_OUT_LE_AUDIO_ENABLED +#if SPI_OUT_HOST_ENABLED + if (LOG_MODULE_INIT(host)() != 0) { + goto host_init_failed; + } +#endif // SPI_OUT_HOST_ENABLED + +#if SPI_OUT_HCI_ENABLED + if (LOG_MODULE_INIT(hci)() != 0) { + goto hci_init_failed; + } +#endif // SPI_OUT_HCI_ENABLED + #if SPI_OUT_FLUSH_TIMER_ENABLED esp_timer_create_args_t timer_args = { .callback = (esp_timer_cb_t)esp_timer_cb_log_flush, @@ -943,6 +966,14 @@ int ble_log_spi_out_init(void) #if SPI_OUT_FLUSH_TIMER_ENABLED timer_init_failed: #endif // SPI_OUT_FLUSH_TIMER_ENABLED +#if SPI_OUT_HCI_ENABLED + LOG_MODULE_DEINIT(hci)(); +hci_init_failed: +#endif // SPI_OUT_HCI_ENABLED +#if SPI_OUT_HOST_ENABLED + LOG_MODULE_DEINIT(host)(); +host_init_failed: +#endif // SPI_OUT_HOST_ENABLED #if SPI_OUT_LE_AUDIO_ENABLED LOG_MODULE_DEINIT(le_audio)(); le_audio_init_failed: @@ -995,6 +1026,14 @@ void ble_log_spi_out_deinit(void) spi_out_ts_sync_deinit(); #endif // SPI_OUT_TS_SYNC_ENABLED +#if SPI_OUT_HCI_ENABLED + LOG_MODULE_DEINIT(hci)(); +#endif // SPI_OUT_HCI_ENABLED + +#if SPI_OUT_HOST_ENABLED + LOG_MODULE_DEINIT(host)(); +#endif // SPI_OUT_HOST_ENABLED + #if SPI_OUT_LE_AUDIO_ENABLED LOG_MODULE_DEINIT(le_audio)(); #endif // SPI_OUT_LE_AUDIO_ENABLED @@ -1056,6 +1095,9 @@ IRAM_ATTR void ble_log_spi_out_ll_write(uint32_t len, const uint8_t *addr, uint3 } else if (flag & BIT(LL_LOG_FLAG_HCI)) { log_cb = ll_hci_log_cb; source = BLE_LOG_SPI_OUT_SOURCE_LL_HCI; + } else if (flag & BIT(LL_LOG_FLAG_HCI_UPSTREAM)) { + log_cb = ll_hci_log_cb; + source = BLE_LOG_SPI_OUT_SOURCE_HCI_UPSTREAM; } else { log_cb = ll_task_log_cb; source = BLE_LOG_SPI_OUT_SOURCE_ESP; @@ -1116,77 +1158,7 @@ int ble_log_spi_out_write(uint8_t source, const uint8_t *addr, uint16_t len) } xSemaphoreTake(LOG_MODULE_MUTEX(ul), portMAX_DELAY); - spi_out_log_write(source, addr, len, false); - xSemaphoreGive(LOG_MODULE_MUTEX(ul)); - return 0; -} - -int ble_log_spi_out_printf(uint8_t source, const char *format, ...) -{ - if (!LOG_MODULE_INIT_FLAG(ul)) { - return -1; - } - - if (!format) { - return -1; - } - - // Get arguments - va_list args; - va_start(args, format); - - va_list args_copy; - va_copy(args_copy, args); - - xSemaphoreTake(LOG_MODULE_MUTEX(ul), portMAX_DELAY); - bool ret = spi_out_log_printf(source, format, args_copy, 0); - xSemaphoreGive(LOG_MODULE_MUTEX(ul)); - - va_end(args_copy); - va_end(args); - return ret? 0: -1; -} - -int ble_log_spi_out_printf_enh(uint8_t source, uint8_t level, const char *tag, const char *format, ...) -{ - if (!LOG_MODULE_INIT_FLAG(ul)) { - return -1; - } - - if (!tag || !format) { - return -1; - } - - va_list args; - va_start(args, format); - - va_list args_copy; - va_copy(args_copy, args); - - // Create log prefix in the format: "[level][tag] " - bool ret = false; - xSemaphoreTake(LOG_MODULE_MUTEX(ul), portMAX_DELAY); - int prefix_len = snprintf((char *)LOG_MODULE_STR_BUF(ul), SPI_OUT_LOG_STR_BUF_SIZE, - "[%d][%s]", level, tag? tag: "NULL"); - if ((prefix_len < 0) || (prefix_len >= SPI_OUT_LOG_STR_BUF_SIZE)) { - goto exit; - } - ret = spi_out_log_printf(source, format, args_copy, prefix_len); -exit: - xSemaphoreGive(LOG_MODULE_MUTEX(ul)); - va_end(args_copy); - va_end(args); - return ret? 0: -1; -} - -int ble_log_spi_out_write_with_ts(uint8_t source, const uint8_t *addr, uint16_t len) -{ - if (!LOG_MODULE_INIT_FLAG(ul)) { - return -1; - } - - xSemaphoreTake(LOG_MODULE_MUTEX(ul), portMAX_DELAY); - spi_out_log_write(source, addr, len, true); + spi_out_write_hex(LOG_MODULE_CB(ul), source, addr, len, false); xSemaphoreGive(LOG_MODULE_MUTEX(ul)); return 0; } @@ -1232,6 +1204,23 @@ void ble_log_spi_out_dump_all(void) } #endif // SPI_OUT_LE_AUDIO_ENABLED + +#if SPI_OUT_HOST_ENABLED + if (LOG_MODULE_INIT_FLAG(host)) { + esp_rom_printf("[HOST_LOG_DUMP_START:\n"); + spi_out_log_cb_dump(LOG_MODULE_CB(host)); + esp_rom_printf("\n:HOST_LOG_DUMP_END]\n\n"); + } +#endif // SPI_OUT_HOST_ENABLED + +#if SPI_OUT_HCI_ENABLED + if (LOG_MODULE_INIT_FLAG(hci)) { + esp_rom_printf("[HCI_LOG_DUMP_START:\n"); + spi_out_log_cb_dump(LOG_MODULE_CB(hci)); + esp_rom_printf("\n:HCI_LOG_DUMP_END]\n\n"); + } +#endif // SPI_OUT_HCI_ENABLED + portEXIT_CRITICAL_SAFE(&spinlock); } @@ -1278,4 +1267,53 @@ IRAM_ATTR void ble_log_spi_out_le_audio_write(const uint8_t *addr, uint16_t len) return; } #endif // CONFIG_BT_BLE_LOG_SPI_OUT_LE_AUDIO_ENABLED + +#if SPI_OUT_HOST_ENABLED +int ble_log_spi_out_host_write(uint8_t source, const char *prefix, const char *format, ...) +{ + if (!LOG_MODULE_INIT_FLAG(host) || !prefix || !format) { + return -1; + } + + // Copy prefix to string buffer + int prefix_len = strlen(prefix); + if (prefix_len >= SPI_OUT_LOG_STR_BUF_SIZE) { + return -1; + } + memcpy(LOG_MODULE_STR_BUF(host), prefix, prefix_len); + + // Write string buffer + va_list args; + va_start(args, format); + int total_len = spi_out_write_str(LOG_MODULE_STR_BUF(host), format, args, prefix_len); + va_end(args); + if (total_len == 0) { + return -1; + } + + // Write log control block buffer + spi_out_write_hex(LOG_MODULE_CB(host), source, + LOG_MODULE_STR_BUF(host), (uint16_t)total_len, true); + return 0; +} +#endif // SPI_OUT_HOST_ENABLED + +#if SPI_OUT_HCI_ENABLED +int ble_log_spi_out_hci_write(uint8_t source, const uint8_t *addr, uint16_t len) +{ + if (!LOG_MODULE_INIT_FLAG(hci)) { + return -1; + } + + if (source == BLE_LOG_SPI_OUT_SOURCE_HCI_UPSTREAM) { +#if SPI_OUT_LL_ENABLED + ble_log_spi_out_ll_write(len, addr, 0, NULL, BIT(LL_LOG_FLAG_HCI_UPSTREAM)); +#endif // SPI_OUT_LL_ENABLED + } + if (source == BLE_LOG_SPI_OUT_SOURCE_HCI_DOWNSTREAM) { + spi_out_write_hex(LOG_MODULE_CB(hci), source, addr, len, true); + } + return 0; +} +#endif // SPI_OUT_HCI_ENABLED #endif // CONFIG_BT_BLE_LOG_SPI_OUT_ENABLED diff --git a/components/bt/common/ble_log/include/ble_log/ble_log_spi_out.h b/components/bt/common/ble_log/include/ble_log/ble_log_spi_out.h index 3a4f8d9020..30462fc72a 100644 --- a/components/bt/common/ble_log/include/ble_log/ble_log_spi_out.h +++ b/components/bt/common/ble_log/include/ble_log/ble_log_spi_out.h @@ -33,15 +33,15 @@ enum { BLE_LOG_SPI_OUT_SOURCE_LOSS, }; -enum { - BLE_LOG_SPI_OUT_LEVEL_NONE = 0, - BLE_LOG_SPI_OUT_LEVEL_ERROR, - BLE_LOG_SPI_OUT_LEVEL_WARN, - BLE_LOG_SPI_OUT_LEVEL_INFO, - BLE_LOG_SPI_OUT_LEVEL_DEBUG, - BLE_LOG_SPI_OUT_LEVEL_VERBOSE, - BLE_LOG_SPI_OUT_LEVEL_MAX, -}; +#define BLE_LOG_SPI_OUT_LEVEL_NONE 0 +#define BLE_LOG_SPI_OUT_LEVEL_ERROR 1 +#define BLE_LOG_SPI_OUT_LEVEL_WARN 2 +#define BLE_LOG_SPI_OUT_LEVEL_INFO 3 +#define BLE_LOG_SPI_OUT_LEVEL_DEBUG 4 +#define BLE_LOG_SPI_OUT_LEVEL_VERBOSE 5 +#define BLE_LOG_SPI_OUT_STR(x) #x +#define BLE_LOG_SPI_OUT_XSTR(x) BLE_LOG_SPI_OUT_STR(x) +#define BLE_LOG_SPI_OUT_BUILD_PREFIX(LEVEL, TAG) "[" BLE_LOG_SPI_OUT_XSTR(LEVEL) "][" TAG "]" // Public functions int ble_log_spi_out_init(void); @@ -53,12 +53,11 @@ void ble_log_spi_out_ll_write(uint32_t len, const uint8_t *addr, uint32_t len_ap void ble_log_spi_out_ll_log_ev_proc(void); void ble_log_spi_out_ts_sync_start(void); void ble_log_spi_out_ts_sync_stop(void); -int ble_log_spi_out_printf(uint8_t source, const char *format, ...); -int ble_log_spi_out_printf_enh(uint8_t source, uint8_t level, const char *tag, const char *format, ...); -int ble_log_spi_out_write_with_ts(uint8_t source, const uint8_t *addr, uint16_t len); void ble_log_spi_out_dump_all(void); void ble_log_spi_out_enable(bool enable); void ble_log_spi_out_flush(void); void ble_log_spi_out_le_audio_write(const uint8_t *addr, uint16_t len); +int ble_log_spi_out_host_write(uint8_t source, const char *prefix, const char *format, ...); +int ble_log_spi_out_hci_write(uint8_t source, const uint8_t *addr, uint16_t len); #endif // __BT_SPI_OUT_H__ diff --git a/components/bt/host/bluedroid/api/esp_bluedroid_hci.c b/components/bt/host/bluedroid/api/esp_bluedroid_hci.c index 0e6baf1118..312639b6dd 100644 --- a/components/bt/host/bluedroid/api/esp_bluedroid_hci.c +++ b/components/bt/host/bluedroid/api/esp_bluedroid_hci.c @@ -68,7 +68,7 @@ void hci_host_send_packet(uint8_t *data, uint16_t len) bt_hci_log_record_hci_data(data[0], &data[1], len - 1); #endif #if (BT_BLE_LOG_SPI_OUT_HCI_ENABLED && !SOC_ESP_NIMBLE_CONTROLLER) - ble_log_spi_out_write_with_ts(BLE_LOG_SPI_OUT_SOURCE_HCI_DOWNSTREAM, data, len); + ble_log_spi_out_hci_write(BLE_LOG_SPI_OUT_SOURCE_HCI_DOWNSTREAM, data, len); #endif // (BT_BLE_LOG_SPI_OUT_HCI_ENABLED && !SOC_ESP_NIMBLE_CONTROLLER) #if (BT_CONTROLLER_INCLUDED == TRUE) esp_vhci_host_send_packet(data, len); diff --git a/components/bt/host/bluedroid/common/include/common/bt_trace.h b/components/bt/host/bluedroid/common/include/common/bt_trace.h index 502d654373..2ffaa8ea86 100644 --- a/components/bt/host/bluedroid/common/include/common/bt_trace.h +++ b/components/bt/host/bluedroid/common/include/common/bt_trace.h @@ -231,12 +231,14 @@ static inline void trc_dump_buffer(const char *prefix, uint8_t *data, uint16_t l } #define BTM_TRACE_API(fmt, args...) { \ - ble_log_spi_out_printf_enh(BLE_LOG_SPI_OUT_SOURCE_BLUEDROID, BLE_LOG_SPI_OUT_LEVEL_INFO, "BT_BTM", fmt, ## args); \ + ble_log_spi_out_host_write(BLE_LOG_SPI_OUT_SOURCE_BLUEDROID, \ + BLE_LOG_SPI_OUT_BUILD_PREFIX(BLE_LOG_SPI_OUT_LEVEL_INFO, "BT_BTM"), fmt, ## args); \ if (btm_cb.trace_level >= BT_TRACE_LEVEL_API && BT_LOG_LEVEL_CHECK(BTM, API)) BT_PRINT_I("BT_BTM", fmt, ## args); \ } #define BTM_TRACE_EVENT(fmt, args...) { \ - ble_log_spi_out_printf_enh(BLE_LOG_SPI_OUT_SOURCE_BLUEDROID, BLE_LOG_SPI_OUT_LEVEL_DEBUG, "BT_BTM", fmt, ## args); \ + ble_log_spi_out_host_write(BLE_LOG_SPI_OUT_SOURCE_BLUEDROID, \ + BLE_LOG_SPI_OUT_BUILD_PREFIX(BLE_LOG_SPI_OUT_LEVEL_DEBUG, "BT_BTM"), fmt, ## args); \ if (btm_cb.trace_level >= BT_TRACE_LEVEL_EVENT && BT_LOG_LEVEL_CHECK(BTM, EVENT)) BT_PRINT_D("BT_BTM", fmt, ## args); \ } @@ -267,7 +269,8 @@ static inline void trc_dump_buffer(const char *prefix, uint8_t *data, uint16_t l } #define L2CAP_TRACE_API(fmt, args...) { \ - ble_log_spi_out_printf_enh(BLE_LOG_SPI_OUT_SOURCE_BLUEDROID, BLE_LOG_SPI_OUT_LEVEL_INFO, "BT_L2CAP", fmt, ## args); \ + ble_log_spi_out_host_write(BLE_LOG_SPI_OUT_SOURCE_BLUEDROID, \ + BLE_LOG_SPI_OUT_BUILD_PREFIX(BLE_LOG_SPI_OUT_LEVEL_INFO, "BT_L2CAP"), fmt, ## args); \ if (l2cb.l2cap_trace_level >= BT_TRACE_LEVEL_API && BT_LOG_LEVEL_CHECK(L2CAP, API)) BT_PRINT_I("BT_L2CAP", fmt, ## args); \ } @@ -318,7 +321,8 @@ static inline void trc_dump_buffer(const char *prefix, uint8_t *data, uint16_t l } #define GAP_TRACE_API(fmt, args...) { \ - ble_log_spi_out_printf_enh(BLE_LOG_SPI_OUT_SOURCE_BLUEDROID, BLE_LOG_SPI_OUT_LEVEL_INFO, "BT_GAP", fmt, ## args); \ + ble_log_spi_out_host_write(BLE_LOG_SPI_OUT_SOURCE_BLUEDROID, \ + BLE_LOG_SPI_OUT_BUILD_PREFIX(BLE_LOG_SPI_OUT_LEVEL_INFO, "BT_GAP"), fmt, ## args); \ if (gap_cb.trace_level >= BT_TRACE_LEVEL_API && BT_LOG_LEVEL_CHECK(GAP, API)) BT_PRINT_I("BT_GAP", fmt, ## args); \ } @@ -441,7 +445,8 @@ static inline void trc_dump_buffer(const char *prefix, uint8_t *data, uint16_t l } #define GATT_TRACE_API(fmt, args...) { \ - ble_log_spi_out_printf_enh(BLE_LOG_SPI_OUT_SOURCE_BLUEDROID, BLE_LOG_SPI_OUT_LEVEL_INFO, "BT_GATT", fmt, ## args); \ + ble_log_spi_out_host_write(BLE_LOG_SPI_OUT_SOURCE_BLUEDROID, \ + BLE_LOG_SPI_OUT_BUILD_PREFIX(BLE_LOG_SPI_OUT_LEVEL_INFO, "BT_GATT"), fmt, ## args); \ if (gatt_cb.trace_level >= BT_TRACE_LEVEL_API && BT_LOG_LEVEL_CHECK(GATT, API)) BT_PRINT_I("BT_GATT", fmt, ## args); \ } @@ -476,7 +481,8 @@ static inline void trc_dump_buffer(const char *prefix, uint8_t *data, uint16_t l } #define SMP_TRACE_API(fmt, args...) { \ - ble_log_spi_out_printf_enh(BLE_LOG_SPI_OUT_SOURCE_BLUEDROID, BLE_LOG_SPI_OUT_LEVEL_INFO, "BT_SMP", fmt, ## args); \ + ble_log_spi_out_host_write(BLE_LOG_SPI_OUT_SOURCE_BLUEDROID, \ + BLE_LOG_SPI_OUT_BUILD_PREFIX(BLE_LOG_SPI_OUT_LEVEL_INFO, "BT_SMP"), fmt, ## args); \ if (smp_cb.trace_level >= BT_TRACE_LEVEL_API && BT_LOG_LEVEL_CHECK(SMP, API)) BT_PRINT_I("BT_SMP", fmt, ## args); \ } diff --git a/components/bt/host/bluedroid/hci/hci_hal_h4.c b/components/bt/host/bluedroid/hci/hci_hal_h4.c index 1dcdf67d32..2b61ee2e60 100644 --- a/components/bt/host/bluedroid/hci/hci_hal_h4.c +++ b/components/bt/host/bluedroid/hci/hci_hal_h4.c @@ -601,7 +601,7 @@ void bt_record_hci_data(uint8_t *data, uint16_t len) static int host_recv_pkt_cb(uint8_t *data, uint16_t len) { #if (BT_BLE_LOG_SPI_OUT_HCI_ENABLED && !SOC_ESP_NIMBLE_CONTROLLER) - ble_log_spi_out_write_with_ts(BLE_LOG_SPI_OUT_SOURCE_HCI_UPSTREAM, data, len); + ble_log_spi_out_hci_write(BLE_LOG_SPI_OUT_SOURCE_HCI_UPSTREAM, data, len); #endif // (BT_BLE_LOG_SPI_OUT_HCI_ENABLED && !SOC_ESP_NIMBLE_CONTROLLER) //Target has packet to host, malloc new buffer for packet BT_HDR *pkt = NULL; diff --git a/components/bt/host/nimble/esp-hci/src/esp_nimble_hci.c b/components/bt/host/nimble/esp-hci/src/esp_nimble_hci.c index b556553947..6a5dacd1a7 100644 --- a/components/bt/host/nimble/esp-hci/src/esp_nimble_hci.c +++ b/components/bt/host/nimble/esp-hci/src/esp_nimble_hci.c @@ -73,7 +73,7 @@ void esp_vhci_host_send_packet_wrapper(uint8_t *data, uint16_t len) bt_hci_log_record_hci_data(data[0], &data[1], len - 1); #endif #if (CONFIG_BT_BLE_LOG_SPI_OUT_HCI_ENABLED && !SOC_ESP_NIMBLE_CONTROLLER) - ble_log_spi_out_write_with_ts(BLE_LOG_SPI_OUT_SOURCE_HCI_DOWNSTREAM, data, len); + ble_log_spi_out_hci_write(BLE_LOG_SPI_OUT_SOURCE_HCI_DOWNSTREAM, data, len); #endif // (CONFIG_BT_BLE_LOG_SPI_OUT_HCI_ENABLED && !SOC_ESP_NIMBLE_CONTROLLER) esp_vhci_host_send_packet(data, len); } @@ -232,7 +232,7 @@ static int dummy_host_rcv_pkt(uint8_t *data, uint16_t len) static int host_rcv_pkt(uint8_t *data, uint16_t len) { #if (CONFIG_BT_BLE_LOG_SPI_OUT_HCI_ENABLED && !SOC_ESP_NIMBLE_CONTROLLER) - ble_log_spi_out_write_with_ts(BLE_LOG_SPI_OUT_SOURCE_HCI_UPSTREAM, data, len); + ble_log_spi_out_hci_write(BLE_LOG_SPI_OUT_SOURCE_HCI_UPSTREAM, data, len); #endif // (CONFIG_BT_BLE_LOG_SPI_OUT_HCI_ENABLED && !SOC_ESP_NIMBLE_CONTROLLER) bt_record_hci_data(data, len); From 2351e02b21824ce40b2ef5218c4c6319c7848228 Mon Sep 17 00:00:00 2001 From: Zhou Xiao Date: Tue, 8 Jul 2025 13:15:12 +0800 Subject: [PATCH 06/14] feat(ble): support ble mesh log module (cherry picked from commit 066e1d3f1b155e14942c7bfab36147c7b5b60d93) Co-authored-by: Zhou Xiao --- components/bt/common/Kconfig.in | 15 ++++ .../bt/common/ble_log/ble_log_spi_out.c | 72 ++++++++++++++++++- .../ble_log/include/ble_log/ble_log_spi_out.h | 2 + 3 files changed, 88 insertions(+), 1 deletion(-) diff --git a/components/bt/common/Kconfig.in b/components/bt/common/Kconfig.in index fa2824e3dc..f6402de87e 100644 --- a/components/bt/common/Kconfig.in +++ b/components/bt/common/Kconfig.in @@ -154,3 +154,18 @@ config BT_BLE_LOG_SPI_OUT_LE_AUDIO_BUF_SIZE help SPI transaction buffer size for LE Audio logs. There will be 2 SPI DMA buffers with the same size. + +config BT_BLE_LOG_SPI_OUT_MESH_ENABLED + bool "Enable BLE mesh log output to SPI" + depends on BT_BLE_LOG_SPI_OUT_ENABLED + default n + help + Enable BLE mesh log output to SPI + +config BT_BLE_LOG_SPI_OUT_MESH_BUF_SIZE + int "SPI transaction buffer size for BLE mesh logs" + depends on BT_BLE_LOG_SPI_OUT_MESH_ENABLED + default 1024 + help + SPI transaction buffer size for BLE mesh logs. + There will be 2 SPI DMA buffers with the same size. diff --git a/components/bt/common/ble_log/ble_log_spi_out.c b/components/bt/common/ble_log/ble_log_spi_out.c index 5731f851f0..2b5a5f95ea 100644 --- a/components/bt/common/ble_log/ble_log_spi_out.c +++ b/components/bt/common/ble_log/ble_log_spi_out.c @@ -30,6 +30,8 @@ #define SPI_OUT_HOST_BUF_SIZE CONFIG_BT_BLE_LOG_SPI_OUT_HOST_BUF_SIZE #define SPI_OUT_HCI_ENABLED CONFIG_BT_BLE_LOG_SPI_OUT_HCI_ENABLED #define SPI_OUT_HCI_BUF_SIZE CONFIG_BT_BLE_LOG_SPI_OUT_HCI_BUF_SIZE +#define SPI_OUT_MESH_ENABLED CONFIG_BT_BLE_LOG_SPI_OUT_MESH_ENABLED +#define SPI_OUT_MESH_BUF_SIZE CONFIG_BT_BLE_LOG_SPI_OUT_MESH_BUF_SIZE // Private defines #define BLE_LOG_TAG "BLE_LOG" @@ -76,11 +78,18 @@ #define SPI_OUT_HCI_QUEUE_SIZE (0) #endif // SPI_OUT_HCI_ENABLED +#if SPI_OUT_MESH_ENABLED +#define SPI_OUT_MESH_QUEUE_SIZE (SPI_OUT_PING_PONG_BUF_CNT) +#else +#define SPI_OUT_MESH_QUEUE_SIZE (0) +#endif // SPI_OUT_MESH_ENABLED + #define SPI_OUT_SPI_MASTER_QUEUE_SIZE (SPI_OUT_UL_QUEUE_SIZE +\ SPI_OUT_LL_QUEUE_SIZE +\ SPI_OUT_LE_AUDIO_QUEUE_SIZE +\ SPI_OUT_HOST_QUEUE_SIZE +\ - SPI_OUT_HCI_QUEUE_SIZE) + SPI_OUT_HCI_QUEUE_SIZE +\ + SPI_OUT_MESH_QUEUE_SIZE) // Private typedefs typedef struct { @@ -134,6 +143,7 @@ enum { LOG_CB_TYPE_LE_AUDIO, LOG_CB_TYPE_HOST, LOG_CB_TYPE_HCI, + LOG_CB_TYPE_MESH, }; enum { @@ -342,6 +352,10 @@ DECLARE_LOG_MODULE(host, LOG_CB_TYPE_HOST, SPI_OUT_HOST_BUF_SIZE, 0, 1) DECLARE_LOG_MODULE(hci, LOG_CB_TYPE_HCI, SPI_OUT_HCI_BUF_SIZE, 0, 0) #endif // SPI_OUT_HCI_ENABLED +#if SPI_OUT_MESH_ENABLED +DECLARE_LOG_MODULE(mesh, LOG_CB_TYPE_MESH, SPI_OUT_MESH_BUF_SIZE, 0, 1) +#endif // SPI_OUT_MESH_ENABLED + // Private functions static int spi_out_init_trans(spi_out_trans_cb_t **trans_cb, uint16_t buf_size) { @@ -617,6 +631,10 @@ static void spi_out_log_flush(void) #if SPI_OUT_HCI_ENABLED LOG_MODULE_FLUSH(hci)(); #endif // SPI_OUT_HCI_ENABLED + +#if SPI_OUT_MESH_ENABLED + LOG_MODULE_FLUSH(mesh)(); +#endif // SPI_OUT_MESH_ENABLED } #if SPI_OUT_FLUSH_TIMER_ENABLED @@ -942,6 +960,12 @@ int ble_log_spi_out_init(void) } #endif // SPI_OUT_HCI_ENABLED +#if SPI_OUT_MESH_ENABLED + if (LOG_MODULE_INIT(mesh)() != 0) { + goto mesh_init_failed; + } +#endif // SPI_OUT_MESH_ENABLED + #if SPI_OUT_FLUSH_TIMER_ENABLED esp_timer_create_args_t timer_args = { .callback = (esp_timer_cb_t)esp_timer_cb_log_flush, @@ -966,6 +990,10 @@ int ble_log_spi_out_init(void) #if SPI_OUT_FLUSH_TIMER_ENABLED timer_init_failed: #endif // SPI_OUT_FLUSH_TIMER_ENABLED +#if SPI_OUT_MESH_ENABLED + LOG_MODULE_DEINIT(mesh)(); +mesh_init_failed: +#endif // SPI_OUT_MESH_ENABLED #if SPI_OUT_HCI_ENABLED LOG_MODULE_DEINIT(hci)(); hci_init_failed: @@ -1026,6 +1054,10 @@ void ble_log_spi_out_deinit(void) spi_out_ts_sync_deinit(); #endif // SPI_OUT_TS_SYNC_ENABLED +#if SPI_OUT_MESH_ENABLED + LOG_MODULE_DEINIT(mesh)(); +#endif // SPI_OUT_MESH_ENABLED + #if SPI_OUT_HCI_ENABLED LOG_MODULE_DEINIT(hci)(); #endif // SPI_OUT_HCI_ENABLED @@ -1221,6 +1253,14 @@ void ble_log_spi_out_dump_all(void) } #endif // SPI_OUT_HCI_ENABLED +#if SPI_OUT_MESH_ENABLED + if (LOG_MODULE_INIT_FLAG(mesh)) { + esp_rom_printf("[MESH_LOG_DUMP_START:\n"); + spi_out_log_cb_dump(LOG_MODULE_CB(mesh)); + esp_rom_printf("\n:MESH_LOG_DUMP_END]\n\n"); + } +#endif // SPI_OUT_MESH_ENABLED + portEXIT_CRITICAL_SAFE(&spinlock); } @@ -1316,4 +1356,34 @@ int ble_log_spi_out_hci_write(uint8_t source, const uint8_t *addr, uint16_t len) return 0; } #endif // SPI_OUT_HCI_ENABLED + +#if SPI_OUT_MESH_ENABLED +int ble_log_spi_out_mesh_write(const char *prefix, const char *format, ...) +{ + if (!LOG_MODULE_INIT_FLAG(mesh) || !prefix || !format) { + return -1; + } + + // Copy prefix to string buffer + int prefix_len = strlen(prefix); + if (prefix_len >= SPI_OUT_LOG_STR_BUF_SIZE) { + return -1; + } + memcpy(LOG_MODULE_STR_BUF(mesh), prefix, prefix_len); + + // Write string buffer + va_list args; + va_start(args, format); + int total_len = spi_out_write_str(LOG_MODULE_STR_BUF(mesh), format, args, prefix_len); + va_end(args); + if (total_len == 0) { + return -1; + } + + // Write log control block buffer + spi_out_write_hex(LOG_MODULE_CB(mesh), BLE_LOG_SPI_OUT_SOURCE_MESH, + LOG_MODULE_STR_BUF(mesh), (uint16_t)total_len, true); + return 0; +} +#endif // SPI_OUT_MESH_ENABLED #endif // CONFIG_BT_BLE_LOG_SPI_OUT_ENABLED diff --git a/components/bt/common/ble_log/include/ble_log/ble_log_spi_out.h b/components/bt/common/ble_log/include/ble_log/ble_log_spi_out.h index 30462fc72a..b62986a0bd 100644 --- a/components/bt/common/ble_log/include/ble_log/ble_log_spi_out.h +++ b/components/bt/common/ble_log/include/ble_log/ble_log_spi_out.h @@ -27,6 +27,7 @@ enum { BLE_LOG_SPI_OUT_SOURCE_ESP_LEGACY_ISR, BLE_LOG_SPI_OUT_SOURCE_LL_HCI, BLE_LOG_SPI_OUT_SOURCE_LE_AUDIO, + BLE_LOG_SPI_OUT_SOURCE_MESH, BLE_LOG_SPI_OUT_SOURCE_USER = 0x10, BLE_LOG_SPI_OUT_SOURCE_SSC = 0xFD, BLE_LOG_SPI_OUT_SOURCE_SYNC, @@ -59,5 +60,6 @@ void ble_log_spi_out_flush(void); void ble_log_spi_out_le_audio_write(const uint8_t *addr, uint16_t len); int ble_log_spi_out_host_write(uint8_t source, const char *prefix, const char *format, ...); int ble_log_spi_out_hci_write(uint8_t source, const uint8_t *addr, uint16_t len); +int ble_log_spi_out_mesh_write(const char *prefix, const char *format, ...); #endif // __BT_SPI_OUT_H__ From 275047b4767f1ad9c741334fbbaadbf57a90e33d Mon Sep 17 00:00:00 2001 From: Zhou Xiao Date: Tue, 8 Jul 2025 13:15:15 +0800 Subject: [PATCH 07/14] change(ble): enable bluedroid logs over debug level through spi output (cherry picked from commit c0d2792b9d72fd6fd0db626c726208d9b5f833f8) Co-authored-by: Zhou Xiao --- .../common/include/common/bt_trace.h | 28 +++++++++++++++++++ 1 file changed, 28 insertions(+) diff --git a/components/bt/host/bluedroid/common/include/common/bt_trace.h b/components/bt/host/bluedroid/common/include/common/bt_trace.h index 2ffaa8ea86..58435d8f6a 100644 --- a/components/bt/host/bluedroid/common/include/common/bt_trace.h +++ b/components/bt/host/bluedroid/common/include/common/bt_trace.h @@ -223,10 +223,14 @@ static inline void trc_dump_buffer(const char *prefix, uint8_t *data, uint16_t l #if (BT_BLE_LOG_SPI_OUT_HOST_ENABLED && !CLASSIC_BT_INCLUDED) #define BTM_TRACE_ERROR(fmt, args...) { \ + ble_log_spi_out_host_write(BLE_LOG_SPI_OUT_SOURCE_BLUEDROID, \ + BLE_LOG_SPI_OUT_BUILD_PREFIX(BLE_LOG_SPI_OUT_LEVEL_ERROR, "BT_BTM"), fmt, ## args); \ if (btm_cb.trace_level >= BT_TRACE_LEVEL_ERROR && BT_LOG_LEVEL_CHECK(BTM, ERROR)) BT_PRINT_E("BT_BTM", fmt, ## args); \ } #define BTM_TRACE_WARNING(fmt, args...) { \ + ble_log_spi_out_host_write(BLE_LOG_SPI_OUT_SOURCE_BLUEDROID, \ + BLE_LOG_SPI_OUT_BUILD_PREFIX(BLE_LOG_SPI_OUT_LEVEL_WARN, "BT_BTM"), fmt, ## args); \ if (btm_cb.trace_level >= BT_TRACE_LEVEL_WARNING && BT_LOG_LEVEL_CHECK(BTM, WARNING)) BT_PRINT_W("BT_BTM", fmt, ## args); \ } @@ -261,10 +265,14 @@ static inline void trc_dump_buffer(const char *prefix, uint8_t *data, uint16_t l #if (BT_BLE_LOG_SPI_OUT_HOST_ENABLED && !CLASSIC_BT_INCLUDED) #define L2CAP_TRACE_ERROR(fmt, args...) { \ + ble_log_spi_out_host_write(BLE_LOG_SPI_OUT_SOURCE_BLUEDROID, \ + BLE_LOG_SPI_OUT_BUILD_PREFIX(BLE_LOG_SPI_OUT_LEVEL_ERROR, "BT_L2CAP"), fmt, ## args); \ if (l2cb.l2cap_trace_level >= BT_TRACE_LEVEL_ERROR && BT_LOG_LEVEL_CHECK(L2CAP, ERROR)) BT_PRINT_E("BT_L2CAP", fmt, ## args); \ } #define L2CAP_TRACE_WARNING(fmt, args...) { \ + ble_log_spi_out_host_write(BLE_LOG_SPI_OUT_SOURCE_BLUEDROID, \ + BLE_LOG_SPI_OUT_BUILD_PREFIX(BLE_LOG_SPI_OUT_LEVEL_WARN, "BT_L2CAP"), fmt, ## args); \ if (l2cb.l2cap_trace_level >= BT_TRACE_LEVEL_WARNING && BT_LOG_LEVEL_CHECK(L2CAP, WARNING)) BT_PRINT_W("BT_L2CAP", fmt, ## args); \ } @@ -275,6 +283,8 @@ static inline void trc_dump_buffer(const char *prefix, uint8_t *data, uint16_t l } #define L2CAP_TRACE_EVENT(fmt, args...) { \ + ble_log_spi_out_host_write(BLE_LOG_SPI_OUT_SOURCE_BLUEDROID, \ + BLE_LOG_SPI_OUT_BUILD_PREFIX(BLE_LOG_SPI_OUT_LEVEL_DEBUG, "BT_L2CAP"), fmt, ## args); \ if (l2cb.l2cap_trace_level >= BT_TRACE_LEVEL_EVENT && BT_LOG_LEVEL_CHECK(L2CAP, EVENT)) BT_PRINT_D("BT_L2CAP", fmt, ## args); \ } @@ -313,10 +323,14 @@ static inline void trc_dump_buffer(const char *prefix, uint8_t *data, uint16_t l #if (BT_BLE_LOG_SPI_OUT_HOST_ENABLED && !CLASSIC_BT_INCLUDED) #define GAP_TRACE_ERROR(fmt, args...) { \ + ble_log_spi_out_host_write(BLE_LOG_SPI_OUT_SOURCE_BLUEDROID, \ + BLE_LOG_SPI_OUT_BUILD_PREFIX(BLE_LOG_SPI_OUT_LEVEL_ERROR, "BT_GAP"), fmt, ## args); \ if (gap_cb.trace_level >= BT_TRACE_LEVEL_ERROR && BT_LOG_LEVEL_CHECK(GAP, ERROR)) BT_PRINT_E("BT_GAP", fmt, ## args); \ } #define GAP_TRACE_WARNING(fmt, args...) { \ + ble_log_spi_out_host_write(BLE_LOG_SPI_OUT_SOURCE_BLUEDROID, \ + BLE_LOG_SPI_OUT_BUILD_PREFIX(BLE_LOG_SPI_OUT_LEVEL_WARN, "BT_GAP"), fmt, ## args); \ if (gap_cb.trace_level >= BT_TRACE_LEVEL_WARNING && BT_LOG_LEVEL_CHECK(GAP, WARNING)) BT_PRINT_W("BT_GAP", fmt, ## args); \ } @@ -327,6 +341,8 @@ static inline void trc_dump_buffer(const char *prefix, uint8_t *data, uint16_t l } #define GAP_TRACE_EVENT(fmt, args...) { \ + ble_log_spi_out_host_write(BLE_LOG_SPI_OUT_SOURCE_BLUEDROID, \ + BLE_LOG_SPI_OUT_BUILD_PREFIX(BLE_LOG_SPI_OUT_LEVEL_DEBUG, "BT_GAP"), fmt, ## args); \ if (gap_cb.trace_level >= BT_TRACE_LEVEL_EVENT && BT_LOG_LEVEL_CHECK(GAP, EVENT)) BT_PRINT_D("BT_GAP", fmt, ## args); \ } @@ -437,10 +453,14 @@ static inline void trc_dump_buffer(const char *prefix, uint8_t *data, uint16_t l #if (BT_BLE_LOG_SPI_OUT_HOST_ENABLED && !CLASSIC_BT_INCLUDED) #define GATT_TRACE_ERROR(fmt, args...) { \ + ble_log_spi_out_host_write(BLE_LOG_SPI_OUT_SOURCE_BLUEDROID, \ + BLE_LOG_SPI_OUT_BUILD_PREFIX(BLE_LOG_SPI_OUT_LEVEL_ERROR, "BT_GATT"), fmt, ## args); \ if (gatt_cb.trace_level >= BT_TRACE_LEVEL_ERROR && BT_LOG_LEVEL_CHECK(GATT, ERROR)) BT_PRINT_E("BT_GATT", fmt, ## args); \ } #define GATT_TRACE_WARNING(fmt, args...) { \ + ble_log_spi_out_host_write(BLE_LOG_SPI_OUT_SOURCE_BLUEDROID, \ + BLE_LOG_SPI_OUT_BUILD_PREFIX(BLE_LOG_SPI_OUT_LEVEL_WARN, "BT_GATT"), fmt, ## args); \ if (gatt_cb.trace_level >= BT_TRACE_LEVEL_WARNING && BT_LOG_LEVEL_CHECK(GATT, WARNING)) BT_PRINT_W("BT_GATT", fmt, ## args); \ } @@ -451,6 +471,8 @@ static inline void trc_dump_buffer(const char *prefix, uint8_t *data, uint16_t l } #define GATT_TRACE_EVENT(fmt, args...) { \ + ble_log_spi_out_host_write(BLE_LOG_SPI_OUT_SOURCE_BLUEDROID, \ + BLE_LOG_SPI_OUT_BUILD_PREFIX(BLE_LOG_SPI_OUT_LEVEL_DEBUG, "BT_GATT"), fmt, ## args); \ if (gatt_cb.trace_level >= BT_TRACE_LEVEL_EVENT && BT_LOG_LEVEL_CHECK(GATT, EVENT)) BT_PRINT_D("BT_GATT", fmt, ## args); \ } @@ -473,10 +495,14 @@ static inline void trc_dump_buffer(const char *prefix, uint8_t *data, uint16_t l #if (BT_BLE_LOG_SPI_OUT_HOST_ENABLED && !CLASSIC_BT_INCLUDED) #define SMP_TRACE_ERROR(fmt, args...) { \ + ble_log_spi_out_host_write(BLE_LOG_SPI_OUT_SOURCE_BLUEDROID, \ + BLE_LOG_SPI_OUT_BUILD_PREFIX(BLE_LOG_SPI_OUT_LEVEL_ERROR, "BT_SMP"), fmt, ## args); \ if (smp_cb.trace_level >= BT_TRACE_LEVEL_ERROR && BT_LOG_LEVEL_CHECK(SMP, ERROR)) BT_PRINT_E("BT_SMP", fmt, ## args); \ } #define SMP_TRACE_WARNING(fmt, args...) { \ + ble_log_spi_out_host_write(BLE_LOG_SPI_OUT_SOURCE_BLUEDROID, \ + BLE_LOG_SPI_OUT_BUILD_PREFIX(BLE_LOG_SPI_OUT_LEVEL_WARN, "BT_SMP"), fmt, ## args); \ if (smp_cb.trace_level >= BT_TRACE_LEVEL_WARNING && BT_LOG_LEVEL_CHECK(SMP, WARNING)) BT_PRINT_W("BT_SMP", fmt, ## args); \ } @@ -487,6 +513,8 @@ static inline void trc_dump_buffer(const char *prefix, uint8_t *data, uint16_t l } #define SMP_TRACE_EVENT(fmt, args...) { \ + ble_log_spi_out_host_write(BLE_LOG_SPI_OUT_SOURCE_BLUEDROID, \ + BLE_LOG_SPI_OUT_BUILD_PREFIX(BLE_LOG_SPI_OUT_LEVEL_DEBUG, "BT_SMP"), fmt, ## args); \ if (smp_cb.trace_level >= BT_TRACE_LEVEL_EVENT && BT_LOG_LEVEL_CHECK(SMP, EVENT)) BT_PRINT_D("BT_SMP", fmt, ## args); \ } From b58dbc325f0cec48f80b8e70a93ae03e2468ab02 Mon Sep 17 00:00:00 2001 From: Zhou Xiao Date: Tue, 8 Jul 2025 13:15:17 +0800 Subject: [PATCH 08/14] change(ble): enable hci log spi out for ESP chips (cherry picked from commit c60dd1a10ed89cacf6e5bf703bf63b94f20f9cb9) Co-authored-by: Zhou Xiao --- components/bt/host/bluedroid/api/esp_bluedroid_hci.c | 4 ++-- components/bt/host/bluedroid/hci/hci_hal_h4.c | 4 ++-- components/bt/host/nimble/esp-hci/src/esp_nimble_hci.c | 8 ++++---- 3 files changed, 8 insertions(+), 8 deletions(-) diff --git a/components/bt/host/bluedroid/api/esp_bluedroid_hci.c b/components/bt/host/bluedroid/api/esp_bluedroid_hci.c index 312639b6dd..ac64d17d04 100644 --- a/components/bt/host/bluedroid/api/esp_bluedroid_hci.c +++ b/components/bt/host/bluedroid/api/esp_bluedroid_hci.c @@ -67,9 +67,9 @@ void hci_host_send_packet(uint8_t *data, uint16_t len) #if (BT_HCI_LOG_INCLUDED == TRUE) bt_hci_log_record_hci_data(data[0], &data[1], len - 1); #endif -#if (BT_BLE_LOG_SPI_OUT_HCI_ENABLED && !SOC_ESP_NIMBLE_CONTROLLER) +#if CONFIG_BT_BLE_LOG_SPI_OUT_HCI_ENABLED ble_log_spi_out_hci_write(BLE_LOG_SPI_OUT_SOURCE_HCI_DOWNSTREAM, data, len); -#endif // (BT_BLE_LOG_SPI_OUT_HCI_ENABLED && !SOC_ESP_NIMBLE_CONTROLLER) +#endif // CONFIG_BT_BLE_LOG_SPI_OUT_HCI_ENABLED #if (BT_CONTROLLER_INCLUDED == TRUE) esp_vhci_host_send_packet(data, len); #else /* BT_CONTROLLER_INCLUDED == TRUE */ diff --git a/components/bt/host/bluedroid/hci/hci_hal_h4.c b/components/bt/host/bluedroid/hci/hci_hal_h4.c index 2b61ee2e60..ef874844ed 100644 --- a/components/bt/host/bluedroid/hci/hci_hal_h4.c +++ b/components/bt/host/bluedroid/hci/hci_hal_h4.c @@ -600,9 +600,9 @@ void bt_record_hci_data(uint8_t *data, uint16_t len) static int host_recv_pkt_cb(uint8_t *data, uint16_t len) { -#if (BT_BLE_LOG_SPI_OUT_HCI_ENABLED && !SOC_ESP_NIMBLE_CONTROLLER) +#if CONFIG_BT_BLE_LOG_SPI_OUT_HCI_ENABLED ble_log_spi_out_hci_write(BLE_LOG_SPI_OUT_SOURCE_HCI_UPSTREAM, data, len); -#endif // (BT_BLE_LOG_SPI_OUT_HCI_ENABLED && !SOC_ESP_NIMBLE_CONTROLLER) +#endif // CONFIG_BT_BLE_LOG_SPI_OUT_HCI_ENABLED //Target has packet to host, malloc new buffer for packet BT_HDR *pkt = NULL; #if (BLE_42_SCAN_EN == TRUE) diff --git a/components/bt/host/nimble/esp-hci/src/esp_nimble_hci.c b/components/bt/host/nimble/esp-hci/src/esp_nimble_hci.c index 6a5dacd1a7..4a001777b0 100644 --- a/components/bt/host/nimble/esp-hci/src/esp_nimble_hci.c +++ b/components/bt/host/nimble/esp-hci/src/esp_nimble_hci.c @@ -72,9 +72,9 @@ void esp_vhci_host_send_packet_wrapper(uint8_t *data, uint16_t len) #if (BT_HCI_LOG_INCLUDED == TRUE) bt_hci_log_record_hci_data(data[0], &data[1], len - 1); #endif -#if (CONFIG_BT_BLE_LOG_SPI_OUT_HCI_ENABLED && !SOC_ESP_NIMBLE_CONTROLLER) +#if CONFIG_BT_BLE_LOG_SPI_OUT_HCI_ENABLED ble_log_spi_out_hci_write(BLE_LOG_SPI_OUT_SOURCE_HCI_DOWNSTREAM, data, len); -#endif // (CONFIG_BT_BLE_LOG_SPI_OUT_HCI_ENABLED && !SOC_ESP_NIMBLE_CONTROLLER) +#endif // CONFIG_BT_BLE_LOG_SPI_OUT_HCI_ENABLED esp_vhci_host_send_packet(data, len); } @@ -231,9 +231,9 @@ static int dummy_host_rcv_pkt(uint8_t *data, uint16_t len) */ static int host_rcv_pkt(uint8_t *data, uint16_t len) { -#if (CONFIG_BT_BLE_LOG_SPI_OUT_HCI_ENABLED && !SOC_ESP_NIMBLE_CONTROLLER) +#if CONFIG_BT_BLE_LOG_SPI_OUT_HCI_ENABLED ble_log_spi_out_hci_write(BLE_LOG_SPI_OUT_SOURCE_HCI_UPSTREAM, data, len); -#endif // (CONFIG_BT_BLE_LOG_SPI_OUT_HCI_ENABLED && !SOC_ESP_NIMBLE_CONTROLLER) +#endif // CONFIG_BT_BLE_LOG_SPI_OUT_HCI_ENABLED bt_record_hci_data(data, len); From 6dc7c032d179e89bccb2a4e72231a8e68ddc15ca Mon Sep 17 00:00:00 2001 From: Zhou Xiao Date: Tue, 8 Jul 2025 13:15:19 +0800 Subject: [PATCH 09/14] change(ble): removed esp log to save code size (cherry picked from commit 0088541f543158ff1fc7b6173f004a90efd4042f) Co-authored-by: Zhou Xiao --- components/bt/common/ble_log/ble_log_spi_out.c | 15 --------------- .../ble_log/include/ble_log/ble_log_spi_out.h | 1 - 2 files changed, 16 deletions(-) diff --git a/components/bt/common/ble_log/ble_log_spi_out.c b/components/bt/common/ble_log/ble_log_spi_out.c index 2b5a5f95ea..7bc5d26951 100644 --- a/components/bt/common/ble_log/ble_log_spi_out.c +++ b/components/bt/common/ble_log/ble_log_spi_out.c @@ -441,7 +441,6 @@ static int spi_out_log_cb_init(spi_out_log_cb_t **log_cb, uint16_t buf_size, uin // Initialize log control block *log_cb = (spi_out_log_cb_t *)SPI_OUT_MALLOC(sizeof(spi_out_log_cb_t)); if (!(*log_cb)) { - ESP_LOGE(BLE_LOG_TAG, "Failed to initialize log control block!"); return -1; } memset(*log_cb, 0, sizeof(spi_out_log_cb_t)); @@ -452,7 +451,6 @@ static int spi_out_log_cb_init(spi_out_log_cb_t **log_cb, uint16_t buf_size, uin ret |= spi_out_init_trans(&((*log_cb)->trans_cb[i]), buf_size); } if (ret != 0) { - ESP_LOGE(BLE_LOG_TAG, "Failed to initialize SPI transactions!"); spi_out_log_cb_deinit(log_cb); return -1; } @@ -690,20 +688,16 @@ static int spi_out_ll_log_init(void) // Initialize log control blocks for controller task & ISR logs if (spi_out_log_cb_init(&ll_task_log_cb, SPI_OUT_LL_TASK_BUF_SIZE, LOG_CB_TYPE_LL_TASK) != 0) { - ESP_LOGE(BLE_LOG_TAG, "Failed to initialize log control blocks for controller task!"); goto task_log_cb_init_failed; } if (spi_out_log_cb_init(&ll_isr_log_cb, SPI_OUT_LL_ISR_BUF_SIZE, LOG_CB_TYPE_LL_ISR) != 0) { - ESP_LOGE(BLE_LOG_TAG, "Failed to initialize log control blocks for controller ISR!"); goto isr_log_cb_init_failed; } if (spi_out_log_cb_init(&ll_hci_log_cb, SPI_OUT_LL_HCI_BUF_SIZE, LOG_CB_TYPE_LL_HCI) != 0) { - ESP_LOGE(BLE_LOG_TAG, "Failed to initialize log control blocks for controller ISR!"); goto hci_log_cb_init_failed; } // Initialization done - ESP_LOGI(BLE_LOG_TAG, "Succeeded to initialize log control blocks for controller task & ISR!"); ll_log_inited = true; return 0; @@ -726,7 +720,6 @@ static void spi_out_ll_log_deinit(void) spi_out_log_cb_deinit(&ll_task_log_cb); // Deinitialization done - ESP_LOGI(BLE_LOG_TAG, "Succeeded to deinitialize controller log!"); ll_log_inited = false; return; } @@ -769,7 +762,6 @@ static int spi_out_ts_sync_init(void) .dispatch_method = ESP_TIMER_TASK }; if (esp_timer_create(&timer_args, &ts_sync_timer) != ESP_OK) { - ESP_LOGE(BLE_LOG_TAG, "Failed to initialize timestamp synchronizer timer!"); goto timer_init_failed; } #endif // !SPI_OUT_TS_SYNC_SLEEP_SUPPORT @@ -783,12 +775,10 @@ static int spi_out_ts_sync_init(void) .pull_up_en = 0 }; if (gpio_config(&io_conf) != ESP_OK) { - ESP_LOGE(BLE_LOG_TAG, "Failed to initialize timestamp synchronizer IO!"); goto gpio_init_failed; } // Initialization done - ESP_LOGI(BLE_LOG_TAG, "Succeeded to initialize timestamp synchronizer!"); ts_sync_inited = true; return 0; @@ -819,7 +809,6 @@ static void spi_out_ts_sync_deinit(void) gpio_reset_pin(SPI_OUT_SYNC_IO_NUM); // Deinitialization done - ESP_LOGI(BLE_LOG_TAG, "Succeeded to deinitialize timestamp synchronizer!"); ts_sync_inited = false; return; } @@ -918,11 +907,9 @@ int ble_log_spi_out_init(void) .flags = SPI_DEVICE_NO_RETURN_RESULT }; if (spi_bus_initialize(SPI_OUT_BUS, &bus_config, SPI_DMA_CH_AUTO) != ESP_OK) { - ESP_LOGE(BLE_LOG_TAG, "Failed to initialize SPI bus!"); goto spi_bus_init_failed; } if (spi_bus_add_device(SPI_OUT_BUS, &dev_config, &spi_handle) != ESP_OK) { - ESP_LOGE(BLE_LOG_TAG, "Failed to add device to SPI bus!"); goto spi_device_add_failed; } @@ -972,13 +959,11 @@ int ble_log_spi_out_init(void) .dispatch_method = ESP_TIMER_TASK }; if (esp_timer_create(&timer_args, &flush_timer) != ESP_OK) { - ESP_LOGE(BLE_LOG_TAG, "Failed to initialize flush timer!"); goto timer_init_failed; } #endif // SPI_OUT_FLUSH_TIMER_ENABLED // Initialization done - ESP_LOGI(BLE_LOG_TAG, "Succeeded to initialize BLE log SPI output interface!"); spi_out_inited = true; spi_out_enabled = true; diff --git a/components/bt/common/ble_log/include/ble_log/ble_log_spi_out.h b/components/bt/common/ble_log/include/ble_log/ble_log_spi_out.h index b62986a0bd..e0d9213dce 100644 --- a/components/bt/common/ble_log/include/ble_log/ble_log_spi_out.h +++ b/components/bt/common/ble_log/include/ble_log/ble_log_spi_out.h @@ -11,7 +11,6 @@ #include "driver/spi_master.h" #include "driver/gpio.h" #include "esp_timer.h" -#include "esp_log.h" #include "freertos/semphr.h" #include "esp_heap_caps.h" From 2dacf4bb865a2c28b6eaab8c319ea22ef4b5f935 Mon Sep 17 00:00:00 2001 From: Zhou Xiao Date: Tue, 8 Jul 2025 13:15:21 +0800 Subject: [PATCH 10/14] fix(ble): fixed controller log api call for ESP32-C3/ESP32-S3 (cherry picked from commit 6ac541aa4ac53a6be0ba4e1cc57024f2b88a04a7) Co-authored-by: Zhou Xiao --- components/bt/controller/esp32c3/Kconfig.in | 1 + components/bt/controller/esp32c3/bt.c | 2 +- 2 files changed, 2 insertions(+), 1 deletion(-) diff --git a/components/bt/controller/esp32c3/Kconfig.in b/components/bt/controller/esp32c3/Kconfig.in index 8ec833c8cc..da1793dd8e 100644 --- a/components/bt/controller/esp32c3/Kconfig.in +++ b/components/bt/controller/esp32c3/Kconfig.in @@ -597,6 +597,7 @@ menu "Controller debug log Options (Experimental)" depends on BT_CTRL_LE_LOG_EN depends on !BT_CTRL_LE_LOG_DUMP_ONLY select BT_BLE_LOG_SPI_OUT_ENABLED + select BT_BLE_LOG_SPI_OUT_LL_ENABLED default n help Output ble controller logs to SPI bus diff --git a/components/bt/controller/esp32c3/bt.c b/components/bt/controller/esp32c3/bt.c index dc7cd3e950..aad745f30f 100644 --- a/components/bt/controller/esp32c3/bt.c +++ b/components/bt/controller/esp32c3/bt.c @@ -552,7 +552,7 @@ static void esp_bt_controller_log_interface(uint32_t len, const uint8_t *addr, b #if CONFIG_BT_CTRL_LE_LOG_SPI_OUT_EN static IRAM_ATTR void esp_bt_controller_spi_log_interface(uint32_t len, const uint8_t *addr, bool end) { - ble_log_spi_out_write(BLE_LOG_SPI_OUT_SOURCE_ESP_LEGACY, addr, len); + ble_log_spi_out_ll_write(len, addr, 0, NULL, 0); } #endif // CONFIG_BT_CTRL_LE_LOG_SPI_OUT_EN From deebad0bbedfc91b721273d1859074aeeb038573 Mon Sep 17 00:00:00 2001 From: Zhou Xiao Date: Tue, 8 Jul 2025 13:15:24 +0800 Subject: [PATCH 11/14] fix(ble): update error code in controller init for ESP32-S3/ESP32-C3 (cherry picked from commit b8b7e153a70e03e42d82f4a7c80bd84706378563) Co-authored-by: Zhou Xiao --- components/bt/controller/esp32c3/bt.c | 1 + 1 file changed, 1 insertion(+) diff --git a/components/bt/controller/esp32c3/bt.c b/components/bt/controller/esp32c3/bt.c index aad745f30f..a0e31c15de 100644 --- a/components/bt/controller/esp32c3/bt.c +++ b/components/bt/controller/esp32c3/bt.c @@ -1810,6 +1810,7 @@ esp_err_t esp_bt_controller_init(esp_bt_controller_config_t *cfg) #if CONFIG_BT_BLE_LOG_SPI_OUT_ENABLED if (ble_log_spi_out_init() != 0) { ESP_LOGE(BT_LOG_TAG, "BLE Log SPI output init failed"); + err = ESP_ERR_NO_MEM; goto error; } #endif // CONFIG_BT_BLE_LOG_SPI_OUT_ENABLED From ba406e871e6658588b37f80df1f2fff756081252 Mon Sep 17 00:00:00 2001 From: Zhou Xiao Date: Tue, 8 Jul 2025 13:15:26 +0800 Subject: [PATCH 12/14] change(ble): support task buffer number configuration (cherry picked from commit 4946a1fe8dd140218e20715763f94cd98980222d) Co-authored-by: Zhou Xiao --- components/bt/common/Kconfig.in | 28 ++ .../bt/common/ble_log/ble_log_spi_out.c | 269 ++++++++++++------ 2 files changed, 214 insertions(+), 83 deletions(-) diff --git a/components/bt/common/Kconfig.in b/components/bt/common/Kconfig.in index f6402de87e..5202f53e9e 100644 --- a/components/bt/common/Kconfig.in +++ b/components/bt/common/Kconfig.in @@ -35,6 +35,13 @@ config BT_BLE_LOG_SPI_OUT_HCI_BUF_SIZE SPI transaction buffer size for HCI logs. There will be 2 SPI DMA buffers with the same size. +config BT_BLE_LOG_SPI_OUT_HCI_TASK_CNT + int "HCI task count" + depends on BT_BLE_LOG_SPI_OUT_HCI_ENABLED + default 1 + help + HCI task count + config BT_BLE_LOG_SPI_OUT_HOST_ENABLED bool "Enable Host log output to SPI" depends on BT_BLE_LOG_SPI_OUT_ENABLED @@ -51,6 +58,13 @@ config BT_BLE_LOG_SPI_OUT_HOST_BUF_SIZE SPI transaction buffer size for host logs. There will be 2 SPI DMA buffers with the same size. +config BT_BLE_LOG_SPI_OUT_HOST_TASK_CNT + int "Host task count" + depends on BT_BLE_LOG_SPI_OUT_HOST_ENABLED + default 2 + help + Host task count. + config BT_BLE_LOG_SPI_OUT_LL_ENABLED bool "Enable Controller log output to SPI" depends on BT_BLE_LOG_SPI_OUT_ENABLED @@ -155,6 +169,13 @@ config BT_BLE_LOG_SPI_OUT_LE_AUDIO_BUF_SIZE SPI transaction buffer size for LE Audio logs. There will be 2 SPI DMA buffers with the same size. +config BT_BLE_LOG_SPI_OUT_LE_AUDIO_TASK_CNT + int "LE audio task count" + depends on BT_BLE_LOG_SPI_OUT_LE_AUDIO_ENABLED + default 1 + help + LE audio task count + config BT_BLE_LOG_SPI_OUT_MESH_ENABLED bool "Enable BLE mesh log output to SPI" depends on BT_BLE_LOG_SPI_OUT_ENABLED @@ -169,3 +190,10 @@ config BT_BLE_LOG_SPI_OUT_MESH_BUF_SIZE help SPI transaction buffer size for BLE mesh logs. There will be 2 SPI DMA buffers with the same size. + +config BT_BLE_LOG_SPI_OUT_MESH_TASK_CNT + int "Mesh task count" + depends on BT_BLE_LOG_SPI_OUT_MESH_ENABLED + default 3 + help + Mesh task count diff --git a/components/bt/common/ble_log/ble_log_spi_out.c b/components/bt/common/ble_log/ble_log_spi_out.c index 7bc5d26951..fd7b33ac96 100644 --- a/components/bt/common/ble_log/ble_log_spi_out.c +++ b/components/bt/common/ble_log/ble_log_spi_out.c @@ -26,12 +26,16 @@ #define SPI_OUT_FLUSH_TIMEOUT_US (CONFIG_BT_BLE_LOG_SPI_OUT_FLUSH_TIMEOUT * 1000) #define SPI_OUT_LE_AUDIO_ENABLED CONFIG_BT_BLE_LOG_SPI_OUT_LE_AUDIO_ENABLED #define SPI_OUT_LE_AUDIO_BUF_SIZE CONFIG_BT_BLE_LOG_SPI_OUT_LE_AUDIO_BUF_SIZE +#define SPI_OUT_LE_AUDIO_TASK_CNT CONFIG_BT_BLE_LOG_SPI_OUT_LE_AUDIO_TASK_CNT #define SPI_OUT_HOST_ENABLED CONFIG_BT_BLE_LOG_SPI_OUT_HOST_ENABLED #define SPI_OUT_HOST_BUF_SIZE CONFIG_BT_BLE_LOG_SPI_OUT_HOST_BUF_SIZE +#define SPI_OUT_HOST_TASK_CNT CONFIG_BT_BLE_LOG_SPI_OUT_HOST_TASK_CNT #define SPI_OUT_HCI_ENABLED CONFIG_BT_BLE_LOG_SPI_OUT_HCI_ENABLED #define SPI_OUT_HCI_BUF_SIZE CONFIG_BT_BLE_LOG_SPI_OUT_HCI_BUF_SIZE +#define SPI_OUT_HCI_TASK_CNT CONFIG_BT_BLE_LOG_SPI_OUT_HCI_TASK_CNT #define SPI_OUT_MESH_ENABLED CONFIG_BT_BLE_LOG_SPI_OUT_MESH_ENABLED #define SPI_OUT_MESH_BUF_SIZE CONFIG_BT_BLE_LOG_SPI_OUT_MESH_BUF_SIZE +#define SPI_OUT_MESH_TASK_CNT CONFIG_BT_BLE_LOG_SPI_OUT_MESH_TASK_CNT // Private defines #define BLE_LOG_TAG "BLE_LOG" @@ -110,6 +114,12 @@ typedef struct { uint8_t type; } spi_out_log_cb_t; +typedef struct { + TaskHandle_t task_handle; + spi_out_log_cb_t *log_cb; + uint8_t *str_buf; +} task_map_t; + typedef struct { uint16_t length; uint8_t source; @@ -137,9 +147,7 @@ enum { enum { LOG_CB_TYPE_UL = 0, - LOG_CB_TYPE_LL_TASK, - LOG_CB_TYPE_LL_ISR, - LOG_CB_TYPE_LL_HCI, + LOG_CB_TYPE_LL, LOG_CB_TYPE_LE_AUDIO, LOG_CB_TYPE_HOST, LOG_CB_TYPE_HCI, @@ -199,7 +207,7 @@ static void spi_out_deinit_trans(spi_out_trans_cb_t **trans_cb); static void spi_out_tx_done_cb(spi_transaction_t *ret_trans); static inline void spi_out_append_trans(spi_out_trans_cb_t *trans_cb); -static int spi_out_log_cb_init(spi_out_log_cb_t **log_cb, uint16_t buf_size, uint8_t type); +static int spi_out_log_cb_init(spi_out_log_cb_t **log_cb, uint16_t buf_size, uint8_t type, uint8_t idx); static void spi_out_log_cb_deinit(spi_out_log_cb_t **log_cb); static inline bool spi_out_log_cb_check_trans(spi_out_log_cb_t *log_cb, uint16_t len, bool *need_append); static inline void spi_out_log_cb_append_trans(spi_out_log_cb_t *log_cb); @@ -209,6 +217,8 @@ static bool spi_out_log_cb_write(spi_out_log_cb_t *log_cb, const uint8_t *addr, bool with_checksum); static void spi_out_log_cb_write_loss(spi_out_log_cb_t *log_cb); static void spi_out_log_cb_dump(spi_out_log_cb_t *log_cb); +static bool spi_out_get_task_mapping(task_map_t *map, size_t num, + spi_out_log_cb_t **log_cb, uint8_t **str_buf); static void spi_out_log_flush(void); static void spi_out_write_hex(spi_out_log_cb_t *log_cb, uint8_t source, @@ -259,18 +269,34 @@ static void esp_timer_cb_ts_sync(void); #define IF_0(...) #define LOG_MODULE_INIT_FLAG(ID) (ID##_log_inited) -#define LOG_MODULE_CB(ID) (ID##_log_cb) +#define LOG_MODULE_CB_ARR(ID) (ID##_log_cb) +#define LOG_MODULE_CB_CNT(ID) (ID##_log_cb_cnt) +#define LOG_MODULE_CB(ID, IDX) (ID##_log_cb[IDX]) +#define LOG_MODULE_TASK_MAP(ID) (ID##_task_map) #define LOG_MODULE_MUTEX(ID) (ID##_log_mutex) -#define LOG_MODULE_STR_BUF(ID) (ID##_log_str_buf) +#define LOG_MODULE_STR_BUF_ARR(ID) (ID##_log_str_buf) +#define LOG_MODULE_STR_BUF(ID, IDX) (ID##_log_str_buf[IDX]) #define LOG_MODULE_INIT(ID) (spi_out_##ID##_log_init) #define LOG_MODULE_DEINIT(ID) (spi_out_##ID##_log_deinit) #define LOG_MODULE_FLUSH(ID) (spi_out_##ID##_log_flush) +#define LOG_MODULE_DUMP(ID) \ + do { \ + if (LOG_MODULE_INIT_FLAG(ID)) { \ + esp_rom_printf("[DUMP_START:\n"); \ + for (int i = 0; i < LOG_MODULE_CB_CNT(ID); i++) { \ + spi_out_log_cb_dump(LOG_MODULE_CB(ID, i)); \ + } \ + esp_rom_printf("\n:DUMP_END]\n"); \ + } \ + } while (0) -#define DECLARE_LOG_MODULE(ID, TYPE, BUF_SIZE, USE_MUTEX, USE_STR) \ +#define DECLARE_LOG_MODULE(ID, TYPE, BUF_SIZE, NUM_CB, USE_MUTEX, USE_STR) \ static bool LOG_MODULE_INIT_FLAG(ID) = false; \ - static spi_out_log_cb_t *LOG_MODULE_CB(ID) = NULL; \ + static spi_out_log_cb_t *LOG_MODULE_CB_ARR(ID)[NUM_CB] = { NULL }; \ + static const size_t LOG_MODULE_CB_CNT(ID) = (NUM_CB); \ + static task_map_t LOG_MODULE_TASK_MAP(ID)[NUM_CB] = {0}; \ IF_##USE_MUTEX(static SemaphoreHandle_t LOG_MODULE_MUTEX(ID) = NULL;) \ - IF_##USE_STR(static uint8_t *LOG_MODULE_STR_BUF(ID) = NULL;) \ + IF_##USE_STR(static uint8_t *LOG_MODULE_STR_BUF_ARR(ID)[NUM_CB] = {0};) \ \ static int LOG_MODULE_INIT(ID)(void); \ static void LOG_MODULE_DEINIT(ID)(void); \ @@ -287,13 +313,22 @@ static void esp_timer_cb_ts_sync(void); } \ ) \ IF_##USE_STR( \ - LOG_MODULE_STR_BUF(ID) = (uint8_t *)SPI_OUT_MALLOC(SPI_OUT_LOG_STR_BUF_SIZE); \ - if (!LOG_MODULE_STR_BUF(ID)) { \ - goto failed; \ + for (size_t i = 0; i < LOG_MODULE_CB_CNT(ID); i++) { \ + LOG_MODULE_STR_BUF(ID, i) = (uint8_t *)SPI_OUT_MALLOC( \ + SPI_OUT_LOG_STR_BUF_SIZE \ + ); \ + if (!LOG_MODULE_STR_BUF(ID, i)) { \ + goto failed; \ + } \ + LOG_MODULE_TASK_MAP(ID)[i].str_buf = LOG_MODULE_STR_BUF(ID, i); \ } \ ) \ - if (spi_out_log_cb_init(&LOG_MODULE_CB(ID), BUF_SIZE, TYPE) != 0) { \ - goto failed; \ + for (size_t i = 0; i < LOG_MODULE_CB_CNT(ID); i++) { \ + if (spi_out_log_cb_init(&LOG_MODULE_CB(ID, i), BUF_SIZE, TYPE, i) != 0) \ + { \ + goto failed; \ + } \ + LOG_MODULE_TASK_MAP(ID)[i].log_cb = LOG_MODULE_CB(ID, i); \ } \ LOG_MODULE_INIT_FLAG(ID) = true; \ return 0; \ @@ -310,13 +345,20 @@ static void esp_timer_cb_ts_sync(void); xSemaphoreTake(LOG_MODULE_MUTEX(ID), portMAX_DELAY); \ ) \ IF_##USE_STR( \ - if (LOG_MODULE_STR_BUF(ID)) { \ - free(LOG_MODULE_STR_BUF(ID)); \ - LOG_MODULE_STR_BUF(ID) = NULL; \ + for (size_t i = 0; i < LOG_MODULE_CB_CNT(ID); i++) { \ + if (LOG_MODULE_STR_BUF(ID, i)) { \ + free(LOG_MODULE_STR_BUF(ID, i)); \ + LOG_MODULE_STR_BUF(ID, i) = NULL; \ + } \ } \ ) \ - spi_out_log_cb_deinit(&LOG_MODULE_CB(ID)); \ - \ + for (size_t i = 0; i < LOG_MODULE_CB_CNT(ID); i++) { \ + spi_out_log_cb_deinit(&LOG_MODULE_CB(ID, i)); \ + LOG_MODULE_CB(ID, i) = NULL; \ + } \ + for (size_t i = 0; i < LOG_MODULE_CB_CNT(ID); i++) { \ + memset(&LOG_MODULE_TASK_MAP(ID)[i], 0, sizeof(task_map_t)); \ + } \ IF_##USE_MUTEX( \ xSemaphoreGive(LOG_MODULE_MUTEX(ID)); \ vSemaphoreDelete(LOG_MODULE_MUTEX(ID)); \ @@ -330,30 +372,36 @@ static void esp_timer_cb_ts_sync(void); IF_##USE_MUTEX( \ xSemaphoreTake(LOG_MODULE_MUTEX(ID), portMAX_DELAY); \ ) \ - spi_out_log_cb_write_loss(LOG_MODULE_CB(ID)); \ - spi_out_log_cb_flush_trans(LOG_MODULE_CB(ID)); \ - spi_out_log_cb_append_trans(LOG_MODULE_CB(ID)); \ + for (size_t i = 0; i < LOG_MODULE_CB_CNT(ID); ++i) { \ + spi_out_log_cb_write_loss(LOG_MODULE_CB(ID, i)); \ + spi_out_log_cb_flush_trans(LOG_MODULE_CB(ID, i)); \ + spi_out_log_cb_append_trans(LOG_MODULE_CB(ID, i)); \ + } \ IF_##USE_MUTEX( \ xSemaphoreGive(LOG_MODULE_MUTEX(ID)); \ ) \ - } \ + } -DECLARE_LOG_MODULE(ul, LOG_CB_TYPE_UL, SPI_OUT_UL_TASK_BUF_SIZE, 1, 1) +DECLARE_LOG_MODULE(ul, LOG_CB_TYPE_UL, SPI_OUT_UL_TASK_BUF_SIZE, 1, 1, 1) #if SPI_OUT_LE_AUDIO_ENABLED -DECLARE_LOG_MODULE(le_audio, LOG_CB_TYPE_LE_AUDIO, SPI_OUT_LE_AUDIO_BUF_SIZE, 0, 0) +DECLARE_LOG_MODULE(le_audio, LOG_CB_TYPE_LE_AUDIO, SPI_OUT_LE_AUDIO_BUF_SIZE, + SPI_OUT_LE_AUDIO_TASK_CNT, 0, 0) #endif // SPI_OUT_LE_AUDIO_ENABLED #if SPI_OUT_HOST_ENABLED -DECLARE_LOG_MODULE(host, LOG_CB_TYPE_HOST, SPI_OUT_HOST_BUF_SIZE, 0, 1) +DECLARE_LOG_MODULE(host, LOG_CB_TYPE_HOST, SPI_OUT_HOST_BUF_SIZE, + SPI_OUT_HOST_TASK_CNT, 0, 1) #endif // SPI_OUT_HOST_ENABLED #if SPI_OUT_HCI_ENABLED -DECLARE_LOG_MODULE(hci, LOG_CB_TYPE_HCI, SPI_OUT_HCI_BUF_SIZE, 0, 0) +DECLARE_LOG_MODULE(hci, LOG_CB_TYPE_HCI, SPI_OUT_HCI_BUF_SIZE, + SPI_OUT_HCI_TASK_CNT, 0, 0) #endif // SPI_OUT_HCI_ENABLED #if SPI_OUT_MESH_ENABLED -DECLARE_LOG_MODULE(mesh, LOG_CB_TYPE_MESH, SPI_OUT_MESH_BUF_SIZE, 0, 1) +DECLARE_LOG_MODULE(mesh, LOG_CB_TYPE_MESH, SPI_OUT_MESH_BUF_SIZE, + SPI_OUT_MESH_TASK_CNT, 0, 1) #endif // SPI_OUT_MESH_ENABLED // Private functions @@ -436,7 +484,7 @@ recycle: return; } -static int spi_out_log_cb_init(spi_out_log_cb_t **log_cb, uint16_t buf_size, uint8_t type) +static int spi_out_log_cb_init(spi_out_log_cb_t **log_cb, uint16_t buf_size, uint8_t type, uint8_t idx) { // Initialize log control block *log_cb = (spi_out_log_cb_t *)SPI_OUT_MALLOC(sizeof(spi_out_log_cb_t)); @@ -455,7 +503,7 @@ static int spi_out_log_cb_init(spi_out_log_cb_t **log_cb, uint16_t buf_size, uin return -1; } - (*log_cb)->type = type; + (*log_cb)->type = (type << 4) | (idx); return 0; } @@ -607,6 +655,67 @@ static void spi_out_log_cb_dump(spi_out_log_cb_t *log_cb) } } +static void spi_out_update_task_mapping(int idx, void *ptr) +{ + // It is a must to clear task handle after task deletion + task_map_t *entry = (task_map_t *)ptr; + entry->task_handle = NULL; +} + +static bool spi_out_get_task_mapping(task_map_t *map, size_t num, + spi_out_log_cb_t **log_cb, uint8_t **str_buf) +{ + if (!map || !log_cb) { + return false; + } + + // Shall not be called in ISR + TaskHandle_t handle = xTaskGetCurrentTaskHandle(); + if (!handle) { + return false; + } + + // Check if the given task handle is already in map + for (size_t i = 0; i < num; i++) { + task_map_t *entry = &map[i]; + if (entry->task_handle == handle) { + *log_cb = entry->log_cb; + if (str_buf) { + *str_buf = entry->str_buf; + } + return true; + } + } + + // Task handle not in map, try to allocate free slot + bool ret = false; + portMUX_TYPE spinlock = portMUX_INITIALIZER_UNLOCKED; + portENTER_CRITICAL_SAFE(&spinlock); + for (size_t i = 0; i < num; i++) { + task_map_t *entry = &map[i]; + if (entry->task_handle == NULL) { + vTaskSetThreadLocalStoragePointerAndDelCallback( + NULL, 0, (void *)entry, spi_out_update_task_mapping + ); + entry->task_handle = handle; + *log_cb = entry->log_cb; + if (str_buf) { + *str_buf = entry->str_buf; + } + ret = true; + break; + } + } + portEXIT_CRITICAL_SAFE(&spinlock); + + if (!ret) { + // Shall not be here in normal case + const char *task_name = pcTaskGetName(NULL); + esp_rom_printf("@EW: Failed to assign slot in task map for task %s\n", task_name); + } + return ret; +} + static void spi_out_log_flush(void) { LOG_MODULE_FLUSH(ul)(); @@ -687,13 +796,13 @@ static int spi_out_ll_log_init(void) } // Initialize log control blocks for controller task & ISR logs - if (spi_out_log_cb_init(&ll_task_log_cb, SPI_OUT_LL_TASK_BUF_SIZE, LOG_CB_TYPE_LL_TASK) != 0) { + if (spi_out_log_cb_init(&ll_task_log_cb, SPI_OUT_LL_TASK_BUF_SIZE, LOG_CB_TYPE_LL, 0) != 0) { goto task_log_cb_init_failed; } - if (spi_out_log_cb_init(&ll_isr_log_cb, SPI_OUT_LL_ISR_BUF_SIZE, LOG_CB_TYPE_LL_ISR) != 0) { + if (spi_out_log_cb_init(&ll_isr_log_cb, SPI_OUT_LL_ISR_BUF_SIZE, LOG_CB_TYPE_LL, 1) != 0) { goto isr_log_cb_init_failed; } - if (spi_out_log_cb_init(&ll_hci_log_cb, SPI_OUT_LL_HCI_BUF_SIZE, LOG_CB_TYPE_LL_HCI) != 0) { + if (spi_out_log_cb_init(&ll_hci_log_cb, SPI_OUT_LL_HCI_BUF_SIZE, LOG_CB_TYPE_LL, 2) != 0) { goto hci_log_cb_init_failed; } @@ -1175,7 +1284,7 @@ int ble_log_spi_out_write(uint8_t source, const uint8_t *addr, uint16_t len) } xSemaphoreTake(LOG_MODULE_MUTEX(ul), portMAX_DELAY); - spi_out_write_hex(LOG_MODULE_CB(ul), source, addr, len, false); + spi_out_write_hex(LOG_MODULE_CB(ul, 0), source, addr, len, false); xSemaphoreGive(LOG_MODULE_MUTEX(ul)); return 0; } @@ -1191,59 +1300,30 @@ void ble_log_spi_out_dump_all(void) #if SPI_OUT_LL_ENABLED if (ll_log_inited) { - // Dump lower layer log buffer - esp_rom_printf("[LL_ISR_LOG_DUMP_START:\n"); + esp_rom_printf("[DUMP_START:\n"); spi_out_log_cb_dump(ll_isr_log_cb); - esp_rom_printf("\n:LL_ISR_LOG_DUMP_END]\n\n"); - - esp_rom_printf("[LL_TASK_LOG_DUMP_START:\n"); spi_out_log_cb_dump(ll_task_log_cb); - esp_rom_printf("\n:LL_TASK_LOG_DUMP_END]\n\n"); - - esp_rom_printf("[LL_HCI_LOG_DUMP_START:\n"); spi_out_log_cb_dump(ll_hci_log_cb); - esp_rom_printf("\n:LL_HCI_LOG_DUMP_END]\n\n"); + esp_rom_printf("\n:DUMP_END]\n\n"); } #endif // SPI_OUT_LL_ENABLED - if (LOG_MODULE_INIT_FLAG(ul)) { - // Dump upper layer log buffer - esp_rom_printf("[UL_LOG_DUMP_START:\n"); - spi_out_log_cb_dump(LOG_MODULE_CB(ul)); - esp_rom_printf("\n:UL_LOG_DUMP_END]\n\n"); - } + LOG_MODULE_DUMP(ul); #if SPI_OUT_LE_AUDIO_ENABLED - if (LOG_MODULE_INIT_FLAG(le_audio)) { - esp_rom_printf("[LE_AUDIO_LOG_DUMP_START:\n"); - spi_out_log_cb_dump(LOG_MODULE_CB(le_audio)); - esp_rom_printf("\n:LE_AUDIO_LOG_DUMP_END]\n\n"); - } + LOG_MODULE_DUMP(le_audio); #endif // SPI_OUT_LE_AUDIO_ENABLED - #if SPI_OUT_HOST_ENABLED - if (LOG_MODULE_INIT_FLAG(host)) { - esp_rom_printf("[HOST_LOG_DUMP_START:\n"); - spi_out_log_cb_dump(LOG_MODULE_CB(host)); - esp_rom_printf("\n:HOST_LOG_DUMP_END]\n\n"); - } + LOG_MODULE_DUMP(host); #endif // SPI_OUT_HOST_ENABLED #if SPI_OUT_HCI_ENABLED - if (LOG_MODULE_INIT_FLAG(hci)) { - esp_rom_printf("[HCI_LOG_DUMP_START:\n"); - spi_out_log_cb_dump(LOG_MODULE_CB(hci)); - esp_rom_printf("\n:HCI_LOG_DUMP_END]\n\n"); - } + LOG_MODULE_DUMP(hci); #endif // SPI_OUT_HCI_ENABLED #if SPI_OUT_MESH_ENABLED - if (LOG_MODULE_INIT_FLAG(mesh)) { - esp_rom_printf("[MESH_LOG_DUMP_START:\n"); - spi_out_log_cb_dump(LOG_MODULE_CB(mesh)); - esp_rom_printf("\n:MESH_LOG_DUMP_END]\n\n"); - } + LOG_MODULE_DUMP(mesh); #endif // SPI_OUT_MESH_ENABLED portEXIT_CRITICAL_SAFE(&spinlock); @@ -1280,15 +1360,21 @@ IRAM_ATTR void ble_log_spi_out_le_audio_write(const uint8_t *addr, uint16_t len) return; } + spi_out_log_cb_t *log_cb; + if (!spi_out_get_task_mapping(LOG_MODULE_TASK_MAP(le_audio), + LOG_MODULE_CB_CNT(le_audio), &log_cb, NULL)) { + return; + } + bool need_append; - if (spi_out_log_cb_check_trans(LOG_MODULE_CB(le_audio), len, &need_append)) { - need_append |= spi_out_log_cb_write(LOG_MODULE_CB(le_audio), addr, len, NULL, 0, + if (spi_out_log_cb_check_trans(log_cb, len, &need_append)) { + need_append |= spi_out_log_cb_write(log_cb, addr, len, NULL, 0, BLE_LOG_SPI_OUT_SOURCE_LE_AUDIO, false); } if (need_append) { - spi_out_log_cb_append_trans(LOG_MODULE_CB(le_audio)); + spi_out_log_cb_append_trans(log_cb); } - spi_out_log_cb_write_loss(LOG_MODULE_CB(le_audio)); + spi_out_log_cb_write_loss(log_cb); return; } #endif // CONFIG_BT_BLE_LOG_SPI_OUT_LE_AUDIO_ENABLED @@ -1300,25 +1386,31 @@ int ble_log_spi_out_host_write(uint8_t source, const char *prefix, const char *f return -1; } + spi_out_log_cb_t *log_cb; + uint8_t *str_buf; + if (!spi_out_get_task_mapping(LOG_MODULE_TASK_MAP(host), + LOG_MODULE_CB_CNT(host), &log_cb, &str_buf)) { + return -1; + } + // Copy prefix to string buffer int prefix_len = strlen(prefix); if (prefix_len >= SPI_OUT_LOG_STR_BUF_SIZE) { return -1; } - memcpy(LOG_MODULE_STR_BUF(host), prefix, prefix_len); + memcpy(str_buf, prefix, prefix_len); // Write string buffer va_list args; va_start(args, format); - int total_len = spi_out_write_str(LOG_MODULE_STR_BUF(host), format, args, prefix_len); + int total_len = spi_out_write_str(str_buf, format, args, prefix_len); va_end(args); if (total_len == 0) { return -1; } // Write log control block buffer - spi_out_write_hex(LOG_MODULE_CB(host), source, - LOG_MODULE_STR_BUF(host), (uint16_t)total_len, true); + spi_out_write_hex(log_cb, source, str_buf, (uint16_t)total_len, true); return 0; } #endif // SPI_OUT_HOST_ENABLED @@ -1336,7 +1428,12 @@ int ble_log_spi_out_hci_write(uint8_t source, const uint8_t *addr, uint16_t len) #endif // SPI_OUT_LL_ENABLED } if (source == BLE_LOG_SPI_OUT_SOURCE_HCI_DOWNSTREAM) { - spi_out_write_hex(LOG_MODULE_CB(hci), source, addr, len, true); + spi_out_log_cb_t *log_cb; + if (!spi_out_get_task_mapping(LOG_MODULE_TASK_MAP(hci), + LOG_MODULE_CB_CNT(hci), &log_cb, NULL)) { + return -1; + } + spi_out_write_hex(log_cb, source, addr, len, true); } return 0; } @@ -1349,25 +1446,31 @@ int ble_log_spi_out_mesh_write(const char *prefix, const char *format, ...) return -1; } + spi_out_log_cb_t *log_cb; + uint8_t *str_buf; + if (!spi_out_get_task_mapping(LOG_MODULE_TASK_MAP(mesh), + LOG_MODULE_CB_CNT(mesh), &log_cb, &str_buf)) { + return -1; + } + // Copy prefix to string buffer int prefix_len = strlen(prefix); if (prefix_len >= SPI_OUT_LOG_STR_BUF_SIZE) { return -1; } - memcpy(LOG_MODULE_STR_BUF(mesh), prefix, prefix_len); + memcpy(str_buf, prefix, prefix_len); // Write string buffer va_list args; va_start(args, format); - int total_len = spi_out_write_str(LOG_MODULE_STR_BUF(mesh), format, args, prefix_len); + int total_len = spi_out_write_str(str_buf, format, args, prefix_len); va_end(args); if (total_len == 0) { return -1; } // Write log control block buffer - spi_out_write_hex(LOG_MODULE_CB(mesh), BLE_LOG_SPI_OUT_SOURCE_MESH, - LOG_MODULE_STR_BUF(mesh), (uint16_t)total_len, true); + spi_out_write_hex(log_cb, BLE_LOG_SPI_OUT_SOURCE_MESH, str_buf, (uint16_t)total_len, true); return 0; } #endif // SPI_OUT_MESH_ENABLED From 7f5c88e27a58f0674132790f3596898b271be710 Mon Sep 17 00:00:00 2001 From: Zhou Xiao Date: Tue, 8 Jul 2025 13:15:29 +0800 Subject: [PATCH 13/14] fix(ble): nimble host & hci log write race condition workaround (cherry picked from commit 6e384644c86acf450edaf0016826f910c99c7682) Co-authored-by: Zhou Xiao --- .../bt/common/ble_log/ble_log_spi_out.c | 26 +++++++++++++------ 1 file changed, 18 insertions(+), 8 deletions(-) diff --git a/components/bt/common/ble_log/ble_log_spi_out.c b/components/bt/common/ble_log/ble_log_spi_out.c index fd7b33ac96..4fbb663ad3 100644 --- a/components/bt/common/ble_log/ble_log_spi_out.c +++ b/components/bt/common/ble_log/ble_log_spi_out.c @@ -707,12 +707,6 @@ static bool spi_out_get_task_mapping(task_map_t *map, size_t num, } } portEXIT_CRITICAL_SAFE(&spinlock); - - if (!ret) { - // Shall not be here in normal case - const char *task_name = pcTaskGetName(NULL); - esp_rom_printf("@EW: Failed to assign slot in task map for task %s\n", task_name); - } return ret; } @@ -1388,9 +1382,14 @@ int ble_log_spi_out_host_write(uint8_t source, const char *prefix, const char *f spi_out_log_cb_t *log_cb; uint8_t *str_buf; + bool fallback = false; if (!spi_out_get_task_mapping(LOG_MODULE_TASK_MAP(host), LOG_MODULE_CB_CNT(host), &log_cb, &str_buf)) { - return -1; + // NimBLE workaround + fallback = true; + xSemaphoreTake(LOG_MODULE_MUTEX(ul), portMAX_DELAY); + log_cb = LOG_MODULE_CB(ul, 0); + str_buf = LOG_MODULE_STR_BUF(ul, 0); } // Copy prefix to string buffer @@ -1411,6 +1410,10 @@ int ble_log_spi_out_host_write(uint8_t source, const char *prefix, const char *f // Write log control block buffer spi_out_write_hex(log_cb, source, str_buf, (uint16_t)total_len, true); + + if (fallback) { + xSemaphoreGive(LOG_MODULE_MUTEX(ul)); + } return 0; } #endif // SPI_OUT_HOST_ENABLED @@ -1429,11 +1432,18 @@ int ble_log_spi_out_hci_write(uint8_t source, const uint8_t *addr, uint16_t len) } if (source == BLE_LOG_SPI_OUT_SOURCE_HCI_DOWNSTREAM) { spi_out_log_cb_t *log_cb; + bool fallback = false; if (!spi_out_get_task_mapping(LOG_MODULE_TASK_MAP(hci), LOG_MODULE_CB_CNT(hci), &log_cb, NULL)) { - return -1; + // NimBLE workaround + fallback = true; + xSemaphoreTake(LOG_MODULE_MUTEX(ul), portMAX_DELAY); + log_cb = LOG_MODULE_CB(ul, 0); } spi_out_write_hex(log_cb, source, addr, len, true); + if (fallback) { + xSemaphoreGive(LOG_MODULE_MUTEX(ul)); + } } return 0; } From 243facef85878662156a3a5ad3c2f575ae8d24c6 Mon Sep 17 00:00:00 2001 From: Zhou Xiao Date: Tue, 8 Jul 2025 13:15:31 +0800 Subject: [PATCH 14/14] change(ble): upgraded spi log frame header (cherry picked from commit 5f3ac91d6305eb4daecc340fe669a13fe3d1daad) Co-authored-by: Zhou Xiao --- .../bt/common/ble_log/ble_log_spi_out.c | 36 +++++++++---------- 1 file changed, 17 insertions(+), 19 deletions(-) diff --git a/components/bt/common/ble_log/ble_log_spi_out.c b/components/bt/common/ble_log/ble_log_spi_out.c index 4fbb663ad3..e1c6a278cb 100644 --- a/components/bt/common/ble_log/ble_log_spi_out.c +++ b/components/bt/common/ble_log/ble_log_spi_out.c @@ -41,10 +41,6 @@ #define BLE_LOG_TAG "BLE_LOG" #define SPI_OUT_BUS SPI2_HOST #define SPI_OUT_MAX_TRANSFER_SIZE (10240) -#define SPI_OUT_FRAME_HEAD_LEN (4) -#define SPI_OUT_FRAME_TAIL_LEN (4) -#define SPI_OUT_FRAME_OVERHEAD (8) -#define SPI_OUT_PACKET_LOSS_FRAME_SIZE (6) #define SPI_OUT_TRANS_ITVL_MIN_US (30) #define SPI_OUT_LOG_STR_BUF_SIZE (100) #define SPI_OUT_MALLOC(size) heap_caps_malloc(size, MALLOC_CAP_INTERNAL | MALLOC_CAP_8BIT) @@ -108,10 +104,10 @@ typedef struct { typedef struct { spi_out_trans_cb_t *trans_cb[2]; uint8_t trans_cb_idx; - uint8_t frame_sn; + uint8_t type; uint16_t lost_frame_cnt; uint32_t lost_bytes_cnt; - uint8_t type; + uint32_t frame_sn; } spi_out_log_cb_t; typedef struct { @@ -123,7 +119,8 @@ typedef struct { typedef struct { uint16_t length; uint8_t source; - uint8_t frame_sn; + uint8_t type; + uint16_t frame_sn; } __attribute__((packed)) frame_head_t; typedef struct { @@ -404,6 +401,12 @@ DECLARE_LOG_MODULE(mesh, LOG_CB_TYPE_MESH, SPI_OUT_MESH_BUF_SIZE, SPI_OUT_MESH_TASK_CNT, 0, 1) #endif // SPI_OUT_MESH_ENABLED +// Private macros +#define SPI_OUT_FRAME_HEAD_LEN (sizeof(frame_head_t)) +#define SPI_OUT_FRAME_TAIL_LEN (sizeof(uint32_t)) +#define SPI_OUT_FRAME_OVERHEAD (SPI_OUT_FRAME_HEAD_LEN + SPI_OUT_FRAME_TAIL_LEN) +#define SPI_OUT_GET_FRAME_SN(VAR) __atomic_fetch_add(VAR, 1, __ATOMIC_RELAXED) + // Private functions static int spi_out_init_trans(spi_out_trans_cb_t **trans_cb, uint16_t buf_size) { @@ -546,7 +549,6 @@ IRAM_ATTR static inline bool spi_out_log_cb_check_trans(spi_out_log_cb_t *log_cb failed: log_cb->lost_bytes_cnt += frame_len; log_cb->lost_frame_cnt++; - log_cb->frame_sn++; return false; } @@ -587,27 +589,23 @@ IRAM_ATTR static bool spi_out_log_cb_write(spi_out_log_cb_t *log_cb, const uint8 frame_head_t head = { .length = total_length, .source = source, - .frame_sn = log_cb->frame_sn, + .type = log_cb->type, + .frame_sn = SPI_OUT_GET_FRAME_SN(&(log_cb->frame_sn)) & 0xFFFF, }; - uint32_t checksum = 0; - if (with_checksum) { - for (int i = 0; i < len; i++) { - checksum += addr[i]; - } - for (int i = 0; i < len_append; i++) { - checksum += addr_append[i]; - } - } memcpy(buf, (const uint8_t *)&head, SPI_OUT_FRAME_HEAD_LEN); memcpy(buf + SPI_OUT_FRAME_HEAD_LEN, addr, len); if (len_append && addr_append) { memcpy(buf + SPI_OUT_FRAME_HEAD_LEN + len, addr_append, len_append); } + + uint32_t checksum = 0; + for (int i = 0; i < SPI_OUT_FRAME_HEAD_LEN + total_length; i++) { + checksum += buf[i]; + } memcpy(buf + SPI_OUT_FRAME_HEAD_LEN + total_length, &checksum, SPI_OUT_FRAME_TAIL_LEN); trans_cb->length += total_length + SPI_OUT_FRAME_OVERHEAD; - log_cb->frame_sn++; if ((trans_cb->buf_size - trans_cb->length) <= SPI_OUT_FRAME_OVERHEAD) { trans_cb->flag = TRANS_CB_FLAG_NEED_QUEUE; return true;