diff options
Diffstat (limited to 'meta/lib/oeqa/utils')
-rw-r--r-- | meta/lib/oeqa/utils/__init__.py | 9 | ||||
-rw-r--r-- | meta/lib/oeqa/utils/commands.py | 36 | ||||
-rw-r--r-- | meta/lib/oeqa/utils/decorators.py | 85 | ||||
-rw-r--r-- | meta/lib/oeqa/utils/dump.py | 45 | ||||
-rw-r--r-- | meta/lib/oeqa/utils/ftools.py | 2 | ||||
-rw-r--r-- | meta/lib/oeqa/utils/gitarchive.py | 56 | ||||
-rw-r--r-- | meta/lib/oeqa/utils/httpserver.py | 29 | ||||
-rw-r--r-- | meta/lib/oeqa/utils/logparser.py | 73 | ||||
-rw-r--r-- | meta/lib/oeqa/utils/metadata.py | 6 | ||||
-rw-r--r-- | meta/lib/oeqa/utils/network.py | 2 | ||||
-rw-r--r-- | meta/lib/oeqa/utils/nfs.py | 10 | ||||
-rw-r--r-- | meta/lib/oeqa/utils/package_manager.py | 2 | ||||
-rw-r--r-- | meta/lib/oeqa/utils/postactions.py | 98 | ||||
-rw-r--r-- | meta/lib/oeqa/utils/qemurunner.py | 333 | ||||
-rw-r--r-- | meta/lib/oeqa/utils/subprocesstweak.py | 2 |
15 files changed, 501 insertions, 287 deletions
diff --git a/meta/lib/oeqa/utils/__init__.py b/meta/lib/oeqa/utils/__init__.py index 6d1ec4cb99..53bdcbf266 100644 --- a/meta/lib/oeqa/utils/__init__.py +++ b/meta/lib/oeqa/utils/__init__.py @@ -1,4 +1,6 @@ # +# Copyright OpenEmbedded Contributors +# # SPDX-License-Identifier: MIT # # Enable other layers to have modules in the same named directory @@ -88,3 +90,10 @@ def load_test_components(logger, executor): "_executor_class defined." % (comp_name, comp_context)) return components + +def get_json_result_dir(d): + json_result_dir = os.path.join(d.getVar("LOG_DIR"), 'oeqa') + custom_json_result_dir = d.getVar("OEQA_JSON_RESULT_DIR") + if custom_json_result_dir: + json_result_dir = custom_json_result_dir + return json_result_dir
\ No newline at end of file diff --git a/meta/lib/oeqa/utils/commands.py b/meta/lib/oeqa/utils/commands.py index 024261410e..575e380017 100644 --- a/meta/lib/oeqa/utils/commands.py +++ b/meta/lib/oeqa/utils/commands.py @@ -8,11 +8,8 @@ # This module is mainly used by scripts/oe-selftest and modules under meta/oeqa/selftest # It provides a class and methods for running commands on the host in a convienent way for tests. - - import os import sys -import signal import subprocess import threading import time @@ -21,6 +18,7 @@ from oeqa.utils import CommandError from oeqa.utils import ftools import re import contextlib +import errno # Export test doesn't require bb try: import bb @@ -85,7 +83,7 @@ class Command(object): except OSError as ex: # It's not an error when the command does not consume all # of our data. subprocess.communicate() also ignores that. - if ex.errno != EPIPE: + if ex.errno != errno.EPIPE: raise # We write in a separate thread because then we can read @@ -117,7 +115,7 @@ class Command(object): else: deadline = time.time() + self.timeout for thread in self.threads: - timeout = deadline - time.time() + timeout = deadline - time.time() if timeout < 0: timeout = 0 thread.join(timeout) @@ -168,15 +166,22 @@ class Result(object): def runCmd(command, ignore_status=False, timeout=None, assert_error=True, sync=True, - native_sysroot=None, limit_exc_output=0, output_log=None, **options): + native_sysroot=None, target_sys=None, limit_exc_output=0, output_log=None, **options): result = Result() if native_sysroot: - extra_paths = "%s/sbin:%s/usr/sbin:%s/usr/bin" % \ - (native_sysroot, native_sysroot, native_sysroot) - nenv = dict(options.get('env', os.environ)) - nenv['PATH'] = extra_paths + ':' + nenv.get('PATH', '') - options['env'] = nenv + new_env = dict(options.get('env', os.environ)) + paths = new_env["PATH"].split(":") + paths = [ + os.path.join(native_sysroot, "bin"), + os.path.join(native_sysroot, "sbin"), + os.path.join(native_sysroot, "usr", "bin"), + os.path.join(native_sysroot, "usr", "sbin"), + ] + paths + if target_sys: + paths = [os.path.join(native_sysroot, "usr", "bin", target_sys)] + paths + new_env["PATH"] = ":".join(paths) + options['env'] = new_env cmd = Command(command, timeout=timeout, output_log=output_log, **options) cmd.run() @@ -280,8 +285,10 @@ def get_bb_vars(variables=None, target=None, postconfig=None): def get_bb_var(var, target=None, postconfig=None): return get_bb_vars([var], target, postconfig)[var] -def get_test_layer(): - layers = get_bb_var("BBLAYERS").split() +def get_test_layer(bblayers=None): + if bblayers is None: + bblayers = get_bb_var("BBLAYERS") + layers = bblayers.split() testlayer = None for l in layers: if '~' in l: @@ -293,6 +300,7 @@ def get_test_layer(): def create_temp_layer(templayerdir, templayername, priority=999, recipepathspec='recipes-*/*'): os.makedirs(os.path.join(templayerdir, 'conf')) + corenames = get_bb_var('LAYERSERIES_CORENAMES') with open(os.path.join(templayerdir, 'conf', 'layer.conf'), 'w') as f: f.write('BBPATH .= ":${LAYERDIR}"\n') f.write('BBFILES += "${LAYERDIR}/%s/*.bb \\' % recipepathspec) @@ -301,7 +309,7 @@ def create_temp_layer(templayerdir, templayername, priority=999, recipepathspec= f.write('BBFILE_PATTERN_%s = "^${LAYERDIR}/"\n' % templayername) f.write('BBFILE_PRIORITY_%s = "%d"\n' % (templayername, priority)) f.write('BBFILE_PATTERN_IGNORE_EMPTY_%s = "1"\n' % templayername) - f.write('LAYERSERIES_COMPAT_%s = "${LAYERSERIES_COMPAT_core}"\n' % templayername) + f.write('LAYERSERIES_COMPAT_%s = "%s"\n' % (templayername, corenames)) @contextlib.contextmanager def runqemu(pn, ssh=True, runqemuparams='', image_fstype=None, launch_cmd=None, qemuparams=None, overrides={}, discard_writes=True): diff --git a/meta/lib/oeqa/utils/decorators.py b/meta/lib/oeqa/utils/decorators.py index aabf4110cb..ea90164e5e 100644 --- a/meta/lib/oeqa/utils/decorators.py +++ b/meta/lib/oeqa/utils/decorators.py @@ -16,91 +16,6 @@ import threading import signal from functools import wraps -#get the "result" object from one of the upper frames provided that one of these upper frames is a unittest.case frame -class getResults(object): - def __init__(self): - #dynamically determine the unittest.case frame and use it to get the name of the test method - ident = threading.current_thread().ident - upperf = sys._current_frames()[ident] - while (upperf.f_globals['__name__'] != 'unittest.case'): - upperf = upperf.f_back - - def handleList(items): - ret = [] - # items is a list of tuples, (test, failure) or (_ErrorHandler(), Exception()) - for i in items: - s = i[0].id() - #Handle the _ErrorHolder objects from skipModule failures - if "setUpModule (" in s: - ret.append(s.replace("setUpModule (", "").replace(")","")) - else: - ret.append(s) - # Append also the test without the full path - testname = s.split('.')[-1] - if testname: - ret.append(testname) - return ret - self.faillist = handleList(upperf.f_locals['result'].failures) - self.errorlist = handleList(upperf.f_locals['result'].errors) - self.skiplist = handleList(upperf.f_locals['result'].skipped) - - def getFailList(self): - return self.faillist - - def getErrorList(self): - return self.errorlist - - def getSkipList(self): - return self.skiplist - -class skipIfFailure(object): - - def __init__(self,testcase): - self.testcase = testcase - - def __call__(self,f): - @wraps(f) - def wrapped_f(*args, **kwargs): - res = getResults() - if self.testcase in (res.getFailList() or res.getErrorList()): - raise unittest.SkipTest("Testcase dependency not met: %s" % self.testcase) - return f(*args, **kwargs) - wrapped_f.__name__ = f.__name__ - return wrapped_f - -class skipIfSkipped(object): - - def __init__(self,testcase): - self.testcase = testcase - - def __call__(self,f): - @wraps(f) - def wrapped_f(*args, **kwargs): - res = getResults() - if self.testcase in res.getSkipList(): - raise unittest.SkipTest("Testcase dependency not met: %s" % self.testcase) - return f(*args, **kwargs) - wrapped_f.__name__ = f.__name__ - return wrapped_f - -class skipUnlessPassed(object): - - def __init__(self,testcase): - self.testcase = testcase - - def __call__(self,f): - @wraps(f) - def wrapped_f(*args, **kwargs): - res = getResults() - if self.testcase in res.getSkipList() or \ - self.testcase in res.getFailList() or \ - self.testcase in res.getErrorList(): - raise unittest.SkipTest("Testcase dependency not met: %s" % self.testcase) - return f(*args, **kwargs) - wrapped_f.__name__ = f.__name__ - wrapped_f._depends_on = self.testcase - return wrapped_f - class testcase(object): def __init__(self, test_case): self.test_case = test_case diff --git a/meta/lib/oeqa/utils/dump.py b/meta/lib/oeqa/utils/dump.py index 95a79a571c..d4d271369f 100644 --- a/meta/lib/oeqa/utils/dump.py +++ b/meta/lib/oeqa/utils/dump.py @@ -1,4 +1,6 @@ # +# Copyright OpenEmbedded Contributors +# # SPDX-License-Identifier: MIT # @@ -49,9 +51,7 @@ class BaseDumper(object): self.dump_dir = dump_dir def _construct_filename(self, command): - if isinstance(self, HostDumper): - prefix = "host" - elif isinstance(self, TargetDumper): + if isinstance(self, TargetDumper): prefix = "target" elif isinstance(self, MonitorDumper): prefix = "qmp" @@ -74,54 +74,56 @@ class BaseDumper(object): with open(fullname, 'w') as dump_file: dump_file.write(output) -class HostDumper(BaseDumper): - """ Class to get dumps from the host running the tests """ - - def __init__(self, cmds, parent_dir): - super(HostDumper, self).__init__(cmds, parent_dir) - - def dump_host(self, dump_dir=""): - if dump_dir: - self.dump_dir = dump_dir - env = os.environ.copy() - env['PATH'] = '/usr/sbin:/sbin:/usr/bin:/bin' - env['COLUMNS'] = '9999' - for cmd in self.cmds: - result = runCmd(cmd, ignore_status=True, env=env) - self._write_dump(cmd.split()[0], result.output) - class TargetDumper(BaseDumper): - """ Class to get dumps from target, it only works with QemuRunner """ + """ Class to get dumps from target, it only works with QemuRunner. + Will give up permanently after 5 errors from running commands over + serial console. This helps to end testing when target is really dead, hanging + or unresponsive. + """ def __init__(self, cmds, parent_dir, runner): super(TargetDumper, self).__init__(cmds, parent_dir) self.runner = runner + self.errors = 0 def dump_target(self, dump_dir=""): + if self.errors >= 5: + print("Too many errors when dumping data from target, assuming it is dead! Will not dump data anymore!") + return if dump_dir: self.dump_dir = dump_dir for cmd in self.cmds: # We can continue with the testing if serial commands fail try: (status, output) = self.runner.run_serial(cmd) + if status == 0: + self.errors = self.errors + 1 self._write_dump(cmd.split()[0], output) except: + self.errors = self.errors + 1 print("Tried to dump info from target but " "serial console failed") print("Failed CMD: %s" % (cmd)) class MonitorDumper(BaseDumper): - """ Class to get dumps via the Qemu Monitor, it only works with QemuRunner """ + """ Class to get dumps via the Qemu Monitor, it only works with QemuRunner + Will stop completely if there are more than 5 errors when dumping monitor data. + This helps to end testing when target is really dead, hanging or unresponsive. + """ def __init__(self, cmds, parent_dir, runner): super(MonitorDumper, self).__init__(cmds, parent_dir) self.runner = runner + self.errors = 0 def dump_monitor(self, dump_dir=""): if self.runner is None: return if dump_dir: self.dump_dir = dump_dir + if self.errors >= 5: + print("Too many errors when dumping data from qemu monitor, assuming it is dead! Will not dump data anymore!") + return for cmd in self.cmds: cmd_name = cmd.split()[0] try: @@ -135,4 +137,5 @@ class MonitorDumper(BaseDumper): output = self.runner.run_monitor(cmd_name) self._write_dump(cmd_name, output) except Exception as e: + self.errors = self.errors + 1 print("Failed to dump QMP CMD: %s with\nException: %s" % (cmd_name, e)) diff --git a/meta/lib/oeqa/utils/ftools.py b/meta/lib/oeqa/utils/ftools.py index 3093419cc7..a50aaa84c2 100644 --- a/meta/lib/oeqa/utils/ftools.py +++ b/meta/lib/oeqa/utils/ftools.py @@ -1,4 +1,6 @@ # +# Copyright OpenEmbedded Contributors +# # SPDX-License-Identifier: MIT # diff --git a/meta/lib/oeqa/utils/gitarchive.py b/meta/lib/oeqa/utils/gitarchive.py index 6e8040eb5c..10cb267dfa 100644 --- a/meta/lib/oeqa/utils/gitarchive.py +++ b/meta/lib/oeqa/utils/gitarchive.py @@ -100,9 +100,44 @@ def git_commit_data(repo, data_dir, branch, message, exclude, notes, log): if os.path.exists(tmp_index): os.unlink(tmp_index) +def get_tags(repo, log, pattern=None, url=None): + """ Fetch remote tags from current repository + + A pattern can be provided to filter returned tags list + An URL can be provided if local repository has no valid remote configured + """ + + base_cmd = ['ls-remote', '--refs', '--tags', '-q'] + cmd = base_cmd.copy() + + # First try to fetch tags from repository configured remote + cmd.append('origin') + if pattern: + cmd.append("refs/tags/"+pattern) + try: + tags_refs = repo.run_cmd(cmd) + tags = ["".join(d.split()[1].split('/', 2)[2:]) for d in tags_refs.splitlines()] + except GitError as e: + # If it fails, retry with repository url if one is provided + if url: + log.info("No remote repository configured, use provided url") + cmd = base_cmd.copy() + cmd.append(url) + if pattern: + cmd.append(pattern) + tags_refs = repo.run_cmd(cmd) + tags = ["".join(d.split()[1].split('/', 2)[2:]) for d in tags_refs.splitlines()] + else: + log.info("Read local tags only, some remote tags may be missed") + cmd = ["tag"] + if pattern: + cmd += ["-l", pattern] + tags = repo.run_cmd(cmd).splitlines() + + return tags def expand_tag_strings(repo, name_pattern, msg_subj_pattern, msg_body_pattern, - keywords): + url, log, keywords): """Generate tag name and message, with support for running id number""" keyws = keywords.copy() # Tag number is handled specially: if not defined, we autoincrement it @@ -116,7 +151,7 @@ def expand_tag_strings(repo, name_pattern, msg_subj_pattern, msg_body_pattern, tag_re = tag_re.format(tag_number='(?P<tag_number>[0-9]{1,5})') keyws['tag_number'] = 0 - for existing_tag in repo.run_cmd('tag').splitlines(): + for existing_tag in get_tags(repo, log, url=url): match = re.match(tag_re, existing_tag) if match and int(match.group('tag_number')) >= keyws['tag_number']: @@ -143,7 +178,8 @@ def gitarchive(data_dir, git_dir, no_create, bare, commit_msg_subject, commit_ms if not no_tag and tagname: tag_name, tag_msg = expand_tag_strings(data_repo, tagname, tag_msg_subject, - tag_msg_body, keywords) + tag_msg_body, + push, log, keywords) # Commit data commit = git_commit_data(data_repo, data_dir, branch_name, @@ -181,7 +217,7 @@ def get_test_runs(log, repo, tag_name, **kwargs): # Get a list of all matching tags tag_pattern = tag_name.format(**str_fields) - tags = repo.run_cmd(['tag', '-l', tag_pattern]).splitlines() + tags = get_tags(repo, log, pattern=tag_pattern) log.debug("Found %d tags matching pattern '%s'", len(tags), tag_pattern) # Parse undefined fields from tag names @@ -199,6 +235,8 @@ def get_test_runs(log, repo, tag_name, **kwargs): revs = [] for tag in tags: m = tag_re.match(tag) + if not m: + continue groups = m.groupdict() revs.append([groups[f] for f in undef_fields] + [tag]) @@ -219,7 +257,15 @@ def get_test_revs(log, repo, tag_name, **kwargs): if not commit in revs: revs[commit] = TestedRev(commit, commit_num, [tag]) else: - assert commit_num == revs[commit].commit_number, "Commit numbers do not match" + if commit_num != revs[commit].commit_number: + # Historically we have incorrect commit counts of '1' in the repo so fix these up + if int(revs[commit].commit_number) < 5: + tags = revs[commit].tags + revs[commit] = TestedRev(commit, commit_num, [tags]) + elif int(commit_num) < 5: + pass + else: + sys.exit("Commit numbers for commit %s don't match (%s vs %s)" % (commit, commit_num, revs[commit].commit_number)) revs[commit].tags.append(tag) # Return in sorted table diff --git a/meta/lib/oeqa/utils/httpserver.py b/meta/lib/oeqa/utils/httpserver.py index 58d3c3b3f8..80752c1377 100644 --- a/meta/lib/oeqa/utils/httpserver.py +++ b/meta/lib/oeqa/utils/httpserver.py @@ -1,11 +1,13 @@ # +# Copyright OpenEmbedded Contributors +# # SPDX-License-Identifier: MIT # import http.server +import logging import multiprocessing import os -import traceback import signal from socketserver import ThreadingMixIn @@ -13,20 +15,24 @@ class HTTPServer(ThreadingMixIn, http.server.HTTPServer): def server_start(self, root_dir, logger): os.chdir(root_dir) + self.logger = logger self.serve_forever() class HTTPRequestHandler(http.server.SimpleHTTPRequestHandler): def log_message(self, format_str, *args): - pass + self.server.logger.info(format_str, *args) -class HTTPService(object): +class HTTPService: def __init__(self, root_dir, host='', port=0, logger=None): self.root_dir = root_dir self.host = host self.port = port - self.logger = logger + if logger: + self.logger = logger.getChild("HTTPService") + else: + self.logger = logging.getLogger("HTTPService") def start(self): if not os.path.exists(self.root_dir): @@ -38,6 +44,12 @@ class HTTPService(object): self.port = self.server.server_port self.process = multiprocessing.Process(target=self.server.server_start, args=[self.root_dir, self.logger]) + def handle_error(self, request, client_address): + import traceback + exception = traceback.format_exc() + self.logger.warn("Exception when handling %s: %s" % (request, exception)) + self.server.handle_error = handle_error + # The signal handler from testimage.bbclass can cause deadlocks here # if the HTTPServer is terminated before it can restore the standard #signal behaviour @@ -47,7 +59,7 @@ class HTTPService(object): signal.signal(signal.SIGTERM, orig) if self.logger: - self.logger.info("Started HTTPService on %s:%s" % (self.host, self.port)) + self.logger.info("Started HTTPService for %s on %s:%s" % (self.root_dir, self.host, self.port)) def stop(self): @@ -59,3 +71,10 @@ class HTTPService(object): if self.logger: self.logger.info("Stopped HTTPService on %s:%s" % (self.host, self.port)) +if __name__ == "__main__": + import sys, logging + + logger = logging.getLogger(__name__) + logging.basicConfig(level=logging.DEBUG) + httpd = HTTPService(sys.argv[1], port=8888, logger=logger) + httpd.start() diff --git a/meta/lib/oeqa/utils/logparser.py b/meta/lib/oeqa/utils/logparser.py index 879aefca33..496d9e0c90 100644 --- a/meta/lib/oeqa/utils/logparser.py +++ b/meta/lib/oeqa/utils/logparser.py @@ -1,8 +1,10 @@ # +# Copyright OpenEmbedded Contributors +# # SPDX-License-Identifier: MIT # -import sys +import enum import os import re @@ -42,6 +44,8 @@ class PtestParser(object): result = section_regex['begin'].search(line) if result: current_section['name'] = result.group(1) + if current_section['name'] not in self.results: + self.results[current_section['name']] = {} continue result = section_regex['end'].search(line) @@ -73,9 +77,10 @@ class PtestParser(object): for t in test_regex: result = test_regex[t].search(line) if result: - if current_section['name'] not in self.results: - self.results[current_section['name']] = {} - self.results[current_section['name']][result.group(1).strip()] = t + try: + self.results[current_section['name']][result.group(1).strip()] = t + except KeyError: + bb.warn("Result with no section: %s - %s" % (t, result.group(1).strip())) # Python performance for repeatedly joining long strings is poor, do it all at once at the end. # For 2.1 million lines in a log this reduces 18 hours to 12s. @@ -101,30 +106,48 @@ class PtestParser(object): f.write(status + ": " + test_name + "\n") -# ltp log parsing -class LtpParser(object): - def __init__(self): - self.results = {} - self.section = {'duration': "", 'log': ""} - +class LtpParser: + """ + Parse the machine-readable LTP log output into a ptest-friendly data structure. + """ def parse(self, logfile): - test_regex = {} - test_regex['PASSED'] = re.compile(r"PASS") - test_regex['FAILED'] = re.compile(r"FAIL") - test_regex['SKIPPED'] = re.compile(r"SKIP") - - with open(logfile, errors='replace') as f: + results = {} + # Aaccumulate the duration here but as the log rounds quick tests down + # to 0 seconds this is very much a lower bound. The caller can replace + # the value. + section = {"duration": 0, "log": ""} + + class LtpExitCode(enum.IntEnum): + # Exit codes as defined in ltp/include/tst_res_flags.h + TPASS = 0 # Test passed flag + TFAIL = 1 # Test failed flag + TBROK = 2 # Test broken flag + TWARN = 4 # Test warning flag + TINFO = 16 # Test information flag + TCONF = 32 # Test not appropriate for configuration flag + + with open(logfile, errors="replace") as f: + # Lines look like this: + # tag=cfs_bandwidth01 stime=1689762564 dur=0 exit=exited stat=32 core=no cu=0 cs=0 for line in f: - for t in test_regex: - result = test_regex[t].search(line) - if result: - self.results[line.split()[0].strip()] = t - - for test in self.results: - result = self.results[test] - self.section['log'] = self.section['log'] + ("%s: %s\n" % (result.strip()[:-2], test.strip())) + if not line.startswith("tag="): + continue - return self.results, self.section + values = dict(s.split("=") for s in line.strip().split()) + + section["duration"] += int(values["dur"]) + exitcode = int(values["stat"]) + if values["exit"] == "exited" and exitcode == LtpExitCode.TCONF: + # Exited normally with the "invalid configuration" code + results[values["tag"]] = "SKIPPED" + elif exitcode == LtpExitCode.TPASS: + # Successful exit + results[values["tag"]] = "PASSED" + else: + # Other exit + results[values["tag"]] = "FAILED" + + return results, section # ltp Compliance log parsing diff --git a/meta/lib/oeqa/utils/metadata.py b/meta/lib/oeqa/utils/metadata.py index 8013aa684d..15ec190c4a 100644 --- a/meta/lib/oeqa/utils/metadata.py +++ b/meta/lib/oeqa/utils/metadata.py @@ -27,9 +27,9 @@ def metadata_from_bb(): data_dict = get_bb_vars() # Distro information - info_dict['distro'] = {'id': data_dict['DISTRO'], - 'version_id': data_dict['DISTRO_VERSION'], - 'pretty_name': '%s %s' % (data_dict['DISTRO'], data_dict['DISTRO_VERSION'])} + info_dict['distro'] = {'id': data_dict.get('DISTRO', 'NODISTRO'), + 'version_id': data_dict.get('DISTRO_VERSION', 'NO_DISTRO_VERSION'), + 'pretty_name': '%s %s' % (data_dict.get('DISTRO', 'NODISTRO'), data_dict.get('DISTRO_VERSION', 'NO_DISTRO_VERSION'))} # Host distro information os_release = get_os_release() diff --git a/meta/lib/oeqa/utils/network.py b/meta/lib/oeqa/utils/network.py index 59d01723a1..da4ffda9a9 100644 --- a/meta/lib/oeqa/utils/network.py +++ b/meta/lib/oeqa/utils/network.py @@ -1,4 +1,6 @@ # +# Copyright OpenEmbedded Contributors +# # SPDX-License-Identifier: MIT # diff --git a/meta/lib/oeqa/utils/nfs.py b/meta/lib/oeqa/utils/nfs.py index a37686c914..903469bfee 100644 --- a/meta/lib/oeqa/utils/nfs.py +++ b/meta/lib/oeqa/utils/nfs.py @@ -1,4 +1,8 @@ +# +# Copyright OpenEmbedded Contributors +# # SPDX-License-Identifier: MIT +# import os import sys import tempfile @@ -8,7 +12,7 @@ from oeqa.utils.commands import bitbake, get_bb_var, Command from oeqa.utils.network import get_free_port @contextlib.contextmanager -def unfs_server(directory, logger = None): +def unfs_server(directory, logger = None, udp = True): unfs_sysroot = get_bb_var("RECIPE_SYSROOT_NATIVE", "unfs3-native") if not os.path.exists(os.path.join(unfs_sysroot, "usr", "bin", "unfsd")): # build native tool @@ -22,11 +26,11 @@ def unfs_server(directory, logger = None): exports.write("{0} (rw,no_root_squash,no_all_squash,insecure)\n".format(directory).encode()) # find some ports for the server - nfsport, mountport = get_free_port(udp = True), get_free_port(udp = True) + nfsport, mountport = get_free_port(udp), get_free_port(udp) nenv = dict(os.environ) nenv['PATH'] = "{0}/sbin:{0}/usr/sbin:{0}/usr/bin:".format(unfs_sysroot) + nenv.get('PATH', '') - cmd = Command(["unfsd", "-d", "-p", "-N", "-e", exports.name, "-n", str(nfsport), "-m", str(mountport)], + cmd = Command(["unfsd", "-d", "-p", "-e", exports.name, "-n", str(nfsport), "-m", str(mountport)], bg = True, env = nenv, output_log = logger) cmd.run() yield nfsport, mountport diff --git a/meta/lib/oeqa/utils/package_manager.py b/meta/lib/oeqa/utils/package_manager.py index 6b67f22fdd..db799b64d6 100644 --- a/meta/lib/oeqa/utils/package_manager.py +++ b/meta/lib/oeqa/utils/package_manager.py @@ -1,4 +1,6 @@ # +# Copyright OpenEmbedded Contributors +# # SPDX-License-Identifier: MIT # diff --git a/meta/lib/oeqa/utils/postactions.py b/meta/lib/oeqa/utils/postactions.py new file mode 100644 index 0000000000..ecdddd2d40 --- /dev/null +++ b/meta/lib/oeqa/utils/postactions.py @@ -0,0 +1,98 @@ +# +# Copyright OpenEmbedded Contributors +# +# SPDX-License-Identifier: MIT +# + +# Run a set of actions after tests. The runner provides internal data +# dictionary as well as test context to any action to run. + +from oeqa.utils import get_json_result_dir + +def create_artifacts_directory(d, tc): + import shutil + + local_artifacts_dir = os.path.join(get_json_result_dir(d), "artifacts") + if os.path.isdir(local_artifacts_dir): + shutil.rmtree(local_artifacts_dir) + + os.makedirs(local_artifacts_dir) + +################################################################## +# Host/target statistics +################################################################## + +def get_target_disk_usage(d, tc): + output_file = os.path.join(get_json_result_dir(d), "artifacts", "target_disk_usage.txt") + try: + (status, output) = tc.target.run('df -h') + with open(output_file, 'w') as f: + f.write(output) + f.write("\n") + except Exception as e: + bb.warn(f"Can not get target disk usage: {e}") + +def get_host_disk_usage(d, tc): + import subprocess + + output_file = os.path.join(get_json_result_dir(d), "artifacts", "host_disk_usage.txt") + try: + with open(output_file, 'w') as f: + output = subprocess.run(['df', '-hl'], check=True, text=True, stdout=f, env={}) + except Exception as e: + bb.warn(f"Can not get host disk usage: {e}") + +################################################################## +# Artifacts retrieval +################################################################## + +def get_artifacts_list(target, raw_list): + result = [] + # Passed list may contains patterns in paths, expand them directly on target + for raw_path in raw_list.split(): + cmd = f"for p in {raw_path}; do if [ -e $p ]; then echo $p; fi; done" + try: + status, output = target.run(cmd) + if status != 0 or not output: + raise Exception() + result += output.split() + except: + bb.note(f"No file/directory matching path {raw_path}") + + return result + +def retrieve_test_artifacts(target, artifacts_list, target_dir): + local_artifacts_dir = os.path.join(target_dir, "artifacts") + for artifact_path in artifacts_list: + if not os.path.isabs(artifact_path): + bb.warn(f"{artifact_path} is not an absolute path") + continue + try: + dest_dir = os.path.join(local_artifacts_dir, os.path.dirname(artifact_path[1:])) + os.makedirs(dest_dir, exist_ok=True) + target.copyFrom(artifact_path, dest_dir) + except Exception as e: + bb.warn(f"Can not retrieve {artifact_path} from test target: {e}") + +def list_and_fetch_failed_tests_artifacts(d, tc): + artifacts_list = get_artifacts_list(tc.target, d.getVar("TESTIMAGE_FAILED_QA_ARTIFACTS")) + if not artifacts_list: + bb.warn("Could not load artifacts list, skip artifacts retrieval") + else: + retrieve_test_artifacts(tc.target, artifacts_list, get_json_result_dir(d)) + + +################################################################## +# General post actions runner +################################################################## + +def run_failed_tests_post_actions(d, tc): + post_actions=[ + create_artifacts_directory, + list_and_fetch_failed_tests_artifacts, + get_target_disk_usage, + get_host_disk_usage + ] + + for action in post_actions: + action(d, tc) diff --git a/meta/lib/oeqa/utils/qemurunner.py b/meta/lib/oeqa/utils/qemurunner.py index 76296d50cd..cda43aad8c 100644 --- a/meta/lib/oeqa/utils/qemurunner.py +++ b/meta/lib/oeqa/utils/qemurunner.py @@ -19,11 +19,11 @@ import errno import string import threading import codecs -import logging import tempfile -from oeqa.utils.dump import HostDumper from collections import defaultdict +from contextlib import contextmanager import importlib +import traceback # Get Unicode non printable control chars control_range = list(range(0,32))+list(range(127,160)) @@ -31,10 +31,19 @@ control_chars = [chr(x) for x in control_range if chr(x) not in string.printable] re_control_char = re.compile('[%s]' % re.escape("".join(control_chars))) +def getOutput(o): + import fcntl + fl = fcntl.fcntl(o, fcntl.F_GETFL) + fcntl.fcntl(o, fcntl.F_SETFL, fl | os.O_NONBLOCK) + try: + return os.read(o.fileno(), 1000000).decode("utf-8") + except BlockingIOError: + return "" + class QemuRunner: - def __init__(self, machine, rootfs, display, tmpdir, deploy_dir_image, logfile, boottime, dump_dir, dump_host_cmds, - use_kvm, logger, use_slirp=False, serial_ports=2, boot_patterns = defaultdict(str), use_ovmf=False, workdir=None, tmpfsdir=None): + def __init__(self, machine, rootfs, display, tmpdir, deploy_dir_image, logfile, boottime, dump_dir, use_kvm, logger, use_slirp=False, + serial_ports=2, boot_patterns = defaultdict(str), use_ovmf=False, workdir=None, tmpfsdir=None): # Popen object for runqemu self.runqemu = None @@ -57,6 +66,7 @@ class QemuRunner: self.boottime = boottime self.logged = False self.thread = None + self.threadsock = None self.use_kvm = use_kvm self.use_ovmf = use_ovmf self.use_slirp = use_slirp @@ -69,7 +79,6 @@ class QemuRunner: if not workdir: workdir = os.getcwd() self.qemu_pidfile = workdir + '/pidfile_' + str(os.getpid()) - self.host_dumper = HostDumper(dump_host_cmds, dump_dir) self.monitorpipe = None self.logger = logger @@ -85,7 +94,7 @@ class QemuRunner: accepted_patterns = ['search_reached_prompt', 'send_login_user', 'search_login_succeeded', 'search_cmd_finished'] default_boot_patterns = defaultdict(str) # Default to the usual paterns used to communicate with the target - default_boot_patterns['search_reached_prompt'] = b' login:' + default_boot_patterns['search_reached_prompt'] = ' login:' default_boot_patterns['send_login_user'] = 'root\n' default_boot_patterns['search_login_succeeded'] = r"root@[a-zA-Z0-9\-]+:~#" default_boot_patterns['search_cmd_finished'] = r"[a-zA-Z0-9]+@[a-zA-Z0-9\-]+:~#" @@ -99,6 +108,7 @@ class QemuRunner: try: sock = socket.socket(socket.AF_INET, socket.SOCK_STREAM) sock.setblocking(0) + sock.setsockopt(socket.IPPROTO_TCP, socket.TCP_NODELAY, 1) sock.bind(("127.0.0.1",0)) sock.listen(2) port = sock.getsockname()[1] @@ -109,33 +119,24 @@ class QemuRunner: sock.close() raise - def log(self, msg): - if self.logfile: - # It is needed to sanitize the data received from qemu - # because is possible to have control characters - msg = msg.decode("utf-8", errors='ignore') - msg = re_control_char.sub('', msg) - self.msg += msg - with codecs.open(self.logfile, "a", encoding="utf-8") as f: - f.write("%s" % msg) - - def getOutput(self, o): - import fcntl - fl = fcntl.fcntl(o, fcntl.F_GETFL) - fcntl.fcntl(o, fcntl.F_SETFL, fl | os.O_NONBLOCK) - try: - return os.read(o.fileno(), 1000000).decode("utf-8") - except BlockingIOError: - return "" + def decode_qemulog(self, todecode): + # Sanitize the data received from qemu as it may contain control characters + msg = todecode.decode("utf-8", errors='backslashreplace') + msg = re_control_char.sub('', msg) + return msg + def log(self, msg, extension=""): + if self.logfile: + with codecs.open(self.logfile + extension, "ab") as f: + f.write(msg) + self.msg += self.decode_qemulog(msg) def handleSIGCHLD(self, signum, frame): if self.runqemu and self.runqemu.poll(): if self.runqemu.returncode: self.logger.error('runqemu exited with code %d' % self.runqemu.returncode) - self.logger.error('Output from runqemu:\n%s' % self.getOutput(self.runqemu.stdout)) + self.logger.error('Output from runqemu:\n%s' % getOutput(self.runqemu.stdout)) self.stop() - self._dump_host() def start(self, qemuparams = None, get_ip = True, extra_bootparams = None, runqemuparams='', launch_cmd=None, discard_writes=True): env = os.environ.copy() @@ -174,28 +175,32 @@ class QemuRunner: launch_cmd += ' slirp' if self.use_ovmf: launch_cmd += ' ovmf' - launch_cmd += ' %s %s %s' % (runqemuparams, self.machine, self.rootfs) + launch_cmd += ' %s %s' % (runqemuparams, self.machine) + if self.rootfs.endswith('.vmdk'): + self.logger.debug('Bypassing VMDK rootfs for runqemu') + else: + launch_cmd += ' %s' % (self.rootfs) return self.launch(launch_cmd, qemuparams=qemuparams, get_ip=get_ip, extra_bootparams=extra_bootparams, env=env) def launch(self, launch_cmd, get_ip = True, qemuparams = None, extra_bootparams = None, env = None): # use logfile to determine the recipe-sysroot-native path and # then add in the site-packages path components and add that - # to the python sys.path so qmp.py can be found. + # to the python sys.path so the qmp module can be found. python_path = os.path.dirname(os.path.dirname(self.logfile)) python_path += "/recipe-sysroot-native/usr/lib/qemu-python" sys.path.append(python_path) importlib.invalidate_caches() try: qmp = importlib.import_module("qmp") - except: - self.logger.error("qemurunner: qmp.py missing, please ensure it's installed") + except Exception as e: + self.logger.error("qemurunner: qmp module missing, please ensure it's installed in %s (%s)" % (python_path, str(e))) return False # Path relative to tmpdir used as cwd for qemu below to avoid unix socket path length issues qmp_file = "." + next(tempfile._get_candidate_names()) qmp_param = ' -S -qmp unix:./%s,server,wait' % (qmp_file) qmp_port = self.tmpdir + "/" + qmp_file - # Create a second socket connection for debugging use, + # Create a second socket connection for debugging use, # note this will NOT cause qemu to block waiting for the connection qmp_file2 = "." + next(tempfile._get_candidate_names()) qmp_param += ' -qmp unix:./%s,server,nowait' % (qmp_file2) @@ -231,7 +236,7 @@ class QemuRunner: self.origchldhandler = signal.getsignal(signal.SIGCHLD) signal.signal(signal.SIGCHLD, self.handleSIGCHLD) - self.logger.debug('launchcmd=%s'%(launch_cmd)) + self.logger.debug('launchcmd=%s' % (launch_cmd)) # FIXME: We pass in stdin=subprocess.PIPE here to work around stty # blocking at the end of the runqemu script when using this within @@ -268,7 +273,7 @@ class QemuRunner: os._exit(0) self.logger.debug("runqemu started, pid is %s" % self.runqemu.pid) - self.logger.debug("waiting at most %s seconds for qemu pid (%s)" % + self.logger.debug("waiting at most %d seconds for qemu pid (%s)" % (self.runqemutime, time.strftime("%D %H:%M:%S"))) endtime = time.time() + self.runqemutime while not self.is_alive() and time.time() < endtime: @@ -279,8 +284,7 @@ class QemuRunner: if self.runqemu.returncode: # No point waiting any longer self.logger.warning('runqemu exited with code %d' % self.runqemu.returncode) - self._dump_host() - self.logger.warning("Output from runqemu:\n%s" % self.getOutput(output)) + self.logger.warning("Output from runqemu:\n%s" % getOutput(output)) self.stop() return False time.sleep(0.5) @@ -292,7 +296,7 @@ class QemuRunner: self.logger.warning('runqemu exited with code %d' % self.runqemu.returncode) if not self.is_alive(): - self.logger.error("Qemu pid didn't appear in %s seconds (%s)" % + self.logger.error("Qemu pid didn't appear in %d seconds (%s)" % (self.runqemutime, time.strftime("%D %H:%M:%S"))) qemu_pid = None @@ -307,8 +311,7 @@ class QemuRunner: ps = subprocess.Popen(['ps', 'axww', '-o', 'pid,ppid,pri,ni,command '], stdout=subprocess.PIPE).communicate()[0] processes = ps.decode("utf-8") self.logger.debug("Running processes:\n%s" % processes) - self._dump_host() - op = self.getOutput(output) + op = getOutput(output) self.stop() if op: self.logger.error("Output from runqemu:\n%s" % op) @@ -325,7 +328,8 @@ class QemuRunner: try: os.chdir(os.path.dirname(qmp_port)) try: - self.qmp = qmp.QEMUMonitorProtocol(os.path.basename(qmp_port)) + from qmp.legacy import QEMUMonitorProtocol + self.qmp = QEMUMonitorProtocol(os.path.basename(qmp_port)) except OSError as msg: self.logger.warning("Failed to initialize qemu monitor socket: %s File: %s" % (msg, msg.filename)) return False @@ -335,22 +339,24 @@ class QemuRunner: self.logger.debug("QMP Port does not exist waiting for it to be created") endtime = time.time() + self.runqemutime while not os.path.exists(qmp_port) and self.is_alive() and time.time() < endtime: - self.logger.info("QMP port does not exist yet!") - time.sleep(0.5) + self.logger.info("QMP port does not exist yet!") + time.sleep(0.5) if not os.path.exists(qmp_port) and self.is_alive(): self.logger.warning("QMP Port still does not exist but QEMU is alive") return False try: + # set timeout value for all QMP calls + self.qmp.settimeout(self.runqemutime) self.qmp.connect() connect_time = time.time() - self.logger.info("QMP connected to QEMU at %s and took %s seconds" % + self.logger.info("QMP connected to QEMU at %s and took %.2f seconds" % (time.strftime("%D %H:%M:%S"), time.time() - launch_time)) except OSError as msg: self.logger.warning("Failed to connect qemu monitor socket: %s File: %s" % (msg, msg.filename)) return False - except qmp.QMPConnectError as msg: + except qmp.legacy.QMPError as msg: self.logger.warning("Failed to communicate with qemu monitor: %s" % (msg)) return False finally: @@ -378,14 +384,14 @@ class QemuRunner: # Release the qemu process to continue running self.run_monitor('cont') - self.logger.info("QMP released QEMU at %s and took %s seconds from connect" % + self.logger.info("QMP released QEMU at %s and took %.2f seconds from connect" % (time.strftime("%D %H:%M:%S"), time.time() - connect_time)) # We are alive: qemu is running - out = self.getOutput(output) + out = getOutput(output) netconf = False # network configuration is not required by default - self.logger.debug("qemu started in %s seconds - qemu procces pid is %s (%s)" % + self.logger.debug("qemu started in %.2f seconds - qemu procces pid is %s (%s)" % (time.time() - (endtime - self.runqemutime), self.qemupid, time.strftime("%D %H:%M:%S"))) cmdline = '' @@ -397,9 +403,10 @@ class QemuRunner: cmdline = re_control_char.sub(' ', cmdline) try: if self.use_slirp: - tcp_ports = cmdline.split("hostfwd=tcp::")[1] + tcp_ports = cmdline.split("hostfwd=tcp:")[1] + ip, tcp_ports = tcp_ports.split(":")[:2] host_port = tcp_ports[:tcp_ports.find('-')] - self.ip = "localhost:%s" % host_port + self.ip = "%s:%s" % (ip, host_port) else: ips = re.findall(r"((?:[0-9]{1,3}\.){3}[0-9]{1,3})", cmdline.split("ip=")[1]) self.ip = ips[0] @@ -408,7 +415,7 @@ class QemuRunner: except (IndexError, ValueError): # Try to get network configuration from runqemu output match = re.match(r'.*Network configuration: (?:ip=)*([0-9.]+)::([0-9.]+):([0-9.]+).*', - out, re.MULTILINE|re.DOTALL) + out, re.MULTILINE | re.DOTALL) if match: self.ip, self.server_ip, self.netmask = match.groups() # network configuration is required as we couldn't get it @@ -419,16 +426,16 @@ class QemuRunner: self.logger.error("Couldn't get ip from qemu command line and runqemu output! " "Here is the qemu command line used:\n%s\n" "and output from runqemu:\n%s" % (cmdline, out)) - self._dump_host() self.stop() return False self.logger.debug("Target IP: %s" % self.ip) self.logger.debug("Server IP: %s" % self.server_ip) + self.thread = LoggingThread(self.log, self.threadsock, self.logger, self.runqemu.stdout) + self.thread.start() + if self.serial_ports >= 2: - self.thread = LoggingThread(self.log, self.threadsock, self.logger) - self.thread.start() if not self.thread.connection_established.wait(self.boottime): self.logger.error("Didn't receive a console connection from qemu. " "Here is the qemu command line used:\n%s\nand " @@ -440,7 +447,7 @@ class QemuRunner: self.logger.debug("Waiting at most %d seconds for login banner (%s)" % (self.boottime, time.strftime("%D %H:%M:%S"))) endtime = time.time() + self.boottime - socklist = [self.server_socket] + filelist = [self.server_socket] reachedlogin = False stopread = False qemusock = None @@ -448,38 +455,48 @@ class QemuRunner: data = b'' while time.time() < endtime and not stopread: try: - sread, swrite, serror = select.select(socklist, [], [], 5) + sread, swrite, serror = select.select(filelist, [], [], 5) except InterruptedError: continue - for sock in sread: - if sock is self.server_socket: + for file in sread: + if file is self.server_socket: qemusock, addr = self.server_socket.accept() - qemusock.setblocking(0) - socklist.append(qemusock) - socklist.remove(self.server_socket) + qemusock.setblocking(False) + filelist.append(qemusock) + filelist.remove(self.server_socket) self.logger.debug("Connection from %s:%s" % addr) else: - data = data + sock.recv(1024) + # try to avoid reading only a single character at a time + time.sleep(0.1) + if hasattr(file, 'read'): + read = file.read(1024) + elif hasattr(file, 'recv'): + read = file.recv(1024) + else: + self.logger.error('Invalid file type: %s\n%s' % (file)) + read = b'' + + self.logger.debug2('Partial boot log:\n%s' % (read.decode('utf-8', errors='backslashreplace'))) + data = data + read if data: bootlog += data - if self.serial_ports < 2: - # this socket has mixed console/kernel data, log it to logfile - self.log(data) - + self.log(data, extension = ".2") data = b'' - if self.boot_patterns['search_reached_prompt'] in bootlog: + + if bytes(self.boot_patterns['search_reached_prompt'], 'utf-8') in bootlog: + self.server_socket.close() self.server_socket = qemusock stopread = True reachedlogin = True - self.logger.debug("Reached login banner in %s seconds (%s)" % + self.logger.debug("Reached login banner in %.2f seconds (%s)" % (time.time() - (endtime - self.boottime), time.strftime("%D %H:%M:%S"))) else: # no need to check if reachedlogin unless we support multiple connections self.logger.debug("QEMU socket disconnected before login banner reached. (%s)" % time.strftime("%D %H:%M:%S")) - socklist.remove(sock) - sock.close() + filelist.remove(file) + file.close() stopread = True if not reachedlogin: @@ -487,21 +504,33 @@ class QemuRunner: self.logger.warning("Target didn't reach login banner in %d seconds (%s)" % (self.boottime, time.strftime("%D %H:%M:%S"))) tail = lambda l: "\n".join(l.splitlines()[-25:]) - bootlog = bootlog.decode("utf-8") - # in case bootlog is empty, use tail qemu log store at self.msg - lines = tail(bootlog if bootlog else self.msg) - self.logger.warning("Last 25 lines of text:\n%s" % lines) + bootlog = self.decode_qemulog(bootlog) + self.logger.warning("Last 25 lines of login console (%d):\n%s" % (len(bootlog), tail(bootlog))) + self.logger.warning("Last 25 lines of all logging (%d):\n%s" % (len(self.msg), tail(self.msg))) self.logger.warning("Check full boot log: %s" % self.logfile) - self._dump_host() self.stop() + data = True + while data: + try: + time.sleep(1) + data = qemusock.recv(1024) + self.log(data, extension = ".2") + self.logger.warning('Extra log data read: %s\n' % (data.decode('utf-8', errors='backslashreplace'))) + except Exception as e: + self.logger.warning('Extra log data exception %s' % repr(e)) + data = None + self.thread.serial_lock.release() return False + with self.thread.serial_lock: + self.thread.set_serialsock(self.server_socket) + # If we are not able to login the tests can continue try: (status, output) = self.run_serial(self.boot_patterns['send_login_user'], raw=True, timeout=120) if re.search(self.boot_patterns['search_login_succeeded'], output): self.logged = True - self.logger.debug("Logged as root in serial console") + self.logger.debug("Logged in as %s in serial console" % self.boot_patterns['send_login_user'].replace("\n", "")) if netconf: # configure guest networking cmd = "ifconfig eth0 %s netmask %s up\n" % (self.ip, self.netmask) @@ -512,7 +541,7 @@ class QemuRunner: self.logger.debug("Couldn't configure guest networking") else: self.logger.warning("Couldn't login into serial console" - " as root using blank password") + " as %s using blank password" % self.boot_patterns['send_login_user'].replace("\n", "")) self.logger.warning("The output:\n%s" % output) except: self.logger.warning("Serial console failed while trying to login") @@ -532,14 +561,17 @@ class QemuRunner: except OSError as e: if e.errno != errno.ESRCH: raise - endtime = time.time() + self.runqemutime - while self.runqemu.poll() is None and time.time() < endtime: - time.sleep(1) - if self.runqemu.poll() is None: + try: + outs, errs = self.runqemu.communicate(timeout=self.runqemutime) + if outs: + self.logger.info("Output from runqemu:\n%s", outs.decode("utf-8")) + if errs: + self.logger.info("Stderr from runqemu:\n%s", errs.decode("utf-8")) + except subprocess.TimeoutExpired: self.logger.debug("Sending SIGKILL to runqemu") os.killpg(os.getpgid(self.runqemu.pid), signal.SIGKILL) if not self.runqemu.stdout.closed: - self.logger.info("Output from runqemu:\n%s" % self.getOutput(self.runqemu.stdout)) + self.logger.info("Output from runqemu:\n%s" % getOutput(self.runqemu.stdout)) self.runqemu.stdin.close() self.runqemu.stdout.close() self.runqemu_exited = True @@ -598,8 +630,12 @@ class QemuRunner: # so it's possible that the file has been created but the content is empty pidfile_timeout = time.time() + 3 while time.time() < pidfile_timeout: - with open(self.qemu_pidfile, 'r') as f: - qemu_pid = f.read().strip() + try: + with open(self.qemu_pidfile, 'r') as f: + qemu_pid = f.read().strip() + except FileNotFoundError: + # Can be used to detect shutdown so the pid file can disappear + return False # file created but not yet written contents if not qemu_pid: time.sleep(0.5) @@ -612,41 +648,47 @@ class QemuRunner: def run_monitor(self, command, args=None, timeout=60): if hasattr(self, 'qmp') and self.qmp: + self.qmp.settimeout(timeout) if args is not None: - return self.qmp.cmd(command, args) + return self.qmp.cmd_raw(command, args) else: - return self.qmp.cmd(command) + return self.qmp.cmd_raw(command) def run_serial(self, command, raw=False, timeout=60): + # Returns (status, output) where status is 1 on success and 0 on error + # We assume target system have echo to get command status if not raw: command = "%s; echo $?\n" % command data = '' status = 0 - self.server_socket.sendall(command.encode('utf-8')) - start = time.time() - end = start + timeout - while True: - now = time.time() - if now >= end: - data += "<<< run_serial(): command timed out after %d seconds without output >>>\r\n\r\n" % timeout - break - try: - sread, _, _ = select.select([self.server_socket],[],[], end - now) - except InterruptedError: - continue - if sread: - answer = self.server_socket.recv(1024) - if answer: - data += answer.decode('utf-8') - # Search the prompt to stop - if re.search(self.boot_patterns['search_cmd_finished'], data): - break - else: - if self.canexit: - return (1, "") - raise Exception("No data on serial console socket, connection closed?") + with self.thread.serial_lock: + self.server_socket.sendall(command.encode('utf-8')) + start = time.time() + end = start + timeout + while True: + now = time.time() + if now >= end: + data += "<<< run_serial(): command timed out after %d seconds without output >>>\r\n\r\n" % timeout + break + try: + sread, _, _ = select.select([self.server_socket],[],[], end - now) + except InterruptedError: + continue + if sread: + # try to avoid reading single character at a time + time.sleep(0.1) + answer = self.server_socket.recv(1024) + if answer: + data += answer.decode('utf-8') + # Search the prompt to stop + if re.search(self.boot_patterns['search_cmd_finished'], data): + break + else: + if self.canexit: + return (1, "") + raise Exception("No data on serial console socket, connection closed?") if data: if raw: @@ -665,21 +707,27 @@ class QemuRunner: status = 1 return (status, str(data)) - - def _dump_host(self): - self.host_dumper.create_dir("qemu") - self.logger.warning("Qemu ended unexpectedly, dump data from host" - " is in %s" % self.host_dumper.dump_dir) - self.host_dumper.dump_host() +@contextmanager +def nonblocking_lock(lock): + locked = lock.acquire(False) + try: + yield locked + finally: + if locked: + lock.release() # This class is for reading data from a socket and passing it to logfunc # to be processed. It's completely event driven and has a straightforward # event loop. The mechanism for stopping the thread is a simple pipe which # will wake up the poll and allow for tearing everything down. class LoggingThread(threading.Thread): - def __init__(self, logfunc, sock, logger): + def __init__(self, logfunc, sock, logger, qemuoutput): self.connection_established = threading.Event() + self.serial_lock = threading.Lock() + self.serversock = sock + self.serialsock = None + self.qemuoutput = qemuoutput self.logfunc = logfunc self.logger = logger self.readsock = None @@ -691,9 +739,14 @@ class LoggingThread(threading.Thread): threading.Thread.__init__(self, target=self.threadtarget) + def set_serialsock(self, serialsock): + self.serialsock = serialsock + def threadtarget(self): try: self.eventloop() + except Exception as e: + self.logger.warning("Exception %s in logging thread" % traceback.format_exception(e)) finally: self.teardown() @@ -709,7 +762,8 @@ class LoggingThread(threading.Thread): def teardown(self): self.logger.debug("Tearing down logging thread") - self.close_socket(self.serversock) + if self.serversock: + self.close_socket(self.serversock) if self.readsock is not None: self.close_socket(self.readsock) @@ -724,27 +778,31 @@ class LoggingThread(threading.Thread): def eventloop(self): poll = select.poll() event_read_mask = self.errorevents | self.readevents - poll.register(self.serversock.fileno()) + if self.serversock: + poll.register(self.serversock.fileno()) + serial_registered = False + poll.register(self.qemuoutput.fileno()) poll.register(self.readpipe, event_read_mask) breakout = False self.running = True self.logger.debug("Starting thread event loop") while not breakout: - events = poll.poll() - for event in events: + events = poll.poll(2) + for fd, event in events: + # An error occurred, bail out - if event[1] & self.errorevents: - raise Exception(self.stringify_event(event[1])) + if event & self.errorevents: + raise Exception(self.stringify_event(event)) # Event to stop the thread - if self.readpipe == event[0]: + if self.readpipe == fd: self.logger.debug("Stop event received") breakout = True break # A connection request was received - elif self.serversock.fileno() == event[0]: + elif self.serversock and self.serversock.fileno() == fd: self.logger.debug("Connection request received") self.readsock, _ = self.serversock.accept() self.readsock.setblocking(0) @@ -755,15 +813,35 @@ class LoggingThread(threading.Thread): self.connection_established.set() # Actual data to be logged - elif self.readsock.fileno() == event[0]: - data = self.recv(1024) + elif self.readsock and self.readsock.fileno() == fd: + data = self.recv(1024, self.readsock) self.logfunc(data) + elif self.qemuoutput.fileno() == fd: + data = self.qemuoutput.read() + self.logger.debug("Data received on qemu stdout %s" % data) + self.logfunc(data, ".stdout") + elif self.serialsock and self.serialsock.fileno() == fd: + if self.serial_lock.acquire(blocking=False): + data = self.recv(1024, self.serialsock) + self.logger.debug("Data received serial thread %s" % data.decode('utf-8', 'replace')) + self.logfunc(data, ".2") + self.serial_lock.release() + else: + serial_registered = False + poll.unregister(self.serialsock.fileno()) + + if not serial_registered and self.serialsock: + with nonblocking_lock(self.serial_lock) as l: + if l: + serial_registered = True + poll.register(self.serialsock.fileno(), event_read_mask) + # Since the socket is non-blocking make sure to honor EAGAIN # and EWOULDBLOCK. - def recv(self, count): + def recv(self, count, sock): try: - data = self.readsock.recv(count) + data = sock.recv(count) except socket.error as e: if e.errno == errno.EAGAIN or e.errno == errno.EWOULDBLOCK: return b'' @@ -791,6 +869,9 @@ class LoggingThread(threading.Thread): val = 'POLLHUP' elif select.POLLNVAL == event: val = 'POLLNVAL' + else: + val = "0x%x" % (event) + return val def close_socket(self, sock): diff --git a/meta/lib/oeqa/utils/subprocesstweak.py b/meta/lib/oeqa/utils/subprocesstweak.py index b47975a4bc..3e43ed547b 100644 --- a/meta/lib/oeqa/utils/subprocesstweak.py +++ b/meta/lib/oeqa/utils/subprocesstweak.py @@ -1,4 +1,6 @@ # +# Copyright OpenEmbedded Contributors +# # SPDX-License-Identifier: MIT # import subprocess |