From e8f7a22f76c80edda826415486e63551af01f5e7 Mon Sep 17 00:00:00 2001 From: Christian Hopps Date: Tue, 4 Apr 2023 10:21:14 +0000 Subject: [PATCH] tests: lower logging level on some infra logs Signed-off-by: Christian Hopps --- .../config_timing/test_config_timing.py | 4 +- tests/topotests/lib/common_config.py | 60 ++++++++++--------- tests/topotests/lib/topogen.py | 16 ++--- tests/topotests/lib/topotest.py | 28 ++++----- 4 files changed, 56 insertions(+), 52 deletions(-) diff --git a/tests/topotests/config_timing/test_config_timing.py b/tests/topotests/config_timing/test_config_timing.py index 8de6f9bf70..5c1b97262c 100644 --- 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 e5a1e75837..4404a4587a 100644 --- 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 41da660b7d..f2771789d6 100644 --- 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 d35b908e12..d040bc3cf0 100644 --- 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: -- 2.39.5