Bluetooth: Conditionally print out HCI error codes as strings

When developing Bluetooth applications, you typically run into some errors. If you are an experienced Bluetooth developer, you would typically have an HCI error lookup table in your memory. Others might not. This commit utilizes defines CONFIG_BT_DEBUG_HCI_ERR_TO_STR and utilizes bt_hci_err_to_str() to print out HCI error strings when enabled to improve the user experience. Several alternatives where considered. This approach was chosen as it had the best balance between readability, code size, and implementation complexity. The alternatives are listed below as a reference. 1. Macro defined format specifier: ```c #define HCI_ERR_FMT "%s" #define BT_HCI_ERR_TO_STR(err) (err) #define HCI_ERR_FMT "%d" #define BT_HCI_ERR_TO_STR(err) bt_hci_err_to_str((err)) LOG_INF("The event contained " HCI_ERR_FMT " as status", BT_HCI_ERR_TO_STR(err)); ``` Advantage: Space efficient: Code size does not increase Disadvantage: Code becomes hard to read 2. Format specifier to always include both integer and string: ```c static inline const char bt_hci_err_to_str(err) { return ""; } LOG_INF("The event contained %s(0x%02x) as status", bt_hci_err_to_str(err), err); ``` Advantage: Simple to use, implement, and read, Disadvantage: Increases code size when CONFIG_BT_DEBUG_HCI_ERR_TO_STR is disabled. The compiler seems unable to optimize away the unused format specifier. Note: The size increase is only present when logging is enabled. 3. Always print as string, allocate a stack variable when printing: ```c const char *bt_hci_err_to_str(char *dst, size_t dst_size, uint8_t err) { snprintf(dst, dst_size, 0x%02x, err); return dst; } LOG_INF("The event contained %s as status", BT_HCI_ERR_TO_STR(err)); ``` Advantage: Very easy to read. Disadvantage: Printing error codes becomes slow as it involves calling snprint. 4. Implement a custom printf specifier, for example E. This requires a global CONFIG_ERR_AS_STR as I assume we cannot have one specifier for each type of error code. Also, I assume we cannot start adding specifiers for each subsystem. ```c #define BT_HCI_ERR_TO_STR(err) (err) #define BT_HCI_ERR_TO_STR(err) bt_hci_err_to_str((err)) LOG_INF("The event contained %E as status", BT_HCI_ERR_TO_STR(err)); ``` Advantage: Both efficient code and readable code. Disadvantage: This requires a global CONFIG_ERR_AS_STR as I assume we cannot have one specifier for each type of error code. Also, I assume we cannot start adding specifiers for each subsystem. That is, this approach is hard to implement correctly in a scalable way. Signed-off-by: Rubin Gerritsen <rubin.gerritsen@nordicsemi.no>
2024-06-20 13:47:32 +02:00 · 2024-06-20 13:47:32 +02:00 · bfc0cdc905
commit bfc0cdc905
parent a94bfe03a4
9 changed files with 54 additions and 36 deletions
--- a/subsys/bluetooth/host/adv.c
+++ b/subsys/bluetooth/host/adv.c
@ -2153,7 +2153,8 @@ void bt_hci_le_adv_set_terminated(struct net_buf *buf)
 	adv = bt_hci_adv_lookup_handle(evt->adv_handle);
 	conn_handle = sys_le16_to_cpu(evt->conn_handle);

-	LOG_DBG("status 0x%02x adv_handle %u conn_handle 0x%02x num %u", evt->status,
+	LOG_DBG("status 0x%02x %s adv_handle %u conn_handle 0x%02x num %u",
+		evt->status, bt_hci_err_to_str(evt->status),
 		evt->adv_handle, conn_handle, evt->num_completed_ext_adv_evts);

 	if (!adv) {
--- a/subsys/bluetooth/host/att.c
+++ b/subsys/bluetooth/host/att.c
@ -3237,8 +3237,8 @@ static void bt_att_encrypt_change(struct bt_l2cap_chan *chan,
 	struct bt_conn *conn = le_chan->chan.conn;
 	uint8_t err;

-	LOG_DBG("chan %p conn %p handle %u sec_level 0x%02x status 0x%02x", le_chan, conn,
-		conn->handle, conn->sec_level, hci_status);
+	LOG_DBG("chan %p conn %p handle %u sec_level 0x%02x status 0x%02x %s", le_chan, conn,
+		conn->handle, conn->sec_level, hci_status, bt_hci_err_to_str(hci_status));

 	if (!att_chan->att) {
 		LOG_DBG("Ignore encrypt change on detached ATT chan");
--- a/subsys/bluetooth/host/ecc.c
+++ b/subsys/bluetooth/host/ecc.c
@ -207,7 +207,7 @@ void bt_hci_evt_le_pkey_complete(struct net_buf *buf)
 	struct bt_hci_evt_le_p256_public_key_complete *evt = (void *)buf->data;
 	struct bt_pub_key_cb *cb;

-	LOG_DBG("status: 0x%02x", evt->status);
+	LOG_DBG("status: 0x%02x %s", evt->status, bt_hci_err_to_str(evt->status));

 	atomic_clear_bit(bt_dev.flags, BT_DEV_PUB_KEY_BUSY);

@ -229,7 +229,7 @@ void bt_hci_evt_le_dhkey_complete(struct net_buf *buf)
 {
 	struct bt_hci_evt_le_generate_dhkey_complete *evt = (void *)buf->data;

-	LOG_DBG("status: 0x%02x", evt->status);
+	LOG_DBG("status: 0x%02x %s", evt->status, bt_hci_err_to_str(evt->status));

 	if (dh_key_cb) {
 		bt_dh_key_cb_t cb = dh_key_cb;
--- a/subsys/bluetooth/host/hci_core.c
+++ b/subsys/bluetooth/host/hci_core.c
@ -432,7 +432,8 @@ int bt_hci_cmd_send_sync(uint16_t opcode, struct net_buf *buf,

 	status = cmd(buf)->status;
 	if (status) {
-		LOG_WRN("opcode 0x%04x status 0x%02x", opcode, status);
+		LOG_WRN("opcode 0x%04x status 0x%02x %s", opcode,
+			status, bt_hci_err_to_str(status));
 		net_buf_unref(buf);

 		switch (status) {
@ -944,7 +945,8 @@ static void hci_disconn_complete_prio(struct net_buf *buf)
 	uint16_t handle = sys_le16_to_cpu(evt->handle);
 	struct bt_conn *conn;

-	LOG_DBG("status 0x%02x handle %u reason 0x%02x", evt->status, handle, evt->reason);
+	LOG_DBG("status 0x%02x %s handle %u reason 0x%02x",
+		evt->status, bt_hci_err_to_str(evt->status), handle, evt->reason);

 	if (evt->status) {
 		return;
@ -971,7 +973,8 @@ static void hci_disconn_complete(struct net_buf *buf)
 	uint16_t handle = sys_le16_to_cpu(evt->handle);
 	struct bt_conn *conn;

-	LOG_DBG("status 0x%02x handle %u reason 0x%02x", evt->status, handle, evt->reason);
+	LOG_DBG("status 0x%02x %s handle %u reason 0x%02x",
+		evt->status, bt_hci_err_to_str(evt->status), handle, evt->reason);

 	if (evt->status) {
 		return;
@ -1404,7 +1407,8 @@ void bt_hci_le_enh_conn_complete(struct bt_hci_evt_le_enh_conn_complete *evt)
 	struct bt_conn *conn;
 	uint8_t id;

-	LOG_DBG("status 0x%02x handle %u role %u peer %s peer RPA %s", evt->status, handle,
+	LOG_DBG("status 0x%02x %s handle %u role %u peer %s peer RPA %s",
+		evt->status, bt_hci_err_to_str(evt->status), handle,
 		evt->role, bt_addr_le_str(&evt->peer_addr), bt_addr_str(&evt->peer_rpa));
 	LOG_DBG("local RPA %s", bt_addr_str(&evt->local_rpa));

@ -1587,7 +1591,8 @@ void bt_hci_le_enh_conn_complete_sync(struct bt_hci_evt_le_enh_conn_complete_v2
 		return;
 	}

-	LOG_DBG("status 0x%02x handle %u role %u peer %s peer RPA %s", evt->status, handle,
+	LOG_DBG("status 0x%02x %s handle %u role %u peer %s peer RPA %s",
+		evt->status, bt_hci_err_to_str(evt->status), handle,
 		evt->role, bt_addr_le_str(&evt->peer_addr), bt_addr_str(&evt->peer_rpa));
 	LOG_DBG("local RPA %s", bt_addr_str(&evt->local_rpa));

@ -1665,7 +1670,7 @@ static void enh_conn_complete_error_handle(uint8_t status)
 		return;
 	}

-	LOG_WRN("Unexpected status 0x%02x", status);
+	LOG_WRN("Unexpected status 0x%02x %s", status, bt_hci_err_to_str(status));
 }

 static void le_enh_conn_complete(struct net_buf *buf)
@ -1736,7 +1741,8 @@ static void le_legacy_conn_complete(struct net_buf *buf)
 		return;
 	}

-	LOG_DBG("status 0x%02x role %u %s", evt->status, evt->role,
+	LOG_DBG("status 0x%02x %s role %u %s",
+		evt->status, bt_hci_err_to_str(evt->status), evt->role,
 		bt_addr_le_str(&evt->peer_addr));

 	enh.status         = evt->status;
@ -1846,7 +1852,8 @@ static void le_phy_update_complete(struct net_buf *buf)
 		return;
 	}

-	LOG_DBG("PHY updated: status: 0x%02x, tx: %u, rx: %u", evt->status, evt->tx_phy,
+	LOG_DBG("PHY updated: status: 0x%02x %s, tx: %u, rx: %u",
+		evt->status, bt_hci_err_to_str(evt->status), evt->tx_phy,
 		evt->rx_phy);

 #if defined(CONFIG_BT_USER_PHY_UPDATE)
@ -1964,7 +1971,8 @@ static void le_conn_update_complete(struct net_buf *buf)

 	handle = sys_le16_to_cpu(evt->handle);

-	LOG_DBG("status 0x%02x, handle %u", evt->status, handle);
+	LOG_DBG("status 0x%02x %s, handle %u",
+		evt->status, bt_hci_err_to_str(evt->status), handle);

 	conn = bt_conn_lookup_handle(handle, BT_CONN_TYPE_LE);
 	if (!conn) {
@ -2184,7 +2192,8 @@ static void hci_encrypt_change(struct net_buf *buf)
 	uint8_t status = evt->status;
 	struct bt_conn *conn;

-	LOG_DBG("status 0x%02x handle %u encrypt 0x%02x", evt->status, handle, evt->encrypt);
+	LOG_DBG("status 0x%02x %s handle %u encrypt 0x%02x",
+		evt->status, bt_hci_err_to_str(evt->status), handle, evt->encrypt);

 	conn = bt_conn_lookup_handle(handle, BT_CONN_TYPE_ALL);
 	if (!conn) {
@ -2265,7 +2274,8 @@ static void hci_encrypt_key_refresh_complete(struct net_buf *buf)

 	handle = sys_le16_to_cpu(evt->handle);

-	LOG_DBG("status 0x%02x handle %u", evt->status, handle);
+	LOG_DBG("status 0x%02x %s handle %u",
+		evt->status, bt_hci_err_to_str(evt->status), handle);

 	conn = bt_conn_lookup_handle(handle, BT_CONN_TYPE_ALL);
 	if (!conn) {
@ -2425,7 +2435,7 @@ static void hci_reset_complete(struct net_buf *buf)
 	uint8_t status = buf->data[0];
 	atomic_t flags;

-	LOG_DBG("status 0x%02x", status);
+	LOG_DBG("status 0x%02x %s", status, bt_hci_err_to_str(status));

 	if (status) {
 		return;
@ -2448,7 +2458,8 @@ static void hci_cmd_done(uint16_t opcode, uint8_t status, struct net_buf *evt_bu
 	/* Original command buffer. */
 	struct net_buf *buf = NULL;

-	LOG_DBG("opcode 0x%04x status 0x%02x buf %p", opcode, status, evt_buf);
+	LOG_DBG("opcode 0x%04x status 0x%02x %s buf %p", opcode,
+		status, bt_hci_err_to_str(status), evt_buf);

 	/* Unsolicited cmd complete. This does not complete a command.
 	 * The controller can send these for effect of the `ncmd` field.
@ -2523,7 +2534,8 @@ static void hci_cmd_complete(struct net_buf *buf)
 	 * The generation of this command ignores `ncmd_sem`, so should not be given here.
 	 */
 	if (opcode == BT_HCI_OP_HOST_NUM_COMPLETED_PACKETS) {
-		LOG_WRN("Unexpected HOST_NUM_COMPLETED_PACKETS (status 0x%02x)", status);
+		LOG_WRN("Unexpected HOST_NUM_COMPLETED_PACKETS, status 0x%02x %s",
+			status, bt_hci_err_to_str(status));
 		return;
 	}

@ -3033,7 +3045,7 @@ static void read_local_ver_complete(struct net_buf *buf)
 {
 	struct bt_hci_rp_read_local_version_info *rp = (void *)buf->data;

-	LOG_DBG("status 0x%02x", rp->status);
+	LOG_DBG("status 0x%02x %s", rp->status, bt_hci_err_to_str(rp->status));

 	bt_dev.hci_version = rp->hci_version;
 	bt_dev.hci_revision = sys_le16_to_cpu(rp->hci_revision);
@ -3046,7 +3058,7 @@ static void read_le_features_complete(struct net_buf *buf)
 {
 	struct bt_hci_rp_le_read_local_features *rp = (void *)buf->data;

-	LOG_DBG("status 0x%02x", rp->status);
+	LOG_DBG("status 0x%02x %s", rp->status, bt_hci_err_to_str(rp->status));

 	memcpy(bt_dev.le.features, rp->features, sizeof(bt_dev.le.features));
 }
@ -3058,7 +3070,7 @@ static void read_buffer_size_complete(struct net_buf *buf)
 	struct bt_hci_rp_read_buffer_size *rp = (void *)buf->data;
 	uint16_t pkts;

-	LOG_DBG("status 0x%02x", rp->status);
+	LOG_DBG("status 0x%02x %s", rp->status, bt_hci_err_to_str(rp->status));

 	/* If LE-side has buffers we can ignore the BR/EDR values */
 	if (bt_dev.le.acl_mtu) {
@ -3079,7 +3091,7 @@ static void le_read_buffer_size_complete(struct net_buf *buf)
 {
 	struct bt_hci_rp_le_read_buffer_size *rp = (void *)buf->data;

-	LOG_DBG("status 0x%02x", rp->status);
+	LOG_DBG("status 0x%02x %s", rp->status, bt_hci_err_to_str(rp->status));

 #if defined(CONFIG_BT_CONN)
 	uint16_t acl_mtu = sys_le16_to_cpu(rp->le_max_len);
@ -3101,7 +3113,7 @@ static void read_buffer_size_v2_complete(struct net_buf *buf)
 #if defined(CONFIG_BT_ISO)
 	struct bt_hci_rp_le_read_buffer_size_v2 *rp = (void *)buf->data;

-	LOG_DBG("status %u", rp->status);
+	LOG_DBG("status %u %s", rp->status, bt_hci_err_to_str(rp->status));

 #if defined(CONFIG_BT_CONN)
 	uint16_t acl_mtu = sys_le16_to_cpu(rp->acl_max_len);
@ -3151,7 +3163,7 @@ static void read_supported_commands_complete(struct net_buf *buf)
 {
 	struct bt_hci_rp_read_supported_commands *rp = (void *)buf->data;

-	LOG_DBG("status 0x%02x", rp->status);
+	LOG_DBG("status 0x%02x %s", rp->status, bt_hci_err_to_str(rp->status));

 	memcpy(bt_dev.supported_commands, rp->commands,
 	       sizeof(bt_dev.supported_commands));
@ -3168,7 +3180,7 @@ static void read_local_features_complete(struct net_buf *buf)
 {
 	struct bt_hci_rp_read_local_features *rp = (void *)buf->data;

-	LOG_DBG("status 0x%02x", rp->status);
+	LOG_DBG("status 0x%02x %s", rp->status, bt_hci_err_to_str(rp->status));

 	memcpy(bt_dev.features[0], rp->features, sizeof(bt_dev.features[0]));
 }
@ -3177,7 +3189,7 @@ static void le_read_supp_states_complete(struct net_buf *buf)
 {
 	struct bt_hci_rp_le_read_supp_states *rp = (void *)buf->data;

-	LOG_DBG("status 0x%02x", rp->status);
+	LOG_DBG("status 0x%02x %s", rp->status, bt_hci_err_to_str(rp->status));

 	bt_dev.le.states = sys_get_le64(rp->le_states);
 }
@ -3187,7 +3199,7 @@ static void le_read_maximum_adv_data_len_complete(struct net_buf *buf)
 {
 	struct bt_hci_rp_le_read_max_adv_data_len *rp = (void *)buf->data;

-	LOG_DBG("status 0x%02x", rp->status);
+	LOG_DBG("status 0x%02x %s", rp->status, bt_hci_err_to_str(rp->status));

 	bt_dev.le.max_adv_data_len = sys_le16_to_cpu(rp->max_adv_data_len);
 }
--- a/subsys/bluetooth/host/hci_ecc.c
+++ b/subsys/bluetooth/host/hci_ecc.c
@ -88,7 +88,7 @@ static void send_cmd_status(uint16_t opcode, uint8_t status)
 	struct bt_hci_evt_hdr *hdr;
 	struct net_buf *buf;

-	LOG_DBG("opcode %x status %x", opcode, status);
+	LOG_DBG("opcode %x status 0x%02x %s", opcode, status, bt_hci_err_to_str(status));

 	buf = bt_buf_get_evt(BT_HCI_EVT_CMD_STATUS, false, K_FOREVER);
 	bt_buf_set_type(buf, BT_BUF_EVT);
--- a/subsys/bluetooth/host/iso.c
+++ b/subsys/bluetooth/host/iso.c
@ -1162,7 +1162,7 @@ void hci_le_cis_established(struct net_buf *buf)
 	uint16_t handle = sys_le16_to_cpu(evt->conn_handle);
 	struct bt_conn *iso;

-	LOG_DBG("status 0x%02x handle %u", evt->status, handle);
+	LOG_DBG("status 0x%02x %s handle %u", evt->status, bt_hci_err_to_str(evt->status), handle);

 	/* ISO connection handles are already assigned at this point */
 	iso = bt_conn_lookup_handle(handle, BT_CONN_TYPE_ISO);
@ -2334,7 +2334,8 @@ void bt_iso_security_changed(struct bt_conn *acl, uint8_t hci_status)
 			param[param_count].iso_chan = iso_chan;
 			param_count++;
 		} else {
-			LOG_DBG("Failed to encrypt ACL %p for ISO %p: %u", acl, iso, hci_status);
+			LOG_DBG("Failed to encrypt ACL %p for ISO %p: %u %s",
+				acl, iso, hci_status, bt_hci_err_to_str(hci_status));

 			/* We utilize the disconnected callback to make the
 			 * upper layers aware of the error
@ -3053,7 +3054,8 @@ void hci_le_big_complete(struct net_buf *buf)
 	big = lookup_big_by_handle(evt->big_handle);
 	atomic_clear_bit(big->flags, BT_BIG_PENDING);

-	LOG_DBG("BIG[%u] %p completed, status 0x%02x", big->handle, big, evt->status);
+	LOG_DBG("BIG[%u] %p completed, status 0x%02x %s",
+		big->handle, big, evt->status, bt_hci_err_to_str(evt->status));

 	if (evt->status || evt->num_bis != big->num_bis) {
 		if (evt->status == BT_HCI_ERR_SUCCESS && evt->num_bis != big->num_bis) {
@ -3227,7 +3229,8 @@ void hci_le_big_sync_established(struct net_buf *buf)
 	big = lookup_big_by_handle(evt->big_handle);
 	atomic_clear_bit(big->flags, BT_BIG_SYNCING);

-	LOG_DBG("BIG[%u] %p sync established, status 0x%02x", big->handle, big, evt->status);
+	LOG_DBG("BIG[%u] %p sync established, status 0x%02x %s",
+		big->handle, big, evt->status, bt_hci_err_to_str(evt->status));

 	if (evt->status || evt->num_bis != big->num_bis) {
 		if (evt->status == BT_HCI_ERR_SUCCESS && evt->num_bis != big->num_bis) {
--- a/subsys/bluetooth/host/scan.c
+++ b/subsys/bluetooth/host/scan.c
@ -1263,7 +1263,8 @@ static void bt_hci_le_past_received_common(struct net_buf *buf)

 	if (evt->status) {
 		/* No sync created, don't notify app */
-		LOG_DBG("PAST receive failed with status 0x%02X", evt->status);
+		LOG_DBG("PAST receive failed with status 0x%02X %s",
+			evt->status, bt_hci_err_to_str(evt->status));
 		return;
 	}

--- a/subsys/bluetooth/host/smp.c
+++ b/subsys/bluetooth/host/smp.c
@ -4702,8 +4702,8 @@ static void bt_smp_encrypt_change(struct bt_l2cap_chan *chan,
 	struct bt_smp *smp = CONTAINER_OF(chan, struct bt_smp, chan.chan);
 	struct bt_conn *conn = chan->conn;

-	LOG_DBG("chan %p conn %p handle %u encrypt 0x%02x hci status 0x%02x", chan, conn,
-		conn->handle, conn->encrypt, hci_status);
+	LOG_DBG("chan %p conn %p handle %u encrypt 0x%02x hci status 0x%02x %s", chan, conn,
+		conn->handle, conn->encrypt, hci_status, bt_hci_err_to_str(hci_status));

 	if (!atomic_test_and_clear_bit(smp->flags, SMP_FLAG_ENC_PENDING)) {
 		/* We where not waiting for encryption procedure.
--- a/tests/bluetooth/hci/prj.conf
+++ b/tests/bluetooth/hci/prj.conf
@ -2,6 +2,7 @@ CONFIG_TEST=y
 CONFIG_ZTEST=y

 CONFIG_BT=y
+CONFIG_BT_HCI_ERR_TO_STR=y
 CONFIG_BT_CTLR=n
 CONFIG_BT_H4=n
 CONFIG_BT_HCI_ERR_TO_STR=y