Subscribe to my newsletter
What this post is about
Often in an attempt to follow SOLID principles during coding, we tend to keep the code moduler. While debugging / figuring out the root of the problem, a centralized logging functionality can boost the efficiency. This post provides a python template to implement centralized logging functionality which can be extended to submodules.
- part 1: logging custom parameter
- part 2: extending logger to submodules
1. logging custom parameter
There are 2 ways offered in logging module. We can use filters or we can use adapters.
Let’s consider a valid example. In python when we use try catch, instead of the line number that errors out in the try block, we get the line number of the logging function we use in the except block. It becomes tricky to debug codes in this scenario. e.g.
import sys
import logging
import inspect
class myclass:
def __init__(self, a, b):
self.a = a
self.b = b
self.utils_logger = logging.getLogger()
logger = logging.getLogger('mylogger')
logger.setLevel("INFO")
ch = logging.StreamHandler()
ch.setLevel("INFO")
formatter_streamhandler = \
logging.Formatter('%(asctime)s | %(name)-25s | %(filename)-20s | %(funcName)-50s | %(levelname)-8s | %(lineno)-4s | %(message)s')
ch.setFormatter(formatter_streamhandler)
if not self.utils_logger.hasHandlers():
self.utils_logger.addHandler(ch)
def add(self):
return self.a + self.b
def division(self):
try:
self.c = self.a / self.b
self.utils_logger.info('division is complete.')
except Exception as e:
exc_type, exc_obj, exc_tb = sys.exc_info()
self.utils_logger.error('error while division; details = {}, {}, {}'.format(exc_tb.tb_lineno, e, exc_type))
inst = myclass(10,0)
inst.division()
the output we get:
2021-09-23 05:07:40,250 | root | <command-1677565066970560> | division | ERROR | 30 | error while division; details = 25, division by zero, <class 'ZeroDivisionError'>
if we notice, the line that errored out is where we are defining self.c i.e. line number 25. However, because our log output is from the except block i.e. line number 30, we see that number in the log. Ideally, we should be able to see line number 25 in the formatted part as a custom parameter. Right now we are getting line number 25 in the extended message I am deriving from system log. What that means is, we need to find a way to format exc_tb.tb_lineno as acustom logging parameter.
1.1 filter
import sys
import logging
import inspect
class AppFilter(logging.Filter):
def filter(self, record):
record.exact_line_no = line_no
return True
class myclass:
def __init__(self, a, b):
self.a = a
self.b = b
self.utils_logger = logging.getLogger('mod.utils')
self.log_level = 'INFO'
logger = logging.getLogger('mod')
logger.setLevel(self.log_level)
logger.addFilter(AppFilter())
ch = logging.StreamHandler()
ch.setLevel(self.log_level)
formatter_streamhandler = \
logging.Formatter(
'%(asctime)s | %(name)-25s | %(filename)-20s | %(funcName)-50s | %(levelname)-8s | %(lineno)-4s | %(exact_line_no)-4s | %(message)s')
ch.setFormatter(formatter_streamhandler)
logger.addHandler(ch)
if not self.utils_logger.hasHandlers():
# add the handlers to the logger
logger.addHandler(fh)
def add(self):
return self.a + self.b
def division(self):
try:
self.c = self.a / self.b
line_no = 0
self.utils_logger.info('division is complete.', extra={'exact_line_no': line_no})
except Exception as e:
exc_type, exc_obj, exc_tb = sys.exc_info()
line_no = exc_tb.tb_lineno
self.utils_logger.error('error while division; details = {}, {}, {}'.format(exc_tb.tb_lineno, e, exc_type), extra={'exact_line_no': line_no})
inst = myclass(10,0)
inst.division()
gives output
2021-09-23 05:30:07,546 | mod.utils | <command-1677565066970560> | division | ERROR | 38 | 31 | error while division; details = 31, division by zero, <class 'ZeroDivisionError'>
38 is the line number where we wrote the error log. 31 is the formatted custom parameter as our exact line number where error occured.
1.2 adapter
Example picked up from here
import logging
extra = {'module_name':'this_module'}
logger = logging.getLogger(__name__)
syslog = logging.StreamHandler()
formatter = logging.Formatter('%(asctime)s | %(name)-25s | %(filename)-20s | %(funcName)-50s | %(levelname)-8s | %(lineno)-4s | %(message)s')
syslog.setFormatter(formatter)
logger.setLevel(logging.INFO)
logger.addHandler(syslog)
logger = logging.LoggerAdapter(logger, extra)
logger.info('The logger adapter example')
output:
2021-09-23 05:46:21,273 | __main__ | <command-1677565066969778> | <module> | INFO | 12 | The logger adapter example
2. Extending logger object to multiple modules
This section is implementation of solution provided here.
Logger defined centrally:
#mylogger.py
import sys
import logging
import inspect
mylogger = logging.getLogger('appname')
mylogger.setLevel(logging.INFO)
ch = logging.StreamHandler()
formatter_streamhandler = \
logging.Formatter('%(asctime)s | %(name)-25s | %(class_name)-25s | %(function_name)-30s | %(filename)-20s | %(levelname)-8s | %(lineno)-4s | %(exact_line_no)-4s | %(message)s')
ch.setFormatter(formatter_streamhandler)
if not mylogger.hasHandlers():
mylogger.addHandler(ch)
Being called in submodules :
#anothermodule.py
%run ./mylogger
import sys
import logging
import inspect
second_logger = logging.getLogger('appname')
class secondclass:
def __init__(self, a, b, logger):
self.a = a
self.b = b
self.mylogger = logger
def add(self):
try:
self.c = self.a + self.b
extra = {'class_name': __class__, 'function_name': inspect.stack()[0][3], 'exact_line_no': 0}
self.mylogger.info('addition is complete.', extra = extra)
except Exception as e:
exc_type, exc_obj, exc_tb = sys.exc_info()
extra = {'class_name': __class__, 'function_name': inspect.stack()[0][3], 'exact_line_no':exc_tb.tb_lineno}
self.mylogger.error('error while addition; details = {}, {}, {}'.format(exc_tb.tb_lineno, e, exc_type), extra = extra) #
inst = secondclass(10, 'a', second_logger)
inst.add()
errors out as
2021-09-23 04:43:50,007 | appname | <class '__main__.secondclass'> | add | <command-1677565066970569> | ERROR | 16 | 9 | error while addition; details = 9, unsupported operand type(s) for +: 'int' and 'str', <class 'TypeError'>
The key is to inherit the logger by referencing the same name which we used to create the logger object centrally. Hope this helps and you find tempalte useful.