From cd635521219e7d7988ccfd9d0a173ba07217cd00 Mon Sep 17 00:00:00 2001 From: Vratko Polak Date: Thu, 13 Jun 2019 16:58:30 +0200 Subject: [PATCH] SetupFramework: log thread error to console Because logger.error from a non-main thread is lost. + Increase verbosity of virtualenv exception. + Introduce LocalExecution.py library. + Include multiple other style improvements. + Add some ssh.py improvements: + Accept also commands of OptionString type. + Introduce a limited form of raise_from for exception chaining. + Add include_reason argument to exec_cmd_no_error. Change-Id: I0cd92bcdaa1a5c4cc20cb99067593fc3b40d2c31 Signed-off-by: Vratko Polak --- resources/libraries/python/LocalExecution.py | 98 +++++++++++++++++++++ resources/libraries/python/SetupFramework.py | 127 +++++++++++---------------- resources/libraries/python/ssh.py | 83 +++++++++++------ 3 files changed, 205 insertions(+), 103 deletions(-) create mode 100644 resources/libraries/python/LocalExecution.py diff --git a/resources/libraries/python/LocalExecution.py b/resources/libraries/python/LocalExecution.py new file mode 100644 index 0000000000..bb4cf794a1 --- /dev/null +++ b/resources/libraries/python/LocalExecution.py @@ -0,0 +1,98 @@ +# Copyright (c) 2019 Cisco and/or its affiliates. +# Licensed under the Apache License, Version 2.0 (the "License"); +# you may not use this file except in compliance with the License. +# You may obtain a copy of the License at: +# +# http://www.apache.org/licenses/LICENSE-2.0 +# +# Unless required by applicable law or agreed to in writing, software +# distributed under the License is distributed on an "AS IS" BASIS, +# WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +# See the License for the specific language governing permissions and +# limitations under the License. + +"""Python library from executing command on local hosts. + +Subprocess offers various functions, +but there are differences between Python 2 and 3. + +Overall, it is more convenient to introduce this internal API +so call sites are shorter and unified. + +This library should support commands given as Iterable, OptionString. + +Commands given as a string are explicitly not supported, +call sites should call .split(" ") on their own risk. +Similarly, parts within OptionString should not be aggregates. +Alternatively, long string can be wrapped as 'bash -c "{str}"'. +Both approaches can be hacked by malicious values. +""" + +import subprocess + +from robot.api import logger + +from resources.libraries.python.OptionString import OptionString + +__all__ = ["run"] + + +MESSAGE_TEMPLATE = "Command {com} ended with RC {ret} and output:\n{out}" + + +def run(command, msg="", check=False, log=True, console=False): + """Wrapper around subprocess.check_output that can tolerates nonzero RCs. + + Stderr is redirected to stdout, so it is part of output + (but can be mingled as the two streams are buffered independently). + If check and rc is nonzero, RuntimeError is raised. + If log (and not checked failure), both rc and output are logged. + Logging is performed on robot logger. By default .debug(), + optionally .console() instead. + The default log message is optionally prepended by user-given string, + separated by ": ". + + Commands given as single string are not supported, for safety reasons. + Invoke bash explicitly if you need its glob support for arguments. + + :param command: List of commands and arguments. Split your long string. + :param msg: Message prefix. Argument name is short just to save space. + :param check: Whether to raise if return code is nonzero. + :param log: Whether to log results. + :param console: Whether use .console() instead of .debug(). + Mainly useful when running from non-main thread. + :type command: Iterable or OptionString + :type msg: str + :type check: bool + :type log: bool + :type console: bool + :returns: rc and output + :rtype: 2-tuple of int and str + :raises RuntimeError: If check is true and return code non-zero. + :raises TypeError: If command is not an iterable. + """ + if isinstance(command, OptionString): + command = command.parts + if not hasattr(command, "__iter__"): + # Strings are indexable, but turning into iterator is not supported. + raise TypeError("Command {cmd!r} is not an iterable.".format( + cmd=command)) + ret_code = 0 + output = "" + try: + output = subprocess.check_output(command, stderr=subprocess.STDOUT) + except subprocess.CalledProcessError as err: + output = err.output + ret_code = err.returncode + if check: + raise RuntimeError(MESSAGE_TEMPLATE.format( + com=err.cmd, ret=ret_code, out=output)) + if log: + message = MESSAGE_TEMPLATE.format(com=command, ret=ret_code, out=output) + if msg: + message = msg + ": " + message + if console: + logger.console(message) + else: + logger.debug(message) + return ret_code, output diff --git a/resources/libraries/python/SetupFramework.py b/resources/libraries/python/SetupFramework.py index 9aff15278e..a1e4e7a679 100644 --- a/resources/libraries/python/SetupFramework.py +++ b/resources/libraries/python/SetupFramework.py @@ -1,4 +1,4 @@ -# Copyright (c) 2018 Cisco and/or its affiliates. +# Copyright (c) 2019 Cisco and/or its affiliates. # Licensed under the Apache License, Version 2.0 (the "License"); # you may not use this file except in compliance with the License. # You may obtain a copy of the License at: @@ -16,18 +16,16 @@ nodes. All tasks required to be run before the actual tests are started is supposed to end up here. """ -import datetime from os import environ, remove from os.path import basename -from shlex import split -from subprocess import Popen, PIPE from tempfile import NamedTemporaryFile import threading from robot.api import logger -from resources.libraries.python.ssh import SSH from resources.libraries.python.Constants import Constants as con +from resources.libraries.python.ssh import exec_cmd_no_error, scp_node +from resources.libraries.python.LocalExecution import run from resources.libraries.python.topology import NodeType __all__ = ["SetupFramework"] @@ -54,18 +52,9 @@ def pack_framework_dir(): file_name = tmpfile.name tmpfile.close() - proc = Popen( - split("tar --sparse --exclude-vcs --exclude=output*.xml " - "--exclude=./tmp -zcf {0} ." - .format(file_name)), stdout=PIPE, stderr=PIPE) - (stdout, stderr) = proc.communicate() - - logger.debug(stdout) - logger.debug(stderr) - - return_code = proc.wait() - if return_code != 0: - raise RuntimeError("Could not pack testing framework.") + run(["tar", "--sparse", "--exclude-vcs", "--exclude=output*.xml", + "--exclude=./tmp", "-zcf", file_name, "."], + check=True, msg="Could not pack testing framework") return file_name @@ -79,12 +68,10 @@ def copy_tarball_to_node(tarball, node): :type node: dict :returns: nothing """ - logger.console('Copying tarball to {0}'.format(node['host'])) - ssh = SSH() - ssh.connect(node) - - ssh.scp(tarball, "/tmp/") - logger.console('Copying tarball to {0} done'.format(node['host'])) + host = node['host'] + logger.console('Copying tarball to {0} starts.'.format(host)) + scp_node(node, tarball, "/tmp/") + logger.console('Copying tarball to {0} done.'.format(host)) def extract_tarball_at_node(tarball, node): @@ -99,18 +86,16 @@ def extract_tarball_at_node(tarball, node): :returns: nothing :raises RuntimeError: When failed to unpack tarball. """ - logger.console('Extracting tarball to {0} on {1}' - .format(con.REMOTE_FW_DIR, node['host'])) - ssh = SSH() - ssh.connect(node) - (ret_code, _, _) = ssh.exec_command( - 'sudo rm -rf {1}; mkdir {1} ; tar -zxf {0} -C {1}; rm -f {0}' - .format(tarball, con.REMOTE_FW_DIR), timeout=30) - if ret_code != 0: - raise RuntimeError('Failed to extract {0} at node {1}' - .format(tarball, node['host'])) - logger.console('Extracting tarball to {0} on {1} done' - .format(con.REMOTE_FW_DIR, node['host'])) + host = node['host'] + logger.console('Extracting tarball to {0} on {1} starts.' + .format(con.REMOTE_FW_DIR, host)) + exec_cmd_no_error( + node, "sudo rm -rf {1}; mkdir {1}; tar -zxf {0} -C {1};" + " rm -f {0}".format(tarball, con.REMOTE_FW_DIR), + message='Failed to extract {0} at node {1}'.format(tarball, host), + timeout=30, include_reason=True) + logger.console('Extracting tarball to {0} on {1} done.' + .format(con.REMOTE_FW_DIR, host)) def create_env_directory_at_node(node): @@ -121,21 +106,16 @@ def create_env_directory_at_node(node): :returns: nothing :raises RuntimeError: When failed to setup virtualenv. """ - logger.console('Virtualenv setup including requirements.txt on {0}' - .format(node['host'])) - ssh = SSH() - ssh.connect(node) - (ret_code, _, _) = ssh.exec_command( - 'cd {0} && rm -rf env && ' - 'virtualenv --system-site-packages --never-download env && ' - '. env/bin/activate && ' - 'pip install -r requirements.txt' - .format(con.REMOTE_FW_DIR), timeout=100) - if ret_code != 0: - raise RuntimeError('Virtualenv setup including requirements.txt on {0}' - .format(node['host'])) - - logger.console('Virtualenv on {0} created'.format(node['host'])) + host = node['host'] + logger.console('Virtualenv setup including requirements.txt on {0} starts.' + .format(host)) + exec_cmd_no_error( + node, 'cd {0} && rm -rf env' + ' && virtualenv --system-site-packages --never-download env' + ' && source env/bin/activate && pip install -r requirements.txt' + .format(con.REMOTE_FW_DIR), timeout=100, include_reason=True, + message="Failed install at node {host}".format(host=host)) + logger.console('Virtualenv setup on {0} done.'.format(host)) def setup_node(node, tarball, remote_tarball, results=None): @@ -152,17 +132,18 @@ def setup_node(node, tarball, remote_tarball, results=None): :returns: True - success, False - error :rtype: bool """ + host = node['host'] try: copy_tarball_to_node(tarball, node) extract_tarball_at_node(remote_tarball, node) if node['type'] == NodeType.TG: create_env_directory_at_node(node) except RuntimeError as exc: - logger.error("Node {0} setup failed, error:'{1}'" - .format(node['host'], exc.message)) + logger.console("Node {node} setup failed, error: {err!r}".format( + node=host, err=exc)) result = False else: - logger.console('Setup of node {0} done'.format(node['host'])) + logger.console('Setup of node {0} done.'.format(host)) result = True if isinstance(results, list): @@ -186,16 +167,15 @@ def delete_framework_dir(node): :param node: Node to delete framework directory on. :type node: dict """ - logger.console('Deleting framework directory on {0}' - .format(node['host'])) - ssh = SSH() - ssh.connect(node) - (ret_code, _, _) = ssh.exec_command( - 'sudo rm -rf {0}' - .format(con.REMOTE_FW_DIR), timeout=100) - if ret_code != 0: - raise RuntimeError('Deleting framework directory on {0} failed' - .format(node)) + host = node['host'] + logger.console( + 'Deleting framework directory on {0} starts.'.format(host)) + exec_cmd_no_error( + node, 'sudo rm -rf {0}'.format(con.REMOTE_FW_DIR), + message="Framework delete failed at node {host}".format(host=host), + timeout=100, include_reason=True) + logger.console( + 'Deleting framework directory on {0} done.'.format(host)) def cleanup_node(node, results=None): @@ -208,13 +188,14 @@ def cleanup_node(node, results=None): :returns: True - success, False - error :rtype: bool """ + host = node['host'] try: delete_framework_dir(node) except RuntimeError: - logger.error("Cleanup of node {0} failed".format(node['host'])) + logger.error("Cleanup of node {0} failed.".format(host)) result = False else: - logger.console('Cleanup of node {0} done'.format(node['host'])) + logger.console('Cleanup of node {0} done.'.format(host)) result = True if isinstance(results, list): @@ -249,10 +230,8 @@ class SetupFramework(object): threads = [] for node in nodes.values(): - thread = threading.Thread(target=setup_node, args=(node, - tarball, - remote_tarball, - results)) + args = node, tarball, remote_tarball, results + thread = threading.Thread(target=setup_node, args=args) thread.start() threads.append(thread) @@ -266,9 +245,9 @@ class SetupFramework(object): delete_local_tarball(tarball) if all(results): - logger.console('All nodes are ready') + logger.console('All nodes are ready.') else: - raise RuntimeError('Failed to setup framework') + raise RuntimeError('Failed to setup framework.') class CleanupFramework(object): @@ -293,7 +272,7 @@ class CleanupFramework(object): threads.append(thread) logger.info( - 'Executing node cleanups in parallel, waiting for threads to end') + 'Executing node cleanups in parallel, waiting for threads to end.') for thread in threads: thread.join() @@ -301,6 +280,6 @@ class CleanupFramework(object): logger.info('Results: {0}'.format(results)) if all(results): - logger.console('All nodes cleaned up') + logger.console('All nodes cleaned up.') else: - raise RuntimeError('Failed to cleaned up framework') + raise RuntimeError('Failed to cleaned up framework.') diff --git a/resources/libraries/python/ssh.py b/resources/libraries/python/ssh.py index 3523d57302..e4ac93fb1b 100644 --- a/resources/libraries/python/ssh.py +++ b/resources/libraries/python/ssh.py @@ -16,7 +16,6 @@ import socket import StringIO - from time import time, sleep from paramiko import RSAKey, SSHClient, AutoAddPolicy @@ -24,12 +23,32 @@ from paramiko.ssh_exception import SSHException, NoValidConnectionsError from robot.api import logger from scp import SCPClient, SCPException +from resources.libraries.python.OptionString import OptionString __all__ = ["exec_cmd", "exec_cmd_no_error"] # TODO: load priv key +def raise_from(raising, excepted): + """Function to be replaced by "raise from" in Python 3. + + Neither "six" nor "future" offer good enough implementation right now. + chezsoi.org/lucas/blog/displaying-chained-exceptions-stacktraces-in-python-2 + + Current implementation just logs excepted error, and raises the new one. + + :param raising: The exception to raise. + :param excepted: The exception we excepted and want to log. + :type raising: BaseException + :type excepted: BaseException + :raises: raising + """ + logger.error("Excepted: {exc!r}\nRaising: {rai!r}".format( + exc=excepted, rai=raising)) + raise raising + + class SSHTimeout(Exception): """This exception is raised when a timeout occurs.""" pass @@ -103,13 +122,13 @@ class SSH(object): peer=self._ssh.get_transport().getpeername(), total=(time() - start), ssh=self._ssh)) - except SSHException: - raise IOError('Cannot connect to {host}'. - format(host=node['host'])) + except SSHException as exc: + raise_from(IOError('Cannot connect to {host}'.format( + host=node['host'])), exc) except NoValidConnectionsError as err: - logger.error(repr(err)) - raise IOError('Unable to connect to port {port} on {host}'. - format(port=node['port'], host=node['host'])) + raise_from(IOError( + 'Unable to connect to port {port} on {host}'.format( + port=node['port'], host=node['host'])), err) def disconnect(self, node=None): """Close SSH connection to the node. @@ -156,17 +175,15 @@ class SSH(object): :rtype: tuple(int, str, str) :raises SSHTimeout: If command is not finished in timeout time. """ + if isinstance(cmd, (list, tuple)): + cmd = OptionString(cmd) cmd = str(cmd) stdout = StringIO.StringIO() stderr = StringIO.StringIO() try: chan = self._ssh.get_transport().open_session(timeout=5) peer = self._ssh.get_transport().getpeername() - except AttributeError: - self._reconnect() - chan = self._ssh.get_transport().open_session(timeout=5) - peer = self._ssh.get_transport().getpeername() - except SSHException: + except (AttributeError, SSHException): self._reconnect() chan = self._ssh.get_transport().open_session(timeout=5) peer = self._ssh.get_transport().getpeername() @@ -239,6 +256,8 @@ class SSH(object): >>> # Execute command with input (sudo -S cmd <<< "input") >>> ssh.exec_command_sudo("vpp_api_test", "dump_interface_table") """ + if isinstance(cmd, (list, tuple)): + cmd = OptionString(cmd) if cmd_input is None: command = 'sudo -S {c}'.format(c=cmd) else: @@ -298,9 +317,8 @@ class SSH(object): if chan.exit_status_ready(): logger.error('Channel exit status ready') break - except socket.timeout: - logger.error('Socket timeout: {0}'.format(buf)) - raise Exception('Socket timeout: {0}'.format(buf)) + except socket.timeout as exc: + raise_from(Exception('Socket timeout: {0}'.format(buf)), exc) return chan def interactive_terminal_exec_command(self, chan, cmd, prompt): @@ -332,11 +350,10 @@ class SSH(object): if chan.exit_status_ready(): logger.error('Channel exit status ready') break - except socket.timeout: - logger.error('Socket timeout during execution of command: ' - '{0}\nBuffer content:\n{1}'.format(cmd, buf)) - raise Exception('Socket timeout during execution of command: ' - '{0}\nBuffer content:\n{1}'.format(cmd, buf)) + except socket.timeout as exc: + raise_from(Exception( + 'Socket timeout during execution of command: ' + '{0}\nBuffer content:\n{1}'.format(cmd, buf)), exc) tmp = buf.replace(cmd.replace('\n', ''), '') for item in prompt: tmp.replace(item, '') @@ -468,7 +485,7 @@ def exec_cmd(node, cmd, timeout=600, sudo=False, disconnect=False): def exec_cmd_no_error( node, cmd, timeout=600, sudo=False, message=None, disconnect=False, - retries=0): + retries=0, include_reason=False): """Convenience function to ssh/exec/return out & err. Verifies that return code is zero. @@ -483,6 +500,7 @@ def exec_cmd_no_error( :param message: Error message in case of failure. Default: None. :param disconnect: Close the opened SSH connection if True. :param retries: How many times to retry on failure. + :param include_reason: Whether default info should be appended to message. :type node: dict :type cmd: str or OptionString :type timeout: int @@ -490,6 +508,7 @@ def exec_cmd_no_error( :type message: str :type disconnect: bool :type retries: int + :type include_reason: bool :returns: Stdout, Stderr. :rtype: tuple(str, str) :raises RuntimeError: If bash return code is not 0. @@ -501,8 +520,14 @@ def exec_cmd_no_error( break sleep(1) else: - msg = ('Command execution failed: "{cmd}"\n{stderr}'. - format(cmd=cmd, stderr=stderr) if message is None else message) + msg = 'Command execution failed: "{cmd}"\nRC: {rc}\n{stderr}'.format( + cmd=cmd, rc=ret_code, stderr=stderr) + logger.info(msg) + if message: + if include_reason: + msg = message + '\n' + msg + else: + msg = message raise RuntimeError(msg) return stdout, stderr @@ -532,14 +557,14 @@ def scp_node( try: ssh.connect(node) - except SSHException: - raise RuntimeError('Failed to connect to {host}!' - .format(host=node['host'])) + except SSHException as exc: + raise_from(RuntimeError( + 'Failed to connect to {host}!'.format(host=node['host'])), exc) try: ssh.scp(local_path, remote_path, get, timeout) - except SCPException: - raise RuntimeError('SCP execution failed on {host}!' - .format(host=node['host'])) + except SCPException as exc: + raise_from(RuntimeError( + 'SCP execution failed on {host}!'.format(host=node['host'])), exc) finally: if disconnect: ssh.disconnect() -- 2.16.6