proxmox-mirrors/mirror_frr
1
0
Fork 0
mirror of https://git.proxmox.com/git/mirror_frr synced 2025-04-29 20:04:11 +00:00
Code Issues Actions Packages Projects Releases Wiki Activity

tests: lower logging level on some infra logs

Browse Source 
Signed-off-by: Christian Hopps <chopps@labn.net>
This commit is contained in:
Christian Hopps 2023-04-04 10:21:14 +00:00
parent 6fc9bfb11d
commit e8f7a22f76
4 changed files with 56 additions and 52 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

4
tests/topotests/config_timing/test_config_timing.py
View File

@ -133,7 +133,7 @@ def test_static_timing():
delta = (datetime.datetime.now() - tstamp).total_seconds() delta = (datetime.datetime.now() - tstamp).total_seconds()
tot_delta += delta tot_delta += delta
router.logger.info( router.logger.debug(
"\nvtysh command => {}\nvtysh output <= {}\nin {}s".format( "\nvtysh command => {}\nvtysh output <= {}\nin {}s".format(
load_command, output, delta load_command, output, delta
) )
@ -152,7 +152,7 @@ def test_static_timing():
# Number of static routes # Number of static routes
router = tgen.gears["r1"] 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 == "": if output == "":
logger.info("No Address Sanitizer, generating 10000 routes") logger.info("No Address Sanitizer, generating 10000 routes")
prefix_count = 10000 prefix_count = 10000

60
tests/topotests/lib/common_config.py
View File

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

16
tests/topotests/lib/topogen.py
View File

@ -504,7 +504,7 @@ class Topogen(object):
def set_error(self, message, code=None): def set_error(self, message, code=None):
"Sets an error message and signal other tests to skip." "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 no code is defined use a sequential number
if code is None: if code is None:
@ -822,7 +822,7 @@ class TopoRouter(TopoGear):
all routers. all routers.
""" """
daemonstr = self.RD.get(daemon) 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) self.net.loadConf(daemonstr, source, param)
def check_router_running(self): def check_router_running(self):
@ -945,16 +945,16 @@ class TopoRouter(TopoGear):
vtysh_command = 'vtysh {} -c "{}" 2>/dev/null'.format(dparam, command) 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) output = self.run(vtysh_command)
dbgout = output.strip() dbgout = output.strip()
if dbgout: if dbgout:
if "\n" in dbgout: if "\n" in dbgout:
dbgout = dbgout.replace("\n", "\n\t") 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: else:
self.logger.info('vtysh result: "{}"'.format(dbgout)) self.logger.debug('vtysh result: "{}"'.format(dbgout))
if isjson is False: if isjson is False:
return output return output
@ -994,7 +994,7 @@ class TopoRouter(TopoGear):
dbgcmds = commands if is_string(commands) else "\n".join(commands) dbgcmds = commands if is_string(commands) else "\n".join(commands)
dbgcmds = "\t" + dbgcmds.replace("\n", "\n\t") 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) res = self.run(vtysh_command)
os.unlink(fname) os.unlink(fname)
@ -1003,9 +1003,9 @@ class TopoRouter(TopoGear):
if dbgres: if dbgres:
if "\n" in dbgres: if "\n" in dbgres:
dbgres = dbgres.replace("\n", "\n\t") 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: else:
self.logger.info('vtysh result: "{}"'.format(dbgres)) self.logger.debug('vtysh result: "{}"'.format(dbgres))
return res return res
def report_memory_leaks(self, testname): def report_memory_leaks(self, testname):

28
tests/topotests/lib/topotest.py
View File

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