1
0
mirror of https://github.com/EDCD/EDMarketConnector.git synced 2025-04-17 17:42:20 +03:00

Move logging setup to EDMCLogging.py with a class

* Also now providers single caller_class_and_qualname() method to get
 both strings, returned as a Tuple[str, str].  Either could be empty
 if something went wrong.
* Rather than a fragile 'skip' this now:
    1. Looks for the first up-stack frame with self of logging.Logger
    1. Then looks for the next up-stack frame with self NOT of
     logging.Logger.  This should be the call site we want.
This commit is contained in:
Athanasius 2020-07-25 14:46:10 +01:00
parent c196a38e09
commit 596527bda2
2 changed files with 133 additions and 122 deletions

124
EDMCLogging.py Normal file
View File

@ -0,0 +1,124 @@
"""
TODO: blurb
"""
import sys
import logging
from typing import Tuple
class logger(object):
"""
TODO: desc
Wrapper class for all logging configuration and code.
"""
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 self.logger
class EDMCContextFilter(logging.Filter):
"""
TODO: Update this
logging.Filter sub-class to place the calling __class__ in the record.
"""
def filter(self, record: logging.LogRecord) -> bool:
"""
:param record:
:return: bool - True for this record to be logged.
"""
# TODO: Only set these if they're not already, in case upstream
# adds them.
# TODO: Try setattr(record, 'class', ...
(class_name, qualname) = self.caller_class_and_qualname()
record.__dict__['class'] = class_name
record.__dict__['qualname'] = qualname
return True
def caller_class_and_qualname(self, skip=4) -> Tuple[str, str]:
"""
Figure out our caller's qualname
Ref: <https://gist.github.com/techtonik/2151726#gistcomment-2333747>
:param skip: How many stack frames above to look.
:return: str: The caller's qualname
"""
import inspect
# TODO: Fold this into caller_class()
def stack_(frame):
framelist = []
while frame:
framelist.append(frame)
frame = frame.f_back
return framelist
stack = stack_(sys._getframe(0))
# 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!')
if caller_class_name == '':
print('ALERT! Something went wrong with finding caller class name for logging!')
return (caller_class_name, caller_qualname)

View File

@ -21,6 +21,7 @@ import logging
import traceback
from typing import Any, Optional
import EDMCLogging
from config import appname, applongname, appversion, appversion_nobuild, copyright, config
if getattr(sys, 'frozen', False):
@ -943,109 +944,6 @@ def enforce_single_instance() -> None:
EnumWindows(enumwindowsproc, 0)
###########################################################################
# Logging
# Has to be here to be defined for other modules importing
# TODO: now nothing should import this, can it move back into __main__ block ?
logger = logging.getLogger(appname)
class EDMCContextFilter(logging.Filter):
"""
logging.Filter sub-class to place the calling __class__ in the record.
"""
def filter(self, record: logging.LogRecord) -> bool:
"""
:param record:
:return: bool - True for this record to be logged.
"""
record.__dict__['class'] = self.caller_class()
record.__dict__['qualname'] = self.caller_qualname()
return True
def caller_class(self, skip=5) -> str:
"""
Figure out our caller class.
Ref: <https://gist.github.com/techtonik/2151727#gistcomment-2333747>
:param skip: How many stack frames above to look.
:return: str: The class name.
"""
import inspect
def stack_(frame):
framelist = []
while frame:
framelist.append(frame)
frame = frame.f_back
return framelist
stack = stack_(sys._getframe(1))
# TODO: Make this less fragile by not depending on a magic number of
# stack frames to skip. Should be able to find the last
# logger frame, where one of the critical, debug etc functions
# was called and then use the next frame before that.
# ALSO UPDATE caller_qualname() !!!
start = 0 + skip
if len(stack) < start + 1:
return ''
class_name = ''
frame = stack[start]
if 'self' in frame.f_locals:
# Paranoia checks
frame_class = frame.f_locals['self'].__class__
if frame_class and frame_class.__qualname__:
class_name = frame_class.__qualname__
if class_name == '':
print('ALERT! Something went wrong with finding class name for logging!')
return class_name
def caller_qualname(self, skip=5) -> str:
"""
Figure out our caller's qualname
Ref: <https://gist.github.com/techtonik/2151727#gistcomment-2333747>
:param skip: How many stack frames above to look.
:return: str: The caller's qualname
"""
import inspect
def stack_(frame):
framelist = []
while frame:
framelist.append(frame)
frame = frame.f_back
return framelist
stack = stack_(sys._getframe(1))
start = 0 + skip
if len(stack) < start + 1:
return ''
qualname = ''
frame = stack[start]
if frame.f_locals and 'self' in frame.f_locals:
# 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__:
qualname = fn.__qualname__
if qualname == '':
print('ALERT! Something went wrong with finding caller qualname for logging!')
return qualname
###########################################################################
# Run the app
if __name__ == "__main__":
@ -1056,29 +954,18 @@ if __name__ == "__main__":
import tempfile
sys.stdout = sys.stderr = open(join(tempfile.gettempdir(), '%s.log' % appname), 'wt', 1) # unbuffered not allowed for text in python3, so use line buffering
###########################################################################
# Configure the logging.Logger
logger_default_loglevel = logging.DEBUG
logger.setLevel(logger_default_loglevel)
# Set up filter for adding class name
logger_f = EDMCContextFilter()
logger.addFilter(logger_f)
logger_ch = logging.StreamHandler()
logger_ch.setLevel(logger_default_loglevel)
logger_formatter = logging.Formatter('%(asctime)s - %(name)s - %(levelname)s - %(module)s.%(qualname)s:%(lineno)d: %(message)s')
logger_formatter.default_time_format = '%Y-%m-%d %H:%M:%S'
logger_formatter.default_msec_format = '%s.%03d'
logger_ch.setFormatter(logger_formatter)
logger.addHandler(logger_ch)
###########################################################################
logger = EDMCLogging.logger(appname).getLogger()
# Plain, not via `logger`
print(f'{applongname} {appversion}')
class A(object):
class B(object):
def __init__(self):
logger.debug('A call from A.B.__init__')
abinit = A.B()
Translations.install(config.get('language') or None) # Can generate errors so wait til log set up
root = tk.Tk(className=appname.lower())