Use cyw43 macros for bluetooth logging (#2490)

* Tidy up bt logging

Fixes #2253

* Allow logging to be overridden

Author: peterharperuk

src/rp2_common/pico_cyw43_driver/cybt_shared_bus/BUILD.bazel

@@ -6,7 +6,7 @@ cc_library(
         "cybt_shared_bus.c",
         "cybt_shared_bus_driver.c",
     ],
-    hdrs = ["cybt_shared_bus_driver.h"],
+    hdrs = ["cybt_shared_bus_driver.h", "cybt_logging.h"],
     includes = ["."],
     deps = [
         "@cyw43-driver//:cyw43_driver",

src/rp2_common/pico_cyw43_driver/cybt_shared_bus/cybt_logging.h

@@ -0,0 +1,57 @@
+/*
+ * Copyright (c) 2025 Raspberry Pi (Trading) Ltd.
+ *
+ * SPDX-License-Identifier: BSD-3-Clause
+ */
+
+#ifndef CYBT_LOGGING_H
+#define CYBT_LOGGING_H
+
+// Error messages only enabled in debug by default
+#ifndef CYBT_ERROR_ENABLED
+#ifndef NDEBUG
+#define CYBT_ERROR_ENABLED 1
+#else
+#define CYBT_ERROR_ENABLED 0
+#endif
+#endif
+
+// Info messages only enabled in debug by default
+#ifndef CYBT_INFO_ENABLED
+#ifndef NDEBUG
+#define CYBT_INFO_ENABLED 1
+#else
+#define CYBT_INFO_ENABLED 0
+#endif
+#endif
+
+// Debug messages disabled by default
+#ifndef CYBT_DEBUG_ENABLED
+#define CYBT_DEBUG_ENABLED 0
+#endif
+
+#ifndef cybt_error
+#if CYBT_ERROR_ENABLED
+#define cybt_error CYW43_WARN
+#else
+#define cybt_error(...)
+#endif
+#endif
+
+#ifndef cybt_info
+#if CYBT_INFO_ENABLED
+#define cybt_info CYW43_PRINTF
+#else
+#define cybt_info(...)
+#endif
+#endif
+
+#ifndef cybt_debug
+#if CYBT_DEBUG_ENABLED
+#define cybt_debug CYW43_PRINTF
+#else
+#define cybt_debug(...)
+#endif
+#endif
+
+#endif // CYBT_LOGGING_H

src/rp2_common/pico_cyw43_driver/cybt_shared_bus/cybt_shared_bus.c

@@ -15,6 +15,7 @@
 #include "cybt_shared_bus_driver.h"
 
 #include "cyw43_btfw_43439.h"
+#include "cybt_logging.h"
 
 #if CYW43_USE_HEX_BTFW
 extern const char    brcm_patch_version[];
@@ -31,20 +32,6 @@ extern const int     brcm_patch_ram_length;
 #define  BTSDIO_FWBUF_OPER_DELAY_US            (250)
 #define  BTFW_WAIT_TIME_MS                     (150)
 
-#define CYBT_DEBUG 0
-#define CYBT_VDEBUG 0
-
-#if CYBT_DEBUG
-#define cybt_debug(format,args...) printf("%d.%d: " format, (int)cyw43_hal_ticks_ms() / 1000, (int)cyw43_hal_ticks_ms() % 1000, ## args)
-#else
-#define cybt_debug(format, ...) ((void)0)
-#endif
-#ifndef NDEBUG
-#define cybt_printf(format, args...) printf("%d.%d: " format, (int)cyw43_hal_ticks_ms() / 1000, (int)cyw43_hal_ticks_ms() % 1000, ## args)
-#else
-#define cybt_printf(...)
-#endif
-
 #define ROUNDUP(x, a)               ((((x) + ((a) - 1)) / (a)) * (a))
 #define ROUNDDN(x, a)               ((x) & ~((a) - 1))
 #define ISALIGNED(a, x)             (((uint32_t)(a) & ((x) - 1)) == 0)
@@ -123,17 +110,17 @@ int cyw43_btbus_init(cyw43_ll_t *self) {
 
     ret = cybt_fw_download_prepare(&p_write_buf, &p_hex_buf);
     if (CYBT_SUCCESS != ret) {
-        cybt_printf("Could not allocate memory\n");
+        cybt_error("Could not allocate memory\n");
         return ret;
     }
 
     cybt_debug("cybt_fw_download\n");
     const uint8_t *fw_data_buf;
     uint32_t fw_data_len;
 #if CYW43_USE_HEX_BTFW
-    cybt_printf("CYW43_USE_HEX_BTFW is true\n");
+    cybt_error("CYW43_USE_HEX_BTFW is true\n");
 #ifndef NDEBUG
-    cybt_printf("BT FW download, version = %s\n", brcm_patch_version);
+    cybt_info("BT FW download, version = %s\n", brcm_patch_version);
 #endif
     fw_data_len = brcm_patch_ram_length;
     fw_data_buf = brcm_patchram_buf;
@@ -151,7 +138,7 @@ int cyw43_btbus_init(cyw43_ll_t *self) {
     cybt_fw_download_finish(p_write_buf, p_hex_buf);
 
     if (CYBT_SUCCESS != ret) {
-        cybt_printf("hci_open(): FW download failed (0x%x)\n", ret);
+        cybt_error("hci_open(): FW download failed (0x%x)\n", ret);
         return CYBT_ERR_HCI_INIT_FAILED;
     }
 
@@ -161,7 +148,7 @@ int cyw43_btbus_init(cyw43_ll_t *self) {
     if (CYBT_SUCCESS == ret) {
         cybt_debug("hci_open(): FW download successfully\n");
     } else {
-        cybt_printf("hci_open(): Failed to download FW\n");
+        cybt_error("hci_open(): Failed to download FW\n");
         return CYBT_ERR_HCI_INIT_FAILED;
     }
 
@@ -182,7 +169,7 @@ int cyw43_btbus_init(cyw43_ll_t *self) {
     return CYBT_SUCCESS;
 }
 
-#if CYBT_VDEBUG
+#if 0
 static void dump_bytes(const uint8_t *bptr, uint32_t len) {
     unsigned int i = 0;
 
@@ -198,6 +185,9 @@ static void dump_bytes(const uint8_t *bptr, uint32_t len) {
     }
     printf("\n");
 }
+#define DUMP_BYTES dump_bytes
+#else
+#define DUMP_BYTES(...)
 #endif
 
 static cybt_result_t cybt_hci_write_buf(const uint8_t *p_data, uint32_t length) {
@@ -206,7 +196,7 @@ static cybt_result_t cybt_hci_write_buf(const uint8_t *p_data, uint32_t length)
 
     assert(ISALIGNED(p_data, 4));
     if (!ISALIGNED(p_data, 4)) {
-        cybt_printf("cybt_hci_write_hdr: buffer not aligned\n");
+        cybt_error("cybt_hci_write_hdr: buffer not aligned\n");
         return CYBT_ERR_BADARG;
     }
 
@@ -260,7 +250,7 @@ static cybt_result_t cybt_hci_read(uint8_t *p_data, uint32_t *p_length) {
     assert(ISALIGNED(p_data, 4));
     if (!ISALIGNED(p_data, 4)) {
         assert(false);
-        cybt_printf("cybt_hci_read: buffer not aligned\n");
+        cybt_error("cybt_hci_read: buffer not aligned\n");
         return CYBT_ERR_BADARG;
     }
 
@@ -272,9 +262,9 @@ static cybt_result_t cybt_hci_read(uint8_t *p_data, uint32_t *p_length) {
     cybt_debug("cybt_hci_read: bt2host_in_val=%lu bt2host_out_val=%lu fw_b2h_buf_count=%ld\n",
                fw_membuf_info.bt2host_in_val, fw_membuf_info.bt2host_out_val, fw_b2h_buf_count);
     if (fw_b2h_buf_count < available) {
-        cybt_printf("error: cybt_hci_read buffer overflow fw_b2h_buf_count=%ld available=%lu\n", fw_b2h_buf_count,
+        cybt_error("error: cybt_hci_read buffer overflow fw_b2h_buf_count=%ld available=%lu\n", fw_b2h_buf_count,
                     available);
-        cybt_printf("error: cybt_hci_read bt2host_in_val=%lu bt2host_out_val=%lu\n", fw_membuf_info.bt2host_in_val,
+        cybt_error("error: cybt_hci_read bt2host_in_val=%lu bt2host_out_val=%lu\n", fw_membuf_info.bt2host_in_val,
                     fw_membuf_info.bt2host_out_val);
         panic("cyw43 buffer overflow");
     }
@@ -355,9 +345,7 @@ int cyw43_btbus_write(uint8_t *buf, uint32_t size) {
     cybt_bus_request();
 
     cybt_debug("cyw43_btbus_write: %d\n", cmd_len);
-#if CYBT_VDEBUG
-    dump_bytes(buf, size); // dump header and data
-#endif
+    DUMP_BYTES(buf, size); // dump header and data
 
     cybt_hci_write_buf(buf, size);
     cybt_bus_release();
@@ -376,7 +364,7 @@ static bool cybt_hci_read_packet(uint8_t *buf, uint32_t max_buf_size, uint32_t *
 
     if (bt_result != CYBT_SUCCESS) {
         *size = 0;
-        cybt_printf("cybt_hci_read_packet: error %d", bt_result);
+        cybt_error("cybt_hci_read_packet: error %d", bt_result);
         return true;
     }
 
@@ -390,7 +378,7 @@ static bool cybt_hci_read_packet(uint8_t *buf, uint32_t max_buf_size, uint32_t *
     uint32_t hci_read_len = ((buf[2] << 16) & 0xFFFF00) | ((buf[1] << 8) & 0xFF00) | (buf[0] & 0xFF);
     if (hci_read_len > max_buf_size - 4) {
         *size = 0;
-        cybt_printf("cybt_hci_read_packet: too much data len %" PRId32"\n", hci_read_len);
+        cybt_error("cybt_hci_read_packet: too much data len %" PRId32"\n", hci_read_len);
         assert(false);
         return false;
     }
@@ -401,7 +389,7 @@ static bool cybt_hci_read_packet(uint8_t *buf, uint32_t max_buf_size, uint32_t *
     bt_result = cybt_hci_read(buf + 4, &total_read_len);
     if (bt_result != CYBT_SUCCESS) {
         *size = 0;
-        cybt_printf("cybt_hci_read_packet: read failed\n");
+        cybt_error("cybt_hci_read_packet: read failed\n");
         assert(false);
         return false;
     }
@@ -413,15 +401,13 @@ static bool cybt_hci_read_packet(uint8_t *buf, uint32_t max_buf_size, uint32_t *
     } else {
         assert(total_read_len > 0);
         *size = total_read_len + 4;
-        cybt_printf("cybt_hci_read_packet: failed to read all data %lu < %lu\n", total_read_len, hci_read_len);
+        cybt_error("cybt_hci_read_packet: failed to read all data %lu < %lu\n", total_read_len, hci_read_len);
         //assert(false);
         return true;
     }
 
     cybt_debug("cybt_hci_read_packet: %ld\n", *size);
-#if CYBT_VDEBUG
-    dump_bytes(buf, *size);
-#endif
+    DUMP_BYTES(buf, *size);
 
     return true;
 }

src/rp2_common/pico_cyw43_driver/cybt_shared_bus/cybt_shared_bus_driver.c

@@ -11,6 +11,7 @@
 
 #include "cyw43_ll.h"
 #include "cybt_shared_bus_driver.h"
+#include "cybt_logging.h"
 
 // Bluetooth register corruption occurs if both wifi and bluetooth are fully utilised.
 #define CYBT_CORRUPTION_TEST 1
@@ -23,23 +24,6 @@ static uint32_t last_bt_ctrl_reg;
 
 #endif
 
-#ifndef NDEBUG
-#define cybt_printf(format, args ...) printf(format,##args)
-#else
-#define cybt_printf(...)
-#endif
-
-#ifndef CYBT_DEBUG
-#define CYBT_DEBUG 0
-#endif
-
-#if CYBT_DEBUG
-#include <stdio.h>
-#define cybt_debug(format, args ...) printf(format,##args)
-#else
-#define cybt_debug(format, ...) ((void)0)
-#endif
-
 
 /******************************************************************************
  *                                Constants
@@ -319,7 +303,7 @@ cybt_result_t cybt_fw_download(const uint8_t *p_bt_firmware,
     uint8_t version_len = *p_bt_firmware;
     assert(*(p_bt_firmware + version_len) == 0);
 #ifndef NDEBUG
-    cybt_printf("BT FW download, version = %s\n", p_bt_firmware + 1);
+    cybt_info("BT FW download, version = %s\n", p_bt_firmware + 1);
 #endif
     p_bt_firmware += version_len + 1; // skip over version
     p_bt_firmware += 1; // skip over record count
@@ -409,7 +393,7 @@ cybt_result_t cybt_toggle_bt_intr(void) {
     cybt_reg_read(HOST_CTRL_REG_ADDR, &reg_val);
 #if CYBT_CORRUPTION_TEST
     if ((reg_val & ~(BTSDIO_REG_SW_RDY_BITMASK | BTSDIO_REG_WAKE_BT_BITMASK | BTSDIO_REG_DATA_VALID_BITMASK)) != 0) {
-        cybt_printf("cybt_toggle_bt_intr read HOST_CTRL_REG_ADDR as 0x%08lx\n", reg_val);
+        cybt_error("cybt_toggle_bt_intr read HOST_CTRL_REG_ADDR as 0x%08lx\n", reg_val);
         cybt_debug_dump();
         panic("cyw43 btsdio register corruption");
     }
@@ -485,32 +469,32 @@ void cybt_debug_dump(void) {
     uint32_t reg_val = 0;
     cybt_fw_membuf_index_t buf_index;
 
-    cybt_printf("WLAN_RAM_BASE_ADDR: 0x%08lx\n", WLAN_RAM_BASE_ADDR);
-    cybt_printf("H2B_BUF_ADDR: 0x%08lx\n", H2B_BUF_ADDR);
-    cybt_printf("B2H_BUF_ADDR: 0x%08lx\n", B2H_BUF_ADDR);
+    cybt_debug("WLAN_RAM_BASE_ADDR: 0x%08lx\n", WLAN_RAM_BASE_ADDR);
+    cybt_debug("H2B_BUF_ADDR: 0x%08lx\n", H2B_BUF_ADDR);
+    cybt_debug("B2H_BUF_ADDR: 0x%08lx\n", B2H_BUF_ADDR);
 
     cybt_reg_read(H2B_BUF_IN_ADDR, &buf_index.host2bt_in_val);
-    cybt_printf("H2B_BUF_IN_ADDR: 0x%08lx = 0x%08lx (last 0x%08lx)\n", H2B_BUF_IN_ADDR, buf_index.host2bt_in_val,
+    cybt_debug("H2B_BUF_IN_ADDR: 0x%08lx = 0x%08lx (last 0x%08lx)\n", H2B_BUF_IN_ADDR, buf_index.host2bt_in_val,
                 last_buf_index.host2bt_in_val);
 
     cybt_reg_read(H2B_BUF_OUT_ADDR, &buf_index.host2bt_out_val);
-    cybt_printf("H2B_BUF_OUT_ADDR: 0x%08lx = 0x%08lx (last 0x%08lx)\n", H2B_BUF_OUT_ADDR, buf_index.host2bt_out_val,
+    cybt_debug("H2B_BUF_OUT_ADDR: 0x%08lx = 0x%08lx (last 0x%08lx)\n", H2B_BUF_OUT_ADDR, buf_index.host2bt_out_val,
                 last_buf_index.host2bt_out_val);
 
     cybt_reg_read(B2H_BUF_IN_ADDR, &buf_index.bt2host_in_val);
-    cybt_printf("B2H_BUF_IN_ADDR: 0x%08lx = 0x%08lx (last 0x%08lx)\n", B2H_BUF_IN_ADDR, buf_index.bt2host_in_val,
+    cybt_debug("B2H_BUF_IN_ADDR: 0x%08lx = 0x%08lx (last 0x%08lx)\n", B2H_BUF_IN_ADDR, buf_index.bt2host_in_val,
                 last_buf_index.bt2host_in_val);
 
     cybt_reg_read(B2H_BUF_OUT_ADDR, &buf_index.bt2host_out_val);
-    cybt_printf("B2H_BUF_OUT_ADDR: 0x%08lx = 0x%08lx (last 0x%08lx)\n", B2H_BUF_OUT_ADDR, buf_index.bt2host_out_val,
+    cybt_debug("B2H_BUF_OUT_ADDR: 0x%08lx = 0x%08lx (last 0x%08lx)\n", B2H_BUF_OUT_ADDR, buf_index.bt2host_out_val,
                 last_buf_index.bt2host_out_val);
 
     cybt_reg_read(HOST_CTRL_REG_ADDR, &reg_val);
-    cybt_printf("HOST_CTRL_REG_ADDR: 0x%08lx = 0x%08lx (last 0x%08lx)\n", HOST_CTRL_REG_ADDR, reg_val,
+    cybt_debug("HOST_CTRL_REG_ADDR: 0x%08lx = 0x%08lx (last 0x%08lx)\n", HOST_CTRL_REG_ADDR, reg_val,
                 last_host_ctrl_reg);
 
     cybt_reg_read(BT_CTRL_REG_ADDR, &reg_val);
-    cybt_printf("BT_CTRL_REG_ADDR: 0x%08lx = 0x%08lx (last 0x%08lx)\n", BT_CTRL_REG_ADDR, reg_val, last_bt_ctrl_reg);
+    cybt_debug("BT_CTRL_REG_ADDR: 0x%08lx = 0x%08lx (last 0x%08lx)\n", BT_CTRL_REG_ADDR, reg_val, last_bt_ctrl_reg);
 #endif
 }
 
@@ -533,7 +517,7 @@ cybt_result_t cybt_get_bt_buf_index(cybt_fw_membuf_index_t *p_buf_index) {
 #if CYBT_CORRUPTION_TEST
     if (p_buf_index->host2bt_in_val >= BTSDIO_FWBUF_SIZE || p_buf_index->host2bt_out_val >= BTSDIO_FWBUF_SIZE ||
         p_buf_index->bt2host_in_val >= BTSDIO_FWBUF_SIZE || p_buf_index->bt2host_out_val >= BTSDIO_FWBUF_SIZE) {
-        cybt_printf("cybt_get_bt_buf_index invalid buffer value\n");
+        cybt_error("cybt_get_bt_buf_index invalid buffer value\n");
         cybt_debug_dump();
     } else {
         memcpy((uint8_t *) &last_buf_index, (uint8_t *) p_buf_index, sizeof(cybt_fw_membuf_index_t));
@@ -567,7 +551,7 @@ static cybt_result_t cybt_reg_read(uint32_t reg_addr, uint32_t *p_value) {
     return CYBT_SUCCESS;
 }
 
-#if CYBT_DEBUG
+#if 0
 static void dump_bytes(const uint8_t *bptr, uint32_t len) {
     unsigned int i = 0;