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 asserts.assert_true( 484 make_ports_available((self.grpc_port, self.grpc_root_server_port, self.signal_port)), 485 "[%s] Failed to make backing process ports available" % self.label) 486 self.cleanup_port_forwarding() 487 self.sync_device_time() 488 logging.info("Ports cleaned up and clock is set for device %s %s" % (self.label, self.serial_number)) 489 490 # Set up port forwarding or reverse or die 491 self.tcp_forward_or_die(self.grpc_port, self.grpc_port) 492 if self.grpc_root_server_port != -1: 493 self.tcp_forward_or_die(self.grpc_root_server_port, self.grpc_root_server_port) 494 self.tcp_reverse_or_die(self.signal_port, self.signal_port) 495 logging.info("Port forwarding done on device %s %s" % (self.label, self.serial_number)) 496 497 # Push test binaries 498 local_dir = os.path.join(get_gd_root(), "target") 499 500 def generate_dir_pair(local_dir, device_dir, filename): 501 return os.path.join(local_dir, filename), os.path.join(device_dir, filename) 502 503 # Do not override exist libraries shared by other binaries on the Android device to avoid corrupting the Android device 504 self.push_or_die(*generate_dir_pair(local_dir, self.DEVICE_BIN_DIR, "bluetooth_stack_with_facade")) 505 self.push_or_die( 506 *generate_dir_pair(local_dir, self.DEVICE_LIB_DIR, "android.hardware.bluetooth@1.0.so"), 507 overwrite_existing=False) 508 self.push_or_die( 509 *generate_dir_pair(local_dir, self.DEVICE_LIB_DIR, "android.hardware.bluetooth@1.1.so"), 510 overwrite_existing=False) 511 self.push_or_die( 512 *generate_dir_pair(local_dir, self.DEVICE_LIB_DIR, "libandroid_runtime_lazy.so"), overwrite_existing=False) 513 self.push_or_die(*generate_dir_pair(local_dir, self.DEVICE_LIB_DIR, "libbase.so"), overwrite_existing=False) 514 self.push_or_die( 515 *generate_dir_pair(local_dir, self.DEVICE_LIB_DIR, "libbinder_ndk.so"), overwrite_existing=False) 516 self.push_or_die(*generate_dir_pair(local_dir, self.DEVICE_LIB_DIR, "libbinder.so"), overwrite_existing=False) 517 self.push_or_die(*generate_dir_pair(local_dir, self.DEVICE_LIB_DIR, "libc++.so"), overwrite_existing=False) 518 # libclang_rt.asan-aarch64-android.so is only needed for ASAN build and is automatically included on device 519 #self.push_or_die( 520 # *generate_dir_pair(local_dir, self.DEVICE_LIB_DIR, "libclang_rt.asan-aarch64-android.so"), 521 # overwrite_existing=False) 522 self.push_or_die(*generate_dir_pair(local_dir, self.DEVICE_LIB_DIR, "libcrypto.so"), overwrite_existing=False) 523 self.push_or_die(*generate_dir_pair(local_dir, self.DEVICE_LIB_DIR, "libcutils.so"), overwrite_existing=False) 524 self.push_or_die( 525 *generate_dir_pair(local_dir, self.DEVICE_LIB_DIR, "libgrpc_wrap.so"), overwrite_existing=False) 526 self.push_or_die(*generate_dir_pair(local_dir, self.DEVICE_LIB_DIR, "libgrpc++_unsecure.so")) 527 self.push_or_die(*generate_dir_pair(local_dir, self.DEVICE_LIB_DIR, "libgrpc++.so")) 528 self.push_or_die(*generate_dir_pair(local_dir, self.DEVICE_LIB_DIR, "libhidlbase.so"), overwrite_existing=False) 529 self.push_or_die(*generate_dir_pair(local_dir, self.DEVICE_LIB_DIR, "liblog.so"), overwrite_existing=False) 530 self.push_or_die(*generate_dir_pair(local_dir, self.DEVICE_LIB_DIR, "liblzma.so"), overwrite_existing=False) 531 self.push_or_die(*generate_dir_pair(local_dir, self.DEVICE_LIB_DIR, "libprotobuf-cpp-full.so")) 532 self.push_or_die(*generate_dir_pair(local_dir, self.DEVICE_LIB_DIR, "libssl.so"), overwrite_existing=False) 533 self.push_or_die(*generate_dir_pair(local_dir, self.DEVICE_LIB_DIR, "libgrpc++.so")) 534 self.push_or_die(*generate_dir_pair(local_dir, self.DEVICE_LIB_DIR, "libstatslog_bt.so")) 535 self.push_or_die( 536 *generate_dir_pair(local_dir, self.DEVICE_LIB_DIR, "libunwindstack.so"), overwrite_existing=False) 537 self.push_or_die(*generate_dir_pair(local_dir, self.DEVICE_LIB_DIR, "libutils.so"), overwrite_existing=False) 538 self.push_or_die(*generate_dir_pair(local_dir, self.DEVICE_LIB_DIR, "libgrpc++.so")) 539 self.push_or_die(*generate_dir_pair(local_dir, self.DEVICE_LIB_DIR, "libz.so"), overwrite_existing=False) 540 541 logging.info("Binaries pushed to device %s %s" % (self.label, self.serial_number)) 542 543 try: 544 self.adb.shell("rm /data/misc/bluetooth/logs/btsnoop_hci.log") 545 except AdbError as error: 546 if ADB_FILE_NOT_EXIST_ERROR not in str(error): 547 logging.error("Error during setup: " + str(error)) 548 549 try: 550 self.adb.shell("rm /data/misc/bluetooth/logs/btsnooz_hci.log") 551 except AdbError as error: 552 if ADB_FILE_NOT_EXIST_ERROR not in str(error): 553 logging.error("Error during setup: " + str(error)) 554 555 try: 556 self.adb.shell("rm /data/misc/bluedroid/bt_config.conf") 557 except AdbError as error: 558 if ADB_FILE_NOT_EXIST_ERROR not in str(error): 559 logging.error("Error during setup: " + str(error)) 560 561 try: 562 self.adb.shell("rm /data/misc/bluedroid/bt_config.bak") 563 except AdbError as error: 564 if ADB_FILE_NOT_EXIST_ERROR not in str(error): 565 logging.error("Error during setup: " + str(error)) 566 logging.info("Old logs removed from device %s %s" % (self.label, self.serial_number)) 567 568 # Ensure Bluetooth is disabled 569 self.ensure_no_output(self.adb.shell("settings put global ble_scan_always_enabled 0")) 570 self.adb.shell("cmd bluetooth_manager disable") 571 device_bt_state = int(self.adb.shell("settings get global bluetooth_on")) 572 asserts.assert_equal(device_bt_state, 0, 573 "Failed to disable Bluetooth on device %s %s" % (self.label, self.serial_number)) 574 logging.info("Bluetooth disabled on device %s %s" % (self.label, self.serial_number)) 575 576 # Start logcat logging 577 self.logcat_output_path = os.path.join( 578 self.log_path_base, '%s_%s_%s_logcat_logs.txt' % (self.type_identifier, self.label, self.serial_number)) 579 self.logcat_cmd = ["adb", "-s", self.serial_number, "logcat", "-T", "1", "-v", "year", "-v", "uid"] 580 logging.debug("Running %s", " ".join(self.logcat_cmd)) 581 self.logcat_process = subprocess.Popen( 582 self.logcat_cmd, stdout=subprocess.PIPE, stderr=subprocess.STDOUT, universal_newlines=True) 583 asserts.assert_true(self.logcat_process, msg="Cannot start logcat_process at " + " ".join(self.logcat_cmd)) 584 asserts.assert_true( 585 is_subprocess_alive(self.logcat_process), 586 msg="logcat_process stopped immediately after running " + " ".join(self.logcat_cmd)) 587 self.logcat_logger = AsyncSubprocessLogger( 588 self.logcat_process, [self.logcat_output_path], 589 log_to_stdout=self.verbose_mode, 590 tag="%s_%s" % (self.label, self.serial_number), 591 color=self.terminal_color) 592 593 # Done run parent setup 594 logging.info("Done preparation for %s, starting backing process" % self.serial_number) 595 super().setup() 596 597 def teardown(self): 598 super().teardown() 599 stop_signal = signal.SIGINT 600 self.logcat_process.send_signal(stop_signal) 601 try: 602 return_code = self.logcat_process.wait(timeout=self.WAIT_FOR_DEVICE_SIGINT_TIMEOUT_SECONDS) 603 except subprocess.TimeoutExpired: 604 logging.error("[%s_%s] Failed to interrupt logcat process via SIGINT, sending SIGKILL" % 605 (self.label, self.serial_number)) 606 stop_signal = signal.SIGKILL 607 self.logcat_process.kill() 608 try: 609 return_code = self.logcat_process.wait(timeout=self.WAIT_SIGKILL_TIMEOUT_SECONDS) 610 except subprocess.TimeoutExpired: 611 logging.error("Failed to kill logcat_process %s %s" % (self.label, self.serial_number)) 612 return_code = -65536 613 if return_code not in [-stop_signal, 0]: 614 logging.error("logcat_process %s_%s stopped with code: %d" % (self.label, self.serial_number, return_code)) 615 self.logcat_logger.stop() 616 self.cleanup_port_forwarding() 617 self.pull_logs(self.log_path_base) 618 619 def pull_logs(self, base_dir): 620 try: 621 self.adb.pull([ 622 "/data/misc/bluetooth/logs/btsnoop_hci.log", 623 str(os.path.join(base_dir, "%s_btsnoop_hci.log" % self.label)) 624 ]) 625 except AdbError as error: 626 # Some tests have no snoop logs, and that's OK 627 if ADB_FILE_NOT_EXIST_ERROR not in str(error): 628 logging.error(PULL_LOG_FILE_ERROR_MSG_PREFIX + str(error)) 629 try: 630 self.adb.pull( 631 ["/data/misc/bluedroid/bt_config.conf", 632 str(os.path.join(base_dir, "%s_bt_config.conf" % self.label))]) 633 except AdbError as error: 634 # Some tests have no config file, and that's OK 635 if ADB_FILE_NOT_EXIST_ERROR not in str(error): 636 logging.error(PULL_LOG_FILE_ERROR_MSG_PREFIX + str(error)) 637 try: 638 self.adb.pull( 639 ["/data/misc/bluedroid/bt_config.bak", 640 str(os.path.join(base_dir, "%s_bt_config.bak" % self.label))]) 641 except AdbError as error: 642 # Some tests have no config.bak file, and that's OK 643 if ADB_FILE_NOT_EXIST_ERROR not in str(error): 644 logging.error(PULL_LOG_FILE_ERROR_MSG_PREFIX + str(error)) 645 646 def cleanup_port_forwarding(self): 647 try: 648 self.adb.remove_tcp_forward(self.grpc_port) 649 except AdbError as error: 650 msg = PORT_FORWARDING_ERROR_MSG_PREFIX + str(error) 651 if "not found" in msg: 652 logging.debug(msg) 653 else: 654 logging.error(msg) 655 656 try: 657 if self.grpc_root_server_port != -1: 658 self.adb.remove_tcp_forward(self.grpc_root_server_port) 659 except AdbError as error: 660 msg = PORT_FORWARDING_ERROR_MSG_PREFIX + str(error) 661 if "not found" in msg: 662 logging.debug(msg) 663 else: 664 logging.error(msg) 665 666 try: 667 self.adb.reverse(["--remove", "tcp:%d" % self.signal_port]) 668 except AdbError as error: 669 msg = PORT_FORWARDING_ERROR_MSG_PREFIX + str(error) 670 if "not found" in msg: 671 logging.debug(msg) 672 else: 673 logging.error(msg) 674 675 @staticmethod 676 def ensure_no_output(result): 677 """ 678 Ensure a command has not output 679 """ 680 asserts.assert_true( 681 result is None or len(result) == 0, msg="command returned something when it shouldn't: %s" % result) 682 683 def sync_device_time(self): 684 self.adb.shell("settings put global auto_time 0") 685 self.adb.shell("settings put global auto_time_zone 0") 686 device_tz = self.adb.shell("date +%z").decode(UTF_8).rstrip() 687 asserts.assert_true(device_tz, "date +%z must return device timezone, " 688 "but returned {} instead".format(device_tz)) 689 host_tz = time.strftime("%z") 690 if device_tz != host_tz: 691 target_timezone = utils.get_timezone_olson_id() 692 logging.debug("Device timezone %s does not match host timezone %s, " 693 "syncing them by setting timezone to %s" % (device_tz, host_tz, target_timezone)) 694 self.adb.shell("setprop persist.sys.timezone %s" % target_timezone) 695 self.reboot() 696 self.adb.remount() 697 device_tz = self.adb.shell("date +%z").decode(UTF_8).rstrip() 698 asserts.assert_equal( 699 host_tz, device_tz, "Device timezone %s still does not match host " 700 "timezone %s after reset" % (device_tz, host_tz)) 701 self.adb.shell("date %s" % time.strftime("%m%d%H%M%Y.%S")) 702 datetime_format = "%Y-%m-%dT%H:%M:%S%z" 703 try: 704 device_time = datetime.strptime( 705 self.adb.shell("date +'%s'" % datetime_format).decode(UTF_8).rstrip(), datetime_format) 706 except ValueError: 707 asserts.fail("Failed to get time after sync") 708 return 709 # Include ADB delay that might be longer in SSH environment 710 max_delta_seconds = 3 711 host_time = datetime.now(tz=device_time.tzinfo) 712 asserts.assert_almost_equal( 713 (device_time - host_time).total_seconds(), 714 0, 715 msg="Device time %s and host time %s off by >%dms after sync" % 716 (device_time.isoformat(), host_time.isoformat(), int(max_delta_seconds * 1000)), 717 delta=max_delta_seconds) 718 719 def push_or_die(self, src_file_path, dst_file_path, push_timeout=300, overwrite_existing=True): 720 """Pushes a file to the Android device 721 722 Args: 723 src_file_path: The path to the file to install. 724 dst_file_path: The destination of the file. 725 push_timeout: How long to wait for the push to finish in seconds 726 """ 727 if not overwrite_existing and self.adb.path_exists(dst_file_path): 728 logging.debug("Skip pushing {} to {} as it already exists on device".format(src_file_path, dst_file_path)) 729 return 730 out = self.adb.push([src_file_path, dst_file_path], timeout=push_timeout).decode(UTF_8).rstrip() 731 if 'error' in out: 732 asserts.fail('Unable to push file %s to %s due to %s' % (src_file_path, dst_file_path, out)) 733 734 def tcp_forward_or_die(self, host_port, device_port, num_retry=1): 735 """ 736 Forward a TCP port from host to device or fail 737 :param host_port: host port, int, 0 for adb to assign one 738 :param device_port: device port, int 739 :param num_retry: number of times to reboot and retry this before dying 740 :return: host port int 741 """ 742 error_or_port = self.adb.tcp_forward(host_port, device_port) 743 if not error_or_port: 744 logging.debug("host port %d was already forwarded" % host_port) 745 return host_port 746 if not isinstance(error_or_port, int): 747 if num_retry > 0: 748 # If requested, reboot an retry 749 num_retry -= 1 750 logging.warning( 751 "[%s] Failed to TCP forward host port %d to " 752 "device port %d, num_retries left is %d" % (self.label, host_port, device_port, num_retry)) 753 self.reboot() 754 self.adb.remount() 755 return self.tcp_forward_or_die(host_port, device_port, num_retry=num_retry) 756 asserts.fail( 757 'Unable to forward host port %d to device port %d, error %s' % (host_port, device_port, error_or_port)) 758 return error_or_port 759 760 def tcp_reverse_or_die(self, device_port, host_port, num_retry=1): 761 """ 762 Forward a TCP port from device to host or fail 763 :param device_port: device port, int, 0 for adb to assign one 764 :param host_port: host port, int 765 :param num_retry: number of times to reboot and retry this before dying 766 :return: device port int 767 """ 768 error_or_port = self.adb.reverse(["tcp:%d" % device_port, "tcp:%d" % host_port]) 769 if not error_or_port: 770 logging.debug("device port %d was already reversed" % device_port) 771 return device_port 772 try: 773 error_or_port = int(error_or_port) 774 except ValueError: 775 if num_retry > 0: 776 # If requested, reboot an retry 777 num_retry -= 1 778 logging.warning( 779 "[%s] Failed to TCP reverse device port %d to " 780 "host port %d, num_retries left is %d" % (self.label, device_port, host_port, num_retry)) 781 self.reboot() 782 self.adb.remount() 783 return self.tcp_reverse_or_die(device_port, host_port, num_retry=num_retry) 784 asserts.fail( 785 'Unable to reverse device port %d to host port %d, error %s' % (device_port, host_port, error_or_port)) 786 return error_or_port 787 788 def ensure_verity_disabled(self): 789 """Ensures that verity is enabled. 790 791 If verity is not enabled, this call will reboot the phone. Note that 792 this only works on debuggable builds. 793 """ 794 logging.debug("Disabling verity and remount for %s", self.serial_number) 795 # The below properties will only exist if verity has been enabled. 796 system_verity = self.adb.getprop('partition.system.verified') 797 vendor_verity = self.adb.getprop('partition.vendor.verified') 798 if system_verity or vendor_verity: 799 self.adb.disable_verity() 800 self.reboot() 801 self.adb.remount() 802 self.adb.wait_for_device(timeout=self.WAIT_FOR_DEVICE_TIMEOUT_SECONDS) 803 804 def reboot(self, timeout_minutes=15.0): 805 """Reboots the device. 806 807 Reboot the device, wait for device to complete booting. 808 """ 809 logging.debug("Rebooting %s", self.serial_number) 810 self.adb.reboot() 811 812 timeout_start = time.time() 813 timeout = timeout_minutes * 60 814 # Android sometimes return early after `adb reboot` is called. This 815 # means subsequent calls may make it to the device before the reboot 816 # goes through, return false positives for getprops such as 817 # sys.boot_completed. 818 while time.time() < timeout_start + timeout: 819 try: 820 logging.debug("waiting for device %s to turn off", self.serial_number) 821 self.adb.get_state() 822 logging.debug("device %s not turned off yet", self.serial_number) 823 time.sleep(.1) 824 except AdbError: 825 # get_state will raise an error if the device is not found. We 826 # want the device to be missing to prove the device has kicked 827 # off the reboot. 828 logging.debug("device %s is turned off, waiting for it to boot", self.serial_number) 829 break 830 minutes_left = timeout_minutes - (time.time() - timeout_start) / 60.0 831 self.wait_for_boot_completion(timeout_minutes=minutes_left) 832 asserts.assert_true(self.adb.ensure_root(), "device %s cannot run as root after reboot" % self.serial_number) 833 834 def wait_for_boot_completion(self, timeout_minutes=15.0): 835 """ 836 Waits for Android framework to broadcast ACTION_BOOT_COMPLETED. 837 :param timeout_minutes: number of minutes to wait 838 """ 839 timeout_start = time.time() 840 timeout = timeout_minutes * 60 841 842 self.adb.wait_for_device(timeout=self.WAIT_FOR_DEVICE_TIMEOUT_SECONDS) 843 while time.time() < timeout_start + timeout: 844 try: 845 completed = self.adb.getprop("sys.boot_completed") 846 if completed == '1': 847 return 848 except AdbError: 849 # adb shell calls may fail during certain period of booting 850 # process, which is normal. Ignoring these errors. 851 pass 852 time.sleep(5) 853 asserts.fail(msg='Device %s booting process timed out.' % self.serial_number) 854 855 def gracefully_stop_backing_process(self): 856 """ 857 Gracefully stops backing process 858 :return: expected backing process exit code on success, 0 on error 859 """ 860 backing_process_pid = None 861 # Since we do not know which segment of self.cmd is the command running 862 # on the Android device. We have to iterate with trial and error. 863 cmd = self.cmd 864 if len(self.cmd) >= 5: 865 # skip adb -s serial shell to speed up the search 866 # we don't know if any environment variables are set up before the 867 # actual command and hence has to try from the 4th argument 868 cmd = self.cmd[4:] + self.cmd[:4] 869 for segment in cmd: 870 try: 871 # pgrep only takes 16 bytes including null terminator 872 # -f cannot be used because that include the full command args 873 current_cmd = pathlib.Path(segment).stem[:15] 874 # -x matches whole command, cannot avoid as short segment may partially match 875 # -n returnes the newest command matched 876 backing_process_pid = int(self.adb.shell("pgrep -n -x {}".format(current_cmd))) 877 logging.debug("Found backing process name on Android as {}, pid is {}".format( 878 segment, backing_process_pid)) 879 except (AdbError, ValueError) as e: 880 logging.debug("Failed to run pgrep {}".format(e)) 881 if backing_process_pid is not None: 882 break 883 if backing_process_pid is None: 884 logging.warning("Failed to get pid for cmd {}".format(self.cmd)) 885 try: 886 logging.debug(self.adb.shell("ps -A | grep bluetooth")) 887 except AdbError: 888 pass 889 return 0 890 stop_signal = signal.SIGINT 891 self.adb.shell("kill -{} {}".format(stop_signal, backing_process_pid)) 892 logging.debug("Sent SIGINT to backing process at pid {}".format(backing_process_pid)) 893 stop_signal = -self.ADB_ABORT_EXIT_CODE 894 return stop_signal 895