diff --git a/tools/frr-reload.py b/tools/frr-reload.py index f124cae713..6758caa42d 100755 --- a/tools/frr-reload.py +++ b/tools/frr-reload.py @@ -14,6 +14,7 @@ This program from __future__ import print_function, unicode_literals import argparse +import datetime import logging import os, os.path import random @@ -95,7 +96,7 @@ class Vtysh(object): output = self("configure") if "configuration is locked" in output.lower(): - log.error("vtysh 'configure' returned\n%s\n" % (output)) + log.error(f"vtysh 'configure' returned\n{output}\n") return False return True @@ -104,7 +105,7 @@ class Vtysh(object): child = self._call(["-f", filename]) if child.wait() != 0: raise VtyshException( - "vtysh (exec file) exited with status %d" % (child.returncode) + f"vtysh (exec file) exited with status {child.returncode}" ) def mark_file(self, filename, stdin=None): @@ -320,7 +321,7 @@ class Config(object): The internal representation has been marked appropriately by passing it through vtysh with the -m parameter """ - log.info("Loading Config object from file %s", filename) + log.info(f"Loading Config object from file {filename}") file_output = self.vtysh.mark_file(filename) @@ -660,7 +661,7 @@ class Config(object): self.save_contexts(ctx_keys, cur_ctx_lines) # exit current context - log.debug("LINE %-50s: exit context %-50s", line, ctx_keys) + log.debug(f"LINE {line:<50}: exit context {' '.join(ctx_keys):<50}") ctx_keys.pop() cur_ctx_keywords.pop() @@ -675,7 +676,7 @@ class Config(object): self.save_contexts(ctx_keys, cur_ctx_lines) # exit current context - log.debug("LINE %-50s: exit context %-50s", line, ctx_keys) + log.debug(f"LINE {line:<50}: exit context {' '.join(ctx_keys):<50}") ctx_keys.pop() cur_ctx_keywords.pop() @@ -706,17 +707,21 @@ class Config(object): cur_ctx_keywords.append(v) cur_ctx_lines = [] - log.debug("LINE %-50s: enter context %-50s", line, ctx_keys) + log.debug( + f"LINE {line:<50}: enter context {' '.join(ctx_keys):<50}" + ) break if new_ctx: continue if len(ctx_keys) == 0: - log.debug("LINE %-50s: single-line context", line) + log.debug(f"LINE {line:<50}: single-line context") self.save_contexts([line], []) else: - log.debug("LINE %-50s: add to current context %-50s", line, ctx_keys) + log.debug( + f"LINE {line:<50}: add to current context {' '.join(ctx_keys):<50}" + ) cur_ctx_lines.append(line) # Save the context of the last one @@ -1711,7 +1716,7 @@ def ignore_unconfigurable_lines(lines_to_add, lines_to_del): ] ] ): - log.info('"%s" cannot be removed' % (ctx_keys[-1],)) + log.info(f'"{ctx_keys[-1]}" cannot be removed') lines_to_del_to_del.append((ctx_keys, line)) for ctx_keys, line in lines_to_del_to_del: @@ -1990,6 +1995,50 @@ def compare_context_objects(newconf, running): return (lines_to_add, lines_to_del) +class LogFmtFormatter(logging.Formatter): + def format(self, record: logging.LogRecord) -> str: + """ + Creates log messages with key=value pairs, in logfmt format. + """ + # Escape double quotes in the message, replace newlines with '\n' + msg = record.getMessage().replace('"', '\\"').replace("\n", "\\n").strip() + # Format the time in RFC 3339 format + timestamp = datetime.datetime.fromtimestamp( + record.created, datetime.timezone.utc + ) + asctime = timestamp.astimezone().isoformat(timespec="seconds") + # Create logfmt style log message, ignore default fields + logfmt = f'ts={asctime} level={record.levelname} msg="{msg}"' + default_fields = [ + "args", + "asctime", + "created", + "exc_info", + "exc_text", + "filename", + "funcName", + "levelname", + "levelno", + "lineno", + "module", + "msecs", + "msg", + "name", + "pathname", + "process", + "processName", + "relativeCreated", + "stack_info", + "thread", + "threadName", + ] + for key, value in vars(record).items(): + if key in default_fields: + continue + logfmt += f" {key}={value}" + return logfmt + + if __name__ == "__main__": # Command line options parser = argparse.ArgumentParser( @@ -2057,15 +2106,24 @@ if __name__ == "__main__": action="store_true", help="Used by topotest to not delete debug or log file commands", ) + parser.add_argument( + "--logfmt", + action="store_true", + help="Use logfmt as log format", + default=False, + ) args = parser.parse_args() # Logging # For --test log to stdout # For --reload log to /var/log/frr/frr-reload.log - if args.test or args.stdout: - logging.basicConfig(format="%(asctime)s %(levelname)5s: %(message)s") - + # If --logfmt, use the logfmt format + formatter = logging.Formatter("%(asctime)s %(levelname)5s: %(message)s") + handler = logging.StreamHandler() + if args.logfmt: + formatter = LogFmtFormatter() + elif args.test or args.stdout: # Color the errors and warnings in red logging.addLevelName( logging.ERROR, "\033[91m %s\033[0m" % logging.getLevelName(logging.ERROR) @@ -2073,20 +2131,15 @@ if __name__ == "__main__": logging.addLevelName( logging.WARNING, "\033[91m%s\033[0m" % logging.getLevelName(logging.WARNING) ) - - elif args.reload: + if args.reload: if not os.path.isdir("/var/log/frr/"): os.makedirs("/var/log/frr/", mode=0o0755) - - logging.basicConfig( - filename="/var/log/frr/frr-reload.log", - format="%(asctime)s %(levelname)5s: %(message)s", - ) - - # argparse should prevent this from happening but just to be safe... - else: - raise Exception("Must specify --reload or --test") + handler = logging.FileHandler("/var/log/frr/frr-reload.log") + if args.stdout: + handler = logging.StreamHandler(sys.stdout) + handler.setFormatter(formatter) log = logging.getLogger(__name__) + log.addHandler(handler) if args.debug: log.setLevel(logging.DEBUG) @@ -2106,26 +2159,26 @@ if __name__ == "__main__": # Verify the new config file is valid if not os.path.isfile(args.filename): - log.error("Filename %s does not exist" % args.filename) + log.error(f"Filename {args.filename} does not exist") sys.exit(1) if not os.path.getsize(args.filename): - log.error("Filename %s is an empty file" % args.filename) + log.error(f"Filename {args.filename} is an empty file") sys.exit(1) # Verify that confdir is correct if not os.path.isdir(args.confdir): - log.error("Confdir %s is not a valid path" % args.confdir) + log.error(f"Confdir {args.confdir} is not a valid path") sys.exit(1) # Verify that bindir is correct if not os.path.isdir(args.bindir) or not os.path.isfile(args.bindir + "/vtysh"): - log.error("Bindir %s is not a valid path to vtysh" % args.bindir) + log.error(f"Bindir {args.bindir} is not a valid path to vtysh") sys.exit(1) # verify that the vty_socket, if specified, is valid if args.vty_socket and not os.path.isdir(args.vty_socket): - log.error("vty_socket %s is not a valid path" % args.vty_socket) + log.error(f"vty_socket {args.vty_socket} is not a valid path") sys.exit(1) # verify that the daemon, if specified, is valid @@ -2180,7 +2233,7 @@ if __name__ == "__main__": ) sys.exit(1) - log.info('Called via "%s"', str(args)) + log.info(f'Called via "{args}"') # Create a Config object from the config generated by newconf newconf = Config(vtysh) @@ -2256,7 +2309,7 @@ if __name__ == "__main__": if not vtysh.is_config_available() or not reload_ok: sys.exit(1) - log.debug("New Frr Config\n%s", newconf.get_lines()) + log.debug(f"New Frr Config\n{newconf.get_lines()}") # This looks a little odd but we have to do this twice...here is why # If the user had this running bgp config: @@ -2298,7 +2351,7 @@ if __name__ == "__main__": for x in range(2): running = Config(vtysh) running.load_from_show_running(args.daemon) - log.debug("Running Frr Config (Pass #%d)\n%s", x, running.get_lines()) + log.debug(f"Running Frr Config (Pass #{x})\n{running.get_lines()}") (lines_to_add, lines_to_del) = compare_context_objects(newconf, running) @@ -2355,7 +2408,7 @@ if __name__ == "__main__": # 'no ip ospf authentication message-digest 1.1.1.1' in # our example above # - Split that last entry by whitespace and drop the last word - log.error("Failed to execute %s", " ".join(cmd)) + log.error(f"Failed to execute {' '.join(cmd)}") last_arg = cmd[-1].split(" ") if len(last_arg) <= 2: @@ -2372,7 +2425,7 @@ if __name__ == "__main__": new_last_arg = last_arg[0:-1] cmd[-1] = " ".join(new_last_arg) else: - log.info('Executed "%s"', " ".join(cmd)) + log.info(f'Executed "{" ".join(cmd)}"') break if lines_to_add: @@ -2399,7 +2452,7 @@ if __name__ == "__main__": ) filename = args.rundir + "/reload-%s.txt" % random_string - log.info("%s content\n%s" % (filename, pformat(lines_to_configure))) + log.info(f"{filename} content\n{pformat(lines_to_configure)}") with open(filename, "w") as fh: for line in lines_to_configure: @@ -2408,7 +2461,7 @@ if __name__ == "__main__": try: vtysh.exec_file(filename) except VtyshException as e: - log.warning("frr-reload.py failed due to\n%s" % e.args) + log.warning(f"frr-reload.py failed due to\n{e.args}") reload_ok = False os.unlink(filename)