From 79e78fb31d84d0e55eda47603d76d413d48544a1 Mon Sep 17 00:00:00 2001 From: Peter Hoyes Date: Tue, 15 Nov 2022 15:01:15 +0000 Subject: [PATCH] arm/oeqa: Log the FVP output in OEFVPSSHTarget It is often useful to inspect the FVP output after running the tests. Refactor OEFVPSerialTarget._create_logfile into OEFVPSSHTarget._create_log_filename, so that all FVP test controllers are able to create secondary log files. Pass a filehandle to the stdout argument of run_fvp so that the FVP output is asynchronously logged to a file. Change the port parsing logic to read back from the same log file instead of reading the stdout directly. Issue-Id: SCM-5314 Signed-off-by: Peter Hoyes Change-Id: I2ddb423fa0d896c13d3e96884858c680c4d34555 Signed-off-by: Jon Mason --- documentation/oeqa-fvp.md | 2 +- meta-arm/lib/fvp/runner.py | 4 +- meta-arm/lib/oeqa/controllers/fvp.py | 95 +++++++++++++++------------- 3 files changed, 53 insertions(+), 48 deletions(-) diff --git a/documentation/oeqa-fvp.md b/documentation/oeqa-fvp.md index 582dd38b..e1468851 100644 --- a/documentation/oeqa-fvp.md +++ b/documentation/oeqa-fvp.md @@ -4,7 +4,7 @@ OE-Core's [oeqa][OEQA] framework provides a method of performing runtime tests o Tests can be configured to run automatically post-build by setting the variable `TESTIMAGE_AUTO="1"`, e.g. in your Kas file or local.conf. -There are two main methods of testing, using different test "targets". +There are two main methods of testing, using different test "targets". Both test targets generate an additional log file with the prefix 'fvp_log' in the image recipe's `${WORKDIR}/testimage` containing the FVP's stdout. ## OEFVPTarget diff --git a/meta-arm/lib/fvp/runner.py b/meta-arm/lib/fvp/runner.py index 5c5ded28..f55c579d 100644 --- a/meta-arm/lib/fvp/runner.py +++ b/meta-arm/lib/fvp/runner.py @@ -77,7 +77,7 @@ class FVPRunner: self._telnets = [] self._pexpects = [] - def start(self, config, extra_args=[], terminal_choice="none"): + def start(self, config, extra_args=[], terminal_choice="none", stdout=subprocess.PIPE): cli = cli_from_config(config, terminal_choice) cli += extra_args @@ -91,7 +91,7 @@ class FVPRunner: self._logger.debug(f"Constructed FVP call: {shlex.join(cli)}") self._fvp_process = subprocess.Popen( cli, - stdin=subprocess.DEVNULL, stdout=subprocess.PIPE, stderr=subprocess.STDOUT, + stdin=subprocess.DEVNULL, stdout=stdout, stderr=subprocess.STDOUT, env=env) def stop(self): diff --git a/meta-arm/lib/oeqa/controllers/fvp.py b/meta-arm/lib/oeqa/controllers/fvp.py index 0c3c2214..e8a094f1 100644 --- a/meta-arm/lib/oeqa/controllers/fvp.py +++ b/meta-arm/lib/oeqa/controllers/fvp.py @@ -12,7 +12,7 @@ class OEFVPSSHTarget(OESSHTarget): Contains common logic to start and stop an FVP. """ def __init__(self, logger, target_ip, server_ip, timeout=300, user='root', - port=None, dir_image=None, rootfs=None, **kwargs): + port=None, dir_image=None, rootfs=None, bootlog=None, **kwargs): super().__init__(logger, target_ip, server_ip, timeout, user, port) image_dir = pathlib.Path(dir_image) # rootfs may have multiple extensions so we need to strip *all* suffixes @@ -20,6 +20,7 @@ class OEFVPSSHTarget(OESSHTarget): basename = basename.name.replace("".join(basename.suffixes), "") self.fvpconf = image_dir / (basename + ".fvpconf") self.config = conffile.load(self.fvpconf) + self.bootlog = bootlog if not self.fvpconf.exists(): raise FileNotFoundError(f"Cannot find {self.fvpconf}") @@ -28,8 +29,9 @@ class OEFVPSSHTarget(OESSHTarget): pass def start(self, **kwargs): + self.fvp_log = self._create_logfile("fvp") self.fvp = runner.FVPRunner(self.logger) - self.fvp.start(self.config) + self.fvp.start(self.config, stdout=self.fvp_log) self.logger.debug(f"Started FVP PID {self.fvp.pid()}") self._after_start() @@ -37,6 +39,22 @@ class OEFVPSSHTarget(OESSHTarget): returncode = self.fvp.stop() self.logger.debug(f"Stopped FVP with return code {returncode}") + def _create_logfile(self, name): + if not self.bootlog: + return None + + test_log_path = pathlib.Path(self.bootlog).parent + test_log_suffix = pathlib.Path(self.bootlog).suffix + fvp_log_file = f"{name}_log{test_log_suffix}" + fvp_log_path = pathlib.Path(test_log_path, fvp_log_file) + fvp_log_symlink = pathlib.Path(test_log_path, f"{name}_log") + try: + os.remove(fvp_log_symlink) + except: + pass + os.symlink(fvp_log_file, fvp_log_symlink) + return open(fvp_log_path, 'wb') + class OEFVPTarget(OEFVPSSHTarget): """ @@ -44,33 +62,34 @@ class OEFVPTarget(OEFVPSSHTarget): waits for a Linux shell before returning to ensure that SSH commands work with the default test dependencies. """ - def __init__(self, logger, target_ip, server_ip, bootlog=None, **kwargs): + def __init__(self, logger, target_ip, server_ip, **kwargs): super().__init__(logger, target_ip, server_ip, **kwargs) - self.logfile = bootlog and open(bootlog, "wb") or None + self.logfile = self.bootlog and open(self.bootlog, "wb") or None # FVPs boot slowly, so allow ten minutes self.boot_timeout = 10 * 60 def _after_start(self): - parser = runner.ConsolePortParser(self.fvp.stdout) - self.logger.debug(f"Awaiting console on terminal {self.config['consoles']['default']}") - port = parser.parse_port(self.config['consoles']['default']) - console = self.fvp.create_pexpect(port) - try: - console.expect("login\\:", timeout=self.boot_timeout) - self.logger.debug("Found login prompt") - except pexpect.TIMEOUT: - self.logger.info("Timed out waiting for login prompt.") - self.logger.info("Boot log follows:") - self.logger.info(b"\n".join(console.before.splitlines()[-200:]).decode("utf-8", errors="replace")) - raise RuntimeError("Failed to start FVP.") + with open(self.fvp_log.name, 'rb') as logfile: + parser = runner.ConsolePortParser(logfile) + self.logger.debug(f"Awaiting console on terminal {self.config['consoles']['default']}") + port = parser.parse_port(self.config['consoles']['default']) + console = self.fvp.create_pexpect(port) + try: + console.expect("login\\:", timeout=self.boot_timeout) + self.logger.debug("Found login prompt") + except pexpect.TIMEOUT: + self.logger.info("Timed out waiting for login prompt.") + self.logger.info("Boot log follows:") + self.logger.info(b"\n".join(console.before.splitlines()[-200:]).decode("utf-8", errors="replace")) + raise RuntimeError("Failed to start FVP.") class OEFVPSerialTarget(OEFVPSSHTarget): """ This target is intended for interaction with the target over one or more telnet consoles using pexpect. - + This still depends on OEFVPSSHTarget so SSH commands can still be run on the target, but note that this class does not inherently guarantee that the SSH server is running prior to running test cases. Test cases that use @@ -79,39 +98,25 @@ class OEFVPSerialTarget(OEFVPSSHTarget): """ DEFAULT_CONSOLE = "default" - def __init__(self, logger, target_ip, server_ip, bootlog=None, **kwargs): + def __init__(self, logger, target_ip, server_ip, **kwargs): super().__init__(logger, target_ip, server_ip, **kwargs) self.terminals = {} - self.test_log_path = pathlib.Path(bootlog).parent - self.test_log_suffix = pathlib.Path(bootlog).suffix - self.bootlog = bootlog - - def _create_logfile(self, name): - fvp_log_file = f"{name}_log{self.test_log_suffix}" - fvp_log_path = pathlib.Path(self.test_log_path, fvp_log_file) - fvp_log_symlink = pathlib.Path(self.test_log_path, f"{name}_log") - try: - os.remove(fvp_log_symlink) - except: - pass - os.symlink(fvp_log_file, fvp_log_symlink) - return open(fvp_log_path, 'wb') - def _after_start(self): - parser = runner.ConsolePortParser(self.fvp.stdout) - for name, console in self.config["consoles"].items(): - logfile = self._create_logfile(name) - self.logger.info(f'Creating terminal {name} on {console}') - port = parser.parse_port(console) - self.terminals[name] = \ - self.fvp.create_pexpect(port, logfile=logfile) + with open(self.fvp_log.name, 'rb') as logfile: + parser = runner.ConsolePortParser(logfile) + for name, console in self.config["consoles"].items(): + logfile = self._create_logfile(name) + self.logger.info(f'Creating terminal {name} on {console}') + port = parser.parse_port(console) + self.terminals[name] = \ + self.fvp.create_pexpect(port, logfile=logfile) - # testimage.bbclass expects to see a log file at `bootlog`, - # so make a symlink to the 'default' log file - if name == 'default': - default_test_file = f"{name}_log{self.test_log_suffix}" - os.symlink(default_test_file, self.bootlog) + # testimage.bbclass expects to see a log file at `bootlog`, + # so make a symlink to the 'default' log file + if name == 'default': + default_test_file = f"{name}_log{self.test_log_suffix}" + os.symlink(default_test_file, self.bootlog) def _get_terminal(self, name): return self.terminals[name]