""" 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() strings. """ # So that any warning about accessing a protected member is only in one place. from sys import _getframe as getframe import inspect import logging from typing import Tuple # TODO: Tests: # # 1. Call from bare function in file. # 2. Call from `if __name__ == "__main__":` section # # 3. Call from 1st level function in 1st level Class in file # 4. Call from 2nd level function in 1st level Class in file # 5. Call from 3rd level function in 1st level Class in file # # 6. Call from 1st level function in 2nd level Class in file # 7. Call from 2nd level function in 2nd level Class in file # 8. Call from 3rd level function in 2nd level Class in file # # 9. Call from 1st level function in 3rd level Class in file # 10. Call from 2nd level function in 3rd level Class in file # 11. Call from 3rd level function in 3rd level Class in file # # 12. Call from 2nd level file, all as above. # # 13. Call from *module* # # 14. Call from *package* _default_loglevel = logging.DEBUG class Logger: """ Wrapper class for all logging configuration and code. Class instantiation requires the 'logger name' and optional loglevel. It is intended that this 'logger name' be re-used in all files/modules that need to log. 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(). """ self.logger = logging.getLogger(logger_name) # Configure the logging.Logger self.logger.setLevel(loglevel) # Set up filter for adding class name self.logger_filter = EDMCContextFilter() self.logger.addFilter(self.logger_filter) 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.default_time_format = '%Y-%m-%d %H:%M:%S' self.logger_formatter.default_msec_format = '%s.%03d' self.logger_channel.setFormatter(self.logger_formatter) self.logger.addHandler(self.logger_channel) 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.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 into the record. """ def filter(self, record: logging.LogRecord) -> bool: """ Attempt to set the following 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....]. 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. :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() # Only set if not already provided by logging itself if getattr(record, 'class', None) is None: setattr(record, 'class', class_name) # Only set if not already provided by logging itself if getattr(record, 'qualname', None) is None: setattr(record, 'qualname', qualname) return True @classmethod def caller_class_and_qualname(cls) -> Tuple[str, str]: """ Figure out our caller's class name(s) and qualname Ref: :return: Tuple[str, str]: The caller's class name(s) and qualname """ # 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 caller_qualname = caller_class_names = '' if frame: # frame_info = inspect.getframeinfo(frame) args, _, _, value_dict = inspect.getargvalues(frame) if len(args) and args[0] == 'self': frame_class = value_dict['self'] if frame_class: # Find __qualname__ of the caller fn = getattr(frame_class, frame_info.function) if fn and fn.__qualname__: caller_qualname = fn.__qualname__ # Find containing class name(s) of caller, if any if frame_class.__class__ and frame_class.__class__.__qualname__: caller_class_names = frame_class.__class__.__qualname__ # It's a call from the top level module file elif frame_info.function == '': caller_class_names = '' caller_qualname = value_dict['__name__'] elif frame_info.function != '': caller_class_names = '' caller_qualname = frame_info.function # https://docs.python.org/3.7/library/inspect.html#the-interpreter-stack del frame if caller_qualname == '': print('ALERT! Something went wrong with finding caller qualname for logging!') caller_qualname = '' if caller_class_names == '': print('ALERT! Something went wrong with finding caller class name(s) for logging!') caller_class_names = '' return caller_class_names, caller_qualname