Skip to content

Instantly share code, notes, and snippets.

@RyanCPeters

RyanCPeters/logger_control_script.py

Last active May 30, 2019 02:13
Show Gist options
  • Save RyanCPeters/914f5b1a0f6d97c34a8776622894bb7d to your computer and use it in GitHub Desktop.
Save RyanCPeters/914f5b1a0f6d97c34a8776622894bb7d to your computer and use it in GitHub Desktop.
Download ZIP
A custom logging control script for setting up formatted loggers of various levels
Raw
logger_control_script.py
# yup... I am a dirty windows user ;) otherwise the sha-bang would have been here
import sys
import logging
try:
# This is only needed in order to detect if we are in debug mode when running in Pycharm IDE
import pydevd
DEBUGGING = True
except ImportError:
# we must not be running from inside the Pycharm IDE, so lets check if the code was called
# from a terminal along with the `-d` system flag
DEBUGGING = len(sys.argv)>1 and sys.flags.debug==1 # note that sys.flags is a namedtuple object
# the following "table" of data was taken from the official python docs for
# python version 3.6.8 on May 5, 2019
# found here: https://docs.python.org/3.6/library/logging.html
# see that link for the full description of the available attributes
#
# Attribute name Format
# args You shouldn’t need to format this yourself.
# asctime %(asctime)s
# created %(created)f
# exc_info You shouldn’t need to format this yourself.
# filename %(filename)s
# funcName %(funcName)s
# levelname %(levelname)s
# levelno %(levelno)s
# lineno %(lineno)d
# message %(message)s
# module %(module)s
# msecs %(msecs)d
# msg You shouldn’t need to format this yourself.
# name %(name)s
# pathname %(pathname)s
# process %(process)d
# processName %(processName)s
# relativeCreated %(relativeCreated)d
# thread %(thread)d
# threadName %(threadName)s
# Level Numeric value
# CRITICAL 50
# ERROR 40
# WARNING 30
# INFO 20
# DEBUG 10
# NOTSET 0
logging.basicConfig(level=logging.DEBUG if DEBUGGING else logging.INFO)
class LoggerExtraDefined(logging.Logger):
"""
a subclass of logging.Logger which allows the definition of the extra dict at instantiation time
so that we may define contextual information for our log records that may be most easily known
at the time of the logger's instantiation.
This subclass will still defer to invocations of the extra keyword argument on calls to log, but
if a call to log leaves extra as None, we substitute in the reference given at instantiation.
"""
def __init__(self, name, level=logging.NOTSET,extra:dict=None):
super().__init__(name, level)
self.extra = extra if extra is not None else {"extra":""}
def assign_exta_dict(self,extra:dict):
self.extra=extra or self.extra
def _log(self, level, msg, args, exc_info=None, extra=None, stack_info=False):
extra = extra if extra is not None else self.extra
super(LoggerExtraDefined, self)._log(level, msg, args, exc_info, extra)
# logger formatting
logging.setLoggerClass(LoggerExtraDefined)
# regarding *_PRI_LOGGER_HEADER_COLOR_PREFIX, defined bellow:
# HIGH, and LOW priority header color prefix templates vary only in that HIGH sets 7 as a flag.
# By including 7 as a formatting flag (the order of flags does not matter) the text will trade
# foreground and background colors.
# E.G. for a critical message header, supposing the background
# is set to black by default, we will see black text on a bright-red background.
#
# As added emphasis, the order of flags is irrelevant. "1;4;7;Xm"<=>"7;1;4;Xm" or any other
# possible permutation of the ordering.
#
# For further reference and details, please see the following wikipedia link:
# http://www.lihaoyi.com/post/BuildyourownCommandLinewithANSIescapecodes.html
ESC_SEQ = "\033["
HIGH_PRI_LOGGER_HEADER_COLOR_PREFIX = ESC_SEQ+"1;4;7;{}m"
LOW_PRI_LOGGER_HEADER_COLOR_PREFIX = ESC_SEQ+"1;4;{}m"
LOGGER_MSG_COLOR = ESC_SEQ+"1;{}m"
NOTSET_ID = 30 # basic white
DBG_ID = 35 # purple
INFO_ID = 32 # green -- might be just my eyes, but green(32) and yellow(33) look almost identical
WARN_ID = 93 # bright-yellow
ERR_ID = 95 # bright-purple
CRIT_ID = 91 # bright-red
RESET = ESC_SEQ+"0m"
log_id_map = {logging.ERROR:ERR_ID, logging.INFO:INFO_ID, logging.WARNING:WARN_ID,
logging.DEBUG:DBG_ID, logging.NOTSET:NOTSET_ID}
log_levels_to_names = {logging.CRITICAL:"Critical",
logging.ERROR:"Error",
logging.WARNING:"Warning",
logging.INFO:"Info",
logging.DEBUG:"Debug",
logging.NOTSET:"NotSet"}
def logger_setup(root_name: str, child_name: str = None,
formatter: logging.Formatter = None,
level: int = None,
extra_dict:dict=None,
handler_delegate=logging.StreamHandler,
use_message_first_line_indent:bool=True,
**handler_kwargs):
"""A convenience function for creating well named loggers with optional custom formatter.
This function will implement an already defined formatter for you if the formatter param is
None. For an example of a good general use logger see the example code at the bottom of this
file.
SPECIAL NOTE:
Although this function's signature allows the caller to pass virtually any logging.Handler
subclass into the handler_delegate parameter, I've only tested this functionality against
the logging.StreamHandler class. If you wish to use it for others you will likely encounter
bugs. But if you are up to the task it seems like it could potentially be a helpful tool for
allowing the instantiation of a wide array of utility loggers under a single interface.
:param root_name: The root of a logger hierarchy you wish to use for controlling default
configuration details for any child loggers you wish to use. Typically it
is best to pass in the name of the file or class in which the logger is
being instantiated. E.G. __name__
:type root_name: A string
:param child_name: The auxiliary logger you wish to create to handle some specific task. The
logger which maps to this child will set its level, handlers, and formatters
according to your inputs, allowing you to specify many different loggers to
manage data output in a form that suites you.
:type child_name: A string
:param formatter: An optional parameter that specifies the manner in which you wish to format
the available logging-event-data as well as how you wish to present the
message data for your log events. The default formatter will take one of
two styles, based the given `level`.
For level==logging.INFO (20) and bellow:
log messages will be presented in two parts.
* First, a header line that's formatted to be bold, and underlined,
that gives the time-stamp for when the log was submitted, the
child_name, the model and function and line number from which the
log-message was originated
* Followed by an indented new-line where the log-message will be
be printed. The message
For level==logging.INFO+1 (21) and above:
log messages will be presented in two parts.
* First, a header line that's formatted to be bold, and underlined,
that gives the time-stamp for when the log was submitted, the
child_name, the model and function and line number from which the
log-message was originated
* Followed, on the same line as the header, the log-message. This
distinction, as opposed to the indented new-line in lower level
messaged, is done because it is often the case the when higher
level messages occur, there are very many of them. Forcing each
one to then be a multi-line message actually makes it much harder
to visually parse.
* Special note: In order to aid in automated parsing of these
log-messages, the header details and log message will be seperated
by the following character key:
`::>`
:type formatter: an instance of logging.Formatter
:param handler_delegate: An optional parameter that Specifies the type of handler you want to
associate to the logger instance that's mapped to the
root_name.child_name you've passed in. The handler will be set up
inside of this function, this parameter simply allows you to indicate
the way you wish to have your output handled.
(E.G. to std_out, std_err, or some file output stream)
:type handler_delegate: This should be a delegate function of your desired handler's
constructor, DEFAULT=logging.StreamHandler
:param extra_dict: If you wish to add additional contextual information to the resulting
logger, you can provide that information as key:value pairs.
:type extra_dict: A dictionary
:param level: Specifies the desired logging level of the resulting logger.
DEFAULT=logging.DEBUG
:type level: An int, must be in the range of [0,0xffffffff]
:param use_message_first_line_indent: This bool can be used to indicate you want the logger to
automatically indent the first line of the log-message.
DEFAULT=True, this often helps to make it clear at a
glance where the log-message starts.
:type use_message_first_line_indent: bool
:type handler_kwargs: Any additional keywords that should be passed into the construction of the
handler. These are necessary for the instantiation of handlers that will
output to anything other than sys.std_out, and sys.std_err.
:return: a reference to the logger instance that's mapped to the input naming scheme of
<root_name>.<child_name >
:rtype: logging.Logger
"""
level = level or (logging.DEBUG if DEBUGGING else logging.NOTSET)
if child_name:
logger = logging.getLogger(root_name).getChild(child_name)
else:
child_name = log_levels_to_names[level]
logger = logging.getLogger(root_name)
logger.assign_exta_dict(extra_dict)
# The caller may pass an int into `level` that doesn't directly map onto our color coding. So,
# we should
level_normalized = min(level,logging.CRITICAL)
while level_normalized not in log_levels_to_names:
level_normalized-=1
colr_id = log_id_map[level_normalized]
if formatter is None:
if level<=20:
formatter = logging.Formatter(
"{header}%(asctime)s - {} - %(module)s.%(funcName)s(...) - %(lineno)d:{reset}{msg}"
"\n\t%(message)s{reset}\n".format(
child_name.capitalize(),
header=LOW_PRI_LOGGER_HEADER_COLOR_PREFIX.format(colr_id),
msg=LOGGER_MSG_COLOR.format(colr_id),
reset=RESET),
"%H:%M:%S")
else:
formatter = logging.Formatter(
"{header}%(asctime)s - {} - %(module)s.%(funcName)s(...) - %(lineno)d:{reset}{msg}"
" ::> %(message)s{reset}".format(
child_name.capitalize(),
header=LOW_PRI_LOGGER_HEADER_COLOR_PREFIX.format(colr_id),
msg=LOGGER_MSG_COLOR.format(colr_id),
reset=RESET),
"%H:%M:%S")
logger.propagate = False
handler_kwargs["stream"] = handler_kwargs.get("stream",sys.stdout)
handler = handler_delegate(**handler_kwargs)
if level > logger.level:
logger.setLevel(level)
handler.setLevel(level)
handler.setFormatter(formatter)
logger.addHandler(handler)
return logger
Raw
y_demo_of_custom_logger.py
from logger_control_script import *
class LoggerInstantiationDemoClass:
def __init__(self,
super_happy_funtime_message: str = None,
spiffy_formatter:logging.Formatter =None):
# By not submitting the optional formatter param, logger_setup will instead use its
# own formatter, defined within the function itself.
# This predefined formatter should be appropriate for general case info logs which are meant
# to inform the caller about what's happening where in the code base.
self.logger_info = logger_setup(self.__class__.__name__, "info", level=logging.INFO).info
self.logger_info(super_happy_funtime_message)
# spiffy_logger will use the spiffy_formatter parameter, if it's been passsed into the class
# initialization function, to set up another logger.
self.spiffy_logger = logger_setup(self.__class__.__name__, "spiffy", level=logging.WARNING,
formatter=spiffy_formatter).warning
self.spiffy_logger(super_happy_funtime_message)
# lets define some more custom shit!
# my_stylized_formatter_color_code is setting the color code that can be passed into the,
# module-scoped parameter, LOGGER_HEADER_COLOR_PREFIX.
my_stylized_formatter_color_code= log_id_map[logging.DEBUG]
spiffy_extra_dict = {"superhappyfuntime":super_happy_funtime_message,
"squirly":self.__class__.__name__+".spiffy_cusom"}
# (LOGGER_HEADER_COLOR_PREFIX in turn, is just a template string containing the needed
# ANSI escape and color code syntax to output colorized console messages.)
# Now the example of creating a custom formatter that matches the default formatter's style
# and appearance but adds the use of a custom formatting attribute defined in the extra_dict
stack_tracing_formatter = \
logging.Formatter("{prefix}%(asctime)s - %(squirly)s - %(module)s.%(funcName)s(...) - %(lineno)d:{reset}{msg_color}"
"\n\t%(superhappyfuntime)s"
"\n\t%(message)s{reset}\n"
.format(prefix=LOGGER_HEADER_COLOR_PREFIX.format(my_stylized_formatter_color_code),
logger_name="spiffy2", # matching child name of spiffy_logger
reset=RESET,
msg_color=LOGGER_MSG_COLOR.format(my_stylized_formatter_color_code)),
"%H:%M:%S")# this last parmeter denotes the desired format for the `asctime` string output
# Note that self.spiffy_cusom is passing the same root_name and child_name params as
# self.spiffy_logger, This will cause each logger to output a logging event when a message
# is passed to the internal logging reference by that name.
self.spiffy_cusom = logger_setup(self.__class__.__name__, "spiffy", stack_tracing_formatter, logging.DEBUG, spiffy_extra_dict).debug
self.spiffy_cusom(super_happy_funtime_message)
from pprint import pformat as pf
self.logger_info("\n\t".join([line.strip() for line in pf(self.__class__.__dict__).replace("{","").replace("}","").split("\n")]))
self.logger_info("end of __init__ function")
def write_a_message(self, message:str):
self.spiffy_cusom(message)
self.spiffy_logger(message)
self.logger_info(message)
if __name__=="__main__":
logger_info = logger_setup(root_name=__name__, child_name="info", level=logging.INFO).info
# For the following example usage of the logger consider this example function -- example().
# Note that we are calling the logger reference instantiated just above this comment inside
# our example function.
def example():
logger_info("DEBUGGING == {}".format(DEBUGGING))
# now we can call our example function and observe the output
example()
logger_info("Now lets set up the example class and see how the output of that looks.")
democlass1 = LoggerInstantiationDemoClass("Super Happy Funtime!!")
logger_info("Lets try it again with a custom formatter passed into the optional param")
simple_formatter = logging.Formatter("{header}%(name)s, func = %(funcName)s(...) - %(lineno)d:{reset}{msg}"
"\n\t%(message)s{reset}\n"
.format(header=LOGGER_HEADER_COLOR_PREFIX.format(WARN_ID),
msg=LOGGER_MSG_COLOR.format(ERR_ID),
reset=RESET))
democlass2 = LoggerInstantiationDemoClass("Superer Happier Funertimes!!", simple_formatter)
logger_info("now lets call that write_a_message function on both to see what happens")
democlass1.write_a_message("This is democlass1's message to write.")
democlass2.write_a_message("This is democlass2's message to write.")
Raw
z_custom_logger_example_output.txt
E:\Miniconda3\envs\unet\python.exe C:/Users/Peter/Documents/GitHub_Remotes/Internship_folders_summer_2018/DeepLearningData_RCP/Adapted_Unet_v0_2/utils/custom_logger_demo.py
18:49:58 - Info - custom_logger_demo.example(...) - 59:
DEBUGGING == True
18:49:58 - Info - custom_logger_demo.<module>(...) - 63:
Now lets set up the example class and see how the output of that looks.
18:49:58 - Info - custom_logger_demo.__init__(...) - 12:
Super Happy Funtime!!
18:49:58 - Spiffy - custom_logger_demo.__init__(...) - 17:
Super Happy Funtime!!
18:49:58 - Info - custom_logger_demo.__init__(...) - 43:
mappingproxy('__dict__': <attribute '__dict__' of 'LoggerInstantiationDemoClass' objects>,
'__doc__': None,
'__init__': <function LoggerInstantiationDemoClass.__init__ at 0x00000139615EB400>,
'__module__': '__main__',
'__weakref__': <attribute '__weakref__' of 'LoggerInstantiationDemoClass' objects>,
'write_a_message': <function LoggerInstantiationDemoClass.write_a_message at 0x00000139615EB488>)
18:49:58 - Info - custom_logger_demo.__init__(...) - 44:
end of __init__ function
18:49:58 - Info - custom_logger_demo.<module>(...) - 65:
Lets try it again with a custom formatter passed into the optional param
18:49:58 - Info - custom_logger_demo.__init__(...) - 12:
Superer Happier Funertimes!!
18:49:58 - Info - custom_logger_demo.__init__(...) - 12:
Superer Happier Funertimes!!
18:49:58 - Spiffy - custom_logger_demo.__init__(...) - 17:
Superer Happier Funertimes!!
18:49:58 - LoggerInstantiationDemoClass.spiffy_cusom - custom_logger_demo.__init__(...) - 17:
Super Happy Funtime!!
Superer Happier Funertimes!!
LoggerInstantiationDemoClass.spiffy, func = __init__(...) - 17:
Superer Happier Funertimes!!
18:49:58 - Info - custom_logger_demo.__init__(...) - 43:
mappingproxy('__dict__': <attribute '__dict__' of 'LoggerInstantiationDemoClass' objects>,
'__doc__': None,
'__init__': <function LoggerInstantiationDemoClass.__init__ at 0x00000139615EB400>,
'__module__': '__main__',
'__weakref__': <attribute '__weakref__' of 'LoggerInstantiationDemoClass' objects>,
'write_a_message': <function LoggerInstantiationDemoClass.write_a_message at 0x00000139615EB488>)
18:49:58 - Info - custom_logger_demo.__init__(...) - 43:
mappingproxy('__dict__': <attribute '__dict__' of 'LoggerInstantiationDemoClass' objects>,
'__doc__': None,
'__init__': <function LoggerInstantiationDemoClass.__init__ at 0x00000139615EB400>,
'__module__': '__main__',
'__weakref__': <attribute '__weakref__' of 'LoggerInstantiationDemoClass' objects>,
'write_a_message': <function LoggerInstantiationDemoClass.write_a_message at 0x00000139615EB488>)
18:49:58 - Info - custom_logger_demo.__init__(...) - 44:
end of __init__ function
18:49:58 - Info - custom_logger_demo.__init__(...) - 44:
end of __init__ function
18:49:58 - Info - custom_logger_demo.<module>(...) - 73:
now lets call that write_a_message function on both to see what happens
18:49:58 - Spiffy - custom_logger_demo.write_a_message(...) - 48:
This is democlass1's message to write.
18:49:58 - LoggerInstantiationDemoClass.spiffy_cusom - custom_logger_demo.write_a_message(...) - 48:
Superer Happier Funertimes!!
This is democlass1's message to write.
LoggerInstantiationDemoClass.spiffy, func = write_a_message(...) - 48:
This is democlass1's message to write.
18:49:58 - LoggerInstantiationDemoClass.spiffy_cusom - custom_logger_demo.write_a_message(...) - 48:
Superer Happier Funertimes!!
This is democlass1's message to write.
18:49:58 - Info - custom_logger_demo.write_a_message(...) - 49:
This is democlass1's message to write.
18:49:58 - Info - custom_logger_demo.write_a_message(...) - 49:
This is democlass1's message to write.
18:49:58 - Spiffy - custom_logger_demo.write_a_message(...) - 48:
This is democlass2's message to write.
18:49:58 - LoggerInstantiationDemoClass.spiffy_cusom - custom_logger_demo.write_a_message(...) - 48:
Superer Happier Funertimes!!
This is democlass2's message to write.
LoggerInstantiationDemoClass.spiffy, func = write_a_message(...) - 48:
This is democlass2's message to write.
18:49:58 - LoggerInstantiationDemoClass.spiffy_cusom - custom_logger_demo.write_a_message(...) - 48:
Superer Happier Funertimes!!
This is democlass2's message to write.
18:49:58 - Info - custom_logger_demo.write_a_message(...) - 49:
This is democlass2's message to write.
18:49:58 - Info - custom_logger_demo.write_a_message(...) - 49:
This is democlass2's message to write.
Process finished with exit code 0
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment