tests: lower logging level on some infra logs

Signed-off-by: Christian Hopps <chopps@labn.net>

diff --git a/tests/topotests/config_timing/test_config_timing.py b/tests/topotests/config_timing/test_config_timing.py
index 8de6f9bf7082a0ef9bef54d856bf22aab1288811..5c1b97262c95eb8ba9cb4e8de553856d898b9abc 100644 (file)
--- a/tests/topotests/config_timing/test_config_timing.py
+++ b/tests/topotests/config_timing/test_config_timing.py
@@ -133,7 +133,7 @@ def test_static_timing():
             delta = (datetime.datetime.now() - tstamp).total_seconds()
             tot_delta += delta
 
-            router.logger.info(
+            router.logger.debug(
                 "\nvtysh command => {}\nvtysh output <= {}\nin {}s".format(
                     load_command, output, delta
                 )
@@ -152,7 +152,7 @@ def test_static_timing():
 
     # Number of static routes
     router = tgen.gears["r1"]
-    output = router.run("vtysh -h | grep address-sanitizer")
+    output = router.net.cmd_legacy("vtysh -h | grep address-sanitizer", warn=False)
     if output == "":
         logger.info("No Address Sanitizer, generating 10000 routes")
         prefix_count = 10000

diff --git a/tests/topotests/lib/common_config.py b/tests/topotests/lib/common_config.py
index e5a1e758379c1aa312c9fc00eb0678e1f95e38f4..4404a4587acdc4325dd7fd79e7191f70ce555fb6 100644 (file)
--- a/tests/topotests/lib/common_config.py
+++ b/tests/topotests/lib/common_config.py
@@ -492,7 +492,7 @@ def save_initial_config_on_routers(tgen):
     # Get all running configs in parallel
     procs = {}
     for rname in router_list:
-        logger.info("Fetching running config for router %s", rname)
+        logger.debug("Fetching running config for router %s", rname)
         procs[rname] = router_list[rname].popen(
             ["/usr/bin/env", "vtysh", "-c", "show running-config no-header"],
             stdin=None,
@@ -548,7 +548,7 @@ def reset_config_on_routers(tgen, routerName=None):
     #
     procs = {}
     for rname in router_list:
-        logger.info("Fetching running config for router %s", rname)
+        logger.debug("Fetching running config for router %s", rname)
         procs[rname] = router_list[rname].popen(
             ["/usr/bin/env", "vtysh", "-c", "show running-config no-header"],
             stdin=None,
@@ -570,7 +570,7 @@ def reset_config_on_routers(tgen, routerName=None):
     #
     procs = {}
     for rname in router_list:
-        logger.info(
+        logger.debug(
             "Generating delta for router %s to new configuration (gen %d)", rname, gen
         )
         procs[rname] = tgen.net.popen(
@@ -599,7 +599,7 @@ def reset_config_on_routers(tgen, routerName=None):
     #
     procs = {}
     for rname in router_list:
-        logger.info("Applying delta config on router %s", rname)
+        logger.debug("Applying delta config on router %s", rname)
 
         procs[rname] = router_list[rname].popen(
             ["/usr/bin/env", "vtysh", "-f", delta_fmt.format(rname, gen)],
@@ -611,7 +611,7 @@ def reset_config_on_routers(tgen, routerName=None):
         output, _ = p.communicate()
         vtysh_command = "vtysh -f {}".format(delta_fmt.format(rname, gen))
         if not p.returncode:
-            router_list[rname].logger.info(
+            router_list[rname].logger.debug(
                 '\nvtysh config apply => "{}"\nvtysh output <= "{}"'.format(
                     vtysh_command, output
                 )
@@ -640,7 +640,7 @@ def reset_config_on_routers(tgen, routerName=None):
     if show_router_config:
         procs = {}
         for rname in router_list:
-            logger.info("Fetching running config for router %s", rname)
+            logger.debug("Fetching running config for router %s", rname)
             procs[rname] = router_list[rname].popen(
                 ["/usr/bin/env", "vtysh", "-c", "show running-config no-header"],
                 stdin=None,
@@ -657,7 +657,7 @@ def reset_config_on_routers(tgen, routerName=None):
                     output,
                 )
             else:
-                logger.info(
+                logger.debug(
                     "Configuration on router %s after reset:\n%s", rname, output
                 )
 
@@ -742,7 +742,7 @@ def load_config_to_routers(tgen, routers, save_bkup=False):
             frr_cfg_bkup = frr_cfg_bkup_fmt.format(rname)
             with open(frr_cfg_file, "r+") as cfg:
                 data = cfg.read()
-                logger.info(
+                logger.debug(
                     "Applying following configuration on router %s (gen: %d):\n%s",
                     rname,
                     gen,
@@ -775,7 +775,7 @@ def load_config_to_routers(tgen, routers, save_bkup=False):
         frr_cfg_file = frr_cfg_file_fmt.format(rname)
         vtysh_command = "vtysh -f " + frr_cfg_file
         if not p.returncode:
-            router_list[rname].logger.info(
+            router_list[rname].logger.debug(
                 '\nvtysh config apply => "{}"\nvtysh output <= "{}"'.format(
                     vtysh_command, output
                 )
@@ -821,7 +821,7 @@ def load_config_to_routers(tgen, routers, save_bkup=False):
                     output,
                 )
             else:
-                logger.info("New configuration for router %s:\n%s", rname, output)
+                logger.debug("New configuration for router %s:\n%s", rname, output)
 
     logger.debug("Exiting API: load_config_to_routers")
     return not errors
@@ -957,10 +957,10 @@ def generate_support_bundle():
         bundle_procs[rname] = tgen.net[rname].popen(gen_sup_cmd, stdin=None)
 
     for rname, rnode in router_list.items():
-        logger.info("Waiting on support bundle for %s", rname)
+        logger.debug("Waiting on support bundle for %s", rname)
         output, error = bundle_procs[rname].communicate()
         if output:
-            logger.info(
+            logger.debug(
                 "Output from collecting support bundle for %s:\n%s", rname, output
             )
         if error:
@@ -1234,15 +1234,15 @@ def add_interfaces_to_vlan(tgen, input_dict):
                         cmd = "ip link add link {} name {} type vlan id {}".format(
                             interface, vlan_intf, vlan
                         )
-                        logger.info("[DUT: %s]: Running command: %s", dut, cmd)
+                        logger.debug("[DUT: %s]: Running command: %s", dut, cmd)
                         result = rnode.run(cmd)
-                        logger.info("result %s", result)
+                        logger.debug("result %s", result)
 
                         # Bringing interface up
                         cmd = "ip link set {} up".format(vlan_intf)
-                        logger.info("[DUT: %s]: Running command: %s", dut, cmd)
+                        logger.debug("[DUT: %s]: Running command: %s", dut, cmd)
                         result = rnode.run(cmd)
-                        logger.info("result %s", result)
+                        logger.debug("result %s", result)
 
                         # Assigning IP address
                         ifaddr = ipaddress.ip_interface(
@@ -1254,9 +1254,9 @@ def add_interfaces_to_vlan(tgen, input_dict):
                         cmd = "ip -{0} a flush {1} scope global && ip a add {2} dev {1} && ip l set {1} up".format(
                             ifaddr.version, vlan_intf, ifaddr
                         )
-                        logger.info("[DUT: %s]: Running command: %s", dut, cmd)
+                        logger.debug("[DUT: %s]: Running command: %s", dut, cmd)
                         result = rnode.run(cmd)
-                        logger.info("result %s", result)
+                        logger.debug("result %s", result)
 
 
 def tcpdump_capture_start(
@@ -1567,12 +1567,16 @@ def create_vrf_cfg(tgen, topo, input_dict=None, build=False):
                             vrf["name"], vrf["id"]
                         )
 
-                        logger.info("[DUT: %s]: Running kernel cmd [%s]", c_router, cmd)
+                        logger.debug(
+                            "[DUT: %s]: Running kernel cmd [%s]", c_router, cmd
+                        )
                         rnode.run(cmd)
 
                         # Kernel cmd - Bring down VRF
                         cmd = "ip link set dev {} down".format(name)
-                        logger.info("[DUT: %s]: Running kernel cmd [%s]", c_router, cmd)
+                        logger.debug(
+                            "[DUT: %s]: Running kernel cmd [%s]", c_router, cmd
+                        )
                         rnode.run(cmd)
 
                     else:
@@ -1581,14 +1585,14 @@ def create_vrf_cfg(tgen, topo, input_dict=None, build=False):
                             cmd = "ip link add {} type vrf table {}".format(
                                 name, table_id
                             )
-                            logger.info(
+                            logger.debug(
                                 "[DUT: %s]: Running kernel cmd " "[%s]", c_router, cmd
                             )
                             rnode.run(cmd)
 
                             # Kernel cmd - Bring up VRF
                             cmd = "ip link set dev {} up".format(name)
-                            logger.info(
+                            logger.debug(
                                 "[DUT: %s]: Running kernel " "cmd [%s]", c_router, cmd
                             )
                             rnode.run(cmd)
@@ -1616,7 +1620,7 @@ def create_vrf_cfg(tgen, topo, input_dict=None, build=False):
                                         interface_name, _vrf
                                     )
 
-                                    logger.info(
+                                    logger.debug(
                                         "[DUT: %s]: Running" " kernel cmd [%s]",
                                         c_router,
                                         cmd,
@@ -1683,7 +1687,7 @@ def create_interface_in_kernel(
     cmd = "ip -{0} a flush {1} scope global && ip a add {2} dev {1} && ip l set {1} up".format(
         ifaddr.version, name, ifaddr
     )
-    logger.info("[DUT: %s]: Running command: %s", dut, cmd)
+    logger.debug("[DUT: %s]: Running command: %s", dut, cmd)
     rnode.run(cmd)
 
     if vrf:
@@ -1715,7 +1719,7 @@ def shutdown_bringup_interface_in_kernel(tgen, dut, intf_name, ifaceaction=False
         action = "down"
         cmd = "{} {} {}".format(cmd, intf_name, action)
 
-    logger.info("[DUT: %s]: Running command: %s", dut, cmd)
+    logger.debug("[DUT: %s]: Running command: %s", dut, cmd)
     rnode.run(cmd)
 
 
@@ -1968,7 +1972,7 @@ def retry(retry_timeout, initial_wait=0, expected=True, diag_pct=0.75):
             )
 
             if initial_wait > 0:
-                logger.info("Waiting for [%s]s as initial delay", initial_wait)
+                logger.debug("Waiting for [%s]s as initial delay", initial_wait)
                 sleep(initial_wait)
 
             invert_logic = not _expected
@@ -2027,13 +2031,13 @@ def retry(retry_timeout, initial_wait=0, expected=True, diag_pct=0.75):
                         return saved_failure
 
                 if saved_failure:
-                    logger.info(
+                    logger.debug(
                         "RETRY DIAG: [failure] Sleeping %ds until next retry with %.1f retry time left - too see if timeout was too short",
                         retry_sleep,
                         seconds_left,
                     )
                 else:
-                    logger.info(
+                    logger.debug(
                         "Sleeping %ds until next retry with %.1f retry time left",
                         retry_sleep,
                         seconds_left,

diff --git a/tests/topotests/lib/topogen.py b/tests/topotests/lib/topogen.py
index 41da660b7d027afd1fae978147784cfd072efd47..f2771789d6fa6cab9e939344e6a3c3bb59a442b9 100644 (file)
--- a/tests/topotests/lib/topogen.py
+++ b/tests/topotests/lib/topogen.py
@@ -504,7 +504,7 @@ class Topogen(object):
 
     def set_error(self, message, code=None):
         "Sets an error message and signal other tests to skip."
-        logger.info(message)
+        logger.info("setting error msg: %s", message)
 
         # If no code is defined use a sequential number
         if code is None:
@@ -822,7 +822,7 @@ class TopoRouter(TopoGear):
         all routers.
         """
         daemonstr = self.RD.get(daemon)
-        self.logger.info('loading "{}" configuration: {}'.format(daemonstr, source))
+        self.logger.debug('loading "{}" configuration: {}'.format(daemonstr, source))
         self.net.loadConf(daemonstr, source, param)
 
     def check_router_running(self):
@@ -945,16 +945,16 @@ class TopoRouter(TopoGear):
 
         vtysh_command = 'vtysh {} -c "{}" 2>/dev/null'.format(dparam, command)
 
-        self.logger.info('vtysh command => "{}"'.format(command))
+        self.logger.debug('vtysh command => "{}"'.format(command))
         output = self.run(vtysh_command)
 
         dbgout = output.strip()
         if dbgout:
             if "\n" in dbgout:
                 dbgout = dbgout.replace("\n", "\n\t")
-                self.logger.info("vtysh result:\n\t{}".format(dbgout))
+                self.logger.debug("vtysh result:\n\t{}".format(dbgout))
             else:
-                self.logger.info('vtysh result: "{}"'.format(dbgout))
+                self.logger.debug('vtysh result: "{}"'.format(dbgout))
 
         if isjson is False:
             return output
@@ -994,7 +994,7 @@ class TopoRouter(TopoGear):
 
         dbgcmds = commands if is_string(commands) else "\n".join(commands)
         dbgcmds = "\t" + dbgcmds.replace("\n", "\n\t")
-        self.logger.info("vtysh command => FILE:\n{}".format(dbgcmds))
+        self.logger.debug("vtysh command => FILE:\n{}".format(dbgcmds))
 
         res = self.run(vtysh_command)
         os.unlink(fname)
@@ -1003,9 +1003,9 @@ class TopoRouter(TopoGear):
         if dbgres:
             if "\n" in dbgres:
                 dbgres = dbgres.replace("\n", "\n\t")
-                self.logger.info("vtysh result:\n\t{}".format(dbgres))
+                self.logger.debug("vtysh result:\n\t{}".format(dbgres))
             else:
-                self.logger.info('vtysh result: "{}"'.format(dbgres))
+                self.logger.debug('vtysh result: "{}"'.format(dbgres))
         return res
 
     def report_memory_leaks(self, testname):

diff --git a/tests/topotests/lib/topotest.py b/tests/topotests/lib/topotest.py
index d35b908e120ed9851dcefdbdd5c674b0f8465a2c..d040bc3cf0af94f1f0cfda6625a4f5e0b907178c 100644 (file)
--- a/tests/topotests/lib/topotest.py
+++ b/tests/topotests/lib/topotest.py
@@ -352,7 +352,7 @@ def run_and_expect(func, what, count=20, wait=3):
             count, wait
         )
 
-    logger.info(
+    logger.debug(
         "'{}' polling started (interval {} secs, maximum {} tries)".format(
             func_name, wait, count
         )
@@ -366,7 +366,7 @@ def run_and_expect(func, what, count=20, wait=3):
             continue
 
         end_time = time.time()
-        logger.info(
+        logger.debug(
             "'{}' succeeded after {:.2f} seconds".format(
                 func_name, end_time - start_time
             )
@@ -409,7 +409,7 @@ def run_and_expect_type(func, etype, count=20, wait=3, avalue=None):
             count, wait
         )
 
-    logger.info(
+    logger.debug(
         "'{}' polling started (interval {} secs, maximum wait {} secs)".format(
             func_name, wait, int(wait * count)
         )
@@ -432,7 +432,7 @@ def run_and_expect_type(func, etype, count=20, wait=3, avalue=None):
             continue
 
         end_time = time.time()
-        logger.info(
+        logger.debug(
             "'{}' succeeded after {:.2f} seconds".format(
                 func_name, end_time - start_time
             )
@@ -1130,7 +1130,7 @@ def _sysctl_atleast(commander, variable, min_value):
             valstr = " ".join([str(x) for x in min_value])
         else:
             valstr = str(min_value)
-        logger.info("Increasing sysctl %s from %s to %s", variable, cur_val, valstr)
+        logger.debug("Increasing sysctl %s from %s to %s", variable, cur_val, valstr)
         commander.cmd_raises('sysctl -w {}="{}"\n'.format(variable, valstr))
 
 
@@ -1161,7 +1161,7 @@ def _sysctl_assure(commander, variable, value):
             valstr = " ".join([str(x) for x in value])
         else:
             valstr = str(value)
-        logger.info("Changing sysctl %s from %s to %s", variable, cur_val, valstr)
+        logger.debug("Changing sysctl %s from %s to %s", variable, cur_val, valstr)
         commander.cmd_raises('sysctl -w {}="{}"\n'.format(variable, valstr))
 
 
@@ -1204,7 +1204,7 @@ def rlimit_atleast(rname, min_value, raises=False):
         soft, hard = cval
         if soft < min_value:
             nval = (min_value, hard if min_value < hard else min_value)
-            logger.info("Increasing rlimit %s from %s to %s", rname, cval, nval)
+            logger.debug("Increasing rlimit %s from %s to %s", rname, cval, nval)
             resource.setrlimit(rname, nval)
     except subprocess.CalledProcessError as error:
         logger.warning(
@@ -1478,11 +1478,11 @@ class Router(Node):
 
         logger.info("%s: stopping %s", self.name, ", ".join([x[0] for x in running]))
         for name, pid in running:
-            logger.info("{}: sending SIGTERM to {}".format(self.name, name))
+            logger.debug("{}: sending SIGTERM to {}".format(self.name, name))
             try:
                 os.kill(pid, signal.SIGTERM)
             except OSError as err:
-                logger.info(
+                logger.debug(
                     "%s: could not kill %s (%s): %s", self.name, name, pid, str(err)
                 )
 
@@ -1560,7 +1560,7 @@ class Router(Node):
                 router_relative = os.path.join(script_dir, self.name, tail)
                 if self.path_exists(router_relative):
                     source = router_relative
-                    self.logger.info(
+                    self.logger.debug(
                         "using router relative configuration: {}".format(source)
                     )
 
@@ -1617,7 +1617,7 @@ class Router(Node):
                     # Auto-Started staticd has no config, so it will read from zebra config
 
         else:
-            logger.info("No daemon {} known".format(daemon))
+            logger.warning("No daemon {} known".format(daemon))
         # print "Daemons after:", self.daemons
 
     def runInWindow(self, cmd, title=None):
@@ -1859,7 +1859,7 @@ class Router(Node):
                         else "",
                     )
                 else:
-                    logger.info("%s: %s %s started", self, self.routertype, daemon)
+                    logger.debug("%s: %s %s started", self, self.routertype, daemon)
 
         # Start mgmtd first
         if "mgmtd" in daemons_list:
@@ -1934,7 +1934,7 @@ class Router(Node):
                         daemonpidfile = d.rstrip()
                         daemonpid = self.cmd("cat %s" % daemonpidfile).rstrip()
                         if daemonpid.isdigit() and pid_exists(int(daemonpid)):
-                            logger.info(
+                            logger.debug(
                                 "{}: killing {}".format(
                                     self.name,
                                     os.path.basename(daemonpidfile.rsplit(".", 1)[0]),
@@ -2198,7 +2198,7 @@ class Router(Node):
                 log = self.getStdErr(daemon)
                 if "memstats" in log:
                     # Found memory leak
-                    logger.info(
+                    logger.warning(
                         "\nRouter {} {} StdErr Log:\n{}".format(self.name, daemon, log)
                     )
                     if not leakfound: