Make logging more readable
Replace formatting templates for commands from `"{!r}"` to `u"{!s}"` for better representation of commands with more than one line. Change-Id: I76a29757d4faffff321cfa3df7e39190acbb406b Co-Authored-By: Fedor Zhadaev <fzhadaev@mirantis.com>
This commit is contained in:
parent
3cb41214b5
commit
272fab15b3
|
@ -0,0 +1,27 @@
|
|||
# coding=utf-8
|
||||
|
||||
# Copyright 2017 Mirantis, Inc.
|
||||
#
|
||||
# Licensed under the Apache License, Version 2.0 (the "License"); you may
|
||||
# not use this file except in compliance with the License. You may obtain
|
||||
# a copy of the License at
|
||||
#
|
||||
# http://www.apache.org/licenses/LICENSE-2.0
|
||||
#
|
||||
# Unless required by applicable law or agreed to in writing, software
|
||||
# distributed under the License is distributed on an "AS IS" BASIS, WITHOUT
|
||||
# WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. See the
|
||||
# License for the specific language governing permissions and limitations
|
||||
# under the License.
|
||||
|
||||
CMD_EXEC = u"\nExecuting command: '{cmd!s}'"
|
||||
CMD_RESULT = (u"\nCommand '{cmd!s}'\nexecution results: "
|
||||
u"Exit code: '{code!s}'")
|
||||
CMD_UNEXPECTED_EXIT_CODE = (u"{append}Command '{cmd!s}' returned "
|
||||
u"exit code '{code!s}' while "
|
||||
u"expected '{expected!s}'\n")
|
||||
CMD_UNEXPECTED_STDERR = (u"{append}Command '{cmd!s}' STDERR while "
|
||||
u"not expected\n"
|
||||
u"\texit code: '{code!s}'")
|
||||
CMD_WAIT_ERROR = (u"Wait for '{cmd!s}' during {timeout!s}s: "
|
||||
u"no return code!")
|
|
@ -29,6 +29,7 @@ import six
|
|||
from devops import error
|
||||
from devops.helpers import decorators
|
||||
from devops.helpers import exec_result
|
||||
from devops.helpers import log_templates
|
||||
from devops.helpers import proc_enums
|
||||
from devops import logger
|
||||
|
||||
|
@ -629,8 +630,7 @@ class SSHClient(six.with_metaclass(_MemorizedSSH, object)):
|
|||
ret = self.execute(command, verbose, timeout, **kwargs)
|
||||
if ret['exit_code'] not in expected:
|
||||
message = (
|
||||
"{append}Command '{cmd!r}' returned exit code {code!s} while "
|
||||
"expected {expected!s}\n".format(
|
||||
log_templates.CMD_UNEXPECTED_EXIT_CODE.format(
|
||||
append=error_info + '\n' if error_info else '',
|
||||
cmd=command,
|
||||
code=ret['exit_code'],
|
||||
|
@ -665,8 +665,7 @@ class SSHClient(six.with_metaclass(_MemorizedSSH, object)):
|
|||
error_info=error_info, raise_on_err=raise_on_err, **kwargs)
|
||||
if ret['stderr']:
|
||||
message = (
|
||||
"{append}Command '{cmd!r}' STDERR while not expected\n"
|
||||
"\texit code: {code!s}\n".format(
|
||||
log_templates.CMD_UNEXPECTED_STDERR.format(
|
||||
append=error_info + '\n' if error_info else '',
|
||||
cmd=command,
|
||||
code=ret['exit_code'],
|
||||
|
@ -780,10 +779,12 @@ class SSHClient(six.with_metaclass(_MemorizedSSH, object)):
|
|||
# channel.status_event.wait(timeout)
|
||||
result = exec_result.ExecResult(cmd=command)
|
||||
stop_event = threading.Event()
|
||||
message = log_templates.CMD_EXEC.format(cmd=command.rstrip())
|
||||
if verbose:
|
||||
logger.info("\nExecuting command: {!r}".format(command.rstrip()))
|
||||
logger.info(message)
|
||||
else:
|
||||
logger.debug("\nExecuting command: {!r}".format(command.rstrip()))
|
||||
logger.debug(message)
|
||||
|
||||
poll_pipes(
|
||||
stdout=stdout,
|
||||
stderr=stderr,
|
||||
|
@ -802,9 +803,9 @@ class SSHClient(six.with_metaclass(_MemorizedSSH, object)):
|
|||
|
||||
stop_event.set()
|
||||
channel.close()
|
||||
|
||||
wait_err_msg = ('Wait for {0!r} during {1}s: no return code!\n'
|
||||
.format(command, timeout))
|
||||
wait_err_msg = log_templates.CMD_WAIT_ERROR.format(
|
||||
cmd=command.rstrip(),
|
||||
timeout=timeout)
|
||||
output_brief_msg = ('\tSTDOUT:\n'
|
||||
'{0}\n'
|
||||
'\tSTDERR"\n'
|
||||
|
@ -828,12 +829,8 @@ class SSHClient(six.with_metaclass(_MemorizedSSH, object)):
|
|||
command, chan, stdout, stderr, timeout,
|
||||
verbose=verbose
|
||||
)
|
||||
|
||||
message = (
|
||||
'\n{cmd!r} execution results: Exit code: {code!s}'.format(
|
||||
cmd=command,
|
||||
code=result.exit_code
|
||||
))
|
||||
message = (log_templates.CMD_RESULT.format(
|
||||
cmd=command.rstrip(), code=result.exit_code))
|
||||
if verbose:
|
||||
logger.info(message)
|
||||
else:
|
||||
|
@ -853,7 +850,8 @@ class SSHClient(six.with_metaclass(_MemorizedSSH, object)):
|
|||
paramiko.ChannelFile
|
||||
)
|
||||
"""
|
||||
logger.debug("Executing command: {!r}".format(command.rstrip()))
|
||||
message = log_templates.CMD_EXEC.format(cmd=command.rstrip())
|
||||
logger.debug(message)
|
||||
|
||||
chan = self._ssh.get_transport().open_session()
|
||||
|
||||
|
|
|
@ -26,6 +26,7 @@ import six
|
|||
from devops import error
|
||||
from devops.helpers import decorators
|
||||
from devops.helpers import exec_result
|
||||
from devops.helpers import log_templates
|
||||
from devops.helpers import metaclasses
|
||||
from devops.helpers import proc_enums
|
||||
from devops import logger
|
||||
|
@ -125,13 +126,11 @@ class Subprocess(six.with_metaclass(metaclasses.SingletonMeta, object)):
|
|||
with cls.__lock:
|
||||
result = exec_result.ExecResult(cmd=command)
|
||||
stop_event = threading.Event()
|
||||
|
||||
message = log_templates.CMD_EXEC.format(cmd=command.rstrip())
|
||||
if verbose:
|
||||
logger.info("\nExecuting command: {!r}"
|
||||
.format(command.rstrip()))
|
||||
logger.info(message)
|
||||
else:
|
||||
logger.debug("\nExecuting command: {!r}"
|
||||
.format(command.rstrip()))
|
||||
logger.debug(message)
|
||||
# Run
|
||||
process = subprocess.Popen(
|
||||
args=[command],
|
||||
|
@ -150,7 +149,6 @@ class Subprocess(six.with_metaclass(metaclasses.SingletonMeta, object)):
|
|||
if stop_event.isSet():
|
||||
stop_event.clear()
|
||||
return result
|
||||
|
||||
# Kill not ended process and wait for close
|
||||
try:
|
||||
process.kill() # kill -9
|
||||
|
@ -159,11 +157,12 @@ class Subprocess(six.with_metaclass(metaclasses.SingletonMeta, object)):
|
|||
except OSError:
|
||||
# Nothing to kill
|
||||
logger.warning(
|
||||
"{!r} has been completed just after timeout: "
|
||||
u"{!s} has been completed just after timeout: "
|
||||
"please validate timeout.".format(command))
|
||||
|
||||
wait_err_msg = ('Wait for {0!r} during {1}s: no return code!\n'
|
||||
.format(command, timeout))
|
||||
wait_err_msg = log_templates.CMD_WAIT_ERROR.format(
|
||||
cmd=command.rstrip(),
|
||||
timeout=timeout)
|
||||
output_brief_msg = ('\tSTDOUT:\n'
|
||||
'{0}\n'
|
||||
'\tSTDERR"\n'
|
||||
|
@ -186,11 +185,8 @@ class Subprocess(six.with_metaclass(metaclasses.SingletonMeta, object)):
|
|||
"""
|
||||
result = cls.__exec_command(command=command, timeout=timeout,
|
||||
verbose=verbose, **kwargs)
|
||||
message = (
|
||||
'\n{cmd!r} execution results: Exit code: {code!s}'.format(
|
||||
cmd=command,
|
||||
code=result.exit_code
|
||||
))
|
||||
message = log_templates.CMD_RESULT.format(
|
||||
cmd=command, code=result.exit_code)
|
||||
if verbose:
|
||||
logger.info(message)
|
||||
else:
|
||||
|
@ -232,8 +228,7 @@ class Subprocess(six.with_metaclass(metaclasses.SingletonMeta, object)):
|
|||
ret = cls.execute(command, verbose, timeout, **kwargs)
|
||||
if ret['exit_code'] not in expected:
|
||||
message = (
|
||||
"{append}Command '{cmd!r}' returned exit code {code!s} while "
|
||||
"expected {expected!s}\n".format(
|
||||
log_templates.CMD_UNEXPECTED_EXIT_CODE.format(
|
||||
append=error_info + '\n' if error_info else '',
|
||||
cmd=command,
|
||||
code=ret['exit_code'],
|
||||
|
@ -271,8 +266,7 @@ class Subprocess(six.with_metaclass(metaclasses.SingletonMeta, object)):
|
|||
error_info=error_info, raise_on_err=raise_on_err, **kwargs)
|
||||
if ret['stderr']:
|
||||
message = (
|
||||
"{append}Command '{cmd!r}' STDERR while not expected\n"
|
||||
"\texit code: {code!s}\n".format(
|
||||
log_templates.CMD_UNEXPECTED_STDERR.format(
|
||||
append=error_info + '\n' if error_info else '',
|
||||
cmd=command,
|
||||
code=ret['exit_code']
|
||||
|
|
|
@ -1,3 +1,5 @@
|
|||
# coding=utf-8
|
||||
|
||||
# Copyright 2016 Mirantis, Inc.
|
||||
#
|
||||
# Licensed under the Apache License, Version 2.0 (the "License"); you may
|
||||
|
@ -62,7 +64,8 @@ port = 22
|
|||
username = 'user'
|
||||
password = 'pass'
|
||||
private_keys = []
|
||||
command = 'ls ~ '
|
||||
command = 'ls ~\nline 2\nline 3\nline с кирилицей'
|
||||
command_log = u"\nExecuting command: '{!s}'".format(command.rstrip())
|
||||
stdout_list = [b' \n', b'2\n', b'3\n', b' \n']
|
||||
stderr_list = [b' \n', b'0\n', b'1\n', b' \n']
|
||||
encoded_cmd = base64.b64encode(
|
||||
|
@ -920,6 +923,12 @@ class TestExecute(unittest.TestCase):
|
|||
password=password
|
||||
))
|
||||
|
||||
@staticmethod
|
||||
def gen_cmd_result_log_message(result):
|
||||
return (u"\nCommand '{cmd!s}'\nexecution results: "
|
||||
u"Exit code: '{code!s}'".format(
|
||||
cmd=result.cmd.rstrip(), code=result.exit_code))
|
||||
|
||||
def test_execute_async(self, client, policy, logger):
|
||||
chan = mock.Mock()
|
||||
open_session = mock.Mock(return_value=chan)
|
||||
|
@ -945,8 +954,7 @@ class TestExecute(unittest.TestCase):
|
|||
mock.call.exec_command('{}\n'.format(command))
|
||||
))
|
||||
self.assertIn(
|
||||
mock.call.debug(
|
||||
"Executing command: {!r}".format(command.rstrip())),
|
||||
mock.call.debug(command_log),
|
||||
logger.mock_calls
|
||||
)
|
||||
|
||||
|
@ -980,8 +988,7 @@ class TestExecute(unittest.TestCase):
|
|||
mock.call.exec_command('{}\n'.format(command))
|
||||
))
|
||||
self.assertIn(
|
||||
mock.call.debug(
|
||||
"Executing command: {!r}".format(command.rstrip())),
|
||||
mock.call.debug(command_log),
|
||||
logger.mock_calls
|
||||
)
|
||||
|
||||
|
@ -1013,8 +1020,7 @@ class TestExecute(unittest.TestCase):
|
|||
"eval \"$(base64 -d <(echo \"{0}\"))\"'".format(encoded_cmd))
|
||||
))
|
||||
self.assertIn(
|
||||
mock.call.debug(
|
||||
"Executing command: {!r}".format(command.rstrip())),
|
||||
mock.call.debug(command_log),
|
||||
logger.mock_calls
|
||||
)
|
||||
|
||||
|
@ -1049,8 +1055,7 @@ class TestExecute(unittest.TestCase):
|
|||
"eval \"$(base64 -d <(echo \"{0}\"))\"'".format(encoded_cmd))
|
||||
))
|
||||
self.assertIn(
|
||||
mock.call.debug(
|
||||
"Executing command: {!r}".format(command.rstrip())),
|
||||
mock.call.debug(command_log),
|
||||
logger.mock_calls
|
||||
)
|
||||
|
||||
|
@ -1081,8 +1086,7 @@ class TestExecute(unittest.TestCase):
|
|||
mock.call.exec_command('{}\n'.format(command))
|
||||
))
|
||||
self.assertIn(
|
||||
mock.call.debug(
|
||||
"Executing command: {!r}".format(command.rstrip())),
|
||||
mock.call.debug(command_log),
|
||||
logger.mock_calls
|
||||
)
|
||||
|
||||
|
@ -1113,8 +1117,7 @@ class TestExecute(unittest.TestCase):
|
|||
mock.call.exec_command('{}\n'.format(command))
|
||||
))
|
||||
self.assertIn(
|
||||
mock.call.debug(
|
||||
"Executing command: {!r}".format(command.rstrip())),
|
||||
mock.call.debug(command_log),
|
||||
logger.mock_calls
|
||||
)
|
||||
|
||||
|
@ -1158,8 +1161,7 @@ class TestExecute(unittest.TestCase):
|
|||
"eval \"$(base64 -d <(echo \"{0}\"))\"'".format(encoded_cmd))
|
||||
))
|
||||
self.assertIn(
|
||||
mock.call.debug(
|
||||
"Executing command: {!r}".format(command.rstrip())),
|
||||
mock.call.debug(command_log),
|
||||
logger.mock_calls
|
||||
)
|
||||
|
||||
|
@ -1229,9 +1231,9 @@ class TestExecute(unittest.TestCase):
|
|||
)
|
||||
execute_async.assert_called_once_with(command)
|
||||
chan.assert_has_calls((mock.call.status_event.is_set(), ))
|
||||
message = self.gen_cmd_result_log_message(result)
|
||||
logger.assert_has_calls([
|
||||
mock.call.debug(
|
||||
"\nExecuting command: {!r}".format(command.rstrip())),
|
||||
mock.call.debug(command_log),
|
||||
] + [
|
||||
mock.call.debug(str(x.rstrip().decode('utf-8')))
|
||||
for x in stdout_list
|
||||
|
@ -1239,12 +1241,7 @@ class TestExecute(unittest.TestCase):
|
|||
mock.call.debug(str(x.rstrip().decode('utf-8')))
|
||||
for x in stderr_list
|
||||
] + [
|
||||
mock.call.debug(
|
||||
'\n{cmd!r} execution results: '
|
||||
'Exit code: {code!s}'.format(
|
||||
cmd=command,
|
||||
code=result.exit_code,
|
||||
)),
|
||||
mock.call.debug(message),
|
||||
])
|
||||
|
||||
@mock.patch(
|
||||
|
@ -1275,9 +1272,9 @@ class TestExecute(unittest.TestCase):
|
|||
execute_async.assert_called_once_with(command)
|
||||
chan.assert_has_calls((mock.call.status_event.is_set(), ))
|
||||
|
||||
message = self.gen_cmd_result_log_message(result)
|
||||
logger.assert_has_calls([
|
||||
mock.call.info(
|
||||
"\nExecuting command: {!r}".format(command.rstrip())),
|
||||
mock.call.info(command_log),
|
||||
] + [
|
||||
mock.call.info(str(x.rstrip().decode('utf-8')))
|
||||
for x in stdout_list
|
||||
|
@ -1285,12 +1282,7 @@ class TestExecute(unittest.TestCase):
|
|||
mock.call.error(str(x.rstrip().decode('utf-8')))
|
||||
for x in stderr_list
|
||||
] + [
|
||||
mock.call.info(
|
||||
'\n{cmd!r} execution results: '
|
||||
'Exit code: {code!s}'.format(
|
||||
cmd=command,
|
||||
code=result.exit_code,
|
||||
)),
|
||||
mock.call.info(message),
|
||||
])
|
||||
|
||||
@mock.patch('time.sleep', autospec=True)
|
||||
|
@ -1321,13 +1313,9 @@ class TestExecute(unittest.TestCase):
|
|||
)
|
||||
execute_async.assert_called_once_with(command)
|
||||
chan.assert_has_calls((mock.call.status_event.is_set(), ))
|
||||
message = self.gen_cmd_result_log_message(result)
|
||||
logger.assert_has_calls((
|
||||
mock.call.debug(
|
||||
'\n{cmd!r} execution results: '
|
||||
'Exit code: {code!s}'.format(
|
||||
cmd=exp_result.cmd,
|
||||
code=exp_result.exit_code
|
||||
)),
|
||||
mock.call.debug(message),
|
||||
))
|
||||
|
||||
@mock.patch(
|
||||
|
@ -1616,7 +1604,7 @@ class TestExecuteThrowHost(unittest.TestCase):
|
|||
channel.assert_has_calls((
|
||||
mock.call.makefile('rb'),
|
||||
mock.call.makefile_stderr('rb'),
|
||||
mock.call.exec_command('ls ~ '),
|
||||
mock.call.exec_command(command),
|
||||
mock.call.recv_ready(),
|
||||
mock.call.recv_stderr_ready(),
|
||||
mock.call.status_event.is_set(),
|
||||
|
@ -1670,7 +1658,7 @@ class TestExecuteThrowHost(unittest.TestCase):
|
|||
channel.assert_has_calls((
|
||||
mock.call.makefile('rb'),
|
||||
mock.call.makefile_stderr('rb'),
|
||||
mock.call.exec_command('ls ~ '),
|
||||
mock.call.exec_command(command),
|
||||
mock.call.recv_ready(),
|
||||
mock.call.recv_stderr_ready(),
|
||||
mock.call.status_event.is_set(),
|
||||
|
|
|
@ -1,3 +1,5 @@
|
|||
# coding=utf-8
|
||||
|
||||
# Copyright 2016 Mirantis, Inc.
|
||||
#
|
||||
# Licensed under the Apache License, Version 2.0 (the "License"); you may
|
||||
|
@ -23,7 +25,8 @@ from devops import error
|
|||
from devops.helpers import exec_result
|
||||
from devops.helpers import subprocess_runner
|
||||
|
||||
command = 'ls ~ '
|
||||
command = 'ls ~\nline 2\nline 3\nline с кирилицей'
|
||||
command_log = u"\nExecuting command: '{!s}'".format(command.rstrip())
|
||||
stdout_list = [b' \n', b'2\n', b'3\n', b' \n']
|
||||
stderr_list = [b' \n', b'0\n', b'1\n', b' \n']
|
||||
|
||||
|
@ -73,6 +76,12 @@ class TestSubprocessRunner(unittest.TestCase):
|
|||
|
||||
return popen_obj, exp_result
|
||||
|
||||
@staticmethod
|
||||
def gen_cmd_result_log_message(result):
|
||||
return (u"\nCommand '{cmd!s}'\nexecution results: "
|
||||
u"Exit code: '{code!s}'".format(
|
||||
cmd=result.cmd.rstrip(), code=result.exit_code))
|
||||
|
||||
def test_call(self, popen, fcntl, select, logger):
|
||||
popen_obj, exp_result = self.prepare_close(popen)
|
||||
select.return_value = [popen_obj.stdout, popen_obj.stderr], [], []
|
||||
|
@ -97,8 +106,7 @@ class TestSubprocessRunner(unittest.TestCase):
|
|||
universal_newlines=False),
|
||||
))
|
||||
logger.assert_has_calls([
|
||||
mock.call.debug(
|
||||
"\nExecuting command: {!r}".format(command.rstrip())),
|
||||
mock.call.debug(command_log),
|
||||
] + [
|
||||
mock.call.debug(str(x.rstrip().decode('utf-8')))
|
||||
for x in stdout_list
|
||||
|
@ -106,12 +114,7 @@ class TestSubprocessRunner(unittest.TestCase):
|
|||
mock.call.debug(str(x.rstrip().decode('utf-8')))
|
||||
for x in stderr_list
|
||||
] + [
|
||||
mock.call.debug(
|
||||
'\n{cmd!r} execution results: '
|
||||
'Exit code: {code!s}'.format(
|
||||
cmd=command,
|
||||
code=result.exit_code
|
||||
)),
|
||||
mock.call.debug(self.gen_cmd_result_log_message(result)),
|
||||
])
|
||||
self.assertIn(
|
||||
mock.call.poll(), popen_obj.mock_calls
|
||||
|
@ -127,8 +130,7 @@ class TestSubprocessRunner(unittest.TestCase):
|
|||
result = runner.execute(command, verbose=True)
|
||||
|
||||
logger.assert_has_calls([
|
||||
mock.call.info(
|
||||
"\nExecuting command: {!r}".format(command.rstrip())),
|
||||
mock.call.info(command_log),
|
||||
] + [
|
||||
mock.call.info(str(x.rstrip().decode('utf-8')))
|
||||
for x in stdout_list
|
||||
|
@ -136,12 +138,7 @@ class TestSubprocessRunner(unittest.TestCase):
|
|||
mock.call.error(str(x.rstrip().decode('utf-8')))
|
||||
for x in stderr_list
|
||||
] + [
|
||||
mock.call.info(
|
||||
'\n{cmd!r} execution results: '
|
||||
'Exit code: {code!s}'.format(
|
||||
cmd=command,
|
||||
code=result.exit_code,
|
||||
)),
|
||||
mock.call.info(self.gen_cmd_result_log_message(result)),
|
||||
])
|
||||
|
||||
|
||||
|
|
Loading…
Reference in New Issue