HFP: Add more logs to SCO sessions

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

diff --git a/bta/ag/bta_ag_at.cc b/bta/ag/bta_ag_at.cc
index 90c46ff..9bf34ab 100644 (file)
--- a/bta/ag/bta_ag_at.cc
+++ b/bta/ag/bta_ag_at.cc
@@ -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 error */
-    else {
+    } else {
+      /* else error */
+      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 no match call error callback */
-  else {
+  } else {
+    /* else no match call error callback */
+    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);
   }
 }

diff --git a/bta/ag/bta_ag_at.h b/bta/ag/bta_ag_at.h
index c5b5d88..d633a72 100644 (file)
--- a/bta/ag/bta_ag_at.h
+++ b/bta/ag/bta_ag_at.h
@@ -24,6 +24,8 @@
 #ifndef BTA_AG_AT_H
 #define BTA_AG_AT_H
 
+#include <cstdint>
+
 /*****************************************************************************
  *  Constants
  ****************************************************************************/

diff --git a/bta/ag/bta_ag_cmd.cc b/bta/ag/bta_ag_cmd.cc
index 214ffd7..b1c0e04 100644 (file)
--- a/bta/ag/bta_ag_cmd.cc
+++ b/bta/ag/bta_ag_cmd.cc
@@ -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;

diff --git a/bta/ag/bta_ag_sco.cc b/bta/ag/bta_ag_sco.cc
index 297d93d..28e446e 100644 (file)
--- a/bta/ag/bta_ag_sco.cc
+++ b/bta/ag/bta_ag_sco.cc
@@ -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"
@@ -45,11 +46,11 @@ static RawAddress active_device_addr = {};
 
 /* sco events */
 enum {
-  BTA_AG_SCO_LISTEN_E,       /* listen request */
-  BTA_AG_SCO_OPEN_E,         /* open request */
-  BTA_AG_SCO_XFER_E,         /* transfer request */
-  BTA_AG_SCO_CN_DONE_E, /* codec negotiation done */
-  BTA_AG_SCO_REOPEN_E,  /* Retry with other codec when failed */
+  BTA_AG_SCO_LISTEN_E,     /* listen request */
+  BTA_AG_SCO_OPEN_E,       /* open request */
+  BTA_AG_SCO_XFER_E,       /* transfer request */
+  BTA_AG_SCO_CN_DONE_E,    /* codec negotiation done */
+  BTA_AG_SCO_REOPEN_E,     /* Retry with other codec when failed */
   BTA_AG_SCO_CLOSE_E,      /* close request */
   BTA_AG_SCO_SHUTDOWN_E,   /* shutdown request */
   BTA_AG_SCO_CONN_OPEN_E,  /* sco open */
@@ -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,11 +617,10 @@ 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(),
-                   bta_ag_sco_state_str(p_sco->state), p_sco->state,
-                   bta_ag_sco_evt_str(event), event);
+  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);
 
   switch (p_sco->state) {
     case BTA_AG_SCO_SHUTDOWN_ST:
@@ -635,9 +632,8 @@ 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__,
-              bta_ag_sco_evt_str(event), event);
+          LOG_WARN("BTA_AG_SCO_SHUTDOWN_ST: Ignoring event %s[%d]",
+                   bta_ag_sco_evt_str(event), event);
           break;
       }
       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,9 +868,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_XFER_ST: Ignoring event %s[%d]", __func__,
-              bta_ag_sco_evt_str(event), event);
+          LOG_WARN("BTA_AG_SCO_OPEN_XFER_ST: Ignoring event %s[%d]",
+                   bta_ag_sco_evt_str(event), event);
           break;
       }
       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,9 +992,8 @@ 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__,
-              bta_ag_sco_evt_str(event), event);
+          LOG_WARN("BTA_AG_SCO_CLOSE_OP_ST: Ignoring event %s[%d]",
+                   bta_ag_sco_evt_str(event), event);
           break;
       }
       break;
@@ -1050,9 +1043,8 @@ 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__,
-              bta_ag_sco_evt_str(event), event);
+          LOG_WARN(" BTA_AG_SCO_CLOSE_XFER_ST: Ignoring event %s[%d]",
+                   bta_ag_sco_evt_str(event), event);
           break;
       }
       break;
@@ -1108,9 +1100,8 @@ 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__,
-              bta_ag_sco_evt_str(event), event);
+          LOG_WARN("BTA_AG_SCO_SHUTTING_ST: Ignoring event %s[%d]",
+                   bta_ag_sco_evt_str(event), event);
           break;
       }
       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);
   }
 }