CSIT-828: Fix the output of failed VAT execution

Change-Id: Id387bd685142dcfaa17f0236e930e40e6c0bce5a
Signed-off-by: Jan Gelety <jgelety@cisco.com>
(cherry picked from commit 4d2e646f21659a6540312779190b03aed91395d5)

2 files changed, 181 insertions, 53 deletions

diff --git a/resources/libraries/python/VatExecutor.py b/resources/libraries/python/VatExecutor.py
index a3f12bf46f..841bd0c6cb 100644
--- a/resources/libraries/python/VatExecutor.py
+++ b/resources/libraries/python/VatExecutor.py
@@ -15,32 +15,55 @@
 
 import json
 
+from paramiko.ssh_exception import SSHException
 from robot.api import logger
 
-from resources.libraries.python.ssh import SSH
+from resources.libraries.python.ssh import SSH, SSHTimeout
 from resources.libraries.python.constants import Constants
 from resources.libraries.python.VatHistory import VatHistory
 
-
 __all__ = ['VatExecutor']
 
 
-def cleanup_vat_json_output(json_output):
+def cleanup_vat_json_output(json_output, vat_name=None):
     """Return VAT JSON output cleaned from VAT clutter.
 
     Clean up VAT JSON output from clutter like vat# prompts and such.
 
     :param json_output: Cluttered JSON output.
+    :param vat_name: Name of the VAT script.
+    :type json_output: JSON
+    :type vat_name: str
     :returns: Cleaned up output JSON string.
+    :rtype: JSON
     """
 
     retval = json_output
     clutter = ['vat#', 'dump_interface_table error: Misc']
+    if vat_name:
+        remote_file_path = '{0}/{1}/{2}'.format(Constants.REMOTE_FW_DIR,
+                                                Constants.RESOURCES_TPL_VAT,
+                                                vat_name)
+        clutter.append("{0}(2):".format(remote_file_path))
     for garbage in clutter:
         retval = retval.replace(garbage, '')
     return retval
 
 
+def get_vpp_pid(node):
+    """Get PID of running VPP process.
+
+    :param node: DUT node.
+    :type node: dict
+    :returns: PID of VPP process / List of PIDs if more VPP processes are
+    running on the DUT node.
+    :rtype: int or list
+    """
+    import resources.libraries.python.DUTSetup as PidLib
+    pid = PidLib.DUTSetup.get_vpp_pid(node)
+    return pid
+
+
 class VatExecutor(object):
     """Contains methods for executing VAT commands on DUTs."""
     def __init__(self):
@@ -48,7 +71,7 @@ class VatExecutor(object):
         self._stderr = None
         self._ret_code = None
 
-    def execute_script(self, vat_name, node, timeout=10, json_out=True):
+    def execute_script(self, vat_name, node, timeout=15, json_out=True):
         """Copy local_path script to node, execute it and return result.
 
         :param vat_name: Name of the vat script file. Only the file name of
@@ -56,11 +79,21 @@ class VatExecutor(object):
         :param node: Node to execute the VAT script on.
         :param timeout: Seconds to allow the script to run.
         :param json_out: Require JSON output.
-        :return: (rc, stdout, stderr) tuple.
+        :type vat_name: str
+        :type node: dict
+        :type timeout: int
+        :type json_out: bool
+        :returns: Status code, stdout and stderr of executed VAT script.
+        :rtype: tuple
+        :raises RuntimeError: If VAT script execution failed.
         """
 
         ssh = SSH()
-        ssh.connect(node)
+        try:
+            ssh.connect(node)
+        except:
+            raise SSHException("Cannot open SSH connection to execute VAT "
+                               "command(s) from template {0}".format(vat_name))
 
         remote_file_path = '{0}/{1}/{2}'.format(Constants.REMOTE_FW_DIR,
                                                 Constants.RESOURCES_TPL_VAT,
@@ -68,23 +101,27 @@ class VatExecutor(object):
         # TODO this overwrites the output if the vat script has been used twice
         # remote_file_out = remote_file_path + ".out"
 
-        cmd = "sudo -S {vat} {json} < {input}".format(
+        cmd = "sudo -S {vat} {json} in {input} script".format(
             vat=Constants.VAT_BIN_NAME,
             json="json" if json_out is True else "",
             input=remote_file_path)
-        (ret_code, stdout, stderr) = ssh.exec_command(cmd, timeout)
+
+        try:
+            (ret_code, stdout, stderr) = ssh.exec_command(cmd, timeout)
+        except SSHTimeout:
+            logger.error("VAT script execution timeout: {0}".format(cmd))
+            raise
+        except:
+            raise RuntimeError("VAT script execution failed: {0}".format(cmd))
+
         self._ret_code = ret_code
         self._stdout = stdout
         self._stderr = stderr
 
-        logger.trace("Command '{0}' returned {1}'".format(cmd, self._ret_code))
-        logger.trace("stdout: '{0}'".format(self._stdout))
-        logger.trace("stderr: '{0}'".format(self._stderr))
-
         # TODO: download vpp_api_test output file
         # self._delete_files(node, remote_file_path, remote_file_out)
 
-    def scp_and_execute_script(self, vat_name, node, timeout=10, json_out=True):
+    def scp_and_execute_script(self, vat_name, node, timeout=15, json_out=True):
         """Copy vat_name script to node, execute it and return result.
 
         :param vat_name: Name of the vat script file.
@@ -96,31 +133,40 @@ class VatExecutor(object):
         :type node: dict
         :type timeout: int
         :type json_out: bool
-        :returns: Status code, stdout and stderr of executed script
+        :returns: Status code, stdout and stderr of executed VAT script.
         :rtype: tuple
+        :raises RuntimeError: If VAT script execution failed.
         """
 
         ssh = SSH()
-        ssh.connect(node)
+        try:
+            ssh.connect(node)
+        except:
+            raise SSHException("Cannot open SSH connection to execute VAT "
+                               "command(s) from template {0}".format(vat_name))
 
         ssh.scp(vat_name, vat_name)
 
-        cmd = "sudo -S {vat} {json} < {input}".format(
+        cmd = "sudo -S {vat} {json} in {input} script".format(
             json="json" if json_out is True else "",
             vat=Constants.VAT_BIN_NAME,
             input=vat_name)
-        (ret_code, stdout, stderr) = ssh.exec_command(cmd, timeout)
+
+        try:
+            (ret_code, stdout, stderr) = ssh.exec_command(cmd, timeout)
+        except SSHTimeout:
+            logger.error("VAT script execution timeout: {0}".format(cmd))
+            raise
+        except:
+            raise RuntimeError("VAT script execution failed: {0}".format(cmd))
+
         self._ret_code = ret_code
         self._stdout = stdout
         self._stderr = stderr
 
-        logger.trace("Command '{0}' returned {1}'".format(cmd, self._ret_code))
-        logger.trace("stdout: '{0}'".format(self._stdout))
-        logger.trace("stderr: '{0}'".format(self._stderr))
-
         self._delete_files(node, vat_name)
 
-    def scp_and_execute_cli_script(self, fname, node, timeout=10,
+    def scp_and_execute_cli_script(self, fname, node, timeout=15,
                                    json_out=True):
         """Copy vat_name script to node, execute it and return result.
 
@@ -129,39 +175,59 @@ class VatExecutor(object):
         :param node: Node to execute the VPP script on.
         :param timeout: Seconds to allow the script to run.
         :param json_out: Require JSON output.
-        :type vat_name: str
+        :type fname: str
         :type node: dict
         :type timeout: int
         :type json_out: bool
-        :returns: Status code, stdout and stderr of executed script
+        :returns: Status code, stdout and stderr of executed CLI script.
         :rtype: tuple
+        :raises RuntimeError: If CLI script execution failed.
         """
 
         ssh = SSH()
-        ssh.connect(node)
+        try:
+            ssh.connect(node)
+        except:
+            raise SSHException("Cannot open SSH connection to execute CLI "
+                               "command(s) from template {0}".format(fname))
 
         ssh.scp(fname, fname)
 
         cmd = "{vat} {json}".format(json="json" if json_out is True else "",
                                     vat=Constants.VAT_BIN_NAME)
         cmd_input = "exec exec {0}".format(fname)
-        (ret_code, stdout, stderr) = ssh.exec_command_sudo(cmd, cmd_input,
-                                                           timeout)
+
+        try:
+            (ret_code, stdout, stderr) = ssh.exec_command_sudo(cmd, cmd_input,
+                                                               timeout)
+        except SSHTimeout:
+            logger.error("CLI script execution timeout: {0}{1}".
+                         format(cmd, "<<< " + cmd_input if cmd_input else ""))
+            raise
+        except:
+            raise RuntimeError("CLI script execution failed: {0}{1}".format(
+                cmd, "<<< " + cmd_input if cmd_input else ""))
+
         self._ret_code = ret_code
         self._stdout = stdout
         self._stderr = stderr
 
-        logger.trace("Command '{0}' returned {1}'".format(cmd, self._ret_code))
-        logger.trace("stdout: '{0}'".format(self._stdout))
-        logger.trace("stderr: '{0}'".format(self._stderr))
-
         self._delete_files(node, fname)
 
-    def execute_script_json_out(self, vat_name, node, timeout=10):
+    def execute_script_json_out(self, vat_name, node, timeout=15):
         """Pass all arguments to 'execute_script' method, then cleanup returned
-        json output."""
+        json output.
+
+         :param vat_name: Name of the vat script file. Only the file name of
+        the script is required, the resources path is prepended automatically.
+        :param node: Node to execute the VAT script on.
+        :param timeout: Seconds to allow the script to run.
+        :type vat_name: str
+        :type node: dict
+        :type timeout: int
+        """
         self.execute_script(vat_name, node, timeout, json_out=True)
-        self._stdout = cleanup_vat_json_output(self._stdout)
+        self._stdout = cleanup_vat_json_output(self._stdout, vat_name=vat_name)
 
     @staticmethod
     def _delete_files(node, *files):
@@ -239,11 +305,37 @@ class VatTerminal(object):
         self._node = node
         self._ssh = SSH()
         self._ssh.connect(self._node)
-        self._tty = self._ssh.interactive_terminal_open()
-        self._ssh.interactive_terminal_exec_command(
-            self._tty,
-            'sudo -S {}{}'.format(Constants.VAT_BIN_NAME, json_text),
-            self.__VAT_PROMPT)
+        try:
+            self._tty = self._ssh.interactive_terminal_open()
+        except Exception:
+            raise RuntimeError("Cannot open interactive terminal on node {0}".
+                               format(self._node))
+
+        for _ in range(3):
+            try:
+                self._ssh.interactive_terminal_exec_command(
+                    self._tty,
+                    'sudo -S {0}{1}'.format(Constants.VAT_BIN_NAME, json_text),
+                    self.__VAT_PROMPT)
+            except Exception:
+                    continue
+            else:
+                break
+        else:
+            vpp_pid = get_vpp_pid(self._node)
+            if vpp_pid:
+                if isinstance(vpp_pid, int):
+                    logger.trace("VPP running on node {0}".
+                                 format(self._node['host']))
+                else:
+                    logger.error("More instances of VPP running on node {0}.".
+                                 format(self._node['host']))
+            else:
+                logger.error("VPP not running on node {0}.".
+                             format(self._node['host']))
+            raise RuntimeError("Failed to open VAT console on node {0}".
+                               format(self._node['host']))
+
         self._exec_failure = False
         self.vat_stdout = None
 
@@ -262,16 +354,29 @@ class VatTerminal(object):
         None if not in JSON mode.
         """
         VatHistory.add_to_vat_history(self._node, cmd)
-        logger.debug("Executing command in VAT terminal: {}".format(cmd))
+        logger.debug("Executing command in VAT terminal: {0}".format(cmd))
         try:
             out = self._ssh.interactive_terminal_exec_command(self._tty, cmd,
                                                               self.__VAT_PROMPT)
             self.vat_stdout = out
-        except:
+        except Exception:
             self._exec_failure = True
-            raise
+            vpp_pid = get_vpp_pid(self._node)
+            if vpp_pid:
+                if isinstance(vpp_pid, int):
+                    raise RuntimeError("VPP running on node {0} but VAT command"
+                                       " {1} execution failed.".
+                                       format(self._node['host'], cmd))
+                else:
+                    raise RuntimeError("More instances of VPP running on node "
+                                       "{0}. VAT command {1} execution failed.".
+                                       format(self._node['host'], cmd))
+            else:
+                raise RuntimeError("VPP not running on node {0}. VAT command "
+                                   "{1} execution failed.".
+                                   format(self._node['host'], cmd))
 
-        logger.debug("VAT output: {}".format(out))
+        logger.debug("VAT output: {0}".format(out))
         if self.json:
             obj_start = out.find('{')
             obj_end = out.rfind('}')
@@ -279,7 +384,7 @@ class VatTerminal(object):
             array_end = out.rfind(']')
 
             if obj_start == -1 and array_start == -1:
-                raise RuntimeError("VAT: no JSON data.")
+                raise RuntimeError("VAT command {0}: no JSON data.".format(cmd))
 
             if obj_start < array_start or array_start == -1:
                 start = obj_start
@@ -297,10 +402,29 @@ class VatTerminal(object):
         """Close VAT terminal."""
         # interactive terminal is dead, we only need to close session
         if not self._exec_failure:
-            self._ssh.interactive_terminal_exec_command(self._tty,
-                                                        'quit',
-                                                        self.__LINUX_PROMPT)
-        self._ssh.interactive_terminal_close(self._tty)
+            try:
+                self._ssh.interactive_terminal_exec_command(self._tty,
+                                                            'quit',
+                                                            self.__LINUX_PROMPT)
+            except Exception:
+                vpp_pid = get_vpp_pid(self._node)
+                if vpp_pid:
+                    if isinstance(vpp_pid, int):
+                        logger.trace("VPP running on node {0}.".
+                                     format(self._node['host']))
+                    else:
+                        logger.error("More instances of VPP running on node "
+                                     "{0}.".format(self._node['host']))
+                else:
+                    logger.error("VPP not running on node {0}.".
+                                 format(self._node['host']))
+                raise RuntimeError("Failed to close VAT console on node {0}".
+                                   format(self._node['host']))
+        try:
+            self._ssh.interactive_terminal_close(self._tty)
+        except:
+            raise RuntimeError("Cannot close interactive terminal on node {0}".
+                               format(self._node['host']))
 
     def vat_terminal_exec_cmd_from_template(self, vat_template_file, **args):
         """Execute VAT script from a file.
diff --git a/resources/libraries/python/ssh.py b/resources/libraries/python/ssh.py
index 5777c32001..87fc02d3dd 100644
--- a/resources/libraries/python/ssh.py
+++ b/resources/libraries/python/ssh.py
@@ -157,10 +157,10 @@ class SSH(object):
 
             if time() - start > timeout:
                 raise SSHTimeout(
-                    'Timeout exception.\n'
-                    'Current contents of stdout buffer: {0}\n'
-                    'Current contents of stderr buffer: {1}\n'
-                    .format(stdout.getvalue(), stderr.getvalue())
+                    'Timeout exception during execution of command: {0}\n'
+                    'Current contents of stdout buffer: {1}\n'
+                    'Current contents of stderr buffer: {2}\n'
+                    .format(cmd, stdout.getvalue(), stderr.getvalue())
                 )
 
             sleep(0.1)
@@ -260,6 +260,7 @@ class SSH(object):
                     logger.error('Channel exit status ready')
                     break
             except socket.timeout:
+                logger.error('Socket timeout: {0}'.format(buf))
                 raise Exception('Socket timeout: {0}'.format(buf))
         return chan
 
@@ -293,7 +294,10 @@ class SSH(object):
                     logger.error('Channel exit status ready')
                     break
             except socket.timeout:
-                raise Exception('Socket timeout: {0}'.format(buf))
+                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))
         tmp = buf.replace(cmd.replace('\n', ''), '')
         for item in prompt:
             tmp.replace(item, '')