From 898ff9fbb2548bb4aa55aa446ba911e20a451ac5 Mon Sep 17 00:00:00 2001 From: Athanasius Date: Thu, 30 Jul 2020 15:33:55 +0100 Subject: [PATCH 01/11] Logging: Make correct loggers for 'found' plugins * Log messages propagate up Parent.Child chains, so we don't need a channel on the plugin logger. * But it still needs the filter to define qualname and class for formatting. --- EDMCLogging.py | 31 ++++++++++++++++++++++++++++++- plug.py | 16 ++++++++++++---- 2 files changed, 42 insertions(+), 5 deletions(-) diff --git a/EDMCLogging.py b/EDMCLogging.py index 15a29286..7ad069a1 100644 --- a/EDMCLogging.py +++ b/EDMCLogging.py @@ -35,6 +35,8 @@ from typing import Tuple # # 14. Call from *package* +_default_loglevel = logging.DEBUG + class Logger: """ @@ -47,7 +49,7 @@ 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' @@ -78,6 +80,33 @@ class Logger: return self.logger +def get_plugin_logger(name: str, loglevel: int = _default_loglevel) -> logging.Logger: + """ + '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): """ logging.Filter sub-class to place extra attributes of the calling site diff --git a/plug.py b/plug.py index f836d7cd..0a0a3f8a 100644 --- a/plug.py +++ b/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 From 04c4f5e6834907811e242c682119e4479eafdad7 Mon Sep 17 00:00:00 2001 From: Athanasius Date: Thu, 30 Jul 2020 16:29:43 +0100 Subject: [PATCH 02/11] Using a LoggerAdapter to prepend a string. 1. This makes setting up logging everywhere slightly more involved. 2. If I then want to change, say, %(module)s value I'll end up needing to stack walk again. So this might be better done in a filter. But these commits for the record, and to come back to if needs be. --- EDMCLogging.py | 24 ++++++++++++++++-------- EDMarketConnector.py | 2 +- plug.py | 2 +- 3 files changed, 18 insertions(+), 10 deletions(-) diff --git a/EDMCLogging.py b/EDMCLogging.py index 7ad069a1..ecb96050 100644 --- a/EDMCLogging.py +++ b/EDMCLogging.py @@ -9,7 +9,7 @@ strings. from sys import _getframe as getframe import inspect import logging -from typing import Tuple +from typing import Any, MutableMapping, Tuple # TODO: Tests: @@ -55,13 +55,14 @@ class Logger: This includes using an EDMCContextFilter to add 'class' and 'qualname' expansions for logging.Formatter(). """ - self.logger = logging.getLogger(logger_name) + # Using a LoggerAdapter, so make the actual Logger internal + self._logger = logging.getLogger(logger_name) # Configure the logging.Logger - self.logger.setLevel(loglevel) + self._logger.setLevel(loglevel) # Set up filter for adding class name self.logger_filter = EDMCContextFilter() - self.logger.addFilter(self.logger_filter) + self._logger.addFilter(self.logger_filter) self.logger_channel = logging.StreamHandler() self.logger_channel.setLevel(loglevel) @@ -71,16 +72,18 @@ class Logger: self.logger_formatter.default_msec_format = '%s.%03d' self.logger_channel.setFormatter(self.logger_formatter) - self.logger.addHandler(self.logger_channel) + self._logger.addHandler(self.logger_channel) - def get_logger(self) -> logging.Logger: + self.logger = EDMCLoggerAdapter(self._logger, {'from': self.__class__.__qualname__}) + + def get_logger(self) -> logging.LoggerAdapter: """ :return: The logging.Logger instance. """ return self.logger -def get_plugin_logger(name: str, loglevel: int = _default_loglevel) -> logging.Logger: +def get_plugin_logger(name: str, loglevel: int = _default_loglevel) -> logging.LoggerAdapter: """ '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. @@ -104,7 +107,7 @@ def get_plugin_logger(name: str, loglevel: int = _default_loglevel) -> logging.L plugin_logger.addFilter(EDMCContextFilter()) - return plugin_logger + return EDMCLoggerAdapter(plugin_logger, {'from': __name__}) class EDMCContextFilter(logging.Filter): @@ -212,3 +215,8 @@ class EDMCContextFilter(logging.Filter): caller_class_names = '' return caller_class_names, caller_qualname + + +class EDMCLoggerAdapter(logging.LoggerAdapter): + def process(self, msg: Any, kwargs: MutableMapping[str, Any]) -> Tuple[Any, MutableMapping[str, Any]]: + return f'ADAPTED {msg}', kwargs \ No newline at end of file diff --git a/EDMarketConnector.py b/EDMarketConnector.py index 2d1b81b9..c1005a80 100755 --- a/EDMarketConnector.py +++ b/EDMarketConnector.py @@ -1033,7 +1033,7 @@ if __name__ == "__main__": logger = EDMCLogging.Logger(appname).get_logger() # TODO: unittests in place of these - # logger.debug('Test from __main__') + logger.debug('Test from __main__') # test_logging() class A(object): class B(object): diff --git a/plug.py b/plug.py index 0a0a3f8a..8731a173 100644 --- a/plug.py +++ b/plug.py @@ -17,7 +17,7 @@ import myNotebook as nb # noqa: N813 from config import config, appname import EDMCLogging -logger = logging.getLogger(appname) +logger = EDMCLogging.EDMCLoggerAdapter(logging.getLogger(appname), {'from': __name__}) # Dashboard Flags constants FlagsDocked = 1 << 0 # on a landing pad From e5723957189a8c0fa8c987c5db459533bad62d91 Mon Sep 17 00:00:00 2001 From: Athanasius Date: Thu, 30 Jul 2020 16:34:02 +0100 Subject: [PATCH 03/11] LoggerAdapter can't change anything but %(message)s --- EDMCLogging.py | 24 ++++++++---------------- EDMarketConnector.py | 2 +- plug.py | 2 +- 3 files changed, 10 insertions(+), 18 deletions(-) diff --git a/EDMCLogging.py b/EDMCLogging.py index ecb96050..7ad069a1 100644 --- a/EDMCLogging.py +++ b/EDMCLogging.py @@ -9,7 +9,7 @@ strings. from sys import _getframe as getframe import inspect import logging -from typing import Any, MutableMapping, Tuple +from typing import Tuple # TODO: Tests: @@ -55,14 +55,13 @@ class Logger: This includes using an EDMCContextFilter to add 'class' and 'qualname' expansions for logging.Formatter(). """ - # Using a LoggerAdapter, so make the actual Logger internal - self._logger = logging.getLogger(logger_name) + self.logger = logging.getLogger(logger_name) # Configure the logging.Logger - self._logger.setLevel(loglevel) + self.logger.setLevel(loglevel) # Set up filter for adding class name self.logger_filter = EDMCContextFilter() - self._logger.addFilter(self.logger_filter) + self.logger.addFilter(self.logger_filter) self.logger_channel = logging.StreamHandler() self.logger_channel.setLevel(loglevel) @@ -72,18 +71,16 @@ class Logger: self.logger_formatter.default_msec_format = '%s.%03d' self.logger_channel.setFormatter(self.logger_formatter) - self._logger.addHandler(self.logger_channel) + self.logger.addHandler(self.logger_channel) - self.logger = EDMCLoggerAdapter(self._logger, {'from': self.__class__.__qualname__}) - - def get_logger(self) -> logging.LoggerAdapter: + def get_logger(self) -> logging.Logger: """ :return: The logging.Logger instance. """ return self.logger -def get_plugin_logger(name: str, loglevel: int = _default_loglevel) -> logging.LoggerAdapter: +def get_plugin_logger(name: str, loglevel: int = _default_loglevel) -> logging.Logger: """ '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. @@ -107,7 +104,7 @@ def get_plugin_logger(name: str, loglevel: int = _default_loglevel) -> logging.L plugin_logger.addFilter(EDMCContextFilter()) - return EDMCLoggerAdapter(plugin_logger, {'from': __name__}) + return plugin_logger class EDMCContextFilter(logging.Filter): @@ -215,8 +212,3 @@ class EDMCContextFilter(logging.Filter): caller_class_names = '' return caller_class_names, caller_qualname - - -class EDMCLoggerAdapter(logging.LoggerAdapter): - def process(self, msg: Any, kwargs: MutableMapping[str, Any]) -> Tuple[Any, MutableMapping[str, Any]]: - return f'ADAPTED {msg}', kwargs \ No newline at end of file diff --git a/EDMarketConnector.py b/EDMarketConnector.py index c1005a80..2d1b81b9 100755 --- a/EDMarketConnector.py +++ b/EDMarketConnector.py @@ -1033,7 +1033,7 @@ if __name__ == "__main__": logger = EDMCLogging.Logger(appname).get_logger() # TODO: unittests in place of these - logger.debug('Test from __main__') + # logger.debug('Test from __main__') # test_logging() class A(object): class B(object): diff --git a/plug.py b/plug.py index 8731a173..0a0a3f8a 100644 --- a/plug.py +++ b/plug.py @@ -17,7 +17,7 @@ import myNotebook as nb # noqa: N813 from config import config, appname import EDMCLogging -logger = EDMCLogging.EDMCLoggerAdapter(logging.getLogger(appname), {'from': __name__}) +logger = logging.getLogger(appname) # Dashboard Flags constants FlagsDocked = 1 << 0 # on a landing pad From e3b3f1e5b5b5449da93415f6e5c46ce3fdac9fb2 Mon Sep 17 00:00:00 2001 From: Athanasius Date: Thu, 30 Jul 2020 17:37:31 +0100 Subject: [PATCH 04/11] Prepend some useful information to %(module)s if caller is a plugin NB: This assumes only one level within the plugin folder, TODO to fix that. --- EDMCLogging.py | 26 +++++++++++++++++++------- 1 file changed, 19 insertions(+), 7 deletions(-) diff --git a/EDMCLogging.py b/EDMCLogging.py index 7ad069a1..0ecdbe96 100644 --- a/EDMCLogging.py +++ b/EDMCLogging.py @@ -9,8 +9,10 @@ strings. from sys import _getframe as getframe import inspect import logging +import pathlib from typing import Tuple +from config import config # TODO: Tests: # @@ -131,10 +133,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 = '' - # Don't even call in if both already set. - if not getattr(record, 'class', None) or not getattr(record, 'qualname', None): - (class_name, qualname) = self.caller_class_and_qualname() + (class_name, qualname, module_name) = self.caller_attributes(module_name=getattr(record, 'module')) + + # Only set if we got a useful value + if module_name: + setattr(record, 'module', module_name) # Only set if not already provided by logging itself if getattr(record, 'class', None) is None: @@ -147,13 +150,13 @@ class EDMCContextFilter(logging.Filter): return True @classmethod - def caller_class_and_qualname(cls) -> Tuple[str, str]: + def caller_attributes(cls, module_name: str = ''): """ Figure out our caller's class name(s) and qualname Ref: - :return: Tuple[str, str]: The caller's class name(s) and qualname + :return: Tuple[str, str, str]: The caller's class name(s), qualname and module_name """ # Go up through stack frames until we find the first with a # type(f_locals.self) of logging.Logger. This should be the start @@ -200,6 +203,15 @@ class EDMCContextFilter(logging.Filter): caller_class_names = '' caller_qualname = frame_info.function + # TODO: This assumes caller is only one level into the plugin folder + # Need to walk back up checking. + # Is this a 'found' plugin calling us? + file_name = pathlib.Path(frame_info.filename).expanduser() + plugin_dir = pathlib.Path(config.plugin_dir).expanduser() + if file_name.parent.parent == plugin_dir: + # Pre-pend 'plugins..' to module + module_name = f'.{file_name.parent.name}.{module_name}' + # https://docs.python.org/3.7/library/inspect.html#the-interpreter-stack del frame @@ -211,4 +223,4 @@ class EDMCContextFilter(logging.Filter): print('ALERT! Something went wrong with finding caller class name(s) for logging!') caller_class_names = '' - return caller_class_names, caller_qualname + return caller_class_names, caller_qualname, module_name From beea4ef39b7d06af43f7a0167b547bea6cabd0ec Mon Sep 17 00:00:00 2001 From: Athanasius Date: Thu, 30 Jul 2020 17:38:09 +0100 Subject: [PATCH 05/11] Remove %(name)s from logging format as un-necessary. --- EDMCLogging.py | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/EDMCLogging.py b/EDMCLogging.py index 0ecdbe96..4143edff 100644 --- a/EDMCLogging.py +++ b/EDMCLogging.py @@ -68,7 +68,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: %(class)s: %(message)s') # noqa: E501 self.logger_formatter.default_time_format = '%Y-%m-%d %H:%M:%S' self.logger_formatter.default_msec_format = '%s.%03d' From ad021e0765d8591ea09f037fc0486ad87523f2c7 Mon Sep 17 00:00:00 2001 From: Athanasius Date: Thu, 30 Jul 2020 17:39:16 +0100 Subject: [PATCH 06/11] Remove %(class)s from logging format as un-necessary. It was only there to test the code populating it. --- EDMCLogging.py | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/EDMCLogging.py b/EDMCLogging.py index 4143edff..8bba3f13 100644 --- a/EDMCLogging.py +++ b/EDMCLogging.py @@ -68,7 +68,7 @@ class Logger: self.logger_channel = logging.StreamHandler() self.logger_channel.setLevel(loglevel) - self.logger_formatter = logging.Formatter('%(asctime)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' From 89f2726e48dbc44bfa857c072a6dd5098d3d7281 Mon Sep 17 00:00:00 2001 From: Athanasius Date: Thu, 30 Jul 2020 18:04:03 +0100 Subject: [PATCH 07/11] Set internal and found plugin module_name separately. Settled on `plugins..found` as the format. --- EDMCLogging.py | 5 +++++ 1 file changed, 5 insertions(+) diff --git a/EDMCLogging.py b/EDMCLogging.py index 8bba3f13..41f06044 100644 --- a/EDMCLogging.py +++ b/EDMCLogging.py @@ -208,10 +208,15 @@ class EDMCContextFilter(logging.Filter): # Is this a 'found' plugin calling us? 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() + if file_name.parent.parent == plugin_dir: # Pre-pend 'plugins..' to module module_name = f'.{file_name.parent.name}.{module_name}' + elif file_name.parent == internal_plugin_dir: + module_name = f'plugins.{module_name}' + # https://docs.python.org/3.7/library/inspect.html#the-interpreter-stack del frame From 657253b3e35aa5bfd8abfd141a5e31d38c513d0c Mon Sep 17 00:00:00 2001 From: Athanasius Date: Thu, 30 Jul 2020 19:29:12 +0100 Subject: [PATCH 08/11] Set internal and found plugin module_name separately. * Settled on `plugins.internal` and `.found` as the format. * A PyCharm recommendation was to use 'cls' instead of 'self' on class methods, so the class detection code needs to cater for that. Technically a developer could use any string for the "myself" member name, but we'll assume just these two. * Found will always have at least one folder level within plugin_dir * Internal should always have *no* folder within internal_plugin_dir, but cater for it just in case in future. --- EDMCLogging.py | 41 ++++++++++++++++++++++++++++++++++------- 1 file changed, 34 insertions(+), 7 deletions(-) diff --git a/EDMCLogging.py b/EDMCLogging.py index 41f06044..b6cdefe8 100644 --- a/EDMCLogging.py +++ b/EDMCLogging.py @@ -181,8 +181,8 @@ class EDMCContextFilter(logging.Filter): # frame_info = inspect.getframeinfo(frame) args, _, _, value_dict = inspect.getargvalues(frame) - if len(args) and args[0] == 'self': - frame_class = value_dict['self'] + if len(args) and args[0] in ('self', 'cls'): + frame_class = value_dict[args[0]] if frame_class: # Find __qualname__ of the caller @@ -203,6 +203,9 @@ class EDMCContextFilter(logging.Filter): caller_class_names = '' caller_qualname = frame_info.function + ################################################################### + # Fixups for EDMC plugins + ################################################################### # TODO: This assumes caller is only one level into the plugin folder # Need to walk back up checking. # Is this a 'found' plugin calling us? @@ -210,12 +213,36 @@ class EDMCContextFilter(logging.Filter): plugin_dir = pathlib.Path(config.plugin_dir).expanduser() internal_plugin_dir = pathlib.Path(config.internal_plugin_dir).expanduser() - if file_name.parent.parent == plugin_dir: - # Pre-pend 'plugins..' to module - module_name = f'.{file_name.parent.name}.{module_name}' + # Find the first parent called 'plugins' + plugin_top = file_name + while plugin_top and plugin_top.name != '': + if plugin_top.parent.name == 'plugins': + break - elif file_name.parent == internal_plugin_dir: - module_name = f'plugins.{module_name}' + plugin_top = plugin_top.parent + + # Check we didn't walk up to the root/anchor + if plugin_top.name != '': + # And this check means we must still be inside config.app_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'.{name_path}.{module_name}' + + # Or in this case 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..' 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}' + ################################################################### # https://docs.python.org/3.7/library/inspect.html#the-interpreter-stack del frame From 282e3ddbc52b6b0bac608046c5c5c8e1de451fd3 Mon Sep 17 00:00:00 2001 From: Athanasius Date: Thu, 30 Jul 2020 23:59:10 +0100 Subject: [PATCH 09/11] Fix up and expand on docstrings. --- EDMCLogging.py | 46 +++++++++++++++++++++++++++++----------------- 1 file changed, 29 insertions(+), 17 deletions(-) diff --git a/EDMCLogging.py b/EDMCLogging.py index b6cdefe8..c2445c09 100644 --- a/EDMCLogging.py +++ b/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() @@ -51,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 = _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(). """ @@ -77,13 +81,17 @@ 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. @@ -111,24 +119,27 @@ def get_plugin_logger(name: str, loglevel: int = _default_loglevel) -> logging.L 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 - logging.Formatter() as you can use just this no matter if there is - a class involved or not, so you get a nice clean: - .[.classB....]. + 1. class = class name(s) of the call site, if applicable + 2. qualname = __qualname__ of the call site. This simplifies + logging.Formatter() as you can use just this no matter if there is + a class involved or not, so you get a nice clean: + .[.classB....]. If we fail to be able to properly set either then: - 1. Use print() to alert, to be SURE a message is seen. - 2. But also return strings noting the error, so there'll be - something in the log output if it happens. + 1. Use print() to alert, to be SURE a message is seen. + 2. But also return strings noting the error, so there'll be + something in the log output if it happens. :param record: The LogRecord we're "filtering" :return: bool - Always true in order for this record to be logged. @@ -150,13 +161,15 @@ class EDMCContextFilter(logging.Filter): return True @classmethod - def caller_attributes(cls, module_name: 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: - - :return: Tuple[str, str, str]: The caller's class name(s), qualname and module_name + 1. qualname finds the relevant object and its __qualname__ + 2. caller_class_names is just the full class names of the calling + 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 # type(f_locals.self) of logging.Logger. This should be the start @@ -206,8 +219,7 @@ class EDMCContextFilter(logging.Filter): ################################################################### # Fixups for EDMC plugins ################################################################### - # TODO: This assumes caller is only one level into the plugin folder - # Need to walk back up checking. + # TODO: Refactor this bit out into another function # Is this a 'found' plugin calling us? file_name = pathlib.Path(frame_info.filename).expanduser() plugin_dir = pathlib.Path(config.plugin_dir).expanduser() From efe63ceac97a1e0726a76e32575c9c235ec489bb Mon Sep 17 00:00:00 2001 From: Athanasius Date: Fri, 31 Jul 2020 11:20:14 +0100 Subject: [PATCH 10/11] Refactor caller_attributes() code into separate methods * find_caller_frame() to do the frame walk. * munge_module_name() to fix up for plugins. NB: caller_attributes() now has a noqa on CCR001 as I don't think it can sensibly be made any less complex. Pulling out the 'if frame:' section just results in *that* new method then being labelled as too complex.:244 --- EDMCLogging.py | 137 +++++++++++++++++++++++++++++-------------------- 1 file changed, 80 insertions(+), 57 deletions(-) diff --git a/EDMCLogging.py b/EDMCLogging.py index c2445c09..c8710cd0 100644 --- a/EDMCLogging.py +++ b/EDMCLogging.py @@ -160,7 +160,7 @@ class EDMCContextFilter(logging.Filter): return True - @classmethod + @classmethod # noqa: CCR001 - this is as refactored as is sensible def caller_attributes(cls, module_name: str = '') -> Tuple[str, str, str]: """ Determine extra or changed fields for the caller. @@ -171,23 +171,7 @@ class EDMCContextFilter(logging.Filter): 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 - # 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 + frame = cls.find_caller_frame() caller_qualname = caller_class_names = '' if frame: @@ -216,45 +200,7 @@ class EDMCContextFilter(logging.Filter): caller_class_names = '' caller_qualname = frame_info.function - ################################################################### - # Fixups for EDMC plugins - ################################################################### - # TODO: Refactor this bit out into another function - # Is this a 'found' plugin calling us? - 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 != '': - # And this check means we must still be inside config.app_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'.{name_path}.{module_name}' - - # Or in this case 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..' 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}' - ################################################################### + module_name = cls.munge_module_name(frame_info, module_name) # https://docs.python.org/3.7/library/inspect.html#the-interpreter-stack del frame @@ -268,3 +214,80 @@ class EDMCContextFilter(logging.Filter): caller_class_names = '' 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.FrameInfo, 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.". + For 'found' plugins we want "....". + + :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'.{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..' 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 From 3a31139cbdad517be554437cf5daf8bb19a11838 Mon Sep 17 00:00:00 2001 From: Athanasius Date: Fri, 31 Jul 2020 11:41:23 +0100 Subject: [PATCH 11/11] Correct frame_info type --- EDMCLogging.py | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/EDMCLogging.py b/EDMCLogging.py index c8710cd0..81487d8a 100644 --- a/EDMCLogging.py +++ b/EDMCLogging.py @@ -241,7 +241,7 @@ class EDMCContextFilter(logging.Filter): return frame @classmethod - def munge_module_name(cls, frame_info: inspect.FrameInfo, module_name: str) -> str: + 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.