Merge lp:~javier.collado/utah/bug1095669-2 into lp:utah

[Javier Collado]

This branch adds a wrapper method to log all the sql commands executed during
the provisioning step.

In addition to this, since the inventory is created before the machine object,
there a lot of changes regarding logging:
- root logger object is configured in all run_* scripts
- machine logger propagates messages and doesn't contain any handler by itself
- logging messages outside the machine object now use the root logger
- the log format has been updated to include the python module name
- paramiko logs are only written to debug log file regardless of their level

The big change is that since root logger object is configured using pretty much
the same code that was used for the machine logger, now it's possible to use
logging in any place, not only in the machine object. This should be useful to
add logging messages that previously were not even printed because of the lack
of handlers for the root logger.

[lp:~javier.collado/utah/bug1095669-2]

810. By Javier Collado on 2013-01-23

Added separate file to log ssh related messages

The new file writes the whole set of ssh logs including the ones from paramiko
to a different file. Note that while paramiko logger doesn't propagate, the ssh
one does, so the ssh related messages that were written to log files before
this change will still be written.

811. By Javier Collado on 2013-01-23

Removed module name from logs

812. By Javier Collado on 2013-01-23

Fixed activecheck shouldn't use ssh logger

813. By Javier Collado on 2013-01-23

Set console log level back to WARNING

814. By Javier Collado on 2013-01-23

Set console log level to debug if -d/--debug option is passed

[Javier Collado (javier.collado)]

I've added a few changes to the logging part that don't really change anything
with regard to sql.

The biggest change is that ssh log is now written to a different file in case
detailed information is needed to troubleshoot a problem. In particular, the
logs from the paramiko library are also included in that file.

Aside from this, I think that the -d/--debug flag in the command line is kind
of confusing. In this branch, the console and log file handlers use the levels
set from the configuration file (the handler for the debug file is always set
to debug). The -d/--debug flag is used just to set to debug the logging in the
console, but not on the the file log. I'm not sure if this is the intended
behavior, but I don't think setting the file log to debug is a great benefit if
there's already a debug file. Maybe the -d/--debug flag should be removed since
it's not very likely that we use it to troubleshoot something looking just at
the console instead of checking the debug file. Please let me know what do you
think.

[Max Brustkern (nuclearbob)]

When -d was originally implemented, we didn't have a separate debug log file. I think enabling or disabling debug affects some code paths for cleanup routines as well. I think removing that option in favor of newer ones would be good. We can have explicit options for cleaning things up or not, and leave the log level stuff to the configuration files. I think that would be worth doing as a separate merge, since it'll affect some cleanup routines and need more testing.

[Max Brustkern (nuclearbob)]

Lines 214, 219, and 247 of the merge look like leftover bzr merge lines. Those are all in utah/provisioning/inventory/sqlite.py I wonder if lines 215-218 are still needed as well, as they would seem to be superseded by the lines after that.

Other than that, it looks like it should improve things a lot. If we do decide to start using rotating file handlers instead of external log rotation, this will make that a lot easier as well.

review: Approve

[Max Brustkern (nuclearbob)]

I'm not sure if I should have marked approve or not. I feel like the actual changes are good, and I'm confident you'll fix the typos, but I guess technically I wouldn't merge it in the current state. I think anyone who would merge it will be reading enough to know to fix those things and retest.

[Javier Collado (javier.collado)]

I think it's ok to mark the merge request as approved for now because we don't
have any auto-merging mechanism in place.

However, once tarmac is finally setup, an attempt to merge the code will be
made in such a situation, so we should avoid approving until the changes are
completely fine. Anyway, in this particular case, the merge would fail because
of the conflicts that you saw in the diff.

[Javier Collado (javier.collado)]

The merge conflict is because both lp:bug1095669 and lp:bug1095669-2 were
branched from the same dev branch revision and the latter is already merged.
Anyway, that's not a problem I'll fix the conflict in the merge itself.

=== modified file 'examples/run_install_test.py'
--- examples/run_install_test.py	2012-12-19 15:41:25 +0000
+++ examples/run_install_test.py	2013-01-23 12:29:24 +0000
@@ -27,6 +27,7 @@
     file_arguments,
     run_tests,
     virtual_arguments,
+    configure_logging,
 )
 
 
@@ -60,6 +61,8 @@
     exitstatus = 0
     machine = None
 
+    configure_logging(args.debug)
+
     try:
         inventory = TinySQLiteInventory()
         machine = inventory.request(
 
=== modified file 'examples/run_test_bamboo_feeder.py'
--- examples/run_test_bamboo_feeder.py	2012-12-19 15:41:25 +0000
+++ examples/run_test_bamboo_feeder.py	2013-01-23 12:29:24 +0000
@@ -18,6 +18,7 @@
 import argparse
 import os
 import sys
+import logging
 
 from utah.exceptions import UTAHException
 from utah.group import check_user_group, print_group_error_message
@@ -29,6 +30,7 @@
     custom_arguments,
     name_argument,
     run_tests,
+    configure_logging,
 )
 
 
@@ -61,6 +63,8 @@
     exitstatus = 0
     machine = None
 
+    configure_logging(args.debug)
+
     try:
         inventory = ManualBaremetalSQLiteInventory(
             db=os.path.join('~', '.utah-bamboofeeder-inventory'),
@@ -79,7 +83,7 @@
     except UTAHException as error:
         mesg = 'Exception: ' + str(error)
         try:
-            machine.logger.error(mesg)
+            logging.error(mesg)
         except (AttributeError, NameError):
             sys.stderr.write(mesg)
         exitstatus = 2
 
=== modified file 'examples/run_test_cobbler.py'
--- examples/run_test_cobbler.py	2012-12-19 15:41:25 +0000
+++ examples/run_test_cobbler.py	2013-01-23 12:29:24 +0000
@@ -17,6 +17,7 @@
 
 import argparse
 import sys
+import logging
 
 from utah.exceptions import UTAHException
 from utah.group import check_user_group, print_group_error_message
@@ -28,6 +29,7 @@
     custom_arguments,
     name_argument,
     run_tests,
+    configure_logging,
 )
 
 
@@ -60,6 +62,8 @@
     exitstatus = 0
     machine = None
 
+    configure_logging(args.debug)
+
     try:
         inventory = ManualBaremetalSQLiteInventory()
         kw = {}
@@ -84,7 +88,7 @@
     except UTAHException as error:
         mesg = 'Exception: ' + str(error)
         try:
-            machine.logger.error(mesg)
+            logging.error(mesg)
         except (AttributeError, NameError):
             sys.stderr.write(mesg)
         exitstatus = 2
 
=== modified file 'examples/run_test_vm.py'
--- examples/run_test_vm.py	2012-12-19 15:41:25 +0000
+++ examples/run_test_vm.py	2013-01-23 12:29:24 +0000
@@ -21,7 +21,7 @@
 from utah.exceptions import UTAHException
 from utah.group import check_user_group, print_group_error_message
 from utah.provisioning.vm.vm import TinySQLiteInventory
-from utah.run import common_arguments, run_tests
+from utah.run import common_arguments, run_tests, configure_logging
 
 
 def get_parser():
@@ -50,6 +50,8 @@
     exitstatus = 0
     machine = None
 
+    configure_logging(args.debug)
+
     try:
         inventory = TinySQLiteInventory()
         kw = {}
 
=== modified file 'examples/run_utah_tests.py'
--- examples/run_utah_tests.py	2012-12-19 15:41:25 +0000
+++ examples/run_utah_tests.py	2013-01-23 12:29:24 +0000
@@ -26,6 +26,7 @@
     file_arguments,
     name_argument,
     virtual_arguments,
+    configure_logging
 )
 from utah.timeout import timeout, UTAHTimeout
 from run_install_test import run_install_test
@@ -70,6 +71,8 @@
     else:
         machinetype = args.machinetype
 
+    configure_logging(args.debug)
+
     # Default is now CustomVM
     function = run_install_test
 
 
=== modified file 'utah/config.py'
--- utah/config.py	2013-01-22 10:35:02 +0000
+++ utah/config.py	2013-01-23 12:29:24 +0000
@@ -171,6 +171,11 @@
     DEFAULTS['logpath'],
     LOCALDEFAULTS['hostname'] + '-debug.log')
 
+# Log file used to log SSH related information
+LOCALDEFAULTS['ssh_logfile'] = \
+    os.path.join(DEFAULTS['logpath'],
+                 '{}-ssh.log'.format(LOCALDEFAULTS['hostname']))
+
 # This depends on a binary that may not be installed.
 # Also, the null thing may seem obvious, but I found it here:
 # http://stackoverflow.com/questions/699325/
 
=== modified file 'utah/provisioning/baremetal/inventory.py'
--- utah/provisioning/baremetal/inventory.py	2012-12-13 09:07:58 +0000
+++ utah/provisioning/baremetal/inventory.py	2013-01-23 12:29:24 +0000
@@ -41,8 +41,7 @@
         super(ManualBaremetalSQLiteInventory, self).__init__(*args, db=db,
                                                              lockfile=lockfile,
                                                              **kw)
-        machines_count = (self.connection
-                          .execute('SELECT COUNT(*) FROM machines')
+        machines_count = (self.execute('SELECT COUNT(*) FROM machines')
                           .fetchall()[0][0])
         if machines_count == 0:
             raise UTAHProvisioningInventoryException('No machines in database')
@@ -54,7 +53,7 @@
         if name is not None:
             query += ' WHERE name=?'
             queryvars.append(name)
-        result = self.connection.execute(query, queryvars).fetchall()
+        result = self.execute(query, queryvars).fetchall()
         if result is None:
             raise UTAHProvisioningInventoryException(
                 'No machines meet criteria')
@@ -84,7 +83,7 @@
         name = machineinfo.pop('name')
         state = machineinfo.pop('state')
         machineinfo.pop('pid')
-        update = self.connection.execute(
+        update = self.execute(
             "UPDATE machines SET pid=?, state='provisioned' WHERE machineid=?"
             "AND state=?",
             [os.getpid(), machineid, state]).rowcount
@@ -115,7 +114,7 @@
                 'name required to release a machine')
         query = "UPDATE machines SET state='available' WHERE name=?"
         queryvars = [name]
-        update = self.connection.execute(query, queryvars).rowcount
+        update = self.execute(query, queryvars).rowcount
         if update == 1:
             if machine is not None:
                 if machine in self.machines:
 
=== modified file 'utah/provisioning/inventory/sqlite.py'
--- utah/provisioning/inventory/sqlite.py	2013-01-22 10:35:02 +0000
+++ utah/provisioning/inventory/sqlite.py	2013-01-23 12:29:24 +0000
@@ -17,6 +17,8 @@
 
 import sqlite3
 import os
+import logging
+
 from utah.provisioning.inventory.inventory import Inventory
 from utah import config
 
@@ -30,10 +32,40 @@
         db = os.path.expanduser(db)
         super(SQLiteInventory, self).__init__(*args, uniqueid=db, **kw)
         self.db = db
+<<<<<<< TREE
         self.connection = sqlite3.connect(self.db,
                                           config.sqlite3_db_connection_timeout)
         self.connection.isolation_level = None
         self.connection.row_factory = sqlite3.Row
+=======
+        self._connection = sqlite3.connect(self.db)
+        self._connection.isolation_level = None
+        self._connection.row_factory = sqlite3.Row
+
+    def execute(self, sql, parameters=None):
+        """Execute sql statement and return cursor
+
+        This method is expected to be used as a wrapper around all
+        `connection.execute` calls so that all the SQL statements are logged in
+        case this information is needed to troubleshoot problems.
+
+        :param sql: A sql statement to be executed
+        :type sql: str
+        :param parameters:
+            Parameters to use to replace the placeholder
+            values in the sql statement.
+        :type parameters:
+            list (question mark placeholders) |
+            dict (colon named placeholders)
+        """
+        if parameters is None:
+            parameters = []
+
+        logging.debug('Executing SQL statement: {}, {}'
+                      .format(sql, parameters))
+        cursor = self._connection.execute(sql, parameters)
+        return cursor
+>>>>>>> MERGE-SOURCE
 
     def delete(self):
         os.unlink(self.db)
 
=== modified file 'utah/provisioning/provisioning.py'
--- utah/provisioning/provisioning.py	2013-01-16 14:08:17 +0000
+++ utah/provisioning/provisioning.py	2013-01-23 12:29:24 +0000
@@ -265,33 +265,7 @@
         Initialize the logging for the machine.
         Subclasses can override or supplement to customize logging.
         """
-        self.logger = logging.getLogger('utah.provisioning.' + str(self.name))
-        self.logger.propagate = False
-        self.logger.setLevel(logging.INFO)
-        for handler in list(self.logger.handlers):
-            self.logger.removeHandler(handler)
-            del handler
-        self.consolehandler = logging.StreamHandler(stream=sys.stderr)
-        log_format = logging.Formatter('%(asctime)s ' + self.name
-                                       + ' %(levelname)s: %(message)s')
-        console_formatter = log_format
-        self.consolehandler.setFormatter(console_formatter)
-        self.consolehandler.setLevel(config.consoleloglevel)
-        self.logger.addHandler(self.consolehandler)
-        self.filehandler = logging.handlers.WatchedFileHandler(config.logfile)
-        file_formatter = log_format
-        self.filehandler.setFormatter(file_formatter)
-        self.filehandler.setLevel(config.fileloglevel)
-        self.logger.addHandler(self.filehandler)
-        if config.debuglog is not None:
-            self.logger.setLevel(logging.DEBUG)
-            self.debughandler = (
-                logging.handlers.WatchedFileHandler(config.debuglog))
-            self.debughandler.setFormatter(file_formatter)
-            self.debughandler.setLevel(logging.DEBUG)
-            self.logger.addHandler(self.debughandler)
-        if self.debug:
-            self.logger.setLevel(logging.DEBUG)
+        self.logger = logging.getLogger(self.name)
 
     def _loggerunsetup(self):
         """
@@ -299,8 +273,6 @@
         Principally used when a machine changes name after init.
         """
         del self.logger
-        del self.consolehandler
-        del self.filehandler
 
     def provisioncheck(self):
         """
 
=== modified file 'utah/provisioning/ssh.py'
--- utah/provisioning/ssh.py	2012-12-12 18:56:29 +0000
+++ utah/provisioning/ssh.py	2013-01-23 12:29:24 +0000
@@ -43,6 +43,7 @@
         ssh_client = paramiko.SSHClient()
         ssh_client.set_missing_host_key_policy(paramiko.AutoAddPolicy())
         self.ssh_client = ssh_client
+        self.ssh_logger = logging.getLogger('ssh')
 
     def run(self, command, _quiet=None, root=False, timeout=None):
         """
@@ -64,15 +65,15 @@
         # With additions from here:
         # http://od-eon.com/blogs/
         # stefan/automating-remote-commands-over-ssh-paramiko/
-        self.logger.debug('Connecting SSH')
+        self.ssh_logger.debug('Connecting SSH')
         self.ssh_client.connect(self.name,
                                 username=user,
                                 key_filename=config.sshprivatekey)
 
-        self.logger.debug('Opening SSH session')
+        self.ssh_logger.debug('Opening SSH session')
         channel = self.ssh_client.get_transport().open_session()
 
-        self.logger.info('Running command through SSH: ' + commandstring)
+        self.ssh_logger.info('Running command through SSH: ' + commandstring)
         stdout = channel.makefile('rb')
         stderr = channel.makefile_stderr('rb')
         if timeout is None:
@@ -81,22 +82,22 @@
             utah.timeout.timeout(timeout, channel.exec_command, commandstring)
         retval = channel.recv_exit_status()
 
-        self.logger.debug('Closing SSH connection')
+        self.ssh_logger.debug('Closing SSH connection')
         self.ssh_client.close()
 
         log_level = logging.DEBUG if retval == 0 else logging.WARNING
         log_message = 'Return code: {}'.format(retval)
-        self.logger.log(log_level, log_message)
+        self.ssh_logger.log(log_level, log_message)
 
-        self.logger.debug('Standard output follows:')
+        self.ssh_logger.debug('Standard output follows:')
         stdout_lines = stdout.readlines()
         for line in stdout_lines:
-            self.logger.debug(line.strip())
+            self.ssh_logger.debug(line.strip())
 
-        self.logger.debug('Standard error follows:')
+        self.ssh_logger.debug('Standard error follows:')
         stderr_lines = stderr.readlines()
         for line in stderr_lines:
-            self.logger.debug(line.strip())
+            self.ssh_logger.debug(line.strip())
 
         return retval, ''.join(stdout_lines), ''.join(stderr_lines)
 
@@ -116,9 +117,9 @@
         try:
             for localpath in files:
                 if os.path.isfile(localpath):
-                    self.logger.info('Uploading ' + localpath
-                                     + ' from the host to ' + target
-                                     + ' on the machine')
+                    self.ssh_logger.info('Uploading {} from the host '
+                                         'to {} on the machine'
+                                         .format(localpath, target))
                     remotepath = os.path.join(target,
                                               os.path.basename(localpath))
                     sftp_client.put(localpath, remotepath)
@@ -155,9 +156,9 @@
         try:
             for remotepath in files:
                 localpath = get_localpath(remotepath)
-                self.logger.info('Downloading ' + remotepath
-                                 + ' from the machine to ' + target
-                                 + ' on the host')
+                self.ssh_logger.info('Downloading {} from the machine '
+                                     'to {} on the host'
+                                     .format(remotepath, target))
                 sftp_client.get(remotepath, localpath)
         finally:
             sftp_client.close()
@@ -179,9 +180,9 @@
         for myfile in files:
             newtarget = os.path.join(target, os.path.basename(myfile))
             if S_ISDIR(sftp_client.stat(myfile).st_mode):
-                self.logger.debug(myfile + ' is a directory, recursing')
+                self.ssh_logger.debug(myfile + ' is a directory, recursing')
                 if not os.path.isdir(newtarget):
-                    self.logger.debug('Attempting to create ' + newtarget)
+                    self.ssh_logger.debug('Attempting to create ' + newtarget)
                     os.makedirs(newtarget)
                 myfiles = [os.path.join(myfile, x)
                            for x in sftp_client.listdir(myfile)]
@@ -194,16 +195,16 @@
         Clean up known hosts for machine.
         """
         # TODO: evaluate value of known_hosts with paramiko
-        self.logger.info('Removing machine addresses '
-                         'from ssh known_hosts file')
+        self.ssh_logger.info('Removing machine addresses '
+                             'from ssh known_hosts file')
         addresses = [self.name]
         try:
             addresses.append(socket.gethostbyname(self.name))
         except socket.gaierror as err:
             if err.errno in [-2, -5]:
-                self.logger.debug(self.name
-                                  + ' is not resolvable, '
-                                  + 'so not removing from known_hosts')
+                self.ssh_logger.debug('{} is not resolvable, '
+                                      'so not removing from known_hosts'
+                                      .format(self.name))
             else:
                 raise err
 
@@ -227,10 +228,10 @@
         Return a retryable exception if it is not.
         Intended for use with retry.
         """
-        self.logger.info('Sleeping {timeout} seconds'
-                         .format(timeout=timeout))
+        self.ssh_logger.info('Sleeping {timeout} seconds'
+                             .format(timeout=timeout))
         time.sleep(timeout)
-        self.logger.info('Checking for ssh availability')
+        self.ssh_logger.info('Checking for ssh availability')
         try:
             self.ssh_client.connect(self.name,
                                     username=config.user,
@@ -246,7 +247,7 @@
         if timeout is None:
             timeout = self.boottimeout
         if logmethod is None:
-            logmethod = self.logger.debug
+            logmethod = self.ssh_logger.debug
         utah.timeout.timeout(timeout, retry, self.sshcheck, checktimeout,
                              logmethod=logmethod)
 
 
=== modified file 'utah/provisioning/vm/vm.py'
--- utah/provisioning/vm/vm.py	2012-12-17 19:55:15 +0000
+++ utah/provisioning/vm/vm.py	2013-01-23 12:29:24 +0000
@@ -589,7 +589,7 @@
         Initialize simple database.
         """
         super(TinySQLiteInventory, self).__init__(*args, **kw)
-        self.connection.execute(
+        self.execute(
             'CREATE TABLE IF NOT EXISTS '
             'machines(machineid INTEGER PRIMARY KEY, state TEXT)')
 
@@ -599,8 +599,8 @@
         machineid along with all other arguments to that class's constructor,
         returning the resulting object.
         """
-        cursor = self.connection.cursor()
-        cursor.execute("INSERT INTO machines (state) VALUES ('provisioned')")
+        cursor = self.execute("INSERT INTO machines (state) "
+                              "VALUES ('provisioned')")
         machineid = cursor.lastrowid
         return machinetype(machineid=machineid, *args, **kw)
 
@@ -608,7 +608,7 @@
         """
         Updates the database to indicate the machine is available.
         """
-        if self.connection.execute(
+        if self.execute(
                 "UPDATE machines SET state='available' WHERE machineid=?",
                 [machineid]):
             return True
@@ -620,7 +620,7 @@
         Updates the database to indicate the machine is destroyed, but does not
         destroy the machine.
         """
-        if self.connection.execute(
+        if self.execute(
                 "UPDATE machines SET state='destroyed' ""WHERE machineid=?",
                 [machineid]):
             return True
 
=== modified file 'utah/run.py'
--- utah/run.py	2013-01-16 11:05:00 +0000
+++ utah/run.py	2013-01-23 12:29:24 +0000
@@ -134,7 +134,7 @@
             utah_command = 'utah {} {}'.format(extraopts, options)
             exitstatus, _stdout, _stderr = machine.run(utah_command, root=True)
         except UTAHException as error:
-            machine.logger.error('Failed to run test: ' + str(error))
+            logging.error('Failed to run test: ' + str(error))
             exitstatus = 1
         else:
             _write(runlist, report_remote_path)
@@ -164,17 +164,12 @@
         report_local_path = os.path.join(config.logpath, log_filename)
         report_local_path = os.path.normpath(report_local_path)
         machine.downloadfiles(report_remote_path, report_local_path)
-        machine.logger.info('Test log copied to ' + report_local_path)
+        logging.info('Test log copied to ' + report_local_path)
         locallogs.append(report_local_path)
         if args.dumplogs:
             with open(report_local_path, 'r') as f:
                 print(f.read())
 
-    # Since we're running from a script, output INFO
-    for logger in [machine.logger] + machine.logger.handlers:
-        if logger.level > logging.INFO:
-            logger.setLevel(logging.INFO)
-
     # Write the machine name to standard out for log gathering
     print('Running on machine: ' + machine.name)
 
@@ -196,14 +191,13 @@
             try:
                 locallogs += getfiles(args, machine)
             except Exception as err:
-                machine.logger.warning('Failed to download files: ' + str(err))
+                logging.warning('Failed to download files: ' + str(err))
 
     if args.outputpreseed or config.outputpreseed:
         if args.outputpreseed:
-            machine.logger.debug('Capturing preseed due to '
-                                 'command line option')
+            logging.debug('Capturing preseed due to command line option')
         elif config.outputpreseed:
-            machine.logger.debug('Capturing preseed due to config option')
+            logging.debug('Capturing preseed due to config option')
         preseedfile = os.path.join(config.logpath,
                                    machine.name + '-preseed.cfg')
         shutil.copyfile(machine.finalpreseed, preseedfile)
@@ -230,3 +224,66 @@
             localfiles.append(myfile)
 
     return localfiles
+
+
+def configure_logging(debug=False):
+    """Configure logging.
+
+    Configure root logger using three different handlers with a different log
+    level:
+    - Console: Set according to `consoleloglevel` from configuration
+    - Log file: Set according to `fileloglevel` from configuration
+    - Debug log file: Always set to debug
+
+    Other loggers are expected to propagate their messages up to the logging
+    hierarchy.
+
+    """
+    logger = logging.getLogger()
+    # configure_logging is being called in different scripts that might call
+    # other scripts. This check avoids adding multiple handlers when logging as
+    # already been configured.
+    if logger.handlers:
+        logger.debug('Logging already configured. '
+                     'Skipping logging configuration.')
+        return
+
+    logger.setLevel(logging.NOTSET)
+
+    formatter = logging.Formatter('%(asctime)s %(name)s '
+                                  '%(levelname)s: %(message)s')
+
+    # Console logging
+    console_handler = logging.StreamHandler()
+    console_handler.setFormatter(formatter)
+    log_level = logging.DEBUG if debug else config.consoleloglevel
+    console_handler.setLevel(log_level)
+    logger.addHandler(console_handler)
+
+    # File logging
+    file_handler = logging.handlers.WatchedFileHandler(config.logfile)
+    file_handler.setFormatter(formatter)
+    file_handler.setLevel(config.fileloglevel)
+    logger.addHandler(file_handler)
+
+    # Debug file logging
+    if config.debuglog is not None:
+        debug_file_handler = \
+            logging.handlers.WatchedFileHandler(config.debuglog)
+        debug_file_handler.setFormatter(formatter)
+        debug_file_handler.setLevel(logging.DEBUG)
+        logger.addHandler(debug_file_handler)
+
+    # Configure ssh logging in a separate file
+    ssh_file_handler = logging.handlers.WatchedFileHandler(config.ssh_logfile)
+    ssh_file_handler.setFormatter(formatter)
+    ssh_file_handler.setLevel(logging.DEBUG)
+
+    # ssh logs available in both ssh log file and other files
+    logger = logging.getLogger('ssh')
+    logger.addHandler(ssh_file_handler)
+
+    # paramiko logs only available in ssh log file
+    logger = logging.getLogger('paramiko')
+    logger.propagate = False
+    logger.addHandler(ssh_file_handler)