diff options
Diffstat (limited to 'tests/topotests/munet')
-rw-r--r-- | tests/topotests/munet/base.py | 72 | ||||
-rw-r--r-- | tests/topotests/munet/cli.py | 5 | ||||
-rw-r--r-- | tests/topotests/munet/linux.py | 11 | ||||
-rw-r--r-- | tests/topotests/munet/mutest/userapi.py | 184 | ||||
-rw-r--r-- | tests/topotests/munet/native.py | 144 | ||||
-rw-r--r-- | tests/topotests/munet/testing/fixtures.py | 2 | ||||
-rw-r--r-- | tests/topotests/munet/testing/hooks.py | 4 | ||||
-rw-r--r-- | tests/topotests/munet/watchlog.py | 170 |
8 files changed, 474 insertions, 118 deletions
diff --git a/tests/topotests/munet/base.py b/tests/topotests/munet/base.py index 06ca4de..72b5df5 100644 --- a/tests/topotests/munet/base.py +++ b/tests/topotests/munet/base.py @@ -21,7 +21,6 @@ import subprocess import sys import tempfile import time as time_mod - from collections import defaultdict from pathlib import Path from typing import Union @@ -29,10 +28,8 @@ from typing import Union from . import config as munet_config from . import linux - try: import pexpect - from pexpect.fdpexpect import fdspawn from pexpect.popen_spawn import PopenSpawn @@ -513,9 +510,8 @@ class Commander: # pylint: disable=R0904 self.logger.debug('%s("%s") [no precmd]', method, shlex.join(cmd_list)) else: self.logger.debug( - '%s: %s %s("%s", pre_cmd: "%s" use_pty: %s kwargs: %.120s)', + '%s: %s("%s", pre_cmd: "%s" use_pty: %s kwargs: %.120s)', self, - "XXX" if method == "_spawn" else "", method, cmd_list, pre_cmd_list if not skip_pre_cmd else "", @@ -566,7 +562,7 @@ class Commander: # pylint: disable=R0904 def _spawn(self, cmd, skip_pre_cmd=False, use_pty=False, echo=False, **kwargs): logging.debug( - '%s: XXX _spawn: cmd "%s" skip_pre_cmd %s use_pty %s echo %s kwargs %s', + '%s: _spawn: cmd "%s" skip_pre_cmd %s use_pty %s echo %s kwargs %s', self, cmd, skip_pre_cmd, @@ -579,7 +575,7 @@ class Commander: # pylint: disable=R0904 ) self.logger.debug( - '%s: XXX %s("%s", use_pty %s echo %s defaults: %s)', + '%s: %s("%s", use_pty %s echo %s defaults: %s)', self, "PopenSpawn" if not use_pty else "pexpect.spawn", actual_cmd, @@ -865,14 +861,18 @@ class Commander: # pylint: disable=R0904 else: o, e = await p.communicate() self.logger.debug( - "%s: cmd_p already exited status: %s", self, proc_error(p, o, e) + "%s: [cleanup_proc] proc already exited status: %s", + self, + proc_error(p, o, e), ) return None if pid is None: pid = p.pid - self.logger.debug("%s: terminate process: %s (pid %s)", self, proc_str(p), pid) + self.logger.debug( + "%s: [cleanup_proc] terminate process: %s (pid %s)", self, proc_str(p), pid + ) try: # This will SIGHUP and wait a while then SIGKILL and return immediately await self.cleanup_pid(p.pid, pid) @@ -885,14 +885,19 @@ class Commander: # pylint: disable=R0904 else: o, e = await asyncio.wait_for(p.communicate(), timeout=wait_secs) self.logger.debug( - "%s: cmd_p exited after kill, status: %s", self, proc_error(p, o, e) + "%s: [cleanup_proc] exited after kill, status: %s", + self, + proc_error(p, o, e), ) except (asyncio.TimeoutError, subprocess.TimeoutExpired): - self.logger.warning("%s: SIGKILL timeout", self) + self.logger.warning("%s: [cleanup_proc] SIGKILL timeout", self) return p except Exception as error: self.logger.warning( - "%s: kill unexpected exception: %s", self, error, exc_info=True + "%s: [cleanup_proc] kill unexpected exception: %s", + self, + error, + exc_info=True, ) return p return None @@ -1206,7 +1211,7 @@ class Commander: # pylint: disable=R0904 # XXX need to test ssh in Xterm sudo_path = get_exec_path_host(["sudo"]) # This first test case seems same as last but using list instead of string? - if self.is_vm and self.use_ssh: # pylint: disable=E1101 + if self.is_vm and self.use_ssh and not ns_only: # pylint: disable=E1101 if isinstance(cmd, str): cmd = shlex.split(cmd) cmd = ["/usr/bin/env", f"MUNET_NODENAME={self.name}"] + cmd @@ -1226,8 +1231,14 @@ class Commander: # pylint: disable=R0904 else: # This is the command to execute to be inside the namespace. # We are getting into trouble with quoting. - # Why aren't we passing in MUNET_RUNDIR? - cmd = f"/usr/bin/env MUNET_NODENAME={self.name} {cmd}" + envvars = f"MUNET_NODENAME={self.name} NODENAME={self.name}" + if hasattr(self, "rundir"): + envvars += f" RUNDIR={self.rundir}" + if hasattr(self.unet, "config_dirname") and self.unet.config_dirname: + envvars += f" CONFIGDIR={self.unet.config_dirname}" + elif "CONFIGDIR" in os.environ: + envvars += f" CONFIGDIR={os.environ['CONFIGDIR']}" + cmd = f"/usr/bin/env {envvars} {cmd}" # We need sudo b/c we are executing as the user inside the window system. sudo_path = get_exec_path_host(["sudo"]) nscmd = ( @@ -1337,6 +1348,14 @@ class Commander: # pylint: disable=R0904 "select-layout", "-t", pane_info if not tmux_target else tmux_target, + "even-horizontal", + ] + commander.cmd_status(cmd) + cmd = [ + get_exec_path_host("tmux"), + "select-layout", + "-t", + pane_info if not tmux_target else tmux_target, "tiled", ] commander.cmd_status(cmd) @@ -1915,18 +1934,19 @@ class LinuxNamespace(Commander, InterfaceMixin): assert unet is None self.uflags = uflags # - # Open file descriptors for current namespaces for later resotration. + # Open file descriptors for current namespaces for later restoration. # try: + # pidfd_open is actually present in 5.4, is this 5.8 check for another + # aspect of what the pidfd_open code is relying on, something in the + # namespace code? If not we can simply check for os.pidfd_open() being + # present as our compat module linux.py runtime patches it in if + # supported by the kernel. kversion = [int(x) for x in platform.release().split("-")[0].split(".")] kvok = kversion[0] > 5 or (kversion[0] == 5 and kversion[1] >= 8) except ValueError: kvok = False - if ( - not kvok - or sys.version_info[0] < 3 - or (sys.version_info[0] == 3 and sys.version_info[1] < 9) - ): + if not kvok: # get list of namespace file descriptors before we unshare self.p_ns_fds = [] self.p_ns_fnames = [] @@ -2005,8 +2025,10 @@ class LinuxNamespace(Commander, InterfaceMixin): stdout=stdout, stderr=stderr, text=True, - start_new_session=not unet, shell=False, + # start_new_session=not unet + # preexec_fn=os.setsid if not unet else None, + preexec_fn=os.setsid, ) # The pid number returned is in the global pid namespace. For unshare_inline @@ -2345,14 +2367,14 @@ class LinuxNamespace(Commander, InterfaceMixin): and self.pid != our_pid ): self.logger.debug( - "cleanup pid on separate pid %s from proc pid %s", + "cleanup separate pid %s from namespace proc pid %s", self.pid, self.p.pid if self.p else None, ) await self.cleanup_pid(self.pid) if self.p is not None: - self.logger.debug("cleanup proc pid %s", self.p.pid) + self.logger.debug("cleanup namespace proc pid %s", self.p.pid) await self.async_cleanup_proc(self.p) # return to the previous namespace, need to do this in case anothe munet @@ -2937,7 +2959,7 @@ if True: # pylint: disable=using-constant-test ) logging.debug( - 'ShellWraper: XXX prompt "%s" will_echo %s child.echo %s', + 'ShellWraper: prompt "%s" will_echo %s child.echo %s', prompt, will_echo, spawn.echo, diff --git a/tests/topotests/munet/cli.py b/tests/topotests/munet/cli.py index f631073..133644e 100644 --- a/tests/topotests/munet/cli.py +++ b/tests/topotests/munet/cli.py @@ -325,13 +325,14 @@ def get_shcmd(unet, host, kinds, execfmt, ucmd): if not execfmt: return "" - # Do substitutions for {} in string + # Do substitutions for {} and {N} in string numfmt = len(re.findall(r"{\d*}", execfmt)) if numfmt > 1: ucmd = execfmt.format(*shlex.split(ucmd)) elif numfmt: ucmd = execfmt.format(ucmd) - elif len(re.findall(r"{[a-zA-Z_][0-9a-zA-Z_\.]*}", execfmt)): + # look for any pair of {}s but do not count escaped {{ or }} + elif len(re.findall(r"{[^}]+}", execfmt.replace("{{", "").replace("}}", ""))): if execfmt.endswith('"'): fstring = "f'''" + execfmt + "'''" else: diff --git a/tests/topotests/munet/linux.py b/tests/topotests/munet/linux.py index 417f745..519c55f 100644 --- a/tests/topotests/munet/linux.py +++ b/tests/topotests/munet/linux.py @@ -132,8 +132,17 @@ def pidfd_open(pid, flags=0): return fd +# Runtime patch if kernel supports the call. if not hasattr(os, "pidfd_open"): - os.pidfd_open = pidfd_open + try: + import platform + + kversion = [int(x) for x in platform.release().split("-")[0].split(".")] + kvok = kversion[0] > 5 or (kversion[0] == 5 and kversion[1] >= 4) + except ValueError: + kvok = False + if kvok: + os.pidfd_open = pidfd_open def setns(fd, nstype): # noqa: D402 diff --git a/tests/topotests/munet/mutest/userapi.py b/tests/topotests/munet/mutest/userapi.py index 1df8c0d..7967dd0 100644 --- a/tests/topotests/munet/mutest/userapi.py +++ b/tests/topotests/munet/mutest/userapi.py @@ -144,7 +144,6 @@ class TestCase: result_logger: logging.Logger = None, full_summary: bool = False, ): - self.info = TestCaseInfo(tag, name, path) self.__saved_info = [] self.__short_doc_header = not full_summary @@ -248,7 +247,6 @@ class TestCase: self.rlog.info("%s. %s", tag, header) def __exec_script(self, path, print_header, add_newline): - # Below was the original method to avoid the global TestCase # variable; however, we need global functions so we can import them # into test scripts. Without imports pylint will complain about undefined @@ -393,12 +391,12 @@ class TestCase: self, target: str, cmd: str, - ) -> dict: + ) -> Union[list, dict]: """Execute a json ``cmd`` and return json result. Args: target: the target to execute the command on. - cmd: string to execut on the target. + cmd: string to execute on the target. """ out = self.targets[target].cmd_nostatus(cmd, warn=False) self.last = out = out.rstrip() @@ -420,6 +418,7 @@ class TestCase: match: str, expect_fail: bool, flags: int, + exact_match: bool, ) -> (bool, Union[str, list]): """Execute a ``cmd`` and check result. @@ -429,6 +428,8 @@ class TestCase: match: regex to ``re.search()`` for in output. expect_fail: if True then succeed when the regexp doesn't match. flags: python regex flags to modify matching behavior + exact_match: if True then ``match`` must be exactly matched somewhere + in the output of ``cmd`` using ``str.find()``. Returns: (success, matches): if the match fails then "matches" will be None, @@ -436,6 +437,17 @@ class TestCase: ``matches`` otherwise group(0) (i.e., the matching text). """ out = self._command(target, cmd) + if exact_match: + if match not in out: + success = expect_fail + ret = None + else: + success = not expect_fail + ret = match + level = logging.DEBUG if success else logging.WARNING + self.olog.log(level, "exactly matched:%s:", ret) + return success, ret + search = re.search(match, out, flags) self.last_m = search if search is None: @@ -455,17 +467,19 @@ class TestCase: self, target: str, cmd: str, - match: Union[str, dict], + match: Union[str, list, dict], expect_fail: bool, - ) -> Union[str, dict]: + exact_match: bool, + ) -> (bool, Union[list, dict]): """Execute a json ``cmd`` and check result. Args: target: the target to execute the command on. cmd: string to execut on the target. - match: A json ``str`` or object (``dict``) to compare against the json - output from ``cmd``. + match: A json ``str``, object (``dict``), or array (``list``) to + compare against the json output from ``cmd``. expect_fail: if True then succeed when the json doesn't match. + exact_match: if True then the json must exactly match. """ js = self._command_json(target, cmd) try: @@ -476,7 +490,27 @@ class TestCase: "JSON load failed. Check match value is in JSON format: %s", error ) - if json_diff := json_cmp(expect, js): + if exact_match: + deep_diff = json_cmp(expect, js) + # Convert DeepDiff completely into dicts or lists at all levels + json_diff = json.loads(deep_diff.to_json()) + else: + deep_diff = json_cmp(expect, js, ignore_order=True) + # Convert DeepDiff completely into dicts or lists at all levels + json_diff = json.loads(deep_diff.to_json()) + # Remove new fields in json object from diff + if json_diff.get("dictionary_item_added") is not None: + del json_diff["dictionary_item_added"] + # Remove new json objects in json array from diff + if (new_items := json_diff.get("iterable_item_added")) is not None: + new_item_paths = list(new_items.keys()) + for path in new_item_paths: + if type(new_items[path]) is dict: + del new_items[path] + if len(new_items) == 0: + del json_diff["iterable_item_added"] + + if json_diff: success = expect_fail if not success: self.logf("JSON DIFF:%s:" % json_diff) @@ -489,14 +523,24 @@ class TestCase: self, target: str, cmd: str, - match: Union[str, dict], + match: Union[str, list, dict], is_json: bool, timeout: float, interval: float, expect_fail: bool, flags: int, - ) -> Union[str, dict]: - """Execute a command repeatedly waiting for result until timeout.""" + exact_match: bool, + ) -> Union[str, list, dict]: + """Execute a command repeatedly waiting for result until timeout. + + ``match`` is a regular expression to search for in the output of ``cmd`` + when ``is_json`` is False. + + When ``is_json`` is True ``match`` must be a json object, a json array, + or a ``str`` which parses into a json object. Likewise, the ``cmd`` output + is parsed into a json object or array and then a comparison is done between + the two json objects or arrays. + """ startt = time.time() endt = startt + timeout @@ -504,10 +548,12 @@ class TestCase: ret = None while not success and time.time() < endt: if is_json: - success, ret = self._match_command_json(target, cmd, match, expect_fail) + success, ret = self._match_command_json( + target, cmd, match, expect_fail, exact_match + ) else: success, ret = self._match_command( - target, cmd, match, expect_fail, flags + target, cmd, match, expect_fail, flags, exact_match ) if not success: time.sleep(interval) @@ -626,7 +672,7 @@ class TestCase: ) return self._command(target, cmd) - def step_json(self, target: str, cmd: str) -> dict: + def step_json(self, target: str, cmd: str) -> Union[list, dict]: """See :py:func:`~munet.mutest.userapi.step_json`. :meta private: @@ -649,13 +695,14 @@ class TestCase: desc: str = "", expect_fail: bool = False, flags: int = re.DOTALL, + exact_match: bool = False, ) -> (bool, Union[str, list]): """See :py:func:`~munet.mutest.userapi.match_step`. :meta private: """ self.logf( - "#%s.%s:%s:MATCH_STEP:%s:%s:%s:%s:%s:%s", + "#%s.%s:%s:MATCH_STEP:%s:%s:%s:%s:%s:%s:%s", self.tag, self.steps + 1, self.info.path, @@ -665,8 +712,11 @@ class TestCase: desc, expect_fail, flags, + exact_match, + ) + success, ret = self._match_command( + target, cmd, match, expect_fail, flags, exact_match ) - success, ret = self._match_command(target, cmd, match, expect_fail, flags) if desc: self.__post_result(target, success, desc) return success, ret @@ -684,16 +734,17 @@ class TestCase: self, target: str, cmd: str, - match: Union[str, dict], + match: Union[str, list, dict], desc: str = "", expect_fail: bool = False, - ) -> (bool, Union[str, dict]): + exact_match: bool = False, + ) -> (bool, Union[list, dict]): """See :py:func:`~munet.mutest.userapi.match_step_json`. :meta private: """ self.logf( - "#%s.%s:%s:MATCH_STEP_JSON:%s:%s:%s:%s:%s", + "#%s.%s:%s:MATCH_STEP_JSON:%s:%s:%s:%s:%s:%s", self.tag, self.steps + 1, self.info.path, @@ -702,8 +753,11 @@ class TestCase: match, desc, expect_fail, + exact_match, + ) + success, ret = self._match_command_json( + target, cmd, match, expect_fail, exact_match ) - success, ret = self._match_command_json(target, cmd, match, expect_fail) if desc: self.__post_result(target, success, desc) return success, ret @@ -718,6 +772,7 @@ class TestCase: interval=0.5, expect_fail: bool = False, flags: int = re.DOTALL, + exact_match: bool = False, ) -> (bool, Union[str, list]): """See :py:func:`~munet.mutest.userapi.wait_step`. @@ -726,7 +781,7 @@ class TestCase: if interval is None: interval = min(timeout / 20, 0.25) self.logf( - "#%s.%s:%s:WAIT_STEP:%s:%s:%s:%s:%s:%s:%s:%s", + "#%s.%s:%s:WAIT_STEP:%s:%s:%s:%s:%s:%s:%s:%s:%s", self.tag, self.steps + 1, self.info.path, @@ -738,9 +793,18 @@ class TestCase: desc, expect_fail, flags, + exact_match, ) success, ret = self._wait( - target, cmd, match, False, timeout, interval, expect_fail, flags + target, + cmd, + match, + False, + timeout, + interval, + expect_fail, + flags, + exact_match, ) if desc: self.__post_result(target, success, desc) @@ -750,12 +814,13 @@ class TestCase: self, target: str, cmd: str, - match: Union[str, dict], + match: Union[str, list, dict], desc: str = "", timeout=10, interval=None, expect_fail: bool = False, - ) -> (bool, Union[str, dict]): + exact_match: bool = False, + ) -> (bool, Union[list, dict]): """See :py:func:`~munet.mutest.userapi.wait_step_json`. :meta private: @@ -763,7 +828,7 @@ class TestCase: if interval is None: interval = min(timeout / 20, 0.25) self.logf( - "#%s.%s:%s:WAIT_STEP:%s:%s:%s:%s:%s:%s:%s", + "#%s.%s:%s:WAIT_STEP:%s:%s:%s:%s:%s:%s:%s:%s", self.tag, self.steps + 1, self.info.path, @@ -774,9 +839,10 @@ class TestCase: interval, desc, expect_fail, + exact_match, ) success, ret = self._wait( - target, cmd, match, True, timeout, interval, expect_fail, 0 + target, cmd, match, True, timeout, interval, expect_fail, 0, exact_match ) if desc: self.__post_result(target, success, desc) @@ -864,15 +930,15 @@ def step(target: str, cmd: str) -> str: return TestCase.g_tc.step(target, cmd) -def step_json(target: str, cmd: str) -> dict: - """Execute a json ``cmd`` on a ``target`` and return the json object. +def step_json(target: str, cmd: str) -> Union[list, dict]: + """Execute a json ``cmd`` on a ``target`` and return the json object or array. Args: target: the target to execute the ``cmd`` on. cmd: string to execute on the target. Returns: - Returns the json object after parsing the ``cmd`` output. + Returns the json object or array after parsing the ``cmd`` output. If json parse fails, a warning is logged and an empty ``dict`` is used. """ @@ -904,6 +970,7 @@ def match_step( desc: str = "", expect_fail: bool = False, flags: int = re.DOTALL, + exact_match: bool = False, ) -> (bool, Union[str, list]): """Execute a ``cmd`` on a ``target`` check result. @@ -922,44 +989,53 @@ def match_step( desc: description of test, if no description then no result is logged. expect_fail: if True then succeed when the regexp doesn't match. flags: python regex flags to modify matching behavior + exact_match: if True then ``match`` must be exactly matched somewhere + in the output of ``cmd`` using ``str.find()``. Returns: Returns a 2-tuple. The first value is a bool indicating ``success``. The second value will be a list from ``re.Match.groups()`` if non-empty, otherwise ``re.Match.group(0)`` if there was a match otherwise None. """ - return TestCase.g_tc.match_step(target, cmd, match, desc, expect_fail, flags) + return TestCase.g_tc.match_step( + target, cmd, match, desc, expect_fail, flags, exact_match + ) def match_step_json( target: str, cmd: str, - match: Union[str, dict], + match: Union[str, list, dict], desc: str = "", expect_fail: bool = False, -) -> (bool, Union[str, dict]): + exact_match: bool = False, +) -> (bool, Union[list, dict]): """Execute a ``cmd`` on a ``target`` check result. - Execute ``cmd`` on ``target`` and check if the json object in ``match`` + Execute ``cmd`` on ``target`` and check if the json object or array in ``match`` matches or doesn't match (according to the ``expect_fail`` value) the json output from ``cmd``. Args: target: the target to execute the ``cmd`` on. cmd: string to execut on the ``target``. - match: A json ``str`` or object (``dict``) to compare against the json - output from ``cmd``. + match: A json ``str``, object (``dict``), or array (``list``) to compare + against the json output from ``cmd``. desc: description of test, if no description then no result is logged. expect_fail: if True then succeed if the a json doesn't match. + exact_match: if True then the json must exactly match. Returns: Returns a 2-tuple. The first value is a bool indicating ``success``. The - second value is a ``str`` diff if there is a difference found in the json - compare, otherwise the value is the json object (``dict``) from the ``cmd``. + second value is a ``dict`` of the diff if there is a difference found in + the json compare, otherwise the value is the json object (``dict``) or + array (``list``) from the ``cmd``. If json parse fails, a warning is logged and an empty ``dict`` is used. """ - return TestCase.g_tc.match_step_json(target, cmd, match, desc, expect_fail) + return TestCase.g_tc.match_step_json( + target, cmd, match, desc, expect_fail, exact_match + ) def wait_step( @@ -971,6 +1047,7 @@ def wait_step( interval: float = 0.5, expect_fail: bool = False, flags: int = re.DOTALL, + exact_match: bool = False, ) -> (bool, Union[str, list]): """Execute a ``cmd`` on a ``target`` repeatedly, looking for a result. @@ -991,6 +1068,8 @@ def wait_step( desc: description of test, if no description then no result is logged. expect_fail: if True then succeed when the regexp *doesn't* match. flags: python regex flags to modify matching behavior + exact_match: if True then ``match`` must be exactly matched somewhere + in the output of ``cmd`` using ``str.find()``. Returns: Returns a 2-tuple. The first value is a bool indicating ``success``. @@ -998,37 +1077,31 @@ def wait_step( otherwise ``re.Match.group(0)`` if there was a match otherwise None. """ return TestCase.g_tc.wait_step( - target, cmd, match, desc, timeout, interval, expect_fail, flags + target, cmd, match, desc, timeout, interval, expect_fail, flags, exact_match ) def wait_step_json( target: str, cmd: str, - match: Union[str, dict], + match: Union[str, list, dict], desc: str = "", timeout=10, interval=None, expect_fail: bool = False, -) -> (bool, Union[str, dict]): + exact_match: bool = False, +) -> (bool, Union[list, dict]): """Execute a cmd repeatedly and wait for matching result. Execute ``cmd`` on ``target``, every ``interval`` seconds until the output of ``cmd`` matches or doesn't match (according to the ``expect_fail`` value) ``match``, for up to ``timeout`` seconds. - ``match`` is a regular expression to search for in the output of ``cmd`` when - ``is_json`` is False. - - When ``is_json`` is True ``match`` must be a json object or a ``str`` which - parses into a json object. Likewise, the ``cmd`` output is parsed into a json - object and then a comparison is done between the two json objects. - Args: target: the target to execute the ``cmd`` on. cmd: string to execut on the ``target``. - match: A json object or str representation of one to compare against json - output from ``cmd``. + match: A json object, json array, or str representation of json to compare + against json output from ``cmd``. desc: description of test, if no description then no result is logged. timeout: The number of seconds to repeat the ``cmd`` looking for a match (or non-match if ``expect_fail`` is True). @@ -1037,17 +1110,18 @@ def wait_step_json( average the cmd will execute 10 times. The minimum calculated interval is .25s, shorter values can be passed explicitly. expect_fail: if True then succeed if the a json doesn't match. + exact_match: if True then the json must exactly match. Returns: Returns a 2-tuple. The first value is a bool indicating ``success``. - The second value is a ``str`` diff if there is a difference found in the - json compare, otherwise the value is a json object (dict) from the ``cmd`` - output. + The second value is a ``dict`` of the diff if there is a difference + found in the json compare, otherwise the value is a json object (``dict``) + or array (``list``) from the ``cmd`` output. If json parse fails, a warning is logged and an empty ``dict`` is used. """ return TestCase.g_tc.wait_step_json( - target, cmd, match, desc, timeout, interval, expect_fail + target, cmd, match, desc, timeout, interval, expect_fail, exact_match ) diff --git a/tests/topotests/munet/native.py b/tests/topotests/munet/native.py index fecf709..4fbbb85 100644 --- a/tests/topotests/munet/native.py +++ b/tests/topotests/munet/native.py @@ -20,6 +20,8 @@ import socket import subprocess import time +from pathlib import Path + from . import cli from .base import BaseMunet from .base import Bridge @@ -38,6 +40,7 @@ from .config import config_to_dict_with_key from .config import find_matching_net_config from .config import find_with_kv from .config import merge_kind_config +from .watchlog import WatchLog class L3ContainerNotRunningError(MunetError): @@ -455,13 +458,14 @@ class NodeMixin: bps = self.unet.cfgopt.getoption("--gdb-breakpoints", "").split(",") for bp in bps: - gdbcmd += f" '-ex=b {bp}'" + if bp: + gdbcmd += f" '-ex=b {bp}'" - cmds = self.config.get("gdb-run-cmd", []) + cmds = self.config.get("gdb-run-cmds", []) for cmd in cmds: gdbcmd += f" '-ex={cmd}'" - self.run_in_window(gdbcmd) + self.run_in_window(gdbcmd, ns_only=True) elif should_gdb and use_emacs: gdbcmd = gdbcmd.replace("gdb ", "gdb -i=mi ") ecbin = self.get_exec_path("emacsclient") @@ -664,6 +668,7 @@ class L3NodeMixin(NodeMixin): self.phycount = 0 self.phy_odrivers = {} self.tapmacs = {} + self.watched_logs = {} self.intf_tc_count = 0 @@ -723,6 +728,26 @@ ff02::2\tip6-allrouters if hasattr(self, "bind_mount"): self.bind_mount(hosts_file, "/etc/hosts") + def add_watch_log(self, path, watchfor_re=None): + """Add a WatchLog to this nodes watched logs. + + Args: + path: If relative is relative to the nodes ``rundir`` + watchfor_re: Regular expression to watch the log for and raise an exception + if found. + + Return: + The watching task if request or None otherwise. + """ + path = Path(path) + if not path.is_absolute(): + path = self.rundir.joinpath(path) + + wl = WatchLog(path) + self.watched_logs[wl.path] = wl + task = wl.raise_if_match_task(watchfor_re) if watchfor_re else None + return task + async def console( self, concmd, @@ -938,8 +963,32 @@ ff02::2\tip6-allrouters if hname in self.host_intfs: return self.host_intfs[hname] = lname - self.unet.rootcmd.cmd_nostatus(f"ip link set {hname} down ") - self.unet.rootcmd.cmd_raises(f"ip link set {hname} netns {self.pid}") + + # See if this interace is missing and needs to be fixed + rc, o, _ = self.unet.rootcmd.cmd_status("ip -o link show") + m = re.search(rf"\d+:\s+(\S+):.*altname {re.escape(hname)}\W", o) + if m: + # need to rename + dname = m.group(1) + self.logger.info("Fixing misnamed %s to %s", dname, hname) + self.unet.rootcmd.cmd_status( + f"ip link property del dev {dname} altname {hname}" + ) + self.unet.rootcmd.cmd_status(f"ip link set {dname} name {hname}") + + rc, o, _ = self.unet.rootcmd.cmd_status("ip -o link show") + m = re.search(rf"\d+:\s+{re.escape(hname)}:.*", o) + if m: + self.unet.rootcmd.cmd_nostatus(f"ip link set {hname} down ") + self.unet.rootcmd.cmd_raises(f"ip link set {hname} netns {self.pid}") + # Wait for interface to show up in namespace + for retry in range(0, 10): + rc, o, _ = self.cmd_status(f"ip -o link show {hname}") + if not rc: + if re.search(rf"\d+: {re.escape(hname)}:.*", o): + break + if retry > 0: + await asyncio.sleep(1) self.cmd_raises(f"ip link set {hname} name {lname}") if mtu: self.cmd_raises(f"ip link set {lname} mtu {mtu}") @@ -949,7 +998,12 @@ ff02::2\tip6-allrouters lname = self.host_intfs[hname] self.cmd_raises(f"ip link set {lname} down") self.cmd_raises(f"ip link set {lname} name {hname}") - self.cmd_raises(f"ip link set {hname} netns 1") + self.cmd_status(f"ip link set netns 1 dev {hname}") + # The above is failing sometimes and not sure why + # logging.error( + # "XXX after setns %s", + # self.unet.rootcmd.cmd_nostatus(f"ip link show {hname}"), + # ) del self.host_intfs[hname] async def add_phy_intf(self, devaddr, lname): @@ -1019,12 +1073,13 @@ ff02::2\tip6-allrouters "Physical PCI device %s already bound to vfio-pci", devaddr ) return + self.logger.info( "Unbinding physical PCI device %s from driver %s", devaddr, driver ) self.phy_odrivers[devaddr] = driver self.unet.rootcmd.cmd_raises( - f"echo {devaddr} > /sys/bus/pci/drivers/{driver}/unbind" + f"echo {devaddr} | timeout 10 tee /sys/bus/pci/drivers/{driver}/unbind" ) # Add the device vendor and device id to vfio-pci in case it's the first time @@ -1035,7 +1090,14 @@ ff02::2\tip6-allrouters f"echo {vendor} {devid} > /sys/bus/pci/drivers/vfio-pci/new_id", warn=False ) - if not self.unet.rootcmd.path_exists(f"/sys/bus/pci/driver/vfio-pci/{devaddr}"): + for retry in range(0, 10): + if self.unet.rootcmd.path_exists( + f"/sys/bus/pci/drivers/vfio-pci/{devaddr}" + ): + break + if retry > 0: + await asyncio.sleep(1) + # Bind to vfio-pci if wasn't added with new_id self.logger.info("Binding physical PCI device %s to vfio-pci", devaddr) ec, _, _ = self.unet.rootcmd.cmd_status( @@ -1066,7 +1128,7 @@ ff02::2\tip6-allrouters "Unbinding physical PCI device %s from driver vfio-pci", devaddr ) self.unet.rootcmd.cmd_status( - f"echo {devaddr} > /sys/bus/pci/drivers/vfio-pci/unbind" + f"echo {devaddr} | timeout 10 tee /sys/bus/pci/drivers/vfio-pci/unbind" ) self.logger.info("Binding physical PCI device %s to driver %s", devaddr, driver) @@ -1085,13 +1147,13 @@ ff02::2\tip6-allrouters for hname in list(self.host_intfs): await self.rem_host_intf(hname) - # remove any hostintf interfaces - for devaddr in list(self.phy_intfs): - await self.rem_phy_intf(devaddr) - # delete the LinuxNamespace/InterfaceMixin await super()._async_delete() + # remove any hostintf interfaces, needs to come after normal exits + for devaddr in list(self.phy_intfs): + await self.rem_phy_intf(devaddr) + class L3NamespaceNode(L3NodeMixin, LinuxNamespace): """A namespace L3 node.""" @@ -1123,6 +1185,7 @@ class L3ContainerNode(L3NodeMixin, LinuxNamespace): assert self.container_image self.cmd_p = None + self.cmd_pid = None self.__base_cmd = [] self.__base_cmd_pty = [] @@ -1393,7 +1456,13 @@ class L3ContainerNode(L3NodeMixin, LinuxNamespace): start_new_session=True, # keeps main tty signals away from podman ) - self.logger.debug("%s: async_popen => %s", self, self.cmd_p.pid) + # If our process is actually the child of an nsenter fetch its pid. + if self.nsenter_fork: + self.cmd_pid = await self.get_proc_child_pid(self.cmd_p) + + self.logger.debug( + "%s: async_popen => %s (%s)", self, self.cmd_p.pid, self.cmd_pid + ) self.pytest_hook_run_cmd(stdout, stderr) @@ -1542,6 +1611,7 @@ class L3QemuVM(L3NodeMixin, LinuxNamespace): """Create a Container Node.""" self.cont_exec_paths = {} self.launch_p = None + self.launch_pid = None self.qemu_config = config["qemu"] self.extra_mounts = [] assert self.qemu_config @@ -1968,8 +2038,9 @@ class L3QemuVM(L3NodeMixin, LinuxNamespace): con.cmd_raises(f"ip -6 route add default via {switch.ip6_address}") con.cmd_raises("ip link set lo up") - if self.unet.cfgopt.getoption("--coverage"): - con.cmd_raises("mount -t debugfs none /sys/kernel/debug") + # This is already mounted now + # if self.unet.cfgopt.getoption("--coverage"): + # con.cmd_raises("mount -t debugfs none /sys/kernel/debug") async def gather_coverage_data(self): con = self.conrepl @@ -2261,25 +2332,29 @@ class L3QemuVM(L3NodeMixin, LinuxNamespace): stdout = open(os.path.join(self.rundir, "qemu.out"), "wb") stderr = open(os.path.join(self.rundir, "qemu.err"), "wb") - self.launch_p = await self.async_popen( + self.launch_p = await self.async_popen_nsonly( args, stdin=subprocess.DEVNULL, stdout=stdout, stderr=stderr, pass_fds=pass_fds, - # We don't need this here b/c we are only ever running qemu and that's all - # we need to kill for cleanup - # XXX reconcile this - start_new_session=True, # allows us to signal all children to exit + # Don't want Keybaord interrupt etc to pass to child. + # start_new_session=True, + preexec_fn=os.setsid, ) + if self.nsenter_fork: + self.launch_pid = await self.get_proc_child_pid(self.launch_p) + self.pytest_hook_run_cmd(stdout, stderr) # We've passed these on, so don't need these open here anymore. for fd in pass_fds: os.close(fd) - self.logger.debug("%s: async_popen => %s", self, self.launch_p.pid) + self.logger.debug( + "%s: popen => %s (%s)", self, self.launch_p.pid, self.launch_pid + ) confiles = ["_console"] if use_cmdcon: @@ -2307,10 +2382,10 @@ class L3QemuVM(L3NodeMixin, LinuxNamespace): # the monitor output has super annoying ANSI escapes in it output = self.monrepl.cmd_nostatus("info status") - self.logger.info("VM status: %s", output) + self.logger.debug("VM status: %s", output) output = self.monrepl.cmd_nostatus("info kvm") - self.logger.info("KVM status: %s", output) + self.logger.debug("KVM status: %s", output) # # Set thread affinity @@ -2348,11 +2423,6 @@ class L3QemuVM(L3NodeMixin, LinuxNamespace): "%s: node launch (qemu) cmd wait() canceled: %s", future, error ) - async def cleanup_qemu(self): - """Launch qemu.""" - if self.launch_p: - await self.async_cleanup_proc(self.launch_p) - async def async_cleanup_cmd(self): """Run the configured cleanup commands for this node.""" self.cleanup_called = True @@ -2372,7 +2442,7 @@ class L3QemuVM(L3NodeMixin, LinuxNamespace): # Need to cleanup early b/c it is running on the VM if self.cmd_p: - await self.async_cleanup_proc(self.cmd_p) + await self.async_cleanup_proc(self.cmd_p, self.cmd_pid) self.cmd_p = None try: @@ -2388,9 +2458,9 @@ class L3QemuVM(L3NodeMixin, LinuxNamespace): if not self.launch_p: self.logger.warning("async_delete: qemu is not running") else: - await self.cleanup_qemu() + await self.async_cleanup_proc(self.launch_p, self.launch_pid) except Exception as error: - self.logger.warning("%s: failued to cleanup qemu process: %s", self, error) + self.logger.warning("%s: failed to cleanup qemu process: %s", self, error) await super()._async_delete() @@ -2814,6 +2884,8 @@ ff02::2\tip6-allrouters logging.debug("Launching nodes") await asyncio.gather(*[x.launch() for x in launch_nodes]) + logging.debug("Launched nodes -- Queueing Waits") + # Watch for launched processes to exit for node in launch_nodes: task = asyncio.create_task( @@ -2822,17 +2894,23 @@ ff02::2\tip6-allrouters task.add_done_callback(node.launch_completed) tasks.append(task) + logging.debug("Wait complete queued, running cmd") + if run_nodes: # would like a info when verbose here. logging.debug("Running `cmd` on nodes") await asyncio.gather(*[x.run_cmd() for x in run_nodes]) + logging.debug("Ran cmds -- Queueing Waits") + # Watch for run_cmd processes to exit for node in run_nodes: task = asyncio.create_task(node.cmd_p.wait(), name=f"Node-{node.name}-cmd") task.add_done_callback(node.cmd_completed) tasks.append(task) + logging.debug("Wait complete queued, waiting for ready") + # Wait for nodes to be ready if ready_nodes: @@ -2853,6 +2931,8 @@ ff02::2\tip6-allrouters raise asyncio.TimeoutError() logging.debug("All nodes ready") + logging.debug("All done returning tasks: %s", tasks) + return tasks async def _async_delete(self): diff --git a/tests/topotests/munet/testing/fixtures.py b/tests/topotests/munet/testing/fixtures.py index 25039df..3c6d946 100644 --- a/tests/topotests/munet/testing/fixtures.py +++ b/tests/topotests/munet/testing/fixtures.py @@ -95,7 +95,7 @@ def _push_log_handler(desc, logpath): logging.debug("conftest: adding %s logging at %s", desc, logpath) root_logger = logging.getLogger() handler = logging.FileHandler(logpath, mode="w") - fmt = logging.Formatter("%(asctime)s %(levelname)5s: %(message)s") + fmt = logging.Formatter("%(asctime)s %(levelname)5s: %(name)s: %(message)s") handler.setFormatter(fmt) root_logger.addHandler(handler) return handler diff --git a/tests/topotests/munet/testing/hooks.py b/tests/topotests/munet/testing/hooks.py index 9b6a49a..985eef9 100644 --- a/tests/topotests/munet/testing/hooks.py +++ b/tests/topotests/munet/testing/hooks.py @@ -196,10 +196,10 @@ def pytest_runtest_makereport(item, call): if error: item.skip_more_pause = True - # we can't asyncio.run() (which pause does) if we are unhsare_inline + # we can't asyncio.run() (which pause does) if we are not unhsare_inline # at this point, count on an autouse fixture to pause instead in this # case - if not BaseMunet.g_unet or not BaseMunet.g_unet.unshare_inline: + if BaseMunet.g_unet and BaseMunet.g_unet.unshare_inline: pause_test(f"before test '{item.nodeid}'") # check for a result to try and catch setup (or module setup) failure diff --git a/tests/topotests/munet/watchlog.py b/tests/topotests/munet/watchlog.py new file mode 100644 index 0000000..27bc325 --- /dev/null +++ b/tests/topotests/munet/watchlog.py @@ -0,0 +1,170 @@ +# -*- coding: utf-8 eval: (blacken-mode 1) -*- +# SPDX-License-Identifier: GPL-2.0-or-later +# +# August 21 2023, Christian Hopps <chopps@labn.net> +# +# Copyright (c) 2023, LabN Consulting, L.L.C. +# +"""A module supporting an object for watching a logfile.""" +import asyncio +import logging +import re + +from pathlib import Path + + +class MatchFoundError(Exception): + """An error raised when a match is not found.""" + def __init__(self, watchlog, match): + self.watchlog = watchlog + self.match = match + super().__init__(watchlog, match) + + +class WatchLog: + """An object for watching a logfile.""" + + def __init__(self, path, encoding="utf-8"): + """Watch a logfile. + + Args: + path: that path of the logfile to watch + encoding: the encoding of the logfile + """ + # Immutable + self.path = Path(path) + self.encoding = encoding + + # Mutable + self.content = "" + self.last_snap_mark = 0 + self.last_user_mark = 0 + self.stat = None + + if self.path.exists(): + self.snapshot() + + def _stat_snapshot(self): + ostat = self.stat + + if not self.path.exists(): + self.stat = None + return ostat is not None + + stat = self.path.stat() + self.stat = stat + + if ostat is None: + return True + + return ( + stat.st_mtime_ns != ostat.st_mtime_ns + or stat.st_ctime_ns != ostat.st_ctime_ns + or stat.st_ino != ostat.st_ino + or stat.st_size != ostat.st_size + ) + + def reset(self): + self.content = "" + self.last_user_mark = 0 + self.last_snap_mark = 0 + + def update_content(self): + ostat = self.stat + osize = ostat.st_size if ostat else 0 + oino = ostat.st_ino if ostat else -1 + if not self._stat_snapshot(): + logging.debug("XXX logfile %s no stat change", self.path) + return "" + + nino = self.stat.st_ino + # If the inode changed and we had content previously warn + if oino != -1 and oino != nino and self.content: + logging.warning( + "logfile %s replaced (new inode) resetting content", self.path + ) + self.reset() + osize = 0 + + nsize = self.stat.st_size + if osize > nsize: + logging.warning("logfile %s shrunk resetting content", self.path) + self.reset() + osize = 0 + + if osize == nsize: + logging.debug( + "XXX watchlog: %s no update, osize == nsize == %s", self.path, osize + ) + return "" + + # Read non-blocking + with open(self.path, "r", encoding=self.encoding) as f: + if osize: + f.seek(osize) + logging.debug( + "XXX watchlog: %s reading new content from %s to %s", + self.path, + osize, + nsize, + ) + newcontent = f.read(nsize - osize) + + self.content += newcontent + return newcontent + + def raise_if_match_task(self, match): + """Start an async task that searches for a match. + + This doesn't work well with pytest as the task must be awaited for the exception + to propagate. + """ + + async def scan_for_match(wl, regex): + while True: + logging.debug("watchlog: %s scan for updating content", wl.path) + wl.update_content() + if m := regex.search(wl.content): + logging.error( + "XXX watchlog: %s regexp FOUND raising exception!", wl.path + ) + raise MatchFoundError(wl, m) + await asyncio.sleep(2) + + aw = scan_for_match(self, re.compile(match)) + return asyncio.create_task(aw) + + def from_mark(self, mark=None): + """Return the file content starting from ``mark``. + + If ``mark`` is None then return content since last ``set_mark`` was called. + + Args: + mark: the mark in the content to return file content from. + + Return: + returns the content between ``mark`` and the end of content. + """ + return self.content[mark:] + + def set_mark(self): + """Set a mark for later use.""" + last_mark = self.last_user_mark + self.last_user_mark = len(self.content) + return last_mark + + def snapshot(self): + """Update the file content and return new text. + + Returns any new text added since the last snapshot, + also updates the snapshot mark. + + Return: + Newly added text. + """ + # Update the content which may reset marks + self.update_content() + + last_mark = self.last_snap_mark + self.last_snap_mark = len(self.content) + return self.content[last_mark:] |