From 0f056d66d7572eb070a0ebf5be591503b9dbacd5 Mon Sep 17 00:00:00 2001 From: Alexandre Aubin Date: Tue, 18 Jul 2023 00:20:24 +0200 Subject: [PATCH] Moulinette logging is an unecessarily complex mess, episode 57682 --- moulinette/actionsmap.py | 19 +------- moulinette/interfaces/__init__.py | 3 +- moulinette/interfaces/cli.py | 22 ++++----- moulinette/utils/log.py | 81 ++----------------------------- 4 files changed, 16 insertions(+), 109 deletions(-) diff --git a/moulinette/actionsmap.py b/moulinette/actionsmap.py index e5e9547b..c213ab2e 100644 --- a/moulinette/actionsmap.py +++ b/moulinette/actionsmap.py @@ -19,7 +19,6 @@ from moulinette.core import ( MoulinetteValidationError, ) from moulinette.interfaces import BaseActionsMapParser -from moulinette.utils.log import start_action_logging from moulinette.utils.filesystem import read_yaml logger = logging.getLogger("moulinette.actionsmap") @@ -398,8 +397,6 @@ class ActionsMap: self.from_cache = False - logger.debug("loading actions map") - actionsmap_yml_dir = os.path.dirname(actionsmap_yml) actionsmap_yml_file = os.path.basename(actionsmap_yml) actionsmap_yml_stat = os.stat(actionsmap_yml) @@ -562,17 +559,7 @@ class ActionsMap: logger.exception(error_message) raise MoulinetteError(error_message, raw_msg=True) else: - log_id = start_action_logging() - if logger.isEnabledFor(logging.DEBUG): - # Log arguments in debug mode only for safety reasons - logger.debug( - "processing action [%s]: %s with args=%s", - log_id, - full_action_name, - arguments, - ) - else: - logger.debug("processing action [%s]: %s", log_id, full_action_name) + logger.debug("processing action '%s'", full_action_name) # Load translation and process the action start = time() @@ -580,7 +567,7 @@ class ActionsMap: return func(**arguments) finally: stop = time() - logger.debug("action [%s] executed in %.3fs", log_id, stop - start) + logger.debug("action executed in %.3fs", stop - start) # Private methods @@ -598,7 +585,6 @@ class ActionsMap: """ - logger.debug("building parser...") start = time() interface_type = top_parser.interface @@ -717,5 +703,4 @@ class ActionsMap: else: action_parser.want_to_take_lock = True - logger.debug("building parser took %.3fs", time() - start) return top_parser diff --git a/moulinette/interfaces/__init__.py b/moulinette/interfaces/__init__.py index 54776552..73d75f1e 100644 --- a/moulinette/interfaces/__init__.py +++ b/moulinette/interfaces/__init__.py @@ -33,8 +33,7 @@ class BaseActionsMapParser: """ def __init__(self, parent=None, **kwargs): - if not parent: - logger.debug("initializing base actions map parser for %s", self.interface) + pass # Virtual properties # Each parser classes must implement these properties. diff --git a/moulinette/interfaces/cli.py b/moulinette/interfaces/cli.py index 84e72185..f1005558 100644 --- a/moulinette/interfaces/cli.py +++ b/moulinette/interfaces/cli.py @@ -235,28 +235,26 @@ class TTYHandler(logging.StreamHandler): log.CRITICAL: "red", } - def __init__(self, message_key="fmessage"): + def __init__(self, message_key="message_with_color"): logging.StreamHandler.__init__(self) self.message_key = message_key def format(self, record): """Enhance message with level and colors if supported.""" msg = record.getMessage() + level = record.levelname + level_with_color = level if self.supports_color(): - level = "" - if self.level <= log.DEBUG: - # add level name before message - level = "%s " % record.levelname - elif record.levelname in ["SUCCESS", "WARNING", "ERROR", "INFO"]: - # add translated level name before message - level = "%s " % m18n.g(record.levelname.lower()) + if self.level > log.DEBUG and record.levelname in ["SUCCESS", "WARNING", "ERROR", "INFO"]: + level = m18n.g(record.levelname.lower()) color = self.LEVELS_COLOR.get(record.levelno, "white") - msg = "{}{}{}{}".format(colors_codes[color], level, END_CLI_COLOR, msg) + level_with_color = f"{colors_codes[color]}{level}{END_CLI_COLOR}" + if self.level == log.DEBUG: + level_with_color = level_with_color + " " * max(0, 7 - len(level)) if self.formatter: - # use user-defined formatter - record.__dict__[self.message_key] = msg + record.__dict__["level_with_color"] = level_with_color return self.formatter.format(record) - return msg + return level_with_color + " " + msg def emit(self, record): # set proper stream first diff --git a/moulinette/utils/log.py b/moulinette/utils/log.py index 02f8a30a..3d010726 100644 --- a/moulinette/utils/log.py +++ b/moulinette/utils/log.py @@ -110,89 +110,14 @@ class MoulinetteLogger(Logger): f = currentframe() if f is not None: f = f.f_back - rv = "(unknown file)", 0, "(unknown function)" + rv = "(unknown file)", 0, "(unknown function)", None while hasattr(f, "f_code"): co = f.f_code filename = os.path.normcase(co.co_filename) if filename == _srcfile or filename == __file__: f = f.f_back continue - rv = (co.co_filename, f.f_lineno, co.co_name) + rv = (co.co_filename, f.f_lineno, co.co_name, None) break + return rv - - def _log(self, *args, **kwargs): - """Append action_id if available to the extra.""" - if self.action_id is not None: - extra = kwargs.get("extra", {}) - if "action_id" not in extra: - # FIXME: Get real action_id instead of logger/current one - extra["action_id"] = _get_action_id() - kwargs["extra"] = extra - return super()._log(*args, **kwargs) - - -# Action logging ------------------------------------------------------- - -pid = os.getpid() -action_id = 0 - - -def _get_action_id(): - return "%d.%d" % (pid, action_id) - - -def start_action_logging(): - """Configure logging for a new action - - Returns: - The new action id - - """ - global action_id - action_id += 1 - - return _get_action_id() - - -def getActionLogger(name=None, logger=None, action_id=None): - """Get the logger adapter for an action - - Return a logger for the specified name - or use given logger - and - optionally for a given action id, retrieving it if necessary. - - Either a name or a logger must be specified. - - """ - if not name and not logger: - raise ValueError("Either a name or a logger must be specified") - - logger = logger or getLogger(name) - logger.action_id = action_id if action_id else _get_action_id() - return logger - - -class ActionFilter: - - """Extend log record for an optionnal action - - Filter a given record and look for an `action_id` key. If it is not found - and `strict` is True, the record will not be logged. Otherwise, the key - specified by `message_key` will be added to the record, containing the - message formatted for the action or just the original one. - - """ - - def __init__(self, message_key="fmessage", strict=False): - self.message_key = message_key - self.strict = strict - - def filter(self, record): - msg = record.getMessage() - action_id = record.__dict__.get("action_id", None) - if action_id is not None: - msg = "[{:s}] {:s}".format(action_id, msg) - elif self.strict: - return False - record.__dict__[self.message_key] = msg - return True