Logger fixes. Fix #37 (#38)

* Logger fixes. Fix #37

* [x] Use class name as logger prefix
* [x] Use normal repr instead of manual `'{}'` code
* [x] On reconnect/close use client logger instead of formatting to str
* [x] Single used log templates moved to the use place

Author: penguinolog

exec_helpers/_api.py

@@ -33,7 +33,6 @@
 from exec_helpers import exceptions
 from exec_helpers import exec_result  # noqa  # pylint: disable=unused-import
 from exec_helpers import proc_enums
-from exec_helpers import _log_templates
 
 _type_exit_codes = typing.Union[int, proc_enums.ExitCodes]
 _type_expected = typing.Optional[typing.Iterable[_type_exit_codes]]
@@ -249,7 +248,7 @@ def execute(
                 verbose=verbose,
                 **kwargs
             )
-            message = _log_templates.CMD_RESULT.format(result=result)
+            message = "Command {result.cmd!r} exit code: {result.exit_code!s}".format(result=result)
             self.logger.log(
                 level=logging.INFO if verbose else logging.DEBUG,
                 msg=message
@@ -292,7 +291,8 @@ def check_call(
         ret = self.execute(command, verbose, timeout, **kwargs)
         if ret['exit_code'] not in expected:
             message = (
-                _log_templates.CMD_UNEXPECTED_EXIT_CODE.format(
+                "{append}Command {result.cmd!r} returned exit code "
+                "{result.exit_code!s} while expected {expected!s}".format(
                     append=error_info + '\n' if error_info else '',
                     result=ret,
                     expected=expected
@@ -339,7 +339,8 @@ def check_stderr(
             error_info=error_info, raise_on_err=raise_on_err, **kwargs)
         if ret['stderr']:
             message = (
-                _log_templates.CMD_UNEXPECTED_STDERR.format(
+                "{append}Command {result.cmd!r} STDERR while not expected\n"
+                "\texit code: {result.exit_code!s}".format(
                     append=error_info + '\n' if error_info else '',
                     result=ret,
                 ))

exec_helpers/_log_templates.py

@@ -20,18 +20,10 @@
 from __future__ import division
 from __future__ import unicode_literals
 
-CMD_EXEC = "Executing command:\n{cmd!s}\n"
-CMD_RESULT = "Command exit code '{result.exit_code!s}':\n{result.cmd}\n"
-CMD_UNEXPECTED_EXIT_CODE = (
-    "{append}Command '{result.cmd}' returned exit code '{result.exit_code!s}' "
-    "while expected '{expected!s}'"
-)
-CMD_UNEXPECTED_STDERR = (
-    "{append}Command '{result.cmd}' STDERR while not expected\n"
-    "\texit code: '{result.exit_code!s}'"
-)
+CMD_EXEC = "Executing command:\n{cmd!r}\n"
+
 CMD_WAIT_ERROR = (
-    "Wait for '{result.cmd}' during {timeout!s}s: no return code!\n"
+    "Wait for {result.cmd!r} during {timeout!s}s: no return code!\n"
     '\tSTDOUT:\n'
     '{result.stdout_brief}\n'
     '\tSTDERR"\n'

exec_helpers/_ssh_client_base.py

@@ -50,7 +50,6 @@
 
 __all__ = ('SSHClientBase', )
 
-logger = logging.getLogger(__name__)
 logging.getLogger('paramiko').setLevel(logging.WARNING)
 logging.getLogger('iso8601').setLevel(logging.WARNING)
 
@@ -59,9 +58,6 @@
 ]
 _type_RSAKeys = typing.Iterable[paramiko.RSAKey]
 _type_exit_codes = typing.Union[int, proc_enums.ExitCodes]
-_type_multiple_results = typing.Dict[
-    typing.Tuple[str, int], exec_result.ExecResult
-]
 _type_execute_async = typing.Tuple[
     paramiko.Channel,
     paramiko.ChannelFile,
@@ -149,7 +145,7 @@ def __call__(
                 try:
                     ssh.execute('cd ~', timeout=5)
                 except BaseException:  # Note: Do not change to lower level!
-                    logger.debug('Reconnect {}'.format(ssh))
+                    ssh.logger.debug('Reconnect')
                     ssh.reconnect()
                 return ssh
             if (
@@ -158,7 +154,7 @@ def __call__(
             ):    # pragma: no cover
                 # If we have only cache reference and temporary getrefcount
                 # reference: close connection before deletion
-                logger.debug('Closing {} as unused'.format(cls.__cache[key]))
+                cls.__cache[key].logger.debug('Closing as unused')
                 cls.__cache[key].close()
             del cls.__cache[key]
         # noinspection PyArgumentList
@@ -186,7 +182,7 @@ def clear_cache(mcs):  # type: () -> None
                 CPYTHON and
                 sys.getrefcount(ssh) == n_count
             ):  # pragma: no cover
-                logger.debug('Closing {} as unused'.format(ssh))
+                ssh.logger.debug('Closing as unused')
                 ssh.close()
         mcs.__cache = {}
 
@@ -306,7 +302,9 @@ def __init__(
         .. note:: auth has priority over username/password/private_keys
         """
         super(SSHClientBase, self).__init__(
-            logger=logger.getChild(
+            logger=logging.getLogger(
+                self.__class__.__name__
+            ).getChild(
                 '{host}:{port}'.format(host=host, port=port)
             ),
         )
@@ -376,7 +374,7 @@ def __repr__(self):
             auth=self.auth
         )
 
-    def __str__(self):
+    def __str__(self):  # pragma: no cover
         """Representation for debug purposes."""
         return '{cls}(host={host}, port={port}) for user {user}'.format(
             cls=self.__class__.__name__, host=self.hostname, port=self.port,
@@ -832,7 +830,7 @@ def execute_together(
         expected=None,  # type: typing.Optional[typing.Iterable[int]]
         raise_on_err=True,  # type: bool
         **kwargs
-    ):  # type: (...) -> _type_multiple_results
+    ):  # type: (...) -> typing.Dict[typing.Tuple[str, int], exec_result.ExecResult]
         """Execute command on multiple remotes in async mode.
 
         :param remotes: Connections to execute on

exec_helpers/ssh_auth.py

@@ -187,9 +187,7 @@ def connect(
                     logger.exception('No password has been set!')
                     raise
                 else:
-                    logger.critical(
-                        'Unexpected PasswordRequiredException, '
-                        'when password is set!')
+                    logger.critical('Unexpected PasswordRequiredException, when password is set!')
                     raise
             except (paramiko.AuthenticationException,
                     paramiko.BadHostKeyException):

test/test_ssh_client.py

@@ -53,7 +53,7 @@ def __iter__(self):
 username = 'user'
 password = 'pass'
 command = 'ls ~\nline 2\nline 3\nline с кирилицей'
-command_log = u"Executing command:\n{!s}\n".format(command.rstrip())
+command_log = u"Executing command:\n{!r}\n".format(command.rstrip())
 stdout_list = [b' \n', b'2\n', b'3\n', b' \n']
 stdout_str = b''.join(stdout_list).strip().decode('utf-8')
 stderr_list = [b' \n', b'0\n', b'1\n', b' \n']
@@ -64,7 +64,7 @@ def __iter__(self):
 print_stdin = 'read line; echo "$line"'
 
 
-@mock.patch('exec_helpers._ssh_client_base.logger', autospec=True)
+@mock.patch('logging.getLogger', autospec=True)
 @mock.patch('paramiko.AutoAddPolicy', autospec=True, return_value='AutoAddPolicy')
 @mock.patch('paramiko.SSHClient', autospec=True)
 class TestExecute(unittest.TestCase):
@@ -89,8 +89,7 @@ def get_ssh():
 
     @staticmethod
     def gen_cmd_result_log_message(result):
-        return (u"Command exit code '{code!s}':\n{cmd!s}\n"
-                .format(cmd=result.cmd.rstrip(), code=result.exit_code))
+        return u"Command {result.cmd!r} exit code: {result.exit_code!s}".format(result=result)
 
     def test_001_execute_async(self, client, policy, logger):
         chan = mock.Mock()
@@ -116,7 +115,8 @@ def test_001_execute_async(self, client, policy, logger):
             mock.call.makefile_stderr('rb'),
             mock.call.exec_command('{}\n'.format(command))
         ))
-        log = logger.getChild('{host}:{port}'.format(host=host, port=port))
+        # raise ValueError(logger.mock_calls)
+        log = logger(ssh.__class__.__name__).getChild('{host}:{port}'.format(host=host, port=port))
         self.assertIn(
             mock.call.log(level=logging.DEBUG, msg=command_log),
             log.mock_calls
@@ -151,7 +151,7 @@ def test_002_execute_async_pty(self, client, policy, logger):
             mock.call.makefile_stderr('rb'),
             mock.call.exec_command('{}\n'.format(command))
         ))
-        log = logger.getChild('{host}:{port}'.format(host=host, port=port))
+        log = logger(ssh.__class__.__name__).getChild('{host}:{port}'.format(host=host, port=port))
         self.assertIn(
             mock.call.log(level=logging.DEBUG, msg=command_log),
             log.mock_calls
@@ -235,7 +235,7 @@ def test_004_execute_async_sudo(self, client, policy, logger):
                 "sudo -S bash -c '"
                 "eval \"$(base64 -d <(echo \"{0}\"))\"'".format(encoded_cmd))
         ))
-        log = logger.getChild('{host}:{port}'.format(host=host, port=port))
+        log = logger(ssh.__class__.__name__).getChild('{host}:{port}'.format(host=host, port=port))
         self.assertIn(
             mock.call.log(level=logging.DEBUG, msg=command_log),
             log.mock_calls
@@ -271,7 +271,7 @@ def test_005_execute_async_with_sudo_enforce(self, client, policy, logger):
                 "sudo -S bash -c '"
                 "eval \"$(base64 -d <(echo \"{0}\"))\"'".format(encoded_cmd))
         ))
-        log = logger.getChild('{host}:{port}'.format(host=host, port=port))
+        log = logger(ssh.__class__.__name__).getChild('{host}:{port}'.format(host=host, port=port))
         self.assertIn(
             mock.call.log(level=logging.DEBUG, msg=command_log),
             log.mock_calls
@@ -303,7 +303,7 @@ def test_006_execute_async_with_no_sudo_enforce(self, client, policy, logger):
             mock.call.makefile_stderr('rb'),
             mock.call.exec_command('{}\n'.format(command))
         ))
-        log = logger.getChild('{host}:{port}'.format(host=host, port=port))
+        log = logger(ssh.__class__.__name__).getChild('{host}:{port}'.format(host=host, port=port))
         self.assertIn(
             mock.call.log(level=logging.DEBUG, msg=command_log),
             log.mock_calls
@@ -335,7 +335,7 @@ def test_007_execute_async_with_sudo_none_enforce(self, client, policy, logger):
             mock.call.makefile_stderr('rb'),
             mock.call.exec_command('{}\n'.format(command))
         ))
-        log = logger.getChild('{host}:{port}'.format(host=host, port=port))
+        log = logger(ssh.__class__.__name__).getChild('{host}:{port}'.format(host=host, port=port))
         self.assertIn(
             mock.call.log(level=logging.DEBUG, msg=command_log),
             log.mock_calls
@@ -380,7 +380,7 @@ def test_008_execute_async_sudo_password(
                 "sudo -S bash -c '"
                 "eval \"$(base64 -d <(echo \"{0}\"))\"'".format(encoded_cmd))
         ))
-        log = logger.getChild('{host}:{port}'.format(host=host, port=port))
+        log = logger(ssh.__class__.__name__).getChild('{host}:{port}'.format(host=host, port=port))
         self.assertIn(
             mock.call.log(level=logging.DEBUG, msg=command_log),
             log.mock_calls
@@ -410,7 +410,7 @@ def test_009_execute_async_verbose(self, client, policy, logger):
             mock.call.makefile_stderr('rb'),
             mock.call.exec_command('{}\n'.format(command))
         ))
-        log = logger.getChild('{host}:{port}'.format(host=host, port=port))
+        log = logger(ssh.__class__.__name__).getChild('{host}:{port}'.format(host=host, port=port))
         self.assertIn(
             mock.call.log(level=logging.INFO, msg=command_log),
             log.mock_calls
@@ -420,7 +420,7 @@ def test_010_execute_async_mask_command(self, client, policy, logger):
         cmd = "USE='secret=secret_pass' do task"
         log_mask_re = r"secret\s*=\s*([A-Z-a-z0-9_\-]+)"
         masked_cmd = "USE='secret=<*masked*>' do task"
-        cmd_log = u"Executing command:\n{!s}\n".format(masked_cmd)
+        cmd_log = u"Executing command:\n{!r}\n".format(masked_cmd)
 
         chan = mock.Mock()
         open_session = mock.Mock(return_value=chan)
@@ -445,7 +445,7 @@ def test_010_execute_async_mask_command(self, client, policy, logger):
             mock.call.makefile_stderr('rb'),
             mock.call.exec_command('{}\n'.format(cmd))
         ))
-        log = logger.getChild('{host}:{port}'.format(host=host, port=port))
+        log = logger(ssh.__class__.__name__).getChild('{host}:{port}'.format(host=host, port=port))
         self.assertIn(
             mock.call.log(level=logging.DEBUG, msg=cmd_log),
             log.mock_calls
@@ -620,7 +620,7 @@ def test_014_check_stdin_closed(self, client, policy, logger):
         open_session.assert_called_once()
         stdin.assert_not_called()
 
-        log = logger.getChild('{host}:{port}'.format(host=host, port=port))
+        log = logger(ssh.__class__.__name__).getChild('{host}:{port}'.format(host=host, port=port))
         log.warning.assert_called_once_with('STDIN Send failed: closed channel')
 
         self.assertIn(chan, result)
@@ -777,7 +777,7 @@ def test_019_execute(
         execute_async.assert_called_once_with(command, verbose=False)
         chan.assert_has_calls((mock.call.status_event.is_set(), ))
         message = self.gen_cmd_result_log_message(result)
-        log = logger.getChild('{host}:{port}'.format(host=host, port=port)).log
+        log = logger(ssh.__class__.__name__).getChild('{host}:{port}'.format(host=host, port=port)).log
         log.assert_has_calls(
             [
                 mock.call(
@@ -824,7 +824,7 @@ def test_020_execute_verbose(
         chan.assert_has_calls((mock.call.status_event.is_set(), ))
 
         message = self.gen_cmd_result_log_message(result)
-        log = logger.getChild('{host}:{port}'.format(host=host, port=port)).log
+        log = logger(ssh.__class__.__name__).getChild('{host}:{port}'.format(host=host, port=port)).log
         log.assert_has_calls(
             [
                 mock.call(
@@ -872,7 +872,7 @@ def test_021_execute_no_stdout(
         execute_async.assert_called_once_with(
             command, verbose=False, open_stdout=False)
         message = self.gen_cmd_result_log_message(result)
-        log = logger.getChild('{host}:{port}'.format(host=host, port=port)).log
+        log = logger(ssh.__class__.__name__).getChild('{host}:{port}'.format(host=host, port=port)).log
         log.assert_has_calls(
             [
                 mock.call(
@@ -916,7 +916,7 @@ def test_022_execute_no_stderr(
         execute_async.assert_called_once_with(
             command, verbose=False, open_stderr=False)
         message = self.gen_cmd_result_log_message(result)
-        log = logger.getChild('{host}:{port}'.format(host=host, port=port)).log
+        log = logger(ssh.__class__.__name__).getChild('{host}:{port}'.format(host=host, port=port)).log
         log.assert_has_calls(
             [
                 mock.call(
@@ -968,7 +968,7 @@ def test_023_execute_no_stdout_stderr(
             open_stderr=False
         )
         message = self.gen_cmd_result_log_message(result)
-        log = logger.getChild('{host}:{port}'.format(host=host, port=port)).log
+        log = logger(ssh.__class__.__name__).getChild('{host}:{port}'.format(host=host, port=port)).log
         log.assert_has_calls(
             [
                 mock.call(level=logging.DEBUG, msg=message),
@@ -1003,7 +1003,7 @@ def test_024_execute_timeout(
         execute_async.assert_called_once_with(command, verbose=False)
         chan.assert_has_calls((mock.call.status_event.is_set(), ))
         message = self.gen_cmd_result_log_message(result)
-        log = logger.getChild('{host}:{port}'.format(host=host, port=port)).log
+        log = logger(ssh.__class__.__name__).getChild('{host}:{port}'.format(host=host, port=port)).log
         self.assertIn(
             mock.call(level=logging.DEBUG, msg=message),
             log.mock_calls
@@ -1069,7 +1069,7 @@ def test_026_execute_mask_command(
             cmd, log_mask_re=log_mask_re, verbose=False)
         chan.assert_has_calls((mock.call.status_event.is_set(),))
         message = self.gen_cmd_result_log_message(result)
-        log = logger.getChild('{host}:{port}'.format(host=host, port=port)).log
+        log = logger(ssh.__class__.__name__).getChild('{host}:{port}'.format(host=host, port=port)).log
         log.assert_has_calls(
             [
                 mock.call(
@@ -1297,7 +1297,7 @@ def test_031_check_stderr(self, check_call, client, policy, logger):
             error_info=None, raise_on_err=raise_on_err)
 
 
-@mock.patch('exec_helpers._ssh_client_base.logger', autospec=True)
+@mock.patch('logging.getLogger', autospec=True)
 @mock.patch('paramiko.AutoAddPolicy', autospec=True, return_value='AutoAddPolicy')
 @mock.patch('paramiko.SSHClient', autospec=True)
 @mock.patch('paramiko.Transport', autospec=True)
@@ -1528,7 +1528,7 @@ def test_03_execute_through_host_get_pty(
         ))
 
 
-@mock.patch('exec_helpers._ssh_client_base.logger', autospec=True)
+@mock.patch('logging.getLogger', autospec=True)
 @mock.patch('paramiko.AutoAddPolicy', autospec=True, return_value='AutoAddPolicy')
 @mock.patch('paramiko.SSHClient', autospec=True)
 class TestSftp(unittest.TestCase):