Merge pull request #12 from opensourcerouting/tgen-log

import Topolog

example-test/test_template.py

@@ -38,6 +38,7 @@
 # Import topogen and topotest helpers
 from lib import topotest
 from lib.topogen import Topogen, TopoRouter, get_topogen
+from lib.topolog import logger
 
 # Required to instantiate the topology builder class.
 from mininet.topo import Topo
@@ -67,13 +68,12 @@ def build(self, *_args, **_opts):
         switch.add_link(tgen.gears['r1'])
         switch.add_link(tgen.gears['r2'])
 
-def setup_module(_m):
+def setup_module(mod):
     "Sets up the pytest environment"
     # This function initiates the topology build with Topogen...
-    tgen = Topogen(TemplateTopo)
+    tgen = Topogen(TemplateTopo, mod.__name__)
     # ... and here it calls Mininet initialization functions.
-    # When deploying tests, please remove the debug logging level.
-    tgen.start_topology('debug')
+    tgen.start_topology()
 
     # This is a sample of configuration loading.
     router_list = tgen.routers()
@@ -89,17 +89,28 @@ def setup_module(_m):
     # After loading the configurations, this function loads configured daemons.
     tgen.start_router()
 
-def teardown_module(_m):
+def teardown_module(mod):
     "Teardown the pytest environment"
     tgen = get_topogen()
+
     # This function tears down the whole topology.
     tgen.stop_topology()
 
 def test_call_mininet_cli():
     "Dummy test that just calls mininet CLI so we can interact with the build."
     tgen = get_topogen()
+    logger.info('calling mininet CLI')
     tgen.mininet_cli()
 
+# Memory leak test template
+def test_memory_leak():
+    "Run the memory leak test and report results."
+    tgen = get_topogen()
+    if not tgen.is_memleak_enabled():
+        pytest.skip('Memory leak test/report is disabled')
+
+    tgen.report_memory_leaks()
+
 if __name__ == '__main__':
     args = ["-s"] + sys.argv[1:]
     sys.exit(pytest.main(args))

lib/topogen.py

@@ -42,12 +42,15 @@
 import sys
 import json
 import ConfigParser
+import glob
+import grp
 
 from mininet.net import Mininet
 from mininet.log import setLogLevel
 from mininet.cli import CLI
 
 from lib import topotest
+from lib.topolog import logger, logger_config
 
 CWD = os.path.dirname(os.path.realpath(__file__))
 
@@ -80,14 +83,21 @@ class Topogen(object):
 
     CONFIG_SECTION = 'topogen'
 
-    def __init__(self, cls):
+    def __init__(self, cls, modname='unnamed'):
+        """
+        Topogen initialization function, takes the following arguments:
+        * `cls`: the topology class that is child of mininet.topo
+        * `modname`: module name must be a unique name to identify logs later.
+        """
         self.config = None
         self.topo = None
         self.net = None
         self.gears = {}
         self.routern = 1
         self.switchn = 1
+        self.modname = modname
         self._init_topo(cls)
+        logger.info('loading topology: {}'.format(self.modname))
 
     @staticmethod
     def _mininet_reset():
@@ -212,10 +222,16 @@ def start_topology(self, log_level=None):
         """
         # If log_level is not specified use the configuration.
         if log_level is None:
-            log_level = self.config.get('topogen', 'verbosity')
+            log_level = self.config.get(self.CONFIG_SECTION, 'verbosity')
+
+        # Set python logger level
+        logger_config.set_log_level(log_level)
 
         # Run mininet
-        setLogLevel(log_level)
+        if log_level == 'debug':
+            setLogLevel(log_level)
+
+        logger.info('starting topology: {}'.format(self.modname))
         self.net.start()
 
     def start_router(self, router=None):
@@ -235,6 +251,7 @@ def start_router(self, router=None):
 
     def stop_topology(self):
         "Stops the network topology"
+        logger.info('stopping topology: {}'.format(self.modname))
         self.net.stop()
 
     def mininet_cli(self):
@@ -248,6 +265,27 @@ def mininet_cli(self):
 
         CLI(self.net)
 
+    def is_memleak_enabled(self):
+        "Returns `True` if memory leak report is enable, otherwise `False`."
+        memleak_file = os.environ.get('TOPOTESTS_CHECK_MEMLEAK')
+        if memleak_file is None:
+            return False
+        return True
+
+    def report_memory_leaks(self, testname=None):
+        "Run memory leak test and reports."
+        if not self.is_memleak_enabled():
+            return
+
+        # If no name was specified, use the test module name
+        if testname is None:
+            testname = self.modname
+
+        router_list = self.routers().values()
+        for router in router_list:
+            router.report_memory_leaks(self.modname)
+
+
 #
 # Topology gears (equipment)
 #
@@ -302,6 +340,9 @@ def link_enable(self, myif, enabled=True):
         else:
             operation = 'down'
 
+        logger.info('setting node "{}" link "{}" to state "{}"'.format(
+            self.name, myif, operation
+        ))
         return self.run('ip link set dev {} {}'.format(myif, operation))
 
     def peer_link_enable(self, myif, enabled=True):
@@ -391,17 +432,52 @@ def __init__(self, tgen, cls, name, **params):
         self.name = name
         self.cls = cls
         self.options = {}
+        self.routertype = params.get('routertype', 'frr')
         if not params.has_key('privateDirs'):
             params['privateDirs'] = self.PRIVATE_DIRS
 
         self.options['memleak_path'] = params.get('memleak_path', None)
+
+        # Create new log directory
+        self.logdir = '/tmp/topotests/{}'.format(self.tgen.modname)
+        # Clean up before starting new log files: avoids removing just created
+        # log files.
+        self._prepare_tmpfiles()
+        # Propagate the router log directory
+        params['logdir'] = self.logdir
+
+        # Open router log file
+        logfile = '{}/{}.log'.format(self.logdir, name)
+        self.logger = logger_config.get_logger(name=name, target=logfile)
         self.tgen.topo.addNode(self.name, cls=self.cls, **params)
 
     def __str__(self):
         gear = super(TopoRouter, self).__str__()
         gear += ' TopoRouter<>'
         return gear
 
+    def _prepare_tmpfiles(self):
+        # Create directories if they don't exist
+        try:
+            os.makedirs(self.logdir, 0755)
+        except OSError:
+            pass
+
+        # Allow unprivileged daemon user (frr/quagga) to create log files
+        try:
+            # Only allow group, if it exist.
+            gid = grp.getgrnam(self.routertype)[2]
+            os.chown(self.logdir, 0, gid)
+            os.chmod(self.logdir, 0775)
+        except KeyError:
+            # Allow anyone, but set the sticky bit to avoid file deletions
+            os.chmod(self.logdir, 01777)
+
+        # Try to find relevant old logfiles in /tmp and delete them
+        map(os.remove, glob.glob('{}/*{}*.log'.format(self.logdir, self.name)))
+        # Remove old core files
+        map(os.remove, glob.glob('{}/{}*.dmp'.format(self.logdir, self.name)))
+
     def load_config(self, daemon, source=None):
         """
         Loads daemon configuration from the specified source
@@ -411,12 +487,14 @@ def load_config(self, daemon, source=None):
         TopoRouter.RD_PIM.
         """
         daemonstr = self.RD.get(daemon)
+        self.logger.info('loading "{}" configuration: {}'.format(daemonstr, source))
         self.tgen.net[self.name].loadConf(daemonstr, source)
 
     def check_router_running(self):
         """
         Run a series of checks and returns a status string.
         """
+        self.logger.info('checking if daemons are running')
         return self.tgen.net[self.name].checkRouterRunning()
 
     def start(self):
@@ -426,8 +504,28 @@ def start(self):
         * Clean up files
         * Configure interfaces
         * Start daemons (e.g. FRR/Quagga)
+        * Configure daemon logging files
         """
-        return self.tgen.net[self.name].startRouter()
+        self.logger.debug('starting')
+        nrouter = self.tgen.net[self.name]
+        result = nrouter.startRouter()
+
+        # Enable all daemon logging files and set them to the logdir.
+        for daemon, enabled in nrouter.daemons.iteritems():
+            if enabled == 0:
+                continue
+            self.vtysh_cmd('configure terminal\nlog file {}/{}-{}.log'.format(
+                self.logdir, self.name, daemon))
+
+        return result
+
+    def stop(self):
+        """
+        Stop router:
+        * Kill daemons
+        """
+        self.logger.debug('stopping')
+        return self.tgen.net[self.name].stopRouter()
 
     def vtysh_cmd(self, command, isjson=False):
         """
@@ -443,6 +541,8 @@ def vtysh_cmd(self, command, isjson=False):
 
         vtysh_command = 'vtysh -c "{}" 2>/dev/null'.format(command)
         output = self.run(vtysh_command)
+        self.logger.info('\nvtysh command => {}\nvtysh output <= {}'.format(
+            command, output))
         if isjson is False:
             return output
 
@@ -469,6 +569,9 @@ def vtysh_multicmd(self, commands, pretty_output=True):
         res = self.run(vtysh_command)
         os.unlink(fname)
 
+        self.logger.info('\nvtysh command => "{}"\nvtysh output <= "{}"'.format(
+            vtysh_command, res))
+
         return res
 
     def report_memory_leaks(self, testname):
@@ -481,10 +584,10 @@ def report_memory_leaks(self, testname):
         """
         memleak_file = os.environ.get('TOPOTESTS_CHECK_MEMLEAK') or self.options['memleak_path']
         if memleak_file is None:
-            print "SKIPPED check on Memory leaks: Disabled (TOPOTESTS_CHECK_MEMLEAK undefined)"
             return
 
-        self.tgen.net[self.name].stopRouter()
+        self.stop()
+        self.logger.info('running memory leak report')
         self.tgen.net[self.name].report_memory_leaks(memleak_file, testname)
 
 class TopoSwitch(TopoGear):

lib/topolog.py

@@ -0,0 +1,100 @@
+#
+# topolog.py
+# Library of helper functions for NetDEF Topology Tests
+#
+# Copyright (c) 2017 by
+# Network Device Education Foundation, Inc. ("NetDEF")
+#
+# Permission to use, copy, modify, and/or distribute this software
+# for any purpose with or without fee is hereby granted, provided
+# that the above copyright notice and this permission notice appear
+# in all copies.
+#
+# THE SOFTWARE IS PROVIDED "AS IS" AND NETDEF DISCLAIMS ALL WARRANTIES
+# WITH REGARD TO THIS SOFTWARE INCLUDING ALL IMPLIED WARRANTIES OF
+# MERCHANTABILITY AND FITNESS. IN NO EVENT SHALL NETDEF BE LIABLE FOR
+# ANY SPECIAL, DIRECT, INDIRECT, OR CONSEQUENTIAL DAMAGES OR ANY
+# DAMAGES WHATSOEVER RESULTING FROM LOSS OF USE, DATA OR PROFITS,
+# WHETHER IN AN ACTION OF CONTRACT, NEGLIGENCE OR OTHER TORTIOUS
+# ACTION, ARISING OUT OF OR IN CONNECTION WITH THE USE OR PERFORMANCE
+# OF THIS SOFTWARE.
+#
+
+"""
+Logging utilities for topology tests.
+
+This file defines our logging abstraction.
+"""
+
+import sys
+import logging
+
+# Helper dictionary to convert Topogen logging levels to Python's logging.
+DEBUG_TOPO2LOGGING = {
+    'debug': logging.DEBUG,
+    'info': logging.INFO,
+    'output': logging.INFO,
+    'warning': logging.WARNING,
+    'error': logging.ERROR,
+    'critical': logging.CRITICAL,
+}
+
+#
+# Logger class definition
+#
+
+class Logger(object):
+    """
+    Logger class that encapsulates logging functions, internaly it uses Python
+    logging module with a separated instance instead of global.
+
+    Default logging level is 'info'.
+    """
+
+    def __init__(self):
+        # Create default global logger
+        self.log_level = logging.INFO
+        self.logger = logging.Logger('topolog', level=self.log_level)
+        handler = logging.StreamHandler()
+        handler.setFormatter(
+            logging.Formatter(fmt='%(asctime)s %(levelname)s: %(message)s')
+        )
+        self.logger.addHandler(handler)
+
+        # Handle more loggers
+        self.loggers = {'topolog': self.logger}
+
+    def set_log_level(self, level):
+        "Set the logging level"
+        self.log_level = DEBUG_TOPO2LOGGING.get(level)
+        self.logger.setLevel(self.log_level)
+
+    def get_logger(self, name='topolog', log_level=None, target=sys.stdout):
+        """
+        Get a new logger entry. Allows creating different loggers for formating,
+        filtering or handling (file, stream or stdout/stderr).
+        """
+        if log_level is None:
+            log_level = self.log_level
+        if self.loggers.has_key(name):
+            return self.loggers[name]
+
+        nlogger = logging.Logger(name, level=log_level)
+        if isinstance(target, str):
+            handler = logging.FileHandler(filename=target)
+        else:
+            handler = logging.StreamHandler(stream=target)
+
+        handler.setFormatter(
+            logging.Formatter(fmt='%(asctime)s %(levelname)s: %(message)s')
+        )
+        nlogger.addHandler(handler)
+        self.loggers[name] = nlogger
+        return nlogger
+
+#
+# Global variables
+#
+
+logger_config = Logger()
+logger = logger_config.logger