From 91adc50f8d21d0b9f970839fa63842c60c0b0037 Mon Sep 17 00:00:00 2001 From: Federico Ressi Date: Mon, 3 Feb 2020 11:34:16 +0100 Subject: [PATCH] Improve shell command execution verbosity To improve framework usability refactor the verbosity of SSH command execution removing that lines from the log which only purpouse was to debug patamiko integration. This also facilitate debugging the result of command execution with always printing command execution outcome hiding such values that aren't relevant (empty strings or None). Because of that ping command integration has been reviewd too to avoid printing out ping command output twice if no herror appeared. It also introduces new fields to execution result: - login: a friendly string used to specify on which 'user@host' pair has been used for connecting to remote host (none for local commands). - status: according the way the command has been executed helps detecting if the outcome is the one expected by telling if the command execution has succeeded, has failed, was timedout or simply it was impossible to wait for its termination (for example because of a conectivity problem). - timeout: tells wich timeout value has been passed to the command - details: a nice string containing relevant values to describe to human beens what has been the result of command execution Change-Id: I2bde89fb9a1fa089a2188f86a4522f7692c9b65e --- tobiko/shell/ping/_interface.py | 4 +- tobiko/shell/ping/_ping.py | 2 - tobiko/shell/sh/_execute.py | 138 ++++++++++++++---- tobiko/shell/sh/_io.py | 3 - tobiko/shell/sh/_process.py | 29 +--- tobiko/shell/sh/_ssh.py | 29 ++-- tobiko/shell/ssh/_client.py | 33 ++--- tobiko/tests/functional/shell/test_execute.py | 18 ++- 8 files changed, 161 insertions(+), 95 deletions(-) diff --git a/tobiko/shell/ping/_interface.py b/tobiko/shell/ping/_interface.py index 58703d29b..7c09f21f5 100644 --- a/tobiko/shell/ping/_interface.py +++ b/tobiko/shell/ping/_interface.py @@ -85,10 +85,10 @@ def get_ping_usage(ssh_client): usage = ((result.stdout and str(result.stdout)) or (result.stderr and str(result.stderr)) or "").strip() if usage: - LOG.debug('Got ping usage text:\n%s\n', usage) + LOG.debug('Got ping usage text') else: LOG.warning("Unable to get usage message from ping command:\n" - "%r", result) + "%s", result.details) return usage diff --git a/tobiko/shell/ping/_ping.py b/tobiko/shell/ping/_ping.py index d5701f02e..d0cbfcc3d 100644 --- a/tobiko/shell/ping/_ping.py +++ b/tobiko/shell/ping/_ping.py @@ -274,13 +274,11 @@ def execute_ping(parameters, ssh_client=None, check=True): if stdout: output = str(stdout) - LOG.debug('Received ping STDOUT:\n%s', output) else: output = None if stderr: error = str(stderr) - LOG.info('Received ping STDERR:\n%s', error) if check and result.exit_status: handle_ping_command_error(error=error) diff --git a/tobiko/shell/sh/_execute.py b/tobiko/shell/sh/_execute.py index e927a7a63..33ef3b808 100644 --- a/tobiko/shell/sh/_execute.py +++ b/tobiko/shell/sh/_execute.py @@ -15,10 +15,13 @@ # under the License. from __future__ import absolute_import +import collections +import enum from oslo_log import log import six +import tobiko from tobiko.shell.sh import _exception from tobiko.shell.sh import _process @@ -29,29 +32,85 @@ LOG = log.getLogger(__name__) DATA_TYPES = six.string_types + (six.binary_type, six.text_type) -class ShellExecuteResult(object): +@enum.unique +class ShellExecuteStatus(enum.Enum): + SUCCEEDED = 'SUCCEEDED' + FAILED = 'FAILED' + TIMEDOUT = 'TIMEDOUT' + UNTERMINATED = 'UNTERMINATED' - def __init__(self, command=None, exit_status=None, stdin=None, stdout=None, - stderr=None): - self.command = str(command) - self.exit_status = exit_status - self.stdin = stdin and str(stdin) or None - self.stdout = stdout and str(stdout) or None - self.stderr = stderr and str(stderr) or None + +def execute_result(command, exit_status=None, timeout=None, + status=None, login=None, stdin=None, stdout=None, + stderr=None): + command = str(command) + if exit_status is not None: + exit_status = int(exit_status) + if timeout is not None: + timeout = float(timeout) + if status is not None: + status = ShellExecuteStatus(status) + stdin = _process.str_from_stream(stdin) + stdout = _process.str_from_stream(stdout) + stderr = _process.str_from_stream(stderr) + return ShellExecuteResult(command=command, + exit_status=exit_status, + timeout=timeout, + status=status, + stdin=stdin, + stdout=stdout, + stderr=stderr, + login=login) + + +class ShellExecuteResult(collections.namedtuple( + 'ShellExecuteResult', ['command', 'exit_status', 'timeout', 'status', + 'login', 'stdin', 'stdout', 'stderr'])): + + _details = None + + @property + def details(self): + details = self._details + if details is None: + self._details = details = self.get_details() + return details + + def get_details(self): + details = [] + details.append("command: {!r}".format(self.command)) + + exit_status = self.exit_status + if exit_status is not None: + details.append("exit_status: {!r}".format(exit_status)) + + timeout = self.timeout + if timeout is not None: + details.append("timeout: {!r}".format(timeout)) + + status = self.status + if status is not None: + details.append("status: {!s}".format(status)) + + login = self.login + if login is not None: + details.append("login: {!r}".format(login)) + + stdin = self.stdin + if stdin: + details.append("stdin:\n{!s}".format(_indent(stdin))) + + stdout = self.stdout + if stdout: + details.append("stdout:\n{!s}".format(_indent(stdout))) + + stderr = self.stderr + if stderr: + details.append("stderr:\n{!s}".format(_indent(stderr))) + return '\n'.join(details) def format(self): - text = '' - if self.stdin: - text += '- stdin: >\n' + _indent(self.stdin) + '\n' - if self.stdout: - text += '- stdout: >\n' + _indent(self.stdout) + '\n' - if self.stderr: - text += '- stderr: >\n' + _indent(self.stderr) + '\n' - return ("Shell command result:\n" - "- command: {command}" - "- exit_status: {exit_status}\n" - ).format(command=self.command, - exit_status=self.exit_status) + text + return self.details def _indent(text, space=' ', newline='\n'): @@ -89,25 +148,48 @@ def execute(command, environment=None, timeout=None, shell=None, stderr=stderr, ssh_client=ssh_client, **kwargs) + login = getattr(ssh_client, 'login', None) return execute_process(process=process, stdin=stdin, + login=login, expect_exit_status=expect_exit_status) -def execute_process(process, stdin, expect_exit_status): +def execute_process(process, stdin, expect_exit_status, login=None): + error = None + status = None try: with process: if stdin and isinstance(stdin, DATA_TYPES): process.send_all(data=stdin) except _exception.ShellTimeoutExpired: + status = ShellExecuteStatus.TIMEDOUT if expect_exit_status is not None: - raise + error = tobiko.exc_info() else: if expect_exit_status is not None: - process.check_exit_status(expect_exit_status) + try: + process.check_exit_status(expect_exit_status) + except _exception.ShellCommandFailed: + status = ShellExecuteStatus.FAILED + error = tobiko.exc_info() + except _exception.ShellProcessNotTeriminated: + status = ShellExecuteStatus.UNTERMINATED + else: + status = ShellExecuteStatus.SUCCEEDED - return ShellExecuteResult(command=str(process.command), - exit_status=process.exit_status, - stdin=_process.str_from_stream(process.stdin), - stdout=_process.str_from_stream(process.stdout), - stderr=_process.str_from_stream(process.stderr)) + result = execute_result(command=process.command, + exit_status=process.exit_status, + timeout=process.timeout, + status=status, + login=login, + stdin=process.stdin, + stdout=process.stdout, + stderr=process.stderr) + if error: + LOG.info("Command error:\n%s\n", result.details) + error.result = result + error.reraise() + + LOG.debug("Command executed:\n%s\n", result.details) + return result diff --git a/tobiko/shell/sh/_io.py b/tobiko/shell/sh/_io.py index a37516f91..f6ccdab3e 100644 --- a/tobiko/shell/sh/_io.py +++ b/tobiko/shell/sh/_io.py @@ -159,9 +159,6 @@ def select_files(files, timeout, mode='rw'): read_ready = select_read_ready_files(readable) write_ready = select_write_ready_files(writable) if not write_ready and not read_ready: - if timeout > 0.: - LOG.debug("Calling select with %d files and timeout %f", - len(opened), timeout) rlist, wlist, xlist = select.select(readable, writable, opened, timeout) read_ready = readable & set(rlist + xlist) diff --git a/tobiko/shell/sh/_process.py b/tobiko/shell/sh/_process.py index 08f6749d1..0fc71cc57 100644 --- a/tobiko/shell/sh/_process.py +++ b/tobiko/shell/sh/_process.py @@ -39,6 +39,11 @@ def process(command=None, environment=None, timeout=None, shell=None, kwargs.update(command=command, environment=environment, timeout=timeout, shell=shell, stdin=stdin, stdout=stdout, stderr=stderr, sudo=sudo) + timeout = kwargs['timeout'] + if timeout is not None: + if timeout < 0.: + raise ValueError("Invalid timeout for executing process: " + "{!r}".format(timeout)) try: from tobiko.shell.sh import _ssh from tobiko.shell import ssh @@ -309,8 +314,6 @@ class ShellProcessFixture(tobiko.SharedFixture): read_ready, write_ready = _io.select_files( files=streams, timeout=poll_interval) if read_ready or write_ready: - LOG.debug('Communicating with process (%s): %r', self.command, - read_ready | write_ready) # Avoid waiting for data the next time poll_interval = 0. if self.stdin in write_ready: @@ -337,16 +340,10 @@ class ShellProcessFixture(tobiko.SharedFixture): def _is_communicating(self, streams, send, receive): if send and self.stdin in streams: - LOG.debug('Trying to send data to process (%s): %r', self.command, - streams) return True elif receive and {self.stdout, self.stderr} & streams: - LOG.debug('Trying to receive data from process (%s): %r', - self.command, streams) return True else: - LOG.debug('Stop communicating with process (%s): %r', self.command, - streams) return False def _write_to_stdin(self, data, check=True): @@ -355,8 +352,6 @@ class ShellProcessFixture(tobiko.SharedFixture): self.check_stdin_is_opened() sent_bytes = self.stdin.write(data) if sent_bytes: - LOG.debug("Written %d bytes to STDIN (%s)", sent_bytes, - self.command) return data[sent_bytes:] or None else: LOG.debug("%r closed by peer on %r", self.stdin, self) @@ -368,8 +363,6 @@ class ShellProcessFixture(tobiko.SharedFixture): # Read data from remote stream chunk = self.stdout.read(buffer_size) if chunk: - LOG.debug("Read %d bytes from STDOUT (%s)", len(chunk), - self.command) return chunk else: LOG.debug("%r closed by peer on %r", self.stdout, self) @@ -381,8 +374,6 @@ class ShellProcessFixture(tobiko.SharedFixture): # Read data from remote stream chunk = self.stderr.read(buffer_size) if chunk: - LOG.debug("Read %d bytes from STDERR (%s)", len(chunk), - self.command) return chunk else: LOG.debug("%r closed by peer on %r", self.stderr, self) @@ -398,7 +389,6 @@ class ShellProcessFixture(tobiko.SharedFixture): stdin=str_from_stream(self.stdin), stdout=str_from_stream(self.stdout), stderr=str_from_stream(self.stderr)) - LOG.debug("%s", ex) raise ex return time_left @@ -412,7 +402,6 @@ class ShellProcessFixture(tobiko.SharedFixture): stdin=self.stdin, stdout=self.stdout, stderr=self.stderr) - LOG.debug("%s", ex) raise ex exit_status = int(exit_status) @@ -423,16 +412,8 @@ class ShellProcessFixture(tobiko.SharedFixture): stdin=str_from_stream(self.stdin), stdout=str_from_stream(self.stdout), stderr=str_from_stream(self.stderr)) - LOG.debug("%s", ex) raise ex - LOG.debug("Command '%s' succeeded (exit_status=%d):\n" - "stdin:\n%s\n" - "stdout:\n%s\n" - "stderr:\n%s", - self.command, exit_status, - self.stdin, self.stdout, self.stderr) - def merge_dictionaries(*dictionaries): merged = {} diff --git a/tobiko/shell/sh/_ssh.py b/tobiko/shell/sh/_ssh.py index 9e6984da1..93cf15d4f 100644 --- a/tobiko/shell/sh/_ssh.py +++ b/tobiko/shell/sh/_ssh.py @@ -18,6 +18,7 @@ from __future__ import absolute_import from oslo_log import log import paramiko +import tobiko from tobiko.shell.sh import _exception from tobiko.shell.sh import _execute from tobiko.shell.sh import _io @@ -32,7 +33,7 @@ LOG = log.getLogger(__name__) def ssh_execute(ssh_client, command, environment=None, timeout=None, stdin=None, stdout=None, stderr=None, shell=None, expect_exit_status=0, **kwargs): - """Execute command on local host using local shell""" + """Execute command on remote host using SSH client""" process = ssh_process(command=command, environment=environment, timeout=timeout, @@ -77,18 +78,24 @@ class SSHShellProcessFixture(_process.ShellProcessFixture): def create_process(self): """Execute command on a remote host using SSH client""" - parameters = self.parameters - assert isinstance(parameters, SSHShellProcessParameters) - - ssh_client = self.ssh_client - if isinstance(ssh_client, ssh.SSHClientFixture): - # Connect to SSH server - ssh_client = ssh_client.connect() - command = str(self.command) + ssh_client = self.ssh_client timeout = self.timeout and float(self.timeout) + parameters = self.parameters + + tobiko.check_valid_type(ssh_client, ssh.SSHClientFixture) + tobiko.check_valid_type(parameters, SSHShellProcessParameters) + + LOG.debug("Executing remote command: %r (login=%r, timeout=%r)...", + command, ssh_client.login, timeout) + + # Connect to SSH server + client = ssh_client.connect() + + # Open a new SSH session try: - process = ssh_client.get_transport().open_session(timeout=timeout) + process = client.get_transport().open_session( + timeout=timeout) except paramiko.SSHException as ex: LOG.debug('Error executing command %r', command, exc_info=1) error = str(ex) @@ -101,8 +108,6 @@ class SSHShellProcessFixture(_process.ShellProcessFixture): else: raise _exception.ShellError(error) - LOG.debug("Execute command %r on remote host (timeout=%r)...", - command, self.timeout) if parameters.environment: process.update_environment(parameters.environment) process.exec_command(command) diff --git a/tobiko/shell/ssh/_client.py b/tobiko/shell/ssh/_client.py index a2459d5df..3bedd9093 100644 --- a/tobiko/shell/ssh/_client.py +++ b/tobiko/shell/ssh/_client.py @@ -274,33 +274,18 @@ class SSHClientFixture(tobiko.SharedFixture): gather_parameters(destination=parameters, schema=schema, remove_from_schema=True) - if parameters: - LOG.debug('SSH connect parameters for host %r:\n%r', self.host, - parameters) return parameters def gather_initial_connect_parameters(self, **kwargs): - parameters = gather_ssh_connect_parameters( + return gather_ssh_connect_parameters( source=self._connect_parameters, **kwargs) - if parameters: - LOG.debug('Initial SSH connect parameters for host %r:\n' - '%r', self.host, parameters) - return parameters def gather_host_config_connect_parameters(self, **kwargs): - parameters = gather_ssh_connect_parameters( + return gather_ssh_connect_parameters( source=self.host_config.connect_parameters, **kwargs) - if parameters: - LOG.debug('Host configured SSH connect parameters for host %r:\n' - '%r', self.host, parameters) - return parameters def gather_default_connect_parameters(self, **kwargs): - parameters = gather_ssh_connect_parameters(source=self, **kwargs) - if parameters: - LOG.debug('Default SSH connect parameters for host %r:\n' - '%r', self.host, parameters) - return parameters + return gather_ssh_connect_parameters(source=self, **kwargs) def setup_ssh_client(self): self.client, self.proxy_sock = ssh_connect( @@ -333,6 +318,9 @@ class SSHClientFixture(tobiko.SharedFixture): def connect(self): return tobiko.setup_fixture(self).client + def close(self): + tobiko.cleanup_fixture(self) + def get_ssh_command(self, host=None, username=None, port=None, command=None, config_files=None, host_config=None, proxy_command=None, key_filename=None, **options): @@ -361,6 +349,13 @@ class SSHClientFixture(tobiko.SharedFixture): key_filename=key_filename, **options) + @property + def login(self): + parameters = self.setup_connect_parameters() + return _command.ssh_login(hostname=parameters['hostname'], + username=parameters['username'], + port=parameters['port']) + UNDEFINED_CLIENT = 'UNDEFINED_CLIENT' @@ -449,8 +444,6 @@ def ssh_connect(hostname, username=None, port=None, connection_interval=None, LOG.debug("Error logging in to %r: %s", login, ex) sleep_time = start_time + interval - time.time() if sleep_time > 0.: - LOG.debug("Retrying connecting to %r in %d seconds...", login, - sleep_time) time.sleep(sleep_time) else: diff --git a/tobiko/tests/functional/shell/test_execute.py b/tobiko/tests/functional/shell/test_execute.py index d501a641a..3e8e1f52c 100644 --- a/tobiko/tests/functional/shell/test_execute.py +++ b/tobiko/tests/functional/shell/test_execute.py @@ -32,11 +32,12 @@ class ExecuteTest(testtools.TestCase): shell = '/bin/sh -c' def test_succeed(self, command='true', stdin=None, stdout=None, - stderr=None, **kwargs): + stderr=None, expect_exit_status=0, **kwargs): process = self.execute(command=command, stdin=stdin, stdout=bool(stdout), stderr=bool(stderr), + expect_exit_status=expect_exit_status, **kwargs) self.assertEqual(self.expected_command(command), process.command) if stdin: @@ -51,7 +52,8 @@ class ExecuteTest(testtools.TestCase): self.assertEqual(stderr, str(process.stderr)) else: self.assertIsNone(process.stderr) - self.assertEqual(0, process.exit_status) + if expect_exit_status is not None: + self.assertEqual(0, process.exit_status) def test_succeed_with_command_list(self): self.test_succeed(['echo', 'something'], @@ -73,11 +75,16 @@ class ExecuteTest(testtools.TestCase): def test_succeed_with_timeout(self): self.test_succeed(timeout=30.) + def test_succeed_with_no_exit_status(self): + self.test_succeed(command='false', expect_exit_status=None) + def test_fails(self, command='false', exit_status=None, stdin=None, - stdout=None, stderr=None, **kwargs): + stdout=None, stderr=None, expect_exit_status=0, + **kwargs): ex = self.assertRaises(sh.ShellCommandFailed, self.execute, command=command, + expect_exit_status=expect_exit_status, stdin=stdin, stdout=bool(stdout), stderr=bool(stderr), @@ -95,7 +102,7 @@ class ExecuteTest(testtools.TestCase): self.assertEqual(stderr, ex.stderr) else: self.assertIsNone(ex.stderr) - if exit_status: + if exit_status is not None: self.assertEqual(exit_status, ex.exit_status) else: self.assertTrue(ex.exit_status) @@ -116,6 +123,9 @@ class ExecuteTest(testtools.TestCase): stdin='some input\n', stdout='some input\n') + def test_fails_with_check_exit_status(self): + self.test_fails(command='true', expect_exit_status=1, exit_status=0) + def test_timeout_expires(self, command='sleep 10', timeout=5., stdin=None, stdout=None, stderr=None, **kwargs): ex = self.assertRaises(sh.ShellTimeoutExpired,