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