Merge pull request #650 from EDCD/enhancement/logging-found-plugins

Ensure all plugins have correct logging from core code

EDMCLogging.py

@@ -1,4 +1,6 @@
 """
+Set up required logging for the application.
+
 This module provides for a common logging-powered log facility.
 Mostly it implements a logging.Filter() in order to get two extra
 members on the logging.LogRecord instance for use in logging.Formatter()
@@ -9,8 +11,10 @@ strings.
 from sys import _getframe as getframe
 import inspect
 import logging
+import pathlib
 from typing import Tuple
 
+from config import config
 
 # TODO: Tests:
 #
@@ -35,6 +39,8 @@ from typing import Tuple
 #
 #      14. Call from *package*
 
+_default_loglevel = logging.DEBUG
+
 
 class Logger:
     """
@@ -47,9 +53,11 @@ class Logger:
     Users of this class should then call getLogger() to get the
     logging.Logger instance.
     """
-    def __init__(self, logger_name: str, loglevel: int = logging.DEBUG):
+
+    def __init__(self, logger_name: str, loglevel: int = _default_loglevel):
         """
         Set up a `logging.Logger` with our preferred configuration.
+
         This includes using an EDMCContextFilter to add 'class' and 'qualname'
         expansions for logging.Formatter().
         """
@@ -64,7 +72,7 @@ class Logger:
         self.logger_channel = logging.StreamHandler()
         self.logger_channel.setLevel(loglevel)
 
-        self.logger_formatter = logging.Formatter('%(asctime)s - %(name)s - %(levelname)s - %(module)s.%(qualname)s:%(lineno)d: %(class)s: %(message)s')  # noqa: E501
+        self.logger_formatter = logging.Formatter('%(asctime)s - %(levelname)s - %(module)s.%(qualname)s:%(lineno)d: %(message)s')  # noqa: E501
         self.logger_formatter.default_time_format = '%Y-%m-%d %H:%M:%S'
         self.logger_formatter.default_msec_format = '%s.%03d'
 
@@ -73,19 +81,53 @@ class Logger:
 
     def get_logger(self) -> logging.Logger:
         """
-        :return: The logging.Logger instance.
+        Obtain the self.logger of the class instance.
+
+        Not to be confused with logging.getLogger().
         """
         return self.logger
 
 
+def get_plugin_logger(name: str, loglevel: int = _default_loglevel) -> logging.Logger:
+    """
+    Return a logger suitable for a plugin.
+
+    'Found' plugins need their own logger to call out where the logging is
+    coming from, but we don't need to set up *everything* for them.
+
+    The name will be '{config.appname}.{plugin.name}', e.g.
+    'EDMarketConnector.miggytest'.  This means that any logging sent through
+    there *also* goes to the channels defined in the 'EDMarketConnector'
+    logger, so we can let that take care of the formatting.
+
+    If we add our own channel then the output gets duplicated (assuming same
+    logLevel set).
+
+    However we do need to attach our filter to this still.  That's not at
+    the channel level.
+    :param name: Name of this Logger.
+    :param loglevel: Optional logLevel for this Logger.
+    :return: logging.Logger instance, all set up.
+    """
+    plugin_logger = logging.getLogger(name)
+    plugin_logger.setLevel(loglevel)
+
+    plugin_logger.addFilter(EDMCContextFilter())
+
+    return plugin_logger
+
+
 class EDMCContextFilter(logging.Filter):
     """
+    Implements filtering to add extra format specifiers, and tweak others.
+
     logging.Filter sub-class to place extra attributes of the calling site
     into the record.
     """
+
     def filter(self, record: logging.LogRecord) -> bool:
         """
-        Attempt to set the following in the LogRecord:
+        Attempt to set/change fields in the LogRecord.
 
         1. class = class name(s) of the call site, if applicable
         2. qualname = __qualname__ of the call site.  This simplifies
@@ -102,10 +144,11 @@ class EDMCContextFilter(logging.Filter):
         :param record: The LogRecord we're "filtering"
         :return: bool - Always true in order for this record to be logged.
         """
-        class_name = qualname = ''
+        (class_name, qualname, module_name) = self.caller_attributes(module_name=getattr(record, 'module'))
-        # Don't even call in if both already set.
+
-        if not getattr(record, 'class', None) or not getattr(record, 'qualname', None):
+        # Only set if we got a useful value
-            (class_name, qualname) = self.caller_class_and_qualname()
+        if module_name:
+            setattr(record, 'module', module_name)
 
         # Only set if not already provided by logging itself
         if getattr(record, 'class', None) is None:
@@ -117,40 +160,26 @@ class EDMCContextFilter(logging.Filter):
 
         return True
 
-    @classmethod
+    @classmethod  # noqa: CCR001 - this is as refactored as is sensible
-    def caller_class_and_qualname(cls) -> Tuple[str, str]:
+    def caller_attributes(cls, module_name: str = '') -> Tuple[str, str, str]:
         """
-        Figure out our caller's class name(s) and qualname
+        Determine extra or changed fields for the caller.
 
-        Ref: <https://gist.github.com/techtonik/2151726#gistcomment-2333747>
+        1. qualname finds the relevant object and its __qualname__
-
+        2. caller_class_names is just the full class names of the calling
-        :return: Tuple[str, str]: The caller's class name(s) and qualname
+         class if relevant.
+        3. module is munged if we detect the caller is an EDMC plugin,
+         whether internal or found.
         """
-        # Go up through stack frames until we find the first with a
+        frame = cls.find_caller_frame()
-        # type(f_locals.self) of logging.Logger.  This should be the start
-        # of the frames internal to logging.
-        frame: 'frame' = getframe(0)
-        while frame:
-            if isinstance(frame.f_locals.get('self'), logging.Logger):
-                frame = frame.f_back  # Want to start on the next frame below
-                break
-            frame = frame.f_back
-
-        # Now continue up through frames until we find the next one where
-        # that is *not* true, as it should be the call site of the logger
-        # call
-        while frame:
-            if not isinstance(frame.f_locals.get('self'), logging.Logger):
-                break  # We've found the frame we want
-            frame = frame.f_back
 
         caller_qualname = caller_class_names = ''
         if frame:
             # <https://stackoverflow.com/questions/2203424/python-how-to-retrieve-class-information-from-a-frame-object#2220759>
             frame_info = inspect.getframeinfo(frame)
             args, _, _, value_dict = inspect.getargvalues(frame)
-            if len(args) and args[0] == 'self':
+            if len(args) and args[0] in ('self', 'cls'):
-                frame_class = value_dict['self']
+                frame_class = value_dict[args[0]]
 
                 if frame_class:
                     # Find __qualname__ of the caller
@@ -171,6 +200,8 @@ class EDMCContextFilter(logging.Filter):
                 caller_class_names = '<none>'
                 caller_qualname = frame_info.function
 
+            module_name = cls.munge_module_name(frame_info, module_name)
+
             # https://docs.python.org/3.7/library/inspect.html#the-interpreter-stack
             del frame
 
@@ -182,4 +213,81 @@ class EDMCContextFilter(logging.Filter):
             print('ALERT!  Something went wrong with finding caller class name(s) for logging!')
             caller_class_names = '<ERROR in EDMCLogging.caller_class_and_qualname() for "class">'
 
-        return caller_class_names, caller_qualname
+        return caller_class_names, caller_qualname, module_name
+
+    @classmethod
+    def find_caller_frame(cls):
+        """
+        Find the stack frame of the logging caller.
+
+        :returns: 'frame' object such as from sys._getframe()
+        """
+        # Go up through stack frames until we find the first with a
+        # type(f_locals.self) of logging.Logger.  This should be the start
+        # of the frames internal to logging.
+        frame: 'frame' = getframe(0)
+        while frame:
+            if isinstance(frame.f_locals.get('self'), logging.Logger):
+                frame = frame.f_back  # Want to start on the next frame below
+                break
+            frame = frame.f_back
+        # Now continue up through frames until we find the next one where
+        # that is *not* true, as it should be the call site of the logger
+        # call
+        while frame:
+            if not isinstance(frame.f_locals.get('self'), logging.Logger):
+                break  # We've found the frame we want
+            frame = frame.f_back
+        return frame
+
+    @classmethod
+    def munge_module_name(cls, frame_info: inspect.Traceback, module_name: str) -> str:
+        """
+        Adjust module_name based on the file path for the given frame.
+
+        We want to distinguish between other code and both our internal plugins
+        and the 'found' ones.
+
+        For internal plugins we want "plugins.<filename>".
+        For 'found' plugins we want "<plugins>.<plugin_name>...".
+
+        :param frame_info: The frame_info of the caller.
+        :param module_name: The module_name string to munge.
+        :return: The munged module_name.
+        """
+        file_name = pathlib.Path(frame_info.filename).expanduser()
+        plugin_dir = pathlib.Path(config.plugin_dir).expanduser()
+        internal_plugin_dir = pathlib.Path(config.internal_plugin_dir).expanduser()
+        # Find the first parent called 'plugins'
+        plugin_top = file_name
+        while plugin_top and plugin_top.name != '':
+            if plugin_top.parent.name == 'plugins':
+                break
+
+            plugin_top = plugin_top.parent
+
+        # Check we didn't walk up to the root/anchor
+        if plugin_top.name != '':
+            # Check we're still inside config.plugin_dir
+            if plugin_top.parent == plugin_dir:
+                # In case of deeper callers we need a range of the file_name
+                pt_len = len(plugin_top.parts)
+                name_path = '.'.join(file_name.parts[(pt_len - 1):-1])
+                module_name = f'<plugins>.{name_path}.{module_name}'
+
+            # Check we're still inside the installation folder.
+            elif file_name.parent == internal_plugin_dir:
+                # Is this a deeper caller ?
+                pt_len = len(plugin_top.parts)
+                name_path = '.'.join(file_name.parts[(pt_len - 1):-1])
+
+                # Pre-pend 'plugins.<plugin folder>.' to module
+                if name_path == '':
+                    # No sub-folder involved so module_name is sufficient
+                    module_name = f'plugins.{module_name}'
+
+                else:
+                    # Sub-folder(s) involved, so include them
+                    module_name = f'plugins.{name_path}.{module_name}'
+
+        return module_name

plug.py

@@ -8,12 +8,14 @@ import importlib
 import sys
 import operator
 import threading  # noqa: F401 - We don't use it, but plugins might
+from typing import Optional
 import logging
 import tkinter as tk
 
 import myNotebook as nb  # noqa: N813
 
 from config import config, appname
+import EDMCLogging
 
 logger = logging.getLogger(appname)
 
@@ -79,7 +81,7 @@ last_error = {
 
 class Plugin(object):
 
-    def __init__(self, name, loadfile):
+    def __init__(self, name: str, loadfile: str, plugin_logger: Optional[logging.Logger]):
         """
         Load a single plugin
         :param name: module name
@@ -90,6 +92,7 @@ class Plugin(object):
         self.name = name  # Display name.
         self.folder = name  # basename of plugin folder. None for internal plugins.
         self.module = None  # None for disabled plugins.
+        self.logger = plugin_logger
 
         if loadfile:
             logger.info(f'loading plugin "{name.replace(".", "_")}" from "{loadfile}"')
@@ -173,7 +176,7 @@ def load_plugins(master):
     for name in sorted(os.listdir(config.internal_plugin_dir)):
         if name.endswith('.py') and not name[0] in ['.', '_']:
             try:
-                plugin = Plugin(name[:-3], os.path.join(config.internal_plugin_dir, name))
+                plugin = Plugin(name[:-3], os.path.join(config.internal_plugin_dir, name), logger)
                 plugin.folder = None  # Suppress listing in Plugins prefs tab
                 internal.append(plugin)
             except Exception as e:
@@ -191,12 +194,17 @@ def load_plugins(master):
             pass
         elif name.endswith('.disabled'):
             name, discard = name.rsplit('.', 1)
-            found.append(Plugin(name, None))
+            found.append(Plugin(name, None, logger))
         else:
             try:
                 # Add plugin's folder to load path in case plugin has internal package dependencies
                 sys.path.append(os.path.join(config.plugin_dir, name))
-                found.append(Plugin(name, os.path.join(config.plugin_dir, name, 'load.py')))
+
+                # Create a logger for this 'found' plugin.  Must be before the
+                # load.py is loaded.
+                plugin_logger = EDMCLogging.get_plugin_logger(f'{appname}.{name}')
+
+                found.append(Plugin(name, os.path.join(config.plugin_dir, name, 'load.py'), plugin_logger))
             except Exception as e:
                 logger.exception(f'Failure loading found Plugin "{name}"')
                 pass