Merge pull request #74 from ploxiln/logging_reform

logging reform: Transport,SFTP* _log() refactor

demos/demo.py

@@ -46,7 +46,7 @@ def agent_auth(transport, username):
         return
 
     for key in agent_keys:
-        print('Trying ssh-agent key %s' % hexlify(key.get_fingerprint()))
+        print('Trying ssh-agent key %s' % hexlify(key.get_fingerprint()).decode())
         try:
             transport.auth_publickey(username, key)
             print('... success!')

paramiko/auth_handler.py

@@ -70,8 +70,8 @@ def __init__(self, transport):
         self.gss_host = None
         self.gss_deleg_creds = True
 
-    def _log(self, *args):
-        return self.transport._log(*args)
+    def _log(self, level, msg):
+        return self.transport._log(level, "%s", msg)
 
     def is_authenticated(self):
         return self.authenticated
@@ -611,7 +611,7 @@ def _parse_userauth_failure(self, m):
     def _parse_userauth_banner(self, m):
         banner = m.get_string()
         self.transport.banner = banner
-        self._log(INFO, 'Auth banner: {}'.format(banner))
+        self._log(INFO, "Auth banner: {!r}".format(banner))
         # who cares.
 
     def _parse_userauth_info_request(self, m):

paramiko/client.py

@@ -511,7 +511,7 @@ def _key_from_filepath(self, filename, klass=None, password=None):
         # when #387 is released, since this is a critical log message users are
         # likely testing/filtering for (bah.)
         msg = "Trying discovered key {} in {}".format(
-            hexlify(key.get_fingerprint()), key_path,
+            hexlify(key.get_fingerprint()).decode(), key_path,
         )
         self._log(DEBUG, msg)
         # Attempt to load cert if it exists.
@@ -581,10 +581,7 @@ def _auth(
 
         if pkey is not None and 'publickey' in allowed_types:
             try:
-                self._log(
-                    DEBUG,
-                    'Trying SSH key {}'.format(hexlify(pkey.get_fingerprint()))
-                )
+                self._log(DEBUG, "Trying SSH key %s" % hexlify(pkey.get_fingerprint()).decode())
                 allowed_types = set(
                     self._transport.auth_publickey(username, pkey))
                 two_factor = (allowed_types & two_factor_types)
@@ -612,8 +609,8 @@ def _auth(
 
             for key in self._agent.get_keys():
                 try:
-                    id_ = hexlify(key.get_fingerprint())
-                    self._log(DEBUG, 'Trying SSH agent key {}'.format(id_))
+                    self._log(DEBUG, "Trying SSH agent key %s"
+                              % hexlify(key.get_fingerprint()).decode())
                     allowed_types = set(
                         self._transport.auth_publickey(username, key))
                     two_factor = (allowed_types & two_factor_types)
@@ -684,7 +681,7 @@ def _auth(
         raise SSHException('No authentication methods available')
 
     def _log(self, level, msg):
-        self._transport._log(level, msg)
+        self._transport._log(level, "%s", msg)
 
 
 class MissingHostKeyPolicy (object):
@@ -719,7 +716,7 @@ def missing_host_key(self, client, hostname, key):
         if client._host_keys_filename is not None:
             client.save_host_keys(client._host_keys_filename)
         client._log(DEBUG, 'Adding {} host key for {}: {}'.format(
-            key.get_name(), hostname, hexlify(key.get_fingerprint()),
+            key.get_name(), hostname, hexlify(key.get_fingerprint()).decode(),
         ))
 
 
@@ -731,7 +728,7 @@ class RejectPolicy (MissingHostKeyPolicy):
 
     def missing_host_key(self, client, hostname, key):
         client._log(DEBUG, 'Rejecting {} host key for {}: {}'.format(
-            key.get_name(), hostname, hexlify(key.get_fingerprint()),
+            key.get_name(), hostname, hexlify(key.get_fingerprint()).decode(),
         ))
         raise SSHException(
             'Server {!r} not found in known_hosts'.format(hostname)
@@ -745,5 +742,5 @@ class WarningPolicy (MissingHostKeyPolicy):
     """
     def missing_host_key(self, client, hostname, key):
         warnings.warn('Unknown {} host key for {}: {}'.format(
-            key.get_name(), hostname, hexlify(key.get_fingerprint()),
+            key.get_name(), hostname, hexlify(key.get_fingerprint()).decode(),
         ))

paramiko/kex_gex.py

@@ -137,14 +137,10 @@ def _parse_kexdh_gex_request(self, m):
         # generate prime
         pack = self.transport._get_modulus_pack()
         if pack is None:
-            raise SSHException(
-                'Can\'t do server-side gex with no modulus pack')
-        self.transport._log(
-            DEBUG,
-            'Picking p ({} <= {} <= {} bits)'.format(
-                minbits, preferredbits, maxbits,
-            )
-        )
+            raise SSHException("Can't do server-side gex with no modulus pack")
+
+        self.transport._log(DEBUG, "Picking p (%s <= %s <= %s bits)",
+                            minbits, preferredbits, maxbits)
         self.g, self.p = pack.get_modulus(minbits, preferredbits, maxbits)
         m = Message()
         m.add_byte(c_MSG_KEXDH_GEX_GROUP)

paramiko/kex_gss.py

@@ -414,14 +414,10 @@ def _parse_kexgss_groupreq(self, m):
         # generate prime
         pack = self.transport._get_modulus_pack()
         if pack is None:
-            raise SSHException(
-                'Can\'t do server-side gex with no modulus pack')
-        self.transport._log(
-            DEBUG,  # noqa
-            'Picking p ({} <= {} <= {} bits)'.format(
-                minbits, preferredbits, maxbits,
-            )
-        )
+            raise SSHException("Can't do server-side gex with no modulus pack")
+
+        self.transport._log(DEBUG, "Picking p (%s <= %s <= %s bits)",
+                            minbits, preferredbits, maxbits)
         self.g, self.p = pack.get_modulus(minbits, preferredbits, maxbits)
         m = Message()
         m.add_byte(c_MSG_KEXGSS_GROUP)
@@ -444,7 +440,7 @@ def _parse_kexgss_group(self, m):
             raise SSHException(
                 'Server-generated gex p (don\'t ask) is out of range '
                 '({} bits)'.format(bitlen))
-        self.transport._log(DEBUG, 'Got server p ({} bits)'.format(bitlen))  # noqa
+        self.transport._log(DEBUG, "Got server p (%s bits)", bitlen)
         self._generate_x()
         # now compute e = g^x mod p
         self.e = pow(self.g, self.x, self.p)

paramiko/server.py

@@ -21,7 +21,6 @@
 """
 
 import threading
-from paramiko import util
 from paramiko.common import (
     DEBUG, ERROR, OPEN_FAILED_ADMINISTRATIVELY_PROHIBITED, AUTH_FAILED,
     AUTH_SUCCESSFUL,
@@ -667,18 +666,11 @@ def get_server(self):
 
     def _run(self):
         try:
-            self.__transport._log(
-                DEBUG, 'Starting handler for subsystem {}'.format(self.__name)
-            )
+            self.__transport._log(DEBUG, "Starting handler for subsystem %s", self.__name)
             self.start_subsystem(self.__name, self.__transport, self.__channel)
         except Exception as e:
-            self.__transport._log(
-                ERROR,
-                'Exception in subsystem handler for "{}": {}'.format(
-                    self.__name, e
-                )
-            )
-            self.__transport._log(ERROR, util.tb_strings())
+            self.__transport._log(ERROR, 'Exception in subsystem handler for "%s": %s',
+                                  self.__name, e, exc_info=True)
         try:
             self.finish_subsystem()
         except:

paramiko/sftp.py

@@ -127,8 +127,12 @@ def _send_server_version(self):
         self._send_packet(CMD_VERSION, msg)
         return version
 
-    def _log(self, level, msg, *args):
-        self.logger.log(level, msg, *args)
+    def _log(self, level, msg, *args, **kwargs):
+        self.logger.log(level, msg, *args, **kwargs)
+
+    def _loglist(self, level, msgs):
+        for m in msgs:
+            self._log(level, "%s", m)
 
     def _write_all(self, out):
         while len(out) > 0:
@@ -167,7 +171,7 @@ def _send_packet(self, t, packet):
         packet = asbytes(packet)
         out = struct.pack('>I', len(packet) + 1) + byte_chr(t) + packet
         if self.ultra_debug:
-            self._log(DEBUG, util.format_binary(out, 'OUT: '))
+            self._loglist(DEBUG, util.format_binary(out, 'OUT: '))
         self._write_all(out)
 
     def _read_packet(self):
@@ -179,7 +183,7 @@ def _read_packet(self):
         size = struct.unpack('>I', x)[0]
         data = self._read_all(size)
         if self.ultra_debug:
-            self._log(DEBUG, util.format_binary(data, 'IN: '))
+            self._loglist(DEBUG, util.format_binary(data, 'IN: '))
         if size > 0:
             t = byte_ord(data[0])
             return t, data[1:]