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
This commit is contained in:
Federico Ressi 2020-02-03 11:34:16 +01:00
parent 8e2c3b5c91
commit 91adc50f8d
8 changed files with 161 additions and 95 deletions

View File

@ -85,10 +85,10 @@ def get_ping_usage(ssh_client):
usage = ((result.stdout and str(result.stdout)) or usage = ((result.stdout and str(result.stdout)) or
(result.stderr and str(result.stderr)) or "").strip() (result.stderr and str(result.stderr)) or "").strip()
if usage: if usage:
LOG.debug('Got ping usage text:\n%s\n', usage) LOG.debug('Got ping usage text')
else: else:
LOG.warning("Unable to get usage message from ping command:\n" LOG.warning("Unable to get usage message from ping command:\n"
"%r", result) "%s", result.details)
return usage return usage

View File

@ -274,13 +274,11 @@ def execute_ping(parameters, ssh_client=None, check=True):
if stdout: if stdout:
output = str(stdout) output = str(stdout)
LOG.debug('Received ping STDOUT:\n%s', output)
else: else:
output = None output = None
if stderr: if stderr:
error = str(stderr) error = str(stderr)
LOG.info('Received ping STDERR:\n%s', error)
if check and result.exit_status: if check and result.exit_status:
handle_ping_command_error(error=error) handle_ping_command_error(error=error)

View File

@ -15,10 +15,13 @@
# under the License. # under the License.
from __future__ import absolute_import from __future__ import absolute_import
import collections
import enum
from oslo_log import log from oslo_log import log
import six import six
import tobiko
from tobiko.shell.sh import _exception from tobiko.shell.sh import _exception
from tobiko.shell.sh import _process 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) 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): def execute_result(command, exit_status=None, timeout=None,
self.command = str(command) status=None, login=None, stdin=None, stdout=None,
self.exit_status = exit_status stderr=None):
self.stdin = stdin and str(stdin) or None command = str(command)
self.stdout = stdout and str(stdout) or None if exit_status is not None:
self.stderr = stderr and str(stderr) or 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): def format(self):
text = '' return self.details
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
def _indent(text, space=' ', newline='\n'): def _indent(text, space=' ', newline='\n'):
@ -89,25 +148,48 @@ def execute(command, environment=None, timeout=None, shell=None,
stderr=stderr, stderr=stderr,
ssh_client=ssh_client, ssh_client=ssh_client,
**kwargs) **kwargs)
login = getattr(ssh_client, 'login', None)
return execute_process(process=process, return execute_process(process=process,
stdin=stdin, stdin=stdin,
login=login,
expect_exit_status=expect_exit_status) 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: try:
with process: with process:
if stdin and isinstance(stdin, DATA_TYPES): if stdin and isinstance(stdin, DATA_TYPES):
process.send_all(data=stdin) process.send_all(data=stdin)
except _exception.ShellTimeoutExpired: except _exception.ShellTimeoutExpired:
status = ShellExecuteStatus.TIMEDOUT
if expect_exit_status is not None: if expect_exit_status is not None:
raise error = tobiko.exc_info()
else: else:
if expect_exit_status is not None: 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), result = execute_result(command=process.command,
exit_status=process.exit_status, exit_status=process.exit_status,
stdin=_process.str_from_stream(process.stdin), timeout=process.timeout,
stdout=_process.str_from_stream(process.stdout), status=status,
stderr=_process.str_from_stream(process.stderr)) 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

View File

@ -159,9 +159,6 @@ def select_files(files, timeout, mode='rw'):
read_ready = select_read_ready_files(readable) read_ready = select_read_ready_files(readable)
write_ready = select_write_ready_files(writable) write_ready = select_write_ready_files(writable)
if not write_ready and not read_ready: 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, rlist, wlist, xlist = select.select(readable, writable, opened,
timeout) timeout)
read_ready = readable & set(rlist + xlist) read_ready = readable & set(rlist + xlist)

View File

@ -39,6 +39,11 @@ def process(command=None, environment=None, timeout=None, shell=None,
kwargs.update(command=command, environment=environment, timeout=timeout, kwargs.update(command=command, environment=environment, timeout=timeout,
shell=shell, stdin=stdin, stdout=stdout, stderr=stderr, shell=shell, stdin=stdin, stdout=stdout, stderr=stderr,
sudo=sudo) sudo=sudo)
timeout = kwargs['timeout']
if timeout is not None:
if timeout < 0.:
raise ValueError("Invalid timeout for executing process: "
"{!r}".format(timeout))
try: try:
from tobiko.shell.sh import _ssh from tobiko.shell.sh import _ssh
from tobiko.shell import ssh from tobiko.shell import ssh
@ -309,8 +314,6 @@ class ShellProcessFixture(tobiko.SharedFixture):
read_ready, write_ready = _io.select_files( read_ready, write_ready = _io.select_files(
files=streams, timeout=poll_interval) files=streams, timeout=poll_interval)
if read_ready or write_ready: 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 # Avoid waiting for data the next time
poll_interval = 0. poll_interval = 0.
if self.stdin in write_ready: if self.stdin in write_ready:
@ -337,16 +340,10 @@ class ShellProcessFixture(tobiko.SharedFixture):
def _is_communicating(self, streams, send, receive): def _is_communicating(self, streams, send, receive):
if send and self.stdin in streams: if send and self.stdin in streams:
LOG.debug('Trying to send data to process (%s): %r', self.command,
streams)
return True return True
elif receive and {self.stdout, self.stderr} & streams: elif receive and {self.stdout, self.stderr} & streams:
LOG.debug('Trying to receive data from process (%s): %r',
self.command, streams)
return True return True
else: else:
LOG.debug('Stop communicating with process (%s): %r', self.command,
streams)
return False return False
def _write_to_stdin(self, data, check=True): def _write_to_stdin(self, data, check=True):
@ -355,8 +352,6 @@ class ShellProcessFixture(tobiko.SharedFixture):
self.check_stdin_is_opened() self.check_stdin_is_opened()
sent_bytes = self.stdin.write(data) sent_bytes = self.stdin.write(data)
if sent_bytes: if sent_bytes:
LOG.debug("Written %d bytes to STDIN (%s)", sent_bytes,
self.command)
return data[sent_bytes:] or None return data[sent_bytes:] or None
else: else:
LOG.debug("%r closed by peer on %r", self.stdin, self) LOG.debug("%r closed by peer on %r", self.stdin, self)
@ -368,8 +363,6 @@ class ShellProcessFixture(tobiko.SharedFixture):
# Read data from remote stream # Read data from remote stream
chunk = self.stdout.read(buffer_size) chunk = self.stdout.read(buffer_size)
if chunk: if chunk:
LOG.debug("Read %d bytes from STDOUT (%s)", len(chunk),
self.command)
return chunk return chunk
else: else:
LOG.debug("%r closed by peer on %r", self.stdout, self) LOG.debug("%r closed by peer on %r", self.stdout, self)
@ -381,8 +374,6 @@ class ShellProcessFixture(tobiko.SharedFixture):
# Read data from remote stream # Read data from remote stream
chunk = self.stderr.read(buffer_size) chunk = self.stderr.read(buffer_size)
if chunk: if chunk:
LOG.debug("Read %d bytes from STDERR (%s)", len(chunk),
self.command)
return chunk return chunk
else: else:
LOG.debug("%r closed by peer on %r", self.stderr, self) 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), stdin=str_from_stream(self.stdin),
stdout=str_from_stream(self.stdout), stdout=str_from_stream(self.stdout),
stderr=str_from_stream(self.stderr)) stderr=str_from_stream(self.stderr))
LOG.debug("%s", ex)
raise ex raise ex
return time_left return time_left
@ -412,7 +402,6 @@ class ShellProcessFixture(tobiko.SharedFixture):
stdin=self.stdin, stdin=self.stdin,
stdout=self.stdout, stdout=self.stdout,
stderr=self.stderr) stderr=self.stderr)
LOG.debug("%s", ex)
raise ex raise ex
exit_status = int(exit_status) exit_status = int(exit_status)
@ -423,16 +412,8 @@ class ShellProcessFixture(tobiko.SharedFixture):
stdin=str_from_stream(self.stdin), stdin=str_from_stream(self.stdin),
stdout=str_from_stream(self.stdout), stdout=str_from_stream(self.stdout),
stderr=str_from_stream(self.stderr)) stderr=str_from_stream(self.stderr))
LOG.debug("%s", ex)
raise 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): def merge_dictionaries(*dictionaries):
merged = {} merged = {}

View File

@ -18,6 +18,7 @@ from __future__ import absolute_import
from oslo_log import log from oslo_log import log
import paramiko import paramiko
import tobiko
from tobiko.shell.sh import _exception from tobiko.shell.sh import _exception
from tobiko.shell.sh import _execute from tobiko.shell.sh import _execute
from tobiko.shell.sh import _io from tobiko.shell.sh import _io
@ -32,7 +33,7 @@ LOG = log.getLogger(__name__)
def ssh_execute(ssh_client, command, environment=None, timeout=None, def ssh_execute(ssh_client, command, environment=None, timeout=None,
stdin=None, stdout=None, stderr=None, shell=None, stdin=None, stdout=None, stderr=None, shell=None,
expect_exit_status=0, **kwargs): 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, process = ssh_process(command=command,
environment=environment, environment=environment,
timeout=timeout, timeout=timeout,
@ -77,18 +78,24 @@ class SSHShellProcessFixture(_process.ShellProcessFixture):
def create_process(self): def create_process(self):
"""Execute command on a remote host using SSH client""" """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) command = str(self.command)
ssh_client = self.ssh_client
timeout = self.timeout and float(self.timeout) 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: try:
process = ssh_client.get_transport().open_session(timeout=timeout) process = client.get_transport().open_session(
timeout=timeout)
except paramiko.SSHException as ex: except paramiko.SSHException as ex:
LOG.debug('Error executing command %r', command, exc_info=1) LOG.debug('Error executing command %r', command, exc_info=1)
error = str(ex) error = str(ex)
@ -101,8 +108,6 @@ class SSHShellProcessFixture(_process.ShellProcessFixture):
else: else:
raise _exception.ShellError(error) raise _exception.ShellError(error)
LOG.debug("Execute command %r on remote host (timeout=%r)...",
command, self.timeout)
if parameters.environment: if parameters.environment:
process.update_environment(parameters.environment) process.update_environment(parameters.environment)
process.exec_command(command) process.exec_command(command)

View File

@ -274,33 +274,18 @@ class SSHClientFixture(tobiko.SharedFixture):
gather_parameters(destination=parameters, gather_parameters(destination=parameters,
schema=schema, schema=schema,
remove_from_schema=True) remove_from_schema=True)
if parameters:
LOG.debug('SSH connect parameters for host %r:\n%r', self.host,
parameters)
return parameters return parameters
def gather_initial_connect_parameters(self, **kwargs): def gather_initial_connect_parameters(self, **kwargs):
parameters = gather_ssh_connect_parameters( return gather_ssh_connect_parameters(
source=self._connect_parameters, **kwargs) 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): 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) 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): def gather_default_connect_parameters(self, **kwargs):
parameters = gather_ssh_connect_parameters(source=self, **kwargs) return 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
def setup_ssh_client(self): def setup_ssh_client(self):
self.client, self.proxy_sock = ssh_connect( self.client, self.proxy_sock = ssh_connect(
@ -333,6 +318,9 @@ class SSHClientFixture(tobiko.SharedFixture):
def connect(self): def connect(self):
return tobiko.setup_fixture(self).client return tobiko.setup_fixture(self).client
def close(self):
tobiko.cleanup_fixture(self)
def get_ssh_command(self, host=None, username=None, port=None, def get_ssh_command(self, host=None, username=None, port=None,
command=None, config_files=None, host_config=None, command=None, config_files=None, host_config=None,
proxy_command=None, key_filename=None, **options): proxy_command=None, key_filename=None, **options):
@ -361,6 +349,13 @@ class SSHClientFixture(tobiko.SharedFixture):
key_filename=key_filename, key_filename=key_filename,
**options) **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' 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) LOG.debug("Error logging in to %r: %s", login, ex)
sleep_time = start_time + interval - time.time() sleep_time = start_time + interval - time.time()
if sleep_time > 0.: if sleep_time > 0.:
LOG.debug("Retrying connecting to %r in %d seconds...", login,
sleep_time)
time.sleep(sleep_time) time.sleep(sleep_time)
else: else:

View File

@ -32,11 +32,12 @@ class ExecuteTest(testtools.TestCase):
shell = '/bin/sh -c' shell = '/bin/sh -c'
def test_succeed(self, command='true', stdin=None, stdout=None, 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, process = self.execute(command=command,
stdin=stdin, stdin=stdin,
stdout=bool(stdout), stdout=bool(stdout),
stderr=bool(stderr), stderr=bool(stderr),
expect_exit_status=expect_exit_status,
**kwargs) **kwargs)
self.assertEqual(self.expected_command(command), process.command) self.assertEqual(self.expected_command(command), process.command)
if stdin: if stdin:
@ -51,7 +52,8 @@ class ExecuteTest(testtools.TestCase):
self.assertEqual(stderr, str(process.stderr)) self.assertEqual(stderr, str(process.stderr))
else: else:
self.assertIsNone(process.stderr) 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): def test_succeed_with_command_list(self):
self.test_succeed(['echo', 'something'], self.test_succeed(['echo', 'something'],
@ -73,11 +75,16 @@ class ExecuteTest(testtools.TestCase):
def test_succeed_with_timeout(self): def test_succeed_with_timeout(self):
self.test_succeed(timeout=30.) 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, 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, ex = self.assertRaises(sh.ShellCommandFailed,
self.execute, self.execute,
command=command, command=command,
expect_exit_status=expect_exit_status,
stdin=stdin, stdin=stdin,
stdout=bool(stdout), stdout=bool(stdout),
stderr=bool(stderr), stderr=bool(stderr),
@ -95,7 +102,7 @@ class ExecuteTest(testtools.TestCase):
self.assertEqual(stderr, ex.stderr) self.assertEqual(stderr, ex.stderr)
else: else:
self.assertIsNone(ex.stderr) self.assertIsNone(ex.stderr)
if exit_status: if exit_status is not None:
self.assertEqual(exit_status, ex.exit_status) self.assertEqual(exit_status, ex.exit_status)
else: else:
self.assertTrue(ex.exit_status) self.assertTrue(ex.exit_status)
@ -116,6 +123,9 @@ class ExecuteTest(testtools.TestCase):
stdin='some input\n', stdin='some input\n',
stdout='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, def test_timeout_expires(self, command='sleep 10', timeout=5., stdin=None,
stdout=None, stderr=None, **kwargs): stdout=None, stderr=None, **kwargs):
ex = self.assertRaises(sh.ShellTimeoutExpired, ex = self.assertRaises(sh.ShellTimeoutExpired,