Merge "Added extra A2DP logging when there is an error" into oc-mr1-dev

5 files changed, 182 insertions, 102 deletions

diff --git a/bta/av/bta_av_aact.cc b/bta/av/bta_av_aact.cc
index 5ce82096c..12f8b2434 100644
--- a/bta/av/bta_av_aact.cc
+++ b/bta/av/bta_av_aact.cc
@@ -405,6 +405,8 @@ static bool bta_av_next_getcap(tBTA_AV_SCB* p_scb, tBTA_AV_DATA* p_data) {
 
   /* if no streams available then stream open fails */
   if (!sent_cmd) {
+    APPL_TRACE_ERROR("%s: BTA_AV_STR_GETCAP_FAIL_EVT: peer_addr=%s", __func__,
+                     p_scb->peer_addr.ToString().c_str());
     bta_av_ssm_execute(p_scb, BTA_AV_STR_GETCAP_FAIL_EVT, p_data);
   }
 
@@ -925,6 +927,8 @@ void bta_av_do_disc_a2dp(tBTA_AV_SCB* p_scb, tBTA_AV_DATA* p_data) {
     case BTA_AV_RS_FAIL:
       /* report a new failure event  */
       p_scb->open_status = BTA_AV_FAIL_ROLE;
+      APPL_TRACE_ERROR("%s: BTA_AV_SDP_DISC_FAIL_EVT: peer_addr=%s", __func__,
+                       p_scb->peer_addr.ToString().c_str());
       bta_av_ssm_execute(p_scb, BTA_AV_SDP_DISC_FAIL_EVT, NULL);
       break;
 
@@ -1177,7 +1181,8 @@ void bta_av_disconnect_req(tBTA_AV_SCB* p_scb,
                            UNUSED_ATTR tBTA_AV_DATA* p_data) {
   tBTA_AV_RCB* p_rcb;
 
-  APPL_TRACE_DEBUG("%s: conn_lcb: 0x%x", __func__, bta_av_cb.conn_lcb);
+  APPL_TRACE_WARNING("%s: conn_lcb: 0x%x peer_addr: %s", __func__,
+                     bta_av_cb.conn_lcb, p_scb->peer_addr.ToString().c_str());
 
   alarm_cancel(bta_av_cb.link_signalling_timer);
   alarm_cancel(p_scb->avrc_ct_timer);
@@ -1531,7 +1536,12 @@ void bta_av_connect_req(tBTA_AV_SCB* p_scb, UNUSED_ATTR tBTA_AV_DATA* p_data) {
  *
  ******************************************************************************/
 void bta_av_sdp_failed(tBTA_AV_SCB* p_scb, tBTA_AV_DATA* p_data) {
-  if (!p_scb->open_status) p_scb->open_status = BTA_AV_FAIL_SDP;
+  APPL_TRACE_ERROR("%s: peer_addr=%s open_status=%d", __func__,
+                   p_scb->peer_addr.ToString().c_str(), p_scb->open_status);
+
+  if (p_scb->open_status == BTA_AV_SUCCESS) {
+    p_scb->open_status = BTA_AV_FAIL_SDP;
+  }
 
   p_scb->sdp_discovery_started = false;
   bta_av_str_closed(p_scb, p_data);
@@ -1586,6 +1596,8 @@ void bta_av_disc_results(tBTA_AV_SCB* p_scb, tBTA_AV_DATA* p_data) {
   }
   /* else we got discover response but with no streams; we're done */
   else {
+    APPL_TRACE_ERROR("%s: BTA_AV_STR_DISC_FAIL_EVT: peer_addr=%s", __func__,
+                     p_scb->peer_addr.ToString().c_str());
     bta_av_ssm_execute(p_scb, BTA_AV_STR_DISC_FAIL_EVT, p_data);
   }
 }
@@ -1630,6 +1642,8 @@ void bta_av_disc_res_as_acp(tBTA_AV_SCB* p_scb, tBTA_AV_DATA* p_data) {
   }
   /* else we got discover response but with no streams; we're done */
   else {
+    APPL_TRACE_ERROR("%s: BTA_AV_STR_DISC_FAIL_EVT: peer_addr=%s", __func__,
+                     p_scb->peer_addr.ToString().c_str());
     bta_av_ssm_execute(p_scb, BTA_AV_STR_DISC_FAIL_EVT, p_data);
   }
 }
@@ -1727,7 +1741,8 @@ void bta_av_open_failed(tBTA_AV_SCB* p_scb, tBTA_AV_DATA* p_data) {
   tBTA_AV_SCB* p_opened_scb = NULL;
   uint8_t idx;
 
-  APPL_TRACE_DEBUG("%s", __func__);
+  APPL_TRACE_ERROR("%s: peer_addr=%s", __func__,
+                   p_scb->peer_addr.ToString().c_str());
   p_scb->open_status = BTA_AV_FAIL_STREAM;
   bta_av_cco_close(p_scb, p_data);
 
@@ -1760,6 +1775,12 @@ void bta_av_open_failed(tBTA_AV_SCB* p_scb, tBTA_AV_DATA* p_data) {
       open.sep = AVDT_TSEP_SRC;
     }
 
+    APPL_TRACE_ERROR(
+        "%s: there is already an active connection: peer_addr=%s chnl=%d "
+        "hndl=%d status=%d starting=%d edr=%d",
+        __func__, open.bd_addr.ToString().c_str(), open.chnl, open.hndl,
+        open.status, open.starting, open.edr);
+
     tBTA_AV bta_av_data;
     bta_av_data.open = open;
     (*bta_av_cb.p_cback)(BTA_AV_OPEN_EVT, &bta_av_data);
@@ -1902,6 +1923,9 @@ void bta_av_discover_req(tBTA_AV_SCB* p_scb, UNUSED_ATTR tBTA_AV_DATA* p_data) {
  *
  ******************************************************************************/
 void bta_av_conn_failed(tBTA_AV_SCB* p_scb, tBTA_AV_DATA* p_data) {
+  APPL_TRACE_ERROR("%s: peer_addr=%s open_status=%d", __func__,
+                   p_scb->peer_addr.ToString().c_str(), p_scb->open_status);
+
   p_scb->open_status = BTA_AV_FAIL_STREAM;
   bta_av_str_closed(p_scb, p_data);
 }
@@ -2475,6 +2499,11 @@ void bta_av_str_closed(tBTA_AV_SCB* p_scb, tBTA_AV_DATA* p_data) {
   tBTA_AV_EVT event;
   uint8_t policy = HCI_ENABLE_SNIFF_MODE;
 
+  APPL_TRACE_WARNING(
+      "%s: peer_addr=%s open_status=%d chnl=%d hndl=%d co_started=%d", __func__,
+      p_scb->peer_addr.ToString().c_str(), p_scb->open_status, p_scb->chnl,
+      p_scb->hndl, p_scb->co_started);
+
   if ((bta_av_cb.features & BTA_AV_FEAT_MASTER) == 0 ||
       bta_av_cb.audio_open_cnt == 1)
     policy |= HCI_ENABLE_MASTER_SLAVE_SWITCH;
@@ -2484,7 +2513,7 @@ void bta_av_str_closed(tBTA_AV_SCB* p_scb, tBTA_AV_DATA* p_data) {
     L2CA_SetDesireRole(L2CAP_ROLE_ALLOW_SWITCH);
   }
 
-  if (p_scb->open_status) {
+  if (p_scb->open_status != BTA_AV_SUCCESS) {
     /* must be failure when opening the stream */
     data.open.bd_addr = p_scb->peer_addr;
     data.open.status = p_scb->open_status;
@@ -2677,8 +2706,10 @@ void bta_av_rcfg_str_ok(tBTA_AV_SCB* p_scb, tBTA_AV_DATA* p_data) {
  *
  ******************************************************************************/
 void bta_av_rcfg_failed(tBTA_AV_SCB* p_scb, tBTA_AV_DATA* p_data) {
-  APPL_TRACE_DEBUG("%s: num_recfg: %d, conn_lcb:0x%x", __func__,
-                   p_scb->num_recfg, bta_av_cb.conn_lcb);
+  APPL_TRACE_ERROR("%s: num_recfg=%d conn_lcb=0x%x peer_addr=%s", __func__,
+                   p_scb->num_recfg, bta_av_cb.conn_lcb,
+                   p_scb->peer_addr.ToString().c_str());
+
   if (p_scb->num_recfg > BTA_AV_RECONFIG_RETRY) {
     bta_av_cco_close(p_scb, p_data);
     /* report failure */
@@ -2733,7 +2764,10 @@ void bta_av_rcfg_connect(tBTA_AV_SCB* p_scb, UNUSED_ATTR tBTA_AV_DATA* p_data) {
  *
  ******************************************************************************/
 void bta_av_rcfg_discntd(tBTA_AV_SCB* p_scb, UNUSED_ATTR tBTA_AV_DATA* p_data) {
-  APPL_TRACE_DEBUG("%s: num_recfg: %d", __func__, p_scb->num_recfg);
+  APPL_TRACE_ERROR("%s: num_recfg=%d conn_lcb=0x%x peer_addr=%s", __func__,
+                   p_scb->num_recfg, bta_av_cb.conn_lcb,
+                   p_scb->peer_addr.ToString().c_str());
+
   p_scb->num_recfg++;
   if (p_scb->num_recfg > BTA_AV_RECONFIG_RETRY) {
     /* report failure */
@@ -2774,6 +2808,8 @@ void bta_av_suspend_cont(tBTA_AV_SCB* p_scb, tBTA_AV_DATA* p_data) {
       tBTA_AV bta_av_data;
       bta_av_data.reconfig = reconfig;
       (*bta_av_cb.p_cback)(BTA_AV_RECONFIG_EVT, &bta_av_data);
+      APPL_TRACE_ERROR("%s: BTA_AV_STR_DISC_FAIL_EVT: peer_addr=%s", __func__,
+                       p_scb->peer_addr.ToString().c_str());
       bta_av_ssm_execute(p_scb, BTA_AV_STR_DISC_FAIL_EVT, NULL);
     } else {
       APPL_TRACE_ERROR("%s: suspend rejected, try close", __func__);
diff --git a/bta/av/bta_av_act.cc b/bta/av/bta_av_act.cc
index 6a59221fa..4125b6c88 100644
--- a/bta/av/bta_av_act.cc
+++ b/bta/av/bta_av_act.cc
@@ -1473,7 +1473,9 @@ void bta_av_sig_chg(tBTA_AV_DATA* p_data) {
         if (((mask & p_lcb->conn_msk) || bta_av_cb.conn_lcb) &&
             p_cb->p_scb[xx] &&
             p_cb->p_scb[xx]->peer_addr == p_data->str_msg.bd_addr) {
-          APPL_TRACE_DEBUG("%s: Sending AVDT_DISCONNECT_EVT", __func__);
+          APPL_TRACE_WARNING("%s: Sending AVDT_DISCONNECT_EVT peer_addr=%s",
+                             __func__,
+                             p_cb->p_scb[xx]->peer_addr.ToString().c_str());
           bta_av_ssm_execute(p_cb->p_scb[xx], BTA_AV_AVDT_DISCONNECT_EVT, NULL);
         }
       }
diff --git a/btif/src/btif_a2dp.cc b/btif/src/btif_a2dp.cc
index 7c83ff9a1..62a217acb 100644
--- a/btif/src/btif_a2dp.cc
+++ b/btif/src/btif_a2dp.cc
@@ -33,7 +33,8 @@
 #include "osi/include/log.h"
 
 void btif_a2dp_on_idle(void) {
-  APPL_TRACE_EVENT("## ON A2DP IDLE ## peer_sep = %d", btif_av_get_peer_sep());
+  APPL_TRACE_WARNING("## ON A2DP IDLE ## peer_sep = %d",
+                     btif_av_get_peer_sep());
   if (btif_av_get_peer_sep() == AVDT_TSEP_SNK) {
     btif_a2dp_source_on_idle();
   } else if (btif_av_get_peer_sep() == AVDT_TSEP_SRC) {
@@ -44,7 +45,7 @@ void btif_a2dp_on_idle(void) {
 bool btif_a2dp_on_started(tBTA_AV_START* p_av_start, bool pending_start) {
   bool ack = false;
 
-  APPL_TRACE_EVENT("## ON A2DP STARTED ##");
+  APPL_TRACE_WARNING("## ON A2DP STARTED ##");
 
   if (p_av_start == NULL) {
     /* ack back a local start request */
@@ -52,6 +53,11 @@ bool btif_a2dp_on_started(tBTA_AV_START* p_av_start, bool pending_start) {
     return true;
   }
 
+  APPL_TRACE_WARNING(
+      "%s: pending_start = %d status = %d suspending = %d initiator = %d",
+      __func__, pending_start, p_av_start->status, p_av_start->suspending,
+      p_av_start->initiator);
+
   if (p_av_start->status == BTA_AV_SUCCESS) {
     if (!p_av_start->suspending) {
       if (p_av_start->initiator) {
@@ -78,7 +84,7 @@ bool btif_a2dp_on_started(tBTA_AV_START* p_av_start, bool pending_start) {
 }
 
 void btif_a2dp_on_stopped(tBTA_AV_SUSPEND* p_av_suspend) {
-  APPL_TRACE_EVENT("## ON A2DP STOPPED ##");
+  APPL_TRACE_WARNING("## ON A2DP STOPPED ##");
 
   if (btif_av_get_peer_sep() == AVDT_TSEP_SRC) {
     btif_a2dp_sink_on_stopped(p_av_suspend);
@@ -89,7 +95,7 @@ void btif_a2dp_on_stopped(tBTA_AV_SUSPEND* p_av_suspend) {
 }
 
 void btif_a2dp_on_suspended(tBTA_AV_SUSPEND* p_av_suspend) {
-  APPL_TRACE_EVENT("## ON A2DP SUSPENDED ##");
+  APPL_TRACE_WARNING("## ON A2DP SUSPENDED ##");
   if (btif_av_get_peer_sep() == AVDT_TSEP_SRC) {
     btif_a2dp_sink_on_suspended(p_av_suspend);
   } else {
diff --git a/btif/src/btif_av.cc b/btif/src/btif_av.cc
index a69f0e5ca..b7f1ac935 100644
--- a/btif/src/btif_av.cc
+++ b/btif/src/btif_av.cc
@@ -224,7 +224,7 @@ static void btif_initiate_av_open_timer_timeout(UNUSED_ATTR void* data) {
 
   /* is there at least one RC connection - There should be */
   if (btif_rc_get_connected_peer(&peer_addr)) {
-    BTIF_TRACE_DEBUG("%s Issuing connect to the remote RC peer", __func__);
+    BTIF_TRACE_DEBUG("%s: Issuing connect to the remote RC peer", __func__);
     /* In case of AVRCP connection request, we will initiate SRC connection */
     connect_req.target_bda = &peer_addr;
     if (bt_av_sink_callbacks != NULL)
@@ -234,7 +234,7 @@ static void btif_initiate_av_open_timer_timeout(UNUSED_ATTR void* data) {
     btif_dispatch_sm_event(BTIF_AV_CONNECT_REQ_EVT, (char*)&connect_req,
                            sizeof(connect_req));
   } else {
-    BTIF_TRACE_ERROR("%s No connected RC peers", __func__);
+    BTIF_TRACE_ERROR("%s: No connected RC peers", __func__);
   }
 }
 
@@ -284,11 +284,12 @@ static void btif_report_audio_state(btav_audio_state_t state,
 }
 
 static void btif_update_source_codec(void* p_data) {
-  btav_a2dp_codec_config_t req;
+  BTIF_TRACE_DEBUG("%s", __func__);
+
   // copy to avoid alignment problems
+  btav_a2dp_codec_config_t req;
   memcpy(&req, p_data, sizeof(req));
 
-  BTIF_TRACE_DEBUG("BTIF_AV_SOURCE_CONFIG_REQ_EVT");
   btif_a2dp_source_encoder_user_config_update_req(req);
 }
 
@@ -303,8 +304,9 @@ static void btif_report_source_codec_state(UNUSED_ATTR void* p_data) {
           &codec_config, &codecs_local_capabilities,
           &codecs_selectable_capabilities)) {
     BTIF_TRACE_WARNING(
-        "BTIF_AV_SOURCE_CONFIG_UPDATED_EVT failed: "
-        "cannot get codec config and capabilities");
+        "%s: error reporting audio source codec state: "
+        "cannot get codec config and capabilities",
+        __func__);
     return;
   }
   if (bt_av_src_callbacks != NULL) {
@@ -324,7 +326,7 @@ static void btif_report_source_codec_state(UNUSED_ATTR void* p_data) {
  ******************************************************************************/
 
 static bool btif_av_state_idle_handler(btif_sm_event_t event, void* p_data) {
-  BTIF_TRACE_DEBUG("%s event:%s flags %x", __func__,
+  BTIF_TRACE_DEBUG("%s: event=%s flags=0x%x", __func__,
                    dump_av_sm_event_name((btif_av_sm_event_t)event),
                    btif_av_cb.flags);
 
@@ -384,14 +386,14 @@ static bool btif_av_state_idle_handler(btif_sm_event_t event, void* p_data) {
        * TODO: We may need to do this only on an AVRCP Play. FixMe
        */
 
-      BTIF_TRACE_DEBUG("BTA_AV_RC_OPEN_EVT received w/o AV");
+      BTIF_TRACE_WARNING("%s: BTA_AV_RC_OPEN_EVT received w/o AV", __func__);
       alarm_set_on_mloop(av_open_on_rc_timer, BTIF_TIMEOUT_AV_OPEN_ON_RC_MS,
                          btif_initiate_av_open_timer_timeout, NULL);
       btif_rc_handler(event, (tBTA_AV*)p_data);
       break;
 
     case BTA_AV_RC_BROWSE_OPEN_EVT:
-      BTIF_TRACE_DEBUG("BTA_AV_RC_BROWSE_OPEN_EVT received");
+      BTIF_TRACE_DEBUG("%s: BTA_AV_RC_BROWSE_OPEN_EVT received", __func__);
       btif_rc_handler(event, (tBTA_AV*)p_data);
       break;
 
@@ -415,8 +417,10 @@ static bool btif_av_state_idle_handler(btif_sm_event_t event, void* p_data) {
       // copy to avoid alignment problems
       memcpy(&req, p_data, sizeof(req));
 
-      BTIF_TRACE_WARNING("BTIF_AV_SINK_CONFIG_REQ_EVT %d %d", req.sample_rate,
-                         req.channel_count);
+      BTIF_TRACE_WARNING(
+          "%s: BTIF_AV_SINK_CONFIG_REQ_EVT sample_rate=%d "
+          "channel_count=%d",
+          __func__, req.sample_rate, req.channel_count);
       if (bt_av_sink_callbacks != NULL) {
         HAL_CBACK(bt_av_sink_callbacks, audio_config_cb, &(req.peer_bd),
                   req.sample_rate, req.channel_count);
@@ -427,8 +431,8 @@ static bool btif_av_state_idle_handler(btif_sm_event_t event, void* p_data) {
       tBTA_AV* p_bta_data = (tBTA_AV*)p_data;
       btav_connection_state_t state;
       btif_sm_state_t av_state;
-      BTIF_TRACE_DEBUG("status:%d, edr 0x%x", p_bta_data->open.status,
-                       p_bta_data->open.edr);
+      BTIF_TRACE_WARNING("%s: BTA_AV_OPEN_EVT status=%d, edr=0x%x", __func__,
+                         p_bta_data->open.status, p_bta_data->open.edr);
 
       if (p_bta_data->open.status == BTA_AV_SUCCESS) {
         state = BTAV_CONNECTION_STATE_CONNECTED;
@@ -437,7 +441,7 @@ static bool btif_av_state_idle_handler(btif_sm_event_t event, void* p_data) {
 
         btif_av_cb.peer_sep = p_bta_data->open.sep;
       } else {
-        BTIF_TRACE_WARNING("BTA_AV_OPEN_EVT::FAILED status: %d",
+        BTIF_TRACE_WARNING("%s: BTA_AV_OPEN_EVT::FAILED status=%d", __func__,
                            p_bta_data->open.status);
         state = BTAV_CONNECTION_STATE_DISCONNECTED;
         av_state = BTIF_AV_STATE_IDLE;
@@ -469,19 +473,20 @@ static bool btif_av_state_idle_handler(btif_sm_event_t event, void* p_data) {
       break;
 
     case BTA_AV_RC_CLOSE_EVT:
-      BTIF_TRACE_DEBUG("BTA_AV_RC_CLOSE_EVT: Stopping AV timer.");
+      BTIF_TRACE_DEBUG("%s: BTA_AV_RC_CLOSE_EVT: Stopping AV timer.", __func__);
       alarm_cancel(av_open_on_rc_timer);
       btif_rc_handler(event, (tBTA_AV*)p_data);
       break;
 
     case BTIF_AV_OFFLOAD_START_REQ_EVT:
       BTIF_TRACE_ERROR(
-          "BTIF_AV_OFFLOAD_START_REQ_EVT: Stream not Started IDLE");
+          "%s: BTIF_AV_OFFLOAD_START_REQ_EVT: Stream not Started IDLE",
+          __func__);
       btif_a2dp_on_offload_started(BTA_AV_FAIL);
       break;
 
     default:
-      BTIF_TRACE_WARNING("%s : unhandled event:%s", __func__,
+      BTIF_TRACE_WARNING("%s: unhandled event=%s", __func__,
                          dump_av_sm_event_name((btif_av_sm_event_t)event));
       return false;
   }
@@ -500,7 +505,7 @@ static bool btif_av_state_idle_handler(btif_sm_event_t event, void* p_data) {
  ******************************************************************************/
 
 static bool btif_av_state_opening_handler(btif_sm_event_t event, void* p_data) {
-  BTIF_TRACE_DEBUG("%s event:%s flags %x", __func__,
+  BTIF_TRACE_DEBUG("%s: event=%s flags=0x%x", __func__,
                    dump_av_sm_event_name((btif_av_sm_event_t)event),
                    btif_av_cb.flags);
 
@@ -515,7 +520,7 @@ static bool btif_av_state_opening_handler(btif_sm_event_t event, void* p_data) {
       break;
 
     case BTA_AV_REJECT_EVT:
-      BTIF_TRACE_DEBUG(" Received  BTA_AV_REJECT_EVT ");
+      BTIF_TRACE_WARNING("%s: Received BTA_AV_REJECT_EVT", __func__);
       btif_report_connection_state(BTAV_CONNECTION_STATE_DISCONNECTED,
                                    &(btif_av_cb.peer_bda));
       btif_sm_change_state(btif_av_cb.sm_handle, BTIF_AV_STATE_IDLE);
@@ -525,8 +530,8 @@ static bool btif_av_state_opening_handler(btif_sm_event_t event, void* p_data) {
       tBTA_AV* p_bta_data = (tBTA_AV*)p_data;
       btav_connection_state_t state;
       btif_sm_state_t av_state;
-      BTIF_TRACE_DEBUG("status:%d, edr 0x%x", p_bta_data->open.status,
-                       p_bta_data->open.edr);
+      BTIF_TRACE_WARNING("%s: BTA_AV_OPEN_EVT status=%d, edr=0x%x", __func__,
+                         p_bta_data->open.status, p_bta_data->open.edr);
 
       if (p_bta_data->open.status == BTA_AV_SUCCESS) {
         state = BTAV_CONNECTION_STATE_CONNECTED;
@@ -535,7 +540,7 @@ static bool btif_av_state_opening_handler(btif_sm_event_t event, void* p_data) {
 
         btif_av_cb.peer_sep = p_bta_data->open.sep;
       } else {
-        BTIF_TRACE_WARNING("BTA_AV_OPEN_EVT::FAILED status: %d",
+        BTIF_TRACE_WARNING("%s: BTA_AV_OPEN_EVT::FAILED status: %d", __func__,
                            p_bta_data->open.status);
         RawAddress peer_addr;
         uint8_t peer_handle = BTRC_HANDLE_NONE;
@@ -545,7 +550,8 @@ static bool btif_av_state_opening_handler(btif_sm_event_t event, void* p_data) {
            * Disconnect AVRCP connection, if
            * A2DP conneciton failed, for any reason
            */
-          BTIF_TRACE_WARNING(" Disconnecting AVRCP ");
+          BTIF_TRACE_WARNING("%s: Disconnecting AVRCP: peer_addr=%s", __func__,
+                             peer_addr.ToString().c_str());
           peer_handle = btif_rc_get_connected_peer_handle(peer_addr);
           if (peer_handle != BTRC_HANDLE_NONE) {
             BTA_AvCloseRc(peer_handle);
@@ -585,8 +591,10 @@ static bool btif_av_state_opening_handler(btif_sm_event_t event, void* p_data) {
       // copy to avoid alignment problems
       memcpy(&req, p_data, sizeof(req));
 
-      BTIF_TRACE_WARNING("BTIF_AV_SINK_CONFIG_REQ_EVT %d %d", req.sample_rate,
-                         req.channel_count);
+      BTIF_TRACE_WARNING(
+          "%s: BTIF_AV_SINK_CONFIG_REQ_EVT sample_rate=%d "
+          "channel_count=%d",
+          __func__, req.sample_rate, req.channel_count);
       if (btif_av_cb.peer_sep == AVDT_TSEP_SRC &&
           bt_av_sink_callbacks != NULL) {
         HAL_CBACK(bt_av_sink_callbacks, audio_config_cb, &(btif_av_cb.peer_bda),
@@ -598,38 +606,42 @@ static bool btif_av_state_opening_handler(btif_sm_event_t event, void* p_data) {
       // Check for device, if same device which moved to opening then ignore
       // callback
       btif_av_connect_req_t* connect_req_p = (btif_av_connect_req_t*)p_data;
-      if (btif_av_cb.peer_bda == *connect_req_p->target_bda) {
-        BTIF_TRACE_DEBUG(
-            "%s: Same device moved to Opening state,ignore Connect Req",
-            __func__);
+      RawAddress& target_bda = *connect_req_p->target_bda;
+      if (btif_av_cb.peer_bda == target_bda) {
+        BTIF_TRACE_WARNING(
+            "%s: Same device moved to Opening state, ignore Connect request: "
+            "target_bda=%s",
+            __func__, target_bda.ToString().c_str());
       } else {
-        BTIF_TRACE_DEBUG("%s: Moved from idle by Incoming Connection request",
-                         __func__);
-        btif_report_connection_state(
-            BTAV_CONNECTION_STATE_DISCONNECTED,
-            ((btif_av_connect_req_t*)p_data)->target_bda);
+        BTIF_TRACE_WARNING("%s: Moved from idle by incoming Connect request: ",
+                           "target_bda=%s", __func__,
+                           target_bda.ToString().c_str());
+        btif_report_connection_state(BTAV_CONNECTION_STATE_DISCONNECTED,
+                                     &target_bda);
       }
       btif_queue_advance();
     } break;
 
-    case BTA_AV_PENDING_EVT:
+    case BTA_AV_PENDING_EVT: {
       // Check for device, if same device which moved to opening then ignore
       // callback
-      if (((tBTA_AV*)p_data)->pend.bd_addr == btif_av_cb.peer_bda) {
-        BTIF_TRACE_DEBUG(
-            "%s: Same device moved to Opening state,ignore Pending Req",
-            __func__);
-        break;
+      const RawAddress& bd_addr = ((tBTA_AV*)p_data)->pend.bd_addr;
+      if (bd_addr == btif_av_cb.peer_bda) {
+        BTIF_TRACE_WARNING(
+            "%s: Same device moved to Opening state, ignore Pending request: ",
+            "bd_addr=%s", __func__, bd_addr.ToString().c_str());
       } else {
-        BTIF_TRACE_DEBUG("%s: Moved from idle by outgoing Connection request",
-                         __func__);
-        BTA_AvDisconnect(((tBTA_AV*)p_data)->pend.bd_addr);
-        break;
+        BTIF_TRACE_WARNING(
+            "%s: Moved from idle by outgoing Connection request: bd_addr=%s",
+            __func__, bd_addr.ToString().c_str());
+        BTA_AvDisconnect(bd_addr);
       }
+    } break;
 
     case BTIF_AV_OFFLOAD_START_REQ_EVT:
       BTIF_TRACE_ERROR(
-          "BTIF_AV_OFFLOAD_START_REQ_EVT: Stream not Started OPENING");
+          "%s: BTIF_AV_OFFLOAD_START_REQ_EVT: Stream not Started OPENING",
+          __func__);
       btif_a2dp_on_offload_started(BTA_AV_FAIL);
       break;
 
@@ -643,7 +655,7 @@ static bool btif_av_state_opening_handler(btif_sm_event_t event, void* p_data) {
       CHECK_RC_EVENT(event, (tBTA_AV*)p_data);
 
     default:
-      BTIF_TRACE_WARNING("%s : unhandled event:%s", __func__,
+      BTIF_TRACE_WARNING("%s: unhandled event=%s", __func__,
                          dump_av_sm_event_name((btif_av_sm_event_t)event));
       return false;
   }
@@ -662,7 +674,7 @@ static bool btif_av_state_opening_handler(btif_sm_event_t event, void* p_data) {
  ******************************************************************************/
 
 static bool btif_av_state_closing_handler(btif_sm_event_t event, void* p_data) {
-  BTIF_TRACE_DEBUG("%s event:%s flags %x", __func__,
+  BTIF_TRACE_DEBUG("%s: event=%s flags=0x%x", __func__,
                    dump_av_sm_event_name((btif_av_sm_event_t)event),
                    btif_av_cb.flags);
 
@@ -715,12 +727,13 @@ static bool btif_av_state_closing_handler(btif_sm_event_t event, void* p_data) {
 
     case BTIF_AV_OFFLOAD_START_REQ_EVT:
       BTIF_TRACE_ERROR(
-          "BTIF_AV_OFFLOAD_START_REQ_EVT: Stream not Started Closing");
+          "%s: BTIF_AV_OFFLOAD_START_REQ_EVT: Stream not Started Closing",
+          __func__);
       btif_a2dp_on_offload_started(BTA_AV_FAIL);
       break;
 
     default:
-      BTIF_TRACE_WARNING("%s : unhandled event:%s", __func__,
+      BTIF_TRACE_WARNING("%s: unhandled event=%s", __func__,
                          dump_av_sm_event_name((btif_av_sm_event_t)event));
       return false;
   }
@@ -740,7 +753,7 @@ static bool btif_av_state_closing_handler(btif_sm_event_t event, void* p_data) {
 static bool btif_av_state_opened_handler(btif_sm_event_t event, void* p_data) {
   tBTA_AV* p_av = (tBTA_AV*)p_data;
 
-  BTIF_TRACE_DEBUG("%s event:%s flags %x", __func__,
+  BTIF_TRACE_DEBUG("%s: event=%s flags=0x%x", __func__,
                    dump_av_sm_event_name((btif_av_sm_event_t)event),
                    btif_av_cb.flags);
 
@@ -768,9 +781,11 @@ static bool btif_av_state_opened_handler(btif_sm_event_t event, void* p_data) {
       break;
 
     case BTA_AV_START_EVT: {
-      BTIF_TRACE_EVENT("BTA_AV_START_EVT status %d, suspending %d, init %d",
-                       p_av->start.status, p_av->start.suspending,
-                       p_av->start.initiator);
+      BTIF_TRACE_WARNING(
+          "%s: BTA_AV_START_EVT status=%d suspending=%d initiator=%d "
+          "flags=0x%x",
+          __func__, p_av->start.status, p_av->start.suspending,
+          p_av->start.initiator, btif_av_cb.flags);
 
       if ((p_av->start.status == BTA_SUCCESS) &&
           (p_av->start.suspending == true))
@@ -782,8 +797,8 @@ static bool btif_av_state_opened_handler(btif_sm_event_t event, void* p_data) {
        */
       if (!(btif_av_cb.flags & BTIF_AV_FLAG_PENDING_START)) {
         if (btif_av_cb.peer_sep == AVDT_TSEP_SNK) {
-          BTIF_TRACE_EVENT("%s: trigger suspend as remote initiated!!",
-                           __func__);
+          BTIF_TRACE_WARNING("%s: trigger suspend as remote initiated!!",
+                             __func__);
           btif_dispatch_sm_event(BTIF_AV_SUSPEND_STREAM_REQ_EVT, NULL, 0);
         }
       }
@@ -864,28 +879,33 @@ static bool btif_av_state_opened_handler(btif_sm_event_t event, void* p_data) {
 
     case BTIF_AV_CONNECT_REQ_EVT: {
       btif_av_connect_req_t* connect_req_p = (btif_av_connect_req_t*)p_data;
-      if (btif_av_cb.peer_bda == *connect_req_p->target_bda) {
-        BTIF_TRACE_DEBUG("%s: Ignore BTIF_AV_CONNECT_REQ_EVT for same device",
-                         __func__);
+      RawAddress& target_bda = *connect_req_p->target_bda;
+      if (btif_av_cb.peer_bda == target_bda) {
+        BTIF_TRACE_WARNING(
+            "%s: Ignore BTIF_AV_CONNECT_REQ_EVT for same device: target_bda=%s",
+            __func__, target_bda.ToString().c_str());
       } else {
-        BTIF_TRACE_DEBUG("%s: Moved to opened by Other Incoming Conn req",
-                         __func__);
+        BTIF_TRACE_WARNING(
+            "%s: Moved to opened by Other incoming Connect request: "
+            "target_bda=%s",
+            __func__, target_bda.ToString().c_str());
         btif_report_connection_state(BTAV_CONNECTION_STATE_DISCONNECTED,
-                                     (RawAddress*)p_data);
+                                     &target_bda);
       }
       btif_queue_advance();
     } break;
 
     case BTIF_AV_OFFLOAD_START_REQ_EVT:
       BTIF_TRACE_ERROR(
-          "BTIF_AV_OFFLOAD_START_REQ_EVT: Stream not Started Opened");
+          "%s: BTIF_AV_OFFLOAD_START_REQ_EVT: Stream not Started Opened",
+          __func__);
       btif_a2dp_on_offload_started(BTA_AV_FAIL);
       break;
 
       CHECK_RC_EVENT(event, (tBTA_AV*)p_data);
 
     default:
-      BTIF_TRACE_WARNING("%s : unhandled event:%s", __func__,
+      BTIF_TRACE_WARNING("%s: unhandled event=%s", __func__,
                          dump_av_sm_event_name((btif_av_sm_event_t)event));
       return false;
   }
@@ -905,7 +925,7 @@ static bool btif_av_state_opened_handler(btif_sm_event_t event, void* p_data) {
 static bool btif_av_state_started_handler(btif_sm_event_t event, void* p_data) {
   tBTA_AV* p_av = (tBTA_AV*)p_data;
 
-  BTIF_TRACE_DEBUG("%s event:%s flags %x", __func__,
+  BTIF_TRACE_DEBUG("%s: event=%s flags=0x%x", __func__,
                    dump_av_sm_event_name((btif_av_sm_event_t)event),
                    btif_av_cb.flags);
 
@@ -943,7 +963,9 @@ static bool btif_av_state_started_handler(btif_sm_event_t event, void* p_data) {
     /* fixme -- use suspend = true always to work around issue with BTA AV */
     case BTIF_AV_STOP_STREAM_REQ_EVT:
     case BTIF_AV_SUSPEND_STREAM_REQ_EVT:
-
+      BTIF_TRACE_WARNING("%s: event=%s flags=0x%x", __func__,
+                         dump_av_sm_event_name((btif_av_sm_event_t)event),
+                         btif_av_cb.flags);
       /* set pending flag to ensure btif task is not trying to restart
          stream while suspend is in progress */
       btif_av_cb.flags |= BTIF_AV_FLAG_LOCAL_SUSPEND_PENDING;
@@ -968,6 +990,9 @@ static bool btif_av_state_started_handler(btif_sm_event_t event, void* p_data) {
       break;
 
     case BTIF_AV_DISCONNECT_REQ_EVT:
+      BTIF_TRACE_WARNING("%s: event=%s flags=0x%x", __func__,
+                         dump_av_sm_event_name((btif_av_sm_event_t)event),
+                         btif_av_cb.flags);
 
       /* request avdtp to close */
       BTA_AvClose(btif_av_cb.bta_handle);
@@ -984,9 +1009,9 @@ static bool btif_av_state_started_handler(btif_sm_event_t event, void* p_data) {
       break;
 
     case BTA_AV_SUSPEND_EVT:
-
-      BTIF_TRACE_EVENT("BTA_AV_SUSPEND_EVT status %d, init %d",
-                       p_av->suspend.status, p_av->suspend.initiator);
+      BTIF_TRACE_WARNING(
+          "%s: BTA_AV_SUSPEND_EVT status=%d initiator=%d flags=0x%x", __func__,
+          p_av->suspend.status, p_av->suspend.initiator, btif_av_cb.flags);
 
       /* a2dp suspended, stop media task until resumed */
       btif_a2dp_on_suspended(&p_av->suspend);
@@ -1025,6 +1050,9 @@ static bool btif_av_state_started_handler(btif_sm_event_t event, void* p_data) {
       break;
 
     case BTA_AV_STOP_EVT:
+      BTIF_TRACE_WARNING("%s: event=%s flags=0x%x", __func__,
+                         dump_av_sm_event_name((btif_av_sm_event_t)event),
+                         btif_av_cb.flags);
 
       btif_av_cb.flags |= BTIF_AV_FLAG_PENDING_STOP;
       btif_a2dp_on_stopped(&p_av->suspend);
@@ -1038,6 +1066,9 @@ static bool btif_av_state_started_handler(btif_sm_event_t event, void* p_data) {
       break;
 
     case BTA_AV_CLOSE_EVT:
+      BTIF_TRACE_WARNING("%s: event=%s flags=0x%x", __func__,
+                         dump_av_sm_event_name((btif_av_sm_event_t)event),
+                         btif_av_cb.flags);
 
       btif_av_cb.flags |= BTIF_AV_FLAG_PENDING_STOP;
 
@@ -1062,7 +1093,7 @@ static bool btif_av_state_started_handler(btif_sm_event_t event, void* p_data) {
       CHECK_RC_EVENT(event, (tBTA_AV*)p_data);
 
     default:
-      BTIF_TRACE_WARNING("%s: unhandled event: %s", __func__,
+      BTIF_TRACE_WARNING("%s: unhandled event=%s", __func__,
                          dump_av_sm_event_name((btif_av_sm_event_t)event));
       return false;
   }
@@ -1075,7 +1106,7 @@ static bool btif_av_state_started_handler(btif_sm_event_t event, void* p_data) {
  *****************************************************************************/
 
 static void btif_av_handle_event(uint16_t event, char* p_param) {
-  BTIF_TRACE_EVENT("%s event:%s", __func__,
+  BTIF_TRACE_EVENT("%s: event=%s", __func__,
                    dump_av_sm_event_name((btif_av_sm_event_t)event));
   switch (event) {
     case BTIF_AV_CLEANUP_REQ_EVT:
@@ -1248,7 +1279,7 @@ bt_status_t btif_av_init(int service_id) {
 static bt_status_t init_src(
     btav_source_callbacks_t* callbacks,
     std::vector<btav_a2dp_codec_config_t> codec_priorities) {
-  BTIF_TRACE_EVENT("%s()", __func__);
+  BTIF_TRACE_EVENT("%s", __func__);
 
   btif_av_cb.codec_priorities = codec_priorities;
   bt_status_t status = btif_av_init(BTA_A2DP_SOURCE_SERVICE_ID);
@@ -1268,7 +1299,7 @@ static bt_status_t init_src(
  ******************************************************************************/
 
 static bt_status_t init_sink(btav_sink_callbacks_t* callbacks) {
-  BTIF_TRACE_EVENT("%s()", __func__);
+  BTIF_TRACE_EVENT("%s", __func__);
 
   bt_status_t status = btif_av_init(BTA_A2DP_SINK_SERVICE_ID);
   if (status == BT_STATUS_SUCCESS) bt_av_sink_callbacks = callbacks;
@@ -1287,7 +1318,7 @@ static bt_status_t init_sink(btav_sink_callbacks_t* callbacks) {
  *
  ******************************************************************************/
 static void update_audio_focus_state(int state) {
-  BTIF_TRACE_DEBUG("%s: state %d", __func__, state);
+  BTIF_TRACE_DEBUG("%s: state=%d", __func__, state);
   btif_a2dp_sink_set_focus_state_req((btif_a2dp_sink_focus_state_t)state);
 }
 
@@ -1301,7 +1332,7 @@ static void update_audio_focus_state(int state) {
  *
  ******************************************************************************/
 static void update_audio_track_gain(float gain) {
-  BTIF_TRACE_DEBUG("%s: gain %f", __func__, gain);
+  BTIF_TRACE_DEBUG("%s: gain=%f", __func__, gain);
   btif_a2dp_sink_set_audio_track_gain(gain);
 }
 
@@ -1484,12 +1515,12 @@ bool btif_av_is_sink_enabled(void) {
 bool btif_av_stream_ready(void) {
   btif_sm_state_t state = btif_sm_get_state(btif_av_cb.sm_handle);
 
-  BTIF_TRACE_DEBUG("btif_av_stream_ready : sm hdl %d, state %d, flags %x",
+  BTIF_TRACE_DEBUG("%s: sm_handle=%d, state=%d, flags=0x%x", __func__,
                    btif_av_cb.sm_handle, state, btif_av_cb.flags);
 
   /* also make sure main adapter is enabled */
   if (btif_is_enabled() == 0) {
-    BTIF_TRACE_EVENT("main adapter not enabled");
+    BTIF_TRACE_EVENT("%s: main adapter not enabled", __func__);
     return false;
   }
 
@@ -1513,17 +1544,21 @@ bool btif_av_stream_ready(void) {
 
 bool btif_av_stream_started_ready(void) {
   btif_sm_state_t state = btif_sm_get_state(btif_av_cb.sm_handle);
-
-  BTIF_TRACE_DEBUG("btif_av_stream_started : sm hdl %d, state %d, flags %x",
-                   btif_av_cb.sm_handle, state, btif_av_cb.flags);
+  bool ready = false;
 
   /* disallow media task to start if we have pending actions */
   if (btif_av_cb.flags &
       (BTIF_AV_FLAG_LOCAL_SUSPEND_PENDING | BTIF_AV_FLAG_REMOTE_SUSPEND |
-       BTIF_AV_FLAG_PENDING_STOP))
-    return false;
+       BTIF_AV_FLAG_PENDING_STOP)) {
+    ready = false;
+  } else {
+    ready = (state == BTIF_AV_STATE_STARTED);
+  }
 
-  return (state == BTIF_AV_STATE_STARTED);
+  BTIF_TRACE_WARNING("%s: sm_handle=%d state=%d flags=0x%x ready=%d", __func__,
+                     btif_av_cb.sm_handle, state, btif_av_cb.flags, ready);
+
+  return ready;
 }
 
 /*******************************************************************************
@@ -1688,7 +1723,7 @@ bool btif_av_is_peer_edr(void) {
  * Returns          void
  *****************************************************************************/
 void btif_av_clear_remote_suspend_flag(void) {
-  BTIF_TRACE_DEBUG("%s: flag :%x", __func__, btif_av_cb.flags);
+  BTIF_TRACE_DEBUG("%s: flags=0x%x", __func__, btif_av_cb.flags);
   btif_av_cb.flags &= ~BTIF_AV_FLAG_REMOTE_SUSPEND;
 }
 
@@ -1725,11 +1760,11 @@ bool btif_av_peer_supports_3mbps(void) {
 void btif_av_move_idle(RawAddress bd_addr) {
   /* inform the application that ACL is disconnected and move to idle state */
   btif_sm_state_t state = btif_sm_get_state(btif_av_cb.sm_handle);
-  BTIF_TRACE_DEBUG("%s: ACL Disconnected state %d  is same device %d", __func__,
-                   state,
-                   memcmp(&bd_addr, &(btif_av_cb.peer_bda), sizeof(bd_addr)));
-  if (state == BTIF_AV_STATE_OPENING &&
-      (memcmp(&bd_addr, &(btif_av_cb.peer_bda), sizeof(bd_addr)) == 0)) {
+  BTIF_TRACE_WARNING("%s: ACL Disconnected state %d bd_addr=%s peer_bda=%s",
+                     __func__, state, bd_addr.ToString().c_str(),
+                     btif_av_cb.peer_bda.ToString().c_str());
+
+  if (state == BTIF_AV_STATE_OPENING && (bd_addr == btif_av_cb.peer_bda)) {
     BTIF_TRACE_DEBUG(
         "%s: Moving State from Opening to Idle due to ACL disconnect",
         __func__);
diff --git a/stack/avdt/avdt_api.cc b/stack/avdt/avdt_api.cc
index 26e0c29ee..a50784174 100644
--- a/stack/avdt/avdt_api.cc
+++ b/stack/avdt/avdt_api.cc
@@ -1043,7 +1043,7 @@ uint16_t AVDT_DisconnectReq(const RawAddress& bd_addr,
   uint16_t result = AVDT_SUCCESS;
   tAVDT_CCB_EVT evt;
 
-  AVDT_TRACE_DEBUG("%s", __func__);
+  AVDT_TRACE_WARNING("%s: address=%s", __func__, bd_addr.ToString().c_str());
 
   /* find channel control block for this bd addr; if none, error */
   p_ccb = avdt_ccb_by_bd(bd_addr);
@@ -1057,7 +1057,8 @@ uint16_t AVDT_DisconnectReq(const RawAddress& bd_addr,
     avdt_ccb_event(p_ccb, AVDT_CCB_API_DISCONNECT_REQ_EVT, &evt);
   }
 
-  AVDT_TRACE_DEBUG("%s: result=%d", __func__, result);
+  AVDT_TRACE_DEBUG("%s: address=%s result=%d", __func__,
+                   bd_addr.ToString().c_str(), result);
 
   return result;
 }