1#!/usr/bin/env python3 2# 3# Copyright 2021 - Google 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 datetime import datetime 18import os 19import re 20import shutil 21import time 22 23from acts import utils 24from acts.libs.proc import job 25from acts.controllers.android_device import DEFAULT_QXDM_LOG_PATH 26from acts.controllers.android_device import DEFAULT_SDM_LOG_PATH 27from acts.libs.utils.multithread import run_multithread_func 28from acts.utils import get_current_epoch_time 29from acts.utils import start_standing_subprocess 30 31 32_LS_MASK_NAME = "Lassen default + TCP" 33 34_LS_ENABLE_LOG_SHELL = f'\ 35am broadcast -n com.android.pixellogger/.receiver.AlwaysOnLoggingReceiver \ 36-a com.android.pixellogger.service.logging.LoggingService.ACTION_CONFIGURE_ALWAYS_ON_LOGGING \ 37-e intent_key_enable "true" -e intent_key_config "{_LS_MASK_NAME}" \ 38--ei intent_key_max_log_size_mb 100 --ei intent_key_max_number_of_files 100' 39_LS_DISABLE_LOG_SHELL = '\ 40am broadcast -n com.android.pixellogger/.receiver.AlwaysOnLoggingReceiver \ 41-a com.android.pixellogger.service.logging.LoggingService.ACTION_CONFIGURE_ALWAYS_ON_LOGGING \ 42-e intent_key_enable "false"' 43_LS_GET_LOG_STATUS_SHELL = 'getprop vendor.sys.modem.logging.status' 44_LS_START_LS_TIMEOUT_SECS = 30 45_LS_STOP_LS_TIMEOUT_SECS = 30 46 47def check_if_tensor_platform(ad): 48 """Check if current platform belongs to the Tensor platform 49 50 Args: 51 ad: Android object 52 53 Returns: 54 True if current platform belongs to the Tensor platform. Otherwise False. 55 """ 56 result = ad.adb.getprop("ro.boot.hardware.platform") 57 if re.search('^gs', result, re.I): 58 return True 59 return False 60 61 62def start_pixellogger_always_on_logging(ad): 63 """Start always-on logging of Pixellogger for both Qualcomm and Tensor 64 platform. 65 66 Args: 67 ad: Android object 68 69 Returns: 70 True if the property is set correctly. Otherwise False. 71 """ 72 setattr(ad, 'enable_always_on_modem_logger', True) 73 if check_if_tensor_platform(ad): 74 key = "persist.vendor.sys.modem.logging.enable" 75 else: 76 key = "persist.vendor.sys.modem.diag.mdlog" 77 78 if ad.adb.getprop(key) == "false": 79 ad.adb.shell("setprop persist.vendor.sys.modem.logging.enable true") 80 time.sleep(5) 81 if ad.adb.getprop(key) == "true": 82 return True 83 else: 84 return False 85 else: 86 return True 87 88 89def start_dsp_logger(ad, p21 = False, retry = 3): 90 """Start DSP logging for P21/P22 devices. 91 92 Args: 93 ad: Android object. 94 p21: True if p21 device, False otherwise. 95 retry: times of retry to enable DSP logger. 96 97 Returns: 98 True if DSP logger is enabled correctly. Otherwise False. 99 """ 100 registry_name = "!LTEL1.HAL.DSP\\ clkgating\\ Enb/Dis" if p21 else "NASU.LCPU.LOG.SWITCH" 101 nv_value = "00" if p21 else "02" 102 103 def _is_dsp_enabled(ad): 104 return nv_value in ad.adb.shell('am instrument -w -e request ' 105 f'at+googgetnv=\\"{registry_name}\\" -e response wait ' 106 'com.google.mdstest/com.google.mdstest.instrument.' 107 'ModemATCommandInstrumentation') 108 109 for _ in range(retry): 110 if not _is_dsp_enabled(ad): 111 ad.adb.shell('am instrument -w -e request at+googsetnv=\\"' 112 f'{registry_name}\\",0,\\"{nv_value}\\" -e response wait ' 113 'com.google.mdstest/com.google.mdstest.instrument.' 114 'ModemATCommandInstrumentation') 115 time.sleep(3) 116 else: 117 ad.log.info("DSP logger is enabled, reboot to start.") 118 ad.reboot() 119 return True 120 ad.log.warning("DSP logger enable failed") 121 return False 122 123 124def is_sdm_logger_running(ad): 125 """Queries the status of SDM logger. 126 127 Returns: 128 True if the SDM logger is runninng. 129 """ 130 return "true" in ad.adb.shell(_LS_GET_LOG_STATUS_SHELL, ignore_status=True) 131 132 133def start_sdm_logger(ad): 134 """Start SDM logger.""" 135 if not getattr(ad, "sdm_log", True): return 136 137 # Delete existing SDM logs which were created 15 mins prior 138 ad.sdm_log_path = DEFAULT_SDM_LOG_PATH 139 file_count = ad.adb.shell( 140 f"find {ad.sdm_log_path} -type f -iname sbuff_[0-9]*.sdm* | wc -l") 141 if int(file_count) > 3: 142 seconds = 15 * 60 143 # Remove sdm logs modified more than specified seconds ago 144 ad.adb.shell( 145 f"find {ad.sdm_log_path} -type f -iname sbuff_[0-9]*.sdm* " 146 f"-not -mtime -{seconds}s -delete") 147 148 if not is_sdm_logger_running(ad): 149 ad.log.debug("starting sdm logger...") 150 ad.adb.shell(_LS_ENABLE_LOG_SHELL, ignore_status=True) 151 152 timeout = time.monotonic() + _LS_START_LS_TIMEOUT_SECS 153 while time.monotonic() < timeout: 154 time.sleep(1) 155 if is_sdm_logger_running(ad): 156 ad.log.info('SDM logger has started') 157 break 158 else: 159 raise RuntimeError( 160 'Timed out while waiting for SDM logger to start.') 161 162 163def stop_sdm_logger(ad): 164 """Stop SDM logger.""" 165 if is_sdm_logger_running(ad): 166 ad.log.info("Stopping SDM logger...") 167 ad.adb.shell(_LS_DISABLE_LOG_SHELL, ignore_status=True) 168 169 timeout = time.monotonic() + _LS_STOP_LS_TIMEOUT_SECS 170 while time.monotonic() < timeout: 171 time.sleep(1) 172 if not is_sdm_logger_running(ad): 173 ad.log.info('SDM logger has stoped') 174 break 175 else: 176 raise RuntimeError( 177 'Timed out while waiting for SDM logger to stop.') 178 179 180def start_sdm_loggers(log, ads): 181 tasks = [(start_sdm_logger, [ad]) for ad in ads 182 if getattr(ad, "sdm_log", True)] 183 if tasks: run_multithread_func(log, tasks) 184 185 186def stop_sdm_loggers(log, ads): 187 tasks = [(stop_sdm_logger, [ad]) for ad in ads] 188 run_multithread_func(log, tasks) 189 190 191def find_qxdm_log_mask(ad, mask="default.cfg"): 192 """Find QXDM logger mask.""" 193 if "/" not in mask: 194 # Call nexuslogger to generate log mask 195 start_nexuslogger(ad) 196 # Find the log mask path 197 for path in (DEFAULT_QXDM_LOG_PATH, "/data/diag_logs", 198 "/vendor/etc/mdlog/", "/vendor/etc/modem/"): 199 out = ad.adb.shell( 200 "find %s -type f -iname %s" % (path, mask), ignore_status=True) 201 if out and "No such" not in out and "Permission denied" not in out: 202 if path.startswith("/vendor/"): 203 setattr(ad, "qxdm_log_path", DEFAULT_QXDM_LOG_PATH) 204 else: 205 setattr(ad, "qxdm_log_path", path) 206 return out.split("\n")[0] 207 for mask_file in ("/vendor/etc/mdlog/", "/vendor/etc/modem/"): 208 if mask in ad.adb.shell("ls %s" % mask_file, ignore_status=True): 209 setattr(ad, "qxdm_log_path", DEFAULT_QXDM_LOG_PATH) 210 return "%s/%s" % (mask_file, mask) 211 else: 212 out = ad.adb.shell("ls %s" % mask, ignore_status=True) 213 if out and "No such" not in out: 214 qxdm_log_path, cfg_name = os.path.split(mask) 215 setattr(ad, "qxdm_log_path", qxdm_log_path) 216 return mask 217 ad.log.warning("Could NOT find QXDM logger mask path for %s", mask) 218 219 220def set_qxdm_logger_command(ad, mask=None): 221 """Set QXDM logger always on. 222 223 Args: 224 ad: android device object. 225 226 """ 227 ## Neet to check if log mask will be generated without starting nexus logger 228 masks = [] 229 mask_path = None 230 if mask: 231 masks = [mask] 232 masks.extend(["QC_Default.cfg", "default.cfg"]) 233 for mask in masks: 234 mask_path = find_qxdm_log_mask(ad, mask) 235 if mask_path: break 236 if not mask_path: 237 ad.log.error("Cannot find QXDM mask %s", mask) 238 ad.qxdm_logger_command = None 239 return False 240 else: 241 ad.log.info("Use QXDM log mask %s", mask_path) 242 ad.log.debug("qxdm_log_path = %s", ad.qxdm_log_path) 243 output_path = os.path.join(ad.qxdm_log_path, "logs") 244 ad.qxdm_logger_command = ("diag_mdlog -f %s -o %s -s 90 -c" % 245 (mask_path, output_path)) 246 return True 247 248 249def stop_qxdm_logger(ad): 250 """Stop QXDM logger.""" 251 for cmd in ("diag_mdlog -k", "killall diag_mdlog"): 252 output = ad.adb.shell("ps -ef | grep mdlog") or "" 253 if "diag_mdlog" not in output: 254 break 255 ad.log.debug("Kill the existing qxdm process") 256 ad.adb.shell(cmd, ignore_status=True) 257 time.sleep(5) 258 259 260def start_qxdm_logger(ad, begin_time=None): 261 """Start QXDM logger.""" 262 if not getattr(ad, "qxdm_log", True): return 263 # Delete existing QXDM logs 5 minutes earlier than the begin_time 264 current_time = get_current_epoch_time() 265 if getattr(ad, "qxdm_log_path", None): 266 seconds = None 267 file_count = ad.adb.shell( 268 "find %s -type f -iname *.qmdl | wc -l" % ad.qxdm_log_path) 269 if int(file_count) > 3: 270 if begin_time: 271 # if begin_time specified, delete old qxdm logs modified 272 # 10 minutes before begin time 273 seconds = int((current_time - begin_time) / 1000.0) + 10 * 60 274 else: 275 # if begin_time is not specified, delete old qxdm logs modified 276 # 15 minutes before current time 277 seconds = 15 * 60 278 if seconds: 279 # Remove qxdm logs modified more than specified seconds ago 280 ad.adb.shell( 281 "find %s -type f -iname *.qmdl -not -mtime -%ss -delete" % 282 (ad.qxdm_log_path, seconds)) 283 ad.adb.shell( 284 "find %s -type f -iname *.xml -not -mtime -%ss -delete" % 285 (ad.qxdm_log_path, seconds)) 286 if getattr(ad, "qxdm_logger_command", None): 287 output = ad.adb.shell("ps -ef | grep mdlog") or "" 288 if ad.qxdm_logger_command not in output: 289 ad.log.debug("QXDM logging command %s is not running", 290 ad.qxdm_logger_command) 291 if "diag_mdlog" in output: 292 # Kill the existing non-matching diag_mdlog process 293 # Only one diag_mdlog process can be run 294 stop_qxdm_logger(ad) 295 ad.log.info("Start QXDM logger") 296 ad.adb.shell_nb(ad.qxdm_logger_command) 297 time.sleep(10) 298 else: 299 run_time = check_qxdm_logger_run_time(ad) 300 if run_time < 600: 301 # the last diag_mdlog started within 10 minutes ago 302 # no need to restart 303 return True 304 if ad.search_logcat( 305 "Diag_Lib: diag: In delete_log", 306 begin_time=current_time - 307 run_time) or not ad.get_file_names( 308 ad.qxdm_log_path, 309 begin_time=current_time - 600000, 310 match_string="*.qmdl"): 311 # diag_mdlog starts deleting files or no qmdl logs were 312 # modified in the past 10 minutes 313 ad.log.debug("Quit existing diag_mdlog and start a new one") 314 stop_qxdm_logger(ad) 315 ad.adb.shell_nb(ad.qxdm_logger_command) 316 time.sleep(10) 317 return True 318 319 320def disable_qxdm_logger(ad): 321 for prop in ("persist.sys.modem.diag.mdlog", 322 "persist.vendor.sys.modem.diag.mdlog", 323 "vendor.sys.modem.diag.mdlog_on"): 324 if ad.adb.getprop(prop): 325 ad.adb.shell("setprop %s false" % prop, ignore_status=True) 326 for apk in ("com.android.nexuslogger", "com.android.pixellogger"): 327 if ad.is_apk_installed(apk) and ad.is_apk_running(apk): 328 ad.force_stop_apk(apk) 329 stop_qxdm_logger(ad) 330 return True 331 332 333def check_qxdm_logger_run_time(ad): 334 output = ad.adb.shell("ps -eo etime,cmd | grep diag_mdlog") 335 result = re.search(r"(\d+):(\d+):(\d+) diag_mdlog", output) 336 if result: 337 return int(result.group(1)) * 60 * 60 + int( 338 result.group(2)) * 60 + int(result.group(3)) 339 else: 340 result = re.search(r"(\d+):(\d+) diag_mdlog", output) 341 if result: 342 return int(result.group(1)) * 60 + int(result.group(2)) 343 else: 344 return 0 345 346 347def start_qxdm_loggers(log, ads, begin_time=None): 348 tasks = [(start_qxdm_logger, [ad, begin_time]) for ad in ads 349 if getattr(ad, "qxdm_log", True)] 350 if tasks: run_multithread_func(log, tasks) 351 352 353def stop_qxdm_loggers(log, ads): 354 tasks = [(stop_qxdm_logger, [ad]) for ad in ads] 355 run_multithread_func(log, tasks) 356 357 358def check_qxdm_logger_mask(ad, mask_file="QC_Default.cfg"): 359 """Check if QXDM logger always on is set. 360 361 Args: 362 ad: android device object. 363 364 """ 365 output = ad.adb.shell( 366 "ls /data/vendor/radio/diag_logs/", ignore_status=True) 367 if not output or "No such" in output: 368 return True 369 if mask_file not in ad.adb.shell( 370 "cat /data/vendor/radio/diag_logs/diag.conf", ignore_status=True): 371 return False 372 return True 373 374 375def start_nexuslogger(ad): 376 """Start Nexus/Pixel Logger Apk.""" 377 qxdm_logger_apk = None 378 for apk, activity in (("com.android.nexuslogger", ".MainActivity"), 379 ("com.android.pixellogger", 380 ".ui.main.MainActivity")): 381 if ad.is_apk_installed(apk): 382 qxdm_logger_apk = apk 383 break 384 if not qxdm_logger_apk: return 385 if ad.is_apk_running(qxdm_logger_apk): 386 if "granted=true" in ad.adb.shell( 387 "dumpsys package %s | grep READ_EXTERN" % qxdm_logger_apk): 388 return True 389 else: 390 ad.log.info("Kill %s" % qxdm_logger_apk) 391 ad.force_stop_apk(qxdm_logger_apk) 392 time.sleep(5) 393 ad.adb.shell("pm grant %s android.permission.READ_EXTERNAL_STORAGE" % (qxdm_logger_apk)) 394 time.sleep(2) 395 for i in range(3): 396 ad.unlock_screen() 397 ad.log.info("Start %s Attempt %d" % (qxdm_logger_apk, i + 1)) 398 ad.adb.shell("am start -n %s/%s" % (qxdm_logger_apk, activity)) 399 time.sleep(5) 400 if ad.is_apk_running(qxdm_logger_apk): 401 ad.send_keycode("HOME") 402 return True 403 return False 404 405 406def start_tcpdumps(ads, 407 test_name="", 408 begin_time=None, 409 interface="any", 410 mask="all"): 411 for ad in ads: 412 try: 413 start_adb_tcpdump( 414 ad, 415 test_name=test_name, 416 begin_time=begin_time, 417 interface=interface, 418 mask=mask) 419 except Exception as e: 420 ad.log.warning("Fail to start tcpdump due to %s", e) 421 422 423def start_adb_tcpdump(ad, 424 test_name="", 425 begin_time=None, 426 interface="any", 427 mask="all"): 428 """Start tcpdump on any iface 429 430 Args: 431 ad: android device object. 432 test_name: tcpdump file name will have this 433 434 """ 435 out = ad.adb.shell("ls -l /data/local/tmp/tcpdump/", ignore_status=True) 436 if "No such file" in out or not out: 437 ad.adb.shell("mkdir /data/local/tmp/tcpdump") 438 else: 439 ad.adb.shell( 440 "find /data/local/tmp/tcpdump -type f -not -mtime -1800s -delete", 441 ignore_status=True) 442 ad.adb.shell( 443 "find /data/local/tmp/tcpdump -type f -size +5G -delete", 444 ignore_status=True) 445 446 if not begin_time: 447 begin_time = get_current_epoch_time() 448 449 out = ad.adb.shell( 450 'ifconfig | grep -v -E "r_|-rmnet" | grep -E "lan|data"', 451 ignore_status=True, 452 timeout=180) 453 intfs = re.findall(r"(\S+).*", out) 454 if interface and interface not in ("any", "all"): 455 if interface not in intfs: return 456 intfs = [interface] 457 458 out = ad.adb.shell("ps -ef | grep tcpdump") 459 cmds = [] 460 for intf in intfs: 461 if intf in out: 462 ad.log.info("tcpdump on interface %s is already running", intf) 463 continue 464 else: 465 log_file_name = "/data/local/tmp/tcpdump/tcpdump_%s_%s_%s_%s.pcap" \ 466 % (ad.serial, intf, test_name, begin_time) 467 if mask == "ims": 468 cmds.append( 469 "adb -s %s shell tcpdump -i %s -s0 -n -p udp port 500 or " 470 "udp port 4500 -w %s" % (ad.serial, intf, log_file_name)) 471 else: 472 cmds.append("adb -s %s shell tcpdump -i %s -s0 -w %s" % 473 (ad.serial, intf, log_file_name)) 474 if "Qualcomm" not in str(ad.adb.shell("getprop gsm.version.ril-impl")): 475 log_file_name = ("/data/local/tmp/tcpdump/tcpdump_%s_any_%s_%s.pcap" 476 % (ad.serial, test_name, begin_time)) 477 cmds.append("adb -s %s shell nohup tcpdump -i any -s0 -w %s" % 478 (ad.serial, log_file_name)) 479 for cmd in cmds: 480 ad.log.info(cmd) 481 try: 482 start_standing_subprocess(cmd, 10) 483 except Exception as e: 484 ad.log.error(e) 485 if cmds: 486 time.sleep(5) 487 488 489def stop_tcpdumps(ads): 490 for ad in ads: 491 stop_adb_tcpdump(ad) 492 493 494def stop_adb_tcpdump(ad, interface="any"): 495 """Stops tcpdump on any iface 496 Pulls the tcpdump file in the tcpdump dir 497 498 Args: 499 ad: android device object. 500 501 """ 502 if interface == "any": 503 try: 504 ad.adb.shell("killall -9 tcpdump", ignore_status=True) 505 except Exception as e: 506 ad.log.error("Killing tcpdump with exception %s", e) 507 else: 508 out = ad.adb.shell("ps -ef | grep tcpdump | grep %s" % interface) 509 if "tcpdump -i" in out: 510 pids = re.findall(r"\S+\s+(\d+).*tcpdump -i", out) 511 for pid in pids: 512 ad.adb.shell("kill -9 %s" % pid) 513 ad.adb.shell( 514 "find /data/local/tmp/tcpdump -type f -not -mtime -1800s -delete", 515 ignore_status=True) 516 517 518def get_tcpdump_log(ad, test_name="", begin_time=None): 519 """Stops tcpdump on any iface 520 Pulls the tcpdump file in the tcpdump dir 521 Zips all tcpdump files 522 523 Args: 524 ad: android device object. 525 test_name: test case name 526 begin_time: test begin time 527 """ 528 logs = ad.get_file_names("/data/local/tmp/tcpdump", begin_time=begin_time) 529 if logs: 530 ad.log.info("Pulling tcpdumps %s", logs) 531 log_path = os.path.join( 532 ad.device_log_path, "TCPDUMP_%s_%s" % (ad.model, ad.serial)) 533 os.makedirs(log_path, exist_ok=True) 534 ad.pull_files(logs, log_path) 535 shutil.make_archive(log_path, "zip", log_path) 536 shutil.rmtree(log_path) 537 return True 538 539 540def wait_for_log(ad, pattern, begin_time=None, end_time=None, max_wait_time=120): 541 """Wait for logcat logs matching given pattern. This function searches in 542 logcat for strings matching given pattern by using search_logcat per second 543 until max_wait_time reaches. 544 545 Args: 546 ad: android device object 547 pattern: pattern to be searched in grep format 548 begin_time: only the lines in logcat with time stamps later than 549 begin_time will be searched. 550 end_time: only the lines in logcat with time stamps earlier than 551 end_time will be searched. 552 max_wait_time: timeout of this function 553 554 Returns: 555 All matched lines will be returned. If no line matches the given pattern 556 None will be returned. 557 """ 558 start_time = datetime.now() 559 while True: 560 ad.log.info( 561 '====== Searching logcat for "%s" ====== ', pattern) 562 res = ad.search_logcat( 563 pattern, begin_time=begin_time, end_time=end_time) 564 if res: 565 return res 566 time.sleep(1) 567 stop_time = datetime.now() 568 passed_time = (stop_time - start_time).total_seconds() 569 if passed_time > max_wait_time: 570 return 571 572 573def extract_test_log(log, src_file, dst_file, test_tag): 574 os.makedirs(os.path.dirname(dst_file), exist_ok=True) 575 cmd = "grep -n '%s' %s" % (test_tag, src_file) 576 result = job.run(cmd, ignore_status=True) 577 if not result.stdout or result.exit_status == 1: 578 log.warning("Command %s returns %s", cmd, result) 579 return 580 line_nums = re.findall(r"(\d+).*", result.stdout) 581 if line_nums: 582 begin_line = int(line_nums[0]) 583 end_line = int(line_nums[-1]) 584 if end_line - begin_line <= 5: 585 result = job.run("wc -l < %s" % src_file) 586 if result.stdout: 587 end_line = int(result.stdout) 588 log.info("Extract %s from line %s to line %s to %s", src_file, 589 begin_line, end_line, dst_file) 590 job.run("awk 'NR >= %s && NR <= %s' %s > %s" % (begin_line, end_line, 591 src_file, dst_file)) 592 593 594def log_screen_shot(ad, test_name=""): 595 file_name = "/sdcard/Pictures/screencap" 596 if test_name: 597 file_name = "%s_%s" % (file_name, test_name) 598 file_name = "%s_%s.png" % (file_name, utils.get_current_epoch_time()) 599 try: 600 ad.adb.shell("screencap -p %s" % file_name) 601 except: 602 ad.log.error("Fail to log screen shot to %s", file_name) 603 604 605def get_screen_shot_log(ad, test_name="", begin_time=None): 606 logs = ad.get_file_names("/sdcard/Pictures", begin_time=begin_time) 607 if logs: 608 ad.log.info("Pulling %s", logs) 609 log_path = os.path.join(ad.device_log_path, "Screenshot_%s" % ad.serial) 610 os.makedirs(log_path, exist_ok=True) 611 ad.pull_files(logs, log_path) 612 ad.adb.shell("rm -rf /sdcard/Pictures/screencap_*", ignore_status=True) 613 614 615def get_screen_shot_logs(ads, test_name="", begin_time=None): 616 for ad in ads: 617 get_screen_shot_log(ad, test_name=test_name, begin_time=begin_time)