Add last `n` classic inquiry procedure stats (700b73fd) · Commits · e / os / android_packages_modules_Bluetooth

system/bta/dm/bta_dm_act.cc

+13 −10

Original line number	Diff line number	Diff line
		@@ -845,8 +845,6 @@ void bta_dm_ci_rmt_oob_act(std::unique_ptr<tBTA_DM_CI_RMT_OOB> msg) {
		*
		******************************************************************************/
		void bta_dm_search_start(tBTA_DM_MSG* p_data) {
		tBTM_INQUIRY_CMPL result = {};

		bta_dm_gattc_register();

		APPL_TRACE_DEBUG("%s avoid_scatter=%d", __func__,
		@@ -857,14 +855,19 @@ void bta_dm_search_start(tBTA_DM_MSG* p_data) {
		bta_dm_search_cb.p_search_cback = p_data->search.p_cback;
		bta_dm_search_cb.services = p_data->search.services;

		result.status = BTM_StartInquiry(bta_dm_inq_results_cb, bta_dm_inq_cmpl_cb);

		APPL_TRACE_EVENT("%s status=%d", __func__, result.status);
		if (result.status != BTM_CMD_STARTED) {
		LOG(ERROR) << __func__ << ": BTM_StartInquiry returned "
		<< std::to_string(result.status);
		result.num_resp = 0;
		bta_dm_inq_cmpl_cb((void*)&result);
		const tBTM_STATUS btm_status =
		BTM_StartInquiry(bta_dm_inq_results_cb, bta_dm_inq_cmpl_cb);
		switch (btm_status) {
		case BTM_CMD_STARTED:
		// Completion callback will be executed when controller inquiry
		// timer pops or is cancelled by the user
		break;
		default:
		LOG_WARN("Unable to start device discovery search btm_status:%s",
		btm_status_text(btm_status).c_str());
		// Not started so completion callback is executed now
		bta_dm_inq_cmpl(0);
		break;
		}
		}

system/main/shim/acl.cc

+25 −0

Original line number	Diff line number	Diff line
		@@ -147,6 +147,17 @@ using OnDisconnect = std::function<void(HciHandle, hci::ErrorCode reason)>;

		constexpr char kConnectionDescriptorTimeFormat[] = "%Y-%m-%d %H:%M:%S";

		constexpr unsigned MillisPerSecond = 1000;
		std::string EpochMillisToString(long long time_ms) {
		time_t time_sec = time_ms / MillisPerSecond;
		struct tm tm;
		localtime_r(&time_sec, &tm);
		std::string s = common::StringFormatTime(kConnectionDescriptorTimeFormat, tm);
		return base::StringPrintf(
		"%s.%03u", s.c_str(),
		static_cast<unsigned int>(time_ms % MillisPerSecond));
		}

		inline bool IsRpa(const hci::AddressWithType address_with_type) {
		return address_with_type.GetAddressType() ==
		hci::AddressType::RANDOM_DEVICE_ADDRESS &&
		@@ -1339,6 +1350,20 @@ void DumpsysNeighbor(int fd) {
		1000.0,
		btm_cb.neighbor.le_scan.results);
		}
		const auto copy = btm_cb.neighbor.inquiry_history_->Pull();
		LOG_DUMPSYS(fd, "Last %zu inquiry scans:", copy.size());
		for (const auto& it : copy) {
		LOG_DUMPSYS(fd,
		" %s - %s duration_ms:%-5Lu num_resp:%-2u"
		" std:%-2u rssi:%-2u ext:%-2u %12s",
		EpochMillisToString(it.entry.start_time_ms).c_str(),
		EpochMillisToString(it.timestamp).c_str(),
		it.timestamp - it.entry.start_time_ms, it.entry.num_resp,
		it.entry.resp_type[BTM_INQ_RESULT_STANDARD],
		it.entry.resp_type[BTM_INQ_RESULT_WITH_RSSI],
		it.entry.resp_type[BTM_INQ_RESULT_EXTENDED],
		btm_inquiry_cmpl_status_text(it.entry.status).c_str());
		}
		}
		#undef DUMPSYS_TAG

system/stack/btm/btm_inq.cc

+94 −34

Original line number	Diff line number	Diff line
		@@ -483,13 +483,32 @@ void BTM_CancelInquiry(void) {

		CHECK(BTM_IsDeviceUp());

		btm_cb.neighbor.inquiry_history_->Push({
		.status = tBTM_INQUIRY_CMPL::CANCELED,
		.num_resp = btm_cb.btm_inq_vars.inq_cmpl_info.num_resp,
		.resp_type =
		{
		btm_cb.btm_inq_vars.inq_cmpl_info
		.resp_type[BTM_INQ_RESULT_STANDARD],
		btm_cb.btm_inq_vars.inq_cmpl_info
		.resp_type[BTM_INQ_RESULT_WITH_RSSI],
		btm_cb.btm_inq_vars.inq_cmpl_info
		.resp_type[BTM_INQ_RESULT_EXTENDED],
		},
		.start_time_ms = btm_cb.neighbor.classic_inquiry.start_time_ms,
		});

		const auto end_time_ms = timestamper_in_milliseconds.GetTimestamp();
		BTM_LogHistory(
		kBtmLogTag, RawAddress::kEmpty, "Classic inquiry canceled",
		base::StringPrintf("duration_s:%6.3f results:%lu",
		(timestamper_in_milliseconds.GetTimestamp() -
		btm_cb.neighbor.classic_inquiry.start_time_ms) /
		base::StringPrintf(
		"duration_s:%6.3f results:%lu std:%u rssi:%u ext:%u",
		(end_time_ms - btm_cb.neighbor.classic_inquiry.start_time_ms) /
		1000.0,
		btm_cb.neighbor.classic_inquiry.results));
		btm_cb.neighbor.classic_inquiry.results,
		p_inq->inq_cmpl_info.resp_type[BTM_INQ_RESULT_STANDARD],
		p_inq->inq_cmpl_info.resp_type[BTM_INQ_RESULT_WITH_RSSI],
		p_inq->inq_cmpl_info.resp_type[BTM_INQ_RESULT_EXTENDED]));
		btm_cb.neighbor.classic_inquiry = {};

		/* Only cancel if not in periodic mode, otherwise the caller should call
		@@ -567,12 +586,18 @@ tBTM_STATUS BTM_StartInquiry(tBTM_INQ_RESULTS_CB* p_results_cb,
		" state:%hhu counter:%u",
		btm_cb.btm_inq_vars.inq_active, btm_cb.btm_inq_vars.state,
		btm_cb.btm_inq_vars.inq_counter);
		btm_cb.neighbor.inquiry_history_->Push({
		.status = tBTM_INQUIRY_CMPL::NOT_STARTED,
		});
		return BTM_BUSY;
		}

		/* Make sure the device is ready */
		if (!BTM_IsDeviceUp()) {
		LOG(ERROR) << __func__ << ": adapter is not up";
		btm_cb.neighbor.inquiry_history_->Push({
		.status = tBTM_INQUIRY_CMPL::NOT_STARTED,
		});
		return BTM_WRONG_MODE;
		}

		@@ -594,8 +619,7 @@ tBTM_STATUS BTM_StartInquiry(tBTM_INQ_RESULTS_CB* p_results_cb,
		btm_cb.btm_inq_vars.state = BTM_INQ_ACTIVE_STATE;
		btm_cb.btm_inq_vars.p_inq_cmpl_cb = p_cmpl_cb;
		btm_cb.btm_inq_vars.p_inq_results_cb = p_results_cb;
		btm_cb.btm_inq_vars.inq_cmpl_info.num_resp =
		0; /* Clear the results counter */
		btm_cb.btm_inq_vars.inq_cmpl_info = {}; /* Clear the results counter */
		btm_cb.btm_inq_vars.inq_active = btm_cb.btm_inq_vars.inqparms.mode;
		btm_cb.neighbor.classic_inquiry = {
		.start_time_ms = timestamper_in_milliseconds.GetTimestamp(),
		@@ -1311,8 +1335,21 @@ void btm_process_inq_results(const uint8_t* p, uint8_t hci_evt_len,

		p_i->time_of_resp = bluetooth::common::time_get_os_boottime_ms();

		if (p_i->inq_count != p_inq->inq_counter)
		p_inq->inq_cmpl_info.num_resp++; /* A new response was found */
		if (p_i->inq_count != p_inq->inq_counter) {
		/* A new response was found */
		btm_cb.btm_inq_vars.inq_cmpl_info.num_resp++;
		switch (static_cast<tBTM_INQ_RESULT>(inq_res_mode)) {
		case BTM_INQ_RESULT_STANDARD:
		case BTM_INQ_RESULT_WITH_RSSI:
		case BTM_INQ_RESULT_EXTENDED:
		btm_cb.btm_inq_vars.inq_cmpl_info.resp_type[inq_res_mode]++;
		break;
		case BTM_INQ_RES_IGNORE_RSSI:
		btm_cb.btm_inq_vars.inq_cmpl_info
		.resp_type[BTM_INQ_RESULT_STANDARD]++;
		break;
		}
		}

		p_cur->inq_result_type \|= BTM_INQ_RESULT_BR;
		if (p_i->inq_count != p_inq->inq_counter) {
		@@ -1399,22 +1436,21 @@ void btm_sort_inq_result(void) {
		*
		******************************************************************************/
		void btm_process_inq_complete(tHCI_STATUS status, uint8_t mode) {
		tBTM_CMPL_CB* p_inq_cb = btm_cb.btm_inq_vars.p_inq_cmpl_cb;
		tBTM_INQUIRY_VAR_ST* p_inq = &btm_cb.btm_inq_vars;

		p_inq->inqparms.mode &= ~(mode);
		const auto inq_active = p_inq->inq_active;

		#if (BTM_INQ_DEBUG == TRUE)
		BTM_TRACE_DEBUG("btm_process_inq_complete inq_active:0x%x state:%d",
		btm_cb.btm_inq_vars.inq_active, btm_cb.btm_inq_vars.state);
		#endif
		btm_acl_update_inquiry_status(BTM_INQUIRY_COMPLETE);

		if (status != HCI_SUCCESS) {
		LOG_WARN("Received unexpected hci status:%s",
		hci_error_code_text(status).c_str());
		}

		/* Ignore any stray or late complete messages if the inquiry is not active */
		if (p_inq->inq_active) {
		p_inq->inq_cmpl_info.status =
		(tBTM_STATUS)((status == HCI_SUCCESS) ? BTM_SUCCESS
		: BTM_ERR_PROCESSING);
		p_inq->inq_cmpl_info.hci_status = status;

		/* Notify caller that the inquiry has completed; (periodic inquiries do not
		* send completion events */
		@@ -1427,36 +1463,60 @@ void btm_process_inq_complete(tHCI_STATUS status, uint8_t mode) {

		btm_clr_inq_result_flt();

		if ((p_inq->inq_cmpl_info.status == BTM_SUCCESS) &&
		if ((status == HCI_SUCCESS) &&
		controller_get_interface()->supports_rssi_with_inquiry_results()) {
		btm_sort_inq_result();
		}

		if (btm_cb.btm_inq_vars.p_inq_cmpl_cb) {
		(btm_cb.btm_inq_vars.p_inq_cmpl_cb)(
		(tBTM_INQUIRY_CMPL*)&p_inq->inq_cmpl_info);
		} else {
		LOG_WARN("No callback to return inquiry result");
		}

		btm_cb.neighbor.inquiry_history_->Push({
		.status = tBTM_INQUIRY_CMPL::TIMER_POPPED,
		.num_resp = btm_cb.btm_inq_vars.inq_cmpl_info.num_resp,
		.resp_type =
		{
		btm_cb.btm_inq_vars.inq_cmpl_info
		.resp_type[BTM_INQ_RESULT_STANDARD],
		btm_cb.btm_inq_vars.inq_cmpl_info
		.resp_type[BTM_INQ_RESULT_WITH_RSSI],
		btm_cb.btm_inq_vars.inq_cmpl_info
		.resp_type[BTM_INQ_RESULT_EXTENDED],
		},
		.start_time_ms = btm_cb.neighbor.classic_inquiry.start_time_ms,
		});
		const auto end_time_ms = timestamper_in_milliseconds.GetTimestamp();
		BTM_LogHistory(
		kBtmLogTag, RawAddress::kEmpty, "Classic inquiry complete",
		base::StringPrintf(
		"duration_s:%6.3f results:%lu inq_active:0x%02x std:%u rssi:%u "
		"ext:%u status:%s",
		(end_time_ms - btm_cb.neighbor.classic_inquiry.start_time_ms) /
		1000.0,
		btm_cb.neighbor.classic_inquiry.results, inq_active,
		p_inq->inq_cmpl_info.resp_type[BTM_INQ_RESULT_STANDARD],
		p_inq->inq_cmpl_info.resp_type[BTM_INQ_RESULT_WITH_RSSI],
		p_inq->inq_cmpl_info.resp_type[BTM_INQ_RESULT_EXTENDED],
		hci_error_code_text(status).c_str()));

		btm_cb.neighbor.classic_inquiry.start_time_ms = 0;
		/* Clear the results callback if set */
		p_inq->p_inq_results_cb = NULL;
		p_inq->inq_active = BTM_INQUIRY_INACTIVE;
		p_inq->p_inq_cmpl_cb = NULL;

		/* If we have a callback registered for inquiry complete, call it */
		BTM_TRACE_DEBUG("BTM Inq Compl Callback: status 0x%02x, num results %d",
		p_inq->inq_cmpl_info.status,
		p_inq->inq_cmpl_info.num_resp);

		if (p_inq_cb) (p_inq_cb)((tBTM_INQUIRY_CMPL*)&p_inq->inq_cmpl_info);
		BTM_LogHistory(kBtmLogTag, RawAddress::kEmpty, "Classic inquiry complete",
		base::StringPrintf(
		"duration_s:%6.3f results:%lu inq_active:0x%02x",
		(timestamper_in_milliseconds.GetTimestamp() -
		btm_cb.neighbor.classic_inquiry.start_time_ms) /
		1000.0,
		btm_cb.neighbor.classic_inquiry.results, inq_active));
		btm_cb.neighbor.classic_inquiry.start_time_ms = 0;
		} else {
		LOG_INFO(
		"Inquiry params is not clear so not sending callback inq_parms:%u",
		btm_cb.btm_inq_vars.inqparms.mode);
		}
		} else {
		LOG_ERROR("Received inquiry complete when no inquiry was active");
		}
		BTM_TRACE_DEBUG("inq_active:0x%x state:%d", btm_cb.btm_inq_vars.inq_active,
		btm_cb.btm_inq_vars.state);
		}

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

system/stack/btm/btm_int_types.h

+6 −0

Original line number	Diff line number	Diff line
		@@ -40,6 +40,7 @@

		constexpr size_t kMaxLogSize = 255;
		constexpr size_t kBtmLogHistoryBufferSize = 200;
		constexpr size_t kMaxInquiryScanHistory = 10;

		extern bluetooth::common::TimestamperInMilliseconds timestamper_in_milliseconds;

		@@ -313,6 +314,11 @@ typedef struct tBTM_CB {
		long long start_time_ms;
		unsigned long results;
		} classic_inquiry, le_scan, le_inquiry, le_observe, le_legacy_scan;
		std::unique_ptr<
		bluetooth::common::TimestampedCircularBuffer<tBTM_INQUIRY_CMPL>>
		inquiry_history_ = std::make_unique<
		bluetooth::common::TimestampedCircularBuffer<tBTM_INQUIRY_CMPL>>(
		kMaxInquiryScanHistory);
		} neighbor;

		void Init(uint8_t initial_security_mode) {

system/stack/btm/neighbor_inquiry.h

+34 −3

Original line number	Diff line number	Diff line
		@@ -86,13 +86,14 @@ enum : uint16_t {
		};

		/* Define inquiry results mode */
		enum : uint8_t {
		typedef enum : uint8_t {
		BTM_INQ_RESULT_STANDARD = 0,
		BTM_INQ_RESULT_WITH_RSSI = 1,
		BTM_INQ_RESULT_EXTENDED = 2,
		/* RSSI value not supplied (ignore it) */
		BTM_INQ_RES_IGNORE_RSSI = 0x7f,
		};
		} tBTM_INQ_RESULT;
		constexpr size_t kMaxNumberInquiryResults = BTM_INQ_RESULT_EXTENDED + 1;

		/* These are the fields returned in each device's response to the inquiry. It
		* is returned in the results callback if registered.
		@@ -181,10 +182,40 @@ typedef struct /* contains the parameters passed to the inquiry functions */

		/* Structure returned with inquiry complete callback */
		typedef struct {
		tBTM_STATUS status;
		// Possible inquiry completion status
		enum STATUS {
		CANCELED, // Expected user API cancel
		TIMER_POPPED, // Expected controller initiated timeout
		NOT_STARTED, // Unexpected controller unable to execute inquiry command
		SSP_ACTIVE, // Unexpected secure simple pairing is operational
		};
		STATUS status;
		tHCI_STATUS hci_status;
		uint8_t num_resp; /* Number of results from the current inquiry */
		unsigned resp_type[kMaxNumberInquiryResults];
		long long start_time_ms;
		} tBTM_INQUIRY_CMPL;

		#ifndef CASE_RETURN_TEXT
		#define CASE_RETURN_TEXT(code) \
		case code: \
		return #code
		#endif

		inline std::string btm_inquiry_cmpl_status_text(
		const tBTM_INQUIRY_CMPL::STATUS& status) {
		switch (status) {
		CASE_RETURN_TEXT(tBTM_INQUIRY_CMPL::CANCELED);
		CASE_RETURN_TEXT(tBTM_INQUIRY_CMPL::TIMER_POPPED);
		CASE_RETURN_TEXT(tBTM_INQUIRY_CMPL::NOT_STARTED);
		CASE_RETURN_TEXT(tBTM_INQUIRY_CMPL::SSP_ACTIVE);
		default:
		return std::string("UNKNOWN[") + std::to_string(status) +
		std::string("]");
		}
		}
		#undef CASE_RETURN_TEXT

		/* Structure returned with remote name request */
		typedef struct {
		tBTM_STATUS status;