Remote/VM plugins: Log full remote debug info to job log dir

In order to troubleshoot more effectively problems
happening in remote/vm operations, make all output
coming from fabric and paramiko to a 'remote.log'
file in the top level job directory.
Signed-off-by: NLucas Meneghel Rodrigues <lmr@redhat.com>

avocado/core/log.py

@@ -83,6 +83,16 @@ DEFAULT_LOGGING = {
             'level': 'DEBUG',
             'propagate': False,
         },
+        'avocado.fabric': {
+            'handlers': ['null'],
+            'level': 'DEBUG',
+            'propagate': False,
+        },
+        'paramiko': {
+            'handlers': ['null'],
+            'level': 'DEBUG',
+            'propagate': False,
+        },
         'avocado.test.stdout': {
             'handlers': ['null'],
             'level': 'DEBUG',

avocado/core/remote/result.py

@@ -82,8 +82,7 @@ class RemoteTestResult(HumanTestResult):
         self.remote = remoter.Remote(self.args.remote_hostname,
                                      self.args.remote_username,
                                      self.args.remote_password,
-                                     self.args.remote_port,
-                                     quiet=True)
+                                     self.args.remote_port)
         self._copy_tests()
 
     def tear_down(self):

avocado/core/remote/runner.py

@@ -17,8 +17,10 @@ import sys
 import json
 import os
 import re
+import logging
 
 from .test import RemoteTest
+from .. import output
 from .. import exceptions
 from .. import status
 from ..runner import TestRunner
@@ -46,6 +48,10 @@ class RemoteTestRunner(TestRunner):
         :returns: (True, (x, y, z)) if avocado appears to be installed and
                   (False, None) otherwise.
         """
+        # This will be useful as extra debugging info in case avocado
+        # doesn't seem to be available in the remote system.
+        self.result.remote.run('env', ignore_status=True, timeout=60)
+
         result = self.result.remote.run('avocado -v',
                                         ignore_status=True,
                                         timeout=60)
@@ -128,39 +134,63 @@ class RemoteTestRunner(TestRunner):
         if not timeout:     # avoid timeout = 0
             timeout = None
         failures = []
+
+        stdout_backup = sys.stdout
+        stderr_backup = sys.stderr
+        fabric_debugfile = os.path.join(self.job.logdir, 'remote.log')
+        paramiko_logger = logging.getLogger('paramiko')
+        fabric_logger = logging.getLogger('avocado.fabric')
+        app_logger = logging.getLogger('avocado.debug')
+        fmt = ('%(asctime)s %(module)-10.10s L%(lineno)-.4d %('
+               'levelname)-5.5s| %(message)s')
+        formatter = logging.Formatter(fmt=fmt, datefmt='%H:%M:%S')
+        file_handler = logging.FileHandler(filename=fabric_debugfile)
+        file_handler.setFormatter(formatter)
+        fabric_logger.addHandler(file_handler)
+        paramiko_logger.addHandler(file_handler)
+        logger_list = [fabric_logger]
+        if self.result.args.show_job_log:
+            logger_list.append(app_logger)
+            output.add_console_handler(paramiko_logger)
+        sys.stdout = output.LoggingFile(logger=logger_list)
+        sys.stderr = output.LoggingFile(logger=logger_list)
         try:
-            self.result.setup()
-        except Exception, details:
-            stacktrace.log_exc_info(sys.exc_info(), logger='avocado.test')
-            raise exceptions.JobError(details)
-        results = self.run_test(self.result.urls, timeout)
-        remote_log_dir = os.path.dirname(results['debuglog'])
-        self.result.start_tests()
-        for tst in results['tests']:
-            test = RemoteTest(name=tst['test'],
-                              time=tst['time'],
-                              start=tst['start'],
-                              end=tst['end'],
-                              status=tst['status'],
-                              logdir=tst['logdir'],
-                              logfile=tst['logfile'],
-                              fail_reason=tst['fail_reason'])
-            state = test.get_state()
-            self.result.start_test(state)
-            self.result.check_test(state)
-            if not status.mapping[state['status']]:
-                failures.append(state['tagged_name'])
-        local_log_dir = os.path.dirname(self.result.stream.debuglog)
-        zip_filename = remote_log_dir + '.zip'
-        zip_path_filename = os.path.join(local_log_dir,
-                                         os.path.basename(zip_filename))
-        self.result.remote.receive_files(local_log_dir, zip_filename)
-        archive.uncompress(zip_path_filename, local_log_dir)
-        os.remove(zip_path_filename)
-        self.result.end_tests()
-        try:
-            self.result.tear_down()
-        except Exception, details:
-            stacktrace.log_exc_info(sys.exc_info(), logger='avocado.test')
-            raise exceptions.JobError(details)
+            try:
+                self.result.setup()
+            except Exception, details:
+                stacktrace.log_exc_info(sys.exc_info(), logger='avocado.test')
+                raise exceptions.JobError(details)
+            results = self.run_test(self.result.urls, timeout)
+            remote_log_dir = os.path.dirname(results['debuglog'])
+            self.result.start_tests()
+            for tst in results['tests']:
+                test = RemoteTest(name=tst['test'],
+                                  time=tst['time'],
+                                  start=tst['start'],
+                                  end=tst['end'],
+                                  status=tst['status'],
+                                  logdir=tst['logdir'],
+                                  logfile=tst['logfile'],
+                                  fail_reason=tst['fail_reason'])
+                state = test.get_state()
+                self.result.start_test(state)
+                self.result.check_test(state)
+                if not status.mapping[state['status']]:
+                    failures.append(state['tagged_name'])
+            local_log_dir = os.path.dirname(self.result.stream.debuglog)
+            zip_filename = remote_log_dir + '.zip'
+            zip_path_filename = os.path.join(local_log_dir,
+                                             os.path.basename(zip_filename))
+            self.result.remote.receive_files(local_log_dir, zip_filename)
+            archive.uncompress(zip_path_filename, local_log_dir)
+            os.remove(zip_path_filename)
+            self.result.end_tests()
+            try:
+                self.result.tear_down()
+            except Exception, details:
+                stacktrace.log_exc_info(sys.exc_info(), logger='avocado.test')
+                raise exceptions.JobError(details)
+        finally:
+            sys.stdout = stdout_backup
+            sys.stderr = stderr_backup
         return failures

avocado/core/remoter.py

@@ -85,16 +85,10 @@ class Remote(object):
         :rtype: :class:`avocado.utils.process.CmdResult`.
         :raise fabric.exceptions.CommandTimeout: When timeout exhausted.
         """
-        if not self.quiet:
-            LOG.info('[%s] Running command %s', self.hostname, command)
         result = process.CmdResult()
-        stdout = output.LoggingFile(logger=logging.getLogger('avocado.test'))
-        stderr = output.LoggingFile(logger=logging.getLogger('avocado.test'))
         start_time = time.time()
         fabric_result = fabric.operations.run(command=command,
                                               quiet=self.quiet,
-                                              stdout=stdout,
-                                              stderr=stderr,
                                               warn_only=True,
                                               timeout=timeout)
         end_time = time.time()
@@ -138,15 +132,11 @@ class Remote(object):
         :param local_path: the local path.
         :param remote_path: the remote path.
         """
-        if not self.quiet:
-            LOG.info('[%s] Sending files %s -> %s', self.hostname,
-                     local_path, remote_path)
-        with fabric.context_managers.quiet():
-            try:
-                fabric.operations.put(local_path, remote_path,
-                                      mirror_local_mode=True)
-            except ValueError:
-                return False
+        try:
+            fabric.operations.put(local_path, remote_path,
+                                  mirror_local_mode=True)
+        except ValueError:
+            return False
         return True
 
     def receive_files(self, local_path, remote_path):
@@ -156,13 +146,9 @@ class Remote(object):
         :param local_path: the local path.
         :param remote_path: the remote path.
         """
-        if not self.quiet:
-            LOG.info('[%s] Receive remote files %s -> %s', self.hostname,
-                     local_path, remote_path)
-        with fabric.context_managers.quiet():
-            try:
-                fabric.operations.get(remote_path,
-                                      local_path)
-            except ValueError:
-                return False
+        try:
+            fabric.operations.get(remote_path,
+                                  local_path)
+        except ValueError:
+            return False
         return True

avocado/core/virt.py

@@ -273,8 +273,7 @@ class VM(object):
         :param password: the password.
         """
         if not self.logged:
-            self.remote = remoter.Remote(hostname, username, password,
-                                         quiet=True)
+            self.remote = remoter.Remote(hostname, username, password)
             res = self.remote.uptime()
             if res.succeeded:
                 self.logged = True

selftests/all/unit/avocado/remote_unittest.py

@@ -32,14 +32,44 @@ class RemoteTestRunnerTest(unittest.TestCase):
     def setUp(self):
         flexmock(remote.RemoteTestRunner).should_receive('__init__')
         self.remote = remote.RemoteTestRunner(None, None)
+        self.remote.job = flexmock(logdir='.')
+
         test_results = flexmock(stdout=JSON_RESULTS, exit_status=0)
         stream = flexmock(job_unique_id='sleeptest.1',
                           debuglog='/local/path/dirname')
         Remote = flexmock()
-        args = 'avocado -v'
+        args_version = 'avocado -v'
         version_result = flexmock(stdout='Avocado 1.2.3', exit_status=0)
+        args_env = 'env'
+        env_result = flexmock(stdout='''XDG_SESSION_ID=20
+HOSTNAME=rhel7.0
+SELINUX_ROLE_REQUESTED=
+SHELL=/bin/bash
+TERM=vt100
+HISTSIZE=1000
+SSH_CLIENT=192.168.124.1 52948 22
+SELINUX_USE_CURRENT_RANGE=
+SSH_TTY=/dev/pts/0
+USER=root
+PATH=/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/root/bin
+MAIL=/var/spool/mail/root
+PWD=/root
+LANG=en_US.UTF-8
+SELINUX_LEVEL_REQUESTED=
+HISTCONTROL=ignoredups
+HOME=/root
+SHLVL=2
+LOGNAME=root
+SSH_CONNECTION=192.168.124.1 52948 192.168.124.65 22
+LESSOPEN=||/usr/bin/lesspipe.sh %s
+XDG_RUNTIME_DIR=/run/user/0
+_=/usr/bin/env''', exit_status=0)
+        (Remote.should_receive('run')
+         .with_args(args_env, ignore_status=True, timeout=60)
+         .once().and_return(env_result))
+
         (Remote.should_receive('run')
-         .with_args(args, ignore_status=True, timeout=60)
+         .with_args(args_version, ignore_status=True, timeout=60)
          .once().and_return(version_result))
 
         args = 'cd ~/avocado/tests; avocado list sleeptest --paginator=off'
@@ -54,7 +84,8 @@ class RemoteTestRunnerTest(unittest.TestCase):
          .with_args(args, timeout=61, ignore_status=True)
          .once().and_return(test_results))
         Results = flexmock(remote=Remote, urls=['sleeptest'],
-                           stream=stream, timeout=None)
+                           stream=stream, timeout=None,
+                           args=flexmock(show_job_log=False))
         Results.should_receive('setup').once().ordered()
         Results.should_receive('start_tests').once().ordered()
         args = {'status': u'PASS', 'whiteboard': '', 'time_start': 0,
@@ -102,7 +133,7 @@ class RemoteTestResultTest(unittest.TestCase):
         Stream.should_receive('notify').once().ordered()
         remote_remote = flexmock(remoter)
         (remote_remote.should_receive('Remote')
-         .with_args('hostname', 'username', 'password', 22, quiet=True)
+         .with_args('hostname', 'username', 'password', 22)
          .once().ordered()
          .and_return(Remote))
         (Remote.should_receive('makedir').with_args('~/avocado/tests')