From patchwork Tue Nov 15 15:01:12 2022 Content-Type: text/plain; charset="utf-8" MIME-Version: 1.0 Content-Transfer-Encoding: 7bit X-Patchwork-Submitter: Peter Hoyes X-Patchwork-Id: 15489 Return-Path: X-Spam-Checker-Version: SpamAssassin 3.4.0 (2014-02-07) on aws-us-west-2-korg-lkml-1.web.codeaurora.org Received: from aws-us-west-2-korg-lkml-1.web.codeaurora.org (localhost.localdomain [127.0.0.1]) by smtp.lore.kernel.org (Postfix) with ESMTP id 5403DC43217 for ; Tue, 15 Nov 2022 15:01:37 +0000 (UTC) Received: from foss.arm.com (foss.arm.com [217.140.110.172]) by mx.groups.io with SMTP id smtpd.web12.6492.1668524492269866330 for ; Tue, 15 Nov 2022 07:01:32 -0800 Authentication-Results: mx.groups.io; dkim=missing; spf=pass (domain: arm.com, ip: 217.140.110.172, mailfrom: peter.hoyes@arm.com) Received: from usa-sjc-imap-foss1.foss.arm.com (unknown [10.121.207.14]) by usa-sjc-mx-foss1.foss.arm.com (Postfix) with ESMTP id 9F88413D5; Tue, 15 Nov 2022 07:01:37 -0800 (PST) Received: from e125920.cambridge.arm.com (unknown [10.1.199.64]) by usa-sjc-imap-foss1.foss.arm.com (Postfix) with ESMTPSA id DEF353F587; Tue, 15 Nov 2022 07:01:30 -0800 (PST) From: Peter Hoyes To: meta-arm@lists.yoctoproject.org Cc: Peter Hoyes Subject: [PATCH 1/5] arm/fvp: Join cli arguments in verbose logging Date: Tue, 15 Nov 2022 15:01:12 +0000 Message-Id: <20221115150116.314729-1-peter.hoyes@arm.com> X-Mailer: git-send-email 2.25.1 MIME-Version: 1.0 List-Id: X-Webhook-Received: from li982-79.members.linode.com [45.33.32.79] by aws-us-west-2-korg-lkml-1.web.codeaurora.org with HTTPS for ; Tue, 15 Nov 2022 15:01:37 -0000 X-Groupsio-URL: https://lists.yoctoproject.org/g/meta-arm/message/4129 From: Peter Hoyes It is sometimes helpful to copy and paste the cli arguments from the verbose runfvp output (e.g. to test with a development FVP build), but currently the arguments are printed as a Python list. Use shlex.join(cli) to safely join the arguments together in form that can be reused directly in a shell. Issue-Id: SCM-5314 Signed-off-by: Peter Hoyes Change-Id: Ibb5c5ed45d02e241cb3858f68740fb9d4e89357a --- meta-arm/lib/fvp/runner.py | 3 ++- 1 file changed, 2 insertions(+), 1 deletion(-) diff --git a/meta-arm/lib/fvp/runner.py b/meta-arm/lib/fvp/runner.py index 28351a39..f5c61f8b 100644 --- a/meta-arm/lib/fvp/runner.py +++ b/meta-arm/lib/fvp/runner.py @@ -2,6 +2,7 @@ import asyncio import re import subprocess import os +import shlex import shutil import sys @@ -67,7 +68,7 @@ class FVPRunner: if name in os.environ: env[name] = os.environ[name] - self._logger.debug(f"Constructed FVP call: {cli}") + self._logger.debug(f"Constructed FVP call: {shlex.join(cli)}") self._fvp_process = await asyncio.create_subprocess_exec( *cli, stdin=subprocess.DEVNULL, stdout=subprocess.PIPE, stderr=subprocess.STDOUT, From patchwork Tue Nov 15 15:01:13 2022 Content-Type: text/plain; charset="utf-8" MIME-Version: 1.0 Content-Transfer-Encoding: 7bit X-Patchwork-Submitter: Peter Hoyes X-Patchwork-Id: 15490 Return-Path: X-Spam-Checker-Version: SpamAssassin 3.4.0 (2014-02-07) on aws-us-west-2-korg-lkml-1.web.codeaurora.org Received: from aws-us-west-2-korg-lkml-1.web.codeaurora.org (localhost.localdomain [127.0.0.1]) by smtp.lore.kernel.org (Postfix) with ESMTP id 52DE6C4332F for ; Tue, 15 Nov 2022 15:01:37 +0000 (UTC) Received: from foss.arm.com (foss.arm.com [217.140.110.172]) by mx.groups.io with SMTP id smtpd.web11.6502.1668524495722025218 for ; Tue, 15 Nov 2022 07:01:35 -0800 Authentication-Results: mx.groups.io; dkim=missing; spf=pass (domain: arm.com, ip: 217.140.110.172, mailfrom: peter.hoyes@arm.com) Received: from usa-sjc-imap-foss1.foss.arm.com (unknown [10.121.207.14]) by usa-sjc-mx-foss1.foss.arm.com (Postfix) with ESMTP id A670D13D5; Tue, 15 Nov 2022 07:01:41 -0800 (PST) Received: from e125920.cambridge.arm.com (unknown [10.1.199.64]) by usa-sjc-imap-foss1.foss.arm.com (Postfix) with ESMTPSA id CC6B63F587; Tue, 15 Nov 2022 07:01:34 -0800 (PST) From: Peter Hoyes To: meta-arm@lists.yoctoproject.org Cc: Peter Hoyes Subject: [PATCH 2/5] arm/lib: Factor out asyncio in FVPRunner Date: Tue, 15 Nov 2022 15:01:13 +0000 Message-Id: <20221115150116.314729-2-peter.hoyes@arm.com> X-Mailer: git-send-email 2.25.1 In-Reply-To: <20221115150116.314729-1-peter.hoyes@arm.com> References: <20221115150116.314729-1-peter.hoyes@arm.com> MIME-Version: 1.0 List-Id: X-Webhook-Received: from li982-79.members.linode.com [45.33.32.79] by aws-us-west-2-korg-lkml-1.web.codeaurora.org with HTTPS for ; Tue, 15 Nov 2022 15:01:37 -0000 X-Groupsio-URL: https://lists.yoctoproject.org/g/meta-arm/message/4130 From: Peter Hoyes FVPRunner relies heavily on asyncio, despite there being very little concurrent work happening. Additionally, while the runfvp entry point starts an asyncio runner, it is not practical to have a single asyncio runtime during testimage, which is fully synchronous. Refactor to use subprocess.Popen and related functionality. The process object has a similar interface to its async equivalent. Cascade the API changes to runfvp and the test target classes. Issue-Id: SCM-5314 Signed-off-by: Peter Hoyes Change-Id: I3e7517e8bcbb3b93c41405d43dbd8bd24a9e7eb8 --- meta-arm/lib/fvp/runner.py | 35 +++++++++--------- meta-arm/lib/oeqa/controllers/fvp.py | 41 +++++++--------------- meta-arm/lib/oeqa/selftest/cases/runfvp.py | 16 ++++----- scripts/runfvp | 23 +++++------- 4 files changed, 46 insertions(+), 69 deletions(-) diff --git a/meta-arm/lib/fvp/runner.py b/meta-arm/lib/fvp/runner.py index f5c61f8b..9b537e27 100644 --- a/meta-arm/lib/fvp/runner.py +++ b/meta-arm/lib/fvp/runner.py @@ -1,4 +1,3 @@ -import asyncio import re import subprocess import os @@ -57,7 +56,7 @@ class FVPRunner: def add_line_callback(self, callback): self._line_callbacks.append(callback) - async def start(self, config, extra_args=[], terminal_choice="none"): + def start(self, config, extra_args=[], terminal_choice="none"): cli = cli_from_config(config, terminal_choice) cli += extra_args @@ -69,8 +68,8 @@ class FVPRunner: env[name] = os.environ[name] self._logger.debug(f"Constructed FVP call: {shlex.join(cli)}") - self._fvp_process = await asyncio.create_subprocess_exec( - *cli, + self._fvp_process = subprocess.Popen( + cli, stdin=subprocess.DEVNULL, stdout=subprocess.PIPE, stderr=subprocess.STDOUT, env=env) @@ -82,13 +81,13 @@ class FVPRunner: self._terminal_ports[terminal] = port self.add_line_callback(detect_terminals) - async def stop(self): + def stop(self): if self._fvp_process: self._logger.debug(f"Terminating FVP PID {self._fvp_process.pid}") try: self._fvp_process.terminate() - await asyncio.wait_for(self._fvp_process.wait(), 10.0) - except asyncio.TimeoutError: + self._fvp_process.wait(10.0) + except subprocess.TimeoutExpired: self._logger.debug(f"Killing FVP PID {self._fvp_process.pid}") self._fvp_process.kill() except ProcessLookupError: @@ -97,8 +96,8 @@ class FVPRunner: for telnet in self._telnets: try: telnet.terminate() - await asyncio.wait_for(telnet.wait(), 10.0) - except asyncio.TimeoutError: + telnet.wait(10.0) + except subprocess.TimeoutExpired: telnet.kill() except ProcessLookupError: pass @@ -118,34 +117,34 @@ class FVPRunner: else: return 0 - async def run(self, until=None): + def run(self, until=None): if until and until(): return - async for line in self._fvp_process.stdout: + for line in self._fvp_process.stdout: line = line.strip().decode("utf-8", errors="replace") for callback in self._line_callbacks: callback(line) if until and until(): return - async def _get_terminal_port(self, terminal, timeout): + def _get_terminal_port(self, terminal): def terminal_exists(): return terminal in self._terminal_ports - await asyncio.wait_for(self.run(terminal_exists), timeout) + self.run(terminal_exists) return self._terminal_ports[terminal] - async def create_telnet(self, terminal, timeout=15.0): + def create_telnet(self, terminal): check_telnet() - port = await self._get_terminal_port(terminal, timeout) - telnet = await asyncio.create_subprocess_exec("telnet", "localhost", str(port), stdin=sys.stdin, stdout=sys.stdout) + port = self._get_terminal_port(terminal) + telnet = subprocess.Popen(["telnet", "localhost", str(port)], stdin=sys.stdin, stdout=sys.stdout) self._telnets.append(telnet) return telnet - async def create_pexpect(self, terminal, timeout=15.0, **kwargs): + def create_pexpect(self, terminal, **kwargs): check_telnet() import pexpect - port = await self._get_terminal_port(terminal, timeout) + port = self._get_terminal_port(terminal) instance = pexpect.spawn(f"telnet localhost {port}", **kwargs) self._pexpects.append(instance) return instance diff --git a/meta-arm/lib/oeqa/controllers/fvp.py b/meta-arm/lib/oeqa/controllers/fvp.py index c8dcf298..dfc2b88b 100644 --- a/meta-arm/lib/oeqa/controllers/fvp.py +++ b/meta-arm/lib/oeqa/controllers/fvp.py @@ -1,4 +1,3 @@ -import asyncio import pathlib import pexpect import os @@ -25,32 +24,18 @@ class OEFVPSSHTarget(OESSHTarget): if not self.fvpconf.exists(): raise FileNotFoundError(f"Cannot find {self.fvpconf}") - async def boot_fvp(self): - self.fvp = runner.FVPRunner(self.logger) - await self.fvp.start(self.config) - self.logger.debug(f"Started FVP PID {self.fvp.pid()}") - await self._after_start() - - async def _after_start(self): + def _after_start(self): pass - async def _after_stop(self): - pass - - async def stop_fvp(self): - returncode = await self.fvp.stop() - await self._after_stop() - - self.logger.debug(f"Stopped FVP with return code {returncode}") - def start(self, **kwargs): - # When we can assume Py3.7+, this can simply be asyncio.run() - loop = asyncio.get_event_loop() - loop.run_until_complete(asyncio.gather(self.boot_fvp())) + self.fvp = runner.FVPRunner(self.logger) + self.fvp.start(self.config) + self.logger.debug(f"Started FVP PID {self.fvp.pid()}") + self._after_start() def stop(self, **kwargs): - loop = asyncio.get_event_loop() - loop.run_until_complete(asyncio.gather(self.stop_fvp())) + returncode = self.fvp.stop() + self.logger.debug(f"Stopped FVP with return code {returncode}") class OEFVPTarget(OEFVPSSHTarget): @@ -66,9 +51,9 @@ class OEFVPTarget(OEFVPSSHTarget): # FVPs boot slowly, so allow ten minutes self.boot_timeout = 10 * 60 - async def _after_start(self): + def _after_start(self): self.logger.debug(f"Awaiting console on terminal {self.config['consoles']['default']}") - console = await self.fvp.create_pexpect(self.config['consoles']['default']) + console = self.fvp.create_pexpect(self.config['consoles']['default']) try: console.expect("login\\:", timeout=self.boot_timeout) self.logger.debug("Found login prompt") @@ -100,11 +85,11 @@ class OEFVPSerialTarget(OEFVPSSHTarget): self.test_log_suffix = pathlib.Path(bootlog).suffix self.bootlog = bootlog - async def _add_terminal(self, name, fvp_name): + def _add_terminal(self, name, fvp_name): logfile = self._create_logfile(name) self.logger.info(f'Creating terminal {name} on {fvp_name}') self.terminals[name] = \ - await self.fvp.create_pexpect(fvp_name, logfile=logfile) + self.fvp.create_pexpect(fvp_name, logfile=logfile) def _create_logfile(self, name): fvp_log_file = f"{name}_log{self.test_log_suffix}" @@ -117,9 +102,9 @@ class OEFVPSerialTarget(OEFVPSSHTarget): os.symlink(fvp_log_file, fvp_log_symlink) return open(fvp_log_path, 'wb') - async def _after_start(self): + def _after_start(self): for name, console in self.config["consoles"].items(): - await self._add_terminal(name, console) + self._add_terminal(name, console) # testimage.bbclass expects to see a log file at `bootlog`, # so make a symlink to the 'default' log file diff --git a/meta-arm/lib/oeqa/selftest/cases/runfvp.py b/meta-arm/lib/oeqa/selftest/cases/runfvp.py index cf8a3c53..5cc8660f 100644 --- a/meta-arm/lib/oeqa/selftest/cases/runfvp.py +++ b/meta-arm/lib/oeqa/selftest/cases/runfvp.py @@ -81,13 +81,13 @@ class ConfFileTests(OESelftestTestCase): class RunnerTests(OESelftestTestCase): def create_mock(self): - return unittest.mock.patch("asyncio.create_subprocess_exec") + return unittest.mock.patch("subprocess.Popen") def test_start(self): from fvp import runner with self.create_mock() as m: fvp = runner.FVPRunner(self.logger) - asyncio.run(fvp.start({ + fvp.start({ "fvp-bindir": "/usr/bin", "exe": "FVP_Binary", "parameters": {'foo': 'bar'}, @@ -96,13 +96,13 @@ class RunnerTests(OESelftestTestCase): "terminals": {}, "args": ['--extra-arg'], "env": {"FOO": "BAR"} - })) + }) - m.assert_called_once_with('/usr/bin/FVP_Binary', + m.assert_called_once_with(['/usr/bin/FVP_Binary', '--parameter', 'foo=bar', '--data', 'data1', '--application', 'a1=file', - '--extra-arg', + '--extra-arg'], stdin=unittest.mock.ANY, stdout=unittest.mock.ANY, stderr=unittest.mock.ANY, @@ -113,7 +113,7 @@ class RunnerTests(OESelftestTestCase): from fvp import runner with self.create_mock() as m: fvp = runner.FVPRunner(self.logger) - asyncio.run(fvp.start({ + fvp.start({ "fvp-bindir": "/usr/bin", "exe": "FVP_Binary", "parameters": {}, @@ -122,9 +122,9 @@ class RunnerTests(OESelftestTestCase): "terminals": {}, "args": [], "env": {"FOO": "BAR"} - })) + }) - m.assert_called_once_with('/usr/bin/FVP_Binary', + m.assert_called_once_with(['/usr/bin/FVP_Binary'], stdin=unittest.mock.ANY, stdout=unittest.mock.ANY, stderr=unittest.mock.ANY, diff --git a/scripts/runfvp b/scripts/runfvp index c5a74b2f..727223ca 100755 --- a/scripts/runfvp +++ b/scripts/runfvp @@ -1,6 +1,5 @@ #! /usr/bin/env python3 -import asyncio import os import pathlib import signal @@ -47,11 +46,10 @@ def parse_args(arguments): logger.debug(f"FVP arguments: {fvp_args}") return args, fvp_args - -async def start_fvp(args, config, extra_args): +def start_fvp(args, config, extra_args): fvp = runner.FVPRunner(logger) try: - await fvp.start(config, extra_args, args.terminals) + fvp.start(config, extra_args, args.terminals) if args.console: fvp.add_line_callback(lambda line: logger.debug(f"FVP output: {line}")) @@ -59,15 +57,16 @@ async def start_fvp(args, config, extra_args): if not expected_terminal: logger.error("--console used but FVP_CONSOLE not set in machine configuration") return 1 - telnet = await fvp.create_telnet(expected_terminal) - await telnet.wait() + telnet = fvp.create_telnet(expected_terminal) + telnet.wait() logger.debug(f"Telnet quit, cancelling tasks") else: fvp.add_line_callback(lambda line: print(line)) - await fvp.run() + fvp.run() finally: - await fvp.stop() + fvp.stop() + def runfvp(cli_args): args, extra_args = parse_args(cli_args) @@ -77,14 +76,8 @@ def runfvp(cli_args): config_file = conffile.find(args.config) logger.debug(f"Loading {config_file}") config = conffile.load(config_file) + start_fvp(args, config, extra_args) - try: - # When we can assume Py3.7+, this can simply be asyncio.run() - loop = asyncio.get_event_loop() - return loop.run_until_complete(start_fvp(args, config, extra_args)) - except asyncio.CancelledError: - # This means telnet exited, which isn't an error - return 0 if __name__ == "__main__": try: From patchwork Tue Nov 15 15:01:14 2022 Content-Type: text/plain; charset="utf-8" MIME-Version: 1.0 Content-Transfer-Encoding: 7bit X-Patchwork-Submitter: Peter Hoyes X-Patchwork-Id: 15492 Return-Path: X-Spam-Checker-Version: SpamAssassin 3.4.0 (2014-02-07) on aws-us-west-2-korg-lkml-1.web.codeaurora.org Received: from aws-us-west-2-korg-lkml-1.web.codeaurora.org (localhost.localdomain [127.0.0.1]) by smtp.lore.kernel.org (Postfix) with ESMTP id 42038C433FE for ; Tue, 15 Nov 2022 15:01:47 +0000 (UTC) Received: from foss.arm.com (foss.arm.com [217.140.110.172]) by mx.groups.io with SMTP id smtpd.web11.6503.1668524497317902423 for ; Tue, 15 Nov 2022 07:01:37 -0800 Authentication-Results: mx.groups.io; dkim=missing; spf=pass (domain: arm.com, ip: 217.140.110.172, mailfrom: peter.hoyes@arm.com) Received: from usa-sjc-imap-foss1.foss.arm.com (unknown [10.121.207.14]) by usa-sjc-mx-foss1.foss.arm.com (Postfix) with ESMTP id 129CC1477; Tue, 15 Nov 2022 07:01:43 -0800 (PST) Received: from e125920.cambridge.arm.com (unknown [10.1.199.64]) by usa-sjc-imap-foss1.foss.arm.com (Postfix) with ESMTPSA id 536113F587; Tue, 15 Nov 2022 07:01:36 -0800 (PST) From: Peter Hoyes To: meta-arm@lists.yoctoproject.org Cc: Peter Hoyes Subject: [PATCH 3/5] arm/lib: Decouple console parsing from the FVPRunner Date: Tue, 15 Nov 2022 15:01:14 +0000 Message-Id: <20221115150116.314729-3-peter.hoyes@arm.com> X-Mailer: git-send-email 2.25.1 In-Reply-To: <20221115150116.314729-1-peter.hoyes@arm.com> References: <20221115150116.314729-1-peter.hoyes@arm.com> MIME-Version: 1.0 List-Id: X-Webhook-Received: from li982-79.members.linode.com [45.33.32.79] by aws-us-west-2-korg-lkml-1.web.codeaurora.org with HTTPS for ; Tue, 15 Nov 2022 15:01:47 -0000 X-Groupsio-URL: https://lists.yoctoproject.org/g/meta-arm/message/4131 From: Peter Hoyes To simplify the FVPRunner class, create a separate ConsolePortParser class to handle reading an iterator of lines and parsing port numbers for FVP consoles. Use this in runfvp and the test targets. This refactor also allows the stream being monitored to be changed more easily, e.g. to a log file. Issue-Id: SCM-5314 Signed-off-by: Peter Hoyes Change-Id: Iade3a4c803fb355b04af7afa298d0a41fe707d94 --- meta-arm/lib/fvp/runner.py | 66 ++++++++++++++-------------- meta-arm/lib/oeqa/controllers/fvp.py | 17 +++---- scripts/runfvp | 9 ++-- 3 files changed, 47 insertions(+), 45 deletions(-) diff --git a/meta-arm/lib/fvp/runner.py b/meta-arm/lib/fvp/runner.py index 9b537e27..5c5ded28 100644 --- a/meta-arm/lib/fvp/runner.py +++ b/meta-arm/lib/fvp/runner.py @@ -44,18 +44,39 @@ def check_telnet(): if not bool(shutil.which("telnet")): raise RuntimeError("Cannot find telnet, this is needed to connect to the FVP.") + +class ConsolePortParser: + def __init__(self, lines): + self._lines = lines + self._console_ports = {} + + def parse_port(self, console): + if console in self._console_ports: + return self._console_ports[console] + + while True: + try: + line = next(self._lines).strip().decode(errors='ignore') + m = re.match(r"^(\S+): Listening for serial connection on port (\d+)$", line) + if m: + matched_console = m.group(1) + matched_port = int(m.group(2)) + if matched_console == console: + return matched_port + else: + self._console_ports[matched_console] = matched_port + except StopIteration: + # self._lines might be a growing log file + pass + + class FVPRunner: def __init__(self, logger): - self._terminal_ports = {} - self._line_callbacks = [] self._logger = logger self._fvp_process = None self._telnets = [] self._pexpects = [] - def add_line_callback(self, callback): - self._line_callbacks.append(callback) - def start(self, config, extra_args=[], terminal_choice="none"): cli = cli_from_config(config, terminal_choice) cli += extra_args @@ -73,14 +94,6 @@ class FVPRunner: stdin=subprocess.DEVNULL, stdout=subprocess.PIPE, stderr=subprocess.STDOUT, env=env) - def detect_terminals(line): - m = re.match(r"^(\S+): Listening for serial connection on port (\d+)$", line) - if m: - terminal = m.group(1) - port = int(m.group(2)) - self._terminal_ports[terminal] = port - self.add_line_callback(detect_terminals) - def stop(self): if self._fvp_process: self._logger.debug(f"Terminating FVP PID {self._fvp_process.pid}") @@ -117,34 +130,21 @@ class FVPRunner: else: return 0 - def run(self, until=None): - if until and until(): - return + def wait(self, timeout): + self._fvp_process.wait(timeout) - for line in self._fvp_process.stdout: - line = line.strip().decode("utf-8", errors="replace") - for callback in self._line_callbacks: - callback(line) - if until and until(): - return + @property + def stdout(self): + return self._fvp_process.stdout - def _get_terminal_port(self, terminal): - def terminal_exists(): - return terminal in self._terminal_ports - self.run(terminal_exists) - return self._terminal_ports[terminal] - - def create_telnet(self, terminal): + def create_telnet(self, port): check_telnet() - port = self._get_terminal_port(terminal) telnet = subprocess.Popen(["telnet", "localhost", str(port)], stdin=sys.stdin, stdout=sys.stdout) self._telnets.append(telnet) return telnet - def create_pexpect(self, terminal, **kwargs): - check_telnet() + def create_pexpect(self, port, **kwargs): import pexpect - port = self._get_terminal_port(terminal) instance = pexpect.spawn(f"telnet localhost {port}", **kwargs) self._pexpects.append(instance) return instance diff --git a/meta-arm/lib/oeqa/controllers/fvp.py b/meta-arm/lib/oeqa/controllers/fvp.py index dfc2b88b..0c3c2214 100644 --- a/meta-arm/lib/oeqa/controllers/fvp.py +++ b/meta-arm/lib/oeqa/controllers/fvp.py @@ -52,8 +52,10 @@ class OEFVPTarget(OEFVPSSHTarget): 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']}") - console = self.fvp.create_pexpect(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") @@ -85,12 +87,6 @@ class OEFVPSerialTarget(OEFVPSSHTarget): self.test_log_suffix = pathlib.Path(bootlog).suffix self.bootlog = bootlog - def _add_terminal(self, name, fvp_name): - logfile = self._create_logfile(name) - self.logger.info(f'Creating terminal {name} on {fvp_name}') - self.terminals[name] = \ - self.fvp.create_pexpect(fvp_name, logfile=logfile) - 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) @@ -103,8 +99,13 @@ class OEFVPSerialTarget(OEFVPSSHTarget): return open(fvp_log_path, 'wb') def _after_start(self): + parser = runner.ConsolePortParser(self.fvp.stdout) for name, console in self.config["consoles"].items(): - self._add_terminal(name, console) + 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 diff --git a/scripts/runfvp b/scripts/runfvp index 727223ca..454acb86 100755 --- a/scripts/runfvp +++ b/scripts/runfvp @@ -52,17 +52,18 @@ def start_fvp(args, config, extra_args): fvp.start(config, extra_args, args.terminals) if args.console: - fvp.add_line_callback(lambda line: logger.debug(f"FVP output: {line}")) expected_terminal = config["consoles"]["default"] if not expected_terminal: logger.error("--console used but FVP_CONSOLE not set in machine configuration") return 1 - telnet = fvp.create_telnet(expected_terminal) + parser = runner.ConsolePortParser(fvp.stdout) + port = parser.parse_port(expected_terminal) + telnet = fvp.create_telnet(port) telnet.wait() logger.debug(f"Telnet quit, cancelling tasks") else: - fvp.add_line_callback(lambda line: print(line)) - fvp.run() + for line in fvp.stdout: + print(line.strip().decode(errors='ignore')) finally: fvp.stop() From patchwork Tue Nov 15 15:01:15 2022 Content-Type: text/plain; charset="utf-8" MIME-Version: 1.0 Content-Transfer-Encoding: 7bit X-Patchwork-Submitter: Peter Hoyes X-Patchwork-Id: 15493 Return-Path: X-Spam-Checker-Version: SpamAssassin 3.4.0 (2014-02-07) on aws-us-west-2-korg-lkml-1.web.codeaurora.org Received: from aws-us-west-2-korg-lkml-1.web.codeaurora.org (localhost.localdomain [127.0.0.1]) by smtp.lore.kernel.org (Postfix) with ESMTP id 3D95DC4332F for ; Tue, 15 Nov 2022 15:01:47 +0000 (UTC) Received: from foss.arm.com (foss.arm.com [217.140.110.172]) by mx.groups.io with SMTP id smtpd.web12.6496.1668524498683333715 for ; Tue, 15 Nov 2022 07:01:38 -0800 Authentication-Results: mx.groups.io; dkim=missing; spf=pass (domain: arm.com, ip: 217.140.110.172, mailfrom: peter.hoyes@arm.com) Received: from usa-sjc-imap-foss1.foss.arm.com (unknown [10.121.207.14]) by usa-sjc-mx-foss1.foss.arm.com (Postfix) with ESMTP id 994DC13D5; Tue, 15 Nov 2022 07:01:44 -0800 (PST) Received: from e125920.cambridge.arm.com (unknown [10.1.199.64]) by usa-sjc-imap-foss1.foss.arm.com (Postfix) with ESMTPSA id DA2923F587; Tue, 15 Nov 2022 07:01:37 -0800 (PST) From: Peter Hoyes To: meta-arm@lists.yoctoproject.org Cc: Peter Hoyes Subject: [PATCH 4/5] arm/oeqa: Log the FVP output in OEFVPSSHTarget Date: Tue, 15 Nov 2022 15:01:15 +0000 Message-Id: <20221115150116.314729-4-peter.hoyes@arm.com> X-Mailer: git-send-email 2.25.1 In-Reply-To: <20221115150116.314729-1-peter.hoyes@arm.com> References: <20221115150116.314729-1-peter.hoyes@arm.com> MIME-Version: 1.0 List-Id: X-Webhook-Received: from li982-79.members.linode.com [45.33.32.79] by aws-us-west-2-korg-lkml-1.web.codeaurora.org with HTTPS for ; Tue, 15 Nov 2022 15:01:47 -0000 X-Groupsio-URL: https://lists.yoctoproject.org/g/meta-arm/message/4132 From: Peter Hoyes 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 --- documentation/oeqa-fvp.md | 2 +- meta-arm/lib/fvp/runner.py | 4 +- meta-arm/lib/oeqa/controllers/fvp.py | 97 +++++++++++++++------------- 3 files changed, 54 insertions(+), 49 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) - - # 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) + 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) def _get_terminal(self, name): return self.terminals[name] From patchwork Tue Nov 15 15:01:16 2022 Content-Type: text/plain; charset="utf-8" MIME-Version: 1.0 Content-Transfer-Encoding: 7bit X-Patchwork-Submitter: Peter Hoyes X-Patchwork-Id: 15491 Return-Path: X-Spam-Checker-Version: SpamAssassin 3.4.0 (2014-02-07) on aws-us-west-2-korg-lkml-1.web.codeaurora.org Received: from aws-us-west-2-korg-lkml-1.web.codeaurora.org (localhost.localdomain [127.0.0.1]) by smtp.lore.kernel.org (Postfix) with ESMTP id 3D99DC43217 for ; Tue, 15 Nov 2022 15:01:47 +0000 (UTC) Received: from foss.arm.com (foss.arm.com [217.140.110.172]) by mx.groups.io with SMTP id smtpd.web10.6580.1668524501535484776 for ; Tue, 15 Nov 2022 07:01:41 -0800 Authentication-Results: mx.groups.io; dkim=missing; spf=pass (domain: arm.com, ip: 217.140.110.172, mailfrom: peter.hoyes@arm.com) Received: from usa-sjc-imap-foss1.foss.arm.com (unknown [10.121.207.14]) by usa-sjc-mx-foss1.foss.arm.com (Postfix) with ESMTP id 83EF213D5; Tue, 15 Nov 2022 07:01:47 -0800 (PST) Received: from e125920.cambridge.arm.com (unknown [10.1.199.64]) by usa-sjc-imap-foss1.foss.arm.com (Postfix) with ESMTPSA id C4BD73F587; Tue, 15 Nov 2022 07:01:40 -0800 (PST) From: Peter Hoyes To: meta-arm@lists.yoctoproject.org Cc: Peter Hoyes Subject: [PATCH 5/5] runfvp: Fix verbose output when using --console Date: Tue, 15 Nov 2022 15:01:16 +0000 Message-Id: <20221115150116.314729-5-peter.hoyes@arm.com> X-Mailer: git-send-email 2.25.1 In-Reply-To: <20221115150116.314729-1-peter.hoyes@arm.com> References: <20221115150116.314729-1-peter.hoyes@arm.com> MIME-Version: 1.0 List-Id: X-Webhook-Received: from li982-79.members.linode.com [45.33.32.79] by aws-us-west-2-korg-lkml-1.web.codeaurora.org with HTTPS for ; Tue, 15 Nov 2022 15:01:47 -0000 X-Groupsio-URL: https://lists.yoctoproject.org/g/meta-arm/message/4133 From: Peter Hoyes Start a new thread to simultaneously log the output of FVP and the telnet output if the --verbose flag is passed to runfvp. So that ConsolePortParser can read the same stream, use itertools.tee to temporarily duplicate the stream. Use a custom log format string with an escape character to ensure that log output always starts at the beginning of a line when interleaved with console output. Issue-Id: SCM-5314 Signed-off-by: Peter Hoyes Change-Id: I3e815d9d899425e0d2af619524f09f2eda87562c --- scripts/runfvp | 16 ++++++++++++++-- 1 file changed, 14 insertions(+), 2 deletions(-) diff --git a/scripts/runfvp b/scripts/runfvp index 454acb86..939352b5 100755 --- a/scripts/runfvp +++ b/scripts/runfvp @@ -1,9 +1,11 @@ #! /usr/bin/env python3 +import itertools import os import pathlib import signal import sys +import threading import logging logger = logging.getLogger("RunFVP") @@ -36,7 +38,8 @@ def parse_args(arguments): fvp_args = [] args = parser.parse_args(args=arguments) - logging.basicConfig(level=args.verbose and logging.DEBUG or logging.WARNING) + logging.basicConfig(level=args.verbose and logging.DEBUG or logging.WARNING, + format='\033[G%(levelname)s: %(message)s') # If we're hooking up the console, don't start any terminals if args.console: @@ -56,8 +59,17 @@ def start_fvp(args, config, extra_args): if not expected_terminal: logger.error("--console used but FVP_CONSOLE not set in machine configuration") return 1 - parser = runner.ConsolePortParser(fvp.stdout) + port_stdout, log_stdout = itertools.tee(fvp.stdout, 2) + parser = runner.ConsolePortParser(port_stdout) port = parser.parse_port(expected_terminal) + + def debug_log(): + for line in log_stdout: + line = line.strip().decode(errors='ignore') + logger.debug(f'FVP output: {line}') + log_thread = threading.Thread(None, debug_log) + log_thread.start() + telnet = fvp.create_telnet(port) telnet.wait() logger.debug(f"Telnet quit, cancelling tasks")