From a6743812aa8cd9f29e65768b9a749e3101b656e6 Mon Sep 17 00:00:00 2001 From: Lucas Meneghel Rodrigues Date: Mon, 22 Jun 2015 16:08:09 -0300 Subject: [PATCH] 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: Lucas Meneghel Rodrigues --- avocado/core/log.py | 10 ++ avocado/core/remote/result.py | 3 +- avocado/core/remote/runner.py | 98 ++++++++++++------- avocado/core/remoter.py | 34 ++----- avocado/core/virt.py | 3 +- selftests/all/unit/avocado/remote_unittest.py | 39 +++++++- 6 files changed, 121 insertions(+), 66 deletions(-) diff --git a/avocado/core/log.py b/avocado/core/log.py index 5b25281f..916ef938 100644 --- a/avocado/core/log.py +++ b/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', diff --git a/avocado/core/remote/result.py b/avocado/core/remote/result.py index 1dbc2b0a..8fc87f1c 100644 --- a/avocado/core/remote/result.py +++ b/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): diff --git a/avocado/core/remote/runner.py b/avocado/core/remote/runner.py index fdd6c7e4..da760f0d 100644 --- a/avocado/core/remote/runner.py +++ b/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 diff --git a/avocado/core/remoter.py b/avocado/core/remoter.py index c1b58b82..c936c476 100644 --- a/avocado/core/remoter.py +++ b/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 diff --git a/avocado/core/virt.py b/avocado/core/virt.py index d25bfbad..e67755d2 100644 --- a/avocado/core/virt.py +++ b/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 diff --git a/selftests/all/unit/avocado/remote_unittest.py b/selftests/all/unit/avocado/remote_unittest.py index ea1810b3..b42435dd 100644 --- a/selftests/all/unit/avocado/remote_unittest.py +++ b/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') -- GitLab