diff --git a/devops/helpers/log_templates.py b/devops/helpers/log_templates.py new file mode 100644 index 00000000..cc4d28e3 --- /dev/null +++ b/devops/helpers/log_templates.py @@ -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!") diff --git a/devops/helpers/ssh_client.py b/devops/helpers/ssh_client.py index 97350111..97ace254 100644 --- a/devops/helpers/ssh_client.py +++ b/devops/helpers/ssh_client.py @@ -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() diff --git a/devops/helpers/subprocess_runner.py b/devops/helpers/subprocess_runner.py index 3d29455c..de04d0af 100644 --- a/devops/helpers/subprocess_runner.py +++ b/devops/helpers/subprocess_runner.py @@ -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'] diff --git a/devops/tests/helpers/test_ssh_client.py b/devops/tests/helpers/test_ssh_client.py index cb86f50e..223d2bf8 100644 --- a/devops/tests/helpers/test_ssh_client.py +++ b/devops/tests/helpers/test_ssh_client.py @@ -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(), diff --git a/devops/tests/helpers/test_subprocess_runner.py b/devops/tests/helpers/test_subprocess_runner.py index f1c1ee2f..ea1855a5 100644 --- a/devops/tests/helpers/test_subprocess_runner.py +++ b/devops/tests/helpers/test_subprocess_runner.py @@ -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)), ])