changeset 3280:96b9b65b4368

core (log): logging with Twisted now uses the new twisted.logger
author Goffi <goffi@goffi.org>
date Mon, 25 May 2020 15:46:21 +0200
parents 8de63fe6b5c9
children a3639d6d9643
files sat/core/log.py sat/core/log_config.py
diffstat 2 files changed, 51 insertions(+), 144 deletions(-) [+]
line wrap: on
line diff
--- a/sat/core/log.py	Tue May 19 18:34:06 2020 +0200
+++ b/sat/core/log.py	Mon May 25 15:46:21 2020 +0200
@@ -37,7 +37,7 @@
     pass
 
 
-class Logger(object):
+class Logger:
     """High level logging class"""
     fmt = None # format option as given by user (e.g. SAT_LOG_LOGGER)
     filter_name = None # filter to call
@@ -163,7 +163,7 @@
         return self.filter(log_record) == 1
 
 
-class ConfigureBase(object):
+class ConfigureBase:
     LOGGER_CLASS = Logger
     # True if color location is specified in fmt (with COLOR_START)
     _color_location = False
--- a/sat/core/log_config.py	Tue May 19 18:34:06 2020 +0200
+++ b/sat/core/log_config.py	Mon May 25 15:46:21 2020 +0200
@@ -29,20 +29,22 @@
     force_colors = False
 
     def __init__(self, *args, **kwargs):
-        super(TwistedLogger, self).__init__(*args, **kwargs)
-        from twisted.python import log as twisted_log
-
-        self.twisted_log = twisted_log
+        super().__init__(*args, **kwargs)
+        from twisted.logger import Logger
+        self.twisted_log = Logger()
 
     def out(self, message, level=None, **kwargs):
         """Actually log the message
 
         @param message: formatted message
         """
-        if kwargs.get('exc_info', False):
+        if kwargs.pop('exc_info', False):
             message = self.addTraceback(message)
-        self.twisted_log.msg(
-            message.encode("utf-8", "ignore"), sat_logged=True, level=level
+        self.twisted_log.emit(
+            level=self.level_map[level],
+            format=message,
+            sat_logged=True,
+            **kwargs,
         )
 
 
@@ -107,148 +109,52 @@
 class ConfigureTwisted(ConfigureBasic):
     LOGGER_CLASS = TwistedLogger
 
-    def changeObserver(self, observer, can_colors=False):
-        """Install a hook on observer to manage SàT specificities
-
-        @param observer: original observer to hook
-        @param can_colors: True if observer can display ansi colors
-        """
-
-        def observer_hook(event):
-            """redirect non SàT log to twisted_logger, and add colors when possible"""
-            if (
-                "sat_logged" in event
-            ):  # we only want our own logs, other are managed by twistedObserver
-                # we add colors if possible
-                if (
-                    can_colors and self.LOGGER_CLASS.colors
-                ) or self.LOGGER_CLASS.force_colors:
-                    message = event.get("message", tuple())
-                    if message:
-                        event["message"] = (b"".join(message),)  # must be a tuple
-                observer(event)  # we can now call the original observer
-
-        return observer_hook
-
-    def changeFileLogObserver(self, observer):
-        """Install SàT hook for FileLogObserver
-
-        if the output is a tty, we allow colors, else we don't
-        @param observer: original observer to hook
-        """
-        log_obs = observer.__self__
-        log_file = log_obs.write.__self__
-        try:
-            can_colors = log_file.isatty()
-        except AttributeError:
-            can_colors = False
-        return self.changeObserver(observer, can_colors=can_colors)
-
-    def installObserverHook(self, observer):
-        """Check observer type and install SàT hook when possible
-
-        @param observer: observer to hook
-        @return: hooked observer or original one
-        """
-        if hasattr(observer, "__self__"):
-            ori = observer
-            if isinstance(observer.__self__, self.twisted_log.FileLogObserver):
-                observer = self.changeFileLogObserver(observer)
-            elif isinstance(observer.__self__, self.twisted_log.DefaultObserver):
-                observer = self.changeObserver(observer, can_colors=True)
-            else:
-                # we use print because log system is not fully initialized
-                print(("Unmanaged observer [%s]" % observer))
-                return observer
-            self.observers[ori] = observer
-        return observer
-
     def preTreatment(self):
-        """initialise needed attributes, and install observers hooks"""
-        self.observers = {}
-        from twisted.python import log as twisted_log
-
-        self.twisted_log = twisted_log
-        self.log_publisher = twisted_log.msg.__self__
-
-        def addObserverObserver(self_logpub, other):
-            """Install hook so we know when a new observer is added"""
-            other = self.installObserverHook(other)
-            return self_logpub._originalAddObserver(other)
-
-        def removeObserverObserver(self_logpub, ori):
-            """removeObserver hook fix
-
-            As we wrap the original observer, the original removeObserver may want to remove the original object instead of the wrapper, this method fix this
-            """
-            if ori in self.observers:
-                self_logpub._originalRemoveObserver(self.observers[ori])
-            else:
-                try:
-                    self_logpub._originalRemoveObserver(ori)
-                except ValueError:
-                    try:
-                        ori in self.cleared_observers
-                    except AttributeError:
-                        raise ValueError("Unknown observer")
-
-        # we replace addObserver/removeObserver by our own
-        twisted_log.LogPublisher._originalAddObserver = (
-            twisted_log.LogPublisher.addObserver
-        )
-        twisted_log.LogPublisher._originalRemoveObserver = (
-            twisted_log.LogPublisher.removeObserver
-        )
-        import types  # see https://stackoverflow.com/a/4267590 (thx Chris Morgan/aaronasterling)
-
-        twisted_log.addObserver = types.MethodType(
-            addObserverObserver, self.log_publisher
-        )
-        twisted_log.removeObserver = types.MethodType(
-            removeObserverObserver, self.log_publisher
-        )
-
-        # we now change existing observers
-        for idx, observer in enumerate(self.log_publisher.observers):
-            self.log_publisher.observers[idx] = self.installObserverHook(observer)
+        from twisted import logger
+        global logger
+        self.level_map = {
+            C.LOG_LVL_DEBUG: logger.LogLevel.debug,
+            C.LOG_LVL_INFO: logger.LogLevel.info,
+            C.LOG_LVL_WARNING: logger.LogLevel.warn,
+            C.LOG_LVL_ERROR: logger.LogLevel.error,
+            C.LOG_LVL_CRITICAL: logger.LogLevel.critical,
+        }
+        self.LOGGER_CLASS.level_map = self.level_map
 
     def configureLevel(self, level):
-        self.LOGGER_CLASS.level = level
-        super(ConfigureTwisted, self).configureLevel(level)
+        self.level = self.level_map[level]
 
     def configureOutput(self, output):
         import sys
+        from twisted.python import logfile
+        self.log_publisher = logger.LogPublisher()
 
         if output is None:
             output = C.LOG_OPT_OUTPUT_SEP + C.LOG_OPT_OUTPUT_DEFAULT
         self.manageOutputs(output)
-        addObserver = self.twisted_log.addObserver
 
         if C.LOG_OPT_OUTPUT_DEFAULT in log.handlers:
-            # default output is already managed, we just add output to stdout if we are in debug or nodaemon mode
             if self.backend_data is None:
                 raise ValueError(
                     "You must pass options as backend_data with Twisted backend"
                 )
             options = self.backend_data
+            log_file = logfile.LogFile.fromFullPath(options['logfile'])
+            self.log_publisher.addObserver(
+                logger.FileLogObserver(log_file, self.textFormatter))
+            # we also want output to stdout if we are in debug or nodaemon mode
             if options.get("nodaemon", False) or options.get("debug", False):
-                addObserver(self.twisted_log.FileLogObserver(sys.stdout).emit)
-        else:
-            # \\default is not in the output, so we remove current observers
-            self.cleared_observers = self.log_publisher.observers
-            self.observers.clear()
-            del self.log_publisher.observers[:]
-            # and we forbid twistd to add any observer
-            self.twisted_log.addObserver = lambda other: None
+                self.log_publisher.addObserver(
+                    logger.FileLogObserver(sys.stdout, self.textFormatter))
 
         if C.LOG_OPT_OUTPUT_FILE in log.handlers:
-            from twisted.python import logfile
 
             for path in log.handlers[C.LOG_OPT_OUTPUT_FILE]:
                 log_file = (
                     sys.stdout if path == "-" else logfile.LogFile.fromFullPath(path)
                 )
-                addObserver(self.twisted_log.FileLogObserver(log_file).emit)
+                self.log_publisher.addObserver(
+                    logger.FileLogObserver(log_file, self.textFormatter))
 
         if C.LOG_OPT_OUTPUT_MEMORY in log.handlers:
             raise NotImplementedError(
@@ -266,25 +172,26 @@
 
     def postTreatment(self):
         """Install twistedObserver which manage non SàT logs"""
-
-        def twistedObserver(event):
-            """Observer which redirect log message not produced by SàT to SàT logging system"""
-            if not "sat_logged" in event:
-                # this log was not produced by SàT
-                from twisted.python import log as twisted_log
+        # from twisted import logger
+        import sys
+        filtering_obs = logger.FilteringLogObserver(
+            observer=self.log_publisher,
+            predicates=[
+                logger.LogLevelFilterPredicate(self.level),
+                ]
+        )
+        logger.globalLogBeginner.beginLoggingTo([filtering_obs])
 
-                text = twisted_log.textFromEventDict(event)
-                if text is None:
-                    return
-                twisted_logger = log.getLogger(C.LOG_TWISTED_LOGGER)
-                log_method = (
-                    twisted_logger.error
-                    if event.get("isError", False)
-                    else twisted_logger.info
-                )
-                log_method(text)
-
-        self.log_publisher._originalAddObserver(twistedObserver)
+    def textFormatter(self, event):
+        if event.get('sat_logged', False):
+            timestamp = ''.join([logger.formatTime(event.get("log_time", None)), " "])
+            return f"{timestamp}{event.get('log_format', '')}\n"
+        else:
+            eventText = logger.eventAsText(
+                event, includeSystem=True)
+            if not eventText:
+                return None
+            return eventText.replace("\n", "\n\t") + "\n"
 
 
 class ConfigureStandard(ConfigureBasic):