1#!/usr/bin/env python3 2# 3# Copyright 2019 - The Android Open Source Project 4# 5# Licensed under the Apache License, Version 2.0 (the "License"); 6# you may not use this file except in compliance with the License. 7# You may obtain a copy of the License at 8# 9# http://www.apache.org/licenses/LICENSE-2.0 10# 11# Unless required by applicable law or agreed to in writing, software 12# distributed under the License is distributed on an "AS IS" BASIS, 13# WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. 14# See the License for the specific language governing permissions and 15# limitations under the License. 16 17from abc import ABC 18from abc import abstractmethod 19from datetime import datetime 20import inspect 21import logging 22import os 23import pathlib 24import shutil 25import signal 26import subprocess 27import time 28from typing import List 29 30import grpc 31 32from google.protobuf import empty_pb2 as empty_proto 33 34from blueberry.tests.gd.cert import asserts 35from blueberry.tests.gd.cert.adb import BlueberryAdbProxy 36from blueberry.tests.gd.cert.adb import UTF_8 37from blueberry.tests.gd.cert.async_subprocess_logger import AsyncSubprocessLogger 38from blueberry.tests.gd.cert.context import get_current_context 39from blueberry.tests.gd.cert.logging_client_interceptor import LoggingClientInterceptor 40from blueberry.tests.gd.cert.os_utils import get_gd_root 41from blueberry.tests.gd.cert.os_utils import read_crash_snippet_and_log_tail 42from blueberry.tests.gd.cert.os_utils import is_subprocess_alive 43from blueberry.tests.gd.cert.os_utils import make_ports_available 44from blueberry.tests.gd.cert.os_utils import TerminalColor 45 46from blueberry.facade import rootservice_pb2_grpc as facade_rootservice_pb2_grpc 47from blueberry.facade.hal import hal_facade_pb2_grpc 48from blueberry.facade.hci import hci_facade_pb2_grpc 49from blueberry.facade.hci import acl_manager_facade_pb2_grpc 50from blueberry.facade.hci import controller_facade_pb2_grpc 51from blueberry.facade.hci import le_acl_manager_facade_pb2_grpc 52from blueberry.facade.hci import le_advertising_manager_facade_pb2_grpc 53from blueberry.facade.hci import le_initiator_address_facade_pb2_grpc 54from blueberry.facade.hci import le_scanning_manager_facade_pb2_grpc 55from blueberry.facade.l2cap.classic import facade_pb2_grpc as l2cap_facade_pb2_grpc 56from blueberry.facade.l2cap.le import facade_pb2_grpc as l2cap_le_facade_pb2_grpc 57from blueberry.facade.neighbor import facade_pb2_grpc as neighbor_facade_pb2_grpc 58 59from mobly import utils 60from mobly.controllers.android_device_lib.adb import AdbError 61 62ADB_FILE_NOT_EXIST_ERROR = "No such file or directory" 63GRPC_START_TIMEOUT_SEC = 15 64MOBLY_CONTROLLER_CONFIG_NAME = "GdDevice" 65PORT_FORWARDING_ERROR_MSG_PREFIX = "During port forwarding cleanup: " 66PULL_LOG_FILE_ERROR_MSG_PREFIX = "While trying to pull log files" 67 68 69def create(configs): 70 if not configs: 71 raise Exception("Configuration is empty") 72 elif not isinstance(configs, list): 73 raise Exception("Configuration should be a list") 74 return get_instances_with_configs(configs) 75 76 77def destroy(devices): 78 for device in devices: 79 try: 80 device.teardown() 81 except: 82 logging.exception("[%s] Failed to clean up properly due to" % device.label) 83 84 85def get_info(devices): 86 return [] 87 88 89def replace_vars(string, config): 90 serial_number = config.get("serial_number") 91 if serial_number is None: 92 serial_number = "" 93 rootcanal_port = config.get("rootcanal_port") 94 if rootcanal_port is None: 95 rootcanal_port = "" 96 if serial_number == "DUT" or serial_number == "CERT": 97 raise Exception("Did you forget to configure the serial number?") 98 return string.replace("$GD_ROOT", get_gd_root()) \ 99 .replace("$(grpc_port)", config.get("grpc_port")) \ 100 .replace("$(grpc_root_server_port)", config.get("grpc_root_server_port")) \ 101 .replace("$(rootcanal_port)", rootcanal_port) \ 102 .replace("$(signal_port)", config.get("signal_port")) \ 103 .replace("$(serial_number)", serial_number) 104 105 106def get_instances_with_configs(configs): 107 print(configs) 108 devices = [] 109 for config in configs: 110 resolved_cmd = [] 111 for arg in config["cmd"]: 112 logging.debug(arg) 113 resolved_cmd.append(replace_vars(arg, config)) 114 verbose_mode = bool(config.get('verbose_mode', False)) 115 if config.get("serial_number"): 116 device = GdAndroidDevice(config["grpc_port"], config["grpc_root_server_port"], config["signal_port"], 117 resolved_cmd, config["label"], MOBLY_CONTROLLER_CONFIG_NAME, config["name"], 118 config["serial_number"], verbose_mode) 119 else: 120 device = GdHostOnlyDevice(config["grpc_port"], config["grpc_root_server_port"], config["signal_port"], 121 resolved_cmd, config["label"], MOBLY_CONTROLLER_CONFIG_NAME, config["name"], 122 verbose_mode) 123 device.setup() 124 devices.append(device) 125 return devices 126 127 128class GdDeviceBase(ABC): 129 """ 130 Base GD device class that covers common traits which assumes that the 131 device must be driven by a driver-like backing process that takes following 132 command line arguments: 133 --grpc-port: main entry port for facade services 134 --root-server-port: management port for starting and stopping services 135 --btsnoop: path to btsnoop HCI log 136 --signal-port: signaling port to indicate that backing process is started 137 --rootcanal-port: root-canal HCI port, optional 138 """ 139 140 WAIT_CHANNEL_READY_TIMEOUT_SECONDS = 10 141 WAIT_SIGINT_TIMEOUT_SECONDS = 5 142 WAIT_SIGKILL_TIMEOUT_SECONDS = 1 143 144 def __init__(self, grpc_port: str, grpc_root_server_port: str, signal_port: str, cmd: List[str], label: str, 145 type_identifier: str, name: str, verbose_mode: bool): 146 """Verify arguments and log path, initialize Base GD device, common traits 147 for both device based and host only GD cert tests 148 :param grpc_port: main gRPC service port 149 :param grpc_root_server_port: gRPC root server port 150 :param signal_port: signaling port for backing process start up 151 :param cmd: list of arguments to run in backing process 152 :param label: device label used in logs 153 :param type_identifier: device type identifier used in logs 154 :param name: name of device used in logs 155 """ 156 # Must be at the first line of __init__ method 157 values = locals() 158 arguments = [values[arg] for arg in inspect.getfullargspec(GdDeviceBase.__init__).args if arg != "verbose_mode"] 159 asserts.assert_true(all(arguments), "All arguments to GdDeviceBase must not be None nor empty") 160 asserts.assert_true(all(cmd), "cmd list should not have None nor empty component") 161 self.verbose_mode = verbose_mode 162 self.host_only_device = False 163 self.grpc_root_server_port = int(grpc_root_server_port) 164 self.grpc_port = int(grpc_port) 165 self.signal_port = int(signal_port) 166 self.name = name 167 self.type_identifier = type_identifier 168 self.label = label 169 self.log_path_base = get_current_context().get_full_output_path() 170 self.test_runner_base_path = \ 171 get_current_context().get_base_output_path() 172 self.backing_process_log_path = os.path.join(self.log_path_base, 173 '%s_%s_backing_logs.txt' % (self.type_identifier, self.label)) 174 if "--btsnoop=" not in " ".join(cmd): 175 cmd.append("--btsnoop=%s" % os.path.join(self.log_path_base, '%s_btsnoop_hci.log' % self.label)) 176 if "--btsnooz=" not in " ".join(cmd): 177 cmd.append("--btsnooz=%s" % os.path.join(self.log_path_base, '%s_btsnooz_hci.log' % self.label)) 178 if "--btconfig=" not in " ".join(cmd): 179 cmd.append("--btconfig=%s" % os.path.join(self.log_path_base, '%s_bt_config.conf' % self.label)) 180 self.cmd = cmd 181 self.environment = os.environ.copy() 182 if "cert" in self.label: 183 self.terminal_color = TerminalColor.BLUE 184 else: 185 self.terminal_color = TerminalColor.YELLOW 186 187 def setup(self): 188 """Set up this device for test, ensure signal port is available and backing process is started and alive, 189 must run before using this device. 190 - After calling this, teardown() must be called when test finishes 191 - Should be executed after children classes' setup() methods 192 :return: 193 """ 194 # Start backing process 195 logging.debug("[%s] Running %s %s" % (self.type_identifier, self.label, " ".join(self.cmd))) 196 self.backing_process = subprocess.Popen(self.cmd, 197 cwd=get_gd_root(), 198 env=self.environment, 199 stdout=subprocess.PIPE, 200 stderr=subprocess.STDOUT, 201 universal_newlines=True) 202 203 self.backing_process_logger = AsyncSubprocessLogger(self.backing_process, [self.backing_process_log_path], 204 log_to_stdout=self.verbose_mode, 205 tag=self.label, 206 color=self.terminal_color) 207 208 asserts.assert_true(self.backing_process, 209 msg="[%s] failed to open backing process for %s" % (self.type_identifier, self.label)) 210 self.is_backing_process_alive = is_subprocess_alive(self.backing_process) 211 212 asserts.assert_true(self.is_backing_process_alive, 213 msg="[%s] backing process for %s died after starting" % (self.type_identifier, self.label)) 214 215 # If gRPC root server port is not specified, we can skip settings up the root server 216 if self.grpc_root_server_port != -1: 217 # Setup gRPC management channels 218 self.grpc_root_server_channel = grpc.insecure_channel("localhost:%d" % self.grpc_root_server_port) 219 220 self.grpc_root_server_ready = False 221 222 try: 223 logging.info("[%s] Waiting to connect to gRPC root server for %s, timeout is %d seconds" % 224 (self.type_identifier, self.label, GRPC_START_TIMEOUT_SEC)) 225 grpc.channel_ready_future(self.grpc_root_server_channel).result(timeout=GRPC_START_TIMEOUT_SEC) 226 logging.info("[%s] Successfully connected to gRPC root server for %s" % 227 (self.type_identifier, self.label)) 228 self.grpc_root_server_ready = True 229 except grpc.FutureTimeoutError: 230 logging.error("[%s] Failed to connect to gRPC root server for %s" % (self.type_identifier, self.label)) 231 232 asserts.assert_true(self.grpc_root_server_ready, 233 msg="gRPC root server did not start after running " + " ".join(self.cmd)) 234 235 self.grpc_channel = grpc.insecure_channel("localhost:%d" % self.grpc_port) 236 237 if self.verbose_mode: 238 self.grpc_channel = grpc.intercept_channel(self.grpc_channel, LoggingClientInterceptor(self.label)) 239 240 # Establish services from facades 241 if self.grpc_root_server_port != -1: 242 self.rootservice = facade_rootservice_pb2_grpc.RootFacadeStub(self.grpc_root_server_channel) 243 244 self.hal = hal_facade_pb2_grpc.HciHalFacadeStub(self.grpc_channel) 245 self.controller_read_only_property = facade_rootservice_pb2_grpc.ReadOnlyPropertyStub(self.grpc_channel) 246 self.hci = hci_facade_pb2_grpc.HciFacadeStub(self.grpc_channel) 247 self.l2cap = l2cap_facade_pb2_grpc.L2capClassicModuleFacadeStub(self.grpc_channel) 248 self.l2cap_le = l2cap_le_facade_pb2_grpc.L2capLeModuleFacadeStub(self.grpc_channel) 249 self.hci_acl_manager = acl_manager_facade_pb2_grpc.AclManagerFacadeStub(self.grpc_channel) 250 self.hci_le_acl_manager = le_acl_manager_facade_pb2_grpc.LeAclManagerFacadeStub(self.grpc_channel) 251 self.hci_le_initiator_address = le_initiator_address_facade_pb2_grpc.LeInitiatorAddressFacadeStub( 252 self.grpc_channel) 253 self.hci_controller = controller_facade_pb2_grpc.ControllerFacadeStub(self.grpc_channel) 254 self.hci_controller.GetMacAddressSimple = lambda: self.hci_controller.GetMacAddress(empty_proto.Empty()).address 255 self.hci_controller.GetLocalNameSimple = lambda: self.hci_controller.GetLocalName(empty_proto.Empty()).name 256 self.hci_le_advertising_manager = le_advertising_manager_facade_pb2_grpc.LeAdvertisingManagerFacadeStub( 257 self.grpc_channel) 258 self.hci_le_scanning_manager = le_scanning_manager_facade_pb2_grpc.LeScanningManagerFacadeStub( 259 self.grpc_channel) 260 self.neighbor = neighbor_facade_pb2_grpc.NeighborFacadeStub(self.grpc_channel) 261 262 def get_crash_snippet_and_log_tail(self): 263 if is_subprocess_alive(self.backing_process): 264 return None, None 265 266 return read_crash_snippet_and_log_tail(self.backing_process_log_path) 267 268 def teardown(self): 269 """Tear down this device and clean up any resources. 270 - Must be called after setup() 271 - Should be executed before children classes' teardown() 272 :return: 273 """ 274 self.grpc_channel.close() 275 if self.grpc_root_server_port != -1: 276 self.grpc_root_server_channel.close() 277 stop_signal = self.gracefully_stop_backing_process() 278 try: 279 if stop_signal == 0: 280 raise RuntimeError("Failed to gracefully shutdown backing process") 281 return_code = self.backing_process.wait(timeout=self.WAIT_SIGINT_TIMEOUT_SECONDS) 282 except (subprocess.TimeoutExpired, RuntimeError): 283 logging.error("[%s] Failed to interrupt backing process via SIGINT, sending SIGKILL" % self.label) 284 stop_signal = signal.SIGKILL 285 self.backing_process.kill() 286 try: 287 return_code = self.backing_process.wait(timeout=self.WAIT_SIGKILL_TIMEOUT_SECONDS) 288 except subprocess.TimeoutExpired: 289 logging.error("Failed to kill backing process") 290 return_code = -65536 291 if return_code not in [-stop_signal, 0]: 292 logging.error("backing process %s stopped with code: %d" % (self.label, return_code)) 293 self.backing_process_logger.stop() 294 295 def wait_channel_ready(self): 296 future = grpc.channel_ready_future(self.grpc_channel) 297 try: 298 future.result(timeout=self.WAIT_CHANNEL_READY_TIMEOUT_SECONDS) 299 except grpc.FutureTimeoutError: 300 asserts.fail("[%s] wait channel ready timeout" % self.label) 301 302 @abstractmethod 303 def gracefully_stop_backing_process(self): 304 return NotImplemented 305 306 307class GdHostOnlyDevice(GdDeviceBase): 308 """ 309 Host only device where the backing process is running on the host machine 310 """ 311 312 def __init__(self, grpc_port: str, grpc_root_server_port: str, signal_port: str, cmd: List[str], label: str, 313 type_identifier: str, name: str, verbose_mode: bool): 314 super().__init__(grpc_port, grpc_root_server_port, signal_port, cmd, label, MOBLY_CONTROLLER_CONFIG_NAME, name, 315 verbose_mode) 316 self.host_only_device = True 317 # Enable LLVM code coverage output for host only tests 318 self.backing_process_profraw_path = pathlib.Path(self.log_path_base).joinpath( 319 "%s_%s_backing_coverage.profraw" % (self.type_identifier, self.label)) 320 self.environment["LLVM_PROFILE_FILE"] = str(self.backing_process_profraw_path) 321 llvm_binutils = pathlib.Path(get_gd_root()).joinpath("llvm_binutils").joinpath("bin") 322 llvm_symbolizer = llvm_binutils.joinpath("llvm-symbolizer") 323 if llvm_symbolizer.is_file(): 324 self.environment["ASAN_SYMBOLIZER_PATH"] = llvm_symbolizer 325 else: 326 logging.warning("[%s] Cannot find LLVM symbolizer at %s" % (self.label, str(llvm_symbolizer))) 327 self.profdata_path = self.get_coverage_profdata_path_for_host(self.test_runner_base_path, self.type_identifier, 328 self.label) 329 330 def setup(self): 331 # Ensure ports are available 332 # Only check on host only test, for Android devices, these ports will 333 # be opened on Android device and host machine ports will be occupied 334 # by sshd or adb forwarding 335 ports_needed = [self.grpc_port, self.grpc_root_server_port 336 ] if self.grpc_root_server_port != -1 else [self.grpc_port] 337 asserts.assert_true(make_ports_available(ports_needed), 338 "[%s] Failed to make backing process ports available" % self.label) 339 super().setup() 340 341 def teardown(self): 342 super().teardown() 343 self.merge_coverage_profdata_for_host(self.backing_process_profraw_path, self.profdata_path, self.label) 344 345 def get_coverage_info(self): 346 """ 347 Get information needed for coverage reporting 348 :return: a dictionary with all information needed for coverage reporting 349 """ 350 return { 351 "profdata_path": self.profdata_path, 352 "label": self.label, 353 "test_runner_base_path": self.test_runner_base_path, 354 "type_identifier": self.type_identifier, 355 "stack_bin": self.cmd[0] 356 } 357 358 def get_coverage_profdata_path_for_host(self, test_runner_base_path, type_identifier, label) -> pathlib.Path: 359 return pathlib.Path(test_runner_base_path).parent.parent.joinpath("%s_%s_backing_process_coverage.profdata" % 360 (type_identifier, label)) 361 362 def merge_coverage_profdata_for_host(self, backing_process_profraw_path, profdata_path: pathlib.Path, label): 363 if not backing_process_profraw_path.is_file(): 364 logging.info("[%s] Skip coverage report as there is no profraw file at %s" % 365 (label, str(backing_process_profraw_path))) 366 return 367 try: 368 if backing_process_profraw_path.stat().st_size <= 0: 369 logging.info("[%s] Skip coverage report as profraw file is empty at %s" % 370 (label, str(backing_process_profraw_path))) 371 return 372 except OSError: 373 logging.info("[%s] Skip coverage report as profraw file is inaccessible at %s" % 374 (label, str(backing_process_profraw_path))) 375 return 376 llvm_binutils = pathlib.Path(get_gd_root()).joinpath("llvm_binutils").joinpath("bin") 377 llvm_profdata = llvm_binutils.joinpath("llvm-profdata") 378 if not llvm_profdata.is_file(): 379 logging.info("[%s] Skip coverage report as llvm-profdata is not found at %s" % (label, str(llvm_profdata))) 380 return 381 logging.info("[%s] Merging coverage profdata" % label) 382 profdata_path_tmp = profdata_path.parent / (profdata_path.stem + "_tmp" + profdata_path.suffix) 383 # Merge with existing profdata if possible 384 profdata_cmd = [str(llvm_profdata), "merge", "-sparse", str(backing_process_profraw_path)] 385 if profdata_path.is_file(): 386 profdata_cmd.append(str(profdata_path)) 387 profdata_cmd += ["-o", str(profdata_path_tmp)] 388 logging.debug("Running llvm_profdata: %s" % " ".join(profdata_cmd)) 389 result = subprocess.run(profdata_cmd, stdout=subprocess.PIPE, stderr=subprocess.STDOUT) 390 if result.returncode != 0: 391 logging.warning("[%s] Failed to index profdata, cmd result: %r" % (label, result)) 392 profdata_path.unlink(missing_ok=True) 393 return 394 shutil.move(profdata_path_tmp, profdata_path) 395 396 def generate_coverage_report_for_host(self, coverage_info): 397 label = coverage_info["label"] 398 test_runner_base_path = coverage_info["test_runner_base_path"] 399 type_identifier = coverage_info["type_identifier"] 400 profdata_path = coverage_info["profdata_path"] 401 stack_bin = coverage_info["stack_bin"] 402 llvm_binutils = pathlib.Path(get_gd_root()).joinpath("llvm_binutils").joinpath("bin") 403 llvm_cov = llvm_binutils.joinpath("llvm-cov") 404 if not llvm_cov.is_file(): 405 logging.info("[%s] Skip coverage report as llvm-cov is not found at %s" % (label, str(llvm_cov))) 406 return 407 logging.info("[%s] Generating coverage report in JSON" % label) 408 coverage_result_path = pathlib.Path(test_runner_base_path).parent.parent.joinpath( 409 "%s_%s_backing_process_coverage.json" % (type_identifier, label)) 410 with coverage_result_path.open("w") as coverage_result_file: 411 llvm_cov_export_cmd = [ 412 str(llvm_cov), "export", "--format=text", "--ignore-filename-regex", "(external|out).*", 413 "--instr-profile", 414 str(profdata_path), 415 str(stack_bin) 416 ] 417 logging.debug("Running llvm_cov export: %s" % " ".join(llvm_cov_export_cmd)) 418 result = subprocess.run(llvm_cov_export_cmd, 419 stderr=subprocess.PIPE, 420 stdout=coverage_result_file, 421 cwd=os.path.join(get_gd_root())) 422 if result.returncode != 0: 423 logging.warning("[%s] Failed to generated coverage report, cmd result: %r" % (label, result)) 424 coverage_result_path.unlink(missing_ok=True) 425 return 426 logging.info("[%s] Generating coverage summary in text" % label) 427 coverage_summary_path = pathlib.Path(test_runner_base_path).parent.parent.joinpath( 428 "%s_%s_backing_process_coverage_summary.txt" % (type_identifier, label)) 429 with coverage_summary_path.open("w") as coverage_summary_file: 430 llvm_cov_report_cmd = [ 431 str(llvm_cov), "report", "--ignore-filename-regex", "(external|out).*", "--instr-profile", 432 str(profdata_path), 433 str(stack_bin) 434 ] 435 logging.debug("Running llvm_cov report: %s" % " ".join(llvm_cov_report_cmd)) 436 result = subprocess.run(llvm_cov_report_cmd, 437 stderr=subprocess.PIPE, 438 stdout=coverage_summary_file, 439 cwd=os.path.join(get_gd_root())) 440 if result.returncode != 0: 441 logging.warning("[%s] Failed to generated coverage summary, cmd result: %r" % (label, result)) 442 coverage_summary_path.unlink(missing_ok=True) 443 444 def gracefully_stop_backing_process(self): 445 stop_signal = signal.SIGINT 446 self.backing_process.send_signal(stop_signal) 447 return stop_signal 448 449 450class GdAndroidDevice(GdDeviceBase): 451 """Real Android device where the backing process is running on it 452 """ 453 454 WAIT_FOR_DEVICE_TIMEOUT_SECONDS = 180 455 WAIT_FOR_DEVICE_SIGINT_TIMEOUT_SECONDS = 1 456 ADB_ABORT_EXIT_CODE = 134 457 DEVICE_LIB_DIR = "/system/lib64" 458 DEVICE_BIN_DIR = "/system/bin" 459 460 def __init__(self, grpc_port: str, grpc_root_server_port: str, signal_port: str, cmd: List[str], label: str, 461 type_identifier: str, name: str, serial_number: str, verbose_mode: bool): 462 super().__init__(grpc_port, grpc_root_server_port, signal_port, cmd, label, type_identifier, name, verbose_mode) 463 asserts.assert_true(serial_number, "serial_number must not be None nor empty") 464 self.serial_number = serial_number 465 self.adb = BlueberryAdbProxy(serial_number) 466 467 def setup(self): 468 logging.info("Setting up device %s %s" % (self.label, self.serial_number)) 469 asserts.assert_true(self.adb.ensure_root(), "device %s cannot run as root", self.serial_number) 470 self.ensure_verity_disabled() 471 logging.info("Confirmed that verity is disabled on device %s %s" % (self.label, self.serial_number)) 472 473 # Try freeing ports and ignore results 474 asserts.assert_true(make_ports_available((self.grpc_port, self.grpc_root_server_port, self.signal_port)), 475 "[%s] Failed to make backing process ports available" % self.label) 476 self.cleanup_port_forwarding() 477 self.sync_device_time() 478 logging.info("Ports cleaned up and clock is set for device %s %s" % (self.label, self.serial_number)) 479 480 # Set up port forwarding or reverse or die 481 self.tcp_forward_or_die(self.grpc_port, self.grpc_port) 482 if self.grpc_root_server_port != -1: 483 self.tcp_forward_or_die(self.grpc_root_server_port, self.grpc_root_server_port) 484 self.tcp_reverse_or_die(self.signal_port, self.signal_port) 485 logging.info("Port forwarding done on device %s %s" % (self.label, self.serial_number)) 486 487 # Push test binaries 488 local_dir = os.path.join(get_gd_root(), "target") 489 490 def generate_dir_pair(local_dir, device_dir, filename): 491 return os.path.join(local_dir, filename), os.path.join(device_dir, filename) 492 493 # Do not override exist libraries shared by other binaries on the Android device to avoid corrupting the Android device 494 self.push_or_die(*generate_dir_pair(local_dir, self.DEVICE_BIN_DIR, "bluetooth_stack_with_facade")) 495 self.push_or_die(*generate_dir_pair(local_dir, self.DEVICE_LIB_DIR, "[email protected]"), 496 overwrite_existing=False) 497 self.push_or_die(*generate_dir_pair(local_dir, self.DEVICE_LIB_DIR, "[email protected]"), 498 overwrite_existing=False) 499 self.push_or_die(*generate_dir_pair(local_dir, self.DEVICE_LIB_DIR, "libandroid_runtime_lazy.so"), 500 overwrite_existing=False) 501 self.push_or_die(*generate_dir_pair(local_dir, self.DEVICE_LIB_DIR, "libbase.so"), overwrite_existing=False) 502 self.push_or_die(*generate_dir_pair(local_dir, self.DEVICE_LIB_DIR, "libbinder_ndk.so"), 503 overwrite_existing=False) 504 self.push_or_die(*generate_dir_pair(local_dir, self.DEVICE_LIB_DIR, "libbinder.so"), overwrite_existing=False) 505 self.push_or_die(*generate_dir_pair(local_dir, self.DEVICE_LIB_DIR, "libc++.so"), overwrite_existing=False) 506 # libclang_rt.asan-aarch64-android.so is only needed for ASAN build and is automatically included on device 507 #self.push_or_die( 508 # *generate_dir_pair(local_dir, self.DEVICE_LIB_DIR, "libclang_rt.asan-aarch64-android.so"), 509 # overwrite_existing=False) 510 self.push_or_die(*generate_dir_pair(local_dir, self.DEVICE_LIB_DIR, "libcrypto.so"), overwrite_existing=False) 511 self.push_or_die(*generate_dir_pair(local_dir, self.DEVICE_LIB_DIR, "libcutils.so"), overwrite_existing=False) 512 self.push_or_die(*generate_dir_pair(local_dir, self.DEVICE_LIB_DIR, "libgrpc_wrap.so"), 513 overwrite_existing=False) 514 self.push_or_die(*generate_dir_pair(local_dir, self.DEVICE_LIB_DIR, "libgrpc++.so")) 515 self.push_or_die(*generate_dir_pair(local_dir, self.DEVICE_LIB_DIR, "libhidlbase.so"), overwrite_existing=False) 516 self.push_or_die(*generate_dir_pair(local_dir, self.DEVICE_LIB_DIR, "liblog.so"), overwrite_existing=False) 517 self.push_or_die(*generate_dir_pair(local_dir, self.DEVICE_LIB_DIR, "liblzma.so"), overwrite_existing=False) 518 self.push_or_die(*generate_dir_pair(local_dir, self.DEVICE_LIB_DIR, "libprotobuf-cpp-full.so")) 519 self.push_or_die(*generate_dir_pair(local_dir, self.DEVICE_LIB_DIR, "libssl.so"), overwrite_existing=False) 520 self.push_or_die(*generate_dir_pair(local_dir, self.DEVICE_LIB_DIR, "libgrpc++.so")) 521 self.push_or_die(*generate_dir_pair(local_dir, self.DEVICE_LIB_DIR, "libunwindstack.so"), 522 overwrite_existing=False) 523 self.push_or_die(*generate_dir_pair(local_dir, self.DEVICE_LIB_DIR, "libutils.so"), overwrite_existing=False) 524 self.push_or_die(*generate_dir_pair(local_dir, self.DEVICE_LIB_DIR, "libgrpc++.so")) 525 self.push_or_die(*generate_dir_pair(local_dir, self.DEVICE_LIB_DIR, "libz.so"), overwrite_existing=False) 526 527 logging.info("Binaries pushed to device %s %s" % (self.label, self.serial_number)) 528 529 try: 530 self.adb.shell("rm /data/misc/bluetooth/logs/btsnoop_hci.log") 531 except AdbError as error: 532 if ADB_FILE_NOT_EXIST_ERROR not in str(error): 533 logging.error("Error during setup: " + str(error)) 534 535 try: 536 self.adb.shell("rm /data/misc/bluetooth/logs/btsnooz_hci.log") 537 except AdbError as error: 538 if ADB_FILE_NOT_EXIST_ERROR not in str(error): 539 logging.error("Error during setup: " + str(error)) 540 541 try: 542 self.adb.shell("rm /data/misc/bluedroid/bt_config.conf") 543 except AdbError as error: 544 if ADB_FILE_NOT_EXIST_ERROR not in str(error): 545 logging.error("Error during setup: " + str(error)) 546 547 logging.info("Old logs removed from device %s %s" % (self.label, self.serial_number)) 548 549 # Ensure Bluetooth is disabled 550 self.ensure_no_output(self.adb.shell("settings put global ble_scan_always_enabled 0")) 551 self.adb.shell("cmd bluetooth_manager disable") 552 device_bt_state = int(self.adb.shell("settings get global bluetooth_on")) 553 asserts.assert_equal(device_bt_state, 0, 554 "Failed to disable Bluetooth on device %s %s" % (self.label, self.serial_number)) 555 logging.info("Bluetooth disabled on device %s %s" % (self.label, self.serial_number)) 556 557 # Start logcat logging 558 self.logcat_output_path = os.path.join( 559 self.log_path_base, '%s_%s_%s_logcat_logs.txt' % (self.type_identifier, self.label, self.serial_number)) 560 self.logcat_cmd = ["adb", "-s", self.serial_number, "logcat", "-T", "1", "-v", "year", "-v", "uid"] 561 logging.debug("Running %s", " ".join(self.logcat_cmd)) 562 self.logcat_process = subprocess.Popen(self.logcat_cmd, 563 stdout=subprocess.PIPE, 564 stderr=subprocess.STDOUT, 565 universal_newlines=True) 566 asserts.assert_true(self.logcat_process, msg="Cannot start logcat_process at " + " ".join(self.logcat_cmd)) 567 asserts.assert_true(is_subprocess_alive(self.logcat_process), 568 msg="logcat_process stopped immediately after running " + " ".join(self.logcat_cmd)) 569 self.logcat_logger = AsyncSubprocessLogger(self.logcat_process, [self.logcat_output_path], 570 log_to_stdout=self.verbose_mode, 571 tag="%s_%s" % (self.label, self.serial_number), 572 color=self.terminal_color) 573 574 # Done run parent setup 575 logging.info("Done preparation for %s, starting backing process" % self.serial_number) 576 super().setup() 577 578 def teardown(self): 579 super().teardown() 580 stop_signal = signal.SIGINT 581 self.logcat_process.send_signal(stop_signal) 582 try: 583 return_code = self.logcat_process.wait(timeout=self.WAIT_FOR_DEVICE_SIGINT_TIMEOUT_SECONDS) 584 except subprocess.TimeoutExpired: 585 logging.error("[%s_%s] Failed to interrupt logcat process via SIGINT, sending SIGKILL" % 586 (self.label, self.serial_number)) 587 stop_signal = signal.SIGKILL 588 self.logcat_process.kill() 589 try: 590 return_code = self.logcat_process.wait(timeout=self.WAIT_SIGKILL_TIMEOUT_SECONDS) 591 except subprocess.TimeoutExpired: 592 logging.error("Failed to kill logcat_process %s %s" % (self.label, self.serial_number)) 593 return_code = -65536 594 if return_code not in [-stop_signal, 0]: 595 logging.error("logcat_process %s_%s stopped with code: %d" % (self.label, self.serial_number, return_code)) 596 self.logcat_logger.stop() 597 self.cleanup_port_forwarding() 598 self.pull_logs(self.log_path_base) 599 600 def pull_logs(self, base_dir): 601 try: 602 self.adb.pull([ 603 "/data/misc/bluetooth/logs/btsnoop_hci.log", 604 str(os.path.join(base_dir, "%s_btsnoop_hci.log" % self.label)) 605 ]) 606 except AdbError as error: 607 # Some tests have no snoop logs, and that's OK 608 if ADB_FILE_NOT_EXIST_ERROR not in str(error): 609 logging.error(PULL_LOG_FILE_ERROR_MSG_PREFIX + str(error)) 610 try: 611 self.adb.pull( 612 ["/data/misc/bluedroid/bt_config.conf", 613 str(os.path.join(base_dir, "%s_bt_config.conf" % self.label))]) 614 except AdbError as error: 615 # Some tests have no config file, and that's OK 616 if ADB_FILE_NOT_EXIST_ERROR not in str(error): 617 logging.error(PULL_LOG_FILE_ERROR_MSG_PREFIX + str(error)) 618 619 def cleanup_port_forwarding(self): 620 try: 621 self.adb.remove_tcp_forward(self.grpc_port) 622 except AdbError as error: 623 msg = PORT_FORWARDING_ERROR_MSG_PREFIX + str(error) 624 if "not found" in msg: 625 logging.debug(msg) 626 else: 627 logging.error(msg) 628 629 try: 630 if self.grpc_root_server_port != -1: 631 self.adb.remove_tcp_forward(self.grpc_root_server_port) 632 except AdbError as error: 633 msg = PORT_FORWARDING_ERROR_MSG_PREFIX + str(error) 634 if "not found" in msg: 635 logging.debug(msg) 636 else: 637 logging.error(msg) 638 639 try: 640 self.adb.reverse(["--remove", "tcp:%d" % self.signal_port]) 641 except AdbError as error: 642 msg = PORT_FORWARDING_ERROR_MSG_PREFIX + str(error) 643 if "not found" in msg: 644 logging.debug(msg) 645 else: 646 logging.error(msg) 647 648 @staticmethod 649 def ensure_no_output(result): 650 """ 651 Ensure a command has not output 652 """ 653 asserts.assert_true(result is None or len(result) == 0, 654 msg="command returned something when it shouldn't: %s" % result) 655 656 def sync_device_time(self): 657 self.adb.shell("settings put global auto_time 0") 658 self.adb.shell("settings put global auto_time_zone 0") 659 device_tz = self.adb.shell("date +%z").decode(UTF_8).rstrip() 660 asserts.assert_true(device_tz, "date +%z must return device timezone, " 661 "but returned {} instead".format(device_tz)) 662 host_tz = time.strftime("%z") 663 if device_tz != host_tz: 664 target_timezone = utils.get_timezone_olson_id() 665 logging.debug("Device timezone %s does not match host timezone %s, " 666 "syncing them by setting timezone to %s" % (device_tz, host_tz, target_timezone)) 667 self.adb.shell("setprop persist.sys.timezone %s" % target_timezone) 668 self.reboot() 669 self.adb.remount() 670 device_tz = self.adb.shell("date +%z").decode(UTF_8).rstrip() 671 asserts.assert_equal( 672 host_tz, device_tz, "Device timezone %s still does not match host " 673 "timezone %s after reset" % (device_tz, host_tz)) 674 self.adb.shell("date %s" % time.strftime("%m%d%H%M%Y.%S")) 675 datetime_format = "%Y-%m-%dT%H:%M:%S%z" 676 try: 677 device_time = datetime.strptime( 678 self.adb.shell("date +'%s'" % datetime_format).decode(UTF_8).rstrip(), datetime_format) 679 except ValueError: 680 asserts.fail("Failed to get time after sync") 681 return 682 # Include ADB delay that might be longer in SSH environment 683 max_delta_seconds = 3 684 host_time = datetime.now(tz=device_time.tzinfo) 685 asserts.assert_almost_equal((device_time - host_time).total_seconds(), 686 0, 687 msg="Device time %s and host time %s off by >%dms after sync" % 688 (device_time.isoformat(), host_time.isoformat(), int(max_delta_seconds * 1000)), 689 delta=max_delta_seconds) 690 691 def push_or_die(self, src_file_path, dst_file_path, push_timeout=300, overwrite_existing=True): 692 """Pushes a file to the Android device 693 694 Args: 695 src_file_path: The path to the file to install. 696 dst_file_path: The destination of the file. 697 push_timeout: How long to wait for the push to finish in seconds 698 """ 699 if not overwrite_existing and self.adb.path_exists(dst_file_path): 700 logging.debug("Skip pushing {} to {} as it already exists on device".format(src_file_path, dst_file_path)) 701 return 702 out = self.adb.push([src_file_path, dst_file_path], timeout=push_timeout).decode(UTF_8).rstrip() 703 if 'error' in out: 704 asserts.fail('Unable to push file %s to %s due to %s' % (src_file_path, dst_file_path, out)) 705 706 def tcp_forward_or_die(self, host_port, device_port, num_retry=1): 707 """ 708 Forward a TCP port from host to device or fail 709 :param host_port: host port, int, 0 for adb to assign one 710 :param device_port: device port, int 711 :param num_retry: number of times to reboot and retry this before dying 712 :return: host port int 713 """ 714 error_or_port = self.adb.tcp_forward(host_port, device_port) 715 if not error_or_port: 716 logging.debug("host port %d was already forwarded" % host_port) 717 return host_port 718 if not isinstance(error_or_port, int): 719 if num_retry > 0: 720 # If requested, reboot an retry 721 num_retry -= 1 722 logging.warning("[%s] Failed to TCP forward host port %d to " 723 "device port %d, num_retries left is %d" % 724 (self.label, host_port, device_port, num_retry)) 725 self.reboot() 726 self.adb.remount() 727 return self.tcp_forward_or_die(host_port, device_port, num_retry=num_retry) 728 asserts.fail('Unable to forward host port %d to device port %d, error %s' % 729 (host_port, device_port, error_or_port)) 730 return error_or_port 731 732 def tcp_reverse_or_die(self, device_port, host_port, num_retry=1): 733 """ 734 Forward a TCP port from device to host or fail 735 :param device_port: device port, int, 0 for adb to assign one 736 :param host_port: host port, int 737 :param num_retry: number of times to reboot and retry this before dying 738 :return: device port int 739 """ 740 error_or_port = self.adb.reverse(["tcp:%d" % device_port, "tcp:%d" % host_port]) 741 if not error_or_port: 742 logging.debug("device port %d was already reversed" % device_port) 743 return device_port 744 try: 745 error_or_port = int(error_or_port) 746 except ValueError: 747 if num_retry > 0: 748 # If requested, reboot an retry 749 num_retry -= 1 750 logging.warning("[%s] Failed to TCP reverse device port %d to " 751 "host port %d, num_retries left is %d" % 752 (self.label, device_port, host_port, num_retry)) 753 self.reboot() 754 self.adb.remount() 755 return self.tcp_reverse_or_die(device_port, host_port, num_retry=num_retry) 756 asserts.fail('Unable to reverse device port %d to host port %d, error %s' % 757 (device_port, host_port, error_or_port)) 758 return error_or_port 759 760 def ensure_verity_disabled(self): 761 """Ensures that verity is enabled. 762 763 If verity is not enabled, this call will reboot the phone. Note that 764 this only works on debuggable builds. 765 """ 766 logging.debug("Disabling verity and remount for %s", self.serial_number) 767 # The below properties will only exist if verity has been enabled. 768 system_verity = self.adb.getprop('partition.system.verified') 769 vendor_verity = self.adb.getprop('partition.vendor.verified') 770 if system_verity or vendor_verity: 771 self.adb.disable_verity() 772 self.reboot() 773 self.adb.remount() 774 self.adb.wait_for_device(timeout=self.WAIT_FOR_DEVICE_TIMEOUT_SECONDS) 775 776 def reboot(self, timeout_minutes=15.0): 777 """Reboots the device. 778 779 Reboot the device, wait for device to complete booting. 780 """ 781 logging.debug("Rebooting %s", self.serial_number) 782 self.adb.reboot() 783 784 timeout_start = time.time() 785 timeout = timeout_minutes * 60 786 # Android sometimes return early after `adb reboot` is called. This 787 # means subsequent calls may make it to the device before the reboot 788 # goes through, return false positives for getprops such as 789 # sys.boot_completed. 790 while time.time() < timeout_start + timeout: 791 try: 792 logging.debug("waiting for device %s to turn off", self.serial_number) 793 self.adb.get_state() 794 logging.debug("device %s not turned off yet", self.serial_number) 795 time.sleep(.1) 796 except AdbError: 797 # get_state will raise an error if the device is not found. We 798 # want the device to be missing to prove the device has kicked 799 # off the reboot. 800 logging.debug("device %s is turned off, waiting for it to boot", self.serial_number) 801 break 802 minutes_left = timeout_minutes - (time.time() - timeout_start) / 60.0 803 self.wait_for_boot_completion(timeout_minutes=minutes_left) 804 asserts.assert_true(self.adb.ensure_root(), "device %s cannot run as root after reboot" % self.serial_number) 805 806 def wait_for_boot_completion(self, timeout_minutes=15.0): 807 """ 808 Waits for Android framework to broadcast ACTION_BOOT_COMPLETED. 809 :param timeout_minutes: number of minutes to wait 810 """ 811 timeout_start = time.time() 812 timeout = timeout_minutes * 60 813 814 self.adb.wait_for_device(timeout=self.WAIT_FOR_DEVICE_TIMEOUT_SECONDS) 815 while time.time() < timeout_start + timeout: 816 try: 817 completed = self.adb.getprop("sys.boot_completed") 818 if completed == '1': 819 return 820 except AdbError: 821 # adb shell calls may fail during certain period of booting 822 # process, which is normal. Ignoring these errors. 823 pass 824 time.sleep(5) 825 asserts.fail(msg='Device %s booting process timed out.' % self.serial_number) 826 827 def gracefully_stop_backing_process(self): 828 """ 829 Gracefully stops backing process 830 :return: expected backing process exit code on success, 0 on error 831 """ 832 backing_process_pid = None 833 # Since we do not know which segment of self.cmd is the command running 834 # on the Android device. We have to iterate with trial and error. 835 cmd = self.cmd 836 if len(self.cmd) >= 5: 837 # skip adb -s serial shell to speed up the search 838 # we don't know if any environment variables are set up before the 839 # actual command and hence has to try from the 4th argument 840 cmd = self.cmd[4:] + self.cmd[:4] 841 for segment in cmd: 842 try: 843 # pgrep only takes 16 bytes including null terminator 844 # -f cannot be used because that include the full command args 845 current_cmd = pathlib.Path(segment).stem[:15] 846 # -x matches whole command, cannot avoid as short segment may partially match 847 # -n returnes the newest command matched 848 backing_process_pid = int(self.adb.shell("pgrep -n -x {}".format(current_cmd))) 849 logging.debug("Found backing process name on Android as {}, pid is {}".format( 850 segment, backing_process_pid)) 851 except (AdbError, ValueError) as e: 852 logging.debug("Failed to run pgrep {}".format(e)) 853 if backing_process_pid is not None: 854 break 855 if backing_process_pid is None: 856 logging.warning("Failed to get pid for cmd {}".format(self.cmd)) 857 try: 858 logging.debug(self.adb.shell("ps -A | grep bluetooth")) 859 except AdbError: 860 pass 861 return 0 862 stop_signal = signal.SIGINT 863 self.adb.shell("kill -{} {}".format(stop_signal, backing_process_pid)) 864 logging.debug("Sent SIGINT to backing process at pid {}".format(backing_process_pid)) 865 stop_signal = -self.ADB_ABORT_EXIT_CODE 866 return stop_signal 867