diff --git a/exec_helpers/_api.py b/exec_helpers/_api.py index 3283474..55c32ad 100644 --- a/exec_helpers/_api.py +++ b/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, )) diff --git a/exec_helpers/_log_templates.py b/exec_helpers/_log_templates.py index d3f8c3b..56cda0f 100644 --- a/exec_helpers/_log_templates.py +++ b/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' diff --git a/exec_helpers/_ssh_client_base.py b/exec_helpers/_ssh_client_base.py index 8ac7d88..e30ca28 100644 --- a/exec_helpers/_ssh_client_base.py +++ b/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 diff --git a/exec_helpers/ssh_auth.py b/exec_helpers/ssh_auth.py index 7ab9f98..63ca33b 100644 --- a/exec_helpers/ssh_auth.py +++ b/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): diff --git a/test/test_ssh_client.py b/test/test_ssh_client.py index 3a3c4a3..9119773 100644 --- a/test/test_ssh_client.py +++ b/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): diff --git a/test/test_ssh_client_init.py b/test/test_ssh_client_init.py index 8117eff..a5f400d 100644 --- a/test/test_ssh_client_init.py +++ b/test/test_ssh_client_init.py @@ -381,9 +381,10 @@ def test_013_init_clear_failed(self, client, policy, logger): _ssh.attach_mock(mock.Mock(return_value=_sftp), 'open_sftp') with mock.patch( - 'exec_helpers._ssh_client_base.logger', + 'logging.getLogger', autospec=True - ) as ssh_logger: + ) as get_logger: + ssh_logger = get_logger(exec_helpers.SSHClient.__name__) ssh = exec_helpers.SSHClient( host=host, @@ -408,13 +409,13 @@ def test_013_init_clear_failed(self, client, policy, logger): ssh.close() - log = ssh_logger.getChild( - '{host}:{port}'.format(host=host, port=port) - ) - log.assert_has_calls(( - mock.call.exception('Could not close ssh connection'), - mock.call.exception('Could not close sftp connection'), - )) + log = ssh_logger.getChild( + '{host}:{port}'.format(host=host, port=port) + ) + log.assert_has_calls(( + mock.call.exception('Could not close ssh connection'), + mock.call.exception('Could not close sftp connection'), + )) def test_014_init_reconnect(self, client, policy, logger): """Test reconnect @@ -619,9 +620,10 @@ def test_021_init_no_sftp(self, client, policy, logger): client.return_value = _ssh with mock.patch( - 'exec_helpers._ssh_client_base.logger', + 'logging.getLogger', autospec=True - ) as ssh_logger: + ) as get_logger: + ssh_logger = get_logger(exec_helpers.SSHClient.__name__) ssh = exec_helpers.SSHClient( host=host, auth=exec_helpers.SSHAuth(password=password)) @@ -631,14 +633,14 @@ def test_021_init_no_sftp(self, client, policy, logger): # noinspection PyStatementEffect ssh._sftp # pylint: enable=pointless-statement - log = ssh_logger.getChild( - '{host}:{port}'.format(host=host, port=port) - ) - log.assert_has_calls(( - mock.call.debug('SFTP is not connected, try to connect...'), - mock.call.warning( - 'SFTP enable failed! SSH only is accessible.'), - )) + log = ssh_logger.getChild( + '{host}:{port}'.format(host=host, port=port) + ) + log.assert_has_calls(( + mock.call.debug('SFTP is not connected, try to connect...'), + mock.call.warning( + 'SFTP enable failed! SSH only is accessible.'), + )) def test_022_init_sftp_repair(self, client, policy, logger): _sftp = mock.Mock() @@ -652,9 +654,10 @@ def test_022_init_sftp_repair(self, client, policy, logger): client.return_value = _ssh with mock.patch( - 'exec_helpers._ssh_client_base.logger', + 'logging.getLogger', autospec=True - ) as ssh_logger: + ) as get_logger: + ssh_logger = get_logger(exec_helpers.SSHClient.__name__) ssh = exec_helpers.SSHClient( host=host, auth=exec_helpers.SSHAuth(password=password) @@ -670,12 +673,12 @@ def test_022_init_sftp_repair(self, client, policy, logger): sftp = ssh._sftp self.assertEqual(sftp, open_sftp()) - log = ssh_logger.getChild( - '{host}:{port}'.format(host=host, port=port) - ) - log.assert_has_calls(( - mock.call.debug('SFTP is not connected, try to connect...'), - )) + log = ssh_logger.getChild( + '{host}:{port}'.format(host=host, port=port) + ) + log.assert_has_calls(( + mock.call.debug('SFTP is not connected, try to connect...'), + )) @mock.patch('exec_helpers.exec_result.ExecResult', autospec=True) def test_023_init_memorize( diff --git a/test/test_sshauth.py b/test/test_sshauth.py index 0c4ce5f..60c1cfe 100644 --- a/test/test_sshauth.py +++ b/test/test_sshauth.py @@ -36,10 +36,7 @@ def gen_private_keys(amount=1): - keys = [] - for _ in range(amount): - keys.append(paramiko.RSAKey.generate(1024)) - return keys + return [paramiko.RSAKey.generate(1024) for _ in range(amount)] def gen_public_key(private_key=None): diff --git a/test/test_subprocess_runner.py b/test/test_subprocess_runner.py index ef3449a..04555c7 100644 --- a/test/test_subprocess_runner.py +++ b/test/test_subprocess_runner.py @@ -32,7 +32,7 @@ from exec_helpers import subprocess_runner 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'] stderr_list = [b' \n', b'0\n', b'1\n', b' \n'] print_stdin = 'read line; echo "$line"' @@ -105,8 +105,7 @@ def prepare_close( @staticmethod def gen_cmd_result_log_message(result): - return ("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_call( self, @@ -369,7 +368,7 @@ def test_008_execute_mask_global(self, popen, _, select, 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) popen_obj, exp_result = self.prepare_close( popen, @@ -424,7 +423,7 @@ def test_009_execute_mask_local(self, popen, _, select, 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) popen_obj, exp_result = self.prepare_close( popen,