EDMarketConnector/EDMCLogging.py

"""
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.
"""

import sys
import logging
from typing import Tuple

class logger(object):
    """
    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=logging.DEBUG):
        """
        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')
        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 getLogger(self) -> logging.Logger:
        """
        :return: The logging.Logger instance.
        """
        return self.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 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:
                 <file/module>.<classA>[.classB....].<function>

        :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

    def caller_class_and_qualname(self) -> Tuple[str, str]:
        """
        Figure out our caller's class name and qualname

        Ref: <https://gist.github.com/techtonik/2151726#gistcomment-2333747>

        :return: Tuple[str, str]: The caller's class name and qualname
        """
        # TODO: we might as well just walk this below.
        # Build the stack of frames from here upwards
        stack = []
        frame = sys._getframe(0)
        while frame:
            stack.append(frame)
            frame = frame.f_back

        # 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.
        f = 0
        while stack[f]:
            if type(stack[f].f_locals.get('self')) == logging.Logger:
                f += 1  # Want to start on the next frame below
                break
            f += 1

        # 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 stack[f]:
            if type(stack[f].f_locals.get('self')) != logging.Logger:
                break  # We've found the frame we want
            f += 1

        caller_qualname = caller_class_name = ''
        if stack[f]:
            frame = stack[f]
            if frame.f_locals and 'self' in frame.f_locals:

                # Find __qualname__ of the caller
                # Paranoia checks
                if frame.f_code and frame.f_code.co_name:
                    fn = getattr(frame.f_locals['self'], frame.f_code.co_name)

                    if fn and fn.__qualname__:
                        caller_qualname = fn.__qualname__

                # Find immediate containing class name of caller, if any
                frame_class = frame.f_locals['self'].__class__
                # Paranoia checks
                if frame_class and frame_class.__qualname__:
                    caller_class_name = frame_class.__qualname__

        if caller_qualname == '':
            print('ALERT!  Something went wrong with finding caller qualname for logging!')
            caller_qualname = '<ERROR in EDMCLogging.caller_class_and_qualname()>'

        if caller_class_name == '':
            print('ALERT!  Something went wrong with finding caller class name for logging!')
            caller_class_name = '<ERROR in EDMCLogging.caller_class_and_qualname()>'

        return (caller_class_name, caller_qualname)