| #!/usr/bin/env python3 |
| # vim: set syntax=python ts=4 : |
| # |
| # Copyright (c) 20180-2022 Intel Corporation |
| # SPDX-License-Identifier: Apache-2.0 |
| |
| import math |
| import os |
| import sys |
| import csv |
| import time |
| import signal |
| import logging |
| import shlex |
| import subprocess |
| import threading |
| import select |
| import re |
| from twisterlib.environment import ZEPHYR_BASE |
| |
| try: |
| import serial |
| except ImportError: |
| print("Install pyserial python module with pip to use --device-testing option.") |
| |
| try: |
| import psutil |
| except ImportError: |
| print("Install psutil python module with pip to run in Qemu.") |
| |
| try: |
| import pty |
| except ImportError as capture_error: |
| if os.name == "nt": # "nt" means that program is running on Windows OS |
| pass # "--device-serial-pty" option is not supported on Windows OS |
| else: |
| raise capture_error |
| |
| logger = logging.getLogger('twister') |
| logger.setLevel(logging.DEBUG) |
| |
| |
| class HarnessImporter: |
| |
| def __init__(self, name): |
| sys.path.insert(0, os.path.join(ZEPHYR_BASE, "scripts/pylib/twister/twisterlib")) |
| module = __import__("harness") |
| if name: |
| my_class = getattr(module, name) |
| else: |
| my_class = getattr(module, "Test") |
| |
| self.instance = my_class() |
| |
| class Handler: |
| def __init__(self, instance, type_str="build"): |
| """Constructor |
| |
| """ |
| self.options = None |
| |
| self.state = "waiting" |
| self.run = False |
| self.type_str = type_str |
| |
| self.binary = None |
| self.pid_fn = None |
| self.call_make_run = True |
| |
| self.name = instance.name |
| self.instance = instance |
| self.timeout = math.ceil(instance.testsuite.timeout * instance.platform.timeout_multiplier) |
| self.sourcedir = instance.testsuite.source_dir |
| self.build_dir = instance.build_dir |
| self.log = os.path.join(self.build_dir, "handler.log") |
| self.returncode = 0 |
| self.generator = None |
| self.generator_cmd = None |
| self.suite_name_check = True |
| |
| self.args = [] |
| self.terminated = False |
| |
| def record(self, harness): |
| if harness.recording: |
| filename = os.path.join(self.build_dir, "recording.csv") |
| with open(filename, "at") as csvfile: |
| cw = csv.writer(csvfile, harness.fieldnames, lineterminator=os.linesep) |
| cw.writerow(harness.fieldnames) |
| for instance in harness.recording: |
| cw.writerow(instance) |
| |
| def terminate(self, proc): |
| # encapsulate terminate functionality so we do it consistently where ever |
| # we might want to terminate the proc. We need try_kill_process_by_pid |
| # because of both how newer ninja (1.6.0 or greater) and .NET / renode |
| # work. Newer ninja's don't seem to pass SIGTERM down to the children |
| # so we need to use try_kill_process_by_pid. |
| for child in psutil.Process(proc.pid).children(recursive=True): |
| try: |
| os.kill(child.pid, signal.SIGTERM) |
| except ProcessLookupError: |
| pass |
| proc.terminate() |
| # sleep for a while before attempting to kill |
| time.sleep(0.5) |
| proc.kill() |
| self.terminated = True |
| |
| def _verify_ztest_suite_name(self, harness_state, detected_suite_names, handler_time): |
| """ |
| If test suite names was found in test's C source code, then verify if |
| detected suite names from output correspond to expected suite names |
| (and not in reverse). |
| """ |
| expected_suite_names = self.instance.testsuite.ztest_suite_names |
| if not expected_suite_names or \ |
| not harness_state == "passed": |
| return |
| if not detected_suite_names: |
| self._missing_suite_name(expected_suite_names, handler_time) |
| for detected_suite_name in detected_suite_names: |
| if detected_suite_name not in expected_suite_names: |
| self._missing_suite_name(expected_suite_names, handler_time) |
| break |
| |
| def _missing_suite_name(self, expected_suite_names, handler_time): |
| """ |
| Change result of performed test if problem with missing or unpropper |
| suite name was occurred. |
| """ |
| self.instance.status = "failed" |
| self.instance.execution_time = handler_time |
| for tc in self.instance.testcases: |
| tc.status = "failed" |
| self.instance.reason = f"Testsuite mismatch" |
| logger.debug("Test suite names were not printed or some of them in " \ |
| "output do not correspond with expected: %s", |
| str(expected_suite_names)) |
| |
| def _final_handle_actions(self, harness, handler_time): |
| |
| # only for Ztest tests: |
| harness_class_name = type(harness).__name__ |
| if self.suite_name_check and harness_class_name == "Test": |
| self._verify_ztest_suite_name(harness.state, harness.detected_suite_names, handler_time) |
| |
| if not harness.matched_run_id and harness.run_id_exists: |
| self.instance.status = "failed" |
| self.instance.execution_time = handler_time |
| self.instance.reason = "RunID mismatch" |
| for tc in self.instance.testcases: |
| tc.status = "failed" |
| |
| self.record(harness) |
| |
| |
| class BinaryHandler(Handler): |
| def __init__(self, instance, type_str): |
| """Constructor |
| |
| @param instance Test Instance |
| """ |
| super().__init__(instance, type_str) |
| |
| self.call_west_flash = False |
| self.seed = None |
| |
| def try_kill_process_by_pid(self): |
| if self.pid_fn: |
| pid = int(open(self.pid_fn).read()) |
| os.unlink(self.pid_fn) |
| self.pid_fn = None # clear so we don't try to kill the binary twice |
| try: |
| os.kill(pid, signal.SIGTERM) |
| except ProcessLookupError: |
| pass |
| |
| def _output_reader(self, proc): |
| self.line = proc.stdout.readline() |
| |
| def _output_handler(self, proc, harness): |
| if harness.is_pytest: |
| harness.handle(None) |
| return |
| |
| log_out_fp = open(self.log, "wt") |
| timeout_extended = False |
| timeout_time = time.time() + self.timeout |
| while True: |
| this_timeout = timeout_time - time.time() |
| if this_timeout < 0: |
| break |
| reader_t = threading.Thread(target=self._output_reader, args=(proc,), daemon=True) |
| reader_t.start() |
| reader_t.join(this_timeout) |
| if not reader_t.is_alive(): |
| line = self.line |
| logger.debug("OUTPUT: {0}".format(line.decode('utf-8').rstrip())) |
| log_out_fp.write(line.decode('utf-8')) |
| log_out_fp.flush() |
| harness.handle(line.decode('utf-8').rstrip()) |
| if harness.state: |
| if not timeout_extended or harness.capture_coverage: |
| timeout_extended = True |
| if harness.capture_coverage: |
| timeout_time = time.time() + 30 |
| else: |
| timeout_time = time.time() + 2 |
| else: |
| reader_t.join(0) |
| break |
| try: |
| # POSIX arch based ztests end on their own, |
| # so let's give it up to 100ms to do so |
| proc.wait(0.1) |
| except subprocess.TimeoutExpired: |
| self.terminate(proc) |
| |
| log_out_fp.close() |
| |
| def handle(self): |
| |
| harness_name = self.instance.testsuite.harness.capitalize() |
| harness_import = HarnessImporter(harness_name) |
| harness = harness_import.instance |
| harness.configure(self.instance) |
| |
| if self.call_make_run: |
| command = [self.generator_cmd, "run"] |
| elif self.call_west_flash: |
| command = ["west", "flash", "--skip-rebuild", "-d", self.build_dir] |
| else: |
| command = [self.binary] |
| |
| run_valgrind = False |
| if self.options.enable_valgrind: |
| command = ["valgrind", "--error-exitcode=2", |
| "--leak-check=full", |
| "--suppressions=" + ZEPHYR_BASE + "/scripts/valgrind.supp", |
| "--log-file=" + self.build_dir + "/valgrind.log", |
| "--track-origins=yes", |
| ] + command |
| run_valgrind = True |
| |
| # Only valid for native_posix |
| if self.seed is not None: |
| command = command + ["--seed="+str(self.seed)] |
| |
| logger.debug("Spawning process: " + |
| " ".join(shlex.quote(word) for word in command) + os.linesep + |
| "in directory: " + self.build_dir) |
| |
| start_time = time.time() |
| |
| env = os.environ.copy() |
| if self.options.enable_asan: |
| env["ASAN_OPTIONS"] = "log_path=stdout:" + \ |
| env.get("ASAN_OPTIONS", "") |
| if not self.options.enable_lsan: |
| env["ASAN_OPTIONS"] += "detect_leaks=0" |
| |
| if self.options.enable_ubsan: |
| env["UBSAN_OPTIONS"] = "log_path=stdout:halt_on_error=1:" + \ |
| env.get("UBSAN_OPTIONS", "") |
| |
| with subprocess.Popen(command, stdout=subprocess.PIPE, |
| stderr=subprocess.PIPE, cwd=self.build_dir, env=env) as proc: |
| logger.debug("Spawning BinaryHandler Thread for %s" % self.name) |
| t = threading.Thread(target=self._output_handler, args=(proc, harness,), daemon=True) |
| t.start() |
| t.join() |
| if t.is_alive(): |
| self.terminate(proc) |
| t.join() |
| proc.wait() |
| self.returncode = proc.returncode |
| self.try_kill_process_by_pid() |
| |
| handler_time = time.time() - start_time |
| |
| if self.options.coverage: |
| subprocess.call(["GCOV_PREFIX=" + self.build_dir, |
| "gcov", self.sourcedir, "-b", "-s", self.build_dir], shell=True) |
| |
| # FIXME: This is needed when killing the simulator, the console is |
| # garbled and needs to be reset. Did not find a better way to do that. |
| if sys.stdout.isatty(): |
| subprocess.call(["stty", "sane"]) |
| |
| if harness.is_pytest: |
| harness.pytest_run(self.log) |
| |
| self.instance.execution_time = handler_time |
| if not self.terminated and self.returncode != 0: |
| self.instance.status = "failed" |
| if run_valgrind and self.returncode == 2: |
| self.instance.reason = "Valgrind error" |
| else: |
| # When a process is killed, the default handler returns 128 + SIGTERM |
| # so in that case the return code itself is not meaningful |
| self.instance.reason = "Failed" |
| elif harness.state: |
| self.instance.status = harness.state |
| if harness.state == "failed": |
| self.instance.reason = "Failed" |
| else: |
| self.instance.status = "failed" |
| self.instance.reason = "Timeout" |
| self.instance.add_missing_case_status("blocked", "Timeout") |
| |
| self._final_handle_actions(harness, handler_time) |
| |
| |
| class DeviceHandler(Handler): |
| |
| def __init__(self, instance, type_str): |
| """Constructor |
| |
| @param instance Test Instance |
| """ |
| super().__init__(instance, type_str) |
| |
| def monitor_serial(self, ser, halt_fileno, harness): |
| if harness.is_pytest: |
| harness.handle(None) |
| return |
| |
| log_out_fp = open(self.log, "wt") |
| |
| ser_fileno = ser.fileno() |
| readlist = [halt_fileno, ser_fileno] |
| |
| if self.options.coverage: |
| # Set capture_coverage to True to indicate that right after |
| # test results we should get coverage data, otherwise we exit |
| # from the test. |
| harness.capture_coverage = True |
| |
| ser.flush() |
| |
| while ser.isOpen(): |
| readable, _, _ = select.select(readlist, [], [], self.timeout) |
| |
| if halt_fileno in readable: |
| logger.debug('halted') |
| ser.close() |
| break |
| if ser_fileno not in readable: |
| continue # Timeout. |
| |
| serial_line = None |
| try: |
| serial_line = ser.readline() |
| except TypeError: |
| pass |
| # ignore SerialException which may happen during the serial device |
| # power off/on process. |
| except serial.SerialException: |
| pass |
| |
| # Just because ser_fileno has data doesn't mean an entire line |
| # is available yet. |
| if serial_line: |
| sl = serial_line.decode('utf-8', 'ignore').lstrip() |
| logger.debug("DEVICE: {0}".format(sl.rstrip())) |
| |
| log_out_fp.write(sl) |
| log_out_fp.flush() |
| harness.handle(sl.rstrip()) |
| |
| if harness.state: |
| if not harness.capture_coverage: |
| ser.close() |
| break |
| |
| log_out_fp.close() |
| |
| def device_is_available(self, instance): |
| device = instance.platform.name |
| fixture = instance.testsuite.harness_config.get("fixture") |
| for d in self.duts: |
| if fixture and fixture not in d.fixtures: |
| continue |
| if d.platform != device or (d.serial is None and d.serial_pty is None): |
| continue |
| d.lock.acquire() |
| avail = False |
| if d.available: |
| d.available = 0 |
| d.counter += 1 |
| avail = True |
| d.lock.release() |
| if avail: |
| return d |
| |
| return None |
| |
| def make_device_available(self, serial): |
| for d in self.duts: |
| if serial in [d.serial_pty, d.serial]: |
| d.available = 1 |
| |
| @staticmethod |
| def run_custom_script(script, timeout): |
| with subprocess.Popen(script, stderr=subprocess.PIPE, stdout=subprocess.PIPE) as proc: |
| try: |
| stdout, stderr = proc.communicate(timeout=timeout) |
| logger.debug(stdout.decode()) |
| if proc.returncode != 0: |
| logger.error(f"Custom script failure: {stderr.decode(errors='ignore')}") |
| |
| except subprocess.TimeoutExpired: |
| proc.kill() |
| proc.communicate() |
| logger.error("{} timed out".format(script)) |
| |
| def handle(self): |
| runner = None |
| |
| hardware = self.device_is_available(self.instance) |
| while not hardware: |
| logger.debug("Waiting for device {} to become available".format(self.instance.platform.name)) |
| time.sleep(1) |
| hardware = self.device_is_available(self.instance) |
| |
| runner = hardware.runner or self.options.west_runner |
| serial_pty = hardware.serial_pty |
| |
| ser_pty_process = None |
| if serial_pty: |
| master, slave = pty.openpty() |
| try: |
| ser_pty_process = subprocess.Popen(re.split(',| ', serial_pty), stdout=master, stdin=master, stderr=master) |
| except subprocess.CalledProcessError as error: |
| logger.error("Failed to run subprocess {}, error {}".format(serial_pty, error.output)) |
| return |
| |
| serial_device = os.ttyname(slave) |
| else: |
| serial_device = hardware.serial |
| |
| logger.debug(f"Using serial device {serial_device} @ {hardware.baud} baud") |
| |
| if (self.options.west_flash is not None) or runner: |
| command = ["west", "flash", "--skip-rebuild", "-d", self.build_dir] |
| command_extra_args = [] |
| |
| # There are three ways this option is used. |
| # 1) bare: --west-flash |
| # This results in options.west_flash == [] |
| # 2) with a value: --west-flash="--board-id=42" |
| # This results in options.west_flash == "--board-id=42" |
| # 3) Multiple values: --west-flash="--board-id=42,--erase" |
| # This results in options.west_flash == "--board-id=42 --erase" |
| if self.options.west_flash and self.options.west_flash != []: |
| command_extra_args.extend(self.options.west_flash.split(',')) |
| |
| if runner: |
| command.append("--runner") |
| command.append(runner) |
| |
| board_id = hardware.probe_id or hardware.id |
| product = hardware.product |
| if board_id is not None: |
| if runner == "pyocd": |
| command_extra_args.append("--board-id") |
| command_extra_args.append(board_id) |
| elif runner == "nrfjprog": |
| command_extra_args.append("--dev-id") |
| command_extra_args.append(board_id) |
| elif runner == "openocd" and product == "STM32 STLink": |
| command_extra_args.append("--cmd-pre-init") |
| command_extra_args.append("hla_serial %s" % (board_id)) |
| elif runner == "openocd" and product == "STLINK-V3": |
| command_extra_args.append("--cmd-pre-init") |
| command_extra_args.append("hla_serial %s" % (board_id)) |
| elif runner == "openocd" and product == "EDBG CMSIS-DAP": |
| command_extra_args.append("--cmd-pre-init") |
| command_extra_args.append("cmsis_dap_serial %s" % (board_id)) |
| elif runner == "jlink": |
| command.append("--tool-opt=-SelectEmuBySN %s" % (board_id)) |
| elif runner == "stm32cubeprogrammer": |
| command.append("--tool-opt=sn=%s" % (board_id)) |
| elif runner == "intel_adsp": |
| command.append("--pty") |
| |
| # Receive parameters from runner_params field. |
| if hardware.runner_params: |
| for param in hardware.runner_params: |
| command.append(param) |
| |
| if command_extra_args != []: |
| command.append('--') |
| command.extend(command_extra_args) |
| else: |
| command = [self.generator_cmd, "-C", self.build_dir, "flash"] |
| |
| pre_script = hardware.pre_script |
| post_flash_script = hardware.post_flash_script |
| post_script = hardware.post_script |
| |
| if pre_script: |
| self.run_custom_script(pre_script, 30) |
| |
| try: |
| ser = serial.Serial( |
| serial_device, |
| baudrate=hardware.baud, |
| parity=serial.PARITY_NONE, |
| stopbits=serial.STOPBITS_ONE, |
| bytesize=serial.EIGHTBITS, |
| timeout=self.timeout |
| ) |
| except serial.SerialException as e: |
| self.instance.status = "failed" |
| self.instance.reason = "Serial Device Error" |
| logger.error("Serial device error: %s" % (str(e))) |
| |
| self.instance.add_missing_case_status("blocked", "Serial Device Error") |
| if serial_pty and ser_pty_process: |
| ser_pty_process.terminate() |
| outs, errs = ser_pty_process.communicate() |
| logger.debug("Process {} terminated outs: {} errs {}".format(serial_pty, outs, errs)) |
| |
| if serial_pty: |
| self.make_device_available(serial_pty) |
| else: |
| self.make_device_available(serial_device) |
| return |
| |
| ser.flush() |
| |
| harness_name = self.instance.testsuite.harness.capitalize() |
| harness_import = HarnessImporter(harness_name) |
| harness = harness_import.instance |
| harness.configure(self.instance) |
| read_pipe, write_pipe = os.pipe() |
| start_time = time.time() |
| |
| t = threading.Thread(target=self.monitor_serial, daemon=True, |
| args=(ser, read_pipe, harness)) |
| t.start() |
| |
| d_log = "{}/device.log".format(self.instance.build_dir) |
| logger.debug('Flash command: %s', command) |
| flash_error = False |
| try: |
| stdout = stderr = None |
| with subprocess.Popen(command, stderr=subprocess.PIPE, stdout=subprocess.PIPE) as proc: |
| try: |
| (stdout, stderr) = proc.communicate(timeout=60) |
| # ignore unencodable unicode chars |
| logger.debug(stdout.decode(errors = "ignore")) |
| |
| if proc.returncode != 0: |
| self.instance.status = "error" |
| self.instance.reason = "Device issue (Flash error?)" |
| flash_error = True |
| with open(d_log, "w") as dlog_fp: |
| dlog_fp.write(stderr.decode()) |
| os.write(write_pipe, b'x') # halt the thread |
| except subprocess.TimeoutExpired: |
| logger.warning("Flash operation timed out.") |
| proc.kill() |
| (stdout, stderr) = proc.communicate() |
| self.instance.status = "error" |
| self.instance.reason = "Device issue (Timeout)" |
| flash_error = True |
| |
| with open(d_log, "w") as dlog_fp: |
| dlog_fp.write(stderr.decode()) |
| |
| except subprocess.CalledProcessError: |
| os.write(write_pipe, b'x') # halt the thread |
| |
| if post_flash_script: |
| self.run_custom_script(post_flash_script, 30) |
| |
| if not flash_error: |
| t.join(self.timeout) |
| if t.is_alive(): |
| logger.debug("Timed out while monitoring serial output on {}".format(self.instance.platform.name)) |
| |
| if ser.isOpen(): |
| ser.close() |
| |
| if serial_pty: |
| ser_pty_process.terminate() |
| outs, errs = ser_pty_process.communicate() |
| logger.debug("Process {} terminated outs: {} errs {}".format(serial_pty, outs, errs)) |
| |
| os.close(write_pipe) |
| os.close(read_pipe) |
| |
| handler_time = time.time() - start_time |
| |
| if harness.is_pytest: |
| harness.pytest_run(self.log) |
| |
| self.instance.execution_time = handler_time |
| if harness.state: |
| self.instance.status = harness.state |
| if harness.state == "failed": |
| self.instance.reason = "Failed" |
| elif not flash_error: |
| self.instance.status = "error" |
| self.instance.reason = "No Console Output(Timeout)" |
| |
| if self.instance.status == "error": |
| self.instance.add_missing_case_status("blocked", self.instance.reason) |
| |
| if not flash_error: |
| self._final_handle_actions(harness, handler_time) |
| |
| if post_script: |
| self.run_custom_script(post_script, 30) |
| |
| if serial_pty: |
| self.make_device_available(serial_pty) |
| else: |
| self.make_device_available(serial_device) |
| |
| class QEMUHandler(Handler): |
| """Spawns a thread to monitor QEMU output from pipes |
| |
| We pass QEMU_PIPE to 'make run' and monitor the pipes for output. |
| We need to do this as once qemu starts, it runs forever until killed. |
| Test cases emit special messages to the console as they run, we check |
| for these to collect whether the test passed or failed. |
| """ |
| |
| def __init__(self, instance, type_str): |
| """Constructor |
| |
| @param instance Test instance |
| """ |
| |
| super().__init__(instance, type_str) |
| self.fifo_fn = os.path.join(instance.build_dir, "qemu-fifo") |
| |
| self.pid_fn = os.path.join(instance.build_dir, "qemu.pid") |
| |
| if "ignore_qemu_crash" in instance.testsuite.tags: |
| self.ignore_qemu_crash = True |
| self.ignore_unexpected_eof = True |
| else: |
| self.ignore_qemu_crash = False |
| self.ignore_unexpected_eof = False |
| |
| @staticmethod |
| def _get_cpu_time(pid): |
| """get process CPU time. |
| |
| The guest virtual time in QEMU icount mode isn't host time and |
| it's maintained by counting guest instructions, so we use QEMU |
| process execution time to mostly simulate the time of guest OS. |
| """ |
| proc = psutil.Process(pid) |
| cpu_time = proc.cpu_times() |
| return cpu_time.user + cpu_time.system |
| |
| @staticmethod |
| def _thread(handler, timeout, outdir, logfile, fifo_fn, pid_fn, results, harness, |
| ignore_unexpected_eof=False): |
| fifo_in = fifo_fn + ".in" |
| fifo_out = fifo_fn + ".out" |
| |
| # These in/out nodes are named from QEMU's perspective, not ours |
| if os.path.exists(fifo_in): |
| os.unlink(fifo_in) |
| os.mkfifo(fifo_in) |
| if os.path.exists(fifo_out): |
| os.unlink(fifo_out) |
| os.mkfifo(fifo_out) |
| |
| # We don't do anything with out_fp but we need to open it for |
| # writing so that QEMU doesn't block, due to the way pipes work |
| out_fp = open(fifo_in, "wb") |
| # Disable internal buffering, we don't |
| # want read() or poll() to ever block if there is data in there |
| in_fp = open(fifo_out, "rb", buffering=0) |
| log_out_fp = open(logfile, "wt") |
| |
| start_time = time.time() |
| timeout_time = start_time + timeout |
| p = select.poll() |
| p.register(in_fp, select.POLLIN) |
| out_state = None |
| |
| line = "" |
| timeout_extended = False |
| |
| pid = 0 |
| if os.path.exists(pid_fn): |
| pid = int(open(pid_fn).read()) |
| |
| while True: |
| this_timeout = int((timeout_time - time.time()) * 1000) |
| if this_timeout < 0 or not p.poll(this_timeout): |
| try: |
| if pid and this_timeout > 0: |
| #there's possibility we polled nothing because |
| #of not enough CPU time scheduled by host for |
| #QEMU process during p.poll(this_timeout) |
| cpu_time = QEMUHandler._get_cpu_time(pid) |
| if cpu_time < timeout and not out_state: |
| timeout_time = time.time() + (timeout - cpu_time) |
| continue |
| except ProcessLookupError: |
| out_state = "failed" |
| break |
| |
| if not out_state: |
| out_state = "timeout" |
| break |
| |
| if pid == 0 and os.path.exists(pid_fn): |
| pid = int(open(pid_fn).read()) |
| |
| if harness.is_pytest: |
| harness.handle(None) |
| out_state = harness.state |
| break |
| |
| try: |
| c = in_fp.read(1).decode("utf-8") |
| except UnicodeDecodeError: |
| # Test is writing something weird, fail |
| out_state = "unexpected byte" |
| break |
| |
| if c == "": |
| # EOF, this shouldn't happen unless QEMU crashes |
| if not ignore_unexpected_eof: |
| out_state = "unexpected eof" |
| break |
| line = line + c |
| if c != "\n": |
| continue |
| |
| # line contains a full line of data output from QEMU |
| log_out_fp.write(line) |
| log_out_fp.flush() |
| line = line.strip() |
| logger.debug(f"QEMU ({pid}): {line}") |
| |
| harness.handle(line) |
| if harness.state: |
| # if we have registered a fail make sure the state is not |
| # overridden by a false success message coming from the |
| # testsuite |
| if out_state not in ['failed', 'unexpected eof', 'unexpected byte']: |
| out_state = harness.state |
| |
| # if we get some state, that means test is doing well, we reset |
| # the timeout and wait for 2 more seconds to catch anything |
| # printed late. We wait much longer if code |
| # coverage is enabled since dumping this information can |
| # take some time. |
| if not timeout_extended or harness.capture_coverage: |
| timeout_extended = True |
| if harness.capture_coverage: |
| timeout_time = time.time() + 30 |
| else: |
| timeout_time = time.time() + 2 |
| line = "" |
| |
| if harness.is_pytest: |
| harness.pytest_run(logfile) |
| out_state = harness.state |
| |
| handler_time = time.time() - start_time |
| logger.debug(f"QEMU ({pid}) complete ({out_state}) after {handler_time} seconds") |
| |
| handler.instance.execution_time = handler_time |
| if out_state == "timeout": |
| handler.instance.status = "failed" |
| handler.instance.reason = "Timeout" |
| elif out_state == "failed": |
| handler.instance.status = "failed" |
| handler.instance.reason = "Failed" |
| elif out_state in ['unexpected eof', 'unexpected byte']: |
| handler.instance.status = "failed" |
| handler.instance.reason = out_state |
| else: |
| handler.instance.status = out_state |
| handler.instance.reason = "Unknown" |
| |
| log_out_fp.close() |
| out_fp.close() |
| in_fp.close() |
| if pid: |
| try: |
| if pid: |
| os.kill(pid, signal.SIGTERM) |
| except ProcessLookupError: |
| # Oh well, as long as it's dead! User probably sent Ctrl-C |
| pass |
| |
| os.unlink(fifo_in) |
| os.unlink(fifo_out) |
| |
| def handle(self): |
| self.results = {} |
| self.run = True |
| |
| # We pass this to QEMU which looks for fifos with .in and .out |
| # suffixes. |
| |
| self.fifo_fn = os.path.join(self.instance.build_dir, "qemu-fifo") |
| self.pid_fn = os.path.join(self.instance.build_dir, "qemu.pid") |
| |
| if os.path.exists(self.pid_fn): |
| os.unlink(self.pid_fn) |
| |
| self.log_fn = self.log |
| |
| harness_import = HarnessImporter(self.instance.testsuite.harness.capitalize()) |
| harness = harness_import.instance |
| harness.configure(self.instance) |
| |
| self.thread = threading.Thread(name=self.name, target=QEMUHandler._thread, |
| args=(self, self.timeout, self.build_dir, |
| self.log_fn, self.fifo_fn, |
| self.pid_fn, self.results, harness, |
| self.ignore_unexpected_eof)) |
| |
| self.thread.daemon = True |
| logger.debug("Spawning QEMUHandler Thread for %s" % self.name) |
| self.thread.start() |
| if sys.stdout.isatty(): |
| subprocess.call(["stty", "sane"]) |
| |
| logger.debug("Running %s (%s)" % (self.name, self.type_str)) |
| command = [self.generator_cmd] |
| command += ["-C", self.build_dir, "run"] |
| |
| is_timeout = False |
| qemu_pid = None |
| |
| with subprocess.Popen(command, stdout=subprocess.PIPE, stderr=subprocess.PIPE, cwd=self.build_dir) as proc: |
| logger.debug("Spawning QEMUHandler Thread for %s" % self.name) |
| |
| try: |
| proc.wait(self.timeout) |
| except subprocess.TimeoutExpired: |
| # sometimes QEMU can't handle SIGTERM signal correctly |
| # in that case kill -9 QEMU process directly and leave |
| # twister to judge testing result by console output |
| |
| is_timeout = True |
| self.terminate(proc) |
| if harness.state == "passed": |
| self.returncode = 0 |
| else: |
| self.returncode = proc.returncode |
| else: |
| if os.path.exists(self.pid_fn): |
| qemu_pid = int(open(self.pid_fn).read()) |
| logger.debug(f"No timeout, return code from QEMU ({qemu_pid}): {proc.returncode}") |
| self.returncode = proc.returncode |
| # Need to wait for harness to finish processing |
| # output from QEMU. Otherwise it might miss some |
| # error messages. |
| self.thread.join(0) |
| if self.thread.is_alive(): |
| logger.debug("Timed out while monitoring QEMU output") |
| |
| if os.path.exists(self.pid_fn): |
| qemu_pid = int(open(self.pid_fn).read()) |
| os.unlink(self.pid_fn) |
| |
| logger.debug(f"return code from QEMU ({qemu_pid}): {self.returncode}") |
| |
| if (self.returncode != 0 and not self.ignore_qemu_crash) or not harness.state: |
| self.instance.status = "failed" |
| if is_timeout: |
| self.instance.reason = "Timeout" |
| else: |
| if not self.instance.reason: |
| self.instance.reason = "Exited with {}".format(self.returncode) |
| self.instance.add_missing_case_status("blocked") |
| |
| self._final_handle_actions(harness, 0) |
| |
| def get_fifo(self): |
| return self.fifo_fn |
