Add more details in native Bluetooth debug logs

As part of debugging a security/pairing issue, these logs are modified
to give better debug information.

Test: compiled
Bug: 71364658
Change-Id: I742cc7dda0afc6350e881c22d03bdc1c69d37d88

diff --git a/btif/src/btif_dm.cc b/btif/src/btif_dm.cc
index 8926670..42b5854 100644 (file)
--- a/btif/src/btif_dm.cc
+++ b/btif/src/btif_dm.cc
@@ -1047,7 +1047,9 @@ static void btif_dm_auth_cmpl_evt(tBTA_DM_AUTH_CMPL* p_auth_cmpl) {
   bt_bond_state_t state = BT_BOND_STATE_NONE;
   bool skip_sdp = false;
 
-  BTIF_TRACE_DEBUG("%s: bond state=%d", __func__, pairing_cb.state);
+  BTIF_TRACE_DEBUG("%s: bond state=%d, success=%d, key_present=%d", __func__,
+                   pairing_cb.state, p_auth_cmpl->success,
+                   p_auth_cmpl->key_present);
 
   RawAddress bd_addr = p_auth_cmpl->bd_addr;
   if ((p_auth_cmpl->success) && (p_auth_cmpl->key_present)) {
@@ -2483,7 +2485,8 @@ bt_status_t btif_dm_get_remote_services(const RawAddress& remote_addr) {
  ******************************************************************************/
 bt_status_t btif_dm_get_remote_services_by_transport(RawAddress* remote_addr,
                                                      const int transport) {
-  BTIF_TRACE_EVENT("%s", __func__);
+  BTIF_TRACE_EVENT("%s: transport=%d, remote_addr=%s", __func__, transport,
+                   remote_addr->ToString().c_str());
 
   /* Set the mask extension */
   tBTA_SERVICE_MASK_EXT mask_ext;

diff --git a/stack/btm/btm_ble.cc b/stack/btm/btm_ble.cc
index f013a03..1f16c1e 100644 (file)
--- a/stack/btm/btm_ble.cc
+++ b/stack/btm/btm_ble.cc
@@ -89,8 +89,9 @@ bool BTM_SecAddBleDevice(const RawAddress& bd_addr, BD_NAME bd_name,
     p_dev_rec->conn_params.supervision_tout = BTM_BLE_CONN_PARAM_UNDEF;
     p_dev_rec->conn_params.slave_latency = BTM_BLE_CONN_PARAM_UNDEF;
 
-    BTM_TRACE_DEBUG("%s: Device added, handle=0x%x ", __func__,
-                    p_dev_rec->ble_hci_handle);
+    BTM_TRACE_DEBUG("%s: Device added, handle=0x%x, p_dev_rec=%p, bd_addr=%s",
+                    __func__, p_dev_rec->ble_hci_handle, p_dev_rec,
+                    bd_addr.ToString().c_str());
   }
 
   memset(p_dev_rec->sec_bd_name, 0, sizeof(tBTM_BD_NAME));
@@ -1317,8 +1318,11 @@ void btm_sec_save_le_key(const RawAddress& bd_addr, tBTM_LE_KEY_TYPE key_type,
         p_rec->ble.static_addr = p_keys->pid_key.static_addr;
         p_rec->ble.static_addr_type = p_keys->pid_key.addr_type;
         p_rec->ble.key_type |= BTM_LE_KEY_PID;
-        BTM_TRACE_DEBUG("BTM_LE_KEY_PID key_type=0x%x save peer IRK",
-                        p_rec->ble.key_type);
+        BTM_TRACE_DEBUG(
+            "%s: BTM_LE_KEY_PID key_type=0x%x save peer IRK, change bd_addr=%s "
+            "to static_addr=%s",
+            __func__, p_rec->ble.key_type, p_rec->bd_addr.ToString().c_str(),
+            p_keys->pid_key.static_addr.ToString().c_str());
         /* update device record address as static address */
         p_rec->bd_addr = p_keys->pid_key.static_addr;
         /* combine DUMO device security record if needed */
@@ -1380,7 +1384,7 @@ void btm_sec_save_le_key(const RawAddress& bd_addr, tBTM_LE_KEY_TYPE key_type,
         return;
     }
 
-    VLOG(1) << "BLE key type 0x" << std::hex << key_type
+    VLOG(1) << "BLE key type 0x" << loghex(key_type)
             << " updated for BDA: " << bd_addr << " (btm_sec_save_le_key)";
 
     /* Notify the application that one of the BLE keys has been updated
@@ -1394,7 +1398,7 @@ void btm_sec_save_le_key(const RawAddress& bd_addr, tBTM_LE_KEY_TYPE key_type,
     return;
   }
 
-  LOG(WARNING) << "BLE key type 0x" << std::hex << key_type
+  LOG(WARNING) << "BLE key type 0x" << loghex(key_type)
                << " called for Unknown BDA or type: " << bd_addr
                << "(btm_sec_save_le_key)";
 
@@ -1866,13 +1870,15 @@ void btm_ble_connected(const RawAddress& bda, uint16_t handle, uint8_t enc_mode,
   */
   if (p_dev_rec) {
     VLOG(1) << __func__ << " Security Manager: handle:" << handle
-            << " enc_mode:" << enc_mode << "  bda: " << bda
-            << " RName: " << p_dev_rec->sec_bd_name;
+            << " enc_mode:" << loghex(enc_mode) << "  bda: " << bda
+            << " RName: " << p_dev_rec->sec_bd_name
+            << " p_dev_rec:" << p_dev_rec;
 
     BTM_TRACE_DEBUG("btm_ble_connected sec_flags=0x%x", p_dev_rec->sec_flags);
   } else {
     VLOG(1) << __func__ << " Security Manager: handle:" << handle
-            << " enc_mode:" << enc_mode << "  bda: " << bda;
+            << " enc_mode:" << loghex(enc_mode) << "  bda: " << bda
+            << " p_dev_rec:" << p_dev_rec;
   }
 
   if (!p_dev_rec) {

diff --git a/stack/btm/btm_dev.cc b/stack/btm/btm_dev.cc
index b024137..66382e8 100644 (file)
--- a/stack/btm/btm_dev.cc
+++ b/stack/btm/btm_dev.cc
@@ -68,6 +68,8 @@ bool BTM_SecAddDevice(const RawAddress& bd_addr, DEV_CLASS dev_class,
   tBTM_SEC_DEV_REC* p_dev_rec = btm_find_dev(bd_addr);
   if (!p_dev_rec) {
     p_dev_rec = btm_sec_allocate_dev_rec();
+    BTM_TRACE_API("%s: allocated p_dev_rec=%p, bd_addr=%s", __func__, p_dev_rec,
+                  bd_addr.ToString().c_str());
 
     p_dev_rec->bd_addr = bd_addr;
     p_dev_rec->hci_handle = BTM_GetHCIConnHandle(bd_addr, BT_TRANSPORT_BR_EDR);
@@ -225,10 +227,12 @@ char* BTM_SecReadDevName(const RawAddress& bd_addr) {
  ******************************************************************************/
 tBTM_SEC_DEV_REC* btm_sec_alloc_dev(const RawAddress& bd_addr) {
   tBTM_INQ_INFO* p_inq_info;
-  BTM_TRACE_EVENT("btm_sec_alloc_dev");
 
   tBTM_SEC_DEV_REC* p_dev_rec = btm_sec_allocate_dev_rec();
 
+  BTM_TRACE_EVENT("%s: allocated p_dev_rec=%p, bd_addr=%s", __func__, p_dev_rec,
+                  bd_addr.ToString().c_str());
+
   /* Check with the BT manager if details about remote device are known */
   /* outgoing connection */
   p_inq_info = BTM_InqDbRead(bd_addr);

diff --git a/stack/btm/btm_sec.cc b/stack/btm/btm_sec.cc
index c76dad6..bd88054 100644 (file)
--- a/stack/btm/btm_sec.cc
+++ b/stack/btm/btm_sec.cc
@@ -873,7 +873,8 @@ tBTM_STATUS btm_sec_bond_by_transport(const RawAddress& bd_addr,
   tACL_CONN* p = btm_bda_to_acl(bd_addr, transport);
   VLOG(1) << __func__ << " BDA: " << bd_addr;
 
-  BTM_TRACE_DEBUG("btm_sec_bond_by_transport: Transport used %d", transport);
+  BTM_TRACE_DEBUG("%s: Transport used %d, bd_addr=%s", __func__, transport,
+                  bd_addr.ToString().c_str());
 
   /* Other security process is in progress */
   if (btm_cb.pairing_state != BTM_PAIR_STATE_IDLE) {
@@ -1286,9 +1287,9 @@ tBTM_STATUS BTM_SetEncryption(const RawAddress& bd_addr,
 
   BTM_TRACE_API(
       "Security Manager: BTM_SetEncryption Handle:%d State:%d Flags:0x%x "
-      "Required:0x%x",
+      "Required:0x%x, p_dev_rec=%p, p_callback=%p",
       p_dev_rec->hci_handle, p_dev_rec->sec_state, p_dev_rec->sec_flags,
-      p_dev_rec->security_required);
+      p_dev_rec->security_required, p_dev_rec, p_callback);
 
   if (transport == BT_TRANSPORT_LE) {
     tACL_CONN* p = btm_bda_to_acl(bd_addr, transport);
@@ -1305,6 +1306,11 @@ tBTM_STATUS BTM_SetEncryption(const RawAddress& bd_addr,
 
   if (rc != BTM_CMD_STARTED && rc != BTM_BUSY) {
     if (p_callback) {
+      BTM_TRACE_DEBUG(
+          "%s: clearing p_callback=%p, p_dev_rec=%p, transport=%d, "
+          "bd_addr=%s",
+          __func__, p_callback, p_dev_rec, transport,
+          bd_addr.ToString().c_str());
       p_dev_rec->p_callback = NULL;
       (*p_callback)(&bd_addr, transport, p_dev_rec->p_ref_data, rc);
     }
@@ -1938,8 +1944,8 @@ tBTM_STATUS btm_sec_l2cap_access_req(const RawAddress& bd_addr, uint16_t psm,
 
   is_originator = conn_type;
 
-  BTM_TRACE_DEBUG("%s() is_originator:%d, 0x%x", __func__, is_originator,
-                  p_ref_data);
+  BTM_TRACE_DEBUG("%s() is_originator:%d, 0x%x, psm=0x%04x", __func__,
+                  is_originator, p_ref_data, psm);
 
   /* Find or get oldest record */
   p_dev_rec = btm_find_or_alloc_dev(bd_addr);
@@ -2226,6 +2232,8 @@ tBTM_STATUS btm_sec_l2cap_access_req(const RawAddress& bd_addr, uint16_t psm,
 
   rc = btm_sec_execute_procedure(p_dev_rec);
   if (rc != BTM_CMD_STARTED) {
+    BTM_TRACE_DEBUG("%s: p_dev_rec=%p, clearing callback. old p_callback=%p",
+                    __func__, p_dev_rec, p_dev_rec->p_callback);
     p_dev_rec->p_callback = NULL;
     (*p_callback)(&bd_addr, transport, p_dev_rec->p_ref_data, (uint8_t)rc);
   }
@@ -2745,6 +2753,9 @@ void btm_sec_abort_access_req(const RawAddress& bd_addr) {
     return;
 
   p_dev_rec->sec_state = BTM_SEC_STATE_IDLE;
+
+  BTM_TRACE_DEBUG("%s: clearing callback. p_dev_rec=%p, p_callback=%p",
+                  __func__, p_dev_rec, p_dev_rec->p_callback);
   p_dev_rec->p_callback = NULL;
 }
 
@@ -3758,14 +3769,14 @@ void btm_sec_auth_complete(uint16_t handle, uint8_t status) {
   bool are_bonding = false;
 
   if (p_dev_rec) {
-    VLOG(2) << __func__ << "Security Manager: in state: "
+    VLOG(2) << __func__ << ": Security Manager: in state: "
             << btm_pair_state_descr(btm_cb.pairing_state)
             << " handle:" << handle << " status:" << status
             << "dev->sec_state:" << p_dev_rec->sec_state
             << " bda:" << p_dev_rec->bd_addr
             << "RName:" << p_dev_rec->sec_bd_name;
   } else {
-    VLOG(2) << __func__ << "Security Manager: in state: "
+    VLOG(2) << __func__ << ": Security Manager: in state: "
             << btm_pair_state_descr(btm_cb.pairing_state)
             << " handle:" << handle << " status:" << status;
   }
@@ -4032,6 +4043,8 @@ void btm_sec_encrypt_change(uint16_t handle, uint8_t status,
   if (p_dev_rec->sec_state != BTM_SEC_STATE_ENCRYPTING) {
     if (BTM_SEC_STATE_DELAY_FOR_ENC == p_dev_rec->sec_state) {
       p_dev_rec->sec_state = BTM_SEC_STATE_IDLE;
+      BTM_TRACE_DEBUG("%s: clearing callback. p_dev_rec=%p, p_callback=%p",
+                      __func__, p_dev_rec, p_dev_rec->p_callback);
       p_dev_rec->p_callback = NULL;
       l2cu_resubmit_pending_sec_req(&p_dev_rec->bd_addr);
     }
@@ -4103,16 +4116,16 @@ void btm_sec_connected(const RawAddress& bda, uint16_t handle, uint8_t status,
   btm_acl_resubmit_page();
 
   if (p_dev_rec) {
-    VLOG(2) << __func__ << "Security Manager: in state: "
+    VLOG(2) << __func__ << ": Security Manager: in state: "
             << btm_pair_state_descr(btm_cb.pairing_state)
-            << " handle:" << handle << " status:" << status
-            << "enc_mode:" << enc_mode << " bda:" << bda
-            << "RName:" << p_dev_rec->sec_bd_name;
+            << " handle:" << handle << " status:" << loghex(status)
+            << " enc_mode:" << loghex(enc_mode) << " bda:" << bda
+            << " RName:" << p_dev_rec->sec_bd_name;
   } else {
-    VLOG(2) << __func__ << "Security Manager: in state: "
+    VLOG(2) << __func__ << ": Security Manager: in state: "
             << btm_pair_state_descr(btm_cb.pairing_state)
-            << " handle:" << handle << " status:" << status
-            << "enc_mode:" << enc_mode << " bda:" << bda;
+            << " handle:" << handle << " status:" << loghex(status)
+            << " enc_mode:" << loghex(enc_mode) << " bda:" << bda;
   }
 
   if (!p_dev_rec) {
@@ -4534,6 +4547,8 @@ void btm_sec_disconnected(uint16_t handle, uint8_t reason) {
 
   /* if security is pending, send callback to clean up the security state */
   if (p_callback) {
+    BTM_TRACE_DEBUG("%s: clearing callback. p_dev_rec=%p, p_callback=%p",
+                    __func__, p_dev_rec, p_dev_rec->p_callback);
     p_dev_rec->p_callback =
         NULL; /* when the peer device time out the authentication before
                  we do, this call back must be reset here */
@@ -5545,6 +5560,10 @@ void btm_sec_dev_rec_cback_event(tBTM_SEC_DEV_REC* p_dev_rec, uint8_t res,
                                  bool is_le_transport) {
   tBTM_SEC_CALLBACK* p_callback = p_dev_rec->p_callback;
 
+  BTM_TRACE_DEBUG("%s: p_callback=%p, is_le_transport=%d, res=%d, p_dev_rec=%p",
+                  __func__, p_dev_rec->p_callback, is_le_transport, res,
+                  p_dev_rec);
+
   if (p_dev_rec->p_callback) {
     p_dev_rec->p_callback = NULL;
 

diff --git a/stack/l2cap/l2c_ble.cc b/stack/l2cap/l2c_ble.cc
index ff5ee81..51f81cf 100644 (file)
--- a/stack/l2cap/l2c_ble.cc
+++ b/stack/l2cap/l2c_ble.cc
@@ -1340,7 +1340,8 @@ void l2cble_sec_comp(const RawAddress* bda, tBT_TRANSPORT transport,
   uint8_t sec_act;
 
   if (!p_lcb) {
-    L2CAP_TRACE_WARNING("%s security complete for unknown device", __func__);
+    L2CAP_TRACE_WARNING("%s: security complete for unknown device. bda=%s",
+                        __func__, bda->ToString().c_str());
     return;
   }
 

diff --git a/stack/l2cap/l2c_csm.cc b/stack/l2cap/l2c_csm.cc
index 97841f2..aa1537b 100644 (file)
--- a/stack/l2cap/l2c_csm.cc
+++ b/stack/l2cap/l2c_csm.cc
@@ -299,8 +299,11 @@ static void l2c_csm_orig_w4_sec_comp(tL2C_CCB* p_ccb, uint16_t event,
   tL2CA_CONNECT_CFM_CB* connect_cfm = p_ccb->p_rcb->api.pL2CA_ConnectCfm_Cb;
   uint16_t local_cid = p_ccb->local_cid;
 
-  L2CAP_TRACE_EVENT("L2CAP - LCID: 0x%04x  st: ORIG_W4_SEC_COMP  evt: %s",
-                    p_ccb->local_cid, l2c_csm_get_event_name(event));
+  L2CAP_TRACE_EVENT(
+      "%s: %sL2CAP - LCID: 0x%04x  st: ORIG_W4_SEC_COMP  evt: %s", __func__,
+      ((p_ccb->p_lcb) && (p_ccb->p_lcb->transport == BT_TRANSPORT_LE)) ? "LE "
+                                                                       : "",
+      p_ccb->local_cid, l2c_csm_get_event_name(event));
 
   switch (event) {
     case L2CEVT_LP_DISCONNECT_IND: /* Link was disconnected */

diff --git a/stack/l2cap/l2c_link.cc b/stack/l2cap/l2c_link.cc
index b33ba91..30cb830 100644 (file)
--- a/stack/l2cap/l2c_link.cc
+++ b/stack/l2cap/l2c_link.cc
@@ -285,7 +285,8 @@ void l2c_link_sec_comp2(const RawAddress& p_bda,
   tL2C_CCB* p_next_ccb;
   uint8_t event;
 
-  L2CAP_TRACE_DEBUG("l2c_link_sec_comp: %d, 0x%x", status, p_ref_data);
+  L2CAP_TRACE_DEBUG("%s: status=%d, p_ref_data=%p, BD_ADDR=%s", __func__,
+                    status, p_ref_data, p_bda.ToString().c_str());
 
   if (status == BTM_SUCCESS_NO_SECURITY) status = BTM_SUCCESS;
 

diff --git a/stack/l2cap/l2c_utils.cc b/stack/l2cap/l2c_utils.cc
index 4b17f14..337e076 100644 (file)
--- a/stack/l2cap/l2c_utils.cc
+++ b/stack/l2cap/l2c_utils.cc
@@ -1182,9 +1182,8 @@ void l2cu_enqueue_ccb(tL2C_CCB* p_ccb) {
   if (p_ccb->p_lcb != NULL) p_q = &p_ccb->p_lcb->ccb_queue;
 
   if ((!p_ccb->in_use) || (p_q == NULL)) {
-    L2CAP_TRACE_ERROR(
-        "l2cu_enqueue_ccb  CID: 0x%04x ERROR in_use: %u  p_lcb: 0x%08x",
-        p_ccb->local_cid, p_ccb->in_use, p_ccb->p_lcb);
+    L2CAP_TRACE_ERROR("%s: CID: 0x%04x ERROR in_use: %u  p_lcb: %p", __func__,
+                      p_ccb->local_cid, p_ccb->in_use, p_ccb->p_lcb);
     return;
   }
 

diff --git a/stack/smp/smp_act.cc b/stack/smp/smp_act.cc
index bc2bd7f..10f5172 100644 (file)
--- a/stack/smp/smp_act.cc
+++ b/stack/smp/smp_act.cc
@@ -501,7 +501,9 @@ void smp_proc_pair_cmd(tSMP_CB* p_cb, tSMP_INT_DATA* p_data) {
   uint8_t* p = p_data->p_data;
   tBTM_SEC_DEV_REC* p_dev_rec = btm_find_dev(p_cb->pairing_bda);
 
-  SMP_TRACE_DEBUG("%s", __func__);
+  SMP_TRACE_DEBUG("%s: pairing_bda=%s", __func__,
+                  p_cb->pairing_bda.ToString().c_str());
+
   /* erase all keys if it is slave proc pairing req */
   if (p_dev_rec && (p_cb->role == HCI_ROLE_SLAVE))
     btm_sec_clear_ble_keys(p_dev_rec);

diff --git a/stack/smp/smp_api.cc b/stack/smp/smp_api.cc
index 5303acf..d096da5 100644 (file)
--- a/stack/smp/smp_api.cc
+++ b/stack/smp/smp_api.cc
@@ -133,8 +133,10 @@ bool SMP_Register(tSMP_CALLBACK* p_cback) {
 tSMP_STATUS SMP_Pair(const RawAddress& bd_addr) {
   tSMP_CB* p_cb = &smp_cb;
 
-  SMP_TRACE_EVENT("%s state=%d br_state=%d flag=0x%x ", __func__, p_cb->state,
-                  p_cb->br_state, p_cb->flags);
+  SMP_TRACE_EVENT("%s: state=%d br_state=%d flag=0x%x, bd_addr=%s", __func__,
+                  p_cb->state, p_cb->br_state, p_cb->flags,
+                  bd_addr.ToString().c_str());
+
   if (p_cb->state != SMP_STATE_IDLE ||
       p_cb->flags & SMP_PAIR_FLAGS_WE_STARTED_DD || p_cb->smp_over_br) {
     /* pending security on going, reject this one */
@@ -171,8 +173,9 @@ tSMP_STATUS SMP_Pair(const RawAddress& bd_addr) {
 tSMP_STATUS SMP_BR_PairWith(const RawAddress& bd_addr) {
   tSMP_CB* p_cb = &smp_cb;
 
-  SMP_TRACE_EVENT("%s state=%d br_state=%d flag=0x%x ", __func__, p_cb->state,
-                  p_cb->br_state, p_cb->flags);
+  SMP_TRACE_EVENT("%s: state=%d br_state=%d flag=0x%x, bd_addr=%s", __func__,
+                  p_cb->state, p_cb->br_state, p_cb->flags,
+                  bd_addr.ToString().c_str());
 
   if (p_cb->state != SMP_STATE_IDLE || p_cb->smp_over_br ||
       p_cb->flags & SMP_PAIR_FLAGS_WE_STARTED_DD) {

diff --git a/stack/smp/smp_l2c.cc b/stack/smp/smp_l2c.cc
index 528bea8..1e0cb71 100644 (file)
--- a/stack/smp/smp_l2c.cc
+++ b/stack/smp/smp_l2c.cc
@@ -94,7 +94,9 @@ static void smp_connect_callback(uint16_t channel, const RawAddress& bd_addr,
   tSMP_CB* p_cb = &smp_cb;
   tSMP_INT_DATA int_data;
 
-  SMP_TRACE_EVENT("SMDBG l2c %s", __func__);
+  SMP_TRACE_EVENT("%s: SMDBG l2c: bd_addr=%s, p_cb->pairing_bda=%s", __func__,
+                  bd_addr.ToString().c_str(),
+                  p_cb->pairing_bda.ToString().c_str());
 
   if (transport == BT_TRANSPORT_BR_EDR || bd_addr.IsEmpty()) return;
 
@@ -138,10 +140,11 @@ static void smp_data_received(uint16_t channel, const RawAddress& bd_addr,
   tSMP_CB* p_cb = &smp_cb;
   uint8_t* p = (uint8_t*)(p_buf + 1) + p_buf->offset;
   uint8_t cmd;
-  SMP_TRACE_EVENT("SMDBG l2c %s", __func__);
 
   STREAM_TO_UINT8(cmd, p);
 
+  SMP_TRACE_EVENT("%s: SMDBG l2c, cmd=0x%x", __func__, cmd);
+
   /* sanity check */
   if ((SMP_OPCODE_MAX < cmd) || (SMP_OPCODE_MIN > cmd)) {
     SMP_TRACE_WARNING("Ignore received command with RESERVED code 0x%02x", cmd);
@@ -240,11 +243,12 @@ static void smp_br_connect_callback(uint16_t channel, const RawAddress& bd_addr,
     return;
   }
 
-  if (bd_addr != p_cb->pairing_bda) return;
-
   VLOG(1) << __func__ << " for pairing BDA: " << bd_addr
+          << ", pairing_bda:" << p_cb->pairing_bda
           << " Event: " << ((connected) ? "connected" : "disconnected");
 
+  if (bd_addr != p_cb->pairing_bda) return;
+
   if (connected) {
     if (!p_cb->connect_initialized) {
       p_cb->connect_initialized = true;

diff --git a/stack/smp/smp_utils.cc b/stack/smp/smp_utils.cc
index 6a0e356..bff5645 100644 (file)
--- a/stack/smp/smp_utils.cc
+++ b/stack/smp/smp_utils.cc
@@ -332,7 +332,10 @@ bool smp_send_msg_to_L2CAP(const RawAddress& rem_bda, BT_HDR* p_toL2CAP) {
 bool smp_send_cmd(uint8_t cmd_code, tSMP_CB* p_cb) {
   BT_HDR* p_buf;
   bool sent = false;
-  SMP_TRACE_EVENT("smp_send_cmd on l2cap cmd_code=0x%x", cmd_code);
+
+  SMP_TRACE_EVENT("%s: on l2cap cmd_code=0x%x, pairing_bda=%s", __func__,
+                  cmd_code, p_cb->pairing_bda.ToString().c_str());
+
   if (cmd_code <= (SMP_OPCODE_MAX + 1 /* for SMP_OPCODE_PAIR_COMMITM */) &&
       smp_cmd_build_act[cmd_code] != NULL) {
     p_buf = (*smp_cmd_build_act[cmd_code])(cmd_code, p_cb);
@@ -921,7 +924,8 @@ void smp_proc_pairing_cmpl(tSMP_CB* p_cb) {
   tSMP_EVT_DATA evt_data = {0};
   tSMP_CALLBACK* p_callback = p_cb->p_callback;
 
-  SMP_TRACE_DEBUG("smp_proc_pairing_cmpl ");
+  SMP_TRACE_DEBUG("%s: pairing_bda=%s", __func__,
+                  p_cb->pairing_bda.ToString().c_str());
 
   evt_data.cmplt.reason = p_cb->status;
   evt_data.cmplt.smp_over_br = p_cb->smp_over_br;