Merge "HFP: Add more logs to SCO sessions" (6bd1e956) · Commits · e / os / android_packages_modules_Bluetooth

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);
		}
		}