btm_log_history: Add scanning time and result count (562555f8) · Commits · e / os / android_packages_modules_Bluetooth

system/main/shim/le_scanning_manager.cc

+18 −4

Original line number	Diff line number	Diff line
		@@ -50,6 +50,8 @@
		using bluetooth::ToGdAddress;
		using bluetooth::ToRawAddress;

		extern tBTM_CB btm_cb;

		namespace {
		constexpr char kBtmLogTag[] = "SCAN";
		constexpr uint16_t kAllowServiceDataFilter = 0x0040;
		@@ -158,14 +160,25 @@ void BleScannerInterfaceImpl::Unregister(int scanner_id) {
		void BleScannerInterfaceImpl::Scan(bool start) {
		LOG(INFO) << __func__ << " in shim layer " << ((start) ? "started" : "stopped");
		bluetooth::shim::GetScanning()->Scan(start);
		BTM_LogHistory(
		kBtmLogTag, RawAddress::kEmpty,
		base::StringPrintf("Le scan %s", (start) ? "started" : "stopped"));
		if (start) {
		btm_cb.neighbor.le_scan = {
		.start_time_ms = timestamper_in_milliseconds.GetTimestamp(),
		.results = 0,
		};
		BTM_LogHistory(kBtmLogTag, RawAddress::kEmpty, "Le scan started");
		btm_cb.ble_ctr_cb.set_ble_observe_active();
		} else {
		} else { // stopped
		const unsigned long long duration_timestamp =
		timestamper_in_milliseconds.GetTimestamp() -
		btm_cb.neighbor.le_scan.start_time_ms;
		BTM_LogHistory(kBtmLogTag, RawAddress::kEmpty, "Le scan stopped",
		base::StringPrintf("duration_s:%6.3f results:%-3lu",
		(double)duration_timestamp / 1000.0,
		btm_cb.neighbor.le_scan.results));
		btm_cb.ble_ctr_cb.reset_ble_observe();
		btm_cb.neighbor.le_scan = {};
		}

		do_in_jni_thread(FROM_HERE,
		base::Bind(&BleScannerInterfaceImpl::AddressCache::init,
		base::Unretained(&address_cache_)));
		@@ -485,6 +498,7 @@ void BleScannerInterfaceImpl::OnScanResult(
		RawAddress raw_address = ToRawAddress(address);
		tBLE_ADDR_TYPE ble_addr_type = to_ble_addr_type(address_type);

		btm_cb.neighbor.le_scan.results++;
		if (ble_addr_type != BLE_ADDR_ANONYMOUS) {
		btm_ble_process_adv_addr(raw_address, &ble_addr_type);
		}

system/main/test/main_shim_test.cc

+2 −0

Original line number	Diff line number	Diff line
		@@ -115,6 +115,8 @@ class DevNullOrStdErr {

		} // namespace

		bluetooth::common::TimestamperInMilliseconds timestamper_in_milliseconds;

		uint8_t mock_get_ble_acceptlist_size() { return 123; }

		struct controller_t mock_controller {

system/stack/btm/btm_ble_gap.cc

+49 −5

Original line number	Diff line number	Diff line
		@@ -94,6 +94,8 @@ static tBTM_STATUS btm_ble_start_adv(void);

		namespace {

		constexpr char kBtmLogTag[] = "SCAN";

		class AdvertisingCache {
		public:
		/* Set the data to \|data\| for device \|addr_type, addr\| */
		@@ -558,6 +560,12 @@ tBTM_STATUS BTM_BleObserve(bool start, uint8_t duration,
		btm_ble_start_scan();
		}

		btm_cb.neighbor.le_observe = {
		.start_time_ms = timestamper_in_milliseconds.GetTimestamp(),
		.results = 0,
		};
		BTM_LogHistory(kBtmLogTag, RawAddress::kEmpty, "Le observe started");

		if (status == BTM_CMD_STARTED) {
		btm_cb.ble_ctr_cb.set_ble_observe_active();
		if (duration != 0) {
		@@ -568,6 +576,13 @@ tBTM_STATUS BTM_BleObserve(bool start, uint8_t duration,
		}
		}
		} else if (btm_cb.ble_ctr_cb.is_ble_observe_active()) {
		const unsigned long long duration_timestamp =
		timestamper_in_milliseconds.GetTimestamp() -
		btm_cb.neighbor.le_observe.start_time_ms;
		BTM_LogHistory(kBtmLogTag, RawAddress::kEmpty, "Le observe stopped",
		base::StringPrintf("duration_s:%6.3f results:%-3lu",
		(double)duration_timestamp / 1000.0,
		btm_cb.neighbor.le_observe.results));
		status = BTM_CMD_STARTED;
		btm_ble_stop_observe();
		} else {
		@@ -2050,6 +2065,12 @@ tBTM_STATUS btm_ble_start_inquiry(uint8_t duration) {
		btm_ble_inquiry_timer_timeout, NULL);
		}

		btm_cb.neighbor.le_inquiry = {
		.start_time_ms = timestamper_in_milliseconds.GetTimestamp(),
		.results = 0,
		};
		BTM_LogHistory(kBtmLogTag, RawAddress::kEmpty, "Le inquiry started");

		return BTM_CMD_STARTED;
		}

		@@ -2860,6 +2881,7 @@ void btm_ble_process_adv_pkt_cont_for_inquiry(
		(!p_i->inq_info.results.include_rsi && include_rsi))) {
		update = true;
		} else if (btm_cb.ble_ctr_cb.is_ble_observe_active()) {
		btm_cb.neighbor.le_observe.results++;
		update = false;
		} else {
		/* if yes, skip it */
		@@ -2874,8 +2896,12 @@ void btm_ble_process_adv_pkt_cont_for_inquiry(
		if (p_i != NULL) {
		p_inq->inq_cmpl_info.num_resp++;
		p_i->time_of_resp = bluetooth::common::time_get_os_boottime_ms();
		} else
		btm_cb.neighbor.le_inquiry.results++;
		btm_cb.neighbor.le_legacy_scan.results++;
		} else {
		LOG_WARN("Unable to allocate entry for inquiry result");
		return;
		}
		} else if (p_i->inq_count !=
		p_inq->inq_counter) /* first time seen in this inquiry */
		{
		@@ -2949,11 +2975,17 @@ void btm_ble_process_phy_update_pkt(uint8_t len, uint8_t* data) {
		*
		******************************************************************************/
		static void btm_ble_start_scan() {
		tBTM_BLE_INQ_CB* p_inq = &btm_cb.ble_ctr_cb.inq_var;
		btm_cb.neighbor.le_legacy_scan = {
		.start_time_ms = timestamper_in_milliseconds.GetTimestamp(),
		.results = 0,
		};
		BTM_LogHistory(kBtmLogTag, RawAddress::kEmpty, "Le legacy scan started",
		"Duplicates:disable");

		/* start scan, disable duplicate filtering */
		btm_send_hci_scan_enable(BTM_BLE_SCAN_ENABLE, BTM_BLE_DUPLICATE_DISABLE);

		if (p_inq->scan_type == BTM_BLE_SCAN_MODE_ACTI)
		if (btm_cb.ble_ctr_cb.inq_var.scan_type == BTM_BLE_SCAN_MODE_ACTI)
		btm_ble_set_topology_mask(BTM_BLE_STATE_ACTIVE_SCAN_BIT);
		else
		btm_ble_set_topology_mask(BTM_BLE_STATE_PASSIVE_SCAN_BIT);
		@@ -2969,8 +3001,6 @@ static void btm_ble_start_scan() {
		*
		******************************************************************************/
		static void btm_ble_stop_scan(void) {
		BTM_TRACE_EVENT("btm_ble_stop_scan ");

		if (btm_cb.ble_ctr_cb.inq_var.scan_type == BTM_BLE_SCAN_MODE_ACTI)
		btm_ble_clear_topology_mask(BTM_BLE_STATE_ACTIVE_SCAN_BIT);
		else
		@@ -2980,6 +3010,13 @@ static void btm_ble_stop_scan(void) {
		btm_cb.ble_ctr_cb.inq_var.scan_type = BTM_BLE_SCAN_MODE_NONE;

		/* stop discovery now */
		const unsigned long long duration_timestamp =
		timestamper_in_milliseconds.GetTimestamp() -
		btm_cb.neighbor.le_legacy_scan.start_time_ms;
		BTM_LogHistory(kBtmLogTag, RawAddress::kEmpty, "Le legacy scan stopped",
		base::StringPrintf("duration_s:%6.3f results:%-3lu",
		(double)duration_timestamp / 1000.0,
		btm_cb.neighbor.le_legacy_scan.results));
		btm_send_hci_scan_enable(BTM_BLE_SCAN_DISABLE, BTM_BLE_DUPLICATE_ENABLE);

		btm_update_scanner_filter_policy(SP_ADV_ALL);
		@@ -2999,6 +3036,13 @@ void btm_ble_stop_inquiry(void) {

		alarm_cancel(p_ble_cb->inq_var.inquiry_timer);

		const unsigned long long duration_timestamp =
		timestamper_in_milliseconds.GetTimestamp() -
		btm_cb.neighbor.le_inquiry.start_time_ms;
		BTM_LogHistory(kBtmLogTag, RawAddress::kEmpty, "Le inquiry stopped",
		base::StringPrintf("duration_s:%6.3f results:%-3lu",
		(double)duration_timestamp / 1000.0,
		btm_cb.neighbor.le_inquiry.results));
		p_ble_cb->reset_ble_inquiry();

		/* Cleanup anything remaining on index 0 */

system/stack/btm/btm_inq.cc

+50 −7

Original line number	Diff line number	Diff line
		@@ -55,8 +55,21 @@

		namespace {
		constexpr char kBtmLogTag[] = "SCAN";

		void btm_log_history_scan_mode(uint8_t scan_mode) {
		static uint8_t scan_mode_cached_ = 0xff;
		if (scan_mode_cached_ == scan_mode) return;

		BTM_LogHistory(
		kBtmLogTag, RawAddress::kEmpty, "Classic updated",
		base::StringPrintf("inquiry_scan_enable:%c page_scan_enable:%c",
		(scan_mode & HCI_INQUIRY_SCAN_ENABLED) ? 'T' : 'F',
		(scan_mode & HCI_PAGE_SCAN_ENABLED) ? 'T' : 'F'));
		scan_mode_cached_ = scan_mode;
		}

		} // namespace

		extern tBTM_CB btm_cb;

		extern void btm_inq_remote_name_timer_timeout(void* data);
		@@ -269,6 +282,7 @@ tBTM_STATUS BTM_SetDiscoverability(uint16_t inq_mode) {
		if (btm_cb.btm_inq_vars.connectable_mode & BTM_CONNECTABLE_MASK)
		scan_mode \|= HCI_PAGE_SCAN_ENABLED;

		btm_log_history_scan_mode(scan_mode);
		btsnd_hcic_write_scan_enable(scan_mode);
		btm_cb.btm_inq_vars.discoverable_mode &= (~BTM_DISCOVERABLE_MASK);
		btm_cb.btm_inq_vars.discoverable_mode \|= inq_mode;
		@@ -440,6 +454,7 @@ tBTM_STATUS BTM_SetConnectability(uint16_t page_mode) {
		if (p_inq->discoverable_mode & BTM_DISCOVERABLE_MASK)
		scan_mode \|= HCI_INQUIRY_SCAN_ENABLED;

		btm_log_history_scan_mode(scan_mode);
		btsnd_hcic_write_scan_enable(scan_mode);
		p_inq->connectable_mode &= (~BTM_CONNECTABLE_MASK);
		p_inq->connectable_mode \|= page_mode;
		@@ -480,13 +495,20 @@ void BTM_CancelInquiry(void) {
		return;
		}

		BTM_LogHistory(kBtmLogTag, RawAddress::kEmpty, "Classic inquiry stopped");

		tBTM_INQUIRY_VAR_ST* p_inq = &btm_cb.btm_inq_vars;
		BTM_TRACE_API("BTM_CancelInquiry called");

		CHECK(BTM_IsDeviceUp());

		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) /
		1000.0,
		btm_cb.neighbor.classic_inquiry.results));
		btm_cb.neighbor.classic_inquiry = {};

		/* Only cancel if not in periodic mode, otherwise the caller should call
		* BTM_CancelPeriodicMode */
		if ((p_inq->inq_active & BTM_INQUIRY_ACTIVE_MASK) != 0) {
		@@ -562,7 +584,11 @@ tBTM_STATUS BTM_StartInquiry(tBTM_INQ_RESULTS_CB* p_results_cb,
		return BTM_WRONG_MODE;
		}

		BTM_LogHistory(kBtmLogTag, RawAddress::kEmpty, "Classic inquiry started");
		BTM_LogHistory(kBtmLogTag, RawAddress::kEmpty, "Classic inquiry started",
		base::StringPrintf(
		"%s", (btm_cb.neighbor.classic_inquiry.start_time_ms == 0)
		? ""
		: "ERROR Already in progress"));

		/* Save the inquiry parameters to be used upon the completion of
		* setting/clearing the inquiry filter */
		@@ -576,6 +602,10 @@ tBTM_STATUS BTM_StartInquiry(tBTM_INQ_RESULTS_CB* p_results_cb,
		p_inq->p_inq_results_cb = p_results_cb;
		p_inq->inq_cmpl_info.num_resp = 0; /* Clear the results counter */
		p_inq->inq_active = p_inq->inqparms.mode;
		btm_cb.neighbor.classic_inquiry = {
		.start_time_ms = timestamper_in_milliseconds.GetTimestamp(),
		.results = 0,
		};

		BTM_TRACE_DEBUG("BTM_StartInquiry: p_inq->inq_active = 0x%02x",
		p_inq->inq_active);
		@@ -810,6 +840,8 @@ void btm_inq_db_reset(void) {
		uint8_t num_responses;
		uint8_t temp_inq_active;

		LOG_DEBUG("Resetting inquiry database");

		/* If an inquiry or periodic inquiry is active, reset the mode to inactive */
		if (p_inq->inq_active != BTM_INQUIRY_INACTIVE) {
		temp_inq_active = p_inq->inq_active; /* Save so state can change BEFORE
		@@ -1141,6 +1173,7 @@ void btm_process_inq_results(const uint8_t* p, uint8_t hci_evt_len,
		}
		}

		btm_cb.neighbor.classic_inquiry.results += num_resp;
		for (xx = 0; xx < num_resp; xx++) {
		update = false;
		/* Extract inquiry results */
		@@ -1319,6 +1352,7 @@ void btm_process_inq_complete(tHCI_STATUS status, uint8_t mode) {
		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",
		@@ -1327,8 +1361,9 @@ void btm_process_inq_complete(tHCI_STATUS status, uint8_t mode) {
		btm_acl_update_inquiry_status(BTM_INQUIRY_COMPLETE);
		/* 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.status =
		(tBTM_STATUS)((status == HCI_SUCCESS) ? BTM_SUCCESS
		: BTM_ERR_PROCESSING);

		/* Notify caller that the inquiry has completed; (periodic inquiries do not
		* send completion events */
		@@ -1357,12 +1392,20 @@ void btm_process_inq_complete(tHCI_STATUS status, uint8_t mode) {
		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_ERROR("Received inquiry complete when no inquiry was active");
		}
		#if (BTM_INQ_DEBUG == TRUE)
		BTM_TRACE_DEBUG("inq_active:0x%x state:%d", btm_cb.btm_inq_vars.inq_active,
		btm_cb.btm_inq_vars.state);
		#endif
		}

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

system/stack/btm/btm_int_types.h

+10 −1

Original line number	Diff line number	Diff line
		@@ -41,6 +41,8 @@
		constexpr size_t kMaxLogSize = 255;
		constexpr size_t kBtmLogHistoryBufferSize = 100;

		extern bluetooth::common::TimestamperInMilliseconds timestamper_in_milliseconds;

		class TimestampedStringCircularBuffer
		: public bluetooth::common::TimestampedCircularBuffer<std::string> {
		public:
		@@ -306,6 +308,13 @@ typedef struct tBTM_CB {

		std::shared_ptr<TimestampedStringCircularBuffer> history_{nullptr};

		struct {
		struct {
		long long start_time_ms;
		unsigned long results;
		} classic_inquiry, le_scan, le_inquiry, le_observe, le_legacy_scan;
		} neighbor;

		void Init(uint8_t initial_security_mode) {
		memset(&cfg, 0, sizeof(cfg));
		memset(&devcb, 0, sizeof(devcb));
		@@ -323,6 +332,7 @@ typedef struct tBTM_CB {
		memset(&connecting_dc, 0, sizeof(connecting_dc));

		acl_cb_ = {};
		neighbor = {};

		page_queue = fixed_queue_new(SIZE_MAX);
		sec_pending_q = fixed_queue_new(SIZE_MAX);
		@@ -346,7 +356,6 @@ typedef struct tBTM_CB {

		/* Initialize BTM component structures */
		btm_inq_vars.Init(); /* Inquiry Database and Structures */
		acl_cb_ = {};
		sco_cb.Init(); /* SCO Database and Structures (If included) */
		devcb.Init();