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 <vrpolak@cisco.com>

3 files changed, 205 insertions, 103 deletions

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()