Donate to e Foundation | Murena handsets with /e/OS | Own a part of Murena! Learn more

Commit ada1add5 authored by Stanley Tng's avatar Stanley Tng
Browse files

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
parent 27461cb8

system/btif/src/btif_dm.cc

+5 −2
Original line number Diff line number Diff line
@@ -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;

system/stack/btm/btm_ble.cc

+15 −9
Original line number Diff line number Diff line
@@ -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) {

system/stack/btm/btm_dev.cc

+5 −1
Original line number Diff line number Diff line
@@ -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);

system/stack/btm/btm_sec.cc

+33 −14
Original line number Diff line number Diff line
@@ -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

            << " 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;

system/stack/l2cap/l2c_ble.cc

+2 −1
Original line number Diff line number Diff line
@@ -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;

  }