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:
Alexey Zvyagintsev 2017-06-16 15:07:08 +03:00 committed by Fedor Zhadaev
parent 3cb41214b5
commit 272fab15b3
5 changed files with 94 additions and 90 deletions

View File

@ -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!")

View File

@ -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()

View File

@ -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']

View File

@ -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(),

View File

@ -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)),
])