1# Lint as: python2, python3 2# Copyright 2022 The Chromium OS Authors. All rights reserved. 3# Use of this source code is governed by a BSD-style license that can be 4# found in the LICENSE file. 5"""Server side Bluetooth Quality Report tests.""" 6 7from __future__ import absolute_import 8from __future__ import division 9from __future__ import print_function 10 11import collections 12import logging 13import os 14from threading import Thread 15import time 16 17from autotest_lib.client.common_lib import error 18from autotest_lib.server.cros.bluetooth.bluetooth_adapter_audio_tests import ( 19 BluetoothAdapterAudioTests) 20from autotest_lib.server.cros.bluetooth.bluetooth_adapter_hidreports_tests import ( 21 BluetoothAdapterHIDReportTests) 22from autotest_lib.server.cros.bluetooth.bluetooth_adapter_tests import ( 23 test_retry_and_log) 24 25# List of the controllers that does not support the Bluetooth Quality Report. 26QR_UNSUPPORTED_CHIPSETS = [ 27 'MVL-8897', 'MVL-8997', 28 'Intel-AC7260', 'Intel-AC7265', 29 'QCA-6174A-3-UART', 'QCA-6174A-5-USB' 30] 31 32# An example AOSP BQR event in btsnoop.log looks like: 33# = bluetoothd: quality: BQR Quality Report 75.018599 34# = bluetoothd: quality: quality_report_id 1 75.018658 35# = bluetoothd: quality: packet_type 2 75.019402 36# = bluetoothd: quality: conn_handle 1 75.019477 37# = bluetoothd: quality: conn_role 0 75.019539 38# = bluetoothd: quality: tx_power_level 0 75.019601 39# = bluetoothd: quality: rssi -29 75.019665 40# = bluetoothd: quality: snr 0 75.019727 41# = bluetoothd: quality: unused_afh_channel_count 3 75.019787 42# = bluetoothd: quality: afh_select_unideal_channel_count 0 75.019847 43# = bluetoothd: quality: lsto 20000.00 75.019906 44# = bluetoothd: quality: conn_piconet_clock 9143780.00 75.019965 45# = bluetoothd: quality: retransmission_count 0 75.020050 46# = bluetoothd: quality: no_rx_count 0 75.020120 47# = bluetoothd: quality: nak_count 0 75.020420 48# = bluetoothd: quality: last_tx_ack_timestamp 9143754.06 75.020485 49# = bluetoothd: quality: flow_off_count 0 75.020551 50# = bluetoothd: quality: last_flow_on_timestamp 9143779.06 75.020610 51# = bluetoothd: quality: buffer_overflow_bytes 0 75.020670 52# = bluetoothd: quality: buffer_underflow_bytes 150492 75.020732 53 54# An example Telemetry event for A2DP (ACL) in btsnoop.log looks like: 55# = bluetoothd: quality: Intel Extended Telemetry Event 5.251502 56# = bluetoothd: quality: ACL connection handle: 0x0100 5.251520 57# = bluetoothd: quality: Rx HEC errors: 0 5.251546 58# = bluetoothd: quality: Rx CRC errors: 0 5.251558 59# = bluetoothd: quality: Packets from host: 222 5.251581 60# = bluetoothd: quality: Tx packets: 221 5.251594 61# = bluetoothd: quality: Tx packets 0 retries: 217 5.251617 62# = bluetoothd: quality: Tx packets 1 retries: 4 5.251630 63# = bluetoothd: quality: Tx packets 2 retries: 0 5.251651 64# = bluetoothd: quality: Tx packets 3 retries: 0 5.251662 65# = bluetoothd: quality: Tx packets 4 retries: 0 5.251686 66# = bluetoothd: quality: Tx DH1 packets: 0 5.251703 67# = bluetoothd: quality: Tx DH3 packets: 0 5.251725 68# = bluetoothd: quality: Tx DH5 packets: 0 5.251762 69# = bluetoothd: quality: Tx 2DH1 packets: 0 5.251790 70# = bluetoothd: quality: Tx 2DH3 packets: 0 5.251818 71# = bluetoothd: quality: Tx 2DH5 packets: 0 5.251847 72# = bluetoothd: quality: Tx 3DH1 packets: 55 5.251872 73# = bluetoothd: quality: Tx 3DH3 packets: 2 5.251898 74# = bluetoothd: quality: Tx 3DH5 packets: 164 5.251926 75# = bluetoothd: quality: Rx packets: 1304 5.251953 76# = bluetoothd: quality: ACL link throughput: 97143 5.251978 77# = bluetoothd: quality: ACL max packet latency: 25625 5.252023 78# = bluetoothd: quality: ACL avg packet latency: 9143 5.252052 79 80# An example Telemetry events for HFP (SCO) in btsnoop.log looks like: 81# = bluetoothd: quality: Intel Extended Telemetry Event 5.894338 82# = bluetoothd: quality: SCO connection handle: 0x010a 5.894359 83# = bluetoothd: quality: Packets from host: 1584 5.894378 84# = bluetoothd: quality: Tx packets: 637 5.894397 85# = bluetoothd: quality: Rx payload lost: 0 5.894417 86# = bluetoothd: quality: Tx payload lost: 24 5.894436 87# = bluetoothd: quality: Rx No SYNC errors (slot 0): 0 5.894454 88# = bluetoothd: quality: Rx No SYNC errors (slot 1): 20 5.894474 89# = bluetoothd: quality: Rx No SYNC errors (slot 2): 0 5.894492 90# = bluetoothd: quality: Rx No SYNC errors (slot 3): 0 5.894511 91# = bluetoothd: quality: Rx No SYNC errors (slot 4): 0 5.894531 92# = bluetoothd: quality: Rx HEC errors (slot 0): 65536 5.894550 93# = bluetoothd: quality: Rx HEC errors (slot 1): 1 5.894569 94# = bluetoothd: quality: Rx HEC errors (slot 2): 0 5.894590 95# = bluetoothd: quality: Rx HEC errors (slot 3): 0 5.894608 96# = bluetoothd: quality: Rx HEC errors (slot 4): 0 5.894627 97# = bluetoothd: quality: Rx CRC errors (slot 0): 0 5.894645 98# = bluetoothd: quality: Rx CRC errors (slot 1): 0 5.894664 99# = bluetoothd: quality: Rx CRC errors (slot 2): 0 5.894682 100# = bluetoothd: quality: Rx CRC errors (slot 3): 0 5.894701 101# = bluetoothd: quality: Rx CRC errors (slot 4): 0 5.894720 102# = bluetoothd: quality: Rx NAK errors (slot 0): 41549824 5.894738 103# = bluetoothd: quality: Rx NAK errors (slot 1): 4 5.894757 104# = bluetoothd: quality: Rx NAK errors (slot 2): 0 5.894775 105# = bluetoothd: quality: Rx NAK errors (slot 3): 0 5.894806 106# = bluetoothd: quality: Rx NAK errors (slot 4): 0 5.894824 107# = bluetoothd: quality: Failed Tx due to Wifi coex (slot 0): 0 5.894843 108# = bluetoothd: quality: Failed Tx due to Wifi coex (slot 1): 0 5.894861 109# = bluetoothd: quality: Failed Tx due to Wifi coex (slot 2): 0 5.894876 110# = bluetoothd: quality: Failed Tx due to Wifi coex (slot 3): 0 5.894890 111# = bluetoothd: quality: Failed Tx due to Wifi coex (slot 4): 0 5.894903 112# = bluetoothd: quality: Failed Rx due to Wifi coex (slot 0): 0 5.894917 113# = bluetoothd: quality: Failed Rx due to Wifi coex (slot 1): 0 5.894930 114# = bluetoothd: quality: Failed Rx due to Wifi coex (slot 2): 0 5.894944 115# = bluetoothd: quality: Failed Rx due to Wifi coex (slot 3): 0 5.894957 116# = bluetoothd: quality: Failed Rx due to Wifi coex (slot 4): 0 5.894971 117# = bluetoothd: quality: Late samples inserted based on CDC: 0 5.894984 118# = bluetoothd: quality: Samples dropped: 0 5.894997 119# = bluetoothd: quality: Mute samples sent at initial connection: 18 5.895032 120# = bluetoothd: quality: PLC injection data: 0 5.895050 121 122# Define constants 123QR_EVENT_PERIOD = 5 124TELEMETRY_NUM_SLOTS = 5 125TELEMETRY_NUM_RETRIES = 5 126TELEMETRY_NUM_PACKET_TYPES = 9 127 128# Define event types 129AOSP_BQR = 0 130TELEMETRY_ACL = 1 131TELEMETRY_SCO = 2 132 133# Define event subevts 134AOSP_SUBEVTS = [ 135 'quality_report_id', 'packet_type', 'conn_handle', 'conn_role', 136 'tx_power_level', 'rssi', 'snr', 'unused_afh_channel_count', 137 'afh_select_unideal_channel_count', 'lsto', 'conn_piconet_clock', 138 'retransmission_count', 'no_rx_count', 'nak_count', 139 'last_tx_ack_timestamp', 'flow_off_count', 140 'last_flow_on_timestamp', 'buffer_overflow_bytes', 141 'buffer_underflow_bytes' 142] 143 144BREDR_PACKET_TYPE = [ 145 'DH1', 'DH3', 'DH5', '2DH1', '2DH3', '2DH5', '3DH1', '3DH3', '3DH5' 146] 147 148TELEMETRY_ACL_SUBEVTS = [ 149 'ACL_connection_handle', 'Rx_HEC_errors', 'Rx_CRC_errors', 150 'Packets_from_host', 'Tx_packets', 'Rx_packets', 151 'ACL_link_throughput', 'ACL_max_packet_latency', 152 'ACL_avg_packet_latency' 153] 154 155for t in BREDR_PACKET_TYPE: 156 TELEMETRY_ACL_SUBEVTS.append(f'Tx_{t}_packets') 157 158for i in range(TELEMETRY_NUM_RETRIES): 159 TELEMETRY_ACL_SUBEVTS.append(f'Tx_packets_{i}_retries') 160 161TELEMETRY_SCO_SUBEVTS = [ 162 'Tx_packets', 'Rx_payload_lost', 163 'Late_samples_inserted_based_on_CDC', 'Samples_dropped', 164 'Mute_samples_sent_at_initial_connection', 'PLC_injection_data' 165] 166 167for i in range(TELEMETRY_NUM_SLOTS): 168 TELEMETRY_SCO_SUBEVTS.append(f'Rx_No_SYNC_errors_(slot_{i})') 169 TELEMETRY_SCO_SUBEVTS.append(f'Rx_HEC_errors_(slot_{i})') 170 TELEMETRY_SCO_SUBEVTS.append(f'Rx_CRC_errors_(slot_{i})') 171 TELEMETRY_SCO_SUBEVTS.append(f'Rx_NAK_errors_(slot_{i})') 172 TELEMETRY_SCO_SUBEVTS.append(f'Failed_Tx_due_to_Wifi_coex_(slot_{i})') 173 TELEMETRY_SCO_SUBEVTS.append(f'Failed_Rx_due_to_Wifi_coex_(slot_{i})') 174 175START_TIME_SUBEVT = 'start_time' 176END_TIME_SUBEVT = 'end_time' 177QUALITY_PREFIX_STRING = '= bluetoothd: quality:' 178 179# Define event handler ids and last ids 180AOSP_HANDLER_SUBEVT = 'conn_handle' 181AOSP_LAST_SUBEVT = 'buffer_underflow_bytes' 182 183TELEMETRY_ACL_HANDLER_SUBEVT = 'ACL_connection_handle' 184TELEMETRY_ACL_LAST_SUBEVT = 'ACL_avg_packet_latency' 185 186TELEMETRY_SCO_HANDLER_SUBEVT = 'SCO_connection_handle' 187TELEMETRY_SCO_LAST_SUBEVT = 'PLC_injection_data' 188 189HANDLER_SUBEVT = (AOSP_HANDLER_SUBEVT, TELEMETRY_ACL_HANDLER_SUBEVT, 190 TELEMETRY_SCO_HANDLER_SUBEVT) 191END_SUBEVT = (AOSP_LAST_SUBEVT, TELEMETRY_ACL_LAST_SUBEVT, 192 TELEMETRY_SCO_LAST_SUBEVT) 193CHECK_SUBEVTS = (AOSP_SUBEVTS, TELEMETRY_ACL_SUBEVTS, 194 TELEMETRY_SCO_SUBEVTS) 195NOT_EVENT_SUBEVTS = (START_TIME_SUBEVT, END_TIME_SUBEVT) 196 197def _read_line(line): 198 """Reading a line of log produced by the quality event packet. 199 200 A line of log looks like: 201 202 = bluetoothd: quality: buffer_underflow_bytes 150492 75.020732 203 204 line[0:2] is the prefix, 205 line[3:-2] is the data subevt, may separate by some spaces, 206 line[-2] is the value of the subevt, 207 line[-1] is the sending time of the data. 208 209 @returns: subevt, name of the variable in the packet. 210 value, value of the variable in the packet. 211 time, sending time of the variable in the packet. 212 213 @raises: error.TestError if failed. 214 """ 215 try: 216 line = line.split() 217 subevt = '_'.join(line[3:-2]).strip(':') 218 value = line[-2] 219 time_ = line[-1] 220 except Exception as e: 221 raise error.TestError( 222 'Exception in reading Bluetooth Quality Report: %s' % e) 223 return subevt, value, time_ 224 225def _handler_to_base_10(handler): 226 """Convert handler from string to base 10 integer. 227 228 @param handler: a string of quality report handler. 229 230 @returns: integer represents the handler. 231 """ 232 # Either base 10 or base 16. 233 if handler.startswith('0x'): 234 handler = int(handler, 16) 235 else: 236 handler = int(handler) 237 238 return handler 239 240def collect_qr_event_from_log(file_path): 241 """Collecting all the quality event reports from the btsnoop log. 242 243 This function will grep all the quality event from the log 244 and store into a dict. 245 246 @param file_path: where the btsnoop log place at. 247 248 @returns: all_reports, a dict with the format: 249 {'handler1':packet_list1, 'handler2':packet_list2, ...}. 250 251 @raises: error.TestError if failed. 252 """ 253 all_reports = collections.defaultdict(list) 254 255 lines = None 256 with open(file_path, 'r') as f: 257 lines = f.readlines() 258 259 report, handler = {}, None 260 for line in lines: 261 if not line.startswith(QUALITY_PREFIX_STRING): 262 continue 263 264 subevt, value, time_ = _read_line(line) 265 if not report: 266 report[START_TIME_SUBEVT] = time_ 267 else: 268 report[subevt] = value 269 270 if subevt in HANDLER_SUBEVT: 271 handler = _handler_to_base_10(value) 272 273 if subevt in END_SUBEVT: 274 if handler is None: 275 raise error.TestError( 276 'Report handler is None type') 277 278 report[END_TIME_SUBEVT] = time_ 279 all_reports[handler].append(report) 280 report, handler = {}, None 281 282 logging.debug("========== Got reports: ========== ") 283 for handler, reports in all_reports.items(): 284 logging.debug('handler: %s \n', handler) 285 for report in reports: 286 logging.debug('report: %s \n', report) 287 logging.debug('\n') 288 289 return all_reports 290 291class BluetoothAdapterQRTests(BluetoothAdapterHIDReportTests, 292 BluetoothAdapterAudioTests): 293 """Server side Bluetooth adapter QR test class.""" 294 BTSNOOP_LOG_DIR = '/tmp' 295 BTSNOOP_LOG_FILENAME = 'btsnoop.log' 296 BTSNOOP_LOG_FILE = os.path.join(BTSNOOP_LOG_DIR, BTSNOOP_LOG_FILENAME) 297 298 def collect_qr_event_from_log(self): 299 """Collect the quality event from btsnoop log""" 300 return collect_qr_event_from_log(self.BTSNOOP_LOG_FILE) 301 302 @test_retry_and_log(False) 303 def test_check_connection_handle_unique(self, reports, handler_subevt): 304 """Checking if the handler subevt in the quality packet list is unique. 305 306 @param reports: a list of quality event reports. 307 @param handler_subevt: specify a handler subevt in HANDLER_SUBEVT to 308 check. 309 310 @returns: True if the handler subevt is unique in the packet list, 311 False otherwise. 312 """ 313 reports_len = len(reports) 314 if reports_len <= 1: 315 return True 316 317 handlers = [reports[i][handler_subevt] for i in range(reports_len)] 318 return len(set(handlers)) == 1 319 320 @test_retry_and_log(False) 321 def test_check_reports_completeness(self, reports, check_subevt_list): 322 """Check if all sub-events in check_subevt_list can be found in reports. 323 324 @param reports: a list of quality event reports. 325 @param check_subevt_list: a set of subevts that define the content of 326 the quality event packet. 327 328 @returns: True if all sub-events in check_subevt_list can be found in 329 reports, False otherwise. 330 """ 331 missing_subevt = [] 332 for report in reports: 333 # Check the completeness of the packet. 334 for check_subevt in check_subevt_list: 335 if check_subevt not in report: 336 missing_subevt.append(check_subevt) 337 338 # Check the length of the packet. 339 if (len(check_subevt_list) + len(NOT_EVENT_SUBEVTS)) > len(report): 340 logging.error('Error in test_check_reports_completeness(): ' 341 'wrong packet size') 342 return False 343 344 if missing_subevt: 345 logging.info( 346 'Error in test_check_reports_completeness(): ' 347 'missing subevt: %s in all reports', missing_subevt) 348 return False 349 return True 350 351 @test_retry_and_log(False) 352 def test_check_period(self, reports, report_type, 353 tolerable_deviation=0.05): 354 """Checking if the sending time between adjecent packet is tolerable. 355 356 @param reports: a list of quality event reports. 357 @param tolerable_deviation : the percentage of the tolerable deviation 358 to the QR_EVENT_PERIOD. 359 360 @returns: True if all the time differences between reports are 361 less than the tolerance. 362 """ 363 if len(reports) <= 1: 364 return True 365 366 tolerance = tolerable_deviation * QR_EVENT_PERIOD 367 368 # According to the spec of AOSP, there are 4 kind of sub-events and we 369 # only care about the sub-event whose quality_report_id is 1. 370 if report_type == AOSP_BQR: 371 reports = [ 372 report for report in reports 373 if report['quality_report_id'] == '1' 374 ] 375 376 for i in range(1, len(reports)): 377 time_diff = (float(reports[i][START_TIME_SUBEVT]) - 378 float(reports[i - 1][END_TIME_SUBEVT])) 379 380 if time_diff < 0: 381 logging.error('Error in test_check_period(): time_diff < 0') 382 return False 383 if abs(time_diff - QR_EVENT_PERIOD) >= tolerance: 384 logging.error('Error in test_check_period: tolerance exceed') 385 return False 386 return True 387 388 @test_retry_and_log(False) 389 def test_send_log(self): 390 """Sending the btsnoop log from the DUT back to the autoserv. 391 392 This test can be used only when the self.dut_btmon_log_path 393 was set and this variable is set in the quick_test_init() by default. 394 395 @returns: True if success, False otherwise. 396 """ 397 btsnoop_path = self.BTSNOOP_LOG_FILE 398 try: 399 cmd = f'btmon -C 100 -r {self.dut_btmon_log_path} > {btsnoop_path}' 400 res = self.host.run(cmd).stdout 401 logging.debug('run command: %s, result: %s', cmd, res) 402 403 self.host.get_file(btsnoop_path, btsnoop_path, delete_dest=True) 404 except Exception as e: 405 logging.error('Exception in test_send_log: %s', e) 406 return False 407 return True 408 409 @test_retry_and_log(False) 410 def test_not_receive_qr_event_log(self): 411 """Checking if not reveice the qr event log""" 412 all_reports = self.collect_qr_event_from_log() 413 logging.debug("all_reports: %s", all_reports) 414 return len(all_reports) == 0 415 416 # --------------------------------------------------------------- 417 # Definitions of all bluetooth audio test sequences 418 # --------------------------------------------------------------- 419 420 def check_qr_event_log(self, num_devices): 421 """Checking if the all the packet list pass the criteria. 422 423 This function check four things: 424 - the number of event handlers is greater than the num_devices 425 - test_check_connection_handle_unique 426 - test_check_reports_completeness 427 - test_check_period 428 429 @param num_devices: number of Bluetooth devices expected. 430 """ 431 all_reports = self.collect_qr_event_from_log() 432 433 if len(all_reports) < num_devices: 434 raise error.TestFail( 435 'Error in test_check_qr_event_log: wrong ' 436 'handler number: %s, expected: %s' % (len(all_reports), 437 num_devices)) 438 439 for reports in all_reports.values(): 440 report_type = None 441 for type_, handler_subevt in enumerate(HANDLER_SUBEVT): 442 if handler_subevt in reports[0]: 443 report_type = type_ 444 break 445 if report_type is None: 446 raise error.TestError('report_type is None') 447 448 self.test_check_connection_handle_unique( 449 reports, HANDLER_SUBEVT[report_type]) 450 self.test_check_reports_completeness( 451 reports, CHECK_SUBEVTS[report_type]) 452 self.test_check_period(reports, report_type) 453 454 def qr_a2dp(self, device, test_profile): 455 """Checking if quality event works fine with A2DP streaming. 456 457 @param device: the bluetooth peer device. 458 @param test_profile: the test profile to used. 459 """ 460 self.test_a2dp_sinewaves(device, test_profile, duration=None) 461 462 def qr_hfp_dut_as_src(self, device, test_profile): 463 """Checking if quality event works fine with HFP streaming. 464 465 @param device: the bluetooth peer device. 466 @param test_profile: the test profile to used. 467 """ 468 self.hfp_dut_as_source(device, test_profile) 469 470 def qr_disabled_a2dp(self, device, test_profile): 471 """Checking if disable logging quality event success. 472 473 @param device: the bluetooth peer device. 474 @param test_profile: the test profile to used. 475 """ 476 self.enable_disable_debug_log(enable=True) 477 self.enable_disable_quality_debug_log(enable=True) 478 time.sleep(3) 479 self.enable_disable_quality_debug_log(enable=False) 480 self.enable_disable_debug_log(enable=False) 481 time.sleep(3) 482 483 self.dut_btmon_log_path = self.start_new_btmon() 484 self.test_a2dp_sinewaves(device, test_profile, duration=None) 485 self.test_send_log() 486 self.test_not_receive_qr_event_log() 487 488 def qr_a2dp_cl_keyboard(self, audio_device, keyboard_device, test_profile): 489 """Checking if quality event works fine with multiple devices. 490 491 @param audio_device: the bluetooth audio device. 492 @param keyboard_device: the bluetooth keyboard device. 493 @param test_profile: the audio test profile to used. 494 """ 495 p1 = Thread(target=self.test_keyboard_input_from_trace, 496 args=(keyboard_device, "simple_text")) 497 p2 = Thread(target=self.test_a2dp_sinewaves, 498 args=(audio_device, test_profile, None)) 499 p1.start() 500 p2.start() 501 p1.join() 502 p2.join() 503 504 def qr_hfp_dut_as_sink_cl_keyboard(self, audio_device, keyboard_device, 505 test_profile): 506 """Checking if quality event works fine with multiple devices. 507 508 @param audio_device: the bluetooth audio device. 509 @param keyboard_device: the bluetooth keyboard device. 510 @param test_profile: the audio test profile to used. 511 """ 512 p1 = Thread(target=self.test_keyboard_input_from_trace, 513 args=(keyboard_device, "simple_text")) 514 p2 = Thread(target=self.hfp_dut_as_sink, 515 args=(audio_device, test_profile)) 516 p1.start() 517 p2.start() 518 p1.join() 519 p2.join() 520 521 def qr_power_cycle_a2dp(self, device, test_profile): 522 """Checking if the enable debug state persists after power reset. 523 524 @param device: the bluetooth audio device. 525 @param test_profile: the audio test profile to used. 526 """ 527 self.test_reset_off_adapter() 528 time.sleep(3) 529 self.test_reset_on_adapter() 530 531 # Need to connect to the device again. 532 self.test_bluetoothd_running() 533 self.test_discover_device(device.address) 534 self.test_pairing(device.address, device.pin, trusted=True) 535 self.test_connection_by_adapter(device.address) 536 537 self.dut_btmon_log_path = self.start_new_btmon() 538 539 self.test_a2dp_sinewaves(device, test_profile, duration=None) 540