Logging: added set and reset logging level method, small logging modifications.

4 files changed, 118 insertions, 22 deletions

diff --git a/rumba/log.py b/rumba/log.py
index e856b42..0e3f0dc 100644
--- a/rumba/log.py
+++ b/rumba/log.py
@@ -1,3 +1,22 @@
+#
+# Logging wrapper for Rumba
+#
+#    Marco Capitani <m.capitani@nextworks.it>
+#
+# This library is free software; you can redistribute it and/or
+# modify it under the terms of the GNU Lesser General Public
+# License as published by the Free Software Foundation; either
+# version 2.1 of the License, or (at your option) any later version.
+#
+# This library is distributed in the hope that it will be useful,
+# but WITHOUT ANY WARRANTY; without even the implied warranty of
+# MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the GNU
+# Lesser General Public License for more details.
+#
+# You should have received a copy of the GNU Lesser General Public
+# License along with this library; if not, write to the Free Software
+# Foundation, Inc., 51 Franklin Street, Fifth Floor, Boston,
+# MA  02110-1301  USA
 import logging
 
 import sys
@@ -5,21 +24,43 @@ import sys
 import multiprocessing
 
 
+loggers_set = set()
+
+
+class RumbaFormatter(logging.Formatter):
+    """The logging.Formatter subclass used by RUMBA"""
+
+    level_name_table = {
+        'CRITICAL': 'CRT',
+        'ERROR': 'ERR',
+        'WARNING': 'WRN',
+        'INFO': 'INF',
+        'DEBUG': 'DBG'
+    }
+
+    def __init__(self):
+        super(RumbaFormatter, self).__init__(
+            fmt='{asctime} | {levelname:3.3} | '
+                '{name:11.11} | {message}',
+            style='{',
+            datefmt='%H:%M:%S')
+
+    def format(self, record):
+        record.name = record.name.split('.')[-1]
+        record.levelname = self.level_name_table[record.levelname]
+        return super(RumbaFormatter, self).format(record)
+
+
 def setup():
+    """Configures the logging framework with default values."""
     handler = logging.StreamHandler(sys.stdout)
     handler.lock = multiprocessing.RLock()
-    logging.basicConfig(format='{asctime} | {levelname:3.3} | '
-                               '{name:11.11} | {message}',
-                        style='{',
-                        datefmt='%H:%M:%S',
-                        handlers=[handler],
-                        level=logging.DEBUG)
-    logging.addLevelName(logging.CRITICAL, 'CRT')
-    logging.addLevelName(logging.ERROR, 'ERR')
-    logging.addLevelName(logging.WARNING, 'WRN')
-    logging.addLevelName(logging.INFO, 'INF')
-    logging.addLevelName(logging.DEBUG, 'DBG')
+    handler.setLevel(logging.DEBUG)
+    formatter = RumbaFormatter()
+    handler.setFormatter(formatter)
+    logging.basicConfig(handlers=[handler], level=logging.DEBUG)
     logging.getLogger('').setLevel(logging.ERROR)
+    logging.getLogger('rumba').setLevel(logging.DEBUG)
 
 
 # Used for the first call, in order to configure logging
@@ -40,6 +81,52 @@ _get_logger = _get_logger_with_setup
 
 
 def get_logger(name):
-    logger = _get_logger(name.split('.')[-1])
-    logger.setLevel(logging.DEBUG)
-    return logger
+    """
+    Returns the logger named <name>.
+    <name> should be the module name, for consistency. If setup has not been
+    called yet, it will call it first.
+    :param name: the name of the desired logger
+    :return: The logger
+    """
+    return _get_logger(name)
+
+
+def set_logging_level(level, name=None):
+    """
+    Set the current logging level to <level> for logger named <name>.
+    If name is not specified, sets the logging level for all rumba loggers.
+    Accepted levels are: 
+        DEBUG == 10, 
+        INFO == 20, 
+        WARNING == 30, 
+        ERROR == 40, 
+        CRITICAL == 50,
+        NOTSET == 0
+    (resets the logger: its level is set to the default or its parents' level)
+    :param level: the desired logging level.
+    :param name: The name of the logger to configure
+    """
+    if name is None:
+        if level == 'NOTSET' or level == 0:
+            set_logging_level(logging.INFO)
+            return
+        name = 'rumba'
+    if (level == 'NOTSET' or level == 0) and name == '':
+        set_logging_level(logging.ERROR, '')
+        return
+    logger = get_logger(name)
+    loggers_set.add(logger)
+    logger.setLevel(level)
+
+
+def reset_logging_level():
+    """
+    Resets the current logging levels to the defaults.
+    Defaults are: rumba           -> INFO,
+                  everything else -> ERROR
+    """
+    # Un-sets every logger previously set
+    for logger in loggers_set:
+        logger.setLevel(logging.NOTSET)
+    set_logging_level(logging.INFO)
+    set_logging_level(logging.ERROR, '')
diff --git a/rumba/prototypes/irati.py b/rumba/prototypes/irati.py
index 958b4e8..35e9ddf 100644
--- a/rumba/prototypes/irati.py
+++ b/rumba/prototypes/irati.py
@@ -117,6 +117,7 @@ class Experiment(mod.Experiment):
         """
         name = node.name
 
+        logger.info('Setting up vlans for node %s', node.name)
         for ipcp in node.ipcps:
             if isinstance(ipcp, mod.ShimEthIPCP):
                 if_name = ipcp.ifname
@@ -147,7 +148,7 @@ class Experiment(mod.Experiment):
                        'verb': 'DBG',
                        'ipcmcomps': ipcm_components}
 
-        # TODO: watch out for empty path...
+        logger.info('Copying configuration files to node %s', node.name)
         ssh.copy_paths_to_testbed(self.testbed,
                                   node.ssh_config,
                                   gen_files,
@@ -164,16 +165,16 @@ class Experiment(mod.Experiment):
                            '-c /etc/%(name)s.ipcm.conf -l %(verb)s &> log &'
                            % format_args)]
 
-        logger.info('Sending node setup via ssh.')
+        logger.info('Sending setup commands to node %s.', node.name)
         ssh.execute_commands(self.testbed, node.ssh_config, cmds)
 
     def enroll_nodes(self):
         """Runs the enrollments one by one, respecting dependencies"""
         for enrollment_list in self.enrollments:
             for e in enrollment_list:
-                logger.debug(
-                    'I am going to enroll %s to DIF %s against neighbor %s,'
-                    ' through lower DIF %s',
+                logger.info(
+                    'Enrolling %s to DIF %s against neighbor %s,'
+                    ' through lower DIF %s.',
                     e['enrollee'].name,
                     e['dif'].name,
                     e['enroller'].name,
@@ -191,7 +192,6 @@ class Experiment(mod.Experiment):
                                 '--enrollee-name %(dif)s.%(name)s.IPCP '
                                 '--enroller-name %(dif)s.%(o_name)s.IPCP'
                                 % e_args)
-                logger.info('Sending enrollment operation via ssh.')
                 ssh.execute_command(self.testbed,
                                     e['enrollee'].ssh_config,
                                     cmd)
diff --git a/rumba/ssh_support.py b/rumba/ssh_support.py
index 84ff607..26d64fb 100644
--- a/rumba/ssh_support.py
+++ b/rumba/ssh_support.py
@@ -174,7 +174,7 @@ def copy_paths_to_testbed(testbed, ssh_config, paths, destination):
         for path in paths:
             file_name = os.path.basename(path)
             dest_file = destination + file_name
-            logger.info("Copying %s to %s@%s:%s path %s" % (
+            logger.debug("Copying %s to %s@%s:%s path %s" % (
                 path,
                 testbed.username,
                 ssh_config.hostname,
@@ -215,7 +215,7 @@ def setup_vlan(testbed, node, vlan_id, int_name):
         def sudo(s):
             return 'sudo ' + s
 
-    logger.info("Setting up VLAN on node " + node.name)
+    logger.debug("Setting up VLAN on node %s, if %s.", node.name, int_name)
 
     args = {'ifname': str(int_name), 'vlan': str(vlan_id)}
 
diff --git a/rumba/testbeds/qemu.py b/rumba/testbeds/qemu.py
index 6121e6b..a916525 100644
--- a/rumba/testbeds/qemu.py
+++ b/rumba/testbeds/qemu.py
@@ -114,6 +114,7 @@ class Testbed(mod.Testbed):
                 raise Exception('Not authenticated')
 
         logger.info("swapping in")
+        logger.info('Setting up interfaces.')
 
         # Building bridges and taps
         shim_processes = []
@@ -203,6 +204,9 @@ class Testbed(mod.Testbed):
             except:
                 max_waiting_time -= 1
 
+        logger.info('Interfaces setup complete. '
+                    'Building VMs (this might take a while).')
+
         # Building vms
 
         boot_batch_size = max(1, multiprocessing.cpu_count() // 2)
@@ -300,11 +304,14 @@ class Testbed(mod.Testbed):
 
         self.recover_if_names(experiment)
 
+        logger.info('Experiment has been successfully swapped in.')
+
     def swap_out(self, experiment):
         """
         :rtype str
         :return: The script to tear down the experiment
         """
+        logger.info('Killing qemu processes.')
         # TERM qemu processes
         for process in self.boot_processes:
             process.terminate()
@@ -313,6 +320,7 @@ class Testbed(mod.Testbed):
         for process in self.boot_processes:
             process.wait()
 
+        logger.info('Destroying interfaces.')
         port_processes = []
         error_queue = multiprocessing.Queue()
         results_queue = multiprocessing.Queue()
@@ -394,3 +402,4 @@ class Testbed(mod.Testbed):
                                  % (over_processes, total_processes))
             except:
                 max_waiting_time -= 1
+        logger.info('Experiment has been swapped out.')