topogen: add per router logging

TopoRouters now create a logger (which logs to /tmp/{router_name}.log)
on start to record all commands and events that it goes through. All log
messages contain timestamps that may be used in the future to:
(1) correlate commands call with events
(2) benchmark/time command speed

tests/topotests/lib/topogen.py

@@ -42,6 +42,7 @@ import os
 import sys
 import json
 import ConfigParser
+import glob
 
 from mininet.net import Mininet
 from mininet.log import setLogLevel
@@ -81,14 +82,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():
@@ -213,13 +221,16 @@ class Topogen(object):
         """
         # 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):
@@ -239,6 +250,7 @@ class Topogen(object):
 
     def stop_topology(self):
         "Stops the network topology"
+        logger.info('stopping topology: {}'.format(self.modname))
         self.net.stop()
 
     def mininet_cli(self):
@@ -252,6 +264,27 @@ class Topogen(object):
 
         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)
 #
@@ -306,6 +339,9 @@ class TopoGear(object):
         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):
@@ -399,6 +435,18 @@ class TopoRouter(TopoGear):
             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):
@@ -406,6 +454,18 @@ class TopoRouter(TopoGear):
         gear += ' TopoRouter<>'
         return gear
 
+    def _prepare_tmpfiles(self):
+        # Create directories if they don't exist
+        try:
+            os.makedirs(self.logdir, 0755)
+        except OSError:
+            pass
+
+        # 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
@@ -415,12 +475,14 @@ class TopoRouter(TopoGear):
         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):
@@ -431,8 +493,17 @@ class TopoRouter(TopoGear):
         * Configure interfaces
         * Start daemons (e.g. FRR/Quagga)
         """
+        self.logger.debug('starting')
         return self.tgen.net[self.name].startRouter()
 
+    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):
         """
         Runs the provided command string in the vty shell and returns a string
@@ -447,6 +518,8 @@ class TopoRouter(TopoGear):
 
         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
 
@@ -473,6 +546,9 @@ class TopoRouter(TopoGear):
         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):
@@ -485,10 +561,10 @@ class TopoRouter(TopoGear):
         """
         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):

tests/topotests/lib/topotest.py

@@ -255,6 +255,7 @@ class Router(Node):
 
     def __init__(self, name, **params):
         super(Router, self).__init__(name, **params)
+        self.logdir = params.get('logdir', '/tmp')
         self.daemondir = None
         self.routertype = 'frr'
         self.daemons = {'zebra': 0, 'ripd': 0, 'ripngd': 0, 'ospfd': 0,
@@ -309,7 +310,7 @@ class Router(Node):
         # Enable coredumps
         assert_sysctl(self, 'kernel.core_uses_pid', 1)
         assert_sysctl(self, 'fs.suid_dumpable', 2)
-        corefile = '/tmp/{0}_%e_core-sig_%s-pid_%p.dmp'.format(self.name)
+        corefile = '{}/{}_%e_core-sig_%s-pid_%p.dmp'.format(self.logdir, self.name)
         assert_sysctl(self, 'kernel.core_pattern', corefile)
         self.cmd('ulimit -c unlimited')
         # Set ownership of config files
@@ -359,6 +360,7 @@ class Router(Node):
         # Disable integrated-vtysh-config
         self.cmd('echo "no service integrated-vtysh-config" >> /etc/%s/vtysh.conf' % self.routertype)
         self.cmd('chown %s:%svty /etc/%s/vtysh.conf' % (self.routertype, self.routertype, self.routertype))
+        # TODO remove the following lines after all tests are migrated to Topogen.
         # Try to find relevant old logfiles in /tmp and delete them
         map(os.remove, glob.glob("/tmp/*%s*.log" % self.name))
         # Remove old core files
@@ -391,8 +393,8 @@ class Router(Node):
         # Start Zebra first
         if self.daemons['zebra'] == 1:
             zebra_path = os.path.join(self.daemondir, 'zebra')
-            self.cmd('{0} > /tmp/{1}-zebra.out 2> /tmp/{1}-zebra.err &'.format(
+            self.cmd('{0} > {1}/{2}-zebra.out 2> {1}/{2}-zebra.err &'.format(
-                zebra_path, self.name
+                zebra_path, self.logdir, self.name
             ))
             self.waitOutput()
             logger.debug('{}: {} zebra started'.format(self, self.routertype))
@@ -407,8 +409,8 @@ class Router(Node):
                 continue
 
             daemon_path = os.path.join(self.daemondir, daemon)
-            self.cmd('{0} > /tmp/{1}-{2}.out 2> /tmp/{1}-{2}.err &'.format(
+            self.cmd('{0} > {1}/{2}-{3}.out 2> {1}/{2}-{3}.err &'.format(
-                daemon_path, self.name, daemon
+                daemon_path, self.logdir, self.name, daemon
             ))
             self.waitOutput()
             logger.debug('{}: {} {} started'.format(self, self.routertype, daemon))
@@ -417,7 +419,7 @@ class Router(Node):
     def getStdOut(self, daemon):
         return self.getLog('out', daemon)
     def getLog(self, log, daemon):
-        return self.cmd('cat /tmp/%s-%s.%s' % (self.name, daemon, log) )
+        return self.cmd('cat {}/{}-{}.{}'.format(self.logdir, self.name, daemon, log))
     def checkRouterRunning(self):
         "Check if router daemons are running and collect crashinfo they don't run"
 
@@ -432,7 +434,8 @@ class Router(Node):
             if (self.daemons[daemon] == 1) and not (daemon in daemonsRunning):
                 sys.stderr.write("%s: Daemon %s not running\n" % (self.name, daemon))
                 # Look for core file
-                corefiles = glob.glob("/tmp/%s_%s_core*.dmp" % (self.name, daemon))
+                corefiles = glob.glob('{}/{}_{}_core*.dmp'.format(
+                    self.logdir, self.name, daemon))
                 if (len(corefiles) > 0):
                     daemon_path = os.path.join(self.daemondir, daemon)
                     backtrace = subprocess.check_output([
@@ -442,8 +445,11 @@ class Router(Node):
                     sys.stderr.write("%s\n" % backtrace)
                 else:
                     # No core found - If we find matching logfile in /tmp, then print last 20 lines from it.
-                    if os.path.isfile("/tmp/%s-%s.log" % (self.name, daemon)):
+                    if os.path.isfile('{}/{}-{}.log'.format(self.logdir, self.name, daemon)):
-                        log_tail = subprocess.check_output(["tail -n20 /tmp/%s-%s.log 2> /dev/null"  % (self.name, daemon)], shell=True)
+                        log_tail = subprocess.check_output([
+                            "tail -n20 {}/{}-{}.log 2> /dev/null".format(
+                                self.logdir, self.name, daemon)
+                            ], shell=True)
                         sys.stderr.write("\nFrom %s %s %s log file:\n" % (self.routertype, self.name, daemon))
                         sys.stderr.write("%s\n" % log_tail)