| # Copyright 2020 Google LLC |
| # |
| # Licensed under the Apache License, Version 2.0 (the "License"); |
| # you may not use this file except in compliance with the License. |
| # You may obtain a copy of the License at |
| # |
| # http://www.apache.org/licenses/LICENSE-2.0 |
| # |
| # Unless required by applicable law or agreed to in writing, software |
| # distributed under the License is distributed on an "AS IS" BASIS, |
| # WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. |
| # See the License for the specific language governing permissions and |
| # limitations under the License. |
| |
| """Stress test utility for repeating actions repeatedly on android devices. |
| |
| Configures multiple devices to simultaneously run through the same set of |
| actions over and over, while keeping logs from various sources. Primarily |
| designed for playing audio to the devices and scanning their log output for |
| events, while running other adb commands in between. |
| """ |
| from __future__ import absolute_import |
| from __future__ import division |
| from __future__ import print_function |
| |
| import datetime |
| from email import encoders |
| from email.mime import text |
| import email.mime.base as base |
| import email.mime.multipart as multipart |
| import logging |
| import mimetypes |
| import os |
| import platform |
| import re |
| import shlex |
| import signal |
| import smtplib |
| import socket |
| import subprocess |
| import sys |
| import tempfile |
| import threading |
| import time |
| import uuid |
| import wave |
| from absl import app |
| from absl import flags |
| import pexpect |
| import queue |
| import stress_test_common |
| import stress_test_pb2 |
| from google.protobuf import text_format |
| |
| _SUMMARY_LINES = "-" * 73 |
| |
| if sys.platform.startswith("win"): |
| pexpect = None |
| |
| _SUMMARY_COLUMNS = ( |
| "| Event Type | Event Count | Consecutive no event |") |
| _SUMMARY_COL_FORMATT = "|%-25.25s|% 22d|% 22d|" |
| |
| FLAGS = flags.FLAGS |
| flags.DEFINE_string("notification_address", "", |
| "Email address where to send notification events. Will " |
| "default to $USER@google.com if not provided. No emails " |
| "will be sent if suppress_notification_emails is True.") |
| flags.DEFINE_bool("suppress_notification_emails", False, |
| "Prevents emails from being sent as notifications if True.") |
| flags.DEFINE_string("test_name", None, |
| "Name of stress test to run. For example, if you set this " |
| "to 'dsp_trigger_sw_rejection', the stress test in " |
| "'stress_test.dsp_trigger_sw_rejection.ascii_proto' will " |
| "be loaded and executed.") |
| # flags.mark_flag_as_required("test_name") |
| flags.DEFINE_string("output_root", "./", |
| "Path where directory should be generated containing all " |
| "logs from devices and moved files.") |
| flags.DEFINE_integer("num_iterations", None, |
| "If set to a positive number, the number of iterations of " |
| "the stress test to run. Otherwise, the test runs " |
| "forever.") |
| flags.DEFINE_list("devices", [], |
| "Serial numbers of devices that should be included in the " |
| "stress test. If empty, all devices will be used.") |
| flags.DEFINE_integer("print_summary_every_n", 10, |
| "Prints the summary to the log file every n iterations.") |
| |
| flags.DEFINE_string("email_sender_address", "", |
| "Account to use for sending notification emails.") |
| flags.DEFINE_string("email_sender_password", "", |
| "Password to use for notification email account.") |
| flags.DEFINE_string("email_smtp_server", "smtp.gmail.com", |
| "SMTP server to use for sending notification emails.") |
| flags.DEFINE_integer("email_smtp_port", 465, |
| "Port to use for the notification SMTP server.") |
| flags.DEFINE_integer("device_settle_time", 5, |
| "Time to wait for devices to settle.") |
| flags.DEFINE_bool("use_sox", platform.system() != "Windows", |
| "Use sox for playback, otherwise, attempt to use platform " |
| "specific features.") |
| flags.DEFINE_bool("attach_bugreport", True, |
| "Attach bugreport to email if test failed.") |
| flags.DEFINE_bool("delete_data_dir", False, |
| "If true, code will delete all the files generated by this " |
| "test at the end.") |
| |
| if platform.system().startswith("CYGWIN"): |
| FLAGS.device_settle_time = 30 |
| |
| |
| def QueueWorker(worker_queue): |
| while True: |
| work = worker_queue.get() |
| try: |
| work() |
| except: # pylint:disable=bare-except |
| logging.exception("Exception in worker queue - task remains uncompleted.") |
| worker_queue.task_done() |
| |
| |
| def SendNotificationEmail(subject, body, bugreport=None): |
| """Sends an email with the specified subject and body. |
| |
| Also attach bugreport if bugreport location is provided as argument |
| |
| Args: |
| subject: Subject of the email. |
| body: Body of the email. |
| bugreport: If provided, it will be attach to the email. |
| """ |
| if FLAGS.suppress_notification_emails: |
| logging.info("Email with subject '%s' has been suppressed", subject) |
| return |
| try: |
| # Assemble the message to send. |
| recpient_address = FLAGS.notification_address |
| message = multipart.MIMEMultipart("alternative") |
| message["From"] = "Stress Test on %s" % socket.gethostname() |
| message["To"] = recpient_address |
| message["Subject"] = subject |
| message.attach(text.MIMEText(body, "plain")) |
| message.attach(text.MIMEText("<pre>%s</pre>" % body, "html")) |
| |
| if FLAGS.attach_bugreport and bugreport: |
| # buildozer: disable=unused-variable |
| ctype, _ = mimetypes.guess_type(bugreport) |
| maintype, subtype = ctype.split("/", 1) |
| with open(bugreport, "rb") as fp: |
| att = base.MIMEBase(maintype, subtype) |
| att.set_payload(fp.read()) |
| encoders.encode_base64(att) |
| att.add_header("Content-Disposition", "attachment", filename=bugreport) |
| message.attach(att) |
| |
| # Send the message from our special account. |
| server = smtplib.SMTP_SSL(FLAGS.email_smtp_server, FLAGS.email_smtp_port) |
| server.login(FLAGS.email_sender_address, FLAGS.email_sender_password) |
| server.sendmail(FLAGS.email_sender_address, recpient_address, |
| message.as_string()) |
| server.quit() |
| logging.info("Email with subject '%s' has been sent", subject) |
| except: # pylint:disable=bare-except |
| logging.exception("Failed to send notification email") |
| |
| |
| class ProcessLogger(threading.Thread): |
| |
| class EventScanner(object): |
| |
| def __init__(self, name, process_name, regexes): |
| """Struct to store the data about an event. |
| |
| Args: |
| name: Name of event. |
| process_name: Name of the process that is being logged. |
| regexes: An iteratable of regex strings that indicate an event has |
| happened. |
| """ |
| |
| self.name = name |
| self.process_name = process_name |
| self.searches = [re.compile(regex).search for regex in regexes] |
| self.count = 0 |
| |
| def ScanForEvent(self, line, lock=None): |
| """Checks the line for matches. If found, updates the internal counter.""" |
| |
| for search in self.searches: |
| if search(line.decode("utf-8")): |
| # Grab the lock (if provided), update the counter, and release it. |
| if lock: lock.acquire() |
| self.count += 1 |
| if lock: lock.release() |
| logging.info("Event '%s' detected on %s", self.name, |
| self.process_name) |
| |
| def __init__(self, name, command, output, events, |
| restart_process, repeats_output_when_opened): |
| """Threaded class that monitors processes for events, and logs output. |
| |
| Args: |
| name: The name of the process being logged. |
| command: A list of arguments to be passed to the subprocess to execute. |
| output: Name of output file to write process stdout to. If blank or None, |
| will not be generated. |
| events: An iterable of LoggingEventConfigs to look for in the output. |
| restart_process: Restart the process if it terminates by itself. This |
| should typically be true, but false for processes that only should be |
| run once and have their output logged. |
| repeats_output_when_opened: Set to true if the process will repeat the |
| output of a previous call when it is restarted. This will prevent |
| duplicate lines from being logged. |
| """ |
| super(ProcessLogger, self).__init__() |
| self.name = name |
| self.command = command |
| self.restart_process = restart_process |
| self.repeats_output_when_opened = repeats_output_when_opened |
| self.process = None |
| self.lock = threading.Lock() |
| self.looking = False |
| |
| # Compile the list of regexes that we're supposed to be looking for. |
| self.events = [] |
| for event in events: |
| self.events.append(ProcessLogger.EventScanner(event.name, self.name, |
| event.regex)) |
| |
| if output: |
| stress_test_common.MakeDirsIfNeeded(os.path.dirname(output)) |
| self.output_fp = open(output, "w", encoding="utf-8") |
| logging.info("Logging device info to %s", output) |
| else: |
| self.output_fp = None |
| |
| def GetEventCountsSinceLastCall(self): |
| """Returns the counts of all events since this method was last called.""" |
| event_map = {} |
| self.lock.acquire() |
| for event in self.events: |
| event_map[event.name] = event.count |
| event.count = 0 |
| self.lock.release() |
| return event_map |
| |
| def run(self): |
| last_line = None |
| should_log = True |
| first_run = True |
| skip_exception_line = False |
| self.lock.acquire() |
| last_run_time = 0 |
| while self.restart_process: |
| self.lock.release() |
| if not first_run: |
| logging.info("Restarting process %s", "".join(str(self.command))) |
| time_since_last_run = datetime.datetime.now() - last_run_time |
| if time_since_last_run.total_seconds() < 1.0: |
| needed_delay = 1.0 - time_since_last_run.total_seconds() |
| logging.info("Delaying for %.2f seconds", needed_delay) |
| time.sleep(needed_delay) |
| else: |
| first_run = False |
| |
| try: |
| if pexpect: |
| self.process = pexpect.spawn(" ".join(self.command), timeout=None) |
| output_source = self.process |
| else: |
| self.process = subprocess.Popen(self.command, stdout=subprocess.PIPE) |
| output_source = self.process.stdout |
| last_run_time = datetime.datetime.now() |
| for line in output_source: |
| # If the process we're logging likes to repeat its output, we need to |
| # look for the last line we saw before we start doing anything with |
| # these lines anymore. |
| if self.repeats_output_when_opened: |
| if not should_log: |
| if last_line == line: |
| should_log = True |
| continue |
| elif skip_exception_line: |
| # ignore the last line which caused UnicodeEncodeError |
| skip_exception_line = False |
| continue |
| |
| if self.output_fp: |
| self.output_fp.write(line.decode("utf-8", "backslashreplace").rstrip()) |
| self.output_fp.write("\n") |
| |
| # Loop through all events we're watching for, to see if they occur on |
| # this line. If they do, update the fact that we've seen this event. |
| for event in self.events: |
| if self.looking: |
| event.ScanForEvent(line, lock=self.lock) |
| last_line = line |
| except UnicodeEncodeError: |
| logging.exception("UnicodeEncodeError on running logger process") |
| skip_exception_line = True |
| except: # pylint:disable=bare-except |
| logging.exception("Exception encountered running process") |
| finally: |
| if pexpect: |
| self.process.terminate() |
| else: |
| self.process.send_signal(signal.SIGTERM) |
| should_log = False |
| self.lock.acquire() |
| |
| self.lock.release() |
| if pexpect: |
| if self.process.exitstatus is not None: |
| logging.info("Process finished - exit code %d", self.process.exitstatus) |
| else: |
| logging.info("Process finished - signal code %d", |
| self.process.signalstatus) |
| else: |
| if self.process.returncode is not None: |
| logging.info("Process finished - return code %d", |
| self.process.returncode) |
| else: |
| logging.info("Process finished - no return code") |
| |
| def StopLogging(self): |
| if self.process: |
| self.lock.acquire() |
| self.restart_process = False |
| self.lock.release() |
| |
| if pexpect: |
| self.process.kill(signal.SIGHUP) |
| self.process.kill(signal.SIGINT) |
| else: |
| self.process.send_signal(signal.SIGTERM) |
| |
| |
| class Device(object): |
| |
| SECONDS_TO_SLEEP_DURING_ROOT = 0.5 |
| |
| def __init__(self, serial_number, output_root, test_events, expected_result): |
| """Responsible for monitoring a specific device, and pulling files from it. |
| |
| The actual work of the constructor will be handled asynchronously, you must |
| call WaitForTasks() before using the device. |
| |
| Args: |
| serial_number: The device serial number. |
| output_root: The directory where to output log files/anything pulled from |
| the device. |
| test_events: The events (with conditions) that come from the StressTest |
| that should be evaluated at every iteration, along with a list of |
| actions to take when one of these events occur. For example, if there |
| have not been any detected hotword triggers, a bugreport can be |
| generated. |
| expected_result: Expected event count to pass the test. |
| """ |
| self.serial_number = serial_number |
| self.output_root = output_root |
| self.cmd_string_replacements = {} |
| self.iteration = 0 |
| self.cmd_string_replacements["iteration"] = 0 |
| self.cmd_string_replacements["serial_number"] = serial_number |
| self.cmd_string_replacements["output_root"] = output_root |
| self.name = None |
| self.process_loggers = [] |
| self.event_log = stress_test_pb2.EventLog() |
| self.cnt_per_iteration = expected_result |
| |
| # Prepare the work queue, and offload the rest of the init into it. |
| self.work_queue = queue.Queue() |
| self.worker = threading.Thread(target=QueueWorker, args=[self.work_queue]) |
| self.worker.daemon = True |
| self.worker.name = self.name |
| self.worker.start() |
| self.abort_requested = False |
| self.remove_device = False |
| self.test_events = test_events |
| |
| self.work_queue.put(self.__init_async__) |
| |
| def __init_async__(self): |
| # Get the device type, and append it to the serial number. |
| self.device_type = self.Command(["shell", "getprop", |
| "ro.product.name"]).strip().decode("utf-8") |
| self.name = "%s_%s" % (self.device_type, self.serial_number) |
| self.worker.name = self.name |
| self.cmd_string_replacements["device"] = self.name |
| logging.info("Setting up device %s", self.name) |
| |
| config = stress_test_common.LoadDeviceConfig(self.device_type, |
| self.serial_number) |
| |
| # Get the device ready. |
| self.Root() |
| |
| # Run any setup commands. |
| for cmd in config.setup_command: |
| result = self.Command( |
| shlex.split(cmd % self.cmd_string_replacements)).strip() |
| if result: |
| for line in result.splitlines(): |
| logging.info(line) |
| |
| self.files_to_move = config.file_to_move |
| |
| self.event_names = set([event.name for event in config.event]) |
| self.event_counter = {name: 0 for name in self.event_names} |
| self.iterations_since_event = {name: 0 for name in self.event_names} |
| |
| for file_to_watch in config.file_to_watch: |
| # Are there any events that match up with this file? |
| events = [x for x in config.event if x.source == file_to_watch.source] |
| |
| if file_to_watch.source == "LOGCAT": |
| command = [ |
| "adb", "-s", self.serial_number, "logcat", "-v", "usec", "" |
| ] |
| command.extend(["%s:S" % tag for tag in config.tag_to_suppress]) |
| name = "logcat_" + self.serial_number |
| else: |
| command = [ |
| "adb", "-s", self.serial_number, "shell", |
| "while : ; do cat %s 2>&1; done" % file_to_watch.source |
| ] |
| name = "%s_%s" % (os.path.basename( |
| file_to_watch.source), self.serial_number) |
| |
| process_logger = ProcessLogger( |
| name, command, os.path.join( |
| self.output_root, |
| file_to_watch.destination % self.cmd_string_replacements), |
| events, True, file_to_watch.repeats_output_on_open) |
| self.process_loggers.append(process_logger) |
| process_logger.start() |
| |
| # Add any of the background processes. |
| for daemon_process in config.daemon_process: |
| # Are there any events that match up with this file? |
| events = [x for x in config.event if x.source == daemon_process.name] |
| command = shlex.split( |
| daemon_process.command % self.cmd_string_replacements) |
| if daemon_process.destination: |
| output = os.path.join( |
| self.output_root, |
| daemon_process.destination % self.cmd_string_replacements) |
| else: |
| output = None |
| name = "%s_%s" % (daemon_process.name, self.serial_number) |
| process_logger = ProcessLogger(name, command, output, events, |
| daemon_process.restart, |
| daemon_process.repeats_output_on_open) |
| self.process_loggers.append(process_logger) |
| process_logger.start() |
| |
| # Build up the list of events we can actually process. |
| self.__UpdateEventCounters(number_of_iterations=0) |
| test_events = self.test_events |
| self.test_events = [] |
| for event in test_events: |
| try: |
| eval(event.condition, # pylint:disable=eval-used |
| {"__builtins__": None}, self.__ValuesInEval()) |
| self.test_events.append(event) |
| except Exception as err: # pylint:disable=broad-except |
| logging.error("Test event %s is not compatible with %s", event.name, |
| self.name) |
| logging.error(str(err)) |
| # Make sure that device specific events don't have conditions. |
| self.device_events = [] |
| for event in config.test_event: |
| if not event.name: |
| logging.error("Device %s test event is missing a name", self.name) |
| continue |
| if event.condition: |
| self.test_events.append(event) |
| else: |
| self.device_events.append(event) |
| |
| def StartLookingForEvents(self): |
| """Starts all child ProcessLoggers to start looking for events.""" |
| for process_logger in self.process_loggers: |
| process_logger.looking = True |
| |
| def __ValuesInEval(self): |
| values_in_eval = {key: value for key, value |
| in list(self.event_counter.items())} |
| for key, value in list(self.iterations_since_event.items()): |
| values_in_eval["iterations_since_%s" % key] = value |
| return values_in_eval |
| |
| def __GetExpectedEventCount(self, event): |
| if event == "logcat_iteration": |
| return -1 |
| try: |
| event_cnt = getattr(self.cnt_per_iteration, event) |
| except AttributeError: |
| event_cnt = -1 |
| logging.exception("%s is not an attribute of expected_result", event) |
| return event_cnt |
| |
| def __UpdateEventCounters(self, number_of_iterations=1): |
| # Update the event counters |
| visited_events = set() |
| error_log = [] |
| for process_logger in self.process_loggers: |
| events = process_logger.GetEventCountsSinceLastCall() |
| for event, count in list(events.items()): |
| # Print log when there is any missed event |
| expected_count = self.__GetExpectedEventCount(event) |
| |
| if expected_count > 0: |
| if count > expected_count * number_of_iterations: |
| logging.info( |
| "[STRESS_TEST] In iteration %d, got duplicated %s : %d", |
| self.iteration, self.name, count) |
| logging.info("[STRESS_TEST] Will count only : %d", |
| expected_count * number_of_iterations) |
| count = expected_count * number_of_iterations |
| |
| if count: |
| self.event_counter[event] += count |
| visited_events.add(event) |
| |
| if expected_count >= 0: |
| if expected_count * number_of_iterations != count: |
| error_log.append( |
| _SUMMARY_COL_FORMATT % |
| (event, count, expected_count * number_of_iterations)) |
| |
| # Go clear all the events that weren't consecutive. |
| for event in self.iterations_since_event: |
| if event in visited_events: |
| self.iterations_since_event[event] = 0 |
| else: |
| self.iterations_since_event[event] += number_of_iterations |
| |
| if error_log: |
| logging.info(_SUMMARY_LINES) |
| logging.info(" iteration %d : Something wrong in %s.", |
| self.iteration, self.name) |
| logging.info(_SUMMARY_LINES) |
| logging.info(_SUMMARY_COLUMNS) |
| logging.info(_SUMMARY_LINES) |
| for line in error_log: |
| logging.info(line) |
| logging.info(_SUMMARY_LINES) |
| |
| def ProcessEvents(self): |
| """Updates the event_counter and iterations_since_event maps.""" |
| self.work_queue.put(self.__ProcessEventsAsync) |
| |
| def __ProcessEventsAsync(self): |
| # Move any files to the local machine that should be moved. |
| if self.files_to_move: |
| for file_to_move in self.files_to_move: |
| try: |
| self.Command(["pull", file_to_move.source, file_to_move.destination]) |
| except: # pylint:disable=bare-except |
| logging.exception("Failed to pull %s", file_to_move.source) |
| |
| self.__UpdateEventCounters() |
| |
| for event in self.test_events: |
| if eval(event.condition, # pylint:disable=eval-used |
| {"__builtins__": None}, self.__ValuesInEval()): |
| logging.info("Condition has been met for event '%s'", event.name) |
| # Write the updated event log. |
| event_log_details = self.event_log.event.add() |
| event_log_details.iteration = self.iteration |
| event_log_details.name = event.name |
| with open(os.path.join(self.output_root, |
| "%s_event_log.ascii_proto" % self.name), |
| "w") as fp: |
| text_format.PrintMessage(self.event_log, fp) |
| |
| # Do whatever other actions that are part of the event. |
| self.__ProcessEventActionQueue(event) |
| |
| # Run any device specific actions for this event. |
| for device_event in self.device_events: |
| if device_event.name == event.name: |
| self.__ProcessEventActionQueue(device_event) |
| |
| # Set up the next iteration. |
| self.iteration += 1 |
| self.cmd_string_replacements["iteration"] = self.iteration |
| |
| def __ProcessEventActionQueue(self, event): |
| bugreport = None |
| for action in event.action: |
| if action == "BUGREPORT": |
| bugreport = self.TakeBugReport() |
| elif action.startswith("DUMPSYS "): |
| self.CaptureDumpsys(action[action.find(" ") + 1:]) |
| elif action == "NOTIFY": |
| SendNotificationEmail( |
| "%s had event '%s' occur" % (self.name, event.name), |
| "\n".join(["Current Summary:"] + self.GetSummaryLines()), bugreport) |
| elif action == "REMOVE_DEVICE": |
| logging.info("Removing %s from the test", self.serial_number) |
| self.remove_device = True |
| elif action == "ABORT": |
| logging.info("Abort requested") |
| self.abort_requested = True |
| else: |
| action %= self.cmd_string_replacements |
| logging.info("Running command %s on %s", action, self.name) |
| result = self.Command(shlex.split(action)).strip() |
| if result: |
| for line in result.splitlines(): |
| logging.info(line) |
| |
| def Root(self): |
| self.Command(["root"]) |
| time.sleep(Device.SECONDS_TO_SLEEP_DURING_ROOT) |
| self.Command(["wait-for-device"]) |
| time.sleep(Device.SECONDS_TO_SLEEP_DURING_ROOT) |
| |
| def Stop(self): |
| """Stops all file loggers attached to this device.""" |
| for process_logger in self.process_loggers: |
| process_logger.StopLogging() |
| self.process_loggers = [] |
| |
| def Join(self): |
| for process_logger in self.process_loggers: |
| process_logger.join() |
| self.WaitForTasks() |
| |
| def AsyncCommand(self, command, log_output=False): |
| self.work_queue.put( |
| lambda: self.__AsyncCommand(command, log_output=log_output)) |
| |
| def __AsyncCommand(self, command, log_output=False): |
| result = self.Command(command).strip() |
| if result and log_output: |
| for line in result.splitlines(): |
| logging.info(line.decode("utf-8")) |
| |
| def Command(self, command): |
| """Runs the provided command on this device.""" |
| if command[0] in {"bugreport", "root", "wait-for-device", "shell", |
| "logcat"}: |
| return subprocess.check_output( |
| ["adb", "-s", self.serial_number] + command) |
| elif command[0] == "DUMPSYS": |
| self.CaptureDumpsys(command[1]) |
| return "" |
| elif command[0] == "pull": |
| try: |
| files = subprocess.check_output( |
| ["adb", "-s", self.serial_number, "shell", "ls", command[1]] |
| ).strip().splitlines() |
| except subprocess.CalledProcessError: |
| return "" |
| if len(files) == 1 and "No such file or directory" in files[0]: |
| return "" |
| for source_file in files: |
| destination = os.path.join(self.output_root, |
| command[2] % self.cmd_string_replacements) |
| stress_test_common.MakeDirsIfNeeded(os.path.dirname(destination)) |
| logging.info("Moving %s from %s to %s", source_file, self.name, |
| destination) |
| subprocess.check_output(["adb", "-s", self.serial_number, "pull", |
| source_file, destination]) |
| if FLAGS.delete_data_dir: |
| subprocess.check_output([ |
| "adb", "-s", self.serial_number, "shell", "rm", "-rf", source_file |
| ]) |
| return "" |
| else: |
| return subprocess.check_output(command) |
| |
| def TakeBugReport(self): |
| logging.info("Capturing bugreport on %s", self.name) |
| bugreport = os.path.join(self.output_root, |
| "%s_bugreport_iteration_%06d.zip" % |
| (self.name, self.iteration)) |
| sdk = int(self.Command( |
| ["shell", "getprop", "ro.build.version.sdk"]).strip()) |
| if sdk >= 24: # SDK 24 = Android N |
| with open(bugreport, "w") as bugreport_fp: |
| bugreport_fp.write(self.Command(["bugreport", bugreport])) |
| else: |
| bugreport_txt = os.path.join(self.output_root, |
| "%s_bugreport_iteration_%06d.txt" % |
| (self.name, self.iteration)) |
| with open(bugreport_txt, "w") as bugreport_fp: |
| bugreport_fp.write(self.Command(["bugreport"])) |
| self.Command(["zip", bugreport, bugreport_txt]) |
| |
| self.Command(["pull", "/data/anr/traces.txt", |
| "%s_traces_iteration_%06d.txt" % (self.name, self.iteration)]) |
| self.Command(["pull", "/data/anr/traces.txt.bugreport", |
| "%s_traces_iteration_%06d.txt.bugreport" % (self.name, |
| self.iteration)]) |
| return bugreport |
| |
| def CaptureDumpsys(self, dumpsys_unit): |
| logging.info("Taking dumpsys %s on %s", dumpsys_unit, self.name) |
| stress_test_common.MakeDirsIfNeeded(os.path.join(self.output_root, |
| self.name)) |
| with open(os.path.join(self.output_root, self.name, |
| "%s_%06d.txt" % (dumpsys_unit, self.iteration)), |
| "w") as dumpsys_fp: |
| dumpsys_fp.write(self.Command(["shell", "dumpsys", dumpsys_unit])) |
| |
| def WaitForTasks(self): |
| self.work_queue.join() |
| |
| def GetSummaryLines(self): |
| lines = [ |
| "Device {}".format(self.name), |
| _SUMMARY_LINES, _SUMMARY_COLUMNS, _SUMMARY_LINES |
| ] |
| for event, count in sorted(self.event_counter.items()): |
| lines.append(_SUMMARY_COL_FORMATT % ( |
| event, count, self.iterations_since_event[event])) |
| lines.append(_SUMMARY_LINES) |
| return lines |
| |
| |
| def RunAsyncCommand(devices, command): |
| """Helper function for running async commands on many devices.""" |
| for device in devices: |
| device.AsyncCommand(command) |
| for device in devices: |
| device.WaitForTasks() |
| |
| |
| class StressTest(object): |
| """Manages dispatching commands to devices/playing audio and events.""" |
| |
| def __init__(self, output_root, test_name): |
| self.output_root = output_root |
| self.devices = [] |
| self.test_name = test_name |
| config = stress_test_pb2.StressTestConfig() |
| config_contents = stress_test_common.GetResourceContents( |
| os.path.join(stress_test_common.RESOURCE_DIR, |
| "stress_test.%s.ascii_proto" % test_name)) |
| text_format.Merge(config_contents, config) |
| self.events = config.event |
| self.setup_commands = config.setup_command |
| self.steps = config.step |
| self.audio_tempfiles = {} |
| self.uuid = str(uuid.uuid4()) |
| self.expected_result = None |
| self.iteration = 0 |
| if config.expected_result: |
| self.expected_result = config.expected_result[0] |
| |
| # Place all the audio files into temp files. |
| for step in self.steps: |
| if step.audio_file and step.audio_file not in self.audio_tempfiles: |
| # We can't delete the temp file on windows, since it gets nuked too |
| # early. |
| audio_tempfile = tempfile.NamedTemporaryFile( |
| delete=(platform.system() != "Windows"), |
| dir="." if platform.system().startswith("CYGWIN") else None |
| ) |
| if platform.system().startswith("CYGWIN"): |
| audio_tempfile.name = os.path.basename(audio_tempfile.name) |
| self.audio_tempfiles[step.audio_file] = audio_tempfile |
| if FLAGS.use_sox: |
| # Write out the raw PCM samples as a wave file. |
| audio_tempfile.write( |
| stress_test_common.GetResourceContents(step.audio_file)) |
| else: |
| # Make a temporary wave file for playout if we can't use sox. |
| wavefile = wave.open(audio_tempfile, "wb") |
| if step.audio_file_sample_rate <= 0: |
| step.audio_file_sample_rate = 16000 |
| wavefile.setframerate(step.audio_file_sample_rate) |
| if step.audio_file_num_channels <= 0: |
| step.audio_file_num_channels = 1 |
| wavefile.setnchannels(step.audio_file_num_channels) |
| if not step.audio_file_format: |
| wavefile.setsampwidth(2) |
| elif step.audio_file_format == "s8": |
| wavefile.setsampwidth(1) |
| elif step.audio_file_format == "s16": |
| wavefile.setsampwidth(2) |
| elif step.audio_file_format == "s32": |
| wavefile.setsampwidth(4) |
| else: |
| raise RuntimeError( |
| "Unsupported wave file format for %s" % step.audio_file) |
| wavefile.writeframes(stress_test_common.GetResourceContents( |
| step.audio_file)) |
| wavefile.close() |
| audio_tempfile.flush() |
| |
| if platform.system() == "Windows": |
| audio_tempfile.close() |
| |
| # Create all the devices that are attached to this machine. |
| for serial_number in self.GetActiveSerialNumbers(): |
| self.devices.append( |
| Device(serial_number, output_root, self.events, self.expected_result)) |
| if not self.devices: |
| raise app.UsageError("No devices connected") |
| |
| self.devices.sort(key=lambda x: x.name) |
| |
| # Make sure every device is done with their work for setup. |
| for device in self.devices: |
| device.WaitForTasks() |
| |
| # Write out the info meta-data proto. Useful for doing analysis of the logs |
| # after the stress test has completed. |
| stress_test_info = stress_test_pb2.StressTestInfo() |
| stress_test_info.test_name = self.test_name |
| stress_test_info.test_description = config.description |
| stress_test_info.uuid = self.uuid |
| for device in self.devices: |
| device_pb = stress_test_info.device.add() |
| device_pb.device_type = device.device_type |
| device_pb.serial_number = device.serial_number |
| |
| text_format.PrintMessage(stress_test_info, open(os.path.join( |
| self.output_root, "stress_test_info.ascii_proto"), "w")) |
| |
| def GetActiveSerialNumbers(self): |
| serial_numbers = [] |
| for line in sorted( |
| subprocess.check_output(["adb", "devices"]).splitlines()): |
| if line.endswith(b"device"): |
| serial_number = line.split()[0].strip() |
| if FLAGS.devices and serial_number not in FLAGS.devices: |
| continue |
| serial_numbers.append(serial_number.decode("utf-8")) |
| return serial_numbers |
| |
| def Start(self): |
| logging.info("Waiting for devices to settle") |
| time.sleep(5) |
| # Make a copy of the device list, as we'll be modifying this actual list. |
| devices = list(self.devices) |
| dropped_devices = [] |
| |
| # If we have any setup commands, run them. |
| for command in self.setup_commands: |
| logging.info("Running command %s", command) |
| # Can't use the async command helper function since we need to get at |
| # the device cmd_string_replacements. |
| for device in devices: |
| device.AsyncCommand( |
| shlex.split(command % device.cmd_string_replacements), |
| log_output=True) |
| for device in devices: |
| device.WaitForTasks() |
| |
| for device in devices: |
| device.StartLookingForEvents() |
| device.AsyncCommand(["shell", "log", "-t", "STRESS_TEST", |
| "Starting {%s} TZ=$(getprop persist.sys.timezone) " |
| "YEAR=$(date +%%Y)" % self.uuid], True) |
| self.iteration = 0 |
| while True: |
| logging.info("Starting iteration %d", self.iteration) |
| # Perform all the actions specified in the test. |
| RunAsyncCommand(devices, [ |
| "shell", "log", "-t", "STRESS_TEST", |
| "Performing iteration %d $(head -n 3 " |
| "/proc/timer_list | tail -n 1)" % self.iteration |
| ]) |
| |
| for step in self.steps: |
| if step.delay_before: |
| logging.info("Waiting for %.2f seconds", step.delay_before) |
| time.sleep(step.delay_before) |
| |
| if step.audio_file: |
| logging.info("Playing %s", step.audio_file) |
| RunAsyncCommand(devices, ["shell", "log", "-t", "STRESS_TEST", |
| "Playing %s" % step.audio_file]) |
| |
| if FLAGS.use_sox: |
| subprocess.check_call(["sox", "-q", |
| self.audio_tempfiles[step.audio_file].name, |
| "-d"]) |
| elif platform.system() == "Windows": |
| import winsound # pylint:disable=g-import-not-at-top |
| winsound.PlaySound(self.audio_tempfiles[step.audio_file].name, |
| winsound.SND_FILENAME | winsound.SND_NODEFAULT) |
| else: |
| raise app.RuntimeError("Unsupported platform for audio playback") |
| |
| if step.command: |
| logging.info("Running command %s", step.command) |
| # Can't use the async command helper function since we need to get at |
| # the device cmd_string_replacements. |
| for device in devices: |
| device.AsyncCommand( |
| shlex.split(step.command % device.cmd_string_replacements), |
| log_output=True) |
| for device in devices: |
| device.WaitForTasks() |
| |
| if step.delay_after: |
| logging.info("Waiting for %.2f seconds", step.delay_after) |
| time.sleep(step.delay_after) |
| |
| RunAsyncCommand(devices, [ |
| "shell", "log", "-t", "STRESS_TEST", |
| "Iteration %d complete $(head -n 3 " |
| "/proc/timer_list | tail -n 1)" % self.iteration |
| ]) |
| self.iteration += 1 |
| |
| # TODO(somebody): Sometimes the logcat seems to get stuck and buffers for |
| # a bit. This throws off the event counts, so we should probably add some |
| # synchronization rules before we trigger any events. |
| |
| # Go through each device, update the event counter, and see if we need to |
| # trigger any events. |
| devices_to_remove = [] |
| abort_requested = False |
| active_devices = self.GetActiveSerialNumbers() |
| for device in devices: |
| if device.serial_number in active_devices: |
| device.ProcessEvents() |
| else: |
| logging.error("Dropped device %s", device.name) |
| SendNotificationEmail( |
| "Dropped device %s" % device.name, |
| "Device %s is not longer present in the system" % device.name) |
| dropped_devices.append(device) |
| devices_to_remove.append(device) |
| |
| # Check to see if any of the dropped devices have come back. If yes, grab |
| # a bug report. |
| for device in dropped_devices: |
| if device.serial_number in active_devices: |
| logging.info("Device %s reappeared", device.name) |
| device.Root() |
| device.TakeBugReport() |
| |
| dropped_devices = [d for d in dropped_devices |
| if d.serial_number not in active_devices] |
| |
| for device in devices: |
| device.WaitForTasks() |
| if device.remove_device: |
| devices_to_remove.append(device) |
| if device.abort_requested: |
| abort_requested = True |
| |
| # Remove devices from our list of things to monitor if they've been marked |
| # for deletion. |
| if devices_to_remove: |
| for device in devices_to_remove: |
| device.Stop() |
| devices = [d for d in devices if d not in devices_to_remove] |
| |
| # Print out the iteration summary. |
| if self.iteration % FLAGS.print_summary_every_n == 0: |
| for line in self.GetSummaryLines(): |
| logging.info(line) |
| |
| # See if we need to break out of the outer loop. |
| if abort_requested or not devices: |
| break |
| if FLAGS.num_iterations: |
| if self.iteration >= FLAGS.num_iterations: |
| logging.info("Completed full iteration : %d", self.iteration) |
| break |
| SendNotificationEmail( |
| "Stress test %s completed" % (FLAGS.test_name), |
| "\n".join(["Summary:"] + self.GetSummaryLines())) |
| |
| def Stop(self): |
| logging.debug("Stopping devices") |
| for device in self.devices: |
| device.Stop() |
| for device in self.devices: |
| device.Join() |
| |
| def GetSummaryLines(self): |
| lines = [ |
| _SUMMARY_LINES, |
| "Conducted %d iterations out of %d" % |
| (self.iteration, FLAGS.num_iterations), |
| _SUMMARY_LINES |
| ] |
| for device in self.devices: |
| lines.extend(device.GetSummaryLines()) |
| lines.append(_SUMMARY_LINES) |
| return lines |
| |
| |
| def main(unused_argv): |
| # Check to make sure that there are no other instances of ADB running - if |
| # there are, print a warning and wait a bit for them to see it and decide if |
| # they want to keep running, knowing that logs may be invalid. |
| try: |
| if "adb" in subprocess.check_output(["ps", "-ale"]).decode("utf-8"): |
| print("It looks like there are other instances of adb running. If these " |
| "other instances are also cating log files, you will not be " |
| "capturing everything in this stress test (so logs will be " |
| "invalid).") |
| print("Continuing in 3...", end=" ") |
| sys.stdout.flush() |
| for i in [2, 1, 0]: |
| time.sleep(1) |
| if i: |
| print("%d..." % i, end=" ") |
| else: |
| print("") |
| sys.stdout.flush() |
| except OSError: |
| print("Unexpected error:", sys.exc_info()[0]) |
| if sys.platform.startswith("win"): |
| pass |
| else: |
| raise |
| |
| # Make the base output directory. |
| output_root = os.path.join(FLAGS.output_root, "%s_%s" % ( |
| FLAGS.test_name, datetime.datetime.now().strftime("%Y%m%d_%H%M%S"))) |
| # output_root = os.path.join(FLAGS.output_root, FLAGS.test_name) |
| stress_test_common.MakeDirsIfNeeded(output_root) |
| |
| # Set up logging. |
| formatter = logging.Formatter( |
| "%(levelname)-1.1s %(asctime)s [%(threadName)-16.16s] %(message)s") |
| root_logger = logging.getLogger() |
| root_logger.setLevel(logging.INFO) |
| root_logger.setLevel(logging.DEBUG) |
| |
| file_handler = logging.FileHandler(os.path.join(output_root, |
| "stress_test.log")) |
| file_handler.setFormatter(formatter) |
| root_logger.addHandler(file_handler) |
| |
| console_handler = logging.StreamHandler() |
| console_handler.setFormatter(formatter) |
| root_logger.addHandler(console_handler) |
| |
| stress_test = StressTest(output_root, FLAGS.test_name) |
| try: |
| stress_test.Start() |
| finally: |
| logging.info("Stopping device logging threads") |
| stress_test.Stop() |
| for line in stress_test.GetSummaryLines(): |
| logging.info(line) |
| if FLAGS.delete_data_dir: |
| print("Deleting Data Dir") |
| subprocess.check_output(["rm", "-r", "-f", output_root]) |
| |
| |
| if __name__ == "__main__": |
| app.run(main) |
