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