From c64dc1d28496b5e917d0f82317d40d3c60e6495d Mon Sep 17 00:00:00 2001
From: Pavlin Radoslavov <pavlin@google.com>
Date: Wed, 2 Aug 2017 13:52:14 -0700
Subject: [PATCH] Don't reuse AVDTP internal state for different purposes

A number of issues were exposed by carkits that proactively try
to discover the codecs supported by the Phone and explicitly select
the A2DP codec.

* Don't reuse p_scb->p_cap for storing the most recent fetched capability
  and for storing the result configuration while reconfiguring the stream.
  Instead, use p_scb->cfg for storing the result configuration.
* Don't try to reconfigure the audio stream before all peer's capabilities
  have been retrieved.
* Don't reset p_scb->sep_info_idx after fetching all capabilities inside
  bta_av_save_caps(), otherwise the stream reconfiguration logic is
  confused. Apparently, p_scb->sep_info_idx is overused for both:
  (a) Pointing where to store the next capability while fetching the
      capabilities.
  (b) Storing the selected the SEP after the codec selection is completed.
  Resetting p_scb->sep_info_idx to 0 creates logical confusion when the
  actual selected SEP index is 0.
* Add extra debug log messages

Test: Connecting to and streaming with various carkits
Bug: 64128712
Change-Id: I5f57e9069d5402bcbb17613470ac0d29c8e45069
---
 bta/av/bta_av_aact.cc      |  50 +++++++++++++++-----
 btif/co/bta_av_co.cc       |  34 ++++++++++++--
 stack/avdt/avdt_api.cc     | 112 +++++++++++++++++++++++++++++++++++++++++++--
 stack/avdt/avdt_ccb.cc     |   6 +--
 stack/avdt/avdt_ccb_act.cc |   5 ++
 stack/avdt/avdt_scb_act.cc |  14 ++++++
 6 files changed, 200 insertions(+), 21 deletions(-)

diff --git a/bta/av/bta_av_aact.cc b/bta/av/bta_av_aact.cc
index 2b94e2bd6..ed8ee3091 100644
--- a/bta/av/bta_av_aact.cc
+++ b/bta/av/bta_av_aact.cc
@@ -1097,6 +1097,10 @@ void bta_av_config_ind(tBTA_AV_SCB* p_scb, tBTA_AV_DATA* p_data) {
 
   local_sep = bta_av_get_scb_sep_type(p_scb, p_msg->handle);
   p_scb->avdt_label = p_data->str_msg.msg.hdr.label;
+
+  APPL_TRACE_DEBUG("%s: local_sep = %d", __func__, local_sep);
+  A2DP_DumpCodecInfo(p_evt_cfg->codec_info);
+
   memcpy(p_scb->cfg.codec_info, p_evt_cfg->codec_info, AVDT_CODEC_SIZE);
   bta_av_save_addr(p_scb, p_data->str_msg.bd_addr);
 
@@ -1456,6 +1460,8 @@ void bta_av_security_cfm(tBTA_AV_SCB* p_scb, tBTA_AV_DATA* p_data) {
  *
  ******************************************************************************/
 void bta_av_do_close(tBTA_AV_SCB* p_scb, UNUSED_ATTR tBTA_AV_DATA* p_data) {
+  APPL_TRACE_DEBUG("%s: p_scb->co_started=%d", __func__, p_scb->co_started);
+
   /* stop stream if started */
   if (p_scb->co_started) {
     bta_av_str_stopped(p_scb, NULL);
@@ -1634,12 +1640,18 @@ void bta_av_save_caps(tBTA_AV_SCB* p_scb, tBTA_AV_DATA* p_data) {
 
   APPL_TRACE_DEBUG("%s: num_seps:%d sep_info_idx:%d wait:x%x", __func__,
                    p_scb->num_seps, p_scb->sep_info_idx, p_scb->wait);
+  A2DP_DumpCodecInfo(p_scb->p_cap->codec_info);
+
   memcpy(&cfg, p_scb->p_cap, sizeof(tAVDT_CFG));
   /* let application know the capability of the SNK */
   p_scb->p_cos->getcfg(p_scb->hndl, cfg.codec_info, &p_scb->sep_info_idx,
                        p_info->seid, &cfg.num_protect, cfg.protect_info);
 
   p_scb->sep_info_idx++;
+  APPL_TRACE_DEBUG("%s: result: sep_info_idx:%d", __func__,
+                   p_scb->sep_info_idx);
+  A2DP_DumpCodecInfo(cfg.codec_info);
+
   if (p_scb->num_seps > p_scb->sep_info_idx) {
     /* Some devices have seps at the end of the discover list, which is not */
     /* matching media type(video not audio).                                */
@@ -1650,8 +1662,9 @@ void bta_av_save_caps(tBTA_AV_SCB* p_scb, tBTA_AV_DATA* p_data) {
     getcap_done = true;
 
   if (getcap_done) {
-    /* we are done getting capabilities. restore the p_cb->sep_info_idx */
-    p_scb->sep_info_idx = 0;
+    APPL_TRACE_DEBUG("%s: getcap_done: num_seps:%d sep_info_idx:%d wait:x%x",
+                     __func__, p_scb->num_seps, p_scb->sep_info_idx,
+                     p_scb->wait);
     p_scb->wait &= ~(BTA_AV_WAIT_ACP_CAPS_ON | BTA_AV_WAIT_ACP_CAPS_STARTED);
     if (old_wait & BTA_AV_WAIT_ACP_CAPS_STARTED) {
       bta_av_start_ok(p_scb, NULL);
@@ -1769,6 +1782,7 @@ void bta_av_getcap_results(tBTA_AV_SCB* p_scb, tBTA_AV_DATA* p_data) {
   APPL_TRACE_DEBUG("%s: num_codec %d", __func__, p_scb->p_cap->num_codec);
   APPL_TRACE_DEBUG("%s: media type x%x, x%x", __func__, media_type,
                    p_scb->media_type);
+  A2DP_DumpCodecInfo(p_scb->cfg.codec_info);
 
   /* if codec present and we get a codec configuration */
   if ((p_scb->p_cap->num_codec != 0) && (media_type == p_scb->media_type) &&
@@ -1778,6 +1792,10 @@ void bta_av_getcap_results(tBTA_AV_SCB* p_scb, tBTA_AV_DATA* p_data) {
     /* save copy of codec configuration */
     memcpy(&p_scb->cfg, &cfg, sizeof(tAVDT_CFG));
 
+    APPL_TRACE_DEBUG("%s: result: sep_info_idx=%d", __func__,
+                     p_scb->sep_info_idx);
+    A2DP_DumpCodecInfo(p_scb->cfg.codec_info);
+
     uuid_int = p_scb->uuid_int;
     APPL_TRACE_DEBUG("%s: initiator UUID = 0x%x", __func__, uuid_int);
     if (uuid_int == UUID_SERVCLASS_AUDIO_SOURCE)
@@ -2036,16 +2054,22 @@ void bta_av_reconfig(tBTA_AV_SCB* p_scb, tBTA_AV_DATA* p_data) {
   /* store the new configuration in control block */
   if (p_scb->p_cap == NULL)
     p_scb->p_cap = (tAVDT_CFG*)osi_malloc(sizeof(tAVDT_CFG));
-  p_cfg = p_scb->p_cap;
+  p_cfg = &p_scb->cfg;
 
   alarm_cancel(p_scb->avrc_ct_timer);
 
-  memcpy(p_cfg, &p_scb->cfg, sizeof(tAVDT_CFG));
+  APPL_TRACE_DEBUG(
+      "%s: p_scb->sep_info_idx=%d p_scb->rcfg_idx=%d p_rcfg->sep_info_idx=%d",
+      __func__, p_scb->sep_info_idx, p_scb->rcfg_idx, p_rcfg->sep_info_idx);
+  A2DP_DumpCodecInfo(p_scb->p_cap->codec_info);
+  A2DP_DumpCodecInfo(p_scb->cfg.codec_info);
+  A2DP_DumpCodecInfo(p_rcfg->codec_info);
+
   p_cfg->num_protect = p_rcfg->num_protect;
   memcpy(p_cfg->codec_info, p_rcfg->codec_info, AVDT_CODEC_SIZE);
   memcpy(p_cfg->protect_info, p_rcfg->p_protect_info, p_rcfg->num_protect);
   p_scb->rcfg_idx = p_rcfg->sep_info_idx;
-  p_scb->p_cap->psc_mask = p_scb->cur_psc_mask;
+  p_cfg->psc_mask = p_scb->cur_psc_mask;
 
   // If the requested SEP index is same as the current one, then we
   // can Suspend->Reconfigure->Start.
@@ -2062,8 +2086,9 @@ void bta_av_reconfig(tBTA_AV_SCB* p_scb, tBTA_AV_DATA* p_data) {
     } else {
       // Reconfigure
       APPL_TRACE_DEBUG("%s: reconfig", __func__);
-      AVDT_ReconfigReq(p_scb->avdt_handle, p_scb->p_cap);
-      p_scb->p_cap->psc_mask = p_scb->cur_psc_mask;
+      A2DP_DumpCodecInfo(p_scb->cfg.codec_info);
+      AVDT_ReconfigReq(p_scb->avdt_handle, &p_scb->cfg);
+      p_scb->cfg.psc_mask = p_scb->cur_psc_mask;
     }
   } else {
     // Close the stream first, and then Configure it
@@ -2731,8 +2756,9 @@ void bta_av_suspend_cont(tBTA_AV_SCB* p_scb, tBTA_AV_DATA* p_data) {
     APPL_TRACE_DEBUG("%s: calling AVDT_ReconfigReq", __func__);
     /* reconfig the stream */
 
-    AVDT_ReconfigReq(p_scb->avdt_handle, p_scb->p_cap);
-    p_scb->p_cap->psc_mask = p_scb->cur_psc_mask;
+    A2DP_DumpCodecInfo(p_scb->cfg.codec_info);
+    AVDT_ReconfigReq(p_scb->avdt_handle, &p_scb->cfg);
+    p_scb->cfg.psc_mask = p_scb->cur_psc_mask;
   }
 }
 
@@ -2817,7 +2843,9 @@ void bta_av_rcfg_open(tBTA_AV_SCB* p_scb, UNUSED_ATTR tBTA_AV_DATA* p_data) {
     AVDT_DiscoverReq(p_scb->peer_addr, p_scb->sep_info, BTA_AV_NUM_SEPS,
                      bta_av_dt_cback[p_scb->hdi]);
   } else {
-    memcpy(p_scb->cfg.codec_info, p_scb->p_cap->codec_info, AVDT_CODEC_SIZE);
+    APPL_TRACE_DEBUG("%s: calling AVDT_OpenReq()", __func__);
+    A2DP_DumpCodecInfo(p_scb->cfg.codec_info);
+
     /* we may choose to use a different SEP at reconfig.
      * adjust the sep_idx now */
     bta_av_adjust_seps_idx(p_scb, bta_av_get_scb_handle(p_scb, AVDT_TSEP_SRC));
@@ -2825,7 +2853,7 @@ void bta_av_rcfg_open(tBTA_AV_SCB* p_scb, UNUSED_ATTR tBTA_AV_DATA* p_data) {
     /* open the stream with the new config */
     p_scb->sep_info_idx = p_scb->rcfg_idx;
     AVDT_OpenReq(p_scb->avdt_handle, p_scb->peer_addr,
-                 p_scb->sep_info[p_scb->sep_info_idx].seid, p_scb->p_cap);
+                 p_scb->sep_info[p_scb->sep_info_idx].seid, &p_scb->cfg);
   }
 }
 
diff --git a/btif/co/bta_av_co.cc b/btif/co/bta_av_co.cc
index 76b01992d..687499a33 100644
--- a/btif/co/bta_av_co.cc
+++ b/btif/co/bta_av_co.cc
@@ -395,6 +395,7 @@ tA2DP_STATUS bta_av_co_audio_getconfig(tBTA_AV_HNDL hndl, uint8_t* p_codec_info,
   tBTA_AV_CO_PEER* p_peer;
 
   APPL_TRACE_DEBUG("%s", __func__);
+  A2DP_DumpCodecInfo(p_codec_info);
 
   /* Retrieve the peer info */
   p_peer = bta_av_co_get_peer(hndl);
@@ -506,6 +507,7 @@ void bta_av_co_audio_setconfig(tBTA_AV_HNDL hndl, const uint8_t* p_codec_info,
   APPL_TRACE_DEBUG("num_protect:0x%02x protect_info:0x%02x%02x%02x",
                    num_protect, p_protect_info[0], p_protect_info[1],
                    p_protect_info[2]);
+  A2DP_DumpCodecInfo(p_codec_info);
 
   /* Retrieve the peer info */
   p_peer = bta_av_co_get_peer(hndl);
@@ -991,6 +993,9 @@ static void bta_av_co_save_new_codec_config(tBTA_AV_CO_PEER* p_peer,
                                             const uint8_t* new_codec_config,
                                             uint8_t num_protect,
                                             const uint8_t* p_protect_info) {
+  APPL_TRACE_DEBUG("%s", __func__);
+  A2DP_DumpCodecInfo(new_codec_config);
+
   // Protect access to bta_av_co_cb.codec_config
   mutex_global_lock();
 
@@ -1113,6 +1118,15 @@ bool bta_av_co_set_codec_user_config(
       success = false;
       goto done;
     }
+    // Don't call BTA_AvReconfig() prior to retrieving all peer's capabilities
+    if ((p_peer->num_rx_sinks != p_peer->num_sinks) &&
+        (p_peer->num_sup_sinks != BTA_AV_CO_NUM_ELEMENTS(p_peer->sinks))) {
+      APPL_TRACE_WARNING("%s: not all peer's capabilities have been retrieved",
+                         __func__);
+      success = false;
+      goto done;
+    }
+
     APPL_TRACE_DEBUG("%s: call BTA_AvReconfig(x%x)", __func__, p_peer->handle);
     BTA_AvReconfig(p_peer->handle, true, p_sink->sep_info_idx,
                    p_peer->codec_config, num_protect, bta_av_co_cp_scmst);
@@ -1153,6 +1167,9 @@ static bool bta_av_co_set_codec_ota_config(tBTA_AV_CO_PEER* p_peer,
   bool restart_output = false;
   bool config_updated = false;
 
+  APPL_TRACE_DEBUG("%s", __func__);
+  A2DP_DumpCodecInfo(p_ota_codec_config);
+
   *p_restart_output = false;
 
   // Find the peer SEP codec to use
@@ -1189,6 +1206,9 @@ static bool bta_av_co_set_codec_ota_config(tBTA_AV_CO_PEER* p_peer,
   }
 
   if (restart_output) {
+    APPL_TRACE_DEBUG("%s: restart output", __func__);
+    A2DP_DumpCodecInfo(result_codec_config);
+
     *p_restart_output = true;
     p_peer->p_sink = p_sink;
     bta_av_co_save_new_codec_config(p_peer, result_codec_config, num_protect,
@@ -1248,9 +1268,17 @@ bool bta_av_co_set_codec_audio_config(
     bta_av_co_save_new_codec_config(p_peer, result_codec_config,
                                     p_sink->num_protect, p_sink->protect_info);
 
-    APPL_TRACE_DEBUG("%s: call BTA_AvReconfig(x%x)", __func__, p_peer->handle);
-    BTA_AvReconfig(p_peer->handle, true, p_sink->sep_info_idx,
-                   p_peer->codec_config, num_protect, bta_av_co_cp_scmst);
+    // Don't call BTA_AvReconfig() prior to retrieving all peer's capabilities
+    if ((p_peer->num_rx_sinks != p_peer->num_sinks) &&
+        (p_peer->num_sup_sinks != BTA_AV_CO_NUM_ELEMENTS(p_peer->sinks))) {
+      APPL_TRACE_WARNING("%s: not all peer's capabilities have been retrieved",
+                         __func__);
+    } else {
+      APPL_TRACE_DEBUG("%s: call BTA_AvReconfig(x%x)", __func__,
+                       p_peer->handle);
+      BTA_AvReconfig(p_peer->handle, true, p_sink->sep_info_idx,
+                     p_peer->codec_config, num_protect, bta_av_co_cp_scmst);
+    }
   }
 
   if (config_updated) {
diff --git a/stack/avdt/avdt_api.cc b/stack/avdt/avdt_api.cc
index bf45ad3f3..5369f6ecf 100644
--- a/stack/avdt/avdt_api.cc
+++ b/stack/avdt/avdt_api.cc
@@ -32,6 +32,7 @@
 #include "btm_api.h"
 #include "btu.h"
 #include "l2c_api.h"
+#include "stack/include/a2dp_codec_api.h"
 
 /* Control block for AVDT */
 tAVDT_CB avdt_cb;
@@ -135,7 +136,7 @@ void AVDT_Deregister(void) {
 }
 
 void AVDT_AbortReq(uint8_t handle) {
-  AVDT_TRACE_ERROR("%s", __func__);
+  AVDT_TRACE_WARNING("%s: handle=%d", __func__, handle);
 
   tAVDT_SCB* p_scb = avdt_scb_by_hdl(handle);
   if (p_scb != NULL) {
@@ -163,6 +164,8 @@ uint16_t AVDT_CreateStream(uint8_t* p_handle, tAVDT_CS* p_cs) {
   uint16_t result = AVDT_SUCCESS;
   tAVDT_SCB* p_scb;
 
+  AVDT_TRACE_DEBUG("%s", __func__);
+
   /* Verify parameters; if invalid, return failure */
   if (((p_cs->cfg.psc_mask & (~AVDT_PSC)) != 0) ||
       (p_cs->p_ctrl_cback == NULL)) {
@@ -177,6 +180,9 @@ uint16_t AVDT_CreateStream(uint8_t* p_handle, tAVDT_CS* p_cs) {
       *p_handle = avdt_scb_to_hdl(p_scb);
     }
   }
+
+  AVDT_TRACE_DEBUG("%s: result=%d", __func__, result);
+
   return result;
 }
 
@@ -198,6 +204,8 @@ uint16_t AVDT_RemoveStream(uint8_t handle) {
   uint16_t result = AVDT_SUCCESS;
   tAVDT_SCB* p_scb;
 
+  AVDT_TRACE_DEBUG("%s: handle=%d", __func__, handle);
+
   /* look up scb */
   p_scb = avdt_scb_by_hdl(handle);
   if (p_scb == NULL) {
@@ -206,6 +214,9 @@ uint16_t AVDT_RemoveStream(uint8_t handle) {
     /* send remove event to scb */
     avdt_scb_event(p_scb, AVDT_SCB_API_REMOVE_EVT, NULL);
   }
+
+  AVDT_TRACE_DEBUG("%s: result=%d", __func__, result);
+
   return result;
 }
 
@@ -241,6 +252,8 @@ uint16_t AVDT_DiscoverReq(BD_ADDR bd_addr, tAVDT_SEP_INFO* p_sep_info,
   uint16_t result = AVDT_SUCCESS;
   tAVDT_CCB_EVT evt;
 
+  AVDT_TRACE_DEBUG("%s", __func__);
+
   /* find channel control block for this bd addr; if none, allocate one */
   p_ccb = avdt_ccb_by_bd(bd_addr);
   if (p_ccb == NULL) {
@@ -264,6 +277,9 @@ uint16_t AVDT_DiscoverReq(BD_ADDR bd_addr, tAVDT_SEP_INFO* p_sep_info,
       avdt_ccb_event(p_ccb, AVDT_CCB_API_DISCOVER_REQ_EVT, &evt);
     }
   }
+
+  AVDT_TRACE_DEBUG("%s: result=%d", __func__, result);
+
   return result;
 }
 
@@ -281,6 +297,8 @@ static uint16_t avdt_get_cap_req(BD_ADDR bd_addr, tAVDT_CCB_API_GETCAP* p_evt) {
   tAVDT_CCB* p_ccb = NULL;
   uint16_t result = AVDT_SUCCESS;
 
+  AVDT_TRACE_DEBUG("%s", __func__);
+
   /* verify SEID */
   if ((p_evt->single.seid < AVDT_SEID_MIN) ||
       (p_evt->single.seid > AVDT_SEID_MAX)) {
@@ -309,6 +327,9 @@ static uint16_t avdt_get_cap_req(BD_ADDR bd_addr, tAVDT_CCB_API_GETCAP* p_evt) {
       avdt_ccb_event(p_ccb, AVDT_CCB_API_GETCAP_REQ_EVT, (tAVDT_CCB_EVT*)p_evt);
     }
   }
+
+  AVDT_TRACE_DEBUG("%s: result=%d", __func__, result);
+
   return result;
 }
 
@@ -339,12 +360,19 @@ static uint16_t avdt_get_cap_req(BD_ADDR bd_addr, tAVDT_CCB_API_GETCAP* p_evt) {
 uint16_t AVDT_GetCapReq(BD_ADDR bd_addr, uint8_t seid, tAVDT_CFG* p_cfg,
                         tAVDT_CTRL_CBACK* p_cback) {
   tAVDT_CCB_API_GETCAP getcap;
+  uint16_t result = AVDT_SUCCESS;
+
+  AVDT_TRACE_DEBUG("%s", __func__);
 
   getcap.single.seid = seid;
   getcap.single.sig_id = AVDT_SIG_GETCAP;
   getcap.p_cfg = p_cfg;
   getcap.p_cback = p_cback;
-  return avdt_get_cap_req(bd_addr, &getcap);
+  result = avdt_get_cap_req(bd_addr, &getcap);
+
+  AVDT_TRACE_DEBUG("%s: result=%d", __func__, result);
+
+  return result;
 }
 
 /*******************************************************************************
@@ -374,12 +402,19 @@ uint16_t AVDT_GetCapReq(BD_ADDR bd_addr, uint8_t seid, tAVDT_CFG* p_cfg,
 uint16_t AVDT_GetAllCapReq(BD_ADDR bd_addr, uint8_t seid, tAVDT_CFG* p_cfg,
                            tAVDT_CTRL_CBACK* p_cback) {
   tAVDT_CCB_API_GETCAP getcap;
+  uint16_t result = AVDT_SUCCESS;
+
+  AVDT_TRACE_DEBUG("%s", __func__);
 
   getcap.single.seid = seid;
   getcap.single.sig_id = AVDT_SIG_GET_ALLCAP;
   getcap.p_cfg = p_cfg;
   getcap.p_cback = p_cback;
-  return avdt_get_cap_req(bd_addr, &getcap);
+  result = avdt_get_cap_req(bd_addr, &getcap);
+
+  AVDT_TRACE_DEBUG("%s: result=%d", __func__, result);
+
+  return result;
 }
 
 /*******************************************************************************
@@ -398,6 +433,9 @@ uint16_t AVDT_DelayReport(uint8_t handle, uint8_t seid, uint16_t delay) {
   uint16_t result = AVDT_SUCCESS;
   tAVDT_SCB_EVT evt;
 
+  AVDT_TRACE_DEBUG("%s: handle=%d ceid=%d delay=%d", __func__, handle, seid,
+                   delay);
+
   /* map handle to scb */
   p_scb = avdt_scb_by_hdl(handle);
   if (p_scb == NULL) {
@@ -410,6 +448,8 @@ uint16_t AVDT_DelayReport(uint8_t handle, uint8_t seid, uint16_t delay) {
     avdt_scb_event(p_scb, AVDT_SCB_API_DELAY_RPT_REQ_EVT, &evt);
   }
 
+  AVDT_TRACE_DEBUG("%s: result=%d", __func__, result);
+
   return result;
 }
 
@@ -434,6 +474,8 @@ uint16_t AVDT_OpenReq(uint8_t handle, BD_ADDR bd_addr, uint8_t seid,
   uint16_t result = AVDT_SUCCESS;
   tAVDT_SCB_EVT evt;
 
+  AVDT_TRACE_DEBUG("%s: handle=%d seid=%d", __func__, handle, seid);
+
   /* verify SEID */
   if ((seid < AVDT_SEID_MIN) || (seid > AVDT_SEID_MAX)) {
     result = AVDT_BAD_PARAMS;
@@ -459,12 +501,17 @@ uint16_t AVDT_OpenReq(uint8_t handle, BD_ADDR bd_addr, uint8_t seid,
 
   /* send event to scb */
   if (result == AVDT_SUCCESS) {
+    A2DP_DumpCodecInfo(p_cfg->codec_info);
+
     evt.msg.config_cmd.hdr.seid = seid;
     evt.msg.config_cmd.hdr.ccb_idx = avdt_ccb_to_idx(p_ccb);
     evt.msg.config_cmd.int_seid = handle;
     evt.msg.config_cmd.p_cfg = p_cfg;
     avdt_scb_event(p_scb, AVDT_SCB_API_SETCONFIG_REQ_EVT, &evt);
   }
+
+  AVDT_TRACE_DEBUG("%s: result=%d", __func__, result);
+
   return result;
 }
 
@@ -487,6 +534,9 @@ uint16_t AVDT_ConfigRsp(uint8_t handle, uint8_t label, uint8_t error_code,
   uint16_t result = AVDT_SUCCESS;
   uint8_t event_code;
 
+  AVDT_TRACE_DEBUG("%s: handle=%d label=%d error_code=%d category=%d", __func__,
+                   handle, label, error_code, category);
+
   /* map handle to scb */
   p_scb = avdt_scb_by_hdl(handle);
   if (p_scb == NULL) {
@@ -511,6 +561,8 @@ uint16_t AVDT_ConfigRsp(uint8_t handle, uint8_t label, uint8_t error_code,
     avdt_scb_event(p_scb, event_code, &evt);
   }
 
+  AVDT_TRACE_DEBUG("%s: result=%d", __func__, result);
+
   return result;
 }
 
@@ -535,6 +587,8 @@ uint16_t AVDT_StartReq(uint8_t* p_handles, uint8_t num_handles) {
   uint16_t result = AVDT_SUCCESS;
   int i;
 
+  AVDT_TRACE_DEBUG("%s: num_handles=%d", __func__, num_handles);
+
   if ((num_handles == 0) || (num_handles > AVDT_NUM_SEPS)) {
     result = AVDT_BAD_PARAMS;
   } else {
@@ -558,6 +612,9 @@ uint16_t AVDT_StartReq(uint8_t* p_handles, uint8_t num_handles) {
       avdt_ccb_event(p_scb->p_ccb, AVDT_CCB_API_START_REQ_EVT, &evt);
     }
   }
+
+  AVDT_TRACE_DEBUG("%s: result=%d", __func__, result);
+
   return result;
 }
 
@@ -582,6 +639,8 @@ uint16_t AVDT_SuspendReq(uint8_t* p_handles, uint8_t num_handles) {
   uint16_t result = AVDT_SUCCESS;
   int i;
 
+  AVDT_TRACE_DEBUG("%s: num_handles=%d", __func__, num_handles);
+
   if ((num_handles == 0) || (num_handles > AVDT_NUM_SEPS)) {
     result = AVDT_BAD_PARAMS;
   } else {
@@ -606,6 +665,8 @@ uint16_t AVDT_SuspendReq(uint8_t* p_handles, uint8_t num_handles) {
     }
   }
 
+  AVDT_TRACE_DEBUG("%s: result=%d", __func__, result);
+
   return result;
 }
 
@@ -627,6 +688,8 @@ uint16_t AVDT_CloseReq(uint8_t handle) {
   tAVDT_SCB* p_scb;
   uint16_t result = AVDT_SUCCESS;
 
+  AVDT_TRACE_DEBUG("%s: handle=%d", __func__, handle);
+
   /* map handle to scb */
   p_scb = avdt_scb_by_hdl(handle);
   if (p_scb == NULL) {
@@ -637,6 +700,8 @@ uint16_t AVDT_CloseReq(uint8_t handle) {
     avdt_scb_event(p_scb, AVDT_SCB_API_CLOSE_REQ_EVT, NULL);
   }
 
+  AVDT_TRACE_DEBUG("%s: result=%d", __func__, result);
+
   return result;
 }
 
@@ -662,6 +727,8 @@ uint16_t AVDT_ReconfigReq(uint8_t handle, tAVDT_CFG* p_cfg) {
   uint16_t result = AVDT_SUCCESS;
   tAVDT_SCB_EVT evt;
 
+  AVDT_TRACE_DEBUG("%s: handle=%d", __func__, handle);
+
   /* map handle to scb */
   p_scb = avdt_scb_by_hdl(handle);
   if (p_scb == NULL) {
@@ -671,10 +738,12 @@ uint16_t AVDT_ReconfigReq(uint8_t handle, tAVDT_CFG* p_cfg) {
   else {
     /* force psc_mask to zero */
     p_cfg->psc_mask = 0;
-
     evt.msg.reconfig_cmd.p_cfg = p_cfg;
     avdt_scb_event(p_scb, AVDT_SCB_API_RECONFIG_REQ_EVT, &evt);
   }
+
+  AVDT_TRACE_DEBUG("%s: result=%d", __func__, result);
+
   return result;
 }
 
@@ -696,6 +765,9 @@ uint16_t AVDT_ReconfigRsp(uint8_t handle, uint8_t label, uint8_t error_code,
   tAVDT_SCB_EVT evt;
   uint16_t result = AVDT_SUCCESS;
 
+  AVDT_TRACE_DEBUG("%s: handle=%d label=%d error_code=%d category=%d", __func__,
+                   handle, label, error_code, category);
+
   /* map handle to scb */
   p_scb = avdt_scb_by_hdl(handle);
   if (p_scb == NULL) {
@@ -709,6 +781,8 @@ uint16_t AVDT_ReconfigRsp(uint8_t handle, uint8_t label, uint8_t error_code,
     avdt_scb_event(p_scb, AVDT_SCB_API_RECONFIG_RSP_EVT, &evt);
   }
 
+  AVDT_TRACE_DEBUG("%s: result=%d", __func__, result);
+
   return result;
 }
 
@@ -731,6 +805,8 @@ uint16_t AVDT_SecurityReq(uint8_t handle, uint8_t* p_data, uint16_t len) {
   uint16_t result = AVDT_SUCCESS;
   tAVDT_SCB_EVT evt;
 
+  AVDT_TRACE_DEBUG("%s: handle=%d len=%d", __func__, handle, len);
+
   /* map handle to scb */
   p_scb = avdt_scb_by_hdl(handle);
   if (p_scb == NULL) {
@@ -742,6 +818,9 @@ uint16_t AVDT_SecurityReq(uint8_t handle, uint8_t* p_data, uint16_t len) {
     evt.msg.security_rsp.len = len;
     avdt_scb_event(p_scb, AVDT_SCB_API_SECURITY_REQ_EVT, &evt);
   }
+
+  AVDT_TRACE_DEBUG("%s: result=%d", __func__, result);
+
   return result;
 }
 
@@ -765,6 +844,9 @@ uint16_t AVDT_SecurityRsp(uint8_t handle, uint8_t label, uint8_t error_code,
   uint16_t result = AVDT_SUCCESS;
   tAVDT_SCB_EVT evt;
 
+  AVDT_TRACE_DEBUG("%s: handle=%d label=%d error_code=%d len=%d", __func__,
+                   handle, label, error_code, len);
+
   /* map handle to scb */
   p_scb = avdt_scb_by_hdl(handle);
   if (p_scb == NULL) {
@@ -778,6 +860,9 @@ uint16_t AVDT_SecurityRsp(uint8_t handle, uint8_t label, uint8_t error_code,
     evt.msg.security_rsp.len = len;
     avdt_scb_event(p_scb, AVDT_SCB_API_SECURITY_RSP_EVT, &evt);
   }
+
+  AVDT_TRACE_DEBUG("%s: result=%d", __func__, result);
+
   return result;
 }
 
@@ -824,6 +909,9 @@ uint16_t AVDT_WriteReqOpt(uint8_t handle, BT_HDR* p_pkt, uint32_t time_stamp,
   tAVDT_SCB_EVT evt;
   uint16_t result = AVDT_SUCCESS;
 
+  AVDT_TRACE_DEBUG("%s: handle=%d timestamp=%d m_pt=0x%x opt=0x%x", __func__,
+                   handle, time_stamp, m_pt, opt);
+
   /* map handle to scb */
   p_scb = avdt_scb_by_hdl(handle);
   if (p_scb == NULL) {
@@ -836,6 +924,8 @@ uint16_t AVDT_WriteReqOpt(uint8_t handle, BT_HDR* p_pkt, uint32_t time_stamp,
     avdt_scb_event(p_scb, AVDT_SCB_API_WRITE_REQ_EVT, &evt);
   }
 
+  AVDT_TRACE_DEBUG("%s: result=%d", __func__, result);
+
   return result;
 }
 
@@ -899,6 +989,8 @@ uint16_t AVDT_ConnectReq(BD_ADDR bd_addr, uint8_t sec_mask,
   uint16_t result = AVDT_SUCCESS;
   tAVDT_CCB_EVT evt;
 
+  AVDT_TRACE_DEBUG("%s: sec_mask=0x%x", __func__, sec_mask);
+
   /* find channel control block for this bd addr; if none, allocate one */
   p_ccb = avdt_ccb_by_bd(bd_addr);
   if (p_ccb == NULL) {
@@ -920,6 +1012,9 @@ uint16_t AVDT_ConnectReq(BD_ADDR bd_addr, uint8_t sec_mask,
     evt.connect.sec_mask = sec_mask;
     avdt_ccb_event(p_ccb, AVDT_CCB_API_CONNECT_REQ_EVT, &evt);
   }
+
+  AVDT_TRACE_DEBUG("%s: result=%d", __func__, result);
+
   return result;
 }
 
@@ -940,6 +1035,8 @@ uint16_t AVDT_DisconnectReq(BD_ADDR bd_addr, tAVDT_CTRL_CBACK* p_cback) {
   uint16_t result = AVDT_SUCCESS;
   tAVDT_CCB_EVT evt;
 
+  AVDT_TRACE_DEBUG("%s", __func__);
+
   /* find channel control block for this bd addr; if none, error */
   p_ccb = avdt_ccb_by_bd(bd_addr);
   if (p_ccb == NULL) {
@@ -951,6 +1048,9 @@ uint16_t AVDT_DisconnectReq(BD_ADDR bd_addr, tAVDT_CTRL_CBACK* p_cback) {
     evt.disconnect.p_cback = p_cback;
     avdt_ccb_event(p_ccb, AVDT_CCB_API_DISCONNECT_REQ_EVT, &evt);
   }
+
+  AVDT_TRACE_DEBUG("%s: result=%d", __func__, result);
+
   return result;
 }
 
@@ -1032,6 +1132,8 @@ uint16_t AVDT_SendReport(uint8_t handle, AVDT_REPORT_TYPE type,
   uint32_t ssrc;
   uint16_t len;
 
+  AVDT_TRACE_DEBUG("%s: handle=%d type=%d", __func__, handle, type);
+
   /* map handle to scb && verify parameters */
   if (((p_scb = avdt_scb_by_hdl(handle)) != NULL) && (p_scb->p_ccb != NULL) &&
       (((type == AVDT_RTCP_PT_SR) && (p_scb->cs.tsep == AVDT_TSEP_SRC)) ||
@@ -1099,6 +1201,8 @@ uint16_t AVDT_SendReport(uint8_t handle, AVDT_REPORT_TYPE type,
     }
   }
 
+  AVDT_TRACE_DEBUG("%s: result=%d", __func__, result);
+
   return result;
 }
 #endif
diff --git a/stack/avdt/avdt_ccb.cc b/stack/avdt/avdt_ccb.cc
index c1f1469ec..a9ca128cb 100644
--- a/stack/avdt/avdt_ccb.cc
+++ b/stack/avdt/avdt_ccb.cc
@@ -37,7 +37,6 @@
 /*****************************************************************************
  * state machine constants and types
  ****************************************************************************/
-#if (AVDT_DEBUG == TRUE)
 
 /* verbose state strings for trace */
 const char* const avdt_ccb_st_str[] = {"CCB_IDLE_ST", "CCB_OPENING_ST",
@@ -60,8 +59,6 @@ const char* const avdt_ccb_evt_str[] = {
     "UL_CLOSE_EVT",         "LL_OPEN_EVT",
     "LL_CLOSE_EVT",         "LL_CONG_EVT"};
 
-#endif
-
 /* action function list */
 const tAVDT_CCB_ACTION avdt_ccb_action[] = {
     avdt_ccb_chan_open,        avdt_ccb_chan_close,
@@ -387,6 +384,9 @@ void avdt_ccb_event(tAVDT_CCB* p_ccb, uint8_t event, tAVDT_CCB_EVT* p_data) {
   /* execute action functions */
   for (i = 0; i < AVDT_CCB_ACTIONS; i++) {
     action = state_table[event][i];
+    AVDT_TRACE_DEBUG("%s: event=%s state=%s action=%d", __func__,
+                     avdt_ccb_evt_str[event], avdt_ccb_st_str[p_ccb->state],
+                     action);
     if (action != AVDT_CCB_IGNORE) {
       (*avdt_cb.p_ccb_act[action])(p_ccb, p_data);
     } else {
diff --git a/stack/avdt/avdt_ccb_act.cc b/stack/avdt/avdt_ccb_act.cc
index 943855f75..934764680 100644
--- a/stack/avdt/avdt_ccb_act.cc
+++ b/stack/avdt/avdt_ccb_act.cc
@@ -486,6 +486,8 @@ void avdt_ccb_snd_start_cmd(tAVDT_CCB* p_ccb, tAVDT_CCB_EVT* p_data) {
   tAVDT_MSG avdt_msg;
   uint8_t seid_list[AVDT_NUM_SEPS];
 
+  AVDT_TRACE_DEBUG("%s", __func__);
+
   /* make copy of our seid list */
   memcpy(seid_list, p_data->msg.multi.seid_list, p_data->msg.multi.num_seps);
 
@@ -494,6 +496,8 @@ void avdt_ccb_snd_start_cmd(tAVDT_CCB* p_ccb, tAVDT_CCB_EVT* p_data) {
       avdt_scb_verify(p_ccb, AVDT_VERIFY_OPEN, p_data->msg.multi.seid_list,
                       p_data->msg.multi.num_seps, &avdt_msg.hdr.err_code);
   if (avdt_msg.hdr.err_param == 0) {
+    AVDT_TRACE_DEBUG("%s: AVDT_SIG_START", __func__);
+
     /* set peer seid list in messsage */
     avdt_scb_peer_seid_list(&p_data->msg.multi);
 
@@ -504,6 +508,7 @@ void avdt_ccb_snd_start_cmd(tAVDT_CCB* p_ccb, tAVDT_CCB_EVT* p_data) {
     for (i = 0; i < p_data->msg.multi.num_seps; i++) {
       p_scb = avdt_scb_by_hdl(seid_list[i]);
       if (p_scb != NULL) {
+        AVDT_TRACE_DEBUG("%s: AVDT_SCB_MSG_START_REJ_EVT: i=%d", __func__, i);
         avdt_scb_event(p_scb, AVDT_SCB_MSG_START_REJ_EVT,
                        (tAVDT_SCB_EVT*)&avdt_msg.hdr);
       }
diff --git a/stack/avdt/avdt_scb_act.cc b/stack/avdt/avdt_scb_act.cc
index 8832d44c6..c44a5a263 100644
--- a/stack/avdt/avdt_scb_act.cc
+++ b/stack/avdt/avdt_scb_act.cc
@@ -503,7 +503,11 @@ void avdt_scb_hdl_security_rsp(tAVDT_SCB* p_scb, tAVDT_SCB_EVT* p_data) {
 void avdt_scb_hdl_setconfig_cmd(tAVDT_SCB* p_scb, tAVDT_SCB_EVT* p_data) {
   tAVDT_CFG* p_cfg;
 
+  AVDT_TRACE_DEBUG("%s: p_scb->in_use=%d", __func__, p_scb->in_use);
+
   if (!p_scb->in_use) {
+    A2DP_DumpCodecInfo(p_scb->cs.cfg.codec_info);
+    A2DP_DumpCodecInfo(p_data->msg.config_cmd.p_cfg->codec_info);
     p_cfg = p_data->msg.config_cmd.p_cfg;
     if (A2DP_GetCodecType(p_scb->cs.cfg.codec_info) ==
         A2DP_GetCodecType(p_cfg->codec_info)) {
@@ -526,6 +530,7 @@ void avdt_scb_hdl_setconfig_cmd(tAVDT_SCB* p_scb, tAVDT_SCB_EVT* p_data) {
                         p_data->msg.hdr.sig_id, &p_data->msg);
     }
   } else {
+    AVDT_TRACE_DEBUG("%s: calling avdt_scb_rej_in_use()", __func__);
     avdt_scb_rej_in_use(p_scb, p_data);
   }
 }
@@ -916,6 +921,8 @@ void avdt_scb_snd_abort_req(tAVDT_SCB* p_scb,
                             UNUSED_ATTR tAVDT_SCB_EVT* p_data) {
   tAVDT_EVT_HDR hdr;
 
+  AVDT_TRACE_DEBUG("%s: p_scb->p_ccb=%p", __func__, p_scb->p_ccb);
+
   if (p_scb->p_ccb != NULL) {
     p_scb->role = AVDT_CLOSE_INT;
 
@@ -1071,6 +1078,10 @@ void avdt_scb_snd_open_rsp(tAVDT_SCB* p_scb, tAVDT_SCB_EVT* p_data) {
  *
  ******************************************************************************/
 void avdt_scb_snd_reconfig_req(tAVDT_SCB* p_scb, tAVDT_SCB_EVT* p_data) {
+  AVDT_TRACE_DEBUG("%s: p_scb->peer_seid=%d p_data->msg.hdr.seid=%d", __func__,
+                   p_scb->peer_seid, p_data->msg.hdr.seid);
+  A2DP_DumpCodecInfo(p_data->msg.config_cmd.p_cfg->codec_info);
+
   memcpy(&p_scb->req_cfg, p_data->msg.config_cmd.p_cfg, sizeof(tAVDT_CFG));
   p_data->msg.hdr.seid = p_scb->peer_seid;
   avdt_msg_send_cmd(p_scb->p_ccb, p_scb, AVDT_SIG_RECONFIG, &p_data->msg);
@@ -1173,6 +1184,9 @@ void avdt_scb_snd_setconfig_rej(tAVDT_SCB* p_scb, tAVDT_SCB_EVT* p_data) {
 void avdt_scb_snd_setconfig_req(tAVDT_SCB* p_scb, tAVDT_SCB_EVT* p_data) {
   tAVDT_CFG *p_req, *p_cfg;
 
+  AVDT_TRACE_DEBUG("%s", __func__);
+  A2DP_DumpCodecInfo(p_data->msg.config_cmd.p_cfg->codec_info);
+
   /* copy API parameters to scb, set scb as in use */
   p_scb->in_use = true;
   p_scb->p_ccb = avdt_ccb_by_idx(p_data->msg.config_cmd.hdr.ccb_idx);
-- 
2.11.0