logging reform: Transport,SFTP* _log() refactor

Transport._log() does not take msg list, it takes format string

SFTPClient/SFTPServer _log() method does not take msg list
SFTPBase gets new _loglist() method for the rare list case

Transport and SFTP* use proper logging format strings
and separate arguments

SSHClient and AuthHandler always log with single msg string,
so pass to Transport._log() as "%s", msg

get rid of util.tb_strings(), instead _log() with exc_info=True
so that lines of traceback are not separate log messages
(inspired by paramiko#406)

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

paramiko/client.py

@@ -684,7 +684,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):

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:]

paramiko/sftp_client.py

@@ -103,10 +103,7 @@ def __init__(self, sock):
             server_version = self._send_version()
         except EOFError:
             raise SSHException('EOF during negotiation')
-        self._log(
-            INFO,
-            'Opened sftp connection (server version {})'.format(server_version)
-        )
+        self._log(INFO, "Opened sftp connection (server version %s)", server_version)
 
     @classmethod
     def from_transport(cls, t, window_size=None, max_packet_size=None):
@@ -139,19 +136,9 @@ def from_transport(cls, t, window_size=None, max_packet_size=None):
         chan.invoke_subsystem('sftp')
         return cls(chan)
 
-    def _log(self, level, msg, *args):
-        if isinstance(msg, list):
-            for m in msg:
-                self._log(level, m, *args)
-        else:
-            # NOTE: these bits MUST continue using %-style format junk because
-            # logging.Logger.log() explicitly requires it. Grump.
-            # escape '%' in msg (they could come from file or directory names)
-            # before logging
-            msg = msg.replace('%', '%%')
-            super(SFTPClient, self)._log(
-                level,
-                "[chan %s] " + msg, *([self.sock.get_name()] + list(args)))
+    def _log(self, level, msg, *args, **kwargs):
+        super(SFTPClient, self)._log(level, "[chan %s] " + msg,
+                                     self.sock.get_name(), *args, **kwargs)
 
     def close(self):
         """
@@ -203,7 +190,7 @@ def listdir_attr(self, path='.'):
         .. versionadded:: 1.2
         """
         path = self._adjust_cwd(path)
-        self._log(DEBUG, 'listdir({!r})'.format(path))
+        self._log(DEBUG, "listdir(%r)", path)
         t, msg = self._request(CMD_OPENDIR, path)
         if t != CMD_HANDLE:
             raise SFTPError('Expected handle')
@@ -242,7 +229,7 @@ def listdir_iter(self, path='.', read_aheads=10):
         .. versionadded:: 1.15
         """
         path = self._adjust_cwd(path)
-        self._log(DEBUG, 'listdir({!r})'.format(path))
+        self._log(DEBUG, "listdir(%r)", path)
         t, msg = self._request(CMD_OPENDIR, path)
 
         if t != CMD_HANDLE:
@@ -314,7 +301,7 @@ def open(self, filename, mode='r', bufsize=-1):
         :raises: ``IOError`` -- if the file could not be opened.
         """
         filename = self._adjust_cwd(filename)
-        self._log(DEBUG, 'open({!r}, {!r})'.format(filename, mode))
+        self._log(DEBUG, "open(%r, %r)", filename, mode)
         imode = 0
         if ('r' in mode) or ('+' in mode):
             imode |= SFTP_FLAG_READ
@@ -331,10 +318,7 @@ def open(self, filename, mode='r', bufsize=-1):
         if t != CMD_HANDLE:
             raise SFTPError('Expected handle')
         handle = msg.get_binary()
-        self._log(
-            DEBUG,
-            'open({!r}, {!r}) -> {}'.format(filename, mode, u(hexlify(handle)))
-        )
+        self._log(DEBUG, "open(%r, %r) -> %s", filename, mode, u(hexlify(handle)))
         return SFTPFile(self, handle, mode, bufsize)
 
     # Python continues to vacillate about "open" vs "file"...
@@ -350,7 +334,7 @@ def remove(self, path):
         :raises: ``IOError`` -- if the path refers to a folder (directory)
         """
         path = self._adjust_cwd(path)
-        self._log(DEBUG, 'remove({!r})'.format(path))
+        self._log(DEBUG, "remove(%r)", path)
         self._request(CMD_REMOVE, path)
 
     unlink = remove
@@ -375,7 +359,7 @@ def rename(self, oldpath, newpath):
         """
         oldpath = self._adjust_cwd(oldpath)
         newpath = self._adjust_cwd(newpath)
-        self._log(DEBUG, 'rename({!r}, {!r})'.format(oldpath, newpath))
+        self._log(DEBUG, "rename(%r, %r)", oldpath, newpath)
         self._request(CMD_RENAME, oldpath, newpath)
 
     def posix_rename(self, oldpath, newpath):
@@ -395,7 +379,7 @@ def posix_rename(self, oldpath, newpath):
         """
         oldpath = self._adjust_cwd(oldpath)
         newpath = self._adjust_cwd(newpath)
-        self._log(DEBUG, 'posix_rename({!r}, {!r})'.format(oldpath, newpath))
+        self._log(DEBUG, "posix_rename(%r, %r)", oldpath, newpath)
         self._request(
             CMD_EXTENDED, "posix-rename@openssh.com", oldpath, newpath
         )
@@ -410,7 +394,7 @@ def mkdir(self, path, mode=o777):
         :param int mode: permissions (posix-style) for the newly-created folder
         """
         path = self._adjust_cwd(path)
-        self._log(DEBUG, 'mkdir({!r}, {!r})'.format(path, mode))
+        self._log(DEBUG, "mkdir(%r, %r)", path, mode)
         attr = SFTPAttributes()
         attr.st_mode = mode
         self._request(CMD_MKDIR, path, attr)
@@ -422,7 +406,7 @@ def rmdir(self, path):
         :param str path: name of the folder to remove
         """
         path = self._adjust_cwd(path)
-        self._log(DEBUG, 'rmdir({!r})'.format(path))
+        self._log(DEBUG, "rmdir(%r)", path)
         self._request(CMD_RMDIR, path)
 
     def stat(self, path):
@@ -445,7 +429,7 @@ def stat(self, path):
             file
         """
         path = self._adjust_cwd(path)
-        self._log(DEBUG, 'stat({!r})'.format(path))
+        self._log(DEBUG, "stat(%r)", path)
         t, msg = self._request(CMD_STAT, path)
         if t != CMD_ATTRS:
             raise SFTPError('Expected attributes')
@@ -463,7 +447,7 @@ def lstat(self, path):
             file
         """
         path = self._adjust_cwd(path)
-        self._log(DEBUG, 'lstat({!r})'.format(path))
+        self._log(DEBUG, "lstat(%r)", path)
         t, msg = self._request(CMD_LSTAT, path)
         if t != CMD_ATTRS:
             raise SFTPError('Expected attributes')
@@ -477,7 +461,7 @@ def symlink(self, source, dest):
         :param str dest: path of the newly created symlink
         """
         dest = self._adjust_cwd(dest)
-        self._log(DEBUG, 'symlink({!r}, {!r})'.format(source, dest))
+        self._log(DEBUG, "symlink(%r, %r)", source, dest)
         source = b(source)
         self._request(CMD_SYMLINK, source, dest)
 
@@ -491,7 +475,7 @@ def chmod(self, path, mode):
         :param int mode: new permissions
         """
         path = self._adjust_cwd(path)
-        self._log(DEBUG, 'chmod({!r}, {!r})'.format(path, mode))
+        self._log(DEBUG, "chmod(%r, %r)", path, mode)
         attr = SFTPAttributes()
         attr.st_mode = mode
         self._request(CMD_SETSTAT, path, attr)
@@ -508,7 +492,7 @@ def chown(self, path, uid, gid):
         :param int gid: new group id
         """
         path = self._adjust_cwd(path)
-        self._log(DEBUG, 'chown({!r}, {!r}, {!r})'.format(path, uid, gid))
+        self._log(DEBUG, "chown(%r, %r, %r)", path, uid, gid)
         attr = SFTPAttributes()
         attr.st_uid, attr.st_gid = uid, gid
         self._request(CMD_SETSTAT, path, attr)
@@ -530,7 +514,7 @@ def utime(self, path, times):
         path = self._adjust_cwd(path)
         if times is None:
             times = (time.time(), time.time())
-        self._log(DEBUG, 'utime({!r}, {!r})'.format(path, times))
+        self._log(DEBUG, "utime(%r, %r)", path, times)
         attr = SFTPAttributes()
         attr.st_atime, attr.st_mtime = times
         self._request(CMD_SETSTAT, path, attr)
@@ -545,7 +529,7 @@ def truncate(self, path, size):
         :param int size: the new size of the file
         """
         path = self._adjust_cwd(path)
-        self._log(DEBUG, 'truncate({!r}, {!r})'.format(path, size))
+        self._log(DEBUG, "truncate(%r, %r)", path, size)
         attr = SFTPAttributes()
         attr.st_size = size
         self._request(CMD_SETSTAT, path, attr)
@@ -560,7 +544,7 @@ def readlink(self, path):
         :return: target path, as a `str`
         """
         path = self._adjust_cwd(path)
-        self._log(DEBUG, 'readlink({!r})'.format(path))
+        self._log(DEBUG, "readlink(%r)", path)
         t, msg = self._request(CMD_READLINK, path)
         if t != CMD_NAME:
             raise SFTPError('Expected name response')
@@ -584,7 +568,7 @@ def normalize(self, path):
         :raises: ``IOError`` -- if the path can't be resolved on the server
         """
         path = self._adjust_cwd(path)
-        self._log(DEBUG, 'normalize({!r})'.format(path))
+        self._log(DEBUG, "normalize(%r)", path)
         t, msg = self._request(CMD_REALPATH, path)
         if t != CMD_NAME:
             raise SFTPError('Expected name response')
@@ -814,7 +798,7 @@ def _read_response(self, waitfor=None):
                 if num not in self._expecting:
                     # might be response for a file that was closed before
                     # responses came back
-                    self._log(DEBUG, 'Unexpected response #{}'.format(num))
+                    self._log(DEBUG, "Unexpected response #%s", num)
                     if waitfor is None:
                         # just doing a single check
                         break

paramiko/sftp_server.py

@@ -87,20 +87,13 @@ def __init__(self, channel, name, server, sftp_si=SFTPServerInterface,
         self.folder_table = {}
         self.server = sftp_si(server, *largs, **kwargs)
 
-    def _log(self, level, msg):
-        if isinstance(msg, list):
-            for m in msg:
-                super(SFTPServer, self)._log(
-                    level,
-                    "[chan " + self.sock.get_name() + "] " + m)
-        else:
-            super(SFTPServer, self)._log(
-                level,
-                "[chan " + self.sock.get_name() + "] " + msg)
+    def _log(self, level, msg, *args, **kwargs):
+        super(SFTPServer, self)._log(level, "[chan %s] " + msg,
+                                     self.sock.get_name(), *args, **kwargs)
 
     def start_subsystem(self, name, transport, channel):
         self.sock = channel
-        self._log(DEBUG, 'Started sftp server on channel {!r}'.format(channel))
+        self._log(DEBUG, "Started sftp server on channel %r", channel)
         self._send_server_version()
         self.server.session_started()
         while True:
@@ -110,16 +103,14 @@ def start_subsystem(self, name, transport, channel):
                 self._log(DEBUG, 'EOF -- end of session')
                 return
             except Exception as e:
-                self._log(DEBUG, 'Exception on channel: ' + str(e))
-                self._log(DEBUG, util.tb_strings())
+                self._log(DEBUG, "Exception on channel: %s", e, exc_info=True)
                 return
             msg = Message(data)
             request_number = msg.get_int()
             try:
                 self._process(t, request_number, msg)
             except Exception as e:
-                self._log(DEBUG, 'Exception in server processing: ' + str(e))
-                self._log(DEBUG, util.tb_strings())
+                self._log(DEBUG, "Exception in server processing: %s", e, exc_info=True)
                 # send some kind of failure message, at least
                 try:
                     self._send_status(request_number, SFTP_FAILURE)
@@ -334,7 +325,7 @@ def _convert_pflags(self, pflags):
         return flags
 
     def _process(self, t, request_number, msg):
-        self._log(DEBUG, 'Request: {}'.format(CMD_NAMES[t]))
+        self._log(DEBUG, "Request: %s", CMD_NAMES[t])
         if t == CMD_OPEN:
             path = msg.get_text()
             flags = self._convert_pflags(msg.get_int())