Moulinette logging is an unecessarily complex mess, episode 57682

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()
+                logger.debug("processing action '%s'", full_action_name)
-                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)
 
                 # 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

moulinette/interfaces/__init__.py

@@ -33,8 +33,7 @@ class BaseActionsMapParser:
     """
 
     def __init__(self, parent=None, **kwargs):
-        if not parent:
+        pass
-            logger.debug("initializing base actions map parser for %s", self.interface)
 
     # Virtual properties
     # Each parser classes must implement these properties.

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 and record.levelname in ["SUCCESS", "WARNING", "ERROR", "INFO"]:
-            if self.level <= log.DEBUG:
+                level = m18n.g(record.levelname.lower())
-                # 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())
             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__["level_with_color"] = level_with_color
-            record.__dict__[self.message_key] = msg
             return self.formatter.format(record)
-        return msg
+        return level_with_color + " " + msg
 
     def emit(self, record):
         # set proper stream first

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