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

Commit fc8342c5 authored by Jack He's avatar Jack He
Browse files

HFP: Add more logs to SCO sessions 

Bug: 159815595
Test: make phone call with HFP
Tag: #refactor
Change-Id: Idcca06da14c1212c28fb1dadd215b4035202b60f
parent 72402713

system/bta/ag/bta_ag_at.cc

+13 −8
Original line number Diff line number Diff line
@@ -22,11 +22,14 @@ 
 *

 ******************************************************************************/



#include "bta_ag_at.h"



#include <log/log.h>



#include <cstring>



#include "bt_common.h"

#include "bta_ag_at.h"

#include "log/log.h"

#include "osi/include/log.h"

#include "utl.h"



/*****************************************************************************
@@ -135,6 +138,7 @@ void bta_ag_process_at(tBTA_AG_AT_CB* p_cb, char* p_end) { 
        if (int_arg < (int16_t)p_cb->p_at_tbl[idx].min ||

            int_arg > (int16_t)p_cb->p_at_tbl[idx].max) {

          /* arg out of range; error */

          LOG_WARN("arg out of range");

          (*p_cb->p_err_cback)((tBTA_AG_SCB*)p_cb->p_user, false, nullptr);

        } else {

          (*p_cb->p_cmd_cback)((tBTA_AG_SCB*)p_cb->p_user,
@@ -146,14 +150,15 @@ void bta_ag_process_at(tBTA_AG_AT_CB* p_cb, char* p_end) { 
                             p_cb->p_at_tbl[idx].command_id, arg_type, p_arg,

                             p_end, int_arg);

      }

    }

    } else {

      /* else error */

    else {

      LOG_WARN("Incoming arg type 0x%x does not match cmd arg type 0x%x",

               arg_type, p_cb->p_at_tbl[idx].arg_type);

      (*p_cb->p_err_cback)((tBTA_AG_SCB*)p_cb->p_user, false, nullptr);

    }

  }

  } else {

    /* else no match call error callback */

  else {

    LOG_WARN("Unmatched command index %d", idx);

    (*p_cb->p_err_cback)((tBTA_AG_SCB*)p_cb->p_user, true, p_cb->p_cmd_buf);

  }

}

system/bta/ag/bta_ag_at.h

+2 −0
Original line number Diff line number Diff line
@@ -24,6 +24,8 @@ 
#ifndef BTA_AG_AT_H

#define BTA_AG_AT_H



#include <cstdint>



/*****************************************************************************

 *  Constants

 ****************************************************************************/

system/bta/ag/bta_ag_cmd.cc

+2 −2
Original line number Diff line number Diff line
@@ -839,7 +839,7 @@ void bta_ag_at_hfp_cback(tBTA_AG_SCB* p_scb, uint16_t cmd, uint8_t arg_type, 
  uint32_t i, ind_id;

  uint32_t bia_masked_out;

  if (p_arg == nullptr) {

    APPL_TRACE_ERROR("%s: p_arg is null, send error and return", __func__);

    LOG_WARN("p_arg is null for cmd 0x%x, send error and return", cmd);

    bta_ag_send_error(p_scb, BTA_AG_ERR_INV_CHAR_IN_TSTR);

    return;

  }
@@ -854,7 +854,7 @@ void bta_ag_at_hfp_cback(tBTA_AG_SCB* p_scb, uint16_t cmd, uint8_t arg_type, 
  val.bd_addr = p_scb->peer_addr;



  if ((p_end - p_arg + 1) >= (long)sizeof(val.str)) {

    APPL_TRACE_ERROR("%s: p_arg is too long, send error and return", __func__);

    LOG_ERROR("p_arg is too long for cmd 0x%x, send error and return", cmd);

    bta_ag_send_error(p_scb, BTA_AG_ERR_TEXT_TOO_LONG);

    android_errorWriteLog(0x534e4554, "112860487");

    return;

system/bta/ag/bta_ag_sco.cc

+50 −58
Original line number Diff line number Diff line
@@ -31,6 +31,7 @@ 
#include "btm_api.h"

#include "device/include/controller.h"

#include "device/include/esco_parameters.h"

#include "osi/include/log.h"

#include "osi/include/osi.h"

#include "stack/include/btu.h"

#include "utl.h"
@@ -184,7 +185,6 @@ static void bta_ag_sco_disc_cback(uint16_t sco_idx) { 
  }



  if (handle != 0) {



    /* Restore settings */

    if (bta_ag_cb.sco.p_curr_scb->inuse_codec == BTA_AG_CODEC_MSBC) {

      /* Bypass vendor specific and voice settings if enhanced eSCO supported */
@@ -538,7 +538,7 @@ static void bta_ag_create_pending_sco(tBTA_AG_SCB* p_scb, bool is_local) { 
 *

 ******************************************************************************/

static void bta_ag_codec_negotiation_timer_cback(void* data) {

  APPL_TRACE_DEBUG("%s", __func__);

  LOG_WARN("Codec negotiation timeout");

  tBTA_AG_SCB* p_scb = (tBTA_AG_SCB*)data;



  /* Announce that codec negotiation failed. */
@@ -559,14 +559,12 @@ static void bta_ag_codec_negotiation_timer_cback(void* data) { 
 *

 ******************************************************************************/

void bta_ag_codec_negotiate(tBTA_AG_SCB* p_scb) {

  APPL_TRACE_DEBUG("%s", __func__);

  bta_ag_cb.sco.p_curr_scb = p_scb;

  uint8_t* p_rem_feat = BTM_ReadRemoteFeatures(p_scb->peer_addr);

  bool sdp_wbs_support = p_scb->peer_sdp_features & BTA_AG_FEAT_WBS_SUPPORT;



  if (p_rem_feat == nullptr) {

    LOG(WARNING) << __func__

                 << ": Fail to read remote feature, skip codec negotiation";

    LOG_WARN("Skip codec negotiation, failed to read remote features");

    bta_ag_sco_codec_nego(p_scb, false);

    return;

  }
@@ -582,11 +580,13 @@ void bta_ag_codec_negotiate(tBTA_AG_SCB* p_scb) { 
  // SCO setup fail by Firmware reject.

  if (!HCI_LMP_TRANSPNT_SUPPORTED(p_rem_feat) || !sdp_wbs_support ||

      !(p_scb->peer_features & BTA_AG_PEER_FEAT_CODEC)) {

    LOG_INFO("Assume CVSD by default due to mask mismatch");

    p_scb->sco_codec = UUID_CODEC_CVSD;

  }



  if ((p_scb->codec_updated || p_scb->codec_fallback) &&

      (p_scb->peer_features & BTA_AG_PEER_FEAT_CODEC)) {

    LOG_INFO("Starting codec negotiation");

    /* Change the power mode to Active until SCO open is completed. */

    bta_sys_busy(BTA_ID_AG, p_scb->app_id, p_scb->peer_addr);
@@ -599,9 +599,7 @@ void bta_ag_codec_negotiate(tBTA_AG_SCB* p_scb) { 
                       bta_ag_codec_negotiation_timer_cback, p_scb);

  } else {

    /* use same codec type as previous SCO connection, skip codec negotiation */

    APPL_TRACE_DEBUG(

        "use same codec type as previous SCO connection,skip codec "

        "negotiation");

    LOG_INFO("Skip codec negotiation, using the same codec");

    bta_ag_sco_codec_nego(p_scb, true);

  }

}
@@ -619,9 +617,8 @@ void bta_ag_codec_negotiate(tBTA_AG_SCB* p_scb) { 
static void bta_ag_sco_event(tBTA_AG_SCB* p_scb, uint8_t event) {

  tBTA_AG_SCO_CB* p_sco = &bta_ag_cb.sco;

  uint8_t previous_state = p_sco->state;

  APPL_TRACE_EVENT("%s: index=0x%04x, device=%s, state=%s[%d], event=%s[%d]",

                   __func__, p_scb->sco_idx,

                   p_scb->peer_addr.ToString().c_str(),

  LOG_DEBUG("index=0x%04x, device=%s, state=%s[%d], event=%s[%d]",

            p_scb->sco_idx, p_scb->peer_addr.ToString().c_str(),

            bta_ag_sco_state_str(p_sco->state), p_sco->state,

            bta_ag_sco_evt_str(event), event);
@@ -635,8 +632,7 @@ static void bta_ag_sco_event(tBTA_AG_SCB* p_scb, uint8_t event) { 
          break;



        default:

          APPL_TRACE_WARNING(

              "%s: BTA_AG_SCO_SHUTDOWN_ST: Ignoring event %s[%d]", __func__,

          LOG_WARN("BTA_AG_SCO_SHUTDOWN_ST: Ignoring event %s[%d]",

                   bta_ag_sco_evt_str(event), event);

          break;

      }
@@ -677,10 +673,9 @@ static void bta_ag_sco_event(tBTA_AG_SCB* p_scb, uint8_t event) { 


        case BTA_AG_SCO_CLOSE_E:

          /* remove listening connection */

          /* Ignore the event. Keep listening SCO for the active SLC

           */

          APPL_TRACE_WARNING("%s: BTA_AG_SCO_LISTEN_ST: Ignoring event %s[%d]",

                             __func__, bta_ag_sco_evt_str(event), event);

          /* Ignore the event. Keep listening SCO for the active SLC */

          LOG_WARN("BTA_AG_SCO_LISTEN_ST: Ignoring event %s[%d]",

                   bta_ag_sco_evt_str(event), event);

          break;



        case BTA_AG_SCO_CONN_CLOSE_E:
@@ -690,8 +685,8 @@ static void bta_ag_sco_event(tBTA_AG_SCB* p_scb, uint8_t event) { 
          break;



        default:

          APPL_TRACE_WARNING("%s: BTA_AG_SCO_LISTEN_ST: Ignoring event %s[%d]",

                             __func__, bta_ag_sco_evt_str(event), event);

          LOG_WARN("BTA_AG_SCO_LISTEN_ST: Ignoring event %s[%d]",

                   bta_ag_sco_evt_str(event), event);

          break;

      }

      break;
@@ -739,8 +734,8 @@ static void bta_ag_sco_event(tBTA_AG_SCB* p_scb, uint8_t event) { 
          break;



        default:

          APPL_TRACE_WARNING("%s: BTA_AG_SCO_CODEC_ST: Ignoring event %s[%d]",

                             __func__, bta_ag_sco_evt_str(event), event);

          LOG_WARN("BTA_AG_SCO_CODEC_ST: Ignoring event %s[%d]",

                   bta_ag_sco_evt_str(event), event);

          break;

      }

      break;
@@ -794,8 +789,8 @@ static void bta_ag_sco_event(tBTA_AG_SCB* p_scb, uint8_t event) { 
          break;



        default:

          APPL_TRACE_WARNING("%s: BTA_AG_SCO_OPENING_ST: Ignoring event %s[%d]",

                             __func__, bta_ag_sco_evt_str(event), event);

          LOG_WARN("BTA_AG_SCO_OPENING_ST: Ignoring event %s[%d]",

                   bta_ag_sco_evt_str(event), event);

          break;

      }

      break;
@@ -837,8 +832,8 @@ static void bta_ag_sco_event(tBTA_AG_SCB* p_scb, uint8_t event) { 
          break;



        default:

          APPL_TRACE_WARNING("%s: BTA_AG_SCO_OPEN_CL_ST: Ignoring event %s[%d]",

                             __func__, bta_ag_sco_evt_str(event), event);

          LOG_WARN("BTA_AG_SCO_OPEN_CL_ST: Ignoring event %s[%d]",

                   bta_ag_sco_evt_str(event), event);

          break;

      }

      break;
@@ -873,8 +868,7 @@ static void bta_ag_sco_event(tBTA_AG_SCB* p_scb, uint8_t event) { 
          break;



        default:

          APPL_TRACE_WARNING(

              "%s: BTA_AG_SCO_OPEN_XFER_ST: Ignoring event %s[%d]", __func__,

          LOG_WARN("BTA_AG_SCO_OPEN_XFER_ST: Ignoring event %s[%d]",

                   bta_ag_sco_evt_str(event), event);

          break;

      }
@@ -924,8 +918,8 @@ static void bta_ag_sco_event(tBTA_AG_SCB* p_scb, uint8_t event) { 
          break;



        default:

          APPL_TRACE_WARNING("%s: BTA_AG_SCO_OPEN_ST: Ignoring event %s[%d]",

                             __func__, bta_ag_sco_evt_str(event), event);

          LOG_WARN("BTA_AG_SCO_OPEN_ST: Ignoring event %s[%d]",

                   bta_ag_sco_evt_str(event), event);

          break;

      }

      break;
@@ -968,8 +962,8 @@ static void bta_ag_sco_event(tBTA_AG_SCB* p_scb, uint8_t event) { 
          break;



        default:

          APPL_TRACE_WARNING("%s: BTA_AG_SCO_CLOSING_ST: Ignoring event %s[%d]",

                             __func__, bta_ag_sco_evt_str(event), event);

          LOG_WARN("BTA_AG_SCO_CLOSING_ST: Ignoring event %s[%d]",

                   bta_ag_sco_evt_str(event), event);

          break;

      }

      break;
@@ -998,8 +992,7 @@ static void bta_ag_sco_event(tBTA_AG_SCB* p_scb, uint8_t event) { 
          break;



        default:

          APPL_TRACE_WARNING(

              "%s: BTA_AG_SCO_CLOSE_OP_ST: Ignoring event %s[%d]", __func__,

          LOG_WARN("BTA_AG_SCO_CLOSE_OP_ST: Ignoring event %s[%d]",

                   bta_ag_sco_evt_str(event), event);

          break;

      }
@@ -1050,8 +1043,7 @@ static void bta_ag_sco_event(tBTA_AG_SCB* p_scb, uint8_t event) { 
        }



        default:

          APPL_TRACE_WARNING(

              "%s: BTA_AG_SCO_CLOSE_XFER_ST: Ignoring event %s[%d]", __func__,

          LOG_WARN(" BTA_AG_SCO_CLOSE_XFER_ST: Ignoring event %s[%d]",

                   bta_ag_sco_evt_str(event), event);

          break;

      }
@@ -1108,8 +1100,7 @@ static void bta_ag_sco_event(tBTA_AG_SCB* p_scb, uint8_t event) { 
          break;



        default:

          APPL_TRACE_WARNING(

              "%s: BTA_AG_SCO_SHUTTING_ST: Ignoring event %s[%d]", __func__,

          LOG_WARN("BTA_AG_SCO_SHUTTING_ST: Ignoring event %s[%d]",

                   bta_ag_sco_evt_str(event), event);

          break;

      }
@@ -1119,10 +1110,10 @@ static void bta_ag_sco_event(tBTA_AG_SCB* p_scb, uint8_t event) { 
      break;

  }

  if (p_sco->state != previous_state) {

    APPL_TRACE_EVENT(

        "%s: SCO_state_change: [%s(0x%02x)]->[%s(0x%02x)] "

    LOG_WARN(

        "SCO_state_change: [%s(0x%02x)]->[%s(0x%02x)] "

        "after event [%s(0x%02x)]",

        __func__, bta_ag_sco_state_str(previous_state), previous_state,

        bta_ag_sco_state_str(previous_state), previous_state,

        bta_ag_sco_state_str(p_sco->state), p_sco->state,

        bta_ag_sco_evt_str(event), event);

  }
@@ -1192,8 +1183,9 @@ void bta_ag_sco_open(tBTA_AG_SCB* p_scb, UNUSED_ATTR const tBTA_AG_DATA& data) { 
  }

  /* if another scb using sco, this is a transfer */

  if (bta_ag_cb.sco.p_curr_scb && bta_ag_cb.sco.p_curr_scb != p_scb) {

    LOG(INFO) << __func__ << ": tranfer " << bta_ag_cb.sco.p_curr_scb->peer_addr

              << " -> " << p_scb->peer_addr;

    LOG(INFO) << __func__ << ": transfer "

              << bta_ag_cb.sco.p_curr_scb->peer_addr << " -> "

              << p_scb->peer_addr;

    bta_ag_sco_event(p_scb, BTA_AG_SCO_XFER_E);

  } else {

    /* else it is an open */
@@ -1237,14 +1229,14 @@ void bta_ag_sco_close(tBTA_AG_SCB* p_scb, 
void bta_ag_sco_codec_nego(tBTA_AG_SCB* p_scb, bool result) {

  if (result) {

    /* Subsequent SCO connection will skip codec negotiation */

    APPL_TRACE_DEBUG("%s: Succeeded for index 0x%04x, device %s", __func__,

                     p_scb->sco_idx, p_scb->peer_addr.ToString().c_str());

    LOG_DEBUG("Succeeded for index 0x%04x, device %s", p_scb->sco_idx,

              p_scb->peer_addr.ToString().c_str());

    p_scb->codec_updated = false;

    bta_ag_sco_event(p_scb, BTA_AG_SCO_CN_DONE_E);

  } else {

    /* codec negotiation failed */

    APPL_TRACE_ERROR("%s: Failed for index 0x%04x, device %s", __func__,

                     p_scb->sco_idx, p_scb->peer_addr.ToString().c_str());

    LOG_DEBUG("Failed for index 0x%04x, device %s", p_scb->sco_idx,

              p_scb->peer_addr.ToString().c_str());

    bta_ag_sco_event(p_scb, BTA_AG_SCO_CLOSE_E);

  }

}