From eda14393d20cdd0b9ef9303f024f4c8a0b47eda2 Mon Sep 17 00:00:00 2001 From: Marco Capitani Date: Mon, 24 Apr 2017 15:00:21 +0200 Subject: Logging: added set and reset logging level method, small logging modifications. --- rumba/log.py | 115 ++++++++++++++++++++++++++++++++++++++++------ rumba/prototypes/irati.py | 12 ++--- rumba/ssh_support.py | 4 +- rumba/testbeds/qemu.py | 9 ++++ 4 files changed, 118 insertions(+), 22 deletions(-) (limited to 'rumba') 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 +# +# 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 . + 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 for logger named . + 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.') -- cgit v1.2.3